2011-02-28T18:41:28.08410Z,1298918488.0841 [Supervisor](DEBUG): Initializing supervisor.
2011-02-28T18:41:28.08730Z,1298918488.0873 [SyncHandler](DEBUG): Created PCaller Thread at 1077007584
2011-02-28T18:41:28.08810Z,1298918488.0881 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2011-02-28T18:41:28.08930Z,1298918488.0893 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 1077073120
2011-02-28T18:41:28.09040Z,1298918488.0904 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2011-02-28T18:41:28.10210Z,1298918488.1021 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2011-02-28T18:41:28.10330Z,1298918488.1033 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 1077138656
2011-02-28T18:41:28.10390Z,1298918488.1039 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2011-02-28T18:41:28.10440Z,1298918488.1044 [Supervisor](INFO): Looking for Config files in directory: Config/
2011-02-28T18:41:28.10750Z,1298918488.1075 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2011-02-28T18:41:28.73100Z,1298918488.731 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2011-02-28T18:41:28.73170Z,1298918488.7317 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2011-02-28T18:41:28.92910Z,1298918488.9291 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2011-02-28T18:41:28.92970Z,1298918488.9297 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2011-02-28T18:41:29.02000Z,1298918489.02 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2011-02-28T18:41:29.02060Z,1298918489.0206 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2011-02-28T18:41:29.20480Z,1298918489.2048 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2011-02-28T18:41:29.20550Z,1298918489.2055 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2011-02-28T18:41:29.34970Z,1298918489.3497 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2011-02-28T18:41:29.35030Z,1298918489.3503 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2011-02-28T18:41:29.69290Z,1298918489.6929 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2011-02-28T18:41:29.69360Z,1298918489.6936 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2011-02-28T18:41:29.85660Z,1298918489.8566 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2011-02-28T18:41:29.85730Z,1298918489.8573 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2011-02-28T18:41:29.95620Z,1298918489.9562 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2011-02-28T18:41:29.95690Z,1298918489.9569 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2011-02-28T18:41:30.06220Z,1298918490.0622 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2011-02-28T18:41:30.06300Z,1298918490.063 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2011-02-28T18:41:32.43050Z,1298918492.4305 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2011-02-28T18:41:32.43140Z,1298918492.4314 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2011-02-28T18:41:33.21560Z,1298918493.2156 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2011-02-28T18:41:33.21630Z,1298918493.2163 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2011-02-28T18:41:33.47040Z,1298918493.4704 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-tethys/
2011-02-28T18:41:33.47140Z,1298918493.4714 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/vehicle.cfg
2011-02-28T18:41:33.56940Z,1298918493.5694 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/vehicle"
2011-02-28T18:41:33.57000Z,1298918493.57 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Sensor.cfg
2011-02-28T18:41:33.70100Z,1298918493.701 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Sensor"
2011-02-28T18:41:33.70170Z,1298918493.7017 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/BIT.cfg
2011-02-28T18:41:33.79400Z,1298918493.794 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/BIT"
2011-02-28T18:41:33.79470Z,1298918493.7947 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Servo.cfg
2011-02-28T18:41:33.89570Z,1298918493.8957 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Servo"
2011-02-28T18:41:33.89630Z,1298918493.8963 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Science.cfg
2011-02-28T18:41:33.99360Z,1298918493.9936 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Science"
2011-02-28T18:41:33.99430Z,1298918493.9943 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/workSite.cfg
2011-02-28T18:41:34.08570Z,1298918494.0857 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/workSite"
2011-02-28T18:41:34.08640Z,1298918494.0864 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Simulator.cfg
2011-02-28T18:41:34.17460Z,1298918494.1746 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Simulator"
2011-02-28T18:41:34.17530Z,1298918494.1753 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Derivation.cfg
2011-02-28T18:41:34.26360Z,1298918494.2636 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Derivation"
2011-02-28T18:41:34.26420Z,1298918494.2642 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Sensor2.cfg
2011-02-28T18:41:34.37130Z,1298918494.3713 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor2
2011-02-28T18:41:34.37330Z,1298918494.3733 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-tethys//
2011-02-28T18:41:34.37410Z,1298918494.3741 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//vehicle.cfg
2011-02-28T18:41:34.47170Z,1298918494.4717 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/vehicle"
2011-02-28T18:41:34.47230Z,1298918494.4723 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//Sensor.cfg
2011-02-28T18:41:34.59460Z,1298918494.5946 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Sensor"
2011-02-28T18:41:34.59530Z,1298918494.5953 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//BIT.cfg
2011-02-28T18:41:34.68520Z,1298918494.6852 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/BIT"
2011-02-28T18:41:34.68580Z,1298918494.6858 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//Servo.cfg
2011-02-28T18:41:34.78470Z,1298918494.7847 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Servo"
2011-02-28T18:41:34.78530Z,1298918494.7853 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//Science.cfg
2011-02-28T18:41:34.88100Z,1298918494.881 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Science"
2011-02-28T18:41:34.88170Z,1298918494.8817 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//workSite.cfg
2011-02-28T18:41:34.97190Z,1298918494.9719 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/workSite"
2011-02-28T18:41:34.97250Z,1298918494.9725 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//Simulator.cfg
2011-02-28T18:41:36.78960Z,1298918496.7896 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Simulator"
2011-02-28T18:41:36.79020Z,1298918496.7902 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//Derivation.cfg
2011-02-28T18:41:37.04290Z,1298918497.0429 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Derivation"
2011-02-28T18:41:37.04350Z,1298918497.0435 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//Sensor2.cfg
2011-02-28T18:41:37.54350Z,1298918497.5435 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Sensor2"
2011-02-28T18:41:38.03500Z,1298918498.035 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2011-02-28T18:41:38.14390Z,1298918498.1439 [InternalSim] Loaded
2011-02-28T18:41:38.14430Z,1298918498.1443 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2011-02-28T18:41:38.14520Z,1298918498.1452 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2011-02-28T18:41:38.14590Z,1298918498.1459 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2011-02-28T18:41:38.32720Z,1298918498.3272 [SBIT](DEBUG): Construct Startup Built In Test.
2011-02-28T18:41:38.36020Z,1298918498.3602 [SBIT] Loaded
2011-02-28T18:41:38.36050Z,1298918498.3605 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2011-02-28T18:41:38.36160Z,1298918498.3616 [IBIT](DEBUG): Construct Initiated Built In Test.
2011-02-28T18:41:38.39550Z,1298918498.3955 [IBIT] Loaded
2011-02-28T18:41:38.39580Z,1298918498.3958 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2011-02-28T18:41:38.39700Z,1298918498.397 [CBIT](DEBUG): Construct CBIT Built In Test.
2011-02-28T18:41:38.42780Z,1298918498.4278 [CBIT] Loaded
2011-02-28T18:41:38.42810Z,1298918498.4281 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2011-02-28T18:41:38.42860Z,1298918498.4286 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2011-02-28T18:41:38.42930Z,1298918498.4293 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2011-02-28T18:41:38.52620Z,1298918498.5262 [BuoyancyServo] Loaded
2011-02-28T18:41:38.52650Z,1298918498.5265 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2011-02-28T18:41:38.53460Z,1298918498.5346 [ElevatorServo] Loaded
2011-02-28T18:41:38.53500Z,1298918498.535 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2011-02-28T18:41:38.54310Z,1298918498.5431 [MassServo] Loaded
2011-02-28T18:41:38.54340Z,1298918498.5434 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2011-02-28T18:41:38.55140Z,1298918498.5514 [RudderServo] Loaded
2011-02-28T18:41:38.55180Z,1298918498.5518 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2011-02-28T18:41:38.56000Z,1298918498.56 [ThrusterServo] Loaded
2011-02-28T18:41:38.56030Z,1298918498.5603 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2011-02-28T18:41:38.56080Z,1298918498.5608 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2011-02-28T18:41:38.56150Z,1298918498.5615 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2011-02-28T18:41:38.59550Z,1298918498.5955 [Bathymetry] Loaded
2011-02-28T18:41:38.59580Z,1298918498.5958 [ComponentRegistry](DEBUG): SyncComponent "Bathymetry" handled in the control thread.
2011-02-28T18:41:38.60280Z,1298918498.6028 [DepthRateCalculator] Loaded
2011-02-28T18:41:38.60310Z,1298918498.6031 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2011-02-28T18:41:38.61000Z,1298918498.61 [PitchRateCalculator] Loaded
2011-02-28T18:41:38.61030Z,1298918498.6103 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2011-02-28T18:41:38.61720Z,1298918498.6172 [SpeedCalculator] Loaded
2011-02-28T18:41:38.61750Z,1298918498.6175 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2011-02-28T18:41:38.63460Z,1298918498.6346 [TempGradientCalculator] Loaded
2011-02-28T18:41:38.63500Z,1298918498.635 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2011-02-28T18:41:38.64210Z,1298918498.6421 [YawRateCalculator] Loaded
2011-02-28T18:41:38.64240Z,1298918498.6424 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2011-02-28T18:41:38.67840Z,1298918498.6784 [Navigation] Loaded
2011-02-28T18:41:38.67880Z,1298918498.6788 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2011-02-28T18:41:38.67940Z,1298918498.6794 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2011-02-28T18:41:38.68010Z,1298918498.6801 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2011-02-28T18:41:38.72700Z,1298918498.727 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2011-02-28T18:41:38.72770Z,1298918498.7277 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2011-02-28T18:41:38.74080Z,1298918498.7408 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2011-02-28T18:41:38.74150Z,1298918498.7415 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2011-02-28T18:41:38.76860Z,1298918498.7686 [VerticalControl](DEBUG): Construct VerticalControl.
2011-02-28T18:41:38.98740Z,1298918498.9874 [VerticalControl] Loaded
2011-02-28T18:41:38.98780Z,1298918498.9878 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2011-02-28T18:41:38.98890Z,1298918498.9889 [HorizontalControl](DEBUG): Construct HorizontalControl.
2011-02-28T18:41:39.04600Z,1298918499.046 [HorizontalControl] Loaded
2011-02-28T18:41:39.04630Z,1298918499.0463 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2011-02-28T18:41:39.04750Z,1298918499.0475 [SpeedControl](DEBUG): Construct SpeedControl.
2011-02-28T18:41:39.04970Z,1298918499.0497 [SpeedControl] Loaded
2011-02-28T18:41:39.05010Z,1298918499.0501 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2011-02-28T18:41:39.05130Z,1298918499.0513 [LoopControl](DEBUG): Construct LoopControl.
2011-02-28T18:41:39.05620Z,1298918499.0562 [LoopControl] Loaded
2011-02-28T18:41:39.05660Z,1298918499.0566 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2011-02-28T18:41:39.05710Z,1298918499.0571 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2011-02-28T18:41:39.05780Z,1298918499.0578 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2011-02-28T18:41:39.06940Z,1298918499.0694 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2011-02-28T18:41:39.07570Z,1298918499.0757 [AsyncPiEstimator] Loaded
2011-02-28T18:41:39.07610Z,1298918499.0761 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2011-02-28T18:41:39.07890Z,1298918499.0789 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 1078576352
2011-02-28T18:41:39.08030Z,1298918499.0803 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2011-02-28T18:41:39.08100Z,1298918499.081 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2011-02-28T18:41:39.15350Z,1298918499.1535 [AHRS_3DMGX3] Loaded
2011-02-28T18:41:39.15380Z,1298918499.1538 [ComponentRegistry](DEBUG): SyncComponent "AHRS_3DMGX3" handled in the control thread.
2011-02-28T18:41:39.52630Z,1298918499.5263 [Batt_Ocean_Server] Loaded
2011-02-28T18:41:39.52670Z,1298918499.5267 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2011-02-28T18:41:39.54170Z,1298918499.5417 [Depth_Keller] Loaded
2011-02-28T18:41:39.54200Z,1298918499.542 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2011-02-28T18:41:39.54840Z,1298918499.5484 [DropWeight] Loaded
2011-02-28T18:41:39.54870Z,1298918499.5487 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2011-02-28T18:41:39.65960Z,1298918499.6596 [DVL_micro] Loaded
2011-02-28T18:41:39.66000Z,1298918499.66 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2011-02-28T18:41:39.74990Z,1298918499.7499 [NAL9601] Loaded
2011-02-28T18:41:39.75030Z,1298918499.7503 [ComponentRegistry](DEBUG): SyncComponent "NAL9601" handled in the control thread.
2011-02-28T18:41:39.80140Z,1298918499.8014 [Onboard] Loaded
2011-02-28T18:41:39.80170Z,1298918499.8017 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2011-02-28T18:41:39.80940Z,1298918499.8094 [Radio_Freewave] Loaded
2011-02-28T18:41:39.80980Z,1298918499.8098 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2011-02-28T18:41:39.81030Z,1298918499.8103 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2011-02-28T18:41:39.81100Z,1298918499.811 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2011-02-28T18:41:39.86210Z,1298918499.8621 [CTD_NeilBrown] Loaded
2011-02-28T18:41:39.86240Z,1298918499.8624 [ComponentRegistry](DEBUG): SyncComponent "CTD_NeilBrown" handled in the control thread.
2011-02-28T18:41:39.89560Z,1298918499.8956 [WetLabsBB2FL] Loaded
2011-02-28T18:41:39.89600Z,1298918499.896 [ComponentRegistry](DEBUG): SyncComponent "WetLabsBB2FL" handled in the control thread.
2011-02-28T18:41:39.91690Z,1298918499.9169 [Aanderaa_O2] Loaded
2011-02-28T18:41:39.91730Z,1298918499.9173 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2011-02-28T18:41:39.92800Z,1298918499.928 [ISUS] Loaded
2011-02-28T18:41:39.92840Z,1298918499.9284 [ComponentRegistry](DEBUG): SyncComponent "ISUS" handled in the control thread.
2011-02-28T18:41:39.92880Z,1298918499.9288 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2011-02-28T18:41:39.92950Z,1298918499.9295 [Module Loader](DEBUG): Loading Module at Modules/Sensor2.so
2011-02-28T18:41:40.02450Z,1298918500.0245 [AHRS_sp3003D] Loaded
2011-02-28T18:41:40.02480Z,1298918500.0248 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2011-02-28T18:41:40.02550Z,1298918500.0255 [Module Loader](DEBUG): Loaded Module: Sensor2 (Contains the sensor components)
2011-02-28T18:41:40.02850Z,1298918500.0285 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2011-02-28T18:41:40.02960Z,1298918500.0296 [ComponentRegistry](DEBUG): SyncComponent "Maintainer" handled in the control thread.
2011-02-28T18:41:40.03060Z,1298918500.0306 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2011-02-28T18:41:40.03080Z,1298918500.0308 [Supervisor](DEBUG): Running supervisor.
2011-02-28T18:41:40.03400Z,1298918500.034 [controlThread](DEBUG): Initializing ControlThread
2011-02-28T18:41:40.03520Z,1298918500.0352 [InternalSim](DEBUG):  InternalSim initializing...
2011-02-28T18:41:40.06760Z,1298918500.0676 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2011-02-28T18:41:40.09520Z,1298918500.0952 [SBIT](INFO): Initialize SBIT Component.
2011-02-28T18:41:40.09770Z,1298918500.0977 [IBIT](INFO): Initialize IBIT Component.
2011-02-28T18:41:40.10010Z,1298918500.1001 [CBIT](DEBUG): Initialize CBIT Component.
2011-02-28T18:41:40.10320Z,1298918500.1032 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2011-02-28T18:41:40.12840Z,1298918500.1284 [Bathymetry](DEBUG): Initialize Bathymetry Derivation.
2011-02-28T18:41:40.13710Z,1298918500.1371 [Bathymetry](DEBUG): Opened 
2011-02-28T18:41:40.14950Z,1298918500.1495 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2011-02-28T18:41:40.15000Z,1298918500.15 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2011-02-28T18:41:40.15040Z,1298918500.1504 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2011-02-28T18:41:40.15120Z,1298918500.1512 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2011-02-28T18:41:40.15290Z,1298918500.1529 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2011-02-28T18:41:40.15340Z,1298918500.1534 [Navigation](DEBUG): Initializing Navigation.
2011-02-28T18:41:40.15390Z,1298918500.1539 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2011-02-28T18:41:40.16960Z,1298918500.1696 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2011-02-28T18:41:40.17290Z,1298918500.1729 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2011-02-28T18:41:40.17380Z,1298918500.1738 [LoopControl](DEBUG): Initialize LoopControlComponent.
2011-02-28T18:41:42.12170Z,1298918502.1217 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2011-02-28T18:41:42.12860Z,1298918502.1286 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2011-02-28T18:41:42.14440Z,1298918502.1444 [Startup:0.GoToSurface](DEBUG): Construct GoToSurface.
2011-02-28T18:41:42.15580Z,1298918502.1558 [MissionManager](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2011-02-28T18:41:42.15910Z,1298918502.1591 [MissionManager](DEBUG): Initialize ReadDataComponent to sense platform_communications
2011-02-28T18:41:42.16170Z,1298918502.1617 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface RunIn="Progression"/>

    <Aggregate Id="StartupSatComms" >

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

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

    </Aggregate>

</Mission>


2011-02-28T18:41:42.16260Z,1298918502.1626 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2011-02-28T18:41:42.90610Z,1298918502.9061 [Default:GPS:0.SetSpeed](DEBUG): Construct.
2011-02-28T18:41:42.92160Z,1298918502.9216 [Default:GPS:1.GoToSurface](DEBUG): Construct GoToSurface.
2011-02-28T18:41:42.93200Z,1298918502.932 [MissionManager](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2011-02-28T18:41:42.93430Z,1298918502.9343 [Default:Iridium:0.SetSpeed](DEBUG): Construct.
2011-02-28T18:41:42.95010Z,1298918502.9501 [Default:Iridium:1.GoToSurface](DEBUG): Construct GoToSurface.
2011-02-28T18:41:42.96030Z,1298918502.9603 [MissionManager](DEBUG): Initialize ReadDataComponent to sense platform_communications
2011-02-28T18:41:42.96270Z,1298918502.9627 [Default:Iridium:0_Timeout:0.Execute](DEBUG): Construct Execute.
2011-02-28T18:41:42.98360Z,1298918502.9836 [Default:4.SetSpeed](DEBUG): Construct.
2011-02-28T18:41:42.99890Z,1298918502.9989 [Default:5.GoToSurface](DEBUG): Construct GoToSurface.
2011-02-28T18:41:43.00830Z,1298918503.0083 [Default:6.Wait](DEBUG): Construct Wait.
2011-02-28T18:41:43.02300Z,1298918503.023 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Default">

    <Aggregate Id="GPS" >

<!--    Run at high speed -->

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

<!--    Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!--    Get GPS fix -->

        <ReadDatum Id="Read GPS"><Universal:latitude_fix/>
        </ReadDatum>

    </Aggregate>

    <Aggregate Id="Iridium" >

<!--    Run at high speed -->

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

<!--    Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!--    Do data comms -->

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

    </Aggregate>

    <Aggregate Id="CallGPS" >

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

        <Call RefId="GPS"/>

    </Aggregate>

    <Aggregate Id="CallIridium" >

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

        <Call RefId="Iridium"/>

    </Aggregate>

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

<!-- Run at low speed -->

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

    <Guidance:GoToSurface RunIn="Parallel"/>

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

</Mission>


2011-02-28T18:41:43.02950Z,1298918503.0295 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_3DMGX3,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9601,Onboard,Radio_Freewave,CTD_NeilBrown,WetLabsBB2FL,Aanderaa_O2,ISUS,AHRS_sp3003D,Depth_Keller,Bathymetry,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintainer,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,logger,
2011-02-28T18:41:43.06040Z,1298918503.0604 [AHRS_3DMGX3](DEBUG): Initializing AHRS_3DMGX3.
2011-02-28T18:41:43.24120Z,1298918503.2412 [DVL_micro](DEBUG): Initializing DVL_micro.
2011-02-28T18:41:43.26520Z,1298918503.2652 [Radio_Freewave](INFO): Powering up
2011-02-28T18:41:43.27140Z,1298918503.2714 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2011-02-28T18:41:43.33430Z,1298918503.3343 [WetLabsBB2FL](INFO): Powering down
2011-02-28T18:41:43.41150Z,1298918503.4115 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2011-02-28T18:41:43.55690Z,1298918503.5569 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2011-02-28T18:41:43.61110Z,1298918503.6111 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2011-02-28T18:41:43.62230Z,1298918503.6223 [ElevatorServo](DEBUG): Initializing EZServoServo.
2011-02-28T18:41:43.67900Z,1298918503.679 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2011-02-28T18:41:43.68870Z,1298918503.6887 [MassServo](DEBUG): Initializing EZServoServo.
2011-02-28T18:41:43.74310Z,1298918503.7431 [MassServo](DEBUG): Initializing MassServo.
2011-02-28T18:41:43.75220Z,1298918503.7522 [RudderServo](DEBUG): Initializing EZServoServo.
2011-02-28T18:41:43.80710Z,1298918503.8071 [RudderServo](DEBUG): Initializing RudderServo.
2011-02-28T18:41:43.81650Z,1298918503.8165 [ThrusterServo](DEBUG): Initializing EZServoServo.
2011-02-28T18:41:43.87110Z,1298918503.8711 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2011-02-28T18:41:45.91100Z,1298918505.911 [NAL9601](INFO): Powering up NAL9601
2011-02-28T18:41:47.58700Z,1298918507.587 [Aanderaa_O2](INFO): Powering down
2011-02-28T18:41:55.52050Z,1298918515.5205 [SBIT](INFO): Beginning Startup BIT
2011-02-28T18:42:33.52100Z,1298918553.521 [SBIT](IMPORTANT): SBIT PASSED
2011-02-28T18:42:33.90380Z,1298918553.9038 [MissionManager](IMPORTANT): Started mission Startup
2011-02-28T18:42:33.90390Z,1298918553.9039 [Startup] Running Loop=1
2011-02-28T18:42:33.90410Z,1298918553.9041 [Startup](INFO): Aggregate::initialize Startup
2011-02-28T18:42:33.90430Z,1298918553.9043 [Startup:0.GoToSurface] Running Loop=1
2011-02-28T18:42:33.90440Z,1298918553.9044 [Startup:0.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-28T18:42:33.91140Z,1298918553.9114 [Startup:StartupSatComms] Running Loop=1
2011-02-28T18:42:33.91160Z,1298918553.9116 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2011-02-28T18:42:33.91180Z,1298918553.9118 [Startup:StartupSatComms:0] Running Loop=1
2011-02-28T18:42:51.52340Z,1298918571.5234 [NAL9601](INFO): NAL9601 initialized
2011-02-28T18:42:52.67380Z,1298918572.6738 [NAL9601](IMPORTANT): GPS fix at: 1298919378
2011-02-28T18:42:52.70900Z,1298918572.709 [Startup:StartupSatComms:0] Stopped
2011-02-28T18:42:52.70920Z,1298918572.7092 [Startup:StartupSatComms:1] Running Loop=1
2011-02-28T18:43:09.69440Z,1298918589.6944 [NAL9601](IMPORTANT): SBD MO Status=0, MOMSN=13887, MT Status=1, MTMSN=1770
2011-02-28T18:43:10.30200Z,1298918590.302 [NAL9601](INFO): Received command:run Insert/Surface.xml
2011-02-28T18:43:10.35530Z,1298918590.3553 [CommandLine](IMPORTANT): got command run ./Missions/Insert/Surface.xml
2011-02-28T18:43:10.35570Z,1298918590.3557 [MissionManager](INFO): Loading Mission: ./Missions/Insert/Surface.xml
2011-02-28T18:43:10.37620Z,1298918590.3762 [MissionManager](INFO): DefineArg IridiumTimeout = 30 min
2011-02-28T18:43:10.37760Z,1298918590.3776 [SurfaceComms:0.GoToSurface](DEBUG): Construct GoToSurface.
2011-02-28T18:43:10.39690Z,1298918590.3969 [MissionManager](DEBUG): Initialize ReadDataComponent to sense time_fix
2011-02-28T18:43:10.39990Z,1298918590.3999 [MissionManager](DEBUG): Initialize ReadDataComponent to sense platform_communications
2011-02-28T18:43:10.41580Z,1298918590.4158 [MissionManager](DEBUG): Initialize ReadDataComponent to sense time_fix
2011-02-28T18:43:10.41780Z,1298918590.4178 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Aggregate 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="SurfaceComms"
       RunIn="Sequence">

    <DefineArg Name="IridiumTimeout"><Units:minute/><Value>30</Value></DefineArg>

    <Guidance:GoToSurface RunIn="Progression"/>

    <Aggregate>

        <Preemptive><True/></Preemptive>

        <ReadDatum><Universal:time_fix/>
        </ReadDatum>

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

        <ReadDatum><Universal:time_fix/>
        </ReadDatum>

    </Aggregate>

</Aggregate>


2011-02-28T18:43:10.41840Z,1298918590.4184 [CommandLine](IMPORTANT): Running ./Missions/Insert/Surface.xml
2011-02-28T18:43:19.11530Z,1298918599.1153 [NAL9601](INFO): SBD MO Status=0, MOMSN=13888, MT Status=0, MTMSN=0
2011-02-28T18:43:19.30850Z,1298918599.3085 [Startup:StartupSatComms:1] Stopped
2011-02-28T18:43:19.30880Z,1298918599.3088 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2011-02-28T18:43:19.30890Z,1298918599.3089 [Startup:StartupSatComms] Stopped
2011-02-28T18:43:19.30910Z,1298918599.3091 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2011-02-28T18:43:19.30960Z,1298918599.3096 [Startup](INFO): Completed Startup
2011-02-28T18:43:19.30980Z,1298918599.3098 [Startup] Stopped
2011-02-28T18:43:19.30990Z,1298918599.3099 [Startup](INFO): Aggregate::uninitialize Startup
2011-02-28T18:43:19.31000Z,1298918599.31 [Startup:0.GoToSurface] Stopped
2011-02-28T18:43:19.31010Z,1298918599.3101 [Startup:0.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-28T18:43:19.55250Z,1298918599.5525 [MissionManager](IMPORTANT): Started mission SurfaceComms
2011-02-28T18:43:19.55260Z,1298918599.5526 [SurfaceComms] Running Loop=1
2011-02-28T18:43:19.55280Z,1298918599.5528 [SurfaceComms](INFO): Aggregate::initialize SurfaceComms
2011-02-28T18:43:19.55290Z,1298918599.5529 [SurfaceComms:0.GoToSurface] Running Loop=1
2011-02-28T18:43:19.55300Z,1298918599.553 [SurfaceComms:0.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-28T18:43:19.55940Z,1298918599.5594 [SurfaceComms:1] Running Loop=1
2011-02-28T18:43:19.55960Z,1298918599.5596 [SurfaceComms:1](INFO): Aggregate::initialize SurfaceComms:1
2011-02-28T18:43:19.55980Z,1298918599.5598 [SurfaceComms:1:0] Running Loop=1
2011-02-28T18:43:21.52440Z,1298918601.5244 [NAL9601](IMPORTANT): GPS fix at: 1298919407
2011-02-28T18:43:21.56450Z,1298918601.5645 [SurfaceComms:1:0] Stopped
2011-02-28T18:43:21.56480Z,1298918601.5648 [SurfaceComms:1:1] Running Loop=1
2011-02-28T18:43:36.56230Z,1298918616.5623 [NAL9601](INFO): SBD MO Status=0, MOMSN=13889, MT Status=0, MTMSN=0
2011-02-28T18:43:36.78470Z,1298918616.7847 [SurfaceComms:1:1] Stopped
2011-02-28T18:43:36.78490Z,1298918616.7849 [SurfaceComms:1:2] Running Loop=1
2011-02-28T18:43:38.96410Z,1298918618.9641 [NAL9601](IMPORTANT): GPS fix at: 1298919424
2011-02-28T18:43:39.00500Z,1298918619.005 [SurfaceComms:1:2] Stopped
2011-02-28T18:43:39.00530Z,1298918619.0053 [SurfaceComms:1](INFO): Completed SurfaceComms:1
2011-02-28T18:43:39.00540Z,1298918619.0054 [SurfaceComms:1] Stopped
2011-02-28T18:43:39.00550Z,1298918619.0055 [SurfaceComms:1](INFO): Aggregate::uninitialize SurfaceComms:1
2011-02-28T18:43:39.00620Z,1298918619.0062 [SurfaceComms](INFO): Completed SurfaceComms
2011-02-28T18:43:39.00630Z,1298918619.0063 [SurfaceComms] Stopped
2011-02-28T18:43:39.00650Z,1298918619.0065 [SurfaceComms](INFO): Aggregate::uninitialize SurfaceComms
2011-02-28T18:43:39.00660Z,1298918619.0066 [SurfaceComms:0.GoToSurface] Stopped
2011-02-28T18:43:39.00670Z,1298918619.0067 [SurfaceComms:0.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-28T18:43:39.39290Z,1298918619.3929 [MissionManager](IMPORTANT): Started mission Default
2011-02-28T18:43:39.39310Z,1298918619.3931 [Default] Running Loop=1
2011-02-28T18:43:39.39320Z,1298918619.3932 [Default](INFO): Aggregate::initialize Default
2011-02-28T18:43:39.39330Z,1298918619.3933 [Default:4.SetSpeed] Running Loop=1
2011-02-28T18:43:39.39340Z,1298918619.3934 [Default:4.SetSpeed](DEBUG): Initialize.
2011-02-28T18:43:39.39360Z,1298918619.3936 [Default:5.GoToSurface] Running Loop=1
2011-02-28T18:43:39.39370Z,1298918619.3937 [Default:5.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-28T18:43:39.39430Z,1298918619.3943 [Default:GPS] Running Loop=1
2011-02-28T18:43:39.39440Z,1298918619.3944 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-02-28T18:43:39.39460Z,1298918619.3946 [Default:GPS:0.SetSpeed] Running Loop=1
2011-02-28T18:43:39.39460Z,1298918619.3946 [Default:GPS:0.SetSpeed](DEBUG): Initialize.
2011-02-28T18:43:39.39500Z,1298918619.395 [Default:GPS:1.GoToSurface] Running Loop=1
2011-02-28T18:43:39.39510Z,1298918619.3951 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-28T18:43:39.39600Z,1298918619.396 [Default:5.GoToSurface] Running Loop=1
2011-02-28T18:43:39.40180Z,1298918619.4018 [Default:4.SetSpeed] Running Loop=1
2011-02-28T18:43:39.41610Z,1298918619.4161 [Default:GPS:1.GoToSurface] Stopped
2011-02-28T18:43:39.41620Z,1298918619.4162 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-28T18:43:39.41640Z,1298918619.4164 [Default:GPS:Read GPS] Running Loop=1
2011-02-28T18:43:39.41650Z,1298918619.4165 [Default:GPS:0.SetSpeed] Running Loop=1
2011-02-28T18:43:40.96400Z,1298918620.964 [NAL9601](IMPORTANT): GPS fix at: 1298919426
2011-02-28T18:43:41.00570Z,1298918621.0057 [Default:GPS:Read GPS] Stopped
2011-02-28T18:43:41.00620Z,1298918621.0062 [Default:GPS](INFO): Completed Default:GPS
2011-02-28T18:43:41.00630Z,1298918621.0063 [Default:GPS] Stopped
2011-02-28T18:43:41.00650Z,1298918621.0065 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-02-28T18:43:41.00660Z,1298918621.0066 [Default:GPS:0.SetSpeed] Stopped
2011-02-28T18:43:41.00670Z,1298918621.0067 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize.
2011-02-28T18:43:41.00690Z,1298918621.0069 [Default:Iridium] Running Loop=1
2011-02-28T18:43:41.00710Z,1298918621.0071 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-02-28T18:43:41.00720Z,1298918621.0072 [Default:Iridium:0.SetSpeed] Running Loop=1
2011-02-28T18:43:41.00730Z,1298918621.0073 [Default:Iridium:0.SetSpeed](DEBUG): Initialize.
2011-02-28T18:43:41.00760Z,1298918621.0076 [Default:Iridium:1.GoToSurface] Running Loop=1
2011-02-28T18:43:41.00770Z,1298918621.0077 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-28T18:43:41.39930Z,1298918621.3993 [Default:Iridium:1.GoToSurface] Stopped
2011-02-28T18:43:41.39940Z,1298918621.3994 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-28T18:43:41.39960Z,1298918621.3996 [Default:Iridium:Read Iridium] Running Loop=1
2011-02-28T18:43:41.39970Z,1298918621.3997 [Default:Iridium:0.SetSpeed] Running Loop=1
2011-02-28T18:44:03.58220Z,1298918643.5822 [NAL9601](INFO): SBD MO Status=2, MOMSN=13890, MT Status=2, MTMSN=0
2011-02-28T18:44:03.58240Z,1298918643.5824 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-28T18:44:08.59690Z,1298918648.5969 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T18:44:30.81920Z,1298918670.8192 [NAL9601](INFO): SBD MO Status=2, MOMSN=13890, MT Status=2, MTMSN=0
2011-02-28T18:44:30.81950Z,1298918670.8195 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-28T18:44:35.86080Z,1298918675.8608 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T18:44:38.49650Z,1298918678.4965 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T18:44:42.69680Z,1298918682.6968 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T18:44:46.56640Z,1298918686.5664 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T18:45:07.14210Z,1298918707.1421 [NAL9601](INFO): SBD MO Status=0, MOMSN=13890, MT Status=0, MTMSN=0
2011-02-28T18:45:07.34180Z,1298918707.3418 [Default:Iridium:Read Iridium] Stopped
2011-02-28T18:45:07.34250Z,1298918707.3425 [Default:Iridium](INFO): Completed Default:Iridium
2011-02-28T18:45:07.34260Z,1298918707.3426 [Default:Iridium] Stopped
2011-02-28T18:45:07.34280Z,1298918707.3428 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-02-28T18:45:07.34290Z,1298918707.3429 [Default:Iridium:0.SetSpeed] Stopped
2011-02-28T18:45:07.34300Z,1298918707.343 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize.
2011-02-28T18:45:07.34320Z,1298918707.3432 [Default:6.Wait] Running Loop=1
2011-02-28T18:45:07.34330Z,1298918707.3433 [Default:6.Wait](DEBUG): Initialize Wait Component.
2011-02-28T18:45:17.68740Z,1298918717.6874 [NAL9601](INFO): Powering down
2011-02-28T18:48:42.68950Z,1298918922.6895 [Default:CallGPS] Running Loop=1
2011-02-28T18:48:42.68970Z,1298918922.6897 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-02-28T18:48:42.69000Z,1298918922.69 [Default:CallGPS:0] Running Loop=1
2011-02-28T18:48:42.69020Z,1298918922.6902 [Default:CallGPS:0](INFO): Aggregate::initialize Default:CallGPS:0
2011-02-28T18:48:47.74420Z,1298918927.7442 [Default:GPS] Running Loop=1
2011-02-28T18:48:47.74440Z,1298918927.7444 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-02-28T18:48:47.74450Z,1298918927.7445 [Default:GPS:0.SetSpeed] Running Loop=1
2011-02-28T18:48:47.74460Z,1298918927.7446 [Default:GPS:0.SetSpeed](DEBUG): Initialize.
2011-02-28T18:48:47.74490Z,1298918927.7449 [Default:GPS:1.GoToSurface] Running Loop=1
2011-02-28T18:48:47.74500Z,1298918927.745 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-28T18:48:47.74570Z,1298918927.7457 [Default:GPS:1.GoToSurface] Stopped
2011-02-28T18:48:47.74580Z,1298918927.7458 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-28T18:48:47.74600Z,1298918927.746 [Default:GPS:Read GPS] Running Loop=1
2011-02-28T18:48:48.36590Z,1298918928.3659 [NAL9601](INFO): Powering up
2011-02-28T18:49:54.17940Z,1298918994.1794 [NAL9601](INFO): NAL9601 initialized
2011-02-28T18:50:07.60550Z,1298919007.6055 [Default:CallIridium] Running Loop=1
2011-02-28T18:50:07.60570Z,1298919007.6057 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-02-28T18:50:07.60600Z,1298919007.606 [Default:CallIridium:0] Running Loop=1
2011-02-28T18:50:07.60620Z,1298919007.6062 [Default:CallIridium:0](INFO): Aggregate::initialize Default:CallIridium:0
2011-02-28T18:50:08.01330Z,1298919008.0133 [Default:Iridium] Running Loop=1
2011-02-28T18:50:08.01350Z,1298919008.0135 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-02-28T18:50:08.01360Z,1298919008.0136 [Default:Iridium:0.SetSpeed] Running Loop=1
2011-02-28T18:50:08.01370Z,1298919008.0137 [Default:Iridium:0.SetSpeed](DEBUG): Initialize.
2011-02-28T18:50:08.01400Z,1298919008.014 [Default:Iridium:1.GoToSurface] Running Loop=1
2011-02-28T18:50:08.01410Z,1298919008.0141 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-28T18:50:08.01500Z,1298919008.015 [Default:Iridium:1.GoToSurface] Stopped
2011-02-28T18:50:08.01510Z,1298919008.0151 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-28T18:50:08.01530Z,1298919008.0153 [Default:Iridium:Read Iridium] Running Loop=1
2011-02-28T18:50:30.20230Z,1298919030.2023 [NAL9601](INFO): SBD MO Status=0, MOMSN=13891, MT Status=0, MTMSN=0
2011-02-28T18:50:30.45360Z,1298919030.4536 [Default:Iridium:Read Iridium] Stopped
2011-02-28T18:50:30.45420Z,1298919030.4542 [Default:Iridium](INFO): Completed Default:Iridium
2011-02-28T18:50:30.45430Z,1298919030.4543 [Default:Iridium] Stopped
2011-02-28T18:50:30.45450Z,1298919030.4545 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-02-28T18:50:30.45460Z,1298919030.4546 [Default:Iridium:0.SetSpeed] Stopped
2011-02-28T18:50:30.45470Z,1298919030.4547 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize.
2011-02-28T18:50:30.63360Z,1298919030.6336 [Default:CallIridium:0](INFO): Completed Default:CallIridium:0
2011-02-28T18:50:30.63370Z,1298919030.6337 [Default:CallIridium:0] Stopped
2011-02-28T18:50:30.63390Z,1298919030.6339 [Default:CallIridium:0](INFO): Aggregate::uninitialize Default:CallIridium:0
2011-02-28T18:50:30.63410Z,1298919030.6341 [Default:CallIridium](INFO): Completed Default:CallIridium
2011-02-28T18:50:30.63420Z,1298919030.6342 [Default:CallIridium] Stopped
2011-02-28T18:50:30.63440Z,1298919030.6344 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-02-28T18:50:37.40670Z,1298919037.4067 [NAL9601](IMPORTANT): GPS fix at: 1298919843
2011-02-28T18:50:37.44970Z,1298919037.4497 [Default:GPS:Read GPS] Stopped
2011-02-28T18:50:37.45030Z,1298919037.4503 [Default:GPS](INFO): Completed Default:GPS
2011-02-28T18:50:37.45040Z,1298919037.4504 [Default:GPS] Stopped
2011-02-28T18:50:37.45050Z,1298919037.4505 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-02-28T18:50:37.45060Z,1298919037.4506 [Default:GPS:0.SetSpeed] Stopped
2011-02-28T18:50:37.45070Z,1298919037.4507 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize.
2011-02-28T18:50:37.83400Z,1298919037.834 [Default:CallGPS:0](INFO): Completed Default:CallGPS:0
2011-02-28T18:50:37.83410Z,1298919037.8341 [Default:CallGPS:0] Stopped
2011-02-28T18:50:37.83430Z,1298919037.8343 [Default:CallGPS:0](INFO): Aggregate::uninitialize Default:CallGPS:0
2011-02-28T18:50:37.83450Z,1298919037.8345 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-02-28T18:50:37.83460Z,1298919037.8346 [Default:CallGPS] Stopped
2011-02-28T18:50:37.83500Z,1298919037.835 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-02-28T18:50:57.92950Z,1298919057.9295 [NAL9601](INFO): Powering down
2011-02-28T18:55:32.96950Z,1298919332.9695 [Default:CallIridium] Running Loop=1
2011-02-28T18:55:32.96970Z,1298919332.9697 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-02-28T18:55:32.96990Z,1298919332.9699 [Default:CallIridium:0] Running Loop=1
2011-02-28T18:55:32.97000Z,1298919332.97 [Default:CallIridium:0](INFO): Aggregate::initialize Default:CallIridium:0
2011-02-28T18:55:37.91750Z,1298919337.9175 [Default:CallGPS] Running Loop=1
2011-02-28T18:55:37.91770Z,1298919337.9177 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-02-28T18:55:37.91790Z,1298919337.9179 [Default:CallGPS:0] Running Loop=1
2011-02-28T18:55:37.91810Z,1298919337.9181 [Default:CallGPS:0](INFO): Aggregate::initialize Default:CallGPS:0
2011-02-28T18:55:37.91830Z,1298919337.9183 [Default:Iridium] Running Loop=1
2011-02-28T18:55:37.91840Z,1298919337.9184 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-02-28T18:55:37.91850Z,1298919337.9185 [Default:Iridium:0.SetSpeed] Running Loop=1
2011-02-28T18:55:37.91860Z,1298919337.9186 [Default:Iridium:0.SetSpeed](DEBUG): Initialize.
2011-02-28T18:55:37.91890Z,1298919337.9189 [Default:Iridium:1.GoToSurface] Running Loop=1
2011-02-28T18:55:37.91900Z,1298919337.919 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-28T18:55:37.91990Z,1298919337.9199 [Default:Iridium:1.GoToSurface] Stopped
2011-02-28T18:55:37.92000Z,1298919337.92 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-28T18:55:37.92020Z,1298919337.9202 [Default:Iridium:Read Iridium] Running Loop=1
2011-02-28T18:55:38.23450Z,1298919338.2345 [Default:GPS] Running Loop=1
2011-02-28T18:55:38.23470Z,1298919338.2347 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-02-28T18:55:38.23490Z,1298919338.2349 [Default:GPS:0.SetSpeed] Running Loop=1
2011-02-28T18:55:38.23500Z,1298919338.235 [Default:GPS:0.SetSpeed](DEBUG): Initialize.
2011-02-28T18:55:38.23530Z,1298919338.2353 [Default:GPS:1.GoToSurface] Running Loop=1
2011-02-28T18:55:38.23540Z,1298919338.2354 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-28T18:55:38.23620Z,1298919338.2362 [Default:GPS:1.GoToSurface] Stopped
2011-02-28T18:55:38.23630Z,1298919338.2363 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-28T18:55:38.23650Z,1298919338.2365 [Default:GPS:Read GPS] Running Loop=1
2011-02-28T18:55:38.62460Z,1298919338.6246 [NAL9601](INFO): Powering up
2011-02-28T18:56:44.43540Z,1298919404.4354 [NAL9601](INFO): NAL9601 initialized
2011-02-28T18:56:49.20880Z,1298919409.2088 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T18:56:50.41230Z,1298919410.4123 [NAL9601](IMPORTANT): GPS fix at: 1298920217
2011-02-28T18:56:50.45420Z,1298919410.4542 [Default:GPS:Read GPS] Stopped
2011-02-28T18:56:50.45480Z,1298919410.4548 [Default:GPS](INFO): Completed Default:GPS
2011-02-28T18:56:50.45490Z,1298919410.4549 [Default:GPS] Stopped
2011-02-28T18:56:50.45500Z,1298919410.455 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-02-28T18:56:50.45510Z,1298919410.4551 [Default:GPS:0.SetSpeed] Stopped
2011-02-28T18:56:50.45520Z,1298919410.4552 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize.
2011-02-28T18:56:50.90160Z,1298919410.9016 [Default:CallGPS:0](INFO): Completed Default:CallGPS:0
2011-02-28T18:56:50.90170Z,1298919410.9017 [Default:CallGPS:0] Stopped
2011-02-28T18:56:50.90190Z,1298919410.9019 [Default:CallGPS:0](INFO): Aggregate::uninitialize Default:CallGPS:0
2011-02-28T18:56:50.90210Z,1298919410.9021 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-02-28T18:56:50.90220Z,1298919410.9022 [Default:CallGPS] Stopped
2011-02-28T18:56:50.90230Z,1298919410.9023 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-02-28T18:57:05.43410Z,1298919425.4341 [NAL9601](INFO): SBD MO Status=2, MOMSN=13892, MT Status=2, MTMSN=0
2011-02-28T18:57:05.43440Z,1298919425.4344 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-28T18:57:22.89720Z,1298919442.8972 [NAL9601](INFO): SBD MO Status=2, MOMSN=13892, MT Status=2, MTMSN=0
2011-02-28T18:57:22.89740Z,1298919442.8974 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-28T18:57:27.48880Z,1298919447.4888 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T18:57:36.90890Z,1298919456.9089 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T18:57:39.94480Z,1298919459.9448 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T18:57:44.15680Z,1298919464.1568 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T18:58:32.01420Z,1298919512.0142 [NAL9601](INFO): SBD MO Status=2, MOMSN=13892, MT Status=2, MTMSN=0
2011-02-28T18:58:32.01450Z,1298919512.0145 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-28T18:58:48.63420Z,1298919528.6342 [NAL9601](INFO): SBD MO Status=2, MOMSN=13892, MT Status=2, MTMSN=0
2011-02-28T18:58:48.63450Z,1298919528.6345 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-28T18:59:05.64330Z,1298919545.6433 [NAL9601](INFO): SBD MO Status=2, MOMSN=13892, MT Status=2, MTMSN=0
2011-02-28T18:59:05.64350Z,1298919545.6435 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-28T18:59:23.07270Z,1298919563.0727 [NAL9601](INFO): SBD MO Status=2, MOMSN=13892, MT Status=2, MTMSN=0
2011-02-28T18:59:23.07300Z,1298919563.073 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-28T18:59:40.53340Z,1298919580.5334 [NAL9601](IMPORTANT): SBD MO Status=0, MOMSN=13892, MT Status=1, MTMSN=1771
2011-02-28T18:59:41.20400Z,1298919581.204 [NAL9601](IMPORTANT): Initialized file: Config/lrauv-tethys/vehicle.cfg
2011-02-28T18:59:41.20540Z,1298919581.2054 [NAL9601](IMPORTANT): More data left to go, at position 74
2011-02-28T18:59:55.19850Z,1298919595.1985 [NAL9601](IMPORTANT): SBD MO Status=0, MOMSN=13893, MT Status=1, MTMSN=1772
2011-02-28T18:59:55.77230Z,1298919595.7723 [NAL9601](IMPORTANT): Added data to file: Config/lrauv-tethys/vehicle.cfg
2011-02-28T18:59:58.00350Z,1298919598.0035 [NAL9601](IMPORTANT): Success executing cat Logs/latest/4D6BF2A1.part | gunzip -f -d | cat `cp Config/lrauv-tethys/.svn/text-base/vehicle.cfg.svn-base Config/lrauv-tethys/vehicle.cfg` | vim -e Config/lrauv-tethys/vehicle.cfg
2011-02-28T18:59:58.06210Z,1298919598.0621 [CommandLine](IMPORTANT): 2beb2c32dd89482b95e4e44d86e50284  Config/lrauv-tethys/vehicle.cfg

2011-02-28T19:00:06.05020Z,1298919606.0502 [NAL9601](INFO): SBD MO Status=0, MOMSN=13894, MT Status=0, MTMSN=0
2011-02-28T19:00:06.25930Z,1298919606.2593 [Default:Iridium:Read Iridium] Stopped
2011-02-28T19:00:06.25990Z,1298919606.2599 [Default:Iridium](INFO): Completed Default:Iridium
2011-02-28T19:00:06.26010Z,1298919606.2601 [Default:Iridium] Stopped
2011-02-28T19:00:06.26020Z,1298919606.2602 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-02-28T19:00:06.26030Z,1298919606.2603 [Default:Iridium:0.SetSpeed] Stopped
2011-02-28T19:00:06.26040Z,1298919606.2604 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize.
2011-02-28T19:00:06.48960Z,1298919606.4896 [Default:CallIridium:0](INFO): Completed Default:CallIridium:0
2011-02-28T19:00:06.48970Z,1298919606.4897 [Default:CallIridium:0] Stopped
2011-02-28T19:00:06.48980Z,1298919606.4898 [Default:CallIridium:0](INFO): Aggregate::uninitialize Default:CallIridium:0
2011-02-28T19:00:06.49010Z,1298919606.4901 [Default:CallIridium](INFO): Completed Default:CallIridium
2011-02-28T19:00:06.49020Z,1298919606.4902 [Default:CallIridium] Stopped
2011-02-28T19:00:06.49030Z,1298919606.4903 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-02-28T19:00:16.57760Z,1298919616.5776 [NAL9601](INFO): Powering down
2011-02-28T19:01:51.61730Z,1298919711.6173 [Default:CallGPS] Running Loop=1
2011-02-28T19:01:51.61750Z,1298919711.6175 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-02-28T19:01:51.61770Z,1298919711.6177 [Default:CallGPS:0] Running Loop=1
2011-02-28T19:01:51.61780Z,1298919711.6178 [Default:CallGPS:0](INFO): Aggregate::initialize Default:CallGPS:0
2011-02-28T19:01:56.50910Z,1298919716.5091 [Default:GPS] Running Loop=1
2011-02-28T19:01:56.50930Z,1298919716.5093 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-02-28T19:01:56.50940Z,1298919716.5094 [Default:GPS:0.SetSpeed] Running Loop=1
2011-02-28T19:01:56.50950Z,1298919716.5095 [Default:GPS:0.SetSpeed](DEBUG): Initialize.
2011-02-28T19:01:56.50990Z,1298919716.5099 [Default:GPS:1.GoToSurface] Running Loop=1
2011-02-28T19:01:56.51000Z,1298919716.51 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-28T19:01:56.51080Z,1298919716.5108 [Default:GPS:1.GoToSurface] Stopped
2011-02-28T19:01:56.51090Z,1298919716.5109 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-28T19:01:56.51110Z,1298919716.5111 [Default:GPS:Read GPS] Running Loop=1
2011-02-28T19:01:57.26770Z,1298919717.2677 [NAL9601](INFO): Powering up
2011-02-28T19:03:02.87940Z,1298919782.8794 [NAL9601](INFO): NAL9601 initialized
2011-02-28T19:03:04.05240Z,1298919784.0524 [NAL9601](IMPORTANT): GPS fix at: 1298920591
2011-02-28T19:03:04.09790Z,1298919784.0979 [Default:GPS:Read GPS] Stopped
2011-02-28T19:03:04.09840Z,1298919784.0984 [Default:GPS](INFO): Completed Default:GPS
2011-02-28T19:03:04.09850Z,1298919784.0985 [Default:GPS] Stopped
2011-02-28T19:03:04.09870Z,1298919784.0987 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-02-28T19:03:04.09880Z,1298919784.0988 [Default:GPS:0.SetSpeed] Stopped
2011-02-28T19:03:04.09890Z,1298919784.0989 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize.
2011-02-28T19:03:04.48190Z,1298919784.4819 [Default:CallGPS:0](INFO): Completed Default:CallGPS:0
2011-02-28T19:03:04.48200Z,1298919784.482 [Default:CallGPS:0] Stopped
2011-02-28T19:03:04.48220Z,1298919784.4822 [Default:CallGPS:0](INFO): Aggregate::uninitialize Default:CallGPS:0
2011-02-28T19:03:04.48240Z,1298919784.4824 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-02-28T19:03:04.48250Z,1298919784.4825 [Default:CallGPS] Stopped
2011-02-28T19:03:04.48260Z,1298919784.4826 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-02-28T19:03:24.52250Z,1298919804.5225 [NAL9601](INFO): Powering down
2011-02-28T19:05:09.61760Z,1298919909.6176 [Default:CallIridium] Running Loop=1
2011-02-28T19:05:09.61780Z,1298919909.6178 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-02-28T19:05:09.61800Z,1298919909.618 [Default:CallIridium:0] Running Loop=1
2011-02-28T19:05:09.61820Z,1298919909.6182 [Default:CallIridium:0](INFO): Aggregate::initialize Default:CallIridium:0
2011-02-28T19:05:14.50940Z,1298919914.5094 [Default:Iridium] Running Loop=1
2011-02-28T19:05:14.50960Z,1298919914.5096 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-02-28T19:05:14.50970Z,1298919914.5097 [Default:Iridium:0.SetSpeed] Running Loop=1
2011-02-28T19:05:14.50980Z,1298919914.5098 [Default:Iridium:0.SetSpeed](DEBUG): Initialize.
2011-02-28T19:05:14.51000Z,1298919914.51 [Default:Iridium:1.GoToSurface] Running Loop=1
2011-02-28T19:05:14.51010Z,1298919914.5101 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-28T19:05:14.51100Z,1298919914.511 [Default:Iridium:1.GoToSurface] Stopped
2011-02-28T19:05:14.51110Z,1298919914.5111 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-28T19:05:14.51120Z,1298919914.5112 [Default:Iridium:Read Iridium] Running Loop=1
2011-02-28T19:05:15.24240Z,1298919915.2424 [NAL9601](INFO): Powering up
2011-02-28T19:06:21.15160Z,1298919981.1516 [NAL9601](INFO): NAL9601 initialized
2011-02-28T19:06:42.68280Z,1298920002.6828 [NAL9601](INFO): SBD MO Status=2, MOMSN=13895, MT Status=2, MTMSN=0
2011-02-28T19:06:42.68300Z,1298920002.683 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-28T19:06:47.72880Z,1298920007.7288 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T19:06:51.15690Z,1298920011.1569 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T19:06:59.76940Z,1298920019.7694 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T19:07:05.64080Z,1298920025.6408 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T19:07:08.26500Z,1298920028.265 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T19:07:12.97940Z,1298920032.9794 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T19:07:17.28130Z,1298920037.2813 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T19:07:19.57400Z,1298920039.574 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T19:07:31.37810Z,1298920051.3781 [NAL9601](INFO): SBD MO Status=2, MOMSN=13895, MT Status=2, MTMSN=0
2011-02-28T19:07:31.37840Z,1298920051.3784 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-28T19:07:36.41280Z,1298920056.4128 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-28T19:07:54.64630Z,1298920074.6463 [NAL9601](IMPORTANT): SBD MO Status=0, MOMSN=13895, MT Status=1, MTMSN=1773
2011-02-28T19:07:55.20920Z,1298920075.2092 [NAL9601](INFO): Received command:restart

2011-02-28T19:07:55.21040Z,1298920075.2104 [CommandLine](IMPORTANT): got command restart
2011-02-28T19:07:55.21090Z,1298920075.2109 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2011-02-28T19:07:55.40530Z,1298920075.4053 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2011-02-28T19:07:55.54870Z,1298920075.5487 [controlThread](DEBUG): Uninitializing ControlThread
2011-02-28T19:07:55.54930Z,1298920075.5493 [AHRS_3DMGX3](INFO): Powering down
2011-02-28T19:07:55.55060Z,1298920075.5506 [DVL_micro](INFO): Powering down
2011-02-28T19:07:55.55120Z,1298920075.5512 [NAL9601](INFO): Powering down
2011-02-28T19:07:55.55220Z,1298920075.5522 [CTD_NeilBrown](INFO): Powering down
2011-02-28T19:07:55.55260Z,1298920075.5526 [WetLabsBB2FL](INFO): Powering down
2011-02-28T19:07:55.55300Z,1298920075.553 [Aanderaa_O2](INFO): Powering down
2011-02-28T19:07:55.55380Z,1298920075.5538 [AHRS_sp3003D](INFO): Powering down
2011-02-28T19:07:55.63950Z,1298920075.6395 [Bathymetry](DEBUG): Uninitialize Bathymetry Derivation.
2011-02-28T19:07:55.64160Z,1298920075.6416 [Default] Stopped
2011-02-28T19:07:55.64180Z,1298920075.6418 [Default](INFO): Aggregate::uninitialize Default
2011-02-28T19:07:55.64190Z,1298920075.6419 [Default:Iridium] Stopped
2011-02-28T19:07:55.64210Z,1298920075.6421 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-02-28T19:07:55.64220Z,1298920075.6422 [Default:Iridium:0.SetSpeed] Stopped
2011-02-28T19:07:55.64220Z,1298920075.6422 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize.
2011-02-28T19:07:55.64230Z,1298920075.6423 [Default:Iridium:Read Iridium] Stopped
2011-02-28T19:07:55.64240Z,1298920075.6424 [Default:CallIridium] Stopped
2011-02-28T19:07:55.64260Z,1298920075.6426 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-02-28T19:07:55.64270Z,1298920075.6427 [Default:CallIridium:0] Stopped
2011-02-28T19:07:55.64290Z,1298920075.6429 [Default:CallIridium:0](INFO): Aggregate::uninitialize Default:CallIridium:0
2011-02-28T19:07:55.64300Z,1298920075.643 [Default:4.SetSpeed] Stopped
2011-02-28T19:07:55.64310Z,1298920075.6431 [Default:4.SetSpeed](DEBUG): Uninitialize.
2011-02-28T19:07:55.64320Z,1298920075.6432 [Default:5.GoToSurface] Stopped
2011-02-28T19:07:55.64320Z,1298920075.6432 [Default:5.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-28T19:07:55.64330Z,1298920075.6433 [Default:6.Wait] Stopped
2011-02-28T19:07:55.64340Z,1298920075.6434 [Default:6.Wait](DEBUG): Uninitialize Wait Component.
2011-02-28T19:07:55.64860Z,1298920075.6486 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2011-02-28T19:07:55.64900Z,1298920075.649 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2011-02-28T19:07:55.64930Z,1298920075.6493 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2011-02-28T19:07:55.64960Z,1298920075.6496 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2011-02-28T19:07:55.65010Z,1298920075.6501 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2011-02-28T19:07:55.65040Z,1298920075.6504 [BuoyancyServo](INFO): Powering down
2011-02-28T19:07:55.65120Z,1298920075.6512 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2011-02-28T19:07:55.65140Z,1298920075.6514 [ElevatorServo](INFO): Powering down
2011-02-28T19:07:55.65180Z,1298920075.6518 [MassServo](DEBUG): Uninitialize Mass Servo.
2011-02-28T19:07:55.65190Z,1298920075.6519 [MassServo](INFO): Powering down
2011-02-28T19:07:55.65230Z,1298920075.6523 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2011-02-28T19:07:55.65240Z,1298920075.6524 [RudderServo](INFO): Powering down
2011-02-28T19:07:55.65280Z,1298920075.6528 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2011-02-28T19:07:55.65290Z,1298920075.6529 [ThrusterServo](INFO): Powering down
2011-02-28T19:07:55.65330Z,1298920075.6533 [SBIT](DEBUG): Uninitialize SBIT Component.
2011-02-28T19:07:55.65360Z,1298920075.6536 [IBIT](DEBUG): Uninitialize IBIT Component.
2011-02-28T19:07:55.65400Z,1298920075.654 [CBIT](DEBUG): Uninitialize CBIT Component.