2014-08-01T05:13:40.643Z,1406870020.643 [Supervisor](DEBUG): Initializing supervisor.
2014-08-01T05:13:40.646Z,1406870020.646 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-08-01T05:13:40.647Z,1406870020.647 [SyncHandler](INFO): Protected caller Thread ID is 1484
2014-08-01T05:13:40.647Z,1406870020.647 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-08-01T05:13:40.648Z,1406870020.648 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2014-08-01T05:13:40.649Z,1406870020.649 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1485
2014-08-01T05:13:40.651Z,1406870020.651 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-08-01T05:13:40.663Z,1406870020.663 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-08-01T05:13:40.664Z,1406870020.664 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2014-08-01T05:13:40.664Z,1406870020.664 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1486
2014-08-01T05:13:40.665Z,1406870020.665 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-08-01T05:13:40.666Z,1406870020.666 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2014-08-01T05:13:40.666Z,1406870020.666 [logger ThreadHandler](INFO): Protected caller Thread ID is 1487
2014-08-01T05:13:40.669Z,1406870020.669 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-08-01T05:13:40.670Z,1406870020.670 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-08-01T05:13:40.671Z,1406870020.671 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-08-01T05:13:41.163Z,1406870021.163 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-08-01T05:13:41.164Z,1406870021.164 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-08-01T05:13:41.319Z,1406870021.319 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-08-01T05:13:41.320Z,1406870021.320 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-08-01T05:13:41.428Z,1406870021.428 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-08-01T05:13:41.428Z,1406870021.428 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-08-01T05:13:41.552Z,1406870021.552 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-08-01T05:13:41.552Z,1406870021.552 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-08-01T05:13:41.639Z,1406870021.639 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-08-01T05:13:41.774Z,1406870021.774 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-08-01T05:13:41.775Z,1406870021.775 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-08-01T05:13:41.861Z,1406870021.861 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-08-01T05:13:41.861Z,1406870021.861 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-08-01T05:13:42.059Z,1406870022.059 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-08-01T05:13:42.059Z,1406870022.059 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-08-01T05:13:42.349Z,1406870022.349 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-08-01T05:13:42.349Z,1406870022.349 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-08-01T05:13:42.653Z,1406870022.653 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-08-01T05:13:42.654Z,1406870022.654 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-08-01T05:13:43.149Z,1406870023.149 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-08-01T05:13:43.149Z,1406870023.149 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-08-01T05:13:43.339Z,1406870023.339 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-08-01T05:13:43.340Z,1406870023.340 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-08-01T05:13:43.443Z,1406870023.443 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-08-01T05:13:43.444Z,1406870023.444 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-08-01T05:13:43.839Z,1406870023.839 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-08-01T05:13:43.839Z,1406870023.839 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-08-01T05:13:43.949Z,1406870023.949 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-08-01T05:13:43.951Z,1406870023.951 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-08-01T05:13:43.952Z,1406870023.952 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-08-01T05:13:44.056Z,1406870024.056 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-08-01T05:13:44.174Z,1406870024.174 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-08-01T05:13:44.284Z,1406870024.284 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-08-01T05:13:44.381Z,1406870024.381 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-08-01T05:13:44.509Z,1406870024.509 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-08-01T05:13:44.653Z,1406870024.653 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-08-01T05:13:44.762Z,1406870024.762 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-08-01T05:13:48.759Z,1406870028.759 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-08-01T05:13:48.852Z,1406870028.852 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-08-01T05:13:48.949Z,1406870028.949 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-08-01T05:13:49.059Z,1406870029.059 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-08-01T05:13:49.147Z,1406870029.147 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2014-08-01T05:13:49.149Z,1406870029.149 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-08-01T05:13:49.198Z,1406870029.198 [VerticalControl](DEBUG): Construct VerticalControl.
2014-08-01T05:13:49.316Z,1406870029.316 [VerticalControl] Loaded
2014-08-01T05:13:49.316Z,1406870029.316 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-08-01T05:13:49.317Z,1406870029.317 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-08-01T05:13:49.387Z,1406870029.387 [HorizontalControl] Loaded
2014-08-01T05:13:49.387Z,1406870029.387 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-08-01T05:13:49.388Z,1406870029.388 [SpeedControl](DEBUG): Construct SpeedControl.
2014-08-01T05:13:49.394Z,1406870029.394 [SpeedControl] Loaded
2014-08-01T05:13:49.394Z,1406870029.394 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-08-01T05:13:49.395Z,1406870029.395 [LoopControl](DEBUG): Construct LoopControl.
2014-08-01T05:13:49.395Z,1406870029.395 [LoopControl] Loaded
2014-08-01T05:13:49.395Z,1406870029.395 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-08-01T05:13:49.396Z,1406870029.396 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-08-01T05:13:49.396Z,1406870029.396 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-08-01T05:13:49.492Z,1406870029.492 [SBIT](DEBUG): Construct Startup Built In Test.
2014-08-01T05:13:49.504Z,1406870029.504 [SBIT] Loaded
2014-08-01T05:13:49.504Z,1406870029.504 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-08-01T05:13:49.505Z,1406870029.505 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-08-01T05:13:49.533Z,1406870029.533 [IBIT] Loaded
2014-08-01T05:13:49.534Z,1406870029.534 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-08-01T05:13:49.536Z,1406870029.536 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-08-01T05:13:49.653Z,1406870029.653 [CBIT] Loaded
2014-08-01T05:13:49.653Z,1406870029.653 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-08-01T05:13:49.654Z,1406870029.654 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-08-01T05:13:49.654Z,1406870029.654 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-08-01T05:13:49.673Z,1406870029.673 [DepthRateCalculator] Loaded
2014-08-01T05:13:49.673Z,1406870029.673 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-08-01T05:13:49.679Z,1406870029.679 [PitchRateCalculator] Loaded
2014-08-01T05:13:49.679Z,1406870029.679 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-08-01T05:13:49.690Z,1406870029.690 [SpeedCalculator] Loaded
2014-08-01T05:13:49.690Z,1406870029.690 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-08-01T05:13:49.706Z,1406870029.706 [TempGradientCalculator] Loaded
2014-08-01T05:13:49.707Z,1406870029.707 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-08-01T05:13:49.712Z,1406870029.712 [YawRateCalculator] Loaded
2014-08-01T05:13:49.712Z,1406870029.712 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-08-01T05:13:49.713Z,1406870029.713 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-08-01T05:13:49.713Z,1406870029.713 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-08-01T05:13:54.813Z,1406870034.813 [HFRadarModelCalc] Loaded
2014-08-01T05:13:54.813Z,1406870034.813 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2014-08-01T05:13:58.952Z,1406870038.952 [HFRadarCompactModelForecaster] Loaded
2014-08-01T05:13:58.952Z,1406870038.952 [ComponentRegistry](DEBUG): SyncComponent "HFRadarCompactModelForecaster" handled in the control thread.
2014-08-01T05:14:00.081Z,1406870040.081 [HFRCMSpaceInterpolator] Loaded
2014-08-01T05:14:00.082Z,1406870040.082 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSpaceInterpolator" handled in the control thread.
2014-08-01T05:14:00.084Z,1406870040.084 [HFRCMTimeInterpolator] Loaded
2014-08-01T05:14:00.084Z,1406870040.084 [ComponentRegistry](DEBUG): SyncComponent "HFRCMTimeInterpolator" handled in the control thread.
2014-08-01T05:14:01.180Z,1406870041.180 [HFRCMReconstructedInterpolator] Loaded
2014-08-01T05:14:01.180Z,1406870041.180 [ComponentRegistry](DEBUG): SyncComponent "HFRCMReconstructedInterpolator" handled in the control thread.
2014-08-01T05:14:01.192Z,1406870041.192 [HFRCMSurfaceCurrentAtVehicleLocation] Loaded
2014-08-01T05:14:01.192Z,1406870041.192 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSurfaceCurrentAtVehicleLocation" handled in the control thread.
2014-08-01T05:14:01.219Z,1406870041.219 [HFRCMVirtualSurfaceDrifter] Loaded
2014-08-01T05:14:01.219Z,1406870041.219 [ComponentRegistry](DEBUG): SyncComponent "HFRCMVirtualSurfaceDrifter" handled in the control thread.
2014-08-01T05:14:01.220Z,1406870041.220 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-08-01T05:14:01.220Z,1406870041.220 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-08-01T05:14:01.450Z,1406870041.450 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-08-01T05:14:01.451Z,1406870041.451 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-08-01T05:14:01.531Z,1406870041.531 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-08-01T05:14:01.531Z,1406870041.531 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-08-01T05:14:01.577Z,1406870041.577 [DeadReckonWithRespectToWater] Loaded
2014-08-01T05:14:01.577Z,1406870041.577 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToWater" handled in the control thread.
2014-08-01T05:14:01.623Z,1406870041.623 [DeadReckonWithRespectToSeafloor] Loaded
2014-08-01T05:14:01.623Z,1406870041.623 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2014-08-01T05:14:01.682Z,1406870041.682 [DeadReckonUsingDVLWaterTrack] Loaded
2014-08-01T05:14:01.682Z,1406870041.682 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingDVLWaterTrack" handled in the control thread.
2014-08-01T05:14:01.729Z,1406870041.729 [DeadReckonUsingCompactModelForecast] Loaded
2014-08-01T05:14:01.730Z,1406870041.730 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingCompactModelForecast" handled in the control thread.
2014-08-01T05:14:01.747Z,1406870041.747 [NavChart] Loaded
2014-08-01T05:14:01.747Z,1406870041.747 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-08-01T05:14:01.751Z,1406870041.751 [UniversalFixResidualReporter] Loaded
2014-08-01T05:14:01.752Z,1406870041.752 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-08-01T05:14:01.752Z,1406870041.752 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-08-01T05:14:01.753Z,1406870041.753 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-08-01T05:14:01.758Z,1406870041.758 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-08-01T05:14:01.759Z,1406870041.759 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-08-01T05:14:01.950Z,1406870041.950 [CTD_NeilBrown] Loaded
2014-08-01T05:14:01.951Z,1406870041.951 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-08-01T05:14:01.952Z,1406870041.952 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407B94E0
2014-08-01T05:14:01.952Z,1406870041.952 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1569
2014-08-01T05:14:01.968Z,1406870041.968 [PAR_Licor] Loaded
2014-08-01T05:14:01.968Z,1406870041.968 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-08-01T05:14:02.003Z,1406870042.003 [WetLabsBB2FL] Loaded
2014-08-01T05:14:02.003Z,1406870042.003 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-08-01T05:14:02.004Z,1406870042.004 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407E94E0
2014-08-01T05:14:02.005Z,1406870042.005 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1570
2014-08-01T05:14:02.005Z,1406870042.005 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-08-01T05:14:02.006Z,1406870042.006 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-08-01T05:14:02.290Z,1406870042.290 [AHRS_sp3003D] Loaded
2014-08-01T05:14:02.290Z,1406870042.290 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-08-01T05:14:02.550Z,1406870042.550 [Batt_Ocean_Server] Loaded
2014-08-01T05:14:02.550Z,1406870042.550 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-08-01T05:14:02.563Z,1406870042.563 [Depth_Keller] Loaded
2014-08-01T05:14:02.564Z,1406870042.564 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-08-01T05:14:02.569Z,1406870042.569 [DropWeight] Loaded
2014-08-01T05:14:02.569Z,1406870042.569 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-08-01T05:14:02.700Z,1406870042.700 [DVL_micro] Loaded
2014-08-01T05:14:02.700Z,1406870042.700 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2014-08-01T05:14:02.793Z,1406870042.793 [NAL9602] Loaded
2014-08-01T05:14:02.794Z,1406870042.794 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-08-01T05:14:02.835Z,1406870042.835 [Onboard] Loaded
2014-08-01T05:14:02.836Z,1406870042.836 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-08-01T05:14:02.843Z,1406870042.843 [Radio_Freewave] Loaded
2014-08-01T05:14:02.843Z,1406870042.843 [ComponentRegistry](DEBUG): Component "Radio_Freewave" handled in its own thread.
2014-08-01T05:14:02.844Z,1406870042.844 [Radio_Freewave ThreadHandler](DEBUG): Created PCaller Thread at 40A1E4E0
2014-08-01T05:14:02.845Z,1406870042.845 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 1571
2014-08-01T05:14:02.972Z,1406870042.972 [DAT] Loaded
2014-08-01T05:14:02.972Z,1406870042.972 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2014-08-01T05:14:02.978Z,1406870042.978 [SCPI] Loaded
2014-08-01T05:14:02.979Z,1406870042.979 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-08-01T05:14:03.288Z,1406870043.288 [BPC1] Loaded
2014-08-01T05:14:03.288Z,1406870043.288 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2014-08-01T05:14:03.289Z,1406870043.289 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-08-01T05:14:03.289Z,1406870043.289 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-08-01T05:14:03.389Z,1406870043.389 [BuoyancyServo] Loaded
2014-08-01T05:14:03.389Z,1406870043.389 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-08-01T05:14:03.412Z,1406870043.412 [ElevatorServo] Loaded
2014-08-01T05:14:03.412Z,1406870043.412 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-08-01T05:14:03.424Z,1406870043.424 [MassServo] Loaded
2014-08-01T05:14:03.424Z,1406870043.424 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-08-01T05:14:03.436Z,1406870043.436 [RudderServo] Loaded
2014-08-01T05:14:03.436Z,1406870043.436 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-08-01T05:14:03.448Z,1406870043.448 [ThrusterServo] Loaded
2014-08-01T05:14:03.448Z,1406870043.448 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-08-01T05:14:03.448Z,1406870043.448 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-08-01T05:14:03.449Z,1406870043.449 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-08-01T05:14:03.602Z,1406870043.602 [InternalSim] Loaded
2014-08-01T05:14:03.603Z,1406870043.603 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-08-01T05:14:03.603Z,1406870043.603 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-08-01T05:14:03.604Z,1406870043.604 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-08-01T05:14:03.628Z,1406870043.628 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-08-01T05:14:03.630Z,1406870043.630 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-08-01T05:14:03.631Z,1406870043.631 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-08-01T05:14:03.638Z,1406870043.638 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-08-01T05:14:03.639Z,1406870043.639 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ACF4E0
2014-08-01T05:14:03.639Z,1406870043.639 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1572
2014-08-01T05:14:03.644Z,1406870043.644 [Supervisor](INFO): Main Thread ID is 977
2014-08-01T05:14:03.645Z,1406870043.645 [Supervisor](DEBUG): Running supervisor.
2014-08-01T05:14:03.645Z,1406870043.645 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1573
2014-08-01T05:14:03.649Z,1406870043.649 [controlThread ThreadHandler](INFO): Handler Thread ID is 1574
2014-08-01T05:14:03.650Z,1406870043.650 [controlThread](DEBUG): Initializing ControlThread
2014-08-01T05:14:03.650Z,1406870043.650 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-08-01T05:14:03.652Z,1406870043.652 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-08-01T05:14:03.653Z,1406870043.653 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-08-01T05:14:03.653Z,1406870043.653 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-08-01T05:14:03.654Z,1406870043.654 [SBIT](INFO): Initialize SBIT Component.
2014-08-01T05:14:03.654Z,1406870043.654 [SBIT](IMPORTANT): Tethys CM Info: SVN revision: 11462
2014-08-01T05:14:03.655Z,1406870043.655 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2014-08-01T05:14:03.655Z,1406870043.655 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-08-01T05:14:03.655Z,1406870043.655 [IBIT](INFO): Initialize IBIT Component.
2014-08-01T05:14:03.656Z,1406870043.656 [CBIT](DEBUG): Initialize CBIT Component.
2014-08-01T05:14:03.657Z,1406870043.657 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2014-08-01T05:14:03.658Z,1406870043.658 [logger ThreadHandler](INFO): Handler Thread ID is 1575
2014-08-01T05:14:03.677Z,1406870043.677 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1576
2014-08-01T05:14:03.677Z,1406870043.677 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-08-01T05:14:03.680Z,1406870043.680 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-08-01T05:14:03.681Z,1406870043.681 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-08-01T05:14:03.681Z,1406870043.681 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-08-01T05:14:03.681Z,1406870043.681 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-08-01T05:14:03.682Z,1406870043.682 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-08-01T05:14:03.684Z,1406870043.684 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-08-01T05:14:03.696Z,1406870043.696 [HFRadarCompactModelForecaster](DEBUG): Found new ECs!
2014-08-01T05:14:03.698Z,1406870043.698 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1578
2014-08-01T05:14:03.701Z,1406870043.701 [WetLabsBB2FL](INFO): Powering down
2014-08-01T05:14:03.739Z,1406870043.739 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 1579
2014-08-01T05:14:03.741Z,1406870043.741 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1580
2014-08-01T05:14:03.751Z,1406870043.751 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-08-01T05:14:03.752Z,1406870043.752 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-08-01T05:14:03.752Z,1406870043.752 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-08-01T05:14:03.752Z,1406870043.752 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-08-01T05:14:03.753Z,1406870043.753 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-08-01T05:14:03.753Z,1406870043.753 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-08-01T05:14:03.753Z,1406870043.753 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-08-01T05:14:03.753Z,1406870043.753 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-08-01T05:14:03.754Z,1406870043.754 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-08-01T05:14:12.833Z,1406870052.833 [HFRadarCompactModelForecaster](IMPORTANT): forecast time 201408010200: published 50 modes in rows, 61 hours in columns
2014-08-01T05:14:12.853Z,1406870052.853 [HFRadarCompactModelForecaster](IMPORTANT): expansionCoefficients_[0][48] = -9.214992 for 2014-08-01T02:00:00.000Z
2014-08-01T05:14:12.854Z,1406870052.854 [HFRCMSpaceInterpolator](DEBUG): Initializing HFRCMSpaceInterpolator component with verbosity level 0.
2014-08-01T05:14:12.864Z,1406870052.864 [HFRCMTimeInterpolator](DEBUG): Initializing HFRCMTimeInterpolator component.
2014-08-01T05:14:12.866Z,1406870052.866 [HFRCMReconstructedInterpolator](INFO): Initializing HFRCMReconstructedInterpolator component with velocityAccuracy_ = 0.300000 m/s.
2014-08-01T05:14:12.867Z,1406870052.867 [HFRCMSurfaceCurrentAtVehicleLocation](DEBUG): Initializing HFRCMSurfaceCurrentAtVehicleLocation component.
2014-08-01T05:14:12.868Z,1406870052.868 [HFRCMVirtualSurfaceDrifter](DEBUG): Initializing HFRCMVirtualSurfaceDrifter component.
2014-08-01T05:14:12.868Z,1406870052.868 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-08-01T05:14:12.875Z,1406870052.875 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component.
2014-08-01T05:14:12.875Z,1406870052.875 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component.
2014-08-01T05:14:12.876Z,1406870052.876 [DeadReckonUsingDVLWaterTrack](DEBUG): Initializing DeadReckonUsingDVLWaterTrack component.
2014-08-01T05:14:12.876Z,1406870052.876 [DeadReckonUsingCompactModelForecast](DEBUG): Initializing DeadReckonUsingCompactModelForecast component.
2014-08-01T05:14:12.876Z,1406870052.876 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-08-01T05:14:12.877Z,1406870052.877 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-08-01T05:14:14.153Z,1406870054.153 [Batt_Ocean_Server](ERROR): Batt_Ocean_Server A initialization uart error: serial timeout
2014-08-01T05:14:14.153Z,1406870054.153 [Batt_Ocean_Server](ERROR): Ocean Server Batteries failed to initialize. Re-initializing
2014-08-01T05:14:14.156Z,1406870054.156 [Batt_Ocean_Server] Communications Fault, FailCount= 1
2014-08-01T05:14:14.156Z,1406870054.156 [Batt_Ocean_Server](ERROR): Communications Fault
2014-08-01T05:14:14.165Z,1406870054.165 [InternalSim](DEBUG):  InternalSim initializing...
2014-08-01T05:14:14.268Z,1406870054.268 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-08-01T05:14:14.291Z,1406870054.291 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-08-01T05:14:14.312Z,1406870054.312 [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:14:14.337Z,1406870054.337 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-08-01T05:14:14.391Z,1406870054.391 [Default:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-08-01T05:14:14.416Z,1406870054.416 [Default:CheckIn:A.SetSpeed](DEBUG): Construct.
2014-08-01T05:14:14.438Z,1406870054.438 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-08-01T05:14:14.441Z,1406870054.441 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-08-01T05:14:14.463Z,1406870054.463 [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:14:14.470Z,1406870054.470 [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:14:14.627Z,1406870054.627 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-08-01T05:14:14.865Z,1406870054.865 [Radio_Freewave](INFO): Powering up
2014-08-01T05:14:14.867Z,1406870054.867 [DVL_micro](INFO): Initializing
2014-08-01T05:14:14.902Z,1406870054.902 [NAL9602](INFO): Powering up NAL9602
2014-08-01T05:14:14.998Z,1406870054.998 [DAT](INFO): Powering up
2014-08-01T05:14:14.998Z,1406870054.998 [DAT](DEBUG): Initializing DAT.
2014-08-01T05:14:15.029Z,1406870055.029 [BPC1](DEBUG): Initializing BPC1.
2014-08-01T05:14:15.672Z,1406870055.672 [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:14:22.923Z,1406870062.923 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-08-01T05:14:22.935Z,1406870062.935 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-08-01T05:14:22.941Z,1406870062.941 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-08-01T05:14:22.946Z,1406870062.946 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-08-01T05:14:22.968Z,1406870062.968 [MassServo](DEBUG): Initializing EZServoServo.
2014-08-01T05:14:22.974Z,1406870062.974 [MassServo](DEBUG): Initializing MassServo.
2014-08-01T05:14:22.997Z,1406870062.997 [RudderServo](DEBUG): Initializing EZServoServo.
2014-08-01T05:14:23.002Z,1406870063.002 [RudderServo](DEBUG): Initializing RudderServo.
2014-08-01T05:14:23.008Z,1406870063.008 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-08-01T05:14:23.014Z,1406870063.014 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-08-01T05:14:23.045Z,1406870063.045 [CBIT](ERROR): Communications Fault in component: Batt_Ocean_Server
2014-08-01T05:14:23.045Z,1406870063.045 [CBIT](INFO): Clearing failed state for component Batt_Ocean_Server
2014-08-01T05:14:23.045Z,1406870063.045 [Batt_Ocean_Server] No Fault, FailCount= 1
2014-08-01T05:14:25.177Z,1406870065.177 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-08-01T05:14:25.567Z,1406870065.567 [SBIT](IMPORTANT): Beginning Startup BIT
2014-08-01T05:14:25.569Z,1406870065.569 [CBIT](IMPORTANT): Beginning GF scan
2014-08-01T05:14:26.059Z,1406870066.059 [NAL9602](INFO): NAL9602 initialized
2014-08-01T05:14:35.335Z,1406870075.335 [DAT](INFO): Powering down
2014-08-01T05:14:52.897Z,1406870092.897 [CBIT](IMPORTANT): No ground fault detected
2014-08-01T05:15:06.407Z,1406870106.407 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:15:06.407Z,1406870106.407 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:15:06.453Z,1406870106.453 [MissionManager](INFO): DefineArg tracking_on_surface.MissionTimeout = 10.000000 min
2014-08-01T05:15:06.462Z,1406870106.462 [MissionManager](INFO): DefineArg tracking_on_surface.ContactLabel = 1.000000 count
2014-08-01T05:15:06.465Z,1406870106.465 [MissionManager](INFO): DefineArg tracking_on_surface.TrackingUpdatePeriod = 45.000000 s
2014-08-01T05:15:06.492Z,1406870106.492 [MissionManager](INFO): DefineArg tracking_on_surface.TrackingQueryMode = 0.000000 count
2014-08-01T05:15:06.496Z,1406870106.496 [MissionManager](INFO): DefineArg tracking_on_surface.Repeat = 13.000000 count
2014-08-01T05:15:06.499Z,1406870106.499 [MissionManager](INFO): DefineArg tracking_on_surface.MassDefault = 0.000000 n/a
2014-08-01T05:15:06.501Z,1406870106.501 [tracking_on_surface:A.Pitch](DEBUG): Construct.
2014-08-01T05:15:06.893Z,1406870106.893 [tracking_on_surface:TestDrive:C.Wait](DEBUG): Construct Wait.
2014-08-01T05:15:06.935Z,1406870106.935 [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:15:06.937Z,1406870106.937 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:15:20.002Z,1406870120.002 [SBIT](IMPORTANT): SBIT PASSED
2014-08-01T05:15:20.437Z,1406870120.437 [MissionManager](IMPORTANT): Started mission Startup
2014-08-01T05:15:20.438Z,1406870120.438 [Startup] Running Loop=1
2014-08-01T05:15:20.438Z,1406870120.438 [Startup](INFO): Aggregate::initialize Startup
2014-08-01T05:15:20.438Z,1406870120.438 [Startup:A.GoToSurface] Running Loop=1
2014-08-01T05:15:20.438Z,1406870120.438 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-08-01T05:15:20.438Z,1406870120.438 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-08-01T05:15:20.439Z,1406870120.439 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-08-01T05:15:20.439Z,1406870120.439 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-08-01T05:15:20.445Z,1406870120.445 [Startup:StartupSatComms] Running Loop=1
2014-08-01T05:15:20.446Z,1406870120.446 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-08-01T05:15:20.446Z,1406870120.446 [Startup:StartupSatComms:A] Running Loop=1
2014-08-01T05:15:20.859Z,1406870120.859 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-08-01T05:15:33.675Z,1406870133.675 [DVL_micro](ERROR): NQ1 string checksum mismatch. Reported:99 Calculated:125
2014-08-01T05:15:33.675Z,1406870133.675 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 123 110 45 74 3 3 4 38.0 94.9 2 -89.0 -72.2 94.9 2 104 48 94 2 -89 -72 94 2 5.34 -0.41 194.3 -3.0 24.9 0.005 35.0 1489 99
2014-08-01T05:16:10.747Z,1406870170.747 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:16:10.751Z,1406870170.751 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:16:10.798Z,1406870170.798 [MissionManager](INFO): DefineArg tracking_on_surface.MissionTimeout = 10.000000 min
2014-08-01T05:16:10.800Z,1406870170.800 [MissionManager](INFO): DefineArg tracking_on_surface.ContactLabel = 0.000000 count
2014-08-01T05:16:10.804Z,1406870170.804 [MissionManager](INFO): DefineArg tracking_on_surface.NumberOfPings = 1.000000 count
2014-08-01T05:16:10.806Z,1406870170.806 [MissionManager](INFO): DefineArg tracking_on_surface.TrackingUpdatePeriod = 60.000000 s
2014-08-01T05:16:10.809Z,1406870170.809 [MissionManager](INFO): DefineArg tracking_on_surface.Repeat = 13.000000 count
2014-08-01T05:16:10.832Z,1406870170.832 [MissionManager](INFO): DefineArg tracking_on_surface.MassDefault = 0.000000 n/a
2014-08-01T05:16:10.833Z,1406870170.833 [tracking_on_surface:A.Pitch](DEBUG): Construct.
2014-08-01T05:16:10.882Z,1406870170.882 [tracking_on_surface:TestDrive:C.Wait](DEBUG): Construct Wait.
2014-08-01T05:16:10.888Z,1406870170.888 [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>0</Value></DefineArg>

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

    <DefineArg Name="TrackingUpdatePeriod"><Units:second/><Value>60</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.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
        <Setting><Derivation:Tracking.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></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:16:10.890Z,1406870170.890 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:16:20.711Z,1406870180.711 [Startup:StartupSatComms:A](INFO): Timed out from 2014-08-01T05:15:20.4Z
2014-08-01T05:16:20.711Z,1406870180.711 [Startup:StartupSatComms:A] Stopped
2014-08-01T05:16:20.711Z,1406870180.711 [Startup:StartupSatComms:B] Running Loop=1
2014-08-01T05:16:21.118Z,1406870181.118 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-08-01T05:16:24.781Z,1406870184.781 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:16:24.785Z,1406870184.785 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:16:24.847Z,1406870184.847 [MissionManager](INFO): DefineArg tracking_on_surface.MissionTimeout = 10.000000 min
2014-08-01T05:16:24.852Z,1406870184.852 [MissionManager](INFO): DefineArg tracking_on_surface.ContactLabel = 0.000000 count
2014-08-01T05:16:24.855Z,1406870184.855 [MissionManager](INFO): DefineArg tracking_on_surface.NumberOfPings = 1.000000 count
2014-08-01T05:16:24.861Z,1406870184.861 [MissionManager](INFO): DefineArg tracking_on_surface.TrackingUpdatePeriod = 60.000000 s
2014-08-01T05:16:24.864Z,1406870184.864 [MissionManager](INFO): DefineArg tracking_on_surface.Repeat = 13.000000 count
2014-08-01T05:16:24.866Z,1406870184.866 [MissionManager](INFO): DefineArg tracking_on_surface.MassDefault = 0.000000 n/a
2014-08-01T05:16:24.867Z,1406870184.867 [tracking_on_surface:A.Pitch](DEBUG): Construct.
2014-08-01T05:16:24.954Z,1406870184.954 [tracking_on_surface:TestDrive:C.Wait](DEBUG): Construct Wait.
2014-08-01T05:16:24.958Z,1406870184.958 [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>0</Value></DefineArg>

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

    <DefineArg Name="TrackingUpdatePeriod"><Units:second/><Value>60</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.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
        <Setting><Derivation:Tracking.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></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:16:24.966Z,1406870184.966 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:17:20.744Z,1406870240.744 [Startup:StartupSatComms:B](INFO): Timed out from 2014-08-01T05:16:20.7Z
2014-08-01T05:17:20.744Z,1406870240.744 [Startup:StartupSatComms:B] Stopped
2014-08-01T05:17:20.744Z,1406870240.744 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2014-08-01T05:17:20.744Z,1406870240.744 [Startup:StartupSatComms] Stopped
2014-08-01T05:17:20.745Z,1406870240.745 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2014-08-01T05:17:20.745Z,1406870240.745 [Startup](INFO): Completed Startup
2014-08-01T05:17:20.746Z,1406870240.746 [Startup] Stopped
2014-08-01T05:17:20.746Z,1406870240.746 [Startup](INFO): Aggregate::uninitialize Startup
2014-08-01T05:17:20.746Z,1406870240.746 [Startup:A.GoToSurface] Stopped
2014-08-01T05:17:20.746Z,1406870240.746 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-08-01T05:17:21.173Z,1406870241.173 [MissionManager](IMPORTANT): Started mission tracking_on_surface
2014-08-01T05:17:21.173Z,1406870241.173 [tracking_on_surface] Running Loop=1
2014-08-01T05:17:21.174Z,1406870241.174 [tracking_on_surface](INFO): Aggregate::initialize tracking_on_surface
2014-08-01T05:17:21.174Z,1406870241.174 [tracking_on_surface:A.Pitch] Running Loop=1
2014-08-01T05:17:21.174Z,1406870241.174 [tracking_on_surface:A.Pitch](DEBUG): Initialize.
2014-08-01T05:17:21.174Z,1406870241.174 [tracking_on_surface:B.] Running Loop=1
2014-08-01T05:17:21.174Z,1406870241.174 [tracking_on_surface:B.](INFO): Initializing Tracking.
2014-08-01T05:17:21.175Z,1406870241.175 [tracking_on_surface:TestDrive] Running Loop=1
2014-08-01T05:17:21.175Z,1406870241.175 [tracking_on_surface:TestDrive](INFO): Aggregate::initialize tracking_on_surface:TestDrive
2014-08-01T05:17:21.175Z,1406870241.175 [tracking_on_surface:TestDrive:B] Running Loop=1
2014-08-01T05:17:21.176Z,1406870241.176 [tracking_on_surface:TestDrive:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-08-01T05:17:21.177Z,1406870241.177 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:21.177Z,1406870241.177 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:21.178Z,1406870241.178 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:21.210Z,1406870241.210 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:21.210Z,1406870241.210 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:21.210Z,1406870241.210 [tracking_on_surface:B.] Running Loop=1
2014-08-01T05:17:21.210Z,1406870241.210 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:21.240Z,1406870241.240 [tracking_on_surface:A.Pitch] Running Loop=1
2014-08-01T05:17:21.884Z,1406870241.884 [DAT](INFO): Powering up
2014-08-01T05:17:21.925Z,1406870241.925 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:21.925Z,1406870241.925 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:21.925Z,1406870241.925 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:21.925Z,1406870241.925 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:21.925Z,1406870241.925 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:22.320Z,1406870242.320 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:22.321Z,1406870242.321 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:22.321Z,1406870242.321 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:22.322Z,1406870242.322 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:22.322Z,1406870242.322 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:22.322Z,1406870242.322 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:22.737Z,1406870242.737 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:22.739Z,1406870242.739 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:22.739Z,1406870242.739 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:22.740Z,1406870242.740 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:22.741Z,1406870242.741 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:23.273Z,1406870243.273 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:23.273Z,1406870243.273 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:23.273Z,1406870243.273 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:23.278Z,1406870243.278 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:23.278Z,1406870243.278 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:23.278Z,1406870243.278 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:24.190Z,1406870244.190 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:24.191Z,1406870244.191 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:24.191Z,1406870244.191 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:24.191Z,1406870244.191 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:24.191Z,1406870244.191 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:25.634Z,1406870245.634 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:25.635Z,1406870245.635 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:25.635Z,1406870245.635 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:25.636Z,1406870245.636 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:25.636Z,1406870245.636 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:25.636Z,1406870245.636 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:26.146Z,1406870246.146 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:26.147Z,1406870246.147 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:26.147Z,1406870246.147 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:26.147Z,1406870246.147 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:26.147Z,1406870246.147 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:26.637Z,1406870246.637 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:26.637Z,1406870246.637 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:26.637Z,1406870246.637 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:26.638Z,1406870246.638 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:26.638Z,1406870246.638 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:26.638Z,1406870246.638 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:27.053Z,1406870247.053 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:27.053Z,1406870247.053 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:27.053Z,1406870247.053 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:27.053Z,1406870247.053 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:27.053Z,1406870247.053 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:27.497Z,1406870247.497 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:27.497Z,1406870247.497 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:27.497Z,1406870247.497 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:27.498Z,1406870247.498 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:27.498Z,1406870247.498 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:27.499Z,1406870247.499 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:27.901Z,1406870247.901 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:27.901Z,1406870247.901 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:27.902Z,1406870247.902 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:27.902Z,1406870247.902 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:27.902Z,1406870247.902 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:28.309Z,1406870248.309 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:28.310Z,1406870248.310 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:28.310Z,1406870248.310 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:28.311Z,1406870248.311 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:28.311Z,1406870248.311 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:28.311Z,1406870248.311 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:28.720Z,1406870248.720 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:28.720Z,1406870248.720 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:28.720Z,1406870248.720 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:28.720Z,1406870248.720 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:28.720Z,1406870248.720 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:29.162Z,1406870249.162 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:29.162Z,1406870249.162 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:29.162Z,1406870249.162 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:29.163Z,1406870249.163 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:29.163Z,1406870249.163 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:29.163Z,1406870249.163 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:30.152Z,1406870250.152 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:30.152Z,1406870250.152 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:30.152Z,1406870250.152 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:30.153Z,1406870250.153 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:30.153Z,1406870250.153 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:31.661Z,1406870251.661 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:31.661Z,1406870251.661 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:31.661Z,1406870251.661 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:31.662Z,1406870251.662 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:31.662Z,1406870251.662 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:31.663Z,1406870251.663 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:32.066Z,1406870252.066 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-08-01T05:17:32.066Z,1406870252.066 [DVL_micro] Data Fault, FailCount= 1
2014-08-01T05:17:32.066Z,1406870252.066 [DVL_micro](ERROR): Data Fault
2014-08-01T05:17:32.121Z,1406870252.121 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:32.121Z,1406870252.121 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:32.122Z,1406870252.122 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:32.122Z,1406870252.122 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:32.122Z,1406870252.122 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:32.131Z,1406870252.131 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-08-01T05:17:32.506Z,1406870252.506 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T05:17:32.571Z,1406870252.571 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:32.571Z,1406870252.571 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:32.571Z,1406870252.571 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:32.573Z,1406870252.573 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:32.573Z,1406870252.573 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:32.573Z,1406870252.573 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:32.991Z,1406870252.991 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-08-01T05:17:32.991Z,1406870252.991 [DVL_micro] Hardware Fault, FailCount= 1
2014-08-01T05:17:32.991Z,1406870252.991 [DVL_micro](ERROR): Hardware Fault
2014-08-01T05:17:33.054Z,1406870253.054 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:33.054Z,1406870253.054 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:33.054Z,1406870253.054 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:33.054Z,1406870253.054 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:33.055Z,1406870253.055 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:33.436Z,1406870253.436 [DVL_micro](INFO): Initializing
2014-08-01T05:17:33.490Z,1406870253.490 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:33.490Z,1406870253.490 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:33.491Z,1406870253.491 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:33.492Z,1406870253.492 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:33.492Z,1406870253.492 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:33.492Z,1406870253.492 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:33.502Z,1406870253.502 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-08-01T05:17:33.502Z,1406870253.502 [DVL_micro] No Fault, FailCount= 1
2014-08-01T05:17:33.934Z,1406870253.934 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:33.934Z,1406870253.934 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:33.934Z,1406870253.934 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:33.935Z,1406870253.935 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:33.935Z,1406870253.935 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:34.346Z,1406870254.346 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:34.346Z,1406870254.346 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:34.346Z,1406870254.346 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:34.347Z,1406870254.347 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:34.347Z,1406870254.347 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:34.348Z,1406870254.348 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:34.760Z,1406870254.760 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:34.761Z,1406870254.761 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:34.761Z,1406870254.761 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:34.761Z,1406870254.761 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:34.761Z,1406870254.761 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:35.203Z,1406870255.203 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:35.203Z,1406870255.203 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:35.203Z,1406870255.203 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:35.205Z,1406870255.205 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:35.205Z,1406870255.205 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:35.205Z,1406870255.205 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:36.199Z,1406870256.199 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:36.199Z,1406870256.199 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:36.199Z,1406870256.199 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:36.199Z,1406870256.199 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:36.199Z,1406870256.199 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:37.658Z,1406870257.658 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:37.658Z,1406870257.658 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:37.658Z,1406870257.658 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:37.659Z,1406870257.659 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:37.659Z,1406870257.659 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:37.659Z,1406870257.659 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:38.098Z,1406870258.098 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:38.098Z,1406870258.098 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:38.098Z,1406870258.098 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:38.099Z,1406870258.099 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:38.099Z,1406870258.099 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:38.512Z,1406870258.512 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:38.512Z,1406870258.512 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:38.512Z,1406870258.512 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:38.513Z,1406870258.513 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:38.513Z,1406870258.513 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:38.513Z,1406870258.513 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:38.944Z,1406870258.944 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:38.945Z,1406870258.945 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:38.945Z,1406870258.945 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:38.945Z,1406870258.945 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:38.945Z,1406870258.945 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:39.453Z,1406870259.453 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:39.453Z,1406870259.453 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:39.453Z,1406870259.453 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:39.454Z,1406870259.454 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:39.454Z,1406870259.454 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:39.454Z,1406870259.454 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:39.860Z,1406870259.860 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:39.860Z,1406870259.860 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:39.860Z,1406870259.860 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:39.860Z,1406870259.860 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:39.860Z,1406870259.860 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:40.281Z,1406870260.281 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:40.281Z,1406870260.281 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:40.281Z,1406870260.281 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:40.282Z,1406870260.282 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:40.282Z,1406870260.282 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:40.283Z,1406870260.283 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:40.787Z,1406870260.787 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:40.787Z,1406870260.787 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:40.787Z,1406870260.787 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:40.787Z,1406870260.787 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:40.788Z,1406870260.788 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:41.218Z,1406870261.218 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:41.218Z,1406870261.218 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:41.218Z,1406870261.218 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:41.219Z,1406870261.219 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:41.219Z,1406870261.219 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:41.219Z,1406870261.219 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:42.230Z,1406870262.230 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:42.230Z,1406870262.230 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:42.230Z,1406870262.230 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:42.230Z,1406870262.230 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:42.231Z,1406870262.231 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:44.010Z,1406870264.010 [DAT](FAULT): DAT uart error: serial timeout
2014-08-01T05:17:44.010Z,1406870264.010 [DAT](INFO): deviceResponse_: 
2014-08-01T05:17:44.010Z,1406870264.010 [DAT] Communications Fault, FailCount= 1
2014-08-01T05:17:44.010Z,1406870264.010 [DAT](ERROR): Communications Fault
2014-08-01T05:17:44.034Z,1406870264.034 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:44.034Z,1406870264.034 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:44.034Z,1406870264.034 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:44.036Z,1406870264.036 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:44.036Z,1406870264.036 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:44.036Z,1406870264.036 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:44.045Z,1406870264.045 [CBIT](ERROR): Communications Fault in component: DAT
2014-08-01T05:17:44.499Z,1406870264.499 [DAT](INFO): Powering down
2014-08-01T05:17:44.561Z,1406870264.561 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:44.562Z,1406870264.562 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:44.562Z,1406870264.562 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:44.562Z,1406870264.562 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:44.562Z,1406870264.562 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:44.975Z,1406870264.975 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:44.975Z,1406870264.975 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:44.975Z,1406870264.975 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:44.976Z,1406870264.976 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:44.976Z,1406870264.976 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:44.977Z,1406870264.977 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:45.418Z,1406870265.418 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:45.418Z,1406870265.418 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:45.418Z,1406870265.418 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:45.418Z,1406870265.418 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:45.418Z,1406870265.418 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:45.428Z,1406870265.428 [CBIT](INFO): Clearing failed state for component DAT
2014-08-01T05:17:45.428Z,1406870265.428 [DAT] No Fault, FailCount= 1
2014-08-01T05:17:45.913Z,1406870265.913 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:45.913Z,1406870265.913 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:45.913Z,1406870265.913 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:45.915Z,1406870265.915 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:45.915Z,1406870265.915 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:45.915Z,1406870265.915 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:46.370Z,1406870266.370 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:46.370Z,1406870266.370 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:46.370Z,1406870266.370 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:46.370Z,1406870266.370 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:46.371Z,1406870266.371 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:46.791Z,1406870266.791 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:46.791Z,1406870266.791 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:46.792Z,1406870266.792 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:46.793Z,1406870266.793 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:46.793Z,1406870266.793 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:46.793Z,1406870266.793 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:47.224Z,1406870267.224 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:47.224Z,1406870267.224 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:47.224Z,1406870267.224 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:47.225Z,1406870267.225 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:47.225Z,1406870267.225 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:48.157Z,1406870268.157 [DAT](INFO): Powering up
2014-08-01T05:17:48.157Z,1406870268.157 [DAT](DEBUG): Initializing DAT.
2014-08-01T05:17:48.191Z,1406870268.191 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:48.191Z,1406870268.191 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:48.191Z,1406870268.191 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:48.192Z,1406870268.192 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:48.192Z,1406870268.192 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:48.192Z,1406870268.192 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:51.383Z,1406870271.383 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:51.383Z,1406870271.383 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:51.383Z,1406870271.383 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:51.383Z,1406870271.383 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:51.383Z,1406870271.383 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:51.955Z,1406870271.955 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:51.956Z,1406870271.956 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:51.956Z,1406870271.956 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:51.957Z,1406870271.957 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:51.957Z,1406870271.957 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:51.957Z,1406870271.957 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:52.398Z,1406870272.398 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:52.398Z,1406870272.398 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:52.398Z,1406870272.398 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:52.399Z,1406870272.399 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:52.399Z,1406870272.399 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:52.865Z,1406870272.865 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:52.865Z,1406870272.865 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:52.865Z,1406870272.865 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:52.866Z,1406870272.866 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:52.866Z,1406870272.866 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:52.866Z,1406870272.866 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:53.298Z,1406870273.298 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:53.298Z,1406870273.298 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:53.298Z,1406870273.298 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:53.299Z,1406870273.299 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:53.299Z,1406870273.299 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:53.712Z,1406870273.712 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:53.713Z,1406870273.713 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:53.713Z,1406870273.713 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:53.714Z,1406870273.714 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:53.714Z,1406870273.714 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:53.714Z,1406870273.714 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:54.146Z,1406870274.146 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:54.146Z,1406870274.146 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:54.147Z,1406870274.147 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:54.147Z,1406870274.147 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:54.147Z,1406870274.147 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:54.555Z,1406870274.555 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:54.555Z,1406870274.555 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:54.555Z,1406870274.555 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:54.557Z,1406870274.557 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:54.557Z,1406870274.557 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:54.557Z,1406870274.557 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:55.042Z,1406870275.042 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:55.043Z,1406870275.043 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:55.047Z,1406870275.047 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:55.047Z,1406870275.047 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:55.047Z,1406870275.047 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:55.965Z,1406870275.965 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:55.965Z,1406870275.965 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:55.965Z,1406870275.965 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:55.966Z,1406870275.966 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:55.966Z,1406870275.966 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:55.966Z,1406870275.966 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:57.512Z,1406870277.512 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:57.512Z,1406870277.512 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:57.512Z,1406870277.512 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:57.512Z,1406870277.512 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:57.513Z,1406870277.513 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:57.940Z,1406870277.940 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:57.940Z,1406870277.940 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:57.940Z,1406870277.940 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:57.941Z,1406870277.941 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:57.941Z,1406870277.941 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:57.941Z,1406870277.941 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:58.396Z,1406870278.396 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:58.400Z,1406870278.400 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:58.400Z,1406870278.400 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:58.400Z,1406870278.400 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:58.401Z,1406870278.401 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:58.844Z,1406870278.844 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:58.844Z,1406870278.844 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:58.844Z,1406870278.844 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:58.845Z,1406870278.845 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:58.845Z,1406870278.845 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:58.846Z,1406870278.846 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:59.308Z,1406870279.308 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:17:59.309Z,1406870279.309 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:17:59.309Z,1406870279.309 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:17:59.309Z,1406870279.309 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:59.309Z,1406870279.309 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:17:59.736Z,1406870279.736 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:17:59.736Z,1406870279.736 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:17:59.736Z,1406870279.736 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:17:59.737Z,1406870279.737 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:17:59.737Z,1406870279.737 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:17:59.737Z,1406870279.737 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:00.145Z,1406870280.145 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:00.145Z,1406870280.145 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:00.146Z,1406870280.146 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:00.146Z,1406870280.146 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:00.146Z,1406870280.146 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:00.562Z,1406870280.562 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:00.562Z,1406870280.562 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:00.562Z,1406870280.562 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:00.564Z,1406870280.564 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:00.564Z,1406870280.564 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:00.564Z,1406870280.564 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:01.007Z,1406870281.007 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:01.007Z,1406870281.007 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:01.007Z,1406870281.007 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:01.007Z,1406870281.007 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:01.007Z,1406870281.007 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:02.005Z,1406870282.005 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:02.005Z,1406870282.005 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:02.006Z,1406870282.006 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:02.007Z,1406870282.007 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:02.007Z,1406870282.007 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:02.007Z,1406870282.007 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:03.462Z,1406870283.462 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:03.462Z,1406870283.462 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:03.462Z,1406870283.462 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:03.463Z,1406870283.463 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:03.463Z,1406870283.463 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:03.884Z,1406870283.884 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:03.884Z,1406870283.884 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:03.884Z,1406870283.884 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:03.886Z,1406870283.886 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:03.886Z,1406870283.886 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:03.886Z,1406870283.886 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:04.329Z,1406870284.329 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:04.329Z,1406870284.329 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:04.329Z,1406870284.329 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:04.329Z,1406870284.329 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:04.330Z,1406870284.330 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:04.774Z,1406870284.774 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:04.774Z,1406870284.774 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:04.774Z,1406870284.774 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:04.776Z,1406870284.776 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:04.776Z,1406870284.776 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:04.776Z,1406870284.776 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:05.246Z,1406870285.246 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:05.251Z,1406870285.251 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:05.251Z,1406870285.251 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:05.251Z,1406870285.251 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:05.251Z,1406870285.251 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:05.701Z,1406870285.701 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:05.701Z,1406870285.701 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:05.701Z,1406870285.701 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:05.702Z,1406870285.702 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:05.702Z,1406870285.702 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:05.703Z,1406870285.703 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:06.133Z,1406870286.133 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:06.134Z,1406870286.134 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:06.134Z,1406870286.134 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:06.134Z,1406870286.134 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:06.134Z,1406870286.134 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:06.605Z,1406870286.605 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:06.605Z,1406870286.605 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:06.605Z,1406870286.605 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:06.606Z,1406870286.606 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:06.606Z,1406870286.606 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:06.607Z,1406870286.607 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:07.053Z,1406870287.053 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:07.053Z,1406870287.053 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:07.053Z,1406870287.053 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:07.053Z,1406870287.053 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:07.054Z,1406870287.054 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:08.122Z,1406870288.122 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:08.122Z,1406870288.122 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:08.122Z,1406870288.122 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:08.146Z,1406870288.146 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:08.146Z,1406870288.146 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:08.146Z,1406870288.146 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:09.906Z,1406870289.906 [DAT](FAULT): DAT uart error: serial timeout
2014-08-01T05:18:09.906Z,1406870289.906 [DAT](INFO): deviceResponse_: 
2014-08-01T05:18:09.906Z,1406870289.906 [DAT] Communications Fault, FailCount= 2
2014-08-01T05:18:09.906Z,1406870289.906 [DAT](ERROR): Communications Fault
2014-08-01T05:18:09.961Z,1406870289.961 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:09.961Z,1406870289.961 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:09.961Z,1406870289.961 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:09.961Z,1406870289.961 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:09.961Z,1406870289.961 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:09.970Z,1406870289.970 [CBIT](ERROR): Communications Fault in component: DAT
2014-08-01T05:18:10.408Z,1406870290.408 [DAT](INFO): Powering down
2014-08-01T05:18:10.449Z,1406870290.449 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:10.449Z,1406870290.449 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:10.449Z,1406870290.449 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:10.450Z,1406870290.450 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:10.451Z,1406870290.451 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:10.451Z,1406870290.451 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:10.876Z,1406870290.876 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:10.876Z,1406870290.876 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:10.876Z,1406870290.876 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:10.876Z,1406870290.876 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:10.877Z,1406870290.877 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:11.312Z,1406870291.312 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:11.312Z,1406870291.312 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:11.312Z,1406870291.312 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:11.313Z,1406870291.313 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:11.314Z,1406870291.314 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:11.314Z,1406870291.314 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:11.323Z,1406870291.323 [CBIT](INFO): Clearing failed state for component DAT
2014-08-01T05:18:11.323Z,1406870291.323 [DAT] No Fault, FailCount= 2
2014-08-01T05:18:11.855Z,1406870291.855 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:11.855Z,1406870291.855 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:11.855Z,1406870291.855 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:11.856Z,1406870291.856 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:11.856Z,1406870291.856 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:12.314Z,1406870292.314 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:12.314Z,1406870292.314 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:12.314Z,1406870292.314 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:12.315Z,1406870292.315 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:12.315Z,1406870292.315 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:12.315Z,1406870292.315 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:12.724Z,1406870292.724 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:12.724Z,1406870292.724 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:12.724Z,1406870292.724 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:12.724Z,1406870292.724 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:12.724Z,1406870292.724 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:13.190Z,1406870293.190 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:13.190Z,1406870293.190 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:13.190Z,1406870293.190 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:13.196Z,1406870293.196 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:13.196Z,1406870293.196 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:13.196Z,1406870293.196 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:14.097Z,1406870294.097 [DAT](INFO): Powering up
2014-08-01T05:18:14.097Z,1406870294.097 [DAT](DEBUG): Initializing DAT.
2014-08-01T05:18:14.132Z,1406870294.132 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:14.132Z,1406870294.132 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:14.132Z,1406870294.132 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:14.132Z,1406870294.132 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:14.132Z,1406870294.132 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:15.573Z,1406870295.573 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:15.573Z,1406870295.573 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:15.573Z,1406870295.573 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:15.574Z,1406870295.574 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:15.574Z,1406870295.574 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:15.575Z,1406870295.575 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:16.034Z,1406870296.034 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:16.035Z,1406870296.035 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:16.035Z,1406870296.035 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:16.035Z,1406870296.035 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:16.035Z,1406870296.035 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:16.523Z,1406870296.523 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:16.523Z,1406870296.523 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:16.523Z,1406870296.523 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:16.529Z,1406870296.529 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:16.529Z,1406870296.529 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:16.529Z,1406870296.529 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:17.005Z,1406870297.005 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:17.005Z,1406870297.005 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:17.005Z,1406870297.005 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:17.005Z,1406870297.005 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:17.005Z,1406870297.005 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:17.421Z,1406870297.421 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:17.421Z,1406870297.421 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:17.421Z,1406870297.421 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:17.438Z,1406870297.438 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:17.439Z,1406870297.439 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:17.439Z,1406870297.439 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:17.843Z,1406870297.843 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:17.844Z,1406870297.844 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:17.844Z,1406870297.844 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:17.844Z,1406870297.844 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:17.844Z,1406870297.844 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:18.258Z,1406870298.258 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:18.259Z,1406870298.259 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:18.259Z,1406870298.259 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:18.260Z,1406870298.260 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:18.260Z,1406870298.260 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:18.260Z,1406870298.260 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:18.704Z,1406870298.704 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:18.704Z,1406870298.704 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:18.704Z,1406870298.704 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:18.704Z,1406870298.704 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:18.704Z,1406870298.704 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:19.167Z,1406870299.167 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:19.168Z,1406870299.168 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:19.168Z,1406870299.168 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:19.169Z,1406870299.169 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:19.169Z,1406870299.169 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:19.169Z,1406870299.169 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:20.104Z,1406870300.104 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:20.104Z,1406870300.104 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:20.104Z,1406870300.104 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:20.104Z,1406870300.104 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:20.104Z,1406870300.104 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:21.568Z,1406870301.568 [tracking_on_surface:TestDrive:B](INFO): Timed out from 2014-08-01T05:17:21.2Z
2014-08-01T05:18:21.568Z,1406870301.568 [tracking_on_surface:TestDrive:B] Stopped
2014-08-01T05:18:21.568Z,1406870301.568 [tracking_on_surface:TestDrive:C.Wait] Running Loop=1
2014-08-01T05:18:21.568Z,1406870301.568 [tracking_on_surface:TestDrive:C.Wait](DEBUG): Initialize Wait Component.
2014-08-01T05:18:21.568Z,1406870301.568 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:21.569Z,1406870301.569 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:21.569Z,1406870301.569 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:21.570Z,1406870301.570 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:21.570Z,1406870301.570 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:21.570Z,1406870301.570 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:22.126Z,1406870302.126 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:22.126Z,1406870302.126 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:22.126Z,1406870302.126 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:22.127Z,1406870302.127 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:22.127Z,1406870302.127 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:22.564Z,1406870302.564 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:22.564Z,1406870302.564 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:22.564Z,1406870302.564 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:22.566Z,1406870302.566 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:22.566Z,1406870302.566 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:22.566Z,1406870302.566 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:23.025Z,1406870303.025 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:23.025Z,1406870303.025 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:23.025Z,1406870303.025 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:23.025Z,1406870303.025 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:23.026Z,1406870303.026 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:23.495Z,1406870303.495 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:23.495Z,1406870303.495 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:23.495Z,1406870303.495 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:23.496Z,1406870303.496 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:23.496Z,1406870303.496 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:23.496Z,1406870303.496 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:23.919Z,1406870303.919 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:23.919Z,1406870303.919 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:23.919Z,1406870303.919 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:23.920Z,1406870303.920 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:23.920Z,1406870303.920 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:24.333Z,1406870304.333 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:24.333Z,1406870304.333 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:24.334Z,1406870304.334 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:24.335Z,1406870304.335 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:24.335Z,1406870304.335 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:24.335Z,1406870304.335 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:24.742Z,1406870304.742 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:24.743Z,1406870304.743 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:24.743Z,1406870304.743 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:24.743Z,1406870304.743 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:24.743Z,1406870304.743 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:25.186Z,1406870305.186 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:25.187Z,1406870305.187 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:25.187Z,1406870305.187 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:25.188Z,1406870305.188 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:25.188Z,1406870305.188 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:25.188Z,1406870305.188 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:25.650Z,1406870305.650 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:25.650Z,1406870305.650 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:25.650Z,1406870305.650 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:25.650Z,1406870305.650 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:25.651Z,1406870305.651 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:26.088Z,1406870306.088 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:26.088Z,1406870306.088 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:26.088Z,1406870306.088 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:26.089Z,1406870306.089 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:26.089Z,1406870306.089 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:26.089Z,1406870306.089 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:26.556Z,1406870306.556 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:26.556Z,1406870306.556 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:26.556Z,1406870306.556 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:26.556Z,1406870306.556 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:26.556Z,1406870306.556 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:27.039Z,1406870307.039 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:27.039Z,1406870307.039 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:27.039Z,1406870307.039 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:27.041Z,1406870307.041 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:27.041Z,1406870307.041 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:27.041Z,1406870307.041 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:27.456Z,1406870307.456 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:27.456Z,1406870307.456 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:27.456Z,1406870307.456 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:27.456Z,1406870307.456 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:27.457Z,1406870307.457 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:27.871Z,1406870307.871 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:27.872Z,1406870307.872 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:27.872Z,1406870307.872 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:27.873Z,1406870307.873 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:27.873Z,1406870307.873 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:27.873Z,1406870307.873 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:28.313Z,1406870308.313 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:28.314Z,1406870308.314 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:28.314Z,1406870308.314 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:28.314Z,1406870308.314 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:28.314Z,1406870308.314 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:28.805Z,1406870308.805 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:28.805Z,1406870308.805 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:28.805Z,1406870308.805 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:28.806Z,1406870308.806 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:28.806Z,1406870308.806 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:28.806Z,1406870308.806 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:29.255Z,1406870309.255 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:29.256Z,1406870309.256 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:29.256Z,1406870309.256 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:29.256Z,1406870309.256 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:29.256Z,1406870309.256 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:29.682Z,1406870309.682 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:29.682Z,1406870309.682 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:29.682Z,1406870309.682 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:29.683Z,1406870309.683 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:29.683Z,1406870309.683 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:29.684Z,1406870309.684 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:30.127Z,1406870310.127 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:30.127Z,1406870310.127 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:30.127Z,1406870310.127 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:30.127Z,1406870310.127 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:30.127Z,1406870310.127 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:30.552Z,1406870310.552 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:30.552Z,1406870310.552 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:30.552Z,1406870310.552 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:30.554Z,1406870310.554 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:30.570Z,1406870310.570 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:30.570Z,1406870310.570 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:30.987Z,1406870310.987 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:30.987Z,1406870310.987 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:30.987Z,1406870310.987 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:30.988Z,1406870310.988 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:30.988Z,1406870310.988 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:31.435Z,1406870311.435 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:31.435Z,1406870311.435 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:31.435Z,1406870311.435 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:31.436Z,1406870311.436 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:31.436Z,1406870311.436 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:31.437Z,1406870311.437 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:31.880Z,1406870311.880 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:31.880Z,1406870311.880 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:31.881Z,1406870311.881 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:31.881Z,1406870311.881 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:31.881Z,1406870311.881 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:32.432Z,1406870312.432 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:32.432Z,1406870312.432 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:32.432Z,1406870312.432 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:32.433Z,1406870312.433 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:32.434Z,1406870312.434 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:32.434Z,1406870312.434 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:32.851Z,1406870312.851 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:32.851Z,1406870312.851 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:32.851Z,1406870312.851 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:32.851Z,1406870312.851 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:32.851Z,1406870312.851 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:33.405Z,1406870313.405 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:33.405Z,1406870313.405 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:33.405Z,1406870313.405 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:33.407Z,1406870313.407 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:33.407Z,1406870313.407 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:33.407Z,1406870313.407 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:34.115Z,1406870314.115 [DAT](FAULT): DAT uart error: serial timeout
2014-08-01T05:18:34.116Z,1406870314.116 [DAT](INFO): deviceResponse_: 
2014-08-01T05:18:34.116Z,1406870314.116 [DAT] Communications Fault, FailCount= 3
2014-08-01T05:18:34.116Z,1406870314.116 [DAT](ERROR): Communications Fault
2014-08-01T05:18:34.161Z,1406870314.161 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:34.161Z,1406870314.161 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:34.161Z,1406870314.161 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:34.162Z,1406870314.162 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:34.162Z,1406870314.162 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:34.204Z,1406870314.204 [CBIT](ERROR): Communications Fault in component: DAT
2014-08-01T05:18:34.205Z,1406870314.205 [CBIT](CRITICAL): Communications Fault in component: DAT
2014-08-01T05:18:34.579Z,1406870314.579 [DAT](INFO): Powering down
2014-08-01T05:18:34.597Z,1406870314.597 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:18:34.597Z,1406870314.597 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:34.598Z,1406870314.598 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:18:34.599Z,1406870314.599 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:18:34.599Z,1406870314.599 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:18:34.600Z,1406870314.600 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:34.608Z,1406870314.608 [CommandLine](FAULT): Scheduling is paused
2014-08-01T05:18:35.044Z,1406870315.044 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:18:35.044Z,1406870315.044 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:18:35.044Z,1406870315.044 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:18:35.044Z,1406870315.044 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:18:35.045Z,1406870315.045 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:18:35.046Z,1406870315.046 [tracking_on_surface] Stopped
2014-08-01T05:18:35.046Z,1406870315.046 [tracking_on_surface](INFO): Aggregate::uninitialize tracking_on_surface
2014-08-01T05:18:35.046Z,1406870315.046 [tracking_on_surface:A.Pitch] Stopped
2014-08-01T05:18:35.046Z,1406870315.046 [tracking_on_surface:B.] Stopped
2014-08-01T05:18:35.046Z,1406870315.046 [tracking_on_surface:B.](DEBUG): Uninitializing Tracking.
2014-08-01T05:18:35.046Z,1406870315.046 [tracking_on_surface:TestDrive] Stopped
2014-08-01T05:18:35.046Z,1406870315.046 [tracking_on_surface:TestDrive](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive
2014-08-01T05:18:35.046Z,1406870315.046 [tracking_on_surface:TestDrive:C.Wait] Stopped
2014-08-01T05:18:35.047Z,1406870315.047 [tracking_on_surface:TestDrive:C.Wait](DEBUG): Uninitialize Wait Component.
2014-08-01T05:18:35.506Z,1406870315.506 [MissionManager](IMPORTANT): Started mission Default
2014-08-01T05:18:35.506Z,1406870315.506 [Default] Running Loop=1
2014-08-01T05:18:35.506Z,1406870315.506 [Default](INFO): Aggregate::initialize Default
2014-08-01T05:18:35.506Z,1406870315.506 [Default:A.GoToSurface] Running Loop=1
2014-08-01T05:18:35.506Z,1406870315.506 [Default:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-08-01T05:18:35.506Z,1406870315.506 [Default:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-08-01T05:18:35.507Z,1406870315.507 [Default:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-08-01T05:18:35.507Z,1406870315.507 [Default:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-08-01T05:18:35.508Z,1406870315.508 [Default:CheckIn] Running Loop=1
2014-08-01T05:18:35.508Z,1406870315.508 [Default:CheckIn](INFO): Aggregate::initialize Default:CheckIn
2014-08-01T05:18:35.508Z,1406870315.508 [Default:CheckIn:A.SetSpeed] Running Loop=1
2014-08-01T05:18:35.508Z,1406870315.508 [Default:CheckIn:A.SetSpeed](DEBUG): Initialize.
2014-08-01T05:18:35.508Z,1406870315.508 [Default:CheckIn:Read_GPS] Running Loop=1
2014-08-01T05:18:35.509Z,1406870315.509 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-08-01T05:18:35.511Z,1406870315.511 [Default:CheckIn:A.SetSpeed] Running Loop=1
2014-08-01T05:18:35.521Z,1406870315.521 [Default:WaitAtTheSurface] Running Loop=1
2014-08-01T05:18:35.521Z,1406870315.521 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface
2014-08-01T05:18:35.521Z,1406870315.521 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2014-08-01T05:18:35.522Z,1406870315.522 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Initialize.
2014-08-01T05:18:36.006Z,1406870316.006 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2014-08-01T05:20:39.224Z,1406870439.224 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-08-01T05:20:39.224Z,1406870439.224 [DVL_micro] Data Fault, FailCount= 1
2014-08-01T05:20:39.224Z,1406870439.224 [DVL_micro](ERROR): Data Fault
2014-08-01T05:20:39.300Z,1406870439.300 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-08-01T05:20:39.660Z,1406870439.660 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T05:20:40.113Z,1406870440.113 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-08-01T05:20:40.113Z,1406870440.113 [DVL_micro] Hardware Fault, FailCount= 1
2014-08-01T05:20:40.113Z,1406870440.113 [DVL_micro](ERROR): Hardware Fault
2014-08-01T05:20:40.609Z,1406870440.609 [DVL_micro](INFO): Initializing
2014-08-01T05:20:40.673Z,1406870440.673 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-08-01T05:20:40.673Z,1406870440.673 [DVL_micro] No Fault, FailCount= 1
2014-08-01T05:23:34.215Z,1406870614.215 [CBIT](INFO): Clearing failed count for component DAT
2014-08-01T05:23:34.215Z,1406870614.215 [DAT] No Fault, FailCount= 3
2014-08-01T05:23:34.616Z,1406870614.616 [DAT](INFO): Powering up
2014-08-01T05:23:34.616Z,1406870614.616 [DAT](DEBUG): Initializing DAT.
2014-08-01T05:23:35.603Z,1406870615.603 [Default:CheckIn:Read_GPS](INFO): Timed out from 2014-08-01T05:18:35.5Z
2014-08-01T05:23:35.603Z,1406870615.603 [Default:CheckIn:Read_GPS] Stopped
2014-08-01T05:23:35.603Z,1406870615.603 [Default:CheckIn:Read_Iridium] Running Loop=1
2014-08-01T05:23:36.019Z,1406870616.019 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-08-01T05:23:45.977Z,1406870625.977 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-08-01T05:23:45.977Z,1406870625.977 [DVL_micro] Data Fault, FailCount= 1
2014-08-01T05:23:45.977Z,1406870625.977 [DVL_micro](ERROR): Data Fault
2014-08-01T05:23:46.057Z,1406870626.057 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-08-01T05:23:46.438Z,1406870626.438 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T05:23:46.874Z,1406870626.874 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-08-01T05:23:46.874Z,1406870626.874 [DVL_micro] Hardware Fault, FailCount= 1
2014-08-01T05:23:46.874Z,1406870626.874 [DVL_micro](ERROR): Hardware Fault
2014-08-01T05:23:47.304Z,1406870627.304 [DVL_micro](INFO): Initializing
2014-08-01T05:23:47.383Z,1406870627.383 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-08-01T05:23:47.383Z,1406870627.383 [DVL_micro] No Fault, FailCount= 1
2014-08-01T05:23:54.625Z,1406870634.625 [DAT](INFO): Powering down
2014-08-01T05:24:28.533Z,1406870668.533 [NAL9602](FAULT): GPS failed to acquire within timeout.
2014-08-01T05:24:28.533Z,1406870668.533 [NAL9602] Data Fault, FailCount= 1
2014-08-01T05:24:28.533Z,1406870668.533 [NAL9602](ERROR): Data Fault
2014-08-01T05:24:28.602Z,1406870668.602 [CBIT](ERROR): Data Fault in component: NAL9602
2014-08-01T05:24:29.009Z,1406870669.009 [NAL9602](INFO): Powering down
2014-08-01T05:24:29.886Z,1406870669.886 [CBIT](INFO): Clearing failed state for component NAL9602
2014-08-01T05:24:29.886Z,1406870669.886 [NAL9602] No Fault, FailCount= 1
2014-08-01T05:24:34.108Z,1406870674.108 [NAL9602](INFO): Powering up NAL9602
2014-08-01T05:24:44.851Z,1406870684.851 [NAL9602](INFO): NAL9602 initialized
2014-08-01T05:25:22.920Z,1406870722.920 [CommandLine](IMPORTANT): got command restart application
2014-08-01T05:25:23.926Z,1406870723.926 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:25:23.926Z,1406870723.926 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:23.935Z,1406870723.935 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2014-08-01T05:25:23.935Z,1406870723.935 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:23.936Z,1406870723.936 [CommandLine](INFO): Join timeout helper Thread ID is 1659
2014-08-01T05:25:23.936Z,1406870723.936 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2014-08-01T05:25:23.936Z,1406870723.936 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:23.937Z,1406870723.937 [NavChartDb](INFO): Join timeout helper Thread ID is 1660
2014-08-01T05:25:24.083Z,1406870724.083 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:25:24.084Z,1406870724.084 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:24.095Z,1406870724.095 [ComponentRegistry](INFO): Shutting down Radio_Freewave ThreadHandler
2014-08-01T05:25:24.095Z,1406870724.095 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:24.096Z,1406870724.096 [Radio_Freewave](INFO): Join timeout helper Thread ID is 1661
2014-08-01T05:25:24.288Z,1406870724.288 [Radio_Freewave ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:25:24.385Z,1406870724.385 [Radio_Freewave](INFO): Powering down
2014-08-01T05:25:24.788Z,1406870724.788 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:24.800Z,1406870724.800 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2014-08-01T05:25:24.800Z,1406870724.800 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:24.801Z,1406870724.801 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1663
2014-08-01T05:25:25.009Z,1406870725.009 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:25:25.009Z,1406870725.009 [WetLabsBB2FL](INFO): Powering down
2014-08-01T05:25:25.010Z,1406870725.010 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:25.021Z,1406870725.021 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2014-08-01T05:25:25.021Z,1406870725.021 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:25.021Z,1406870725.021 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1664
2014-08-01T05:25:25.237Z,1406870725.237 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:25:25.237Z,1406870725.237 [CTD_NeilBrown](INFO): Powering down
2014-08-01T05:25:25.238Z,1406870725.238 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:25.246Z,1406870725.246 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2014-08-01T05:25:25.246Z,1406870725.246 [logger ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:25.247Z,1406870725.247 [logger](INFO): Join timeout helper Thread ID is 1665
2014-08-01T05:25:25.261Z,1406870725.261 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:25:25.261Z,1406870725.261 [logger ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:25.266Z,1406870725.266 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2014-08-01T05:25:25.266Z,1406870725.266 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:25.266Z,1406870725.266 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2014-08-01T05:25:25.266Z,1406870725.266 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:25.267Z,1406870725.267 [controlThread](INFO): Join timeout helper Thread ID is 1666
2014-08-01T05:25:25.384Z,1406870725.384 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:25:25.384Z,1406870725.384 [controlThread](DEBUG): Uninitializing ControlThread
2014-08-01T05:25:25.385Z,1406870725.385 [AHRS_sp3003D](INFO): Powering down
2014-08-01T05:25:25.386Z,1406870725.386 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T05:25:25.387Z,1406870725.387 [NAL9602](INFO): Powering down
2014-08-01T05:25:25.388Z,1406870725.388 [DAT](INFO): Powering down
2014-08-01T05:25:25.390Z,1406870725.390 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-08-01T05:25:25.393Z,1406870725.393 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2014-08-01T05:25:25.394Z,1406870725.394 [Default] Stopped
2014-08-01T05:25:25.394Z,1406870725.394 [Default](INFO): Aggregate::uninitialize Default
2014-08-01T05:25:25.394Z,1406870725.394 [Default:A.GoToSurface] Stopped
2014-08-01T05:25:25.394Z,1406870725.394 [Default:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-08-01T05:25:25.394Z,1406870725.394 [Default:CheckIn] Stopped
2014-08-01T05:25:25.394Z,1406870725.394 [Default:CheckIn](INFO): Aggregate::uninitialize Default:CheckIn
2014-08-01T05:25:25.394Z,1406870725.394 [Default:CheckIn:A.SetSpeed] Stopped
2014-08-01T05:25:25.394Z,1406870725.394 [Default:CheckIn:A.SetSpeed](DEBUG): Uninitialize.
2014-08-01T05:25:25.394Z,1406870725.394 [Default:CheckIn:Read_Iridium] Stopped
2014-08-01T05:25:25.395Z,1406870725.395 [Default:WaitAtTheSurface] Stopped
2014-08-01T05:25:25.395Z,1406870725.395 [Default:WaitAtTheSurface](INFO): Aggregate::uninitialize Default:WaitAtTheSurface
2014-08-01T05:25:25.395Z,1406870725.395 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Stopped
2014-08-01T05:25:25.395Z,1406870725.395 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Uninitialize.
2014-08-01T05:25:25.398Z,1406870725.398 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2014-08-01T05:25:25.398Z,1406870725.398 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2014-08-01T05:25:25.399Z,1406870725.399 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2014-08-01T05:25:25.399Z,1406870725.399 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2014-08-01T05:25:25.399Z,1406870725.399 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-08-01T05:25:25.400Z,1406870725.400 [BuoyancyServo](INFO): Powering down
2014-08-01T05:25:25.413Z,1406870725.413 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2014-08-01T05:25:25.413Z,1406870725.413 [ElevatorServo](INFO): Powering down
2014-08-01T05:25:25.414Z,1406870725.414 [MassServo](DEBUG): Uninitialize Mass Servo.
2014-08-01T05:25:25.414Z,1406870725.414 [MassServo](INFO): Powering down
2014-08-01T05:25:25.415Z,1406870725.415 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2014-08-01T05:25:25.416Z,1406870725.416 [RudderServo](INFO): Powering down
2014-08-01T05:25:25.416Z,1406870725.416 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2014-08-01T05:25:25.417Z,1406870725.417 [ThrusterServo](INFO): Powering down
2014-08-01T05:25:25.417Z,1406870725.417 [SBIT](DEBUG): Uninitialize SBIT Component.
2014-08-01T05:25:25.418Z,1406870725.418 [IBIT](DEBUG): Uninitialize IBIT Component.
2014-08-01T05:25:25.418Z,1406870725.418 [CBIT](DEBUG): Uninitialize CBIT Component.
2014-08-01T05:25:25.462Z,1406870725.462 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:25.532Z,1406870725.532 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:25.536Z,1406870725.536 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:25.551Z,1406870725.551 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:25.604Z,1406870725.604 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:25:25.641Z,1406870725.641 [logger ThreadHandler](INFO): Thread cancelled.