2014-08-01T05:01:01.498Z,1406869261.498 [Supervisor](DEBUG): Initializing supervisor.
2014-08-01T05:01:01.501Z,1406869261.501 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-08-01T05:01:01.502Z,1406869261.502 [SyncHandler](INFO): Protected caller Thread ID is 1165
2014-08-01T05:01:01.502Z,1406869261.502 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-08-01T05:01:01.503Z,1406869261.503 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2014-08-01T05:01:01.503Z,1406869261.503 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1166
2014-08-01T05:01:01.506Z,1406869261.506 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-08-01T05:01:01.518Z,1406869261.518 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-08-01T05:01:01.519Z,1406869261.519 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2014-08-01T05:01:01.519Z,1406869261.519 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1167
2014-08-01T05:01:01.520Z,1406869261.520 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-08-01T05:01:01.521Z,1406869261.521 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2014-08-01T05:01:01.522Z,1406869261.522 [logger ThreadHandler](INFO): Protected caller Thread ID is 1168
2014-08-01T05:01:01.524Z,1406869261.524 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-08-01T05:01:01.524Z,1406869261.524 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-08-01T05:01:01.526Z,1406869261.526 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-08-01T05:01:01.860Z,1406869261.860 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-08-01T05:01:01.861Z,1406869261.861 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-08-01T05:01:02.017Z,1406869262.017 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-08-01T05:01:02.018Z,1406869262.018 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-08-01T05:01:02.124Z,1406869262.124 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-08-01T05:01:02.125Z,1406869262.125 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-08-01T05:01:02.246Z,1406869262.246 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-08-01T05:01:02.247Z,1406869262.247 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-08-01T05:01:02.332Z,1406869262.332 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-08-01T05:01:02.466Z,1406869262.466 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-08-01T05:01:02.467Z,1406869262.467 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-08-01T05:01:02.551Z,1406869262.551 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-08-01T05:01:02.552Z,1406869262.552 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-08-01T05:01:02.730Z,1406869262.730 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-08-01T05:01:02.731Z,1406869262.731 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-08-01T05:01:03.021Z,1406869263.021 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-08-01T05:01:03.021Z,1406869263.021 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-08-01T05:01:03.326Z,1406869263.326 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-08-01T05:01:03.326Z,1406869263.326 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-08-01T05:01:03.826Z,1406869263.826 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-08-01T05:01:03.826Z,1406869263.826 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-08-01T05:01:04.014Z,1406869264.014 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-08-01T05:01:04.014Z,1406869264.014 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-08-01T05:01:04.116Z,1406869264.116 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-08-01T05:01:04.117Z,1406869264.117 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-08-01T05:01:04.514Z,1406869264.514 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-08-01T05:01:04.515Z,1406869264.515 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-08-01T05:01:04.623Z,1406869264.623 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-08-01T05:01:04.625Z,1406869264.625 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-08-01T05:01:04.626Z,1406869264.626 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-08-01T05:01:04.729Z,1406869264.729 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-08-01T05:01:04.845Z,1406869264.845 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-08-01T05:01:04.953Z,1406869264.953 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-08-01T05:01:05.049Z,1406869265.049 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-08-01T05:01:05.175Z,1406869265.175 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-08-01T05:01:05.319Z,1406869265.319 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-08-01T05:01:05.419Z,1406869265.419 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-08-01T05:01:05.504Z,1406869265.504 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-08-01T05:01:05.595Z,1406869265.595 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-08-01T05:01:05.690Z,1406869265.690 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-08-01T05:01:05.799Z,1406869265.799 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-08-01T05:01:05.892Z,1406869265.892 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2014-08-01T05:01:05.894Z,1406869265.894 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-08-01T05:01:05.944Z,1406869265.944 [VerticalControl](DEBUG): Construct VerticalControl.
2014-08-01T05:01:06.064Z,1406869266.064 [VerticalControl] Loaded
2014-08-01T05:01:06.065Z,1406869266.065 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-08-01T05:01:06.065Z,1406869266.065 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-08-01T05:01:06.174Z,1406869266.174 [HorizontalControl] Loaded
2014-08-01T05:01:06.175Z,1406869266.175 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-08-01T05:01:06.175Z,1406869266.175 [SpeedControl](DEBUG): Construct SpeedControl.
2014-08-01T05:01:06.181Z,1406869266.181 [SpeedControl] Loaded
2014-08-01T05:01:06.181Z,1406869266.181 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-08-01T05:01:06.182Z,1406869266.182 [LoopControl](DEBUG): Construct LoopControl.
2014-08-01T05:01:06.183Z,1406869266.183 [LoopControl] Loaded
2014-08-01T05:01:06.183Z,1406869266.183 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-08-01T05:01:06.183Z,1406869266.183 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-08-01T05:01:06.184Z,1406869266.184 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-08-01T05:01:06.281Z,1406869266.281 [SBIT](DEBUG): Construct Startup Built In Test.
2014-08-01T05:01:06.293Z,1406869266.293 [SBIT] Loaded
2014-08-01T05:01:06.293Z,1406869266.293 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-08-01T05:01:06.294Z,1406869266.294 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-08-01T05:01:06.324Z,1406869266.324 [IBIT] Loaded
2014-08-01T05:01:06.324Z,1406869266.324 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-08-01T05:01:06.326Z,1406869266.326 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-08-01T05:01:06.445Z,1406869266.445 [CBIT] Loaded
2014-08-01T05:01:06.445Z,1406869266.445 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-08-01T05:01:06.446Z,1406869266.446 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-08-01T05:01:06.446Z,1406869266.446 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-08-01T05:01:06.465Z,1406869266.465 [DepthRateCalculator] Loaded
2014-08-01T05:01:06.465Z,1406869266.465 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-08-01T05:01:06.471Z,1406869266.471 [PitchRateCalculator] Loaded
2014-08-01T05:01:06.471Z,1406869266.471 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-08-01T05:01:06.483Z,1406869266.483 [SpeedCalculator] Loaded
2014-08-01T05:01:06.483Z,1406869266.483 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-08-01T05:01:06.500Z,1406869266.500 [TempGradientCalculator] Loaded
2014-08-01T05:01:06.500Z,1406869266.500 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-08-01T05:01:06.505Z,1406869266.505 [YawRateCalculator] Loaded
2014-08-01T05:01:06.506Z,1406869266.506 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-08-01T05:01:06.506Z,1406869266.506 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-08-01T05:01:06.507Z,1406869266.507 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-08-01T05:01:11.579Z,1406869271.579 [HFRadarModelCalc] Loaded
2014-08-01T05:01:11.580Z,1406869271.580 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2014-08-01T05:01:15.667Z,1406869275.667 [HFRadarCompactModelForecaster] Loaded
2014-08-01T05:01:15.667Z,1406869275.667 [ComponentRegistry](DEBUG): SyncComponent "HFRadarCompactModelForecaster" handled in the control thread.
2014-08-01T05:01:16.800Z,1406869276.800 [HFRCMSpaceInterpolator] Loaded
2014-08-01T05:01:16.800Z,1406869276.800 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSpaceInterpolator" handled in the control thread.
2014-08-01T05:01:16.803Z,1406869276.803 [HFRCMTimeInterpolator] Loaded
2014-08-01T05:01:16.803Z,1406869276.803 [ComponentRegistry](DEBUG): SyncComponent "HFRCMTimeInterpolator" handled in the control thread.
2014-08-01T05:01:17.908Z,1406869277.908 [HFRCMReconstructedInterpolator] Loaded
2014-08-01T05:01:17.908Z,1406869277.908 [ComponentRegistry](DEBUG): SyncComponent "HFRCMReconstructedInterpolator" handled in the control thread.
2014-08-01T05:01:17.920Z,1406869277.920 [HFRCMSurfaceCurrentAtVehicleLocation] Loaded
2014-08-01T05:01:17.920Z,1406869277.920 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSurfaceCurrentAtVehicleLocation" handled in the control thread.
2014-08-01T05:01:17.947Z,1406869277.947 [HFRCMVirtualSurfaceDrifter] Loaded
2014-08-01T05:01:17.948Z,1406869277.948 [ComponentRegistry](DEBUG): SyncComponent "HFRCMVirtualSurfaceDrifter" handled in the control thread.
2014-08-01T05:01:17.948Z,1406869277.948 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-08-01T05:01:17.949Z,1406869277.949 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-08-01T05:01:18.184Z,1406869278.184 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-08-01T05:01:18.185Z,1406869278.185 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-08-01T05:01:18.267Z,1406869278.267 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-08-01T05:01:18.267Z,1406869278.267 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-08-01T05:01:18.313Z,1406869278.313 [DeadReckonWithRespectToWater] Loaded
2014-08-01T05:01:18.313Z,1406869278.313 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToWater" handled in the control thread.
2014-08-01T05:01:18.361Z,1406869278.361 [DeadReckonWithRespectToSeafloor] Loaded
2014-08-01T05:01:18.361Z,1406869278.361 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2014-08-01T05:01:18.421Z,1406869278.421 [DeadReckonUsingDVLWaterTrack] Loaded
2014-08-01T05:01:18.422Z,1406869278.422 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingDVLWaterTrack" handled in the control thread.
2014-08-01T05:01:18.470Z,1406869278.470 [DeadReckonUsingCompactModelForecast] Loaded
2014-08-01T05:01:18.470Z,1406869278.470 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingCompactModelForecast" handled in the control thread.
2014-08-01T05:01:18.487Z,1406869278.487 [NavChart] Loaded
2014-08-01T05:01:18.488Z,1406869278.488 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-08-01T05:01:18.492Z,1406869278.492 [UniversalFixResidualReporter] Loaded
2014-08-01T05:01:18.492Z,1406869278.492 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-08-01T05:01:18.493Z,1406869278.493 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-08-01T05:01:18.494Z,1406869278.494 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-08-01T05:01:18.499Z,1406869278.499 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-08-01T05:01:18.500Z,1406869278.500 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-08-01T05:01:18.676Z,1406869278.676 [CTD_NeilBrown] Loaded
2014-08-01T05:01:18.677Z,1406869278.677 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-08-01T05:01:18.678Z,1406869278.678 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407B94E0
2014-08-01T05:01:18.678Z,1406869278.678 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1250
2014-08-01T05:01:18.694Z,1406869278.694 [PAR_Licor] Loaded
2014-08-01T05:01:18.694Z,1406869278.694 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-08-01T05:01:18.730Z,1406869278.730 [WetLabsBB2FL] Loaded
2014-08-01T05:01:18.730Z,1406869278.730 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-08-01T05:01:18.732Z,1406869278.732 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407E94E0
2014-08-01T05:01:18.732Z,1406869278.732 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1251
2014-08-01T05:01:18.732Z,1406869278.732 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-08-01T05:01:18.733Z,1406869278.733 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-08-01T05:01:19.014Z,1406869279.014 [AHRS_sp3003D] Loaded
2014-08-01T05:01:19.014Z,1406869279.014 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-08-01T05:01:19.283Z,1406869279.283 [Batt_Ocean_Server] Loaded
2014-08-01T05:01:19.283Z,1406869279.283 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-08-01T05:01:19.297Z,1406869279.297 [Depth_Keller] Loaded
2014-08-01T05:01:19.297Z,1406869279.297 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-08-01T05:01:19.302Z,1406869279.302 [DropWeight] Loaded
2014-08-01T05:01:19.303Z,1406869279.303 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-08-01T05:01:19.437Z,1406869279.437 [DVL_micro] Loaded
2014-08-01T05:01:19.437Z,1406869279.437 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2014-08-01T05:01:19.534Z,1406869279.534 [NAL9602] Loaded
2014-08-01T05:01:19.534Z,1406869279.534 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-08-01T05:01:19.577Z,1406869279.577 [Onboard] Loaded
2014-08-01T05:01:19.577Z,1406869279.577 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-08-01T05:01:19.584Z,1406869279.584 [Radio_Freewave] Loaded
2014-08-01T05:01:19.584Z,1406869279.584 [ComponentRegistry](DEBUG): Component "Radio_Freewave" handled in its own thread.
2014-08-01T05:01:19.586Z,1406869279.586 [Radio_Freewave ThreadHandler](DEBUG): Created PCaller Thread at 40A1E4E0
2014-08-01T05:01:19.586Z,1406869279.586 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 1252
2014-08-01T05:01:19.716Z,1406869279.716 [DAT] Loaded
2014-08-01T05:01:19.717Z,1406869279.717 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2014-08-01T05:01:19.723Z,1406869279.723 [SCPI] Loaded
2014-08-01T05:01:19.724Z,1406869279.724 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-08-01T05:01:20.045Z,1406869280.045 [BPC1] Loaded
2014-08-01T05:01:20.046Z,1406869280.046 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2014-08-01T05:01:20.046Z,1406869280.046 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-08-01T05:01:20.047Z,1406869280.047 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-08-01T05:01:20.146Z,1406869280.146 [BuoyancyServo] Loaded
2014-08-01T05:01:20.147Z,1406869280.147 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-08-01T05:01:20.159Z,1406869280.159 [ElevatorServo] Loaded
2014-08-01T05:01:20.159Z,1406869280.159 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-08-01T05:01:20.171Z,1406869280.171 [MassServo] Loaded
2014-08-01T05:01:20.172Z,1406869280.172 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-08-01T05:01:20.183Z,1406869280.183 [RudderServo] Loaded
2014-08-01T05:01:20.184Z,1406869280.184 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-08-01T05:01:20.195Z,1406869280.195 [ThrusterServo] Loaded
2014-08-01T05:01:20.196Z,1406869280.196 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-08-01T05:01:20.196Z,1406869280.196 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-08-01T05:01:20.197Z,1406869280.197 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-08-01T05:01:20.355Z,1406869280.355 [InternalSim] Loaded
2014-08-01T05:01:20.355Z,1406869280.355 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-08-01T05:01:20.356Z,1406869280.356 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-08-01T05:01:20.357Z,1406869280.357 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-08-01T05:01:20.381Z,1406869280.381 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-08-01T05:01:20.383Z,1406869280.383 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-08-01T05:01:20.384Z,1406869280.384 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-08-01T05:01:20.391Z,1406869280.391 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-08-01T05:01:20.392Z,1406869280.392 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ACF4E0
2014-08-01T05:01:20.392Z,1406869280.392 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1253
2014-08-01T05:01:20.397Z,1406869280.397 [Supervisor](INFO): Main Thread ID is 977
2014-08-01T05:01:20.397Z,1406869280.397 [Supervisor](DEBUG): Running supervisor.
2014-08-01T05:01:20.398Z,1406869280.398 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1254
2014-08-01T05:01:20.402Z,1406869280.402 [controlThread ThreadHandler](INFO): Handler Thread ID is 1255
2014-08-01T05:01:20.402Z,1406869280.402 [controlThread](DEBUG): Initializing ControlThread
2014-08-01T05:01:20.403Z,1406869280.403 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-08-01T05:01:20.405Z,1406869280.405 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-08-01T05:01:20.406Z,1406869280.406 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-08-01T05:01:20.406Z,1406869280.406 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-08-01T05:01:20.406Z,1406869280.406 [SBIT](INFO): Initialize SBIT Component.
2014-08-01T05:01:20.407Z,1406869280.407 [SBIT](IMPORTANT): Tethys CM Info: SVN revision: 11462
2014-08-01T05:01:20.407Z,1406869280.407 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2014-08-01T05:01:20.408Z,1406869280.408 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-08-01T05:01:20.408Z,1406869280.408 [IBIT](INFO): Initialize IBIT Component.
2014-08-01T05:01:20.409Z,1406869280.409 [CBIT](DEBUG): Initialize CBIT Component.
2014-08-01T05:01:20.409Z,1406869280.409 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2014-08-01T05:01:20.410Z,1406869280.410 [logger ThreadHandler](INFO): Handler Thread ID is 1256
2014-08-01T05:01:20.429Z,1406869280.429 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1257
2014-08-01T05:01:20.430Z,1406869280.430 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-08-01T05:01:20.433Z,1406869280.433 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-08-01T05:01:20.433Z,1406869280.433 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-08-01T05:01:20.434Z,1406869280.434 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-08-01T05:01:20.434Z,1406869280.434 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-08-01T05:01:20.435Z,1406869280.435 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-08-01T05:01:20.442Z,1406869280.442 [HFRadarCompactModelForecaster](DEBUG): Found new ECs!
2014-08-01T05:01:20.453Z,1406869280.453 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-08-01T05:01:20.463Z,1406869280.463 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1259
2014-08-01T05:01:20.464Z,1406869280.464 [WetLabsBB2FL](INFO): Powering down
2014-08-01T05:01:20.496Z,1406869280.496 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 1260
2014-08-01T05:01:20.514Z,1406869280.514 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1261
2014-08-01T05:01:20.516Z,1406869280.516 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-08-01T05:01:20.517Z,1406869280.517 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-08-01T05:01:20.518Z,1406869280.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-08-01T05:01:20.518Z,1406869280.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-08-01T05:01:20.518Z,1406869280.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-08-01T05:01:20.518Z,1406869280.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-08-01T05:01:20.518Z,1406869280.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-08-01T05:01:20.519Z,1406869280.519 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-08-01T05:01:20.519Z,1406869280.519 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-08-01T05:01:29.409Z,1406869289.409 [HFRadarCompactModelForecaster](IMPORTANT): forecast time 201408010200: published 50 modes in rows, 61 hours in columns
2014-08-01T05:01:29.413Z,1406869289.413 [HFRadarCompactModelForecaster](IMPORTANT): expansionCoefficients_[0][48] = -9.214992 for 2014-08-01T02:00:00.000Z
2014-08-01T05:01:29.413Z,1406869289.413 [HFRCMSpaceInterpolator](DEBUG): Initializing HFRCMSpaceInterpolator component with verbosity level 0.
2014-08-01T05:01:29.415Z,1406869289.415 [HFRCMTimeInterpolator](DEBUG): Initializing HFRCMTimeInterpolator component.
2014-08-01T05:01:29.415Z,1406869289.415 [HFRCMReconstructedInterpolator](INFO): Initializing HFRCMReconstructedInterpolator component with velocityAccuracy_ = 0.300000 m/s.
2014-08-01T05:01:29.417Z,1406869289.417 [HFRCMSurfaceCurrentAtVehicleLocation](DEBUG): Initializing HFRCMSurfaceCurrentAtVehicleLocation component.
2014-08-01T05:01:29.417Z,1406869289.417 [HFRCMVirtualSurfaceDrifter](DEBUG): Initializing HFRCMVirtualSurfaceDrifter component.
2014-08-01T05:01:29.418Z,1406869289.418 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-08-01T05:01:29.418Z,1406869289.418 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component.
2014-08-01T05:01:29.418Z,1406869289.418 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component.
2014-08-01T05:01:29.435Z,1406869289.435 [DeadReckonUsingDVLWaterTrack](DEBUG): Initializing DeadReckonUsingDVLWaterTrack component.
2014-08-01T05:01:29.435Z,1406869289.435 [DeadReckonUsingCompactModelForecast](DEBUG): Initializing DeadReckonUsingCompactModelForecast component.
2014-08-01T05:01:29.436Z,1406869289.436 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-08-01T05:01:29.436Z,1406869289.436 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-08-01T05:01:31.121Z,1406869291.121 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-08-01T05:01:31.154Z,1406869291.154 [InternalSim](DEBUG):  InternalSim initializing...
2014-08-01T05:01:31.256Z,1406869291.256 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-08-01T05:01:31.283Z,1406869291.283 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-08-01T05:01:31.312Z,1406869291.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:01:31.313Z,1406869291.313 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-08-01T05:01:31.412Z,1406869291.412 [Default:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-08-01T05:01:31.478Z,1406869291.478 [Default:CheckIn:A.SetSpeed](DEBUG): Construct.
2014-08-01T05:01:31.485Z,1406869291.485 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-08-01T05:01:31.512Z,1406869291.512 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-08-01T05:01:31.536Z,1406869291.536 [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:01:31.544Z,1406869291.544 [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:01:31.647Z,1406869291.647 [Radio_Freewave](INFO): Powering up
2014-08-01T05:01:31.674Z,1406869291.674 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-08-01T05:01:31.870Z,1406869291.870 [DVL_micro](INFO): Initializing
2014-08-01T05:01:31.902Z,1406869291.902 [NAL9602](INFO): Powering up NAL9602
2014-08-01T05:01:31.955Z,1406869291.955 [DAT](INFO): Powering up
2014-08-01T05:01:31.955Z,1406869291.955 [DAT](DEBUG): Initializing DAT.
2014-08-01T05:01:31.986Z,1406869291.986 [BPC1](DEBUG): Initializing BPC1.
2014-08-01T05:01:32.453Z,1406869292.453 [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:01:39.655Z,1406869299.655 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-08-01T05:01:39.663Z,1406869299.663 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-08-01T05:01:39.681Z,1406869299.681 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-08-01T05:01:39.683Z,1406869299.683 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-08-01T05:01:39.689Z,1406869299.689 [MassServo](DEBUG): Initializing EZServoServo.
2014-08-01T05:01:39.695Z,1406869299.695 [MassServo](DEBUG): Initializing MassServo.
2014-08-01T05:01:39.701Z,1406869299.701 [RudderServo](DEBUG): Initializing EZServoServo.
2014-08-01T05:01:39.707Z,1406869299.707 [RudderServo](DEBUG): Initializing RudderServo.
2014-08-01T05:01:39.712Z,1406869299.712 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-08-01T05:01:39.743Z,1406869299.743 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-08-01T05:01:40.436Z,1406869300.436 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2014-08-01T05:01:40.436Z,1406869300.436 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2014-08-01T05:01:40.436Z,1406869300.436 [AHRS_sp3003D] Hardware Fault, FailCount= 1
2014-08-01T05:01:40.436Z,1406869300.436 [AHRS_sp3003D](ERROR): Hardware Fault
2014-08-01T05:01:41.046Z,1406869301.046 [SBIT](IMPORTANT): Beginning Startup BIT
2014-08-01T05:01:41.049Z,1406869301.049 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2014-08-01T05:01:41.049Z,1406869301.049 [CBIT](IMPORTANT): Beginning GF scan
2014-08-01T05:01:41.142Z,1406869301.142 [AHRS_sp3003D](INFO): Powering down
2014-08-01T05:01:42.740Z,1406869302.740 [NAL9602](INFO): NAL9602 initialized
2014-08-01T05:01:42.832Z,1406869302.832 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2014-08-01T05:01:42.832Z,1406869302.832 [AHRS_sp3003D] No Fault, FailCount= 1
2014-08-01T05:01:43.081Z,1406869303.081 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-08-01T05:01:44.262Z,1406869304.262 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2014-08-01T05:01:44.262Z,1406869304.262 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2014-08-01T05:01:44.262Z,1406869304.262 [AHRS_sp3003D] Hardware Fault, FailCount= 2
2014-08-01T05:01:44.262Z,1406869304.262 [AHRS_sp3003D](ERROR): Hardware Fault
2014-08-01T05:01:44.727Z,1406869304.727 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2014-08-01T05:01:44.796Z,1406869304.796 [AHRS_sp3003D](INFO): Powering down
2014-08-01T05:01:46.785Z,1406869306.785 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2014-08-01T05:01:46.785Z,1406869306.785 [AHRS_sp3003D] No Fault, FailCount= 2
2014-08-01T05:01:46.811Z,1406869306.811 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-08-01T05:01:46.886Z,1406869306.886 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:01:47.967Z,1406869307.967 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2014-08-01T05:01:47.968Z,1406869307.968 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2014-08-01T05:01:47.968Z,1406869307.968 [AHRS_sp3003D] Hardware Fault, FailCount= 3
2014-08-01T05:01:47.968Z,1406869307.968 [AHRS_sp3003D](ERROR): Hardware Fault
2014-08-01T05:01:48.148Z,1406869308.148 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2014-08-01T05:01:48.165Z,1406869308.165 [AHRS_sp3003D](INFO): Powering down
2014-08-01T05:01:49.406Z,1406869309.406 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:01:49.658Z,1406869309.658 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2014-08-01T05:01:49.658Z,1406869309.658 [AHRS_sp3003D] No Fault, FailCount= 3
2014-08-01T05:01:49.767Z,1406869309.767 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-08-01T05:01:51.116Z,1406869311.116 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2014-08-01T05:01:51.117Z,1406869311.117 [AHRS_sp3003D](ERROR): readHeadingMagBin got 0xA409A0
2014-08-01T05:01:51.117Z,1406869311.117 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2014-08-01T05:01:51.117Z,1406869311.117 [AHRS_sp3003D] Hardware Fault, FailCount= 4
2014-08-01T05:01:51.117Z,1406869311.117 [AHRS_sp3003D](ERROR): Hardware Fault
2014-08-01T05:01:51.351Z,1406869311.351 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2014-08-01T05:01:51.402Z,1406869311.402 [AHRS_sp3003D](INFO): Powering down
2014-08-01T05:01:51.462Z,1406869311.462 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:01:51.893Z,1406869311.893 [DAT](INFO): Powering down
2014-08-01T05:01:53.143Z,1406869313.143 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2014-08-01T05:01:53.143Z,1406869313.143 [AHRS_sp3003D] No Fault, FailCount= 4
2014-08-01T05:01:53.373Z,1406869313.373 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-08-01T05:01:54.526Z,1406869314.526 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2014-08-01T05:01:54.526Z,1406869314.526 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2014-08-01T05:01:54.526Z,1406869314.526 [AHRS_sp3003D] Hardware Fault, FailCount= 5
2014-08-01T05:01:54.526Z,1406869314.526 [AHRS_sp3003D](ERROR): Hardware Fault
2014-08-01T05:01:54.575Z,1406869314.575 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:01:54.733Z,1406869314.733 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2014-08-01T05:01:54.733Z,1406869314.733 [CBIT](CRITICAL): Hardware Fault in component: AHRS_sp3003D
2014-08-01T05:01:54.795Z,1406869314.795 [AHRS_sp3003D](INFO): Powering down
2014-08-01T05:01:54.894Z,1406869314.894 [CommandLine](FAULT): Scheduling is paused
2014-08-01T05:01:56.395Z,1406869316.395 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:01:59.081Z,1406869319.081 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:02:01.480Z,1406869321.480 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:02:03.600Z,1406869323.600 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:02:06.004Z,1406869326.004 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:02:07.691Z,1406869327.691 [CBIT](IMPORTANT): No ground fault detected
2014-08-01T05:02:08.783Z,1406869328.783 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:02:11.199Z,1406869331.199 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:02:13.597Z,1406869333.597 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:02:15.994Z,1406869335.994 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:02:18.399Z,1406869338.399 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:02:20.798Z,1406869340.798 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-08-01T05:02:34.965Z,1406869354.965 [SBIT](IMPORTANT): SBIT PASSED
2014-08-01T05:02:35.366Z,1406869355.366 [MissionManager](IMPORTANT): Started mission Startup
2014-08-01T05:02:35.367Z,1406869355.367 [Startup] Running Loop=1
2014-08-01T05:02:35.367Z,1406869355.367 [Startup](INFO): Aggregate::initialize Startup
2014-08-01T05:02:35.367Z,1406869355.367 [Startup:A.GoToSurface] Running Loop=1
2014-08-01T05:02:35.367Z,1406869355.367 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-08-01T05:02:35.368Z,1406869355.368 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-08-01T05:02:35.368Z,1406869355.368 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-08-01T05:02:35.368Z,1406869355.368 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-08-01T05:02:35.374Z,1406869355.374 [Startup:StartupSatComms] Running Loop=1
2014-08-01T05:02:35.374Z,1406869355.374 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-08-01T05:02:35.374Z,1406869355.374 [Startup:StartupSatComms:A] Running Loop=1
2014-08-01T05:02:35.765Z,1406869355.765 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-08-01T05:03:33.648Z,1406869413.648 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:03:33.648Z,1406869413.648 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:03:33.690Z,1406869413.690 [MissionManager](INFO): DefineArg tracking_on_surface.MissionTimeout = 10.000000 min
2014-08-01T05:03:33.694Z,1406869413.694 [MissionManager](INFO): DefineArg tracking_on_surface.ContactLabel = 1.000000 count
2014-08-01T05:03:33.717Z,1406869413.717 [MissionManager](INFO): DefineArg tracking_on_surface.TrackingUpdatePeriod = 45.000000 s
2014-08-01T05:03:33.740Z,1406869413.740 [MissionManager](INFO): DefineArg tracking_on_surface.TrackingQueryMode = 0.000000 count
2014-08-01T05:03:33.748Z,1406869413.748 [MissionManager](INFO): DefineArg tracking_on_surface.Repeat = 13.000000 count
2014-08-01T05:03:33.760Z,1406869413.760 [MissionManager](INFO): DefineArg tracking_on_surface.MassDefault = 0.000000 n/a
2014-08-01T05:03:33.761Z,1406869413.761 [tracking_on_surface:A.Pitch](DEBUG): Construct.
2014-08-01T05:03:33.963Z,1406869413.963 [tracking_on_surface:TestDrive:C.Wait](DEBUG): Construct Wait.
2014-08-01T05:03:33.976Z,1406869413.976 [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:03:33.979Z,1406869413.979 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:03:35.758Z,1406869415.758 [Startup:StartupSatComms:A](INFO): Timed out from 2014-08-01T05:02:35.4Z
2014-08-01T05:03:35.758Z,1406869415.758 [Startup:StartupSatComms:A] Stopped
2014-08-01T05:03:35.758Z,1406869415.758 [Startup:StartupSatComms:B] Running Loop=1
2014-08-01T05:03:36.231Z,1406869416.231 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-08-01T05:03:40.704Z,1406869420.704 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:03:40.709Z,1406869420.709 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:03:40.768Z,1406869420.768 [MissionManager](INFO): DefineArg tracking_on_surface.MissionTimeout = 10.000000 min
2014-08-01T05:03:40.770Z,1406869420.770 [MissionManager](INFO): DefineArg tracking_on_surface.ContactLabel = 1.000000 count
2014-08-01T05:03:40.773Z,1406869420.773 [MissionManager](INFO): DefineArg tracking_on_surface.TrackingUpdatePeriod = 45.000000 s
2014-08-01T05:03:40.775Z,1406869420.775 [MissionManager](INFO): DefineArg tracking_on_surface.TrackingQueryMode = 0.000000 count
2014-08-01T05:03:40.777Z,1406869420.777 [MissionManager](INFO): DefineArg tracking_on_surface.Repeat = 13.000000 count
2014-08-01T05:03:40.784Z,1406869420.784 [MissionManager](INFO): DefineArg tracking_on_surface.MassDefault = 0.000000 n/a
2014-08-01T05:03:40.785Z,1406869420.785 [tracking_on_surface:A.Pitch](DEBUG): Construct.
2014-08-01T05:03:40.868Z,1406869420.868 [tracking_on_surface:TestDrive:C.Wait](DEBUG): Construct Wait.
2014-08-01T05:03:40.873Z,1406869420.873 [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:03:40.875Z,1406869420.875 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:03:53.946Z,1406869433.946 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:03:53.951Z,1406869433.951 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:03:53.979Z,1406869433.979 [MissionManager](INFO): DefineArg tracking_on_surface.MissionTimeout = 10.000000 min
2014-08-01T05:03:53.981Z,1406869433.981 [MissionManager](INFO): DefineArg tracking_on_surface.ContactLabel = 1.000000 count
2014-08-01T05:03:53.984Z,1406869433.984 [MissionManager](INFO): DefineArg tracking_on_surface.TrackingUpdatePeriod = 45.000000 s
2014-08-01T05:03:53.986Z,1406869433.986 [MissionManager](INFO): DefineArg tracking_on_surface.TrackingQueryMode = 0.000000 count
2014-08-01T05:03:54.038Z,1406869434.038 [MissionManager](INFO): DefineArg tracking_on_surface.Repeat = 13.000000 count
2014-08-01T05:03:54.044Z,1406869434.044 [MissionManager](INFO): DefineArg tracking_on_surface.MassDefault = 0.000000 n/a
2014-08-01T05:03:54.045Z,1406869434.045 [tracking_on_surface:A.Pitch](DEBUG): Construct.
2014-08-01T05:03:54.122Z,1406869434.122 [tracking_on_surface:TestDrive:C.Wait](DEBUG): Construct Wait.
2014-08-01T05:03:54.143Z,1406869434.143 [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:03:54.149Z,1406869434.149 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/tracking_on_surface.xml
2014-08-01T05:04:36.075Z,1406869476.075 [Startup:StartupSatComms:B](INFO): Timed out from 2014-08-01T05:03:35.8Z
2014-08-01T05:04:36.075Z,1406869476.075 [Startup:StartupSatComms:B] Stopped
2014-08-01T05:04:36.076Z,1406869476.076 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2014-08-01T05:04:36.076Z,1406869476.076 [Startup:StartupSatComms] Stopped
2014-08-01T05:04:36.076Z,1406869476.076 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2014-08-01T05:04:36.077Z,1406869476.077 [Startup](INFO): Completed Startup
2014-08-01T05:04:36.077Z,1406869476.077 [Startup] Stopped
2014-08-01T05:04:36.077Z,1406869476.077 [Startup](INFO): Aggregate::uninitialize Startup
2014-08-01T05:04:36.077Z,1406869476.077 [Startup:A.GoToSurface] Stopped
2014-08-01T05:04:36.077Z,1406869476.077 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-08-01T05:04:36.311Z,1406869476.311 [MissionManager](IMPORTANT): Started mission tracking_on_surface
2014-08-01T05:04:36.311Z,1406869476.311 [tracking_on_surface] Running Loop=1
2014-08-01T05:04:36.311Z,1406869476.311 [tracking_on_surface](INFO): Aggregate::initialize tracking_on_surface
2014-08-01T05:04:36.311Z,1406869476.311 [tracking_on_surface:A.Pitch] Running Loop=1
2014-08-01T05:04:36.311Z,1406869476.311 [tracking_on_surface:A.Pitch](DEBUG): Initialize.
2014-08-01T05:04:36.312Z,1406869476.312 [tracking_on_surface:B.] Running Loop=1
2014-08-01T05:04:36.312Z,1406869476.312 [tracking_on_surface:B.](INFO): Initializing Tracking.
2014-08-01T05:04:36.312Z,1406869476.312 [tracking_on_surface:TestDrive] Running Loop=1
2014-08-01T05:04:36.316Z,1406869476.316 [tracking_on_surface:TestDrive](INFO): Aggregate::initialize tracking_on_surface:TestDrive
2014-08-01T05:04:36.317Z,1406869476.317 [tracking_on_surface:TestDrive:B] Running Loop=1
2014-08-01T05:04:36.318Z,1406869476.318 [tracking_on_surface:TestDrive:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-08-01T05:04:36.319Z,1406869476.319 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:36.319Z,1406869476.319 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:36.319Z,1406869476.319 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:36.335Z,1406869476.335 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:36.335Z,1406869476.335 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:36.335Z,1406869476.335 [tracking_on_surface:B.] Running Loop=1
2014-08-01T05:04:36.336Z,1406869476.336 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:36.349Z,1406869476.349 [tracking_on_surface:A.Pitch] Running Loop=1
2014-08-01T05:04:36.700Z,1406869476.700 [DAT](INFO): Powering up
2014-08-01T05:04:36.737Z,1406869476.737 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:36.737Z,1406869476.737 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:36.737Z,1406869476.737 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:36.737Z,1406869476.737 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:36.737Z,1406869476.737 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:37.125Z,1406869477.125 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:37.126Z,1406869477.126 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:37.126Z,1406869477.126 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:37.127Z,1406869477.127 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:37.127Z,1406869477.127 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:37.127Z,1406869477.127 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:37.527Z,1406869477.527 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:37.527Z,1406869477.527 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:37.527Z,1406869477.527 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:37.527Z,1406869477.527 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:37.527Z,1406869477.527 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:37.924Z,1406869477.924 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:37.924Z,1406869477.924 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:37.925Z,1406869477.925 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:37.926Z,1406869477.926 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:37.926Z,1406869477.926 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:37.926Z,1406869477.926 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:38.344Z,1406869478.344 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:38.344Z,1406869478.344 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:38.344Z,1406869478.344 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:38.345Z,1406869478.345 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:38.345Z,1406869478.345 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:38.723Z,1406869478.723 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:38.724Z,1406869478.724 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:38.724Z,1406869478.724 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:38.729Z,1406869478.729 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:38.729Z,1406869478.729 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:38.729Z,1406869478.729 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:39.132Z,1406869479.132 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:39.132Z,1406869479.132 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:39.132Z,1406869479.132 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:39.132Z,1406869479.132 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:39.132Z,1406869479.132 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:40.030Z,1406869480.030 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:40.030Z,1406869480.030 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:40.030Z,1406869480.030 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:40.032Z,1406869480.032 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:40.032Z,1406869480.032 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:40.032Z,1406869480.032 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:41.196Z,1406869481.196 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:41.196Z,1406869481.196 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:41.196Z,1406869481.196 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:41.196Z,1406869481.196 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:41.196Z,1406869481.196 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:41.385Z,1406869481.385 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:41.386Z,1406869481.386 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:41.386Z,1406869481.386 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:41.387Z,1406869481.387 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:41.387Z,1406869481.387 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:41.387Z,1406869481.387 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:41.736Z,1406869481.736 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:41.736Z,1406869481.736 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:41.736Z,1406869481.736 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:41.737Z,1406869481.737 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:41.737Z,1406869481.737 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:42.084Z,1406869482.084 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:42.084Z,1406869482.084 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:42.084Z,1406869482.084 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:42.085Z,1406869482.085 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:42.085Z,1406869482.085 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:42.085Z,1406869482.085 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:42.489Z,1406869482.489 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:42.489Z,1406869482.489 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:42.489Z,1406869482.489 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:42.489Z,1406869482.489 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:42.489Z,1406869482.489 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:42.895Z,1406869482.895 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:42.896Z,1406869482.896 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:42.896Z,1406869482.896 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:42.897Z,1406869482.897 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:42.897Z,1406869482.897 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:42.897Z,1406869482.897 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:43.249Z,1406869483.249 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:43.249Z,1406869483.249 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:43.249Z,1406869483.249 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:43.250Z,1406869483.250 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:43.250Z,1406869483.250 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:43.662Z,1406869483.662 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:43.662Z,1406869483.662 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:43.663Z,1406869483.663 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:43.664Z,1406869483.664 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:43.664Z,1406869483.664 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:43.664Z,1406869483.664 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:44.068Z,1406869484.068 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:44.068Z,1406869484.068 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:44.068Z,1406869484.068 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:44.068Z,1406869484.068 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:44.068Z,1406869484.068 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:44.969Z,1406869484.969 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:44.969Z,1406869484.969 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:44.969Z,1406869484.969 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:44.995Z,1406869484.995 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:44.995Z,1406869484.995 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:44.995Z,1406869484.995 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:45.081Z,1406869485.081 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-08-01T05:04:45.081Z,1406869485.081 [DVL_micro] Data Fault, FailCount= 1
2014-08-01T05:04:45.081Z,1406869485.081 [DVL_micro](ERROR): Data Fault
2014-08-01T05:04:46.192Z,1406869486.192 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:46.192Z,1406869486.192 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:46.192Z,1406869486.192 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:46.192Z,1406869486.192 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:46.192Z,1406869486.192 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:46.201Z,1406869486.201 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-08-01T05:04:46.338Z,1406869486.338 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T05:04:46.361Z,1406869486.361 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:46.361Z,1406869486.361 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:46.361Z,1406869486.361 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:46.362Z,1406869486.362 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:46.363Z,1406869486.363 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:46.363Z,1406869486.363 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:46.620Z,1406869486.620 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-08-01T05:04:46.620Z,1406869486.620 [DVL_micro] Hardware Fault, FailCount= 1
2014-08-01T05:04:46.620Z,1406869486.620 [DVL_micro](ERROR): Hardware Fault
2014-08-01T05:04:46.687Z,1406869486.687 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:46.687Z,1406869486.687 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:46.687Z,1406869486.687 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:46.687Z,1406869486.687 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:46.688Z,1406869486.688 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:47.039Z,1406869487.039 [DVL_micro](INFO): Initializing
2014-08-01T05:04:47.074Z,1406869487.074 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:47.074Z,1406869487.074 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:47.074Z,1406869487.074 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:47.075Z,1406869487.075 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:47.076Z,1406869487.076 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:47.076Z,1406869487.076 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:47.109Z,1406869487.109 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-08-01T05:04:47.109Z,1406869487.109 [DVL_micro] No Fault, FailCount= 1
2014-08-01T05:04:47.466Z,1406869487.466 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:47.466Z,1406869487.466 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:47.467Z,1406869487.467 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:47.467Z,1406869487.467 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:47.467Z,1406869487.467 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:47.856Z,1406869487.856 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:47.856Z,1406869487.856 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:47.856Z,1406869487.856 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:47.857Z,1406869487.857 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:47.857Z,1406869487.857 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:47.858Z,1406869487.858 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:48.266Z,1406869488.266 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:48.266Z,1406869488.266 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:48.266Z,1406869488.266 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:48.266Z,1406869488.266 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:48.267Z,1406869488.267 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:48.715Z,1406869488.715 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:48.715Z,1406869488.715 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:48.715Z,1406869488.715 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:48.716Z,1406869488.716 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:48.716Z,1406869488.716 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:48.717Z,1406869488.717 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:49.068Z,1406869489.068 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:49.068Z,1406869489.068 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:49.068Z,1406869489.068 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:49.068Z,1406869489.068 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:49.068Z,1406869489.068 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:49.962Z,1406869489.962 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:49.962Z,1406869489.962 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:49.962Z,1406869489.962 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:49.963Z,1406869489.963 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:49.964Z,1406869489.964 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:49.964Z,1406869489.964 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:51.090Z,1406869491.090 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:51.091Z,1406869491.091 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:51.091Z,1406869491.091 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:51.091Z,1406869491.091 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:51.091Z,1406869491.091 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:51.193Z,1406869491.193 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:51.193Z,1406869491.193 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:51.193Z,1406869491.193 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:51.194Z,1406869491.194 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:51.194Z,1406869491.194 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:51.194Z,1406869491.194 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:51.721Z,1406869491.721 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:51.721Z,1406869491.721 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:51.721Z,1406869491.721 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:51.721Z,1406869491.721 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:51.721Z,1406869491.721 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:52.015Z,1406869492.015 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:52.016Z,1406869492.016 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:52.016Z,1406869492.016 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:52.017Z,1406869492.017 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:52.017Z,1406869492.017 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:52.017Z,1406869492.017 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:52.419Z,1406869492.419 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:52.419Z,1406869492.419 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:52.419Z,1406869492.419 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:52.419Z,1406869492.419 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:52.420Z,1406869492.420 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:52.787Z,1406869492.787 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:52.788Z,1406869492.788 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:52.788Z,1406869492.788 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:52.789Z,1406869492.789 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:52.789Z,1406869492.789 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:52.789Z,1406869492.789 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:53.183Z,1406869493.183 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:53.183Z,1406869493.183 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:53.183Z,1406869493.183 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:53.183Z,1406869493.183 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:53.183Z,1406869493.183 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:53.585Z,1406869493.585 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:53.585Z,1406869493.585 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:53.585Z,1406869493.585 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:53.586Z,1406869493.586 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:53.586Z,1406869493.586 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:53.587Z,1406869493.587 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:54.055Z,1406869494.055 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:54.056Z,1406869494.056 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:54.056Z,1406869494.056 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:54.060Z,1406869494.060 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:54.060Z,1406869494.060 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:54.892Z,1406869494.892 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:54.892Z,1406869494.892 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:54.892Z,1406869494.892 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:54.893Z,1406869494.893 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:54.893Z,1406869494.893 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:54.893Z,1406869494.893 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:56.053Z,1406869496.053 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:56.053Z,1406869496.053 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:56.054Z,1406869496.054 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:56.054Z,1406869496.054 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:56.054Z,1406869496.054 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:56.262Z,1406869496.262 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:56.263Z,1406869496.263 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:56.263Z,1406869496.263 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:56.264Z,1406869496.264 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:56.264Z,1406869496.264 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:56.264Z,1406869496.264 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:56.816Z,1406869496.816 [DAT](FAULT): DAT uart error.serial timeout
2014-08-01T05:04:56.816Z,1406869496.816 [DAT] Communications Fault, FailCount= 1
2014-08-01T05:04:56.816Z,1406869496.816 [DAT](ERROR): Communications Fault
2014-08-01T05:04:56.871Z,1406869496.871 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:56.871Z,1406869496.871 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:56.871Z,1406869496.871 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:56.871Z,1406869496.871 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:56.871Z,1406869496.871 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:56.893Z,1406869496.893 [CBIT](ERROR): Communications Fault in component: DAT
2014-08-01T05:04:57.072Z,1406869497.072 [DAT](INFO): Powering down
2014-08-01T05:04:57.122Z,1406869497.122 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:57.123Z,1406869497.123 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:57.123Z,1406869497.123 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:57.124Z,1406869497.124 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:57.124Z,1406869497.124 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:57.124Z,1406869497.124 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:57.367Z,1406869497.367 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:57.367Z,1406869497.367 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:57.367Z,1406869497.367 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:57.367Z,1406869497.367 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:57.367Z,1406869497.367 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:57.759Z,1406869497.759 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:57.759Z,1406869497.759 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:57.759Z,1406869497.759 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:57.760Z,1406869497.760 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:57.760Z,1406869497.760 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:57.760Z,1406869497.760 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:57.769Z,1406869497.769 [CBIT](INFO): Clearing failed state for component DAT
2014-08-01T05:04:57.769Z,1406869497.769 [DAT] No Fault, FailCount= 1
2014-08-01T05:04:58.175Z,1406869498.175 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:58.175Z,1406869498.175 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:58.175Z,1406869498.175 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:58.175Z,1406869498.175 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:58.175Z,1406869498.175 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:58.560Z,1406869498.560 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:58.561Z,1406869498.561 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:58.561Z,1406869498.561 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:58.562Z,1406869498.562 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:58.562Z,1406869498.562 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:58.562Z,1406869498.562 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:58.968Z,1406869498.968 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:04:58.969Z,1406869498.969 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:04:58.969Z,1406869498.969 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:04:58.969Z,1406869498.969 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:58.969Z,1406869498.969 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:04:59.858Z,1406869499.858 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:04:59.858Z,1406869499.858 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:04:59.859Z,1406869499.859 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:04:59.860Z,1406869499.860 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:04:59.860Z,1406869499.860 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:04:59.860Z,1406869499.860 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:01.006Z,1406869501.006 [DAT](INFO): Powering up
2014-08-01T05:05:01.006Z,1406869501.006 [DAT](DEBUG): Initializing DAT.
2014-08-01T05:05:01.042Z,1406869501.042 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:01.042Z,1406869501.042 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:01.042Z,1406869501.042 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:01.042Z,1406869501.042 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:01.042Z,1406869501.042 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:01.176Z,1406869501.176 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:01.176Z,1406869501.176 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:01.176Z,1406869501.176 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:01.177Z,1406869501.177 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:01.177Z,1406869501.177 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:01.178Z,1406869501.178 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:01.595Z,1406869501.595 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:01.595Z,1406869501.595 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:01.596Z,1406869501.596 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:01.596Z,1406869501.596 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:01.596Z,1406869501.596 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:02.033Z,1406869502.033 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:02.033Z,1406869502.033 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:02.034Z,1406869502.034 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:02.035Z,1406869502.035 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:02.035Z,1406869502.035 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:02.035Z,1406869502.035 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:02.351Z,1406869502.351 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:02.351Z,1406869502.351 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:02.351Z,1406869502.351 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:02.351Z,1406869502.351 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:02.351Z,1406869502.351 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:02.734Z,1406869502.734 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:02.734Z,1406869502.734 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:02.734Z,1406869502.734 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:02.736Z,1406869502.736 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:02.736Z,1406869502.736 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:02.736Z,1406869502.736 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:03.132Z,1406869503.132 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:03.132Z,1406869503.132 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:03.132Z,1406869503.132 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:03.133Z,1406869503.133 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:03.133Z,1406869503.133 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:03.541Z,1406869503.541 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:03.542Z,1406869503.542 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:03.542Z,1406869503.542 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:03.543Z,1406869503.543 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:03.543Z,1406869503.543 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:03.543Z,1406869503.543 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:03.988Z,1406869503.988 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:03.988Z,1406869503.988 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:03.988Z,1406869503.988 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:03.988Z,1406869503.988 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:03.988Z,1406869503.988 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:04.847Z,1406869504.847 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:04.847Z,1406869504.847 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:04.847Z,1406869504.847 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:04.849Z,1406869504.849 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:04.849Z,1406869504.849 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:04.849Z,1406869504.849 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:05.994Z,1406869505.994 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:05.994Z,1406869505.994 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:05.994Z,1406869505.994 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:05.994Z,1406869505.994 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:05.994Z,1406869505.994 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:06.107Z,1406869506.107 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:06.107Z,1406869506.107 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:06.107Z,1406869506.107 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:06.109Z,1406869506.109 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:06.109Z,1406869506.109 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:06.109Z,1406869506.109 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:06.490Z,1406869506.490 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:06.490Z,1406869506.490 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:06.490Z,1406869506.490 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:06.490Z,1406869506.490 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:06.491Z,1406869506.491 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:06.985Z,1406869506.985 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:06.985Z,1406869506.985 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:06.985Z,1406869506.985 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:06.987Z,1406869506.987 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:06.987Z,1406869506.987 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:06.987Z,1406869506.987 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:07.272Z,1406869507.272 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:07.272Z,1406869507.272 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:07.272Z,1406869507.272 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:07.288Z,1406869507.288 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:07.289Z,1406869507.289 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:07.655Z,1406869507.655 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:07.656Z,1406869507.656 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:07.656Z,1406869507.656 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:07.657Z,1406869507.657 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:07.657Z,1406869507.657 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:07.657Z,1406869507.657 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:08.104Z,1406869508.104 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:08.104Z,1406869508.104 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:08.104Z,1406869508.104 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:08.104Z,1406869508.104 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:08.104Z,1406869508.104 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:08.458Z,1406869508.458 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:08.459Z,1406869508.459 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:08.459Z,1406869508.459 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:08.460Z,1406869508.460 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:08.460Z,1406869508.460 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:08.460Z,1406869508.460 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:08.869Z,1406869508.869 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:08.870Z,1406869508.870 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:08.870Z,1406869508.870 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:08.870Z,1406869508.870 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:08.870Z,1406869508.870 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:09.764Z,1406869509.764 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:09.764Z,1406869509.764 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:09.764Z,1406869509.764 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:09.765Z,1406869509.765 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:09.765Z,1406869509.765 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:09.765Z,1406869509.765 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:10.950Z,1406869510.950 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:10.950Z,1406869510.950 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:10.950Z,1406869510.950 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:10.950Z,1406869510.950 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:10.950Z,1406869510.950 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:11.060Z,1406869511.060 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:11.061Z,1406869511.061 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:11.061Z,1406869511.061 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:11.062Z,1406869511.062 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:11.062Z,1406869511.062 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:11.062Z,1406869511.062 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:11.478Z,1406869511.478 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:11.479Z,1406869511.479 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:11.479Z,1406869511.479 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:11.495Z,1406869511.495 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:11.495Z,1406869511.495 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:11.826Z,1406869511.826 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:11.827Z,1406869511.827 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:11.827Z,1406869511.827 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:11.828Z,1406869511.828 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:11.828Z,1406869511.828 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:11.828Z,1406869511.828 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:12.299Z,1406869512.299 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:12.299Z,1406869512.299 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:12.299Z,1406869512.299 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:12.299Z,1406869512.299 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:12.299Z,1406869512.299 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:12.613Z,1406869512.613 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:12.613Z,1406869512.613 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:12.613Z,1406869512.613 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:12.615Z,1406869512.615 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:12.615Z,1406869512.615 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:12.615Z,1406869512.615 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:13.020Z,1406869513.020 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:13.020Z,1406869513.020 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:13.020Z,1406869513.020 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:13.020Z,1406869513.020 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:13.021Z,1406869513.021 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:13.419Z,1406869513.419 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:13.419Z,1406869513.419 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:13.419Z,1406869513.419 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:13.421Z,1406869513.421 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:13.421Z,1406869513.421 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:13.421Z,1406869513.421 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:13.826Z,1406869513.826 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:13.826Z,1406869513.826 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:13.826Z,1406869513.826 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:13.826Z,1406869513.826 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:13.827Z,1406869513.827 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:14.234Z,1406869514.234 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:14.235Z,1406869514.235 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:14.235Z,1406869514.235 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:14.236Z,1406869514.236 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:14.236Z,1406869514.236 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:14.236Z,1406869514.236 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:15.120Z,1406869515.120 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:15.120Z,1406869515.120 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:15.120Z,1406869515.120 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:15.120Z,1406869515.120 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:15.121Z,1406869515.121 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:16.286Z,1406869516.286 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:16.286Z,1406869516.286 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:16.286Z,1406869516.286 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:16.287Z,1406869516.287 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:16.287Z,1406869516.287 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:16.287Z,1406869516.287 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:16.387Z,1406869516.387 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:16.387Z,1406869516.387 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:16.387Z,1406869516.387 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:16.387Z,1406869516.387 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:16.388Z,1406869516.388 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:16.835Z,1406869516.835 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:16.835Z,1406869516.835 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:16.836Z,1406869516.836 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:16.837Z,1406869516.837 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:16.837Z,1406869516.837 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:16.837Z,1406869516.837 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:17.249Z,1406869517.249 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:17.249Z,1406869517.249 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:17.249Z,1406869517.249 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:17.250Z,1406869517.250 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:17.250Z,1406869517.250 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:17.579Z,1406869517.579 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:17.579Z,1406869517.579 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:17.579Z,1406869517.579 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:17.580Z,1406869517.580 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:17.580Z,1406869517.580 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:17.580Z,1406869517.580 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:18.019Z,1406869518.019 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:18.019Z,1406869518.019 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:18.019Z,1406869518.019 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:18.019Z,1406869518.019 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:18.019Z,1406869518.019 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:18.385Z,1406869518.385 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:18.385Z,1406869518.385 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:18.386Z,1406869518.386 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:18.387Z,1406869518.387 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:18.387Z,1406869518.387 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:18.387Z,1406869518.387 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:18.791Z,1406869518.791 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:18.791Z,1406869518.791 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:18.791Z,1406869518.791 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:18.791Z,1406869518.791 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:18.791Z,1406869518.791 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:19.198Z,1406869519.198 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:19.198Z,1406869519.198 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:19.198Z,1406869519.198 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:19.200Z,1406869519.200 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:19.200Z,1406869519.200 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:19.200Z,1406869519.200 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:20.307Z,1406869520.307 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:20.307Z,1406869520.307 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:20.307Z,1406869520.307 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:20.307Z,1406869520.307 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:20.308Z,1406869520.308 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:23.611Z,1406869523.611 [DAT](FAULT): DAT uart error.serial timeout
2014-08-01T05:05:23.611Z,1406869523.611 [DAT] Communications Fault, FailCount= 2
2014-08-01T05:05:23.611Z,1406869523.611 [DAT](ERROR): Communications Fault
2014-08-01T05:05:23.649Z,1406869523.649 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:23.649Z,1406869523.649 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:23.649Z,1406869523.649 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:23.655Z,1406869523.655 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:23.655Z,1406869523.655 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:23.655Z,1406869523.655 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:23.713Z,1406869523.713 [CBIT](ERROR): Communications Fault in component: DAT
2014-08-01T05:05:24.133Z,1406869524.133 [DAT](INFO): Powering down
2014-08-01T05:05:24.200Z,1406869524.200 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:24.200Z,1406869524.200 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:24.201Z,1406869524.201 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:24.201Z,1406869524.201 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:24.201Z,1406869524.201 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:24.399Z,1406869524.399 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:24.400Z,1406869524.400 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:24.400Z,1406869524.400 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:24.402Z,1406869524.402 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:24.402Z,1406869524.402 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:24.402Z,1406869524.402 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:24.767Z,1406869524.767 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:24.780Z,1406869524.780 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:24.780Z,1406869524.780 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:24.781Z,1406869524.781 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:24.781Z,1406869524.781 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:24.830Z,1406869524.830 [CBIT](INFO): Clearing failed state for component DAT
2014-08-01T05:05:24.830Z,1406869524.830 [DAT] No Fault, FailCount= 2
2014-08-01T05:05:25.124Z,1406869525.124 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:25.124Z,1406869525.124 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:25.124Z,1406869525.124 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:25.125Z,1406869525.125 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:25.125Z,1406869525.125 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:25.125Z,1406869525.125 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:25.479Z,1406869525.479 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:25.479Z,1406869525.479 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:25.479Z,1406869525.479 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:25.479Z,1406869525.479 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:25.479Z,1406869525.479 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:25.888Z,1406869525.888 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:25.888Z,1406869525.888 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:25.888Z,1406869525.888 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:25.890Z,1406869525.890 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:25.890Z,1406869525.890 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:25.890Z,1406869525.890 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:26.083Z,1406869526.083 [CommandLine](IMPORTANT): got command restart application
2014-08-01T05:05:26.781Z,1406869526.781 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:26.782Z,1406869526.782 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2014-08-01T05:05:26.782Z,1406869526.782 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:26.782Z,1406869526.782 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:26.782Z,1406869526.782 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:27.091Z,1406869527.091 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:05:27.091Z,1406869527.091 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:27.279Z,1406869527.279 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2014-08-01T05:05:27.280Z,1406869527.280 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:27.280Z,1406869527.280 [CommandLine](INFO): Join timeout helper Thread ID is 1300
2014-08-01T05:05:27.288Z,1406869527.288 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2014-08-01T05:05:27.288Z,1406869527.288 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:27.288Z,1406869527.288 [NavChartDb](INFO): Join timeout helper Thread ID is 1301
2014-08-01T05:05:27.548Z,1406869527.548 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:05:27.548Z,1406869527.548 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:27.556Z,1406869527.556 [ComponentRegistry](INFO): Shutting down Radio_Freewave ThreadHandler
2014-08-01T05:05:27.556Z,1406869527.556 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:27.557Z,1406869527.557 [Radio_Freewave](INFO): Join timeout helper Thread ID is 1302
2014-08-01T05:05:27.929Z,1406869527.929 [Radio_Freewave ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:05:27.984Z,1406869527.984 [DAT](INFO): Powering up
2014-08-01T05:05:27.985Z,1406869527.985 [DAT](DEBUG): Initializing DAT.
2014-08-01T05:05:28.047Z,1406869528.047 [tracking_on_surface:TestDrive:Data] Running Loop=1
2014-08-01T05:05:28.047Z,1406869528.047 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::initialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:28.048Z,1406869528.048 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2014-08-01T05:05:28.049Z,1406869528.049 [tracking_on_surface:TestDrive:Data:A] Stopped
2014-08-01T05:05:28.049Z,1406869528.049 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2014-08-01T05:05:28.049Z,1406869528.049 [tracking_on_surface:B.](DEBUG): Tracking...
2014-08-01T05:05:28.050Z,1406869528.050 [tracking_on_surface] Stopped
2014-08-01T05:05:28.050Z,1406869528.050 [tracking_on_surface](INFO): Aggregate::uninitialize tracking_on_surface
2014-08-01T05:05:28.050Z,1406869528.050 [tracking_on_surface:A.Pitch] Stopped
2014-08-01T05:05:28.050Z,1406869528.050 [tracking_on_surface:B.] Stopped
2014-08-01T05:05:28.051Z,1406869528.051 [tracking_on_surface:B.](DEBUG): Uninitializing Tracking.
2014-08-01T05:05:28.051Z,1406869528.051 [tracking_on_surface:TestDrive] Stopped
2014-08-01T05:05:28.051Z,1406869528.051 [tracking_on_surface:TestDrive](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive
2014-08-01T05:05:28.051Z,1406869528.051 [tracking_on_surface:TestDrive:Data] Stopped
2014-08-01T05:05:28.051Z,1406869528.051 [tracking_on_surface:TestDrive:Data](INFO): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2014-08-01T05:05:28.051Z,1406869528.051 [tracking_on_surface:TestDrive:Data:B] Stopped
2014-08-01T05:05:28.051Z,1406869528.051 [tracking_on_surface:TestDrive:B] Stopped
2014-08-01T05:05:28.120Z,1406869528.120 [Radio_Freewave](INFO): Powering down
2014-08-01T05:05:28.294Z,1406869528.294 [MissionManager](IMPORTANT): Started mission Default
2014-08-01T05:05:28.294Z,1406869528.294 [Default] Running Loop=1
2014-08-01T05:05:28.294Z,1406869528.294 [Default](INFO): Aggregate::initialize Default
2014-08-01T05:05:28.295Z,1406869528.295 [Default:A.GoToSurface] Running Loop=1
2014-08-01T05:05:28.295Z,1406869528.295 [Default:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-08-01T05:05:28.295Z,1406869528.295 [Default:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-08-01T05:05:28.295Z,1406869528.295 [Default:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-08-01T05:05:28.296Z,1406869528.296 [Default:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-08-01T05:05:28.296Z,1406869528.296 [Default:CheckIn] Running Loop=1
2014-08-01T05:05:28.296Z,1406869528.296 [Default:CheckIn](INFO): Aggregate::initialize Default:CheckIn
2014-08-01T05:05:28.296Z,1406869528.296 [Default:CheckIn:A.SetSpeed] Running Loop=1
2014-08-01T05:05:28.297Z,1406869528.297 [Default:CheckIn:A.SetSpeed](DEBUG): Initialize.
2014-08-01T05:05:28.297Z,1406869528.297 [Default:CheckIn:Read_GPS] Running Loop=1
2014-08-01T05:05:28.299Z,1406869528.299 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-08-01T05:05:28.301Z,1406869528.301 [Default:CheckIn:A.SetSpeed] Running Loop=1
2014-08-01T05:05:28.313Z,1406869528.313 [Default:WaitAtTheSurface] Running Loop=1
2014-08-01T05:05:28.329Z,1406869528.329 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface
2014-08-01T05:05:28.329Z,1406869528.329 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2014-08-01T05:05:28.329Z,1406869528.329 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Initialize.
2014-08-01T05:05:28.522Z,1406869528.522 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:28.542Z,1406869528.542 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2014-08-01T05:05:28.542Z,1406869528.542 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:28.542Z,1406869528.542 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1304
2014-08-01T05:05:28.602Z,1406869528.602 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2014-08-01T05:05:28.698Z,1406869528.698 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:05:28.698Z,1406869528.698 [WetLabsBB2FL](INFO): Powering down
2014-08-01T05:05:28.699Z,1406869528.699 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:28.706Z,1406869528.706 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2014-08-01T05:05:28.706Z,1406869528.706 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:28.706Z,1406869528.706 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1305
2014-08-01T05:05:29.107Z,1406869529.107 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:05:29.107Z,1406869529.107 [CTD_NeilBrown](INFO): Powering down
2014-08-01T05:05:29.108Z,1406869529.108 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:29.125Z,1406869529.125 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2014-08-01T05:05:29.125Z,1406869529.125 [logger ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:29.126Z,1406869529.126 [logger](INFO): Join timeout helper Thread ID is 1306
2014-08-01T05:05:29.126Z,1406869529.126 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:05:29.126Z,1406869529.126 [logger ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:29.128Z,1406869529.128 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2014-08-01T05:05:29.128Z,1406869529.128 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:29.128Z,1406869529.128 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2014-08-01T05:05:29.128Z,1406869529.128 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:29.129Z,1406869529.129 [controlThread](INFO): Join timeout helper Thread ID is 1307
2014-08-01T05:05:29.323Z,1406869529.323 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T05:05:29.323Z,1406869529.323 [controlThread](DEBUG): Uninitializing ControlThread
2014-08-01T05:05:29.324Z,1406869529.324 [AHRS_sp3003D](INFO): Powering down
2014-08-01T05:05:29.324Z,1406869529.324 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T05:05:29.325Z,1406869529.325 [NAL9602](INFO): Powering down
2014-08-01T05:05:29.326Z,1406869529.326 [DAT](INFO): Powering down
2014-08-01T05:05:29.328Z,1406869529.328 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-08-01T05:05:29.330Z,1406869529.330 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2014-08-01T05:05:29.330Z,1406869529.330 [Default] Stopped
2014-08-01T05:05:29.330Z,1406869529.330 [Default](INFO): Aggregate::uninitialize Default
2014-08-01T05:05:29.330Z,1406869529.330 [Default:A.GoToSurface] Stopped
2014-08-01T05:05:29.330Z,1406869529.330 [Default:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-08-01T05:05:29.330Z,1406869529.330 [Default:CheckIn] Stopped
2014-08-01T05:05:29.330Z,1406869529.330 [Default:CheckIn](INFO): Aggregate::uninitialize Default:CheckIn
2014-08-01T05:05:29.331Z,1406869529.331 [Default:CheckIn:A.SetSpeed] Stopped
2014-08-01T05:05:29.331Z,1406869529.331 [Default:CheckIn:A.SetSpeed](DEBUG): Uninitialize.
2014-08-01T05:05:29.331Z,1406869529.331 [Default:CheckIn:Read_GPS] Stopped
2014-08-01T05:05:29.331Z,1406869529.331 [Default:WaitAtTheSurface] Stopped
2014-08-01T05:05:29.331Z,1406869529.331 [Default:WaitAtTheSurface](INFO): Aggregate::uninitialize Default:WaitAtTheSurface
2014-08-01T05:05:29.331Z,1406869529.331 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Stopped
2014-08-01T05:05:29.331Z,1406869529.331 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Uninitialize.
2014-08-01T05:05:29.334Z,1406869529.334 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2014-08-01T05:05:29.334Z,1406869529.334 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2014-08-01T05:05:29.334Z,1406869529.334 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2014-08-01T05:05:29.335Z,1406869529.335 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2014-08-01T05:05:29.335Z,1406869529.335 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-08-01T05:05:29.335Z,1406869529.335 [BuoyancyServo](INFO): Powering down
2014-08-01T05:05:29.347Z,1406869529.347 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2014-08-01T05:05:29.347Z,1406869529.347 [ElevatorServo](INFO): Powering down
2014-08-01T05:05:29.348Z,1406869529.348 [MassServo](DEBUG): Uninitialize Mass Servo.
2014-08-01T05:05:29.348Z,1406869529.348 [MassServo](INFO): Powering down
2014-08-01T05:05:29.349Z,1406869529.349 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2014-08-01T05:05:29.349Z,1406869529.349 [RudderServo](INFO): Powering down
2014-08-01T05:05:29.349Z,1406869529.349 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2014-08-01T05:05:29.350Z,1406869529.350 [ThrusterServo](INFO): Powering down
2014-08-01T05:05:29.350Z,1406869529.350 [SBIT](DEBUG): Uninitialize SBIT Component.
2014-08-01T05:05:29.351Z,1406869529.351 [IBIT](DEBUG): Uninitialize IBIT Component.
2014-08-01T05:05:29.351Z,1406869529.351 [CBIT](DEBUG): Uninitialize CBIT Component.
2014-08-01T05:05:29.396Z,1406869529.396 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:29.465Z,1406869529.465 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:29.468Z,1406869529.468 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:29.483Z,1406869529.483 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:29.536Z,1406869529.536 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-08-01T05:05:29.572Z,1406869529.572 [logger ThreadHandler](INFO): Thread cancelled.