2011-02-22T21:09:00.53410Z,1298408940.5341 [Supervisor](DEBUG): Initializing supervisor. 2011-02-22T21:09:00.53710Z,1298408940.5371 [SyncHandler](DEBUG): Created PCaller Thread at 1077007584 2011-02-22T21:09:00.53790Z,1298408940.5379 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2011-02-22T21:09:00.53910Z,1298408940.5391 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 1077073120 2011-02-22T21:09:00.54010Z,1298408940.5401 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2011-02-22T21:09:00.55080Z,1298408940.5508 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2011-02-22T21:09:00.55200Z,1298408940.552 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 1077138656 2011-02-22T21:09:00.55250Z,1298408940.5525 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread. 2011-02-22T21:09:00.55300Z,1298408940.553 [Supervisor](INFO): Looking for Config files in directory: Config/ 2011-02-22T21:09:00.55430Z,1298408940.5543 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2011-02-22T21:09:01.13830Z,1298408941.1383 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2011-02-22T21:09:01.13900Z,1298408941.139 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2011-02-22T21:09:01.32910Z,1298408941.3291 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2011-02-22T21:09:01.32960Z,1298408941.3296 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2011-02-22T21:09:01.41620Z,1298408941.4162 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2011-02-22T21:09:01.41670Z,1298408941.4167 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2011-02-22T21:09:01.59330Z,1298408941.5933 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2011-02-22T21:09:01.59390Z,1298408941.5939 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2011-02-22T21:09:01.69360Z,1298408941.6936 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2011-02-22T21:09:01.69410Z,1298408941.6941 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2011-02-22T21:09:02.02960Z,1298408942.0296 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2011-02-22T21:09:02.03010Z,1298408942.0301 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2011-02-22T21:09:02.18760Z,1298408942.1876 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2011-02-22T21:09:02.18820Z,1298408942.1882 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2011-02-22T21:09:02.28380Z,1298408942.2838 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2011-02-22T21:09:02.28430Z,1298408942.2843 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2011-02-22T21:09:02.38350Z,1298408942.3835 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2011-02-22T21:09:02.38410Z,1298408942.3841 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2011-02-22T21:09:02.72830Z,1298408942.7283 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2011-02-22T21:09:02.72890Z,1298408942.7289 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2011-02-22T21:09:02.84650Z,1298408942.8465 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2011-02-22T21:09:02.84720Z,1298408942.8472 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2011-02-22T21:09:02.93310Z,1298408942.9331 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-tethys/ 2011-02-22T21:09:02.93400Z,1298408942.934 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/vehicle.cfg 2011-02-22T21:09:03.02650Z,1298408943.0265 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/vehicle" 2011-02-22T21:09:03.02720Z,1298408943.0272 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Sensor.cfg 2011-02-22T21:09:03.15170Z,1298408943.1517 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Sensor" 2011-02-22T21:09:03.15220Z,1298408943.1522 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/BIT.cfg 2011-02-22T21:09:03.24060Z,1298408943.2406 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/BIT" 2011-02-22T21:09:03.24120Z,1298408943.2412 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Servo.cfg 2011-02-22T21:09:03.33760Z,1298408943.3376 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Servo" 2011-02-22T21:09:03.33820Z,1298408943.3382 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Science.cfg 2011-02-22T21:09:03.43160Z,1298408943.4316 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Science" 2011-02-22T21:09:03.43210Z,1298408943.4321 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/workSite.cfg 2011-02-22T21:09:03.52000Z,1298408943.52 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/workSite" 2011-02-22T21:09:03.52060Z,1298408943.5206 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Simulator.cfg 2011-02-22T21:09:03.60620Z,1298408943.6062 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Simulator" 2011-02-22T21:09:03.60680Z,1298408943.6068 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Derivation.cfg 2011-02-22T21:09:03.69260Z,1298408943.6926 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Derivation" 2011-02-22T21:09:03.69420Z,1298408943.6942 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-tethys// 2011-02-22T21:09:03.69510Z,1298408943.6951 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//vehicle.cfg 2011-02-22T21:09:03.78730Z,1298408943.7873 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/vehicle" 2011-02-22T21:09:03.78780Z,1298408943.7878 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//Sensor.cfg 2011-02-22T21:09:03.90180Z,1298408943.9018 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Sensor" 2011-02-22T21:09:03.90230Z,1298408943.9023 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//BIT.cfg 2011-02-22T21:09:03.98920Z,1298408943.9892 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/BIT" 2011-02-22T21:09:03.98970Z,1298408943.9897 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//Servo.cfg 2011-02-22T21:09:04.08450Z,1298408944.0845 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Servo" 2011-02-22T21:09:04.08510Z,1298408944.0851 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//Science.cfg 2011-02-22T21:09:04.17710Z,1298408944.1771 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Science" 2011-02-22T21:09:04.17760Z,1298408944.1776 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//workSite.cfg 2011-02-22T21:09:04.26520Z,1298408944.2652 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/workSite" 2011-02-22T21:09:04.26570Z,1298408944.2657 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//Simulator.cfg 2011-02-22T21:09:04.35180Z,1298408944.3518 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Simulator" 2011-02-22T21:09:04.35240Z,1298408944.3524 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys//Derivation.cfg 2011-02-22T21:09:04.43730Z,1298408944.4373 [ComponentRegistry](DEBUG): Attempting to register duplicate component named "Config/Derivation" 2011-02-22T21:09:04.45560Z,1298408944.4556 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2011-02-22T21:09:04.55330Z,1298408944.5533 [InternalSim] Loaded 2011-02-22T21:09:04.55360Z,1298408944.5536 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread. 2011-02-22T21:09:04.55450Z,1298408944.5545 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2011-02-22T21:09:04.55520Z,1298408944.5552 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2011-02-22T21:09:04.56770Z,1298408944.5677 [SBIT](DEBUG): Construct Startup Built In Test. 2011-02-22T21:09:04.59990Z,1298408944.5999 [SBIT] Loaded 2011-02-22T21:09:04.60020Z,1298408944.6002 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2011-02-22T21:09:04.60130Z,1298408944.6013 [IBIT](DEBUG): Construct Initiated Built In Test. 2011-02-22T21:09:04.63400Z,1298408944.634 [IBIT] Loaded 2011-02-22T21:09:04.63430Z,1298408944.6343 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2011-02-22T21:09:04.63550Z,1298408944.6355 [CBIT](DEBUG): Construct CBIT Built In Test. 2011-02-22T21:09:04.66570Z,1298408944.6657 [CBIT] Loaded 2011-02-22T21:09:04.66600Z,1298408944.666 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2011-02-22T21:09:04.66650Z,1298408944.6665 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2011-02-22T21:09:04.66710Z,1298408944.6671 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2011-02-22T21:09:04.76650Z,1298408944.7665 [BuoyancyServo] Loaded 2011-02-22T21:09:04.76690Z,1298408944.7669 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2011-02-22T21:09:04.77500Z,1298408944.775 [ElevatorServo] Loaded 2011-02-22T21:09:04.77530Z,1298408944.7753 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2011-02-22T21:09:04.78330Z,1298408944.7833 [MassServo] Loaded 2011-02-22T21:09:04.78360Z,1298408944.7836 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2011-02-22T21:09:04.79140Z,1298408944.7914 [RudderServo] Loaded 2011-02-22T21:09:04.79170Z,1298408944.7917 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2011-02-22T21:09:04.79970Z,1298408944.7997 [ThrusterServo] Loaded 2011-02-22T21:09:04.80000Z,1298408944.8 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2011-02-22T21:09:04.80050Z,1298408944.8005 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2011-02-22T21:09:04.80100Z,1298408944.801 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2011-02-22T21:09:04.82530Z,1298408944.8253 [Bathymetry] Loaded 2011-02-22T21:09:04.82560Z,1298408944.8256 [ComponentRegistry](DEBUG): SyncComponent "Bathymetry" handled in the control thread. 2011-02-22T21:09:04.83250Z,1298408944.8325 [DepthRateCalculator] Loaded 2011-02-22T21:09:04.83280Z,1298408944.8328 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2011-02-22T21:09:04.83980Z,1298408944.8398 [PitchRateCalculator] Loaded 2011-02-22T21:09:04.84020Z,1298408944.8402 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2011-02-22T21:09:04.84710Z,1298408944.8471 [SpeedCalculator] Loaded 2011-02-22T21:09:04.84740Z,1298408944.8474 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2011-02-22T21:09:04.86450Z,1298408944.8645 [TempGradientCalculator] Loaded 2011-02-22T21:09:04.86480Z,1298408944.8648 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2011-02-22T21:09:04.87160Z,1298408944.8716 [YawRateCalculator] Loaded 2011-02-22T21:09:04.87190Z,1298408944.8719 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2011-02-22T21:09:04.90790Z,1298408944.9079 [Navigation] Loaded 2011-02-22T21:09:04.90820Z,1298408944.9082 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread. 2011-02-22T21:09:04.90880Z,1298408944.9088 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2011-02-22T21:09:04.90940Z,1298408944.9094 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2011-02-22T21:09:04.95620Z,1298408944.9562 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2011-02-22T21:09:04.95680Z,1298408944.9568 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2011-02-22T21:09:04.96620Z,1298408944.9662 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2011-02-22T21:09:04.96690Z,1298408944.9669 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2011-02-22T21:09:04.98010Z,1298408944.9801 [VerticalControl](DEBUG): Construct VerticalControl. 2011-02-22T21:09:05.20060Z,1298408945.2006 [VerticalControl] Loaded 2011-02-22T21:09:05.20090Z,1298408945.2009 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2011-02-22T21:09:05.20210Z,1298408945.2021 [HorizontalControl](DEBUG): Construct HorizontalControl. 2011-02-22T21:09:05.25920Z,1298408945.2592 [HorizontalControl] Loaded 2011-02-22T21:09:05.25950Z,1298408945.2595 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2011-02-22T21:09:05.26060Z,1298408945.2606 [SpeedControl](DEBUG): Construct SpeedControl. 2011-02-22T21:09:05.26280Z,1298408945.2628 [SpeedControl] Loaded 2011-02-22T21:09:05.26320Z,1298408945.2632 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2011-02-22T21:09:05.26430Z,1298408945.2643 [LoopControl](DEBUG): Construct LoopControl. 2011-02-22T21:09:05.26910Z,1298408945.2691 [LoopControl] Loaded 2011-02-22T21:09:05.26940Z,1298408945.2694 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2011-02-22T21:09:05.26990Z,1298408945.2699 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2011-02-22T21:09:05.27050Z,1298408945.2705 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2011-02-22T21:09:05.27620Z,1298408945.2762 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator. 2011-02-22T21:09:05.28200Z,1298408945.282 [AsyncPiEstimator] Loaded 2011-02-22T21:09:05.28230Z,1298408945.2823 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread. 2011-02-22T21:09:05.28360Z,1298408945.2836 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 1078576352 2011-02-22T21:09:05.28440Z,1298408945.2844 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2011-02-22T21:09:05.28500Z,1298408945.285 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2011-02-22T21:09:05.35910Z,1298408945.3591 [AHRS_3DMGX3] Loaded 2011-02-22T21:09:05.35950Z,1298408945.3595 [ComponentRegistry](DEBUG): SyncComponent "AHRS_3DMGX3" handled in the control thread. 2011-02-22T21:09:05.73160Z,1298408945.7316 [Batt_Ocean_Server] Loaded 2011-02-22T21:09:05.73190Z,1298408945.7319 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread. 2011-02-22T21:09:05.74650Z,1298408945.7465 [Depth_Keller] Loaded 2011-02-22T21:09:05.74690Z,1298408945.7469 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2011-02-22T21:09:05.75320Z,1298408945.7532 [DropWeight] Loaded 2011-02-22T21:09:05.75350Z,1298408945.7535 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2011-02-22T21:09:05.86620Z,1298408945.8662 [DVL_micro] Loaded 2011-02-22T21:09:05.86660Z,1298408945.8666 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread. 2011-02-22T21:09:05.95600Z,1298408945.956 [NAL9601] Loaded 2011-02-22T21:09:05.95640Z,1298408945.9564 [ComponentRegistry](DEBUG): SyncComponent "NAL9601" handled in the control thread. 2011-02-22T21:09:06.00580Z,1298408946.0058 [Onboard] Loaded 2011-02-22T21:09:06.00620Z,1298408946.0062 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2011-02-22T21:09:06.01560Z,1298408946.0156 [Radio_Freewave] Loaded 2011-02-22T21:09:06.01600Z,1298408946.016 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread. 2011-02-22T21:09:06.01640Z,1298408946.0164 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2011-02-22T21:09:06.01700Z,1298408946.017 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2011-02-22T21:09:06.06780Z,1298408946.0678 [CTD_NeilBrown] Loaded 2011-02-22T21:09:06.06810Z,1298408946.0681 [ComponentRegistry](DEBUG): SyncComponent "CTD_NeilBrown" handled in the control thread. 2011-02-22T21:09:06.10170Z,1298408946.1017 [WetLabsBB2FL] Loaded 2011-02-22T21:09:06.10210Z,1298408946.1021 [ComponentRegistry](DEBUG): SyncComponent "WetLabsBB2FL" handled in the control thread. 2011-02-22T21:09:06.12280Z,1298408946.1228 [Aanderaa_O2] Loaded 2011-02-22T21:09:06.12320Z,1298408946.1232 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread. 2011-02-22T21:09:06.13370Z,1298408946.1337 [ISUS] Loaded 2011-02-22T21:09:06.13410Z,1298408946.1341 [ComponentRegistry](DEBUG): SyncComponent "ISUS" handled in the control thread. 2011-02-22T21:09:06.13460Z,1298408946.1346 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2011-02-22T21:09:06.13740Z,1298408946.1374 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2011-02-22T21:09:06.13840Z,1298408946.1384 [ComponentRegistry](DEBUG): SyncComponent "Maintainer" handled in the control thread. 2011-02-22T21:09:06.13940Z,1298408946.1394 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2011-02-22T21:09:06.13960Z,1298408946.1396 [Supervisor](DEBUG): Running supervisor. 2011-02-22T21:09:06.14280Z,1298408946.1428 [controlThread](DEBUG): Initializing ControlThread 2011-02-22T21:09:06.14400Z,1298408946.144 [InternalSim](DEBUG): InternalSim initializing... 2011-02-22T21:09:06.17960Z,1298408946.1796 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator. 2011-02-22T21:09:06.20440Z,1298408946.2044 [SBIT](INFO): Initialize SBIT Component. 2011-02-22T21:09:06.20700Z,1298408946.207 [IBIT](INFO): Initialize IBIT Component. 2011-02-22T21:09:06.20930Z,1298408946.2093 [CBIT](DEBUG): Initialize CBIT Component. 2011-02-22T21:09:06.21230Z,1298408946.2123 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2011-02-22T21:09:06.23640Z,1298408946.2364 [Bathymetry](DEBUG): Initialize Bathymetry Derivation. 2011-02-22T21:09:06.24200Z,1298408946.242 [Bathymetry](DEBUG): Opened 2011-02-22T21:09:06.25600Z,1298408946.256 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2011-02-22T21:09:06.25650Z,1298408946.2565 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2011-02-22T21:09:06.25700Z,1298408946.257 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2011-02-22T21:09:06.25770Z,1298408946.2577 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2011-02-22T21:09:06.25950Z,1298408946.2595 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2011-02-22T21:09:06.25990Z,1298408946.2599 [Navigation](DEBUG): Initializing Navigation. 2011-02-22T21:09:06.26040Z,1298408946.2604 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2011-02-22T21:09:06.27610Z,1298408946.2761 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2011-02-22T21:09:06.27940Z,1298408946.2794 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2011-02-22T21:09:06.28030Z,1298408946.2803 [LoopControl](DEBUG): Initialize LoopControlComponent. 2011-02-22T21:09:07.93640Z,1298408947.9364 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized 2011-02-22T21:09:07.94290Z,1298408947.9429 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2011-02-22T21:09:07.95650Z,1298408947.9565 [Startup:0.GoToSurface](DEBUG): Construct GoToSurface. 2011-02-22T21:09:07.96770Z,1298408947.9677 [MissionManager](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2011-02-22T21:09:07.97110Z,1298408947.9711 [MissionManager](DEBUG): Initialize ReadDataComponent to sense platform_communications 2011-02-22T21:09:07.97390Z,1298408947.9739 [MissionManager](DEBUG): 2011-02-22T21:09:07.97480Z,1298408947.9748 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2011-02-22T21:09:08.01160Z,1298408948.0116 [Default:GPS:0.SetSpeed](DEBUG): Construct. 2011-02-22T21:09:08.02700Z,1298408948.027 [Default:GPS:1.GoToSurface](DEBUG): Construct GoToSurface. 2011-02-22T21:09:08.03720Z,1298408948.0372 [MissionManager](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2011-02-22T21:09:08.03960Z,1298408948.0396 [Default:Iridium:0.SetSpeed](DEBUG): Construct. 2011-02-22T21:09:08.05500Z,1298408948.055 [Default:Iridium:1.GoToSurface](DEBUG): Construct GoToSurface. 2011-02-22T21:09:08.06490Z,1298408948.0649 [MissionManager](DEBUG): Initialize ReadDataComponent to sense platform_communications 2011-02-22T21:09:08.06740Z,1298408948.0674 [Default:Iridium:0_Timeout:0.Execute](DEBUG): Construct Execute. 2011-02-22T21:09:08.08820Z,1298408948.0882 [Default:4.SetSpeed](DEBUG): Construct. 2011-02-22T21:09:08.10350Z,1298408948.1035 [Default:5.GoToSurface](DEBUG): Construct GoToSurface. 2011-02-22T21:09:08.11290Z,1298408948.1129 [Default:6.Wait](DEBUG): Construct Wait. 2011-02-22T21:09:08.12750Z,1298408948.1275 [MissionManager](DEBUG): 400 400 Burn on Dropped drop weight due to communications timeout 1.0 5.0 5.0 1.0 5 2011-02-22T21:09:08.13380Z,1298408948.1338 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_3DMGX3,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9601,Onboard,Radio_Freewave,CTD_NeilBrown,WetLabsBB2FL,Aanderaa_O2,ISUS,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-22T21:09:08.16480Z,1298408948.1648 [AHRS_3DMGX3](DEBUG): Initializing AHRS_3DMGX3. 2011-02-22T21:09:08.34080Z,1298408948.3408 [DVL_micro](DEBUG): Initializing DVL_micro. 2011-02-22T21:09:08.36500Z,1298408948.365 [Radio_Freewave](INFO): Powering up 2011-02-22T21:09:08.37150Z,1298408948.3715 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown. 2011-02-22T21:09:08.43410Z,1298408948.4341 [WetLabsBB2FL](INFO): Powering down 2011-02-22T21:09:08.58890Z,1298408948.5889 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2011-02-22T21:09:08.64310Z,1298408948.6431 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2011-02-22T21:09:08.65470Z,1298408948.6547 [ElevatorServo](DEBUG): Initializing EZServoServo. 2011-02-22T21:09:08.71100Z,1298408948.711 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2011-02-22T21:09:08.72060Z,1298408948.7206 [MassServo](DEBUG): Initializing EZServoServo. 2011-02-22T21:09:08.77510Z,1298408948.7751 [MassServo](DEBUG): Initializing MassServo. 2011-02-22T21:09:08.78430Z,1298408948.7843 [RudderServo](DEBUG): Initializing EZServoServo. 2011-02-22T21:09:08.83900Z,1298408948.839 [RudderServo](DEBUG): Initializing RudderServo. 2011-02-22T21:09:08.85170Z,1298408948.8517 [ThrusterServo](DEBUG): Initializing EZServoServo. 2011-02-22T21:09:08.90700Z,1298408948.907 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2011-02-22T21:09:11.22390Z,1298408951.2239 [NAL9601](INFO): Powering up NAL9601 2011-02-22T21:09:12.90310Z,1298408952.9031 [Aanderaa_O2](INFO): Powering down 2011-02-22T21:09:21.61680Z,1298408961.6168 [SBIT](INFO): Beginning Startup BIT 2011-02-22T21:09:59.62480Z,1298408999.6248 [SBIT](IMPORTANT): SBIT PASSED 2011-02-22T21:09:59.99080Z,1298408999.9908 [MissionManager](IMPORTANT): Started mission Startup 2011-02-22T21:09:59.99090Z,1298408999.9909 [Startup] Running Loop=1 2011-02-22T21:09:59.99110Z,1298408999.9911 [Startup](INFO): Aggregate::initialize Startup 2011-02-22T21:09:59.99130Z,1298408999.9913 [Startup:0.GoToSurface] Running Loop=1 2011-02-22T21:09:59.99130Z,1298408999.9913 [Startup:0.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T21:09:59.99850Z,1298408999.9985 [Startup:StartupSatComms] Running Loop=1 2011-02-22T21:09:59.99860Z,1298408999.9986 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms 2011-02-22T21:09:59.99890Z,1298408999.9989 [Startup:StartupSatComms:0] Running Loop=1 2011-02-22T21:10:17.03540Z,1298409017.0354 [NAL9601](INFO): NAL9601 initialized 2011-02-22T21:10:17.98500Z,1298409017.985 [NAL9601](IMPORTANT): GPS fix at: 1298409031 2011-02-22T21:10:18.00070Z,1298409018.0007 [Startup:StartupSatComms:0] Stopped 2011-02-22T21:10:18.00090Z,1298409018.0009 [Startup:StartupSatComms:1] Running Loop=1 2011-02-22T21:10:47.11840Z,1298409047.1184 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=12726, MT Status=1, MTMSN=1573 2011-02-22T21:10:47.27530Z,1298409047.2753 [NAL9601](INFO): Sent 244 bytes from file Logs/20110222T183731/shore0012.lzma 2011-02-22T21:10:47.27560Z,1298409047.2756 [NAL9601](INFO): Packets left to send: 0 2011-02-22T21:10:47.30520Z,1298409047.3052 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000000 2011-02-22T21:10:47.69400Z,1298409047.694 [NAL9601](INFO): Received command:run Transport/transit_2km.xml 2011-02-22T21:10:47.78720Z,1298409047.7872 [CommandLine](IMPORTANT): got command run ./Missions/Transport/transit_2km.xml 2011-02-22T21:10:47.78760Z,1298409047.7876 [MissionManager](INFO): Loading Mission: ./Missions/Transport/transit_2km.xml 2011-02-22T21:10:47.82310Z,1298409047.8231 [MissionManager](INFO): DefineArg ApproachDepth = 10 m 2011-02-22T21:10:47.82660Z,1298409047.8266 [MissionManager](INFO): DefineArg Wpt1Lat = 36.8049 arcdeg 2011-02-22T21:10:47.83030Z,1298409047.8303 [MissionManager](INFO): DefineArg Wpt1Lon = -121.8108 arcdeg 2011-02-22T21:10:47.83280Z,1298409047.8328 [transit_2km:0.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope. 2011-02-22T21:10:47.91830Z,1298409047.9183 [transit_2km:1.DepthEnvelope](DEBUG): Construct DepthEnvelope. 2011-02-22T21:10:48.00950Z,1298409048.0095 [transit_2km:2.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope. 2011-02-22T21:10:48.04400Z,1298409048.044 [MissionManager](INFO): Inserting Stack: Missions/Insert/Surface.xml 2011-02-22T21:10:48.07300Z,1298409048.073 [MissionManager](INFO): DefineArg IridiumTimeout = 30 min 2011-02-22T21:10:48.07430Z,1298409048.0743 [transit_2km:SURFACECOMMS:0.GoToSurface](DEBUG): Construct GoToSurface. 2011-02-22T21:10:48.09720Z,1298409048.0972 [MissionManager](DEBUG): Initialize ReadDataComponent to sense time_fix 2011-02-22T21:10:48.11160Z,1298409048.1116 [MissionManager](DEBUG): Initialize ReadDataComponent to sense platform_communications 2011-02-22T21:10:48.11470Z,1298409048.1147 [MissionManager](DEBUG): Initialize ReadDataComponent to sense time_fix 2011-02-22T21:10:48.11970Z,1298409048.1197 [transit_2km:5.Buoyancy](DEBUG): Construct Buoyancy. 2011-02-22T21:10:48.14360Z,1298409048.1436 [transit_2km:WaypointOne:0.Pitch](DEBUG): Construct. 2011-02-22T21:10:48.23430Z,1298409048.2343 [transit_2km:WaypointOne:1.SetSpeed](DEBUG): Construct. 2011-02-22T21:10:48.26150Z,1298409048.2615 [transit_2km:WaypointOne:WaypointW1.Waypoint](DEBUG): Construct Waypoint. 2011-02-22T21:10:48.33140Z,1298409048.3314 [MissionManager](DEBUG): 10.0 36.8049 -121.8108 7 20 0.75 35 275 1 2011-02-22T21:10:48.33190Z,1298409048.3319 [CommandLine](IMPORTANT): Running ./Missions/Transport/transit_2km.xml 2011-02-22T21:11:14.56950Z,1298409074.5695 [NAL9601](INFO): SBD MO Status=1, MOMSN=12727, MT Status=0, MTMSN=0 2011-02-22T21:11:14.73530Z,1298409074.7353 [NAL9601](INFO): Sent 332 bytes from file Logs/20110222T210900/shore0000.lzma 2011-02-22T21:11:14.73560Z,1298409074.7356 [NAL9601](INFO): Packets left to send: 1 2011-02-22T21:11:14.73730Z,1298409074.7373 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000001 2011-02-22T21:11:18.28290Z,1298409078.2829 [Startup:StartupSatComms:1](INFO): Timed out from 2011-02-22T21:10:18.Z 2011-02-22T21:11:18.28300Z,1298409078.283 [Startup:StartupSatComms:0_Timeout] Running Loop=1 2011-02-22T21:11:18.28320Z,1298409078.2832 [Startup:StartupSatComms:0_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:0_Timeout 2011-02-22T21:11:18.28350Z,1298409078.2835 [Startup:StartupSatComms:0_Timeout](INFO): Completed Startup:StartupSatComms:0_Timeout 2011-02-22T21:11:18.28360Z,1298409078.2836 [Startup:StartupSatComms:1] Stopped 2011-02-22T21:11:18.28380Z,1298409078.2838 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2011-02-22T21:11:18.28390Z,1298409078.2839 [Startup:StartupSatComms] Stopped 2011-02-22T21:11:18.28410Z,1298409078.2841 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms 2011-02-22T21:11:18.28470Z,1298409078.2847 [Startup](INFO): Completed Startup 2011-02-22T21:11:18.28480Z,1298409078.2848 [Startup] Stopped 2011-02-22T21:11:18.28490Z,1298409078.2849 [Startup](INFO): Aggregate::uninitialize Startup 2011-02-22T21:11:18.28500Z,1298409078.285 [Startup:0.GoToSurface] Stopped 2011-02-22T21:11:18.28510Z,1298409078.2851 [Startup:0.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T21:11:18.68230Z,1298409078.6823 [MissionManager](IMPORTANT): Started mission transit_2km 2011-02-22T21:11:18.68240Z,1298409078.6824 [transit_2km] Running Loop=1 2011-02-22T21:11:18.68260Z,1298409078.6826 [transit_2km](INFO): Aggregate::initialize transit_2km 2011-02-22T21:11:18.68270Z,1298409078.6827 [transit_2km:0.AltitudeEnvelope] Running Loop=1 2011-02-22T21:11:18.68280Z,1298409078.6828 [transit_2km:0.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent. 2011-02-22T21:11:18.68320Z,1298409078.6832 [transit_2km:1.DepthEnvelope] Running Loop=1 2011-02-22T21:11:18.68330Z,1298409078.6833 [transit_2km:1.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent. 2011-02-22T21:11:18.68470Z,1298409078.6847 [transit_2km:2.OffshoreEnvelope] Running Loop=1 2011-02-22T21:11:18.68480Z,1298409078.6848 [transit_2km:2.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent. 2011-02-22T21:11:18.68830Z,1298409078.6883 [transit_2km:2.OffshoreEnvelope](DEBUG): Opened Resources/cencalShoreDist.nc 2011-02-22T21:11:18.70560Z,1298409078.7056 [transit_2km:5.Buoyancy] Running Loop=1 2011-02-22T21:11:18.70570Z,1298409078.7057 [transit_2km:5.Buoyancy](DEBUG): Initialize Buoyancy Component. 2011-02-22T21:11:18.70640Z,1298409078.7064 [transit_2km:SURFACECOMMS] Running Loop=1 2011-02-22T21:11:18.70660Z,1298409078.7066 [transit_2km:SURFACECOMMS](INFO): Aggregate::initialize transit_2km:SURFACECOMMS 2011-02-22T21:11:18.70680Z,1298409078.7068 [transit_2km:SURFACECOMMS:0.GoToSurface] Running Loop=1 2011-02-22T21:11:18.70690Z,1298409078.7069 [transit_2km:SURFACECOMMS:0.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T21:11:18.70790Z,1298409078.7079 [transit_2km:5.Buoyancy] Running Loop=1 2011-02-22T21:11:18.71940Z,1298409078.7194 [transit_2km:SURFACECOMMS:1] Running Loop=1 2011-02-22T21:11:18.71960Z,1298409078.7196 [transit_2km:SURFACECOMMS:1](INFO): Aggregate::initialize transit_2km:SURFACECOMMS:1 2011-02-22T21:11:18.71990Z,1298409078.7199 [transit_2km:SURFACECOMMS:1:0] Running Loop=1 2011-02-22T21:11:18.72000Z,1298409078.72 [transit_2km:2.OffshoreEnvelope] Running Loop=1 2011-02-22T21:11:18.74080Z,1298409078.7408 [transit_2km:1.DepthEnvelope] Running Loop=1 2011-02-22T21:11:18.74700Z,1298409078.747 [transit_2km:0.AltitudeEnvelope] Running Loop=1 2011-02-22T21:11:19.11700Z,1298409079.117 [transit_2km:5.Buoyancy] Preempted 2011-02-22T21:11:27.46690Z,1298409087.4669 [NAL9601](INFO): SBD MO Status=1, MOMSN=12728, MT Status=0, MTMSN=0 2011-02-22T21:11:27.61130Z,1298409087.6113 [NAL9601](INFO): Sent 113 bytes from file Logs/20110222T210900/shore0000.lzma 2011-02-22T21:11:27.61160Z,1298409087.6116 [NAL9601](INFO): Packets left to send: 0 2011-02-22T21:11:27.61270Z,1298409087.6127 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000002 2011-02-22T21:11:40.27420Z,1298409100.2742 [NAL9601](INFO): SBD MO Status=0, MOMSN=12729, MT Status=0, MTMSN=0 2011-02-22T21:11:41.48350Z,1298409101.4835 [NAL9601](IMPORTANT): GPS fix at: 1298409115 2011-02-22T21:11:41.49940Z,1298409101.4994 [transit_2km:SURFACECOMMS:1:0] Stopped 2011-02-22T21:11:41.49970Z,1298409101.4997 [transit_2km:SURFACECOMMS:1:1] Running Loop=1 2011-02-22T21:12:14.67570Z,1298409134.6757 [NAL9601](INFO): SBD MO Status=2, MOMSN=12730, MT Status=2, MTMSN=0 2011-02-22T21:12:14.67600Z,1298409134.676 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2 2011-02-22T21:12:38.65850Z,1298409158.6585 [NAL9601](INFO): SBD MO Status=1, MOMSN=12730, MT Status=0, MTMSN=0 2011-02-22T21:12:38.80330Z,1298409158.8033 [NAL9601](INFO): Sent 280 bytes from file Logs/20110222T210900/shore0001.lzma 2011-02-22T21:12:38.80360Z,1298409158.8036 [NAL9601](INFO): Packets left to send: 0 2011-02-22T21:12:39.02550Z,1298409159.0255 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000003 2011-02-22T21:13:09.98700Z,1298409189.987 [NAL9601](INFO): SBD MO Status=0, MOMSN=12731, MT Status=0, MTMSN=0 2011-02-22T21:13:10.17140Z,1298409190.1714 [transit_2km:SURFACECOMMS:1:1] Stopped 2011-02-22T21:13:10.17170Z,1298409190.1717 [transit_2km:SURFACECOMMS:1:2] Running Loop=1 2011-02-22T21:13:12.39070Z,1298409192.3907 [NAL9601](IMPORTANT): GPS fix at: 1298409206 2011-02-22T21:13:12.40680Z,1298409192.4068 [transit_2km:SURFACECOMMS:1:2] Stopped 2011-02-22T21:13:12.40710Z,1298409192.4071 [transit_2km:SURFACECOMMS:1](INFO): Completed transit_2km:SURFACECOMMS:1 2011-02-22T21:13:12.40720Z,1298409192.4072 [transit_2km:SURFACECOMMS:1] Stopped 2011-02-22T21:13:12.40740Z,1298409192.4074 [transit_2km:SURFACECOMMS:1](INFO): Aggregate::uninitialize transit_2km:SURFACECOMMS:1 2011-02-22T21:13:12.40810Z,1298409192.4081 [transit_2km:SURFACECOMMS](INFO): Completed transit_2km:SURFACECOMMS 2011-02-22T21:13:12.40820Z,1298409192.4082 [transit_2km:SURFACECOMMS] Stopped 2011-02-22T21:13:12.40830Z,1298409192.4083 [transit_2km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_2km:SURFACECOMMS 2011-02-22T21:13:12.40840Z,1298409192.4084 [transit_2km:SURFACECOMMS:0.GoToSurface] Stopped 2011-02-22T21:13:12.40850Z,1298409192.4085 [transit_2km:SURFACECOMMS:0.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T21:13:12.40870Z,1298409192.4087 [transit_2km:WaypointOne] Running Loop=1 2011-02-22T21:13:12.40890Z,1298409192.4089 [transit_2km:WaypointOne](INFO): Aggregate::initialize transit_2km:WaypointOne 2011-02-22T21:13:12.40930Z,1298409192.4093 [transit_2km:WaypointOne:0.Pitch] Running Loop=1 2011-02-22T21:13:12.40940Z,1298409192.4094 [transit_2km:WaypointOne:0.Pitch](DEBUG): Initialize. 2011-02-22T21:13:12.40960Z,1298409192.4096 [transit_2km:WaypointOne:1.SetSpeed] Running Loop=1 2011-02-22T21:13:12.40970Z,1298409192.4097 [transit_2km:WaypointOne:1.SetSpeed](DEBUG): Initialize. 2011-02-22T21:13:12.41050Z,1298409192.4105 [transit_2km:WaypointOne:WaypointW1.Waypoint] Running Loop=1 2011-02-22T21:13:12.41060Z,1298409192.4106 [transit_2km:WaypointOne:WaypointW1.Waypoint](DEBUG): Initialize WaypointComponent. 2011-02-22T21:13:12.82430Z,1298409192.8243 [transit_2km:WaypointOne:1.SetSpeed] Running Loop=1 2011-02-22T21:13:12.82940Z,1298409192.8294 [transit_2km:WaypointOne:0.Pitch] Running Loop=1 2011-02-22T21:13:12.83540Z,1298409192.8354 [transit_2km:5.Buoyancy] Running Loop=1 2011-02-22T21:13:18.78810Z,1298409198.7881 [NAL9601](INFO): Powering down 2011-02-22T21:17:10.38710Z,1298409430.3871 [Radio_Freewave](INFO): Powering down 2011-02-22T21:34:42.59200Z,1298410482.592 [transit_2km:WaypointOne:WaypointW1.Waypoint](INFO): Reached Waypoint: 36.80490123,-121.8107958 2011-02-22T21:34:42.59230Z,1298410482.5923 [transit_2km:WaypointOne:WaypointW1.Waypoint] Stopped 2011-02-22T21:34:42.59240Z,1298410482.5924 [transit_2km:WaypointOne:WaypointW1.Waypoint](DEBUG): Uninitialize WaypointComponent. 2011-02-22T21:34:42.59270Z,1298410482.5927 [transit_2km:WaypointOne:PHONEHOMEWPT1] Running Loop=1 2011-02-22T21:34:42.59280Z,1298410482.5928 [transit_2km:WaypointOne:PHONEHOMEWPT1](INFO): Aggregate::initialize transit_2km:WaypointOne:PHONEHOMEWPT1 2011-02-22T21:34:43.01330Z,1298410483.0133 [transit_2km:SURFACECOMMS] Running Loop=1 2011-02-22T21:34:43.01350Z,1298410483.0135 [transit_2km:SURFACECOMMS](INFO): Aggregate::initialize transit_2km:SURFACECOMMS 2011-02-22T21:34:43.01370Z,1298410483.0137 [transit_2km:SURFACECOMMS:0.GoToSurface] Running Loop=1 2011-02-22T21:34:43.01380Z,1298410483.0138 [transit_2km:SURFACECOMMS:0.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T21:36:07.79810Z,1298410567.7981 [Radio_Freewave](INFO): Powering up 2011-02-22T21:36:07.81070Z,1298410567.8107 [transit_2km:SURFACECOMMS:1] Running Loop=1 2011-02-22T21:36:07.81090Z,1298410567.8109 [transit_2km:SURFACECOMMS:1](INFO): Aggregate::initialize transit_2km:SURFACECOMMS:1 2011-02-22T21:36:07.81110Z,1298410567.8111 [transit_2km:SURFACECOMMS:1:0] Running Loop=1 2011-02-22T21:36:08.18610Z,1298410568.1861 [transit_2km:5.Buoyancy] Preempted 2011-02-22T21:36:08.57890Z,1298410568.5789 [NAL9601](INFO): Powering up 2011-02-22T21:37:14.29140Z,1298410634.2914 [NAL9601](INFO): NAL9601 initialized 2011-02-22T21:37:15.37120Z,1298410635.3712 [NAL9601](IMPORTANT): GPS fix at: 1298410651 2011-02-22T21:37:15.38790Z,1298410635.3879 [transit_2km:SURFACECOMMS:1:0] Stopped 2011-02-22T21:37:15.38830Z,1298410635.3883 [transit_2km:SURFACECOMMS:1:1] Running Loop=1 2011-02-22T21:37:45.36660Z,1298410665.3666 [NAL9601](INFO): SBD MO Status=2, MOMSN=12732, MT Status=2, MTMSN=0 2011-02-22T21:37:45.36690Z,1298410665.3669 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2 2011-02-22T21:38:07.83420Z,1298410687.8342 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=12732, MT Status=1, MTMSN=1574 2011-02-22T21:38:07.99530Z,1298410687.9953 [NAL9601](INFO): Sent 298 bytes from file Logs/20110222T210900/shore0002.lzma 2011-02-22T21:38:07.99560Z,1298410687.9956 [NAL9601](INFO): Packets left to send: 0 2011-02-22T21:38:07.99680Z,1298410687.9968 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000004 2011-02-22T21:38:08.30920Z,1298410688.3092 [NAL9601](INFO): Received command:stop 2011-02-22T21:38:08.31010Z,1298410688.3101 [CommandLine](IMPORTANT): got command stop 2011-02-22T21:38:08.32800Z,1298410688.328 [transit_2km] Stopped 2011-02-22T21:38:08.32820Z,1298410688.3282 [transit_2km](INFO): Aggregate::uninitialize transit_2km 2011-02-22T21:38:08.32830Z,1298410688.3283 [transit_2km:0.AltitudeEnvelope] Stopped 2011-02-22T21:38:08.32840Z,1298410688.3284 [transit_2km:0.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent. 2011-02-22T21:38:08.32850Z,1298410688.3285 [transit_2km:1.DepthEnvelope] Stopped 2011-02-22T21:38:08.32860Z,1298410688.3286 [transit_2km:1.DepthEnvelope](DEBUG): Uninitialize. 2011-02-22T21:38:08.32870Z,1298410688.3287 [transit_2km:2.OffshoreEnvelope] Stopped 2011-02-22T21:38:08.32880Z,1298410688.3288 [transit_2km:2.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent. 2011-02-22T21:38:08.32960Z,1298410688.3296 [transit_2km:SURFACECOMMS] Stopped 2011-02-22T21:38:08.32990Z,1298410688.3299 [transit_2km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_2km:SURFACECOMMS 2011-02-22T21:38:08.33000Z,1298410688.33 [transit_2km:SURFACECOMMS:0.GoToSurface] Stopped 2011-02-22T21:38:08.33010Z,1298410688.3301 [transit_2km:SURFACECOMMS:0.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T21:38:08.33020Z,1298410688.3302 [transit_2km:SURFACECOMMS:1] Stopped 2011-02-22T21:38:08.33030Z,1298410688.3303 [transit_2km:SURFACECOMMS:1](INFO): Aggregate::uninitialize transit_2km:SURFACECOMMS:1 2011-02-22T21:38:08.33040Z,1298410688.3304 [transit_2km:SURFACECOMMS:1:1] Stopped 2011-02-22T21:38:08.33050Z,1298410688.3305 [transit_2km:5.Buoyancy] Stopped 2011-02-22T21:38:08.33060Z,1298410688.3306 [transit_2km:5.Buoyancy](DEBUG): Uninitialize Buoyancy Component. 2011-02-22T21:38:08.33080Z,1298410688.3308 [transit_2km:WaypointOne] Stopped 2011-02-22T21:38:08.33090Z,1298410688.3309 [transit_2km:WaypointOne](INFO): Aggregate::uninitialize transit_2km:WaypointOne 2011-02-22T21:38:08.33100Z,1298410688.331 [transit_2km:WaypointOne:0.Pitch] Stopped 2011-02-22T21:38:08.33110Z,1298410688.3311 [transit_2km:WaypointOne:1.SetSpeed] Stopped 2011-02-22T21:38:08.33120Z,1298410688.3312 [transit_2km:WaypointOne:1.SetSpeed](DEBUG): Uninitialize. 2011-02-22T21:38:08.33130Z,1298410688.3313 [transit_2km:WaypointOne:PHONEHOMEWPT1] Stopped 2011-02-22T21:38:08.33140Z,1298410688.3314 [transit_2km:WaypointOne:PHONEHOMEWPT1](INFO): Aggregate::uninitialize transit_2km:WaypointOne:PHONEHOMEWPT1 2011-02-22T21:38:08.57030Z,1298410688.5703 [MissionManager](IMPORTANT): Started mission Default 2011-02-22T21:38:08.57050Z,1298410688.5705 [Default] Running Loop=1 2011-02-22T21:38:08.57060Z,1298410688.5706 [Default](INFO): Aggregate::initialize Default 2011-02-22T21:38:08.57100Z,1298410688.571 [Default:4.SetSpeed] Running Loop=1 2011-02-22T21:38:08.57110Z,1298410688.5711 [Default:4.SetSpeed](DEBUG): Initialize. 2011-02-22T21:38:08.57130Z,1298410688.5713 [Default:5.GoToSurface] Running Loop=1 2011-02-22T21:38:08.57140Z,1298410688.5714 [Default:5.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T21:38:08.57200Z,1298410688.572 [Default:GPS] Running Loop=1 2011-02-22T21:38:08.57220Z,1298410688.5722 [Default:GPS](INFO): Aggregate::initialize Default:GPS 2011-02-22T21:38:08.57230Z,1298410688.5723 [Default:GPS:0.SetSpeed] Running Loop=1 2011-02-22T21:38:08.57240Z,1298410688.5724 [Default:GPS:0.SetSpeed](DEBUG): Initialize. 2011-02-22T21:38:08.57270Z,1298410688.5727 [Default:GPS:1.GoToSurface] Running Loop=1 2011-02-22T21:38:08.57280Z,1298410688.5728 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T21:38:08.57380Z,1298410688.5738 [Default:5.GoToSurface] Running Loop=1 2011-02-22T21:38:08.57990Z,1298410688.5799 [Default:4.SetSpeed] Running Loop=1 2011-02-22T21:38:08.58570Z,1298410688.5857 [Default:CallIridium] Running Loop=1 2011-02-22T21:38:08.58590Z,1298410688.5859 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium 2011-02-22T21:38:08.58620Z,1298410688.5862 [Default:CallIridium:0] Running Loop=1 2011-02-22T21:38:08.58640Z,1298410688.5864 [Default:CallIridium:0](INFO): Aggregate::initialize Default:CallIridium:0 2011-02-22T21:38:08.59250Z,1298410688.5925 [Default:GPS:1.GoToSurface] Stopped 2011-02-22T21:38:08.59260Z,1298410688.5926 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T21:38:08.59280Z,1298410688.5928 [Default:GPS:Read GPS] Running Loop=1 2011-02-22T21:38:08.59290Z,1298410688.5929 [Default:GPS:0.SetSpeed] Running Loop=1 2011-02-22T21:38:08.97700Z,1298410688.977 [Default:Iridium] Running Loop=1 2011-02-22T21:38:08.97710Z,1298410688.9771 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium 2011-02-22T21:38:08.97730Z,1298410688.9773 [Default:Iridium:0.SetSpeed] Running Loop=1 2011-02-22T21:38:08.97740Z,1298410688.9774 [Default:Iridium:0.SetSpeed](DEBUG): Initialize. 2011-02-22T21:38:08.97770Z,1298410688.9777 [Default:Iridium:1.GoToSurface] Running Loop=1 2011-02-22T21:38:08.97780Z,1298410688.9778 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T21:38:08.98420Z,1298410688.9842 [Default:Iridium:1.GoToSurface] Stopped 2011-02-22T21:38:08.98430Z,1298410688.9843 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T21:38:08.98460Z,1298410688.9846 [Default:Iridium:Read Iridium] Running Loop=1 2011-02-22T21:38:08.98460Z,1298410688.9846 [Default:Iridium:0.SetSpeed] Running Loop=1 2011-02-22T21:38:31.78130Z,1298410711.7813 [NAL9601](IMPORTANT): SBD MO Status=0, MOMSN=12733, MT Status=1, MTMSN=1575 2011-02-22T21:38:32.37760Z,1298410712.3776 [NAL9601](INFO): Received command:run Insert/Surface.xml 2011-02-22T21:38:32.47520Z,1298410712.4752 [CommandLine](IMPORTANT): got command run ./Missions/Insert/Surface.xml 2011-02-22T21:38:32.47550Z,1298410712.4755 [MissionManager](INFO): Loading Mission: ./Missions/Insert/Surface.xml 2011-02-22T21:38:32.49240Z,1298410712.4924 [MissionManager](INFO): DefineArg IridiumTimeout = 30 min 2011-02-22T21:38:32.49370Z,1298410712.4937 [SurfaceComms:0.GoToSurface](DEBUG): Construct GoToSurface. 2011-02-22T21:38:32.50520Z,1298410712.5052 [MissionManager](DEBUG): Initialize ReadDataComponent to sense time_fix 2011-02-22T21:38:32.50740Z,1298410712.5074 [MissionManager](DEBUG): Initialize ReadDataComponent to sense platform_communications 2011-02-22T21:38:32.51060Z,1298410712.5106 [MissionManager](DEBUG): Initialize ReadDataComponent to sense time_fix 2011-02-22T21:38:32.53580Z,1298410712.5358 [MissionManager](DEBUG): 30 2011-02-22T21:38:32.53630Z,1298410712.5363 [CommandLine](IMPORTANT): Running ./Missions/Insert/Surface.xml 2011-02-22T21:38:32.56690Z,1298410712.5669 [Default] Stopped 2011-02-22T21:38:32.56710Z,1298410712.5671 [Default](INFO): Aggregate::uninitialize Default 2011-02-22T21:38:32.56720Z,1298410712.5672 [Default:GPS] Stopped 2011-02-22T21:38:32.56740Z,1298410712.5674 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS 2011-02-22T21:38:32.56750Z,1298410712.5675 [Default:GPS:0.SetSpeed] Stopped 2011-02-22T21:38:32.56750Z,1298410712.5675 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize. 2011-02-22T21:38:32.56760Z,1298410712.5676 [Default:GPS:Read GPS] Stopped 2011-02-22T21:38:32.56770Z,1298410712.5677 [Default:Iridium] Stopped 2011-02-22T21:38:32.56790Z,1298410712.5679 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium 2011-02-22T21:38:32.56800Z,1298410712.568 [Default:Iridium:0.SetSpeed] Stopped 2011-02-22T21:38:32.56810Z,1298410712.5681 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize. 2011-02-22T21:38:32.56810Z,1298410712.5681 [Default:Iridium:Read Iridium] Stopped 2011-02-22T21:38:32.56820Z,1298410712.5682 [Default:CallIridium] Stopped 2011-02-22T21:38:32.56840Z,1298410712.5684 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium 2011-02-22T21:38:32.56850Z,1298410712.5685 [Default:CallIridium:0] Stopped 2011-02-22T21:38:32.56860Z,1298410712.5686 [Default:CallIridium:0](INFO): Aggregate::uninitialize Default:CallIridium:0 2011-02-22T21:38:32.56870Z,1298410712.5687 [Default:4.SetSpeed] Stopped 2011-02-22T21:38:32.56880Z,1298410712.5688 [Default:4.SetSpeed](DEBUG): Uninitialize. 2011-02-22T21:38:32.56890Z,1298410712.5689 [Default:5.GoToSurface] Stopped 2011-02-22T21:38:32.56900Z,1298410712.569 [Default:5.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T21:38:32.56910Z,1298410712.5691 [MissionManager](IMPORTANT): Started mission SurfaceComms 2011-02-22T21:38:32.56930Z,1298410712.5693 [SurfaceComms] Running Loop=1 2011-02-22T21:38:32.56940Z,1298410712.5694 [SurfaceComms](INFO): Aggregate::initialize SurfaceComms 2011-02-22T21:38:32.56950Z,1298410712.5695 [SurfaceComms:0.GoToSurface] Running Loop=1 2011-02-22T21:38:32.56960Z,1298410712.5696 [SurfaceComms:0.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T21:38:32.57620Z,1298410712.5762 [SurfaceComms:1] Running Loop=1 2011-02-22T21:38:32.57630Z,1298410712.5763 [SurfaceComms:1](INFO): Aggregate::initialize SurfaceComms:1 2011-02-22T21:38:32.57660Z,1298410712.5766 [SurfaceComms:1:0] Running Loop=1 2011-02-22T21:38:33.35120Z,1298410713.3512 [NAL9601](IMPORTANT): GPS fix at: 1298410729 2011-02-22T21:38:33.36740Z,1298410713.3674 [SurfaceComms:1:0] Stopped 2011-02-22T21:38:33.36780Z,1298410713.3678 [SurfaceComms:1:1] Running Loop=1 2011-02-22T21:38:40.34500Z,1298410720.345 [NAL9601](IMPORTANT): SBD MO Status=0, MOMSN=12734, MT Status=1, MTMSN=1576 2011-02-22T21:38:40.96150Z,1298410720.9615 [NAL9601](INFO): Received command:run Insert/Surface.xml 2011-02-22T21:38:41.03920Z,1298410721.0392 [CommandLine](IMPORTANT): got command run ./Missions/Insert/Surface.xml 2011-02-22T21:38:41.03940Z,1298410721.0394 [SurfaceComms] Stopped 2011-02-22T21:38:41.03960Z,1298410721.0396 [SurfaceComms](INFO): Aggregate::uninitialize SurfaceComms 2011-02-22T21:38:41.03970Z,1298410721.0397 [SurfaceComms:0.GoToSurface] Stopped 2011-02-22T21:38:41.03970Z,1298410721.0397 [SurfaceComms:0.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T21:38:41.03980Z,1298410721.0398 [SurfaceComms:1] Stopped 2011-02-22T21:38:41.04000Z,1298410721.04 [SurfaceComms:1](INFO): Aggregate::uninitialize SurfaceComms:1 2011-02-22T21:38:41.04010Z,1298410721.0401 [SurfaceComms:1:1] Stopped 2011-02-22T21:38:41.04190Z,1298410721.0419 [MissionManager](INFO): Loading Mission: ./Missions/Insert/Surface.xml 2011-02-22T21:38:41.05730Z,1298410721.0573 [MissionManager](INFO): DefineArg IridiumTimeout = 30 min 2011-02-22T21:38:41.05840Z,1298410721.0584 [SurfaceComms:0.GoToSurface](DEBUG): Construct GoToSurface. 2011-02-22T21:38:41.06350Z,1298410721.0635 [MissionManager](DEBUG): Initialize ReadDataComponent to sense time_fix 2011-02-22T21:38:41.06520Z,1298410721.0652 [MissionManager](DEBUG): Initialize ReadDataComponent to sense platform_communications 2011-02-22T21:38:41.06790Z,1298410721.0679 [MissionManager](DEBUG): Initialize ReadDataComponent to sense time_fix 2011-02-22T21:38:41.07000Z,1298410721.07 [MissionManager](DEBUG): 30 2011-02-22T21:38:41.07050Z,1298410721.0705 [CommandLine](IMPORTANT): Running ./Missions/Insert/Surface.xml 2011-02-22T21:38:41.16370Z,1298410721.1637 [MissionManager](IMPORTANT): Started mission SurfaceComms 2011-02-22T21:38:41.16390Z,1298410721.1639 [SurfaceComms] Running Loop=1 2011-02-22T21:38:41.16400Z,1298410721.164 [SurfaceComms](INFO): Aggregate::initialize SurfaceComms 2011-02-22T21:38:41.16410Z,1298410721.1641 [SurfaceComms:0.GoToSurface] Running Loop=1 2011-02-22T21:38:41.16420Z,1298410721.1642 [SurfaceComms:0.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T21:38:41.16620Z,1298410721.1662 [SurfaceComms:1] Running Loop=1 2011-02-22T21:38:41.16640Z,1298410721.1664 [SurfaceComms:1](INFO): Aggregate::initialize SurfaceComms:1 2011-02-22T21:38:41.16660Z,1298410721.1666 [SurfaceComms:1:0] Running Loop=1 2011-02-22T21:38:43.14730Z,1298410723.1473 [NAL9601](IMPORTANT): GPS fix at: 1298410739 2011-02-22T21:38:43.16240Z,1298410723.1624 [SurfaceComms:1:0] Stopped 2011-02-22T21:38:43.16280Z,1298410723.1628 [SurfaceComms:1:1] Running Loop=1 2011-02-22T21:39:05.74570Z,1298410745.7457 [NAL9601](INFO): SBD MO Status=0, MOMSN=12735, MT Status=0, MTMSN=0 2011-02-22T21:39:05.92210Z,1298410745.9221 [SurfaceComms:1:1] Stopped 2011-02-22T21:39:05.92230Z,1298410745.9223 [SurfaceComms:1:2] Running Loop=1 2011-02-22T21:39:08.15210Z,1298410748.1521 [NAL9601](IMPORTANT): GPS fix at: 1298410764 2011-02-22T21:39:08.16750Z,1298410748.1675 [SurfaceComms:1:2] Stopped 2011-02-22T21:39:08.16780Z,1298410748.1678 [SurfaceComms:1](INFO): Completed SurfaceComms:1 2011-02-22T21:39:08.16790Z,1298410748.1679 [SurfaceComms:1] Stopped 2011-02-22T21:39:08.16810Z,1298410748.1681 [SurfaceComms:1](INFO): Aggregate::uninitialize SurfaceComms:1 2011-02-22T21:39:08.16870Z,1298410748.1687 [SurfaceComms](INFO): Completed SurfaceComms 2011-02-22T21:39:08.16880Z,1298410748.1688 [SurfaceComms] Stopped 2011-02-22T21:39:08.16900Z,1298410748.169 [SurfaceComms](INFO): Aggregate::uninitialize SurfaceComms 2011-02-22T21:39:08.16910Z,1298410748.1691 [SurfaceComms:0.GoToSurface] Stopped 2011-02-22T21:39:08.16920Z,1298410748.1692 [SurfaceComms:0.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T21:39:08.59280Z,1298410748.5928 [MissionManager](IMPORTANT): Started mission Default 2011-02-22T21:39:08.59290Z,1298410748.5929 [Default] Running Loop=1 2011-02-22T21:39:08.59310Z,1298410748.5931 [Default](INFO): Aggregate::initialize Default 2011-02-22T21:39:08.59320Z,1298410748.5932 [Default:4.SetSpeed] Running Loop=1 2011-02-22T21:39:08.59330Z,1298410748.5933 [Default:4.SetSpeed](DEBUG): Initialize. 2011-02-22T21:39:08.59350Z,1298410748.5935 [Default:5.GoToSurface] Running Loop=1 2011-02-22T21:39:08.59360Z,1298410748.5936 [Default:5.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T21:39:08.59410Z,1298410748.5941 [Default:GPS] Running Loop=1 2011-02-22T21:39:08.59430Z,1298410748.5943 [Default:GPS](INFO): Aggregate::initialize Default:GPS 2011-02-22T21:39:08.59440Z,1298410748.5944 [Default:GPS:0.SetSpeed] Running Loop=1 2011-02-22T21:39:08.59450Z,1298410748.5945 [Default:GPS:0.SetSpeed](DEBUG): Initialize. 2011-02-22T21:39:08.59490Z,1298410748.5949 [Default:GPS:1.GoToSurface] Running Loop=1 2011-02-22T21:39:08.59500Z,1298410748.595 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T21:39:08.59690Z,1298410748.5969 [Default:GPS:1.GoToSurface] Stopped 2011-02-22T21:39:08.59700Z,1298410748.597 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T21:39:08.59730Z,1298410748.5973 [Default:GPS:Read GPS] Running Loop=1 2011-02-22T21:39:10.14680Z,1298410750.1468 [NAL9601](IMPORTANT): GPS fix at: 1298410766 2011-02-22T21:39:10.16310Z,1298410750.1631 [Default:GPS:Read GPS] Stopped 2011-02-22T21:39:10.16370Z,1298410750.1637 [Default:GPS](INFO): Completed Default:GPS 2011-02-22T21:39:10.16380Z,1298410750.1638 [Default:GPS] Stopped 2011-02-22T21:39:10.16400Z,1298410750.164 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS 2011-02-22T21:39:10.16410Z,1298410750.1641 [Default:GPS:0.SetSpeed] Stopped 2011-02-22T21:39:10.16420Z,1298410750.1642 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize. 2011-02-22T21:39:10.16440Z,1298410750.1644 [Default:Iridium] Running Loop=1 2011-02-22T21:39:10.16450Z,1298410750.1645 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium 2011-02-22T21:39:10.16460Z,1298410750.1646 [Default:Iridium:0.SetSpeed] Running Loop=1 2011-02-22T21:39:10.16470Z,1298410750.1647 [Default:Iridium:0.SetSpeed](DEBUG): Initialize. 2011-02-22T21:39:10.16500Z,1298410750.165 [Default:Iridium:1.GoToSurface] Running Loop=1 2011-02-22T21:39:10.16510Z,1298410750.1651 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T21:39:10.56170Z,1298410750.5617 [Default:Iridium:1.GoToSurface] Stopped 2011-02-22T21:39:10.56180Z,1298410750.5618 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T21:39:10.56200Z,1298410750.562 [Default:Iridium:Read Iridium] Running Loop=1 2011-02-22T21:39:34.24390Z,1298410774.2439 [NAL9601](INFO): SBD MO Status=2, MOMSN=12736, MT Status=2, MTMSN=0 2011-02-22T21:39:34.24420Z,1298410774.2442 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2 2011-02-22T21:39:57.38230Z,1298410797.3823 [NAL9601](INFO): SBD MO Status=1, MOMSN=12736, MT Status=0, MTMSN=0 2011-02-22T21:39:57.52730Z,1298410797.5273 [NAL9601](INFO): Sent 332 bytes from file Logs/20110222T210900/shore0003.lzma 2011-02-22T21:39:57.52760Z,1298410797.5276 [NAL9601](INFO): Packets left to send: 1 2011-02-22T21:39:57.52870Z,1298410797.5287 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000005 2011-02-22T21:40:10.74930Z,1298410810.7493 [NAL9601](INFO): SBD MO Status=2, MOMSN=12737, MT Status=2, MTMSN=0 2011-02-22T21:40:10.74960Z,1298410810.7496 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2 2011-02-22T21:40:38.26190Z,1298410838.2619 [NAL9601](INFO): SBD MO Status=1, MOMSN=12737, MT Status=0, MTMSN=0 2011-02-22T21:40:38.46330Z,1298410838.4633 [NAL9601](INFO): Sent 30 bytes from file Logs/20110222T210900/shore0003.lzma 2011-02-22T21:40:38.46350Z,1298410838.4635 [NAL9601](INFO): Packets left to send: 0 2011-02-22T21:40:38.46470Z,1298410838.4647 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000006 2011-02-22T21:40:54.23010Z,1298410854.2301 [NAL9601](INFO): SBD MO Status=0, MOMSN=12738, MT Status=0, MTMSN=0 2011-02-22T21:40:54.45500Z,1298410854.455 [Default:Iridium:Read Iridium] Stopped 2011-02-22T21:40:54.45560Z,1298410854.4556 [Default:Iridium](INFO): Completed Default:Iridium 2011-02-22T21:40:54.45580Z,1298410854.4558 [Default:Iridium] Stopped 2011-02-22T21:40:54.45590Z,1298410854.4559 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium 2011-02-22T21:40:54.45600Z,1298410854.456 [Default:Iridium:0.SetSpeed] Stopped 2011-02-22T21:40:54.45610Z,1298410854.4561 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize. 2011-02-22T21:40:54.45630Z,1298410854.4563 [Default:6.Wait] Running Loop=1 2011-02-22T21:40:54.45640Z,1298410854.4564 [Default:6.Wait](DEBUG): Initialize Wait Component. 2011-02-22T21:41:04.72120Z,1298410864.7212 [NAL9601](INFO): Powering down 2011-02-22T21:44:14.77410Z,1298411054.7741 [Default:CallGPS] Running Loop=1 2011-02-22T21:44:14.77430Z,1298411054.7743 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS 2011-02-22T21:44:14.77460Z,1298411054.7746 [Default:CallGPS:0] Running Loop=1 2011-02-22T21:44:14.77480Z,1298411054.7748 [Default:CallGPS:0](INFO): Aggregate::initialize Default:CallGPS:0 2011-02-22T21:44:19.71990Z,1298411059.7199 [Default:GPS] Running Loop=1 2011-02-22T21:44:19.72010Z,1298411059.7201 [Default:GPS](INFO): Aggregate::initialize Default:GPS 2011-02-22T21:44:19.72020Z,1298411059.7202 [Default:GPS:0.SetSpeed] Running Loop=1 2011-02-22T21:44:19.72030Z,1298411059.7203 [Default:GPS:0.SetSpeed](DEBUG): Initialize. 2011-02-22T21:44:19.72060Z,1298411059.7206 [Default:GPS:1.GoToSurface] Running Loop=1 2011-02-22T21:44:19.72070Z,1298411059.7207 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T21:44:19.72150Z,1298411059.7215 [Default:GPS:1.GoToSurface] Stopped 2011-02-22T21:44:19.72160Z,1298411059.7216 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T21:44:19.72180Z,1298411059.7218 [Default:GPS:Read GPS] Running Loop=1 2011-02-22T21:44:20.42870Z,1298411060.4287 [NAL9601](INFO): Powering up 2011-02-22T21:45:26.13940Z,1298411126.1394 [NAL9601](INFO): NAL9601 initialized 2011-02-22T21:45:37.25260Z,1298411137.2526 [NAL9601](IMPORTANT): GPS fix at: 1298411154 2011-02-22T21:45:37.26940Z,1298411137.2694 [Default:GPS:Read GPS] Stopped 2011-02-22T21:45:37.26990Z,1298411137.2699 [Default:GPS](INFO): Completed Default:GPS 2011-02-22T21:45:37.27000Z,1298411137.27 [Default:GPS] Stopped 2011-02-22T21:45:37.27020Z,1298411137.2702 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS 2011-02-22T21:45:37.27030Z,1298411137.2703 [Default:GPS:0.SetSpeed] Stopped 2011-02-22T21:45:37.27030Z,1298411137.2703 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize. 2011-02-22T21:45:37.64010Z,1298411137.6401 [Default:CallGPS:0](INFO): Completed Default:CallGPS:0 2011-02-22T21:45:37.64020Z,1298411137.6402 [Default:CallGPS:0] Stopped 2011-02-22T21:45:37.64030Z,1298411137.6403 [Default:CallGPS:0](INFO): Aggregate::uninitialize Default:CallGPS:0 2011-02-22T21:45:37.64060Z,1298411137.6406 [Default:CallGPS](INFO): Completed Default:CallGPS 2011-02-22T21:45:37.64070Z,1298411137.6407 [Default:CallGPS] Stopped 2011-02-22T21:45:37.64080Z,1298411137.6408 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS 2011-02-22T21:45:57.75870Z,1298411157.7587 [NAL9601](INFO): Powering down 2011-02-22T21:45:57.77700Z,1298411157.777 [Default:CallIridium] Running Loop=1 2011-02-22T21:45:57.77720Z,1298411157.7772 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium 2011-02-22T21:45:57.77740Z,1298411157.7774 [Default:CallIridium:0] Running Loop=1 2011-02-22T21:45:57.77760Z,1298411157.7776 [Default:CallIridium:0](INFO): Aggregate::initialize Default:CallIridium:0 2011-02-22T21:46:02.79090Z,1298411162.7909 [Default:Iridium] Running Loop=1 2011-02-22T21:46:02.79110Z,1298411162.7911 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium 2011-02-22T21:46:02.79120Z,1298411162.7912 [Default:Iridium:0.SetSpeed] Running Loop=1 2011-02-22T21:46:02.79130Z,1298411162.7913 [Default:Iridium:0.SetSpeed](DEBUG): Initialize. 2011-02-22T21:46:02.79150Z,1298411162.7915 [Default:Iridium:1.GoToSurface] Running Loop=1 2011-02-22T21:46:02.79160Z,1298411162.7916 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T21:46:02.79240Z,1298411162.7924 [Default:Iridium:1.GoToSurface] Stopped 2011-02-22T21:46:02.79250Z,1298411162.7925 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T21:46:02.79270Z,1298411162.7927 [Default:Iridium:Read Iridium] Running Loop=1 2011-02-22T21:46:03.44980Z,1298411163.4498 [NAL9601](INFO): Powering up 2011-02-22T21:47:09.05940Z,1298411229.0594 [NAL9601](INFO): NAL9601 initialized 2011-02-22T21:47:24.92150Z,1298411244.9215 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=12739, MT Status=1, MTMSN=1577 2011-02-22T21:47:25.12330Z,1298411245.1233 [NAL9601](INFO): Sent 121 bytes from file Logs/20110222T210900/shore0004.lzma 2011-02-22T21:47:25.12360Z,1298411245.1236 [NAL9601](INFO): Packets left to send: 0 2011-02-22T21:47:25.12470Z,1298411245.1247 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000007 2011-02-22T21:47:25.54150Z,1298411245.5415 [NAL9601](INFO): Received command:run Transport/transit_3km.xml 2011-02-22T21:47:25.61120Z,1298411245.6112 [CommandLine](IMPORTANT): got command run ./Missions/Transport/transit_3km.xml 2011-02-22T21:47:25.61150Z,1298411245.6115 [MissionManager](INFO): Loading Mission: ./Missions/Transport/transit_3km.xml 2011-02-22T21:47:25.66810Z,1298411245.6681 [MissionManager](INFO): DefineArg ApproachDepth = 10 m 2011-02-22T21:47:25.67180Z,1298411245.6718 [MissionManager](INFO): DefineArg Wpt1Lat = 36.806966 arcdeg 2011-02-22T21:47:25.67540Z,1298411245.6754 [MissionManager](INFO): DefineArg Wpt1Lon = -121.824326 arcdeg 2011-02-22T21:47:25.67890Z,1298411245.6789 [MissionManager](INFO): DefineArg Speed = 1 m/s 2011-02-22T21:47:25.68090Z,1298411245.6809 [transit_3km:0.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope. 2011-02-22T21:47:25.79590Z,1298411245.7959 [transit_3km:1.DepthEnvelope](DEBUG): Construct DepthEnvelope. 2011-02-22T21:47:25.87770Z,1298411245.8777 [transit_3km:2.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope. 2011-02-22T21:47:25.93970Z,1298411245.9397 [transit_3km:SURFACECOMMS:0.GoToSurface](DEBUG): Construct GoToSurface. 2011-02-22T21:47:25.96190Z,1298411245.9619 [transit_3km:SURFACECOMMS:1:0.SetSpeed](DEBUG): Construct. 2011-02-22T21:47:25.98940Z,1298411245.9894 [MissionManager](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2011-02-22T21:47:25.99170Z,1298411245.9917 [MissionManager](DEBUG): Initialize ReadDataComponent to sense platform_communications 2011-02-22T21:47:26.00890Z,1298411246.0089 [MissionManager](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2011-02-22T21:47:26.01380Z,1298411246.0138 [transit_3km:5.Buoyancy](DEBUG): Construct Buoyancy. 2011-02-22T21:47:26.03810Z,1298411246.0381 [transit_3km:WaypointOne:0.Pitch](DEBUG): Construct. 2011-02-22T21:47:26.11350Z,1298411246.1135 [transit_3km:WaypointOne:1.SetSpeed](DEBUG): Construct. 2011-02-22T21:47:26.15180Z,1298411246.1518 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Construct Waypoint. 2011-02-22T21:47:26.22770Z,1298411246.2277 [MissionManager](DEBUG):  10.0 36.806966 -121.824326 1 7 20 1 0 35 275 2011-02-22T21:47:26.22830Z,1298411246.2283 [CommandLine](IMPORTANT): Running ./Missions/Transport/transit_3km.xml 2011-02-22T21:47:26.29100Z,1298411246.291 [Default] Stopped 2011-02-22T21:47:26.29120Z,1298411246.2912 [Default](INFO): Aggregate::uninitialize Default 2011-02-22T21:47:26.29130Z,1298411246.2913 [Default:Iridium] Stopped 2011-02-22T21:47:26.29150Z,1298411246.2915 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium 2011-02-22T21:47:26.29160Z,1298411246.2916 [Default:Iridium:0.SetSpeed] Stopped 2011-02-22T21:47:26.29170Z,1298411246.2917 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize. 2011-02-22T21:47:26.29180Z,1298411246.2918 [Default:Iridium:Read Iridium] Stopped 2011-02-22T21:47:26.29180Z,1298411246.2918 [Default:CallIridium] Stopped 2011-02-22T21:47:26.29200Z,1298411246.292 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium 2011-02-22T21:47:26.29210Z,1298411246.2921 [Default:CallIridium:0] Stopped 2011-02-22T21:47:26.29230Z,1298411246.2923 [Default:CallIridium:0](INFO): Aggregate::uninitialize Default:CallIridium:0 2011-02-22T21:47:26.29240Z,1298411246.2924 [Default:4.SetSpeed] Stopped 2011-02-22T21:47:26.29240Z,1298411246.2924 [Default:4.SetSpeed](DEBUG): Uninitialize. 2011-02-22T21:47:26.29250Z,1298411246.2925 [Default:5.GoToSurface] Stopped 2011-02-22T21:47:26.29260Z,1298411246.2926 [Default:5.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T21:47:26.29270Z,1298411246.2927 [Default:6.Wait] Stopped 2011-02-22T21:47:26.29280Z,1298411246.2928 [Default:6.Wait](DEBUG): Uninitialize Wait Component. 2011-02-22T21:47:26.29300Z,1298411246.293 [MissionManager](IMPORTANT): Started mission transit_3km 2011-02-22T21:47:26.29310Z,1298411246.2931 [transit_3km] Running Loop=1 2011-02-22T21:47:26.29320Z,1298411246.2932 [transit_3km](INFO): Aggregate::initialize transit_3km 2011-02-22T21:47:26.29330Z,1298411246.2933 [transit_3km:0.AltitudeEnvelope] Running Loop=1 2011-02-22T21:47:26.29340Z,1298411246.2934 [transit_3km:0.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent. 2011-02-22T21:47:26.29370Z,1298411246.2937 [transit_3km:1.DepthEnvelope] Running Loop=1 2011-02-22T21:47:26.29380Z,1298411246.2938 [transit_3km:1.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent. 2011-02-22T21:47:26.29500Z,1298411246.295 [transit_3km:2.OffshoreEnvelope] Running Loop=1 2011-02-22T21:47:26.29510Z,1298411246.2951 [transit_3km:2.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent. 2011-02-22T21:47:26.29820Z,1298411246.2982 [transit_3km:2.OffshoreEnvelope](DEBUG): Opened Resources/cencalShoreDist.nc 2011-02-22T21:47:26.31650Z,1298411246.3165 [transit_3km:5.Buoyancy] Running Loop=1 2011-02-22T21:47:26.31660Z,1298411246.3166 [transit_3km:5.Buoyancy](DEBUG): Initialize Buoyancy Component. 2011-02-22T21:47:26.31730Z,1298411246.3173 [transit_3km:SURFACECOMMS] Running Loop=1 2011-02-22T21:47:26.31750Z,1298411246.3175 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS 2011-02-22T21:47:26.31760Z,1298411246.3176 [transit_3km:SURFACECOMMS:0.GoToSurface] Running Loop=1 2011-02-22T21:47:26.31770Z,1298411246.3177 [transit_3km:SURFACECOMMS:0.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T21:47:26.31860Z,1298411246.3186 [transit_3km:5.Buoyancy] Running Loop=1 2011-02-22T21:47:26.33010Z,1298411246.3301 [transit_3km:SURFACECOMMS:1] Running Loop=1 2011-02-22T21:47:26.33020Z,1298411246.3302 [transit_3km:SURFACECOMMS:1](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:1 2011-02-22T21:47:26.33030Z,1298411246.3303 [transit_3km:SURFACECOMMS:1:0.SetSpeed] Running Loop=1 2011-02-22T21:47:26.33040Z,1298411246.3304 [transit_3km:SURFACECOMMS:1:0.SetSpeed](DEBUG): Initialize. 2011-02-22T21:47:26.33100Z,1298411246.331 [transit_3km:SURFACECOMMS:1:1] Running Loop=1 2011-02-22T21:47:26.33120Z,1298411246.3312 [transit_3km:2.OffshoreEnvelope] Running Loop=1 2011-02-22T21:47:26.33800Z,1298411246.338 [transit_3km:1.DepthEnvelope] Running Loop=1 2011-02-22T21:47:26.34460Z,1298411246.3446 [transit_3km:0.AltitudeEnvelope] Running Loop=1 2011-02-22T21:47:26.69600Z,1298411246.696 [transit_3km:5.Buoyancy] Preempted 2011-02-22T21:47:26.69800Z,1298411246.698 [transit_3km:SURFACECOMMS:1:0.SetSpeed] Running Loop=1 2011-02-22T21:47:36.49420Z,1298411256.4942 [NAL9601](INFO): SBD MO Status=0, MOMSN=12740, MT Status=0, MTMSN=0 2011-02-22T21:47:37.77180Z,1298411257.7718 [NAL9601](IMPORTANT): GPS fix at: 1298411274 2011-02-22T21:47:37.78790Z,1298411257.7879 [transit_3km:SURFACECOMMS:1:1] Stopped 2011-02-22T21:47:37.78810Z,1298411257.7881 [transit_3km:SURFACECOMMS:1:2] Running Loop=1 2011-02-22T21:47:51.27270Z,1298411271.2727 [NAL9601](INFO): SBD MO Status=1, MOMSN=12741, MT Status=0, MTMSN=0 2011-02-22T21:47:51.48330Z,1298411271.4833 [NAL9601](INFO): Sent 254 bytes from file Logs/20110222T210900/shore0005.lzma 2011-02-22T21:47:51.48360Z,1298411271.4836 [NAL9601](INFO): Packets left to send: 0 2011-02-22T21:47:51.48470Z,1298411271.4847 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000008 2011-02-22T21:48:08.42910Z,1298411288.4291 [NAL9601](INFO): SBD MO Status=2, MOMSN=12742, MT Status=2, MTMSN=0 2011-02-22T21:48:08.42940Z,1298411288.4294 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2 2011-02-22T21:48:19.46150Z,1298411299.4615 [NAL9601](INFO): SBD MO Status=0, MOMSN=12742, MT Status=0, MTMSN=0 2011-02-22T21:48:19.65490Z,1298411299.6549 [transit_3km:SURFACECOMMS:1:2] Stopped 2011-02-22T21:48:19.65510Z,1298411299.6551 [transit_3km:SURFACECOMMS:1:3] Running Loop=1 2011-02-22T21:48:21.86570Z,1298411301.8657 [NAL9601](IMPORTANT): GPS fix at: 1298411318 2011-02-22T21:48:21.88210Z,1298411301.8821 [transit_3km:SURFACECOMMS:1:3] Stopped 2011-02-22T21:48:21.88280Z,1298411301.8828 [transit_3km:SURFACECOMMS:1](INFO): Completed transit_3km:SURFACECOMMS:1 2011-02-22T21:48:21.88290Z,1298411301.8829 [transit_3km:SURFACECOMMS:1] Stopped 2011-02-22T21:48:21.88310Z,1298411301.8831 [transit_3km:SURFACECOMMS:1](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:1 2011-02-22T21:48:21.88320Z,1298411301.8832 [transit_3km:SURFACECOMMS:1:0.SetSpeed] Stopped 2011-02-22T21:48:21.88330Z,1298411301.8833 [transit_3km:SURFACECOMMS:1:0.SetSpeed](DEBUG): Uninitialize. 2011-02-22T21:48:21.88390Z,1298411301.8839 [transit_3km:SURFACECOMMS](INFO): Completed transit_3km:SURFACECOMMS 2011-02-22T21:48:21.88400Z,1298411301.884 [transit_3km:SURFACECOMMS] Stopped 2011-02-22T21:48:21.88410Z,1298411301.8841 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS 2011-02-22T21:48:21.88420Z,1298411301.8842 [transit_3km:SURFACECOMMS:0.GoToSurface] Stopped 2011-02-22T21:48:21.88430Z,1298411301.8843 [transit_3km:SURFACECOMMS:0.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T21:48:21.88450Z,1298411301.8845 [transit_3km:WaypointOne] Running Loop=1 2011-02-22T21:48:21.88470Z,1298411301.8847 [transit_3km:WaypointOne](INFO): Aggregate::initialize transit_3km:WaypointOne 2011-02-22T21:48:21.88510Z,1298411301.8851 [transit_3km:WaypointOne:0.Pitch] Running Loop=1 2011-02-22T21:48:21.88520Z,1298411301.8852 [transit_3km:WaypointOne:0.Pitch](DEBUG): Initialize. 2011-02-22T21:48:21.88560Z,1298411301.8856 [transit_3km:WaypointOne:1.SetSpeed] Running Loop=1 2011-02-22T21:48:21.88570Z,1298411301.8857 [transit_3km:WaypointOne:1.SetSpeed](DEBUG): Initialize. 2011-02-22T21:48:21.88650Z,1298411301.8865 [transit_3km:WaypointOne:WaypointW1.Waypoint] Running Loop=1 2011-02-22T21:48:21.88660Z,1298411301.8866 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Initialize WaypointComponent. 2011-02-22T21:48:22.24940Z,1298411302.2494 [transit_3km:WaypointOne:1.SetSpeed] Running Loop=1 2011-02-22T21:48:22.25480Z,1298411302.2548 [transit_3km:WaypointOne:0.Pitch] Running Loop=1 2011-02-22T21:48:22.26050Z,1298411302.2605 [transit_3km:5.Buoyancy] Running Loop=1 2011-02-22T21:48:28.22760Z,1298411308.2276 [NAL9601](INFO): Powering down 2011-02-22T21:51:52.41760Z,1298411512.4176 [Radio_Freewave](INFO): Powering down 2011-02-22T21:52:01.26580Z,1298411521.2658 [Radio_Freewave](INFO): Powering up 2011-02-22T21:52:06.04920Z,1298411526.0492 [Radio_Freewave](INFO): Powering down 2011-02-22T21:52:14.42950Z,1298411534.4295 [Radio_Freewave](INFO): Powering up 2011-02-22T21:52:17.63270Z,1298411537.6327 [Radio_Freewave](INFO): Powering down 2011-02-22T22:10:21.41230Z,1298412621.4123 [transit_3km:WaypointOne:WaypointW1.Waypoint](INFO): Reached Waypoint: 36.80696736,-121.8243195 2011-02-22T22:10:21.41270Z,1298412621.4127 [transit_3km:WaypointOne:WaypointW1.Waypoint] Stopped 2011-02-22T22:10:21.41280Z,1298412621.4128 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Uninitialize WaypointComponent. 2011-02-22T22:10:21.41300Z,1298412621.413 [transit_3km:WaypointOne:PHONEHOMEWPT1] Running Loop=1 2011-02-22T22:10:21.41320Z,1298412621.4132 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Aggregate::initialize transit_3km:WaypointOne:PHONEHOMEWPT1 2011-02-22T22:10:21.83110Z,1298412621.8311 [transit_3km:SURFACECOMMS] Running Loop=1 2011-02-22T22:10:21.83130Z,1298412621.8313 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS 2011-02-22T22:10:21.83150Z,1298412621.8315 [transit_3km:SURFACECOMMS:0.GoToSurface] Running Loop=1 2011-02-22T22:10:21.83160Z,1298412621.8316 [transit_3km:SURFACECOMMS:0.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T22:11:47.88420Z,1298412707.8842 [Radio_Freewave](INFO): Powering up 2011-02-22T22:11:47.89690Z,1298412707.8969 [transit_3km:SURFACECOMMS:1] Running Loop=1 2011-02-22T22:11:47.89710Z,1298412707.8971 [transit_3km:SURFACECOMMS:1](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:1 2011-02-22T22:11:47.89720Z,1298412707.8972 [transit_3km:SURFACECOMMS:1:0.SetSpeed] Running Loop=1 2011-02-22T22:11:47.89730Z,1298412707.8973 [transit_3km:SURFACECOMMS:1:0.SetSpeed](DEBUG): Initialize. 2011-02-22T22:11:47.89760Z,1298412707.8976 [transit_3km:SURFACECOMMS:1:1] Running Loop=1 2011-02-22T22:11:48.24830Z,1298412708.2483 [transit_3km:5.Buoyancy] Preempted 2011-02-22T22:11:48.64510Z,1298412708.6451 [NAL9601](INFO): Powering up 2011-02-22T22:12:54.35540Z,1298412774.3554 [NAL9601](INFO): NAL9601 initialized 2011-02-22T22:12:55.43520Z,1298412775.4352 [NAL9601](IMPORTANT): GPS fix at: 1298412794 2011-02-22T22:12:55.45120Z,1298412775.4512 [transit_3km:SURFACECOMMS:1:1] Stopped 2011-02-22T22:12:55.45140Z,1298412775.4514 [transit_3km:SURFACECOMMS:1:2] Running Loop=1 2011-02-22T22:13:35.03040Z,1298412815.0304 [NAL9601](INFO): SBD MO Status=2, MOMSN=12743, MT Status=2, MTMSN=0 2011-02-22T22:13:35.03070Z,1298412815.0307 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2 2011-02-22T22:14:22.64130Z,1298412862.6413 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=12743, MT Status=1, MTMSN=1578 2011-02-22T22:14:22.80730Z,1298412862.8073 [NAL9601](INFO): Sent 278 bytes from file Logs/20110222T210900/shore0006.lzma 2011-02-22T22:14:22.80760Z,1298412862.8076 [NAL9601](INFO): Packets left to send: 0 2011-02-22T22:14:22.80870Z,1298412862.8087 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000009 2011-02-22T22:14:23.33600Z,1298412863.336 [NAL9601](IMPORTANT): Initialized file: Config/lrauv-tethys/Sensor.cfg 2011-02-22T22:14:25.75110Z,1298412865.7511 [NAL9601](IMPORTANT): Success executing cat Logs/latest/4D642E3D.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-22T22:14:25.81030Z,1298412865.8103 [CommandLine](IMPORTANT): 14aaf0c412a849fc09a9128a139de6d6 Config/lrauv-tethys/Sensor.cfg 2011-02-22T22:14:27.77010Z,1298412867.7701 [NAL9601](ERROR): Inadequate Iridium signal strength reported: 0 2011-02-22T22:14:54.77410Z,1298412894.7741 [NAL9601](IMPORTANT): SBD MO Status=0, MOMSN=12744, MT Status=1, MTMSN=1579 2011-02-22T22:14:55.37350Z,1298412895.3735 [NAL9601](INFO): Received command:run Insert/Surface.xml 2011-02-22T22:14:55.43120Z,1298412895.4312 [CommandLine](IMPORTANT): got command run ./Missions/Insert/Surface.xml 2011-02-22T22:14:55.43140Z,1298412895.4314 [transit_3km] Stopped 2011-02-22T22:14:55.43160Z,1298412895.4316 [transit_3km](INFO): Aggregate::uninitialize transit_3km 2011-02-22T22:14:55.43170Z,1298412895.4317 [transit_3km:0.AltitudeEnvelope] Stopped 2011-02-22T22:14:55.43180Z,1298412895.4318 [transit_3km:0.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent. 2011-02-22T22:14:55.43190Z,1298412895.4319 [transit_3km:1.DepthEnvelope] Stopped 2011-02-22T22:14:55.43200Z,1298412895.432 [transit_3km:1.DepthEnvelope](DEBUG): Uninitialize. 2011-02-22T22:14:55.43210Z,1298412895.4321 [transit_3km:2.OffshoreEnvelope] Stopped 2011-02-22T22:14:55.43210Z,1298412895.4321 [transit_3km:2.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent. 2011-02-22T22:14:55.43280Z,1298412895.4328 [transit_3km:SURFACECOMMS] Stopped 2011-02-22T22:14:55.43300Z,1298412895.433 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS 2011-02-22T22:14:55.43320Z,1298412895.4332 [transit_3km:SURFACECOMMS:0.GoToSurface] Stopped 2011-02-22T22:14:55.43320Z,1298412895.4332 [transit_3km:SURFACECOMMS:0.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T22:14:55.43330Z,1298412895.4333 [transit_3km:SURFACECOMMS:1] Stopped 2011-02-22T22:14:55.43350Z,1298412895.4335 [transit_3km:SURFACECOMMS:1](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:1 2011-02-22T22:14:55.43360Z,1298412895.4336 [transit_3km:SURFACECOMMS:1:0.SetSpeed] Stopped 2011-02-22T22:14:55.43370Z,1298412895.4337 [transit_3km:SURFACECOMMS:1:0.SetSpeed](DEBUG): Uninitialize. 2011-02-22T22:14:55.43380Z,1298412895.4338 [transit_3km:SURFACECOMMS:1:2] Stopped 2011-02-22T22:14:55.43390Z,1298412895.4339 [transit_3km:5.Buoyancy] Stopped 2011-02-22T22:14:55.43400Z,1298412895.434 [transit_3km:5.Buoyancy](DEBUG): Uninitialize Buoyancy Component. 2011-02-22T22:14:55.43410Z,1298412895.4341 [transit_3km:WaypointOne] Stopped 2011-02-22T22:14:55.43420Z,1298412895.4342 [transit_3km:WaypointOne](INFO): Aggregate::uninitialize transit_3km:WaypointOne 2011-02-22T22:14:55.43430Z,1298412895.4343 [transit_3km:WaypointOne:0.Pitch] Stopped 2011-02-22T22:14:55.43440Z,1298412895.4344 [transit_3km:WaypointOne:1.SetSpeed] Stopped 2011-02-22T22:14:55.43450Z,1298412895.4345 [transit_3km:WaypointOne:1.SetSpeed](DEBUG): Uninitialize. 2011-02-22T22:14:55.43460Z,1298412895.4346 [transit_3km:WaypointOne:PHONEHOMEWPT1] Stopped 2011-02-22T22:14:55.43480Z,1298412895.4348 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Aggregate::uninitialize transit_3km:WaypointOne:PHONEHOMEWPT1 2011-02-22T22:14:55.44420Z,1298412895.4442 [MissionManager](INFO): Loading Mission: ./Missions/Insert/Surface.xml 2011-02-22T22:14:55.46410Z,1298412895.4641 [MissionManager](INFO): DefineArg IridiumTimeout = 30 min 2011-02-22T22:14:55.46510Z,1298412895.4651 [SurfaceComms:0.GoToSurface](DEBUG): Construct GoToSurface. 2011-02-22T22:14:55.47020Z,1298412895.4702 [MissionManager](DEBUG): Initialize ReadDataComponent to sense time_fix 2011-02-22T22:14:55.48410Z,1298412895.4841 [MissionManager](DEBUG): Initialize ReadDataComponent to sense platform_communications 2011-02-22T22:14:55.48650Z,1298412895.4865 [MissionManager](DEBUG): Initialize ReadDataComponent to sense time_fix 2011-02-22T22:14:55.48880Z,1298412895.4888 [MissionManager](DEBUG): 30 2011-02-22T22:14:55.48930Z,1298412895.4893 [CommandLine](IMPORTANT): Running ./Missions/Insert/Surface.xml 2011-02-22T22:14:55.74220Z,1298412895.7422 [MissionManager](IMPORTANT): Started mission SurfaceComms 2011-02-22T22:14:55.74240Z,1298412895.7424 [SurfaceComms] Running Loop=1 2011-02-22T22:14:55.74250Z,1298412895.7425 [SurfaceComms](INFO): Aggregate::initialize SurfaceComms 2011-02-22T22:14:55.74260Z,1298412895.7426 [SurfaceComms:0.GoToSurface] Running Loop=1 2011-02-22T22:14:55.74280Z,1298412895.7428 [SurfaceComms:0.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T22:14:55.74470Z,1298412895.7447 [SurfaceComms:1] Running Loop=1 2011-02-22T22:14:55.74490Z,1298412895.7449 [SurfaceComms:1](INFO): Aggregate::initialize SurfaceComms:1 2011-02-22T22:14:55.74510Z,1298412895.7451 [SurfaceComms:1:0] Running Loop=1 2011-02-22T22:14:57.61920Z,1298412897.6192 [NAL9601](IMPORTANT): GPS fix at: 1298412917 2011-02-22T22:14:57.63490Z,1298412897.6349 [SurfaceComms:1:0] Stopped 2011-02-22T22:14:57.63520Z,1298412897.6352 [SurfaceComms:1:1] Running Loop=1 2011-02-22T22:15:11.85170Z,1298412911.8517 [NAL9601](INFO): SBD MO Status=0, MOMSN=12745, MT Status=0, MTMSN=0 2011-02-22T22:15:12.04630Z,1298412912.0463 [SurfaceComms:1:1] Stopped 2011-02-22T22:15:12.04650Z,1298412912.0465 [SurfaceComms:1:2] Running Loop=1 2011-02-22T22:15:14.22040Z,1298412914.2204 [NAL9601](IMPORTANT): GPS fix at: 1298412933 2011-02-22T22:15:14.23590Z,1298412914.2359 [SurfaceComms:1:2] Stopped 2011-02-22T22:15:14.23620Z,1298412914.2362 [SurfaceComms:1](INFO): Completed SurfaceComms:1 2011-02-22T22:15:14.23630Z,1298412914.2363 [SurfaceComms:1] Stopped 2011-02-22T22:15:14.23650Z,1298412914.2365 [SurfaceComms:1](INFO): Aggregate::uninitialize SurfaceComms:1 2011-02-22T22:15:14.23720Z,1298412914.2372 [SurfaceComms](INFO): Completed SurfaceComms 2011-02-22T22:15:14.23730Z,1298412914.2373 [SurfaceComms] Stopped 2011-02-22T22:15:14.23750Z,1298412914.2375 [SurfaceComms](INFO): Aggregate::uninitialize SurfaceComms 2011-02-22T22:15:14.23760Z,1298412914.2376 [SurfaceComms:0.GoToSurface] Stopped 2011-02-22T22:15:14.23760Z,1298412914.2376 [SurfaceComms:0.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T22:15:14.63570Z,1298412914.6357 [MissionManager](IMPORTANT): Started mission Default 2011-02-22T22:15:14.63580Z,1298412914.6358 [Default] Running Loop=1 2011-02-22T22:15:14.63600Z,1298412914.636 [Default](INFO): Aggregate::initialize Default 2011-02-22T22:15:14.63610Z,1298412914.6361 [Default:4.SetSpeed] Running Loop=1 2011-02-22T22:15:14.63620Z,1298412914.6362 [Default:4.SetSpeed](DEBUG): Initialize. 2011-02-22T22:15:14.63640Z,1298412914.6364 [Default:5.GoToSurface] Running Loop=1 2011-02-22T22:15:14.63650Z,1298412914.6365 [Default:5.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T22:15:14.63700Z,1298412914.637 [Default:GPS] Running Loop=1 2011-02-22T22:15:14.63720Z,1298412914.6372 [Default:GPS](INFO): Aggregate::initialize Default:GPS 2011-02-22T22:15:14.63730Z,1298412914.6373 [Default:GPS:0.SetSpeed] Running Loop=1 2011-02-22T22:15:14.63740Z,1298412914.6374 [Default:GPS:0.SetSpeed](DEBUG): Initialize. 2011-02-22T22:15:14.63770Z,1298412914.6377 [Default:GPS:1.GoToSurface] Running Loop=1 2011-02-22T22:15:14.63780Z,1298412914.6378 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T22:15:14.63980Z,1298412914.6398 [Default:GPS:1.GoToSurface] Stopped 2011-02-22T22:15:14.63990Z,1298412914.6399 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T22:15:14.64010Z,1298412914.6401 [Default:GPS:Read GPS] Running Loop=1 2011-02-22T22:15:16.28590Z,1298412916.2859 [NAL9601](IMPORTANT): GPS fix at: 1298412935 2011-02-22T22:15:16.30260Z,1298412916.3026 [Default:GPS:Read GPS] Stopped 2011-02-22T22:15:16.30320Z,1298412916.3032 [Default:GPS](INFO): Completed Default:GPS 2011-02-22T22:15:16.30330Z,1298412916.3033 [Default:GPS] Stopped 2011-02-22T22:15:16.30340Z,1298412916.3034 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS 2011-02-22T22:15:16.30350Z,1298412916.3035 [Default:GPS:0.SetSpeed] Stopped 2011-02-22T22:15:16.30360Z,1298412916.3036 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize. 2011-02-22T22:15:16.30380Z,1298412916.3038 [Default:Iridium] Running Loop=1 2011-02-22T22:15:16.30400Z,1298412916.304 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium 2011-02-22T22:15:16.30410Z,1298412916.3041 [Default:Iridium:0.SetSpeed] Running Loop=1 2011-02-22T22:15:16.30420Z,1298412916.3042 [Default:Iridium:0.SetSpeed](DEBUG): Initialize. 2011-02-22T22:15:16.30440Z,1298412916.3044 [Default:Iridium:1.GoToSurface] Running Loop=1 2011-02-22T22:15:16.30450Z,1298412916.3045 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T22:15:16.63220Z,1298412916.6322 [Default:Iridium:1.GoToSurface] Stopped 2011-02-22T22:15:16.63230Z,1298412916.6323 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T22:15:16.63250Z,1298412916.6325 [Default:Iridium:Read Iridium] Running Loop=1 2011-02-22T22:16:03.20280Z,1298412963.2028 [NAL9601](INFO): SBD MO Status=2, MOMSN=12746, MT Status=2, MTMSN=0 2011-02-22T22:16:03.20310Z,1298412963.2031 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2 2011-02-22T22:16:32.48540Z,1298412992.4854 [NAL9601](INFO): SBD MO Status=2, MOMSN=12746, MT Status=2, MTMSN=0 2011-02-22T22:16:32.48570Z,1298412992.4857 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2 2011-02-22T22:17:03.43740Z,1298413023.4374 [NAL9601](INFO): SBD MO Status=1, MOMSN=12746, MT Status=0, MTMSN=0 2011-02-22T22:17:03.55930Z,1298413023.5593 [NAL9601](INFO): Sent 332 bytes from file Logs/20110222T210900/shore0007.lzma 2011-02-22T22:17:03.55950Z,1298413023.5595 [NAL9601](INFO): Packets left to send: 1 2011-02-22T22:17:03.56130Z,1298413023.5613 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000010 2011-02-22T22:17:11.66840Z,1298413031.6684 [NAL9601](INFO): SBD MO Status=1, MOMSN=12747, MT Status=0, MTMSN=0 2011-02-22T22:17:11.84730Z,1298413031.8473 [NAL9601](INFO): Sent 155 bytes from file Logs/20110222T210900/shore0007.lzma 2011-02-22T22:17:11.84760Z,1298413031.8476 [NAL9601](INFO): Packets left to send: 0 2011-02-22T22:17:11.84870Z,1298413031.8487 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000011 2011-02-22T22:17:23.20630Z,1298413043.2063 [NAL9601](INFO): SBD MO Status=0, MOMSN=12748, MT Status=0, MTMSN=0 2011-02-22T22:17:23.34300Z,1298413043.343 [Default:Iridium:Read Iridium] Stopped 2011-02-22T22:17:23.34350Z,1298413043.3435 [Default:Iridium](INFO): Completed Default:Iridium 2011-02-22T22:17:23.34360Z,1298413043.3436 [Default:Iridium] Stopped 2011-02-22T22:17:23.34380Z,1298413043.3438 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium 2011-02-22T22:17:23.34390Z,1298413043.3439 [Default:Iridium:0.SetSpeed] Stopped 2011-02-22T22:17:23.34400Z,1298413043.344 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize. 2011-02-22T22:17:23.34420Z,1298413043.3442 [Default:6.Wait] Running Loop=1 2011-02-22T22:17:23.34430Z,1298413043.3443 [Default:6.Wait](DEBUG): Initialize Wait Component. 2011-02-22T22:17:33.75200Z,1298413053.752 [NAL9601](INFO): Powering down 2011-02-22T22:20:18.75410Z,1298413218.7541 [Default:CallGPS] Running Loop=1 2011-02-22T22:20:18.75430Z,1298413218.7543 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS 2011-02-22T22:20:18.75450Z,1298413218.7545 [Default:CallGPS:0] Running Loop=1 2011-02-22T22:20:18.75460Z,1298413218.7546 [Default:CallGPS:0](INFO): Aggregate::initialize Default:CallGPS:0 2011-02-22T22:20:23.73180Z,1298413223.7318 [Default:GPS] Running Loop=1 2011-02-22T22:20:23.73200Z,1298413223.732 [Default:GPS](INFO): Aggregate::initialize Default:GPS 2011-02-22T22:20:23.73220Z,1298413223.7322 [Default:GPS:0.SetSpeed] Running Loop=1 2011-02-22T22:20:23.73230Z,1298413223.7323 [Default:GPS:0.SetSpeed](DEBUG): Initialize. 2011-02-22T22:20:23.73250Z,1298413223.7325 [Default:GPS:1.GoToSurface] Running Loop=1 2011-02-22T22:20:23.73260Z,1298413223.7326 [Default:GPS:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T22:20:23.73340Z,1298413223.7334 [Default:GPS:1.GoToSurface] Stopped 2011-02-22T22:20:23.73350Z,1298413223.7335 [Default:GPS:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T22:20:23.73370Z,1298413223.7337 [Default:GPS:Read GPS] Running Loop=1 2011-02-22T22:20:24.40390Z,1298413224.4039 [NAL9601](INFO): Powering up 2011-02-22T22:21:30.11540Z,1298413290.1154 [NAL9601](INFO): NAL9601 initialized 2011-02-22T22:21:37.20880Z,1298413297.2088 [NAL9601](IMPORTANT): GPS fix at: 1298413317 2011-02-22T22:21:37.22510Z,1298413297.2251 [Default:GPS:Read GPS] Stopped 2011-02-22T22:21:37.22570Z,1298413297.2257 [Default:GPS](INFO): Completed Default:GPS 2011-02-22T22:21:37.22580Z,1298413297.2258 [Default:GPS] Stopped 2011-02-22T22:21:37.22600Z,1298413297.226 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS 2011-02-22T22:21:37.22610Z,1298413297.2261 [Default:GPS:0.SetSpeed] Stopped 2011-02-22T22:21:37.22620Z,1298413297.2262 [Default:GPS:0.SetSpeed](DEBUG): Uninitialize. 2011-02-22T22:21:37.62500Z,1298413297.625 [Default:CallGPS:0](INFO): Completed Default:CallGPS:0 2011-02-22T22:21:37.62510Z,1298413297.6251 [Default:CallGPS:0] Stopped 2011-02-22T22:21:37.62530Z,1298413297.6253 [Default:CallGPS:0](INFO): Aggregate::uninitialize Default:CallGPS:0 2011-02-22T22:21:37.62550Z,1298413297.6255 [Default:CallGPS](INFO): Completed Default:CallGPS 2011-02-22T22:21:37.62560Z,1298413297.6256 [Default:CallGPS] Stopped 2011-02-22T22:21:37.62580Z,1298413297.6258 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS 2011-02-22T22:21:57.72450Z,1298413317.7245 [NAL9601](INFO): Powering down 2011-02-22T22:22:27.69900Z,1298413347.699 [Default:CallIridium] Running Loop=1 2011-02-22T22:22:27.69920Z,1298413347.6992 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium 2011-02-22T22:22:27.69950Z,1298413347.6995 [Default:CallIridium:0] Running Loop=1 2011-02-22T22:22:27.69960Z,1298413347.6996 [Default:CallIridium:0](INFO): Aggregate::initialize Default:CallIridium:0 2011-02-22T22:22:32.70800Z,1298413352.708 [Default:Iridium] Running Loop=1 2011-02-22T22:22:32.70820Z,1298413352.7082 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium 2011-02-22T22:22:32.70830Z,1298413352.7083 [Default:Iridium:0.SetSpeed] Running Loop=1 2011-02-22T22:22:32.70840Z,1298413352.7084 [Default:Iridium:0.SetSpeed](DEBUG): Initialize. 2011-02-22T22:22:32.70870Z,1298413352.7087 [Default:Iridium:1.GoToSurface] Running Loop=1 2011-02-22T22:22:32.70880Z,1298413352.7088 [Default:Iridium:1.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2011-02-22T22:22:32.70970Z,1298413352.7097 [Default:Iridium:1.GoToSurface] Stopped 2011-02-22T22:22:32.70980Z,1298413352.7098 [Default:Iridium:1.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T22:22:32.71000Z,1298413352.71 [Default:Iridium:Read Iridium] Running Loop=1 2011-02-22T22:22:33.42970Z,1298413353.4297 [NAL9601](INFO): Powering up 2011-02-22T22:23:39.03940Z,1298413419.0394 [NAL9601](INFO): NAL9601 initialized 2011-02-22T22:23:58.11820Z,1298413438.1182 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=12749, MT Status=1, MTMSN=1580 2011-02-22T22:23:58.29930Z,1298413438.2993 [NAL9601](INFO): Sent 178 bytes from file Logs/20110222T210900/shore0008.lzma 2011-02-22T22:23:58.29960Z,1298413438.2996 [NAL9601](INFO): Packets left to send: 0 2011-02-22T22:23:58.30070Z,1298413438.3007 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000012 2011-02-22T22:23:58.71320Z,1298413438.7132 [NAL9601](INFO): Received command:restart 2011-02-22T22:23:58.71440Z,1298413438.7144 [CommandLine](IMPORTANT): got command restart 2011-02-22T22:23:58.76280Z,1298413438.7628 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2011-02-22T22:23:58.84540Z,1298413438.8454 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator. 2011-02-22T22:23:58.97590Z,1298413438.9759 [controlThread](DEBUG): Uninitializing ControlThread 2011-02-22T22:23:59.04700Z,1298413439.047 [AHRS_3DMGX3](INFO): Powering down 2011-02-22T22:23:59.04840Z,1298413439.0484 [DVL_micro](INFO): Powering down 2011-02-22T22:23:59.04890Z,1298413439.0489 [NAL9601](INFO): Powering down 2011-02-22T22:23:59.04980Z,1298413439.0498 [CTD_NeilBrown](INFO): Powering down 2011-02-22T22:23:59.05020Z,1298413439.0502 [WetLabsBB2FL](INFO): Powering down 2011-02-22T22:23:59.05080Z,1298413439.0508 [Aanderaa_O2](INFO): Powering down 2011-02-22T22:23:59.05180Z,1298413439.0518 [Bathymetry](DEBUG): Uninitialize Bathymetry Derivation. 2011-02-22T22:23:59.05370Z,1298413439.0537 [Default] Stopped 2011-02-22T22:23:59.05390Z,1298413439.0539 [Default](INFO): Aggregate::uninitialize Default 2011-02-22T22:23:59.05410Z,1298413439.0541 [Default:Iridium] Stopped 2011-02-22T22:23:59.05420Z,1298413439.0542 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium 2011-02-22T22:23:59.05430Z,1298413439.0543 [Default:Iridium:0.SetSpeed] Stopped 2011-02-22T22:23:59.05440Z,1298413439.0544 [Default:Iridium:0.SetSpeed](DEBUG): Uninitialize. 2011-02-22T22:23:59.05450Z,1298413439.0545 [Default:Iridium:Read Iridium] Stopped 2011-02-22T22:23:59.05460Z,1298413439.0546 [Default:CallIridium] Stopped 2011-02-22T22:23:59.05490Z,1298413439.0549 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium 2011-02-22T22:23:59.05500Z,1298413439.055 [Default:CallIridium:0] Stopped 2011-02-22T22:23:59.05520Z,1298413439.0552 [Default:CallIridium:0](INFO): Aggregate::uninitialize Default:CallIridium:0 2011-02-22T22:23:59.05530Z,1298413439.0553 [Default:4.SetSpeed] Stopped 2011-02-22T22:23:59.05540Z,1298413439.0554 [Default:4.SetSpeed](DEBUG): Uninitialize. 2011-02-22T22:23:59.05550Z,1298413439.0555 [Default:5.GoToSurface] Stopped 2011-02-22T22:23:59.05560Z,1298413439.0556 [Default:5.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2011-02-22T22:23:59.05560Z,1298413439.0556 [Default:6.Wait] Stopped 2011-02-22T22:23:59.05570Z,1298413439.0557 [Default:6.Wait](DEBUG): Uninitialize Wait Component. 2011-02-22T22:23:59.06150Z,1298413439.0615 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2011-02-22T22:23:59.06180Z,1298413439.0618 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2011-02-22T22:23:59.06220Z,1298413439.0622 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2011-02-22T22:23:59.06250Z,1298413439.0625 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2011-02-22T22:23:59.06310Z,1298413439.0631 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2011-02-22T22:23:59.06340Z,1298413439.0634 [BuoyancyServo](INFO): Powering down 2011-02-22T22:23:59.06400Z,1298413439.064 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2011-02-22T22:23:59.06420Z,1298413439.0642 [ElevatorServo](INFO): Powering down 2011-02-22T22:23:59.06460Z,1298413439.0646 [MassServo](DEBUG): Uninitialize Mass Servo. 2011-02-22T22:23:59.06470Z,1298413439.0647 [MassServo](INFO): Powering down 2011-02-22T22:23:59.06510Z,1298413439.0651 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2011-02-22T22:23:59.06520Z,1298413439.0652 [RudderServo](INFO): Powering down 2011-02-22T22:23:59.06560Z,1298413439.0656 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2011-02-22T22:23:59.06570Z,1298413439.0657 [ThrusterServo](INFO): Powering down 2011-02-22T22:23:59.06610Z,1298413439.0661 [SBIT](DEBUG): Uninitialize SBIT Component. 2011-02-22T22:23:59.06640Z,1298413439.0664 [IBIT](DEBUG): Uninitialize IBIT Component. 2011-02-22T22:23:59.06690Z,1298413439.0669 [CBIT](DEBUG): Uninitialize CBIT Component.