2012-05-30T16:03:48.171Z,1338393828.171 [Supervisor](DEBUG): Initializing supervisor.
2012-05-30T16:03:48.173Z,1338393828.173 [SyncHandler](DEBUG): Created PCaller Thread at 1077138656
2012-05-30T16:03:48.174Z,1338393828.174 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-05-30T16:03:48.175Z,1338393828.175 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 1077335264
2012-05-30T16:03:48.176Z,1338393828.176 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-05-30T16:03:48.186Z,1338393828.186 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-05-30T16:03:48.187Z,1338393828.187 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 1077531872
2012-05-30T16:03:48.188Z,1338393828.188 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2012-05-30T16:03:48.188Z,1338393828.188 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-05-30T16:03:48.189Z,1338393828.189 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-05-30T16:03:48.457Z,1338393828.457 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-05-30T16:03:48.457Z,1338393828.457 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-05-30T16:03:48.637Z,1338393828.637 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-05-30T16:03:48.638Z,1338393828.638 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-05-30T16:03:48.722Z,1338393828.722 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-05-30T16:03:48.723Z,1338393828.723 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-05-30T16:03:48.908Z,1338393828.908 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-05-30T16:03:48.908Z,1338393828.908 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-05-30T16:03:49.033Z,1338393829.033 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-05-30T16:03:49.033Z,1338393829.033 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-05-30T16:03:49.247Z,1338393829.247 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-05-30T16:03:49.247Z,1338393829.247 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-05-30T16:03:49.395Z,1338393829.395 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-05-30T16:03:49.395Z,1338393829.395 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-05-30T16:03:49.649Z,1338393829.649 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-05-30T16:03:49.650Z,1338393829.650 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-05-30T16:03:49.747Z,1338393829.747 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-05-30T16:03:49.748Z,1338393829.748 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-05-30T16:03:50.123Z,1338393830.123 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-05-30T16:03:50.124Z,1338393830.124 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-05-30T16:03:50.233Z,1338393830.233 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-05-30T16:03:50.234Z,1338393830.234 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-05-30T16:03:50.320Z,1338393830.320 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2012-05-30T16:03:50.320Z,1338393830.320 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2012-05-30T16:03:50.423Z,1338393830.423 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2012-05-30T16:03:50.554Z,1338393830.555 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2012-05-30T16:03:50.656Z,1338393830.656 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2012-05-30T16:03:50.752Z,1338393830.752 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2012-05-30T16:03:50.862Z,1338393830.862 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2012-05-30T16:03:50.951Z,1338393830.951 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2012-05-30T16:03:51.038Z,1338393831.038 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2012-05-30T16:03:51.150Z,1338393831.150 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-05-30T16:03:51.278Z,1338393831.278 [InternalSim] Loaded
2012-05-30T16:03:51.278Z,1338393831.278 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-05-30T16:03:51.279Z,1338393831.279 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-05-30T16:03:51.279Z,1338393831.279 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-05-30T16:03:51.324Z,1338393831.324 [SBIT](DEBUG): Construct Startup Built In Test.
2012-05-30T16:03:51.335Z,1338393831.335 [SBIT] Loaded
2012-05-30T16:03:51.336Z,1338393831.336 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-05-30T16:03:51.336Z,1338393831.336 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-05-30T16:03:51.360Z,1338393831.360 [IBIT] Loaded
2012-05-30T16:03:51.360Z,1338393831.360 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-05-30T16:03:51.368Z,1338393831.368 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-05-30T16:03:51.474Z,1338393831.474 [CBIT] Loaded
2012-05-30T16:03:51.474Z,1338393831.474 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-05-30T16:03:51.475Z,1338393831.475 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-05-30T16:03:51.475Z,1338393831.475 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-05-30T16:03:51.605Z,1338393831.605 [BuoyancyServo] Loaded
2012-05-30T16:03:51.605Z,1338393831.605 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-05-30T16:03:51.613Z,1338393831.612 [ElevatorServo] Loaded
2012-05-30T16:03:51.613Z,1338393831.613 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2012-05-30T16:03:51.619Z,1338393831.619 [MassServo] Loaded
2012-05-30T16:03:51.620Z,1338393831.620 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2012-05-30T16:03:51.626Z,1338393831.626 [RudderServo] Loaded
2012-05-30T16:03:51.627Z,1338393831.627 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-05-30T16:03:51.633Z,1338393831.633 [ThrusterServo] Loaded
2012-05-30T16:03:51.634Z,1338393831.634 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-05-30T16:03:51.634Z,1338393831.634 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-05-30T16:03:51.635Z,1338393831.635 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-05-30T16:03:51.650Z,1338393831.650 [DepthRateCalculator] Loaded
2012-05-30T16:03:51.650Z,1338393831.650 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-05-30T16:03:51.666Z,1338393831.666 [NavChart] Loaded
2012-05-30T16:03:51.666Z,1338393831.666 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-05-30T16:03:51.672Z,1338393831.672 [PitchRateCalculator] Loaded
2012-05-30T16:03:51.672Z,1338393831.672 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-05-30T16:03:51.678Z,1338393831.678 [SpeedCalculator] Loaded
2012-05-30T16:03:51.678Z,1338393831.678 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-05-30T16:03:51.693Z,1338393831.693 [TempGradientCalculator] Loaded
2012-05-30T16:03:51.693Z,1338393831.693 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-05-30T16:03:51.699Z,1338393831.699 [YawRateCalculator] Loaded
2012-05-30T16:03:51.699Z,1338393831.699 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-05-30T16:03:51.729Z,1338393831.729 [Navigation] Loaded
2012-05-30T16:03:51.729Z,1338393831.730 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-05-30T16:03:51.730Z,1338393831.730 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-05-30T16:03:51.731Z,1338393831.731 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-05-30T16:03:51.947Z,1338393831.947 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-05-30T16:03:51.947Z,1338393831.947 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-05-30T16:03:51.969Z,1338393831.969 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-05-30T16:03:51.970Z,1338393831.970 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-05-30T16:03:52.010Z,1338393832.010 [VerticalControl](DEBUG): Construct VerticalControl.
2012-05-30T16:03:52.052Z,1338393832.052 [VerticalControl] Loaded
2012-05-30T16:03:52.053Z,1338393832.053 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-05-30T16:03:52.054Z,1338393832.054 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-05-30T16:03:52.073Z,1338393832.073 [HorizontalControl] Loaded
2012-05-30T16:03:52.073Z,1338393832.073 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-05-30T16:03:52.074Z,1338393832.074 [SpeedControl](DEBUG): Construct SpeedControl.
2012-05-30T16:03:52.076Z,1338393832.076 [SpeedControl] Loaded
2012-05-30T16:03:52.076Z,1338393832.076 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-05-30T16:03:52.077Z,1338393832.077 [LoopControl](DEBUG): Construct LoopControl.
2012-05-30T16:03:52.077Z,1338393832.077 [LoopControl] Loaded
2012-05-30T16:03:52.078Z,1338393832.078 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-05-30T16:03:52.078Z,1338393832.078 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-05-30T16:03:52.079Z,1338393832.079 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-05-30T16:03:52.084Z,1338393832.084 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-05-30T16:03:52.089Z,1338393832.089 [AsyncPiEstimator] Loaded
2012-05-30T16:03:52.089Z,1338393832.089 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-05-30T16:03:52.090Z,1338393832.090 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 1078998240
2012-05-30T16:03:52.091Z,1338393832.091 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-05-30T16:03:52.091Z,1338393832.091 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-05-30T16:03:52.184Z,1338393832.184 [AHRS_sp3003D] Loaded
2012-05-30T16:03:52.184Z,1338393832.184 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-05-30T16:03:52.433Z,1338393832.433 [Batt_Ocean_Server] Loaded
2012-05-30T16:03:52.433Z,1338393832.434 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2012-05-30T16:03:52.446Z,1338393832.446 [Depth_Keller] Loaded
2012-05-30T16:03:52.446Z,1338393832.446 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2012-05-30T16:03:52.451Z,1338393832.451 [DropWeight] Loaded
2012-05-30T16:03:52.452Z,1338393832.452 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2012-05-30T16:03:52.547Z,1338393832.547 [DVL_micro] Loaded
2012-05-30T16:03:52.547Z,1338393832.547 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2012-05-30T16:03:52.625Z,1338393832.625 [NAL9601] Loaded
2012-05-30T16:03:52.626Z,1338393832.625 [ComponentRegistry](DEBUG): SyncComponent "NAL9601" handled in the control thread.
2012-05-30T16:03:52.674Z,1338393832.674 [Onboard] Loaded
2012-05-30T16:03:52.674Z,1338393832.674 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-05-30T16:03:52.680Z,1338393832.680 [Radio_Freewave] Loaded
2012-05-30T16:03:52.681Z,1338393832.681 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2012-05-30T16:03:52.681Z,1338393832.681 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-05-30T16:03:52.682Z,1338393832.682 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-05-30T16:03:52.711Z,1338393832.711 [Aanderaa_O2] Loaded
2012-05-30T16:03:52.712Z,1338393832.712 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2012-05-30T16:03:52.746Z,1338393832.746 [CTD_NeilBrown] Loaded
2012-05-30T16:03:52.746Z,1338393832.746 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2012-05-30T16:03:52.747Z,1338393832.747 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 1079649504
2012-05-30T16:03:52.776Z,1338393832.776 [WetLabsBB2FL] Loaded
2012-05-30T16:03:52.777Z,1338393832.777 [ComponentRegistry](DEBUG): SyncComponent "WetLabsBB2FL" handled in the control thread.
2012-05-30T16:03:52.777Z,1338393832.777 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-05-30T16:03:52.780Z,1338393832.780 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-05-30T16:03:52.780Z,1338393832.780 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-05-30T16:03:52.786Z,1338393832.786 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-05-30T16:03:52.787Z,1338393832.787 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 1079846112
2012-05-30T16:03:52.787Z,1338393832.787 [Supervisor](DEBUG): Running supervisor.
2012-05-30T16:03:52.790Z,1338393832.790 [controlThread](DEBUG): Initializing ControlThread
2012-05-30T16:03:52.791Z,1338393832.791 [InternalSim](DEBUG):  InternalSim initializing...
2012-05-30T16:03:52.826Z,1338393832.826 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-05-30T16:03:52.827Z,1338393832.827 [SBIT](INFO): Initialize SBIT Component.
2012-05-30T16:03:52.828Z,1338393832.828 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 9656 $
2012-05-30T16:03:52.828Z,1338393832.828 [IBIT](INFO): Initialize IBIT Component.
2012-05-30T16:03:52.839Z,1338393832.839 [CBIT](DEBUG): Initialize CBIT Component.
2012-05-30T16:03:52.839Z,1338393832.839 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2012-05-30T16:03:52.840Z,1338393832.840 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-05-30T16:03:52.872Z,1338393832.872 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-05-30T16:03:52.872Z,1338393832.872 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-05-30T16:03:52.873Z,1338393832.873 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-05-30T16:03:52.873Z,1338393832.873 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-05-30T16:03:52.873Z,1338393832.874 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-05-30T16:03:52.875Z,1338393832.875 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-05-30T16:03:52.875Z,1338393832.875 [Navigation](DEBUG): Initializing Navigation.
2012-05-30T16:03:52.876Z,1338393832.876 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-05-30T16:03:52.878Z,1338393832.878 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-05-30T16:03:52.878Z,1338393832.878 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-05-30T16:03:52.879Z,1338393832.879 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-05-30T16:03:52.950Z,1338393832.950 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-05-30T16:03:52.955Z,1338393832.955 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2012-05-30T16:03:52.960Z,1338393832.960 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2012-05-30T16:03:52.964Z,1338393832.964 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2012-05-30T16:03:52.968Z,1338393832.968 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2012-05-30T16:03:52.969Z,1338393832.968 [NavChartDb](INFO): Creating index for Soundings
2012-05-30T16:03:52.972Z,1338393832.972 [NavChartDb](INFO): Creating index for Contour 0p0
2012-05-30T16:03:52.974Z,1338393832.974 [NavChartDb](INFO): Creating index for Contour 1p8
2012-05-30T16:03:52.976Z,1338393832.976 [NavChartDb](INFO): Creating index for Contour 3p6
2012-05-30T16:03:52.978Z,1338393832.978 [NavChartDb](INFO): Creating index for Contour 5p4
2012-05-30T16:03:52.980Z,1338393832.980 [NavChartDb](INFO): Creating index for Contour 9p1
2012-05-30T16:03:52.982Z,1338393832.982 [NavChartDb](INFO): Creating index for Contour 10p9
2012-05-30T16:03:52.986Z,1338393832.986 [NavChartDb](INFO): Creating index for Contour 18p2
2012-05-30T16:03:52.988Z,1338393832.988 [NavChartDb](INFO): Creating index for Contour 36p5
2012-05-30T16:03:52.990Z,1338393832.990 [NavChartDb](INFO): Creating index for Contour 54p8
2012-05-30T16:03:52.993Z,1338393832.993 [NavChartDb](INFO): Creating index for Contour 73p1
2012-05-30T16:03:52.995Z,1338393832.995 [NavChartDb](INFO): Creating index for Contour 91p4
2012-05-30T16:03:52.997Z,1338393832.997 [NavChartDb](INFO): Creating index for Contour 182p8
2012-05-30T16:03:52.999Z,1338393832.999 [NavChartDb](INFO): Creating index for Contour 365p7
2012-05-30T16:03:53.001Z,1338393833.000 [NavChartDb](INFO): Creating index for Contour 548p6
2012-05-30T16:03:53.002Z,1338393833.003 [NavChartDb](INFO): Creating index for Contour 731p5
2012-05-30T16:03:53.004Z,1338393833.004 [NavChartDb](INFO): Creating index for Contour 914p4
2012-05-30T16:03:53.006Z,1338393833.006 [NavChartDb](INFO): Creating index for Contour 1097p2
2012-05-30T16:03:53.009Z,1338393833.009 [NavChartDb](INFO): Creating index for Contour 1280p1
2012-05-30T16:03:53.011Z,1338393833.011 [NavChartDb](INFO): Creating index for Contour 1463p0
2012-05-30T16:03:53.013Z,1338393833.013 [NavChartDb](INFO): Creating index for Contour 1645p9
2012-05-30T16:03:53.014Z,1338393833.014 [NavChartDb](INFO): Creating index for Contour 1828p8
2012-05-30T16:03:53.016Z,1338393833.016 [NavChartDb](INFO): Creating index for Contour 2011p6
2012-05-30T16:03:53.018Z,1338393833.018 [NavChartDb](INFO): Creating index for Contour 2194p5
2012-05-30T16:03:53.020Z,1338393833.020 [NavChartDb](INFO): Creating index for Contour 2377p4
2012-05-30T16:03:53.022Z,1338393833.022 [NavChartDb](INFO): Creating index for Contour 2560p3
2012-05-30T16:03:53.024Z,1338393833.024 [NavChartDb](INFO): Creating index for Contour 2743p2
2012-05-30T16:03:53.026Z,1338393833.026 [NavChartDb](INFO): Creating index for Contour 2926p0
2012-05-30T16:03:53.028Z,1338393833.028 [NavChartDb](INFO): Creating index for Contour 3108p9
2012-05-30T16:03:53.030Z,1338393833.030 [NavChartDb](INFO): Creating index for Contour 3291p8
2012-05-30T16:03:53.032Z,1338393833.032 [NavChartDb](INFO): Creating index for Contour 3474p7
2012-05-30T16:03:53.034Z,1338393833.034 [NavChartDb](INFO): Creating index for Contour 3657p6
2012-05-30T16:03:54.439Z,1338393834.439 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2012-05-30T16:03:54.444Z,1338393834.444 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-05-30T16:03:54.454Z,1338393834.454 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-30T16:03:54.463Z,1338393834.463 [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-05-30T16:03:54.464Z,1338393834.464 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-05-30T16:03:54.490Z,1338393834.490 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2012-05-30T16:03:54.493Z,1338393834.493 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-05-30T16:03:54.500Z,1338393834.500 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-30T16:03:54.507Z,1338393834.507 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-05-30T16:03:54.511Z,1338393834.510 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-30T16:03:54.516Z,1338393834.516 [Default:Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-05-30T16:03:54.525Z,1338393834.525 [Default:D.SetSpeed](DEBUG): Construct.
2012-05-30T16:03:54.528Z,1338393834.528 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-30T16:03:54.532Z,1338393834.532 [Default:F.Wait](DEBUG): Construct Wait.
2012-05-30T16:03:54.536Z,1338393834.536 [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-05-30T16:03:54.541Z,1338393834.541 [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-05-30T16:03:54.560Z,1338393834.560 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-05-30T16:03:54.670Z,1338393834.670 [DVL_micro](DEBUG): Initializing DVL_micro.
2012-05-30T16:03:54.691Z,1338393834.691 [Radio_Freewave](INFO): Powering up
2012-05-30T16:03:54.703Z,1338393834.703 [WetLabsBB2FL](INFO): Powering down
2012-05-30T16:03:54.773Z,1338393834.773 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-05-30T16:03:54.775Z,1338393834.775 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-05-30T16:03:54.784Z,1338393834.783 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-05-30T16:03:54.784Z,1338393834.784 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-05-30T16:03:54.793Z,1338393834.793 [MassServo](DEBUG): Initializing EZServoServo.
2012-05-30T16:03:54.794Z,1338393834.794 [MassServo](DEBUG): Initializing MassServo.
2012-05-30T16:03:54.801Z,1338393834.801 [RudderServo](DEBUG): Initializing EZServoServo.
2012-05-30T16:03:54.802Z,1338393834.802 [RudderServo](DEBUG): Initializing RudderServo.
2012-05-30T16:03:54.810Z,1338393834.810 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-05-30T16:03:54.811Z,1338393834.811 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-05-30T16:03:57.445Z,1338393837.445 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items
2012-05-30T16:03:57.445Z,1338393837.445 [DVL_micro](ERROR): Failed to parse DVL response
2012-05-30T16:03:57.445Z,1338393837.445 [DVL_micro] Data Fault, FailCount= 1
2012-05-30T16:03:57.445Z,1338393837.445 [DVL_micro](ERROR): Data Fault
2012-05-30T16:03:57.468Z,1338393837.468 [CBIT](ERROR): Data Fault in component: DVL_micro
2012-05-30T16:03:57.863Z,1338393837.863 [DVL_micro](INFO): Powering down
2012-05-30T16:03:57.865Z,1338393837.865 [NAL9601](INFO): Powering up NAL9601
2012-05-30T16:03:57.888Z,1338393837.888 [CBIT](INFO): Clearing failed state for component DVL_micro
2012-05-30T16:03:57.888Z,1338393837.888 [DVL_micro] No Fault, FailCount= 1
2012-05-30T16:03:58.254Z,1338393838.254 [DVL_micro](DEBUG): Initializing DVL_micro.
2012-05-30T16:03:58.759Z,1338393838.759 [Aanderaa_O2](INFO): Powering down
2012-05-30T16:03:59.044Z,1338393839.044 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items
2012-05-30T16:03:59.045Z,1338393839.045 [DVL_micro](ERROR): Failed to parse DVL response
2012-05-30T16:03:59.045Z,1338393839.045 [DVL_micro] Data Fault, FailCount= 2
2012-05-30T16:03:59.045Z,1338393839.045 [DVL_micro](ERROR): Data Fault
2012-05-30T16:03:59.085Z,1338393839.085 [CBIT](ERROR): Data Fault in component: DVL_micro
2012-05-30T16:03:59.452Z,1338393839.452 [DVL_micro](INFO): Powering down
2012-05-30T16:03:59.621Z,1338393839.621 [CBIT](INFO): Clearing failed state for component DVL_micro
2012-05-30T16:03:59.621Z,1338393839.621 [DVL_micro] No Fault, FailCount= 2
2012-05-30T16:03:59.886Z,1338393839.886 [DVL_micro](DEBUG): Initializing DVL_micro.
2012-05-30T16:04:00.656Z,1338393840.657 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items
2012-05-30T16:04:00.657Z,1338393840.657 [DVL_micro](ERROR): Failed to parse DVL response
2012-05-30T16:04:00.657Z,1338393840.657 [DVL_micro] Data Fault, FailCount= 3
2012-05-30T16:04:00.657Z,1338393840.657 [DVL_micro](ERROR): Data Fault
2012-05-30T16:04:00.702Z,1338393840.702 [CBIT](ERROR): Data Fault in component: DVL_micro
2012-05-30T16:04:01.072Z,1338393841.072 [DVL_micro](INFO): Powering down
2012-05-30T16:04:01.115Z,1338393841.115 [CBIT](INFO): Clearing failed state for component DVL_micro
2012-05-30T16:04:01.115Z,1338393841.115 [DVL_micro] No Fault, FailCount= 3
2012-05-30T16:04:01.459Z,1338393841.459 [DVL_micro](DEBUG): Initializing DVL_micro.
2012-05-30T16:04:02.256Z,1338393842.256 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items
2012-05-30T16:04:02.257Z,1338393842.257 [DVL_micro](ERROR): Failed to parse DVL response
2012-05-30T16:04:02.257Z,1338393842.257 [DVL_micro] Data Fault, FailCount= 4
2012-05-30T16:04:02.257Z,1338393842.257 [DVL_micro](ERROR): Data Fault
2012-05-30T16:04:02.398Z,1338393842.398 [CBIT](ERROR): Data Fault in component: DVL_micro
2012-05-30T16:04:02.652Z,1338393842.652 [DVL_micro](INFO): Powering down
2012-05-30T16:04:02.675Z,1338393842.675 [CBIT](INFO): Clearing failed state for component DVL_micro
2012-05-30T16:04:02.675Z,1338393842.675 [DVL_micro] No Fault, FailCount= 4
2012-05-30T16:04:03.058Z,1338393843.058 [DVL_micro](DEBUG): Initializing DVL_micro.
2012-05-30T16:04:03.855Z,1338393843.855 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items
2012-05-30T16:04:03.856Z,1338393843.856 [DVL_micro](ERROR): Failed to parse DVL response
2012-05-30T16:04:03.856Z,1338393843.856 [DVL_micro] Data Fault, FailCount= 5
2012-05-30T16:04:03.856Z,1338393843.856 [DVL_micro](ERROR): Data Fault
2012-05-30T16:04:03.877Z,1338393843.877 [CBIT](ERROR): Data Fault in component: DVL_micro
2012-05-30T16:04:03.878Z,1338393843.878 [CBIT](CRITICAL): Data Fault in component: DVL_micro
2012-05-30T16:04:04.271Z,1338393844.271 [DVL_micro](INFO): Powering down
2012-05-30T16:04:08.265Z,1338393848.265 [SBIT](IMPORTANT): Beginning Startup BIT
2012-05-30T16:04:08.268Z,1338393848.268 [CBIT](IMPORTANT): Beginning GF scan
2012-05-30T16:04:34.488Z,1338393874.488 [CBIT](IMPORTANT): No ground fault detected
2012-05-30T16:04:39.286Z,1338393879.286 [SBIT](FAULT): Elevator: EXPECTED:-15.000000 ACTUAL:-14.832867
2012-05-30T16:04:39.286Z,1338393879.286 [SBIT](FAULT): Control surface position failure.
2012-05-30T16:04:49.973Z,1338393889.973 [SBIT](FAULT): Rudder: EXPECTED:0.000000 ACTUAL:-0.261731
2012-05-30T16:04:49.973Z,1338393889.973 [SBIT](FAULT): Control surface position failure.
2012-05-30T16:04:50.432Z,1338393890.432 [SBIT](CRITICAL): SBIT FAILED
2012-05-30T16:04:50.720Z,1338393890.720 [MissionManager](IMPORTANT): Started mission Startup
2012-05-30T16:04:50.720Z,1338393890.720 [Startup] Running Loop=1
2012-05-30T16:04:50.720Z,1338393890.720 [Startup](INFO): Aggregate::initialize Startup
2012-05-30T16:04:50.720Z,1338393890.720 [Startup:A.GoToSurface] Running Loop=1
2012-05-30T16:04:50.720Z,1338393890.720 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T16:04:50.726Z,1338393890.726 [Startup:StartupSatComms] Running Loop=1
2012-05-30T16:04:50.727Z,1338393890.727 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2012-05-30T16:04:50.727Z,1338393890.727 [Startup:StartupSatComms:A] Running Loop=1
2012-05-30T16:04:51.120Z,1338393891.120 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-05-30T16:05:03.587Z,1338393903.587 [NAL9601](INFO): NAL9601 initialized
2012-05-30T16:05:04.712Z,1338393904.712 [NAL9601](IMPORTANT): GPS fix at: 1338393887.00
2012-05-30T16:05:04.726Z,1338393904.726 [Startup:StartupSatComms:A] Stopped
2012-05-30T16:05:04.726Z,1338393904.726 [Startup:StartupSatComms:B] Running Loop=1
2012-05-30T16:05:05.125Z,1338393905.125 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-05-30T16:05:25.716Z,1338393925.716 [NAL9601](INFO): SBD MO Status=1, MOMSN=6905, MT Status=0, MTMSN=0
2012-05-30T16:05:25.839Z,1338393925.839 [NAL9601](INFO): Sent 189 bytes from file Logs/20120530T153324/shore0007.lzma
2012-05-30T16:05:25.839Z,1338393925.839 [NAL9601](INFO): Packets left to send: 0
2012-05-30T16:05:25.840Z,1338393925.841 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000000
2012-05-30T16:05:36.845Z,1338393936.845 [NAL9601](INFO): SBD MO Status=1, MOMSN=6906, MT Status=0, MTMSN=0
2012-05-30T16:05:37.023Z,1338393937.023 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0000.lzma
2012-05-30T16:05:37.023Z,1338393937.023 [NAL9601](INFO): Packets left to send: 1
2012-05-30T16:05:37.024Z,1338393937.024 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000001
2012-05-30T16:05:45.805Z,1338393945.805 [NAL9601](INFO): SBD MO Status=1, MOMSN=6907, MT Status=0, MTMSN=0
2012-05-30T16:05:46.007Z,1338393946.007 [NAL9601](INFO): Sent 314 bytes from file Logs/20120530T160348/shore0000.lzma
2012-05-30T16:05:46.007Z,1338393946.007 [NAL9601](INFO): Packets left to send: 0
2012-05-30T16:05:46.008Z,1338393946.008 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000002
2012-05-30T16:05:52.605Z,1338393952.605 [NAL9601](INFO): SBD MO Status=0, MOMSN=6908, MT Status=0, MTMSN=0
2012-05-30T16:05:52.821Z,1338393952.821 [Startup:StartupSatComms:B] Stopped
2012-05-30T16:05:52.821Z,1338393952.821 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2012-05-30T16:05:52.821Z,1338393952.821 [Startup:StartupSatComms] Stopped
2012-05-30T16:05:52.821Z,1338393952.821 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2012-05-30T16:05:52.829Z,1338393952.829 [Startup](INFO): Completed Startup
2012-05-30T16:05:52.829Z,1338393952.829 [Startup] Stopped
2012-05-30T16:05:52.829Z,1338393952.829 [Startup](INFO): Aggregate::uninitialize Startup
2012-05-30T16:05:52.829Z,1338393952.829 [Startup:A.GoToSurface] Stopped
2012-05-30T16:05:52.829Z,1338393952.829 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T16:05:53.100Z,1338393953.100 [MissionManager](IMPORTANT): Started mission Default
2012-05-30T16:05:53.100Z,1338393953.100 [Default] Running Loop=1
2012-05-30T16:05:53.100Z,1338393953.100 [Default](INFO): Aggregate::initialize Default
2012-05-30T16:05:53.100Z,1338393953.100 [Default:D.SetSpeed] Running Loop=1
2012-05-30T16:05:53.100Z,1338393953.100 [Default:D.SetSpeed](DEBUG): Initialize.
2012-05-30T16:05:53.101Z,1338393953.101 [Default:E.GoToSurface] Running Loop=1
2012-05-30T16:05:53.101Z,1338393953.101 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T16:05:53.101Z,1338393953.101 [Default:Iridium] Running Loop=1
2012-05-30T16:05:53.101Z,1338393953.101 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-30T16:05:53.101Z,1338393953.101 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-30T16:05:53.101Z,1338393953.101 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-30T16:05:53.101Z,1338393953.102 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-30T16:05:53.102Z,1338393953.102 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T16:05:53.102Z,1338393953.102 [Default:E.GoToSurface] Running Loop=1
2012-05-30T16:05:53.116Z,1338393953.116 [Default:D.SetSpeed] Running Loop=1
2012-05-30T16:05:53.134Z,1338393953.134 [Default:Iridium:B.GoToSurface] Stopped
2012-05-30T16:05:53.134Z,1338393953.134 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T16:05:53.134Z,1338393953.134 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-30T16:05:53.134Z,1338393953.134 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-30T16:05:53.147Z,1338393953.147 [Default:GPS] Running Loop=1
2012-05-30T16:05:53.147Z,1338393953.148 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-30T16:05:53.148Z,1338393953.148 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-30T16:05:53.148Z,1338393953.148 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-30T16:05:53.148Z,1338393953.148 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-30T16:05:53.148Z,1338393953.148 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T16:05:53.158Z,1338393953.158 [Default:GPS:B.GoToSurface] Stopped
2012-05-30T16:05:53.158Z,1338393953.158 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T16:05:53.158Z,1338393953.158 [Default:GPS:Read_GPS] Running Loop=1
2012-05-30T16:05:53.158Z,1338393953.158 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-30T16:05:53.534Z,1338393953.534 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-05-30T16:05:53.537Z,1338393953.537 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-05-30T16:05:55.019Z,1338393955.019 [NAL9601](IMPORTANT): GPS fix at: 1338393937.00
2012-05-30T16:05:55.054Z,1338393955.054 [Default:GPS:Read_GPS] Stopped
2012-05-30T16:05:55.054Z,1338393955.054 [Default:GPS:D] Running Loop=1
2012-05-30T16:05:55.448Z,1338393955.448 [Default:GPS:D] Stopped
2012-05-30T16:05:55.449Z,1338393955.449 [Default:GPS](INFO): Completed Default:GPS
2012-05-30T16:05:55.449Z,1338393955.449 [Default:GPS] Stopped
2012-05-30T16:05:55.449Z,1338393955.449 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-30T16:05:55.449Z,1338393955.449 [Default:GPS:A.SetSpeed] Stopped
2012-05-30T16:05:55.449Z,1338393955.449 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T16:06:10.317Z,1338393970.317 [NAL9601](INFO): SBD MO Status=1, MOMSN=6909, MT Status=0, MTMSN=0
2012-05-30T16:06:10.471Z,1338393970.471 [NAL9601](INFO): Sent 137 bytes from file Logs/20120530T160348/shore0001.lzma
2012-05-30T16:06:10.471Z,1338393970.471 [NAL9601](INFO): Packets left to send: 0
2012-05-30T16:06:10.472Z,1338393970.472 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000003
2012-05-30T16:06:18.705Z,1338393978.705 [NAL9601](INFO): SBD MO Status=0, MOMSN=6910, MT Status=0, MTMSN=0
2012-05-30T16:06:18.879Z,1338393978.879 [Default:Iridium:Read_Iridium] Stopped
2012-05-30T16:06:18.879Z,1338393978.879 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-30T16:06:18.879Z,1338393978.879 [Default:Iridium] Stopped
2012-05-30T16:06:18.879Z,1338393978.879 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-30T16:06:18.879Z,1338393978.879 [Default:Iridium:A.SetSpeed] Stopped
2012-05-30T16:06:18.880Z,1338393978.880 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T16:06:18.880Z,1338393978.880 [Default:F.Wait] Running Loop=1
2012-05-30T16:06:18.880Z,1338393978.880 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-05-30T16:06:29.433Z,1338393989.433 [NAL9601](INFO): Powering down
2012-05-30T16:11:19.313Z,1338394279.313 [Default:CallIridium] Running Loop=1
2012-05-30T16:11:19.314Z,1338394279.314 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-30T16:11:19.314Z,1338394279.314 [Default:CallIridium:A] Running Loop=1
2012-05-30T16:11:19.316Z,1338394279.316 [Default:CallIridium:A] Stopped
2012-05-30T16:11:19.316Z,1338394279.316 [Default:CallIridium:B] Running Loop=1
2012-05-30T16:11:19.316Z,1338394279.316 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-30T16:11:24.406Z,1338394284.406 [Default:Iridium] Running Loop=1
2012-05-30T16:11:24.406Z,1338394284.406 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-30T16:11:24.406Z,1338394284.406 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-30T16:11:24.406Z,1338394284.406 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-30T16:11:24.407Z,1338394284.407 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-30T16:11:24.407Z,1338394284.407 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T16:11:24.408Z,1338394284.408 [Default:Iridium:B.GoToSurface] Stopped
2012-05-30T16:11:24.408Z,1338394284.408 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T16:11:24.408Z,1338394284.408 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-30T16:11:24.408Z,1338394284.408 [Default:GPS] Running Loop=1
2012-05-30T16:11:24.408Z,1338394284.408 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-30T16:11:24.408Z,1338394284.408 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-30T16:11:24.408Z,1338394284.408 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-30T16:11:24.409Z,1338394284.409 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-30T16:11:24.409Z,1338394284.409 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T16:11:24.410Z,1338394284.410 [Default:GPS:B.GoToSurface] Stopped
2012-05-30T16:11:24.410Z,1338394284.410 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T16:11:24.410Z,1338394284.410 [Default:GPS:Read_GPS] Running Loop=1
2012-05-30T16:11:25.008Z,1338394285.008 [NAL9601](INFO): Powering up
2012-05-30T16:12:30.731Z,1338394350.731 [NAL9601](INFO): NAL9601 initialized
2012-05-30T16:12:31.835Z,1338394351.835 [NAL9601](IMPORTANT): GPS fix at: 1338394334.00
2012-05-30T16:12:31.851Z,1338394351.851 [Default:GPS:Read_GPS] Stopped
2012-05-30T16:12:31.851Z,1338394351.851 [Default:GPS:D] Running Loop=1
2012-05-30T16:12:32.240Z,1338394352.240 [Default:GPS:D] Stopped
2012-05-30T16:12:32.240Z,1338394352.240 [Default:GPS](INFO): Completed Default:GPS
2012-05-30T16:12:32.240Z,1338394352.240 [Default:GPS] Stopped
2012-05-30T16:12:32.240Z,1338394352.240 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-30T16:12:32.241Z,1338394352.240 [Default:GPS:A.SetSpeed] Stopped
2012-05-30T16:12:32.241Z,1338394352.241 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T16:14:04.171Z,1338394444.171 [CBIT](INFO): Clearing failed count for component DVL_micro
2012-05-30T16:14:04.171Z,1338394444.171 [DVL_micro] No Fault, FailCount= 5
2012-05-30T16:14:04.551Z,1338394444.551 [DVL_micro](DEBUG): Initializing DVL_micro.
2012-05-30T16:14:17.746Z,1338394457.746 [NAL9601](INFO): SBD MO Status=2, MOMSN=6911, MT Status=2, MTMSN=0
2012-05-30T16:14:17.746Z,1338394457.746 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-30T16:14:40.230Z,1338394480.230 [NAL9601](INFO): SBD MO Status=1, MOMSN=6911, MT Status=0, MTMSN=0
2012-05-30T16:14:40.419Z,1338394480.419 [NAL9601](INFO): Sent 261 bytes from file Logs/20120530T160348/shore0002.lzma
2012-05-30T16:14:40.419Z,1338394480.419 [NAL9601](INFO): Packets left to send: 0
2012-05-30T16:14:40.420Z,1338394480.420 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000004
2012-05-30T16:14:48.625Z,1338394488.625 [NAL9601](INFO): SBD MO Status=0, MOMSN=6912, MT Status=0, MTMSN=0
2012-05-30T16:14:48.822Z,1338394488.822 [Default:Iridium:Read_Iridium] Stopped
2012-05-30T16:14:48.822Z,1338394488.822 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-30T16:14:48.822Z,1338394488.822 [Default:Iridium] Stopped
2012-05-30T16:14:48.822Z,1338394488.822 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-30T16:14:48.822Z,1338394488.822 [Default:Iridium:A.SetSpeed] Stopped
2012-05-30T16:14:48.822Z,1338394488.822 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T16:14:49.038Z,1338394489.038 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-30T16:14:49.038Z,1338394489.038 [Default:CallIridium:B] Stopped
2012-05-30T16:14:49.039Z,1338394489.039 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-30T16:14:49.039Z,1338394489.039 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-30T16:14:49.039Z,1338394489.039 [Default:CallIridium] Stopped
2012-05-30T16:14:49.039Z,1338394489.039 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-30T16:14:59.195Z,1338394499.195 [NAL9601](INFO): Powering down
2012-05-30T16:15:24.155Z,1338394524.155 [Depth_Keller](ERROR): Pressure reading out of range: 1830.917603 decibar
2012-05-30T16:15:28.664Z,1338394528.664 [CTD_NeilBrown](ERROR): Pressure reading out of range: -13.680000 decibar
2012-05-30T16:15:54.151Z,1338394554.151 [Depth_Keller](ERROR): Pressure reading out of range: 1830.991821 decibar
2012-05-30T16:15:58.035Z,1338394558.035 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.037390 psu
2012-05-30T16:15:58.036Z,1338394558.036 [CTD_NeilBrown](ERROR): Pressure reading out of range: -229.370010 decibar
2012-05-30T16:18:24.192Z,1338394704.192 [Depth_Keller](ERROR): Pressure reading out of range: 1831.036255 decibar
2012-05-30T16:18:28.507Z,1338394708.507 [CTD_NeilBrown](ERROR): Pressure reading out of range: -13.670000 decibar
2012-05-30T16:19:14.195Z,1338394754.195 [Depth_Keller](ERROR): Pressure reading out of range: 1830.919312 decibar
2012-05-30T16:19:24.153Z,1338394764.153 [Depth_Keller](ERROR): Pressure reading out of range: 1830.928101 decibar
2012-05-30T16:19:27.635Z,1338394767.635 [CTD_NeilBrown](ERROR): Pressure reading out of range: -241.830002 decibar
2012-05-30T16:19:34.146Z,1338394774.146 [Depth_Keller](ERROR): Pressure reading out of range: 1830.862671 decibar
2012-05-30T16:19:49.235Z,1338394789.235 [Default:CallIridium] Running Loop=1
2012-05-30T16:19:49.235Z,1338394789.235 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-30T16:19:49.235Z,1338394789.236 [Default:CallIridium:A] Running Loop=1
2012-05-30T16:19:49.236Z,1338394789.236 [Default:CallIridium:A] Stopped
2012-05-30T16:19:49.236Z,1338394789.236 [Default:CallIridium:B] Running Loop=1
2012-05-30T16:19:49.236Z,1338394789.236 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-30T16:19:54.150Z,1338394794.150 [Depth_Keller](ERROR): Pressure reading out of range: 1830.887085 decibar
2012-05-30T16:19:54.171Z,1338394794.171 [Default:Iridium] Running Loop=1
2012-05-30T16:19:54.171Z,1338394794.171 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-30T16:19:54.171Z,1338394794.171 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-30T16:19:54.171Z,1338394794.171 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-30T16:19:54.171Z,1338394794.171 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-30T16:19:54.171Z,1338394794.171 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T16:19:54.172Z,1338394794.172 [Default:Iridium:B.GoToSurface] Stopped
2012-05-30T16:19:54.173Z,1338394794.173 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T16:19:54.173Z,1338394794.173 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-30T16:19:54.173Z,1338394794.173 [Default:GPS] Running Loop=1
2012-05-30T16:19:54.173Z,1338394794.173 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-30T16:19:54.173Z,1338394794.173 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-30T16:19:54.173Z,1338394794.173 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-30T16:19:54.174Z,1338394794.174 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-30T16:19:54.174Z,1338394794.174 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T16:19:54.175Z,1338394794.175 [Default:GPS:B.GoToSurface] Stopped
2012-05-30T16:19:54.175Z,1338394794.175 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T16:19:54.175Z,1338394794.175 [Default:GPS:Read_GPS] Running Loop=1
2012-05-30T16:19:54.823Z,1338394794.823 [NAL9601](INFO): Powering up
2012-05-30T16:21:00.547Z,1338394860.547 [NAL9601](INFO): NAL9601 initialized
2012-05-30T16:21:01.627Z,1338394861.627 [NAL9601](IMPORTANT): GPS fix at: 1338394845.00
2012-05-30T16:21:01.655Z,1338394861.655 [Default:GPS:Read_GPS] Stopped
2012-05-30T16:21:01.656Z,1338394861.656 [Default:GPS:D] Running Loop=1
2012-05-30T16:21:02.060Z,1338394862.060 [Default:GPS:D] Stopped
2012-05-30T16:21:02.060Z,1338394862.060 [Default:GPS](INFO): Completed Default:GPS
2012-05-30T16:21:02.060Z,1338394862.060 [Default:GPS] Stopped
2012-05-30T16:21:02.060Z,1338394862.060 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-30T16:21:02.060Z,1338394862.060 [Default:GPS:A.SetSpeed] Stopped
2012-05-30T16:21:02.061Z,1338394862.061 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T16:21:34.754Z,1338394894.754 [NAL9601](INFO): SBD MO Status=1, MOMSN=6913, MT Status=0, MTMSN=0
2012-05-30T16:21:34.883Z,1338394894.883 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0003.lzma
2012-05-30T16:21:34.883Z,1338394894.883 [NAL9601](INFO): Packets left to send: 1
2012-05-30T16:21:34.884Z,1338394894.884 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000005
2012-05-30T16:21:58.045Z,1338394918.045 [NAL9601](INFO): SBD MO Status=1, MOMSN=6914, MT Status=0, MTMSN=0
2012-05-30T16:21:58.247Z,1338394918.247 [NAL9601](INFO): Sent 100 bytes from file Logs/20120530T160348/shore0003.lzma
2012-05-30T16:21:58.247Z,1338394918.247 [NAL9601](INFO): Packets left to send: 0
2012-05-30T16:21:58.248Z,1338394918.248 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000006
2012-05-30T16:22:15.250Z,1338394935.250 [NAL9601](INFO): SBD MO Status=2, MOMSN=6915, MT Status=2, MTMSN=0
2012-05-30T16:22:15.250Z,1338394935.250 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-30T16:22:32.246Z,1338394952.246 [NAL9601](INFO): SBD MO Status=2, MOMSN=6915, MT Status=2, MTMSN=0
2012-05-30T16:22:32.246Z,1338394952.246 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-30T16:22:50.072Z,1338394970.072 [NAL9601](INFO): SBD MO Status=2, MOMSN=6915, MT Status=2, MTMSN=0
2012-05-30T16:22:50.073Z,1338394970.073 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-30T16:23:01.510Z,1338394981.510 [NAL9601](INFO): SBD MO Status=0, MOMSN=6915, MT Status=0, MTMSN=0
2012-05-30T16:23:01.671Z,1338394981.671 [Default:Iridium:Read_Iridium] Stopped
2012-05-30T16:23:01.672Z,1338394981.672 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-30T16:23:01.672Z,1338394981.672 [Default:Iridium] Stopped
2012-05-30T16:23:01.672Z,1338394981.672 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-30T16:23:01.672Z,1338394981.672 [Default:Iridium:A.SetSpeed] Stopped
2012-05-30T16:23:01.672Z,1338394981.672 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T16:23:01.923Z,1338394981.923 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-30T16:23:01.923Z,1338394981.923 [Default:CallIridium:B] Stopped
2012-05-30T16:23:01.923Z,1338394981.923 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-30T16:23:01.924Z,1338394981.924 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-30T16:23:01.924Z,1338394981.924 [Default:CallIridium] Stopped
2012-05-30T16:23:01.924Z,1338394981.924 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-30T16:23:07.084Z,1338394987.084 [Depth_Keller](ERROR): Pressure reading out of range: 1830.823364 decibar
2012-05-30T16:23:12.157Z,1338394992.158 [NAL9601](INFO): Powering down
2012-05-30T16:24:47.042Z,1338395087.042 [Radio_Freewave](INFO): Powering down
2012-05-30T16:24:57.066Z,1338395097.066 [Radio_Freewave](INFO): Powering up
2012-05-30T16:25:07.006Z,1338395107.006 [Depth_Keller](ERROR): Pressure reading out of range: 1830.911499 decibar
2012-05-30T16:25:42.028Z,1338395142.028 [Depth_Keller](ERROR): Pressure reading out of range: 1830.819946 decibar
2012-05-30T16:25:46.563Z,1338395146.563 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.037400 psu
2012-05-30T16:25:46.564Z,1338395146.564 [CTD_NeilBrown](ERROR): Pressure reading out of range: -108.850006 decibar
2012-05-30T16:25:52.013Z,1338395152.013 [Depth_Keller](ERROR): Pressure reading out of range: 1830.880981 decibar
2012-05-30T16:25:55.760Z,1338395155.760 [CTD_NeilBrown](ERROR): Pressure reading out of range: -13.710000 decibar
2012-05-30T16:26:12.032Z,1338395172.032 [Depth_Keller](ERROR): Pressure reading out of range: 1830.799805 decibar
2012-05-30T16:26:16.156Z,1338395176.156 [CTD_NeilBrown](ERROR): Pressure reading out of range: -15.680000 decibar
2012-05-30T16:27:02.049Z,1338395222.049 [Depth_Keller](ERROR): Pressure reading out of range: 1830.847778 decibar
2012-05-30T16:27:06.715Z,1338395226.715 [CTD_NeilBrown](ERROR): Bad response: 
-249.63
2012-05-30T16:27:12.056Z,1338395232.056 [Depth_Keller](ERROR): Pressure reading out of range: 1830.838257 decibar
2012-05-30T16:27:15.743Z,1338395235.743 [CTD_NeilBrown](ERROR): Salinity reading out of range: -81.860291 psu
2012-05-30T16:27:15.879Z,1338395235.879 [CTD_NeilBrown](ERROR): Salinity reading out of range: -83.293961 psu
2012-05-30T16:27:15.880Z,1338395235.880 [CTD_NeilBrown](ERROR): Pressure reading out of range: -471.489990 decibar
2012-05-30T16:27:22.076Z,1338395242.076 [Depth_Keller](ERROR): Pressure reading out of range: 1830.810303 decibar
2012-05-30T16:27:42.102Z,1338395262.102 [Depth_Keller](ERROR): Pressure reading out of range: 1830.849609 decibar
2012-05-30T16:28:02.099Z,1338395282.099 [Depth_Keller](ERROR): Pressure reading out of range: 1830.852173 decibar
2012-05-30T16:28:02.115Z,1338395282.115 [Default:CallIridium] Running Loop=1
2012-05-30T16:28:02.115Z,1338395282.115 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-30T16:28:02.116Z,1338395282.116 [Default:CallIridium:A] Running Loop=1
2012-05-30T16:28:02.116Z,1338395282.116 [Default:CallIridium:A] Stopped
2012-05-30T16:28:02.116Z,1338395282.116 [Default:CallIridium:B] Running Loop=1
2012-05-30T16:28:02.116Z,1338395282.116 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-30T16:28:06.248Z,1338395286.248 [CTD_NeilBrown](ERROR): Pressure reading out of range: -13.660000 decibar
2012-05-30T16:28:07.057Z,1338395287.057 [Default:Iridium] Running Loop=1
2012-05-30T16:28:07.057Z,1338395287.057 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-30T16:28:07.058Z,1338395287.057 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-30T16:28:07.058Z,1338395287.058 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-30T16:28:07.058Z,1338395287.058 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-30T16:28:07.058Z,1338395287.058 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T16:28:07.059Z,1338395287.059 [Default:Iridium:B.GoToSurface] Stopped
2012-05-30T16:28:07.059Z,1338395287.059 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T16:28:07.059Z,1338395287.059 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-30T16:28:07.060Z,1338395287.060 [Default:GPS] Running Loop=1
2012-05-30T16:28:07.060Z,1338395287.060 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-30T16:28:07.060Z,1338395287.060 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-30T16:28:07.060Z,1338395287.060 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-30T16:28:07.060Z,1338395287.060 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-30T16:28:07.060Z,1338395287.060 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T16:28:07.061Z,1338395287.061 [Default:GPS:B.GoToSurface] Stopped
2012-05-30T16:28:07.061Z,1338395287.061 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T16:28:07.061Z,1338395287.061 [Default:GPS:Read_GPS] Running Loop=1
2012-05-30T16:28:07.708Z,1338395287.708 [NAL9601](INFO): Powering up
2012-05-30T16:29:13.431Z,1338395353.431 [NAL9601](INFO): NAL9601 initialized
2012-05-30T16:29:14.506Z,1338395354.506 [NAL9601](IMPORTANT): GPS fix at: 1338395346.00
2012-05-30T16:29:14.522Z,1338395354.522 [Default:GPS:Read_GPS] Stopped
2012-05-30T16:29:14.522Z,1338395354.523 [Default:GPS:D] Running Loop=1
2012-05-30T16:29:14.924Z,1338395354.924 [Default:GPS:D] Stopped
2012-05-30T16:29:14.924Z,1338395354.924 [Default:GPS](INFO): Completed Default:GPS
2012-05-30T16:29:14.924Z,1338395354.924 [Default:GPS] Stopped
2012-05-30T16:29:14.925Z,1338395354.925 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-30T16:29:14.925Z,1338395354.925 [Default:GPS:A.SetSpeed] Stopped
2012-05-30T16:29:14.925Z,1338395354.925 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T16:29:32.806Z,1338395372.806 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=6916, MT Status=1, MTMSN=2631
2012-05-30T16:29:32.991Z,1338395372.991 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0004.lzma
2012-05-30T16:29:32.991Z,1338395372.991 [NAL9601](INFO): Packets left to send: 1
2012-05-30T16:29:32.992Z,1338395372.992 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000007
2012-05-30T16:29:33.408Z,1338395373.408 [NAL9601](INFO): Received command:run Transport/transit_3km.xml
2012-05-30T16:29:33.425Z,1338395373.425 [CommandLine](IMPORTANT): got command run ./Missions/Transport/transit_3km.xml
2012-05-30T16:29:33.425Z,1338395373.425 [MissionManager](INFO): Loading Mission: ./Missions/Transport/transit_3km.xml
2012-05-30T16:29:33.482Z,1338395373.482 [MissionManager](INFO): DefineArg transit_3km.ApproachDepth = 10.000000 m
2012-05-30T16:29:33.489Z,1338395373.489 [MissionManager](INFO): DefineArg transit_3km.Wpt1Lat = 36.806966 arcdeg
2012-05-30T16:29:33.503Z,1338395373.503 [MissionManager](INFO): DefineArg transit_3km.Wpt1Lon = -121.824326 arcdeg
2012-05-30T16:29:33.505Z,1338395373.505 [MissionManager](INFO): DefineArg transit_3km.Speed = 1.000000 m/s
2012-05-30T16:29:33.512Z,1338395373.513 [MissionManager](INFO): DefineArg transit_3km.MaxDepth = 20.000000 m
2012-05-30T16:29:33.520Z,1338395373.520 [MissionManager](INFO): DefineArg transit_3km.TimeoutDuration = 240.000000 min
2012-05-30T16:29:33.521Z,1338395373.521 [transit_3km:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-05-30T16:29:33.538Z,1338395373.537 [transit_3km:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-05-30T16:29:33.562Z,1338395373.562 [transit_3km:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2012-05-30T16:29:33.570Z,1338395373.570 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-30T16:29:33.579Z,1338395373.579 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Construct.
2012-05-30T16:29:33.615Z,1338395373.615 [transit_3km:WaypointOne:A.Pitch](DEBUG): Construct.
2012-05-30T16:29:33.620Z,1338395373.620 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Construct.
2012-05-30T16:29:33.623Z,1338395373.623 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Construct Waypoint.
2012-05-30T16:29:33.645Z,1338395373.645 [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-05-30T16:29:33.645Z,1338395373.645 [CommandLine](IMPORTANT): Running ./Missions/Transport/transit_3km.xml
2012-05-30T16:29:33.776Z,1338395373.776 [Default] Stopped
2012-05-30T16:29:33.776Z,1338395373.776 [Default](INFO): Aggregate::uninitialize Default
2012-05-30T16:29:33.776Z,1338395373.776 [Default:Iridium] Stopped
2012-05-30T16:29:33.777Z,1338395373.777 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-30T16:29:33.777Z,1338395373.777 [Default:Iridium:A.SetSpeed] Stopped
2012-05-30T16:29:33.777Z,1338395373.777 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T16:29:33.777Z,1338395373.777 [Default:Iridium:Read_Iridium] Stopped
2012-05-30T16:29:33.777Z,1338395373.777 [Default:CallIridium] Stopped
2012-05-30T16:29:33.777Z,1338395373.777 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-30T16:29:33.777Z,1338395373.777 [Default:CallIridium:B] Stopped
2012-05-30T16:29:33.777Z,1338395373.777 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-30T16:29:33.777Z,1338395373.777 [Default:D.SetSpeed] Stopped
2012-05-30T16:29:33.777Z,1338395373.777 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-05-30T16:29:33.777Z,1338395373.777 [Default:E.GoToSurface] Stopped
2012-05-30T16:29:33.777Z,1338395373.777 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T16:29:33.777Z,1338395373.777 [Default:F.Wait] Stopped
2012-05-30T16:29:33.778Z,1338395373.778 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2012-05-30T16:29:33.778Z,1338395373.778 [MissionManager](IMPORTANT): Started mission transit_3km
2012-05-30T16:29:33.778Z,1338395373.778 [transit_3km] Running Loop=1
2012-05-30T16:29:33.778Z,1338395373.778 [transit_3km](INFO): Aggregate::initialize transit_3km
2012-05-30T16:29:33.778Z,1338395373.778 [transit_3km:A.AltitudeEnvelope] Running Loop=1
2012-05-30T16:29:33.778Z,1338395373.778 [transit_3km:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-05-30T16:29:33.779Z,1338395373.779 [transit_3km:B.DepthEnvelope] Running Loop=1
2012-05-30T16:29:33.779Z,1338395373.779 [transit_3km:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-05-30T16:29:33.780Z,1338395373.780 [transit_3km:C.OffshoreEnvelope] Running Loop=1
2012-05-30T16:29:33.780Z,1338395373.780 [transit_3km:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2012-05-30T16:29:33.780Z,1338395373.780 [transit_3km:SURFACECOMMS] Running Loop=1
2012-05-30T16:29:33.780Z,1338395373.780 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2012-05-30T16:29:33.780Z,1338395373.780 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-05-30T16:29:33.780Z,1338395373.780 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T16:29:33.785Z,1338395373.786 [transit_3km:SURFACECOMMS:B] Running Loop=1
2012-05-30T16:29:33.786Z,1338395373.786 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:B
2012-05-30T16:29:33.786Z,1338395373.786 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-05-30T16:29:33.786Z,1338395373.786 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-05-30T16:29:33.786Z,1338395373.786 [transit_3km:SURFACECOMMS:B:B] Running Loop=1
2012-05-30T16:29:33.786Z,1338395373.786 [transit_3km:C.OffshoreEnvelope] Running Loop=1
2012-05-30T16:29:33.799Z,1338395373.799 [transit_3km:B.DepthEnvelope] Running Loop=1
2012-05-30T16:29:33.804Z,1338395373.804 [transit_3km:A.AltitudeEnvelope] Running Loop=1
2012-05-30T16:29:34.161Z,1338395374.161 [transit_3km:SURFACECOMMS:B:B](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-05-30T16:29:34.162Z,1338395374.162 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-05-30T16:29:35.347Z,1338395375.347 [NAL9601](IMPORTANT): GPS fix at: 1338395367.00
2012-05-30T16:29:35.361Z,1338395375.361 [transit_3km:SURFACECOMMS:B:B] Stopped
2012-05-30T16:29:35.361Z,1338395375.361 [transit_3km:SURFACECOMMS:B:C] Running Loop=1
2012-05-30T16:29:35.768Z,1338395375.768 [transit_3km:SURFACECOMMS:B:C](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-05-30T16:29:52.317Z,1338395392.317 [Radio_Freewave](INFO): Powering down
2012-05-30T16:29:55.473Z,1338395395.473 [NAL9601](INFO): SBD MO Status=2, MOMSN=6917, MT Status=2, MTMSN=0
2012-05-30T16:29:55.473Z,1338395395.473 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-30T16:30:24.621Z,1338395424.621 [Radio_Freewave](INFO): Powering up
2012-05-30T16:30:41.978Z,1338395441.978 [Radio_Freewave](INFO): Powering down
2012-05-30T16:30:50.357Z,1338395450.357 [NAL9601](INFO): SBD MO Status=2, MOMSN=6917, MT Status=2, MTMSN=0
2012-05-30T16:30:50.357Z,1338395450.357 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-30T16:31:03.025Z,1338395463.025 [Radio_Freewave](INFO): Powering up
2012-05-30T16:31:14.864Z,1338395474.864 [Radio_Freewave](INFO): Powering down
2012-05-30T16:31:22.038Z,1338395482.038 [NAL9601](INFO): SBD MO Status=2, MOMSN=6917, MT Status=2, MTMSN=0
2012-05-30T16:31:22.038Z,1338395482.038 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-30T16:31:36.424Z,1338395496.424 [Radio_Freewave](INFO): Powering up
2012-05-30T16:31:46.145Z,1338395506.145 [Radio_Freewave](INFO): Powering down
2012-05-30T16:31:54.189Z,1338395514.189 [NAL9601](INFO): SBD MO Status=2, MOMSN=6917, MT Status=2, MTMSN=0
2012-05-30T16:31:54.189Z,1338395514.189 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-30T16:32:08.360Z,1338395528.360 [Radio_Freewave](INFO): Powering up
2012-05-30T16:32:19.446Z,1338395539.446 [NAL9601](INFO): SBD MO Status=1, MOMSN=6917, MT Status=0, MTMSN=0
2012-05-30T16:32:19.631Z,1338395539.631 [NAL9601](INFO): Sent 93 bytes from file Logs/20120530T160348/shore0004.lzma
2012-05-30T16:32:19.631Z,1338395539.631 [NAL9601](INFO): Packets left to send: 0
2012-05-30T16:32:19.632Z,1338395539.632 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000008
2012-05-30T16:32:22.877Z,1338395542.877 [Radio_Freewave](INFO): Powering down
2012-05-30T16:32:30.023Z,1338395550.023 [NAL9601](INFO): SBD MO Status=2, MOMSN=6918, MT Status=2, MTMSN=0
2012-05-30T16:32:30.023Z,1338395550.023 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-30T16:32:44.425Z,1338395564.425 [Radio_Freewave](INFO): Powering up
2012-05-30T16:32:59.888Z,1338395579.888 [NAL9601](INFO): SBD MO Status=1, MOMSN=6918, MT Status=0, MTMSN=0
2012-05-30T16:33:00.067Z,1338395580.067 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0005.lzma
2012-05-30T16:33:00.067Z,1338395580.067 [NAL9601](INFO): Packets left to send: 1
2012-05-30T16:33:00.068Z,1338395580.068 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000009
2012-05-30T16:33:02.664Z,1338395582.664 [Radio_Freewave](INFO): Powering down
2012-05-30T16:33:08.445Z,1338395588.445 [NAL9601](INFO): SBD MO Status=2, MOMSN=6919, MT Status=2, MTMSN=0
2012-05-30T16:33:08.445Z,1338395588.445 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-30T16:33:23.109Z,1338395603.109 [Radio_Freewave](INFO): Powering up
2012-05-30T16:33:35.194Z,1338395615.194 [NAL9601](INFO): SBD MO Status=1, MOMSN=6919, MT Status=0, MTMSN=0
2012-05-30T16:33:35.315Z,1338395615.315 [NAL9601](INFO): Sent 80 bytes from file Logs/20120530T160348/shore0005.lzma
2012-05-30T16:33:35.315Z,1338395615.315 [NAL9601](INFO): Packets left to send: 0
2012-05-30T16:33:35.316Z,1338395615.316 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000010
2012-05-30T16:33:45.958Z,1338395625.958 [NAL9601](INFO): SBD MO Status=0, MOMSN=6920, MT Status=0, MTMSN=0
2012-05-30T16:33:58.121Z,1338395638.121 [NAL9601](INFO): SBD MO Status=1, MOMSN=6921, MT Status=0, MTMSN=0
2012-05-30T16:33:58.279Z,1338395638.279 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0006.lzma
2012-05-30T16:33:58.279Z,1338395638.279 [NAL9601](INFO): Packets left to send: 1
2012-05-30T16:33:58.280Z,1338395638.280 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000011
2012-05-30T16:34:01.598Z,1338395641.598 [Radio_Freewave](INFO): Powering down
2012-05-30T16:34:07.717Z,1338395647.717 [NAL9601](INFO): SBD MO Status=2, MOMSN=6922, MT Status=2, MTMSN=0
2012-05-30T16:34:07.717Z,1338395647.717 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-30T16:34:21.534Z,1338395661.533 [Radio_Freewave](INFO): Powering up
2012-05-30T16:34:33.669Z,1338395673.669 [NAL9601](INFO): SBD MO Status=1, MOMSN=6922, MT Status=0, MTMSN=0
2012-05-30T16:34:33.823Z,1338395673.823 [NAL9601](INFO): Sent 240 bytes from file Logs/20120530T160348/shore0006.lzma
2012-05-30T16:34:33.823Z,1338395673.823 [NAL9601](INFO): Packets left to send: 0
2012-05-30T16:34:33.824Z,1338395673.824 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000012
2012-05-30T16:34:36.874Z,1338395676.874 [NAL9601](INFO): SBD MO Status=0, MOMSN=6923, MT Status=0, MTMSN=0
2012-05-30T16:34:37.033Z,1338395677.033 [transit_3km:SURFACECOMMS:B:C] Stopped
2012-05-30T16:34:37.033Z,1338395677.033 [transit_3km:SURFACECOMMS:B:D] Running Loop=1
2012-05-30T16:34:37.339Z,1338395677.339 [transit_3km:SURFACECOMMS:B:D](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-05-30T16:34:39.276Z,1338395679.276 [NAL9601](IMPORTANT): GPS fix at: 1338395671.00
2012-05-30T16:34:39.290Z,1338395679.290 [transit_3km:SURFACECOMMS:B:D] Stopped
2012-05-30T16:34:39.290Z,1338395679.290 [transit_3km:SURFACECOMMS:B](INFO): Completed transit_3km:SURFACECOMMS:B
2012-05-30T16:34:39.290Z,1338395679.290 [transit_3km:SURFACECOMMS:B] Stopped
2012-05-30T16:34:39.290Z,1338395679.290 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:B
2012-05-30T16:34:39.290Z,1338395679.290 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-05-30T16:34:39.291Z,1338395679.291 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T16:34:39.291Z,1338395679.291 [transit_3km:SURFACECOMMS](INFO): Completed transit_3km:SURFACECOMMS
2012-05-30T16:34:39.292Z,1338395679.292 [transit_3km:SURFACECOMMS] Stopped
2012-05-30T16:34:39.292Z,1338395679.292 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2012-05-30T16:34:39.292Z,1338395679.292 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2012-05-30T16:34:39.292Z,1338395679.292 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T16:34:39.292Z,1338395679.292 [transit_3km:WaypointOne] Running Loop=1
2012-05-30T16:34:39.292Z,1338395679.292 [transit_3km:WaypointOne](INFO): Aggregate::initialize transit_3km:WaypointOne
2012-05-30T16:34:39.292Z,1338395679.292 [transit_3km:WaypointOne:A.Pitch] Running Loop=1
2012-05-30T16:34:39.292Z,1338395679.292 [transit_3km:WaypointOne:A.Pitch](DEBUG): Initialize.
2012-05-30T16:34:39.292Z,1338395679.292 [transit_3km:WaypointOne:B.SetSpeed] Running Loop=1
2012-05-30T16:34:39.292Z,1338395679.293 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Initialize.
2012-05-30T16:34:39.293Z,1338395679.293 [transit_3km:WaypointOne:WaypointW1.Waypoint] Running Loop=1
2012-05-30T16:34:39.293Z,1338395679.293 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Initialize WaypointComponent.
2012-05-30T16:34:39.735Z,1338395679.735 [transit_3km:WaypointOne:B.SetSpeed] Running Loop=1
2012-05-30T16:34:39.739Z,1338395679.739 [transit_3km:WaypointOne:A.Pitch] Running Loop=1
2012-05-30T16:34:40.500Z,1338395680.500 [Radio_Freewave](INFO): Powering down
2012-05-30T16:34:45.720Z,1338395685.720 [NAL9601](INFO): Powering down
2012-05-30T16:35:02.965Z,1338395702.965 [Radio_Freewave](INFO): Powering up
2012-05-30T16:35:19.945Z,1338395719.945 [Radio_Freewave](INFO): Powering down
2012-05-30T17:04:06.518Z,1338397446.518 [transit_3km:WaypointOne:WaypointW1.Waypoint](INFO): Reached Waypoint: 36.806966,-121.824326
2012-05-30T17:04:06.518Z,1338397446.519 [transit_3km:WaypointOne:WaypointW1.Waypoint] Stopped
2012-05-30T17:04:06.519Z,1338397446.519 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Uninitialize WaypointComponent.
2012-05-30T17:04:06.519Z,1338397446.519 [transit_3km:WaypointOne:PHONEHOMEWPT1] Running Loop=1
2012-05-30T17:04:06.519Z,1338397446.519 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Aggregate::initialize transit_3km:WaypointOne:PHONEHOMEWPT1
2012-05-30T17:04:06.910Z,1338397446.910 [transit_3km:SURFACECOMMS] Running Loop=1
2012-05-30T17:04:06.910Z,1338397446.910 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2012-05-30T17:04:06.910Z,1338397446.910 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-05-30T17:04:06.910Z,1338397446.910 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T17:06:42.929Z,1338397602.929 [Radio_Freewave](INFO): Powering up
2012-05-30T17:06:42.951Z,1338397602.951 [transit_3km:SURFACECOMMS:B] Running Loop=1
2012-05-30T17:06:42.951Z,1338397602.951 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:B
2012-05-30T17:06:42.951Z,1338397602.951 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-05-30T17:06:42.951Z,1338397602.951 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-05-30T17:06:42.952Z,1338397602.952 [transit_3km:SURFACECOMMS:B:B] Running Loop=1
2012-05-30T17:06:43.591Z,1338397603.591 [NAL9601](INFO): Powering up
2012-05-30T17:07:49.315Z,1338397669.315 [NAL9601](INFO): NAL9601 initialized
2012-05-30T17:07:50.399Z,1338397670.399 [NAL9601](IMPORTANT): GPS fix at: 1338397658.00
2012-05-30T17:07:50.413Z,1338397670.413 [Navigation](IMPORTANT): Navigation Error 6.5 %DT

2012-05-30T17:07:50.414Z,1338397670.414 [transit_3km:SURFACECOMMS:B:B] Stopped
2012-05-30T17:07:50.414Z,1338397670.414 [transit_3km:SURFACECOMMS:B:C] Running Loop=1
2012-05-30T17:08:05.897Z,1338397685.898 [NAL9601](INFO): SBD MO Status=1, MOMSN=6924, MT Status=0, MTMSN=0
2012-05-30T17:08:06.083Z,1338397686.083 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0007.lzma
2012-05-30T17:08:06.083Z,1338397686.083 [NAL9601](INFO): Packets left to send: 7
2012-05-30T17:08:06.085Z,1338397686.085 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000013
2012-05-30T17:08:17.994Z,1338397697.994 [NAL9601](INFO): SBD MO Status=1, MOMSN=6925, MT Status=0, MTMSN=0
2012-05-30T17:08:18.163Z,1338397698.163 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0007.lzma
2012-05-30T17:08:18.163Z,1338397698.163 [NAL9601](INFO): Packets left to send: 6
2012-05-30T17:08:18.164Z,1338397698.164 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000014
2012-05-30T17:08:28.113Z,1338397708.113 [NAL9601](INFO): SBD MO Status=1, MOMSN=6926, MT Status=0, MTMSN=0
2012-05-30T17:08:28.243Z,1338397708.243 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0007.lzma
2012-05-30T17:08:28.243Z,1338397708.243 [NAL9601](INFO): Packets left to send: 5
2012-05-30T17:08:28.244Z,1338397708.244 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000015
2012-05-30T17:08:41.006Z,1338397721.006 [NAL9601](INFO): SBD MO Status=1, MOMSN=6927, MT Status=0, MTMSN=0
2012-05-30T17:08:41.123Z,1338397721.123 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0007.lzma
2012-05-30T17:08:41.123Z,1338397721.123 [NAL9601](INFO): Packets left to send: 4
2012-05-30T17:08:41.124Z,1338397721.124 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000016
2012-05-30T17:08:58.754Z,1338397738.754 [NAL9601](INFO): SBD MO Status=1, MOMSN=6928, MT Status=0, MTMSN=0
2012-05-30T17:08:58.895Z,1338397738.895 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0007.lzma
2012-05-30T17:08:58.895Z,1338397738.895 [NAL9601](INFO): Packets left to send: 3
2012-05-30T17:08:58.896Z,1338397738.897 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000017
2012-05-30T17:09:08.046Z,1338397748.046 [NAL9601](INFO): SBD MO Status=1, MOMSN=6929, MT Status=0, MTMSN=0
2012-05-30T17:09:08.183Z,1338397748.183 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0007.lzma
2012-05-30T17:09:08.183Z,1338397748.183 [NAL9601](INFO): Packets left to send: 2
2012-05-30T17:09:08.184Z,1338397748.184 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000018
2012-05-30T17:09:16.207Z,1338397756.207 [NAL9601](INFO): SBD MO Status=1, MOMSN=6930, MT Status=0, MTMSN=0
2012-05-30T17:09:16.367Z,1338397756.367 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0007.lzma
2012-05-30T17:09:16.367Z,1338397756.367 [NAL9601](INFO): Packets left to send: 1
2012-05-30T17:09:16.368Z,1338397756.368 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000019
2012-05-30T17:09:24.266Z,1338397764.266 [NAL9601](INFO): SBD MO Status=1, MOMSN=6931, MT Status=0, MTMSN=0
2012-05-30T17:09:24.455Z,1338397764.455 [NAL9601](INFO): Sent 17 bytes from file Logs/20120530T160348/shore0007.lzma
2012-05-30T17:09:24.455Z,1338397764.455 [NAL9601](INFO): Packets left to send: 0
2012-05-30T17:09:24.456Z,1338397764.456 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000020
2012-05-30T17:09:32.662Z,1338397772.662 [NAL9601](INFO): SBD MO Status=0, MOMSN=6932, MT Status=0, MTMSN=0
2012-05-30T17:09:32.862Z,1338397772.862 [transit_3km:SURFACECOMMS:B:C] Stopped
2012-05-30T17:09:32.862Z,1338397772.862 [transit_3km:SURFACECOMMS:B:D] Running Loop=1
2012-05-30T17:09:35.097Z,1338397775.097 [NAL9601](IMPORTANT): GPS fix at: 1338397763.00
2012-05-30T17:09:35.126Z,1338397775.126 [transit_3km:SURFACECOMMS:B:D] Stopped
2012-05-30T17:09:35.131Z,1338397775.131 [transit_3km:SURFACECOMMS:B](INFO): Completed transit_3km:SURFACECOMMS:B
2012-05-30T17:09:35.131Z,1338397775.131 [transit_3km:SURFACECOMMS:B] Stopped
2012-05-30T17:09:35.131Z,1338397775.131 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:B
2012-05-30T17:09:35.131Z,1338397775.131 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-05-30T17:09:35.131Z,1338397775.131 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T17:09:35.132Z,1338397775.132 [transit_3km:SURFACECOMMS](INFO): Completed transit_3km:SURFACECOMMS
2012-05-30T17:09:35.132Z,1338397775.132 [transit_3km:SURFACECOMMS] Stopped
2012-05-30T17:09:35.132Z,1338397775.132 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2012-05-30T17:09:35.132Z,1338397775.132 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2012-05-30T17:09:35.132Z,1338397775.132 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T17:09:35.483Z,1338397775.483 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Completed transit_3km:WaypointOne:PHONEHOMEWPT1
2012-05-30T17:09:35.483Z,1338397775.483 [transit_3km:WaypointOne:PHONEHOMEWPT1] Stopped
2012-05-30T17:09:35.483Z,1338397775.483 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Aggregate::uninitialize transit_3km:WaypointOne:PHONEHOMEWPT1
2012-05-30T17:09:35.484Z,1338397775.484 [transit_3km:WaypointOne](INFO): Completed transit_3km:WaypointOne
2012-05-30T17:09:35.484Z,1338397775.484 [transit_3km:WaypointOne] Stopped
2012-05-30T17:09:35.484Z,1338397775.484 [transit_3km:WaypointOne](INFO): Aggregate::uninitialize transit_3km:WaypointOne
2012-05-30T17:09:35.484Z,1338397775.484 [transit_3km:WaypointOne:A.Pitch] Stopped
2012-05-30T17:09:35.484Z,1338397775.484 [transit_3km:WaypointOne:B.SetSpeed] Stopped
2012-05-30T17:09:35.484Z,1338397775.484 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Uninitialize.
2012-05-30T17:09:35.486Z,1338397775.486 [transit_3km](INFO): Completed transit_3km
2012-05-30T17:09:35.486Z,1338397775.486 [transit_3km] Stopped
2012-05-30T17:09:35.486Z,1338397775.486 [transit_3km](INFO): Aggregate::uninitialize transit_3km
2012-05-30T17:09:35.486Z,1338397775.486 [transit_3km:A.AltitudeEnvelope] Stopped
2012-05-30T17:09:35.486Z,1338397775.486 [transit_3km:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-05-30T17:09:35.486Z,1338397775.486 [transit_3km:B.DepthEnvelope] Stopped
2012-05-30T17:09:35.493Z,1338397775.493 [transit_3km:B.DepthEnvelope](DEBUG): Uninitialize.
2012-05-30T17:09:35.493Z,1338397775.493 [transit_3km:C.OffshoreEnvelope] Stopped
2012-05-30T17:09:35.493Z,1338397775.493 [transit_3km:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2012-05-30T17:09:35.902Z,1338397775.902 [MissionManager](IMPORTANT): Started mission Default
2012-05-30T17:09:35.902Z,1338397775.902 [Default] Running Loop=1
2012-05-30T17:09:35.902Z,1338397775.902 [Default](INFO): Aggregate::initialize Default
2012-05-30T17:09:35.907Z,1338397775.907 [Default:D.SetSpeed] Running Loop=1
2012-05-30T17:09:35.907Z,1338397775.907 [Default:D.SetSpeed](DEBUG): Initialize.
2012-05-30T17:09:35.907Z,1338397775.907 [Default:E.GoToSurface] Running Loop=1
2012-05-30T17:09:35.907Z,1338397775.907 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T17:09:35.907Z,1338397775.907 [Default:Iridium] Running Loop=1
2012-05-30T17:09:35.908Z,1338397775.908 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-30T17:09:35.908Z,1338397775.908 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-30T17:09:35.908Z,1338397775.908 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-30T17:09:35.908Z,1338397775.908 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-30T17:09:35.908Z,1338397775.908 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T17:09:35.910Z,1338397775.910 [Default:Iridium:B.GoToSurface] Stopped
2012-05-30T17:09:35.910Z,1338397775.910 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T17:09:35.910Z,1338397775.910 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-30T17:09:48.692Z,1338397788.693 [NAL9601](INFO): SBD MO Status=1, MOMSN=6933, MT Status=0, MTMSN=0
2012-05-30T17:09:48.819Z,1338397788.819 [NAL9601](INFO): Sent 189 bytes from file Logs/20120530T160348/shore0008.lzma
2012-05-30T17:09:48.819Z,1338397788.819 [NAL9601](INFO): Packets left to send: 0
2012-05-30T17:09:48.820Z,1338397788.820 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000021
2012-05-30T17:09:58.694Z,1338397798.694 [NAL9601](INFO): SBD MO Status=0, MOMSN=6934, MT Status=0, MTMSN=0
2012-05-30T17:09:58.927Z,1338397798.927 [Default:Iridium:Read_Iridium] Stopped
2012-05-30T17:09:58.927Z,1338397798.927 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-30T17:09:58.927Z,1338397798.927 [Default:Iridium] Stopped
2012-05-30T17:09:58.928Z,1338397798.928 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-30T17:09:58.928Z,1338397798.928 [Default:Iridium:A.SetSpeed] Stopped
2012-05-30T17:09:58.928Z,1338397798.928 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T17:09:58.928Z,1338397798.928 [Default:F.Wait] Running Loop=1
2012-05-30T17:09:58.928Z,1338397798.928 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-05-30T17:10:09.230Z,1338397809.230 [NAL9601](INFO): Powering down
2012-05-30T17:14:59.379Z,1338398099.379 [Default:CallIridium] Running Loop=1
2012-05-30T17:14:59.379Z,1338398099.379 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-30T17:14:59.379Z,1338398099.379 [Default:CallIridium:A] Running Loop=1
2012-05-30T17:14:59.380Z,1338398099.380 [Default:CallIridium:A] Stopped
2012-05-30T17:14:59.380Z,1338398099.380 [Default:CallIridium:B] Running Loop=1
2012-05-30T17:14:59.380Z,1338398099.380 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-30T17:15:04.278Z,1338398104.278 [Default:Iridium] Running Loop=1
2012-05-30T17:15:04.278Z,1338398104.278 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-30T17:15:04.278Z,1338398104.278 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-30T17:15:04.278Z,1338398104.278 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-30T17:15:04.278Z,1338398104.278 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-30T17:15:04.278Z,1338398104.279 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T17:15:04.280Z,1338398104.280 [Default:Iridium:B.GoToSurface] Stopped
2012-05-30T17:15:04.280Z,1338398104.280 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T17:15:04.280Z,1338398104.280 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-30T17:15:04.280Z,1338398104.280 [Default:GPS] Running Loop=1
2012-05-30T17:15:04.280Z,1338398104.280 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-30T17:15:04.280Z,1338398104.280 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-30T17:15:04.280Z,1338398104.280 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-30T17:15:04.280Z,1338398104.280 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-30T17:15:04.281Z,1338398104.281 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T17:15:04.282Z,1338398104.282 [Default:GPS:B.GoToSurface] Stopped
2012-05-30T17:15:04.282Z,1338398104.282 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T17:15:04.282Z,1338398104.282 [Default:GPS:Read_GPS] Running Loop=1
2012-05-30T17:15:04.892Z,1338398104.892 [NAL9601](INFO): Powering up
2012-05-30T17:16:10.615Z,1338398170.615 [NAL9601](INFO): NAL9601 initialized
2012-05-30T17:16:11.695Z,1338398171.695 [NAL9601](IMPORTANT): GPS fix at: 1338398160.00
2012-05-30T17:16:11.711Z,1338398171.711 [Default:GPS:Read_GPS] Stopped
2012-05-30T17:16:11.711Z,1338398171.711 [Default:GPS:D] Running Loop=1
2012-05-30T17:16:12.116Z,1338398172.116 [Default:GPS:D] Stopped
2012-05-30T17:16:12.116Z,1338398172.116 [Default:GPS](INFO): Completed Default:GPS
2012-05-30T17:16:12.117Z,1338398172.117 [Default:GPS] Stopped
2012-05-30T17:16:12.117Z,1338398172.117 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-30T17:16:12.117Z,1338398172.117 [Default:GPS:A.SetSpeed] Stopped
2012-05-30T17:16:12.117Z,1338398172.117 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T17:16:25.646Z,1338398185.645 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=6935, MT Status=1, MTMSN=2632
2012-05-30T17:16:25.779Z,1338398185.779 [NAL9601](INFO): Sent 156 bytes from file Logs/20120530T160348/shore0009.lzma
2012-05-30T17:16:25.779Z,1338398185.779 [NAL9601](INFO): Packets left to send: 0
2012-05-30T17:16:25.780Z,1338398185.780 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000022
2012-05-30T17:16:26.212Z,1338398186.211 [NAL9601](INFO): Received command:run Maintenance/ballast_and_trim.xml
2012-05-30T17:16:26.275Z,1338398186.275 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/ballast_and_trim.xml
2012-05-30T17:16:26.275Z,1338398186.275 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/ballast_and_trim.xml
2012-05-30T17:16:26.399Z,1338398186.399 [MissionManager](INFO): DefineArg ballast_and_trim.BallastDepth = 25.000000 m
2012-05-30T17:16:26.402Z,1338398186.402 [MissionManager](INFO): DefineArg ballast_and_trim.HoldDuration = 25.000000 min
2012-05-30T17:16:26.413Z,1338398186.413 [MissionManager](INFO): DefineArg ballast_and_trim.Speed = 1.000000 m/s
2012-05-30T17:16:26.425Z,1338398186.425 [MissionManager](INFO): DefineArg ballast_and_trim.DepthDeadband = 4.000000 m
2012-05-30T17:16:26.436Z,1338398186.436 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyPeriod = 0.400000 s
2012-05-30T17:16:26.447Z,1338398186.447 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyancyDefault = 0.000945 n/a
2012-05-30T17:16:26.469Z,1338398186.469 [ballast_and_trim:D.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-05-30T17:16:26.506Z,1338398186.506 [ballast_and_trim:E.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-05-30T17:16:26.535Z,1338398186.535 [ballast_and_trim:F.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2012-05-30T17:16:26.558Z,1338398186.558 [MissionManager](INFO): Inserting Stack: Missions/Insert/Surface.xml
2012-05-30T17:16:26.598Z,1338398186.598 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfaceDepthRate = nan m/s
2012-05-30T17:16:26.601Z,1338398186.601 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfacePitch = nan arcdeg
2012-05-30T17:16:26.613Z,1338398186.613 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfaceSpeed = 0.500000 m/s
2012-05-30T17:16:26.616Z,1338398186.616 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.IridiumTimeout = 30.000000 min
2012-05-30T17:16:26.617Z,1338398186.617 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-30T17:16:26.643Z,1338398186.643 [ballast_and_trim:H.SetSpeed](DEBUG): Construct.
2012-05-30T17:16:26.648Z,1338398186.648 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Construct.
2012-05-30T17:16:26.665Z,1338398186.665 [ballast_and_trim:ballast:C.Pitch](DEBUG): Construct.
2012-05-30T17:16:26.670Z,1338398186.670 [ballast_and_trim:ballast:D.Wait](DEBUG): Construct Wait.
2012-05-30T17:16:26.688Z,1338398186.688 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Construct Wait.
2012-05-30T17:16:26.692Z,1338398186.692 [ballast_and_trim:ballast:Float_Up:A.SetSpeed](DEBUG): Construct.
2012-05-30T17:16:26.695Z,1338398186.695 [ballast_and_trim:ballast:Float_Up:B.Buoyancy](DEBUG): Construct Buoyancy.
2012-05-30T17:16:26.698Z,1338398186.698 [ballast_and_trim:ballast:Float_Up:C.Wait](DEBUG): Construct Wait.
2012-05-30T17:16:26.742Z,1338398186.742 [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-05-30T17:16:26.754Z,1338398186.754 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/ballast_and_trim.xml
2012-05-30T17:16:26.863Z,1338398186.863 [Default] Stopped
2012-05-30T17:16:26.863Z,1338398186.863 [Default](INFO): Aggregate::uninitialize Default
2012-05-30T17:16:26.863Z,1338398186.863 [Default:Iridium] Stopped
2012-05-30T17:16:26.863Z,1338398186.863 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-30T17:16:26.863Z,1338398186.863 [Default:Iridium:A.SetSpeed] Stopped
2012-05-30T17:16:26.863Z,1338398186.863 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T17:16:26.863Z,1338398186.863 [Default:Iridium:Read_Iridium] Stopped
2012-05-30T17:16:26.863Z,1338398186.863 [Default:CallIridium] Stopped
2012-05-30T17:16:26.863Z,1338398186.864 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-30T17:16:26.864Z,1338398186.864 [Default:CallIridium:B] Stopped
2012-05-30T17:16:26.864Z,1338398186.864 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-30T17:16:26.864Z,1338398186.864 [Default:D.SetSpeed] Stopped
2012-05-30T17:16:26.864Z,1338398186.864 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-05-30T17:16:26.864Z,1338398186.864 [Default:E.GoToSurface] Stopped
2012-05-30T17:16:26.864Z,1338398186.864 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T17:16:26.864Z,1338398186.864 [Default:F.Wait] Stopped
2012-05-30T17:16:26.864Z,1338398186.864 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2012-05-30T17:16:26.864Z,1338398186.864 [MissionManager](IMPORTANT): Started mission ballast_and_trim
2012-05-30T17:16:26.864Z,1338398186.864 [ballast_and_trim] Running Loop=1
2012-05-30T17:16:26.864Z,1338398186.865 [ballast_and_trim](INFO): Aggregate::initialize ballast_and_trim
2012-05-30T17:16:26.865Z,1338398186.865 [ballast_and_trim:A] Running Loop=1
2012-05-30T17:16:26.865Z,1338398186.865 [ballast_and_trim:B] Running Loop=1
2012-05-30T17:16:26.865Z,1338398186.865 [ballast_and_trim:C] Running Loop=1
2012-05-30T17:16:26.865Z,1338398186.865 [ballast_and_trim:D.AltitudeEnvelope] Running Loop=1
2012-05-30T17:16:26.865Z,1338398186.865 [ballast_and_trim:D.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-05-30T17:16:26.865Z,1338398186.865 [ballast_and_trim:E.DepthEnvelope] Running Loop=1
2012-05-30T17:16:26.865Z,1338398186.865 [ballast_and_trim:E.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-05-30T17:16:26.866Z,1338398186.866 [ballast_and_trim:F.OffshoreEnvelope] Running Loop=1
2012-05-30T17:16:26.866Z,1338398186.866 [ballast_and_trim:F.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2012-05-30T17:16:26.866Z,1338398186.866 [ballast_and_trim:H.SetSpeed] Running Loop=1
2012-05-30T17:16:26.866Z,1338398186.866 [ballast_and_trim:H.SetSpeed](DEBUG): Initialize.
2012-05-30T17:16:26.866Z,1338398186.866 [ballast_and_trim:SurfaceComms] Running Loop=1
2012-05-30T17:16:26.867Z,1338398186.867 [ballast_and_trim:SurfaceComms](INFO): Aggregate::initialize ballast_and_trim:SurfaceComms
2012-05-30T17:16:26.867Z,1338398186.867 [ballast_and_trim:SurfaceComms:A.GoToSurface] Running Loop=1
2012-05-30T17:16:26.867Z,1338398186.867 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T17:16:26.868Z,1338398186.868 [ballast_and_trim:H.SetSpeed] Running Loop=1
2012-05-30T17:16:26.878Z,1338398186.878 [ballast_and_trim:SurfaceComms:B] Running Loop=1
2012-05-30T17:16:26.878Z,1338398186.878 [ballast_and_trim:SurfaceComms:B](INFO): Aggregate::initialize ballast_and_trim:SurfaceComms:B
2012-05-30T17:16:26.878Z,1338398186.878 [ballast_and_trim:SurfaceComms:B:A] Running Loop=1
2012-05-30T17:16:26.878Z,1338398186.878 [ballast_and_trim:F.OffshoreEnvelope] Running Loop=1
2012-05-30T17:16:26.883Z,1338398186.883 [ballast_and_trim:E.DepthEnvelope] Running Loop=1
2012-05-30T17:16:26.888Z,1338398186.888 [ballast_and_trim:D.AltitudeEnvelope] Running Loop=1
2012-05-30T17:16:26.892Z,1338398186.892 [ballast_and_trim:C] Running Loop=1
2012-05-30T17:16:26.894Z,1338398186.894 [ballast_and_trim:B] Running Loop=1
2012-05-30T17:16:26.895Z,1338398186.895 [ballast_and_trim:A] Running Loop=1
2012-05-30T17:16:27.238Z,1338398187.238 [ballast_and_trim:H.SetSpeed] Preempted
2012-05-30T17:16:27.238Z,1338398187.239 [ballast_and_trim:SurfaceComms:B:A](DEBUG): Initialize ReadDataComponent to sense time_fix
2012-05-30T17:16:28.427Z,1338398188.427 [NAL9601](IMPORTANT): GPS fix at: 1338398177.00
2012-05-30T17:16:28.441Z,1338398188.441 [ballast_and_trim:SurfaceComms:B:A] Stopped
2012-05-30T17:16:28.441Z,1338398188.441 [ballast_and_trim:SurfaceComms:B:B] Running Loop=1
2012-05-30T17:16:28.841Z,1338398188.841 [ballast_and_trim:SurfaceComms:B:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-05-30T17:16:37.605Z,1338398197.605 [NAL9601](INFO): SBD MO Status=1, MOMSN=6936, MT Status=0, MTMSN=0
2012-05-30T17:16:37.763Z,1338398197.763 [NAL9601](INFO): Sent 273 bytes from file Logs/20120530T160348/shore0010.lzma
2012-05-30T17:16:37.763Z,1338398197.763 [NAL9601](INFO): Packets left to send: 0
2012-05-30T17:16:37.765Z,1338398197.765 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000023
2012-05-30T17:16:41.590Z,1338398201.590 [NAL9601](INFO): SBD MO Status=0, MOMSN=6937, MT Status=0, MTMSN=0
2012-05-30T17:16:54.777Z,1338398214.777 [NAL9601](INFO): SBD MO Status=1, MOMSN=6938, MT Status=0, MTMSN=0
2012-05-30T17:16:54.935Z,1338398214.935 [NAL9601](INFO): Sent 101 bytes from file Logs/20120530T160348/shore0011.lzma
2012-05-30T17:16:54.935Z,1338398214.935 [NAL9601](INFO): Packets left to send: 0
2012-05-30T17:16:54.936Z,1338398214.936 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000024
2012-05-30T17:16:58.913Z,1338398218.913 [NAL9601](INFO): SBD MO Status=0, MOMSN=6939, MT Status=0, MTMSN=0
2012-05-30T17:16:59.145Z,1338398219.145 [ballast_and_trim:SurfaceComms:B:B] Stopped
2012-05-30T17:16:59.145Z,1338398219.145 [ballast_and_trim:SurfaceComms:B:C] Running Loop=1
2012-05-30T17:16:59.326Z,1338398219.326 [ballast_and_trim:SurfaceComms:B:C](DEBUG): Initialize ReadDataComponent to sense time_fix
2012-05-30T17:17:01.315Z,1338398221.315 [NAL9601](IMPORTANT): GPS fix at: 1338398210.00
2012-05-30T17:17:01.373Z,1338398221.373 [ballast_and_trim:SurfaceComms:B:C] Stopped
2012-05-30T17:17:01.373Z,1338398221.374 [ballast_and_trim:SurfaceComms:B](INFO): Completed ballast_and_trim:SurfaceComms:B
2012-05-30T17:17:01.373Z,1338398221.374 [ballast_and_trim:SurfaceComms:B] Stopped
2012-05-30T17:17:01.374Z,1338398221.374 [ballast_and_trim:SurfaceComms:B](INFO): Aggregate::uninitialize ballast_and_trim:SurfaceComms:B
2012-05-30T17:17:01.379Z,1338398221.379 [ballast_and_trim:SurfaceComms](INFO): Completed ballast_and_trim:SurfaceComms
2012-05-30T17:17:01.379Z,1338398221.379 [ballast_and_trim:SurfaceComms] Stopped
2012-05-30T17:17:01.379Z,1338398221.379 [ballast_and_trim:SurfaceComms](INFO): Aggregate::uninitialize ballast_and_trim:SurfaceComms
2012-05-30T17:17:01.379Z,1338398221.379 [ballast_and_trim:SurfaceComms:A.GoToSurface] Stopped
2012-05-30T17:17:01.379Z,1338398221.379 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T17:17:01.379Z,1338398221.379 [ballast_and_trim:ballast] Running Loop=1
2012-05-30T17:17:01.379Z,1338398221.379 [ballast_and_trim:ballast](INFO): Aggregate::initialize ballast_and_trim:ballast
2012-05-30T17:17:01.380Z,1338398221.379 [ballast_and_trim:ballast:A.SetSpeed] Running Loop=1
2012-05-30T17:17:01.380Z,1338398221.380 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Initialize.
2012-05-30T17:17:01.380Z,1338398221.380 [ballast_and_trim:ballast:B] Running Loop=1
2012-05-30T17:17:01.380Z,1338398221.380 [ballast_and_trim:ballast:C.Pitch] Running Loop=1
2012-05-30T17:17:01.380Z,1338398221.380 [ballast_and_trim:ballast:C.Pitch](DEBUG): Initialize.
2012-05-30T17:17:01.380Z,1338398221.380 [ballast_and_trim:ballast:D.Wait] Running Loop=1
2012-05-30T17:17:01.380Z,1338398221.380 [ballast_and_trim:ballast:D.Wait](DEBUG): Initialize Wait Component.
2012-05-30T17:17:01.731Z,1338398221.731 [ballast_and_trim:ballast:C.Pitch] Running Loop=1
2012-05-30T17:17:01.735Z,1338398221.735 [ballast_and_trim:ballast:B] Running Loop=1
2012-05-30T17:17:01.737Z,1338398221.737 [ballast_and_trim:ballast:A.SetSpeed] Running Loop=1
2012-05-30T17:17:01.741Z,1338398221.741 [ballast_and_trim:H.SetSpeed] Running Loop=1
2012-05-30T17:17:07.600Z,1338398227.600 [NAL9601](INFO): Powering down
2012-05-30T17:22:24.865Z,1338398544.865 [Radio_Freewave](INFO): Powering down
2012-05-30T17:42:02.087Z,1338399722.087 [ballast_and_trim:ballast:D.Wait](INFO): Done Waiting.
2012-05-30T17:42:02.088Z,1338399722.088 [ballast_and_trim:ballast:D.Wait] Stopped
2012-05-30T17:42:02.088Z,1338399722.088 [ballast_and_trim:ballast:D.Wait](DEBUG): Uninitialize Wait Component.
2012-05-30T17:42:02.088Z,1338399722.088 [ballast_and_trim:ballast:ReportPositions] Running Loop=1
2012-05-30T17:42:02.088Z,1338399722.088 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-05-30T17:42:02.088Z,1338399722.088 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-05-30T17:42:02.487Z,1338399722.487 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 399.935321 cc Mass: -0.624684 cm Pitch: -0.069043 arcdeg 
2012-05-30T17:42:02.489Z,1338399722.489 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-05-30T17:42:02.489Z,1338399722.489 [ballast_and_trim:ballast:ReportPositions:B.Wait] Running Loop=1
2012-05-30T17:42:02.489Z,1338399722.489 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Initialize Wait Component.
2012-05-30T17:43:02.899Z,1338399782.899 [ballast_and_trim:ballast:ReportPositions:B.Wait](INFO): Timed out from 2012-05-30T17:42:02.5Z
2012-05-30T17:43:02.899Z,1338399782.899 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-05-30T17:43:02.900Z,1338399782.900 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-30T17:43:02.900Z,1338399782.900 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-30T17:43:02.900Z,1338399782.900 [ballast_and_trim:ballast:ReportPositions:B.Wait] Stopped
2012-05-30T17:43:02.900Z,1338399782.900 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Uninitialize Wait Component.
2012-05-30T17:43:02.900Z,1338399782.900 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-05-30T17:43:02.900Z,1338399782.900 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-05-30T17:43:02.900Z,1338399782.900 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-05-30T17:43:02.901Z,1338399782.901 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #2
2012-05-30T17:43:02.901Z,1338399782.901 [ballast_and_trim:ballast:ReportPositions] Running Loop=2
2012-05-30T17:43:02.901Z,1338399782.901 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-05-30T17:43:02.901Z,1338399782.901 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-05-30T17:43:03.286Z,1338399783.286 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 399.935321 cc Mass: -0.628293 cm Pitch: 0.392383 arcdeg 
2012-05-30T17:43:03.286Z,1338399783.286 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-05-30T17:43:03.286Z,1338399783.286 [ballast_and_trim:ballast:ReportPositions:B.Wait] Running Loop=1
2012-05-30T17:43:03.286Z,1338399783.286 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Initialize Wait Component.
2012-05-30T17:44:03.653Z,1338399843.653 [ballast_and_trim:ballast:ReportPositions:B.Wait](INFO): Timed out from 2012-05-30T17:43:03.3Z
2012-05-30T17:44:03.654Z,1338399843.654 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-05-30T17:44:03.654Z,1338399843.654 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-30T17:44:03.654Z,1338399843.654 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-30T17:44:03.654Z,1338399843.654 [ballast_and_trim:ballast:ReportPositions:B.Wait] Stopped
2012-05-30T17:44:03.654Z,1338399843.654 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Uninitialize Wait Component.
2012-05-30T17:44:03.654Z,1338399843.654 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-05-30T17:44:03.655Z,1338399843.655 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-05-30T17:44:03.655Z,1338399843.655 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-05-30T17:44:03.655Z,1338399843.655 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #3
2012-05-30T17:44:03.655Z,1338399843.655 [ballast_and_trim:ballast:ReportPositions] Running Loop=3
2012-05-30T17:44:03.655Z,1338399843.655 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-05-30T17:44:03.655Z,1338399843.655 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-05-30T17:44:04.092Z,1338399844.092 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 399.935321 cc Mass: -0.628293 cm Pitch: 0.216602 arcdeg 
2012-05-30T17:44:04.092Z,1338399844.092 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-05-30T17:44:04.092Z,1338399844.092 [ballast_and_trim:ballast:ReportPositions:B.Wait] Running Loop=1
2012-05-30T17:44:04.092Z,1338399844.092 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Initialize Wait Component.
2012-05-30T17:45:04.101Z,1338399904.101 [ballast_and_trim:ballast:ReportPositions:B.Wait](INFO): Timed out from 2012-05-30T17:44:04.1Z
2012-05-30T17:45:04.101Z,1338399904.101 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-05-30T17:45:04.101Z,1338399904.101 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-30T17:45:04.101Z,1338399904.101 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-30T17:45:04.101Z,1338399904.101 [ballast_and_trim:ballast:ReportPositions:B.Wait] Stopped
2012-05-30T17:45:04.101Z,1338399904.102 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Uninitialize Wait Component.
2012-05-30T17:45:04.102Z,1338399904.102 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-05-30T17:45:04.102Z,1338399904.102 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-05-30T17:45:04.102Z,1338399904.102 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-05-30T17:45:04.102Z,1338399904.102 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #4
2012-05-30T17:45:04.102Z,1338399904.102 [ballast_and_trim:ballast:ReportPositions] Running Loop=4
2012-05-30T17:45:04.102Z,1338399904.102 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-05-30T17:45:04.102Z,1338399904.102 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-05-30T17:45:04.500Z,1338399904.500 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 399.935321 cc Mass: -0.628293 cm Pitch: -0.442578 arcdeg 
2012-05-30T17:45:04.500Z,1338399904.500 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-05-30T17:45:04.500Z,1338399904.500 [ballast_and_trim:ballast:ReportPositions:B.Wait] Running Loop=1
2012-05-30T17:45:04.500Z,1338399904.500 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Initialize Wait Component.
2012-05-30T17:46:04.724Z,1338399964.724 [ballast_and_trim:ballast:ReportPositions:B.Wait](INFO): Timed out from 2012-05-30T17:45:04.5Z
2012-05-30T17:46:04.725Z,1338399964.724 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-05-30T17:46:04.725Z,1338399964.725 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-30T17:46:04.725Z,1338399964.725 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-30T17:46:04.725Z,1338399964.725 [ballast_and_trim:ballast:ReportPositions:B.Wait] Stopped
2012-05-30T17:46:04.725Z,1338399964.725 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Uninitialize Wait Component.
2012-05-30T17:46:04.725Z,1338399964.725 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-05-30T17:46:04.725Z,1338399964.725 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-05-30T17:46:04.725Z,1338399964.725 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-05-30T17:46:04.726Z,1338399964.726 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #5
2012-05-30T17:46:04.726Z,1338399964.726 [ballast_and_trim:ballast:ReportPositions] Running Loop=5
2012-05-30T17:46:04.726Z,1338399964.726 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-05-30T17:46:04.726Z,1338399964.726 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-05-30T17:46:05.101Z,1338399965.102 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 402.084144 cc Mass: -0.625739 cm Pitch: 0.216602 arcdeg 
2012-05-30T17:46:05.102Z,1338399965.102 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-05-30T17:46:05.102Z,1338399965.102 [ballast_and_trim:ballast:ReportPositions:B.Wait] Running Loop=1
2012-05-30T17:46:05.102Z,1338399965.102 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Initialize Wait Component.
2012-05-30T17:47:05.149Z,1338400025.149 [ballast_and_trim:ballast:ReportPositions:B.Wait](INFO): Timed out from 2012-05-30T17:46:05.1Z
2012-05-30T17:47:05.149Z,1338400025.149 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-05-30T17:47:05.149Z,1338400025.149 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-30T17:47:05.149Z,1338400025.149 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-30T17:47:05.149Z,1338400025.149 [ballast_and_trim:ballast:ReportPositions:B.Wait] Stopped
2012-05-30T17:47:05.149Z,1338400025.149 [ballast_and_trim:ballast:ReportPositions:B.Wait](DEBUG): Uninitialize Wait Component.
2012-05-30T17:47:05.150Z,1338400025.150 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-05-30T17:47:05.150Z,1338400025.150 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-05-30T17:47:05.150Z,1338400025.150 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-05-30T17:47:05.150Z,1338400025.150 [ballast_and_trim:ballast:Float_Up] Running Loop=1
2012-05-30T17:47:05.150Z,1338400025.150 [ballast_and_trim:ballast:Float_Up](INFO): Aggregate::initialize ballast_and_trim:ballast:Float_Up
2012-05-30T17:47:05.150Z,1338400025.150 [ballast_and_trim:ballast:Float_Up:A.SetSpeed] Running Loop=1
2012-05-30T17:47:05.150Z,1338400025.150 [ballast_and_trim:ballast:Float_Up:A.SetSpeed](DEBUG): Initialize.
2012-05-30T17:47:05.150Z,1338400025.150 [ballast_and_trim:ballast:Float_Up:B.Buoyancy] Running Loop=1
2012-05-30T17:47:05.150Z,1338400025.151 [ballast_and_trim:ballast:Float_Up:B.Buoyancy](DEBUG): Initialize Buoyancy Component.
2012-05-30T17:47:05.151Z,1338400025.151 [ballast_and_trim:ballast:Float_Up:C.Wait] Running Loop=1
2012-05-30T17:47:05.151Z,1338400025.151 [ballast_and_trim:ballast:Float_Up:C.Wait](DEBUG): Initialize Wait Component.
2012-05-30T17:47:05.509Z,1338400025.509 [ballast_and_trim:ballast:Float_Up:B.Buoyancy] Running Loop=1
2012-05-30T17:47:05.513Z,1338400025.513 [ballast_and_trim:ballast:Float_Up:A.SetSpeed] Running Loop=1
2012-05-30T17:51:00.290Z,1338400260.290 [ballast_and_trim:ballast:Float_Up] Stopped
2012-05-30T17:51:00.290Z,1338400260.290 [ballast_and_trim:ballast:Float_Up](INFO): Aggregate::uninitialize ballast_and_trim:ballast:Float_Up
2012-05-30T17:51:00.290Z,1338400260.290 [ballast_and_trim:ballast:Float_Up:A.SetSpeed] Stopped
2012-05-30T17:51:00.290Z,1338400260.290 [ballast_and_trim:ballast:Float_Up:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T17:51:00.290Z,1338400260.290 [ballast_and_trim:ballast:Float_Up:B.Buoyancy] Stopped
2012-05-30T17:51:00.290Z,1338400260.290 [ballast_and_trim:ballast:Float_Up:B.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2012-05-30T17:51:00.290Z,1338400260.290 [ballast_and_trim:ballast:Float_Up:C.Wait] Stopped
2012-05-30T17:51:00.291Z,1338400260.291 [ballast_and_trim:ballast:Float_Up:C.Wait](DEBUG): Uninitialize Wait Component.
2012-05-30T17:51:00.292Z,1338400260.292 [ballast_and_trim:ballast](INFO): Completed ballast_and_trim:ballast
2012-05-30T17:51:00.292Z,1338400260.292 [ballast_and_trim:ballast] Stopped
2012-05-30T17:51:00.292Z,1338400260.292 [ballast_and_trim:ballast](INFO): Aggregate::uninitialize ballast_and_trim:ballast
2012-05-30T17:51:00.292Z,1338400260.292 [ballast_and_trim:ballast:A.SetSpeed] Stopped
2012-05-30T17:51:00.292Z,1338400260.292 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T17:51:00.292Z,1338400260.292 [ballast_and_trim:ballast:B] Stopped
2012-05-30T17:51:00.292Z,1338400260.292 [ballast_and_trim:ballast:C.Pitch] Stopped
2012-05-30T17:51:00.295Z,1338400260.295 [ballast_and_trim](INFO): Completed ballast_and_trim
2012-05-30T17:51:00.295Z,1338400260.295 [ballast_and_trim] Stopped
2012-05-30T17:51:00.295Z,1338400260.295 [ballast_and_trim](INFO): Aggregate::uninitialize ballast_and_trim
2012-05-30T17:51:00.295Z,1338400260.295 [ballast_and_trim:A] Stopped
2012-05-30T17:51:00.295Z,1338400260.295 [ballast_and_trim:B] Stopped
2012-05-30T17:51:00.295Z,1338400260.295 [ballast_and_trim:C] Stopped
2012-05-30T17:51:00.295Z,1338400260.295 [ballast_and_trim:D.AltitudeEnvelope] Stopped
2012-05-30T17:51:00.295Z,1338400260.295 [ballast_and_trim:D.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-05-30T17:51:00.295Z,1338400260.295 [ballast_and_trim:E.DepthEnvelope] Stopped
2012-05-30T17:51:00.295Z,1338400260.295 [ballast_and_trim:E.DepthEnvelope](DEBUG): Uninitialize.
2012-05-30T17:51:00.295Z,1338400260.295 [ballast_and_trim:F.OffshoreEnvelope] Stopped
2012-05-30T17:51:00.295Z,1338400260.295 [ballast_and_trim:F.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2012-05-30T17:51:00.295Z,1338400260.295 [ballast_and_trim:H.SetSpeed] Stopped
2012-05-30T17:51:00.296Z,1338400260.296 [ballast_and_trim:H.SetSpeed](DEBUG): Uninitialize.
2012-05-30T17:51:00.689Z,1338400260.689 [MissionManager](IMPORTANT): Started mission Default
2012-05-30T17:51:00.689Z,1338400260.689 [Default] Running Loop=1
2012-05-30T17:51:00.689Z,1338400260.689 [Default](INFO): Aggregate::initialize Default
2012-05-30T17:51:00.689Z,1338400260.689 [Default:D.SetSpeed] Running Loop=1
2012-05-30T17:51:00.689Z,1338400260.689 [Default:D.SetSpeed](DEBUG): Initialize.
2012-05-30T17:51:00.689Z,1338400260.689 [Default:E.GoToSurface] Running Loop=1
2012-05-30T17:51:00.689Z,1338400260.689 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T17:51:00.690Z,1338400260.690 [Default:Iridium] Running Loop=1
2012-05-30T17:51:00.690Z,1338400260.690 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-30T17:51:00.690Z,1338400260.690 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-30T17:51:00.690Z,1338400260.690 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-30T17:51:00.690Z,1338400260.690 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-30T17:51:00.690Z,1338400260.690 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T17:51:00.692Z,1338400260.692 [Default:CallIridium] Running Loop=1
2012-05-30T17:51:00.692Z,1338400260.692 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-30T17:51:00.692Z,1338400260.692 [Default:CallIridium:A] Running Loop=1
2012-05-30T17:51:00.692Z,1338400260.692 [Default:CallIridium:A] Stopped
2012-05-30T17:51:00.692Z,1338400260.693 [Default:CallIridium:B] Running Loop=1
2012-05-30T17:51:00.693Z,1338400260.693 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-30T17:51:01.092Z,1338400261.092 [Default:GPS] Running Loop=1
2012-05-30T17:51:01.092Z,1338400261.092 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-30T17:51:01.092Z,1338400261.092 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-30T17:51:01.092Z,1338400261.092 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-30T17:51:01.092Z,1338400261.092 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-30T17:51:01.092Z,1338400261.092 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T17:51:02.281Z,1338400262.281 [Radio_Freewave](INFO): Powering up
2012-05-30T17:51:02.292Z,1338400262.292 [Default:Iridium:B.GoToSurface] Stopped
2012-05-30T17:51:02.292Z,1338400262.292 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T17:51:02.292Z,1338400262.292 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-30T17:51:02.293Z,1338400262.293 [Default:GPS:B.GoToSurface] Stopped
2012-05-30T17:51:02.293Z,1338400262.293 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T17:51:02.293Z,1338400262.293 [Default:GPS:Read_GPS] Running Loop=1
2012-05-30T17:51:03.076Z,1338400263.076 [NAL9601](INFO): Powering up
2012-05-30T17:52:08.699Z,1338400328.699 [NAL9601](INFO): NAL9601 initialized
2012-05-30T17:52:09.830Z,1338400329.830 [NAL9601](IMPORTANT): GPS fix at: 1338400322.00
2012-05-30T17:52:09.873Z,1338400329.874 [Default:GPS:Read_GPS] Stopped
2012-05-30T17:52:09.874Z,1338400329.874 [Default:GPS:D] Running Loop=1
2012-05-30T17:52:10.261Z,1338400330.261 [Default:GPS:D] Stopped
2012-05-30T17:52:10.261Z,1338400330.261 [Default:GPS](INFO): Completed Default:GPS
2012-05-30T17:52:10.261Z,1338400330.261 [Default:GPS] Stopped
2012-05-30T17:52:10.261Z,1338400330.261 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-30T17:52:10.262Z,1338400330.261 [Default:GPS:A.SetSpeed] Stopped
2012-05-30T17:52:10.262Z,1338400330.262 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T17:52:24.933Z,1338400344.933 [NAL9601](INFO): SBD MO Status=1, MOMSN=6940, MT Status=0, MTMSN=0
2012-05-30T17:52:25.063Z,1338400345.063 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0012.lzma
2012-05-30T17:52:25.063Z,1338400345.063 [NAL9601](INFO): Packets left to send: 1
2012-05-30T17:52:25.064Z,1338400345.064 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000025
2012-05-30T17:52:36.659Z,1338400356.659 [NAL9601](INFO): SBD MO Status=1, MOMSN=6941, MT Status=0, MTMSN=0
2012-05-30T17:52:36.847Z,1338400356.847 [NAL9601](INFO): Sent 206 bytes from file Logs/20120530T160348/shore0012.lzma
2012-05-30T17:52:36.847Z,1338400356.847 [NAL9601](INFO): Packets left to send: 0
2012-05-30T17:52:36.848Z,1338400356.848 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000026
2012-05-30T17:52:43.836Z,1338400363.836 [NAL9601](INFO): SBD MO Status=0, MOMSN=6942, MT Status=0, MTMSN=0
2012-05-30T17:52:44.050Z,1338400364.050 [Default:Iridium:Read_Iridium] Stopped
2012-05-30T17:52:44.050Z,1338400364.050 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-30T17:52:44.050Z,1338400364.050 [Default:Iridium] Stopped
2012-05-30T17:52:44.051Z,1338400364.050 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-30T17:52:44.051Z,1338400364.051 [Default:Iridium:A.SetSpeed] Stopped
2012-05-30T17:52:44.051Z,1338400364.051 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T17:52:44.051Z,1338400364.051 [Default:F.Wait] Running Loop=1
2012-05-30T17:52:44.051Z,1338400364.051 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-05-30T17:52:44.250Z,1338400364.250 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-30T17:52:44.251Z,1338400364.251 [Default:CallIridium:B] Stopped
2012-05-30T17:52:44.251Z,1338400364.251 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-30T17:52:44.251Z,1338400364.251 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-30T17:52:44.251Z,1338400364.251 [Default:CallIridium] Stopped
2012-05-30T17:52:44.251Z,1338400364.251 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-30T17:52:54.407Z,1338400374.407 [NAL9601](INFO): Powering down
2012-05-30T17:57:44.389Z,1338400664.389 [Default:CallIridium] Running Loop=1
2012-05-30T17:57:44.389Z,1338400664.389 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-30T17:57:44.389Z,1338400664.389 [Default:CallIridium:A] Running Loop=1
2012-05-30T17:57:44.390Z,1338400664.390 [Default:CallIridium:A] Stopped
2012-05-30T17:57:44.390Z,1338400664.390 [Default:CallIridium:B] Running Loop=1
2012-05-30T17:57:44.390Z,1338400664.390 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-30T17:57:49.389Z,1338400669.389 [Default:Iridium] Running Loop=1
2012-05-30T17:57:49.390Z,1338400669.390 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-30T17:57:49.390Z,1338400669.390 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-30T17:57:49.390Z,1338400669.390 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-30T17:57:49.390Z,1338400669.390 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-30T17:57:49.390Z,1338400669.390 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T17:57:49.391Z,1338400669.391 [Default:Iridium:B.GoToSurface] Stopped
2012-05-30T17:57:49.391Z,1338400669.391 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T17:57:49.391Z,1338400669.391 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-30T17:57:49.392Z,1338400669.392 [Default:GPS] Running Loop=1
2012-05-30T17:57:49.392Z,1338400669.392 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-30T17:57:49.392Z,1338400669.392 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-30T17:57:49.392Z,1338400669.392 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-30T17:57:49.392Z,1338400669.392 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-30T17:57:49.392Z,1338400669.392 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T17:57:49.393Z,1338400669.393 [Default:GPS:B.GoToSurface] Stopped
2012-05-30T17:57:49.393Z,1338400669.393 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T17:57:49.394Z,1338400669.394 [Default:GPS:Read_GPS] Running Loop=1
2012-05-30T17:57:50.040Z,1338400670.040 [NAL9601](INFO): Powering up
2012-05-30T17:58:55.763Z,1338400735.763 [NAL9601](INFO): NAL9601 initialized
2012-05-30T17:59:19.478Z,1338400759.478 [NAL9601](INFO): SBD MO Status=1, MOMSN=6943, MT Status=0, MTMSN=0
2012-05-30T17:59:19.615Z,1338400759.615 [NAL9601](INFO): Sent 101 bytes from file Logs/20120530T160348/shore0013.lzma
2012-05-30T17:59:19.615Z,1338400759.615 [NAL9601](INFO): Packets left to send: 0
2012-05-30T17:59:19.616Z,1338400759.616 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000027
2012-05-30T17:59:29.478Z,1338400769.478 [NAL9601](INFO): SBD MO Status=0, MOMSN=6944, MT Status=0, MTMSN=0
2012-05-30T17:59:29.663Z,1338400769.662 [Default:Iridium:Read_Iridium] Stopped
2012-05-30T17:59:29.663Z,1338400769.663 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-30T17:59:29.663Z,1338400769.663 [Default:Iridium] Stopped
2012-05-30T17:59:29.663Z,1338400769.663 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-30T17:59:29.663Z,1338400769.663 [Default:Iridium:A.SetSpeed] Stopped
2012-05-30T17:59:29.663Z,1338400769.663 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T17:59:29.896Z,1338400769.896 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-30T17:59:29.896Z,1338400769.896 [Default:CallIridium:B] Stopped
2012-05-30T17:59:29.896Z,1338400769.896 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-30T17:59:29.896Z,1338400769.896 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-30T17:59:29.896Z,1338400769.896 [Default:CallIridium] Stopped
2012-05-30T17:59:29.896Z,1338400769.896 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-30T18:00:10.783Z,1338400810.783 [NAL9601](IMPORTANT): GPS fix at: 1338400803.00
2012-05-30T18:00:10.798Z,1338400810.798 [Default:GPS:Read_GPS] Stopped
2012-05-30T18:00:10.799Z,1338400810.799 [Default:GPS:D] Running Loop=1
2012-05-30T18:00:11.174Z,1338400811.174 [Default:GPS:D] Stopped
2012-05-30T18:00:11.174Z,1338400811.174 [Default:GPS](INFO): Completed Default:GPS
2012-05-30T18:00:11.175Z,1338400811.175 [Default:GPS] Stopped
2012-05-30T18:00:11.175Z,1338400811.175 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-30T18:00:11.175Z,1338400811.175 [Default:GPS:A.SetSpeed] Stopped
2012-05-30T18:00:11.175Z,1338400811.175 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T18:00:26.700Z,1338400826.700 [NAL9601](INFO): Powering down
2012-05-30T18:04:31.812Z,1338401071.812 [Default:CallIridium] Running Loop=1
2012-05-30T18:04:31.812Z,1338401071.812 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-30T18:04:31.812Z,1338401071.812 [Default:CallIridium:A] Running Loop=1
2012-05-30T18:04:31.812Z,1338401071.812 [Default:CallIridium:A] Stopped
2012-05-30T18:04:31.812Z,1338401071.812 [Default:CallIridium:B] Running Loop=1
2012-05-30T18:04:31.813Z,1338401071.813 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-30T18:04:36.853Z,1338401076.853 [Default:Iridium] Running Loop=1
2012-05-30T18:04:36.853Z,1338401076.853 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-30T18:04:36.853Z,1338401076.853 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-30T18:04:36.853Z,1338401076.853 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-30T18:04:36.854Z,1338401076.853 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-30T18:04:36.854Z,1338401076.854 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T18:04:36.855Z,1338401076.855 [Default:Iridium:B.GoToSurface] Stopped
2012-05-30T18:04:36.855Z,1338401076.855 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T18:04:36.855Z,1338401076.855 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-30T18:04:36.855Z,1338401076.855 [Default:GPS] Running Loop=1
2012-05-30T18:04:36.855Z,1338401076.855 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-30T18:04:36.855Z,1338401076.855 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-30T18:04:36.855Z,1338401076.855 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-30T18:04:36.856Z,1338401076.856 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-30T18:04:36.856Z,1338401076.856 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T18:04:36.857Z,1338401076.857 [Default:GPS:B.GoToSurface] Stopped
2012-05-30T18:04:36.857Z,1338401076.857 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T18:04:36.857Z,1338401076.857 [Default:GPS:Read_GPS] Running Loop=1
2012-05-30T18:04:37.392Z,1338401077.392 [NAL9601](INFO): Powering up
2012-05-30T18:05:43.115Z,1338401143.115 [NAL9601](INFO): NAL9601 initialized
2012-05-30T18:06:00.066Z,1338401160.066 [NAL9601](INFO): SBD MO Status=1, MOMSN=6945, MT Status=0, MTMSN=0
2012-05-30T18:06:00.283Z,1338401160.283 [NAL9601](INFO): Sent 150 bytes from file Logs/20120530T160348/shore0014.lzma
2012-05-30T18:06:00.283Z,1338401160.283 [NAL9601](INFO): Packets left to send: 0
2012-05-30T18:06:00.284Z,1338401160.284 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000028
2012-05-30T18:06:04.466Z,1338401164.466 [NAL9601](INFO): SBD MO Status=0, MOMSN=6946, MT Status=0, MTMSN=0
2012-05-30T18:06:04.686Z,1338401164.686 [Default:Iridium:Read_Iridium] Stopped
2012-05-30T18:06:04.687Z,1338401164.687 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-30T18:06:04.687Z,1338401164.687 [Default:Iridium] Stopped
2012-05-30T18:06:04.687Z,1338401164.687 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-30T18:06:04.687Z,1338401164.687 [Default:Iridium:A.SetSpeed] Stopped
2012-05-30T18:06:04.687Z,1338401164.687 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T18:06:04.879Z,1338401164.879 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-30T18:06:04.879Z,1338401164.879 [Default:CallIridium:B] Stopped
2012-05-30T18:06:04.879Z,1338401164.879 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-30T18:06:04.879Z,1338401164.879 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-30T18:06:04.879Z,1338401164.879 [Default:CallIridium] Stopped
2012-05-30T18:06:04.879Z,1338401164.879 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-30T18:06:15.686Z,1338401175.686 [NAL9601](IMPORTANT): GPS fix at: 1338401169.00
2012-05-30T18:06:15.709Z,1338401175.709 [Default:GPS:Read_GPS] Stopped
2012-05-30T18:06:15.709Z,1338401175.709 [Default:GPS:D] Running Loop=1
2012-05-30T18:06:16.075Z,1338401176.075 [Default:GPS:D] Stopped
2012-05-30T18:06:16.076Z,1338401176.076 [Default:GPS](INFO): Completed Default:GPS
2012-05-30T18:06:16.076Z,1338401176.076 [Default:GPS] Stopped
2012-05-30T18:06:16.076Z,1338401176.076 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-30T18:06:16.076Z,1338401176.076 [Default:GPS:A.SetSpeed] Stopped
2012-05-30T18:06:16.076Z,1338401176.076 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T18:06:31.607Z,1338401191.607 [NAL9601](INFO): Powering down
2012-05-30T18:11:06.625Z,1338401466.625 [Default:CallIridium] Running Loop=1
2012-05-30T18:11:06.625Z,1338401466.625 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-30T18:11:06.625Z,1338401466.625 [Default:CallIridium:A] Running Loop=1
2012-05-30T18:11:06.625Z,1338401466.625 [Default:CallIridium:A] Stopped
2012-05-30T18:11:06.626Z,1338401466.625 [Default:CallIridium:B] Running Loop=1
2012-05-30T18:11:06.626Z,1338401466.626 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-30T18:11:11.887Z,1338401471.887 [Default:Iridium] Running Loop=1
2012-05-30T18:11:11.887Z,1338401471.887 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-30T18:11:11.887Z,1338401471.887 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-30T18:11:11.887Z,1338401471.887 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-30T18:11:11.887Z,1338401471.887 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-30T18:11:11.887Z,1338401471.887 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T18:11:11.888Z,1338401471.888 [Default:Iridium:B.GoToSurface] Stopped
2012-05-30T18:11:11.888Z,1338401471.888 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T18:11:11.888Z,1338401471.888 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-30T18:11:11.889Z,1338401471.889 [Default:GPS] Running Loop=1
2012-05-30T18:11:11.889Z,1338401471.889 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-30T18:11:11.889Z,1338401471.889 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-30T18:11:11.889Z,1338401471.889 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-30T18:11:11.889Z,1338401471.889 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-30T18:11:11.889Z,1338401471.889 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T18:11:11.895Z,1338401471.895 [Default:GPS:B.GoToSurface] Stopped
2012-05-30T18:11:11.895Z,1338401471.895 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T18:11:11.895Z,1338401471.895 [Default:GPS:Read_GPS] Running Loop=1
2012-05-30T18:11:12.504Z,1338401472.504 [NAL9601](INFO): Powering up
2012-05-30T18:12:18.031Z,1338401538.031 [NAL9601](INFO): NAL9601 initialized
2012-05-30T18:12:33.445Z,1338401553.445 [NAL9601](INFO): SBD MO Status=1, MOMSN=6947, MT Status=0, MTMSN=0
2012-05-30T18:12:33.591Z,1338401553.591 [NAL9601](INFO): Sent 150 bytes from file Logs/20120530T160348/shore0015.lzma
2012-05-30T18:12:33.591Z,1338401553.591 [NAL9601](INFO): Packets left to send: 0
2012-05-30T18:12:33.592Z,1338401553.592 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000029
2012-05-30T18:12:40.650Z,1338401560.649 [NAL9601](INFO): SBD MO Status=0, MOMSN=6948, MT Status=0, MTMSN=0
2012-05-30T18:12:40.798Z,1338401560.798 [Default:Iridium:Read_Iridium] Stopped
2012-05-30T18:12:40.799Z,1338401560.799 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-30T18:12:40.799Z,1338401560.799 [Default:Iridium] Stopped
2012-05-30T18:12:40.799Z,1338401560.799 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-30T18:12:40.799Z,1338401560.799 [Default:Iridium:A.SetSpeed] Stopped
2012-05-30T18:12:40.799Z,1338401560.799 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T18:12:41.054Z,1338401561.054 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-30T18:12:41.054Z,1338401561.054 [Default:CallIridium:B] Stopped
2012-05-30T18:12:41.054Z,1338401561.054 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-30T18:12:41.054Z,1338401561.054 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-30T18:12:41.055Z,1338401561.055 [Default:CallIridium] Stopped
2012-05-30T18:12:41.055Z,1338401561.055 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-30T18:12:41.846Z,1338401561.846 [NAL9601](IMPORTANT): GPS fix at: 1338401556.00
2012-05-30T18:12:41.861Z,1338401561.861 [Default:GPS:Read_GPS] Stopped
2012-05-30T18:12:41.861Z,1338401561.861 [Default:GPS:D] Running Loop=1
2012-05-30T18:12:42.255Z,1338401562.255 [Default:GPS:D] Stopped
2012-05-30T18:12:42.255Z,1338401562.255 [Default:GPS](INFO): Completed Default:GPS
2012-05-30T18:12:42.255Z,1338401562.256 [Default:GPS] Stopped
2012-05-30T18:12:42.256Z,1338401562.256 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-30T18:12:42.256Z,1338401562.256 [Default:GPS:A.SetSpeed] Stopped
2012-05-30T18:12:42.256Z,1338401562.256 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T18:12:57.856Z,1338401577.856 [NAL9601](INFO): Powering down
2012-05-30T18:17:42.857Z,1338401862.856 [Default:CallIridium] Running Loop=1
2012-05-30T18:17:42.857Z,1338401862.857 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-30T18:17:42.857Z,1338401862.857 [Default:CallIridium:A] Running Loop=1
2012-05-30T18:17:42.857Z,1338401862.857 [Default:CallIridium:A] Stopped
2012-05-30T18:17:42.857Z,1338401862.857 [Default:CallIridium:B] Running Loop=1
2012-05-30T18:17:42.857Z,1338401862.857 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-30T18:17:47.787Z,1338401867.787 [Default:Iridium] Running Loop=1
2012-05-30T18:17:47.787Z,1338401867.787 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-30T18:17:47.787Z,1338401867.787 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-30T18:17:47.787Z,1338401867.787 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-30T18:17:47.787Z,1338401867.787 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-30T18:17:47.787Z,1338401867.787 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T18:17:47.788Z,1338401867.788 [Default:Iridium:B.GoToSurface] Stopped
2012-05-30T18:17:47.789Z,1338401867.789 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T18:17:47.789Z,1338401867.789 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-30T18:17:47.789Z,1338401867.789 [Default:GPS] Running Loop=1
2012-05-30T18:17:47.789Z,1338401867.789 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-30T18:17:47.789Z,1338401867.789 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-30T18:17:47.789Z,1338401867.789 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-30T18:17:47.789Z,1338401867.789 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-30T18:17:47.789Z,1338401867.789 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T18:17:47.790Z,1338401867.790 [Default:GPS:B.GoToSurface] Stopped
2012-05-30T18:17:47.791Z,1338401867.791 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T18:17:47.791Z,1338401867.791 [Default:GPS:Read_GPS] Running Loop=1
2012-05-30T18:17:48.444Z,1338401868.444 [NAL9601](INFO): Powering up
2012-05-30T18:18:54.167Z,1338401934.167 [NAL9601](INFO): NAL9601 initialized
2012-05-30T18:18:55.264Z,1338401935.263 [NAL9601](IMPORTANT): GPS fix at: 1338401930.00
2012-05-30T18:18:55.280Z,1338401935.280 [Default:GPS:Read_GPS] Stopped
2012-05-30T18:18:55.280Z,1338401935.280 [Default:GPS:D] Running Loop=1
2012-05-30T18:18:55.709Z,1338401935.709 [Default:GPS:D] Stopped
2012-05-30T18:18:55.709Z,1338401935.709 [Default:GPS](INFO): Completed Default:GPS
2012-05-30T18:18:55.709Z,1338401935.709 [Default:GPS] Stopped
2012-05-30T18:18:55.709Z,1338401935.709 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-30T18:18:55.710Z,1338401935.710 [Default:GPS:A.SetSpeed] Stopped
2012-05-30T18:18:55.710Z,1338401935.710 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T18:19:13.169Z,1338401953.168 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=6949, MT Status=1, MTMSN=2633
2012-05-30T18:19:13.327Z,1338401953.327 [NAL9601](INFO): Sent 172 bytes from file Logs/20120530T160348/shore0016.lzma
2012-05-30T18:19:13.327Z,1338401953.327 [NAL9601](INFO): Packets left to send: 0
2012-05-30T18:19:13.328Z,1338401953.328 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000030
2012-05-30T18:19:13.828Z,1338401953.828 [NAL9601](INFO): Received command:load Transport/transit_3km.xml;set transit_3km.Wpt1Lat 36.9 degree;set transit_3km.Wpt1Lon -121.9 degree;set transit_3km.TimeoutDuration 300 minute;run 
2012-05-30T18:19:13.849Z,1338401953.849 [CommandLine](IMPORTANT): got command load ./Missions/Transport/transit_3km.xml
2012-05-30T18:19:13.849Z,1338401953.849 [MissionManager](INFO): Loading Mission: ./Missions/Transport/transit_3km.xml
2012-05-30T18:19:13.918Z,1338401953.918 [MissionManager](INFO): DefineArg transit_3km.ApproachDepth = 10.000000 m
2012-05-30T18:19:13.921Z,1338401953.921 [MissionManager](INFO): DefineArg transit_3km.Wpt1Lat = 36.806966 arcdeg
2012-05-30T18:19:13.935Z,1338401953.935 [MissionManager](INFO): DefineArg transit_3km.Wpt1Lon = -121.824326 arcdeg
2012-05-30T18:19:13.937Z,1338401953.937 [MissionManager](INFO): DefineArg transit_3km.Speed = 1.000000 m/s
2012-05-30T18:19:13.940Z,1338401953.940 [MissionManager](INFO): DefineArg transit_3km.MaxDepth = 20.000000 m
2012-05-30T18:19:13.942Z,1338401953.942 [MissionManager](INFO): DefineArg transit_3km.TimeoutDuration = 240.000000 min
2012-05-30T18:19:13.943Z,1338401953.943 [transit_3km:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-05-30T18:19:13.960Z,1338401953.960 [transit_3km:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-05-30T18:19:13.966Z,1338401953.966 [transit_3km:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2012-05-30T18:19:13.976Z,1338401953.976 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-30T18:19:13.979Z,1338401953.979 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Construct.
2012-05-30T18:19:14.000Z,1338401954.000 [transit_3km:WaypointOne:A.Pitch](DEBUG): Construct.
2012-05-30T18:19:14.004Z,1338401954.004 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Construct.
2012-05-30T18:19:14.006Z,1338401954.006 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Construct Waypoint.
2012-05-30T18:19:14.027Z,1338401954.027 [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-05-30T18:19:14.028Z,1338401954.028 [CommandLine](IMPORTANT): Loaded ./Missions/Transport/transit_3km.xml
2012-05-30T18:19:14.183Z,1338401954.183 [CommandLine](IMPORTANT): got command set transit_3km.Wpt1Lat 36.900002 degree
2012-05-30T18:19:14.338Z,1338401954.338 [CommandLine](IMPORTANT): got command set transit_3km.Wpt1Lon -121.900002 degree
2012-05-30T18:19:14.479Z,1338401954.480 [CommandLine](IMPORTANT): got command set transit_3km.TimeoutDuration 300.000000 minute
2012-05-30T18:19:14.481Z,1338401954.481 [CommandLine](IMPORTANT): got command run 
2012-05-30T18:19:14.481Z,1338401954.481 [CommandLine](IMPORTANT): Running 
2012-05-30T18:19:14.497Z,1338401954.497 [Default] Stopped
2012-05-30T18:19:14.498Z,1338401954.497 [Default](INFO): Aggregate::uninitialize Default
2012-05-30T18:19:14.498Z,1338401954.498 [Default:Iridium] Stopped
2012-05-30T18:19:14.498Z,1338401954.498 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-30T18:19:14.498Z,1338401954.498 [Default:Iridium:A.SetSpeed] Stopped
2012-05-30T18:19:14.498Z,1338401954.498 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T18:19:14.498Z,1338401954.498 [Default:Iridium:Read_Iridium] Stopped
2012-05-30T18:19:14.498Z,1338401954.498 [Default:CallIridium] Stopped
2012-05-30T18:19:14.498Z,1338401954.498 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-30T18:19:14.498Z,1338401954.498 [Default:CallIridium:B] Stopped
2012-05-30T18:19:14.498Z,1338401954.498 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-30T18:19:14.498Z,1338401954.498 [Default:D.SetSpeed] Stopped
2012-05-30T18:19:14.498Z,1338401954.499 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-05-30T18:19:14.498Z,1338401954.499 [Default:E.GoToSurface] Stopped
2012-05-30T18:19:14.499Z,1338401954.499 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T18:19:14.499Z,1338401954.499 [Default:F.Wait] Stopped
2012-05-30T18:19:14.499Z,1338401954.499 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2012-05-30T18:19:14.499Z,1338401954.499 [MissionManager](IMPORTANT): Started mission transit_3km
2012-05-30T18:19:14.499Z,1338401954.499 [transit_3km] Running Loop=1
2012-05-30T18:19:14.499Z,1338401954.499 [transit_3km](INFO): Aggregate::initialize transit_3km
2012-05-30T18:19:14.499Z,1338401954.499 [transit_3km:A.AltitudeEnvelope] Running Loop=1
2012-05-30T18:19:14.499Z,1338401954.499 [transit_3km:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-05-30T18:19:14.500Z,1338401954.500 [transit_3km:B.DepthEnvelope] Running Loop=1
2012-05-30T18:19:14.500Z,1338401954.500 [transit_3km:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-05-30T18:19:14.500Z,1338401954.500 [transit_3km:C.OffshoreEnvelope] Running Loop=1
2012-05-30T18:19:14.500Z,1338401954.500 [transit_3km:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2012-05-30T18:19:14.500Z,1338401954.500 [transit_3km:SURFACECOMMS] Running Loop=1
2012-05-30T18:19:14.501Z,1338401954.500 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2012-05-30T18:19:14.501Z,1338401954.501 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-05-30T18:19:14.501Z,1338401954.501 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T18:19:14.503Z,1338401954.503 [transit_3km:SURFACECOMMS:B] Running Loop=1
2012-05-30T18:19:14.503Z,1338401954.503 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:B
2012-05-30T18:19:14.503Z,1338401954.503 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-05-30T18:19:14.503Z,1338401954.503 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-05-30T18:19:14.503Z,1338401954.503 [transit_3km:SURFACECOMMS:B:B] Running Loop=1
2012-05-30T18:19:14.503Z,1338401954.503 [transit_3km:C.OffshoreEnvelope] Running Loop=1
2012-05-30T18:19:14.504Z,1338401954.504 [transit_3km:B.DepthEnvelope] Running Loop=1
2012-05-30T18:19:14.505Z,1338401954.505 [transit_3km:A.AltitudeEnvelope] Running Loop=1
2012-05-30T18:19:14.752Z,1338401954.752 [transit_3km:SURFACECOMMS:B:B](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-05-30T18:19:14.753Z,1338401954.753 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-05-30T18:19:16.715Z,1338401956.715 [NAL9601](IMPORTANT): GPS fix at: 1338401951.00
2012-05-30T18:19:16.729Z,1338401956.729 [transit_3km:SURFACECOMMS:B:B] Stopped
2012-05-30T18:19:16.729Z,1338401956.729 [transit_3km:SURFACECOMMS:B:C] Running Loop=1
2012-05-30T18:19:17.121Z,1338401957.121 [transit_3km:SURFACECOMMS:B:C](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-05-30T18:19:32.906Z,1338401972.906 [NAL9601](INFO): SBD MO Status=0, MOMSN=6950, MT Status=0, MTMSN=0
2012-05-30T18:19:45.664Z,1338401985.664 [NAL9601](INFO): SBD MO Status=1, MOMSN=6951, MT Status=0, MTMSN=0
2012-05-30T18:19:45.875Z,1338401985.875 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0017.lzma
2012-05-30T18:19:45.875Z,1338401985.875 [NAL9601](INFO): Packets left to send: 1
2012-05-30T18:19:45.876Z,1338401985.876 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000031
2012-05-30T18:19:51.547Z,1338401991.547 [NAL9601](INFO): SBD MO Status=1, MOMSN=6952, MT Status=0, MTMSN=0
2012-05-30T18:19:51.667Z,1338401991.667 [NAL9601](INFO): Sent 24 bytes from file Logs/20120530T160348/shore0017.lzma
2012-05-30T18:19:51.667Z,1338401991.667 [NAL9601](INFO): Packets left to send: 0
2012-05-30T18:19:51.668Z,1338401991.668 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000032
2012-05-30T18:19:58.334Z,1338401998.334 [NAL9601](INFO): SBD MO Status=0, MOMSN=6953, MT Status=0, MTMSN=0
2012-05-30T18:19:58.468Z,1338401998.468 [transit_3km:SURFACECOMMS:B:C] Stopped
2012-05-30T18:19:58.469Z,1338401998.469 [transit_3km:SURFACECOMMS:B:D] Running Loop=1
2012-05-30T18:19:58.751Z,1338401998.751 [transit_3km:SURFACECOMMS:B:D](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-05-30T18:20:00.724Z,1338402000.724 [NAL9601](IMPORTANT): GPS fix at: 1338401995.00
2012-05-30T18:20:00.738Z,1338402000.738 [transit_3km:SURFACECOMMS:B:D] Stopped
2012-05-30T18:20:00.739Z,1338402000.739 [transit_3km:SURFACECOMMS:B](INFO): Completed transit_3km:SURFACECOMMS:B
2012-05-30T18:20:00.739Z,1338402000.739 [transit_3km:SURFACECOMMS:B] Stopped
2012-05-30T18:20:00.739Z,1338402000.739 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:B
2012-05-30T18:20:00.739Z,1338402000.739 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-05-30T18:20:00.739Z,1338402000.739 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T18:20:00.740Z,1338402000.740 [transit_3km:SURFACECOMMS](INFO): Completed transit_3km:SURFACECOMMS
2012-05-30T18:20:00.740Z,1338402000.740 [transit_3km:SURFACECOMMS] Stopped
2012-05-30T18:20:00.740Z,1338402000.740 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2012-05-30T18:20:00.740Z,1338402000.740 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2012-05-30T18:20:00.740Z,1338402000.740 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T18:20:00.740Z,1338402000.740 [transit_3km:WaypointOne] Running Loop=1
2012-05-30T18:20:00.741Z,1338402000.741 [transit_3km:WaypointOne](INFO): Aggregate::initialize transit_3km:WaypointOne
2012-05-30T18:20:00.741Z,1338402000.741 [transit_3km:WaypointOne:A.Pitch] Running Loop=1
2012-05-30T18:20:00.741Z,1338402000.741 [transit_3km:WaypointOne:A.Pitch](DEBUG): Initialize.
2012-05-30T18:20:00.741Z,1338402000.741 [transit_3km:WaypointOne:B.SetSpeed] Running Loop=1
2012-05-30T18:20:00.741Z,1338402000.741 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Initialize.
2012-05-30T18:20:00.741Z,1338402000.741 [transit_3km:WaypointOne:WaypointW1.Waypoint] Running Loop=1
2012-05-30T18:20:00.741Z,1338402000.741 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Initialize WaypointComponent.
2012-05-30T18:20:01.120Z,1338402001.120 [transit_3km:WaypointOne:B.SetSpeed] Running Loop=1
2012-05-30T18:20:01.121Z,1338402001.121 [transit_3km:WaypointOne:A.Pitch] Running Loop=1
2012-05-30T18:20:07.158Z,1338402007.158 [NAL9601](INFO): Powering down
2012-05-30T18:20:17.179Z,1338402017.179 [Radio_Freewave](INFO): Powering down
2012-05-30T18:20:38.289Z,1338402038.289 [Radio_Freewave](INFO): Powering up
2012-05-30T18:21:03.152Z,1338402063.152 [Radio_Freewave](INFO): Powering down
2012-05-30T18:55:00.846Z,1338404100.846 [transit_3km:NeedComms] Running Loop=1
2012-05-30T18:55:00.850Z,1338404100.851 [transit_3km:NeedComms](INFO): Aggregate::initialize transit_3km:NeedComms
2012-05-30T18:55:00.851Z,1338404100.851 [transit_3km:NeedComms:NEEDCOMMS] Running Loop=1
2012-05-30T18:55:00.851Z,1338404100.851 [transit_3km:NeedComms:NEEDCOMMS](INFO): Aggregate::initialize transit_3km:NeedComms:NEEDCOMMS
2012-05-30T18:55:01.240Z,1338404101.240 [transit_3km:SURFACECOMMS] Running Loop=1
2012-05-30T18:55:01.240Z,1338404101.240 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2012-05-30T18:55:01.240Z,1338404101.240 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-05-30T18:55:01.240Z,1338404101.240 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T18:57:37.625Z,1338404257.625 [Radio_Freewave](INFO): Powering up
2012-05-30T18:57:37.636Z,1338404257.636 [transit_3km:SURFACECOMMS:B] Running Loop=1
2012-05-30T18:57:37.636Z,1338404257.636 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:B
2012-05-30T18:57:37.636Z,1338404257.636 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-05-30T18:57:37.636Z,1338404257.636 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-05-30T18:57:37.636Z,1338404257.636 [transit_3km:SURFACECOMMS:B:B] Running Loop=1
2012-05-30T18:57:38.419Z,1338404258.419 [NAL9601](INFO): Powering up
2012-05-30T18:58:05.624Z,1338404285.624 [Radio_Freewave](INFO): Powering down
2012-05-30T18:58:06.429Z,1338404286.429 [Radio_Freewave](INFO): Powering up
2012-05-30T18:58:09.027Z,1338404289.027 [ThrusterServo](FAULT): getVelocity uart error serial timeout
2012-05-30T18:58:09.027Z,1338404289.027 [ThrusterServo](FAULT): Thruster uart error: serial timeout
2012-05-30T18:58:09.027Z,1338404289.027 [ThrusterServo] Communications Fault, FailCount= 1
2012-05-30T18:58:09.027Z,1338404289.027 [ThrusterServo](ERROR): Communications Fault
2012-05-30T18:58:09.030Z,1338404289.030 [CBIT](ERROR): Communications Fault in component: ThrusterServo
2012-05-30T18:58:09.118Z,1338404289.118 [Radio_Freewave](INFO): Powering down
2012-05-30T18:58:09.160Z,1338404289.160 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2012-05-30T18:58:09.160Z,1338404289.160 [ThrusterServo](INFO): Powering down
2012-05-30T18:58:09.162Z,1338404289.162 [CBIT](INFO): Clearing failed state for component ThrusterServo
2012-05-30T18:58:09.162Z,1338404289.162 [ThrusterServo] No Fault, FailCount= 1
2012-05-30T18:58:09.508Z,1338404289.508 [Radio_Freewave](INFO): Powering up
2012-05-30T18:58:09.969Z,1338404289.969 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-05-30T18:58:10.087Z,1338404290.087 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-05-30T18:58:43.847Z,1338404323.847 [NAL9601](INFO): NAL9601 initialized
2012-05-30T18:58:45.006Z,1338404325.006 [NAL9601](IMPORTANT): GPS fix at: 1338404323.00
2012-05-30T18:58:45.020Z,1338404325.020 [Navigation](IMPORTANT): Navigation Error 2.5 %DT

2012-05-30T18:58:45.021Z,1338404325.021 [transit_3km:SURFACECOMMS:B:B] Stopped
2012-05-30T18:58:45.021Z,1338404325.021 [transit_3km:SURFACECOMMS:B:C] Running Loop=1
2012-05-30T18:59:11.317Z,1338404351.317 [NAL9601](INFO): SBD MO Status=1, MOMSN=6954, MT Status=0, MTMSN=0
2012-05-30T18:59:11.491Z,1338404351.491 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0018.lzma
2012-05-30T18:59:11.491Z,1338404351.491 [NAL9601](INFO): Packets left to send: 7
2012-05-30T18:59:11.492Z,1338404351.492 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000033
2012-05-30T18:59:19.418Z,1338404359.418 [NAL9601](INFO): SBD MO Status=1, MOMSN=6955, MT Status=0, MTMSN=0
2012-05-30T18:59:19.579Z,1338404359.579 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0018.lzma
2012-05-30T18:59:19.579Z,1338404359.579 [NAL9601](INFO): Packets left to send: 6
2012-05-30T18:59:19.580Z,1338404359.580 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000034
2012-05-30T18:59:32.305Z,1338404372.305 [NAL9601](INFO): SBD MO Status=1, MOMSN=6956, MT Status=0, MTMSN=0
2012-05-30T18:59:32.463Z,1338404372.463 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0018.lzma
2012-05-30T18:59:32.463Z,1338404372.463 [NAL9601](INFO): Packets left to send: 5
2012-05-30T18:59:32.464Z,1338404372.464 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000035
2012-05-30T18:59:43.601Z,1338404383.601 [NAL9601](INFO): SBD MO Status=1, MOMSN=6957, MT Status=0, MTMSN=0
2012-05-30T18:59:43.747Z,1338404383.747 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0018.lzma
2012-05-30T18:59:43.747Z,1338404383.747 [NAL9601](INFO): Packets left to send: 4
2012-05-30T18:59:43.748Z,1338404383.748 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000036
2012-05-30T18:59:52.501Z,1338404392.501 [NAL9601](INFO): SBD MO Status=1, MOMSN=6958, MT Status=0, MTMSN=0
2012-05-30T18:59:52.639Z,1338404392.639 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0018.lzma
2012-05-30T18:59:52.639Z,1338404392.639 [NAL9601](INFO): Packets left to send: 3
2012-05-30T18:59:52.640Z,1338404392.640 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000037
2012-05-30T19:00:01.866Z,1338404401.866 [NAL9601](INFO): SBD MO Status=1, MOMSN=6959, MT Status=0, MTMSN=0
2012-05-30T19:00:02.011Z,1338404402.011 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0018.lzma
2012-05-30T19:00:02.011Z,1338404402.011 [NAL9601](INFO): Packets left to send: 2
2012-05-30T19:00:02.012Z,1338404402.012 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000038
2012-05-30T19:00:09.989Z,1338404409.989 [NAL9601](INFO): SBD MO Status=1, MOMSN=6960, MT Status=0, MTMSN=0
2012-05-30T19:00:10.199Z,1338404410.199 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0018.lzma
2012-05-30T19:00:10.199Z,1338404410.199 [NAL9601](INFO): Packets left to send: 1
2012-05-30T19:00:10.200Z,1338404410.200 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000039
2012-05-30T19:00:18.059Z,1338404418.059 [NAL9601](INFO): SBD MO Status=1, MOMSN=6961, MT Status=0, MTMSN=0
2012-05-30T19:00:18.187Z,1338404418.187 [NAL9601](INFO): Sent 160 bytes from file Logs/20120530T160348/shore0018.lzma
2012-05-30T19:00:18.187Z,1338404418.187 [NAL9601](INFO): Packets left to send: 0
2012-05-30T19:00:18.188Z,1338404418.188 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000040
2012-05-30T19:00:28.441Z,1338404428.441 [NAL9601](INFO): SBD MO Status=0, MOMSN=6962, MT Status=0, MTMSN=0
2012-05-30T19:00:28.585Z,1338404428.585 [transit_3km:SURFACECOMMS:B:C] Stopped
2012-05-30T19:00:28.585Z,1338404428.585 [transit_3km:SURFACECOMMS:B:D] Running Loop=1
2012-05-30T19:00:30.842Z,1338404430.842 [NAL9601](IMPORTANT): GPS fix at: 1338404429.00
2012-05-30T19:00:30.856Z,1338404430.856 [transit_3km:SURFACECOMMS:B:D] Stopped
2012-05-30T19:00:30.857Z,1338404430.857 [transit_3km:SURFACECOMMS:B](INFO): Completed transit_3km:SURFACECOMMS:B
2012-05-30T19:00:30.857Z,1338404430.857 [transit_3km:SURFACECOMMS:B] Stopped
2012-05-30T19:00:30.857Z,1338404430.857 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:B
2012-05-30T19:00:30.857Z,1338404430.857 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-05-30T19:00:30.857Z,1338404430.857 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T19:00:30.858Z,1338404430.858 [transit_3km:SURFACECOMMS](INFO): Completed transit_3km:SURFACECOMMS
2012-05-30T19:00:30.858Z,1338404430.858 [transit_3km:SURFACECOMMS] Stopped
2012-05-30T19:00:30.859Z,1338404430.859 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2012-05-30T19:00:30.859Z,1338404430.859 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2012-05-30T19:00:30.859Z,1338404430.859 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T19:00:31.273Z,1338404431.273 [transit_3km:NeedComms:NEEDCOMMS](INFO): Completed transit_3km:NeedComms:NEEDCOMMS
2012-05-30T19:00:31.273Z,1338404431.273 [transit_3km:NeedComms:NEEDCOMMS] Stopped
2012-05-30T19:00:31.273Z,1338404431.273 [transit_3km:NeedComms:NEEDCOMMS](INFO): Aggregate::uninitialize transit_3km:NeedComms:NEEDCOMMS
2012-05-30T19:00:31.274Z,1338404431.274 [transit_3km:NeedComms](INFO): Completed transit_3km:NeedComms
2012-05-30T19:00:31.274Z,1338404431.274 [transit_3km:NeedComms] Stopped
2012-05-30T19:00:31.274Z,1338404431.274 [transit_3km:NeedComms](INFO): Aggregate::uninitialize transit_3km:NeedComms
2012-05-30T19:00:37.396Z,1338404437.396 [NAL9601](INFO): Powering down
2012-05-30T19:00:41.733Z,1338404441.733 [Radio_Freewave](INFO): Powering down
2012-05-30T19:01:00.905Z,1338404460.905 [Radio_Freewave](INFO): Powering up
2012-05-30T19:01:06.527Z,1338404466.527 [Radio_Freewave](INFO): Powering down
2012-05-30T19:33:58.262Z,1338406438.263 [ThrusterServo](FAULT): Overload Error
2012-05-30T19:33:58.263Z,1338406438.263 [ThrusterServo] Hardware Fault, FailCount= 1
2012-05-30T19:33:58.263Z,1338406438.263 [ThrusterServo](ERROR): Hardware Fault
2012-05-30T19:33:58.265Z,1338406438.265 [CBIT](ERROR): Hardware Fault in component: ThrusterServo
2012-05-30T19:33:58.492Z,1338406438.492 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2012-05-30T19:33:58.492Z,1338406438.492 [ThrusterServo](INFO): Powering down
2012-05-30T19:33:58.494Z,1338406438.494 [CBIT](INFO): Clearing failed state for component ThrusterServo
2012-05-30T19:33:58.494Z,1338406438.494 [ThrusterServo] No Fault, FailCount= 1
2012-05-30T19:33:59.312Z,1338406439.312 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-05-30T19:33:59.436Z,1338406439.436 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-05-30T19:35:31.014Z,1338406531.014 [transit_3km:NeedComms] Running Loop=1
2012-05-30T19:35:31.014Z,1338406531.014 [transit_3km:NeedComms](INFO): Aggregate::initialize transit_3km:NeedComms
2012-05-30T19:35:31.014Z,1338406531.014 [transit_3km:NeedComms:NEEDCOMMS] Running Loop=1
2012-05-30T19:35:31.014Z,1338406531.014 [transit_3km:NeedComms:NEEDCOMMS](INFO): Aggregate::initialize transit_3km:NeedComms:NEEDCOMMS
2012-05-30T19:35:31.423Z,1338406531.423 [transit_3km:SURFACECOMMS] Running Loop=1
2012-05-30T19:35:31.423Z,1338406531.423 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2012-05-30T19:35:31.423Z,1338406531.423 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-05-30T19:35:31.423Z,1338406531.423 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T19:38:05.893Z,1338406685.893 [Radio_Freewave](INFO): Powering up
2012-05-30T19:38:05.904Z,1338406685.904 [transit_3km:SURFACECOMMS:B] Running Loop=1
2012-05-30T19:38:05.904Z,1338406685.904 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:B
2012-05-30T19:38:05.904Z,1338406685.904 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-05-30T19:38:05.904Z,1338406685.904 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-05-30T19:38:05.904Z,1338406685.904 [transit_3km:SURFACECOMMS:B:B] Running Loop=1
2012-05-30T19:38:06.688Z,1338406686.688 [NAL9601](INFO): Powering up
2012-05-30T19:38:12.731Z,1338406692.731 [Radio_Freewave](INFO): Powering down
2012-05-30T19:38:15.097Z,1338406695.097 [Radio_Freewave](INFO): Powering up
2012-05-30T19:39:12.411Z,1338406752.411 [NAL9601](INFO): NAL9601 initialized
2012-05-30T19:39:13.493Z,1338406753.493 [NAL9601](IMPORTANT): GPS fix at: 1338406755.00
2012-05-30T19:39:13.507Z,1338406753.507 [Navigation](IMPORTANT): Navigation Error 10.1 %DT

2012-05-30T19:39:13.508Z,1338406753.508 [transit_3km:SURFACECOMMS:B:B] Stopped
2012-05-30T19:39:13.508Z,1338406753.508 [transit_3km:SURFACECOMMS:B:C] Running Loop=1
2012-05-30T19:39:34.258Z,1338406774.258 [NAL9601](INFO): SBD MO Status=1, MOMSN=6963, MT Status=0, MTMSN=0
2012-05-30T19:39:34.467Z,1338406774.467 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0019.lzma
2012-05-30T19:39:34.467Z,1338406774.467 [NAL9601](INFO): Packets left to send: 6
2012-05-30T19:39:34.468Z,1338406774.468 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000041
2012-05-30T19:39:46.758Z,1338406786.758 [NAL9601](INFO): SBD MO Status=1, MOMSN=6964, MT Status=0, MTMSN=0
2012-05-30T19:39:46.947Z,1338406786.947 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0019.lzma
2012-05-30T19:39:46.947Z,1338406786.947 [NAL9601](INFO): Packets left to send: 5
2012-05-30T19:39:46.948Z,1338406786.948 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000042
2012-05-30T19:39:59.673Z,1338406799.673 [Radio_Freewave](INFO): Powering down
2012-05-30T19:40:02.373Z,1338406802.373 [Radio_Freewave](INFO): Powering up
2012-05-30T19:40:03.165Z,1338406803.165 [NAL9601](INFO): SBD MO Status=2, MOMSN=6965, MT Status=2, MTMSN=0
2012-05-30T19:40:03.165Z,1338406803.165 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-30T19:41:10.141Z,1338406870.141 [NAL9601](INFO): SBD MO Status=2, MOMSN=6965, MT Status=2, MTMSN=0
2012-05-30T19:41:10.141Z,1338406870.141 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-30T19:41:22.904Z,1338406882.904 [NAL9601](INFO): SBD MO Status=1, MOMSN=6965, MT Status=0, MTMSN=0
2012-05-30T19:41:23.099Z,1338406883.099 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0019.lzma
2012-05-30T19:41:23.099Z,1338406883.099 [NAL9601](INFO): Packets left to send: 4
2012-05-30T19:41:23.100Z,1338406883.100 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000043
2012-05-30T19:41:32.605Z,1338406892.605 [NAL9601](INFO): SBD MO Status=1, MOMSN=6966, MT Status=0, MTMSN=0
2012-05-30T19:41:32.783Z,1338406892.783 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0019.lzma
2012-05-30T19:41:32.783Z,1338406892.783 [NAL9601](INFO): Packets left to send: 3
2012-05-30T19:41:32.784Z,1338406892.784 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000044
2012-05-30T19:41:42.007Z,1338406902.007 [NAL9601](INFO): SBD MO Status=1, MOMSN=6967, MT Status=0, MTMSN=0
2012-05-30T19:41:42.167Z,1338406902.167 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0019.lzma
2012-05-30T19:41:42.167Z,1338406902.167 [NAL9601](INFO): Packets left to send: 2
2012-05-30T19:41:42.168Z,1338406902.168 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000045
2012-05-30T19:41:50.118Z,1338406910.118 [NAL9601](INFO): SBD MO Status=1, MOMSN=6968, MT Status=0, MTMSN=0
2012-05-30T19:41:50.255Z,1338406910.255 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0019.lzma
2012-05-30T19:41:50.255Z,1338406910.255 [NAL9601](INFO): Packets left to send: 1
2012-05-30T19:41:50.256Z,1338406910.256 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000046
2012-05-30T19:41:58.440Z,1338406918.441 [NAL9601](INFO): SBD MO Status=1, MOMSN=6969, MT Status=0, MTMSN=0
2012-05-30T19:41:58.643Z,1338406918.643 [NAL9601](INFO): Sent 257 bytes from file Logs/20120530T160348/shore0019.lzma
2012-05-30T19:41:58.643Z,1338406918.643 [NAL9601](INFO): Packets left to send: 0
2012-05-30T19:41:58.644Z,1338406918.644 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000047
2012-05-30T19:42:06.451Z,1338406926.451 [NAL9601](INFO): SBD MO Status=0, MOMSN=6970, MT Status=0, MTMSN=0
2012-05-30T19:42:06.644Z,1338406926.644 [transit_3km:SURFACECOMMS:B:C] Stopped
2012-05-30T19:42:06.645Z,1338406926.645 [transit_3km:SURFACECOMMS:B:D] Running Loop=1
2012-05-30T19:42:08.834Z,1338406928.834 [NAL9601](IMPORTANT): GPS fix at: 1338406931.00
2012-05-30T19:42:08.848Z,1338406928.848 [transit_3km:SURFACECOMMS:B:D] Stopped
2012-05-30T19:42:08.848Z,1338406928.848 [transit_3km:SURFACECOMMS:B](INFO): Completed transit_3km:SURFACECOMMS:B
2012-05-30T19:42:08.848Z,1338406928.848 [transit_3km:SURFACECOMMS:B] Stopped
2012-05-30T19:42:08.849Z,1338406928.849 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:B
2012-05-30T19:42:08.849Z,1338406928.849 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-05-30T19:42:08.849Z,1338406928.849 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T19:42:08.850Z,1338406928.849 [transit_3km:SURFACECOMMS](INFO): Completed transit_3km:SURFACECOMMS
2012-05-30T19:42:08.850Z,1338406928.850 [transit_3km:SURFACECOMMS] Stopped
2012-05-30T19:42:08.850Z,1338406928.850 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2012-05-30T19:42:08.850Z,1338406928.850 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2012-05-30T19:42:08.850Z,1338406928.850 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T19:42:09.243Z,1338406929.243 [transit_3km:NeedComms:NEEDCOMMS](INFO): Completed transit_3km:NeedComms:NEEDCOMMS
2012-05-30T19:42:09.243Z,1338406929.243 [transit_3km:NeedComms:NEEDCOMMS] Stopped
2012-05-30T19:42:09.243Z,1338406929.243 [transit_3km:NeedComms:NEEDCOMMS](INFO): Aggregate::uninitialize transit_3km:NeedComms:NEEDCOMMS
2012-05-30T19:42:09.243Z,1338406929.243 [transit_3km:NeedComms](INFO): Completed transit_3km:NeedComms
2012-05-30T19:42:09.243Z,1338406929.243 [transit_3km:NeedComms] Stopped
2012-05-30T19:42:09.243Z,1338406929.243 [transit_3km:NeedComms](INFO): Aggregate::uninitialize transit_3km:NeedComms
2012-05-30T19:42:15.219Z,1338406935.219 [NAL9601](INFO): Powering down
2012-05-30T19:42:20.491Z,1338406940.491 [Radio_Freewave](INFO): Powering down
2012-05-30T19:42:39.573Z,1338406959.573 [Radio_Freewave](INFO): Powering up
2012-05-30T19:42:46.061Z,1338406966.061 [Radio_Freewave](INFO): Powering down
2012-05-30T19:42:59.709Z,1338406979.709 [Radio_Freewave](INFO): Powering up
2012-05-30T19:43:05.337Z,1338406985.337 [Radio_Freewave](INFO): Powering down
2012-05-30T20:17:09.007Z,1338409029.007 [transit_3km:NeedComms] Running Loop=1
2012-05-30T20:17:09.007Z,1338409029.007 [transit_3km:NeedComms](INFO): Aggregate::initialize transit_3km:NeedComms
2012-05-30T20:17:09.007Z,1338409029.007 [transit_3km:NeedComms:NEEDCOMMS] Running Loop=1
2012-05-30T20:17:09.007Z,1338409029.007 [transit_3km:NeedComms:NEEDCOMMS](INFO): Aggregate::initialize transit_3km:NeedComms:NEEDCOMMS
2012-05-30T20:17:09.403Z,1338409029.402 [transit_3km:SURFACECOMMS] Running Loop=1
2012-05-30T20:17:09.403Z,1338409029.403 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2012-05-30T20:17:09.403Z,1338409029.403 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-05-30T20:17:09.403Z,1338409029.403 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T20:19:46.370Z,1338409186.370 [Radio_Freewave](INFO): Powering up
2012-05-30T20:19:46.382Z,1338409186.382 [transit_3km:SURFACECOMMS:B] Running Loop=1
2012-05-30T20:19:46.382Z,1338409186.382 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:B
2012-05-30T20:19:46.382Z,1338409186.382 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-05-30T20:19:46.382Z,1338409186.382 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-05-30T20:19:46.382Z,1338409186.382 [transit_3km:SURFACECOMMS:B:B] Running Loop=1
2012-05-30T20:19:47.127Z,1338409187.127 [NAL9601](INFO): Powering up
2012-05-30T20:20:52.851Z,1338409252.851 [NAL9601](INFO): NAL9601 initialized
2012-05-30T20:20:53.930Z,1338409253.930 [NAL9601](IMPORTANT): GPS fix at: 1338409260.00
2012-05-30T20:20:53.944Z,1338409253.944 [Navigation](IMPORTANT): Navigation Error 12.0 %DT

2012-05-30T20:20:53.945Z,1338409253.945 [transit_3km:SURFACECOMMS:B:B] Stopped
2012-05-30T20:20:53.945Z,1338409253.945 [transit_3km:SURFACECOMMS:B:C] Running Loop=1
2012-05-30T20:21:11.866Z,1338409271.866 [NAL9601](INFO): SBD MO Status=1, MOMSN=6971, MT Status=0, MTMSN=0
2012-05-30T20:21:12.015Z,1338409272.015 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0020.lzma
2012-05-30T20:21:12.015Z,1338409272.015 [NAL9601](INFO): Packets left to send: 7
2012-05-30T20:21:12.016Z,1338409272.016 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000048
2012-05-30T20:21:23.981Z,1338409283.981 [NAL9601](INFO): SBD MO Status=1, MOMSN=6972, MT Status=0, MTMSN=0
2012-05-30T20:21:24.191Z,1338409284.191 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0020.lzma
2012-05-30T20:21:24.191Z,1338409284.191 [NAL9601](INFO): Packets left to send: 6
2012-05-30T20:21:24.192Z,1338409284.192 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000049
2012-05-30T20:21:37.286Z,1338409297.286 [NAL9601](INFO): SBD MO Status=1, MOMSN=6973, MT Status=0, MTMSN=0
2012-05-30T20:21:37.475Z,1338409297.475 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0020.lzma
2012-05-30T20:21:37.475Z,1338409297.475 [NAL9601](INFO): Packets left to send: 5
2012-05-30T20:21:37.477Z,1338409297.477 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000050
2012-05-30T20:21:58.181Z,1338409318.181 [NAL9601](INFO): SBD MO Status=1, MOMSN=6974, MT Status=0, MTMSN=0
2012-05-30T20:21:58.343Z,1338409318.343 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0020.lzma
2012-05-30T20:21:58.343Z,1338409318.343 [NAL9601](INFO): Packets left to send: 4
2012-05-30T20:21:58.344Z,1338409318.344 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000051
2012-05-30T20:22:09.140Z,1338409329.140 [NAL9601](INFO): SBD MO Status=1, MOMSN=6975, MT Status=0, MTMSN=0
2012-05-30T20:22:09.327Z,1338409329.327 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0020.lzma
2012-05-30T20:22:09.327Z,1338409329.327 [NAL9601](INFO): Packets left to send: 3
2012-05-30T20:22:09.329Z,1338409329.329 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000052
2012-05-30T20:22:16.852Z,1338409336.852 [NAL9601](INFO): SBD MO Status=1, MOMSN=6976, MT Status=0, MTMSN=0
2012-05-30T20:22:17.011Z,1338409337.011 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0020.lzma
2012-05-30T20:22:17.011Z,1338409337.011 [NAL9601](INFO): Packets left to send: 2
2012-05-30T20:22:17.012Z,1338409337.012 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000053
2012-05-30T20:22:29.349Z,1338409349.349 [NAL9601](INFO): SBD MO Status=1, MOMSN=6977, MT Status=0, MTMSN=0
2012-05-30T20:22:29.491Z,1338409349.491 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0020.lzma
2012-05-30T20:22:29.491Z,1338409349.491 [NAL9601](INFO): Packets left to send: 1
2012-05-30T20:22:29.492Z,1338409349.492 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000054
2012-05-30T20:22:40.313Z,1338409360.313 [NAL9601](INFO): SBD MO Status=1, MOMSN=6978, MT Status=0, MTMSN=0
2012-05-30T20:22:40.471Z,1338409360.471 [NAL9601](INFO): Sent 99 bytes from file Logs/20120530T160348/shore0020.lzma
2012-05-30T20:22:40.471Z,1338409360.471 [NAL9601](INFO): Packets left to send: 0
2012-05-30T20:22:40.472Z,1338409360.472 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000055
2012-05-30T20:22:46.308Z,1338409366.308 [NAL9601](INFO): SBD MO Status=0, MOMSN=6979, MT Status=0, MTMSN=0
2012-05-30T20:22:46.477Z,1338409366.477 [transit_3km:SURFACECOMMS:B:C] Stopped
2012-05-30T20:22:46.477Z,1338409366.477 [transit_3km:SURFACECOMMS:B:D] Running Loop=1
2012-05-30T20:22:48.710Z,1338409368.710 [NAL9601](IMPORTANT): GPS fix at: 1338409375.00
2012-05-30T20:22:48.724Z,1338409368.724 [transit_3km:SURFACECOMMS:B:D] Stopped
2012-05-30T20:22:48.725Z,1338409368.724 [transit_3km:SURFACECOMMS:B](INFO): Completed transit_3km:SURFACECOMMS:B
2012-05-30T20:22:48.725Z,1338409368.724 [transit_3km:SURFACECOMMS:B] Stopped
2012-05-30T20:22:48.725Z,1338409368.725 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:B
2012-05-30T20:22:48.725Z,1338409368.725 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-05-30T20:22:48.725Z,1338409368.725 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T20:22:48.726Z,1338409368.726 [transit_3km:SURFACECOMMS](INFO): Completed transit_3km:SURFACECOMMS
2012-05-30T20:22:48.726Z,1338409368.726 [transit_3km:SURFACECOMMS] Stopped
2012-05-30T20:22:48.726Z,1338409368.726 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2012-05-30T20:22:48.726Z,1338409368.726 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2012-05-30T20:22:48.726Z,1338409368.726 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T20:22:49.123Z,1338409369.123 [transit_3km:NeedComms:NEEDCOMMS](INFO): Completed transit_3km:NeedComms:NEEDCOMMS
2012-05-30T20:22:49.123Z,1338409369.123 [transit_3km:NeedComms:NEEDCOMMS] Stopped
2012-05-30T20:22:49.123Z,1338409369.123 [transit_3km:NeedComms:NEEDCOMMS](INFO): Aggregate::uninitialize transit_3km:NeedComms:NEEDCOMMS
2012-05-30T20:22:49.123Z,1338409369.123 [transit_3km:NeedComms](INFO): Completed transit_3km:NeedComms
2012-05-30T20:22:49.123Z,1338409369.123 [transit_3km:NeedComms] Stopped
2012-05-30T20:22:49.124Z,1338409369.124 [transit_3km:NeedComms](INFO): Aggregate::uninitialize transit_3km:NeedComms
2012-05-30T20:22:55.112Z,1338409375.112 [NAL9601](INFO): Powering down
2012-05-30T20:23:12.673Z,1338409392.673 [Radio_Freewave](INFO): Powering down
2012-05-30T20:23:24.345Z,1338409404.345 [Radio_Freewave](INFO): Powering up
2012-05-30T20:23:41.513Z,1338409421.513 [Radio_Freewave](INFO): Powering down
2012-05-30T20:57:49.161Z,1338411469.161 [transit_3km:NeedComms] Running Loop=1
2012-05-30T20:57:49.161Z,1338411469.161 [transit_3km:NeedComms](INFO): Aggregate::initialize transit_3km:NeedComms
2012-05-30T20:57:49.161Z,1338411469.161 [transit_3km:NeedComms:NEEDCOMMS] Running Loop=1
2012-05-30T20:57:49.161Z,1338411469.161 [transit_3km:NeedComms:NEEDCOMMS](INFO): Aggregate::initialize transit_3km:NeedComms:NEEDCOMMS
2012-05-30T20:57:49.559Z,1338411469.559 [transit_3km:SURFACECOMMS] Running Loop=1
2012-05-30T20:57:49.559Z,1338411469.559 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2012-05-30T20:57:49.559Z,1338411469.559 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-05-30T20:57:49.559Z,1338411469.559 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T21:00:25.832Z,1338411625.832 [Radio_Freewave](INFO): Powering up
2012-05-30T21:00:25.859Z,1338411625.859 [transit_3km:SURFACECOMMS:B] Running Loop=1
2012-05-30T21:00:25.859Z,1338411625.859 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:B
2012-05-30T21:00:25.859Z,1338411625.859 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-05-30T21:00:25.859Z,1338411625.859 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-05-30T21:00:25.859Z,1338411625.859 [transit_3km:SURFACECOMMS:B:B] Running Loop=1
2012-05-30T21:00:26.583Z,1338411626.583 [NAL9601](INFO): Powering up
2012-05-30T21:00:44.993Z,1338411644.993 [Radio_Freewave](INFO): Powering down
2012-05-30T21:00:47.815Z,1338411647.815 [Radio_Freewave](INFO): Powering up
2012-05-30T21:01:00.194Z,1338411660.194 [Radio_Freewave](INFO): Powering down
2012-05-30T21:01:00.612Z,1338411660.612 [Radio_Freewave](INFO): Powering up
2012-05-30T21:01:02.565Z,1338411662.565 [Radio_Freewave](INFO): Powering down
2012-05-30T21:01:03.369Z,1338411663.369 [Radio_Freewave](INFO): Powering up
2012-05-30T21:01:03.891Z,1338411663.891 [ThrusterServo](FAULT): getVelocity uart error serial timeout
2012-05-30T21:01:03.891Z,1338411663.891 [ThrusterServo](FAULT): Thruster uart error: serial timeout
2012-05-30T21:01:03.891Z,1338411663.891 [ThrusterServo] Communications Fault, FailCount= 1
2012-05-30T21:01:03.891Z,1338411663.891 [ThrusterServo](ERROR): Communications Fault
2012-05-30T21:01:03.893Z,1338411663.893 [CBIT](ERROR): Communications Fault in component: ThrusterServo
2012-05-30T21:01:04.580Z,1338411664.580 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2012-05-30T21:01:04.580Z,1338411664.580 [ThrusterServo](INFO): Powering down
2012-05-30T21:01:04.583Z,1338411664.583 [CBIT](INFO): Clearing failed state for component ThrusterServo
2012-05-30T21:01:04.583Z,1338411664.583 [ThrusterServo] No Fault, FailCount= 1
2012-05-30T21:01:05.147Z,1338411665.147 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-05-30T21:01:05.268Z,1338411665.267 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-05-30T21:01:32.307Z,1338411692.307 [NAL9601](INFO): NAL9601 initialized
2012-05-30T21:01:33.488Z,1338411693.488 [NAL9601](IMPORTANT): GPS fix at: 1338411703.00
2012-05-30T21:01:33.502Z,1338411693.502 [Navigation](IMPORTANT): Navigation Error 7.3 %DT

2012-05-30T21:01:33.503Z,1338411693.503 [transit_3km:SURFACECOMMS:B:B] Stopped
2012-05-30T21:01:33.503Z,1338411693.503 [transit_3km:SURFACECOMMS:B:C] Running Loop=1
2012-05-30T21:01:56.615Z,1338411716.615 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=6980, MT Status=1, MTMSN=2634
2012-05-30T21:01:56.759Z,1338411716.759 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0021.lzma
2012-05-30T21:01:56.759Z,1338411716.759 [NAL9601](INFO): Packets left to send: 7
2012-05-30T21:01:56.760Z,1338411716.760 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000056
2012-05-30T21:01:57.228Z,1338411717.228 [NAL9601](INFO): Received command:configset VerticalControl.buoyancyNeutral 400 cc persist; configset VerticalControl.massDefault -0.627 cm persist;
2012-05-30T21:01:57.247Z,1338411717.247 [CommandLine](IMPORTANT): got command configSet VerticalControl.buoyancyNeutral 400.000000 cubic_centimeter persist
2012-05-30T21:02:00.564Z,1338411720.564 [CommandLine](IMPORTANT): got command configSet VerticalControl.massDefault -0.627000 centimeter persist
2012-05-30T21:02:13.674Z,1338411733.674 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=6981, MT Status=1, MTMSN=2635
2012-05-30T21:02:13.831Z,1338411733.831 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0021.lzma
2012-05-30T21:02:13.831Z,1338411733.831 [NAL9601](INFO): Packets left to send: 6
2012-05-30T21:02:13.832Z,1338411733.832 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000057
2012-05-30T21:02:14.259Z,1338411734.260 [NAL9601](INFO): Received command:get VerticalControl.buoyancyNeutral;
2012-05-30T21:02:14.420Z,1338411734.420 [CommandLine](IMPORTANT): got command get VerticalControl.buoyancyNeutral
2012-05-30T21:02:14.421Z,1338411734.421 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral 399.999990 cubic_centimeter
2012-05-30T21:02:27.229Z,1338411747.229 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=6982, MT Status=1, MTMSN=2636
2012-05-30T21:02:27.411Z,1338411747.411 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0021.lzma
2012-05-30T21:02:27.411Z,1338411747.411 [NAL9601](INFO): Packets left to send: 5
2012-05-30T21:02:27.412Z,1338411747.412 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000058
2012-05-30T21:02:27.828Z,1338411747.828 [NAL9601](INFO): Received command:get VerticalControl.massDefault
2012-05-30T21:02:28.055Z,1338411748.055 [CommandLine](IMPORTANT): got command get VerticalControl.massDefault
2012-05-30T21:02:28.056Z,1338411748.056 [CommandLine](IMPORTANT): VerticalControl.massDefault -0.627000 centimeter
2012-05-30T21:02:49.017Z,1338411769.017 [NAL9601](INFO): SBD MO Status=1, MOMSN=6983, MT Status=0, MTMSN=0
2012-05-30T21:02:49.175Z,1338411769.175 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0021.lzma
2012-05-30T21:02:49.175Z,1338411769.175 [NAL9601](INFO): Packets left to send: 4
2012-05-30T21:02:49.176Z,1338411769.176 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000059
2012-05-30T21:02:57.890Z,1338411777.889 [NAL9601](INFO): SBD MO Status=1, MOMSN=6984, MT Status=0, MTMSN=0
2012-05-30T21:02:58.063Z,1338411778.063 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0021.lzma
2012-05-30T21:02:58.063Z,1338411778.063 [NAL9601](INFO): Packets left to send: 3
2012-05-30T21:02:58.064Z,1338411778.065 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000060
2012-05-30T21:03:07.649Z,1338411787.649 [NAL9601](INFO): SBD MO Status=1, MOMSN=6985, MT Status=0, MTMSN=0
2012-05-30T21:03:07.847Z,1338411787.847 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0021.lzma
2012-05-30T21:03:07.847Z,1338411787.847 [NAL9601](INFO): Packets left to send: 2
2012-05-30T21:03:07.849Z,1338411787.849 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000061
2012-05-30T21:03:16.214Z,1338411796.214 [NAL9601](INFO): SBD MO Status=1, MOMSN=6986, MT Status=0, MTMSN=0
2012-05-30T21:03:16.335Z,1338411796.335 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0021.lzma
2012-05-30T21:03:16.335Z,1338411796.335 [NAL9601](INFO): Packets left to send: 1
2012-05-30T21:03:16.336Z,1338411796.336 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000062
2012-05-30T21:03:25.870Z,1338411805.870 [NAL9601](INFO): SBD MO Status=1, MOMSN=6987, MT Status=0, MTMSN=0
2012-05-30T21:03:26.019Z,1338411806.019 [NAL9601](INFO): Sent 72 bytes from file Logs/20120530T160348/shore0021.lzma
2012-05-30T21:03:26.019Z,1338411806.019 [NAL9601](INFO): Packets left to send: 0
2012-05-30T21:03:26.020Z,1338411806.020 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000063
2012-05-30T21:03:29.465Z,1338411809.464 [NAL9601](INFO): SBD MO Status=0, MOMSN=6988, MT Status=0, MTMSN=0
2012-05-30T21:03:51.842Z,1338411831.842 [NAL9601](INFO): SBD MO Status=1, MOMSN=6989, MT Status=0, MTMSN=0
2012-05-30T21:03:51.979Z,1338411831.979 [NAL9601](INFO): Sent 328 bytes from file Logs/20120530T160348/shore0022.lzma
2012-05-30T21:03:51.979Z,1338411831.979 [NAL9601](INFO): Packets left to send: 0
2012-05-30T21:03:51.980Z,1338411831.980 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000064
2012-05-30T21:03:56.166Z,1338411836.165 [NAL9601](INFO): SBD MO Status=0, MOMSN=6990, MT Status=0, MTMSN=0
2012-05-30T21:03:56.433Z,1338411836.433 [transit_3km:SURFACECOMMS:B:C] Stopped
2012-05-30T21:03:56.433Z,1338411836.433 [transit_3km:SURFACECOMMS:B:D] Running Loop=1
2012-05-30T21:03:58.567Z,1338411838.567 [NAL9601](IMPORTANT): GPS fix at: 1338411855.00
2012-05-30T21:03:58.581Z,1338411838.581 [transit_3km:SURFACECOMMS:B:D] Stopped
2012-05-30T21:03:58.582Z,1338411838.582 [transit_3km:SURFACECOMMS:B](INFO): Completed transit_3km:SURFACECOMMS:B
2012-05-30T21:03:58.582Z,1338411838.582 [transit_3km:SURFACECOMMS:B] Stopped
2012-05-30T21:03:58.582Z,1338411838.582 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:B
2012-05-30T21:03:58.582Z,1338411838.582 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-05-30T21:03:58.582Z,1338411838.582 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T21:03:58.583Z,1338411838.583 [transit_3km:SURFACECOMMS](INFO): Completed transit_3km:SURFACECOMMS
2012-05-30T21:03:58.584Z,1338411838.583 [transit_3km:SURFACECOMMS] Stopped
2012-05-30T21:03:58.584Z,1338411838.584 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2012-05-30T21:03:58.584Z,1338411838.584 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2012-05-30T21:03:58.584Z,1338411838.584 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T21:03:58.975Z,1338411838.975 [transit_3km:NeedComms:NEEDCOMMS](INFO): Completed transit_3km:NeedComms:NEEDCOMMS
2012-05-30T21:03:58.975Z,1338411838.975 [transit_3km:NeedComms:NEEDCOMMS] Stopped
2012-05-30T21:03:58.975Z,1338411838.975 [transit_3km:NeedComms:NEEDCOMMS](INFO): Aggregate::uninitialize transit_3km:NeedComms:NEEDCOMMS
2012-05-30T21:03:58.976Z,1338411838.976 [transit_3km:NeedComms](INFO): Completed transit_3km:NeedComms
2012-05-30T21:03:58.976Z,1338411838.976 [transit_3km:NeedComms] Stopped
2012-05-30T21:03:58.976Z,1338411838.976 [transit_3km:NeedComms](INFO): Aggregate::uninitialize transit_3km:NeedComms
2012-05-30T21:04:04.971Z,1338411844.971 [NAL9601](INFO): Powering down
2012-05-30T21:04:16.873Z,1338411856.873 [Radio_Freewave](INFO): Powering down
2012-05-30T21:04:26.882Z,1338411866.882 [Radio_Freewave](INFO): Powering up
2012-05-30T21:04:29.217Z,1338411869.217 [Radio_Freewave](INFO): Powering down
2012-05-30T21:38:58.679Z,1338413938.679 [transit_3km:NeedComms] Running Loop=1
2012-05-30T21:38:58.680Z,1338413938.680 [transit_3km:NeedComms](INFO): Aggregate::initialize transit_3km:NeedComms
2012-05-30T21:38:58.680Z,1338413938.680 [transit_3km:NeedComms:NEEDCOMMS] Running Loop=1
2012-05-30T21:38:58.680Z,1338413938.680 [transit_3km:NeedComms:NEEDCOMMS](INFO): Aggregate::initialize transit_3km:NeedComms:NEEDCOMMS
2012-05-30T21:38:59.148Z,1338413939.148 [transit_3km:SURFACECOMMS] Running Loop=1
2012-05-30T21:38:59.148Z,1338413939.148 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2012-05-30T21:38:59.148Z,1338413939.148 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-05-30T21:38:59.148Z,1338413939.148 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T21:41:28.705Z,1338414088.705 [Radio_Freewave](INFO): Powering up
2012-05-30T21:41:28.729Z,1338414088.729 [transit_3km:SURFACECOMMS:B] Running Loop=1
2012-05-30T21:41:28.729Z,1338414088.729 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:B
2012-05-30T21:41:28.729Z,1338414088.729 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-05-30T21:41:28.729Z,1338414088.729 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-05-30T21:41:28.729Z,1338414088.729 [transit_3km:SURFACECOMMS:B:B] Running Loop=1
2012-05-30T21:41:29.495Z,1338414089.495 [NAL9601](INFO): Powering up
2012-05-30T21:42:35.219Z,1338414155.219 [NAL9601](INFO): NAL9601 initialized
2012-05-30T21:42:36.299Z,1338414156.299 [NAL9601](IMPORTANT): GPS fix at: 1338414170.00
2012-05-30T21:42:36.313Z,1338414156.313 [Navigation](IMPORTANT): Navigation Error 5.2 %DT

2012-05-30T21:42:36.315Z,1338414156.315 [transit_3km:SURFACECOMMS:B:B] Stopped
2012-05-30T21:42:36.315Z,1338414156.315 [transit_3km:SURFACECOMMS:B:C] Running Loop=1
2012-05-30T21:42:55.010Z,1338414175.010 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=6991, MT Status=1, MTMSN=2637
2012-05-30T21:42:55.175Z,1338414175.175 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0023.lzma
2012-05-30T21:42:55.175Z,1338414175.175 [NAL9601](INFO): Packets left to send: 6
2012-05-30T21:42:55.176Z,1338414175.177 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000065
2012-05-30T21:42:55.730Z,1338414175.730 [NAL9601](IMPORTANT): Initialized file: Config/logger.cfg
2012-05-30T21:42:55.732Z,1338414175.732 [NAL9601](IMPORTANT): More data left to go, at position 90
2012-05-30T21:43:16.542Z,1338414196.542 [NAL9601](INFO): SBD MO Status=2, MOMSN=6992, MT Status=2, MTMSN=0
2012-05-30T21:43:16.542Z,1338414196.542 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-30T21:43:39.158Z,1338414219.158 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=6992, MT Status=1, MTMSN=2638
2012-05-30T21:43:39.311Z,1338414219.311 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0023.lzma
2012-05-30T21:43:39.311Z,1338414219.311 [NAL9601](INFO): Packets left to send: 5
2012-05-30T21:43:39.312Z,1338414219.312 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000066
2012-05-30T21:43:39.906Z,1338414219.906 [NAL9601](IMPORTANT): Added data to file: Config/logger.cfg
2012-05-30T21:43:43.673Z,1338414223.673 [NAL9601](IMPORTANT): Success executing cat Logs/latest/4FC68D3B.part | gunzip -f -d | cat `cp Config/.svn/text-base/logger.cfg.svn-base Config/logger.cfg` | vim -e Config/logger.cfg
2012-05-30T21:43:43.757Z,1338414223.757 [CommandLine](IMPORTANT): 5ba76316e34cbdd84afbf1362a97dd65  Config/logger.cfg

2012-05-30T21:43:54.747Z,1338414234.747 [NAL9601](INFO): SBD MO Status=1, MOMSN=6993, MT Status=0, MTMSN=0
2012-05-30T21:43:54.900Z,1338414234.900 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0023.lzma
2012-05-30T21:43:54.900Z,1338414234.900 [NAL9601](INFO): Packets left to send: 4
2012-05-30T21:43:54.901Z,1338414234.901 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000067
2012-05-30T21:44:21.242Z,1338414261.242 [NAL9601](INFO): SBD MO Status=1, MOMSN=6994, MT Status=0, MTMSN=0
2012-05-30T21:44:21.447Z,1338414261.447 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0023.lzma
2012-05-30T21:44:21.447Z,1338414261.447 [NAL9601](INFO): Packets left to send: 3
2012-05-30T21:44:21.448Z,1338414261.448 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000068
2012-05-30T21:44:28.566Z,1338414268.566 [NAL9601](INFO): SBD MO Status=2, MOMSN=6995, MT Status=2, MTMSN=0
2012-05-30T21:44:28.566Z,1338414268.566 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-30T21:45:00.677Z,1338414300.677 [NAL9601](INFO): SBD MO Status=2, MOMSN=6995, MT Status=2, MTMSN=0
2012-05-30T21:45:00.678Z,1338414300.678 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-30T21:45:57.099Z,1338414357.099 [NAL9601](INFO): SBD MO Status=1, MOMSN=6995, MT Status=0, MTMSN=0
2012-05-30T21:45:57.295Z,1338414357.295 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0023.lzma
2012-05-30T21:45:57.295Z,1338414357.295 [NAL9601](INFO): Packets left to send: 2
2012-05-30T21:45:57.296Z,1338414357.296 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000069
2012-05-30T21:46:05.562Z,1338414365.562 [NAL9601](INFO): SBD MO Status=1, MOMSN=6996, MT Status=0, MTMSN=0
2012-05-30T21:46:05.679Z,1338414365.679 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0023.lzma
2012-05-30T21:46:05.679Z,1338414365.679 [NAL9601](INFO): Packets left to send: 1
2012-05-30T21:46:05.681Z,1338414365.681 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000070
2012-05-30T21:46:12.970Z,1338414372.970 [NAL9601](INFO): SBD MO Status=1, MOMSN=6997, MT Status=0, MTMSN=0
2012-05-30T21:46:13.171Z,1338414373.171 [NAL9601](INFO): Sent 124 bytes from file Logs/20120530T160348/shore0023.lzma
2012-05-30T21:46:13.171Z,1338414373.171 [NAL9601](INFO): Packets left to send: 0
2012-05-30T21:46:13.172Z,1338414373.172 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000071
2012-05-30T21:46:22.974Z,1338414382.974 [Radio_Freewave](INFO): Powering down
2012-05-30T21:46:24.885Z,1338414384.885 [Radio_Freewave](INFO): Powering up
2012-05-30T21:46:26.886Z,1338414386.885 [NAL9601](INFO): SBD MO Status=2, MOMSN=6998, MT Status=2, MTMSN=0
2012-05-30T21:46:26.886Z,1338414386.886 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-30T21:46:36.692Z,1338414396.693 [NAL9601](INFO): SBD MO Status=0, MOMSN=6998, MT Status=0, MTMSN=0
2012-05-30T21:46:49.418Z,1338414409.418 [NAL9601](INFO): SBD MO Status=1, MOMSN=6999, MT Status=0, MTMSN=0
2012-05-30T21:46:49.611Z,1338414409.611 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0024.lzma
2012-05-30T21:46:49.611Z,1338414409.611 [NAL9601](INFO): Packets left to send: 1
2012-05-30T21:46:49.613Z,1338414409.613 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000072
2012-05-30T21:46:55.552Z,1338414415.552 [NAL9601](INFO): SBD MO Status=1, MOMSN=7000, MT Status=0, MTMSN=0
2012-05-30T21:46:55.703Z,1338414415.703 [NAL9601](INFO): Sent 52 bytes from file Logs/20120530T160348/shore0024.lzma
2012-05-30T21:46:55.703Z,1338414415.703 [NAL9601](INFO): Packets left to send: 0
2012-05-30T21:46:55.705Z,1338414415.705 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000073
2012-05-30T21:47:04.069Z,1338414424.069 [NAL9601](INFO): SBD MO Status=0, MOMSN=7001, MT Status=0, MTMSN=0
2012-05-30T21:47:04.204Z,1338414424.204 [transit_3km:SURFACECOMMS:B:C] Stopped
2012-05-30T21:47:04.205Z,1338414424.205 [transit_3km:SURFACECOMMS:B:D] Running Loop=1
2012-05-30T21:47:06.479Z,1338414426.479 [NAL9601](IMPORTANT): GPS fix at: 1338414440.00
2012-05-30T21:47:06.493Z,1338414426.493 [transit_3km:SURFACECOMMS:B:D] Stopped
2012-05-30T21:47:06.493Z,1338414426.493 [transit_3km:SURFACECOMMS:B](INFO): Completed transit_3km:SURFACECOMMS:B
2012-05-30T21:47:06.493Z,1338414426.493 [transit_3km:SURFACECOMMS:B] Stopped
2012-05-30T21:47:06.493Z,1338414426.493 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:B
2012-05-30T21:47:06.493Z,1338414426.493 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-05-30T21:47:06.493Z,1338414426.493 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T21:47:06.495Z,1338414426.494 [transit_3km:SURFACECOMMS](INFO): Completed transit_3km:SURFACECOMMS
2012-05-30T21:47:06.495Z,1338414426.495 [transit_3km:SURFACECOMMS] Stopped
2012-05-30T21:47:06.495Z,1338414426.495 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2012-05-30T21:47:06.495Z,1338414426.495 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2012-05-30T21:47:06.495Z,1338414426.495 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T21:47:06.883Z,1338414426.883 [transit_3km:NeedComms:NEEDCOMMS](INFO): Completed transit_3km:NeedComms:NEEDCOMMS
2012-05-30T21:47:06.883Z,1338414426.884 [transit_3km:NeedComms:NEEDCOMMS] Stopped
2012-05-30T21:47:06.884Z,1338414426.884 [transit_3km:NeedComms:NEEDCOMMS](INFO): Aggregate::uninitialize transit_3km:NeedComms:NEEDCOMMS
2012-05-30T21:47:06.884Z,1338414426.884 [transit_3km:NeedComms](INFO): Completed transit_3km:NeedComms
2012-05-30T21:47:06.884Z,1338414426.884 [transit_3km:NeedComms] Stopped
2012-05-30T21:47:06.884Z,1338414426.884 [transit_3km:NeedComms](INFO): Aggregate::uninitialize transit_3km:NeedComms
2012-05-30T21:47:13.008Z,1338414433.008 [NAL9601](INFO): Powering down
2012-05-30T21:47:21.953Z,1338414441.953 [Radio_Freewave](INFO): Powering down
2012-05-30T21:47:30.488Z,1338414450.487 [Radio_Freewave](INFO): Powering up
2012-05-30T21:48:00.461Z,1338414480.461 [Radio_Freewave](INFO): Powering down
2012-05-30T21:48:14.197Z,1338414494.197 [Radio_Freewave](INFO): Powering up
2012-05-30T21:48:21.842Z,1338414501.842 [Radio_Freewave](INFO): Powering down
2012-05-30T21:55:01.927Z,1338414901.927 [transit_3km:WaypointOne:WaypointW1.Waypoint](INFO): Reached Waypoint: 36.900001,-121.899998
2012-05-30T21:55:01.927Z,1338414901.927 [transit_3km:WaypointOne:WaypointW1.Waypoint] Stopped
2012-05-30T21:55:01.927Z,1338414901.927 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Uninitialize WaypointComponent.
2012-05-30T21:55:01.927Z,1338414901.927 [transit_3km:WaypointOne:PHONEHOMEWPT1] Running Loop=1
2012-05-30T21:55:01.927Z,1338414901.927 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Aggregate::initialize transit_3km:WaypointOne:PHONEHOMEWPT1
2012-05-30T21:55:02.302Z,1338414902.302 [transit_3km:SURFACECOMMS] Running Loop=1
2012-05-30T21:55:02.303Z,1338414902.303 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2012-05-30T21:55:02.303Z,1338414902.303 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-05-30T21:55:02.303Z,1338414902.303 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T21:58:03.385Z,1338415083.385 [Radio_Freewave](INFO): Powering up
2012-05-30T21:58:03.396Z,1338415083.397 [transit_3km:SURFACECOMMS:B] Running Loop=1
2012-05-30T21:58:03.397Z,1338415083.397 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:B
2012-05-30T21:58:03.397Z,1338415083.397 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-05-30T21:58:03.397Z,1338415083.397 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-05-30T21:58:03.397Z,1338415083.397 [transit_3km:SURFACECOMMS:B:B] Running Loop=1
2012-05-30T21:58:04.180Z,1338415084.180 [NAL9601](INFO): Powering up
2012-05-30T21:59:09.703Z,1338415149.703 [NAL9601](INFO): NAL9601 initialized
2012-05-30T21:59:10.874Z,1338415150.874 [NAL9601](IMPORTANT): GPS fix at: 1338415166.00
2012-05-30T21:59:10.889Z,1338415150.889 [Navigation](IMPORTANT): Navigation Error 2.1 %DT

2012-05-30T21:59:10.890Z,1338415150.890 [transit_3km:SURFACECOMMS:B:B] Stopped
2012-05-30T21:59:10.890Z,1338415150.890 [transit_3km:SURFACECOMMS:B:C] Running Loop=1
2012-05-30T21:59:37.181Z,1338415177.181 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=7002, MT Status=1, MTMSN=2639
2012-05-30T21:59:37.355Z,1338415177.355 [NAL9601](INFO): Sent 332 bytes from file Logs/20120530T160348/shore0025.lzma
2012-05-30T21:59:37.355Z,1338415177.355 [NAL9601](INFO): Packets left to send: 2
2012-05-30T21:59:37.357Z,1338415177.357 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000074
2012-05-30T21:59:37.768Z,1338415177.768 [NAL9601](INFO): Received command:restart application
2012-05-30T21:59:37.807Z,1338415177.807 [CommandLine](IMPORTANT): got command restart application
2012-05-30T21:59:37.992Z,1338415177.992 [transit_3km] Stopped
2012-05-30T21:59:37.992Z,1338415177.992 [transit_3km](INFO): Aggregate::uninitialize transit_3km
2012-05-30T21:59:37.992Z,1338415177.992 [transit_3km:A.AltitudeEnvelope] Stopped
2012-05-30T21:59:37.993Z,1338415177.993 [transit_3km:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-05-30T21:59:37.993Z,1338415177.993 [transit_3km:B.DepthEnvelope] Stopped
2012-05-30T21:59:37.993Z,1338415177.993 [transit_3km:B.DepthEnvelope](DEBUG): Uninitialize.
2012-05-30T21:59:37.993Z,1338415177.993 [transit_3km:C.OffshoreEnvelope] Stopped
2012-05-30T21:59:37.993Z,1338415177.993 [transit_3km:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2012-05-30T21:59:37.993Z,1338415177.993 [transit_3km:SURFACECOMMS] Stopped
2012-05-30T21:59:37.993Z,1338415177.993 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2012-05-30T21:59:37.993Z,1338415177.993 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2012-05-30T21:59:37.993Z,1338415177.993 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T21:59:37.993Z,1338415177.993 [transit_3km:SURFACECOMMS:B] Stopped
2012-05-30T21:59:37.993Z,1338415177.993 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:B
2012-05-30T21:59:37.993Z,1338415177.993 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-05-30T21:59:37.993Z,1338415177.993 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T21:59:37.993Z,1338415177.993 [transit_3km:SURFACECOMMS:B:C] Stopped
2012-05-30T21:59:37.993Z,1338415177.993 [transit_3km:WaypointOne] Stopped
2012-05-30T21:59:37.994Z,1338415177.994 [transit_3km:WaypointOne](INFO): Aggregate::uninitialize transit_3km:WaypointOne
2012-05-30T21:59:37.994Z,1338415177.994 [transit_3km:WaypointOne:A.Pitch] Stopped
2012-05-30T21:59:37.994Z,1338415177.994 [transit_3km:WaypointOne:B.SetSpeed] Stopped
2012-05-30T21:59:37.994Z,1338415177.994 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Uninitialize.
2012-05-30T21:59:37.994Z,1338415177.994 [transit_3km:WaypointOne:PHONEHOMEWPT1] Stopped
2012-05-30T21:59:37.994Z,1338415177.994 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Aggregate::uninitialize transit_3km:WaypointOne:PHONEHOMEWPT1
2012-05-30T21:59:38.003Z,1338415178.003 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2012-05-30T21:59:38.003Z,1338415178.003 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2012-05-30T21:59:38.346Z,1338415178.346 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2012-05-30T21:59:38.375Z,1338415178.375 [CTD_NeilBrown](INFO): Powering down
2012-05-30T21:59:38.375Z,1338415178.375 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2012-05-30T21:59:38.394Z,1338415178.394 [MissionManager](IMPORTANT): Started mission Default
2012-05-30T21:59:38.394Z,1338415178.394 [Default] Running Loop=1
2012-05-30T21:59:38.394Z,1338415178.394 [Default](INFO): Aggregate::initialize Default
2012-05-30T21:59:38.394Z,1338415178.394 [Default:D.SetSpeed] Running Loop=1
2012-05-30T21:59:38.394Z,1338415178.394 [Default:D.SetSpeed](DEBUG): Initialize.
2012-05-30T21:59:38.394Z,1338415178.394 [Default:E.GoToSurface] Running Loop=1
2012-05-30T21:59:38.394Z,1338415178.394 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T21:59:38.395Z,1338415178.395 [Default:Iridium] Running Loop=1
2012-05-30T21:59:38.395Z,1338415178.395 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-30T21:59:38.395Z,1338415178.395 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-30T21:59:38.395Z,1338415178.395 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-30T21:59:38.395Z,1338415178.395 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-30T21:59:38.395Z,1338415178.395 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T21:59:38.397Z,1338415178.397 [Default:CallIridium] Running Loop=1
2012-05-30T21:59:38.397Z,1338415178.397 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-30T21:59:38.397Z,1338415178.397 [Default:CallIridium:A] Running Loop=1
2012-05-30T21:59:38.398Z,1338415178.398 [Default:CallIridium:A] Stopped
2012-05-30T21:59:38.398Z,1338415178.398 [Default:CallIridium:B] Running Loop=1
2012-05-30T21:59:38.398Z,1338415178.398 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-30T21:59:38.399Z,1338415178.399 [Default:Iridium:B.GoToSurface] Stopped
2012-05-30T21:59:38.399Z,1338415178.399 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T21:59:38.399Z,1338415178.399 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-30T21:59:38.477Z,1338415178.477 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2012-05-30T21:59:38.477Z,1338415178.477 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2012-05-30T21:59:38.477Z,1338415178.477 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2012-05-30T21:59:38.808Z,1338415178.808 [Default:GPS] Running Loop=1
2012-05-30T21:59:38.808Z,1338415178.808 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-30T21:59:38.808Z,1338415178.808 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-30T21:59:38.808Z,1338415178.808 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-30T21:59:38.808Z,1338415178.808 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-30T21:59:38.808Z,1338415178.809 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-30T21:59:38.809Z,1338415178.809 [Default:GPS:B.GoToSurface] Stopped
2012-05-30T21:59:38.809Z,1338415178.809 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T21:59:38.810Z,1338415178.810 [Default:GPS:Read_GPS] Running Loop=1
2012-05-30T21:59:38.860Z,1338415178.860 [controlThread](DEBUG): Uninitializing ControlThread
2012-05-30T21:59:38.860Z,1338415178.860 [AHRS_sp3003D](INFO): Powering down
2012-05-30T21:59:38.948Z,1338415178.948 [DVL_micro](INFO): Powering down
2012-05-30T21:59:38.948Z,1338415178.948 [NAL9601](INFO): Powering down
2012-05-30T21:59:38.949Z,1338415178.949 [Aanderaa_O2](INFO): Powering down
2012-05-30T21:59:38.950Z,1338415178.950 [WetLabsBB2FL](INFO): Powering down
2012-05-30T21:59:38.950Z,1338415178.950 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-05-30T21:59:38.950Z,1338415178.950 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2012-05-30T21:59:38.951Z,1338415178.951 [Default] Stopped
2012-05-30T21:59:38.952Z,1338415178.952 [Default](INFO): Aggregate::uninitialize Default
2012-05-30T21:59:38.952Z,1338415178.952 [Default:GPS] Stopped
2012-05-30T21:59:38.952Z,1338415178.952 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-30T21:59:38.952Z,1338415178.952 [Default:GPS:A.SetSpeed] Stopped
2012-05-30T21:59:38.952Z,1338415178.952 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T21:59:38.952Z,1338415178.952 [Default:GPS:Read_GPS] Stopped
2012-05-30T21:59:38.952Z,1338415178.952 [Default:Iridium] Stopped
2012-05-30T21:59:38.952Z,1338415178.952 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-30T21:59:38.952Z,1338415178.952 [Default:Iridium:A.SetSpeed] Stopped
2012-05-30T21:59:38.952Z,1338415178.952 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-30T21:59:38.952Z,1338415178.953 [Default:Iridium:Read_Iridium] Stopped
2012-05-30T21:59:38.952Z,1338415178.953 [Default:CallIridium] Stopped
2012-05-30T21:59:38.953Z,1338415178.953 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-30T21:59:38.953Z,1338415178.953 [Default:CallIridium:B] Stopped
2012-05-30T21:59:38.953Z,1338415178.953 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-30T21:59:38.953Z,1338415178.953 [Default:D.SetSpeed] Stopped
2012-05-30T21:59:38.953Z,1338415178.953 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-05-30T21:59:38.953Z,1338415178.953 [Default:E.GoToSurface] Stopped
2012-05-30T21:59:38.953Z,1338415178.953 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-30T21:59:38.957Z,1338415178.957 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2012-05-30T21:59:38.958Z,1338415178.958 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2012-05-30T21:59:38.958Z,1338415178.958 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2012-05-30T21:59:38.958Z,1338415178.958 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2012-05-30T21:59:38.959Z,1338415178.959 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2012-05-30T21:59:38.959Z,1338415178.959 [BuoyancyServo](INFO): Powering down
2012-05-30T21:59:38.959Z,1338415178.959 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-05-30T21:59:38.960Z,1338415178.960 [ElevatorServo](INFO): Powering down
2012-05-30T21:59:38.960Z,1338415178.960 [MassServo](DEBUG): Uninitialize Mass Servo.
2012-05-30T21:59:38.960Z,1338415178.960 [MassServo](INFO): Powering down
2012-05-30T21:59:38.960Z,1338415178.960 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2012-05-30T21:59:38.960Z,1338415178.960 [RudderServo](INFO): Powering down
2012-05-30T21:59:38.961Z,1338415178.961 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2012-05-30T21:59:38.961Z,1338415178.961 [ThrusterServo](INFO): Powering down
2012-05-30T21:59:38.961Z,1338415178.961 [SBIT](DEBUG): Uninitialize SBIT Component.
2012-05-30T21:59:38.961Z,1338415178.961 [IBIT](DEBUG): Uninitialize IBIT Component.
2012-05-30T21:59:38.962Z,1338415178.962 [CBIT](DEBUG): Uninitialize CBIT Component.