2013-04-23T15:34:30.274Z,1366731270.274 [Supervisor](DEBUG): Initializing supervisor.
2013-04-23T15:34:30.276Z,1366731270.276 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2013-04-23T15:34:30.277Z,1366731270.277 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2013-04-23T15:34:30.278Z,1366731270.278 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2013-04-23T15:34:30.282Z,1366731270.282 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2013-04-23T15:34:30.292Z,1366731270.292 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2013-04-23T15:34:30.293Z,1366731270.293 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2013-04-23T15:34:30.294Z,1366731270.294 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2013-04-23T15:34:30.295Z,1366731270.295 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0
2013-04-23T15:34:30.296Z,1366731270.296 [Supervisor](INFO): Looking for Config files in directory: Config/
2013-04-23T15:34:30.297Z,1366731270.297 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2013-04-23T15:34:30.575Z,1366731270.575 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2013-04-23T15:34:30.575Z,1366731270.575 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2013-04-23T15:34:30.762Z,1366731270.763 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2013-04-23T15:34:30.763Z,1366731270.763 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2013-04-23T15:34:30.848Z,1366731270.848 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2013-04-23T15:34:30.848Z,1366731270.848 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2013-04-23T15:34:31.026Z,1366731271.026 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2013-04-23T15:34:31.027Z,1366731271.027 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2013-04-23T15:34:31.166Z,1366731271.166 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2013-04-23T15:34:31.167Z,1366731271.167 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2013-04-23T15:34:31.397Z,1366731271.397 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2013-04-23T15:34:31.397Z,1366731271.397 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2013-04-23T15:34:31.566Z,1366731271.566 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2013-04-23T15:34:31.567Z,1366731271.567 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2013-04-23T15:34:31.816Z,1366731271.816 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2013-04-23T15:34:31.817Z,1366731271.817 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2013-04-23T15:34:31.915Z,1366731271.915 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2013-04-23T15:34:31.916Z,1366731271.916 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2013-04-23T15:34:32.311Z,1366731272.311 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2013-04-23T15:34:32.312Z,1366731272.312 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2013-04-23T15:34:32.425Z,1366731272.425 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2013-04-23T15:34:32.426Z,1366731272.426 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2013-04-23T15:34:32.512Z,1366731272.512 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2013-04-23T15:34:32.512Z,1366731272.513 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2013-04-23T15:34:32.617Z,1366731272.617 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2013-04-23T15:34:32.745Z,1366731272.745 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2013-04-23T15:34:32.831Z,1366731272.831 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2013-04-23T15:34:32.933Z,1366731272.933 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2013-04-23T15:34:33.033Z,1366731273.033 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2013-04-23T15:34:33.150Z,1366731273.151 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2013-04-23T15:34:33.244Z,1366731273.244 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2013-04-23T15:34:33.331Z,1366731273.331 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2013-04-23T15:34:33.357Z,1366731273.357 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2013-04-23T15:34:33.505Z,1366731273.505 [InternalSim] Loaded
2013-04-23T15:34:33.505Z,1366731273.505 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2013-04-23T15:34:33.506Z,1366731273.506 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2013-04-23T15:34:33.507Z,1366731273.507 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2013-04-23T15:34:33.562Z,1366731273.562 [SBIT](DEBUG): Construct Startup Built In Test.
2013-04-23T15:34:33.592Z,1366731273.592 [SBIT] Loaded
2013-04-23T15:34:33.592Z,1366731273.592 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2013-04-23T15:34:33.593Z,1366731273.593 [IBIT](DEBUG): Construct Initiated Built In Test.
2013-04-23T15:34:33.621Z,1366731273.621 [IBIT] Loaded
2013-04-23T15:34:33.622Z,1366731273.622 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2013-04-23T15:34:33.625Z,1366731273.625 [CBIT](DEBUG): Construct CBIT Built In Test.
2013-04-23T15:34:33.743Z,1366731273.743 [CBIT] Loaded
2013-04-23T15:34:33.743Z,1366731273.743 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2013-04-23T15:34:33.744Z,1366731273.744 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2013-04-23T15:34:33.744Z,1366731273.744 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2013-04-23T15:34:33.892Z,1366731273.892 [BuoyancyServo] Loaded
2013-04-23T15:34:33.892Z,1366731273.892 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2013-04-23T15:34:33.905Z,1366731273.905 [ElevatorServo] Loaded
2013-04-23T15:34:33.905Z,1366731273.905 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2013-04-23T15:34:33.917Z,1366731273.917 [MassServo] Loaded
2013-04-23T15:34:33.917Z,1366731273.917 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2013-04-23T15:34:33.929Z,1366731273.929 [RudderServo] Loaded
2013-04-23T15:34:33.929Z,1366731273.930 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2013-04-23T15:34:33.941Z,1366731273.941 [ThrusterServo] Loaded
2013-04-23T15:34:33.942Z,1366731273.942 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2013-04-23T15:34:33.942Z,1366731273.942 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2013-04-23T15:34:33.943Z,1366731273.943 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2013-04-23T15:34:33.960Z,1366731273.960 [DepthRateCalculator] Loaded
2013-04-23T15:34:33.960Z,1366731273.960 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2013-04-23T15:34:36.990Z,1366731276.990 [HFRadarModelCalc] Loaded
2013-04-23T15:34:36.990Z,1366731276.990 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2013-04-23T15:34:37.006Z,1366731277.006 [NavChart] Loaded
2013-04-23T15:34:37.007Z,1366731277.007 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2013-04-23T15:34:37.013Z,1366731277.013 [PitchRateCalculator] Loaded
2013-04-23T15:34:37.013Z,1366731277.013 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2013-04-23T15:34:37.019Z,1366731277.019 [SpeedCalculator] Loaded
2013-04-23T15:34:37.019Z,1366731277.019 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2013-04-23T15:34:37.034Z,1366731277.034 [TempGradientCalculator] Loaded
2013-04-23T15:34:37.034Z,1366731277.034 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2013-04-23T15:34:37.040Z,1366731277.040 [YawRateCalculator] Loaded
2013-04-23T15:34:37.041Z,1366731277.041 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2013-04-23T15:34:37.081Z,1366731277.081 [Navigation] Loaded
2013-04-23T15:34:37.082Z,1366731277.082 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2013-04-23T15:34:37.082Z,1366731277.082 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2013-04-23T15:34:37.083Z,1366731277.083 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2013-04-23T15:34:37.294Z,1366731277.295 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2013-04-23T15:34:37.295Z,1366731277.295 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2013-04-23T15:34:37.316Z,1366731277.316 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2013-04-23T15:34:37.317Z,1366731277.317 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2013-04-23T15:34:37.355Z,1366731277.355 [VerticalControl](DEBUG): Construct VerticalControl.
2013-04-23T15:34:37.449Z,1366731277.449 [VerticalControl] Loaded
2013-04-23T15:34:37.449Z,1366731277.449 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2013-04-23T15:34:37.450Z,1366731277.450 [HorizontalControl](DEBUG): Construct HorizontalControl.
2013-04-23T15:34:37.506Z,1366731277.506 [HorizontalControl] Loaded
2013-04-23T15:34:37.507Z,1366731277.507 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2013-04-23T15:34:37.508Z,1366731277.508 [SpeedControl](DEBUG): Construct SpeedControl.
2013-04-23T15:34:37.509Z,1366731277.509 [SpeedControl] Loaded
2013-04-23T15:34:37.510Z,1366731277.510 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2013-04-23T15:34:37.511Z,1366731277.511 [LoopControl](DEBUG): Construct LoopControl.
2013-04-23T15:34:37.511Z,1366731277.511 [LoopControl] Loaded
2013-04-23T15:34:37.511Z,1366731277.511 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2013-04-23T15:34:37.512Z,1366731277.512 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2013-04-23T15:34:37.512Z,1366731277.512 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2013-04-23T15:34:37.518Z,1366731277.518 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2013-04-23T15:34:37.522Z,1366731277.523 [AsyncPiEstimator] Loaded
2013-04-23T15:34:37.523Z,1366731277.523 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2013-04-23T15:34:37.524Z,1366731277.524 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 4063B4E0
2013-04-23T15:34:37.525Z,1366731277.525 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2013-04-23T15:34:37.525Z,1366731277.525 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2013-04-23T15:34:37.649Z,1366731277.649 [AHRS_sp3003D] Loaded
2013-04-23T15:34:37.649Z,1366731277.649 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2013-04-23T15:34:37.906Z,1366731277.906 [Batt_Ocean_Server] Loaded
2013-04-23T15:34:37.906Z,1366731277.906 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2013-04-23T15:34:37.920Z,1366731277.920 [Depth_Keller] Loaded
2013-04-23T15:34:37.920Z,1366731277.920 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2013-04-23T15:34:37.926Z,1366731277.926 [DropWeight] Loaded
2013-04-23T15:34:37.926Z,1366731277.926 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2013-04-23T15:34:38.099Z,1366731278.099 [DVL_micro] Loaded
2013-04-23T15:34:38.100Z,1366731278.099 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2013-04-23T15:34:38.101Z,1366731278.101 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 406BF4E0
2013-04-23T15:34:38.183Z,1366731278.182 [NAL9602] Loaded
2013-04-23T15:34:38.183Z,1366731278.183 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2013-04-23T15:34:38.233Z,1366731278.233 [Onboard] Loaded
2013-04-23T15:34:38.233Z,1366731278.233 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2013-04-23T15:34:38.240Z,1366731278.240 [Radio_Freewave] Loaded
2013-04-23T15:34:38.240Z,1366731278.240 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2013-04-23T15:34:38.334Z,1366731278.334 [DAT] Loaded
2013-04-23T15:34:38.335Z,1366731278.335 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2013-04-23T15:34:38.335Z,1366731278.335 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2013-04-23T15:34:38.336Z,1366731278.336 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2013-04-23T15:34:38.407Z,1366731278.407 [CTD_NeilBrown] Loaded
2013-04-23T15:34:38.407Z,1366731278.407 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2013-04-23T15:34:38.408Z,1366731278.408 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407114E0
2013-04-23T15:34:38.424Z,1366731278.424 [PAR_Licor] Loaded
2013-04-23T15:34:38.424Z,1366731278.424 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2013-04-23T15:34:38.455Z,1366731278.455 [WetLabsBB2FL] Loaded
2013-04-23T15:34:38.455Z,1366731278.455 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2013-04-23T15:34:38.456Z,1366731278.456 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407414E0
2013-04-23T15:34:38.457Z,1366731278.457 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2013-04-23T15:34:38.459Z,1366731278.459 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2013-04-23T15:34:38.460Z,1366731278.460 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2013-04-23T15:34:38.467Z,1366731278.467 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2013-04-23T15:34:38.468Z,1366731278.468 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407714E0
2013-04-23T15:34:38.472Z,1366731278.472 [Supervisor](DEBUG): Running supervisor.
2013-04-23T15:34:38.473Z,1366731278.473 [CommandLine](INFO): Thread ID is 7091
2013-04-23T15:34:38.476Z,1366731278.476 [controlThread](INFO): Thread ID is 7090
2013-04-23T15:34:38.476Z,1366731278.476 [controlThread](DEBUG): Initializing ControlThread
2013-04-23T15:34:38.476Z,1366731278.476 [CycleStarter](INFO): Thread ID is 7089
2013-04-23T15:34:38.477Z,1366731278.477 [InternalSim](DEBUG):  InternalSim initializing...
2013-04-23T15:34:38.513Z,1366731278.513 [logger](INFO): Thread ID is 7092
2013-04-23T15:34:38.534Z,1366731278.534 [SBIT](INFO): Initialize SBIT Component.
2013-04-23T15:34:38.535Z,1366731278.535 [SBIT](IMPORTANT): Tethys CM Info:
$Rev:10302
2013-04-23T15:34:38.535Z,1366731278.535 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2013-04-23T15:34:38.536Z,1366731278.536 [SBIT](FAULT): Kernel Reporting Different Version From Configuration.
Expected:#634 PREEMPT Wed Feb 13 10:21:48 PST 2013
Kernel Reported:#625 PREEMPT Mon Nov 5 10:42:26 PST 2012
2013-04-23T15:34:38.536Z,1366731278.536 [IBIT](INFO): Initialize IBIT Component.
2013-04-23T15:34:38.537Z,1366731278.537 [CBIT](DEBUG): Initialize CBIT Component.
2013-04-23T15:34:38.537Z,1366731278.537 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET.
2013-04-23T15:34:38.547Z,1366731278.547 [AsyncPiEstimator](INFO): Thread ID is 7153
2013-04-23T15:34:38.547Z,1366731278.547 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2013-04-23T15:34:38.567Z,1366731278.568 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-04-23T15:34:38.568Z,1366731278.568 [NavChart](DEBUG): Initialize NavChart Derivation.
2013-04-23T15:34:38.568Z,1366731278.569 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2013-04-23T15:34:38.569Z,1366731278.569 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2013-04-23T15:34:38.569Z,1366731278.569 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2013-04-23T15:34:38.571Z,1366731278.571 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2013-04-23T15:34:38.571Z,1366731278.571 [Navigation](DEBUG): Initializing Navigation.
2013-04-23T15:34:38.571Z,1366731278.571 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2013-04-23T15:34:38.573Z,1366731278.573 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2013-04-23T15:34:38.574Z,1366731278.574 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2013-04-23T15:34:38.575Z,1366731278.575 [LoopControl](DEBUG): Initialize LoopControlComponent.
2013-04-23T15:34:38.577Z,1366731278.577 [DVL_micro](INFO): Thread ID is 7154
2013-04-23T15:34:38.593Z,1366731278.593 [DVL_micro](INFO): pause:Powering down
2013-04-23T15:34:38.595Z,1366731278.595 [CTD_NeilBrown](INFO): Thread ID is 7155
2013-04-23T15:34:38.596Z,1366731278.596 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2013-04-23T15:34:38.599Z,1366731278.599 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2013-04-23T15:34:38.606Z,1366731278.606 [WetLabsBB2FL](INFO): Thread ID is 7156
2013-04-23T15:34:38.607Z,1366731278.607 [WetLabsBB2FL](INFO): Powering down
2013-04-23T15:34:38.643Z,1366731278.643 [NavChartDb](INFO): Thread ID is 7157
2013-04-23T15:34:38.646Z,1366731278.645 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2013-04-23T15:34:38.646Z,1366731278.646 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2013-04-23T15:34:38.647Z,1366731278.647 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2013-04-23T15:34:38.647Z,1366731278.647 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2013-04-23T15:34:38.647Z,1366731278.647 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2013-04-23T15:34:38.648Z,1366731278.648 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2013-04-23T15:34:38.648Z,1366731278.648 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2013-04-23T15:34:38.648Z,1366731278.648 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2013-04-23T15:34:38.648Z,1366731278.648 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2013-04-23T15:34:40.005Z,1366731280.005 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2013-04-23T15:34:40.039Z,1366731280.039 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2013-04-23T15:34:40.039Z,1366731280.039 [DropWeight] Hardware Fault, FailCount= 1
2013-04-23T15:34:40.039Z,1366731280.039 [DropWeight](ERROR): Hardware Fault
2013-04-23T15:34:40.042Z,1366731280.042 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2013-04-23T15:34:40.078Z,1366731280.078 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2013-04-23T15:34:40.096Z,1366731280.096 [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-04-23T15:34:40.097Z,1366731280.097 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2013-04-23T15:34:40.186Z,1366731280.186 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2013-04-23T15:34:40.188Z,1366731280.188 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2013-04-23T15:34:40.191Z,1366731280.191 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-04-23T15:34:40.212Z,1366731280.212 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2013-04-23T15:34:40.239Z,1366731280.239 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-04-23T15:34:40.246Z,1366731280.246 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2013-04-23T15:34:40.277Z,1366731280.277 [Default:D.SetSpeed](DEBUG): Construct.
2013-04-23T15:34:40.280Z,1366731280.280 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2013-04-23T15:34:40.285Z,1366731280.285 [Default:F.Wait](DEBUG): Construct Wait.
2013-04-23T15:34:40.300Z,1366731280.300 [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-04-23T15:34:40.305Z,1366731280.305 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,NAL9602,Onboard,Radio_Freewave,DAT,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,
2013-04-23T15:34:40.431Z,1366731280.431 [Depth_Keller](ERROR): Pressure reading out of range: 1831.078247 decibar
2013-04-23T15:34:40.491Z,1366731280.490 [Radio_Freewave](INFO): Powering up
2013-04-23T15:34:40.496Z,1366731280.496 [DAT](INFO): Powering up
2013-04-23T15:34:40.496Z,1366731280.496 [DAT](DEBUG): Initializing DAT.
2013-04-23T15:34:40.867Z,1366731280.867 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-04-23T15:34:40.869Z,1366731280.869 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-04-23T15:34:40.890Z,1366731280.890 [ElevatorServo](DEBUG): Initializing EZServoServo.
2013-04-23T15:34:40.902Z,1366731280.902 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2013-04-23T15:34:40.908Z,1366731280.908 [MassServo](DEBUG): Initializing EZServoServo.
2013-04-23T15:34:40.938Z,1366731280.938 [MassServo](DEBUG): Initializing MassServo.
2013-04-23T15:34:40.944Z,1366731280.944 [RudderServo](DEBUG): Initializing EZServoServo.
2013-04-23T15:34:40.951Z,1366731280.951 [RudderServo](DEBUG): Initializing RudderServo.
2013-04-23T15:34:40.964Z,1366731280.964 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-04-23T15:34:40.966Z,1366731280.967 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-04-23T15:34:40.000Z,1366731281.000 [CBIT](ERROR): Hardware Fault in component: DropWeight
2013-04-23T15:34:41.000Z,1366731281.000 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2013-04-23T15:34:43.197Z,1366731283.197 [NAL9602](INFO): Powering up NAL9602
2013-04-23T15:34:53.639Z,1366731293.639 [NAL9602](INFO): NAL9602 initialized
2013-04-23T15:34:54.088Z,1366731294.088 [SBIT](IMPORTANT): Beginning Startup BIT
2013-04-23T15:34:54.091Z,1366731294.091 [CBIT](IMPORTANT): Beginning GF scan
2013-04-23T15:35:00.569Z,1366731300.569 [DAT](INFO): Powering down
2013-04-23T15:35:02.215Z,1366731302.215 [CommandLine](IMPORTANT): got command failComponent
2013-04-23T15:35:02.215Z,1366731302.215 [CommandLine](IMPORTANT): Failed components:
2013-04-23T15:35:02.215Z,1366731302.215 [CommandLine](IMPORTANT): DropWeight: Hardware Fault
2013-04-23T15:35:20.479Z,1366731320.479 [CBIT](IMPORTANT): No ground fault detected
2013-04-23T15:35:29.403Z,1366731329.403 [CommandLine](IMPORTANT): got command show stack
2013-04-23T15:35:29.403Z,1366731329.403 [CommandLine](INFO): Behavior Stack:

2013-04-23T15:35:29.403Z,1366731329.403 [MissionManager](INFO): Mission loaded, but not running.
2013-04-23T15:35:42.947Z,1366731342.947 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2013-04-23T15:35:45.943Z,1366731345.943 [CommandLine](IMPORTANT): got command show variable DAT
2013-04-23T15:35:45.949Z,1366731345.949 [CommandLine](INFO): Config/vehicle.sendDataToShore (bool)
2013-04-23T15:35:45.951Z,1366731345.951 [CommandLine](INFO): Config/vehicle.DAT_card (none)
2013-04-23T15:35:45.952Z,1366731345.952 [CommandLine](INFO): Config/vehicle.DAT_uart (none)
2013-04-23T15:35:45.952Z,1366731345.952 [CommandLine](INFO): Config/vehicle.DAT_baud (bit_per_second)
2013-04-23T15:35:45.955Z,1366731345.955 [CommandLine](INFO): Config/Sensor.DAT_enable (bool)
2013-04-23T15:35:45.956Z,1366731345.956 [CommandLine](INFO): Config/Sensor.DAT_useHardware (bool)
2013-04-23T15:35:45.956Z,1366731345.956 [CommandLine](INFO): Config/Sensor.DAT_remoteAddress (count)
2013-04-23T15:35:45.956Z,1366731345.956 [CommandLine](INFO): Config/Sensor.DAT_rotationOffset (degree)
2013-04-23T15:35:45.981Z,1366731345.981 [CommandLine](INFO): Config/Simulator.oceanModelData (none)
2013-04-23T15:35:46.005Z,1366731346.005 [CommandLine](INFO): DAT.onewayRequestedCmd (bool)
2013-04-23T15:35:46.006Z,1366731346.006 [CommandLine](INFO): DAT.homing_target_range (meter)
2013-04-23T15:35:46.042Z,1366731346.042 [CommandLine](INFO): DAT.homing_target_azimuth (degree)
2013-04-23T15:35:46.042Z,1366731346.042 [CommandLine](INFO): DAT.homing_target_elevation (degree)
2013-04-23T15:35:46.043Z,1366731346.043 [CommandLine](INFO): DAT.homing_target_heading (degree)
2013-04-23T15:35:46.043Z,1366731346.043 [CommandLine](INFO): DAT.LVL1 (count)
2013-04-23T15:35:46.043Z,1366731346.043 [CommandLine](INFO): DAT.LVL2 (count)
2013-04-23T15:35:46.044Z,1366731346.044 [CommandLine](INFO): DAT.LVL3 (count)
2013-04-23T15:35:46.044Z,1366731346.044 [CommandLine](INFO): DAT.LVL4 (count)
2013-04-23T15:35:46.045Z,1366731346.045 [CommandLine](INFO): DAT.AGC (count)
2013-04-23T15:35:46.045Z,1366731346.045 [CommandLine](INFO): DAT.IDXPeak (count)
2013-04-23T15:35:46.045Z,1366731346.045 [CommandLine](INFO): DAT.IDXFit (degree)
2013-04-23T15:35:46.046Z,1366731346.046 [CommandLine](INFO): DAT.IDXPhase (degree)
2013-04-23T15:35:46.058Z,1366731346.058 [CommandLine](INFO): DAT.phaseA (degree)
2013-04-23T15:35:46.058Z,1366731346.059 [CommandLine](INFO): DAT.phaseB (degree)
2013-04-23T15:35:46.059Z,1366731346.059 [CommandLine](INFO): DAT.phaseC (degree)
2013-04-23T15:35:46.059Z,1366731346.059 [CommandLine](INFO): DAT.vectorMagnitude (degree)
2013-04-23T15:35:46.060Z,1366731346.060 [CommandLine](INFO): DAT.rawAzimuth (degree)
2013-04-23T15:35:46.060Z,1366731346.060 [CommandLine](INFO): DAT.rawElevation (degree)
2013-04-23T15:35:46.060Z,1366731346.060 [CommandLine](INFO): DAT.calibratedAzimuth (degree)
2013-04-23T15:35:46.061Z,1366731346.061 [CommandLine](INFO): DAT.calibratedElevation (degree)
2013-04-23T15:35:46.064Z,1366731346.063 [CommandLine](INFO): DAT.durationOfLastRun (second)
2013-04-23T15:35:46.067Z,1366731346.067 [CommandLine](INFO): DAT.component_voltage (volt)
2013-04-23T15:35:46.067Z,1366731346.067 [CommandLine](INFO): DAT.component_avgVoltage (volt)
2013-04-23T15:35:46.067Z,1366731346.067 [CommandLine](INFO): DAT.component_current (milliampere)
2013-04-23T15:35:46.068Z,1366731346.068 [CommandLine](INFO): DAT.component_avgCurrent (milliampere)
2013-04-23T15:35:48.177Z,1366731348.177 [SBIT](IMPORTANT): SBIT PASSED
2013-04-23T15:35:48.573Z,1366731348.573 [MissionManager](IMPORTANT): Started mission Startup
2013-04-23T15:35:48.573Z,1366731348.573 [Startup] Running Loop=1
2013-04-23T15:35:48.573Z,1366731348.573 [Startup](INFO): Aggregate::initialize Startup
2013-04-23T15:35:48.573Z,1366731348.573 [Startup:A.GoToSurface] Running Loop=1
2013-04-23T15:35:48.573Z,1366731348.573 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-04-23T15:35:48.580Z,1366731348.580 [Startup:StartupSatComms] Running Loop=1
2013-04-23T15:35:48.580Z,1366731348.580 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2013-04-23T15:35:48.580Z,1366731348.580 [Startup:StartupSatComms:A] Running Loop=1
2013-04-23T15:35:48.983Z,1366731348.983 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-04-23T15:35:54.807Z,1366731354.807 [CommandLine](IMPORTANT): got command report touch DAT.homing_target_range
2013-04-23T15:36:01.767Z,1366731361.767 [CommandLine](IMPORTANT): got command report touch DAT.phaseA
2013-04-23T15:36:16.479Z,1366731376.479 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2013-04-23T15:36:28.695Z,1366731388.695 [CommandLine](IMPORTANT): got command set NAL9602.latitude_fix 36.799999 degree
2013-04-23T15:36:28.777Z,1366731388.777 [Startup:StartupSatComms:A] Stopped
2013-04-23T15:36:28.777Z,1366731388.777 [Startup:StartupSatComms:B] Running Loop=1
2013-04-23T15:36:29.172Z,1366731389.172 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-04-23T15:36:31.591Z,1366731391.591 [CommandLine](IMPORTANT): got command show stack
2013-04-23T15:36:31.591Z,1366731391.591 [CommandLine](INFO): Behavior Stack:

2013-04-23T15:36:31.591Z,1366731391.591 [Startup](INFO): Priority 0: Startup:A.GoToSurface
2013-04-23T15:36:31.591Z,1366731391.591 [Startup:StartupSatComms](INFO): Priority 1: Startup:StartupSatComms:B
2013-04-23T15:36:33.356Z,1366731393.356 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-04-23T15:36:37.587Z,1366731397.587 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-04-23T15:36:37.719Z,1366731397.719 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2013-04-23T15:36:41.585Z,1366731401.585 [Startup:StartupSatComms:B] Stopped
2013-04-23T15:36:41.585Z,1366731401.585 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2013-04-23T15:36:41.585Z,1366731401.585 [Startup:StartupSatComms] Stopped
2013-04-23T15:36:41.585Z,1366731401.585 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2013-04-23T15:36:41.586Z,1366731401.586 [Startup](INFO): Completed Startup
2013-04-23T15:36:41.586Z,1366731401.586 [Startup] Stopped
2013-04-23T15:36:41.586Z,1366731401.586 [Startup](INFO): Aggregate::uninitialize Startup
2013-04-23T15:36:41.586Z,1366731401.586 [Startup:A.GoToSurface] Stopped
2013-04-23T15:36:41.586Z,1366731401.586 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-04-23T15:36:41.903Z,1366731401.903 [MissionManager](IMPORTANT): Started mission Default
2013-04-23T15:36:41.903Z,1366731401.903 [Default] Running Loop=1
2013-04-23T15:36:41.903Z,1366731401.903 [Default](INFO): Aggregate::initialize Default
2013-04-23T15:36:41.903Z,1366731401.903 [Default:D.SetSpeed] Running Loop=1
2013-04-23T15:36:41.903Z,1366731401.903 [Default:D.SetSpeed](DEBUG): Initialize.
2013-04-23T15:36:41.904Z,1366731401.904 [Default:E.GoToSurface] Running Loop=1
2013-04-23T15:36:41.904Z,1366731401.904 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-04-23T15:36:41.904Z,1366731401.904 [Default:Iridium] Running Loop=1
2013-04-23T15:36:41.904Z,1366731401.904 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2013-04-23T15:36:41.904Z,1366731401.904 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-04-23T15:36:41.904Z,1366731401.904 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2013-04-23T15:36:41.905Z,1366731401.905 [Default:Iridium:B.GoToSurface] Running Loop=1
2013-04-23T15:36:41.905Z,1366731401.905 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-04-23T15:36:41.905Z,1366731401.905 [Default:E.GoToSurface] Running Loop=1
2013-04-23T15:36:41.910Z,1366731401.910 [Default:D.SetSpeed] Running Loop=1
2013-04-23T15:36:41.932Z,1366731401.932 [Default:Iridium:B.GoToSurface] Stopped
2013-04-23T15:36:41.932Z,1366731401.932 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-04-23T15:36:41.932Z,1366731401.932 [Default:Iridium:Read_Iridium] Running Loop=1
2013-04-23T15:36:41.932Z,1366731401.932 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-04-23T15:36:41.937Z,1366731401.937 [Default:GPS] Running Loop=1
2013-04-23T15:36:41.937Z,1366731401.937 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2013-04-23T15:36:41.937Z,1366731401.937 [Default:GPS:A.SetSpeed] Running Loop=1
2013-04-23T15:36:41.937Z,1366731401.937 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2013-04-23T15:36:41.938Z,1366731401.938 [Default:GPS:B.GoToSurface] Running Loop=1
2013-04-23T15:36:41.938Z,1366731401.938 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-04-23T15:36:41.983Z,1366731401.983 [Default:GPS:B.GoToSurface] Stopped
2013-04-23T15:36:41.983Z,1366731401.983 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-04-23T15:36:41.983Z,1366731401.983 [Default:GPS:Read_GPS] Running Loop=1
2013-04-23T15:36:41.983Z,1366731401.983 [Default:GPS:A.SetSpeed] Running Loop=1
2013-04-23T15:36:42.111Z,1366731402.111 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-04-23T15:36:42.114Z,1366731402.114 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-04-23T15:36:43.231Z,1366731403.231 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2013-04-23T15:36:46.787Z,1366731406.787 [Default:Iridium:Read_Iridium] Stopped
2013-04-23T15:36:46.787Z,1366731406.787 [Default:Iridium](INFO): Completed Default:Iridium
2013-04-23T15:36:46.787Z,1366731406.787 [Default:Iridium] Stopped
2013-04-23T15:36:46.787Z,1366731406.787 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2013-04-23T15:36:46.787Z,1366731406.787 [Default:Iridium:A.SetSpeed] Stopped
2013-04-23T15:36:46.788Z,1366731406.787 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2013-04-23T15:36:46.788Z,1366731406.788 [Default:F.Wait] Running Loop=1
2013-04-23T15:36:46.788Z,1366731406.788 [Default:F.Wait](DEBUG): Initialize Wait Component.
2013-04-23T15:36:49.518Z,1366731409.519 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/dat_on.xml
2013-04-23T15:36:49.519Z,1366731409.519 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/dat_on.xml
2013-04-23T15:36:49.535Z,1366731409.535 [MissionManager](INFO): DefineArg dat_on.MassDefault = 0.004000 n/a
2013-04-23T15:36:49.537Z,1366731409.537 [dat_on:A.Pitch](DEBUG): Construct.
2013-04-23T15:36:49.548Z,1366731409.548 [dat_on:TestDrive:C.Wait](DEBUG): Construct Wait.
2013-04-23T15:36:49.553Z,1366731409.553 [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-04-23T15:36:49.553Z,1366731409.553 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/dat_on.xml
2013-04-23T15:36:49.629Z,1366731409.629 [Default] Stopped
2013-04-23T15:36:49.629Z,1366731409.629 [Default](INFO): Aggregate::uninitialize Default
2013-04-23T15:36:49.629Z,1366731409.629 [Default:GPS] Stopped
2013-04-23T15:36:49.629Z,1366731409.629 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2013-04-23T15:36:49.629Z,1366731409.629 [Default:GPS:A.SetSpeed] Stopped
2013-04-23T15:36:49.629Z,1366731409.629 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2013-04-23T15:36:49.629Z,1366731409.629 [Default:GPS:Read_GPS] Stopped
2013-04-23T15:36:49.629Z,1366731409.629 [Default:D.SetSpeed] Stopped
2013-04-23T15:36:49.629Z,1366731409.629 [Default:D.SetSpeed](DEBUG): Uninitialize.
2013-04-23T15:36:49.629Z,1366731409.629 [Default:E.GoToSurface] Stopped
2013-04-23T15:36:49.629Z,1366731409.629 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-04-23T15:36:49.630Z,1366731409.630 [Default:F.Wait] Stopped
2013-04-23T15:36:49.630Z,1366731409.630 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2013-04-23T15:36:49.630Z,1366731409.630 [MissionManager](IMPORTANT): Started mission dat_on
2013-04-23T15:36:49.630Z,1366731409.630 [dat_on] Running Loop=1
2013-04-23T15:36:49.630Z,1366731409.630 [dat_on](INFO): Aggregate::initialize dat_on
2013-04-23T15:36:49.630Z,1366731409.630 [dat_on:A.Pitch] Running Loop=1
2013-04-23T15:36:49.630Z,1366731409.630 [dat_on:A.Pitch](DEBUG): Initialize.
2013-04-23T15:36:49.631Z,1366731409.631 [dat_on:TestDrive] Running Loop=1
2013-04-23T15:36:49.631Z,1366731409.631 [dat_on:TestDrive](INFO): Aggregate::initialize dat_on:TestDrive
2013-04-23T15:36:49.631Z,1366731409.631 [dat_on:TestDrive:A] Running Loop=1
2013-04-23T15:36:49.631Z,1366731409.631 [dat_on:TestDrive:C.Wait] Running Loop=1
2013-04-23T15:36:49.631Z,1366731409.631 [dat_on:TestDrive:C.Wait](DEBUG): Initialize Wait Component.
2013-04-23T15:36:49.636Z,1366731409.636 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:36:49.636Z,1366731409.636 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:36:49.637Z,1366731409.637 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:36:49.640Z,1366731409.640 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:36:49.640Z,1366731409.640 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:36:49.640Z,1366731409.640 [dat_on:TestDrive:A] Running Loop=1
2013-04-23T15:36:49.641Z,1366731409.641 [dat_on:TestDrive:A](DEBUG): Initialize ReadDataComponent to sense homing_target_range
2013-04-23T15:36:49.642Z,1366731409.642 [dat_on:A.Pitch] Running Loop=1
2013-04-23T15:36:50.033Z,1366731410.033 [DAT](INFO): Powering up
2013-04-23T15:36:50.042Z,1366731410.042 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:36:50.043Z,1366731410.043 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:36:50.043Z,1366731410.043 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:36:50.043Z,1366731410.043 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:36:50.428Z,1366731410.428 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:36:50.429Z,1366731410.429 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:36:50.429Z,1366731410.429 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:36:50.429Z,1366731410.429 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:36:50.430Z,1366731410.430 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:36:50.849Z,1366731410.849 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:36:50.849Z,1366731410.849 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:36:50.849Z,1366731410.849 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:36:50.850Z,1366731410.850 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:36:51.300Z,1366731411.300 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:36:51.300Z,1366731411.300 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:36:51.301Z,1366731411.301 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:36:51.301Z,1366731411.301 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:36:51.301Z,1366731411.301 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:36:51.649Z,1366731411.649 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:36:51.649Z,1366731411.649 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:36:51.649Z,1366731411.649 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:36:51.650Z,1366731411.649 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:36:52.083Z,1366731412.083 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:36:52.083Z,1366731412.083 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:36:52.084Z,1366731412.084 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:36:52.084Z,1366731412.084 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:36:52.084Z,1366731412.084 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:36:52.437Z,1366731412.437 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:36:52.437Z,1366731412.437 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:36:52.437Z,1366731412.437 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:36:52.437Z,1366731412.437 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:36:52.833Z,1366731412.833 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:36:52.833Z,1366731412.833 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:36:52.833Z,1366731412.833 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:36:52.834Z,1366731412.834 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:36:52.834Z,1366731412.834 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:36:53.232Z,1366731413.232 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:36:53.232Z,1366731413.232 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:36:53.232Z,1366731413.232 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:36:53.232Z,1366731413.232 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:36:53.644Z,1366731413.644 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:36:53.645Z,1366731413.645 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:36:53.645Z,1366731413.645 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:36:53.645Z,1366731413.645 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:36:53.645Z,1366731413.645 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:36:54.053Z,1366731414.053 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:36:54.053Z,1366731414.053 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:36:54.054Z,1366731414.053 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:36:54.054Z,1366731414.054 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:36:54.445Z,1366731414.445 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:36:54.445Z,1366731414.445 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:36:54.445Z,1366731414.445 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:36:54.446Z,1366731414.446 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:36:54.446Z,1366731414.446 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:36:54.872Z,1366731414.872 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:36:54.872Z,1366731414.872 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:36:54.873Z,1366731414.872 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:36:54.873Z,1366731414.873 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:36:55.231Z,1366731415.231 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:36:55.232Z,1366731415.232 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:36:55.232Z,1366731415.232 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:36:55.232Z,1366731415.232 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:36:55.233Z,1366731415.233 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:36:55.625Z,1366731415.625 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:36:55.625Z,1366731415.625 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:36:55.625Z,1366731415.625 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:36:55.625Z,1366731415.625 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:36:56.033Z,1366731416.033 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:36:56.033Z,1366731416.033 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:36:56.033Z,1366731416.033 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:36:56.034Z,1366731416.034 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:36:56.034Z,1366731416.034 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:36:56.433Z,1366731416.433 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:36:56.433Z,1366731416.433 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:36:56.433Z,1366731416.433 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:36:56.433Z,1366731416.433 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:36:56.845Z,1366731416.845 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:36:56.845Z,1366731416.845 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:36:56.846Z,1366731416.846 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:36:56.846Z,1366731416.846 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:36:56.847Z,1366731416.847 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:36:57.295Z,1366731417.295 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:36:57.295Z,1366731417.295 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:36:57.296Z,1366731417.296 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:36:57.296Z,1366731417.296 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:36:57.649Z,1366731417.649 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:36:57.650Z,1366731417.649 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:36:57.650Z,1366731417.650 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:36:57.650Z,1366731417.650 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:36:57.650Z,1366731417.650 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:36:58.074Z,1366731418.074 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:36:58.075Z,1366731418.075 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:36:58.075Z,1366731418.075 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:36:58.075Z,1366731418.075 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:36:58.432Z,1366731418.432 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:36:58.432Z,1366731418.432 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:36:58.433Z,1366731418.432 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:36:58.433Z,1366731418.433 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:36:58.433Z,1366731418.433 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:36:58.834Z,1366731418.833 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:36:58.834Z,1366731418.834 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:36:58.834Z,1366731418.834 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:36:58.834Z,1366731418.834 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:36:59.235Z,1366731419.235 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:36:59.235Z,1366731419.235 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:36:59.235Z,1366731419.235 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:36:59.236Z,1366731419.236 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:36:59.236Z,1366731419.236 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:36:59.643Z,1366731419.643 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:36:59.643Z,1366731419.643 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:36:59.643Z,1366731419.643 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:36:59.644Z,1366731419.644 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:00.047Z,1366731420.047 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:00.047Z,1366731420.047 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:00.047Z,1366731420.047 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:00.048Z,1366731420.048 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:00.048Z,1366731420.048 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:00.441Z,1366731420.441 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:00.441Z,1366731420.441 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:00.441Z,1366731420.441 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:00.442Z,1366731420.441 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:00.832Z,1366731420.832 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:00.832Z,1366731420.832 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:00.833Z,1366731420.833 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:00.833Z,1366731420.833 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:00.833Z,1366731420.833 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:01.274Z,1366731421.274 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:01.274Z,1366731421.274 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:01.274Z,1366731421.274 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:01.274Z,1366731421.274 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:01.633Z,1366731421.633 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:01.633Z,1366731421.633 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:01.633Z,1366731421.633 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:01.634Z,1366731421.634 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:01.634Z,1366731421.634 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:02.033Z,1366731422.033 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:02.033Z,1366731422.033 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:02.033Z,1366731422.033 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:02.033Z,1366731422.033 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:02.483Z,1366731422.483 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:02.483Z,1366731422.483 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:02.483Z,1366731422.483 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:02.484Z,1366731422.484 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:02.484Z,1366731422.484 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:02.849Z,1366731422.849 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:02.849Z,1366731422.849 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:02.849Z,1366731422.849 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:02.850Z,1366731422.849 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:03.243Z,1366731423.243 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:03.243Z,1366731423.243 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:03.243Z,1366731423.243 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:03.244Z,1366731423.244 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:03.244Z,1366731423.244 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:03.636Z,1366731423.636 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:03.636Z,1366731423.636 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:03.636Z,1366731423.636 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:03.636Z,1366731423.636 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:04.032Z,1366731424.033 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:04.033Z,1366731424.033 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:04.033Z,1366731424.033 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:04.033Z,1366731424.033 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:04.034Z,1366731424.033 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:04.433Z,1366731424.433 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:04.433Z,1366731424.433 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:04.433Z,1366731424.433 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:04.433Z,1366731424.433 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:04.873Z,1366731424.873 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:04.873Z,1366731424.873 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:04.873Z,1366731424.873 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:04.874Z,1366731424.874 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:04.874Z,1366731424.874 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:05.231Z,1366731425.231 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:05.231Z,1366731425.231 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:05.231Z,1366731425.231 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:05.232Z,1366731425.232 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:05.648Z,1366731425.648 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:05.648Z,1366731425.648 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:05.649Z,1366731425.649 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:05.649Z,1366731425.649 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:05.649Z,1366731425.649 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:06.047Z,1366731426.047 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:06.048Z,1366731426.048 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:06.048Z,1366731426.048 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:06.048Z,1366731426.048 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:06.453Z,1366731426.453 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:06.453Z,1366731426.453 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:06.453Z,1366731426.453 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:06.454Z,1366731426.454 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:06.454Z,1366731426.454 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:06.832Z,1366731426.832 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:06.832Z,1366731426.832 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:06.832Z,1366731426.832 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:06.833Z,1366731426.833 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:07.231Z,1366731427.231 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:07.232Z,1366731427.232 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:07.232Z,1366731427.232 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:07.232Z,1366731427.232 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:07.233Z,1366731427.233 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:07.683Z,1366731427.683 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:07.683Z,1366731427.684 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:07.684Z,1366731427.684 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:07.684Z,1366731427.684 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:08.077Z,1366731428.077 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:08.077Z,1366731428.077 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:08.077Z,1366731428.077 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:08.078Z,1366731428.078 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:08.078Z,1366731428.078 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:08.425Z,1366731428.425 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:08.425Z,1366731428.425 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:08.426Z,1366731428.425 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:08.426Z,1366731428.426 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:08.849Z,1366731428.849 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:08.849Z,1366731428.849 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:08.849Z,1366731428.849 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:08.850Z,1366731428.850 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:08.850Z,1366731428.850 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:09.251Z,1366731429.251 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:09.251Z,1366731429.251 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:09.251Z,1366731429.251 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:09.251Z,1366731429.251 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:09.705Z,1366731429.704 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:09.705Z,1366731429.705 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:09.705Z,1366731429.705 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:09.705Z,1366731429.705 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:09.706Z,1366731429.705 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:10.057Z,1366731430.057 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:10.057Z,1366731430.057 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:10.058Z,1366731430.057 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:10.058Z,1366731430.058 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:10.433Z,1366731430.433 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:10.433Z,1366731430.433 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:10.433Z,1366731430.433 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:10.434Z,1366731430.434 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:10.434Z,1366731430.434 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:10.833Z,1366731430.833 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:10.834Z,1366731430.834 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:10.834Z,1366731430.834 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:10.834Z,1366731430.834 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:11.273Z,1366731431.273 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:11.273Z,1366731431.273 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:11.273Z,1366731431.273 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:11.274Z,1366731431.274 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:11.274Z,1366731431.274 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:11.649Z,1366731431.649 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:11.649Z,1366731431.649 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:11.650Z,1366731431.649 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:11.650Z,1366731431.650 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:12.053Z,1366731432.053 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:12.053Z,1366731432.053 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:12.053Z,1366731432.053 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:12.054Z,1366731432.054 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:12.054Z,1366731432.054 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:12.505Z,1366731432.505 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:12.505Z,1366731432.505 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:12.506Z,1366731432.506 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:12.506Z,1366731432.506 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:12.833Z,1366731432.833 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:12.833Z,1366731432.833 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:12.833Z,1366731432.833 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:12.834Z,1366731432.834 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:12.834Z,1366731432.834 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:13.239Z,1366731433.239 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:13.239Z,1366731433.239 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:13.239Z,1366731433.239 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:13.239Z,1366731433.239 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:13.634Z,1366731433.634 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:13.634Z,1366731433.634 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:13.635Z,1366731433.635 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:13.635Z,1366731433.635 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:13.635Z,1366731433.635 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:13.645Z,1366731433.645 [Reporter](INFO): DAT.homing_target_range nan m
2013-04-23T15:37:13.646Z,1366731433.646 [Reporter](INFO): DAT.phaseA -0.014000 arcdeg
2013-04-23T15:37:14.069Z,1366731434.069 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:14.069Z,1366731434.069 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:14.070Z,1366731434.070 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:14.070Z,1366731434.070 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:14.473Z,1366731434.473 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:14.474Z,1366731434.474 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:14.474Z,1366731434.474 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:14.474Z,1366731434.474 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:14.475Z,1366731434.475 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:14.849Z,1366731434.849 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:14.850Z,1366731434.849 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:14.850Z,1366731434.850 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:14.850Z,1366731434.850 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:15.249Z,1366731435.249 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:15.249Z,1366731435.249 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:15.249Z,1366731435.249 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:15.250Z,1366731435.250 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:15.250Z,1366731435.250 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:15.644Z,1366731435.644 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:15.644Z,1366731435.644 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:15.644Z,1366731435.644 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:15.645Z,1366731435.645 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:16.033Z,1366731436.033 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:16.033Z,1366731436.033 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:16.033Z,1366731436.033 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:16.034Z,1366731436.034 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:16.034Z,1366731436.034 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:16.433Z,1366731436.433 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:16.433Z,1366731436.433 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:16.433Z,1366731436.433 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:16.433Z,1366731436.433 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:16.833Z,1366731436.833 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:16.833Z,1366731436.833 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:16.833Z,1366731436.833 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:16.834Z,1366731436.834 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:16.834Z,1366731436.834 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:17.239Z,1366731437.239 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:17.239Z,1366731437.239 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:17.239Z,1366731437.239 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:17.239Z,1366731437.239 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:17.753Z,1366731437.753 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:17.753Z,1366731437.753 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:17.753Z,1366731437.753 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:17.754Z,1366731437.754 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:17.754Z,1366731437.754 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:17.789Z,1366731437.789 [Reporter](INFO): DAT.homing_target_range nan m
2013-04-23T15:37:17.789Z,1366731437.789 [Reporter](INFO): DAT.phaseA -0.015000 arcdeg
2013-04-23T15:37:18.072Z,1366731438.072 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:18.072Z,1366731438.072 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:18.072Z,1366731438.072 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:18.072Z,1366731438.072 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:18.449Z,1366731438.449 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:18.449Z,1366731438.449 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:18.449Z,1366731438.449 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:18.450Z,1366731438.450 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:18.450Z,1366731438.450 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:18.833Z,1366731438.833 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:18.833Z,1366731438.833 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:18.833Z,1366731438.833 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:18.833Z,1366731438.833 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:19.231Z,1366731439.231 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:19.231Z,1366731439.231 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:19.232Z,1366731439.232 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:19.232Z,1366731439.232 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:19.232Z,1366731439.232 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:19.633Z,1366731439.633 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:19.633Z,1366731439.633 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:19.633Z,1366731439.634 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:19.634Z,1366731439.634 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:20.029Z,1366731440.029 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:20.029Z,1366731440.029 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:20.030Z,1366731440.030 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:20.030Z,1366731440.030 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:20.030Z,1366731440.030 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:20.426Z,1366731440.425 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:20.426Z,1366731440.426 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:20.426Z,1366731440.426 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:20.426Z,1366731440.426 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:20.845Z,1366731440.845 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:20.845Z,1366731440.845 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:20.845Z,1366731440.845 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:20.846Z,1366731440.846 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:20.846Z,1366731440.846 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:21.282Z,1366731441.282 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:21.282Z,1366731441.283 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:21.283Z,1366731441.283 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:21.283Z,1366731441.283 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:21.644Z,1366731441.644 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:21.644Z,1366731441.644 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:21.644Z,1366731441.644 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:21.645Z,1366731441.645 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:21.645Z,1366731441.645 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:21.655Z,1366731441.655 [Reporter](INFO): DAT.homing_target_range nan m
2013-04-23T15:37:21.656Z,1366731441.656 [Reporter](INFO): DAT.phaseA -0.012000 arcdeg
2013-04-23T15:37:22.069Z,1366731442.069 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:22.069Z,1366731442.069 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:22.069Z,1366731442.069 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:22.070Z,1366731442.070 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:22.433Z,1366731442.433 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:22.433Z,1366731442.433 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:22.433Z,1366731442.433 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:22.433Z,1366731442.434 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:22.434Z,1366731442.434 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:22.887Z,1366731442.887 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:22.887Z,1366731442.887 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:22.887Z,1366731442.888 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:22.888Z,1366731442.888 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:23.231Z,1366731443.231 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:23.231Z,1366731443.231 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:23.231Z,1366731443.231 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:23.232Z,1366731443.232 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:23.232Z,1366731443.232 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:23.645Z,1366731443.645 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:23.645Z,1366731443.645 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:23.645Z,1366731443.645 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:23.645Z,1366731443.645 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:24.053Z,1366731444.053 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:24.053Z,1366731444.053 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:24.053Z,1366731444.053 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:24.054Z,1366731444.054 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:24.054Z,1366731444.054 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:24.485Z,1366731444.485 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:24.485Z,1366731444.485 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:24.486Z,1366731444.486 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:24.486Z,1366731444.486 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:24.832Z,1366731444.832 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:24.833Z,1366731444.833 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:24.833Z,1366731444.833 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:24.833Z,1366731444.833 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:24.834Z,1366731444.833 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:25.233Z,1366731445.233 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:25.233Z,1366731445.233 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:25.233Z,1366731445.233 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:25.234Z,1366731445.234 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:25.641Z,1366731445.641 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:25.641Z,1366731445.641 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:25.641Z,1366731445.641 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:25.642Z,1366731445.642 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:25.642Z,1366731445.642 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:25.652Z,1366731445.652 [Reporter](INFO): DAT.homing_target_range nan m
2013-04-23T15:37:25.653Z,1366731445.653 [Reporter](INFO): DAT.phaseA -0.016000 arcdeg
2013-04-23T15:37:26.069Z,1366731446.069 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:26.069Z,1366731446.069 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:26.069Z,1366731446.069 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:26.069Z,1366731446.069 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:26.425Z,1366731446.425 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:26.426Z,1366731446.425 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:26.426Z,1366731446.426 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:26.426Z,1366731446.426 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:26.427Z,1366731446.427 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:26.845Z,1366731446.845 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:26.845Z,1366731446.845 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:26.845Z,1366731446.845 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:26.845Z,1366731446.845 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:27.249Z,1366731447.249 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:27.249Z,1366731447.249 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:27.250Z,1366731447.250 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:27.250Z,1366731447.250 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:27.250Z,1366731447.250 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:27.732Z,1366731447.732 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:27.732Z,1366731447.732 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:27.732Z,1366731447.732 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:27.732Z,1366731447.732 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:28.033Z,1366731448.033 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:28.033Z,1366731448.033 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:28.033Z,1366731448.033 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:28.034Z,1366731448.033 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:28.034Z,1366731448.034 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:28.433Z,1366731448.433 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:28.433Z,1366731448.434 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:28.434Z,1366731448.434 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:28.434Z,1366731448.434 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:28.833Z,1366731448.833 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:28.834Z,1366731448.833 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:28.834Z,1366731448.834 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:28.835Z,1366731448.835 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:28.835Z,1366731448.835 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:29.233Z,1366731449.233 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:29.233Z,1366731449.233 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:29.233Z,1366731449.233 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:29.233Z,1366731449.233 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:29.653Z,1366731449.653 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:29.653Z,1366731449.653 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:29.654Z,1366731449.654 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:29.654Z,1366731449.654 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:29.654Z,1366731449.654 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:29.688Z,1366731449.688 [Reporter](INFO): DAT.homing_target_range nan m
2013-04-23T15:37:29.688Z,1366731449.688 [Reporter](INFO): DAT.phaseA -0.016000 arcdeg
2013-04-23T15:37:30.072Z,1366731450.072 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:30.072Z,1366731450.072 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:30.072Z,1366731450.072 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:30.072Z,1366731450.072 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:30.449Z,1366731450.449 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:30.449Z,1366731450.449 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:30.449Z,1366731450.449 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:30.450Z,1366731450.450 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:30.450Z,1366731450.450 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:30.874Z,1366731450.874 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:30.874Z,1366731450.874 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:30.874Z,1366731450.874 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:30.874Z,1366731450.875 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:31.241Z,1366731451.240 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:31.242Z,1366731451.242 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:31.242Z,1366731451.242 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:31.244Z,1366731451.244 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:31.245Z,1366731451.245 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:31.633Z,1366731451.633 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:31.633Z,1366731451.633 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:31.633Z,1366731451.633 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:31.633Z,1366731451.633 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:32.029Z,1366731452.029 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:32.030Z,1366731452.030 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:32.030Z,1366731452.030 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:32.031Z,1366731452.030 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:32.031Z,1366731452.031 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:32.433Z,1366731452.433 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:32.433Z,1366731452.433 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:32.433Z,1366731452.433 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:32.433Z,1366731452.434 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:32.901Z,1366731452.901 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:32.901Z,1366731452.901 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:32.901Z,1366731452.901 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:32.902Z,1366731452.902 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:32.902Z,1366731452.902 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:33.245Z,1366731453.245 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:33.245Z,1366731453.245 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:33.245Z,1366731453.246 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:33.246Z,1366731453.246 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:33.648Z,1366731453.648 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:33.648Z,1366731453.648 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:33.649Z,1366731453.648 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:33.649Z,1366731453.649 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:33.649Z,1366731453.649 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:33.676Z,1366731453.676 [Reporter](INFO): DAT.homing_target_range nan m
2013-04-23T15:37:33.676Z,1366731453.676 [Reporter](INFO): DAT.phaseA -0.012000 arcdeg
2013-04-23T15:37:34.085Z,1366731454.085 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:34.085Z,1366731454.085 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:34.085Z,1366731454.085 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:34.085Z,1366731454.085 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:34.433Z,1366731454.433 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:34.433Z,1366731454.433 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:34.433Z,1366731454.433 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:34.434Z,1366731454.434 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:34.434Z,1366731454.434 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:34.831Z,1366731454.831 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:34.831Z,1366731454.831 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:34.831Z,1366731454.831 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:34.831Z,1366731454.831 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:35.236Z,1366731455.236 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:35.236Z,1366731455.236 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:35.236Z,1366731455.236 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:35.237Z,1366731455.237 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:35.237Z,1366731455.237 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:35.646Z,1366731455.646 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:35.646Z,1366731455.646 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:35.646Z,1366731455.646 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:35.646Z,1366731455.646 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:36.048Z,1366731456.048 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:36.048Z,1366731456.048 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:36.049Z,1366731456.049 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:36.049Z,1366731456.049 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:36.049Z,1366731456.049 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:36.450Z,1366731456.450 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:36.450Z,1366731456.450 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:36.450Z,1366731456.450 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:36.450Z,1366731456.450 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:36.833Z,1366731456.833 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:36.833Z,1366731456.833 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:36.833Z,1366731456.833 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:36.834Z,1366731456.833 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:36.834Z,1366731456.834 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:37.234Z,1366731457.234 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:37.234Z,1366731457.234 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:37.234Z,1366731457.234 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:37.234Z,1366731457.234 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:37.686Z,1366731457.686 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:37.686Z,1366731457.686 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:37.686Z,1366731457.686 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:37.687Z,1366731457.687 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:37.687Z,1366731457.687 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:37.697Z,1366731457.697 [Reporter](INFO): DAT.homing_target_range nan m
2013-04-23T15:37:37.698Z,1366731457.698 [Reporter](INFO): DAT.phaseA -0.016000 arcdeg
2013-04-23T15:37:38.103Z,1366731458.103 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:38.103Z,1366731458.103 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:38.103Z,1366731458.103 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:38.103Z,1366731458.103 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:38.425Z,1366731458.425 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:38.425Z,1366731458.425 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:38.426Z,1366731458.425 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:38.426Z,1366731458.426 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:38.426Z,1366731458.427 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:38.845Z,1366731458.845 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:38.845Z,1366731458.845 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:38.845Z,1366731458.845 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:38.845Z,1366731458.845 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:39.248Z,1366731459.248 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:39.248Z,1366731459.248 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:39.248Z,1366731459.248 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:39.249Z,1366731459.249 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:39.249Z,1366731459.249 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:39.636Z,1366731459.636 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:39.636Z,1366731459.636 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:39.636Z,1366731459.636 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:39.636Z,1366731459.636 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:40.032Z,1366731460.032 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:40.032Z,1366731460.032 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:40.032Z,1366731460.033 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:40.033Z,1366731460.033 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:40.033Z,1366731460.033 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:40.433Z,1366731460.433 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:40.433Z,1366731460.434 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:40.434Z,1366731460.434 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:40.434Z,1366731460.434 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:40.874Z,1366731460.874 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:40.874Z,1366731460.874 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:40.874Z,1366731460.874 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:40.875Z,1366731460.875 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:40.875Z,1366731460.875 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:41.269Z,1366731461.269 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:41.269Z,1366731461.269 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:41.269Z,1366731461.269 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:41.269Z,1366731461.270 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:41.642Z,1366731461.642 [DAT](ERROR): Unexpected response:16:48:57.4729 , LVL= 10304,  3473,  24= 62 0.05,-2.518, PHS=-0.015, 0.048, 0.062, |v|= 0.046, RAW= 260.0,-24.8, CAL= 268.2,-24.1, ROT= 347.2,-24.1
Compass  18.1
Range 1 to 0 : 0.2 m 
2013-04-23T15:37:41.650Z,1366731461.650 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:41.650Z,1366731461.650 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:41.650Z,1366731461.650 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:41.651Z,1366731461.651 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:41.651Z,1366731461.651 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:41.686Z,1366731461.686 [Reporter](INFO): DAT.homing_target_range nan m
2013-04-23T15:37:42.084Z,1366731462.084 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:42.084Z,1366731462.084 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:42.084Z,1366731462.085 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:42.085Z,1366731462.085 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:42.445Z,1366731462.445 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:42.445Z,1366731462.445 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:42.445Z,1366731462.445 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:42.446Z,1366731462.446 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:42.446Z,1366731462.446 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:42.833Z,1366731462.833 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:42.833Z,1366731462.833 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:42.833Z,1366731462.833 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:42.833Z,1366731462.833 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:43.284Z,1366731463.284 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:43.284Z,1366731463.284 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:43.284Z,1366731463.284 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:43.285Z,1366731463.285 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:43.285Z,1366731463.285 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:43.633Z,1366731463.633 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:43.633Z,1366731463.633 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:43.633Z,1366731463.633 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:43.633Z,1366731463.633 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:44.073Z,1366731464.073 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:44.074Z,1366731464.074 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:44.074Z,1366731464.074 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:44.074Z,1366731464.074 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:44.075Z,1366731464.075 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:44.426Z,1366731464.425 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:44.426Z,1366731464.426 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:44.426Z,1366731464.426 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:44.426Z,1366731464.426 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:44.849Z,1366731464.849 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:44.849Z,1366731464.849 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:44.849Z,1366731464.849 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:44.850Z,1366731464.850 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:44.850Z,1366731464.850 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:45.245Z,1366731465.245 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:45.245Z,1366731465.246 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:45.246Z,1366731465.246 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:45.246Z,1366731465.246 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:45.644Z,1366731465.644 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:45.644Z,1366731465.644 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:45.645Z,1366731465.645 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:45.645Z,1366731465.645 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:45.645Z,1366731465.645 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:45.655Z,1366731465.655 [Reporter](INFO): DAT.homing_target_range nan m
2013-04-23T15:37:45.656Z,1366731465.656 [Reporter](INFO): DAT.phaseA -0.014000 arcdeg
2013-04-23T15:37:46.069Z,1366731466.069 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:46.070Z,1366731466.070 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:46.070Z,1366731466.070 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:46.070Z,1366731466.070 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:46.440Z,1366731466.440 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:46.440Z,1366731466.440 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:46.440Z,1366731466.440 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:46.440Z,1366731466.441 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:46.441Z,1366731466.441 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:37:46.834Z,1366731466.834 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:37:46.834Z,1366731466.834 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:37:46.834Z,1366731466.834 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:37:46.834Z,1366731466.834 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:37:47.280Z,1366731467.280 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:37:47.280Z,1366731467.280 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:37:47.280Z,1366731467.280 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:37:47.280Z,1366731467.280 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:37:47.281Z,1366731467.281 [dat_on:TestDrive:Data:B] Running Loop=1