2013-10-15T10:44:54.943Z,1381833894.943 [Supervisor](DEBUG): Initializing supervisor.
2013-10-15T10:44:54.943Z,1381833894.943 [SyncHandler](DEBUG): Created PCaller Thread at 2FB3F700
2013-10-15T10:44:54.943Z,1381833894.943 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2013-10-15T10:44:54.943Z,1381833894.943 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 2FADE700
2013-10-15T10:44:54.943Z,1381833894.943 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2013-10-15T10:44:54.944Z,1381833894.944 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2013-10-15T10:44:54.944Z,1381833894.944 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 2FA7D700
2013-10-15T10:44:54.944Z,1381833894.944 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2013-10-15T10:44:54.944Z,1381833894.944 [logger ThreadHandler](DEBUG): Created PCaller Thread at 2FA1C700
2013-10-15T10:44:54.944Z,1381833894.944 [Supervisor](INFO): Looking for Config files in directory: Config/
2013-10-15T10:44:54.944Z,1381833894.944 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2013-10-15T10:44:54.958Z,1381833894.958 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2013-10-15T10:44:54.958Z,1381833894.958 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2013-10-15T10:44:54.975Z,1381833894.975 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2013-10-15T10:44:54.975Z,1381833894.975 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2013-10-15T10:44:55.008Z,1381833895.008 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2013-10-15T10:44:55.008Z,1381833895.008 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2013-10-15T10:44:55.018Z,1381833895.018 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2013-10-15T10:44:55.032Z,1381833895.032 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2013-10-15T10:44:55.032Z,1381833895.032 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2013-10-15T10:44:55.046Z,1381833895.046 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2013-10-15T10:44:55.046Z,1381833895.046 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2013-10-15T10:44:55.068Z,1381833895.068 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2013-10-15T10:44:55.068Z,1381833895.068 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2013-10-15T10:44:55.079Z,1381833895.079 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2013-10-15T10:44:55.079Z,1381833895.079 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2013-10-15T10:44:55.090Z,1381833895.090 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2013-10-15T10:44:55.090Z,1381833895.090 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2013-10-15T10:44:55.100Z,1381833895.100 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2013-10-15T10:44:55.100Z,1381833895.100 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2013-10-15T10:44:55.114Z,1381833895.114 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2013-10-15T10:44:55.114Z,1381833895.114 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2013-10-15T10:44:55.124Z,1381833895.124 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2013-10-15T10:44:55.125Z,1381833895.125 [Supervisor](INFO): Looking for Config files in directory: Config/tethyssim/
2013-10-15T10:44:55.125Z,1381833895.125 [Supervisor](INFO): Looking for Config files in directory: Config/tethyssim/tethysadmin/
2013-10-15T10:44:55.125Z,1381833895.125 [Supervisor](INFO): Looking for Config files in directory: Config/sim/
2013-10-15T10:44:55.125Z,1381833895.125 [Supervisor](INFO): Opening Config file at: Config/sim/Science.cfg
2013-10-15T10:44:55.137Z,1381833895.137 [Supervisor](INFO): Opening Config file at: Config/sim/Simulator.cfg
2013-10-15T10:44:55.147Z,1381833895.147 [Supervisor](INFO): Opening Config file at: Config/sim/vehicle.cfg
2013-10-15T10:44:55.157Z,1381833895.157 [Supervisor](INFO): Opening Config file at: Config/sim/Servo.cfg
2013-10-15T10:44:55.168Z,1381833895.168 [Supervisor](INFO): Opening Config file at: Config/sim/Sensor.cfg
2013-10-15T10:44:55.179Z,1381833895.179 [Supervisor](INFO): Opening Config file at: Config/sim/Derivation.cfg
2013-10-15T10:44:55.189Z,1381833895.189 [Supervisor](INFO): Looking for Config files in directory: Config/sim/tethysadmin/
2013-10-15T10:44:55.189Z,1381833895.189 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2013-10-15T10:44:55.189Z,1381833895.189 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2013-10-15T10:44:55.191Z,1381833895.191 [VerticalControl](DEBUG): Construct VerticalControl.
2013-10-15T10:44:55.194Z,1381833895.194 [VerticalControl] Loaded
2013-10-15T10:44:55.194Z,1381833895.194 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2013-10-15T10:44:55.194Z,1381833895.194 [HorizontalControl](DEBUG): Construct HorizontalControl.
2013-10-15T10:44:55.195Z,1381833895.195 [HorizontalControl] Loaded
2013-10-15T10:44:55.195Z,1381833895.195 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2013-10-15T10:44:55.195Z,1381833895.195 [SpeedControl](DEBUG): Construct SpeedControl.
2013-10-15T10:44:55.195Z,1381833895.195 [SpeedControl] Loaded
2013-10-15T10:44:55.195Z,1381833895.195 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2013-10-15T10:44:55.195Z,1381833895.195 [LoopControl](DEBUG): Construct LoopControl.
2013-10-15T10:44:55.195Z,1381833895.195 [LoopControl] Loaded
2013-10-15T10:44:55.195Z,1381833895.195 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2013-10-15T10:44:55.195Z,1381833895.195 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2013-10-15T10:44:55.195Z,1381833895.195 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2013-10-15T10:44:55.196Z,1381833895.196 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2013-10-15T10:44:55.196Z,1381833895.196 [AsyncPiEstimator] Loaded
2013-10-15T10:44:55.196Z,1381833895.196 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2013-10-15T10:44:55.196Z,1381833895.196 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 2F37B700
2013-10-15T10:44:55.196Z,1381833895.196 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2013-10-15T10:44:55.196Z,1381833895.196 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2013-10-15T10:44:55.251Z,1381833895.251 [CTD_NeilBrown] Loaded
2013-10-15T10:44:55.251Z,1381833895.251 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2013-10-15T10:44:55.251Z,1381833895.251 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 2F0F4700
2013-10-15T10:44:55.251Z,1381833895.251 [ISUS] Loaded
2013-10-15T10:44:55.251Z,1381833895.251 [ComponentRegistry](DEBUG): SyncComponent "ISUS" handled in the control thread.
2013-10-15T10:44:55.252Z,1381833895.252 [PAR_Licor] Loaded
2013-10-15T10:44:55.252Z,1381833895.252 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2013-10-15T10:44:55.252Z,1381833895.252 [WetLabsBB2FL] Loaded
2013-10-15T10:44:55.252Z,1381833895.252 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2013-10-15T10:44:55.253Z,1381833895.253 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 2F093700
2013-10-15T10:44:55.253Z,1381833895.253 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2013-10-15T10:44:55.253Z,1381833895.253 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2013-10-15T10:44:55.258Z,1381833895.258 [ExternalSim] Loaded
2013-10-15T10:44:55.258Z,1381833895.258 [ComponentRegistry](DEBUG): SyncComponent "ExternalSim" handled in the control thread.
2013-10-15T10:44:55.259Z,1381833895.259 [InternalSim] Loaded
2013-10-15T10:44:55.259Z,1381833895.259 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2013-10-15T10:44:55.259Z,1381833895.259 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2013-10-15T10:44:55.259Z,1381833895.259 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2013-10-15T10:44:55.260Z,1381833895.260 [DepthRateCalculator] Loaded
2013-10-15T10:44:55.260Z,1381833895.260 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2013-10-15T10:44:55.289Z,1381833895.289 [HFRadarModelCalc] Loaded
2013-10-15T10:44:55.289Z,1381833895.289 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2013-10-15T10:44:55.289Z,1381833895.289 [NavChart] Loaded
2013-10-15T10:44:55.289Z,1381833895.289 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2013-10-15T10:44:55.289Z,1381833895.289 [PitchRateCalculator] Loaded
2013-10-15T10:44:55.289Z,1381833895.289 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2013-10-15T10:44:55.290Z,1381833895.290 [SpeedCalculator] Loaded
2013-10-15T10:44:55.290Z,1381833895.290 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2013-10-15T10:44:55.290Z,1381833895.290 [TempGradientCalculator] Loaded
2013-10-15T10:44:55.290Z,1381833895.290 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2013-10-15T10:44:55.290Z,1381833895.290 [YawRateCalculator] Loaded
2013-10-15T10:44:55.290Z,1381833895.290 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2013-10-15T10:44:55.291Z,1381833895.291 [Navigation] Loaded
2013-10-15T10:44:55.291Z,1381833895.291 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2013-10-15T10:44:55.291Z,1381833895.291 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2013-10-15T10:44:55.291Z,1381833895.291 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2013-10-15T10:44:55.292Z,1381833895.292 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2013-10-15T10:44:55.292Z,1381833895.292 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2013-10-15T10:44:55.296Z,1381833895.296 [AHRS_sp3003D] Loaded
2013-10-15T10:44:55.296Z,1381833895.296 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2013-10-15T10:44:55.296Z,1381833895.296 [Depth_Keller] Loaded
2013-10-15T10:44:55.296Z,1381833895.296 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2013-10-15T10:44:55.296Z,1381833895.296 [DropWeight] Loaded
2013-10-15T10:44:55.296Z,1381833895.296 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2013-10-15T10:44:55.301Z,1381833895.301 [DVL_micro] Loaded
2013-10-15T10:44:55.301Z,1381833895.301 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2013-10-15T10:44:55.301Z,1381833895.301 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 2E687700
2013-10-15T10:44:55.303Z,1381833895.303 [NAL9602] Loaded
2013-10-15T10:44:55.303Z,1381833895.303 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2013-10-15T10:44:55.304Z,1381833895.304 [Onboard] Loaded
2013-10-15T10:44:55.304Z,1381833895.304 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2013-10-15T10:44:55.304Z,1381833895.304 [Radio_Freewave] Loaded
2013-10-15T10:44:55.304Z,1381833895.304 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2013-10-15T10:44:55.308Z,1381833895.308 [DAT] Loaded
2013-10-15T10:44:55.308Z,1381833895.308 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2013-10-15T10:44:55.308Z,1381833895.308 [SCPI] Loaded
2013-10-15T10:44:55.308Z,1381833895.308 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2013-10-15T10:44:55.308Z,1381833895.308 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2013-10-15T10:44:55.308Z,1381833895.308 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2013-10-15T10:44:55.310Z,1381833895.310 [SBIT](DEBUG): Construct Startup Built In Test.
2013-10-15T10:44:55.310Z,1381833895.310 [SBIT] Loaded
2013-10-15T10:44:55.310Z,1381833895.310 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2013-10-15T10:44:55.310Z,1381833895.310 [IBIT](DEBUG): Construct Initiated Built In Test.
2013-10-15T10:44:55.311Z,1381833895.311 [IBIT] Loaded
2013-10-15T10:44:55.311Z,1381833895.311 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2013-10-15T10:44:55.311Z,1381833895.311 [CBIT](DEBUG): Construct CBIT Built In Test.
2013-10-15T10:44:55.314Z,1381833895.314 [CBIT] Loaded
2013-10-15T10:44:55.314Z,1381833895.314 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2013-10-15T10:44:55.314Z,1381833895.314 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2013-10-15T10:44:55.314Z,1381833895.314 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2013-10-15T10:44:55.317Z,1381833895.317 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2013-10-15T10:44:55.317Z,1381833895.317 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2013-10-15T10:44:55.319Z,1381833895.319 [BuoyancyServo] Loaded
2013-10-15T10:44:55.319Z,1381833895.319 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2013-10-15T10:44:55.319Z,1381833895.319 [ElevatorServo] Loaded
2013-10-15T10:44:55.319Z,1381833895.319 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2013-10-15T10:44:55.319Z,1381833895.319 [MassServo] Loaded
2013-10-15T10:44:55.319Z,1381833895.319 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2013-10-15T10:44:55.320Z,1381833895.320 [RudderServo] Loaded
2013-10-15T10:44:55.320Z,1381833895.320 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2013-10-15T10:44:55.320Z,1381833895.320 [ThrusterServo] Loaded
2013-10-15T10:44:55.320Z,1381833895.320 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2013-10-15T10:44:55.320Z,1381833895.320 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2013-10-15T10:44:55.320Z,1381833895.320 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2013-10-15T10:44:55.320Z,1381833895.320 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2013-10-15T10:44:55.320Z,1381833895.320 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2013-10-15T10:44:55.320Z,1381833895.320 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 2DF7F700
2013-10-15T10:44:55.322Z,1381833895.322 [Supervisor](DEBUG): Running supervisor.
2013-10-15T10:44:55.323Z,1381833895.323 [logger](INFO): Thread ID is 10491
2013-10-15T10:44:55.323Z,1381833895.323 [AsyncPiEstimator](INFO): Thread ID is 10546
2013-10-15T10:44:55.323Z,1381833895.323 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2013-10-15T10:44:55.324Z,1381833895.324 [CTD_NeilBrown](INFO): Thread ID is 10547
2013-10-15T10:44:55.324Z,1381833895.324 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2013-10-15T10:44:55.324Z,1381833895.324 [WetLabsBB2FL](INFO): Thread ID is 10548
2013-10-15T10:44:55.324Z,1381833895.324 [DVL_micro](INFO): Thread ID is 10549
2013-10-15T10:44:55.325Z,1381833895.325 [NavChartDb](INFO): Thread ID is 10550
2013-10-15T10:44:55.325Z,1381833895.325 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2013-10-15T10:44:55.325Z,1381833895.325 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2013-10-15T10:44:55.325Z,1381833895.325 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2013-10-15T10:44:55.325Z,1381833895.325 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2013-10-15T10:44:55.325Z,1381833895.325 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2013-10-15T10:44:55.325Z,1381833895.325 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2013-10-15T10:44:55.325Z,1381833895.325 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2013-10-15T10:44:55.325Z,1381833895.325 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2013-10-15T10:44:55.325Z,1381833895.325 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2013-10-15T10:44:55.327Z,1381833895.327 [CommandLine](INFO): Thread ID is 10490
2013-10-15T10:44:55.327Z,1381833895.327 [controlThread](INFO): Thread ID is 10489
2013-10-15T10:44:55.327Z,1381833895.327 [controlThread](DEBUG): Initializing ControlThread
2013-10-15T10:44:55.327Z,1381833895.327 [CycleStarter](INFO): Thread ID is 10488
2013-10-15T10:44:55.327Z,1381833895.327 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2013-10-15T10:44:55.328Z,1381833895.328 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2013-10-15T10:44:55.328Z,1381833895.328 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2013-10-15T10:44:55.328Z,1381833895.328 [LoopControl](DEBUG): Initialize LoopControlComponent.
2013-10-15T10:44:55.328Z,1381833895.328 [ExternalSim](INFO): ExternalSim initializing...
2013-10-15T10:44:55.329Z,1381833895.329 [ExternalSim](DEBUG): beaconLat = 36.81340
2013-10-15T10:44:55.329Z,1381833895.329 [ExternalSim](DEBUG): beaconLon = -121.82240
2013-10-15T10:44:55.329Z,1381833895.329 [ExternalSim](DEBUG): beaconDepth = 25.00
2013-10-15T10:44:55.329Z,1381833895.329 [DVL_micro](INFO): pause:Powering down
2013-10-15T10:44:55.330Z,1381833895.330 [ExternalSim](DEBUG): Simulator initialized
2013-10-15T10:44:55.330Z,1381833895.330 [InternalSim](DEBUG):  InternalSim initializing...
2013-10-15T10:44:55.331Z,1381833895.331 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-10-15T10:44:55.331Z,1381833895.331 [NavChart](DEBUG): Initialize NavChart Derivation.
2013-10-15T10:44:55.331Z,1381833895.331 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2013-10-15T10:44:55.331Z,1381833895.331 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2013-10-15T10:44:55.331Z,1381833895.331 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2013-10-15T10:44:55.331Z,1381833895.331 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2013-10-15T10:44:55.331Z,1381833895.331 [Navigation](DEBUG): Initializing Navigation.
2013-10-15T10:44:55.331Z,1381833895.331 [SBIT](INFO): Initialize SBIT Component.
2013-10-15T10:44:55.331Z,1381833895.331 [SBIT](IMPORTANT): Tethys CM Info: 
$Rev:10503
2013-10-15T10:44:55.331Z,1381833895.331 [SBIT](FAULT): Kernel Reporting Different Release From Configuration. Expected:2.6.32-45-generic-pae
Kernel Reported:2.6.32-358.18.1.el6.x86_64
2013-10-15T10:44:55.331Z,1381833895.331 [SBIT](FAULT): Kernel Reporting Different Version From Configuration.
Expected:#102-Ubuntu SMP Wed Jan 2 22:10:16 UTC 2013
Kernel Reported:#1 SMP Wed Aug 28 17:19:38 UTC 2013
2013-10-15T10:44:55.331Z,1381833895.331 [IBIT](INFO): Initialize IBIT Component.
2013-10-15T10:44:55.332Z,1381833895.332 [CBIT](DEBUG): Initialize CBIT Component.
2013-10-15T10:44:55.332Z,1381833895.332 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2013-10-15T10:44:55.332Z,1381833895.332 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2013-10-15T10:44:55.334Z,1381833895.334 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2013-10-15T10:44:55.335Z,1381833895.335 [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-15T10:44:55.335Z,1381833895.335 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2013-10-15T10:44:55.335Z,1381833895.335 [Default:A.Execute](DEBUG): Construct Execute.
2013-10-15T10:44:55.336Z,1381833895.336 [MissionManager](DEBUG): 
<Mission Id='Default'><Guidance:Execute RunIn='Sequence'><Setting><Guidance:Execute.command/><String>quit</String></Setting></Guidance:Execute></Mission>


2013-10-15T10:44:55.336Z,1381833895.336 [controlThread](DEBUG): Component order: CycleStarter,ExternalSim,InternalSim,ISUS,PAR_Licor,AHRS_sp3003D,Depth_Keller,DropWeight,NAL9602,Onboard,Radio_Freewave,DAT,SCPI,PAR_Licor,Depth_Keller,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,
2013-10-15T10:44:55.347Z,1381833895.347 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-10-15T10:44:55.347Z,1381833895.347 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2013-10-15T10:44:55.349Z,1381833895.349 [MassServo](DEBUG): Initializing MassServo.
2013-10-15T10:44:55.349Z,1381833895.349 [RudderServo](DEBUG): Initializing RudderServo.
2013-10-15T10:44:55.350Z,1381833895.350 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-10-15T10:44:55.381Z,1381833895.381 [CommandLine](IMPORTANT): got command load ./Missions/Demo/Circle.xml
2013-10-15T10:44:55.381Z,1381833895.381 [MissionManager](INFO): Loading Mission: ./Missions/Demo/Circle.xml
2013-10-15T10:44:55.382Z,1381833895.382 [TestMission:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2013-10-15T10:44:55.382Z,1381833895.382 [TestMission:B.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2013-10-15T10:44:55.382Z,1381833895.382 [TestMission:C.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2013-10-15T10:44:55.383Z,1381833895.383 [MissionManager](INFO): Inserting Stack: Missions/Insert/Surface.xml
2013-10-15T10:44:55.384Z,1381833895.384 [MissionManager](INFO): DefineArg TestMission:SurfaceOps.SurfaceDepthRate = nan m/s
2013-10-15T10:44:55.384Z,1381833895.384 [MissionManager](INFO): DefineArg TestMission:SurfaceOps.SurfacePitch = nan arcdeg
2013-10-15T10:44:55.384Z,1381833895.384 [MissionManager](INFO): DefineArg TestMission:SurfaceOps.SurfaceSpeed = 0.500000 m/s
2013-10-15T10:44:55.384Z,1381833895.384 [MissionManager](INFO): DefineArg TestMission:SurfaceOps.IridiumTimeout = 30.000000 min
2013-10-15T10:44:55.384Z,1381833895.384 [MissionManager](INFO): DefineArg TestMission:SurfaceOps.UnpackSplitAtSurface = 0 bool
2013-10-15T10:44:55.384Z,1381833895.384 [TestMission:SurfaceOps:A.GoToSurface](DEBUG): Construct GoToSurface.
2013-10-15T10:44:55.384Z,1381833895.384 [TestMission:SpiralAggregate:A.SetSpeed](DEBUG): Construct.
2013-10-15T10:44:55.384Z,1381833895.384 [TestMission:SpiralAggregate:B.YoYo](DEBUG): Construct YoYo.
2013-10-15T10:44:55.384Z,1381833895.384 [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="TestMission">

<!-- some high priority behaviors -->

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

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

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

<!-- Initial GPS (and Iridium) Update -->

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

    <Aggregate Id="SpiralAggregate">

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

        <Guidance:YoYo RunIn="Parallel"/>

        <CustomBehavior Name="SpiralCommand" RunIn="Sequence">
            <Timeout Duration="P120M30S"></Timeout>
            <Initialize>
                <Input Name="latitude"><Universal:latitude/><Units:degree/><DefaultValue>NaN</DefaultValue></Input>
                <Input Name="longitude"><Universal:longitude/><Units:degree/><DefaultValue>NaN</DefaultValue></Input>
                <Test InputValue="36.0 -122"/>
                <Script Language="Lua"><![CDATA[
                        i = 0;
                        origLat = latitude;
                        origLon = longitude;
                        goalLat = (math.sin(i) * 0.005) + origLat;
                        goalLon = (math.cos(i) * 0.005) + origLon;
                    ]]></Script>
            </Initialize>
            <Run>
                <Input Name="latitude"><Universal:latitude/><Units:degree/><DefaultValue>NaN</DefaultValue></Input>
                <Input Name="longitude"><Universal:longitude/><Units:degree/><DefaultValue>NaN</DefaultValue></Input>
                <Output><Control:HorizontalControl.horizontalMode/><Units:enum/></Output>
                <Output><Control:HorizontalControl.latitudeCmd/><Units:degree/></Output>
                <Output><Control:HorizontalControl.longitudeCmd/><Units:degree/></Output>
                <Test OutputValue="1.0 36.0 -122.0"/>
                <Script Language="Lua"><![CDATA[
                        diffLat = math.abs(goalLat - latitude);
                        diffLon = math.abs(goalLon - longitude);
                        if diffLat <= 0.0001 and diffLon <= 0.0001 then
                            i = (i + 0.2) % (2 * math.pi);
                            goalLat = (math.sin(i) * 0.005) + origLat;
                            goalLon = (math.cos(i) * 0.005) + origLon;
                        end                         
                        return 1.0, goalLat, goalLon;
                     ]]></Script>
            </Run>
        </CustomBehavior>

    </Aggregate>

<!-- end of STACK -->

</Mission>


2013-10-15T10:44:55.385Z,1381833895.385 [CommandLine](IMPORTANT): Loaded ./Missions/Demo/Circle.xml
2013-10-15T10:44:55.427Z,1381833895.427 [CommandLine](IMPORTANT): got command run quitatend
2013-10-15T10:44:55.429Z,1381833895.429 [CommandLine](IMPORTANT): Running 
2013-10-15T10:44:55.727Z,1381833895.727 [CTD_NeilBrown](ERROR): Salinity reading out of range: 33.438362 psu
2013-10-15T10:44:55.727Z,1381833895.727 [CTD_NeilBrown](ERROR): Pressure reading out of range: 0.000000 decibar
2013-10-15T10:45:04.937Z,1381833904.937 [NAL9602](IMPORTANT): GPS fix at: 1381833904.93
2013-10-15T10:45:10.937Z,1381833910.937 [NAL9602](INFO): Powering down
2013-10-15T10:45:10.939Z,1381833910.939 [SBIT](IMPORTANT): Beginning Startup BIT
2013-10-15T10:46:04.937Z,1381833964.937 [SBIT](IMPORTANT): SBIT PASSED
2013-10-15T10:46:05.336Z,1381833965.336 [MissionManager](IMPORTANT): Started mission Startup
2013-10-15T10:46:05.336Z,1381833965.336 [Startup] Running Loop=1
2013-10-15T10:46:05.336Z,1381833965.336 [Startup](INFO): Aggregate::initialize Startup
2013-10-15T10:46:05.336Z,1381833965.336 [Startup:A.GoToSurface] Running Loop=1
2013-10-15T10:46:05.336Z,1381833965.336 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-15T10:46:05.337Z,1381833965.337 [Startup:StartupSatComms] Running Loop=1
2013-10-15T10:46:05.337Z,1381833965.337 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2013-10-15T10:46:05.337Z,1381833965.337 [Startup:StartupSatComms:A] Running Loop=1
2013-10-15T10:46:05.736Z,1381833965.736 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-10-15T10:46:06.137Z,1381833966.137 [NAL9602](INFO): Powering up
2013-10-15T10:46:11.337Z,1381833971.337 [NAL9602](IMPORTANT): GPS fix at: 1381833971.33
2013-10-15T10:46:11.337Z,1381833971.337 [Startup:StartupSatComms:A] Stopped
2013-10-15T10:46:11.337Z,1381833971.337 [Startup:StartupSatComms:B] Running Loop=1
2013-10-15T10:46:11.738Z,1381833971.738 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-10-15T10:46:14.136Z,1381833974.136 [NAL9602](INFO): Sent 209 bytes from file Logs/20131015T104454/Courier0000.lzma
2013-10-15T10:46:14.136Z,1381833974.136 [NAL9602](INFO): Packets left to send: 0
2013-10-15T10:46:14.139Z,1381833974.139 [NAL9602](INFO): Stored copy of sent data in Logs/20131015T104454/Courier0000.lzma.parts/0000.sbd
2013-10-15T10:46:15.336Z,1381833975.336 [NAL9602](INFO): Sent 332 bytes from file Logs/20131015T104454/Express0001.lzma
2013-10-15T10:46:15.336Z,1381833975.336 [NAL9602](INFO): Packets left to send: 2
2013-10-15T10:46:15.339Z,1381833975.339 [NAL9602](INFO): Stored copy of sent data in Logs/20131015T104454/Express0001.lzma.parts/0002.sbd
2013-10-15T10:46:16.536Z,1381833976.536 [NAL9602](INFO): Sent 332 bytes from file Logs/20131015T104454/Express0001.lzma
2013-10-15T10:46:16.536Z,1381833976.536 [NAL9602](INFO): Packets left to send: 1
2013-10-15T10:46:16.538Z,1381833976.538 [NAL9602](INFO): Stored copy of sent data in Logs/20131015T104454/Express0001.lzma.parts/0001.sbd
2013-10-15T10:46:17.736Z,1381833977.736 [NAL9602](INFO): Sent 38 bytes from file Logs/20131015T104454/Express0001.lzma
2013-10-15T10:46:17.736Z,1381833977.736 [NAL9602](INFO): Packets left to send: 0
2013-10-15T10:46:17.739Z,1381833977.739 [NAL9602](INFO): Stored copy of sent data in Logs/20131015T104454/Express0001.lzma.parts/0000.sbd
2013-10-15T10:46:18.536Z,1381833978.536 [Startup:StartupSatComms:B] Stopped
2013-10-15T10:46:18.536Z,1381833978.536 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2013-10-15T10:46:18.536Z,1381833978.536 [Startup:StartupSatComms] Stopped
2013-10-15T10:46:18.536Z,1381833978.536 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2013-10-15T10:46:18.536Z,1381833978.536 [Startup](INFO): Completed Startup
2013-10-15T10:46:18.536Z,1381833978.536 [Startup] Stopped
2013-10-15T10:46:18.536Z,1381833978.536 [Startup](INFO): Aggregate::uninitialize Startup
2013-10-15T10:46:18.536Z,1381833978.536 [Startup:A.GoToSurface] Stopped
2013-10-15T10:46:18.536Z,1381833978.536 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-15T10:46:18.936Z,1381833978.936 [MissionManager](IMPORTANT): Started mission TestMission
2013-10-15T10:46:18.936Z,1381833978.936 [TestMission] Running Loop=1
2013-10-15T10:46:18.936Z,1381833978.936 [TestMission](INFO): Aggregate::initialize TestMission
2013-10-15T10:46:18.936Z,1381833978.936 [TestMission:A.AltitudeEnvelope] Running Loop=1
2013-10-15T10:46:18.936Z,1381833978.936 [TestMission:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2013-10-15T10:46:18.936Z,1381833978.936 [TestMission:B.OffshoreEnvelope] Running Loop=1
2013-10-15T10:46:18.936Z,1381833978.936 [TestMission:B.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2013-10-15T10:46:18.936Z,1381833978.936 [TestMission:C.DepthEnvelope] Running Loop=1
2013-10-15T10:46:18.936Z,1381833978.936 [TestMission:C.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2013-10-15T10:46:18.936Z,1381833978.936 [TestMission:SurfaceOps] Running Loop=1
2013-10-15T10:46:18.936Z,1381833978.936 [TestMission:SurfaceOps](INFO): Aggregate::initialize TestMission:SurfaceOps
2013-10-15T10:46:18.936Z,1381833978.936 [TestMission:SurfaceOps:A.GoToSurface] Running Loop=1
2013-10-15T10:46:18.936Z,1381833978.936 [TestMission:SurfaceOps:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-15T10:46:18.936Z,1381833978.936 [TestMission:SurfaceOps:B] Running Loop=1
2013-10-15T10:46:18.936Z,1381833978.936 [TestMission:SurfaceOps:B](INFO): Aggregate::initialize TestMission:SurfaceOps:B
2013-10-15T10:46:18.936Z,1381833978.936 [TestMission:SurfaceOps:B:A] Running Loop=1
2013-10-15T10:46:18.936Z,1381833978.936 [TestMission:C.DepthEnvelope] Running Loop=1
2013-10-15T10:46:18.937Z,1381833978.937 [TestMission:B.OffshoreEnvelope] Running Loop=1
2013-10-15T10:46:18.937Z,1381833978.937 [TestMission:A.AltitudeEnvelope] Running Loop=1
2013-10-15T10:46:19.336Z,1381833979.336 [TestMission:SurfaceOps:B] Stopped
2013-10-15T10:46:19.336Z,1381833979.336 [TestMission:SurfaceOps:B](INFO): Aggregate::uninitialize TestMission:SurfaceOps:B
2013-10-15T10:46:19.336Z,1381833979.336 [TestMission:SurfaceOps:B:A] Stopped
2013-10-15T10:46:19.336Z,1381833979.336 [TestMission:SurfaceOps:C] Running Loop=1
2013-10-15T10:46:19.336Z,1381833979.336 [TestMission:SurfaceOps:C](INFO): Aggregate::initialize TestMission:SurfaceOps:C
2013-10-15T10:46:19.336Z,1381833979.336 [TestMission:SurfaceOps:C:A] Running Loop=1
2013-10-15T10:46:19.737Z,1381833979.737 [TestMission:SurfaceOps:C:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-10-15T10:46:24.136Z,1381833984.136 [NAL9602](IMPORTANT): GPS fix at: 1381833984.13
2013-10-15T10:46:24.136Z,1381833984.136 [TestMission:SurfaceOps:C:A] Stopped
2013-10-15T10:46:24.136Z,1381833984.136 [TestMission:SurfaceOps:C:B] Running Loop=1
2013-10-15T10:46:24.537Z,1381833984.537 [TestMission:SurfaceOps:C:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-10-15T10:46:25.762Z,1381833985.762 [DVL_micro](INFO): NQ1 requested
2013-10-15T10:46:25.762Z,1381833985.762 [DVL_micro](INFO): resume:Powering up
2013-10-15T10:46:25.762Z,1381833985.762 [DVL_micro](INFO): Cycling power to configure device.
2013-10-15T10:46:26.937Z,1381833986.937 [NAL9602](INFO): Sent 60 bytes from file Logs/20131015T104454/Courier0004.lzma
2013-10-15T10:46:26.937Z,1381833986.937 [NAL9602](INFO): Packets left to send: 0
2013-10-15T10:46:26.940Z,1381833986.940 [NAL9602](INFO): Stored copy of sent data in Logs/20131015T104454/Courier0004.lzma.parts/0000.sbd
2013-10-15T10:46:28.137Z,1381833988.137 [NAL9602](INFO): Sent 127 bytes from file Logs/20131015T104454/Express0005.lzma
2013-10-15T10:46:28.137Z,1381833988.137 [NAL9602](INFO): Packets left to send: 0
2013-10-15T10:46:28.140Z,1381833988.140 [NAL9602](INFO): Stored copy of sent data in Logs/20131015T104454/Express0005.lzma.parts/0000.sbd
2013-10-15T10:46:28.937Z,1381833988.937 [TestMission:SurfaceOps:C:B] Stopped
2013-10-15T10:46:28.937Z,1381833988.937 [TestMission:SurfaceOps:C:C] Running Loop=1
2013-10-15T10:46:29.337Z,1381833989.337 [TestMission:SurfaceOps:C:C](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-10-15T10:46:34.137Z,1381833994.137 [NAL9602](IMPORTANT): GPS fix at: 1381833994.13
2013-10-15T10:46:34.137Z,1381833994.137 [TestMission:SurfaceOps:C:C] Stopped
2013-10-15T10:46:34.137Z,1381833994.137 [TestMission:SurfaceOps:C](INFO): Completed TestMission:SurfaceOps:C
2013-10-15T10:46:34.137Z,1381833994.137 [TestMission:SurfaceOps:C] Stopped
2013-10-15T10:46:34.137Z,1381833994.137 [TestMission:SurfaceOps:C](INFO): Aggregate::uninitialize TestMission:SurfaceOps:C
2013-10-15T10:46:34.137Z,1381833994.137 [TestMission:SurfaceOps](INFO): Completed TestMission:SurfaceOps
2013-10-15T10:46:34.137Z,1381833994.137 [TestMission:SurfaceOps] Stopped
2013-10-15T10:46:34.137Z,1381833994.137 [TestMission:SurfaceOps](INFO): Aggregate::uninitialize TestMission:SurfaceOps
2013-10-15T10:46:34.137Z,1381833994.137 [TestMission:SurfaceOps:A.GoToSurface] Stopped
2013-10-15T10:46:34.137Z,1381833994.137 [TestMission:SurfaceOps:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-15T10:46:34.137Z,1381833994.137 [TestMission:SpiralAggregate] Running Loop=1
2013-10-15T10:46:34.137Z,1381833994.137 [TestMission:SpiralAggregate](INFO): Aggregate::initialize TestMission:SpiralAggregate
2013-10-15T10:46:34.137Z,1381833994.137 [TestMission:SpiralAggregate:A.SetSpeed] Running Loop=1
2013-10-15T10:46:34.137Z,1381833994.137 [TestMission:SpiralAggregate:A.SetSpeed](DEBUG): Initialize.
2013-10-15T10:46:34.137Z,1381833994.137 [TestMission:SpiralAggregate:B.YoYo] Running Loop=1
2013-10-15T10:46:34.137Z,1381833994.137 [TestMission:SpiralAggregate:B.YoYo](DEBUG): Initialize YoYoComponent.
2013-10-15T10:46:34.137Z,1381833994.137 [TestMission:SpiralAggregate:C.SpiralCommand] Running Loop=1
2013-10-15T10:46:34.137Z,1381833994.137 [TestMission:SpiralAggregate:C.SpiralCommand](INFO): Initialize
2013-10-15T10:46:34.537Z,1381833994.537 [TestMission:SpiralAggregate:B.YoYo] Running Loop=1
2013-10-15T10:46:34.537Z,1381833994.537 [TestMission:SpiralAggregate:A.SetSpeed] Running Loop=1
2013-10-15T10:46:40.137Z,1381834000.137 [NAL9602](INFO): Powering down
2013-10-15T10:59:24.537Z,1381834764.537 [DVL_micro](INFO): Querying output modes
2013-10-15T10:59:24.537Z,1381834764.537 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-10-15T10:59:24.537Z,1381834764.537 [DVL_micro](INFO): NQ1 output enabled
2013-10-15T10:59:24.537Z,1381834764.537 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:SpiralAggregate:C.SpiralCommand](INFO): Timed out from 2013-10-15T10:46:34.1Z
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:SpiralAggregate:C.SpiralCommand:A_Timeout] Running Loop=1
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:SpiralAggregate:C.SpiralCommand:A_Timeout](INFO): Aggregate::initialize TestMission:SpiralAggregate:C.SpiralCommand:A_Timeout
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:SpiralAggregate:C.SpiralCommand:A_Timeout](INFO): Completed TestMission:SpiralAggregate:C.SpiralCommand:A_Timeout
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:SpiralAggregate:C.SpiralCommand] Stopped
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:SpiralAggregate:C.SpiralCommand](INFO): Uninitialize
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:SpiralAggregate](INFO): Completed TestMission:SpiralAggregate
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:SpiralAggregate] Stopped
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:SpiralAggregate](INFO): Aggregate::uninitialize TestMission:SpiralAggregate
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:SpiralAggregate:A.SetSpeed] Stopped
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:SpiralAggregate:A.SetSpeed](DEBUG): Uninitialize.
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:SpiralAggregate:B.YoYo] Stopped
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:SpiralAggregate:B.YoYo](DEBUG): Uninitialize YoYoComponent.
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission](INFO): Completed TestMission
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission] Stopped
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission](INFO): Aggregate::uninitialize TestMission
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:A.AltitudeEnvelope] Stopped
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:B.OffshoreEnvelope] Stopped
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:B.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:C.DepthEnvelope] Stopped
2013-10-15T12:47:04.536Z,1381841224.536 [TestMission:C.DepthEnvelope](DEBUG): Uninitialize.
2013-10-15T12:47:04.537Z,1381841224.537 [DVL_micro](INFO): pause:Powering down
2013-10-15T12:47:04.552Z,1381841224.552 [CommandLine](IMPORTANT): got command quit
2013-10-15T12:47:04.938Z,1381841224.938 [MissionManager](IMPORTANT): Started mission Default
2013-10-15T12:47:04.938Z,1381841224.938 [Default] Running Loop=1
2013-10-15T12:47:04.938Z,1381841224.938 [Default](INFO): Aggregate::initialize Default
2013-10-15T12:47:04.938Z,1381841224.938 [Default:A.Execute] Running Loop=1
2013-10-15T12:47:04.938Z,1381841224.938 [Default:A.Execute](INFO): Executing command quit
2013-10-15T12:47:04.938Z,1381841224.938 [Default:A.Execute] Stopped
2013-10-15T12:47:04.938Z,1381841224.938 [Default](INFO): Completed Default
2013-10-15T12:47:04.938Z,1381841224.938 [Default] Stopped
2013-10-15T12:47:04.938Z,1381841224.938 [Default](INFO): Aggregate::uninitialize Default
2013-10-15T12:47:05.338Z,1381841225.338 [MissionManager](IMPORTANT): Started mission Default
2013-10-15T12:47:05.338Z,1381841225.338 [Default] Running Loop=1
2013-10-15T12:47:05.338Z,1381841225.338 [Default](INFO): Aggregate::initialize Default
2013-10-15T12:47:05.338Z,1381841225.338 [Default:A.Execute] Running Loop=1
2013-10-15T12:47:05.338Z,1381841225.338 [Default:A.Execute](INFO): Executing command quit
2013-10-15T12:47:05.338Z,1381841225.338 [Default:A.Execute] Stopped
2013-10-15T12:47:05.338Z,1381841225.338 [Default](INFO): Completed Default
2013-10-15T12:47:05.338Z,1381841225.338 [Default] Stopped
2013-10-15T12:47:05.338Z,1381841225.338 [Default](INFO): Aggregate::uninitialize Default
2013-10-15T12:47:05.592Z,1381841225.592 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2013-10-15T12:47:05.592Z,1381841225.592 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2013-10-15T12:47:05.737Z,1381841225.737 [MissionManager](IMPORTANT): Started mission Default
2013-10-15T12:47:05.737Z,1381841225.737 [Default] Running Loop=1
2013-10-15T12:47:05.737Z,1381841225.737 [Default](INFO): Aggregate::initialize Default
2013-10-15T12:47:05.737Z,1381841225.737 [Default:A.Execute] Running Loop=1
2013-10-15T12:47:05.737Z,1381841225.737 [Default:A.Execute](INFO): Executing command quit
2013-10-15T12:47:05.738Z,1381841225.738 [Default:A.Execute] Stopped
2013-10-15T12:47:05.738Z,1381841225.738 [Default](INFO): Completed Default
2013-10-15T12:47:05.738Z,1381841225.738 [Default] Stopped
2013-10-15T12:47:05.738Z,1381841225.738 [Default](INFO): Aggregate::uninitialize Default
2013-10-15T12:47:05.753Z,1381841225.753 [ComponentRegistry](INFO): Shutting down DVL_micro ThreadHandler
2013-10-15T12:47:06.137Z,1381841226.137 [MissionManager](IMPORTANT): Started mission Default
2013-10-15T12:47:06.137Z,1381841226.137 [Default] Running Loop=1
2013-10-15T12:47:06.137Z,1381841226.137 [Default](INFO): Aggregate::initialize Default
2013-10-15T12:47:06.137Z,1381841226.137 [Default:A.Execute] Running Loop=1
2013-10-15T12:47:06.137Z,1381841226.137 [Default:A.Execute](INFO): Executing command quit
2013-10-15T12:47:06.137Z,1381841226.137 [Default:A.Execute] Stopped
2013-10-15T12:47:06.137Z,1381841226.137 [Default](INFO): Completed Default
2013-10-15T12:47:06.137Z,1381841226.137 [Default] Stopped
2013-10-15T12:47:06.137Z,1381841226.137 [Default](INFO): Aggregate::uninitialize Default
2013-10-15T12:47:06.138Z,1381841226.138 [DVL_micro](INFO): uninitialize:Powering down
2013-10-15T12:47:06.155Z,1381841226.155 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2013-10-15T12:47:06.175Z,1381841226.175 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2013-10-15T12:47:06.336Z,1381841226.336 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2013-10-15T12:47:06.537Z,1381841226.537 [MissionManager](IMPORTANT): Started mission Default
2013-10-15T12:47:06.537Z,1381841226.537 [Default] Running Loop=1
2013-10-15T12:47:06.537Z,1381841226.537 [Default](INFO): Aggregate::initialize Default
2013-10-15T12:47:06.537Z,1381841226.537 [Default:A.Execute] Running Loop=1
2013-10-15T12:47:06.537Z,1381841226.537 [Default:A.Execute](INFO): Executing command quit
2013-10-15T12:47:06.538Z,1381841226.538 [Default:A.Execute] Stopped
2013-10-15T12:47:06.538Z,1381841226.538 [Default](INFO): Completed Default
2013-10-15T12:47:06.538Z,1381841226.538 [Default] Stopped
2013-10-15T12:47:06.538Z,1381841226.538 [Default](INFO): Aggregate::uninitialize Default
2013-10-15T12:47:06.603Z,1381841226.603 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2013-10-15T12:47:06.618Z,1381841226.618 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2013-10-15T12:47:06.638Z,1381841226.638 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2013-10-15T12:47:06.658Z,1381841226.658 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2013-10-15T12:47:06.936Z,1381841226.936 [controlThread](DEBUG): Uninitializing ControlThread
2013-10-15T12:47:06.936Z,1381841226.936 [NAL9602](INFO): Powering down
2013-10-15T12:47:06.936Z,1381841226.936 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-10-15T12:47:06.936Z,1381841226.936 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2013-10-15T12:47:06.937Z,1381841226.937 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2013-10-15T12:47:06.937Z,1381841226.937 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2013-10-15T12:47:06.937Z,1381841226.937 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2013-10-15T12:47:06.937Z,1381841226.937 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2013-10-15T12:47:06.937Z,1381841226.937 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-10-15T12:47:06.947Z,1381841226.947 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2013-10-15T12:47:06.947Z,1381841226.947 [MassServo](DEBUG): Uninitialize Mass Servo.
2013-10-15T12:47:06.947Z,1381841226.947 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2013-10-15T12:47:06.947Z,1381841226.947 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2013-10-15T12:47:06.947Z,1381841226.947 [SBIT](DEBUG): Uninitialize SBIT Component.
2013-10-15T12:47:06.947Z,1381841226.947 [IBIT](DEBUG): Uninitialize IBIT Component.
2013-10-15T12:47:06.947Z,1381841226.947 [CBIT](DEBUG): Uninitialize CBIT Component.