2013-09-16T04:38:27.341Z,1379306307.341 [Supervisor](DEBUG): Initializing supervisor.
2013-09-16T04:38:27.343Z,1379306307.343 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2013-09-16T04:38:27.344Z,1379306307.344 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2013-09-16T04:38:27.345Z,1379306307.345 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2013-09-16T04:38:27.348Z,1379306307.348 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2013-09-16T04:38:27.358Z,1379306307.358 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2013-09-16T04:38:27.359Z,1379306307.359 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2013-09-16T04:38:27.360Z,1379306307.360 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2013-09-16T04:38:27.361Z,1379306307.361 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0
2013-09-16T04:38:27.362Z,1379306307.362 [Supervisor](INFO): Looking for Config files in directory: Config/
2013-09-16T04:38:27.363Z,1379306307.363 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2013-09-16T04:38:27.644Z,1379306307.644 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2013-09-16T04:38:27.645Z,1379306307.645 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2013-09-16T04:38:27.837Z,1379306307.837 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2013-09-16T04:38:27.838Z,1379306307.838 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2013-09-16T04:38:27.923Z,1379306307.923 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2013-09-16T04:38:27.924Z,1379306307.924 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2013-09-16T04:38:28.035Z,1379306308.035 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2013-09-16T04:38:28.035Z,1379306308.035 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2013-09-16T04:38:28.178Z,1379306308.178 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2013-09-16T04:38:28.179Z,1379306308.179 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2013-09-16T04:38:28.417Z,1379306308.417 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2013-09-16T04:38:28.418Z,1379306308.418 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2013-09-16T04:38:28.582Z,1379306308.582 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2013-09-16T04:38:28.583Z,1379306308.583 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2013-09-16T04:38:28.849Z,1379306308.849 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2013-09-16T04:38:28.849Z,1379306308.849 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2013-09-16T04:38:28.959Z,1379306308.959 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2013-09-16T04:38:28.959Z,1379306308.959 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2013-09-16T04:38:29.372Z,1379306309.372 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2013-09-16T04:38:29.373Z,1379306309.373 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2013-09-16T04:38:29.484Z,1379306309.484 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2013-09-16T04:38:29.485Z,1379306309.485 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2013-09-16T04:38:29.571Z,1379306309.571 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2013-09-16T04:38:29.572Z,1379306309.572 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2013-09-16T04:38:29.670Z,1379306309.670 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2013-09-16T04:38:29.796Z,1379306309.796 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2013-09-16T04:38:29.891Z,1379306309.891 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2013-09-16T04:38:29.995Z,1379306309.995 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2013-09-16T04:38:30.141Z,1379306310.141 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2013-09-16T04:38:30.149Z,1379306310.149 [Config/Science](ERROR): Could not parse value:
2013-09-16T04:38:30.267Z,1379306310.267 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2013-09-16T04:38:30.363Z,1379306310.363 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2013-09-16T04:38:30.448Z,1379306310.448 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/LOGIN/
2013-09-16T04:38:30.449Z,1379306310.449 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2013-09-16T04:38:30.453Z,1379306310.453 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2013-09-16T04:38:30.612Z,1379306310.612 [InternalSim] Loaded
2013-09-16T04:38:30.612Z,1379306310.612 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2013-09-16T04:38:30.613Z,1379306310.613 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2013-09-16T04:38:30.613Z,1379306310.613 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2013-09-16T04:38:30.697Z,1379306310.697 [SBIT](DEBUG): Construct Startup Built In Test.
2013-09-16T04:38:30.725Z,1379306310.725 [SBIT] Loaded
2013-09-16T04:38:30.725Z,1379306310.725 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2013-09-16T04:38:30.726Z,1379306310.726 [IBIT](DEBUG): Construct Initiated Built In Test.
2013-09-16T04:38:30.755Z,1379306310.755 [IBIT] Loaded
2013-09-16T04:38:30.755Z,1379306310.755 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2013-09-16T04:38:30.757Z,1379306310.757 [CBIT](DEBUG): Construct CBIT Built In Test.
2013-09-16T04:38:30.870Z,1379306310.870 [CBIT] Loaded
2013-09-16T04:38:30.871Z,1379306310.871 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2013-09-16T04:38:30.871Z,1379306310.871 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2013-09-16T04:38:30.872Z,1379306310.872 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2013-09-16T04:38:31.036Z,1379306311.036 [BuoyancyServo] Loaded
2013-09-16T04:38:31.036Z,1379306311.036 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2013-09-16T04:38:31.048Z,1379306311.048 [ElevatorServo] Loaded
2013-09-16T04:38:31.048Z,1379306311.048 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2013-09-16T04:38:31.059Z,1379306311.059 [MassServo] Loaded
2013-09-16T04:38:31.059Z,1379306311.059 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2013-09-16T04:38:31.071Z,1379306311.071 [RudderServo] Loaded
2013-09-16T04:38:31.071Z,1379306311.071 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2013-09-16T04:38:31.082Z,1379306311.082 [ThrusterServo] Loaded
2013-09-16T04:38:31.082Z,1379306311.082 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2013-09-16T04:38:31.083Z,1379306311.083 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2013-09-16T04:38:31.083Z,1379306311.083 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2013-09-16T04:38:31.117Z,1379306311.117 [DepthRateCalculator] Loaded
2013-09-16T04:38:31.118Z,1379306311.118 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2013-09-16T04:38:34.200Z,1379306314.200 [HFRadarModelCalc] Loaded
2013-09-16T04:38:34.200Z,1379306314.200 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2013-09-16T04:38:34.216Z,1379306314.216 [NavChart] Loaded
2013-09-16T04:38:34.216Z,1379306314.216 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2013-09-16T04:38:34.222Z,1379306314.222 [PitchRateCalculator] Loaded
2013-09-16T04:38:34.222Z,1379306314.222 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2013-09-16T04:38:34.232Z,1379306314.232 [SpeedCalculator] Loaded
2013-09-16T04:38:34.233Z,1379306314.233 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2013-09-16T04:38:34.249Z,1379306314.249 [TempGradientCalculator] Loaded
2013-09-16T04:38:34.249Z,1379306314.249 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2013-09-16T04:38:34.254Z,1379306314.254 [YawRateCalculator] Loaded
2013-09-16T04:38:34.255Z,1379306314.255 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2013-09-16T04:38:34.300Z,1379306314.300 [Navigation] Loaded
2013-09-16T04:38:34.301Z,1379306314.301 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2013-09-16T04:38:34.301Z,1379306314.301 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2013-09-16T04:38:34.302Z,1379306314.302 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2013-09-16T04:38:34.535Z,1379306314.535 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2013-09-16T04:38:34.536Z,1379306314.536 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2013-09-16T04:38:34.558Z,1379306314.558 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2013-09-16T04:38:34.559Z,1379306314.559 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2013-09-16T04:38:34.605Z,1379306314.605 [VerticalControl](DEBUG): Construct VerticalControl.
2013-09-16T04:38:34.698Z,1379306314.698 [VerticalControl] Loaded
2013-09-16T04:38:34.698Z,1379306314.698 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2013-09-16T04:38:34.699Z,1379306314.699 [HorizontalControl](DEBUG): Construct HorizontalControl.
2013-09-16T04:38:34.756Z,1379306314.756 [HorizontalControl] Loaded
2013-09-16T04:38:34.756Z,1379306314.756 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2013-09-16T04:38:34.756Z,1379306314.756 [SpeedControl](DEBUG): Construct SpeedControl.
2013-09-16T04:38:34.758Z,1379306314.758 [SpeedControl] Loaded
2013-09-16T04:38:34.758Z,1379306314.758 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2013-09-16T04:38:34.759Z,1379306314.759 [LoopControl](DEBUG): Construct LoopControl.
2013-09-16T04:38:34.760Z,1379306314.760 [LoopControl] Loaded
2013-09-16T04:38:34.760Z,1379306314.760 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2013-09-16T04:38:34.760Z,1379306314.760 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2013-09-16T04:38:34.761Z,1379306314.761 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2013-09-16T04:38:34.767Z,1379306314.767 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2013-09-16T04:38:34.771Z,1379306314.771 [AsyncPiEstimator] Loaded
2013-09-16T04:38:34.772Z,1379306314.772 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2013-09-16T04:38:34.773Z,1379306314.773 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406474E0
2013-09-16T04:38:34.774Z,1379306314.774 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2013-09-16T04:38:34.774Z,1379306314.774 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2013-09-16T04:38:34.963Z,1379306314.963 [AHRS_sp3003D] Loaded
2013-09-16T04:38:34.964Z,1379306314.964 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2013-09-16T04:38:34.977Z,1379306314.977 [Depth_Keller] Loaded
2013-09-16T04:38:34.978Z,1379306314.978 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2013-09-16T04:38:35.156Z,1379306315.156 [DVL_micro] Loaded
2013-09-16T04:38:35.157Z,1379306315.157 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2013-09-16T04:38:35.158Z,1379306315.158 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 406CE4E0
2013-09-16T04:38:35.245Z,1379306315.245 [NAL9602] Loaded
2013-09-16T04:38:35.245Z,1379306315.245 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2013-09-16T04:38:35.287Z,1379306315.287 [Onboard] Loaded
2013-09-16T04:38:35.288Z,1379306315.288 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2013-09-16T04:38:35.294Z,1379306315.294 [Radio_Freewave] Loaded
2013-09-16T04:38:35.294Z,1379306315.294 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2013-09-16T04:38:35.432Z,1379306315.432 [DAT] Loaded
2013-09-16T04:38:35.433Z,1379306315.433 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2013-09-16T04:38:35.433Z,1379306315.433 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2013-09-16T04:38:35.434Z,1379306315.434 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2013-09-16T04:38:35.530Z,1379306315.530 [CTD_NeilBrown] Loaded
2013-09-16T04:38:35.530Z,1379306315.530 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2013-09-16T04:38:35.532Z,1379306315.532 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4072B4E0
2013-09-16T04:38:35.546Z,1379306315.546 [PAR_Licor] Loaded
2013-09-16T04:38:35.547Z,1379306315.547 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2013-09-16T04:38:35.578Z,1379306315.578 [WetLabsBB2FL] Loaded
2013-09-16T04:38:35.578Z,1379306315.578 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2013-09-16T04:38:35.579Z,1379306315.579 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4075B4E0
2013-09-16T04:38:35.580Z,1379306315.580 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2013-09-16T04:38:35.582Z,1379306315.582 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2013-09-16T04:38:35.583Z,1379306315.583 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2013-09-16T04:38:35.590Z,1379306315.590 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2013-09-16T04:38:35.591Z,1379306315.591 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 4078B4E0
2013-09-16T04:38:35.595Z,1379306315.595 [Supervisor](DEBUG): Running supervisor.
2013-09-16T04:38:35.596Z,1379306315.596 [CommandLine](INFO): Thread ID is 2513
2013-09-16T04:38:35.598Z,1379306315.598 [controlThread](INFO): Thread ID is 2512
2013-09-16T04:38:35.599Z,1379306315.599 [controlThread](DEBUG): Initializing ControlThread
2013-09-16T04:38:35.599Z,1379306315.599 [CycleStarter](INFO): Thread ID is 2511
2013-09-16T04:38:35.600Z,1379306315.600 [InternalSim](DEBUG): InternalSim initializing...
2013-09-16T04:38:35.635Z,1379306315.635 [logger](INFO): Thread ID is 2514
2013-09-16T04:38:35.659Z,1379306315.659 [SBIT](INFO): Initialize SBIT Component.
2013-09-16T04:38:35.660Z,1379306315.660 [SBIT](IMPORTANT): Tethys CM Info:
$Rev:10634
2013-09-16T04:38:35.660Z,1379306315.660 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2013-09-16T04:38:35.660Z,1379306315.660 [SBIT](IMPORTANT): Kernel Version:#634 PREEMPT Wed Feb 13 10:21:48 PST 2013
2013-09-16T04:38:35.661Z,1379306315.661 [IBIT](INFO): Initialize IBIT Component.
2013-09-16T04:38:35.662Z,1379306315.662 [CBIT](DEBUG): Initialize CBIT Component.
2013-09-16T04:38:35.662Z,1379306315.662 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2013-09-16T04:38:35.675Z,1379306315.675 [AsyncPiEstimator](INFO): Thread ID is 2575
2013-09-16T04:38:35.675Z,1379306315.675 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2013-09-16T04:38:35.687Z,1379306315.687 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-09-16T04:38:35.688Z,1379306315.688 [NavChart](DEBUG): Initialize NavChart Derivation.
2013-09-16T04:38:35.688Z,1379306315.688 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2013-09-16T04:38:35.689Z,1379306315.689 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2013-09-16T04:38:35.689Z,1379306315.689 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2013-09-16T04:38:35.689Z,1379306315.689 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2013-09-16T04:38:35.690Z,1379306315.690 [Navigation](DEBUG): Initializing Navigation.
2013-09-16T04:38:35.690Z,1379306315.690 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2013-09-16T04:38:35.692Z,1379306315.692 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2013-09-16T04:38:35.693Z,1379306315.693 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2013-09-16T04:38:35.693Z,1379306315.693 [LoopControl](DEBUG): Initialize LoopControlComponent.
2013-09-16T04:38:35.705Z,1379306315.705 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2013-09-16T04:38:35.707Z,1379306315.707 [DVL_micro](INFO): Thread ID is 2576
2013-09-16T04:38:35.716Z,1379306315.716 [DVL_micro](INFO): Initializing
2013-09-16T04:38:35.716Z,1379306315.716 [DVL_micro](INFO): start:Powering up
2013-09-16T04:38:35.717Z,1379306315.717 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T04:38:35.717Z,1379306315.717 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T04:38:35.736Z,1379306315.736 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2013-09-16T04:38:35.740Z,1379306315.740 [CTD_NeilBrown](INFO): Thread ID is 2577
2013-09-16T04:38:35.740Z,1379306315.740 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2013-09-16T04:38:35.775Z,1379306315.775 [WetLabsBB2FL](INFO): Thread ID is 2578
2013-09-16T04:38:35.776Z,1379306315.776 [WetLabsBB2FL](INFO): Powering down
2013-09-16T04:38:35.804Z,1379306315.804 [MissionManager](DEBUG):
2013-09-16T04:38:35.805Z,1379306315.805 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2013-09-16T04:38:35.810Z,1379306315.810 [NavChartDb](INFO): Thread ID is 2579
2013-09-16T04:38:35.812Z,1379306315.812 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2013-09-16T04:38:35.813Z,1379306315.813 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2013-09-16T04:38:35.813Z,1379306315.813 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2013-09-16T04:38:35.814Z,1379306315.814 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2013-09-16T04:38:35.814Z,1379306315.814 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2013-09-16T04:38:35.814Z,1379306315.814 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2013-09-16T04:38:35.815Z,1379306315.815 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2013-09-16T04:38:35.815Z,1379306315.815 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2013-09-16T04:38:35.815Z,1379306315.815 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2013-09-16T04:38:35.894Z,1379306315.894 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2013-09-16T04:38:35.908Z,1379306315.908 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2013-09-16T04:38:35.911Z,1379306315.911 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-09-16T04:38:35.931Z,1379306315.931 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2013-09-16T04:38:35.934Z,1379306315.934 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-09-16T04:38:35.973Z,1379306315.973 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2013-09-16T04:38:35.998Z,1379306315.998 [Default:D.SetSpeed](DEBUG): Construct.
2013-09-16T04:38:36.001Z,1379306316.001 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2013-09-16T04:38:36.016Z,1379306316.016 [Default:F.Wait](DEBUG): Construct Wait.
2013-09-16T04:38:36.032Z,1379306316.032 [MissionManager](DEBUG):
400
400
Burn 300
Dropped drop weight due to communications timeout
5.0
1.0
5
2013-09-16T04:38:36.036Z,1379306316.036 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Depth_Keller,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-09-16T04:38:36.109Z,1379306316.109 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-09-16T04:38:36.159Z,1379306316.159 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.000000 psu
2013-09-16T04:38:36.267Z,1379306316.267 [Radio_Freewave](INFO): Powering up
2013-09-16T04:38:36.276Z,1379306316.276 [DAT](INFO): Powering up
2013-09-16T04:38:36.277Z,1379306316.277 [DAT](DEBUG): Initializing DAT.
2013-09-16T04:38:36.596Z,1379306316.596 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-09-16T04:38:36.600Z,1379306316.600 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-09-16T04:38:36.607Z,1379306316.607 [ElevatorServo](DEBUG): Initializing EZServoServo.
2013-09-16T04:38:36.608Z,1379306316.608 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2013-09-16T04:38:36.658Z,1379306316.658 [MassServo](DEBUG): Initializing EZServoServo.
2013-09-16T04:38:36.664Z,1379306316.664 [MassServo](DEBUG): Initializing MassServo.
2013-09-16T04:38:36.670Z,1379306316.670 [RudderServo](DEBUG): Initializing EZServoServo.
2013-09-16T04:38:36.678Z,1379306316.678 [RudderServo](DEBUG): Initializing RudderServo.
2013-09-16T04:38:36.684Z,1379306316.684 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-09-16T04:38:36.688Z,1379306316.688 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-09-16T04:38:37.814Z,1379306317.814 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T04:38:37.814Z,1379306317.814 [DVL_micro](INFO): Querying output modes
2013-09-16T04:38:37.814Z,1379306317.814 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606
2013-09-16T04:38:37.826Z,1379306317.826 [DVL_micro](DEBUG): cmdResponse: 01 16
2013-09-16T04:38:37.826Z,1379306317.826 [DVL_micro](INFO): NQ1 output enabled
2013-09-16T04:38:37.826Z,1379306317.826 [DVL_micro](INFO): RSSI output enabled
2013-09-16T04:38:37.826Z,1379306317.826 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525
2013-09-16T04:38:37.838Z,1379306317.838 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON
2013-09-16T04:38:37.853Z,1379306317.853 [DVL_micro](INFO): pause:Powering down
2013-09-16T04:38:40.467Z,1379306320.467 [NAL9602](INFO): Powering up NAL9602
2013-09-16T04:38:44.131Z,1379306324.131 [BuoyancyServo](ERROR): getPosition uart error serial timeout
2013-09-16T04:38:44.131Z,1379306324.131 [BuoyancyServo](FAULT): Buoyancy getPosition uart error.serial timeout
2013-09-16T04:38:44.131Z,1379306324.131 [BuoyancyServo] Communications Fault, FailCount= 1
2013-09-16T04:38:44.132Z,1379306324.132 [BuoyancyServo](ERROR): Communications Fault
2013-09-16T04:38:44.136Z,1379306324.136 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2013-09-16T04:38:44.421Z,1379306324.421 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-09-16T04:38:44.422Z,1379306324.422 [BuoyancyServo](INFO): Powering down
2013-09-16T04:38:45.974Z,1379306325.974 [BuoyancyServo](FAULT): LCB fault: Current Limiter Activated.
2013-09-16T04:38:45.974Z,1379306325.974 [BuoyancyServo] Hardware Fault, FailCount= 1
2013-09-16T04:38:45.975Z,1379306325.974 [BuoyancyServo](ERROR): Hardware Fault
2013-09-16T04:38:46.465Z,1379306326.465 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2013-09-16T04:38:46.465Z,1379306326.465 [BuoyancyServo] No Fault, FailCount= 1
2013-09-16T04:38:46.794Z,1379306326.794 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-09-16T04:38:46.908Z,1379306326.908 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-09-16T04:38:51.155Z,1379306331.155 [NAL9602](INFO): NAL9602 initialized
2013-09-16T04:38:51.229Z,1379306331.229 [SBIT](IMPORTANT): Beginning Startup BIT
2013-09-16T04:38:51.232Z,1379306331.232 [CBIT](IMPORTANT): Beginning GF scan
2013-09-16T04:38:54.591Z,1379306334.591 [BuoyancyServo](ERROR): getPosition uart error serial timeout
2013-09-16T04:38:54.592Z,1379306334.592 [BuoyancyServo](FAULT): Buoyancy getPosition uart error.serial timeout
2013-09-16T04:38:54.592Z,1379306334.592 [BuoyancyServo] Communications Fault, FailCount= 2
2013-09-16T04:38:54.592Z,1379306334.592 [BuoyancyServo](ERROR): Communications Fault
2013-09-16T04:38:54.732Z,1379306334.732 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2013-09-16T04:38:54.994Z,1379306334.994 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-09-16T04:38:54.995Z,1379306334.995 [BuoyancyServo](INFO): Powering down
2013-09-16T04:38:56.409Z,1379306336.409 [DAT](INFO): Powering down
2013-09-16T04:38:56.622Z,1379306336.622 [BuoyancyServo](FAULT): LCB fault: Current Limiter Activated.
2013-09-16T04:38:56.622Z,1379306336.622 [BuoyancyServo] Hardware Fault, FailCount= 2
2013-09-16T04:38:56.622Z,1379306336.622 [BuoyancyServo](ERROR): Hardware Fault
2013-09-16T04:38:56.995Z,1379306336.995 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2013-09-16T04:38:56.995Z,1379306336.995 [BuoyancyServo] No Fault, FailCount= 2
2013-09-16T04:38:57.370Z,1379306337.370 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-09-16T04:38:57.489Z,1379306337.489 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-09-16T04:39:04.695Z,1379306344.695 [BuoyancyServo](ERROR): getPosition uart error serial timeout
2013-09-16T04:39:04.695Z,1379306344.695 [BuoyancyServo](FAULT): Buoyancy getPosition uart error.serial timeout
2013-09-16T04:39:04.695Z,1379306344.695 [BuoyancyServo] Communications Fault, FailCount= 3
2013-09-16T04:39:04.695Z,1379306344.695 [BuoyancyServo](ERROR): Communications Fault
2013-09-16T04:39:04.701Z,1379306344.701 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2013-09-16T04:39:04.971Z,1379306344.971 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-09-16T04:39:04.983Z,1379306344.983 [BuoyancyServo](INFO): Powering down
2013-09-16T04:39:06.529Z,1379306346.529 [BuoyancyServo](FAULT): LCB fault: Current Limiter Activated.
2013-09-16T04:39:06.529Z,1379306346.529 [BuoyancyServo] Hardware Fault, FailCount= 3
2013-09-16T04:39:06.529Z,1379306346.529 [BuoyancyServo](ERROR): Hardware Fault
2013-09-16T04:39:07.584Z,1379306347.584 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2013-09-16T04:39:07.584Z,1379306347.584 [BuoyancyServo] No Fault, FailCount= 3
2013-09-16T04:39:07.875Z,1379306347.875 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-09-16T04:39:07.993Z,1379306347.993 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-09-16T04:39:15.327Z,1379306355.327 [BuoyancyServo](ERROR): getPosition uart error serial timeout
2013-09-16T04:39:15.328Z,1379306355.328 [BuoyancyServo](FAULT): Buoyancy getPosition uart error.serial timeout
2013-09-16T04:39:15.328Z,1379306355.328 [BuoyancyServo] Communications Fault, FailCount= 4
2013-09-16T04:39:15.328Z,1379306355.328 [BuoyancyServo](ERROR): Communications Fault
2013-09-16T04:39:15.380Z,1379306355.380 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2013-09-16T04:39:15.590Z,1379306355.590 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-09-16T04:39:15.591Z,1379306355.591 [BuoyancyServo](INFO): Powering down
2013-09-16T04:39:17.207Z,1379306357.207 [BuoyancyServo](FAULT): LCB fault: Current Limiter Activated.
2013-09-16T04:39:17.207Z,1379306357.207 [BuoyancyServo] Hardware Fault, FailCount= 4
2013-09-16T04:39:17.208Z,1379306357.208 [BuoyancyServo](ERROR): Hardware Fault
2013-09-16T04:39:17.627Z,1379306357.627 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2013-09-16T04:39:17.627Z,1379306357.627 [BuoyancyServo] No Fault, FailCount= 4
2013-09-16T04:39:17.981Z,1379306357.981 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-09-16T04:39:18.097Z,1379306358.097 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-09-16T04:39:18.145Z,1379306358.145 [CBIT](IMPORTANT): No ground fault detected
2013-09-16T04:39:25.291Z,1379306365.291 [BuoyancyServo](ERROR): getPosition uart error serial timeout
2013-09-16T04:39:25.291Z,1379306365.291 [BuoyancyServo](FAULT): Buoyancy getPosition uart error.serial timeout
2013-09-16T04:39:25.291Z,1379306365.291 [BuoyancyServo] Communications Fault, FailCount= 5
2013-09-16T04:39:25.291Z,1379306365.291 [BuoyancyServo](ERROR): Communications Fault
2013-09-16T04:39:25.296Z,1379306365.296 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2013-09-16T04:39:25.296Z,1379306365.296 [CBIT](CRITICAL): Communications Fault in component: BuoyancyServo
2013-09-16T04:39:25.516Z,1379306365.516 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-09-16T04:39:25.517Z,1379306365.517 [BuoyancyServo](INFO): Powering down
2013-09-16T04:39:25.555Z,1379306365.555 [CommandLine](FAULT): Scheduling is paused
2013-09-16T04:39:27.102Z,1379306367.102 [BuoyancyServo](FAULT): LCB fault: Current Limiter Activated.
2013-09-16T04:39:27.102Z,1379306367.102 [BuoyancyServo] Hardware Fault, FailCount= 5
2013-09-16T04:39:27.102Z,1379306367.102 [BuoyancyServo](ERROR): Hardware Fault
2013-09-16T04:39:43.295Z,1379306383.295 [CommandLine](IMPORTANT): got command quit
2013-09-16T04:39:44.384Z,1379306384.384 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye!
2013-09-16T04:39:44.385Z,1379306384.385 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2013-09-16T04:39:44.489Z,1379306384.489 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2013-09-16T04:39:44.862Z,1379306384.862 [WetLabsBB2FL](INFO): Powering down
2013-09-16T04:39:44.881Z,1379306384.881 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2013-09-16T04:39:45.170Z,1379306385.170 [ComponentRegistry](INFO): Shutting down DVL_micro ThreadHandler
2013-09-16T04:39:45.256Z,1379306385.256 [SBIT](IMPORTANT): SBIT PASSED
2013-09-16T04:39:45.370Z,1379306385.370 [DVL_micro](INFO): uninitialize:Powering down
2013-09-16T04:39:45.378Z,1379306385.378 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2013-09-16T04:39:45.651Z,1379306385.651 [MissionManager](IMPORTANT): Started mission Startup
2013-09-16T04:39:45.651Z,1379306385.651 [Startup] Running Loop=1
2013-09-16T04:39:45.652Z,1379306385.652 [Startup](INFO): Aggregate::initialize Startup
2013-09-16T04:39:45.652Z,1379306385.652 [Startup:A.GoToSurface] Running Loop=1
2013-09-16T04:39:45.652Z,1379306385.652 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-09-16T04:39:45.658Z,1379306385.658 [Startup:StartupSatComms] Running Loop=1
2013-09-16T04:39:45.658Z,1379306385.658 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2013-09-16T04:39:45.658Z,1379306385.658 [Startup:StartupSatComms:A] Running Loop=1
2013-09-16T04:39:45.679Z,1379306385.679 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2013-09-16T04:39:45.699Z,1379306385.699 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2013-09-16T04:39:45.743Z,1379306385.743 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2013-09-16T04:39:45.745Z,1379306385.745 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2013-09-16T04:39:45.859Z,1379306385.859 [controlThread](DEBUG): Uninitializing ControlThread
2013-09-16T04:39:45.860Z,1379306385.860 [AHRS_sp3003D](INFO): Powering down
2013-09-16T04:39:45.947Z,1379306385.947 [NAL9602](INFO): Powering down
2013-09-16T04:39:45.949Z,1379306385.949 [DAT](INFO): Powering down
2013-09-16T04:39:45.950Z,1379306385.950 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-09-16T04:39:45.951Z,1379306385.951 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2013-09-16T04:39:45.955Z,1379306385.955 [Startup] Stopped
2013-09-16T04:39:45.955Z,1379306385.955 [Startup](INFO): Aggregate::uninitialize Startup
2013-09-16T04:39:45.955Z,1379306385.955 [Startup:A.GoToSurface] Stopped
2013-09-16T04:39:45.955Z,1379306385.955 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-09-16T04:39:45.956Z,1379306385.956 [Startup:StartupSatComms] Stopped
2013-09-16T04:39:45.956Z,1379306385.956 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2013-09-16T04:39:45.956Z,1379306385.956 [Startup:StartupSatComms:A] Stopped
2013-09-16T04:39:45.957Z,1379306385.957 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2013-09-16T04:39:45.957Z,1379306385.957 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2013-09-16T04:39:45.958Z,1379306385.958 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2013-09-16T04:39:45.958Z,1379306385.958 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2013-09-16T04:39:45.958Z,1379306385.958 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-09-16T04:39:45.959Z,1379306385.959 [BuoyancyServo](INFO): Powering down
2013-09-16T04:39:45.975Z,1379306385.975 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2013-09-16T04:39:45.975Z,1379306385.975 [ElevatorServo](INFO): Powering down
2013-09-16T04:39:45.976Z,1379306385.976 [MassServo](DEBUG): Uninitialize Mass Servo.
2013-09-16T04:39:45.976Z,1379306385.976 [MassServo](INFO): Powering down
2013-09-16T04:39:45.977Z,1379306385.977 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2013-09-16T04:39:45.977Z,1379306385.977 [RudderServo](INFO): Powering down
2013-09-16T04:39:45.978Z,1379306385.978 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2013-09-16T04:39:45.978Z,1379306385.978 [ThrusterServo](INFO): Powering down
2013-09-16T04:39:45.979Z,1379306385.979 [SBIT](DEBUG): Uninitialize SBIT Component.
2013-09-16T04:39:45.979Z,1379306385.979 [IBIT](DEBUG): Uninitialize IBIT Component.
2013-09-16T04:39:45.980Z,1379306385.980 [CBIT](DEBUG): Uninitialize CBIT Component.