2014-08-01T04:46:52.120Z,1406868412.120 [Supervisor](DEBUG): Initializing supervisor.
2014-08-01T04:46:52.123Z,1406868412.123 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-08-01T04:46:52.127Z,1406868412.127 [SyncHandler](INFO): Protected caller Thread ID is 978
2014-08-01T04:46:52.128Z,1406868412.128 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-08-01T04:46:52.129Z,1406868412.129 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2014-08-01T04:46:52.129Z,1406868412.129 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 979
2014-08-01T04:46:52.137Z,1406868412.137 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-08-01T04:46:52.154Z,1406868412.154 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-08-01T04:46:52.155Z,1406868412.155 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2014-08-01T04:46:52.156Z,1406868412.156 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 980
2014-08-01T04:46:52.161Z,1406868412.161 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-08-01T04:46:52.162Z,1406868412.162 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2014-08-01T04:46:52.163Z,1406868412.163 [logger ThreadHandler](INFO): Protected caller Thread ID is 981
2014-08-01T04:46:52.165Z,1406868412.165 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-08-01T04:46:52.165Z,1406868412.165 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-08-01T04:46:52.167Z,1406868412.167 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-08-01T04:46:52.790Z,1406868412.790 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-08-01T04:46:52.791Z,1406868412.791 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-08-01T04:46:52.945Z,1406868412.945 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-08-01T04:46:52.945Z,1406868412.945 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-08-01T04:46:53.052Z,1406868413.052 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-08-01T04:46:53.052Z,1406868413.052 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-08-01T04:46:53.174Z,1406868413.174 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-08-01T04:46:53.175Z,1406868413.175 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-08-01T04:46:53.260Z,1406868413.260 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-08-01T04:46:53.393Z,1406868413.393 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-08-01T04:46:53.394Z,1406868413.394 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-08-01T04:46:53.479Z,1406868413.479 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-08-01T04:46:53.479Z,1406868413.479 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-08-01T04:46:53.656Z,1406868413.656 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-08-01T04:46:53.657Z,1406868413.657 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-08-01T04:46:53.943Z,1406868413.943 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-08-01T04:46:53.944Z,1406868413.944 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-08-01T04:46:54.245Z,1406868414.245 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-08-01T04:46:54.246Z,1406868414.246 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-08-01T04:46:54.737Z,1406868414.737 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-08-01T04:46:54.738Z,1406868414.738 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-08-01T04:46:54.925Z,1406868414.925 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-08-01T04:46:54.925Z,1406868414.925 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-08-01T04:46:55.028Z,1406868415.028 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-08-01T04:46:55.029Z,1406868415.029 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-08-01T04:46:55.421Z,1406868415.421 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-08-01T04:46:55.421Z,1406868415.421 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-08-01T04:46:55.529Z,1406868415.529 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-08-01T04:46:55.532Z,1406868415.532 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-08-01T04:46:55.532Z,1406868415.532 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-08-01T04:46:55.636Z,1406868415.636 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-08-01T04:46:55.752Z,1406868415.752 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-08-01T04:46:55.860Z,1406868415.860 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-08-01T04:46:55.955Z,1406868415.955 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-08-01T04:46:56.081Z,1406868416.081 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-08-01T04:46:56.224Z,1406868416.224 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-08-01T04:46:56.323Z,1406868416.323 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-08-01T04:46:56.408Z,1406868416.408 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-08-01T04:46:56.499Z,1406868416.499 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-08-01T04:46:56.596Z,1406868416.596 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-08-01T04:46:56.707Z,1406868416.707 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-08-01T04:46:57.465Z,1406868417.465 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2014-08-01T04:46:57.467Z,1406868417.467 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-08-01T04:46:57.518Z,1406868417.518 [VerticalControl](DEBUG): Construct VerticalControl.
2014-08-01T04:46:57.638Z,1406868417.638 [VerticalControl] Loaded
2014-08-01T04:46:57.638Z,1406868417.638 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-08-01T04:46:57.639Z,1406868417.639 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-08-01T04:46:57.710Z,1406868417.710 [HorizontalControl] Loaded
2014-08-01T04:46:57.710Z,1406868417.710 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-08-01T04:46:57.711Z,1406868417.711 [SpeedControl](DEBUG): Construct SpeedControl.
2014-08-01T04:46:57.717Z,1406868417.717 [SpeedControl] Loaded
2014-08-01T04:46:57.717Z,1406868417.717 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-08-01T04:46:57.718Z,1406868417.718 [LoopControl](DEBUG): Construct LoopControl.
2014-08-01T04:46:57.718Z,1406868417.718 [LoopControl] Loaded
2014-08-01T04:46:57.718Z,1406868417.718 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-08-01T04:46:57.719Z,1406868417.719 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-08-01T04:46:57.719Z,1406868417.719 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-08-01T04:46:57.818Z,1406868417.818 [SBIT](DEBUG): Construct Startup Built In Test.
2014-08-01T04:46:57.829Z,1406868417.829 [SBIT] Loaded
2014-08-01T04:46:57.830Z,1406868417.830 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-08-01T04:46:57.830Z,1406868417.830 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-08-01T04:46:57.859Z,1406868417.859 [IBIT] Loaded
2014-08-01T04:46:57.860Z,1406868417.860 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-08-01T04:46:57.862Z,1406868417.862 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-08-01T04:46:57.980Z,1406868417.980 [CBIT] Loaded
2014-08-01T04:46:57.980Z,1406868417.980 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-08-01T04:46:57.980Z,1406868417.980 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-08-01T04:46:57.981Z,1406868417.981 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-08-01T04:46:58.006Z,1406868418.006 [DepthRateCalculator] Loaded
2014-08-01T04:46:58.006Z,1406868418.006 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-08-01T04:46:58.012Z,1406868418.012 [PitchRateCalculator] Loaded
2014-08-01T04:46:58.012Z,1406868418.012 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-08-01T04:46:58.023Z,1406868418.023 [SpeedCalculator] Loaded
2014-08-01T04:46:58.023Z,1406868418.023 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-08-01T04:46:58.040Z,1406868418.040 [TempGradientCalculator] Loaded
2014-08-01T04:46:58.040Z,1406868418.040 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-08-01T04:46:58.045Z,1406868418.045 [YawRateCalculator] Loaded
2014-08-01T04:46:58.046Z,1406868418.046 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-08-01T04:46:58.046Z,1406868418.046 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-08-01T04:46:58.047Z,1406868418.047 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-08-01T04:47:03.026Z,1406868423.026 [HFRadarModelCalc] Loaded
2014-08-01T04:47:03.026Z,1406868423.026 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2014-08-01T04:47:07.011Z,1406868427.011 [HFRadarCompactModelForecaster] Loaded
2014-08-01T04:47:07.011Z,1406868427.011 [ComponentRegistry](DEBUG): SyncComponent "HFRadarCompactModelForecaster" handled in the control thread.
2014-08-01T04:47:08.108Z,1406868428.108 [HFRCMSpaceInterpolator] Loaded
2014-08-01T04:47:08.108Z,1406868428.108 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSpaceInterpolator" handled in the control thread.
2014-08-01T04:47:08.110Z,1406868428.110 [HFRCMTimeInterpolator] Loaded
2014-08-01T04:47:08.111Z,1406868428.111 [ComponentRegistry](DEBUG): SyncComponent "HFRCMTimeInterpolator" handled in the control thread.
2014-08-01T04:47:09.185Z,1406868429.185 [HFRCMReconstructedInterpolator] Loaded
2014-08-01T04:47:09.186Z,1406868429.186 [ComponentRegistry](DEBUG): SyncComponent "HFRCMReconstructedInterpolator" handled in the control thread.
2014-08-01T04:47:09.198Z,1406868429.198 [HFRCMSurfaceCurrentAtVehicleLocation] Loaded
2014-08-01T04:47:09.198Z,1406868429.198 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSurfaceCurrentAtVehicleLocation" handled in the control thread.
2014-08-01T04:47:09.225Z,1406868429.225 [HFRCMVirtualSurfaceDrifter] Loaded
2014-08-01T04:47:09.225Z,1406868429.225 [ComponentRegistry](DEBUG): SyncComponent "HFRCMVirtualSurfaceDrifter" handled in the control thread.
2014-08-01T04:47:09.226Z,1406868429.226 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-08-01T04:47:09.226Z,1406868429.226 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-08-01T04:47:09.463Z,1406868429.463 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-08-01T04:47:09.464Z,1406868429.464 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-08-01T04:47:09.546Z,1406868429.546 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-08-01T04:47:09.546Z,1406868429.546 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-08-01T04:47:09.592Z,1406868429.592 [DeadReckonWithRespectToWater] Loaded
2014-08-01T04:47:09.592Z,1406868429.592 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToWater" handled in the control thread.
2014-08-01T04:47:09.639Z,1406868429.639 [DeadReckonWithRespectToSeafloor] Loaded
2014-08-01T04:47:09.639Z,1406868429.639 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2014-08-01T04:47:09.700Z,1406868429.700 [DeadReckonUsingDVLWaterTrack] Loaded
2014-08-01T04:47:09.700Z,1406868429.700 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingDVLWaterTrack" handled in the control thread.
2014-08-01T04:47:09.749Z,1406868429.749 [DeadReckonUsingCompactModelForecast] Loaded
2014-08-01T04:47:09.749Z,1406868429.749 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingCompactModelForecast" handled in the control thread.
2014-08-01T04:47:09.766Z,1406868429.766 [NavChart] Loaded
2014-08-01T04:47:09.767Z,1406868429.767 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-08-01T04:47:09.771Z,1406868429.771 [UniversalFixResidualReporter] Loaded
2014-08-01T04:47:09.771Z,1406868429.771 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-08-01T04:47:09.772Z,1406868429.772 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-08-01T04:47:09.772Z,1406868429.772 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-08-01T04:47:09.785Z,1406868429.785 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-08-01T04:47:09.785Z,1406868429.785 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-08-01T04:47:09.964Z,1406868429.964 [CTD_NeilBrown] Loaded
2014-08-01T04:47:09.964Z,1406868429.964 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-08-01T04:47:09.966Z,1406868429.966 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407B94E0
2014-08-01T04:47:09.966Z,1406868429.966 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1063
2014-08-01T04:47:09.982Z,1406868429.982 [PAR_Licor] Loaded
2014-08-01T04:47:09.982Z,1406868429.982 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-08-01T04:47:10.018Z,1406868430.018 [WetLabsBB2FL] Loaded
2014-08-01T04:47:10.018Z,1406868430.018 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-08-01T04:47:10.019Z,1406868430.019 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407E94E0
2014-08-01T04:47:10.019Z,1406868430.019 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1064
2014-08-01T04:47:10.020Z,1406868430.020 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-08-01T04:47:10.021Z,1406868430.021 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-08-01T04:47:10.311Z,1406868430.311 [AHRS_sp3003D] Loaded
2014-08-01T04:47:10.311Z,1406868430.311 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-08-01T04:47:10.575Z,1406868430.575 [Batt_Ocean_Server] Loaded
2014-08-01T04:47:10.575Z,1406868430.575 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-08-01T04:47:10.589Z,1406868430.589 [Depth_Keller] Loaded
2014-08-01T04:47:10.589Z,1406868430.589 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-08-01T04:47:10.594Z,1406868430.594 [DropWeight] Loaded
2014-08-01T04:47:10.595Z,1406868430.595 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-08-01T04:47:10.728Z,1406868430.728 [DVL_micro] Loaded
2014-08-01T04:47:10.729Z,1406868430.729 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2014-08-01T04:47:10.824Z,1406868430.824 [NAL9602] Loaded
2014-08-01T04:47:10.824Z,1406868430.824 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-08-01T04:47:10.866Z,1406868430.866 [Onboard] Loaded
2014-08-01T04:47:10.866Z,1406868430.866 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-08-01T04:47:10.874Z,1406868430.874 [Radio_Freewave] Loaded
2014-08-01T04:47:10.874Z,1406868430.874 [ComponentRegistry](DEBUG): Component "Radio_Freewave" handled in its own thread.
2014-08-01T04:47:10.875Z,1406868430.875 [Radio_Freewave ThreadHandler](DEBUG): Created PCaller Thread at 40A1E4E0
2014-08-01T04:47:10.875Z,1406868430.875 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 1065
2014-08-01T04:47:11.006Z,1406868431.006 [DAT] Loaded
2014-08-01T04:47:11.007Z,1406868431.007 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2014-08-01T04:47:11.014Z,1406868431.013 [SCPI] Loaded
2014-08-01T04:47:11.014Z,1406868431.014 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-08-01T04:47:11.331Z,1406868431.331 [BPC1] Loaded
2014-08-01T04:47:11.331Z,1406868431.331 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2014-08-01T04:47:11.332Z,1406868431.332 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-08-01T04:47:11.332Z,1406868431.332 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-08-01T04:47:11.433Z,1406868431.433 [BuoyancyServo] Loaded
2014-08-01T04:47:11.433Z,1406868431.433 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-08-01T04:47:11.446Z,1406868431.446 [ElevatorServo] Loaded
2014-08-01T04:47:11.446Z,1406868431.446 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-08-01T04:47:11.458Z,1406868431.458 [MassServo] Loaded
2014-08-01T04:47:11.458Z,1406868431.458 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-08-01T04:47:11.470Z,1406868431.470 [RudderServo] Loaded
2014-08-01T04:47:11.470Z,1406868431.470 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-08-01T04:47:11.482Z,1406868431.482 [ThrusterServo] Loaded
2014-08-01T04:47:11.482Z,1406868431.482 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-08-01T04:47:11.483Z,1406868431.483 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-08-01T04:47:11.483Z,1406868431.483 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-08-01T04:47:11.641Z,1406868431.641 [InternalSim] Loaded
2014-08-01T04:47:11.642Z,1406868431.642 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-08-01T04:47:11.642Z,1406868431.642 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-08-01T04:47:11.643Z,1406868431.643 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-08-01T04:47:11.668Z,1406868431.668 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-08-01T04:47:11.670Z,1406868431.670 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-08-01T04:47:11.671Z,1406868431.671 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-08-01T04:47:11.677Z,1406868431.677 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-08-01T04:47:11.678Z,1406868431.678 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ACF4E0
2014-08-01T04:47:11.679Z,1406868431.679 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1066
2014-08-01T04:47:11.684Z,1406868431.684 [Supervisor](INFO): Main Thread ID is 977
2014-08-01T04:47:11.684Z,1406868431.684 [Supervisor](DEBUG): Running supervisor.
2014-08-01T04:47:11.685Z,1406868431.685 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1067
2014-08-01T04:47:11.688Z,1406868431.688 [controlThread ThreadHandler](INFO): Handler Thread ID is 1068
2014-08-01T04:47:11.689Z,1406868431.689 [controlThread](DEBUG): Initializing ControlThread
2014-08-01T04:47:11.690Z,1406868431.690 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-08-01T04:47:11.691Z,1406868431.691 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-08-01T04:47:11.692Z,1406868431.692 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-08-01T04:47:11.693Z,1406868431.693 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-08-01T04:47:11.693Z,1406868431.693 [SBIT](INFO): Initialize SBIT Component.
2014-08-01T04:47:11.693Z,1406868431.693 [SBIT](IMPORTANT): Tethys CM Info: SVN revision: 11462
2014-08-01T04:47:11.694Z,1406868431.694 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2014-08-01T04:47:11.694Z,1406868431.694 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-08-01T04:47:11.695Z,1406868431.695 [IBIT](INFO): Initialize IBIT Component.
2014-08-01T04:47:11.695Z,1406868431.695 [CBIT](DEBUG): Initialize CBIT Component.
2014-08-01T04:47:11.696Z,1406868431.696 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2014-08-01T04:47:11.697Z,1406868431.697 [logger ThreadHandler](INFO): Handler Thread ID is 1069
2014-08-01T04:47:11.718Z,1406868431.718 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1070
2014-08-01T04:47:11.718Z,1406868431.718 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-08-01T04:47:11.721Z,1406868431.721 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-08-01T04:47:11.722Z,1406868431.722 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-08-01T04:47:11.722Z,1406868431.722 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-08-01T04:47:11.722Z,1406868431.722 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-08-01T04:47:11.723Z,1406868431.723 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-08-01T04:47:11.725Z,1406868431.725 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-08-01T04:47:11.737Z,1406868431.737 [HFRadarCompactModelForecaster](DEBUG): Found new ECs!
2014-08-01T04:47:11.740Z,1406868431.740 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1072
2014-08-01T04:47:11.742Z,1406868431.742 [WetLabsBB2FL](INFO): Powering down
2014-08-01T04:47:11.775Z,1406868431.775 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 1073
2014-08-01T04:47:11.782Z,1406868431.782 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1074
2014-08-01T04:47:11.792Z,1406868431.792 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-08-01T04:47:11.793Z,1406868431.793 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-08-01T04:47:11.793Z,1406868431.793 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-08-01T04:47:11.793Z,1406868431.793 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-08-01T04:47:11.794Z,1406868431.794 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-08-01T04:47:11.794Z,1406868431.794 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-08-01T04:47:11.794Z,1406868431.794 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-08-01T04:47:11.794Z,1406868431.794 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-08-01T04:47:11.795Z,1406868431.795 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-08-01T04:47:20.584Z,1406868440.584 [HFRadarCompactModelForecaster](IMPORTANT): forecast time 201408010100: published 50 modes in rows, 61 hours in columns
2014-08-01T04:47:20.588Z,1406868440.588 [HFRadarCompactModelForecaster](IMPORTANT): expansionCoefficients_[0][48] = -10.333895 for 2014-08-01T01:00:00.000Z
2014-08-01T04:47:20.595Z,1406868440.595 [HFRCMSpaceInterpolator](DEBUG): Initializing HFRCMSpaceInterpolator component with verbosity level 0.
2014-08-01T04:47:20.597Z,1406868440.597 [HFRCMTimeInterpolator](DEBUG): Initializing HFRCMTimeInterpolator component.
2014-08-01T04:47:20.597Z,1406868440.597 [HFRCMReconstructedInterpolator](INFO): Initializing HFRCMReconstructedInterpolator component with velocityAccuracy_ = 0.300000 m/s.
2014-08-01T04:47:20.615Z,1406868440.615 [HFRCMSurfaceCurrentAtVehicleLocation](DEBUG): Initializing HFRCMSurfaceCurrentAtVehicleLocation component.
2014-08-01T04:47:20.615Z,1406868440.615 [HFRCMVirtualSurfaceDrifter](DEBUG): Initializing HFRCMVirtualSurfaceDrifter component.
2014-08-01T04:47:20.615Z,1406868440.615 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-08-01T04:47:20.616Z,1406868440.616 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component.
2014-08-01T04:47:20.616Z,1406868440.616 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component.
2014-08-01T04:47:20.617Z,1406868440.617 [DeadReckonUsingDVLWaterTrack](DEBUG): Initializing DeadReckonUsingDVLWaterTrack component.
2014-08-01T04:47:20.617Z,1406868440.617 [DeadReckonUsingCompactModelForecast](DEBUG): Initializing DeadReckonUsingCompactModelForecast component.
2014-08-01T04:47:20.617Z,1406868440.617 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-08-01T04:47:20.618Z,1406868440.618 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-08-01T04:47:22.606Z,1406868442.606 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-08-01T04:47:22.643Z,1406868442.643 [InternalSim](DEBUG):  InternalSim initializing...
2014-08-01T04:47:22.747Z,1406868442.747 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-08-01T04:47:22.992Z,1406868442.992 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-08-01T04:47:23.001Z,1406868443.001 [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-08-01T04:47:23.002Z,1406868443.002 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-08-01T04:47:23.113Z,1406868443.113 [Default:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-08-01T04:47:23.140Z,1406868443.140 [Default:CheckIn:A.SetSpeed](DEBUG): Construct.
2014-08-01T04:47:23.179Z,1406868443.179 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-08-01T04:47:23.182Z,1406868443.182 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-08-01T04:47:23.209Z,1406868443.209 [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">

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="CheckIn">

        <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>
<!-- TODO: Do we really want this When operating on platform_communications? or on something else like time_fix? -->

<!-- Run application at high speed -->

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

        <ReadDatum Id="Read_GPS">
            <Timeout Duration="P5M"/>
<!-- NOTE: Original Default.xml didn't have a timeout on the GPS read, so theoretically could have hung indefinitely there... --> 
            <Universal:latitude_fix/>
        </ReadDatum>

        <!-- 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="WaitAtTheSurface">

        <Sequence/>

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

    </Aggregate>

</Mission>


2014-08-01T04:47:23.235Z,1406868443.235 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,PAR_Licor,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,DAT,SCPI,BPC1,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,HFRadarModelCalc,HFRadarCompactModelForecaster,HFRCMSpaceInterpolator,HFRCMTimeInterpolator,HFRCMReconstructedInterpolator,HFRCMSurfaceCurrentAtVehicleLocation,HFRCMVirtualSurfaceDrifter,DeadReckonUsingMultipleVelocitySources,DeadReckonWithRespectToWater,DeadReckonWithRespectToSeafloor,DeadReckonUsingDVLWaterTrack,DeadReckonUsingCompactModelForecast,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2014-08-01T04:47:23.310Z,1406868443.310 [Radio_Freewave](INFO): Powering up
2014-08-01T04:47:23.346Z,1406868443.346 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-08-01T04:47:23.511Z,1406868443.511 [DVL_micro](INFO): Initializing
2014-08-01T04:47:23.550Z,1406868443.550 [NAL9602](INFO): Powering up NAL9602
2014-08-01T04:47:23.620Z,1406868443.620 [DAT](INFO): Powering up
2014-08-01T04:47:23.620Z,1406868443.620 [DAT](DEBUG): Initializing DAT.
2014-08-01T04:47:23.650Z,1406868443.650 [BPC1](DEBUG): Initializing BPC1.
2014-08-01T04:47:24.113Z,1406868444.113 [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-08-01T04:47:31.069Z,1406868451.069 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-08-01T04:47:31.071Z,1406868451.071 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-08-01T04:47:31.107Z,1406868451.107 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-08-01T04:47:31.115Z,1406868451.115 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-08-01T04:47:31.121Z,1406868451.121 [MassServo](DEBUG): Initializing EZServoServo.
2014-08-01T04:47:31.127Z,1406868451.127 [MassServo](DEBUG): Initializing MassServo.
2014-08-01T04:47:31.147Z,1406868451.147 [RudderServo](DEBUG): Initializing EZServoServo.
2014-08-01T04:47:31.156Z,1406868451.156 [RudderServo](DEBUG): Initializing RudderServo.
2014-08-01T04:47:31.161Z,1406868451.161 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-08-01T04:47:31.167Z,1406868451.167 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-08-01T04:47:32.258Z,1406868452.258 [SBIT](IMPORTANT): Beginning Startup BIT
2014-08-01T04:47:32.261Z,1406868452.261 [CBIT](IMPORTANT): Beginning GF scan
2014-08-01T04:47:34.356Z,1406868454.356 [NAL9602](INFO): NAL9602 initialized
2014-08-01T04:47:43.924Z,1406868463.924 [DAT](INFO): Powering down
2014-08-01T04:47:57.747Z,1406868477.747 [CommandLine](IMPORTANT): got command report mod DAT.queryAddressRequested
2014-08-01T04:47:58.187Z,1406868478.187 [Reporter](INFO): DAT.queryAddressRequested no_value
2014-08-01T04:47:59.976Z,1406868479.976 [CBIT](IMPORTANT): No ground fault detected
2014-08-01T04:48:13.034Z,1406868493.034 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T04:48:13.034Z,1406868493.034 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T04:48:13.078Z,1406868493.078 [MissionManager](INFO): DefineArg tracking_on_surface.MissionTimeout = 10.000000 min
2014-08-01T04:48:13.089Z,1406868493.089 [MissionManager](INFO): DefineArg tracking_on_surface.ContactLabel = 1.000000 count
2014-08-01T04:48:13.101Z,1406868493.101 [MissionManager](INFO): DefineArg tracking_on_surface.TrackingUpdatePeriod = 45.000000 s
2014-08-01T04:48:13.104Z,1406868493.104 [MissionManager](INFO): DefineArg tracking_on_surface.TrackingQueryMode = 0.000000 count
2014-08-01T04:48:13.139Z,1406868493.139 [MissionManager](INFO): DefineArg tracking_on_surface.Repeat = 13.000000 count
2014-08-01T04:48:13.147Z,1406868493.147 [MissionManager](INFO): DefineArg tracking_on_surface.MassDefault = 0.000000 n/a
2014-08-01T04:48:13.148Z,1406868493.148 [tracking_on_surface:A.Pitch](DEBUG): Construct.
2014-08-01T04:48:13.431Z,1406868493.431 [tracking_on_surface:TestDrive:C.Wait](DEBUG): Construct Wait.
2014-08-01T04:48:13.444Z,1406868493.444 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Derivation="Tethys/Derivation"
       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/Derivation http://aosn.mbari.org/tethys/Xml/Derivation.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="tracking_on_surface">

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

    <DefineArg Name="ContactLabel"><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="TrackingUpdatePeriod"><Units:second/><Value>45</Value></DefineArg>

    <DefineArg Name="TrackingQueryMode"><Description>
        Which query mode to use. (only two-way works with LSTs right now) 1 is
        one-way, anything else is two-way
    </Description><Units:count/><Value>0</Value></DefineArg>

    <DefineArg Name="Repeat"><Units:count/><Value>13</Value></DefineArg>

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

    <Timeout Duration="MissionTimeout"/>

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

    <Derivation:Tracking>
        <Parallel/>
        <Setting><Derivation:Tracking.contactLabelSetting/><Arg Name="ContactLabel"/></Setting>
        <Setting><Derivation:Tracking.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
        <Setting><Derivation:Tracking.queryModeSetting/><Arg Name="TrackingQueryMode"/></Setting>
    </Derivation:Tracking>

    <Aggregate Id="TestDrive">

        <Sequence Repeat="Repeat"/>

        <Aggregate Id="Data">

            <When>
                <True/>
            </When>

            <SendData Service="Express">
                <Derivation:Tracking.contact_latitude/><Units:degree/>
                <Derivation:Tracking.contact_longitude/><Units:degree/>
                <Derivation:Tracking.contact_depth/><Units:meter/>
                <Derivation:Tracking.range_to_contact/><Units:meter/>
                <Derivation:Tracking.heading_to_contact/><Units:degree/>
            </SendData>

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

        </Aggregate>

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

        <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>1</Value></Setting>
        </Guidance:Wait>

    </Aggregate>

</Mission>


2014-08-01T04:48:13.455Z,1406868493.455 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T04:48:26.410Z,1406868506.410 [SBIT](IMPORTANT): SBIT PASSED
2014-08-01T04:48:26.812Z,1406868506.812 [MissionManager](IMPORTANT): Started mission Startup
2014-08-01T04:48:26.812Z,1406868506.812 [Startup] Running Loop=1
2014-08-01T04:48:26.812Z,1406868506.812 [Startup](INFO): Aggregate::initialize Startup
2014-08-01T04:48:26.812Z,1406868506.812 [Startup:A.GoToSurface] Running Loop=1
2014-08-01T04:48:26.812Z,1406868506.812 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-08-01T04:48:26.813Z,1406868506.813 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-08-01T04:48:26.814Z,1406868506.814 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-08-01T04:48:26.814Z,1406868506.814 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-08-01T04:48:26.820Z,1406868506.820 [Startup:StartupSatComms] Running Loop=1
2014-08-01T04:48:26.820Z,1406868506.820 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-08-01T04:48:26.820Z,1406868506.820 [Startup:StartupSatComms:A] Running Loop=1
2014-08-01T04:48:27.261Z,1406868507.261 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-08-01T04:49:01.245Z,1406868541.245 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T04:49:01.250Z,1406868541.250 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T04:49:01.340Z,1406868541.340 [MissionManager](INFO): DefineArg tracking_on_surface.MissionTimeout = 10.000000 min
2014-08-01T04:49:01.343Z,1406868541.343 [MissionManager](INFO): DefineArg tracking_on_surface.ContactLabel = 1.000000 count
2014-08-01T04:49:01.345Z,1406868541.345 [MissionManager](INFO): DefineArg tracking_on_surface.TrackingUpdatePeriod = 45.000000 s
2014-08-01T04:49:01.351Z,1406868541.351 [MissionManager](INFO): DefineArg tracking_on_surface.TrackingQueryMode = 0.000000 count
2014-08-01T04:49:01.353Z,1406868541.353 [MissionManager](INFO): DefineArg tracking_on_surface.Repeat = 13.000000 count
2014-08-01T04:49:01.356Z,1406868541.356 [MissionManager](INFO): DefineArg tracking_on_surface.MassDefault = 0.000000 n/a
2014-08-01T04:49:01.357Z,1406868541.357 [tracking_on_surface:A.Pitch](DEBUG): Construct.
2014-08-01T04:49:01.430Z,1406868541.430 [tracking_on_surface:TestDrive:C.Wait](DEBUG): Construct Wait.
2014-08-01T04:49:01.436Z,1406868541.436 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Derivation="Tethys/Derivation"
       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/Derivation http://aosn.mbari.org/tethys/Xml/Derivation.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="tracking_on_surface">

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

    <DefineArg Name="ContactLabel"><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="TrackingUpdatePeriod"><Units:second/><Value>45</Value></DefineArg>

    <DefineArg Name="TrackingQueryMode"><Description>
        Which query mode to use. (only two-way works with LSTs right now) 1 is
        one-way, anything else is two-way
    </Description><Units:count/><Value>0</Value></DefineArg>

    <DefineArg Name="Repeat"><Units:count/><Value>13</Value></DefineArg>

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

    <Timeout Duration="MissionTimeout"/>

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

    <Derivation:Tracking>
        <Parallel/>
        <Setting><Derivation:Tracking.contactLabelSetting/><Arg Name="ContactLabel"/></Setting>
        <Setting><Derivation:Tracking.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
        <Setting><Derivation:Tracking.queryModeSetting/><Arg Name="TrackingQueryMode"/></Setting>
    </Derivation:Tracking>

    <Aggregate Id="TestDrive">

        <Sequence Repeat="Repeat"/>

        <Aggregate Id="Data">

            <When>
                <True/>
            </When>

            <SendData Service="Express">
                <Derivation:Tracking.contact_latitude/><Units:degree/>
                <Derivation:Tracking.contact_longitude/><Units:degree/>
                <Derivation:Tracking.contact_depth/><Units:meter/>
                <Derivation:Tracking.range_to_contact/><Units:meter/>
                <Derivation:Tracking.heading_to_contact/><Units:degree/>
            </SendData>

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

        </Aggregate>

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

        <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>1</Value></Setting>
        </Guidance:Wait>

    </Aggregate>

</Mission>


2014-08-01T04:49:01.437Z,1406868541.437 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T04:49:26.995Z,1406868566.995 [Startup:StartupSatComms:A](INFO): Timed out from 2014-08-01T04:48:26.8Z
2014-08-01T04:49:26.995Z,1406868566.995 [Startup:StartupSatComms:A] Stopped
2014-08-01T04:49:26.996Z,1406868566.996 [Startup:StartupSatComms:B] Running Loop=1
2014-08-01T04:49:27.461Z,1406868567.461 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-08-01T04:50:27.315Z,1406868627.315 [Startup:StartupSatComms:B](INFO): Timed out from 2014-08-01T04:49:26.0Z
2014-08-01T04:50:27.315Z,1406868627.315 [Startup:StartupSatComms:B] Stopped
2014-08-01T04:50:27.316Z,1406868627.316 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2014-08-01T04:50:27.316Z,1406868627.316 [Startup:StartupSatComms] Stopped
2014-08-01T04:50:27.316Z,1406868627.316 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2014-08-01T04:50:27.317Z,1406868627.317 [Startup](INFO): Completed Startup
2014-08-01T04:50:27.317Z,1406868627.317 [Startup] Stopped
2014-08-01T04:50:27.317Z,1406868627.317 [Startup](INFO): Aggregate::uninitialize Startup
2014-08-01T04:50:27.317Z,1406868627.317 [Startup:A.GoToSurface] Stopped
2014-08-01T04:50:27.317Z,1406868627.317 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-08-01T04:50:27.879Z,1406868627.879 [MissionManager](IMPORTANT): Started mission tracking_on_surface
2014-08-01T04:50:27.879Z,1406868627.879 [tracking_on_surface] Running Loop=1
2014-08-01T04:50:27.879Z,1406868627.879 [tracking_on_surface](INFO): Aggregate::initialize tracking_on_surface
2014-08-01T04:50:27.879Z,1406868627.879 [tracking_on_surface:A.Pitch] Running Loop=1
2014-08-01T04:50:27.879Z,1406868627.879 [tracking_on_surface:A.Pitch](DEBUG): Initialize.
2014-08-01T04:50:27.879Z,1406868627.879 [tracking_on_surface:B.] Running Loop=1
2014-08-01T04:50:27.879Z,1406868627.879 [tracking_on_surface:B.](INFO): Initializing Tracking.
2014-08-01T04:50:27.880Z,1406868627.880 [tracking_on_surface:TestDrive] Running Loop=1
2014-08-01T04:50:27.880Z,1406868627.880 [tracking_on_surface:TestDrive](INFO): Aggregate::initialize tracking_on_surface:TestDrive
2014-08-01T04:50:27.880Z,1406868627.880 [tracking_on_surface:TestDrive:B] Running Loop=1
2014-08-01T04:50:27.881Z,1406868627.881 [tracking_on_surface:TestDrive:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-08-01T04:50:27.882Z,1406868627.882 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:27.882Z,1406868627.882 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:27.883Z,1406868627.883 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:27.890Z,1406868627.890 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:27.890Z,1406868627.890 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:27.890Z,1406868627.890 [tracking_on_surface:B.] Running Loop=1
2014-08-01T04:50:27.890Z,1406868627.890 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:27.896Z,1406868627.896 [tracking_on_surface:A.Pitch] Running Loop=1
2014-08-01T04:50:28.569Z,1406868628.569 [DAT](INFO): Powering up
2014-08-01T04:50:28.605Z,1406868628.605 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:28.605Z,1406868628.605 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:28.605Z,1406868628.605 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:28.605Z,1406868628.605 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:28.605Z,1406868628.605 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:29.048Z,1406868629.048 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:29.048Z,1406868629.048 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:29.048Z,1406868629.048 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:29.050Z,1406868629.050 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:29.050Z,1406868629.050 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:29.050Z,1406868629.050 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:29.510Z,1406868629.510 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:29.510Z,1406868629.510 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:29.510Z,1406868629.510 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:29.510Z,1406868629.510 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:29.511Z,1406868629.511 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:29.933Z,1406868629.933 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:29.933Z,1406868629.933 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:29.933Z,1406868629.933 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:29.934Z,1406868629.934 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:29.934Z,1406868629.934 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:29.934Z,1406868629.934 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:30.368Z,1406868630.368 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:30.368Z,1406868630.368 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:30.368Z,1406868630.368 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:30.369Z,1406868630.369 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:30.369Z,1406868630.369 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:30.851Z,1406868630.851 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:30.851Z,1406868630.851 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:30.851Z,1406868630.851 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:30.852Z,1406868630.852 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:30.852Z,1406868630.852 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:30.852Z,1406868630.852 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:31.782Z,1406868631.782 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:31.782Z,1406868631.782 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:31.782Z,1406868631.782 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:31.783Z,1406868631.783 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:31.783Z,1406868631.783 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:33.216Z,1406868633.216 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:33.216Z,1406868633.216 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:33.216Z,1406868633.216 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:33.218Z,1406868633.218 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:33.218Z,1406868633.218 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:33.218Z,1406868633.218 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:33.763Z,1406868633.763 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:33.764Z,1406868633.764 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:33.764Z,1406868633.764 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:33.764Z,1406868633.764 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:33.764Z,1406868633.764 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:34.218Z,1406868634.218 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:34.218Z,1406868634.218 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:34.218Z,1406868634.218 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:34.224Z,1406868634.224 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:34.224Z,1406868634.224 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:34.224Z,1406868634.224 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:34.626Z,1406868634.626 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:34.626Z,1406868634.626 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:34.626Z,1406868634.626 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:34.626Z,1406868634.626 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:34.626Z,1406868634.626 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:35.073Z,1406868635.073 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:35.074Z,1406868635.074 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:35.074Z,1406868635.074 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:35.075Z,1406868635.075 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:35.075Z,1406868635.075 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:35.075Z,1406868635.075 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:35.483Z,1406868635.483 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:35.483Z,1406868635.483 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:35.483Z,1406868635.483 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:35.483Z,1406868635.483 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:35.483Z,1406868635.483 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:35.899Z,1406868635.899 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:35.899Z,1406868635.899 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:35.900Z,1406868635.900 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:35.901Z,1406868635.901 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:35.901Z,1406868635.901 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:35.901Z,1406868635.901 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:36.337Z,1406868636.337 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:36.337Z,1406868636.337 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:36.337Z,1406868636.337 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:36.337Z,1406868636.337 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:36.338Z,1406868636.338 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:36.725Z,1406868636.725 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-08-01T04:50:36.725Z,1406868636.725 [DVL_micro] Data Fault, FailCount= 1
2014-08-01T04:50:36.725Z,1406868636.725 [DVL_micro](ERROR): Data Fault
2014-08-01T04:50:36.794Z,1406868636.794 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:36.794Z,1406868636.794 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:36.794Z,1406868636.794 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:36.800Z,1406868636.800 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:36.800Z,1406868636.800 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:36.800Z,1406868636.800 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:36.816Z,1406868636.816 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-08-01T04:50:37.178Z,1406868637.178 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T04:50:37.712Z,1406868637.712 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:37.712Z,1406868637.712 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:37.712Z,1406868637.712 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:37.712Z,1406868637.712 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:37.728Z,1406868637.728 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:38.155Z,1406868638.155 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-08-01T04:50:38.156Z,1406868638.156 [DVL_micro] Hardware Fault, FailCount= 1
2014-08-01T04:50:38.156Z,1406868638.156 [DVL_micro](ERROR): Hardware Fault
2014-08-01T04:50:39.233Z,1406868639.233 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:39.233Z,1406868639.233 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:39.233Z,1406868639.233 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:39.234Z,1406868639.234 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:39.234Z,1406868639.234 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:39.234Z,1406868639.234 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:39.660Z,1406868639.660 [DVL_micro](INFO): Initializing
2014-08-01T04:50:39.704Z,1406868639.704 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:39.704Z,1406868639.704 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:39.704Z,1406868639.704 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:39.704Z,1406868639.704 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:39.704Z,1406868639.704 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:39.713Z,1406868639.713 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-08-01T04:50:39.713Z,1406868639.713 [DVL_micro] No Fault, FailCount= 1
2014-08-01T04:50:40.139Z,1406868640.139 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:40.139Z,1406868640.139 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:40.139Z,1406868640.139 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:40.145Z,1406868640.145 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:40.145Z,1406868640.145 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:40.145Z,1406868640.145 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:40.554Z,1406868640.554 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:40.554Z,1406868640.554 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:40.554Z,1406868640.554 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:40.554Z,1406868640.554 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:40.554Z,1406868640.554 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:40.995Z,1406868640.995 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:40.995Z,1406868640.995 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:40.995Z,1406868640.995 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:40.997Z,1406868640.997 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:40.997Z,1406868640.997 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:40.997Z,1406868640.997 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:41.406Z,1406868641.406 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:41.406Z,1406868641.406 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:41.406Z,1406868641.406 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:41.406Z,1406868641.406 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:41.407Z,1406868641.407 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:41.818Z,1406868641.818 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:41.818Z,1406868641.818 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:41.818Z,1406868641.818 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:41.819Z,1406868641.819 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:41.819Z,1406868641.819 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:41.819Z,1406868641.819 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:42.224Z,1406868642.224 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:42.224Z,1406868642.224 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:42.224Z,1406868642.224 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:42.224Z,1406868642.224 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:42.225Z,1406868642.225 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:42.703Z,1406868642.703 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:42.703Z,1406868642.703 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:42.703Z,1406868642.703 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:42.704Z,1406868642.704 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:42.704Z,1406868642.704 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:42.705Z,1406868642.705 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:43.700Z,1406868643.700 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:43.700Z,1406868643.700 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:43.700Z,1406868643.700 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:43.700Z,1406868643.700 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:43.700Z,1406868643.700 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:45.123Z,1406868645.123 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:45.123Z,1406868645.123 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:45.123Z,1406868645.123 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:45.124Z,1406868645.124 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:45.125Z,1406868645.125 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:45.125Z,1406868645.125 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:45.563Z,1406868645.563 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:45.563Z,1406868645.563 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:45.563Z,1406868645.563 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:45.563Z,1406868645.563 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:45.563Z,1406868645.563 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:46.099Z,1406868646.099 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:46.100Z,1406868646.100 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:46.100Z,1406868646.100 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:46.101Z,1406868646.101 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:46.101Z,1406868646.101 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:46.105Z,1406868646.105 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:46.533Z,1406868646.533 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:46.533Z,1406868646.533 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:46.533Z,1406868646.533 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:46.534Z,1406868646.534 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:46.534Z,1406868646.534 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:46.973Z,1406868646.973 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:46.973Z,1406868646.973 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:46.973Z,1406868646.973 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:46.974Z,1406868646.974 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:46.974Z,1406868646.974 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:46.974Z,1406868646.974 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:47.377Z,1406868647.377 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:47.377Z,1406868647.377 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:47.377Z,1406868647.377 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:47.377Z,1406868647.377 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:47.378Z,1406868647.378 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:47.819Z,1406868647.819 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:47.820Z,1406868647.820 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:47.820Z,1406868647.820 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:47.821Z,1406868647.821 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:47.821Z,1406868647.821 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:47.821Z,1406868647.821 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:48.387Z,1406868648.387 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:48.388Z,1406868648.388 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:48.388Z,1406868648.388 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:48.388Z,1406868648.388 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:48.388Z,1406868648.388 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:49.114Z,1406868649.114 [DAT](FAULT): DAT uart error.serial timeout
2014-08-01T04:50:49.114Z,1406868649.114 [DAT] Communications Fault, FailCount= 1
2014-08-01T04:50:49.114Z,1406868649.114 [DAT](ERROR): Communications Fault
2014-08-01T04:50:49.137Z,1406868649.137 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:49.137Z,1406868649.137 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:49.137Z,1406868649.137 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:49.139Z,1406868649.139 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:49.139Z,1406868649.139 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:49.139Z,1406868649.139 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:49.148Z,1406868649.148 [CBIT](ERROR): Communications Fault in component: DAT
2014-08-01T04:50:50.094Z,1406868650.094 [DAT](INFO): Powering down
2014-08-01T04:50:50.129Z,1406868650.129 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:50.129Z,1406868650.129 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:50.129Z,1406868650.129 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:50.130Z,1406868650.130 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:50.130Z,1406868650.130 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:51.551Z,1406868651.551 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:51.551Z,1406868651.551 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:51.551Z,1406868651.551 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:51.553Z,1406868651.553 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:51.553Z,1406868651.553 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:51.553Z,1406868651.553 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:51.983Z,1406868651.983 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:51.983Z,1406868651.983 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:51.983Z,1406868651.983 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:51.983Z,1406868651.983 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:51.983Z,1406868651.983 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:51.992Z,1406868651.992 [CBIT](INFO): Clearing failed state for component DAT
2014-08-01T04:50:51.992Z,1406868651.992 [DAT] No Fault, FailCount= 1
2014-08-01T04:50:52.482Z,1406868652.482 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:52.482Z,1406868652.482 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:52.482Z,1406868652.482 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:52.484Z,1406868652.484 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:52.484Z,1406868652.484 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:52.484Z,1406868652.484 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:52.907Z,1406868652.907 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:52.907Z,1406868652.907 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:52.907Z,1406868652.907 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:52.907Z,1406868652.907 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:52.907Z,1406868652.907 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:53.422Z,1406868653.422 [DAT](INFO): Powering up
2014-08-01T04:50:53.422Z,1406868653.422 [DAT](DEBUG): Initializing DAT.
2014-08-01T04:50:53.453Z,1406868653.453 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:53.453Z,1406868653.453 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:53.453Z,1406868653.453 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:53.455Z,1406868653.455 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:53.455Z,1406868653.455 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:53.455Z,1406868653.455 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:53.882Z,1406868653.882 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:53.882Z,1406868653.882 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:53.882Z,1406868653.882 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:53.883Z,1406868653.883 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:53.883Z,1406868653.883 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:54.296Z,1406868654.296 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:54.296Z,1406868654.296 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:54.296Z,1406868654.296 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:54.297Z,1406868654.297 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:54.297Z,1406868654.297 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:54.298Z,1406868654.298 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:54.726Z,1406868654.726 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:54.726Z,1406868654.726 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:54.726Z,1406868654.726 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:54.743Z,1406868654.743 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:54.743Z,1406868654.743 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:55.659Z,1406868655.659 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:55.659Z,1406868655.659 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:55.659Z,1406868655.659 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:55.660Z,1406868655.660 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:55.660Z,1406868655.660 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:55.660Z,1406868655.660 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:57.130Z,1406868657.130 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:57.130Z,1406868657.130 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:57.146Z,1406868657.146 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:57.147Z,1406868657.147 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:57.147Z,1406868657.147 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:57.573Z,1406868657.573 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:57.573Z,1406868657.573 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:57.573Z,1406868657.573 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:57.575Z,1406868657.575 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:57.575Z,1406868657.575 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:57.575Z,1406868657.575 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:58.014Z,1406868658.014 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:58.014Z,1406868658.014 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:58.014Z,1406868658.014 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:58.014Z,1406868658.014 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:58.014Z,1406868658.014 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:58.524Z,1406868658.524 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:58.524Z,1406868658.524 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:58.524Z,1406868658.524 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:58.525Z,1406868658.525 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:58.525Z,1406868658.525 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:58.525Z,1406868658.525 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:59.007Z,1406868659.007 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:59.007Z,1406868659.007 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:59.007Z,1406868659.007 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:59.007Z,1406868659.007 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:59.008Z,1406868659.008 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:59.421Z,1406868659.421 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:50:59.421Z,1406868659.421 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:59.421Z,1406868659.421 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:50:59.423Z,1406868659.423 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:50:59.423Z,1406868659.423 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:50:59.423Z,1406868659.423 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:50:59.843Z,1406868659.843 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:50:59.843Z,1406868659.843 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:50:59.843Z,1406868659.843 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:50:59.843Z,1406868659.843 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:50:59.844Z,1406868659.844 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:00.265Z,1406868660.265 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:00.265Z,1406868660.265 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:00.265Z,1406868660.265 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:00.266Z,1406868660.266 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:00.266Z,1406868660.266 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:00.266Z,1406868660.266 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:00.721Z,1406868660.721 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:00.721Z,1406868660.721 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:00.721Z,1406868660.721 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:00.722Z,1406868660.722 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:00.722Z,1406868660.722 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:01.646Z,1406868661.646 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:01.647Z,1406868661.647 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:01.647Z,1406868661.647 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:01.648Z,1406868661.648 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:01.648Z,1406868661.648 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:01.648Z,1406868661.648 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:03.111Z,1406868663.111 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:03.112Z,1406868663.112 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:03.112Z,1406868663.112 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:03.113Z,1406868663.113 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:03.113Z,1406868663.113 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:03.701Z,1406868663.701 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:03.702Z,1406868663.702 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:03.702Z,1406868663.702 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:03.703Z,1406868663.703 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:03.703Z,1406868663.703 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:03.703Z,1406868663.703 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:04.115Z,1406868664.115 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:04.116Z,1406868664.116 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:04.116Z,1406868664.116 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:04.116Z,1406868664.116 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:04.116Z,1406868664.116 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:04.564Z,1406868664.564 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:04.564Z,1406868664.564 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:04.564Z,1406868664.564 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:04.566Z,1406868664.566 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:04.566Z,1406868664.566 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:04.566Z,1406868664.566 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:05.012Z,1406868665.012 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:05.012Z,1406868665.012 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:05.012Z,1406868665.012 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:05.012Z,1406868665.012 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:05.013Z,1406868665.013 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:05.474Z,1406868665.474 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:05.474Z,1406868665.474 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:05.474Z,1406868665.474 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:05.475Z,1406868665.475 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:05.475Z,1406868665.475 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:05.475Z,1406868665.475 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:05.889Z,1406868665.889 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:05.889Z,1406868665.889 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:05.889Z,1406868665.889 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:05.890Z,1406868665.890 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:05.890Z,1406868665.890 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:06.303Z,1406868666.303 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:06.303Z,1406868666.303 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:06.303Z,1406868666.303 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:06.304Z,1406868666.304 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:06.304Z,1406868666.304 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:06.337Z,1406868666.337 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:06.782Z,1406868666.782 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:06.782Z,1406868666.782 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:06.782Z,1406868666.782 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:06.783Z,1406868666.783 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:06.783Z,1406868666.783 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:07.678Z,1406868667.678 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:07.678Z,1406868667.678 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:07.678Z,1406868667.678 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:07.679Z,1406868667.679 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:07.680Z,1406868667.680 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:07.680Z,1406868667.680 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:09.107Z,1406868669.107 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:09.107Z,1406868669.107 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:09.107Z,1406868669.107 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:09.108Z,1406868669.108 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:09.108Z,1406868669.108 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:09.651Z,1406868669.651 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:09.652Z,1406868669.652 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:09.652Z,1406868669.652 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:09.653Z,1406868669.653 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:09.653Z,1406868669.653 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:09.653Z,1406868669.653 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:10.127Z,1406868670.127 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:10.127Z,1406868670.127 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:10.127Z,1406868670.127 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:10.127Z,1406868670.127 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:10.127Z,1406868670.127 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:10.578Z,1406868670.578 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:10.578Z,1406868670.578 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:10.578Z,1406868670.578 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:10.579Z,1406868670.579 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:10.580Z,1406868670.580 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:10.580Z,1406868670.580 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:11.007Z,1406868671.007 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:11.007Z,1406868671.007 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:11.007Z,1406868671.007 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:11.007Z,1406868671.007 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:11.008Z,1406868671.008 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:11.437Z,1406868671.437 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:11.437Z,1406868671.437 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:11.437Z,1406868671.437 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:11.438Z,1406868671.438 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:11.439Z,1406868671.439 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:11.439Z,1406868671.439 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:11.851Z,1406868671.851 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:11.851Z,1406868671.851 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:11.851Z,1406868671.851 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:11.851Z,1406868671.851 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:11.851Z,1406868671.851 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:12.309Z,1406868672.309 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:12.309Z,1406868672.309 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:12.309Z,1406868672.309 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:12.311Z,1406868672.311 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:12.311Z,1406868672.311 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:12.311Z,1406868672.311 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:12.892Z,1406868672.892 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:12.892Z,1406868672.892 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:12.893Z,1406868672.893 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:12.893Z,1406868672.893 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:12.893Z,1406868672.893 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:12.903Z,1406868672.903 [Reporter](INFO): DAT.queryAddressRequested 1 count
2014-08-01T04:51:14.133Z,1406868674.133 [DAT](FAULT): DAT uart error.serial timeout
2014-08-01T04:51:14.133Z,1406868674.133 [DAT] Communications Fault, FailCount= 2
2014-08-01T04:51:14.133Z,1406868674.133 [DAT](ERROR): Communications Fault
2014-08-01T04:51:14.156Z,1406868674.156 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:14.157Z,1406868674.157 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:14.157Z,1406868674.157 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:14.158Z,1406868674.158 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:14.158Z,1406868674.158 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:14.159Z,1406868674.159 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:14.168Z,1406868674.168 [CBIT](ERROR): Communications Fault in component: DAT
2014-08-01T04:51:15.677Z,1406868675.677 [DAT](INFO): Powering down
2014-08-01T04:51:15.711Z,1406868675.711 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:15.711Z,1406868675.711 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:15.711Z,1406868675.711 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:15.711Z,1406868675.711 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:15.712Z,1406868675.712 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:16.165Z,1406868676.165 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:16.166Z,1406868676.166 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:16.166Z,1406868676.166 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:16.167Z,1406868676.167 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:16.167Z,1406868676.167 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:16.167Z,1406868676.167 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:16.605Z,1406868676.605 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:16.605Z,1406868676.605 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:16.606Z,1406868676.606 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:16.606Z,1406868676.606 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:16.606Z,1406868676.606 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:16.615Z,1406868676.615 [CBIT](INFO): Clearing failed state for component DAT
2014-08-01T04:51:16.615Z,1406868676.615 [DAT] No Fault, FailCount= 2
2014-08-01T04:51:17.020Z,1406868677.020 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:17.020Z,1406868677.020 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:17.020Z,1406868677.020 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:17.021Z,1406868677.021 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:17.022Z,1406868677.022 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:17.022Z,1406868677.022 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:17.496Z,1406868677.496 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:17.496Z,1406868677.496 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:17.496Z,1406868677.496 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:17.496Z,1406868677.496 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:17.496Z,1406868677.496 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:17.918Z,1406868677.918 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:17.919Z,1406868677.919 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:17.919Z,1406868677.919 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:17.920Z,1406868677.920 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:17.920Z,1406868677.920 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:17.920Z,1406868677.920 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:18.328Z,1406868678.328 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:18.328Z,1406868678.328 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:18.328Z,1406868678.328 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:18.328Z,1406868678.328 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:18.328Z,1406868678.328 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:18.774Z,1406868678.774 [DAT](INFO): Powering up
2014-08-01T04:51:18.774Z,1406868678.774 [DAT](DEBUG): Initializing DAT.
2014-08-01T04:51:18.827Z,1406868678.827 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:18.827Z,1406868678.827 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:18.827Z,1406868678.827 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:18.828Z,1406868678.828 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:18.828Z,1406868678.828 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:18.828Z,1406868678.828 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:19.793Z,1406868679.793 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:19.793Z,1406868679.793 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:19.793Z,1406868679.793 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:19.793Z,1406868679.793 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:19.793Z,1406868679.793 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:21.234Z,1406868681.234 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:21.234Z,1406868681.234 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:21.234Z,1406868681.234 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:21.235Z,1406868681.235 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:21.235Z,1406868681.235 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:21.236Z,1406868681.236 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:21.708Z,1406868681.708 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:21.708Z,1406868681.708 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:21.712Z,1406868681.712 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:21.713Z,1406868681.713 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:21.713Z,1406868681.713 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:22.174Z,1406868682.174 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:22.174Z,1406868682.174 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:22.175Z,1406868682.175 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:22.176Z,1406868682.176 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:22.176Z,1406868682.176 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:22.176Z,1406868682.176 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:22.628Z,1406868682.628 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:22.628Z,1406868682.628 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:22.628Z,1406868682.628 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:22.629Z,1406868682.629 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:22.629Z,1406868682.629 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:23.038Z,1406868683.038 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:23.038Z,1406868683.038 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:23.038Z,1406868683.038 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:23.039Z,1406868683.039 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:23.039Z,1406868683.039 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:23.040Z,1406868683.040 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:23.451Z,1406868683.451 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:23.451Z,1406868683.451 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:23.452Z,1406868683.452 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:23.452Z,1406868683.452 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:23.452Z,1406868683.452 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:23.889Z,1406868683.889 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:23.889Z,1406868683.889 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:23.889Z,1406868683.889 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:23.890Z,1406868683.890 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:23.890Z,1406868683.890 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:23.890Z,1406868683.890 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:24.349Z,1406868684.349 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:24.350Z,1406868684.350 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:24.350Z,1406868684.350 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:24.350Z,1406868684.350 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:24.350Z,1406868684.350 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:24.815Z,1406868684.815 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:24.815Z,1406868684.815 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:24.815Z,1406868684.815 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:24.816Z,1406868684.816 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:24.816Z,1406868684.816 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:24.816Z,1406868684.816 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:25.722Z,1406868685.722 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:25.722Z,1406868685.722 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:25.723Z,1406868685.723 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:25.723Z,1406868685.723 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:25.723Z,1406868685.723 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:27.247Z,1406868687.247 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:27.247Z,1406868687.247 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:27.248Z,1406868687.248 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:27.249Z,1406868687.249 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:27.249Z,1406868687.249 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:27.249Z,1406868687.249 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:27.701Z,1406868687.701 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:27.701Z,1406868687.701 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:27.701Z,1406868687.701 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:27.701Z,1406868687.701 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:27.701Z,1406868687.701 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:28.191Z,1406868688.191 [tracking_on_surface:TestDrive:B](INFO): Timed out from 2014-08-01T04:50:27.9Z
2014-08-01T04:51:28.191Z,1406868688.191 [tracking_on_surface:TestDrive:B] Stopped
2014-08-01T04:51:28.192Z,1406868688.192 [tracking_on_surface:TestDrive:C.Wait] Running Loop=1
2014-08-01T04:51:28.192Z,1406868688.192 [tracking_on_surface:TestDrive:C.Wait](DEBUG): Initialize Wait Component.
2014-08-01T04:51:28.192Z,1406868688.192 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:28.192Z,1406868688.192 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:28.192Z,1406868688.192 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:28.193Z,1406868688.193 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:28.193Z,1406868688.193 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:28.193Z,1406868688.193 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:28.673Z,1406868688.673 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:28.673Z,1406868688.673 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:28.673Z,1406868688.673 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:28.673Z,1406868688.673 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:28.673Z,1406868688.673 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:29.114Z,1406868689.114 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:29.114Z,1406868689.114 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:29.114Z,1406868689.114 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:29.115Z,1406868689.115 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:29.116Z,1406868689.116 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:29.116Z,1406868689.116 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:29.576Z,1406868689.576 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:29.576Z,1406868689.576 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:29.577Z,1406868689.577 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:29.577Z,1406868689.577 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:29.577Z,1406868689.577 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:30.013Z,1406868690.013 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:30.013Z,1406868690.013 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:30.013Z,1406868690.013 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:30.014Z,1406868690.014 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:30.014Z,1406868690.014 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:30.014Z,1406868690.014 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:30.417Z,1406868690.417 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:30.418Z,1406868690.418 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:30.418Z,1406868690.418 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:30.418Z,1406868690.418 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:30.419Z,1406868690.419 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:30.823Z,1406868690.823 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:30.824Z,1406868690.824 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:30.824Z,1406868690.824 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:30.825Z,1406868690.825 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:30.825Z,1406868690.825 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:30.825Z,1406868690.825 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:31.311Z,1406868691.311 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:31.311Z,1406868691.311 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:31.311Z,1406868691.311 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:31.311Z,1406868691.311 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:31.311Z,1406868691.311 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:31.741Z,1406868691.741 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:31.741Z,1406868691.741 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:31.741Z,1406868691.741 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:31.742Z,1406868691.742 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:31.742Z,1406868691.742 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:31.742Z,1406868691.742 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:32.236Z,1406868692.236 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:32.236Z,1406868692.236 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:32.236Z,1406868692.236 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:32.236Z,1406868692.236 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:32.236Z,1406868692.236 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:32.653Z,1406868692.653 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:32.653Z,1406868692.653 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:32.654Z,1406868692.654 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:32.655Z,1406868692.655 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:32.655Z,1406868692.655 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:32.655Z,1406868692.655 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:33.067Z,1406868693.067 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:33.067Z,1406868693.067 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:33.067Z,1406868693.067 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:33.067Z,1406868693.067 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:33.067Z,1406868693.067 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:33.501Z,1406868693.501 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:33.501Z,1406868693.501 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:33.501Z,1406868693.501 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:33.503Z,1406868693.503 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:33.503Z,1406868693.503 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:33.503Z,1406868693.503 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:33.917Z,1406868693.917 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:33.917Z,1406868693.917 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:33.917Z,1406868693.917 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:33.917Z,1406868693.917 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:33.917Z,1406868693.917 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:34.455Z,1406868694.455 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:34.455Z,1406868694.455 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:34.455Z,1406868694.455 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:34.457Z,1406868694.457 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:34.457Z,1406868694.457 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:34.457Z,1406868694.457 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:34.880Z,1406868694.880 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:34.881Z,1406868694.881 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:34.881Z,1406868694.881 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:34.897Z,1406868694.897 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:34.897Z,1406868694.897 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:35.360Z,1406868695.360 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:35.360Z,1406868695.360 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:35.360Z,1406868695.360 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:35.362Z,1406868695.362 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:35.362Z,1406868695.362 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:35.362Z,1406868695.362 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:35.761Z,1406868695.761 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:35.761Z,1406868695.761 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:35.761Z,1406868695.761 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:35.761Z,1406868695.761 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:35.761Z,1406868695.761 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:36.180Z,1406868696.180 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:36.180Z,1406868696.180 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:36.180Z,1406868696.180 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:36.181Z,1406868696.181 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:36.181Z,1406868696.181 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:36.182Z,1406868696.182 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:36.613Z,1406868696.613 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:36.613Z,1406868696.613 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:36.613Z,1406868696.613 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:36.613Z,1406868696.613 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:36.613Z,1406868696.613 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:37.062Z,1406868697.062 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:37.062Z,1406868697.062 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:37.062Z,1406868697.062 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:37.063Z,1406868697.063 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:37.063Z,1406868697.063 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:37.063Z,1406868697.063 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:37.520Z,1406868697.520 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:37.520Z,1406868697.520 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:37.520Z,1406868697.520 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:37.521Z,1406868697.521 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:37.525Z,1406868697.525 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:38.085Z,1406868698.085 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:38.085Z,1406868698.085 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:38.085Z,1406868698.085 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:38.086Z,1406868698.086 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:38.086Z,1406868698.086 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:38.086Z,1406868698.086 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:38.831Z,1406868698.831 [DAT](FAULT): DAT uart error.serial timeout
2014-08-01T04:51:38.831Z,1406868698.831 [DAT] Communications Fault, FailCount= 3
2014-08-01T04:51:38.831Z,1406868698.831 [DAT](ERROR): Communications Fault
2014-08-01T04:51:38.875Z,1406868698.875 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:38.875Z,1406868698.875 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:38.875Z,1406868698.875 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:38.875Z,1406868698.875 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:38.876Z,1406868698.876 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:38.885Z,1406868698.885 [CBIT](ERROR): Communications Fault in component: DAT
2014-08-01T04:51:38.885Z,1406868698.885 [CBIT](CRITICAL): Communications Fault in component: DAT
2014-08-01T04:51:39.258Z,1406868699.258 [DAT](INFO): Powering down
2014-08-01T04:51:39.276Z,1406868699.276 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T04:51:39.276Z,1406868699.276 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:39.276Z,1406868699.276 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T04:51:39.278Z,1406868699.278 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T04:51:39.278Z,1406868699.278 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T04:51:39.278Z,1406868699.278 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:39.286Z,1406868699.286 [CommandLine](FAULT): Scheduling is paused
2014-08-01T04:51:39.759Z,1406868699.759 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T04:51:39.759Z,1406868699.759 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T04:51:39.759Z,1406868699.759 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T04:51:39.759Z,1406868699.759 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T04:51:39.759Z,1406868699.759 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T04:51:39.760Z,1406868699.760 [tracking_on_surface] Stopped
2014-08-01T04:51:39.760Z,1406868699.760 [tracking_on_surface](INFO): Aggregate::uninitialize tracking_on_surface
2014-08-01T04:51:39.760Z,1406868699.760 [tracking_on_surface:A.Pitch] Stopped
2014-08-01T04:51:39.760Z,1406868699.760 [tracking_on_surface:B.] Stopped
2014-08-01T04:51:39.760Z,1406868699.760 [tracking_on_surface:B.](DEBUG): Uninitializing Tracking.
2014-08-01T04:51:39.760Z,1406868699.760 [tracking_on_surface:TestDrive] Stopped
2014-08-01T04:51:39.776Z,1406868699.776 [tracking_on_surface:TestDrive](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive
2014-08-01T04:51:39.777Z,1406868699.777 [tracking_on_surface:TestDrive:C.Wait] Stopped
2014-08-01T04:51:39.777Z,1406868699.777 [tracking_on_surface:TestDrive:C.Wait](DEBUG): Uninitialize Wait Component.
2014-08-01T04:51:39.803Z,1406868699.803 [Reporter](INFO): DAT.queryAddressRequested no_value
2014-08-01T04:51:40.202Z,1406868700.202 [MissionManager](IMPORTANT): Started mission Default
2014-08-01T04:51:40.202Z,1406868700.202 [Default] Running Loop=1
2014-08-01T04:51:40.202Z,1406868700.202 [Default](INFO): Aggregate::initialize Default
2014-08-01T04:51:40.202Z,1406868700.202 [Default:A.GoToSurface] Running Loop=1
2014-08-01T04:51:40.202Z,1406868700.202 [Default:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-08-01T04:51:40.203Z,1406868700.203 [Default:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-08-01T04:51:40.203Z,1406868700.203 [Default:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-08-01T04:51:40.203Z,1406868700.203 [Default:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-08-01T04:51:40.204Z,1406868700.204 [Default:CheckIn] Running Loop=1
2014-08-01T04:51:40.204Z,1406868700.204 [Default:CheckIn](INFO): Aggregate::initialize Default:CheckIn
2014-08-01T04:51:40.204Z,1406868700.204 [Default:CheckIn:A.SetSpeed] Running Loop=1
2014-08-01T04:51:40.204Z,1406868700.204 [Default:CheckIn:A.SetSpeed](DEBUG): Initialize.
2014-08-01T04:51:40.204Z,1406868700.204 [Default:CheckIn:Read_GPS] Running Loop=1
2014-08-01T04:51:40.205Z,1406868700.205 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-08-01T04:51:40.207Z,1406868700.207 [Default:CheckIn:A.SetSpeed] Running Loop=1
2014-08-01T04:51:40.217Z,1406868700.217 [Default:WaitAtTheSurface] Running Loop=1
2014-08-01T04:51:40.218Z,1406868700.218 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface
2014-08-01T04:51:40.218Z,1406868700.218 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2014-08-01T04:51:40.218Z,1406868700.218 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Initialize.
2014-08-01T04:51:40.686Z,1406868700.686 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2014-08-01T04:53:44.302Z,1406868824.302 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-08-01T04:53:44.302Z,1406868824.302 [DVL_micro] Data Fault, FailCount= 1
2014-08-01T04:53:44.303Z,1406868824.303 [DVL_micro](ERROR): Data Fault
2014-08-01T04:53:44.352Z,1406868824.352 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-08-01T04:53:44.716Z,1406868824.716 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T04:53:45.125Z,1406868825.125 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-08-01T04:53:45.125Z,1406868825.125 [DVL_micro] Hardware Fault, FailCount= 1
2014-08-01T04:53:45.125Z,1406868825.125 [DVL_micro](ERROR): Hardware Fault
2014-08-01T04:53:45.616Z,1406868825.616 [DVL_micro](INFO): Initializing
2014-08-01T04:53:45.682Z,1406868825.682 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-08-01T04:53:45.683Z,1406868825.682 [DVL_micro] No Fault, FailCount= 1
2014-08-01T04:56:39.156Z,1406868999.156 [CBIT](INFO): Clearing failed count for component DAT
2014-08-01T04:56:39.156Z,1406868999.156 [DAT] No Fault, FailCount= 3
2014-08-01T04:56:39.583Z,1406868999.583 [DAT](INFO): Powering up
2014-08-01T04:56:39.583Z,1406868999.583 [DAT](DEBUG): Initializing DAT.
2014-08-01T04:56:40.514Z,1406869000.514 [Default:CheckIn:Read_GPS](INFO): Timed out from 2014-08-01T04:51:40.2Z
2014-08-01T04:56:40.514Z,1406869000.514 [Default:CheckIn:Read_GPS] Stopped
2014-08-01T04:56:40.514Z,1406869000.514 [Default:CheckIn:Read_Iridium] Running Loop=1
2014-08-01T04:56:40.952Z,1406869000.952 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-08-01T04:56:49.884Z,1406869009.884 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-08-01T04:56:49.884Z,1406869009.884 [DVL_micro] Data Fault, FailCount= 1
2014-08-01T04:56:49.885Z,1406869009.885 [DVL_micro](ERROR): Data Fault
2014-08-01T04:56:50.952Z,1406869010.952 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-08-01T04:56:51.338Z,1406869011.338 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T04:56:51.811Z,1406869011.811 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-08-01T04:56:51.811Z,1406869011.811 [DVL_micro] Hardware Fault, FailCount= 1
2014-08-01T04:56:51.811Z,1406869011.811 [DVL_micro](ERROR): Hardware Fault
2014-08-01T04:56:52.280Z,1406869012.280 [DVL_micro](INFO): Initializing
2014-08-01T04:56:52.366Z,1406869012.366 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-08-01T04:56:52.366Z,1406869012.366 [DVL_micro] No Fault, FailCount= 1
2014-08-01T04:56:59.669Z,1406869019.669 [DAT](INFO): Powering down
2014-08-01T04:57:39.924Z,1406869059.924 [NAL9602](FAULT): GPS failed to acquire within timeout.
2014-08-01T04:57:39.924Z,1406869059.924 [NAL9602] Data Fault, FailCount= 1
2014-08-01T04:57:39.924Z,1406869059.924 [NAL9602](ERROR): Data Fault
2014-08-01T04:57:39.984Z,1406869059.984 [CBIT](ERROR): Data Fault in component: NAL9602
2014-08-01T04:57:40.350Z,1406869060.350 [NAL9602](INFO): Powering down
2014-08-01T04:57:41.223Z,1406869061.223 [CBIT](INFO): Clearing failed state for component NAL9602
2014-08-01T04:57:41.223Z,1406869061.223 [NAL9602] No Fault, FailCount= 1
2014-08-01T04:57:45.495Z,1406869065.495 [NAL9602](INFO): Powering up NAL9602
2014-08-01T04:57:56.245Z,1406869076.245 [NAL9602](INFO): NAL9602 initialized
2014-08-01T04:59:58.552Z,1406869198.552 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-08-01T04:59:58.552Z,1406869198.552 [DVL_micro] Data Fault, FailCount= 1
2014-08-01T04:59:58.552Z,1406869198.552 [DVL_micro](ERROR): Data Fault
2014-08-01T04:59:58.612Z,1406869198.612 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-08-01T04:59:58.977Z,1406869198.977 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T04:59:59.437Z,1406869199.437 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-08-01T04:59:59.437Z,1406869199.437 [DVL_micro] Hardware Fault, FailCount= 1
2014-08-01T04:59:59.437Z,1406869199.437 [DVL_micro](ERROR): Hardware Fault
2014-08-01T04:59:59.851Z,1406869199.851 [DVL_micro](INFO): Initializing
2014-08-01T04:59:59.915Z,1406869199.915 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-08-01T04:59:59.915Z,1406869199.915 [DVL_micro] No Fault, FailCount= 1
2014-08-01T05:00:57.742Z,1406869257.742 [CommandLine](IMPORTANT): got command restart application
2014-08-01T05:00:58.750Z,1406869258.750 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:00:58.751Z,1406869258.751 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:00:58.799Z,1406869258.799 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2014-08-01T05:00:58.799Z,1406869258.799 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:00:58.800Z,1406869258.800 [CommandLine](INFO): Join timeout helper Thread ID is 1156
2014-08-01T05:00:58.801Z,1406869258.801 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2014-08-01T05:00:58.801Z,1406869258.801 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:00:58.801Z,1406869258.801 [NavChartDb](INFO): Join timeout helper Thread ID is 1157
2014-08-01T05:00:59.092Z,1406869259.092 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:00:59.092Z,1406869259.092 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:00:59.104Z,1406869259.104 [ComponentRegistry](INFO): Shutting down Radio_Freewave ThreadHandler
2014-08-01T05:00:59.104Z,1406869259.104 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:00:59.104Z,1406869259.104 [Radio_Freewave](INFO): Join timeout helper Thread ID is 1158
2014-08-01T05:00:59.421Z,1406869259.421 [Radio_Freewave ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:00:59.517Z,1406869259.517 [Radio_Freewave](INFO): Powering down
2014-08-01T05:00:59.921Z,1406869259.921 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:00:59.929Z,1406869259.929 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2014-08-01T05:00:59.929Z,1406869259.929 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:00:59.930Z,1406869259.930 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1160
2014-08-01T05:01:00.110Z,1406869260.110 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:01:00.110Z,1406869260.110 [WetLabsBB2FL](INFO): Powering down
2014-08-01T05:01:00.111Z,1406869260.111 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:01:00.129Z,1406869260.129 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2014-08-01T05:01:00.129Z,1406869260.129 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:01:00.130Z,1406869260.130 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1161
2014-08-01T05:01:00.191Z,1406869260.191 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:01:00.191Z,1406869260.191 [CTD_NeilBrown](INFO): Powering down
2014-08-01T05:01:00.192Z,1406869260.192 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:01:00.211Z,1406869260.211 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2014-08-01T05:01:00.211Z,1406869260.211 [logger ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:01:00.211Z,1406869260.211 [logger](INFO): Join timeout helper Thread ID is 1162
2014-08-01T05:01:00.238Z,1406869260.238 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:01:00.238Z,1406869260.238 [logger ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:01:00.250Z,1406869260.250 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2014-08-01T05:01:00.251Z,1406869260.251 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:01:00.251Z,1406869260.251 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2014-08-01T05:01:00.251Z,1406869260.251 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:01:00.251Z,1406869260.251 [controlThread](INFO): Join timeout helper Thread ID is 1163
2014-08-01T05:01:00.529Z,1406869260.529 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:01:00.529Z,1406869260.529 [controlThread](DEBUG): Uninitializing ControlThread
2014-08-01T05:01:00.529Z,1406869260.529 [AHRS_sp3003D](INFO): Powering down
2014-08-01T05:01:00.531Z,1406869260.531 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T05:01:00.532Z,1406869260.532 [NAL9602](INFO): Powering down
2014-08-01T05:01:00.533Z,1406869260.533 [DAT](INFO): Powering down
2014-08-01T05:01:00.535Z,1406869260.535 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-08-01T05:01:00.537Z,1406869260.537 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2014-08-01T05:01:00.538Z,1406869260.538 [Default] Stopped
2014-08-01T05:01:00.538Z,1406869260.538 [Default](INFO): Aggregate::uninitialize Default
2014-08-01T05:01:00.538Z,1406869260.538 [Default:A.GoToSurface] Stopped
2014-08-01T05:01:00.538Z,1406869260.538 [Default:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-08-01T05:01:00.539Z,1406869260.539 [Default:CheckIn] Stopped
2014-08-01T05:01:00.539Z,1406869260.539 [Default:CheckIn](INFO): Aggregate::uninitialize Default:CheckIn
2014-08-01T05:01:00.539Z,1406869260.539 [Default:CheckIn:A.SetSpeed] Stopped
2014-08-01T05:01:00.539Z,1406869260.539 [Default:CheckIn:A.SetSpeed](DEBUG): Uninitialize.
2014-08-01T05:01:00.539Z,1406869260.539 [Default:CheckIn:Read_Iridium] Stopped
2014-08-01T05:01:00.539Z,1406869260.539 [Default:WaitAtTheSurface] Stopped
2014-08-01T05:01:00.539Z,1406869260.539 [Default:WaitAtTheSurface](INFO): Aggregate::uninitialize Default:WaitAtTheSurface
2014-08-01T05:01:00.539Z,1406869260.539 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Stopped
2014-08-01T05:01:00.539Z,1406869260.539 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Uninitialize.
2014-08-01T05:01:00.542Z,1406869260.542 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2014-08-01T05:01:00.542Z,1406869260.542 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2014-08-01T05:01:00.543Z,1406869260.543 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2014-08-01T05:01:00.543Z,1406869260.543 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2014-08-01T05:01:00.543Z,1406869260.543 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-08-01T05:01:00.543Z,1406869260.543 [BuoyancyServo](INFO): Powering down
2014-08-01T05:01:00.558Z,1406869260.558 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2014-08-01T05:01:00.558Z,1406869260.558 [ElevatorServo](INFO): Powering down
2014-08-01T05:01:00.559Z,1406869260.559 [MassServo](DEBUG): Uninitialize Mass Servo.
2014-08-01T05:01:00.559Z,1406869260.559 [MassServo](INFO): Powering down
2014-08-01T05:01:00.560Z,1406869260.560 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2014-08-01T05:01:00.560Z,1406869260.560 [RudderServo](INFO): Powering down
2014-08-01T05:01:00.561Z,1406869260.561 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2014-08-01T05:01:00.561Z,1406869260.561 [ThrusterServo](INFO): Powering down
2014-08-01T05:01:00.562Z,1406869260.562 [SBIT](DEBUG): Uninitialize SBIT Component.
2014-08-01T05:01:00.562Z,1406869260.562 [IBIT](DEBUG): Uninitialize IBIT Component.
2014-08-01T05:01:00.562Z,1406869260.562 [CBIT](DEBUG): Uninitialize CBIT Component.
2014-08-01T05:01:00.607Z,1406869260.607 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:01:00.677Z,1406869260.677 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:01:00.680Z,1406869260.680 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:01:00.695Z,1406869260.695 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:01:00.741Z,1406869260.741 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:01:00.777Z,1406869260.777 [logger ThreadHandler](INFO): Thread cancelled.