2012-06-20T16:03:49.643Z,1340208229.643 [Supervisor](DEBUG): Initializing supervisor.
2012-06-20T16:03:49.645Z,1340208229.645 [SyncHandler](DEBUG): Created PCaller Thread at 1077130464
2012-06-20T16:03:49.646Z,1340208229.646 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-06-20T16:03:49.647Z,1340208229.647 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 1077327072
2012-06-20T16:03:49.648Z,1340208229.648 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-06-20T16:03:49.659Z,1340208229.659 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-06-20T16:03:49.660Z,1340208229.660 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 1077523680
2012-06-20T16:03:49.660Z,1340208229.661 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2012-06-20T16:03:49.661Z,1340208229.661 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-06-20T16:03:49.662Z,1340208229.662 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-06-20T16:03:49.923Z,1340208229.923 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-06-20T16:03:49.923Z,1340208229.923 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-06-20T16:03:50.110Z,1340208230.110 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-06-20T16:03:50.111Z,1340208230.111 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-06-20T16:03:50.196Z,1340208230.196 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-06-20T16:03:50.197Z,1340208230.197 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-06-20T16:03:50.386Z,1340208230.385 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-06-20T16:03:50.386Z,1340208230.386 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-06-20T16:03:50.518Z,1340208230.518 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-06-20T16:03:50.519Z,1340208230.519 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-06-20T16:03:50.738Z,1340208230.738 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-06-20T16:03:50.739Z,1340208230.739 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-06-20T16:03:50.888Z,1340208230.888 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-06-20T16:03:50.888Z,1340208230.888 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-06-20T16:03:51.133Z,1340208231.134 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-06-20T16:03:51.134Z,1340208231.134 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-06-20T16:03:51.232Z,1340208231.232 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-06-20T16:03:51.233Z,1340208231.233 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-06-20T16:03:51.611Z,1340208231.611 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-06-20T16:03:51.612Z,1340208231.612 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-06-20T16:03:51.722Z,1340208231.722 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-06-20T16:03:51.722Z,1340208231.722 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-06-20T16:03:51.808Z,1340208231.808 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2012-06-20T16:03:51.809Z,1340208231.809 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2012-06-20T16:03:51.909Z,1340208231.909 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2012-06-20T16:03:52.039Z,1340208232.039 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2012-06-20T16:03:52.140Z,1340208232.140 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2012-06-20T16:03:52.236Z,1340208232.237 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2012-06-20T16:03:52.347Z,1340208232.347 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2012-06-20T16:03:52.438Z,1340208232.438 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2012-06-20T16:03:52.525Z,1340208232.525 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2012-06-20T16:03:52.637Z,1340208232.637 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-06-20T16:03:52.764Z,1340208232.764 [InternalSim] Loaded
2012-06-20T16:03:52.764Z,1340208232.764 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-06-20T16:03:52.765Z,1340208232.765 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-06-20T16:03:52.766Z,1340208232.766 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-06-20T16:03:52.812Z,1340208232.812 [SBIT](DEBUG): Construct Startup Built In Test.
2012-06-20T16:03:52.824Z,1340208232.824 [SBIT] Loaded
2012-06-20T16:03:52.824Z,1340208232.824 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-06-20T16:03:52.825Z,1340208232.825 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-06-20T16:03:52.851Z,1340208232.851 [IBIT] Loaded
2012-06-20T16:03:52.851Z,1340208232.851 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-06-20T16:03:52.854Z,1340208232.854 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-06-20T16:03:52.968Z,1340208232.968 [CBIT] Loaded
2012-06-20T16:03:52.968Z,1340208232.968 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-06-20T16:03:52.969Z,1340208232.969 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-06-20T16:03:52.969Z,1340208232.969 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-06-20T16:03:53.097Z,1340208233.097 [BuoyancyServo] Loaded
2012-06-20T16:03:53.097Z,1340208233.097 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-06-20T16:03:53.104Z,1340208233.104 [ElevatorServo] Loaded
2012-06-20T16:03:53.104Z,1340208233.104 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2012-06-20T16:03:53.111Z,1340208233.111 [MassServo] Loaded
2012-06-20T16:03:53.111Z,1340208233.111 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2012-06-20T16:03:53.118Z,1340208233.118 [RudderServo] Loaded
2012-06-20T16:03:53.118Z,1340208233.118 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-06-20T16:03:53.125Z,1340208233.125 [ThrusterServo] Loaded
2012-06-20T16:03:53.125Z,1340208233.125 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-06-20T16:03:53.126Z,1340208233.126 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-06-20T16:03:53.126Z,1340208233.126 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-06-20T16:03:53.142Z,1340208233.142 [DepthRateCalculator] Loaded
2012-06-20T16:03:53.142Z,1340208233.142 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-06-20T16:03:53.157Z,1340208233.157 [NavChart] Loaded
2012-06-20T16:03:53.158Z,1340208233.158 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-06-20T16:03:53.163Z,1340208233.163 [PitchRateCalculator] Loaded
2012-06-20T16:03:53.164Z,1340208233.164 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-06-20T16:03:53.170Z,1340208233.170 [SpeedCalculator] Loaded
2012-06-20T16:03:53.170Z,1340208233.170 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-06-20T16:03:53.184Z,1340208233.184 [TempGradientCalculator] Loaded
2012-06-20T16:03:53.184Z,1340208233.184 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-06-20T16:03:53.190Z,1340208233.190 [YawRateCalculator] Loaded
2012-06-20T16:03:53.190Z,1340208233.190 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-06-20T16:03:53.219Z,1340208233.219 [Navigation] Loaded
2012-06-20T16:03:53.220Z,1340208233.220 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-06-20T16:03:53.220Z,1340208233.220 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-06-20T16:03:53.221Z,1340208233.220 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-06-20T16:03:53.436Z,1340208233.436 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-06-20T16:03:53.437Z,1340208233.437 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-06-20T16:03:53.457Z,1340208233.457 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-06-20T16:03:53.457Z,1340208233.457 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-06-20T16:03:53.495Z,1340208233.495 [VerticalControl](DEBUG): Construct VerticalControl.
2012-06-20T16:03:53.538Z,1340208233.538 [VerticalControl] Loaded
2012-06-20T16:03:53.538Z,1340208233.538 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-06-20T16:03:53.539Z,1340208233.539 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-06-20T16:03:53.558Z,1340208233.558 [HorizontalControl] Loaded
2012-06-20T16:03:53.558Z,1340208233.558 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-06-20T16:03:53.559Z,1340208233.559 [SpeedControl](DEBUG): Construct SpeedControl.
2012-06-20T16:03:53.561Z,1340208233.561 [SpeedControl] Loaded
2012-06-20T16:03:53.561Z,1340208233.561 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-06-20T16:03:53.562Z,1340208233.562 [LoopControl](DEBUG): Construct LoopControl.
2012-06-20T16:03:53.563Z,1340208233.563 [LoopControl] Loaded
2012-06-20T16:03:53.563Z,1340208233.563 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-06-20T16:03:53.564Z,1340208233.564 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-06-20T16:03:53.564Z,1340208233.564 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-06-20T16:03:53.571Z,1340208233.571 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-06-20T16:03:53.576Z,1340208233.576 [AsyncPiEstimator] Loaded
2012-06-20T16:03:53.576Z,1340208233.576 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-06-20T16:03:53.577Z,1340208233.577 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 1078998240
2012-06-20T16:03:53.578Z,1340208233.578 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-06-20T16:03:53.578Z,1340208233.579 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-06-20T16:03:53.707Z,1340208233.707 [AHRS_sp3003D] Loaded
2012-06-20T16:03:53.707Z,1340208233.707 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-06-20T16:03:53.956Z,1340208233.956 [Batt_Ocean_Server] Loaded
2012-06-20T16:03:53.957Z,1340208233.957 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2012-06-20T16:03:53.969Z,1340208233.969 [Depth_Keller] Loaded
2012-06-20T16:03:53.969Z,1340208233.969 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2012-06-20T16:03:53.974Z,1340208233.974 [DropWeight] Loaded
2012-06-20T16:03:53.975Z,1340208233.975 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2012-06-20T16:03:54.067Z,1340208234.067 [DVL_micro] Loaded
2012-06-20T16:03:54.068Z,1340208234.068 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2012-06-20T16:03:54.162Z,1340208234.162 [NAL9601] Loaded
2012-06-20T16:03:54.162Z,1340208234.162 [ComponentRegistry](DEBUG): SyncComponent "NAL9601" handled in the control thread.
2012-06-20T16:03:54.210Z,1340208234.210 [Onboard] Loaded
2012-06-20T16:03:54.211Z,1340208234.211 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-06-20T16:03:54.218Z,1340208234.217 [Radio_Freewave] Loaded
2012-06-20T16:03:54.218Z,1340208234.218 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2012-06-20T16:03:54.219Z,1340208234.219 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-06-20T16:03:54.219Z,1340208234.219 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-06-20T16:03:54.265Z,1340208234.265 [Aanderaa_O2] Loaded
2012-06-20T16:03:54.265Z,1340208234.265 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2012-06-20T16:03:54.296Z,1340208234.296 [CTD_NeilBrown] Loaded
2012-06-20T16:03:54.297Z,1340208234.297 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2012-06-20T16:03:54.298Z,1340208234.298 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 1079690464
2012-06-20T16:03:54.328Z,1340208234.328 [WetLabsBB2FL] Loaded
2012-06-20T16:03:54.328Z,1340208234.328 [ComponentRegistry](DEBUG): SyncComponent "WetLabsBB2FL" handled in the control thread.
2012-06-20T16:03:54.328Z,1340208234.328 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-06-20T16:03:54.331Z,1340208234.331 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-06-20T16:03:54.332Z,1340208234.332 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-06-20T16:03:54.337Z,1340208234.337 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-06-20T16:03:54.338Z,1340208234.338 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 1079887072
2012-06-20T16:03:54.342Z,1340208234.342 [Supervisor](DEBUG): Running supervisor.
2012-06-20T16:03:54.345Z,1340208234.345 [controlThread](DEBUG): Initializing ControlThread
2012-06-20T16:03:54.346Z,1340208234.346 [InternalSim](DEBUG):  InternalSim initializing...
2012-06-20T16:03:54.379Z,1340208234.379 [SBIT](INFO): Initialize SBIT Component.
2012-06-20T16:03:54.382Z,1340208234.382 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 9708 $
2012-06-20T16:03:54.390Z,1340208234.390 [IBIT](INFO): Initialize IBIT Component.
2012-06-20T16:03:54.392Z,1340208234.392 [CBIT](DEBUG): Initialize CBIT Component.
2012-06-20T16:03:54.393Z,1340208234.393 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2012-06-20T16:03:54.393Z,1340208234.393 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-06-20T16:03:54.402Z,1340208234.402 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-06-20T16:03:54.424Z,1340208234.424 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-06-20T16:03:54.424Z,1340208234.424 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-06-20T16:03:54.424Z,1340208234.424 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-06-20T16:03:54.425Z,1340208234.425 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-06-20T16:03:54.425Z,1340208234.425 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-06-20T16:03:54.431Z,1340208234.431 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-06-20T16:03:54.431Z,1340208234.431 [Navigation](DEBUG): Initializing Navigation.
2012-06-20T16:03:54.431Z,1340208234.431 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-06-20T16:03:54.434Z,1340208234.434 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-06-20T16:03:54.443Z,1340208234.443 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-06-20T16:03:54.443Z,1340208234.443 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-06-20T16:03:54.517Z,1340208234.517 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-06-20T16:03:54.522Z,1340208234.522 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2012-06-20T16:03:54.526Z,1340208234.526 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2012-06-20T16:03:54.530Z,1340208234.530 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2012-06-20T16:03:54.534Z,1340208234.534 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2012-06-20T16:03:54.535Z,1340208234.535 [NavChartDb](INFO): Creating index for Soundings
2012-06-20T16:03:54.539Z,1340208234.539 [NavChartDb](INFO): Creating index for Contour 0p0
2012-06-20T16:03:54.540Z,1340208234.540 [NavChartDb](INFO): Creating index for Contour 1p8
2012-06-20T16:03:54.543Z,1340208234.543 [NavChartDb](INFO): Creating index for Contour 3p6
2012-06-20T16:03:54.544Z,1340208234.544 [NavChartDb](INFO): Creating index for Contour 5p4
2012-06-20T16:03:54.547Z,1340208234.546 [NavChartDb](INFO): Creating index for Contour 9p1
2012-06-20T16:03:54.548Z,1340208234.548 [NavChartDb](INFO): Creating index for Contour 10p9
2012-06-20T16:03:54.550Z,1340208234.550 [NavChartDb](INFO): Creating index for Contour 18p2
2012-06-20T16:03:54.552Z,1340208234.552 [NavChartDb](INFO): Creating index for Contour 36p5
2012-06-20T16:03:54.554Z,1340208234.554 [NavChartDb](INFO): Creating index for Contour 54p8
2012-06-20T16:03:54.556Z,1340208234.556 [NavChartDb](INFO): Creating index for Contour 73p1
2012-06-20T16:03:54.558Z,1340208234.558 [NavChartDb](INFO): Creating index for Contour 91p4
2012-06-20T16:03:54.560Z,1340208234.560 [NavChartDb](INFO): Creating index for Contour 182p8
2012-06-20T16:03:54.562Z,1340208234.562 [NavChartDb](INFO): Creating index for Contour 365p7
2012-06-20T16:03:54.564Z,1340208234.564 [NavChartDb](INFO): Creating index for Contour 548p6
2012-06-20T16:03:54.566Z,1340208234.566 [NavChartDb](INFO): Creating index for Contour 731p5
2012-06-20T16:03:54.568Z,1340208234.568 [NavChartDb](INFO): Creating index for Contour 914p4
2012-06-20T16:03:54.570Z,1340208234.569 [NavChartDb](INFO): Creating index for Contour 1097p2
2012-06-20T16:03:54.572Z,1340208234.572 [NavChartDb](INFO): Creating index for Contour 1280p1
2012-06-20T16:03:54.573Z,1340208234.573 [NavChartDb](INFO): Creating index for Contour 1463p0
2012-06-20T16:03:54.576Z,1340208234.576 [NavChartDb](INFO): Creating index for Contour 1645p9
2012-06-20T16:03:54.577Z,1340208234.577 [NavChartDb](INFO): Creating index for Contour 1828p8
2012-06-20T16:03:54.580Z,1340208234.580 [NavChartDb](INFO): Creating index for Contour 2011p6
2012-06-20T16:03:54.581Z,1340208234.581 [NavChartDb](INFO): Creating index for Contour 2194p5
2012-06-20T16:03:54.584Z,1340208234.584 [NavChartDb](INFO): Creating index for Contour 2377p4
2012-06-20T16:03:54.585Z,1340208234.585 [NavChartDb](INFO): Creating index for Contour 2560p3
2012-06-20T16:03:54.587Z,1340208234.588 [NavChartDb](INFO): Creating index for Contour 2743p2
2012-06-20T16:03:54.589Z,1340208234.589 [NavChartDb](INFO): Creating index for Contour 2926p0
2012-06-20T16:03:54.591Z,1340208234.591 [NavChartDb](INFO): Creating index for Contour 3108p9
2012-06-20T16:03:54.593Z,1340208234.593 [NavChartDb](INFO): Creating index for Contour 3291p8
2012-06-20T16:03:54.595Z,1340208234.595 [NavChartDb](INFO): Creating index for Contour 3474p7
2012-06-20T16:03:54.597Z,1340208234.597 [NavChartDb](INFO): Creating index for Contour 3657p6
2012-06-20T16:03:56.104Z,1340208236.104 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2012-06-20T16:03:56.109Z,1340208236.109 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-06-20T16:03:56.119Z,1340208236.119 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-06-20T16:03:56.129Z,1340208236.129 [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-06-20T16:03:56.130Z,1340208236.130 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-06-20T16:03:56.158Z,1340208236.158 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2012-06-20T16:03:56.160Z,1340208236.160 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-06-20T16:03:56.163Z,1340208236.163 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-06-20T16:03:56.170Z,1340208236.171 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-06-20T16:03:56.174Z,1340208236.174 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-06-20T16:03:56.180Z,1340208236.180 [Default:Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-06-20T16:03:56.189Z,1340208236.189 [Default:D.SetSpeed](DEBUG): Construct.
2012-06-20T16:03:56.191Z,1340208236.191 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2012-06-20T16:03:56.196Z,1340208236.196 [Default:F.Wait](DEBUG): Construct Wait.
2012-06-20T16:03:56.200Z,1340208236.200 [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">

    <DefineArg Name="NeedGPS"><True/></DefineArg>

    <Aggregate Id="GPS" >

        <When><Arg Name="NeedGPS"/>
        </When>

<!-- 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>

        <Assign><Arg Name="NeedGPS"/><False/></Assign>

    </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 300</String></Setting>
                </Guidance:Execute>
                <Syslog Severity="Critical">Dropped drop weight due to communications timeout</Syslog>
            </Timeout><Universal:platform_communications/>
        </ReadDatum>

    </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>

        <Assign><Arg Name="NeedGPS"/><True/></Assign>

        <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-06-20T16:03:56.204Z,1340208236.204 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9601,Onboard,Radio_Freewave,Aanderaa_O2,WetLabsBB2FL,Depth_Keller,DepthRateCalculator,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,logger,
2012-06-20T16:03:56.223Z,1340208236.223 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-06-20T16:03:56.334Z,1340208236.334 [DVL_micro](DEBUG): Initializing DVL_micro.
2012-06-20T16:03:56.354Z,1340208236.354 [Radio_Freewave](INFO): Powering up
2012-06-20T16:03:56.366Z,1340208236.365 [WetLabsBB2FL](INFO): Powering down
2012-06-20T16:03:56.435Z,1340208236.435 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-06-20T16:03:56.436Z,1340208236.436 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-06-20T16:03:56.445Z,1340208236.445 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-06-20T16:03:56.446Z,1340208236.446 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-06-20T16:03:56.454Z,1340208236.454 [MassServo](DEBUG): Initializing EZServoServo.
2012-06-20T16:03:56.455Z,1340208236.455 [MassServo](DEBUG): Initializing MassServo.
2012-06-20T16:03:56.462Z,1340208236.462 [RudderServo](DEBUG): Initializing EZServoServo.
2012-06-20T16:03:56.463Z,1340208236.463 [RudderServo](DEBUG): Initializing RudderServo.
2012-06-20T16:03:56.471Z,1340208236.471 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-06-20T16:03:56.472Z,1340208236.472 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-06-20T16:03:59.176Z,1340208239.176 [NAL9601](INFO): Powering up NAL9601
2012-06-20T16:04:00.463Z,1340208240.463 [Aanderaa_O2](INFO): Powering down
2012-06-20T16:04:09.959Z,1340208249.959 [SBIT](IMPORTANT): Beginning Startup BIT
2012-06-20T16:04:09.961Z,1340208249.961 [CBIT](IMPORTANT): Beginning GF scan
2012-06-20T16:04:36.171Z,1340208276.171 [CBIT](IMPORTANT): No ground fault detected
2012-06-20T16:04:40.974Z,1340208280.974 [SBIT](FAULT): Elevator: EXPECTED:-15.000000 ACTUAL:-14.905448
2012-06-20T16:04:40.974Z,1340208280.974 [SBIT](FAULT): Control surface position failure.
2012-06-20T16:04:52.019Z,1340208292.019 [SBIT](CRITICAL): SBIT FAILED
2012-06-20T16:04:52.447Z,1340208292.447 [MissionManager](IMPORTANT): Started mission Startup
2012-06-20T16:04:52.447Z,1340208292.447 [Startup] Running Loop=1
2012-06-20T16:04:52.447Z,1340208292.447 [Startup](INFO): Aggregate::initialize Startup
2012-06-20T16:04:52.448Z,1340208292.448 [Startup:A.GoToSurface] Running Loop=1
2012-06-20T16:04:52.448Z,1340208292.448 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T16:04:52.453Z,1340208292.453 [Startup:StartupSatComms] Running Loop=1
2012-06-20T16:04:52.453Z,1340208292.453 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2012-06-20T16:04:52.454Z,1340208292.454 [Startup:StartupSatComms:A] Running Loop=1
2012-06-20T16:04:52.812Z,1340208292.812 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-06-20T16:05:04.895Z,1340208304.895 [NAL9601](INFO): NAL9601 initialized
2012-06-20T16:05:08.001Z,1340208308.001 [NAL9601](IMPORTANT): GPS fix at: 1340208301.00
2012-06-20T16:05:08.014Z,1340208308.014 [Startup:StartupSatComms:A] Stopped
2012-06-20T16:05:08.015Z,1340208308.015 [Startup:StartupSatComms:B] Running Loop=1
2012-06-20T16:05:08.439Z,1340208308.439 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-06-20T16:05:08.539Z,1340208308.539 [NavChartDb](INFO): Charting Soundings
2012-06-20T16:05:10.139Z,1340208310.138 [NavChartDb](INFO): Charting 0p0
2012-06-20T16:05:11.739Z,1340208311.739 [NavChartDb](INFO): Charting 1p8
2012-06-20T16:05:13.339Z,1340208313.339 [NavChartDb](INFO): Charting 3p6
2012-06-20T16:05:14.938Z,1340208314.938 [NavChartDb](INFO): Charting 5p4
2012-06-20T16:05:16.538Z,1340208316.538 [NavChartDb](INFO): Charting 9p1
2012-06-20T16:05:18.139Z,1340208318.138 [NavChartDb](INFO): Charting 10p9
2012-06-20T16:05:19.739Z,1340208319.739 [NavChartDb](INFO): Charting 18p2
2012-06-20T16:05:21.106Z,1340208321.106 [NAL9601](INFO): SBD MO Status=1, MOMSN=9925, MT Status=0, MTMSN=0
2012-06-20T16:05:21.259Z,1340208321.259 [NAL9601](INFO): Sent 206 bytes from file Logs/20120620T152038/shore0009.lzma
2012-06-20T16:05:21.259Z,1340208321.259 [NAL9601](INFO): Packets left to send: 0
2012-06-20T16:05:21.261Z,1340208321.261 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T152038/shore0009.lzma.parts/0000.sbd
2012-06-20T16:05:21.419Z,1340208321.418 [NavChartDb](INFO): Charting 36p5
2012-06-20T16:05:23.019Z,1340208323.019 [NavChartDb](INFO): Charting 54p8
2012-06-20T16:05:29.494Z,1340208329.494 [NavChartDb](INFO): Charting 73p1
2012-06-20T16:05:30.838Z,1340208330.838 [NAL9601](INFO): SBD MO Status=1, MOMSN=9926, MT Status=0, MTMSN=0
2012-06-20T16:05:31.043Z,1340208331.043 [NAL9601](INFO): Sent 332 bytes from file Logs/20120620T160349/shore0000.lzma
2012-06-20T16:05:31.043Z,1340208331.043 [NAL9601](INFO): Packets left to send: 1
2012-06-20T16:05:31.045Z,1340208331.045 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0000.lzma.parts/0001.sbd
2012-06-20T16:05:31.094Z,1340208331.095 [NavChartDb](INFO): Charting 91p4
2012-06-20T16:05:33.014Z,1340208333.014 [NavChartDb](INFO): Charting 182p8
2012-06-20T16:05:39.805Z,1340208339.805 [NAL9601](INFO): SBD MO Status=1, MOMSN=9927, MT Status=0, MTMSN=0
2012-06-20T16:05:39.931Z,1340208339.931 [NAL9601](INFO): Sent 295 bytes from file Logs/20120620T160349/shore0000.lzma
2012-06-20T16:05:39.931Z,1340208339.931 [NAL9601](INFO): Packets left to send: 0
2012-06-20T16:05:39.932Z,1340208339.932 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0000.lzma.parts/0000.sbd
2012-06-20T16:05:40.831Z,1340208340.830 [NavChartDb](INFO): Charting 365p7
2012-06-20T16:05:43.127Z,1340208343.127 [NavChartDb](INFO): Charting 548p6
2012-06-20T16:05:44.751Z,1340208344.750 [NavChartDb](INFO): Charting 731p5
2012-06-20T16:05:47.259Z,1340208347.259 [NavChartDb](INFO): Charting 914p4
2012-06-20T16:05:49.405Z,1340208349.405 [NAL9601](INFO): SBD MO Status=0, MOMSN=9928, MT Status=0, MTMSN=0
2012-06-20T16:05:49.646Z,1340208349.646 [Startup:StartupSatComms:B] Stopped
2012-06-20T16:05:49.646Z,1340208349.646 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2012-06-20T16:05:49.646Z,1340208349.646 [Startup:StartupSatComms] Stopped
2012-06-20T16:05:49.646Z,1340208349.647 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2012-06-20T16:05:49.647Z,1340208349.647 [Startup](INFO): Completed Startup
2012-06-20T16:05:49.647Z,1340208349.647 [Startup] Stopped
2012-06-20T16:05:49.647Z,1340208349.648 [Startup](INFO): Aggregate::uninitialize Startup
2012-06-20T16:05:49.648Z,1340208349.648 [Startup:A.GoToSurface] Stopped
2012-06-20T16:05:49.648Z,1340208349.648 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T16:05:49.831Z,1340208349.832 [MissionManager](IMPORTANT): Started mission Default
2012-06-20T16:05:49.832Z,1340208349.832 [Default] Running Loop=1
2012-06-20T16:05:49.832Z,1340208349.832 [Default](INFO): Aggregate::initialize Default
2012-06-20T16:05:49.832Z,1340208349.832 [Default:D.SetSpeed] Running Loop=1
2012-06-20T16:05:49.832Z,1340208349.832 [Default:D.SetSpeed](DEBUG): Initialize.
2012-06-20T16:05:49.832Z,1340208349.832 [Default:E.GoToSurface] Running Loop=1
2012-06-20T16:05:49.832Z,1340208349.832 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T16:05:49.832Z,1340208349.832 [Default:Iridium] Running Loop=1
2012-06-20T16:05:49.832Z,1340208349.832 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-06-20T16:05:49.833Z,1340208349.833 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-06-20T16:05:49.833Z,1340208349.833 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-06-20T16:05:49.833Z,1340208349.833 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-06-20T16:05:49.833Z,1340208349.833 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T16:05:49.833Z,1340208349.833 [Default:E.GoToSurface] Running Loop=1
2012-06-20T16:05:49.846Z,1340208349.846 [Default:D.SetSpeed] Running Loop=1
2012-06-20T16:05:49.864Z,1340208349.864 [Default:Iridium:B.GoToSurface] Stopped
2012-06-20T16:05:49.864Z,1340208349.864 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T16:05:49.864Z,1340208349.864 [Default:Iridium:Read_Iridium] Running Loop=1
2012-06-20T16:05:49.864Z,1340208349.864 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-06-20T16:05:49.873Z,1340208349.873 [Default:GPS] Running Loop=1
2012-06-20T16:05:49.873Z,1340208349.873 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-06-20T16:05:49.873Z,1340208349.873 [Default:GPS:A.SetSpeed] Running Loop=1
2012-06-20T16:05:49.873Z,1340208349.873 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-06-20T16:05:49.873Z,1340208349.873 [Default:GPS:B.GoToSurface] Running Loop=1
2012-06-20T16:05:49.873Z,1340208349.873 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T16:05:49.886Z,1340208349.886 [Default:GPS:B.GoToSurface] Stopped
2012-06-20T16:05:49.887Z,1340208349.886 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T16:05:49.887Z,1340208349.887 [Default:GPS:Read_GPS] Running Loop=1
2012-06-20T16:05:49.887Z,1340208349.887 [Default:GPS:A.SetSpeed] Running Loop=1
2012-06-20T16:05:50.228Z,1340208350.228 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-06-20T16:05:50.235Z,1340208350.235 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-06-20T16:05:51.803Z,1340208351.803 [NAL9601](IMPORTANT): GPS fix at: 1340208345.00
2012-06-20T16:05:51.839Z,1340208351.839 [Default:GPS:Read_GPS] Stopped
2012-06-20T16:05:51.839Z,1340208351.839 [Default:GPS:D] Running Loop=1
2012-06-20T16:05:52.249Z,1340208352.249 [Default:GPS:D] Stopped
2012-06-20T16:05:52.250Z,1340208352.250 [Default:GPS](INFO): Completed Default:GPS
2012-06-20T16:05:52.250Z,1340208352.250 [Default:GPS] Stopped
2012-06-20T16:05:52.250Z,1340208352.250 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-06-20T16:05:52.250Z,1340208352.250 [Default:GPS:A.SetSpeed] Stopped
2012-06-20T16:05:52.250Z,1340208352.250 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T16:06:11.238Z,1340208371.238 [NAL9601](INFO): SBD MO Status=1, MOMSN=9929, MT Status=0, MTMSN=0
2012-06-20T16:06:11.383Z,1340208371.383 [NAL9601](INFO): Sent 148 bytes from file Logs/20120620T160349/shore0001.lzma
2012-06-20T16:06:11.383Z,1340208371.383 [NAL9601](INFO): Packets left to send: 0
2012-06-20T16:06:11.384Z,1340208371.384 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0001.lzma.parts/0000.sbd
2012-06-20T16:06:18.033Z,1340208378.033 [NAL9601](INFO): SBD MO Status=0, MOMSN=9930, MT Status=0, MTMSN=0
2012-06-20T16:06:18.185Z,1340208378.185 [Default:Iridium:Read_Iridium] Stopped
2012-06-20T16:06:18.186Z,1340208378.186 [Default:Iridium](INFO): Completed Default:Iridium
2012-06-20T16:06:18.186Z,1340208378.186 [Default:Iridium] Stopped
2012-06-20T16:06:18.186Z,1340208378.186 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-06-20T16:06:18.186Z,1340208378.186 [Default:Iridium:A.SetSpeed] Stopped
2012-06-20T16:06:18.186Z,1340208378.186 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T16:06:18.186Z,1340208378.186 [Default:F.Wait] Running Loop=1
2012-06-20T16:06:18.186Z,1340208378.186 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-06-20T16:06:28.664Z,1340208388.664 [NAL9601](INFO): Powering down
2012-06-20T16:06:30.334Z,1340208390.334 [NavChartDb](INFO): Charting 1097p2
2012-06-20T16:06:32.514Z,1340208392.514 [NavChartDb](INFO): Charting 1280p1
2012-06-20T16:06:34.922Z,1340208394.922 [NavChartDb](INFO): Charting 1463p0
2012-06-20T16:06:37.070Z,1340208397.070 [NavChartDb](INFO): Charting 1645p9
2012-06-20T16:06:39.034Z,1340208399.034 [NavChartDb](INFO): Charting 1828p8
2012-06-20T16:06:49.330Z,1340208409.330 [NavChartDb](INFO): Charting 2011p6
2012-06-20T16:06:50.930Z,1340208410.930 [NavChartDb](INFO): Charting 2194p5
2012-06-20T16:06:52.690Z,1340208412.690 [NavChartDb](INFO): Charting 2377p4
2012-06-20T16:06:54.562Z,1340208414.562 [NavChartDb](INFO): Charting 2560p3
2012-06-20T16:06:56.162Z,1340208416.162 [NavChartDb](INFO): Charting 2743p2
2012-06-20T16:07:01.661Z,1340208421.661 [NavChartDb](INFO): Charting 2926p0
2012-06-20T16:07:03.651Z,1340208423.651 [NavChartDb](INFO): Charting 3108p9
2012-06-20T16:07:05.566Z,1340208425.566 [NavChartDb](INFO): Charting 3291p8
2012-06-20T16:07:07.326Z,1340208427.326 [NavChartDb](INFO): Charting 3474p7
2012-06-20T16:07:08.927Z,1340208428.927 [NavChartDb](INFO): Charting 3657p6
2012-06-20T16:11:18.564Z,1340208678.564 [Default:CallIridium] Running Loop=1
2012-06-20T16:11:18.564Z,1340208678.564 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-06-20T16:11:18.564Z,1340208678.564 [Default:CallIridium:A] Running Loop=1
2012-06-20T16:11:18.566Z,1340208678.566 [Default:CallIridium:A] Stopped
2012-06-20T16:11:18.566Z,1340208678.566 [Default:CallIridium:B] Running Loop=1
2012-06-20T16:11:18.566Z,1340208678.566 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-06-20T16:11:23.637Z,1340208683.637 [Default:Iridium] Running Loop=1
2012-06-20T16:11:23.637Z,1340208683.637 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-06-20T16:11:23.637Z,1340208683.637 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-06-20T16:11:23.637Z,1340208683.637 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-06-20T16:11:23.637Z,1340208683.638 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-06-20T16:11:23.638Z,1340208683.638 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T16:11:23.639Z,1340208683.639 [Default:Iridium:B.GoToSurface] Stopped
2012-06-20T16:11:23.639Z,1340208683.639 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T16:11:23.639Z,1340208683.639 [Default:Iridium:Read_Iridium] Running Loop=1
2012-06-20T16:11:23.639Z,1340208683.639 [Default:GPS] Running Loop=1
2012-06-20T16:11:23.639Z,1340208683.639 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-06-20T16:11:23.639Z,1340208683.639 [Default:GPS:A.SetSpeed] Running Loop=1
2012-06-20T16:11:23.639Z,1340208683.639 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-06-20T16:11:23.640Z,1340208683.640 [Default:GPS:B.GoToSurface] Running Loop=1
2012-06-20T16:11:23.640Z,1340208683.640 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T16:11:23.640Z,1340208683.640 [Default:GPS:B.GoToSurface] Stopped
2012-06-20T16:11:23.641Z,1340208683.641 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T16:11:23.641Z,1340208683.641 [Default:GPS:Read_GPS] Running Loop=1
2012-06-20T16:11:24.247Z,1340208684.247 [NAL9601](INFO): Powering up
2012-06-20T16:12:29.871Z,1340208749.871 [NAL9601](INFO): NAL9601 initialized
2012-06-20T16:12:31.053Z,1340208751.053 [NAL9601](IMPORTANT): GPS fix at: 1340208745.00
2012-06-20T16:12:31.072Z,1340208751.072 [Default:GPS:Read_GPS] Stopped
2012-06-20T16:12:31.072Z,1340208751.072 [Default:GPS:D] Running Loop=1
2012-06-20T16:12:31.476Z,1340208751.476 [Default:GPS:D] Stopped
2012-06-20T16:12:31.476Z,1340208751.476 [Default:GPS](INFO): Completed Default:GPS
2012-06-20T16:12:31.477Z,1340208751.477 [Default:GPS] Stopped
2012-06-20T16:12:31.477Z,1340208751.477 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-06-20T16:12:31.477Z,1340208751.477 [Default:GPS:A.SetSpeed] Stopped
2012-06-20T16:12:31.477Z,1340208751.477 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T16:12:44.160Z,1340208764.160 [NAL9601](INFO): SBD MO Status=1, MOMSN=9931, MT Status=0, MTMSN=0
2012-06-20T16:12:44.335Z,1340208764.335 [NAL9601](INFO): Sent 141 bytes from file Logs/20120620T160349/shore0002.lzma
2012-06-20T16:12:44.335Z,1340208764.335 [NAL9601](INFO): Packets left to send: 0
2012-06-20T16:12:44.336Z,1340208764.336 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0002.lzma.parts/0000.sbd
2012-06-20T16:12:45.394Z,1340208765.394 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#5 STATUS: 65535
2012-06-20T16:12:52.966Z,1340208772.966 [NAL9601](INFO): SBD MO Status=0, MOMSN=9932, MT Status=0, MTMSN=0
2012-06-20T16:12:53.138Z,1340208773.138 [Default:Iridium:Read_Iridium] Stopped
2012-06-20T16:12:53.139Z,1340208773.139 [Default:Iridium](INFO): Completed Default:Iridium
2012-06-20T16:12:53.139Z,1340208773.139 [Default:Iridium] Stopped
2012-06-20T16:12:53.139Z,1340208773.139 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-06-20T16:12:53.139Z,1340208773.139 [Default:Iridium:A.SetSpeed] Stopped
2012-06-20T16:12:53.139Z,1340208773.139 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T16:12:53.374Z,1340208773.374 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-06-20T16:12:53.374Z,1340208773.374 [Default:CallIridium:B] Stopped
2012-06-20T16:12:53.375Z,1340208773.375 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-06-20T16:12:53.375Z,1340208773.375 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-06-20T16:12:53.375Z,1340208773.375 [Default:CallIridium] Stopped
2012-06-20T16:12:53.375Z,1340208773.375 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-06-20T16:13:03.520Z,1340208783.520 [NAL9601](INFO): Powering down
2012-06-20T16:17:53.651Z,1340209073.651 [Default:CallIridium] Running Loop=1
2012-06-20T16:17:53.652Z,1340209073.652 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-06-20T16:17:53.652Z,1340209073.652 [Default:CallIridium:A] Running Loop=1
2012-06-20T16:17:53.652Z,1340209073.652 [Default:CallIridium:A] Stopped
2012-06-20T16:17:53.652Z,1340209073.652 [Default:CallIridium:B] Running Loop=1
2012-06-20T16:17:53.652Z,1340209073.652 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-06-20T16:17:58.778Z,1340209078.778 [Default:Iridium] Running Loop=1
2012-06-20T16:17:58.778Z,1340209078.778 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-06-20T16:17:58.778Z,1340209078.778 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-06-20T16:17:58.778Z,1340209078.778 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-06-20T16:17:58.778Z,1340209078.778 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-06-20T16:17:58.779Z,1340209078.779 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T16:17:58.779Z,1340209078.779 [Default:Iridium:B.GoToSurface] Stopped
2012-06-20T16:17:58.779Z,1340209078.779 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T16:17:58.779Z,1340209078.779 [Default:Iridium:Read_Iridium] Running Loop=1
2012-06-20T16:17:58.780Z,1340209078.780 [Default:GPS] Running Loop=1
2012-06-20T16:17:58.780Z,1340209078.780 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-06-20T16:17:58.780Z,1340209078.780 [Default:GPS:A.SetSpeed] Running Loop=1
2012-06-20T16:17:58.780Z,1340209078.780 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-06-20T16:17:58.780Z,1340209078.780 [Default:GPS:B.GoToSurface] Running Loop=1
2012-06-20T16:17:58.780Z,1340209078.780 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T16:17:58.781Z,1340209078.781 [Default:GPS:B.GoToSurface] Stopped
2012-06-20T16:17:58.781Z,1340209078.781 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T16:17:58.781Z,1340209078.781 [Default:GPS:Read_GPS] Running Loop=1
2012-06-20T16:17:59.464Z,1340209079.464 [NAL9601](INFO): Powering up
2012-06-20T16:19:05.087Z,1340209145.087 [NAL9601](INFO): NAL9601 initialized
2012-06-20T16:20:03.684Z,1340209203.684 [NAL9601](INFO): SBD MO Status=2, MOMSN=9933, MT Status=2, MTMSN=0
2012-06-20T16:20:03.685Z,1340209203.685 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-06-20T16:21:23.189Z,1340209283.188 [NAL9601](INFO): SBD MO Status=1, MOMSN=9933, MT Status=0, MTMSN=0
2012-06-20T16:21:23.363Z,1340209283.363 [NAL9601](INFO): Sent 204 bytes from file Logs/20120620T160349/shore0003.lzma
2012-06-20T16:21:23.363Z,1340209283.363 [NAL9601](INFO): Packets left to send: 0
2012-06-20T16:21:23.364Z,1340209283.365 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0003.lzma.parts/0000.sbd
2012-06-20T16:21:31.589Z,1340209291.589 [NAL9601](INFO): SBD MO Status=0, MOMSN=9934, MT Status=0, MTMSN=0
2012-06-20T16:21:31.765Z,1340209291.765 [Default:Iridium:Read_Iridium] Stopped
2012-06-20T16:21:31.766Z,1340209291.766 [Default:Iridium](INFO): Completed Default:Iridium
2012-06-20T16:21:31.766Z,1340209291.766 [Default:Iridium] Stopped
2012-06-20T16:21:31.766Z,1340209291.766 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-06-20T16:21:31.766Z,1340209291.766 [Default:Iridium:A.SetSpeed] Stopped
2012-06-20T16:21:31.766Z,1340209291.766 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T16:21:32.002Z,1340209292.002 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-06-20T16:21:32.002Z,1340209292.003 [Default:CallIridium:B] Stopped
2012-06-20T16:21:32.003Z,1340209292.003 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-06-20T16:21:32.003Z,1340209292.003 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-06-20T16:21:32.003Z,1340209292.003 [Default:CallIridium] Stopped
2012-06-20T16:21:32.003Z,1340209292.003 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-06-20T16:21:32.795Z,1340209292.795 [NAL9601](IMPORTANT): GPS fix at: 1340209288.00
2012-06-20T16:21:32.810Z,1340209292.810 [Default:GPS:Read_GPS] Stopped
2012-06-20T16:21:32.811Z,1340209292.810 [Default:GPS:D] Running Loop=1
2012-06-20T16:21:33.203Z,1340209293.203 [Default:GPS:D] Stopped
2012-06-20T16:21:33.204Z,1340209293.204 [Default:GPS](INFO): Completed Default:GPS
2012-06-20T16:21:33.204Z,1340209293.204 [Default:GPS] Stopped
2012-06-20T16:21:33.204Z,1340209293.204 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-06-20T16:21:33.204Z,1340209293.204 [Default:GPS:A.SetSpeed] Stopped
2012-06-20T16:21:33.204Z,1340209293.204 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T16:21:48.788Z,1340209308.788 [NAL9601](INFO): Powering down
2012-06-20T16:21:58.770Z,1340209318.770 [Depth_Keller](ERROR): Pressure reading out of range: 1830.913208 decibar
2012-06-20T16:22:08.763Z,1340209328.763 [Depth_Keller](ERROR): Pressure reading out of range: 1830.440063 decibar
2012-06-20T16:22:18.720Z,1340209338.720 [Depth_Keller](ERROR): Pressure reading out of range: 1830.490845 decibar
2012-06-20T16:22:28.730Z,1340209348.730 [Depth_Keller](ERROR): Pressure reading out of range: 1830.693359 decibar
2012-06-20T16:22:38.749Z,1340209358.749 [Depth_Keller](ERROR): Pressure reading out of range: 1830.906250 decibar
2012-06-20T16:22:48.758Z,1340209368.758 [Depth_Keller](ERROR): Pressure reading out of range: 1830.686279 decibar
2012-06-20T16:22:58.829Z,1340209378.829 [Depth_Keller](ERROR): Pressure reading out of range: 1830.568359 decibar
2012-06-20T16:23:48.839Z,1340209428.839 [Depth_Keller](ERROR): Pressure reading out of range: 1830.685303 decibar
2012-06-20T16:23:58.747Z,1340209438.747 [Depth_Keller](ERROR): Pressure reading out of range: 1830.567505 decibar
2012-06-20T16:24:18.902Z,1340209458.902 [Depth_Keller](ERROR): Pressure reading out of range: 1831.004883 decibar
2012-06-20T16:24:38.930Z,1340209478.930 [Depth_Keller](ERROR): Pressure reading out of range: 1830.471436 decibar
2012-06-20T16:24:53.744Z,1340209493.744 [Depth_Keller](ERROR): Pressure reading out of range: 1830.508179 decibar
2012-06-20T16:25:48.720Z,1340209548.720 [Depth_Keller](ERROR): Pressure reading out of range: 1830.563232 decibar
2012-06-20T16:26:08.831Z,1340209568.831 [Depth_Keller](ERROR): Pressure reading out of range: 1830.515259 decibar
2012-06-20T16:26:33.954Z,1340209593.954 [Default:CallIridium] Running Loop=1
2012-06-20T16:26:33.954Z,1340209593.954 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-06-20T16:26:33.955Z,1340209593.954 [Default:CallIridium:A] Running Loop=1
2012-06-20T16:26:33.955Z,1340209593.955 [Default:CallIridium:A] Stopped
2012-06-20T16:26:33.955Z,1340209593.955 [Default:CallIridium:B] Running Loop=1
2012-06-20T16:26:33.955Z,1340209593.955 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-06-20T16:26:38.747Z,1340209598.747 [Default:Iridium] Running Loop=1
2012-06-20T16:26:38.747Z,1340209598.747 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-06-20T16:26:38.747Z,1340209598.747 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-06-20T16:26:38.748Z,1340209598.747 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-06-20T16:26:38.748Z,1340209598.748 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-06-20T16:26:38.748Z,1340209598.748 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T16:26:38.748Z,1340209598.748 [Default:Iridium:B.GoToSurface] Stopped
2012-06-20T16:26:38.748Z,1340209598.749 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T16:26:38.749Z,1340209598.749 [Default:Iridium:Read_Iridium] Running Loop=1
2012-06-20T16:26:38.749Z,1340209598.749 [Default:GPS] Running Loop=1
2012-06-20T16:26:38.749Z,1340209598.749 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-06-20T16:26:38.749Z,1340209598.749 [Default:GPS:A.SetSpeed] Running Loop=1
2012-06-20T16:26:38.749Z,1340209598.749 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-06-20T16:26:38.749Z,1340209598.750 [Default:GPS:B.GoToSurface] Running Loop=1
2012-06-20T16:26:38.749Z,1340209598.750 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T16:26:38.750Z,1340209598.750 [Default:GPS:B.GoToSurface] Stopped
2012-06-20T16:26:38.750Z,1340209598.750 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T16:26:38.751Z,1340209598.750 [Default:GPS:Read_GPS] Running Loop=1
2012-06-20T16:26:39.409Z,1340209599.409 [NAL9601](INFO): Powering up
2012-06-20T16:27:45.131Z,1340209665.131 [NAL9601](INFO): NAL9601 initialized
2012-06-20T16:28:08.112Z,1340209688.112 [NAL9601](INFO): SBD MO Status=1, MOMSN=9935, MT Status=0, MTMSN=0
2012-06-20T16:28:08.287Z,1340209688.287 [NAL9601](INFO): Sent 168 bytes from file Logs/20120620T160349/shore0004.lzma
2012-06-20T16:28:08.287Z,1340209688.287 [NAL9601](INFO): Packets left to send: 0
2012-06-20T16:28:08.288Z,1340209688.288 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0004.lzma.parts/0000.sbd
2012-06-20T16:28:15.682Z,1340209695.682 [NAL9601](INFO): SBD MO Status=0, MOMSN=9936, MT Status=0, MTMSN=0
2012-06-20T16:28:15.890Z,1340209695.890 [Default:Iridium:Read_Iridium] Stopped
2012-06-20T16:28:15.891Z,1340209695.891 [Default:Iridium](INFO): Completed Default:Iridium
2012-06-20T16:28:15.891Z,1340209695.891 [Default:Iridium] Stopped
2012-06-20T16:28:15.891Z,1340209695.891 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-06-20T16:28:15.891Z,1340209695.891 [Default:Iridium:A.SetSpeed] Stopped
2012-06-20T16:28:15.891Z,1340209695.891 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T16:28:16.090Z,1340209696.090 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-06-20T16:28:16.090Z,1340209696.090 [Default:CallIridium:B] Stopped
2012-06-20T16:28:16.090Z,1340209696.090 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-06-20T16:28:16.091Z,1340209696.091 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-06-20T16:28:16.091Z,1340209696.091 [Default:CallIridium] Stopped
2012-06-20T16:28:16.091Z,1340209696.091 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-06-20T16:28:16.956Z,1340209696.956 [NAL9601](IMPORTANT): GPS fix at: 1340209692.00
2012-06-20T16:28:16.988Z,1340209696.988 [Default:GPS:Read_GPS] Stopped
2012-06-20T16:28:16.988Z,1340209696.988 [Default:GPS:D] Running Loop=1
2012-06-20T16:28:17.335Z,1340209697.335 [Default:GPS:D] Stopped
2012-06-20T16:28:17.336Z,1340209697.336 [Default:GPS](INFO): Completed Default:GPS
2012-06-20T16:28:17.336Z,1340209697.336 [Default:GPS] Stopped
2012-06-20T16:28:17.336Z,1340209697.336 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-06-20T16:28:17.336Z,1340209697.336 [Default:GPS:A.SetSpeed] Stopped
2012-06-20T16:28:17.336Z,1340209697.336 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T16:28:32.828Z,1340209712.828 [NAL9601](INFO): Powering down
2012-06-20T16:30:22.973Z,1340209822.973 [Depth_Keller](ERROR): Pressure reading out of range: 1830.658325 decibar
2012-06-20T16:33:17.897Z,1340209997.897 [Default:CallIridium] Running Loop=1
2012-06-20T16:33:17.897Z,1340209997.897 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-06-20T16:33:17.897Z,1340209997.897 [Default:CallIridium:A] Running Loop=1
2012-06-20T16:33:17.898Z,1340209997.898 [Default:CallIridium:A] Stopped
2012-06-20T16:33:17.898Z,1340209997.898 [Default:CallIridium:B] Running Loop=1
2012-06-20T16:33:17.898Z,1340209997.898 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-06-20T16:33:22.858Z,1340210002.858 [Default:Iridium] Running Loop=1
2012-06-20T16:33:22.858Z,1340210002.858 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-06-20T16:33:22.858Z,1340210002.858 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-06-20T16:33:22.858Z,1340210002.858 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-06-20T16:33:22.858Z,1340210002.858 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-06-20T16:33:22.858Z,1340210002.858 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T16:33:22.859Z,1340210002.859 [Default:Iridium:B.GoToSurface] Stopped
2012-06-20T16:33:22.859Z,1340210002.859 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T16:33:22.859Z,1340210002.859 [Default:Iridium:Read_Iridium] Running Loop=1
2012-06-20T16:33:22.860Z,1340210002.860 [Default:GPS] Running Loop=1
2012-06-20T16:33:22.860Z,1340210002.860 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-06-20T16:33:22.860Z,1340210002.860 [Default:GPS:A.SetSpeed] Running Loop=1
2012-06-20T16:33:22.860Z,1340210002.860 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-06-20T16:33:22.860Z,1340210002.860 [Default:GPS:B.GoToSurface] Running Loop=1
2012-06-20T16:33:22.860Z,1340210002.860 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T16:33:22.861Z,1340210002.861 [Default:GPS:B.GoToSurface] Stopped
2012-06-20T16:33:22.861Z,1340210002.861 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T16:33:22.861Z,1340210002.861 [Default:GPS:Read_GPS] Running Loop=1
2012-06-20T16:33:23.475Z,1340210003.475 [NAL9601](INFO): Powering up
2012-06-20T16:34:29.199Z,1340210069.199 [NAL9601](INFO): NAL9601 initialized
2012-06-20T16:34:30.283Z,1340210070.283 [NAL9601](IMPORTANT): GPS fix at: 1340210066.00
2012-06-20T16:34:30.299Z,1340210070.299 [Default:GPS:Read_GPS] Stopped
2012-06-20T16:34:30.299Z,1340210070.299 [Default:GPS:D] Running Loop=1
2012-06-20T16:34:30.691Z,1340210070.691 [Default:GPS:D] Stopped
2012-06-20T16:34:30.691Z,1340210070.691 [Default:GPS](INFO): Completed Default:GPS
2012-06-20T16:34:30.691Z,1340210070.691 [Default:GPS] Stopped
2012-06-20T16:34:30.691Z,1340210070.691 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-06-20T16:34:30.691Z,1340210070.691 [Default:GPS:A.SetSpeed] Stopped
2012-06-20T16:34:30.691Z,1340210070.691 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T16:34:55.879Z,1340210095.879 [NAL9601](INFO): SBD MO Status=2, MOMSN=9937, MT Status=2, MTMSN=0
2012-06-20T16:34:55.879Z,1340210095.879 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-06-20T16:35:16.165Z,1340210116.165 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=9937, MT Status=1, MTMSN=2741
2012-06-20T16:35:16.319Z,1340210116.319 [NAL9601](INFO): Sent 208 bytes from file Logs/20120620T160349/shore0005.lzma
2012-06-20T16:35:16.319Z,1340210116.319 [NAL9601](INFO): Packets left to send: 0
2012-06-20T16:35:16.320Z,1340210116.320 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0005.lzma.parts/0000.sbd
2012-06-20T16:35:16.732Z,1340210116.732 [NAL9601](INFO): Received command:run Transport/transit_3km.xml
2012-06-20T16:35:16.749Z,1340210116.749 [CommandLine](IMPORTANT): got command run ./Missions/Transport/transit_3km.xml
2012-06-20T16:35:16.749Z,1340210116.749 [MissionManager](INFO): Loading Mission: ./Missions/Transport/transit_3km.xml
2012-06-20T16:35:16.796Z,1340210116.796 [MissionManager](INFO): DefineArg transit_3km.ApproachDepth = 10.000000 m
2012-06-20T16:35:16.799Z,1340210116.799 [MissionManager](INFO): DefineArg transit_3km.Wpt1Lat = 36.806966 arcdeg
2012-06-20T16:35:16.801Z,1340210116.801 [MissionManager](INFO): DefineArg transit_3km.Wpt1Lon = -121.824326 arcdeg
2012-06-20T16:35:16.808Z,1340210116.808 [MissionManager](INFO): DefineArg transit_3km.Speed = 1.000000 m/s
2012-06-20T16:35:16.811Z,1340210116.811 [MissionManager](INFO): DefineArg transit_3km.MaxDepth = 20.000000 m
2012-06-20T16:35:16.814Z,1340210116.814 [MissionManager](INFO): DefineArg transit_3km.TimeoutDuration = 240.000000 min
2012-06-20T16:35:16.816Z,1340210116.816 [transit_3km:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-06-20T16:35:16.832Z,1340210116.832 [transit_3km:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-06-20T16:35:16.849Z,1340210116.849 [transit_3km:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2012-06-20T16:35:16.868Z,1340210116.868 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-06-20T16:35:16.878Z,1340210116.878 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Construct.
2012-06-20T16:35:16.902Z,1340210116.902 [transit_3km:WaypointOne:A.Pitch](DEBUG): Construct.
2012-06-20T16:35:16.925Z,1340210116.925 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Construct.
2012-06-20T16:35:16.933Z,1340210116.933 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Construct Waypoint.
2012-06-20T16:35:16.956Z,1340210116.955 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="utf-8"?>
<Mission xmlns="Tethys" xmlns:Control="Tethys/Control" xmlns:Guidance="Tethys/Guidance" xmlns:Units="Tethys/Units" xmlns:Universal="Tethys/Universal" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd                            Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd                            Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd                            Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd                            Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd" Id="transit_3km">

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

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

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

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

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

    <DefineArg Name="MaxDepth"><Description>
        Maximum depth for the entire mission.
    </Description><Units:meter/><Value>20</Value></DefineArg>

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

    <Timeout Duration="TimeoutDuration"/>

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

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

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

    <Aggregate Id="SURFACECOMMS">

        <Guidance:GoToSurface RunIn="Progression" />

        <Aggregate>

            <Preemptive><True /></Preemptive>

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

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

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

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

        </Aggregate>

    </Aggregate>

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

    <Aggregate Id="NeedComms">

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

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

    </Aggregate>

    <Aggregate Id="WaypointOne">

<!-- Go to Wpt1 -->

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

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

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

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

    </Aggregate>

</Mission>


2012-06-20T16:35:16.956Z,1340210116.956 [CommandLine](IMPORTANT): Running ./Missions/Transport/transit_3km.xml
2012-06-20T16:35:17.097Z,1340210117.097 [Default] Stopped
2012-06-20T16:35:17.097Z,1340210117.097 [Default](INFO): Aggregate::uninitialize Default
2012-06-20T16:35:17.097Z,1340210117.097 [Default:Iridium] Stopped
2012-06-20T16:35:17.097Z,1340210117.097 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-06-20T16:35:17.097Z,1340210117.097 [Default:Iridium:A.SetSpeed] Stopped
2012-06-20T16:35:17.097Z,1340210117.097 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T16:35:17.097Z,1340210117.097 [Default:Iridium:Read_Iridium] Stopped
2012-06-20T16:35:17.097Z,1340210117.097 [Default:CallIridium] Stopped
2012-06-20T16:35:17.097Z,1340210117.098 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-06-20T16:35:17.097Z,1340210117.098 [Default:CallIridium:B] Stopped
2012-06-20T16:35:17.098Z,1340210117.098 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-06-20T16:35:17.098Z,1340210117.098 [Default:D.SetSpeed] Stopped
2012-06-20T16:35:17.098Z,1340210117.098 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-06-20T16:35:17.098Z,1340210117.098 [Default:E.GoToSurface] Stopped
2012-06-20T16:35:17.098Z,1340210117.098 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T16:35:17.098Z,1340210117.098 [Default:F.Wait] Stopped
2012-06-20T16:35:17.098Z,1340210117.098 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2012-06-20T16:35:17.098Z,1340210117.098 [MissionManager](IMPORTANT): Started mission transit_3km
2012-06-20T16:35:17.099Z,1340210117.099 [transit_3km] Running Loop=1
2012-06-20T16:35:17.099Z,1340210117.099 [transit_3km](INFO): Aggregate::initialize transit_3km
2012-06-20T16:35:17.099Z,1340210117.099 [transit_3km:A.AltitudeEnvelope] Running Loop=1
2012-06-20T16:35:17.099Z,1340210117.099 [transit_3km:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-06-20T16:35:17.099Z,1340210117.099 [transit_3km:B.DepthEnvelope] Running Loop=1
2012-06-20T16:35:17.099Z,1340210117.099 [transit_3km:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-06-20T16:35:17.100Z,1340210117.100 [transit_3km:C.OffshoreEnvelope] Running Loop=1
2012-06-20T16:35:17.100Z,1340210117.100 [transit_3km:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2012-06-20T16:35:17.101Z,1340210117.101 [transit_3km:SURFACECOMMS] Running Loop=1
2012-06-20T16:35:17.101Z,1340210117.101 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2012-06-20T16:35:17.101Z,1340210117.101 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-06-20T16:35:17.101Z,1340210117.101 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T16:35:17.106Z,1340210117.106 [transit_3km:SURFACECOMMS:B] Running Loop=1
2012-06-20T16:35:17.106Z,1340210117.106 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:B
2012-06-20T16:35:17.106Z,1340210117.106 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-06-20T16:35:17.106Z,1340210117.106 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-06-20T16:35:17.107Z,1340210117.107 [transit_3km:SURFACECOMMS:B:B] Running Loop=1
2012-06-20T16:35:17.107Z,1340210117.107 [transit_3km:C.OffshoreEnvelope] Running Loop=1
2012-06-20T16:35:17.120Z,1340210117.120 [transit_3km:B.DepthEnvelope] Running Loop=1
2012-06-20T16:35:17.124Z,1340210117.124 [transit_3km:A.AltitudeEnvelope] Running Loop=1
2012-06-20T16:35:17.499Z,1340210117.499 [transit_3km:SURFACECOMMS:B:B](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-06-20T16:35:17.500Z,1340210117.500 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-06-20T16:35:18.710Z,1340210118.710 [NAL9601](IMPORTANT): GPS fix at: 1340210115.00
2012-06-20T16:35:18.724Z,1340210118.724 [transit_3km:SURFACECOMMS:B:B] Stopped
2012-06-20T16:35:18.725Z,1340210118.724 [transit_3km:SURFACECOMMS:B:C] Running Loop=1
2012-06-20T16:35:19.103Z,1340210119.103 [transit_3km:SURFACECOMMS:B:C](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-06-20T16:35:37.988Z,1340210137.988 [Radio_Freewave](INFO): Powering down
2012-06-20T16:35:47.554Z,1340210147.554 [NAL9601](INFO): SBD MO Status=2, MOMSN=9938, MT Status=2, MTMSN=0
2012-06-20T16:35:47.558Z,1340210147.558 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-06-20T16:36:16.589Z,1340210176.589 [Radio_Freewave](INFO): Powering up
2012-06-20T16:36:29.065Z,1340210189.065 [Radio_Freewave](INFO): Powering down
2012-06-20T16:36:34.225Z,1340210194.225 [NAL9601](INFO): SBD MO Status=2, MOMSN=9938, MT Status=2, MTMSN=0
2012-06-20T16:36:34.226Z,1340210194.226 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-06-20T16:36:56.667Z,1340210216.667 [Radio_Freewave](INFO): Powering up
2012-06-20T16:37:06.957Z,1340210226.957 [Radio_Freewave](INFO): Powering down
2012-06-20T16:37:18.954Z,1340210238.954 [NAL9601](INFO): SBD MO Status=2, MOMSN=9938, MT Status=2, MTMSN=0
2012-06-20T16:37:18.954Z,1340210238.954 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-06-20T16:37:30.910Z,1340210250.910 [Radio_Freewave](INFO): Powering up
2012-06-20T16:37:39.765Z,1340210259.765 [Radio_Freewave](INFO): Powering down
2012-06-20T16:38:05.250Z,1340210285.250 [Radio_Freewave](INFO): Powering up
2012-06-20T16:38:19.157Z,1340210299.157 [NAL9601](INFO): SBD MO Status=1, MOMSN=9938, MT Status=0, MTMSN=0
2012-06-20T16:38:19.331Z,1340210299.331 [NAL9601](INFO): Sent 332 bytes from file Logs/20120620T160349/shore0006.lzma
2012-06-20T16:38:19.331Z,1340210299.331 [NAL9601](INFO): Packets left to send: 1
2012-06-20T16:38:19.333Z,1340210299.332 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0006.lzma.parts/0001.sbd
2012-06-20T16:38:22.202Z,1340210302.202 [Radio_Freewave](INFO): Powering down
2012-06-20T16:38:29.761Z,1340210309.761 [NAL9601](INFO): SBD MO Status=2, MOMSN=9939, MT Status=2, MTMSN=0
2012-06-20T16:38:29.761Z,1340210309.761 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-06-20T16:38:48.883Z,1340210328.883 [Radio_Freewave](INFO): Powering up
2012-06-20T16:38:58.430Z,1340210338.430 [Radio_Freewave](INFO): Powering down
2012-06-20T16:39:03.225Z,1340210343.225 [NAL9601](INFO): SBD MO Status=2, MOMSN=9939, MT Status=2, MTMSN=0
2012-06-20T16:39:03.225Z,1340210343.225 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-06-20T16:39:58.217Z,1340210398.217 [Radio_Freewave](INFO): Powering up
2012-06-20T16:40:14.656Z,1340210414.656 [Radio_Freewave](INFO): Powering down
2012-06-20T16:40:23.911Z,1340210423.911 [NAL9601](INFO): SBD MO Status=2, MOMSN=9939, MT Status=2, MTMSN=0
2012-06-20T16:40:23.911Z,1340210423.911 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-06-20T16:40:55.376Z,1340210455.376 [Radio_Freewave](INFO): Powering up
2012-06-20T16:41:07.023Z,1340210467.023 [NAL9601](INFO): SBD MO Status=1, MOMSN=9939, MT Status=0, MTMSN=0
2012-06-20T16:41:07.171Z,1340210467.171 [NAL9601](INFO): Sent 100 bytes from file Logs/20120620T160349/shore0006.lzma
2012-06-20T16:41:07.171Z,1340210467.171 [NAL9601](INFO): Packets left to send: 0
2012-06-20T16:41:07.172Z,1340210467.172 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0006.lzma.parts/0000.sbd
2012-06-20T16:41:11.057Z,1340210471.057 [NAL9601](INFO): SBD MO Status=0, MOMSN=9940, MT Status=0, MTMSN=0
2012-06-20T16:41:29.800Z,1340210489.800 [NAL9601](INFO): SBD MO Status=1, MOMSN=9941, MT Status=0, MTMSN=0
2012-06-20T16:41:29.935Z,1340210489.935 [NAL9601](INFO): Sent 332 bytes from file Logs/20120620T160349/shore0007.lzma
2012-06-20T16:41:29.935Z,1340210489.935 [NAL9601](INFO): Packets left to send: 1
2012-06-20T16:41:29.936Z,1340210489.936 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0007.lzma.parts/0001.sbd
2012-06-20T16:41:38.326Z,1340210498.326 [NAL9601](INFO): SBD MO Status=1, MOMSN=9942, MT Status=0, MTMSN=0
2012-06-20T16:41:38.523Z,1340210498.523 [NAL9601](INFO): Sent 300 bytes from file Logs/20120620T160349/shore0007.lzma
2012-06-20T16:41:38.523Z,1340210498.523 [NAL9601](INFO): Packets left to send: 0
2012-06-20T16:41:38.524Z,1340210498.524 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0007.lzma.parts/0000.sbd
2012-06-20T16:41:45.914Z,1340210505.914 [NAL9601](INFO): SBD MO Status=0, MOMSN=9943, MT Status=0, MTMSN=0
2012-06-20T16:41:46.139Z,1340210506.139 [transit_3km:SURFACECOMMS:B:C] Stopped
2012-06-20T16:41:46.139Z,1340210506.139 [transit_3km:SURFACECOMMS:B:D] Running Loop=1
2012-06-20T16:41:46.367Z,1340210506.367 [transit_3km:SURFACECOMMS:B:D](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-06-20T16:41:48.314Z,1340210508.314 [NAL9601](IMPORTANT): GPS fix at: 1340210505.00
2012-06-20T16:41:48.329Z,1340210508.329 [transit_3km:SURFACECOMMS:B:D] Stopped
2012-06-20T16:41:48.330Z,1340210508.330 [transit_3km:SURFACECOMMS:B](INFO): Completed transit_3km:SURFACECOMMS:B
2012-06-20T16:41:48.330Z,1340210508.330 [transit_3km:SURFACECOMMS:B] Stopped
2012-06-20T16:41:48.330Z,1340210508.330 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:B
2012-06-20T16:41:48.330Z,1340210508.330 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-06-20T16:41:48.330Z,1340210508.330 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T16:41:48.331Z,1340210508.331 [transit_3km:SURFACECOMMS](INFO): Completed transit_3km:SURFACECOMMS
2012-06-20T16:41:48.331Z,1340210508.331 [transit_3km:SURFACECOMMS] Stopped
2012-06-20T16:41:48.331Z,1340210508.331 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2012-06-20T16:41:48.331Z,1340210508.331 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2012-06-20T16:41:48.331Z,1340210508.331 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T16:41:48.331Z,1340210508.332 [transit_3km:WaypointOne] Running Loop=1
2012-06-20T16:41:48.332Z,1340210508.332 [transit_3km:WaypointOne](INFO): Aggregate::initialize transit_3km:WaypointOne
2012-06-20T16:41:48.332Z,1340210508.332 [transit_3km:WaypointOne:A.Pitch] Running Loop=1
2012-06-20T16:41:48.332Z,1340210508.332 [transit_3km:WaypointOne:A.Pitch](DEBUG): Initialize.
2012-06-20T16:41:48.332Z,1340210508.332 [transit_3km:WaypointOne:B.SetSpeed] Running Loop=1
2012-06-20T16:41:48.332Z,1340210508.332 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Initialize.
2012-06-20T16:41:48.332Z,1340210508.332 [transit_3km:WaypointOne:WaypointW1.Waypoint] Running Loop=1
2012-06-20T16:41:48.332Z,1340210508.332 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Initialize WaypointComponent.
2012-06-20T16:41:48.747Z,1340210508.747 [transit_3km:WaypointOne:B.SetSpeed] Running Loop=1
2012-06-20T16:41:48.751Z,1340210508.751 [transit_3km:WaypointOne:A.Pitch] Running Loop=1
2012-06-20T16:41:54.711Z,1340210514.711 [NAL9601](INFO): Powering down
2012-06-20T16:42:05.163Z,1340210525.163 [Radio_Freewave](INFO): Powering down
2012-06-20T16:42:24.041Z,1340210544.041 [Radio_Freewave](INFO): Powering up
2012-06-20T16:42:37.282Z,1340210557.282 [Radio_Freewave](INFO): Powering down
2012-06-20T16:42:52.589Z,1340210572.589 [Radio_Freewave](INFO): Powering up
2012-06-20T16:42:56.288Z,1340210576.288 [Radio_Freewave](INFO): Powering down
2012-06-20T17:12:52.827Z,1340212372.827 [transit_3km:WaypointOne:WaypointW1.Waypoint](INFO): Reached Waypoint: 36.806966,-121.824326
2012-06-20T17:12:52.827Z,1340212372.828 [transit_3km:WaypointOne:WaypointW1.Waypoint] Stopped
2012-06-20T17:12:52.828Z,1340212372.828 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Uninitialize WaypointComponent.
2012-06-20T17:12:52.828Z,1340212372.828 [transit_3km:WaypointOne:PHONEHOMEWPT1] Running Loop=1
2012-06-20T17:12:52.828Z,1340212372.828 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Aggregate::initialize transit_3km:WaypointOne:PHONEHOMEWPT1
2012-06-20T17:12:53.158Z,1340212373.158 [transit_3km:SURFACECOMMS] Running Loop=1
2012-06-20T17:12:53.158Z,1340212373.158 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2012-06-20T17:12:53.158Z,1340212373.158 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-06-20T17:12:53.158Z,1340212373.158 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T17:15:33.669Z,1340212533.669 [Radio_Freewave](INFO): Powering up
2012-06-20T17:15:33.692Z,1340212533.692 [transit_3km:SURFACECOMMS:B] Running Loop=1
2012-06-20T17:15:33.692Z,1340212533.692 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:B
2012-06-20T17:15:33.692Z,1340212533.693 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-06-20T17:15:33.693Z,1340212533.693 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-06-20T17:15:33.693Z,1340212533.693 [transit_3km:SURFACECOMMS:B:B] Running Loop=1
2012-06-20T17:15:34.459Z,1340212534.459 [NAL9601](INFO): Powering up
2012-06-20T17:16:40.083Z,1340212600.083 [NAL9601](INFO): NAL9601 initialized
2012-06-20T17:16:41.176Z,1340212601.176 [NAL9601](IMPORTANT): GPS fix at: 1340212601.00
2012-06-20T17:16:41.191Z,1340212601.191 [Navigation](IMPORTANT): Error 4.0 %DT at bearing 90.8 deg., over the last 1672.1 m.
2012-06-20T17:16:41.192Z,1340212601.192 [transit_3km:SURFACECOMMS:B:B] Stopped
2012-06-20T17:16:41.192Z,1340212601.192 [transit_3km:SURFACECOMMS:B:C] Running Loop=1
2012-06-20T17:17:05.495Z,1340212625.496 [NAL9601](INFO): SBD MO Status=1, MOMSN=9944, MT Status=0, MTMSN=0
2012-06-20T17:17:05.635Z,1340212625.635 [NAL9601](INFO): Sent 332 bytes from file Logs/20120620T160349/shore0008.lzma
2012-06-20T17:17:05.635Z,1340212625.635 [NAL9601](INFO): Packets left to send: 6
2012-06-20T17:17:05.637Z,1340212625.637 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0008.lzma.parts/0006.sbd
2012-06-20T17:17:25.250Z,1340212645.250 [NAL9601](INFO): SBD MO Status=1, MOMSN=9945, MT Status=0, MTMSN=0
2012-06-20T17:17:25.407Z,1340212645.407 [NAL9601](INFO): Sent 332 bytes from file Logs/20120620T160349/shore0008.lzma
2012-06-20T17:17:25.407Z,1340212645.407 [NAL9601](INFO): Packets left to send: 5
2012-06-20T17:17:25.408Z,1340212645.408 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0008.lzma.parts/0005.sbd
2012-06-20T17:17:34.882Z,1340212654.882 [NAL9601](INFO): SBD MO Status=2, MOMSN=9946, MT Status=2, MTMSN=0
2012-06-20T17:17:34.882Z,1340212654.882 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-06-20T17:17:54.874Z,1340212674.875 [NAL9601](INFO): SBD MO Status=1, MOMSN=9946, MT Status=0, MTMSN=0
2012-06-20T17:17:55.061Z,1340212675.061 [NAL9601](INFO): Sent 332 bytes from file Logs/20120620T160349/shore0008.lzma
2012-06-20T17:17:55.061Z,1340212675.061 [NAL9601](INFO): Packets left to send: 4
2012-06-20T17:17:55.062Z,1340212675.062 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0008.lzma.parts/0004.sbd
2012-06-20T17:18:08.618Z,1340212688.618 [NAL9601](INFO): SBD MO Status=1, MOMSN=9947, MT Status=0, MTMSN=0
2012-06-20T17:18:08.835Z,1340212688.835 [NAL9601](INFO): Sent 332 bytes from file Logs/20120620T160349/shore0008.lzma
2012-06-20T17:18:08.835Z,1340212688.835 [NAL9601](INFO): Packets left to send: 3
2012-06-20T17:18:08.836Z,1340212688.836 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0008.lzma.parts/0003.sbd
2012-06-20T17:18:19.952Z,1340212699.952 [NAL9601](INFO): SBD MO Status=1, MOMSN=9948, MT Status=0, MTMSN=0
2012-06-20T17:18:20.119Z,1340212700.119 [NAL9601](INFO): Sent 332 bytes from file Logs/20120620T160349/shore0008.lzma
2012-06-20T17:18:20.119Z,1340212700.119 [NAL9601](INFO): Packets left to send: 2
2012-06-20T17:18:20.120Z,1340212700.120 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0008.lzma.parts/0002.sbd
2012-06-20T17:18:33.359Z,1340212713.359 [NAL9601](INFO): SBD MO Status=1, MOMSN=9949, MT Status=0, MTMSN=0
2012-06-20T17:18:33.499Z,1340212713.499 [NAL9601](INFO): Sent 332 bytes from file Logs/20120620T160349/shore0008.lzma
2012-06-20T17:18:33.499Z,1340212713.499 [NAL9601](INFO): Packets left to send: 1
2012-06-20T17:18:33.500Z,1340212713.500 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0008.lzma.parts/0001.sbd
2012-06-20T17:18:44.649Z,1340212724.649 [NAL9601](INFO): SBD MO Status=1, MOMSN=9950, MT Status=0, MTMSN=0
2012-06-20T17:18:44.779Z,1340212724.779 [NAL9601](INFO): Sent 112 bytes from file Logs/20120620T160349/shore0008.lzma
2012-06-20T17:18:44.779Z,1340212724.779 [NAL9601](INFO): Packets left to send: 0
2012-06-20T17:18:44.780Z,1340212724.780 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0008.lzma.parts/0000.sbd
2012-06-20T17:18:50.304Z,1340212730.304 [NAL9601](INFO): SBD MO Status=0, MOMSN=9951, MT Status=0, MTMSN=0
2012-06-20T17:18:50.485Z,1340212730.485 [transit_3km:SURFACECOMMS:B:C] Stopped
2012-06-20T17:18:50.485Z,1340212730.485 [transit_3km:SURFACECOMMS:B:D] Running Loop=1
2012-06-20T17:18:52.659Z,1340212732.659 [NAL9601](IMPORTANT): GPS fix at: 1340212740.00
2012-06-20T17:18:52.673Z,1340212732.673 [transit_3km:SURFACECOMMS:B:D] Stopped
2012-06-20T17:18:52.674Z,1340212732.674 [transit_3km:SURFACECOMMS:B](INFO): Completed transit_3km:SURFACECOMMS:B
2012-06-20T17:18:52.674Z,1340212732.674 [transit_3km:SURFACECOMMS:B] Stopped
2012-06-20T17:18:52.674Z,1340212732.674 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:B
2012-06-20T17:18:52.674Z,1340212732.674 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-06-20T17:18:52.674Z,1340212732.674 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T17:18:52.675Z,1340212732.675 [transit_3km:SURFACECOMMS](INFO): Completed transit_3km:SURFACECOMMS
2012-06-20T17:18:52.675Z,1340212732.675 [transit_3km:SURFACECOMMS] Stopped
2012-06-20T17:18:52.675Z,1340212732.675 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2012-06-20T17:18:52.675Z,1340212732.675 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2012-06-20T17:18:52.675Z,1340212732.675 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T17:18:53.082Z,1340212733.082 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Completed transit_3km:WaypointOne:PHONEHOMEWPT1
2012-06-20T17:18:53.082Z,1340212733.082 [transit_3km:WaypointOne:PHONEHOMEWPT1] Stopped
2012-06-20T17:18:53.082Z,1340212733.082 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Aggregate::uninitialize transit_3km:WaypointOne:PHONEHOMEWPT1
2012-06-20T17:18:53.083Z,1340212733.083 [transit_3km:WaypointOne](INFO): Completed transit_3km:WaypointOne
2012-06-20T17:18:53.083Z,1340212733.083 [transit_3km:WaypointOne] Stopped
2012-06-20T17:18:53.083Z,1340212733.083 [transit_3km:WaypointOne](INFO): Aggregate::uninitialize transit_3km:WaypointOne
2012-06-20T17:18:53.083Z,1340212733.083 [transit_3km:WaypointOne:A.Pitch] Stopped
2012-06-20T17:18:53.083Z,1340212733.083 [transit_3km:WaypointOne:B.SetSpeed] Stopped
2012-06-20T17:18:53.083Z,1340212733.083 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Uninitialize.
2012-06-20T17:18:53.085Z,1340212733.085 [transit_3km](INFO): Completed transit_3km
2012-06-20T17:18:53.085Z,1340212733.085 [transit_3km] Stopped
2012-06-20T17:18:53.085Z,1340212733.085 [transit_3km](INFO): Aggregate::uninitialize transit_3km
2012-06-20T17:18:53.085Z,1340212733.085 [transit_3km:A.AltitudeEnvelope] Stopped
2012-06-20T17:18:53.085Z,1340212733.085 [transit_3km:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-06-20T17:18:53.085Z,1340212733.085 [transit_3km:B.DepthEnvelope] Stopped
2012-06-20T17:18:53.085Z,1340212733.085 [transit_3km:B.DepthEnvelope](DEBUG): Uninitialize.
2012-06-20T17:18:53.085Z,1340212733.085 [transit_3km:C.OffshoreEnvelope] Stopped
2012-06-20T17:18:53.085Z,1340212733.085 [transit_3km:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2012-06-20T17:18:53.484Z,1340212733.484 [MissionManager](IMPORTANT): Started mission Default
2012-06-20T17:18:53.484Z,1340212733.484 [Default] Running Loop=1
2012-06-20T17:18:53.484Z,1340212733.484 [Default](INFO): Aggregate::initialize Default
2012-06-20T17:18:53.485Z,1340212733.485 [Default:D.SetSpeed] Running Loop=1
2012-06-20T17:18:53.485Z,1340212733.485 [Default:D.SetSpeed](DEBUG): Initialize.
2012-06-20T17:18:53.485Z,1340212733.485 [Default:E.GoToSurface] Running Loop=1
2012-06-20T17:18:53.485Z,1340212733.485 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T17:18:53.485Z,1340212733.485 [Default:Iridium] Running Loop=1
2012-06-20T17:18:53.485Z,1340212733.485 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-06-20T17:18:53.485Z,1340212733.485 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-06-20T17:18:53.485Z,1340212733.485 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-06-20T17:18:53.486Z,1340212733.486 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-06-20T17:18:53.486Z,1340212733.486 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T17:18:53.488Z,1340212733.488 [Default:Iridium:B.GoToSurface] Stopped
2012-06-20T17:18:53.488Z,1340212733.488 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T17:18:53.488Z,1340212733.488 [Default:Iridium:Read_Iridium] Running Loop=1
2012-06-20T17:19:10.961Z,1340212750.961 [NAL9601](INFO): SBD MO Status=1, MOMSN=9952, MT Status=0, MTMSN=0
2012-06-20T17:19:11.143Z,1340212751.143 [NAL9601](INFO): Sent 179 bytes from file Logs/20120620T160349/shore0009.lzma
2012-06-20T17:19:11.143Z,1340212751.143 [NAL9601](INFO): Packets left to send: 0
2012-06-20T17:19:11.144Z,1340212751.144 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0009.lzma.parts/0000.sbd
2012-06-20T17:19:15.357Z,1340212755.357 [NAL9601](INFO): SBD MO Status=0, MOMSN=9953, MT Status=0, MTMSN=0
2012-06-20T17:19:15.545Z,1340212755.545 [Default:Iridium:Read_Iridium] Stopped
2012-06-20T17:19:15.546Z,1340212755.546 [Default:Iridium](INFO): Completed Default:Iridium
2012-06-20T17:19:15.546Z,1340212755.546 [Default:Iridium] Stopped
2012-06-20T17:19:15.546Z,1340212755.546 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-06-20T17:19:15.546Z,1340212755.546 [Default:Iridium:A.SetSpeed] Stopped
2012-06-20T17:19:15.546Z,1340212755.546 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T17:19:15.546Z,1340212755.546 [Default:F.Wait] Running Loop=1
2012-06-20T17:19:15.547Z,1340212755.546 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-06-20T17:19:25.891Z,1340212765.891 [NAL9601](INFO): Powering down
2012-06-20T17:24:15.955Z,1340213055.955 [Default:CallIridium] Running Loop=1
2012-06-20T17:24:15.955Z,1340213055.955 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-06-20T17:24:15.955Z,1340213055.955 [Default:CallIridium:A] Running Loop=1
2012-06-20T17:24:15.956Z,1340213055.956 [Default:CallIridium:A] Stopped
2012-06-20T17:24:15.956Z,1340213055.956 [Default:CallIridium:B] Running Loop=1
2012-06-20T17:24:15.956Z,1340213055.956 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-06-20T17:24:21.178Z,1340213061.178 [Default:Iridium] Running Loop=1
2012-06-20T17:24:21.178Z,1340213061.178 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-06-20T17:24:21.178Z,1340213061.178 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-06-20T17:24:21.178Z,1340213061.178 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-06-20T17:24:21.178Z,1340213061.178 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-06-20T17:24:21.178Z,1340213061.178 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T17:24:21.179Z,1340213061.179 [Default:Iridium:B.GoToSurface] Stopped
2012-06-20T17:24:21.179Z,1340213061.179 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T17:24:21.179Z,1340213061.179 [Default:Iridium:Read_Iridium] Running Loop=1
2012-06-20T17:24:21.180Z,1340213061.180 [Default:GPS] Running Loop=1
2012-06-20T17:24:21.180Z,1340213061.180 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-06-20T17:24:21.180Z,1340213061.180 [Default:GPS:A.SetSpeed] Running Loop=1
2012-06-20T17:24:21.180Z,1340213061.180 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-06-20T17:24:21.180Z,1340213061.180 [Default:GPS:B.GoToSurface] Running Loop=1
2012-06-20T17:24:21.180Z,1340213061.180 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T17:24:21.181Z,1340213061.181 [Default:GPS:B.GoToSurface] Stopped
2012-06-20T17:24:21.181Z,1340213061.181 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T17:24:21.181Z,1340213061.181 [Default:GPS:Read_GPS] Running Loop=1
2012-06-20T17:24:21.767Z,1340213061.767 [NAL9601](INFO): Powering up
2012-06-20T17:25:27.491Z,1340213127.491 [NAL9601](INFO): NAL9601 initialized
2012-06-20T17:25:44.078Z,1340213144.078 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=9954, MT Status=1, MTMSN=2742
2012-06-20T17:25:44.255Z,1340213144.255 [NAL9601](INFO): Sent 102 bytes from file Logs/20120620T160349/shore0010.lzma
2012-06-20T17:25:44.255Z,1340213144.255 [NAL9601](INFO): Packets left to send: 0
2012-06-20T17:25:44.257Z,1340213144.257 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0010.lzma.parts/0000.sbd
2012-06-20T17:25:44.683Z,1340213144.683 [NAL9601](INFO): Received command:run Maintenance/ballast_and_trim.xml
2012-06-20T17:25:44.703Z,1340213144.703 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/ballast_and_trim.xml
2012-06-20T17:25:44.703Z,1340213144.703 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/ballast_and_trim.xml
2012-06-20T17:25:44.787Z,1340213144.787 [MissionManager](INFO): DefineArg ballast_and_trim.BallastDepth = 25.000000 m
2012-06-20T17:25:44.790Z,1340213144.790 [MissionManager](INFO): DefineArg ballast_and_trim.HoldDuration = 25.000000 min
2012-06-20T17:25:44.797Z,1340213144.797 [MissionManager](INFO): DefineArg ballast_and_trim.Speed = 1.000000 m/s
2012-06-20T17:25:44.804Z,1340213144.804 [MissionManager](INFO): DefineArg ballast_and_trim.DepthDeadband = 4.000000 m
2012-06-20T17:25:44.811Z,1340213144.811 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyPeriod = 0.400000 s
2012-06-20T17:25:44.839Z,1340213144.839 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyancyDefault = 0.000945 n/a
2012-06-20T17:25:44.850Z,1340213144.850 [ballast_and_trim:D.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-06-20T17:25:44.866Z,1340213144.866 [ballast_and_trim:E.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-06-20T17:25:44.887Z,1340213144.887 [ballast_and_trim:F.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2012-06-20T17:25:44.902Z,1340213144.902 [MissionManager](INFO): Inserting Stack: Missions/Insert/Surface.xml
2012-06-20T17:25:44.944Z,1340213144.944 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfaceDepthRate = nan m/s
2012-06-20T17:25:44.955Z,1340213144.955 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfacePitch = nan arcdeg
2012-06-20T17:25:44.958Z,1340213144.958 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfaceSpeed = 0.500000 m/s
2012-06-20T17:25:44.961Z,1340213144.961 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.IridiumTimeout = 30.000000 min
2012-06-20T17:25:44.962Z,1340213144.962 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-06-20T17:25:44.992Z,1340213144.992 [ballast_and_trim:H.SetSpeed](DEBUG): Construct.
2012-06-20T17:25:44.997Z,1340213144.997 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Construct.
2012-06-20T17:25:45.005Z,1340213145.005 [ballast_and_trim:ballast:C.Pitch](DEBUG): Construct.
2012-06-20T17:25:45.019Z,1340213145.019 [ballast_and_trim:ballast:D.Wait](DEBUG): Construct Wait.
2012-06-20T17:25:45.029Z,1340213145.029 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Construct Wait.
2012-06-20T17:25:45.044Z,1340213145.044 [ballast_and_trim:ballast:Float_Up:A.SetSpeed](DEBUG): Construct.
2012-06-20T17:25:45.052Z,1340213145.052 [ballast_and_trim:ballast:Float_Up:B.Buoyancy](DEBUG): Construct Buoyancy.
2012-06-20T17:25:45.062Z,1340213145.062 [ballast_and_trim:ballast:Float_Up:C.Wait](DEBUG): Construct Wait.
2012-06-20T17:25:45.074Z,1340213145.074 [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>0.4</Value></DefineArg>

    <DefineArg Name="BuoyancyDefault"><Control:VerticalControl.buoyancyDefault/></DefineArg>

<!-- The timeout -->

    <Timeout Duration="P90M"/>

<!-- And now the mission -->

    <Assign RunIn="Parallel"><Control:VerticalControl.kpPitchMass/><Units:count/><Value>0.01</Value></Assign>

    <Assign RunIn="Parallel"><Control:VerticalControl.kiPitchMass/><Units:reciprocal_second/><Value>0.0015</Value></Assign>

    <Assign RunIn="Parallel"><Control:VerticalControl.kdPitchMass/><Units:second/><Value>0</Value></Assign>

    <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>

        <Assign RunIn="Parallel"><Control:VerticalControl.depthDeadband/><Arg Name="DepthDeadband"/></Assign>

        <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/>
            Mass:<Universal:platform_mass_position/><Units:centimeter/>
            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-06-20T17:25:45.082Z,1340213145.082 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/ballast_and_trim.xml
2012-06-20T17:25:45.169Z,1340213145.169 [Default] Stopped
2012-06-20T17:25:45.169Z,1340213145.170 [Default](INFO): Aggregate::uninitialize Default
2012-06-20T17:25:45.170Z,1340213145.170 [Default:GPS] Stopped
2012-06-20T17:25:45.170Z,1340213145.170 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-06-20T17:25:45.170Z,1340213145.170 [Default:GPS:A.SetSpeed] Stopped
2012-06-20T17:25:45.170Z,1340213145.170 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T17:25:45.170Z,1340213145.170 [Default:GPS:Read_GPS] Stopped
2012-06-20T17:25:45.170Z,1340213145.170 [Default:Iridium] Stopped
2012-06-20T17:25:45.170Z,1340213145.170 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-06-20T17:25:45.170Z,1340213145.170 [Default:Iridium:A.SetSpeed] Stopped
2012-06-20T17:25:45.170Z,1340213145.171 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T17:25:45.171Z,1340213145.171 [Default:Iridium:Read_Iridium] Stopped
2012-06-20T17:25:45.171Z,1340213145.171 [Default:CallIridium] Stopped
2012-06-20T17:25:45.171Z,1340213145.171 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-06-20T17:25:45.171Z,1340213145.171 [Default:CallIridium:B] Stopped
2012-06-20T17:25:45.171Z,1340213145.171 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-06-20T17:25:45.171Z,1340213145.171 [Default:D.SetSpeed] Stopped
2012-06-20T17:25:45.171Z,1340213145.171 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-06-20T17:25:45.171Z,1340213145.171 [Default:E.GoToSurface] Stopped
2012-06-20T17:25:45.171Z,1340213145.171 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T17:25:45.171Z,1340213145.171 [Default:F.Wait] Stopped
2012-06-20T17:25:45.171Z,1340213145.171 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2012-06-20T17:25:45.171Z,1340213145.171 [MissionManager](IMPORTANT): Started mission ballast_and_trim
2012-06-20T17:25:45.172Z,1340213145.172 [ballast_and_trim] Running Loop=1
2012-06-20T17:25:45.172Z,1340213145.172 [ballast_and_trim](INFO): Aggregate::initialize ballast_and_trim
2012-06-20T17:25:45.172Z,1340213145.172 [ballast_and_trim:A] Running Loop=1
2012-06-20T17:25:45.172Z,1340213145.172 [ballast_and_trim:B] Running Loop=1
2012-06-20T17:25:45.172Z,1340213145.172 [ballast_and_trim:C] Running Loop=1
2012-06-20T17:25:45.172Z,1340213145.172 [ballast_and_trim:D.AltitudeEnvelope] Running Loop=1
2012-06-20T17:25:45.172Z,1340213145.172 [ballast_and_trim:D.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-06-20T17:25:45.172Z,1340213145.172 [ballast_and_trim:E.DepthEnvelope] Running Loop=1
2012-06-20T17:25:45.172Z,1340213145.172 [ballast_and_trim:E.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-06-20T17:25:45.173Z,1340213145.173 [ballast_and_trim:F.OffshoreEnvelope] Running Loop=1
2012-06-20T17:25:45.173Z,1340213145.173 [ballast_and_trim:F.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2012-06-20T17:25:45.173Z,1340213145.173 [ballast_and_trim:H.SetSpeed] Running Loop=1
2012-06-20T17:25:45.173Z,1340213145.173 [ballast_and_trim:H.SetSpeed](DEBUG): Initialize.
2012-06-20T17:25:45.174Z,1340213145.174 [ballast_and_trim:SurfaceComms] Running Loop=1
2012-06-20T17:25:45.174Z,1340213145.174 [ballast_and_trim:SurfaceComms](INFO): Aggregate::initialize ballast_and_trim:SurfaceComms
2012-06-20T17:25:45.174Z,1340213145.174 [ballast_and_trim:SurfaceComms:A.GoToSurface] Running Loop=1
2012-06-20T17:25:45.174Z,1340213145.174 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T17:25:45.175Z,1340213145.175 [ballast_and_trim:H.SetSpeed] Running Loop=1
2012-06-20T17:25:45.185Z,1340213145.185 [ballast_and_trim:SurfaceComms:B] Running Loop=1
2012-06-20T17:25:45.185Z,1340213145.185 [ballast_and_trim:SurfaceComms:B](INFO): Aggregate::initialize ballast_and_trim:SurfaceComms:B
2012-06-20T17:25:45.185Z,1340213145.185 [ballast_and_trim:SurfaceComms:B:A] Running Loop=1
2012-06-20T17:25:45.185Z,1340213145.185 [ballast_and_trim:F.OffshoreEnvelope] Running Loop=1
2012-06-20T17:25:45.190Z,1340213145.190 [ballast_and_trim:E.DepthEnvelope] Running Loop=1
2012-06-20T17:25:45.195Z,1340213145.195 [ballast_and_trim:D.AltitudeEnvelope] Running Loop=1
2012-06-20T17:25:45.201Z,1340213145.201 [ballast_and_trim:C] Running Loop=1
2012-06-20T17:25:45.203Z,1340213145.203 [ballast_and_trim:B] Running Loop=1
2012-06-20T17:25:45.204Z,1340213145.204 [ballast_and_trim:A] Running Loop=1
2012-06-20T17:25:45.589Z,1340213145.589 [ballast_and_trim:H.SetSpeed] Preempted
2012-06-20T17:25:45.590Z,1340213145.590 [ballast_and_trim:SurfaceComms:B:A](DEBUG): Initialize ReadDataComponent to sense time_fix
2012-06-20T17:25:51.943Z,1340213151.943 [NAL9601](IMPORTANT): GPS fix at: 1340213153.00
2012-06-20T17:25:51.958Z,1340213151.958 [ballast_and_trim:SurfaceComms:B:A] Stopped
2012-06-20T17:25:51.958Z,1340213151.958 [ballast_and_trim:SurfaceComms:B:B] Running Loop=1
2012-06-20T17:25:52.364Z,1340213152.364 [ballast_and_trim:SurfaceComms:B:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-06-20T17:26:06.558Z,1340213166.558 [NAL9601](INFO): SBD MO Status=0, MOMSN=9955, MT Status=0, MTMSN=0
2012-06-20T17:26:21.449Z,1340213181.449 [NAL9601](INFO): SBD MO Status=1, MOMSN=9956, MT Status=0, MTMSN=0
2012-06-20T17:26:21.595Z,1340213181.595 [NAL9601](INFO): Sent 332 bytes from file Logs/20120620T160349/shore0011.lzma
2012-06-20T17:26:21.595Z,1340213181.595 [NAL9601](INFO): Packets left to send: 1
2012-06-20T17:26:21.596Z,1340213181.596 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0011.lzma.parts/0001.sbd
2012-06-20T17:26:34.289Z,1340213194.289 [NAL9601](INFO): SBD MO Status=1, MOMSN=9957, MT Status=0, MTMSN=0
2012-06-20T17:26:34.475Z,1340213194.475 [NAL9601](INFO): Sent 16 bytes from file Logs/20120620T160349/shore0011.lzma
2012-06-20T17:26:34.475Z,1340213194.475 [NAL9601](INFO): Packets left to send: 0
2012-06-20T17:26:34.476Z,1340213194.476 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0011.lzma.parts/0000.sbd
2012-06-20T17:26:45.069Z,1340213205.069 [NAL9601](INFO): SBD MO Status=2, MOMSN=9958, MT Status=2, MTMSN=0
2012-06-20T17:26:45.069Z,1340213205.069 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-06-20T17:26:56.503Z,1340213216.503 [NAL9601](INFO): SBD MO Status=0, MOMSN=9958, MT Status=0, MTMSN=0
2012-06-20T17:26:56.657Z,1340213216.657 [ballast_and_trim:SurfaceComms:B:B] Stopped
2012-06-20T17:26:56.657Z,1340213216.657 [ballast_and_trim:SurfaceComms:B:C] Running Loop=1
2012-06-20T17:26:56.894Z,1340213216.894 [ballast_and_trim:SurfaceComms:B:C](DEBUG): Initialize ReadDataComponent to sense time_fix
2012-06-20T17:26:58.896Z,1340213218.896 [NAL9601](IMPORTANT): GPS fix at: 1340213220.00
2012-06-20T17:26:58.911Z,1340213218.911 [ballast_and_trim:SurfaceComms:B:C] Stopped
2012-06-20T17:26:58.911Z,1340213218.911 [ballast_and_trim:SurfaceComms:B](INFO): Completed ballast_and_trim:SurfaceComms:B
2012-06-20T17:26:58.911Z,1340213218.911 [ballast_and_trim:SurfaceComms:B] Stopped
2012-06-20T17:26:58.911Z,1340213218.911 [ballast_and_trim:SurfaceComms:B](INFO): Aggregate::uninitialize ballast_and_trim:SurfaceComms:B
2012-06-20T17:26:58.912Z,1340213218.912 [ballast_and_trim:SurfaceComms](INFO): Completed ballast_and_trim:SurfaceComms
2012-06-20T17:26:58.912Z,1340213218.912 [ballast_and_trim:SurfaceComms] Stopped
2012-06-20T17:26:58.913Z,1340213218.912 [ballast_and_trim:SurfaceComms](INFO): Aggregate::uninitialize ballast_and_trim:SurfaceComms
2012-06-20T17:26:58.913Z,1340213218.912 [ballast_and_trim:SurfaceComms:A.GoToSurface] Stopped
2012-06-20T17:26:58.913Z,1340213218.913 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T17:26:58.913Z,1340213218.913 [ballast_and_trim:ballast] Running Loop=1
2012-06-20T17:26:58.913Z,1340213218.913 [ballast_and_trim:ballast](INFO): Aggregate::initialize ballast_and_trim:ballast
2012-06-20T17:26:58.913Z,1340213218.913 [ballast_and_trim:ballast:A.SetSpeed] Running Loop=1
2012-06-20T17:26:58.913Z,1340213218.913 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Initialize.
2012-06-20T17:26:58.913Z,1340213218.913 [ballast_and_trim:ballast:B] Running Loop=1
2012-06-20T17:26:58.913Z,1340213218.913 [ballast_and_trim:ballast:C.Pitch] Running Loop=1
2012-06-20T17:26:58.913Z,1340213218.913 [ballast_and_trim:ballast:C.Pitch](DEBUG): Initialize.
2012-06-20T17:26:58.914Z,1340213218.914 [ballast_and_trim:ballast:D.Wait] Running Loop=1
2012-06-20T17:26:58.914Z,1340213218.914 [ballast_and_trim:ballast:D.Wait](DEBUG): Initialize Wait Component.
2012-06-20T17:26:59.303Z,1340213219.303 [ballast_and_trim:ballast:C.Pitch] Running Loop=1
2012-06-20T17:26:59.307Z,1340213219.307 [ballast_and_trim:ballast:B] Running Loop=1
2012-06-20T17:26:59.309Z,1340213219.309 [ballast_and_trim:ballast:A.SetSpeed] Running Loop=1
2012-06-20T17:26:59.313Z,1340213219.313 [ballast_and_trim:H.SetSpeed] Running Loop=1
2012-06-20T17:27:05.213Z,1340213225.213 [NAL9601](INFO): Powering down
2012-06-20T17:31:36.241Z,1340213496.240 [Radio_Freewave](INFO): Powering down
2012-06-20T17:51:59.656Z,1340214719.656 [ballast_and_trim:ballast:D.Wait](INFO): Done Waiting.
2012-06-20T17:51:59.656Z,1340214719.656 [ballast_and_trim:ballast:D.Wait] Stopped
2012-06-20T17:51:59.656Z,1340214719.656 [ballast_and_trim:ballast:D.Wait](DEBUG): Uninitialize Wait Component.
2012-06-20T17:51:59.656Z,1340214719.656 [ballast_and_trim:ballast:ReportPositions] Running Loop=1
2012-06-20T17:51:59.656Z,1340214719.656 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-06-20T17:51:59.656Z,1340214719.657 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-06-20T17:51:59.963Z,1340214719.963 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 492.468069 cc Mass: -0.732881 cm Pitch: -0.398633 arcdeg 
2012-06-20T17:51:59.964Z,1340214719.964 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-06-20T17:51:59.964Z,1340214719.964 [ballast_and_trim:ballast:ReportPositions:B.Wait] Running Loop=1
2012-06-20T17:51:59.964Z,1340214719.964 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Initialize Wait Component.
2012-06-20T17:53:00.375Z,1340214780.375 [ballast_and_trim:ballast:ReportPositions:B.Wait](INFO): Timed out from 2012-06-20T17:51:59.0Z
2012-06-20T17:53:00.375Z,1340214780.375 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-06-20T17:53:00.375Z,1340214780.375 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-06-20T17:53:00.376Z,1340214780.376 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-06-20T17:53:00.376Z,1340214780.376 [ballast_and_trim:ballast:ReportPositions:B.Wait] Stopped
2012-06-20T17:53:00.376Z,1340214780.376 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Uninitialize Wait Component.
2012-06-20T17:53:00.376Z,1340214780.376 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-06-20T17:53:00.376Z,1340214780.376 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-06-20T17:53:00.376Z,1340214780.376 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-06-20T17:53:00.376Z,1340214780.376 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #2
2012-06-20T17:53:00.377Z,1340214780.376 [ballast_and_trim:ballast:ReportPositions] Running Loop=2
2012-06-20T17:53:00.377Z,1340214780.377 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-06-20T17:53:00.377Z,1340214780.377 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-06-20T17:53:00.772Z,1340214780.772 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 492.468069 cc Mass: -0.732881 cm Pitch: -0.310742 arcdeg 
2012-06-20T17:53:00.772Z,1340214780.772 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-06-20T17:53:00.772Z,1340214780.772 [ballast_and_trim:ballast:ReportPositions:B.Wait] Running Loop=1
2012-06-20T17:53:00.772Z,1340214780.772 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Initialize Wait Component.
2012-06-20T17:54:01.049Z,1340214841.049 [ballast_and_trim:ballast:ReportPositions:B.Wait](INFO): Timed out from 2012-06-20T17:53:00.8Z
2012-06-20T17:54:01.049Z,1340214841.049 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-06-20T17:54:01.049Z,1340214841.049 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-06-20T17:54:01.050Z,1340214841.050 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-06-20T17:54:01.050Z,1340214841.050 [ballast_and_trim:ballast:ReportPositions:B.Wait] Stopped
2012-06-20T17:54:01.050Z,1340214841.050 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Uninitialize Wait Component.
2012-06-20T17:54:01.050Z,1340214841.050 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-06-20T17:54:01.050Z,1340214841.050 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-06-20T17:54:01.051Z,1340214841.050 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-06-20T17:54:01.051Z,1340214841.051 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #3
2012-06-20T17:54:01.051Z,1340214841.051 [ballast_and_trim:ballast:ReportPositions] Running Loop=3
2012-06-20T17:54:01.051Z,1340214841.051 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-06-20T17:54:01.051Z,1340214841.051 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-06-20T17:54:01.450Z,1340214841.450 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 477.292138 cc Mass: -0.826802 cm Pitch: 2.062305 arcdeg 
2012-06-20T17:54:01.450Z,1340214841.450 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-06-20T17:54:01.450Z,1340214841.450 [ballast_and_trim:ballast:ReportPositions:B.Wait] Running Loop=1
2012-06-20T17:54:01.450Z,1340214841.450 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Initialize Wait Component.
2012-06-20T17:55:01.720Z,1340214901.720 [ballast_and_trim:ballast:ReportPositions:B.Wait](INFO): Timed out from 2012-06-20T17:54:01.4Z
2012-06-20T17:55:01.720Z,1340214901.720 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-06-20T17:55:01.720Z,1340214901.720 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-06-20T17:55:01.720Z,1340214901.720 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-06-20T17:55:01.720Z,1340214901.720 [ballast_and_trim:ballast:ReportPositions:B.Wait] Stopped
2012-06-20T17:55:01.720Z,1340214901.720 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Uninitialize Wait Component.
2012-06-20T17:55:01.720Z,1340214901.720 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-06-20T17:55:01.720Z,1340214901.720 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-06-20T17:55:01.721Z,1340214901.721 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-06-20T17:55:01.721Z,1340214901.721 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #4
2012-06-20T17:55:01.721Z,1340214901.721 [ballast_and_trim:ballast:ReportPositions] Running Loop=4
2012-06-20T17:55:01.721Z,1340214901.721 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-06-20T17:55:01.721Z,1340214901.721 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-06-20T17:55:02.106Z,1340214902.106 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 485.887373 cc Mass: -0.732962 cm Pitch: -0.134961 arcdeg 
2012-06-20T17:55:02.106Z,1340214902.106 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-06-20T17:55:02.107Z,1340214902.107 [ballast_and_trim:ballast:ReportPositions:B.Wait] Running Loop=1
2012-06-20T17:55:02.107Z,1340214902.107 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Initialize Wait Component.
2012-06-20T17:56:02.115Z,1340214962.115 [ballast_and_trim:ballast:ReportPositions:B.Wait](INFO): Timed out from 2012-06-20T17:55:02.1Z
2012-06-20T17:56:02.115Z,1340214962.115 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-06-20T17:56:02.115Z,1340214962.115 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-06-20T17:56:02.115Z,1340214962.115 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-06-20T17:56:02.115Z,1340214962.115 [ballast_and_trim:ballast:ReportPositions:B.Wait] Stopped
2012-06-20T17:56:02.115Z,1340214962.115 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Uninitialize Wait Component.
2012-06-20T17:56:02.116Z,1340214962.116 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-06-20T17:56:02.116Z,1340214962.116 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-06-20T17:56:02.116Z,1340214962.116 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-06-20T17:56:02.116Z,1340214962.116 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #5
2012-06-20T17:56:02.116Z,1340214962.116 [ballast_and_trim:ballast:ReportPositions] Running Loop=5
2012-06-20T17:56:02.116Z,1340214962.116 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-06-20T17:56:02.116Z,1340214962.116 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-06-20T17:56:02.543Z,1340214962.543 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 485.887373 cc Mass: -0.732962 cm Pitch: -0.882031 arcdeg 
2012-06-20T17:56:02.543Z,1340214962.543 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-06-20T17:56:02.543Z,1340214962.543 [ballast_and_trim:ballast:ReportPositions:B.Wait] Running Loop=1
2012-06-20T17:56:02.543Z,1340214962.543 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Initialize Wait Component.
2012-06-20T17:57:02.840Z,1340215022.839 [ballast_and_trim:ballast:ReportPositions:B.Wait](INFO): Timed out from 2012-06-20T17:56:02.5Z
2012-06-20T17:57:02.840Z,1340215022.840 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-06-20T17:57:02.840Z,1340215022.840 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-06-20T17:57:02.840Z,1340215022.840 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-06-20T17:57:02.840Z,1340215022.840 [ballast_and_trim:ballast:ReportPositions:B.Wait] Stopped
2012-06-20T17:57:02.840Z,1340215022.840 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Uninitialize Wait Component.
2012-06-20T17:57:02.840Z,1340215022.840 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-06-20T17:57:02.840Z,1340215022.840 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-06-20T17:57:02.840Z,1340215022.841 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-06-20T17:57:02.841Z,1340215022.841 [ballast_and_trim:ballast:Float_Up] Running Loop=1
2012-06-20T17:57:02.841Z,1340215022.841 [ballast_and_trim:ballast:Float_Up](INFO): Aggregate::initialize ballast_and_trim:ballast:Float_Up
2012-06-20T17:57:02.841Z,1340215022.841 [ballast_and_trim:ballast:Float_Up:A.SetSpeed] Running Loop=1
2012-06-20T17:57:02.841Z,1340215022.841 [ballast_and_trim:ballast:Float_Up:A.SetSpeed](DEBUG): Initialize.
2012-06-20T17:57:02.841Z,1340215022.841 [ballast_and_trim:ballast:Float_Up:B.Buoyancy] Running Loop=1
2012-06-20T17:57:02.841Z,1340215022.841 [ballast_and_trim:ballast:Float_Up:B.Buoyancy](DEBUG): Initialize Buoyancy Component.
2012-06-20T17:57:02.842Z,1340215022.842 [ballast_and_trim:ballast:Float_Up:C.Wait] Running Loop=1
2012-06-20T17:57:02.842Z,1340215022.842 [ballast_and_trim:ballast:Float_Up:C.Wait](DEBUG): Initialize Wait Component.
2012-06-20T17:57:03.226Z,1340215023.226 [ballast_and_trim:ballast:Float_Up:B.Buoyancy] Running Loop=1
2012-06-20T17:57:03.231Z,1340215023.231 [ballast_and_trim:ballast:Float_Up:A.SetSpeed] Running Loop=1
2012-06-20T18:00:14.799Z,1340215214.799 [ballast_and_trim:ballast:Float_Up] Stopped
2012-06-20T18:00:14.799Z,1340215214.799 [ballast_and_trim:ballast:Float_Up](INFO): Aggregate::uninitialize ballast_and_trim:ballast:Float_Up
2012-06-20T18:00:14.799Z,1340215214.799 [ballast_and_trim:ballast:Float_Up:A.SetSpeed] Stopped
2012-06-20T18:00:14.799Z,1340215214.799 [ballast_and_trim:ballast:Float_Up:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T18:00:14.799Z,1340215214.799 [ballast_and_trim:ballast:Float_Up:B.Buoyancy] Stopped
2012-06-20T18:00:14.799Z,1340215214.799 [ballast_and_trim:ballast:Float_Up:B.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2012-06-20T18:00:14.799Z,1340215214.799 [ballast_and_trim:ballast:Float_Up:C.Wait] Stopped
2012-06-20T18:00:14.799Z,1340215214.799 [ballast_and_trim:ballast:Float_Up:C.Wait](DEBUG): Uninitialize Wait Component.
2012-06-20T18:00:14.800Z,1340215214.800 [ballast_and_trim:ballast](INFO): Completed ballast_and_trim:ballast
2012-06-20T18:00:14.800Z,1340215214.800 [ballast_and_trim:ballast] Stopped
2012-06-20T18:00:14.800Z,1340215214.800 [ballast_and_trim:ballast](INFO): Aggregate::uninitialize ballast_and_trim:ballast
2012-06-20T18:00:14.801Z,1340215214.801 [ballast_and_trim:ballast:A.SetSpeed] Stopped
2012-06-20T18:00:14.801Z,1340215214.801 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T18:00:14.801Z,1340215214.801 [ballast_and_trim:ballast:B] Stopped
2012-06-20T18:00:14.801Z,1340215214.801 [ballast_and_trim:ballast:C.Pitch] Stopped
2012-06-20T18:00:14.803Z,1340215214.803 [ballast_and_trim](INFO): Completed ballast_and_trim
2012-06-20T18:00:14.803Z,1340215214.803 [ballast_and_trim] Stopped
2012-06-20T18:00:14.804Z,1340215214.804 [ballast_and_trim](INFO): Aggregate::uninitialize ballast_and_trim
2012-06-20T18:00:14.804Z,1340215214.804 [ballast_and_trim:A] Stopped
2012-06-20T18:00:14.804Z,1340215214.804 [ballast_and_trim:B] Stopped
2012-06-20T18:00:14.804Z,1340215214.804 [ballast_and_trim:C] Stopped
2012-06-20T18:00:14.804Z,1340215214.804 [ballast_and_trim:D.AltitudeEnvelope] Stopped
2012-06-20T18:00:14.804Z,1340215214.804 [ballast_and_trim:D.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-06-20T18:00:14.804Z,1340215214.804 [ballast_and_trim:E.DepthEnvelope] Stopped
2012-06-20T18:00:14.804Z,1340215214.804 [ballast_and_trim:E.DepthEnvelope](DEBUG): Uninitialize.
2012-06-20T18:00:14.804Z,1340215214.804 [ballast_and_trim:F.OffshoreEnvelope] Stopped
2012-06-20T18:00:14.804Z,1340215214.804 [ballast_and_trim:F.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2012-06-20T18:00:14.804Z,1340215214.804 [ballast_and_trim:H.SetSpeed] Stopped
2012-06-20T18:00:14.804Z,1340215214.804 [ballast_and_trim:H.SetSpeed](DEBUG): Uninitialize.
2012-06-20T18:00:15.206Z,1340215215.207 [MissionManager](IMPORTANT): Started mission Default
2012-06-20T18:00:15.207Z,1340215215.207 [Default] Running Loop=1
2012-06-20T18:00:15.207Z,1340215215.207 [Default](INFO): Aggregate::initialize Default
2012-06-20T18:00:15.207Z,1340215215.207 [Default:D.SetSpeed] Running Loop=1
2012-06-20T18:00:15.207Z,1340215215.207 [Default:D.SetSpeed](DEBUG): Initialize.
2012-06-20T18:00:15.207Z,1340215215.207 [Default:E.GoToSurface] Running Loop=1
2012-06-20T18:00:15.207Z,1340215215.207 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T18:00:15.207Z,1340215215.207 [Default:Iridium] Running Loop=1
2012-06-20T18:00:15.207Z,1340215215.207 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-06-20T18:00:15.207Z,1340215215.207 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-06-20T18:00:15.208Z,1340215215.208 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-06-20T18:00:15.208Z,1340215215.208 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-06-20T18:00:15.208Z,1340215215.208 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T18:00:15.209Z,1340215215.209 [Default:CallIridium] Running Loop=1
2012-06-20T18:00:15.209Z,1340215215.209 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-06-20T18:00:15.209Z,1340215215.209 [Default:CallIridium:A] Running Loop=1
2012-06-20T18:00:15.210Z,1340215215.210 [Default:CallIridium:A] Stopped
2012-06-20T18:00:15.210Z,1340215215.210 [Default:CallIridium:B] Running Loop=1
2012-06-20T18:00:15.210Z,1340215215.210 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-06-20T18:00:15.211Z,1340215215.211 [Default:GPS] Running Loop=1
2012-06-20T18:00:15.211Z,1340215215.211 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-06-20T18:00:15.211Z,1340215215.211 [Default:GPS:A.SetSpeed] Running Loop=1
2012-06-20T18:00:15.211Z,1340215215.211 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-06-20T18:00:15.212Z,1340215215.212 [Default:GPS:B.GoToSurface] Running Loop=1
2012-06-20T18:00:15.212Z,1340215215.212 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T18:00:17.145Z,1340215217.145 [Radio_Freewave](INFO): Powering up
2012-06-20T18:00:17.155Z,1340215217.155 [Default:Iridium:B.GoToSurface] Stopped
2012-06-20T18:00:17.155Z,1340215217.155 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T18:00:17.155Z,1340215217.155 [Default:Iridium:Read_Iridium] Running Loop=1
2012-06-20T18:00:17.156Z,1340215217.156 [Default:GPS:B.GoToSurface] Stopped
2012-06-20T18:00:17.156Z,1340215217.156 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T18:00:17.156Z,1340215217.157 [Default:GPS:Read_GPS] Running Loop=1
2012-06-20T18:00:18.087Z,1340215218.087 [NAL9601](INFO): Powering up
2012-06-20T18:01:23.811Z,1340215283.811 [NAL9601](INFO): NAL9601 initialized
2012-06-20T18:01:24.913Z,1340215284.913 [NAL9601](IMPORTANT): GPS fix at: 1340215289.00
2012-06-20T18:01:24.929Z,1340215284.930 [Default:GPS:Read_GPS] Stopped
2012-06-20T18:01:24.930Z,1340215284.930 [Default:GPS:D] Running Loop=1
2012-06-20T18:01:25.303Z,1340215285.303 [Default:GPS:D] Stopped
2012-06-20T18:01:25.303Z,1340215285.303 [Default:GPS](INFO): Completed Default:GPS
2012-06-20T18:01:25.303Z,1340215285.303 [Default:GPS] Stopped
2012-06-20T18:01:25.303Z,1340215285.303 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-06-20T18:01:25.303Z,1340215285.303 [Default:GPS:A.SetSpeed] Stopped
2012-06-20T18:01:25.303Z,1340215285.303 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T18:01:41.244Z,1340215301.244 [NAL9601](INFO): SBD MO Status=1, MOMSN=9959, MT Status=0, MTMSN=0
2012-06-20T18:01:41.371Z,1340215301.371 [NAL9601](INFO): Sent 332 bytes from file Logs/20120620T160349/shore0012.lzma
2012-06-20T18:01:41.371Z,1340215301.371 [NAL9601](INFO): Packets left to send: 1
2012-06-20T18:01:41.373Z,1340215301.372 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0012.lzma.parts/0001.sbd
2012-06-20T18:02:20.289Z,1340215340.289 [NAL9601](INFO): SBD MO Status=2, MOMSN=9960, MT Status=2, MTMSN=0
2012-06-20T18:02:20.289Z,1340215340.289 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-06-20T18:02:34.553Z,1340215354.553 [NAL9601](INFO): SBD MO Status=1, MOMSN=9960, MT Status=0, MTMSN=0
2012-06-20T18:02:34.691Z,1340215354.691 [NAL9601](INFO): Sent 323 bytes from file Logs/20120620T160349/shore0012.lzma
2012-06-20T18:02:34.691Z,1340215354.691 [NAL9601](INFO): Packets left to send: 0
2012-06-20T18:02:34.692Z,1340215354.692 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0012.lzma.parts/0000.sbd
2012-06-20T18:02:53.376Z,1340215373.376 [NAL9601](INFO): SBD MO Status=0, MOMSN=9961, MT Status=0, MTMSN=0
2012-06-20T18:02:53.581Z,1340215373.581 [Default:Iridium:Read_Iridium] Stopped
2012-06-20T18:02:53.582Z,1340215373.582 [Default:Iridium](INFO): Completed Default:Iridium
2012-06-20T18:02:53.582Z,1340215373.582 [Default:Iridium] Stopped
2012-06-20T18:02:53.582Z,1340215373.582 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-06-20T18:02:53.582Z,1340215373.582 [Default:Iridium:A.SetSpeed] Stopped
2012-06-20T18:02:53.582Z,1340215373.582 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T18:02:53.582Z,1340215373.582 [Default:F.Wait] Running Loop=1
2012-06-20T18:02:53.582Z,1340215373.582 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-06-20T18:02:53.770Z,1340215373.770 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-06-20T18:02:53.770Z,1340215373.770 [Default:CallIridium:B] Stopped
2012-06-20T18:02:53.771Z,1340215373.770 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-06-20T18:02:53.771Z,1340215373.771 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-06-20T18:02:53.771Z,1340215373.771 [Default:CallIridium] Stopped
2012-06-20T18:02:53.771Z,1340215373.771 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-06-20T18:03:03.908Z,1340215383.908 [NAL9601](INFO): Powering down
2012-06-20T18:07:53.900Z,1340215673.900 [Default:CallIridium] Running Loop=1
2012-06-20T18:07:53.900Z,1340215673.901 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-06-20T18:07:53.901Z,1340215673.901 [Default:CallIridium:A] Running Loop=1
2012-06-20T18:07:53.901Z,1340215673.901 [Default:CallIridium:A] Stopped
2012-06-20T18:07:53.901Z,1340215673.901 [Default:CallIridium:B] Running Loop=1
2012-06-20T18:07:53.901Z,1340215673.901 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-06-20T18:07:58.950Z,1340215678.950 [Default:Iridium] Running Loop=1
2012-06-20T18:07:58.950Z,1340215678.950 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-06-20T18:07:58.950Z,1340215678.950 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-06-20T18:07:58.950Z,1340215678.950 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-06-20T18:07:58.950Z,1340215678.950 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-06-20T18:07:58.950Z,1340215678.950 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T18:07:58.951Z,1340215678.951 [Default:Iridium:B.GoToSurface] Stopped
2012-06-20T18:07:58.951Z,1340215678.951 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T18:07:58.951Z,1340215678.951 [Default:Iridium:Read_Iridium] Running Loop=1
2012-06-20T18:07:58.951Z,1340215678.951 [Default:GPS] Running Loop=1
2012-06-20T18:07:58.952Z,1340215678.952 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-06-20T18:07:58.952Z,1340215678.952 [Default:GPS:A.SetSpeed] Running Loop=1
2012-06-20T18:07:58.952Z,1340215678.952 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-06-20T18:07:58.952Z,1340215678.952 [Default:GPS:B.GoToSurface] Running Loop=1
2012-06-20T18:07:58.952Z,1340215678.952 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T18:07:58.953Z,1340215678.953 [Default:GPS:B.GoToSurface] Stopped
2012-06-20T18:07:58.953Z,1340215678.953 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T18:07:58.953Z,1340215678.953 [Default:GPS:Read_GPS] Running Loop=1
2012-06-20T18:07:59.551Z,1340215679.551 [NAL9601](INFO): Powering up
2012-06-20T18:09:05.275Z,1340215745.275 [NAL9601](INFO): NAL9601 initialized
2012-06-20T18:09:21.981Z,1340215761.981 [NAL9601](INFO): SBD MO Status=1, MOMSN=9962, MT Status=0, MTMSN=0
2012-06-20T18:09:22.143Z,1340215762.143 [NAL9601](INFO): Sent 102 bytes from file Logs/20120620T160349/shore0013.lzma
2012-06-20T18:09:22.143Z,1340215762.143 [NAL9601](INFO): Packets left to send: 0
2012-06-20T18:09:22.144Z,1340215762.144 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0013.lzma.parts/0000.sbd
2012-06-20T18:09:37.942Z,1340215777.942 [NAL9601](INFO): SBD MO Status=0, MOMSN=9963, MT Status=0, MTMSN=0
2012-06-20T18:09:38.131Z,1340215778.131 [Default:Iridium:Read_Iridium] Stopped
2012-06-20T18:09:38.131Z,1340215778.131 [Default:Iridium](INFO): Completed Default:Iridium
2012-06-20T18:09:38.131Z,1340215778.131 [Default:Iridium] Stopped
2012-06-20T18:09:38.131Z,1340215778.131 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-06-20T18:09:38.131Z,1340215778.131 [Default:Iridium:A.SetSpeed] Stopped
2012-06-20T18:09:38.131Z,1340215778.131 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T18:09:38.350Z,1340215778.350 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-06-20T18:09:38.350Z,1340215778.350 [Default:CallIridium:B] Stopped
2012-06-20T18:09:38.350Z,1340215778.350 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-06-20T18:09:38.351Z,1340215778.351 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-06-20T18:09:38.351Z,1340215778.351 [Default:CallIridium] Stopped
2012-06-20T18:09:38.351Z,1340215778.351 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-06-20T18:14:38.393Z,1340216078.393 [Default:CallIridium] Running Loop=1
2012-06-20T18:14:38.393Z,1340216078.393 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-06-20T18:14:38.393Z,1340216078.393 [Default:CallIridium:A] Running Loop=1
2012-06-20T18:14:38.394Z,1340216078.394 [Default:CallIridium:A] Stopped
2012-06-20T18:14:38.394Z,1340216078.394 [Default:CallIridium:B] Running Loop=1
2012-06-20T18:14:38.394Z,1340216078.394 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-06-20T18:14:38.755Z,1340216078.755 [Default:Iridium] Running Loop=1
2012-06-20T18:14:38.755Z,1340216078.755 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-06-20T18:14:38.755Z,1340216078.755 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-06-20T18:14:38.755Z,1340216078.755 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-06-20T18:14:38.755Z,1340216078.755 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-06-20T18:14:38.756Z,1340216078.756 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T18:14:38.756Z,1340216078.756 [Default:Iridium:B.GoToSurface] Stopped
2012-06-20T18:14:38.756Z,1340216078.756 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T18:14:38.756Z,1340216078.756 [Default:Iridium:Read_Iridium] Running Loop=1
2012-06-20T18:14:53.845Z,1340216093.845 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=9964, MT Status=1, MTMSN=2743
2012-06-20T18:14:54.023Z,1340216094.023 [NAL9601](INFO): Sent 100 bytes from file Logs/20120620T160349/shore0014.lzma
2012-06-20T18:14:54.023Z,1340216094.023 [NAL9601](INFO): Packets left to send: 0
2012-06-20T18:14:54.024Z,1340216094.024 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0014.lzma.parts/0000.sbd
2012-06-20T18:14:54.483Z,1340216094.483 [NAL9601](INFO): Received command:configset VerticalControl.buoyancyNeutral 450 cc; configset VerticalControl.massDefault -0.6 cm
2012-06-20T18:14:54.501Z,1340216094.501 [CommandLine](IMPORTANT): got command configSet VerticalControl.buoyancyNeutral 450.000000 cubic_centimeter
2012-06-20T18:14:54.518Z,1340216094.518 [CommandLine](IMPORTANT): got command configSet VerticalControl.massDefault -0.600000 centimeter
2012-06-20T18:15:04.357Z,1340216104.357 [NAL9601](IMPORTANT): SBD MO Status=0, MOMSN=9965, MT Status=1, MTMSN=2744
2012-06-20T18:15:04.952Z,1340216104.952 [NAL9601](INFO): Received command:get VerticalControl.buoyancyNeutral; get VerticalControl.massDefault
2012-06-20T18:15:05.096Z,1340216105.096 [CommandLine](IMPORTANT): got command get VerticalControl.buoyancyNeutral
2012-06-20T18:15:05.097Z,1340216105.097 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral 449.999992 cubic_centimeter
2012-06-20T18:15:05.203Z,1340216105.203 [CommandLine](IMPORTANT): got command get VerticalControl.massDefault
2012-06-20T18:15:05.203Z,1340216105.203 [CommandLine](IMPORTANT): VerticalControl.massDefault -0.600000 centimeter
2012-06-20T18:15:06.242Z,1340216106.242 [NAL9601](IMPORTANT): GPS fix at: 1340216112.00
2012-06-20T18:15:06.258Z,1340216106.258 [Default:GPS:Read_GPS] Stopped
2012-06-20T18:15:06.258Z,1340216106.258 [Default:GPS:D] Running Loop=1
2012-06-20T18:15:06.654Z,1340216106.654 [Default:GPS:D] Stopped
2012-06-20T18:15:06.655Z,1340216106.655 [Default:GPS](INFO): Completed Default:GPS
2012-06-20T18:15:06.655Z,1340216106.655 [Default:GPS] Stopped
2012-06-20T18:15:06.655Z,1340216106.655 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-06-20T18:15:06.655Z,1340216106.655 [Default:GPS:A.SetSpeed] Stopped
2012-06-20T18:15:06.655Z,1340216106.655 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T18:15:13.226Z,1340216113.226 [NAL9601](INFO): SBD MO Status=0, MOMSN=9966, MT Status=0, MTMSN=0
2012-06-20T18:15:26.796Z,1340216126.796 [NAL9601](INFO): SBD MO Status=1, MOMSN=9967, MT Status=0, MTMSN=0
2012-06-20T18:15:26.971Z,1340216126.971 [NAL9601](INFO): Sent 332 bytes from file Logs/20120620T160349/shore0015.lzma
2012-06-20T18:15:26.971Z,1340216126.971 [NAL9601](INFO): Packets left to send: 1
2012-06-20T18:15:27.112Z,1340216127.112 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0015.lzma.parts/0001.sbd
2012-06-20T18:15:38.210Z,1340216138.210 [NAL9601](INFO): SBD MO Status=1, MOMSN=9968, MT Status=0, MTMSN=0
2012-06-20T18:15:38.355Z,1340216138.355 [NAL9601](INFO): Sent 24 bytes from file Logs/20120620T160349/shore0015.lzma
2012-06-20T18:15:38.355Z,1340216138.355 [NAL9601](INFO): Packets left to send: 0
2012-06-20T18:15:38.356Z,1340216138.356 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0015.lzma.parts/0000.sbd
2012-06-20T18:15:46.209Z,1340216146.209 [NAL9601](INFO): SBD MO Status=0, MOMSN=9969, MT Status=0, MTMSN=0
2012-06-20T18:15:46.423Z,1340216146.423 [Default:Iridium:Read_Iridium] Stopped
2012-06-20T18:15:46.423Z,1340216146.423 [Default:Iridium](INFO): Completed Default:Iridium
2012-06-20T18:15:46.424Z,1340216146.424 [Default:Iridium] Stopped
2012-06-20T18:15:46.424Z,1340216146.424 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-06-20T18:15:46.424Z,1340216146.424 [Default:Iridium:A.SetSpeed] Stopped
2012-06-20T18:15:46.424Z,1340216146.424 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T18:15:46.623Z,1340216146.623 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-06-20T18:15:46.623Z,1340216146.623 [Default:CallIridium:B] Stopped
2012-06-20T18:15:46.623Z,1340216146.623 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-06-20T18:15:46.624Z,1340216146.624 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-06-20T18:15:46.624Z,1340216146.624 [Default:CallIridium] Stopped
2012-06-20T18:15:46.624Z,1340216146.624 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-06-20T18:15:56.872Z,1340216156.872 [NAL9601](INFO): Powering down
2012-06-20T18:20:46.963Z,1340216446.963 [Default:CallIridium] Running Loop=1
2012-06-20T18:20:46.963Z,1340216446.963 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-06-20T18:20:46.963Z,1340216446.963 [Default:CallIridium:A] Running Loop=1
2012-06-20T18:20:46.963Z,1340216446.963 [Default:CallIridium:A] Stopped
2012-06-20T18:20:46.963Z,1340216446.963 [Default:CallIridium:B] Running Loop=1
2012-06-20T18:20:46.964Z,1340216446.964 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-06-20T18:20:51.764Z,1340216451.764 [Default:Iridium] Running Loop=1
2012-06-20T18:20:51.764Z,1340216451.764 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-06-20T18:20:51.764Z,1340216451.764 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-06-20T18:20:51.764Z,1340216451.764 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-06-20T18:20:51.764Z,1340216451.764 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-06-20T18:20:51.764Z,1340216451.764 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T18:20:51.765Z,1340216451.765 [Default:Iridium:B.GoToSurface] Stopped
2012-06-20T18:20:51.765Z,1340216451.765 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T18:20:51.765Z,1340216451.765 [Default:Iridium:Read_Iridium] Running Loop=1
2012-06-20T18:20:51.766Z,1340216451.766 [Default:GPS] Running Loop=1
2012-06-20T18:20:51.766Z,1340216451.766 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-06-20T18:20:51.766Z,1340216451.766 [Default:GPS:A.SetSpeed] Running Loop=1
2012-06-20T18:20:51.766Z,1340216451.766 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-06-20T18:20:51.766Z,1340216451.766 [Default:GPS:B.GoToSurface] Running Loop=1
2012-06-20T18:20:51.766Z,1340216451.766 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T18:20:51.767Z,1340216451.767 [Default:GPS:B.GoToSurface] Stopped
2012-06-20T18:20:51.767Z,1340216451.767 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T18:20:51.767Z,1340216451.767 [Default:GPS:Read_GPS] Running Loop=1
2012-06-20T18:20:52.412Z,1340216452.412 [NAL9601](INFO): Powering up
2012-06-20T18:21:58.135Z,1340216518.135 [NAL9601](INFO): NAL9601 initialized
2012-06-20T18:22:15.998Z,1340216535.997 [NAL9601](INFO): SBD MO Status=1, MOMSN=9970, MT Status=0, MTMSN=0
2012-06-20T18:22:16.203Z,1340216536.203 [NAL9601](INFO): Sent 102 bytes from file Logs/20120620T160349/shore0016.lzma
2012-06-20T18:22:16.203Z,1340216536.203 [NAL9601](INFO): Packets left to send: 0
2012-06-20T18:22:16.204Z,1340216536.204 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0016.lzma.parts/0000.sbd
2012-06-20T18:22:23.998Z,1340216543.998 [NAL9601](INFO): SBD MO Status=0, MOMSN=9971, MT Status=0, MTMSN=0
2012-06-20T18:22:24.201Z,1340216544.201 [Default:Iridium:Read_Iridium] Stopped
2012-06-20T18:22:24.202Z,1340216544.202 [Default:Iridium](INFO): Completed Default:Iridium
2012-06-20T18:22:24.202Z,1340216544.202 [Default:Iridium] Stopped
2012-06-20T18:22:24.202Z,1340216544.202 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-06-20T18:22:24.202Z,1340216544.202 [Default:Iridium:A.SetSpeed] Stopped
2012-06-20T18:22:24.202Z,1340216544.202 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T18:22:24.432Z,1340216544.432 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-06-20T18:22:24.432Z,1340216544.432 [Default:CallIridium:B] Stopped
2012-06-20T18:22:24.432Z,1340216544.432 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-06-20T18:22:24.433Z,1340216544.432 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-06-20T18:22:24.433Z,1340216544.433 [Default:CallIridium] Stopped
2012-06-20T18:22:24.433Z,1340216544.433 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-06-20T18:22:33.199Z,1340216553.199 [NAL9601](IMPORTANT): GPS fix at: 1340216559.00
2012-06-20T18:22:33.215Z,1340216553.215 [Default:GPS:Read_GPS] Stopped
2012-06-20T18:22:33.215Z,1340216553.215 [Default:GPS:D] Running Loop=1
2012-06-20T18:22:33.646Z,1340216553.646 [Default:GPS:D] Stopped
2012-06-20T18:22:33.647Z,1340216553.647 [Default:GPS](INFO): Completed Default:GPS
2012-06-20T18:22:33.647Z,1340216553.647 [Default:GPS] Stopped
2012-06-20T18:22:33.647Z,1340216553.647 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-06-20T18:22:33.647Z,1340216553.647 [Default:GPS:A.SetSpeed] Stopped
2012-06-20T18:22:33.647Z,1340216553.647 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T18:22:49.195Z,1340216569.195 [NAL9601](INFO): Powering down
2012-06-20T18:27:24.295Z,1340216844.295 [Default:CallIridium] Running Loop=1
2012-06-20T18:27:24.295Z,1340216844.295 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-06-20T18:27:24.295Z,1340216844.295 [Default:CallIridium:A] Running Loop=1
2012-06-20T18:27:24.296Z,1340216844.296 [Default:CallIridium:A] Stopped
2012-06-20T18:27:24.296Z,1340216844.296 [Default:CallIridium:B] Running Loop=1
2012-06-20T18:27:24.296Z,1340216844.296 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-06-20T18:27:29.098Z,1340216849.098 [Default:Iridium] Running Loop=1
2012-06-20T18:27:29.098Z,1340216849.098 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-06-20T18:27:29.098Z,1340216849.098 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-06-20T18:27:29.098Z,1340216849.098 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-06-20T18:27:29.098Z,1340216849.098 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-06-20T18:27:29.098Z,1340216849.099 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T18:27:29.099Z,1340216849.099 [Default:Iridium:B.GoToSurface] Stopped
2012-06-20T18:27:29.099Z,1340216849.099 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T18:27:29.100Z,1340216849.099 [Default:Iridium:Read_Iridium] Running Loop=1
2012-06-20T18:27:29.100Z,1340216849.100 [Default:GPS] Running Loop=1
2012-06-20T18:27:29.100Z,1340216849.100 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-06-20T18:27:29.100Z,1340216849.100 [Default:GPS:A.SetSpeed] Running Loop=1
2012-06-20T18:27:29.100Z,1340216849.100 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-06-20T18:27:29.100Z,1340216849.100 [Default:GPS:B.GoToSurface] Running Loop=1
2012-06-20T18:27:29.100Z,1340216849.100 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T18:27:29.101Z,1340216849.101 [Default:GPS:B.GoToSurface] Stopped
2012-06-20T18:27:29.101Z,1340216849.101 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T18:27:29.101Z,1340216849.101 [Default:GPS:Read_GPS] Running Loop=1
2012-06-20T18:27:29.796Z,1340216849.796 [NAL9601](INFO): Powering up
2012-06-20T18:28:35.519Z,1340216915.519 [NAL9601](INFO): NAL9601 initialized
2012-06-20T18:28:58.090Z,1340216938.090 [NAL9601](INFO): SBD MO Status=1, MOMSN=9972, MT Status=0, MTMSN=0
2012-06-20T18:28:58.275Z,1340216938.275 [NAL9601](INFO): Sent 163 bytes from file Logs/20120620T160349/shore0017.lzma
2012-06-20T18:28:58.275Z,1340216938.275 [NAL9601](INFO): Packets left to send: 0
2012-06-20T18:28:58.276Z,1340216938.276 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0017.lzma.parts/0000.sbd
2012-06-20T18:29:13.686Z,1340216953.685 [NAL9601](INFO): SBD MO Status=0, MOMSN=9973, MT Status=0, MTMSN=0
2012-06-20T18:29:13.866Z,1340216953.866 [Default:Iridium:Read_Iridium] Stopped
2012-06-20T18:29:13.867Z,1340216953.866 [Default:Iridium](INFO): Completed Default:Iridium
2012-06-20T18:29:13.867Z,1340216953.867 [Default:Iridium] Stopped
2012-06-20T18:29:13.867Z,1340216953.867 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-06-20T18:29:13.867Z,1340216953.867 [Default:Iridium:A.SetSpeed] Stopped
2012-06-20T18:29:13.867Z,1340216953.867 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T18:29:14.105Z,1340216954.105 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-06-20T18:29:14.105Z,1340216954.105 [Default:CallIridium:B] Stopped
2012-06-20T18:29:14.105Z,1340216954.105 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-06-20T18:29:14.105Z,1340216954.105 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-06-20T18:29:14.105Z,1340216954.105 [Default:CallIridium] Stopped
2012-06-20T18:29:14.105Z,1340216954.105 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-06-20T18:33:58.887Z,1340217238.887 [NAL9601](IMPORTANT): GPS fix at: 1340217253.00
2012-06-20T18:33:58.936Z,1340217238.936 [Default:GPS:Read_GPS] Stopped
2012-06-20T18:33:58.936Z,1340217238.936 [Default:GPS:D] Running Loop=1
2012-06-20T18:33:59.402Z,1340217239.402 [Default:GPS:D] Stopped
2012-06-20T18:33:59.403Z,1340217239.403 [Default:GPS](INFO): Completed Default:GPS
2012-06-20T18:33:59.403Z,1340217239.403 [Default:GPS] Stopped
2012-06-20T18:33:59.403Z,1340217239.403 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-06-20T18:33:59.403Z,1340217239.403 [Default:GPS:A.SetSpeed] Stopped
2012-06-20T18:33:59.403Z,1340217239.403 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T18:34:14.822Z,1340217254.822 [NAL9601](INFO): Powering down
2012-06-20T18:34:14.839Z,1340217254.839 [Default:CallIridium] Running Loop=1
2012-06-20T18:34:14.840Z,1340217254.840 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-06-20T18:34:14.840Z,1340217254.840 [Default:CallIridium:A] Running Loop=1
2012-06-20T18:34:14.840Z,1340217254.840 [Default:CallIridium:A] Stopped
2012-06-20T18:34:14.840Z,1340217254.840 [Default:CallIridium:B] Running Loop=1
2012-06-20T18:34:14.840Z,1340217254.840 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-06-20T18:34:19.912Z,1340217259.912 [Default:Iridium] Running Loop=1
2012-06-20T18:34:19.912Z,1340217259.912 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-06-20T18:34:19.913Z,1340217259.912 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-06-20T18:34:19.913Z,1340217259.913 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-06-20T18:34:19.913Z,1340217259.913 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-06-20T18:34:19.913Z,1340217259.913 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T18:34:19.914Z,1340217259.914 [Default:Iridium:B.GoToSurface] Stopped
2012-06-20T18:34:19.914Z,1340217259.914 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T18:34:19.914Z,1340217259.914 [Default:Iridium:Read_Iridium] Running Loop=1
2012-06-20T18:34:19.914Z,1340217259.914 [Default:GPS] Running Loop=1
2012-06-20T18:34:19.914Z,1340217259.914 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-06-20T18:34:19.914Z,1340217259.914 [Default:GPS:A.SetSpeed] Running Loop=1
2012-06-20T18:34:19.915Z,1340217259.915 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-06-20T18:34:19.915Z,1340217259.915 [Default:GPS:B.GoToSurface] Running Loop=1
2012-06-20T18:34:19.915Z,1340217259.915 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T18:34:19.916Z,1340217259.916 [Default:GPS:B.GoToSurface] Stopped
2012-06-20T18:34:19.916Z,1340217259.916 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T18:34:19.916Z,1340217259.916 [Default:GPS:Read_GPS] Running Loop=1
2012-06-20T18:34:20.483Z,1340217260.483 [NAL9601](INFO): Powering up
2012-06-20T18:35:26.203Z,1340217326.203 [NAL9601](INFO): NAL9601 initialized
2012-06-20T18:35:27.286Z,1340217327.286 [NAL9601](IMPORTANT): GPS fix at: 1340217335.00
2012-06-20T18:35:27.302Z,1340217327.302 [Default:GPS:Read_GPS] Stopped
2012-06-20T18:35:27.302Z,1340217327.302 [Default:GPS:D] Running Loop=1
2012-06-20T18:35:27.704Z,1340217327.704 [Default:GPS:D] Stopped
2012-06-20T18:35:27.704Z,1340217327.704 [Default:GPS](INFO): Completed Default:GPS
2012-06-20T18:35:27.704Z,1340217327.704 [Default:GPS] Stopped
2012-06-20T18:35:27.704Z,1340217327.704 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-06-20T18:35:27.705Z,1340217327.704 [Default:GPS:A.SetSpeed] Stopped
2012-06-20T18:35:27.705Z,1340217327.705 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T18:35:45.598Z,1340217345.598 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=9974, MT Status=1, MTMSN=2745
2012-06-20T18:35:45.763Z,1340217345.763 [NAL9601](INFO): Sent 179 bytes from file Logs/20120620T160349/shore0018.lzma
2012-06-20T18:35:45.763Z,1340217345.763 [NAL9601](INFO): Packets left to send: 0
2012-06-20T18:35:45.765Z,1340217345.764 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0018.lzma.parts/0000.sbd
2012-06-20T18:35:46.224Z,1340217346.224 [NAL9601](INFO): Received command:configset VerticalControl.buoyancyNeutral 480 cc persist; configset VerticalControl.massDefault -0.7 cm persist
2012-06-20T18:35:46.243Z,1340217346.243 [CommandLine](IMPORTANT): got command configSet VerticalControl.buoyancyNeutral 480.000000 cubic_centimeter persist
2012-06-20T18:35:46.498Z,1340217346.498 [CommandLine](IMPORTANT): got command configSet VerticalControl.massDefault -0.700000 centimeter persist
2012-06-20T18:35:56.070Z,1340217356.070 [NAL9601](IMPORTANT): SBD MO Status=0, MOMSN=9975, MT Status=1, MTMSN=2746
2012-06-20T18:35:56.684Z,1340217356.684 [NAL9601](INFO): Received command:run Engineering/triangle_control_speed_compare.xml
2012-06-20T18:35:56.739Z,1340217356.739 [CommandLine](IMPORTANT): got command run ./Missions/Engineering/triangle_control_speed_compare.xml
2012-06-20T18:35:56.739Z,1340217356.739 [MissionManager](INFO): Loading Mission: ./Missions/Engineering/triangle_control_speed_compare.xml
2012-06-20T18:35:56.932Z,1340217356.931 [MissionManager](INFO): DefineArg triangle_control_speed_compare.Wpt1Lat = 36.815000 arcdeg
2012-06-20T18:35:56.939Z,1340217356.939 [MissionManager](INFO): DefineArg triangle_control_speed_compare.Wpt1Lon = -121.869000 arcdeg
2012-06-20T18:35:56.942Z,1340217356.941 [MissionManager](INFO): DefineArg triangle_control_speed_compare.Wpt2Lat = 36.829000 arcdeg
2012-06-20T18:35:56.949Z,1340217356.949 [MissionManager](INFO): DefineArg triangle_control_speed_compare.Wpt2Lon = -121.886000 arcdeg
2012-06-20T18:35:56.956Z,1340217356.956 [MissionManager](INFO): DefineArg triangle_control_speed_compare.Wpt3Lat = 36.816000 arcdeg
2012-06-20T18:35:56.963Z,1340217356.963 [MissionManager](INFO): DefineArg triangle_control_speed_compare.Wpt3Lon = -121.883000 arcdeg
2012-06-20T18:35:56.966Z,1340217356.966 [MissionManager](INFO): DefineArg triangle_control_speed_compare.MassHold = 1 bool
2012-06-20T18:35:56.973Z,1340217356.973 [MissionManager](INFO): DefineArg triangle_control_speed_compare.BuoyancyHold = 1 bool
2012-06-20T18:35:56.980Z,1340217356.980 [MissionManager](INFO): DefineArg triangle_control_speed_compare.DepthShallow = 15.000000 m
2012-06-20T18:35:56.987Z,1340217356.987 [MissionManager](INFO): DefineArg triangle_control_speed_compare.DepthDeep = 32.000000 m
2012-06-20T18:35:56.990Z,1340217356.990 [MissionManager](INFO): DefineArg triangle_control_speed_compare.Speed1 = 1.000000 m/s
2012-06-20T18:35:56.997Z,1340217356.997 [MissionManager](INFO): DefineArg triangle_control_speed_compare.Speed2 = 0.750000 m/s
2012-06-20T18:35:57.004Z,1340217357.004 [MissionManager](INFO): DefineArg triangle_control_speed_compare.Speed3 = 0.600000 m/s
2012-06-20T18:35:57.012Z,1340217357.012 [MissionManager](INFO): DefineArg triangle_control_speed_compare.BuoyancyNeutral = 0.000480 n/a
2012-06-20T18:35:57.020Z,1340217357.020 [MissionManager](INFO): DefineArg triangle_control_speed_compare.MassDefault = -0.007000 n/a
2012-06-20T18:35:57.027Z,1340217357.027 [MissionManager](INFO): DefineArg triangle_control_speed_compare.MaxDepth = 37.000000 m
2012-06-20T18:35:57.035Z,1340217357.035 [MissionManager](INFO): DefineArg triangle_control_speed_compare.NeedCommsTime = 50.000000 min
2012-06-20T18:35:57.040Z,1340217357.040 [MissionManager](INFO): DefineArg triangle_control_speed_compare.MinAltitude = 7.000000 m
2012-06-20T18:35:57.043Z,1340217357.043 [MissionManager](INFO): DefineArg triangle_control_speed_compare.TimeoutDuration = 600.000000 min
2012-06-20T18:35:57.045Z,1340217357.045 [triangle_control_speed_compare:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-06-20T18:35:57.061Z,1340217357.061 [triangle_control_speed_compare:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-06-20T18:35:57.078Z,1340217357.078 [triangle_control_speed_compare:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2012-06-20T18:35:57.103Z,1340217357.103 [triangle_control_speed_compare:SURFACECOMMS:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-06-20T18:35:57.113Z,1340217357.113 [triangle_control_speed_compare:SURFACECOMMS:B:A.SetSpeed](DEBUG): Construct.
2012-06-20T18:35:57.142Z,1340217357.142 [triangle_control_speed_compare:WaypointOne:A.Pitch](DEBUG): Construct.
2012-06-20T18:35:57.152Z,1340217357.152 [triangle_control_speed_compare:WaypointOne:B.SetSpeed](DEBUG): Construct.
2012-06-20T18:35:57.160Z,1340217357.160 [triangle_control_speed_compare:WaypointOne:WaypointW1.Waypoint](DEBUG): Construct Waypoint.
2012-06-20T18:35:57.173Z,1340217357.173 [triangle_control_speed_compare:ThreeLaps:BuoyancyHold:A.Buoyancy](DEBUG): Construct Buoyancy.
2012-06-20T18:35:57.185Z,1340217357.185 [triangle_control_speed_compare:ThreeLaps:MassHold:A.Pitch](DEBUG): Construct.
2012-06-20T18:35:57.208Z,1340217357.208 [triangle_control_speed_compare:ThreeLaps:TestDrive:Speed1:A.SetSpeed](DEBUG): Construct.
2012-06-20T18:35:57.235Z,1340217357.235 [triangle_control_speed_compare:ThreeLaps:TestDrive:Speed1:B.Pitch](DEBUG): Construct.
2012-06-20T18:35:57.245Z,1340217357.245 [triangle_control_speed_compare:ThreeLaps:TestDrive:Speed1:Wpt2.Waypoint](DEBUG): Construct Waypoint.
2012-06-20T18:35:57.260Z,1340217357.260 [triangle_control_speed_compare:ThreeLaps:TestDrive:Speed2:A.SetSpeed](DEBUG): Construct.
2012-06-20T18:35:57.267Z,1340217357.267 [triangle_control_speed_compare:ThreeLaps:TestDrive:Speed2:B.Pitch](DEBUG): Construct.
2012-06-20T18:35:57.277Z,1340217357.277 [triangle_control_speed_compare:ThreeLaps:TestDrive:Speed2:Wpt3.Waypoint](DEBUG): Construct Waypoint.
2012-06-20T18:35:57.292Z,1340217357.292 [triangle_control_speed_compare:ThreeLaps:TestDrive:Speed3:A.SetSpeed](DEBUG): Construct.
2012-06-20T18:35:57.299Z,1340217357.299 [triangle_control_speed_compare:ThreeLaps:TestDrive:Speed3:B.Pitch](DEBUG): Construct.
2012-06-20T18:35:57.317Z,1340217357.317 [triangle_control_speed_compare:ThreeLaps:TestDrive:Speed3:Wpt1.Waypoint](DEBUG): Construct Waypoint.
2012-06-20T18:35:57.378Z,1340217357.378 [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="triangle_control_speed_compare">

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

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

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

    <DefineArg Name="Wpt2Lat"><Units:degree/><Value>36.829</Value></DefineArg>

    <DefineArg Name="Wpt2Lon"><Units:degree/><Value>-121.886</Value></DefineArg>

    <DefineArg Name="Wpt3Lat"><Units:degree/><Value>36.816</Value></DefineArg>

    <DefineArg Name="Wpt3Lon"><Units:degree/><Value>-121.883</Value></DefineArg>

    <DefineArg Name="MassHold"><Description>
        Set to True in order to hold mass at user defined position, False to
        allow mass to run on its own.
    </Description><True/></DefineArg>

    <DefineArg Name="BuoyancyHold"><Description>
        Set to True in order to hold buoyancy at neutral position, False to
        allow buoyancy to run on its own.
    </Description><True/></DefineArg>

    <DefineArg Name="DepthShallow"><Description>
        Depth for transit
    </Description><Units:meter/><Value>15</Value></DefineArg>

    <DefineArg Name="DepthDeep"><Description>
        Depth for test
    </Description><Units:meter/><Value>32</Value></DefineArg>

    <DefineArg Name="Speed1"><Description>
        Speed for leg 1
    </Description><Units:meter_per_second/><Value>1</Value></DefineArg>

    <DefineArg Name="Speed2"><Description>
        Speed for leg 2
    </Description><Units:meter_per_second/><Value>.75</Value></DefineArg>

    <DefineArg Name="Speed3"><Description>
        Speed for leg 3
    </Description><Units:meter_per_second/><Value>.60</Value></DefineArg>

    <DefineArg Name="BuoyancyNeutral"><Description>
        Buoyancy bladder position while performing the transit. Defaults to
        buoyancyNeutral setting in the Config/Control.cfg file.
    </Description><Control:VerticalControl.buoyancyNeutral/></DefineArg>

    <DefineArg Name="MassDefault"><Description>
        Static setting for mass during the mission.
    </Description><Control:VerticalControl.massDefault/></DefineArg>

    <DefineArg Name="MaxDepth"><Description>
        Maximum depth for the entire mission.
    </Description><Units:meter/><Value>37</Value></DefineArg>

    <DefineArg Name="NeedCommsTime"><Description>
        Elapsed time after previous surface communications when vehicle will
        begin to ascend for additional surface communications
    </Description><Units:minute/><Value>50</Value></DefineArg>

    <DefineArg Name="MinAltitude"><Description>
        Minimum height above the sea floor for the entire mission.
    </Description><Units:meter/><Value>7.0</Value></DefineArg>

    <DefineArg Name="TimeoutDuration"><Description>
        Maximum length of mission
    </Description><Units:minute/><Value>600</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/><Units:kilometer/><Value>1</Value></Setting>
    </Guidance:OffshoreEnvelope>

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

    <Aggregate Id="SURFACECOMMS">

        <Guidance:GoToSurface RunIn="Progression" />

        <Aggregate>

            <Preemptive><True /></Preemptive>

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

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

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

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

        </Aggregate>

    </Aggregate>

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

    <Aggregate Id="NeedComms">

        <When>
            <Elapsed><Universal:time_fix/></Elapsed>
            <Gt><Arg Name="NeedCommsTime"/></Gt>
        </When>

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

    </Aggregate>

    <Aggregate Id="WaypointOne">

<!-- Go to Wpt1 and start from there -->

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

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

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

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

    </Aggregate>

    <Aggregate Id="ThreeLaps">

        <Aggregate Id="BuoyancyHold" RunIn="Parallel">

            <While><Arg Name="BuoyancyHold"/>
            </While>

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

        </Aggregate>

        <Aggregate Id="MassHold" RunIn="Parallel">

            <While><Arg Name="MassHold"/>
            </While>

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

        </Aggregate>

        <Assign RunIn="Parallel"><Control:VerticalControl.useElevIntInDepthMode/><False/></Assign>
        <Assign RunIn="Parallel"><Control:VerticalControl.massDeadband/><Units:millimeter/><Value>0.0</Value></Assign>

        <Aggregate Id="TestDrive">

            <Aggregate Id="Speed1">

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

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

                <Guidance:Waypoint Id="Wpt2" RunIn="Sequence">
                    <Setting><Guidance:Waypoint.latitude/><Arg Name="Wpt2Lat"/></Setting>
                    <Setting><Guidance:Waypoint.longitude/><Arg Name="Wpt2Lon"/></Setting>
                </Guidance:Waypoint>

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

            </Aggregate>

            <Aggregate Id="Speed2">

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

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

                <Guidance:Waypoint Id="Wpt3" RunIn="Sequence">
                    <Setting><Guidance:Waypoint.latitude/><Arg Name="Wpt3Lat"/></Setting>
                    <Setting><Guidance:Waypoint.longitude/><Arg Name="Wpt3Lon"/></Setting>
                </Guidance:Waypoint>

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

            </Aggregate>

            <Aggregate Id="Speed3">

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

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

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

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

            </Aggregate>

        </Aggregate>

        <Aggregate Id="Lap2">

            <Assign RunIn="Parallel"><Control:VerticalControl.elevDeadband/><Units:degree/><Value>0.0</Value></Assign>

            <Call Id="LAP2" RefId="TestDrive"/>

        </Aggregate>

        <Aggregate Id="Lap3">

            <Assign><Arg Name="BuoyancyHold"/><False/></Assign>

            <Assign RunIn="Parallel"><Control:VerticalControl.elevDeadband/><Units:degree/><Value>0.0</Value></Assign>

            <Call Id="LAP3" RefId="TestDrive"/>

        </Aggregate>

        <Aggregate Id="Lap4">

            <Assign><Arg Name="BuoyancyHold"/><False/></Assign>

            <Call Id="LAP4" RefId="TestDrive"/>

        </Aggregate>

    </Aggregate>

<!-- End of 3 laps -->

<!--
    <Aggregate Id="NewGains1">

VerticalControl.useElevIntInDepthMode (bool)


        <Assign RunIn="Parallel"><Control:VerticalControl.elevDeadband/><Units:degree/><Value>0.01</Value></Assign>

        <Assign RunIn="Parallel"><Control:VerticalControl.kdPitchMass/><Units:second/><Value>0.2</Value></Assign>

        <Assign RunIn="Parallel"><Control:VerticalControl.kiDepthOff/><Units:meter_per_second/><Value>.2</Value></Assign>

        <Assign RunIn="Parallel"><Control:VerticalControl.kiPitchMass/><Units:reciprocal_second/><Value>0.002</Value></Assign>

        <Assign RunIn="Parallel"><Control:VerticalControl.kpPitchMass/><Units:count/><Value>0.1</Value></Assign>

        <Assign RunIn="Parallel"><Control:VerticalControl.massDeadband/><Units:millimeter/><Value>0.01</Value></Assign>

        <Assign RunIn="Parallel"><Control:VerticalControl.maxDiveAccel/><Units:meter_per_second_squared/><Value>0.001</Value></Assign>

        <Call Id="RUN2" RefId="ThreeLaps"/>

    </Aggregate>-->

</Mission>


2012-06-20T18:35:57.379Z,1340217357.379 [CommandLine](IMPORTANT): Running ./Missions/Engineering/triangle_control_speed_compare.xml
2012-06-20T18:35:57.685Z,1340217357.685 [Default] Stopped
2012-06-20T18:35:57.685Z,1340217357.685 [Default](INFO): Aggregate::uninitialize Default
2012-06-20T18:35:57.685Z,1340217357.685 [Default:Iridium] Stopped
2012-06-20T18:35:57.685Z,1340217357.685 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-06-20T18:35:57.685Z,1340217357.685 [Default:Iridium:A.SetSpeed] Stopped
2012-06-20T18:35:57.685Z,1340217357.685 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T18:35:57.685Z,1340217357.685 [Default:Iridium:Read_Iridium] Stopped
2012-06-20T18:35:57.685Z,1340217357.685 [Default:CallIridium] Stopped
2012-06-20T18:35:57.686Z,1340217357.685 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-06-20T18:35:57.686Z,1340217357.685 [Default:CallIridium:B] Stopped
2012-06-20T18:35:57.686Z,1340217357.686 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-06-20T18:35:57.686Z,1340217357.686 [Default:D.SetSpeed] Stopped
2012-06-20T18:35:57.686Z,1340217357.686 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-06-20T18:35:57.686Z,1340217357.686 [Default:E.GoToSurface] Stopped
2012-06-20T18:35:57.686Z,1340217357.686 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T18:35:57.686Z,1340217357.686 [Default:F.Wait] Stopped
2012-06-20T18:35:57.686Z,1340217357.686 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2012-06-20T18:35:57.686Z,1340217357.686 [MissionManager](IMPORTANT): Started mission triangle_control_speed_compare
2012-06-20T18:35:57.686Z,1340217357.686 [triangle_control_speed_compare] Running Loop=1
2012-06-20T18:35:57.687Z,1340217357.687 [triangle_control_speed_compare](INFO): Aggregate::initialize triangle_control_speed_compare
2012-06-20T18:35:57.687Z,1340217357.687 [triangle_control_speed_compare:A.AltitudeEnvelope] Running Loop=1
2012-06-20T18:35:57.687Z,1340217357.687 [triangle_control_speed_compare:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-06-20T18:35:57.687Z,1340217357.687 [triangle_control_speed_compare:B.DepthEnvelope] Running Loop=1
2012-06-20T18:35:57.687Z,1340217357.687 [triangle_control_speed_compare:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-06-20T18:35:57.688Z,1340217357.688 [triangle_control_speed_compare:C.OffshoreEnvelope] Running Loop=1
2012-06-20T18:35:57.688Z,1340217357.688 [triangle_control_speed_compare:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2012-06-20T18:35:57.688Z,1340217357.688 [triangle_control_speed_compare:D] Running Loop=1
2012-06-20T18:35:57.688Z,1340217357.688 [triangle_control_speed_compare:SURFACECOMMS] Running Loop=1
2012-06-20T18:35:57.688Z,1340217357.688 [triangle_control_speed_compare:SURFACECOMMS](INFO): Aggregate::initialize triangle_control_speed_compare:SURFACECOMMS
2012-06-20T18:35:57.688Z,1340217357.688 [triangle_control_speed_compare:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-06-20T18:35:57.688Z,1340217357.688 [triangle_control_speed_compare:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T18:35:57.693Z,1340217357.694 [triangle_control_speed_compare:SURFACECOMMS:B] Running Loop=1
2012-06-20T18:35:57.694Z,1340217357.694 [triangle_control_speed_compare:SURFACECOMMS:B](INFO): Aggregate::initialize triangle_control_speed_compare:SURFACECOMMS:B
2012-06-20T18:35:57.694Z,1340217357.694 [triangle_control_speed_compare:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-06-20T18:35:57.694Z,1340217357.694 [triangle_control_speed_compare:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-06-20T18:35:57.694Z,1340217357.694 [triangle_control_speed_compare:SURFACECOMMS:B:B] Running Loop=1
2012-06-20T18:35:57.694Z,1340217357.694 [triangle_control_speed_compare:D] Running Loop=1
2012-06-20T18:35:57.695Z,1340217357.695 [triangle_control_speed_compare:D](DEBUG): Initialize ReadDataComponent to sense platform_orientation
2012-06-20T18:35:57.696Z,1340217357.696 [triangle_control_speed_compare:C.OffshoreEnvelope] Running Loop=1
2012-06-20T18:35:57.700Z,1340217357.700 [triangle_control_speed_compare:B.DepthEnvelope] Running Loop=1
2012-06-20T18:35:57.705Z,1340217357.705 [triangle_control_speed_compare:A.AltitudeEnvelope] Running Loop=1
2012-06-20T18:35:58.087Z,1340217358.087 [triangle_control_speed_compare:SURFACECOMMS:B:B](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-06-20T18:35:58.088Z,1340217358.088 [triangle_control_speed_compare:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-06-20T18:36:04.327Z,1340217364.327 [NAL9601](INFO): SBD MO Status=0, MOMSN=9976, MT Status=0, MTMSN=0
2012-06-20T18:36:05.519Z,1340217365.519 [NAL9601](IMPORTANT): GPS fix at: 1340217373.00
2012-06-20T18:36:05.535Z,1340217365.535 [triangle_control_speed_compare:SURFACECOMMS:B:B] Stopped
2012-06-20T18:36:05.535Z,1340217365.535 [triangle_control_speed_compare:SURFACECOMMS:B:C] Running Loop=1
2012-06-20T18:36:05.964Z,1340217365.964 [triangle_control_speed_compare:SURFACECOMMS:B:C](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-06-20T18:36:17.511Z,1340217377.511 [NAL9601](INFO): SBD MO Status=1, MOMSN=9977, MT Status=0, MTMSN=0
2012-06-20T18:36:17.711Z,1340217377.711 [NAL9601](INFO): Sent 332 bytes from file Logs/20120620T160349/shore0019.lzma
2012-06-20T18:36:17.711Z,1340217377.711 [NAL9601](INFO): Packets left to send: 1
2012-06-20T18:36:17.712Z,1340217377.712 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0019.lzma.parts/0001.sbd
2012-06-20T18:36:26.814Z,1340217386.814 [NAL9601](INFO): SBD MO Status=1, MOMSN=9978, MT Status=0, MTMSN=0
2012-06-20T18:36:26.999Z,1340217386.999 [NAL9601](INFO): Sent 45 bytes from file Logs/20120620T160349/shore0019.lzma
2012-06-20T18:36:26.999Z,1340217386.999 [NAL9601](INFO): Packets left to send: 0
2012-06-20T18:36:27.000Z,1340217387.000 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0019.lzma.parts/0000.sbd
2012-06-20T18:36:30.430Z,1340217390.430 [NAL9601](INFO): SBD MO Status=0, MOMSN=9979, MT Status=0, MTMSN=0
2012-06-20T18:36:30.605Z,1340217390.605 [triangle_control_speed_compare:SURFACECOMMS:B:C] Stopped
2012-06-20T18:36:30.606Z,1340217390.606 [triangle_control_speed_compare:SURFACECOMMS:B:D] Running Loop=1
2012-06-20T18:36:30.832Z,1340217390.832 [triangle_control_speed_compare:SURFACECOMMS:B:D](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-06-20T18:36:32.833Z,1340217392.833 [NAL9601](IMPORTANT): GPS fix at: 1340217400.00
2012-06-20T18:36:32.848Z,1340217392.848 [triangle_control_speed_compare:SURFACECOMMS:B:D] Stopped
2012-06-20T18:36:32.848Z,1340217392.848 [triangle_control_speed_compare:SURFACECOMMS:B](INFO): Completed triangle_control_speed_compare:SURFACECOMMS:B
2012-06-20T18:36:32.848Z,1340217392.848 [triangle_control_speed_compare:SURFACECOMMS:B] Stopped
2012-06-20T18:36:32.849Z,1340217392.849 [triangle_control_speed_compare:SURFACECOMMS:B](INFO): Aggregate::uninitialize triangle_control_speed_compare:SURFACECOMMS:B
2012-06-20T18:36:32.849Z,1340217392.849 [triangle_control_speed_compare:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-06-20T18:36:32.849Z,1340217392.849 [triangle_control_speed_compare:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-06-20T18:36:32.850Z,1340217392.849 [triangle_control_speed_compare:SURFACECOMMS](INFO): Completed triangle_control_speed_compare:SURFACECOMMS
2012-06-20T18:36:32.850Z,1340217392.850 [triangle_control_speed_compare:SURFACECOMMS] Stopped
2012-06-20T18:36:32.850Z,1340217392.850 [triangle_control_speed_compare:SURFACECOMMS](INFO): Aggregate::uninitialize triangle_control_speed_compare:SURFACECOMMS
2012-06-20T18:36:32.850Z,1340217392.850 [triangle_control_speed_compare:SURFACECOMMS:A.GoToSurface] Stopped
2012-06-20T18:36:32.850Z,1340217392.850 [triangle_control_speed_compare:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-06-20T18:36:32.850Z,1340217392.850 [triangle_control_speed_compare:WaypointOne] Running Loop=1
2012-06-20T18:36:32.850Z,1340217392.850 [triangle_control_speed_compare:WaypointOne](INFO): Aggregate::initialize triangle_control_speed_compare:WaypointOne
2012-06-20T18:36:32.850Z,1340217392.850 [triangle_control_speed_compare:WaypointOne:A.Pitch] Running Loop=1
2012-06-20T18:36:32.850Z,1340217392.851 [triangle_control_speed_compare:WaypointOne:A.Pitch](DEBUG): Initialize.
2012-06-20T18:36:32.851Z,1340217392.851 [triangle_control_speed_compare:WaypointOne:B.SetSpeed] Running Loop=1
2012-06-20T18:36:32.851Z,1340217392.851 [triangle_control_speed_compare:WaypointOne:B.SetSpeed](DEBUG): Initialize.
2012-06-20T18:36:32.851Z,1340217392.851 [triangle_control_speed_compare:WaypointOne:WaypointW1.Waypoint] Running Loop=1
2012-06-20T18:36:32.851Z,1340217392.851 [triangle_control_speed_compare:WaypointOne:WaypointW1.Waypoint](DEBUG): Initialize WaypointComponent.
2012-06-20T18:36:33.231Z,1340217393.231 [triangle_control_speed_compare:WaypointOne:B.SetSpeed] Running Loop=1
2012-06-20T18:36:33.236Z,1340217393.236 [triangle_control_speed_compare:WaypointOne:A.Pitch] Running Loop=1
2012-06-20T18:36:39.225Z,1340217399.225 [NAL9601](INFO): Powering down
2012-06-20T18:36:56.187Z,1340217416.187 [Radio_Freewave](INFO): Powering down
2012-06-20T18:37:08.222Z,1340217428.222 [Radio_Freewave](INFO): Powering up
2012-06-20T18:37:32.327Z,1340217452.327 [Radio_Freewave](INFO): Powering down
2012-06-20T19:26:33.264Z,1340220393.264 [triangle_control_speed_compare:NeedComms] Running Loop=1
2012-06-20T19:26:33.264Z,1340220393.264 [triangle_control_speed_compare:NeedComms](INFO): Aggregate::initialize triangle_control_speed_compare:NeedComms
2012-06-20T19:26:33.264Z,1340220393.264 [triangle_control_speed_compare:NeedComms:NEEDCOMMS] Running Loop=1
2012-06-20T19:26:33.264Z,1340220393.264 [triangle_control_speed_compare:NeedComms:NEEDCOMMS](INFO): Aggregate::initialize triangle_control_speed_compare:NeedComms:NEEDCOMMS
2012-06-20T19:26:33.548Z,1340220393.548 [triangle_control_speed_compare:SURFACECOMMS] Running Loop=1
2012-06-20T19:26:33.549Z,1340220393.549 [triangle_control_speed_compare:SURFACECOMMS](INFO): Aggregate::initialize triangle_control_speed_compare:SURFACECOMMS
2012-06-20T19:26:33.549Z,1340220393.549 [triangle_control_speed_compare:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-06-20T19:26:33.549Z,1340220393.549 [triangle_control_speed_compare:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-06-20T19:29:51.621Z,1340220591.621 [Radio_Freewave](INFO): Powering up
2012-06-20T19:29:51.633Z,1340220591.633 [triangle_control_speed_compare:SURFACECOMMS:B] Running Loop=1
2012-06-20T19:29:51.633Z,1340220591.633 [triangle_control_speed_compare:SURFACECOMMS:B](INFO): Aggregate::initialize triangle_control_speed_compare:SURFACECOMMS:B
2012-06-20T19:29:51.633Z,1340220591.633 [triangle_control_speed_compare:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-06-20T19:29:51.633Z,1340220591.633 [triangle_control_speed_compare:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-06-20T19:29:51.633Z,1340220591.633 [triangle_control_speed_compare:SURFACECOMMS:B:B] Running Loop=1
2012-06-20T19:29:52.768Z,1340220592.768 [NAL9601](INFO): Powering up
2012-06-20T19:29:59.977Z,1340220599.977 [Radio_Freewave](INFO): Powering down
2012-06-20T19:30:00.377Z,1340220600.377 [Radio_Freewave](INFO): Powering up
2012-06-20T19:30:58.491Z,1340220658.491 [NAL9601](INFO): NAL9601 initialized
2012-06-20T19:30:59.583Z,1340220659.583 [NAL9601](IMPORTANT): GPS fix at: 1340220672.00
2012-06-20T19:30:59.597Z,1340220659.597 [Navigation](IMPORTANT): Error 3.6 %DT at bearing 57.3 deg., over the last 2988.1 m.
2012-06-20T19:30:59.598Z,1340220659.598 [Navigation](IMPORTANT): Distance made good 2515.4 m, at (36.8134, -121.8529).
2012-06-20T19:30:59.599Z,1340220659.599 [triangle_control_speed_compare:SURFACECOMMS:B:B] Stopped
2012-06-20T19:30:59.599Z,1340220659.599 [triangle_control_speed_compare:SURFACECOMMS:B:C] Running Loop=1
2012-06-20T19:31:10.405Z,1340220670.405 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=9980, MT Status=1, MTMSN=2747
2012-06-20T19:31:10.563Z,1340220670.563 [NAL9601](INFO): Sent 332 bytes from file Logs/20120620T160349/shore0020.lzma
2012-06-20T19:31:10.563Z,1340220670.563 [NAL9601](INFO): Packets left to send: 9
2012-06-20T19:31:10.568Z,1340220670.568 [NAL9601](INFO): Stored copy of sent data in Logs/20120620T160349/shore0020.lzma.parts/0009.sbd
2012-06-20T19:31:10.980Z,1340220670.980 [NAL9601](INFO): Received command:restart logs
2012-06-20T19:31:11.047Z,1340220671.047 [CommandLine](IMPORTANT): got command restart logs