2013-05-16T21:13:22.794Z,1368738802.795 [Supervisor](DEBUG): Initializing supervisor.
2013-05-16T21:13:22.797Z,1368738802.797 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2013-05-16T21:13:22.798Z,1368738802.798 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2013-05-16T21:13:22.799Z,1368738802.799 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2013-05-16T21:13:22.802Z,1368738802.802 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2013-05-16T21:13:22.813Z,1368738802.813 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2013-05-16T21:13:22.814Z,1368738802.814 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2013-05-16T21:13:22.815Z,1368738802.815 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2013-05-16T21:13:22.816Z,1368738802.816 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0
2013-05-16T21:13:22.817Z,1368738802.816 [Supervisor](INFO): Looking for Config files in directory: Config/
2013-05-16T21:13:22.818Z,1368738802.818 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2013-05-16T21:13:23.105Z,1368738803.105 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2013-05-16T21:13:23.106Z,1368738803.106 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2013-05-16T21:13:23.299Z,1368738803.299 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2013-05-16T21:13:23.299Z,1368738803.299 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2013-05-16T21:13:23.385Z,1368738803.385 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2013-05-16T21:13:23.385Z,1368738803.385 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2013-05-16T21:13:23.591Z,1368738803.591 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2013-05-16T21:13:23.592Z,1368738803.592 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2013-05-16T21:13:23.736Z,1368738803.736 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2013-05-16T21:13:23.736Z,1368738803.736 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2013-05-16T21:13:23.978Z,1368738803.978 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2013-05-16T21:13:23.979Z,1368738803.979 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2013-05-16T21:13:24.153Z,1368738804.152 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2013-05-16T21:13:24.153Z,1368738804.153 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2013-05-16T21:13:24.413Z,1368738804.413 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2013-05-16T21:13:24.414Z,1368738804.414 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2013-05-16T21:13:24.515Z,1368738804.515 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2013-05-16T21:13:24.515Z,1368738804.515 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2013-05-16T21:13:24.926Z,1368738804.926 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2013-05-16T21:13:24.927Z,1368738804.927 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2013-05-16T21:13:25.042Z,1368738805.042 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2013-05-16T21:13:25.043Z,1368738805.043 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2013-05-16T21:13:25.130Z,1368738805.130 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2013-05-16T21:13:25.131Z,1368738805.131 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2013-05-16T21:13:25.238Z,1368738805.238 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2013-05-16T21:13:25.371Z,1368738805.371 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2013-05-16T21:13:25.457Z,1368738805.457 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2013-05-16T21:13:25.566Z,1368738805.566 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2013-05-16T21:13:25.669Z,1368738805.669 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2013-05-16T21:13:25.794Z,1368738805.794 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2013-05-16T21:13:25.892Z,1368738805.892 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2013-05-16T21:13:25.982Z,1368738805.982 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/LOGIN/
2013-05-16T21:13:25.983Z,1368738805.983 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2013-05-16T21:13:26.006Z,1368738806.006 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2013-05-16T21:13:26.159Z,1368738806.158 [InternalSim] Loaded
2013-05-16T21:13:26.159Z,1368738806.159 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2013-05-16T21:13:26.160Z,1368738806.160 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2013-05-16T21:13:26.160Z,1368738806.160 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2013-05-16T21:13:26.219Z,1368738806.219 [SBIT](DEBUG): Construct Startup Built In Test.
2013-05-16T21:13:26.248Z,1368738806.248 [SBIT] Loaded
2013-05-16T21:13:26.248Z,1368738806.248 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2013-05-16T21:13:26.249Z,1368738806.249 [IBIT](DEBUG): Construct Initiated Built In Test.
2013-05-16T21:13:26.278Z,1368738806.278 [IBIT] Loaded
2013-05-16T21:13:26.279Z,1368738806.279 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2013-05-16T21:13:26.282Z,1368738806.282 [CBIT](DEBUG): Construct CBIT Built In Test.
2013-05-16T21:13:26.403Z,1368738806.403 [CBIT] Loaded
2013-05-16T21:13:26.403Z,1368738806.403 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2013-05-16T21:13:26.403Z,1368738806.403 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2013-05-16T21:13:26.404Z,1368738806.404 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2013-05-16T21:13:26.556Z,1368738806.556 [BuoyancyServo] Loaded
2013-05-16T21:13:26.556Z,1368738806.556 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2013-05-16T21:13:26.569Z,1368738806.569 [ElevatorServo] Loaded
2013-05-16T21:13:26.569Z,1368738806.569 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2013-05-16T21:13:26.581Z,1368738806.581 [MassServo] Loaded
2013-05-16T21:13:26.581Z,1368738806.582 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2013-05-16T21:13:26.594Z,1368738806.594 [RudderServo] Loaded
2013-05-16T21:13:26.594Z,1368738806.594 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2013-05-16T21:13:26.606Z,1368738806.606 [ThrusterServo] Loaded
2013-05-16T21:13:26.606Z,1368738806.606 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2013-05-16T21:13:26.607Z,1368738806.607 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2013-05-16T21:13:26.607Z,1368738806.607 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2013-05-16T21:13:26.624Z,1368738806.624 [DepthRateCalculator] Loaded
2013-05-16T21:13:26.625Z,1368738806.625 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2013-05-16T21:13:29.770Z,1368738809.770 [HFRadarModelCalc] Loaded
2013-05-16T21:13:29.770Z,1368738809.770 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2013-05-16T21:13:29.787Z,1368738809.787 [NavChart] Loaded
2013-05-16T21:13:29.787Z,1368738809.787 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2013-05-16T21:13:29.793Z,1368738809.793 [PitchRateCalculator] Loaded
2013-05-16T21:13:29.793Z,1368738809.793 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2013-05-16T21:13:29.804Z,1368738809.804 [SpeedCalculator] Loaded
2013-05-16T21:13:29.804Z,1368738809.804 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2013-05-16T21:13:29.820Z,1368738809.820 [TempGradientCalculator] Loaded
2013-05-16T21:13:29.820Z,1368738809.820 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2013-05-16T21:13:29.826Z,1368738809.826 [YawRateCalculator] Loaded
2013-05-16T21:13:29.827Z,1368738809.827 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2013-05-16T21:13:29.873Z,1368738809.873 [Navigation] Loaded
2013-05-16T21:13:29.874Z,1368738809.874 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2013-05-16T21:13:29.874Z,1368738809.874 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2013-05-16T21:13:29.875Z,1368738809.875 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2013-05-16T21:13:30.088Z,1368738810.088 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2013-05-16T21:13:30.088Z,1368738810.088 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2013-05-16T21:13:30.110Z,1368738810.110 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2013-05-16T21:13:30.111Z,1368738810.111 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2013-05-16T21:13:30.152Z,1368738810.152 [VerticalControl](DEBUG): Construct VerticalControl.
2013-05-16T21:13:30.245Z,1368738810.246 [VerticalControl] Loaded
2013-05-16T21:13:30.246Z,1368738810.246 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2013-05-16T21:13:30.247Z,1368738810.247 [HorizontalControl](DEBUG): Construct HorizontalControl.
2013-05-16T21:13:30.304Z,1368738810.304 [HorizontalControl] Loaded
2013-05-16T21:13:30.305Z,1368738810.305 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2013-05-16T21:13:30.305Z,1368738810.305 [SpeedControl](DEBUG): Construct SpeedControl.
2013-05-16T21:13:30.307Z,1368738810.307 [SpeedControl] Loaded
2013-05-16T21:13:30.308Z,1368738810.307 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2013-05-16T21:13:30.308Z,1368738810.308 [LoopControl](DEBUG): Construct LoopControl.
2013-05-16T21:13:30.309Z,1368738810.309 [LoopControl] Loaded
2013-05-16T21:13:30.309Z,1368738810.309 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2013-05-16T21:13:30.310Z,1368738810.310 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2013-05-16T21:13:30.310Z,1368738810.310 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2013-05-16T21:13:30.316Z,1368738810.316 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2013-05-16T21:13:30.321Z,1368738810.321 [AsyncPiEstimator] Loaded
2013-05-16T21:13:30.321Z,1368738810.321 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2013-05-16T21:13:30.322Z,1368738810.322 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 4063B4E0
2013-05-16T21:13:30.323Z,1368738810.323 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2013-05-16T21:13:30.324Z,1368738810.324 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2013-05-16T21:13:30.450Z,1368738810.450 [AHRS_sp3003D] Loaded
2013-05-16T21:13:30.450Z,1368738810.450 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2013-05-16T21:13:30.710Z,1368738810.710 [Batt_Ocean_Server] Loaded
2013-05-16T21:13:30.711Z,1368738810.711 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2013-05-16T21:13:30.725Z,1368738810.725 [Depth_Keller] Loaded
2013-05-16T21:13:30.725Z,1368738810.725 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2013-05-16T21:13:30.731Z,1368738810.731 [DropWeight] Loaded
2013-05-16T21:13:30.731Z,1368738810.731 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2013-05-16T21:13:30.905Z,1368738810.905 [DVL_micro] Loaded
2013-05-16T21:13:30.905Z,1368738810.905 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2013-05-16T21:13:30.906Z,1368738810.906 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 406BD4E0
2013-05-16T21:13:30.989Z,1368738810.989 [NAL9602] Loaded
2013-05-16T21:13:30.989Z,1368738810.989 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2013-05-16T21:13:31.041Z,1368738811.041 [Onboard] Loaded
2013-05-16T21:13:31.041Z,1368738811.041 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2013-05-16T21:13:31.048Z,1368738811.048 [Radio_Freewave] Loaded
2013-05-16T21:13:31.048Z,1368738811.048 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2013-05-16T21:13:31.169Z,1368738811.169 [DAT] Loaded
2013-05-16T21:13:31.170Z,1368738811.170 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2013-05-16T21:13:31.170Z,1368738811.170 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2013-05-16T21:13:31.171Z,1368738811.171 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2013-05-16T21:13:31.243Z,1368738811.243 [CTD_NeilBrown] Loaded
2013-05-16T21:13:31.243Z,1368738811.243 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2013-05-16T21:13:31.244Z,1368738811.244 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4070F4E0
2013-05-16T21:13:31.276Z,1368738811.276 [WetLabsBB2FL] Loaded
2013-05-16T21:13:31.276Z,1368738811.276 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2013-05-16T21:13:31.277Z,1368738811.277 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4073F4E0
2013-05-16T21:13:31.278Z,1368738811.278 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2013-05-16T21:13:31.280Z,1368738811.280 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2013-05-16T21:13:31.281Z,1368738811.281 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2013-05-16T21:13:31.288Z,1368738811.288 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2013-05-16T21:13:31.289Z,1368738811.289 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 4076F4E0
2013-05-16T21:13:31.293Z,1368738811.293 [Supervisor](DEBUG): Running supervisor.
2013-05-16T21:13:31.294Z,1368738811.294 [CommandLine](INFO): Thread ID is 9175
2013-05-16T21:13:31.297Z,1368738811.297 [controlThread](INFO): Thread ID is 9174
2013-05-16T21:13:31.297Z,1368738811.297 [controlThread](DEBUG): Initializing ControlThread
2013-05-16T21:13:31.298Z,1368738811.297 [CycleStarter](INFO): Thread ID is 9173
2013-05-16T21:13:31.298Z,1368738811.298 [InternalSim](DEBUG):  InternalSim initializing...
2013-05-16T21:13:31.331Z,1368738811.331 [logger](INFO): Thread ID is 9176
2013-05-16T21:13:31.356Z,1368738811.356 [SBIT](INFO): Initialize SBIT Component.
2013-05-16T21:13:31.357Z,1368738811.357 [SBIT](IMPORTANT): Tethys CM Info:
$Rev:10359
2013-05-16T21:13:31.357Z,1368738811.357 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2013-05-16T21:13:31.358Z,1368738811.358 [SBIT](IMPORTANT): Kernel Version:#634 PREEMPT Wed Feb 13 10:21:48 PST 2013
2013-05-16T21:13:31.358Z,1368738811.358 [IBIT](INFO): Initialize IBIT Component.
2013-05-16T21:13:31.359Z,1368738811.359 [CBIT](DEBUG): Initialize CBIT Component.
2013-05-16T21:13:31.359Z,1368738811.359 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2013-05-16T21:13:31.371Z,1368738811.371 [AsyncPiEstimator](INFO): Thread ID is 9237
2013-05-16T21:13:31.371Z,1368738811.371 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2013-05-16T21:13:31.384Z,1368738811.384 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-05-16T21:13:31.384Z,1368738811.384 [NavChart](DEBUG): Initialize NavChart Derivation.
2013-05-16T21:13:31.385Z,1368738811.385 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2013-05-16T21:13:31.385Z,1368738811.385 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2013-05-16T21:13:31.385Z,1368738811.385 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2013-05-16T21:13:31.387Z,1368738811.387 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2013-05-16T21:13:31.387Z,1368738811.387 [Navigation](DEBUG): Initializing Navigation.
2013-05-16T21:13:31.388Z,1368738811.388 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2013-05-16T21:13:31.389Z,1368738811.389 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2013-05-16T21:13:31.390Z,1368738811.390 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2013-05-16T21:13:31.391Z,1368738811.391 [LoopControl](DEBUG): Initialize LoopControlComponent.
2013-05-16T21:13:31.396Z,1368738811.396 [DVL_micro](INFO): Thread ID is 9238
2013-05-16T21:13:31.406Z,1368738811.406 [DVL_micro](INFO): Initializing
2013-05-16T21:13:31.406Z,1368738811.406 [DVL_micro](INFO): start:Powering up
2013-05-16T21:13:31.407Z,1368738811.407 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-05-16T21:13:31.407Z,1368738811.407 [DVL_micro](INFO): Cycling power to configure device.
2013-05-16T21:13:31.419Z,1368738811.419 [CTD_NeilBrown](INFO): Thread ID is 9239
2013-05-16T21:13:31.420Z,1368738811.420 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2013-05-16T21:13:31.423Z,1368738811.423 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2013-05-16T21:13:31.432Z,1368738811.432 [WetLabsBB2FL](INFO): Thread ID is 9240
2013-05-16T21:13:31.432Z,1368738811.432 [WetLabsBB2FL](INFO): Powering down
2013-05-16T21:13:31.471Z,1368738811.471 [NavChartDb](INFO): Thread ID is 9241
2013-05-16T21:13:31.473Z,1368738811.473 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2013-05-16T21:13:31.475Z,1368738811.475 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2013-05-16T21:13:31.475Z,1368738811.475 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2013-05-16T21:13:31.475Z,1368738811.475 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2013-05-16T21:13:31.475Z,1368738811.476 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2013-05-16T21:13:31.476Z,1368738811.476 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2013-05-16T21:13:31.476Z,1368738811.476 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2013-05-16T21:13:31.476Z,1368738811.476 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2013-05-16T21:13:31.477Z,1368738811.477 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2013-05-16T21:13:33.095Z,1368738813.095 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2013-05-16T21:13:33.123Z,1368738813.123 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2013-05-16T21:13:33.156Z,1368738813.157 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2013-05-16T21:13:33.187Z,1368738813.187 [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 RunIn="Progression"/>

    <Aggregate Id="StartupSatComms" >

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

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

    </Aggregate>

</Mission>


2013-05-16T21:13:33.188Z,1368738813.188 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2013-05-16T21:13:33.255Z,1368738813.255 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2013-05-16T21:13:33.257Z,1368738813.257 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2013-05-16T21:13:33.276Z,1368738813.276 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-05-16T21:13:33.293Z,1368738813.293 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2013-05-16T21:13:33.308Z,1368738813.308 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-05-16T21:13:33.315Z,1368738813.315 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2013-05-16T21:13:33.354Z,1368738813.355 [Default:D.SetSpeed](DEBUG): Construct.
2013-05-16T21:13:33.357Z,1368738813.358 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2013-05-16T21:13:33.381Z,1368738813.381 [Default:F.Wait](DEBUG): Construct Wait.
2013-05-16T21:13:33.396Z,1368738813.397 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
xmlns:Control="Tethys/Control"
xmlns:Guidance="Tethys/Guidance" 
xmlns:Units="Tethys/Units"
xmlns:Universal="Tethys/Universal"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
Id="Default">

    <DefineArg Name="NeedGPS"><True/></DefineArg>

    <Aggregate Id="GPS" >

        <When><Arg Name="NeedGPS"/>
        </When>

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Get GPS fix -->

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

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

    </Aggregate>

    <Aggregate Id="Iridium" >

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Do data comms -->

        <ReadDatum Id="Read_Iridium">
            <Timeout Duration="P2H">
                <Guidance:Execute RunIn="Sequence">
                    <Setting>
                    <Guidance:Execute.command/><String>Burn 300</String></Setting>
                </Guidance:Execute>
                <Syslog Severity="Critical">Dropped drop weight due to communications timeout</Syslog>
            </Timeout><Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

    <Aggregate Id="CallIridium" >

        <When>
            <Elapsed><Universal:platform_communications/></Elapsed>
            <Gt><Units:minute/><Value>5.0</Value></Gt>
            <And><Universal:platform_conversation/><Eq><True/></Eq></And>
            <Or>
            <Elapsed><Universal:platform_communications/></Elapsed><Gt><Units:hour/><Value>1.0</Value></Gt></Or>
        </When>

        <Assign><Arg Name="NeedGPS"/><True/></Assign>

        <Call RefId="Iridium"/>

    </Aggregate>

<!-- Wait forever at the surface-->

<!-- Run at low speed -->

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

    <Guidance:GoToSurface RunIn="Parallel"/>

    <Guidance:Wait RunIn="Sequence"></Guidance:Wait>

</Mission>


2013-05-16T21:13:33.401Z,1368738813.401 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,NAL9602,Onboard,Radio_Freewave,DAT,Depth_Keller,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,
2013-05-16T21:13:33.458Z,1368738813.458 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-05-16T21:13:33.499Z,1368738813.499 [Depth_Keller](ERROR): Pressure reading out of range: 1831.078247 decibar
2013-05-16T21:13:33.507Z,1368738813.507 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-05-16T21:13:33.507Z,1368738813.507 [DVL_micro](INFO): Querying output modes
2013-05-16T21:13:33.507Z,1368738813.507 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-05-16T21:13:33.518Z,1368738813.519 [DVL_micro](DEBUG): cmdResponse: 01 03 16
2013-05-16T21:13:33.519Z,1368738813.519 [DVL_micro](INFO): NQ1 output enabled
2013-05-16T21:13:33.519Z,1368738813.519 [DVL_micro](INFO): RSSI output enabled
2013-05-16T21:13:33.519Z,1368738813.519 [DVL_micro](INFO): ADCP output enabled
2013-05-16T21:13:33.519Z,1368738813.519 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-05-16T21:13:33.530Z,1368738813.530 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2013-05-16T21:13:33.540Z,1368738813.540 [DVL_micro](INFO): pause:Powering down
2013-05-16T21:13:33.623Z,1368738813.622 [Radio_Freewave](INFO): Powering up
2013-05-16T21:13:33.628Z,1368738813.628 [DAT](INFO): Powering up
2013-05-16T21:13:33.628Z,1368738813.628 [DAT](DEBUG): Initializing DAT.
2013-05-16T21:13:33.891Z,1368738813.891 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-05-16T21:13:33.899Z,1368738813.899 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-05-16T21:13:33.905Z,1368738813.905 [ElevatorServo](DEBUG): Initializing EZServoServo.
2013-05-16T21:13:33.910Z,1368738813.911 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2013-05-16T21:13:33.916Z,1368738813.916 [MassServo](DEBUG): Initializing EZServoServo.
2013-05-16T21:13:33.923Z,1368738813.922 [MassServo](DEBUG): Initializing MassServo.
2013-05-16T21:13:33.928Z,1368738813.928 [RudderServo](DEBUG): Initializing EZServoServo.
2013-05-16T21:13:33.959Z,1368738813.958 [RudderServo](DEBUG): Initializing RudderServo.
2013-05-16T21:13:33.964Z,1368738813.964 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-05-16T21:13:33.970Z,1368738813.970 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-05-16T21:13:34.182Z,1368738814.182 [AHRS_sp3003D](ERROR): readHeadingMagBin got 0x42360D0AA4
2013-05-16T21:13:34.183Z,1368738814.182 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-05-16T21:13:34.183Z,1368738814.183 [AHRS_sp3003D] Hardware Fault, FailCount= 1
2013-05-16T21:13:34.183Z,1368738814.183 [AHRS_sp3003D](ERROR): Hardware Fault
2013-05-16T21:13:34.332Z,1368738814.332 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-05-16T21:13:34.347Z,1368738814.347 [DVL_micro](INFO): RSSI unrequested
2013-05-16T21:13:34.347Z,1368738814.347 [DVL_micro](INFO): ADCP unrequested
2013-05-16T21:13:34.347Z,1368738814.347 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-05-16T21:13:34.348Z,1368738814.348 [DVL_micro](INFO): resume:Powering up
2013-05-16T21:13:34.348Z,1368738814.348 [DVL_micro](INFO): Cycling power to configure device.
2013-05-16T21:13:34.446Z,1368738814.446 [AHRS_sp3003D](INFO): Powering down
2013-05-16T21:13:35.812Z,1368738815.812 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2013-05-16T21:13:35.812Z,1368738815.812 [AHRS_sp3003D] No Fault, FailCount= 1
2013-05-16T21:13:36.145Z,1368738816.145 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-05-16T21:13:36.169Z,1368738816.169 [NAL9602](INFO): Powering up NAL9602
2013-05-16T21:13:36.355Z,1368738816.355 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-05-16T21:13:36.355Z,1368738816.355 [DVL_micro](INFO): Querying output modes
2013-05-16T21:13:36.355Z,1368738816.355 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-05-16T21:13:36.370Z,1368738816.371 [DVL_micro](DEBUG): cmdResponse: 01 03 16
2013-05-16T21:13:36.371Z,1368738816.371 [DVL_micro](INFO): NQ1 output enabled
2013-05-16T21:13:36.371Z,1368738816.372 [DVL_micro](INFO): RSSI output enabled
2013-05-16T21:13:36.372Z,1368738816.372 [DVL_micro](INFO): ADCP output enabled
2013-05-16T21:13:36.372Z,1368738816.372 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-05-16T21:13:36.387Z,1368738816.387 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2013-05-16T21:13:36.389Z,1368738816.389 [DVL_micro](INFO): pause:Powering down
2013-05-16T21:13:43.051Z,1368738823.051 [CommandLine](IMPORTANT): got command show variable DAT
2013-05-16T21:13:43.057Z,1368738823.057 [CommandLine](INFO): Config/vehicle.sendDataToShore (bool)
2013-05-16T21:13:43.060Z,1368738823.060 [CommandLine](INFO): Config/vehicle.DAT_card (none)
2013-05-16T21:13:43.060Z,1368738823.060 [CommandLine](INFO): Config/vehicle.DAT_uart (none)
2013-05-16T21:13:43.060Z,1368738823.060 [CommandLine](INFO): Config/vehicle.DAT_baud (bit_per_second)
2013-05-16T21:13:43.063Z,1368738823.063 [CommandLine](INFO): Config/Sensor.DAT_enable (bool)
2013-05-16T21:13:43.064Z,1368738823.064 [CommandLine](INFO): Config/Sensor.DAT_useHardware (bool)
2013-05-16T21:13:43.064Z,1368738823.064 [CommandLine](INFO): Config/Sensor.DAT_remoteAddress (count)
2013-05-16T21:13:43.064Z,1368738823.065 [CommandLine](INFO): Config/Sensor.DAT_rotationOffset (degree)
2013-05-16T21:13:43.106Z,1368738823.106 [CommandLine](INFO): Config/Simulator.oceanModelData (none)
2013-05-16T21:13:43.112Z,1368738823.112 [CommandLine](INFO): Navigation.useHFRadarData (bool)
2013-05-16T21:13:43.167Z,1368738823.167 [CommandLine](INFO): DAT.onewayRequestedCmd (bool)
2013-05-16T21:13:43.168Z,1368738823.168 [CommandLine](INFO): DAT.homing_target_range (meter)
2013-05-16T21:13:43.168Z,1368738823.168 [CommandLine](INFO): DAT.homing_target_azimuth (degree)
2013-05-16T21:13:43.168Z,1368738823.168 [CommandLine](INFO): DAT.homing_target_elevation (degree)
2013-05-16T21:13:43.169Z,1368738823.169 [CommandLine](INFO): DAT.homing_target_heading (degree)
2013-05-16T21:13:43.169Z,1368738823.169 [CommandLine](INFO): DAT.LVL1 (count)
2013-05-16T21:13:43.169Z,1368738823.169 [CommandLine](INFO): DAT.LVL2 (count)
2013-05-16T21:13:43.170Z,1368738823.170 [CommandLine](INFO): DAT.LVL3 (count)
2013-05-16T21:13:43.186Z,1368738823.186 [CommandLine](INFO): DAT.LVL4 (count)
2013-05-16T21:13:43.187Z,1368738823.187 [CommandLine](INFO): DAT.AGC (count)
2013-05-16T21:13:43.187Z,1368738823.187 [CommandLine](INFO): DAT.IDXPeak (count)
2013-05-16T21:13:43.188Z,1368738823.188 [CommandLine](INFO): DAT.IDXFit (degree)
2013-05-16T21:13:43.188Z,1368738823.188 [CommandLine](INFO): DAT.IDXPhase (degree)
2013-05-16T21:13:43.188Z,1368738823.188 [CommandLine](INFO): DAT.phaseA (degree)
2013-05-16T21:13:43.189Z,1368738823.189 [CommandLine](INFO): DAT.phaseB (degree)
2013-05-16T21:13:43.189Z,1368738823.189 [CommandLine](INFO): DAT.phaseC (degree)
2013-05-16T21:13:43.189Z,1368738823.189 [CommandLine](INFO): DAT.vectorMagnitude (degree)
2013-05-16T21:13:43.190Z,1368738823.190 [CommandLine](INFO): DAT.rawAzimuth (degree)
2013-05-16T21:13:43.198Z,1368738823.198 [CommandLine](INFO): DAT.rawElevation (degree)
2013-05-16T21:13:43.199Z,1368738823.199 [CommandLine](INFO): DAT.calibratedAzimuth (degree)
2013-05-16T21:13:43.199Z,1368738823.199 [CommandLine](INFO): DAT.calibratedElevation (degree)
2013-05-16T21:13:43.199Z,1368738823.200 [CommandLine](INFO): DAT.rotatedAzimuth (degree)
2013-05-16T21:13:43.200Z,1368738823.200 [CommandLine](INFO): DAT.rotatedElevation (degree)
2013-05-16T21:13:43.200Z,1368738823.200 [CommandLine](INFO): DAT.txHeading (degree)
2013-05-16T21:13:43.201Z,1368738823.201 [CommandLine](INFO): DAT.txAddress (count)
2013-05-16T21:13:43.201Z,1368738823.201 [CommandLine](INFO): DAT.rxAddress (count)
2013-05-16T21:13:43.201Z,1368738823.201 [CommandLine](INFO): DAT.range (meter)
2013-05-16T21:13:43.205Z,1368738823.205 [CommandLine](INFO): DAT.durationOfLastRun (second)
2013-05-16T21:13:46.671Z,1368738826.671 [NAL9602](INFO): NAL9602 initialized
2013-05-16T21:13:47.073Z,1368738827.073 [SBIT](IMPORTANT): Beginning Startup BIT
2013-05-16T21:13:47.076Z,1368738827.076 [CBIT](IMPORTANT): Beginning GF scan
2013-05-16T21:13:53.933Z,1368738833.933 [DAT](INFO): Powering down
2013-05-16T21:14:13.915Z,1368738853.915 [CBIT](IMPORTANT): No ground fault detected
2013-05-16T21:14:41.252Z,1368738881.252 [SBIT](IMPORTANT): SBIT PASSED
2013-05-16T21:14:41.607Z,1368738881.607 [MissionManager](IMPORTANT): Started mission Startup
2013-05-16T21:14:41.608Z,1368738881.608 [Startup] Running Loop=1
2013-05-16T21:14:41.608Z,1368738881.608 [Startup](INFO): Aggregate::initialize Startup
2013-05-16T21:14:41.608Z,1368738881.608 [Startup:A.GoToSurface] Running Loop=1
2013-05-16T21:14:41.608Z,1368738881.608 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-05-16T21:14:41.614Z,1368738881.614 [Startup:StartupSatComms] Running Loop=1
2013-05-16T21:14:41.614Z,1368738881.614 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2013-05-16T21:14:41.614Z,1368738881.614 [Startup:StartupSatComms:A] Running Loop=1
2013-05-16T21:14:42.019Z,1368738882.019 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-05-16T21:15:00.111Z,1368738900.111 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/dat_on.xml
2013-05-16T21:15:00.111Z,1368738900.111 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/dat_on.xml
2013-05-16T21:15:00.127Z,1368738900.127 [MissionManager](INFO): DefineArg dat_on.MassDefault = 0.000000 n/a
2013-05-16T21:15:00.129Z,1368738900.129 [dat_on:A.Pitch](DEBUG): Construct.
2013-05-16T21:15:00.140Z,1368738900.140 [dat_on:TestDrive:C.Wait](DEBUG): Construct Wait.
2013-05-16T21:15:00.143Z,1368738900.143 [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="dat_on">

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

    <Timeout Duration="P15M"/>

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

    <Aggregate Id="TestDrive">

        <ReadData>
            <Universal:homing_target_range/>
        </ReadData>

        <Aggregate Id="Data">

            <When><True/>
            </When>

            <Shorelog><Control:HorizontalControl.latitudeCmd/><Units:degree/><Control:HorizontalControl.longitudeCmd/><Units:degree/>
            </Shorelog>

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

        </Aggregate>

        <Guidance:Wait RunIn="Sequence">
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>2</Value></Setting>
        </Guidance:Wait>

    </Aggregate>

</Mission>


2013-05-16T21:15:00.143Z,1368738900.143 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/dat_on.xml
2013-05-16T21:15:41.638Z,1368738941.638 [Startup:StartupSatComms:A](INFO): Timed out from 2013-05-16T21:14:41.6Z
2013-05-16T21:15:41.638Z,1368738941.638 [Startup:StartupSatComms:A:A_Timeout] Running Loop=1
2013-05-16T21:15:41.638Z,1368738941.638 [Startup:StartupSatComms:A:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A:A_Timeout
2013-05-16T21:15:41.638Z,1368738941.638 [Startup:StartupSatComms:A:A_Timeout](INFO): Completed Startup:StartupSatComms:A:A_Timeout
2013-05-16T21:15:41.638Z,1368738941.638 [Startup:StartupSatComms:A] Stopped
2013-05-16T21:15:41.639Z,1368738941.639 [Startup:StartupSatComms:B] Running Loop=1
2013-05-16T21:15:42.009Z,1368738942.009 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-05-16T21:15:46.315Z,1368738946.315 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-05-16T21:15:50.701Z,1368738950.701 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-05-16T21:15:54.596Z,1368738954.596 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-05-16T21:15:58.880Z,1368738958.880 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-05-16T21:16:03.597Z,1368738963.597 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-05-16T21:16:07.919Z,1368738967.919 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-05-16T21:16:12.267Z,1368738972.267 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-05-16T21:16:16.684Z,1368738976.684 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-05-16T21:16:20.556Z,1368738980.556 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-05-16T21:16:24.863Z,1368738984.863 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-05-16T21:16:29.595Z,1368738989.595 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-05-16T21:16:33.944Z,1368738993.944 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-05-16T21:16:38.305Z,1368738998.305 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-05-16T21:16:42.388Z,1368739002.388 [Startup:StartupSatComms:B](INFO): Timed out from 2013-05-16T21:15:41.6Z
2013-05-16T21:16:42.388Z,1368739002.388 [Startup:StartupSatComms:B:A_Timeout] Running Loop=1
2013-05-16T21:16:42.388Z,1368739002.388 [Startup:StartupSatComms:B:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:B:A_Timeout
2013-05-16T21:16:42.389Z,1368739002.389 [Startup:StartupSatComms:B:A_Timeout](INFO): Completed Startup:StartupSatComms:B:A_Timeout
2013-05-16T21:16:42.389Z,1368739002.389 [Startup:StartupSatComms:B] Stopped
2013-05-16T21:16:42.389Z,1368739002.389 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2013-05-16T21:16:42.389Z,1368739002.389 [Startup:StartupSatComms] Stopped
2013-05-16T21:16:42.389Z,1368739002.389 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2013-05-16T21:16:42.390Z,1368739002.390 [Startup](INFO): Completed Startup
2013-05-16T21:16:42.390Z,1368739002.390 [Startup] Stopped
2013-05-16T21:16:42.391Z,1368739002.391 [Startup](INFO): Aggregate::uninitialize Startup
2013-05-16T21:16:42.391Z,1368739002.391 [Startup:A.GoToSurface] Stopped
2013-05-16T21:16:42.391Z,1368739002.391 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-05-16T21:16:42.640Z,1368739002.640 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-05-16T21:16:42.653Z,1368739002.653 [MissionManager](IMPORTANT): Started mission dat_on
2013-05-16T21:16:42.653Z,1368739002.653 [dat_on] Running Loop=1
2013-05-16T21:16:42.653Z,1368739002.653 [dat_on](INFO): Aggregate::initialize dat_on
2013-05-16T21:16:42.653Z,1368739002.653 [dat_on:A.Pitch] Running Loop=1
2013-05-16T21:16:42.653Z,1368739002.653 [dat_on:A.Pitch](DEBUG): Initialize.
2013-05-16T21:16:42.654Z,1368739002.654 [dat_on:TestDrive] Running Loop=1
2013-05-16T21:16:42.654Z,1368739002.654 [dat_on:TestDrive](INFO): Aggregate::initialize dat_on:TestDrive
2013-05-16T21:16:42.654Z,1368739002.654 [dat_on:TestDrive:A] Running Loop=1
2013-05-16T21:16:42.655Z,1368739002.655 [dat_on:TestDrive:C.Wait] Running Loop=1
2013-05-16T21:16:42.655Z,1368739002.655 [dat_on:TestDrive:C.Wait](DEBUG): Initialize Wait Component.
2013-05-16T21:16:42.660Z,1368739002.660 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:42.660Z,1368739002.660 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:42.660Z,1368739002.660 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:42.664Z,1368739002.664 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:42.664Z,1368739002.664 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:42.664Z,1368739002.664 [dat_on:TestDrive:A] Running Loop=1
2013-05-16T21:16:42.665Z,1368739002.665 [dat_on:TestDrive:A](DEBUG): Initialize ReadDataComponent to sense homing_target_range
2013-05-16T21:16:42.666Z,1368739002.666 [dat_on:A.Pitch] Running Loop=1
2013-05-16T21:16:42.986Z,1368739002.986 [DAT](INFO): Powering up
2013-05-16T21:16:42.995Z,1368739002.995 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:42.995Z,1368739002.995 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:42.995Z,1368739002.995 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:42.996Z,1368739002.996 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:43.405Z,1368739003.405 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:43.405Z,1368739003.405 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:43.406Z,1368739003.406 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:43.407Z,1368739003.407 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:43.407Z,1368739003.407 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:43.813Z,1368739003.813 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:43.813Z,1368739003.813 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:43.813Z,1368739003.813 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:43.813Z,1368739003.813 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:44.207Z,1368739004.207 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:44.207Z,1368739004.207 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:44.207Z,1368739004.207 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:44.208Z,1368739004.208 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:44.208Z,1368739004.208 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:44.588Z,1368739004.588 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:44.588Z,1368739004.588 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:44.589Z,1368739004.589 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:44.589Z,1368739004.589 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:44.994Z,1368739004.994 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:44.994Z,1368739004.994 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:44.994Z,1368739004.994 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:44.995Z,1368739004.995 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:44.995Z,1368739004.995 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:45.433Z,1368739005.433 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:45.433Z,1368739005.433 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:45.433Z,1368739005.433 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:45.434Z,1368739005.434 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:45.812Z,1368739005.812 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:45.813Z,1368739005.813 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:45.813Z,1368739005.813 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:45.813Z,1368739005.813 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:45.813Z,1368739005.813 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:46.269Z,1368739006.269 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:46.269Z,1368739006.269 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:46.269Z,1368739006.269 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:46.269Z,1368739006.269 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:46.603Z,1368739006.603 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:46.603Z,1368739006.603 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:46.603Z,1368739006.603 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:46.604Z,1368739006.604 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:46.604Z,1368739006.604 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:46.988Z,1368739006.988 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:46.988Z,1368739006.988 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:46.988Z,1368739006.989 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:46.989Z,1368739006.989 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:47.396Z,1368739007.396 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:47.396Z,1368739007.396 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:47.396Z,1368739007.396 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:47.397Z,1368739007.397 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:47.397Z,1368739007.397 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:47.833Z,1368739007.833 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:47.833Z,1368739007.833 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:47.833Z,1368739007.833 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:47.834Z,1368739007.833 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:48.192Z,1368739008.192 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:48.192Z,1368739008.192 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:48.192Z,1368739008.192 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:48.193Z,1368739008.193 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:48.193Z,1368739008.193 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:48.613Z,1368739008.612 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:48.613Z,1368739008.613 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:48.613Z,1368739008.613 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:48.613Z,1368739008.613 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:49.007Z,1368739009.007 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:49.007Z,1368739009.007 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:49.007Z,1368739009.007 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:49.008Z,1368739009.008 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:49.008Z,1368739009.008 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:49.403Z,1368739009.403 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:49.403Z,1368739009.403 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:49.403Z,1368739009.404 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:49.404Z,1368739009.404 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:49.793Z,1368739009.793 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:49.793Z,1368739009.793 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:49.793Z,1368739009.793 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:49.794Z,1368739009.794 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:49.794Z,1368739009.794 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:50.235Z,1368739010.235 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:50.235Z,1368739010.235 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:50.235Z,1368739010.236 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:50.236Z,1368739010.236 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:50.598Z,1368739010.598 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:50.598Z,1368739010.598 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:50.599Z,1368739010.599 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:50.599Z,1368739010.599 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:50.599Z,1368739010.599 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:50.994Z,1368739010.994 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:50.994Z,1368739010.994 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:50.994Z,1368739010.994 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:50.995Z,1368739010.995 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:51.453Z,1368739011.453 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:51.453Z,1368739011.453 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:51.453Z,1368739011.453 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:51.454Z,1368739011.454 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:51.454Z,1368739011.454 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:51.807Z,1368739011.807 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:51.808Z,1368739011.807 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:51.808Z,1368739011.808 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:51.808Z,1368739011.808 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:52.225Z,1368739012.225 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:52.225Z,1368739012.225 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:52.226Z,1368739012.226 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:52.226Z,1368739012.226 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:52.226Z,1368739012.226 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:52.640Z,1368739012.639 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:52.640Z,1368739012.640 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:52.640Z,1368739012.640 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:52.640Z,1368739012.640 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:52.988Z,1368739012.988 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:52.988Z,1368739012.988 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:52.988Z,1368739012.988 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:52.989Z,1368739012.989 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:52.989Z,1368739012.989 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:53.396Z,1368739013.396 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:53.396Z,1368739013.396 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:53.396Z,1368739013.396 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:53.396Z,1368739013.397 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:53.794Z,1368739013.793 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:53.794Z,1368739013.794 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:53.794Z,1368739013.794 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:53.794Z,1368739013.795 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:53.795Z,1368739013.795 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:54.192Z,1368739014.192 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:54.192Z,1368739014.192 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:54.192Z,1368739014.192 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:54.192Z,1368739014.192 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:54.612Z,1368739014.612 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:54.613Z,1368739014.613 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:54.613Z,1368739014.613 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:54.613Z,1368739014.613 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:54.613Z,1368739014.613 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:55.042Z,1368739015.042 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:55.042Z,1368739015.042 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:55.042Z,1368739015.042 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:55.042Z,1368739015.042 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:55.403Z,1368739015.403 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:55.403Z,1368739015.403 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:55.403Z,1368739015.403 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:55.404Z,1368739015.404 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:55.404Z,1368739015.404 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:55.793Z,1368739015.793 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:55.793Z,1368739015.793 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:55.793Z,1368739015.793 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:55.793Z,1368739015.793 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:56.199Z,1368739016.199 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:56.199Z,1368739016.199 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:56.199Z,1368739016.199 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:56.200Z,1368739016.200 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:56.200Z,1368739016.200 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:56.642Z,1368739016.642 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:56.642Z,1368739016.642 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:56.642Z,1368739016.642 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:56.642Z,1368739016.642 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:56.994Z,1368739016.994 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:56.994Z,1368739016.994 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:56.994Z,1368739016.994 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:56.995Z,1368739016.995 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:56.995Z,1368739016.995 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:57.433Z,1368739017.433 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:57.433Z,1368739017.433 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:57.433Z,1368739017.433 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:57.433Z,1368739017.433 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:57.807Z,1368739017.807 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:57.807Z,1368739017.807 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:57.807Z,1368739017.807 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:57.808Z,1368739017.808 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:57.808Z,1368739017.808 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:58.225Z,1368739018.225 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:58.226Z,1368739018.226 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:58.226Z,1368739018.226 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:58.226Z,1368739018.226 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:58.603Z,1368739018.603 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:58.603Z,1368739018.603 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:58.603Z,1368739018.603 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:58.604Z,1368739018.604 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:58.604Z,1368739018.604 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:58.988Z,1368739018.988 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:58.988Z,1368739018.988 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:58.988Z,1368739018.989 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:58.989Z,1368739018.989 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:16:59.396Z,1368739019.397 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:16:59.397Z,1368739019.397 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:16:59.397Z,1368739019.397 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:16:59.397Z,1368739019.397 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:16:59.398Z,1368739019.398 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:16:59.833Z,1368739019.833 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:16:59.834Z,1368739019.833 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:16:59.834Z,1368739019.834 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:16:59.834Z,1368739019.834 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:00.192Z,1368739020.192 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:00.193Z,1368739020.193 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:00.193Z,1368739020.193 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:00.193Z,1368739020.193 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:00.193Z,1368739020.193 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:00.613Z,1368739020.612 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:00.613Z,1368739020.613 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:00.613Z,1368739020.613 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:00.613Z,1368739020.613 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:01.007Z,1368739021.007 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:01.007Z,1368739021.007 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:01.007Z,1368739021.007 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:01.008Z,1368739021.008 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:01.008Z,1368739021.008 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:01.467Z,1368739021.467 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:01.468Z,1368739021.468 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:01.468Z,1368739021.468 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:01.468Z,1368739021.468 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:01.793Z,1368739021.793 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:01.794Z,1368739021.793 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:01.794Z,1368739021.794 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:01.794Z,1368739021.795 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:01.795Z,1368739021.795 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:02.235Z,1368739022.235 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:02.235Z,1368739022.236 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:02.236Z,1368739022.236 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:02.236Z,1368739022.236 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:02.660Z,1368739022.661 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:02.661Z,1368739022.661 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:02.661Z,1368739022.661 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:02.661Z,1368739022.661 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:02.661Z,1368739022.661 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:03.012Z,1368739023.012 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:03.012Z,1368739023.012 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:03.012Z,1368739023.012 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:03.012Z,1368739023.012 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:03.397Z,1368739023.397 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:03.397Z,1368739023.397 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:03.397Z,1368739023.397 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:03.398Z,1368739023.398 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:03.398Z,1368739023.398 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:03.808Z,1368739023.808 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:03.808Z,1368739023.808 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:03.808Z,1368739023.808 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:03.808Z,1368739023.808 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:04.226Z,1368739024.226 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:04.226Z,1368739024.226 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:04.227Z,1368739024.227 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:04.227Z,1368739024.227 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:04.227Z,1368739024.227 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:04.653Z,1368739024.653 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:04.653Z,1368739024.653 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:04.653Z,1368739024.653 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:04.653Z,1368739024.653 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:04.988Z,1368739024.989 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:04.989Z,1368739024.989 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:04.989Z,1368739024.989 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:04.989Z,1368739024.989 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:04.989Z,1368739024.990 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:05.397Z,1368739025.397 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:05.397Z,1368739025.397 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:05.397Z,1368739025.397 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:05.397Z,1368739025.397 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:05.799Z,1368739025.799 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:05.799Z,1368739025.799 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:05.799Z,1368739025.799 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:05.800Z,1368739025.800 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:05.800Z,1368739025.800 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:06.197Z,1368739026.197 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:06.198Z,1368739026.198 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:06.198Z,1368739026.198 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:06.198Z,1368739026.198 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:06.677Z,1368739026.677 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:06.677Z,1368739026.677 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:06.677Z,1368739026.677 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:06.678Z,1368739026.678 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:06.678Z,1368739026.678 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:07.057Z,1368739027.057 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:07.058Z,1368739027.057 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:07.058Z,1368739027.058 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:07.058Z,1368739027.058 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:07.404Z,1368739027.404 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:07.404Z,1368739027.404 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:07.405Z,1368739027.405 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:07.405Z,1368739027.405 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:07.405Z,1368739027.405 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:07.793Z,1368739027.793 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:07.794Z,1368739027.794 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:07.794Z,1368739027.794 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:07.794Z,1368739027.794 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:08.197Z,1368739028.197 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:08.197Z,1368739028.197 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:08.197Z,1368739028.197 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:08.198Z,1368739028.198 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:08.198Z,1368739028.198 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:08.589Z,1368739028.589 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:08.589Z,1368739028.589 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:08.589Z,1368739028.589 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:08.589Z,1368739028.589 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:08.994Z,1368739028.994 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:08.994Z,1368739028.994 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:08.994Z,1368739028.994 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:08.995Z,1368739028.995 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:08.995Z,1368739028.995 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:09.434Z,1368739029.434 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:09.434Z,1368739029.434 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:09.434Z,1368739029.434 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:09.434Z,1368739029.434 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:09.808Z,1368739029.807 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:09.808Z,1368739029.808 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:09.808Z,1368739029.808 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:09.808Z,1368739029.808 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:09.808Z,1368739029.809 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:10.226Z,1368739030.226 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:10.227Z,1368739030.227 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:10.227Z,1368739030.227 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:10.227Z,1368739030.227 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:10.609Z,1368739030.609 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:10.609Z,1368739030.609 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:10.609Z,1368739030.609 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:10.609Z,1368739030.609 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:10.609Z,1368739030.609 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:10.994Z,1368739030.994 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:10.994Z,1368739030.994 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:10.994Z,1368739030.994 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:10.994Z,1368739030.994 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:11.397Z,1368739031.397 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:11.397Z,1368739031.397 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:11.397Z,1368739031.397 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:11.398Z,1368739031.398 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:11.398Z,1368739031.398 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:11.879Z,1368739031.879 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:11.879Z,1368739031.879 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:11.879Z,1368739031.879 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:11.879Z,1368739031.879 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:12.192Z,1368739032.192 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:12.192Z,1368739032.193 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:12.193Z,1368739032.193 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:12.193Z,1368739032.193 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:12.193Z,1368739032.193 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:12.670Z,1368739032.670 [DAT](ERROR): No response from remote modem
2013-05-16T21:17:12.685Z,1368739032.685 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:12.685Z,1368739032.685 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:12.685Z,1368739032.685 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:12.685Z,1368739032.685 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:13.033Z,1368739033.033 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:13.033Z,1368739033.033 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:13.033Z,1368739033.033 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:13.034Z,1368739033.034 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:13.034Z,1368739033.034 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:13.404Z,1368739033.404 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:13.404Z,1368739033.404 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:13.404Z,1368739033.404 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:13.404Z,1368739033.404 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:13.793Z,1368739033.793 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:13.793Z,1368739033.793 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:13.793Z,1368739033.793 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:13.794Z,1368739033.794 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:13.794Z,1368739033.794 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:14.198Z,1368739034.197 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:14.198Z,1368739034.198 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:14.198Z,1368739034.198 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:14.198Z,1368739034.198 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:14.637Z,1368739034.636 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:14.637Z,1368739034.637 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:14.637Z,1368739034.637 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:14.637Z,1368739034.637 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:14.637Z,1368739034.638 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:14.993Z,1368739034.993 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:14.993Z,1368739034.993 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:14.994Z,1368739034.994 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:14.994Z,1368739034.994 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:15.408Z,1368739035.408 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:15.409Z,1368739035.409 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:15.409Z,1368739035.409 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:15.409Z,1368739035.409 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:15.409Z,1368739035.409 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:15.808Z,1368739035.808 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:15.808Z,1368739035.808 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:15.808Z,1368739035.808 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:15.808Z,1368739035.808 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:16.226Z,1368739036.226 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:16.226Z,1368739036.226 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:16.226Z,1368739036.226 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:16.227Z,1368739036.227 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:16.227Z,1368739036.227 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:16.642Z,1368739036.642 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:16.643Z,1368739036.643 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:16.643Z,1368739036.643 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:16.643Z,1368739036.643 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:17.033Z,1368739037.033 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:17.034Z,1368739037.034 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:17.034Z,1368739037.034 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:17.034Z,1368739037.034 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:17.035Z,1368739037.035 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:17.409Z,1368739037.409 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:17.409Z,1368739037.409 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:17.409Z,1368739037.409 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:17.409Z,1368739037.409 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:17.812Z,1368739037.812 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:17.812Z,1368739037.812 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:17.813Z,1368739037.813 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:17.813Z,1368739037.813 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:17.813Z,1368739037.813 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:18.204Z,1368739038.204 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:18.205Z,1368739038.204 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:18.205Z,1368739038.205 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:18.205Z,1368739038.205 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:18.593Z,1368739038.593 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:18.593Z,1368739038.593 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:18.593Z,1368739038.593 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:18.594Z,1368739038.594 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:18.595Z,1368739038.595 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:18.994Z,1368739038.994 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:18.995Z,1368739038.995 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:18.995Z,1368739038.995 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:18.995Z,1368739038.995 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:19.434Z,1368739039.434 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:19.434Z,1368739039.434 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:19.434Z,1368739039.434 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:19.435Z,1368739039.435 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:19.435Z,1368739039.435 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:19.813Z,1368739039.813 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:19.813Z,1368739039.813 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:19.814Z,1368739039.814 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:19.814Z,1368739039.814 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:20.211Z,1368739040.211 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:20.212Z,1368739040.211 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:20.212Z,1368739040.212 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:20.212Z,1368739040.212 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:20.212Z,1368739040.212 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:20.600Z,1368739040.600 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:20.600Z,1368739040.600 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:20.600Z,1368739040.600 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:20.600Z,1368739040.600 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:20.993Z,1368739040.993 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:20.993Z,1368739040.993 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:20.993Z,1368739040.993 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:20.994Z,1368739040.994 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:20.994Z,1368739040.994 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:21.397Z,1368739041.397 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:21.397Z,1368739041.397 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:21.397Z,1368739041.397 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:21.397Z,1368739041.397 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:21.880Z,1368739041.880 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:21.880Z,1368739041.880 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:21.880Z,1368739041.880 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:21.881Z,1368739041.881 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:21.881Z,1368739041.881 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:22.197Z,1368739042.197 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:22.198Z,1368739042.197 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:22.198Z,1368739042.198 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:22.198Z,1368739042.198 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:22.658Z,1368739042.658 [DAT](ERROR): No response from remote modem
2013-05-16T21:17:22.672Z,1368739042.672 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:22.672Z,1368739042.672 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:22.673Z,1368739042.673 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:22.673Z,1368739042.673 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:22.673Z,1368739042.673 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:23.028Z,1368739043.028 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:23.028Z,1368739043.028 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:23.028Z,1368739043.028 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:23.028Z,1368739043.028 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:23.409Z,1368739043.409 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:23.409Z,1368739043.409 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:23.409Z,1368739043.409 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:23.410Z,1368739043.410 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:23.410Z,1368739043.410 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:23.793Z,1368739043.793 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:23.793Z,1368739043.793 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:23.794Z,1368739043.793 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:23.794Z,1368739043.794 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:24.236Z,1368739044.236 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:24.236Z,1368739044.236 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:24.236Z,1368739044.236 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:24.237Z,1368739044.237 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:24.237Z,1368739044.237 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:24.593Z,1368739044.593 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:24.594Z,1368739044.593 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:24.594Z,1368739044.594 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:24.594Z,1368739044.594 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:24.994Z,1368739044.994 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:24.994Z,1368739044.994 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:24.994Z,1368739044.994 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:24.995Z,1368739044.995 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:24.995Z,1368739044.995 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:25.391Z,1368739045.391 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:25.391Z,1368739045.391 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:25.391Z,1368739045.391 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:25.391Z,1368739045.391 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:25.813Z,1368739045.813 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:25.813Z,1368739045.813 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:25.813Z,1368739045.813 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:25.813Z,1368739045.813 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:25.814Z,1368739045.814 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:26.225Z,1368739046.225 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:26.225Z,1368739046.225 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:26.225Z,1368739046.225 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:26.225Z,1368739046.225 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:26.640Z,1368739046.640 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:26.640Z,1368739046.640 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:26.640Z,1368739046.640 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:26.641Z,1368739046.641 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:26.641Z,1368739046.641 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:27.044Z,1368739047.044 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:27.045Z,1368739047.045 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:27.045Z,1368739047.045 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:27.045Z,1368739047.045 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:27.397Z,1368739047.397 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:27.397Z,1368739047.397 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:27.397Z,1368739047.397 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:27.398Z,1368739047.398 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:27.398Z,1368739047.398 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:27.795Z,1368739047.795 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:27.795Z,1368739047.795 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:27.795Z,1368739047.795 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:27.795Z,1368739047.795 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:28.197Z,1368739048.197 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:28.197Z,1368739048.197 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:28.197Z,1368739048.197 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:28.198Z,1368739048.198 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:28.198Z,1368739048.198 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:28.609Z,1368739048.609 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:28.609Z,1368739048.609 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:28.609Z,1368739048.609 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:28.609Z,1368739048.609 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:29.013Z,1368739049.013 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:29.013Z,1368739049.013 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:29.013Z,1368739049.013 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:29.014Z,1368739049.014 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:29.014Z,1368739049.014 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:29.445Z,1368739049.445 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:29.445Z,1368739049.445 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:29.445Z,1368739049.445 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:29.445Z,1368739049.445 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:29.793Z,1368739049.793 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:29.793Z,1368739049.793 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:29.793Z,1368739049.793 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:29.794Z,1368739049.794 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:29.794Z,1368739049.794 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:30.198Z,1368739050.198 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:30.198Z,1368739050.198 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:30.198Z,1368739050.198 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:30.198Z,1368739050.198 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:30.593Z,1368739050.593 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:30.593Z,1368739050.593 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:30.593Z,1368739050.593 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:30.594Z,1368739050.594 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:30.594Z,1368739050.594 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:30.995Z,1368739050.995 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:30.995Z,1368739050.995 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:30.995Z,1368739050.995 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:30.995Z,1368739050.995 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:31.397Z,1368739051.397 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:31.397Z,1368739051.397 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:31.397Z,1368739051.397 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:31.398Z,1368739051.398 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:31.398Z,1368739051.398 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:31.905Z,1368739051.905 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:31.905Z,1368739051.905 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:31.905Z,1368739051.905 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:31.905Z,1368739051.905 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:32.213Z,1368739052.213 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:32.213Z,1368739052.213 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:32.213Z,1368739052.213 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:32.213Z,1368739052.214 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:32.214Z,1368739052.214 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:32.670Z,1368739052.670 [DAT](ERROR): No response from remote modem
2013-05-16T21:17:32.685Z,1368739052.685 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:32.685Z,1368739052.685 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:32.685Z,1368739052.685 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:32.685Z,1368739052.685 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:33.013Z,1368739053.013 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:33.013Z,1368739053.013 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:33.013Z,1368739053.013 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:33.013Z,1368739053.013 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:33.014Z,1368739053.013 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:33.397Z,1368739053.397 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:33.397Z,1368739053.397 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:33.397Z,1368739053.397 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:33.398Z,1368739053.398 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:33.791Z,1368739053.792 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:33.792Z,1368739053.792 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:33.792Z,1368739053.792 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:33.792Z,1368739053.792 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:33.793Z,1368739053.793 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:34.236Z,1368739054.236 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:34.236Z,1368739054.236 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:34.236Z,1368739054.236 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:34.236Z,1368739054.236 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:34.609Z,1368739054.609 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:34.609Z,1368739054.609 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:34.609Z,1368739054.609 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:34.609Z,1368739054.609 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:34.610Z,1368739054.610 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:35.007Z,1368739055.007 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:35.007Z,1368739055.007 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:35.008Z,1368739055.008 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:35.008Z,1368739055.008 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:35.409Z,1368739055.409 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:35.409Z,1368739055.409 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:35.409Z,1368739055.409 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:35.410Z,1368739055.409 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:35.410Z,1368739055.410 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:35.793Z,1368739055.793 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:35.794Z,1368739055.793 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:35.794Z,1368739055.794 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:35.794Z,1368739055.794 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:36.197Z,1368739056.197 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:36.197Z,1368739056.197 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:36.198Z,1368739056.197 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:36.198Z,1368739056.198 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:36.198Z,1368739056.198 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:36.641Z,1368739056.641 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:36.641Z,1368739056.641 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:36.641Z,1368739056.641 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:36.641Z,1368739056.641 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:37.044Z,1368739057.044 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:37.044Z,1368739057.044 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:37.044Z,1368739057.044 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:37.045Z,1368739057.045 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:37.045Z,1368739057.045 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:37.409Z,1368739057.409 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:37.409Z,1368739057.409 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:37.409Z,1368739057.409 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:37.409Z,1368739057.409 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:37.813Z,1368739057.813 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:37.813Z,1368739057.813 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:37.813Z,1368739057.813 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:37.813Z,1368739057.813 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:37.814Z,1368739057.814 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:38.213Z,1368739058.213 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:38.213Z,1368739058.213 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:38.213Z,1368739058.213 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:38.213Z,1368739058.214 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:38.593Z,1368739058.593 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:38.593Z,1368739058.593 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:38.594Z,1368739058.593 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:38.594Z,1368739058.594 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:38.594Z,1368739058.594 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:39.033Z,1368739059.033 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:39.034Z,1368739059.033 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:39.034Z,1368739059.034 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:39.034Z,1368739059.034 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:39.396Z,1368739059.397 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:39.397Z,1368739059.397 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:39.397Z,1368739059.397 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:39.397Z,1368739059.397 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:39.398Z,1368739059.398 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:39.795Z,1368739059.795 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:39.795Z,1368739059.795 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:39.795Z,1368739059.796 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:39.796Z,1368739059.796 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:40.198Z,1368739060.198 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:40.198Z,1368739060.198 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:40.198Z,1368739060.198 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:40.199Z,1368739060.199 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:40.199Z,1368739060.199 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:40.609Z,1368739060.609 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:40.609Z,1368739060.609 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:40.609Z,1368739060.609 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:40.609Z,1368739060.609 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:41.007Z,1368739061.007 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:41.007Z,1368739061.007 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:41.008Z,1368739061.008 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:41.008Z,1368739061.008 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:41.008Z,1368739061.008 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:41.461Z,1368739061.461 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:41.461Z,1368739061.461 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:41.461Z,1368739061.461 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:41.461Z,1368739061.461 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:41.793Z,1368739061.793 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:41.793Z,1368739061.793 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:41.793Z,1368739061.793 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:41.794Z,1368739061.794 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:41.794Z,1368739061.794 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:42.262Z,1368739062.262 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:42.263Z,1368739062.263 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:42.263Z,1368739062.263 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:42.263Z,1368739062.263 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:42.658Z,1368739062.658 [DAT](ERROR): No response from remote modem
2013-05-16T21:17:42.673Z,1368739062.672 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:42.673Z,1368739062.673 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:42.673Z,1368739062.673 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:42.673Z,1368739062.673 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:42.674Z,1368739062.674 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:43.037Z,1368739063.037 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:43.037Z,1368739063.037 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:43.037Z,1368739063.037 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:43.037Z,1368739063.037 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:43.413Z,1368739063.413 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:43.413Z,1368739063.413 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:43.413Z,1368739063.413 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:43.414Z,1368739063.414 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:43.414Z,1368739063.414 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:43.849Z,1368739063.849 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:43.849Z,1368739063.849 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:43.849Z,1368739063.849 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:43.849Z,1368739063.849 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:44.197Z,1368739064.197 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:44.197Z,1368739064.197 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:44.197Z,1368739064.197 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:44.198Z,1368739064.198 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:44.198Z,1368739064.198 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:44.595Z,1368739064.595 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:44.595Z,1368739064.595 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:44.595Z,1368739064.595 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:44.595Z,1368739064.595 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:44.993Z,1368739064.993 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:44.993Z,1368739064.993 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:44.993Z,1368739064.993 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:44.994Z,1368739064.994 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:44.994Z,1368739064.994 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:45.413Z,1368739065.413 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:45.413Z,1368739065.413 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:45.413Z,1368739065.413 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:45.413Z,1368739065.413 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:45.812Z,1368739065.812 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:45.813Z,1368739065.813 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:45.813Z,1368739065.813 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:45.813Z,1368739065.813 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:45.813Z,1368739065.813 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:46.253Z,1368739066.253 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:46.253Z,1368739066.253 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:46.253Z,1368739066.253 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:46.253Z,1368739066.253 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:46.594Z,1368739066.594 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:46.594Z,1368739066.594 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:46.594Z,1368739066.594 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:46.595Z,1368739066.595 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:46.595Z,1368739066.595 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:46.990Z,1368739066.990 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:46.991Z,1368739066.991 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:46.991Z,1368739066.991 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:46.991Z,1368739066.991 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:47.455Z,1368739067.455 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:47.455Z,1368739067.455 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:47.455Z,1368739067.455 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:47.456Z,1368739067.456 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:47.456Z,1368739067.456 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:47.793Z,1368739067.793 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:47.794Z,1368739067.793 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:47.794Z,1368739067.794 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:47.794Z,1368739067.794 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:48.203Z,1368739068.203 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:48.203Z,1368739068.203 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:48.203Z,1368739068.203 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:48.204Z,1368739068.204 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:48.204Z,1368739068.204 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:48.613Z,1368739068.613 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:48.614Z,1368739068.614 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:48.614Z,1368739068.614 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:48.614Z,1368739068.614 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:49.042Z,1368739069.042 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:49.042Z,1368739069.042 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:49.042Z,1368739069.042 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:49.043Z,1368739069.043 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:49.043Z,1368739069.043 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:49.392Z,1368739069.392 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:49.392Z,1368739069.392 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:49.392Z,1368739069.392 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:49.392Z,1368739069.392 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:49.793Z,1368739069.793 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:49.793Z,1368739069.793 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:49.793Z,1368739069.793 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:49.794Z,1368739069.794 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:49.794Z,1368739069.794 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:50.197Z,1368739070.197 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:50.198Z,1368739070.197 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:50.198Z,1368739070.198 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:50.198Z,1368739070.198 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:50.595Z,1368739070.595 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:50.595Z,1368739070.595 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:50.595Z,1368739070.595 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:50.595Z,1368739070.595 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:50.596Z,1368739070.596 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:50.993Z,1368739070.993 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:50.993Z,1368739070.993 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:50.993Z,1368739070.993 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:50.994Z,1368739070.994 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:51.439Z,1368739071.439 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:51.440Z,1368739071.440 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:51.440Z,1368739071.440 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:51.440Z,1368739071.440 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:51.440Z,1368739071.440 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:51.803Z,1368739071.803 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:51.804Z,1368739071.804 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:51.804Z,1368739071.804 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:51.804Z,1368739071.804 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:52.273Z,1368739072.273 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:52.273Z,1368739072.273 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:52.274Z,1368739072.274 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:52.274Z,1368739072.274 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:52.275Z,1368739072.274 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:52.658Z,1368739072.658 [DAT](ERROR): No response from remote modem
2013-05-16T21:17:52.673Z,1368739072.673 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:52.673Z,1368739072.673 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:52.673Z,1368739072.673 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:52.673Z,1368739072.673 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:53.010Z,1368739073.010 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:53.010Z,1368739073.010 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:53.011Z,1368739073.011 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:53.011Z,1368739073.011 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:53.011Z,1368739073.011 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:53.394Z,1368739073.394 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:53.394Z,1368739073.394 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:53.394Z,1368739073.395 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:53.395Z,1368739073.395 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:53.833Z,1368739073.833 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:53.833Z,1368739073.833 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:53.833Z,1368739073.833 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:53.834Z,1368739073.834 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:53.834Z,1368739073.834 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:54.211Z,1368739074.211 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:54.212Z,1368739074.211 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:54.212Z,1368739074.212 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:54.212Z,1368739074.212 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:54.613Z,1368739074.613 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:54.613Z,1368739074.613 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:54.613Z,1368739074.613 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:54.613Z,1368739074.614 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:54.614Z,1368739074.614 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:55.009Z,1368739075.009 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:55.009Z,1368739075.009 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:55.009Z,1368739075.009 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:55.009Z,1368739075.009 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:55.392Z,1368739075.392 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:55.392Z,1368739075.392 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:55.392Z,1368739075.392 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:55.393Z,1368739075.392 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:55.393Z,1368739075.393 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:55.793Z,1368739075.793 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:55.794Z,1368739075.794 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:55.794Z,1368739075.794 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:55.794Z,1368739075.794 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:56.237Z,1368739076.237 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:56.237Z,1368739076.237 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:56.237Z,1368739076.237 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:56.237Z,1368739076.237 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:56.238Z,1368739076.238 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:56.594Z,1368739076.594 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:56.594Z,1368739076.594 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:56.594Z,1368739076.594 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:56.594Z,1368739076.594 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:57.013Z,1368739077.013 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:57.014Z,1368739077.014 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:57.014Z,1368739077.014 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:57.031Z,1368739077.030 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:57.031Z,1368739077.031 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:57.468Z,1368739077.468 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:57.468Z,1368739077.468 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:57.468Z,1368739077.468 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:57.468Z,1368739077.468 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:57.807Z,1368739077.807 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:57.807Z,1368739077.807 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:57.808Z,1368739077.807 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:57.808Z,1368739077.808 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:57.808Z,1368739077.808 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:58.199Z,1368739078.199 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:58.199Z,1368739078.199 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:58.199Z,1368739078.199 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:58.199Z,1368739078.199 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:58.633Z,1368739078.633 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:58.634Z,1368739078.634 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:58.634Z,1368739078.634 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:58.635Z,1368739078.635 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:58.635Z,1368739078.635 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:58.999Z,1368739078.999 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:58.000Z,1368739079.000 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:58.000Z,1368739079.000 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:58.000Z,1368739079.000 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:17:59.409Z,1368739079.409 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:17:59.409Z,1368739079.409 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:17:59.409Z,1368739079.409 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:17:59.410Z,1368739079.410 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:17:59.410Z,1368739079.410 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:17:59.804Z,1368739079.804 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:17:59.804Z,1368739079.804 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:17:59.804Z,1368739079.804 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:17:59.804Z,1368739079.804 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:18:00.195Z,1368739080.195 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:18:00.196Z,1368739080.195 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:18:00.196Z,1368739080.196 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:18:00.196Z,1368739080.196 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:18:00.196Z,1368739080.196 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:18:00.594Z,1368739080.594 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:18:00.594Z,1368739080.594 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:18:00.594Z,1368739080.594 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:18:00.594Z,1368739080.594 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:18:01.042Z,1368739081.042 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:18:01.042Z,1368739081.042 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:18:01.042Z,1368739081.042 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:18:01.043Z,1368739081.043 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:18:01.043Z,1368739081.043 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:18:01.411Z,1368739081.411 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:18:01.411Z,1368739081.411 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:18:01.411Z,1368739081.411 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:18:01.411Z,1368739081.411 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:18:01.813Z,1368739081.813 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:18:01.813Z,1368739081.813 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:18:01.813Z,1368739081.813 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:18:01.814Z,1368739081.814 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:18:01.814Z,1368739081.814 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:18:02.255Z,1368739082.255 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:18:02.255Z,1368739082.255 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:18:02.255Z,1368739082.255 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:18:02.256Z,1368739082.256 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:18:02.658Z,1368739082.658 [DAT](ERROR): No response from remote modem
2013-05-16T21:18:02.665Z,1368739082.665 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:18:02.665Z,1368739082.665 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:18:02.665Z,1368739082.665 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:18:02.666Z,1368739082.666 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:18:02.667Z,1368739082.667 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:18:03.037Z,1368739083.037 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:18:03.037Z,1368739083.037 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:18:03.037Z,1368739083.037 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:18:03.037Z,1368739083.037 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:18:03.439Z,1368739083.439 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:18:03.440Z,1368739083.440 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:18:03.440Z,1368739083.440 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:18:03.440Z,1368739083.440 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:18:03.440Z,1368739083.440 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:18:03.807Z,1368739083.807 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:18:03.808Z,1368739083.808 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:18:03.808Z,1368739083.808 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:18:03.808Z,1368739083.808 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-05-16T21:18:04.199Z,1368739084.199 [dat_on:TestDrive:Data] Running Loop=1
2013-05-16T21:18:04.199Z,1368739084.199 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-05-16T21:18:04.199Z,1368739084.199 [dat_on:TestDrive:Data:A] Running Loop=1
2013-05-16T21:18:04.199Z,1368739084.200 [dat_on:TestDrive:Data:A] Stopped
2013-05-16T21:18:04.200Z,1368739084.200 [dat_on:TestDrive:Data:B] Running Loop=1
2013-05-16T21:18:04.593Z,1368739084.593 [dat_on:TestDrive:Data:B] Stopped
2013-05-16T21:18:04.594Z,1368739084.594 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-05-16T21:18:04.594Z,1368739084.594 [dat_on:TestDrive:Data] Stopped
2013-05-16T21:18:04.594Z,1368739084.594 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data