2012-01-04T21:24:27.33140Z,1325712267.3314 [Supervisor](DEBUG): Initializing supervisor.
2012-01-04T21:24:27.33390Z,1325712267.3339 [SyncHandler](DEBUG): Created PCaller Thread at 1077138656
2012-01-04T21:24:27.33460Z,1325712267.3346 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-01-04T21:24:27.33570Z,1325712267.3357 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 1077335264
2012-01-04T21:24:27.33660Z,1325712267.3366 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-01-04T21:24:27.34680Z,1325712267.3468 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-01-04T21:24:27.34790Z,1325712267.3479 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 1077531872
2012-01-04T21:24:27.34880Z,1325712267.3488 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2012-01-04T21:24:27.34920Z,1325712267.3492 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-01-04T21:24:27.35230Z,1325712267.3523 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-01-04T21:24:27.62070Z,1325712267.6207 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-01-04T21:24:27.62320Z,1325712267.6232 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-01-04T21:24:27.79680Z,1325712267.7968 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-01-04T21:24:27.79750Z,1325712267.7975 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-01-04T21:24:27.88390Z,1325712267.8839 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-01-04T21:24:27.88640Z,1325712267.8864 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-01-04T21:24:28.07430Z,1325712268.0743 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-01-04T21:24:28.07500Z,1325712268.075 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-01-04T21:24:28.20310Z,1325712268.2031 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-01-04T21:24:28.20560Z,1325712268.2056 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-01-04T21:24:28.42490Z,1325712268.4249 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-01-04T21:24:28.42560Z,1325712268.4256 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-01-04T21:24:28.56800Z,1325712268.568 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-01-04T21:24:28.56880Z,1325712268.5688 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-01-04T21:24:28.81710Z,1325712268.8171 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-01-04T21:24:28.81960Z,1325712268.8196 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-01-04T21:24:28.91790Z,1325712268.9179 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-01-04T21:24:28.91860Z,1325712268.9186 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-01-04T21:24:29.30030Z,1325712269.3003 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-01-04T21:24:29.30290Z,1325712269.3029 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-01-04T21:24:29.41290Z,1325712269.4129 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-01-04T21:24:29.41360Z,1325712269.4136 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-01-04T21:24:29.50040Z,1325712269.5004 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-tethys/
2012-01-04T21:24:29.50290Z,1325712269.5029 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/vehicle.cfg
2012-01-04T21:24:29.60630Z,1325712269.6063 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Sensor.cfg
2012-01-04T21:24:29.72790Z,1325712269.7279 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/BIT.cfg
2012-01-04T21:24:29.82630Z,1325712269.8263 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Servo.cfg
2012-01-04T21:24:29.92300Z,1325712269.923 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Science.cfg
2012-01-04T21:24:30.01740Z,1325712270.0174 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/workSite.cfg
2012-01-04T21:24:30.10470Z,1325712270.1047 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Simulator.cfg
2012-01-04T21:24:30.19020Z,1325712270.1902 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Derivation.cfg
2012-01-04T21:24:30.30720Z,1325712270.3072 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-01-04T21:24:30.42120Z,1325712270.4212 [InternalSim] Loaded
2012-01-04T21:24:30.42140Z,1325712270.4214 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-01-04T21:24:30.42220Z,1325712270.4222 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-01-04T21:24:30.42300Z,1325712270.423 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-01-04T21:24:30.45690Z,1325712270.4569 [SBIT](DEBUG): Construct Startup Built In Test.
2012-01-04T21:24:30.48530Z,1325712270.4853 [SBIT] Loaded
2012-01-04T21:24:30.48560Z,1325712270.4856 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-01-04T21:24:30.48650Z,1325712270.4865 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-01-04T21:24:30.50990Z,1325712270.5099 [IBIT] Loaded
2012-01-04T21:24:30.51020Z,1325712270.5102 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-01-04T21:24:30.51710Z,1325712270.5171 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-01-04T21:24:30.62750Z,1325712270.6275 [CBIT] Loaded
2012-01-04T21:24:30.62770Z,1325712270.6277 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-01-04T21:24:30.62810Z,1325712270.6281 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-01-04T21:24:30.62900Z,1325712270.629 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-01-04T21:24:30.74430Z,1325712270.7443 [BuoyancyServo] Loaded
2012-01-04T21:24:30.74450Z,1325712270.7445 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-01-04T21:24:30.75150Z,1325712270.7515 [ElevatorServo] Loaded
2012-01-04T21:24:30.75180Z,1325712270.7518 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2012-01-04T21:24:30.75870Z,1325712270.7587 [MassServo] Loaded
2012-01-04T21:24:30.75900Z,1325712270.759 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2012-01-04T21:24:30.76580Z,1325712270.7658 [RudderServo] Loaded
2012-01-04T21:24:30.76610Z,1325712270.7661 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-01-04T21:24:30.77310Z,1325712270.7731 [ThrusterServo] Loaded
2012-01-04T21:24:30.77350Z,1325712270.7735 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-01-04T21:24:30.77400Z,1325712270.774 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-01-04T21:24:30.77470Z,1325712270.7747 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-01-04T21:24:30.80520Z,1325712270.8052 [DepthRateCalculator] Loaded
2012-01-04T21:24:30.80550Z,1325712270.8055 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-01-04T21:24:30.82110Z,1325712270.8211 [NavChart] Loaded
2012-01-04T21:24:30.82140Z,1325712270.8214 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-01-04T21:24:30.82720Z,1325712270.8272 [PitchRateCalculator] Loaded
2012-01-04T21:24:30.82750Z,1325712270.8275 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-01-04T21:24:30.83320Z,1325712270.8332 [SpeedCalculator] Loaded
2012-01-04T21:24:30.83350Z,1325712270.8335 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-01-04T21:24:30.84800Z,1325712270.848 [TempGradientCalculator] Loaded
2012-01-04T21:24:30.84830Z,1325712270.8483 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-01-04T21:24:30.85410Z,1325712270.8541 [YawRateCalculator] Loaded
2012-01-04T21:24:30.85440Z,1325712270.8544 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-01-04T21:24:30.88420Z,1325712270.8842 [Navigation] Loaded
2012-01-04T21:24:30.88450Z,1325712270.8845 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-01-04T21:24:30.88490Z,1325712270.8849 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-01-04T21:24:30.88560Z,1325712270.8856 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-01-04T21:24:30.97870Z,1325712270.9787 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-01-04T21:24:30.97950Z,1325712270.9795 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-01-04T21:24:30.99840Z,1325712270.9984 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-01-04T21:24:30.99910Z,1325712270.9991 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-01-04T21:24:31.04550Z,1325712271.0455 [VerticalControl](DEBUG): Construct VerticalControl.
2012-01-04T21:24:31.25150Z,1325712271.2515 [VerticalControl] Loaded
2012-01-04T21:24:31.25180Z,1325712271.2518 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-01-04T21:24:31.25280Z,1325712271.2528 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-01-04T21:24:31.31160Z,1325712271.3116 [HorizontalControl] Loaded
2012-01-04T21:24:31.31190Z,1325712271.3119 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-01-04T21:24:31.31290Z,1325712271.3129 [SpeedControl](DEBUG): Construct SpeedControl.
2012-01-04T21:24:31.31460Z,1325712271.3146 [SpeedControl] Loaded
2012-01-04T21:24:31.31490Z,1325712271.3149 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-01-04T21:24:31.31590Z,1325712271.3159 [LoopControl](DEBUG): Construct LoopControl.
2012-01-04T21:24:31.31660Z,1325712271.3166 [LoopControl] Loaded
2012-01-04T21:24:31.31690Z,1325712271.3169 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-01-04T21:24:31.31740Z,1325712271.3174 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-01-04T21:24:31.31800Z,1325712271.318 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-01-04T21:24:34.73590Z,1325712274.7359 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-01-04T21:24:34.74270Z,1325712274.7427 [AsyncPiEstimator] Loaded
2012-01-04T21:24:34.74300Z,1325712274.743 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-01-04T21:24:34.74420Z,1325712274.7442 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 1078928608
2012-01-04T21:24:34.74490Z,1325712274.7449 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-01-04T21:24:34.74560Z,1325712274.7456 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-01-04T21:24:34.99660Z,1325712274.9966 [AHRS_sp3003D] Loaded
2012-01-04T21:24:34.99690Z,1325712274.9969 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-01-04T21:24:35.03750Z,1325712275.0375 [AHRS_3DMGX3] Loaded
2012-01-04T21:24:35.03780Z,1325712275.0378 [ComponentRegistry](DEBUG): SyncComponent "AHRS_3DMGX3" handled in the control thread.
2012-01-04T21:24:35.29440Z,1325712275.2944 [Batt_Ocean_Server] Loaded
2012-01-04T21:24:35.29480Z,1325712275.2948 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2012-01-04T21:24:35.30710Z,1325712275.3071 [Depth_Keller] Loaded
2012-01-04T21:24:35.30740Z,1325712275.3074 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2012-01-04T21:24:35.31280Z,1325712275.3128 [DropWeight] Loaded
2012-01-04T21:24:35.31320Z,1325712275.3132 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2012-01-04T21:24:35.40730Z,1325712275.4073 [DVL_micro] Loaded
2012-01-04T21:24:35.40760Z,1325712275.4076 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2012-01-04T21:24:35.48800Z,1325712275.488 [NAL9601] Loaded
2012-01-04T21:24:35.48830Z,1325712275.4883 [ComponentRegistry](DEBUG): SyncComponent "NAL9601" handled in the control thread.
2012-01-04T21:24:35.53820Z,1325712275.5382 [Onboard] Loaded
2012-01-04T21:24:35.53850Z,1325712275.5385 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-01-04T21:24:35.54480Z,1325712275.5448 [Radio_Freewave] Loaded
2012-01-04T21:24:35.54510Z,1325712275.5451 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2012-01-04T21:24:35.56850Z,1325712275.5685 [DAT] Loaded
2012-01-04T21:24:35.56880Z,1325712275.5688 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2012-01-04T21:24:35.56920Z,1325712275.5692 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-01-04T21:24:35.56990Z,1325712275.5699 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-01-04T21:24:35.62940Z,1325712275.6294 [CTD_NeilBrown] Loaded
2012-01-04T21:24:35.62970Z,1325712275.6297 [ComponentRegistry](DEBUG): SyncComponent "CTD_NeilBrown" handled in the control thread.
2012-01-04T21:24:35.65960Z,1325712275.6596 [WetLabsBB2FL] Loaded
2012-01-04T21:24:35.65990Z,1325712275.6599 [ComponentRegistry](DEBUG): SyncComponent "WetLabsBB2FL" handled in the control thread.
2012-01-04T21:24:35.66110Z,1325712275.6611 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-01-04T21:24:35.66340Z,1325712275.6634 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-01-04T21:24:35.66420Z,1325712275.6642 [ComponentRegistry](DEBUG): SyncComponent "Maintainer" handled in the control thread.
2012-01-04T21:24:35.66500Z,1325712275.665 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-01-04T21:24:35.67030Z,1325712275.6703 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-01-04T21:24:35.67150Z,1325712275.6715 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 1079497952
2012-01-04T21:24:35.67190Z,1325712275.6719 [Supervisor](DEBUG): Running supervisor.
2012-01-04T21:24:35.67510Z,1325712275.6751 [controlThread](DEBUG): Initializing ControlThread
2012-01-04T21:24:35.67610Z,1325712275.6761 [InternalSim](DEBUG):  InternalSim initializing...
2012-01-04T21:24:35.77290Z,1325712275.7729 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-01-04T21:24:35.97160Z,1325712275.9716 [SBIT](INFO): Initialize SBIT Component.
2012-01-04T21:24:35.97330Z,1325712275.9733 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 9454 $
2012-01-04T21:24:35.97390Z,1325712275.9739 [IBIT](INFO): Initialize IBIT Component.
2012-01-04T21:24:35.98090Z,1325712275.9809 [CBIT](DEBUG): Initialize CBIT Component.
2012-01-04T21:24:35.98120Z,1325712275.9812 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET.
2012-01-04T21:24:36.00820Z,1325712276.0082 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-01-04T21:24:36.00860Z,1325712276.0086 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-01-04T21:24:36.00890Z,1325712276.0089 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-01-04T21:24:36.00930Z,1325712276.0093 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-01-04T21:24:36.00990Z,1325712276.0099 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-01-04T21:24:36.01190Z,1325712276.0119 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-01-04T21:24:36.01230Z,1325712276.0123 [Navigation](DEBUG): Initializing Navigation.
2012-01-04T21:24:36.01270Z,1325712276.0127 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-01-04T21:24:36.03890Z,1325712276.0389 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-01-04T21:24:36.05350Z,1325712276.0535 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-01-04T21:24:36.05430Z,1325712276.0543 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-01-04T21:24:36.08090Z,1325712276.0809 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-01-04T21:24:36.09070Z,1325712276.0907 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2012-01-04T21:24:36.09450Z,1325712276.0945 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2012-01-04T21:24:36.10380Z,1325712276.1038 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2012-01-04T21:24:36.11030Z,1325712276.1103 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2012-01-04T21:24:36.11110Z,1325712276.1111 [NavChartDb](INFO): Creating index for Soundings
2012-01-04T21:24:36.11420Z,1325712276.1142 [NavChartDb](INFO): Creating index for Contour 0p0
2012-01-04T21:24:36.11630Z,1325712276.1163 [NavChartDb](INFO): Creating index for Contour 1p8
2012-01-04T21:24:36.11810Z,1325712276.1181 [NavChartDb](INFO): Creating index for Contour 3p6
2012-01-04T21:24:36.12010Z,1325712276.1201 [NavChartDb](INFO): Creating index for Contour 5p4
2012-01-04T21:24:36.12190Z,1325712276.1219 [NavChartDb](INFO): Creating index for Contour 9p1
2012-01-04T21:24:36.12400Z,1325712276.124 [NavChartDb](INFO): Creating index for Contour 10p9
2012-01-04T21:24:36.12580Z,1325712276.1258 [NavChartDb](INFO): Creating index for Contour 18p2
2012-01-04T21:24:36.12780Z,1325712276.1278 [NavChartDb](INFO): Creating index for Contour 36p5
2012-01-04T21:24:36.12960Z,1325712276.1296 [NavChartDb](INFO): Creating index for Contour 54p8
2012-01-04T21:24:36.13160Z,1325712276.1316 [NavChartDb](INFO): Creating index for Contour 73p1
2012-01-04T21:24:36.13340Z,1325712276.1334 [NavChartDb](INFO): Creating index for Contour 91p4
2012-01-04T21:24:36.13540Z,1325712276.1354 [NavChartDb](INFO): Creating index for Contour 182p8
2012-01-04T21:24:36.13720Z,1325712276.1372 [NavChartDb](INFO): Creating index for Contour 365p7
2012-01-04T21:24:36.13920Z,1325712276.1392 [NavChartDb](INFO): Creating index for Contour 548p6
2012-01-04T21:24:36.14100Z,1325712276.141 [NavChartDb](INFO): Creating index for Contour 731p5
2012-01-04T21:24:36.14290Z,1325712276.1429 [NavChartDb](INFO): Creating index for Contour 914p4
2012-01-04T21:24:36.14470Z,1325712276.1447 [NavChartDb](INFO): Creating index for Contour 1097p2
2012-01-04T21:24:36.14650Z,1325712276.1465 [NavChartDb](INFO): Creating index for Contour 1280p1
2012-01-04T21:24:36.14850Z,1325712276.1485 [NavChartDb](INFO): Creating index for Contour 1463p0
2012-01-04T21:24:36.15030Z,1325712276.1503 [NavChartDb](INFO): Creating index for Contour 1645p9
2012-01-04T21:24:36.15230Z,1325712276.1523 [NavChartDb](INFO): Creating index for Contour 1828p8
2012-01-04T21:24:36.15410Z,1325712276.1541 [NavChartDb](INFO): Creating index for Contour 2011p6
2012-01-04T21:24:36.15610Z,1325712276.1561 [NavChartDb](INFO): Creating index for Contour 2194p5
2012-01-04T21:24:36.15790Z,1325712276.1579 [NavChartDb](INFO): Creating index for Contour 2377p4
2012-01-04T21:24:36.15990Z,1325712276.1599 [NavChartDb](INFO): Creating index for Contour 2560p3
2012-01-04T21:24:36.16170Z,1325712276.1617 [NavChartDb](INFO): Creating index for Contour 2743p2
2012-01-04T21:24:36.16370Z,1325712276.1637 [NavChartDb](INFO): Creating index for Contour 2926p0
2012-01-04T21:24:36.16550Z,1325712276.1655 [NavChartDb](INFO): Creating index for Contour 3108p9
2012-01-04T21:24:36.16750Z,1325712276.1675 [NavChartDb](INFO): Creating index for Contour 3291p8
2012-01-04T21:24:36.16930Z,1325712276.1693 [NavChartDb](INFO): Creating index for Contour 3474p7
2012-01-04T21:24:36.17130Z,1325712276.1713 [NavChartDb](INFO): Creating index for Contour 3657p6
2012-01-04T21:24:37.67990Z,1325712277.6799 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2012-01-04T21:24:37.68470Z,1325712277.6847 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-01-04T21:24:37.69860Z,1325712277.6986 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-01-04T21:24:37.70860Z,1325712277.7086 [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-04T21:24:37.70940Z,1325712277.7094 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-01-04T21:24:37.74560Z,1325712277.7456 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-01-04T21:24:37.74940Z,1325712277.7494 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-01-04T21:24:37.75580Z,1325712277.7558 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-01-04T21:24:37.75930Z,1325712277.7593 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-01-04T21:24:37.76590Z,1325712277.7659 [Default:Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-01-04T21:24:37.78200Z,1325712277.782 [Default:E.SetSpeed](DEBUG): Construct.
2012-01-04T21:24:37.78570Z,1325712277.7857 [Default:F.GoToSurface](DEBUG): Construct GoToSurface.
2012-01-04T21:24:37.79090Z,1325712277.7909 [Default:G.Wait](DEBUG): Construct Wait.
2012-01-04T21:24:37.79510Z,1325712277.7951 [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-04T21:24:37.80080Z,1325712277.8008 [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-04T21:24:37.82870Z,1325712277.8287 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-01-04T21:24:37.83580Z,1325712277.8358 [AHRS_3DMGX3](DEBUG): Initializing AHRS_3DMGX3.
2012-01-04T21:24:37.94590Z,1325712277.9459 [DVL_micro](DEBUG): Initializing DVL_micro.
2012-01-04T21:24:37.97150Z,1325712277.9715 [DAT](INFO): Powering up
2012-01-04T21:24:37.97170Z,1325712277.9717 [DAT](DEBUG): Initializing DAT.
2012-01-04T21:24:37.97750Z,1325712277.9775 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-01-04T21:24:37.98600Z,1325712277.986 [WetLabsBB2FL](INFO): Powering down
2012-01-04T21:24:38.05810Z,1325712278.0581 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-01-04T21:24:38.05930Z,1325712278.0593 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-01-04T21:24:38.06850Z,1325712278.0685 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-01-04T21:24:38.06950Z,1325712278.0695 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-01-04T21:24:38.07790Z,1325712278.0779 [MassServo](DEBUG): Initializing EZServoServo.
2012-01-04T21:24:38.07920Z,1325712278.0792 [MassServo](DEBUG): Initializing MassServo.
2012-01-04T21:24:38.08730Z,1325712278.0873 [RudderServo](DEBUG): Initializing EZServoServo.
2012-01-04T21:24:38.08820Z,1325712278.0882 [RudderServo](DEBUG): Initializing RudderServo.
2012-01-04T21:24:38.09680Z,1325712278.0968 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-01-04T21:24:38.09770Z,1325712278.0977 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-01-04T21:24:40.88680Z,1325712280.8868 [DVL_micro](ERROR): DVL uart error: serial timeout
2012-01-04T21:24:40.88700Z,1325712280.887 [DVL_micro] Communications Fault, FailCount= 1
2012-01-04T21:24:40.88700Z,1325712280.887 [DVL_micro](ERROR): Communications Fault
2012-01-04T21:24:40.88980Z,1325712280.8898 [NAL9601](INFO): Powering up NAL9601
2012-01-04T21:24:40.90900Z,1325712280.909 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.08657000214 psu
2012-01-04T21:24:40.92290Z,1325712280.9229 [CBIT](ERROR): Communications Fault in component: DVL_micro
2012-01-04T21:24:41.29240Z,1325712281.2924 [DVL_micro](INFO): Powering down
2012-01-04T21:24:41.43700Z,1325712281.437 [CBIT](INFO): Clearing failed state for component DVL_micro
2012-01-04T21:24:41.43710Z,1325712281.4371 [DVL_micro] No Fault, FailCount= 1
2012-01-04T21:24:41.62740Z,1325712281.6274 [DVL_micro](DEBUG): Initializing DVL_micro.
2012-01-04T21:24:51.67590Z,1325712291.6759 [SBIT](IMPORTANT): Beginning Startup BIT
2012-01-04T21:24:51.67840Z,1325712291.6784 [CBIT](IMPORTANT): Beginning GF scan
2012-01-04T21:24:52.82150Z,1325712292.8215 [DAT](INFO): Powering down
2012-01-04T21:25:17.77060Z,1325712317.7706 [CBIT](IMPORTANT): No ground fault detected
2012-01-04T21:25:33.67130Z,1325712333.6713 [SBIT](IMPORTANT): SBIT PASSED
2012-01-04T21:25:34.06690Z,1325712334.0669 [MissionManager](IMPORTANT): Started mission Startup
2012-01-04T21:25:34.06700Z,1325712334.067 [Startup] Running Loop=1
2012-01-04T21:25:34.06720Z,1325712334.0672 [Startup](INFO): Aggregate::initialize Startup
2012-01-04T21:25:34.06720Z,1325712334.0672 [Startup:A.GoToSurface] Running Loop=1
2012-01-04T21:25:34.06730Z,1325712334.0673 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T21:25:34.07330Z,1325712334.0733 [Startup:StartupSatComms] Running Loop=1
2012-01-04T21:25:34.07340Z,1325712334.0734 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2012-01-04T21:25:34.07360Z,1325712334.0736 [Startup:StartupSatComms:A] Running Loop=1
2012-01-04T21:25:34.47240Z,1325712334.4724 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-01-04T21:25:46.35920Z,1325712346.3592 [NAL9601](INFO): NAL9601 initialized
2012-01-04T21:25:47.47230Z,1325712347.4723 [NAL9601](IMPORTANT): GPS fix at: 1325712346
2012-01-04T21:25:47.48560Z,1325712347.4856 [Startup:StartupSatComms:A] Stopped
2012-01-04T21:25:47.48580Z,1325712347.4858 [Startup:StartupSatComms:B] Running Loop=1
2012-01-04T21:25:47.90730Z,1325712347.9073 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-01-04T21:26:01.83790Z,1325712361.8379 [NAL9601](INFO): SBD MO Status=1, MOMSN=40197, MT Status=0, MTMSN=0
2012-01-04T21:26:02.01920Z,1325712362.0192 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T194857/shore0010.lzma
2012-01-04T21:26:02.01950Z,1325712362.0195 [NAL9601](INFO): Packets left to send: 1
2012-01-04T21:26:02.02070Z,1325712362.0207 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000000
2012-01-04T21:26:10.37380Z,1325712370.3738 [NAL9601](INFO): SBD MO Status=1, MOMSN=40198, MT Status=0, MTMSN=0
2012-01-04T21:26:10.50720Z,1325712370.5072 [NAL9601](INFO): Sent 269 bytes from file Logs/20120104T194857/shore0010.lzma
2012-01-04T21:26:10.50740Z,1325712370.5074 [NAL9601](INFO): Packets left to send: 0
2012-01-04T21:26:10.50840Z,1325712370.5084 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000001
2012-01-04T21:26:18.48570Z,1325712378.4857 [NAL9601](INFO): SBD MO Status=1, MOMSN=40199, MT Status=0, MTMSN=0
2012-01-04T21:26:18.69520Z,1325712378.6952 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T194857/shore0011.lzma
2012-01-04T21:26:18.69550Z,1325712378.6955 [NAL9601](INFO): Packets left to send: 1
2012-01-04T21:26:18.69650Z,1325712378.6965 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000002
2012-01-04T21:26:25.01370Z,1325712385.0137 [NAL9601](INFO): SBD MO Status=1, MOMSN=40200, MT Status=0, MTMSN=0
2012-01-04T21:26:25.18320Z,1325712385.1832 [NAL9601](INFO): Sent 117 bytes from file Logs/20120104T194857/shore0011.lzma
2012-01-04T21:26:25.18350Z,1325712385.1835 [NAL9601](INFO): Packets left to send: 0
2012-01-04T21:26:25.18450Z,1325712385.1845 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000003
2012-01-04T21:26:36.28970Z,1325712396.2897 [NAL9601](INFO): SBD MO Status=1, MOMSN=40201, MT Status=0, MTMSN=0
2012-01-04T21:26:36.46720Z,1325712396.4672 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0000.lzma
2012-01-04T21:26:36.46750Z,1325712396.4675 [NAL9601](INFO): Packets left to send: 2
2012-01-04T21:26:36.46850Z,1325712396.4685 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000004
2012-01-04T21:26:44.21360Z,1325712404.2136 [NAL9601](INFO): SBD MO Status=1, MOMSN=40202, MT Status=0, MTMSN=0
2012-01-04T21:26:44.35520Z,1325712404.3552 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0000.lzma
2012-01-04T21:26:44.35550Z,1325712404.3555 [NAL9601](INFO): Packets left to send: 1
2012-01-04T21:26:44.35650Z,1325712404.3565 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000005
2012-01-04T21:26:47.59630Z,1325712407.5963 [Startup:StartupSatComms:B](INFO): Timed out from 2012-01-04T21:25:47.Z
2012-01-04T21:26:47.59650Z,1325712407.5965 [Startup:StartupSatComms:A_Timeout] Running Loop=1
2012-01-04T21:26:47.59660Z,1325712407.5966 [Startup:StartupSatComms:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A_Timeout
2012-01-04T21:26:47.59690Z,1325712407.5969 [Startup:StartupSatComms:A_Timeout](INFO): Completed Startup:StartupSatComms:A_Timeout
2012-01-04T21:26:47.59700Z,1325712407.597 [Startup:StartupSatComms:B] Stopped
2012-01-04T21:26:47.59710Z,1325712407.5971 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2012-01-04T21:26:47.59720Z,1325712407.5972 [Startup:StartupSatComms] Stopped
2012-01-04T21:26:47.59740Z,1325712407.5974 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2012-01-04T21:26:47.59790Z,1325712407.5979 [Startup](INFO): Completed Startup
2012-01-04T21:26:47.59800Z,1325712407.598 [Startup] Stopped
2012-01-04T21:26:47.59810Z,1325712407.5981 [Startup](INFO): Aggregate::uninitialize Startup
2012-01-04T21:26:47.59820Z,1325712407.5982 [Startup:A.GoToSurface] Stopped
2012-01-04T21:26:47.59830Z,1325712407.5983 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T21:26:47.87980Z,1325712407.8798 [MissionManager](IMPORTANT): Started mission Default
2012-01-04T21:26:47.87990Z,1325712407.8799 [Default] Running Loop=1
2012-01-04T21:26:47.88000Z,1325712407.88 [Default](INFO): Aggregate::initialize Default
2012-01-04T21:26:47.88010Z,1325712407.8801 [Default:E.SetSpeed] Running Loop=1
2012-01-04T21:26:47.88010Z,1325712407.8801 [Default:E.SetSpeed](DEBUG): Initialize.
2012-01-04T21:26:47.88040Z,1325712407.8804 [Default:F.GoToSurface] Running Loop=1
2012-01-04T21:26:47.88050Z,1325712407.8805 [Default:F.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T21:26:47.88100Z,1325712407.881 [Default:GPS] Running Loop=1
2012-01-04T21:26:47.88110Z,1325712407.8811 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T21:26:47.88120Z,1325712407.8812 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T21:26:47.88130Z,1325712407.8813 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T21:26:47.88150Z,1325712407.8815 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T21:26:47.88160Z,1325712407.8816 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T21:26:47.88250Z,1325712407.8825 [Default:F.GoToSurface] Running Loop=1
2012-01-04T21:26:47.88730Z,1325712407.8873 [Default:E.SetSpeed] Running Loop=1
2012-01-04T21:26:47.90440Z,1325712407.9044 [Default:CallIridium] Running Loop=1
2012-01-04T21:26:47.90450Z,1325712407.9045 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-04T21:26:47.90480Z,1325712407.9048 [Default:CallIridium:A] Running Loop=1
2012-01-04T21:26:47.90490Z,1325712407.9049 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-04T21:26:47.90500Z,1325712407.905 [Default:CallGPS] Running Loop=1
2012-01-04T21:26:47.90520Z,1325712407.9052 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T21:26:47.90540Z,1325712407.9054 [Default:CallGPS:A] Running Loop=1
2012-01-04T21:26:47.90550Z,1325712407.9055 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T21:26:47.92250Z,1325712407.9225 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T21:26:47.92260Z,1325712407.9226 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T21:26:47.92280Z,1325712407.9228 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T21:26:47.92280Z,1325712407.9228 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T21:26:48.19820Z,1325712408.1982 [Default:Iridium] Running Loop=1
2012-01-04T21:26:48.19840Z,1325712408.1984 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-04T21:26:48.19850Z,1325712408.1985 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-04T21:26:48.19860Z,1325712408.1986 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-04T21:26:48.20310Z,1325712408.2031 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-04T21:26:48.20310Z,1325712408.2031 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T21:26:48.20840Z,1325712408.2084 [Default:Iridium:B.GoToSurface] Stopped
2012-01-04T21:26:48.20850Z,1325712408.2085 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T21:26:48.20860Z,1325712408.2086 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-04T21:26:48.20870Z,1325712408.2087 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-04T21:26:48.21390Z,1325712408.2139 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-01-04T21:26:48.55640Z,1325712408.5564 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-01-04T21:26:51.72960Z,1325712411.7296 [NAL9601](INFO): SBD MO Status=1, MOMSN=40203, MT Status=0, MTMSN=0
2012-01-04T21:26:51.94320Z,1325712411.9432 [NAL9601](INFO): Sent 264 bytes from file Logs/20120104T212427/shore0000.lzma
2012-01-04T21:26:51.94350Z,1325712411.9435 [NAL9601](INFO): Packets left to send: 0
2012-01-04T21:26:51.94460Z,1325712411.9446 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000006
2012-01-04T21:27:01.71770Z,1325712421.7177 [NAL9601](INFO): SBD MO Status=0, MOMSN=40204, MT Status=0, MTMSN=0
2012-01-04T21:27:01.94500Z,1325712421.945 [Default:Iridium:Read_Iridium] Stopped
2012-01-04T21:27:01.94540Z,1325712421.9454 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-04T21:27:01.94550Z,1325712421.9455 [Default:Iridium] Stopped
2012-01-04T21:27:01.94560Z,1325712421.9456 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-04T21:27:01.94570Z,1325712421.9457 [Default:Iridium:A.SetSpeed] Stopped
2012-01-04T21:27:01.94580Z,1325712421.9458 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T21:27:02.18090Z,1325712422.1809 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-04T21:27:02.18100Z,1325712422.181 [Default:CallIridium:A] Stopped
2012-01-04T21:27:02.18110Z,1325712422.1811 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-04T21:27:02.18140Z,1325712422.1814 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-04T21:27:02.18140Z,1325712422.1814 [Default:CallIridium] Stopped
2012-01-04T21:27:02.18160Z,1325712422.1816 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-04T21:27:02.98630Z,1325712422.9863 [NAL9601](IMPORTANT): GPS fix at: 1325712421
2012-01-04T21:27:03.06840Z,1325712423.0684 [Default:GPS:Read_GPS] Stopped
2012-01-04T21:27:03.06890Z,1325712423.0689 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T21:27:03.06900Z,1325712423.069 [Default:GPS] Stopped
2012-01-04T21:27:03.06910Z,1325712423.0691 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T21:27:03.06920Z,1325712423.0692 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T21:27:03.06930Z,1325712423.0693 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T21:27:03.06940Z,1325712423.0694 [Default:Iridium] Running Loop=1
2012-01-04T21:27:03.06960Z,1325712423.0696 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-04T21:27:03.06970Z,1325712423.0697 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-04T21:27:03.06970Z,1325712423.0697 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-04T21:27:03.06990Z,1325712423.0699 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-04T21:27:03.07000Z,1325712423.07 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T21:27:03.37310Z,1325712423.3731 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T21:27:03.37310Z,1325712423.3731 [Default:CallGPS:A] Stopped
2012-01-04T21:27:03.37330Z,1325712423.3733 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T21:27:03.37350Z,1325712423.3735 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T21:27:03.37360Z,1325712423.3736 [Default:CallGPS] Stopped
2012-01-04T21:27:03.37370Z,1325712423.3737 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T21:27:03.37400Z,1325712423.374 [Default:Iridium:B.GoToSurface] Stopped
2012-01-04T21:27:03.37410Z,1325712423.3741 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T21:27:03.37430Z,1325712423.3743 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-04T21:27:14.91760Z,1325712434.9176 [NAL9601](INFO): SBD MO Status=1, MOMSN=40205, MT Status=0, MTMSN=0
2012-01-04T21:27:15.10950Z,1325712435.1095 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0001.lzma
2012-01-04T21:27:15.10970Z,1325712435.1097 [NAL9601](INFO): Packets left to send: 1
2012-01-04T21:27:15.11110Z,1325712435.1111 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000007
2012-01-04T21:27:21.86170Z,1325712441.8617 [NAL9601](INFO): SBD MO Status=1, MOMSN=40206, MT Status=0, MTMSN=0
2012-01-04T21:27:21.99520Z,1325712441.9952 [NAL9601](INFO): Sent 17 bytes from file Logs/20120104T212427/shore0001.lzma
2012-01-04T21:27:21.99540Z,1325712441.9954 [NAL9601](INFO): Packets left to send: 0
2012-01-04T21:27:21.99650Z,1325712441.9965 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000008
2012-01-04T21:27:31.45770Z,1325712451.4577 [NAL9601](INFO): SBD MO Status=0, MOMSN=40207, MT Status=0, MTMSN=0
2012-01-04T21:27:31.60420Z,1325712451.6042 [Default:Iridium:Read_Iridium] Stopped
2012-01-04T21:27:31.60460Z,1325712451.6046 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-04T21:27:31.60470Z,1325712451.6047 [Default:Iridium] Stopped
2012-01-04T21:27:31.60490Z,1325712451.6049 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-04T21:27:31.60490Z,1325712451.6049 [Default:Iridium:A.SetSpeed] Stopped
2012-01-04T21:27:31.60500Z,1325712451.605 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T21:27:31.60520Z,1325712451.6052 [Default:G.Wait] Running Loop=1
2012-01-04T21:27:31.60520Z,1325712451.6052 [Default:G.Wait](DEBUG): Initialize Wait Component.
2012-01-04T21:27:42.03430Z,1325712462.0343 [NAL9601](INFO): Powering down
2012-01-04T21:32:32.13790Z,1325712752.1379 [Default:CallIridium] Running Loop=1
2012-01-04T21:32:32.13810Z,1325712752.1381 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-04T21:32:32.13830Z,1325712752.1383 [Default:CallIridium:A] Running Loop=1
2012-01-04T21:32:32.13840Z,1325712752.1384 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-04T21:32:32.13850Z,1325712752.1385 [Default:CallGPS] Running Loop=1
2012-01-04T21:32:32.13870Z,1325712752.1387 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T21:32:32.13880Z,1325712752.1388 [Default:CallGPS:A] Running Loop=1
2012-01-04T21:32:32.13900Z,1325712752.139 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T21:32:37.06270Z,1325712757.0627 [Default:Iridium] Running Loop=1
2012-01-04T21:32:37.06290Z,1325712757.0629 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-04T21:32:37.06300Z,1325712757.063 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-04T21:32:37.06300Z,1325712757.063 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-04T21:32:37.06320Z,1325712757.0632 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-04T21:32:37.06330Z,1325712757.0633 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T21:32:37.06400Z,1325712757.064 [Default:Iridium:B.GoToSurface] Stopped
2012-01-04T21:32:37.06410Z,1325712757.0641 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T21:32:37.06420Z,1325712757.0642 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-04T21:32:37.06450Z,1325712757.0645 [Default:GPS] Running Loop=1
2012-01-04T21:32:37.06470Z,1325712757.0647 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T21:32:37.06480Z,1325712757.0648 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T21:32:37.06480Z,1325712757.0648 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T21:32:37.06500Z,1325712757.065 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T21:32:37.06510Z,1325712757.0651 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T21:32:37.06580Z,1325712757.0658 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T21:32:37.06580Z,1325712757.0658 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T21:32:37.06600Z,1325712757.066 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T21:32:37.65650Z,1325712757.6565 [NAL9601](INFO): Powering up
2012-01-04T21:33:43.36720Z,1325712823.3672 [NAL9601](INFO): NAL9601 initialized
2012-01-04T21:33:44.48100Z,1325712824.481 [NAL9601](IMPORTANT): GPS fix at: 1325712824
2012-01-04T21:33:44.49510Z,1325712824.4951 [Default:GPS:Read_GPS] Stopped
2012-01-04T21:33:44.49550Z,1325712824.4955 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T21:33:44.49560Z,1325712824.4956 [Default:GPS] Stopped
2012-01-04T21:33:44.49570Z,1325712824.4957 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T21:33:44.49580Z,1325712824.4958 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T21:33:44.49590Z,1325712824.4959 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T21:33:44.87440Z,1325712824.8744 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T21:33:44.87450Z,1325712824.8745 [Default:CallGPS:A] Stopped
2012-01-04T21:33:44.87460Z,1325712824.8746 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T21:33:44.87480Z,1325712824.8748 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T21:33:44.87490Z,1325712824.8749 [Default:CallGPS] Stopped
2012-01-04T21:33:44.87510Z,1325712824.8751 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T21:33:45.27830Z,1325712825.2783 [Default:CallGPS] Running Loop=1
2012-01-04T21:33:45.27840Z,1325712825.2784 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T21:33:45.27860Z,1325712825.2786 [Default:CallGPS:A] Running Loop=1
2012-01-04T21:33:45.27880Z,1325712825.2788 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T21:33:45.71090Z,1325712825.7109 [Default:GPS] Running Loop=1
2012-01-04T21:33:45.71100Z,1325712825.711 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T21:33:45.71110Z,1325712825.7111 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T21:33:45.71120Z,1325712825.7112 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T21:33:45.71140Z,1325712825.7114 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T21:33:45.71150Z,1325712825.7115 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T21:33:45.71220Z,1325712825.7122 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T21:33:45.71230Z,1325712825.7123 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T21:33:45.71240Z,1325712825.7124 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T21:34:00.41760Z,1325712840.4176 [NAL9601](INFO): SBD MO Status=1, MOMSN=40208, MT Status=0, MTMSN=0
2012-01-04T21:34:00.63120Z,1325712840.6312 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0002.lzma
2012-01-04T21:34:00.63140Z,1325712840.6314 [NAL9601](INFO): Packets left to send: 1
2012-01-04T21:34:00.63250Z,1325712840.6325 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000009
2012-01-04T21:34:10.90170Z,1325712850.9017 [NAL9601](INFO): SBD MO Status=1, MOMSN=40209, MT Status=0, MTMSN=0
2012-01-04T21:34:11.11380Z,1325712851.1138 [NAL9601](INFO): Sent 132 bytes from file Logs/20120104T212427/shore0002.lzma
2012-01-04T21:34:11.11410Z,1325712851.1141 [NAL9601](INFO): Packets left to send: 0
2012-01-04T21:34:11.11520Z,1325712851.1152 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000010
2012-01-04T21:34:20.10170Z,1325712860.1017 [NAL9601](INFO): SBD MO Status=0, MOMSN=40210, MT Status=0, MTMSN=0
2012-01-04T21:34:20.33430Z,1325712860.3343 [Default:Iridium:Read_Iridium] Stopped
2012-01-04T21:34:20.33480Z,1325712860.3348 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-04T21:34:20.33490Z,1325712860.3349 [Default:Iridium] Stopped
2012-01-04T21:34:20.33500Z,1325712860.335 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-04T21:34:20.33510Z,1325712860.3351 [Default:Iridium:A.SetSpeed] Stopped
2012-01-04T21:34:20.33520Z,1325712860.3352 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T21:34:20.50830Z,1325712860.5083 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-04T21:34:20.50840Z,1325712860.5084 [Default:CallIridium:A] Stopped
2012-01-04T21:34:20.50850Z,1325712860.5085 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-04T21:34:20.50870Z,1325712860.5087 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-04T21:34:20.50880Z,1325712860.5088 [Default:CallIridium] Stopped
2012-01-04T21:34:20.50890Z,1325712860.5089 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-04T21:34:21.29920Z,1325712861.2992 [NAL9601](IMPORTANT): GPS fix at: 1325712861
2012-01-04T21:34:21.35730Z,1325712861.3573 [Default:GPS:Read_GPS] Stopped
2012-01-04T21:34:21.35770Z,1325712861.3577 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T21:34:21.35780Z,1325712861.3578 [Default:GPS] Stopped
2012-01-04T21:34:21.35790Z,1325712861.3579 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T21:34:21.35800Z,1325712861.358 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T21:34:21.35810Z,1325712861.3581 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T21:34:21.71800Z,1325712861.718 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T21:34:21.71810Z,1325712861.7181 [Default:CallGPS:A] Stopped
2012-01-04T21:34:21.71820Z,1325712861.7182 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T21:34:21.71840Z,1325712861.7184 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T21:34:21.71850Z,1325712861.7185 [Default:CallGPS] Stopped
2012-01-04T21:34:21.71870Z,1325712861.7187 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T21:34:41.91540Z,1325712881.9154 [NAL9601](INFO): Powering down
2012-01-04T21:39:22.04250Z,1325713162.0425 [Default:CallIridium] Running Loop=1
2012-01-04T21:39:22.04270Z,1325713162.0427 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-04T21:39:22.04290Z,1325713162.0429 [Default:CallIridium:A] Running Loop=1
2012-01-04T21:39:22.04300Z,1325713162.043 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-04T21:39:22.04320Z,1325713162.0432 [Default:CallGPS] Running Loop=1
2012-01-04T21:39:22.04330Z,1325713162.0433 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T21:39:22.04340Z,1325713162.0434 [Default:CallGPS:A] Running Loop=1
2012-01-04T21:39:22.04360Z,1325713162.0436 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T21:39:26.88580Z,1325713166.8858 [Default:Iridium] Running Loop=1
2012-01-04T21:39:26.88600Z,1325713166.886 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-04T21:39:26.88610Z,1325713166.8861 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-04T21:39:26.88620Z,1325713166.8862 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-04T21:39:26.88640Z,1325713166.8864 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-04T21:39:26.88640Z,1325713166.8864 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T21:39:26.88710Z,1325713166.8871 [Default:Iridium:B.GoToSurface] Stopped
2012-01-04T21:39:26.88720Z,1325713166.8872 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T21:39:26.88740Z,1325713166.8874 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-04T21:39:26.88770Z,1325713166.8877 [Default:GPS] Running Loop=1
2012-01-04T21:39:26.88790Z,1325713166.8879 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T21:39:26.88800Z,1325713166.888 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T21:39:26.88800Z,1325713166.888 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T21:39:26.88820Z,1325713166.8882 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T21:39:26.88830Z,1325713166.8883 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T21:39:26.88900Z,1325713166.889 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T21:39:26.88900Z,1325713166.889 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T21:39:26.88920Z,1325713166.8892 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T21:39:27.50030Z,1325713167.5003 [NAL9601](INFO): Powering up
2012-01-04T21:40:33.21120Z,1325713233.2112 [NAL9601](INFO): NAL9601 initialized
2012-01-04T21:40:52.59280Z,1325713252.5928 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=40211, MT Status=1, MTMSN=3346
2012-01-04T21:40:52.77120Z,1325713252.7712 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0003.lzma
2012-01-04T21:40:52.77140Z,1325713252.7714 [NAL9601](INFO): Packets left to send: 2
2012-01-04T21:40:52.77250Z,1325713252.7725 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000011
2012-01-04T21:40:53.30010Z,1325713253.3001 [NAL9601](INFO): Received command:run Maintenance/ballast_and_trim.xml
2012-01-04T21:40:53.38310Z,1325713253.3831 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/ballast_and_trim.xml
2012-01-04T21:40:53.38350Z,1325713253.3835 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/ballast_and_trim.xml
2012-01-04T21:40:53.45210Z,1325713253.4521 [MissionManager](INFO): DefineArg ballast_and_trim.BallastDepth = 25 m
2012-01-04T21:40:53.45520Z,1325713253.4552 [MissionManager](INFO): DefineArg ballast_and_trim.HoldDuration = 25 min
2012-01-04T21:40:53.45820Z,1325713253.4582 [MissionManager](INFO): DefineArg ballast_and_trim.Speed = 1 m/s
2012-01-04T21:40:53.50210Z,1325713253.5021 [MissionManager](INFO): DefineArg ballast_and_trim.DepthDeadband = 4 m
2012-01-04T21:40:53.50540Z,1325713253.5054 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyPeriod = 5 s
2012-01-04T21:40:53.52520Z,1325713253.5252 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyancyDefault = 0.000945 n/a
2012-01-04T21:40:53.59140Z,1325713253.5914 [ballast_and_trim:B.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-01-04T21:40:53.61130Z,1325713253.6113 [ballast_and_trim:C.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-01-04T21:40:53.62750Z,1325713253.6275 [ballast_and_trim:D.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2012-01-04T21:40:53.64410Z,1325713253.6441 [MissionManager](INFO): Inserting Stack: Missions/Insert/Surface.xml
2012-01-04T21:40:53.68910Z,1325713253.6891 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfaceDepthRate = nan m/s
2012-01-04T21:40:53.69240Z,1325713253.6924 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfacePitch = nan arcdeg
2012-01-04T21:40:53.69970Z,1325713253.6997 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfaceSpeed = 0.5 m/s
2012-01-04T21:40:53.70290Z,1325713253.7029 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.IridiumTimeout = 30 min
2012-01-04T21:40:53.70400Z,1325713253.704 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-01-04T21:40:53.73090Z,1325713253.7309 [ballast_and_trim:F.SetSpeed](DEBUG): Construct.
2012-01-04T21:40:53.74040Z,1325713253.7404 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Construct.
2012-01-04T21:40:53.79350Z,1325713253.7935 [ballast_and_trim:ballast:C.Pitch](DEBUG): Construct.
2012-01-04T21:40:53.80620Z,1325713253.8062 [ballast_and_trim:ballast:D.Wait](DEBUG): Construct Wait.
2012-01-04T21:40:53.82190Z,1325713253.8219 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Construct Wait.
2012-01-04T21:40:53.82590Z,1325713253.8259 [ballast_and_trim:ballast:Float_Up:A.SetSpeed](DEBUG): Construct.
2012-01-04T21:40:53.82950Z,1325713253.8295 [ballast_and_trim:ballast:Float_Up:B.Buoyancy](DEBUG): Construct Buoyancy.
2012-01-04T21:40:53.84460Z,1325713253.8446 [ballast_and_trim:ballast:Float_Up:C.Wait](DEBUG): Construct Wait.
2012-01-04T21:40:53.86120Z,1325713253.8612 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Trigger="Tethys/Trigger" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Trigger http://aosn.mbari.org/tethys/Xml/Trigger.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="ballast_and_trim">

<!-- The following arguments are input arguments -->

    <DefineArg Name="BallastDepth"><Units:meter/><Value>25.0</Value></DefineArg>

    <DefineArg Name="HoldDuration"><Units:minute/><Value>25</Value></DefineArg>

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

    <DefineArg Name="DepthDeadband"><Units:meter/><Value>4.0</Value></DefineArg>

    <DefineArg Name="BuoyPeriod"><Units:second/><Value>5.0</Value></DefineArg>

    <DefineArg Name="BuoyancyDefault"><CustomUri Uri="Config/Control.buoyancyDefault"/></DefineArg>

<!-- The timeout -->

    <Timeout Duration="P90M"/>

<!-- And now the mission -->

    <Guidance:VerticalControlConfig RunIn="Parallel">
        <Setting><Guidance:VerticalControlConfig.kpPitchMass/><Units:count/><Value>0.01</Value></Setting>
        <Setting><Guidance:VerticalControlConfig.kiPitchMass/><Units:reciprocal_second/><Value>0.0015</Value></Setting>
        <Setting><Guidance:VerticalControlConfig.kdPitchMass/><Units:second/><Value>0</Value></Setting>
    </Guidance:VerticalControlConfig>

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

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

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

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

    <Guidance:SetSpeed>
        <While><Universal:platform_propeller_rotation_rate/>
            <Eq><Units:radian_per_second/><Value>0</Value></Eq>
        </While>
        <Setting><Guidance:SetSpeed.period/><Arg Name="BuoyPeriod"/></Setting>
    </Guidance:SetSpeed>

    <Aggregate Id="ballast">

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

        <Guidance:VerticalControlConfig RunIn="Parallel">
            <Setting><Guidance:VerticalControlConfig.depthDeadband/><Arg Name="DepthDeadband"/></Setting>
        </Guidance:VerticalControlConfig>

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

        <Guidance:Wait RunIn="Sequence">
            <Setting><Guidance:Wait.duration/><Arg Name="HoldDuration"/></Setting>
        </Guidance:Wait>

        <Aggregate Id="ReportPositions" Repeat="5" >

            <Syslog Severity="Important">Buoyancy:<Universal:platform_buoyancy_position/><Units:cubic_centimeter/>
            </Syslog>

            <Syslog Severity="Important">Mass:<Universal:platform_mass_position/><Units:centimeter/>
            </Syslog>

            <Syslog Severity="Important">Pitch:<Universal:platform_pitch_angle/><Units:degree/>
            </Syslog>

            <Guidance:Wait RunIn="Sequence">
                <Timeout Duration="P1M"></Timeout>
            </Guidance:Wait>

        </Aggregate>

        <Aggregate Id="Float_Up">

            <Until><Universal:depth/>
                <Lt><Units:meter/><Value>1</Value></Lt>
            </Until>

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

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

            <Guidance:Wait RunIn="Sequence">
                <Timeout Duration="P15M"></Timeout>
            </Guidance:Wait>

        </Aggregate>

    </Aggregate>

</Mission>


2012-01-04T21:40:53.86170Z,1325713253.8617 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/ballast_and_trim.xml
2012-01-04T21:40:53.98460Z,1325713253.9846 [Default] Stopped
2012-01-04T21:40:53.98480Z,1325713253.9848 [Default](INFO): Aggregate::uninitialize Default
2012-01-04T21:40:53.98490Z,1325713253.9849 [Default:GPS] Stopped
2012-01-04T21:40:53.98500Z,1325713253.985 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T21:40:53.98510Z,1325713253.9851 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T21:40:53.98520Z,1325713253.9852 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T21:40:53.98530Z,1325713253.9853 [Default:GPS:Read_GPS] Stopped
2012-01-04T21:40:53.98530Z,1325713253.9853 [Default:Iridium] Stopped
2012-01-04T21:40:53.98560Z,1325713253.9856 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-04T21:40:53.98560Z,1325713253.9856 [Default:Iridium:A.SetSpeed] Stopped
2012-01-04T21:40:53.98570Z,1325713253.9857 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T21:40:53.98580Z,1325713253.9858 [Default:Iridium:Read_Iridium] Stopped
2012-01-04T21:40:53.98590Z,1325713253.9859 [Default:CallGPS] Stopped
2012-01-04T21:40:53.98600Z,1325713253.986 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T21:40:53.98610Z,1325713253.9861 [Default:CallGPS:A] Stopped
2012-01-04T21:40:53.98620Z,1325713253.9862 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T21:40:53.98630Z,1325713253.9863 [Default:CallIridium] Stopped
2012-01-04T21:40:53.98640Z,1325713253.9864 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-04T21:40:53.98640Z,1325713253.9864 [Default:CallIridium:A] Stopped
2012-01-04T21:40:53.98660Z,1325713253.9866 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-04T21:40:53.98670Z,1325713253.9867 [Default:E.SetSpeed] Stopped
2012-01-04T21:40:53.98690Z,1325713253.9869 [Default:E.SetSpeed](DEBUG): Uninitialize.
2012-01-04T21:40:53.98700Z,1325713253.987 [Default:F.GoToSurface] Stopped
2012-01-04T21:40:53.98700Z,1325713253.987 [Default:F.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T21:40:53.98710Z,1325713253.9871 [Default:G.Wait] Stopped
2012-01-04T21:40:53.98720Z,1325713253.9872 [Default:G.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T21:40:53.98730Z,1325713253.9873 [MissionManager](IMPORTANT): Started mission ballast_and_trim
2012-01-04T21:40:53.98740Z,1325713253.9874 [ballast_and_trim] Running Loop=1
2012-01-04T21:40:53.98760Z,1325713253.9876 [ballast_and_trim](INFO): Aggregate::initialize ballast_and_trim
2012-01-04T21:40:53.98770Z,1325713253.9877 [ballast_and_trim:A.VerticalControlConfig] Running Loop=1
2012-01-04T21:40:53.98790Z,1325713253.9879 [ballast_and_trim:B.AltitudeEnvelope] Running Loop=1
2012-01-04T21:40:53.98800Z,1325713253.988 [ballast_and_trim:B.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-01-04T21:40:53.98830Z,1325713253.9883 [ballast_and_trim:C.DepthEnvelope] Running Loop=1
2012-01-04T21:40:53.98840Z,1325713253.9884 [ballast_and_trim:C.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-01-04T21:40:53.99000Z,1325713253.99 [ballast_and_trim:D.OffshoreEnvelope] Running Loop=1
2012-01-04T21:40:53.99010Z,1325713253.9901 [ballast_and_trim:D.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2012-01-04T21:40:53.99020Z,1325713253.9902 [ballast_and_trim:F.SetSpeed] Running Loop=1
2012-01-04T21:40:53.99030Z,1325713253.9903 [ballast_and_trim:F.SetSpeed](DEBUG): Initialize.
2012-01-04T21:40:53.99060Z,1325713253.9906 [ballast_and_trim:SurfaceComms] Running Loop=1
2012-01-04T21:40:53.99080Z,1325713253.9908 [ballast_and_trim:SurfaceComms](INFO): Aggregate::initialize ballast_and_trim:SurfaceComms
2012-01-04T21:40:53.99100Z,1325713253.991 [ballast_and_trim:SurfaceComms:A.GoToSurface] Running Loop=1
2012-01-04T21:40:53.99110Z,1325713253.9911 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T21:40:53.99200Z,1325713253.992 [ballast_and_trim:F.SetSpeed] Running Loop=1
2012-01-04T21:40:54.00100Z,1325713254.001 [ballast_and_trim:SurfaceComms:B] Running Loop=1
2012-01-04T21:40:54.00110Z,1325713254.0011 [ballast_and_trim:SurfaceComms:B](INFO): Aggregate::initialize ballast_and_trim:SurfaceComms:B
2012-01-04T21:40:54.00130Z,1325713254.0013 [ballast_and_trim:SurfaceComms:B:A] Running Loop=1
2012-01-04T21:40:54.00140Z,1325713254.0014 [ballast_and_trim:D.OffshoreEnvelope] Running Loop=1
2012-01-04T21:40:54.00630Z,1325713254.0063 [ballast_and_trim:C.DepthEnvelope] Running Loop=1
2012-01-04T21:40:54.01130Z,1325713254.0113 [ballast_and_trim:B.AltitudeEnvelope] Running Loop=1
2012-01-04T21:40:54.01610Z,1325713254.0161 [ballast_and_trim:A.VerticalControlConfig] Running Loop=1
2012-01-04T21:40:59.10430Z,1325713259.1043 [ballast_and_trim:F.SetSpeed] Preempted
2012-01-04T21:40:59.10510Z,1325713259.1051 [ballast_and_trim:SurfaceComms:B:A](DEBUG): Initialize ReadDataComponent to sense time_fix
2012-01-04T21:42:13.12930Z,1325713333.1293 [NAL9601](IMPORTANT): GPS fix at: 1325713333
2012-01-04T21:42:13.14340Z,1325713333.1434 [ballast_and_trim:SurfaceComms:B:A] Stopped
2012-01-04T21:42:13.14360Z,1325713333.1436 [ballast_and_trim:SurfaceComms:B:B] Running Loop=1
2012-01-04T21:42:13.53810Z,1325713333.5381 [ballast_and_trim:SurfaceComms:B:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-01-04T21:42:31.12170Z,1325713351.1217 [NAL9601](INFO): SBD MO Status=1, MOMSN=40212, MT Status=0, MTMSN=0
2012-01-04T21:42:31.31520Z,1325713351.3152 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0003.lzma
2012-01-04T21:42:31.31540Z,1325713351.3154 [NAL9601](INFO): Packets left to send: 1
2012-01-04T21:42:31.31730Z,1325713351.3173 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000012
2012-01-04T21:42:40.39760Z,1325713360.3976 [NAL9601](INFO): SBD MO Status=1, MOMSN=40213, MT Status=0, MTMSN=0
2012-01-04T21:42:40.60710Z,1325713360.6071 [NAL9601](INFO): Sent 3 bytes from file Logs/20120104T212427/shore0003.lzma
2012-01-04T21:42:40.60740Z,1325713360.6074 [NAL9601](INFO): Packets left to send: 0
2012-01-04T21:42:40.60840Z,1325713360.6084 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000013
2012-01-04T21:42:48.81020Z,1325713368.8102 [NAL9601](INFO): SBD MO Status=0, MOMSN=40214, MT Status=0, MTMSN=0
2012-01-04T21:43:00.79970Z,1325713380.7997 [NAL9601](INFO): SBD MO Status=1, MOMSN=40215, MT Status=0, MTMSN=0
2012-01-04T21:43:00.97130Z,1325713380.9713 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0004.lzma
2012-01-04T21:43:00.97150Z,1325713380.9715 [NAL9601](INFO): Packets left to send: 2
2012-01-04T21:43:00.97260Z,1325713380.9726 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000014
2012-01-04T21:43:11.28160Z,1325713391.2816 [NAL9601](INFO): SBD MO Status=1, MOMSN=40216, MT Status=0, MTMSN=0
2012-01-04T21:43:11.45520Z,1325713391.4552 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0004.lzma
2012-01-04T21:43:11.45540Z,1325713391.4554 [NAL9601](INFO): Packets left to send: 1
2012-01-04T21:43:11.45650Z,1325713391.4565 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000015
2012-01-04T21:43:18.29780Z,1325713398.2978 [NAL9601](INFO): SBD MO Status=1, MOMSN=40217, MT Status=0, MTMSN=0
2012-01-04T21:43:18.44330Z,1325713398.4433 [NAL9601](INFO): Sent 7 bytes from file Logs/20120104T212427/shore0004.lzma
2012-01-04T21:43:18.44350Z,1325713398.4435 [NAL9601](INFO): Packets left to send: 0
2012-01-04T21:43:18.44460Z,1325713398.4446 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000016
2012-01-04T21:43:23.49800Z,1325713403.498 [NAL9601](INFO): SBD MO Status=0, MOMSN=40218, MT Status=0, MTMSN=0
2012-01-04T21:43:23.64840Z,1325713403.6484 [ballast_and_trim:SurfaceComms:B:B] Stopped
2012-01-04T21:43:23.64850Z,1325713403.6485 [ballast_and_trim:SurfaceComms:B:C] Running Loop=1
2012-01-04T21:43:23.95910Z,1325713403.9591 [ballast_and_trim:SurfaceComms:B:C](DEBUG): Initialize ReadDataComponent to sense time_fix
2012-01-04T21:43:25.90650Z,1325713405.9065 [NAL9601](IMPORTANT): GPS fix at: 1325713406
2012-01-04T21:43:25.92050Z,1325713405.9205 [ballast_and_trim:SurfaceComms:B:C] Stopped
2012-01-04T21:43:25.92070Z,1325713405.9207 [ballast_and_trim:SurfaceComms:B](INFO): Completed ballast_and_trim:SurfaceComms:B
2012-01-04T21:43:25.92080Z,1325713405.9208 [ballast_and_trim:SurfaceComms:B] Stopped
2012-01-04T21:43:25.92100Z,1325713405.921 [ballast_and_trim:SurfaceComms:B](INFO): Aggregate::uninitialize ballast_and_trim:SurfaceComms:B
2012-01-04T21:43:25.92140Z,1325713405.9214 [ballast_and_trim:SurfaceComms](INFO): Completed ballast_and_trim:SurfaceComms
2012-01-04T21:43:25.92150Z,1325713405.9215 [ballast_and_trim:SurfaceComms] Stopped
2012-01-04T21:43:25.92170Z,1325713405.9217 [ballast_and_trim:SurfaceComms](INFO): Aggregate::uninitialize ballast_and_trim:SurfaceComms
2012-01-04T21:43:25.92170Z,1325713405.9217 [ballast_and_trim:SurfaceComms:A.GoToSurface] Stopped
2012-01-04T21:43:25.92180Z,1325713405.9218 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T21:43:25.92200Z,1325713405.922 [ballast_and_trim:ballast] Running Loop=1
2012-01-04T21:43:25.92210Z,1325713405.9221 [ballast_and_trim:ballast](INFO): Aggregate::initialize ballast_and_trim:ballast
2012-01-04T21:43:25.92220Z,1325713405.9222 [ballast_and_trim:ballast:A.SetSpeed] Running Loop=1
2012-01-04T21:43:25.92230Z,1325713405.9223 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Initialize.
2012-01-04T21:43:25.92240Z,1325713405.9224 [ballast_and_trim:ballast:B.VerticalControlConfig] Running Loop=1
2012-01-04T21:43:25.92280Z,1325713405.9228 [ballast_and_trim:ballast:C.Pitch] Running Loop=1
2012-01-04T21:43:25.92280Z,1325713405.9228 [ballast_and_trim:ballast:C.Pitch](DEBUG): Initialize.
2012-01-04T21:43:25.92320Z,1325713405.9232 [ballast_and_trim:ballast:D.Wait] Running Loop=1
2012-01-04T21:43:25.92330Z,1325713405.9233 [ballast_and_trim:ballast:D.Wait](DEBUG): Initialize Wait Component.
2012-01-04T21:43:26.40910Z,1325713406.4091 [ballast_and_trim:ballast:C.Pitch] Running Loop=1
2012-01-04T21:43:26.41390Z,1325713406.4139 [ballast_and_trim:ballast:B.VerticalControlConfig] Running Loop=1
2012-01-04T21:43:26.41850Z,1325713406.4185 [ballast_and_trim:ballast:A.SetSpeed] Running Loop=1
2012-01-04T21:43:26.42290Z,1325713406.4229 [ballast_and_trim:F.SetSpeed] Running Loop=1
2012-01-04T21:43:46.49340Z,1325713426.4934 [NAL9601](INFO): Powering down
2012-01-04T21:50:51.46740Z,1325713851.4674 [Batt_Ocean_Server](INFO): Over Temperature Alarm! Battery Bank #9 STATUS: 5911
2012-01-04T21:50:51.46780Z,1325713851.4678 [Batt_Ocean_Server](INFO): Not Initialized - Battery Bank #9 STATUS: 5911
2012-01-04T22:08:26.56410Z,1325714906.5641 [ballast_and_trim:ballast:D.Wait](INFO): Done Waiting.
2012-01-04T22:08:26.56440Z,1325714906.5644 [ballast_and_trim:ballast:D.Wait] Stopped
2012-01-04T22:08:26.56450Z,1325714906.5645 [ballast_and_trim:ballast:D.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:08:26.56470Z,1325714906.5647 [ballast_and_trim:ballast:ReportPositions] Running Loop=1
2012-01-04T22:08:26.56480Z,1325714906.5648 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-01-04T22:08:26.56500Z,1325714906.565 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-01-04T22:08:31.47420Z,1325714911.4742 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 363.5400499 cc 
2012-01-04T22:08:31.47560Z,1325714911.4756 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-01-04T22:08:31.47580Z,1325714911.4758 [ballast_and_trim:ballast:ReportPositions:B] Running Loop=1
2012-01-04T22:08:36.48790Z,1325714916.4879 [ballast_and_trim:ballast:ReportPositions:B](IMPORTANT): Mass: 0.2466050908 cm 
2012-01-04T22:08:36.48930Z,1325714916.4893 [ballast_and_trim:ballast:ReportPositions:B] Stopped
2012-01-04T22:08:36.48950Z,1325714916.4895 [ballast_and_trim:ballast:ReportPositions:C] Running Loop=1
2012-01-04T22:08:41.49770Z,1325714921.4977 [ballast_and_trim:ballast:ReportPositions:C](IMPORTANT): Pitch: -0.397343747 arcdeg 
2012-01-04T22:08:41.49910Z,1325714921.4991 [ballast_and_trim:ballast:ReportPositions:C] Stopped
2012-01-04T22:08:41.49920Z,1325714921.4992 [ballast_and_trim:ballast:ReportPositions:D.Wait] Running Loop=1
2012-01-04T22:08:41.49930Z,1325714921.4993 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:09:41.63900Z,1325714981.639 [ballast_and_trim:ballast:ReportPositions:D.Wait](INFO): Timed out from 2012-01-04T22:08:41.Z
2012-01-04T22:09:41.63910Z,1325714981.6391 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-01-04T22:09:41.63930Z,1325714981.6393 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-01-04T22:09:41.63960Z,1325714981.6396 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-01-04T22:09:41.63970Z,1325714981.6397 [ballast_and_trim:ballast:ReportPositions:D.Wait] Stopped
2012-01-04T22:09:41.63980Z,1325714981.6398 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:09:41.64000Z,1325714981.64 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-01-04T22:09:41.64010Z,1325714981.6401 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-01-04T22:09:41.64020Z,1325714981.6402 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-01-04T22:09:41.64040Z,1325714981.6404 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #2
2012-01-04T22:09:41.64050Z,1325714981.6405 [ballast_and_trim:ballast:ReportPositions] Running Loop=2
2012-01-04T22:09:41.64070Z,1325714981.6407 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-01-04T22:09:41.64080Z,1325714981.6408 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-01-04T22:09:46.47920Z,1325714986.4792 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 363.5400499 cc 
2012-01-04T22:09:46.47930Z,1325714986.4793 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-01-04T22:09:46.47950Z,1325714986.4795 [ballast_and_trim:ballast:ReportPositions:B] Running Loop=1
2012-01-04T22:09:51.51720Z,1325714991.5172 [ballast_and_trim:ballast:ReportPositions:B](IMPORTANT): Mass: 0.2099448116 cm 
2012-01-04T22:09:51.51730Z,1325714991.5173 [ballast_and_trim:ballast:ReportPositions:B] Stopped
2012-01-04T22:09:51.51750Z,1325714991.5175 [ballast_and_trim:ballast:ReportPositions:C] Running Loop=1
2012-01-04T22:09:56.63810Z,1325714996.6381 [ballast_and_trim:ballast:ReportPositions:C](IMPORTANT): Pitch: -0.001835933505 arcdeg 
2012-01-04T22:09:56.63840Z,1325714996.6384 [ballast_and_trim:ballast:ReportPositions:C] Stopped
2012-01-04T22:09:56.63850Z,1325714996.6385 [ballast_and_trim:ballast:ReportPositions:D.Wait] Running Loop=1
2012-01-04T22:09:56.63870Z,1325714996.6387 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:11:01.51420Z,1325715061.5142 [ballast_and_trim:ballast:ReportPositions:D.Wait](INFO): Timed out from 2012-01-04T22:09:56.Z
2012-01-04T22:11:01.51430Z,1325715061.5143 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-01-04T22:11:01.51450Z,1325715061.5145 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-01-04T22:11:01.51480Z,1325715061.5148 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-01-04T22:11:01.51490Z,1325715061.5149 [ballast_and_trim:ballast:ReportPositions:D.Wait] Stopped
2012-01-04T22:11:01.51500Z,1325715061.515 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:11:01.51520Z,1325715061.5152 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-01-04T22:11:01.51520Z,1325715061.5152 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-01-04T22:11:01.51540Z,1325715061.5154 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-01-04T22:11:01.51560Z,1325715061.5156 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #3
2012-01-04T22:11:01.51570Z,1325715061.5157 [ballast_and_trim:ballast:ReportPositions] Running Loop=3
2012-01-04T22:11:01.51580Z,1325715061.5158 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-01-04T22:11:01.51590Z,1325715061.5159 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-01-04T22:11:06.49110Z,1325715066.4911 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 363.5400499 cc 
2012-01-04T22:11:06.49130Z,1325715066.4913 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-01-04T22:11:06.49150Z,1325715066.4915 [ballast_and_trim:ballast:ReportPositions:B] Running Loop=1
2012-01-04T22:11:11.46880Z,1325715071.4688 [ballast_and_trim:ballast:ReportPositions:B](IMPORTANT): Mass: 0.2019963693 cm 
2012-01-04T22:11:11.46890Z,1325715071.4689 [ballast_and_trim:ballast:ReportPositions:B] Stopped
2012-01-04T22:11:11.46910Z,1325715071.4691 [ballast_and_trim:ballast:ReportPositions:C] Running Loop=1
2012-01-04T22:11:16.50360Z,1325715076.5036 [ballast_and_trim:ballast:ReportPositions:C](IMPORTANT): Pitch: 0.4156445452 arcdeg 
2012-01-04T22:11:16.50380Z,1325715076.5038 [ballast_and_trim:ballast:ReportPositions:C] Stopped
2012-01-04T22:11:16.50400Z,1325715076.504 [ballast_and_trim:ballast:ReportPositions:D.Wait] Running Loop=1
2012-01-04T22:11:16.50410Z,1325715076.5041 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:12:21.50520Z,1325715141.5052 [ballast_and_trim:ballast:ReportPositions:D.Wait](INFO): Timed out from 2012-01-04T22:11:16.Z
2012-01-04T22:12:21.50530Z,1325715141.5053 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-01-04T22:12:21.50540Z,1325715141.5054 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-01-04T22:12:21.50570Z,1325715141.5057 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-01-04T22:12:21.50570Z,1325715141.5057 [ballast_and_trim:ballast:ReportPositions:D.Wait] Stopped
2012-01-04T22:12:21.50580Z,1325715141.5058 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:12:21.50600Z,1325715141.506 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-01-04T22:12:21.50610Z,1325715141.5061 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-01-04T22:12:21.50630Z,1325715141.5063 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-01-04T22:12:21.50650Z,1325715141.5065 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #4
2012-01-04T22:12:21.50670Z,1325715141.5067 [ballast_and_trim:ballast:ReportPositions] Running Loop=4
2012-01-04T22:12:21.50690Z,1325715141.5069 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-01-04T22:12:21.50700Z,1325715141.507 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-01-04T22:12:26.71380Z,1325715146.7138 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 363.5400499 cc 
2012-01-04T22:12:26.71400Z,1325715146.714 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-01-04T22:12:26.71420Z,1325715146.7142 [ballast_and_trim:ballast:ReportPositions:B] Running Loop=1
2012-01-04T22:12:31.73760Z,1325715151.7376 [ballast_and_trim:ballast:ReportPositions:B](IMPORTANT): Mass: 0.1793675823 cm 
2012-01-04T22:12:31.73780Z,1325715151.7378 [ballast_and_trim:ballast:ReportPositions:B] Stopped
2012-01-04T22:12:31.73790Z,1325715151.7379 [ballast_and_trim:ballast:ReportPositions:C] Running Loop=1
2012-01-04T22:12:36.48080Z,1325715156.4808 [ballast_and_trim:ballast:ReportPositions:C](IMPORTANT): Pitch: -0.3753710818 arcdeg 
2012-01-04T22:12:36.48110Z,1325715156.4811 [ballast_and_trim:ballast:ReportPositions:C] Stopped
2012-01-04T22:12:36.48120Z,1325715156.4812 [ballast_and_trim:ballast:ReportPositions:D.Wait] Running Loop=1
2012-01-04T22:12:36.48130Z,1325715156.4813 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:13:36.51970Z,1325715216.5197 [ballast_and_trim:ballast:ReportPositions:D.Wait](INFO): Timed out from 2012-01-04T22:12:36.Z
2012-01-04T22:13:36.51990Z,1325715216.5199 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-01-04T22:13:36.52000Z,1325715216.52 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-01-04T22:13:36.52030Z,1325715216.5203 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-01-04T22:13:36.52030Z,1325715216.5203 [ballast_and_trim:ballast:ReportPositions:D.Wait] Stopped
2012-01-04T22:13:36.52040Z,1325715216.5204 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:13:36.52060Z,1325715216.5206 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-01-04T22:13:36.52070Z,1325715216.5207 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-01-04T22:13:36.52080Z,1325715216.5208 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-01-04T22:13:36.52110Z,1325715216.5211 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #5
2012-01-04T22:13:36.52110Z,1325715216.5211 [ballast_and_trim:ballast:ReportPositions] Running Loop=5
2012-01-04T22:13:36.52130Z,1325715216.5213 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-01-04T22:13:36.52140Z,1325715216.5214 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-01-04T22:13:41.60070Z,1325715221.6007 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 361.3912268 cc 
2012-01-04T22:13:41.60090Z,1325715221.6009 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-01-04T22:13:41.60110Z,1325715221.6011 [ballast_and_trim:ballast:ReportPositions:B] Running Loop=1
2012-01-04T22:13:46.53620Z,1325715226.5362 [ballast_and_trim:ballast:ReportPositions:B](IMPORTANT): Mass: 0.1695131068 cm 
2012-01-04T22:13:46.53650Z,1325715226.5365 [ballast_and_trim:ballast:ReportPositions:B] Stopped
2012-01-04T22:13:46.53660Z,1325715226.5366 [ballast_and_trim:ballast:ReportPositions:C] Running Loop=1
2012-01-04T22:13:51.49760Z,1325715231.4976 [ballast_and_trim:ballast:ReportPositions:C](IMPORTANT): Pitch: -0.3314257514 arcdeg 
2012-01-04T22:13:51.49780Z,1325715231.4978 [ballast_and_trim:ballast:ReportPositions:C] Stopped
2012-01-04T22:13:51.49800Z,1325715231.498 [ballast_and_trim:ballast:ReportPositions:D.Wait] Running Loop=1
2012-01-04T22:13:51.49800Z,1325715231.498 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:14:51.57250Z,1325715291.5725 [ballast_and_trim:ballast:ReportPositions:D.Wait](INFO): Timed out from 2012-01-04T22:13:51.Z
2012-01-04T22:14:51.57260Z,1325715291.5726 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-01-04T22:14:51.57280Z,1325715291.5728 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-01-04T22:14:51.57300Z,1325715291.573 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-01-04T22:14:51.57310Z,1325715291.5731 [ballast_and_trim:ballast:ReportPositions:D.Wait] Stopped
2012-01-04T22:14:51.57320Z,1325715291.5732 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:14:51.57340Z,1325715291.5734 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-01-04T22:14:51.57350Z,1325715291.5735 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-01-04T22:14:51.57360Z,1325715291.5736 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-01-04T22:14:51.57380Z,1325715291.5738 [ballast_and_trim:ballast:Float_Up] Running Loop=1
2012-01-04T22:14:51.57390Z,1325715291.5739 [ballast_and_trim:ballast:Float_Up](INFO): Aggregate::initialize ballast_and_trim:ballast:Float_Up
2012-01-04T22:14:51.57400Z,1325715291.574 [ballast_and_trim:ballast:Float_Up:A.SetSpeed] Running Loop=1
2012-01-04T22:14:51.57410Z,1325715291.5741 [ballast_and_trim:ballast:Float_Up:A.SetSpeed](DEBUG): Initialize.
2012-01-04T22:14:51.57420Z,1325715291.5742 [ballast_and_trim:ballast:Float_Up:B.Buoyancy] Running Loop=1
2012-01-04T22:14:51.57430Z,1325715291.5743 [ballast_and_trim:ballast:Float_Up:B.Buoyancy](DEBUG): Initialize Buoyancy Component.
2012-01-04T22:14:51.57500Z,1325715291.575 [ballast_and_trim:ballast:Float_Up:C.Wait] Running Loop=1
2012-01-04T22:14:51.57510Z,1325715291.5751 [ballast_and_trim:ballast:Float_Up:C.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:14:56.48340Z,1325715296.4834 [ballast_and_trim:ballast:Float_Up:B.Buoyancy] Running Loop=1
2012-01-04T22:14:56.48800Z,1325715296.488 [ballast_and_trim:ballast:Float_Up:A.SetSpeed] Running Loop=1
2012-01-04T22:20:06.46410Z,1325715606.4641 [ballast_and_trim:ballast:Float_Up] Stopped
2012-01-04T22:20:06.46430Z,1325715606.4643 [ballast_and_trim:ballast:Float_Up](INFO): Aggregate::uninitialize ballast_and_trim:ballast:Float_Up
2012-01-04T22:20:06.46440Z,1325715606.4644 [ballast_and_trim:ballast:Float_Up:A.SetSpeed] Stopped
2012-01-04T22:20:06.46450Z,1325715606.4645 [ballast_and_trim:ballast:Float_Up:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:20:06.46460Z,1325715606.4646 [ballast_and_trim:ballast:Float_Up:B.Buoyancy] Stopped
2012-01-04T22:20:06.46460Z,1325715606.4646 [ballast_and_trim:ballast:Float_Up:B.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2012-01-04T22:20:06.46470Z,1325715606.4647 [ballast_and_trim:ballast:Float_Up:C.Wait] Stopped
2012-01-04T22:20:06.46480Z,1325715606.4648 [ballast_and_trim:ballast:Float_Up:C.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:20:06.46570Z,1325715606.4657 [ballast_and_trim:ballast](INFO): Completed ballast_and_trim:ballast
2012-01-04T22:20:06.46580Z,1325715606.4658 [ballast_and_trim:ballast] Stopped
2012-01-04T22:20:06.46590Z,1325715606.4659 [ballast_and_trim:ballast](INFO): Aggregate::uninitialize ballast_and_trim:ballast
2012-01-04T22:20:06.46600Z,1325715606.466 [ballast_and_trim:ballast:A.SetSpeed] Stopped
2012-01-04T22:20:06.46610Z,1325715606.4661 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:20:06.46610Z,1325715606.4661 [ballast_and_trim:ballast:B.VerticalControlConfig] Stopped
2012-01-04T22:20:06.46620Z,1325715606.4662 [ballast_and_trim:ballast:C.Pitch] Stopped
2012-01-04T22:20:06.46760Z,1325715606.4676 [ballast_and_trim](INFO): Completed ballast_and_trim
2012-01-04T22:20:06.46770Z,1325715606.4677 [ballast_and_trim] Stopped
2012-01-04T22:20:06.46780Z,1325715606.4678 [ballast_and_trim](INFO): Aggregate::uninitialize ballast_and_trim
2012-01-04T22:20:06.46790Z,1325715606.4679 [ballast_and_trim:A.VerticalControlConfig] Stopped
2012-01-04T22:20:06.46800Z,1325715606.468 [ballast_and_trim:B.AltitudeEnvelope] Stopped
2012-01-04T22:20:06.46800Z,1325715606.468 [ballast_and_trim:B.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-01-04T22:20:06.46810Z,1325715606.4681 [ballast_and_trim:C.DepthEnvelope] Stopped
2012-01-04T22:20:06.46820Z,1325715606.4682 [ballast_and_trim:C.DepthEnvelope](DEBUG): Uninitialize.
2012-01-04T22:20:06.46820Z,1325715606.4682 [ballast_and_trim:D.OffshoreEnvelope] Stopped
2012-01-04T22:20:06.46830Z,1325715606.4683 [ballast_and_trim:D.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2012-01-04T22:20:06.46840Z,1325715606.4684 [ballast_and_trim:F.SetSpeed] Stopped
2012-01-04T22:20:06.46850Z,1325715606.4685 [ballast_and_trim:F.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:20:11.52150Z,1325715611.5215 [MissionManager](IMPORTANT): Started mission Default
2012-01-04T22:20:11.52160Z,1325715611.5216 [Default] Running Loop=1
2012-01-04T22:20:11.52170Z,1325715611.5217 [Default](INFO): Aggregate::initialize Default
2012-01-04T22:20:11.52180Z,1325715611.5218 [Default:E.SetSpeed] Running Loop=1
2012-01-04T22:20:11.52190Z,1325715611.5219 [Default:E.SetSpeed](DEBUG): Initialize.
2012-01-04T22:20:11.52200Z,1325715611.522 [Default:F.GoToSurface] Running Loop=1
2012-01-04T22:20:11.52210Z,1325715611.5221 [Default:F.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T22:20:11.52280Z,1325715611.5228 [Default:GPS] Running Loop=1
2012-01-04T22:20:11.52300Z,1325715611.523 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T22:20:11.52310Z,1325715611.5231 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T22:20:11.52320Z,1325715611.5232 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T22:20:11.52330Z,1325715611.5233 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T22:20:11.52340Z,1325715611.5234 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T22:20:11.52490Z,1325715611.5249 [Default:CallIridium] Running Loop=1
2012-01-04T22:20:11.52510Z,1325715611.5251 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-04T22:20:11.52520Z,1325715611.5252 [Default:CallIridium:A] Running Loop=1
2012-01-04T22:20:11.52540Z,1325715611.5254 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-04T22:20:11.52550Z,1325715611.5255 [Default:CallGPS] Running Loop=1
2012-01-04T22:20:11.52560Z,1325715611.5256 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T22:20:11.52580Z,1325715611.5258 [Default:CallGPS:A] Running Loop=1
2012-01-04T22:20:11.52590Z,1325715611.5259 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T22:20:11.52630Z,1325715611.5263 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T22:20:11.52630Z,1325715611.5263 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T22:20:11.52650Z,1325715611.5265 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T22:20:11.76010Z,1325715611.7601 [Default:Iridium] Running Loop=1
2012-01-04T22:20:11.76020Z,1325715611.7602 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-04T22:20:11.76030Z,1325715611.7603 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-04T22:20:11.76040Z,1325715611.7604 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-04T22:20:11.76060Z,1325715611.7606 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-04T22:20:11.76070Z,1325715611.7607 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T22:20:11.76140Z,1325715611.7614 [Default:Iridium:B.GoToSurface] Stopped
2012-01-04T22:20:11.76150Z,1325715611.7615 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T22:20:11.76170Z,1325715611.7617 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-04T22:20:12.16450Z,1325715612.1645 [NAL9601](INFO): Powering up
2012-01-04T22:21:17.98720Z,1325715677.9872 [NAL9601](INFO): NAL9601 initialized
2012-01-04T22:21:18.93110Z,1325715678.9311 [NAL9601](IMPORTANT): GPS fix at: 1325715682
2012-01-04T22:21:18.94510Z,1325715678.9451 [Default:GPS:Read_GPS] Stopped
2012-01-04T22:21:18.94540Z,1325715678.9454 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T22:21:18.94550Z,1325715678.9455 [Default:GPS] Stopped
2012-01-04T22:21:18.94570Z,1325715678.9457 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T22:21:18.94570Z,1325715678.9457 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T22:21:18.94580Z,1325715678.9458 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:21:19.33690Z,1325715679.3369 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T22:21:19.33700Z,1325715679.337 [Default:CallGPS:A] Stopped
2012-01-04T22:21:19.33710Z,1325715679.3371 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T22:21:19.33740Z,1325715679.3374 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T22:21:19.33740Z,1325715679.3374 [Default:CallGPS] Stopped
2012-01-04T22:21:19.33760Z,1325715679.3376 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T22:21:19.74720Z,1325715679.7472 [Default:CallGPS] Running Loop=1
2012-01-04T22:21:19.74740Z,1325715679.7474 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T22:21:19.74760Z,1325715679.7476 [Default:CallGPS:A] Running Loop=1
2012-01-04T22:21:19.74770Z,1325715679.7477 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T22:21:20.19970Z,1325715680.1997 [Default:GPS] Running Loop=1
2012-01-04T22:21:20.19980Z,1325715680.1998 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T22:21:20.19990Z,1325715680.1999 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T22:21:20.20000Z,1325715680.2 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T22:21:20.20020Z,1325715680.2002 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T22:21:20.20030Z,1325715680.2003 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T22:21:20.20100Z,1325715680.201 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T22:21:20.20110Z,1325715680.2011 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T22:21:20.20120Z,1325715680.2012 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T22:21:37.60580Z,1325715697.6058 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=40219, MT Status=1, MTMSN=3347
2012-01-04T22:21:37.73530Z,1325715697.7353 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0005.lzma
2012-01-04T22:21:37.73550Z,1325715697.7355 [NAL9601](INFO): Packets left to send: 4
2012-01-04T22:21:37.73660Z,1325715697.7366 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000017
2012-01-04T22:21:38.35530Z,1325715698.3553 [NAL9601](IMPORTANT): Initialized file: Missions/Maintenance/calibrateSparton.xml
2012-01-04T22:21:42.72430Z,1325715702.7243 [NAL9601](IMPORTANT): Success executing cat Logs/latest/4F04CE05.part | gunzip -f -d | cat `cp Missions/Maintenance/.svn/text-base/calibrateSparton.xml.svn-base Missions/Maintenance/calibrateSparton.xml` | vim -e Missions/Maintenance/calibrateSparton.xml
2012-01-04T22:21:42.81200Z,1325715702.812 [CommandLine](IMPORTANT): 5dbfe3213165a6480edb82bf67e50d6e  Missions/Maintenance/calibrateSparton.xml

2012-01-04T22:21:43.72350Z,1325715703.7235 [NAL9601](IMPORTANT): GPS fix at: 1325715707
2012-01-04T22:21:43.73780Z,1325715703.7378 [Default:GPS:Read_GPS] Stopped
2012-01-04T22:21:43.73820Z,1325715703.7382 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T22:21:43.73830Z,1325715703.7383 [Default:GPS] Stopped
2012-01-04T22:21:43.73840Z,1325715703.7384 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T22:21:43.73850Z,1325715703.7385 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T22:21:43.73870Z,1325715703.7387 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:21:44.20620Z,1325715704.2062 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T22:21:44.20630Z,1325715704.2063 [Default:CallGPS:A] Stopped
2012-01-04T22:21:44.20650Z,1325715704.2065 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T22:21:44.20680Z,1325715704.2068 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T22:21:44.20690Z,1325715704.2069 [Default:CallGPS] Stopped
2012-01-04T22:21:44.20700Z,1325715704.207 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T22:21:44.53830Z,1325715704.5383 [Default:CallGPS] Running Loop=1
2012-01-04T22:21:44.53850Z,1325715704.5385 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T22:21:44.53870Z,1325715704.5387 [Default:CallGPS:A] Running Loop=1
2012-01-04T22:21:44.53890Z,1325715704.5389 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T22:21:44.93380Z,1325715704.9338 [Default:GPS] Running Loop=1
2012-01-04T22:21:44.93400Z,1325715704.934 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T22:21:44.93410Z,1325715704.9341 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T22:21:44.93420Z,1325715704.9342 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T22:21:44.93440Z,1325715704.9344 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T22:21:44.93450Z,1325715704.9345 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T22:21:44.93510Z,1325715704.9351 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T22:21:44.93520Z,1325715704.9352 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T22:21:44.93540Z,1325715704.9354 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T22:22:02.21220Z,1325715722.2122 [NAL9601](INFO): SBD MO Status=1, MOMSN=40220, MT Status=0, MTMSN=0
2012-01-04T22:22:02.39520Z,1325715722.3952 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0005.lzma
2012-01-04T22:22:02.39540Z,1325715722.3954 [NAL9601](INFO): Packets left to send: 3
2012-01-04T22:22:02.39650Z,1325715722.3965 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000018
2012-01-04T22:22:15.04900Z,1325715735.049 [NAL9601](INFO): SBD MO Status=1, MOMSN=40221, MT Status=0, MTMSN=0
2012-01-04T22:22:15.17510Z,1325715735.1751 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0005.lzma
2012-01-04T22:22:15.17540Z,1325715735.1754 [NAL9601](INFO): Packets left to send: 2
2012-01-04T22:22:15.17650Z,1325715735.1765 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000019
2012-01-04T22:22:30.39770Z,1325715750.3977 [NAL9601](INFO): SBD MO Status=1, MOMSN=40222, MT Status=0, MTMSN=0
2012-01-04T22:22:30.55120Z,1325715750.5512 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0005.lzma
2012-01-04T22:22:30.55140Z,1325715750.5514 [NAL9601](INFO): Packets left to send: 1
2012-01-04T22:22:30.55250Z,1325715750.5525 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000020
2012-01-04T22:22:40.50570Z,1325715760.5057 [NAL9601](INFO): SBD MO Status=2, MOMSN=40223, MT Status=2, MTMSN=0
2012-01-04T22:22:40.50590Z,1325715760.5059 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-01-04T22:22:41.70310Z,1325715761.7031 [NAL9601](IMPORTANT): GPS fix at: 1325715765
2012-01-04T22:22:41.76160Z,1325715761.7616 [Default:GPS:Read_GPS] Stopped
2012-01-04T22:22:41.76190Z,1325715761.7619 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T22:22:41.76200Z,1325715761.762 [Default:GPS] Stopped
2012-01-04T22:22:41.76220Z,1325715761.7622 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T22:22:41.76230Z,1325715761.7623 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T22:22:41.76230Z,1325715761.7623 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:22:42.15750Z,1325715762.1575 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T22:22:42.15760Z,1325715762.1576 [Default:CallGPS:A] Stopped
2012-01-04T22:22:42.15770Z,1325715762.1577 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T22:22:42.15800Z,1325715762.158 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T22:22:42.15800Z,1325715762.158 [Default:CallGPS] Stopped
2012-01-04T22:22:42.15820Z,1325715762.1582 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T22:22:42.53960Z,1325715762.5396 [Default:CallGPS] Running Loop=1
2012-01-04T22:22:42.53980Z,1325715762.5398 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T22:22:42.53990Z,1325715762.5399 [Default:CallGPS:A] Running Loop=1
2012-01-04T22:22:42.54010Z,1325715762.5401 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T22:22:42.95600Z,1325715762.956 [Default:GPS] Running Loop=1
2012-01-04T22:22:42.95620Z,1325715762.9562 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T22:22:42.95630Z,1325715762.9563 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T22:22:42.95640Z,1325715762.9564 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T22:22:42.95660Z,1325715762.9566 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T22:22:42.95670Z,1325715762.9567 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T22:22:42.95740Z,1325715762.9574 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T22:22:42.95750Z,1325715762.9575 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T22:22:42.95760Z,1325715762.9576 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T22:22:57.60980Z,1325715777.6098 [NAL9601](INFO): SBD MO Status=1, MOMSN=40223, MT Status=0, MTMSN=0
2012-01-04T22:22:57.81120Z,1325715777.8112 [NAL9601](INFO): Sent 56 bytes from file Logs/20120104T212427/shore0005.lzma
2012-01-04T22:22:57.81140Z,1325715777.8114 [NAL9601](INFO): Packets left to send: 0
2012-01-04T22:22:57.81270Z,1325715777.8127 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000021
2012-01-04T22:23:09.60520Z,1325715789.6052 [NAL9601](INFO): SBD MO Status=0, MOMSN=40224, MT Status=0, MTMSN=0
2012-01-04T22:23:10.81120Z,1325715790.8112 [NAL9601](IMPORTANT): GPS fix at: 1325715795
2012-01-04T22:23:10.82490Z,1325715790.8249 [Default:GPS:Read_GPS] Stopped
2012-01-04T22:23:10.82530Z,1325715790.8253 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T22:23:10.82540Z,1325715790.8254 [Default:GPS] Stopped
2012-01-04T22:23:10.82560Z,1325715790.8256 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T22:23:10.82560Z,1325715790.8256 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T22:23:10.82570Z,1325715790.8257 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:23:11.22200Z,1325715791.222 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T22:23:11.22210Z,1325715791.2221 [Default:CallGPS:A] Stopped
2012-01-04T22:23:11.22220Z,1325715791.2222 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T22:23:11.22240Z,1325715791.2224 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T22:23:11.22250Z,1325715791.2225 [Default:CallGPS] Stopped
2012-01-04T22:23:11.22270Z,1325715791.2227 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T22:23:11.65090Z,1325715791.6509 [Default:CallGPS] Running Loop=1
2012-01-04T22:23:11.65110Z,1325715791.6511 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T22:23:11.65130Z,1325715791.6513 [Default:CallGPS:A] Running Loop=1
2012-01-04T22:23:11.65140Z,1325715791.6514 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T22:23:12.01720Z,1325715792.0172 [Default:GPS] Running Loop=1
2012-01-04T22:23:12.01740Z,1325715792.0174 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T22:23:12.01750Z,1325715792.0175 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T22:23:12.01760Z,1325715792.0176 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T22:23:12.01780Z,1325715792.0178 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T22:23:12.01780Z,1325715792.0178 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T22:23:12.01850Z,1325715792.0185 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T22:23:12.01860Z,1325715792.0186 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T22:23:12.01880Z,1325715792.0188 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T22:23:22.40970Z,1325715802.4097 [NAL9601](INFO): SBD MO Status=1, MOMSN=40225, MT Status=0, MTMSN=0
2012-01-04T22:23:22.57120Z,1325715802.5712 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0006.lzma
2012-01-04T22:23:22.57140Z,1325715802.5714 [NAL9601](INFO): Packets left to send: 1
2012-01-04T22:23:22.57250Z,1325715802.5725 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000022
2012-01-04T22:23:35.34580Z,1325715815.3458 [NAL9601](INFO): SBD MO Status=1, MOMSN=40226, MT Status=0, MTMSN=0
2012-01-04T22:23:35.55120Z,1325715815.5512 [NAL9601](INFO): Sent 291 bytes from file Logs/20120104T212427/shore0006.lzma
2012-01-04T22:23:35.55140Z,1325715815.5514 [NAL9601](INFO): Packets left to send: 0
2012-01-04T22:23:35.55260Z,1325715815.5526 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000023
2012-01-04T22:23:46.54510Z,1325715826.5451 [NAL9601](INFO): SBD MO Status=0, MOMSN=40227, MT Status=0, MTMSN=0
2012-01-04T22:23:46.75720Z,1325715826.7572 [Default:Iridium:Read_Iridium] Stopped
2012-01-04T22:23:46.75770Z,1325715826.7577 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-04T22:23:46.75780Z,1325715826.7578 [Default:Iridium] Stopped
2012-01-04T22:23:46.75800Z,1325715826.758 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-04T22:23:46.75800Z,1325715826.758 [Default:Iridium:A.SetSpeed] Stopped
2012-01-04T22:23:46.75810Z,1325715826.7581 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:23:46.75830Z,1325715826.7583 [Default:G.Wait] Running Loop=1
2012-01-04T22:23:46.75830Z,1325715826.7583 [Default:G.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:23:46.93430Z,1325715826.9343 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-04T22:23:46.93440Z,1325715826.9344 [Default:CallIridium:A] Stopped
2012-01-04T22:23:46.93480Z,1325715826.9348 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-04T22:23:46.93500Z,1325715826.935 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-04T22:23:46.93510Z,1325715826.9351 [Default:CallIridium] Stopped
2012-01-04T22:23:46.93530Z,1325715826.9353 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-04T22:23:47.70320Z,1325715827.7032 [NAL9601](IMPORTANT): GPS fix at: 1325715832
2012-01-04T22:23:47.76060Z,1325715827.7606 [Default:GPS:Read_GPS] Stopped
2012-01-04T22:23:47.76110Z,1325715827.7611 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T22:23:47.76120Z,1325715827.7612 [Default:GPS] Stopped
2012-01-04T22:23:47.76140Z,1325715827.7614 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T22:23:47.76140Z,1325715827.7614 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T22:23:47.76150Z,1325715827.7615 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:23:48.16160Z,1325715828.1616 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T22:23:48.16170Z,1325715828.1617 [Default:CallGPS:A] Stopped
2012-01-04T22:23:48.16180Z,1325715828.1618 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T22:23:48.16200Z,1325715828.162 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T22:23:48.16210Z,1325715828.1621 [Default:CallGPS] Stopped
2012-01-04T22:23:48.16230Z,1325715828.1623 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T22:24:08.28620Z,1325715848.2862 [NAL9601](INFO): Powering down
2012-01-04T22:28:48.40000Z,1325716128.4 [Default:CallIridium] Running Loop=1
2012-01-04T22:28:48.40020Z,1325716128.4002 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-04T22:28:48.40030Z,1325716128.4003 [Default:CallIridium:A] Running Loop=1
2012-01-04T22:28:48.40050Z,1325716128.4005 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-04T22:28:48.40060Z,1325716128.4006 [Default:CallGPS] Running Loop=1
2012-01-04T22:28:48.40070Z,1325716128.4007 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T22:28:48.40090Z,1325716128.4009 [Default:CallGPS:A] Running Loop=1
2012-01-04T22:28:48.40100Z,1325716128.401 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T22:28:53.40560Z,1325716133.4056 [Default:Iridium] Running Loop=1
2012-01-04T22:28:53.40580Z,1325716133.4058 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-04T22:28:53.40590Z,1325716133.4059 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-04T22:28:53.40600Z,1325716133.406 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-04T22:28:53.40620Z,1325716133.4062 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-04T22:28:53.40630Z,1325716133.4063 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T22:28:53.41110Z,1325716133.4111 [Default:Iridium:B.GoToSurface] Stopped
2012-01-04T22:28:53.41120Z,1325716133.4112 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T22:28:53.41140Z,1325716133.4114 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-04T22:28:53.41170Z,1325716133.4117 [Default:GPS] Running Loop=1
2012-01-04T22:28:53.41180Z,1325716133.4118 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T22:28:53.41190Z,1325716133.4119 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T22:28:53.41200Z,1325716133.412 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T22:28:53.41220Z,1325716133.4122 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T22:28:53.41230Z,1325716133.4123 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T22:28:53.41290Z,1325716133.4129 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T22:28:53.41290Z,1325716133.4129 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T22:28:53.41310Z,1325716133.4131 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T22:28:53.96840Z,1325716133.9684 [NAL9601](INFO): Powering up
2012-01-04T22:29:59.77930Z,1325716199.7793 [NAL9601](INFO): NAL9601 initialized
2012-01-04T22:30:00.75910Z,1325716200.7591 [NAL9601](IMPORTANT): GPS fix at: 1325716205
2012-01-04T22:30:00.77630Z,1325716200.7763 [Default:GPS:Read_GPS] Stopped
2012-01-04T22:30:00.77670Z,1325716200.7767 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T22:30:00.77680Z,1325716200.7768 [Default:GPS] Stopped
2012-01-04T22:30:00.77690Z,1325716200.7769 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T22:30:00.77700Z,1325716200.777 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T22:30:00.77710Z,1325716200.7771 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:30:01.18760Z,1325716201.1876 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T22:30:01.18770Z,1325716201.1877 [Default:CallGPS:A] Stopped
2012-01-04T22:30:01.18780Z,1325716201.1878 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T22:30:01.18810Z,1325716201.1881 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T22:30:01.18810Z,1325716201.1881 [Default:CallGPS] Stopped
2012-01-04T22:30:01.18830Z,1325716201.1883 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T22:30:01.57520Z,1325716201.5752 [Default:CallGPS] Running Loop=1
2012-01-04T22:30:01.57540Z,1325716201.5754 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T22:30:01.57560Z,1325716201.5756 [Default:CallGPS:A] Running Loop=1
2012-01-04T22:30:01.57570Z,1325716201.5757 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T22:30:02.00800Z,1325716202.008 [Default:GPS] Running Loop=1
2012-01-04T22:30:02.00810Z,1325716202.0081 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T22:30:02.00820Z,1325716202.0082 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T22:30:02.00830Z,1325716202.0083 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T22:30:02.00850Z,1325716202.0085 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T22:30:02.00860Z,1325716202.0086 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T22:30:02.00920Z,1325716202.0092 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T22:30:02.00930Z,1325716202.0093 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T22:30:02.00940Z,1325716202.0094 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T22:30:19.52570Z,1325716219.5257 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=40228, MT Status=1, MTMSN=3348
2012-01-04T22:30:19.73920Z,1325716219.7392 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0007.lzma
2012-01-04T22:30:19.73940Z,1325716219.7394 [NAL9601](INFO): Packets left to send: 1
2012-01-04T22:30:19.74050Z,1325716219.7405 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000024
2012-01-04T22:30:20.16780Z,1325716220.1678 [NAL9601](INFO): Received command:run Maintenance/calibrateSparton.xml
2012-01-04T22:30:20.26310Z,1325716220.2631 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/calibrateSparton.xml
2012-01-04T22:30:20.26340Z,1325716220.2634 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/calibrateSparton.xml
2012-01-04T22:30:20.40420Z,1325716220.4042 [MissionManager](INFO): DefineArg calibrateSparton.MassDefault = 0.0015 n/a
2012-01-04T22:30:20.40740Z,1325716220.4074 [MissionManager](INFO): DefineArg calibrateSparton.Depth = 20 m
2012-01-04T22:30:20.41050Z,1325716220.4105 [MissionManager](INFO): DefineArg calibrateSparton.Speed = 1 m/s
2012-01-04T22:30:20.41360Z,1325716220.4136 [MissionManager](INFO): DefineArg calibrateSparton.WaitDuration = 20 s
2012-01-04T22:30:20.41680Z,1325716220.4168 [MissionManager](INFO): DefineArg calibrateSparton.RudderAngle = 10 arcdeg
2012-01-04T22:30:20.42010Z,1325716220.4201 [MissionManager](INFO): DefineArg calibrateSparton.MagNorthHeading = 15 arcdeg
2012-01-04T22:30:20.42330Z,1325716220.4233 [MissionManager](INFO): DefineArg calibrateSparton.MinAltitude = 7 m
2012-01-04T22:30:20.42630Z,1325716220.4263 [MissionManager](INFO): DefineArg calibrateSparton.MaxDepth = 30 m
2012-01-04T22:30:20.42970Z,1325716220.4297 [MissionManager](INFO): DefineArg calibrateSparton.MinWaterDepth = 15 m
2012-01-04T22:30:20.43290Z,1325716220.4329 [MissionManager](INFO): DefineArg calibrateSparton.MinOffshore = 2000 m
2012-01-04T22:30:20.43620Z,1325716220.4362 [MissionManager](INFO): DefineArg calibrateSparton.NeedCommsTime = 30 min
2012-01-04T22:30:20.44180Z,1325716220.4418 [MissionManager](INFO): DefineArg calibrateSparton.ManualLoops = 1 count
2012-01-04T22:30:20.44510Z,1325716220.4451 [MissionManager](INFO): DefineArg calibrateSparton.AutoLoops = 3 count
2012-01-04T22:30:20.44830Z,1325716220.4483 [MissionManager](INFO): DefineArg calibrateSparton.CheckLoops = 2 count
2012-01-04T22:30:20.45190Z,1325716220.4519 [MissionManager](INFO): DefineArg calibrateSparton.BuoyancyNeutral = 0.000418 n/a
2012-01-04T22:30:20.45520Z,1325716220.4552 [MissionManager](INFO): DefineArg calibrateSparton.TimeoutDuration = 60 min
2012-01-04T22:30:20.45680Z,1325716220.4568 [calibrateSparton:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-01-04T22:30:20.46430Z,1325716220.4643 [calibrateSparton:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-01-04T22:30:20.47250Z,1325716220.4725 [calibrateSparton:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2012-01-04T22:30:20.48230Z,1325716220.4823 [calibrateSparton:E.Buoyancy](DEBUG): Construct Buoyancy.
2012-01-04T22:30:20.48640Z,1325716220.4864 [calibrateSparton:F.SetSpeed](DEBUG): Construct.
2012-01-04T22:30:20.48990Z,1325716220.4899 [calibrateSparton:G.Pitch](DEBUG): Construct.
2012-01-04T22:30:20.49930Z,1325716220.4993 [calibrateSparton:MassOff:A.Pitch](DEBUG): Construct.
2012-01-04T22:30:20.50880Z,1325716220.5088 [calibrateSparton:MassOff:Initialization:A.Point](DEBUG): Construct.
2012-01-04T22:30:20.51610Z,1325716220.5161 [calibrateSparton:MassOff:Initialization:B.Wait](DEBUG): Construct Wait.
2012-01-04T22:30:20.51850Z,1325716220.5185 [calibrateSparton:MassOff:PreCircles:A.Point](DEBUG): Construct.
2012-01-04T22:30:20.52600Z,1325716220.526 [calibrateSparton:MassOff:PreCircles:B.Wait](DEBUG): Construct Wait.
2012-01-04T22:30:20.52780Z,1325716220.5278 [calibrateSparton:MassOff:PreCircles:C.Point](DEBUG): Construct.
2012-01-04T22:30:20.53680Z,1325716220.5368 [calibrateSparton:MassOff:Calibration:Manual_Loop:A.Point](DEBUG): Construct.
2012-01-04T22:30:20.54430Z,1325716220.5443 [calibrateSparton:MassOff:Calibration:Manual_Loop:B.Wait](DEBUG): Construct Wait.
2012-01-04T22:30:20.54590Z,1325716220.5459 [calibrateSparton:MassOff:Calibration:Manual_Loop:C.Point](DEBUG): Construct.
2012-01-04T22:30:20.55340Z,1325716220.5534 [calibrateSparton:MassOff:Calibration:B.Wait](DEBUG): Construct Wait.
2012-01-04T22:30:20.55610Z,1325716220.5561 [calibrateSparton:MassOff:Calibration:Auto_Loop:A.Point](DEBUG): Construct.
2012-01-04T22:30:20.56330Z,1325716220.5633 [calibrateSparton:MassOff:Calibration:Auto_Loop:B.Wait](DEBUG): Construct Wait.
2012-01-04T22:30:20.56490Z,1325716220.5649 [calibrateSparton:MassOff:Calibration:Auto_Loop:C.Point](DEBUG): Construct.
2012-01-04T22:30:20.57250Z,1325716220.5725 [calibrateSparton:MassOff:Calibration:D.CalibrateSparton](DEBUG): Construct CalibrateSparton.
2012-01-04T22:30:20.57440Z,1325716220.5744 [calibrateSparton:MassOff:PostCircles:A.Point](DEBUG): Construct.
2012-01-04T22:30:20.58160Z,1325716220.5816 [calibrateSparton:MassOff:PostCircles:B.Wait](DEBUG): Construct Wait.
2012-01-04T22:30:20.58330Z,1325716220.5833 [calibrateSparton:MassOff:PostCircles:C.Point](DEBUG): Construct.
2012-01-04T22:30:20.59130Z,1325716220.5913 [calibrateSparton:PostCirclesMass:A.Point](DEBUG): Construct.
2012-01-04T22:30:20.59830Z,1325716220.5983 [calibrateSparton:PostCirclesMass:B.Wait](DEBUG): Construct Wait.
2012-01-04T22:30:20.60000Z,1325716220.6 [calibrateSparton:PostCirclesMass:C.Point](DEBUG): Construct.
2012-01-04T22:30:20.61490Z,1325716220.6149 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="utf-8"?>
<Mission xmlns="Tethys" xmlns:Control="Tethys/Control" 
         xmlns:Guidance="Tethys/Guidance" 
         xmlns:Sensor="Tethys/Sensor"
         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/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Sensor http://aosn.mbari.org/tethys/Xml/Sensor.xsd
                             Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
         Id="calibrateSparton">

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

    <DefineArg Name="Depth"><Units:meter /><Value>20.0</Value></DefineArg>

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

    <DefineArg Name="WaitDuration"><Units:second /><Value>20</Value></DefineArg>

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

    <DefineArg Name="MagNorthHeading"><Units:degree /><Value>15</Value></DefineArg>

    <DefineArg Name="MinAltitude"><Units:meter/><Value>7</Value></DefineArg>

    <DefineArg Name="MaxDepth"><Units:meter/><Value>30</Value></DefineArg>

    <DefineArg Name="MinWaterDepth"><Units:meter/><Value>15</Value></DefineArg>

    <DefineArg Name="MinOffshore"><Units:meter/><Value>2000</Value></DefineArg>

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

    <DefineArg Name="ManualLoops"><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="AutoLoops"><Units:count/><Value>3</Value></DefineArg>

    <DefineArg Name="CheckLoops"><Units:count/><Value>2</Value></DefineArg>

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

    <DefineArg Name="TimeoutDuration"><Units:minute/><Value>60</Value></DefineArg>

    <Timeout Duration="TimeoutDuration"/>

    <Guidance:AltitudeEnvelope RunIn="Parallel">
        <Setting><Guidance:AltitudeEnvelope.minAltitude /><Arg Name="MinAltitude"/></Setting>
    </Guidance:AltitudeEnvelope>

    <Guidance:DepthEnvelope RunIn="Parallel">
        <Setting><Guidance:DepthEnvelope.maxDepth /><Arg Name="MaxDepth"/></Setting>
    </Guidance:DepthEnvelope>

    <Guidance:OffshoreEnvelope RunIn="Parallel">
        <Setting><Guidance:OffshoreEnvelope.minOffshore/><Arg Name="MinOffshore"/></Setting>
    </Guidance:OffshoreEnvelope>

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

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

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

    <Guidance:Pitch RunIn="Progression">
        <Setting><Guidance:Pitch.depth /><Arg Name="Depth" /></Setting>
    </Guidance:Pitch>

    <Aggregate Id="MassOff">

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

        <Aggregate Id="Initialization">

            <Guidance:Point RunIn="Progression">
                <Setting><Guidance:Point.heading /><Arg Name="MagNorthHeading" /></Setting>
            </Guidance:Point>

            <Guidance:Wait RunIn="Sequence">
                <Setting><Guidance:Wait.duration /><Arg Name="WaitDuration" /></Setting>
            </Guidance:Wait>

        </Aggregate>

        <Aggregate Id="PreCircles" Repeat = "CheckLoops">

            <Guidance:Point RunIn="Parallel">
                <Setting><Guidance:Point.rudderAngle /><Arg Name="RudderAngle" /></Setting>
            </Guidance:Point>

            <Guidance:Wait RunIn="Sequence">
                <Setting><Guidance:Wait.duration /><Arg Name="WaitDuration" /></Setting>
            </Guidance:Wait>

            <Guidance:Point RunIn="Sequence">
                <Setting><Guidance:Point.heading /><Arg Name="MagNorthHeading" /></Setting>
            </Guidance:Point>

        </Aggregate>

        <Aggregate Id="Calibration">

            <Aggregate Id="Manual_Loop" Repeat="ManualLoops">

                <Guidance:Point RunIn="Parallel">
                    <Setting><Guidance:Point.rudderAngle /><Arg Name="RudderAngle" /></Setting>
                </Guidance:Point>

                <Guidance:Wait RunIn="Sequence">
                    <Setting><Guidance:Wait.duration /><Arg Name="WaitDuration" /></Setting>
                </Guidance:Wait>

                <Guidance:Point RunIn="Sequence">
                    <Setting><Guidance:Point.heading /><Arg Name="MagNorthHeading" /></Setting>
                </Guidance:Point>

            </Aggregate>

            <Guidance:Wait RunIn="Sequence">
                <Preemptive><True/></Preemptive>
                <Setting><Guidance:Wait.duration /><Units:second/><Value>0</Value></Setting>
            </Guidance:Wait>

            <Aggregate Id="Auto_Loop" Repeat="AutoLoops">

                <Guidance:Point RunIn="Parallel">
                    <Setting><Guidance:Point.rudderAngle /><Arg Name="RudderAngle" /></Setting>
                </Guidance:Point>

                <Guidance:Wait RunIn="Sequence">
                    <Setting><Guidance:Wait.duration /><Arg Name="WaitDuration" /></Setting>
                </Guidance:Wait>

                <Guidance:Point RunIn="Sequence">
                    <Setting><Guidance:Point.heading /><Arg Name="MagNorthHeading" /></Setting>
                </Guidance:Point>

            </Aggregate>

            <Sensor:CalibrateSparton RunIn="Parallel"></Sensor:CalibrateSparton>

        </Aggregate>

        <Aggregate Id="PostCircles" Repeat= "CheckLoops">

            <Guidance:Point RunIn="Parallel">
                <Setting><Guidance:Point.rudderAngle /><Arg Name="RudderAngle" /></Setting>
            </Guidance:Point>

            <Guidance:Wait RunIn="Sequence">
                <Setting><Guidance:Wait.duration /><Arg Name="WaitDuration" /></Setting>
            </Guidance:Wait>

            <Guidance:Point RunIn="Sequence">
                <Setting><Guidance:Point.heading /><Arg Name="MagNorthHeading" /></Setting>
            </Guidance:Point>

        </Aggregate>

    </Aggregate>

    <Aggregate Id="PostCirclesMass" Repeat= "CheckLoops">

        <Guidance:Point RunIn="Parallel">
            <Setting><Guidance:Point.rudderAngle /><Arg Name="RudderAngle" /></Setting>
        </Guidance:Point>

        <Guidance:Wait RunIn="Sequence">
            <Setting><Guidance:Wait.duration /><Arg Name="WaitDuration" /></Setting>
        </Guidance:Wait>

        <Guidance:Point RunIn="Sequence">
            <Setting><Guidance:Point.heading /><Arg Name="MagNorthHeading" /></Setting>
        </Guidance:Point>

    </Aggregate>

</Mission>


2012-01-04T22:30:20.61550Z,1325716220.6155 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/calibrateSparton.xml
2012-01-04T22:30:20.76780Z,1325716220.7678 [Default] Stopped
2012-01-04T22:30:20.76800Z,1325716220.768 [Default](INFO): Aggregate::uninitialize Default
2012-01-04T22:30:20.76810Z,1325716220.7681 [Default:GPS] Stopped
2012-01-04T22:30:20.76830Z,1325716220.7683 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T22:30:20.76830Z,1325716220.7683 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T22:30:20.76840Z,1325716220.7684 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:30:20.76850Z,1325716220.7685 [Default:GPS:Read_GPS] Stopped
2012-01-04T22:30:20.76850Z,1325716220.7685 [Default:Iridium] Stopped
2012-01-04T22:30:20.76870Z,1325716220.7687 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-04T22:30:20.76870Z,1325716220.7687 [Default:Iridium:A.SetSpeed] Stopped
2012-01-04T22:30:20.76880Z,1325716220.7688 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:30:20.76890Z,1325716220.7689 [Default:Iridium:Read_Iridium] Stopped
2012-01-04T22:30:20.76890Z,1325716220.7689 [Default:CallGPS] Stopped
2012-01-04T22:30:20.76910Z,1325716220.7691 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T22:30:20.76910Z,1325716220.7691 [Default:CallGPS:A] Stopped
2012-01-04T22:30:20.76930Z,1325716220.7693 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T22:30:20.76940Z,1325716220.7694 [Default:CallIridium] Stopped
2012-01-04T22:30:20.76950Z,1325716220.7695 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-04T22:30:20.76960Z,1325716220.7696 [Default:CallIridium:A] Stopped
2012-01-04T22:30:20.76970Z,1325716220.7697 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-04T22:30:20.76980Z,1325716220.7698 [Default:E.SetSpeed] Stopped
2012-01-04T22:30:20.76980Z,1325716220.7698 [Default:E.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:30:20.76990Z,1325716220.7699 [Default:F.GoToSurface] Stopped
2012-01-04T22:30:20.77000Z,1325716220.77 [Default:F.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T22:30:20.77000Z,1325716220.77 [Default:G.Wait] Stopped
2012-01-04T22:30:20.77010Z,1325716220.7701 [Default:G.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:30:20.77030Z,1325716220.7703 [MissionManager](IMPORTANT): Started mission calibrateSparton
2012-01-04T22:30:20.77040Z,1325716220.7704 [calibrateSparton] Running Loop=1
2012-01-04T22:30:20.77310Z,1325716220.7731 [calibrateSparton](INFO): Aggregate::initialize calibrateSparton
2012-01-04T22:30:20.77320Z,1325716220.7732 [calibrateSparton:A.AltitudeEnvelope] Running Loop=1
2012-01-04T22:30:20.77320Z,1325716220.7732 [calibrateSparton:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-01-04T22:30:20.77340Z,1325716220.7734 [calibrateSparton:B.DepthEnvelope] Running Loop=1
2012-01-04T22:30:20.77350Z,1325716220.7735 [calibrateSparton:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-01-04T22:30:20.77490Z,1325716220.7749 [calibrateSparton:C.OffshoreEnvelope] Running Loop=1
2012-01-04T22:30:20.77500Z,1325716220.775 [calibrateSparton:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2012-01-04T22:30:20.77510Z,1325716220.7751 [calibrateSparton:D] Running Loop=1
2012-01-04T22:30:20.77520Z,1325716220.7752 [calibrateSparton:E.Buoyancy] Running Loop=1
2012-01-04T22:30:20.77530Z,1325716220.7753 [calibrateSparton:E.Buoyancy](DEBUG): Initialize Buoyancy Component.
2012-01-04T22:30:20.77570Z,1325716220.7757 [calibrateSparton:F.SetSpeed] Running Loop=1
2012-01-04T22:30:20.77570Z,1325716220.7757 [calibrateSparton:F.SetSpeed](DEBUG): Initialize.
2012-01-04T22:30:20.77590Z,1325716220.7759 [calibrateSparton:G.Pitch] Running Loop=1
2012-01-04T22:30:20.77600Z,1325716220.776 [calibrateSparton:G.Pitch](DEBUG): Initialize.
2012-01-04T22:30:20.78110Z,1325716220.7811 [calibrateSparton:F.SetSpeed] Running Loop=1
2012-01-04T22:30:20.79040Z,1325716220.7904 [calibrateSparton:D] Running Loop=1
2012-01-04T22:30:20.79120Z,1325716220.7912 [calibrateSparton:D](DEBUG): Initialize ReadDataComponent to sense platform_orientation
2012-01-04T22:30:20.79260Z,1325716220.7926 [calibrateSparton:C.OffshoreEnvelope] Running Loop=1
2012-01-04T22:30:20.79730Z,1325716220.7973 [calibrateSparton:B.DepthEnvelope] Running Loop=1
2012-01-04T22:30:20.80190Z,1325716220.8019 [calibrateSparton:A.AltitudeEnvelope] Running Loop=1
2012-01-04T22:30:21.22100Z,1325716221.221 [NAL9601](IMPORTANT): GPS fix at: 1325716225
2012-01-04T22:30:28.00850Z,1325716228.0085 [NAL9601](INFO): Powering down
2012-01-04T22:33:34.01100Z,1325716414.011 [calibrateSparton:MassOff] Running Loop=1
2012-01-04T22:33:34.01120Z,1325716414.0112 [calibrateSparton:MassOff](INFO): Aggregate::initialize calibrateSparton:MassOff
2012-01-04T22:33:34.01130Z,1325716414.0113 [calibrateSparton:MassOff:A.Pitch] Running Loop=1
2012-01-04T22:33:34.01140Z,1325716414.0114 [calibrateSparton:MassOff:A.Pitch](DEBUG): Initialize.
2012-01-04T22:33:34.01170Z,1325716414.0117 [calibrateSparton:MassOff:Initialization] Running Loop=1
2012-01-04T22:33:34.01180Z,1325716414.0118 [calibrateSparton:MassOff:Initialization](INFO): Aggregate::initialize calibrateSparton:MassOff:Initialization
2012-01-04T22:33:34.01190Z,1325716414.0119 [calibrateSparton:MassOff:Initialization:A.Point] Running Loop=1
2012-01-04T22:33:34.01200Z,1325716414.012 [calibrateSparton:MassOff:Initialization:A.Point](DEBUG): Initialize.
2012-01-04T22:33:34.42350Z,1325716414.4235 [calibrateSparton:MassOff:A.Pitch] Running Loop=1
2012-01-04T22:33:49.56690Z,1325716429.5669 [calibrateSparton:MassOff:Initialization:B.Wait] Running Loop=1
2012-01-04T22:33:49.56700Z,1325716429.567 [calibrateSparton:MassOff:Initialization:B.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:34:10.28700Z,1325716450.287 [calibrateSparton:MassOff:Initialization:B.Wait](INFO): Done Waiting.
2012-01-04T22:34:10.28720Z,1325716450.2872 [calibrateSparton:MassOff:Initialization:B.Wait] Stopped
2012-01-04T22:34:10.28730Z,1325716450.2873 [calibrateSparton:MassOff:Initialization:B.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:34:10.28790Z,1325716450.2879 [calibrateSparton:MassOff:Initialization](INFO): Completed calibrateSparton:MassOff:Initialization
2012-01-04T22:34:10.28800Z,1325716450.288 [calibrateSparton:MassOff:Initialization] Stopped
2012-01-04T22:34:10.28810Z,1325716450.2881 [calibrateSparton:MassOff:Initialization](INFO): Aggregate::uninitialize calibrateSparton:MassOff:Initialization
2012-01-04T22:34:10.28820Z,1325716450.2882 [calibrateSparton:MassOff:Initialization:A.Point] Stopped
2012-01-04T22:34:10.28840Z,1325716450.2884 [calibrateSparton:MassOff:PreCircles] Running Loop=1
2012-01-04T22:34:10.28850Z,1325716450.2885 [calibrateSparton:MassOff:PreCircles](INFO): Aggregate::initialize calibrateSparton:MassOff:PreCircles
2012-01-04T22:34:10.28860Z,1325716450.2886 [calibrateSparton:MassOff:PreCircles:A.Point] Running Loop=1
2012-01-04T22:34:10.28870Z,1325716450.2887 [calibrateSparton:MassOff:PreCircles:A.Point](DEBUG): Initialize.
2012-01-04T22:34:10.28900Z,1325716450.289 [calibrateSparton:MassOff:PreCircles:B.Wait] Running Loop=1
2012-01-04T22:34:10.28910Z,1325716450.2891 [calibrateSparton:MassOff:PreCircles:B.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:34:10.67770Z,1325716450.6777 [calibrateSparton:MassOff:PreCircles:A.Point] Running Loop=1
2012-01-04T22:34:30.75750Z,1325716470.7575 [calibrateSparton:MassOff:PreCircles:B.Wait](INFO): Done Waiting.
2012-01-04T22:34:30.75780Z,1325716470.7578 [calibrateSparton:MassOff:PreCircles:B.Wait] Stopped
2012-01-04T22:34:30.75780Z,1325716470.7578 [calibrateSparton:MassOff:PreCircles:B.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:34:30.75800Z,1325716470.758 [calibrateSparton:MassOff:PreCircles:C.Point] Running Loop=1
2012-01-04T22:34:30.75810Z,1325716470.7581 [calibrateSparton:MassOff:PreCircles:C.Point](DEBUG): Initialize.
2012-01-04T22:35:33.20920Z,1325716533.2092 [calibrateSparton:MassOff:PreCircles:C.Point] Stopped
2012-01-04T22:35:33.20980Z,1325716533.2098 [calibrateSparton:MassOff:PreCircles](INFO): Completed calibrateSparton:MassOff:PreCircles
2012-01-04T22:35:33.20990Z,1325716533.2099 [calibrateSparton:MassOff:PreCircles] Stopped
2012-01-04T22:35:33.21000Z,1325716533.21 [calibrateSparton:MassOff:PreCircles](INFO): Aggregate::uninitialize calibrateSparton:MassOff:PreCircles
2012-01-04T22:35:33.21010Z,1325716533.2101 [calibrateSparton:MassOff:PreCircles:A.Point] Stopped
2012-01-04T22:35:33.21030Z,1325716533.2103 [calibrateSparton:MassOff:PreCircles](INFO): Running loop #2
2012-01-04T22:35:33.21040Z,1325716533.2104 [calibrateSparton:MassOff:PreCircles] Running Loop=2
2012-01-04T22:35:33.21070Z,1325716533.2107 [calibrateSparton:MassOff:PreCircles](INFO): Aggregate::initialize calibrateSparton:MassOff:PreCircles
2012-01-04T22:35:33.21080Z,1325716533.2108 [calibrateSparton:MassOff:PreCircles:A.Point] Running Loop=1
2012-01-04T22:35:33.21090Z,1325716533.2109 [calibrateSparton:MassOff:PreCircles:A.Point](DEBUG): Initialize.
2012-01-04T22:35:33.21120Z,1325716533.2112 [calibrateSparton:MassOff:PreCircles:B.Wait] Running Loop=1
2012-01-04T22:35:33.21120Z,1325716533.2112 [calibrateSparton:MassOff:PreCircles:B.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:35:53.90620Z,1325716553.9062 [calibrateSparton:MassOff:PreCircles:B.Wait](INFO): Done Waiting.
2012-01-04T22:35:53.90640Z,1325716553.9064 [calibrateSparton:MassOff:PreCircles:B.Wait] Stopped
2012-01-04T22:35:53.90650Z,1325716553.9065 [calibrateSparton:MassOff:PreCircles:B.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:35:53.90670Z,1325716553.9067 [calibrateSparton:MassOff:PreCircles:C.Point] Running Loop=1
2012-01-04T22:35:53.90680Z,1325716553.9068 [calibrateSparton:MassOff:PreCircles:C.Point](DEBUG): Initialize.
2012-01-04T22:36:41.77390Z,1325716601.7739 [Batt_Ocean_Server](INFO): Over Temperature Alarm! Battery Bank #7 STATUS: 5911
2012-01-04T22:36:41.77430Z,1325716601.7743 [Batt_Ocean_Server](INFO): Not Initialized - Battery Bank #7 STATUS: 5911
2012-01-04T22:36:54.32970Z,1325716614.3297 [calibrateSparton:MassOff:PreCircles:C.Point] Stopped
2012-01-04T22:36:54.33020Z,1325716614.3302 [calibrateSparton:MassOff:PreCircles](INFO): Completed calibrateSparton:MassOff:PreCircles
2012-01-04T22:36:54.33030Z,1325716614.3303 [calibrateSparton:MassOff:PreCircles] Stopped
2012-01-04T22:36:54.33050Z,1325716614.3305 [calibrateSparton:MassOff:PreCircles](INFO): Aggregate::uninitialize calibrateSparton:MassOff:PreCircles
2012-01-04T22:36:54.33050Z,1325716614.3305 [calibrateSparton:MassOff:PreCircles:A.Point] Stopped
2012-01-04T22:36:54.33090Z,1325716614.3309 [calibrateSparton:MassOff:Calibration] Running Loop=1
2012-01-04T22:36:54.33100Z,1325716614.331 [calibrateSparton:MassOff:Calibration](INFO): Aggregate::initialize calibrateSparton:MassOff:Calibration
2012-01-04T22:36:54.33110Z,1325716614.3311 [calibrateSparton:MassOff:Calibration:D.CalibrateSparton] Running Loop=1
2012-01-04T22:36:54.33120Z,1325716614.3312 [calibrateSparton:MassOff:Calibration:D.CalibrateSparton](INFO): Initialize CalibrateSpartonComponent.
2012-01-04T22:36:54.39630Z,1325716614.3963 [calibrateSparton:MassOff:Calibration:Manual_Loop] Running Loop=1
2012-01-04T22:36:54.39650Z,1325716614.3965 [calibrateSparton:MassOff:Calibration:Manual_Loop](INFO): Aggregate::initialize calibrateSparton:MassOff:Calibration:Manual_Loop
2012-01-04T22:36:54.39660Z,1325716614.3966 [calibrateSparton:MassOff:Calibration:Manual_Loop:A.Point] Running Loop=1
2012-01-04T22:36:54.39670Z,1325716614.3967 [calibrateSparton:MassOff:Calibration:Manual_Loop:A.Point](DEBUG): Initialize.
2012-01-04T22:36:54.39700Z,1325716614.397 [calibrateSparton:MassOff:Calibration:Manual_Loop:B.Wait] Running Loop=1
2012-01-04T22:36:54.39710Z,1325716614.3971 [calibrateSparton:MassOff:Calibration:Manual_Loop:B.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:36:54.71770Z,1325716614.7177 [calibrateSparton:MassOff:Calibration:D.CalibrateSparton] Running Loop=1
2012-01-04T22:36:54.72710Z,1325716614.7271 [calibrateSparton:MassOff:Calibration:Manual_Loop:A.Point] Running Loop=1
2012-01-04T22:37:14.81890Z,1325716634.8189 [calibrateSparton:MassOff:Calibration:Manual_Loop:B.Wait](INFO): Done Waiting.
2012-01-04T22:37:14.81910Z,1325716634.8191 [calibrateSparton:MassOff:Calibration:Manual_Loop:B.Wait] Stopped
2012-01-04T22:37:14.81920Z,1325716634.8192 [calibrateSparton:MassOff:Calibration:Manual_Loop:B.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:37:14.81940Z,1325716634.8194 [calibrateSparton:MassOff:Calibration:Manual_Loop:C.Point] Running Loop=1
2012-01-04T22:37:14.81940Z,1325716634.8194 [calibrateSparton:MassOff:Calibration:Manual_Loop:C.Point](DEBUG): Initialize.
2012-01-04T22:38:22.60570Z,1325716702.6057 [calibrateSparton:MassOff:Calibration:Manual_Loop:C.Point] Stopped
2012-01-04T22:38:22.60630Z,1325716702.6063 [calibrateSparton:MassOff:Calibration:Manual_Loop](INFO): Completed calibrateSparton:MassOff:Calibration:Manual_Loop
2012-01-04T22:38:22.60640Z,1325716702.6064 [calibrateSparton:MassOff:Calibration:Manual_Loop] Stopped
2012-01-04T22:38:22.60650Z,1325716702.6065 [calibrateSparton:MassOff:Calibration:Manual_Loop](INFO): Aggregate::uninitialize calibrateSparton:MassOff:Calibration:Manual_Loop
2012-01-04T22:38:22.60660Z,1325716702.6066 [calibrateSparton:MassOff:Calibration:Manual_Loop:A.Point] Stopped
2012-01-04T22:38:22.60680Z,1325716702.6068 [calibrateSparton:MassOff:Calibration:B.Wait] Running Loop=1
2012-01-04T22:38:22.60690Z,1325716702.6069 [calibrateSparton:MassOff:Calibration:B.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:38:22.96950Z,1325716702.9695 [calibrateSparton:MassOff:Calibration:D.CalibrateSparton] Preempted
2012-01-04T22:38:22.96960Z,1325716702.9696 [calibrateSparton:MassOff:Calibration:D.CalibrateSparton](INFO): Preempted CalibrateSpartonComponent.
2012-01-04T22:38:22.99970Z,1325716702.9997 [calibrateSparton:MassOff:Calibration:B.Wait](INFO): Done Waiting.
2012-01-04T22:38:23.00420Z,1325716703.0042 [calibrateSparton:MassOff:Calibration:B.Wait] Stopped
2012-01-04T22:38:23.00430Z,1325716703.0043 [calibrateSparton:MassOff:Calibration:B.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:38:23.00450Z,1325716703.0045 [calibrateSparton:MassOff:Calibration:Auto_Loop] Running Loop=1
2012-01-04T22:38:23.00470Z,1325716703.0047 [calibrateSparton:MassOff:Calibration:Auto_Loop](INFO): Aggregate::initialize calibrateSparton:MassOff:Calibration:Auto_Loop
2012-01-04T22:38:23.00480Z,1325716703.0048 [calibrateSparton:MassOff:Calibration:Auto_Loop:A.Point] Running Loop=1
2012-01-04T22:38:23.00480Z,1325716703.0048 [calibrateSparton:MassOff:Calibration:Auto_Loop:A.Point](DEBUG): Initialize.
2012-01-04T22:38:23.00520Z,1325716703.0052 [calibrateSparton:MassOff:Calibration:Auto_Loop:B.Wait] Running Loop=1
2012-01-04T22:38:23.00520Z,1325716703.0052 [calibrateSparton:MassOff:Calibration:Auto_Loop:B.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:38:23.35780Z,1325716703.3578 [calibrateSparton:MassOff:Calibration:D.CalibrateSparton] Running Loop=1
2012-01-04T22:38:23.36290Z,1325716703.3629 [calibrateSparton:MassOff:Calibration:Auto_Loop:A.Point] Running Loop=1
2012-01-04T22:38:43.41010Z,1325716723.4101 [calibrateSparton:MassOff:Calibration:Auto_Loop:B.Wait](INFO): Done Waiting.
2012-01-04T22:38:43.41030Z,1325716723.4103 [calibrateSparton:MassOff:Calibration:Auto_Loop:B.Wait] Stopped
2012-01-04T22:38:43.41040Z,1325716723.4104 [calibrateSparton:MassOff:Calibration:Auto_Loop:B.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:38:43.41080Z,1325716723.4108 [calibrateSparton:MassOff:Calibration:Auto_Loop:C.Point] Running Loop=1
2012-01-04T22:38:43.41080Z,1325716723.4108 [calibrateSparton:MassOff:Calibration:Auto_Loop:C.Point](DEBUG): Initialize.
2012-01-04T22:39:44.59540Z,1325716784.5954 [calibrateSparton:MassOff:Calibration:Auto_Loop:C.Point] Stopped
2012-01-04T22:39:44.59590Z,1325716784.5959 [calibrateSparton:MassOff:Calibration:Auto_Loop](INFO): Completed calibrateSparton:MassOff:Calibration:Auto_Loop
2012-01-04T22:39:44.59600Z,1325716784.596 [calibrateSparton:MassOff:Calibration:Auto_Loop] Stopped
2012-01-04T22:39:44.59610Z,1325716784.5961 [calibrateSparton:MassOff:Calibration:Auto_Loop](INFO): Aggregate::uninitialize calibrateSparton:MassOff:Calibration:Auto_Loop
2012-01-04T22:39:44.59620Z,1325716784.5962 [calibrateSparton:MassOff:Calibration:Auto_Loop:A.Point] Stopped
2012-01-04T22:39:44.59640Z,1325716784.5964 [calibrateSparton:MassOff:Calibration:Auto_Loop](INFO): Running loop #2
2012-01-04T22:39:44.59650Z,1325716784.5965 [calibrateSparton:MassOff:Calibration:Auto_Loop] Running Loop=2
2012-01-04T22:39:44.59670Z,1325716784.5967 [calibrateSparton:MassOff:Calibration:Auto_Loop](INFO): Aggregate::initialize calibrateSparton:MassOff:Calibration:Auto_Loop
2012-01-04T22:39:44.59680Z,1325716784.5968 [calibrateSparton:MassOff:Calibration:Auto_Loop:A.Point] Running Loop=1
2012-01-04T22:39:44.59680Z,1325716784.5968 [calibrateSparton:MassOff:Calibration:Auto_Loop:A.Point](DEBUG): Initialize.
2012-01-04T22:39:44.59710Z,1325716784.5971 [calibrateSparton:MassOff:Calibration:Auto_Loop:B.Wait] Running Loop=1
2012-01-04T22:39:44.59720Z,1325716784.5972 [calibrateSparton:MassOff:Calibration:Auto_Loop:B.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:40:05.03790Z,1325716805.0379 [calibrateSparton:MassOff:Calibration:Auto_Loop:B.Wait](INFO): Done Waiting.
2012-01-04T22:40:05.03820Z,1325716805.0382 [calibrateSparton:MassOff:Calibration:Auto_Loop:B.Wait] Stopped
2012-01-04T22:40:05.03820Z,1325716805.0382 [calibrateSparton:MassOff:Calibration:Auto_Loop:B.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:40:05.03840Z,1325716805.0384 [calibrateSparton:MassOff:Calibration:Auto_Loop:C.Point] Running Loop=1
2012-01-04T22:40:05.03850Z,1325716805.0385 [calibrateSparton:MassOff:Calibration:Auto_Loop:C.Point](DEBUG): Initialize.
2012-01-04T22:41:04.93950Z,1325716864.9395 [calibrateSparton:MassOff:Calibration:Auto_Loop:C.Point] Stopped
2012-01-04T22:41:04.94000Z,1325716864.94 [calibrateSparton:MassOff:Calibration:Auto_Loop](INFO): Completed calibrateSparton:MassOff:Calibration:Auto_Loop
2012-01-04T22:41:04.94010Z,1325716864.9401 [calibrateSparton:MassOff:Calibration:Auto_Loop] Stopped
2012-01-04T22:41:04.94030Z,1325716864.9403 [calibrateSparton:MassOff:Calibration:Auto_Loop](INFO): Aggregate::uninitialize calibrateSparton:MassOff:Calibration:Auto_Loop
2012-01-04T22:41:04.94030Z,1325716864.9403 [calibrateSparton:MassOff:Calibration:Auto_Loop:A.Point] Stopped
2012-01-04T22:41:04.94060Z,1325716864.9406 [calibrateSparton:MassOff:Calibration:Auto_Loop](INFO): Running loop #3
2012-01-04T22:41:04.94070Z,1325716864.9407 [calibrateSparton:MassOff:Calibration:Auto_Loop] Running Loop=3
2012-01-04T22:41:04.94090Z,1325716864.9409 [calibrateSparton:MassOff:Calibration:Auto_Loop](INFO): Aggregate::initialize calibrateSparton:MassOff:Calibration:Auto_Loop
2012-01-04T22:41:04.94090Z,1325716864.9409 [calibrateSparton:MassOff:Calibration:Auto_Loop:A.Point] Running Loop=1
2012-01-04T22:41:04.94100Z,1325716864.941 [calibrateSparton:MassOff:Calibration:Auto_Loop:A.Point](DEBUG): Initialize.
2012-01-04T22:41:04.94130Z,1325716864.9413 [calibrateSparton:MassOff:Calibration:Auto_Loop:B.Wait] Running Loop=1
2012-01-04T22:41:04.94140Z,1325716864.9414 [calibrateSparton:MassOff:Calibration:Auto_Loop:B.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:41:25.62420Z,1325716885.6242 [calibrateSparton:MassOff:Calibration:Auto_Loop:B.Wait](INFO): Done Waiting.
2012-01-04T22:41:25.62440Z,1325716885.6244 [calibrateSparton:MassOff:Calibration:Auto_Loop:B.Wait] Stopped
2012-01-04T22:41:25.62450Z,1325716885.6245 [calibrateSparton:MassOff:Calibration:Auto_Loop:B.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:41:25.62470Z,1325716885.6247 [calibrateSparton:MassOff:Calibration:Auto_Loop:C.Point] Running Loop=1
2012-01-04T22:41:25.62470Z,1325716885.6247 [calibrateSparton:MassOff:Calibration:Auto_Loop:C.Point](DEBUG): Initialize.
2012-01-04T22:42:29.04210Z,1325716949.0421 [calibrateSparton:MassOff:Calibration:Auto_Loop:C.Point] Stopped
2012-01-04T22:42:29.04290Z,1325716949.0429 [calibrateSparton:MassOff:Calibration:Auto_Loop](INFO): Completed calibrateSparton:MassOff:Calibration:Auto_Loop
2012-01-04T22:42:29.04300Z,1325716949.043 [calibrateSparton:MassOff:Calibration:Auto_Loop] Stopped
2012-01-04T22:42:29.04310Z,1325716949.0431 [calibrateSparton:MassOff:Calibration:Auto_Loop](INFO): Aggregate::uninitialize calibrateSparton:MassOff:Calibration:Auto_Loop
2012-01-04T22:42:29.04320Z,1325716949.0432 [calibrateSparton:MassOff:Calibration:Auto_Loop:A.Point] Stopped
2012-01-04T22:42:29.04340Z,1325716949.0434 [calibrateSparton:MassOff:Calibration](INFO): Completed calibrateSparton:MassOff:Calibration
2012-01-04T22:42:29.04350Z,1325716949.0435 [calibrateSparton:MassOff:Calibration] Stopped
2012-01-04T22:42:29.04370Z,1325716949.0437 [calibrateSparton:MassOff:Calibration](INFO): Aggregate::uninitialize calibrateSparton:MassOff:Calibration
2012-01-04T22:42:29.04370Z,1325716949.0437 [calibrateSparton:MassOff:Calibration:D.CalibrateSparton] Stopped
2012-01-04T22:42:29.04380Z,1325716949.0438 [calibrateSparton:MassOff:Calibration:D.CalibrateSparton](INFO): Uninitialize CalibrateSpartonComponent.
2012-01-04T22:42:29.08730Z,1325716949.0873 [AHRS_sp3003D](IMPORTANT): Magnetic calibration quality (0[best] to 10000) is 1
2012-01-04T22:42:29.08810Z,1325716949.0881 [calibrateSparton:MassOff:PostCircles] Running Loop=1
2012-01-04T22:42:29.08830Z,1325716949.0883 [calibrateSparton:MassOff:PostCircles](INFO): Aggregate::initialize calibrateSparton:MassOff:PostCircles
2012-01-04T22:42:29.08840Z,1325716949.0884 [calibrateSparton:MassOff:PostCircles:A.Point] Running Loop=1
2012-01-04T22:42:29.08850Z,1325716949.0885 [calibrateSparton:MassOff:PostCircles:A.Point](DEBUG): Initialize.
2012-01-04T22:42:29.08880Z,1325716949.0888 [calibrateSparton:MassOff:PostCircles:B.Wait] Running Loop=1
2012-01-04T22:42:29.08890Z,1325716949.0889 [calibrateSparton:MassOff:PostCircles:B.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:42:29.51250Z,1325716949.5125 [calibrateSparton:MassOff:PostCircles:A.Point] Running Loop=1
2012-01-04T22:42:49.66320Z,1325716969.6632 [calibrateSparton:MassOff:PostCircles:B.Wait](INFO): Done Waiting.
2012-01-04T22:42:49.66350Z,1325716969.6635 [calibrateSparton:MassOff:PostCircles:B.Wait] Stopped
2012-01-04T22:42:49.66360Z,1325716969.6636 [calibrateSparton:MassOff:PostCircles:B.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:42:49.66370Z,1325716969.6637 [calibrateSparton:MassOff:PostCircles:C.Point] Running Loop=1
2012-01-04T22:42:49.66380Z,1325716969.6638 [calibrateSparton:MassOff:PostCircles:C.Point](DEBUG): Initialize.
2012-01-04T22:43:43.74160Z,1325717023.7416 [calibrateSparton:MassOff:PostCircles:C.Point] Stopped
2012-01-04T22:43:43.74220Z,1325717023.7422 [calibrateSparton:MassOff:PostCircles](INFO): Completed calibrateSparton:MassOff:PostCircles
2012-01-04T22:43:43.74230Z,1325717023.7423 [calibrateSparton:MassOff:PostCircles] Stopped
2012-01-04T22:43:43.74240Z,1325717023.7424 [calibrateSparton:MassOff:PostCircles](INFO): Aggregate::uninitialize calibrateSparton:MassOff:PostCircles
2012-01-04T22:43:43.74250Z,1325717023.7425 [calibrateSparton:MassOff:PostCircles:A.Point] Stopped
2012-01-04T22:43:43.74270Z,1325717023.7427 [calibrateSparton:MassOff:PostCircles](INFO): Running loop #2
2012-01-04T22:43:43.74290Z,1325717023.7429 [calibrateSparton:MassOff:PostCircles] Running Loop=2
2012-01-04T22:43:43.74300Z,1325717023.743 [calibrateSparton:MassOff:PostCircles](INFO): Aggregate::initialize calibrateSparton:MassOff:PostCircles
2012-01-04T22:43:43.74310Z,1325717023.7431 [calibrateSparton:MassOff:PostCircles:A.Point] Running Loop=1
2012-01-04T22:43:43.74320Z,1325717023.7432 [calibrateSparton:MassOff:PostCircles:A.Point](DEBUG): Initialize.
2012-01-04T22:43:43.74350Z,1325717023.7435 [calibrateSparton:MassOff:PostCircles:B.Wait] Running Loop=1
2012-01-04T22:43:43.74350Z,1325717023.7435 [calibrateSparton:MassOff:PostCircles:B.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:44:04.18120Z,1325717044.1812 [calibrateSparton:MassOff:PostCircles:B.Wait](INFO): Done Waiting.
2012-01-04T22:44:04.18150Z,1325717044.1815 [calibrateSparton:MassOff:PostCircles:B.Wait] Stopped
2012-01-04T22:44:04.18160Z,1325717044.1816 [calibrateSparton:MassOff:PostCircles:B.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:44:04.18180Z,1325717044.1818 [calibrateSparton:MassOff:PostCircles:C.Point] Running Loop=1
2012-01-04T22:44:04.18180Z,1325717044.1818 [calibrateSparton:MassOff:PostCircles:C.Point](DEBUG): Initialize.
2012-01-04T22:45:06.99360Z,1325717106.9936 [calibrateSparton:MassOff:PostCircles:C.Point] Stopped
2012-01-04T22:45:06.99410Z,1325717106.9941 [calibrateSparton:MassOff:PostCircles](INFO): Completed calibrateSparton:MassOff:PostCircles
2012-01-04T22:45:06.99420Z,1325717106.9942 [calibrateSparton:MassOff:PostCircles] Stopped
2012-01-04T22:45:06.99440Z,1325717106.9944 [calibrateSparton:MassOff:PostCircles](INFO): Aggregate::uninitialize calibrateSparton:MassOff:PostCircles
2012-01-04T22:45:06.99440Z,1325717106.9944 [calibrateSparton:MassOff:PostCircles:A.Point] Stopped
2012-01-04T22:45:06.99510Z,1325717106.9951 [calibrateSparton:MassOff](INFO): Completed calibrateSparton:MassOff
2012-01-04T22:45:06.99520Z,1325717106.9952 [calibrateSparton:MassOff] Stopped
2012-01-04T22:45:06.99530Z,1325717106.9953 [calibrateSparton:MassOff](INFO): Aggregate::uninitialize calibrateSparton:MassOff
2012-01-04T22:45:06.99540Z,1325717106.9954 [calibrateSparton:MassOff:A.Pitch] Stopped
2012-01-04T22:45:06.99560Z,1325717106.9956 [calibrateSparton:PostCirclesMass] Running Loop=1
2012-01-04T22:45:06.99570Z,1325717106.9957 [calibrateSparton:PostCirclesMass](INFO): Aggregate::initialize calibrateSparton:PostCirclesMass
2012-01-04T22:45:06.99580Z,1325717106.9958 [calibrateSparton:PostCirclesMass:A.Point] Running Loop=1
2012-01-04T22:45:06.99580Z,1325717106.9958 [calibrateSparton:PostCirclesMass:A.Point](DEBUG): Initialize.
2012-01-04T22:45:06.99620Z,1325717106.9962 [calibrateSparton:PostCirclesMass:B.Wait] Running Loop=1
2012-01-04T22:45:06.99630Z,1325717106.9963 [calibrateSparton:PostCirclesMass:B.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:45:07.40080Z,1325717107.4008 [calibrateSparton:PostCirclesMass:A.Point] Running Loop=1
2012-01-04T22:45:27.62460Z,1325717127.6246 [calibrateSparton:PostCirclesMass:B.Wait](INFO): Done Waiting.
2012-01-04T22:45:27.62490Z,1325717127.6249 [calibrateSparton:PostCirclesMass:B.Wait] Stopped
2012-01-04T22:45:27.62490Z,1325717127.6249 [calibrateSparton:PostCirclesMass:B.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:45:27.62510Z,1325717127.6251 [calibrateSparton:PostCirclesMass:C.Point] Running Loop=1
2012-01-04T22:45:27.62520Z,1325717127.6252 [calibrateSparton:PostCirclesMass:C.Point](DEBUG): Initialize.
2012-01-04T22:46:28.01880Z,1325717188.0188 [calibrateSparton:PostCirclesMass:C.Point] Stopped
2012-01-04T22:46:28.01930Z,1325717188.0193 [calibrateSparton:PostCirclesMass](INFO): Completed calibrateSparton:PostCirclesMass
2012-01-04T22:46:28.01930Z,1325717188.0193 [calibrateSparton:PostCirclesMass] Stopped
2012-01-04T22:46:28.01950Z,1325717188.0195 [calibrateSparton:PostCirclesMass](INFO): Aggregate::uninitialize calibrateSparton:PostCirclesMass
2012-01-04T22:46:28.01960Z,1325717188.0196 [calibrateSparton:PostCirclesMass:A.Point] Stopped
2012-01-04T22:46:28.01980Z,1325717188.0198 [calibrateSparton:PostCirclesMass](INFO): Running loop #2
2012-01-04T22:46:28.01990Z,1325717188.0199 [calibrateSparton:PostCirclesMass] Running Loop=2
2012-01-04T22:46:28.02000Z,1325717188.02 [calibrateSparton:PostCirclesMass](INFO): Aggregate::initialize calibrateSparton:PostCirclesMass
2012-01-04T22:46:28.02010Z,1325717188.0201 [calibrateSparton:PostCirclesMass:A.Point] Running Loop=1
2012-01-04T22:46:28.02020Z,1325717188.0202 [calibrateSparton:PostCirclesMass:A.Point](DEBUG): Initialize.
2012-01-04T22:46:28.02050Z,1325717188.0205 [calibrateSparton:PostCirclesMass:B.Wait] Running Loop=1
2012-01-04T22:46:28.02050Z,1325717188.0205 [calibrateSparton:PostCirclesMass:B.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:46:48.76360Z,1325717208.7636 [calibrateSparton:PostCirclesMass:B.Wait](INFO): Done Waiting.
2012-01-04T22:46:48.76390Z,1325717208.7639 [calibrateSparton:PostCirclesMass:B.Wait] Stopped
2012-01-04T22:46:48.76400Z,1325717208.764 [calibrateSparton:PostCirclesMass:B.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T22:46:48.76410Z,1325717208.7641 [calibrateSparton:PostCirclesMass:C.Point] Running Loop=1
2012-01-04T22:46:48.76420Z,1325717208.7642 [calibrateSparton:PostCirclesMass:C.Point](DEBUG): Initialize.
2012-01-04T22:48:01.03020Z,1325717281.0302 [calibrateSparton:PostCirclesMass:C.Point] Stopped
2012-01-04T22:48:01.03090Z,1325717281.0309 [calibrateSparton:PostCirclesMass](INFO): Completed calibrateSparton:PostCirclesMass
2012-01-04T22:48:01.03100Z,1325717281.031 [calibrateSparton:PostCirclesMass] Stopped
2012-01-04T22:48:01.03120Z,1325717281.0312 [calibrateSparton:PostCirclesMass](INFO): Aggregate::uninitialize calibrateSparton:PostCirclesMass
2012-01-04T22:48:01.03130Z,1325717281.0313 [calibrateSparton:PostCirclesMass:A.Point] Stopped
2012-01-04T22:48:01.03330Z,1325717281.0333 [calibrateSparton](INFO): Completed calibrateSparton
2012-01-04T22:48:01.03340Z,1325717281.0334 [calibrateSparton] Stopped
2012-01-04T22:48:01.03360Z,1325717281.0336 [calibrateSparton](INFO): Aggregate::uninitialize calibrateSparton
2012-01-04T22:48:01.03370Z,1325717281.0337 [calibrateSparton:A.AltitudeEnvelope] Stopped
2012-01-04T22:48:01.03370Z,1325717281.0337 [calibrateSparton:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-01-04T22:48:01.03380Z,1325717281.0338 [calibrateSparton:B.DepthEnvelope] Stopped
2012-01-04T22:48:01.03390Z,1325717281.0339 [calibrateSparton:B.DepthEnvelope](DEBUG): Uninitialize.
2012-01-04T22:48:01.03400Z,1325717281.034 [calibrateSparton:C.OffshoreEnvelope] Stopped
2012-01-04T22:48:01.03400Z,1325717281.034 [calibrateSparton:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2012-01-04T22:48:01.03410Z,1325717281.0341 [calibrateSparton:D] Stopped
2012-01-04T22:48:01.03420Z,1325717281.0342 [calibrateSparton:E.Buoyancy] Stopped
2012-01-04T22:48:01.03420Z,1325717281.0342 [calibrateSparton:E.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2012-01-04T22:48:01.03430Z,1325717281.0343 [calibrateSparton:F.SetSpeed] Stopped
2012-01-04T22:48:01.03440Z,1325717281.0344 [calibrateSparton:F.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:48:01.03440Z,1325717281.0344 [calibrateSparton:G.Pitch] Stopped
2012-01-04T22:48:01.45860Z,1325717281.4586 [MissionManager](IMPORTANT): Started mission Default
2012-01-04T22:48:01.45870Z,1325717281.4587 [Default] Running Loop=1
2012-01-04T22:48:01.45880Z,1325717281.4588 [Default](INFO): Aggregate::initialize Default
2012-01-04T22:48:01.45890Z,1325717281.4589 [Default:E.SetSpeed] Running Loop=1
2012-01-04T22:48:01.45900Z,1325717281.459 [Default:E.SetSpeed](DEBUG): Initialize.
2012-01-04T22:48:01.45910Z,1325717281.4591 [Default:F.GoToSurface] Running Loop=1
2012-01-04T22:48:01.45920Z,1325717281.4592 [Default:F.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T22:48:01.45970Z,1325717281.4597 [Default:GPS] Running Loop=1
2012-01-04T22:48:01.45980Z,1325717281.4598 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T22:48:01.45990Z,1325717281.4599 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T22:48:01.46000Z,1325717281.46 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T22:48:01.46020Z,1325717281.4602 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T22:48:01.46020Z,1325717281.4602 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T22:48:01.46180Z,1325717281.4618 [Default:CallIridium] Running Loop=1
2012-01-04T22:48:01.46190Z,1325717281.4619 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-04T22:48:01.46210Z,1325717281.4621 [Default:CallIridium:A] Running Loop=1
2012-01-04T22:48:01.46220Z,1325717281.4622 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-04T22:48:01.46240Z,1325717281.4624 [Default:CallGPS] Running Loop=1
2012-01-04T22:48:01.46250Z,1325717281.4625 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T22:48:01.46270Z,1325717281.4627 [Default:CallGPS:A] Running Loop=1
2012-01-04T22:48:01.46280Z,1325717281.4628 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T22:48:01.89910Z,1325717281.8991 [Default:Iridium] Running Loop=1
2012-01-04T22:48:01.89930Z,1325717281.8993 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-04T22:48:01.89940Z,1325717281.8994 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-04T22:48:01.89940Z,1325717281.8994 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-04T22:48:01.89960Z,1325717281.8996 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-04T22:48:01.89970Z,1325717281.8997 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T22:51:40.23330Z,1325717500.2333 [Default:Iridium:B.GoToSurface] Stopped
2012-01-04T22:51:40.23340Z,1325717500.2334 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T22:51:40.23360Z,1325717500.2336 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-04T22:51:40.23410Z,1325717500.2341 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T22:51:40.23420Z,1325717500.2342 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T22:51:40.23430Z,1325717500.2343 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T22:51:41.01520Z,1325717501.0152 [NAL9601](INFO): Powering up
2012-01-04T22:52:46.72730Z,1325717566.7273 [NAL9601](INFO): NAL9601 initialized
2012-01-04T22:52:47.88200Z,1325717567.882 [NAL9601](IMPORTANT): GPS fix at: 1325717574
2012-01-04T22:52:47.90710Z,1325717567.9071 [Default:GPS:Read_GPS] Stopped
2012-01-04T22:52:47.90750Z,1325717567.9075 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T22:52:47.90760Z,1325717567.9076 [Default:GPS] Stopped
2012-01-04T22:52:47.90770Z,1325717567.9077 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T22:52:47.90780Z,1325717567.9078 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T22:52:47.90780Z,1325717567.9078 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:52:48.29330Z,1325717568.2933 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T22:52:48.29340Z,1325717568.2934 [Default:CallGPS:A] Stopped
2012-01-04T22:52:48.29350Z,1325717568.2935 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T22:52:48.29380Z,1325717568.2938 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T22:52:48.29380Z,1325717568.2938 [Default:CallGPS] Stopped
2012-01-04T22:52:48.29400Z,1325717568.294 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T22:52:48.73240Z,1325717568.7324 [Default:CallGPS] Running Loop=1
2012-01-04T22:52:48.73260Z,1325717568.7326 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T22:52:48.73280Z,1325717568.7328 [Default:CallGPS:A] Running Loop=1
2012-01-04T22:52:48.73290Z,1325717568.7329 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T22:52:49.14110Z,1325717569.1411 [Default:GPS] Running Loop=1
2012-01-04T22:52:49.14130Z,1325717569.1413 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T22:52:49.14140Z,1325717569.1414 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T22:52:49.14150Z,1325717569.1415 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T22:52:49.14170Z,1325717569.1417 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T22:52:49.14180Z,1325717569.1418 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T22:52:49.14250Z,1325717569.1425 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T22:52:49.14260Z,1325717569.1426 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T22:52:49.14280Z,1325717569.1428 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T22:52:51.33360Z,1325717571.3336 [NAL9601](IMPORTANT): GPS fix at: 1325717578
2012-01-04T22:52:51.34760Z,1325717571.3476 [Default:GPS:Read_GPS] Stopped
2012-01-04T22:52:51.34800Z,1325717571.348 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T22:52:51.34800Z,1325717571.348 [Default:GPS] Stopped
2012-01-04T22:52:51.34820Z,1325717571.3482 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T22:52:51.34830Z,1325717571.3483 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T22:52:51.34830Z,1325717571.3483 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:52:51.73740Z,1325717571.7374 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T22:52:51.73750Z,1325717571.7375 [Default:CallGPS:A] Stopped
2012-01-04T22:52:51.73760Z,1325717571.7376 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T22:52:51.73780Z,1325717571.7378 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T22:52:51.73790Z,1325717571.7379 [Default:CallGPS] Stopped
2012-01-04T22:52:51.73800Z,1325717571.738 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T22:52:52.17180Z,1325717572.1718 [Default:CallGPS] Running Loop=1
2012-01-04T22:52:52.17200Z,1325717572.172 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T22:52:52.17220Z,1325717572.1722 [Default:CallGPS:A] Running Loop=1
2012-01-04T22:52:52.17230Z,1325717572.1723 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T22:52:52.56910Z,1325717572.5691 [Default:GPS] Running Loop=1
2012-01-04T22:52:52.56930Z,1325717572.5693 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T22:52:52.56940Z,1325717572.5694 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T22:52:52.56950Z,1325717572.5695 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T22:52:52.56970Z,1325717572.5697 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T22:52:52.56980Z,1325717572.5698 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T22:52:52.57050Z,1325717572.5705 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T22:52:52.57060Z,1325717572.5706 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T22:52:52.57080Z,1325717572.5708 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T22:53:05.98960Z,1325717585.9896 [NAL9601](INFO): SBD MO Status=1, MOMSN=40229, MT Status=0, MTMSN=0
2012-01-04T22:53:06.18720Z,1325717586.1872 [NAL9601](INFO): Sent 203 bytes from file Logs/20120104T212427/shore0007.lzma
2012-01-04T22:53:06.18740Z,1325717586.1874 [NAL9601](INFO): Packets left to send: 0
2012-01-04T22:53:06.18860Z,1325717586.1886 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000025
2012-01-04T22:53:13.58970Z,1325717593.5897 [NAL9601](INFO): SBD MO Status=0, MOMSN=40230, MT Status=0, MTMSN=0
2012-01-04T22:53:13.79730Z,1325717593.7973 [Default:Iridium:Read_Iridium] Stopped
2012-01-04T22:53:13.79780Z,1325717593.7978 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-04T22:53:13.79790Z,1325717593.7979 [Default:Iridium] Stopped
2012-01-04T22:53:13.79800Z,1325717593.798 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-04T22:53:13.79810Z,1325717593.7981 [Default:Iridium:A.SetSpeed] Stopped
2012-01-04T22:53:13.79820Z,1325717593.7982 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:53:13.79840Z,1325717593.7984 [Default:G.Wait] Running Loop=1
2012-01-04T22:53:13.79840Z,1325717593.7984 [Default:G.Wait](DEBUG): Initialize Wait Component.
2012-01-04T22:53:14.04200Z,1325717594.042 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-04T22:53:14.04210Z,1325717594.0421 [Default:CallIridium:A] Stopped
2012-01-04T22:53:14.04220Z,1325717594.0422 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-04T22:53:14.04250Z,1325717594.0425 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-04T22:53:14.04250Z,1325717594.0425 [Default:CallIridium] Stopped
2012-01-04T22:53:14.04270Z,1325717594.0427 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-04T22:53:14.79120Z,1325717594.7912 [NAL9601](IMPORTANT): GPS fix at: 1325717601
2012-01-04T22:53:14.80510Z,1325717594.8051 [Default:GPS:Read_GPS] Stopped
2012-01-04T22:53:14.80560Z,1325717594.8056 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T22:53:14.80570Z,1325717594.8057 [Default:GPS] Stopped
2012-01-04T22:53:14.80580Z,1325717594.8058 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T22:53:14.80590Z,1325717594.8059 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T22:53:14.80600Z,1325717594.806 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:53:15.69620Z,1325717595.6962 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T22:53:15.69630Z,1325717595.6963 [Default:CallGPS:A] Stopped
2012-01-04T22:53:15.69640Z,1325717595.6964 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T22:53:15.69660Z,1325717595.6966 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T22:53:15.69670Z,1325717595.6967 [Default:CallGPS] Stopped
2012-01-04T22:53:15.69680Z,1325717595.6968 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T22:53:35.85260Z,1325717615.8526 [NAL9601](INFO): Powering down
2012-01-04T22:58:15.96220Z,1325717895.9622 [Default:CallIridium] Running Loop=1
2012-01-04T22:58:15.96240Z,1325717895.9624 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-04T22:58:15.96670Z,1325717895.9667 [Default:CallIridium:A] Running Loop=1
2012-01-04T22:58:15.96690Z,1325717895.9669 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-04T22:58:15.96700Z,1325717895.967 [Default:CallGPS] Running Loop=1
2012-01-04T22:58:15.96720Z,1325717895.9672 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T22:58:15.96730Z,1325717895.9673 [Default:CallGPS:A] Running Loop=1
2012-01-04T22:58:15.96750Z,1325717895.9675 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T22:58:20.84800Z,1325717900.848 [Default:Iridium] Running Loop=1
2012-01-04T22:58:20.84820Z,1325717900.8482 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-04T22:58:20.84830Z,1325717900.8483 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-04T22:58:20.84830Z,1325717900.8483 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-04T22:58:20.84850Z,1325717900.8485 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-04T22:58:20.84860Z,1325717900.8486 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T22:58:20.84930Z,1325717900.8493 [Default:Iridium:B.GoToSurface] Stopped
2012-01-04T22:58:20.84940Z,1325717900.8494 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T22:58:20.84960Z,1325717900.8496 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-04T22:58:20.84990Z,1325717900.8499 [Default:GPS] Running Loop=1
2012-01-04T22:58:20.85000Z,1325717900.85 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T22:58:20.85010Z,1325717900.8501 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T22:58:20.85020Z,1325717900.8502 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T22:58:20.85040Z,1325717900.8504 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T22:58:20.85040Z,1325717900.8504 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T22:58:20.85120Z,1325717900.8512 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T22:58:20.85130Z,1325717900.8513 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T22:58:20.85140Z,1325717900.8514 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T22:58:21.45550Z,1325717901.4555 [NAL9601](INFO): Powering up
2012-01-04T22:59:27.26720Z,1325717967.2672 [NAL9601](INFO): NAL9601 initialized
2012-01-04T22:59:28.26320Z,1325717968.2632 [NAL9601](IMPORTANT): GPS fix at: 1325717975
2012-01-04T22:59:28.27670Z,1325717968.2767 [Default:GPS:Read_GPS] Stopped
2012-01-04T22:59:28.27720Z,1325717968.2772 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T22:59:28.27720Z,1325717968.2772 [Default:GPS] Stopped
2012-01-04T22:59:28.27740Z,1325717968.2774 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T22:59:28.27750Z,1325717968.2775 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T22:59:28.27750Z,1325717968.2775 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T22:59:28.66880Z,1325717968.6688 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T22:59:28.66890Z,1325717968.6689 [Default:CallGPS:A] Stopped
2012-01-04T22:59:28.66910Z,1325717968.6691 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T22:59:28.66930Z,1325717968.6693 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T22:59:28.66940Z,1325717968.6694 [Default:CallGPS] Stopped
2012-01-04T22:59:28.66950Z,1325717968.6695 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T22:59:29.11240Z,1325717969.1124 [Default:CallGPS] Running Loop=1
2012-01-04T22:59:29.11260Z,1325717969.1126 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T22:59:29.11280Z,1325717969.1128 [Default:CallGPS:A] Running Loop=1
2012-01-04T22:59:29.11290Z,1325717969.1129 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T22:59:29.55570Z,1325717969.5557 [Default:GPS] Running Loop=1
2012-01-04T22:59:29.55590Z,1325717969.5559 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T22:59:29.55600Z,1325717969.556 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T22:59:29.55600Z,1325717969.556 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T22:59:29.55620Z,1325717969.5562 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T22:59:29.55630Z,1325717969.5563 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T22:59:29.55690Z,1325717969.5569 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T22:59:29.55700Z,1325717969.557 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T22:59:29.55720Z,1325717969.5572 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T22:59:46.72570Z,1325717986.7257 [NAL9601](INFO): SBD MO Status=1, MOMSN=40231, MT Status=0, MTMSN=0
2012-01-04T22:59:46.92320Z,1325717986.9232 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0008.lzma
2012-01-04T22:59:46.92340Z,1325717986.9234 [NAL9601](INFO): Packets left to send: 5
2012-01-04T22:59:47.03170Z,1325717987.0317 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000026
2012-01-04T22:59:55.81900Z,1325717995.819 [NAL9601](INFO): SBD MO Status=1, MOMSN=40232, MT Status=0, MTMSN=0
2012-01-04T22:59:56.01120Z,1325717996.0112 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0008.lzma
2012-01-04T22:59:56.01140Z,1325717996.0114 [NAL9601](INFO): Packets left to send: 4
2012-01-04T22:59:56.01250Z,1325717996.0125 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000027
2012-01-04T23:00:07.34170Z,1325718007.3417 [NAL9601](INFO): SBD MO Status=1, MOMSN=40233, MT Status=0, MTMSN=0
2012-01-04T23:00:07.49120Z,1325718007.4912 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0008.lzma
2012-01-04T23:00:07.49150Z,1325718007.4915 [NAL9601](INFO): Packets left to send: 3
2012-01-04T23:00:07.49260Z,1325718007.4926 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000028
2012-01-04T23:00:19.37370Z,1325718019.3737 [NAL9601](INFO): SBD MO Status=1, MOMSN=40234, MT Status=0, MTMSN=0
2012-01-04T23:00:19.57910Z,1325718019.5791 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0008.lzma
2012-01-04T23:00:19.57940Z,1325718019.5794 [NAL9601](INFO): Packets left to send: 2
2012-01-04T23:00:19.58050Z,1325718019.5805 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000029
2012-01-04T23:00:27.16180Z,1325718027.1618 [NAL9601](INFO): SBD MO Status=2, MOMSN=40235, MT Status=2, MTMSN=0
2012-01-04T23:00:27.16210Z,1325718027.1621 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-01-04T23:00:28.36320Z,1325718028.3632 [NAL9601](IMPORTANT): GPS fix at: 1325718036
2012-01-04T23:00:28.39020Z,1325718028.3902 [Default:GPS:Read_GPS] Stopped
2012-01-04T23:00:28.39080Z,1325718028.3908 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T23:00:28.39090Z,1325718028.3909 [Default:GPS] Stopped
2012-01-04T23:00:28.39110Z,1325718028.3911 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T23:00:28.39110Z,1325718028.3911 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T23:00:28.39120Z,1325718028.3912 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:00:28.81870Z,1325718028.8187 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T23:00:28.81880Z,1325718028.8188 [Default:CallGPS:A] Stopped
2012-01-04T23:00:28.81900Z,1325718028.819 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T23:00:28.81920Z,1325718028.8192 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T23:00:28.81930Z,1325718028.8193 [Default:CallGPS] Stopped
2012-01-04T23:00:28.81940Z,1325718028.8194 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T23:00:29.18360Z,1325718029.1836 [Default:CallGPS] Running Loop=1
2012-01-04T23:00:29.18380Z,1325718029.1838 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T23:00:29.18390Z,1325718029.1839 [Default:CallGPS:A] Running Loop=1
2012-01-04T23:00:29.18410Z,1325718029.1841 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T23:00:29.57310Z,1325718029.5731 [Default:GPS] Running Loop=1
2012-01-04T23:00:29.57330Z,1325718029.5733 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T23:00:29.57340Z,1325718029.5734 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T23:00:29.57350Z,1325718029.5735 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T23:00:29.57370Z,1325718029.5737 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T23:00:29.57370Z,1325718029.5737 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:00:29.57440Z,1325718029.5744 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T23:00:29.57450Z,1325718029.5745 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:00:29.57470Z,1325718029.5747 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T23:00:45.02500Z,1325718045.025 [NAL9601](INFO): SBD MO Status=1, MOMSN=40235, MT Status=0, MTMSN=0
2012-01-04T23:00:45.23520Z,1325718045.2352 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0008.lzma
2012-01-04T23:00:45.23540Z,1325718045.2354 [NAL9601](INFO): Packets left to send: 1
2012-01-04T23:00:45.23650Z,1325718045.2365 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000030
2012-01-04T23:00:53.50980Z,1325718053.5098 [NAL9601](INFO): SBD MO Status=1, MOMSN=40236, MT Status=0, MTMSN=0
2012-01-04T23:00:53.72310Z,1325718053.7231 [NAL9601](INFO): Sent 263 bytes from file Logs/20120104T212427/shore0008.lzma
2012-01-04T23:00:53.72340Z,1325718053.7234 [NAL9601](INFO): Packets left to send: 0
2012-01-04T23:00:53.72450Z,1325718053.7245 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000031
2012-01-04T23:01:00.30500Z,1325718060.305 [NAL9601](INFO): SBD MO Status=0, MOMSN=40237, MT Status=0, MTMSN=0
2012-01-04T23:01:00.53890Z,1325718060.5389 [Default:Iridium:Read_Iridium] Stopped
2012-01-04T23:01:00.53950Z,1325718060.5395 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-04T23:01:00.53950Z,1325718060.5395 [Default:Iridium] Stopped
2012-01-04T23:01:00.53970Z,1325718060.5397 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-04T23:01:00.53980Z,1325718060.5398 [Default:Iridium:A.SetSpeed] Stopped
2012-01-04T23:01:00.53980Z,1325718060.5398 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:01:00.79070Z,1325718060.7907 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-04T23:01:00.79080Z,1325718060.7908 [Default:CallIridium:A] Stopped
2012-01-04T23:01:00.79100Z,1325718060.791 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-04T23:01:00.79120Z,1325718060.7912 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-04T23:01:00.79130Z,1325718060.7913 [Default:CallIridium] Stopped
2012-01-04T23:01:00.79140Z,1325718060.7914 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-04T23:01:01.51100Z,1325718061.511 [NAL9601](IMPORTANT): GPS fix at: 1325718069
2012-01-04T23:01:01.52470Z,1325718061.5247 [Default:GPS:Read_GPS] Stopped
2012-01-04T23:01:01.52520Z,1325718061.5252 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T23:01:01.52530Z,1325718061.5253 [Default:GPS] Stopped
2012-01-04T23:01:01.52540Z,1325718061.5254 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T23:01:01.52550Z,1325718061.5255 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T23:01:01.52560Z,1325718061.5256 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:01:01.91730Z,1325718061.9173 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T23:01:01.91740Z,1325718061.9174 [Default:CallGPS:A] Stopped
2012-01-04T23:01:01.91760Z,1325718061.9176 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T23:01:01.91780Z,1325718061.9178 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T23:01:01.91790Z,1325718061.9179 [Default:CallGPS] Stopped
2012-01-04T23:01:01.91800Z,1325718061.918 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T23:01:22.05560Z,1325718082.0556 [NAL9601](INFO): Powering down
2012-01-04T23:06:02.09490Z,1325718362.0949 [Default:CallIridium] Running Loop=1
2012-01-04T23:06:02.09510Z,1325718362.0951 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-04T23:06:02.09530Z,1325718362.0953 [Default:CallIridium:A] Running Loop=1
2012-01-04T23:06:02.09540Z,1325718362.0954 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-04T23:06:02.09560Z,1325718362.0956 [Default:CallGPS] Running Loop=1
2012-01-04T23:06:02.09570Z,1325718362.0957 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T23:06:02.09580Z,1325718362.0958 [Default:CallGPS:A] Running Loop=1
2012-01-04T23:06:02.09600Z,1325718362.096 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T23:06:07.30100Z,1325718367.301 [Default:Iridium] Running Loop=1
2012-01-04T23:06:07.30120Z,1325718367.3012 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-04T23:06:07.30130Z,1325718367.3013 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-04T23:06:07.30140Z,1325718367.3014 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-04T23:06:07.30160Z,1325718367.3016 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-04T23:06:07.30160Z,1325718367.3016 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:06:07.30230Z,1325718367.3023 [Default:Iridium:B.GoToSurface] Stopped
2012-01-04T23:06:07.30230Z,1325718367.3023 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:06:07.30250Z,1325718367.3025 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-04T23:06:07.30290Z,1325718367.3029 [Default:GPS] Running Loop=1
2012-01-04T23:06:07.30310Z,1325718367.3031 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T23:06:07.30320Z,1325718367.3032 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T23:06:07.30320Z,1325718367.3032 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T23:06:07.30340Z,1325718367.3034 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T23:06:07.30350Z,1325718367.3035 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:06:07.30420Z,1325718367.3042 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T23:06:07.30430Z,1325718367.3043 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:06:07.30440Z,1325718367.3044 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T23:06:07.83970Z,1325718367.8397 [NAL9601](INFO): Powering up
2012-01-04T23:07:13.65120Z,1325718433.6512 [NAL9601](INFO): NAL9601 initialized
2012-01-04T23:07:39.38870Z,1325718459.3887 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=40238, MT Status=1, MTMSN=3349
2012-01-04T23:07:39.59920Z,1325718459.5992 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0009.lzma
2012-01-04T23:07:39.59940Z,1325718459.5994 [NAL9601](INFO): Packets left to send: 2
2012-01-04T23:07:39.60060Z,1325718459.6006 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000032
2012-01-04T23:07:40.01210Z,1325718460.0121 [NAL9601](INFO): Received command:restart logs
2012-01-04T23:07:40.06310Z,1325718460.0631 [CommandLine](IMPORTANT): got command restart logs