2012-01-09T20:13:40.02800Z,1326140020.028 [Supervisor](DEBUG): Initializing supervisor.
2012-01-09T20:13:40.03060Z,1326140020.0306 [SyncHandler](DEBUG): Created PCaller Thread at 1077138656
2012-01-09T20:13:40.03130Z,1326140020.0313 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-01-09T20:13:40.03230Z,1326140020.0323 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 1077335264
2012-01-09T20:13:40.03330Z,1326140020.0333 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-01-09T20:13:40.04380Z,1326140020.0438 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-01-09T20:13:40.04490Z,1326140020.0449 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 1077531872
2012-01-09T20:13:40.04580Z,1326140020.0458 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2012-01-09T20:13:40.04620Z,1326140020.0462 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-01-09T20:13:40.04740Z,1326140020.0474 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-01-09T20:13:40.31730Z,1326140020.3173 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-01-09T20:13:40.31780Z,1326140020.3178 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-01-09T20:13:40.49170Z,1326140020.4917 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-01-09T20:13:40.49220Z,1326140020.4922 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-01-09T20:13:40.57640Z,1326140020.5764 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-01-09T20:13:40.57690Z,1326140020.5769 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-01-09T20:13:40.76480Z,1326140020.7648 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-01-09T20:13:40.76540Z,1326140020.7654 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-01-09T20:13:40.89330Z,1326140020.8933 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-01-09T20:13:40.89380Z,1326140020.8938 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-01-09T20:13:41.11440Z,1326140021.1144 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-01-09T20:13:41.11500Z,1326140021.115 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-01-09T20:13:41.25700Z,1326140021.257 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-01-09T20:13:41.25760Z,1326140021.2576 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-01-09T20:13:41.50690Z,1326140021.5069 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-01-09T20:13:41.50740Z,1326140021.5074 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-01-09T20:13:41.60570Z,1326140021.6057 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-01-09T20:13:41.60620Z,1326140021.6062 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-01-09T20:13:41.98100Z,1326140021.981 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-01-09T20:13:41.98170Z,1326140021.9817 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-01-09T20:13:42.08990Z,1326140022.0899 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-01-09T20:13:42.09060Z,1326140022.0906 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-01-09T20:13:42.17600Z,1326140022.176 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-tethys/
2012-01-09T20:13:42.17690Z,1326140022.1769 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/vehicle.cfg
2012-01-09T20:13:42.28060Z,1326140022.2806 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Sensor.cfg
2012-01-09T20:13:42.40150Z,1326140022.4015 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/BIT.cfg
2012-01-09T20:13:42.49860Z,1326140022.4986 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Servo.cfg
2012-01-09T20:13:42.59410Z,1326140022.5941 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Science.cfg
2012-01-09T20:13:42.68540Z,1326140022.6854 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/workSite.cfg
2012-01-09T20:13:42.77270Z,1326140022.7727 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Simulator.cfg
2012-01-09T20:13:42.85960Z,1326140022.8596 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Derivation.cfg
2012-01-09T20:13:42.97090Z,1326140022.9709 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-01-09T20:13:43.05550Z,1326140023.0555 [InternalSim] Loaded
2012-01-09T20:13:43.05580Z,1326140023.0558 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-01-09T20:13:43.05670Z,1326140023.0567 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-01-09T20:13:43.05720Z,1326140023.0572 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-01-09T20:13:43.07100Z,1326140023.071 [SBIT](DEBUG): Construct Startup Built In Test.
2012-01-09T20:13:43.10250Z,1326140023.1025 [SBIT] Loaded
2012-01-09T20:13:43.10270Z,1326140023.1027 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-01-09T20:13:43.10370Z,1326140023.1037 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-01-09T20:13:43.12720Z,1326140023.1272 [IBIT] Loaded
2012-01-09T20:13:43.12740Z,1326140023.1274 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-01-09T20:13:43.13480Z,1326140023.1348 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-01-09T20:13:43.24440Z,1326140023.2444 [CBIT] Loaded
2012-01-09T20:13:43.24470Z,1326140023.2447 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-01-09T20:13:43.24540Z,1326140023.2454 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-01-09T20:13:43.24600Z,1326140023.246 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-01-09T20:13:43.33990Z,1326140023.3399 [BuoyancyServo] Loaded
2012-01-09T20:13:43.34010Z,1326140023.3401 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-01-09T20:13:43.34910Z,1326140023.3491 [ElevatorServo] Loaded
2012-01-09T20:13:43.34940Z,1326140023.3494 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2012-01-09T20:13:43.35830Z,1326140023.3583 [MassServo] Loaded
2012-01-09T20:13:43.35860Z,1326140023.3586 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2012-01-09T20:13:43.36550Z,1326140023.3655 [RudderServo] Loaded
2012-01-09T20:13:43.36580Z,1326140023.3658 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-01-09T20:13:43.37620Z,1326140023.3762 [ThrusterServo] Loaded
2012-01-09T20:13:43.37650Z,1326140023.3765 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-01-09T20:13:43.37700Z,1326140023.377 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-01-09T20:13:43.37760Z,1326140023.3776 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-01-09T20:13:43.39210Z,1326140023.3921 [DepthRateCalculator] Loaded
2012-01-09T20:13:43.39240Z,1326140023.3924 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-01-09T20:13:43.40800Z,1326140023.408 [NavChart] Loaded
2012-01-09T20:13:43.40830Z,1326140023.4083 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-01-09T20:13:43.41400Z,1326140023.414 [PitchRateCalculator] Loaded
2012-01-09T20:13:43.41440Z,1326140023.4144 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-01-09T20:13:43.42010Z,1326140023.4201 [SpeedCalculator] Loaded
2012-01-09T20:13:43.42040Z,1326140023.4204 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-01-09T20:13:43.43500Z,1326140023.435 [TempGradientCalculator] Loaded
2012-01-09T20:13:43.43530Z,1326140023.4353 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-01-09T20:13:43.44100Z,1326140023.441 [YawRateCalculator] Loaded
2012-01-09T20:13:43.44130Z,1326140023.4413 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-01-09T20:13:43.47130Z,1326140023.4713 [Navigation] Loaded
2012-01-09T20:13:43.47160Z,1326140023.4716 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-01-09T20:13:43.47200Z,1326140023.472 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-01-09T20:13:43.47260Z,1326140023.4726 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-01-09T20:13:43.52570Z,1326140023.5257 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-01-09T20:13:43.52650Z,1326140023.5265 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-01-09T20:13:43.53590Z,1326140023.5359 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-01-09T20:13:43.53650Z,1326140023.5365 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-01-09T20:13:43.54900Z,1326140023.549 [VerticalControl](DEBUG): Construct VerticalControl.
2012-01-09T20:13:43.75730Z,1326140023.7573 [VerticalControl] Loaded
2012-01-09T20:13:43.75760Z,1326140023.7576 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-01-09T20:13:43.75870Z,1326140023.7587 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-01-09T20:13:43.81320Z,1326140023.8132 [HorizontalControl] Loaded
2012-01-09T20:13:43.81350Z,1326140023.8135 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-01-09T20:13:43.81470Z,1326140023.8147 [SpeedControl](DEBUG): Construct SpeedControl.
2012-01-09T20:13:43.81650Z,1326140023.8165 [SpeedControl] Loaded
2012-01-09T20:13:43.81680Z,1326140023.8168 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-01-09T20:13:43.81770Z,1326140023.8177 [LoopControl](DEBUG): Construct LoopControl.
2012-01-09T20:13:43.81850Z,1326140023.8185 [LoopControl] Loaded
2012-01-09T20:13:43.81880Z,1326140023.8188 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-01-09T20:13:43.81930Z,1326140023.8193 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-01-09T20:13:43.81980Z,1326140023.8198 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-01-09T20:13:43.82500Z,1326140023.825 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-01-09T20:13:43.83000Z,1326140023.83 [AsyncPiEstimator] Loaded
2012-01-09T20:13:43.83030Z,1326140023.8303 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-01-09T20:13:43.83150Z,1326140023.8315 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 1078928608
2012-01-09T20:13:43.83220Z,1326140023.8322 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-01-09T20:13:43.83280Z,1326140023.8328 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-01-09T20:13:43.92050Z,1326140023.9205 [AHRS_sp3003D] Loaded
2012-01-09T20:13:43.92080Z,1326140023.9208 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-01-09T20:13:43.96140Z,1326140023.9614 [AHRS_3DMGX3] Loaded
2012-01-09T20:13:43.96170Z,1326140023.9617 [ComponentRegistry](DEBUG): SyncComponent "AHRS_3DMGX3" handled in the control thread.
2012-01-09T20:13:44.22140Z,1326140024.2214 [Batt_Ocean_Server] Loaded
2012-01-09T20:13:44.22170Z,1326140024.2217 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2012-01-09T20:13:44.23410Z,1326140024.2341 [Depth_Keller] Loaded
2012-01-09T20:13:44.23440Z,1326140024.2344 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2012-01-09T20:13:44.24000Z,1326140024.24 [DropWeight] Loaded
2012-01-09T20:13:44.24020Z,1326140024.2402 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2012-01-09T20:13:44.33480Z,1326140024.3348 [DVL_micro] Loaded
2012-01-09T20:13:44.33510Z,1326140024.3351 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2012-01-09T20:13:44.42100Z,1326140024.421 [NAL9601] Loaded
2012-01-09T20:13:44.42130Z,1326140024.4213 [ComponentRegistry](DEBUG): SyncComponent "NAL9601" handled in the control thread.
2012-01-09T20:13:44.47130Z,1326140024.4713 [Onboard] Loaded
2012-01-09T20:13:44.47170Z,1326140024.4717 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-01-09T20:13:44.47790Z,1326140024.4779 [Radio_Freewave] Loaded
2012-01-09T20:13:44.47820Z,1326140024.4782 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2012-01-09T20:13:44.49950Z,1326140024.4995 [DAT] Loaded
2012-01-09T20:13:44.49980Z,1326140024.4998 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2012-01-09T20:13:44.50030Z,1326140024.5003 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-01-09T20:13:44.50090Z,1326140024.5009 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-01-09T20:13:44.54390Z,1326140024.5439 [CTD_NeilBrown] Loaded
2012-01-09T20:13:44.54420Z,1326140024.5442 [ComponentRegistry](DEBUG): SyncComponent "CTD_NeilBrown" handled in the control thread.
2012-01-09T20:13:44.57510Z,1326140024.5751 [WetLabsBB2FL] Loaded
2012-01-09T20:13:44.57540Z,1326140024.5754 [ComponentRegistry](DEBUG): SyncComponent "WetLabsBB2FL" handled in the control thread.
2012-01-09T20:13:44.57660Z,1326140024.5766 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-01-09T20:13:44.57890Z,1326140024.5789 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-01-09T20:13:44.57970Z,1326140024.5797 [ComponentRegistry](DEBUG): SyncComponent "Maintainer" handled in the control thread.
2012-01-09T20:13:44.58050Z,1326140024.5805 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-01-09T20:13:44.58590Z,1326140024.5859 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-01-09T20:13:44.58700Z,1326140024.587 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 1079497952
2012-01-09T20:13:44.58740Z,1326140024.5874 [Supervisor](DEBUG): Running supervisor.
2012-01-09T20:13:44.59060Z,1326140024.5906 [controlThread](DEBUG): Initializing ControlThread
2012-01-09T20:13:44.59150Z,1326140024.5915 [InternalSim](DEBUG):  InternalSim initializing...
2012-01-09T20:13:44.62710Z,1326140024.6271 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-01-09T20:13:44.63780Z,1326140024.6378 [SBIT](INFO): Initialize SBIT Component.
2012-01-09T20:13:44.63950Z,1326140024.6395 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 9470 $
2012-01-09T20:13:44.64010Z,1326140024.6401 [IBIT](INFO): Initialize IBIT Component.
2012-01-09T20:13:44.64360Z,1326140024.6436 [CBIT](DEBUG): Initialize CBIT Component.
2012-01-09T20:13:44.64390Z,1326140024.6439 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2012-01-09T20:13:44.67180Z,1326140024.6718 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-01-09T20:13:44.67220Z,1326140024.6722 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-01-09T20:13:44.67260Z,1326140024.6726 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-01-09T20:13:44.67290Z,1326140024.6729 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-01-09T20:13:44.67360Z,1326140024.6736 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-01-09T20:13:44.67500Z,1326140024.675 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-01-09T20:13:44.67540Z,1326140024.6754 [Navigation](DEBUG): Initializing Navigation.
2012-01-09T20:13:44.67580Z,1326140024.6758 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-01-09T20:13:44.70250Z,1326140024.7025 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-01-09T20:13:44.70560Z,1326140024.7056 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-01-09T20:13:44.70640Z,1326140024.7064 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-01-09T20:13:44.76050Z,1326140024.7605 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-01-09T20:13:44.76550Z,1326140024.7655 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2012-01-09T20:13:44.76980Z,1326140024.7698 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2012-01-09T20:13:44.77380Z,1326140024.7738 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2012-01-09T20:13:44.77780Z,1326140024.7778 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2012-01-09T20:13:44.77870Z,1326140024.7787 [NavChartDb](INFO): Creating index for Soundings
2012-01-09T20:13:44.78180Z,1326140024.7818 [NavChartDb](INFO): Creating index for Contour 0p0
2012-01-09T20:13:44.78390Z,1326140024.7839 [NavChartDb](INFO): Creating index for Contour 1p8
2012-01-09T20:13:44.78560Z,1326140024.7856 [NavChartDb](INFO): Creating index for Contour 3p6
2012-01-09T20:13:44.78780Z,1326140024.7878 [NavChartDb](INFO): Creating index for Contour 5p4
2012-01-09T20:13:44.78960Z,1326140024.7896 [NavChartDb](INFO): Creating index for Contour 9p1
2012-01-09T20:13:44.79160Z,1326140024.7916 [NavChartDb](INFO): Creating index for Contour 10p9
2012-01-09T20:13:44.79340Z,1326140024.7934 [NavChartDb](INFO): Creating index for Contour 18p2
2012-01-09T20:13:44.79540Z,1326140024.7954 [NavChartDb](INFO): Creating index for Contour 36p5
2012-01-09T20:13:44.79720Z,1326140024.7972 [NavChartDb](INFO): Creating index for Contour 54p8
2012-01-09T20:13:44.79910Z,1326140024.7991 [NavChartDb](INFO): Creating index for Contour 73p1
2012-01-09T20:13:44.80090Z,1326140024.8009 [NavChartDb](INFO): Creating index for Contour 91p4
2012-01-09T20:13:44.80280Z,1326140024.8028 [NavChartDb](INFO): Creating index for Contour 182p8
2012-01-09T20:13:44.80440Z,1326140024.8044 [NavChartDb](INFO): Creating index for Contour 365p7
2012-01-09T20:13:44.80610Z,1326140024.8061 [NavChartDb](INFO): Creating index for Contour 548p6
2012-01-09T20:13:44.80810Z,1326140024.8081 [NavChartDb](INFO): Creating index for Contour 731p5
2012-01-09T20:13:44.80990Z,1326140024.8099 [NavChartDb](INFO): Creating index for Contour 914p4
2012-01-09T20:13:44.81190Z,1326140024.8119 [NavChartDb](INFO): Creating index for Contour 1097p2
2012-01-09T20:13:44.81360Z,1326140024.8136 [NavChartDb](INFO): Creating index for Contour 1280p1
2012-01-09T20:13:44.81580Z,1326140024.8158 [NavChartDb](INFO): Creating index for Contour 1463p0
2012-01-09T20:13:44.81760Z,1326140024.8176 [NavChartDb](INFO): Creating index for Contour 1645p9
2012-01-09T20:13:44.81960Z,1326140024.8196 [NavChartDb](INFO): Creating index for Contour 1828p8
2012-01-09T20:13:44.82140Z,1326140024.8214 [NavChartDb](INFO): Creating index for Contour 2011p6
2012-01-09T20:13:44.82340Z,1326140024.8234 [NavChartDb](INFO): Creating index for Contour 2194p5
2012-01-09T20:13:44.82520Z,1326140024.8252 [NavChartDb](INFO): Creating index for Contour 2377p4
2012-01-09T20:13:44.82700Z,1326140024.827 [NavChartDb](INFO): Creating index for Contour 2560p3
2012-01-09T20:13:44.82870Z,1326140024.8287 [NavChartDb](INFO): Creating index for Contour 2743p2
2012-01-09T20:13:44.83050Z,1326140024.8305 [NavChartDb](INFO): Creating index for Contour 2926p0
2012-01-09T20:13:44.83230Z,1326140024.8323 [NavChartDb](INFO): Creating index for Contour 3108p9
2012-01-09T20:13:44.83410Z,1326140024.8341 [NavChartDb](INFO): Creating index for Contour 3291p8
2012-01-09T20:13:44.83600Z,1326140024.836 [NavChartDb](INFO): Creating index for Contour 3474p7
2012-01-09T20:13:44.83780Z,1326140024.8378 [NavChartDb](INFO): Creating index for Contour 3657p6
2012-01-09T20:13:46.65560Z,1326140026.6556 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2012-01-09T20:13:46.66030Z,1326140026.6603 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-01-09T20:13:46.67000Z,1326140026.67 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-01-09T20:13:46.68000Z,1326140026.68 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface RunIn="Progression"/>

    <Aggregate Id="StartupSatComms" >

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

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

    </Aggregate>

</Mission>


2012-01-09T20:13:46.68090Z,1326140026.6809 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-01-09T20:13:46.71020Z,1326140026.7102 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-01-09T20:13:46.71390Z,1326140026.7139 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-01-09T20:13:46.72020Z,1326140026.7202 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-01-09T20:13:46.72380Z,1326140026.7238 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-01-09T20:13:46.73030Z,1326140026.7303 [Default:Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-01-09T20:13:46.74350Z,1326140026.7435 [Default:E.SetSpeed](DEBUG): Construct.
2012-01-09T20:13:46.74710Z,1326140026.7471 [Default:F.GoToSurface](DEBUG): Construct GoToSurface.
2012-01-09T20:13:46.75180Z,1326140026.7518 [Default:G.Wait](DEBUG): Construct Wait.
2012-01-09T20:13:46.75600Z,1326140026.756 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Default">

    <Aggregate Id="GPS" >

<!--    Run at high speed -->

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

<!--    Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!--    Get GPS fix -->

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

    </Aggregate>

    <Aggregate Id="Iridium" >

<!--    Run at high speed -->

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

<!--    Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!--    Do data comms -->

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

    </Aggregate>

    <Aggregate Id="CallGPS" >

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

        <Call RefId="GPS"/>

    </Aggregate>

    <Aggregate Id="CallIridium" >

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

        <Call RefId="Iridium"/>

    </Aggregate>

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

<!-- Run at low speed -->

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

    <Guidance:GoToSurface RunIn="Parallel"/>

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

</Mission>


2012-01-09T20:13:46.76190Z,1326140026.7619 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,AHRS_3DMGX3,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9601,Onboard,Radio_Freewave,DAT,CTD_NeilBrown,WetLabsBB2FL,Depth_Keller,DepthRateCalculator,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintainer,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,logger,
2012-01-09T20:13:46.78110Z,1326140026.7811 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-01-09T20:13:46.78830Z,1326140026.7883 [AHRS_3DMGX3](DEBUG): Initializing AHRS_3DMGX3.
2012-01-09T20:13:46.89850Z,1326140026.8985 [DVL_micro](DEBUG): Initializing DVL_micro.
2012-01-09T20:13:46.92380Z,1326140026.9238 [DAT](INFO): Powering up
2012-01-09T20:13:46.92410Z,1326140026.9241 [DAT](DEBUG): Initializing DAT.
2012-01-09T20:13:46.92990Z,1326140026.9299 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-01-09T20:13:46.93860Z,1326140026.9386 [WetLabsBB2FL](INFO): Powering down
2012-01-09T20:13:47.01140Z,1326140027.0114 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-01-09T20:13:47.01240Z,1326140027.0124 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-01-09T20:13:47.02190Z,1326140027.0219 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-01-09T20:13:47.02310Z,1326140027.0231 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-01-09T20:13:47.03120Z,1326140027.0312 [MassServo](DEBUG): Initializing EZServoServo.
2012-01-09T20:13:47.03210Z,1326140027.0321 [MassServo](DEBUG): Initializing MassServo.
2012-01-09T20:13:47.04040Z,1326140027.0404 [RudderServo](DEBUG): Initializing EZServoServo.
2012-01-09T20:13:47.04130Z,1326140027.0413 [RudderServo](DEBUG): Initializing RudderServo.
2012-01-09T20:13:47.04940Z,1326140027.0494 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-01-09T20:13:47.05240Z,1326140027.0524 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-01-09T20:13:49.53610Z,1326140029.5361 [NAL9601](INFO): Powering up NAL9601
2012-01-09T20:13:49.89430Z,1326140029.8943 [CTD_NeilBrown](ERROR): Salinity reading out of range: -0.1419200003 psu
2012-01-09T20:14:00.32470Z,1326140040.3247 [SBIT](IMPORTANT): Beginning Startup BIT
2012-01-09T20:14:00.32710Z,1326140040.3271 [CBIT](IMPORTANT): Beginning GF scan
2012-01-09T20:14:01.86860Z,1326140041.8686 [DAT](INFO): Powering down
2012-01-09T20:14:26.53020Z,1326140066.5302 [CBIT](IMPORTANT): No ground fault detected
2012-01-09T20:14:42.41080Z,1326140082.4108 [SBIT](IMPORTANT): SBIT PASSED
2012-01-09T20:14:42.80660Z,1326140082.8066 [MissionManager](IMPORTANT): Started mission Startup
2012-01-09T20:14:42.80670Z,1326140082.8067 [Startup] Running Loop=1
2012-01-09T20:14:42.80680Z,1326140082.8068 [Startup](INFO): Aggregate::initialize Startup
2012-01-09T20:14:42.80690Z,1326140082.8069 [Startup:A.GoToSurface] Running Loop=1
2012-01-09T20:14:42.80700Z,1326140082.807 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T20:14:42.81270Z,1326140082.8127 [Startup:StartupSatComms] Running Loop=1
2012-01-09T20:14:42.81280Z,1326140082.8128 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2012-01-09T20:14:42.81300Z,1326140082.813 [Startup:StartupSatComms:A] Running Loop=1
2012-01-09T20:14:43.20700Z,1326140083.207 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-01-09T20:14:55.14690Z,1326140095.1469 [NAL9601](INFO): NAL9601 initialized
2012-01-09T20:15:43.04180Z,1326140143.0418 [Startup:StartupSatComms:A](INFO): Timed out from 2012-01-09T20:14:42.Z
2012-01-09T20:15:43.04200Z,1326140143.042 [Startup:StartupSatComms:A_Timeout] Running Loop=1
2012-01-09T20:15:43.04210Z,1326140143.0421 [Startup:StartupSatComms:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A_Timeout
2012-01-09T20:15:43.04260Z,1326140143.0426 [Startup:StartupSatComms:A_Timeout](INFO): Completed Startup:StartupSatComms:A_Timeout
2012-01-09T20:15:43.04270Z,1326140143.0427 [Startup:StartupSatComms:A] Stopped
2012-01-09T20:15:43.04280Z,1326140143.0428 [Startup:StartupSatComms:B] Running Loop=1
2012-01-09T20:15:43.41900Z,1326140143.419 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-01-09T20:15:58.09170Z,1326140158.0917 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=40807, MT Status=1, MTMSN=3390
2012-01-09T20:15:58.23890Z,1326140158.2389 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T182911/shore0012.lzma
2012-01-09T20:15:58.23920Z,1326140158.2392 [NAL9601](INFO): Packets left to send: 1
2012-01-09T20:15:58.24120Z,1326140158.2412 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000000
2012-01-09T20:15:58.65630Z,1326140158.6563 [NAL9601](INFO): Received command:run Maintenance/dat_on.xml
2012-01-09T20:15:58.73070Z,1326140158.7307 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/dat_on.xml
2012-01-09T20:15:58.73110Z,1326140158.7311 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/dat_on.xml
2012-01-09T20:15:58.74440Z,1326140158.7444 [MissionManager](INFO): DefineArg dat_on.MassDefault = 0.0015 n/a
2012-01-09T20:15:58.74620Z,1326140158.7462 [dat_on:A.Pitch](DEBUG): Construct.
2012-01-09T20:15:58.75610Z,1326140158.7561 [dat_on:TestDrive:B.Wait](DEBUG): Construct Wait.
2012-01-09T20:15:58.75860Z,1326140158.7586 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="dat_on">

    <DefineArg Name="MassDefault"><CustomUri Uri="Config/Control.massDefault"/></DefineArg>

    <Timeout Duration="P15M"/>

    <Guidance:Pitch RunIn="Parallel">
        <Setting><Guidance:Pitch.massPosition/><Arg Name="MassDefault"/></Setting>
    </Guidance:Pitch>

    <Aggregate Id="TestDrive">

        <ReadData>
            <Universal:homing_target_range/>
        </ReadData>

        <Guidance:Wait RunIn="Sequence">
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>2</Value></Setting>
        </Guidance:Wait>

    </Aggregate>

</Mission>


2012-01-09T20:15:58.75910Z,1326140158.7591 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/dat_on.xml
2012-01-09T20:16:14.70560Z,1326140174.7056 [NAL9601](INFO): SBD MO Status=1, MOMSN=40808, MT Status=0, MTMSN=0
2012-01-09T20:16:14.91090Z,1326140174.9109 [NAL9601](INFO): Sent 212 bytes from file Logs/20120109T182911/shore0012.lzma
2012-01-09T20:16:14.91110Z,1326140174.9111 [NAL9601](INFO): Packets left to send: 0
2012-01-09T20:16:14.91210Z,1326140174.9121 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000001
2012-01-09T20:16:29.17770Z,1326140189.1777 [NAL9601](INFO): SBD MO Status=1, MOMSN=40809, MT Status=0, MTMSN=0
2012-01-09T20:16:29.39480Z,1326140189.3948 [NAL9601](INFO): Sent 253 bytes from file Logs/20120109T182911/shore0013.lzma
2012-01-09T20:16:29.39510Z,1326140189.3951 [NAL9601](INFO): Packets left to send: 0
2012-01-09T20:16:29.39610Z,1326140189.3961 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000002
2012-01-09T20:16:43.25980Z,1326140203.2598 [Startup:StartupSatComms:B](INFO): Timed out from 2012-01-09T20:15:43.Z
2012-01-09T20:16:43.25990Z,1326140203.2599 [Startup:StartupSatComms:A_Timeout] Running Loop=1
2012-01-09T20:16:43.26000Z,1326140203.26 [Startup:StartupSatComms:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A_Timeout
2012-01-09T20:16:43.26020Z,1326140203.2602 [Startup:StartupSatComms:A_Timeout](INFO): Completed Startup:StartupSatComms:A_Timeout
2012-01-09T20:16:43.26030Z,1326140203.2603 [Startup:StartupSatComms:B] Stopped
2012-01-09T20:16:43.26050Z,1326140203.2605 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2012-01-09T20:16:43.26060Z,1326140203.2606 [Startup:StartupSatComms] Stopped
2012-01-09T20:16:43.26070Z,1326140203.2607 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2012-01-09T20:16:43.26120Z,1326140203.2612 [Startup](INFO): Completed Startup
2012-01-09T20:16:43.26130Z,1326140203.2613 [Startup] Stopped
2012-01-09T20:16:43.26140Z,1326140203.2614 [Startup](INFO): Aggregate::uninitialize Startup
2012-01-09T20:16:43.26150Z,1326140203.2615 [Startup:A.GoToSurface] Stopped
2012-01-09T20:16:43.26150Z,1326140203.2615 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T20:16:43.69760Z,1326140203.6976 [MissionManager](IMPORTANT): Started mission dat_on
2012-01-09T20:16:43.69770Z,1326140203.6977 [dat_on] Running Loop=1
2012-01-09T20:16:43.69780Z,1326140203.6978 [dat_on](INFO): Aggregate::initialize dat_on
2012-01-09T20:16:43.69790Z,1326140203.6979 [dat_on:A.Pitch] Running Loop=1
2012-01-09T20:16:43.69800Z,1326140203.698 [dat_on:A.Pitch](DEBUG): Initialize.
2012-01-09T20:16:43.69850Z,1326140203.6985 [dat_on:TestDrive] Running Loop=1
2012-01-09T20:16:43.69860Z,1326140203.6986 [dat_on:TestDrive](INFO): Aggregate::initialize dat_on:TestDrive
2012-01-09T20:16:43.69870Z,1326140203.6987 [dat_on:TestDrive:A] Running Loop=1
2012-01-09T20:16:43.69890Z,1326140203.6989 [dat_on:TestDrive:B.Wait] Running Loop=1
2012-01-09T20:16:43.69890Z,1326140203.6989 [dat_on:TestDrive:B.Wait](DEBUG): Initialize Wait Component.
2012-01-09T20:16:43.70380Z,1326140203.7038 [dat_on:TestDrive:A] Running Loop=1
2012-01-09T20:16:43.70440Z,1326140203.7044 [dat_on:TestDrive:A](DEBUG): Initialize ReadDataComponent to sense homing_target_range
2012-01-09T20:16:43.70570Z,1326140203.7057 [dat_on:A.Pitch] Running Loop=1
2012-01-09T20:16:44.05370Z,1326140204.0537 [DAT](INFO): Powering up
2012-01-09T20:16:44.46720Z,1326140204.4672 [NAL9601](INFO): SBD MO Status=1, MOMSN=40810, MT Status=0, MTMSN=0
2012-01-09T20:16:44.66690Z,1326140204.6669 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0000.lzma
2012-01-09T20:16:44.66720Z,1326140204.6672 [NAL9601](INFO): Packets left to send: 2
2012-01-09T20:16:44.66820Z,1326140204.6682 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000003
2012-01-09T20:17:06.92160Z,1326140226.9216 [NAL9601](INFO): SBD MO Status=1, MOMSN=40811, MT Status=0, MTMSN=0
2012-01-09T20:17:07.13090Z,1326140227.1309 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0000.lzma
2012-01-09T20:17:07.13110Z,1326140227.1311 [NAL9601](INFO): Packets left to send: 1
2012-01-09T20:17:07.13220Z,1326140227.1322 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000004
2012-01-09T20:17:11.46640Z,1326140231.4664 [DAT](ERROR): No response from remote modem
2012-01-09T20:17:14.60560Z,1326140234.6056 [NAL9601](INFO): SBD MO Status=1, MOMSN=40812, MT Status=0, MTMSN=0
2012-01-09T20:17:14.82280Z,1326140234.8228 [NAL9601](INFO): Sent 157 bytes from file Logs/20120109T201340/shore0000.lzma
2012-01-09T20:17:14.82310Z,1326140234.8231 [NAL9601](INFO): Packets left to send: 0
2012-01-09T20:17:14.82410Z,1326140234.8241 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000005
2012-01-09T20:17:23.87440Z,1326140243.8744 [DAT](ERROR): No response from remote modem
2012-01-09T20:17:24.32280Z,1326140244.3228 [NAL9601](INFO): SBD MO Status=0, MOMSN=40813, MT Status=0, MTMSN=0
2012-01-09T20:17:36.67440Z,1326140256.6744 [DAT](ERROR): No response from remote modem
2012-01-09T20:17:49.47840Z,1326140269.4784 [DAT](ERROR): No response from remote modem
2012-01-09T20:18:02.27440Z,1326140282.2744 [DAT](ERROR): No response from remote modem
2012-01-09T20:18:14.67840Z,1326140294.6784 [DAT](ERROR): No response from remote modem
2012-01-09T20:18:27.09440Z,1326140307.0944 [DAT](ERROR): No response from remote modem
2012-01-09T20:18:39.87040Z,1326140319.8704 [DAT](ERROR): No response from remote modem
2012-01-09T20:18:43.81950Z,1326140323.8195 [dat_on:TestDrive:B.Wait](INFO): Done Waiting.
2012-01-09T20:18:43.81970Z,1326140323.8197 [dat_on:TestDrive:B.Wait] Stopped
2012-01-09T20:18:43.81980Z,1326140323.8198 [dat_on:TestDrive:B.Wait](DEBUG): Uninitialize Wait Component.
2012-01-09T20:18:43.82020Z,1326140323.8202 [dat_on:TestDrive](INFO): Completed dat_on:TestDrive
2012-01-09T20:18:43.82030Z,1326140323.8203 [dat_on:TestDrive] Stopped
2012-01-09T20:18:43.82040Z,1326140323.8204 [dat_on:TestDrive](INFO): Aggregate::uninitialize dat_on:TestDrive
2012-01-09T20:18:43.82050Z,1326140323.8205 [dat_on:TestDrive:A] Stopped
2012-01-09T20:18:43.82090Z,1326140323.8209 [dat_on](INFO): Completed dat_on
2012-01-09T20:18:43.82100Z,1326140323.821 [dat_on] Stopped
2012-01-09T20:18:43.82110Z,1326140323.8211 [dat_on](INFO): Aggregate::uninitialize dat_on
2012-01-09T20:18:43.82120Z,1326140323.8212 [dat_on:A.Pitch] Stopped
2012-01-09T20:18:44.23750Z,1326140324.2375 [MissionManager](IMPORTANT): Started mission Default
2012-01-09T20:18:44.23760Z,1326140324.2376 [Default] Running Loop=1
2012-01-09T20:18:44.23770Z,1326140324.2377 [Default](INFO): Aggregate::initialize Default
2012-01-09T20:18:44.23780Z,1326140324.2378 [Default:E.SetSpeed] Running Loop=1
2012-01-09T20:18:44.23790Z,1326140324.2379 [Default:E.SetSpeed](DEBUG): Initialize.
2012-01-09T20:18:44.23800Z,1326140324.238 [Default:F.GoToSurface] Running Loop=1
2012-01-09T20:18:44.23810Z,1326140324.2381 [Default:F.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T20:18:44.23860Z,1326140324.2386 [Default:GPS] Running Loop=1
2012-01-09T20:18:44.23880Z,1326140324.2388 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-09T20:18:44.23890Z,1326140324.2389 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-09T20:18:44.23890Z,1326140324.2389 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-09T20:18:44.23910Z,1326140324.2391 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-09T20:18:44.23920Z,1326140324.2392 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T20:18:44.23990Z,1326140324.2399 [Default:F.GoToSurface] Running Loop=1
2012-01-09T20:18:44.24470Z,1326140324.2447 [Default:E.SetSpeed] Running Loop=1
2012-01-09T20:18:44.25000Z,1326140324.25 [Default:CallIridium] Running Loop=1
2012-01-09T20:18:44.25020Z,1326140324.2502 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-09T20:18:44.25040Z,1326140324.2504 [Default:CallIridium:A] Running Loop=1
2012-01-09T20:18:44.25060Z,1326140324.2506 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-09T20:18:44.25070Z,1326140324.2507 [Default:CallGPS] Running Loop=1
2012-01-09T20:18:44.25090Z,1326140324.2509 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-09T20:18:44.25110Z,1326140324.2511 [Default:CallGPS:A] Running Loop=1
2012-01-09T20:18:44.25120Z,1326140324.2512 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-09T20:18:44.25600Z,1326140324.256 [Default:GPS:B.GoToSurface] Stopped
2012-01-09T20:18:44.25610Z,1326140324.2561 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T20:18:44.25620Z,1326140324.2562 [Default:GPS:Read_GPS] Running Loop=1
2012-01-09T20:18:44.25630Z,1326140324.2563 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-09T20:18:44.60880Z,1326140324.6088 [DAT](INFO): Powering down
2012-01-09T20:18:44.61570Z,1326140324.6157 [Default:Iridium] Running Loop=1
2012-01-09T20:18:44.61580Z,1326140324.6158 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-09T20:18:44.61590Z,1326140324.6159 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-09T20:18:44.61600Z,1326140324.616 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-09T20:18:44.61620Z,1326140324.6162 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-09T20:18:44.61630Z,1326140324.6163 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T20:18:44.62140Z,1326140324.6214 [Default:Iridium:B.GoToSurface] Stopped
2012-01-09T20:18:44.62140Z,1326140324.6214 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T20:18:44.62160Z,1326140324.6216 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-09T20:18:44.62160Z,1326140324.6216 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-09T20:18:44.62690Z,1326140324.6269 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-01-09T20:18:45.02090Z,1326140325.0209 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-01-09T20:19:06.96180Z,1326140346.9618 [NAL9601](INFO): SBD MO Status=1, MOMSN=40814, MT Status=0, MTMSN=0
2012-01-09T20:19:07.14690Z,1326140347.1469 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0001.lzma
2012-01-09T20:19:07.14710Z,1326140347.1471 [NAL9601](INFO): Packets left to send: 1
2012-01-09T20:19:07.14820Z,1326140347.1482 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000006
2012-01-09T20:19:14.23350Z,1326140354.2335 [NAL9601](INFO): SBD MO Status=1, MOMSN=40815, MT Status=0, MTMSN=0
2012-01-09T20:19:14.43490Z,1326140354.4349 [NAL9601](INFO): Sent 160 bytes from file Logs/20120109T201340/shore0001.lzma
2012-01-09T20:19:14.43510Z,1326140354.4351 [NAL9601](INFO): Packets left to send: 0
2012-01-09T20:19:14.43610Z,1326140354.4361 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000007
2012-01-09T20:19:22.29410Z,1326140362.2941 [NAL9601](INFO): SBD MO Status=0, MOMSN=40816, MT Status=0, MTMSN=0
2012-01-09T20:19:22.43460Z,1326140362.4346 [Default:Iridium:Read_Iridium] Stopped
2012-01-09T20:19:22.43500Z,1326140362.435 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-09T20:19:22.43510Z,1326140362.4351 [Default:Iridium] Stopped
2012-01-09T20:19:22.43520Z,1326140362.4352 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-09T20:19:22.43530Z,1326140362.4353 [Default:Iridium:A.SetSpeed] Stopped
2012-01-09T20:19:22.43540Z,1326140362.4354 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T20:19:22.64160Z,1326140362.6416 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-09T20:19:22.64170Z,1326140362.6417 [Default:CallIridium:A] Stopped
2012-01-09T20:19:22.64180Z,1326140362.6418 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-09T20:19:22.64200Z,1326140362.642 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-09T20:19:22.64210Z,1326140362.6421 [Default:CallIridium] Stopped
2012-01-09T20:19:22.64220Z,1326140362.6422 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-09T20:24:22.64740Z,1326140662.6474 [Default:CallIridium] Running Loop=1
2012-01-09T20:24:22.64760Z,1326140662.6476 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-09T20:24:22.64770Z,1326140662.6477 [Default:CallIridium:A] Running Loop=1
2012-01-09T20:24:22.64790Z,1326140662.6479 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-09T20:24:23.04440Z,1326140663.0444 [Default:Iridium] Running Loop=1
2012-01-09T20:24:23.04460Z,1326140663.0446 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-09T20:24:23.04470Z,1326140663.0447 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-09T20:24:23.04480Z,1326140663.0448 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-09T20:24:23.04490Z,1326140663.0449 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-09T20:24:23.04500Z,1326140663.045 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T20:24:23.04560Z,1326140663.0456 [Default:Iridium:B.GoToSurface] Stopped
2012-01-09T20:24:23.04570Z,1326140663.0457 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T20:24:23.04580Z,1326140663.0458 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-09T20:24:42.07770Z,1326140682.0777 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=40817, MT Status=1, MTMSN=3391
2012-01-09T20:24:42.22680Z,1326140682.2268 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0002.lzma
2012-01-09T20:24:42.22710Z,1326140682.2271 [NAL9601](INFO): Packets left to send: 3
2012-01-09T20:24:42.22820Z,1326140682.2282 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000008
2012-01-09T20:24:42.64400Z,1326140682.644 [NAL9601](INFO): Received command:run Maintenance/dat_on.xml
2012-01-09T20:24:42.66680Z,1326140682.6668 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/dat_on.xml
2012-01-09T20:24:42.66750Z,1326140682.6675 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/dat_on.xml
2012-01-09T20:24:42.67990Z,1326140682.6799 [MissionManager](INFO): DefineArg dat_on.MassDefault = 0.0015 n/a
2012-01-09T20:24:42.68130Z,1326140682.6813 [dat_on:A.Pitch](DEBUG): Construct.
2012-01-09T20:24:42.68870Z,1326140682.6887 [dat_on:TestDrive:B.Wait](DEBUG): Construct Wait.
2012-01-09T20:24:42.70740Z,1326140682.7074 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="dat_on">

    <DefineArg Name="MassDefault"><CustomUri Uri="Config/Control.massDefault"/></DefineArg>

    <Timeout Duration="P15M"/>

    <Guidance:Pitch RunIn="Parallel">
        <Setting><Guidance:Pitch.massPosition/><Arg Name="MassDefault"/></Setting>
    </Guidance:Pitch>

    <Aggregate Id="TestDrive">

        <ReadData>
            <Universal:homing_target_range/>
        </ReadData>

        <Guidance:Wait RunIn="Sequence">
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>2</Value></Setting>
        </Guidance:Wait>

    </Aggregate>

</Mission>


2012-01-09T20:24:42.70780Z,1326140682.7078 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/dat_on.xml
2012-01-09T20:24:42.88740Z,1326140682.8874 [Default] Stopped
2012-01-09T20:24:42.88750Z,1326140682.8875 [Default](INFO): Aggregate::uninitialize Default
2012-01-09T20:24:42.88760Z,1326140682.8876 [Default:GPS] Stopped
2012-01-09T20:24:42.88780Z,1326140682.8878 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-09T20:24:42.88780Z,1326140682.8878 [Default:GPS:A.SetSpeed] Stopped
2012-01-09T20:24:42.88790Z,1326140682.8879 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T20:24:42.88800Z,1326140682.888 [Default:GPS:Read_GPS] Stopped
2012-01-09T20:24:42.88800Z,1326140682.888 [Default:Iridium] Stopped
2012-01-09T20:24:42.88820Z,1326140682.8882 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-09T20:24:42.88820Z,1326140682.8882 [Default:Iridium:A.SetSpeed] Stopped
2012-01-09T20:24:42.88830Z,1326140682.8883 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T20:24:42.88840Z,1326140682.8884 [Default:Iridium:Read_Iridium] Stopped
2012-01-09T20:24:42.88840Z,1326140682.8884 [Default:CallGPS] Stopped
2012-01-09T20:24:42.88860Z,1326140682.8886 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-09T20:24:42.88860Z,1326140682.8886 [Default:CallGPS:A] Stopped
2012-01-09T20:24:42.88880Z,1326140682.8888 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-09T20:24:42.88890Z,1326140682.8889 [Default:CallIridium] Stopped
2012-01-09T20:24:42.88900Z,1326140682.889 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-09T20:24:42.88910Z,1326140682.8891 [Default:CallIridium:A] Stopped
2012-01-09T20:24:42.88920Z,1326140682.8892 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-09T20:24:42.88930Z,1326140682.8893 [Default:E.SetSpeed] Stopped
2012-01-09T20:24:42.88930Z,1326140682.8893 [Default:E.SetSpeed](DEBUG): Uninitialize.
2012-01-09T20:24:42.88940Z,1326140682.8894 [Default:F.GoToSurface] Stopped
2012-01-09T20:24:42.88950Z,1326140682.8895 [Default:F.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T20:24:42.88960Z,1326140682.8896 [MissionManager](IMPORTANT): Started mission dat_on
2012-01-09T20:24:42.88970Z,1326140682.8897 [dat_on] Running Loop=1
2012-01-09T20:24:42.88990Z,1326140682.8899 [dat_on](INFO): Aggregate::initialize dat_on
2012-01-09T20:24:42.88990Z,1326140682.8899 [dat_on:A.Pitch] Running Loop=1
2012-01-09T20:24:42.89000Z,1326140682.89 [dat_on:A.Pitch](DEBUG): Initialize.
2012-01-09T20:24:42.89020Z,1326140682.8902 [dat_on:TestDrive] Running Loop=1
2012-01-09T20:24:42.89040Z,1326140682.8904 [dat_on:TestDrive](INFO): Aggregate::initialize dat_on:TestDrive
2012-01-09T20:24:42.89050Z,1326140682.8905 [dat_on:TestDrive:A] Running Loop=1
2012-01-09T20:24:42.89070Z,1326140682.8907 [dat_on:TestDrive:B.Wait] Running Loop=1
2012-01-09T20:24:42.89070Z,1326140682.8907 [dat_on:TestDrive:B.Wait](DEBUG): Initialize Wait Component.
2012-01-09T20:24:42.89170Z,1326140682.8917 [dat_on:TestDrive:A] Running Loop=1
2012-01-09T20:24:42.89220Z,1326140682.8922 [dat_on:TestDrive:A](DEBUG): Initialize ReadDataComponent to sense homing_target_range
2012-01-09T20:24:42.89300Z,1326140682.893 [dat_on:A.Pitch] Running Loop=1
2012-01-09T20:24:43.28250Z,1326140683.2825 [DAT](INFO): Powering up
2012-01-09T20:24:57.31660Z,1326140697.3166 [NAL9601](FAULT): GPS failed to acquire within timeout.
2012-01-09T20:24:57.31670Z,1326140697.3167 [NAL9601] Data Fault, FailCount= 1
2012-01-09T20:24:57.31680Z,1326140697.3168 [NAL9601](ERROR): Data Fault
2012-01-09T20:24:57.33490Z,1326140697.3349 [CBIT](ERROR): Data Fault in component: NAL9601
2012-01-09T20:24:57.67150Z,1326140697.6715 [NAL9601](INFO): Powering down
2012-01-09T20:24:57.68970Z,1326140697.6897 [CBIT](INFO): Clearing failed state for component NAL9601
2012-01-09T20:24:57.68980Z,1326140697.6898 [NAL9601] No Fault, FailCount= 1
2012-01-09T20:25:02.87760Z,1326140702.8776 [NAL9601](INFO): Powering up NAL9601
2012-01-09T20:25:10.98240Z,1326140710.9824 [DAT](ERROR): No response from remote modem
2012-01-09T20:25:23.73840Z,1326140723.7384 [DAT](ERROR): No response from remote modem
2012-01-09T20:25:36.56240Z,1326140736.5624 [DAT](ERROR): No response from remote modem
2012-01-09T20:25:48.94240Z,1326140748.9424 [DAT](ERROR): No response from remote modem
2012-01-09T20:26:01.73840Z,1326140761.7384 [DAT](ERROR): No response from remote modem
2012-01-09T20:26:08.58690Z,1326140768.5869 [NAL9601](INFO): NAL9601 initialized
2012-01-09T20:26:09.71740Z,1326140769.7174 [NAL9601](IMPORTANT): GPS fix at: 1326140781
2012-01-09T20:26:14.17050Z,1326140774.1705 [DAT](ERROR): No response from remote modem
2012-01-09T20:26:16.08010Z,1326140776.0801 [NAL9601](INFO): Powering down
2012-01-09T20:26:26.94640Z,1326140786.9464 [DAT](ERROR): No response from remote modem
2012-01-09T20:26:39.74640Z,1326140799.7464 [DAT](ERROR): No response from remote modem
2012-01-09T20:26:42.94640Z,1326140802.9464 [dat_on:TestDrive:B.Wait](INFO): Done Waiting.
2012-01-09T20:26:42.94660Z,1326140802.9466 [dat_on:TestDrive:B.Wait] Stopped
2012-01-09T20:26:42.94670Z,1326140802.9467 [dat_on:TestDrive:B.Wait](DEBUG): Uninitialize Wait Component.
2012-01-09T20:26:42.94710Z,1326140802.9471 [dat_on:TestDrive](INFO): Completed dat_on:TestDrive
2012-01-09T20:26:42.94720Z,1326140802.9472 [dat_on:TestDrive] Stopped
2012-01-09T20:26:42.94730Z,1326140802.9473 [dat_on:TestDrive](INFO): Aggregate::uninitialize dat_on:TestDrive
2012-01-09T20:26:42.94740Z,1326140802.9474 [dat_on:TestDrive:A] Stopped
2012-01-09T20:26:42.94780Z,1326140802.9478 [dat_on](INFO): Completed dat_on
2012-01-09T20:26:42.94790Z,1326140802.9479 [dat_on] Stopped
2012-01-09T20:26:42.94800Z,1326140802.948 [dat_on](INFO): Aggregate::uninitialize dat_on
2012-01-09T20:26:42.94810Z,1326140802.9481 [dat_on:A.Pitch] Stopped
2012-01-09T20:26:43.31980Z,1326140803.3198 [MissionManager](IMPORTANT): Started mission Default
2012-01-09T20:26:43.31990Z,1326140803.3199 [Default] Running Loop=1
2012-01-09T20:26:43.32000Z,1326140803.32 [Default](INFO): Aggregate::initialize Default
2012-01-09T20:26:43.32010Z,1326140803.3201 [Default:E.SetSpeed] Running Loop=1
2012-01-09T20:26:43.32020Z,1326140803.3202 [Default:E.SetSpeed](DEBUG): Initialize.
2012-01-09T20:26:43.32030Z,1326140803.3203 [Default:F.GoToSurface] Running Loop=1
2012-01-09T20:26:43.32040Z,1326140803.3204 [Default:F.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T20:26:43.32080Z,1326140803.3208 [Default:GPS] Running Loop=1
2012-01-09T20:26:43.32090Z,1326140803.3209 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-09T20:26:43.32100Z,1326140803.321 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-09T20:26:43.32110Z,1326140803.3211 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-09T20:26:43.32130Z,1326140803.3213 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-09T20:26:43.32130Z,1326140803.3213 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T20:26:43.32310Z,1326140803.3231 [Default:CallIridium] Running Loop=1
2012-01-09T20:26:43.32330Z,1326140803.3233 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-09T20:26:43.32350Z,1326140803.3235 [Default:CallIridium:A] Running Loop=1
2012-01-09T20:26:43.32360Z,1326140803.3236 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-09T20:26:43.32370Z,1326140803.3237 [Default:CallGPS] Running Loop=1
2012-01-09T20:26:43.32390Z,1326140803.3239 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-09T20:26:43.32400Z,1326140803.324 [Default:CallGPS:A] Running Loop=1
2012-01-09T20:26:43.32410Z,1326140803.3241 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-09T20:26:43.32450Z,1326140803.3245 [Default:GPS:B.GoToSurface] Stopped
2012-01-09T20:26:43.32460Z,1326140803.3246 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T20:26:43.32470Z,1326140803.3247 [Default:GPS:Read_GPS] Running Loop=1
2012-01-09T20:26:43.70700Z,1326140803.707 [DAT](INFO): Powering down
2012-01-09T20:26:43.71490Z,1326140803.7149 [Default:Iridium] Running Loop=1
2012-01-09T20:26:43.71510Z,1326140803.7151 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-09T20:26:43.71520Z,1326140803.7152 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-09T20:26:43.71530Z,1326140803.7153 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-09T20:26:43.71540Z,1326140803.7154 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-09T20:26:43.71550Z,1326140803.7155 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T20:26:43.71620Z,1326140803.7162 [Default:Iridium:B.GoToSurface] Stopped
2012-01-09T20:26:43.71630Z,1326140803.7163 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T20:26:43.71650Z,1326140803.7165 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-09T20:26:44.08000Z,1326140804.08 [NAL9601](INFO): Powering up
2012-01-09T20:27:49.79100Z,1326140869.791 [NAL9601](INFO): NAL9601 initialized
2012-01-09T20:27:50.90880Z,1326140870.9088 [NAL9601](IMPORTANT): GPS fix at: 1326140882
2012-01-09T20:27:50.95990Z,1326140870.9599 [Default:GPS:Read_GPS] Stopped
2012-01-09T20:27:50.96030Z,1326140870.9603 [Default:GPS](INFO): Completed Default:GPS
2012-01-09T20:27:50.96040Z,1326140870.9604 [Default:GPS] Stopped
2012-01-09T20:27:50.96060Z,1326140870.9606 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-09T20:27:50.96060Z,1326140870.9606 [Default:GPS:A.SetSpeed] Stopped
2012-01-09T20:27:50.96070Z,1326140870.9607 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T20:27:51.36350Z,1326140871.3635 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-09T20:27:51.36360Z,1326140871.3636 [Default:CallGPS:A] Stopped
2012-01-09T20:27:51.36370Z,1326140871.3637 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-09T20:27:51.36390Z,1326140871.3639 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-09T20:27:51.36400Z,1326140871.364 [Default:CallGPS] Stopped
2012-01-09T20:27:51.36410Z,1326140871.3641 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-09T20:27:51.72360Z,1326140871.7236 [Default:CallGPS] Running Loop=1
2012-01-09T20:27:51.72380Z,1326140871.7238 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-09T20:27:51.72400Z,1326140871.724 [Default:CallGPS:A] Running Loop=1
2012-01-09T20:27:51.72410Z,1326140871.7241 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-09T20:27:52.14360Z,1326140872.1436 [Default:GPS] Running Loop=1
2012-01-09T20:27:52.14380Z,1326140872.1438 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-09T20:27:52.14390Z,1326140872.1439 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-09T20:27:52.14390Z,1326140872.1439 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-09T20:27:52.14410Z,1326140872.1441 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-09T20:27:52.14420Z,1326140872.1442 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T20:27:52.14490Z,1326140872.1449 [Default:GPS:B.GoToSurface] Stopped
2012-01-09T20:27:52.14500Z,1326140872.145 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T20:27:52.14510Z,1326140872.1451 [Default:GPS:Read_GPS] Running Loop=1
2012-01-09T20:28:08.48700Z,1326140888.487 [NAL9601](INFO): SBD MO Status=1, MOMSN=40818, MT Status=0, MTMSN=0
2012-01-09T20:28:08.65100Z,1326140888.651 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0002.lzma
2012-01-09T20:28:08.65120Z,1326140888.6512 [NAL9601](INFO): Packets left to send: 2
2012-01-09T20:28:08.65230Z,1326140888.6523 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000009
2012-01-09T20:28:16.99880Z,1326140896.9988 [NAL9601](INFO): SBD MO Status=1, MOMSN=40819, MT Status=0, MTMSN=0
2012-01-09T20:28:17.13490Z,1326140897.1349 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0002.lzma
2012-01-09T20:28:17.13510Z,1326140897.1351 [NAL9601](INFO): Packets left to send: 1
2012-01-09T20:28:17.13620Z,1326140897.1362 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000010
2012-01-09T20:28:23.67730Z,1326140903.6773 [NAL9601](INFO): SBD MO Status=1, MOMSN=40820, MT Status=0, MTMSN=0
2012-01-09T20:28:23.82690Z,1326140903.8269 [NAL9601](INFO): Sent 12 bytes from file Logs/20120109T201340/shore0002.lzma
2012-01-09T20:28:23.82720Z,1326140903.8272 [NAL9601](INFO): Packets left to send: 0
2012-01-09T20:28:23.82830Z,1326140903.8283 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000011
2012-01-09T20:28:32.47650Z,1326140912.4765 [NAL9601](INFO): SBD MO Status=0, MOMSN=40821, MT Status=0, MTMSN=0
2012-01-09T20:28:32.62720Z,1326140912.6272 [Default:Iridium:Read_Iridium] Stopped
2012-01-09T20:28:32.62770Z,1326140912.6277 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-09T20:28:32.62780Z,1326140912.6278 [Default:Iridium] Stopped
2012-01-09T20:28:32.62790Z,1326140912.6279 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-09T20:28:32.62800Z,1326140912.628 [Default:Iridium:A.SetSpeed] Stopped
2012-01-09T20:28:32.62810Z,1326140912.6281 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T20:28:32.62820Z,1326140912.6282 [Default:G.Wait] Running Loop=1
2012-01-09T20:28:32.62830Z,1326140912.6283 [Default:G.Wait](DEBUG): Initialize Wait Component.
2012-01-09T20:28:32.89190Z,1326140912.8919 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-09T20:28:32.89190Z,1326140912.8919 [Default:CallIridium:A] Stopped
2012-01-09T20:28:32.89210Z,1326140912.8921 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-09T20:28:32.89230Z,1326140912.8923 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-09T20:28:32.89240Z,1326140912.8924 [Default:CallIridium] Stopped
2012-01-09T20:28:32.89250Z,1326140912.8925 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-09T20:28:33.67880Z,1326140913.6788 [NAL9601](IMPORTANT): GPS fix at: 1326140925
2012-01-09T20:28:33.72030Z,1326140913.7203 [Default:GPS:Read_GPS] Stopped
2012-01-09T20:28:33.72070Z,1326140913.7207 [Default:GPS](INFO): Completed Default:GPS
2012-01-09T20:28:33.72080Z,1326140913.7208 [Default:GPS] Stopped
2012-01-09T20:28:33.72090Z,1326140913.7209 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-09T20:28:33.72100Z,1326140913.721 [Default:GPS:A.SetSpeed] Stopped
2012-01-09T20:28:33.72110Z,1326140913.7211 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T20:28:34.08870Z,1326140914.0887 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-09T20:28:34.08880Z,1326140914.0888 [Default:CallGPS:A] Stopped
2012-01-09T20:28:34.08890Z,1326140914.0889 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-09T20:28:34.08910Z,1326140914.0891 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-09T20:28:34.08920Z,1326140914.0892 [Default:CallGPS] Stopped
2012-01-09T20:28:34.08940Z,1326140914.0894 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-09T20:28:54.24840Z,1326140934.2484 [NAL9601](INFO): Powering down
2012-01-09T20:33:34.25030Z,1326141214.2503 [Default:CallIridium] Running Loop=1
2012-01-09T20:33:34.25050Z,1326141214.2505 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-09T20:33:34.25070Z,1326141214.2507 [Default:CallIridium:A] Running Loop=1
2012-01-09T20:33:34.25080Z,1326141214.2508 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-09T20:33:34.25090Z,1326141214.2509 [Default:CallGPS] Running Loop=1
2012-01-09T20:33:34.25110Z,1326141214.2511 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-09T20:33:34.25120Z,1326141214.2512 [Default:CallGPS:A] Running Loop=1
2012-01-09T20:33:34.25130Z,1326141214.2513 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-09T20:33:39.28140Z,1326141219.2814 [Default:Iridium] Running Loop=1
2012-01-09T20:33:39.28160Z,1326141219.2816 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-09T20:33:39.28170Z,1326141219.2817 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-09T20:33:39.28180Z,1326141219.2818 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-09T20:33:39.28200Z,1326141219.282 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-09T20:33:39.28200Z,1326141219.282 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T20:33:39.28280Z,1326141219.2828 [Default:Iridium:B.GoToSurface] Stopped
2012-01-09T20:33:39.28290Z,1326141219.2829 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T20:33:39.28300Z,1326141219.283 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-09T20:33:39.28340Z,1326141219.2834 [Default:GPS] Running Loop=1
2012-01-09T20:33:39.28350Z,1326141219.2835 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-09T20:33:39.28360Z,1326141219.2836 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-09T20:33:39.28370Z,1326141219.2837 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-09T20:33:39.28380Z,1326141219.2838 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-09T20:33:39.28390Z,1326141219.2839 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T20:33:39.28450Z,1326141219.2845 [Default:GPS:B.GoToSurface] Stopped
2012-01-09T20:33:39.28460Z,1326141219.2846 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T20:33:39.28470Z,1326141219.2847 [Default:GPS:Read_GPS] Running Loop=1
2012-01-09T20:33:39.87500Z,1326141219.875 [NAL9601](INFO): Powering up
2012-01-09T20:34:45.58690Z,1326141285.5869 [NAL9601](INFO): NAL9601 initialized
2012-01-09T20:35:06.15060Z,1326141306.1506 [NAL9601](INFO): SBD MO Status=1, MOMSN=40822, MT Status=0, MTMSN=0
2012-01-09T20:35:06.34290Z,1326141306.3429 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0003.lzma
2012-01-09T20:35:06.34310Z,1326141306.3431 [NAL9601](INFO): Packets left to send: 3
2012-01-09T20:35:06.34420Z,1326141306.3442 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000012
2012-01-09T20:35:15.03610Z,1326141315.0361 [NAL9601](INFO): SBD MO Status=1, MOMSN=40823, MT Status=0, MTMSN=0
2012-01-09T20:35:15.23090Z,1326141315.2309 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0003.lzma
2012-01-09T20:35:15.23110Z,1326141315.2311 [NAL9601](INFO): Packets left to send: 2
2012-01-09T20:35:15.26730Z,1326141315.2673 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000013
2012-01-09T20:35:29.08940Z,1326141329.0894 [NAL9601](INFO): SBD MO Status=1, MOMSN=40824, MT Status=0, MTMSN=0
2012-01-09T20:35:29.20680Z,1326141329.2068 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0003.lzma
2012-01-09T20:35:29.20710Z,1326141329.2071 [NAL9601](INFO): Packets left to send: 1
2012-01-09T20:35:29.20820Z,1326141329.2082 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000014
2012-01-09T20:35:36.41560Z,1326141336.4156 [NAL9601](INFO): SBD MO Status=1, MOMSN=40825, MT Status=0, MTMSN=0
2012-01-09T20:35:36.59890Z,1326141336.5989 [NAL9601](INFO): Sent 171 bytes from file Logs/20120109T201340/shore0003.lzma
2012-01-09T20:35:36.59920Z,1326141336.5992 [NAL9601](INFO): Packets left to send: 0
2012-01-09T20:35:36.60040Z,1326141336.6004 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000015
2012-01-09T20:35:43.99480Z,1326141343.9948 [NAL9601](INFO): SBD MO Status=0, MOMSN=40826, MT Status=0, MTMSN=0
2012-01-09T20:35:44.19990Z,1326141344.1999 [Default:Iridium:Read_Iridium] Stopped
2012-01-09T20:35:44.20030Z,1326141344.2003 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-09T20:35:44.20040Z,1326141344.2004 [Default:Iridium] Stopped
2012-01-09T20:35:44.20060Z,1326141344.2006 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-09T20:35:44.20060Z,1326141344.2006 [Default:Iridium:A.SetSpeed] Stopped
2012-01-09T20:35:44.20070Z,1326141344.2007 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T20:35:44.38420Z,1326141344.3842 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-09T20:35:44.38430Z,1326141344.3843 [Default:CallIridium:A] Stopped
2012-01-09T20:35:44.38450Z,1326141344.3845 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-09T20:35:44.38470Z,1326141344.3847 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-09T20:35:44.38480Z,1326141344.3848 [Default:CallIridium] Stopped
2012-01-09T20:35:44.38490Z,1326141344.3849 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-09T20:38:01.21730Z,1326141481.2173 [NAL9601](IMPORTANT): GPS fix at: 1326141494
2012-01-09T20:38:01.23120Z,1326141481.2312 [Default:GPS:Read_GPS] Stopped
2012-01-09T20:38:01.23170Z,1326141481.2317 [Default:GPS](INFO): Completed Default:GPS
2012-01-09T20:38:01.23180Z,1326141481.2318 [Default:GPS] Stopped
2012-01-09T20:38:01.23190Z,1326141481.2319 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-09T20:38:01.23200Z,1326141481.232 [Default:GPS:A.SetSpeed] Stopped
2012-01-09T20:38:01.23210Z,1326141481.2321 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T20:38:01.60730Z,1326141481.6073 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-09T20:38:01.60740Z,1326141481.6074 [Default:CallGPS:A] Stopped
2012-01-09T20:38:01.60750Z,1326141481.6075 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-09T20:38:01.60770Z,1326141481.6077 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-09T20:38:01.60780Z,1326141481.6078 [Default:CallGPS] Stopped
2012-01-09T20:38:01.60790Z,1326141481.6079 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-09T20:38:21.76970Z,1326141501.7697 [NAL9601](INFO): Powering down
2012-01-09T20:40:46.91100Z,1326141646.911 [Default:CallIridium] Running Loop=1
2012-01-09T20:40:46.91120Z,1326141646.9112 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-09T20:40:46.91140Z,1326141646.9114 [Default:CallIridium:A] Running Loop=1
2012-01-09T20:40:46.91150Z,1326141646.9115 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-09T20:40:46.91170Z,1326141646.9117 [Default:CallGPS] Running Loop=1
2012-01-09T20:40:46.91180Z,1326141646.9118 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-09T20:40:46.91190Z,1326141646.9119 [Default:CallGPS:A] Running Loop=1
2012-01-09T20:40:46.91210Z,1326141646.9121 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-09T20:40:51.89650Z,1326141651.8965 [Default:Iridium] Running Loop=1
2012-01-09T20:40:51.89670Z,1326141651.8967 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-09T20:40:51.89680Z,1326141651.8968 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-09T20:40:51.89690Z,1326141651.8969 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-09T20:40:51.89700Z,1326141651.897 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-09T20:40:51.89710Z,1326141651.8971 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T20:40:51.89780Z,1326141651.8978 [Default:Iridium:B.GoToSurface] Stopped
2012-01-09T20:40:51.89790Z,1326141651.8979 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T20:40:51.89800Z,1326141651.898 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-09T20:40:51.89840Z,1326141651.8984 [Default:GPS] Running Loop=1
2012-01-09T20:40:51.89850Z,1326141651.8985 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-09T20:40:51.89860Z,1326141651.8986 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-09T20:40:51.89870Z,1326141651.8987 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-09T20:40:51.89890Z,1326141651.8989 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-09T20:40:51.89890Z,1326141651.8989 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T20:40:51.89950Z,1326141651.8995 [Default:GPS:B.GoToSurface] Stopped
2012-01-09T20:40:51.89960Z,1326141651.8996 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T20:40:51.89970Z,1326141651.8997 [Default:GPS:Read_GPS] Running Loop=1
2012-01-09T20:40:52.42730Z,1326141652.4273 [NAL9601](INFO): Powering up
2012-01-09T20:41:58.33890Z,1326141718.3389 [NAL9601](INFO): NAL9601 initialized
2012-01-09T20:42:16.56150Z,1326141736.5615 [NAL9601](INFO): SBD MO Status=1, MOMSN=40827, MT Status=0, MTMSN=0
2012-01-09T20:42:16.69900Z,1326141736.699 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0004.lzma
2012-01-09T20:42:16.69920Z,1326141736.6992 [NAL9601](INFO): Packets left to send: 1
2012-01-09T20:42:16.70040Z,1326141736.7004 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000016
2012-01-09T20:42:23.82940Z,1326141743.8294 [NAL9601](INFO): SBD MO Status=1, MOMSN=40828, MT Status=0, MTMSN=0
2012-01-09T20:42:23.98680Z,1326141743.9868 [NAL9601](INFO): Sent 309 bytes from file Logs/20120109T201340/shore0004.lzma
2012-01-09T20:42:23.98710Z,1326141743.9871 [NAL9601](INFO): Packets left to send: 0
2012-01-09T20:42:23.98820Z,1326141743.9882 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000017
2012-01-09T20:42:27.82470Z,1326141747.8247 [NAL9601](INFO): SBD MO Status=0, MOMSN=40829, MT Status=0, MTMSN=0
2012-01-09T20:42:27.99610Z,1326141747.9961 [Default:Iridium:Read_Iridium] Stopped
2012-01-09T20:42:27.99650Z,1326141747.9965 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-09T20:42:27.99660Z,1326141747.9966 [Default:Iridium] Stopped
2012-01-09T20:42:27.99670Z,1326141747.9967 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-09T20:42:27.99680Z,1326141747.9968 [Default:Iridium:A.SetSpeed] Stopped
2012-01-09T20:42:27.99690Z,1326141747.9969 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T20:42:28.24170Z,1326141748.2417 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-09T20:42:28.24180Z,1326141748.2418 [Default:CallIridium:A] Stopped
2012-01-09T20:42:28.24200Z,1326141748.242 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-09T20:42:28.24230Z,1326141748.2423 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-09T20:42:28.24240Z,1326141748.2424 [Default:CallIridium] Stopped
2012-01-09T20:42:28.24260Z,1326141748.2426 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-09T20:42:29.02690Z,1326141749.0269 [NAL9601](IMPORTANT): GPS fix at: 1326141762
2012-01-09T20:42:29.08910Z,1326141749.0891 [Default:GPS:Read_GPS] Stopped
2012-01-09T20:42:29.08950Z,1326141749.0895 [Default:GPS](INFO): Completed Default:GPS
2012-01-09T20:42:29.08960Z,1326141749.0896 [Default:GPS] Stopped
2012-01-09T20:42:29.08980Z,1326141749.0898 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-09T20:42:29.08980Z,1326141749.0898 [Default:GPS:A.SetSpeed] Stopped
2012-01-09T20:42:29.08990Z,1326141749.0899 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T20:42:29.43980Z,1326141749.4398 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-09T20:42:29.43990Z,1326141749.4399 [Default:CallGPS:A] Stopped
2012-01-09T20:42:29.44010Z,1326141749.4401 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-09T20:42:29.44030Z,1326141749.4403 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-09T20:42:29.44030Z,1326141749.4403 [Default:CallGPS] Stopped
2012-01-09T20:42:29.44050Z,1326141749.4405 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-09T20:42:49.58830Z,1326141769.5883 [NAL9601](INFO): Powering down
2012-01-09T20:47:29.71440Z,1326142049.7144 [Default:CallIridium] Running Loop=1
2012-01-09T20:47:29.71460Z,1326142049.7146 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-09T20:47:29.71480Z,1326142049.7148 [Default:CallIridium:A] Running Loop=1
2012-01-09T20:47:29.71490Z,1326142049.7149 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-09T20:47:29.71510Z,1326142049.7151 [Default:CallGPS] Running Loop=1
2012-01-09T20:47:29.71520Z,1326142049.7152 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-09T20:47:29.71530Z,1326142049.7153 [Default:CallGPS:A] Running Loop=1
2012-01-09T20:47:29.71550Z,1326142049.7155 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-09T20:47:34.60990Z,1326142054.6099 [Default:Iridium] Running Loop=1
2012-01-09T20:47:34.61010Z,1326142054.6101 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-09T20:47:34.61010Z,1326142054.6101 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-09T20:47:34.61020Z,1326142054.6102 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-09T20:47:34.61050Z,1326142054.6105 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-09T20:47:34.61050Z,1326142054.6105 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T20:47:34.61120Z,1326142054.6112 [Default:Iridium:B.GoToSurface] Stopped
2012-01-09T20:47:34.61130Z,1326142054.6113 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T20:47:34.61140Z,1326142054.6114 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-09T20:47:34.61170Z,1326142054.6117 [Default:GPS] Running Loop=1
2012-01-09T20:47:34.61190Z,1326142054.6119 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-09T20:47:34.61200Z,1326142054.612 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-09T20:47:34.61200Z,1326142054.612 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-09T20:47:34.61220Z,1326142054.6122 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-09T20:47:34.61230Z,1326142054.6123 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T20:47:34.61300Z,1326142054.613 [Default:GPS:B.GoToSurface] Stopped
2012-01-09T20:47:34.61300Z,1326142054.613 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T20:47:34.61320Z,1326142054.6132 [Default:GPS:Read_GPS] Running Loop=1
2012-01-09T20:47:35.22800Z,1326142055.228 [NAL9601](INFO): Powering up
2012-01-09T20:48:40.93900Z,1326142120.939 [NAL9601](INFO): NAL9601 initialized
2012-01-09T20:49:01.49360Z,1326142141.4936 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=40830, MT Status=1, MTMSN=3392
2012-01-09T20:49:01.69880Z,1326142141.6988 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0005.lzma
2012-01-09T20:49:01.69910Z,1326142141.6991 [NAL9601](INFO): Packets left to send: 1
2012-01-09T20:49:01.84600Z,1326142141.846 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000018
2012-01-09T20:49:02.16410Z,1326142142.1641 [NAL9601](INFO): Received command:load Transport/transit_3km.xml;set transit_3km.Wpt1Lat 36.817 degree;set transit_3km.Wpt1Lon -121.828 degree;run 
2012-01-09T20:49:02.18150Z,1326142142.1815 [CommandLine](IMPORTANT): got command load ./Missions/Transport/transit_3km.xml
2012-01-09T20:49:02.18180Z,1326142142.1818 [MissionManager](INFO): Loading Mission: ./Missions/Transport/transit_3km.xml
2012-01-09T20:49:02.22590Z,1326142142.2259 [MissionManager](INFO): DefineArg transit_3km.ApproachDepth = 10 m
2012-01-09T20:49:02.22920Z,1326142142.2292 [MissionManager](INFO): DefineArg transit_3km.Wpt1Lat = 36.806966 arcdeg
2012-01-09T20:49:02.23250Z,1326142142.2325 [MissionManager](INFO): DefineArg transit_3km.Wpt1Lon = -121.824326 arcdeg
2012-01-09T20:49:02.23570Z,1326142142.2357 [MissionManager](INFO): DefineArg transit_3km.Speed = 1 m/s
2012-01-09T20:49:02.23750Z,1326142142.2375 [transit_3km:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-01-09T20:49:02.24550Z,1326142142.2455 [transit_3km:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-01-09T20:49:02.25370Z,1326142142.2537 [transit_3km:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2012-01-09T20:49:02.26320Z,1326142142.2632 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-01-09T20:49:02.26900Z,1326142142.269 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Construct.
2012-01-09T20:49:02.28170Z,1326142142.2817 [transit_3km:WaypointOne:A.Pitch](DEBUG): Construct.
2012-01-09T20:49:02.29020Z,1326142142.2902 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Construct.
2012-01-09T20:49:02.29370Z,1326142142.2937 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Construct Waypoint.
2012-01-09T20:49:02.30680Z,1326142142.3068 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="utf-8"?>
<Mission xmlns="Tethys" xmlns:Control="Tethys/Control" xmlns:Guidance="Tethys/Guidance" xmlns:Units="Tethys/Units" xmlns:Universal="Tethys/Universal" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd                            Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd                            Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd                            Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd                            Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd" Id="transit_3km">

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

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

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

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

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

    <Timeout Duration="P130M" />

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

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

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

    <Aggregate Id="SURFACECOMMS">

        <Guidance:GoToSurface RunIn="Progression" />

        <Aggregate>

            <Preemptive><True /></Preemptive>

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

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

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

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

        </Aggregate>

    </Aggregate>

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

    <Aggregate Id="NeedComms">

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

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

    </Aggregate>

    <Aggregate Id="WaypointOne">

<!-- Go to Wpt1 -->

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

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

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

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

    </Aggregate>

</Mission>


2012-01-09T20:49:02.30740Z,1326142142.3074 [CommandLine](IMPORTANT): Loaded ./Missions/Transport/transit_3km.xml
2012-01-09T20:49:02.38930Z,1326142142.3893 [CommandLine](IMPORTANT): got command set transit_3km.Wpt1Lat 36.81700134 degree
2012-01-09T20:49:02.47060Z,1326142142.4706 [CommandLine](IMPORTANT): got command set transit_3km.Wpt1Lon -121.8280029 degree
2012-01-09T20:49:02.47190Z,1326142142.4719 [CommandLine](IMPORTANT): got command run 
2012-01-09T20:49:02.47210Z,1326142142.4721 [CommandLine](IMPORTANT): Running 
2012-01-09T20:49:02.48510Z,1326142142.4851 [Default] Stopped
2012-01-09T20:49:02.48520Z,1326142142.4852 [Default](INFO): Aggregate::uninitialize Default
2012-01-09T20:49:02.48530Z,1326142142.4853 [Default:GPS] Stopped
2012-01-09T20:49:02.48550Z,1326142142.4855 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-09T20:49:02.48550Z,1326142142.4855 [Default:GPS:A.SetSpeed] Stopped
2012-01-09T20:49:02.48560Z,1326142142.4856 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T20:49:02.48570Z,1326142142.4857 [Default:GPS:Read_GPS] Stopped
2012-01-09T20:49:02.48570Z,1326142142.4857 [Default:Iridium] Stopped
2012-01-09T20:49:02.48590Z,1326142142.4859 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-09T20:49:02.48590Z,1326142142.4859 [Default:Iridium:A.SetSpeed] Stopped
2012-01-09T20:49:02.48600Z,1326142142.486 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T20:49:02.48610Z,1326142142.4861 [Default:Iridium:Read_Iridium] Stopped
2012-01-09T20:49:02.48610Z,1326142142.4861 [Default:CallGPS] Stopped
2012-01-09T20:49:02.48630Z,1326142142.4863 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-09T20:49:02.48640Z,1326142142.4864 [Default:CallGPS:A] Stopped
2012-01-09T20:49:02.48650Z,1326142142.4865 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-09T20:49:02.48660Z,1326142142.4866 [Default:CallIridium] Stopped
2012-01-09T20:49:02.48670Z,1326142142.4867 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-09T20:49:02.48680Z,1326142142.4868 [Default:CallIridium:A] Stopped
2012-01-09T20:49:02.48690Z,1326142142.4869 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-09T20:49:02.48700Z,1326142142.487 [Default:E.SetSpeed] Stopped
2012-01-09T20:49:02.48710Z,1326142142.4871 [Default:E.SetSpeed](DEBUG): Uninitialize.
2012-01-09T20:49:02.48710Z,1326142142.4871 [Default:F.GoToSurface] Stopped
2012-01-09T20:49:02.48720Z,1326142142.4872 [Default:F.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T20:49:02.48730Z,1326142142.4873 [Default:G.Wait] Stopped
2012-01-09T20:49:02.48730Z,1326142142.4873 [Default:G.Wait](DEBUG): Uninitialize Wait Component.
2012-01-09T20:49:02.48750Z,1326142142.4875 [MissionManager](IMPORTANT): Started mission transit_3km
2012-01-09T20:49:02.48760Z,1326142142.4876 [transit_3km] Running Loop=1
2012-01-09T20:49:02.48770Z,1326142142.4877 [transit_3km](INFO): Aggregate::initialize transit_3km
2012-01-09T20:49:02.48780Z,1326142142.4878 [transit_3km:A.AltitudeEnvelope] Running Loop=1
2012-01-09T20:49:02.48790Z,1326142142.4879 [transit_3km:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-01-09T20:49:02.48810Z,1326142142.4881 [transit_3km:B.DepthEnvelope] Running Loop=1
2012-01-09T20:49:02.48820Z,1326142142.4882 [transit_3km:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-01-09T20:49:02.48970Z,1326142142.4897 [transit_3km:C.OffshoreEnvelope] Running Loop=1
2012-01-09T20:49:02.48980Z,1326142142.4898 [transit_3km:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2012-01-09T20:49:02.49000Z,1326142142.49 [transit_3km:SURFACECOMMS] Running Loop=1
2012-01-09T20:49:02.49010Z,1326142142.4901 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2012-01-09T20:49:02.49020Z,1326142142.4902 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-01-09T20:49:02.49040Z,1326142142.4904 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T20:49:02.49580Z,1326142142.4958 [transit_3km:SURFACECOMMS:B] Running Loop=1
2012-01-09T20:49:02.49600Z,1326142142.496 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:B
2012-01-09T20:49:02.49610Z,1326142142.4961 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-01-09T20:49:02.49610Z,1326142142.4961 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-01-09T20:49:02.49640Z,1326142142.4964 [transit_3km:SURFACECOMMS:B:B] Running Loop=1
2012-01-09T20:49:02.49650Z,1326142142.4965 [transit_3km:C.OffshoreEnvelope] Running Loop=1
2012-01-09T20:49:02.50150Z,1326142142.5015 [transit_3km:B.DepthEnvelope] Running Loop=1
2012-01-09T20:49:02.50660Z,1326142142.5066 [transit_3km:A.AltitudeEnvelope] Running Loop=1
2012-01-09T20:49:02.83740Z,1326142142.8374 [transit_3km:SURFACECOMMS:B:B](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-01-09T20:49:02.83880Z,1326142142.8388 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-01-09T20:49:04.85240Z,1326142144.8524 [NAL9601](IMPORTANT): GPS fix at: 1326142158
2012-01-09T20:49:04.87340Z,1326142144.8734 [transit_3km:SURFACECOMMS:B:B] Stopped
2012-01-09T20:49:04.87360Z,1326142144.8736 [transit_3km:SURFACECOMMS:B:C] Running Loop=1
2012-01-09T20:49:05.18940Z,1326142145.1894 [transit_3km:SURFACECOMMS:B:C](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-01-09T20:49:22.31720Z,1326142162.3172 [NAL9601](INFO): SBD MO Status=1, MOMSN=40831, MT Status=0, MTMSN=0
2012-01-09T20:49:22.46290Z,1326142162.4629 [NAL9601](INFO): Sent 167 bytes from file Logs/20120109T201340/shore0005.lzma
2012-01-09T20:49:22.46310Z,1326142162.4631 [NAL9601](INFO): Packets left to send: 0
2012-01-09T20:49:22.46420Z,1326142162.4642 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000019
2012-01-09T20:49:34.37300Z,1326142174.373 [NAL9601](INFO): SBD MO Status=0, MOMSN=40832, MT Status=0, MTMSN=0
2012-01-09T20:49:54.67980Z,1326142194.6798 [NAL9601](INFO): SBD MO Status=1, MOMSN=40833, MT Status=0, MTMSN=0
2012-01-09T20:49:54.81090Z,1326142194.8109 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0006.lzma
2012-01-09T20:49:54.81110Z,1326142194.8111 [NAL9601](INFO): Packets left to send: 1
2012-01-09T20:49:54.81220Z,1326142194.8122 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000020
2012-01-09T20:50:01.94130Z,1326142201.9413 [NAL9601](INFO): SBD MO Status=1, MOMSN=40834, MT Status=0, MTMSN=0
2012-01-09T20:50:02.10290Z,1326142202.1029 [NAL9601](INFO): Sent 182 bytes from file Logs/20120109T201340/shore0006.lzma
2012-01-09T20:50:02.10310Z,1326142202.1031 [NAL9601](INFO): Packets left to send: 0
2012-01-09T20:50:02.10430Z,1326142202.1043 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000021
2012-01-09T20:50:10.33670Z,1326142210.3367 [NAL9601](INFO): SBD MO Status=0, MOMSN=40835, MT Status=0, MTMSN=0
2012-01-09T20:50:10.50410Z,1326142210.5041 [transit_3km:SURFACECOMMS:B:C] Stopped
2012-01-09T20:50:10.50420Z,1326142210.5042 [transit_3km:SURFACECOMMS:B:D] Running Loop=1
2012-01-09T20:50:10.80570Z,1326142210.8057 [transit_3km:SURFACECOMMS:B:D](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-01-09T20:50:12.73790Z,1326142212.7379 [NAL9601](IMPORTANT): GPS fix at: 1326142226
2012-01-09T20:50:12.75180Z,1326142212.7518 [transit_3km:SURFACECOMMS:B:D] Stopped
2012-01-09T20:50:12.75230Z,1326142212.7523 [transit_3km:SURFACECOMMS:B](INFO): Completed transit_3km:SURFACECOMMS:B
2012-01-09T20:50:12.75240Z,1326142212.7524 [transit_3km:SURFACECOMMS:B] Stopped
2012-01-09T20:50:12.75250Z,1326142212.7525 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:B
2012-01-09T20:50:12.75260Z,1326142212.7526 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-01-09T20:50:12.75270Z,1326142212.7527 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T20:50:12.75320Z,1326142212.7532 [transit_3km:SURFACECOMMS](INFO): Completed transit_3km:SURFACECOMMS
2012-01-09T20:50:12.75320Z,1326142212.7532 [transit_3km:SURFACECOMMS] Stopped
2012-01-09T20:50:12.75340Z,1326142212.7534 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2012-01-09T20:50:12.75350Z,1326142212.7535 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2012-01-09T20:50:12.75350Z,1326142212.7535 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T20:50:12.75370Z,1326142212.7537 [transit_3km:WaypointOne] Running Loop=1
2012-01-09T20:50:12.75380Z,1326142212.7538 [transit_3km:WaypointOne](INFO): Aggregate::initialize transit_3km:WaypointOne
2012-01-09T20:50:12.75390Z,1326142212.7539 [transit_3km:WaypointOne:A.Pitch] Running Loop=1
2012-01-09T20:50:12.75400Z,1326142212.754 [transit_3km:WaypointOne:A.Pitch](DEBUG): Initialize.
2012-01-09T20:50:12.75420Z,1326142212.7542 [transit_3km:WaypointOne:B.SetSpeed] Running Loop=1
2012-01-09T20:50:12.75440Z,1326142212.7544 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Initialize.
2012-01-09T20:50:12.75470Z,1326142212.7547 [transit_3km:WaypointOne:WaypointW1.Waypoint] Running Loop=1
2012-01-09T20:50:12.75480Z,1326142212.7548 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Initialize WaypointComponent.
2012-01-09T20:50:13.17100Z,1326142213.171 [transit_3km:WaypointOne:B.SetSpeed] Running Loop=1
2012-01-09T20:50:13.17540Z,1326142213.1754 [transit_3km:WaypointOne:A.Pitch] Running Loop=1
2012-01-09T20:50:19.07940Z,1326142219.0794 [NAL9601](INFO): Powering down
2012-01-09T21:17:44.03640Z,1326143864.0364 [transit_3km:WaypointOne:WaypointW1.Waypoint](INFO): Reached Waypoint: 36.81700091,-121.8280078
2012-01-09T21:17:44.03670Z,1326143864.0367 [transit_3km:WaypointOne:WaypointW1.Waypoint] Stopped
2012-01-09T21:17:44.03670Z,1326143864.0367 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Uninitialize WaypointComponent.
2012-01-09T21:17:44.03690Z,1326143864.0369 [transit_3km:WaypointOne:PHONEHOMEWPT1] Running Loop=1
2012-01-09T21:17:44.03710Z,1326143864.0371 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Aggregate::initialize transit_3km:WaypointOne:PHONEHOMEWPT1
2012-01-09T21:17:44.40030Z,1326143864.4003 [transit_3km:SURFACECOMMS] Running Loop=1
2012-01-09T21:17:44.40050Z,1326143864.4005 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2012-01-09T21:17:44.40060Z,1326143864.4006 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-01-09T21:17:44.40070Z,1326143864.4007 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T21:20:30.38890Z,1326144030.3889 [transit_3km:SURFACECOMMS:B] Running Loop=1
2012-01-09T21:20:30.38910Z,1326144030.3891 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:B
2012-01-09T21:20:30.38910Z,1326144030.3891 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-01-09T21:20:30.38920Z,1326144030.3892 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-01-09T21:20:30.38940Z,1326144030.3894 [transit_3km:SURFACECOMMS:B:B] Running Loop=1
2012-01-09T21:20:31.16910Z,1326144031.1691 [NAL9601](INFO): Powering up
2012-01-09T21:21:36.89100Z,1326144096.891 [NAL9601](INFO): NAL9601 initialized
2012-01-09T21:21:37.96840Z,1326144097.9684 [NAL9601](IMPORTANT): GPS fix at: 1326144115
2012-01-09T21:21:37.98170Z,1326144097.9817 [transit_3km:SURFACECOMMS:B:B] Stopped
2012-01-09T21:21:37.98190Z,1326144097.9819 [transit_3km:SURFACECOMMS:B:C] Running Loop=1
2012-01-09T21:21:53.16270Z,1326144113.1627 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=40836, MT Status=1, MTMSN=3393
2012-01-09T21:21:53.34290Z,1326144113.3429 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0007.lzma
2012-01-09T21:21:53.34310Z,1326144113.3431 [NAL9601](INFO): Packets left to send: 4
2012-01-09T21:21:53.34420Z,1326144113.3442 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000022
2012-01-09T21:21:53.76000Z,1326144113.76 [NAL9601](INFO): Received command:run Maintenance/dat_on.xml
2012-01-09T21:21:53.82270Z,1326144113.8227 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/dat_on.xml
2012-01-09T21:21:53.82290Z,1326144113.8229 [transit_3km] Stopped
2012-01-09T21:21:53.82300Z,1326144113.823 [transit_3km](INFO): Aggregate::uninitialize transit_3km
2012-01-09T21:21:53.82310Z,1326144113.8231 [transit_3km:A.AltitudeEnvelope] Stopped
2012-01-09T21:21:53.82320Z,1326144113.8232 [transit_3km:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-01-09T21:21:53.82320Z,1326144113.8232 [transit_3km:B.DepthEnvelope] Stopped
2012-01-09T21:21:53.82330Z,1326144113.8233 [transit_3km:B.DepthEnvelope](DEBUG): Uninitialize.
2012-01-09T21:21:53.82340Z,1326144113.8234 [transit_3km:C.OffshoreEnvelope] Stopped
2012-01-09T21:21:53.82340Z,1326144113.8234 [transit_3km:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2012-01-09T21:21:53.82350Z,1326144113.8235 [transit_3km:SURFACECOMMS] Stopped
2012-01-09T21:21:53.82360Z,1326144113.8236 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2012-01-09T21:21:53.82370Z,1326144113.8237 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2012-01-09T21:21:53.82380Z,1326144113.8238 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T21:21:53.82390Z,1326144113.8239 [transit_3km:SURFACECOMMS:B] Stopped
2012-01-09T21:21:53.82400Z,1326144113.824 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:B
2012-01-09T21:21:53.82410Z,1326144113.8241 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-01-09T21:21:53.82410Z,1326144113.8241 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T21:21:53.82420Z,1326144113.8242 [transit_3km:SURFACECOMMS:B:C] Stopped
2012-01-09T21:21:53.82430Z,1326144113.8243 [transit_3km:WaypointOne] Stopped
2012-01-09T21:21:53.82440Z,1326144113.8244 [transit_3km:WaypointOne](INFO): Aggregate::uninitialize transit_3km:WaypointOne
2012-01-09T21:21:53.82450Z,1326144113.8245 [transit_3km:WaypointOne:A.Pitch] Stopped
2012-01-09T21:21:53.82450Z,1326144113.8245 [transit_3km:WaypointOne:B.SetSpeed] Stopped
2012-01-09T21:21:53.82460Z,1326144113.8246 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Uninitialize.
2012-01-09T21:21:53.82470Z,1326144113.8247 [transit_3km:WaypointOne:PHONEHOMEWPT1] Stopped
2012-01-09T21:21:53.82480Z,1326144113.8248 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Aggregate::uninitialize transit_3km:WaypointOne:PHONEHOMEWPT1
2012-01-09T21:21:53.83130Z,1326144113.8313 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/dat_on.xml
2012-01-09T21:21:53.84360Z,1326144113.8436 [MissionManager](INFO): DefineArg dat_on.MassDefault = 0.0015 n/a
2012-01-09T21:21:53.84500Z,1326144113.845 [dat_on:A.Pitch](DEBUG): Construct.
2012-01-09T21:21:53.85240Z,1326144113.8524 [dat_on:TestDrive:B.Wait](DEBUG): Construct Wait.
2012-01-09T21:21:53.85520Z,1326144113.8552 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="dat_on">

    <DefineArg Name="MassDefault"><CustomUri Uri="Config/Control.massDefault"/></DefineArg>

    <Timeout Duration="P15M"/>

    <Guidance:Pitch RunIn="Parallel">
        <Setting><Guidance:Pitch.massPosition/><Arg Name="MassDefault"/></Setting>
    </Guidance:Pitch>

    <Aggregate Id="TestDrive">

        <ReadData>
            <Universal:homing_target_range/>
        </ReadData>

        <Guidance:Wait RunIn="Sequence">
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>2</Value></Setting>
        </Guidance:Wait>

    </Aggregate>

</Mission>


2012-01-09T21:21:53.85560Z,1326144113.8556 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/dat_on.xml
2012-01-09T21:21:54.04000Z,1326144114.04 [MissionManager](IMPORTANT): Started mission dat_on
2012-01-09T21:21:54.04010Z,1326144114.0401 [dat_on] Running Loop=1
2012-01-09T21:21:54.04020Z,1326144114.0402 [dat_on](INFO): Aggregate::initialize dat_on
2012-01-09T21:21:54.04030Z,1326144114.0403 [dat_on:A.Pitch] Running Loop=1
2012-01-09T21:21:54.04040Z,1326144114.0404 [dat_on:A.Pitch](DEBUG): Initialize.
2012-01-09T21:21:54.04060Z,1326144114.0406 [dat_on:TestDrive] Running Loop=1
2012-01-09T21:21:54.04080Z,1326144114.0408 [dat_on:TestDrive](INFO): Aggregate::initialize dat_on:TestDrive
2012-01-09T21:21:54.04090Z,1326144114.0409 [dat_on:TestDrive:A] Running Loop=1
2012-01-09T21:21:54.04100Z,1326144114.041 [dat_on:TestDrive:B.Wait] Running Loop=1
2012-01-09T21:21:54.04110Z,1326144114.0411 [dat_on:TestDrive:B.Wait](DEBUG): Initialize Wait Component.
2012-01-09T21:21:54.04210Z,1326144114.0421 [dat_on:TestDrive:A] Running Loop=1
2012-01-09T21:21:54.04260Z,1326144114.0426 [dat_on:TestDrive:A](DEBUG): Initialize ReadDataComponent to sense homing_target_range
2012-01-09T21:21:54.04340Z,1326144114.0434 [dat_on:A.Pitch] Running Loop=1
2012-01-09T21:21:54.36300Z,1326144114.363 [DAT](INFO): Powering up
2012-01-09T21:21:59.14330Z,1326144119.1433 [NAL9601](INFO): Powering down
2012-01-09T21:22:22.01040Z,1326144142.0104 [DAT](ERROR): No response from remote modem
2012-01-09T21:22:34.43440Z,1326144154.4344 [DAT](ERROR): No response from remote modem
2012-01-09T21:22:47.23440Z,1326144167.2344 [DAT](ERROR): No response from remote modem
2012-01-09T21:22:59.63440Z,1326144179.6344 [DAT](ERROR): No response from remote modem
2012-01-09T21:23:12.03440Z,1326144192.0344 [DAT](ERROR): No response from remote modem
2012-01-09T21:23:24.56650Z,1326144204.5665 [DAT](ERROR): No response from remote modem
2012-01-09T21:23:36.85440Z,1326144216.8544 [DAT](ERROR): No response from remote modem
2012-01-09T21:23:49.23440Z,1326144229.2344 [DAT](ERROR): No response from remote modem
2012-01-09T21:23:54.48410Z,1326144234.4841 [dat_on:TestDrive:B.Wait](INFO): Done Waiting.
2012-01-09T21:23:54.48440Z,1326144234.4844 [dat_on:TestDrive:B.Wait] Stopped
2012-01-09T21:23:54.48450Z,1326144234.4845 [dat_on:TestDrive:B.Wait](DEBUG): Uninitialize Wait Component.
2012-01-09T21:23:54.48480Z,1326144234.4848 [dat_on:TestDrive](INFO): Completed dat_on:TestDrive
2012-01-09T21:23:54.48490Z,1326144234.4849 [dat_on:TestDrive] Stopped
2012-01-09T21:23:54.48500Z,1326144234.485 [dat_on:TestDrive](INFO): Aggregate::uninitialize dat_on:TestDrive
2012-01-09T21:23:54.48510Z,1326144234.4851 [dat_on:TestDrive:A] Stopped
2012-01-09T21:23:54.48550Z,1326144234.4855 [dat_on](INFO): Completed dat_on
2012-01-09T21:23:54.48560Z,1326144234.4856 [dat_on] Stopped
2012-01-09T21:23:54.48570Z,1326144234.4857 [dat_on](INFO): Aggregate::uninitialize dat_on
2012-01-09T21:23:54.48580Z,1326144234.4858 [dat_on:A.Pitch] Stopped
2012-01-09T21:23:54.76890Z,1326144234.7689 [MissionManager](IMPORTANT): Started mission Default
2012-01-09T21:23:54.76900Z,1326144234.769 [Default] Running Loop=1
2012-01-09T21:23:54.76910Z,1326144234.7691 [Default](INFO): Aggregate::initialize Default
2012-01-09T21:23:54.76920Z,1326144234.7692 [Default:E.SetSpeed] Running Loop=1
2012-01-09T21:23:54.76930Z,1326144234.7693 [Default:E.SetSpeed](DEBUG): Initialize.
2012-01-09T21:23:54.76940Z,1326144234.7694 [Default:F.GoToSurface] Running Loop=1
2012-01-09T21:23:54.76950Z,1326144234.7695 [Default:F.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T21:23:54.76990Z,1326144234.7699 [Default:GPS] Running Loop=1
2012-01-09T21:23:54.77010Z,1326144234.7701 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-09T21:23:54.77010Z,1326144234.7701 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-09T21:23:54.77020Z,1326144234.7702 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-09T21:23:54.77040Z,1326144234.7704 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-09T21:23:54.77050Z,1326144234.7705 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T21:23:54.77190Z,1326144234.7719 [Default:CallIridium] Running Loop=1
2012-01-09T21:23:54.77200Z,1326144234.772 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-09T21:23:54.77220Z,1326144234.7722 [Default:CallIridium:A] Running Loop=1
2012-01-09T21:23:54.77230Z,1326144234.7723 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-09T21:23:54.77250Z,1326144234.7725 [Default:CallGPS] Running Loop=1
2012-01-09T21:23:54.77260Z,1326144234.7726 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-09T21:23:54.77270Z,1326144234.7727 [Default:CallGPS:A] Running Loop=1
2012-01-09T21:23:54.77290Z,1326144234.7729 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-09T21:23:54.77330Z,1326144234.7733 [Default:GPS:B.GoToSurface] Stopped
2012-01-09T21:23:54.77340Z,1326144234.7734 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T21:23:54.77350Z,1326144234.7735 [Default:GPS:Read_GPS] Running Loop=1
2012-01-09T21:23:55.14840Z,1326144235.1484 [DAT](INFO): Powering down
2012-01-09T21:23:55.15680Z,1326144235.1568 [Default:Iridium] Running Loop=1
2012-01-09T21:23:55.15700Z,1326144235.157 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-09T21:23:55.15710Z,1326144235.1571 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-09T21:23:55.15710Z,1326144235.1571 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-09T21:23:55.15730Z,1326144235.1573 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-09T21:23:55.15740Z,1326144235.1574 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T21:23:55.15810Z,1326144235.1581 [Default:Iridium:B.GoToSurface] Stopped
2012-01-09T21:23:55.15820Z,1326144235.1582 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T21:23:55.15840Z,1326144235.1584 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-09T21:23:55.54330Z,1326144235.5433 [NAL9601](INFO): Powering up
2012-01-09T21:25:01.25500Z,1326144301.255 [NAL9601](INFO): NAL9601 initialized
2012-01-09T21:25:02.36300Z,1326144302.363 [NAL9601](IMPORTANT): GPS fix at: 1326144319
2012-01-09T21:25:02.37730Z,1326144302.3773 [Default:GPS:Read_GPS] Stopped
2012-01-09T21:25:02.37770Z,1326144302.3777 [Default:GPS](INFO): Completed Default:GPS
2012-01-09T21:25:02.37780Z,1326144302.3778 [Default:GPS] Stopped
2012-01-09T21:25:02.37790Z,1326144302.3779 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-09T21:25:02.37800Z,1326144302.378 [Default:GPS:A.SetSpeed] Stopped
2012-01-09T21:25:02.37800Z,1326144302.378 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T21:25:02.76420Z,1326144302.7642 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-09T21:25:02.76430Z,1326144302.7643 [Default:CallGPS:A] Stopped
2012-01-09T21:25:02.76450Z,1326144302.7645 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-09T21:25:02.76470Z,1326144302.7647 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-09T21:25:02.76470Z,1326144302.7647 [Default:CallGPS] Stopped
2012-01-09T21:25:02.76490Z,1326144302.7649 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-09T21:25:03.16960Z,1326144303.1696 [Default:CallGPS] Running Loop=1
2012-01-09T21:25:03.16980Z,1326144303.1698 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-09T21:25:03.17000Z,1326144303.17 [Default:CallGPS:A] Running Loop=1
2012-01-09T21:25:03.17010Z,1326144303.1701 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-09T21:25:03.56040Z,1326144303.5604 [Default:GPS] Running Loop=1
2012-01-09T21:25:03.56060Z,1326144303.5606 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-09T21:25:03.56070Z,1326144303.5607 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-09T21:25:03.56070Z,1326144303.5607 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-09T21:25:03.56090Z,1326144303.5609 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-09T21:25:03.56100Z,1326144303.561 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T21:25:03.56160Z,1326144303.5616 [Default:GPS:B.GoToSurface] Stopped
2012-01-09T21:25:03.56170Z,1326144303.5617 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T21:25:03.56180Z,1326144303.5618 [Default:GPS:Read_GPS] Running Loop=1
2012-01-09T21:25:18.60530Z,1326144318.6053 [NAL9601](INFO): SBD MO Status=1, MOMSN=40837, MT Status=0, MTMSN=0
2012-01-09T21:25:18.81900Z,1326144318.819 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0007.lzma
2012-01-09T21:25:18.81930Z,1326144318.8193 [NAL9601](INFO): Packets left to send: 3
2012-01-09T21:25:18.82040Z,1326144318.8204 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000023
2012-01-09T21:25:26.28150Z,1326144326.2815 [NAL9601](INFO): SBD MO Status=1, MOMSN=40838, MT Status=0, MTMSN=0
2012-01-09T21:25:26.40700Z,1326144326.407 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0007.lzma
2012-01-09T21:25:26.40720Z,1326144326.4072 [NAL9601](INFO): Packets left to send: 2
2012-01-09T21:25:26.40830Z,1326144326.4083 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000024
2012-01-09T21:25:34.01460Z,1326144334.0146 [NAL9601](INFO): SBD MO Status=1, MOMSN=40839, MT Status=0, MTMSN=0
2012-01-09T21:25:34.19090Z,1326144334.1909 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0007.lzma
2012-01-09T21:25:34.19110Z,1326144334.1911 [NAL9601](INFO): Packets left to send: 1
2012-01-09T21:25:34.19230Z,1326144334.1923 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000025
2012-01-09T21:25:39.77160Z,1326144339.7716 [NAL9601](INFO): SBD MO Status=1, MOMSN=40840, MT Status=0, MTMSN=0
2012-01-09T21:25:39.98290Z,1326144339.9829 [NAL9601](INFO): Sent 102 bytes from file Logs/20120109T201340/shore0007.lzma
2012-01-09T21:25:39.98310Z,1326144339.9831 [NAL9601](INFO): Packets left to send: 0
2012-01-09T21:25:39.98420Z,1326144339.9842 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000026
2012-01-09T21:25:47.32830Z,1326144347.3283 [NAL9601](INFO): SBD MO Status=0, MOMSN=40841, MT Status=0, MTMSN=0
2012-01-09T21:25:47.48380Z,1326144347.4838 [Default:Iridium:Read_Iridium] Stopped
2012-01-09T21:25:47.48430Z,1326144347.4843 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-09T21:25:47.48440Z,1326144347.4844 [Default:Iridium] Stopped
2012-01-09T21:25:47.48450Z,1326144347.4845 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-09T21:25:47.48460Z,1326144347.4846 [Default:Iridium:A.SetSpeed] Stopped
2012-01-09T21:25:47.48460Z,1326144347.4846 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T21:25:47.48480Z,1326144347.4848 [Default:G.Wait] Running Loop=1
2012-01-09T21:25:47.48480Z,1326144347.4848 [Default:G.Wait](DEBUG): Initialize Wait Component.
2012-01-09T21:25:47.74030Z,1326144347.7403 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-09T21:25:47.74040Z,1326144347.7404 [Default:CallIridium:A] Stopped
2012-01-09T21:25:47.74050Z,1326144347.7405 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-09T21:25:47.74070Z,1326144347.7407 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-09T21:25:47.74080Z,1326144347.7408 [Default:CallIridium] Stopped
2012-01-09T21:25:47.74090Z,1326144347.7409 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-09T21:25:48.55290Z,1326144348.5529 [NAL9601](IMPORTANT): GPS fix at: 1326144365
2012-01-09T21:25:48.56680Z,1326144348.5668 [Default:GPS:Read_GPS] Stopped
2012-01-09T21:25:48.56720Z,1326144348.5672 [Default:GPS](INFO): Completed Default:GPS
2012-01-09T21:25:48.56730Z,1326144348.5673 [Default:GPS] Stopped
2012-01-09T21:25:48.56740Z,1326144348.5674 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-09T21:25:48.56750Z,1326144348.5675 [Default:GPS:A.SetSpeed] Stopped
2012-01-09T21:25:48.56760Z,1326144348.5676 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T21:25:48.94570Z,1326144348.9457 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-09T21:25:48.94580Z,1326144348.9458 [Default:CallGPS:A] Stopped
2012-01-09T21:25:48.94600Z,1326144348.946 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-09T21:25:48.94620Z,1326144348.9462 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-09T21:25:48.94620Z,1326144348.9462 [Default:CallGPS] Stopped
2012-01-09T21:25:48.94650Z,1326144348.9465 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-09T21:26:09.10840Z,1326144369.1084 [NAL9601](INFO): Powering down
2012-01-09T21:30:49.09390Z,1326144649.0939 [Default:CallIridium] Running Loop=1
2012-01-09T21:30:49.09410Z,1326144649.0941 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-09T21:30:49.09440Z,1326144649.0944 [Default:CallIridium:A] Running Loop=1
2012-01-09T21:30:49.09450Z,1326144649.0945 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-09T21:30:49.09470Z,1326144649.0947 [Default:CallGPS] Running Loop=1
2012-01-09T21:30:49.09480Z,1326144649.0948 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-09T21:30:49.09500Z,1326144649.095 [Default:CallGPS:A] Running Loop=1
2012-01-09T21:30:49.09510Z,1326144649.0951 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-09T21:30:54.11330Z,1326144654.1133 [Default:Iridium] Running Loop=1
2012-01-09T21:30:54.11350Z,1326144654.1135 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-09T21:30:54.11360Z,1326144654.1136 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-09T21:30:54.11360Z,1326144654.1136 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-09T21:30:54.11380Z,1326144654.1138 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-09T21:30:54.11390Z,1326144654.1139 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T21:30:54.11460Z,1326144654.1146 [Default:Iridium:B.GoToSurface] Stopped
2012-01-09T21:30:54.11470Z,1326144654.1147 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T21:30:54.11490Z,1326144654.1149 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-09T21:30:54.11520Z,1326144654.1152 [Default:GPS] Running Loop=1
2012-01-09T21:30:54.11540Z,1326144654.1154 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-09T21:30:54.11540Z,1326144654.1154 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-09T21:30:54.11550Z,1326144654.1155 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-09T21:30:54.11570Z,1326144654.1157 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-09T21:30:54.11580Z,1326144654.1158 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T21:30:54.11640Z,1326144654.1164 [Default:GPS:B.GoToSurface] Stopped
2012-01-09T21:30:54.11650Z,1326144654.1165 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T21:30:54.11660Z,1326144654.1166 [Default:GPS:Read_GPS] Running Loop=1
2012-01-09T21:30:54.74700Z,1326144654.747 [NAL9601](INFO): Powering up
2012-01-09T21:32:00.45890Z,1326144720.4589 [NAL9601](INFO): NAL9601 initialized
2012-01-09T21:32:01.53490Z,1326144721.5349 [NAL9601](IMPORTANT): GPS fix at: 1326144739
2012-01-09T21:32:01.54950Z,1326144721.5495 [Default:GPS:Read_GPS] Stopped
2012-01-09T21:32:01.55000Z,1326144721.55 [Default:GPS](INFO): Completed Default:GPS
2012-01-09T21:32:01.55000Z,1326144721.55 [Default:GPS] Stopped
2012-01-09T21:32:01.55020Z,1326144721.5502 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-09T21:32:01.55020Z,1326144721.5502 [Default:GPS:A.SetSpeed] Stopped
2012-01-09T21:32:01.55040Z,1326144721.5504 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T21:32:01.94660Z,1326144721.9466 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-09T21:32:01.94670Z,1326144721.9467 [Default:CallGPS:A] Stopped
2012-01-09T21:32:01.94680Z,1326144721.9468 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-09T21:32:01.94700Z,1326144721.947 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-09T21:32:01.94710Z,1326144721.9471 [Default:CallGPS] Stopped
2012-01-09T21:32:01.94720Z,1326144721.9472 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-09T21:32:02.36740Z,1326144722.3674 [Default:CallGPS] Running Loop=1
2012-01-09T21:32:02.36760Z,1326144722.3676 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-09T21:32:02.36770Z,1326144722.3677 [Default:CallGPS:A] Running Loop=1
2012-01-09T21:32:02.36790Z,1326144722.3679 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-09T21:32:02.78840Z,1326144722.7884 [Default:GPS] Running Loop=1
2012-01-09T21:32:02.78860Z,1326144722.7886 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-09T21:32:02.78870Z,1326144722.7887 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-09T21:32:02.78880Z,1326144722.7888 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-09T21:32:02.78890Z,1326144722.7889 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-09T21:32:02.78900Z,1326144722.789 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T21:32:02.78970Z,1326144722.7897 [Default:GPS:B.GoToSurface] Stopped
2012-01-09T21:32:02.78980Z,1326144722.7898 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T21:32:02.78990Z,1326144722.7899 [Default:GPS:Read_GPS] Running Loop=1
2012-01-09T21:32:17.87340Z,1326144737.8734 [NAL9601](INFO): SBD MO Status=1, MOMSN=40842, MT Status=0, MTMSN=0
2012-01-09T21:32:18.01890Z,1326144738.0189 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0008.lzma
2012-01-09T21:32:18.01910Z,1326144738.0191 [NAL9601](INFO): Packets left to send: 3
2012-01-09T21:32:18.02030Z,1326144738.0203 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000027
2012-01-09T21:32:26.00670Z,1326144746.0067 [NAL9601](INFO): SBD MO Status=1, MOMSN=40843, MT Status=0, MTMSN=0
2012-01-09T21:32:26.21110Z,1326144746.2111 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0008.lzma
2012-01-09T21:32:26.21130Z,1326144746.2113 [NAL9601](INFO): Packets left to send: 2
2012-01-09T21:32:26.21250Z,1326144746.2125 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000028
2012-01-09T21:32:33.66530Z,1326144753.6653 [NAL9601](INFO): SBD MO Status=1, MOMSN=40844, MT Status=0, MTMSN=0
2012-01-09T21:32:33.79500Z,1326144753.795 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0008.lzma
2012-01-09T21:32:33.79520Z,1326144753.7952 [NAL9601](INFO): Packets left to send: 1
2012-01-09T21:32:33.79640Z,1326144753.7964 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000029
2012-01-09T21:32:40.16950Z,1326144760.1695 [NAL9601](INFO): SBD MO Status=1, MOMSN=40845, MT Status=0, MTMSN=0
2012-01-09T21:32:40.38290Z,1326144760.3829 [NAL9601](INFO): Sent 128 bytes from file Logs/20120109T201340/shore0008.lzma
2012-01-09T21:32:40.38310Z,1326144760.3831 [NAL9601](INFO): Packets left to send: 0
2012-01-09T21:32:40.38440Z,1326144760.3844 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000030
2012-01-09T21:32:47.36460Z,1326144767.3646 [NAL9601](INFO): SBD MO Status=0, MOMSN=40846, MT Status=0, MTMSN=0
2012-01-09T21:32:47.58780Z,1326144767.5878 [Default:Iridium:Read_Iridium] Stopped
2012-01-09T21:32:47.58830Z,1326144767.5883 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-09T21:32:47.58840Z,1326144767.5884 [Default:Iridium] Stopped
2012-01-09T21:32:47.58850Z,1326144767.5885 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-09T21:32:47.58860Z,1326144767.5886 [Default:Iridium:A.SetSpeed] Stopped
2012-01-09T21:32:47.58870Z,1326144767.5887 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T21:32:47.83350Z,1326144767.8335 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-09T21:32:47.83360Z,1326144767.8336 [Default:CallIridium:A] Stopped
2012-01-09T21:32:47.83390Z,1326144767.8339 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-09T21:32:47.83410Z,1326144767.8341 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-09T21:32:47.83420Z,1326144767.8342 [Default:CallIridium] Stopped
2012-01-09T21:32:47.84640Z,1326144767.8464 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-09T21:32:48.60690Z,1326144768.6069 [NAL9601](IMPORTANT): GPS fix at: 1326144786
2012-01-09T21:32:48.62070Z,1326144768.6207 [Default:GPS:Read_GPS] Stopped
2012-01-09T21:32:48.62120Z,1326144768.6212 [Default:GPS](INFO): Completed Default:GPS
2012-01-09T21:32:48.62130Z,1326144768.6213 [Default:GPS] Stopped
2012-01-09T21:32:48.62140Z,1326144768.6214 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-09T21:32:48.62150Z,1326144768.6215 [Default:GPS:A.SetSpeed] Stopped
2012-01-09T21:32:48.62160Z,1326144768.6216 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T21:32:49.01760Z,1326144769.0176 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-09T21:32:49.01770Z,1326144769.0177 [Default:CallGPS:A] Stopped
2012-01-09T21:32:49.01780Z,1326144769.0178 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-09T21:32:49.01800Z,1326144769.018 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-09T21:32:49.01810Z,1326144769.0181 [Default:CallGPS] Stopped
2012-01-09T21:32:49.01820Z,1326144769.0182 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-09T21:33:09.13000Z,1326144789.13 [NAL9601](INFO): Powering down
2012-01-09T21:37:49.34210Z,1326145069.3421 [Default:CallIridium] Running Loop=1
2012-01-09T21:37:49.34640Z,1326145069.3464 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-09T21:37:49.34660Z,1326145069.3466 [Default:CallIridium:A] Running Loop=1
2012-01-09T21:37:49.34670Z,1326145069.3467 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-09T21:37:49.34690Z,1326145069.3469 [Default:CallGPS] Running Loop=1
2012-01-09T21:37:49.34700Z,1326145069.347 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-09T21:37:49.34720Z,1326145069.3472 [Default:CallGPS:A] Running Loop=1
2012-01-09T21:37:49.34730Z,1326145069.3473 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-09T21:37:54.23080Z,1326145074.2308 [Default:Iridium] Running Loop=1
2012-01-09T21:37:54.23100Z,1326145074.231 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-09T21:37:54.23110Z,1326145074.2311 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-09T21:37:54.23120Z,1326145074.2312 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-09T21:37:54.23130Z,1326145074.2313 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-09T21:37:54.23140Z,1326145074.2314 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T21:37:54.23210Z,1326145074.2321 [Default:Iridium:B.GoToSurface] Stopped
2012-01-09T21:37:54.23220Z,1326145074.2322 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T21:37:54.23230Z,1326145074.2323 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-09T21:37:54.23270Z,1326145074.2327 [Default:GPS] Running Loop=1
2012-01-09T21:37:54.23280Z,1326145074.2328 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-09T21:37:54.23290Z,1326145074.2329 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-09T21:37:54.23300Z,1326145074.233 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-09T21:37:54.23310Z,1326145074.2331 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-09T21:37:54.23320Z,1326145074.2332 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T21:37:54.23380Z,1326145074.2338 [Default:GPS:B.GoToSurface] Stopped
2012-01-09T21:37:54.23390Z,1326145074.2339 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T21:37:54.23410Z,1326145074.2341 [Default:GPS:Read_GPS] Running Loop=1
2012-01-09T21:37:54.94800Z,1326145074.948 [NAL9601](INFO): Powering up
2012-01-09T21:39:00.65890Z,1326145140.6589 [NAL9601](INFO): NAL9601 initialized
2012-01-09T21:39:16.41730Z,1326145156.4173 [NAL9601](INFO): SBD MO Status=1, MOMSN=40847, MT Status=0, MTMSN=0
2012-01-09T21:39:16.62530Z,1326145156.6253 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0009.lzma
2012-01-09T21:39:16.62550Z,1326145156.6255 [NAL9601](INFO): Packets left to send: 1
2012-01-09T21:39:16.62670Z,1326145156.6267 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000031
2012-01-09T21:39:28.89750Z,1326145168.8975 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=40848, MT Status=1, MTMSN=3394
2012-01-09T21:39:29.10700Z,1326145169.107 [NAL9601](INFO): Sent 167 bytes from file Logs/20120109T201340/shore0009.lzma
2012-01-09T21:39:29.10720Z,1326145169.1072 [NAL9601](INFO): Packets left to send: 0
2012-01-09T21:39:29.10830Z,1326145169.1083 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000032
2012-01-09T21:39:29.55970Z,1326145169.5597 [NAL9601](INFO): Received command:load Engineering/Homing_altitude.xml;set homing_altitude.finalApproach 0.01 meter;run 
2012-01-09T21:39:29.58270Z,1326145169.5827 [CommandLine](IMPORTANT): got command load ./Missions/Engineering/Homing_altitude.xml
2012-01-09T21:39:29.58300Z,1326145169.583 [MissionManager](INFO): Loading Mission: ./Missions/Engineering/Homing_altitude.xml
2012-01-09T21:39:29.65850Z,1326145169.6585 [MissionManager](INFO): DefineArg homing_altitude.Wpt1Lat = 36.823 arcdeg
2012-01-09T21:39:29.66160Z,1326145169.6616 [MissionManager](INFO): DefineArg homing_altitude.Wpt1Lon = -121.83 arcdeg
2012-01-09T21:39:29.66460Z,1326145169.6646 [MissionManager](INFO): DefineArg homing_altitude.Altitude = 10 m
2012-01-09T21:39:29.66760Z,1326145169.6676 [MissionManager](INFO): DefineArg homing_altitude.Speed = 1 m/s
2012-01-09T21:39:29.67100Z,1326145169.671 [MissionManager](INFO): DefineArg homing_altitude.MassDefault = 0.0015 n/a
2012-01-09T21:39:29.67420Z,1326145169.6742 [MissionManager](INFO): DefineArg homing_altitude.BuoyancyNeutral = 0.000418 n/a
2012-01-09T21:39:29.67720Z,1326145169.6772 [MissionManager](INFO): DefineArg homing_altitude.dockBearing = 10 arcdeg
2012-01-09T21:39:29.68020Z,1326145169.6802 [MissionManager](INFO): DefineArg homing_altitude.inTrkOffset = 0 m
2012-01-09T21:39:29.68320Z,1326145169.6832 [MissionManager](INFO): DefineArg homing_altitude.xTrkOffset = 0 m
2012-01-09T21:39:29.68620Z,1326145169.6862 [MissionManager](INFO): DefineArg homing_altitude.finalApproach = 200 m
2012-01-09T21:39:29.68930Z,1326145169.6893 [MissionManager](INFO): DefineArg homing_altitude.clusterRadius = 20 m
2012-01-09T21:39:29.69250Z,1326145169.6925 [MissionManager](INFO): DefineArg homing_altitude.TimeoutDuration = 40 min
2012-01-09T21:39:29.69560Z,1326145169.6956 [MissionManager](INFO): DefineArg homing_altitude.kpAltitude = -0.08 n/a
2012-01-09T21:39:29.69870Z,1326145169.6987 [MissionManager](INFO): DefineArg homing_altitude.kiAltitude = 0 n/a
2012-01-09T21:39:29.70170Z,1326145169.7017 [MissionManager](INFO): DefineArg homing_altitude.kdAltitude = 0 n/a
2012-01-09T21:39:29.70340Z,1326145169.7034 [homing_altitude:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-01-09T21:39:29.71090Z,1326145169.7109 [homing_altitude:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-01-09T21:39:29.71900Z,1326145169.719 [homing_altitude:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2012-01-09T21:39:29.72800Z,1326145169.728 [MissionManager](INFO): Inserting Stack: Missions/Insert/Surface.xml
2012-01-09T21:39:29.74870Z,1326145169.7487 [MissionManager](INFO): DefineArg homing_altitude:SURFACECOMMS.SurfaceDepthRate = nan m/s
2012-01-09T21:39:29.75180Z,1326145169.7518 [MissionManager](INFO): DefineArg homing_altitude:SURFACECOMMS.SurfacePitch = nan arcdeg
2012-01-09T21:39:29.75480Z,1326145169.7548 [MissionManager](INFO): DefineArg homing_altitude:SURFACECOMMS.SurfaceSpeed = 0.5 m/s
2012-01-09T21:39:29.75780Z,1326145169.7578 [MissionManager](INFO): DefineArg homing_altitude:SURFACECOMMS.IridiumTimeout = 30 min
2012-01-09T21:39:29.75910Z,1326145169.7591 [homing_altitude:SURFACECOMMS:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-01-09T21:39:29.77020Z,1326145169.7702 [homing_altitude:WaypointOne:A.Pitch](DEBUG): Construct.
2012-01-09T21:39:29.77850Z,1326145169.7785 [homing_altitude:WaypointOne:B.Buoyancy](DEBUG): Construct Buoyancy.
2012-01-09T21:39:29.78250Z,1326145169.7825 [homing_altitude:WaypointOne:C.SetSpeed](DEBUG): Construct.
2012-01-09T21:39:29.78600Z,1326145169.786 [homing_altitude:WaypointOne:D.PitchServo](DEBUG): Construct.
2012-01-09T21:39:29.79390Z,1326145169.7939 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Construct Waypoint.
2012-01-09T21:39:29.79820Z,1326145169.7982 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Construct Homing.
2012-01-09T21:39:29.82080Z,1326145169.8208 [homing_altitude:H.Execute](DEBUG): Construct Execute.
2012-01-09T21:39:29.82980Z,1326145169.8298 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="homing_altitude">

<!-- Wpt1 d=74m; Wpt2 d=75m; Wpt3 d=77m -->

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

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

    <DefineArg Name="Altitude"><Units:meter/><Value>10</Value></DefineArg>

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

    <DefineArg Name="MassDefault"><CustomUri Uri="Config/Control.massDefault"/></DefineArg>

    <DefineArg Name="BuoyancyNeutral"><CustomUri Uri="Config/Control.buoyancyNeutral"/></DefineArg>

    <DefineArg Name="dockBearing"><Units:degree/><Value>10</Value></DefineArg>

    <DefineArg Name="inTrkOffset"><Units:meter/><Value>0</Value></DefineArg>

    <DefineArg Name="xTrkOffset"><Units:meter/><Value>0</Value></DefineArg>

    <DefineArg Name="finalApproach"><Units:meter/><Value>200</Value></DefineArg>

    <DefineArg Name="clusterRadius"><Units:meter/><Value>20</Value></DefineArg>

    <DefineArg Name="TimeoutDuration"><Description>
        Maximum length of mission
    </Description><Units:minute/><Value>40</Value></DefineArg>

    <DefineArg Name="kpAltitude"><Description>
        PID loop parameter for following the bottom.
    </Description><Units:none/><Value>-0.08</Value></DefineArg>

    <DefineArg Name="kiAltitude"><Description>
        PID loop parameter for following the bottom.
    </Description><Units:none/><Value>0</Value></DefineArg>

    <DefineArg Name="kdAltitude"><Description>
        PID loop parameter for following the bottom.
    </Description><Units:none/><Value>0</Value></DefineArg>

    <Timeout Duration="TimeoutDuration"/>

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

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

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

    <ReadData Strategy="AllDevices">
        <Universal:platform_orientation/>
    </ReadData>

    <Insert Filename="Insert/Surface.xml" Id="SURFACECOMMS" />

    <Aggregate Id="WaypointOne">

<!-- Home to Wpt1  -->

        <Guidance:Pitch RunIn="Parallel">
            <Setting><Guidance:Pitch.massPosition/><Arg Name="MassDefault"/></Setting>
        </Guidance:Pitch>

        <Guidance:Buoyancy RunIn="Parallel">
            <Setting><Guidance:Buoyancy.position /><Arg Name="BuoyancyNeutral"/></Setting>
        </Guidance:Buoyancy>

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

        <Guidance:PitchServo RunIn="Parallel">
            <Setting>
            <Guidance:PitchServo.uri/><Universal:height_above_sea_floor/></Setting>
            <Setting><Guidance:PitchServo.holdValue/><Arg Name="Altitude"/></Setting>
            <Setting><Guidance:PitchServo.proportionalGain/><Arg Name="kpAltitude"/></Setting>
            <Setting><Guidance:PitchServo.integralGain/><Arg Name="kiAltitude"/></Setting>
            <Setting><Guidance:PitchServo.derivativeGain/><Arg Name="kdAltitude"/></Setting>
            <Setting><Guidance:PitchServo.changePerMeter/><Units:meter/><Value>-1</Value></Setting>
        </Guidance:PitchServo>

        <Guidance:Homing Id="WaypointW1" RunIn="Sequence">
            <Setting><Guidance:Homing.dockBearing/><Arg Name="dockBearing"/></Setting>
            <Setting><Guidance:Homing.inTrkOffset/><Arg Name="inTrkOffset"/></Setting>
            <Setting><Guidance:Homing.xTrkOffset/><Arg Name="xTrkOffset"/></Setting>
            <Setting><Guidance:Homing.finalApproach/><Arg Name="finalApproach"/></Setting>
            <Setting><Guidance:Homing.clusterRadius/><Arg Name="clusterRadius"/></Setting>
            <Setting><Guidance:Homing.latitude/><Arg Name="Wpt1Lat"/></Setting>
            <Setting><Guidance:Homing.longitude/><Arg Name="Wpt1Lon"/></Setting>
        </Guidance:Homing>

    </Aggregate>

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

    <Guidance:Execute RunIn="Sequence">
        <Setting>
        <Guidance:Execute.command/><String>restart logs</String></Setting>
    </Guidance:Execute>

</Mission>


2012-01-09T21:39:29.83040Z,1326145169.8304 [CommandLine](IMPORTANT): Loaded ./Missions/Engineering/Homing_altitude.xml
2012-01-09T21:39:29.94500Z,1326145169.945 [CommandLine](IMPORTANT): got command set homing_altitude.finalApproach 0.009999999776 meter
2012-01-09T21:39:29.94640Z,1326145169.9464 [CommandLine](IMPORTANT): got command run 
2012-01-09T21:39:29.94660Z,1326145169.9466 [CommandLine](IMPORTANT): Running 
2012-01-09T21:39:29.96170Z,1326145169.9617 [Default] Stopped
2012-01-09T21:39:29.96190Z,1326145169.9619 [Default](INFO): Aggregate::uninitialize Default
2012-01-09T21:39:29.96200Z,1326145169.962 [Default:GPS] Stopped
2012-01-09T21:39:29.96210Z,1326145169.9621 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-09T21:39:29.96220Z,1326145169.9622 [Default:GPS:A.SetSpeed] Stopped
2012-01-09T21:39:29.96230Z,1326145169.9623 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T21:39:29.96240Z,1326145169.9624 [Default:GPS:Read_GPS] Stopped
2012-01-09T21:39:29.96240Z,1326145169.9624 [Default:Iridium] Stopped
2012-01-09T21:39:29.96260Z,1326145169.9626 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-09T21:39:29.96260Z,1326145169.9626 [Default:Iridium:A.SetSpeed] Stopped
2012-01-09T21:39:29.96270Z,1326145169.9627 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-09T21:39:29.96280Z,1326145169.9628 [Default:Iridium:Read_Iridium] Stopped
2012-01-09T21:39:29.96280Z,1326145169.9628 [Default:CallGPS] Stopped
2012-01-09T21:39:29.96300Z,1326145169.963 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-09T21:39:29.96300Z,1326145169.963 [Default:CallGPS:A] Stopped
2012-01-09T21:39:29.96320Z,1326145169.9632 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-09T21:39:29.96320Z,1326145169.9632 [Default:CallIridium] Stopped
2012-01-09T21:39:29.96340Z,1326145169.9634 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-09T21:39:29.96340Z,1326145169.9634 [Default:CallIridium:A] Stopped
2012-01-09T21:39:29.96360Z,1326145169.9636 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-09T21:39:29.96360Z,1326145169.9636 [Default:E.SetSpeed] Stopped
2012-01-09T21:39:29.96370Z,1326145169.9637 [Default:E.SetSpeed](DEBUG): Uninitialize.
2012-01-09T21:39:29.96380Z,1326145169.9638 [Default:F.GoToSurface] Stopped
2012-01-09T21:39:29.96380Z,1326145169.9638 [Default:F.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T21:39:29.96390Z,1326145169.9639 [Default:G.Wait] Stopped
2012-01-09T21:39:29.96400Z,1326145169.964 [Default:G.Wait](DEBUG): Uninitialize Wait Component.
2012-01-09T21:39:29.96410Z,1326145169.9641 [MissionManager](IMPORTANT): Started mission homing_altitude
2012-01-09T21:39:29.96430Z,1326145169.9643 [homing_altitude] Running Loop=1
2012-01-09T21:39:29.96440Z,1326145169.9644 [homing_altitude](INFO): Aggregate::initialize homing_altitude
2012-01-09T21:39:29.96450Z,1326145169.9645 [homing_altitude:A.AltitudeEnvelope] Running Loop=1
2012-01-09T21:39:29.96460Z,1326145169.9646 [homing_altitude:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-01-09T21:39:29.96470Z,1326145169.9647 [homing_altitude:B.DepthEnvelope] Running Loop=1
2012-01-09T21:39:29.96480Z,1326145169.9648 [homing_altitude:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-01-09T21:39:29.96610Z,1326145169.9661 [homing_altitude:C.OffshoreEnvelope] Running Loop=1
2012-01-09T21:39:29.96620Z,1326145169.9662 [homing_altitude:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2012-01-09T21:39:29.96630Z,1326145169.9663 [homing_altitude:D] Running Loop=1
2012-01-09T21:39:29.96660Z,1326145169.9666 [homing_altitude:SURFACECOMMS] Running Loop=1
2012-01-09T21:39:29.96670Z,1326145169.9667 [homing_altitude:SURFACECOMMS](INFO): Aggregate::initialize homing_altitude:SURFACECOMMS
2012-01-09T21:39:29.96680Z,1326145169.9668 [homing_altitude:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-01-09T21:39:29.96690Z,1326145169.9669 [homing_altitude:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T21:39:29.97230Z,1326145169.9723 [homing_altitude:SURFACECOMMS:B] Running Loop=1
2012-01-09T21:39:29.97250Z,1326145169.9725 [homing_altitude:SURFACECOMMS:B](INFO): Aggregate::initialize homing_altitude:SURFACECOMMS:B
2012-01-09T21:39:29.97270Z,1326145169.9727 [homing_altitude:SURFACECOMMS:B:A] Running Loop=1
2012-01-09T21:39:29.97280Z,1326145169.9728 [homing_altitude:D] Running Loop=1
2012-01-09T21:39:29.97350Z,1326145169.9735 [homing_altitude:D](DEBUG): Initialize ReadDataComponent to sense platform_orientation
2012-01-09T21:39:29.97490Z,1326145169.9749 [homing_altitude:C.OffshoreEnvelope] Running Loop=1
2012-01-09T21:39:29.97960Z,1326145169.9796 [homing_altitude:B.DepthEnvelope] Running Loop=1
2012-01-09T21:39:29.98420Z,1326145169.9842 [homing_altitude:A.AltitudeEnvelope] Running Loop=1
2012-01-09T21:39:30.72090Z,1326145170.7209 [homing_altitude:SURFACECOMMS:B:A](DEBUG): Initialize ReadDataComponent to sense time_fix
2012-01-09T21:39:46.69950Z,1326145186.6995 [NAL9601](IMPORTANT): GPS fix at: 1326145205
2012-01-09T21:39:46.71290Z,1326145186.7129 [homing_altitude:SURFACECOMMS:B:A] Stopped
2012-01-09T21:39:46.71320Z,1326145186.7132 [homing_altitude:SURFACECOMMS:B:B] Running Loop=1
2012-01-09T21:39:47.11990Z,1326145187.1199 [homing_altitude:SURFACECOMMS:B:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-01-09T21:39:53.75040Z,1326145193.7504 [NAL9601](INFO): SBD MO Status=0, MOMSN=40849, MT Status=0, MTMSN=0
2012-01-09T21:40:13.30520Z,1326145213.3052 [NAL9601](INFO): SBD MO Status=1, MOMSN=40850, MT Status=0, MTMSN=0
2012-01-09T21:40:13.43490Z,1326145213.4349 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0010.lzma
2012-01-09T21:40:13.43510Z,1326145213.4351 [NAL9601](INFO): Packets left to send: 1
2012-01-09T21:40:13.43650Z,1326145213.4365 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000033
2012-01-09T21:40:21.39240Z,1326145221.3924 [NAL9601](INFO): SBD MO Status=1, MOMSN=40851, MT Status=0, MTMSN=0
2012-01-09T21:40:21.52290Z,1326145221.5229 [NAL9601](INFO): Sent 171 bytes from file Logs/20120109T201340/shore0010.lzma
2012-01-09T21:40:21.52310Z,1326145221.5231 [NAL9601](INFO): Packets left to send: 0
2012-01-09T21:40:21.52430Z,1326145221.5243 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000034
2012-01-09T21:40:28.21460Z,1326145228.2146 [NAL9601](INFO): SBD MO Status=0, MOMSN=40852, MT Status=0, MTMSN=0
2012-01-09T21:40:28.42400Z,1326145228.424 [homing_altitude:SURFACECOMMS:B:B] Stopped
2012-01-09T21:40:28.42410Z,1326145228.4241 [homing_altitude:SURFACECOMMS:B:C] Running Loop=1
2012-01-09T21:40:28.66320Z,1326145228.6632 [homing_altitude:SURFACECOMMS:B:C](DEBUG): Initialize ReadDataComponent to sense time_fix
2012-01-09T21:40:30.59900Z,1326145230.599 [NAL9601](IMPORTANT): GPS fix at: 1326145249
2012-01-09T21:40:30.61300Z,1326145230.613 [homing_altitude:SURFACECOMMS:B:C] Stopped
2012-01-09T21:40:30.61320Z,1326145230.6132 [homing_altitude:SURFACECOMMS:B](INFO): Completed homing_altitude:SURFACECOMMS:B
2012-01-09T21:40:30.61330Z,1326145230.6133 [homing_altitude:SURFACECOMMS:B] Stopped
2012-01-09T21:40:30.61350Z,1326145230.6135 [homing_altitude:SURFACECOMMS:B](INFO): Aggregate::uninitialize homing_altitude:SURFACECOMMS:B
2012-01-09T21:40:30.61400Z,1326145230.614 [homing_altitude:SURFACECOMMS](INFO): Completed homing_altitude:SURFACECOMMS
2012-01-09T21:40:30.61410Z,1326145230.6141 [homing_altitude:SURFACECOMMS] Stopped
2012-01-09T21:40:30.61430Z,1326145230.6143 [homing_altitude:SURFACECOMMS](INFO): Aggregate::uninitialize homing_altitude:SURFACECOMMS
2012-01-09T21:40:30.61440Z,1326145230.6144 [homing_altitude:SURFACECOMMS:A.GoToSurface] Stopped
2012-01-09T21:40:30.61450Z,1326145230.6145 [homing_altitude:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T21:40:30.61460Z,1326145230.6146 [homing_altitude:WaypointOne] Running Loop=1
2012-01-09T21:40:30.61480Z,1326145230.6148 [homing_altitude:WaypointOne](INFO): Aggregate::initialize homing_altitude:WaypointOne
2012-01-09T21:40:30.61490Z,1326145230.6149 [homing_altitude:WaypointOne:A.Pitch] Running Loop=1
2012-01-09T21:40:30.61490Z,1326145230.6149 [homing_altitude:WaypointOne:A.Pitch](DEBUG): Initialize.
2012-01-09T21:40:30.61510Z,1326145230.6151 [homing_altitude:WaypointOne:B.Buoyancy] Running Loop=1
2012-01-09T21:40:30.61520Z,1326145230.6152 [homing_altitude:WaypointOne:B.Buoyancy](DEBUG): Initialize Buoyancy Component.
2012-01-09T21:40:30.61570Z,1326145230.6157 [homing_altitude:WaypointOne:C.SetSpeed] Running Loop=1
2012-01-09T21:40:30.61580Z,1326145230.6158 [homing_altitude:WaypointOne:C.SetSpeed](DEBUG): Initialize.
2012-01-09T21:40:30.61590Z,1326145230.6159 [homing_altitude:WaypointOne:D.PitchServo] Running Loop=1
2012-01-09T21:40:30.61590Z,1326145230.6159 [homing_altitude:WaypointOne:D.PitchServo](DEBUG): Initialize.
2012-01-09T21:40:30.61620Z,1326145230.6162 [homing_altitude:WaypointOne:D.PitchServo](INFO): Initialize with holdValue=height_above_sea_floor
2012-01-09T21:40:30.61710Z,1326145230.6171 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint] Running Loop=1
2012-01-09T21:40:30.61720Z,1326145230.6172 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Initialize HomingComponent.
2012-01-09T21:40:30.61740Z,1326145230.6174 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Initialize WaypointComponent.
2012-01-09T21:40:31.04080Z,1326145231.0408 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Homing:: Beacon is in the DAT FOV with dtw = 756.98. Turning DAT on.
2012-01-09T21:40:31.04620Z,1326145231.0462 [homing_altitude:WaypointOne:D.PitchServo] Running Loop=1
2012-01-09T21:40:31.07390Z,1326145231.0739 [homing_altitude:WaypointOne:C.SetSpeed] Running Loop=1
2012-01-09T21:40:31.07850Z,1326145231.0785 [homing_altitude:WaypointOne:B.Buoyancy] Running Loop=1
2012-01-09T21:40:31.08310Z,1326145231.0831 [homing_altitude:WaypointOne:A.Pitch] Running Loop=1
2012-01-09T21:40:31.40130Z,1326145231.4013 [DAT](INFO): Powering up
2012-01-09T21:40:37.03060Z,1326145237.0306 [NAL9601](INFO): Powering down
2012-01-09T21:40:58.35040Z,1326145258.3504 [DAT](ERROR): No response from remote modem
2012-01-09T21:41:10.81440Z,1326145270.8144 [DAT](ERROR): No response from remote modem
2012-01-09T21:41:23.23850Z,1326145283.2385 [DAT](ERROR): No response from remote modem
2012-01-09T21:41:36.05440Z,1326145296.0544 [DAT](ERROR): No response from remote modem
2012-01-09T21:41:48.83840Z,1326145308.8384 [DAT](ERROR): No response from remote modem
2012-01-09T21:42:01.22660Z,1326145321.2266 [DAT](ERROR): No response from remote modem
2012-01-09T21:42:14.13840Z,1326145334.1384 [DAT](ERROR): No response from remote modem
2012-01-09T21:42:26.93440Z,1326145346.9344 [DAT](ERROR): No response from remote modem
2012-01-09T21:42:39.33850Z,1326145359.3385 [DAT](ERROR): No response from remote modem
2012-01-09T21:42:52.15840Z,1326145372.1584 [DAT](ERROR): No response from remote modem
2012-01-09T21:43:04.61840Z,1326145384.6184 [DAT](ERROR): No response from remote modem
2012-01-09T21:43:17.41840Z,1326145397.4184 [DAT](ERROR): No response from remote modem
2012-01-09T21:43:29.87450Z,1326145409.8745 [DAT](ERROR): No response from remote modem
2012-01-09T21:43:42.63840Z,1326145422.6384 [DAT](ERROR): No response from remote modem
2012-01-09T21:43:55.05840Z,1326145435.0584 [DAT](ERROR): No response from remote modem
2012-01-09T21:44:07.81840Z,1326145447.8184 [DAT](ERROR): No response from remote modem
2012-01-09T21:44:20.25850Z,1326145460.2585 [DAT](ERROR): No response from remote modem
2012-01-09T21:44:32.78240Z,1326145472.7824 [DAT](ERROR): No response from remote modem
2012-01-09T21:44:45.62640Z,1326145485.6264 [DAT](ERROR): No response from remote modem
2012-01-09T21:44:57.99840Z,1326145497.9984 [DAT](ERROR): No response from remote modem
2012-01-09T21:45:10.41850Z,1326145510.4185 [DAT](ERROR): No response from remote modem
2012-01-09T21:45:22.83840Z,1326145522.8384 [DAT](ERROR): No response from remote modem
2012-01-09T21:45:35.63840Z,1326145535.6384 [DAT](ERROR): No response from remote modem
2012-01-09T21:45:48.43040Z,1326145548.4304 [DAT](ERROR): No response from remote modem
2012-01-09T21:46:01.25450Z,1326145561.2545 [DAT](ERROR): No response from remote modem
2012-01-09T21:46:13.62470Z,1326145573.6247 [DAT](ERROR): No response from remote modem
2012-01-09T21:46:26.04240Z,1326145586.0424 [DAT](ERROR): No response from remote modem
2012-01-09T21:46:38.87040Z,1326145598.8704 [DAT](ERROR): No response from remote modem
2012-01-09T21:46:51.63640Z,1326145611.6364 [DAT](ERROR): No response from remote modem
2012-01-09T21:47:04.43440Z,1326145624.4344 [DAT](ERROR): No response from remote modem
2012-01-09T21:47:16.81840Z,1326145636.8184 [DAT](ERROR): No response from remote modem
2012-01-09T21:47:29.39040Z,1326145649.3904 [DAT](ERROR): No response from remote modem
2012-01-09T21:47:42.19040Z,1326145662.1904 [DAT](ERROR): No response from remote modem
2012-01-09T21:47:54.57840Z,1326145674.5784 [DAT](ERROR): No response from remote modem
2012-01-09T21:48:07.01040Z,1326145687.0104 [DAT](ERROR): No response from remote modem
2012-01-09T21:48:19.38240Z,1326145699.3824 [DAT](ERROR): No response from remote modem
2012-01-09T21:48:32.17440Z,1326145712.1744 [DAT](ERROR): No response from remote modem
2012-01-09T21:48:45.10240Z,1326145725.1024 [DAT](ERROR): No response from remote modem
2012-01-09T21:48:57.77440Z,1326145737.7744 [DAT](ERROR): No response from remote modem
2012-01-09T21:49:10.57440Z,1326145750.5744 [DAT](ERROR): No response from remote modem
2012-01-09T21:49:23.07440Z,1326145763.0744 [DAT](ERROR): No response from remote modem
2012-01-09T21:49:35.84640Z,1326145775.8464 [DAT](ERROR): No response from remote modem
2012-01-09T21:49:48.23840Z,1326145788.2384 [DAT](ERROR): No response from remote modem
2012-01-09T21:50:00.65040Z,1326145800.6504 [DAT](ERROR): No response from remote modem
2012-01-09T21:50:13.14640Z,1326145813.1464 [DAT](ERROR): No response from remote modem
2012-01-09T21:50:25.53050Z,1326145825.5305 [DAT](ERROR): No response from remote modem
2012-01-09T21:50:38.32240Z,1326145838.3224 [DAT](ERROR): No response from remote modem
2012-01-09T21:50:50.78650Z,1326145850.7865 [DAT](ERROR): No response from remote modem
2012-01-09T21:51:03.61840Z,1326145863.6184 [DAT](ERROR): No response from remote modem
2012-01-09T21:51:16.45860Z,1326145876.4586 [DAT](ERROR): No response from remote modem
2012-01-09T21:51:29.21040Z,1326145889.2104 [DAT](ERROR): No response from remote modem
2012-01-09T21:51:42.01440Z,1326145902.0144 [DAT](ERROR): No response from remote modem
2012-01-09T21:51:54.45060Z,1326145914.4506 [DAT](ERROR): No response from remote modem
2012-01-09T21:52:07.23850Z,1326145927.2385 [DAT](ERROR): No response from remote modem
2012-01-09T21:52:19.63840Z,1326145939.6384 [DAT](ERROR): No response from remote modem
2012-01-09T21:52:32.41850Z,1326145952.4185 [DAT](ERROR): No response from remote modem
2012-01-09T21:52:45.22640Z,1326145965.2264 [DAT](ERROR): No response from remote modem
2012-01-09T21:52:58.02640Z,1326145978.0264 [DAT](ERROR): No response from remote modem
2012-01-09T21:53:10.84240Z,1326145990.8424 [DAT](ERROR): No response from remote modem
2012-01-09T21:53:23.92640Z,1326146003.9264 [DAT](ERROR): No response from remote modem
2012-01-09T21:53:36.30250Z,1326146016.3025 [DAT](ERROR): No response from remote modem
2012-01-09T21:53:49.09860Z,1326146029.0986 [DAT](ERROR): No response from remote modem
2012-01-09T21:54:01.81040Z,1326146041.8104 [DAT](ERROR): No response from remote modem
2012-01-09T21:54:14.55840Z,1326146054.5584 [DAT](ERROR): No response from remote modem
2012-01-09T21:54:27.40640Z,1326146067.4064 [DAT](ERROR): No response from remote modem
2012-01-09T21:54:39.87840Z,1326146079.8784 [DAT](ERROR): No response from remote modem
2012-01-09T21:54:52.27840Z,1326146092.2784 [DAT](ERROR): No response from remote modem
2012-01-09T21:55:04.66640Z,1326146104.6664 [DAT](ERROR): No response from remote modem
2012-01-09T21:55:17.50350Z,1326146117.5035 [DAT](ERROR): No response from remote modem
2012-01-09T21:55:30.23440Z,1326146130.2344 [DAT](ERROR): No response from remote modem
2012-01-09T21:55:43.01440Z,1326146143.0144 [DAT](ERROR): No response from remote modem
2012-01-09T21:55:55.43440Z,1326146155.4344 [DAT](ERROR): No response from remote modem
2012-01-09T21:56:07.85040Z,1326146167.8504 [DAT](ERROR): No response from remote modem
2012-01-09T21:56:20.38250Z,1326146180.3825 [DAT](ERROR): No response from remote modem
2012-01-09T21:56:33.07050Z,1326146193.0705 [DAT](ERROR): No response from remote modem
2012-01-09T21:56:45.45840Z,1326146205.4584 [DAT](ERROR): No response from remote modem
2012-01-09T21:56:58.26240Z,1326146218.2624 [DAT](ERROR): No response from remote modem
2012-01-09T21:56:59.38860Z,1326146219.3886 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](IMPORTANT): Homing:: Terminating now. dtw = -0.0 m, DATRange = nan m.
2012-01-09T21:56:59.38920Z,1326146219.3892 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](INFO): Homing::Reached Waypoint 36.823,-121.83
2012-01-09T21:56:59.38940Z,1326146219.3894 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint] Stopped
2012-01-09T21:56:59.38950Z,1326146219.3895 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Uninitialize HomingComponent.
2012-01-09T21:56:59.39090Z,1326146219.3909 [homing_altitude:WaypointOne](INFO): Completed homing_altitude:WaypointOne
2012-01-09T21:56:59.39100Z,1326146219.391 [homing_altitude:WaypointOne] Stopped
2012-01-09T21:56:59.39120Z,1326146219.3912 [homing_altitude:WaypointOne](INFO): Aggregate::uninitialize homing_altitude:WaypointOne
2012-01-09T21:56:59.39130Z,1326146219.3913 [homing_altitude:WaypointOne:A.Pitch] Stopped
2012-01-09T21:56:59.39130Z,1326146219.3913 [homing_altitude:WaypointOne:B.Buoyancy] Stopped
2012-01-09T21:56:59.39140Z,1326146219.3914 [homing_altitude:WaypointOne:B.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2012-01-09T21:56:59.39140Z,1326146219.3914 [homing_altitude:WaypointOne:C.SetSpeed] Stopped
2012-01-09T21:56:59.39150Z,1326146219.3915 [homing_altitude:WaypointOne:C.SetSpeed](DEBUG): Uninitialize.
2012-01-09T21:56:59.39160Z,1326146219.3916 [homing_altitude:WaypointOne:D.PitchServo] Stopped
2012-01-09T21:56:59.39160Z,1326146219.3916 [homing_altitude:WaypointOne:D.PitchServo](DEBUG): Uninitialize.
2012-01-09T21:56:59.39180Z,1326146219.3918 [homing_altitude:PHONEHOMEWPT1] Running Loop=1
2012-01-09T21:56:59.39190Z,1326146219.3919 [homing_altitude:PHONEHOMEWPT1](INFO): Aggregate::initialize homing_altitude:PHONEHOMEWPT1
2012-01-09T21:56:59.80090Z,1326146219.8009 [homing_altitude:SURFACECOMMS] Running Loop=1
2012-01-09T21:56:59.80110Z,1326146219.8011 [homing_altitude:SURFACECOMMS](INFO): Aggregate::initialize homing_altitude:SURFACECOMMS
2012-01-09T21:56:59.80120Z,1326146219.8012 [homing_altitude:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-01-09T21:56:59.80130Z,1326146219.8013 [homing_altitude:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T21:57:00.18070Z,1326146220.1807 [DAT](INFO): Powering down
2012-01-09T21:59:35.46080Z,1326146375.4608 [homing_altitude:SURFACECOMMS:B] Running Loop=1
2012-01-09T21:59:35.46100Z,1326146375.461 [homing_altitude:SURFACECOMMS:B](INFO): Aggregate::initialize homing_altitude:SURFACECOMMS:B
2012-01-09T21:59:35.46110Z,1326146375.4611 [homing_altitude:SURFACECOMMS:B:A] Running Loop=1
2012-01-09T21:59:36.26100Z,1326146376.261 [NAL9601](INFO): Powering up
2012-01-09T22:00:41.97090Z,1326146441.9709 [NAL9601](INFO): NAL9601 initialized
2012-01-09T22:00:43.10880Z,1326146443.1088 [NAL9601](IMPORTANT): GPS fix at: 1326146463
2012-01-09T22:00:43.12320Z,1326146443.1232 [homing_altitude:SURFACECOMMS:B:A] Stopped
2012-01-09T22:00:43.12340Z,1326146443.1234 [homing_altitude:SURFACECOMMS:B:B] Running Loop=1
2012-01-09T22:01:25.02510Z,1326146485.0251 [NAL9601](INFO): SBD MO Status=2, MOMSN=40853, MT Status=2, MTMSN=0
2012-01-09T22:01:25.02530Z,1326146485.0253 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-01-09T22:01:45.35470Z,1326146505.3547 [NAL9601](INFO): SBD MO Status=1, MOMSN=40853, MT Status=0, MTMSN=0
2012-01-09T22:01:45.56290Z,1326146505.5629 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0011.lzma
2012-01-09T22:01:45.56310Z,1326146505.5631 [NAL9601](INFO): Packets left to send: 3
2012-01-09T22:01:45.56430Z,1326146505.5643 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000035
2012-01-09T22:01:55.50360Z,1326146515.5036 [NAL9601](INFO): SBD MO Status=1, MOMSN=40854, MT Status=0, MTMSN=0
2012-01-09T22:01:55.64690Z,1326146515.6469 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0011.lzma
2012-01-09T22:01:55.64710Z,1326146515.6471 [NAL9601](INFO): Packets left to send: 2
2012-01-09T22:01:55.64900Z,1326146515.649 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000036
2012-01-09T22:02:03.95220Z,1326146523.9522 [NAL9601](INFO): SBD MO Status=1, MOMSN=40855, MT Status=0, MTMSN=0
2012-01-09T22:02:04.13480Z,1326146524.1348 [NAL9601](INFO): Sent 332 bytes from file Logs/20120109T201340/shore0011.lzma
2012-01-09T22:02:04.13510Z,1326146524.1351 [NAL9601](INFO): Packets left to send: 1
2012-01-09T22:02:04.13630Z,1326146524.1363 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000037
2012-01-09T22:02:12.07210Z,1326146532.0721 [NAL9601](INFO): SBD MO Status=1, MOMSN=40856, MT Status=0, MTMSN=0
2012-01-09T22:02:12.21890Z,1326146532.2189 [NAL9601](INFO): Sent 197 bytes from file Logs/20120109T201340/shore0011.lzma
2012-01-09T22:02:12.21910Z,1326146532.2191 [NAL9601](INFO): Packets left to send: 0
2012-01-09T22:02:12.22100Z,1326146532.221 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000038
2012-01-09T22:02:20.49200Z,1326146540.492 [NAL9601](INFO): SBD MO Status=0, MOMSN=40857, MT Status=0, MTMSN=0
2012-01-09T22:02:20.72000Z,1326146540.72 [homing_altitude:SURFACECOMMS:B:B] Stopped
2012-01-09T22:02:20.72010Z,1326146540.7201 [homing_altitude:SURFACECOMMS:B:C] Running Loop=1
2012-01-09T22:02:22.87210Z,1326146542.8721 [NAL9601](IMPORTANT): GPS fix at: 1326146563
2012-01-09T22:02:22.88580Z,1326146542.8858 [homing_altitude:SURFACECOMMS:B:C] Stopped
2012-01-09T22:02:22.88610Z,1326146542.8861 [homing_altitude:SURFACECOMMS:B](INFO): Completed homing_altitude:SURFACECOMMS:B
2012-01-09T22:02:22.88620Z,1326146542.8862 [homing_altitude:SURFACECOMMS:B] Stopped
2012-01-09T22:02:22.88650Z,1326146542.8865 [homing_altitude:SURFACECOMMS:B](INFO): Aggregate::uninitialize homing_altitude:SURFACECOMMS:B
2012-01-09T22:02:22.88700Z,1326146542.887 [homing_altitude:SURFACECOMMS](INFO): Completed homing_altitude:SURFACECOMMS
2012-01-09T22:02:22.88710Z,1326146542.8871 [homing_altitude:SURFACECOMMS] Stopped
2012-01-09T22:02:22.88720Z,1326146542.8872 [homing_altitude:SURFACECOMMS](INFO): Aggregate::uninitialize homing_altitude:SURFACECOMMS
2012-01-09T22:02:22.88730Z,1326146542.8873 [homing_altitude:SURFACECOMMS:A.GoToSurface] Stopped
2012-01-09T22:02:22.88730Z,1326146542.8873 [homing_altitude:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T22:02:23.29690Z,1326146543.2969 [homing_altitude:PHONEHOMEWPT1](INFO): Completed homing_altitude:PHONEHOMEWPT1
2012-01-09T22:02:23.29700Z,1326146543.297 [homing_altitude:PHONEHOMEWPT1] Stopped
2012-01-09T22:02:23.29720Z,1326146543.2972 [homing_altitude:PHONEHOMEWPT1](INFO): Aggregate::uninitialize homing_altitude:PHONEHOMEWPT1
2012-01-09T22:02:23.29730Z,1326146543.2973 [homing_altitude:H.Execute] Running Loop=1
2012-01-09T22:02:23.67400Z,1326146543.674 [homing_altitude:H.Execute](INFO): Executing command restart logs
2012-01-09T22:02:23.67930Z,1326146543.6793 [homing_altitude:H.Execute] Stopped
2012-01-09T22:02:23.68040Z,1326146543.6804 [homing_altitude](INFO): Completed homing_altitude
2012-01-09T22:02:23.68050Z,1326146543.6805 [homing_altitude] Stopped
2012-01-09T22:02:23.68060Z,1326146543.6806 [homing_altitude](INFO): Aggregate::uninitialize homing_altitude
2012-01-09T22:02:23.68070Z,1326146543.6807 [homing_altitude:A.AltitudeEnvelope] Stopped
2012-01-09T22:02:23.68080Z,1326146543.6808 [homing_altitude:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-01-09T22:02:23.68090Z,1326146543.6809 [homing_altitude:B.DepthEnvelope] Stopped
2012-01-09T22:02:23.68090Z,1326146543.6809 [homing_altitude:B.DepthEnvelope](DEBUG): Uninitialize.
2012-01-09T22:02:23.68100Z,1326146543.681 [homing_altitude:C.OffshoreEnvelope] Stopped
2012-01-09T22:02:23.68110Z,1326146543.6811 [homing_altitude:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2012-01-09T22:02:23.68120Z,1326146543.6812 [homing_altitude:D] Stopped
2012-01-09T22:02:23.75470Z,1326146543.7547 [CommandLine](IMPORTANT): got command restart logs
2012-01-09T22:02:24.15970Z,1326146544.1597 [MissionManager](IMPORTANT): Started mission Default
2012-01-09T22:02:24.15980Z,1326146544.1598 [Default] Running Loop=1
2012-01-09T22:02:24.15990Z,1326146544.1599 [Default](INFO): Aggregate::initialize Default
2012-01-09T22:02:24.16000Z,1326146544.16 [Default:E.SetSpeed] Running Loop=1
2012-01-09T22:02:24.16010Z,1326146544.1601 [Default:E.SetSpeed](DEBUG): Initialize.
2012-01-09T22:02:24.16020Z,1326146544.1602 [Default:F.GoToSurface] Running Loop=1
2012-01-09T22:02:24.16030Z,1326146544.1603 [Default:F.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T22:02:24.16070Z,1326146544.1607 [Default:GPS] Running Loop=1
2012-01-09T22:02:24.16080Z,1326146544.1608 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-09T22:02:24.16090Z,1326146544.1609 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-09T22:02:24.16100Z,1326146544.161 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-09T22:02:24.16120Z,1326146544.1612 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-09T22:02:24.16120Z,1326146544.1612 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-09T22:02:24.16280Z,1326146544.1628 [Default:GPS:B.GoToSurface] Stopped
2012-01-09T22:02:24.16290Z,1326146544.1629 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-09T22:02:24.16310Z,1326146544.1631 [Default:GPS:Read_GPS] Running Loop=1