2014-08-01T05:05:30.337Z,1406869530.337 [Supervisor](DEBUG): Initializing supervisor.
2014-08-01T05:05:30.340Z,1406869530.340 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-08-01T05:05:30.340Z,1406869530.340 [SyncHandler](INFO): Protected caller Thread ID is 1309
2014-08-01T05:05:30.341Z,1406869530.341 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-08-01T05:05:30.342Z,1406869530.342 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2014-08-01T05:05:30.342Z,1406869530.342 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1310
2014-08-01T05:05:30.345Z,1406869530.345 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-08-01T05:05:30.358Z,1406869530.358 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-08-01T05:05:30.359Z,1406869530.359 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2014-08-01T05:05:30.359Z,1406869530.359 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1311
2014-08-01T05:05:30.360Z,1406869530.360 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-08-01T05:05:30.361Z,1406869530.361 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2014-08-01T05:05:30.362Z,1406869530.362 [logger ThreadHandler](INFO): Protected caller Thread ID is 1312
2014-08-01T05:05:30.364Z,1406869530.364 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-08-01T05:05:30.364Z,1406869530.364 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-08-01T05:05:30.366Z,1406869530.366 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-08-01T05:05:30.720Z,1406869530.720 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-08-01T05:05:30.720Z,1406869530.720 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-08-01T05:05:30.875Z,1406869530.875 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-08-01T05:05:30.876Z,1406869530.876 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-08-01T05:05:30.982Z,1406869530.982 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-08-01T05:05:30.983Z,1406869530.983 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-08-01T05:05:31.114Z,1406869531.114 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-08-01T05:05:31.114Z,1406869531.114 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-08-01T05:05:31.203Z,1406869531.203 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-08-01T05:05:31.414Z,1406869531.414 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-08-01T05:05:31.415Z,1406869531.415 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-08-01T05:05:31.501Z,1406869531.501 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-08-01T05:05:31.501Z,1406869531.501 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-08-01T05:05:31.678Z,1406869531.678 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-08-01T05:05:31.679Z,1406869531.679 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-08-01T05:05:31.966Z,1406869531.966 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-08-01T05:05:31.967Z,1406869531.967 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-08-01T05:05:32.269Z,1406869532.269 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-08-01T05:05:32.269Z,1406869532.269 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-08-01T05:05:32.768Z,1406869532.768 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-08-01T05:05:32.769Z,1406869532.769 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-08-01T05:05:32.960Z,1406869532.960 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-08-01T05:05:32.961Z,1406869532.961 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-08-01T05:05:33.066Z,1406869533.066 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-08-01T05:05:33.067Z,1406869533.067 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-08-01T05:05:33.462Z,1406869533.462 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-08-01T05:05:33.463Z,1406869533.463 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-08-01T05:05:33.572Z,1406869533.572 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-08-01T05:05:33.574Z,1406869533.574 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-08-01T05:05:33.575Z,1406869533.575 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-08-01T05:05:33.678Z,1406869533.678 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-08-01T05:05:33.794Z,1406869533.794 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-08-01T05:05:33.904Z,1406869533.904 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-08-01T05:05:33.000Z,1406869534.000 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-08-01T05:05:34.126Z,1406869534.126 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-08-01T05:05:34.269Z,1406869534.269 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-08-01T05:05:34.369Z,1406869534.369 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-08-01T05:05:34.454Z,1406869534.454 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-08-01T05:05:34.546Z,1406869534.546 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-08-01T05:05:34.642Z,1406869534.642 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-08-01T05:05:34.752Z,1406869534.752 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-08-01T05:05:34.837Z,1406869534.837 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2014-08-01T05:05:34.839Z,1406869534.839 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-08-01T05:05:34.897Z,1406869534.897 [VerticalControl](DEBUG): Construct VerticalControl.
2014-08-01T05:05:35.026Z,1406869535.026 [VerticalControl] Loaded
2014-08-01T05:05:35.026Z,1406869535.026 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-08-01T05:05:35.027Z,1406869535.027 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-08-01T05:05:35.105Z,1406869535.105 [HorizontalControl] Loaded
2014-08-01T05:05:35.105Z,1406869535.105 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-08-01T05:05:35.106Z,1406869535.106 [SpeedControl](DEBUG): Construct SpeedControl.
2014-08-01T05:05:35.112Z,1406869535.112 [SpeedControl] Loaded
2014-08-01T05:05:35.113Z,1406869535.113 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-08-01T05:05:35.113Z,1406869535.113 [LoopControl](DEBUG): Construct LoopControl.
2014-08-01T05:05:35.114Z,1406869535.114 [LoopControl] Loaded
2014-08-01T05:05:35.114Z,1406869535.114 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-08-01T05:05:35.115Z,1406869535.115 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-08-01T05:05:35.115Z,1406869535.115 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-08-01T05:05:35.223Z,1406869535.223 [SBIT](DEBUG): Construct Startup Built In Test.
2014-08-01T05:05:35.235Z,1406869535.235 [SBIT] Loaded
2014-08-01T05:05:35.236Z,1406869535.236 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-08-01T05:05:35.237Z,1406869535.237 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-08-01T05:05:35.267Z,1406869535.267 [IBIT] Loaded
2014-08-01T05:05:35.267Z,1406869535.267 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-08-01T05:05:35.269Z,1406869535.269 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-08-01T05:05:35.396Z,1406869535.396 [CBIT] Loaded
2014-08-01T05:05:35.396Z,1406869535.396 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-08-01T05:05:35.397Z,1406869535.397 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-08-01T05:05:35.398Z,1406869535.398 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-08-01T05:05:35.418Z,1406869535.418 [DepthRateCalculator] Loaded
2014-08-01T05:05:35.418Z,1406869535.418 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-08-01T05:05:35.424Z,1406869535.424 [PitchRateCalculator] Loaded
2014-08-01T05:05:35.425Z,1406869535.425 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-08-01T05:05:35.437Z,1406869535.437 [SpeedCalculator] Loaded
2014-08-01T05:05:35.437Z,1406869535.437 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-08-01T05:05:35.455Z,1406869535.455 [TempGradientCalculator] Loaded
2014-08-01T05:05:35.455Z,1406869535.455 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-08-01T05:05:35.461Z,1406869535.461 [YawRateCalculator] Loaded
2014-08-01T05:05:35.462Z,1406869535.462 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-08-01T05:05:35.462Z,1406869535.462 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-08-01T05:05:35.463Z,1406869535.463 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-08-01T05:05:40.631Z,1406869540.631 [HFRadarModelCalc] Loaded
2014-08-01T05:05:40.632Z,1406869540.632 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2014-08-01T05:05:44.680Z,1406869544.680 [HFRadarCompactModelForecaster] Loaded
2014-08-01T05:05:44.680Z,1406869544.680 [ComponentRegistry](DEBUG): SyncComponent "HFRadarCompactModelForecaster" handled in the control thread.
2014-08-01T05:05:45.789Z,1406869545.789 [HFRCMSpaceInterpolator] Loaded
2014-08-01T05:05:45.790Z,1406869545.790 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSpaceInterpolator" handled in the control thread.
2014-08-01T05:05:45.792Z,1406869545.792 [HFRCMTimeInterpolator] Loaded
2014-08-01T05:05:45.792Z,1406869545.792 [ComponentRegistry](DEBUG): SyncComponent "HFRCMTimeInterpolator" handled in the control thread.
2014-08-01T05:05:46.878Z,1406869546.878 [HFRCMReconstructedInterpolator] Loaded
2014-08-01T05:05:46.879Z,1406869546.879 [ComponentRegistry](DEBUG): SyncComponent "HFRCMReconstructedInterpolator" handled in the control thread.
2014-08-01T05:05:46.892Z,1406869546.892 [HFRCMSurfaceCurrentAtVehicleLocation] Loaded
2014-08-01T05:05:46.892Z,1406869546.892 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSurfaceCurrentAtVehicleLocation" handled in the control thread.
2014-08-01T05:05:46.921Z,1406869546.921 [HFRCMVirtualSurfaceDrifter] Loaded
2014-08-01T05:05:46.921Z,1406869546.921 [ComponentRegistry](DEBUG): SyncComponent "HFRCMVirtualSurfaceDrifter" handled in the control thread.
2014-08-01T05:05:46.922Z,1406869546.922 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-08-01T05:05:46.923Z,1406869546.923 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-08-01T05:05:47.195Z,1406869547.195 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-08-01T05:05:47.196Z,1406869547.196 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-08-01T05:05:47.288Z,1406869547.288 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-08-01T05:05:47.289Z,1406869547.289 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-08-01T05:05:47.338Z,1406869547.338 [DeadReckonWithRespectToWater] Loaded
2014-08-01T05:05:47.338Z,1406869547.338 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToWater" handled in the control thread.
2014-08-01T05:05:47.389Z,1406869547.389 [DeadReckonWithRespectToSeafloor] Loaded
2014-08-01T05:05:47.389Z,1406869547.389 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2014-08-01T05:05:47.455Z,1406869547.455 [DeadReckonUsingDVLWaterTrack] Loaded
2014-08-01T05:05:47.455Z,1406869547.455 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingDVLWaterTrack" handled in the control thread.
2014-08-01T05:05:47.508Z,1406869547.508 [DeadReckonUsingCompactModelForecast] Loaded
2014-08-01T05:05:47.508Z,1406869547.508 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingCompactModelForecast" handled in the control thread.
2014-08-01T05:05:47.527Z,1406869547.527 [NavChart] Loaded
2014-08-01T05:05:47.527Z,1406869547.527 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-08-01T05:05:47.532Z,1406869547.532 [UniversalFixResidualReporter] Loaded
2014-08-01T05:05:47.532Z,1406869547.532 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-08-01T05:05:47.533Z,1406869547.533 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-08-01T05:05:47.533Z,1406869547.533 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-08-01T05:05:47.539Z,1406869547.539 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-08-01T05:05:47.540Z,1406869547.540 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-08-01T05:05:47.724Z,1406869547.724 [CTD_NeilBrown] Loaded
2014-08-01T05:05:47.724Z,1406869547.724 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-08-01T05:05:47.726Z,1406869547.726 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407B94E0
2014-08-01T05:05:47.726Z,1406869547.726 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1394
2014-08-01T05:05:47.743Z,1406869547.743 [PAR_Licor] Loaded
2014-08-01T05:05:47.743Z,1406869547.743 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-08-01T05:05:47.782Z,1406869547.782 [WetLabsBB2FL] Loaded
2014-08-01T05:05:47.782Z,1406869547.782 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-08-01T05:05:47.783Z,1406869547.783 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407E94E0
2014-08-01T05:05:47.784Z,1406869547.784 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1395
2014-08-01T05:05:47.784Z,1406869547.784 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-08-01T05:05:47.785Z,1406869547.785 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-08-01T05:05:48.104Z,1406869548.104 [AHRS_sp3003D] Loaded
2014-08-01T05:05:48.105Z,1406869548.105 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-08-01T05:05:48.389Z,1406869548.389 [Batt_Ocean_Server] Loaded
2014-08-01T05:05:48.389Z,1406869548.389 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-08-01T05:05:48.403Z,1406869548.403 [Depth_Keller] Loaded
2014-08-01T05:05:48.404Z,1406869548.404 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-08-01T05:05:48.409Z,1406869548.409 [DropWeight] Loaded
2014-08-01T05:05:48.410Z,1406869548.410 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-08-01T05:05:48.555Z,1406869548.555 [DVL_micro] Loaded
2014-08-01T05:05:48.555Z,1406869548.555 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2014-08-01T05:05:48.658Z,1406869548.658 [NAL9602] Loaded
2014-08-01T05:05:48.659Z,1406869548.659 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-08-01T05:05:48.704Z,1406869548.704 [Onboard] Loaded
2014-08-01T05:05:48.705Z,1406869548.705 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-08-01T05:05:48.712Z,1406869548.712 [Radio_Freewave] Loaded
2014-08-01T05:05:48.713Z,1406869548.713 [ComponentRegistry](DEBUG): Component "Radio_Freewave" handled in its own thread.
2014-08-01T05:05:48.714Z,1406869548.714 [Radio_Freewave ThreadHandler](DEBUG): Created PCaller Thread at 40A1E4E0
2014-08-01T05:05:48.714Z,1406869548.714 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 1396
2014-08-01T05:05:48.856Z,1406869548.856 [DAT] Loaded
2014-08-01T05:05:48.857Z,1406869548.857 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2014-08-01T05:05:48.864Z,1406869548.864 [SCPI] Loaded
2014-08-01T05:05:48.864Z,1406869548.864 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-08-01T05:05:49.208Z,1406869549.208 [BPC1] Loaded
2014-08-01T05:05:49.209Z,1406869549.209 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2014-08-01T05:05:49.209Z,1406869549.209 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-08-01T05:05:49.210Z,1406869549.210 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-08-01T05:05:49.324Z,1406869549.324 [BuoyancyServo] Loaded
2014-08-01T05:05:49.324Z,1406869549.324 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-08-01T05:05:49.337Z,1406869549.337 [ElevatorServo] Loaded
2014-08-01T05:05:49.337Z,1406869549.337 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-08-01T05:05:49.350Z,1406869549.350 [MassServo] Loaded
2014-08-01T05:05:49.350Z,1406869549.350 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-08-01T05:05:49.363Z,1406869549.363 [RudderServo] Loaded
2014-08-01T05:05:49.363Z,1406869549.363 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-08-01T05:05:49.375Z,1406869549.375 [ThrusterServo] Loaded
2014-08-01T05:05:49.376Z,1406869549.376 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-08-01T05:05:49.376Z,1406869549.376 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-08-01T05:05:49.377Z,1406869549.377 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-08-01T05:05:49.551Z,1406869549.551 [InternalSim] Loaded
2014-08-01T05:05:49.551Z,1406869549.551 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-08-01T05:05:49.552Z,1406869549.552 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-08-01T05:05:49.553Z,1406869549.553 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-08-01T05:05:49.580Z,1406869549.580 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-08-01T05:05:49.582Z,1406869549.582 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-08-01T05:05:49.583Z,1406869549.583 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-08-01T05:05:49.589Z,1406869549.589 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-08-01T05:05:49.591Z,1406869549.591 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ACF4E0
2014-08-01T05:05:49.591Z,1406869549.591 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1397
2014-08-01T05:05:49.596Z,1406869549.596 [Supervisor](INFO): Main Thread ID is 977
2014-08-01T05:05:49.596Z,1406869549.596 [Supervisor](DEBUG): Running supervisor.
2014-08-01T05:05:49.597Z,1406869549.597 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1398
2014-08-01T05:05:49.601Z,1406869549.601 [controlThread ThreadHandler](INFO): Handler Thread ID is 1399
2014-08-01T05:05:49.601Z,1406869549.601 [controlThread](DEBUG): Initializing ControlThread
2014-08-01T05:05:49.602Z,1406869549.602 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-08-01T05:05:49.604Z,1406869549.604 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-08-01T05:05:49.604Z,1406869549.604 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-08-01T05:05:49.605Z,1406869549.605 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-08-01T05:05:49.605Z,1406869549.605 [SBIT](INFO): Initialize SBIT Component.
2014-08-01T05:05:49.606Z,1406869549.606 [SBIT](IMPORTANT): Tethys CM Info: SVN revision: 11462
2014-08-01T05:05:49.606Z,1406869549.606 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2014-08-01T05:05:49.606Z,1406869549.606 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-08-01T05:05:49.607Z,1406869549.607 [IBIT](INFO): Initialize IBIT Component.
2014-08-01T05:05:49.608Z,1406869549.608 [CBIT](DEBUG): Initialize CBIT Component.
2014-08-01T05:05:49.608Z,1406869549.608 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2014-08-01T05:05:49.609Z,1406869549.609 [logger ThreadHandler](INFO): Handler Thread ID is 1400
2014-08-01T05:05:49.634Z,1406869549.634 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-08-01T05:05:49.635Z,1406869549.635 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-08-01T05:05:49.635Z,1406869549.635 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-08-01T05:05:49.635Z,1406869549.635 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-08-01T05:05:49.636Z,1406869549.636 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-08-01T05:05:49.643Z,1406869549.643 [HFRadarCompactModelForecaster](DEBUG): Found new ECs!
2014-08-01T05:05:49.659Z,1406869549.659 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1401
2014-08-01T05:05:49.659Z,1406869549.659 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-08-01T05:05:49.667Z,1406869549.667 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-08-01T05:05:49.687Z,1406869549.687 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1403
2014-08-01T05:05:49.688Z,1406869549.688 [WetLabsBB2FL](INFO): Powering down
2014-08-01T05:05:49.719Z,1406869549.719 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 1404
2014-08-01T05:05:49.735Z,1406869549.735 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1405
2014-08-01T05:05:49.738Z,1406869549.738 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-08-01T05:05:49.739Z,1406869549.739 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-08-01T05:05:49.739Z,1406869549.739 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-08-01T05:05:49.739Z,1406869549.739 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-08-01T05:05:49.739Z,1406869549.739 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-08-01T05:05:49.740Z,1406869549.740 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-08-01T05:05:49.740Z,1406869549.740 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-08-01T05:05:49.740Z,1406869549.740 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-08-01T05:05:49.740Z,1406869549.740 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-08-01T05:05:58.733Z,1406869558.733 [HFRadarCompactModelForecaster](IMPORTANT): forecast time 201408010200: published 50 modes in rows, 61 hours in columns
2014-08-01T05:05:58.736Z,1406869558.736 [HFRadarCompactModelForecaster](IMPORTANT): expansionCoefficients_[0][48] = -9.214992 for 2014-08-01T02:00:00.000Z
2014-08-01T05:05:58.753Z,1406869558.753 [HFRCMSpaceInterpolator](DEBUG): Initializing HFRCMSpaceInterpolator component with verbosity level 0.
2014-08-01T05:05:58.754Z,1406869558.754 [HFRCMTimeInterpolator](DEBUG): Initializing HFRCMTimeInterpolator component.
2014-08-01T05:05:58.755Z,1406869558.755 [HFRCMReconstructedInterpolator](INFO): Initializing HFRCMReconstructedInterpolator component with velocityAccuracy_ = 0.300000 m/s.
2014-08-01T05:05:58.756Z,1406869558.756 [HFRCMSurfaceCurrentAtVehicleLocation](DEBUG): Initializing HFRCMSurfaceCurrentAtVehicleLocation component.
2014-08-01T05:05:58.756Z,1406869558.756 [HFRCMVirtualSurfaceDrifter](DEBUG): Initializing HFRCMVirtualSurfaceDrifter component.
2014-08-01T05:05:58.757Z,1406869558.757 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-08-01T05:05:58.757Z,1406869558.757 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component.
2014-08-01T05:05:58.758Z,1406869558.758 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component.
2014-08-01T05:05:58.758Z,1406869558.758 [DeadReckonUsingDVLWaterTrack](DEBUG): Initializing DeadReckonUsingDVLWaterTrack component.
2014-08-01T05:05:58.759Z,1406869558.759 [DeadReckonUsingCompactModelForecast](DEBUG): Initializing DeadReckonUsingCompactModelForecast component.
2014-08-01T05:05:58.759Z,1406869558.759 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-08-01T05:05:58.759Z,1406869558.759 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-08-01T05:06:00.466Z,1406869560.466 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-08-01T05:06:00.504Z,1406869560.504 [InternalSim](DEBUG):  InternalSim initializing...
2014-08-01T05:06:00.637Z,1406869560.637 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-08-01T05:06:00.665Z,1406869560.665 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-08-01T05:06:00.690Z,1406869560.690 [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-01T05:06:00.690Z,1406869560.690 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-08-01T05:06:00.756Z,1406869560.756 [Default:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-08-01T05:06:00.774Z,1406869560.774 [Default:CheckIn:A.SetSpeed](DEBUG): Construct.
2014-08-01T05:06:00.808Z,1406869560.808 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-08-01T05:06:00.811Z,1406869560.811 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-08-01T05:06:00.841Z,1406869560.841 [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-01T05:06:00.848Z,1406869560.848 [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-01T05:06:01.033Z,1406869561.033 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-08-01T05:06:01.179Z,1406869561.179 [Radio_Freewave](INFO): Powering up
2014-08-01T05:06:01.264Z,1406869561.264 [DVL_micro](INFO): Initializing
2014-08-01T05:06:01.295Z,1406869561.295 [NAL9602](INFO): Powering up NAL9602
2014-08-01T05:06:01.349Z,1406869561.349 [DAT](INFO): Powering up
2014-08-01T05:06:01.349Z,1406869561.349 [DAT](DEBUG): Initializing DAT.
2014-08-01T05:06:01.379Z,1406869561.379 [BPC1](DEBUG): Initializing BPC1.
2014-08-01T05:06:01.983Z,1406869561.983 [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-01T05:06:08.952Z,1406869568.952 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-08-01T05:06:08.960Z,1406869568.960 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-08-01T05:06:08.985Z,1406869568.985 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-08-01T05:06:08.993Z,1406869568.993 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-08-01T05:06:08.998Z,1406869568.998 [MassServo](DEBUG): Initializing EZServoServo.
2014-08-01T05:06:09.005Z,1406869569.005 [MassServo](DEBUG): Initializing MassServo.
2014-08-01T05:06:09.022Z,1406869569.022 [RudderServo](DEBUG): Initializing EZServoServo.
2014-08-01T05:06:09.029Z,1406869569.029 [RudderServo](DEBUG): Initializing RudderServo.
2014-08-01T05:06:09.042Z,1406869569.042 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-08-01T05:06:09.049Z,1406869569.049 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-08-01T05:06:09.995Z,1406869569.995 [SBIT](IMPORTANT): Beginning Startup BIT
2014-08-01T05:06:09.998Z,1406869569.998 [CBIT](IMPORTANT): Beginning GF scan
2014-08-01T05:06:12.090Z,1406869572.090 [NAL9602](INFO): NAL9602 initialized
2014-08-01T05:06:21.614Z,1406869581.614 [DAT](INFO): Powering down
2014-08-01T05:06:36.690Z,1406869596.690 [CBIT](IMPORTANT): No ground fault detected
2014-08-01T05:07:03.867Z,1406869623.867 [SBIT](IMPORTANT): SBIT PASSED
2014-08-01T05:07:04.275Z,1406869624.275 [MissionManager](IMPORTANT): Started mission Startup
2014-08-01T05:07:04.275Z,1406869624.275 [Startup] Running Loop=1
2014-08-01T05:07:04.275Z,1406869624.275 [Startup](INFO): Aggregate::initialize Startup
2014-08-01T05:07:04.275Z,1406869624.275 [Startup:A.GoToSurface] Running Loop=1
2014-08-01T05:07:04.276Z,1406869624.276 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-08-01T05:07:04.276Z,1406869624.276 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-08-01T05:07:04.277Z,1406869624.277 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-08-01T05:07:04.277Z,1406869624.277 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-08-01T05:07:04.283Z,1406869624.283 [Startup:StartupSatComms] Running Loop=1
2014-08-01T05:07:04.283Z,1406869624.283 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-08-01T05:07:04.283Z,1406869624.283 [Startup:StartupSatComms:A] Running Loop=1
2014-08-01T05:07:04.746Z,1406869624.746 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-08-01T05:08:04.482Z,1406869684.482 [Startup:StartupSatComms:A](INFO): Timed out from 2014-08-01T05:07:04.3Z
2014-08-01T05:08:04.482Z,1406869684.482 [Startup:StartupSatComms:A] Stopped
2014-08-01T05:08:04.482Z,1406869684.482 [Startup:StartupSatComms:B] Running Loop=1
2014-08-01T05:08:04.971Z,1406869684.971 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-08-01T05:09:01.109Z,1406869741.109 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:09:01.110Z,1406869741.110 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:09:01.153Z,1406869741.153 [MissionManager](INFO): DefineArg tracking_on_surface.MissionTimeout = 10.000000 min
2014-08-01T05:09:01.157Z,1406869741.157 [MissionManager](INFO): DefineArg tracking_on_surface.ContactLabel = 1.000000 count
2014-08-01T05:09:01.160Z,1406869741.160 [MissionManager](INFO): DefineArg tracking_on_surface.TrackingUpdatePeriod = 45.000000 s
2014-08-01T05:09:01.163Z,1406869741.163 [MissionManager](INFO): DefineArg tracking_on_surface.TrackingQueryMode = 0.000000 count
2014-08-01T05:09:01.166Z,1406869741.166 [MissionManager](INFO): DefineArg tracking_on_surface.Repeat = 13.000000 count
2014-08-01T05:09:01.171Z,1406869741.171 [MissionManager](INFO): DefineArg tracking_on_surface.MassDefault = 0.000000 n/a
2014-08-01T05:09:01.172Z,1406869741.172 [tracking_on_surface:A.Pitch](DEBUG): Construct.
2014-08-01T05:09:01.386Z,1406869741.386 [tracking_on_surface:TestDrive:C.Wait](DEBUG): Construct Wait.
2014-08-01T05:09:01.399Z,1406869741.399 [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-01T05:09:01.410Z,1406869741.410 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:09:04.701Z,1406869744.701 [Startup:StartupSatComms:B](INFO): Timed out from 2014-08-01T05:08:04.5Z
2014-08-01T05:09:04.701Z,1406869744.701 [Startup:StartupSatComms:B] Stopped
2014-08-01T05:09:04.701Z,1406869744.701 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2014-08-01T05:09:04.701Z,1406869744.701 [Startup:StartupSatComms] Stopped
2014-08-01T05:09:04.701Z,1406869744.701 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2014-08-01T05:09:04.702Z,1406869744.702 [Startup](INFO): Completed Startup
2014-08-01T05:09:04.702Z,1406869744.702 [Startup] Stopped
2014-08-01T05:09:04.702Z,1406869744.702 [Startup](INFO): Aggregate::uninitialize Startup
2014-08-01T05:09:04.702Z,1406869744.702 [Startup:A.GoToSurface] Stopped
2014-08-01T05:09:04.702Z,1406869744.702 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-08-01T05:09:05.120Z,1406869745.120 [MissionManager](IMPORTANT): Started mission tracking_on_surface
2014-08-01T05:09:05.120Z,1406869745.120 [tracking_on_surface] Running Loop=1
2014-08-01T05:09:05.121Z,1406869745.121 [tracking_on_surface](INFO): Aggregate::initialize tracking_on_surface
2014-08-01T05:09:05.121Z,1406869745.121 [tracking_on_surface:A.Pitch] Running Loop=1
2014-08-01T05:09:05.121Z,1406869745.121 [tracking_on_surface:A.Pitch](DEBUG): Initialize.
2014-08-01T05:09:05.121Z,1406869745.121 [tracking_on_surface:B.] Running Loop=1
2014-08-01T05:09:05.121Z,1406869745.121 [tracking_on_surface:B.](INFO): Initializing Tracking.
2014-08-01T05:09:05.122Z,1406869745.122 [tracking_on_surface:TestDrive] Running Loop=1
2014-08-01T05:09:05.122Z,1406869745.122 [tracking_on_surface:TestDrive](INFO): Aggregate::initialize tracking_on_surface:TestDrive
2014-08-01T05:09:05.122Z,1406869745.122 [tracking_on_surface:TestDrive:B] Running Loop=1
2014-08-01T05:09:05.123Z,1406869745.123 [tracking_on_surface:TestDrive:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-08-01T05:09:05.124Z,1406869745.124 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:05.124Z,1406869745.124 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:05.125Z,1406869745.125 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:05.133Z,1406869745.133 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:05.133Z,1406869745.133 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:05.133Z,1406869745.133 [tracking_on_surface:B.] Running Loop=1
2014-08-01T05:09:05.133Z,1406869745.133 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:05.156Z,1406869745.156 [tracking_on_surface:A.Pitch] Running Loop=1
2014-08-01T05:09:05.885Z,1406869745.885 [DAT](INFO): Powering up
2014-08-01T05:09:05.927Z,1406869745.927 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:05.927Z,1406869745.927 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:05.927Z,1406869745.927 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:05.927Z,1406869745.927 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:05.928Z,1406869745.928 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:06.320Z,1406869746.320 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:06.321Z,1406869746.321 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:06.321Z,1406869746.321 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:06.322Z,1406869746.322 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:06.322Z,1406869746.322 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:06.322Z,1406869746.322 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:06.770Z,1406869746.770 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:06.770Z,1406869746.770 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:06.770Z,1406869746.770 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:06.770Z,1406869746.770 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:06.770Z,1406869746.770 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:07.246Z,1406869747.246 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:07.246Z,1406869747.246 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:07.246Z,1406869747.246 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:07.248Z,1406869747.248 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:07.248Z,1406869747.248 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:07.248Z,1406869747.248 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:07.688Z,1406869747.688 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:07.688Z,1406869747.688 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:07.689Z,1406869747.689 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:07.689Z,1406869747.689 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:07.689Z,1406869747.689 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:08.630Z,1406869748.630 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:08.630Z,1406869748.630 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:08.630Z,1406869748.630 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:08.632Z,1406869748.632 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:08.632Z,1406869748.632 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:08.632Z,1406869748.632 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:10.096Z,1406869750.096 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:10.096Z,1406869750.096 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:10.096Z,1406869750.096 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:10.096Z,1406869750.096 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:10.096Z,1406869750.096 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:10.681Z,1406869750.681 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:10.681Z,1406869750.681 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:10.681Z,1406869750.681 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:10.687Z,1406869750.687 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:10.687Z,1406869750.687 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:10.687Z,1406869750.687 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:11.118Z,1406869751.118 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:11.118Z,1406869751.118 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:11.118Z,1406869751.118 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:11.118Z,1406869751.118 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:11.119Z,1406869751.119 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:11.552Z,1406869751.552 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:11.552Z,1406869751.552 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:11.553Z,1406869751.553 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:11.554Z,1406869751.554 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:11.554Z,1406869751.554 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:11.554Z,1406869751.554 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:11.975Z,1406869751.975 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:11.976Z,1406869751.976 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:11.992Z,1406869751.992 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:11.992Z,1406869751.992 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:11.992Z,1406869751.992 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:12.405Z,1406869752.405 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:12.405Z,1406869752.405 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:12.406Z,1406869752.406 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:12.407Z,1406869752.407 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:12.407Z,1406869752.407 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:12.407Z,1406869752.407 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:12.817Z,1406869752.817 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:12.817Z,1406869752.817 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:12.818Z,1406869752.818 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:12.818Z,1406869752.818 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:12.818Z,1406869752.818 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:13.251Z,1406869753.251 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:13.251Z,1406869753.251 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:13.252Z,1406869753.252 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:13.253Z,1406869753.253 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:13.253Z,1406869753.253 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:13.253Z,1406869753.253 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:13.739Z,1406869753.739 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:13.739Z,1406869753.739 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:13.739Z,1406869753.739 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:13.739Z,1406869753.739 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:13.740Z,1406869753.740 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:14.659Z,1406869754.659 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:14.659Z,1406869754.659 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:14.659Z,1406869754.659 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:14.660Z,1406869754.660 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:14.661Z,1406869754.661 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:14.661Z,1406869754.661 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:15.055Z,1406869755.055 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-08-01T05:09:15.055Z,1406869755.055 [DVL_micro] Data Fault, FailCount= 1
2014-08-01T05:09:15.055Z,1406869755.055 [DVL_micro](ERROR): Data Fault
2014-08-01T05:09:16.116Z,1406869756.116 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:16.116Z,1406869756.116 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:16.116Z,1406869756.116 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:16.117Z,1406869756.117 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:16.117Z,1406869756.117 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:16.125Z,1406869756.125 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-08-01T05:09:16.593Z,1406869756.593 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T05:09:16.661Z,1406869756.661 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:16.661Z,1406869756.661 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:16.661Z,1406869756.661 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:16.663Z,1406869756.663 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:16.663Z,1406869756.663 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:16.663Z,1406869756.663 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:17.094Z,1406869757.094 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-08-01T05:09:17.094Z,1406869757.094 [DVL_micro] Hardware Fault, FailCount= 1
2014-08-01T05:09:17.094Z,1406869757.094 [DVL_micro](ERROR): Hardware Fault
2014-08-01T05:09:17.164Z,1406869757.164 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:17.164Z,1406869757.164 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:17.164Z,1406869757.164 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:17.165Z,1406869757.165 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:17.165Z,1406869757.165 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:17.552Z,1406869757.552 [DVL_micro](INFO): Initializing
2014-08-01T05:09:17.591Z,1406869757.591 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:17.591Z,1406869757.591 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:17.591Z,1406869757.591 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:17.592Z,1406869757.592 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:17.592Z,1406869757.592 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:17.593Z,1406869757.593 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:17.602Z,1406869757.602 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-08-01T05:09:17.602Z,1406869757.602 [DVL_micro] No Fault, FailCount= 1
2014-08-01T05:09:18.028Z,1406869758.028 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:18.028Z,1406869758.028 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:18.028Z,1406869758.028 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:18.028Z,1406869758.028 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:18.029Z,1406869758.029 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:18.441Z,1406869758.441 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:18.441Z,1406869758.441 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:18.441Z,1406869758.441 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:18.443Z,1406869758.443 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:18.443Z,1406869758.443 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:18.443Z,1406869758.443 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:18.855Z,1406869758.855 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:18.855Z,1406869758.855 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:18.855Z,1406869758.855 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:18.855Z,1406869758.855 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:18.856Z,1406869758.856 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:19.303Z,1406869759.303 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:19.304Z,1406869759.304 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:19.304Z,1406869759.304 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:19.306Z,1406869759.306 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:19.306Z,1406869759.306 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:19.306Z,1406869759.306 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:20.241Z,1406869760.241 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:20.241Z,1406869760.241 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:20.241Z,1406869760.241 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:20.242Z,1406869760.242 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:20.242Z,1406869760.242 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:21.774Z,1406869761.774 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:21.774Z,1406869761.774 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:21.774Z,1406869761.774 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:21.792Z,1406869761.792 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:21.792Z,1406869761.792 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:21.792Z,1406869761.792 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:22.213Z,1406869762.213 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:22.213Z,1406869762.213 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:22.214Z,1406869762.214 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:22.214Z,1406869762.214 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:22.214Z,1406869762.214 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:22.655Z,1406869762.655 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:22.655Z,1406869762.655 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:22.655Z,1406869762.655 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:22.656Z,1406869762.656 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:22.656Z,1406869762.656 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:22.656Z,1406869762.656 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:23.072Z,1406869763.072 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:23.072Z,1406869763.072 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:23.072Z,1406869763.072 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:23.072Z,1406869763.072 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:23.073Z,1406869763.073 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:23.556Z,1406869763.556 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:23.556Z,1406869763.556 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:23.556Z,1406869763.556 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:23.557Z,1406869763.557 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:23.557Z,1406869763.557 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:23.558Z,1406869763.558 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:23.966Z,1406869763.966 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:23.966Z,1406869763.966 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:23.966Z,1406869763.966 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:23.966Z,1406869763.966 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:23.966Z,1406869763.966 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:24.391Z,1406869764.391 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:24.411Z,1406869764.411 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:24.411Z,1406869764.411 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:24.412Z,1406869764.412 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:24.413Z,1406869764.413 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:24.413Z,1406869764.413 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:24.836Z,1406869764.836 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:24.836Z,1406869764.836 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:24.836Z,1406869764.836 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:24.837Z,1406869764.837 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:24.837Z,1406869764.837 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:25.285Z,1406869765.285 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:25.285Z,1406869765.285 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:25.285Z,1406869765.285 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:25.286Z,1406869765.286 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:25.286Z,1406869765.286 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:25.286Z,1406869765.286 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:26.337Z,1406869766.337 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:26.337Z,1406869766.337 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:26.337Z,1406869766.337 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:26.337Z,1406869766.337 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:26.337Z,1406869766.337 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:28.185Z,1406869768.185 [DAT](FAULT): DAT uart error: serial timeout
2014-08-01T05:09:28.185Z,1406869768.185 [DAT](INFO): deviceResponse_: 
2014-08-01T05:09:28.185Z,1406869768.185 [DAT] Communications Fault, FailCount= 1
2014-08-01T05:09:28.185Z,1406869768.185 [DAT](ERROR): Communications Fault
2014-08-01T05:09:28.240Z,1406869768.240 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:28.240Z,1406869768.240 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:28.240Z,1406869768.240 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:28.242Z,1406869768.242 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:28.242Z,1406869768.242 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:28.242Z,1406869768.242 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:28.274Z,1406869768.274 [CBIT](ERROR): Communications Fault in component: DAT
2014-08-01T05:09:28.672Z,1406869768.672 [DAT](INFO): Powering down
2014-08-01T05:09:28.690Z,1406869768.690 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:28.690Z,1406869768.690 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:28.690Z,1406869768.690 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:28.691Z,1406869768.691 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:28.691Z,1406869768.691 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:29.128Z,1406869769.128 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:29.128Z,1406869769.128 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:29.128Z,1406869769.128 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:29.129Z,1406869769.129 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:29.129Z,1406869769.129 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:29.129Z,1406869769.129 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:29.571Z,1406869769.571 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:29.571Z,1406869769.571 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:29.571Z,1406869769.571 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:29.571Z,1406869769.571 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:29.572Z,1406869769.572 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:29.580Z,1406869769.580 [CBIT](INFO): Clearing failed state for component DAT
2014-08-01T05:09:29.580Z,1406869769.580 [DAT] No Fault, FailCount= 1
2014-08-01T05:09:30.027Z,1406869770.027 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:30.027Z,1406869770.027 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:30.027Z,1406869770.027 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:30.029Z,1406869770.029 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:30.029Z,1406869770.029 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:30.029Z,1406869770.029 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:30.480Z,1406869770.480 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:30.481Z,1406869770.481 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:30.481Z,1406869770.481 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:30.481Z,1406869770.481 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:30.481Z,1406869770.481 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:30.898Z,1406869770.898 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:30.898Z,1406869770.898 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:30.898Z,1406869770.898 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:30.899Z,1406869770.899 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:30.899Z,1406869770.899 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:30.900Z,1406869770.900 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:31.405Z,1406869771.405 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:31.405Z,1406869771.405 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:31.405Z,1406869771.405 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:31.406Z,1406869771.406 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:31.406Z,1406869771.406 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:32.329Z,1406869772.329 [DAT](INFO): Powering up
2014-08-01T05:09:32.329Z,1406869772.329 [DAT](DEBUG): Initializing DAT.
2014-08-01T05:09:32.366Z,1406869772.366 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:32.366Z,1406869772.366 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:32.366Z,1406869772.366 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:32.399Z,1406869772.399 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:32.399Z,1406869772.399 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:32.399Z,1406869772.399 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:33.801Z,1406869773.801 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:33.801Z,1406869773.801 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:33.802Z,1406869773.802 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:33.802Z,1406869773.802 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:33.802Z,1406869773.802 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:34.272Z,1406869774.272 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:34.272Z,1406869774.272 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:34.273Z,1406869774.273 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:34.274Z,1406869774.274 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:34.274Z,1406869774.274 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:34.274Z,1406869774.274 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:34.710Z,1406869774.710 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:34.710Z,1406869774.710 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:34.711Z,1406869774.711 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:34.711Z,1406869774.711 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:34.711Z,1406869774.711 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:35.158Z,1406869775.158 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:35.158Z,1406869775.158 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:35.159Z,1406869775.159 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:35.160Z,1406869775.160 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:35.160Z,1406869775.160 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:35.160Z,1406869775.160 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:35.628Z,1406869775.628 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:35.629Z,1406869775.629 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:35.629Z,1406869775.629 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:35.629Z,1406869775.629 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:35.629Z,1406869775.629 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:36.030Z,1406869776.030 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:36.030Z,1406869776.030 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:36.030Z,1406869776.030 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:36.031Z,1406869776.031 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:36.031Z,1406869776.031 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:36.032Z,1406869776.032 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:36.527Z,1406869776.527 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:36.527Z,1406869776.527 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:36.527Z,1406869776.527 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:36.527Z,1406869776.527 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:36.527Z,1406869776.527 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:36.976Z,1406869776.976 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:36.976Z,1406869776.976 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:36.976Z,1406869776.976 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:36.977Z,1406869776.977 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:36.977Z,1406869776.977 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:36.977Z,1406869776.977 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:37.421Z,1406869777.421 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:37.421Z,1406869777.421 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:37.421Z,1406869777.421 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:37.421Z,1406869777.421 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:37.421Z,1406869777.421 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:38.335Z,1406869778.335 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:38.335Z,1406869778.335 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:38.335Z,1406869778.335 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:38.336Z,1406869778.336 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:38.336Z,1406869778.336 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:38.337Z,1406869778.337 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:39.832Z,1406869779.832 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:39.832Z,1406869779.832 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:39.832Z,1406869779.832 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:39.832Z,1406869779.832 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:39.832Z,1406869779.832 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:40.328Z,1406869780.328 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:40.328Z,1406869780.328 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:40.329Z,1406869780.329 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:40.330Z,1406869780.330 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:40.330Z,1406869780.330 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:40.330Z,1406869780.330 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:40.771Z,1406869780.771 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:40.771Z,1406869780.771 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:40.771Z,1406869780.771 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:40.771Z,1406869780.771 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:40.771Z,1406869780.771 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:41.218Z,1406869781.218 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:41.218Z,1406869781.218 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:41.219Z,1406869781.219 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:41.220Z,1406869781.220 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:41.220Z,1406869781.220 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:41.220Z,1406869781.220 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:41.689Z,1406869781.689 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:41.689Z,1406869781.689 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:41.689Z,1406869781.689 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:41.689Z,1406869781.689 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:41.690Z,1406869781.690 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:42.099Z,1406869782.099 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:42.099Z,1406869782.099 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:42.099Z,1406869782.099 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:42.101Z,1406869782.101 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:42.101Z,1406869782.101 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:42.101Z,1406869782.101 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:42.536Z,1406869782.536 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:42.536Z,1406869782.536 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:42.537Z,1406869782.537 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:42.537Z,1406869782.537 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:42.537Z,1406869782.537 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:42.958Z,1406869782.958 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:42.959Z,1406869782.959 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:42.959Z,1406869782.959 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:42.980Z,1406869782.980 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:42.980Z,1406869782.980 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:42.980Z,1406869782.980 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:43.440Z,1406869783.440 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:43.440Z,1406869783.440 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:43.440Z,1406869783.440 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:43.440Z,1406869783.440 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:43.440Z,1406869783.440 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:44.357Z,1406869784.357 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:44.357Z,1406869784.357 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:44.357Z,1406869784.357 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:44.358Z,1406869784.358 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:44.358Z,1406869784.358 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:44.358Z,1406869784.358 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:45.791Z,1406869785.791 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:45.791Z,1406869785.791 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:45.792Z,1406869785.792 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:45.792Z,1406869785.792 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:45.792Z,1406869785.792 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:46.247Z,1406869786.247 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:46.247Z,1406869786.247 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:46.247Z,1406869786.247 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:46.249Z,1406869786.249 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:46.249Z,1406869786.249 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:46.253Z,1406869786.253 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:46.799Z,1406869786.799 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:46.799Z,1406869786.799 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:46.799Z,1406869786.799 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:46.799Z,1406869786.799 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:46.800Z,1406869786.800 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:47.230Z,1406869787.230 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:47.230Z,1406869787.230 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:47.230Z,1406869787.230 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:47.231Z,1406869787.231 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:47.231Z,1406869787.231 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:47.231Z,1406869787.231 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:47.670Z,1406869787.670 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:47.671Z,1406869787.671 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:47.671Z,1406869787.671 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:47.671Z,1406869787.671 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:47.671Z,1406869787.671 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:48.087Z,1406869788.087 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:48.087Z,1406869788.087 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:48.088Z,1406869788.088 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:48.089Z,1406869788.089 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:48.089Z,1406869788.089 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:48.089Z,1406869788.089 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:48.518Z,1406869788.518 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:48.518Z,1406869788.518 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:48.518Z,1406869788.518 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:48.518Z,1406869788.518 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:48.519Z,1406869788.519 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:48.939Z,1406869788.939 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:48.939Z,1406869788.939 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:48.940Z,1406869788.940 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:48.941Z,1406869788.941 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:48.941Z,1406869788.941 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:48.941Z,1406869788.941 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:49.415Z,1406869789.415 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:49.415Z,1406869789.415 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:49.415Z,1406869789.415 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:49.415Z,1406869789.415 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:49.415Z,1406869789.415 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:50.354Z,1406869790.354 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:50.354Z,1406869790.354 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:50.354Z,1406869790.354 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:50.355Z,1406869790.355 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:50.355Z,1406869790.355 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:50.356Z,1406869790.356 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:51.946Z,1406869791.946 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:51.946Z,1406869791.946 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:51.946Z,1406869791.946 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:51.947Z,1406869791.947 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:51.947Z,1406869791.947 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:52.740Z,1406869792.740 [DAT](FAULT): DAT uart error: serial timeout
2014-08-01T05:09:52.740Z,1406869792.740 [DAT](INFO): deviceResponse_: 
2014-08-01T05:09:52.740Z,1406869792.740 [DAT] Communications Fault, FailCount= 2
2014-08-01T05:09:52.740Z,1406869792.740 [DAT](ERROR): Communications Fault
2014-08-01T05:09:52.762Z,1406869792.762 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:52.763Z,1406869792.763 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:52.763Z,1406869792.763 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:52.786Z,1406869792.786 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:52.786Z,1406869792.786 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:52.786Z,1406869792.786 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:52.803Z,1406869792.803 [CBIT](ERROR): Communications Fault in component: DAT
2014-08-01T05:09:53.218Z,1406869793.218 [DAT](INFO): Powering down
2014-08-01T05:09:53.260Z,1406869793.260 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:53.261Z,1406869793.261 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:53.261Z,1406869793.261 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:53.261Z,1406869793.261 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:53.261Z,1406869793.261 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:53.672Z,1406869793.672 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:53.672Z,1406869793.672 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:53.672Z,1406869793.672 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:53.673Z,1406869793.673 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:53.673Z,1406869793.673 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:53.673Z,1406869793.673 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:54.114Z,1406869794.114 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:54.114Z,1406869794.114 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:54.114Z,1406869794.114 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:54.114Z,1406869794.114 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:54.114Z,1406869794.114 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:54.123Z,1406869794.123 [CBIT](INFO): Clearing failed state for component DAT
2014-08-01T05:09:54.123Z,1406869794.123 [DAT] No Fault, FailCount= 2
2014-08-01T05:09:54.535Z,1406869794.535 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:54.535Z,1406869794.535 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:54.535Z,1406869794.535 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:54.536Z,1406869794.536 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:54.536Z,1406869794.536 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:54.536Z,1406869794.536 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:54.947Z,1406869794.947 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:54.947Z,1406869794.947 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:54.947Z,1406869794.947 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:54.947Z,1406869794.947 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:54.948Z,1406869794.948 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:55.382Z,1406869795.382 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:55.383Z,1406869795.383 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:55.383Z,1406869795.383 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:55.384Z,1406869795.384 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:55.384Z,1406869795.384 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:55.384Z,1406869795.384 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:56.307Z,1406869796.307 [DAT](INFO): Powering up
2014-08-01T05:09:56.307Z,1406869796.307 [DAT](DEBUG): Initializing DAT.
2014-08-01T05:09:56.338Z,1406869796.338 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:56.338Z,1406869796.338 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:56.339Z,1406869796.339 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:56.339Z,1406869796.339 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:56.339Z,1406869796.339 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:57.883Z,1406869797.883 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:57.884Z,1406869797.884 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:57.884Z,1406869797.884 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:57.885Z,1406869797.885 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:57.885Z,1406869797.885 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:57.885Z,1406869797.885 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:58.305Z,1406869798.305 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:58.305Z,1406869798.305 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:58.305Z,1406869798.305 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:58.305Z,1406869798.305 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:58.305Z,1406869798.305 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:58.727Z,1406869798.727 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:58.727Z,1406869798.727 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:58.728Z,1406869798.728 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:58.745Z,1406869798.745 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:58.745Z,1406869798.745 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:58.745Z,1406869798.745 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:59.158Z,1406869799.158 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:09:59.158Z,1406869799.158 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:09:59.158Z,1406869799.158 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:09:59.159Z,1406869799.159 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:59.159Z,1406869799.159 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:09:59.629Z,1406869799.629 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:09:59.629Z,1406869799.629 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:09:59.629Z,1406869799.629 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:09:59.630Z,1406869799.630 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:09:59.630Z,1406869799.630 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:09:59.631Z,1406869799.631 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:00.076Z,1406869800.076 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:10:00.076Z,1406869800.076 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:10:00.076Z,1406869800.076 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:10:00.076Z,1406869800.076 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:00.077Z,1406869800.077 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:00.511Z,1406869800.511 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:10:00.511Z,1406869800.511 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:00.512Z,1406869800.512 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:10:00.513Z,1406869800.513 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:10:00.513Z,1406869800.513 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:10:00.513Z,1406869800.513 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:00.918Z,1406869800.918 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:10:00.918Z,1406869800.918 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:10:00.918Z,1406869800.918 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:10:00.918Z,1406869800.918 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:00.918Z,1406869800.918 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:01.363Z,1406869801.363 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:10:01.364Z,1406869801.364 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:01.364Z,1406869801.364 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:10:01.365Z,1406869801.365 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:10:01.365Z,1406869801.365 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:10:01.365Z,1406869801.365 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:02.319Z,1406869802.319 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:10:02.319Z,1406869802.319 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:10:02.319Z,1406869802.319 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:10:02.319Z,1406869802.319 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:02.319Z,1406869802.319 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:05.394Z,1406869805.394 [tracking_on_surface:TestDrive:B](INFO): Timed out from 2014-08-01T05:09:05.1Z
2014-08-01T05:10:05.394Z,1406869805.394 [tracking_on_surface:TestDrive:B] Stopped
2014-08-01T05:10:05.394Z,1406869805.394 [tracking_on_surface:TestDrive:C.Wait] Running Loop=1
2014-08-01T05:10:05.394Z,1406869805.394 [tracking_on_surface:TestDrive:C.Wait](DEBUG): Initialize Wait Component.
2014-08-01T05:10:05.394Z,1406869805.394 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:10:05.394Z,1406869805.394 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:05.394Z,1406869805.394 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:10:05.420Z,1406869805.420 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:10:05.420Z,1406869805.420 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:10:05.420Z,1406869805.420 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:06.197Z,1406869806.197 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:10:06.197Z,1406869806.197 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:10:06.197Z,1406869806.197 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:10:06.197Z,1406869806.197 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:06.197Z,1406869806.197 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:06.726Z,1406869806.726 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:10:06.726Z,1406869806.726 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:06.726Z,1406869806.726 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:10:06.728Z,1406869806.728 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:10:06.728Z,1406869806.728 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:10:06.728Z,1406869806.728 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:07.334Z,1406869807.334 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:10:07.334Z,1406869807.334 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:10:07.334Z,1406869807.334 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:10:07.334Z,1406869807.334 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:07.335Z,1406869807.335 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:07.833Z,1406869807.833 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:10:07.833Z,1406869807.833 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:07.833Z,1406869807.833 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:10:07.836Z,1406869807.836 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:10:07.836Z,1406869807.836 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:10:07.836Z,1406869807.836 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:08.326Z,1406869808.326 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:10:08.327Z,1406869808.327 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:10:08.327Z,1406869808.327 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:10:08.327Z,1406869808.327 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:08.327Z,1406869808.327 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:08.835Z,1406869808.835 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:10:08.835Z,1406869808.835 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:08.835Z,1406869808.835 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:10:08.845Z,1406869808.845 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:10:08.846Z,1406869808.846 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:10:08.846Z,1406869808.846 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:09.326Z,1406869809.326 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:10:09.326Z,1406869809.326 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:10:09.326Z,1406869809.326 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:10:09.326Z,1406869809.326 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:09.327Z,1406869809.327 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:09.865Z,1406869809.865 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:10:09.865Z,1406869809.865 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:09.865Z,1406869809.865 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:10:09.871Z,1406869809.871 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:10:09.871Z,1406869809.871 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:10:09.871Z,1406869809.871 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:10.424Z,1406869810.424 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:10:10.425Z,1406869810.425 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:10:10.425Z,1406869810.425 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:10:10.425Z,1406869810.425 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:10.425Z,1406869810.425 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:10.942Z,1406869810.942 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:10:10.942Z,1406869810.942 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:10.942Z,1406869810.942 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:10:10.970Z,1406869810.970 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:10:10.970Z,1406869810.970 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:10:10.971Z,1406869810.971 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:11.475Z,1406869811.475 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:10:11.475Z,1406869811.475 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:10:11.475Z,1406869811.475 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:10:11.475Z,1406869811.475 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:11.475Z,1406869811.475 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:12.067Z,1406869812.067 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:10:12.068Z,1406869812.068 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:12.068Z,1406869812.068 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:10:12.080Z,1406869812.080 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:10:12.080Z,1406869812.080 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:10:12.081Z,1406869812.081 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:12.727Z,1406869812.727 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:10:12.727Z,1406869812.727 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:10:12.727Z,1406869812.727 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:10:12.727Z,1406869812.727 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:12.728Z,1406869812.728 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:13.392Z,1406869813.392 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:10:13.393Z,1406869813.393 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:13.393Z,1406869813.393 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:10:13.394Z,1406869813.394 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:10:13.394Z,1406869813.394 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:10:13.394Z,1406869813.394 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:13.907Z,1406869813.907 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:10:13.907Z,1406869813.907 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:10:13.907Z,1406869813.907 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:10:13.908Z,1406869813.908 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:13.911Z,1406869813.911 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:14.407Z,1406869814.407 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:10:14.407Z,1406869814.407 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:14.407Z,1406869814.407 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:10:14.413Z,1406869814.413 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:10:14.413Z,1406869814.413 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:10:14.413Z,1406869814.413 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:14.911Z,1406869814.911 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:10:14.911Z,1406869814.911 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:10:14.911Z,1406869814.911 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:10:14.911Z,1406869814.911 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:14.912Z,1406869814.912 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:15.617Z,1406869815.617 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:10:15.618Z,1406869815.618 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:15.618Z,1406869815.618 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:10:15.624Z,1406869815.624 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:10:15.624Z,1406869815.624 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:10:15.624Z,1406869815.624 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:16.440Z,1406869816.440 [DAT](FAULT): DAT uart error: serial timeout
2014-08-01T05:10:16.440Z,1406869816.440 [DAT](INFO): deviceResponse_: 
2014-08-01T05:10:16.440Z,1406869816.440 [DAT] Communications Fault, FailCount= 3
2014-08-01T05:10:16.440Z,1406869816.440 [DAT](ERROR): Communications Fault
2014-08-01T05:10:16.511Z,1406869816.511 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:10:16.511Z,1406869816.511 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:10:16.511Z,1406869816.511 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:10:16.511Z,1406869816.511 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:16.511Z,1406869816.511 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:16.533Z,1406869816.533 [CBIT](ERROR): Communications Fault in component: DAT
2014-08-01T05:10:16.533Z,1406869816.533 [CBIT](CRITICAL): Communications Fault in component: DAT
2014-08-01T05:10:16.979Z,1406869816.979 [DAT](INFO): Powering down
2014-08-01T05:10:17.002Z,1406869817.002 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:10:17.002Z,1406869817.002 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:17.002Z,1406869817.002 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:10:17.003Z,1406869817.003 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:10:17.003Z,1406869817.003 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:10:17.004Z,1406869817.004 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:17.056Z,1406869817.056 [CommandLine](FAULT): Scheduling is paused
2014-08-01T05:10:17.697Z,1406869817.697 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:10:17.697Z,1406869817.697 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:10:17.703Z,1406869817.703 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:10:17.703Z,1406869817.703 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:10:17.703Z,1406869817.703 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:10:17.704Z,1406869817.704 [tracking_on_surface] Stopped
2014-08-01T05:10:17.704Z,1406869817.704 [tracking_on_surface](INFO): Aggregate::uninitialize tracking_on_surface
2014-08-01T05:10:17.704Z,1406869817.704 [tracking_on_surface:A.Pitch] Stopped
2014-08-01T05:10:17.704Z,1406869817.704 [tracking_on_surface:B.] Stopped
2014-08-01T05:10:17.704Z,1406869817.704 [tracking_on_surface:B.](DEBUG): Uninitializing Tracking.
2014-08-01T05:10:17.704Z,1406869817.704 [tracking_on_surface:TestDrive] Stopped
2014-08-01T05:10:17.704Z,1406869817.704 [tracking_on_surface:TestDrive](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive
2014-08-01T05:10:17.704Z,1406869817.704 [tracking_on_surface:TestDrive:C.Wait] Stopped
2014-08-01T05:10:17.704Z,1406869817.704 [tracking_on_surface:TestDrive:C.Wait](DEBUG): Uninitialize Wait Component.
2014-08-01T05:10:18.210Z,1406869818.210 [MissionManager](IMPORTANT): Started mission Default
2014-08-01T05:10:18.210Z,1406869818.210 [Default] Running Loop=1
2014-08-01T05:10:18.210Z,1406869818.210 [Default](INFO): Aggregate::initialize Default
2014-08-01T05:10:18.210Z,1406869818.210 [Default:A.GoToSurface] Running Loop=1
2014-08-01T05:10:18.210Z,1406869818.210 [Default:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-08-01T05:10:18.210Z,1406869818.210 [Default:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-08-01T05:10:18.213Z,1406869818.213 [Default:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-08-01T05:10:18.214Z,1406869818.214 [Default:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-08-01T05:10:18.215Z,1406869818.215 [Default:CheckIn] Running Loop=1
2014-08-01T05:10:18.215Z,1406869818.215 [Default:CheckIn](INFO): Aggregate::initialize Default:CheckIn
2014-08-01T05:10:18.215Z,1406869818.215 [Default:CheckIn:A.SetSpeed] Running Loop=1
2014-08-01T05:10:18.215Z,1406869818.215 [Default:CheckIn:A.SetSpeed](DEBUG): Initialize.
2014-08-01T05:10:18.216Z,1406869818.216 [Default:CheckIn:Read_GPS] Running Loop=1
2014-08-01T05:10:18.216Z,1406869818.216 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-08-01T05:10:18.221Z,1406869818.221 [Default:CheckIn:A.SetSpeed] Running Loop=1
2014-08-01T05:10:18.268Z,1406869818.268 [Default:WaitAtTheSurface] Running Loop=1
2014-08-01T05:10:18.269Z,1406869818.269 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface
2014-08-01T05:10:18.269Z,1406869818.269 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2014-08-01T05:10:18.269Z,1406869818.269 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Initialize.
2014-08-01T05:10:18.778Z,1406869818.778 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2014-08-01T05:10:35.136Z,1406869835.136 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items. Got 41 of 46
2014-08-01T05:10:35.136Z,1406869835.136 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 101 111 146 75 3 3 4 3 -60.1 48.0 116.7 2 70.3 -31.3 116.7 2 -60 48 116 2 70 -31 116 2 5.36 -0.29 194.6 -3.0 24.9 0.01489 90
2014-08-01T05:12:22.938Z,1406869942.938 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-08-01T05:12:22.938Z,1406869942.938 [DVL_micro] Data Fault, FailCount= 1
2014-08-01T05:12:22.938Z,1406869942.938 [DVL_micro](ERROR): Data Fault
2014-08-01T05:12:23.022Z,1406869943.022 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-08-01T05:12:23.391Z,1406869943.391 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T05:12:23.807Z,1406869943.807 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-08-01T05:12:23.807Z,1406869943.807 [DVL_micro] Hardware Fault, FailCount= 1
2014-08-01T05:12:23.807Z,1406869943.807 [DVL_micro](ERROR): Hardware Fault
2014-08-01T05:12:24.234Z,1406869944.234 [DVL_micro](INFO): Initializing
2014-08-01T05:12:24.290Z,1406869944.290 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-08-01T05:12:24.290Z,1406869944.290 [DVL_micro] No Fault, FailCount= 1
2014-08-01T05:12:40.837Z,1406869960.837 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:12:43.532Z,1406869963.532 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:12:45.697Z,1406869965.697 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:12:48.357Z,1406869968.357 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:12:50.547Z,1406869970.547 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:12:52.795Z,1406869972.795 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:12:55.411Z,1406869975.411 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:12:57.624Z,1406869977.624 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:13:00.226Z,1406869980.226 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:13:02.490Z,1406869982.490 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:13:05.073Z,1406869985.073 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:13:07.241Z,1406869987.241 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:13:09.869Z,1406869989.869 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:13:12.352Z,1406869992.352 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:13:14.693Z,1406869994.693 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:13:16.853Z,1406869996.853 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:13:19.498Z,1406869999.498 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:13:21.752Z,1406870001.752 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:13:24.027Z,1406870004.027 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:13:26.234Z,1406870006.234 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:13:28.975Z,1406870008.975 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:13:31.390Z,1406870011.390 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:13:33.654Z,1406870013.654 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:13:36.294Z,1406870016.294 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:13:36.530Z,1406870016.530 [CommandLine](IMPORTANT): got command restart application
2014-08-01T05:13:37.543Z,1406870017.543 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:13:37.543Z,1406870017.543 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:37.684Z,1406870017.684 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2014-08-01T05:13:37.684Z,1406870017.684 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:37.685Z,1406870017.685 [CommandLine](INFO): Join timeout helper Thread ID is 1475
2014-08-01T05:13:37.685Z,1406870017.685 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2014-08-01T05:13:37.685Z,1406870017.685 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:37.686Z,1406870017.686 [NavChartDb](INFO): Join timeout helper Thread ID is 1476
2014-08-01T05:13:37.704Z,1406870017.704 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:13:37.705Z,1406870017.705 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:37.731Z,1406870017.731 [ComponentRegistry](INFO): Shutting down Radio_Freewave ThreadHandler
2014-08-01T05:13:37.731Z,1406870017.731 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:37.732Z,1406870017.732 [Radio_Freewave](INFO): Join timeout helper Thread ID is 1477
2014-08-01T05:13:38.032Z,1406870018.032 [Radio_Freewave ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:13:38.251Z,1406870018.251 [Radio_Freewave](INFO): Powering down
2014-08-01T05:13:38.550Z,1406870018.550 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:13:38.654Z,1406870018.654 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:38.661Z,1406870018.661 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2014-08-01T05:13:38.662Z,1406870018.662 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:38.662Z,1406870018.662 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1479
2014-08-01T05:13:38.894Z,1406870018.894 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:13:38.894Z,1406870018.894 [WetLabsBB2FL](INFO): Powering down
2014-08-01T05:13:38.895Z,1406870018.895 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:38.902Z,1406870018.902 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2014-08-01T05:13:38.902Z,1406870018.902 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:38.902Z,1406870018.902 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1480
2014-08-01T05:13:39.042Z,1406870019.042 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:13:39.043Z,1406870019.043 [CTD_NeilBrown](INFO): Powering down
2014-08-01T05:13:39.043Z,1406870019.043 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:39.045Z,1406870019.045 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2014-08-01T05:13:39.045Z,1406870019.045 [logger ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:39.046Z,1406870019.046 [logger](INFO): Join timeout helper Thread ID is 1481
2014-08-01T05:13:39.074Z,1406870019.074 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:13:39.075Z,1406870019.075 [logger ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:39.087Z,1406870019.087 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2014-08-01T05:13:39.087Z,1406870019.087 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:39.087Z,1406870019.087 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2014-08-01T05:13:39.087Z,1406870019.087 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:39.088Z,1406870019.088 [controlThread](INFO): Join timeout helper Thread ID is 1482
2014-08-01T05:13:39.502Z,1406870019.502 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:13:39.503Z,1406870019.503 [controlThread](DEBUG): Uninitializing ControlThread
2014-08-01T05:13:39.503Z,1406870019.503 [AHRS_sp3003D](INFO): Powering down
2014-08-01T05:13:39.505Z,1406870019.505 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T05:13:39.506Z,1406870019.506 [NAL9602](INFO): Powering down
2014-08-01T05:13:39.507Z,1406870019.507 [DAT](INFO): Powering down
2014-08-01T05:13:39.508Z,1406870019.508 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-08-01T05:13:39.511Z,1406870019.511 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2014-08-01T05:13:39.512Z,1406870019.512 [Default] Stopped
2014-08-01T05:13:39.512Z,1406870019.512 [Default](INFO): Aggregate::uninitialize Default
2014-08-01T05:13:39.512Z,1406870019.512 [Default:A.GoToSurface] Stopped
2014-08-01T05:13:39.512Z,1406870019.512 [Default:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-08-01T05:13:39.512Z,1406870019.512 [Default:CheckIn] Stopped
2014-08-01T05:13:39.513Z,1406870019.513 [Default:CheckIn](INFO): Aggregate::uninitialize Default:CheckIn
2014-08-01T05:13:39.513Z,1406870019.513 [Default:CheckIn:A.SetSpeed] Stopped
2014-08-01T05:13:39.513Z,1406870019.513 [Default:CheckIn:A.SetSpeed](DEBUG): Uninitialize.
2014-08-01T05:13:39.513Z,1406870019.513 [Default:CheckIn:Read_GPS] Stopped
2014-08-01T05:13:39.513Z,1406870019.513 [Default:WaitAtTheSurface] Stopped
2014-08-01T05:13:39.513Z,1406870019.513 [Default:WaitAtTheSurface](INFO): Aggregate::uninitialize Default:WaitAtTheSurface
2014-08-01T05:13:39.513Z,1406870019.513 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Stopped
2014-08-01T05:13:39.513Z,1406870019.513 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Uninitialize.
2014-08-01T05:13:39.516Z,1406870019.516 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2014-08-01T05:13:39.516Z,1406870019.516 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2014-08-01T05:13:39.517Z,1406870019.517 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2014-08-01T05:13:39.517Z,1406870019.517 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2014-08-01T05:13:39.517Z,1406870019.517 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-08-01T05:13:39.518Z,1406870019.518 [BuoyancyServo](INFO): Powering down
2014-08-01T05:13:39.531Z,1406870019.531 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2014-08-01T05:13:39.531Z,1406870019.531 [ElevatorServo](INFO): Powering down
2014-08-01T05:13:39.532Z,1406870019.532 [MassServo](DEBUG): Uninitialize Mass Servo.
2014-08-01T05:13:39.532Z,1406870019.532 [MassServo](INFO): Powering down
2014-08-01T05:13:39.533Z,1406870019.533 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2014-08-01T05:13:39.533Z,1406870019.533 [RudderServo](INFO): Powering down
2014-08-01T05:13:39.534Z,1406870019.534 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2014-08-01T05:13:39.534Z,1406870019.534 [ThrusterServo](INFO): Powering down
2014-08-01T05:13:39.535Z,1406870019.535 [SBIT](DEBUG): Uninitialize SBIT Component.
2014-08-01T05:13:39.535Z,1406870019.535 [IBIT](DEBUG): Uninitialize IBIT Component.
2014-08-01T05:13:39.535Z,1406870019.535 [CBIT](DEBUG): Uninitialize CBIT Component.
2014-08-01T05:13:39.580Z,1406870019.580 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:39.666Z,1406870019.666 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:39.670Z,1406870019.670 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:39.684Z,1406870019.684 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:39.737Z,1406870019.737 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:13:39.773Z,1406870019.773 [logger ThreadHandler](INFO): Thread cancelled.