2012-09-11T00:58:35.721Z,1347325115.721 [Supervisor](DEBUG): Initializing supervisor.
2012-09-11T00:58:35.726Z,1347325115.726 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2012-09-11T00:58:35.727Z,1347325115.727 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-09-11T00:58:35.730Z,1347325115.730 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2012-09-11T00:58:35.734Z,1347325115.734 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-09-11T00:58:35.744Z,1347325115.744 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-09-11T00:58:35.747Z,1347325115.747 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2012-09-11T00:58:35.748Z,1347325115.747 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2012-09-11T00:58:35.748Z,1347325115.748 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-09-11T00:58:35.751Z,1347325115.751 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-09-11T00:58:36.072Z,1347325116.072 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-09-11T00:58:36.074Z,1347325116.074 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-09-11T00:58:36.275Z,1347325116.276 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-09-11T00:58:36.276Z,1347325116.276 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-09-11T00:58:36.374Z,1347325116.374 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-09-11T00:58:36.376Z,1347325116.376 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-09-11T00:58:36.600Z,1347325116.600 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-09-11T00:58:36.601Z,1347325116.601 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-09-11T00:58:36.751Z,1347325116.751 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-09-11T00:58:36.753Z,1347325116.753 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-09-11T00:58:37.006Z,1347325117.006 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-09-11T00:58:37.007Z,1347325117.007 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-09-11T00:58:37.195Z,1347325117.195 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-09-11T00:58:37.197Z,1347325117.197 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-09-11T00:58:37.478Z,1347325117.478 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-09-11T00:58:37.480Z,1347325117.480 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-09-11T00:58:37.590Z,1347325117.590 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-09-11T00:58:37.591Z,1347325117.591 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-09-11T00:58:38.034Z,1347325118.034 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-09-11T00:58:38.035Z,1347325118.035 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-09-11T00:58:38.158Z,1347325118.158 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-09-11T00:58:38.159Z,1347325118.159 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-09-11T00:58:38.256Z,1347325118.256 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2012-09-11T00:58:38.259Z,1347325118.259 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2012-09-11T00:58:38.368Z,1347325118.368 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2012-09-11T00:58:38.512Z,1347325118.512 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2012-09-11T00:58:38.606Z,1347325118.606 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2012-09-11T00:58:38.720Z,1347325118.720 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2012-09-11T00:58:38.830Z,1347325118.830 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2012-09-11T00:58:38.964Z,1347325118.964 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2012-09-11T00:58:39.066Z,1347325119.066 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2012-09-11T00:58:39.210Z,1347325119.210 [Supervisor](IMPORTANT): Reading configuration overrides from Data/config.db
2012-09-11T00:58:39.224Z,1347325119.224 [ComponentRegistry](DEBUG): Loaded Config Component "configDb
2012-09-11T00:58:39.261Z,1347325119.261 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-09-11T00:58:39.468Z,1347325119.468 [InternalSim] Loaded
2012-09-11T00:58:39.469Z,1347325119.469 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-09-11T00:58:39.470Z,1347325119.470 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-09-11T00:58:39.470Z,1347325119.470 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-09-11T00:58:39.629Z,1347325119.629 [SBIT](DEBUG): Construct Startup Built In Test.
2012-09-11T00:58:39.642Z,1347325119.642 [SBIT] Loaded
2012-09-11T00:58:39.643Z,1347325119.643 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-09-11T00:58:39.644Z,1347325119.644 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-09-11T00:58:39.676Z,1347325119.676 [IBIT] Loaded
2012-09-11T00:58:39.676Z,1347325119.676 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-09-11T00:58:39.680Z,1347325119.680 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-09-11T00:58:39.809Z,1347325119.809 [CBIT] Loaded
2012-09-11T00:58:39.809Z,1347325119.809 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-09-11T00:58:39.810Z,1347325119.810 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-09-11T00:58:39.810Z,1347325119.810 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-09-11T00:58:39.981Z,1347325119.981 [BuoyancyServo] Loaded
2012-09-11T00:58:39.981Z,1347325119.981 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-09-11T00:58:39.991Z,1347325119.991 [ElevatorServo] Loaded
2012-09-11T00:58:39.991Z,1347325119.991 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2012-09-11T00:58:40.004Z,1347325120.003 [MassServo] Loaded
2012-09-11T00:58:40.004Z,1347325120.004 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2012-09-11T00:58:40.020Z,1347325120.020 [RudderServo] Loaded
2012-09-11T00:58:40.020Z,1347325120.020 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-09-11T00:58:40.032Z,1347325120.032 [ThrusterServo] Loaded
2012-09-11T00:58:40.032Z,1347325120.032 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-09-11T00:58:40.033Z,1347325120.033 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-09-11T00:58:40.033Z,1347325120.033 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-09-11T00:58:40.066Z,1347325120.066 [DepthRateCalculator] Loaded
2012-09-11T00:58:40.066Z,1347325120.066 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-09-11T00:58:43.144Z,1347325123.144 [HFRadarModelCalc] Loaded
2012-09-11T00:58:43.144Z,1347325123.144 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2012-09-11T00:58:43.164Z,1347325123.164 [NavChart] Loaded
2012-09-11T00:58:43.165Z,1347325123.165 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-09-11T00:58:43.171Z,1347325123.171 [PitchRateCalculator] Loaded
2012-09-11T00:58:43.171Z,1347325123.171 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-09-11T00:58:43.177Z,1347325123.177 [SpeedCalculator] Loaded
2012-09-11T00:58:43.178Z,1347325123.178 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-09-11T00:58:43.197Z,1347325123.197 [TempGradientCalculator] Loaded
2012-09-11T00:58:43.197Z,1347325123.197 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-09-11T00:58:43.203Z,1347325123.203 [YawRateCalculator] Loaded
2012-09-11T00:58:43.203Z,1347325123.203 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-09-11T00:58:43.227Z,1347325123.227 [Navigation] Loaded
2012-09-11T00:58:43.228Z,1347325123.228 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-09-11T00:58:43.228Z,1347325123.228 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-09-11T00:58:43.229Z,1347325123.229 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-09-11T00:58:43.523Z,1347325123.523 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-09-11T00:58:43.524Z,1347325123.524 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-09-11T00:58:43.568Z,1347325123.568 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-09-11T00:58:43.568Z,1347325123.569 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-09-11T00:58:43.634Z,1347325123.634 [VerticalControl](DEBUG): Construct VerticalControl.
2012-09-11T00:58:43.684Z,1347325123.684 [VerticalControl] Loaded
2012-09-11T00:58:43.684Z,1347325123.684 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-09-11T00:58:43.685Z,1347325123.685 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-09-11T00:58:43.710Z,1347325123.710 [HorizontalControl] Loaded
2012-09-11T00:58:43.710Z,1347325123.710 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-09-11T00:58:43.711Z,1347325123.711 [SpeedControl](DEBUG): Construct SpeedControl.
2012-09-11T00:58:43.713Z,1347325123.713 [SpeedControl] Loaded
2012-09-11T00:58:43.713Z,1347325123.713 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-09-11T00:58:43.714Z,1347325123.714 [LoopControl](DEBUG): Construct LoopControl.
2012-09-11T00:58:43.714Z,1347325123.714 [LoopControl] Loaded
2012-09-11T00:58:43.715Z,1347325123.715 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-09-11T00:58:43.715Z,1347325123.715 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-09-11T00:58:43.716Z,1347325123.716 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-09-11T00:58:43.724Z,1347325123.724 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-09-11T00:58:43.729Z,1347325123.729 [AsyncPiEstimator] Loaded
2012-09-11T00:58:43.729Z,1347325123.729 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-09-11T00:58:43.730Z,1347325123.730 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 4060A4E0
2012-09-11T00:58:43.731Z,1347325123.731 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-09-11T00:58:43.732Z,1347325123.732 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-09-11T00:58:43.909Z,1347325123.908 [AHRS_sp3003D] Loaded
2012-09-11T00:58:43.909Z,1347325123.909 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-09-11T00:58:43.922Z,1347325123.922 [Depth_Keller] Loaded
2012-09-11T00:58:43.923Z,1347325123.923 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2012-09-11T00:58:43.928Z,1347325123.928 [DropWeight] Loaded
2012-09-11T00:58:43.929Z,1347325123.929 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2012-09-11T00:58:44.058Z,1347325124.058 [DVL_micro] Loaded
2012-09-11T00:58:44.058Z,1347325124.058 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2012-09-11T00:58:44.067Z,1347325124.067 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 4068A4E0
2012-09-11T00:58:44.157Z,1347325124.157 [NAL9602] Loaded
2012-09-11T00:58:44.157Z,1347325124.157 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2012-09-11T00:58:44.212Z,1347325124.212 [Onboard] Loaded
2012-09-11T00:58:44.212Z,1347325124.212 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-09-11T00:58:44.213Z,1347325124.213 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-09-11T00:58:44.214Z,1347325124.214 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-09-11T00:58:44.319Z,1347325124.319 [CTD_NeilBrown] Loaded
2012-09-11T00:58:44.319Z,1347325124.319 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2012-09-11T00:58:44.322Z,1347325124.322 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 406E24E0
2012-09-11T00:58:44.333Z,1347325124.333 [PAR_Licor] Loaded
2012-09-11T00:58:44.334Z,1347325124.334 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2012-09-11T00:58:44.355Z,1347325124.355 [Turbulence_NPS] Loaded
2012-09-11T00:58:44.355Z,1347325124.355 [ComponentRegistry](DEBUG): Component "Turbulence_NPS" handled in its own thread.
2012-09-11T00:58:44.359Z,1347325124.359 [Turbulence_NPS ThreadHandler](DEBUG): Created PCaller Thread at 407124E0
2012-09-11T00:58:44.393Z,1347325124.393 [WetLabsBB2FL] Loaded
2012-09-11T00:58:44.393Z,1347325124.393 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2012-09-11T00:58:44.394Z,1347325124.395 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407424E0
2012-09-11T00:58:44.395Z,1347325124.395 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-09-11T00:58:44.398Z,1347325124.398 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-09-11T00:58:44.398Z,1347325124.398 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-09-11T00:58:44.404Z,1347325124.404 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-09-11T00:58:44.407Z,1347325124.407 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407724E0
2012-09-11T00:58:44.411Z,1347325124.411 [Supervisor](DEBUG): Running supervisor.
2012-09-11T00:58:44.415Z,1347325124.415 [controlThread](DEBUG): Initializing ControlThread
2012-09-11T00:58:44.416Z,1347325124.416 [InternalSim](DEBUG):  InternalSim initializing...
2012-09-11T00:58:44.532Z,1347325124.532 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-09-11T00:58:44.748Z,1347325124.748 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-09-11T00:58:44.770Z,1347325124.770 [DVL_micro](INFO): Initializing
2012-09-11T00:58:44.770Z,1347325124.770 [DVL_micro](INFO): start:Powering up
2012-09-11T00:58:44.809Z,1347325124.809 [Turbulence_NPS](DEBUG): Initializing Turbulence_NPS.
2012-09-11T00:58:44.822Z,1347325124.822 [SBIT](INFO): Initialize SBIT Component.
2012-09-11T00:58:44.822Z,1347325124.822 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 9842
2012-09-11T00:58:44.827Z,1347325124.827 [IBIT](INFO): Initialize IBIT Component.
2012-09-11T00:58:44.828Z,1347325124.828 [CBIT](DEBUG): Initialize CBIT Component.
2012-09-11T00:58:44.828Z,1347325124.828 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2012-09-11T00:58:44.830Z,1347325124.830 [WetLabsBB2FL](INFO): Powering down
2012-09-11T00:58:44.856Z,1347325124.856 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-09-11T00:58:44.857Z,1347325124.857 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-09-11T00:58:44.857Z,1347325124.857 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-09-11T00:58:44.858Z,1347325124.858 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-09-11T00:58:44.858Z,1347325124.858 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-09-11T00:58:44.860Z,1347325124.860 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-09-11T00:58:44.860Z,1347325124.860 [Navigation](DEBUG): Initializing Navigation.
2012-09-11T00:58:44.861Z,1347325124.861 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-09-11T00:58:44.871Z,1347325124.871 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-09-11T00:58:44.872Z,1347325124.872 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-09-11T00:58:44.877Z,1347325124.877 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-09-11T00:58:44.918Z,1347325124.918 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-09-11T00:58:44.984Z,1347325124.984 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-11T00:58:44.994Z,1347325124.994 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface RunIn="Progression"/>

    <Aggregate Id="StartupSatComms" >

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

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

    </Aggregate>

</Mission>


2012-09-11T00:58:44.995Z,1347325124.995 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-09-11T00:58:45.051Z,1347325125.051 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2012-09-11T00:58:45.053Z,1347325125.053 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-09-11T00:58:45.056Z,1347325125.056 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-11T00:58:45.064Z,1347325125.064 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-09-11T00:58:45.067Z,1347325125.067 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-11T00:58:45.075Z,1347325125.075 [Default:Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-09-11T00:58:45.090Z,1347325125.090 [Default:D.SetSpeed](DEBUG): Construct.
2012-09-11T00:58:45.106Z,1347325125.106 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-11T00:58:45.112Z,1347325125.112 [Default:F.Wait](DEBUG): Construct Wait.
2012-09-11T00:58:45.115Z,1347325125.115 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
xmlns:Control="Tethys/Control"
xmlns:Guidance="Tethys/Guidance" 
xmlns:Units="Tethys/Units"
xmlns:Universal="Tethys/Universal"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
Id="Default">

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

    <Aggregate Id="GPS" >

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

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Get GPS fix -->

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

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

    </Aggregate>

    <Aggregate Id="Iridium" >

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Do data comms -->

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

    </Aggregate>

    <Aggregate Id="CallIridium" >

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

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

        <Call RefId="Iridium"/>

    </Aggregate>

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

<!-- Run at low speed -->

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

    <Guidance:GoToSurface RunIn="Parallel"/>

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

</Mission>


2012-09-11T00:58:45.120Z,1347325125.120 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Depth_Keller,DropWeight,NAL9602,Onboard,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,logger,
2012-09-11T00:58:45.165Z,1347325125.165 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-09-11T00:58:45.169Z,1347325125.168 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-11T00:58:45.173Z,1347325125.173 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2012-09-11T00:58:45.184Z,1347325125.184 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2012-09-11T00:58:45.188Z,1347325125.188 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2012-09-11T00:58:45.191Z,1347325125.191 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2012-09-11T00:58:45.192Z,1347325125.192 [NavChartDb](INFO): Creating index for Soundings
2012-09-11T00:58:45.195Z,1347325125.195 [NavChartDb](INFO): Creating index for Contour 0p0
2012-09-11T00:58:45.197Z,1347325125.197 [NavChartDb](INFO): Creating index for Contour 1p8
2012-09-11T00:58:45.199Z,1347325125.199 [NavChartDb](INFO): Creating index for Contour 3p6
2012-09-11T00:58:45.201Z,1347325125.201 [NavChartDb](INFO): Creating index for Contour 5p4
2012-09-11T00:58:45.205Z,1347325125.205 [NavChartDb](INFO): Creating index for Contour 9p1
2012-09-11T00:58:45.207Z,1347325125.207 [NavChartDb](INFO): Creating index for Contour 10p9
2012-09-11T00:58:45.209Z,1347325125.209 [NavChartDb](INFO): Creating index for Contour 18p2
2012-09-11T00:58:45.211Z,1347325125.211 [NavChartDb](INFO): Creating index for Contour 36p5
2012-09-11T00:58:45.213Z,1347325125.213 [NavChartDb](INFO): Creating index for Contour 54p8
2012-09-11T00:58:45.215Z,1347325125.215 [NavChartDb](INFO): Creating index for Contour 73p1
2012-09-11T00:58:45.216Z,1347325125.217 [NavChartDb](INFO): Creating index for Contour 91p4
2012-09-11T00:58:45.218Z,1347325125.218 [NavChartDb](INFO): Creating index for Contour 182p8
2012-09-11T00:58:45.220Z,1347325125.220 [NavChartDb](INFO): Creating index for Contour 365p7
2012-09-11T00:58:45.222Z,1347325125.222 [NavChartDb](INFO): Creating index for Contour 548p6
2012-09-11T00:58:45.224Z,1347325125.224 [NavChartDb](INFO): Creating index for Contour 731p5
2012-09-11T00:58:45.226Z,1347325125.226 [NavChartDb](INFO): Creating index for Contour 914p4
2012-09-11T00:58:45.228Z,1347325125.227 [NavChartDb](INFO): Creating index for Contour 1097p2
2012-09-11T00:58:45.229Z,1347325125.229 [NavChartDb](INFO): Creating index for Contour 1280p1
2012-09-11T00:58:45.231Z,1347325125.231 [NavChartDb](INFO): Creating index for Contour 1463p0
2012-09-11T00:58:45.233Z,1347325125.233 [NavChartDb](INFO): Creating index for Contour 1645p9
2012-09-11T00:58:45.235Z,1347325125.235 [NavChartDb](INFO): Creating index for Contour 1828p8
2012-09-11T00:58:45.237Z,1347325125.237 [NavChartDb](INFO): Creating index for Contour 2011p6
2012-09-11T00:58:45.239Z,1347325125.239 [NavChartDb](INFO): Creating index for Contour 2194p5
2012-09-11T00:58:45.241Z,1347325125.241 [NavChartDb](INFO): Creating index for Contour 2377p4
2012-09-11T00:58:45.243Z,1347325125.243 [NavChartDb](INFO): Creating index for Contour 2560p3
2012-09-11T00:58:45.245Z,1347325125.245 [NavChartDb](INFO): Creating index for Contour 2743p2
2012-09-11T00:58:45.247Z,1347325125.247 [NavChartDb](INFO): Creating index for Contour 2926p0
2012-09-11T00:58:45.248Z,1347325125.248 [NavChartDb](INFO): Creating index for Contour 3108p9
2012-09-11T00:58:45.250Z,1347325125.250 [NavChartDb](INFO): Creating index for Contour 3291p8
2012-09-11T00:58:45.256Z,1347325125.256 [NavChartDb](INFO): Creating index for Contour 3474p7
2012-09-11T00:58:45.258Z,1347325125.258 [NavChartDb](INFO): Creating index for Contour 3657p6
2012-09-11T00:58:45.563Z,1347325125.563 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-09-11T00:58:45.567Z,1347325125.567 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-09-11T00:58:45.573Z,1347325125.573 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T00:58:45.575Z,1347325125.575 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T00:58:45.581Z,1347325125.581 [MassServo](DEBUG): Initializing EZServoServo.
2012-09-11T00:58:45.583Z,1347325125.583 [MassServo](DEBUG): Initializing MassServo.
2012-09-11T00:58:45.589Z,1347325125.589 [RudderServo](DEBUG): Initializing EZServoServo.
2012-09-11T00:58:45.590Z,1347325125.590 [RudderServo](DEBUG): Initializing RudderServo.
2012-09-11T00:58:45.597Z,1347325125.597 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-09-11T00:58:45.599Z,1347325125.599 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-09-11T00:58:46.371Z,1347325126.371 [DVL_micro](INFO): Querying output modes
2012-09-11T00:58:46.371Z,1347325126.371 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-11T00:58:46.375Z,1347325126.375 [DVL_micro](DEBUG): cmdResponse: 01 03 16
2012-09-11T00:58:46.375Z,1347325126.375 [DVL_micro](INFO): NQ1 output enabled
2012-09-11T00:58:46.375Z,1347325126.375 [DVL_micro](INFO): RSSI output enabled
2012-09-11T00:58:46.375Z,1347325126.375 [DVL_micro](INFO): ADCP output enabled
2012-09-11T00:58:46.375Z,1347325126.375 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-11T00:58:46.383Z,1347325126.383 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-11T00:58:46.388Z,1347325126.388 [DVL_micro](INFO): pause:Powering down
2012-09-11T00:58:49.289Z,1347325129.289 [NAL9602](INFO): Powering up NAL9602
2012-09-11T00:59:00.115Z,1347325140.115 [NAL9602](INFO): NAL9602 initialized
2012-09-11T00:59:00.501Z,1347325140.501 [SBIT](IMPORTANT): Beginning Startup BIT
2012-09-11T00:59:00.504Z,1347325140.504 [CBIT](IMPORTANT): Beginning GF scan
2012-09-11T00:59:02.523Z,1347325142.523 [ElevatorServo](FAULT): Overload Error
2012-09-11T00:59:02.523Z,1347325142.523 [ElevatorServo] Hardware Fault, FailCount= 1
2012-09-11T00:59:02.523Z,1347325142.523 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T00:59:03.118Z,1347325143.118 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T00:59:03.218Z,1347325143.218 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T00:59:03.219Z,1347325143.219 [ElevatorServo](INFO): Powering down
2012-09-11T00:59:03.278Z,1347325143.278 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-09-11T00:59:03.278Z,1347325143.278 [ElevatorServo] No Fault, FailCount= 1
2012-09-11T00:59:04.006Z,1347325144.006 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T00:59:04.124Z,1347325144.124 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T00:59:04.124Z,1347325144.124 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T00:59:08.827Z,1347325148.827 [ElevatorServo](FAULT): Overload Error
2012-09-11T00:59:08.827Z,1347325148.827 [ElevatorServo] Hardware Fault, FailCount= 2
2012-09-11T00:59:08.827Z,1347325148.827 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T00:59:08.879Z,1347325148.879 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T00:59:09.214Z,1347325149.214 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T00:59:09.214Z,1347325149.214 [ElevatorServo](INFO): Powering down
2012-09-11T00:59:09.243Z,1347325149.243 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-09-11T00:59:09.243Z,1347325149.243 [ElevatorServo] No Fault, FailCount= 2
2012-09-11T00:59:10.005Z,1347325150.005 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T00:59:10.123Z,1347325150.124 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T00:59:10.124Z,1347325150.124 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T00:59:13.630Z,1347325153.630 [SBIT](FAULT): Elevator: EXPECTED:15.000000 ACTUAL:-8.707491
2012-09-11T00:59:14.826Z,1347325154.826 [ElevatorServo](FAULT): Overload Error
2012-09-11T00:59:14.827Z,1347325154.827 [ElevatorServo] Hardware Fault, FailCount= 3
2012-09-11T00:59:14.827Z,1347325154.827 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T00:59:14.856Z,1347325154.856 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T00:59:14.856Z,1347325154.856 [CBIT](CRITICAL): Hardware Fault in component: ElevatorServo
2012-09-11T00:59:15.213Z,1347325155.214 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T00:59:15.214Z,1347325155.214 [ElevatorServo](INFO): Powering down
2012-09-11T00:59:27.108Z,1347325167.108 [CBIT](IMPORTANT): No ground fault detected
2012-09-11T00:59:54.136Z,1347325194.136 [SBIT](CRITICAL): SBIT FAILED
2012-09-11T00:59:54.527Z,1347325194.527 [MissionManager](IMPORTANT): Started mission Startup
2012-09-11T00:59:54.527Z,1347325194.527 [Startup] Running Loop=1
2012-09-11T00:59:54.528Z,1347325194.528 [Startup](INFO): Aggregate::initialize Startup
2012-09-11T00:59:54.528Z,1347325194.528 [Startup:A.GoToSurface] Running Loop=1
2012-09-11T00:59:54.528Z,1347325194.528 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T00:59:54.534Z,1347325194.534 [Startup:StartupSatComms] Running Loop=1
2012-09-11T00:59:54.534Z,1347325194.534 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2012-09-11T00:59:54.534Z,1347325194.534 [Startup:StartupSatComms:A] Running Loop=1
2012-09-11T00:59:54.928Z,1347325194.928 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-09-11T01:00:33.721Z,1347325233.721 [NAL9602](IMPORTANT): GPS fix at: 1347325226.00
2012-09-11T01:00:33.736Z,1347325233.736 [Startup:StartupSatComms:A] Stopped
2012-09-11T01:00:33.736Z,1347325233.736 [Startup:StartupSatComms:B] Running Loop=1
2012-09-11T01:00:34.135Z,1347325234.135 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-09-11T01:00:34.395Z,1347325234.395 [NavChartDb](INFO): Charting Soundings
2012-09-11T01:00:35.995Z,1347325235.995 [NavChartDb](INFO): Charting 0p0
2012-09-11T01:00:43.681Z,1347325243.681 [NavChartDb](INFO): Charting 1p8
2012-09-11T01:00:46.591Z,1347325246.591 [NavChartDb](INFO): Charting 3p6
2012-09-11T01:00:49.340Z,1347325249.340 [NavChartDb](INFO): Charting 5p4
2012-09-11T01:00:52.437Z,1347325252.437 [NavChartDb](INFO): Charting 9p1
2012-09-11T01:00:54.547Z,1347325254.547 [NavChartDb](INFO): Charting 10p9
2012-09-11T01:00:56.151Z,1347325256.151 [NavChartDb](INFO): Charting 18p2
2012-09-11T01:00:59.460Z,1347325259.460 [NavChartDb](INFO): Charting 36p5
2012-09-11T01:01:02.572Z,1347325262.572 [NavChartDb](INFO): Charting 54p8
2012-09-11T01:01:06.008Z,1347325266.008 [NavChartDb](INFO): Charting 73p1
2012-09-11T01:01:09.605Z,1347325269.605 [NavChartDb](INFO): Charting 91p4
2012-09-11T01:01:14.889Z,1347325274.889 [NavChartDb](INFO): Charting 182p8
2012-09-11T01:01:21.311Z,1347325281.311 [NavChartDb](INFO): Charting 365p7
2012-09-11T01:01:26.711Z,1347325286.711 [NavChartDb](INFO): Charting 548p6
2012-09-11T01:01:33.437Z,1347325293.437 [NavChartDb](INFO): Charting 731p5
2012-09-11T01:01:33.758Z,1347325293.758 [Startup:StartupSatComms:B](INFO): Timed out from 2012-09-11T01:00:33.7Z
2012-09-11T01:01:33.758Z,1347325293.758 [Startup:StartupSatComms:A_Timeout] Running Loop=1
2012-09-11T01:01:33.758Z,1347325293.758 [Startup:StartupSatComms:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A_Timeout
2012-09-11T01:01:33.759Z,1347325293.759 [Startup:StartupSatComms:A_Timeout](INFO): Completed Startup:StartupSatComms:A_Timeout
2012-09-11T01:01:33.759Z,1347325293.759 [Startup:StartupSatComms:B] Stopped
2012-09-11T01:01:33.759Z,1347325293.759 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2012-09-11T01:01:33.759Z,1347325293.759 [Startup:StartupSatComms] Stopped
2012-09-11T01:01:33.759Z,1347325293.759 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2012-09-11T01:01:33.760Z,1347325293.760 [Startup](INFO): Completed Startup
2012-09-11T01:01:33.760Z,1347325293.760 [Startup] Stopped
2012-09-11T01:01:33.760Z,1347325293.760 [Startup](INFO): Aggregate::uninitialize Startup
2012-09-11T01:01:33.761Z,1347325293.760 [Startup:A.GoToSurface] Stopped
2012-09-11T01:01:33.761Z,1347325293.760 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T01:01:33.982Z,1347325293.982 [MissionManager](IMPORTANT): Started mission Default
2012-09-11T01:01:33.982Z,1347325293.982 [Default] Running Loop=1
2012-09-11T01:01:33.982Z,1347325293.982 [Default](INFO): Aggregate::initialize Default
2012-09-11T01:01:33.982Z,1347325293.982 [Default:D.SetSpeed] Running Loop=1
2012-09-11T01:01:33.982Z,1347325293.982 [Default:D.SetSpeed](DEBUG): Initialize.
2012-09-11T01:01:33.982Z,1347325293.982 [Default:E.GoToSurface] Running Loop=1
2012-09-11T01:01:33.987Z,1347325293.987 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T01:01:33.987Z,1347325293.987 [Default:Iridium] Running Loop=1
2012-09-11T01:01:33.987Z,1347325293.987 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-11T01:01:33.987Z,1347325293.987 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T01:01:33.987Z,1347325293.987 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-11T01:01:33.987Z,1347325293.987 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-11T01:01:33.987Z,1347325293.987 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T01:01:33.988Z,1347325293.988 [Default:E.GoToSurface] Running Loop=1
2012-09-11T01:01:33.998Z,1347325293.997 [Default:D.SetSpeed] Running Loop=1
2012-09-11T01:01:34.013Z,1347325294.013 [Default:CallIridium] Running Loop=1
2012-09-11T01:01:34.014Z,1347325294.014 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-11T01:01:34.014Z,1347325294.014 [Default:CallIridium:A] Running Loop=1
2012-09-11T01:01:34.021Z,1347325294.020 [Default:CallIridium:A] Stopped
2012-09-11T01:01:34.021Z,1347325294.021 [Default:CallIridium:B] Running Loop=1
2012-09-11T01:01:34.021Z,1347325294.021 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-11T01:01:34.030Z,1347325294.030 [Default:Iridium:B.GoToSurface] Stopped
2012-09-11T01:01:34.030Z,1347325294.030 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T01:01:34.030Z,1347325294.030 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-11T01:01:34.030Z,1347325294.030 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T01:01:34.043Z,1347325294.043 [Default:GPS] Running Loop=1
2012-09-11T01:01:34.043Z,1347325294.043 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-11T01:01:34.043Z,1347325294.043 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T01:01:34.043Z,1347325294.043 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-11T01:01:34.043Z,1347325294.043 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-11T01:01:34.043Z,1347325294.043 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T01:01:34.054Z,1347325294.054 [Default:GPS:B.GoToSurface] Stopped
2012-09-11T01:01:34.054Z,1347325294.054 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T01:01:34.054Z,1347325294.054 [Default:GPS:Read_GPS] Running Loop=1
2012-09-11T01:01:34.054Z,1347325294.054 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T01:01:34.425Z,1347325294.425 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-09-11T01:01:34.428Z,1347325294.428 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-09-11T01:01:36.339Z,1347325296.339 [NAL9602](IMPORTANT): GPS fix at: 1347325289.00
2012-09-11T01:01:36.372Z,1347325296.372 [Default:GPS:Read_GPS] Stopped
2012-09-11T01:01:36.372Z,1347325296.372 [Default:GPS:D] Running Loop=1
2012-09-11T01:01:36.783Z,1347325296.783 [Default:GPS:D] Stopped
2012-09-11T01:01:36.783Z,1347325296.783 [Default:GPS](INFO): Completed Default:GPS
2012-09-11T01:01:36.783Z,1347325296.783 [Default:GPS] Stopped
2012-09-11T01:01:36.783Z,1347325296.783 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-11T01:01:36.784Z,1347325296.783 [Default:GPS:A.SetSpeed] Stopped
2012-09-11T01:01:36.784Z,1347325296.783 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T01:02:14.055Z,1347325334.055 [NAL9602](INFO): SBD MO Status=2, MOMSN=850, MT Status=2, MTMSN=0
2012-09-11T01:02:14.055Z,1347325334.055 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T01:02:17.703Z,1347325337.703 [NavChartDb](INFO): Charting 914p4
2012-09-11T01:02:22.922Z,1347325342.922 [NavChartDb](INFO): Charting 1097p2
2012-09-11T01:02:29.161Z,1347325349.161 [NavChartDb](INFO): Charting 1280p1
2012-09-11T01:02:36.107Z,1347325356.107 [NavChartDb](INFO): Charting 1463p0
2012-09-11T01:02:42.185Z,1347325362.185 [NavChartDb](INFO): Charting 1645p9
2012-09-11T01:02:48.983Z,1347325368.983 [NavChartDb](INFO): Charting 1828p8
2012-09-11T01:02:54.096Z,1347325374.096 [NavChartDb](INFO): Charting 2011p6
2012-09-11T01:03:01.651Z,1347325381.651 [NavChartDb](INFO): Charting 2194p5
2012-09-11T01:03:08.154Z,1347325388.154 [NavChartDb](INFO): Charting 2377p4
2012-09-11T01:03:14.264Z,1347325394.264 [NAL9602](INFO): SBD MO Status=1, MOMSN=850, MT Status=0, MTMSN=0
2012-09-11T01:03:14.299Z,1347325394.299 [NAL9602](INFO): Sent 104 bytes from file Logs/20120910T221418/shore0029.lzma
2012-09-11T01:03:14.299Z,1347325394.299 [NAL9602](INFO): Packets left to send: 0
2012-09-11T01:03:14.301Z,1347325394.301 [NAL9602](INFO): Stored copy of sent data in Logs/20120910T221418/shore0029.lzma.parts/0000.sbd
2012-09-11T01:03:14.606Z,1347325394.606 [NavChartDb](INFO): Charting 2560p3
2012-09-11T01:03:22.229Z,1347325402.229 [NavChartDb](INFO): Charting 2743p2
2012-09-11T01:03:24.875Z,1347325404.875 [NavChartDb](INFO): Charting 2926p0
2012-09-11T01:03:26.479Z,1347325406.479 [NavChartDb](INFO): Charting 3108p9
2012-09-11T01:03:28.079Z,1347325408.079 [NavChartDb](INFO): Charting 3291p8
2012-09-11T01:03:30.084Z,1347325410.084 [NAL9602](INFO): SBD MO Status=1, MOMSN=851, MT Status=0, MTMSN=0
2012-09-11T01:03:30.119Z,1347325410.119 [NAL9602](INFO): Sent 332 bytes from file Logs/20120911T005835/shore0000.lzma
2012-09-11T01:03:30.119Z,1347325410.119 [NAL9602](INFO): Packets left to send: 2
2012-09-11T01:03:30.121Z,1347325410.121 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0000.lzma.parts/0002.sbd
2012-09-11T01:03:31.447Z,1347325411.447 [NavChartDb](INFO): Charting 3474p7
2012-09-11T01:03:33.047Z,1347325413.047 [NavChartDb](INFO): Charting 3657p6
2012-09-11T01:03:43.468Z,1347325423.468 [NAL9602](INFO): SBD MO Status=1, MOMSN=852, MT Status=0, MTMSN=0
2012-09-11T01:03:43.503Z,1347325423.503 [NAL9602](INFO): Sent 332 bytes from file Logs/20120911T005835/shore0000.lzma
2012-09-11T01:03:43.503Z,1347325423.503 [NAL9602](INFO): Packets left to send: 1
2012-09-11T01:03:43.504Z,1347325423.504 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0000.lzma.parts/0001.sbd
2012-09-11T01:03:54.904Z,1347325434.904 [NAL9602](INFO): SBD MO Status=1, MOMSN=853, MT Status=0, MTMSN=0
2012-09-11T01:03:54.939Z,1347325434.939 [NAL9602](INFO): Sent 88 bytes from file Logs/20120911T005835/shore0000.lzma
2012-09-11T01:03:54.939Z,1347325434.939 [NAL9602](INFO): Packets left to send: 0
2012-09-11T01:03:54.940Z,1347325434.940 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0000.lzma.parts/0000.sbd
2012-09-11T01:04:05.301Z,1347325445.301 [NAL9602](INFO): SBD MO Status=0, MOMSN=854, MT Status=0, MTMSN=0
2012-09-11T01:04:05.354Z,1347325445.354 [Default:Iridium:Read_Iridium] Stopped
2012-09-11T01:04:05.354Z,1347325445.355 [Default:Iridium](INFO): Completed Default:Iridium
2012-09-11T01:04:05.355Z,1347325445.355 [Default:Iridium] Stopped
2012-09-11T01:04:05.355Z,1347325445.355 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-11T01:04:05.355Z,1347325445.355 [Default:Iridium:A.SetSpeed] Stopped
2012-09-11T01:04:05.355Z,1347325445.355 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T01:04:05.355Z,1347325445.355 [Default:F.Wait] Running Loop=1
2012-09-11T01:04:05.355Z,1347325445.355 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-09-11T01:04:05.728Z,1347325445.728 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-09-11T01:04:05.729Z,1347325445.728 [Default:CallIridium:B] Stopped
2012-09-11T01:04:05.729Z,1347325445.729 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-09-11T01:04:05.729Z,1347325445.729 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-09-11T01:04:05.729Z,1347325445.729 [Default:CallIridium] Stopped
2012-09-11T01:04:05.729Z,1347325445.729 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-09-11T01:04:15.771Z,1347325455.771 [NAL9602](INFO): Powering down
2012-09-11T01:09:05.784Z,1347325745.784 [Default:CallIridium] Running Loop=1
2012-09-11T01:09:05.784Z,1347325745.784 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-11T01:09:05.784Z,1347325745.784 [Default:CallIridium:A] Running Loop=1
2012-09-11T01:09:05.785Z,1347325745.785 [Default:CallIridium:A] Stopped
2012-09-11T01:09:05.785Z,1347325745.785 [Default:CallIridium:B] Running Loop=1
2012-09-11T01:09:05.785Z,1347325745.785 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-11T01:09:10.785Z,1347325750.785 [Default:Iridium] Running Loop=1
2012-09-11T01:09:10.785Z,1347325750.785 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-11T01:09:10.785Z,1347325750.786 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T01:09:10.786Z,1347325750.786 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-11T01:09:10.786Z,1347325750.786 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-11T01:09:10.786Z,1347325750.786 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T01:09:10.787Z,1347325750.787 [Default:Iridium:B.GoToSurface] Stopped
2012-09-11T01:09:10.787Z,1347325750.787 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T01:09:10.787Z,1347325750.787 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-11T01:09:10.787Z,1347325750.787 [Default:GPS] Running Loop=1
2012-09-11T01:09:10.788Z,1347325750.787 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-11T01:09:10.788Z,1347325750.788 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T01:09:10.788Z,1347325750.788 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-11T01:09:10.788Z,1347325750.788 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-11T01:09:10.788Z,1347325750.788 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T01:09:10.789Z,1347325750.789 [Default:GPS:B.GoToSurface] Stopped
2012-09-11T01:09:10.789Z,1347325750.789 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T01:09:10.789Z,1347325750.789 [Default:GPS:Read_GPS] Running Loop=1
2012-09-11T01:09:11.508Z,1347325751.508 [NAL9602](INFO): Powering up
2012-09-11T01:09:22.523Z,1347325762.523 [NAL9602](INFO): NAL9602 initialized
2012-09-11T01:09:47.057Z,1347325787.057 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=855, MT Status=1, MTMSN=89
2012-09-11T01:09:47.095Z,1347325787.095 [NAL9602](INFO): Sent 272 bytes from file Logs/20120911T005835/shore0001.lzma
2012-09-11T01:09:47.095Z,1347325787.095 [NAL9602](INFO): Packets left to send: 0
2012-09-11T01:09:47.097Z,1347325787.097 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0001.lzma.parts/0000.sbd
2012-09-11T01:09:47.708Z,1347325787.708 [NAL9602](INFO): Received command:maintain control VerticalControl.elevatorAngleAction 0 degree
2012-09-11T01:09:47.862Z,1347325787.862 [CommandLine](IMPORTANT): got command maintain control VerticalControl.elevatorAngleAction 0.000000 degree
2012-09-11T01:09:47.864Z,1347325787.864 [ComponentRegistry](DEBUG): SyncComponent "Maintain_VerticalControl.elevatorAngleAction" handled in the control thread.
2012-09-11T01:09:47.947Z,1347325787.947 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Depth_Keller,DropWeight,NAL9602,Onboard,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintain_VerticalControl.elevatorAngleAction,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,logger,
2012-09-11T01:09:55.841Z,1347325795.841 [NAL9602](IMPORTANT): SBD MO Status=0, MOMSN=856, MT Status=1, MTMSN=90
2012-09-11T01:09:56.436Z,1347325796.436 [NAL9602](INFO): Received command:get platform_elevator_angle
2012-09-11T01:09:56.553Z,1347325796.553 [CommandLine](IMPORTANT): got command get platform_elevator_angle
2012-09-11T01:09:56.554Z,1347325796.554 [CommandLine](IMPORTANT): platform_elevator_angle 0.000000 degree
2012-09-11T01:10:03.682Z,1347325803.682 [NAL9602](INFO): SBD MO Status=0, MOMSN=857, MT Status=0, MTMSN=0
2012-09-11T01:10:16.325Z,1347325816.325 [NAL9602](INFO): SBD MO Status=1, MOMSN=858, MT Status=0, MTMSN=0
2012-09-11T01:10:16.359Z,1347325816.359 [NAL9602](INFO): Sent 286 bytes from file Logs/20120911T005835/shore0002.lzma
2012-09-11T01:10:16.359Z,1347325816.359 [NAL9602](INFO): Packets left to send: 0
2012-09-11T01:10:16.361Z,1347325816.361 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0002.lzma.parts/0000.sbd
2012-09-11T01:10:19.933Z,1347325819.933 [NAL9602](INFO): SBD MO Status=0, MOMSN=859, MT Status=0, MTMSN=0
2012-09-11T01:10:19.984Z,1347325819.984 [Default:Iridium:Read_Iridium] Stopped
2012-09-11T01:10:19.984Z,1347325819.984 [Default:Iridium](INFO): Completed Default:Iridium
2012-09-11T01:10:19.984Z,1347325819.984 [Default:Iridium] Stopped
2012-09-11T01:10:19.984Z,1347325819.984 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-11T01:10:19.984Z,1347325819.984 [Default:Iridium:A.SetSpeed] Stopped
2012-09-11T01:10:19.984Z,1347325819.984 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T01:10:20.340Z,1347325820.340 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-09-11T01:10:20.340Z,1347325820.340 [Default:CallIridium:B] Stopped
2012-09-11T01:10:20.340Z,1347325820.340 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-09-11T01:10:20.340Z,1347325820.341 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-09-11T01:10:20.341Z,1347325820.341 [Default:CallIridium] Stopped
2012-09-11T01:10:20.341Z,1347325820.341 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-09-11T01:10:21.127Z,1347325821.127 [NAL9602](IMPORTANT): GPS fix at: 1347325814.00
2012-09-11T01:10:21.143Z,1347325821.143 [Default:GPS:Read_GPS] Stopped
2012-09-11T01:10:21.143Z,1347325821.143 [Default:GPS:D] Running Loop=1
2012-09-11T01:10:21.543Z,1347325821.543 [Default:GPS:D] Stopped
2012-09-11T01:10:21.544Z,1347325821.544 [Default:GPS](INFO): Completed Default:GPS
2012-09-11T01:10:21.544Z,1347325821.544 [Default:GPS] Stopped
2012-09-11T01:10:21.544Z,1347325821.544 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-11T01:10:21.544Z,1347325821.544 [Default:GPS:A.SetSpeed] Stopped
2012-09-11T01:10:21.544Z,1347325821.544 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T01:10:41.993Z,1347325841.993 [NAL9602](INFO): Powering down
2012-09-11T01:14:17.067Z,1347326057.067 [CBIT](INFO): Clearing failed count for component ElevatorServo
2012-09-11T01:14:17.067Z,1347326057.067 [ElevatorServo] No Fault, FailCount= 3
2012-09-11T01:14:27.064Z,1347326067.063 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T01:14:27.207Z,1347326067.207 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T01:14:27.207Z,1347326067.207 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T01:14:57.039Z,1347326097.039 [ElevatorServo](FAULT): Overload Error
2012-09-11T01:14:57.039Z,1347326097.039 [ElevatorServo] Hardware Fault, FailCount= 1
2012-09-11T01:14:57.039Z,1347326097.039 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T01:14:57.066Z,1347326097.066 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T01:15:02.015Z,1347326102.015 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T01:15:02.015Z,1347326102.016 [ElevatorServo](INFO): Powering down
2012-09-11T01:15:02.019Z,1347326102.019 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-09-11T01:15:02.020Z,1347326102.020 [ElevatorServo] No Fault, FailCount= 1
2012-09-11T01:15:12.017Z,1347326112.017 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T01:15:12.136Z,1347326112.136 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T01:15:12.136Z,1347326112.136 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T01:15:22.009Z,1347326122.009 [Default:CallIridium] Running Loop=1
2012-09-11T01:15:22.009Z,1347326122.009 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-11T01:15:22.009Z,1347326122.009 [Default:CallIridium:A] Running Loop=1
2012-09-11T01:15:22.009Z,1347326122.009 [Default:CallIridium:A] Stopped
2012-09-11T01:15:22.009Z,1347326122.009 [Default:CallIridium:B] Running Loop=1
2012-09-11T01:15:22.010Z,1347326122.010 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-11T01:15:27.042Z,1347326127.042 [Default:Iridium] Running Loop=1
2012-09-11T01:15:27.042Z,1347326127.042 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-11T01:15:27.042Z,1347326127.042 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T01:15:27.042Z,1347326127.042 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-11T01:15:27.042Z,1347326127.042 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-11T01:15:27.043Z,1347326127.043 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T01:15:27.043Z,1347326127.043 [Default:Iridium:B.GoToSurface] Stopped
2012-09-11T01:15:27.043Z,1347326127.043 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T01:15:27.043Z,1347326127.043 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-11T01:15:27.044Z,1347326127.044 [Default:GPS] Running Loop=1
2012-09-11T01:15:27.044Z,1347326127.044 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-11T01:15:27.044Z,1347326127.044 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T01:15:27.044Z,1347326127.044 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-11T01:15:27.044Z,1347326127.044 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-11T01:15:27.044Z,1347326127.044 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T01:15:27.045Z,1347326127.045 [Default:GPS:B.GoToSurface] Stopped
2012-09-11T01:15:27.045Z,1347326127.045 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T01:15:27.045Z,1347326127.045 [Default:GPS:Read_GPS] Running Loop=1
2012-09-11T01:15:27.729Z,1347326127.729 [NAL9602](INFO): Powering up
2012-09-11T01:15:29.371Z,1347326129.371 [ElevatorServo](FAULT): Overload Error
2012-09-11T01:15:29.371Z,1347326129.371 [ElevatorServo] Hardware Fault, FailCount= 2
2012-09-11T01:15:29.371Z,1347326129.371 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T01:15:29.398Z,1347326129.398 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T01:15:29.748Z,1347326129.747 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T01:15:29.748Z,1347326129.748 [ElevatorServo](INFO): Powering down
2012-09-11T01:15:29.752Z,1347326129.751 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-09-11T01:15:29.752Z,1347326129.752 [ElevatorServo] No Fault, FailCount= 2
2012-09-11T01:15:30.549Z,1347326130.549 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T01:15:30.668Z,1347326130.668 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T01:15:30.668Z,1347326130.668 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T01:15:35.371Z,1347326135.371 [ElevatorServo](FAULT): Overload Error
2012-09-11T01:15:35.371Z,1347326135.371 [ElevatorServo] Hardware Fault, FailCount= 3
2012-09-11T01:15:35.371Z,1347326135.371 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T01:15:35.398Z,1347326135.398 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T01:15:35.399Z,1347326135.399 [CBIT](CRITICAL): Hardware Fault in component: ElevatorServo
2012-09-11T01:15:35.748Z,1347326135.748 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T01:15:35.748Z,1347326135.748 [ElevatorServo](INFO): Powering down
2012-09-11T01:15:38.703Z,1347326138.703 [NAL9602](INFO): NAL9602 initialized
2012-09-11T01:16:06.453Z,1347326166.453 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=860, MT Status=1, MTMSN=91
2012-09-11T01:16:06.487Z,1347326166.487 [NAL9602](INFO): Sent 226 bytes from file Logs/20120911T005835/shore0003.lzma
2012-09-11T01:16:06.487Z,1347326166.487 [NAL9602](INFO): Packets left to send: 0
2012-09-11T01:16:06.489Z,1347326166.489 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0003.lzma.parts/0000.sbd
2012-09-11T01:16:07.132Z,1347326167.132 [NAL9602](INFO): Received command:run Maintenance/ballast_and_trim.xml
2012-09-11T01:16:07.152Z,1347326167.152 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/ballast_and_trim.xml
2012-09-11T01:16:07.153Z,1347326167.152 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/ballast_and_trim.xml
2012-09-11T01:16:07.210Z,1347326167.210 [MissionManager](INFO): DefineArg ballast_and_trim.BallastDepth = 25.000000 m
2012-09-11T01:16:07.237Z,1347326167.237 [MissionManager](INFO): DefineArg ballast_and_trim.HoldDuration = 25.000000 min
2012-09-11T01:16:07.240Z,1347326167.240 [MissionManager](INFO): DefineArg ballast_and_trim.Speed = 1.000000 m/s
2012-09-11T01:16:07.243Z,1347326167.243 [MissionManager](INFO): DefineArg ballast_and_trim.DepthDeadband = 4.000000 m
2012-09-11T01:16:07.246Z,1347326167.246 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyPeriod = 0.400000 s
2012-09-11T01:16:07.262Z,1347326167.261 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyancyDefault = 0.000945 n/a
2012-09-11T01:16:07.269Z,1347326167.269 [ballast_and_trim:D.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-09-11T01:16:07.288Z,1347326167.288 [ballast_and_trim:E.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-09-11T01:16:07.310Z,1347326167.310 [ballast_and_trim:F.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2012-09-11T01:16:07.317Z,1347326167.316 [MissionManager](INFO): Inserting Stack: Missions/Insert/Surface.xml
2012-09-11T01:16:07.354Z,1347326167.354 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfaceDepthRate = nan m/s
2012-09-11T01:16:07.357Z,1347326167.357 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfacePitch = nan arcdeg
2012-09-11T01:16:07.372Z,1347326167.372 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfaceSpeed = 0.500000 m/s
2012-09-11T01:16:07.375Z,1347326167.375 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.IridiumTimeout = 30.000000 min
2012-09-11T01:16:07.377Z,1347326167.377 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-11T01:16:07.399Z,1347326167.399 [ballast_and_trim:H.SetSpeed](DEBUG): Construct.
2012-09-11T01:16:07.404Z,1347326167.404 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Construct.
2012-09-11T01:16:07.409Z,1347326167.409 [ballast_and_trim:ballast:C.Pitch](DEBUG): Construct.
2012-09-11T01:16:07.427Z,1347326167.427 [ballast_and_trim:ballast:D.Wait](DEBUG): Construct Wait.
2012-09-11T01:16:07.433Z,1347326167.433 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Construct Wait.
2012-09-11T01:16:07.449Z,1347326167.449 [ballast_and_trim:ballast:Float_Up:A.SetSpeed](DEBUG): Construct.
2012-09-11T01:16:07.452Z,1347326167.452 [ballast_and_trim:ballast:Float_Up:B.Buoyancy](DEBUG): Construct Buoyancy.
2012-09-11T01:16:07.456Z,1347326167.455 [ballast_and_trim:ballast:Float_Up:C.Wait](DEBUG): Construct Wait.
2012-09-11T01:16:07.475Z,1347326167.475 [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>0.4</Value></DefineArg>

    <DefineArg Name="BuoyancyDefault"><Control:VerticalControl.buoyancyDefault/></DefineArg>

<!-- The timeout -->

    <Timeout Duration="P90M"/>

<!-- And now the mission -->

    <Assign RunIn="Parallel"><Control:VerticalControl.kpPitchMass/><Units:count/><Value>0.01</Value></Assign>

    <Assign RunIn="Parallel"><Control:VerticalControl.kiPitchMass/><Units:reciprocal_second/><Value>0.0015</Value></Assign>

    <Assign RunIn="Parallel"><Control:VerticalControl.kdPitchMass/><Units:second/><Value>0</Value></Assign>

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

        <Assign RunIn="Parallel"><Control:VerticalControl.depthDeadband/><Arg Name="DepthDeadband"/></Assign>

        <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/>
            Mass:<Universal:platform_mass_position/><Units:centimeter/>
            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>


2012-09-11T01:16:07.476Z,1347326167.476 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/ballast_and_trim.xml
2012-09-11T01:16:07.588Z,1347326167.588 [Default] Stopped
2012-09-11T01:16:07.589Z,1347326167.589 [Default](INFO): Aggregate::uninitialize Default
2012-09-11T01:16:07.589Z,1347326167.589 [Default:GPS] Stopped
2012-09-11T01:16:07.589Z,1347326167.589 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-11T01:16:07.589Z,1347326167.589 [Default:GPS:A.SetSpeed] Stopped
2012-09-11T01:16:07.589Z,1347326167.589 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T01:16:07.589Z,1347326167.589 [Default:GPS:Read_GPS] Stopped
2012-09-11T01:16:07.589Z,1347326167.589 [Default:Iridium] Stopped
2012-09-11T01:16:07.589Z,1347326167.589 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-11T01:16:07.589Z,1347326167.589 [Default:Iridium:A.SetSpeed] Stopped
2012-09-11T01:16:07.589Z,1347326167.589 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T01:16:07.590Z,1347326167.589 [Default:Iridium:Read_Iridium] Stopped
2012-09-11T01:16:07.590Z,1347326167.590 [Default:CallIridium] Stopped
2012-09-11T01:16:07.590Z,1347326167.590 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-09-11T01:16:07.590Z,1347326167.590 [Default:CallIridium:B] Stopped
2012-09-11T01:16:07.590Z,1347326167.590 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-09-11T01:16:07.590Z,1347326167.590 [Default:D.SetSpeed] Stopped
2012-09-11T01:16:07.590Z,1347326167.590 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-09-11T01:16:07.590Z,1347326167.590 [Default:E.GoToSurface] Stopped
2012-09-11T01:16:07.590Z,1347326167.590 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T01:16:07.590Z,1347326167.591 [Default:F.Wait] Stopped
2012-09-11T01:16:07.591Z,1347326167.591 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2012-09-11T01:16:07.591Z,1347326167.591 [MissionManager](IMPORTANT): Started mission ballast_and_trim
2012-09-11T01:16:07.591Z,1347326167.591 [ballast_and_trim] Running Loop=1
2012-09-11T01:16:07.591Z,1347326167.591 [ballast_and_trim](INFO): Aggregate::initialize ballast_and_trim
2012-09-11T01:16:07.591Z,1347326167.591 [ballast_and_trim:A] Running Loop=1
2012-09-11T01:16:07.591Z,1347326167.591 [ballast_and_trim:B] Running Loop=1
2012-09-11T01:16:07.591Z,1347326167.591 [ballast_and_trim:C] Running Loop=1
2012-09-11T01:16:07.591Z,1347326167.591 [ballast_and_trim:D.AltitudeEnvelope] Running Loop=1
2012-09-11T01:16:07.591Z,1347326167.591 [ballast_and_trim:D.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-09-11T01:16:07.592Z,1347326167.592 [ballast_and_trim:E.DepthEnvelope] Running Loop=1
2012-09-11T01:16:07.592Z,1347326167.592 [ballast_and_trim:E.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-09-11T01:16:07.593Z,1347326167.593 [ballast_and_trim:F.OffshoreEnvelope] Running Loop=1
2012-09-11T01:16:07.593Z,1347326167.593 [ballast_and_trim:F.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2012-09-11T01:16:07.593Z,1347326167.593 [ballast_and_trim:H.SetSpeed] Running Loop=1
2012-09-11T01:16:07.593Z,1347326167.593 [ballast_and_trim:H.SetSpeed](DEBUG): Initialize.
2012-09-11T01:16:07.593Z,1347326167.593 [ballast_and_trim:SurfaceComms] Running Loop=1
2012-09-11T01:16:07.593Z,1347326167.593 [ballast_and_trim:SurfaceComms](INFO): Aggregate::initialize ballast_and_trim:SurfaceComms
2012-09-11T01:16:07.593Z,1347326167.593 [ballast_and_trim:SurfaceComms:A.GoToSurface] Running Loop=1
2012-09-11T01:16:07.594Z,1347326167.593 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T01:16:07.594Z,1347326167.594 [ballast_and_trim:H.SetSpeed] Running Loop=1
2012-09-11T01:16:07.604Z,1347326167.604 [ballast_and_trim:SurfaceComms:B] Running Loop=1
2012-09-11T01:16:07.604Z,1347326167.605 [ballast_and_trim:SurfaceComms:B](INFO): Aggregate::initialize ballast_and_trim:SurfaceComms:B
2012-09-11T01:16:07.605Z,1347326167.605 [ballast_and_trim:SurfaceComms:B:A] Running Loop=1
2012-09-11T01:16:07.605Z,1347326167.605 [ballast_and_trim:F.OffshoreEnvelope] Running Loop=1
2012-09-11T01:16:07.618Z,1347326167.618 [ballast_and_trim:E.DepthEnvelope] Running Loop=1
2012-09-11T01:16:07.624Z,1347326167.624 [ballast_and_trim:D.AltitudeEnvelope] Running Loop=1
2012-09-11T01:16:07.629Z,1347326167.629 [ballast_and_trim:C] Running Loop=1
2012-09-11T01:16:07.631Z,1347326167.631 [ballast_and_trim:B] Running Loop=1
2012-09-11T01:16:07.632Z,1347326167.632 [ballast_and_trim:A] Running Loop=1
2012-09-11T01:16:07.939Z,1347326167.939 [DVL_micro](INFO): RSSI unrequested
2012-09-11T01:16:07.939Z,1347326167.939 [DVL_micro](INFO): ADCP unrequested
2012-09-11T01:16:07.940Z,1347326167.940 [DVL_micro](INFO): resume:Powering up
2012-09-11T01:16:07.985Z,1347326167.985 [ballast_and_trim:H.SetSpeed] Preempted
2012-09-11T01:16:07.986Z,1347326167.986 [ballast_and_trim:SurfaceComms:B:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-09-11T01:16:09.447Z,1347326169.447 [DVL_micro](INFO): Querying output modes
2012-09-11T01:16:09.447Z,1347326169.447 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-11T01:16:09.455Z,1347326169.455 [DVL_micro](DEBUG): cmdResponse: 01 03 16
2012-09-11T01:16:09.455Z,1347326169.455 [DVL_micro](INFO): NQ1 output enabled
2012-09-11T01:16:09.455Z,1347326169.455 [DVL_micro](INFO): RSSI output enabled
2012-09-11T01:16:09.455Z,1347326169.455 [DVL_micro](INFO): ADCP output enabled
2012-09-11T01:16:09.455Z,1347326169.455 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-11T01:16:09.463Z,1347326169.463 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-11T01:16:09.465Z,1347326169.465 [DVL_micro](INFO): RSSI unrequested
2012-09-11T01:16:09.465Z,1347326169.465 [DVL_micro](INFO): ADCP unrequested
2012-09-11T01:18:37.974Z,1347326317.974 [NAL9602](IMPORTANT): GPS fix at: 1347326312.00
2012-09-11T01:18:38.023Z,1347326318.023 [ballast_and_trim:SurfaceComms:B:A] Stopped
2012-09-11T01:18:38.023Z,1347326318.023 [ballast_and_trim:SurfaceComms:B:B] Running Loop=1
2012-09-11T01:18:38.596Z,1347326318.596 [ballast_and_trim:SurfaceComms:B:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-09-11T01:18:47.580Z,1347326327.580 [NAL9602](INFO): SBD MO Status=2, MOMSN=861, MT Status=2, MTMSN=0
2012-09-11T01:18:47.580Z,1347326327.580 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T01:18:52.752Z,1347326332.752 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T01:18:56.328Z,1347326336.328 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T01:19:19.432Z,1347326359.432 [NAL9602](INFO): SBD MO Status=0, MOMSN=861, MT Status=0, MTMSN=0
2012-09-11T01:19:40.121Z,1347326380.121 [NAL9602](INFO): SBD MO Status=2, MOMSN=862, MT Status=2, MTMSN=0
2012-09-11T01:19:40.121Z,1347326380.121 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T01:20:10.948Z,1347326410.948 [NAL9602](INFO): SBD MO Status=2, MOMSN=862, MT Status=2, MTMSN=0
2012-09-11T01:20:10.949Z,1347326410.949 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T01:20:29.812Z,1347326429.812 [NAL9602](INFO): SBD MO Status=1, MOMSN=862, MT Status=0, MTMSN=0
2012-09-11T01:20:29.847Z,1347326429.847 [NAL9602](INFO): Sent 332 bytes from file Logs/20120911T005835/shore0004.lzma
2012-09-11T01:20:29.847Z,1347326429.847 [NAL9602](INFO): Packets left to send: 1
2012-09-11T01:20:29.849Z,1347326429.849 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0004.lzma.parts/0001.sbd
2012-09-11T01:20:42.521Z,1347326442.521 [NAL9602](INFO): SBD MO Status=1, MOMSN=863, MT Status=0, MTMSN=0
2012-09-11T01:20:42.555Z,1347326442.555 [NAL9602](INFO): Sent 210 bytes from file Logs/20120911T005835/shore0004.lzma
2012-09-11T01:20:42.555Z,1347326442.555 [NAL9602](INFO): Packets left to send: 0
2012-09-11T01:20:42.556Z,1347326442.556 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0004.lzma.parts/0000.sbd
2012-09-11T01:20:59.722Z,1347326459.722 [NAL9602](INFO): SBD MO Status=0, MOMSN=864, MT Status=0, MTMSN=0
2012-09-11T01:20:59.793Z,1347326459.793 [ballast_and_trim:SurfaceComms:B:B] Stopped
2012-09-11T01:20:59.793Z,1347326459.793 [ballast_and_trim:SurfaceComms:B:C] Running Loop=1
2012-09-11T01:21:00.160Z,1347326460.159 [ballast_and_trim:SurfaceComms:B:C](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-09-11T01:21:02.134Z,1347326462.134 [NAL9602](IMPORTANT): GPS fix at: 1347326457.00
2012-09-11T01:21:02.166Z,1347326462.166 [ballast_and_trim:SurfaceComms:B:C] Stopped
2012-09-11T01:21:02.166Z,1347326462.166 [ballast_and_trim:SurfaceComms:B](INFO): Completed ballast_and_trim:SurfaceComms:B
2012-09-11T01:21:02.166Z,1347326462.166 [ballast_and_trim:SurfaceComms:B] Stopped
2012-09-11T01:21:02.170Z,1347326462.171 [ballast_and_trim:SurfaceComms:B](INFO): Aggregate::uninitialize ballast_and_trim:SurfaceComms:B
2012-09-11T01:21:02.171Z,1347326462.171 [ballast_and_trim:SurfaceComms](INFO): Completed ballast_and_trim:SurfaceComms
2012-09-11T01:21:02.171Z,1347326462.171 [ballast_and_trim:SurfaceComms] Stopped
2012-09-11T01:21:02.172Z,1347326462.172 [ballast_and_trim:SurfaceComms](INFO): Aggregate::uninitialize ballast_and_trim:SurfaceComms
2012-09-11T01:21:02.172Z,1347326462.172 [ballast_and_trim:SurfaceComms:A.GoToSurface] Stopped
2012-09-11T01:21:02.172Z,1347326462.172 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T01:21:02.172Z,1347326462.172 [ballast_and_trim:ballast] Running Loop=1
2012-09-11T01:21:02.172Z,1347326462.172 [ballast_and_trim:ballast](INFO): Aggregate::initialize ballast_and_trim:ballast
2012-09-11T01:21:02.172Z,1347326462.172 [ballast_and_trim:ballast:A.SetSpeed] Running Loop=1
2012-09-11T01:21:02.172Z,1347326462.172 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Initialize.
2012-09-11T01:21:02.172Z,1347326462.172 [ballast_and_trim:ballast:B] Running Loop=1
2012-09-11T01:21:02.172Z,1347326462.172 [ballast_and_trim:ballast:C.Pitch] Running Loop=1
2012-09-11T01:21:02.172Z,1347326462.172 [ballast_and_trim:ballast:C.Pitch](DEBUG): Initialize.
2012-09-11T01:21:02.173Z,1347326462.173 [ballast_and_trim:ballast:D.Wait] Running Loop=1
2012-09-11T01:21:02.173Z,1347326462.173 [ballast_and_trim:ballast:D.Wait](DEBUG): Initialize Wait Component.
2012-09-11T01:21:02.574Z,1347326462.574 [ballast_and_trim:ballast:C.Pitch] Running Loop=1
2012-09-11T01:21:02.587Z,1347326462.587 [ballast_and_trim:ballast:B] Running Loop=1
2012-09-11T01:21:02.588Z,1347326462.588 [ballast_and_trim:ballast:A.SetSpeed] Running Loop=1
2012-09-11T01:21:03.379Z,1347326463.379 [ballast_and_trim:H.SetSpeed] Running Loop=1
2012-09-11T01:21:08.922Z,1347326468.922 [NAL9602](INFO): Powering down
2012-09-11T01:21:20.554Z,1347326480.555 [ThrusterServo](FAULT): getVelocity uart error serial timeout
2012-09-11T01:21:20.555Z,1347326480.555 [ThrusterServo](FAULT): Thruster uart error: serial timeout
2012-09-11T01:21:20.555Z,1347326480.555 [ThrusterServo] Communications Fault, FailCount= 1
2012-09-11T01:21:20.555Z,1347326480.555 [ThrusterServo](ERROR): Communications Fault
2012-09-11T01:21:20.558Z,1347326480.557 [CBIT](ERROR): Communications Fault in component: ThrusterServo
2012-09-11T01:21:20.912Z,1347326480.912 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2012-09-11T01:21:20.912Z,1347326480.912 [ThrusterServo](INFO): Powering down
2012-09-11T01:21:20.915Z,1347326480.915 [CBIT](INFO): Clearing failed state for component ThrusterServo
2012-09-11T01:21:20.915Z,1347326480.915 [ThrusterServo] No Fault, FailCount= 1
2012-09-11T01:21:21.648Z,1347326481.648 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-09-11T01:21:21.768Z,1347326481.768 [ThrusterServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T01:21:21.768Z,1347326481.768 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-09-11T01:30:35.459Z,1347327035.459 [CBIT](INFO): Clearing failed count for component ElevatorServo
2012-09-11T01:30:35.459Z,1347327035.459 [ElevatorServo] No Fault, FailCount= 3
2012-09-11T01:30:36.240Z,1347327036.240 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T01:30:36.360Z,1347327036.360 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T01:30:36.360Z,1347327036.360 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T01:30:41.047Z,1347327041.047 [ElevatorServo](FAULT): Overload Error
2012-09-11T01:30:41.047Z,1347327041.047 [ElevatorServo] Hardware Fault, FailCount= 1
2012-09-11T01:30:41.047Z,1347327041.047 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T01:30:41.097Z,1347327041.097 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T01:30:41.421Z,1347327041.421 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T01:30:41.421Z,1347327041.421 [ElevatorServo](INFO): Powering down
2012-09-11T01:30:41.501Z,1347327041.501 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-09-11T01:30:41.501Z,1347327041.501 [ElevatorServo] No Fault, FailCount= 1
2012-09-11T01:30:42.218Z,1347327042.218 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T01:30:42.336Z,1347327042.336 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T01:30:42.336Z,1347327042.336 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T01:30:47.027Z,1347327047.027 [ElevatorServo](FAULT): Overload Error
2012-09-11T01:30:47.027Z,1347327047.027 [ElevatorServo] Hardware Fault, FailCount= 2
2012-09-11T01:30:47.027Z,1347327047.027 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T01:30:47.077Z,1347327047.077 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T01:30:47.405Z,1347327047.405 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T01:30:47.406Z,1347327047.406 [ElevatorServo](INFO): Powering down
2012-09-11T01:30:47.485Z,1347327047.485 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-09-11T01:30:47.485Z,1347327047.485 [ElevatorServo] No Fault, FailCount= 2
2012-09-11T01:30:48.228Z,1347327048.228 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T01:30:48.348Z,1347327048.348 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T01:30:48.348Z,1347327048.348 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T01:30:53.051Z,1347327053.051 [ElevatorServo](FAULT): Overload Error
2012-09-11T01:30:53.051Z,1347327053.051 [ElevatorServo] Hardware Fault, FailCount= 3
2012-09-11T01:30:53.051Z,1347327053.051 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T01:30:53.101Z,1347327053.101 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T01:30:53.102Z,1347327053.102 [CBIT](CRITICAL): Hardware Fault in component: ElevatorServo
2012-09-11T01:30:53.417Z,1347327053.418 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T01:30:53.418Z,1347327053.418 [ElevatorServo](INFO): Powering down
2012-09-11T01:30:53.813Z,1347327053.813 [ballast_and_trim] Stopped
2012-09-11T01:30:53.813Z,1347327053.813 [ballast_and_trim](INFO): Aggregate::uninitialize ballast_and_trim
2012-09-11T01:30:53.814Z,1347327053.814 [ballast_and_trim:A] Stopped
2012-09-11T01:30:53.814Z,1347327053.814 [ballast_and_trim:B] Stopped
2012-09-11T01:30:53.814Z,1347327053.814 [ballast_and_trim:C] Stopped
2012-09-11T01:30:53.814Z,1347327053.814 [ballast_and_trim:D.AltitudeEnvelope] Stopped
2012-09-11T01:30:53.814Z,1347327053.814 [ballast_and_trim:D.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-09-11T01:30:53.814Z,1347327053.814 [ballast_and_trim:E.DepthEnvelope] Stopped
2012-09-11T01:30:53.814Z,1347327053.814 [ballast_and_trim:E.DepthEnvelope](DEBUG): Uninitialize.
2012-09-11T01:30:53.814Z,1347327053.814 [ballast_and_trim:F.OffshoreEnvelope] Stopped
2012-09-11T01:30:53.814Z,1347327053.814 [ballast_and_trim:F.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2012-09-11T01:30:53.814Z,1347327053.814 [ballast_and_trim:H.SetSpeed] Stopped
2012-09-11T01:30:53.818Z,1347327053.819 [ballast_and_trim:H.SetSpeed](DEBUG): Uninitialize.
2012-09-11T01:30:53.819Z,1347327053.819 [ballast_and_trim:ballast] Stopped
2012-09-11T01:30:53.819Z,1347327053.819 [ballast_and_trim:ballast](INFO): Aggregate::uninitialize ballast_and_trim:ballast
2012-09-11T01:30:53.819Z,1347327053.819 [ballast_and_trim:ballast:A.SetSpeed] Stopped
2012-09-11T01:30:53.819Z,1347327053.819 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T01:30:53.819Z,1347327053.819 [ballast_and_trim:ballast:B] Stopped
2012-09-11T01:30:53.819Z,1347327053.819 [ballast_and_trim:ballast:C.Pitch] Stopped
2012-09-11T01:30:53.819Z,1347327053.819 [ballast_and_trim:ballast:D.Wait] Stopped
2012-09-11T01:30:53.819Z,1347327053.819 [ballast_and_trim:ballast:D.Wait](DEBUG): Uninitialize Wait Component.
2012-09-11T01:30:54.174Z,1347327054.174 [MissionManager](IMPORTANT): Started mission Default
2012-09-11T01:30:54.174Z,1347327054.174 [Default] Running Loop=1
2012-09-11T01:30:54.174Z,1347327054.174 [Default](INFO): Aggregate::initialize Default
2012-09-11T01:30:54.174Z,1347327054.174 [Default:D.SetSpeed] Running Loop=1
2012-09-11T01:30:54.174Z,1347327054.174 [Default:D.SetSpeed](DEBUG): Initialize.
2012-09-11T01:30:54.178Z,1347327054.178 [Default:E.GoToSurface] Running Loop=1
2012-09-11T01:30:54.178Z,1347327054.178 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T01:30:54.179Z,1347327054.179 [Default:Iridium] Running Loop=1
2012-09-11T01:30:54.179Z,1347327054.179 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-11T01:30:54.179Z,1347327054.179 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T01:30:54.179Z,1347327054.179 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-11T01:30:54.179Z,1347327054.179 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-11T01:30:54.179Z,1347327054.179 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T01:30:54.181Z,1347327054.181 [Default:CallIridium] Running Loop=1
2012-09-11T01:30:54.181Z,1347327054.181 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-11T01:30:54.181Z,1347327054.181 [Default:CallIridium:A] Running Loop=1
2012-09-11T01:30:54.181Z,1347327054.181 [Default:CallIridium:A] Stopped
2012-09-11T01:30:54.181Z,1347327054.181 [Default:CallIridium:B] Running Loop=1
2012-09-11T01:30:54.182Z,1347327054.182 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-11T01:30:54.187Z,1347327054.187 [Default:GPS] Running Loop=1
2012-09-11T01:30:54.187Z,1347327054.187 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-11T01:30:54.187Z,1347327054.187 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T01:30:54.187Z,1347327054.187 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-11T01:30:54.187Z,1347327054.187 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-11T01:30:54.187Z,1347327054.187 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T01:31:34.177Z,1347327094.177 [VerticalControl](CRITICAL): Can not stop descending, stopping mission at depth excursion=6.014307, upwardsErrorDepth_=19.964808, depthRate=0.101685
2012-09-11T01:35:16.296Z,1347327316.296 [Default:Iridium:B.GoToSurface] Stopped
2012-09-11T01:35:16.296Z,1347327316.296 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T01:35:16.296Z,1347327316.296 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-11T01:35:16.297Z,1347327316.297 [Default:GPS:B.GoToSurface] Stopped
2012-09-11T01:35:16.297Z,1347327316.297 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T01:35:16.297Z,1347327316.297 [Default:GPS:Read_GPS] Running Loop=1
2012-09-11T01:35:17.051Z,1347327317.051 [NAL9602](INFO): Powering up
2012-09-11T01:35:28.019Z,1347327328.019 [NAL9602](INFO): NAL9602 initialized
2012-09-11T01:36:02.172Z,1347327362.172 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=865, MT Status=1, MTMSN=92
2012-09-11T01:36:02.207Z,1347327362.207 [NAL9602](INFO): Sent 332 bytes from file Logs/20120911T005835/shore0005.lzma
2012-09-11T01:36:02.207Z,1347327362.207 [NAL9602](INFO): Packets left to send: 3
2012-09-11T01:36:02.209Z,1347327362.209 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0005.lzma.parts/0003.sbd
2012-09-11T01:36:02.748Z,1347327362.748 [NAL9602](INFO): Received command:get platform_elevator_angle
2012-09-11T01:36:02.954Z,1347327362.954 [CommandLine](IMPORTANT): got command get platform_elevator_angle
2012-09-11T01:36:02.955Z,1347327362.954 [CommandLine](IMPORTANT): platform_elevator_angle 0.000000 degree
2012-09-11T01:36:15.491Z,1347327375.491 [NAL9602](INFO): SBD MO Status=1, MOMSN=866, MT Status=0, MTMSN=0
2012-09-11T01:36:15.523Z,1347327375.523 [NAL9602](INFO): Sent 332 bytes from file Logs/20120911T005835/shore0005.lzma
2012-09-11T01:36:15.523Z,1347327375.523 [NAL9602](INFO): Packets left to send: 2
2012-09-11T01:36:15.524Z,1347327375.524 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0005.lzma.parts/0002.sbd
2012-09-11T01:36:24.047Z,1347327384.047 [NAL9602](INFO): SBD MO Status=1, MOMSN=867, MT Status=0, MTMSN=0
2012-09-11T01:36:24.079Z,1347327384.079 [NAL9602](INFO): Sent 332 bytes from file Logs/20120911T005835/shore0005.lzma
2012-09-11T01:36:24.079Z,1347327384.079 [NAL9602](INFO): Packets left to send: 1
2012-09-11T01:36:24.080Z,1347327384.080 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0005.lzma.parts/0001.sbd
2012-09-11T01:36:35.024Z,1347327395.024 [NAL9602](INFO): SBD MO Status=1, MOMSN=868, MT Status=0, MTMSN=0
2012-09-11T01:36:35.059Z,1347327395.059 [NAL9602](INFO): Sent 136 bytes from file Logs/20120911T005835/shore0005.lzma
2012-09-11T01:36:35.059Z,1347327395.059 [NAL9602](INFO): Packets left to send: 0
2012-09-11T01:36:35.060Z,1347327395.060 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0005.lzma.parts/0000.sbd
2012-09-11T01:36:43.424Z,1347327403.424 [NAL9602](INFO): SBD MO Status=0, MOMSN=869, MT Status=0, MTMSN=0
2012-09-11T01:36:44.626Z,1347327404.626 [NAL9602](IMPORTANT): GPS fix at: 1347327400.00
2012-09-11T01:36:44.654Z,1347327404.654 [Navigation](IMPORTANT): Error 32.6 %DT at bearing 40.2 deg., over the last 575.7 m.
2012-09-11T01:36:44.661Z,1347327404.661 [Default:GPS:Read_GPS] Stopped
2012-09-11T01:36:44.661Z,1347327404.661 [Default:GPS:D] Running Loop=1
2012-09-11T01:36:45.060Z,1347327405.060 [Default:GPS:D] Stopped
2012-09-11T01:36:45.061Z,1347327405.061 [Default:GPS](INFO): Completed Default:GPS
2012-09-11T01:36:45.061Z,1347327405.061 [Default:GPS] Stopped
2012-09-11T01:36:45.061Z,1347327405.061 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-11T01:36:45.061Z,1347327405.061 [Default:GPS:A.SetSpeed] Stopped
2012-09-11T01:36:45.061Z,1347327405.061 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T01:36:55.880Z,1347327415.880 [NAL9602](INFO): SBD MO Status=1, MOMSN=870, MT Status=0, MTMSN=0
2012-09-11T01:36:55.915Z,1347327415.915 [NAL9602](INFO): Sent 220 bytes from file Logs/20120911T005835/shore0006.lzma
2012-09-11T01:36:55.915Z,1347327415.915 [NAL9602](INFO): Packets left to send: 0
2012-09-11T01:36:55.917Z,1347327415.917 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0006.lzma.parts/0000.sbd
2012-09-11T01:37:05.081Z,1347327425.081 [NAL9602](INFO): SBD MO Status=0, MOMSN=871, MT Status=0, MTMSN=0
2012-09-11T01:37:05.156Z,1347327425.157 [Default:Iridium:Read_Iridium] Stopped
2012-09-11T01:37:05.157Z,1347327425.157 [Default:Iridium](INFO): Completed Default:Iridium
2012-09-11T01:37:05.157Z,1347327425.157 [Default:Iridium] Stopped
2012-09-11T01:37:05.157Z,1347327425.157 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-11T01:37:05.157Z,1347327425.157 [Default:Iridium:A.SetSpeed] Stopped
2012-09-11T01:37:05.157Z,1347327425.157 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T01:37:05.158Z,1347327425.158 [Default:F.Wait] Running Loop=1
2012-09-11T01:37:05.158Z,1347327425.158 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-09-11T01:37:05.512Z,1347327425.512 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-09-11T01:37:05.512Z,1347327425.512 [Default:CallIridium:B] Stopped
2012-09-11T01:37:05.512Z,1347327425.512 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-09-11T01:37:05.512Z,1347327425.512 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-09-11T01:37:05.512Z,1347327425.512 [Default:CallIridium] Stopped
2012-09-11T01:37:05.512Z,1347327425.512 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-09-11T01:37:15.675Z,1347327435.675 [NAL9602](INFO): Powering down
2012-09-11T01:42:05.619Z,1347327725.619 [Default:CallIridium] Running Loop=1
2012-09-11T01:42:05.619Z,1347327725.619 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-11T01:42:05.619Z,1347327725.619 [Default:CallIridium:A] Running Loop=1
2012-09-11T01:42:05.619Z,1347327725.619 [Default:CallIridium:A] Stopped
2012-09-11T01:42:05.620Z,1347327725.620 [Default:CallIridium:B] Running Loop=1
2012-09-11T01:42:05.620Z,1347327725.620 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-11T01:42:10.715Z,1347327730.715 [Default:Iridium] Running Loop=1
2012-09-11T01:42:10.715Z,1347327730.715 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-11T01:42:10.715Z,1347327730.715 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T01:42:10.715Z,1347327730.715 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-11T01:42:10.715Z,1347327730.716 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-11T01:42:10.716Z,1347327730.716 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T01:42:10.716Z,1347327730.716 [Default:Iridium:B.GoToSurface] Stopped
2012-09-11T01:42:10.716Z,1347327730.717 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T01:42:10.717Z,1347327730.717 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-11T01:42:10.717Z,1347327730.717 [Default:GPS] Running Loop=1
2012-09-11T01:42:10.717Z,1347327730.717 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-11T01:42:10.717Z,1347327730.717 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T01:42:10.717Z,1347327730.717 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-11T01:42:10.717Z,1347327730.717 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-11T01:42:10.718Z,1347327730.718 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T01:42:10.726Z,1347327730.727 [Default:GPS:B.GoToSurface] Stopped
2012-09-11T01:42:10.727Z,1347327730.727 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T01:42:10.727Z,1347327730.727 [Default:GPS:Read_GPS] Running Loop=1
2012-09-11T01:42:11.395Z,1347327731.395 [NAL9602](INFO): Powering up
2012-09-11T01:42:21.936Z,1347327741.935 [NAL9602](INFO): NAL9602 initialized
2012-09-11T01:42:39.920Z,1347327759.920 [NAL9602](INFO): SBD MO Status=1, MOMSN=872, MT Status=0, MTMSN=0
2012-09-11T01:42:39.955Z,1347327759.955 [NAL9602](INFO): Sent 255 bytes from file Logs/20120911T005835/shore0007.lzma
2012-09-11T01:42:39.955Z,1347327759.955 [NAL9602](INFO): Packets left to send: 0
2012-09-11T01:42:39.957Z,1347327759.957 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0007.lzma.parts/0000.sbd
2012-09-11T01:42:49.524Z,1347327769.524 [NAL9602](INFO): SBD MO Status=0, MOMSN=873, MT Status=0, MTMSN=0
2012-09-11T01:42:49.593Z,1347327769.593 [Default:Iridium:Read_Iridium] Stopped
2012-09-11T01:42:49.594Z,1347327769.593 [Default:Iridium](INFO): Completed Default:Iridium
2012-09-11T01:42:49.594Z,1347327769.594 [Default:Iridium] Stopped
2012-09-11T01:42:49.594Z,1347327769.594 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-11T01:42:49.594Z,1347327769.594 [Default:Iridium:A.SetSpeed] Stopped
2012-09-11T01:42:49.594Z,1347327769.594 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T01:42:49.970Z,1347327769.970 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-09-11T01:42:49.971Z,1347327769.971 [Default:CallIridium:B] Stopped
2012-09-11T01:42:49.971Z,1347327769.971 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-09-11T01:42:49.971Z,1347327769.971 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-09-11T01:42:49.971Z,1347327769.971 [Default:CallIridium] Stopped
2012-09-11T01:42:49.971Z,1347327769.971 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-09-11T01:42:50.730Z,1347327770.730 [NAL9602](IMPORTANT): GPS fix at: 1347327767.00
2012-09-11T01:42:50.771Z,1347327770.771 [Default:GPS:Read_GPS] Stopped
2012-09-11T01:42:50.771Z,1347327770.771 [Default:GPS:D] Running Loop=1
2012-09-11T01:42:51.156Z,1347327771.156 [Default:GPS:D] Stopped
2012-09-11T01:42:51.156Z,1347327771.156 [Default:GPS](INFO): Completed Default:GPS
2012-09-11T01:42:51.156Z,1347327771.156 [Default:GPS] Stopped
2012-09-11T01:42:51.156Z,1347327771.157 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-11T01:42:51.157Z,1347327771.157 [Default:GPS:A.SetSpeed] Stopped
2012-09-11T01:42:51.157Z,1347327771.157 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T01:43:11.638Z,1347327791.638 [NAL9602](INFO): Powering down
2012-09-11T01:45:56.822Z,1347327956.822 [CBIT](INFO): Clearing failed count for component ElevatorServo
2012-09-11T01:45:56.822Z,1347327956.822 [ElevatorServo] No Fault, FailCount= 3
2012-09-11T01:46:06.705Z,1347327966.705 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T01:46:06.824Z,1347327966.824 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T01:46:06.824Z,1347327966.824 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T01:46:36.724Z,1347327996.724 [ElevatorServo](FAULT): Overload Error
2012-09-11T01:46:36.724Z,1347327996.724 [ElevatorServo] Hardware Fault, FailCount= 1
2012-09-11T01:46:36.724Z,1347327996.724 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T01:46:36.750Z,1347327996.750 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T01:46:41.697Z,1347328001.697 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T01:46:41.697Z,1347328001.697 [ElevatorServo](INFO): Powering down
2012-09-11T01:46:41.701Z,1347328001.701 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-09-11T01:46:41.701Z,1347328001.701 [ElevatorServo] No Fault, FailCount= 1
2012-09-11T01:46:51.726Z,1347328011.726 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T01:46:51.844Z,1347328011.844 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T01:46:51.844Z,1347328011.844 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T01:47:21.787Z,1347328041.787 [ElevatorServo](FAULT): Overload Error
2012-09-11T01:47:21.787Z,1347328041.787 [ElevatorServo] Hardware Fault, FailCount= 2
2012-09-11T01:47:21.787Z,1347328041.787 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T01:47:21.814Z,1347328041.814 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T01:47:26.697Z,1347328046.697 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T01:47:26.697Z,1347328046.697 [ElevatorServo](INFO): Powering down
2012-09-11T01:47:26.705Z,1347328046.705 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-09-11T01:47:26.705Z,1347328046.705 [ElevatorServo] No Fault, FailCount= 2
2012-09-11T01:47:36.701Z,1347328056.701 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T01:47:36.820Z,1347328056.820 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T01:47:36.820Z,1347328056.820 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T01:47:51.671Z,1347328071.671 [Default:CallIridium] Running Loop=1
2012-09-11T01:47:51.671Z,1347328071.671 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-11T01:47:51.671Z,1347328071.671 [Default:CallIridium:A] Running Loop=1
2012-09-11T01:47:51.672Z,1347328071.671 [Default:CallIridium:A] Stopped
2012-09-11T01:47:51.672Z,1347328071.672 [Default:CallIridium:B] Running Loop=1
2012-09-11T01:47:51.672Z,1347328071.672 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-11T01:47:56.679Z,1347328076.679 [Default:Iridium] Running Loop=1
2012-09-11T01:47:56.679Z,1347328076.680 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-11T01:47:56.680Z,1347328076.680 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T01:47:56.680Z,1347328076.680 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-11T01:47:56.680Z,1347328076.680 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-11T01:47:56.680Z,1347328076.680 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T01:47:56.681Z,1347328076.681 [Default:Iridium:B.GoToSurface] Stopped
2012-09-11T01:47:56.681Z,1347328076.681 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T01:47:56.681Z,1347328076.681 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-11T01:47:56.681Z,1347328076.681 [Default:GPS] Running Loop=1
2012-09-11T01:47:56.682Z,1347328076.681 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-11T01:47:56.682Z,1347328076.682 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T01:47:56.682Z,1347328076.682 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-11T01:47:56.682Z,1347328076.682 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-11T01:47:56.682Z,1347328076.682 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T01:47:56.687Z,1347328076.687 [Default:GPS:B.GoToSurface] Stopped
2012-09-11T01:47:56.687Z,1347328076.687 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T01:47:56.687Z,1347328076.687 [Default:GPS:Read_GPS] Running Loop=1
2012-09-11T01:47:57.308Z,1347328077.308 [NAL9602](INFO): Powering up
2012-09-11T01:47:58.599Z,1347328078.599 [ElevatorServo](FAULT): Overload Error
2012-09-11T01:47:58.599Z,1347328078.599 [ElevatorServo] Hardware Fault, FailCount= 3
2012-09-11T01:47:58.599Z,1347328078.599 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T01:47:58.626Z,1347328078.626 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T01:47:58.627Z,1347328078.627 [CBIT](CRITICAL): Hardware Fault in component: ElevatorServo
2012-09-11T01:47:58.991Z,1347328078.991 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T01:47:58.991Z,1347328078.991 [ElevatorServo](INFO): Powering down
2012-09-11T01:48:08.327Z,1347328088.327 [NAL9602](INFO): NAL9602 initialized
2012-09-11T01:48:29.360Z,1347328109.360 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=874, MT Status=1, MTMSN=93
2012-09-11T01:48:29.395Z,1347328109.395 [NAL9602](INFO): Sent 234 bytes from file Logs/20120911T005835/shore0008.lzma
2012-09-11T01:48:29.395Z,1347328109.395 [NAL9602](INFO): Packets left to send: 0
2012-09-11T01:48:29.397Z,1347328109.397 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0008.lzma.parts/0000.sbd
2012-09-11T01:48:30.047Z,1347328110.047 [NAL9602](INFO): Received command:maintain control VerticalControl.elevatorAngleAction -7 degree
2012-09-11T01:48:30.416Z,1347328110.416 [CommandLine](IMPORTANT): got command maintain control VerticalControl.elevatorAngleAction -7.000000 degree
2012-09-11T01:48:38.112Z,1347328118.112 [NAL9602](INFO): SBD MO Status=0, MOMSN=875, MT Status=0, MTMSN=0
2012-09-11T01:48:59.730Z,1347328139.730 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=876, MT Status=1, MTMSN=94
2012-09-11T01:48:59.763Z,1347328139.763 [NAL9602](INFO): Sent 221 bytes from file Logs/20120911T005835/shore0009.lzma
2012-09-11T01:48:59.763Z,1347328139.763 [NAL9602](INFO): Packets left to send: 0
2012-09-11T01:48:59.765Z,1347328139.765 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0009.lzma.parts/0000.sbd
2012-09-11T01:49:00.396Z,1347328140.396 [NAL9602](INFO): Received command:report m platform_elevator_angle
2012-09-11T01:49:00.713Z,1347328140.713 [CommandLine](IMPORTANT): got command report mod platform_elevator_angle
2012-09-11T01:49:00.791Z,1347328140.792 [Reporter](INFO): platform_elevator_angle -7.000000 arcdeg
2012-09-11T01:49:20.800Z,1347328160.800 [NAL9602](INFO): SBD MO Status=0, MOMSN=877, MT Status=0, MTMSN=0
2012-09-11T01:49:42.452Z,1347328182.452 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=878, MT Status=1, MTMSN=95
2012-09-11T01:49:42.487Z,1347328182.487 [NAL9602](INFO): Sent 197 bytes from file Logs/20120911T005835/shore0010.lzma
2012-09-11T01:49:42.487Z,1347328182.487 [NAL9602](INFO): Packets left to send: 0
2012-09-11T01:49:42.489Z,1347328182.489 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0010.lzma.parts/0000.sbd
2012-09-11T01:49:43.040Z,1347328183.039 [NAL9602](INFO): Received command:failc n ElevatorServo
2012-09-11T01:49:43.115Z,1347328183.115 [CommandLine](IMPORTANT): got command failComponent none ElevatorServo
2012-09-11T01:49:43.115Z,1347328183.115 [ElevatorServo] No Fault, FailCount= 3
2012-09-11T01:49:43.116Z,1347328183.115 [CommandLine](IMPORTANT): ElevatorServo failureMode is No Fault
2012-09-11T01:49:43.715Z,1347328183.715 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T01:49:43.836Z,1347328183.836 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T01:49:43.836Z,1347328183.836 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T01:49:44.057Z,1347328184.057 [NAL9602](IMPORTANT): GPS fix at: 1347328181.00
2012-09-11T01:49:44.115Z,1347328184.115 [Default:GPS:Read_GPS] Stopped
2012-09-11T01:49:44.115Z,1347328184.115 [Default:GPS:D] Running Loop=1
2012-09-11T01:49:44.476Z,1347328184.476 [Default:GPS:D] Stopped
2012-09-11T01:49:44.477Z,1347328184.477 [Default:GPS](INFO): Completed Default:GPS
2012-09-11T01:49:44.477Z,1347328184.477 [Default:GPS] Stopped
2012-09-11T01:49:44.477Z,1347328184.477 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-11T01:49:44.477Z,1347328184.477 [Default:GPS:A.SetSpeed] Stopped
2012-09-11T01:49:44.477Z,1347328184.477 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T01:49:46.510Z,1347328186.510 [Reporter](INFO): platform_elevator_angle -0.156351 rad
2012-09-11T01:49:47.460Z,1347328187.460 [Reporter](INFO): platform_elevator_angle -0.159383 rad
2012-09-11T01:49:47.728Z,1347328187.728 [Reporter](INFO): platform_elevator_angle -0.156312 rad
2012-09-11T01:49:48.084Z,1347328188.084 [Reporter](INFO): platform_elevator_angle -0.156351 rad
2012-09-11T01:49:48.863Z,1347328188.863 [ElevatorServo](FAULT): Overload Error
2012-09-11T01:49:48.863Z,1347328188.863 [ElevatorServo] Hardware Fault, FailCount= 4
2012-09-11T01:49:48.863Z,1347328188.863 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T01:49:48.890Z,1347328188.890 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T01:49:48.891Z,1347328188.891 [CBIT](CRITICAL): Hardware Fault in component: ElevatorServo
2012-09-11T01:49:48.892Z,1347328188.892 [Reporter](INFO): platform_elevator_angle -7.000000 arcdeg
2012-09-11T01:49:49.250Z,1347328189.250 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T01:49:49.250Z,1347328189.250 [ElevatorServo](INFO): Powering down
2012-09-11T01:49:53.988Z,1347328193.988 [NAL9602](INFO): SBD MO Status=0, MOMSN=879, MT Status=0, MTMSN=0
2012-09-11T01:50:08.104Z,1347328208.104 [NAL9602](INFO): SBD MO Status=1, MOMSN=880, MT Status=0, MTMSN=0
2012-09-11T01:50:08.139Z,1347328208.139 [NAL9602](INFO): Sent 317 bytes from file Logs/20120911T005835/shore0011.lzma
2012-09-11T01:50:08.139Z,1347328208.139 [NAL9602](INFO): Packets left to send: 0
2012-09-11T01:50:08.141Z,1347328208.141 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0011.lzma.parts/0000.sbd
2012-09-11T01:50:23.706Z,1347328223.706 [NAL9602](INFO): SBD MO Status=0, MOMSN=881, MT Status=0, MTMSN=0
2012-09-11T01:50:23.785Z,1347328223.786 [Default:Iridium:Read_Iridium] Stopped
2012-09-11T01:50:23.786Z,1347328223.786 [Default:Iridium](INFO): Completed Default:Iridium
2012-09-11T01:50:23.786Z,1347328223.786 [Default:Iridium] Stopped
2012-09-11T01:50:23.786Z,1347328223.786 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-11T01:50:23.794Z,1347328223.795 [Default:Iridium:A.SetSpeed] Stopped
2012-09-11T01:50:23.795Z,1347328223.795 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T01:50:24.172Z,1347328224.172 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-09-11T01:50:24.172Z,1347328224.172 [Default:CallIridium:B] Stopped
2012-09-11T01:50:24.172Z,1347328224.172 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-09-11T01:50:24.172Z,1347328224.172 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-09-11T01:50:24.172Z,1347328224.172 [Default:CallIridium] Stopped
2012-09-11T01:50:24.172Z,1347328224.172 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-09-11T01:50:34.246Z,1347328234.246 [NAL9602](INFO): Powering down
2012-09-11T01:55:24.291Z,1347328524.291 [Default:CallIridium] Running Loop=1
2012-09-11T01:55:24.291Z,1347328524.291 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-11T01:55:24.291Z,1347328524.291 [Default:CallIridium:A] Running Loop=1
2012-09-11T01:55:24.292Z,1347328524.292 [Default:CallIridium:A] Stopped
2012-09-11T01:55:24.292Z,1347328524.292 [Default:CallIridium:B] Running Loop=1
2012-09-11T01:55:24.292Z,1347328524.292 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-11T01:55:29.266Z,1347328529.266 [Default:Iridium] Running Loop=1
2012-09-11T01:55:29.267Z,1347328529.267 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-11T01:55:29.267Z,1347328529.267 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T01:55:29.267Z,1347328529.267 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-11T01:55:29.267Z,1347328529.267 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-11T01:55:29.267Z,1347328529.267 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T01:55:29.268Z,1347328529.268 [Default:Iridium:B.GoToSurface] Stopped
2012-09-11T01:55:29.268Z,1347328529.268 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T01:55:29.268Z,1347328529.268 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-11T01:55:29.268Z,1347328529.268 [Default:GPS] Running Loop=1
2012-09-11T01:55:29.269Z,1347328529.269 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-11T01:55:29.269Z,1347328529.269 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T01:55:29.269Z,1347328529.269 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-11T01:55:29.269Z,1347328529.269 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-11T01:55:29.269Z,1347328529.269 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T01:55:29.270Z,1347328529.270 [Default:GPS:B.GoToSurface] Stopped
2012-09-11T01:55:29.270Z,1347328529.270 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T01:55:29.270Z,1347328529.270 [Default:GPS:Read_GPS] Running Loop=1
2012-09-11T01:55:29.903Z,1347328529.903 [NAL9602](INFO): Powering up
2012-09-11T01:55:40.799Z,1347328540.799 [NAL9602](INFO): NAL9602 initialized
2012-09-11T01:55:57.970Z,1347328557.970 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=882, MT Status=1, MTMSN=96
2012-09-11T01:55:58.003Z,1347328558.003 [NAL9602](INFO): Sent 105 bytes from file Logs/20120911T005835/shore0012.lzma
2012-09-11T01:55:58.003Z,1347328558.003 [NAL9602](INFO): Packets left to send: 0
2012-09-11T01:55:58.005Z,1347328558.005 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0012.lzma.parts/0000.sbd
2012-09-11T01:55:58.667Z,1347328558.667 [NAL9602](INFO): Received command:maintain control VerticalControl.elevatorAngleAction 5 degree;failc n ElevatorServo
2012-09-11T01:55:59.014Z,1347328559.014 [CommandLine](IMPORTANT): got command maintain control VerticalControl.elevatorAngleAction 5.000000 degree
2012-09-11T01:55:59.028Z,1347328559.028 [CommandLine](IMPORTANT): got command failComponent none ElevatorServo
2012-09-11T01:55:59.029Z,1347328559.029 [ElevatorServo] No Fault, FailCount= 4
2012-09-11T01:55:59.029Z,1347328559.029 [CommandLine](IMPORTANT): ElevatorServo failureMode is No Fault
2012-09-11T01:55:59.275Z,1347328559.275 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T01:55:59.396Z,1347328559.396 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T01:55:59.396Z,1347328559.396 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T01:55:59.401Z,1347328559.401 [Reporter](INFO): platform_elevator_angle -0.732999 arcdeg
2012-09-11T01:55:59.667Z,1347328559.667 [Reporter](INFO): platform_elevator_angle 2.324000 arcdeg
2012-09-11T01:56:00.099Z,1347328560.099 [Reporter](INFO): platform_elevator_angle 5.000000 arcdeg
2012-09-11T01:56:02.066Z,1347328562.066 [Reporter](INFO): platform_elevator_angle -0.156389 rad
2012-09-11T01:56:02.544Z,1347328562.544 [Reporter](INFO): platform_elevator_angle -0.158193 rad
2012-09-11T01:56:02.900Z,1347328562.900 [Reporter](INFO): platform_elevator_angle -0.156389 rad
2012-09-11T01:56:03.292Z,1347328563.292 [Reporter](INFO): platform_elevator_angle -0.156351 rad
2012-09-11T01:56:04.083Z,1347328564.083 [ElevatorServo](FAULT): Overload Error
2012-09-11T01:56:04.083Z,1347328564.083 [ElevatorServo] Hardware Fault, FailCount= 5
2012-09-11T01:56:04.083Z,1347328564.083 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T01:56:04.111Z,1347328564.111 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T01:56:04.111Z,1347328564.111 [CBIT](CRITICAL): Hardware Fault in component: ElevatorServo
2012-09-11T01:56:04.113Z,1347328564.113 [Reporter](INFO): platform_elevator_angle 5.000000 arcdeg
2012-09-11T01:56:04.463Z,1347328564.463 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T01:56:04.463Z,1347328564.463 [ElevatorServo](INFO): Powering down
2012-09-11T01:56:15.884Z,1347328575.884 [NAL9602](INFO): SBD MO Status=0, MOMSN=883, MT Status=0, MTMSN=0
2012-09-11T01:56:38.712Z,1347328598.712 [NAL9602](INFO): SBD MO Status=1, MOMSN=884, MT Status=0, MTMSN=0
2012-09-11T01:56:38.747Z,1347328598.747 [NAL9602](INFO): Sent 316 bytes from file Logs/20120911T005835/shore0013.lzma
2012-09-11T01:56:38.747Z,1347328598.747 [NAL9602](INFO): Packets left to send: 0
2012-09-11T01:56:38.749Z,1347328598.749 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0013.lzma.parts/0000.sbd
2012-09-11T01:56:51.912Z,1347328611.912 [NAL9602](INFO): SBD MO Status=0, MOMSN=885, MT Status=0, MTMSN=0
2012-09-11T01:56:51.980Z,1347328611.980 [Default:Iridium:Read_Iridium] Stopped
2012-09-11T01:56:51.981Z,1347328611.981 [Default:Iridium](INFO): Completed Default:Iridium
2012-09-11T01:56:51.981Z,1347328611.981 [Default:Iridium] Stopped
2012-09-11T01:56:51.981Z,1347328611.981 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-11T01:56:51.981Z,1347328611.981 [Default:Iridium:A.SetSpeed] Stopped
2012-09-11T01:56:51.981Z,1347328611.981 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T01:56:52.365Z,1347328612.365 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-09-11T01:56:52.365Z,1347328612.365 [Default:CallIridium:B] Stopped
2012-09-11T01:56:52.365Z,1347328612.365 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-09-11T01:56:52.366Z,1347328612.366 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-09-11T01:56:52.366Z,1347328612.366 [Default:CallIridium] Stopped
2012-09-11T01:56:52.366Z,1347328612.366 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-09-11T01:56:56.314Z,1347328616.314 [NAL9602](IMPORTANT): GPS fix at: 1347328615.00
2012-09-11T01:56:56.367Z,1347328616.367 [Default:GPS:Read_GPS] Stopped
2012-09-11T01:56:56.367Z,1347328616.367 [Default:GPS:D] Running Loop=1
2012-09-11T01:56:56.765Z,1347328616.765 [Default:GPS:D] Stopped
2012-09-11T01:56:56.765Z,1347328616.765 [Default:GPS](INFO): Completed Default:GPS
2012-09-11T01:56:56.765Z,1347328616.765 [Default:GPS] Stopped
2012-09-11T01:56:56.765Z,1347328616.765 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-11T01:56:56.765Z,1347328616.765 [Default:GPS:A.SetSpeed] Stopped
2012-09-11T01:56:56.766Z,1347328616.766 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T01:57:17.294Z,1347328637.294 [NAL9602](INFO): Powering down
2012-09-11T02:01:52.295Z,1347328912.295 [Default:CallIridium] Running Loop=1
2012-09-11T02:01:52.295Z,1347328912.295 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-11T02:01:52.295Z,1347328912.295 [Default:CallIridium:A] Running Loop=1
2012-09-11T02:01:52.295Z,1347328912.295 [Default:CallIridium:A] Stopped
2012-09-11T02:01:52.296Z,1347328912.296 [Default:CallIridium:B] Running Loop=1
2012-09-11T02:01:52.296Z,1347328912.296 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-11T02:01:57.283Z,1347328917.283 [Default:Iridium] Running Loop=1
2012-09-11T02:01:57.283Z,1347328917.283 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-11T02:01:57.283Z,1347328917.283 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T02:01:57.283Z,1347328917.283 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-11T02:01:57.283Z,1347328917.283 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-11T02:01:57.283Z,1347328917.283 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T02:01:57.284Z,1347328917.284 [Default:Iridium:B.GoToSurface] Stopped
2012-09-11T02:01:57.284Z,1347328917.284 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T02:01:57.285Z,1347328917.284 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-11T02:01:57.285Z,1347328917.285 [Default:GPS] Running Loop=1
2012-09-11T02:01:57.285Z,1347328917.285 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-11T02:01:57.285Z,1347328917.285 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T02:01:57.285Z,1347328917.285 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-11T02:01:57.285Z,1347328917.285 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-11T02:01:57.285Z,1347328917.285 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T02:01:57.286Z,1347328917.286 [Default:GPS:B.GoToSurface] Stopped
2012-09-11T02:01:57.286Z,1347328917.286 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T02:01:57.291Z,1347328917.291 [Default:GPS:Read_GPS] Running Loop=1
2012-09-11T02:01:57.906Z,1347328917.906 [NAL9602](INFO): Powering up
2012-09-11T02:02:08.807Z,1347328928.807 [NAL9602](INFO): NAL9602 initialized
2012-09-11T02:02:35.212Z,1347328955.212 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=886, MT Status=1, MTMSN=97
2012-09-11T02:02:35.247Z,1347328955.247 [NAL9602](INFO): Sent 152 bytes from file Logs/20120911T005835/shore0014.lzma
2012-09-11T02:02:35.247Z,1347328955.247 [NAL9602](INFO): Packets left to send: 0
2012-09-11T02:02:35.249Z,1347328955.249 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0014.lzma.parts/0000.sbd
2012-09-11T02:02:35.827Z,1347328955.827 [NAL9602](INFO): Received command:failc n ElevatorServo;get platform_elevator_angle;report clear
2012-09-11T02:02:35.838Z,1347328955.838 [CommandLine](IMPORTANT): got command failComponent none ElevatorServo
2012-09-11T02:02:35.838Z,1347328955.838 [ElevatorServo] No Fault, FailCount= 5
2012-09-11T02:02:35.838Z,1347328955.838 [CommandLine](IMPORTANT): ElevatorServo failureMode is No Fault
2012-09-11T02:02:36.061Z,1347328956.061 [CommandLine](IMPORTANT): got command get platform_elevator_angle
2012-09-11T02:02:36.062Z,1347328956.062 [CommandLine](IMPORTANT): platform_elevator_angle 5.000000 degree
2012-09-11T02:02:36.067Z,1347328956.067 [CommandLine](IMPORTANT): got command report clear
2012-09-11T02:02:36.350Z,1347328956.351 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T02:02:36.472Z,1347328956.472 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T02:02:36.472Z,1347328956.472 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T02:02:41.483Z,1347328961.483 [ElevatorServo](FAULT): Overload Error
2012-09-11T02:02:41.483Z,1347328961.483 [ElevatorServo] Hardware Fault, FailCount= 6
2012-09-11T02:02:41.483Z,1347328961.483 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T02:02:41.511Z,1347328961.511 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T02:02:41.512Z,1347328961.511 [CBIT](CRITICAL): Hardware Fault in component: ElevatorServo
2012-09-11T02:02:41.855Z,1347328961.855 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T02:02:41.855Z,1347328961.855 [ElevatorServo](INFO): Powering down
2012-09-11T02:02:44.998Z,1347328964.998 [NAL9602](INFO): SBD MO Status=0, MOMSN=887, MT Status=0, MTMSN=0
2012-09-11T02:02:59.440Z,1347328979.440 [NAL9602](INFO): SBD MO Status=1, MOMSN=888, MT Status=0, MTMSN=0
2012-09-11T02:02:59.475Z,1347328979.475 [NAL9602](INFO): Sent 326 bytes from file Logs/20120911T005835/shore0015.lzma
2012-09-11T02:02:59.475Z,1347328979.475 [NAL9602](INFO): Packets left to send: 0
2012-09-11T02:02:59.477Z,1347328979.477 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0015.lzma.parts/0000.sbd
2012-09-11T02:03:07.840Z,1347328987.840 [NAL9602](INFO): SBD MO Status=0, MOMSN=889, MT Status=0, MTMSN=0
2012-09-11T02:03:07.913Z,1347328987.913 [Default:Iridium:Read_Iridium] Stopped
2012-09-11T02:03:07.914Z,1347328987.914 [Default:Iridium](INFO): Completed Default:Iridium
2012-09-11T02:03:07.914Z,1347328987.914 [Default:Iridium] Stopped
2012-09-11T02:03:07.914Z,1347328987.914 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-11T02:03:07.914Z,1347328987.914 [Default:Iridium:A.SetSpeed] Stopped
2012-09-11T02:03:07.914Z,1347328987.914 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T02:03:08.292Z,1347328988.292 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-09-11T02:03:08.292Z,1347328988.292 [Default:CallIridium:B] Stopped
2012-09-11T02:03:08.292Z,1347328988.292 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-09-11T02:03:08.292Z,1347328988.292 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-09-11T02:03:08.292Z,1347328988.293 [Default:CallIridium] Stopped
2012-09-11T02:03:08.293Z,1347328988.293 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-09-11T02:03:35.442Z,1347329015.441 [NAL9602](IMPORTANT): GPS fix at: 1347329014.00
2012-09-11T02:03:35.475Z,1347329015.475 [Default:GPS:Read_GPS] Stopped
2012-09-11T02:03:35.475Z,1347329015.475 [Default:GPS:D] Running Loop=1
2012-09-11T02:03:35.868Z,1347329015.868 [Default:GPS:D] Stopped
2012-09-11T02:03:35.869Z,1347329015.869 [Default:GPS](INFO): Completed Default:GPS
2012-09-11T02:03:35.869Z,1347329015.869 [Default:GPS] Stopped
2012-09-11T02:03:35.869Z,1347329015.869 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-11T02:03:35.869Z,1347329015.869 [Default:GPS:A.SetSpeed] Stopped
2012-09-11T02:03:35.869Z,1347329015.869 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T02:03:56.386Z,1347329036.386 [NAL9602](INFO): Powering down
2012-09-11T02:08:11.439Z,1347329291.439 [Default:CallIridium] Running Loop=1
2012-09-11T02:08:11.439Z,1347329291.439 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-11T02:08:11.440Z,1347329291.440 [Default:CallIridium:A] Running Loop=1
2012-09-11T02:08:11.440Z,1347329291.440 [Default:CallIridium:A] Stopped
2012-09-11T02:08:11.440Z,1347329291.440 [Default:CallIridium:B] Running Loop=1
2012-09-11T02:08:11.440Z,1347329291.440 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-11T02:08:16.434Z,1347329296.434 [Default:Iridium] Running Loop=1
2012-09-11T02:08:16.435Z,1347329296.435 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-11T02:08:16.435Z,1347329296.435 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T02:08:16.435Z,1347329296.435 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-11T02:08:16.435Z,1347329296.435 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-11T02:08:16.435Z,1347329296.435 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T02:08:16.436Z,1347329296.436 [Default:Iridium:B.GoToSurface] Stopped
2012-09-11T02:08:16.436Z,1347329296.436 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T02:08:16.436Z,1347329296.436 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-11T02:08:16.436Z,1347329296.436 [Default:GPS] Running Loop=1
2012-09-11T02:08:16.437Z,1347329296.437 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-11T02:08:16.437Z,1347329296.437 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T02:08:16.437Z,1347329296.437 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-11T02:08:16.437Z,1347329296.437 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-11T02:08:16.437Z,1347329296.437 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T02:08:16.438Z,1347329296.438 [Default:GPS:B.GoToSurface] Stopped
2012-09-11T02:08:16.438Z,1347329296.438 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T02:08:16.438Z,1347329296.438 [Default:GPS:Read_GPS] Running Loop=1
2012-09-11T02:08:17.026Z,1347329297.026 [NAL9602](INFO): Powering up
2012-09-11T02:08:27.635Z,1347329307.635 [NAL9602](INFO): NAL9602 initialized
2012-09-11T02:09:09.968Z,1347329349.968 [NAL9602](INFO): SBD MO Status=2, MOMSN=890, MT Status=2, MTMSN=0
2012-09-11T02:09:09.968Z,1347329349.968 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T02:09:30.108Z,1347329370.108 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=890, MT Status=1, MTMSN=99
2012-09-11T02:09:30.143Z,1347329370.143 [NAL9602](INFO): Sent 153 bytes from file Logs/20120911T005835/shore0016.lzma
2012-09-11T02:09:30.143Z,1347329370.143 [NAL9602](INFO): Packets left to send: 0
2012-09-11T02:09:30.145Z,1347329370.145 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0016.lzma.parts/0000.sbd
2012-09-11T02:09:30.720Z,1347329370.720 [NAL9602](INFO): Received command:get platform_elevator_angle
2012-09-11T02:09:30.935Z,1347329370.935 [CommandLine](IMPORTANT): got command get platform_elevator_angle
2012-09-11T02:09:30.936Z,1347329370.936 [CommandLine](IMPORTANT): platform_elevator_angle 5.000000 degree
2012-09-11T02:09:40.206Z,1347329380.207 [NAL9602](IMPORTANT): SBD MO Status=0, MOMSN=891, MT Status=1, MTMSN=98
2012-09-11T02:09:40.720Z,1347329380.720 [NAL9602](INFO): Received command:failc n ElevatorServo
2012-09-11T02:09:40.735Z,1347329380.735 [CommandLine](IMPORTANT): got command failComponent none ElevatorServo
2012-09-11T02:09:40.735Z,1347329380.735 [ElevatorServo] No Fault, FailCount= 6
2012-09-11T02:09:40.735Z,1347329380.735 [CommandLine](IMPORTANT): ElevatorServo failureMode is No Fault
2012-09-11T02:09:41.038Z,1347329381.038 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T02:09:41.164Z,1347329381.164 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T02:09:41.164Z,1347329381.164 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T02:09:45.783Z,1347329385.783 [ElevatorServo](FAULT): Overload Error
2012-09-11T02:09:45.783Z,1347329385.783 [ElevatorServo] Hardware Fault, FailCount= 7
2012-09-11T02:09:45.783Z,1347329385.783 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T02:09:45.810Z,1347329385.810 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T02:09:45.811Z,1347329385.811 [CBIT](CRITICAL): Hardware Fault in component: ElevatorServo
2012-09-11T02:09:46.157Z,1347329386.158 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T02:09:46.158Z,1347329386.158 [ElevatorServo](INFO): Powering down
2012-09-11T02:09:50.092Z,1347329390.092 [NAL9602](INFO): SBD MO Status=0, MOMSN=892, MT Status=0, MTMSN=0
2012-09-11T02:10:15.040Z,1347329415.040 [NAL9602](INFO): SBD MO Status=2, MOMSN=893, MT Status=2, MTMSN=0
2012-09-11T02:10:15.040Z,1347329415.040 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T02:10:40.648Z,1347329440.648 [NAL9602](INFO): SBD MO Status=1, MOMSN=893, MT Status=0, MTMSN=0
2012-09-11T02:10:40.683Z,1347329440.683 [NAL9602](INFO): Sent 326 bytes from file Logs/20120911T005835/shore0017.lzma
2012-09-11T02:10:40.683Z,1347329440.683 [NAL9602](INFO): Packets left to send: 0
2012-09-11T02:10:40.685Z,1347329440.685 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0017.lzma.parts/0000.sbd
2012-09-11T02:10:51.448Z,1347329451.448 [NAL9602](INFO): SBD MO Status=0, MOMSN=894, MT Status=0, MTMSN=0
2012-09-11T02:10:51.521Z,1347329451.521 [Default:Iridium:Read_Iridium] Stopped
2012-09-11T02:10:51.521Z,1347329451.521 [Default:Iridium](INFO): Completed Default:Iridium
2012-09-11T02:10:51.521Z,1347329451.522 [Default:Iridium] Stopped
2012-09-11T02:10:51.522Z,1347329451.522 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-11T02:10:51.522Z,1347329451.522 [Default:Iridium:A.SetSpeed] Stopped
2012-09-11T02:10:51.522Z,1347329451.522 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T02:10:51.904Z,1347329451.904 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-09-11T02:10:51.904Z,1347329451.904 [Default:CallIridium:B] Stopped
2012-09-11T02:10:51.904Z,1347329451.904 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-09-11T02:10:51.904Z,1347329451.904 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-09-11T02:10:51.904Z,1347329451.904 [Default:CallIridium] Stopped
2012-09-11T02:10:51.904Z,1347329451.904 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-09-11T02:10:52.649Z,1347329452.649 [NAL9602](IMPORTANT): GPS fix at: 1347329452.00
2012-09-11T02:10:52.679Z,1347329452.679 [Default:GPS:Read_GPS] Stopped
2012-09-11T02:10:52.679Z,1347329452.679 [Default:GPS:D] Running Loop=1
2012-09-11T02:10:53.075Z,1347329453.076 [Default:GPS:D] Stopped
2012-09-11T02:10:53.076Z,1347329453.076 [Default:GPS](INFO): Completed Default:GPS
2012-09-11T02:10:53.076Z,1347329453.076 [Default:GPS] Stopped
2012-09-11T02:10:53.076Z,1347329453.076 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-11T02:10:53.076Z,1347329453.076 [Default:GPS:A.SetSpeed] Stopped
2012-09-11T02:10:53.076Z,1347329453.076 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T02:11:13.571Z,1347329473.571 [NAL9602](INFO): Powering down
2012-09-11T02:15:53.679Z,1347329753.679 [Default:CallIridium] Running Loop=1
2012-09-11T02:15:53.679Z,1347329753.680 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-11T02:15:53.680Z,1347329753.680 [Default:CallIridium:A] Running Loop=1
2012-09-11T02:15:53.680Z,1347329753.680 [Default:CallIridium:A] Stopped
2012-09-11T02:15:53.680Z,1347329753.680 [Default:CallIridium:B] Running Loop=1
2012-09-11T02:15:53.680Z,1347329753.680 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-11T02:15:58.607Z,1347329758.607 [Default:Iridium] Running Loop=1
2012-09-11T02:15:58.607Z,1347329758.607 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-11T02:15:58.607Z,1347329758.607 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T02:15:58.607Z,1347329758.607 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-11T02:15:58.607Z,1347329758.607 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-11T02:15:58.608Z,1347329758.608 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T02:15:58.608Z,1347329758.608 [Default:Iridium:B.GoToSurface] Stopped
2012-09-11T02:15:58.608Z,1347329758.608 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T02:15:58.609Z,1347329758.609 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-11T02:15:58.609Z,1347329758.609 [Default:GPS] Running Loop=1
2012-09-11T02:15:58.609Z,1347329758.609 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-11T02:15:58.609Z,1347329758.609 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T02:15:58.609Z,1347329758.609 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-11T02:15:58.609Z,1347329758.609 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-11T02:15:58.609Z,1347329758.609 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T02:15:58.610Z,1347329758.610 [Default:GPS:B.GoToSurface] Stopped
2012-09-11T02:15:58.614Z,1347329758.614 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T02:15:58.615Z,1347329758.615 [Default:GPS:Read_GPS] Running Loop=1
2012-09-11T02:15:59.240Z,1347329759.240 [NAL9602](INFO): Powering up
2012-09-11T02:16:10.307Z,1347329770.307 [NAL9602](INFO): NAL9602 initialized
2012-09-11T02:16:38.570Z,1347329798.570 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=895, MT Status=1, MTMSN=100
2012-09-11T02:16:38.603Z,1347329798.603 [NAL9602](INFO): Sent 151 bytes from file Logs/20120911T005835/shore0018.lzma
2012-09-11T02:16:38.603Z,1347329798.603 [NAL9602](INFO): Packets left to send: 0
2012-09-11T02:16:38.605Z,1347329798.605 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0018.lzma.parts/0000.sbd
2012-09-11T02:16:39.199Z,1347329799.200 [NAL9602](INFO): Received command:maintain control VerticalControl.elevatorAngleAction 0 degree;failc n ElevatorServo
2012-09-11T02:16:39.544Z,1347329799.544 [CommandLine](IMPORTANT): got command maintain control VerticalControl.elevatorAngleAction 0.000000 degree
2012-09-11T02:16:39.554Z,1347329799.554 [CommandLine](IMPORTANT): got command failComponent none ElevatorServo
2012-09-11T02:16:39.555Z,1347329799.555 [ElevatorServo] No Fault, FailCount= 7
2012-09-11T02:16:39.555Z,1347329799.555 [CommandLine](IMPORTANT): ElevatorServo failureMode is No Fault
2012-09-11T02:16:39.827Z,1347329799.827 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T02:16:39.948Z,1347329799.948 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T02:16:39.948Z,1347329799.948 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T02:16:40.550Z,1347329800.550 [NAL9602](IMPORTANT): GPS fix at: 1347329800.00
2012-09-11T02:16:40.607Z,1347329800.607 [Default:GPS:Read_GPS] Stopped
2012-09-11T02:16:40.607Z,1347329800.607 [Default:GPS:D] Running Loop=1
2012-09-11T02:16:40.985Z,1347329800.985 [Default:GPS:D] Stopped
2012-09-11T02:16:40.985Z,1347329800.985 [Default:GPS](INFO): Completed Default:GPS
2012-09-11T02:16:40.985Z,1347329800.985 [Default:GPS] Stopped
2012-09-11T02:16:40.985Z,1347329800.985 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-11T02:16:40.985Z,1347329800.985 [Default:GPS:A.SetSpeed] Stopped
2012-09-11T02:16:40.985Z,1347329800.986 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T02:16:44.899Z,1347329804.899 [ElevatorServo](FAULT): Overload Error
2012-09-11T02:16:44.899Z,1347329804.899 [ElevatorServo] Hardware Fault, FailCount= 8
2012-09-11T02:16:44.899Z,1347329804.899 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T02:16:44.926Z,1347329804.926 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T02:16:44.927Z,1347329804.927 [CBIT](CRITICAL): Hardware Fault in component: ElevatorServo
2012-09-11T02:16:45.278Z,1347329805.278 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T02:16:45.278Z,1347329805.278 [ElevatorServo](INFO): Powering down
2012-09-11T02:16:55.640Z,1347329815.640 [NAL9602](IMPORTANT): SBD MO Status=0, MOMSN=896, MT Status=1, MTMSN=101
2012-09-11T02:16:56.260Z,1347329816.260 [NAL9602](INFO): Received command:get platform_elevator_angle
2012-09-11T02:16:56.487Z,1347329816.487 [CommandLine](IMPORTANT): got command get platform_elevator_angle
2012-09-11T02:16:56.487Z,1347329816.487 [CommandLine](IMPORTANT): platform_elevator_angle 0.000000 degree
2012-09-11T02:17:34.547Z,1347329854.547 [NAL9602](IMPORTANT): SBD MO Status=0, MOMSN=897, MT Status=1, MTMSN=102
2012-09-11T02:17:35.020Z,1347329855.020 [NAL9602](INFO): Received command:get ElevatorServo.elevator_angle
2012-09-11T02:17:35.448Z,1347329855.448 [CommandLine](IMPORTANT): got command get 
2012-09-11T02:17:35.449Z,1347329855.448 [CommandLine](FAULT): Incomplete syntax. Try: help get
2012-09-11T02:17:39.612Z,1347329859.612 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:17:49.416Z,1347329869.416 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:17:53.785Z,1347329873.784 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:17:58.008Z,1347329878.008 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:18:02.272Z,1347329882.272 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:18:06.536Z,1347329886.536 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:18:08.800Z,1347329888.800 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:18:13.068Z,1347329893.068 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:18:15.319Z,1347329895.319 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:18:24.292Z,1347329904.292 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:18:46.888Z,1347329926.888 [NAL9602](INFO): SBD MO Status=2, MOMSN=898, MT Status=2, MTMSN=0
2012-09-11T02:18:46.888Z,1347329926.888 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T02:18:58.396Z,1347329938.396 [NAL9602](IMPORTANT): SBD MO Status=0, MOMSN=898, MT Status=1, MTMSN=103
2012-09-11T02:18:58.903Z,1347329938.903 [NAL9602](INFO): Received command:show best platform_elevator_angle
2012-09-11T02:18:59.024Z,1347329939.024 [CommandLine](IMPORTANT): got command show best platform_elevator_angle
2012-09-11T02:18:59.024Z,1347329939.024 [CommandLine](IMPORTANT): platform_elevator_angle best is InternalSim.platform_elevator_angle
2012-09-11T02:19:06.716Z,1347329946.716 [NAL9602](INFO): SBD MO Status=0, MOMSN=899, MT Status=0, MTMSN=0
2012-09-11T02:19:20.000Z,1347329960.000 [NAL9602](INFO): SBD MO Status=1, MOMSN=900, MT Status=0, MTMSN=0
2012-09-11T02:19:20.035Z,1347329960.035 [NAL9602](INFO): Sent 332 bytes from file Logs/20120911T005835/shore0019.lzma
2012-09-11T02:19:20.035Z,1347329960.035 [NAL9602](INFO): Packets left to send: 1
2012-09-11T02:19:20.037Z,1347329960.037 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0019.lzma.parts/0001.sbd
2012-09-11T02:19:28.928Z,1347329968.928 [NAL9602](INFO): SBD MO Status=1, MOMSN=901, MT Status=0, MTMSN=0
2012-09-11T02:19:28.963Z,1347329968.963 [NAL9602](INFO): Sent 178 bytes from file Logs/20120911T005835/shore0019.lzma
2012-09-11T02:19:28.963Z,1347329968.963 [NAL9602](INFO): Packets left to send: 0
2012-09-11T02:19:28.964Z,1347329968.964 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0019.lzma.parts/0000.sbd
2012-09-11T02:19:32.528Z,1347329972.528 [NAL9602](INFO): SBD MO Status=0, MOMSN=902, MT Status=0, MTMSN=0
2012-09-11T02:19:32.605Z,1347329972.605 [Default:Iridium:Read_Iridium] Stopped
2012-09-11T02:19:32.605Z,1347329972.605 [Default:Iridium](INFO): Completed Default:Iridium
2012-09-11T02:19:32.605Z,1347329972.605 [Default:Iridium] Stopped
2012-09-11T02:19:32.605Z,1347329972.605 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-11T02:19:32.605Z,1347329972.605 [Default:Iridium:A.SetSpeed] Stopped
2012-09-11T02:19:32.606Z,1347329972.606 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T02:19:32.975Z,1347329972.975 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-09-11T02:19:32.975Z,1347329972.975 [Default:CallIridium:B] Stopped
2012-09-11T02:19:32.975Z,1347329972.975 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-09-11T02:19:32.975Z,1347329972.975 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-09-11T02:19:32.975Z,1347329972.975 [Default:CallIridium] Stopped
2012-09-11T02:19:32.975Z,1347329972.976 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-09-11T02:19:43.079Z,1347329983.079 [NAL9602](INFO): Powering down
2012-09-11T02:24:33.094Z,1347330273.095 [Default:CallIridium] Running Loop=1
2012-09-11T02:24:33.095Z,1347330273.095 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-11T02:24:33.095Z,1347330273.095 [Default:CallIridium:A] Running Loop=1
2012-09-11T02:24:33.095Z,1347330273.095 [Default:CallIridium:A] Stopped
2012-09-11T02:24:33.095Z,1347330273.095 [Default:CallIridium:B] Running Loop=1
2012-09-11T02:24:33.095Z,1347330273.095 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-11T02:24:38.104Z,1347330278.104 [Default:Iridium] Running Loop=1
2012-09-11T02:24:38.104Z,1347330278.104 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-11T02:24:38.104Z,1347330278.104 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T02:24:38.104Z,1347330278.104 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-11T02:24:38.104Z,1347330278.104 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-11T02:24:38.104Z,1347330278.104 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T02:24:38.105Z,1347330278.105 [Default:Iridium:B.GoToSurface] Stopped
2012-09-11T02:24:38.105Z,1347330278.105 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T02:24:38.105Z,1347330278.105 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-11T02:24:38.106Z,1347330278.106 [Default:GPS] Running Loop=1
2012-09-11T02:24:38.106Z,1347330278.106 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-11T02:24:38.106Z,1347330278.106 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T02:24:38.106Z,1347330278.106 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-11T02:24:38.106Z,1347330278.106 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-11T02:24:38.110Z,1347330278.110 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T02:24:38.111Z,1347330278.111 [Default:GPS:B.GoToSurface] Stopped
2012-09-11T02:24:38.111Z,1347330278.111 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T02:24:38.112Z,1347330278.112 [Default:GPS:Read_GPS] Running Loop=1
2012-09-11T02:24:38.722Z,1347330278.722 [NAL9602](INFO): Powering up
2012-09-11T02:24:49.691Z,1347330289.691 [NAL9602](INFO): NAL9602 initialized
2012-09-11T02:25:09.556Z,1347330309.556 [NAL9602](INFO): SBD MO Status=1, MOMSN=903, MT Status=0, MTMSN=0
2012-09-11T02:25:09.607Z,1347330309.607 [NAL9602](INFO): Sent 107 bytes from file Logs/20120911T005835/shore0020.lzma
2012-09-11T02:25:09.607Z,1347330309.607 [NAL9602](INFO): Packets left to send: 0
2012-09-11T02:25:09.609Z,1347330309.609 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0020.lzma.parts/0000.sbd
2012-09-11T02:25:17.144Z,1347330317.144 [NAL9602](INFO): SBD MO Status=0, MOMSN=904, MT Status=0, MTMSN=0
2012-09-11T02:25:17.238Z,1347330317.238 [Default:Iridium:Read_Iridium] Stopped
2012-09-11T02:25:17.247Z,1347330317.247 [Default:Iridium](INFO): Completed Default:Iridium
2012-09-11T02:25:17.247Z,1347330317.247 [Default:Iridium] Stopped
2012-09-11T02:25:17.247Z,1347330317.247 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-11T02:25:17.247Z,1347330317.247 [Default:Iridium:A.SetSpeed] Stopped
2012-09-11T02:25:17.247Z,1347330317.247 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T02:25:17.603Z,1347330317.603 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-09-11T02:25:17.603Z,1347330317.603 [Default:CallIridium:B] Stopped
2012-09-11T02:25:17.603Z,1347330317.603 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-09-11T02:25:17.603Z,1347330317.603 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-09-11T02:25:17.603Z,1347330317.603 [Default:CallIridium] Stopped
2012-09-11T02:25:17.603Z,1347330317.603 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-09-11T02:25:24.346Z,1347330324.346 [NAL9602](IMPORTANT): GPS fix at: 1347330325.00
2012-09-11T02:25:24.379Z,1347330324.379 [Default:GPS:Read_GPS] Stopped
2012-09-11T02:25:24.379Z,1347330324.379 [Default:GPS:D] Running Loop=1
2012-09-11T02:25:24.776Z,1347330324.776 [Default:GPS:D] Stopped
2012-09-11T02:25:24.776Z,1347330324.776 [Default:GPS](INFO): Completed Default:GPS
2012-09-11T02:25:24.776Z,1347330324.776 [Default:GPS] Stopped
2012-09-11T02:25:24.776Z,1347330324.776 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-11T02:25:24.777Z,1347330324.777 [Default:GPS:A.SetSpeed] Stopped
2012-09-11T02:25:24.777Z,1347330324.777 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T02:25:45.323Z,1347330345.323 [NAL9602](INFO): Powering down
2012-09-11T02:30:20.347Z,1347330620.347 [Default:CallIridium] Running Loop=1
2012-09-11T02:30:20.347Z,1347330620.347 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-11T02:30:20.347Z,1347330620.347 [Default:CallIridium:A] Running Loop=1
2012-09-11T02:30:20.348Z,1347330620.348 [Default:CallIridium:A] Stopped
2012-09-11T02:30:20.348Z,1347330620.348 [Default:CallIridium:B] Running Loop=1
2012-09-11T02:30:20.348Z,1347330620.348 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-11T02:30:25.315Z,1347330625.316 [Default:Iridium] Running Loop=1
2012-09-11T02:30:25.316Z,1347330625.316 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-11T02:30:25.316Z,1347330625.316 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T02:30:25.316Z,1347330625.316 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-11T02:30:25.316Z,1347330625.316 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-11T02:30:25.316Z,1347330625.316 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T02:30:25.317Z,1347330625.317 [Default:Iridium:B.GoToSurface] Stopped
2012-09-11T02:30:25.317Z,1347330625.317 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T02:30:25.317Z,1347330625.317 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-11T02:30:25.317Z,1347330625.318 [Default:GPS] Running Loop=1
2012-09-11T02:30:25.318Z,1347330625.318 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-11T02:30:25.318Z,1347330625.318 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T02:30:25.318Z,1347330625.318 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-11T02:30:25.318Z,1347330625.318 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-11T02:30:25.318Z,1347330625.318 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T02:30:25.323Z,1347330625.323 [Default:GPS:B.GoToSurface] Stopped
2012-09-11T02:30:25.323Z,1347330625.323 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T02:30:25.323Z,1347330625.323 [Default:GPS:Read_GPS] Running Loop=1
2012-09-11T02:30:25.954Z,1347330625.954 [NAL9602](INFO): Powering up
2012-09-11T02:30:36.899Z,1347330636.899 [NAL9602](INFO): NAL9602 initialized
2012-09-11T02:30:57.604Z,1347330657.604 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=905, MT Status=1, MTMSN=104
2012-09-11T02:30:57.639Z,1347330657.639 [NAL9602](INFO): Sent 156 bytes from file Logs/20120911T005835/shore0021.lzma
2012-09-11T02:30:57.639Z,1347330657.639 [NAL9602](INFO): Packets left to send: 0
2012-09-11T02:30:57.641Z,1347330657.641 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0021.lzma.parts/0000.sbd
2012-09-11T02:30:58.156Z,1347330658.156 [NAL9602](INFO): Received command:gfscan
2012-09-11T02:30:58.227Z,1347330658.227 [CommandLine](IMPORTANT): got command gfscan
2012-09-11T02:30:58.452Z,1347330658.452 [CBIT](IMPORTANT): Beginning GF scan
2012-09-11T02:31:02.724Z,1347330662.724 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:31:24.604Z,1347330684.604 [CBIT](INFO): No ground fault detected
2012-09-11T02:31:29.740Z,1347330689.740 [NAL9602](INFO): SBD MO Status=2, MOMSN=906, MT Status=2, MTMSN=0
2012-09-11T02:31:29.740Z,1347330689.740 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T02:31:45.253Z,1347330705.253 [CBIT](INFO): Clearing failed count for component ElevatorServo
2012-09-11T02:31:45.253Z,1347330705.253 [ElevatorServo] No Fault, FailCount= 8
2012-09-11T02:31:46.059Z,1347330706.059 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T02:31:46.180Z,1347330706.180 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T02:31:46.180Z,1347330706.180 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T02:31:47.208Z,1347330707.208 [NAL9602](INFO): SBD MO Status=2, MOMSN=906, MT Status=2, MTMSN=0
2012-09-11T02:31:47.208Z,1347330707.208 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T02:31:50.883Z,1347330710.883 [ElevatorServo](FAULT): Overload Error
2012-09-11T02:31:50.883Z,1347330710.883 [ElevatorServo] Hardware Fault, FailCount= 1
2012-09-11T02:31:50.883Z,1347330710.883 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T02:31:50.910Z,1347330710.910 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T02:31:51.250Z,1347330711.250 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T02:31:51.255Z,1347330711.255 [ElevatorServo](INFO): Powering down
2012-09-11T02:31:51.263Z,1347330711.263 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-09-11T02:31:51.263Z,1347330711.263 [ElevatorServo] No Fault, FailCount= 1
2012-09-11T02:31:52.376Z,1347330712.376 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T02:31:52.496Z,1347330712.496 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T02:31:52.496Z,1347330712.496 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T02:31:57.159Z,1347330717.159 [ElevatorServo](FAULT): Overload Error
2012-09-11T02:31:57.159Z,1347330717.159 [ElevatorServo] Hardware Fault, FailCount= 2
2012-09-11T02:31:57.159Z,1347330717.159 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T02:31:57.186Z,1347330717.186 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T02:31:57.539Z,1347330717.539 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T02:31:57.539Z,1347330717.539 [ElevatorServo](INFO): Powering down
2012-09-11T02:31:57.543Z,1347330717.543 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-09-11T02:31:57.544Z,1347330717.543 [ElevatorServo] No Fault, FailCount= 2
2012-09-11T02:31:58.360Z,1347330718.360 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T02:31:58.480Z,1347330718.480 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T02:31:58.480Z,1347330718.480 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T02:32:03.151Z,1347330723.151 [ElevatorServo](FAULT): Overload Error
2012-09-11T02:32:03.151Z,1347330723.151 [ElevatorServo] Hardware Fault, FailCount= 3
2012-09-11T02:32:03.151Z,1347330723.151 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T02:32:03.178Z,1347330723.178 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T02:32:03.179Z,1347330723.179 [CBIT](CRITICAL): Hardware Fault in component: ElevatorServo
2012-09-11T02:32:03.492Z,1347330723.492 [NAL9602](INFO): SBD MO Status=2, MOMSN=906, MT Status=2, MTMSN=0
2012-09-11T02:32:03.492Z,1347330723.492 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T02:32:03.547Z,1347330723.546 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T02:32:03.547Z,1347330723.547 [ElevatorServo](INFO): Powering down
2012-09-11T02:32:04.682Z,1347330724.682 [NAL9602](IMPORTANT): GPS fix at: 1347330725.00
2012-09-11T02:32:04.731Z,1347330724.731 [Default:GPS:Read_GPS] Stopped
2012-09-11T02:32:04.731Z,1347330724.731 [Default:GPS:D] Running Loop=1
2012-09-11T02:32:05.108Z,1347330725.109 [Default:GPS:D] Stopped
2012-09-11T02:32:05.109Z,1347330725.109 [Default:GPS](INFO): Completed Default:GPS
2012-09-11T02:32:05.109Z,1347330725.109 [Default:GPS] Stopped
2012-09-11T02:32:05.109Z,1347330725.109 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-11T02:32:05.109Z,1347330725.109 [Default:GPS:A.SetSpeed] Stopped
2012-09-11T02:32:05.109Z,1347330725.109 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T02:32:08.560Z,1347330728.560 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:32:11.620Z,1347330731.620 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:32:31.496Z,1347330751.496 [NAL9602](INFO): SBD MO Status=2, MOMSN=906, MT Status=2, MTMSN=0
2012-09-11T02:32:31.496Z,1347330751.496 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T02:32:46.192Z,1347330766.192 [NAL9602](INFO): SBD MO Status=2, MOMSN=906, MT Status=2, MTMSN=0
2012-09-11T02:32:46.192Z,1347330766.192 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T02:32:51.284Z,1347330771.284 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:32:53.562Z,1347330773.562 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:32:57.812Z,1347330777.812 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:33:01.280Z,1347330781.280 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:33:03.547Z,1347330783.547 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:33:18.968Z,1347330798.968 [NAL9602](INFO): SBD MO Status=2, MOMSN=906, MT Status=2, MTMSN=0
2012-09-11T02:33:18.968Z,1347330798.968 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T02:33:24.144Z,1347330804.144 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:33:26.360Z,1347330806.360 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:33:30.632Z,1347330810.632 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:33:35.772Z,1347330815.772 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:33:38.005Z,1347330818.005 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:33:42.264Z,1347330822.264 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:33:44.512Z,1347330824.513 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:33:48.796Z,1347330828.796 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:33:51.020Z,1347330831.020 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:33:55.312Z,1347330835.312 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:33:57.584Z,1347330837.584 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:34:08.996Z,1347330848.996 [NAL9602](INFO): SBD MO Status=2, MOMSN=906, MT Status=2, MTMSN=0
2012-09-11T02:34:08.997Z,1347330848.997 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T02:34:13.724Z,1347330853.724 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:34:16.365Z,1347330856.365 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:34:18.616Z,1347330858.616 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:34:22.893Z,1347330862.893 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:34:25.128Z,1347330865.128 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:34:29.424Z,1347330869.424 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:34:31.708Z,1347330871.708 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:34:36.008Z,1347330876.008 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:34:38.281Z,1347330878.281 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:34:42.555Z,1347330882.555 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:34:44.803Z,1347330884.803 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:34:49.060Z,1347330889.060 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:34:51.312Z,1347330891.312 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:34:55.600Z,1347330895.600 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:34:57.848Z,1347330897.848 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:35:02.098Z,1347330902.098 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:35:04.376Z,1347330904.376 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:35:08.648Z,1347330908.648 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:35:10.879Z,1347330910.879 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:35:15.140Z,1347330915.140 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:35:23.789Z,1347330923.789 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:35:28.052Z,1347330928.052 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:35:32.332Z,1347330932.332 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:35:34.596Z,1347330934.596 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:35:38.917Z,1347330938.917 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:35:41.198Z,1347330941.198 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:35:45.454Z,1347330945.454 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:35:47.728Z,1347330947.728 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:35:52.012Z,1347330952.012 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:35:54.276Z,1347330954.276 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:35:58.554Z,1347330958.555 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:00.796Z,1347330960.796 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:05.156Z,1347330965.156 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:07.390Z,1347330967.390 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:11.649Z,1347330971.649 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:13.892Z,1347330973.892 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:18.188Z,1347330978.188 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:20.448Z,1347330980.448 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:24.701Z,1347330984.701 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:26.968Z,1347330986.968 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:31.252Z,1347330991.252 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:33.547Z,1347330993.547 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:37.776Z,1347330997.776 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:40.044Z,1347331000.044 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:44.316Z,1347331004.316 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:46.588Z,1347331006.588 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:50.830Z,1347331010.830 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:53.136Z,1347331013.136 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:57.544Z,1347331017.544 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:36:59.704Z,1347331019.704 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:37:03.976Z,1347331023.976 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:37:06.268Z,1347331026.268 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:37:10.535Z,1347331030.535 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:37:12.769Z,1347331032.769 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:37:17.064Z,1347331037.064 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:37:19.260Z,1347331039.260 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:37:23.535Z,1347331043.535 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:37:25.796Z,1347331045.796 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:37:30.068Z,1347331050.068 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:37:32.308Z,1347331052.308 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:37:36.548Z,1347331056.548 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:37:38.776Z,1347331058.776 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:37:43.045Z,1347331063.045 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:37:45.312Z,1347331065.312 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:37:49.600Z,1347331069.601 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:37:51.804Z,1347331071.804 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:37:56.096Z,1347331076.096 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:38:03.152Z,1347331083.152 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:38:23.808Z,1347331103.808 [NAL9602](INFO): SBD MO Status=2, MOMSN=906, MT Status=2, MTMSN=0
2012-09-11T02:38:23.808Z,1347331103.808 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T02:38:28.916Z,1347331108.916 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:38:39.669Z,1347331119.669 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:39:02.232Z,1347331142.232 [NAL9602](INFO): SBD MO Status=2, MOMSN=906, MT Status=2, MTMSN=0
2012-09-11T02:39:02.233Z,1347331142.233 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T02:39:09.700Z,1347331149.700 [NAL9602](INFO): SBD MO Status=2, MOMSN=906, MT Status=2, MTMSN=0
2012-09-11T02:39:09.700Z,1347331149.700 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T02:39:14.440Z,1347331154.440 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:39:18.292Z,1347331158.292 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2012-09-11T02:39:29.328Z,1347331169.328 [NAL9602](INFO): SBD MO Status=2, MOMSN=906, MT Status=2, MTMSN=0
2012-09-11T02:39:29.328Z,1347331169.328 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T02:39:37.984Z,1347331177.984 [NAL9602](INFO): SBD MO Status=2, MOMSN=906, MT Status=2, MTMSN=0
2012-09-11T02:39:37.985Z,1347331177.985 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T02:39:49.052Z,1347331189.052 [NAL9602](INFO): SBD MO Status=0, MOMSN=906, MT Status=0, MTMSN=0
2012-09-11T02:40:10.364Z,1347331210.364 [NAL9602](INFO): SBD MO Status=1, MOMSN=907, MT Status=0, MTMSN=0
2012-09-11T02:40:10.399Z,1347331210.399 [NAL9602](INFO): Sent 314 bytes from file Logs/20120911T005835/shore0022.lzma
2012-09-11T02:40:10.399Z,1347331210.399 [NAL9602](INFO): Packets left to send: 0
2012-09-11T02:40:10.401Z,1347331210.401 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0022.lzma.parts/0000.sbd
2012-09-11T02:40:21.172Z,1347331221.172 [NAL9602](INFO): SBD MO Status=0, MOMSN=908, MT Status=0, MTMSN=0
2012-09-11T02:40:21.245Z,1347331221.245 [Default:Iridium:Read_Iridium] Stopped
2012-09-11T02:40:21.245Z,1347331221.246 [Default:Iridium](INFO): Completed Default:Iridium
2012-09-11T02:40:21.246Z,1347331221.246 [Default:Iridium] Stopped
2012-09-11T02:40:21.246Z,1347331221.246 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-11T02:40:21.246Z,1347331221.246 [Default:Iridium:A.SetSpeed] Stopped
2012-09-11T02:40:21.246Z,1347331221.246 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T02:40:21.623Z,1347331221.623 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-09-11T02:40:21.623Z,1347331221.623 [Default:CallIridium:B] Stopped
2012-09-11T02:40:21.623Z,1347331221.623 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-09-11T02:40:21.623Z,1347331221.623 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-09-11T02:40:21.623Z,1347331221.623 [Default:CallIridium] Stopped
2012-09-11T02:40:21.623Z,1347331221.623 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-09-11T02:40:31.710Z,1347331231.710 [NAL9602](INFO): Powering down
2012-09-11T02:45:21.759Z,1347331521.759 [Default:CallIridium] Running Loop=1
2012-09-11T02:45:21.759Z,1347331521.759 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-11T02:45:21.760Z,1347331521.760 [Default:CallIridium:A] Running Loop=1
2012-09-11T02:45:21.760Z,1347331521.760 [Default:CallIridium:A] Stopped
2012-09-11T02:45:21.760Z,1347331521.760 [Default:CallIridium:B] Running Loop=1
2012-09-11T02:45:21.760Z,1347331521.760 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-11T02:45:26.738Z,1347331526.738 [Default:Iridium] Running Loop=1
2012-09-11T02:45:26.739Z,1347331526.739 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-11T02:45:26.739Z,1347331526.739 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T02:45:26.739Z,1347331526.739 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-11T02:45:26.739Z,1347331526.739 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-11T02:45:26.739Z,1347331526.739 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T02:45:26.740Z,1347331526.740 [Default:Iridium:B.GoToSurface] Stopped
2012-09-11T02:45:26.740Z,1347331526.740 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T02:45:26.740Z,1347331526.740 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-11T02:45:26.740Z,1347331526.740 [Default:GPS] Running Loop=1
2012-09-11T02:45:26.741Z,1347331526.741 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-11T02:45:26.741Z,1347331526.741 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T02:45:26.741Z,1347331526.741 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-11T02:45:26.741Z,1347331526.741 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-11T02:45:26.741Z,1347331526.741 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T02:45:26.742Z,1347331526.742 [Default:GPS:B.GoToSurface] Stopped
2012-09-11T02:45:26.742Z,1347331526.742 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T02:45:26.742Z,1347331526.742 [Default:GPS:Read_GPS] Running Loop=1
2012-09-11T02:45:27.370Z,1347331527.371 [NAL9602](INFO): Powering up
2012-09-11T02:45:38.375Z,1347331538.375 [NAL9602](INFO): NAL9602 initialized
2012-09-11T02:45:57.388Z,1347331557.388 [NAL9602](INFO): SBD MO Status=1, MOMSN=909, MT Status=0, MTMSN=0
2012-09-11T02:45:57.423Z,1347331557.423 [NAL9602](INFO): Sent 107 bytes from file Logs/20120911T005835/shore0023.lzma
2012-09-11T02:45:57.423Z,1347331557.423 [NAL9602](INFO): Packets left to send: 0
2012-09-11T02:45:57.425Z,1347331557.425 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0023.lzma.parts/0000.sbd
2012-09-11T02:46:07.392Z,1347331567.392 [NAL9602](INFO): SBD MO Status=0, MOMSN=910, MT Status=0, MTMSN=0
2012-09-11T02:46:07.465Z,1347331567.465 [Default:Iridium:Read_Iridium] Stopped
2012-09-11T02:46:07.465Z,1347331567.465 [Default:Iridium](INFO): Completed Default:Iridium
2012-09-11T02:46:07.465Z,1347331567.466 [Default:Iridium] Stopped
2012-09-11T02:46:07.466Z,1347331567.466 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-11T02:46:07.466Z,1347331567.466 [Default:Iridium:A.SetSpeed] Stopped
2012-09-11T02:46:07.466Z,1347331567.466 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T02:46:07.835Z,1347331567.835 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-09-11T02:46:07.835Z,1347331567.835 [Default:CallIridium:B] Stopped
2012-09-11T02:46:07.835Z,1347331567.835 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-09-11T02:46:07.836Z,1347331567.836 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-09-11T02:46:07.836Z,1347331567.836 [Default:CallIridium] Stopped
2012-09-11T02:46:07.836Z,1347331567.836 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-09-11T02:46:29.802Z,1347331589.802 [NAL9602](IMPORTANT): GPS fix at: 1347331593.00
2012-09-11T02:46:29.839Z,1347331589.839 [Default:GPS:Read_GPS] Stopped
2012-09-11T02:46:29.839Z,1347331589.839 [Default:GPS:D] Running Loop=1
2012-09-11T02:46:30.232Z,1347331590.232 [Default:GPS:D] Stopped
2012-09-11T02:46:30.233Z,1347331590.233 [Default:GPS](INFO): Completed Default:GPS
2012-09-11T02:46:30.233Z,1347331590.233 [Default:GPS] Stopped
2012-09-11T02:46:30.233Z,1347331590.233 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-11T02:46:30.233Z,1347331590.233 [Default:GPS:A.SetSpeed] Stopped
2012-09-11T02:46:30.233Z,1347331590.233 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T02:46:50.747Z,1347331610.747 [NAL9602](INFO): Powering down
2012-09-11T02:47:05.777Z,1347331625.777 [CBIT](INFO): Clearing failed count for component ElevatorServo
2012-09-11T02:47:05.777Z,1347331625.777 [ElevatorServo] No Fault, FailCount= 3
2012-09-11T02:47:15.774Z,1347331635.774 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T02:47:15.892Z,1347331635.892 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T02:47:15.892Z,1347331635.892 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T02:47:45.803Z,1347331665.803 [ElevatorServo](FAULT): Overload Error
2012-09-11T02:47:45.803Z,1347331665.803 [ElevatorServo] Hardware Fault, FailCount= 1
2012-09-11T02:47:45.803Z,1347331665.803 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T02:47:45.830Z,1347331665.830 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T02:47:50.830Z,1347331670.830 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T02:47:50.839Z,1347331670.839 [ElevatorServo](INFO): Powering down
2012-09-11T02:47:50.851Z,1347331670.851 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-09-11T02:47:50.851Z,1347331670.851 [ElevatorServo] No Fault, FailCount= 1
2012-09-11T02:48:00.794Z,1347331680.794 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T02:48:00.912Z,1347331680.912 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T02:48:00.912Z,1347331680.912 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T02:48:30.819Z,1347331710.819 [ElevatorServo](FAULT): Overload Error
2012-09-11T02:48:30.819Z,1347331710.819 [ElevatorServo] Hardware Fault, FailCount= 2
2012-09-11T02:48:30.819Z,1347331710.819 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T02:48:30.846Z,1347331710.846 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T02:48:35.798Z,1347331715.798 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T02:48:35.798Z,1347331715.798 [ElevatorServo](INFO): Powering down
2012-09-11T02:48:35.806Z,1347331715.806 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-09-11T02:48:35.806Z,1347331715.806 [ElevatorServo] No Fault, FailCount= 2
2012-09-11T02:48:45.789Z,1347331725.789 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T02:48:45.908Z,1347331725.908 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T02:48:45.908Z,1347331725.908 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T02:49:15.791Z,1347331755.791 [ElevatorServo](FAULT): Overload Error
2012-09-11T02:49:15.791Z,1347331755.791 [ElevatorServo] Hardware Fault, FailCount= 3
2012-09-11T02:49:15.791Z,1347331755.791 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T02:49:15.818Z,1347331755.818 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T02:49:15.819Z,1347331755.819 [CBIT](CRITICAL): Hardware Fault in component: ElevatorServo
2012-09-11T02:49:20.777Z,1347331760.777 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T02:49:20.778Z,1347331760.778 [ElevatorServo](INFO): Powering down
2012-09-11T02:51:10.764Z,1347331870.764 [Default:CallIridium] Running Loop=1
2012-09-11T02:51:10.764Z,1347331870.764 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-11T02:51:10.764Z,1347331870.764 [Default:CallIridium:A] Running Loop=1
2012-09-11T02:51:10.765Z,1347331870.765 [Default:CallIridium:A] Stopped
2012-09-11T02:51:10.765Z,1347331870.765 [Default:CallIridium:B] Running Loop=1
2012-09-11T02:51:10.765Z,1347331870.765 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-11T02:51:15.795Z,1347331875.795 [Default:Iridium] Running Loop=1
2012-09-11T02:51:15.795Z,1347331875.795 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-11T02:51:15.795Z,1347331875.796 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T02:51:15.796Z,1347331875.796 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-11T02:51:15.796Z,1347331875.796 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-11T02:51:15.796Z,1347331875.796 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T02:51:15.797Z,1347331875.797 [Default:Iridium:B.GoToSurface] Stopped
2012-09-11T02:51:15.797Z,1347331875.797 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T02:51:15.797Z,1347331875.797 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-11T02:51:15.797Z,1347331875.797 [Default:GPS] Running Loop=1
2012-09-11T02:51:15.797Z,1347331875.797 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-11T02:51:15.798Z,1347331875.797 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T02:51:15.798Z,1347331875.798 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-11T02:51:15.798Z,1347331875.798 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-11T02:51:15.798Z,1347331875.798 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T02:51:15.803Z,1347331875.803 [Default:GPS:B.GoToSurface] Stopped
2012-09-11T02:51:15.803Z,1347331875.803 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T02:51:15.803Z,1347331875.803 [Default:GPS:Read_GPS] Running Loop=1
2012-09-11T02:51:16.411Z,1347331876.411 [NAL9602](INFO): Powering up
2012-09-11T02:51:27.419Z,1347331887.419 [NAL9602](INFO): NAL9602 initialized
2012-09-11T02:51:55.033Z,1347331915.033 [NAL9602](INFO): SBD MO Status=1, MOMSN=911, MT Status=0, MTMSN=0
2012-09-11T02:51:55.067Z,1347331915.067 [NAL9602](INFO): Sent 248 bytes from file Logs/20120911T005835/shore0024.lzma
2012-09-11T02:51:55.067Z,1347331915.067 [NAL9602](INFO): Packets left to send: 0
2012-09-11T02:51:55.069Z,1347331915.069 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0024.lzma.parts/0000.sbd
2012-09-11T02:52:04.236Z,1347331924.236 [NAL9602](INFO): SBD MO Status=0, MOMSN=912, MT Status=0, MTMSN=0
2012-09-11T02:52:04.321Z,1347331924.321 [Default:Iridium:Read_Iridium] Stopped
2012-09-11T02:52:04.322Z,1347331924.322 [Default:Iridium](INFO): Completed Default:Iridium
2012-09-11T02:52:04.322Z,1347331924.322 [Default:Iridium] Stopped
2012-09-11T02:52:04.322Z,1347331924.322 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-11T02:52:04.322Z,1347331924.322 [Default:Iridium:A.SetSpeed] Stopped
2012-09-11T02:52:04.322Z,1347331924.322 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T02:52:04.657Z,1347331924.657 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-09-11T02:52:04.657Z,1347331924.657 [Default:CallIridium:B] Stopped
2012-09-11T02:52:04.658Z,1347331924.658 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-09-11T02:52:04.658Z,1347331924.658 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-09-11T02:52:04.658Z,1347331924.658 [Default:CallIridium] Stopped
2012-09-11T02:52:04.658Z,1347331924.658 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-09-11T02:52:29.034Z,1347331949.034 [NAL9602](IMPORTANT): GPS fix at: 1347331952.00
2012-09-11T02:52:29.087Z,1347331949.087 [Default:GPS:Read_GPS] Stopped
2012-09-11T02:52:29.087Z,1347331949.087 [Default:GPS:D] Running Loop=1
2012-09-11T02:52:29.464Z,1347331949.464 [Default:GPS:D] Stopped
2012-09-11T02:52:29.464Z,1347331949.464 [Default:GPS](INFO): Completed Default:GPS
2012-09-11T02:52:29.464Z,1347331949.464 [Default:GPS] Stopped
2012-09-11T02:52:29.464Z,1347331949.464 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-11T02:52:29.465Z,1347331949.464 [Default:GPS:A.SetSpeed] Stopped
2012-09-11T02:52:29.465Z,1347331949.465 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T02:52:49.986Z,1347331969.986 [NAL9602](INFO): Powering down
2012-09-11T02:57:04.987Z,1347332224.987 [Default:CallIridium] Running Loop=1
2012-09-11T02:57:04.987Z,1347332224.987 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-11T02:57:04.987Z,1347332224.987 [Default:CallIridium:A] Running Loop=1
2012-09-11T02:57:04.988Z,1347332224.988 [Default:CallIridium:A] Stopped
2012-09-11T02:57:04.988Z,1347332224.988 [Default:CallIridium:B] Running Loop=1
2012-09-11T02:57:04.988Z,1347332224.988 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-11T02:57:09.000Z,1347332230.000 [Default:Iridium] Running Loop=1
2012-09-11T02:57:10.000Z,1347332230.000 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-11T02:57:10.000Z,1347332230.000 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T02:57:10.000Z,1347332230.000 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-11T02:57:10.000Z,1347332230.000 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-11T02:57:10.001Z,1347332230.000 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T02:57:10.001Z,1347332230.001 [Default:Iridium:B.GoToSurface] Stopped
2012-09-11T02:57:10.001Z,1347332230.001 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T02:57:10.002Z,1347332230.002 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-11T02:57:10.002Z,1347332230.002 [Default:GPS] Running Loop=1
2012-09-11T02:57:10.002Z,1347332230.002 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-11T02:57:10.002Z,1347332230.002 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T02:57:10.006Z,1347332230.006 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-11T02:57:10.007Z,1347332230.007 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-11T02:57:10.007Z,1347332230.007 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T02:57:10.008Z,1347332230.008 [Default:GPS:B.GoToSurface] Stopped
2012-09-11T02:57:10.008Z,1347332230.008 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T02:57:10.008Z,1347332230.008 [Default:GPS:Read_GPS] Running Loop=1
2012-09-11T02:57:10.636Z,1347332230.636 [NAL9602](INFO): Powering up
2012-09-11T02:57:21.563Z,1347332241.563 [NAL9602](INFO): NAL9602 initialized
2012-09-11T02:57:39.532Z,1347332259.532 [NAL9602](INFO): SBD MO Status=1, MOMSN=913, MT Status=0, MTMSN=0
2012-09-11T02:57:39.567Z,1347332259.567 [NAL9602](INFO): Sent 155 bytes from file Logs/20120911T005835/shore0025.lzma
2012-09-11T02:57:39.567Z,1347332259.567 [NAL9602](INFO): Packets left to send: 0
2012-09-11T02:57:39.569Z,1347332259.569 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0025.lzma.parts/0000.sbd
2012-09-11T02:57:49.937Z,1347332269.937 [NAL9602](INFO): SBD MO Status=0, MOMSN=914, MT Status=0, MTMSN=0
2012-09-11T02:57:50.025Z,1347332270.026 [Default:Iridium:Read_Iridium] Stopped
2012-09-11T02:57:50.026Z,1347332270.026 [Default:Iridium](INFO): Completed Default:Iridium
2012-09-11T02:57:50.026Z,1347332270.026 [Default:Iridium] Stopped
2012-09-11T02:57:50.026Z,1347332270.026 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-11T02:57:50.034Z,1347332270.034 [Default:Iridium:A.SetSpeed] Stopped
2012-09-11T02:57:50.035Z,1347332270.035 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T02:57:50.375Z,1347332270.375 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-09-11T02:57:50.375Z,1347332270.375 [Default:CallIridium:B] Stopped
2012-09-11T02:57:50.375Z,1347332270.375 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-09-11T02:57:50.375Z,1347332270.375 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-09-11T02:57:50.375Z,1347332270.375 [Default:CallIridium] Stopped
2012-09-11T02:57:50.375Z,1347332270.375 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-09-11T02:58:19.559Z,1347332299.559 [NAL9602](IMPORTANT): GPS fix at: 1347332303.00
2012-09-11T02:58:19.589Z,1347332299.589 [Default:GPS:Read_GPS] Stopped
2012-09-11T02:58:19.589Z,1347332299.589 [Default:GPS:D] Running Loop=1
2012-09-11T02:58:19.985Z,1347332299.985 [Default:GPS:D] Stopped
2012-09-11T02:58:19.985Z,1347332299.985 [Default:GPS](INFO): Completed Default:GPS
2012-09-11T02:58:19.985Z,1347332299.986 [Default:GPS] Stopped
2012-09-11T02:58:19.986Z,1347332299.986 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-11T02:58:19.986Z,1347332299.986 [Default:GPS:A.SetSpeed] Stopped
2012-09-11T02:58:19.986Z,1347332299.986 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T02:58:40.454Z,1347332320.454 [NAL9602](INFO): Powering down
2012-09-11T03:02:50.561Z,1347332570.561 [Default:CallIridium] Running Loop=1
2012-09-11T03:02:50.561Z,1347332570.561 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-11T03:02:50.561Z,1347332570.561 [Default:CallIridium:A] Running Loop=1
2012-09-11T03:02:50.562Z,1347332570.562 [Default:CallIridium:A] Stopped
2012-09-11T03:02:50.562Z,1347332570.562 [Default:CallIridium:B] Running Loop=1
2012-09-11T03:02:50.562Z,1347332570.562 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-11T03:02:55.507Z,1347332575.507 [Default:Iridium] Running Loop=1
2012-09-11T03:02:55.507Z,1347332575.507 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-11T03:02:55.507Z,1347332575.507 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T03:02:55.507Z,1347332575.507 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-11T03:02:55.507Z,1347332575.507 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-11T03:02:55.508Z,1347332575.508 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T03:02:55.508Z,1347332575.508 [Default:Iridium:B.GoToSurface] Stopped
2012-09-11T03:02:55.508Z,1347332575.508 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T03:02:55.509Z,1347332575.509 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-11T03:02:55.509Z,1347332575.509 [Default:GPS] Running Loop=1
2012-09-11T03:02:55.509Z,1347332575.509 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-11T03:02:55.509Z,1347332575.509 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T03:02:55.509Z,1347332575.509 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-11T03:02:55.510Z,1347332575.510 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-11T03:02:55.510Z,1347332575.510 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T03:02:55.514Z,1347332575.514 [Default:GPS:B.GoToSurface] Stopped
2012-09-11T03:02:55.515Z,1347332575.514 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T03:02:55.515Z,1347332575.515 [Default:GPS:Read_GPS] Running Loop=1
2012-09-11T03:02:56.147Z,1347332576.147 [NAL9602](INFO): Powering up
2012-09-11T03:03:07.139Z,1347332587.139 [NAL9602](INFO): NAL9602 initialized
2012-09-11T03:03:40.938Z,1347332620.938 [NAL9602](INFO): SBD MO Status=1, MOMSN=915, MT Status=0, MTMSN=0
2012-09-11T03:03:40.971Z,1347332620.971 [NAL9602](INFO): Sent 139 bytes from file Logs/20120911T005835/shore0026.lzma
2012-09-11T03:03:40.971Z,1347332620.971 [NAL9602](INFO): Packets left to send: 0
2012-09-11T03:03:40.973Z,1347332620.973 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0026.lzma.parts/0000.sbd
2012-09-11T03:03:48.556Z,1347332628.556 [NAL9602](INFO): SBD MO Status=0, MOMSN=916, MT Status=0, MTMSN=0
2012-09-11T03:03:48.633Z,1347332628.633 [Default:Iridium:Read_Iridium] Stopped
2012-09-11T03:03:48.633Z,1347332628.633 [Default:Iridium](INFO): Completed Default:Iridium
2012-09-11T03:03:48.633Z,1347332628.633 [Default:Iridium] Stopped
2012-09-11T03:03:48.633Z,1347332628.633 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-11T03:03:48.633Z,1347332628.633 [Default:Iridium:A.SetSpeed] Stopped
2012-09-11T03:03:48.633Z,1347332628.634 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T03:03:48.995Z,1347332628.995 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-09-11T03:03:48.995Z,1347332628.995 [Default:CallIridium:B] Stopped
2012-09-11T03:03:48.995Z,1347332628.995 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-09-11T03:03:48.995Z,1347332628.995 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-09-11T03:03:48.995Z,1347332628.995 [Default:CallIridium] Stopped
2012-09-11T03:03:48.995Z,1347332628.995 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-09-11T03:03:49.759Z,1347332629.759 [NAL9602](IMPORTANT): GPS fix at: 1347332633.00
2012-09-11T03:03:49.808Z,1347332629.809 [Default:GPS:Read_GPS] Stopped
2012-09-11T03:03:49.809Z,1347332629.809 [Default:GPS:D] Running Loop=1
2012-09-11T03:03:50.179Z,1347332630.179 [Default:GPS:D] Stopped
2012-09-11T03:03:50.180Z,1347332630.180 [Default:GPS](INFO): Completed Default:GPS
2012-09-11T03:03:50.180Z,1347332630.180 [Default:GPS] Stopped
2012-09-11T03:03:50.180Z,1347332630.180 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-11T03:03:50.180Z,1347332630.180 [Default:GPS:A.SetSpeed] Stopped
2012-09-11T03:03:50.180Z,1347332630.180 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T03:04:05.719Z,1347332645.718 [NAL9602](INFO): Powering down
2012-09-11T03:04:15.938Z,1347332655.938 [CBIT](INFO): Clearing failed count for component ElevatorServo
2012-09-11T03:04:15.939Z,1347332655.939 [ElevatorServo] No Fault, FailCount= 3
2012-09-11T03:04:25.734Z,1347332665.734 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T03:04:25.852Z,1347332665.852 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T03:04:25.852Z,1347332665.852 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T03:04:55.779Z,1347332695.779 [ElevatorServo](FAULT): Overload Error
2012-09-11T03:04:55.779Z,1347332695.779 [ElevatorServo] Hardware Fault, FailCount= 1
2012-09-11T03:04:55.779Z,1347332695.779 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T03:04:55.806Z,1347332695.806 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T03:05:00.746Z,1347332700.746 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T03:05:00.746Z,1347332700.746 [ElevatorServo](INFO): Powering down
2012-09-11T03:05:00.754Z,1347332700.754 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-09-11T03:05:00.754Z,1347332700.754 [ElevatorServo] No Fault, FailCount= 1
2012-09-11T03:05:10.826Z,1347332710.826 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T03:05:10.944Z,1347332710.944 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T03:05:10.944Z,1347332710.944 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T03:05:40.747Z,1347332740.747 [ElevatorServo](FAULT): Overload Error
2012-09-11T03:05:40.747Z,1347332740.747 [ElevatorServo] Hardware Fault, FailCount= 2
2012-09-11T03:05:40.747Z,1347332740.747 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T03:05:40.774Z,1347332740.774 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T03:05:45.773Z,1347332745.773 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T03:05:45.773Z,1347332745.773 [ElevatorServo](INFO): Powering down
2012-09-11T03:05:45.781Z,1347332745.781 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-09-11T03:05:45.781Z,1347332745.781 [ElevatorServo] No Fault, FailCount= 2
2012-09-11T03:05:55.725Z,1347332755.726 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-11T03:05:55.844Z,1347332755.844 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-11T03:05:55.844Z,1347332755.844 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-11T03:06:25.759Z,1347332785.759 [ElevatorServo](FAULT): Overload Error
2012-09-11T03:06:25.759Z,1347332785.759 [ElevatorServo] Hardware Fault, FailCount= 3
2012-09-11T03:06:25.759Z,1347332785.759 [ElevatorServo](ERROR): Hardware Fault
2012-09-11T03:06:25.786Z,1347332785.786 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-11T03:06:25.787Z,1347332785.787 [CBIT](CRITICAL): Hardware Fault in component: ElevatorServo
2012-09-11T03:06:30.750Z,1347332790.750 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-11T03:06:30.750Z,1347332790.750 [ElevatorServo](INFO): Powering down
2012-09-11T03:07:50.732Z,1347332870.732 [PAR_Licor](ERROR): PAR reading out of range: -0.006358 uMol/s/m2
2012-09-11T03:08:50.723Z,1347332930.723 [Default:CallIridium] Running Loop=1
2012-09-11T03:08:50.723Z,1347332930.723 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-11T03:08:50.723Z,1347332930.723 [Default:CallIridium:A] Running Loop=1
2012-09-11T03:08:50.724Z,1347332930.724 [Default:CallIridium:A] Stopped
2012-09-11T03:08:50.724Z,1347332930.724 [Default:CallIridium:B] Running Loop=1
2012-09-11T03:08:50.724Z,1347332930.724 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-11T03:08:55.976Z,1347332935.976 [Default:Iridium] Running Loop=1
2012-09-11T03:08:55.976Z,1347332935.976 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-11T03:08:55.976Z,1347332935.977 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T03:08:55.977Z,1347332935.977 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-11T03:08:55.977Z,1347332935.977 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-11T03:08:55.977Z,1347332935.977 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T03:08:55.978Z,1347332935.978 [Default:Iridium:B.GoToSurface] Stopped
2012-09-11T03:08:55.978Z,1347332935.978 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T03:08:55.978Z,1347332935.978 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-11T03:08:55.987Z,1347332935.987 [Default:GPS] Running Loop=1
2012-09-11T03:08:55.987Z,1347332935.987 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-11T03:08:55.987Z,1347332935.987 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T03:08:55.987Z,1347332935.987 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-11T03:08:55.987Z,1347332935.987 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-11T03:08:55.987Z,1347332935.987 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T03:08:55.988Z,1347332935.988 [Default:GPS:B.GoToSurface] Stopped
2012-09-11T03:08:55.988Z,1347332935.988 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T03:08:55.988Z,1347332935.988 [Default:GPS:Read_GPS] Running Loop=1
2012-09-11T03:08:56.663Z,1347332936.663 [NAL9602](INFO): Powering up
2012-09-11T03:09:07.607Z,1347332947.607 [NAL9602](INFO): NAL9602 initialized
2012-09-11T03:09:25.164Z,1347332965.164 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=917, MT Status=1, MTMSN=105
2012-09-11T03:09:25.203Z,1347332965.203 [NAL9602](INFO): Sent 236 bytes from file Logs/20120911T005835/shore0027.lzma
2012-09-11T03:09:25.203Z,1347332965.203 [NAL9602](INFO): Packets left to send: 0
2012-09-11T03:09:25.205Z,1347332965.205 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0027.lzma.parts/0000.sbd
2012-09-11T03:09:26.022Z,1347332966.022 [NAL9602](IMPORTANT): Initialized file: ./Config/lrauv-daphne/Servo.cfg
2012-09-11T03:09:29.938Z,1347332969.938 [NAL9602](IMPORTANT): Success executing cat Logs/latest/504EAA89.part | gunzip -f -d | cat `cp ./Config/lrauv-daphne/.svn/text-base/Servo.cfg.svn-base ./Config/lrauv-daphne/Servo.cfg` | vim -e ./Config/lrauv-daphne/Servo.cfg
2012-09-11T03:09:30.116Z,1347332970.116 [CommandLine](IMPORTANT): 8f5d48d93b0a5ceea9554ea1cbc685d6  ./Config/lrauv-daphne/Servo.cfg

2012-09-11T03:09:36.630Z,1347332976.630 [NAL9602](INFO): SBD MO Status=0, MOMSN=918, MT Status=0, MTMSN=0
2012-09-11T03:09:50.732Z,1347332990.732 [NAL9602](INFO): SBD MO Status=1, MOMSN=919, MT Status=0, MTMSN=0
2012-09-11T03:09:50.768Z,1347332990.768 [NAL9602](INFO): Sent 332 bytes from file Logs/20120911T005835/shore0028.lzma
2012-09-11T03:09:50.768Z,1347332990.768 [NAL9602](INFO): Packets left to send: 1
2012-09-11T03:09:50.770Z,1347332990.770 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0028.lzma.parts/0001.sbd
2012-09-11T03:09:57.284Z,1347332997.284 [NAL9602](INFO): SBD MO Status=1, MOMSN=920, MT Status=0, MTMSN=0
2012-09-11T03:09:57.319Z,1347332997.319 [NAL9602](INFO): Sent 14 bytes from file Logs/20120911T005835/shore0028.lzma
2012-09-11T03:09:57.319Z,1347332997.319 [NAL9602](INFO): Packets left to send: 0
2012-09-11T03:09:57.320Z,1347332997.320 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0028.lzma.parts/0000.sbd
2012-09-11T03:10:05.685Z,1347333005.685 [NAL9602](INFO): SBD MO Status=0, MOMSN=921, MT Status=0, MTMSN=0
2012-09-11T03:10:05.757Z,1347333005.757 [Default:Iridium:Read_Iridium] Stopped
2012-09-11T03:10:05.758Z,1347333005.758 [Default:Iridium](INFO): Completed Default:Iridium
2012-09-11T03:10:05.758Z,1347333005.758 [Default:Iridium] Stopped
2012-09-11T03:10:05.758Z,1347333005.758 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-11T03:10:05.758Z,1347333005.758 [Default:Iridium:A.SetSpeed] Stopped
2012-09-11T03:10:05.758Z,1347333005.758 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T03:10:06.115Z,1347333006.115 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-09-11T03:10:06.115Z,1347333006.115 [Default:CallIridium:B] Stopped
2012-09-11T03:10:06.115Z,1347333006.115 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-09-11T03:10:06.115Z,1347333006.115 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-09-11T03:10:06.115Z,1347333006.115 [Default:CallIridium] Stopped
2012-09-11T03:10:06.116Z,1347333006.115 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-09-11T03:10:27.291Z,1347333027.291 [NAL9602](IMPORTANT): GPS fix at: 1347333032.00
2012-09-11T03:10:27.344Z,1347333027.344 [Default:GPS:Read_GPS] Stopped
2012-09-11T03:10:27.344Z,1347333027.344 [Default:GPS:D] Running Loop=1
2012-09-11T03:10:27.713Z,1347333027.713 [Default:GPS:D] Stopped
2012-09-11T03:10:27.714Z,1347333027.714 [Default:GPS](INFO): Completed Default:GPS
2012-09-11T03:10:27.714Z,1347333027.714 [Default:GPS] Stopped
2012-09-11T03:10:27.714Z,1347333027.714 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-11T03:10:27.714Z,1347333027.714 [Default:GPS:A.SetSpeed] Stopped
2012-09-11T03:10:27.714Z,1347333027.714 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-11T03:10:48.219Z,1347333048.219 [NAL9602](INFO): Powering down
2012-09-11T03:15:08.267Z,1347333308.267 [Default:CallIridium] Running Loop=1
2012-09-11T03:15:08.267Z,1347333308.267 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-11T03:15:08.268Z,1347333308.267 [Default:CallIridium:A] Running Loop=1
2012-09-11T03:15:08.268Z,1347333308.268 [Default:CallIridium:A] Stopped
2012-09-11T03:15:08.268Z,1347333308.268 [Default:CallIridium:B] Running Loop=1
2012-09-11T03:15:08.268Z,1347333308.268 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-11T03:15:13.268Z,1347333313.268 [Default:Iridium] Running Loop=1
2012-09-11T03:15:13.269Z,1347333313.269 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-11T03:15:13.269Z,1347333313.269 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-11T03:15:13.269Z,1347333313.269 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-11T03:15:13.269Z,1347333313.269 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-11T03:15:13.269Z,1347333313.269 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T03:15:13.270Z,1347333313.270 [Default:Iridium:B.GoToSurface] Stopped
2012-09-11T03:15:13.270Z,1347333313.270 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T03:15:13.270Z,1347333313.270 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-11T03:15:13.275Z,1347333313.275 [Default:GPS] Running Loop=1
2012-09-11T03:15:13.275Z,1347333313.275 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-11T03:15:13.275Z,1347333313.275 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-11T03:15:13.275Z,1347333313.275 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-11T03:15:13.275Z,1347333313.275 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-11T03:15:13.275Z,1347333313.275 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-11T03:15:13.276Z,1347333313.276 [Default:GPS:B.GoToSurface] Stopped
2012-09-11T03:15:13.276Z,1347333313.276 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-11T03:15:13.276Z,1347333313.276 [Default:GPS:Read_GPS] Running Loop=1
2012-09-11T03:15:13.882Z,1347333313.882 [NAL9602](INFO): Powering up
2012-09-11T03:15:21.485Z,1347333321.485 [PAR_Licor](ERROR): PAR reading out of range: -0.022253 uMol/s/m2
2012-09-11T03:15:24.803Z,1347333324.803 [NAL9602](INFO): NAL9602 initialized
2012-09-11T03:15:53.457Z,1347333353.457 [NAL9602](INFO): SBD MO Status=2, MOMSN=922, MT Status=2, MTMSN=0
2012-09-11T03:15:53.457Z,1347333353.457 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T03:16:09.897Z,1347333369.897 [PAR_Licor](ERROR): PAR reading out of range: -0.046095 uMol/s/m2
2012-09-11T03:16:11.876Z,1347333371.876 [NAL9602](INFO): SBD MO Status=2, MOMSN=922, MT Status=2, MTMSN=0
2012-09-11T03:16:11.877Z,1347333371.876 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-09-11T03:16:30.856Z,1347333390.856 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=922, MT Status=1, MTMSN=106
2012-09-11T03:16:30.891Z,1347333390.891 [NAL9602](INFO): Sent 162 bytes from file Logs/20120911T005835/shore0029.lzma
2012-09-11T03:16:30.891Z,1347333390.891 [NAL9602](INFO): Packets left to send: 0
2012-09-11T03:16:30.893Z,1347333390.893 [NAL9602](INFO): Stored copy of sent data in Logs/20120911T005835/shore0029.lzma.parts/0000.sbd
2012-09-11T03:16:31.352Z,1347333391.352 [NAL9602](INFO): Received command:restart system
2012-09-11T03:16:31.435Z,1347333391.435 [CommandLine](IMPORTANT): got command restart system