2014-05-09T22:49:15.000Z,1399675756.000 [Supervisor](DEBUG): Initializing supervisor.
2014-05-09T22:49:16.004Z,1399675756.004 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-05-09T22:49:16.004Z,1399675756.004 [SyncHandler](INFO): Protected caller Thread ID is 779
2014-05-09T22:49:16.005Z,1399675756.005 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-05-09T22:49:16.007Z,1399675756.007 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2014-05-09T22:49:16.008Z,1399675756.008 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 780
2014-05-09T22:49:16.011Z,1399675756.011 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-05-09T22:49:16.022Z,1399675756.022 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-05-09T22:49:16.023Z,1399675756.023 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2014-05-09T22:49:16.024Z,1399675756.024 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 781
2014-05-09T22:49:16.025Z,1399675756.025 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-05-09T22:49:16.027Z,1399675756.027 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2014-05-09T22:49:16.028Z,1399675756.028 [logger ThreadHandler](INFO): Protected caller Thread ID is 782
2014-05-09T22:49:16.030Z,1399675756.030 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-05-09T22:49:16.030Z,1399675756.030 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-05-09T22:49:16.035Z,1399675756.035 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-05-09T22:49:16.423Z,1399675756.423 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-05-09T22:49:16.426Z,1399675756.426 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-05-09T22:49:16.732Z,1399675756.732 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-05-09T22:49:16.733Z,1399675756.733 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-05-09T22:49:16.828Z,1399675756.828 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-05-09T22:49:16.829Z,1399675756.829 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-05-09T22:49:17.050Z,1399675757.050 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-05-09T22:49:17.051Z,1399675757.051 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-05-09T22:49:17.226Z,1399675757.226 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-05-09T22:49:17.228Z,1399675757.228 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-05-09T22:49:17.555Z,1399675757.555 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-05-09T22:49:17.556Z,1399675757.556 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-05-09T22:49:17.755Z,1399675757.755 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-05-09T22:49:17.756Z,1399675757.756 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-05-09T22:49:18.127Z,1399675758.127 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-05-09T22:49:18.129Z,1399675758.129 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-05-09T22:49:18.250Z,1399675758.250 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-05-09T22:49:18.253Z,1399675758.253 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-05-09T22:49:18.998Z,1399675758.998 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-05-09T22:49:18.999Z,1399675758.999 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-05-09T22:49:19.117Z,1399675759.117 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-05-09T22:49:19.120Z,1399675759.120 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-05-09T22:49:19.216Z,1399675759.216 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-05-09T22:49:19.339Z,1399675759.339 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-05-09T22:49:19.340Z,1399675759.340 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-05-09T22:49:19.454Z,1399675759.454 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-05-09T22:49:19.455Z,1399675759.455 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-05-09T22:49:19.606Z,1399675759.606 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-05-09T22:49:19.608Z,1399675759.608 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-05-09T22:49:19.612Z,1399675759.612 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-05-09T22:49:19.728Z,1399675759.728 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-05-09T22:49:19.873Z,1399675759.873 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-05-09T22:49:19.979Z,1399675759.979 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-05-09T22:49:20.083Z,1399675760.083 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-05-09T22:49:20.251Z,1399675760.251 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-05-09T22:49:20.380Z,1399675760.380 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-05-09T22:49:20.478Z,1399675760.478 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-05-09T22:49:20.590Z,1399675760.590 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-05-09T22:49:20.700Z,1399675760.700 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-05-09T22:49:20.808Z,1399675760.808 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-05-09T22:49:20.909Z,1399675760.909 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-05-09T22:49:21.016Z,1399675761.016 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2014-05-09T22:49:21.021Z,1399675761.021 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-05-09T22:49:21.634Z,1399675761.634 [AHRS_sp3003D] Loaded
2014-05-09T22:49:21.635Z,1399675761.635 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-05-09T22:49:21.981Z,1399675761.981 [Batt_Ocean_Server] Loaded
2014-05-09T22:49:21.981Z,1399675761.981 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-05-09T22:49:22.176Z,1399675762.176 [DataOverHttps] Loaded
2014-05-09T22:49:22.176Z,1399675762.176 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2014-05-09T22:49:22.190Z,1399675762.190 [Depth_Keller] Loaded
2014-05-09T22:49:22.190Z,1399675762.190 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-05-09T22:49:22.195Z,1399675762.195 [DropWeight] Loaded
2014-05-09T22:49:22.195Z,1399675762.195 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-05-09T22:49:22.308Z,1399675762.308 [NAL9602] Loaded
2014-05-09T22:49:22.308Z,1399675762.308 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-05-09T22:49:22.364Z,1399675762.364 [Onboard] Loaded
2014-05-09T22:49:22.364Z,1399675762.364 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-05-09T22:49:22.372Z,1399675762.372 [Radio_Freewave] Loaded
2014-05-09T22:49:22.372Z,1399675762.372 [ComponentRegistry](DEBUG): Component "Radio_Freewave" handled in its own thread.
2014-05-09T22:49:22.373Z,1399675762.373 [Radio_Freewave ThreadHandler](DEBUG): Created PCaller Thread at 406064E0
2014-05-09T22:49:22.374Z,1399675762.374 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 864
2014-05-09T22:49:22.381Z,1399675762.381 [SCPI] Loaded
2014-05-09T22:49:22.381Z,1399675762.381 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-05-09T22:49:22.382Z,1399675762.382 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-05-09T22:49:22.384Z,1399675762.384 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-05-09T22:49:22.831Z,1399675762.831 [ExternalSim] Loaded
2014-05-09T22:49:22.831Z,1399675762.831 [ComponentRegistry](DEBUG): SyncComponent "ExternalSim" handled in the control thread.
2014-05-09T22:49:22.888Z,1399675762.888 [InternalSim] Loaded
2014-05-09T22:49:22.889Z,1399675762.889 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-05-09T22:49:22.889Z,1399675762.889 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-05-09T22:49:22.891Z,1399675762.891 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-05-09T22:49:23.224Z,1399675763.224 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-05-09T22:49:23.226Z,1399675763.226 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-05-09T22:49:23.235Z,1399675763.235 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2014-05-09T22:49:23.240Z,1399675763.240 [AsyncPiEstimator] Loaded
2014-05-09T22:49:23.240Z,1399675763.240 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2014-05-09T22:49:23.243Z,1399675763.243 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406E34E0
2014-05-09T22:49:23.243Z,1399675763.243 [AsyncPiEstimator ThreadHandler](INFO): Protected caller Thread ID is 867
2014-05-09T22:49:23.244Z,1399675763.244 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-05-09T22:49:23.244Z,1399675763.244 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-05-09T22:49:23.355Z,1399675763.355 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-05-09T22:49:23.355Z,1399675763.355 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-05-09T22:49:23.380Z,1399675763.380 [NavChart] Loaded
2014-05-09T22:49:23.381Z,1399675763.381 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-05-09T22:49:23.385Z,1399675763.385 [UniversalFixResidualReporter] Loaded
2014-05-09T22:49:23.385Z,1399675763.385 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-05-09T22:49:23.386Z,1399675763.386 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-05-09T22:49:23.388Z,1399675763.388 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-05-09T22:49:23.466Z,1399675763.466 [VerticalControl](DEBUG): Construct VerticalControl.
2014-05-09T22:49:23.593Z,1399675763.593 [VerticalControl] Loaded
2014-05-09T22:49:23.593Z,1399675763.593 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-05-09T22:49:23.594Z,1399675763.594 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-05-09T22:49:23.669Z,1399675763.669 [HorizontalControl] Loaded
2014-05-09T22:49:23.670Z,1399675763.670 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-05-09T22:49:23.670Z,1399675763.670 [SpeedControl](DEBUG): Construct SpeedControl.
2014-05-09T22:49:23.676Z,1399675763.676 [SpeedControl] Loaded
2014-05-09T22:49:23.676Z,1399675763.676 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-05-09T22:49:23.677Z,1399675763.677 [LoopControl](DEBUG): Construct LoopControl.
2014-05-09T22:49:23.678Z,1399675763.678 [LoopControl] Loaded
2014-05-09T22:49:23.678Z,1399675763.678 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-05-09T22:49:23.678Z,1399675763.678 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-05-09T22:49:23.681Z,1399675763.681 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-05-09T22:49:23.713Z,1399675763.713 [DepthRateCalculator] Loaded
2014-05-09T22:49:23.714Z,1399675763.714 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-05-09T22:49:23.719Z,1399675763.719 [PitchRateCalculator] Loaded
2014-05-09T22:49:23.720Z,1399675763.720 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-05-09T22:49:23.727Z,1399675763.727 [SpeedCalculator] Loaded
2014-05-09T22:49:23.727Z,1399675763.727 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-05-09T22:49:23.744Z,1399675763.744 [TempGradientCalculator] Loaded
2014-05-09T22:49:23.745Z,1399675763.745 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-05-09T22:49:23.750Z,1399675763.750 [YawRateCalculator] Loaded
2014-05-09T22:49:23.750Z,1399675763.750 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-05-09T22:49:23.751Z,1399675763.751 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-05-09T22:49:23.753Z,1399675763.753 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-05-09T22:49:23.893Z,1399675763.893 [CTD_NeilBrown] Loaded
2014-05-09T22:49:23.893Z,1399675763.893 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-05-09T22:49:23.896Z,1399675763.896 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407854E0
2014-05-09T22:49:23.896Z,1399675763.896 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 868
2014-05-09T22:49:23.912Z,1399675763.912 [ISUS] Loaded
2014-05-09T22:49:23.913Z,1399675763.913 [ComponentRegistry](DEBUG): SyncComponent "ISUS" handled in the control thread.
2014-05-09T22:49:23.927Z,1399675763.927 [PAR_Licor] Loaded
2014-05-09T22:49:23.928Z,1399675763.928 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-05-09T22:49:23.966Z,1399675763.966 [WetLabsBB2FL] Loaded
2014-05-09T22:49:23.966Z,1399675763.966 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-05-09T22:49:23.968Z,1399675763.968 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407B54E0
2014-05-09T22:49:23.968Z,1399675763.968 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 869
2014-05-09T22:49:23.969Z,1399675763.969 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-05-09T22:49:23.971Z,1399675763.971 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-05-09T22:49:24.127Z,1399675764.127 [SBIT](DEBUG): Construct Startup Built In Test.
2014-05-09T22:49:24.139Z,1399675764.139 [SBIT] Loaded
2014-05-09T22:49:24.139Z,1399675764.139 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-05-09T22:49:24.140Z,1399675764.140 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-05-09T22:49:24.157Z,1399675764.157 [IBIT] Loaded
2014-05-09T22:49:24.157Z,1399675764.157 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-05-09T22:49:24.159Z,1399675764.159 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-05-09T22:49:24.243Z,1399675764.243 [CBIT] Loaded
2014-05-09T22:49:24.243Z,1399675764.243 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-05-09T22:49:24.243Z,1399675764.243 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-05-09T22:49:24.495Z,1399675764.495 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-05-09T22:49:24.574Z,1399675764.574 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-05-09T22:49:24.574Z,1399675764.574 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-05-09T22:49:24.706Z,1399675764.706 [BuoyancyServo] Loaded
2014-05-09T22:49:24.707Z,1399675764.707 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-05-09T22:49:24.715Z,1399675764.715 [ElevatorServo] Loaded
2014-05-09T22:49:24.716Z,1399675764.716 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-05-09T22:49:24.728Z,1399675764.728 [MassServo] Loaded
2014-05-09T22:49:24.728Z,1399675764.728 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-05-09T22:49:24.737Z,1399675764.737 [RudderServo] Loaded
2014-05-09T22:49:24.737Z,1399675764.737 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-05-09T22:49:24.745Z,1399675764.745 [ThrusterServo] Loaded
2014-05-09T22:49:24.746Z,1399675764.746 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-05-09T22:49:24.746Z,1399675764.746 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-05-09T22:49:24.747Z,1399675764.747 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-05-09T22:49:24.790Z,1399675764.790 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-05-09T22:49:24.792Z,1399675764.792 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-05-09T22:49:24.793Z,1399675764.793 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-05-09T22:49:24.800Z,1399675764.800 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-05-09T22:49:24.801Z,1399675764.801 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 408844E0
2014-05-09T22:49:24.801Z,1399675764.801 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 870
2014-05-09T22:49:24.808Z,1399675764.808 [Supervisor](INFO): Main Thread ID is 767
2014-05-09T22:49:24.808Z,1399675764.808 [Supervisor](DEBUG): Running supervisor.
2014-05-09T22:49:24.809Z,1399675764.809 [CommandLine ThreadHandler](INFO): Handler Thread ID is 871
2014-05-09T22:49:24.814Z,1399675764.814 [controlThread ThreadHandler](INFO): Handler Thread ID is 872
2014-05-09T22:49:24.814Z,1399675764.814 [controlThread](DEBUG): Initializing ControlThread
2014-05-09T22:49:24.818Z,1399675764.818 [logger ThreadHandler](INFO): Handler Thread ID is 873
2014-05-09T22:49:24.854Z,1399675764.854 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 874
2014-05-09T22:49:24.866Z,1399675764.866 [AsyncPiEstimator ThreadHandler](INFO): Handler Thread ID is 875
2014-05-09T22:49:24.866Z,1399675764.866 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2014-05-09T22:49:24.890Z,1399675764.890 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 876
2014-05-09T22:49:24.890Z,1399675764.890 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-05-09T22:49:24.910Z,1399675764.910 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 877
2014-05-09T22:49:24.926Z,1399675764.926 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 878
2014-05-09T22:49:24.947Z,1399675764.947 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-05-09T22:49:24.950Z,1399675764.950 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-05-09T22:49:24.950Z,1399675764.950 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-05-09T22:49:24.950Z,1399675764.950 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-05-09T22:49:24.951Z,1399675764.951 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-05-09T22:49:24.951Z,1399675764.951 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-05-09T22:49:24.951Z,1399675764.951 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-05-09T22:49:24.951Z,1399675764.951 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-05-09T22:49:24.952Z,1399675764.952 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-05-09T22:49:25.298Z,1399675765.298 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:49:26.389Z,1399675766.389 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-05-09T22:49:26.415Z,1399675766.415 [ExternalSim](INFO): ExternalSim initializing...
2014-05-09T22:49:26.577Z,1399675766.577 [ExternalSim](DEBUG): beaconLat = 36.81340
2014-05-09T22:49:26.577Z,1399675766.577 [ExternalSim](DEBUG): beaconLon = -121.82240
2014-05-09T22:49:26.578Z,1399675766.578 [ExternalSim](DEBUG): beaconDepth = 25.00
2014-05-09T22:49:26.640Z,1399675766.640 [ExternalSim](DEBUG): Simulator initialized
2014-05-09T22:49:26.914Z,1399675766.914 [InternalSim](DEBUG):  InternalSim initializing...
2014-05-09T22:49:27.008Z,1399675767.008 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-05-09T22:49:27.024Z,1399675767.024 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-05-09T22:49:27.025Z,1399675767.025 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-05-09T22:49:27.025Z,1399675767.025 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-05-09T22:49:27.027Z,1399675767.027 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-05-09T22:49:27.027Z,1399675767.027 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-05-09T22:49:27.028Z,1399675767.028 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-05-09T22:49:27.028Z,1399675767.028 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-05-09T22:49:27.045Z,1399675767.045 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-05-09T22:49:27.045Z,1399675767.045 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-05-09T22:49:27.045Z,1399675767.045 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-05-09T22:49:27.046Z,1399675767.046 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-05-09T22:49:27.047Z,1399675767.047 [SBIT](INFO): Initialize SBIT Component.
2014-05-09T22:49:27.048Z,1399675767.048 [SBIT](IMPORTANT): Tethys CM Info: 
$Rev:11280
2014-05-09T22:49:27.048Z,1399675767.048 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2014-05-09T22:49:27.048Z,1399675767.048 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-05-09T22:49:27.057Z,1399675767.057 [IBIT](INFO): Initialize IBIT Component.
2014-05-09T22:49:27.058Z,1399675767.058 [CBIT](DEBUG): Initialize CBIT Component.
2014-05-09T22:49:27.058Z,1399675767.058 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2014-05-09T22:49:27.083Z,1399675767.083 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-05-09T22:49:27.106Z,1399675767.106 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-09T22:49:27.131Z,1399675767.131 [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>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="StartupSatComms">

        <Sequence/>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:latitude_fix/>
        </ReadDatum>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

</Mission>


2014-05-09T22:49:27.131Z,1399675767.131 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-05-09T22:49:27.214Z,1399675767.214 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2014-05-09T22:49:27.216Z,1399675767.216 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2014-05-09T22:49:27.220Z,1399675767.220 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-09T22:49:27.244Z,1399675767.244 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2014-05-09T22:49:27.267Z,1399675767.267 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-09T22:49:27.322Z,1399675767.322 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-05-09T22:49:27.352Z,1399675767.352 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-05-09T22:49:27.356Z,1399675767.356 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-09T22:49:27.403Z,1399675767.403 [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>
            <Parallel/>
            <Setting><Guidance:SetSpeed.period/><Units:millisecond/><Value>400</Value></Setting>
        </Guidance:SetSpeed>

<!-- Get to the surface -->

        <Guidance:GoToSurface>
            <Sequence/>
        </Guidance:GoToSurface>

<!-- Get GPS fix -->

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

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

    </Aggregate>

    <Aggregate Id="Iridium">

        <Sequence/>

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface>
            <Sequence/>
        </Guidance:GoToSurface>

<!-- Do data comms -->

        <ReadDatum Id="Read_Iridium">
            <Timeout Duration="P2H">
                <Guidance:Execute>
                    <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><Sequence/><Arg Name="NeedGPS"/><True/></Assign>

        <Call RefId="Iridium"/>

    </Aggregate>

    <Aggregate Id="WaitAtTheSurface">

        <Sequence/>

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

        <Guidance:GoToSurface>
            <Parallel/>
        </Guidance:GoToSurface>

    </Aggregate>

</Mission>


2014-05-09T22:49:27.415Z,1399675767.415 [controlThread](DEBUG): Component order: CycleStarter,ExternalSim,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,SCPI,ISUS,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2014-05-09T22:49:27.628Z,1399675767.628 [Radio_Freewave](INFO): Powering up
2014-05-09T22:49:27.915Z,1399675767.915 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-05-09T22:49:27.922Z,1399675767.922 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-05-09T22:49:27.936Z,1399675767.936 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-05-09T22:49:27.942Z,1399675767.942 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-05-09T22:49:27.959Z,1399675767.959 [MassServo](DEBUG): Initializing EZServoServo.
2014-05-09T22:49:27.970Z,1399675767.970 [MassServo](DEBUG): Initializing MassServo.
2014-05-09T22:49:27.976Z,1399675767.976 [RudderServo](DEBUG): Initializing EZServoServo.
2014-05-09T22:49:27.982Z,1399675767.982 [RudderServo](DEBUG): Initializing RudderServo.
2014-05-09T22:49:27.993Z,1399675767.993 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-05-09T22:49:28.432Z,1399675768.432 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0
2014-05-09T22:49:31.680Z,1399675771.680 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003306
2014-05-09T22:49:33.866Z,1399675773.866 [NAL9602](IMPORTANT): GPS fix at: 1399675773.86
2014-05-09T22:49:35.069Z,1399675775.069 [NAL9602](INFO): No messages in MT queue
2014-05-09T22:49:40.660Z,1399675780.660 [NAL9602](INFO): Powering down
2014-05-09T22:49:42.424Z,1399675782.424 [SBIT](IMPORTANT): Beginning Startup BIT
2014-05-09T22:49:42.427Z,1399675782.427 [CBIT](IMPORTANT): Beginning GF scan
2014-05-09T22:50:08.483Z,1399675808.483 [CBIT](IMPORTANT): No ground fault detected
2014-05-09T22:50:30.613Z,1399675830.613 [DataOverHttps](IMPORTANT): SBD MTMSN=20140509T225029
2014-05-09T22:50:33.108Z,1399675833.108 [DataOverHttps](INFO): Received command:load Science/EcoHAB_box.xml;set EcoHAB_box.NeedCommsTime 30 minute;set EcoHAB_box.MissionTimeout 65 hour;set EcoHAB_box.LapTimeout 12 hour;run 
2014-05-09T22:50:33.181Z,1399675833.181 [CommandLine](IMPORTANT): got command load ./Missions/Science/EcoHAB_box.xml
2014-05-09T22:50:33.182Z,1399675833.182 [MissionManager](INFO): Loading Mission: ./Missions/Science/EcoHAB_box.xml
2014-05-09T22:50:33.590Z,1399675833.590 [MissionManager](INFO): DefineArg EcoHAB_box.NeedCommsTime = 36.000000 h
2014-05-09T22:50:33.614Z,1399675833.614 [MissionManager](INFO): DefineArg EcoHAB_box.MinAltitude = 4.000000 m
2014-05-09T22:50:33.618Z,1399675833.618 [MissionManager](INFO): DefineArg EcoHAB_box.MaxDepth = 85.000000 m
2014-05-09T22:50:33.669Z,1399675833.669 [MissionManager](INFO): DefineArg EcoHAB_box.MinOffshore = 2000.000000 m
2014-05-09T22:50:33.673Z,1399675833.673 [MissionManager](INFO): DefineArg EcoHAB_box.Speed = 1.000000 m/s
2014-05-09T22:50:33.696Z,1399675833.696 [MissionManager](INFO): DefineArg EcoHAB_box.MissionTimeout = 9.000000 h
2014-05-09T22:50:33.737Z,1399675833.737 [MissionManager](INFO): DefineArg EcoHAB_box.MassDefault = 0.000000 n/a
2014-05-09T22:50:33.741Z,1399675833.741 [MissionManager](INFO): DefineArg EcoHAB_box.BuoyancyNeutral = 0.000300 n/a
2014-05-09T22:50:33.772Z,1399675833.772 [MissionManager](INFO): DefineArg EcoHAB_box.WpESPInshoreLat = 33.607614 arcdeg
2014-05-09T22:50:33.776Z,1399675833.776 [MissionManager](INFO): DefineArg EcoHAB_box.WpESPInshoreLon = -118.018798 arcdeg
2014-05-09T22:50:33.804Z,1399675833.804 [MissionManager](INFO): DefineArg EcoHAB_box.WpESPOffshoreLat = 33.585471 arcdeg
2014-05-09T22:50:33.808Z,1399675833.808 [MissionManager](INFO): DefineArg EcoHAB_box.WpESPOffshoreLon = -118.037372 arcdeg
2014-05-09T22:50:33.811Z,1399675833.811 [MissionManager](INFO): DefineArg EcoHAB_box.WpCorner1Lat = 33.586554 arcdeg
2014-05-09T22:50:33.833Z,1399675833.833 [MissionManager](INFO): DefineArg EcoHAB_box.WpCorner1Lon = -117.979903 arcdeg
2014-05-09T22:50:33.857Z,1399675833.857 [MissionManager](INFO): DefineArg EcoHAB_box.WpCorner2Lat = 33.563841 arcdeg
2014-05-09T22:50:33.860Z,1399675833.860 [MissionManager](INFO): DefineArg EcoHAB_box.WpCorner2Lon = -117.997449 arcdeg
2014-05-09T22:50:33.886Z,1399675833.886 [MissionManager](INFO): DefineArg EcoHAB_box.WpCorner3Lat = 33.606518 arcdeg
2014-05-09T22:50:33.890Z,1399675833.890 [MissionManager](INFO): DefineArg EcoHAB_box.WpCorner3Lon = -118.076276 arcdeg
2014-05-09T22:50:33.907Z,1399675833.907 [MissionManager](INFO): DefineArg EcoHAB_box.WpCorner4Lat = 33.628662 arcdeg
2014-05-09T22:50:33.911Z,1399675833.911 [MissionManager](INFO): DefineArg EcoHAB_box.WpCorner4Lon = -118.057712 arcdeg
2014-05-09T22:50:33.938Z,1399675833.938 [MissionManager](INFO): DefineArg EcoHAB_box.ApproachDepth = 10.000000 m
2014-05-09T22:50:33.942Z,1399675833.942 [MissionManager](INFO): DefineArg EcoHAB_box.ApproachTimeout = 4.000000 h
2014-05-09T22:50:33.967Z,1399675833.967 [MissionManager](INFO): DefineArg EcoHAB_box.ApproachNeedCommsTime = 20.000000 min
2014-05-09T22:50:33.981Z,1399675833.981 [MissionManager](INFO): DefineArg EcoHAB_box.Repeat = 13.000000 count
2014-05-09T22:50:34.017Z,1399675834.017 [MissionManager](INFO): DefineArg EcoHAB_box.CircleRadius = 500.000000 m
2014-05-09T22:50:34.020Z,1399675834.020 [MissionManager](INFO): DefineArg EcoHAB_box.CircleRepeat = 13.000000 count
2014-05-09T22:50:34.024Z,1399675834.024 [MissionManager](INFO): DefineArg EcoHAB_box.CircleDivisor = 2.000000 h
2014-05-09T22:50:34.053Z,1399675834.053 [MissionManager](INFO): DefineArg EcoHAB_box.CircleModulus = nan h
2014-05-09T22:50:34.056Z,1399675834.056 [MissionManager](INFO): DefineArg EcoHAB_box.CircleTimeout = 3.000000 h
2014-05-09T22:50:34.084Z,1399675834.084 [MissionManager](INFO): DefineArg EcoHAB_box.LapTimeout = 8.000000 h
2014-05-09T22:50:34.087Z,1399675834.087 [MissionManager](INFO): DefineArg EcoHAB_box.SCPITimeout = 150.000000 s
2014-05-09T22:50:34.115Z,1399675834.115 [MissionManager](INFO): DefineArg EcoHAB_box.YoYoMinDepth = 4.000000 m
2014-05-09T22:50:34.119Z,1399675834.119 [MissionManager](INFO): DefineArg EcoHAB_box.YoYoMaxDepth = 78.000000 m
2014-05-09T22:50:34.131Z,1399675834.131 [MissionManager](INFO): DefineArg EcoHAB_box.YoYoMinAltitude = 6.000000 m
2014-05-09T22:50:34.134Z,1399675834.134 [MissionManager](INFO): DefineArg EcoHAB_box.YoYoUpPitch = 20.000000 arcdeg
2014-05-09T22:50:34.180Z,1399675834.180 [MissionManager](INFO): DefineArg EcoHAB_box.YoYoDownPitch = -20.000000 arcdeg
2014-05-09T22:50:34.181Z,1399675834.181 [EcoHAB_box:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2014-05-09T22:50:34.207Z,1399675834.207 [EcoHAB_box:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2014-05-09T22:50:34.273Z,1399675834.273 [EcoHAB_box:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2014-05-09T22:50:34.305Z,1399675834.305 [MissionManager](INFO): Inserting Stack: Missions/Insert/NeedComms.xml
2014-05-09T22:50:34.440Z,1399675834.440 [MissionManager](INFO): DefineArg EcoHAB_box:NeedComms.CommsTimeout = 30.000000 min
2014-05-09T22:50:34.471Z,1399675834.471 [MissionManager](INFO): DefineArg EcoHAB_box:NeedComms.DiveInterval = 3.000000 h
2014-05-09T22:50:34.475Z,1399675834.475 [MissionManager](INFO): DefineArg EcoHAB_box:NeedComms.WaitForPitchUp = 10.000000 min
2014-05-09T22:50:34.507Z,1399675834.507 [MissionManager](INFO): DefineArg EcoHAB_box:NeedComms.SurfacePitch = 20.000000 arcdeg
2014-05-09T22:50:34.510Z,1399675834.510 [MissionManager](INFO): DefineArg EcoHAB_box:NeedComms.SurfaceSpeed = 1.000000 m/s
2014-05-09T22:50:34.559Z,1399675834.559 [EcoHAB_box:NeedComms:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-09T22:50:34.627Z,1399675834.627 [MissionManager](INFO): Inserting Stack: Missions/Insert/Surface.xml
2014-05-09T22:50:34.712Z,1399675834.712 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceComms.SurfaceDepthRate = nan m/s
2014-05-09T22:50:34.731Z,1399675834.731 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceComms.SurfacePitch = 20.000000 arcdeg
2014-05-09T22:50:34.755Z,1399675834.755 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceComms.SurfaceSpeed = 1.000000 m/s
2014-05-09T22:50:34.759Z,1399675834.759 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceComms.IridiumTimeout = 30.000000 min
2014-05-09T22:50:34.774Z,1399675834.774 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceComms.UnpackSplitAtSurface = 0 bool
2014-05-09T22:50:34.776Z,1399675834.776 [EcoHAB_box:SurfaceComms:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-09T22:50:34.811Z,1399675834.811 [MissionManager](INFO): Inserting Stack: Missions/Insert/SurfaceCommsSplit.xml
2014-05-09T22:50:34.880Z,1399675834.880 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceCommsSplit.SurfacePitch = 20.000000 arcdeg
2014-05-09T22:50:34.883Z,1399675834.883 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceCommsSplit.SurfaceSpeed = 1.000000 m/s
2014-05-09T22:50:34.884Z,1399675834.884 [MissionManager](INFO): Inserting Stack: Missions/Insert/Surface.xml
2014-05-09T22:50:34.938Z,1399675834.938 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceCommsSplit:SurfaceComms.SurfaceDepthRate = nan m/s
2014-05-09T22:50:34.958Z,1399675834.958 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceCommsSplit:SurfaceComms.SurfacePitch = 20.000000 arcdeg
2014-05-09T22:50:34.962Z,1399675834.962 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceCommsSplit:SurfaceComms.SurfaceSpeed = 1.000000 m/s
2014-05-09T22:50:34.986Z,1399675834.986 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceCommsSplit:SurfaceComms.IridiumTimeout = 30.000000 min
2014-05-09T22:50:34.989Z,1399675834.989 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceCommsSplit:SurfaceComms.UnpackSplitAtSurface = 0 bool
2014-05-09T22:50:34.990Z,1399675834.990 [EcoHAB_box:SurfaceCommsSplit:SurfaceComms:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-09T22:50:35.033Z,1399675835.033 [MissionManager](INFO): RedefineArg EcoHAB_box:SurfaceCommsSplit:SurfaceComms.SurfacePitch = value:20.000000 arcdeg
2014-05-09T22:50:35.035Z,1399675835.035 [MissionManager](INFO): RedefineArg EcoHAB_box:SurfaceCommsSplit:SurfaceComms.SurfaceSpeed = value:1.000000 m/s
2014-05-09T22:50:35.037Z,1399675835.037 [MissionManager](INFO): RedefineArg EcoHAB_box:SurfaceCommsSplit:SurfaceComms.UnpackSplitAtSurface = value:1 bool
2014-05-09T22:50:35.037Z,1399675835.037 [MissionManager](INFO): Inserting Stack: Missions/Insert/SurfaceCommsShort.xml
2014-05-09T22:50:35.104Z,1399675835.104 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceCommsShort.FloatTime = 180.000000 s
2014-05-09T22:50:35.108Z,1399675835.108 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceCommsShort.Timeout = 1.000000 h
2014-05-09T22:50:35.143Z,1399675835.143 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceCommsShort.Pitch = 20.000000 arcdeg
2014-05-09T22:50:35.159Z,1399675835.159 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceCommsShort.Speed = 1.000000 m/s
2014-05-09T22:50:35.160Z,1399675835.160 [EcoHAB_box:SurfaceCommsShort:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-09T22:50:35.198Z,1399675835.198 [MissionManager](INFO): Inserting Stack: Missions/Insert/SurfaceGPS.xml
2014-05-09T22:50:35.261Z,1399675835.261 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceGPS.HalfTimeout = 30.000000 s
2014-05-09T22:50:35.265Z,1399675835.265 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceGPS.SurfacePitch = 20.000000 arcdeg
2014-05-09T22:50:35.280Z,1399675835.280 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceGPS.SurfaceSpeed = 1.000000 m/s
2014-05-09T22:50:35.282Z,1399675835.282 [EcoHAB_box:SurfaceGPS:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-09T22:50:35.304Z,1399675835.304 [MissionManager](INFO): Inserting Stack: Missions/Insert/SurfaceSafety.xml
2014-05-09T22:50:35.343Z,1399675835.343 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceSafety.MaxTime = 11.000000 h
2014-05-09T22:50:35.345Z,1399675835.345 [MissionManager](INFO): Inserting Stack: Missions/Insert/Surface.xml
2014-05-09T22:50:35.411Z,1399675835.411 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceSafety:SurfaceComms.SurfaceDepthRate = nan m/s
2014-05-09T22:50:35.435Z,1399675835.435 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceSafety:SurfaceComms.SurfacePitch = 20.000000 arcdeg
2014-05-09T22:50:35.438Z,1399675835.438 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceSafety:SurfaceComms.SurfaceSpeed = 1.000000 m/s
2014-05-09T22:50:35.442Z,1399675835.442 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceSafety:SurfaceComms.IridiumTimeout = 30.000000 min
2014-05-09T22:50:35.462Z,1399675835.462 [MissionManager](INFO): DefineArg EcoHAB_box:SurfaceSafety:SurfaceComms.UnpackSplitAtSurface = 0 bool
2014-05-09T22:50:35.464Z,1399675835.464 [EcoHAB_box:SurfaceSafety:SurfaceComms:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-09T22:50:35.518Z,1399675835.518 [MissionManager](INFO): RedefineArg EcoHAB_box:SurfaceSafety:SurfaceComms.SurfacePitch = value:20.000000 arcdeg
2014-05-09T22:50:35.529Z,1399675835.529 [MissionManager](INFO): RedefineArg EcoHAB_box:SurfaceSafety:SurfaceComms.SurfaceSpeed = value:1.000000 m/s
2014-05-09T22:50:35.530Z,1399675835.530 [EcoHAB_box:L.Pitch](DEBUG): Construct.
2014-05-09T22:50:35.556Z,1399675835.556 [EcoHAB_box:M.Buoyancy](DEBUG): Construct Buoyancy.
2014-05-09T22:50:35.558Z,1399675835.558 [MissionManager](INFO): Inserting Stack: Missions/Insert/CircleWaypointRepeatedly.xml
2014-05-09T22:50:35.713Z,1399675835.713 [MissionManager](INFO): DefineArg EcoHAB_box:CircleWaypointRepeatedly.Timeout = 90.000000 min
2014-05-09T22:50:35.717Z,1399675835.717 [MissionManager](INFO): DefineArg EcoHAB_box:CircleWaypointRepeatedly.LapTimeout = 240.000000 min
2014-05-09T22:50:35.749Z,1399675835.749 [MissionManager](INFO): DefineArg EcoHAB_box:CircleWaypointRepeatedly.MaxLaps = 32.000000 count
2014-05-09T22:50:35.752Z,1399675835.752 [MissionManager](INFO): DefineArg EcoHAB_box:CircleWaypointRepeatedly.CenterLat = nan arcdeg
2014-05-09T22:50:35.772Z,1399675835.772 [MissionManager](INFO): DefineArg EcoHAB_box:CircleWaypointRepeatedly.CenterLon = nan arcdeg
2014-05-09T22:50:35.780Z,1399675835.780 [MissionManager](INFO): DefineArg EcoHAB_box:CircleWaypointRepeatedly.Radius = 250.000000 m
2014-05-09T22:50:35.803Z,1399675835.803 [MissionManager](INFO): DefineArg EcoHAB_box:CircleWaypointRepeatedly.MaxError = 250.000000 m
2014-05-09T22:50:35.819Z,1399675835.819 [MissionManager](INFO): DefineArg EcoHAB_box:CircleWaypointRepeatedly.TurnToPort = 0 bool
2014-05-09T22:50:35.823Z,1399675835.823 [MissionManager](INFO): DefineArg EcoHAB_box:CircleWaypointRepeatedly.KwpHeading = 0.010000 rad/m
2014-05-09T22:50:35.838Z,1399675835.838 [MissionManager](INFO): DefineArg EcoHAB_box:CircleWaypointRepeatedly.FloatTime = 60.000000 s
2014-05-09T22:50:35.850Z,1399675835.850 [MissionManager](INFO): DefineArg EcoHAB_box:CircleWaypointRepeatedly.Pitch = 20.000000 arcdeg
2014-05-09T22:50:35.862Z,1399675835.862 [MissionManager](INFO): DefineArg EcoHAB_box:CircleWaypointRepeatedly.Speed = 1.000000 m/s
2014-05-09T22:50:35.886Z,1399675835.886 [EcoHAB_box:CircleWaypointRepeatedly:Repeater:Lap:B.Circle](DEBUG): Construct.
2014-05-09T22:50:35.911Z,1399675835.911 [EcoHAB_box:CircleWaypointRepeatedly:Repeater:GTS:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-09T22:50:36.027Z,1399675836.027 [EcoHAB_box:Lap:WpESPInshore.Waypoint](DEBUG): Construct Waypoint.
2014-05-09T22:50:36.050Z,1399675836.050 [EcoHAB_box:Lap:WpCorner1.Waypoint](DEBUG): Construct Waypoint.
2014-05-09T22:50:36.077Z,1399675836.077 [EcoHAB_box:Lap:WpCorner2.Waypoint](DEBUG): Construct Waypoint.
2014-05-09T22:50:36.103Z,1399675836.103 [EcoHAB_box:Lap:WpESPOffshore.Waypoint](DEBUG): Construct Waypoint.
2014-05-09T22:50:36.165Z,1399675836.165 [EcoHAB_box:Lap:WpCorner3.Waypoint](DEBUG): Construct Waypoint.
2014-05-09T22:50:36.180Z,1399675836.180 [EcoHAB_box:Lap:WpCorner4.Waypoint](DEBUG): Construct Waypoint.
2014-05-09T22:50:36.239Z,1399675836.239 [EcoHAB_box:Lap:WpESPInshore.Waypoint](DEBUG): Construct Waypoint.
2014-05-09T22:50:36.261Z,1399675836.261 [EcoHAB_box:Approach:B.Pitch](DEBUG): Construct.
2014-05-09T22:50:36.274Z,1399675836.274 [EcoHAB_box:Approach:C.SetSpeed](DEBUG): Construct.
2014-05-09T22:50:36.277Z,1399675836.277 [EcoHAB_box:Approach:WpApproach.Waypoint](DEBUG): Construct Waypoint.
2014-05-09T22:50:36.313Z,1399675836.313 [MissionManager](INFO): Inserting Stack: Missions/Insert/Science.xml
2014-05-09T22:50:36.523Z,1399675836.523 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:Science.SampleISUS = 0 bool
2014-05-09T22:50:36.526Z,1399675836.526 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:Science.SampleISUSmaxPitch = 60.000000 arcdeg
2014-05-09T22:50:36.560Z,1399675836.560 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:Science.SampleISUSminPitch = -60.000000 arcdeg
2014-05-09T22:50:36.575Z,1399675836.575 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:Science.PeakDetectChlActive = 0 bool
2014-05-09T22:50:36.579Z,1399675836.579 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:Science.PeakDetectNO3Active = 0 bool
2014-05-09T22:50:36.596Z,1399675836.596 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:Science.UpwardDerivativeOfTemperatureActive = 0 bool
2014-05-09T22:50:36.599Z,1399675836.599 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:Science.ComputeWaterCurrent = 0 bool
2014-05-09T22:50:36.619Z,1399675836.619 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:Science.ComputeWaterCurrentMinDepth = 2.000000 m
2014-05-09T22:50:36.623Z,1399675836.623 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:Science.ComputeWaterCurrentMaxDepth = 5.000000 m
2014-05-09T22:50:36.655Z,1399675836.655 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:Science.EnabledAanderaaO2 = 0.000000 n/a
2014-05-09T22:50:36.659Z,1399675836.659 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:Science.EnabledNeilBrown = 1.000000 n/a
2014-05-09T22:50:36.686Z,1399675836.686 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:Science.EnabledTurbulence_NPS = 0.000000 n/a
2014-05-09T22:50:36.690Z,1399675836.690 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:Science.EnabledWetLabsBB2FL = 1.000000 n/a
2014-05-09T22:50:36.718Z,1399675836.718 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:Science.EnabledDVL = 0.000000 n/a
2014-05-09T22:50:36.722Z,1399675836.722 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:Science.EnabledISUS = 1.000000 n/a
2014-05-09T22:50:36.746Z,1399675836.746 [MissionManager](INFO): DefineOutput EcoHAB_box:ScienceOps:Science.PeakChl = 0.000000 ug/l
2014-05-09T22:50:36.750Z,1399675836.750 [MissionManager](INFO): DefineOutput EcoHAB_box:ScienceOps:Science.PeakChlDepth = 0.000000 m
2014-05-09T22:50:36.781Z,1399675836.781 [MissionManager](INFO): DefineOutput EcoHAB_box:ScienceOps:Science.PeakChlLatitude = nan arcdeg
2014-05-09T22:50:36.785Z,1399675836.785 [MissionManager](INFO): DefineOutput EcoHAB_box:ScienceOps:Science.PeakChlLongitude = nan arcdeg
2014-05-09T22:50:36.809Z,1399675836.809 [MissionManager](INFO): DefineOutput EcoHAB_box:ScienceOps:Science.PeakNO3 = 0.000000 umol/l
2014-05-09T22:50:36.813Z,1399675836.813 [MissionManager](INFO): DefineOutput EcoHAB_box:ScienceOps:Science.PeakNO3Depth = 0.000000 m
2014-05-09T22:50:36.816Z,1399675836.816 [MissionManager](INFO): DefineOutput EcoHAB_box:ScienceOps:Science.PeakNO3Latitude = nan arcdeg
2014-05-09T22:50:36.836Z,1399675836.836 [MissionManager](INFO): DefineOutput EcoHAB_box:ScienceOps:Science.PeakNO3Longitude = nan arcdeg
2014-05-09T22:50:36.907Z,1399675836.907 [EcoHAB_box:ScienceOps:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2014-05-09T22:50:36.924Z,1399675836.924 [EcoHAB_box:ScienceOps:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2014-05-09T22:50:36.997Z,1399675836.997 [MissionManager](INFO): RedefineArg EcoHAB_box:ScienceOps:Science.PeakDetectChlActive = value:1 bool
2014-05-09T22:50:36.999Z,1399675836.999 [MissionManager](INFO): RedefineArg EcoHAB_box:ScienceOps:Science.SampleISUS = value:1 bool
2014-05-09T22:50:37.010Z,1399675837.010 [MissionManager](INFO): RedefineArg EcoHAB_box:ScienceOps:Science.SampleISUSmaxPitch = value:30.000000 arcdeg
2014-05-09T22:50:37.012Z,1399675837.012 [MissionManager](INFO): RedefineArg EcoHAB_box:ScienceOps:Science.SampleISUSminPitch = value:10.000000 arcdeg
2014-05-09T22:50:37.031Z,1399675837.031 [MissionManager](INFO): RedefineArg EcoHAB_box:ScienceOps:Science.ComputeWaterCurrent = value:0 bool
2014-05-09T22:50:37.033Z,1399675837.033 [MissionManager](INFO): RedefineArg EcoHAB_box:ScienceOps:Science.UpwardDerivativeOfTemperatureActive = value:0 bool
2014-05-09T22:50:37.045Z,1399675837.045 [MissionManager](INFO): Inserting Stack: Missions/Insert/VerticalTemperatureHomogeneityIndex.xml
2014-05-09T22:50:37.555Z,1399675837.555 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:VTHIdx.DepthShallow = 5.000000 m
2014-05-09T22:50:37.575Z,1399675837.575 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:VTHIdx.DepthMidShallow = 10.000000 m
2014-05-09T22:50:37.591Z,1399675837.591 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:VTHIdx.DepthMidDeep = 15.000000 m
2014-05-09T22:50:37.594Z,1399675837.594 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:VTHIdx.DepthDeep = 20.000000 m
2014-05-09T22:50:37.623Z,1399675837.623 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:VTHIdx.Verbosity = 1.000000 count
2014-05-09T22:50:37.628Z,1399675837.628 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:VTHIdx.TemperatureShallow = 0.000000 K
2014-05-09T22:50:37.648Z,1399675837.648 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:VTHIdx.TemperatureMidShallow = 0.000000 K
2014-05-09T22:50:37.652Z,1399675837.652 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:VTHIdx.TemperatureMidDeep = 0.000000 K
2014-05-09T22:50:37.672Z,1399675837.672 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:VTHIdx.TemperatureDeep = 0.000000 K
2014-05-09T22:50:37.676Z,1399675837.676 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:VTHIdx.DTShallow = 0.000000 K
2014-05-09T22:50:37.707Z,1399675837.707 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:VTHIdx.DTMidShallow = 0.000000 K
2014-05-09T22:50:37.711Z,1399675837.711 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:VTHIdx.DTMidDeep = 0.000000 K
2014-05-09T22:50:37.723Z,1399675837.723 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:VTHIdx.DTDeep = 0.000000 K
2014-05-09T22:50:37.726Z,1399675837.726 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:VTHIdx.Zero = 0.000000 count
2014-05-09T22:50:37.730Z,1399675837.730 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:VTHIdx.One = 1.000000 count
2014-05-09T22:50:37.734Z,1399675837.734 [MissionManager](INFO): DefineArg EcoHAB_box:ScienceOps:VTHIdx.Two = 2.000000 count
2014-05-09T22:50:37.753Z,1399675837.753 [MissionManager](INFO): DefineOutput EcoHAB_box:ScienceOps:VTHIdx.TemperatureMean = 0.000000 K
2014-05-09T22:50:37.757Z,1399675837.757 [MissionManager](INFO): DefineOutput EcoHAB_box:ScienceOps:VTHIdx.TemperatureDelta = 0.000000 K
2014-05-09T22:50:37.761Z,1399675837.761 [MissionManager](INFO): DefineOutput EcoHAB_box:ScienceOps:VTHIdx.DetectLatitude = nan arcdeg
2014-05-09T22:50:37.765Z,1399675837.765 [MissionManager](INFO): DefineOutput EcoHAB_box:ScienceOps:VTHIdx.DetectLongitude = nan arcdeg
2014-05-09T22:50:37.781Z,1399675837.781 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectShallow.ValueDetect](DEBUG): Construct ValueDetect.
2014-05-09T22:50:37.789Z,1399675837.789 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectMidShallow.ValueDetect](DEBUG): Construct ValueDetect.
2014-05-09T22:50:37.811Z,1399675837.811 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectMidDeep.ValueDetect](DEBUG): Construct ValueDetect.
2014-05-09T22:50:37.817Z,1399675837.817 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectDeep.ValueDetect](DEBUG): Construct ValueDetect.
2014-05-09T22:50:37.912Z,1399675837.912 [MissionManager](INFO): RedefineArg EcoHAB_box:ScienceOps:VTHIdx.DepthShallow = value:5.000000 m
2014-05-09T22:50:37.914Z,1399675837.914 [MissionManager](INFO): RedefineArg EcoHAB_box:ScienceOps:VTHIdx.DepthMidShallow = value:10.000000 m
2014-05-09T22:50:37.917Z,1399675837.917 [MissionManager](INFO): RedefineArg EcoHAB_box:ScienceOps:VTHIdx.DepthMidDeep = value:20.000000 m
2014-05-09T22:50:37.920Z,1399675837.920 [MissionManager](INFO): RedefineArg EcoHAB_box:ScienceOps:VTHIdx.DepthDeep = value:25.000000 m
2014-05-09T22:50:37.922Z,1399675837.922 [MissionManager](INFO): RedefineArg EcoHAB_box:ScienceOps:VTHIdx.Verbosity = value:1.000000 count
2014-05-09T22:50:37.939Z,1399675837.939 [EcoHAB_box:ScienceOps:D.SetSpeed](DEBUG): Construct.
2014-05-09T22:50:37.942Z,1399675837.942 [EcoHAB_box:ScienceOps:E.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2014-05-09T22:50:37.957Z,1399675837.957 [EcoHAB_box:ScienceOps:F.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2014-05-09T22:50:37.981Z,1399675837.981 [EcoHAB_box:ScienceOps:G.YoYo](DEBUG): Construct YoYo.
2014-05-09T22:50:38.086Z,1399675838.086 [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:Trigger="Tethys/Trigger" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Sensor http://aosn.mbari.org/tethys/Xml/Sensor.xsd
                           Tethys/Trigger http://aosn.mbari.org/tethys/Xml/Trigger.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="EcoHAB_box">

    <Description>
        This mission runs yoyos counterclockwise around a box. Two sides of the
        box pass through the planned locations for both Environmental Sample
        Processor (ESP) buoys during the Spring 2014 EcoHAB deployment.
    </Description>

<!-- Mission-wide settings -->

    <DefineArg Name="NeedCommsTime"><Description>
        High-level NeedComms directive intended to assist debugging in the
        field. Elapsed time after previous surface fix when vehicle will begin
        to ascend for additional surface fix, if the vehicle has a positive
        pitch. If the vehicle has a negative pitch, it will wait up to 10
        minutes more to begin ascent. The timing operates based on
        Universal:time_fix to avoid repeated attempts after the Iridium timeout.
    </Description><Units:hour/><Value>36</Value></DefineArg>

    <DefineArg Name="MinAltitude"><Description>
        Minimum altitude for the entire mission.
    </Description><Units:meter/><Value>4</Value></DefineArg>

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

    <DefineArg Name="MinOffshore"><Description>
        Minimum offshore distance for the entire mission.
    </Description><Units:meter/><Value>2000</Value></DefineArg>

    <DefineArg Name="Speed"><Description>
        Vehicle speed.
    </Description><Units:meter_per_second/><Value>1</Value></DefineArg>

    <DefineArg Name="MissionTimeout"><Description>
        Maximum duration of mission
    </Description><Units:hour/><Value>9</Value></DefineArg>

    <DefineArg Name="MassDefault"><Description>
        Static setting for mass during the mission. Defaults to massDefault
        setting in the Config/Control.cfg file.
    </Description><Control:VerticalControl.massDefault/></DefineArg>

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

<!-- Waypoint list -->

    <DefineArg Name="WpESPInshoreLat"><Description>
        Latitude of inshore ESP buoy.
    </Description><Units:degree/><Value>33.607614</Value></DefineArg>

    <DefineArg Name="WpESPInshoreLon"><Description>
        Longitude of offshore ESP buoy.
    </Description><Units:degree/><Value>-118.018798</Value></DefineArg>

    <DefineArg Name="WpESPOffshoreLat"><Description>
        Latitude of offshore ESP buoy.
    </Description><Units:degree/><Value>33.585471</Value></DefineArg>

    <DefineArg Name="WpESPOffshoreLon"><Description>
        Longitude of offshore ESP buoy.
    </Description><Units:degree/><Value>-118.037372</Value></DefineArg>

<!--
ESP Buoys are separated by 3000 m                                          
at bearing 35.06,                                              
or bearing -144.93

In[36]: from pyproj import Geod

In[37]: g = Geod(ellps='WGS84')

In [38]: g.inv(WpESPInshoreLon,WpESPInshoreLat,WpESPOffshoreLon,WpESPOffshoreLat)
Out[38]: (-144.92923671982575, 35.06048579554712, 3000.758382977905)
-->

<!--
az0 = 122.892896z0 = 122.892896
WpCorner1Lon, WpCorner1Lat, a = g.fwd(WpESPInshoreLon, WpESPInshoreLat, az0, 4300)
WpCorner2Lon, WpCorner2Lat, a = g.fwd(WpCorner1Lon, WpCorner1Lat, az00+90, 3000)
WpCorner3Lon, WpCorner3Lat, a = g.fwd(WpESPOffshoreLon, WpESPOffshoreLat, az00+180, 4300)
WpCorner4Lon, WpCorner4Lat, a = g.fwd(WpESPInshoreLon, WpESPInshoreLat, az00-180, 4300)

-->

    <DefineArg Name="WpCorner1Lat"><Description>
        Latitude of waypoint for first corner of box.
    </Description><Units:degree/><Value>33.586554427309956</Value></DefineArg>

    <DefineArg Name="WpCorner1Lon"><Description>
        Longitude of waypoint for first corner of box.
    </Description><Units:degree/><Value>-117.97990263671926</Value></DefineArg>

    <DefineArg Name="WpCorner2Lat"><Description>
        Latitude of waypoint for second corner of box.
    </Description><Units:degree/><Value>33.563841488839024</Value></DefineArg>

    <DefineArg Name="WpCorner2Lon"><Description>
        Longitude of waypoint for second corner of box.
    </Description><Units:degree/><Value>-117.99744852771295</Value></DefineArg>

    <DefineArg Name="WpCorner3Lat"><Description>
        Latitude of waypoint for third corner of box.
    </Description><Units:degree/><Value>33.60651834669941</Value></DefineArg>

    <DefineArg Name="WpCorner3Lon"><Description>
        Longitude of waypoint for third corner of box.
    </Description><Units:degree/><Value>-118.076275825578</Value></DefineArg>

    <DefineArg Name="WpCorner4Lat"><Description>
        Latitude of waypoint for fourth corner of box.
    </Description><Units:degree/><Value>33.628662266112016</Value></DefineArg>

    <DefineArg Name="WpCorner4Lon"><Description>
        Longitude of waypoint for fourth corner of box.
    </Description><Units:degree/><Value>-118.05771227683994</Value></DefineArg>

<!-- Approach Settings -->

    <DefineArg Name="ApproachDepth"><Description>
        Depth for initial approach to WpCorner1.
    </Description><Units:meter/><Value>10.0</Value></DefineArg>

    <DefineArg Name="ApproachTimeout"><Description>
        Maximum duration of initial approach
    </Description><Units:hour/><Value>4</Value></DefineArg>

    <DefineArg Name="ApproachNeedCommsTime"><Description>
        Elapsed time after previous surface communications when vehicle will
        begin to ascend for additional surface communications. Only active
        during the approach.
    </Description><Units:minute/><Value>20</Value></DefineArg>

<!-- Science loop settings -->

    <DefineArg Name="Repeat"><Description>
        Number of times to repeat the science loop
    </Description><Units:count/><Value>13</Value></DefineArg>

    <DefineArg Name="CircleRadius"><Description>
        Radius of circle around Inshore ESP during wait time
    </Description><Units:meter/><Value>500</Value></DefineArg>

    <DefineArg Name="CircleRepeat"><Description>
        Maximum number of times to circle the wayopint at the start of each lap.
    </Description><Units:count/><Value>13</Value></DefineArg>

    <DefineArg Name="CircleDivisor"><Description>
        UTC time between reporting events. (e.g., "set CircleDivisor 8 hour" for
        reports at 0000, 0800, 1600 UTC)
    </Description><Units:hour/><Value>2</Value></DefineArg>

    <DefineArg Name="CircleModulus"><Description>
        Current time modulo CircleDivisor (internal variable).
    </Description><Units:hour/><Value>NaN</Value></DefineArg>

    <DefineArg Name="CircleTimeout"><Description>
        Timeout for circling buoy at start of each lap (internal variable).
    </Description><Units:hour/><Value>3</Value></DefineArg>

    <DefineArg Name="LapTimeout"><Description>
        Maximum duration of lap around box.
    </Description><Units:hour/><Value>8</Value></DefineArg>

    <DefineArg Name="SCPITimeout"><Description>
        Request data from the SCPI for this long.
    </Description><Units:second/><Value>150</Value></DefineArg>

    <DefineArg Name="YoYoMinDepth"><Description>
        Minimum depth during yo-yo's.
    </Description><Units:meter/><Value>4.0</Value></DefineArg>

    <DefineArg Name="YoYoMaxDepth"><Description>
        Maximum depth during yo-yo's.
    </Description><Units:meter/><Value>78.0</Value></DefineArg>

    <DefineArg Name="YoYoMinAltitude"><Description>
        Min altitude while in yo-yo mode.
    </Description><Units:meter/><Value>6.0</Value></DefineArg>

    <DefineArg Name="YoYoUpPitch"><Description>
        Pitch when yo-yo's are ascending.
    </Description><Units:degree/><Value>20.0</Value></DefineArg>

    <DefineArg Name="YoYoDownPitch"><Description>
        Pitch when yo-yo's are descending.
    </Description><Units:degree/><Value>-20.0</Value></DefineArg>

<!-- Variables used internally during the mission -->

<!-- The mission -->

    <Timeout Duration="MissionTimeout"/>

<!-- High-priority directives that should always be near the top -->

    <Guidance:AltitudeEnvelope>
        <Parallel/>
        <Setting><Guidance:AltitudeEnvelope.minAltitude/><Arg Name="MinAltitude"/></Setting>
    </Guidance:AltitudeEnvelope>

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

    <Guidance:OffshoreEnvelope>
        <Parallel/>
        <Setting><Guidance:OffshoreEnvelope.minOffshore/><Arg Name="MinOffshore"/></Setting>
    </Guidance:OffshoreEnvelope>

<!-- High-level NeedComms helpful for field debugging. -->

    <Insert Filename="Insert/NeedComms.xml" Id="NeedComms"/>

<!-- NOTE: The <Assign> clauses below will not take effect until you actually run the mission. RedefineArg will not work in this case if you use a "set" after loading the mission. -->

    <Assign><Sequence/><Arg Name="NeedComms:DiveInterval"/><Arg Name="NeedCommsTime"/></Assign>

    <Assign><Sequence/><Arg Name="NeedComms:SurfaceSpeed"/><Arg Name="Speed"/></Assign>

<!-- Surfacing behaviors -->

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

    <Insert Filename="Insert/SurfaceCommsSplit.xml" Id="SurfaceCommsSplit"/>

    <Insert Filename="Insert/SurfaceCommsShort.xml" Id="SurfaceCommsShort"/>

    <Insert Filename="Insert/SurfaceGPS.xml" Id="SurfaceGPS"/>

    <Insert Filename="Insert/SurfaceSafety.xml" Id="SurfaceSafety"/>

<!-- TODO put all of these together into a master Surface insert file -->

<!-- mass and buoyancy defaults are lower priority than surfacing, but higher than everything else -->

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

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

<!-- Begin callable aggregates used in this mission. 
     (Note priority still matters, so these are done _below_ important safety 
     directives like OffshoreEnvelope.) 
     -->

    <Insert Filename="Insert/CircleWaypointRepeatedly.xml"/>

    <Aggregate Id="UpdateCircleTimeout">

        <Description>
            Calculate (current time) mod (CircleDivisor) and determine when to
            stop circling the start-of-lap waypoint.
        </Description>

        <When>
            <Called/>
        </When>

        <Assign><Sequence/><Arg Name="CircleModulus"/><Universal:time/><Mod><Arg Name="CircleDivisor"/>
        </Mod></Assign>

<!-- TODO 
            Might need to add an offset in somewhere to handle specific 
            surfacing times (e.g., 2am, 10pm)
             
            It would be even more useful to have a general method for 
            TimeUntil(arg).
        -->

        <Syslog Severity="Important">CircleModulus calculated as: <Arg Name="CircleModulus"/><Units:hour/></Syslog>

        <Assign><Sequence/><Arg Name="CircleTimeout"/><Arg Name="CircleDivisor"/><Sub><Arg Name="CircleModulus"/></Sub></Assign>

        <Syslog Severity="Important">CircleTimeout updated to: <Arg Name="CircleTimeout"/><Units:hour/></Syslog>

    </Aggregate>

    <Aggregate Id="CircleInshoreESPBuoy">

        <Description>
            Circle a waypoint at the nominal location of the Inshore ESP buoy
            until timeout specified by CircleDivisor and current time.
        </Description>

        <When>
            <Called/>
        </When>

        <Call RefId="UpdateCircleTimeout"/>

        <Aggregate Id="TellMeHowLong">

            <Description>
                Convenience aggregate to notify operator of estimated circling
                time _before_ starting to circle the waypoint. May be commented
                out, since the Timeout in CircleWaypointRepeatedly will still
                achieve the desired behavior.
            </Description>

            <Sequence/>

            <Syslog Severity="Important">CircleInshoreESPBuoy should complete in <Arg Name="CircleTimeout"/><Units:minute/>, due to timeout in CircleWaypointRepeatedly aggregate.</Syslog>

            <Call RefId="SurfaceCommsShort"/>

        </Aggregate>

        <Assign><Sequence/><Arg Name="CircleWaypointRepeatedly:Timeout"/><Arg Name="CircleTimeout"/></Assign>

        <Assign><Sequence/><Arg Name="CircleWaypointRepeatedly:Radius"/><Arg Name="CircleRadius"/></Assign>

        <Assign><Sequence/><Arg Name="CircleWaypointRepeatedly:CenterLat"/><Arg Name="WpESPInshoreLat"/></Assign>

        <Assign><Sequence/><Arg Name="CircleWaypointRepeatedly:CenterLon"/><Arg Name="WpESPInshoreLon"/></Assign>

<!-- Use default values for: Timeout, MaxError, TurnToPort, KwpHeading -->

        <Call RefId="CircleWaypointRepeatedly"/>

        <Syslog Severity="Important">**** Finished circling. ****</Syslog>

        <Call RefId="SurfaceCommsSplit"/>

    </Aggregate>

    <Aggregate Id="Lap">

        <Description>
            Run around the box.
        </Description>

        <When>
            <Called/>
        </When>

        <Timeout Duration="LapTimeout"/>

        <Guidance:Waypoint Id="WpESPInshore">
            <Sequence/>
            <Setting><Guidance:Waypoint.latitude/><Arg Name="WpESPInshoreLat"/></Setting>
            <Setting><Guidance:Waypoint.longitude/><Arg Name="WpESPInshoreLon"/></Setting>
        </Guidance:Waypoint>

        <Call RefId="SurfaceCommsShort"/>

        <Guidance:Waypoint Id="WpCorner1">
            <Sequence/>
            <Setting><Guidance:Waypoint.latitude/><Arg Name="WpCorner1Lat"/></Setting>
            <Setting><Guidance:Waypoint.longitude/><Arg Name="WpCorner1Lon"/></Setting>
        </Guidance:Waypoint>

        <Call RefId="SurfaceCommsShort"/>

        <Guidance:Waypoint Id="WpCorner2">
            <Sequence/>
            <Setting><Guidance:Waypoint.latitude/><Arg Name="WpCorner2Lat"/></Setting>
            <Setting><Guidance:Waypoint.longitude/><Arg Name="WpCorner2Lon"/></Setting>
        </Guidance:Waypoint>

        <Call RefId="SurfaceCommsShort"/>

        <Guidance:Waypoint Id="WpESPOffshore">
            <Sequence/>
            <Setting><Guidance:Waypoint.latitude/><Arg Name="WpESPOffshoreLat"/></Setting>
            <Setting><Guidance:Waypoint.longitude/><Arg Name="WpESPOffshoreLon"/></Setting>
        </Guidance:Waypoint>

        <Call RefId="SurfaceCommsShort"/>

        <Aggregate Id="CircleOffshoreESPBuoy">

            <Sequence/>

            <Assign><Sequence/><Arg Name="CircleWaypointRepeatedly:MaxLaps"/><Units:count/><Value>2.0</Value></Assign>

            <Assign><Sequence/><Arg Name="CircleWaypointRepeatedly:Timeout"/><Arg Name="CircleTimeout"/></Assign>

            <Assign><Sequence/><Arg Name="CircleWaypointRepeatedly:Radius"/><Arg Name="CircleRadius"/></Assign>

            <Assign><Sequence/><Arg Name="CircleWaypointRepeatedly:CenterLat"/><Arg Name="WpESPOffshoreLat"/></Assign>

            <Assign><Sequence/><Arg Name="CircleWaypointRepeatedly:CenterLon"/><Arg Name="WpESPOffshoreLon"/></Assign>

<!-- Use default values for: Timeout, MaxError, TurnToPort, KwpHeading -->

            <Call RefId="CircleWaypointRepeatedly"/>

            <Syslog Severity="Important">**** Finished circling. ****</Syslog>

            <Call RefId="SurfaceCommsShort"/>

        </Aggregate>

        <Guidance:Waypoint Id="WpCorner3">
            <Sequence/>
            <Setting><Guidance:Waypoint.latitude/><Arg Name="WpCorner3Lat"/></Setting>
            <Setting><Guidance:Waypoint.longitude/><Arg Name="WpCorner3Lon"/></Setting>
        </Guidance:Waypoint>

        <Call RefId="SurfaceCommsShort"/>

        <Guidance:Waypoint Id="WpCorner4">
            <Sequence/>
            <Setting><Guidance:Waypoint.latitude/><Arg Name="WpCorner4Lat"/></Setting>
            <Setting><Guidance:Waypoint.longitude/><Arg Name="WpCorner4Lon"/></Setting>
        </Guidance:Waypoint>

        <Call RefId="SurfaceCommsShort"/>

        <Guidance:Waypoint Id="WpESPInshore">
            <Sequence/>
            <Setting><Guidance:Waypoint.latitude/><Arg Name="WpESPInshoreLat"/></Setting>
            <Setting><Guidance:Waypoint.longitude/><Arg Name="WpESPInshoreLon"/></Setting>
        </Guidance:Waypoint>

        <Call RefId="SurfaceCommsShort"/>

    </Aggregate>

<!-- End callable aggregates used in this mission. -->

    <Aggregate Id="Approach">

        <Description>
            Get to start point.
        </Description>

        <Sequence/>

        <Timeout Duration="ApproachTimeout"/>

        <Aggregate>

            <Description>
                Check in periodically, but do not split logs
            </Description>

            <When>
                <Elapsed><Universal:platform_communications/></Elapsed>
                <Gt><Arg Name="ApproachNeedCommsTime"/></Gt>
            </When>

            <Call RefId="SurfaceCommsShort"/>

        </Aggregate>

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

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

        <Guidance:Waypoint Id="WpApproach">
            <Sequence/>
            <Setting><Guidance:Waypoint.latitude/><Arg Name="WpESPInshoreLat"/></Setting>
            <Setting><Guidance:Waypoint.longitude/><Arg Name="WpESPInshoreLon"/></Setting>
        </Guidance:Waypoint>

<!-- Consider removing the SurfaceComms call at the end of the approach. -->

        <Call RefId="SurfaceComms"/>

    </Aggregate>

    <Aggregate Id="ScienceOps">

        <Description>
            Circle then lap many times, collecting science data.
        </Description>

        <Sequence Repeat="Repeat"/>

        <Insert Filename="Insert/Science.xml" Id="Science">
            <Description>
                Get science data, including PeakDetectChl
            </Description>
            <RedefineArg Name="PeakDetectChlActive"><True/></RedefineArg>
            <RedefineArg Name="SampleISUS"><True/></RedefineArg>
            <RedefineArg Name="SampleISUSmaxPitch"><Units:degree/><Value>30.0</Value></RedefineArg>
            <RedefineArg Name="SampleISUSminPitch"><Units:degree/><Value>10.0</Value></RedefineArg>
            <RedefineArg Name="ComputeWaterCurrent"><False/></RedefineArg>
            <RedefineArg Name="UpwardDerivativeOfTemperatureActive"><False/></RedefineArg>
        </Insert>

<!-- compute Vertical Temperature Homogeneity Index -->

        <Insert Filename="Insert/VerticalTemperatureHomogeneityIndex.xml" Id="VTHIdx">
            <RedefineArg Name="DepthShallow"><Units:meter/><Value>5</Value></RedefineArg>
            <RedefineArg Name="DepthMidShallow"><Units:meter/><Value>10</Value></RedefineArg>
            <RedefineArg Name="DepthMidDeep"><Units:meter/><Value>20</Value></RedefineArg>
            <RedefineArg Name="DepthDeep"><Units:meter/><Value>25</Value></RedefineArg>
            <RedefineArg Name="Verbosity"><Units:count/><Value>1</Value></RedefineArg>
        </Insert>

<!-- SCPI activation -->

        <Aggregate Id="RollSCPI">

            <Description>
                Turn on the SCPI camera. (SCPI.sampleTime is set in Sensor.cfg)
            </Description>

            <When>
                <Universal:depth/>
                <Lt><Units:meter/><Value>40</Value></Lt>
                <And><CustomUri Uri="SCPI.loadAtStartup"/></And>
            </When>

            <Timeout Duration="SCPITimeout"/>

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

<!--            <Syslog Severity="Important">rolling SCPI</Syslog> -->

        </Aggregate>

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

        <Guidance:DepthEnvelope>
            <Parallel/>
            <Setting><Guidance:DepthEnvelope.minDepth/><Arg Name="YoYoMinDepth"/></Setting>
            <Setting><Guidance:DepthEnvelope.maxDepth/><Arg Name="YoYoMaxDepth"/></Setting>
            <Setting><Guidance:DepthEnvelope.downPitch/><Arg Name="YoYoDownPitch"/></Setting>
            <Setting><Guidance:DepthEnvelope.upPitch/><Arg Name="YoYoUpPitch"/></Setting>
        </Guidance:DepthEnvelope>

        <Guidance:AltitudeEnvelope>
            <Parallel/>
            <Setting><Guidance:AltitudeEnvelope.minAltitude/><Arg Name="YoYoMinAltitude"/></Setting>
            <Setting><Guidance:AltitudeEnvelope.upPitch/><Arg Name="YoYoUpPitch"/></Setting>
        </Guidance:AltitudeEnvelope>

        <Guidance:YoYo>
            <Parallel/>
            <Setting><Guidance:YoYo.downPitch/><Arg Name="YoYoDownPitch"/></Setting>
            <Setting><Guidance:YoYo.upPitch/><Arg Name="YoYoUpPitch"/></Setting>
        </Guidance:YoYo>

<!-- Call the behavior aggregates that we defined above. -->

        <Call RefId="CircleInshoreESPBuoy"/>

        <Call RefId="Lap"/>

    </Aggregate>

</Mission>


2014-05-09T22:50:38.112Z,1399675838.112 [CommandLine](IMPORTANT): Loaded ./Missions/Science/EcoHAB_box.xml
2014-05-09T22:50:42.189Z,1399675842.189 [CommandLine](IMPORTANT): got command set EcoHAB_box.NeedCommsTime 30.000000 minute
2014-05-09T22:50:42.190Z,1399675842.190 [CommandLine](IMPORTANT): got command set EcoHAB_box.MissionTimeout 65.000000 hour
2014-05-09T22:50:42.191Z,1399675842.191 [CommandLine](IMPORTANT): got command set EcoHAB_box.LapTimeout 12.000000 hour
2014-05-09T22:50:42.191Z,1399675842.191 [CommandLine](IMPORTANT): got command run 
2014-05-09T22:50:42.206Z,1399675842.206 [CommandLine](IMPORTANT): Running 
2014-05-09T22:50:42.669Z,1399675842.669 [SBIT](IMPORTANT): SBIT PASSED
2014-05-09T22:50:42.732Z,1399675842.732 [DataOverHttps](IMPORTANT): SBD MTMSN=20140509T225033
2014-05-09T22:50:42.781Z,1399675842.781 [MissionManager](IMPORTANT): Started mission Startup
2014-05-09T22:50:42.781Z,1399675842.781 [Startup] Running Loop=1
2014-05-09T22:50:42.781Z,1399675842.781 [Startup](INFO): Aggregate::initialize Startup
2014-05-09T22:50:42.781Z,1399675842.781 [Startup:A.GoToSurface] Running Loop=1
2014-05-09T22:50:42.781Z,1399675842.781 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-09T22:50:42.788Z,1399675842.788 [Startup:StartupSatComms] Running Loop=1
2014-05-09T22:50:42.788Z,1399675842.788 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-05-09T22:50:42.788Z,1399675842.788 [Startup:StartupSatComms:A] Running Loop=1
2014-05-09T22:50:43.153Z,1399675843.153 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-05-09T22:50:43.503Z,1399675843.503 [NAL9602](INFO): Powering up
2014-05-09T22:50:44.630Z,1399675844.630 [DataOverHttps](INFO): Received command:! grep "Thread ID" /mnt/mmc/LRAUV/Logs/latest/syslog | tee /mnt/mmc/LRAUV/Logs/latest/threads
2014-05-09T22:50:44.722Z,1399675844.722 [CommandLine](IMPORTANT): got command ! grep "Thread ID" /mnt/mmc/LRAUV/Logs/latest/syslog | tee /mnt/mmc/LRAUV/Logs/latest/threads
2014-05-09T22:50:44.841Z,1399675844.841 [CommandLine](IMPORTANT): 2014-05-09T22:49:16.004Z,1399675756.004 [SyncHandler](INFO): Protected caller Thread ID is 779
2014-05-09T22:49:16.008Z,1399675756.008 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 780
2014-05-09T22:49:16.024Z,1399675756.024 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 781
2014-05-09T22:49:16.028Z,1399675756.028 [logger ThreadHandler](INFO): Protected caller Thread ID is 782
2014-05-09T22:49:22.374Z,1399675762.374 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 864
2014-05-09T22:49:23.243Z,1399675763.243 [AsyncPiEstimator ThreadHandler](INFO): Protected caller Thread ID is 867
2014-05-09T22:49:23.896Z,1399675763.896 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 868
2014-05-09T22:49:23.968Z,1399675763.968 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 869
2014-05-09T22:49:24.801Z,1399675764.801 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 870
2014-05-09T22:49:24.808Z,1399675764.808 [Supervisor](INFO): Main Thread ID is 767
2014-05-09T22:49:24.809Z,1399675764.809 [CommandLine ThreadHandler](INFO): Handler Thread ID is 871
2014-05-09T22:49:24.814Z,1399675764.814 [controlThread ThreadHandler](INFO): Handler Thread ID is 872
2014-05-09T22:49:24.818Z,1399675764.818 [logger ThreadHandler](INFO): Handler Thread ID is 873
2014-05-09T22:49:24.854Z,1399675764.854 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 874
2014-05-09T22:49:24.866Z,1399675764.866 [AsyncPiEstimator ThreadHandler](INFO): Handler Thread ID is 875
2014-05-09T22:49:24.890Z,1399675764.890 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 876
2014-05-09T22:49:24.910Z,1399675764.910 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 877
2014-05-09T22:49:24.926Z,1399675764.926 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 878

2014-05-09T22:50:48.973Z,1399675848.973 [NAL9602](IMPORTANT): GPS fix at: 1399675848.97
2014-05-09T22:50:49.018Z,1399675849.018 [Startup:StartupSatComms:A] Stopped
2014-05-09T22:50:49.018Z,1399675849.018 [Startup:StartupSatComms:B] Running Loop=1
2014-05-09T22:50:49.389Z,1399675849.389 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-05-09T22:50:50.223Z,1399675850.223 [NAL9602](INFO): No messages in MT queue
2014-05-09T22:50:51.597Z,1399675851.597 [DataOverHttps](INFO): Sending 295 bytes from file Logs/20140509T224915/Courier0000.lzma
2014-05-09T22:50:52.292Z,1399675852.292 [DataOverHttps](INFO): Moved sent file to Logs/20140509T224915/Courier0000.lzma.bak
2014-05-09T22:50:52.292Z,1399675852.292 [DataOverHttps](IMPORTANT): SBD MOMSN=940083, MTMSN=20140509T225051
2014-05-09T22:50:54.549Z,1399675854.549 [DataOverHttps](INFO): Received command:! top -b -d 5 -H -p 767 > /mnt/mmc/LRAUV/Logs/latest/toplog &
2014-05-09T22:50:54.557Z,1399675854.557 [CommandLine](IMPORTANT): got command ! top -b -d 5 -H -p 767 > /mnt/mmc/LRAUV/Logs/latest/toplog &
2014-05-09T22:50:57.121Z,1399675857.121 [NAL9602](INFO): Powering down
2014-05-09T22:50:57.241Z,1399675857.241 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:50:57.261Z,1399675857.261 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20140509T224915/Courier0004.lzma
2014-05-09T22:50:57.975Z,1399675857.975 [DataOverHttps](INFO): Moved sent file to Logs/20140509T224915/Courier0004.lzma.bak
2014-05-09T22:50:57.975Z,1399675857.975 [DataOverHttps](INFO): SBD MOMSN=940087
2014-05-09T22:50:59.907Z,1399675859.907 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:01.894Z,1399675861.894 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:02.602Z,1399675862.602 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20140509T224915/Courier0008.lzma
2014-05-09T22:51:03.444Z,1399675863.444 [DataOverHttps](INFO): Moved sent file to Logs/20140509T224915/Courier0008.lzma.bak
2014-05-09T22:51:03.444Z,1399675863.444 [DataOverHttps](INFO): SBD MOMSN=940089
2014-05-09T22:51:04.590Z,1399675864.590 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:06.806Z,1399675866.806 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:07.800Z,1399675867.800 [DataOverHttps](INFO): Sending 1349 bytes from file Logs/20140509T224915/Express0001.lzma
2014-05-09T22:51:08.628Z,1399675868.628 [DataOverHttps](INFO): Moved sent file to Logs/20140509T224915/Express0001.lzma.bak
2014-05-09T22:51:08.628Z,1399675868.628 [DataOverHttps](INFO): SBD MOMSN=940091
2014-05-09T22:51:08.970Z,1399675868.970 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:11.554Z,1399675871.554 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:14.119Z,1399675874.119 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:15.514Z,1399675875.514 [DataOverHttps](INFO): Sending 47 bytes from file Logs/20140509T224915/Express0005.lzma
2014-05-09T22:51:16.307Z,1399675876.307 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:16.337Z,1399675876.337 [DataOverHttps](INFO): Moved sent file to Logs/20140509T224915/Express0005.lzma.bak
2014-05-09T22:51:16.337Z,1399675876.337 [DataOverHttps](INFO): SBD MOMSN=940116
2014-05-09T22:51:18.572Z,1399675878.572 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:20.684Z,1399675880.684 [DataOverHttps](INFO): Sending 197 bytes from file Logs/20140509T224915/Express0009.lzma
2014-05-09T22:51:21.132Z,1399675881.132 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:21.442Z,1399675881.442 [DataOverHttps](INFO): Moved sent file to Logs/20140509T224915/Express0009.lzma.bak
2014-05-09T22:51:21.442Z,1399675881.442 [DataOverHttps](INFO): SBD MOMSN=940118
2014-05-09T22:51:21.881Z,1399675881.881 [Startup:StartupSatComms:B] Stopped
2014-05-09T22:51:21.882Z,1399675881.882 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2014-05-09T22:51:21.882Z,1399675881.882 [Startup:StartupSatComms] Stopped
2014-05-09T22:51:21.882Z,1399675881.882 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2014-05-09T22:51:21.887Z,1399675881.887 [Startup](INFO): Completed Startup
2014-05-09T22:51:21.887Z,1399675881.887 [Startup] Stopped
2014-05-09T22:51:21.887Z,1399675881.887 [Startup](INFO): Aggregate::uninitialize Startup
2014-05-09T22:51:21.887Z,1399675881.887 [Startup:A.GoToSurface] Stopped
2014-05-09T22:51:21.887Z,1399675881.887 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-09T22:51:22.295Z,1399675882.295 [MissionManager](IMPORTANT): Started mission EcoHAB_box
2014-05-09T22:51:22.295Z,1399675882.295 [EcoHAB_box] Running Loop=1
2014-05-09T22:51:22.295Z,1399675882.295 [EcoHAB_box](INFO): Aggregate::initialize EcoHAB_box
2014-05-09T22:51:22.295Z,1399675882.295 [EcoHAB_box:A.AltitudeEnvelope] Running Loop=1
2014-05-09T22:51:22.295Z,1399675882.295 [EcoHAB_box:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2014-05-09T22:51:22.296Z,1399675882.296 [EcoHAB_box:B.DepthEnvelope] Running Loop=1
2014-05-09T22:51:22.296Z,1399675882.296 [EcoHAB_box:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2014-05-09T22:51:22.296Z,1399675882.296 [EcoHAB_box:C.OffshoreEnvelope] Running Loop=1
2014-05-09T22:51:22.296Z,1399675882.296 [EcoHAB_box:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2014-05-09T22:51:22.296Z,1399675882.296 [EcoHAB_box:L.Pitch] Running Loop=1
2014-05-09T22:51:22.296Z,1399675882.296 [EcoHAB_box:L.Pitch](DEBUG): Initialize.
2014-05-09T22:51:22.297Z,1399675882.297 [EcoHAB_box:M.Buoyancy] Running Loop=1
2014-05-09T22:51:22.297Z,1399675882.297 [EcoHAB_box:M.Buoyancy](DEBUG): Initialize Buoyancy Component.
2014-05-09T22:51:22.297Z,1399675882.297 [EcoHAB_box:E] Running Loop=1
2014-05-09T22:51:22.298Z,1399675882.298 [EcoHAB_box:M.Buoyancy] Running Loop=1
2014-05-09T22:51:22.331Z,1399675882.331 [EcoHAB_box:L.Pitch] Running Loop=1
2014-05-09T22:51:22.351Z,1399675882.351 [EcoHAB_box:E] Stopped
2014-05-09T22:51:22.351Z,1399675882.351 [EcoHAB_box:F] Running Loop=1
2014-05-09T22:51:22.351Z,1399675882.351 [EcoHAB_box:C.OffshoreEnvelope] Running Loop=1
2014-05-09T22:51:22.357Z,1399675882.357 [EcoHAB_box:B.DepthEnvelope] Running Loop=1
2014-05-09T22:51:22.375Z,1399675882.375 [EcoHAB_box:A.AltitudeEnvelope] Running Loop=1
2014-05-09T22:51:23.188Z,1399675883.188 [EcoHAB_box:F] Stopped
2014-05-09T22:51:23.188Z,1399675883.188 [EcoHAB_box:SurfaceComms] Running Loop=1
2014-05-09T22:51:23.188Z,1399675883.188 [EcoHAB_box:SurfaceComms](INFO): Aggregate::initialize EcoHAB_box:SurfaceComms
2014-05-09T22:51:23.188Z,1399675883.188 [EcoHAB_box:SurfaceComms:A.GoToSurface] Running Loop=1
2014-05-09T22:51:23.189Z,1399675883.189 [EcoHAB_box:SurfaceComms:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-09T22:51:23.335Z,1399675883.335 [EcoHAB_box:SurfaceComms:B] Running Loop=1
2014-05-09T22:51:23.335Z,1399675883.335 [EcoHAB_box:SurfaceComms:B](INFO): Aggregate::initialize EcoHAB_box:SurfaceComms:B
2014-05-09T22:51:23.335Z,1399675883.335 [EcoHAB_box:SurfaceComms:B:A] Running Loop=1
2014-05-09T22:51:23.722Z,1399675883.722 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:23.791Z,1399675883.791 [EcoHAB_box:SurfaceComms:B] Stopped
2014-05-09T22:51:23.791Z,1399675883.791 [EcoHAB_box:SurfaceComms:B](INFO): Aggregate::uninitialize EcoHAB_box:SurfaceComms:B
2014-05-09T22:51:23.791Z,1399675883.791 [EcoHAB_box:SurfaceComms:B:A] Stopped
2014-05-09T22:51:23.791Z,1399675883.791 [EcoHAB_box:SurfaceComms:C] Running Loop=1
2014-05-09T22:51:23.792Z,1399675883.792 [EcoHAB_box:SurfaceComms:C](INFO): Aggregate::initialize EcoHAB_box:SurfaceComms:C
2014-05-09T22:51:23.792Z,1399675883.792 [EcoHAB_box:SurfaceComms:C:A] Running Loop=1
2014-05-09T22:51:24.074Z,1399675884.074 [EcoHAB_box:M.Buoyancy] Preempted
2014-05-09T22:51:24.074Z,1399675884.074 [EcoHAB_box:L.Pitch] Preempted
2014-05-09T22:51:24.075Z,1399675884.075 [EcoHAB_box:SurfaceComms:C:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-05-09T22:51:24.434Z,1399675884.434 [NAL9602](INFO): Powering up
2014-05-09T22:51:25.670Z,1399675885.670 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:28.070Z,1399675888.070 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:29.633Z,1399675889.633 [NAL9602](IMPORTANT): GPS fix at: 1399675889.63
2014-05-09T22:51:29.669Z,1399675889.669 [EcoHAB_box:SurfaceComms:C:A] Stopped
2014-05-09T22:51:29.669Z,1399675889.669 [EcoHAB_box:SurfaceComms:C:B] Running Loop=1
2014-05-09T22:51:30.048Z,1399675890.048 [EcoHAB_box:SurfaceComms:C:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-05-09T22:51:30.470Z,1399675890.470 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:30.835Z,1399675890.835 [NAL9602](INFO): No messages in MT queue
2014-05-09T22:51:32.054Z,1399675892.054 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20140509T224915/Courier0012.lzma
2014-05-09T22:51:32.842Z,1399675892.842 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:32.876Z,1399675892.876 [DataOverHttps](INFO): Moved sent file to Logs/20140509T224915/Courier0012.lzma.bak
2014-05-09T22:51:32.876Z,1399675892.876 [DataOverHttps](INFO): SBD MOMSN=940122
2014-05-09T22:51:33.600Z,1399675893.600 [CommandLine](IMPORTANT): got command get depth
2014-05-09T22:51:33.601Z,1399675893.601 [CommandLine](IMPORTANT): depth -0.000060 m
2014-05-09T22:51:35.431Z,1399675895.431 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:37.080Z,1399675897.080 [NAL9602](INFO): Powering down
2014-05-09T22:51:37.601Z,1399675897.601 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:39.780Z,1399675899.780 [DataOverHttps](INFO): Sending 148 bytes from file Logs/20140509T224915/Express0013.lzma
2014-05-09T22:51:40.162Z,1399675900.162 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:42.122Z,1399675902.122 [DataOverHttps](INFO): Moved sent file to Logs/20140509T224915/Express0013.lzma.bak
2014-05-09T22:51:42.122Z,1399675902.122 [DataOverHttps](INFO): SBD MOMSN=940124
2014-05-09T22:51:42.560Z,1399675902.560 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:42.610Z,1399675902.610 [EcoHAB_box:SurfaceComms:C:B] Stopped
2014-05-09T22:51:42.615Z,1399675902.615 [EcoHAB_box:SurfaceComms:C:C] Running Loop=1
2014-05-09T22:51:42.966Z,1399675902.966 [EcoHAB_box:SurfaceComms:C:C](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-05-09T22:51:43.834Z,1399675903.834 [NAL9602](INFO): Powering up
2014-05-09T22:51:44.764Z,1399675904.764 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:47.164Z,1399675907.164 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:48.730Z,1399675908.730 [NAL9602](IMPORTANT): GPS fix at: 1399675908.72
2014-05-09T22:51:48.746Z,1399675908.746 [EcoHAB_box:SurfaceComms:C:C] Stopped
2014-05-09T22:51:48.746Z,1399675908.746 [EcoHAB_box:SurfaceComms:C](INFO): Completed EcoHAB_box:SurfaceComms:C
2014-05-09T22:51:48.746Z,1399675908.746 [EcoHAB_box:SurfaceComms:C] Stopped
2014-05-09T22:51:48.746Z,1399675908.746 [EcoHAB_box:SurfaceComms:C](INFO): Aggregate::uninitialize EcoHAB_box:SurfaceComms:C
2014-05-09T22:51:48.747Z,1399675908.747 [EcoHAB_box:SurfaceComms](INFO): Completed EcoHAB_box:SurfaceComms
2014-05-09T22:51:48.747Z,1399675908.747 [EcoHAB_box:SurfaceComms] Stopped
2014-05-09T22:51:48.747Z,1399675908.747 [EcoHAB_box:SurfaceComms](INFO): Aggregate::uninitialize EcoHAB_box:SurfaceComms
2014-05-09T22:51:48.747Z,1399675908.747 [EcoHAB_box:SurfaceComms:A.GoToSurface] Stopped
2014-05-09T22:51:48.748Z,1399675908.748 [EcoHAB_box:SurfaceComms:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-09T22:51:48.748Z,1399675908.748 [EcoHAB_box:SurfaceGPS] Running Loop=1
2014-05-09T22:51:48.749Z,1399675908.749 [EcoHAB_box:SurfaceGPS](INFO): Aggregate::initialize EcoHAB_box:SurfaceGPS
2014-05-09T22:51:48.749Z,1399675908.749 [EcoHAB_box:SurfaceGPS:A.GoToSurface] Running Loop=1
2014-05-09T22:51:48.749Z,1399675908.749 [EcoHAB_box:SurfaceGPS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-09T22:51:49.245Z,1399675909.245 [EcoHAB_box:M.Buoyancy] Running Loop=1
2014-05-09T22:51:49.246Z,1399675909.246 [EcoHAB_box:L.Pitch] Running Loop=1
2014-05-09T22:51:49.252Z,1399675909.252 [EcoHAB_box:SurfaceGPS:GetFix] Running Loop=1
2014-05-09T22:51:49.252Z,1399675909.252 [EcoHAB_box:SurfaceGPS:GetFix](INFO): Aggregate::initialize EcoHAB_box:SurfaceGPS:GetFix
2014-05-09T22:51:49.252Z,1399675909.252 [EcoHAB_box:SurfaceGPS:GetFix:A] Running Loop=1
2014-05-09T22:51:49.565Z,1399675909.565 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:49.606Z,1399675909.606 [EcoHAB_box:SurfaceGPS:GetFix:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-05-09T22:51:49.933Z,1399675909.933 [NAL9602](INFO): No messages in MT queue
2014-05-09T22:51:51.944Z,1399675911.944 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:53.939Z,1399675913.939 [NAL9602](IMPORTANT): GPS fix at: 1399675913.93
2014-05-09T22:51:53.991Z,1399675913.991 [EcoHAB_box:SurfaceGPS:GetFix:A] Stopped
2014-05-09T22:51:53.991Z,1399675913.991 [EcoHAB_box:SurfaceGPS:GetFix](INFO): Completed EcoHAB_box:SurfaceGPS:GetFix
2014-05-09T22:51:53.991Z,1399675913.991 [EcoHAB_box:SurfaceGPS:GetFix] Stopped
2014-05-09T22:51:53.991Z,1399675913.991 [EcoHAB_box:SurfaceGPS:GetFix](INFO): Aggregate::uninitialize EcoHAB_box:SurfaceGPS:GetFix
2014-05-09T22:51:53.992Z,1399675913.992 [EcoHAB_box:SurfaceGPS:GetFix](INFO): Running loop #2
2014-05-09T22:51:53.992Z,1399675913.992 [EcoHAB_box:SurfaceGPS:GetFix] Running Loop=2
2014-05-09T22:51:53.992Z,1399675913.992 [EcoHAB_box:SurfaceGPS:GetFix](INFO): Aggregate::initialize EcoHAB_box:SurfaceGPS:GetFix
2014-05-09T22:51:53.992Z,1399675913.992 [EcoHAB_box:SurfaceGPS:GetFix:A] Running Loop=1
2014-05-09T22:51:54.419Z,1399675914.419 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:56.764Z,1399675916.764 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:51:58.327Z,1399675918.327 [NAL9602](IMPORTANT): GPS fix at: 1399675918.32
2014-05-09T22:51:58.382Z,1399675918.382 [EcoHAB_box:SurfaceGPS:GetFix:A] Stopped
2014-05-09T22:51:58.382Z,1399675918.382 [EcoHAB_box:SurfaceGPS:GetFix](INFO): Completed EcoHAB_box:SurfaceGPS:GetFix
2014-05-09T22:51:58.382Z,1399675918.382 [EcoHAB_box:SurfaceGPS:GetFix] Stopped
2014-05-09T22:51:58.383Z,1399675918.383 [EcoHAB_box:SurfaceGPS:GetFix](INFO): Aggregate::uninitialize EcoHAB_box:SurfaceGPS:GetFix
2014-05-09T22:51:58.388Z,1399675918.388 [EcoHAB_box:SurfaceGPS](INFO): Completed EcoHAB_box:SurfaceGPS
2014-05-09T22:51:58.388Z,1399675918.388 [EcoHAB_box:SurfaceGPS] Stopped
2014-05-09T22:51:58.388Z,1399675918.388 [EcoHAB_box:SurfaceGPS](INFO): Aggregate::uninitialize EcoHAB_box:SurfaceGPS
2014-05-09T22:51:58.388Z,1399675918.388 [EcoHAB_box:SurfaceGPS:A.GoToSurface] Stopped
2014-05-09T22:51:58.388Z,1399675918.388 [EcoHAB_box:SurfaceGPS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-09T22:51:58.388Z,1399675918.388 [EcoHAB_box:Approach] Running Loop=1
2014-05-09T22:51:58.388Z,1399675918.388 [EcoHAB_box:Approach](INFO): Aggregate::initialize EcoHAB_box:Approach
2014-05-09T22:51:58.388Z,1399675918.388 [EcoHAB_box:Approach:B.Pitch] Running Loop=1
2014-05-09T22:51:58.388Z,1399675918.388 [EcoHAB_box:Approach:B.Pitch](DEBUG): Initialize.
2014-05-09T22:51:58.389Z,1399675918.389 [EcoHAB_box:Approach:C.SetSpeed] Running Loop=1
2014-05-09T22:51:58.389Z,1399675918.389 [EcoHAB_box:Approach:C.SetSpeed](DEBUG): Initialize.
2014-05-09T22:51:58.389Z,1399675918.389 [EcoHAB_box:Approach:WpApproach.Waypoint] Running Loop=1
2014-05-09T22:51:58.389Z,1399675918.389 [EcoHAB_box:Approach:WpApproach.Waypoint](DEBUG): Initialize WaypointComponent.
2014-05-09T22:51:58.784Z,1399675918.784 [EcoHAB_box:Approach:C.SetSpeed] Running Loop=1
2014-05-09T22:51:58.793Z,1399675918.793 [EcoHAB_box:Approach:B.Pitch] Running Loop=1
2014-05-09T22:51:59.230Z,1399675919.230 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:52:01.567Z,1399675921.567 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:52:03.964Z,1399675923.964 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:52:04.403Z,1399675924.403 [NAL9602](INFO): Powering down
2014-05-09T22:52:06.361Z,1399675926.361 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:52:08.763Z,1399675928.763 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:52:11.163Z,1399675931.163 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:52:13.566Z,1399675933.566 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:52:15.567Z,1399675935.567 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:52:17.968Z,1399675937.968 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:52:20.365Z,1399675940.365 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-05-09T22:52:51.104Z,1399675971.104 [CommandLine](IMPORTANT): got command get depth
2014-05-09T22:52:51.109Z,1399675971.109 [CommandLine](IMPORTANT): depth 0.140746 m
2014-05-09T22:53:00.091Z,1399675980.091 [Radio_Freewave](INFO): Powering down
2014-05-09T22:54:41.188Z,1399676081.188 [CommandLine](IMPORTANT): got command get depth
2014-05-09T22:54:41.188Z,1399676081.188 [CommandLine](IMPORTANT): depth 9.354476 m
2014-05-09T22:55:06.236Z,1399676106.236 [CommandLine](IMPORTANT): got command get latitude
2014-05-09T22:55:06.237Z,1399676106.237 [CommandLine](IMPORTANT): latitude 33.608847 arcdeg
2014-05-09T22:55:17.613Z,1399676117.613 [CommandLine](IMPORTANT): got command get latitude
2014-05-09T22:55:17.613Z,1399676117.613 [CommandLine](IMPORTANT): latitude 33.608757 arcdeg
2014-05-09T22:55:24.508Z,1399676124.508 [CommandLine](IMPORTANT): got command get longitude
2014-05-09T22:55:24.508Z,1399676124.508 [CommandLine](IMPORTANT): longitude -118.019392 arcdeg
2014-05-09T22:55:34.058Z,1399676134.058 [CommandLine](IMPORTANT): got command get longitude
2014-05-09T22:55:34.058Z,1399676134.058 [CommandLine](IMPORTANT): longitude -118.019348 arcdeg
2014-05-09T22:57:37.329Z,1399676257.329 [EcoHAB_box:Approach:WpApproach.Waypoint](INFO): Reached Waypoint: 33.607614,-118.018798
2014-05-09T22:57:37.329Z,1399676257.329 [EcoHAB_box:Approach:WpApproach.Waypoint] Stopped
2014-05-09T22:57:37.329Z,1399676257.329 [EcoHAB_box:Approach:WpApproach.Waypoint](DEBUG): Uninitialize WaypointComponent.
2014-05-09T22:57:37.330Z,1399676257.330 [EcoHAB_box:Approach:E] Running Loop=1
2014-05-09T22:57:37.330Z,1399676257.330 [EcoHAB_box:Approach:E](INFO): Aggregate::initialize EcoHAB_box:Approach:E
2014-05-09T22:57:37.684Z,1399676257.684 [EcoHAB_box:SurfaceComms] Running Loop=1
2014-05-09T22:57:37.684Z,1399676257.684 [EcoHAB_box:SurfaceComms](INFO): Aggregate::initialize EcoHAB_box:SurfaceComms
2014-05-09T22:57:37.684Z,1399676257.684 [EcoHAB_box:SurfaceComms:A.GoToSurface] Running Loop=1
2014-05-09T22:57:37.684Z,1399676257.684 [EcoHAB_box:SurfaceComms:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-09T22:58:16.784Z,1399676296.784 [EcoHAB_box:SurfaceComms:B] Running Loop=1
2014-05-09T22:58:16.784Z,1399676296.784 [EcoHAB_box:SurfaceComms:B](INFO): Aggregate::initialize EcoHAB_box:SurfaceComms:B
2014-05-09T22:58:16.784Z,1399676296.784 [EcoHAB_box:SurfaceComms:B:A] Running Loop=1
2014-05-09T22:58:16.999Z,1399676296.999 [Radio_Freewave](INFO): Powering up
2014-05-09T22:58:17.174Z,1399676297.174 [EcoHAB_box:SurfaceComms:B] Stopped
2014-05-09T22:58:17.174Z,1399676297.174 [EcoHAB_box:SurfaceComms:B](INFO): Aggregate::uninitialize EcoHAB_box:SurfaceComms:B
2014-05-09T22:58:17.174Z,1399676297.174 [EcoHAB_box:SurfaceComms:B:A] Stopped
2014-05-09T22:58:17.175Z,1399676297.175 [EcoHAB_box:SurfaceComms:C] Running Loop=1
2014-05-09T22:58:17.175Z,1399676297.175 [EcoHAB_box:SurfaceComms:C](INFO): Aggregate::initialize EcoHAB_box:SurfaceComms:C
2014-05-09T22:58:17.175Z,1399676297.175 [EcoHAB_box:SurfaceComms:C:A] Running Loop=1
2014-05-09T22:58:17.613Z,1399676297.613 [EcoHAB_box:M.Buoyancy] Preempted
2014-05-09T22:58:17.613Z,1399676297.613 [EcoHAB_box:L.Pitch] Preempted
2014-05-09T22:58:17.934Z,1399676297.934 [NAL9602](INFO): Powering up
2014-05-09T22:58:18.205Z,1399676298.205 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0
2014-05-09T22:58:23.284Z,1399676303.284 [NAL9602](IMPORTANT): GPS fix at: 1399676303.28
2014-05-09T22:58:23.347Z,1399676303.347 [EcoHAB_box:SurfaceComms:C:A] Stopped
2014-05-09T22:58:23.347Z,1399676303.347 [EcoHAB_box:SurfaceComms:C:B] Running Loop=1
2014-05-09T22:58:24.491Z,1399676304.491 [NAL9602](INFO): No messages in MT queue
2014-05-09T22:58:25.585Z,1399676305.585 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20140509T224915/Courier0016.lzma
2014-05-09T22:58:26.495Z,1399676306.495 [DataOverHttps](INFO): Moved sent file to Logs/20140509T224915/Courier0016.lzma.bak
2014-05-09T22:58:26.495Z,1399676306.495 [DataOverHttps](INFO): SBD MOMSN=940150
2014-05-09T22:58:30.761Z,1399676310.761 [NAL9602](INFO): Powering down
2014-05-09T22:58:33.517Z,1399676313.517 [DataOverHttps](INFO): Sending 673 bytes from file Logs/20140509T224915/Express0017.lzma
2014-05-09T22:58:34.291Z,1399676314.291 [DataOverHttps](INFO): Moved sent file to Logs/20140509T224915/Express0017.lzma.bak
2014-05-09T22:58:34.291Z,1399676314.291 [DataOverHttps](INFO): SBD MOMSN=940152
2014-05-09T22:58:34.737Z,1399676314.737 [EcoHAB_box:SurfaceComms:C:B] Stopped
2014-05-09T22:58:34.737Z,1399676314.737 [EcoHAB_box:SurfaceComms:C:C] Running Loop=1
2014-05-09T22:58:35.997Z,1399676315.997 [NAL9602](INFO): Powering up
2014-05-09T22:58:40.910Z,1399676320.910 [NAL9602](IMPORTANT): GPS fix at: 1399676320.90
2014-05-09T22:58:40.965Z,1399676320.965 [EcoHAB_box:SurfaceComms:C:C] Stopped
2014-05-09T22:58:40.965Z,1399676320.965 [EcoHAB_box:SurfaceComms:C](INFO): Completed EcoHAB_box:SurfaceComms:C
2014-05-09T22:58:40.965Z,1399676320.965 [EcoHAB_box:SurfaceComms:C] Stopped
2014-05-09T22:58:40.965Z,1399676320.965 [EcoHAB_box:SurfaceComms:C](INFO): Aggregate::uninitialize EcoHAB_box:SurfaceComms:C
2014-05-09T22:58:40.966Z,1399676320.966 [EcoHAB_box:SurfaceComms](INFO): Completed EcoHAB_box:SurfaceComms
2014-05-09T22:58:40.966Z,1399676320.966 [EcoHAB_box:SurfaceComms] Stopped
2014-05-09T22:58:40.966Z,1399676320.966 [EcoHAB_box:SurfaceComms](INFO): Aggregate::uninitialize EcoHAB_box:SurfaceComms
2014-05-09T22:58:40.967Z,1399676320.967 [EcoHAB_box:SurfaceComms:A.GoToSurface] Stopped
2014-05-09T22:58:40.967Z,1399676320.967 [EcoHAB_box:SurfaceComms:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-09T22:58:41.363Z,1399676321.363 [EcoHAB_box:Approach:E](INFO): Completed EcoHAB_box:Approach:E
2014-05-09T22:58:41.363Z,1399676321.363 [EcoHAB_box:Approach:E] Stopped
2014-05-09T22:58:41.363Z,1399676321.363 [EcoHAB_box:Approach:E](INFO): Aggregate::uninitialize EcoHAB_box:Approach:E
2014-05-09T22:58:41.364Z,1399676321.364 [EcoHAB_box:Approach](INFO): Completed EcoHAB_box:Approach
2014-05-09T22:58:41.364Z,1399676321.364 [EcoHAB_box:Approach] Stopped
2014-05-09T22:58:41.364Z,1399676321.364 [EcoHAB_box:Approach](INFO): Aggregate::uninitialize EcoHAB_box:Approach
2014-05-09T22:58:41.364Z,1399676321.364 [EcoHAB_box:Approach:B.Pitch] Stopped
2014-05-09T22:58:41.364Z,1399676321.364 [EcoHAB_box:Approach:C.SetSpeed] Stopped
2014-05-09T22:58:41.365Z,1399676321.365 [EcoHAB_box:Approach:C.SetSpeed](DEBUG): Uninitialize.
2014-05-09T22:58:41.365Z,1399676321.365 [EcoHAB_box:ScienceOps] Running Loop=1
2014-05-09T22:58:41.365Z,1399676321.365 [EcoHAB_box:ScienceOps](INFO): Aggregate::initialize EcoHAB_box:ScienceOps
2014-05-09T22:58:41.365Z,1399676321.365 [EcoHAB_box:ScienceOps:Science] Running Loop=1
2014-05-09T22:58:41.365Z,1399676321.365 [EcoHAB_box:ScienceOps:Science](INFO): Aggregate::initialize EcoHAB_box:ScienceOps:Science
2014-05-09T22:58:41.365Z,1399676321.365 [EcoHAB_box:ScienceOps:Science:A] Running Loop=1
2014-05-09T22:58:41.365Z,1399676321.365 [EcoHAB_box:ScienceOps:Science:B] Running Loop=1
2014-05-09T22:58:41.365Z,1399676321.365 [EcoHAB_box:ScienceOps:Science:C] Running Loop=1
2014-05-09T22:58:41.365Z,1399676321.365 [EcoHAB_box:ScienceOps:Science:D] Running Loop=1
2014-05-09T22:58:41.365Z,1399676321.365 [EcoHAB_box:ScienceOps:Science:E] Running Loop=1
2014-05-09T22:58:41.366Z,1399676321.366 [EcoHAB_box:ScienceOps:Science:F] Running Loop=1
2014-05-09T22:58:41.366Z,1399676321.366 [EcoHAB_box:ScienceOps:Science:G] Running Loop=1
2014-05-09T22:58:41.366Z,1399676321.366 [EcoHAB_box:ScienceOps:Science:PeakDetectChl] Running Loop=1
2014-05-09T22:58:41.366Z,1399676321.366 [EcoHAB_box:ScienceOps:Science:PeakDetectChl](INFO): Aggregate::initialize EcoHAB_box:ScienceOps:Science:PeakDetectChl
2014-05-09T22:58:41.366Z,1399676321.366 [EcoHAB_box:ScienceOps:Science:PeakDetectChl:A.PeakDetectVsDepth] Running Loop=1
2014-05-09T22:58:41.366Z,1399676321.366 [EcoHAB_box:ScienceOps:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Initialize.
2014-05-09T22:58:41.368Z,1399676321.368 [EcoHAB_box:ScienceOps:Science:PeakDetectNO3] Running Loop=1
2014-05-09T22:58:41.377Z,1399676321.377 [EcoHAB_box:ScienceOps:Science:PeakDetectNO3](INFO): Aggregate::initialize EcoHAB_box:ScienceOps:Science:PeakDetectNO3
2014-05-09T22:58:41.377Z,1399676321.377 [EcoHAB_box:ScienceOps:Science:PeakDetectNO3:A.PeakDetectVsDepth] Running Loop=1
2014-05-09T22:58:41.377Z,1399676321.377 [EcoHAB_box:ScienceOps:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Initialize.
2014-05-09T22:58:41.378Z,1399676321.378 [EcoHAB_box:ScienceOps:D.SetSpeed] Running Loop=1
2014-05-09T22:58:41.378Z,1399676321.378 [EcoHAB_box:ScienceOps:D.SetSpeed](DEBUG): Initialize.
2014-05-09T22:58:41.378Z,1399676321.378 [EcoHAB_box:ScienceOps:E.DepthEnvelope] Running Loop=1
2014-05-09T22:58:41.379Z,1399676321.379 [EcoHAB_box:ScienceOps:E.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2014-05-09T22:58:41.379Z,1399676321.379 [EcoHAB_box:ScienceOps:F.AltitudeEnvelope] Running Loop=1
2014-05-09T22:58:41.379Z,1399676321.379 [EcoHAB_box:ScienceOps:F.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2014-05-09T22:58:41.379Z,1399676321.379 [EcoHAB_box:ScienceOps:G.YoYo] Running Loop=1
2014-05-09T22:58:41.379Z,1399676321.379 [EcoHAB_box:ScienceOps:G.YoYo](DEBUG): Initialize YoYoComponent.
2014-05-09T22:58:41.380Z,1399676321.380 [EcoHAB_box:ScienceOps:VTHIdx] Running Loop=1
2014-05-09T22:58:41.380Z,1399676321.380 [EcoHAB_box:ScienceOps:VTHIdx](INFO): Aggregate::initialize EcoHAB_box:ScienceOps:VTHIdx
2014-05-09T22:58:41.380Z,1399676321.380 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures] Running Loop=1
2014-05-09T22:58:41.380Z,1399676321.380 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures](INFO): Aggregate::initialize EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures
2014-05-09T22:58:41.380Z,1399676321.380 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectShallow.ValueDetect] Running Loop=1
2014-05-09T22:58:41.380Z,1399676321.380 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectShallow.ValueDetect](DEBUG): Initialize.
2014-05-09T22:58:41.381Z,1399676321.381 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectShallow.ValueDetect](INFO): Initialize with detect=depth
2014-05-09T22:58:41.382Z,1399676321.382 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectShallow.ValueDetect](INFO): Initialize with output=sea_water_temperature
2014-05-09T22:58:41.383Z,1399676321.383 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectMidShallow.ValueDetect] Running Loop=1
2014-05-09T22:58:41.383Z,1399676321.383 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectMidShallow.ValueDetect](DEBUG): Initialize.
2014-05-09T22:58:41.383Z,1399676321.383 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectMidShallow.ValueDetect](INFO): Initialize with detect=depth
2014-05-09T22:58:41.393Z,1399676321.393 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectMidShallow.ValueDetect](INFO): Initialize with output=sea_water_temperature
2014-05-09T22:58:41.394Z,1399676321.394 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectMidDeep.ValueDetect] Running Loop=1
2014-05-09T22:58:41.394Z,1399676321.394 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectMidDeep.ValueDetect](DEBUG): Initialize.
2014-05-09T22:58:41.394Z,1399676321.394 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectMidDeep.ValueDetect](INFO): Initialize with detect=depth
2014-05-09T22:58:41.395Z,1399676321.395 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectMidDeep.ValueDetect](INFO): Initialize with output=sea_water_temperature
2014-05-09T22:58:41.396Z,1399676321.396 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectDeep.ValueDetect] Running Loop=1
2014-05-09T22:58:41.397Z,1399676321.397 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectDeep.ValueDetect](DEBUG): Initialize.
2014-05-09T22:58:41.397Z,1399676321.397 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectDeep.ValueDetect](INFO): Initialize with detect=depth
2014-05-09T22:58:41.397Z,1399676321.397 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectDeep.ValueDetect](INFO): Initialize with output=sea_water_temperature
2014-05-09T22:58:41.399Z,1399676321.399 [EcoHAB_box:M.Buoyancy] Running Loop=1
2014-05-09T22:58:41.399Z,1399676321.399 [EcoHAB_box:L.Pitch] Running Loop=1
2014-05-09T22:58:41.912Z,1399676321.912 [EcoHAB_box:ScienceOps:G.YoYo] Running Loop=1
2014-05-09T22:58:41.918Z,1399676321.918 [EcoHAB_box:ScienceOps:F.AltitudeEnvelope] Running Loop=1
2014-05-09T22:58:41.939Z,1399676321.939 [EcoHAB_box:ScienceOps:E.DepthEnvelope] Running Loop=1
2014-05-09T22:58:41.945Z,1399676321.945 [EcoHAB_box:ScienceOps:D.SetSpeed] Running Loop=1
2014-05-09T22:58:41.962Z,1399676321.962 [EcoHAB_box:ScienceOps:RollSCPI] Running Loop=1
2014-05-09T22:58:41.962Z,1399676321.962 [EcoHAB_box:ScienceOps:RollSCPI](INFO): Aggregate::initialize EcoHAB_box:ScienceOps:RollSCPI
2014-05-09T22:58:41.962Z,1399676321.962 [EcoHAB_box:ScienceOps:RollSCPI:A] Running Loop=1
2014-05-09T22:58:41.963Z,1399676321.963 [EcoHAB_box:ScienceOps:RollSCPI:A] Running Loop=1
2014-05-09T22:58:41.963Z,1399676321.963 [EcoHAB_box:ScienceOps:RollSCPI:A](DEBUG): Initialize ReadDataComponent to sense SCPI.sampleSCPI
2014-05-09T22:58:41.976Z,1399676321.976 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectDeep.ValueDetect] Running Loop=1
2014-05-09T22:58:41.994Z,1399676321.994 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectMidDeep.ValueDetect] Running Loop=1
2014-05-09T22:58:41.999Z,1399676321.999 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectMidShallow.ValueDetect] Running Loop=1
2014-05-09T22:58:42.016Z,1399676322.016 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectShallow.ValueDetect] Running Loop=1
2014-05-09T22:58:42.029Z,1399676322.029 [EcoHAB_box:ScienceOps:Science] Running Loop=1
2014-05-09T22:58:42.059Z,1399676322.059 [EcoHAB_box:ScienceOps:Science:PeakDetectNO3] Stopped
2014-05-09T22:58:42.059Z,1399676322.059 [EcoHAB_box:ScienceOps:Science:PeakDetectNO3](INFO): Aggregate::uninitialize EcoHAB_box:ScienceOps:Science:PeakDetectNO3
2014-05-09T22:58:42.059Z,1399676322.059 [EcoHAB_box:ScienceOps:Science:PeakDetectNO3:A.PeakDetectVsDepth] Stopped
2014-05-09T22:58:42.059Z,1399676322.059 [EcoHAB_box:ScienceOps:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2014-05-09T22:58:42.059Z,1399676322.059 [EcoHAB_box:ScienceOps:Science:PeakDetectChl] Running Loop=1
2014-05-09T22:58:42.064Z,1399676322.064 [EcoHAB_box:ScienceOps:Science:G] Running Loop=1
2014-05-09T22:58:42.065Z,1399676322.065 [EcoHAB_box:ScienceOps:Science:G](DEBUG): Initialize ReadDataComponent to sense mass_concentration_of_chlorophyll_in_sea_water
2014-05-09T22:58:42.067Z,1399676322.067 [EcoHAB_box:ScienceOps:Science:F] Stopped
2014-05-09T22:58:42.067Z,1399676322.067 [EcoHAB_box:ScienceOps:Science:E] Stopped
2014-05-09T22:58:42.067Z,1399676322.067 [EcoHAB_box:ScienceOps:Science:D] Running Loop=1
2014-05-09T22:58:42.068Z,1399676322.068 [EcoHAB_box:ScienceOps:Science:D](DEBUG): Initialize ReadDataComponent to sense sea_water_temperature
2014-05-09T22:58:42.069Z,1399676322.069 [EcoHAB_box:ScienceOps:Science:D](DEBUG): Initialize ReadDataComponent to sense sea_water_salinity
2014-05-09T22:58:42.086Z,1399676322.086 [EcoHAB_box:ScienceOps:Science:C] Stopped
2014-05-09T22:58:42.086Z,1399676322.086 [EcoHAB_box:ScienceOps:Science:B] Stopped
2014-05-09T22:58:42.086Z,1399676322.086 [EcoHAB_box:ScienceOps:Science:A] Stopped
2014-05-09T22:58:42.279Z,1399676322.279 [NAL9602](INFO): No messages in MT queue
2014-05-09T22:58:42.318Z,1399676322.318 [SCPI](INFO): Powering up
2014-05-09T22:58:42.770Z,1399676322.770 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:43.175Z,1399676323.175 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:43.580Z,1399676323.580 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:43.984Z,1399676323.984 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:44.389Z,1399676324.389 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:44.765Z,1399676324.765 [SCPI](INFO): Init failed - response: 
2014-05-09T22:58:44.765Z,1399676324.765 [SCPI](FAULT): SCPI failed to initialize
2014-05-09T22:58:44.766Z,1399676324.766 [SCPI] Communications Fault, FailCount= 1
2014-05-09T22:58:44.766Z,1399676324.766 [SCPI](ERROR): Communications Fault
2014-05-09T22:58:44.794Z,1399676324.794 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:44.835Z,1399676324.835 [CBIT](ERROR): Communications Fault in component: SCPI
2014-05-09T22:58:45.064Z,1399676325.064 [SCPI](INFO): Powering down
2014-05-09T22:58:45.198Z,1399676325.198 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:45.603Z,1399676325.603 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:45.947Z,1399676325.947 [SCPI](INFO): Powering up
2014-05-09T22:58:46.008Z,1399676326.008 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:46.046Z,1399676326.046 [CBIT](INFO): Clearing failed state for component SCPI
2014-05-09T22:58:46.046Z,1399676326.046 [SCPI] No Fault, FailCount= 1
2014-05-09T22:58:46.412Z,1399676326.412 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:46.818Z,1399676326.818 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:47.221Z,1399676327.221 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:47.626Z,1399676327.626 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:47.861Z,1399676327.861 [NAL9602](INFO): Powering down
2014-05-09T22:58:48.031Z,1399676328.031 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:48.343Z,1399676328.343 [SCPI](INFO): Init failed - response: ÿ
2014-05-09T22:58:48.343Z,1399676328.343 [SCPI](FAULT): SCPI failed to initialize
2014-05-09T22:58:48.343Z,1399676328.343 [SCPI] Communications Fault, FailCount= 2
2014-05-09T22:58:48.343Z,1399676328.343 [SCPI](ERROR): Communications Fault
2014-05-09T22:58:48.406Z,1399676328.406 [CBIT](ERROR): Communications Fault in component: SCPI
2014-05-09T22:58:48.435Z,1399676328.435 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:48.664Z,1399676328.664 [SCPI](INFO): Powering down
2014-05-09T22:58:48.840Z,1399676328.840 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:49.244Z,1399676329.244 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:49.561Z,1399676329.561 [SCPI](INFO): Powering up
2014-05-09T22:58:49.649Z,1399676329.649 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:49.721Z,1399676329.721 [CBIT](INFO): Clearing failed state for component SCPI
2014-05-09T22:58:49.721Z,1399676329.721 [SCPI] No Fault, FailCount= 2
2014-05-09T22:58:50.054Z,1399676330.054 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:50.458Z,1399676330.458 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:50.863Z,1399676330.863 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:51.268Z,1399676331.268 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:51.618Z,1399676331.618 [Radio_Freewave](INFO): Powering down
2014-05-09T22:58:51.672Z,1399676331.672 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:51.712Z,1399676331.712 [SCPI](INFO): Init failed - response: ÿ
2014-05-09T22:58:51.712Z,1399676331.712 [SCPI](FAULT): SCPI failed to initialize
2014-05-09T22:58:51.713Z,1399676331.713 [SCPI] Communications Fault, FailCount= 3
2014-05-09T22:58:51.713Z,1399676331.713 [SCPI](ERROR): Communications Fault
2014-05-09T22:58:51.838Z,1399676331.838 [CBIT](ERROR): Communications Fault in component: SCPI
2014-05-09T22:58:51.839Z,1399676331.839 [CBIT](CRITICAL): Communications Fault in component: SCPI
2014-05-09T22:58:51.996Z,1399676331.996 [SCPI](INFO): Powering down
2014-05-09T22:58:52.077Z,1399676332.077 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:52.173Z,1399676332.173 [CommandLine](FAULT): Scheduling is paused
2014-05-09T22:58:52.353Z,1399676332.353 [EcoHAB_box] Stopped
2014-05-09T22:58:52.353Z,1399676332.353 [EcoHAB_box](INFO): Aggregate::uninitialize EcoHAB_box
2014-05-09T22:58:52.354Z,1399676332.354 [EcoHAB_box:A.AltitudeEnvelope] Stopped
2014-05-09T22:58:52.354Z,1399676332.354 [EcoHAB_box:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2014-05-09T22:58:52.354Z,1399676332.354 [EcoHAB_box:B.DepthEnvelope] Stopped
2014-05-09T22:58:52.354Z,1399676332.354 [EcoHAB_box:B.DepthEnvelope](DEBUG): Uninitialize.
2014-05-09T22:58:52.354Z,1399676332.354 [EcoHAB_box:C.OffshoreEnvelope] Stopped
2014-05-09T22:58:52.354Z,1399676332.354 [EcoHAB_box:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2014-05-09T22:58:52.354Z,1399676332.354 [EcoHAB_box:L.Pitch] Stopped
2014-05-09T22:58:52.354Z,1399676332.354 [EcoHAB_box:M.Buoyancy] Stopped
2014-05-09T22:58:52.354Z,1399676332.354 [EcoHAB_box:M.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2014-05-09T22:58:52.354Z,1399676332.354 [EcoHAB_box:ScienceOps] Stopped
2014-05-09T22:58:52.354Z,1399676332.354 [EcoHAB_box:ScienceOps](INFO): Aggregate::uninitialize EcoHAB_box:ScienceOps
2014-05-09T22:58:52.355Z,1399676332.355 [EcoHAB_box:ScienceOps:Science] Stopped
2014-05-09T22:58:52.355Z,1399676332.355 [EcoHAB_box:ScienceOps:Science](INFO): Aggregate::uninitialize EcoHAB_box:ScienceOps:Science
2014-05-09T22:58:52.355Z,1399676332.355 [EcoHAB_box:ScienceOps:Science:D] Stopped
2014-05-09T22:58:52.355Z,1399676332.355 [EcoHAB_box:ScienceOps:Science:G] Stopped
2014-05-09T22:58:52.355Z,1399676332.355 [EcoHAB_box:ScienceOps:Science:PeakDetectChl] Stopped
2014-05-09T22:58:52.355Z,1399676332.355 [EcoHAB_box:ScienceOps:Science:PeakDetectChl](INFO): Aggregate::uninitialize EcoHAB_box:ScienceOps:Science:PeakDetectChl
2014-05-09T22:58:52.355Z,1399676332.355 [EcoHAB_box:ScienceOps:Science:PeakDetectChl:A.PeakDetectVsDepth] Stopped
2014-05-09T22:58:52.355Z,1399676332.355 [EcoHAB_box:ScienceOps:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2014-05-09T22:58:52.355Z,1399676332.355 [EcoHAB_box:ScienceOps:VTHIdx] Stopped
2014-05-09T22:58:52.355Z,1399676332.355 [EcoHAB_box:ScienceOps:VTHIdx](INFO): Aggregate::uninitialize EcoHAB_box:ScienceOps:VTHIdx
2014-05-09T22:58:52.356Z,1399676332.356 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures] Stopped
2014-05-09T22:58:52.356Z,1399676332.356 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures](INFO): Aggregate::uninitialize EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures
2014-05-09T22:58:52.356Z,1399676332.356 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectShallow.ValueDetect] Stopped
2014-05-09T22:58:52.356Z,1399676332.356 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectShallow.ValueDetect](DEBUG): Uninitialize.
2014-05-09T22:58:52.356Z,1399676332.356 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectMidShallow.ValueDetect] Stopped
2014-05-09T22:58:52.356Z,1399676332.356 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectMidShallow.ValueDetect](DEBUG): Uninitialize.
2014-05-09T22:58:52.356Z,1399676332.356 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectMidDeep.ValueDetect] Stopped
2014-05-09T22:58:52.356Z,1399676332.356 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectMidDeep.ValueDetect](DEBUG): Uninitialize.
2014-05-09T22:58:52.356Z,1399676332.356 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectDeep.ValueDetect] Stopped
2014-05-09T22:58:52.356Z,1399676332.356 [EcoHAB_box:ScienceOps:VTHIdx:GetTemperatures:DetectDeep.ValueDetect](DEBUG): Uninitialize.
2014-05-09T22:58:52.357Z,1399676332.357 [EcoHAB_box:ScienceOps:RollSCPI] Stopped
2014-05-09T22:58:52.357Z,1399676332.357 [EcoHAB_box:ScienceOps:RollSCPI](INFO): Aggregate::uninitialize EcoHAB_box:ScienceOps:RollSCPI
2014-05-09T22:58:52.357Z,1399676332.357 [EcoHAB_box:ScienceOps:RollSCPI:A] Stopped
2014-05-09T22:58:52.357Z,1399676332.357 [EcoHAB_box:ScienceOps:D.SetSpeed] Stopped
2014-05-09T22:58:52.357Z,1399676332.357 [EcoHAB_box:ScienceOps:D.SetSpeed](DEBUG): Uninitialize.
2014-05-09T22:58:52.357Z,1399676332.357 [EcoHAB_box:ScienceOps:E.DepthEnvelope] Stopped
2014-05-09T22:58:52.357Z,1399676332.357 [EcoHAB_box:ScienceOps:E.DepthEnvelope](DEBUG): Uninitialize.
2014-05-09T22:58:52.357Z,1399676332.357 [EcoHAB_box:ScienceOps:F.AltitudeEnvelope] Stopped
2014-05-09T22:58:52.357Z,1399676332.357 [EcoHAB_box:ScienceOps:F.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2014-05-09T22:58:52.357Z,1399676332.357 [EcoHAB_box:ScienceOps:G.YoYo] Stopped
2014-05-09T22:58:52.357Z,1399676332.357 [EcoHAB_box:ScienceOps:G.YoYo](DEBUG): Uninitialize YoYoComponent.
2014-05-09T22:58:52.482Z,1399676332.482 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2014-05-09T22:58:52.763Z,1399676332.763 [MissionManager](IMPORTANT): Started mission Default
2014-05-09T22:58:52.764Z,1399676332.764 [Default] Running Loop=1
2014-05-09T22:58:52.764Z,1399676332.764 [Default](INFO): Aggregate::initialize Default
2014-05-09T22:58:52.764Z,1399676332.764 [Default:Iridium] Running Loop=1
2014-05-09T22:58:52.764Z,1399676332.764 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-05-09T22:58:52.764Z,1399676332.764 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-05-09T22:58:52.764Z,1399676332.764 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-05-09T22:58:52.765Z,1399676332.765 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-05-09T22:58:52.765Z,1399676332.765 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-09T22:58:52.771Z,1399676332.771 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-05-09T22:58:52.789Z,1399676332.789 [Default:GPS] Running Loop=1
2014-05-09T22:58:52.789Z,1399676332.789 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-05-09T22:58:52.789Z,1399676332.789 [Default:GPS:A.SetSpeed] Running Loop=1
2014-05-09T22:58:52.789Z,1399676332.789 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-05-09T22:58:52.789Z,1399676332.789 [Default:GPS:B.GoToSurface] Running Loop=1
2014-05-09T22:58:52.790Z,1399676332.790 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-09T22:58:52.795Z,1399676332.795 [Default:GPS:A.SetSpeed] Running Loop=1
2014-05-09T22:59:54.940Z,1399676394.940 [Default:Iridium:B.GoToSurface] Stopped
2014-05-09T22:59:54.940Z,1399676394.940 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-09T22:59:54.940Z,1399676394.940 [Default:Iridium:Read_Iridium] Running Loop=1
2014-05-09T22:59:54.941Z,1399676394.941 [Default:GPS:B.GoToSurface] Stopped
2014-05-09T22:59:54.941Z,1399676394.941 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-09T22:59:54.941Z,1399676394.941 [Default:GPS:Read_GPS] Running Loop=1
2014-05-09T22:59:55.120Z,1399676395.120 [Radio_Freewave](INFO): Powering up
2014-05-09T22:59:55.342Z,1399676395.342 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-05-09T22:59:55.347Z,1399676395.347 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-05-09T22:59:55.712Z,1399676395.712 [NAL9602](INFO): Powering up
2014-05-09T22:59:56.325Z,1399676396.325 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0
2014-05-09T22:59:57.529Z,1399676397.529 [DataOverHttps](INFO): Sending 144 bytes from file Logs/20140509T224915/Courier0020.lzma
2014-05-09T22:59:58.323Z,1399676398.323 [DataOverHttps](INFO): Moved sent file to Logs/20140509T224915/Courier0020.lzma.bak
2014-05-09T22:59:58.324Z,1399676398.324 [DataOverHttps](INFO): SBD MOMSN=940173
2014-05-09T23:00:01.368Z,1399676401.368 [NAL9602](IMPORTANT): GPS fix at: 1399676401.36
2014-05-09T23:00:01.409Z,1399676401.409 [Default:GPS:Read_GPS] Stopped
2014-05-09T23:00:01.409Z,1399676401.409 [Default:GPS:D] Running Loop=1
2014-05-09T23:00:01.808Z,1399676401.808 [Default:GPS:D] Stopped
2014-05-09T23:00:01.808Z,1399676401.808 [Default:GPS](INFO): Completed Default:GPS
2014-05-09T23:00:01.808Z,1399676401.808 [Default:GPS] Stopped
2014-05-09T23:00:01.808Z,1399676401.808 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-05-09T23:00:01.808Z,1399676401.808 [Default:GPS:A.SetSpeed] Stopped
2014-05-09T23:00:01.813Z,1399676401.813 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-05-09T23:00:02.841Z,1399676402.841 [NAL9602](INFO): No messages in MT queue
2014-05-09T23:00:05.412Z,1399676405.412 [DataOverHttps](INFO): Sending 399 bytes from file Logs/20140509T224915/Express0021.lzma
2014-05-09T23:00:06.191Z,1399676406.191 [DataOverHttps](INFO): Moved sent file to Logs/20140509T224915/Express0021.lzma.bak
2014-05-09T23:00:06.191Z,1399676406.191 [DataOverHttps](INFO): SBD MOMSN=940176
2014-05-09T23:00:06.628Z,1399676406.628 [Default:Iridium:Read_Iridium] Stopped
2014-05-09T23:00:06.629Z,1399676406.629 [Default:Iridium](INFO): Completed Default:Iridium
2014-05-09T23:00:06.629Z,1399676406.629 [Default:Iridium] Stopped
2014-05-09T23:00:06.629Z,1399676406.629 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-05-09T23:00:06.629Z,1399676406.629 [Default:Iridium:A.SetSpeed] Stopped
2014-05-09T23:00:06.629Z,1399676406.629 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-05-09T23:00:06.629Z,1399676406.629 [Default:WaitAtTheSurface] Running Loop=1
2014-05-09T23:00:06.629Z,1399676406.629 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface
2014-05-09T23:00:06.629Z,1399676406.629 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Running Loop=1
2014-05-09T23:00:06.629Z,1399676406.629 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Initialize.
2014-05-09T23:00:06.630Z,1399676406.630 [Default:WaitAtTheSurface:B.GoToSurface] Running Loop=1
2014-05-09T23:00:06.630Z,1399676406.630 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-09T23:00:07.025Z,1399676407.025 [Default:WaitAtTheSurface:B.GoToSurface] Running Loop=1
2014-05-09T23:00:07.031Z,1399676407.031 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Running Loop=1
2014-05-09T23:00:12.698Z,1399676412.698 [NAL9602](INFO): Powering down
2014-05-09T23:00:37.907Z,1399676437.907 [CommandLine](INFO): End of History
2014-05-09T23:00:37.938Z,1399676437.938 [CommandLine](INFO): End of History
2014-05-09T23:00:37.978Z,1399676437.978 [CommandLine](INFO): End of History
2014-05-09T23:00:38.003Z,1399676438.003 [CommandLine](INFO): End of History
2014-05-09T23:00:38.049Z,1399676438.049 [CommandLine](INFO): End of History
2014-05-09T23:00:38.086Z,1399676438.086 [CommandLine](INFO): End of History
2014-05-09T23:00:38.124Z,1399676438.124 [CommandLine](INFO): End of History
2014-05-09T23:00:38.150Z,1399676438.150 [CommandLine](INFO): End of History
2014-05-09T23:00:38.186Z,1399676438.186 [CommandLine](INFO): End of History
2014-05-09T23:00:38.229Z,1399676438.229 [CommandLine](INFO): End of History
2014-05-09T23:00:38.261Z,1399676438.261 [CommandLine](INFO): End of History
2014-05-09T23:00:38.290Z,1399676438.290 [CommandLine](INFO): End of History
2014-05-09T23:00:38.322Z,1399676438.322 [CommandLine](INFO): End of History
2014-05-09T23:01:02.113Z,1399676462.113 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/SCPI_on.xml
2014-05-09T23:01:02.114Z,1399676462.114 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/SCPI_on.xml
2014-05-09T23:01:02.163Z,1399676462.163 [MissionManager](INFO): DefineArg SCPI_on.MassDefault = 0.000000 n/a
2014-05-09T23:01:02.165Z,1399676462.165 [SCPI_on:A.Pitch](DEBUG): Construct.
2014-05-09T23:01:02.175Z,1399676462.175 [SCPI_on:TestDrive:C.Wait](DEBUG): Construct Wait.
2014-05-09T23:01:02.187Z,1399676462.187 [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>
        <Parallel/>
        <Setting><Guidance:Pitch.massPosition/><Arg Name="MassDefault"/></Setting>
    </Guidance:Pitch>

    <Aggregate Id="TestDrive">

        <Sequence/>

        <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>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>2</Value></Setting>
        </Guidance:Wait>

    </Aggregate>

</Mission>


2014-05-09T23:01:02.189Z,1399676462.189 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/SCPI_on.xml
2014-05-09T23:01:02.327Z,1399676462.327 [Default] Stopped
2014-05-09T23:01:02.327Z,1399676462.327 [Default](INFO): Aggregate::uninitialize Default
2014-05-09T23:01:02.327Z,1399676462.327 [Default:WaitAtTheSurface] Stopped
2014-05-09T23:01:02.328Z,1399676462.328 [Default:WaitAtTheSurface](INFO): Aggregate::uninitialize Default:WaitAtTheSurface
2014-05-09T23:01:02.328Z,1399676462.328 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Stopped
2014-05-09T23:01:02.328Z,1399676462.328 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Uninitialize.
2014-05-09T23:01:02.328Z,1399676462.328 [Default:WaitAtTheSurface:B.GoToSurface] Stopped
2014-05-09T23:01:02.328Z,1399676462.328 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-09T23:01:02.328Z,1399676462.328 [MissionManager](IMPORTANT): Started mission SCPI_on
2014-05-09T23:01:02.328Z,1399676462.328 [SCPI_on] Running Loop=1
2014-05-09T23:01:02.328Z,1399676462.328 [SCPI_on](INFO): Aggregate::initialize SCPI_on
2014-05-09T23:01:02.328Z,1399676462.328 [SCPI_on:A.Pitch] Running Loop=1
2014-05-09T23:01:02.328Z,1399676462.328 [SCPI_on:A.Pitch](DEBUG): Initialize.
2014-05-09T23:01:02.330Z,1399676462.330 [SCPI_on:TestDrive] Running Loop=1
2014-05-09T23:01:02.330Z,1399676462.330 [SCPI_on:TestDrive](INFO): Aggregate::initialize SCPI_on:TestDrive
2014-05-09T23:01:02.330Z,1399676462.330 [SCPI_on:TestDrive:A] Running Loop=1
2014-05-09T23:01:02.330Z,1399676462.330 [SCPI_on:TestDrive:C.Wait] Running Loop=1
2014-05-09T23:01:02.330Z,1399676462.330 [SCPI_on:TestDrive:C.Wait](DEBUG): Initialize Wait Component.
2014-05-09T23:01:02.344Z,1399676462.344 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:02.344Z,1399676462.344 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:02.344Z,1399676462.344 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:02.347Z,1399676462.347 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:02.347Z,1399676462.347 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:02.348Z,1399676462.348 [SCPI_on:TestDrive:A] Running Loop=1
2014-05-09T23:01:02.348Z,1399676462.348 [SCPI_on:TestDrive:A](DEBUG): Initialize ReadDataComponent to sense SCPI.sampleSCPI
2014-05-09T23:01:02.350Z,1399676462.350 [SCPI_on:A.Pitch] Running Loop=1
2014-05-09T23:01:02.597Z,1399676462.597 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:02.597Z,1399676462.597 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:02.597Z,1399676462.597 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:02.597Z,1399676462.597 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:02.941Z,1399676462.941 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:02.941Z,1399676462.941 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:02.941Z,1399676462.941 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:02.942Z,1399676462.942 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:02.942Z,1399676462.942 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:03.320Z,1399676463.320 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:03.320Z,1399676463.320 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:03.320Z,1399676463.320 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:03.320Z,1399676463.320 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:03.709Z,1399676463.709 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:03.709Z,1399676463.709 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:03.709Z,1399676463.709 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:03.710Z,1399676463.710 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:03.710Z,1399676463.710 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:04.166Z,1399676464.166 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:04.166Z,1399676464.166 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:04.166Z,1399676464.166 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:04.167Z,1399676464.167 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:04.519Z,1399676464.519 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:04.519Z,1399676464.519 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:04.519Z,1399676464.519 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:04.519Z,1399676464.519 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:04.519Z,1399676464.519 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:04.965Z,1399676464.965 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:04.965Z,1399676464.965 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:04.965Z,1399676464.965 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:04.965Z,1399676464.965 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:05.319Z,1399676465.319 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:05.319Z,1399676465.319 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:05.319Z,1399676465.319 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:05.320Z,1399676465.320 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:05.320Z,1399676465.320 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:05.717Z,1399676465.717 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:05.717Z,1399676465.717 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:05.717Z,1399676465.717 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:05.717Z,1399676465.717 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:06.186Z,1399676466.186 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:06.186Z,1399676466.186 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:06.187Z,1399676466.187 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:06.187Z,1399676466.187 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:06.187Z,1399676466.187 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:06.492Z,1399676466.492 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:06.492Z,1399676466.492 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:06.492Z,1399676466.492 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:06.492Z,1399676466.492 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:06.939Z,1399676466.939 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:06.939Z,1399676466.939 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:06.940Z,1399676466.940 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:06.940Z,1399676466.940 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:06.940Z,1399676466.940 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:07.357Z,1399676467.357 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:07.357Z,1399676467.357 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:07.357Z,1399676467.357 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:07.357Z,1399676467.357 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:08.220Z,1399676468.220 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:08.221Z,1399676468.221 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:08.221Z,1399676468.221 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:08.221Z,1399676468.221 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:08.221Z,1399676468.221 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:08.373Z,1399676468.373 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:08.374Z,1399676468.374 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:08.374Z,1399676468.374 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:08.374Z,1399676468.374 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:08.741Z,1399676468.741 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:08.741Z,1399676468.741 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:08.741Z,1399676468.741 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:08.742Z,1399676468.742 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:08.742Z,1399676468.742 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:09.240Z,1399676469.240 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:09.240Z,1399676469.240 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:09.240Z,1399676469.240 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:09.240Z,1399676469.240 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:09.546Z,1399676469.546 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:09.546Z,1399676469.546 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:09.546Z,1399676469.546 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:09.547Z,1399676469.547 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:09.547Z,1399676469.547 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:09.941Z,1399676469.941 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:09.941Z,1399676469.941 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:09.941Z,1399676469.941 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:09.941Z,1399676469.941 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:10.337Z,1399676470.337 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:10.337Z,1399676470.337 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:10.338Z,1399676470.338 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:10.338Z,1399676470.338 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:10.338Z,1399676470.338 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:10.718Z,1399676470.718 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:10.718Z,1399676470.718 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:10.718Z,1399676470.718 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:10.718Z,1399676470.718 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:11.109Z,1399676471.109 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:11.109Z,1399676471.109 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:11.109Z,1399676471.109 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:11.110Z,1399676471.110 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:11.110Z,1399676471.110 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:11.532Z,1399676471.532 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:11.532Z,1399676471.532 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:11.532Z,1399676471.532 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:11.532Z,1399676471.532 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:11.957Z,1399676471.957 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:11.958Z,1399676471.958 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:11.958Z,1399676471.958 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:11.958Z,1399676471.958 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:11.958Z,1399676471.958 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:12.343Z,1399676472.343 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:12.343Z,1399676472.343 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:12.343Z,1399676472.343 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:12.344Z,1399676472.344 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:12.771Z,1399676472.771 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:12.771Z,1399676472.771 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:12.772Z,1399676472.772 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:12.772Z,1399676472.772 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:12.772Z,1399676472.772 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:13.120Z,1399676473.120 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:13.120Z,1399676473.120 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:13.120Z,1399676473.120 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:13.120Z,1399676473.120 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:13.509Z,1399676473.509 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:13.509Z,1399676473.509 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:13.509Z,1399676473.509 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:13.510Z,1399676473.510 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:13.510Z,1399676473.510 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:13.942Z,1399676473.942 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:13.942Z,1399676473.942 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:13.943Z,1399676473.943 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:13.943Z,1399676473.943 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:14.417Z,1399676474.417 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:14.418Z,1399676474.418 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:14.418Z,1399676474.418 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:14.418Z,1399676474.418 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:14.418Z,1399676474.418 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:14.741Z,1399676474.741 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:14.741Z,1399676474.741 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:14.741Z,1399676474.741 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:14.741Z,1399676474.741 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:15.159Z,1399676475.159 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:15.160Z,1399676475.160 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:15.160Z,1399676475.160 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:15.160Z,1399676475.160 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:15.160Z,1399676475.160 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:15.541Z,1399676475.541 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:15.541Z,1399676475.541 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:15.541Z,1399676475.541 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:15.542Z,1399676475.542 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:15.968Z,1399676475.968 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:15.968Z,1399676475.968 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:15.968Z,1399676475.968 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:15.969Z,1399676475.969 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:15.969Z,1399676475.969 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:16.342Z,1399676476.342 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:16.342Z,1399676476.342 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:16.342Z,1399676476.342 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:16.343Z,1399676476.343 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:16.727Z,1399676476.727 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:16.727Z,1399676476.727 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:16.727Z,1399676476.727 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:16.727Z,1399676476.727 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:16.728Z,1399676476.728 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:17.147Z,1399676477.147 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:17.147Z,1399676477.147 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:17.147Z,1399676477.147 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:17.147Z,1399676477.147 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:17.537Z,1399676477.537 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:17.538Z,1399676477.538 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:17.538Z,1399676477.538 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:17.538Z,1399676477.538 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:17.538Z,1399676477.538 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:17.947Z,1399676477.947 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:17.947Z,1399676477.947 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:17.947Z,1399676477.947 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:17.947Z,1399676477.947 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:18.310Z,1399676478.310 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:18.310Z,1399676478.310 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:18.310Z,1399676478.310 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:18.311Z,1399676478.311 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:18.311Z,1399676478.311 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:18.745Z,1399676478.745 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:18.745Z,1399676478.745 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:18.745Z,1399676478.745 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:18.745Z,1399676478.745 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:19.178Z,1399676479.178 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:19.178Z,1399676479.178 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:19.178Z,1399676479.178 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:19.179Z,1399676479.179 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:19.179Z,1399676479.179 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:19.624Z,1399676479.624 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:19.624Z,1399676479.624 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:19.624Z,1399676479.624 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:19.624Z,1399676479.624 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:19.942Z,1399676479.942 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:19.942Z,1399676479.942 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:19.942Z,1399676479.942 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:19.943Z,1399676479.943 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:19.943Z,1399676479.943 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:20.344Z,1399676480.344 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:20.344Z,1399676480.344 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:20.344Z,1399676480.344 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:20.344Z,1399676480.344 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:20.708Z,1399676480.708 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:20.708Z,1399676480.708 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:20.708Z,1399676480.708 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:20.709Z,1399676480.709 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:20.709Z,1399676480.709 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:21.110Z,1399676481.110 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:21.110Z,1399676481.110 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:21.110Z,1399676481.110 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:21.110Z,1399676481.110 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:21.527Z,1399676481.527 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:21.527Z,1399676481.527 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:21.527Z,1399676481.527 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:21.527Z,1399676481.527 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:21.527Z,1399676481.527 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:21.953Z,1399676481.953 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:21.953Z,1399676481.953 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:21.953Z,1399676481.953 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:21.954Z,1399676481.954 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:21.996Z,1399676481.996 [CBIT](INFO): Clearing failed count for component SCPI
2014-05-09T23:01:21.996Z,1399676481.996 [SCPI] No Fault, FailCount= 3
2014-05-09T23:01:22.375Z,1399676482.375 [SCPI](INFO): Powering up
2014-05-09T23:01:22.385Z,1399676482.385 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:22.385Z,1399676482.385 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:22.385Z,1399676482.385 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:22.386Z,1399676482.386 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:22.386Z,1399676482.386 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:22.707Z,1399676482.707 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:22.708Z,1399676482.708 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:22.708Z,1399676482.708 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:22.708Z,1399676482.708 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:23.110Z,1399676483.110 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:23.110Z,1399676483.110 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:23.110Z,1399676483.110 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:23.111Z,1399676483.111 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:23.111Z,1399676483.111 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:23.544Z,1399676483.544 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:23.544Z,1399676483.544 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:23.544Z,1399676483.544 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:23.544Z,1399676483.544 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:23.938Z,1399676483.938 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:23.938Z,1399676483.938 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:23.938Z,1399676483.938 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:23.938Z,1399676483.938 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:23.939Z,1399676483.939 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:24.353Z,1399676484.353 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:24.354Z,1399676484.354 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:24.354Z,1399676484.354 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:24.354Z,1399676484.354 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:24.845Z,1399676484.845 [SCPI](INFO): Init failed - response: ÿ
2014-05-09T23:01:24.846Z,1399676484.846 [SCPI](FAULT): SCPI failed to initialize
2014-05-09T23:01:24.846Z,1399676484.846 [SCPI] Communications Fault, FailCount= 1
2014-05-09T23:01:24.846Z,1399676484.846 [SCPI](ERROR): Communications Fault
2014-05-09T23:01:24.884Z,1399676484.884 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:24.884Z,1399676484.884 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:24.884Z,1399676484.884 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:24.885Z,1399676484.885 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:24.885Z,1399676484.885 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:24.956Z,1399676484.956 [CBIT](ERROR): Communications Fault in component: SCPI
2014-05-09T23:01:25.108Z,1399676485.108 [SCPI](INFO): Powering down
2014-05-09T23:01:25.233Z,1399676485.233 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:25.234Z,1399676485.234 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:25.234Z,1399676485.234 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:25.234Z,1399676485.234 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:25.587Z,1399676485.587 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:25.588Z,1399676485.588 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:25.588Z,1399676485.588 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:25.588Z,1399676485.588 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:25.588Z,1399676485.588 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:25.947Z,1399676485.947 [SCPI](INFO): Powering up
2014-05-09T23:01:25.957Z,1399676485.957 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:25.958Z,1399676485.958 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:25.958Z,1399676485.958 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:25.958Z,1399676485.958 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:26.007Z,1399676486.007 [CBIT](INFO): Clearing failed state for component SCPI
2014-05-09T23:01:26.008Z,1399676486.008 [SCPI] No Fault, FailCount= 1
2014-05-09T23:01:26.345Z,1399676486.345 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:26.345Z,1399676486.345 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:26.345Z,1399676486.345 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:26.346Z,1399676486.346 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:26.346Z,1399676486.346 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:26.711Z,1399676486.711 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:26.711Z,1399676486.711 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:26.711Z,1399676486.711 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:26.711Z,1399676486.711 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:27.114Z,1399676487.114 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:27.114Z,1399676487.114 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:27.114Z,1399676487.114 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:27.115Z,1399676487.115 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:27.115Z,1399676487.115 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:27.538Z,1399676487.538 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:27.538Z,1399676487.538 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:27.538Z,1399676487.538 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:27.538Z,1399676487.538 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:27.911Z,1399676487.911 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:27.911Z,1399676487.911 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:27.912Z,1399676487.912 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:27.912Z,1399676487.912 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:27.912Z,1399676487.912 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:28.363Z,1399676488.363 [SCPI](INFO): Init failed - response: ÿ
2014-05-09T23:01:28.363Z,1399676488.363 [SCPI](FAULT): SCPI failed to initialize
2014-05-09T23:01:28.363Z,1399676488.363 [SCPI] Communications Fault, FailCount= 2
2014-05-09T23:01:28.363Z,1399676488.363 [SCPI](ERROR): Communications Fault
2014-05-09T23:01:28.420Z,1399676488.420 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:28.420Z,1399676488.420 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:28.420Z,1399676488.420 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:28.420Z,1399676488.420 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:28.460Z,1399676488.460 [CBIT](ERROR): Communications Fault in component: SCPI
2014-05-09T23:01:28.767Z,1399676488.767 [SCPI](INFO): Powering down
2014-05-09T23:01:28.901Z,1399676488.901 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:28.902Z,1399676488.902 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:28.902Z,1399676488.902 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:28.902Z,1399676488.902 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:28.902Z,1399676488.902 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:29.149Z,1399676489.149 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:29.149Z,1399676489.149 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:29.149Z,1399676489.149 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:29.149Z,1399676489.149 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:29.597Z,1399676489.597 [SCPI](INFO): Powering up
2014-05-09T23:01:29.607Z,1399676489.607 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:29.607Z,1399676489.607 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:29.607Z,1399676489.607 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:29.608Z,1399676489.608 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:29.608Z,1399676489.608 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:29.686Z,1399676489.686 [CBIT](INFO): Clearing failed state for component SCPI
2014-05-09T23:01:29.686Z,1399676489.686 [SCPI] No Fault, FailCount= 2
2014-05-09T23:01:29.948Z,1399676489.948 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:29.948Z,1399676489.948 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:29.948Z,1399676489.948 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:29.949Z,1399676489.949 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:30.333Z,1399676490.333 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:30.333Z,1399676490.333 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:30.333Z,1399676490.333 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:30.334Z,1399676490.334 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:30.334Z,1399676490.334 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:30.743Z,1399676490.743 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:30.743Z,1399676490.743 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:30.743Z,1399676490.743 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:30.743Z,1399676490.743 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:31.120Z,1399676491.120 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:31.121Z,1399676491.121 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:31.121Z,1399676491.121 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:31.121Z,1399676491.121 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:31.121Z,1399676491.121 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:31.533Z,1399676491.533 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:31.533Z,1399676491.533 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:31.533Z,1399676491.533 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:31.533Z,1399676491.533 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:32.021Z,1399676492.021 [SCPI](INFO): Init failed - response: ÿ
2014-05-09T23:01:32.021Z,1399676492.021 [SCPI](FAULT): SCPI failed to initialize
2014-05-09T23:01:32.021Z,1399676492.021 [SCPI] Communications Fault, FailCount= 3
2014-05-09T23:01:32.021Z,1399676492.021 [SCPI](ERROR): Communications Fault
2014-05-09T23:01:32.030Z,1399676492.030 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:32.031Z,1399676492.031 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:32.031Z,1399676492.031 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:32.031Z,1399676492.031 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:32.031Z,1399676492.031 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:32.092Z,1399676492.092 [CBIT](ERROR): Communications Fault in component: SCPI
2014-05-09T23:01:32.093Z,1399676492.093 [CBIT](CRITICAL): Communications Fault in component: SCPI
2014-05-09T23:01:32.300Z,1399676492.300 [SCPI](INFO): Powering down
2014-05-09T23:01:32.428Z,1399676492.428 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:32.428Z,1399676492.428 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2014-05-09T23:01:32.428Z,1399676492.428 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:32.429Z,1399676492.429 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:32.711Z,1399676492.711 [SCPI_on:TestDrive:Data] Running Loop=1
2014-05-09T23:01:32.711Z,1399676492.711 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2014-05-09T23:01:32.711Z,1399676492.711 [SCPI_on:TestDrive:Data:A] Running Loop=1
2014-05-09T23:01:32.712Z,1399676492.712 [SCPI_on:TestDrive:Data:A] Stopped
2014-05-09T23:01:32.712Z,1399676492.712 [SCPI_on:TestDrive:Data:B] Running Loop=1
2014-05-09T23:01:32.712Z,1399676492.712 [SCPI_on] Stopped
2014-05-09T23:01:32.713Z,1399676492.713 [SCPI_on](INFO): Aggregate::uninitialize SCPI_on
2014-05-09T23:01:32.713Z,1399676492.713 [SCPI_on:A.Pitch] Stopped
2014-05-09T23:01:32.713Z,1399676492.713 [SCPI_on:TestDrive] Stopped
2014-05-09T23:01:32.713Z,1399676492.713 [SCPI_on:TestDrive](INFO): Aggregate::uninitialize SCPI_on:TestDrive
2014-05-09T23:01:32.713Z,1399676492.713 [SCPI_on:TestDrive:A] Stopped
2014-05-09T23:01:32.713Z,1399676492.713 [SCPI_on:TestDrive:Data] Stopped
2014-05-09T23:01:32.713Z,1399676492.713 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2014-05-09T23:01:32.713Z,1399676492.713 [SCPI_on:TestDrive:Data:B] Stopped
2014-05-09T23:01:32.713Z,1399676492.713 [SCPI_on:TestDrive:C.Wait] Stopped
2014-05-09T23:01:32.713Z,1399676492.713 [SCPI_on:TestDrive:C.Wait](DEBUG): Uninitialize Wait Component.
2014-05-09T23:01:33.141Z,1399676493.141 [MissionManager](IMPORTANT): Started mission Default
2014-05-09T23:01:33.141Z,1399676493.141 [Default] Running Loop=1
2014-05-09T23:01:33.141Z,1399676493.141 [Default](INFO): Aggregate::initialize Default
2014-05-09T23:01:33.141Z,1399676493.141 [Default:Iridium] Running Loop=1
2014-05-09T23:01:33.141Z,1399676493.141 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-05-09T23:01:33.141Z,1399676493.141 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-05-09T23:01:33.141Z,1399676493.141 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-05-09T23:01:33.142Z,1399676493.142 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-05-09T23:01:33.142Z,1399676493.142 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-09T23:01:33.143Z,1399676493.143 [Default:Iridium:B.GoToSurface] Stopped
2014-05-09T23:01:33.143Z,1399676493.143 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-09T23:01:33.143Z,1399676493.143 [Default:Iridium:Read_Iridium] Running Loop=1
2014-05-09T23:01:35.470Z,1399676495.470 [DataOverHttps](INFO): Sending 123 bytes from file Logs/20140509T224915/Courier0024.lzma
2014-05-09T23:01:36.185Z,1399676496.185 [DataOverHttps](INFO): Moved sent file to Logs/20140509T224915/Courier0024.lzma.bak
2014-05-09T23:01:36.186Z,1399676496.186 [DataOverHttps](INFO): SBD MOMSN=940184
2014-05-09T23:01:43.378Z,1399676503.378 [DataOverHttps](INFO): Sending 597 bytes from file Logs/20140509T224915/Express0025.lzma
2014-05-09T23:01:44.143Z,1399676504.143 [DataOverHttps](INFO): Moved sent file to Logs/20140509T224915/Express0025.lzma.bak
2014-05-09T23:01:44.143Z,1399676504.143 [DataOverHttps](INFO): SBD MOMSN=940187
2014-05-09T23:01:44.588Z,1399676504.588 [Default:Iridium:Read_Iridium] Stopped
2014-05-09T23:01:44.589Z,1399676504.589 [Default:Iridium](INFO): Completed Default:Iridium
2014-05-09T23:01:44.589Z,1399676504.589 [Default:Iridium] Stopped
2014-05-09T23:01:44.589Z,1399676504.589 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-05-09T23:01:44.589Z,1399676504.589 [Default:Iridium:A.SetSpeed] Stopped
2014-05-09T23:01:44.589Z,1399676504.589 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-05-09T23:01:44.590Z,1399676504.590 [Default:WaitAtTheSurface] Running Loop=1
2014-05-09T23:01:44.590Z,1399676504.590 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface
2014-05-09T23:01:44.590Z,1399676504.590 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Running Loop=1
2014-05-09T23:01:44.590Z,1399676504.590 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Initialize.
2014-05-09T23:01:44.590Z,1399676504.590 [Default:WaitAtTheSurface:B.GoToSurface] Running Loop=1
2014-05-09T23:01:44.590Z,1399676504.590 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-09T23:04:05.167Z,1399676645.167 [CBIT](INFO): Clearing failed count for component SCPI
2014-05-09T23:04:05.168Z,1399676645.168 [SCPI] No Fault, FailCount= 3
2014-05-09T23:04:10.186Z,1399676650.186 [SCPI](INFO): Powering up
2014-05-09T23:04:15.270Z,1399676655.270 [SCPI](INFO): Init failed - response: 
2014-05-09T23:04:15.270Z,1399676655.270 [SCPI](FAULT): SCPI failed to initialize
2014-05-09T23:04:15.270Z,1399676655.270 [SCPI] Communications Fault, FailCount= 1
2014-05-09T23:04:15.270Z,1399676655.270 [SCPI](ERROR): Communications Fault
2014-05-09T23:04:15.289Z,1399676655.289 [CBIT](ERROR): Communications Fault in component: SCPI
2014-05-09T23:04:20.177Z,1399676660.177 [SCPI](INFO): Powering down
2014-05-09T23:04:30.188Z,1399676670.188 [CBIT](INFO): Clearing failed state for component SCPI
2014-05-09T23:04:30.188Z,1399676670.188 [SCPI] No Fault, FailCount= 1
2014-05-09T23:04:35.184Z,1399676675.184 [SCPI](INFO): Powering up
2014-05-09T23:04:40.276Z,1399676680.276 [SCPI](INFO): Init failed - response: 
2014-05-09T23:04:40.277Z,1399676680.277 [SCPI](FAULT): SCPI failed to initialize
2014-05-09T23:04:40.277Z,1399676680.277 [SCPI] Communications Fault, FailCount= 2
2014-05-09T23:04:40.277Z,1399676680.277 [SCPI](ERROR): Communications Fault
2014-05-09T23:04:40.296Z,1399676680.296 [CBIT](ERROR): Communications Fault in component: SCPI
2014-05-09T23:04:45.179Z,1399676685.179 [SCPI](INFO): Powering down
2014-05-09T23:04:55.689Z,1399676695.689 [CBIT](INFO): Clearing failed state for component SCPI
2014-05-09T23:04:55.689Z,1399676695.689 [SCPI] No Fault, FailCount= 2
2014-05-09T23:05:00.183Z,1399676700.183 [SCPI](INFO): Powering up
2014-05-09T23:05:05.276Z,1399676705.276 [SCPI](INFO): Init failed - response: 
2014-05-09T23:05:05.276Z,1399676705.276 [SCPI](FAULT): SCPI failed to initialize
2014-05-09T23:05:05.276Z,1399676705.276 [SCPI] Communications Fault, FailCount= 3
2014-05-09T23:05:05.276Z,1399676705.276 [SCPI](ERROR): Communications Fault
2014-05-09T23:05:05.296Z,1399676705.296 [CBIT](ERROR): Communications Fault in component: SCPI
2014-05-09T23:05:05.296Z,1399676705.296 [CBIT](CRITICAL): Communications Fault in component: SCPI
2014-05-09T23:05:10.150Z,1399676710.150 [SCPI](INFO): Powering down
2014-05-09T23:05:23.614Z,1399676723.614 [CommandLine](IMPORTANT): got command quit
2014-05-09T23:05:24.624Z,1399676724.624 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-09T23:05:24.625Z,1399676724.625 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:24.669Z,1399676724.669 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2014-05-09T23:05:24.669Z,1399676724.669 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:24.670Z,1399676724.670 [CommandLine](INFO): Join timeout helper Thread ID is 1031
2014-05-09T23:05:24.670Z,1399676724.670 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2014-05-09T23:05:24.671Z,1399676724.671 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:24.671Z,1399676724.671 [NavChartDb](INFO): Join timeout helper Thread ID is 1032
2014-05-09T23:05:24.902Z,1399676724.902 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-09T23:05:24.902Z,1399676724.902 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:24.910Z,1399676724.910 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2014-05-09T23:05:24.910Z,1399676724.910 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:24.910Z,1399676724.910 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1033
2014-05-09T23:05:25.010Z,1399676725.010 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-09T23:05:25.010Z,1399676725.010 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:25.014Z,1399676725.014 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2014-05-09T23:05:25.014Z,1399676725.014 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:25.014Z,1399676725.014 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1034
2014-05-09T23:05:25.110Z,1399676725.110 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-09T23:05:25.110Z,1399676725.110 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:25.118Z,1399676725.118 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2014-05-09T23:05:25.118Z,1399676725.118 [AsyncPiEstimator ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:25.118Z,1399676725.118 [AsyncPiEstimator](INFO): Join timeout helper Thread ID is 1035
2014-05-09T23:05:25.202Z,1399676725.202 [AsyncPiEstimator ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-09T23:05:25.203Z,1399676725.203 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2014-05-09T23:05:25.203Z,1399676725.203 [AsyncPiEstimator ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:25.215Z,1399676725.215 [ComponentRegistry](INFO): Shutting down Radio_Freewave ThreadHandler
2014-05-09T23:05:25.215Z,1399676725.215 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:25.216Z,1399676725.216 [Radio_Freewave](INFO): Join timeout helper Thread ID is 1036
2014-05-09T23:05:25.528Z,1399676725.528 [Radio_Freewave ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-09T23:05:25.620Z,1399676725.620 [Radio_Freewave](INFO): Powering down
2014-05-09T23:05:26.024Z,1399676726.024 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:26.028Z,1399676726.028 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2014-05-09T23:05:26.029Z,1399676726.029 [logger ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:26.029Z,1399676726.029 [logger](INFO): Join timeout helper Thread ID is 1038
2014-05-09T23:05:26.029Z,1399676726.029 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-09T23:05:26.030Z,1399676726.030 [logger ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:26.031Z,1399676726.031 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2014-05-09T23:05:26.031Z,1399676726.031 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:26.032Z,1399676726.032 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2014-05-09T23:05:26.032Z,1399676726.032 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:26.032Z,1399676726.032 [controlThread](INFO): Join timeout helper Thread ID is 1039
2014-05-09T23:05:29.914Z,1399676729.914 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-09T23:05:29.914Z,1399676729.914 [controlThread](DEBUG): Uninitializing ControlThread
2014-05-09T23:05:29.916Z,1399676729.916 [NAL9602](INFO): Powering down
2014-05-09T23:05:29.918Z,1399676729.918 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-05-09T23:05:29.918Z,1399676729.918 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2014-05-09T23:05:29.919Z,1399676729.919 [Default] Stopped
2014-05-09T23:05:29.919Z,1399676729.919 [Default](INFO): Aggregate::uninitialize Default
2014-05-09T23:05:29.919Z,1399676729.919 [Default:WaitAtTheSurface] Stopped
2014-05-09T23:05:29.920Z,1399676729.920 [Default:WaitAtTheSurface](INFO): Aggregate::uninitialize Default:WaitAtTheSurface
2014-05-09T23:05:29.920Z,1399676729.920 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Stopped
2014-05-09T23:05:29.920Z,1399676729.920 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Uninitialize.
2014-05-09T23:05:29.920Z,1399676729.920 [Default:WaitAtTheSurface:B.GoToSurface] Stopped
2014-05-09T23:05:29.920Z,1399676729.920 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-09T23:05:29.926Z,1399676729.926 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2014-05-09T23:05:29.926Z,1399676729.926 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2014-05-09T23:05:29.927Z,1399676729.927 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2014-05-09T23:05:29.927Z,1399676729.927 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2014-05-09T23:05:29.927Z,1399676729.927 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-05-09T23:05:29.928Z,1399676729.928 [BuoyancyServo](INFO): Powering down
2014-05-09T23:05:29.942Z,1399676729.942 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2014-05-09T23:05:29.942Z,1399676729.942 [ElevatorServo](INFO): Powering down
2014-05-09T23:05:29.943Z,1399676729.943 [MassServo](DEBUG): Uninitialize Mass Servo.
2014-05-09T23:05:29.943Z,1399676729.943 [MassServo](INFO): Powering down
2014-05-09T23:05:29.944Z,1399676729.944 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2014-05-09T23:05:29.944Z,1399676729.944 [RudderServo](INFO): Powering down
2014-05-09T23:05:29.945Z,1399676729.945 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2014-05-09T23:05:29.945Z,1399676729.945 [SBIT](DEBUG): Uninitialize SBIT Component.
2014-05-09T23:05:29.946Z,1399676729.946 [IBIT](DEBUG): Uninitialize IBIT Component.
2014-05-09T23:05:29.946Z,1399676729.946 [CBIT](DEBUG): Uninitialize CBIT Component.
2014-05-09T23:05:29.993Z,1399676729.993 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:30.008Z,1399676730.008 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:30.064Z,1399676730.064 [AsyncPiEstimator ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:30.085Z,1399676730.085 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:30.088Z,1399676730.088 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:30.116Z,1399676730.116 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-05-09T23:05:30.170Z,1399676730.170 [logger ThreadHandler](INFO): Thread cancelled.