2013-10-22T21:49:08.132Z,1382478548.132 [Supervisor](DEBUG): Initializing supervisor.
2013-10-22T21:49:08.134Z,1382478548.134 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2013-10-22T21:49:08.135Z,1382478548.135 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2013-10-22T21:49:08.136Z,1382478548.136 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2013-10-22T21:49:08.139Z,1382478548.139 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2013-10-22T21:49:08.150Z,1382478548.150 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2013-10-22T21:49:08.151Z,1382478548.151 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2013-10-22T21:49:08.152Z,1382478548.152 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2013-10-22T21:49:08.153Z,1382478548.153 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0
2013-10-22T21:49:08.154Z,1382478548.154 [Supervisor](INFO): Looking for Config files in directory: Config/
2013-10-22T21:49:08.155Z,1382478548.155 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2013-10-22T21:49:08.435Z,1382478548.435 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2013-10-22T21:49:08.436Z,1382478548.436 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2013-10-22T21:49:08.626Z,1382478548.626 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2013-10-22T21:49:08.626Z,1382478548.626 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2013-10-22T21:49:08.712Z,1382478548.712 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2013-10-22T21:49:08.712Z,1382478548.712 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2013-10-22T21:49:08.823Z,1382478548.823 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2013-10-22T21:49:08.824Z,1382478548.824 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2013-10-22T21:49:08.967Z,1382478548.967 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2013-10-22T21:49:08.967Z,1382478548.967 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2013-10-22T21:49:09.205Z,1382478549.205 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2013-10-22T21:49:09.206Z,1382478549.206 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2013-10-22T21:49:09.374Z,1382478549.374 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2013-10-22T21:49:09.375Z,1382478549.375 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2013-10-22T21:49:09.637Z,1382478549.637 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2013-10-22T21:49:09.638Z,1382478549.638 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2013-10-22T21:49:09.739Z,1382478549.739 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2013-10-22T21:49:09.739Z,1382478549.739 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2013-10-22T21:49:10.153Z,1382478550.153 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2013-10-22T21:49:10.153Z,1382478550.153 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2013-10-22T21:49:10.264Z,1382478550.264 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2013-10-22T21:49:10.264Z,1382478550.264 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2013-10-22T21:49:10.350Z,1382478550.350 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2013-10-22T21:49:10.351Z,1382478550.351 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2013-10-22T21:49:10.449Z,1382478550.449 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2013-10-22T21:49:10.572Z,1382478550.572 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2013-10-22T21:49:10.665Z,1382478550.665 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2013-10-22T21:49:10.769Z,1382478550.769 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2013-10-22T21:49:10.863Z,1382478550.863 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2013-10-22T21:49:10.977Z,1382478550.977 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2013-10-22T21:49:11.072Z,1382478551.072 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2013-10-22T21:49:11.158Z,1382478551.158 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/LOGIN/
2013-10-22T21:49:11.159Z,1382478551.159 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2013-10-22T21:49:11.160Z,1382478551.160 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2013-10-22T21:49:11.324Z,1382478551.324 [InternalSim] Loaded
2013-10-22T21:49:11.324Z,1382478551.324 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2013-10-22T21:49:11.325Z,1382478551.325 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2013-10-22T21:49:11.325Z,1382478551.325 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2013-10-22T21:49:11.412Z,1382478551.412 [SBIT](DEBUG): Construct Startup Built In Test.
2013-10-22T21:49:11.441Z,1382478551.441 [SBIT] Loaded
2013-10-22T21:49:11.441Z,1382478551.441 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2013-10-22T21:49:11.441Z,1382478551.441 [IBIT](DEBUG): Construct Initiated Built In Test.
2013-10-22T21:49:11.471Z,1382478551.471 [IBIT] Loaded
2013-10-22T21:49:11.472Z,1382478551.472 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2013-10-22T21:49:11.474Z,1382478551.474 [CBIT](DEBUG): Construct CBIT Built In Test.
2013-10-22T21:49:11.590Z,1382478551.590 [CBIT] Loaded
2013-10-22T21:49:11.590Z,1382478551.590 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2013-10-22T21:49:11.590Z,1382478551.590 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2013-10-22T21:49:11.591Z,1382478551.591 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2013-10-22T21:49:11.758Z,1382478551.758 [BuoyancyServo] Loaded
2013-10-22T21:49:11.758Z,1382478551.758 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2013-10-22T21:49:11.770Z,1382478551.770 [ElevatorServo] Loaded
2013-10-22T21:49:11.770Z,1382478551.770 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2013-10-22T21:49:11.781Z,1382478551.781 [MassServo] Loaded
2013-10-22T21:49:11.782Z,1382478551.782 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2013-10-22T21:49:11.793Z,1382478551.793 [RudderServo] Loaded
2013-10-22T21:49:11.793Z,1382478551.793 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2013-10-22T21:49:11.804Z,1382478551.804 [ThrusterServo] Loaded
2013-10-22T21:49:11.804Z,1382478551.804 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2013-10-22T21:49:11.805Z,1382478551.805 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2013-10-22T21:49:11.805Z,1382478551.805 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2013-10-22T21:49:11.840Z,1382478551.840 [DepthRateCalculator] Loaded
2013-10-22T21:49:11.841Z,1382478551.841 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2013-10-22T21:49:14.915Z,1382478554.915 [HFRadarModelCalc] Loaded
2013-10-22T21:49:14.915Z,1382478554.915 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2013-10-22T21:49:14.931Z,1382478554.931 [NavChart] Loaded
2013-10-22T21:49:14.931Z,1382478554.931 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2013-10-22T21:49:14.937Z,1382478554.937 [PitchRateCalculator] Loaded
2013-10-22T21:49:14.937Z,1382478554.937 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2013-10-22T21:49:14.948Z,1382478554.948 [SpeedCalculator] Loaded
2013-10-22T21:49:14.948Z,1382478554.948 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2013-10-22T21:49:14.965Z,1382478554.965 [TempGradientCalculator] Loaded
2013-10-22T21:49:14.965Z,1382478554.965 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2013-10-22T21:49:14.971Z,1382478554.971 [YawRateCalculator] Loaded
2013-10-22T21:49:14.971Z,1382478554.971 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2013-10-22T21:49:15.018Z,1382478555.018 [Navigation] Loaded
2013-10-22T21:49:15.018Z,1382478555.018 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2013-10-22T21:49:15.019Z,1382478555.019 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2013-10-22T21:49:15.019Z,1382478555.019 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2013-10-22T21:49:15.259Z,1382478555.259 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2013-10-22T21:49:15.260Z,1382478555.260 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2013-10-22T21:49:15.283Z,1382478555.283 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2013-10-22T21:49:15.283Z,1382478555.283 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2013-10-22T21:49:15.334Z,1382478555.334 [VerticalControl](DEBUG): Construct VerticalControl.
2013-10-22T21:49:15.427Z,1382478555.427 [VerticalControl] Loaded
2013-10-22T21:49:15.427Z,1382478555.427 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2013-10-22T21:49:15.428Z,1382478555.428 [HorizontalControl](DEBUG): Construct HorizontalControl.
2013-10-22T21:49:15.487Z,1382478555.487 [HorizontalControl] Loaded
2013-10-22T21:49:15.488Z,1382478555.488 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2013-10-22T21:49:15.488Z,1382478555.488 [SpeedControl](DEBUG): Construct SpeedControl.
2013-10-22T21:49:15.490Z,1382478555.490 [SpeedControl] Loaded
2013-10-22T21:49:15.490Z,1382478555.490 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2013-10-22T21:49:15.491Z,1382478555.491 [LoopControl](DEBUG): Construct LoopControl.
2013-10-22T21:49:15.492Z,1382478555.492 [LoopControl] Loaded
2013-10-22T21:49:15.492Z,1382478555.492 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2013-10-22T21:49:15.492Z,1382478555.492 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2013-10-22T21:49:15.493Z,1382478555.493 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2013-10-22T21:49:15.499Z,1382478555.499 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2013-10-22T21:49:15.504Z,1382478555.504 [AsyncPiEstimator] Loaded
2013-10-22T21:49:15.504Z,1382478555.504 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2013-10-22T21:49:15.505Z,1382478555.505 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406474E0
2013-10-22T21:49:15.506Z,1382478555.506 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2013-10-22T21:49:15.506Z,1382478555.506 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2013-10-22T21:49:15.701Z,1382478555.701 [AHRS_sp3003D] Loaded
2013-10-22T21:49:15.701Z,1382478555.701 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2013-10-22T21:49:15.715Z,1382478555.715 [Depth_Keller] Loaded
2013-10-22T21:49:15.716Z,1382478555.716 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2013-10-22T21:49:15.721Z,1382478555.721 [DropWeight] Loaded
2013-10-22T21:49:15.721Z,1382478555.721 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2013-10-22T21:49:15.904Z,1382478555.904 [DVL_micro] Loaded
2013-10-22T21:49:15.904Z,1382478555.904 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2013-10-22T21:49:15.905Z,1382478555.905 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 406CE4E0
2013-10-22T21:49:15.994Z,1382478555.994 [NAL9602] Loaded
2013-10-22T21:49:15.994Z,1382478555.994 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2013-10-22T21:49:16.037Z,1382478556.037 [Onboard] Loaded
2013-10-22T21:49:16.037Z,1382478556.037 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2013-10-22T21:49:16.044Z,1382478556.044 [Radio_Freewave] Loaded
2013-10-22T21:49:16.044Z,1382478556.044 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2013-10-22T21:49:16.190Z,1382478556.190 [DAT] Loaded
2013-10-22T21:49:16.190Z,1382478556.190 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2013-10-22T21:49:16.197Z,1382478556.197 [SCPI] Loaded
2013-10-22T21:49:16.197Z,1382478556.197 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2013-10-22T21:49:16.198Z,1382478556.198 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2013-10-22T21:49:16.198Z,1382478556.198 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2013-10-22T21:49:16.297Z,1382478556.297 [CTD_NeilBrown] Loaded
2013-10-22T21:49:16.297Z,1382478556.297 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2013-10-22T21:49:16.298Z,1382478556.298 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4072B4E0
2013-10-22T21:49:16.314Z,1382478556.314 [PAR_Licor] Loaded
2013-10-22T21:49:16.314Z,1382478556.314 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2013-10-22T21:49:16.347Z,1382478556.347 [WetLabsBB2FL] Loaded
2013-10-22T21:49:16.347Z,1382478556.347 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2013-10-22T21:49:16.348Z,1382478556.348 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4075B4E0
2013-10-22T21:49:16.349Z,1382478556.349 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2013-10-22T21:49:16.351Z,1382478556.351 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2013-10-22T21:49:16.352Z,1382478556.352 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2013-10-22T21:49:16.359Z,1382478556.359 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2013-10-22T21:49:16.360Z,1382478556.360 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 4078B4E0
2013-10-22T21:49:16.364Z,1382478556.364 [Supervisor](DEBUG): Running supervisor.
2013-10-22T21:49:16.365Z,1382478556.365 [CommandLine](INFO): Thread ID is 9482
2013-10-22T21:49:16.368Z,1382478556.368 [controlThread](INFO): Thread ID is 9481
2013-10-22T21:49:16.368Z,1382478556.368 [controlThread](DEBUG): Initializing ControlThread
2013-10-22T21:49:16.369Z,1382478556.369 [CycleStarter](INFO): Thread ID is 9480
2013-10-22T21:49:16.369Z,1382478556.369 [InternalSim](DEBUG):  InternalSim initializing...
2013-10-22T21:49:16.404Z,1382478556.404 [logger](INFO): Thread ID is 9483
2013-10-22T21:49:16.420Z,1382478556.420 [SBIT](INFO): Initialize SBIT Component.
2013-10-22T21:49:16.420Z,1382478556.420 [SBIT](IMPORTANT): Tethys CM Info: 
 $Rev:10655
2013-10-22T21:49:16.421Z,1382478556.421 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2013-10-22T21:49:16.421Z,1382478556.421 [SBIT](IMPORTANT): Kernel Version:#634 PREEMPT Wed Feb 13 10:21:48 PST 2013
2013-10-22T21:49:16.421Z,1382478556.421 [IBIT](INFO): Initialize IBIT Component.
2013-10-22T21:49:16.422Z,1382478556.422 [CBIT](DEBUG): Initialize CBIT Component.
2013-10-22T21:49:16.423Z,1382478556.423 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2013-10-22T21:49:16.432Z,1382478556.432 [AsyncPiEstimator](INFO): Thread ID is 9544
2013-10-22T21:49:16.432Z,1382478556.432 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2013-10-22T21:49:16.453Z,1382478556.453 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-10-22T21:49:16.453Z,1382478556.453 [NavChart](DEBUG): Initialize NavChart Derivation.
2013-10-22T21:49:16.454Z,1382478556.454 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2013-10-22T21:49:16.454Z,1382478556.454 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2013-10-22T21:49:16.454Z,1382478556.454 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2013-10-22T21:49:16.455Z,1382478556.455 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2013-10-22T21:49:16.456Z,1382478556.456 [Navigation](DEBUG): Initializing Navigation.
2013-10-22T21:49:16.456Z,1382478556.456 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2013-10-22T21:49:16.458Z,1382478556.458 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2013-10-22T21:49:16.458Z,1382478556.458 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2013-10-22T21:49:16.459Z,1382478556.459 [LoopControl](DEBUG): Initialize LoopControlComponent.
2013-10-22T21:49:16.465Z,1382478556.465 [DVL_micro](INFO): Thread ID is 9545
2013-10-22T21:49:16.474Z,1382478556.474 [DVL_micro](INFO): Initializing
2013-10-22T21:49:16.474Z,1382478556.474 [DVL_micro](INFO): start:Powering up
2013-10-22T21:49:16.475Z,1382478556.475 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-10-22T21:49:16.476Z,1382478556.476 [DVL_micro](INFO): Cycling power to configure device.
2013-10-22T21:49:16.491Z,1382478556.491 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2013-10-22T21:49:16.501Z,1382478556.501 [CTD_NeilBrown](INFO): Thread ID is 9546
2013-10-22T21:49:16.501Z,1382478556.501 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2013-10-22T21:49:16.516Z,1382478556.516 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2013-10-22T21:49:16.526Z,1382478556.526 [WetLabsBB2FL](INFO): Thread ID is 9547
2013-10-22T21:49:16.526Z,1382478556.526 [WetLabsBB2FL](INFO): Powering down
2013-10-22T21:49:16.556Z,1382478556.556 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2013-10-22T21:49:16.561Z,1382478556.561 [NavChartDb](INFO): Thread ID is 9548
2013-10-22T21:49:16.563Z,1382478556.563 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2013-10-22T21:49:16.564Z,1382478556.564 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2013-10-22T21:49:16.565Z,1382478556.565 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2013-10-22T21:49:16.565Z,1382478556.565 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2013-10-22T21:49:16.565Z,1382478556.565 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2013-10-22T21:49:16.565Z,1382478556.565 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2013-10-22T21:49:16.566Z,1382478556.566 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2013-10-22T21:49:16.566Z,1382478556.566 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2013-10-22T21:49:16.566Z,1382478556.566 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2013-10-22T21:49:16.591Z,1382478556.591 [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>


2013-10-22T21:49:16.596Z,1382478556.596 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2013-10-22T21:49:16.676Z,1382478556.676 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2013-10-22T21:49:16.678Z,1382478556.678 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2013-10-22T21:49:16.686Z,1382478556.686 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-10-22T21:49:16.722Z,1382478556.722 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2013-10-22T21:49:16.733Z,1382478556.733 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-10-22T21:49:16.747Z,1382478556.747 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2013-10-22T21:49:16.771Z,1382478556.771 [Default:D.SetSpeed](DEBUG): Construct.
2013-10-22T21:49:16.774Z,1382478556.774 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2013-10-22T21:49:16.779Z,1382478556.779 [Default:F.Wait](DEBUG): Construct Wait.
2013-10-22T21:49:16.798Z,1382478556.798 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
xmlns:Control="Tethys/Control"
xmlns:Guidance="Tethys/Guidance" 
xmlns:Units="Tethys/Units"
xmlns:Universal="Tethys/Universal"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
Id="Default">

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

    <Aggregate Id="GPS" >

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

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Get GPS fix -->

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

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

    </Aggregate>

    <Aggregate Id="Iridium" >

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Do data comms -->

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

    </Aggregate>

    <Aggregate Id="CallIridium" >

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

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

        <Call RefId="Iridium"/>

    </Aggregate>

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

<!-- Run at low speed -->

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

    <Guidance:GoToSurface RunIn="Parallel"/>

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

</Mission>


2013-10-22T21:49:16.803Z,1382478556.803 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Depth_Keller,DropWeight,NAL9602,Onboard,Radio_Freewave,DAT,SCPI,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,
2013-10-22T21:49:16.885Z,1382478556.885 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-10-22T21:49:16.899Z,1382478556.899 [Depth_Keller](ERROR): Pressure reading out of range: 1831.078247 decibar
2013-10-22T21:49:16.993Z,1382478556.993 [Radio_Freewave](INFO): Powering up
2013-10-22T21:49:17.002Z,1382478557.002 [DAT](INFO): Powering up
2013-10-22T21:49:17.002Z,1382478557.002 [DAT](DEBUG): Initializing DAT.
2013-10-22T21:49:17.303Z,1382478557.303 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-10-22T21:49:17.325Z,1382478557.325 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-10-22T21:49:17.331Z,1382478557.331 [ElevatorServo](DEBUG): Initializing EZServoServo.
2013-10-22T21:49:17.337Z,1382478557.337 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2013-10-22T21:49:17.357Z,1382478557.357 [MassServo](DEBUG): Initializing EZServoServo.
2013-10-22T21:49:17.358Z,1382478557.358 [MassServo](DEBUG): Initializing MassServo.
2013-10-22T21:49:17.379Z,1382478557.379 [RudderServo](DEBUG): Initializing EZServoServo.
2013-10-22T21:49:17.385Z,1382478557.385 [RudderServo](DEBUG): Initializing RudderServo.
2013-10-22T21:49:17.391Z,1382478557.391 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-10-22T21:49:17.398Z,1382478557.398 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-10-22T21:49:18.351Z,1382478558.351 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2013-10-22T21:49:18.351Z,1382478558.351 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2013-10-22T21:49:18.351Z,1382478558.351 [BuoyancyServo] Communications Fault, FailCount= 1
2013-10-22T21:49:18.351Z,1382478558.351 [BuoyancyServo](ERROR): Communications Fault
2013-10-22T21:49:18.541Z,1382478558.541 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2013-10-22T21:49:18.551Z,1382478558.551 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-10-22T21:49:18.552Z,1382478558.552 [DVL_micro](INFO): Querying output modes
2013-10-22T21:49:18.552Z,1382478558.552 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-10-22T21:49:18.563Z,1382478558.563 [DVL_micro](DEBUG): cmdResponse: 01
2013-10-22T21:49:18.563Z,1382478558.563 [DVL_micro](INFO): NQ1 output enabled
2013-10-22T21:49:18.564Z,1382478558.564 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-10-22T21:49:18.575Z,1382478558.575 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2013-10-22T21:49:18.581Z,1382478558.581 [DVL_micro](INFO): pause:Powering down
2013-10-22T21:49:18.860Z,1382478558.860 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-10-22T21:49:18.865Z,1382478558.865 [BuoyancyServo](INFO): Powering down
2013-10-22T21:49:20.981Z,1382478560.981 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2013-10-22T21:49:20.981Z,1382478560.981 [BuoyancyServo] No Fault, FailCount= 1
2013-10-22T21:49:21.172Z,1382478561.172 [NAL9602](INFO): Powering up NAL9602
2013-10-22T21:49:21.246Z,1382478561.246 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-10-22T21:49:21.364Z,1382478561.364 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-10-22T21:49:31.940Z,1382478571.940 [NAL9602](INFO): NAL9602 initialized
2013-10-22T21:49:32.054Z,1382478572.054 [SBIT](IMPORTANT): Beginning Startup BIT
2013-10-22T21:49:32.057Z,1382478572.057 [CBIT](IMPORTANT): Beginning GF scan
2013-10-22T21:49:36.355Z,1382478576.355 [DAT](INFO): Init failed - response: 
2013-10-22T21:49:36.355Z,1382478576.355 [DAT](FAULT): DAT failed to initialize
2013-10-22T21:49:36.355Z,1382478576.355 [DAT] Communications Fault, FailCount= 1
2013-10-22T21:49:36.355Z,1382478576.355 [DAT](ERROR): Communications Fault
2013-10-22T21:49:36.474Z,1382478576.474 [CBIT](ERROR): Communications Fault in component: DAT
2013-10-22T21:49:36.706Z,1382478576.706 [DAT](INFO): Powering down
2013-10-22T21:49:37.873Z,1382478577.873 [CBIT](INFO): Clearing failed state for component DAT
2013-10-22T21:49:37.873Z,1382478577.873 [DAT] No Fault, FailCount= 1
2013-10-22T21:49:40.159Z,1382478580.159 [DAT](INFO): Powering up
2013-10-22T21:49:40.159Z,1382478580.159 [DAT](DEBUG): Initializing DAT.
2013-10-22T21:49:43.382Z,1382478583.382 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/SCPI_on.xml
2013-10-22T21:49:43.382Z,1382478583.382 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/SCPI_on.xml
2013-10-22T21:49:43.417Z,1382478583.417 [MissionManager](INFO): DefineArg SCPI_on.MassDefault = 0.008000 n/a
2013-10-22T21:49:43.441Z,1382478583.441 [SCPI_on:A.Pitch](DEBUG): Construct.
2013-10-22T21:49:43.468Z,1382478583.468 [SCPI_on:TestDrive:C.Wait](DEBUG): Construct Wait.
2013-10-22T21:49:43.483Z,1382478583.483 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Sensor="Tethys/Sensor"
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Sensor http://aosn.mbari.org/tethys/Xml/Sensor.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="SCPI_on">

    <DefineArg Name="MassDefault"><Control:VerticalControl.massDefault/></DefineArg>

    <Timeout Duration="P15M"/>

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

    <Aggregate Id="TestDrive">

        <ReadData Strategy="MinError">
            <Sensor:SCPI.sampleSCPI/>
        </ReadData>

        <Aggregate Id="Data">

            <When>
                <True/>
            </When>

            <SendData Service="Express">
                <Sensor:SCPI.sampleSCPI/><Units:bool/>
            </SendData>

            <Syslog Severity="None">Pause a cycle</Syslog>

        </Aggregate>

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

    </Aggregate>

</Mission>


2013-10-22T21:49:43.485Z,1382478583.485 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/SCPI_on.xml
2013-10-22T21:49:46.879Z,1382478586.879 [CommandLine](IMPORTANT): got command stop
2013-10-22T21:49:50.889Z,1382478590.889 [CommandLine](IMPORTANT): got command failComponent
2013-10-22T21:49:50.890Z,1382478590.890 [CommandLine](IMPORTANT): Failed components:
2013-10-22T21:49:50.890Z,1382478590.890 [CommandLine](IMPORTANT): No failed Components.
2013-10-22T21:49:58.586Z,1382478598.586 [CBIT](IMPORTANT): No ground fault detected
2013-10-22T21:50:00.243Z,1382478600.243 [DAT](INFO): Powering down
2013-10-22T21:50:25.735Z,1382478625.735 [SBIT](IMPORTANT): SBIT PASSED
2013-10-22T21:50:26.078Z,1382478626.078 [MissionManager](IMPORTANT): Started mission Startup
2013-10-22T21:50:26.078Z,1382478626.078 [Startup] Running Loop=1
2013-10-22T21:50:26.078Z,1382478626.078 [Startup](INFO): Aggregate::initialize Startup
2013-10-22T21:50:26.078Z,1382478626.078 [Startup:A.GoToSurface] Running Loop=1
2013-10-22T21:50:26.078Z,1382478626.078 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-22T21:50:26.093Z,1382478626.093 [Startup:StartupSatComms] Running Loop=1
2013-10-22T21:50:26.093Z,1382478626.093 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2013-10-22T21:50:26.093Z,1382478626.093 [Startup:StartupSatComms:A] Running Loop=1
2013-10-22T21:50:26.470Z,1382478626.470 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-10-22T21:51:26.486Z,1382478686.486 [Startup:StartupSatComms:A](INFO): Timed out from 2013-10-22T21:50:26.1Z
2013-10-22T21:51:26.487Z,1382478686.487 [Startup:StartupSatComms:A:A_Timeout] Running Loop=1
2013-10-22T21:51:26.487Z,1382478686.487 [Startup:StartupSatComms:A:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A:A_Timeout
2013-10-22T21:51:26.487Z,1382478686.487 [Startup:StartupSatComms:A:A_Timeout](INFO): Completed Startup:StartupSatComms:A:A_Timeout
2013-10-22T21:51:26.487Z,1382478686.487 [Startup:StartupSatComms:A] Stopped
2013-10-22T21:51:26.487Z,1382478686.487 [Startup:StartupSatComms:B] Running Loop=1
2013-10-22T21:51:26.887Z,1382478686.887 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-10-22T21:51:30.019Z,1382478690.019 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:51:34.339Z,1382478694.339 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:51:38.661Z,1382478698.661 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:51:42.993Z,1382478702.993 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:51:46.915Z,1382478706.915 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:51:51.240Z,1382478711.240 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:51:55.964Z,1382478715.964 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:52:00.276Z,1382478720.276 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:52:04.214Z,1382478724.214 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:52:08.521Z,1382478728.521 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:52:12.441Z,1382478732.441 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:52:16.753Z,1382478736.753 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:52:25.471Z,1382478745.471 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:52:26.703Z,1382478746.703 [Startup:StartupSatComms:B](INFO): Timed out from 2013-10-22T21:51:26.5Z
2013-10-22T21:52:26.704Z,1382478746.704 [Startup:StartupSatComms:B:A_Timeout] Running Loop=1
2013-10-22T21:52:26.704Z,1382478746.704 [Startup:StartupSatComms:B:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:B:A_Timeout
2013-10-22T21:52:26.705Z,1382478746.705 [Startup:StartupSatComms:B:A_Timeout](INFO): Completed Startup:StartupSatComms:B:A_Timeout
2013-10-22T21:52:26.705Z,1382478746.705 [Startup:StartupSatComms:B] Stopped
2013-10-22T21:52:26.705Z,1382478746.705 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2013-10-22T21:52:26.705Z,1382478746.705 [Startup:StartupSatComms] Stopped
2013-10-22T21:52:26.705Z,1382478746.705 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2013-10-22T21:52:26.728Z,1382478746.728 [Startup](INFO): Completed Startup
2013-10-22T21:52:26.728Z,1382478746.728 [Startup] Stopped
2013-10-22T21:52:26.728Z,1382478746.728 [Startup](INFO): Aggregate::uninitialize Startup
2013-10-22T21:52:26.728Z,1382478746.728 [Startup:A.GoToSurface] Stopped
2013-10-22T21:52:26.728Z,1382478746.728 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-22T21:52:27.090Z,1382478747.090 [MissionManager](IMPORTANT): Started mission SCPI_on
2013-10-22T21:52:27.090Z,1382478747.090 [SCPI_on] Running Loop=1
2013-10-22T21:52:27.090Z,1382478747.090 [SCPI_on](INFO): Aggregate::initialize SCPI_on
2013-10-22T21:52:27.090Z,1382478747.090 [SCPI_on:A.Pitch] Running Loop=1
2013-10-22T21:52:27.090Z,1382478747.090 [SCPI_on:A.Pitch](DEBUG): Initialize.
2013-10-22T21:52:27.091Z,1382478747.091 [SCPI_on:TestDrive] Running Loop=1
2013-10-22T21:52:27.091Z,1382478747.091 [SCPI_on:TestDrive](INFO): Aggregate::initialize SCPI_on:TestDrive
2013-10-22T21:52:27.091Z,1382478747.091 [SCPI_on:TestDrive:A] Running Loop=1
2013-10-22T21:52:27.091Z,1382478747.091 [SCPI_on:TestDrive:C.Wait] Running Loop=1
2013-10-22T21:52:27.091Z,1382478747.091 [SCPI_on:TestDrive:C.Wait](DEBUG): Initialize Wait Component.
2013-10-22T21:52:27.096Z,1382478747.096 [SCPI_on:TestDrive:Data] Running Loop=1
2013-10-22T21:52:27.096Z,1382478747.096 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-10-22T21:52:27.096Z,1382478747.096 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-10-22T21:52:27.099Z,1382478747.099 [SCPI_on:TestDrive:Data:A] Stopped
2013-10-22T21:52:27.099Z,1382478747.099 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-10-22T21:52:27.099Z,1382478747.099 [SCPI_on:TestDrive:A] Running Loop=1
2013-10-22T21:52:27.100Z,1382478747.100 [SCPI_on:TestDrive:A](DEBUG): Initialize ReadDataComponent to sense SCPI.sampleSCPI
2013-10-22T21:52:27.101Z,1382478747.101 [SCPI_on:A.Pitch] Running Loop=1
2013-10-22T21:52:27.143Z,1382478747.143 [SCPI_on] Stopped
2013-10-22T21:52:27.143Z,1382478747.143 [SCPI_on](INFO): Aggregate::uninitialize SCPI_on
2013-10-22T21:52:27.143Z,1382478747.143 [SCPI_on:A.Pitch] Stopped
2013-10-22T21:52:27.143Z,1382478747.143 [SCPI_on:TestDrive] Stopped
2013-10-22T21:52:27.143Z,1382478747.143 [SCPI_on:TestDrive](INFO): Aggregate::uninitialize SCPI_on:TestDrive
2013-10-22T21:52:27.143Z,1382478747.143 [SCPI_on:TestDrive:A] Stopped
2013-10-22T21:52:27.143Z,1382478747.143 [SCPI_on:TestDrive:Data] Stopped
2013-10-22T21:52:27.144Z,1382478747.144 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-10-22T21:52:27.144Z,1382478747.144 [SCPI_on:TestDrive:Data:B] Stopped
2013-10-22T21:52:27.144Z,1382478747.144 [SCPI_on:TestDrive:C.Wait] Stopped
2013-10-22T21:52:27.144Z,1382478747.144 [SCPI_on:TestDrive:C.Wait](DEBUG): Uninitialize Wait Component.
2013-10-22T21:52:27.475Z,1382478747.475 [MissionManager](IMPORTANT): Started mission Default
2013-10-22T21:52:27.475Z,1382478747.475 [Default] Running Loop=1
2013-10-22T21:52:27.475Z,1382478747.475 [Default](INFO): Aggregate::initialize Default
2013-10-22T21:52:27.475Z,1382478747.475 [Default:D.SetSpeed] Running Loop=1
2013-10-22T21:52:27.475Z,1382478747.475 [Default:D.SetSpeed](DEBUG): Initialize.
2013-10-22T21:52:27.475Z,1382478747.475 [Default:E.GoToSurface] Running Loop=1
2013-10-22T21:52:27.475Z,1382478747.475 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-22T21:52:27.476Z,1382478747.476 [Default:Iridium] Running Loop=1
2013-10-22T21:52:27.476Z,1382478747.476 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2013-10-22T21:52:27.476Z,1382478747.476 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-10-22T21:52:27.476Z,1382478747.476 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2013-10-22T21:52:27.476Z,1382478747.476 [Default:Iridium:B.GoToSurface] Running Loop=1
2013-10-22T21:52:27.476Z,1382478747.476 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-22T21:52:27.477Z,1382478747.477 [Default:E.GoToSurface] Running Loop=1
2013-10-22T21:52:27.482Z,1382478747.482 [Default:D.SetSpeed] Running Loop=1
2013-10-22T21:52:27.487Z,1382478747.487 [Default:CallIridium] Running Loop=1
2013-10-22T21:52:27.487Z,1382478747.487 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2013-10-22T21:52:27.487Z,1382478747.487 [Default:CallIridium:A] Running Loop=1
2013-10-22T21:52:27.490Z,1382478747.490 [Default:CallIridium:A] Stopped
2013-10-22T21:52:27.490Z,1382478747.490 [Default:CallIridium:B] Running Loop=1
2013-10-22T21:52:27.490Z,1382478747.490 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2013-10-22T21:52:27.495Z,1382478747.495 [Default:Iridium:B.GoToSurface] Stopped
2013-10-22T21:52:27.495Z,1382478747.495 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-22T21:52:27.496Z,1382478747.496 [Default:Iridium:Read_Iridium] Running Loop=1
2013-10-22T21:52:27.496Z,1382478747.496 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-10-22T21:52:27.501Z,1382478747.501 [Default:GPS] Running Loop=1
2013-10-22T21:52:27.501Z,1382478747.501 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2013-10-22T21:52:27.501Z,1382478747.501 [Default:GPS:A.SetSpeed] Running Loop=1
2013-10-22T21:52:27.501Z,1382478747.501 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2013-10-22T21:52:27.501Z,1382478747.501 [Default:GPS:B.GoToSurface] Running Loop=1
2013-10-22T21:52:27.501Z,1382478747.501 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-22T21:52:27.507Z,1382478747.507 [Default:GPS:B.GoToSurface] Stopped
2013-10-22T21:52:27.507Z,1382478747.507 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-22T21:52:27.507Z,1382478747.507 [Default:GPS:Read_GPS] Running Loop=1
2013-10-22T21:52:27.507Z,1382478747.507 [Default:GPS:A.SetSpeed] Running Loop=1
2013-10-22T21:52:27.880Z,1382478747.880 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-10-22T21:52:27.882Z,1382478747.882 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-10-22T21:52:38.589Z,1382478758.589 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:52:42.922Z,1382478762.922 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:52:47.239Z,1382478767.239 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:52:51.579Z,1382478771.579 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:52:55.497Z,1382478775.497 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:52:59.822Z,1382478779.822 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:53:04.139Z,1382478784.139 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:53:08.469Z,1382478788.469 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:53:12.374Z,1382478792.374 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:53:16.726Z,1382478796.726 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:53:21.438Z,1382478801.438 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:53:25.749Z,1382478805.749 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:53:30.458Z,1382478810.458 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:53:34.773Z,1382478814.773 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:53:39.516Z,1382478819.516 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:53:43.840Z,1382478823.840 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:53:48.550Z,1382478828.550 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:53:52.870Z,1382478832.870 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:53:57.207Z,1382478837.207 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:54:01.532Z,1382478841.532 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:54:05.440Z,1382478845.440 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:54:09.787Z,1382478849.787 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:54:14.502Z,1382478854.502 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:54:18.815Z,1382478858.815 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:54:23.140Z,1382478863.140 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:54:27.476Z,1382478867.476 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:54:31.378Z,1382478871.378 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:54:35.719Z,1382478875.719 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:54:40.441Z,1382478880.441 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:54:44.759Z,1382478884.759 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:54:48.677Z,1382478888.677 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:54:53.411Z,1382478893.411 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:54:57.747Z,1382478897.747 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:55:02.473Z,1382478902.473 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:55:06.805Z,1382478906.805 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:55:11.130Z,1382478911.130 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:55:15.446Z,1382478915.446 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:55:19.380Z,1382478919.380 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:55:23.701Z,1382478923.701 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:55:28.425Z,1382478928.425 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:55:32.737Z,1382478932.737 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:55:36.671Z,1382478936.671 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:55:41.397Z,1382478941.397 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:55:45.729Z,1382478945.729 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:55:50.441Z,1382478950.441 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:55:54.763Z,1382478954.763 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:55:59.513Z,1382478959.513 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:56:03.853Z,1382478963.853 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:56:08.162Z,1382478968.162 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:56:12.483Z,1382478972.483 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:56:16.393Z,1382478976.393 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:56:20.718Z,1382478980.718 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:56:24.648Z,1382478984.648 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:56:29.371Z,1382478989.371 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:56:33.700Z,1382478993.700 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:56:38.410Z,1382478998.410 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:56:42.738Z,1382479002.738 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:56:47.447Z,1382479007.447 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:56:51.774Z,1382479011.774 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:56:56.493Z,1382479016.493 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:57:00.834Z,1382479020.834 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:57:05.147Z,1382479025.147 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:57:09.487Z,1382479029.487 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:57:13.414Z,1382479033.414 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:57:17.714Z,1382479037.714 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:57:22.454Z,1382479042.454 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:57:26.766Z,1382479046.766 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:57:30.298Z,1382479050.298 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:57:34.630Z,1382479054.630 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:57:38.134Z,1382479058.134 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:57:42.458Z,1382479062.458 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:57:46.368Z,1382479066.368 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:57:50.717Z,1382479070.717 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:57:54.647Z,1382479074.647 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:57:59.375Z,1382479079.375 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:58:03.727Z,1382479083.727 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:58:08.465Z,1382479088.465 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:58:12.765Z,1382479092.765 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:58:17.471Z,1382479097.471 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:58:21.827Z,1382479101.827 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:58:26.144Z,1382479106.144 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:58:30.477Z,1382479110.477 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:58:34.387Z,1382479114.387 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:58:38.720Z,1382479118.720 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:58:42.638Z,1382479122.638 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:58:47.385Z,1382479127.385 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:58:51.669Z,1382479131.669 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:58:56.415Z,1382479136.415 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:59:00.736Z,1382479140.736 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:59:05.457Z,1382479145.457 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:59:09.762Z,1382479149.762 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:59:14.514Z,1382479154.514 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:59:18.819Z,1382479158.819 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:59:23.154Z,1382479163.154 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:59:27.477Z,1382479167.477 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:59:31.411Z,1382479171.411 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:59:35.722Z,1382479175.722 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T21:59:36.519Z,1382479176.519 [NAL9602](FAULT): GPS failed to acquire within timeout.
2013-10-22T21:59:36.519Z,1382479176.519 [NAL9602] Data Fault, FailCount= 1
2013-10-22T21:59:36.519Z,1382479176.519 [NAL9602](ERROR): Data Fault
2013-10-22T21:59:36.544Z,1382479176.544 [CBIT](ERROR): Data Fault in component: NAL9602
2013-10-22T21:59:36.914Z,1382479176.914 [NAL9602](INFO): Powering down
2013-10-22T21:59:37.742Z,1382479177.742 [CBIT](INFO): Clearing failed state for component NAL9602
2013-10-22T21:59:37.742Z,1382479177.742 [NAL9602] No Fault, FailCount= 1
2013-10-22T21:59:42.117Z,1382479182.117 [NAL9602](INFO): Powering up NAL9602
2013-10-22T21:59:52.955Z,1382479192.955 [NAL9602](INFO): NAL9602 initialized
2013-10-22T22:00:00.439Z,1382479200.439 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:00:04.761Z,1382479204.761 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:00:09.078Z,1382479209.078 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:00:13.813Z,1382479213.813 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:00:18.132Z,1382479218.132 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:00:22.861Z,1382479222.861 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:00:27.162Z,1382479227.162 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:00:31.871Z,1382479231.871 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:00:36.228Z,1382479236.228 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:00:40.949Z,1382479240.949 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:00:45.262Z,1382479245.262 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:00:49.999Z,1382479249.999 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:00:54.328Z,1382479254.328 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:00:58.661Z,1382479258.661 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:01:02.989Z,1382479262.989 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:01:03.813Z,1382479263.813 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/SCPI_on.xml
2013-10-22T22:01:03.813Z,1382479263.813 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/SCPI_on.xml
2013-10-22T22:01:03.861Z,1382479263.861 [MissionManager](INFO): DefineArg SCPI_on.MassDefault = 0.008000 n/a
2013-10-22T22:01:03.862Z,1382479263.862 [SCPI_on:A.Pitch](DEBUG): Construct.
2013-10-22T22:01:03.870Z,1382479263.870 [SCPI_on:TestDrive:C.Wait](DEBUG): Construct Wait.
2013-10-22T22:01:03.873Z,1382479263.873 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Sensor="Tethys/Sensor"
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Sensor http://aosn.mbari.org/tethys/Xml/Sensor.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="SCPI_on">

    <DefineArg Name="MassDefault"><Control:VerticalControl.massDefault/></DefineArg>

    <Timeout Duration="P15M"/>

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

    <Aggregate Id="TestDrive">

        <ReadData Strategy="MinError">
            <Sensor:SCPI.sampleSCPI/>
        </ReadData>

        <Aggregate Id="Data">

            <When>
                <True/>
            </When>

            <SendData Service="Express">
                <Sensor:SCPI.sampleSCPI/><Units:bool/>
            </SendData>

            <Syslog Severity="None">Pause a cycle</Syslog>

        </Aggregate>

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

    </Aggregate>

</Mission>


2013-10-22T22:01:03.875Z,1382479263.875 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/SCPI_on.xml
2013-10-22T22:01:04.223Z,1382479264.223 [Default] Stopped
2013-10-22T22:01:04.224Z,1382479264.224 [Default](INFO): Aggregate::uninitialize Default
2013-10-22T22:01:04.224Z,1382479264.224 [Default:GPS] Stopped
2013-10-22T22:01:04.224Z,1382479264.224 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2013-10-22T22:01:04.224Z,1382479264.224 [Default:GPS:A.SetSpeed] Stopped
2013-10-22T22:01:04.224Z,1382479264.224 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2013-10-22T22:01:04.224Z,1382479264.224 [Default:GPS:Read_GPS] Stopped
2013-10-22T22:01:04.224Z,1382479264.224 [Default:Iridium] Stopped
2013-10-22T22:01:04.224Z,1382479264.224 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2013-10-22T22:01:04.224Z,1382479264.224 [Default:Iridium:A.SetSpeed] Stopped
2013-10-22T22:01:04.224Z,1382479264.224 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2013-10-22T22:01:04.225Z,1382479264.225 [Default:Iridium:Read_Iridium] Stopped
2013-10-22T22:01:04.225Z,1382479264.225 [Default:CallIridium] Stopped
2013-10-22T22:01:04.225Z,1382479264.225 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2013-10-22T22:01:04.226Z,1382479264.226 [Default:CallIridium:B] Stopped
2013-10-22T22:01:04.226Z,1382479264.226 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2013-10-22T22:01:04.226Z,1382479264.226 [Default:D.SetSpeed] Stopped
2013-10-22T22:01:04.226Z,1382479264.226 [Default:D.SetSpeed](DEBUG): Uninitialize.
2013-10-22T22:01:04.226Z,1382479264.226 [Default:E.GoToSurface] Stopped
2013-10-22T22:01:04.226Z,1382479264.226 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-22T22:01:04.226Z,1382479264.226 [MissionManager](IMPORTANT): Started mission SCPI_on
2013-10-22T22:01:04.226Z,1382479264.226 [SCPI_on] Running Loop=1
2013-10-22T22:01:04.226Z,1382479264.226 [SCPI_on](INFO): Aggregate::initialize SCPI_on
2013-10-22T22:01:04.226Z,1382479264.226 [SCPI_on:A.Pitch] Running Loop=1
2013-10-22T22:01:04.227Z,1382479264.227 [SCPI_on:A.Pitch](DEBUG): Initialize.
2013-10-22T22:01:04.227Z,1382479264.227 [SCPI_on:TestDrive] Running Loop=1
2013-10-22T22:01:04.227Z,1382479264.227 [SCPI_on:TestDrive](INFO): Aggregate::initialize SCPI_on:TestDrive
2013-10-22T22:01:04.227Z,1382479264.227 [SCPI_on:TestDrive:A] Running Loop=1
2013-10-22T22:01:04.227Z,1382479264.227 [SCPI_on:TestDrive:C.Wait] Running Loop=1
2013-10-22T22:01:04.228Z,1382479264.228 [SCPI_on:TestDrive:C.Wait](DEBUG): Initialize Wait Component.
2013-10-22T22:01:04.229Z,1382479264.229 [SCPI_on:TestDrive:Data] Running Loop=1
2013-10-22T22:01:04.229Z,1382479264.229 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-10-22T22:01:04.229Z,1382479264.229 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-10-22T22:01:04.230Z,1382479264.230 [SCPI_on:TestDrive:Data:A] Stopped
2013-10-22T22:01:04.230Z,1382479264.230 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-10-22T22:01:04.230Z,1382479264.230 [SCPI_on:TestDrive:A] Running Loop=1
2013-10-22T22:01:04.231Z,1382479264.231 [SCPI_on:TestDrive:A](DEBUG): Initialize ReadDataComponent to sense SCPI.sampleSCPI
2013-10-22T22:01:04.232Z,1382479264.232 [SCPI_on:A.Pitch] Running Loop=1
2013-10-22T22:01:04.597Z,1382479264.597 [SCPI](INFO): Powering up
2013-10-22T22:01:04.630Z,1382479264.630 [SCPI_on:TestDrive:Data:B] Stopped
2013-10-22T22:01:04.630Z,1382479264.630 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-10-22T22:01:04.631Z,1382479264.631 [SCPI_on:TestDrive:Data] Stopped
2013-10-22T22:01:04.631Z,1382479264.631 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-10-22T22:01:04.982Z,1382479264.982 [SCPI_on:TestDrive:Data] Running Loop=1
2013-10-22T22:01:04.982Z,1382479264.982 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-10-22T22:01:04.982Z,1382479264.982 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-10-22T22:01:04.983Z,1382479264.983 [SCPI_on:TestDrive:Data:A] Stopped
2013-10-22T22:01:04.983Z,1382479264.983 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-10-22T22:01:05.389Z,1382479265.389 [SCPI_on:TestDrive:Data:B] Stopped
2013-10-22T22:01:05.389Z,1382479265.389 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-10-22T22:01:05.389Z,1382479265.389 [SCPI_on:TestDrive:Data] Stopped
2013-10-22T22:01:05.389Z,1382479265.389 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-10-22T22:01:05.786Z,1382479265.786 [SCPI_on:TestDrive:Data] Running Loop=1
2013-10-22T22:01:05.787Z,1382479265.787 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-10-22T22:01:05.787Z,1382479265.787 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-10-22T22:01:05.787Z,1382479265.787 [SCPI_on:TestDrive:Data:A] Stopped
2013-10-22T22:01:05.787Z,1382479265.787 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-10-22T22:01:06.195Z,1382479266.195 [SCPI_on:TestDrive:Data:B] Stopped
2013-10-22T22:01:06.196Z,1382479266.196 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-10-22T22:01:06.196Z,1382479266.196 [SCPI_on:TestDrive:Data] Stopped
2013-10-22T22:01:06.196Z,1382479266.196 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-10-22T22:01:06.713Z,1382479266.713 [SCPI](INFO): Init failed - response: 
2013-10-22T22:01:06.713Z,1382479266.713 [SCPI](FAULT): SCPI failed to initialize
2013-10-22T22:01:06.713Z,1382479266.713 [SCPI] Communications Fault, FailCount= 1
2013-10-22T22:01:06.713Z,1382479266.713 [SCPI](ERROR): Communications Fault
2013-10-22T22:01:06.729Z,1382479266.729 [SCPI_on:TestDrive:Data] Running Loop=1
2013-10-22T22:01:06.729Z,1382479266.729 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-10-22T22:01:06.729Z,1382479266.729 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-10-22T22:01:06.730Z,1382479266.730 [SCPI_on:TestDrive:Data:A] Stopped
2013-10-22T22:01:06.730Z,1382479266.730 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-10-22T22:01:06.739Z,1382479266.739 [CBIT](ERROR): Communications Fault in component: SCPI
2013-10-22T22:01:07.020Z,1382479267.020 [SCPI](INFO): Powering down
2013-10-22T22:01:07.171Z,1382479267.171 [SCPI_on:TestDrive:Data:B] Stopped
2013-10-22T22:01:07.171Z,1382479267.171 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-10-22T22:01:07.171Z,1382479267.171 [SCPI_on:TestDrive:Data] Stopped
2013-10-22T22:01:07.171Z,1382479267.171 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-10-22T22:01:07.397Z,1382479267.397 [SCPI_on:TestDrive:Data] Running Loop=1
2013-10-22T22:01:07.398Z,1382479267.398 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-10-22T22:01:07.398Z,1382479267.398 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-10-22T22:01:07.398Z,1382479267.398 [SCPI_on:TestDrive:Data:A] Stopped
2013-10-22T22:01:07.398Z,1382479267.398 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-10-22T22:01:07.790Z,1382479267.790 [SCPI](INFO): Powering up
2013-10-22T22:01:07.823Z,1382479267.823 [SCPI_on:TestDrive:Data:B] Stopped
2013-10-22T22:01:07.823Z,1382479267.823 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-10-22T22:01:07.823Z,1382479267.823 [SCPI_on:TestDrive:Data] Stopped
2013-10-22T22:01:07.823Z,1382479267.823 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-10-22T22:01:07.837Z,1382479267.837 [CBIT](INFO): Clearing failed state for component SCPI
2013-10-22T22:01:07.837Z,1382479267.837 [SCPI] No Fault, FailCount= 1
2013-10-22T22:01:08.188Z,1382479268.188 [SCPI_on:TestDrive:Data] Running Loop=1
2013-10-22T22:01:08.189Z,1382479268.189 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-10-22T22:01:08.189Z,1382479268.189 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-10-22T22:01:08.189Z,1382479268.189 [SCPI_on:TestDrive:Data:A] Stopped
2013-10-22T22:01:08.189Z,1382479268.189 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-10-22T22:01:08.584Z,1382479268.584 [SCPI_on:TestDrive:Data:B] Stopped
2013-10-22T22:01:08.584Z,1382479268.584 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-10-22T22:01:08.584Z,1382479268.584 [SCPI_on:TestDrive:Data] Stopped
2013-10-22T22:01:08.584Z,1382479268.584 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-10-22T22:01:09.024Z,1382479269.024 [SCPI_on:TestDrive:Data] Running Loop=1
2013-10-22T22:01:09.024Z,1382479269.024 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-10-22T22:01:09.024Z,1382479269.024 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-10-22T22:01:09.025Z,1382479269.025 [SCPI_on:TestDrive:Data:A] Stopped
2013-10-22T22:01:09.025Z,1382479269.025 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-10-22T22:01:09.425Z,1382479269.425 [SCPI_on:TestDrive:Data:B] Stopped
2013-10-22T22:01:09.425Z,1382479269.425 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-10-22T22:01:09.426Z,1382479269.426 [SCPI_on:TestDrive:Data] Stopped
2013-10-22T22:01:09.426Z,1382479269.426 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-10-22T22:01:09.894Z,1382479269.894 [SCPI](INFO): Init failed - response: 
2013-10-22T22:01:09.894Z,1382479269.894 [SCPI](FAULT): SCPI failed to initialize
2013-10-22T22:01:09.894Z,1382479269.894 [SCPI] Communications Fault, FailCount= 2
2013-10-22T22:01:09.894Z,1382479269.894 [SCPI](ERROR): Communications Fault
2013-10-22T22:01:09.925Z,1382479269.925 [SCPI_on:TestDrive:Data] Running Loop=1
2013-10-22T22:01:09.925Z,1382479269.925 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-10-22T22:01:09.926Z,1382479269.926 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-10-22T22:01:09.926Z,1382479269.926 [SCPI_on:TestDrive:Data:A] Stopped
2013-10-22T22:01:09.926Z,1382479269.926 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-10-22T22:01:09.935Z,1382479269.935 [CBIT](ERROR): Communications Fault in component: SCPI
2013-10-22T22:01:10.178Z,1382479270.178 [SCPI](INFO): Powering down
2013-10-22T22:01:10.317Z,1382479270.317 [SCPI_on:TestDrive:Data:B] Stopped
2013-10-22T22:01:10.317Z,1382479270.317 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-10-22T22:01:10.317Z,1382479270.317 [SCPI_on:TestDrive:Data] Stopped
2013-10-22T22:01:10.317Z,1382479270.317 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-10-22T22:01:10.590Z,1382479270.590 [SCPI_on:TestDrive:Data] Running Loop=1
2013-10-22T22:01:10.590Z,1382479270.590 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-10-22T22:01:10.590Z,1382479270.590 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-10-22T22:01:10.591Z,1382479270.591 [SCPI_on:TestDrive:Data:A] Stopped
2013-10-22T22:01:10.591Z,1382479270.591 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-10-22T22:01:10.987Z,1382479270.987 [SCPI](INFO): Powering up
2013-10-22T22:01:11.007Z,1382479271.007 [SCPI_on:TestDrive:Data:B] Stopped
2013-10-22T22:01:11.007Z,1382479271.007 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-10-22T22:01:11.007Z,1382479271.007 [SCPI_on:TestDrive:Data] Stopped
2013-10-22T22:01:11.007Z,1382479271.007 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-10-22T22:01:11.045Z,1382479271.045 [CBIT](INFO): Clearing failed state for component SCPI
2013-10-22T22:01:11.045Z,1382479271.045 [SCPI] No Fault, FailCount= 2
2013-10-22T22:01:11.390Z,1382479271.390 [SCPI_on:TestDrive:Data] Running Loop=1
2013-10-22T22:01:11.390Z,1382479271.390 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-10-22T22:01:11.390Z,1382479271.390 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-10-22T22:01:11.390Z,1382479271.390 [SCPI_on:TestDrive:Data:A] Stopped
2013-10-22T22:01:11.390Z,1382479271.390 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-10-22T22:01:11.798Z,1382479271.798 [SCPI_on:TestDrive:Data:B] Stopped
2013-10-22T22:01:11.798Z,1382479271.798 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-10-22T22:01:11.798Z,1382479271.798 [SCPI_on:TestDrive:Data] Stopped
2013-10-22T22:01:11.798Z,1382479271.798 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-10-22T22:01:12.201Z,1382479272.201 [SCPI_on:TestDrive:Data] Running Loop=1
2013-10-22T22:01:12.201Z,1382479272.201 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-10-22T22:01:12.201Z,1382479272.201 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-10-22T22:01:12.202Z,1382479272.202 [SCPI_on:TestDrive:Data:A] Stopped
2013-10-22T22:01:12.202Z,1382479272.202 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-10-22T22:01:12.627Z,1382479272.627 [SCPI_on:TestDrive:Data:B] Stopped
2013-10-22T22:01:12.627Z,1382479272.627 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-10-22T22:01:12.627Z,1382479272.627 [SCPI_on:TestDrive:Data] Stopped
2013-10-22T22:01:12.627Z,1382479272.627 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-10-22T22:01:13.091Z,1382479273.091 [SCPI](INFO): Init failed - response: 
2013-10-22T22:01:13.091Z,1382479273.091 [SCPI](FAULT): SCPI failed to initialize
2013-10-22T22:01:13.091Z,1382479273.091 [SCPI] Communications Fault, FailCount= 3
2013-10-22T22:01:13.091Z,1382479273.091 [SCPI](ERROR): Communications Fault
2013-10-22T22:01:13.127Z,1382479273.127 [SCPI_on:TestDrive:Data] Running Loop=1
2013-10-22T22:01:13.127Z,1382479273.127 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-10-22T22:01:13.127Z,1382479273.127 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-10-22T22:01:13.128Z,1382479273.128 [SCPI_on:TestDrive:Data:A] Stopped
2013-10-22T22:01:13.128Z,1382479273.128 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-10-22T22:01:13.137Z,1382479273.137 [CBIT](ERROR): Communications Fault in component: SCPI
2013-10-22T22:01:13.137Z,1382479273.137 [CBIT](CRITICAL): Communications Fault in component: SCPI
2013-10-22T22:01:13.394Z,1382479273.394 [SCPI](INFO): Powering down
2013-10-22T22:01:13.524Z,1382479273.524 [SCPI_on:TestDrive:Data:B] Stopped
2013-10-22T22:01:13.524Z,1382479273.524 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-10-22T22:01:13.524Z,1382479273.524 [SCPI_on:TestDrive:Data] Stopped
2013-10-22T22:01:13.524Z,1382479273.524 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-10-22T22:01:13.533Z,1382479273.533 [CommandLine](FAULT): Scheduling is paused
2013-10-22T22:01:13.829Z,1382479273.829 [SCPI_on:TestDrive:Data] Running Loop=1
2013-10-22T22:01:13.829Z,1382479273.829 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-10-22T22:01:13.829Z,1382479273.829 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-10-22T22:01:13.830Z,1382479273.830 [SCPI_on:TestDrive:Data:A] Stopped
2013-10-22T22:01:13.830Z,1382479273.830 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-10-22T22:01:13.831Z,1382479273.831 [SCPI_on] Stopped
2013-10-22T22:01:13.831Z,1382479273.831 [SCPI_on](INFO): Aggregate::uninitialize SCPI_on
2013-10-22T22:01:13.831Z,1382479273.831 [SCPI_on:A.Pitch] Stopped
2013-10-22T22:01:13.831Z,1382479273.831 [SCPI_on:TestDrive] Stopped
2013-10-22T22:01:13.831Z,1382479273.831 [SCPI_on:TestDrive](INFO): Aggregate::uninitialize SCPI_on:TestDrive
2013-10-22T22:01:13.831Z,1382479273.831 [SCPI_on:TestDrive:A] Stopped
2013-10-22T22:01:13.831Z,1382479273.831 [SCPI_on:TestDrive:Data] Stopped
2013-10-22T22:01:13.831Z,1382479273.831 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-10-22T22:01:13.831Z,1382479273.831 [SCPI_on:TestDrive:Data:B] Stopped
2013-10-22T22:01:13.831Z,1382479273.831 [SCPI_on:TestDrive:C.Wait] Stopped
2013-10-22T22:01:13.831Z,1382479273.831 [SCPI_on:TestDrive:C.Wait](DEBUG): Uninitialize Wait Component.
2013-10-22T22:01:14.193Z,1382479274.193 [MissionManager](IMPORTANT): Started mission Default
2013-10-22T22:01:14.193Z,1382479274.193 [Default] Running Loop=1
2013-10-22T22:01:14.194Z,1382479274.194 [Default](INFO): Aggregate::initialize Default
2013-10-22T22:01:14.194Z,1382479274.194 [Default:D.SetSpeed] Running Loop=1
2013-10-22T22:01:14.194Z,1382479274.194 [Default:D.SetSpeed](DEBUG): Initialize.
2013-10-22T22:01:14.194Z,1382479274.194 [Default:E.GoToSurface] Running Loop=1
2013-10-22T22:01:14.194Z,1382479274.194 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-22T22:01:14.194Z,1382479274.194 [Default:Iridium] Running Loop=1
2013-10-22T22:01:14.194Z,1382479274.194 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2013-10-22T22:01:14.194Z,1382479274.194 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-10-22T22:01:14.194Z,1382479274.194 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2013-10-22T22:01:14.195Z,1382479274.195 [Default:Iridium:B.GoToSurface] Running Loop=1
2013-10-22T22:01:14.195Z,1382479274.195 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-22T22:01:14.196Z,1382479274.196 [Default:CallIridium] Running Loop=1
2013-10-22T22:01:14.196Z,1382479274.196 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2013-10-22T22:01:14.196Z,1382479274.196 [Default:CallIridium:A] Running Loop=1
2013-10-22T22:01:14.197Z,1382479274.197 [Default:CallIridium:A] Stopped
2013-10-22T22:01:14.197Z,1382479274.197 [Default:CallIridium:B] Running Loop=1
2013-10-22T22:01:14.197Z,1382479274.197 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2013-10-22T22:01:14.198Z,1382479274.198 [Default:Iridium:B.GoToSurface] Stopped
2013-10-22T22:01:14.198Z,1382479274.198 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-22T22:01:14.198Z,1382479274.198 [Default:Iridium:Read_Iridium] Running Loop=1
2013-10-22T22:01:14.198Z,1382479274.198 [Default:GPS] Running Loop=1
2013-10-22T22:01:14.198Z,1382479274.198 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2013-10-22T22:01:14.198Z,1382479274.198 [Default:GPS:A.SetSpeed] Running Loop=1
2013-10-22T22:01:14.198Z,1382479274.198 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2013-10-22T22:01:14.199Z,1382479274.199 [Default:GPS:B.GoToSurface] Running Loop=1
2013-10-22T22:01:14.199Z,1382479274.199 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-22T22:01:14.199Z,1382479274.199 [Default:GPS:B.GoToSurface] Stopped
2013-10-22T22:01:14.200Z,1382479274.200 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-22T22:01:14.200Z,1382479274.200 [Default:GPS:Read_GPS] Running Loop=1
2013-10-22T22:01:17.971Z,1382479277.971 [CommandLine](IMPORTANT): got command stop
2013-10-22T22:01:18.918Z,1382479278.918 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:01:23.245Z,1382479283.245 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:01:27.958Z,1382479287.958 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:01:31.993Z,1382479291.993 [CommandLine](IMPORTANT): got command restart application
2013-10-22T22:01:32.303Z,1382479292.303 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-22T22:01:33.198Z,1382479293.198 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2013-10-22T22:01:33.198Z,1382479293.198 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2013-10-22T22:01:33.282Z,1382479293.282 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2013-10-22T22:01:33.495Z,1382479293.495 [WetLabsBB2FL](INFO): Powering down
2013-10-22T22:01:33.515Z,1382479293.515 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2013-10-22T22:01:33.715Z,1382479293.715 [CTD_NeilBrown](INFO): Powering down
2013-10-22T22:01:33.727Z,1382479293.727 [ComponentRegistry](INFO): Shutting down DVL_micro ThreadHandler
2013-10-22T22:01:33.759Z,1382479293.759 [DVL_micro](INFO): uninitialize:Powering down
2013-10-22T22:01:33.767Z,1382479293.767 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2013-10-22T22:01:33.768Z,1382479293.768 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2013-10-22T22:01:33.769Z,1382479293.769 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2013-10-22T22:01:33.828Z,1382479293.828 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2013-10-22T22:01:33.829Z,1382479293.829 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2013-10-22T22:01:33.913Z,1382479293.913 [controlThread](DEBUG): Uninitializing ControlThread
2013-10-22T22:01:33.913Z,1382479293.913 [AHRS_sp3003D](INFO): Powering down
2013-10-22T22:01:33.000Z,1382479294.000 [NAL9602](INFO): Powering down
2013-10-22T22:01:34.092Z,1382479294.092 [DAT](INFO): Powering down
2013-10-22T22:01:34.094Z,1382479294.094 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-10-22T22:01:34.094Z,1382479294.094 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2013-10-22T22:01:34.096Z,1382479294.096 [Default] Stopped
2013-10-22T22:01:34.096Z,1382479294.096 [Default](INFO): Aggregate::uninitialize Default
2013-10-22T22:01:34.096Z,1382479294.096 [Default:GPS] Stopped
2013-10-22T22:01:34.096Z,1382479294.096 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2013-10-22T22:01:34.096Z,1382479294.096 [Default:GPS:A.SetSpeed] Stopped
2013-10-22T22:01:34.096Z,1382479294.096 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2013-10-22T22:01:34.096Z,1382479294.096 [Default:GPS:Read_GPS] Stopped
2013-10-22T22:01:34.096Z,1382479294.096 [Default:Iridium] Stopped
2013-10-22T22:01:34.096Z,1382479294.096 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2013-10-22T22:01:34.096Z,1382479294.096 [Default:Iridium:A.SetSpeed] Stopped
2013-10-22T22:01:34.097Z,1382479294.097 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2013-10-22T22:01:34.097Z,1382479294.097 [Default:Iridium:Read_Iridium] Stopped
2013-10-22T22:01:34.097Z,1382479294.097 [Default:CallIridium] Stopped
2013-10-22T22:01:34.097Z,1382479294.097 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2013-10-22T22:01:34.097Z,1382479294.097 [Default:CallIridium:B] Stopped
2013-10-22T22:01:34.097Z,1382479294.097 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2013-10-22T22:01:34.097Z,1382479294.097 [Default:D.SetSpeed] Stopped
2013-10-22T22:01:34.097Z,1382479294.097 [Default:D.SetSpeed](DEBUG): Uninitialize.
2013-10-22T22:01:34.097Z,1382479294.097 [Default:E.GoToSurface] Stopped
2013-10-22T22:01:34.097Z,1382479294.097 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-22T22:01:34.101Z,1382479294.101 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2013-10-22T22:01:34.102Z,1382479294.102 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2013-10-22T22:01:34.102Z,1382479294.102 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2013-10-22T22:01:34.102Z,1382479294.102 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2013-10-22T22:01:34.102Z,1382479294.102 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-10-22T22:01:34.103Z,1382479294.103 [BuoyancyServo](INFO): Powering down
2013-10-22T22:01:34.115Z,1382479294.115 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2013-10-22T22:01:34.116Z,1382479294.116 [ElevatorServo](INFO): Powering down
2013-10-22T22:01:34.116Z,1382479294.116 [MassServo](DEBUG): Uninitialize Mass Servo.
2013-10-22T22:01:34.117Z,1382479294.117 [MassServo](INFO): Powering down
2013-10-22T22:01:34.117Z,1382479294.117 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2013-10-22T22:01:34.118Z,1382479294.118 [RudderServo](INFO): Powering down
2013-10-22T22:01:34.118Z,1382479294.118 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2013-10-22T22:01:34.118Z,1382479294.118 [ThrusterServo](INFO): Powering down
2013-10-22T22:01:34.119Z,1382479294.119 [SBIT](DEBUG): Uninitialize SBIT Component.
2013-10-22T22:01:34.120Z,1382479294.120 [IBIT](DEBUG): Uninitialize IBIT Component.
2013-10-22T22:01:34.120Z,1382479294.120 [CBIT](DEBUG): Uninitialize CBIT Component.