2011-02-22T18:37:31.64530Z,1298399851.6453 [Supervisor](DEBUG): Initializing supervisor.
2011-02-22T18:37:31.64840Z,1298399851.6484 [SyncHandler](DEBUG): Created PCaller Thread at 1077007584
2011-02-22T18:37:31.64920Z,1298399851.6492 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2011-02-22T18:37:31.65040Z,1298399851.6504 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 1077073120
2011-02-22T18:37:31.65150Z,1298399851.6515 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2011-02-22T18:37:31.66220Z,1298399851.6622 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2011-02-22T18:37:31.66340Z,1298399851.6634 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 1077138656
2011-02-22T18:37:31.66390Z,1298399851.6639 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2011-02-22T18:37:31.66440Z,1298399851.6644 [Supervisor](INFO): Looking for Config files in directory: Config/
2011-02-22T18:37:31.66560Z,1298399851.6656 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2011-02-22T18:37:32.23690Z,1298399852.2369 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2011-02-22T18:37:32.23760Z,1298399852.2376 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2011-02-22T18:37:32.42600Z,1298399852.426 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2011-02-22T18:37:32.42660Z,1298399852.4266 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2011-02-22T18:37:32.51300Z,1298399852.513 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2011-02-22T18:37:32.51360Z,1298399852.5136 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2011-02-22T18:37:32.68980Z,1298399852.6898 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2011-02-22T18:37:32.69030Z,1298399852.6903 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2011-02-22T18:37:32.78500Z,1298399852.785 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2011-02-22T18:37:32.78560Z,1298399852.7856 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2011-02-22T18:37:33.11600Z,1298399853.116 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2011-02-22T18:37:33.11650Z,1298399853.1165 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2011-02-22T18:37:33.27380Z,1298399853.2738 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2011-02-22T18:37:33.27440Z,1298399853.2744 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2011-02-22T18:37:33.36940Z,1298399853.3694 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2011-02-22T18:37:33.37000Z,1298399853.37 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2011-02-22T18:37:33.46980Z,1298399853.4698 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2011-02-22T18:37:33.47040Z,1298399853.4704 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2011-02-22T18:37:33.81570Z,1298399853.8157 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2011-02-22T18:37:33.81640Z,1298399853.8164 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2011-02-22T18:37:33.93420Z,1298399853.9342 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2011-02-22T18:37:33.93500Z,1298399853.935 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2011-02-22T18:37:34.02070Z,1298399854.0207 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-tethys/
2011-02-22T18:37:34.02160Z,1298399854.0216 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/vehicle.cfg
2011-02-22T18:37:34.11520Z,1298399854.1152 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/vehicle"
2011-02-22T18:37:34.11580Z,1298399854.1158 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Sensor.cfg
2011-02-22T18:37:34.24030Z,1298399854.2403 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Sensor"
2011-02-22T18:37:34.24090Z,1298399854.2409 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/BIT.cfg
2011-02-22T18:37:34.33080Z,1298399854.3308 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/BIT"
2011-02-22T18:37:34.33130Z,1298399854.3313 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Servo.cfg
2011-02-22T18:37:34.42830Z,1298399854.4283 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Servo"
2011-02-22T18:37:34.42890Z,1298399854.4289 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Science.cfg
2011-02-22T18:37:34.52190Z,1298399854.5219 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Science"
2011-02-22T18:37:34.52250Z,1298399854.5225 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/workSite.cfg
2011-02-22T18:37:34.61220Z,1298399854.6122 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/workSite"
2011-02-22T18:37:34.61280Z,1298399854.6128 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Simulator.cfg
2011-02-22T18:37:34.69850Z,1298399854.6985 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Simulator"
2011-02-22T18:37:34.69910Z,1298399854.6991 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Derivation.cfg
2011-02-22T18:37:34.78520Z,1298399854.7852 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Derivation"
2011-02-22T18:37:34.78680Z,1298399854.7868 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-tethys//
2011-02-22T18:37:34.78760Z,1298399854.7876 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//vehicle.cfg
2011-02-22T18:37:39.09670Z,1298399859.0967 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/vehicle"
2011-02-22T18:37:39.09730Z,1298399859.0973 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//Sensor.cfg
2011-02-22T18:37:39.21240Z,1298399859.2124 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Sensor"
2011-02-22T18:37:39.21300Z,1298399859.213 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//BIT.cfg
2011-02-22T18:37:39.30160Z,1298399859.3016 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/BIT"
2011-02-22T18:37:39.30210Z,1298399859.3021 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//Servo.cfg
2011-02-22T18:37:40.37700Z,1298399860.377 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Servo"
2011-02-22T18:37:40.37760Z,1298399860.3776 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//Science.cfg
2011-02-22T18:37:40.46950Z,1298399860.4695 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Science"
2011-02-22T18:37:40.47000Z,1298399860.47 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//workSite.cfg
2011-02-22T18:37:40.55720Z,1298399860.5572 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/workSite"
2011-02-22T18:37:40.55770Z,1298399860.5577 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//Simulator.cfg
2011-02-22T18:37:40.64330Z,1298399860.6433 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Simulator"
2011-02-22T18:37:40.64390Z,1298399860.6439 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//Derivation.cfg
2011-02-22T18:37:41.14750Z,1298399861.1475 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Derivation"
2011-02-22T18:37:41.16620Z,1298399861.1662 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2011-02-22T18:37:41.26400Z,1298399861.264 [InternalSim] Loaded
2011-02-22T18:37:41.26430Z,1298399861.2643 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2011-02-22T18:37:41.26520Z,1298399861.2652 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2011-02-22T18:37:41.26580Z,1298399861.2658 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2011-02-22T18:37:41.27900Z,1298399861.279 [SBIT](DEBUG): Construct Startup Built In Test.
2011-02-22T18:37:41.31120Z,1298399861.3112 [SBIT] Loaded
2011-02-22T18:37:41.31150Z,1298399861.3115 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2011-02-22T18:37:41.31260Z,1298399861.3126 [IBIT](DEBUG): Construct Initiated Built In Test.
2011-02-22T18:37:41.34540Z,1298399861.3454 [IBIT] Loaded
2011-02-22T18:37:41.34570Z,1298399861.3457 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2011-02-22T18:37:41.34690Z,1298399861.3469 [CBIT](DEBUG): Construct CBIT Built In Test.
2011-02-22T18:37:41.37710Z,1298399861.3771 [CBIT] Loaded
2011-02-22T18:37:41.37740Z,1298399861.3774 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2011-02-22T18:37:41.37790Z,1298399861.3779 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2011-02-22T18:37:41.37850Z,1298399861.3785 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2011-02-22T18:37:41.47860Z,1298399861.4786 [BuoyancyServo] Loaded
2011-02-22T18:37:41.47890Z,1298399861.4789 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2011-02-22T18:37:41.48710Z,1298399861.4871 [ElevatorServo] Loaded
2011-02-22T18:37:41.48740Z,1298399861.4874 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2011-02-22T18:37:41.49540Z,1298399861.4954 [MassServo] Loaded
2011-02-22T18:37:41.49570Z,1298399861.4957 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2011-02-22T18:37:41.50360Z,1298399861.5036 [RudderServo] Loaded
2011-02-22T18:37:41.50390Z,1298399861.5039 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2011-02-22T18:37:41.51180Z,1298399861.5118 [ThrusterServo] Loaded
2011-02-22T18:37:41.51210Z,1298399861.5121 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2011-02-22T18:37:41.51260Z,1298399861.5126 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2011-02-22T18:37:41.51320Z,1298399861.5132 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2011-02-22T18:37:41.53720Z,1298399861.5372 [Bathymetry] Loaded
2011-02-22T18:37:41.53760Z,1298399861.5376 [ComponentRegistry](DEBUG): SyncComponent "Bathymetry" handled in the control thread.
2011-02-22T18:37:41.54450Z,1298399861.5445 [DepthRateCalculator] Loaded
2011-02-22T18:37:41.54480Z,1298399861.5448 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2011-02-22T18:37:41.55180Z,1298399861.5518 [PitchRateCalculator] Loaded
2011-02-22T18:37:41.55220Z,1298399861.5522 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2011-02-22T18:37:41.55900Z,1298399861.559 [SpeedCalculator] Loaded
2011-02-22T18:37:41.55930Z,1298399861.5593 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2011-02-22T18:37:41.57640Z,1298399861.5764 [TempGradientCalculator] Loaded
2011-02-22T18:37:41.57680Z,1298399861.5768 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2011-02-22T18:37:41.58420Z,1298399861.5842 [YawRateCalculator] Loaded
2011-02-22T18:37:41.58450Z,1298399861.5845 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2011-02-22T18:37:41.62200Z,1298399861.622 [Navigation] Loaded
2011-02-22T18:37:41.62230Z,1298399861.6223 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2011-02-22T18:37:41.62290Z,1298399861.6229 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2011-02-22T18:37:41.62350Z,1298399861.6235 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2011-02-22T18:37:41.67460Z,1298399861.6746 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2011-02-22T18:37:41.67530Z,1298399861.6753 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2011-02-22T18:37:41.68470Z,1298399861.6847 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2011-02-22T18:37:41.68530Z,1298399861.6853 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2011-02-22T18:37:41.69860Z,1298399861.6986 [VerticalControl](DEBUG): Construct VerticalControl.
2011-02-22T18:37:41.91940Z,1298399861.9194 [VerticalControl] Loaded
2011-02-22T18:37:41.91980Z,1298399861.9198 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2011-02-22T18:37:41.92090Z,1298399861.9209 [HorizontalControl](DEBUG): Construct HorizontalControl.
2011-02-22T18:37:41.97800Z,1298399861.978 [HorizontalControl] Loaded
2011-02-22T18:37:41.97830Z,1298399861.9783 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2011-02-22T18:37:41.97950Z,1298399861.9795 [SpeedControl](DEBUG): Construct SpeedControl.
2011-02-22T18:37:41.98170Z,1298399861.9817 [SpeedControl] Loaded
2011-02-22T18:37:41.98200Z,1298399861.982 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2011-02-22T18:37:41.98320Z,1298399861.9832 [LoopControl](DEBUG): Construct LoopControl.
2011-02-22T18:37:41.98800Z,1298399861.988 [LoopControl] Loaded
2011-02-22T18:37:41.98830Z,1298399861.9883 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2011-02-22T18:37:41.98870Z,1298399861.9887 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2011-02-22T18:37:41.98930Z,1298399861.9893 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2011-02-22T18:37:41.99480Z,1298399861.9948 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2011-02-22T18:37:42.00070Z,1298399862.0007 [AsyncPiEstimator] Loaded
2011-02-22T18:37:42.00100Z,1298399862.001 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2011-02-22T18:37:42.00230Z,1298399862.0023 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 1078576352
2011-02-22T18:37:42.00310Z,1298399862.0031 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2011-02-22T18:37:42.00380Z,1298399862.0038 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2011-02-22T18:37:42.10840Z,1298399862.1084 [AHRS_sp3003D] Loaded
2011-02-22T18:37:42.10880Z,1298399862.1088 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2011-02-22T18:37:42.15980Z,1298399862.1598 [AHRS_3DMGX3] Loaded
2011-02-22T18:37:42.16010Z,1298399862.1601 [ComponentRegistry](DEBUG): SyncComponent "AHRS_3DMGX3" handled in the control thread.
2011-02-22T18:37:42.53350Z,1298399862.5335 [Batt_Ocean_Server] Loaded
2011-02-22T18:37:42.53380Z,1298399862.5338 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2011-02-22T18:37:42.54840Z,1298399862.5484 [Depth_Keller] Loaded
2011-02-22T18:37:42.54880Z,1298399862.5488 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2011-02-22T18:37:42.55520Z,1298399862.5552 [DropWeight] Loaded
2011-02-22T18:37:42.55550Z,1298399862.5555 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2011-02-22T18:37:42.66690Z,1298399862.6669 [DVL_micro] Loaded
2011-02-22T18:37:42.66730Z,1298399862.6673 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2011-02-22T18:37:42.75660Z,1298399862.7566 [NAL9601] Loaded
2011-02-22T18:37:42.75700Z,1298399862.757 [ComponentRegistry](DEBUG): SyncComponent "NAL9601" handled in the control thread.
2011-02-22T18:37:42.80680Z,1298399862.8068 [Onboard] Loaded
2011-02-22T18:37:42.80720Z,1298399862.8072 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2011-02-22T18:37:42.81470Z,1298399862.8147 [Radio_Freewave] Loaded
2011-02-22T18:37:42.81510Z,1298399862.8151 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2011-02-22T18:37:42.81550Z,1298399862.8155 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2011-02-22T18:37:42.81610Z,1298399862.8161 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2011-02-22T18:37:42.86730Z,1298399862.8673 [CTD_NeilBrown] Loaded
2011-02-22T18:37:42.86770Z,1298399862.8677 [ComponentRegistry](DEBUG): SyncComponent "CTD_NeilBrown" handled in the control thread.
2011-02-22T18:37:42.90120Z,1298399862.9012 [WetLabsBB2FL] Loaded
2011-02-22T18:37:42.90160Z,1298399862.9016 [ComponentRegistry](DEBUG): SyncComponent "WetLabsBB2FL" handled in the control thread.
2011-02-22T18:37:42.92250Z,1298399862.9225 [Aanderaa_O2] Loaded
2011-02-22T18:37:42.92310Z,1298399862.9231 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2011-02-22T18:37:42.93370Z,1298399862.9337 [ISUS] Loaded
2011-02-22T18:37:42.93400Z,1298399862.934 [ComponentRegistry](DEBUG): SyncComponent "ISUS" handled in the control thread.
2011-02-22T18:37:42.93450Z,1298399862.9345 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2011-02-22T18:37:42.93730Z,1298399862.9373 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2011-02-22T18:37:42.93830Z,1298399862.9383 [ComponentRegistry](DEBUG): SyncComponent "Maintainer" handled in the control thread.
2011-02-22T18:37:42.93930Z,1298399862.9393 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2011-02-22T18:37:42.93940Z,1298399862.9394 [Supervisor](DEBUG): Running supervisor.
2011-02-22T18:37:42.94260Z,1298399862.9426 [controlThread](DEBUG): Initializing ControlThread
2011-02-22T18:37:42.94380Z,1298399862.9438 [InternalSim](DEBUG):  InternalSim initializing...
2011-02-22T18:37:42.97960Z,1298399862.9796 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2011-02-22T18:37:43.00460Z,1298399863.0046 [SBIT](INFO): Initialize SBIT Component.
2011-02-22T18:37:43.00720Z,1298399863.0072 [IBIT](INFO): Initialize IBIT Component.
2011-02-22T18:37:43.00960Z,1298399863.0096 [CBIT](DEBUG): Initialize CBIT Component.
2011-02-22T18:37:43.01270Z,1298399863.0127 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2011-02-22T18:37:43.04050Z,1298399863.0405 [Bathymetry](DEBUG): Initialize Bathymetry Derivation.
2011-02-22T18:37:43.04610Z,1298399863.0461 [Bathymetry](DEBUG): Opened 
2011-02-22T18:37:43.05820Z,1298399863.0582 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2011-02-22T18:37:43.05870Z,1298399863.0587 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2011-02-22T18:37:43.05920Z,1298399863.0592 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2011-02-22T18:37:43.06000Z,1298399863.06 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2011-02-22T18:37:43.06160Z,1298399863.0616 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2011-02-22T18:37:43.06210Z,1298399863.0621 [Navigation](DEBUG): Initializing Navigation.
2011-02-22T18:37:43.06260Z,1298399863.0626 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2011-02-22T18:37:43.07770Z,1298399863.0777 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2011-02-22T18:37:43.08100Z,1298399863.081 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2011-02-22T18:37:43.08190Z,1298399863.0819 [LoopControl](DEBUG): Initialize LoopControlComponent.
2011-02-22T18:37:44.43130Z,1298399864.4313 [Batt_Ocean_Server](ERROR): Batt_Ocean_Server A initialization uart error: serial timeout
2011-02-22T18:37:44.43150Z,1298399864.4315 [Batt_Ocean_Server](ERROR): Ocean Server Batteries failed to initialize. Re-initializing
2011-02-22T18:37:44.43160Z,1298399864.4316 [Batt_Ocean_Server] Communications Fault, FailCount= 1
2011-02-22T18:37:44.43170Z,1298399864.4317 [Batt_Ocean_Server](ERROR): Communications Fault
2011-02-22T18:37:44.43830Z,1298399864.4383 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2011-02-22T18:37:44.45180Z,1298399864.4518 [Startup:0.GoToSurface](DEBUG): Construct GoToSurface.
2011-02-22T18:37:44.46380Z,1298399864.4638 [MissionManager](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2011-02-22T18:37:44.46710Z,1298399864.4671 [MissionManager](DEBUG): Initialize ReadDataComponent to sense platform_communications
2011-02-22T18:37:44.46980Z,1298399864.4698 [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-22T18:37:44.47080Z,1298399864.4708 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2011-02-22T18:37:44.50530Z,1298399864.5053 [Default:GPS:0.SetSpeed](DEBUG): Construct.
2011-02-22T18:37:44.52120Z,1298399864.5212 [Default:GPS:1.GoToSurface](DEBUG): Construct GoToSurface.
2011-02-22T18:37:44.53150Z,1298399864.5315 [MissionManager](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2011-02-22T18:37:44.53390Z,1298399864.5339 [Default:Iridium:0.SetSpeed](DEBUG): Construct.
2011-02-22T18:37:44.54980Z,1298399864.5498 [Default:Iridium:1.GoToSurface](DEBUG): Construct GoToSurface.
2011-02-22T18:37:44.56040Z,1298399864.5604 [MissionManager](DEBUG): Initialize ReadDataComponent to sense platform_communications
2011-02-22T18:37:44.56300Z,1298399864.563 [Default:Iridium:0_Timeout:0.Execute](DEBUG): Construct Execute.
2011-02-22T18:37:44.58390Z,1298399864.5839 [Default:4.SetSpeed](DEBUG): Construct.
2011-02-22T18:37:44.59970Z,1298399864.5997 [Default:5.GoToSurface](DEBUG): Construct GoToSurface.
2011-02-22T18:37:44.60950Z,1298399864.6095 [Default:6.Wait](DEBUG): Construct Wait.
2011-02-22T18:37:44.65360Z,1298399864.6536 [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-22T18:37:44.66010Z,1298399864.6601 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,AHRS_3DMGX3,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9601,Onboard,Radio_Freewave,CTD_NeilBrown,WetLabsBB2FL,Aanderaa_O2,ISUS,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-22T18:37:44.71560Z,1298399864.7156 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2011-02-22T18:37:44.77810Z,1298399864.7781 [AHRS_3DMGX3](DEBUG): Initializing AHRS_3DMGX3.
2011-02-22T18:37:44.95300Z,1298399864.953 [DVL_micro](DEBUG): Initializing DVL_micro.
2011-02-22T18:37:44.97670Z,1298399864.9767 [Radio_Freewave](INFO): Powering up
2011-02-22T18:37:44.98250Z,1298399864.9825 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2011-02-22T18:37:45.05010Z,1298399865.0501 [WetLabsBB2FL](INFO): Powering down
2011-02-22T18:37:45.20350Z,1298399865.2035 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2011-02-22T18:37:45.25910Z,1298399865.2591 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2011-02-22T18:37:45.27020Z,1298399865.2702 [ElevatorServo](DEBUG): Initializing EZServoServo.
2011-02-22T18:37:45.32700Z,1298399865.327 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2011-02-22T18:37:45.33640Z,1298399865.3364 [MassServo](DEBUG): Initializing EZServoServo.
2011-02-22T18:37:45.39100Z,1298399865.391 [MassServo](DEBUG): Initializing MassServo.
2011-02-22T18:37:45.40010Z,1298399865.4001 [RudderServo](DEBUG): Initializing EZServoServo.
2011-02-22T18:37:45.45500Z,1298399865.455 [RudderServo](DEBUG): Initializing RudderServo.
2011-02-22T18:37:45.46430Z,1298399865.4643 [ThrusterServo](DEBUG): Initializing EZServoServo.
2011-02-22T18:37:45.51910Z,1298399865.5191 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2011-02-22T18:37:45.54170Z,1298399865.5417 [CBIT](ERROR): Communications Fault in component: Batt_Ocean_Server
2011-02-22T18:37:45.54210Z,1298399865.5421 [CBIT](INFO): Clearing failed state for component Batt_Ocean_Server
2011-02-22T18:37:45.54220Z,1298399865.5422 [Batt_Ocean_Server] No Fault, FailCount= 1
2011-02-22T18:37:49.68800Z,1298399869.688 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2011-02-22T18:37:49.69270Z,1298399869.6927 [NAL9601](INFO): Powering up NAL9601
2011-02-22T18:37:50.91110Z,1298399870.9111 [Aanderaa_O2](INFO): Powering down
2011-02-22T18:37:58.48060Z,1298399878.4806 [SBIT](INFO): Beginning Startup BIT
2011-02-22T18:38:36.48090Z,1298399916.4809 [SBIT](IMPORTANT): SBIT PASSED
2011-02-22T18:38:36.90690Z,1298399916.9069 [MissionManager](IMPORTANT): Started mission Startup
2011-02-22T18:38:36.90700Z,1298399916.907 [Startup] Running Loop=1
2011-02-22T18:38:36.90720Z,1298399916.9072 [Startup](INFO): Aggregate::initialize Startup
2011-02-22T18:38:36.90740Z,1298399916.9074 [Startup:0.GoToSurface] Running Loop=1
2011-02-22T18:38:36.90750Z,1298399916.9075 [Startup:0.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T18:38:36.91460Z,1298399916.9146 [Startup:StartupSatComms] Running Loop=1
2011-02-22T18:38:36.91480Z,1298399916.9148 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2011-02-22T18:38:36.91510Z,1298399916.9151 [Startup:StartupSatComms:0] Running Loop=1
2011-02-22T18:38:55.39940Z,1298399935.3994 [NAL9601](INFO): NAL9601 initialized
2011-02-22T18:38:56.45010Z,1298399936.4501 [NAL9601](IMPORTANT): GPS fix at: 1298399935
2011-02-22T18:38:56.46590Z,1298399936.4659 [Startup:StartupSatComms:0] Stopped
2011-02-22T18:38:56.46610Z,1298399936.4661 [Startup:StartupSatComms:1] Running Loop=1
2011-02-22T18:39:16.38220Z,1298399956.3822 [NAL9601](INFO): SBD MO Status=2, MOMSN=12699, MT Status=2, MTMSN=0
2011-02-22T18:39:16.38250Z,1298399956.3825 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T18:39:56.53170Z,1298399996.5317 [Startup:StartupSatComms:1](INFO): Timed out from 2011-02-22T18:38:56.Z
2011-02-22T18:39:56.53180Z,1298399996.5318 [Startup:StartupSatComms:0_Timeout] Running Loop=1
2011-02-22T18:39:56.53200Z,1298399996.532 [Startup:StartupSatComms:0_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:0_Timeout
2011-02-22T18:39:56.53230Z,1298399996.5323 [Startup:StartupSatComms:0_Timeout](INFO): Completed Startup:StartupSatComms:0_Timeout
2011-02-22T18:39:56.53240Z,1298399996.5324 [Startup:StartupSatComms:1] Stopped
2011-02-22T18:39:56.53260Z,1298399996.5326 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2011-02-22T18:39:56.53270Z,1298399996.5327 [Startup:StartupSatComms] Stopped
2011-02-22T18:39:56.53290Z,1298399996.5329 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2011-02-22T18:39:56.53350Z,1298399996.5335 [Startup](INFO): Completed Startup
2011-02-22T18:39:56.53360Z,1298399996.5336 [Startup] Stopped
2011-02-22T18:39:56.53370Z,1298399996.5337 [Startup](INFO): Aggregate::uninitialize Startup
2011-02-22T18:39:56.53380Z,1298399996.5338 [Startup:0.GoToSurface] Stopped
2011-02-22T18:39:56.53390Z,1298399996.5339 [Startup:0.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T18:39:56.92650Z,1298399996.9265 [MissionManager](IMPORTANT): Started mission Default
2011-02-22T18:39:56.92670Z,1298399996.9267 [Default] Running Loop=1
2011-02-22T18:39:56.92690Z,1298399996.9269 [Default](INFO): Aggregate::initialize Default
2011-02-22T18:39:56.92700Z,1298399996.927 [Default:4.SetSpeed] Running Loop=1
2011-02-22T18:39:56.92710Z,1298399996.9271 [Default:4.SetSpeed](DEBUG): Initialize.
2011-02-22T18:39:56.92730Z,1298399996.9273 [Default:5.GoToSurface] Running Loop=1
2011-02-22T18:39:56.92740Z,1298399996.9274 [Default:5.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T18:39:56.92800Z,1298399996.928 [Default:GPS] Running Loop=1
2011-02-22T18:39:56.92820Z,1298399996.9282 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-02-22T18:39:56.92830Z,1298399996.9283 [Default:GPS:0.SetSpeed] Running Loop=1
2011-02-22T18:39:56.92840Z,1298399996.9284 [Default:GPS:0.SetSpeed](DEBUG): Initialize.
2011-02-22T18:39:56.92870Z,1298399996.9287 [Default:GPS:1.GoToSurface] Running Loop=1
2011-02-22T18:39:56.92880Z,1298399996.9288 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T18:39:56.92980Z,1298399996.9298 [Default:5.GoToSurface] Running Loop=1
2011-02-22T18:39:56.93570Z,1298399996.9357 [Default:4.SetSpeed] Running Loop=1
2011-02-22T18:39:56.94170Z,1298399996.9417 [Default:CallIridium] Running Loop=1
2011-02-22T18:39:56.94180Z,1298399996.9418 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-02-22T18:39:56.94210Z,1298399996.9421 [Default:CallIridium:0] Running Loop=1
2011-02-22T18:39:56.94230Z,1298399996.9423 [Default:CallIridium:0](INFO): Aggregate::initialize Default:CallIridium:0
2011-02-22T18:39:56.94870Z,1298399996.9487 [Default:GPS:1.GoToSurface] Stopped
2011-02-22T18:39:56.94880Z,1298399996.9488 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T18:39:56.94900Z,1298399996.949 [Default:GPS:Read GPS] Running Loop=1
2011-02-22T18:39:56.94900Z,1298399996.949 [Default:GPS:0.SetSpeed] Running Loop=1
2011-02-22T18:39:57.41630Z,1298399997.4163 [Default:Iridium] Running Loop=1
2011-02-22T18:39:57.41650Z,1298399997.4165 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-02-22T18:39:57.41660Z,1298399997.4166 [Default:Iridium:0.SetSpeed] Running Loop=1
2011-02-22T18:39:57.41670Z,1298399997.4167 [Default:Iridium:0.SetSpeed](DEBUG): Initialize.
2011-02-22T18:39:57.41700Z,1298399997.417 [Default:Iridium:1.GoToSurface] Running Loop=1
2011-02-22T18:39:57.41710Z,1298399997.4171 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T18:39:57.42340Z,1298399997.4234 [Default:Iridium:1.GoToSurface] Stopped
2011-02-22T18:39:57.42350Z,1298399997.4235 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T18:39:57.42370Z,1298399997.4237 [Default:Iridium:Read Iridium] Running Loop=1
2011-02-22T18:39:57.42380Z,1298399997.4238 [Default:Iridium:0.SetSpeed] Running Loop=1
2011-02-22T18:40:13.74590Z,1298400013.7459 [NAL9601](INFO): SBD MO Status=2, MOMSN=12699, MT Status=0, MTMSN=0
2011-02-22T18:40:13.74620Z,1298400013.7462 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T18:40:14.91570Z,1298400014.9157 [NAL9601](IMPORTANT): GPS fix at: 1298400014
2011-02-22T18:40:14.93300Z,1298400014.933 [Default:GPS:Read GPS] Stopped
2011-02-22T18:40:14.93340Z,1298400014.9334 [Default:GPS](INFO): Completed Default:GPS
2011-02-22T18:40:14.93350Z,1298400014.9335 [Default:GPS] Stopped
2011-02-22T18:40:14.93360Z,1298400014.9336 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-02-22T18:40:14.93380Z,1298400014.9338 [Default:GPS:0.SetSpeed] Stopped
2011-02-22T18:40:14.93380Z,1298400014.9338 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T18:40:37.64190Z,1298400037.6419 [NAL9601](INFO): SBD MO Status=2, MOMSN=12699, MT Status=2, MTMSN=0
2011-02-22T18:40:37.64210Z,1298400037.6421 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T18:41:03.20220Z,1298400063.2022 [NAL9601](INFO): SBD MO Status=2, MOMSN=12699, MT Status=2, MTMSN=0
2011-02-22T18:41:03.20240Z,1298400063.2024 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T18:41:40.43810Z,1298400100.4381 [NAL9601](INFO): SBD MO Status=2, MOMSN=12699, MT Status=2, MTMSN=0
2011-02-22T18:41:40.43840Z,1298400100.4384 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T18:42:40.82180Z,1298400160.8218 [NAL9601](INFO): SBD MO Status=2, MOMSN=12699, MT Status=0, MTMSN=0
2011-02-22T18:42:40.82210Z,1298400160.8221 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T18:43:01.61790Z,1298400181.6179 [NAL9601](INFO): SBD MO Status=1, MOMSN=12699, MT Status=0, MTMSN=0
2011-02-22T18:43:01.80740Z,1298400181.8074 [NAL9601](INFO): Sent 165 bytes from file Logs/20110222T174530/shore0006.lzma
2011-02-22T18:43:01.80760Z,1298400181.8076 [NAL9601](INFO): Packets left to send: 0
2011-02-22T18:43:01.80910Z,1298400181.8091 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000000
2011-02-22T18:43:16.10610Z,1298400196.1061 [NAL9601](INFO): SBD MO Status=2, MOMSN=12700, MT Status=2, MTMSN=0
2011-02-22T18:43:16.10640Z,1298400196.1064 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T18:43:54.12580Z,1298400234.1258 [NAL9601](INFO): SBD MO Status=1, MOMSN=12700, MT Status=0, MTMSN=0
2011-02-22T18:43:54.32730Z,1298400234.3273 [NAL9601](INFO): Sent 332 bytes from file Logs/20110222T183731/shore0000.lzma
2011-02-22T18:43:54.32760Z,1298400234.3276 [NAL9601](INFO): Packets left to send: 1
2011-02-22T18:43:54.32860Z,1298400234.3286 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000001
2011-02-22T18:44:18.26370Z,1298400258.2637 [NAL9601](INFO): SBD MO Status=1, MOMSN=12701, MT Status=0, MTMSN=0
2011-02-22T18:44:18.38730Z,1298400258.3873 [NAL9601](INFO): Sent 53 bytes from file Logs/20110222T183731/shore0000.lzma
2011-02-22T18:44:18.38750Z,1298400258.3875 [NAL9601](INFO): Packets left to send: 0
2011-02-22T18:44:18.38860Z,1298400258.3886 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000002
2011-02-22T18:44:29.41000Z,1298400269.41 [NAL9601](INFO): SBD MO Status=2, MOMSN=12702, MT Status=2, MTMSN=0
2011-02-22T18:44:29.41020Z,1298400269.4102 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T18:44:47.22600Z,1298400287.226 [NAL9601](INFO): SBD MO Status=0, MOMSN=12702, MT Status=0, MTMSN=0
2011-02-22T18:44:47.35920Z,1298400287.3592 [Default:Iridium:Read Iridium] Stopped
2011-02-22T18:44:47.35990Z,1298400287.3599 [Default:Iridium](INFO): Completed Default:Iridium
2011-02-22T18:44:47.36000Z,1298400287.36 [Default:Iridium] Stopped
2011-02-22T18:44:47.36010Z,1298400287.3601 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-02-22T18:44:47.36020Z,1298400287.3602 [Default:Iridium:0.SetSpeed] Stopped
2011-02-22T18:44:47.36030Z,1298400287.3603 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T18:44:47.36050Z,1298400287.3605 [Default:6.Wait] Running Loop=1
2011-02-22T18:44:47.36060Z,1298400287.3606 [Default:6.Wait](DEBUG): Initialize Wait Component.
2011-02-22T18:44:47.64560Z,1298400287.6456 [Default:CallIridium:0](INFO): Completed Default:CallIridium:0
2011-02-22T18:44:47.64570Z,1298400287.6457 [Default:CallIridium:0] Stopped
2011-02-22T18:44:47.64580Z,1298400287.6458 [Default:CallIridium:0](INFO): Aggregate::uninitialize Default:CallIridium:0
2011-02-22T18:44:47.64610Z,1298400287.6461 [Default:CallIridium](INFO): Completed Default:CallIridium
2011-02-22T18:44:47.64620Z,1298400287.6462 [Default:CallIridium] Stopped
2011-02-22T18:44:47.64630Z,1298400287.6463 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-02-22T18:44:57.67680Z,1298400297.6768 [NAL9601](INFO): Powering down
2011-02-22T18:45:17.67400Z,1298400317.674 [Default:CallGPS] Running Loop=1
2011-02-22T18:45:17.67420Z,1298400317.6742 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-02-22T18:45:17.67450Z,1298400317.6745 [Default:CallGPS:0] Running Loop=1
2011-02-22T18:45:17.67500Z,1298400317.675 [Default:CallGPS:0](INFO): Aggregate::initialize Default:CallGPS:0
2011-02-22T18:45:22.79870Z,1298400322.7987 [Default:GPS] Running Loop=1
2011-02-22T18:45:22.79890Z,1298400322.7989 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-02-22T18:45:22.79910Z,1298400322.7991 [Default:GPS:0.SetSpeed] Running Loop=1
2011-02-22T18:45:22.79910Z,1298400322.7991 [Default:GPS:0.SetSpeed](DEBUG): Initialize.
2011-02-22T18:45:22.79940Z,1298400322.7994 [Default:GPS:1.GoToSurface] Running Loop=1
2011-02-22T18:45:22.79950Z,1298400322.7995 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T18:45:22.80040Z,1298400322.8004 [Default:GPS:1.GoToSurface] Stopped
2011-02-22T18:45:22.80050Z,1298400322.8005 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T18:45:22.80070Z,1298400322.8007 [Default:GPS:Read GPS] Running Loop=1
2011-02-22T18:45:23.42450Z,1298400323.4245 [NAL9601](INFO): Powering up
2011-02-22T18:46:29.13140Z,1298400389.1314 [NAL9601](INFO): NAL9601 initialized
2011-02-22T18:46:30.23210Z,1298400390.2321 [NAL9601](IMPORTANT): GPS fix at: 1298400390
2011-02-22T18:46:30.24830Z,1298400390.2483 [Default:GPS:Read GPS] Stopped
2011-02-22T18:46:30.24900Z,1298400390.249 [Default:GPS](INFO): Completed Default:GPS
2011-02-22T18:46:30.24910Z,1298400390.2491 [Default:GPS] Stopped
2011-02-22T18:46:30.24920Z,1298400390.2492 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-02-22T18:46:30.24930Z,1298400390.2493 [Default:GPS:0.SetSpeed] Stopped
2011-02-22T18:46:30.24940Z,1298400390.2494 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T18:46:30.64070Z,1298400390.6407 [Default:CallGPS:0](INFO): Completed Default:CallGPS:0
2011-02-22T18:46:30.64080Z,1298400390.6408 [Default:CallGPS:0] Stopped
2011-02-22T18:46:30.64090Z,1298400390.6409 [Default:CallGPS:0](INFO): Aggregate::uninitialize Default:CallGPS:0
2011-02-22T18:46:30.64120Z,1298400390.6412 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-02-22T18:46:30.64130Z,1298400390.6413 [Default:CallGPS] Stopped
2011-02-22T18:46:30.64140Z,1298400390.6414 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-02-22T18:46:50.71250Z,1298400410.7125 [NAL9601](INFO): Powering down
2011-02-22T18:49:50.72800Z,1298400590.728 [Default:CallIridium] Running Loop=1
2011-02-22T18:49:50.72820Z,1298400590.7282 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-02-22T18:49:50.72840Z,1298400590.7284 [Default:CallIridium:0] Running Loop=1
2011-02-22T18:49:50.72850Z,1298400590.7285 [Default:CallIridium:0](INFO): Aggregate::initialize Default:CallIridium:0
2011-02-22T18:49:55.79960Z,1298400595.7996 [Default:Iridium] Running Loop=1
2011-02-22T18:49:55.79980Z,1298400595.7998 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-02-22T18:49:55.80000Z,1298400595.8 [Default:Iridium:0.SetSpeed] Running Loop=1
2011-02-22T18:49:55.80000Z,1298400595.8 [Default:Iridium:0.SetSpeed](DEBUG): Initialize.
2011-02-22T18:49:55.80030Z,1298400595.8003 [Default:Iridium:1.GoToSurface] Running Loop=1
2011-02-22T18:49:55.80040Z,1298400595.8004 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T18:49:55.80120Z,1298400595.8012 [Default:Iridium:1.GoToSurface] Stopped
2011-02-22T18:49:55.80130Z,1298400595.8013 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T18:49:55.80150Z,1298400595.8015 [Default:Iridium:Read Iridium] Running Loop=1
2011-02-22T18:49:56.42450Z,1298400596.4245 [NAL9601](INFO): Powering up
2011-02-22T18:51:02.13540Z,1298400662.1354 [NAL9601](INFO): NAL9601 initialized
2011-02-22T18:51:30.62010Z,1298400690.6201 [Default:CallGPS] Running Loop=1
2011-02-22T18:51:30.62030Z,1298400690.6203 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-02-22T18:51:30.62050Z,1298400690.6205 [Default:CallGPS:0] Running Loop=1
2011-02-22T18:51:30.62060Z,1298400690.6206 [Default:CallGPS:0](INFO): Aggregate::initialize Default:CallGPS:0
2011-02-22T18:51:30.99120Z,1298400690.9912 [Default:GPS] Running Loop=1
2011-02-22T18:51:30.99140Z,1298400690.9914 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-02-22T18:51:30.99150Z,1298400690.9915 [Default:GPS:0.SetSpeed] Running Loop=1
2011-02-22T18:51:30.99160Z,1298400690.9916 [Default:GPS:0.SetSpeed](DEBUG): Initialize.
2011-02-22T18:51:30.99190Z,1298400690.9919 [Default:GPS:1.GoToSurface] Running Loop=1
2011-02-22T18:51:30.99200Z,1298400690.992 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T18:51:30.99290Z,1298400690.9929 [Default:GPS:1.GoToSurface] Stopped
2011-02-22T18:51:30.99300Z,1298400690.993 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T18:51:30.99320Z,1298400690.9932 [Default:GPS:Read GPS] Running Loop=1
2011-02-22T18:51:32.57390Z,1298400692.5739 [NAL9601](INFO): SBD MO Status=2, MOMSN=12703, MT Status=2, MTMSN=0
2011-02-22T18:51:32.57410Z,1298400692.5741 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T18:51:33.80880Z,1298400693.8088 [NAL9601](IMPORTANT): GPS fix at: 1298400694
2011-02-22T18:51:33.82600Z,1298400693.826 [Default:GPS:Read GPS] Stopped
2011-02-22T18:51:33.82640Z,1298400693.8264 [Default:GPS](INFO): Completed Default:GPS
2011-02-22T18:51:33.82650Z,1298400693.8265 [Default:GPS] Stopped
2011-02-22T18:51:33.82670Z,1298400693.8267 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-02-22T18:51:33.82680Z,1298400693.8268 [Default:GPS:0.SetSpeed] Stopped
2011-02-22T18:51:33.82690Z,1298400693.8269 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T18:51:34.18850Z,1298400694.1885 [Default:CallGPS:0](INFO): Completed Default:CallGPS:0
2011-02-22T18:51:34.18860Z,1298400694.1886 [Default:CallGPS:0] Stopped
2011-02-22T18:51:34.18870Z,1298400694.1887 [Default:CallGPS:0](INFO): Aggregate::uninitialize Default:CallGPS:0
2011-02-22T18:51:34.18900Z,1298400694.189 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-02-22T18:51:34.18910Z,1298400694.1891 [Default:CallGPS] Stopped
2011-02-22T18:51:34.18920Z,1298400694.1892 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-02-22T18:52:05.71410Z,1298400725.7141 [NAL9601](INFO): SBD MO Status=2, MOMSN=12703, MT Status=2, MTMSN=0
2011-02-22T18:52:05.71440Z,1298400725.7144 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T18:52:47.70220Z,1298400767.7022 [NAL9601](INFO): SBD MO Status=1, MOMSN=12703, MT Status=0, MTMSN=0
2011-02-22T18:52:47.85930Z,1298400767.8593 [NAL9601](INFO): Sent 279 bytes from file Logs/20110222T183731/shore0001.lzma
2011-02-22T18:52:47.85960Z,1298400767.8596 [NAL9601](INFO): Packets left to send: 0
2011-02-22T18:52:47.86070Z,1298400767.8607 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000003
2011-02-22T18:52:59.27010Z,1298400779.2701 [NAL9601](INFO): SBD MO Status=2, MOMSN=12704, MT Status=2, MTMSN=0
2011-02-22T18:52:59.27040Z,1298400779.2704 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T18:53:04.28060Z,1298400784.2806 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T18:53:06.89690Z,1298400786.8969 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T18:53:09.20200Z,1298400789.202 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T18:53:13.25670Z,1298400793.2567 [Radio_Freewave](INFO): Powering down
2011-02-22T18:53:14.40310Z,1298400794.4031 [ThrusterServo](FAULT): getVelocity uart error serial timeout
2011-02-22T18:53:14.40340Z,1298400794.4034 [ThrusterServo](FAULT): Thruster uart error: serial timeout
2011-02-22T18:53:14.40350Z,1298400794.4035 [ThrusterServo] Communications Fault, FailCount= 1
2011-02-22T18:53:14.40360Z,1298400794.4036 [ThrusterServo](ERROR): Communications Fault
2011-02-22T18:53:14.40590Z,1298400794.4059 [CBIT](ERROR): Communications Fault in component: ThrusterServo
2011-02-22T18:53:14.60860Z,1298400794.6086 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2011-02-22T18:53:14.60890Z,1298400794.6089 [ThrusterServo](INFO): Powering down
2011-02-22T18:53:14.61150Z,1298400794.6115 [CBIT](INFO): Clearing failed state for component ThrusterServo
2011-02-22T18:53:14.61170Z,1298400794.6117 [ThrusterServo] No Fault, FailCount= 1
2011-02-22T18:53:14.96430Z,1298400794.9643 [ThrusterServo](DEBUG): Initializing EZServoServo.
2011-02-22T18:53:15.13910Z,1298400795.1391 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2011-02-22T18:53:16.96740Z,1298400796.9674 [BuoyancyServo](ERROR): EZ Servo:6 reading outside of valid range:0

2011-02-22T18:53:16.96760Z,1298400796.9676 [BuoyancyServo](FAULT): Buoyancy engine reporting null position
2011-02-22T18:53:16.96850Z,1298400796.9685 [BuoyancyServo] Hardware Fault, FailCount= 1
2011-02-22T18:53:16.96910Z,1298400796.9691 [BuoyancyServo](ERROR): Hardware Fault
2011-02-22T18:53:17.00190Z,1298400797.0019 [CBIT](ERROR): Hardware Fault in component: BuoyancyServo
2011-02-22T18:53:17.32660Z,1298400797.3266 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2011-02-22T18:53:17.32680Z,1298400797.3268 [BuoyancyServo](INFO): Powering down
2011-02-22T18:53:17.42870Z,1298400797.4287 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2011-02-22T18:53:17.42890Z,1298400797.4289 [BuoyancyServo] No Fault, FailCount= 1
2011-02-22T18:53:18.32120Z,1298400798.3212 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2011-02-22T18:53:18.49510Z,1298400798.4951 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2011-02-22T18:53:18.70260Z,1298400798.7026 [Radio_Freewave](INFO): Powering up
2011-02-22T18:53:19.10240Z,1298400799.1024 [NAL9601](INFO): SBD MO Status=2, MOMSN=12704, MT Status=2, MTMSN=0
2011-02-22T18:53:19.10290Z,1298400799.1029 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T18:53:24.12090Z,1298400804.1209 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T18:53:26.36060Z,1298400806.3606 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T18:53:30.57250Z,1298400810.5725 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T18:53:32.82020Z,1298400812.8202 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T18:53:37.00060Z,1298400817.0006 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T18:53:40.81660Z,1298400820.8166 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T18:53:43.11380Z,1298400823.1138 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T18:53:47.32720Z,1298400827.3272 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T18:53:49.77060Z,1298400829.7706 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T18:53:53.78420Z,1298400833.7842 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T18:53:56.08260Z,1298400836.0826 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T18:54:07.43410Z,1298400847.4341 [NAL9601](INFO): SBD MO Status=2, MOMSN=12704, MT Status=2, MTMSN=0
2011-02-22T18:54:07.43430Z,1298400847.4343 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T18:54:18.84590Z,1298400858.8459 [NAL9601](INFO): SBD MO Status=0, MOMSN=12704, MT Status=0, MTMSN=0
2011-02-22T18:54:19.03120Z,1298400859.0312 [Default:Iridium:Read Iridium] Stopped
2011-02-22T18:54:19.03170Z,1298400859.0317 [Default:Iridium](INFO): Completed Default:Iridium
2011-02-22T18:54:19.03180Z,1298400859.0318 [Default:Iridium] Stopped
2011-02-22T18:54:19.03200Z,1298400859.032 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-02-22T18:54:19.03210Z,1298400859.0321 [Default:Iridium:0.SetSpeed] Stopped
2011-02-22T18:54:19.03210Z,1298400859.0321 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T18:54:19.25610Z,1298400859.2561 [Default:CallIridium:0](INFO): Completed Default:CallIridium:0
2011-02-22T18:54:19.25620Z,1298400859.2562 [Default:CallIridium:0] Stopped
2011-02-22T18:54:19.25630Z,1298400859.2563 [Default:CallIridium:0](INFO): Aggregate::uninitialize Default:CallIridium:0
2011-02-22T18:54:19.25660Z,1298400859.2566 [Default:CallIridium](INFO): Completed Default:CallIridium
2011-02-22T18:54:19.25670Z,1298400859.2567 [Default:CallIridium] Stopped
2011-02-22T18:54:19.25680Z,1298400859.2568 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-02-22T18:54:29.40310Z,1298400869.4031 [NAL9601](INFO): Powering down
2011-02-22T18:56:34.38120Z,1298400994.3812 [Default:CallGPS] Running Loop=1
2011-02-22T18:56:34.38140Z,1298400994.3814 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-02-22T18:56:34.38160Z,1298400994.3816 [Default:CallGPS:0] Running Loop=1
2011-02-22T18:56:34.38180Z,1298400994.3818 [Default:CallGPS:0](INFO): Aggregate::initialize Default:CallGPS:0
2011-02-22T18:56:39.39940Z,1298400999.3994 [Default:GPS] Running Loop=1
2011-02-22T18:56:39.39960Z,1298400999.3996 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-02-22T18:56:39.39970Z,1298400999.3997 [Default:GPS:0.SetSpeed] Running Loop=1
2011-02-22T18:56:39.39980Z,1298400999.3998 [Default:GPS:0.SetSpeed](DEBUG): Initialize.
2011-02-22T18:56:39.40010Z,1298400999.4001 [Default:GPS:1.GoToSurface] Running Loop=1
2011-02-22T18:56:39.40020Z,1298400999.4002 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T18:56:39.40090Z,1298400999.4009 [Default:GPS:1.GoToSurface] Stopped
2011-02-22T18:56:39.40100Z,1298400999.401 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T18:56:39.40120Z,1298400999.4012 [Default:GPS:Read GPS] Running Loop=1
2011-02-22T18:56:40.04060Z,1298401000.0406 [NAL9601](INFO): Powering up
2011-02-22T18:57:45.75140Z,1298401065.7514 [NAL9601](INFO): NAL9601 initialized
2011-02-22T18:57:46.84790Z,1298401066.8479 [NAL9601](IMPORTANT): GPS fix at: 1298401068
2011-02-22T18:57:46.86510Z,1298401066.8651 [Default:GPS:Read GPS] Stopped
2011-02-22T18:57:46.86570Z,1298401066.8657 [Default:GPS](INFO): Completed Default:GPS
2011-02-22T18:57:46.86580Z,1298401066.8658 [Default:GPS] Stopped
2011-02-22T18:57:46.86600Z,1298401066.866 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-02-22T18:57:46.86610Z,1298401066.8661 [Default:GPS:0.SetSpeed] Stopped
2011-02-22T18:57:46.86610Z,1298401066.8661 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T18:57:47.26050Z,1298401067.2605 [Default:CallGPS:0](INFO): Completed Default:CallGPS:0
2011-02-22T18:57:47.26060Z,1298401067.2606 [Default:CallGPS:0] Stopped
2011-02-22T18:57:47.26080Z,1298401067.2608 [Default:CallGPS:0](INFO): Aggregate::uninitialize Default:CallGPS:0
2011-02-22T18:57:47.26100Z,1298401067.261 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-02-22T18:57:47.26110Z,1298401067.2611 [Default:CallGPS] Stopped
2011-02-22T18:57:47.26120Z,1298401067.2612 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-02-22T18:58:07.33290Z,1298401087.3329 [NAL9601](INFO): Powering down
2011-02-22T18:59:22.39620Z,1298401162.3962 [Default:CallIridium] Running Loop=1
2011-02-22T18:59:22.39640Z,1298401162.3964 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-02-22T18:59:22.39660Z,1298401162.3966 [Default:CallIridium:0] Running Loop=1
2011-02-22T18:59:22.39680Z,1298401162.3968 [Default:CallIridium:0](INFO): Aggregate::initialize Default:CallIridium:0
2011-02-22T18:59:27.41900Z,1298401167.419 [Default:Iridium] Running Loop=1
2011-02-22T18:59:27.41920Z,1298401167.4192 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-02-22T18:59:27.41930Z,1298401167.4193 [Default:Iridium:0.SetSpeed] Running Loop=1
2011-02-22T18:59:27.41940Z,1298401167.4194 [Default:Iridium:0.SetSpeed](DEBUG): Initialize.
2011-02-22T18:59:27.41970Z,1298401167.4197 [Default:Iridium:1.GoToSurface] Running Loop=1
2011-02-22T18:59:27.41980Z,1298401167.4198 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T18:59:27.42050Z,1298401167.4205 [Default:Iridium:1.GoToSurface] Stopped
2011-02-22T18:59:27.42060Z,1298401167.4206 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T18:59:27.42090Z,1298401167.4209 [Default:Iridium:Read Iridium] Running Loop=1
2011-02-22T18:59:28.04450Z,1298401168.0445 [NAL9601](INFO): Powering up
2011-02-22T19:00:33.75540Z,1298401233.7554 [NAL9601](INFO): NAL9601 initialized
2011-02-22T19:00:47.97000Z,1298401247.97 [NAL9601](INFO): SBD MO Status=2, MOMSN=12705, MT Status=2, MTMSN=0
2011-02-22T19:00:47.97020Z,1298401247.9702 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T19:01:13.55390Z,1298401273.5539 [NAL9601](INFO): SBD MO Status=2, MOMSN=12705, MT Status=2, MTMSN=0
2011-02-22T19:01:13.55410Z,1298401273.5541 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T19:01:52.33850Z,1298401312.3385 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=12705, MT Status=1, MTMSN=1566
2011-02-22T19:01:52.51930Z,1298401312.5193 [NAL9601](INFO): Sent 299 bytes from file Logs/20110222T183731/shore0002.lzma
2011-02-22T19:01:52.51950Z,1298401312.5195 [NAL9601](INFO): Packets left to send: 0
2011-02-22T19:01:52.52060Z,1298401312.5206 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000004
2011-02-22T19:01:52.94200Z,1298401312.942 [NAL9601](INFO): Received command:run Transport/transit_3km.xml
2011-02-22T19:01:53.03120Z,1298401313.0312 [CommandLine](IMPORTANT): got command run ./Missions/Transport/transit_3km.xml
2011-02-22T19:01:53.03160Z,1298401313.0316 [MissionManager](INFO): Loading Mission: ./Missions/Transport/transit_3km.xml
2011-02-22T19:01:53.07580Z,1298401313.0758 [MissionManager](INFO): DefineArg ApproachDepth = 10 m
2011-02-22T19:01:53.07930Z,1298401313.0793 [MissionManager](INFO): DefineArg Wpt1Lat = 36.806966 arcdeg
2011-02-22T19:01:53.10680Z,1298401313.1068 [MissionManager](INFO): DefineArg Wpt1Lon = -121.824326 arcdeg
2011-02-22T19:01:53.11030Z,1298401313.1103 [MissionManager](INFO): DefineArg Speed = 1 m/s
2011-02-22T19:01:53.11280Z,1298401313.1128 [transit_3km:0.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2011-02-22T19:01:53.21860Z,1298401313.2186 [transit_3km:1.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2011-02-22T19:01:53.31150Z,1298401313.3115 [transit_3km:2.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2011-02-22T19:01:53.37330Z,1298401313.3733 [transit_3km:SURFACECOMMS:0.GoToSurface](DEBUG): Construct GoToSurface.
2011-02-22T19:01:53.39700Z,1298401313.397 [transit_3km:SURFACECOMMS:1:0.SetSpeed](DEBUG): Construct.
2011-02-22T19:01:53.41490Z,1298401313.4149 [MissionManager](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2011-02-22T19:01:53.41710Z,1298401313.4171 [MissionManager](DEBUG): Initialize ReadDataComponent to sense platform_communications
2011-02-22T19:01:53.44660Z,1298401313.4466 [MissionManager](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2011-02-22T19:01:53.45170Z,1298401313.4517 [transit_3km:5.Buoyancy](DEBUG): Construct Buoyancy.
2011-02-22T19:01:53.46770Z,1298401313.4677 [transit_3km:WaypointOne:0.Pitch](DEBUG): Construct.
2011-02-22T19:01:53.55490Z,1298401313.5549 [transit_3km:WaypointOne:1.SetSpeed](DEBUG): Construct.
2011-02-22T19:01:53.58130Z,1298401313.5813 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Construct Waypoint.
2011-02-22T19:01:53.66310Z,1298401313.6631 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="utf-8"?>
<Mission xmlns="Tethys" xmlns:Control="Tethys/Control" xmlns:Guidance="Tethys/Guidance" xmlns:Units="Tethys/Units" xmlns:Universal="Tethys/Universal" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd                            Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd                            Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd                            Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd                            Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd" Id="transit_3km">

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

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

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

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

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

    <Timeout Duration="P130M" />

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

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

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

    <Aggregate Id="SURFACECOMMS">

        <Guidance:GoToSurface RunIn="Progression" />

        <Aggregate>

            <Preemptive><True /></Preemptive>

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

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

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

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

        </Aggregate>

    </Aggregate>

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

    <Aggregate Id="NeedComms">

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

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

    </Aggregate>

    <Guidance:Buoyancy RunIn="Parallel">
        <Setting><Guidance:Buoyancy.position /><Units:cubic_centimeter /><Value>275</Value></Setting>
    </Guidance:Buoyancy>

    <Aggregate Id="WaypointOne">

<!-- Go to Wpt1 -->

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

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

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

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

    </Aggregate>

</Mission>


2011-02-22T19:01:53.66360Z,1298401313.6636 [CommandLine](IMPORTANT): Running ./Missions/Transport/transit_3km.xml
2011-02-22T19:01:53.75910Z,1298401313.7591 [Default] Stopped
2011-02-22T19:01:53.75930Z,1298401313.7593 [Default](INFO): Aggregate::uninitialize Default
2011-02-22T19:01:53.75940Z,1298401313.7594 [Default:Iridium] Stopped
2011-02-22T19:01:53.75960Z,1298401313.7596 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-02-22T19:01:53.75970Z,1298401313.7597 [Default:Iridium:0.SetSpeed] Stopped
2011-02-22T19:01:53.75980Z,1298401313.7598 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T19:01:53.75980Z,1298401313.7598 [Default:Iridium:Read Iridium] Stopped
2011-02-22T19:01:53.75990Z,1298401313.7599 [Default:CallIridium] Stopped
2011-02-22T19:01:53.76010Z,1298401313.7601 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-02-22T19:01:53.76020Z,1298401313.7602 [Default:CallIridium:0] Stopped
2011-02-22T19:01:53.76030Z,1298401313.7603 [Default:CallIridium:0](INFO): Aggregate::uninitialize Default:CallIridium:0
2011-02-22T19:01:53.76040Z,1298401313.7604 [Default:4.SetSpeed] Stopped
2011-02-22T19:01:53.76050Z,1298401313.7605 [Default:4.SetSpeed](DEBUG): Uninitialize.
2011-02-22T19:01:53.76060Z,1298401313.7606 [Default:5.GoToSurface] Stopped
2011-02-22T19:01:53.76070Z,1298401313.7607 [Default:5.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T19:01:53.76080Z,1298401313.7608 [Default:6.Wait] Stopped
2011-02-22T19:01:53.76080Z,1298401313.7608 [Default:6.Wait](DEBUG): Uninitialize Wait Component.
2011-02-22T19:01:53.76100Z,1298401313.761 [MissionManager](IMPORTANT): Started mission transit_3km
2011-02-22T19:01:53.76110Z,1298401313.7611 [transit_3km] Running Loop=1
2011-02-22T19:01:53.76130Z,1298401313.7613 [transit_3km](INFO): Aggregate::initialize transit_3km
2011-02-22T19:01:53.76140Z,1298401313.7614 [transit_3km:0.AltitudeEnvelope] Running Loop=1
2011-02-22T19:01:53.76150Z,1298401313.7615 [transit_3km:0.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2011-02-22T19:01:53.76180Z,1298401313.7618 [transit_3km:1.DepthEnvelope] Running Loop=1
2011-02-22T19:01:53.76190Z,1298401313.7619 [transit_3km:1.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2011-02-22T19:01:53.76360Z,1298401313.7636 [transit_3km:2.OffshoreEnvelope] Running Loop=1
2011-02-22T19:01:53.76370Z,1298401313.7637 [transit_3km:2.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2011-02-22T19:01:53.77020Z,1298401313.7702 [transit_3km:2.OffshoreEnvelope](DEBUG): Opened Resources/cencalShoreDist.nc
2011-02-22T19:01:53.78920Z,1298401313.7892 [transit_3km:5.Buoyancy] Running Loop=1
2011-02-22T19:01:53.78930Z,1298401313.7893 [transit_3km:5.Buoyancy](DEBUG): Initialize Buoyancy Component.
2011-02-22T19:01:53.79030Z,1298401313.7903 [transit_3km:SURFACECOMMS] Running Loop=1
2011-02-22T19:01:53.79040Z,1298401313.7904 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2011-02-22T19:01:53.79060Z,1298401313.7906 [transit_3km:SURFACECOMMS:0.GoToSurface] Running Loop=1
2011-02-22T19:01:53.79070Z,1298401313.7907 [transit_3km:SURFACECOMMS:0.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T19:01:53.79170Z,1298401313.7917 [transit_3km:5.Buoyancy] Running Loop=1
2011-02-22T19:01:53.80330Z,1298401313.8033 [transit_3km:SURFACECOMMS:1] Running Loop=1
2011-02-22T19:01:53.80350Z,1298401313.8035 [transit_3km:SURFACECOMMS:1](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:1
2011-02-22T19:01:53.80360Z,1298401313.8036 [transit_3km:SURFACECOMMS:1:0.SetSpeed] Running Loop=1
2011-02-22T19:01:53.80370Z,1298401313.8037 [transit_3km:SURFACECOMMS:1:0.SetSpeed](DEBUG): Initialize.
2011-02-22T19:01:53.80410Z,1298401313.8041 [transit_3km:SURFACECOMMS:1:1] Running Loop=1
2011-02-22T19:01:53.80420Z,1298401313.8042 [transit_3km:2.OffshoreEnvelope] Running Loop=1
2011-02-22T19:01:53.82790Z,1298401313.8279 [transit_3km:1.DepthEnvelope] Running Loop=1
2011-02-22T19:01:53.83380Z,1298401313.8338 [transit_3km:0.AltitudeEnvelope] Running Loop=1
2011-02-22T19:01:54.16540Z,1298401314.1654 [transit_3km:5.Buoyancy] Preempted
2011-02-22T19:01:54.16750Z,1298401314.1675 [transit_3km:SURFACECOMMS:1:0.SetSpeed] Running Loop=1
2011-02-22T19:01:57.67700Z,1298401317.677 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T19:01:58.88020Z,1298401318.8802 [NAL9601](IMPORTANT): GPS fix at: 1298401320
2011-02-22T19:01:58.89630Z,1298401318.8963 [transit_3km:SURFACECOMMS:1:1] Stopped
2011-02-22T19:01:58.89650Z,1298401318.8965 [transit_3km:SURFACECOMMS:1:2] Running Loop=1
2011-02-22T19:02:09.62320Z,1298401329.6232 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T19:02:13.94430Z,1298401333.9443 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T19:02:22.76510Z,1298401342.7651 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T19:02:26.80900Z,1298401346.809 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T19:02:35.46460Z,1298401355.4646 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T19:02:39.73490Z,1298401359.7349 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T19:02:49.78760Z,1298401369.7876 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T19:02:52.84060Z,1298401372.8406 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T19:03:09.89440Z,1298401389.8944 [NAL9601](INFO): SBD MO Status=2, MOMSN=12706, MT Status=2, MTMSN=0
2011-02-22T19:03:09.89490Z,1298401389.8949 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T19:03:30.23030Z,1298401410.2303 [NAL9601](INFO): SBD MO Status=0, MOMSN=12706, MT Status=0, MTMSN=0
2011-02-22T19:03:30.38670Z,1298401410.3867 [transit_3km:SURFACECOMMS:1:2] Stopped
2011-02-22T19:03:30.38700Z,1298401410.387 [transit_3km:SURFACECOMMS:1:3] Running Loop=1
2011-02-22T19:03:32.63200Z,1298401412.632 [NAL9601](IMPORTANT): GPS fix at: 1298401414
2011-02-22T19:03:32.65120Z,1298401412.6512 [transit_3km:SURFACECOMMS:1:3] Stopped
2011-02-22T19:03:32.65180Z,1298401412.6518 [transit_3km:SURFACECOMMS:1](INFO): Completed transit_3km:SURFACECOMMS:1
2011-02-22T19:03:32.65190Z,1298401412.6519 [transit_3km:SURFACECOMMS:1] Stopped
2011-02-22T19:03:32.65200Z,1298401412.652 [transit_3km:SURFACECOMMS:1](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:1
2011-02-22T19:03:32.65210Z,1298401412.6521 [transit_3km:SURFACECOMMS:1:0.SetSpeed] Stopped
2011-02-22T19:03:32.65220Z,1298401412.6522 [transit_3km:SURFACECOMMS:1:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T19:03:32.65280Z,1298401412.6528 [transit_3km:SURFACECOMMS](INFO): Completed transit_3km:SURFACECOMMS
2011-02-22T19:03:32.65290Z,1298401412.6529 [transit_3km:SURFACECOMMS] Stopped
2011-02-22T19:03:32.65310Z,1298401412.6531 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2011-02-22T19:03:32.65320Z,1298401412.6532 [transit_3km:SURFACECOMMS:0.GoToSurface] Stopped
2011-02-22T19:03:32.65330Z,1298401412.6533 [transit_3km:SURFACECOMMS:0.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T19:03:32.65350Z,1298401412.6535 [transit_3km:WaypointOne] Running Loop=1
2011-02-22T19:03:32.65360Z,1298401412.6536 [transit_3km:WaypointOne](INFO): Aggregate::initialize transit_3km:WaypointOne
2011-02-22T19:03:32.65400Z,1298401412.654 [transit_3km:WaypointOne:0.Pitch] Running Loop=1
2011-02-22T19:03:32.65410Z,1298401412.6541 [transit_3km:WaypointOne:0.Pitch](DEBUG): Initialize.
2011-02-22T19:03:32.65460Z,1298401412.6546 [transit_3km:WaypointOne:1.SetSpeed] Running Loop=1
2011-02-22T19:03:32.65460Z,1298401412.6546 [transit_3km:WaypointOne:1.SetSpeed](DEBUG): Initialize.
2011-02-22T19:03:32.65550Z,1298401412.6555 [transit_3km:WaypointOne:WaypointW1.Waypoint] Running Loop=1
2011-02-22T19:03:32.65560Z,1298401412.6556 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Initialize WaypointComponent.
2011-02-22T19:03:33.05550Z,1298401413.0555 [transit_3km:WaypointOne:1.SetSpeed] Running Loop=1
2011-02-22T19:03:33.06080Z,1298401413.0608 [transit_3km:WaypointOne:0.Pitch] Running Loop=1
2011-02-22T19:03:33.06660Z,1298401413.0666 [transit_3km:5.Buoyancy] Running Loop=1
2011-02-22T19:03:39.02890Z,1298401419.0289 [NAL9601](INFO): Powering down
2011-02-22T19:03:58.25430Z,1298401438.2543 [Radio_Freewave](INFO): Powering down
2011-02-22T19:04:04.25030Z,1298401444.2503 [Radio_Freewave](INFO): Powering up
2011-02-22T19:08:15.77500Z,1298401695.775 [Radio_Freewave](INFO): Powering down
2011-02-22T19:38:33.03670Z,1298403513.0367 [transit_3km:NeedComms] Running Loop=1
2011-02-22T19:38:33.03690Z,1298403513.0369 [transit_3km:NeedComms](INFO): Aggregate::initialize transit_3km:NeedComms
2011-02-22T19:38:33.03720Z,1298403513.0372 [transit_3km:NeedComms:NEEDCOMMS] Running Loop=1
2011-02-22T19:38:33.03740Z,1298403513.0374 [transit_3km:NeedComms:NEEDCOMMS](INFO): Aggregate::initialize transit_3km:NeedComms:NEEDCOMMS
2011-02-22T19:38:33.41790Z,1298403513.4179 [transit_3km:SURFACECOMMS] Running Loop=1
2011-02-22T19:38:33.41810Z,1298403513.4181 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2011-02-22T19:38:33.41820Z,1298403513.4182 [transit_3km:SURFACECOMMS:0.GoToSurface] Running Loop=1
2011-02-22T19:38:33.41830Z,1298403513.4183 [transit_3km:SURFACECOMMS:0.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T19:39:50.20650Z,1298403590.2065 [Radio_Freewave](INFO): Powering up
2011-02-22T19:39:50.21940Z,1298403590.2194 [transit_3km:SURFACECOMMS:1] Running Loop=1
2011-02-22T19:39:50.21960Z,1298403590.2196 [transit_3km:SURFACECOMMS:1](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:1
2011-02-22T19:39:50.21970Z,1298403590.2197 [transit_3km:SURFACECOMMS:1:0.SetSpeed] Running Loop=1
2011-02-22T19:39:50.21980Z,1298403590.2198 [transit_3km:SURFACECOMMS:1:0.SetSpeed](DEBUG): Initialize.
2011-02-22T19:39:50.22010Z,1298403590.2201 [transit_3km:SURFACECOMMS:1:1] Running Loop=1
2011-02-22T19:39:50.67030Z,1298403590.6703 [transit_3km:5.Buoyancy] Preempted
2011-02-22T19:39:51.00510Z,1298403591.0051 [NAL9601](INFO): Powering up
2011-02-22T19:40:56.71540Z,1298403656.7154 [NAL9601](INFO): NAL9601 initialized
2011-02-22T19:40:57.80800Z,1298403657.808 [NAL9601](IMPORTANT): GPS fix at: 1298403663
2011-02-22T19:40:57.82820Z,1298403657.8282 [transit_3km:SURFACECOMMS:1:1] Stopped
2011-02-22T19:40:57.82840Z,1298403657.8284 [transit_3km:SURFACECOMMS:1:2] Running Loop=1
2011-02-22T19:41:25.15020Z,1298403685.1502 [NAL9601](INFO): SBD MO Status=2, MOMSN=12707, MT Status=2, MTMSN=0
2011-02-22T19:41:25.15040Z,1298403685.1504 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T19:42:00.45820Z,1298403720.4582 [NAL9601](INFO): SBD MO Status=1, MOMSN=12707, MT Status=0, MTMSN=0
2011-02-22T19:42:00.60330Z,1298403720.6033 [NAL9601](INFO): Sent 332 bytes from file Logs/20110222T183731/shore0003.lzma
2011-02-22T19:42:00.60350Z,1298403720.6035 [NAL9601](INFO): Packets left to send: 1
2011-02-22T19:42:00.60690Z,1298403720.6069 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000005
2011-02-22T19:42:15.14130Z,1298403735.1413 [NAL9601](INFO): SBD MO Status=2, MOMSN=12708, MT Status=2, MTMSN=0
2011-02-22T19:42:15.14160Z,1298403735.1416 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T19:42:38.39780Z,1298403758.3978 [NAL9601](INFO): SBD MO Status=1, MOMSN=12708, MT Status=0, MTMSN=0
2011-02-22T19:42:38.54730Z,1298403758.5473 [NAL9601](INFO): Sent 301 bytes from file Logs/20110222T183731/shore0003.lzma
2011-02-22T19:42:38.54750Z,1298403758.5475 [NAL9601](INFO): Packets left to send: 0
2011-02-22T19:42:38.54860Z,1298403758.5486 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000006
2011-02-22T19:42:49.58510Z,1298403769.5851 [NAL9601](INFO): SBD MO Status=0, MOMSN=12709, MT Status=0, MTMSN=0
2011-02-22T19:42:49.74320Z,1298403769.7432 [transit_3km:SURFACECOMMS:1:2] Stopped
2011-02-22T19:42:49.74340Z,1298403769.7434 [transit_3km:SURFACECOMMS:1:3] Running Loop=1
2011-02-22T19:42:51.96810Z,1298403771.9681 [NAL9601](IMPORTANT): GPS fix at: 1298403777
2011-02-22T19:42:51.98640Z,1298403771.9864 [transit_3km:SURFACECOMMS:1:3] Stopped
2011-02-22T19:42:51.98710Z,1298403771.9871 [transit_3km:SURFACECOMMS:1](INFO): Completed transit_3km:SURFACECOMMS:1
2011-02-22T19:42:51.98720Z,1298403771.9872 [transit_3km:SURFACECOMMS:1] Stopped
2011-02-22T19:42:51.98740Z,1298403771.9874 [transit_3km:SURFACECOMMS:1](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:1
2011-02-22T19:42:51.98750Z,1298403771.9875 [transit_3km:SURFACECOMMS:1:0.SetSpeed] Stopped
2011-02-22T19:42:51.98760Z,1298403771.9876 [transit_3km:SURFACECOMMS:1:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T19:42:51.98830Z,1298403771.9883 [transit_3km:SURFACECOMMS](INFO): Completed transit_3km:SURFACECOMMS
2011-02-22T19:42:51.98840Z,1298403771.9884 [transit_3km:SURFACECOMMS] Stopped
2011-02-22T19:42:51.98860Z,1298403771.9886 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2011-02-22T19:42:51.98870Z,1298403771.9887 [transit_3km:SURFACECOMMS:0.GoToSurface] Stopped
2011-02-22T19:42:51.98880Z,1298403771.9888 [transit_3km:SURFACECOMMS:0.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T19:42:52.40090Z,1298403772.4009 [transit_3km:5.Buoyancy] Running Loop=1
2011-02-22T19:42:52.40150Z,1298403772.4015 [transit_3km:NeedComms:NEEDCOMMS](INFO): Completed transit_3km:NeedComms:NEEDCOMMS
2011-02-22T19:42:52.40160Z,1298403772.4016 [transit_3km:NeedComms:NEEDCOMMS] Stopped
2011-02-22T19:42:52.40180Z,1298403772.4018 [transit_3km:NeedComms:NEEDCOMMS](INFO): Aggregate::uninitialize transit_3km:NeedComms:NEEDCOMMS
2011-02-22T19:42:52.40200Z,1298403772.402 [transit_3km:NeedComms](INFO): Completed transit_3km:NeedComms
2011-02-22T19:42:52.40210Z,1298403772.4021 [transit_3km:NeedComms] Stopped
2011-02-22T19:42:52.40230Z,1298403772.4023 [transit_3km:NeedComms](INFO): Aggregate::uninitialize transit_3km:NeedComms
2011-02-22T19:42:58.36500Z,1298403778.365 [NAL9601](INFO): Powering down
2011-02-22T19:46:36.57840Z,1298403996.5784 [Radio_Freewave](INFO): Powering down
2011-02-22T20:17:52.10530Z,1298405872.1053 [transit_3km:NeedComms] Running Loop=1
2011-02-22T20:17:52.10550Z,1298405872.1055 [transit_3km:NeedComms](INFO): Aggregate::initialize transit_3km:NeedComms
2011-02-22T20:17:52.10570Z,1298405872.1057 [transit_3km:NeedComms:NEEDCOMMS] Running Loop=1
2011-02-22T20:17:52.10590Z,1298405872.1059 [transit_3km:NeedComms:NEEDCOMMS](INFO): Aggregate::initialize transit_3km:NeedComms:NEEDCOMMS
2011-02-22T20:17:52.52080Z,1298405872.5208 [transit_3km:SURFACECOMMS] Running Loop=1
2011-02-22T20:17:52.52100Z,1298405872.521 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2011-02-22T20:17:52.52110Z,1298405872.5211 [transit_3km:SURFACECOMMS:0.GoToSurface] Running Loop=1
2011-02-22T20:17:52.52120Z,1298405872.5212 [transit_3km:SURFACECOMMS:0.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T20:19:09.11050Z,1298405949.1105 [Radio_Freewave](INFO): Powering up
2011-02-22T20:19:09.12340Z,1298405949.1234 [transit_3km:SURFACECOMMS:1] Running Loop=1
2011-02-22T20:19:09.12360Z,1298405949.1236 [transit_3km:SURFACECOMMS:1](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:1
2011-02-22T20:19:09.12370Z,1298405949.1237 [transit_3km:SURFACECOMMS:1:0.SetSpeed] Running Loop=1
2011-02-22T20:19:09.12380Z,1298405949.1238 [transit_3km:SURFACECOMMS:1:0.SetSpeed](DEBUG): Initialize.
2011-02-22T20:19:09.12410Z,1298405949.1241 [transit_3km:SURFACECOMMS:1:1] Running Loop=1
2011-02-22T20:19:09.54180Z,1298405949.5418 [transit_3km:5.Buoyancy] Preempted
2011-02-22T20:19:09.91290Z,1298405949.9129 [NAL9601](INFO): Powering up
2011-02-22T20:19:21.94120Z,1298405961.9412 [Radio_Freewave](INFO): Powering down
2011-02-22T20:19:27.17690Z,1298405967.1769 [Radio_Freewave](INFO): Powering up
2011-02-22T20:20:15.72740Z,1298406015.7274 [NAL9601](INFO): NAL9601 initialized
2011-02-22T20:20:20.96270Z,1298406020.9627 [NAL9601](IMPORTANT): GPS fix at: 1298406029
2011-02-22T20:20:20.98180Z,1298406020.9818 [transit_3km:SURFACECOMMS:1:1] Stopped
2011-02-22T20:20:20.98200Z,1298406020.982 [transit_3km:SURFACECOMMS:1:2] Running Loop=1
2011-02-22T20:20:47.54890Z,1298406047.5489 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=12710, MT Status=1, MTMSN=1567
2011-02-22T20:20:47.76330Z,1298406047.7633 [NAL9601](INFO): Sent 310 bytes from file Logs/20110222T183731/shore0004.lzma
2011-02-22T20:20:47.76360Z,1298406047.7636 [NAL9601](INFO): Packets left to send: 0
2011-02-22T20:20:47.76460Z,1298406047.7646 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000007
2011-02-22T20:20:48.07720Z,1298406048.0772 [NAL9601](INFO): Received command:stop

2011-02-22T20:20:48.07810Z,1298406048.0781 [CommandLine](IMPORTANT): got command stop
2011-02-22T20:20:48.09690Z,1298406048.0969 [transit_3km] Stopped
2011-02-22T20:20:48.09710Z,1298406048.0971 [transit_3km](INFO): Aggregate::uninitialize transit_3km
2011-02-22T20:20:48.09720Z,1298406048.0972 [transit_3km:0.AltitudeEnvelope] Stopped
2011-02-22T20:20:48.09730Z,1298406048.0973 [transit_3km:0.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2011-02-22T20:20:48.09740Z,1298406048.0974 [transit_3km:1.DepthEnvelope] Stopped
2011-02-22T20:20:48.09750Z,1298406048.0975 [transit_3km:1.DepthEnvelope](DEBUG): Uninitialize.
2011-02-22T20:20:48.09760Z,1298406048.0976 [transit_3km:2.OffshoreEnvelope] Stopped
2011-02-22T20:20:48.09770Z,1298406048.0977 [transit_3km:2.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2011-02-22T20:20:48.09840Z,1298406048.0984 [transit_3km:SURFACECOMMS] Stopped
2011-02-22T20:20:48.09860Z,1298406048.0986 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2011-02-22T20:20:48.09880Z,1298406048.0988 [transit_3km:SURFACECOMMS:0.GoToSurface] Stopped
2011-02-22T20:20:48.09890Z,1298406048.0989 [transit_3km:SURFACECOMMS:0.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T20:20:48.09900Z,1298406048.099 [transit_3km:SURFACECOMMS:1] Stopped
2011-02-22T20:20:48.09910Z,1298406048.0991 [transit_3km:SURFACECOMMS:1](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:1
2011-02-22T20:20:48.09920Z,1298406048.0992 [transit_3km:SURFACECOMMS:1:0.SetSpeed] Stopped
2011-02-22T20:20:48.09930Z,1298406048.0993 [transit_3km:SURFACECOMMS:1:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T20:20:48.09940Z,1298406048.0994 [transit_3km:SURFACECOMMS:1:2] Stopped
2011-02-22T20:20:48.09950Z,1298406048.0995 [transit_3km:NeedComms] Stopped
2011-02-22T20:20:48.09960Z,1298406048.0996 [transit_3km:NeedComms](INFO): Aggregate::uninitialize transit_3km:NeedComms
2011-02-22T20:20:48.09980Z,1298406048.0998 [transit_3km:NeedComms:NEEDCOMMS] Stopped
2011-02-22T20:20:48.09990Z,1298406048.0999 [transit_3km:NeedComms:NEEDCOMMS](INFO): Aggregate::uninitialize transit_3km:NeedComms:NEEDCOMMS
2011-02-22T20:20:48.10000Z,1298406048.1 [transit_3km:5.Buoyancy] Stopped
2011-02-22T20:20:48.10010Z,1298406048.1001 [transit_3km:5.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2011-02-22T20:20:48.10020Z,1298406048.1002 [transit_3km:WaypointOne] Stopped
2011-02-22T20:20:48.10040Z,1298406048.1004 [transit_3km:WaypointOne](INFO): Aggregate::uninitialize transit_3km:WaypointOne
2011-02-22T20:20:48.10040Z,1298406048.1004 [transit_3km:WaypointOne:0.Pitch] Stopped
2011-02-22T20:20:48.10050Z,1298406048.1005 [transit_3km:WaypointOne:1.SetSpeed] Stopped
2011-02-22T20:20:48.10060Z,1298406048.1006 [transit_3km:WaypointOne:1.SetSpeed](DEBUG): Uninitialize.
2011-02-22T20:20:48.10070Z,1298406048.1007 [transit_3km:WaypointOne:WaypointW1.Waypoint] Stopped
2011-02-22T20:20:48.10080Z,1298406048.1008 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Uninitialize WaypointComponent.
2011-02-22T20:20:48.36370Z,1298406048.3637 [MissionManager](IMPORTANT): Started mission Default
2011-02-22T20:20:48.36380Z,1298406048.3638 [Default] Running Loop=1
2011-02-22T20:20:48.36400Z,1298406048.364 [Default](INFO): Aggregate::initialize Default
2011-02-22T20:20:48.36410Z,1298406048.3641 [Default:4.SetSpeed] Running Loop=1
2011-02-22T20:20:48.36420Z,1298406048.3642 [Default:4.SetSpeed](DEBUG): Initialize.
2011-02-22T20:20:48.36440Z,1298406048.3644 [Default:5.GoToSurface] Running Loop=1
2011-02-22T20:20:48.36440Z,1298406048.3644 [Default:5.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T20:20:48.36500Z,1298406048.365 [Default:GPS] Running Loop=1
2011-02-22T20:20:48.36510Z,1298406048.3651 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-02-22T20:20:48.36530Z,1298406048.3653 [Default:GPS:0.SetSpeed] Running Loop=1
2011-02-22T20:20:48.36530Z,1298406048.3653 [Default:GPS:0.SetSpeed](DEBUG): Initialize.
2011-02-22T20:20:48.36560Z,1298406048.3656 [Default:GPS:1.GoToSurface] Running Loop=1
2011-02-22T20:20:48.36570Z,1298406048.3657 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T20:20:48.36730Z,1298406048.3673 [Default:CallIridium] Running Loop=1
2011-02-22T20:20:48.36750Z,1298406048.3675 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-02-22T20:20:48.36770Z,1298406048.3677 [Default:CallIridium:0] Running Loop=1
2011-02-22T20:20:48.36780Z,1298406048.3678 [Default:CallIridium:0](INFO): Aggregate::initialize Default:CallIridium:0
2011-02-22T20:20:48.36830Z,1298406048.3683 [Default:GPS:1.GoToSurface] Stopped
2011-02-22T20:20:48.36840Z,1298406048.3684 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T20:20:48.36860Z,1298406048.3686 [Default:GPS:Read GPS] Running Loop=1
2011-02-22T20:20:48.74480Z,1298406048.7448 [Default:Iridium] Running Loop=1
2011-02-22T20:20:48.74500Z,1298406048.745 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-02-22T20:20:48.74510Z,1298406048.7451 [Default:Iridium:0.SetSpeed] Running Loop=1
2011-02-22T20:20:48.74520Z,1298406048.7452 [Default:Iridium:0.SetSpeed](DEBUG): Initialize.
2011-02-22T20:20:48.74550Z,1298406048.7455 [Default:Iridium:1.GoToSurface] Running Loop=1
2011-02-22T20:20:48.74560Z,1298406048.7456 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T20:20:48.74640Z,1298406048.7464 [Default:Iridium:1.GoToSurface] Stopped
2011-02-22T20:20:48.74650Z,1298406048.7465 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T20:20:48.74670Z,1298406048.7467 [Default:Iridium:Read Iridium] Running Loop=1
2011-02-22T20:20:50.40660Z,1298406050.4066 [NAL9601](IMPORTANT): GPS fix at: 1298406059
2011-02-22T20:20:50.42430Z,1298406050.4243 [Default:GPS:Read GPS] Stopped
2011-02-22T20:20:50.42470Z,1298406050.4247 [Default:GPS](INFO): Completed Default:GPS
2011-02-22T20:20:50.42490Z,1298406050.4249 [Default:GPS] Stopped
2011-02-22T20:20:50.42500Z,1298406050.425 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-02-22T20:20:50.42510Z,1298406050.4251 [Default:GPS:0.SetSpeed] Stopped
2011-02-22T20:20:50.42520Z,1298406050.4252 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T20:21:07.40190Z,1298406067.4019 [NAL9601](INFO): SBD MO Status=2, MOMSN=12711, MT Status=2, MTMSN=0
2011-02-22T20:21:07.40210Z,1298406067.4021 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:21:24.50460Z,1298406084.5046 [NAL9601](INFO): SBD MO Status=2, MOMSN=12711, MT Status=2, MTMSN=0
2011-02-22T20:21:24.50490Z,1298406084.5049 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:21:41.49800Z,1298406101.498 [NAL9601](INFO): SBD MO Status=2, MOMSN=12711, MT Status=2, MTMSN=0
2011-02-22T20:21:41.49830Z,1298406101.4983 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:22:06.51400Z,1298406126.514 [NAL9601](INFO): SBD MO Status=0, MOMSN=12711, MT Status=0, MTMSN=0
2011-02-22T20:22:06.65780Z,1298406126.6578 [Default:Iridium:Read Iridium] Stopped
2011-02-22T20:22:06.65830Z,1298406126.6583 [Default:Iridium](INFO): Completed Default:Iridium
2011-02-22T20:22:06.65840Z,1298406126.6584 [Default:Iridium] Stopped
2011-02-22T20:22:06.65860Z,1298406126.6586 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-02-22T20:22:06.65870Z,1298406126.6587 [Default:Iridium:0.SetSpeed] Stopped
2011-02-22T20:22:06.65880Z,1298406126.6588 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T20:22:06.65910Z,1298406126.6591 [Default:6.Wait] Running Loop=1
2011-02-22T20:22:06.65920Z,1298406126.6592 [Default:6.Wait](DEBUG): Initialize Wait Component.
2011-02-22T20:22:06.92920Z,1298406126.9292 [Default:CallIridium:0](INFO): Completed Default:CallIridium:0
2011-02-22T20:22:06.92930Z,1298406126.9293 [Default:CallIridium:0] Stopped
2011-02-22T20:22:06.92940Z,1298406126.9294 [Default:CallIridium:0](INFO): Aggregate::uninitialize Default:CallIridium:0
2011-02-22T20:22:06.92970Z,1298406126.9297 [Default:CallIridium](INFO): Completed Default:CallIridium
2011-02-22T20:22:06.92980Z,1298406126.9298 [Default:CallIridium] Stopped
2011-02-22T20:22:06.92990Z,1298406126.9299 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-02-22T20:22:17.01710Z,1298406137.0171 [NAL9601](INFO): Powering down
2011-02-22T20:25:52.08690Z,1298406352.0869 [Default:CallGPS] Running Loop=1
2011-02-22T20:25:52.08710Z,1298406352.0871 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-02-22T20:25:52.08730Z,1298406352.0873 [Default:CallGPS:0] Running Loop=1
2011-02-22T20:25:52.08750Z,1298406352.0875 [Default:CallGPS:0](INFO): Aggregate::initialize Default:CallGPS:0
2011-02-22T20:25:57.08670Z,1298406357.0867 [Default:GPS] Running Loop=1
2011-02-22T20:25:57.08690Z,1298406357.0869 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-02-22T20:25:57.08700Z,1298406357.087 [Default:GPS:0.SetSpeed] Running Loop=1
2011-02-22T20:25:57.08710Z,1298406357.0871 [Default:GPS:0.SetSpeed](DEBUG): Initialize.
2011-02-22T20:25:57.08740Z,1298406357.0874 [Default:GPS:1.GoToSurface] Running Loop=1
2011-02-22T20:25:57.08750Z,1298406357.0875 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T20:25:57.08830Z,1298406357.0883 [Default:GPS:1.GoToSurface] Stopped
2011-02-22T20:25:57.08840Z,1298406357.0884 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T20:25:57.08860Z,1298406357.0886 [Default:GPS:Read GPS] Running Loop=1
2011-02-22T20:25:57.72060Z,1298406357.7206 [NAL9601](INFO): Powering up
2011-02-22T20:26:22.55550Z,1298406382.5555 [BuoyancyServo](ERROR): EZ Servo:6 reading outside of valid range:0

2011-02-22T20:26:22.55560Z,1298406382.5556 [BuoyancyServo](FAULT): Buoyancy engine reporting null position
2011-02-22T20:26:22.55670Z,1298406382.5567 [BuoyancyServo] Hardware Fault, FailCount= 1
2011-02-22T20:26:22.55730Z,1298406382.5573 [BuoyancyServo](ERROR): Hardware Fault
2011-02-22T20:26:22.58980Z,1298406382.5898 [CBIT](ERROR): Hardware Fault in component: BuoyancyServo
2011-02-22T20:26:22.96370Z,1298406382.9637 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2011-02-22T20:26:22.96380Z,1298406382.9638 [BuoyancyServo](INFO): Powering down
2011-02-22T20:26:22.98990Z,1298406382.9899 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2011-02-22T20:26:22.99000Z,1298406382.99 [BuoyancyServo] No Fault, FailCount= 1
2011-02-22T20:26:23.72880Z,1298406383.7288 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2011-02-22T20:26:23.90300Z,1298406383.903 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2011-02-22T20:27:03.43140Z,1298406423.4314 [NAL9601](INFO): NAL9601 initialized
2011-02-22T20:27:06.92820Z,1298406426.9282 [Default:CallIridium] Running Loop=1
2011-02-22T20:27:06.92840Z,1298406426.9284 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-02-22T20:27:06.92860Z,1298406426.9286 [Default:CallIridium:0] Running Loop=1
2011-02-22T20:27:06.92870Z,1298406426.9287 [Default:CallIridium:0](INFO): Aggregate::initialize Default:CallIridium:0
2011-02-22T20:27:07.33140Z,1298406427.3314 [Default:Iridium] Running Loop=1
2011-02-22T20:27:07.33160Z,1298406427.3316 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-02-22T20:27:07.33170Z,1298406427.3317 [Default:Iridium:0.SetSpeed] Running Loop=1
2011-02-22T20:27:07.33180Z,1298406427.3318 [Default:Iridium:0.SetSpeed](DEBUG): Initialize.
2011-02-22T20:27:07.33210Z,1298406427.3321 [Default:Iridium:1.GoToSurface] Running Loop=1
2011-02-22T20:27:07.33220Z,1298406427.3322 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T20:27:07.33310Z,1298406427.3331 [Default:Iridium:1.GoToSurface] Stopped
2011-02-22T20:27:07.33320Z,1298406427.3332 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T20:27:07.33340Z,1298406427.3334 [Default:Iridium:Read Iridium] Running Loop=1
2011-02-22T20:27:35.64230Z,1298406455.6423 [NAL9601](INFO): SBD MO Status=2, MOMSN=12712, MT Status=2, MTMSN=0
2011-02-22T20:27:35.64260Z,1298406455.6426 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:27:59.16600Z,1298406479.166 [NAL9601](INFO): SBD MO Status=2, MOMSN=12712, MT Status=2, MTMSN=0
2011-02-22T20:27:59.16620Z,1298406479.1662 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:28:32.73020Z,1298406512.7302 [NAL9601](INFO): SBD MO Status=2, MOMSN=12712, MT Status=2, MTMSN=0
2011-02-22T20:28:32.73040Z,1298406512.7304 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:29:03.31240Z,1298406543.3124 [NAL9601](INFO): SBD MO Status=2, MOMSN=12712, MT Status=2, MTMSN=0
2011-02-22T20:29:03.31270Z,1298406543.3127 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:29:41.27000Z,1298406581.27 [NAL9601](INFO): SBD MO Status=2, MOMSN=12712, MT Status=2, MTMSN=0
2011-02-22T20:29:41.27020Z,1298406581.2702 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:29:42.47200Z,1298406582.472 [NAL9601](IMPORTANT): GPS fix at: 1298406592
2011-02-22T20:29:42.48860Z,1298406582.4886 [Default:GPS:Read GPS] Stopped
2011-02-22T20:29:42.48920Z,1298406582.4892 [Default:GPS](INFO): Completed Default:GPS
2011-02-22T20:29:42.48930Z,1298406582.4893 [Default:GPS] Stopped
2011-02-22T20:29:42.48940Z,1298406582.4894 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-02-22T20:29:42.48950Z,1298406582.4895 [Default:GPS:0.SetSpeed] Stopped
2011-02-22T20:29:42.48960Z,1298406582.4896 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T20:29:42.88400Z,1298406582.884 [Default:CallGPS:0](INFO): Completed Default:CallGPS:0
2011-02-22T20:29:42.88410Z,1298406582.8841 [Default:CallGPS:0] Stopped
2011-02-22T20:29:42.88430Z,1298406582.8843 [Default:CallGPS:0](INFO): Aggregate::uninitialize Default:CallGPS:0
2011-02-22T20:29:42.88450Z,1298406582.8845 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-02-22T20:29:42.88460Z,1298406582.8846 [Default:CallGPS] Stopped
2011-02-22T20:29:42.88470Z,1298406582.8847 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-02-22T20:30:11.66850Z,1298406611.6685 [NAL9601](INFO): SBD MO Status=2, MOMSN=12712, MT Status=2, MTMSN=0
2011-02-22T20:30:11.66880Z,1298406611.6688 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:30:36.77000Z,1298406636.77 [NAL9601](INFO): SBD MO Status=1, MOMSN=12712, MT Status=0, MTMSN=0
2011-02-22T20:30:36.88730Z,1298406636.8873 [NAL9601](INFO): Sent 261 bytes from file Logs/20110222T183731/shore0005.lzma
2011-02-22T20:30:36.88750Z,1298406636.8875 [NAL9601](INFO): Packets left to send: 0
2011-02-22T20:30:36.88860Z,1298406636.8886 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000008
2011-02-22T20:30:51.57000Z,1298406651.57 [NAL9601](INFO): SBD MO Status=0, MOMSN=12713, MT Status=0, MTMSN=0
2011-02-22T20:30:51.78310Z,1298406651.7831 [Default:Iridium:Read Iridium] Stopped
2011-02-22T20:30:51.78370Z,1298406651.7837 [Default:Iridium](INFO): Completed Default:Iridium
2011-02-22T20:30:51.78380Z,1298406651.7838 [Default:Iridium] Stopped
2011-02-22T20:30:51.78390Z,1298406651.7839 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-02-22T20:30:51.78400Z,1298406651.784 [Default:Iridium:0.SetSpeed] Stopped
2011-02-22T20:30:51.78410Z,1298406651.7841 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T20:30:51.98710Z,1298406651.9871 [Default:CallIridium:0](INFO): Completed Default:CallIridium:0
2011-02-22T20:30:51.98730Z,1298406651.9873 [Default:CallIridium:0] Stopped
2011-02-22T20:30:51.98740Z,1298406651.9874 [Default:CallIridium:0](INFO): Aggregate::uninitialize Default:CallIridium:0
2011-02-22T20:30:51.98760Z,1298406651.9876 [Default:CallIridium](INFO): Completed Default:CallIridium
2011-02-22T20:30:51.98770Z,1298406651.9877 [Default:CallIridium] Stopped
2011-02-22T20:30:51.98790Z,1298406651.9879 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-02-22T20:31:02.17870Z,1298406662.1787 [NAL9601](INFO): Powering down
2011-02-22T20:31:57.02960Z,1298406717.0296 [Batt_Ocean_Server](DEBUG): Bus busy reported for battery bank#7 STATUS: 65535
2011-02-22T20:34:47.15170Z,1298406887.1517 [Default:CallGPS] Running Loop=1
2011-02-22T20:34:47.15180Z,1298406887.1518 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-02-22T20:34:47.15210Z,1298406887.1521 [Default:CallGPS:0] Running Loop=1
2011-02-22T20:34:47.15220Z,1298406887.1522 [Default:CallGPS:0](INFO): Aggregate::initialize Default:CallGPS:0
2011-02-22T20:34:52.14210Z,1298406892.1421 [Default:GPS] Running Loop=1
2011-02-22T20:34:52.14230Z,1298406892.1423 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-02-22T20:34:52.14240Z,1298406892.1424 [Default:GPS:0.SetSpeed] Running Loop=1
2011-02-22T20:34:52.14250Z,1298406892.1425 [Default:GPS:0.SetSpeed](DEBUG): Initialize.
2011-02-22T20:34:52.14280Z,1298406892.1428 [Default:GPS:1.GoToSurface] Running Loop=1
2011-02-22T20:34:52.14290Z,1298406892.1429 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T20:34:52.14370Z,1298406892.1437 [Default:GPS:1.GoToSurface] Stopped
2011-02-22T20:34:52.14380Z,1298406892.1438 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T20:34:52.14400Z,1298406892.144 [Default:GPS:Read GPS] Running Loop=1
2011-02-22T20:34:52.76900Z,1298406892.769 [NAL9601](INFO): Powering up
2011-02-22T20:35:51.99130Z,1298406951.9913 [Default:CallIridium] Running Loop=1
2011-02-22T20:35:51.99150Z,1298406951.9915 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-02-22T20:35:51.99170Z,1298406951.9917 [Default:CallIridium:0] Running Loop=1
2011-02-22T20:35:51.99190Z,1298406951.9919 [Default:CallIridium:0](INFO): Aggregate::initialize Default:CallIridium:0
2011-02-22T20:35:52.41580Z,1298406952.4158 [Default:Iridium] Running Loop=1
2011-02-22T20:35:52.41600Z,1298406952.416 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-02-22T20:35:52.41610Z,1298406952.4161 [Default:Iridium:0.SetSpeed] Running Loop=1
2011-02-22T20:35:52.41620Z,1298406952.4162 [Default:Iridium:0.SetSpeed](DEBUG): Initialize.
2011-02-22T20:35:52.41650Z,1298406952.4165 [Default:Iridium:1.GoToSurface] Running Loop=1
2011-02-22T20:35:52.41650Z,1298406952.4165 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T20:35:52.41740Z,1298406952.4174 [Default:Iridium:1.GoToSurface] Stopped
2011-02-22T20:35:52.41750Z,1298406952.4175 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T20:35:52.41770Z,1298406952.4177 [Default:Iridium:Read Iridium] Running Loop=1
2011-02-22T20:35:58.47940Z,1298406958.4794 [NAL9601](INFO): NAL9601 initialized
2011-02-22T20:36:24.71020Z,1298406984.7102 [NAL9601](INFO): SBD MO Status=2, MOMSN=12714, MT Status=2, MTMSN=0
2011-02-22T20:36:24.71040Z,1298406984.7104 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:36:51.95020Z,1298407011.9502 [NAL9601](INFO): SBD MO Status=2, MOMSN=12714, MT Status=2, MTMSN=0
2011-02-22T20:36:51.95040Z,1298407011.9504 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:37:16.68200Z,1298407036.682 [NAL9601](INFO): SBD MO Status=2, MOMSN=12714, MT Status=2, MTMSN=0
2011-02-22T20:37:16.68220Z,1298407036.6822 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:37:40.21040Z,1298407060.2104 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=12714, MT Status=1, MTMSN=1568
2011-02-22T20:37:40.41130Z,1298407060.4113 [NAL9601](INFO): Sent 120 bytes from file Logs/20110222T183731/shore0006.lzma
2011-02-22T20:37:40.41150Z,1298407060.4115 [NAL9601](INFO): Packets left to send: 0
2011-02-22T20:37:40.41260Z,1298407060.4126 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000009
2011-02-22T20:37:40.93570Z,1298407060.9357 [NAL9601](IMPORTANT): Initialized file: Config/lrauv-tethys/Sensor.cfg
2011-02-22T20:37:44.21060Z,1298407064.2106 [NAL9601](IMPORTANT): Success executing cat Logs/latest/4D641D39.part | gunzip -f -d | cat `cp Config/lrauv-tethys/.svn/text-base/Sensor.cfg.svn-base Config/lrauv-tethys/Sensor.cfg` | vim -e Config/lrauv-tethys/Sensor.cfg
2011-02-22T20:37:44.29490Z,1298407064.2949 [CommandLine](IMPORTANT): ed5bf924bfdad92c7bd14f0b4b674763  Config/lrauv-tethys/Sensor.cfg

2011-02-22T20:38:09.05810Z,1298407089.0581 [NAL9601](INFO): SBD MO Status=2, MOMSN=12715, MT Status=2, MTMSN=0
2011-02-22T20:38:09.05840Z,1298407089.0584 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:38:14.16750Z,1298407094.1675 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T20:38:38.75830Z,1298407118.7583 [NAL9601](INFO): SBD MO Status=2, MOMSN=12715, MT Status=2, MTMSN=0
2011-02-22T20:38:38.75850Z,1298407118.7585 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:38:43.76480Z,1298407123.7648 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T20:39:03.61400Z,1298407143.614 [NAL9601](INFO): SBD MO Status=2, MOMSN=12715, MT Status=2, MTMSN=0
2011-02-22T20:39:03.61430Z,1298407143.6143 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:39:04.84750Z,1298407144.8475 [NAL9601](IMPORTANT): GPS fix at: 1298407155
2011-02-22T20:39:04.86480Z,1298407144.8648 [Default:GPS:Read GPS] Stopped
2011-02-22T20:39:04.86540Z,1298407144.8654 [Default:GPS](INFO): Completed Default:GPS
2011-02-22T20:39:04.86550Z,1298407144.8655 [Default:GPS] Stopped
2011-02-22T20:39:04.86560Z,1298407144.8656 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-02-22T20:39:04.86570Z,1298407144.8657 [Default:GPS:0.SetSpeed] Stopped
2011-02-22T20:39:04.86580Z,1298407144.8658 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T20:39:05.22900Z,1298407145.229 [Default:CallGPS:0](INFO): Completed Default:CallGPS:0
2011-02-22T20:39:05.22910Z,1298407145.2291 [Default:CallGPS:0] Stopped
2011-02-22T20:39:05.22920Z,1298407145.2292 [Default:CallGPS:0](INFO): Aggregate::uninitialize Default:CallGPS:0
2011-02-22T20:39:05.22950Z,1298407145.2295 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-02-22T20:39:05.22960Z,1298407145.2296 [Default:CallGPS] Stopped
2011-02-22T20:39:05.22970Z,1298407145.2297 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-02-22T20:39:20.70220Z,1298407160.7022 [NAL9601](INFO): SBD MO Status=2, MOMSN=12715, MT Status=2, MTMSN=0
2011-02-22T20:39:20.70250Z,1298407160.7025 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:39:38.94560Z,1298407178.9456 [NAL9601](INFO): SBD MO Status=2, MOMSN=12715, MT Status=2, MTMSN=0
2011-02-22T20:39:38.94590Z,1298407178.9459 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:39:43.96460Z,1298407183.9646 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T20:39:47.34930Z,1298407187.3493 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T20:40:19.56210Z,1298407219.5621 [NAL9601](INFO): SBD MO Status=2, MOMSN=12715, MT Status=2, MTMSN=0
2011-02-22T20:40:19.56240Z,1298407219.5624 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:40:41.78420Z,1298407241.7842 [NAL9601](INFO): SBD MO Status=2, MOMSN=12715, MT Status=2, MTMSN=0
2011-02-22T20:40:41.78440Z,1298407241.7844 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:40:56.82170Z,1298407256.8217 [NAL9601](INFO): SBD MO Status=2, MOMSN=12715, MT Status=2, MTMSN=0
2011-02-22T20:40:56.82200Z,1298407256.822 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:41:01.83650Z,1298407261.8365 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T20:41:04.85300Z,1298407264.853 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0
2011-02-22T20:41:17.10220Z,1298407277.1022 [NAL9601](INFO): SBD MO Status=0, MOMSN=12715, MT Status=0, MTMSN=0
2011-02-22T20:41:17.29090Z,1298407277.2909 [Default:Iridium:Read Iridium] Stopped
2011-02-22T20:41:17.29140Z,1298407277.2914 [Default:Iridium](INFO): Completed Default:Iridium
2011-02-22T20:41:17.29150Z,1298407277.2915 [Default:Iridium] Stopped
2011-02-22T20:41:17.29170Z,1298407277.2917 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-02-22T20:41:17.29180Z,1298407277.2918 [Default:Iridium:0.SetSpeed] Stopped
2011-02-22T20:41:17.29190Z,1298407277.2919 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T20:41:17.51660Z,1298407277.5166 [Default:CallIridium:0](INFO): Completed Default:CallIridium:0
2011-02-22T20:41:17.51670Z,1298407277.5167 [Default:CallIridium:0] Stopped
2011-02-22T20:41:17.51690Z,1298407277.5169 [Default:CallIridium:0](INFO): Aggregate::uninitialize Default:CallIridium:0
2011-02-22T20:41:17.51710Z,1298407277.5171 [Default:CallIridium](INFO): Completed Default:CallIridium
2011-02-22T20:41:17.51720Z,1298407277.5172 [Default:CallIridium] Stopped
2011-02-22T20:41:17.51740Z,1298407277.5174 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-02-22T20:41:27.65940Z,1298407287.6594 [NAL9601](INFO): Powering down
2011-02-22T20:44:07.67450Z,1298407447.6745 [Default:CallGPS] Running Loop=1
2011-02-22T20:44:07.67500Z,1298407447.675 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-02-22T20:44:07.67520Z,1298407447.6752 [Default:CallGPS:0] Running Loop=1
2011-02-22T20:44:07.67540Z,1298407447.6754 [Default:CallGPS:0](INFO): Aggregate::initialize Default:CallGPS:0
2011-02-22T20:44:12.67420Z,1298407452.6742 [Default:GPS] Running Loop=1
2011-02-22T20:44:12.67440Z,1298407452.6744 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-02-22T20:44:12.67460Z,1298407452.6746 [Default:GPS:0.SetSpeed] Running Loop=1
2011-02-22T20:44:12.67490Z,1298407452.6749 [Default:GPS:0.SetSpeed](DEBUG): Initialize.
2011-02-22T20:44:12.67520Z,1298407452.6752 [Default:GPS:1.GoToSurface] Running Loop=1
2011-02-22T20:44:12.67530Z,1298407452.6753 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T20:44:12.67610Z,1298407452.6761 [Default:GPS:1.GoToSurface] Stopped
2011-02-22T20:44:12.67620Z,1298407452.6762 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T20:44:12.67640Z,1298407452.6764 [Default:GPS:Read GPS] Running Loop=1
2011-02-22T20:44:13.30050Z,1298407453.3005 [NAL9601](INFO): Powering up
2011-02-22T20:45:19.01140Z,1298407519.0114 [NAL9601](INFO): NAL9601 initialized
2011-02-22T20:46:17.31820Z,1298407577.3182 [Default:CallIridium] Running Loop=1
2011-02-22T20:46:17.31840Z,1298407577.3184 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-02-22T20:46:17.31860Z,1298407577.3186 [Default:CallIridium:0] Running Loop=1
2011-02-22T20:46:17.31880Z,1298407577.3188 [Default:CallIridium:0](INFO): Aggregate::initialize Default:CallIridium:0
2011-02-22T20:46:17.71610Z,1298407577.7161 [Default:Iridium] Running Loop=1
2011-02-22T20:46:17.71630Z,1298407577.7163 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-02-22T20:46:17.71640Z,1298407577.7164 [Default:Iridium:0.SetSpeed] Running Loop=1
2011-02-22T20:46:17.71650Z,1298407577.7165 [Default:Iridium:0.SetSpeed](DEBUG): Initialize.
2011-02-22T20:46:17.71680Z,1298407577.7168 [Default:Iridium:1.GoToSurface] Running Loop=1
2011-02-22T20:46:17.71690Z,1298407577.7169 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T20:46:17.71770Z,1298407577.7177 [Default:Iridium:1.GoToSurface] Stopped
2011-02-22T20:46:17.71780Z,1298407577.7178 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T20:46:17.71800Z,1298407577.718 [Default:Iridium:Read Iridium] Running Loop=1
2011-02-22T20:47:07.66610Z,1298407627.6661 [NAL9601](INFO): SBD MO Status=2, MOMSN=12716, MT Status=2, MTMSN=0
2011-02-22T20:47:07.66640Z,1298407627.6664 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:47:25.18570Z,1298407645.1857 [NAL9601](INFO): SBD MO Status=2, MOMSN=12716, MT Status=2, MTMSN=0
2011-02-22T20:47:25.18590Z,1298407645.1859 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:47:52.71800Z,1298407672.718 [NAL9601](INFO): SBD MO Status=2, MOMSN=12716, MT Status=2, MTMSN=0
2011-02-22T20:47:52.71820Z,1298407672.7182 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:47:53.92020Z,1298407673.9202 [NAL9601](IMPORTANT): GPS fix at: 1298407685
2011-02-22T20:47:53.93720Z,1298407673.9372 [Default:GPS:Read GPS] Stopped
2011-02-22T20:47:53.93760Z,1298407673.9376 [Default:GPS](INFO): Completed Default:GPS
2011-02-22T20:47:53.93780Z,1298407673.9378 [Default:GPS] Stopped
2011-02-22T20:47:53.93790Z,1298407673.9379 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-02-22T20:47:53.93800Z,1298407673.938 [Default:GPS:0.SetSpeed] Stopped
2011-02-22T20:47:53.93810Z,1298407673.9381 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T20:47:54.38990Z,1298407674.3899 [Default:CallGPS:0](INFO): Completed Default:CallGPS:0
2011-02-22T20:47:54.39000Z,1298407674.39 [Default:CallGPS:0] Stopped
2011-02-22T20:47:54.39020Z,1298407674.3902 [Default:CallGPS:0](INFO): Aggregate::uninitialize Default:CallGPS:0
2011-02-22T20:47:54.39050Z,1298407674.3905 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-02-22T20:47:54.39060Z,1298407674.3906 [Default:CallGPS] Stopped
2011-02-22T20:47:54.39080Z,1298407674.3908 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-02-22T20:48:17.45420Z,1298407697.4542 [NAL9601](INFO): SBD MO Status=2, MOMSN=12716, MT Status=2, MTMSN=0
2011-02-22T20:48:17.45450Z,1298407697.4545 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:48:34.98610Z,1298407714.9861 [NAL9601](INFO): SBD MO Status=2, MOMSN=12716, MT Status=2, MTMSN=0
2011-02-22T20:48:34.98640Z,1298407714.9864 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:49:15.84020Z,1298407755.8402 [NAL9601](INFO): SBD MO Status=2, MOMSN=12716, MT Status=2, MTMSN=0
2011-02-22T20:49:15.84050Z,1298407755.8405 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:49:50.50230Z,1298407790.5023 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=12716, MT Status=1, MTMSN=1569
2011-02-22T20:49:50.67930Z,1298407790.6793 [NAL9601](INFO): Sent 332 bytes from file Logs/20110222T183731/shore0007.lzma
2011-02-22T20:49:50.67950Z,1298407790.6795 [NAL9601](INFO): Packets left to send: 1
2011-02-22T20:49:50.68070Z,1298407790.6807 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000010
2011-02-22T20:49:51.22440Z,1298407791.2244 [NAL9601](IMPORTANT): Initialized file: Config/lrauv-tethys/Sensor.cfg
2011-02-22T20:49:53.14260Z,1298407793.1426 [NAL9601](IMPORTANT): Success executing cat Logs/latest/4D642019.part | gunzip -f -d | cat `cp Config/lrauv-tethys/.svn/text-base/Sensor.cfg.svn-base Config/lrauv-tethys/Sensor.cfg` | vim -e Config/lrauv-tethys/Sensor.cfg
2011-02-22T20:49:53.20070Z,1298407793.2007 [CommandLine](IMPORTANT): f246eab858122c8cb8a59793975829c9  Config/lrauv-tethys/Sensor.cfg

2011-02-22T20:50:15.76620Z,1298407815.7662 [NAL9601](INFO): SBD MO Status=1, MOMSN=12717, MT Status=0, MTMSN=0
2011-02-22T20:50:15.93930Z,1298407815.9393 [NAL9601](INFO): Sent 28 bytes from file Logs/20110222T183731/shore0007.lzma
2011-02-22T20:50:15.93950Z,1298407815.9395 [NAL9601](INFO): Packets left to send: 0
2011-02-22T20:50:15.94060Z,1298407815.9406 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000011
2011-02-22T20:50:32.96210Z,1298407832.9621 [NAL9601](INFO): SBD MO Status=2, MOMSN=12718, MT Status=2, MTMSN=0
2011-02-22T20:50:32.96240Z,1298407832.9624 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:50:55.58640Z,1298407855.5864 [NAL9601](INFO): SBD MO Status=2, MOMSN=12718, MT Status=2, MTMSN=0
2011-02-22T20:50:55.58680Z,1298407855.5868 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:51:06.60190Z,1298407866.6019 [NAL9601](INFO): SBD MO Status=0, MOMSN=12718, MT Status=0, MTMSN=0
2011-02-22T20:51:06.77460Z,1298407866.7746 [Default:Iridium:Read Iridium] Stopped
2011-02-22T20:51:06.77530Z,1298407866.7753 [Default:Iridium](INFO): Completed Default:Iridium
2011-02-22T20:51:06.77540Z,1298407866.7754 [Default:Iridium] Stopped
2011-02-22T20:51:06.77560Z,1298407866.7756 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-02-22T20:51:06.77570Z,1298407866.7757 [Default:Iridium:0.SetSpeed] Stopped
2011-02-22T20:51:06.77580Z,1298407866.7758 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T20:51:07.01630Z,1298407867.0163 [Default:CallIridium:0](INFO): Completed Default:CallIridium:0
2011-02-22T20:51:07.01640Z,1298407867.0164 [Default:CallIridium:0] Stopped
2011-02-22T20:51:07.01650Z,1298407867.0165 [Default:CallIridium:0](INFO): Aggregate::uninitialize Default:CallIridium:0
2011-02-22T20:51:07.01680Z,1298407867.0168 [Default:CallIridium](INFO): Completed Default:CallIridium
2011-02-22T20:51:07.01690Z,1298407867.0169 [Default:CallIridium] Stopped
2011-02-22T20:51:07.01700Z,1298407867.017 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-02-22T20:51:17.15700Z,1298407877.157 [NAL9601](INFO): Powering down
2011-02-22T20:52:57.19930Z,1298407977.1993 [Default:CallGPS] Running Loop=1
2011-02-22T20:52:57.19950Z,1298407977.1995 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-02-22T20:52:57.19980Z,1298407977.1998 [Default:CallGPS:0] Running Loop=1
2011-02-22T20:52:57.19990Z,1298407977.1999 [Default:CallGPS:0](INFO): Aggregate::initialize Default:CallGPS:0
2011-02-22T20:53:02.14290Z,1298407982.1429 [Default:GPS] Running Loop=1
2011-02-22T20:53:02.14310Z,1298407982.1431 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-02-22T20:53:02.14320Z,1298407982.1432 [Default:GPS:0.SetSpeed] Running Loop=1
2011-02-22T20:53:02.14330Z,1298407982.1433 [Default:GPS:0.SetSpeed](DEBUG): Initialize.
2011-02-22T20:53:02.14360Z,1298407982.1436 [Default:GPS:1.GoToSurface] Running Loop=1
2011-02-22T20:53:02.14370Z,1298407982.1437 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T20:53:02.14450Z,1298407982.1445 [Default:GPS:1.GoToSurface] Stopped
2011-02-22T20:53:02.14460Z,1298407982.1446 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T20:53:02.14480Z,1298407982.1448 [Default:GPS:Read GPS] Running Loop=1
2011-02-22T20:53:02.80080Z,1298407982.8008 [NAL9601](INFO): Powering up
2011-02-22T20:54:08.51140Z,1298408048.5114 [NAL9601](INFO): NAL9601 initialized
2011-02-22T20:54:09.60380Z,1298408049.6038 [NAL9601](IMPORTANT): GPS fix at: 1298408061
2011-02-22T20:54:09.62020Z,1298408049.6202 [Default:GPS:Read GPS] Stopped
2011-02-22T20:54:09.62090Z,1298408049.6209 [Default:GPS](INFO): Completed Default:GPS
2011-02-22T20:54:09.62100Z,1298408049.621 [Default:GPS] Stopped
2011-02-22T20:54:09.62110Z,1298408049.6211 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-02-22T20:54:09.62120Z,1298408049.6212 [Default:GPS:0.SetSpeed] Stopped
2011-02-22T20:54:09.62130Z,1298408049.6213 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T20:54:10.01730Z,1298408050.0173 [Default:CallGPS:0](INFO): Completed Default:CallGPS:0
2011-02-22T20:54:10.01750Z,1298408050.0175 [Default:CallGPS:0] Stopped
2011-02-22T20:54:10.01760Z,1298408050.0176 [Default:CallGPS:0](INFO): Aggregate::uninitialize Default:CallGPS:0
2011-02-22T20:54:10.01780Z,1298408050.0178 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-02-22T20:54:10.01790Z,1298408050.0179 [Default:CallGPS] Stopped
2011-02-22T20:54:10.01810Z,1298408050.0181 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-02-22T20:54:30.10260Z,1298408070.1026 [NAL9601](INFO): Powering down
2011-02-22T20:56:10.15070Z,1298408170.1507 [Default:CallIridium] Running Loop=1
2011-02-22T20:56:10.15090Z,1298408170.1509 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-02-22T20:56:10.15110Z,1298408170.1511 [Default:CallIridium:0] Running Loop=1
2011-02-22T20:56:10.15130Z,1298408170.1513 [Default:CallIridium:0](INFO): Aggregate::initialize Default:CallIridium:0
2011-02-22T20:56:15.15000Z,1298408175.15 [Default:Iridium] Running Loop=1
2011-02-22T20:56:15.15020Z,1298408175.1502 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-02-22T20:56:15.15030Z,1298408175.1503 [Default:Iridium:0.SetSpeed] Running Loop=1
2011-02-22T20:56:15.15040Z,1298408175.1504 [Default:Iridium:0.SetSpeed](DEBUG): Initialize.
2011-02-22T20:56:15.15080Z,1298408175.1508 [Default:Iridium:1.GoToSurface] Running Loop=1
2011-02-22T20:56:15.15090Z,1298408175.1509 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T20:56:15.15170Z,1298408175.1517 [Default:Iridium:1.GoToSurface] Stopped
2011-02-22T20:56:15.15180Z,1298408175.1518 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T20:56:15.15200Z,1298408175.152 [Default:Iridium:Read Iridium] Running Loop=1
2011-02-22T20:56:15.80070Z,1298408175.8007 [NAL9601](INFO): Powering up
2011-02-22T20:57:21.51150Z,1298408241.5115 [NAL9601](INFO): NAL9601 initialized
2011-02-22T20:57:46.61190Z,1298408266.6119 [NAL9601](INFO): SBD MO Status=2, MOMSN=12719, MT Status=2, MTMSN=0
2011-02-22T20:57:46.61210Z,1298408266.6121 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:58:10.49010Z,1298408290.4901 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=12719, MT Status=1, MTMSN=1570
2011-02-22T20:58:10.62330Z,1298408290.6233 [NAL9601](INFO): Sent 332 bytes from file Logs/20110222T183731/shore0008.lzma
2011-02-22T20:58:10.62360Z,1298408290.6236 [NAL9601](INFO): Packets left to send: 1
2011-02-22T20:58:10.62470Z,1298408290.6247 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000012
2011-02-22T20:58:11.04150Z,1298408291.0415 [NAL9601](INFO): Received command:run Insert/Surface.xml
2011-02-22T20:58:11.11920Z,1298408291.1192 [CommandLine](IMPORTANT): got command run ./Missions/Insert/Surface.xml
2011-02-22T20:58:11.11950Z,1298408291.1195 [MissionManager](INFO): Loading Mission: ./Missions/Insert/Surface.xml
2011-02-22T20:58:11.13760Z,1298408291.1376 [MissionManager](INFO): DefineArg IridiumTimeout = 30 min
2011-02-22T20:58:11.13900Z,1298408291.139 [SurfaceComms:0.GoToSurface](DEBUG): Construct GoToSurface.
2011-02-22T20:58:11.15050Z,1298408291.1505 [MissionManager](DEBUG): Initialize ReadDataComponent to sense time_fix
2011-02-22T20:58:11.15280Z,1298408291.1528 [MissionManager](DEBUG): Initialize ReadDataComponent to sense platform_communications
2011-02-22T20:58:11.15600Z,1298408291.156 [MissionManager](DEBUG): Initialize ReadDataComponent to sense time_fix
2011-02-22T20:58:11.15810Z,1298408291.1581 [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-22T20:58:11.15860Z,1298408291.1586 [CommandLine](IMPORTANT): Running ./Missions/Insert/Surface.xml
2011-02-22T20:58:11.30280Z,1298408291.3028 [Default] Stopped
2011-02-22T20:58:11.30300Z,1298408291.303 [Default](INFO): Aggregate::uninitialize Default
2011-02-22T20:58:11.30310Z,1298408291.3031 [Default:Iridium] Stopped
2011-02-22T20:58:11.30330Z,1298408291.3033 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-02-22T20:58:11.30340Z,1298408291.3034 [Default:Iridium:0.SetSpeed] Stopped
2011-02-22T20:58:11.30340Z,1298408291.3034 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T20:58:11.30350Z,1298408291.3035 [Default:Iridium:Read Iridium] Stopped
2011-02-22T20:58:11.30360Z,1298408291.3036 [Default:CallIridium] Stopped
2011-02-22T20:58:11.30380Z,1298408291.3038 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-02-22T20:58:11.30390Z,1298408291.3039 [Default:CallIridium:0] Stopped
2011-02-22T20:58:11.30400Z,1298408291.304 [Default:CallIridium:0](INFO): Aggregate::uninitialize Default:CallIridium:0
2011-02-22T20:58:11.30410Z,1298408291.3041 [Default:4.SetSpeed] Stopped
2011-02-22T20:58:11.30420Z,1298408291.3042 [Default:4.SetSpeed](DEBUG): Uninitialize.
2011-02-22T20:58:11.30430Z,1298408291.3043 [Default:5.GoToSurface] Stopped
2011-02-22T20:58:11.30440Z,1298408291.3044 [Default:5.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T20:58:11.30450Z,1298408291.3045 [Default:6.Wait] Stopped
2011-02-22T20:58:11.30460Z,1298408291.3046 [Default:6.Wait](DEBUG): Uninitialize Wait Component.
2011-02-22T20:58:11.30470Z,1298408291.3047 [MissionManager](IMPORTANT): Started mission SurfaceComms
2011-02-22T20:58:11.30480Z,1298408291.3048 [SurfaceComms] Running Loop=1
2011-02-22T20:58:11.30500Z,1298408291.305 [SurfaceComms](INFO): Aggregate::initialize SurfaceComms
2011-02-22T20:58:11.30510Z,1298408291.3051 [SurfaceComms:0.GoToSurface] Running Loop=1
2011-02-22T20:58:11.30520Z,1298408291.3052 [SurfaceComms:0.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T20:58:11.31450Z,1298408291.3145 [SurfaceComms:1] Running Loop=1
2011-02-22T20:58:11.31470Z,1298408291.3147 [SurfaceComms:1](INFO): Aggregate::initialize SurfaceComms:1
2011-02-22T20:58:11.31500Z,1298408291.315 [SurfaceComms:1:0] Running Loop=1
2011-02-22T20:58:12.89210Z,1298408292.8921 [NAL9601](IMPORTANT): GPS fix at: 1298408305
2011-02-22T20:58:12.90760Z,1298408292.9076 [SurfaceComms:1:0] Stopped
2011-02-22T20:58:12.90790Z,1298408292.9079 [SurfaceComms:1:1] Running Loop=1
2011-02-22T20:58:37.61000Z,1298408317.61 [NAL9601](INFO): SBD MO Status=2, MOMSN=12720, MT Status=2, MTMSN=0
2011-02-22T20:58:37.61020Z,1298408317.6102 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:58:56.89000Z,1298408336.89 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=12720, MT Status=1, MTMSN=1571
2011-02-22T20:58:57.05190Z,1298408337.0519 [NAL9601](INFO): Sent 37 bytes from file Logs/20110222T183731/shore0008.lzma
2011-02-22T20:58:57.05220Z,1298408337.0522 [NAL9601](INFO): Packets left to send: 0
2011-02-22T20:58:57.05330Z,1298408337.0533 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000013
2011-02-22T20:58:57.46950Z,1298408337.4695 [NAL9601](INFO): Received command:run Insert/Surface.xml
2011-02-22T20:58:57.55920Z,1298408337.5592 [CommandLine](IMPORTANT): got command run ./Missions/Insert/Surface.xml
2011-02-22T20:58:57.55930Z,1298408337.5593 [SurfaceComms] Stopped
2011-02-22T20:58:57.55950Z,1298408337.5595 [SurfaceComms](INFO): Aggregate::uninitialize SurfaceComms
2011-02-22T20:58:57.55960Z,1298408337.5596 [SurfaceComms:0.GoToSurface] Stopped
2011-02-22T20:58:57.55970Z,1298408337.5597 [SurfaceComms:0.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T20:58:57.55980Z,1298408337.5598 [SurfaceComms:1] Stopped
2011-02-22T20:58:57.55990Z,1298408337.5599 [SurfaceComms:1](INFO): Aggregate::uninitialize SurfaceComms:1
2011-02-22T20:58:57.56000Z,1298408337.56 [SurfaceComms:1:1] Stopped
2011-02-22T20:58:57.56170Z,1298408337.5617 [MissionManager](INFO): Loading Mission: ./Missions/Insert/Surface.xml
2011-02-22T20:58:57.57620Z,1298408337.5762 [MissionManager](INFO): DefineArg IridiumTimeout = 30 min
2011-02-22T20:58:57.57740Z,1298408337.5774 [SurfaceComms:0.GoToSurface](DEBUG): Construct GoToSurface.
2011-02-22T20:58:57.58320Z,1298408337.5832 [MissionManager](DEBUG): Initialize ReadDataComponent to sense time_fix
2011-02-22T20:58:57.58490Z,1298408337.5849 [MissionManager](DEBUG): Initialize ReadDataComponent to sense platform_communications
2011-02-22T20:58:57.58740Z,1298408337.5874 [MissionManager](DEBUG): Initialize ReadDataComponent to sense time_fix
2011-02-22T20:58:57.58960Z,1298408337.5896 [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-22T20:58:57.59000Z,1298408337.59 [CommandLine](IMPORTANT): Running ./Missions/Insert/Surface.xml
2011-02-22T20:58:57.70360Z,1298408337.7036 [MissionManager](IMPORTANT): Started mission SurfaceComms
2011-02-22T20:58:57.70370Z,1298408337.7037 [SurfaceComms] Running Loop=1
2011-02-22T20:58:57.70390Z,1298408337.7039 [SurfaceComms](INFO): Aggregate::initialize SurfaceComms
2011-02-22T20:58:57.70400Z,1298408337.704 [SurfaceComms:0.GoToSurface] Running Loop=1
2011-02-22T20:58:57.70410Z,1298408337.7041 [SurfaceComms:0.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T20:58:57.70620Z,1298408337.7062 [SurfaceComms:1] Running Loop=1
2011-02-22T20:58:57.70640Z,1298408337.7064 [SurfaceComms:1](INFO): Aggregate::initialize SurfaceComms:1
2011-02-22T20:58:57.70660Z,1298408337.7066 [SurfaceComms:1:0] Running Loop=1
2011-02-22T20:58:59.71770Z,1298408339.7177 [NAL9601](IMPORTANT): GPS fix at: 1298408352
2011-02-22T20:58:59.73340Z,1298408339.7334 [SurfaceComms:1:0] Stopped
2011-02-22T20:58:59.73370Z,1298408339.7337 [SurfaceComms:1:1] Running Loop=1
2011-02-22T20:59:26.41010Z,1298408366.4101 [NAL9601](INFO): SBD MO Status=2, MOMSN=12721, MT Status=2, MTMSN=0
2011-02-22T20:59:26.41040Z,1298408366.4104 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T20:59:52.38380Z,1298408392.3838 [NAL9601](INFO): SBD MO Status=2, MOMSN=12721, MT Status=2, MTMSN=0
2011-02-22T20:59:52.38400Z,1298408392.384 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T21:00:15.50990Z,1298408415.5099 [NAL9601](INFO): SBD MO Status=1, MOMSN=12721, MT Status=0, MTMSN=0
2011-02-22T21:00:15.63130Z,1298408415.6313 [NAL9601](INFO): Sent 254 bytes from file Logs/20110222T183731/shore0009.lzma
2011-02-22T21:00:15.63150Z,1298408415.6315 [NAL9601](INFO): Packets left to send: 0
2011-02-22T21:00:15.63270Z,1298408415.6327 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000014
2011-02-22T21:00:37.10600Z,1298408437.106 [NAL9601](INFO): SBD MO Status=0, MOMSN=12722, MT Status=0, MTMSN=0
2011-02-22T21:00:37.31230Z,1298408437.3123 [SurfaceComms:1:1] Stopped
2011-02-22T21:00:37.31250Z,1298408437.3125 [SurfaceComms:1:2] Running Loop=1
2011-02-22T21:00:39.51180Z,1298408439.5118 [NAL9601](IMPORTANT): GPS fix at: 1298408452
2011-02-22T21:00:39.52670Z,1298408439.5267 [SurfaceComms:1:2] Stopped
2011-02-22T21:00:39.52700Z,1298408439.527 [SurfaceComms:1](INFO): Completed SurfaceComms:1
2011-02-22T21:00:39.52710Z,1298408439.5271 [SurfaceComms:1] Stopped
2011-02-22T21:00:39.52730Z,1298408439.5273 [SurfaceComms:1](INFO): Aggregate::uninitialize SurfaceComms:1
2011-02-22T21:00:39.52790Z,1298408439.5279 [SurfaceComms](INFO): Completed SurfaceComms
2011-02-22T21:00:39.52800Z,1298408439.528 [SurfaceComms] Stopped
2011-02-22T21:00:39.52810Z,1298408439.5281 [SurfaceComms](INFO): Aggregate::uninitialize SurfaceComms
2011-02-22T21:00:39.52820Z,1298408439.5282 [SurfaceComms:0.GoToSurface] Stopped
2011-02-22T21:00:39.52830Z,1298408439.5283 [SurfaceComms:0.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T21:00:39.92390Z,1298408439.9239 [MissionManager](IMPORTANT): Started mission Default
2011-02-22T21:00:39.92400Z,1298408439.924 [Default] Running Loop=1
2011-02-22T21:00:39.92420Z,1298408439.9242 [Default](INFO): Aggregate::initialize Default
2011-02-22T21:00:39.92430Z,1298408439.9243 [Default:4.SetSpeed] Running Loop=1
2011-02-22T21:00:39.92440Z,1298408439.9244 [Default:4.SetSpeed](DEBUG): Initialize.
2011-02-22T21:00:39.92450Z,1298408439.9245 [Default:5.GoToSurface] Running Loop=1
2011-02-22T21:00:39.92460Z,1298408439.9246 [Default:5.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T21:00:39.92520Z,1298408439.9252 [Default:GPS] Running Loop=1
2011-02-22T21:00:39.92530Z,1298408439.9253 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-02-22T21:00:39.92540Z,1298408439.9254 [Default:GPS:0.SetSpeed] Running Loop=1
2011-02-22T21:00:39.92550Z,1298408439.9255 [Default:GPS:0.SetSpeed](DEBUG): Initialize.
2011-02-22T21:00:39.92580Z,1298408439.9258 [Default:GPS:1.GoToSurface] Running Loop=1
2011-02-22T21:00:39.92590Z,1298408439.9259 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T21:00:39.92780Z,1298408439.9278 [Default:GPS:1.GoToSurface] Stopped
2011-02-22T21:00:39.92790Z,1298408439.9279 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T21:00:39.92810Z,1298408439.9281 [Default:GPS:Read GPS] Running Loop=1
2011-02-22T21:00:41.56530Z,1298408441.5653 [NAL9601](IMPORTANT): GPS fix at: 1298408454
2011-02-22T21:00:41.58140Z,1298408441.5814 [Default:GPS:Read GPS] Stopped
2011-02-22T21:00:41.58190Z,1298408441.5819 [Default:GPS](INFO): Completed Default:GPS
2011-02-22T21:00:41.58200Z,1298408441.582 [Default:GPS] Stopped
2011-02-22T21:00:41.58220Z,1298408441.5822 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-02-22T21:00:41.58230Z,1298408441.5823 [Default:GPS:0.SetSpeed] Stopped
2011-02-22T21:00:41.58240Z,1298408441.5824 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T21:00:41.58260Z,1298408441.5826 [Default:Iridium] Running Loop=1
2011-02-22T21:00:41.58280Z,1298408441.5828 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-02-22T21:00:41.58290Z,1298408441.5829 [Default:Iridium:0.SetSpeed] Running Loop=1
2011-02-22T21:00:41.58300Z,1298408441.583 [Default:Iridium:0.SetSpeed](DEBUG): Initialize.
2011-02-22T21:00:41.58330Z,1298408441.5833 [Default:Iridium:1.GoToSurface] Running Loop=1
2011-02-22T21:00:41.58340Z,1298408441.5834 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T21:00:41.92450Z,1298408441.9245 [Default:Iridium:1.GoToSurface] Stopped
2011-02-22T21:00:41.92460Z,1298408441.9246 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T21:00:41.92480Z,1298408441.9248 [Default:Iridium:Read Iridium] Running Loop=1
2011-02-22T21:00:58.63790Z,1298408458.6379 [NAL9601](INFO): SBD MO Status=1, MOMSN=12723, MT Status=0, MTMSN=0
2011-02-22T21:00:58.76330Z,1298408458.7633 [NAL9601](INFO): Sent 290 bytes from file Logs/20110222T183731/shore0010.lzma
2011-02-22T21:00:58.76350Z,1298408458.7635 [NAL9601](INFO): Packets left to send: 0
2011-02-22T21:00:58.76470Z,1298408458.7647 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000015
2011-02-22T21:01:15.86360Z,1298408475.8636 [NAL9601](INFO): SBD MO Status=2, MOMSN=12724, MT Status=2, MTMSN=0
2011-02-22T21:01:15.86390Z,1298408475.8639 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T21:01:26.05410Z,1298408486.0541 [NAL9601](INFO): SBD MO Status=0, MOMSN=12724, MT Status=0, MTMSN=0
2011-02-22T21:01:26.23530Z,1298408486.2353 [Default:Iridium:Read Iridium] Stopped
2011-02-22T21:01:26.23600Z,1298408486.236 [Default:Iridium](INFO): Completed Default:Iridium
2011-02-22T21:01:26.23610Z,1298408486.2361 [Default:Iridium] Stopped
2011-02-22T21:01:26.23630Z,1298408486.2363 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-02-22T21:01:26.23630Z,1298408486.2363 [Default:Iridium:0.SetSpeed] Stopped
2011-02-22T21:01:26.23640Z,1298408486.2364 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T21:01:26.23670Z,1298408486.2367 [Default:6.Wait] Running Loop=1
2011-02-22T21:01:26.23680Z,1298408486.2368 [Default:6.Wait](DEBUG): Initialize Wait Component.
2011-02-22T21:01:36.58630Z,1298408496.5863 [NAL9601](INFO): Powering down
2011-02-22T21:05:41.60190Z,1298408741.6019 [Default:CallGPS] Running Loop=1
2011-02-22T21:05:41.60210Z,1298408741.6021 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-02-22T21:05:41.60230Z,1298408741.6023 [Default:CallGPS:0] Running Loop=1
2011-02-22T21:05:41.60240Z,1298408741.6024 [Default:CallGPS:0](INFO): Aggregate::initialize Default:CallGPS:0
2011-02-22T21:05:46.60090Z,1298408746.6009 [Default:GPS] Running Loop=1
2011-02-22T21:05:46.60100Z,1298408746.601 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-02-22T21:05:46.60120Z,1298408746.6012 [Default:GPS:0.SetSpeed] Running Loop=1
2011-02-22T21:05:46.60130Z,1298408746.6013 [Default:GPS:0.SetSpeed](DEBUG): Initialize.
2011-02-22T21:05:46.60150Z,1298408746.6015 [Default:GPS:1.GoToSurface] Running Loop=1
2011-02-22T21:05:46.60160Z,1298408746.6016 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T21:05:46.60240Z,1298408746.6024 [Default:GPS:1.GoToSurface] Stopped
2011-02-22T21:05:46.60250Z,1298408746.6025 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T21:05:46.60280Z,1298408746.6028 [Default:GPS:Read GPS] Running Loop=1
2011-02-22T21:05:47.25250Z,1298408747.2525 [NAL9601](INFO): Powering up
2011-02-22T21:06:26.49290Z,1298408786.4929 [Default:CallIridium] Running Loop=1
2011-02-22T21:06:26.49310Z,1298408786.4931 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-02-22T21:06:26.49330Z,1298408786.4933 [Default:CallIridium:0] Running Loop=1
2011-02-22T21:06:26.49350Z,1298408786.4935 [Default:CallIridium:0](INFO): Aggregate::initialize Default:CallIridium:0
2011-02-22T21:06:26.86760Z,1298408786.8676 [Default:Iridium] Running Loop=1
2011-02-22T21:06:26.86780Z,1298408786.8678 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-02-22T21:06:26.86790Z,1298408786.8679 [Default:Iridium:0.SetSpeed] Running Loop=1
2011-02-22T21:06:26.86800Z,1298408786.868 [Default:Iridium:0.SetSpeed](DEBUG): Initialize.
2011-02-22T21:06:26.86830Z,1298408786.8683 [Default:Iridium:1.GoToSurface] Running Loop=1
2011-02-22T21:06:26.86840Z,1298408786.8684 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-02-22T21:06:26.86930Z,1298408786.8693 [Default:Iridium:1.GoToSurface] Stopped
2011-02-22T21:06:26.86940Z,1298408786.8694 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T21:06:26.86960Z,1298408786.8696 [Default:Iridium:Read Iridium] Running Loop=1
2011-02-22T21:06:52.96340Z,1298408812.9634 [NAL9601](INFO): NAL9601 initialized
2011-02-22T21:07:20.66200Z,1298408840.662 [NAL9601](INFO): SBD MO Status=2, MOMSN=12725, MT Status=2, MTMSN=0
2011-02-22T21:07:20.66220Z,1298408840.6622 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T21:07:29.27890Z,1298408849.2789 [BuoyancyServo](ERROR): getPosition uart error serial timeout
2011-02-22T21:07:29.27920Z,1298408849.2792 [BuoyancyServo](FAULT): Buoyancy getPosition uart error.serial timeout
2011-02-22T21:07:29.27930Z,1298408849.2793 [BuoyancyServo] Communications Fault, FailCount= 1
2011-02-22T21:07:29.27940Z,1298408849.2794 [BuoyancyServo](ERROR): Communications Fault
2011-02-22T21:07:29.30580Z,1298408849.3058 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2011-02-22T21:07:29.41270Z,1298408849.4127 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2011-02-22T21:07:29.41280Z,1298408849.4128 [BuoyancyServo](INFO): Powering down
2011-02-22T21:07:29.43790Z,1298408849.4379 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2011-02-22T21:07:29.43800Z,1298408849.438 [BuoyancyServo] No Fault, FailCount= 1
2011-02-22T21:07:30.21600Z,1298408850.216 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2011-02-22T21:07:30.39110Z,1298408850.3911 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2011-02-22T21:07:38.22350Z,1298408858.2235 [NAL9601](INFO): SBD MO Status=2, MOMSN=12725, MT Status=2, MTMSN=0
2011-02-22T21:07:38.22380Z,1298408858.2238 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T21:07:55.33020Z,1298408875.3302 [NAL9601](INFO): SBD MO Status=2, MOMSN=12725, MT Status=2, MTMSN=0
2011-02-22T21:07:55.33050Z,1298408875.3305 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T21:08:12.54230Z,1298408892.5423 [NAL9601](INFO): SBD MO Status=2, MOMSN=12725, MT Status=2, MTMSN=0
2011-02-22T21:08:12.54260Z,1298408892.5426 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T21:08:28.33010Z,1298408908.3301 [NAL9601](INFO): SBD MO Status=2, MOMSN=12725, MT Status=2, MTMSN=0
2011-02-22T21:08:28.33040Z,1298408908.3304 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-02-22T21:08:29.53190Z,1298408909.5319 [NAL9601](IMPORTANT): GPS fix at: 1298408922
2011-02-22T21:08:29.54950Z,1298408909.5495 [Default:GPS:Read GPS] Stopped
2011-02-22T21:08:29.54990Z,1298408909.5499 [Default:GPS](INFO): Completed Default:GPS
2011-02-22T21:08:29.55000Z,1298408909.55 [Default:GPS] Stopped
2011-02-22T21:08:29.55020Z,1298408909.5502 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-02-22T21:08:29.55030Z,1298408909.5503 [Default:GPS:0.SetSpeed] Stopped
2011-02-22T21:08:29.55040Z,1298408909.5504 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T21:08:29.94430Z,1298408909.9443 [Default:CallGPS:0](INFO): Completed Default:CallGPS:0
2011-02-22T21:08:29.94440Z,1298408909.9444 [Default:CallGPS:0] Stopped
2011-02-22T21:08:29.94460Z,1298408909.9446 [Default:CallGPS:0](INFO): Aggregate::uninitialize Default:CallGPS:0
2011-02-22T21:08:29.94480Z,1298408909.9448 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-02-22T21:08:29.94490Z,1298408909.9449 [Default:CallGPS] Stopped
2011-02-22T21:08:29.94500Z,1298408909.945 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-02-22T21:08:57.46220Z,1298408937.4622 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=12725, MT Status=1, MTMSN=1572
2011-02-22T21:08:57.65930Z,1298408937.6593 [NAL9601](INFO): Sent 90 bytes from file Logs/20110222T183731/shore0011.lzma
2011-02-22T21:08:57.65960Z,1298408937.6596 [NAL9601](INFO): Packets left to send: 0
2011-02-22T21:08:57.66070Z,1298408937.6607 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000016
2011-02-22T21:08:58.07320Z,1298408938.0732 [NAL9601](INFO): Received command:restart

2011-02-22T21:08:58.07440Z,1298408938.0744 [CommandLine](IMPORTANT): got command restart
2011-02-22T21:08:58.25490Z,1298408938.2549 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2011-02-22T21:08:58.30940Z,1298408938.3094 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2011-02-22T21:08:58.32760Z,1298408938.3276 [controlThread](DEBUG): Uninitializing ControlThread
2011-02-22T21:08:58.32820Z,1298408938.3282 [AHRS_sp3003D](INFO): Powering down
2011-02-22T21:08:58.41530Z,1298408938.4153 [AHRS_3DMGX3](INFO): Powering down
2011-02-22T21:08:58.41660Z,1298408938.4166 [DVL_micro](INFO): Powering down
2011-02-22T21:08:58.41700Z,1298408938.417 [NAL9601](INFO): Powering down
2011-02-22T21:08:58.41790Z,1298408938.4179 [CTD_NeilBrown](INFO): Powering down
2011-02-22T21:08:58.41840Z,1298408938.4184 [WetLabsBB2FL](INFO): Powering down
2011-02-22T21:08:58.41890Z,1298408938.4189 [Aanderaa_O2](INFO): Powering down
2011-02-22T21:08:58.41980Z,1298408938.4198 [Bathymetry](DEBUG): Uninitialize Bathymetry Derivation.
2011-02-22T21:08:58.42180Z,1298408938.4218 [Default] Stopped
2011-02-22T21:08:58.42200Z,1298408938.422 [Default](INFO): Aggregate::uninitialize Default
2011-02-22T21:08:58.42210Z,1298408938.4221 [Default:Iridium] Stopped
2011-02-22T21:08:58.42220Z,1298408938.4222 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-02-22T21:08:58.42230Z,1298408938.4223 [Default:Iridium:0.SetSpeed] Stopped
2011-02-22T21:08:58.42240Z,1298408938.4224 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize.
2011-02-22T21:08:58.42250Z,1298408938.4225 [Default:Iridium:Read Iridium] Stopped
2011-02-22T21:08:58.42260Z,1298408938.4226 [Default:CallIridium] Stopped
2011-02-22T21:08:58.42280Z,1298408938.4228 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-02-22T21:08:58.42290Z,1298408938.4229 [Default:CallIridium:0] Stopped
2011-02-22T21:08:58.42310Z,1298408938.4231 [Default:CallIridium:0](INFO): Aggregate::uninitialize Default:CallIridium:0
2011-02-22T21:08:58.42320Z,1298408938.4232 [Default:4.SetSpeed] Stopped
2011-02-22T21:08:58.42320Z,1298408938.4232 [Default:4.SetSpeed](DEBUG): Uninitialize.
2011-02-22T21:08:58.42330Z,1298408938.4233 [Default:5.GoToSurface] Stopped
2011-02-22T21:08:58.42340Z,1298408938.4234 [Default:5.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-02-22T21:08:58.42350Z,1298408938.4235 [Default:6.Wait] Stopped
2011-02-22T21:08:58.42360Z,1298408938.4236 [Default:6.Wait](DEBUG): Uninitialize Wait Component.
2011-02-22T21:08:58.42920Z,1298408938.4292 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2011-02-22T21:08:58.42960Z,1298408938.4296 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2011-02-22T21:08:58.42990Z,1298408938.4299 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2011-02-22T21:08:58.43020Z,1298408938.4302 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2011-02-22T21:08:58.43080Z,1298408938.4308 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2011-02-22T21:08:58.43100Z,1298408938.431 [BuoyancyServo](INFO): Powering down
2011-02-22T21:08:58.43150Z,1298408938.4315 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2011-02-22T21:08:58.43160Z,1298408938.4316 [ElevatorServo](INFO): Powering down
2011-02-22T21:08:58.43200Z,1298408938.432 [MassServo](DEBUG): Uninitialize Mass Servo.
2011-02-22T21:08:58.43210Z,1298408938.4321 [MassServo](INFO): Powering down
2011-02-22T21:08:58.43250Z,1298408938.4325 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2011-02-22T21:08:58.43260Z,1298408938.4326 [RudderServo](INFO): Powering down
2011-02-22T21:08:58.43300Z,1298408938.433 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2011-02-22T21:08:58.43310Z,1298408938.4331 [ThrusterServo](INFO): Powering down
2011-02-22T21:08:58.43350Z,1298408938.4335 [SBIT](DEBUG): Uninitialize SBIT Component.
2011-02-22T21:08:58.43380Z,1298408938.4338 [IBIT](DEBUG): Uninitialize IBIT Component.
2011-02-22T21:08:58.43410Z,1298408938.4341 [CBIT](DEBUG): Uninitialize CBIT Component.