2012-05-03T15:23:08.270Z,1336058588.270 [Supervisor](DEBUG): Initializing supervisor.
2012-05-03T15:23:08.272Z,1336058588.272 [SyncHandler](DEBUG): Created PCaller Thread at 1077138656
2012-05-03T15:23:08.273Z,1336058588.273 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-05-03T15:23:08.274Z,1336058588.274 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 1077335264
2012-05-03T15:23:08.275Z,1336058588.275 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-05-03T15:23:08.285Z,1336058588.285 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-05-03T15:23:08.286Z,1336058588.286 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 1077531872
2012-05-03T15:23:08.287Z,1336058588.287 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2012-05-03T15:23:08.287Z,1336058588.287 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-05-03T15:23:08.289Z,1336058588.289 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-05-03T15:23:08.556Z,1336058588.556 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-05-03T15:23:08.556Z,1336058588.556 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-05-03T15:23:08.733Z,1336058588.733 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-05-03T15:23:08.733Z,1336058588.733 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-05-03T15:23:08.820Z,1336058588.819 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-05-03T15:23:08.820Z,1336058588.820 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-05-03T15:23:09.002Z,1336058589.002 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-05-03T15:23:09.003Z,1336058589.003 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-05-03T15:23:09.135Z,1336058589.135 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-05-03T15:23:09.136Z,1336058589.136 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-05-03T15:23:09.350Z,1336058589.349 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-05-03T15:23:09.350Z,1336058589.350 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-05-03T15:23:09.495Z,1336058589.495 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-05-03T15:23:09.495Z,1336058589.496 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-05-03T15:23:09.701Z,1336058589.701 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-05-03T15:23:09.702Z,1336058589.702 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-05-03T15:23:09.801Z,1336058589.801 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-05-03T15:23:09.802Z,1336058589.802 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-05-03T15:23:10.186Z,1336058590.186 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-05-03T15:23:10.187Z,1336058590.187 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-05-03T15:23:10.296Z,1336058590.296 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-05-03T15:23:10.296Z,1336058590.296 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-05-03T15:23:10.381Z,1336058590.381 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2012-05-03T15:23:10.382Z,1336058590.382 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2012-05-03T15:23:10.484Z,1336058590.484 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2012-05-03T15:23:10.614Z,1336058590.614 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2012-05-03T15:23:10.713Z,1336058590.713 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2012-05-03T15:23:10.808Z,1336058590.808 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2012-05-03T15:23:10.916Z,1336058590.916 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2012-05-03T15:23:11.005Z,1336058591.006 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2012-05-03T15:23:11.092Z,1336058591.092 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2012-05-03T15:23:11.203Z,1336058591.203 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-05-03T15:23:11.324Z,1336058591.324 [InternalSim] Loaded
2012-05-03T15:23:11.324Z,1336058591.325 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-05-03T15:23:11.325Z,1336058591.325 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-05-03T15:23:11.326Z,1336058591.326 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-05-03T15:23:11.366Z,1336058591.366 [SBIT](DEBUG): Construct Startup Built In Test.
2012-05-03T15:23:11.377Z,1336058591.376 [SBIT] Loaded
2012-05-03T15:23:11.377Z,1336058591.377 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-05-03T15:23:11.378Z,1336058591.378 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-05-03T15:23:11.400Z,1336058591.400 [IBIT] Loaded
2012-05-03T15:23:11.401Z,1336058591.401 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-05-03T15:23:11.407Z,1336058591.408 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-05-03T15:23:11.510Z,1336058591.510 [CBIT] Loaded
2012-05-03T15:23:11.511Z,1336058591.511 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-05-03T15:23:11.511Z,1336058591.511 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-05-03T15:23:11.512Z,1336058591.512 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-05-03T15:23:11.637Z,1336058591.637 [BuoyancyServo] Loaded
2012-05-03T15:23:11.637Z,1336058591.637 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-05-03T15:23:11.643Z,1336058591.644 [ElevatorServo] Loaded
2012-05-03T15:23:11.644Z,1336058591.644 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2012-05-03T15:23:11.650Z,1336058591.650 [MassServo] Loaded
2012-05-03T15:23:11.650Z,1336058591.650 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2012-05-03T15:23:11.656Z,1336058591.657 [RudderServo] Loaded
2012-05-03T15:23:11.657Z,1336058591.657 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-05-03T15:23:11.663Z,1336058591.663 [ThrusterServo] Loaded
2012-05-03T15:23:11.663Z,1336058591.663 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-05-03T15:23:11.664Z,1336058591.664 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-05-03T15:23:11.664Z,1336058591.664 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-05-03T15:23:11.679Z,1336058591.679 [DepthRateCalculator] Loaded
2012-05-03T15:23:11.679Z,1336058591.679 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-05-03T15:23:11.694Z,1336058591.694 [NavChart] Loaded
2012-05-03T15:23:11.694Z,1336058591.694 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-05-03T15:23:11.700Z,1336058591.700 [PitchRateCalculator] Loaded
2012-05-03T15:23:11.700Z,1336058591.700 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-05-03T15:23:11.705Z,1336058591.705 [SpeedCalculator] Loaded
2012-05-03T15:23:11.706Z,1336058591.706 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-05-03T15:23:11.719Z,1336058591.719 [TempGradientCalculator] Loaded
2012-05-03T15:23:11.720Z,1336058591.720 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-05-03T15:23:11.725Z,1336058591.725 [YawRateCalculator] Loaded
2012-05-03T15:23:11.725Z,1336058591.725 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-05-03T15:23:11.754Z,1336058591.754 [Navigation] Loaded
2012-05-03T15:23:11.754Z,1336058591.754 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-05-03T15:23:11.755Z,1336058591.755 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-05-03T15:23:11.755Z,1336058591.755 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-05-03T15:23:11.955Z,1336058591.955 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-05-03T15:23:11.955Z,1336058591.955 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-05-03T15:23:11.975Z,1336058591.975 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-05-03T15:23:11.975Z,1336058591.976 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-05-03T15:23:12.011Z,1336058592.011 [VerticalControl](DEBUG): Construct VerticalControl.
2012-05-03T15:23:12.053Z,1336058592.053 [VerticalControl] Loaded
2012-05-03T15:23:12.053Z,1336058592.053 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-05-03T15:23:12.054Z,1336058592.054 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-05-03T15:23:12.073Z,1336058592.073 [HorizontalControl] Loaded
2012-05-03T15:23:12.073Z,1336058592.073 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-05-03T15:23:12.075Z,1336058592.075 [SpeedControl](DEBUG): Construct SpeedControl.
2012-05-03T15:23:12.076Z,1336058592.076 [SpeedControl] Loaded
2012-05-03T15:23:12.076Z,1336058592.076 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-05-03T15:23:12.077Z,1336058592.077 [LoopControl](DEBUG): Construct LoopControl.
2012-05-03T15:23:12.078Z,1336058592.078 [LoopControl] Loaded
2012-05-03T15:23:12.078Z,1336058592.078 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-05-03T15:23:12.078Z,1336058592.078 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-05-03T15:23:12.079Z,1336058592.079 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-05-03T15:23:12.084Z,1336058592.084 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-05-03T15:23:12.088Z,1336058592.088 [AsyncPiEstimator] Loaded
2012-05-03T15:23:12.089Z,1336058592.089 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-05-03T15:23:12.090Z,1336058592.090 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 1078994144
2012-05-03T15:23:12.091Z,1336058592.091 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-05-03T15:23:12.091Z,1336058592.091 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-05-03T15:23:12.180Z,1336058592.180 [AHRS_sp3003D] Loaded
2012-05-03T15:23:12.180Z,1336058592.180 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-05-03T15:23:12.418Z,1336058592.418 [Batt_Ocean_Server] Loaded
2012-05-03T15:23:12.418Z,1336058592.418 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2012-05-03T15:23:12.430Z,1336058592.430 [Depth_Keller] Loaded
2012-05-03T15:23:12.430Z,1336058592.430 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2012-05-03T15:23:12.435Z,1336058592.435 [DropWeight] Loaded
2012-05-03T15:23:12.435Z,1336058592.435 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2012-05-03T15:23:12.523Z,1336058592.523 [DVL_micro] Loaded
2012-05-03T15:23:12.523Z,1336058592.523 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2012-05-03T15:23:12.598Z,1336058592.598 [NAL9601] Loaded
2012-05-03T15:23:12.598Z,1336058592.598 [ComponentRegistry](DEBUG): SyncComponent "NAL9601" handled in the control thread.
2012-05-03T15:23:12.645Z,1336058592.645 [Onboard] Loaded
2012-05-03T15:23:12.645Z,1336058592.645 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-05-03T15:23:12.651Z,1336058592.651 [Radio_Freewave] Loaded
2012-05-03T15:23:12.651Z,1336058592.651 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2012-05-03T15:23:12.652Z,1336058592.652 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-05-03T15:23:12.652Z,1336058592.652 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-05-03T15:23:12.695Z,1336058592.695 [CTD_NeilBrown] Loaded
2012-05-03T15:23:12.696Z,1336058592.695 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2012-05-03T15:23:12.697Z,1336058592.697 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 1079645408
2012-05-03T15:23:12.725Z,1336058592.726 [WetLabsBB2FL] Loaded
2012-05-03T15:23:12.726Z,1336058592.726 [ComponentRegistry](DEBUG): SyncComponent "WetLabsBB2FL" handled in the control thread.
2012-05-03T15:23:12.726Z,1336058592.726 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-05-03T15:23:12.728Z,1336058592.728 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-05-03T15:23:12.729Z,1336058592.729 [ComponentRegistry](DEBUG): SyncComponent "Maintainer" handled in the control thread.
2012-05-03T15:23:12.730Z,1336058592.730 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-05-03T15:23:12.735Z,1336058592.735 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-05-03T15:23:12.736Z,1336058592.736 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 1079842016
2012-05-03T15:23:12.736Z,1336058592.736 [Supervisor](DEBUG): Running supervisor.
2012-05-03T15:23:12.739Z,1336058592.740 [controlThread](DEBUG): Initializing ControlThread
2012-05-03T15:23:12.740Z,1336058592.740 [InternalSim](DEBUG):  InternalSim initializing...
2012-05-03T15:23:12.775Z,1336058592.775 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-05-03T15:23:12.783Z,1336058592.783 [SBIT](INFO): Initialize SBIT Component.
2012-05-03T15:23:12.784Z,1336058592.784 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 9626 $
2012-05-03T15:23:12.785Z,1336058592.785 [IBIT](INFO): Initialize IBIT Component.
2012-05-03T15:23:12.788Z,1336058592.788 [CBIT](DEBUG): Initialize CBIT Component.
2012-05-03T15:23:12.788Z,1336058592.788 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2012-05-03T15:23:12.789Z,1336058592.789 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-05-03T15:23:12.812Z,1336058592.812 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-05-03T15:23:12.812Z,1336058592.812 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-05-03T15:23:12.812Z,1336058592.812 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-05-03T15:23:12.813Z,1336058592.813 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-05-03T15:23:12.813Z,1336058592.813 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-05-03T15:23:12.815Z,1336058592.815 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-05-03T15:23:12.815Z,1336058592.815 [Navigation](DEBUG): Initializing Navigation.
2012-05-03T15:23:12.816Z,1336058592.816 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-05-03T15:23:12.818Z,1336058592.818 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-05-03T15:23:12.818Z,1336058592.819 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-05-03T15:23:12.819Z,1336058592.819 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-05-03T15:23:12.898Z,1336058592.898 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-05-03T15:23:12.903Z,1336058592.903 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2012-05-03T15:23:12.907Z,1336058592.907 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2012-05-03T15:23:12.911Z,1336058592.911 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2012-05-03T15:23:12.916Z,1336058592.916 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2012-05-03T15:23:12.916Z,1336058592.916 [NavChartDb](INFO): Creating index for Soundings
2012-05-03T15:23:12.920Z,1336058592.920 [NavChartDb](INFO): Creating index for Contour 0p0
2012-05-03T15:23:12.922Z,1336058592.922 [NavChartDb](INFO): Creating index for Contour 1p8
2012-05-03T15:23:12.924Z,1336058592.924 [NavChartDb](INFO): Creating index for Contour 3p6
2012-05-03T15:23:12.926Z,1336058592.926 [NavChartDb](INFO): Creating index for Contour 5p4
2012-05-03T15:23:12.928Z,1336058592.928 [NavChartDb](INFO): Creating index for Contour 9p1
2012-05-03T15:23:12.929Z,1336058592.930 [NavChartDb](INFO): Creating index for Contour 10p9
2012-05-03T15:23:12.932Z,1336058592.932 [NavChartDb](INFO): Creating index for Contour 18p2
2012-05-03T15:23:12.933Z,1336058592.933 [NavChartDb](INFO): Creating index for Contour 36p5
2012-05-03T15:23:12.936Z,1336058592.935 [NavChartDb](INFO): Creating index for Contour 54p8
2012-05-03T15:23:12.937Z,1336058592.937 [NavChartDb](INFO): Creating index for Contour 73p1
2012-05-03T15:23:12.939Z,1336058592.940 [NavChartDb](INFO): Creating index for Contour 91p4
2012-05-03T15:23:12.941Z,1336058592.941 [NavChartDb](INFO): Creating index for Contour 182p8
2012-05-03T15:23:12.943Z,1336058592.943 [NavChartDb](INFO): Creating index for Contour 365p7
2012-05-03T15:23:12.945Z,1336058592.945 [NavChartDb](INFO): Creating index for Contour 548p6
2012-05-03T15:23:12.947Z,1336058592.947 [NavChartDb](INFO): Creating index for Contour 731p5
2012-05-03T15:23:12.949Z,1336058592.949 [NavChartDb](INFO): Creating index for Contour 914p4
2012-05-03T15:23:12.951Z,1336058592.951 [NavChartDb](INFO): Creating index for Contour 1097p2
2012-05-03T15:23:12.953Z,1336058592.953 [NavChartDb](INFO): Creating index for Contour 1280p1
2012-05-03T15:23:12.955Z,1336058592.955 [NavChartDb](INFO): Creating index for Contour 1463p0
2012-05-03T15:23:12.957Z,1336058592.957 [NavChartDb](INFO): Creating index for Contour 1645p9
2012-05-03T15:23:12.959Z,1336058592.959 [NavChartDb](INFO): Creating index for Contour 1828p8
2012-05-03T15:23:12.961Z,1336058592.961 [NavChartDb](INFO): Creating index for Contour 2011p6
2012-05-03T15:23:12.962Z,1336058592.963 [NavChartDb](INFO): Creating index for Contour 2194p5
2012-05-03T15:23:12.964Z,1336058592.964 [NavChartDb](INFO): Creating index for Contour 2377p4
2012-05-03T15:23:12.966Z,1336058592.966 [NavChartDb](INFO): Creating index for Contour 2560p3
2012-05-03T15:23:12.968Z,1336058592.968 [NavChartDb](INFO): Creating index for Contour 2743p2
2012-05-03T15:23:12.970Z,1336058592.970 [NavChartDb](INFO): Creating index for Contour 2926p0
2012-05-03T15:23:12.972Z,1336058592.972 [NavChartDb](INFO): Creating index for Contour 3108p9
2012-05-03T15:23:12.974Z,1336058592.974 [NavChartDb](INFO): Creating index for Contour 3291p8
2012-05-03T15:23:12.976Z,1336058592.976 [NavChartDb](INFO): Creating index for Contour 3474p7
2012-05-03T15:23:12.978Z,1336058592.978 [NavChartDb](INFO): Creating index for Contour 3657p6
2012-05-03T15:23:14.363Z,1336058594.363 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2012-05-03T15:23:14.368Z,1336058594.368 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-05-03T15:23:14.378Z,1336058594.378 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-03T15:23:14.387Z,1336058594.387 [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-03T15:23:14.388Z,1336058594.388 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-05-03T15:23:14.415Z,1336058594.415 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2012-05-03T15:23:14.417Z,1336058594.417 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-05-03T15:23:14.420Z,1336058594.420 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-03T15:23:14.428Z,1336058594.428 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-05-03T15:23:14.431Z,1336058594.431 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-03T15:23:14.437Z,1336058594.437 [Default:Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-05-03T15:23:14.445Z,1336058594.445 [Default:D.SetSpeed](DEBUG): Construct.
2012-05-03T15:23:14.451Z,1336058594.451 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-03T15:23:14.456Z,1336058594.456 [Default:F.Wait](DEBUG): Construct Wait.
2012-05-03T15:23:14.459Z,1336058594.459 [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 on</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-03T15:23:14.465Z,1336058594.464 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9601,Onboard,Radio_Freewave,WetLabsBB2FL,Depth_Keller,DepthRateCalculator,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintainer,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,logger,
2012-05-03T15:23:14.483Z,1336058594.483 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-05-03T15:23:14.593Z,1336058594.593 [DVL_micro](DEBUG): Initializing DVL_micro.
2012-05-03T15:23:14.613Z,1336058594.613 [Radio_Freewave](INFO): Powering up
2012-05-03T15:23:14.619Z,1336058594.619 [WetLabsBB2FL](INFO): Powering down
2012-05-03T15:23:14.688Z,1336058594.688 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-05-03T15:23:14.689Z,1336058594.689 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-05-03T15:23:14.698Z,1336058594.698 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-05-03T15:23:14.699Z,1336058594.699 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-05-03T15:23:14.706Z,1336058594.707 [MassServo](DEBUG): Initializing EZServoServo.
2012-05-03T15:23:14.707Z,1336058594.707 [MassServo](DEBUG): Initializing MassServo.
2012-05-03T15:23:14.716Z,1336058594.716 [RudderServo](DEBUG): Initializing EZServoServo.
2012-05-03T15:23:14.717Z,1336058594.717 [RudderServo](DEBUG): Initializing RudderServo.
2012-05-03T15:23:14.725Z,1336058594.725 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-05-03T15:23:14.725Z,1336058594.726 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-05-03T15:23:17.609Z,1336058597.609 [NAL9601](INFO): Powering up NAL9601
2012-05-03T15:23:28.409Z,1336058608.409 [SBIT](IMPORTANT): Beginning Startup BIT
2012-05-03T15:23:28.412Z,1336058608.411 [CBIT](IMPORTANT): Beginning GF scan
2012-05-03T15:23:55.055Z,1336058635.055 [CBIT](IMPORTANT): No ground fault detected
2012-05-03T15:23:59.448Z,1336058639.448 [SBIT](FAULT): Elevator: EXPECTED:-15.000000 ACTUAL:-14.905448
2012-05-03T15:23:59.448Z,1336058639.448 [SBIT](FAULT): Control surface position failure.
2012-05-03T15:24:10.513Z,1336058650.513 [SBIT](CRITICAL): SBIT FAILED
2012-05-03T15:24:10.867Z,1336058650.867 [MissionManager](IMPORTANT): Started mission Startup
2012-05-03T15:24:10.867Z,1336058650.867 [Startup] Running Loop=1
2012-05-03T15:24:10.868Z,1336058650.868 [Startup](INFO): Aggregate::initialize Startup
2012-05-03T15:24:10.868Z,1336058650.868 [Startup:A.GoToSurface] Running Loop=1
2012-05-03T15:24:10.868Z,1336058650.868 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T15:24:10.873Z,1336058650.874 [Startup:StartupSatComms] Running Loop=1
2012-05-03T15:24:10.874Z,1336058650.874 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2012-05-03T15:24:10.874Z,1336058650.874 [Startup:StartupSatComms:A] Running Loop=1
2012-05-03T15:24:11.263Z,1336058651.263 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-05-03T15:24:23.331Z,1336058663.331 [NAL9601](INFO): NAL9601 initialized
2012-05-03T15:24:24.465Z,1336058664.465 [NAL9601](IMPORTANT): GPS fix at: 1336058654.00
2012-05-03T15:24:24.478Z,1336058664.478 [Startup:StartupSatComms:A] Stopped
2012-05-03T15:24:24.478Z,1336058664.478 [Startup:StartupSatComms:B] Running Loop=1
2012-05-03T15:24:24.873Z,1336058664.873 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-05-03T15:25:24.813Z,1336058724.813 [Startup:StartupSatComms:B](INFO): Timed out from 2012-05-03T15:24:24.5Z
2012-05-03T15:25:24.813Z,1336058724.813 [Startup:StartupSatComms:A_Timeout] Running Loop=1
2012-05-03T15:25:24.813Z,1336058724.813 [Startup:StartupSatComms:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A_Timeout
2012-05-03T15:25:24.813Z,1336058724.813 [Startup:StartupSatComms:A_Timeout](INFO): Completed Startup:StartupSatComms:A_Timeout
2012-05-03T15:25:24.813Z,1336058724.813 [Startup:StartupSatComms:B] Stopped
2012-05-03T15:25:24.813Z,1336058724.813 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2012-05-03T15:25:24.813Z,1336058724.813 [Startup:StartupSatComms] Stopped
2012-05-03T15:25:24.814Z,1336058724.814 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2012-05-03T15:25:24.819Z,1336058724.819 [Startup](INFO): Completed Startup
2012-05-03T15:25:24.819Z,1336058724.819 [Startup] Stopped
2012-05-03T15:25:24.819Z,1336058724.819 [Startup](INFO): Aggregate::uninitialize Startup
2012-05-03T15:25:24.819Z,1336058724.819 [Startup:A.GoToSurface] Stopped
2012-05-03T15:25:24.819Z,1336058724.819 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T15:25:25.715Z,1336058725.715 [MissionManager](IMPORTANT): Started mission Default
2012-05-03T15:25:25.715Z,1336058725.715 [Default] Running Loop=1
2012-05-03T15:25:25.715Z,1336058725.716 [Default](INFO): Aggregate::initialize Default
2012-05-03T15:25:25.716Z,1336058725.716 [Default:D.SetSpeed] Running Loop=1
2012-05-03T15:25:25.716Z,1336058725.716 [Default:D.SetSpeed](DEBUG): Initialize.
2012-05-03T15:25:25.716Z,1336058725.716 [Default:E.GoToSurface] Running Loop=1
2012-05-03T15:25:25.716Z,1336058725.716 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T15:25:25.716Z,1336058725.716 [Default:Iridium] Running Loop=1
2012-05-03T15:25:25.716Z,1336058725.717 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-03T15:25:25.717Z,1336058725.717 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T15:25:25.717Z,1336058725.717 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-03T15:25:25.717Z,1336058725.717 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-03T15:25:25.717Z,1336058725.717 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T15:25:25.718Z,1336058725.718 [Default:E.GoToSurface] Running Loop=1
2012-05-03T15:25:25.723Z,1336058725.723 [Default:D.SetSpeed] Running Loop=1
2012-05-03T15:25:25.739Z,1336058725.739 [Default:CallIridium] Running Loop=1
2012-05-03T15:25:25.739Z,1336058725.739 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-03T15:25:25.740Z,1336058725.740 [Default:CallIridium:A] Running Loop=1
2012-05-03T15:25:25.741Z,1336058725.741 [Default:CallIridium:A] Stopped
2012-05-03T15:25:25.741Z,1336058725.741 [Default:CallIridium:B] Running Loop=1
2012-05-03T15:25:25.742Z,1336058725.741 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-03T15:25:25.746Z,1336058725.746 [Default:Iridium:B.GoToSurface] Stopped
2012-05-03T15:25:25.746Z,1336058725.746 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T15:25:25.747Z,1336058725.747 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-03T15:25:25.747Z,1336058725.747 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T15:25:25.763Z,1336058725.763 [Default:GPS] Running Loop=1
2012-05-03T15:25:25.763Z,1336058725.763 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-03T15:25:25.763Z,1336058725.763 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T15:25:25.763Z,1336058725.763 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-03T15:25:25.764Z,1336058725.764 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-03T15:25:25.764Z,1336058725.764 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T15:25:25.769Z,1336058725.769 [Default:GPS:B.GoToSurface] Stopped
2012-05-03T15:25:25.769Z,1336058725.769 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T15:25:25.769Z,1336058725.769 [Default:GPS:Read_GPS] Running Loop=1
2012-05-03T15:25:25.769Z,1336058725.769 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T15:25:26.035Z,1336058726.035 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-05-03T15:25:26.038Z,1336058726.038 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-05-03T15:25:27.187Z,1336058727.187 [NAL9601](IMPORTANT): GPS fix at: 1336058717.00
2012-05-03T15:25:27.209Z,1336058727.209 [Default:GPS:Read_GPS] Stopped
2012-05-03T15:25:27.210Z,1336058727.210 [Default:GPS:D] Running Loop=1
2012-05-03T15:25:27.616Z,1336058727.616 [Default:GPS:D] Stopped
2012-05-03T15:25:27.616Z,1336058727.616 [Default:GPS](INFO): Completed Default:GPS
2012-05-03T15:25:27.616Z,1336058727.616 [Default:GPS] Stopped
2012-05-03T15:25:27.617Z,1336058727.616 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-03T15:25:27.617Z,1336058727.617 [Default:GPS:A.SetSpeed] Stopped
2012-05-03T15:25:27.617Z,1336058727.617 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T15:26:51.758Z,1336058811.758 [NAL9601](INFO): SBD MO Status=1, MOMSN=5831, MT Status=0, MTMSN=0
2012-05-03T15:26:51.887Z,1336058811.887 [NAL9601](INFO): Sent 207 bytes from file Logs/20120503T145034/shore0007.lzma
2012-05-03T15:26:51.887Z,1336058811.887 [NAL9601](INFO): Packets left to send: 0
2012-05-03T15:26:51.888Z,1336058811.888 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000000
2012-05-03T15:27:10.748Z,1336058830.748 [NAL9601](INFO): SBD MO Status=1, MOMSN=5832, MT Status=0, MTMSN=0
2012-05-03T15:27:10.959Z,1336058830.959 [NAL9601](INFO): Sent 332 bytes from file Logs/20120503T152308/shore0000.lzma
2012-05-03T15:27:10.959Z,1336058830.959 [NAL9601](INFO): Packets left to send: 2
2012-05-03T15:27:10.960Z,1336058830.960 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000001
2012-05-03T15:27:24.448Z,1336058844.448 [NAL9601](INFO): SBD MO Status=1, MOMSN=5833, MT Status=0, MTMSN=0
2012-05-03T15:27:24.635Z,1336058844.635 [NAL9601](INFO): Sent 332 bytes from file Logs/20120503T152308/shore0000.lzma
2012-05-03T15:27:24.635Z,1336058844.635 [NAL9601](INFO): Packets left to send: 1
2012-05-03T15:27:24.636Z,1336058844.636 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000002
2012-05-03T15:27:31.737Z,1336058851.737 [NAL9601](INFO): SBD MO Status=1, MOMSN=5834, MT Status=0, MTMSN=0
2012-05-03T15:27:31.927Z,1336058851.927 [NAL9601](INFO): Sent 84 bytes from file Logs/20120503T152308/shore0000.lzma
2012-05-03T15:27:31.927Z,1336058851.927 [NAL9601](INFO): Packets left to send: 0
2012-05-03T15:27:31.928Z,1336058851.928 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000003
2012-05-03T15:27:39.733Z,1336058859.733 [NAL9601](INFO): SBD MO Status=0, MOMSN=5835, MT Status=0, MTMSN=0
2012-05-03T15:27:39.930Z,1336058859.930 [Default:Iridium:Read_Iridium] Stopped
2012-05-03T15:27:39.930Z,1336058859.931 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-03T15:27:39.931Z,1336058859.931 [Default:Iridium] Stopped
2012-05-03T15:27:39.931Z,1336058859.931 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-03T15:27:39.931Z,1336058859.931 [Default:Iridium:A.SetSpeed] Stopped
2012-05-03T15:27:39.931Z,1336058859.931 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T15:27:39.931Z,1336058859.931 [Default:F.Wait] Running Loop=1
2012-05-03T15:27:39.931Z,1336058859.931 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-05-03T15:27:40.155Z,1336058860.155 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-03T15:27:40.156Z,1336058860.156 [Default:CallIridium:B] Stopped
2012-05-03T15:27:40.156Z,1336058860.156 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-03T15:27:40.156Z,1336058860.156 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-03T15:27:40.156Z,1336058860.156 [Default:CallIridium] Stopped
2012-05-03T15:27:40.156Z,1336058860.156 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-03T15:27:50.299Z,1336058870.299 [NAL9601](INFO): Powering down
2012-05-03T15:28:30.266Z,1336058910.266 [Depth_Keller](ERROR): Pressure reading out of range: 980.650574 decibar
2012-05-03T15:28:50.275Z,1336058930.275 [Depth_Keller](ERROR): Pressure reading out of range: 1830.746460 decibar
2012-05-03T15:29:05.267Z,1336058945.267 [Depth_Keller](ERROR): Pressure reading out of range: 1830.797241 decibar
2012-05-03T15:29:35.278Z,1336058975.278 [Depth_Keller](ERROR): Pressure reading out of range: 1373.052734 decibar
2012-05-03T15:31:25.338Z,1336059085.338 [Depth_Keller](ERROR): Pressure reading out of range: 1830.744751 decibar
2012-05-03T15:31:35.302Z,1336059095.302 [Depth_Keller](ERROR): Pressure reading out of range: 1830.789185 decibar
2012-05-03T15:31:45.318Z,1336059105.318 [Depth_Keller](ERROR): Pressure reading out of range: 1830.831177 decibar
2012-05-03T15:31:55.310Z,1336059115.310 [Depth_Keller](ERROR): Pressure reading out of range: -850.135193 decibar
2012-05-03T15:32:25.364Z,1336059145.364 [Depth_Keller](ERROR): Pressure reading out of range: 1830.839966 decibar
2012-05-03T15:32:40.313Z,1336059160.313 [Default:CallIridium] Running Loop=1
2012-05-03T15:32:40.313Z,1336059160.313 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-03T15:32:40.313Z,1336059160.313 [Default:CallIridium:A] Running Loop=1
2012-05-03T15:32:40.313Z,1336059160.313 [Default:CallIridium:A] Stopped
2012-05-03T15:32:40.314Z,1336059160.314 [Default:CallIridium:B] Running Loop=1
2012-05-03T15:32:40.314Z,1336059160.314 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-03T15:32:45.311Z,1336059165.311 [Default:Iridium] Running Loop=1
2012-05-03T15:32:45.312Z,1336059165.312 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-03T15:32:45.312Z,1336059165.312 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T15:32:45.312Z,1336059165.312 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-03T15:32:45.312Z,1336059165.312 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-03T15:32:45.312Z,1336059165.312 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T15:32:45.313Z,1336059165.313 [Default:Iridium:B.GoToSurface] Stopped
2012-05-03T15:32:45.313Z,1336059165.313 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T15:32:45.313Z,1336059165.313 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-03T15:32:45.313Z,1336059165.313 [Default:GPS] Running Loop=1
2012-05-03T15:32:45.313Z,1336059165.313 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-03T15:32:45.314Z,1336059165.314 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T15:32:45.314Z,1336059165.314 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-03T15:32:45.314Z,1336059165.314 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-03T15:32:45.314Z,1336059165.314 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T15:32:45.316Z,1336059165.316 [Default:GPS:B.GoToSurface] Stopped
2012-05-03T15:32:45.316Z,1336059165.316 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T15:32:45.316Z,1336059165.316 [Default:GPS:Read_GPS] Running Loop=1
2012-05-03T15:32:45.936Z,1336059165.936 [NAL9601](INFO): Powering up
2012-05-03T15:33:51.659Z,1336059231.659 [NAL9601](INFO): NAL9601 initialized
2012-05-03T15:33:52.739Z,1336059232.739 [NAL9601](IMPORTANT): GPS fix at: 1336059223.00
2012-05-03T15:33:52.754Z,1336059232.754 [Default:GPS:Read_GPS] Stopped
2012-05-03T15:33:52.755Z,1336059232.755 [Default:GPS:D] Running Loop=1
2012-05-03T15:33:53.204Z,1336059233.204 [Default:GPS:D] Stopped
2012-05-03T15:33:53.204Z,1336059233.204 [Default:GPS](INFO): Completed Default:GPS
2012-05-03T15:33:53.204Z,1336059233.204 [Default:GPS] Stopped
2012-05-03T15:33:53.205Z,1336059233.204 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-03T15:33:53.205Z,1336059233.205 [Default:GPS:A.SetSpeed] Stopped
2012-05-03T15:33:53.205Z,1336059233.205 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T15:34:08.266Z,1336059248.266 [NAL9601](INFO): SBD MO Status=1, MOMSN=5836, MT Status=0, MTMSN=0
2012-05-03T15:34:08.423Z,1336059248.423 [NAL9601](INFO): Sent 332 bytes from file Logs/20120503T152308/shore0001.lzma
2012-05-03T15:34:08.423Z,1336059248.423 [NAL9601](INFO): Packets left to send: 1
2012-05-03T15:34:08.424Z,1336059248.424 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000004
2012-05-03T15:34:17.577Z,1336059257.577 [NAL9601](INFO): SBD MO Status=1, MOMSN=5837, MT Status=0, MTMSN=0
2012-05-03T15:34:17.707Z,1336059257.707 [NAL9601](INFO): Sent 35 bytes from file Logs/20120503T152308/shore0001.lzma
2012-05-03T15:34:17.707Z,1336059257.707 [NAL9601](INFO): Packets left to send: 0
2012-05-03T15:34:17.708Z,1336059257.708 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000005
2012-05-03T15:34:24.784Z,1336059264.784 [NAL9601](INFO): SBD MO Status=0, MOMSN=5838, MT Status=0, MTMSN=0
2012-05-03T15:34:25.009Z,1336059265.009 [Default:Iridium:Read_Iridium] Stopped
2012-05-03T15:34:25.010Z,1336059265.010 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-03T15:34:25.010Z,1336059265.010 [Default:Iridium] Stopped
2012-05-03T15:34:25.010Z,1336059265.010 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-03T15:34:25.010Z,1336059265.010 [Default:Iridium:A.SetSpeed] Stopped
2012-05-03T15:34:25.010Z,1336059265.010 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T15:34:25.569Z,1336059265.569 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-03T15:34:25.569Z,1336059265.569 [Default:CallIridium:B] Stopped
2012-05-03T15:34:25.569Z,1336059265.569 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-03T15:34:25.569Z,1336059265.569 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-03T15:34:25.569Z,1336059265.569 [Default:CallIridium] Stopped
2012-05-03T15:34:25.569Z,1336059265.569 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-03T15:34:35.434Z,1336059275.434 [NAL9601](INFO): Powering down
2012-05-03T15:39:25.488Z,1336059565.488 [Default:CallIridium] Running Loop=1
2012-05-03T15:39:25.488Z,1336059565.488 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-03T15:39:25.488Z,1336059565.488 [Default:CallIridium:A] Running Loop=1
2012-05-03T15:39:25.488Z,1336059565.488 [Default:CallIridium:A] Stopped
2012-05-03T15:39:25.488Z,1336059565.489 [Default:CallIridium:B] Running Loop=1
2012-05-03T15:39:25.489Z,1336059565.489 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-03T15:39:30.452Z,1336059570.452 [Default:Iridium] Running Loop=1
2012-05-03T15:39:30.452Z,1336059570.452 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-03T15:39:30.452Z,1336059570.452 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T15:39:30.452Z,1336059570.452 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-03T15:39:30.452Z,1336059570.452 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-03T15:39:30.452Z,1336059570.452 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T15:39:30.453Z,1336059570.453 [Default:Iridium:B.GoToSurface] Stopped
2012-05-03T15:39:30.453Z,1336059570.453 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T15:39:30.453Z,1336059570.453 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-03T15:39:30.454Z,1336059570.454 [Default:GPS] Running Loop=1
2012-05-03T15:39:30.454Z,1336059570.454 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-03T15:39:30.454Z,1336059570.454 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T15:39:30.454Z,1336059570.454 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-03T15:39:30.454Z,1336059570.454 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-03T15:39:30.454Z,1336059570.454 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T15:39:30.455Z,1336059570.455 [Default:GPS:B.GoToSurface] Stopped
2012-05-03T15:39:30.456Z,1336059570.455 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T15:39:30.456Z,1336059570.456 [Default:GPS:Read_GPS] Running Loop=1
2012-05-03T15:39:31.104Z,1336059571.104 [NAL9601](INFO): Powering up
2012-05-03T15:40:36.827Z,1336059636.827 [NAL9601](INFO): NAL9601 initialized
2012-05-03T15:40:37.906Z,1336059637.906 [NAL9601](IMPORTANT): GPS fix at: 1336059629.00
2012-05-03T15:40:37.922Z,1336059637.921 [Default:GPS:Read_GPS] Stopped
2012-05-03T15:40:37.922Z,1336059637.922 [Default:GPS:D] Running Loop=1
2012-05-03T15:40:38.324Z,1336059638.324 [Default:GPS:D] Stopped
2012-05-03T15:40:38.324Z,1336059638.324 [Default:GPS](INFO): Completed Default:GPS
2012-05-03T15:40:38.324Z,1336059638.324 [Default:GPS] Stopped
2012-05-03T15:40:38.324Z,1336059638.324 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-03T15:40:38.324Z,1336059638.324 [Default:GPS:A.SetSpeed] Stopped
2012-05-03T15:40:38.324Z,1336059638.324 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T15:40:59.014Z,1336059659.013 [NAL9601](INFO): SBD MO Status=1, MOMSN=5839, MT Status=0, MTMSN=0
2012-05-03T15:40:59.179Z,1336059659.179 [NAL9601](INFO): Sent 208 bytes from file Logs/20120503T152308/shore0002.lzma
2012-05-03T15:40:59.179Z,1336059659.179 [NAL9601](INFO): Packets left to send: 0
2012-05-03T15:40:59.181Z,1336059659.181 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000006
2012-05-03T15:41:02.214Z,1336059662.214 [NAL9601](INFO): SBD MO Status=0, MOMSN=5840, MT Status=0, MTMSN=0
2012-05-03T15:41:02.389Z,1336059662.389 [Default:Iridium:Read_Iridium] Stopped
2012-05-03T15:41:02.390Z,1336059662.390 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-03T15:41:02.390Z,1336059662.390 [Default:Iridium] Stopped
2012-05-03T15:41:02.390Z,1336059662.390 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-03T15:41:02.391Z,1336059662.391 [Default:Iridium:A.SetSpeed] Stopped
2012-05-03T15:41:02.391Z,1336059662.391 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T15:41:02.622Z,1336059662.622 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-03T15:41:02.622Z,1336059662.622 [Default:CallIridium:B] Stopped
2012-05-03T15:41:02.622Z,1336059662.622 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-03T15:41:02.622Z,1336059662.622 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-03T15:41:02.623Z,1336059662.622 [Default:CallIridium] Stopped
2012-05-03T15:41:02.623Z,1336059662.623 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-03T15:41:12.764Z,1336059672.764 [NAL9601](INFO): Powering down
2012-05-03T15:46:02.816Z,1336059962.816 [Default:CallIridium] Running Loop=1
2012-05-03T15:46:02.816Z,1336059962.816 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-03T15:46:02.817Z,1336059962.817 [Default:CallIridium:A] Running Loop=1
2012-05-03T15:46:02.817Z,1336059962.817 [Default:CallIridium:A] Stopped
2012-05-03T15:46:02.817Z,1336059962.817 [Default:CallIridium:B] Running Loop=1
2012-05-03T15:46:02.817Z,1336059962.817 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-03T15:46:07.751Z,1336059967.751 [Default:Iridium] Running Loop=1
2012-05-03T15:46:07.751Z,1336059967.751 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-03T15:46:07.751Z,1336059967.751 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T15:46:07.751Z,1336059967.751 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-03T15:46:07.751Z,1336059967.751 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-03T15:46:07.751Z,1336059967.751 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T15:46:07.752Z,1336059967.752 [Default:Iridium:B.GoToSurface] Stopped
2012-05-03T15:46:07.752Z,1336059967.752 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T15:46:07.752Z,1336059967.752 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-03T15:46:07.753Z,1336059967.753 [Default:GPS] Running Loop=1
2012-05-03T15:46:07.753Z,1336059967.753 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-03T15:46:07.753Z,1336059967.753 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T15:46:07.753Z,1336059967.753 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-03T15:46:07.753Z,1336059967.753 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-03T15:46:07.753Z,1336059967.753 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T15:46:07.754Z,1336059967.754 [Default:GPS:B.GoToSurface] Stopped
2012-05-03T15:46:07.754Z,1336059967.754 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T15:46:07.754Z,1336059967.754 [Default:GPS:Read_GPS] Running Loop=1
2012-05-03T15:46:08.427Z,1336059968.427 [NAL9601](INFO): Powering up
2012-05-03T15:47:14.055Z,1336060034.055 [NAL9601](INFO): NAL9601 initialized
2012-05-03T15:47:15.216Z,1336060035.216 [NAL9601](IMPORTANT): GPS fix at: 1336060027.00
2012-05-03T15:47:15.231Z,1336060035.231 [Default:GPS:Read_GPS] Stopped
2012-05-03T15:47:15.231Z,1336060035.231 [Default:GPS:D] Running Loop=1
2012-05-03T15:47:15.623Z,1336060035.623 [Default:GPS:D] Stopped
2012-05-03T15:47:15.624Z,1336060035.624 [Default:GPS](INFO): Completed Default:GPS
2012-05-03T15:47:15.624Z,1336060035.624 [Default:GPS] Stopped
2012-05-03T15:47:15.624Z,1336060035.624 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-03T15:47:15.624Z,1336060035.624 [Default:GPS:A.SetSpeed] Stopped
2012-05-03T15:47:15.624Z,1336060035.624 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T15:47:32.774Z,1336060052.774 [NAL9601](INFO): SBD MO Status=1, MOMSN=5841, MT Status=0, MTMSN=0
2012-05-03T15:47:32.911Z,1336060052.911 [NAL9601](INFO): Sent 200 bytes from file Logs/20120503T152308/shore0003.lzma
2012-05-03T15:47:32.911Z,1336060052.911 [NAL9601](INFO): Packets left to send: 0
2012-05-03T15:47:32.912Z,1336060052.912 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000007
2012-05-03T15:47:40.373Z,1336060060.374 [NAL9601](INFO): SBD MO Status=0, MOMSN=5842, MT Status=0, MTMSN=0
2012-05-03T15:47:40.526Z,1336060060.526 [Default:Iridium:Read_Iridium] Stopped
2012-05-03T15:47:40.527Z,1336060060.527 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-03T15:47:40.527Z,1336060060.527 [Default:Iridium] Stopped
2012-05-03T15:47:40.527Z,1336060060.527 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-03T15:47:40.527Z,1336060060.527 [Default:Iridium:A.SetSpeed] Stopped
2012-05-03T15:47:40.527Z,1336060060.527 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T15:47:40.785Z,1336060060.785 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-03T15:47:40.785Z,1336060060.785 [Default:CallIridium:B] Stopped
2012-05-03T15:47:40.785Z,1336060060.785 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-03T15:47:40.785Z,1336060060.785 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-03T15:47:40.785Z,1336060060.786 [Default:CallIridium] Stopped
2012-05-03T15:47:40.786Z,1336060060.786 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-03T15:47:50.922Z,1336060070.922 [NAL9601](INFO): Powering down
2012-05-03T15:52:40.981Z,1336060360.981 [Default:CallIridium] Running Loop=1
2012-05-03T15:52:40.981Z,1336060360.981 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-03T15:52:40.982Z,1336060360.981 [Default:CallIridium:A] Running Loop=1
2012-05-03T15:52:40.982Z,1336060360.982 [Default:CallIridium:A] Stopped
2012-05-03T15:52:40.982Z,1336060360.982 [Default:CallIridium:B] Running Loop=1
2012-05-03T15:52:40.982Z,1336060360.982 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-03T15:52:46.047Z,1336060366.047 [Default:Iridium] Running Loop=1
2012-05-03T15:52:46.047Z,1336060366.047 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-03T15:52:46.047Z,1336060366.047 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T15:52:46.047Z,1336060366.047 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-03T15:52:46.047Z,1336060366.047 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-03T15:52:46.047Z,1336060366.047 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T15:52:46.048Z,1336060366.048 [Default:Iridium:B.GoToSurface] Stopped
2012-05-03T15:52:46.048Z,1336060366.048 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T15:52:46.048Z,1336060366.048 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-03T15:52:46.049Z,1336060366.049 [Default:GPS] Running Loop=1
2012-05-03T15:52:46.049Z,1336060366.049 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-03T15:52:46.049Z,1336060366.049 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T15:52:46.049Z,1336060366.049 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-03T15:52:46.049Z,1336060366.049 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-03T15:52:46.049Z,1336060366.049 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T15:52:46.050Z,1336060366.050 [Default:GPS:B.GoToSurface] Stopped
2012-05-03T15:52:46.062Z,1336060366.062 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T15:52:46.062Z,1336060366.062 [Default:GPS:Read_GPS] Running Loop=1
2012-05-03T15:52:46.640Z,1336060366.640 [NAL9601](INFO): Powering up
2012-05-03T15:53:52.363Z,1336060432.363 [NAL9601](INFO): NAL9601 initialized
2012-05-03T15:53:53.449Z,1336060433.450 [NAL9601](IMPORTANT): GPS fix at: 1336060426.00
2012-05-03T15:53:53.465Z,1336060433.464 [Default:GPS:Read_GPS] Stopped
2012-05-03T15:53:53.465Z,1336060433.465 [Default:GPS:D] Running Loop=1
2012-05-03T15:53:53.854Z,1336060433.854 [Default:GPS:D] Stopped
2012-05-03T15:53:53.854Z,1336060433.855 [Default:GPS](INFO): Completed Default:GPS
2012-05-03T15:53:53.855Z,1336060433.855 [Default:GPS] Stopped
2012-05-03T15:53:53.855Z,1336060433.855 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-03T15:53:53.855Z,1336060433.855 [Default:GPS:A.SetSpeed] Stopped
2012-05-03T15:53:53.855Z,1336060433.855 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T15:54:14.176Z,1336060454.176 [NAL9601](INFO): SBD MO Status=1, MOMSN=5843, MT Status=0, MTMSN=0
2012-05-03T15:54:14.319Z,1336060454.319 [NAL9601](INFO): Sent 235 bytes from file Logs/20120503T152308/shore0004.lzma
2012-05-03T15:54:14.319Z,1336060454.319 [NAL9601](INFO): Packets left to send: 0
2012-05-03T15:54:14.320Z,1336060454.320 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000008
2012-05-03T15:54:25.336Z,1336060465.336 [NAL9601](INFO): SBD MO Status=0, MOMSN=5844, MT Status=0, MTMSN=0
2012-05-03T15:54:25.513Z,1336060465.513 [Default:Iridium:Read_Iridium] Stopped
2012-05-03T15:54:25.513Z,1336060465.513 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-03T15:54:25.513Z,1336060465.513 [Default:Iridium] Stopped
2012-05-03T15:54:25.513Z,1336060465.513 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-03T15:54:25.514Z,1336060465.514 [Default:Iridium:A.SetSpeed] Stopped
2012-05-03T15:54:25.514Z,1336060465.514 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T15:54:25.749Z,1336060465.749 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-03T15:54:25.749Z,1336060465.749 [Default:CallIridium:B] Stopped
2012-05-03T15:54:25.749Z,1336060465.749 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-03T15:54:25.750Z,1336060465.750 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-03T15:54:25.750Z,1336060465.750 [Default:CallIridium] Stopped
2012-05-03T15:54:25.750Z,1336060465.750 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-03T15:54:35.890Z,1336060475.890 [NAL9601](INFO): Powering down
2012-05-03T15:59:26.052Z,1336060766.052 [Default:CallIridium] Running Loop=1
2012-05-03T15:59:26.052Z,1336060766.052 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-03T15:59:26.052Z,1336060766.053 [Default:CallIridium:A] Running Loop=1
2012-05-03T15:59:26.053Z,1336060766.053 [Default:CallIridium:A] Stopped
2012-05-03T15:59:26.053Z,1336060766.053 [Default:CallIridium:B] Running Loop=1
2012-05-03T15:59:26.053Z,1336060766.053 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-03T15:59:31.058Z,1336060771.058 [Default:Iridium] Running Loop=1
2012-05-03T15:59:31.058Z,1336060771.058 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-03T15:59:31.058Z,1336060771.059 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T15:59:31.058Z,1336060771.059 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-03T15:59:31.059Z,1336060771.059 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-03T15:59:31.059Z,1336060771.059 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T15:59:31.060Z,1336060771.060 [Default:Iridium:B.GoToSurface] Stopped
2012-05-03T15:59:31.060Z,1336060771.060 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T15:59:31.060Z,1336060771.060 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-03T15:59:31.060Z,1336060771.060 [Default:GPS] Running Loop=1
2012-05-03T15:59:31.060Z,1336060771.060 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-03T15:59:31.060Z,1336060771.060 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T15:59:31.061Z,1336060771.061 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-03T15:59:31.061Z,1336060771.061 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-03T15:59:31.061Z,1336060771.061 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T15:59:31.062Z,1336060771.062 [Default:GPS:B.GoToSurface] Stopped
2012-05-03T15:59:31.062Z,1336060771.062 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T15:59:31.062Z,1336060771.062 [Default:GPS:Read_GPS] Running Loop=1
2012-05-03T15:59:31.580Z,1336060771.580 [NAL9601](INFO): Powering up
2012-05-03T16:00:37.303Z,1336060837.303 [NAL9601](INFO): NAL9601 initialized
2012-05-03T16:00:38.387Z,1336060838.387 [NAL9601](IMPORTANT): GPS fix at: 1336060832.00
2012-05-03T16:00:38.402Z,1336060838.402 [Default:GPS:Read_GPS] Stopped
2012-05-03T16:00:38.403Z,1336060838.402 [Default:GPS:D] Running Loop=1
2012-05-03T16:00:38.803Z,1336060838.803 [Default:GPS:D] Stopped
2012-05-03T16:00:38.803Z,1336060838.803 [Default:GPS](INFO): Completed Default:GPS
2012-05-03T16:00:38.803Z,1336060838.803 [Default:GPS] Stopped
2012-05-03T16:00:38.804Z,1336060838.804 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-03T16:00:38.804Z,1336060838.804 [Default:GPS:A.SetSpeed] Stopped
2012-05-03T16:00:38.804Z,1336060838.804 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T16:00:55.282Z,1336060855.282 [NAL9601](INFO): SBD MO Status=1, MOMSN=5845, MT Status=0, MTMSN=0
2012-05-03T16:00:55.463Z,1336060855.463 [NAL9601](INFO): Sent 233 bytes from file Logs/20120503T152308/shore0005.lzma
2012-05-03T16:00:55.463Z,1336060855.463 [NAL9601](INFO): Packets left to send: 0
2012-05-03T16:00:55.464Z,1336060855.464 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000009
2012-05-03T16:01:02.886Z,1336060862.885 [NAL9601](INFO): SBD MO Status=0, MOMSN=5846, MT Status=0, MTMSN=0
2012-05-03T16:01:03.075Z,1336060863.075 [Default:Iridium:Read_Iridium] Stopped
2012-05-03T16:01:03.075Z,1336060863.075 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-03T16:01:03.075Z,1336060863.075 [Default:Iridium] Stopped
2012-05-03T16:01:03.075Z,1336060863.075 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-03T16:01:03.075Z,1336060863.075 [Default:Iridium:A.SetSpeed] Stopped
2012-05-03T16:01:03.075Z,1336060863.075 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T16:01:03.299Z,1336060863.299 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-03T16:01:03.299Z,1336060863.299 [Default:CallIridium:B] Stopped
2012-05-03T16:01:03.299Z,1336060863.299 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-03T16:01:03.299Z,1336060863.299 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-03T16:01:03.299Z,1336060863.299 [Default:CallIridium] Stopped
2012-05-03T16:01:03.300Z,1336060863.300 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-03T16:01:13.417Z,1336060873.417 [NAL9601](INFO): Powering down
2012-05-03T16:06:03.463Z,1336061163.463 [Default:CallIridium] Running Loop=1
2012-05-03T16:06:03.463Z,1336061163.463 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-03T16:06:03.463Z,1336061163.463 [Default:CallIridium:A] Running Loop=1
2012-05-03T16:06:03.464Z,1336061163.464 [Default:CallIridium:A] Stopped
2012-05-03T16:06:03.464Z,1336061163.464 [Default:CallIridium:B] Running Loop=1
2012-05-03T16:06:03.464Z,1336061163.464 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-03T16:06:08.481Z,1336061168.480 [Default:Iridium] Running Loop=1
2012-05-03T16:06:08.481Z,1336061168.481 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-03T16:06:08.481Z,1336061168.481 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T16:06:08.481Z,1336061168.481 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-03T16:06:08.481Z,1336061168.481 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-03T16:06:08.481Z,1336061168.481 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T16:06:08.482Z,1336061168.482 [Default:Iridium:B.GoToSurface] Stopped
2012-05-03T16:06:08.482Z,1336061168.482 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T16:06:08.482Z,1336061168.482 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-03T16:06:08.483Z,1336061168.483 [Default:GPS] Running Loop=1
2012-05-03T16:06:08.483Z,1336061168.483 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-03T16:06:08.483Z,1336061168.483 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T16:06:08.483Z,1336061168.483 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-03T16:06:08.483Z,1336061168.483 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-03T16:06:08.483Z,1336061168.483 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T16:06:08.484Z,1336061168.484 [Default:GPS:B.GoToSurface] Stopped
2012-05-03T16:06:08.484Z,1336061168.484 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T16:06:08.484Z,1336061168.484 [Default:GPS:Read_GPS] Running Loop=1
2012-05-03T16:06:09.084Z,1336061169.084 [NAL9601](INFO): Powering up
2012-05-03T16:07:14.807Z,1336061234.807 [NAL9601](INFO): NAL9601 initialized
2012-05-03T16:07:15.882Z,1336061235.882 [NAL9601](IMPORTANT): GPS fix at: 1336061230.00
2012-05-03T16:07:15.897Z,1336061235.897 [Default:GPS:Read_GPS] Stopped
2012-05-03T16:07:15.898Z,1336061235.898 [Default:GPS:D] Running Loop=1
2012-05-03T16:07:16.314Z,1336061236.314 [Default:GPS:D] Stopped
2012-05-03T16:07:16.315Z,1336061236.315 [Default:GPS](INFO): Completed Default:GPS
2012-05-03T16:07:16.315Z,1336061236.315 [Default:GPS] Stopped
2012-05-03T16:07:16.315Z,1336061236.315 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-03T16:07:16.315Z,1336061236.315 [Default:GPS:A.SetSpeed] Stopped
2012-05-03T16:07:16.315Z,1336061236.315 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T16:07:38.597Z,1336061258.597 [NAL9601](INFO): SBD MO Status=1, MOMSN=5847, MT Status=0, MTMSN=0
2012-05-03T16:07:38.763Z,1336061258.763 [NAL9601](INFO): Sent 201 bytes from file Logs/20120503T152308/shore0006.lzma
2012-05-03T16:07:38.763Z,1336061258.763 [NAL9601](INFO): Packets left to send: 0
2012-05-03T16:07:38.765Z,1336061258.765 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000010
2012-05-03T16:07:44.998Z,1336061264.998 [NAL9601](INFO): SBD MO Status=0, MOMSN=5848, MT Status=0, MTMSN=0
2012-05-03T16:07:45.174Z,1336061265.174 [Default:Iridium:Read_Iridium] Stopped
2012-05-03T16:07:45.175Z,1336061265.175 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-03T16:07:45.175Z,1336061265.175 [Default:Iridium] Stopped
2012-05-03T16:07:45.175Z,1336061265.175 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-03T16:07:45.175Z,1336061265.175 [Default:Iridium:A.SetSpeed] Stopped
2012-05-03T16:07:45.175Z,1336061265.175 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T16:07:45.426Z,1336061265.426 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-03T16:07:45.426Z,1336061265.426 [Default:CallIridium:B] Stopped
2012-05-03T16:07:45.426Z,1336061265.427 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-03T16:07:45.427Z,1336061265.427 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-03T16:07:45.427Z,1336061265.427 [Default:CallIridium] Stopped
2012-05-03T16:07:45.427Z,1336061265.427 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-03T16:07:55.554Z,1336061275.554 [NAL9601](INFO): Powering down
2012-05-03T16:12:45.545Z,1336061565.545 [Default:CallIridium] Running Loop=1
2012-05-03T16:12:45.545Z,1336061565.545 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-03T16:12:45.545Z,1336061565.545 [Default:CallIridium:A] Running Loop=1
2012-05-03T16:12:45.545Z,1336061565.545 [Default:CallIridium:A] Stopped
2012-05-03T16:12:45.545Z,1336061565.546 [Default:CallIridium:B] Running Loop=1
2012-05-03T16:12:45.546Z,1336061565.546 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-03T16:12:50.577Z,1336061570.577 [Default:Iridium] Running Loop=1
2012-05-03T16:12:50.577Z,1336061570.577 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-03T16:12:50.577Z,1336061570.577 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T16:12:50.577Z,1336061570.577 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-03T16:12:50.577Z,1336061570.577 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-03T16:12:50.577Z,1336061570.577 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T16:12:50.578Z,1336061570.578 [Default:Iridium:B.GoToSurface] Stopped
2012-05-03T16:12:50.578Z,1336061570.579 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T16:12:50.579Z,1336061570.579 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-03T16:12:50.579Z,1336061570.579 [Default:GPS] Running Loop=1
2012-05-03T16:12:50.579Z,1336061570.579 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-03T16:12:50.579Z,1336061570.579 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T16:12:50.579Z,1336061570.579 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-03T16:12:50.579Z,1336061570.579 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-03T16:12:50.580Z,1336061570.579 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T16:12:50.580Z,1336061570.580 [Default:GPS:B.GoToSurface] Stopped
2012-05-03T16:12:50.581Z,1336061570.580 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T16:12:50.581Z,1336061570.581 [Default:GPS:Read_GPS] Running Loop=1
2012-05-03T16:12:51.196Z,1336061571.196 [NAL9601](INFO): Powering up
2012-05-03T16:13:56.919Z,1336061636.919 [NAL9601](INFO): NAL9601 initialized
2012-05-03T16:13:58.003Z,1336061638.003 [NAL9601](IMPORTANT): GPS fix at: 1336061632.00
2012-05-03T16:13:58.019Z,1336061638.019 [Default:GPS:Read_GPS] Stopped
2012-05-03T16:13:58.019Z,1336061638.019 [Default:GPS:D] Running Loop=1
2012-05-03T16:13:58.415Z,1336061638.415 [Default:GPS:D] Stopped
2012-05-03T16:13:58.416Z,1336061638.416 [Default:GPS](INFO): Completed Default:GPS
2012-05-03T16:13:58.416Z,1336061638.416 [Default:GPS] Stopped
2012-05-03T16:13:58.416Z,1336061638.416 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-03T16:13:58.416Z,1336061638.416 [Default:GPS:A.SetSpeed] Stopped
2012-05-03T16:13:58.416Z,1336061638.416 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T16:14:13.937Z,1336061653.937 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=5849, MT Status=1, MTMSN=2573
2012-05-03T16:14:14.083Z,1336061654.083 [NAL9601](INFO): Sent 175 bytes from file Logs/20120503T152308/shore0007.lzma
2012-05-03T16:14:14.083Z,1336061654.083 [NAL9601](INFO): Packets left to send: 0
2012-05-03T16:14:14.084Z,1336061654.084 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000011
2012-05-03T16:14:14.580Z,1336061654.580 [NAL9601](INFO): Received command:load Transport/transit_3km.xml;set transit_3km.Wpt1Lat 36.804 degree;set transit_3km.Wpt1Lon -121.835 degree;set transit_3km.TimeoutDuration 30 minute;run 
2012-05-03T16:14:14.596Z,1336061654.596 [CommandLine](IMPORTANT): got command load ./Missions/Transport/transit_3km.xml
2012-05-03T16:14:14.597Z,1336061654.597 [MissionManager](INFO): Loading Mission: ./Missions/Transport/transit_3km.xml
2012-05-03T16:14:14.635Z,1336061654.635 [MissionManager](INFO): DefineArg transit_3km.ApproachDepth = 10.000000 m
2012-05-03T16:14:14.638Z,1336061654.638 [MissionManager](INFO): DefineArg transit_3km.Wpt1Lat = 36.806966 arcdeg
2012-05-03T16:14:14.657Z,1336061654.657 [MissionManager](INFO): DefineArg transit_3km.Wpt1Lon = -121.824326 arcdeg
2012-05-03T16:14:14.664Z,1336061654.664 [MissionManager](INFO): DefineArg transit_3km.Speed = 1.000000 m/s
2012-05-03T16:14:14.671Z,1336061654.671 [MissionManager](INFO): DefineArg transit_3km.MaxDepth = 20.000000 m
2012-05-03T16:14:14.674Z,1336061654.674 [MissionManager](INFO): DefineArg transit_3km.TimeoutDuration = 240.000000 min
2012-05-03T16:14:14.680Z,1336061654.680 [transit_3km:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-05-03T16:14:14.692Z,1336061654.692 [transit_3km:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-05-03T16:14:14.704Z,1336061654.704 [transit_3km:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2012-05-03T16:14:14.712Z,1336061654.712 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-03T16:14:14.717Z,1336061654.717 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Construct.
2012-05-03T16:14:14.728Z,1336061654.728 [transit_3km:WaypointOne:A.Pitch](DEBUG): Construct.
2012-05-03T16:14:14.734Z,1336061654.734 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Construct.
2012-05-03T16:14:14.737Z,1336061654.737 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Construct Waypoint.
2012-05-03T16:14:14.746Z,1336061654.746 [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-03T16:14:14.747Z,1336061654.747 [CommandLine](IMPORTANT): Loaded ./Missions/Transport/transit_3km.xml
2012-05-03T16:14:14.847Z,1336061654.847 [CommandLine](IMPORTANT): got command set transit_3km.Wpt1Lat 36.804001 degree
2012-05-03T16:14:14.945Z,1336061654.945 [CommandLine](IMPORTANT): got command set transit_3km.Wpt1Lon -121.834999 degree
2012-05-03T16:14:15.142Z,1336061655.142 [CommandLine](IMPORTANT): got command set transit_3km.TimeoutDuration 30.000000 minute
2012-05-03T16:14:15.143Z,1336061655.143 [CommandLine](IMPORTANT): got command run 
2012-05-03T16:14:15.144Z,1336061655.144 [CommandLine](IMPORTANT): Running 
2012-05-03T16:14:15.200Z,1336061655.200 [Default] Stopped
2012-05-03T16:14:15.200Z,1336061655.200 [Default](INFO): Aggregate::uninitialize Default
2012-05-03T16:14:15.200Z,1336061655.200 [Default:Iridium] Stopped
2012-05-03T16:14:15.200Z,1336061655.200 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-03T16:14:15.200Z,1336061655.201 [Default:Iridium:A.SetSpeed] Stopped
2012-05-03T16:14:15.201Z,1336061655.201 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T16:14:15.201Z,1336061655.201 [Default:Iridium:Read_Iridium] Stopped
2012-05-03T16:14:15.201Z,1336061655.201 [Default:CallIridium] Stopped
2012-05-03T16:14:15.201Z,1336061655.201 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-03T16:14:15.201Z,1336061655.201 [Default:CallIridium:B] Stopped
2012-05-03T16:14:15.201Z,1336061655.201 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-03T16:14:15.201Z,1336061655.201 [Default:D.SetSpeed] Stopped
2012-05-03T16:14:15.201Z,1336061655.201 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-05-03T16:14:15.201Z,1336061655.201 [Default:E.GoToSurface] Stopped
2012-05-03T16:14:15.201Z,1336061655.201 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T16:14:15.201Z,1336061655.201 [Default:F.Wait] Stopped
2012-05-03T16:14:15.201Z,1336061655.201 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2012-05-03T16:14:15.202Z,1336061655.202 [MissionManager](IMPORTANT): Started mission transit_3km
2012-05-03T16:14:15.202Z,1336061655.202 [transit_3km] Running Loop=1
2012-05-03T16:14:15.202Z,1336061655.202 [transit_3km](INFO): Aggregate::initialize transit_3km
2012-05-03T16:14:15.202Z,1336061655.202 [transit_3km:A.AltitudeEnvelope] Running Loop=1
2012-05-03T16:14:15.202Z,1336061655.202 [transit_3km:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-05-03T16:14:15.202Z,1336061655.202 [transit_3km:B.DepthEnvelope] Running Loop=1
2012-05-03T16:14:15.202Z,1336061655.202 [transit_3km:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-05-03T16:14:15.203Z,1336061655.203 [transit_3km:C.OffshoreEnvelope] Running Loop=1
2012-05-03T16:14:15.204Z,1336061655.204 [transit_3km:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2012-05-03T16:14:15.204Z,1336061655.204 [transit_3km:SURFACECOMMS] Running Loop=1
2012-05-03T16:14:15.204Z,1336061655.204 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2012-05-03T16:14:15.204Z,1336061655.204 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-05-03T16:14:15.204Z,1336061655.204 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T16:14:15.230Z,1336061655.230 [transit_3km:SURFACECOMMS:B] Running Loop=1
2012-05-03T16:14:15.230Z,1336061655.230 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:B
2012-05-03T16:14:15.230Z,1336061655.230 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-05-03T16:14:15.231Z,1336061655.231 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-05-03T16:14:15.231Z,1336061655.231 [transit_3km:SURFACECOMMS:B:B] Running Loop=1
2012-05-03T16:14:15.231Z,1336061655.231 [transit_3km:C.OffshoreEnvelope] Running Loop=1
2012-05-03T16:14:15.236Z,1336061655.236 [transit_3km:B.DepthEnvelope] Running Loop=1
2012-05-03T16:14:15.241Z,1336061655.240 [transit_3km:A.AltitudeEnvelope] Running Loop=1
2012-05-03T16:14:15.746Z,1336061655.746 [transit_3km:SURFACECOMMS:B:B](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-05-03T16:14:15.748Z,1336061655.748 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-05-03T16:14:18.038Z,1336061658.038 [NAL9601](IMPORTANT): GPS fix at: 1336061652.00
2012-05-03T16:14:18.074Z,1336061658.074 [transit_3km:SURFACECOMMS:B:B] Stopped
2012-05-03T16:14:18.074Z,1336061658.074 [transit_3km:SURFACECOMMS:B:C] Running Loop=1
2012-05-03T16:14:18.424Z,1336061658.424 [transit_3km:SURFACECOMMS:B:C](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-05-03T16:14:33.900Z,1336061673.900 [NAL9601](INFO): SBD MO Status=0, MOMSN=5850, MT Status=0, MTMSN=0
2012-05-03T16:15:19.844Z,1336061719.844 [NAL9601](INFO): SBD MO Status=2, MOMSN=5851, MT Status=2, MTMSN=0
2012-05-03T16:15:19.844Z,1336061719.844 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-03T16:15:32.182Z,1336061732.181 [NAL9601](INFO): SBD MO Status=1, MOMSN=5851, MT Status=0, MTMSN=0
2012-05-03T16:15:32.359Z,1336061732.359 [NAL9601](INFO): Sent 332 bytes from file Logs/20120503T152308/shore0008.lzma
2012-05-03T16:15:32.359Z,1336061732.359 [NAL9601](INFO): Packets left to send: 1
2012-05-03T16:15:32.360Z,1336061732.360 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000012
2012-05-03T16:15:42.689Z,1336061742.690 [NAL9601](INFO): SBD MO Status=1, MOMSN=5852, MT Status=0, MTMSN=0
2012-05-03T16:15:42.843Z,1336061742.843 [NAL9601](INFO): Sent 113 bytes from file Logs/20120503T152308/shore0008.lzma
2012-05-03T16:15:42.843Z,1336061742.843 [NAL9601](INFO): Packets left to send: 0
2012-05-03T16:15:42.844Z,1336061742.844 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000013
2012-05-03T16:15:50.690Z,1336061750.690 [NAL9601](INFO): SBD MO Status=0, MOMSN=5853, MT Status=0, MTMSN=0
2012-05-03T16:15:50.845Z,1336061750.845 [transit_3km:SURFACECOMMS:B:C] Stopped
2012-05-03T16:15:50.845Z,1336061750.845 [transit_3km:SURFACECOMMS:B:D] Running Loop=1
2012-05-03T16:15:51.120Z,1336061751.120 [transit_3km:SURFACECOMMS:B:D](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-05-03T16:15:53.110Z,1336061753.110 [NAL9601](IMPORTANT): GPS fix at: 1336061748.00
2012-05-03T16:15:53.125Z,1336061753.125 [transit_3km:SURFACECOMMS:B:D] Stopped
2012-05-03T16:15:53.126Z,1336061753.126 [transit_3km:SURFACECOMMS:B](INFO): Completed transit_3km:SURFACECOMMS:B
2012-05-03T16:15:53.126Z,1336061753.126 [transit_3km:SURFACECOMMS:B] Stopped
2012-05-03T16:15:53.126Z,1336061753.126 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:B
2012-05-03T16:15:53.126Z,1336061753.126 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-05-03T16:15:53.126Z,1336061753.126 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T16:15:53.127Z,1336061753.127 [transit_3km:SURFACECOMMS](INFO): Completed transit_3km:SURFACECOMMS
2012-05-03T16:15:53.127Z,1336061753.127 [transit_3km:SURFACECOMMS] Stopped
2012-05-03T16:15:53.127Z,1336061753.127 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2012-05-03T16:15:53.127Z,1336061753.127 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2012-05-03T16:15:53.127Z,1336061753.127 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T16:15:53.127Z,1336061753.128 [transit_3km:WaypointOne] Running Loop=1
2012-05-03T16:15:53.128Z,1336061753.128 [transit_3km:WaypointOne](INFO): Aggregate::initialize transit_3km:WaypointOne
2012-05-03T16:15:53.128Z,1336061753.128 [transit_3km:WaypointOne:A.Pitch] Running Loop=1
2012-05-03T16:15:53.128Z,1336061753.128 [transit_3km:WaypointOne:A.Pitch](DEBUG): Initialize.
2012-05-03T16:15:53.128Z,1336061753.128 [transit_3km:WaypointOne:B.SetSpeed] Running Loop=1
2012-05-03T16:15:53.128Z,1336061753.128 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Initialize.
2012-05-03T16:15:53.128Z,1336061753.128 [transit_3km:WaypointOne:WaypointW1.Waypoint] Running Loop=1
2012-05-03T16:15:53.128Z,1336061753.128 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Initialize WaypointComponent.
2012-05-03T16:15:53.502Z,1336061753.502 [transit_3km:WaypointOne:B.SetSpeed] Running Loop=1
2012-05-03T16:15:53.507Z,1336061753.507 [transit_3km:WaypointOne:A.Pitch] Running Loop=1
2012-05-03T16:15:59.636Z,1336061759.636 [NAL9601](INFO): Powering down
2012-05-03T16:16:10.029Z,1336061770.029 [Radio_Freewave](INFO): Powering down
2012-05-03T16:31:26.707Z,1336062686.707 [transit_3km:WaypointOne:WaypointW1.Waypoint](INFO): Reached Waypoint: 36.804000,-121.835002
2012-05-03T16:31:26.708Z,1336062686.708 [transit_3km:WaypointOne:WaypointW1.Waypoint] Stopped
2012-05-03T16:31:26.708Z,1336062686.708 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Uninitialize WaypointComponent.
2012-05-03T16:31:26.708Z,1336062686.708 [transit_3km:WaypointOne:PHONEHOMEWPT1] Running Loop=1
2012-05-03T16:31:26.708Z,1336062686.708 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Aggregate::initialize transit_3km:WaypointOne:PHONEHOMEWPT1
2012-05-03T16:31:27.452Z,1336062687.452 [transit_3km:SURFACECOMMS] Running Loop=1
2012-05-03T16:31:27.452Z,1336062687.453 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2012-05-03T16:31:27.453Z,1336062687.453 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-05-03T16:31:27.453Z,1336062687.453 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T16:33:53.170Z,1336062833.171 [MassServo](FAULT): Overload Error
2012-05-03T16:33:53.171Z,1336062833.171 [MassServo] Hardware Fault, FailCount= 1
2012-05-03T16:33:53.171Z,1336062833.171 [MassServo](ERROR): Hardware Fault
2012-05-03T16:33:53.221Z,1336062833.221 [CBIT](ERROR): Hardware Fault in component: MassServo
2012-05-03T16:33:53.537Z,1336062833.537 [MassServo](DEBUG): Uninitialize Mass Servo.
2012-05-03T16:33:53.537Z,1336062833.537 [MassServo](INFO): Powering down
2012-05-03T16:33:53.564Z,1336062833.564 [CBIT](INFO): Clearing failed state for component MassServo
2012-05-03T16:33:53.564Z,1336062833.565 [MassServo] No Fault, FailCount= 1
2012-05-03T16:33:54.148Z,1336062834.148 [MassServo](DEBUG): Initializing EZServoServo.
2012-05-03T16:33:54.267Z,1336062834.267 [MassServo](DEBUG): Initializing MassServo.
2012-05-03T16:35:09.711Z,1336062909.711 [MassServo](FAULT): Overload Error
2012-05-03T16:35:09.711Z,1336062909.711 [MassServo] Hardware Fault, FailCount= 2
2012-05-03T16:35:09.711Z,1336062909.711 [MassServo](ERROR): Hardware Fault
2012-05-03T16:35:09.765Z,1336062909.765 [CBIT](ERROR): Hardware Fault in component: MassServo
2012-05-03T16:35:10.052Z,1336062910.052 [MassServo](DEBUG): Uninitialize Mass Servo.
2012-05-03T16:35:10.052Z,1336062910.052 [MassServo](INFO): Powering down
2012-05-03T16:35:10.077Z,1336062910.077 [CBIT](INFO): Clearing failed state for component MassServo
2012-05-03T16:35:10.077Z,1336062910.077 [MassServo] No Fault, FailCount= 2
2012-05-03T16:35:10.448Z,1336062910.448 [MassServo](DEBUG): Initializing EZServoServo.
2012-05-03T16:35:10.567Z,1336062910.567 [MassServo](DEBUG): Initializing MassServo.
2012-05-03T16:36:29.666Z,1336062989.667 [MassServo](FAULT): Overload Error
2012-05-03T16:36:29.667Z,1336062989.667 [MassServo] Hardware Fault, FailCount= 3
2012-05-03T16:36:29.667Z,1336062989.667 [MassServo](ERROR): Hardware Fault
2012-05-03T16:36:29.721Z,1336062989.721 [CBIT](ERROR): Hardware Fault in component: MassServo
2012-05-03T16:36:30.036Z,1336062990.036 [MassServo](DEBUG): Uninitialize Mass Servo.
2012-05-03T16:36:30.036Z,1336062990.036 [MassServo](INFO): Powering down
2012-05-03T16:36:30.061Z,1336062990.061 [CBIT](INFO): Clearing failed state for component MassServo
2012-05-03T16:36:30.061Z,1336062990.061 [MassServo] No Fault, FailCount= 3
2012-05-03T16:36:30.436Z,1336062990.436 [MassServo](DEBUG): Initializing EZServoServo.
2012-05-03T16:36:30.555Z,1336062990.555 [MassServo](DEBUG): Initializing MassServo.
2012-05-03T16:37:49.695Z,1336063069.695 [MassServo](FAULT): Overload Error
2012-05-03T16:37:49.695Z,1336063069.695 [MassServo] Hardware Fault, FailCount= 4
2012-05-03T16:37:49.695Z,1336063069.695 [MassServo](ERROR): Hardware Fault
2012-05-03T16:37:49.749Z,1336063069.749 [CBIT](ERROR): Hardware Fault in component: MassServo
2012-05-03T16:37:50.049Z,1336063070.049 [MassServo](DEBUG): Uninitialize Mass Servo.
2012-05-03T16:37:50.050Z,1336063070.050 [MassServo](INFO): Powering down
2012-05-03T16:37:50.076Z,1336063070.076 [CBIT](INFO): Clearing failed state for component MassServo
2012-05-03T16:37:50.076Z,1336063070.076 [MassServo] No Fault, FailCount= 4
2012-05-03T16:37:50.442Z,1336063070.442 [MassServo](DEBUG): Initializing EZServoServo.
2012-05-03T16:37:50.559Z,1336063070.559 [MassServo](DEBUG): Initializing MassServo.
2012-05-03T16:39:09.695Z,1336063149.695 [MassServo](FAULT): Overload Error
2012-05-03T16:39:09.695Z,1336063149.695 [MassServo] Hardware Fault, FailCount= 5
2012-05-03T16:39:09.695Z,1336063149.695 [MassServo](ERROR): Hardware Fault
2012-05-03T16:39:09.745Z,1336063149.745 [CBIT](ERROR): Hardware Fault in component: MassServo
2012-05-03T16:39:09.745Z,1336063149.745 [CBIT](CRITICAL): Hardware Fault in component: MassServo
2012-05-03T16:39:10.052Z,1336063150.052 [MassServo](DEBUG): Uninitialize Mass Servo.
2012-05-03T16:39:10.052Z,1336063150.052 [MassServo](INFO): Powering down
2012-05-03T16:39:10.485Z,1336063150.485 [transit_3km] Stopped
2012-05-03T16:39:10.485Z,1336063150.485 [transit_3km](INFO): Aggregate::uninitialize transit_3km
2012-05-03T16:39:10.485Z,1336063150.485 [transit_3km:A.AltitudeEnvelope] Stopped
2012-05-03T16:39:10.485Z,1336063150.485 [transit_3km:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-05-03T16:39:10.485Z,1336063150.485 [transit_3km:B.DepthEnvelope] Stopped
2012-05-03T16:39:10.485Z,1336063150.485 [transit_3km:B.DepthEnvelope](DEBUG): Uninitialize.
2012-05-03T16:39:10.485Z,1336063150.485 [transit_3km:C.OffshoreEnvelope] Stopped
2012-05-03T16:39:10.485Z,1336063150.485 [transit_3km:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2012-05-03T16:39:10.485Z,1336063150.485 [transit_3km:SURFACECOMMS] Stopped
2012-05-03T16:39:10.486Z,1336063150.486 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2012-05-03T16:39:10.486Z,1336063150.486 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2012-05-03T16:39:10.486Z,1336063150.486 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T16:39:10.486Z,1336063150.486 [transit_3km:WaypointOne] Stopped
2012-05-03T16:39:10.486Z,1336063150.486 [transit_3km:WaypointOne](INFO): Aggregate::uninitialize transit_3km:WaypointOne
2012-05-03T16:39:10.486Z,1336063150.486 [transit_3km:WaypointOne:A.Pitch] Stopped
2012-05-03T16:39:10.486Z,1336063150.486 [transit_3km:WaypointOne:B.SetSpeed] Stopped
2012-05-03T16:39:10.486Z,1336063150.486 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Uninitialize.
2012-05-03T16:39:10.486Z,1336063150.486 [transit_3km:WaypointOne:PHONEHOMEWPT1] Stopped
2012-05-03T16:39:10.491Z,1336063150.490 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Aggregate::uninitialize transit_3km:WaypointOne:PHONEHOMEWPT1
2012-05-03T16:39:10.838Z,1336063150.838 [MissionManager](IMPORTANT): Started mission Default
2012-05-03T16:39:10.838Z,1336063150.838 [Default] Running Loop=1
2012-05-03T16:39:10.839Z,1336063150.839 [Default](INFO): Aggregate::initialize Default
2012-05-03T16:39:10.839Z,1336063150.839 [Default:D.SetSpeed] Running Loop=1
2012-05-03T16:39:10.839Z,1336063150.839 [Default:D.SetSpeed](DEBUG): Initialize.
2012-05-03T16:39:10.839Z,1336063150.839 [Default:E.GoToSurface] Running Loop=1
2012-05-03T16:39:10.839Z,1336063150.839 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T16:39:10.839Z,1336063150.839 [Default:Iridium] Running Loop=1
2012-05-03T16:39:10.839Z,1336063150.839 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-03T16:39:10.840Z,1336063150.839 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T16:39:10.840Z,1336063150.840 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-03T16:39:10.840Z,1336063150.840 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-03T16:39:10.840Z,1336063150.840 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T16:39:10.841Z,1336063150.841 [Default:CallIridium] Running Loop=1
2012-05-03T16:39:10.841Z,1336063150.842 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-03T16:39:10.842Z,1336063150.842 [Default:CallIridium:A] Running Loop=1
2012-05-03T16:39:10.842Z,1336063150.842 [Default:CallIridium:A] Stopped
2012-05-03T16:39:10.842Z,1336063150.842 [Default:CallIridium:B] Running Loop=1
2012-05-03T16:39:10.842Z,1336063150.842 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-03T16:39:11.244Z,1336063151.244 [Default:GPS] Running Loop=1
2012-05-03T16:39:11.244Z,1336063151.244 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-03T16:39:11.244Z,1336063151.244 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T16:39:11.244Z,1336063151.244 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-03T16:39:11.244Z,1336063151.244 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-03T16:39:11.244Z,1336063151.244 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T16:39:13.273Z,1336063153.273 [VerticalControl](CRITICAL): Can not stop descending, stopping mission after 300.411285 seconds.
2012-05-03T16:42:23.238Z,1336063343.238 [Default:Iridium:B.GoToSurface] Stopped
2012-05-03T16:42:23.238Z,1336063343.238 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T16:42:23.238Z,1336063343.238 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-03T16:42:23.239Z,1336063343.239 [Default:GPS:B.GoToSurface] Stopped
2012-05-03T16:42:23.239Z,1336063343.239 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T16:42:23.240Z,1336063343.240 [Default:GPS:Read_GPS] Running Loop=1
2012-05-03T16:42:23.641Z,1336063343.641 [Radio_Freewave](INFO): Powering up
2012-05-03T16:42:24.046Z,1336063344.046 [NAL9601](INFO): Powering up
2012-05-03T16:43:29.671Z,1336063409.671 [NAL9601](INFO): NAL9601 initialized
2012-05-03T16:43:30.831Z,1336063410.831 [NAL9601](IMPORTANT): GPS fix at: 1336063408.00
2012-05-03T16:43:30.845Z,1336063410.845 [Navigation](IMPORTANT): Navigation Error 26.1 %DT

2012-05-03T16:43:30.847Z,1336063410.847 [Default:GPS:Read_GPS] Stopped
2012-05-03T16:43:30.847Z,1336063410.847 [Default:GPS:D] Running Loop=1
2012-05-03T16:43:31.238Z,1336063411.238 [Default:GPS:D] Stopped
2012-05-03T16:43:31.238Z,1336063411.238 [Default:GPS](INFO): Completed Default:GPS
2012-05-03T16:43:31.238Z,1336063411.238 [Default:GPS] Stopped
2012-05-03T16:43:31.238Z,1336063411.239 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-03T16:43:31.239Z,1336063411.239 [Default:GPS:A.SetSpeed] Stopped
2012-05-03T16:43:31.239Z,1336063411.239 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T16:43:47.944Z,1336063427.944 [NAL9601](INFO): SBD MO Status=1, MOMSN=5854, MT Status=0, MTMSN=0
2012-05-03T16:43:48.131Z,1336063428.131 [NAL9601](INFO): Sent 332 bytes from file Logs/20120503T152308/shore0009.lzma
2012-05-03T16:43:48.131Z,1336063428.131 [NAL9601](INFO): Packets left to send: 4
2012-05-03T16:43:48.307Z,1336063428.307 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000014
2012-05-03T16:44:00.513Z,1336063440.513 [NAL9601](INFO): SBD MO Status=1, MOMSN=5855, MT Status=0, MTMSN=0
2012-05-03T16:44:00.711Z,1336063440.711 [NAL9601](INFO): Sent 332 bytes from file Logs/20120503T152308/shore0009.lzma
2012-05-03T16:44:00.711Z,1336063440.711 [NAL9601](INFO): Packets left to send: 3
2012-05-03T16:44:00.712Z,1336063440.712 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000015
2012-05-03T16:44:09.861Z,1336063449.861 [CBIT](INFO): Clearing failed count for component MassServo
2012-05-03T16:44:09.861Z,1336063449.861 [MassServo] No Fault, FailCount= 5
2012-05-03T16:44:10.264Z,1336063450.264 [MassServo](DEBUG): Initializing EZServoServo.
2012-05-03T16:44:10.383Z,1336063450.383 [MassServo](DEBUG): Initializing MassServo.
2012-05-03T16:44:13.045Z,1336063453.045 [NAL9601](INFO): SBD MO Status=1, MOMSN=5856, MT Status=0, MTMSN=0
2012-05-03T16:44:13.191Z,1336063453.191 [NAL9601](INFO): Sent 332 bytes from file Logs/20120503T152308/shore0009.lzma
2012-05-03T16:44:13.191Z,1336063453.191 [NAL9601](INFO): Packets left to send: 2
2012-05-03T16:44:13.192Z,1336063453.192 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000016
2012-05-03T16:44:22.398Z,1336063462.398 [NAL9601](INFO): SBD MO Status=1, MOMSN=5857, MT Status=0, MTMSN=0
2012-05-03T16:44:22.579Z,1336063462.579 [NAL9601](INFO): Sent 332 bytes from file Logs/20120503T152308/shore0009.lzma
2012-05-03T16:44:22.579Z,1336063462.579 [NAL9601](INFO): Packets left to send: 1
2012-05-03T16:44:22.580Z,1336063462.580 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000017
2012-05-03T16:44:33.324Z,1336063473.324 [NAL9601](INFO): SBD MO Status=1, MOMSN=5858, MT Status=0, MTMSN=0
2012-05-03T16:44:33.459Z,1336063473.459 [NAL9601](INFO): Sent 151 bytes from file Logs/20120503T152308/shore0009.lzma
2012-05-03T16:44:33.459Z,1336063473.459 [NAL9601](INFO): Packets left to send: 0
2012-05-03T16:44:33.460Z,1336063473.460 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000018
2012-05-03T16:44:44.105Z,1336063484.105 [NAL9601](INFO): SBD MO Status=0, MOMSN=5859, MT Status=0, MTMSN=0
2012-05-03T16:44:44.257Z,1336063484.257 [Default:Iridium:Read_Iridium] Stopped
2012-05-03T16:44:44.257Z,1336063484.257 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-03T16:44:44.257Z,1336063484.257 [Default:Iridium] Stopped
2012-05-03T16:44:44.257Z,1336063484.257 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-03T16:44:44.257Z,1336063484.257 [Default:Iridium:A.SetSpeed] Stopped
2012-05-03T16:44:44.257Z,1336063484.257 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T16:44:44.258Z,1336063484.258 [Default:F.Wait] Running Loop=1
2012-05-03T16:44:44.258Z,1336063484.258 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-05-03T16:44:44.519Z,1336063484.519 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-03T16:44:44.519Z,1336063484.519 [Default:CallIridium:B] Stopped
2012-05-03T16:44:44.519Z,1336063484.519 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-03T16:44:44.520Z,1336063484.520 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-03T16:44:44.520Z,1336063484.520 [Default:CallIridium] Stopped
2012-05-03T16:44:44.520Z,1336063484.520 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-03T16:44:54.613Z,1336063494.613 [NAL9601](INFO): Powering down
2012-05-03T16:49:44.682Z,1336063784.682 [Default:CallIridium] Running Loop=1
2012-05-03T16:49:44.682Z,1336063784.682 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-03T16:49:44.682Z,1336063784.682 [Default:CallIridium:A] Running Loop=1
2012-05-03T16:49:44.683Z,1336063784.682 [Default:CallIridium:A] Stopped
2012-05-03T16:49:44.683Z,1336063784.683 [Default:CallIridium:B] Running Loop=1
2012-05-03T16:49:44.683Z,1336063784.683 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-03T16:49:49.609Z,1336063789.609 [Default:Iridium] Running Loop=1
2012-05-03T16:49:49.609Z,1336063789.609 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-03T16:49:49.609Z,1336063789.609 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T16:49:49.609Z,1336063789.609 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-03T16:49:49.610Z,1336063789.610 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-03T16:49:49.610Z,1336063789.610 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T16:49:49.611Z,1336063789.611 [Default:Iridium:B.GoToSurface] Stopped
2012-05-03T16:49:49.611Z,1336063789.611 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T16:49:49.611Z,1336063789.611 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-03T16:49:49.612Z,1336063789.612 [Default:GPS] Running Loop=1
2012-05-03T16:49:49.612Z,1336063789.612 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-03T16:49:49.612Z,1336063789.612 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T16:49:49.612Z,1336063789.612 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-03T16:49:49.612Z,1336063789.612 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-03T16:49:49.612Z,1336063789.612 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T16:49:49.613Z,1336063789.613 [Default:GPS:B.GoToSurface] Stopped
2012-05-03T16:49:49.613Z,1336063789.613 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T16:49:49.613Z,1336063789.613 [Default:GPS:Read_GPS] Running Loop=1
2012-05-03T16:49:50.323Z,1336063790.323 [NAL9601](INFO): Powering up
2012-05-03T16:50:56.047Z,1336063856.047 [NAL9601](INFO): NAL9601 initialized
2012-05-03T16:50:57.151Z,1336063857.151 [NAL9601](IMPORTANT): GPS fix at: 1336063855.00
2012-05-03T16:50:57.202Z,1336063857.202 [Default:GPS:Read_GPS] Stopped
2012-05-03T16:50:57.202Z,1336063857.202 [Default:GPS:D] Running Loop=1
2012-05-03T16:50:57.580Z,1336063857.580 [Default:GPS:D] Stopped
2012-05-03T16:50:57.580Z,1336063857.580 [Default:GPS](INFO): Completed Default:GPS
2012-05-03T16:50:57.580Z,1336063857.580 [Default:GPS] Stopped
2012-05-03T16:50:57.581Z,1336063857.580 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-03T16:50:57.581Z,1336063857.580 [Default:GPS:A.SetSpeed] Stopped
2012-05-03T16:50:57.581Z,1336063857.581 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T16:53:19.907Z,1336063999.907 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=5860, MT Status=1, MTMSN=2574
2012-05-03T16:53:20.111Z,1336064000.111 [NAL9601](INFO): Sent 216 bytes from file Logs/20120503T152308/shore0010.lzma
2012-05-03T16:53:20.111Z,1336064000.111 [NAL9601](INFO): Packets left to send: 0
2012-05-03T16:53:20.112Z,1336064000.112 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000019
2012-05-03T16:53:20.444Z,1336064000.444 [NAL9601](INFO): Received command:run Maintenance/ballast_and_trim.xml
2012-05-03T16:53:20.539Z,1336064000.539 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/ballast_and_trim.xml
2012-05-03T16:53:20.539Z,1336064000.539 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/ballast_and_trim.xml
2012-05-03T16:53:20.584Z,1336064000.584 [MissionManager](INFO): DefineArg ballast_and_trim.BallastDepth = 25.000000 m
2012-05-03T16:53:20.588Z,1336064000.588 [MissionManager](INFO): DefineArg ballast_and_trim.HoldDuration = 25.000000 min
2012-05-03T16:53:20.591Z,1336064000.591 [MissionManager](INFO): DefineArg ballast_and_trim.Speed = 1.000000 m/s
2012-05-03T16:53:20.594Z,1336064000.593 [MissionManager](INFO): DefineArg ballast_and_trim.DepthDeadband = 4.000000 m
2012-05-03T16:53:20.597Z,1336064000.597 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyPeriod = 5.000000 s
2012-05-03T16:53:20.600Z,1336064000.600 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyancyDefault = 0.000945 n/a
2012-05-03T16:53:20.607Z,1336064000.607 [ballast_and_trim:D.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-05-03T16:53:20.615Z,1336064000.615 [ballast_and_trim:E.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-05-03T16:53:20.624Z,1336064000.624 [ballast_and_trim:F.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2012-05-03T16:53:20.631Z,1336064000.631 [MissionManager](INFO): Inserting Stack: Missions/Insert/Surface.xml
2012-05-03T16:53:20.669Z,1336064000.670 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfaceDepthRate = nan m/s
2012-05-03T16:53:20.674Z,1336064000.674 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfacePitch = nan arcdeg
2012-05-03T16:53:20.680Z,1336064000.680 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfaceSpeed = 0.500000 m/s
2012-05-03T16:53:20.696Z,1336064000.696 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.IridiumTimeout = 30.000000 min
2012-05-03T16:53:20.697Z,1336064000.697 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-03T16:53:20.724Z,1336064000.724 [ballast_and_trim:H.SetSpeed](DEBUG): Construct.
2012-05-03T16:53:20.729Z,1336064000.729 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Construct.
2012-05-03T16:53:20.733Z,1336064000.733 [ballast_and_trim:ballast:C.Pitch](DEBUG): Construct.
2012-05-03T16:53:20.747Z,1336064000.747 [ballast_and_trim:ballast:D.Wait](DEBUG): Construct Wait.
2012-05-03T16:53:20.754Z,1336064000.754 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Construct Wait.
2012-05-03T16:53:20.770Z,1336064000.770 [ballast_and_trim:ballast:Float_Up:A.SetSpeed](DEBUG): Construct.
2012-05-03T16:53:20.785Z,1336064000.785 [ballast_and_trim:ballast:Float_Up:B.Buoyancy](DEBUG): Construct Buoyancy.
2012-05-03T16:53:20.789Z,1336064000.789 [ballast_and_trim:ballast:Float_Up:C.Wait](DEBUG): Construct Wait.
2012-05-03T16:53:20.808Z,1336064000.808 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Trigger="Tethys/Trigger" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Trigger http://aosn.mbari.org/tethys/Xml/Trigger.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="ballast_and_trim">

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

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

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

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

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

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

    <DefineArg Name="BuoyancyDefault"><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/>
            </Syslog>

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

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

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

        </Aggregate>

        <Aggregate Id="Float_Up">

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

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

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

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

        </Aggregate>

    </Aggregate>

</Mission>


2012-05-03T16:53:20.808Z,1336064000.808 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/ballast_and_trim.xml
2012-05-03T16:53:21.100Z,1336064001.100 [Default] Stopped
2012-05-03T16:53:21.100Z,1336064001.100 [Default](INFO): Aggregate::uninitialize Default
2012-05-03T16:53:21.100Z,1336064001.100 [Default:Iridium] Stopped
2012-05-03T16:53:21.100Z,1336064001.100 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-03T16:53:21.100Z,1336064001.100 [Default:Iridium:A.SetSpeed] Stopped
2012-05-03T16:53:21.100Z,1336064001.100 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T16:53:21.100Z,1336064001.100 [Default:Iridium:Read_Iridium] Stopped
2012-05-03T16:53:21.101Z,1336064001.101 [Default:CallIridium] Stopped
2012-05-03T16:53:21.101Z,1336064001.101 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-03T16:53:21.101Z,1336064001.101 [Default:CallIridium:B] Stopped
2012-05-03T16:53:21.101Z,1336064001.101 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-03T16:53:21.101Z,1336064001.101 [Default:D.SetSpeed] Stopped
2012-05-03T16:53:21.101Z,1336064001.101 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-05-03T16:53:21.101Z,1336064001.101 [Default:E.GoToSurface] Stopped
2012-05-03T16:53:21.101Z,1336064001.101 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T16:53:21.101Z,1336064001.101 [Default:F.Wait] Stopped
2012-05-03T16:53:21.101Z,1336064001.101 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2012-05-03T16:53:21.101Z,1336064001.101 [MissionManager](IMPORTANT): Started mission ballast_and_trim
2012-05-03T16:53:21.101Z,1336064001.102 [ballast_and_trim] Running Loop=1
2012-05-03T16:53:21.102Z,1336064001.102 [ballast_and_trim](INFO): Aggregate::initialize ballast_and_trim
2012-05-03T16:53:21.102Z,1336064001.102 [ballast_and_trim:A] Running Loop=1
2012-05-03T16:53:21.102Z,1336064001.102 [ballast_and_trim:B] Running Loop=1
2012-05-03T16:53:21.102Z,1336064001.102 [ballast_and_trim:C] Running Loop=1
2012-05-03T16:53:21.102Z,1336064001.102 [ballast_and_trim:D.AltitudeEnvelope] Running Loop=1
2012-05-03T16:53:21.102Z,1336064001.102 [ballast_and_trim:D.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-05-03T16:53:21.102Z,1336064001.102 [ballast_and_trim:E.DepthEnvelope] Running Loop=1
2012-05-03T16:53:21.102Z,1336064001.102 [ballast_and_trim:E.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-05-03T16:53:21.103Z,1336064001.103 [ballast_and_trim:F.OffshoreEnvelope] Running Loop=1
2012-05-03T16:53:21.103Z,1336064001.103 [ballast_and_trim:F.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2012-05-03T16:53:21.103Z,1336064001.103 [ballast_and_trim:H.SetSpeed] Running Loop=1
2012-05-03T16:53:21.103Z,1336064001.103 [ballast_and_trim:H.SetSpeed](DEBUG): Initialize.
2012-05-03T16:53:21.104Z,1336064001.104 [ballast_and_trim:SurfaceComms] Running Loop=1
2012-05-03T16:53:21.104Z,1336064001.104 [ballast_and_trim:SurfaceComms](INFO): Aggregate::initialize ballast_and_trim:SurfaceComms
2012-05-03T16:53:21.104Z,1336064001.104 [ballast_and_trim:SurfaceComms:A.GoToSurface] Running Loop=1
2012-05-03T16:53:21.104Z,1336064001.104 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T16:53:21.105Z,1336064001.105 [ballast_and_trim:H.SetSpeed] Running Loop=1
2012-05-03T16:53:21.118Z,1336064001.118 [ballast_and_trim:SurfaceComms:B] Running Loop=1
2012-05-03T16:53:21.118Z,1336064001.118 [ballast_and_trim:SurfaceComms:B](INFO): Aggregate::initialize ballast_and_trim:SurfaceComms:B
2012-05-03T16:53:21.118Z,1336064001.118 [ballast_and_trim:SurfaceComms:B:A] Running Loop=1
2012-05-03T16:53:21.118Z,1336064001.118 [ballast_and_trim:F.OffshoreEnvelope] Running Loop=1
2012-05-03T16:53:21.127Z,1336064001.127 [ballast_and_trim:E.DepthEnvelope] Running Loop=1
2012-05-03T16:53:21.132Z,1336064001.132 [ballast_and_trim:D.AltitudeEnvelope] Running Loop=1
2012-05-03T16:53:21.137Z,1336064001.137 [ballast_and_trim:C] Running Loop=1
2012-05-03T16:53:21.138Z,1336064001.138 [ballast_and_trim:B] Running Loop=1
2012-05-03T16:53:21.140Z,1336064001.140 [ballast_and_trim:A] Running Loop=1
2012-05-03T16:53:26.272Z,1336064006.272 [ballast_and_trim:H.SetSpeed] Preempted
2012-05-03T16:53:26.273Z,1336064006.273 [ballast_and_trim:SurfaceComms:B:A](DEBUG): Initialize ReadDataComponent to sense time_fix
2012-05-03T16:53:31.085Z,1336064011.085 [Radio_Freewave](INFO): Powering down
2012-05-03T16:53:38.916Z,1336064018.916 [NAL9601](INFO): SBD MO Status=0, MOMSN=5861, MT Status=0, MTMSN=0
2012-05-03T16:53:40.658Z,1336064020.658 [NAL9601](IMPORTANT): GPS fix at: 1336064019.00
2012-05-03T16:53:40.673Z,1336064020.672 [ballast_and_trim:SurfaceComms:B:A] Stopped
2012-05-03T16:53:40.673Z,1336064020.673 [ballast_and_trim:SurfaceComms:B:B] Running Loop=1
2012-05-03T16:53:41.083Z,1336064021.083 [ballast_and_trim:SurfaceComms:B:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-05-03T16:53:52.544Z,1336064032.544 [NAL9601](INFO): SBD MO Status=1, MOMSN=5862, MT Status=0, MTMSN=0
2012-05-03T16:53:52.759Z,1336064032.759 [NAL9601](INFO): Sent 317 bytes from file Logs/20120503T152308/shore0011.lzma
2012-05-03T16:53:52.759Z,1336064032.759 [NAL9601](INFO): Packets left to send: 0
2012-05-03T16:53:52.981Z,1336064032.981 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000020
2012-05-03T16:54:03.118Z,1336064043.118 [NAL9601](INFO): SBD MO Status=0, MOMSN=5863, MT Status=0, MTMSN=0
2012-05-03T16:54:03.262Z,1336064043.263 [ballast_and_trim:SurfaceComms:B:B] Stopped
2012-05-03T16:54:03.263Z,1336064043.263 [ballast_and_trim:SurfaceComms:B:C] Running Loop=1
2012-05-03T16:54:03.527Z,1336064043.527 [ballast_and_trim:SurfaceComms:B:C](DEBUG): Initialize ReadDataComponent to sense time_fix
2012-05-03T16:54:05.539Z,1336064045.539 [NAL9601](IMPORTANT): GPS fix at: 1336064044.00
2012-05-03T16:54:05.553Z,1336064045.553 [ballast_and_trim:SurfaceComms:B:C] Stopped
2012-05-03T16:54:05.553Z,1336064045.553 [ballast_and_trim:SurfaceComms:B](INFO): Completed ballast_and_trim:SurfaceComms:B
2012-05-03T16:54:05.553Z,1336064045.553 [ballast_and_trim:SurfaceComms:B] Stopped
2012-05-03T16:54:05.554Z,1336064045.554 [ballast_and_trim:SurfaceComms:B](INFO): Aggregate::uninitialize ballast_and_trim:SurfaceComms:B
2012-05-03T16:54:05.555Z,1336064045.555 [ballast_and_trim:SurfaceComms](INFO): Completed ballast_and_trim:SurfaceComms
2012-05-03T16:54:05.555Z,1336064045.555 [ballast_and_trim:SurfaceComms] Stopped
2012-05-03T16:54:05.555Z,1336064045.555 [ballast_and_trim:SurfaceComms](INFO): Aggregate::uninitialize ballast_and_trim:SurfaceComms
2012-05-03T16:54:05.555Z,1336064045.555 [ballast_and_trim:SurfaceComms:A.GoToSurface] Stopped
2012-05-03T16:54:05.555Z,1336064045.555 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T16:54:05.555Z,1336064045.555 [ballast_and_trim:ballast] Running Loop=1
2012-05-03T16:54:05.555Z,1336064045.555 [ballast_and_trim:ballast](INFO): Aggregate::initialize ballast_and_trim:ballast
2012-05-03T16:54:05.555Z,1336064045.555 [ballast_and_trim:ballast:A.SetSpeed] Running Loop=1
2012-05-03T16:54:05.555Z,1336064045.556 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Initialize.
2012-05-03T16:54:05.556Z,1336064045.556 [ballast_and_trim:ballast:B] Running Loop=1
2012-05-03T16:54:05.556Z,1336064045.556 [ballast_and_trim:ballast:C.Pitch] Running Loop=1
2012-05-03T16:54:05.556Z,1336064045.556 [ballast_and_trim:ballast:C.Pitch](DEBUG): Initialize.
2012-05-03T16:54:05.556Z,1336064045.556 [ballast_and_trim:ballast:D.Wait] Running Loop=1
2012-05-03T16:54:05.556Z,1336064045.556 [ballast_and_trim:ballast:D.Wait](DEBUG): Initialize Wait Component.
2012-05-03T16:54:05.946Z,1336064045.946 [ballast_and_trim:ballast:C.Pitch] Running Loop=1
2012-05-03T16:54:05.951Z,1336064045.951 [ballast_and_trim:ballast:B] Running Loop=1
2012-05-03T16:54:05.953Z,1336064045.953 [ballast_and_trim:ballast:A.SetSpeed] Running Loop=1
2012-05-03T16:54:06.728Z,1336064046.727 [ballast_and_trim:H.SetSpeed] Running Loop=1
2012-05-03T16:54:16.876Z,1336064056.876 [NAL9601](INFO): Powering down
2012-05-03T16:58:46.869Z,1336064326.869 [Radio_Freewave](INFO): Powering up
2012-05-03T17:15:56.850Z,1336065356.850 [Radio_Freewave](INFO): Powering down
2012-05-03T17:17:11.902Z,1336065431.902 [Radio_Freewave](INFO): Powering up
2012-05-03T17:17:21.909Z,1336065441.909 [Radio_Freewave](INFO): Powering down
2012-05-03T17:18:06.899Z,1336065486.899 [Radio_Freewave](INFO): Powering up
2012-05-03T17:18:16.941Z,1336065496.941 [Radio_Freewave](INFO): Powering down
2012-05-03T17:18:46.909Z,1336065526.909 [Radio_Freewave](INFO): Powering up
2012-05-03T17:19:06.889Z,1336065546.889 [ballast_and_trim:ballast:D.Wait](INFO): Done Waiting.
2012-05-03T17:19:06.890Z,1336065546.890 [ballast_and_trim:ballast:D.Wait] Stopped
2012-05-03T17:19:06.890Z,1336065546.890 [ballast_and_trim:ballast:D.Wait](DEBUG): Uninitialize Wait Component.
2012-05-03T17:19:06.890Z,1336065546.890 [ballast_and_trim:ballast:ReportPositions] Running Loop=1
2012-05-03T17:19:06.890Z,1336065546.890 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-05-03T17:19:06.890Z,1336065546.890 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-05-03T17:19:11.946Z,1336065551.946 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 94.805720 cc 
2012-05-03T17:19:11.951Z,1336065551.951 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-05-03T17:19:11.952Z,1336065551.952 [ballast_and_trim:ballast:ReportPositions:B] Running Loop=1
2012-05-03T17:19:16.877Z,1336065556.878 [ballast_and_trim:ballast:ReportPositions:B](IMPORTANT): Mass: 0.295107 cm 
2012-05-03T17:19:16.879Z,1336065556.879 [ballast_and_trim:ballast:ReportPositions:B] Stopped
2012-05-03T17:19:16.879Z,1336065556.879 [ballast_and_trim:ballast:ReportPositions:C] Running Loop=1
2012-05-03T17:19:21.903Z,1336065561.903 [ballast_and_trim:ballast:ReportPositions:C](IMPORTANT): Pitch: -1.123730 arcdeg 
2012-05-03T17:19:21.905Z,1336065561.905 [ballast_and_trim:ballast:ReportPositions:C] Stopped
2012-05-03T17:19:21.905Z,1336065561.905 [ballast_and_trim:ballast:ReportPositions:D.Wait] Running Loop=1
2012-05-03T17:19:21.905Z,1336065561.905 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Initialize Wait Component.
2012-05-03T17:19:31.900Z,1336065571.900 [Radio_Freewave](INFO): Powering down
2012-05-03T17:20:21.936Z,1336065621.936 [ballast_and_trim:ballast:ReportPositions:D.Wait](INFO): Timed out from 2012-05-03T17:19:21.9Z
2012-05-03T17:20:21.936Z,1336065621.936 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-05-03T17:20:21.936Z,1336065621.936 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-03T17:20:21.936Z,1336065621.936 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-03T17:20:21.937Z,1336065621.937 [ballast_and_trim:ballast:ReportPositions:D.Wait] Stopped
2012-05-03T17:20:21.937Z,1336065621.937 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Uninitialize Wait Component.
2012-05-03T17:20:21.937Z,1336065621.937 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-05-03T17:20:21.937Z,1336065621.937 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-05-03T17:20:21.937Z,1336065621.937 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-05-03T17:20:21.937Z,1336065621.937 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #2
2012-05-03T17:20:21.937Z,1336065621.937 [ballast_and_trim:ballast:ReportPositions] Running Loop=2
2012-05-03T17:20:21.937Z,1336065621.937 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-05-03T17:20:21.937Z,1336065621.937 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-05-03T17:20:26.917Z,1336065626.917 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 105.549705 cc 
2012-05-03T17:20:26.917Z,1336065626.917 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-05-03T17:20:26.917Z,1336065626.917 [ballast_and_trim:ballast:ReportPositions:B] Running Loop=1
2012-05-03T17:20:31.883Z,1336065631.884 [ballast_and_trim:ballast:ReportPositions:B](IMPORTANT): Mass: 0.088974 cm 
2012-05-03T17:20:31.884Z,1336065631.884 [ballast_and_trim:ballast:ReportPositions:B] Stopped
2012-05-03T17:20:31.884Z,1336065631.884 [ballast_and_trim:ballast:ReportPositions:C] Running Loop=1
2012-05-03T17:20:36.953Z,1336065636.953 [ballast_and_trim:ballast:ReportPositions:C](IMPORTANT): Pitch: 2.831348 arcdeg 
2012-05-03T17:20:36.953Z,1336065636.953 [ballast_and_trim:ballast:ReportPositions:C] Stopped
2012-05-03T17:20:36.954Z,1336065636.954 [ballast_and_trim:ballast:ReportPositions:D.Wait] Running Loop=1
2012-05-03T17:20:36.954Z,1336065636.954 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Initialize Wait Component.
2012-05-03T17:21:41.994Z,1336065701.994 [ballast_and_trim:ballast:ReportPositions:D.Wait](INFO): Timed out from 2012-05-03T17:20:36.0Z
2012-05-03T17:21:41.994Z,1336065701.994 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-05-03T17:21:41.994Z,1336065701.994 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-03T17:21:41.995Z,1336065701.995 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-03T17:21:41.995Z,1336065701.995 [ballast_and_trim:ballast:ReportPositions:D.Wait] Stopped
2012-05-03T17:21:41.995Z,1336065701.995 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Uninitialize Wait Component.
2012-05-03T17:21:41.995Z,1336065701.995 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-05-03T17:21:41.995Z,1336065701.995 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-05-03T17:21:41.995Z,1336065701.995 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-05-03T17:21:41.995Z,1336065701.995 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #3
2012-05-03T17:21:41.995Z,1336065701.995 [ballast_and_trim:ballast:ReportPositions] Running Loop=3
2012-05-03T17:21:41.996Z,1336065701.996 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-05-03T17:21:41.996Z,1336065701.996 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-05-03T17:21:46.879Z,1336065706.879 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 84.464606 cc 
2012-05-03T17:21:46.879Z,1336065706.879 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-05-03T17:21:46.879Z,1336065706.879 [ballast_and_trim:ballast:ReportPositions:B] Running Loop=1
2012-05-03T17:21:51.913Z,1336065711.913 [ballast_and_trim:ballast:ReportPositions:B](IMPORTANT): Mass: -0.110954 cm 
2012-05-03T17:21:51.913Z,1336065711.913 [ballast_and_trim:ballast:ReportPositions:B] Stopped
2012-05-03T17:21:51.913Z,1336065711.913 [ballast_and_trim:ballast:ReportPositions:C] Running Loop=1
2012-05-03T17:21:56.876Z,1336065716.876 [ballast_and_trim:ballast:ReportPositions:C](IMPORTANT): Pitch: 4.984668 arcdeg 
2012-05-03T17:21:56.876Z,1336065716.876 [ballast_and_trim:ballast:ReportPositions:C] Stopped
2012-05-03T17:21:56.877Z,1336065716.877 [ballast_and_trim:ballast:ReportPositions:D.Wait] Running Loop=1
2012-05-03T17:21:56.877Z,1336065716.877 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Initialize Wait Component.
2012-05-03T17:22:57.030Z,1336065777.030 [ballast_and_trim:ballast:ReportPositions:D.Wait](INFO): Timed out from 2012-05-03T17:21:56.9Z
2012-05-03T17:22:57.030Z,1336065777.030 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-05-03T17:22:57.031Z,1336065777.031 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-03T17:22:57.031Z,1336065777.031 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-03T17:22:57.031Z,1336065777.031 [ballast_and_trim:ballast:ReportPositions:D.Wait] Stopped
2012-05-03T17:22:57.031Z,1336065777.031 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Uninitialize Wait Component.
2012-05-03T17:22:57.031Z,1336065777.031 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-05-03T17:22:57.031Z,1336065777.031 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-05-03T17:22:57.031Z,1336065777.031 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-05-03T17:22:57.032Z,1336065777.032 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #4
2012-05-03T17:22:57.032Z,1336065777.032 [ballast_and_trim:ballast:ReportPositions] Running Loop=4
2012-05-03T17:22:57.032Z,1336065777.032 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-05-03T17:22:57.032Z,1336065777.032 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-05-03T17:23:01.898Z,1336065781.898 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 84.464606 cc 
2012-05-03T17:23:01.898Z,1336065781.898 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-05-03T17:23:01.898Z,1336065781.898 [ballast_and_trim:ballast:ReportPositions:B] Running Loop=1
2012-05-03T17:23:06.881Z,1336065786.881 [ballast_and_trim:ballast:ReportPositions:B](IMPORTANT): Mass: 0.198184 cm 
2012-05-03T17:23:06.881Z,1336065786.881 [ballast_and_trim:ballast:ReportPositions:B] Stopped
2012-05-03T17:23:06.881Z,1336065786.881 [ballast_and_trim:ballast:ReportPositions:C] Running Loop=1
2012-05-03T17:23:11.924Z,1336065791.924 [ballast_and_trim:ballast:ReportPositions:C](IMPORTANT): Pitch: 1.007617 arcdeg 
2012-05-03T17:23:11.924Z,1336065791.924 [ballast_and_trim:ballast:ReportPositions:C] Stopped
2012-05-03T17:23:11.924Z,1336065791.924 [ballast_and_trim:ballast:ReportPositions:D.Wait] Running Loop=1
2012-05-03T17:23:11.924Z,1336065791.924 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Initialize Wait Component.
2012-05-03T17:24:16.859Z,1336065856.859 [ballast_and_trim:ballast:ReportPositions:D.Wait](INFO): Timed out from 2012-05-03T17:23:11.9Z
2012-05-03T17:24:16.859Z,1336065856.859 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-05-03T17:24:16.859Z,1336065856.859 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-03T17:24:16.860Z,1336065856.860 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-03T17:24:16.860Z,1336065856.860 [ballast_and_trim:ballast:ReportPositions:D.Wait] Stopped
2012-05-03T17:24:16.860Z,1336065856.860 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Uninitialize Wait Component.
2012-05-03T17:24:16.860Z,1336065856.860 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-05-03T17:24:16.860Z,1336065856.860 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-05-03T17:24:16.860Z,1336065856.860 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-05-03T17:24:16.860Z,1336065856.860 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #5
2012-05-03T17:24:16.860Z,1336065856.861 [ballast_and_trim:ballast:ReportPositions] Running Loop=5
2012-05-03T17:24:16.861Z,1336065856.861 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2012-05-03T17:24:16.861Z,1336065856.861 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2012-05-03T17:24:22.181Z,1336065862.181 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 84.464606 cc 
2012-05-03T17:24:22.181Z,1336065862.181 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2012-05-03T17:24:22.182Z,1336065862.181 [ballast_and_trim:ballast:ReportPositions:B] Running Loop=1
2012-05-03T17:24:26.855Z,1336065866.855 [ballast_and_trim:ballast:ReportPositions:B](IMPORTANT): Mass: 0.149804 cm 
2012-05-03T17:24:26.855Z,1336065866.855 [ballast_and_trim:ballast:ReportPositions:B] Stopped
2012-05-03T17:24:26.856Z,1336065866.856 [ballast_and_trim:ballast:ReportPositions:C] Running Loop=1
2012-05-03T17:24:31.925Z,1336065871.925 [ballast_and_trim:ballast:ReportPositions:C](IMPORTANT): Pitch: -2.508008 arcdeg 
2012-05-03T17:24:31.925Z,1336065871.925 [ballast_and_trim:ballast:ReportPositions:C] Stopped
2012-05-03T17:24:31.926Z,1336065871.926 [ballast_and_trim:ballast:ReportPositions:D.Wait] Running Loop=1
2012-05-03T17:24:31.926Z,1336065871.926 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Initialize Wait Component.
2012-05-03T17:25:31.917Z,1336065931.917 [Radio_Freewave](INFO): Powering up
2012-05-03T17:25:31.927Z,1336065931.927 [ballast_and_trim:ballast:ReportPositions:D.Wait](INFO): Timed out from 2012-05-03T17:24:31.9Z
2012-05-03T17:25:31.927Z,1336065931.927 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2012-05-03T17:25:31.927Z,1336065931.927 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-03T17:25:31.927Z,1336065931.927 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2012-05-03T17:25:31.927Z,1336065931.927 [ballast_and_trim:ballast:ReportPositions:D.Wait] Stopped
2012-05-03T17:25:31.927Z,1336065931.927 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Uninitialize Wait Component.
2012-05-03T17:25:31.928Z,1336065931.928 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2012-05-03T17:25:31.928Z,1336065931.928 [ballast_and_trim:ballast:ReportPositions] Stopped
2012-05-03T17:25:31.928Z,1336065931.928 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2012-05-03T17:25:31.928Z,1336065931.928 [ballast_and_trim:ballast:Float_Up] Running Loop=1
2012-05-03T17:25:31.928Z,1336065931.928 [ballast_and_trim:ballast:Float_Up](INFO): Aggregate::initialize ballast_and_trim:ballast:Float_Up
2012-05-03T17:25:31.928Z,1336065931.928 [ballast_and_trim:ballast:Float_Up:A.SetSpeed] Running Loop=1
2012-05-03T17:25:31.928Z,1336065931.928 [ballast_and_trim:ballast:Float_Up:A.SetSpeed](DEBUG): Initialize.
2012-05-03T17:25:31.928Z,1336065931.928 [ballast_and_trim:ballast:Float_Up:B.Buoyancy] Running Loop=1
2012-05-03T17:25:31.928Z,1336065931.928 [ballast_and_trim:ballast:Float_Up:B.Buoyancy](DEBUG): Initialize Buoyancy Component.
2012-05-03T17:25:31.929Z,1336065931.929 [ballast_and_trim:ballast:Float_Up:C.Wait] Running Loop=1
2012-05-03T17:25:31.929Z,1336065931.929 [ballast_and_trim:ballast:Float_Up:C.Wait](DEBUG): Initialize Wait Component.
2012-05-03T17:25:36.876Z,1336065936.876 [ballast_and_trim:ballast:Float_Up] Stopped
2012-05-03T17:25:36.876Z,1336065936.876 [ballast_and_trim:ballast:Float_Up](INFO): Aggregate::uninitialize ballast_and_trim:ballast:Float_Up
2012-05-03T17:25:36.877Z,1336065936.876 [ballast_and_trim:ballast:Float_Up:A.SetSpeed] Stopped
2012-05-03T17:25:36.877Z,1336065936.876 [ballast_and_trim:ballast:Float_Up:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T17:25:36.877Z,1336065936.877 [ballast_and_trim:ballast:Float_Up:B.Buoyancy] Stopped
2012-05-03T17:25:36.877Z,1336065936.877 [ballast_and_trim:ballast:Float_Up:B.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2012-05-03T17:25:36.877Z,1336065936.877 [ballast_and_trim:ballast:Float_Up:C.Wait] Stopped
2012-05-03T17:25:36.877Z,1336065936.877 [ballast_and_trim:ballast:Float_Up:C.Wait](DEBUG): Uninitialize Wait Component.
2012-05-03T17:25:36.878Z,1336065936.878 [ballast_and_trim:ballast](INFO): Completed ballast_and_trim:ballast
2012-05-03T17:25:36.878Z,1336065936.878 [ballast_and_trim:ballast] Stopped
2012-05-03T17:25:36.878Z,1336065936.878 [ballast_and_trim:ballast](INFO): Aggregate::uninitialize ballast_and_trim:ballast
2012-05-03T17:25:36.878Z,1336065936.878 [ballast_and_trim:ballast:A.SetSpeed] Stopped
2012-05-03T17:25:36.878Z,1336065936.878 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T17:25:36.878Z,1336065936.878 [ballast_and_trim:ballast:B] Stopped
2012-05-03T17:25:36.878Z,1336065936.878 [ballast_and_trim:ballast:C.Pitch] Stopped
2012-05-03T17:25:36.881Z,1336065936.881 [ballast_and_trim](INFO): Completed ballast_and_trim
2012-05-03T17:25:36.881Z,1336065936.881 [ballast_and_trim] Stopped
2012-05-03T17:25:36.881Z,1336065936.881 [ballast_and_trim](INFO): Aggregate::uninitialize ballast_and_trim
2012-05-03T17:25:36.881Z,1336065936.881 [ballast_and_trim:A] Stopped
2012-05-03T17:25:36.881Z,1336065936.881 [ballast_and_trim:B] Stopped
2012-05-03T17:25:36.881Z,1336065936.881 [ballast_and_trim:C] Stopped
2012-05-03T17:25:36.881Z,1336065936.881 [ballast_and_trim:D.AltitudeEnvelope] Stopped
2012-05-03T17:25:36.881Z,1336065936.881 [ballast_and_trim:D.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-05-03T17:25:36.881Z,1336065936.881 [ballast_and_trim:E.DepthEnvelope] Stopped
2012-05-03T17:25:36.881Z,1336065936.881 [ballast_and_trim:E.DepthEnvelope](DEBUG): Uninitialize.
2012-05-03T17:25:36.882Z,1336065936.882 [ballast_and_trim:F.OffshoreEnvelope] Stopped
2012-05-03T17:25:36.882Z,1336065936.882 [ballast_and_trim:F.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2012-05-03T17:25:36.882Z,1336065936.882 [ballast_and_trim:H.SetSpeed] Stopped
2012-05-03T17:25:36.882Z,1336065936.882 [ballast_and_trim:H.SetSpeed](DEBUG): Uninitialize.
2012-05-03T17:25:41.884Z,1336065941.884 [MissionManager](IMPORTANT): Started mission Default
2012-05-03T17:25:41.884Z,1336065941.884 [Default] Running Loop=1
2012-05-03T17:25:41.884Z,1336065941.884 [Default](INFO): Aggregate::initialize Default
2012-05-03T17:25:41.884Z,1336065941.884 [Default:D.SetSpeed] Running Loop=1
2012-05-03T17:25:41.884Z,1336065941.884 [Default:D.SetSpeed](DEBUG): Initialize.
2012-05-03T17:25:41.884Z,1336065941.884 [Default:E.GoToSurface] Running Loop=1
2012-05-03T17:25:41.884Z,1336065941.884 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T17:25:41.885Z,1336065941.885 [Default:Iridium] Running Loop=1
2012-05-03T17:25:41.885Z,1336065941.885 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-03T17:25:41.885Z,1336065941.885 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T17:25:41.885Z,1336065941.885 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-03T17:25:41.885Z,1336065941.885 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-03T17:25:41.885Z,1336065941.885 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T17:25:41.887Z,1336065941.887 [Default:CallIridium] Running Loop=1
2012-05-03T17:25:41.887Z,1336065941.887 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-03T17:25:41.887Z,1336065941.887 [Default:CallIridium:A] Running Loop=1
2012-05-03T17:25:41.887Z,1336065941.888 [Default:CallIridium:A] Stopped
2012-05-03T17:25:41.888Z,1336065941.888 [Default:CallIridium:B] Running Loop=1
2012-05-03T17:25:41.888Z,1336065941.888 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-03T17:25:41.888Z,1336065941.888 [Default:Iridium:B.GoToSurface] Stopped
2012-05-03T17:25:41.888Z,1336065941.888 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T17:25:41.889Z,1336065941.889 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-03T17:25:42.598Z,1336065942.598 [Default:GPS] Running Loop=1
2012-05-03T17:25:42.598Z,1336065942.598 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-03T17:25:42.598Z,1336065942.598 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T17:25:42.598Z,1336065942.598 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-03T17:25:42.598Z,1336065942.598 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-03T17:25:42.598Z,1336065942.598 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T17:25:42.599Z,1336065942.599 [Default:GPS:B.GoToSurface] Stopped
2012-05-03T17:25:42.600Z,1336065942.599 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T17:25:42.600Z,1336065942.600 [Default:GPS:Read_GPS] Running Loop=1
2012-05-03T17:25:42.988Z,1336065942.988 [NAL9601](INFO): Powering up
2012-05-03T17:26:48.615Z,1336066008.615 [NAL9601](INFO): NAL9601 initialized
2012-05-03T17:26:49.825Z,1336066009.825 [NAL9601](IMPORTANT): GPS fix at: 1336066011.00
2012-05-03T17:26:49.856Z,1336066009.856 [Default:GPS:Read_GPS] Stopped
2012-05-03T17:26:49.856Z,1336066009.856 [Default:GPS:D] Running Loop=1
2012-05-03T17:26:50.194Z,1336066010.194 [Default:GPS:D] Stopped
2012-05-03T17:26:50.194Z,1336066010.194 [Default:GPS](INFO): Completed Default:GPS
2012-05-03T17:26:50.194Z,1336066010.194 [Default:GPS] Stopped
2012-05-03T17:26:50.195Z,1336066010.195 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-03T17:26:50.195Z,1336066010.195 [Default:GPS:A.SetSpeed] Stopped
2012-05-03T17:26:50.195Z,1336066010.195 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T17:27:06.166Z,1336066026.165 [NAL9601](INFO): SBD MO Status=1, MOMSN=5864, MT Status=0, MTMSN=0
2012-05-03T17:27:06.375Z,1336066026.375 [NAL9601](INFO): Sent 332 bytes from file Logs/20120503T152308/shore0012.lzma
2012-05-03T17:27:06.375Z,1336066026.375 [NAL9601](INFO): Packets left to send: 2
2012-05-03T17:27:06.376Z,1336066026.376 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000021
2012-05-03T17:27:22.353Z,1336066042.353 [NAL9601](INFO): SBD MO Status=1, MOMSN=5865, MT Status=0, MTMSN=0
2012-05-03T17:27:22.547Z,1336066042.547 [NAL9601](INFO): Sent 332 bytes from file Logs/20120503T152308/shore0012.lzma
2012-05-03T17:27:22.547Z,1336066042.547 [NAL9601](INFO): Packets left to send: 1
2012-05-03T17:27:22.548Z,1336066042.548 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000022
2012-05-03T17:27:38.111Z,1336066058.111 [NAL9601](INFO): SBD MO Status=1, MOMSN=5866, MT Status=0, MTMSN=0
2012-05-03T17:27:38.323Z,1336066058.323 [NAL9601](INFO): Sent 242 bytes from file Logs/20120503T152308/shore0012.lzma
2012-05-03T17:27:38.323Z,1336066058.323 [NAL9601](INFO): Packets left to send: 0
2012-05-03T17:27:38.774Z,1336066058.774 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000023
2012-05-03T17:27:46.501Z,1336066066.501 [NAL9601](INFO): SBD MO Status=2, MOMSN=5867, MT Status=2, MTMSN=0
2012-05-03T17:27:46.501Z,1336066066.501 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-03T17:27:54.794Z,1336066074.794 [NAL9601](INFO): SBD MO Status=0, MOMSN=5867, MT Status=0, MTMSN=0
2012-05-03T17:27:55.024Z,1336066075.024 [Default:Iridium:Read_Iridium] Stopped
2012-05-03T17:27:55.024Z,1336066075.024 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-03T17:27:55.024Z,1336066075.024 [Default:Iridium] Stopped
2012-05-03T17:27:55.025Z,1336066075.025 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-03T17:27:55.025Z,1336066075.025 [Default:Iridium:A.SetSpeed] Stopped
2012-05-03T17:27:55.025Z,1336066075.025 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T17:27:55.025Z,1336066075.025 [Default:F.Wait] Running Loop=1
2012-05-03T17:27:55.025Z,1336066075.025 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-05-03T17:27:55.201Z,1336066075.201 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-03T17:27:55.201Z,1336066075.201 [Default:CallIridium:B] Stopped
2012-05-03T17:27:55.202Z,1336066075.202 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-03T17:27:55.202Z,1336066075.202 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-03T17:27:55.202Z,1336066075.202 [Default:CallIridium] Stopped
2012-05-03T17:27:55.202Z,1336066075.202 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-03T17:28:05.335Z,1336066085.335 [NAL9601](INFO): Powering down
2012-05-03T17:32:55.331Z,1336066375.331 [Default:CallIridium] Running Loop=1
2012-05-03T17:32:55.331Z,1336066375.331 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-03T17:32:55.331Z,1336066375.331 [Default:CallIridium:A] Running Loop=1
2012-05-03T17:32:55.332Z,1336066375.332 [Default:CallIridium:A] Stopped
2012-05-03T17:32:55.332Z,1336066375.332 [Default:CallIridium:B] Running Loop=1
2012-05-03T17:32:55.332Z,1336066375.332 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-03T17:33:00.377Z,1336066380.377 [Default:Iridium] Running Loop=1
2012-05-03T17:33:00.377Z,1336066380.377 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-03T17:33:00.377Z,1336066380.377 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T17:33:00.377Z,1336066380.377 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-03T17:33:00.377Z,1336066380.378 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-03T17:33:00.378Z,1336066380.378 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T17:33:00.379Z,1336066380.379 [Default:Iridium:B.GoToSurface] Stopped
2012-05-03T17:33:00.379Z,1336066380.379 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T17:33:00.379Z,1336066380.379 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-03T17:33:00.379Z,1336066380.379 [Default:GPS] Running Loop=1
2012-05-03T17:33:00.379Z,1336066380.379 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-03T17:33:00.379Z,1336066380.379 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T17:33:00.380Z,1336066380.379 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-03T17:33:00.380Z,1336066380.380 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-03T17:33:00.380Z,1336066380.380 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T17:33:00.381Z,1336066380.381 [Default:GPS:B.GoToSurface] Stopped
2012-05-03T17:33:00.381Z,1336066380.381 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T17:33:00.381Z,1336066380.381 [Default:GPS:Read_GPS] Running Loop=1
2012-05-03T17:33:00.984Z,1336066380.984 [NAL9601](INFO): Powering up
2012-05-03T17:34:06.707Z,1336066446.707 [NAL9601](INFO): NAL9601 initialized
2012-05-03T17:34:07.802Z,1336066447.802 [NAL9601](IMPORTANT): GPS fix at: 1336066450.00
2012-05-03T17:34:07.817Z,1336066447.817 [Default:GPS:Read_GPS] Stopped
2012-05-03T17:34:07.817Z,1336066447.818 [Default:GPS:D] Running Loop=1
2012-05-03T17:34:08.195Z,1336066448.195 [Default:GPS:D] Stopped
2012-05-03T17:34:08.195Z,1336066448.195 [Default:GPS](INFO): Completed Default:GPS
2012-05-03T17:34:08.195Z,1336066448.195 [Default:GPS] Stopped
2012-05-03T17:34:08.195Z,1336066448.195 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-03T17:34:08.195Z,1336066448.195 [Default:GPS:A.SetSpeed] Stopped
2012-05-03T17:34:08.196Z,1336066448.195 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T17:34:23.270Z,1336066463.270 [NAL9601](INFO): SBD MO Status=1, MOMSN=5868, MT Status=0, MTMSN=0
2012-05-03T17:34:23.471Z,1336066463.471 [NAL9601](INFO): Sent 218 bytes from file Logs/20120503T152308/shore0013.lzma
2012-05-03T17:34:23.471Z,1336066463.471 [NAL9601](INFO): Packets left to send: 0
2012-05-03T17:34:23.472Z,1336066463.472 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000024
2012-05-03T17:34:30.488Z,1336066470.488 [NAL9601](INFO): SBD MO Status=0, MOMSN=5869, MT Status=0, MTMSN=0
2012-05-03T17:34:30.673Z,1336066470.673 [Default:Iridium:Read_Iridium] Stopped
2012-05-03T17:34:30.673Z,1336066470.673 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-03T17:34:30.673Z,1336066470.673 [Default:Iridium] Stopped
2012-05-03T17:34:30.674Z,1336066470.674 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-03T17:34:30.674Z,1336066470.674 [Default:Iridium:A.SetSpeed] Stopped
2012-05-03T17:34:30.674Z,1336066470.674 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T17:34:30.902Z,1336066470.902 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-03T17:34:30.903Z,1336066470.903 [Default:CallIridium:B] Stopped
2012-05-03T17:34:30.903Z,1336066470.903 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-03T17:34:30.903Z,1336066470.903 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-03T17:34:30.903Z,1336066470.903 [Default:CallIridium] Stopped
2012-05-03T17:34:30.903Z,1336066470.903 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-03T17:34:41.066Z,1336066481.066 [NAL9601](INFO): Powering down
2012-05-03T17:39:31.060Z,1336066771.060 [Default:CallIridium] Running Loop=1
2012-05-03T17:39:31.060Z,1336066771.060 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-03T17:39:31.061Z,1336066771.061 [Default:CallIridium:A] Running Loop=1
2012-05-03T17:39:31.061Z,1336066771.061 [Default:CallIridium:A] Stopped
2012-05-03T17:39:31.061Z,1336066771.061 [Default:CallIridium:B] Running Loop=1
2012-05-03T17:39:31.061Z,1336066771.061 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-03T17:39:36.038Z,1336066776.038 [Default:Iridium] Running Loop=1
2012-05-03T17:39:36.038Z,1336066776.038 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-03T17:39:36.038Z,1336066776.038 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T17:39:36.038Z,1336066776.039 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-03T17:39:36.039Z,1336066776.039 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-03T17:39:36.039Z,1336066776.039 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T17:39:36.040Z,1336066776.040 [Default:Iridium:B.GoToSurface] Stopped
2012-05-03T17:39:36.040Z,1336066776.040 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T17:39:36.040Z,1336066776.040 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-03T17:39:36.040Z,1336066776.040 [Default:GPS] Running Loop=1
2012-05-03T17:39:36.040Z,1336066776.040 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-03T17:39:36.041Z,1336066776.040 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T17:39:36.041Z,1336066776.040 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-03T17:39:36.041Z,1336066776.041 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-03T17:39:36.041Z,1336066776.041 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T17:39:36.042Z,1336066776.042 [Default:GPS:B.GoToSurface] Stopped
2012-05-03T17:39:36.042Z,1336066776.042 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T17:39:36.042Z,1336066776.042 [Default:GPS:Read_GPS] Running Loop=1
2012-05-03T17:39:36.668Z,1336066776.668 [NAL9601](INFO): Powering up
2012-05-03T17:40:42.391Z,1336066842.391 [NAL9601](INFO): NAL9601 initialized
2012-05-03T17:40:43.505Z,1336066843.505 [NAL9601](IMPORTANT): GPS fix at: 1336066846.00
2012-05-03T17:40:43.521Z,1336066843.521 [Default:GPS:Read_GPS] Stopped
2012-05-03T17:40:43.521Z,1336066843.521 [Default:GPS:D] Running Loop=1
2012-05-03T17:40:43.878Z,1336066843.878 [Default:GPS:D] Stopped
2012-05-03T17:40:43.878Z,1336066843.878 [Default:GPS](INFO): Completed Default:GPS
2012-05-03T17:40:43.878Z,1336066843.878 [Default:GPS] Stopped
2012-05-03T17:40:43.879Z,1336066843.879 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-03T17:40:43.879Z,1336066843.879 [Default:GPS:A.SetSpeed] Stopped
2012-05-03T17:40:43.879Z,1336066843.879 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T17:40:59.742Z,1336066859.741 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=5870, MT Status=1, MTMSN=2575
2012-05-03T17:40:59.955Z,1336066859.955 [NAL9601](INFO): Sent 195 bytes from file Logs/20120503T152308/shore0014.lzma
2012-05-03T17:40:59.955Z,1336066859.955 [NAL9601](INFO): Packets left to send: 0
2012-05-03T17:40:59.956Z,1336066859.956 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000025
2012-05-03T17:41:00.372Z,1336066860.372 [NAL9601](INFO): Received command:restart application
2012-05-03T17:41:00.419Z,1336066860.419 [CommandLine](IMPORTANT): got command restart application
2012-05-03T17:41:00.470Z,1336066860.470 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2012-05-03T17:41:00.470Z,1336066860.470 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2012-05-03T17:41:00.991Z,1336066860.991 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2012-05-03T17:41:01.015Z,1336066861.015 [CTD_NeilBrown](INFO): Powering down
2012-05-03T17:41:01.015Z,1336066861.015 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2012-05-03T17:41:01.105Z,1336066861.105 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2012-05-03T17:41:01.105Z,1336066861.105 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2012-05-03T17:41:01.105Z,1336066861.105 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2012-05-03T17:41:01.391Z,1336066861.391 [controlThread](DEBUG): Uninitializing ControlThread
2012-05-03T17:41:01.392Z,1336066861.392 [AHRS_sp3003D](INFO): Powering down
2012-05-03T17:41:01.480Z,1336066861.480 [DVL_micro](INFO): Powering down
2012-05-03T17:41:01.480Z,1336066861.480 [NAL9601](INFO): Powering down
2012-05-03T17:41:01.481Z,1336066861.481 [WetLabsBB2FL](INFO): Powering down
2012-05-03T17:41:01.482Z,1336066861.482 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2012-05-03T17:41:01.483Z,1336066861.483 [Default] Stopped
2012-05-03T17:41:01.483Z,1336066861.483 [Default](INFO): Aggregate::uninitialize Default
2012-05-03T17:41:01.483Z,1336066861.483 [Default:Iridium] Stopped
2012-05-03T17:41:01.483Z,1336066861.483 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-03T17:41:01.483Z,1336066861.483 [Default:Iridium:A.SetSpeed] Stopped
2012-05-03T17:41:01.484Z,1336066861.484 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T17:41:01.484Z,1336066861.484 [Default:Iridium:Read_Iridium] Stopped
2012-05-03T17:41:01.484Z,1336066861.484 [Default:CallIridium] Stopped
2012-05-03T17:41:01.484Z,1336066861.484 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-03T17:41:01.484Z,1336066861.484 [Default:CallIridium:B] Stopped
2012-05-03T17:41:01.484Z,1336066861.484 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-03T17:41:01.484Z,1336066861.484 [Default:D.SetSpeed] Stopped
2012-05-03T17:41:01.484Z,1336066861.484 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-05-03T17:41:01.484Z,1336066861.484 [Default:E.GoToSurface] Stopped
2012-05-03T17:41:01.484Z,1336066861.484 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T17:41:01.484Z,1336066861.484 [Default:F.Wait] Stopped
2012-05-03T17:41:01.484Z,1336066861.484 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2012-05-03T17:41:01.489Z,1336066861.489 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2012-05-03T17:41:01.489Z,1336066861.489 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2012-05-03T17:41:01.489Z,1336066861.490 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2012-05-03T17:41:01.490Z,1336066861.490 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2012-05-03T17:41:01.491Z,1336066861.490 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2012-05-03T17:41:01.491Z,1336066861.491 [BuoyancyServo](INFO): Powering down
2012-05-03T17:41:01.491Z,1336066861.491 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-05-03T17:41:01.491Z,1336066861.491 [ElevatorServo](INFO): Powering down
2012-05-03T17:41:01.492Z,1336066861.492 [MassServo](DEBUG): Uninitialize Mass Servo.
2012-05-03T17:41:01.492Z,1336066861.492 [MassServo](INFO): Powering down
2012-05-03T17:41:01.492Z,1336066861.492 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2012-05-03T17:41:01.492Z,1336066861.492 [RudderServo](INFO): Powering down
2012-05-03T17:41:01.493Z,1336066861.493 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2012-05-03T17:41:01.493Z,1336066861.493 [ThrusterServo](INFO): Powering down
2012-05-03T17:41:01.493Z,1336066861.493 [SBIT](DEBUG): Uninitialize SBIT Component.
2012-05-03T17:41:01.493Z,1336066861.493 [IBIT](DEBUG): Uninitialize IBIT Component.
2012-05-03T17:41:01.493Z,1336066861.493 [CBIT](DEBUG): Uninitialize CBIT Component.