2013-10-30T19:21:19.754Z,1383160879.754 [Supervisor](DEBUG): Initializing supervisor.
2013-10-30T19:21:19.757Z,1383160879.757 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2013-10-30T19:21:19.757Z,1383160879.757 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2013-10-30T19:21:19.758Z,1383160879.758 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2013-10-30T19:21:19.762Z,1383160879.762 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2013-10-30T19:21:19.773Z,1383160879.773 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2013-10-30T19:21:19.774Z,1383160879.774 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2013-10-30T19:21:19.807Z,1383160879.807 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2013-10-30T19:21:19.817Z,1383160879.817 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0
2013-10-30T19:21:19.818Z,1383160879.818 [Supervisor](INFO): Looking for Config files in directory: Config/
2013-10-30T19:21:19.819Z,1383160879.819 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2013-10-30T19:21:20.189Z,1383160880.189 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2013-10-30T19:21:20.190Z,1383160880.190 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2013-10-30T19:21:20.465Z,1383160880.465 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2013-10-30T19:21:20.466Z,1383160880.466 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2013-10-30T19:21:20.579Z,1383160880.579 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2013-10-30T19:21:20.579Z,1383160880.579 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2013-10-30T19:21:20.718Z,1383160880.718 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2013-10-30T19:21:20.718Z,1383160880.718 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2013-10-30T19:21:20.933Z,1383160880.933 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2013-10-30T19:21:20.933Z,1383160880.933 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2013-10-30T19:21:21.261Z,1383160881.261 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2013-10-30T19:21:21.262Z,1383160881.262 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2013-10-30T19:21:21.479Z,1383160881.478 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2013-10-30T19:21:21.479Z,1383160881.479 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2013-10-30T19:21:21.832Z,1383160881.832 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2013-10-30T19:21:21.833Z,1383160881.833 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2013-10-30T19:21:21.975Z,1383160881.975 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2013-10-30T19:21:21.975Z,1383160881.975 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2013-10-30T19:21:22.523Z,1383160882.523 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2013-10-30T19:21:22.524Z,1383160882.524 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2013-10-30T19:21:22.677Z,1383160882.677 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2013-10-30T19:21:22.678Z,1383160882.678 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2013-10-30T19:21:22.804Z,1383160882.804 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2013-10-30T19:21:22.805Z,1383160882.805 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2013-10-30T19:21:22.945Z,1383160882.945 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2013-10-30T19:21:23.111Z,1383160883.111 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2013-10-30T19:21:23.247Z,1383160883.247 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2013-10-30T19:21:23.392Z,1383160883.392 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2013-10-30T19:21:23.529Z,1383160883.529 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2013-10-30T19:21:23.686Z,1383160883.686 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2013-10-30T19:21:23.781Z,1383160883.781 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2013-10-30T19:21:23.908Z,1383160883.908 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/LOGIN/
2013-10-30T19:21:23.908Z,1383160883.908 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2013-10-30T19:21:23.910Z,1383160883.910 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2013-10-30T19:21:24.116Z,1383160884.116 [InternalSim] Loaded
2013-10-30T19:21:24.117Z,1383160884.117 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2013-10-30T19:21:24.117Z,1383160884.117 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2013-10-30T19:21:24.118Z,1383160884.118 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2013-10-30T19:21:24.245Z,1383160884.245 [SBIT](DEBUG): Construct Startup Built In Test.
2013-10-30T19:21:24.275Z,1383160884.275 [SBIT] Loaded
2013-10-30T19:21:24.275Z,1383160884.275 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2013-10-30T19:21:24.276Z,1383160884.276 [IBIT](DEBUG): Construct Initiated Built In Test.
2013-10-30T19:21:24.328Z,1383160884.328 [IBIT] Loaded
2013-10-30T19:21:24.328Z,1383160884.328 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2013-10-30T19:21:24.339Z,1383160884.339 [CBIT](DEBUG): Construct CBIT Built In Test.
2013-10-30T19:21:24.497Z,1383160884.497 [CBIT] Loaded
2013-10-30T19:21:24.498Z,1383160884.498 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2013-10-30T19:21:24.498Z,1383160884.498 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2013-10-30T19:21:24.499Z,1383160884.499 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2013-10-30T19:21:24.684Z,1383160884.684 [BuoyancyServo] Loaded
2013-10-30T19:21:24.685Z,1383160884.685 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2013-10-30T19:21:24.697Z,1383160884.697 [ElevatorServo] Loaded
2013-10-30T19:21:24.697Z,1383160884.697 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2013-10-30T19:21:24.708Z,1383160884.708 [MassServo] Loaded
2013-10-30T19:21:24.709Z,1383160884.709 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2013-10-30T19:21:24.720Z,1383160884.720 [RudderServo] Loaded
2013-10-30T19:21:24.721Z,1383160884.721 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2013-10-30T19:21:24.732Z,1383160884.732 [ThrusterServo] Loaded
2013-10-30T19:21:24.732Z,1383160884.732 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2013-10-30T19:21:24.732Z,1383160884.732 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2013-10-30T19:21:24.733Z,1383160884.733 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2013-10-30T19:21:24.798Z,1383160884.798 [DepthRateCalculator] Loaded
2013-10-30T19:21:24.809Z,1383160884.809 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2013-10-30T19:21:28.153Z,1383160888.153 [HFRadarModelCalc] Loaded
2013-10-30T19:21:28.154Z,1383160888.154 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2013-10-30T19:21:28.170Z,1383160888.170 [NavChart] Loaded
2013-10-30T19:21:28.170Z,1383160888.170 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2013-10-30T19:21:28.176Z,1383160888.176 [PitchRateCalculator] Loaded
2013-10-30T19:21:28.176Z,1383160888.176 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2013-10-30T19:21:28.187Z,1383160888.187 [SpeedCalculator] Loaded
2013-10-30T19:21:28.188Z,1383160888.188 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2013-10-30T19:21:28.235Z,1383160888.235 [TempGradientCalculator] Loaded
2013-10-30T19:21:28.235Z,1383160888.235 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2013-10-30T19:21:28.251Z,1383160888.251 [YawRateCalculator] Loaded
2013-10-30T19:21:28.251Z,1383160888.251 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2013-10-30T19:21:28.299Z,1383160888.299 [Navigation] Loaded
2013-10-30T19:21:28.300Z,1383160888.300 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2013-10-30T19:21:28.300Z,1383160888.300 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2013-10-30T19:21:28.301Z,1383160888.301 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2013-10-30T19:21:28.621Z,1383160888.621 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2013-10-30T19:21:28.621Z,1383160888.621 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2013-10-30T19:21:28.644Z,1383160888.644 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2013-10-30T19:21:28.645Z,1383160888.645 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2013-10-30T19:21:28.733Z,1383160888.733 [VerticalControl](DEBUG): Construct VerticalControl.
2013-10-30T19:21:28.859Z,1383160888.859 [VerticalControl] Loaded
2013-10-30T19:21:28.860Z,1383160888.860 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2013-10-30T19:21:28.860Z,1383160888.860 [HorizontalControl](DEBUG): Construct HorizontalControl.
2013-10-30T19:21:28.929Z,1383160888.929 [HorizontalControl] Loaded
2013-10-30T19:21:28.929Z,1383160888.929 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2013-10-30T19:21:28.930Z,1383160888.930 [SpeedControl](DEBUG): Construct SpeedControl.
2013-10-30T19:21:28.931Z,1383160888.931 [SpeedControl] Loaded
2013-10-30T19:21:28.932Z,1383160888.932 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2013-10-30T19:21:28.932Z,1383160888.932 [LoopControl](DEBUG): Construct LoopControl.
2013-10-30T19:21:28.933Z,1383160888.933 [LoopControl] Loaded
2013-10-30T19:21:28.933Z,1383160888.933 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2013-10-30T19:21:28.934Z,1383160888.934 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2013-10-30T19:21:28.934Z,1383160888.934 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2013-10-30T19:21:28.940Z,1383160888.940 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2013-10-30T19:21:28.945Z,1383160888.945 [AsyncPiEstimator] Loaded
2013-10-30T19:21:28.945Z,1383160888.945 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2013-10-30T19:21:28.946Z,1383160888.946 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406474E0
2013-10-30T19:21:28.947Z,1383160888.947 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2013-10-30T19:21:28.947Z,1383160888.947 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2013-10-30T19:21:29.229Z,1383160889.229 [AHRS_sp3003D] Loaded
2013-10-30T19:21:29.230Z,1383160889.230 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2013-10-30T19:21:29.244Z,1383160889.244 [Depth_Keller] Loaded
2013-10-30T19:21:29.244Z,1383160889.244 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2013-10-30T19:21:29.516Z,1383160889.516 [DVL_micro] Loaded
2013-10-30T19:21:29.516Z,1383160889.516 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2013-10-30T19:21:29.517Z,1383160889.517 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 406CE4E0
2013-10-30T19:21:29.639Z,1383160889.639 [NAL9602] Loaded
2013-10-30T19:21:29.639Z,1383160889.639 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2013-10-30T19:21:29.692Z,1383160889.692 [Onboard] Loaded
2013-10-30T19:21:29.692Z,1383160889.692 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2013-10-30T19:21:29.699Z,1383160889.699 [Radio_Freewave] Loaded
2013-10-30T19:21:29.699Z,1383160889.699 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2013-10-30T19:21:29.889Z,1383160889.889 [DAT] Loaded
2013-10-30T19:21:29.889Z,1383160889.889 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2013-10-30T19:21:29.890Z,1383160889.890 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2013-10-30T19:21:29.890Z,1383160889.890 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2013-10-30T19:21:30.031Z,1383160890.031 [CTD_NeilBrown] Loaded
2013-10-30T19:21:30.032Z,1383160890.032 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2013-10-30T19:21:30.033Z,1383160890.033 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4072B4E0
2013-10-30T19:21:30.066Z,1383160890.066 [WetLabsBB2FL] Loaded
2013-10-30T19:21:30.066Z,1383160890.066 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2013-10-30T19:21:30.067Z,1383160890.067 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4075B4E0
2013-10-30T19:21:30.068Z,1383160890.068 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2013-10-30T19:21:30.071Z,1383160890.071 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2013-10-30T19:21:30.072Z,1383160890.072 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2013-10-30T19:21:30.101Z,1383160890.101 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2013-10-30T19:21:30.111Z,1383160890.111 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 4078B4E0
2013-10-30T19:21:30.116Z,1383160890.116 [Supervisor](DEBUG): Running supervisor.
2013-10-30T19:21:30.123Z,1383160890.123 [CommandLine](INFO): Thread ID is 3342
2013-10-30T19:21:30.127Z,1383160890.127 [controlThread](INFO): Thread ID is 3341
2013-10-30T19:21:30.127Z,1383160890.127 [controlThread](DEBUG): Initializing ControlThread
2013-10-30T19:21:30.128Z,1383160890.128 [CycleStarter](INFO): Thread ID is 3340
2013-10-30T19:21:30.128Z,1383160890.128 [InternalSim](DEBUG):  InternalSim initializing...
2013-10-30T19:21:30.167Z,1383160890.167 [logger](INFO): Thread ID is 3345
2013-10-30T19:21:30.183Z,1383160890.183 [SBIT](INFO): Initialize SBIT Component.
2013-10-30T19:21:30.184Z,1383160890.184 [SBIT](IMPORTANT): Tethys CM Info: 
 $Rev:10711
2013-10-30T19:21:30.184Z,1383160890.184 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2013-10-30T19:21:30.184Z,1383160890.184 [SBIT](IMPORTANT): Kernel Version:#634 PREEMPT Wed Feb 13 10:21:48 PST 2013
2013-10-30T19:21:30.185Z,1383160890.185 [IBIT](INFO): Initialize IBIT Component.
2013-10-30T19:21:30.186Z,1383160890.186 [CBIT](DEBUG): Initialize CBIT Component.
2013-10-30T19:21:30.186Z,1383160890.186 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2013-10-30T19:21:30.196Z,1383160890.196 [AsyncPiEstimator](INFO): Thread ID is 3520
2013-10-30T19:21:30.196Z,1383160890.196 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2013-10-30T19:21:30.216Z,1383160890.216 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-10-30T19:21:30.217Z,1383160890.217 [NavChart](DEBUG): Initialize NavChart Derivation.
2013-10-30T19:21:30.217Z,1383160890.217 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2013-10-30T19:21:30.218Z,1383160890.218 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2013-10-30T19:21:30.218Z,1383160890.218 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2013-10-30T19:21:30.219Z,1383160890.219 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2013-10-30T19:21:30.219Z,1383160890.219 [Navigation](DEBUG): Initializing Navigation.
2013-10-30T19:21:30.219Z,1383160890.219 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2013-10-30T19:21:30.221Z,1383160890.221 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2013-10-30T19:21:30.222Z,1383160890.222 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2013-10-30T19:21:30.222Z,1383160890.222 [LoopControl](DEBUG): Initialize LoopControlComponent.
2013-10-30T19:21:30.228Z,1383160890.228 [DVL_micro](INFO): Thread ID is 3529
2013-10-30T19:21:30.237Z,1383160890.237 [DVL_micro](INFO): Initializing
2013-10-30T19:21:30.237Z,1383160890.237 [DVL_micro](INFO): start:Powering up
2013-10-30T19:21:30.238Z,1383160890.238 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-10-30T19:21:30.238Z,1383160890.238 [DVL_micro](INFO): Cycling power to configure device.
2013-10-30T19:21:30.280Z,1383160890.280 [CTD_NeilBrown](INFO): Thread ID is 3536
2013-10-30T19:21:30.281Z,1383160890.281 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2013-10-30T19:21:30.288Z,1383160890.288 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2013-10-30T19:21:30.304Z,1383160890.304 [WetLabsBB2FL](INFO): Thread ID is 3537
2013-10-30T19:21:30.305Z,1383160890.305 [WetLabsBB2FL](INFO): Powering down
2013-10-30T19:21:30.324Z,1383160890.324 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2013-10-30T19:21:30.344Z,1383160890.344 [NavChartDb](INFO): Thread ID is 3539
2013-10-30T19:21:30.347Z,1383160890.347 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2013-10-30T19:21:30.348Z,1383160890.348 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2013-10-30T19:21:30.348Z,1383160890.348 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2013-10-30T19:21:30.348Z,1383160890.348 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2013-10-30T19:21:30.349Z,1383160890.349 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2013-10-30T19:21:30.349Z,1383160890.349 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2013-10-30T19:21:30.349Z,1383160890.349 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2013-10-30T19:21:30.349Z,1383160890.349 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2013-10-30T19:21:30.350Z,1383160890.350 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2013-10-30T19:21:30.372Z,1383160890.372 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2013-10-30T19:21:30.411Z,1383160890.411 [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-10-30T19:21:30.420Z,1383160890.420 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2013-10-30T19:21:30.481Z,1383160890.481 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2013-10-30T19:21:30.483Z,1383160890.483 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2013-10-30T19:21:30.486Z,1383160890.486 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-10-30T19:21:30.574Z,1383160890.574 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2013-10-30T19:21:30.586Z,1383160890.586 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-10-30T19:21:30.616Z,1383160890.616 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2013-10-30T19:21:30.642Z,1383160890.642 [Default:D.SetSpeed](DEBUG): Construct.
2013-10-30T19:21:30.649Z,1383160890.649 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2013-10-30T19:21:30.654Z,1383160890.654 [Default:F.Wait](DEBUG): Construct Wait.
2013-10-30T19:21:30.657Z,1383160890.657 [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-10-30T19:21:30.675Z,1383160890.675 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Depth_Keller,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-10-30T19:21:30.766Z,1383160890.766 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-10-30T19:21:31.012Z,1383160891.012 [Radio_Freewave](INFO): Powering up
2013-10-30T19:21:31.033Z,1383160891.033 [DAT](INFO): Powering up
2013-10-30T19:21:31.033Z,1383160891.033 [DAT](DEBUG): Initializing DAT.
2013-10-30T19:21:31.360Z,1383160891.360 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-10-30T19:21:31.370Z,1383160891.370 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-10-30T19:21:31.384Z,1383160891.384 [ElevatorServo](DEBUG): Initializing EZServoServo.
2013-10-30T19:21:31.397Z,1383160891.397 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2013-10-30T19:21:31.403Z,1383160891.403 [MassServo](DEBUG): Initializing EZServoServo.
2013-10-30T19:21:31.410Z,1383160891.410 [MassServo](DEBUG): Initializing MassServo.
2013-10-30T19:21:31.435Z,1383160891.435 [RudderServo](DEBUG): Initializing EZServoServo.
2013-10-30T19:21:31.441Z,1383160891.441 [RudderServo](DEBUG): Initializing RudderServo.
2013-10-30T19:21:31.458Z,1383160891.458 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-10-30T19:21:31.465Z,1383160891.465 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-10-30T19:21:32.371Z,1383160892.371 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-10-30T19:21:32.371Z,1383160892.371 [DVL_micro](INFO): Querying output modes
2013-10-30T19:21:32.372Z,1383160892.372 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-10-30T19:21:32.383Z,1383160892.383 [DVL_micro](DEBUG): cmdResponse: 01
2013-10-30T19:21:32.383Z,1383160892.383 [DVL_micro](INFO): NQ1 output enabled
2013-10-30T19:21:32.383Z,1383160892.383 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-10-30T19:21:32.395Z,1383160892.395 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2013-10-30T19:21:32.401Z,1383160892.401 [DVL_micro](INFO): pause:Powering down
2013-10-30T19:21:32.439Z,1383160892.439 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2013-10-30T19:21:32.439Z,1383160892.439 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2013-10-30T19:21:32.439Z,1383160892.439 [BuoyancyServo] Communications Fault, FailCount= 1
2013-10-30T19:21:32.439Z,1383160892.439 [BuoyancyServo](ERROR): Communications Fault
2013-10-30T19:21:32.633Z,1383160892.633 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2013-10-30T19:21:33.136Z,1383160893.136 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-10-30T19:21:33.138Z,1383160893.138 [BuoyancyServo](INFO): Powering down
2013-10-30T19:21:34.820Z,1383160894.820 [NAL9602](INFO): Powering up NAL9602
2013-10-30T19:21:35.506Z,1383160895.506 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2013-10-30T19:21:35.506Z,1383160895.506 [BuoyancyServo] No Fault, FailCount= 1
2013-10-30T19:21:36.006Z,1383160896.006 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-10-30T19:21:36.125Z,1383160896.125 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-10-30T19:21:45.539Z,1383160905.539 [NAL9602](INFO): NAL9602 initialized
2013-10-30T19:21:46.302Z,1383160906.302 [SBIT](IMPORTANT): Beginning Startup BIT
2013-10-30T19:21:46.305Z,1383160906.305 [CBIT](IMPORTANT): Beginning GF scan
2013-10-30T19:21:51.411Z,1383160911.411 [DAT](INFO): Powering down
2013-10-30T19:22:13.687Z,1383160933.687 [CBIT](IMPORTANT): No ground fault detected
2013-10-30T19:22:17.513Z,1383160937.513 [NAL9602](ERROR): getFix uart error: serial timeout
2013-10-30T19:22:40.417Z,1383160960.417 [SBIT](IMPORTANT): SBIT PASSED
2013-10-30T19:22:40.812Z,1383160960.812 [MissionManager](IMPORTANT): Started mission Startup
2013-10-30T19:22:40.813Z,1383160960.813 [Startup] Running Loop=1
2013-10-30T19:22:40.813Z,1383160960.813 [Startup](INFO): Aggregate::initialize Startup
2013-10-30T19:22:40.813Z,1383160960.813 [Startup:A.GoToSurface] Running Loop=1
2013-10-30T19:22:40.813Z,1383160960.813 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-30T19:22:40.819Z,1383160960.819 [Startup:StartupSatComms] Running Loop=1
2013-10-30T19:22:40.819Z,1383160960.819 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2013-10-30T19:22:40.819Z,1383160960.819 [Startup:StartupSatComms:A] Running Loop=1
2013-10-30T19:22:41.231Z,1383160961.231 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-10-30T19:22:46.041Z,1383160966.041 [CommandLine](IMPORTANT): got command failComponent
2013-10-30T19:22:46.041Z,1383160966.041 [CommandLine](IMPORTANT): Failed components:
2013-10-30T19:22:46.041Z,1383160966.041 [CommandLine](IMPORTANT): No failed Components.
2013-10-30T19:22:48.410Z,1383160968.410 [NAL9602](ERROR): parseGSV uart error: serial timeout
2013-10-30T19:23:19.994Z,1383160999.994 [NAL9602](ERROR): getFix uart error: serial timeout
2013-10-30T19:23:41.227Z,1383161021.227 [Startup:StartupSatComms:A](INFO): Timed out from 2013-10-30T19:22:40.8Z
2013-10-30T19:23:41.227Z,1383161021.227 [Startup:StartupSatComms:A:A_Timeout] Running Loop=1
2013-10-30T19:23:41.227Z,1383161021.227 [Startup:StartupSatComms:A:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A:A_Timeout
2013-10-30T19:23:41.227Z,1383161021.227 [Startup:StartupSatComms:A:A_Timeout](INFO): Completed Startup:StartupSatComms:A:A_Timeout
2013-10-30T19:23:41.227Z,1383161021.227 [Startup:StartupSatComms:A] Stopped
2013-10-30T19:23:41.227Z,1383161021.227 [Startup:StartupSatComms:B] Running Loop=1
2013-10-30T19:23:41.646Z,1383161021.646 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-10-30T19:23:50.615Z,1383161030.615 [NAL9602](ERROR): parseGSV uart error: serial timeout
2013-10-30T19:24:05.825Z,1383161045.825 [CommandLine](IMPORTANT): got command show variable quality
2013-10-30T19:24:05.845Z,1383161045.845 [CommandLine](INFO): NAL9602.sigQuality (count)
2013-10-30T19:24:11.903Z,1383161051.903 [CommandLine](IMPORTANT): got command report mod NAL9602.sigQuality
2013-10-30T19:24:12.164Z,1383161052.164 [Reporter](INFO): NAL9602.sigQuality no_value
2013-10-30T19:24:21.404Z,1383161061.404 [NAL9602](ERROR): Queried for signal strength and failed to receive proper response. serial timeout
2013-10-30T19:24:21.921Z,1383161061.921 [NAL9602](FAULT): received: 
2013-10-30T19:24:21.921Z,1383161061.921 [NAL9602] Data Fault, FailCount= 1
2013-10-30T19:24:21.921Z,1383161061.921 [NAL9602](ERROR): Data Fault
2013-10-30T19:24:21.944Z,1383161061.944 [CBIT](ERROR): Data Fault in component: NAL9602
2013-10-30T19:24:22.321Z,1383161062.321 [NAL9602](INFO): Powering down
2013-10-30T19:24:23.184Z,1383161063.184 [CBIT](INFO): Clearing failed state for component NAL9602
2013-10-30T19:24:23.184Z,1383161063.184 [NAL9602] No Fault, FailCount= 1
2013-10-30T19:24:27.602Z,1383161067.602 [NAL9602](INFO): Powering up NAL9602
2013-10-30T19:24:38.167Z,1383161078.167 [NAL9602](INFO): NAL9602 initialized
2013-10-30T19:24:41.455Z,1383161081.455 [Startup:StartupSatComms:B](INFO): Timed out from 2013-10-30T19:23:41.2Z
2013-10-30T19:24:41.455Z,1383161081.455 [Startup:StartupSatComms:B:A_Timeout] Running Loop=1
2013-10-30T19:24:41.455Z,1383161081.455 [Startup:StartupSatComms:B:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:B:A_Timeout
2013-10-30T19:24:41.455Z,1383161081.455 [Startup:StartupSatComms:B:A_Timeout](INFO): Completed Startup:StartupSatComms:B:A_Timeout
2013-10-30T19:24:41.455Z,1383161081.455 [Startup:StartupSatComms:B] Stopped
2013-10-30T19:24:41.455Z,1383161081.455 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2013-10-30T19:24:41.456Z,1383161081.456 [Startup:StartupSatComms] Stopped
2013-10-30T19:24:41.456Z,1383161081.456 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2013-10-30T19:24:41.457Z,1383161081.457 [Startup](INFO): Completed Startup
2013-10-30T19:24:41.457Z,1383161081.457 [Startup] Stopped
2013-10-30T19:24:41.457Z,1383161081.457 [Startup](INFO): Aggregate::uninitialize Startup
2013-10-30T19:24:41.457Z,1383161081.457 [Startup:A.GoToSurface] Stopped
2013-10-30T19:24:41.457Z,1383161081.457 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-30T19:24:41.845Z,1383161081.845 [MissionManager](IMPORTANT): Started mission Default
2013-10-30T19:24:41.845Z,1383161081.845 [Default] Running Loop=1
2013-10-30T19:24:41.845Z,1383161081.845 [Default](INFO): Aggregate::initialize Default
2013-10-30T19:24:41.845Z,1383161081.845 [Default:D.SetSpeed] Running Loop=1
2013-10-30T19:24:41.845Z,1383161081.845 [Default:D.SetSpeed](DEBUG): Initialize.
2013-10-30T19:24:41.845Z,1383161081.845 [Default:E.GoToSurface] Running Loop=1
2013-10-30T19:24:41.845Z,1383161081.845 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-30T19:24:41.846Z,1383161081.846 [Default:Iridium] Running Loop=1
2013-10-30T19:24:41.846Z,1383161081.846 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2013-10-30T19:24:41.846Z,1383161081.846 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-10-30T19:24:41.846Z,1383161081.846 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2013-10-30T19:24:41.846Z,1383161081.846 [Default:Iridium:B.GoToSurface] Running Loop=1
2013-10-30T19:24:41.846Z,1383161081.846 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-30T19:24:41.847Z,1383161081.847 [Default:E.GoToSurface] Running Loop=1
2013-10-30T19:24:41.852Z,1383161081.852 [Default:D.SetSpeed] Running Loop=1
2013-10-30T19:24:41.857Z,1383161081.857 [Default:CallIridium] Running Loop=1
2013-10-30T19:24:41.857Z,1383161081.857 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2013-10-30T19:24:41.857Z,1383161081.857 [Default:CallIridium:A] Running Loop=1
2013-10-30T19:24:41.859Z,1383161081.859 [Default:CallIridium:A] Stopped
2013-10-30T19:24:41.859Z,1383161081.859 [Default:CallIridium:B] Running Loop=1
2013-10-30T19:24:41.859Z,1383161081.859 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2013-10-30T19:24:41.868Z,1383161081.868 [Default:Iridium:B.GoToSurface] Stopped
2013-10-30T19:24:41.868Z,1383161081.868 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-30T19:24:41.868Z,1383161081.868 [Default:Iridium:Read_Iridium] Running Loop=1
2013-10-30T19:24:41.868Z,1383161081.868 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-10-30T19:24:41.873Z,1383161081.873 [Default:GPS] Running Loop=1
2013-10-30T19:24:41.873Z,1383161081.873 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2013-10-30T19:24:41.873Z,1383161081.873 [Default:GPS:A.SetSpeed] Running Loop=1
2013-10-30T19:24:41.873Z,1383161081.873 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2013-10-30T19:24:41.873Z,1383161081.873 [Default:GPS:B.GoToSurface] Running Loop=1
2013-10-30T19:24:41.873Z,1383161081.873 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-30T19:24:41.879Z,1383161081.879 [Default:GPS:B.GoToSurface] Stopped
2013-10-30T19:24:41.879Z,1383161081.879 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-30T19:24:41.879Z,1383161081.879 [Default:GPS:Read_GPS] Running Loop=1
2013-10-30T19:24:41.879Z,1383161081.879 [Default:GPS:A.SetSpeed] Running Loop=1
2013-10-30T19:24:42.284Z,1383161082.284 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-10-30T19:24:42.287Z,1383161082.287 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-10-30T19:25:09.780Z,1383161109.780 [NAL9602](ERROR): getFix uart error: serial timeout
2013-10-30T19:25:40.427Z,1383161140.427 [NAL9602](ERROR): parseGSV uart error: serial timeout
2013-10-30T19:26:11.100Z,1383161171.100 [NAL9602](ERROR): Queried for signal strength and failed to receive proper response. serial timeout
2013-10-30T19:26:11.620Z,1383161171.620 [NAL9602](FAULT): received: 
2013-10-30T19:26:11.620Z,1383161171.620 [NAL9602] Data Fault, FailCount= 2
2013-10-30T19:26:11.620Z,1383161171.620 [NAL9602](ERROR): Data Fault
2013-10-30T19:26:11.643Z,1383161171.643 [CBIT](ERROR): Data Fault in component: NAL9602
2013-10-30T19:26:11.643Z,1383161171.643 [CBIT](CRITICAL): Data Fault in component: NAL9602
2013-10-30T19:26:12.003Z,1383161172.003 [NAL9602](INFO): Powering down
2013-10-30T19:26:12.027Z,1383161172.027 [CommandLine](FAULT): Scheduling is paused
2013-10-30T19:28:11.712Z,1383161291.712 [CBIT](INFO): Clearing failed count for component NAL9602
2013-10-30T19:28:11.712Z,1383161291.712 [NAL9602] No Fault, FailCount= 2
2013-10-30T19:28:12.084Z,1383161292.084 [NAL9602](INFO): Powering up NAL9602
2013-10-30T19:28:22.703Z,1383161302.703 [NAL9602](INFO): NAL9602 initialized
2013-10-30T19:28:54.200Z,1383161334.200 [NAL9602](ERROR): getFix uart error: serial timeout
2013-10-30T19:28:55.926Z,1383161335.926 [NAL9602](ERROR): parseGSV uart error: serial timeout
2013-10-30T19:29:09.916Z,1383161349.916 [CommandLine](IMPORTANT): got command report
2013-10-30T19:29:09.916Z,1383161349.916 [Reporter](INFO): NAL9602.sigQuality reporting changes
2013-10-30T19:29:26.511Z,1383161366.511 [NAL9602](ERROR): Queried for signal strength and failed to receive proper response. serial timeout
2013-10-30T19:29:27.031Z,1383161367.031 [NAL9602](FAULT): received: 
2013-10-30T19:29:27.031Z,1383161367.031 [NAL9602] Data Fault, FailCount= 1
2013-10-30T19:29:27.031Z,1383161367.031 [NAL9602](ERROR): Data Fault
2013-10-30T19:29:27.103Z,1383161367.103 [CBIT](ERROR): Data Fault in component: NAL9602
2013-10-30T19:29:27.456Z,1383161367.456 [NAL9602](INFO): Powering down
2013-10-30T19:29:28.310Z,1383161368.310 [CBIT](INFO): Clearing failed state for component NAL9602
2013-10-30T19:29:28.310Z,1383161368.310 [NAL9602] No Fault, FailCount= 1
2013-10-30T19:29:32.657Z,1383161372.657 [NAL9602](INFO): Powering up NAL9602
2013-10-30T19:29:43.416Z,1383161383.416 [NAL9602](INFO): NAL9602 initialized
2013-10-30T19:29:46.256Z,1383161386.256 [NAL9602](ERROR): parseGSV uart error: serial timeout
2013-10-30T19:30:16.799Z,1383161416.799 [NAL9602](ERROR): Queried for signal strength and failed to receive proper response. serial timeout
2013-10-30T19:30:17.312Z,1383161417.312 [NAL9602](FAULT): received: 
2013-10-30T19:30:17.312Z,1383161417.312 [NAL9602] Data Fault, FailCount= 2
2013-10-30T19:30:17.312Z,1383161417.312 [NAL9602](ERROR): Data Fault
2013-10-30T19:30:17.341Z,1383161417.341 [CBIT](ERROR): Data Fault in component: NAL9602
2013-10-30T19:30:17.341Z,1383161417.341 [CBIT](CRITICAL): Data Fault in component: NAL9602
2013-10-30T19:30:17.724Z,1383161417.724 [NAL9602](INFO): Powering down
2013-10-30T19:30:24.099Z,1383161424.099 [CommandLine](IMPORTANT): got command failComponent
2013-10-30T19:30:24.099Z,1383161424.099 [CommandLine](IMPORTANT): Failed components:
2013-10-30T19:30:24.100Z,1383161424.100 [CommandLine](IMPORTANT): NAL9602: Data Fault
2013-10-30T19:30:27.893Z,1383161427.893 [CommandLine](IMPORTANT): got command failComponent none NAL9602
2013-10-30T19:30:27.893Z,1383161427.893 [NAL9602] No Fault, FailCount= 2
2013-10-30T19:30:27.894Z,1383161427.894 [CommandLine](IMPORTANT): NAL9602 failureMode is No Fault
2013-10-30T19:30:28.106Z,1383161428.106 [NAL9602](INFO): Powering up NAL9602
2013-10-30T19:30:38.602Z,1383161438.602 [NAL9602](INFO): NAL9602 initialized
2013-10-30T19:31:10.034Z,1383161470.034 [NAL9602](ERROR): getFix uart error: serial timeout
2013-10-30T19:31:42.594Z,1383161502.594 [NAL9602](ERROR): Queried for signal strength and failed to receive proper response. no error
2013-10-30T19:31:43.113Z,1383161503.113 [NAL9602](FAULT): received: 
2013-10-30T19:31:43.113Z,1383161503.113 [NAL9602] Data Fault, FailCount= 3
2013-10-30T19:31:43.113Z,1383161503.113 [NAL9602](ERROR): Data Fault
2013-10-30T19:31:43.143Z,1383161503.143 [CBIT](ERROR): Data Fault in component: NAL9602
2013-10-30T19:31:43.144Z,1383161503.144 [CBIT](CRITICAL): Data Fault in component: NAL9602
2013-10-30T19:31:43.479Z,1383161503.479 [NAL9602](INFO): Powering down
2013-10-30T19:32:02.512Z,1383161522.512 [CommandLine](IMPORTANT): got command failComponent
2013-10-30T19:32:02.512Z,1383161522.512 [CommandLine](IMPORTANT): Failed components:
2013-10-30T19:32:02.512Z,1383161522.512 [CommandLine](IMPORTANT): NAL9602: Data Fault
2013-10-30T19:32:05.829Z,1383161525.829 [CommandLine](IMPORTANT): got command failComponent none NAL9602
2013-10-30T19:32:05.829Z,1383161525.829 [NAL9602] No Fault, FailCount= 3
2013-10-30T19:32:05.830Z,1383161525.830 [CommandLine](IMPORTANT): NAL9602 failureMode is No Fault
2013-10-30T19:32:05.898Z,1383161525.898 [NAL9602](INFO): Powering up NAL9602
2013-10-30T19:32:16.376Z,1383161536.376 [NAL9602](INFO): NAL9602 initialized
2013-10-30T19:32:17.136Z,1383161537.136 [NAL9602](FAULT): GPS failed to acquire within timeout.
2013-10-30T19:32:17.136Z,1383161537.136 [NAL9602] Data Fault, FailCount= 4
2013-10-30T19:32:17.136Z,1383161537.136 [NAL9602](ERROR): Data Fault
2013-10-30T19:32:17.163Z,1383161537.163 [CBIT](ERROR): Data Fault in component: NAL9602
2013-10-30T19:32:17.163Z,1383161537.163 [CBIT](CRITICAL): Data Fault in component: NAL9602
2013-10-30T19:32:17.544Z,1383161537.544 [NAL9602](INFO): Powering down
2013-10-30T19:32:24.061Z,1383161544.061 [CommandLine](IMPORTANT): got command failComponent none NAL9602
2013-10-30T19:32:24.062Z,1383161544.062 [NAL9602] No Fault, FailCount= 4
2013-10-30T19:32:24.062Z,1383161544.062 [CommandLine](IMPORTANT): NAL9602 failureMode is No Fault
2013-10-30T19:32:24.339Z,1383161544.339 [NAL9602](INFO): Powering up NAL9602
2013-10-30T19:32:34.790Z,1383161554.790 [NAL9602](INFO): NAL9602 initialized
2013-10-30T19:32:46.092Z,1383161566.092 [Reporter](INFO): NAL9602.sigQuality 3 count
2013-10-30T19:32:58.747Z,1383161578.747 [NAL9602](INFO): SBD MO Status=1, MOMSN=20265, MT Status=0, MTMSN=0
2013-10-30T19:32:58.795Z,1383161578.795 [NAL9602](INFO): Sent 60 bytes from file Logs/20131030T185920/Courier0004.lzma
2013-10-30T19:32:58.795Z,1383161578.795 [NAL9602](INFO): Packets left to send: 0
2013-10-30T19:32:58.797Z,1383161578.797 [NAL9602](INFO): Stored copy of sent data in Logs/20131030T185920/Courier0004.lzma.parts/0000.sbd
2013-10-30T19:33:09.118Z,1383161589.118 [NAL9602](INFO): SBD MO Status=1, MOMSN=20266, MT Status=0, MTMSN=0
2013-10-30T19:33:09.167Z,1383161589.167 [NAL9602](INFO): Sent 101 bytes from file Logs/20131030T191533/Courier0000.lzma
2013-10-30T19:33:09.167Z,1383161589.167 [NAL9602](INFO): Packets left to send: 0
2013-10-30T19:33:09.169Z,1383161589.169 [NAL9602](INFO): Stored copy of sent data in Logs/20131030T191533/Courier0000.lzma.parts/0000.sbd
2013-10-30T19:33:24.041Z,1383161604.041 [NAL9602](INFO): SBD MO Status=1, MOMSN=20267, MT Status=0, MTMSN=0
2013-10-30T19:33:24.090Z,1383161604.090 [NAL9602](INFO): Sent 332 bytes from file Logs/20131030T185920/Express0001.lzma
2013-10-30T19:33:24.091Z,1383161604.091 [NAL9602](INFO): Packets left to send: 2
2013-10-30T19:33:24.092Z,1383161604.092 [NAL9602](INFO): Stored copy of sent data in Logs/20131030T185920/Express0001.lzma.parts/0002.sbd
2013-10-30T19:33:34.962Z,1383161614.962 [NAL9602](INFO): SBD MO Status=1, MOMSN=20268, MT Status=0, MTMSN=0
2013-10-30T19:33:35.015Z,1383161615.015 [NAL9602](INFO): Sent 332 bytes from file Logs/20131030T185920/Express0001.lzma
2013-10-30T19:33:35.015Z,1383161615.015 [NAL9602](INFO): Packets left to send: 1
2013-10-30T19:33:35.017Z,1383161615.017 [NAL9602](INFO): Stored copy of sent data in Logs/20131030T185920/Express0001.lzma.parts/0001.sbd
2013-10-30T19:33:47.465Z,1383161627.465 [NAL9602](INFO): SBD MO Status=1, MOMSN=20269, MT Status=0, MTMSN=0
2013-10-30T19:33:47.519Z,1383161627.519 [NAL9602](INFO): Sent 72 bytes from file Logs/20131030T185920/Express0001.lzma
2013-10-30T19:33:47.519Z,1383161627.519 [NAL9602](INFO): Packets left to send: 0
2013-10-30T19:33:47.520Z,1383161627.520 [NAL9602](INFO): Stored copy of sent data in Logs/20131030T185920/Express0001.lzma.parts/0000.sbd
2013-10-30T19:34:07.251Z,1383161647.251 [NAL9602](INFO): SBD MO Status=1, MOMSN=20270, MT Status=0, MTMSN=0
2013-10-30T19:34:07.302Z,1383161647.302 [NAL9602](INFO): Sent 332 bytes from file Logs/20131030T185920/Express0005.lzma
2013-10-30T19:34:07.302Z,1383161647.302 [NAL9602](INFO): Packets left to send: 2
2013-10-30T19:34:07.304Z,1383161647.304 [NAL9602](INFO): Stored copy of sent data in Logs/20131030T185920/Express0005.lzma.parts/0002.sbd
2013-10-30T19:34:13.831Z,1383161653.831 [CommandLine](IMPORTANT): got command quit
2013-10-30T19:34:14.937Z,1383161654.937 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2013-10-30T19:34:14.937Z,1383161654.937 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2013-10-30T19:34:15.141Z,1383161655.141 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2013-10-30T19:34:15.314Z,1383161655.314 [WetLabsBB2FL](INFO): Powering down
2013-10-30T19:34:15.322Z,1383161655.322 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2013-10-30T19:34:15.466Z,1383161655.466 [CTD_NeilBrown](INFO): Powering down
2013-10-30T19:34:15.474Z,1383161655.474 [ComponentRegistry](INFO): Shutting down DVL_micro ThreadHandler
2013-10-30T19:34:15.634Z,1383161655.634 [DVL_micro](INFO): uninitialize:Powering down
2013-10-30T19:34:15.654Z,1383161655.654 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2013-10-30T19:34:15.863Z,1383161655.863 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2013-10-30T19:34:15.875Z,1383161655.875 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2013-10-30T19:34:15.975Z,1383161655.975 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2013-10-30T19:34:15.977Z,1383161655.977 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2013-10-30T19:34:16.146Z,1383161656.146 [controlThread](DEBUG): Uninitializing ControlThread
2013-10-30T19:34:16.147Z,1383161656.147 [AHRS_sp3003D](INFO): Powering down
2013-10-30T19:34:16.235Z,1383161656.235 [NAL9602](INFO): Powering down
2013-10-30T19:34:16.237Z,1383161656.237 [DAT](INFO): Powering down
2013-10-30T19:34:16.238Z,1383161656.238 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-10-30T19:34:16.238Z,1383161656.238 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2013-10-30T19:34:16.240Z,1383161656.240 [Default] Stopped
2013-10-30T19:34:16.240Z,1383161656.240 [Default](INFO): Aggregate::uninitialize Default
2013-10-30T19:34:16.240Z,1383161656.240 [Default:GPS] Stopped
2013-10-30T19:34:16.240Z,1383161656.240 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2013-10-30T19:34:16.240Z,1383161656.240 [Default:GPS:A.SetSpeed] Stopped
2013-10-30T19:34:16.240Z,1383161656.240 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2013-10-30T19:34:16.240Z,1383161656.240 [Default:GPS:Read_GPS] Stopped
2013-10-30T19:34:16.240Z,1383161656.240 [Default:Iridium] Stopped
2013-10-30T19:34:16.240Z,1383161656.240 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2013-10-30T19:34:16.240Z,1383161656.240 [Default:Iridium:A.SetSpeed] Stopped
2013-10-30T19:34:16.241Z,1383161656.241 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2013-10-30T19:34:16.241Z,1383161656.241 [Default:Iridium:Read_Iridium] Stopped
2013-10-30T19:34:16.241Z,1383161656.241 [Default:CallIridium] Stopped
2013-10-30T19:34:16.241Z,1383161656.241 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2013-10-30T19:34:16.241Z,1383161656.241 [Default:CallIridium:B] Stopped
2013-10-30T19:34:16.241Z,1383161656.241 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2013-10-30T19:34:16.241Z,1383161656.241 [Default:D.SetSpeed] Stopped
2013-10-30T19:34:16.241Z,1383161656.241 [Default:D.SetSpeed](DEBUG): Uninitialize.
2013-10-30T19:34:16.241Z,1383161656.241 [Default:E.GoToSurface] Stopped
2013-10-30T19:34:16.241Z,1383161656.241 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-30T19:34:16.245Z,1383161656.245 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2013-10-30T19:34:16.246Z,1383161656.246 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2013-10-30T19:34:16.246Z,1383161656.246 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2013-10-30T19:34:16.246Z,1383161656.246 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2013-10-30T19:34:16.247Z,1383161656.247 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-10-30T19:34:16.247Z,1383161656.247 [BuoyancyServo](INFO): Powering down
2013-10-30T19:34:16.259Z,1383161656.259 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2013-10-30T19:34:16.259Z,1383161656.259 [ElevatorServo](INFO): Powering down
2013-10-30T19:34:16.260Z,1383161656.260 [MassServo](DEBUG): Uninitialize Mass Servo.
2013-10-30T19:34:16.260Z,1383161656.260 [MassServo](INFO): Powering down
2013-10-30T19:34:16.261Z,1383161656.261 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2013-10-30T19:34:16.261Z,1383161656.261 [RudderServo](INFO): Powering down
2013-10-30T19:34:16.262Z,1383161656.262 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2013-10-30T19:34:16.262Z,1383161656.262 [ThrusterServo](INFO): Powering down
2013-10-30T19:34:16.263Z,1383161656.263 [SBIT](DEBUG): Uninitialize SBIT Component.
2013-10-30T19:34:16.263Z,1383161656.263 [IBIT](DEBUG): Uninitialize IBIT Component.
2013-10-30T19:34:16.264Z,1383161656.264 [CBIT](DEBUG): Uninitialize CBIT Component.