2013-04-23T15:21:58.881Z,1366730518.881 [Supervisor](DEBUG): Initializing supervisor.
2013-04-23T15:21:58.894Z,1366730518.894 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2013-04-23T15:21:58.895Z,1366730518.895 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2013-04-23T15:21:58.906Z,1366730518.906 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2013-04-23T15:21:58.937Z,1366730518.937 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2013-04-23T15:21:58.959Z,1366730518.959 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2013-04-23T15:21:58.970Z,1366730518.970 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2013-04-23T15:21:58.971Z,1366730518.971 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2013-04-23T15:21:58.982Z,1366730518.982 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0
2013-04-23T15:21:58.983Z,1366730518.983 [Supervisor](INFO): Looking for Config files in directory: Config/
2013-04-23T15:21:58.998Z,1366730518.998 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2013-04-23T15:21:59.782Z,1366730519.782 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2013-04-23T15:21:59.782Z,1366730519.782 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2013-04-23T15:22:00.136Z,1366730520.136 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2013-04-23T15:22:00.136Z,1366730520.136 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2013-04-23T15:22:00.289Z,1366730520.289 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2013-04-23T15:22:00.291Z,1366730520.291 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2013-04-23T15:22:00.621Z,1366730520.621 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2013-04-23T15:22:00.622Z,1366730520.622 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2013-04-23T15:22:00.882Z,1366730520.882 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2013-04-23T15:22:00.885Z,1366730520.885 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2013-04-23T15:22:01.312Z,1366730521.312 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2013-04-23T15:22:01.313Z,1366730521.313 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2013-04-23T15:22:01.635Z,1366730521.635 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2013-04-23T15:22:01.637Z,1366730521.637 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2013-04-23T15:22:02.203Z,1366730522.203 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2013-04-23T15:22:02.212Z,1366730522.212 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2013-04-23T15:22:02.390Z,1366730522.390 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2013-04-23T15:22:02.391Z,1366730522.391 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2013-04-23T15:22:03.184Z,1366730523.184 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2013-04-23T15:22:03.184Z,1366730523.184 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2013-04-23T15:22:03.372Z,1366730523.372 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2013-04-23T15:22:03.373Z,1366730523.373 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2013-04-23T15:22:03.524Z,1366730523.524 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2013-04-23T15:22:03.528Z,1366730523.528 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2013-04-23T15:22:03.719Z,1366730523.719 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2013-04-23T15:22:03.970Z,1366730523.970 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2013-04-23T15:22:04.120Z,1366730524.120 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2013-04-23T15:22:04.295Z,1366730524.295 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2013-04-23T15:22:04.471Z,1366730524.471 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2013-04-23T15:22:04.686Z,1366730524.686 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2013-04-23T15:22:04.833Z,1366730524.833 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2013-04-23T15:22:04.980Z,1366730524.980 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2013-04-23T15:22:05.007Z,1366730525.007 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2013-04-23T15:22:05.322Z,1366730525.322 [InternalSim] Loaded
2013-04-23T15:22:05.322Z,1366730525.322 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2013-04-23T15:22:05.323Z,1366730525.323 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2013-04-23T15:22:05.324Z,1366730525.324 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2013-04-23T15:22:05.461Z,1366730525.461 [SBIT](DEBUG): Construct Startup Built In Test.
2013-04-23T15:22:05.528Z,1366730525.528 [SBIT] Loaded
2013-04-23T15:22:05.528Z,1366730525.528 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2013-04-23T15:22:05.529Z,1366730525.529 [IBIT](DEBUG): Construct Initiated Built In Test.
2013-04-23T15:22:05.582Z,1366730525.582 [IBIT] Loaded
2013-04-23T15:22:05.582Z,1366730525.582 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2013-04-23T15:22:05.586Z,1366730525.586 [CBIT](DEBUG): Construct CBIT Built In Test.
2013-04-23T15:22:05.834Z,1366730525.834 [CBIT] Loaded
2013-04-23T15:22:05.834Z,1366730525.834 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2013-04-23T15:22:05.834Z,1366730525.834 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2013-04-23T15:22:05.835Z,1366730525.835 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2013-04-23T15:22:06.056Z,1366730526.056 [BuoyancyServo] Loaded
2013-04-23T15:22:06.056Z,1366730526.056 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2013-04-23T15:22:06.081Z,1366730526.081 [ElevatorServo] Loaded
2013-04-23T15:22:06.081Z,1366730526.081 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2013-04-23T15:22:06.103Z,1366730526.103 [MassServo] Loaded
2013-04-23T15:22:06.103Z,1366730526.103 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2013-04-23T15:22:06.123Z,1366730526.123 [RudderServo] Loaded
2013-04-23T15:22:06.123Z,1366730526.123 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2013-04-23T15:22:06.139Z,1366730526.139 [ThrusterServo] Loaded
2013-04-23T15:22:06.139Z,1366730526.139 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2013-04-23T15:22:06.139Z,1366730526.139 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2013-04-23T15:22:06.140Z,1366730526.140 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2013-04-23T15:22:06.191Z,1366730526.191 [DepthRateCalculator] Loaded
2013-04-23T15:22:06.191Z,1366730526.191 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2013-04-23T15:22:10.749Z,1366730530.749 [HFRadarModelCalc] Loaded
2013-04-23T15:22:10.749Z,1366730530.749 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2013-04-23T15:22:10.765Z,1366730530.765 [NavChart] Loaded
2013-04-23T15:22:10.765Z,1366730530.765 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2013-04-23T15:22:10.771Z,1366730530.771 [PitchRateCalculator] Loaded
2013-04-23T15:22:10.772Z,1366730530.772 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2013-04-23T15:22:10.778Z,1366730530.778 [SpeedCalculator] Loaded
2013-04-23T15:22:10.778Z,1366730530.778 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2013-04-23T15:22:10.793Z,1366730530.793 [TempGradientCalculator] Loaded
2013-04-23T15:22:10.793Z,1366730530.793 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2013-04-23T15:22:10.799Z,1366730530.799 [YawRateCalculator] Loaded
2013-04-23T15:22:10.799Z,1366730530.799 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2013-04-23T15:22:10.839Z,1366730530.839 [Navigation] Loaded
2013-04-23T15:22:10.839Z,1366730530.839 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2013-04-23T15:22:10.839Z,1366730530.839 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2013-04-23T15:22:10.840Z,1366730530.840 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2013-04-23T15:22:11.090Z,1366730531.090 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2013-04-23T15:22:11.090Z,1366730531.090 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2013-04-23T15:22:11.127Z,1366730531.127 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2013-04-23T15:22:11.128Z,1366730531.128 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2013-04-23T15:22:11.188Z,1366730531.188 [VerticalControl](DEBUG): Construct VerticalControl.
2013-04-23T15:22:11.280Z,1366730531.280 [VerticalControl] Loaded
2013-04-23T15:22:11.280Z,1366730531.280 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2013-04-23T15:22:11.281Z,1366730531.281 [HorizontalControl](DEBUG): Construct HorizontalControl.
2013-04-23T15:22:11.337Z,1366730531.337 [HorizontalControl] Loaded
2013-04-23T15:22:11.337Z,1366730531.337 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2013-04-23T15:22:11.338Z,1366730531.338 [SpeedControl](DEBUG): Construct SpeedControl.
2013-04-23T15:22:11.340Z,1366730531.340 [SpeedControl] Loaded
2013-04-23T15:22:11.340Z,1366730531.340 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2013-04-23T15:22:11.341Z,1366730531.341 [LoopControl](DEBUG): Construct LoopControl.
2013-04-23T15:22:11.341Z,1366730531.341 [LoopControl] Loaded
2013-04-23T15:22:11.342Z,1366730531.342 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2013-04-23T15:22:11.342Z,1366730531.342 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2013-04-23T15:22:11.343Z,1366730531.343 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2013-04-23T15:22:11.351Z,1366730531.351 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2013-04-23T15:22:11.356Z,1366730531.356 [AsyncPiEstimator] Loaded
2013-04-23T15:22:11.356Z,1366730531.356 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2013-04-23T15:22:11.357Z,1366730531.357 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 4063B4E0
2013-04-23T15:22:11.358Z,1366730531.358 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2013-04-23T15:22:11.358Z,1366730531.358 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2013-04-23T15:22:11.524Z,1366730531.524 [AHRS_sp3003D] Loaded
2013-04-23T15:22:11.524Z,1366730531.524 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2013-04-23T15:22:11.779Z,1366730531.779 [Batt_Ocean_Server] Loaded
2013-04-23T15:22:11.779Z,1366730531.779 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2013-04-23T15:22:11.792Z,1366730531.792 [Depth_Keller] Loaded
2013-04-23T15:22:11.792Z,1366730531.792 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2013-04-23T15:22:11.798Z,1366730531.798 [DropWeight] Loaded
2013-04-23T15:22:11.798Z,1366730531.798 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2013-04-23T15:22:11.968Z,1366730531.968 [DVL_micro] Loaded
2013-04-23T15:22:11.968Z,1366730531.968 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2013-04-23T15:22:11.969Z,1366730531.969 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 406BF4E0
2013-04-23T15:22:12.050Z,1366730532.050 [NAL9602] Loaded
2013-04-23T15:22:12.050Z,1366730532.050 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2013-04-23T15:22:12.099Z,1366730532.099 [Onboard] Loaded
2013-04-23T15:22:12.100Z,1366730532.100 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2013-04-23T15:22:12.106Z,1366730532.106 [Radio_Freewave] Loaded
2013-04-23T15:22:12.107Z,1366730532.107 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2013-04-23T15:22:12.199Z,1366730532.199 [DAT] Loaded
2013-04-23T15:22:12.199Z,1366730532.199 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2013-04-23T15:22:12.200Z,1366730532.200 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2013-04-23T15:22:12.200Z,1366730532.200 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2013-04-23T15:22:12.294Z,1366730532.294 [CTD_NeilBrown] Loaded
2013-04-23T15:22:12.294Z,1366730532.295 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2013-04-23T15:22:12.296Z,1366730532.296 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407114E0
2013-04-23T15:22:12.313Z,1366730532.313 [PAR_Licor] Loaded
2013-04-23T15:22:12.314Z,1366730532.314 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2013-04-23T15:22:12.343Z,1366730532.343 [WetLabsBB2FL] Loaded
2013-04-23T15:22:12.344Z,1366730532.344 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2013-04-23T15:22:12.345Z,1366730532.345 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407414E0
2013-04-23T15:22:12.345Z,1366730532.345 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2013-04-23T15:22:12.348Z,1366730532.348 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2013-04-23T15:22:12.349Z,1366730532.349 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2013-04-23T15:22:12.359Z,1366730532.359 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2013-04-23T15:22:12.360Z,1366730532.360 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407714E0
2013-04-23T15:22:12.364Z,1366730532.364 [Supervisor](DEBUG): Running supervisor.
2013-04-23T15:22:12.365Z,1366730532.365 [CommandLine](INFO): Thread ID is 6623
2013-04-23T15:22:12.367Z,1366730532.367 [controlThread](INFO): Thread ID is 6622
2013-04-23T15:22:12.368Z,1366730532.368 [controlThread](DEBUG): Initializing ControlThread
2013-04-23T15:22:12.368Z,1366730532.368 [CycleStarter](INFO): Thread ID is 6621
2013-04-23T15:22:12.368Z,1366730532.368 [InternalSim](DEBUG):  InternalSim initializing...
2013-04-23T15:22:12.467Z,1366730532.467 [logger](INFO): Thread ID is 6624
2013-04-23T15:22:12.563Z,1366730532.563 [AsyncPiEstimator](INFO): Thread ID is 6685
2013-04-23T15:22:12.563Z,1366730532.563 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2013-04-23T15:22:12.579Z,1366730532.579 [DVL_micro](INFO): Thread ID is 6686
2013-04-23T15:22:12.721Z,1366730532.721 [CTD_NeilBrown](INFO): Thread ID is 6687
2013-04-23T15:22:12.722Z,1366730532.722 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2013-04-23T15:22:12.731Z,1366730532.731 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2013-04-23T15:22:12.732Z,1366730532.732 [WetLabsBB2FL](INFO): Thread ID is 6688
2013-04-23T15:22:12.733Z,1366730532.733 [WetLabsBB2FL](INFO): Powering down
2013-04-23T15:22:12.766Z,1366730532.766 [DVL_micro](INFO): Initializing
2013-04-23T15:22:12.772Z,1366730532.772 [DVL_micro](INFO): start:Powering up
2013-04-23T15:22:12.791Z,1366730532.791 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:22:12.791Z,1366730532.791 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:22:12.799Z,1366730532.799 [NavChartDb](INFO): Thread ID is 6689
2013-04-23T15:22:12.812Z,1366730532.812 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2013-04-23T15:22:12.813Z,1366730532.813 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2013-04-23T15:22:12.813Z,1366730532.813 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2013-04-23T15:22:12.814Z,1366730532.814 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2013-04-23T15:22:12.814Z,1366730532.814 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2013-04-23T15:22:12.814Z,1366730532.814 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2013-04-23T15:22:12.815Z,1366730532.815 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2013-04-23T15:22:12.815Z,1366730532.815 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2013-04-23T15:22:12.815Z,1366730532.815 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2013-04-23T15:22:12.817Z,1366730532.817 [SBIT](INFO): Initialize SBIT Component.
2013-04-23T15:22:12.818Z,1366730532.818 [SBIT](IMPORTANT): Tethys CM Info:
$Rev:10302
2013-04-23T15:22:12.862Z,1366730532.862 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2013-04-23T15:22:12.863Z,1366730532.863 [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:22:12.863Z,1366730532.864 [IBIT](INFO): Initialize IBIT Component.
2013-04-23T15:22:12.864Z,1366730532.864 [CBIT](DEBUG): Initialize CBIT Component.
2013-04-23T15:22:12.864Z,1366730532.865 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2013-04-23T15:22:12.865Z,1366730532.865 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET.
2013-04-23T15:22:12.892Z,1366730532.892 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-04-23T15:22:12.892Z,1366730532.892 [NavChart](DEBUG): Initialize NavChart Derivation.
2013-04-23T15:22:12.893Z,1366730532.893 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2013-04-23T15:22:12.893Z,1366730532.893 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2013-04-23T15:22:12.893Z,1366730532.893 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2013-04-23T15:22:12.895Z,1366730532.895 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2013-04-23T15:22:12.896Z,1366730532.895 [Navigation](DEBUG): Initializing Navigation.
2013-04-23T15:22:12.896Z,1366730532.896 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2013-04-23T15:22:12.898Z,1366730532.898 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2013-04-23T15:22:12.901Z,1366730532.901 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2013-04-23T15:22:12.902Z,1366730532.902 [LoopControl](DEBUG): Initialize LoopControlComponent.
2013-04-23T15:22:14.845Z,1366730534.845 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2013-04-23T15:22:14.879Z,1366730534.879 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2013-04-23T15:22:14.879Z,1366730534.879 [DropWeight] Hardware Fault, FailCount= 1
2013-04-23T15:22:14.879Z,1366730534.879 [DropWeight](ERROR): Hardware Fault
2013-04-23T15:22:14.883Z,1366730534.883 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:22:14.883Z,1366730534.883 [DVL_micro](INFO): Querying output modes
2013-04-23T15:22:14.883Z,1366730534.883 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:22:14.887Z,1366730534.887 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2013-04-23T15:22:14.936Z,1366730534.936 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2013-04-23T15:22:14.966Z,1366730534.966 [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:22:14.975Z,1366730534.975 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2013-04-23T15:22:15.068Z,1366730535.068 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2013-04-23T15:22:15.070Z,1366730535.070 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2013-04-23T15:22:15.077Z,1366730535.077 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-04-23T15:22:15.097Z,1366730535.096 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2013-04-23T15:22:15.099Z,1366730535.099 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-04-23T15:22:15.106Z,1366730535.106 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2013-04-23T15:22:15.169Z,1366730535.169 [Default:D.SetSpeed](DEBUG): Construct.
2013-04-23T15:22:15.180Z,1366730535.180 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2013-04-23T15:22:15.187Z,1366730535.187 [Default:F.Wait](DEBUG): Construct Wait.
2013-04-23T15:22:15.191Z,1366730535.191 [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:22:15.199Z,1366730535.199 [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:22:15.259Z,1366730535.259 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-04-23T15:22:15.407Z,1366730535.407 [Radio_Freewave](INFO): Powering up
2013-04-23T15:22:15.412Z,1366730535.412 [DAT](INFO): Powering up
2013-04-23T15:22:15.412Z,1366730535.412 [DAT](DEBUG): Initializing DAT.
2013-04-23T15:22:15.807Z,1366730535.807 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-04-23T15:22:15.814Z,1366730535.815 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-04-23T15:22:15.837Z,1366730535.837 [ElevatorServo](DEBUG): Initializing EZServoServo.
2013-04-23T15:22:15.843Z,1366730535.843 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2013-04-23T15:22:15.857Z,1366730535.856 [MassServo](DEBUG): Initializing EZServoServo.
2013-04-23T15:22:15.863Z,1366730535.863 [MassServo](DEBUG): Initializing MassServo.
2013-04-23T15:22:15.872Z,1366730535.872 [RudderServo](DEBUG): Initializing EZServoServo.
2013-04-23T15:22:15.878Z,1366730535.878 [RudderServo](DEBUG): Initializing RudderServo.
2013-04-23T15:22:15.884Z,1366730535.884 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-04-23T15:22:15.891Z,1366730535.891 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-04-23T15:22:15.916Z,1366730535.916 [CBIT](ERROR): Hardware Fault in component: DropWeight
2013-04-23T15:22:15.916Z,1366730535.917 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2013-04-23T15:22:16.134Z,1366730536.134 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-04-23T15:22:16.135Z,1366730536.135 [AHRS_sp3003D](ERROR): readHeadingMagBin got 0xA409A0
2013-04-23T15:22:16.135Z,1366730536.135 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-04-23T15:22:16.135Z,1366730536.135 [AHRS_sp3003D] Hardware Fault, FailCount= 1
2013-04-23T15:22:16.135Z,1366730536.135 [AHRS_sp3003D](ERROR): Hardware Fault
2013-04-23T15:22:16.199Z,1366730536.199 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-04-23T15:22:16.385Z,1366730536.385 [AHRS_sp3003D](INFO): Powering down
2013-04-23T15:22:16.887Z,1366730536.887 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:22:16.888Z,1366730536.888 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:22:16.890Z,1366730536.890 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:22:17.345Z,1366730537.345 [NAL9602](INFO): Powering up NAL9602
2013-04-23T15:22:17.886Z,1366730537.886 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2013-04-23T15:22:17.886Z,1366730537.886 [AHRS_sp3003D] No Fault, FailCount= 1
2013-04-23T15:22:18.141Z,1366730538.141 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-04-23T15:22:18.901Z,1366730538.901 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:22:18.906Z,1366730538.906 [DVL_micro](INFO): pause:Powering down
2013-04-23T15:22:19.286Z,1366730539.286 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-04-23T15:22:19.286Z,1366730539.286 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-04-23T15:22:19.287Z,1366730539.286 [AHRS_sp3003D] Hardware Fault, FailCount= 2
2013-04-23T15:22:19.287Z,1366730539.286 [AHRS_sp3003D](ERROR): Hardware Fault
2013-04-23T15:22:19.311Z,1366730539.311 [DVL_micro](INFO): NQ1 requested
2013-04-23T15:22:19.311Z,1366730539.311 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:22:19.312Z,1366730539.312 [DVL_micro](INFO): resume:Powering up
2013-04-23T15:22:19.312Z,1366730539.312 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:22:19.513Z,1366730539.513 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-04-23T15:22:19.532Z,1366730539.532 [AHRS_sp3003D](INFO): Powering down
2013-04-23T15:22:20.873Z,1366730540.874 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2013-04-23T15:22:20.874Z,1366730540.874 [AHRS_sp3003D] No Fault, FailCount= 2
2013-04-23T15:22:21.189Z,1366730541.188 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-04-23T15:22:21.333Z,1366730541.333 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:22:21.333Z,1366730541.333 [DVL_micro](INFO): Querying output modes
2013-04-23T15:22:21.333Z,1366730541.333 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:22:22.334Z,1366730542.334 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-04-23T15:22:22.334Z,1366730542.334 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-04-23T15:22:22.335Z,1366730542.335 [AHRS_sp3003D] Hardware Fault, FailCount= 3
2013-04-23T15:22:22.335Z,1366730542.335 [AHRS_sp3003D](ERROR): Hardware Fault
2013-04-23T15:22:22.429Z,1366730542.429 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-04-23T15:22:22.466Z,1366730542.466 [AHRS_sp3003D](INFO): Powering down
2013-04-23T15:22:23.339Z,1366730543.339 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:22:23.339Z,1366730543.339 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:22:23.339Z,1366730543.339 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:22:23.769Z,1366730543.769 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2013-04-23T15:22:23.770Z,1366730543.770 [AHRS_sp3003D] No Fault, FailCount= 3
2013-04-23T15:22:24.057Z,1366730544.057 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-04-23T15:22:25.190Z,1366730545.190 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-04-23T15:22:25.190Z,1366730545.190 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-04-23T15:22:25.191Z,1366730545.191 [AHRS_sp3003D] Hardware Fault, FailCount= 4
2013-04-23T15:22:25.191Z,1366730545.191 [AHRS_sp3003D](ERROR): Hardware Fault
2013-04-23T15:22:25.351Z,1366730545.351 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:22:25.353Z,1366730545.353 [DVL_micro](INFO): NQ1 requested
2013-04-23T15:22:25.353Z,1366730545.353 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:22:25.406Z,1366730545.406 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-04-23T15:22:25.417Z,1366730545.417 [AHRS_sp3003D](INFO): Powering down
2013-04-23T15:22:26.709Z,1366730546.709 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2013-04-23T15:22:26.710Z,1366730546.710 [AHRS_sp3003D] No Fault, FailCount= 4
2013-04-23T15:22:27.022Z,1366730547.022 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-04-23T15:22:27.363Z,1366730547.363 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:22:27.363Z,1366730547.363 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-04-23T15:22:28.166Z,1366730548.166 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-04-23T15:22:28.166Z,1366730548.166 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-04-23T15:22:28.167Z,1366730548.167 [AHRS_sp3003D] Hardware Fault, FailCount= 5
2013-04-23T15:22:28.167Z,1366730548.167 [AHRS_sp3003D](ERROR): Hardware Fault
2013-04-23T15:22:28.259Z,1366730548.259 [NAL9602](INFO): NAL9602 initialized
2013-04-23T15:22:28.362Z,1366730548.362 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-04-23T15:22:28.363Z,1366730548.362 [CBIT](CRITICAL): Hardware Fault in component: AHRS_sp3003D
2013-04-23T15:22:28.379Z,1366730548.379 [AHRS_sp3003D](INFO): Powering down
2013-04-23T15:22:28.564Z,1366730548.564 [SBIT](IMPORTANT): Beginning Startup BIT
2013-04-23T15:22:28.570Z,1366730548.570 [CBIT](IMPORTANT): Beginning GF scan
2013-04-23T15:22:29.374Z,1366730549.374 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:22:29.374Z,1366730549.374 [DVL_micro](INFO): Enabling NQ1 output
2013-04-23T15:22:29.375Z,1366730549.375 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-04-23T15:22:31.387Z,1366730551.386 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:22:31.387Z,1366730551.387 [DVL_micro](INFO): Querying output modes
2013-04-23T15:22:31.387Z,1366730551.387 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:22:33.394Z,1366730553.394 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:22:33.394Z,1366730553.395 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:22:33.395Z,1366730553.395 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:22:33.467Z,1366730553.467 [CommandLine](IMPORTANT): got command failComponent
2013-04-23T15:22:33.467Z,1366730553.467 [CommandLine](IMPORTANT): Failed components:
2013-04-23T15:22:33.467Z,1366730553.467 [CommandLine](IMPORTANT): AHRS_sp3003D: Hardware Fault
2013-04-23T15:22:33.467Z,1366730553.467 [CommandLine](IMPORTANT): DropWeight: Hardware Fault
2013-04-23T15:22:34.802Z,1366730554.802 [DAT](INFO): Init failed - response: 
2013-04-23T15:22:34.802Z,1366730554.802 [DAT](FAULT): DAT failed to initialize
2013-04-23T15:22:34.803Z,1366730554.803 [DAT] Communications Fault, FailCount= 1
2013-04-23T15:22:34.803Z,1366730554.803 [DAT](ERROR): Communications Fault
2013-04-23T15:22:35.024Z,1366730555.024 [CBIT](ERROR): Communications Fault in component: DAT
2013-04-23T15:22:35.060Z,1366730555.060 [DAT](INFO): Powering down
2013-04-23T15:22:35.403Z,1366730555.403 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:22:36.062Z,1366730556.062 [CBIT](INFO): Clearing failed state for component DAT
2013-04-23T15:22:36.063Z,1366730556.063 [DAT] No Fault, FailCount= 1
2013-04-23T15:22:37.407Z,1366730557.407 [DVL_micro](INFO): NQ1 requested
2013-04-23T15:22:37.407Z,1366730557.407 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:22:38.273Z,1366730558.273 [DAT](INFO): Powering up
2013-04-23T15:22:38.273Z,1366730558.273 [DAT](DEBUG): Initializing DAT.
2013-04-23T15:22:39.415Z,1366730559.415 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:22:39.415Z,1366730559.415 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-04-23T15:22:41.426Z,1366730561.426 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:22:41.426Z,1366730561.426 [DVL_micro](INFO): Enabling NQ1 output
2013-04-23T15:22:41.427Z,1366730561.427 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-04-23T15:22:41.665Z,1366730561.665 [SBIT](FAULT): Mass: EXPECTED:0.006000 ACTUAL:0.004815
2013-04-23T15:22:43.430Z,1366730563.430 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:22:43.430Z,1366730563.430 [DVL_micro](INFO): Querying output modes
2013-04-23T15:22:43.431Z,1366730563.431 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:22:45.441Z,1366730565.441 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:22:45.441Z,1366730565.441 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:22:45.441Z,1366730565.441 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:22:47.454Z,1366730567.454 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:22:49.467Z,1366730569.467 [DVL_micro](INFO): NQ1 requested
2013-04-23T15:22:49.467Z,1366730569.467 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:22:51.475Z,1366730571.475 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:22:51.475Z,1366730571.475 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-04-23T15:22:53.478Z,1366730573.478 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:22:53.478Z,1366730573.478 [DVL_micro](INFO): Enabling NQ1 output
2013-04-23T15:22:53.479Z,1366730573.479 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-04-23T15:22:54.747Z,1366730574.747 [CBIT](IMPORTANT): No ground fault detected
2013-04-23T15:22:55.482Z,1366730575.482 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:22:55.482Z,1366730575.482 [DVL_micro](INFO): Querying output modes
2013-04-23T15:22:55.482Z,1366730575.483 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:22:57.490Z,1366730577.490 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:22:57.491Z,1366730577.490 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:22:57.491Z,1366730577.491 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:22:58.273Z,1366730578.273 [DAT](INFO): Powering down
2013-04-23T15:22:59.502Z,1366730579.502 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:01.515Z,1366730581.515 [DVL_micro](INFO): NQ1 requested
2013-04-23T15:23:01.515Z,1366730581.515 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:23:03.523Z,1366730583.523 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:23:03.523Z,1366730583.523 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-04-23T15:23:05.530Z,1366730585.530 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:05.530Z,1366730585.530 [DVL_micro](INFO): Enabling NQ1 output
2013-04-23T15:23:05.531Z,1366730585.531 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-04-23T15:23:07.542Z,1366730587.542 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:07.542Z,1366730587.542 [DVL_micro](INFO): Querying output modes
2013-04-23T15:23:07.543Z,1366730587.543 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:23:09.554Z,1366730589.554 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:09.554Z,1366730589.554 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:23:09.554Z,1366730589.555 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:23:11.562Z,1366730591.562 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:13.570Z,1366730593.569 [DVL_micro](INFO): NQ1 requested
2013-04-23T15:23:13.570Z,1366730593.570 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:23:14.850Z,1366730594.851 [CommandLine](IMPORTANT): got command failComponent
2013-04-23T15:23:14.851Z,1366730594.851 [CommandLine](IMPORTANT): Failed components:
2013-04-23T15:23:14.851Z,1366730594.851 [CommandLine](IMPORTANT): AHRS_sp3003D: Hardware Fault
2013-04-23T15:23:14.851Z,1366730594.851 [CommandLine](IMPORTANT): DropWeight: Hardware Fault
2013-04-23T15:23:15.579Z,1366730595.579 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:23:15.579Z,1366730595.579 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-04-23T15:23:17.590Z,1366730597.590 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:17.590Z,1366730597.590 [DVL_micro](INFO): Enabling NQ1 output
2013-04-23T15:23:17.590Z,1366730597.591 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-04-23T15:23:19.602Z,1366730599.602 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:19.602Z,1366730599.602 [DVL_micro](INFO): Querying output modes
2013-04-23T15:23:19.603Z,1366730599.602 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:23:21.610Z,1366730601.610 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:21.610Z,1366730601.610 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:23:21.610Z,1366730601.611 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:23:22.289Z,1366730602.289 [SBIT](CRITICAL): SBIT FAILED
2013-04-23T15:23:22.366Z,1366730602.366 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/dat_on.xml
2013-04-23T15:23:22.367Z,1366730602.367 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/dat_on.xml
2013-04-23T15:23:22.384Z,1366730602.384 [MissionManager](INFO): DefineArg dat_on.MassDefault = -0.004050 n/a
2013-04-23T15:23:22.386Z,1366730602.386 [dat_on:A.Pitch](DEBUG): Construct.
2013-04-23T15:23:22.397Z,1366730602.397 [dat_on:TestDrive:C.Wait](DEBUG): Construct Wait.
2013-04-23T15:23:22.400Z,1366730602.400 [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:23:22.400Z,1366730602.400 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/dat_on.xml
2013-04-23T15:23:22.654Z,1366730602.654 [MissionManager](IMPORTANT): Started mission Startup
2013-04-23T15:23:22.654Z,1366730602.654 [Startup] Running Loop=1
2013-04-23T15:23:22.654Z,1366730602.654 [Startup](INFO): Aggregate::initialize Startup
2013-04-23T15:23:22.654Z,1366730602.654 [Startup:A.GoToSurface] Running Loop=1
2013-04-23T15:23:22.654Z,1366730602.654 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-04-23T15:23:22.660Z,1366730602.660 [Startup:StartupSatComms] Running Loop=1
2013-04-23T15:23:22.660Z,1366730602.660 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2013-04-23T15:23:22.660Z,1366730602.660 [Startup:StartupSatComms:A] Running Loop=1
2013-04-23T15:23:23.038Z,1366730603.037 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-04-23T15:23:23.614Z,1366730603.614 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:25.621Z,1366730605.621 [DVL_micro](INFO): NQ1 requested
2013-04-23T15:23:25.621Z,1366730605.621 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:23:26.971Z,1366730606.971 [CommandLine](IMPORTANT): got command show variable dat
2013-04-23T15:23:27.074Z,1366730607.074 [CommandLine](INFO): Config/vehicle.sendDataToShore (bool)
2013-04-23T15:23:27.076Z,1366730607.076 [CommandLine](INFO): Config/vehicle.DAT_card (none)
2013-04-23T15:23:27.077Z,1366730607.077 [CommandLine](INFO): Config/vehicle.DAT_uart (none)
2013-04-23T15:23:27.077Z,1366730607.077 [CommandLine](INFO): Config/vehicle.DAT_baud (bit_per_second)
2013-04-23T15:23:27.080Z,1366730607.080 [CommandLine](INFO): Config/Sensor.DAT_enable (bool)
2013-04-23T15:23:27.081Z,1366730607.081 [CommandLine](INFO): Config/Sensor.DAT_useHardware (bool)
2013-04-23T15:23:27.081Z,1366730607.081 [CommandLine](INFO): Config/Sensor.DAT_remoteAddress (count)
2013-04-23T15:23:27.081Z,1366730607.081 [CommandLine](INFO): Config/Sensor.DAT_rotationOffset (degree)
2013-04-23T15:23:27.098Z,1366730607.099 [CommandLine](INFO): Config/Simulator.oceanModelData (none)
2013-04-23T15:23:27.110Z,1366730607.110 [CommandLine](INFO): DAT.onewayRequestedCmd (bool)
2013-04-23T15:23:27.111Z,1366730607.111 [CommandLine](INFO): DAT.homing_target_range (meter)
2013-04-23T15:23:27.111Z,1366730607.111 [CommandLine](INFO): DAT.homing_target_azimuth (degree)
2013-04-23T15:23:27.111Z,1366730607.111 [CommandLine](INFO): DAT.homing_target_elevation (degree)
2013-04-23T15:23:27.112Z,1366730607.112 [CommandLine](INFO): DAT.homing_target_heading (degree)
2013-04-23T15:23:27.112Z,1366730607.112 [CommandLine](INFO): DAT.LVL1 (count)
2013-04-23T15:23:27.112Z,1366730607.112 [CommandLine](INFO): DAT.LVL2 (count)
2013-04-23T15:23:27.113Z,1366730607.113 [CommandLine](INFO): DAT.LVL3 (count)
2013-04-23T15:23:27.113Z,1366730607.113 [CommandLine](INFO): DAT.LVL4 (count)
2013-04-23T15:23:27.114Z,1366730607.114 [CommandLine](INFO): DAT.AGC (count)
2013-04-23T15:23:27.114Z,1366730607.114 [CommandLine](INFO): DAT.IDXPeak (count)
2013-04-23T15:23:27.115Z,1366730607.115 [CommandLine](INFO): DAT.IDXFit (degree)
2013-04-23T15:23:27.115Z,1366730607.115 [CommandLine](INFO): DAT.IDXPhase (degree)
2013-04-23T15:23:27.115Z,1366730607.115 [CommandLine](INFO): DAT.phaseA (degree)
2013-04-23T15:23:27.116Z,1366730607.116 [CommandLine](INFO): DAT.phaseB (degree)
2013-04-23T15:23:27.116Z,1366730607.116 [CommandLine](INFO): DAT.phaseC (degree)
2013-04-23T15:23:27.116Z,1366730607.116 [CommandLine](INFO): DAT.vectorMagnitude (degree)
2013-04-23T15:23:27.117Z,1366730607.117 [CommandLine](INFO): DAT.rawAzimuth (degree)
2013-04-23T15:23:27.117Z,1366730607.117 [CommandLine](INFO): DAT.rawElevation (degree)
2013-04-23T15:23:27.118Z,1366730607.118 [CommandLine](INFO): DAT.calibratedAzimuth (degree)
2013-04-23T15:23:27.118Z,1366730607.118 [CommandLine](INFO): DAT.calibratedElevation (degree)
2013-04-23T15:23:27.141Z,1366730607.141 [CommandLine](INFO): DAT.durationOfLastRun (second)
2013-04-23T15:23:27.148Z,1366730607.148 [CommandLine](INFO): DAT.component_voltage (volt)
2013-04-23T15:23:27.148Z,1366730607.148 [CommandLine](INFO): DAT.component_avgVoltage (volt)
2013-04-23T15:23:27.148Z,1366730607.148 [CommandLine](INFO): DAT.component_current (milliampere)
2013-04-23T15:23:27.149Z,1366730607.149 [CommandLine](INFO): DAT.component_avgCurrent (milliampere)
2013-04-23T15:23:27.149Z,1366730607.149 [CommandLine](INFO): dat_on.MassDefault (none)
2013-04-23T15:23:27.627Z,1366730607.627 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:23:27.627Z,1366730607.627 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-04-23T15:23:29.638Z,1366730609.638 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:29.638Z,1366730609.638 [DVL_micro](INFO): Enabling NQ1 output
2013-04-23T15:23:29.638Z,1366730609.638 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-04-23T15:23:31.642Z,1366730611.642 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:31.642Z,1366730611.642 [DVL_micro](INFO): Querying output modes
2013-04-23T15:23:31.642Z,1366730611.642 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:23:33.654Z,1366730613.654 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:33.654Z,1366730613.654 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:23:33.655Z,1366730613.655 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:23:35.299Z,1366730615.299 [CommandLine](IMPORTANT): got command report touch DAT.phaseA
2013-04-23T15:23:35.663Z,1366730615.662 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:37.667Z,1366730617.667 [DVL_micro](INFO): NQ1 requested
2013-04-23T15:23:37.667Z,1366730617.667 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:23:39.676Z,1366730619.676 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:23:39.677Z,1366730619.677 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-04-23T15:23:41.686Z,1366730621.686 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:41.686Z,1366730621.686 [DVL_micro](INFO): Enabling NQ1 output
2013-04-23T15:23:41.687Z,1366730621.687 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-04-23T15:23:43.694Z,1366730623.694 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:43.695Z,1366730623.694 [DVL_micro](INFO): Querying output modes
2013-04-23T15:23:43.695Z,1366730623.695 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:23:45.698Z,1366730625.698 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:45.698Z,1366730625.698 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:23:45.698Z,1366730625.698 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:23:47.711Z,1366730627.711 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:49.726Z,1366730629.726 [DVL_micro](INFO): NQ1 requested
2013-04-23T15:23:49.726Z,1366730629.727 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:23:49.775Z,1366730629.776 [CommandLine](IMPORTANT): got command report touch DAT.homing_target_range
2013-04-23T15:23:51.735Z,1366730631.735 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:23:51.735Z,1366730631.735 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-04-23T15:23:53.738Z,1366730633.738 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:53.738Z,1366730633.738 [DVL_micro](INFO): Enabling NQ1 output
2013-04-23T15:23:53.738Z,1366730633.739 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-04-23T15:23:55.742Z,1366730635.742 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:55.742Z,1366730635.742 [DVL_micro](INFO): Querying output modes
2013-04-23T15:23:55.743Z,1366730635.743 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:23:57.751Z,1366730637.750 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:23:57.751Z,1366730637.751 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:23:57.751Z,1366730637.751 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:23:59.762Z,1366730639.763 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:01.771Z,1366730641.771 [DVL_micro](INFO): NQ1 requested
2013-04-23T15:24:01.771Z,1366730641.771 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:24:03.779Z,1366730643.779 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:24:03.779Z,1366730643.779 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-04-23T15:24:04.687Z,1366730644.687 [CommandLine](IMPORTANT): got command show stack
2013-04-23T15:24:04.687Z,1366730644.687 [CommandLine](INFO): Behavior Stack:

2013-04-23T15:24:04.687Z,1366730644.687 [Startup](INFO): Priority 0: Startup:A.GoToSurface
2013-04-23T15:24:04.688Z,1366730644.688 [Startup:StartupSatComms](INFO): Priority 1: Startup:StartupSatComms:A
2013-04-23T15:24:05.787Z,1366730645.787 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:05.787Z,1366730645.787 [DVL_micro](INFO): Enabling NQ1 output
2013-04-23T15:24:05.787Z,1366730645.787 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-04-23T15:24:07.790Z,1366730647.790 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:07.790Z,1366730647.790 [DVL_micro](INFO): Querying output modes
2013-04-23T15:24:07.791Z,1366730647.791 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:24:09.803Z,1366730649.803 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:09.803Z,1366730649.803 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:24:09.803Z,1366730649.803 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:24:11.811Z,1366730651.810 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:12.023Z,1366730652.023 [CommandLine](IMPORTANT): got command failComponent
2013-04-23T15:24:12.023Z,1366730652.023 [CommandLine](IMPORTANT): Failed components:
2013-04-23T15:24:12.023Z,1366730652.023 [CommandLine](IMPORTANT): AHRS_sp3003D: Hardware Fault
2013-04-23T15:24:12.024Z,1366730652.024 [CommandLine](IMPORTANT): DropWeight: Hardware Fault
2013-04-23T15:24:13.825Z,1366730653.825 [DVL_micro](INFO): NQ1 requested
2013-04-23T15:24:13.825Z,1366730653.825 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:24:15.831Z,1366730655.831 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:24:15.831Z,1366730655.831 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-04-23T15:24:17.838Z,1366730657.838 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:17.839Z,1366730657.839 [DVL_micro](INFO): Enabling NQ1 output
2013-04-23T15:24:17.839Z,1366730657.839 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-04-23T15:24:19.842Z,1366730659.842 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:19.843Z,1366730659.843 [DVL_micro](INFO): Querying output modes
2013-04-23T15:24:19.843Z,1366730659.843 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:24:21.846Z,1366730661.846 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:21.847Z,1366730661.847 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:24:21.847Z,1366730661.847 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:24:22.979Z,1366730662.979 [Startup:StartupSatComms:A](INFO): Timed out from 2013-04-23T15:23:22.7Z
2013-04-23T15:24:22.979Z,1366730662.979 [Startup:StartupSatComms:A:A_Timeout] Running Loop=1
2013-04-23T15:24:22.979Z,1366730662.979 [Startup:StartupSatComms:A:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A:A_Timeout
2013-04-23T15:24:22.980Z,1366730662.980 [Startup:StartupSatComms:A:A_Timeout](INFO): Completed Startup:StartupSatComms:A:A_Timeout
2013-04-23T15:24:22.980Z,1366730662.980 [Startup:StartupSatComms:A] Stopped
2013-04-23T15:24:22.980Z,1366730662.980 [Startup:StartupSatComms:B] Running Loop=1
2013-04-23T15:24:23.347Z,1366730663.348 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-04-23T15:24:23.850Z,1366730663.851 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:25.855Z,1366730665.855 [DVL_micro](INFO): NQ1 requested
2013-04-23T15:24:25.855Z,1366730665.855 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:24:26.748Z,1366730666.748 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-04-23T15:24:27.863Z,1366730667.862 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:24:27.863Z,1366730667.863 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-04-23T15:24:29.874Z,1366730669.874 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:29.874Z,1366730669.874 [DVL_micro](INFO): Enabling NQ1 output
2013-04-23T15:24:29.874Z,1366730669.875 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-04-23T15:24:31.316Z,1366730671.316 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-04-23T15:24:31.887Z,1366730671.887 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:31.887Z,1366730671.887 [DVL_micro](INFO): Querying output modes
2013-04-23T15:24:31.887Z,1366730671.887 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:24:33.898Z,1366730673.898 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:33.898Z,1366730673.898 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:24:33.899Z,1366730673.899 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:24:35.480Z,1366730675.480 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-04-23T15:24:35.906Z,1366730675.906 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:37.915Z,1366730677.915 [DVL_micro](INFO): NQ1 requested
2013-04-23T15:24:37.915Z,1366730677.915 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:24:39.923Z,1366730679.923 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:24:39.923Z,1366730679.923 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-04-23T15:24:40.041Z,1366730680.041 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-04-23T15:24:41.930Z,1366730681.930 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:41.930Z,1366730681.930 [DVL_micro](INFO): Enabling NQ1 output
2013-04-23T15:24:41.930Z,1366730681.931 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-04-23T15:24:43.938Z,1366730683.938 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:43.938Z,1366730683.938 [DVL_micro](INFO): Querying output modes
2013-04-23T15:24:43.938Z,1366730683.938 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:24:44.588Z,1366730684.588 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-04-23T15:24:45.615Z,1366730685.615 [CommandLine](IMPORTANT): got command show stack
2013-04-23T15:24:45.615Z,1366730685.615 [CommandLine](INFO): Behavior Stack:

2013-04-23T15:24:45.615Z,1366730685.615 [Startup](INFO): Priority 0: Startup:A.GoToSurface
2013-04-23T15:24:45.615Z,1366730685.615 [Startup:StartupSatComms](INFO): Priority 1: Startup:StartupSatComms:B
2013-04-23T15:24:45.946Z,1366730685.946 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:45.946Z,1366730685.946 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:24:45.947Z,1366730685.947 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:24:47.954Z,1366730687.954 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:48.756Z,1366730688.756 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-04-23T15:24:49.959Z,1366730689.959 [DVL_micro](INFO): NQ1 requested
2013-04-23T15:24:49.959Z,1366730689.959 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:24:51.967Z,1366730691.967 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:24:51.967Z,1366730691.967 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-04-23T15:24:52.580Z,1366730692.580 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-04-23T15:24:53.974Z,1366730693.974 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:53.974Z,1366730693.974 [DVL_micro](INFO): Enabling NQ1 output
2013-04-23T15:24:53.975Z,1366730693.974 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-04-23T15:24:55.986Z,1366730695.986 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:55.986Z,1366730695.986 [DVL_micro](INFO): Querying output modes
2013-04-23T15:24:55.987Z,1366730695.987 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:24:56.423Z,1366730696.423 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2013-04-23T15:24:57.994Z,1366730697.994 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:24:57.994Z,1366730697.994 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:24:57.994Z,1366730697.994 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:25:00.002Z,1366730700.002 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:25:00.227Z,1366730700.227 [Startup:StartupSatComms:B] Stopped
2013-04-23T15:25:00.228Z,1366730700.227 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2013-04-23T15:25:00.228Z,1366730700.228 [Startup:StartupSatComms] Stopped
2013-04-23T15:25:00.228Z,1366730700.228 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2013-04-23T15:25:00.228Z,1366730700.228 [Startup](INFO): Completed Startup
2013-04-23T15:25:00.229Z,1366730700.229 [Startup] Stopped
2013-04-23T15:25:00.229Z,1366730700.229 [Startup](INFO): Aggregate::uninitialize Startup
2013-04-23T15:25:00.229Z,1366730700.229 [Startup:A.GoToSurface] Stopped
2013-04-23T15:25:00.229Z,1366730700.229 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-04-23T15:25:00.431Z,1366730700.431 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-04-23T15:25:00.445Z,1366730700.445 [MissionManager](IMPORTANT): Started mission dat_on
2013-04-23T15:25:00.445Z,1366730700.445 [dat_on] Running Loop=1
2013-04-23T15:25:00.445Z,1366730700.445 [dat_on](INFO): Aggregate::initialize dat_on
2013-04-23T15:25:00.445Z,1366730700.445 [dat_on:A.Pitch] Running Loop=1
2013-04-23T15:25:00.445Z,1366730700.445 [dat_on:A.Pitch](DEBUG): Initialize.
2013-04-23T15:25:00.446Z,1366730700.446 [dat_on:TestDrive] Running Loop=1
2013-04-23T15:25:00.446Z,1366730700.446 [dat_on:TestDrive](INFO): Aggregate::initialize dat_on:TestDrive
2013-04-23T15:25:00.446Z,1366730700.446 [dat_on:TestDrive:A] Running Loop=1
2013-04-23T15:25:00.447Z,1366730700.447 [dat_on:TestDrive:C.Wait] Running Loop=1
2013-04-23T15:25:00.447Z,1366730700.447 [dat_on:TestDrive:C.Wait](DEBUG): Initialize Wait Component.
2013-04-23T15:25:00.452Z,1366730700.452 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:00.452Z,1366730700.452 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:00.452Z,1366730700.452 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:00.455Z,1366730700.455 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:00.455Z,1366730700.455 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:00.455Z,1366730700.455 [dat_on:TestDrive:A] Running Loop=1
2013-04-23T15:25:00.456Z,1366730700.456 [dat_on:TestDrive:A](DEBUG): Initialize ReadDataComponent to sense homing_target_range
2013-04-23T15:25:00.457Z,1366730700.457 [dat_on:A.Pitch] Running Loop=1
2013-04-23T15:25:00.666Z,1366730700.666 [DAT](INFO): Powering up
2013-04-23T15:25:00.677Z,1366730700.677 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:00.677Z,1366730700.677 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:00.677Z,1366730700.677 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:00.677Z,1366730700.677 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:01.091Z,1366730701.091 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:01.091Z,1366730701.091 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:01.091Z,1366730701.092 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:01.092Z,1366730701.092 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:01.092Z,1366730701.092 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:01.495Z,1366730701.495 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:01.495Z,1366730701.495 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:01.495Z,1366730701.495 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:01.495Z,1366730701.495 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:01.891Z,1366730701.891 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:01.891Z,1366730701.891 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:01.891Z,1366730701.891 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:01.892Z,1366730701.892 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:01.892Z,1366730701.892 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:02.015Z,1366730702.015 [DVL_micro](INFO): NQ1 requested
2013-04-23T15:25:02.015Z,1366730702.015 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:25:02.318Z,1366730702.318 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:02.318Z,1366730702.318 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:02.318Z,1366730702.318 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:02.336Z,1366730702.336 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:02.739Z,1366730702.739 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:02.739Z,1366730702.739 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:02.739Z,1366730702.739 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:02.740Z,1366730702.740 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:02.740Z,1366730702.740 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:03.079Z,1366730703.079 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:03.079Z,1366730703.079 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:03.079Z,1366730703.079 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:03.079Z,1366730703.079 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:03.485Z,1366730703.485 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:03.485Z,1366730703.485 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:03.485Z,1366730703.485 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:03.485Z,1366730703.485 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:03.486Z,1366730703.486 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:03.889Z,1366730703.889 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:03.889Z,1366730703.889 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:03.889Z,1366730703.889 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:03.889Z,1366730703.889 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:04.043Z,1366730704.043 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:25:04.043Z,1366730704.043 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-04-23T15:25:04.299Z,1366730704.299 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:04.299Z,1366730704.299 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:04.300Z,1366730704.300 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:04.300Z,1366730704.300 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:04.300Z,1366730704.300 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:04.685Z,1366730704.685 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:04.685Z,1366730704.685 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:04.685Z,1366730704.685 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:04.685Z,1366730704.685 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:05.078Z,1366730705.078 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:05.078Z,1366730705.078 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:05.079Z,1366730705.079 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:05.079Z,1366730705.079 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:05.079Z,1366730705.079 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:05.507Z,1366730705.507 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:05.507Z,1366730705.507 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:05.507Z,1366730705.507 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:05.507Z,1366730705.507 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:05.873Z,1366730705.873 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:05.873Z,1366730705.873 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:05.873Z,1366730705.873 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:05.873Z,1366730705.874 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:05.874Z,1366730705.874 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:06.054Z,1366730706.054 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:25:06.054Z,1366730706.054 [DVL_micro](INFO): Enabling NQ1 output
2013-04-23T15:25:06.054Z,1366730706.055 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-04-23T15:25:06.275Z,1366730706.275 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:06.275Z,1366730706.275 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:06.275Z,1366730706.275 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:06.275Z,1366730706.275 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:06.674Z,1366730706.674 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:06.674Z,1366730706.674 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:06.674Z,1366730706.674 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:06.675Z,1366730706.675 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:06.675Z,1366730706.675 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:07.085Z,1366730707.085 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:07.085Z,1366730707.085 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:07.085Z,1366730707.085 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:07.085Z,1366730707.085 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:07.489Z,1366730707.489 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:07.489Z,1366730707.489 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:07.489Z,1366730707.489 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:07.490Z,1366730707.490 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:07.490Z,1366730707.490 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:07.955Z,1366730707.955 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:07.955Z,1366730707.955 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:07.955Z,1366730707.955 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:07.955Z,1366730707.955 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:08.066Z,1366730708.066 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:25:08.066Z,1366730708.066 [DVL_micro](INFO): Querying output modes
2013-04-23T15:25:08.067Z,1366730708.066 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:25:08.282Z,1366730708.282 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:08.282Z,1366730708.282 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:08.282Z,1366730708.282 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:08.283Z,1366730708.283 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:08.283Z,1366730708.283 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:08.711Z,1366730708.711 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:08.711Z,1366730708.711 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:08.711Z,1366730708.711 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:08.711Z,1366730708.711 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:09.079Z,1366730709.079 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:09.079Z,1366730709.079 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:09.079Z,1366730709.079 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:09.080Z,1366730709.080 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:09.080Z,1366730709.080 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:09.478Z,1366730709.478 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:09.479Z,1366730709.478 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:09.479Z,1366730709.479 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:09.479Z,1366730709.479 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:09.885Z,1366730709.885 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:09.885Z,1366730709.885 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:09.885Z,1366730709.885 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:09.886Z,1366730709.886 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:09.887Z,1366730709.887 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:10.074Z,1366730710.074 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:25:10.074Z,1366730710.074 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:25:10.075Z,1366730710.075 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:25:10.296Z,1366730710.296 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:10.296Z,1366730710.296 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:10.296Z,1366730710.296 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:10.296Z,1366730710.296 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:10.695Z,1366730710.695 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:10.695Z,1366730710.695 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:10.695Z,1366730710.695 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:10.696Z,1366730710.696 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:10.696Z,1366730710.696 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:11.078Z,1366730711.078 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:11.078Z,1366730711.078 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:11.079Z,1366730711.079 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:11.079Z,1366730711.079 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:11.478Z,1366730711.478 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:11.479Z,1366730711.478 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:11.479Z,1366730711.479 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:11.479Z,1366730711.479 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:11.479Z,1366730711.479 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:11.914Z,1366730711.914 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:11.914Z,1366730711.914 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:11.914Z,1366730711.914 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:11.914Z,1366730711.914 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:12.082Z,1366730712.082 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:25:12.273Z,1366730712.273 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:12.273Z,1366730712.273 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:12.274Z,1366730712.274 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:12.274Z,1366730712.274 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:12.275Z,1366730712.274 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:12.691Z,1366730712.691 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:12.691Z,1366730712.691 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:12.691Z,1366730712.691 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:12.691Z,1366730712.691 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:13.142Z,1366730713.142 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:13.142Z,1366730713.142 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:13.142Z,1366730713.142 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:13.143Z,1366730713.143 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:13.143Z,1366730713.143 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:13.485Z,1366730713.485 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:13.485Z,1366730713.485 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:13.485Z,1366730713.485 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:13.485Z,1366730713.485 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:13.874Z,1366730713.874 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:13.874Z,1366730713.875 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:13.875Z,1366730713.875 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:13.875Z,1366730713.875 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:13.875Z,1366730713.875 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:14.087Z,1366730714.087 [DVL_micro](INFO): NQ1 requested
2013-04-23T15:25:14.087Z,1366730714.087 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:25:14.278Z,1366730714.278 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:14.278Z,1366730714.278 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:14.278Z,1366730714.278 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:14.279Z,1366730714.279 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:14.690Z,1366730714.690 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:14.690Z,1366730714.690 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:14.691Z,1366730714.691 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:14.691Z,1366730714.691 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:14.691Z,1366730714.691 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:15.099Z,1366730715.099 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:15.099Z,1366730715.099 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:15.099Z,1366730715.099 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:15.099Z,1366730715.099 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:15.531Z,1366730715.531 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:15.531Z,1366730715.532 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:15.532Z,1366730715.532 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:15.532Z,1366730715.532 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:15.532Z,1366730715.532 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:15.879Z,1366730715.879 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:15.879Z,1366730715.879 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:15.879Z,1366730715.879 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:15.879Z,1366730715.879 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:16.094Z,1366730716.095 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:25:16.095Z,1366730716.095 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-04-23T15:25:16.278Z,1366730716.278 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:16.278Z,1366730716.278 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:16.278Z,1366730716.279 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:16.279Z,1366730716.279 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:16.279Z,1366730716.279 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:16.690Z,1366730716.690 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:16.691Z,1366730716.691 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:16.691Z,1366730716.691 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:16.691Z,1366730716.691 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:17.093Z,1366730717.093 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:17.093Z,1366730717.093 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:17.093Z,1366730717.093 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:17.094Z,1366730717.094 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:17.094Z,1366730717.094 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:17.491Z,1366730717.491 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:17.492Z,1366730717.492 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:17.492Z,1366730717.492 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:17.492Z,1366730717.492 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:17.879Z,1366730717.879 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:17.879Z,1366730717.879 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:17.879Z,1366730717.879 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:17.879Z,1366730717.879 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:17.880Z,1366730717.880 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:18.098Z,1366730718.098 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:25:18.098Z,1366730718.098 [DVL_micro](INFO): Enabling NQ1 output
2013-04-23T15:25:18.099Z,1366730718.099 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-04-23T15:25:18.371Z,1366730718.371 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:18.371Z,1366730718.371 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:18.371Z,1366730718.371 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:18.371Z,1366730718.371 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:18.691Z,1366730718.691 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:18.691Z,1366730718.691 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:18.691Z,1366730718.691 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:18.692Z,1366730718.692 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:18.692Z,1366730718.692 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:19.094Z,1366730719.094 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:19.095Z,1366730719.095 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:19.095Z,1366730719.095 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:19.095Z,1366730719.095 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:19.484Z,1366730719.484 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:19.485Z,1366730719.485 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:19.485Z,1366730719.485 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:19.485Z,1366730719.485 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:19.486Z,1366730719.486 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:19.874Z,1366730719.874 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:19.874Z,1366730719.875 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:19.875Z,1366730719.875 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:19.875Z,1366730719.875 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:20.106Z,1366730720.106 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:25:20.106Z,1366730720.106 [DVL_micro](INFO): Querying output modes
2013-04-23T15:25:20.106Z,1366730720.106 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:25:20.347Z,1366730720.347 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:20.347Z,1366730720.347 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:20.347Z,1366730720.347 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:20.347Z,1366730720.348 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:20.348Z,1366730720.348 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:20.709Z,1366730720.709 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:20.710Z,1366730720.710 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:20.710Z,1366730720.710 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:20.710Z,1366730720.710 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:21.099Z,1366730721.099 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:21.099Z,1366730721.099 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:21.099Z,1366730721.099 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:21.100Z,1366730721.100 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:21.100Z,1366730721.100 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:21.495Z,1366730721.495 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:21.495Z,1366730721.495 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:21.495Z,1366730721.495 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:21.495Z,1366730721.495 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:21.910Z,1366730721.910 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:21.911Z,1366730721.911 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:21.911Z,1366730721.911 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:21.911Z,1366730721.911 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:21.911Z,1366730721.911 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:22.118Z,1366730722.118 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:25:22.118Z,1366730722.118 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:25:22.119Z,1366730722.118 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:25:22.279Z,1366730722.279 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:22.279Z,1366730722.279 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:22.279Z,1366730722.279 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:22.279Z,1366730722.279 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:22.689Z,1366730722.689 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:22.689Z,1366730722.689 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:22.689Z,1366730722.690 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:22.690Z,1366730722.690 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:22.691Z,1366730722.691 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:23.143Z,1366730723.143 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:23.144Z,1366730723.144 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:23.144Z,1366730723.144 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:23.144Z,1366730723.144 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:23.491Z,1366730723.491 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:23.491Z,1366730723.491 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:23.491Z,1366730723.491 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:23.492Z,1366730723.492 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:23.492Z,1366730723.492 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:23.877Z,1366730723.877 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:23.877Z,1366730723.877 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:23.877Z,1366730723.877 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:23.877Z,1366730723.877 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:24.134Z,1366730724.134 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:25:24.273Z,1366730724.273 [DAT](ERROR): Unexpected response:16:36:38.8912 , LVL= 10432,  3377,  2514, 16739, AGC=  38, IDX= 30 0.15, 0.331, PHS=-0.015, 0.051, 0.066, |v|= 0.048, RAW= 260.0,-25.2, CAL= 268.2,-24.4, ROT= 347.2,-24.4, CMP= 293.0,  1.3,   0.5, 00:00:00.0000 
Compass  18.2
Range 1 to 0 : 0.2 m 
2013-04-23T15:25:24.283Z,1366730724.283 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:24.284Z,1366730724.284 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:24.284Z,1366730724.284 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:24.284Z,1366730724.284 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:24.285Z,1366730724.284 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:24.296Z,1366730724.296 [Reporter](INFO): DAT.homing_target_range nan m
2013-04-23T15:25:24.714Z,1366730724.714 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:24.714Z,1366730724.714 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:24.714Z,1366730724.714 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:24.714Z,1366730724.714 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:25.135Z,1366730725.135 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:25.135Z,1366730725.135 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:25.135Z,1366730725.135 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:25.136Z,1366730725.136 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:25.136Z,1366730725.136 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:25.486Z,1366730725.486 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:25.486Z,1366730725.486 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:25.486Z,1366730725.486 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:25.487Z,1366730725.487 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:25.875Z,1366730725.875 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:25.875Z,1366730725.875 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:25.875Z,1366730725.875 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:25.876Z,1366730725.876 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:25.876Z,1366730725.876 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:26.147Z,1366730726.147 [DVL_micro](INFO): NQ1 requested
2013-04-23T15:25:26.147Z,1366730726.147 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:25:26.279Z,1366730726.279 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:26.279Z,1366730726.279 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:26.279Z,1366730726.279 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:26.279Z,1366730726.279 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:26.685Z,1366730726.685 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:26.685Z,1366730726.685 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:26.685Z,1366730726.685 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:26.686Z,1366730726.686 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:26.686Z,1366730726.686 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:27.099Z,1366730727.099 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:27.099Z,1366730727.099 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:27.099Z,1366730727.099 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:27.099Z,1366730727.099 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:27.498Z,1366730727.498 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:27.498Z,1366730727.499 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:27.499Z,1366730727.499 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:27.499Z,1366730727.499 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:27.499Z,1366730727.499 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:27.879Z,1366730727.879 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:27.880Z,1366730727.880 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:27.880Z,1366730727.880 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:27.880Z,1366730727.880 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:28.155Z,1366730728.155 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:25:28.155Z,1366730728.155 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-04-23T15:25:28.371Z,1366730728.371 [DAT](ERROR): Unexpected response:16:36:42.9414 , LVL= 15392,  4945,  3522, 25043, AGC=  40, IDX= 62-0.16,-0.001, PHS=-0.015, 0.039, 0.062, |v|= 0.043, RAW= 253.0,-23.4, CAL= 261.4,-22.3, ROT= 340.4,-22.3, CMP= 293.0,  1.3,   0.5, 00:00:00.0000 
Compass  18.2
Range 1 to 0 : 0.2 m 
2013-04-23T15:25:28.380Z,1366730728.381 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:28.381Z,1366730728.381 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:28.381Z,1366730728.381 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:28.381Z,1366730728.381 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:28.382Z,1366730728.382 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:28.392Z,1366730728.392 [Reporter](INFO): DAT.homing_target_range nan m
2013-04-23T15:25:28.713Z,1366730728.713 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:28.714Z,1366730728.714 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:28.714Z,1366730728.714 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:28.714Z,1366730728.714 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:29.094Z,1366730729.094 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:29.094Z,1366730729.094 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:29.094Z,1366730729.094 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:29.095Z,1366730729.095 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:29.095Z,1366730729.095 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:29.491Z,1366730729.491 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:29.492Z,1366730729.492 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:29.492Z,1366730729.492 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:29.492Z,1366730729.492 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:29.875Z,1366730729.875 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:29.875Z,1366730729.875 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:29.875Z,1366730729.875 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:29.876Z,1366730729.876 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:29.876Z,1366730729.876 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:30.158Z,1366730730.158 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:25:30.158Z,1366730730.158 [DVL_micro](INFO): Enabling NQ1 output
2013-04-23T15:25:30.159Z,1366730730.158 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-04-23T15:25:30.279Z,1366730730.279 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:30.279Z,1366730730.279 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:30.279Z,1366730730.279 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:30.279Z,1366730730.279 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:30.695Z,1366730730.695 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:30.695Z,1366730730.695 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:30.695Z,1366730730.695 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:30.696Z,1366730730.696 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:30.696Z,1366730730.696 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:31.099Z,1366730731.099 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:31.099Z,1366730731.099 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:31.099Z,1366730731.099 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:31.099Z,1366730731.099 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:31.535Z,1366730731.535 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:31.535Z,1366730731.536 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:31.536Z,1366730731.536 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:31.536Z,1366730731.536 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:31.536Z,1366730731.536 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:31.884Z,1366730731.884 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:31.885Z,1366730731.885 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:31.885Z,1366730731.885 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:31.885Z,1366730731.885 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:32.170Z,1366730732.170 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:25:32.170Z,1366730732.170 [DVL_micro](INFO): Querying output modes
2013-04-23T15:25:32.170Z,1366730732.171 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:25:32.287Z,1366730732.287 [DAT](ERROR): Unexpected response:16:36:46.9416 , LVL= 14112,  4561,  3378, 22979, AGC=  41, IDX= 62 0.43,-0.267, PHS=-0.015, 0.049, 0.066, |v|= 0.048, RAW= 259.1,-24.7, CAL= 267.3,-23.9, ROT= 346.3,-23.9, CMP= 293.0,  1.3,   0.5, 00:00:00.0000 
Compass  18.2
Range 1 to 0 : 0.2 m 
2013-04-23T15:25:32.296Z,1366730732.296 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:32.296Z,1366730732.296 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:32.297Z,1366730732.297 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:32.297Z,1366730732.297 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:32.297Z,1366730732.297 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:32.307Z,1366730732.307 [Reporter](INFO): DAT.homing_target_range nan m
2013-04-23T15:25:32.695Z,1366730732.695 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:32.695Z,1366730732.695 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:32.695Z,1366730732.695 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:32.695Z,1366730732.695 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:33.075Z,1366730733.075 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:33.075Z,1366730733.075 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:33.075Z,1366730733.075 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:33.076Z,1366730733.076 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:33.076Z,1366730733.076 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:33.539Z,1366730733.539 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:33.539Z,1366730733.539 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:33.539Z,1366730733.539 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:33.539Z,1366730733.539 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:33.885Z,1366730733.885 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:33.885Z,1366730733.885 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:33.886Z,1366730733.886 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:33.887Z,1366730733.887 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:33.887Z,1366730733.887 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:34.182Z,1366730734.182 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:25:34.182Z,1366730734.182 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:25:34.183Z,1366730734.182 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:25:34.299Z,1366730734.299 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:34.299Z,1366730734.299 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:34.299Z,1366730734.299 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:34.300Z,1366730734.300 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:34.733Z,1366730734.733 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:34.733Z,1366730734.733 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:34.733Z,1366730734.733 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:34.733Z,1366730734.733 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:34.734Z,1366730734.734 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:35.079Z,1366730735.079 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:35.079Z,1366730735.079 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:35.079Z,1366730735.079 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:35.079Z,1366730735.079 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:35.478Z,1366730735.478 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:35.478Z,1366730735.478 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:35.479Z,1366730735.479 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:35.479Z,1366730735.479 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:35.479Z,1366730735.479 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:35.881Z,1366730735.881 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:35.881Z,1366730735.881 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:35.881Z,1366730735.881 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:35.882Z,1366730735.882 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:36.190Z,1366730736.190 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:25:36.279Z,1366730736.279 [DAT](ERROR): Unexpected response:16:36:50.9418 , LVL= 12784,  4225,  3170, 20915, AGC=  40, IDX= 62 0.15, 2.296, PHS=-0.015, 0.051, 0.066, |v|= 0.048, RAW= 260.3,-24.9, CAL= 268.4,-24.2, ROT= 347.4,-24.2, CMP= 293.0,  1.3,   0.5, 00:00:00.0000 
Compass  18.2
Range 1 to 0 : 0.2 m 
2013-04-23T15:25:36.289Z,1366730736.289 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:36.289Z,1366730736.289 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:36.289Z,1366730736.289 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:36.290Z,1366730736.290 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:36.290Z,1366730736.290 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:36.300Z,1366730736.300 [Reporter](INFO): DAT.homing_target_range nan m
2013-04-23T15:25:36.713Z,1366730736.713 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:36.714Z,1366730736.714 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:36.714Z,1366730736.714 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:36.714Z,1366730736.714 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:37.091Z,1366730737.091 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:37.091Z,1366730737.091 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:37.091Z,1366730737.091 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:37.092Z,1366730737.092 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:37.092Z,1366730737.092 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:37.495Z,1366730737.494 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:37.495Z,1366730737.495 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:37.495Z,1366730737.495 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:37.495Z,1366730737.495 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:37.550Z,1366730737.550 [CommandLine](IMPORTANT): got command quit
2013-04-23T15:25:37.879Z,1366730737.879 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:37.879Z,1366730737.879 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:37.879Z,1366730737.879 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:37.880Z,1366730737.880 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:37.880Z,1366730737.880 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:38.195Z,1366730738.195 [DVL_micro](INFO): NQ1 requested
2013-04-23T15:25:38.195Z,1366730738.195 [DVL_micro](INFO): Cycling power to configure device.
2013-04-23T15:25:38.379Z,1366730738.378 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:38.379Z,1366730738.379 [dat_on:TestDrive:Data](INFO): Completed dat_on:TestDrive:Data
2013-04-23T15:25:38.379Z,1366730738.379 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:38.379Z,1366730738.379 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:38.578Z,1366730738.578 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2013-04-23T15:25:38.578Z,1366730738.578 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2013-04-23T15:25:38.691Z,1366730738.691 [dat_on:TestDrive:Data] Running Loop=1
2013-04-23T15:25:38.691Z,1366730738.691 [dat_on:TestDrive:Data](INFO): Aggregate::initialize dat_on:TestDrive:Data
2013-04-23T15:25:38.692Z,1366730738.691 [dat_on:TestDrive:Data:A] Running Loop=1
2013-04-23T15:25:38.692Z,1366730738.692 [dat_on:TestDrive:Data:A] Stopped
2013-04-23T15:25:38.692Z,1366730738.692 [dat_on:TestDrive:Data:B] Running Loop=1
2013-04-23T15:25:38.693Z,1366730738.693 [dat_on] Stopped
2013-04-23T15:25:38.693Z,1366730738.693 [dat_on](INFO): Aggregate::uninitialize dat_on
2013-04-23T15:25:38.693Z,1366730738.693 [dat_on:A.Pitch] Stopped
2013-04-23T15:25:38.693Z,1366730738.693 [dat_on:TestDrive] Stopped
2013-04-23T15:25:38.693Z,1366730738.693 [dat_on:TestDrive](INFO): Aggregate::uninitialize dat_on:TestDrive
2013-04-23T15:25:38.693Z,1366730738.693 [dat_on:TestDrive:A] Stopped
2013-04-23T15:25:38.693Z,1366730738.693 [dat_on:TestDrive:Data] Stopped
2013-04-23T15:25:38.693Z,1366730738.694 [dat_on:TestDrive:Data](INFO): Aggregate::uninitialize dat_on:TestDrive:Data
2013-04-23T15:25:38.693Z,1366730738.694 [dat_on:TestDrive:Data:B] Stopped
2013-04-23T15:25:38.694Z,1366730738.694 [dat_on:TestDrive:C.Wait] Stopped
2013-04-23T15:25:38.694Z,1366730738.694 [dat_on:TestDrive:C.Wait](DEBUG): Uninitialize Wait Component.
2013-04-23T15:25:38.698Z,1366730738.698 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2013-04-23T15:25:38.979Z,1366730738.978 [WetLabsBB2FL](INFO): Powering down
2013-04-23T15:25:38.990Z,1366730738.990 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2013-04-23T15:25:39.055Z,1366730739.055 [CTD_NeilBrown](INFO): Powering down
2013-04-23T15:25:39.062Z,1366730739.062 [ComponentRegistry](INFO): Shutting down DVL_micro ThreadHandler
2013-04-23T15:25:39.098Z,1366730739.098 [MissionManager](IMPORTANT): Started mission Default
2013-04-23T15:25:39.098Z,1366730739.098 [Default] Running Loop=1
2013-04-23T15:25:39.098Z,1366730739.098 [Default](INFO): Aggregate::initialize Default
2013-04-23T15:25:39.098Z,1366730739.098 [Default:D.SetSpeed] Running Loop=1
2013-04-23T15:25:39.098Z,1366730739.098 [Default:D.SetSpeed](DEBUG): Initialize.
2013-04-23T15:25:39.098Z,1366730739.098 [Default:E.GoToSurface] Running Loop=1
2013-04-23T15:25:39.098Z,1366730739.099 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-04-23T15:25:39.099Z,1366730739.099 [Default:Iridium] Running Loop=1
2013-04-23T15:25:39.099Z,1366730739.099 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2013-04-23T15:25:39.099Z,1366730739.099 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-04-23T15:25:39.099Z,1366730739.099 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2013-04-23T15:25:39.099Z,1366730739.099 [Default:Iridium:B.GoToSurface] Running Loop=1
2013-04-23T15:25:39.099Z,1366730739.099 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-04-23T15:25:39.100Z,1366730739.100 [Default:E.GoToSurface] Running Loop=1
2013-04-23T15:25:39.105Z,1366730739.105 [Default:D.SetSpeed] Running Loop=1
2013-04-23T15:25:39.115Z,1366730739.115 [Default:Iridium:B.GoToSurface] Stopped
2013-04-23T15:25:39.115Z,1366730739.115 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-04-23T15:25:39.116Z,1366730739.115 [Default:Iridium:Read_Iridium] Running Loop=1
2013-04-23T15:25:39.116Z,1366730739.115 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-04-23T15:25:39.137Z,1366730739.136 [Default:GPS] Running Loop=1
2013-04-23T15:25:39.137Z,1366730739.137 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2013-04-23T15:25:39.137Z,1366730739.137 [Default:GPS:A.SetSpeed] Running Loop=1
2013-04-23T15:25:39.137Z,1366730739.137 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2013-04-23T15:25:39.137Z,1366730739.137 [Default:GPS:B.GoToSurface] Running Loop=1
2013-04-23T15:25:39.137Z,1366730739.137 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-04-23T15:25:39.151Z,1366730739.151 [Default:GPS:B.GoToSurface] Stopped
2013-04-23T15:25:39.151Z,1366730739.151 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-04-23T15:25:39.151Z,1366730739.151 [Default:GPS:Read_GPS] Running Loop=1
2013-04-23T15:25:39.151Z,1366730739.151 [Default:GPS:A.SetSpeed] Running Loop=1
2013-04-23T15:25:39.481Z,1366730739.481 [DAT](INFO): Powering down
2013-04-23T15:25:39.612Z,1366730739.612 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-04-23T15:25:39.615Z,1366730739.615 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-04-23T15:25:40.203Z,1366730740.203 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-04-23T15:25:40.203Z,1366730740.203 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-04-23T15:25:41.256Z,1366730741.256 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-04-23T15:25:42.214Z,1366730742.214 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:25:42.214Z,1366730742.214 [DVL_micro](INFO): Enabling NQ1 output
2013-04-23T15:25:42.214Z,1366730742.214 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-04-23T15:25:44.226Z,1366730744.226 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:25:44.226Z,1366730744.226 [DVL_micro](INFO): Querying output modes
2013-04-23T15:25:44.227Z,1366730744.227 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-04-23T15:25:45.441Z,1366730745.441 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-04-23T15:25:46.238Z,1366730746.238 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:25:46.238Z,1366730746.238 [DVL_micro](INFO): Output Modes: No Response
2013-04-23T15:25:46.239Z,1366730746.239 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-04-23T15:25:47.844Z,1366730747.844 [CBIT](CRITICAL): run-time exception #7
2013-04-23T15:25:47.844Z,1366730747.844 [CBIT](CRITICAL): Bad address: 0x40309008
2013-04-23T15:25:47.844Z,1366730747.844 [CBIT](CRITICAL): Backtrace: 
./bin/LRAUV(_ZN7PCaller20DefaultSignalHandlerEiP7siginfoPv+0x20) [0x14765c]
/lib/libc.so.6(__default_rt_sa_restorer+0) [0x40203510]

2013-04-23T15:25:47.844Z,1366730747.844 [CBIT] Software Fault, FailCount= 1
2013-04-23T15:25:47.844Z,1366730747.844 [CBIT](ERROR): Software Fault
2013-04-23T15:25:47.846Z,1366730747.846 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2013-04-23T15:25:47.847Z,1366730747.847 [CBIT](INFO): Thread ID is 6745
2013-04-23T15:25:48.246Z,1366730748.246 [DVL_micro](DEBUG): cmdResponse: 
2013-04-23T15:25:48.247Z,1366730748.247 [DVL_micro](INFO): uninitialize:Powering down
2013-04-23T15:25:48.354Z,1366730748.354 [CBIT](DEBUG): Uninitialize CBIT Component.
2013-04-23T15:25:48.389Z,1366730748.389 [CBIT](CRITICAL): run-time exception #7
2013-04-23T15:25:48.390Z,1366730748.390 [CBIT](CRITICAL): Bad address: 0x40309004
2013-04-23T15:25:48.390Z,1366730748.390 [CBIT](CRITICAL): Backtrace: 
./bin/LRAUV(_ZN7PCaller20DefaultSignalHandlerEiP7siginfoPv+0x20) [0x14765c]
/lib/libc.so.6(__default_rt_sa_restorer+0) [0x40203510]

2013-04-23T15:25:48.391Z,1366730748.391 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2013-04-23T15:25:48.391Z,1366730748.391 [CBIT](INFO): Thread ID is 6752
2013-04-23T15:25:48.651Z,1366730748.651 [DVL_micro](INFO): uninitialize:Powering down
2013-04-23T15:25:48.670Z,1366730748.670 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2013-04-23T15:25:48.899Z,1366730748.898 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2013-04-23T15:25:48.911Z,1366730748.911 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2013-04-23T15:25:48.943Z,1366730748.943 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2013-04-23T15:25:48.952Z,1366730748.952 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2013-04-23T15:25:48.983Z,1366730748.983 [controlThread](DEBUG): Uninitializing ControlThread
2013-04-23T15:25:48.983Z,1366730748.983 [AHRS_sp3003D](INFO): Powering down
2013-04-23T15:25:48.985Z,1366730748.985 [NAL9602](INFO): Powering down
2013-04-23T15:25:48.986Z,1366730748.986 [DAT](INFO): Powering down
2013-04-23T15:25:48.988Z,1366730748.987 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-04-23T15:25:48.988Z,1366730748.988 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2013-04-23T15:25:48.989Z,1366730748.989 [Default] Stopped
2013-04-23T15:25:48.989Z,1366730748.989 [Default](INFO): Aggregate::uninitialize Default
2013-04-23T15:25:48.989Z,1366730748.989 [Default:GPS] Stopped
2013-04-23T15:25:48.989Z,1366730748.989 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2013-04-23T15:25:48.989Z,1366730748.990 [Default:GPS:A.SetSpeed] Stopped
2013-04-23T15:25:48.990Z,1366730748.990 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2013-04-23T15:25:48.990Z,1366730748.990 [Default:GPS:Read_GPS] Stopped
2013-04-23T15:25:48.990Z,1366730748.990 [Default:Iridium] Stopped
2013-04-23T15:25:48.990Z,1366730748.990 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2013-04-23T15:25:48.990Z,1366730748.990 [Default:Iridium:A.SetSpeed] Stopped
2013-04-23T15:25:48.990Z,1366730748.990 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2013-04-23T15:25:48.990Z,1366730748.990 [Default:Iridium:Read_Iridium] Stopped
2013-04-23T15:25:48.990Z,1366730748.990 [Default:D.SetSpeed] Stopped
2013-04-23T15:25:48.990Z,1366730748.990 [Default:D.SetSpeed](DEBUG): Uninitialize.
2013-04-23T15:25:48.990Z,1366730748.990 [Default:E.GoToSurface] Stopped
2013-04-23T15:25:48.990Z,1366730748.990 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-04-23T15:25:48.995Z,1366730748.995 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2013-04-23T15:25:48.995Z,1366730748.995 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2013-04-23T15:25:48.995Z,1366730748.995 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2013-04-23T15:25:48.996Z,1366730748.996 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2013-04-23T15:25:48.996Z,1366730748.996 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-04-23T15:25:48.996Z,1366730748.996 [BuoyancyServo](INFO): Powering down
2013-04-23T15:25:49.010Z,1366730749.010 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2013-04-23T15:25:49.011Z,1366730749.011 [ElevatorServo](INFO): Powering down
2013-04-23T15:25:49.012Z,1366730749.012 [MassServo](DEBUG): Uninitialize Mass Servo.
2013-04-23T15:25:49.012Z,1366730749.012 [MassServo](INFO): Powering down
2013-04-23T15:25:49.012Z,1366730749.012 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2013-04-23T15:25:49.013Z,1366730749.013 [RudderServo](INFO): Powering down
2013-04-23T15:25:49.013Z,1366730749.013 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2013-04-23T15:25:49.013Z,1366730749.013 [ThrusterServo](INFO): Powering down
2013-04-23T15:25:49.014Z,1366730749.014 [SBIT](DEBUG): Uninitialize SBIT Component.
2013-04-23T15:25:49.014Z,1366730749.014 [IBIT](DEBUG): Uninitialize IBIT Component.
2013-04-23T15:25:49.015Z,1366730749.015 [CBIT](DEBUG): Uninitialize CBIT Component.
2013-04-23T15:25:49.049Z,1366730749.049 [CBIT](CRITICAL): run-time exception #7
2013-04-23T15:25:49.050Z,1366730749.050 [CBIT](CRITICAL): Bad address: 0x40309004
2013-04-23T15:25:49.050Z,1366730749.050 [CBIT](CRITICAL): Backtrace: 
./bin/LRAUV(_ZN7PCaller20DefaultSignalHandlerEiP7siginfoPv+0x20) [0x14765c]
/lib/libc.so.6(__default_rt_sa_restorer+0) [0x40203510]

2013-04-23T15:25:49.051Z,1366730749.051 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2013-04-23T15:25:49.052Z,1366730749.052 [CBIT](INFO): Thread ID is 6765