2014-05-21T00:20:34.978Z,1400631634.978 [Supervisor](DEBUG): Initializing supervisor.
2014-05-21T00:20:34.982Z,1400631634.982 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-05-21T00:20:34.982Z,1400631634.982 [SyncHandler](INFO): Protected caller Thread ID is 776
2014-05-21T00:20:34.983Z,1400631634.983 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-05-21T00:20:34.987Z,1400631634.987 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2014-05-21T00:20:34.987Z,1400631634.987 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 777
2014-05-21T00:20:34.990Z,1400631634.990 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-05-21T00:20:35.002Z,1400631635.002 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-05-21T00:20:35.003Z,1400631635.003 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2014-05-21T00:20:35.003Z,1400631635.003 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 778
2014-05-21T00:20:35.004Z,1400631635.004 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-05-21T00:20:35.007Z,1400631635.007 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2014-05-21T00:20:35.007Z,1400631635.007 [logger ThreadHandler](INFO): Protected caller Thread ID is 779
2014-05-21T00:20:35.010Z,1400631635.010 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-05-21T00:20:35.010Z,1400631635.010 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-05-21T00:20:35.014Z,1400631635.014 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-05-21T00:20:35.413Z,1400631635.413 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-05-21T00:20:35.415Z,1400631635.415 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-05-21T00:20:35.733Z,1400631635.733 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-05-21T00:20:35.734Z,1400631635.734 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-05-21T00:20:35.831Z,1400631635.831 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-05-21T00:20:35.832Z,1400631635.832 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-05-21T00:20:36.032Z,1400631636.032 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-05-21T00:20:36.034Z,1400631636.034 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-05-21T00:20:36.218Z,1400631636.218 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-05-21T00:20:36.220Z,1400631636.220 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-05-21T00:20:36.563Z,1400631636.563 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-05-21T00:20:36.563Z,1400631636.563 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-05-21T00:20:36.763Z,1400631636.763 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-05-21T00:20:36.763Z,1400631636.763 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-05-21T00:20:37.152Z,1400631637.152 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-05-21T00:20:37.153Z,1400631637.153 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-05-21T00:20:37.267Z,1400631637.267 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-05-21T00:20:37.269Z,1400631637.269 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-05-21T00:20:37.829Z,1400631637.829 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-05-21T00:20:37.831Z,1400631637.831 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-05-21T00:20:37.956Z,1400631637.956 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-05-21T00:20:37.959Z,1400631637.959 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-05-21T00:20:38.055Z,1400631638.055 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-05-21T00:20:38.238Z,1400631638.238 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-05-21T00:20:38.238Z,1400631638.238 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-05-21T00:20:39.639Z,1400631639.639 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-05-21T00:20:39.685Z,1400631639.685 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-05-21T00:20:39.847Z,1400631639.847 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-05-21T00:20:39.849Z,1400631639.849 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-05-21T00:20:39.853Z,1400631639.853 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-05-21T00:20:39.972Z,1400631639.972 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-05-21T00:20:40.120Z,1400631640.120 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-05-21T00:20:40.229Z,1400631640.229 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-05-21T00:20:40.332Z,1400631640.332 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-05-21T00:20:40.493Z,1400631640.493 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-05-21T00:20:40.629Z,1400631640.629 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-05-21T00:20:40.727Z,1400631640.727 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-05-21T00:20:40.847Z,1400631640.847 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-05-21T00:20:40.961Z,1400631640.961 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-05-21T00:20:41.070Z,1400631641.070 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-05-21T00:20:41.170Z,1400631641.170 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-05-21T00:20:41.278Z,1400631641.278 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2014-05-21T00:20:41.284Z,1400631641.284 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-05-21T00:20:41.914Z,1400631641.914 [AHRS_sp3003D] Loaded
2014-05-21T00:20:41.914Z,1400631641.914 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-05-21T00:20:42.249Z,1400631642.249 [Batt_Ocean_Server] Loaded
2014-05-21T00:20:42.249Z,1400631642.249 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-05-21T00:20:42.267Z,1400631642.267 [Depth_Keller] Loaded
2014-05-21T00:20:42.267Z,1400631642.267 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-05-21T00:20:42.272Z,1400631642.272 [DropWeight] Loaded
2014-05-21T00:20:42.273Z,1400631642.273 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-05-21T00:20:42.433Z,1400631642.433 [DVL_micro] Loaded
2014-05-21T00:20:42.433Z,1400631642.433 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2014-05-21T00:20:42.547Z,1400631642.547 [NAL9602] Loaded
2014-05-21T00:20:42.547Z,1400631642.547 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-05-21T00:20:42.604Z,1400631642.604 [Onboard] Loaded
2014-05-21T00:20:42.604Z,1400631642.604 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-05-21T00:20:42.616Z,1400631642.616 [Radio_Freewave] Loaded
2014-05-21T00:20:42.616Z,1400631642.616 [ComponentRegistry](DEBUG): Component "Radio_Freewave" handled in its own thread.
2014-05-21T00:20:42.619Z,1400631642.619 [Radio_Freewave ThreadHandler](DEBUG): Created PCaller Thread at 406074E0
2014-05-21T00:20:42.619Z,1400631642.619 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 861
2014-05-21T00:20:42.626Z,1400631642.626 [SCPI] Loaded
2014-05-21T00:20:42.626Z,1400631642.626 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-05-21T00:20:42.627Z,1400631642.627 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-05-21T00:20:42.628Z,1400631642.628 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-05-21T00:20:42.849Z,1400631642.849 [InternalSim] Loaded
2014-05-21T00:20:42.850Z,1400631642.850 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-05-21T00:20:42.850Z,1400631642.850 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-05-21T00:20:42.855Z,1400631642.855 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-05-21T00:20:43.183Z,1400631643.183 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-05-21T00:20:43.184Z,1400631643.184 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-05-21T00:20:43.194Z,1400631643.194 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2014-05-21T00:20:43.203Z,1400631643.203 [AsyncPiEstimator] Loaded
2014-05-21T00:20:43.203Z,1400631643.203 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2014-05-21T00:20:43.204Z,1400631643.204 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406E44E0
2014-05-21T00:20:43.205Z,1400631643.205 [AsyncPiEstimator ThreadHandler](INFO): Protected caller Thread ID is 862
2014-05-21T00:20:43.205Z,1400631643.205 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-05-21T00:20:43.248Z,1400631643.248 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-05-21T00:20:43.358Z,1400631643.358 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-05-21T00:20:43.358Z,1400631643.358 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-05-21T00:20:43.404Z,1400631643.404 [DeadReckonWithRespectToWater] Loaded
2014-05-21T00:20:43.405Z,1400631643.405 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToWater" handled in the control thread.
2014-05-21T00:20:43.452Z,1400631643.452 [DeadReckonWithRespectToSeafloor] Loaded
2014-05-21T00:20:43.453Z,1400631643.453 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2014-05-21T00:20:43.506Z,1400631643.506 [DeadReckonUsingDVLWaterTrack] Loaded
2014-05-21T00:20:43.507Z,1400631643.507 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingDVLWaterTrack" handled in the control thread.
2014-05-21T00:20:43.527Z,1400631643.527 [NavChart] Loaded
2014-05-21T00:20:43.527Z,1400631643.527 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-05-21T00:20:43.532Z,1400631643.532 [UniversalFixResidualReporter] Loaded
2014-05-21T00:20:43.532Z,1400631643.532 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-05-21T00:20:43.533Z,1400631643.533 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-05-21T00:20:43.533Z,1400631643.533 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-05-21T00:20:43.615Z,1400631643.615 [VerticalControl](DEBUG): Construct VerticalControl.
2014-05-21T00:20:43.741Z,1400631643.741 [VerticalControl] Loaded
2014-05-21T00:20:43.741Z,1400631643.741 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-05-21T00:20:43.742Z,1400631643.742 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-05-21T00:20:43.817Z,1400631643.817 [HorizontalControl] Loaded
2014-05-21T00:20:43.817Z,1400631643.817 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-05-21T00:20:43.818Z,1400631643.818 [SpeedControl](DEBUG): Construct SpeedControl.
2014-05-21T00:20:43.820Z,1400631643.820 [SpeedControl] Loaded
2014-05-21T00:20:43.820Z,1400631643.820 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-05-21T00:20:43.821Z,1400631643.821 [LoopControl](DEBUG): Construct LoopControl.
2014-05-21T00:20:43.821Z,1400631643.821 [LoopControl] Loaded
2014-05-21T00:20:43.821Z,1400631643.821 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-05-21T00:20:43.822Z,1400631643.822 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-05-21T00:20:43.825Z,1400631643.825 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-05-21T00:20:43.853Z,1400631643.853 [DepthRateCalculator] Loaded
2014-05-21T00:20:43.853Z,1400631643.853 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-05-21T00:20:43.862Z,1400631643.862 [PitchRateCalculator] Loaded
2014-05-21T00:20:43.862Z,1400631643.862 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-05-21T00:20:43.870Z,1400631643.870 [SpeedCalculator] Loaded
2014-05-21T00:20:43.870Z,1400631643.870 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-05-21T00:20:43.891Z,1400631643.891 [TempGradientCalculator] Loaded
2014-05-21T00:20:43.891Z,1400631643.891 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-05-21T00:20:43.897Z,1400631643.897 [YawRateCalculator] Loaded
2014-05-21T00:20:43.897Z,1400631643.897 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-05-21T00:20:43.897Z,1400631643.897 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-05-21T00:20:43.900Z,1400631643.900 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-05-21T00:20:44.044Z,1400631644.044 [CTD_NeilBrown] Loaded
2014-05-21T00:20:44.045Z,1400631644.045 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-05-21T00:20:44.049Z,1400631644.049 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407864E0
2014-05-21T00:20:44.049Z,1400631644.049 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 863
2014-05-21T00:20:44.062Z,1400631644.062 [ISUS] Loaded
2014-05-21T00:20:44.063Z,1400631644.063 [ComponentRegistry](DEBUG): SyncComponent "ISUS" handled in the control thread.
2014-05-21T00:20:44.082Z,1400631644.082 [PAR_Licor] Loaded
2014-05-21T00:20:44.082Z,1400631644.082 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-05-21T00:20:44.123Z,1400631644.123 [WetLabsBB2FL] Loaded
2014-05-21T00:20:44.124Z,1400631644.124 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-05-21T00:20:44.125Z,1400631644.125 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407B64E0
2014-05-21T00:20:44.125Z,1400631644.125 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 864
2014-05-21T00:20:44.126Z,1400631644.126 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-05-21T00:20:44.127Z,1400631644.127 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-05-21T00:20:44.264Z,1400631644.264 [SBIT](DEBUG): Construct Startup Built In Test.
2014-05-21T00:20:44.276Z,1400631644.276 [SBIT] Loaded
2014-05-21T00:20:44.276Z,1400631644.276 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-05-21T00:20:44.277Z,1400631644.277 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-05-21T00:20:44.290Z,1400631644.290 [IBIT] Loaded
2014-05-21T00:20:44.291Z,1400631644.291 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-05-21T00:20:44.293Z,1400631644.293 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-05-21T00:20:44.372Z,1400631644.372 [CBIT] Loaded
2014-05-21T00:20:44.372Z,1400631644.372 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-05-21T00:20:44.373Z,1400631644.373 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-05-21T00:20:44.378Z,1400631644.378 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-05-21T00:20:44.455Z,1400631644.455 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-05-21T00:20:44.457Z,1400631644.457 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-05-21T00:20:44.597Z,1400631644.597 [BuoyancyServo] Loaded
2014-05-21T00:20:44.597Z,1400631644.597 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-05-21T00:20:44.609Z,1400631644.609 [ElevatorServo] Loaded
2014-05-21T00:20:44.610Z,1400631644.610 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-05-21T00:20:44.622Z,1400631644.622 [MassServo] Loaded
2014-05-21T00:20:44.622Z,1400631644.622 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-05-21T00:20:44.638Z,1400631644.638 [RudderServo] Loaded
2014-05-21T00:20:44.639Z,1400631644.639 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-05-21T00:20:44.651Z,1400631644.651 [ThrusterServo] Loaded
2014-05-21T00:20:44.651Z,1400631644.651 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-05-21T00:20:44.651Z,1400631644.651 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-05-21T00:20:44.652Z,1400631644.652 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-05-21T00:20:44.693Z,1400631644.693 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-05-21T00:20:44.699Z,1400631644.699 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-05-21T00:20:44.700Z,1400631644.700 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-05-21T00:20:44.706Z,1400631644.706 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-05-21T00:20:44.710Z,1400631644.710 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 408854E0
2014-05-21T00:20:44.710Z,1400631644.710 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 865
2014-05-21T00:20:44.715Z,1400631644.715 [Supervisor](INFO): Main Thread ID is 767
2014-05-21T00:20:44.715Z,1400631644.715 [Supervisor](DEBUG): Running supervisor.
2014-05-21T00:20:44.716Z,1400631644.716 [CommandLine ThreadHandler](INFO): Handler Thread ID is 866
2014-05-21T00:20:44.722Z,1400631644.722 [controlThread ThreadHandler](INFO): Handler Thread ID is 867
2014-05-21T00:20:44.723Z,1400631644.723 [controlThread](DEBUG): Initializing ControlThread
2014-05-21T00:20:44.726Z,1400631644.726 [logger ThreadHandler](INFO): Handler Thread ID is 868
2014-05-21T00:20:44.763Z,1400631644.763 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 869
2014-05-21T00:20:44.775Z,1400631644.775 [AsyncPiEstimator ThreadHandler](INFO): Handler Thread ID is 870
2014-05-21T00:20:44.775Z,1400631644.775 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2014-05-21T00:20:44.799Z,1400631644.799 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 871
2014-05-21T00:20:44.799Z,1400631644.799 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-05-21T00:20:44.806Z,1400631644.806 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-05-21T00:20:44.816Z,1400631644.816 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 873
2014-05-21T00:20:44.817Z,1400631644.817 [WetLabsBB2FL](INFO): Powering down
2014-05-21T00:20:44.843Z,1400631644.843 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 874
2014-05-21T00:20:44.879Z,1400631644.879 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-05-21T00:20:44.881Z,1400631644.881 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-05-21T00:20:44.881Z,1400631644.881 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-05-21T00:20:44.881Z,1400631644.881 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-05-21T00:20:44.882Z,1400631644.882 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-05-21T00:20:44.882Z,1400631644.882 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-05-21T00:20:44.882Z,1400631644.882 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-05-21T00:20:44.883Z,1400631644.883 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-05-21T00:20:44.883Z,1400631644.883 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-05-21T00:20:46.720Z,1400631646.720 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-05-21T00:20:46.751Z,1400631646.751 [DropWeight](CRITICAL): DROP WEIGHT MISSING.
2014-05-21T00:20:46.751Z,1400631646.751 [DropWeight] Hardware Fault, FailCount= 1
2014-05-21T00:20:46.751Z,1400631646.751 [DropWeight](ERROR): Hardware Fault
2014-05-21T00:20:46.752Z,1400631646.752 [InternalSim](DEBUG): InternalSim initializing...
2014-05-21T00:20:47.177Z,1400631647.177 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-05-21T00:20:47.203Z,1400631647.203 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component.
2014-05-21T00:20:47.226Z,1400631647.226 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component.
2014-05-21T00:20:47.227Z,1400631647.227 [DeadReckonUsingDVLWaterTrack](DEBUG): Initializing DeadReckonUsingDVLWaterTrack component.
2014-05-21T00:20:47.227Z,1400631647.227 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-05-21T00:20:47.228Z,1400631647.228 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-05-21T00:20:47.228Z,1400631647.228 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-05-21T00:20:47.231Z,1400631647.231 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-05-21T00:20:47.232Z,1400631647.232 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-05-21T00:20:47.232Z,1400631647.232 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-05-21T00:20:47.233Z,1400631647.233 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-05-21T00:20:47.233Z,1400631647.233 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-05-21T00:20:47.258Z,1400631647.258 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-05-21T00:20:47.258Z,1400631647.258 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-05-21T00:20:47.259Z,1400631647.259 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-05-21T00:20:47.262Z,1400631647.262 [SBIT](INFO): Initialize SBIT Component.
2014-05-21T00:20:47.263Z,1400631647.263 [SBIT](IMPORTANT): Tethys CM Info:
$Rev:11288
2014-05-21T00:20:47.263Z,1400631647.263 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2014-05-21T00:20:47.264Z,1400631647.264 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-05-21T00:20:47.264Z,1400631647.264 [IBIT](INFO): Initialize IBIT Component.
2014-05-21T00:20:47.265Z,1400631647.265 [CBIT](DEBUG): Initialize CBIT Component.
2014-05-21T00:20:47.278Z,1400631647.278 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2014-05-21T00:20:47.304Z,1400631647.304 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-05-21T00:20:47.328Z,1400631647.328 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-21T00:20:47.361Z,1400631647.361 [MissionManager](DEBUG):
2014-05-21T00:20:47.362Z,1400631647.362 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-05-21T00:20:47.453Z,1400631647.453 [Radio_Freewave](INFO): Powering up
2014-05-21T00:20:47.475Z,1400631647.475 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2014-05-21T00:20:47.478Z,1400631647.478 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2014-05-21T00:20:47.497Z,1400631647.497 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-21T00:20:47.514Z,1400631647.514 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2014-05-21T00:20:47.533Z,1400631647.533 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-21T00:20:47.540Z,1400631647.540 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-05-21T00:20:47.590Z,1400631647.590 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-05-21T00:20:47.594Z,1400631647.594 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-21T00:20:47.617Z,1400631647.617 [MissionManager](DEBUG):
400
400
Burn 300
Dropped drop weight due to communications timeout
5.0
1.0
5
2014-05-21T00:20:47.623Z,1400631647.623 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,SCPI,ISUS,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,DeadReckonUsingMultipleVelocitySources,DeadReckonWithRespectToWater,DeadReckonWithRespectToSeafloor,DeadReckonUsingDVLWaterTrack,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2014-05-21T00:20:47.711Z,1400631647.711 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-05-21T00:20:47.899Z,1400631647.899 [DVL_micro](INFO): Initializing
2014-05-21T00:20:47.925Z,1400631647.925 [NAL9602](INFO): Powering up NAL9602
2014-05-21T00:20:48.257Z,1400631648.257 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0
2014-05-21T00:20:48.721Z,1400631648.721 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-05-21T00:20:48.733Z,1400631648.733 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-05-21T00:20:48.739Z,1400631648.739 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-05-21T00:20:48.749Z,1400631648.749 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-05-21T00:20:48.763Z,1400631648.763 [MassServo](DEBUG): Initializing EZServoServo.
2014-05-21T00:20:48.769Z,1400631648.769 [MassServo](DEBUG): Initializing MassServo.
2014-05-21T00:20:48.795Z,1400631648.795 [RudderServo](DEBUG): Initializing EZServoServo.
2014-05-21T00:20:48.801Z,1400631648.801 [RudderServo](DEBUG): Initializing RudderServo.
2014-05-21T00:20:48.806Z,1400631648.806 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-05-21T00:20:48.813Z,1400631648.813 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-05-21T00:20:48.861Z,1400631648.861 [CommandLine](FAULT): Scheduling is paused
2014-05-21T00:20:48.863Z,1400631648.863 [CBIT](ERROR): Hardware Fault in component: DropWeight
2014-05-21T00:20:48.863Z,1400631648.863 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2014-05-21T00:20:49.670Z,1400631649.670 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2014-05-21T00:20:49.670Z,1400631649.670 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2014-05-21T00:20:49.670Z,1400631649.670 [BuoyancyServo] Communications Fault, FailCount= 1
2014-05-21T00:20:49.670Z,1400631649.670 [BuoyancyServo](ERROR): Communications Fault
2014-05-21T00:20:49.904Z,1400631649.904 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2014-05-21T00:20:50.337Z,1400631650.337 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-05-21T00:20:50.338Z,1400631650.338 [BuoyancyServo](INFO): Powering down
2014-05-21T00:20:52.677Z,1400631652.677 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2014-05-21T00:20:52.677Z,1400631652.677 [BuoyancyServo] No Fault, FailCount= 1
2014-05-21T00:20:53.097Z,1400631653.097 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-05-21T00:20:53.216Z,1400631653.216 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-05-21T00:20:58.969Z,1400631658.969 [NAL9602](INFO): NAL9602 initialized
2014-05-21T00:21:03.121Z,1400631663.121 [SBIT](IMPORTANT): Beginning Startup BIT
2014-05-21T00:21:03.124Z,1400631663.124 [CBIT](IMPORTANT): Beginning GF scan
2014-05-21T00:21:29.892Z,1400631689.892 [CBIT](IMPORTANT): No ground fault detected
2014-05-21T00:21:57.346Z,1400631717.346 [SBIT](IMPORTANT): SBIT PASSED
2014-05-21T00:21:57.740Z,1400631717.740 [MissionManager](IMPORTANT): Started mission Startup
2014-05-21T00:21:57.740Z,1400631717.740 [Startup] Running Loop=1
2014-05-21T00:21:57.740Z,1400631717.740 [Startup](INFO): Aggregate::initialize Startup
2014-05-21T00:21:57.741Z,1400631717.741 [Startup:A.GoToSurface] Running Loop=1
2014-05-21T00:21:57.741Z,1400631717.741 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-21T00:21:57.747Z,1400631717.747 [Startup:StartupSatComms] Running Loop=1
2014-05-21T00:21:57.747Z,1400631717.747 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-05-21T00:21:57.747Z,1400631717.747 [Startup:StartupSatComms:A] Running Loop=1
2014-05-21T00:21:58.145Z,1400631718.145 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-05-21T00:22:58.066Z,1400631778.066 [Startup:StartupSatComms:A](INFO): Timed out from 2014-05-21T00:21:57.7Z
2014-05-21T00:22:58.067Z,1400631778.067 [Startup:StartupSatComms:A] Stopped
2014-05-21T00:22:58.067Z,1400631778.067 [Startup:StartupSatComms:B] Running Loop=1
2014-05-21T00:22:58.473Z,1400631778.473 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-05-21T00:23:53.184Z,1400631833.184 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-21T00:23:53.184Z,1400631833.184 [DVL_micro] Data Fault, FailCount= 1
2014-05-21T00:23:53.184Z,1400631833.184 [DVL_micro](ERROR): Data Fault
2014-05-21T00:23:53.240Z,1400631833.240 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-21T00:23:53.588Z,1400631833.588 [DVL_micro](INFO): uninitialize:Powering down
2014-05-21T00:23:53.997Z,1400631833.997 [DVL_micro](FAULT): LCB fault: Software Overcurrent.
2014-05-21T00:23:53.997Z,1400631833.997 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-21T00:23:53.997Z,1400631833.997 [DVL_micro](ERROR): Hardware Fault
2014-05-21T00:23:54.404Z,1400631834.404 [DVL_micro](INFO): Initializing
2014-05-21T00:23:54.462Z,1400631834.462 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-21T00:23:54.462Z,1400631834.462 [DVL_micro] No Fault, FailCount= 1
2014-05-21T00:23:58.198Z,1400631838.198 [Startup:StartupSatComms:B](INFO): Timed out from 2014-05-21T00:22:58.1Z
2014-05-21T00:23:58.198Z,1400631838.198 [Startup:StartupSatComms:B] Stopped
2014-05-21T00:23:58.199Z,1400631838.199 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2014-05-21T00:23:58.199Z,1400631838.199 [Startup:StartupSatComms] Stopped
2014-05-21T00:23:58.199Z,1400631838.199 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2014-05-21T00:23:58.200Z,1400631838.200 [Startup](INFO): Completed Startup
2014-05-21T00:23:58.200Z,1400631838.200 [Startup] Stopped
2014-05-21T00:23:58.200Z,1400631838.200 [Startup](INFO): Aggregate::uninitialize Startup
2014-05-21T00:23:58.200Z,1400631838.200 [Startup:A.GoToSurface] Stopped
2014-05-21T00:23:58.200Z,1400631838.200 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-21T00:23:58.609Z,1400631838.609 [MissionManager](IMPORTANT): Started mission Default
2014-05-21T00:23:58.610Z,1400631838.610 [Default] Running Loop=1
2014-05-21T00:23:58.610Z,1400631838.610 [Default](INFO): Aggregate::initialize Default
2014-05-21T00:23:58.610Z,1400631838.610 [Default:Iridium] Running Loop=1
2014-05-21T00:23:58.610Z,1400631838.610 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-05-21T00:23:58.610Z,1400631838.610 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-05-21T00:23:58.610Z,1400631838.610 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-05-21T00:23:58.610Z,1400631838.610 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-05-21T00:23:58.610Z,1400631838.610 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-21T00:23:58.611Z,1400631838.611 [Default:CallIridium] Running Loop=1
2014-05-21T00:23:58.611Z,1400631838.611 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-05-21T00:23:58.611Z,1400631838.611 [Default:CallIridium:A] Running Loop=1
2014-05-21T00:23:58.613Z,1400631838.613 [Default:CallIridium:A] Stopped
2014-05-21T00:23:58.613Z,1400631838.613 [Default:CallIridium:B] Running Loop=1
2014-05-21T00:23:58.614Z,1400631838.614 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-05-21T00:23:58.619Z,1400631838.619 [Default:Iridium:B.GoToSurface] Stopped
2014-05-21T00:23:58.619Z,1400631838.619 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-21T00:23:58.619Z,1400631838.619 [Default:Iridium:Read_Iridium] Running Loop=1
2014-05-21T00:23:58.619Z,1400631838.619 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-05-21T00:23:58.625Z,1400631838.625 [Default:GPS] Running Loop=1
2014-05-21T00:23:58.625Z,1400631838.625 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-05-21T00:23:58.625Z,1400631838.625 [Default:GPS:A.SetSpeed] Running Loop=1
2014-05-21T00:23:58.625Z,1400631838.625 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-05-21T00:23:58.625Z,1400631838.625 [Default:GPS:B.GoToSurface] Running Loop=1
2014-05-21T00:23:58.625Z,1400631838.625 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-21T00:23:58.660Z,1400631838.660 [Default:GPS:B.GoToSurface] Stopped
2014-05-21T00:23:58.660Z,1400631838.660 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-21T00:23:58.660Z,1400631838.660 [Default:GPS:Read_GPS] Running Loop=1
2014-05-21T00:23:58.660Z,1400631838.660 [Default:GPS:A.SetSpeed] Running Loop=1
2014-05-21T00:23:59.068Z,1400631839.068 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-05-21T00:23:59.072Z,1400631839.072 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-05-21T00:25:46.890Z,1400631946.890 [CBIT](INFO): Clearing failed count for component DropWeight
2014-05-21T00:25:46.890Z,1400631946.890 [DropWeight] No Fault, FailCount= 1
2014-05-21T00:25:47.260Z,1400631947.260 [DropWeight](CRITICAL): DROP WEIGHT MISSING.
2014-05-21T00:25:47.260Z,1400631947.260 [DropWeight] Hardware Fault, FailCount= 1
2014-05-21T00:25:47.260Z,1400631947.260 [DropWeight](ERROR): Hardware Fault
2014-05-21T00:25:47.288Z,1400631947.288 [CBIT](ERROR): Hardware Fault in component: DropWeight
2014-05-21T00:25:47.289Z,1400631947.289 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2014-05-21T00:26:02.716Z,1400631962.716 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2014-05-21T00:26:36.164Z,1400631996.164 [NAL9602](FAULT): Queried for signal strength and failed to receive proper response. no error
2014-05-21T00:26:36.239Z,1400631996.239 [NAL9602](ERROR): received:
+CSQ:0
OK: Started
2014-05-21T00:26:36.239Z,1400631996.239 [NAL9602] Data Fault, FailCount= 1
2014-05-21T00:26:36.239Z,1400631996.239 [NAL9602](ERROR): Data Fault
2014-05-21T00:26:36.300Z,1400631996.300 [CBIT](ERROR): Data Fault in component: NAL9602
2014-05-21T00:26:36.637Z,1400631996.637 [NAL9602](INFO): Powering down
2014-05-21T00:26:37.506Z,1400631997.506 [CBIT](INFO): Clearing failed state for component NAL9602
2014-05-21T00:26:37.506Z,1400631997.506 [NAL9602] No Fault, FailCount= 1
2014-05-21T00:26:41.730Z,1400632001.730 [NAL9602](INFO): Powering up NAL9602
2014-05-21T00:26:52.244Z,1400632012.244 [NAL9602](INFO): NAL9602 initialized
2014-05-21T00:26:58.567Z,1400632018.567 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-21T00:26:58.567Z,1400632018.567 [DVL_micro] Data Fault, FailCount= 1
2014-05-21T00:26:58.567Z,1400632018.567 [DVL_micro](ERROR): Data Fault
2014-05-21T00:26:58.636Z,1400632018.636 [CBIT](ERROR): Data Fault in component: DVL_m