2014-11-04T05:12:21.296Z,1415077941.296 [Supervisor](DEBUG): Initializing supervisor.
2014-11-04T05:12:21.299Z,1415077941.299 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-11-04T05:12:21.299Z,1415077941.299 [SyncHandler](INFO): Protected caller Thread ID is 766
2014-11-04T05:12:21.300Z,1415077941.300 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-11-04T05:12:21.301Z,1415077941.301 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2014-11-04T05:12:21.301Z,1415077941.301 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 767
2014-11-04T05:12:21.304Z,1415077941.304 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-11-04T05:12:21.316Z,1415077941.316 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-11-04T05:12:21.317Z,1415077941.317 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2014-11-04T05:12:21.317Z,1415077941.317 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 768
2014-11-04T05:12:21.318Z,1415077941.318 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-11-04T05:12:21.319Z,1415077941.319 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2014-11-04T05:12:21.319Z,1415077941.319 [logger ThreadHandler](INFO): Protected caller Thread ID is 769
2014-11-04T05:12:21.322Z,1415077941.322 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-11-04T05:12:21.322Z,1415077941.322 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-11-04T05:12:21.327Z,1415077941.327 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-11-04T05:12:21.658Z,1415077941.658 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-11-04T05:12:21.659Z,1415077941.659 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-11-04T05:12:21.819Z,1415077941.819 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-11-04T05:12:21.822Z,1415077941.822 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-11-04T05:12:21.932Z,1415077941.932 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-11-04T05:12:21.933Z,1415077941.933 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-11-04T05:12:22.056Z,1415077942.056 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-11-04T05:12:22.059Z,1415077942.059 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-11-04T05:12:22.148Z,1415077942.148 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-11-04T05:12:22.307Z,1415077942.307 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-11-04T05:12:22.307Z,1415077942.307 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-11-04T05:12:22.395Z,1415077942.395 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-11-04T05:12:22.396Z,1415077942.396 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-11-04T05:12:22.605Z,1415077942.605 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-11-04T05:12:22.605Z,1415077942.605 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-11-04T05:12:22.972Z,1415077942.972 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-11-04T05:12:22.974Z,1415077942.974 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-11-04T05:12:23.289Z,1415077943.289 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-11-04T05:12:23.290Z,1415077943.290 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-11-04T05:12:23.798Z,1415077943.798 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-11-04T05:12:23.799Z,1415077943.799 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-11-04T05:12:23.990Z,1415077943.990 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-11-04T05:12:23.991Z,1415077943.991 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-11-04T05:12:24.097Z,1415077944.097 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-11-04T05:12:24.098Z,1415077944.098 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-11-04T05:12:24.547Z,1415077944.547 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-11-04T05:12:24.548Z,1415077944.548 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-11-04T05:12:24.660Z,1415077944.660 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-11-04T05:12:24.662Z,1415077944.662 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2014-11-04T05:12:24.667Z,1415077944.667 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2014-11-04T05:12:24.932Z,1415077944.932 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2014-11-04T05:12:24.933Z,1415077944.933 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2014-11-04T05:12:37.497Z,1415077957.497 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Estimation.cfg
2014-11-04T05:12:38.395Z,1415077958.395 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2014-11-04T05:12:38.495Z,1415077958.495 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2014-11-04T05:12:38.593Z,1415077958.593 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2014-11-04T05:12:38.736Z,1415077958.736 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2014-11-04T05:12:38.908Z,1415077958.908 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2014-11-04T05:12:39.010Z,1415077959.010 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2014-11-04T05:12:39.098Z,1415077959.098 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2014-11-04T05:12:39.202Z,1415077959.202 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2014-11-04T05:12:39.299Z,1415077959.299 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2014-11-04T05:12:39.474Z,1415077959.474 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2014-11-04T05:12:39.480Z,1415077959.480 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-11-04T05:12:39.555Z,1415077959.555 [VerticalControl](DEBUG): Construct VerticalControl.
2014-11-04T05:12:39.677Z,1415077959.677 [VerticalControl] Loaded
2014-11-04T05:12:39.677Z,1415077959.677 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-11-04T05:12:39.678Z,1415077959.678 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-11-04T05:12:39.751Z,1415077959.751 [HorizontalControl] Loaded
2014-11-04T05:12:39.751Z,1415077959.751 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-11-04T05:12:39.752Z,1415077959.752 [SpeedControl](DEBUG): Construct SpeedControl.
2014-11-04T05:12:39.758Z,1415077959.758 [SpeedControl] Loaded
2014-11-04T05:12:39.758Z,1415077959.758 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-11-04T05:12:39.759Z,1415077959.759 [LoopControl](DEBUG): Construct LoopControl.
2014-11-04T05:12:39.759Z,1415077959.759 [LoopControl] Loaded
2014-11-04T05:12:39.760Z,1415077959.760 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-11-04T05:12:39.760Z,1415077959.760 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-11-04T05:12:39.763Z,1415077959.763 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-11-04T05:12:39.889Z,1415077959.889 [SBIT](DEBUG): Construct Startup Built In Test.
2014-11-04T05:12:39.901Z,1415077959.901 [SBIT] Loaded
2014-11-04T05:12:39.902Z,1415077959.902 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-11-04T05:12:39.903Z,1415077959.903 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-11-04T05:12:39.932Z,1415077959.932 [IBIT] Loaded
2014-11-04T05:12:39.933Z,1415077959.933 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-11-04T05:12:39.935Z,1415077959.935 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-11-04T05:12:40.058Z,1415077960.058 [CBIT] Loaded
2014-11-04T05:12:40.058Z,1415077960.058 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-11-04T05:12:40.059Z,1415077960.059 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-11-04T05:12:40.061Z,1415077960.061 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-11-04T05:12:40.091Z,1415077960.091 [DepthRateCalculator] Loaded
2014-11-04T05:12:40.091Z,1415077960.091 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-11-04T05:12:40.097Z,1415077960.097 [PitchRateCalculator] Loaded
2014-11-04T05:12:40.097Z,1415077960.097 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-11-04T05:12:40.109Z,1415077960.109 [SpeedCalculator] Loaded
2014-11-04T05:12:40.109Z,1415077960.109 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-11-04T05:12:40.126Z,1415077960.126 [TempGradientCalculator] Loaded
2014-11-04T05:12:40.126Z,1415077960.126 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-11-04T05:12:40.132Z,1415077960.132 [YawRateCalculator] Loaded
2014-11-04T05:12:40.132Z,1415077960.132 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-11-04T05:12:40.133Z,1415077960.133 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-11-04T05:12:40.133Z,1415077960.133 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-11-04T05:12:41.466Z,1415077961.466 [HFRCMReconstructedInterpolator] Loaded
2014-11-04T05:12:41.467Z,1415077961.467 [ComponentRegistry](DEBUG): SyncComponent "HFRCMReconstructedInterpolator" handled in the control thread.
2014-11-04T05:12:41.467Z,1415077961.467 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-11-04T05:12:41.468Z,1415077961.468 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-11-04T05:12:41.754Z,1415077961.754 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-11-04T05:12:41.754Z,1415077961.754 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-11-04T05:12:41.816Z,1415077961.816 [NavChart] Loaded
2014-11-04T05:12:41.817Z,1415077961.817 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-11-04T05:12:41.823Z,1415077961.823 [UniversalFixResidualReporter] Loaded
2014-11-04T05:12:41.823Z,1415077961.823 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-11-04T05:12:41.824Z,1415077961.824 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-11-04T05:12:41.825Z,1415077961.825 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-11-04T05:12:41.834Z,1415077961.834 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-11-04T05:12:41.835Z,1415077961.835 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-11-04T05:12:42.060Z,1415077962.060 [CTD_NeilBrown] Loaded
2014-11-04T05:12:42.060Z,1415077962.060 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-11-04T05:12:42.062Z,1415077962.062 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 405DF4E0
2014-11-04T05:12:42.062Z,1415077962.062 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 852
2014-11-04T05:12:42.068Z,1415077962.068 [g3ESP] Loaded
2014-11-04T05:12:42.069Z,1415077962.069 [ComponentRegistry](DEBUG): SyncComponent "g3ESP" handled in the control thread.
2014-11-04T05:12:42.070Z,1415077962.070 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-11-04T05:12:42.070Z,1415077962.070 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-11-04T05:12:42.778Z,1415077962.778 [AHRS_sp3003D] Loaded
2014-11-04T05:12:42.779Z,1415077962.779 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-11-04T05:12:42.940Z,1415077962.940 [DataOverHttps] Loaded
2014-11-04T05:12:42.940Z,1415077962.940 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2014-11-04T05:12:42.954Z,1415077962.954 [Depth_Keller] Loaded
2014-11-04T05:12:42.954Z,1415077962.954 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-11-04T05:12:42.959Z,1415077962.959 [DropWeight] Loaded
2014-11-04T05:12:42.959Z,1415077962.959 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-11-04T05:12:43.003Z,1415077963.003 [Onboard] Loaded
2014-11-04T05:12:43.003Z,1415077963.003 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-11-04T05:12:43.010Z,1415077963.010 [Radio_Surface] Loaded
2014-11-04T05:12:43.011Z,1415077963.011 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2014-11-04T05:12:43.012Z,1415077963.012 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4082C4E0
2014-11-04T05:12:43.012Z,1415077963.012 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 853
2014-11-04T05:12:43.013Z,1415077963.013 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-11-04T05:12:43.014Z,1415077963.014 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-11-04T05:12:55.466Z,1415077975.466 [BuoyancyServo] Loaded
2014-11-04T05:12:55.466Z,1415077975.466 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-11-04T05:12:55.478Z,1415077975.478 [ElevatorServo] Loaded
2014-11-04T05:12:55.479Z,1415077975.479 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-11-04T05:12:55.490Z,1415077975.490 [MassServo] Loaded
2014-11-04T05:12:55.491Z,1415077975.491 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-11-04T05:12:55.503Z,1415077975.503 [RudderServo] Loaded
2014-11-04T05:12:55.503Z,1415077975.503 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-11-04T05:12:55.515Z,1415077975.515 [ThrusterServo] Loaded
2014-11-04T05:12:55.515Z,1415077975.515 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-11-04T05:12:55.515Z,1415077975.515 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-11-04T05:12:55.516Z,1415077975.516 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-11-04T05:12:55.715Z,1415077975.715 [InternalSim] Loaded
2014-11-04T05:12:55.715Z,1415077975.715 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-11-04T05:12:55.716Z,1415077975.716 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-11-04T05:12:55.717Z,1415077975.717 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-11-04T05:12:55.763Z,1415077975.763 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-11-04T05:12:55.765Z,1415077975.765 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-11-04T05:12:55.766Z,1415077975.766 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-11-04T05:12:55.773Z,1415077975.773 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-11-04T05:12:55.774Z,1415077975.774 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 408DD4E0
2014-11-04T05:12:55.774Z,1415077975.774 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 854
2014-11-04T05:12:55.779Z,1415077975.779 [Supervisor](INFO): Main Thread ID is 764
2014-11-04T05:12:55.779Z,1415077975.779 [Supervisor](DEBUG): Running supervisor.
2014-11-04T05:12:55.780Z,1415077975.780 [CommandLine ThreadHandler](INFO): Handler Thread ID is 855
2014-11-04T05:12:55.783Z,1415077975.783 [controlThread ThreadHandler](INFO): Handler Thread ID is 856
2014-11-04T05:12:55.783Z,1415077975.783 [controlThread](DEBUG): Initializing ControlThread
2014-11-04T05:12:55.784Z,1415077975.784 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-11-04T05:12:55.786Z,1415077975.786 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-11-04T05:12:55.786Z,1415077975.786 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-11-04T05:12:55.787Z,1415077975.787 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-11-04T05:12:55.787Z,1415077975.787 [SBIT](INFO): Initialize SBIT Component.
2014-11-04T05:12:55.788Z,1415077975.788 [SBIT](IMPORTANT): Tethys CM Info: SVN revision:11821
2014-11-04T05:12:55.788Z,1415077975.788 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2014-11-04T05:12:55.788Z,1415077975.788 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-11-04T05:12:55.789Z,1415077975.789 [IBIT](INFO): Initialize IBIT Component.
2014-11-04T05:12:55.790Z,1415077975.790 [CBIT](DEBUG): Initialize CBIT Component.
2014-11-04T05:12:55.790Z,1415077975.790 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2014-11-04T05:12:55.790Z,1415077975.790 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2014-11-04T05:12:55.791Z,1415077975.791 [logger ThreadHandler](INFO): Handler Thread ID is 857
2014-11-04T05:12:55.811Z,1415077975.811 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 858
2014-11-04T05:12:55.812Z,1415077975.812 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-11-04T05:12:55.815Z,1415077975.815 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-11-04T05:12:55.816Z,1415077975.816 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-11-04T05:12:55.816Z,1415077975.816 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-11-04T05:12:55.816Z,1415077975.816 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-11-04T05:12:55.817Z,1415077975.817 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-11-04T05:12:55.818Z,1415077975.818 [HFRCMReconstructedInterpolator](INFO): Initializing HFRCMReconstructedInterpolator component with velocityAccuracy_ = 0.300000 m/s.
2014-11-04T05:12:55.820Z,1415077975.820 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-11-04T05:12:55.820Z,1415077975.820 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2014-11-04T05:12:55.826Z,1415077975.826 [InternalSim](DEBUG):  InternalSim initializing...
2014-11-04T05:12:55.836Z,1415077975.836 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-11-04T05:12:55.845Z,1415077975.845 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 860
2014-11-04T05:12:55.851Z,1415077975.851 [Radio_Surface](INFO): Powering up
2014-11-04T05:12:55.860Z,1415077975.860 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 861
2014-11-04T05:12:55.870Z,1415077975.870 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-11-04T05:12:55.871Z,1415077975.871 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-11-04T05:12:55.871Z,1415077975.871 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-11-04T05:12:55.871Z,1415077975.871 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-11-04T05:12:55.872Z,1415077975.872 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-11-04T05:12:55.872Z,1415077975.872 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-11-04T05:12:55.872Z,1415077975.872 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-11-04T05:12:55.873Z,1415077975.873 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-11-04T05:12:55.873Z,1415077975.873 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-11-04T05:12:56.184Z,1415077976.184 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-11-04T05:12:56.219Z,1415077976.219 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-11-04T05:12:56.244Z,1415077976.244 [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>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="StartupSatComms">

        <Sequence/>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:latitude_fix/>
        </ReadDatum>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

</Mission>


2014-11-04T05:12:56.245Z,1415077976.245 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-11-04T05:12:56.348Z,1415077976.348 [MissionManager](INFO): DefineArg Default.TimeMissionWasStarted = 0.000000 h
2014-11-04T05:12:56.368Z,1415077976.368 [MissionManager](INFO): DefineArg Default.ElapsedSinceMissionWasStarted = 0.000000 h
2014-11-04T05:12:56.372Z,1415077976.372 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-11-04T05:12:56.397Z,1415077976.397 [Default:CheckIn:A.SetSpeed](DEBUG): Construct.
2014-11-04T05:12:56.419Z,1415077976.419 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-11-04T05:12:56.437Z,1415077976.437 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-11-04T05:12:56.465Z,1415077976.465 [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="TimeMissionWasStarted"><Units:hour/><Value>0</Value></DefineArg>

    <DefineArg Name="ElapsedSinceMissionWasStarted"><Units:hour/><Value>0</Value></DefineArg>

    <Aggregate Id="StartClock">

        <Sequence/>

        <Assign><Arg Name="TimeMissionWasStarted"/><Universal:time/></Assign>

    </Aggregate>

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="CheckIn">

        <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>

<!-- TODO: Do we really want this When operating on platform_communications? or on something else like time_fix? -->

<!-- Run application at high speed -->

        <Guidance:SetSpeed>
            <Parallel/>
            <Setting><Guidance:SetSpeed.period/><Units:millisecond/><Value>400</Value></Setting>
        </Guidance:SetSpeed>

        <ReadDatum Id="Read_GPS">
            <Timeout Duration="P5M"/>
<!-- NOTE: Original Default.xml didn't have a timeout on the GPS read, so theoretically could have hung indefinitely there... -->
            <Universal:latitude_fix/>
        </ReadDatum>

<!-- Do data comms -->

        <ReadDatum Id="Read_Iridium">
            <Timeout Duration="P2H">
                <Guidance:Execute>
                    <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="UpdateAndReportMinutesSinceMissionStarted">

        <When>
            <Elapsed><Arg Name="ElapsedSinceMissionWasStarted"/></Elapsed>
            <Gt><Units:minute/><Value>5.0</Value></Gt>
        </When>

        <Assign><Arg Name="ElapsedSinceMissionWasStarted"/><Universal:time/><Sub><Arg Name="TimeMissionWasStarted"/></Sub></Assign>

        <Syslog Severity="Important">Default mission has been running for <Arg Name="ElapsedSinceMissionWasStarted"/><Units:minute/></Syslog>

    </Aggregate>

    <Aggregate Id="WaitAtTheSurface">

        <Sequence/>

        <Guidance:SetSpeed Id="RunApplicationAtLowSpeed">
            <Parallel/>
            <Setting><Guidance:SetSpeed.period/><Units:second/><Value>5</Value></Setting>
        </Guidance:SetSpeed>

    </Aggregate>

</Mission>


2014-11-04T05:12:56.485Z,1415077976.485 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,g3ESP,AHRS_sp3003D,DataOverHttps,Depth_Keller,DropWeight,Onboard,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,HFRCMReconstructedInterpolator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2014-11-04T05:12:56.579Z,1415077976.579 [g3ESP](INFO): Powering down
2014-11-04T05:12:56.648Z,1415077976.648 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-11-04T05:12:56.993Z,1415077976.993 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:12:57.094Z,1415077977.094 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-11-04T05:12:57.101Z,1415077977.101 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-11-04T05:12:57.120Z,1415077977.120 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-11-04T05:12:57.125Z,1415077977.125 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-11-04T05:12:57.139Z,1415077977.139 [MassServo](DEBUG): Initializing EZServoServo.
2014-11-04T05:12:57.145Z,1415077977.145 [MassServo](DEBUG): Initializing MassServo.
2014-11-04T05:12:57.167Z,1415077977.167 [RudderServo](DEBUG): Initializing EZServoServo.
2014-11-04T05:12:57.174Z,1415077977.174 [RudderServo](DEBUG): Initializing RudderServo.
2014-11-04T05:12:57.187Z,1415077977.187 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-11-04T05:12:57.194Z,1415077977.194 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-11-04T05:12:57.380Z,1415077977.380 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:12:57.728Z,1415077977.728 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:12:58.067Z,1415077978.067 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2014-11-04T05:12:58.067Z,1415077978.067 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2014-11-04T05:12:58.067Z,1415077978.067 [BuoyancyServo] Communications Fault, FailCount= 1
2014-11-04T05:12:58.067Z,1415077978.067 [BuoyancyServo](ERROR): Communications Fault
2014-11-04T05:12:58.273Z,1415077978.273 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2014-11-04T05:12:58.438Z,1415077978.438 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:12:58.451Z,1415077978.451 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-11-04T05:12:58.452Z,1415077978.452 [BuoyancyServo](INFO): Powering down
2014-11-04T05:12:59.031Z,1415077979.031 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:12:59.443Z,1415077979.443 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:12:59.944Z,1415077979.944 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:00.453Z,1415077980.453 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:00.896Z,1415077980.896 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:01.038Z,1415077981.038 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2014-11-04T05:13:01.038Z,1415077981.038 [BuoyancyServo] No Fault, FailCount= 1
2014-11-04T05:13:01.466Z,1415077981.466 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:01.492Z,1415077981.492 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-11-04T05:13:01.613Z,1415077981.613 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-11-04T05:13:02.348Z,1415077982.348 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:02.860Z,1415077982.860 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:03.285Z,1415077983.285 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:03.694Z,1415077983.694 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:04.155Z,1415077984.155 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:04.673Z,1415077984.673 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:05.191Z,1415077985.191 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:05.700Z,1415077985.700 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:06.238Z,1415077986.238 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:06.694Z,1415077986.694 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:07.095Z,1415077987.095 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:07.567Z,1415077987.567 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:08.048Z,1415077988.048 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:08.454Z,1415077988.454 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:08.878Z,1415077988.878 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:09.282Z,1415077989.282 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:09.703Z,1415077989.703 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:10.128Z,1415077990.128 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:10.600Z,1415077990.600 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:10.997Z,1415077990.997 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:11.441Z,1415077991.441 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:11.482Z,1415077991.482 [SBIT](IMPORTANT): Beginning Startup BIT
2014-11-04T05:13:11.485Z,1415077991.485 [CBIT](IMPORTANT): Beginning GF scan
2014-11-04T05:13:11.930Z,1415077991.930 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:12.439Z,1415077992.439 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:12.888Z,1415077992.888 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:13.333Z,1415077993.333 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:13.861Z,1415077993.861 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:14.338Z,1415077994.338 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2014-11-04T05:13:14.841Z,1415