2014-05-21T00:12:20.050Z,1400631140.050 [Supervisor](DEBUG): Initializing supervisor.
2014-05-21T00:12:20.054Z,1400631140.054 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-05-21T00:12:20.055Z,1400631140.055 [SyncHandler](INFO): Protected caller Thread ID is 776
2014-05-21T00:12:20.055Z,1400631140.055 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-05-21T00:12:20.058Z,1400631140.058 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2014-05-21T00:12:20.058Z,1400631140.058 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 777
2014-05-21T00:12:20.061Z,1400631140.061 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-05-21T00:12:20.072Z,1400631140.072 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-05-21T00:12:20.074Z,1400631140.074 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2014-05-21T00:12:20.074Z,1400631140.074 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 778
2014-05-21T00:12:20.075Z,1400631140.075 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-05-21T00:12:20.078Z,1400631140.078 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2014-05-21T00:12:20.078Z,1400631140.078 [logger ThreadHandler](INFO): Protected caller Thread ID is 779
2014-05-21T00:12:20.081Z,1400631140.081 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-05-21T00:12:20.081Z,1400631140.081 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-05-21T00:12:20.086Z,1400631140.086 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-05-21T00:12:20.470Z,1400631140.470 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-05-21T00:12:20.472Z,1400631140.472 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-05-21T00:12:20.784Z,1400631140.784 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-05-21T00:12:20.785Z,1400631140.785 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-05-21T00:12:20.879Z,1400631140.879 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-05-21T00:12:20.879Z,1400631140.879 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-05-21T00:12:21.077Z,1400631141.077 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-05-21T00:12:21.079Z,1400631141.079 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-05-21T00:12:21.261Z,1400631141.261 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-05-21T00:12:21.263Z,1400631141.263 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-05-21T00:12:21.598Z,1400631141.598 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-05-21T00:12:21.598Z,1400631141.598 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-05-21T00:12:21.803Z,1400631141.803 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-05-21T00:12:21.803Z,1400631141.803 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-05-21T00:12:23.613Z,1400631143.613 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-05-21T00:12:23.614Z,1400631143.614 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-05-21T00:12:23.729Z,1400631143.729 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-05-21T00:12:23.731Z,1400631143.731 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-05-21T00:12:24.278Z,1400631144.278 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-05-21T00:12:24.280Z,1400631144.280 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-05-21T00:12:24.406Z,1400631144.406 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-05-21T00:12:24.408Z,1400631144.408 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-05-21T00:12:24.505Z,1400631144.505 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-05-21T00:12:24.626Z,1400631144.626 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-05-21T00:12:24.627Z,1400631144.627 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-05-21T00:12:24.742Z,1400631144.742 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-05-21T00:12:24.745Z,1400631144.745 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-05-21T00:12:24.903Z,1400631144.903 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-05-21T00:12:24.905Z,1400631144.905 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-05-21T00:12:24.909Z,1400631144.909 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-05-21T00:12:25.027Z,1400631145.027 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-05-21T00:12:25.175Z,1400631145.175 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-05-21T00:12:25.284Z,1400631145.284 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-05-21T00:12:25.388Z,1400631145.388 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-05-21T00:12:25.544Z,1400631145.544 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-05-21T00:12:25.676Z,1400631145.676 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-05-21T00:12:25.775Z,1400631145.775 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-05-21T00:12:25.890Z,1400631145.890 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-05-21T00:12:26.009Z,1400631146.009 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-05-21T00:12:26.117Z,1400631146.117 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-05-21T00:12:26.217Z,1400631146.217 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-05-21T00:12:26.325Z,1400631146.325 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2014-05-21T00:12:26.342Z,1400631146.342 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-05-21T00:12:26.962Z,1400631146.962 [AHRS_sp3003D] Loaded
2014-05-21T00:12:26.963Z,1400631146.963 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-05-21T00:12:27.290Z,1400631147.290 [Batt_Ocean_Server] Loaded
2014-05-21T00:12:27.291Z,1400631147.291 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-05-21T00:12:27.308Z,1400631147.308 [Depth_Keller] Loaded
2014-05-21T00:12:27.308Z,1400631147.308 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-05-21T00:12:27.461Z,1400631147.461 [DVL_micro] Loaded
2014-05-21T00:12:27.461Z,1400631147.461 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2014-05-21T00:12:27.573Z,1400631147.573 [NAL9602] Loaded
2014-05-21T00:12:27.573Z,1400631147.573 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-05-21T00:12:27.634Z,1400631147.634 [Onboard] Loaded
2014-05-21T00:12:27.634Z,1400631147.634 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-05-21T00:12:27.641Z,1400631147.641 [Radio_Freewave] Loaded
2014-05-21T00:12:27.641Z,1400631147.641 [ComponentRegistry](DEBUG): Component "Radio_Freewave" handled in its own thread.
2014-05-21T00:12:27.646Z,1400631147.646 [Radio_Freewave ThreadHandler](DEBUG): Created PCaller Thread at 406074E0
2014-05-21T00:12:27.646Z,1400631147.646 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 861
2014-05-21T00:12:27.653Z,1400631147.653 [SCPI] Loaded
2014-05-21T00:12:27.653Z,1400631147.653 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-05-21T00:12:27.654Z,1400631147.654 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-05-21T00:12:27.655Z,1400631147.655 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-05-21T00:12:27.872Z,1400631147.872 [InternalSim] Loaded
2014-05-21T00:12:27.873Z,1400631147.873 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-05-21T00:12:27.873Z,1400631147.873 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-05-21T00:12:27.875Z,1400631147.875 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-05-21T00:12:28.189Z,1400631148.189 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-05-21T00:12:28.190Z,1400631148.190 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-05-21T00:12:28.199Z,1400631148.199 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2014-05-21T00:12:28.204Z,1400631148.204 [AsyncPiEstimator] Loaded
2014-05-21T00:12:28.204Z,1400631148.204 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2014-05-21T00:12:28.207Z,1400631148.207 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406E44E0
2014-05-21T00:12:28.207Z,1400631148.207 [AsyncPiEstimator ThreadHandler](INFO): Protected caller Thread ID is 862
2014-05-21T00:12:28.208Z,1400631148.208 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-05-21T00:12:28.210Z,1400631148.210 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-05-21T00:12:28.309Z,1400631148.309 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-05-21T00:12:28.310Z,1400631148.310 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-05-21T00:12:28.355Z,1400631148.355 [DeadReckonWithRespectToWater] Loaded
2014-05-21T00:12:28.355Z,1400631148.355 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToWater" handled in the control thread.
2014-05-21T00:12:28.405Z,1400631148.405 [DeadReckonWithRespectToSeafloor] Loaded
2014-05-21T00:12:28.405Z,1400631148.405 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2014-05-21T00:12:28.457Z,1400631148.457 [DeadReckonUsingDVLWaterTrack] Loaded
2014-05-21T00:12:28.458Z,1400631148.458 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingDVLWaterTrack" handled in the control thread.
2014-05-21T00:12:28.478Z,1400631148.478 [NavChart] Loaded
2014-05-21T00:12:28.478Z,1400631148.478 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-05-21T00:12:28.482Z,1400631148.482 [UniversalFixResidualReporter] Loaded
2014-05-21T00:12:28.483Z,1400631148.483 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-05-21T00:12:28.483Z,1400631148.483 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-05-21T00:12:28.484Z,1400631148.484 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-05-21T00:12:28.609Z,1400631148.609 [VerticalControl](DEBUG): Construct VerticalControl.
2014-05-21T00:12:28.731Z,1400631148.731 [VerticalControl] Loaded
2014-05-21T00:12:28.732Z,1400631148.732 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-05-21T00:12:28.732Z,1400631148.732 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-05-21T00:12:28.816Z,1400631148.816 [HorizontalControl] Loaded
2014-05-21T00:12:28.817Z,1400631148.817 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-05-21T00:12:28.817Z,1400631148.817 [SpeedControl](DEBUG): Construct SpeedControl.
2014-05-21T00:12:28.819Z,1400631148.819 [SpeedControl] Loaded
2014-05-21T00:12:28.820Z,1400631148.820 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-05-21T00:12:28.820Z,1400631148.820 [LoopControl](DEBUG): Construct LoopControl.
2014-05-21T00:12:28.821Z,1400631148.821 [LoopControl] Loaded
2014-05-21T00:12:28.821Z,1400631148.821 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-05-21T00:12:28.822Z,1400631148.822 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-05-21T00:12:28.828Z,1400631148.828 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-05-21T00:12:28.855Z,1400631148.855 [DepthRateCalculator] Loaded
2014-05-21T00:12:28.856Z,1400631148.856 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-05-21T00:12:28.864Z,1400631148.864 [PitchRateCalculator] Loaded
2014-05-21T00:12:28.865Z,1400631148.865 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-05-21T00:12:28.872Z,1400631148.872 [SpeedCalculator] Loaded
2014-05-21T00:12:28.872Z,1400631148.872 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-05-21T00:12:28.893Z,1400631148.893 [TempGradientCalculator] Loaded
2014-05-21T00:12:28.893Z,1400631148.893 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-05-21T00:12:28.898Z,1400631148.898 [YawRateCalculator] Loaded
2014-05-21T00:12:28.898Z,1400631148.898 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-05-21T00:12:28.899Z,1400631148.899 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-05-21T00:12:28.901Z,1400631148.901 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-05-21T00:12:29.039Z,1400631149.039 [CTD_NeilBrown] Loaded
2014-05-21T00:12:29.040Z,1400631149.040 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-05-21T00:12:29.044Z,1400631149.044 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407864E0
2014-05-21T00:12:29.044Z,1400631149.044 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 863
2014-05-21T00:12:29.057Z,1400631149.057 [ISUS] Loaded
2014-05-21T00:12:29.057Z,1400631149.057 [ComponentRegistry](DEBUG): SyncComponent "ISUS" handled in the control thread.
2014-05-21T00:12:29.077Z,1400631149.077 [PAR_Licor] Loaded
2014-05-21T00:12:29.077Z,1400631149.077 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-05-21T00:12:29.116Z,1400631149.116 [WetLabsBB2FL] Loaded
2014-05-21T00:12:29.117Z,1400631149.117 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-05-21T00:12:29.120Z,1400631149.120 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407B64E0
2014-05-21T00:12:29.120Z,1400631149.120 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 864
2014-05-21T00:12:29.121Z,1400631149.121 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-05-21T00:12:29.122Z,1400631149.122 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-05-21T00:12:29.255Z,1400631149.255 [SBIT](DEBUG): Construct Startup Built In Test.
2014-05-21T00:12:29.266Z,1400631149.266 [SBIT] Loaded
2014-05-21T00:12:29.267Z,1400631149.267 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-05-21T00:12:29.267Z,1400631149.267 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-05-21T00:12:29.280Z,1400631149.280 [IBIT] Loaded
2014-05-21T00:12:29.280Z,1400631149.280 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-05-21T00:12:29.282Z,1400631149.282 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-05-21T00:12:29.359Z,1400631149.359 [CBIT] Loaded
2014-05-21T00:12:29.360Z,1400631149.360 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-05-21T00:12:29.360Z,1400631149.360 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-05-21T00:12:29.365Z,1400631149.365 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-05-21T00:12:29.441Z,1400631149.441 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-05-21T00:12:29.443Z,1400631149.443 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-05-21T00:12:29.578Z,1400631149.578 [BuoyancyServo] Loaded
2014-05-21T00:12:29.579Z,1400631149.579 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-05-21T00:12:29.595Z,1400631149.595 [ElevatorServo] Loaded
2014-05-21T00:12:29.595Z,1400631149.595 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-05-21T00:12:29.607Z,1400631149.607 [MassServo] Loaded
2014-05-21T00:12:29.607Z,1400631149.607 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-05-21T00:12:29.619Z,1400631149.619 [RudderServo] Loaded
2014-05-21T00:12:29.619Z,1400631149.619 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-05-21T00:12:29.635Z,1400631149.635 [ThrusterServo] Loaded
2014-05-21T00:12:29.635Z,1400631149.635 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-05-21T00:12:29.636Z,1400631149.636 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-05-21T00:12:29.636Z,1400631149.636 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-05-21T00:12:29.680Z,1400631149.680 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-05-21T00:12:29.682Z,1400631149.682 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-05-21T00:12:29.683Z,1400631149.683 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-05-21T00:12:29.689Z,1400631149.689 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-05-21T00:12:29.693Z,1400631149.693 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 408854E0
2014-05-21T00:12:29.693Z,1400631149.693 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 865
2014-05-21T00:12:29.698Z,1400631149.698 [Supervisor](INFO): Main Thread ID is 767
2014-05-21T00:12:29.698Z,1400631149.698 [Supervisor](DEBUG): Running supervisor.
2014-05-21T00:12:29.699Z,1400631149.699 [CommandLine ThreadHandler](INFO): Handler Thread ID is 866
2014-05-21T00:12:29.706Z,1400631149.706 [controlThread ThreadHandler](INFO): Handler Thread ID is 867
2014-05-21T00:12:29.706Z,1400631149.706 [controlThread](DEBUG): Initializing ControlThread
2014-05-21T00:12:29.710Z,1400631149.710 [logger ThreadHandler](INFO): Handler Thread ID is 868
2014-05-21T00:12:29.746Z,1400631149.746 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 869
2014-05-21T00:12:29.758Z,1400631149.758 [AsyncPiEstimator ThreadHandler](INFO): Handler Thread ID is 870
2014-05-21T00:12:29.758Z,1400631149.758 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2014-05-21T00:12:29.782Z,1400631149.782 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 871
2014-05-21T00:12:29.782Z,1400631149.782 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-05-21T00:12:29.790Z,1400631149.790 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-05-21T00:12:29.799Z,1400631149.799 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 873
2014-05-21T00:12:29.800Z,1400631149.800 [WetLabsBB2FL](INFO): Powering down
2014-05-21T00:12:29.830Z,1400631149.830 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 874
2014-05-21T00:12:29.861Z,1400631149.861 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-05-21T00:12:29.866Z,1400631149.866 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-05-21T00:12:29.866Z,1400631149.866 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-05-21T00:12:29.866Z,1400631149.866 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-05-21T00:12:29.867Z,1400631149.867 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-05-21T00:12:29.867Z,1400631149.867 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-05-21T00:12:29.867Z,1400631149.867 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-05-21T00:12:29.867Z,1400631149.867 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-05-21T00:12:29.868Z,1400631149.868 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-05-21T00:12:31.559Z,1400631151.559 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-05-21T00:12:31.589Z,1400631151.589 [InternalSim](DEBUG): InternalSim initializing...
2014-05-21T00:12:32.033Z,1400631152.033 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-05-21T00:12:32.033Z,1400631152.033 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component.
2014-05-21T00:12:32.034Z,1400631152.034 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component.
2014-05-21T00:12:32.034Z,1400631152.034 [DeadReckonUsingDVLWaterTrack](DEBUG): Initializing DeadReckonUsingDVLWaterTrack component.
2014-05-21T00:12:32.034Z,1400631152.034 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-05-21T00:12:32.035Z,1400631152.035 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-05-21T00:12:32.035Z,1400631152.035 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-05-21T00:12:32.041Z,1400631152.041 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-05-21T00:12:32.042Z,1400631152.042 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-05-21T00:12:32.042Z,1400631152.042 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-05-21T00:12:32.042Z,1400631152.042 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-05-21T00:12:32.043Z,1400631152.043 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-05-21T00:12:32.043Z,1400631152.043 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-05-21T00:12:32.043Z,1400631152.043 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-05-21T00:12:32.044Z,1400631152.044 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-05-21T00:12:32.069Z,1400631152.069 [SBIT](INFO): Initialize SBIT Component.
2014-05-21T00:12:32.069Z,1400631152.069 [SBIT](IMPORTANT): Tethys CM Info:
$Rev:11288
2014-05-21T00:12:32.070Z,1400631152.070 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2014-05-21T00:12:32.070Z,1400631152.070 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-05-21T00:12:32.071Z,1400631152.071 [IBIT](INFO): Initialize IBIT Component.
2014-05-21T00:12:32.071Z,1400631152.071 [CBIT](DEBUG): Initialize CBIT Component.
2014-05-21T00:12:32.072Z,1400631152.072 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2014-05-21T00:12:32.099Z,1400631152.099 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-05-21T00:12:32.122Z,1400631152.122 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-21T00:12:32.131Z,1400631152.131 [MissionManager](DEBUG):
2014-05-21T00:12:32.132Z,1400631152.132 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-05-21T00:12:32.265Z,1400631152.265 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2014-05-21T00:12:32.267Z,1400631152.267 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2014-05-21T00:12:32.299Z,1400631152.299 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-21T00:12:32.335Z,1400631152.335 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2014-05-21T00:12:32.339Z,1400631152.339 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-21T00:12:32.363Z,1400631152.363 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-05-21T00:12:32.420Z,1400631152.420 [Radio_Freewave](INFO): Powering up
2014-05-21T00:12:32.438Z,1400631152.438 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-05-21T00:12:32.441Z,1400631152.441 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-21T00:12:32.448Z,1400631152.448 [MissionManager](DEBUG):
400
400
Burn 300
Dropped drop weight due to communications timeout
5.0
1.0
5
2014-05-21T00:12:32.466Z,1400631152.466 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,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:12:32.594Z,1400631152.594 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-05-21T00:12:32.771Z,1400631152.771 [DVL_micro](INFO): Initializing
2014-05-21T00:12:32.796Z,1400631152.796 [NAL9602](INFO): Powering up NAL9602
2014-05-21T00:12:33.224Z,1400631153.224 [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:12:33.276Z,1400631153.276 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-05-21T00:12:33.287Z,1400631153.287 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-05-21T00:12:33.314Z,1400631153.314 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-05-21T00:12:33.327Z,1400631153.327 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-05-21T00:12:33.341Z,1400631153.341 [MassServo](DEBUG): Initializing EZServoServo.
2014-05-21T00:12:33.348Z,1400631153.348 [MassServo](DEBUG): Initializing MassServo.
2014-05-21T00:12:33.366Z,1400631153.366 [RudderServo](DEBUG): Initializing EZServoServo.
2014-05-21T00:12:33.371Z,1400631153.371 [RudderServo](DEBUG): Initializing RudderServo.
2014-05-21T00:12:33.397Z,1400631153.397 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-05-21T00:12:33.403Z,1400631153.403 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-05-21T00:12:34.264Z,1400631154.264 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2014-05-21T00:12:34.264Z,1400631154.264 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2014-05-21T00:12:34.264Z,1400631154.264 [BuoyancyServo] Communications Fault, FailCount= 1
2014-05-21T00:12:34.264Z,1400631154.264 [BuoyancyServo](ERROR): Communications Fault
2014-05-21T00:12:34.467Z,1400631154.467 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2014-05-21T00:12:34.939Z,1400631154.939 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-05-21T00:12:34.940Z,1400631154.940 [BuoyancyServo](INFO): Powering down
2014-05-21T00:12:37.235Z,1400631157.235 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2014-05-21T00:12:37.236Z,1400631157.236 [BuoyancyServo] No Fault, FailCount= 1
2014-05-21T00:12:37.672Z,1400631157.672 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-05-21T00:12:37.791Z,1400631157.791 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-05-21T00:12:43.383Z,1400631163.383 [NAL9602](INFO): NAL9602 initialized
2014-05-21T00:12:47.979Z,1400631167.979 [SBIT](IMPORTANT): Beginning Startup BIT
2014-05-21T00:12:47.991Z,1400631167.991 [CBIT](IMPORTANT): Beginning GF scan
2014-05-21T00:13:01.337Z,1400631181.337 [SBIT](FAULT): Mass: EXPECTED:0.004000 ACTUAL:-0.001911
2014-05-21T00:13:15.095Z,1400631195.095 [CBIT](IMPORTANT): No ground fault detected
2014-05-21T00:13:42.166Z,1400631222.166 [SBIT](CRITICAL): SBIT FAILED
2014-05-21T00:13:42.168Z,1400631222.168 [CommandLine](FAULT): Scheduling is paused
2014-05-21T00:13:42.565Z,1400631222.565 [MissionManager](IMPORTANT): Started mission Startup
2014-05-21T00:13:42.565Z,1400631222.565 [Startup] Running Loop=1
2014-05-21T00:13:42.565Z,1400631222.565 [Startup](INFO): Aggregate::initialize Startup
2014-05-21T00:13:42.565Z,1400631222.565 [Startup:A.GoToSurface] Running Loop=1
2014-05-21T00:13:42.565Z,1400631222.565 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-21T00:13:42.571Z,1400631222.571 [Startup:StartupSatComms] Running Loop=1
2014-05-21T00:13:42.571Z,1400631222.571 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-05-21T00:13:42.571Z,1400631222.571 [Startup:StartupSatComms:A] Running Loop=1
2014-05-21T00:13:42.983Z,1400631222.983 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-05-21T00:14:09.436Z,1400631249.436 [CommandLine](IMPORTANT): got command quit
2014-05-21T00:14:10.448Z,1400631250.448 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-21T00:14:10.449Z,1400631250.449 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:10.505Z,1400631250.505 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye!
2014-05-21T00:14:10.505Z,1400631250.505 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:10.506Z,1400631250.506 [CommandLine](INFO): Join timeout helper Thread ID is 905
2014-05-21T00:14:10.521Z,1400631250.521 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2014-05-21T00:14:10.522Z,1400631250.522 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:10.522Z,1400631250.522 [NavChartDb](INFO): Join timeout helper Thread ID is 906
2014-05-21T00:14:10.662Z,1400631250.662 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-21T00:14:10.662Z,1400631250.662 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:10.674Z,1400631250.674 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2014-05-21T00:14:10.674Z,1400631250.674 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:10.674Z,1400631250.674 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 907
2014-05-21T00:14:10.714Z,1400631250.714 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-21T00:14:10.714Z,1400631250.714 [WetLabsBB2FL](INFO): Powering down
2014-05-21T00:14:10.715Z,1400631250.715 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:10.734Z,1400631250.734 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2014-05-21T00:14:10.734Z,1400631250.734 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:10.734Z,1400631250.734 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 908
2014-05-21T00:14:10.966Z,1400631250.966 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-21T00:14:10.966Z,1400631250.966 [CTD_NeilBrown](INFO): Powering down
2014-05-21T00:14:10.967Z,1400631250.967 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:10.974Z,1400631250.974 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2014-05-21T00:14:10.974Z,1400631250.974 [AsyncPiEstimator ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:10.975Z,1400631250.975 [AsyncPiEstimator](INFO): Join timeout helper Thread ID is 909
2014-05-21T00:14:11.094Z,1400631251.094 [AsyncPiEstimator ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-21T00:14:11.095Z,1400631251.095 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2014-05-21T00:14:11.095Z,1400631251.095 [AsyncPiEstimator ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:11.100Z,1400631251.100 [ComponentRegistry](INFO): Shutting down Radio_Freewave ThreadHandler
2014-05-21T00:14:11.100Z,1400631251.100 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:11.101Z,1400631251.101 [Radio_Freewave](INFO): Join timeout helper Thread ID is 910
2014-05-21T00:14:11.183Z,1400631251.183 [Radio_Freewave ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-21T00:14:11.283Z,1400631251.283 [Radio_Freewave](INFO): Powering down
2014-05-21T00:14:11.687Z,1400631251.687 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:11.695Z,1400631251.695 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2014-05-21T00:14:11.695Z,1400631251.695 [logger ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:11.696Z,1400631251.696 [logger](INFO): Join timeout helper Thread ID is 912
2014-05-21T00:14:11.739Z,1400631251.739 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-21T00:14:11.740Z,1400631251.740 [logger ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:11.756Z,1400631251.756 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2014-05-21T00:14:11.756Z,1400631251.756 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:11.757Z,1400631251.757 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2014-05-21T00:14:11.757Z,1400631251.757 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:11.757Z,1400631251.757 [controlThread](INFO): Join timeout helper Thread ID is 913
2014-05-21T00:14:11.868Z,1400631251.868 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-21T00:14:11.868Z,1400631251.868 [controlThread](DEBUG): Uninitializing ControlThread
2014-05-21T00:14:11.869Z,1400631251.869 [AHRS_sp3003D](INFO): Powering down
2014-05-21T00:14:11.870Z,1400631251.870 [DVL_micro](INFO): uninitialize:Powering down
2014-05-21T00:14:11.871Z,1400631251.871 [NAL9602](INFO): Powering down
2014-05-21T00:14:11.874Z,1400631251.874 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-05-21T00:14:11.875Z,1400631251.875 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2014-05-21T00:14:11.880Z,1400631251.880 [Startup] Stopped
2014-05-21T00:14:11.880Z,1400631251.880 [Startup](INFO): Aggregate::uninitialize Startup
2014-05-21T00:14:11.880Z,1400631251.880 [Startup:A.GoToSurface] Stopped
2014-05-21T00:14:11.881Z,1400631251.881 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-21T00:14:11.881Z,1400631251.881 [Startup:StartupSatComms] Stopped
2014-05-21T00:14:11.881Z,1400631251.881 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2014-05-21T00:14:11.881Z,1400631251.881 [Startup:StartupSatComms:A] Stopped
2014-05-21T00:14:11.882Z,1400631251.882 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2014-05-21T00:14:11.883Z,1400631251.883 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2014-05-21T00:14:11.883Z,1400631251.883 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2014-05-21T00:14:11.883Z,1400631251.883 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2014-05-21T00:14:11.884Z,1400631251.884 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-05-21T00:14:11.884Z,1400631251.884 [BuoyancyServo](INFO): Powering down
2014-05-21T00:14:11.896Z,1400631251.896 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2014-05-21T00:14:11.896Z,1400631251.896 [ElevatorServo](INFO): Powering down
2014-05-21T00:14:11.897Z,1400631251.897 [MassServo](DEBUG): Uninitialize Mass Servo.
2014-05-21T00:14:11.897Z,1400631251.897 [MassServo](INFO): Powering down
2014-05-21T00:14:11.898Z,1400631251.898 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2014-05-21T00:14:11.898Z,1400631251.898 [RudderServo](INFO): Powering down
2014-05-21T00:14:11.899Z,1400631251.899 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2014-05-21T00:14:11.899Z,1400631251.899 [ThrusterServo](INFO): Powering down
2014-05-21T00:14:11.900Z,1400631251.900 [SBIT](DEBUG): Uninitialize SBIT Component.
2014-05-21T00:14:11.900Z,1400631251.900 [IBIT](DEBUG): Uninitialize IBIT Component.
2014-05-21T00:14:11.900Z,1400631251.900 [CBIT](DEBUG): Uninitialize CBIT Component.
2014-05-21T00:14:11.944Z,1400631251.944 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:11.961Z,1400631251.961 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:12.008Z,1400631252.008 [AsyncPiEstimator ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:12.033Z,1400631252.033 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:12.037Z,1400631252.037 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:12.181Z,1400631252.181 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:14:12.221Z,1400631252.221 [logger ThreadHandler](INFO): Thread cancelled.