2013-05-22T14:43:02.416Z,1369233782.416 [Supervisor](DEBUG): Initializing supervisor. 2013-05-22T14:43:02.419Z,1369233782.418 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0 2013-05-22T14:43:02.419Z,1369233782.419 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2013-05-22T14:43:02.420Z,1369233782.420 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0 2013-05-22T14:43:02.424Z,1369233782.424 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2013-05-22T14:43:02.434Z,1369233782.434 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2013-05-22T14:43:02.435Z,1369233782.435 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0 2013-05-22T14:43:02.436Z,1369233782.436 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2013-05-22T14:43:02.437Z,1369233782.437 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0 2013-05-22T14:43:02.438Z,1369233782.438 [Supervisor](INFO): Looking for Config files in directory: Config/ 2013-05-22T14:43:02.439Z,1369233782.439 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2013-05-22T14:43:02.723Z,1369233782.723 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2013-05-22T14:43:02.723Z,1369233782.723 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2013-05-22T14:43:02.913Z,1369233782.913 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2013-05-22T14:43:02.914Z,1369233782.914 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2013-05-22T14:43:02.998Z,1369233782.998 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2013-05-22T14:43:02.998Z,1369233782.999 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2013-05-22T14:43:03.201Z,1369233783.201 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2013-05-22T14:43:03.202Z,1369233783.202 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2013-05-22T14:43:03.339Z,1369233783.339 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2013-05-22T14:43:03.340Z,1369233783.340 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2013-05-22T14:43:03.576Z,1369233783.576 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2013-05-22T14:43:03.577Z,1369233783.577 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2013-05-22T14:43:03.747Z,1369233783.747 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2013-05-22T14:43:03.748Z,1369233783.748 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2013-05-22T14:43:04.005Z,1369233784.005 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2013-05-22T14:43:04.006Z,1369233784.006 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2013-05-22T14:43:04.104Z,1369233784.104 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2013-05-22T14:43:04.105Z,1369233784.105 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2013-05-22T14:43:04.511Z,1369233784.511 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2013-05-22T14:43:04.512Z,1369233784.512 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2013-05-22T14:43:04.625Z,1369233784.625 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2013-05-22T14:43:04.626Z,1369233784.626 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2013-05-22T14:43:04.711Z,1369233784.711 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/ 2013-05-22T14:43:04.711Z,1369233784.711 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg 2013-05-22T14:43:04.816Z,1369233784.816 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg 2013-05-22T14:43:04.945Z,1369233784.945 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg 2013-05-22T14:43:05.095Z,1369233785.095 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg 2013-05-22T14:43:05.199Z,1369233785.199 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg 2013-05-22T14:43:05.298Z,1369233785.298 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg 2013-05-22T14:43:05.416Z,1369233785.416 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg 2013-05-22T14:43:05.509Z,1369233785.509 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg 2013-05-22T14:43:05.596Z,1369233785.596 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/LOGIN/ 2013-05-22T14:43:05.596Z,1369233785.596 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg 2013-05-22T14:43:05.625Z,1369233785.625 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2013-05-22T14:43:05.775Z,1369233785.776 [InternalSim] Loaded 2013-05-22T14:43:05.776Z,1369233785.776 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread. 2013-05-22T14:43:05.777Z,1369233785.777 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2013-05-22T14:43:05.777Z,1369233785.777 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2013-05-22T14:43:05.835Z,1369233785.835 [SBIT](DEBUG): Construct Startup Built In Test. 2013-05-22T14:43:05.864Z,1369233785.865 [SBIT] Loaded 2013-05-22T14:43:05.865Z,1369233785.865 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2013-05-22T14:43:05.866Z,1369233785.866 [IBIT](DEBUG): Construct Initiated Built In Test. 2013-05-22T14:43:05.896Z,1369233785.896 [IBIT] Loaded 2013-05-22T14:43:05.896Z,1369233785.896 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2013-05-22T14:43:05.899Z,1369233785.899 [CBIT](DEBUG): Construct CBIT Built In Test. 2013-05-22T14:43:06.017Z,1369233786.017 [CBIT] Loaded 2013-05-22T14:43:06.017Z,1369233786.017 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2013-05-22T14:43:06.018Z,1369233786.018 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2013-05-22T14:43:06.018Z,1369233786.018 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2013-05-22T14:43:06.168Z,1369233786.168 [BuoyancyServo] Loaded 2013-05-22T14:43:06.168Z,1369233786.168 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2013-05-22T14:43:06.181Z,1369233786.181 [ElevatorServo] Loaded 2013-05-22T14:43:06.181Z,1369233786.181 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2013-05-22T14:43:06.193Z,1369233786.193 [MassServo] Loaded 2013-05-22T14:43:06.193Z,1369233786.193 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2013-05-22T14:43:06.205Z,1369233786.205 [RudderServo] Loaded 2013-05-22T14:43:06.206Z,1369233786.206 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2013-05-22T14:43:06.218Z,1369233786.217 [ThrusterServo] Loaded 2013-05-22T14:43:06.218Z,1369233786.218 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2013-05-22T14:43:06.218Z,1369233786.218 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2013-05-22T14:43:06.219Z,1369233786.219 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2013-05-22T14:43:06.236Z,1369233786.236 [DepthRateCalculator] Loaded 2013-05-22T14:43:06.236Z,1369233786.237 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2013-05-22T14:43:09.188Z,1369233789.188 [HFRadarModelCalc] Loaded 2013-05-22T14:43:09.188Z,1369233789.188 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread. 2013-05-22T14:43:09.204Z,1369233789.204 [NavChart] Loaded 2013-05-22T14:43:09.205Z,1369233789.205 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2013-05-22T14:43:09.211Z,1369233789.211 [PitchRateCalculator] Loaded 2013-05-22T14:43:09.211Z,1369233789.211 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2013-05-22T14:43:09.222Z,1369233789.222 [SpeedCalculator] Loaded 2013-05-22T14:43:09.222Z,1369233789.223 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2013-05-22T14:43:09.237Z,1369233789.237 [TempGradientCalculator] Loaded 2013-05-22T14:43:09.238Z,1369233789.238 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2013-05-22T14:43:09.244Z,1369233789.244 [YawRateCalculator] Loaded 2013-05-22T14:43:09.244Z,1369233789.244 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2013-05-22T14:43:09.291Z,1369233789.291 [Navigation] Loaded 2013-05-22T14:43:09.291Z,1369233789.291 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread. 2013-05-22T14:43:09.291Z,1369233789.291 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2013-05-22T14:43:09.292Z,1369233789.292 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2013-05-22T14:43:09.504Z,1369233789.504 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2013-05-22T14:43:09.505Z,1369233789.505 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2013-05-22T14:43:09.527Z,1369233789.527 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2013-05-22T14:43:09.527Z,1369233789.527 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2013-05-22T14:43:09.566Z,1369233789.566 [VerticalControl](DEBUG): Construct VerticalControl. 2013-05-22T14:43:09.661Z,1369233789.661 [VerticalControl] Loaded 2013-05-22T14:43:09.661Z,1369233789.661 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2013-05-22T14:43:09.663Z,1369233789.662 [HorizontalControl](DEBUG): Construct HorizontalControl. 2013-05-22T14:43:09.720Z,1369233789.720 [HorizontalControl] Loaded 2013-05-22T14:43:09.720Z,1369233789.720 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2013-05-22T14:43:09.721Z,1369233789.721 [SpeedControl](DEBUG): Construct SpeedControl. 2013-05-22T14:43:09.722Z,1369233789.722 [SpeedControl] Loaded 2013-05-22T14:43:09.723Z,1369233789.723 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2013-05-22T14:43:09.724Z,1369233789.724 [LoopControl](DEBUG): Construct LoopControl. 2013-05-22T14:43:09.724Z,1369233789.724 [LoopControl] Loaded 2013-05-22T14:43:09.725Z,1369233789.724 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2013-05-22T14:43:09.725Z,1369233789.725 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2013-05-22T14:43:09.725Z,1369233789.726 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2013-05-22T14:43:09.731Z,1369233789.731 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator. 2013-05-22T14:43:09.736Z,1369233789.736 [AsyncPiEstimator] Loaded 2013-05-22T14:43:09.736Z,1369233789.736 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread. 2013-05-22T14:43:09.737Z,1369233789.737 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 4063B4E0 2013-05-22T14:43:09.738Z,1369233789.738 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2013-05-22T14:43:09.739Z,1369233789.739 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2013-05-22T14:43:09.866Z,1369233789.866 [AHRS_sp3003D] Loaded 2013-05-22T14:43:09.866Z,1369233789.866 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread. 2013-05-22T14:43:10.126Z,1369233790.126 [Batt_Ocean_Server] Loaded 2013-05-22T14:43:10.126Z,1369233790.126 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread. 2013-05-22T14:43:10.140Z,1369233790.140 [Depth_Keller] Loaded 2013-05-22T14:43:10.141Z,1369233790.141 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2013-05-22T14:43:10.146Z,1369233790.146 [DropWeight] Loaded 2013-05-22T14:43:10.147Z,1369233790.147 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2013-05-22T14:43:10.319Z,1369233790.319 [DVL_micro] Loaded 2013-05-22T14:43:10.319Z,1369233790.319 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread. 2013-05-22T14:43:10.320Z,1369233790.320 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 406B64E0 2013-05-22T14:43:10.403Z,1369233790.403 [NAL9602] Loaded 2013-05-22T14:43:10.403Z,1369233790.403 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2013-05-22T14:43:10.456Z,1369233790.456 [Onboard] Loaded 2013-05-22T14:43:10.456Z,1369233790.456 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2013-05-22T14:43:10.463Z,1369233790.463 [Radio_Freewave] Loaded 2013-05-22T14:43:10.463Z,1369233790.463 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread. 2013-05-22T14:43:10.623Z,1369233790.623 [DAT] Loaded 2013-05-22T14:43:10.624Z,1369233790.624 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread. 2013-05-22T14:43:10.624Z,1369233790.624 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2013-05-22T14:43:10.625Z,1369233790.625 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2013-05-22T14:43:10.697Z,1369233790.697 [CTD_NeilBrown] Loaded 2013-05-22T14:43:10.697Z,1369233790.697 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2013-05-22T14:43:10.699Z,1369233790.699 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407084E0 2013-05-22T14:43:10.730Z,1369233790.730 [WetLabsBB2FL] Loaded 2013-05-22T14:43:10.730Z,1369233790.730 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2013-05-22T14:43:10.731Z,1369233790.731 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407384E0 2013-05-22T14:43:10.732Z,1369233790.732 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2013-05-22T14:43:10.734Z,1369233790.734 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2013-05-22T14:43:10.735Z,1369233790.735 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2013-05-22T14:43:10.742Z,1369233790.742 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2013-05-22T14:43:10.743Z,1369233790.743 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407684E0 2013-05-22T14:43:10.747Z,1369233790.747 [Supervisor](DEBUG): Running supervisor. 2013-05-22T14:43:10.748Z,1369233790.748 [CommandLine](INFO): Thread ID is 9882 2013-05-22T14:43:10.751Z,1369233790.751 [controlThread](INFO): Thread ID is 9881 2013-05-22T14:43:10.751Z,1369233790.751 [controlThread](DEBUG): Initializing ControlThread 2013-05-22T14:43:10.752Z,1369233790.751 [CycleStarter](INFO): Thread ID is 9880 2013-05-22T14:43:10.752Z,1369233790.752 [InternalSim](DEBUG): InternalSim initializing... 2013-05-22T14:43:10.787Z,1369233790.787 [logger](INFO): Thread ID is 9883 2013-05-22T14:43:10.811Z,1369233790.811 [SBIT](INFO): Initialize SBIT Component. 2013-05-22T14:43:10.812Z,1369233790.812 [SBIT](IMPORTANT): Tethys CM Info: $Rev:10376 2013-05-22T14:43:10.812Z,1369233790.812 [SBIT](IMPORTANT): Kernel Release:2.6.27.8 2013-05-22T14:43:10.812Z,1369233790.812 [SBIT](IMPORTANT): Kernel Version:#634 PREEMPT Wed Feb 13 10:21:48 PST 2013 2013-05-22T14:43:10.813Z,1369233790.813 [IBIT](INFO): Initialize IBIT Component. 2013-05-22T14:43:10.814Z,1369233790.814 [CBIT](DEBUG): Initialize CBIT Component. 2013-05-22T14:43:10.814Z,1369233790.814 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL. 2013-05-22T14:43:10.814Z,1369233790.814 [CBIT](CRITICAL): Watchdog Timer failed to initialize. 2013-05-22T14:43:10.814Z,1369233790.814 [CBIT] Hardware Fault, FailCount= 1 2013-05-22T14:43:10.814Z,1369233790.815 [CBIT](ERROR): Hardware Fault 2013-05-22T14:43:10.827Z,1369233790.827 [AsyncPiEstimator](INFO): Thread ID is 9944 2013-05-22T14:43:10.827Z,1369233790.827 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator. 2013-05-22T14:43:10.839Z,1369233790.839 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2013-05-22T14:43:10.840Z,1369233790.840 [NavChart](DEBUG): Initialize NavChart Derivation. 2013-05-22T14:43:10.840Z,1369233790.840 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2013-05-22T14:43:10.841Z,1369233790.841 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2013-05-22T14:43:10.841Z,1369233790.841 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2013-05-22T14:43:10.843Z,1369233790.843 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2013-05-22T14:43:10.843Z,1369233790.843 [Navigation](DEBUG): Initializing Navigation. 2013-05-22T14:43:10.843Z,1369233790.843 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2013-05-22T14:43:10.845Z,1369233790.845 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2013-05-22T14:43:10.846Z,1369233790.846 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2013-05-22T14:43:10.847Z,1369233790.847 [LoopControl](DEBUG): Initialize LoopControlComponent. 2013-05-22T14:43:10.853Z,1369233790.852 [DVL_micro](INFO): Thread ID is 9945 2013-05-22T14:43:10.862Z,1369233790.862 [DVL_micro](INFO): Initializing 2013-05-22T14:43:10.862Z,1369233790.862 [DVL_micro](INFO): start:Powering up 2013-05-22T14:43:10.863Z,1369233790.863 [DVL_micro](INFO): Opening uart, block timeout 10ths=20 2013-05-22T14:43:10.863Z,1369233790.864 [DVL_micro](INFO): Cycling power to configure device. 2013-05-22T14:43:10.875Z,1369233790.875 [CTD_NeilBrown](INFO): Thread ID is 9946 2013-05-22T14:43:10.876Z,1369233790.876 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown. 2013-05-22T14:43:10.879Z,1369233790.879 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4 2013-05-22T14:43:10.881Z,1369233790.881 [WetLabsBB2FL](INFO): Thread ID is 9947 2013-05-22T14:43:10.881Z,1369233790.881 [WetLabsBB2FL](INFO): Powering down 2013-05-22T14:43:10.923Z,1369233790.923 [NavChartDb](INFO): Thread ID is 9948 2013-05-22T14:43:10.925Z,1369233790.925 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources 2013-05-22T14:43:10.926Z,1369233790.926 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2013-05-22T14:43:10.927Z,1369233790.927 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2013-05-22T14:43:10.927Z,1369233790.927 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2013-05-22T14:43:10.927Z,1369233790.927 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2013-05-22T14:43:10.927Z,1369233790.927 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2013-05-22T14:43:10.928Z,1369233790.928 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2013-05-22T14:43:10.928Z,1369233790.928 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2013-05-22T14:43:10.928Z,1369233790.928 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2013-05-22T14:43:12.416Z,1369233792.416 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized 2013-05-22T14:43:12.447Z,1369233792.447 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2013-05-22T14:43:12.447Z,1369233792.447 [DropWeight] Hardware Fault, FailCount= 1 2013-05-22T14:43:12.447Z,1369233792.447 [DropWeight](ERROR): Hardware Fault 2013-05-22T14:43:12.449Z,1369233792.449 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2013-05-22T14:43:12.468Z,1369233792.468 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2013-05-22T14:43:12.503Z,1369233792.503 [MissionManager](DEBUG): 2013-05-22T14:43:12.504Z,1369233792.504 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2013-05-22T14:43:12.572Z,1369233792.572 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool 2013-05-22T14:43:12.574Z,1369233792.574 [Default:GPS:A.SetSpeed](DEBUG): Construct. 2013-05-22T14:43:12.577Z,1369233792.577 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface. 2013-05-22T14:43:12.621Z,1369233792.621 [Default:Iridium:A.SetSpeed](DEBUG): Construct. 2013-05-22T14:43:12.624Z,1369233792.624 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface. 2013-05-22T14:43:12.648Z,1369233792.648 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2013-05-22T14:43:12.657Z,1369233792.657 [Default:D.SetSpeed](DEBUG): Construct. 2013-05-22T14:43:12.672Z,1369233792.672 [Default:E.GoToSurface](DEBUG): Construct GoToSurface. 2013-05-22T14:43:12.677Z,1369233792.677 [Default:F.Wait](DEBUG): Construct Wait. 2013-05-22T14:43:12.680Z,1369233792.680 [MissionManager](DEBUG): 400 400 Burn 300 Dropped drop weight due to communications timeout 5.0 1.0 5 2013-05-22T14:43:12.710Z,1369233792.710 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,NAL9602,Onboard,Radio_Freewave,DAT,Depth_Keller,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter, 2013-05-22T14:43:12.762Z,1369233792.761 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D. 2013-05-22T14:43:12.962Z,1369233792.963 [DVL_micro](INFO): Opening uart, block timeout 10ths=20 2013-05-22T14:43:12.963Z,1369233792.963 [DVL_micro](INFO): Querying output modes 2013-05-22T14:43:12.963Z,1369233792.963 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606 2013-05-22T14:43:12.964Z,1369233792.964 [Radio_Freewave](INFO): Powering up 2013-05-22T14:43:12.969Z,1369233792.969 [DAT](INFO): Powering up 2013-05-22T14:43:12.970Z,1369233792.970 [DAT](DEBUG): Initializing DAT. 2013-05-22T14:43:12.974Z,1369233792.974 [DVL_micro](DEBUG): cmdResponse: 01 2013-05-22T14:43:12.975Z,1369233792.975 [DVL_micro](INFO): NQ1 output enabled 2013-05-22T14:43:12.975Z,1369233792.975 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525 2013-05-22T14:43:12.987Z,1369233792.987 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 2013-05-22T14:43:13.000Z,1369233793.000 [DVL_micro](INFO): pause:Powering down 2013-05-22T14:43:13.255Z,1369233793.255 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2013-05-22T14:43:13.262Z,1369233793.262 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2013-05-22T14:43:13.269Z,1369233793.269 [ElevatorServo](DEBUG): Initializing EZServoServo. 2013-05-22T14:43:13.274Z,1369233793.274 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2013-05-22T14:43:13.280Z,1369233793.280 [MassServo](DEBUG): Initializing EZServoServo. 2013-05-22T14:43:13.286Z,1369233793.286 [MassServo](DEBUG): Initializing MassServo. 2013-05-22T14:43:13.308Z,1369233793.308 [RudderServo](DEBUG): Initializing EZServoServo. 2013-05-22T14:43:13.315Z,1369233793.315 [RudderServo](DEBUG): Initializing RudderServo. 2013-05-22T14:43:13.336Z,1369233793.336 [ThrusterServo](DEBUG): Initializing EZServoServo. 2013-05-22T14:43:13.342Z,1369233793.342 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2013-05-22T14:43:13.372Z,1369233793.372 [CBIT](DEBUG): Uninitialize CBIT Component. 2013-05-22T14:43:13.606Z,1369233793.606 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout 2013-05-22T14:43:13.606Z,1369233793.606 [AHRS_sp3003D](ERROR): readHeadingMagBin got 0xB6E9A0 2013-05-22T14:43:13.607Z,1369233793.607 [AHRS_sp3003D](ERROR): SP3003D failed to initialize 2013-05-22T14:43:13.607Z,1369233793.607 [AHRS_sp3003D] Hardware Fault, FailCount= 1 2013-05-22T14:43:13.607Z,1369233793.607 [AHRS_sp3003D](ERROR): Hardware Fault 2013-05-22T14:43:13.807Z,1369233793.807 [DVL_micro](INFO): Opening uart, block timeout 10ths=20 2013-05-22T14:43:13.807Z,1369233793.807 [DVL_micro](INFO): resume:Powering up 2013-05-22T14:43:13.808Z,1369233793.807 [DVL_micro](INFO): Cycling power to configure device. 2013-05-22T14:43:13.836Z,1369233793.836 [AHRS_sp3003D](INFO): Powering down 2013-05-22T14:43:14.534Z,1369233794.534 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout 2013-05-22T14:43:14.534Z,1369233794.534 [BuoyancyServo](FAULT): Buoyancy failed to initialize 2013-05-22T14:43:14.535Z,1369233794.534 [BuoyancyServo] Communications Fault, FailCount= 1 2013-05-22T14:43:14.535Z,1369233794.535 [BuoyancyServo](ERROR): Communications Fault 2013-05-22T14:43:15.046Z,1369233795.046 [ElevatorServo](ERROR): Elevator initialization uart error I:serial timeout 2013-05-22T14:43:15.047Z,1369233795.046 [ElevatorServo](FAULT): Elevator failed to initialize 2013-05-22T14:43:15.047Z,1369233795.047 [ElevatorServo] Communications Fault, FailCount= 1 2013-05-22T14:43:15.047Z,1369233795.047 [ElevatorServo](ERROR): Communications Fault 2013-05-22T14:43:15.550Z,1369233795.550 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2013-05-22T14:43:15.550Z,1369233795.550 [RudderServo](FAULT): Rudder failed to initialize 2013-05-22T14:43:15.550Z,1369233795.550 [RudderServo] Communications Fault, FailCount= 1 2013-05-22T14:43:15.550Z,1369233795.550 [RudderServo](ERROR): Communications Fault 2013-05-22T14:43:15.814Z,1369233795.815 [DVL_micro](INFO): Opening uart, block timeout 10ths=20 2013-05-22T14:43:15.815Z,1369233795.815 [DVL_micro](INFO): Querying output modes 2013-05-22T14:43:15.815Z,1369233795.815 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606 2013-05-22T14:43:16.070Z,1369233796.070 [ThrusterServo](ERROR): Thruster halt for initialization uart error serial timeout 2013-05-22T14:43:16.586Z,1369233796.586 [ThrusterServo](ERROR): Thruster initialization uart error serial timeout 2013-05-22T14:43:16.586Z,1369233796.586 [ThrusterServo](FAULT): Thruster failed to initialize 2013-05-22T14:43:16.586Z,1369233796.586 [ThrusterServo] Communications Fault, FailCount= 1 2013-05-22T14:43:16.586Z,1369233796.586 [ThrusterServo](ERROR): Communications Fault 2013-05-22T14:43:16.789Z,1369233796.789 [NAL9602](INFO): Powering up NAL9602 2013-05-22T14:43:16.847Z,1369233796.847 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2013-05-22T14:43:16.849Z,1369233796.849 [BuoyancyServo](INFO): Powering down 2013-05-22T14:43:16.931Z,1369233796.931 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2013-05-22T14:43:16.931Z,1369233796.931 [ElevatorServo](INFO): Powering down 2013-05-22T14:43:17.474Z,1369233797.474 [MassServo](FAULT): Mass shifter EEPROM initialization uart error serial timeout 2013-05-22T14:43:17.474Z,1369233797.474 [MassServo] Communications Fault, FailCount= 1 2013-05-22T14:43:17.474Z,1369233797.474 [MassServo](ERROR): Communications Fault 2013-05-22T14:43:17.475Z,1369233797.475 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2013-05-22T14:43:17.475Z,1369233797.475 [RudderServo](INFO): Powering down 2013-05-22T14:43:17.523Z,1369233797.523 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2013-05-22T14:43:17.523Z,1369233797.523 [ThrusterServo](INFO): Powering down 2013-05-22T14:43:17.822Z,1369233797.822 [DVL_micro](DEBUG): cmdResponse: 2013-05-22T14:43:17.822Z,1369233797.822 [DVL_micro](INFO): Output Modes: No Response 2013-05-22T14:43:17.823Z,1369233797.823 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525 2013-05-22T14:43:17.834Z,1369233797.834 [MassServo](DEBUG): Uninitialize Mass Servo. 2013-05-22T14:43:17.834Z,1369233797.834 [MassServo](INFO): Powering down 2013-05-22T14:43:18.045Z,1369233798.046 [ElevatorServo](DEBUG): Initializing EZServoServo. 2013-05-22T14:43:18.166Z,1369233798.166 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2013-05-22T14:43:18.168Z,1369233798.168 [RudderServo](DEBUG): Initializing EZServoServo. 2013-05-22T14:43:18.287Z,1369233798.287 [RudderServo](DEBUG): Initializing RudderServo. 2013-05-22T14:43:19.830Z,1369233799.830 [DVL_micro](DEBUG): cmdResponse: 2013-05-22T14:43:21.843Z,1369233801.843 [DVL_micro](FAULT): LCB fault: Current Limiter Activated. 2013-05-22T14:43:21.843Z,1369233801.843 [DVL_micro] Hardware Fault, FailCount= 1 2013-05-22T14:43:21.843Z,1369233801.843 [DVL_micro](ERROR): Hardware Fault 2013-05-22T14:43:21.845Z,1369233801.845 [DVL_micro](INFO): uninitialize:Powering down 2013-05-22T14:43:22.247Z,1369233802.247 [DVL_micro](FAULT): LCB fault: Current Limiter Activated. 2013-05-22T14:43:26.461Z,1369233806.461 [SBIT](IMPORTANT): Beginning Startup BIT 2013-05-22T14:43:29.242Z,1369233809.242 [NAL9602](ERROR): NAL9602 initialize uart error: serial timeout 2013-05-22T14:43:29.242Z,1369233809.242 [NAL9602] Communications Fault, FailCount= 1 2013-05-22T14:43:29.242Z,1369233809.242 [NAL9602](ERROR): Communications Fault 2013-05-22T14:43:29.801Z,1369233809.801 [NAL9602](INFO): Powering down 2013-05-22T14:43:30.083Z,1369233810.083 [NAL9602](FAULT): LCB fault: Software Overcurrent. 2013-05-22T14:43:30.084Z,1369233810.084 [NAL9602] Hardware Fault, FailCount= 1 2013-05-22T14:43:30.084Z,1369233810.084 [NAL9602](ERROR): Hardware Fault 2013-05-22T14:43:32.410Z,1369233812.410 [DAT](INFO): Init failed - response: 2013-05-22T14:43:32.410Z,1369233812.410 [DAT](FAULT): DAT failed to initialize 2013-05-22T14:43:32.410Z,1369233812.410 [DAT] Communications Fault, FailCount= 1 2013-05-22T14:43:32.410Z,1369233812.410 [DAT](ERROR): Communications Fault 2013-05-22T14:43:32.533Z,1369233812.533 [DAT](INFO): Powering down 2013-05-22T14:44:20.537Z,1369233860.537 [SBIT](IMPORTANT): SBIT PASSED 2013-05-22T14:44:20.887Z,1369233860.886 [MissionManager](IMPORTANT): Started mission Startup 2013-05-22T14:44:20.887Z,1369233860.887 [Startup] Running Loop=1 2013-05-22T14:44:20.887Z,1369233860.887 [Startup](INFO): Aggregate::initialize Startup 2013-05-22T14:44:20.887Z,1369233860.887 [Startup:A.GoToSurface] Running Loop=1 2013-05-22T14:44:20.887Z,1369233860.887 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2013-05-22T14:44:20.917Z,1369233860.917 [Startup:StartupSatComms] Running Loop=1 2013-05-22T14:44:20.917Z,1369233860.917 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms 2013-05-22T14:44:20.917Z,1369233860.917 [Startup:StartupSatComms:A] Running Loop=1 2013-05-22T14:44:21.300Z,1369233861.300 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2013-05-22T14:45:21.283Z,1369233921.283 [Startup:StartupSatComms:A](INFO): Timed out from 2013-05-22T14:44:20.9Z 2013-05-22T14:45:21.283Z,1369233921.283 [Startup:StartupSatComms:A:A_Timeout] Running Loop=1 2013-05-22T14:45:21.283Z,1369233921.283 [Startup:StartupSatComms:A:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A:A_Timeout 2013-05-22T14:45:21.283Z,1369233921.283 [Startup:StartupSatComms:A:A_Timeout](INFO): Completed Startup:StartupSatComms:A:A_Timeout 2013-05-22T14:45:21.283Z,1369233921.283 [Startup:StartupSatComms:A] Stopped 2013-05-22T14:45:21.283Z,1369233921.283 [Startup:StartupSatComms:B] Running Loop=1 2013-05-22T14:45:21.688Z,1369233921.688 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2013-05-22T14:46:21.721Z,1369233981.721 [Startup:StartupSatComms:B](INFO): Timed out from 2013-05-22T14:45:21.3Z 2013-05-22T14:46:21.721Z,1369233981.721 [Startup:StartupSatComms:B:A_Timeout] Running Loop=1 2013-05-22T14:46:21.722Z,1369233981.722 [Startup:StartupSatComms:B:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:B:A_Timeout 2013-05-22T14:46:21.722Z,1369233981.722 [Startup:StartupSatComms:B:A_Timeout](INFO): Completed Startup:StartupSatComms:B:A_Timeout 2013-05-22T14:46:21.722Z,1369233981.722 [Startup:StartupSatComms:B] Stopped 2013-05-22T14:46:21.722Z,1369233981.722 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2013-05-22T14:46:21.722Z,1369233981.722 [Startup:StartupSatComms] Stopped 2013-05-22T14:46:21.722Z,1369233981.722 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms 2013-05-22T14:46:21.723Z,1369233981.723 [Startup](INFO): Completed Startup 2013-05-22T14:46:21.723Z,1369233981.723 [Startup] Stopped 2013-05-22T14:46:21.724Z,1369233981.724 [Startup](INFO): Aggregate::uninitialize Startup 2013-05-22T14:46:21.724Z,1369233981.724 [Startup:A.GoToSurface] Stopped 2013-05-22T14:46:21.724Z,1369233981.724 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2013-05-22T14:46:22.090Z,1369233982.090 [MissionManager](IMPORTANT): Started mission Default 2013-05-22T14:46:22.090Z,1369233982.090 [Default] Running Loop=1 2013-05-22T14:46:22.105Z,1369233982.105 [Default](INFO): Aggregate::initialize Default 2013-05-22T14:46:22.105Z,1369233982.105 [Default:D.SetSpeed] Running Loop=1 2013-05-22T14:46:22.105Z,1369233982.105 [Default:D.SetSpeed](DEBUG): Initialize. 2013-05-22T14:46:22.105Z,1369233982.105 [Default:E.GoToSurface] Running Loop=1 2013-05-22T14:46:22.105Z,1369233982.105 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2013-05-22T14:46:22.105Z,1369233982.105 [Default:Iridium] Running Loop=1 2013-05-22T14:46:22.105Z,1369233982.105 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium 2013-05-22T14:46:22.106Z,1369233982.106 [Default:Iridium:A.SetSpeed] Running Loop=1 2013-05-22T14:46:22.106Z,1369233982.106 [Default:Iridium:A.SetSpeed](DEBUG): Initialize. 2013-05-22T14:46:22.106Z,1369233982.106 [Default:Iridium:B.GoToSurface] Running Loop=1 2013-05-22T14:46:22.106Z,1369233982.106 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2013-05-22T14:46:22.106Z,1369233982.106 [Default:E.GoToSurface] Running Loop=1 2013-05-22T14:46:22.112Z,1369233982.112 [Default:D.SetSpeed] Running Loop=1 2013-05-22T14:46:22.128Z,1369233982.128 [Default:CallIridium] Running Loop=1 2013-05-22T14:46:22.129Z,1369233982.129 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium 2013-05-22T14:46:22.129Z,1369233982.129 [Default:CallIridium:A] Running Loop=1 2013-05-22T14:46:22.131Z,1369233982.131 [Default:CallIridium:A] Stopped 2013-05-22T14:46:22.131Z,1369233982.131 [Default:CallIridium:B] Running Loop=1 2013-05-22T14:46:22.131Z,1369233982.131 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B 2013-05-22T14:46:22.136Z,1369233982.136 [Default:Iridium:B.GoToSurface] Stopped 2013-05-22T14:46:22.136Z,1369233982.136 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2013-05-22T14:46:22.136Z,1369233982.136 [Default:Iridium:Read_Iridium] Running Loop=1 2013-05-22T14:46:22.137Z,1369233982.136 [Default:Iridium:A.SetSpeed] Running Loop=1 2013-05-22T14:46:22.153Z,1369233982.153 [Default:GPS] Running Loop=1 2013-05-22T14:46:22.153Z,1369233982.153 [Default:GPS](INFO): Aggregate::initialize Default:GPS 2013-05-22T14:46:22.153Z,1369233982.153 [Default:GPS:A.SetSpeed] Running Loop=1 2013-05-22T14:46:22.154Z,1369233982.154 [Default:GPS:A.SetSpeed](DEBUG): Initialize. 2013-05-22T14:46:22.154Z,1369233982.154 [Default:GPS:B.GoToSurface] Running Loop=1 2013-05-22T14:46:22.154Z,1369233982.154 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2013-05-22T14:46:22.167Z,1369233982.167 [Default:GPS:B.GoToSurface] Stopped 2013-05-22T14:46:22.167Z,1369233982.167 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2013-05-22T14:46:22.167Z,1369233982.167 [Default:GPS:Read_GPS] Running Loop=1 2013-05-22T14:46:22.168Z,1369233982.168 [Default:GPS:A.SetSpeed] Running Loop=1 2013-05-22T14:46:22.512Z,1369233982.513 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2013-05-22T14:46:22.519Z,1369233982.519 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix