2014-05-22T15:11:54.039Z,1400771514.039 [Supervisor](DEBUG): Initializing supervisor.
2014-05-22T15:11:54.053Z,1400771514.053 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-05-22T15:11:54.054Z,1400771514.054 [SyncHandler](INFO): Protected caller Thread ID is 768
2014-05-22T15:11:54.055Z,1400771514.055 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-05-22T15:11:54.069Z,1400771514.069 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2014-05-22T15:11:54.069Z,1400771514.069 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 769
2014-05-22T15:11:54.072Z,1400771514.072 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-05-22T15:11:54.084Z,1400771514.084 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-05-22T15:11:54.085Z,1400771514.085 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2014-05-22T15:11:54.085Z,1400771514.085 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 770
2014-05-22T15:11:54.086Z,1400771514.086 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-05-22T15:11:54.101Z,1400771514.101 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2014-05-22T15:11:54.101Z,1400771514.101 [logger ThreadHandler](INFO): Protected caller Thread ID is 771
2014-05-22T15:11:54.104Z,1400771514.104 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-05-22T15:11:54.104Z,1400771514.104 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-05-22T15:11:54.116Z,1400771514.116 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-05-22T15:11:54.849Z,1400771514.849 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-05-22T15:11:54.850Z,1400771514.850 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-05-22T15:11:55.170Z,1400771515.170 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-05-22T15:11:55.172Z,1400771515.172 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-05-22T15:11:55.270Z,1400771515.270 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-05-22T15:11:55.272Z,1400771515.272 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-05-22T15:11:55.472Z,1400771515.472 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-05-22T15:11:55.473Z,1400771515.473 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-05-22T15:11:55.659Z,1400771515.659 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-05-22T15:11:55.661Z,1400771515.661 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-05-22T15:11:55.999Z,1400771515.999 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-05-22T15:11:56.000Z,1400771516.000 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-05-22T15:11:56.209Z,1400771516.209 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-05-22T15:11:56.210Z,1400771516.210 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-05-22T15:11:56.594Z,1400771516.594 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-05-22T15:11:56.597Z,1400771516.597 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-05-22T15:11:56.722Z,1400771516.722 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-05-22T15:11:56.722Z,1400771516.722 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-05-22T15:11:57.283Z,1400771517.283 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-05-22T15:11:57.284Z,1400771517.284 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-05-22T15:11:57.399Z,1400771517.399 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-05-22T15:11:57.400Z,1400771517.400 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-05-22T15:11:57.594Z,1400771517.594 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-05-22T15:11:59.602Z,1400771519.602 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-05-22T15:11:59.603Z,1400771519.603 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-05-22T15:11:59.719Z,1400771519.719 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-05-22T15:11:59.720Z,1400771519.720 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-05-22T15:11:59.879Z,1400771519.879 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-05-22T15:11:59.881Z,1400771519.881 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-05-22T15:11:59.885Z,1400771519.885 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-05-22T15:12:00.005Z,1400771520.005 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-05-22T15:12:00.152Z,1400771520.152 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-05-22T15:12:00.260Z,1400771520.260 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-05-22T15:12:00.364Z,1400771520.364 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-05-22T15:12:00.528Z,1400771520.528 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-05-22T15:12:00.666Z,1400771520.666 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-05-22T15:12:00.763Z,1400771520.763 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-05-22T15:12:00.882Z,1400771520.882 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-05-22T15:12:00.997Z,1400771520.997 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-05-22T15:12:01.107Z,1400771521.107 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-05-22T15:12:01.204Z,1400771521.204 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-05-22T15:12:01.317Z,1400771521.317 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2014-05-22T15:12:01.322Z,1400771521.322 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-05-22T15:12:01.960Z,1400771521.960 [AHRS_sp3003D] Loaded
2014-05-22T15:12:01.960Z,1400771521.960 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-05-22T15:12:02.295Z,1400771522.295 [Batt_Ocean_Server] Loaded
2014-05-22T15:12:02.295Z,1400771522.295 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-05-22T15:12:02.309Z,1400771522.309 [Depth_Keller] Loaded
2014-05-22T15:12:02.309Z,1400771522.309 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-05-22T15:12:02.314Z,1400771522.314 [DropWeight] Loaded
2014-05-22T15:12:02.315Z,1400771522.315 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-05-22T15:12:02.474Z,1400771522.474 [DVL_micro] Loaded
2014-05-22T15:12:02.474Z,1400771522.474 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2014-05-22T15:12:02.588Z,1400771522.588 [NAL9602] Loaded
2014-05-22T15:12:02.588Z,1400771522.588 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-05-22T15:12:02.646Z,1400771522.646 [Onboard] Loaded
2014-05-22T15:12:02.650Z,1400771522.650 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-05-22T15:12:02.658Z,1400771522.658 [Radio_Freewave] Loaded
2014-05-22T15:12:02.658Z,1400771522.658 [ComponentRegistry](DEBUG): Component "Radio_Freewave" handled in its own thread.
2014-05-22T15:12:02.662Z,1400771522.662 [Radio_Freewave ThreadHandler](DEBUG): Created PCaller Thread at 4060F4E0
2014-05-22T15:12:02.663Z,1400771522.663 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 861
2014-05-22T15:12:02.670Z,1400771522.670 [SCPI] Loaded
2014-05-22T15:12:02.670Z,1400771522.670 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-05-22T15:12:02.670Z,1400771522.670 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-05-22T15:12:02.671Z,1400771522.671 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-05-22T15:12:02.886Z,1400771522.886 [InternalSim] Loaded
2014-05-22T15:12:02.887Z,1400771522.887 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-05-22T15:12:02.887Z,1400771522.887 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-05-22T15:12:02.890Z,1400771522.890 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-05-22T15:12:03.206Z,1400771523.206 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-05-22T15:12:03.208Z,1400771523.208 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-05-22T15:12:03.216Z,1400771523.216 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-05-22T15:12:03.218Z,1400771523.218 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-05-22T15:12:03.325Z,1400771523.325 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-05-22T15:12:03.325Z,1400771523.325 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-05-22T15:12:03.380Z,1400771523.380 [DeadReckonWithRespectToWater] Loaded
2014-05-22T15:12:03.380Z,1400771523.380 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToWater" handled in the control thread.
2014-05-22T15:12:03.431Z,1400771523.431 [DeadReckonWithRespectToSeafloor] Loaded
2014-05-22T15:12:03.431Z,1400771523.431 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2014-05-22T15:12:03.484Z,1400771523.484 [DeadReckonUsingDVLWaterTrack] Loaded
2014-05-22T15:12:03.484Z,1400771523.484 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingDVLWaterTrack" handled in the control thread.
2014-05-22T15:12:03.536Z,1400771523.536 [DeadReckonUsingCompactModelForecast] Loaded
2014-05-22T15:12:03.537Z,1400771523.537 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingCompactModelForecast" handled in the control thread.
2014-05-22T15:12:03.557Z,1400771523.557 [NavChart] Loaded
2014-05-22T15:12:03.557Z,1400771523.557 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-05-22T15:12:03.561Z,1400771523.561 [UniversalFixResidualReporter] Loaded
2014-05-22T15:12:03.562Z,1400771523.562 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-05-22T15:12:03.562Z,1400771523.562 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-05-22T15:12:03.564Z,1400771523.564 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-05-22T15:12:03.638Z,1400771523.638 [VerticalControl](DEBUG): Construct VerticalControl.
2014-05-22T15:12:03.762Z,1400771523.762 [VerticalControl] Loaded
2014-05-22T15:12:03.763Z,1400771523.763 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-05-22T15:12:03.763Z,1400771523.763 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-05-22T15:12:03.841Z,1400771523.841 [HorizontalControl] Loaded
2014-05-22T15:12:03.841Z,1400771523.841 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-05-22T15:12:03.842Z,1400771523.842 [SpeedControl](DEBUG): Construct SpeedControl.
2014-05-22T15:12:03.843Z,1400771523.843 [SpeedControl] Loaded
2014-05-22T15:12:03.844Z,1400771523.844 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-05-22T15:12:03.845Z,1400771523.845 [LoopControl](DEBUG): Construct LoopControl.
2014-05-22T15:12:03.845Z,1400771523.845 [LoopControl] Loaded
2014-05-22T15:12:03.845Z,1400771523.845 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-05-22T15:12:03.846Z,1400771523.846 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-05-22T15:12:03.848Z,1400771523.848 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-05-22T15:12:03.876Z,1400771523.876 [DepthRateCalculator] Loaded
2014-05-22T15:12:03.876Z,1400771523.876 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-05-22T15:12:03.887Z,1400771523.887 [PitchRateCalculator] Loaded
2014-05-22T15:12:03.888Z,1400771523.888 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-05-22T15:12:03.895Z,1400771523.895 [SpeedCalculator] Loaded
2014-05-22T15:12:03.895Z,1400771523.895 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-05-22T15:12:03.912Z,1400771523.912 [TempGradientCalculator] Loaded
2014-05-22T15:12:03.913Z,1400771523.913 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-05-22T15:12:03.918Z,1400771523.918 [YawRateCalculator] Loaded
2014-05-22T15:12:03.918Z,1400771523.918 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-05-22T15:12:03.919Z,1400771523.919 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-05-22T15:12:03.921Z,1400771523.921 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-05-22T15:12:04.067Z,1400771524.067 [CTD_NeilBrown] Loaded
2014-05-22T15:12:04.067Z,1400771524.067 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-05-22T15:12:04.068Z,1400771524.068 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4075E4E0
2014-05-22T15:12:04.069Z,1400771524.069 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 862
2014-05-22T15:12:04.082Z,1400771524.082 [ISUS] Loaded
2014-05-22T15:12:04.082Z,1400771524.082 [ComponentRegistry](DEBUG): SyncComponent "ISUS" handled in the control thread.
2014-05-22T15:12:04.102Z,1400771524.102 [PAR_Licor] Loaded
2014-05-22T15:12:04.102Z,1400771524.102 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-05-22T15:12:04.141Z,1400771524.141 [WetLabsBB2FL] Loaded
2014-05-22T15:12:04.141Z,1400771524.141 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-05-22T15:12:04.144Z,1400771524.144 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4078E4E0
2014-05-22T15:12:04.145Z,1400771524.145 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 863
2014-05-22T15:12:04.145Z,1400771524.145 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-05-22T15:12:04.147Z,1400771524.147 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-05-22T15:12:04.278Z,1400771524.278 [SBIT](DEBUG): Construct Startup Built In Test.
2014-05-22T15:12:04.290Z,1400771524.290 [SBIT] Loaded
2014-05-22T15:12:04.290Z,1400771524.290 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-05-22T15:12:04.291Z,1400771524.291 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-05-22T15:12:04.308Z,1400771524.308 [IBIT] Loaded
2014-05-22T15:12:04.309Z,1400771524.309 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-05-22T15:12:04.311Z,1400771524.311 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-05-22T15:12:04.388Z,1400771524.388 [CBIT] Loaded
2014-05-22T15:12:04.389Z,1400771524.389 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-05-22T15:12:04.389Z,1400771524.389 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-05-22T15:12:04.390Z,1400771524.390 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-05-22T15:12:09.806Z,1400771529.806 [HFRadarModelCalc] Loaded
2014-05-22T15:12:09.806Z,1400771529.806 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2014-05-22T15:12:14.009Z,1400771534.009 [HFRadarCompactModelForecaster] Loaded
2014-05-22T15:12:14.009Z,1400771534.009 [ComponentRegistry](DEBUG): SyncComponent "HFRadarCompactModelForecaster" handled in the control thread.
2014-05-22T15:12:15.171Z,1400771535.171 [HFRCMSpaceInterpolator] Loaded
2014-05-22T15:12:15.171Z,1400771535.171 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSpaceInterpolator" handled in the control thread.
2014-05-22T15:12:15.173Z,1400771535.173 [HFRCMTimeInterpolator] Loaded
2014-05-22T15:12:15.173Z,1400771535.173 [ComponentRegistry](DEBUG): SyncComponent "HFRCMTimeInterpolator" handled in the control thread.
2014-05-22T15:12:15.186Z,1400771535.186 [HFRCMSurfaceCurrentAtVehicleLocation] Loaded
2014-05-22T15:12:15.187Z,1400771535.187 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSurfaceCurrentAtVehicleLocation" handled in the control thread.
2014-05-22T15:12:15.219Z,1400771535.219 [HFRCMVirtualSurfaceDrifter] Loaded
2014-05-22T15:12:15.219Z,1400771535.219 [ComponentRegistry](DEBUG): SyncComponent "HFRCMVirtualSurfaceDrifter" handled in the control thread.
2014-05-22T15:12:15.219Z,1400771535.219 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-05-22T15:12:15.220Z,1400771535.220 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-05-22T15:12:15.354Z,1400771535.354 [BuoyancyServo] Loaded
2014-05-22T15:12:15.354Z,1400771535.354 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-05-22T15:12:15.367Z,1400771535.367 [ElevatorServo] Loaded
2014-05-22T15:12:15.367Z,1400771535.367 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-05-22T15:12:15.383Z,1400771535.383 [MassServo] Loaded
2014-05-22T15:12:15.383Z,1400771535.383 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-05-22T15:12:15.395Z,1400771535.395 [RudderServo] Loaded
2014-05-22T15:12:15.395Z,1400771535.395 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-05-22T15:12:15.407Z,1400771535.407 [ThrusterServo] Loaded
2014-05-22T15:12:15.407Z,1400771535.407 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-05-22T15:12:15.407Z,1400771535.407 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-05-22T15:12:15.408Z,1400771535.408 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-05-22T15:12:15.452Z,1400771535.452 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-05-22T15:12:15.454Z,1400771535.454 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-05-22T15:12:15.455Z,1400771535.455 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-05-22T15:12:15.462Z,1400771535.462 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-05-22T15:12:15.466Z,1400771535.466 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A4F4E0
2014-05-22T15:12:15.466Z,1400771535.466 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 864
2014-05-22T15:12:15.471Z,1400771535.471 [Supervisor](INFO): Main Thread ID is 766
2014-05-22T15:12:15.471Z,1400771535.471 [Supervisor](DEBUG): Running supervisor.
2014-05-22T15:12:15.472Z,1400771535.472 [CommandLine ThreadHandler](INFO): Handler Thread ID is 865
2014-05-22T15:12:15.479Z,1400771535.479 [controlThread ThreadHandler](INFO): Handler Thread ID is 866
2014-05-22T15:12:15.479Z,1400771535.479 [controlThread](DEBUG): Initializing ControlThread
2014-05-22T15:12:15.483Z,1400771535.483 [logger ThreadHandler](INFO): Handler Thread ID is 867
2014-05-22T15:12:15.519Z,1400771535.519 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 868
2014-05-22T15:12:15.531Z,1400771535.531 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 869
2014-05-22T15:12:15.531Z,1400771535.531 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-05-22T15:12:15.535Z,1400771535.535 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-05-22T15:12:15.544Z,1400771535.544 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 871
2014-05-22T15:12:15.545Z,1400771535.545 [WetLabsBB2FL](INFO): Powering down
2014-05-22T15:12:15.575Z,1400771535.575 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 872
2014-05-22T15:12:15.598Z,1400771535.598 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-05-22T15:12:15.599Z,1400771535.599 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-05-22T15:12:15.599Z,1400771535.599 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-05-22T15:12:15.599Z,1400771535.599 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-05-22T15:12:15.600Z,1400771535.600 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-05-22T15:12:15.600Z,1400771535.600 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-05-22T15:12:15.600Z,1400771535.600 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-05-22T15:12:15.600Z,1400771535.600 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-05-22T15:12:15.600Z,1400771535.600 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-05-22T15:12:17.266Z,1400771537.266 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-05-22T15:12:17.296Z,1400771537.296 [InternalSim](DEBUG):  InternalSim initializing...
2014-05-22T15:12:17.730Z,1400771537.730 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-05-22T15:12:17.730Z,1400771537.730 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component.
2014-05-22T15:12:17.731Z,1400771537.731 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component.
2014-05-22T15:12:17.731Z,1400771537.731 [DeadReckonUsingDVLWaterTrack](DEBUG): Initializing DeadReckonUsingDVLWaterTrack component.
2014-05-22T15:12:17.731Z,1400771537.731 [DeadReckonUsingCompactModelForecast](DEBUG): Initializing DeadReckonUsingCompactModelForecast component.
2014-05-22T15:12:17.732Z,1400771537.732 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-05-22T15:12:17.732Z,1400771537.732 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-05-22T15:12:17.732Z,1400771537.732 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-05-22T15:12:17.734Z,1400771537.734 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-05-22T15:12:17.735Z,1400771537.735 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-05-22T15:12:17.736Z,1400771537.736 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-05-22T15:12:17.736Z,1400771537.736 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-05-22T15:12:17.736Z,1400771537.736 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-05-22T15:12:17.737Z,1400771537.737 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-05-22T15:12:17.737Z,1400771537.737 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-05-22T15:12:17.738Z,1400771537.738 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-05-22T15:12:17.739Z,1400771537.739 [SBIT](INFO): Initialize SBIT Component.
2014-05-22T15:12:17.740Z,1400771537.740 [SBIT](IMPORTANT): Tethys CM Info: 
 $Rev:11330
2014-05-22T15:12:17.740Z,1400771537.740 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2014-05-22T15:12:17.740Z,1400771537.740 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-05-22T15:12:17.741Z,1400771537.741 [IBIT](INFO): Initialize IBIT Component.
2014-05-22T15:12:17.750Z,1400771537.750 [CBIT](DEBUG): Initialize CBIT Component.
2014-05-22T15:12:17.750Z,1400771537.750 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2014-05-22T15:12:17.792Z,1400771537.792 [HFRadarCompactModelForecaster](DEBUG): Found new ECs!
2014-05-22T15:12:18.236Z,1400771538.236 [Radio_Freewave](INFO): Powering up
2014-05-22T15:12:19.045Z,1400771539.045 [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-22T15:12:27.239Z,1400771547.239 [HFRadarCompactModelForecaster](IMPORTANT): Forecast time 201405221100: published 50 modes in rows, 61 hours in columns, 3050 elements.
2014-05-22T15:12:27.257Z,1400771547.257 [HFRCMSpaceInterpolator](DEBUG): Initializing HFRCMSpaceInterpolator component.
2014-05-22T15:12:27.258Z,1400771547.258 [HFRCMTimeInterpolator](DEBUG): Initializing HFRCMTimeInterpolator component.
2014-05-22T15:12:27.259Z,1400771547.259 [HFRCMSurfaceCurrentAtVehicleLocation](DEBUG): Initializing HFRCMSurfaceCurrentAtVehicleLocation component.
2014-05-22T15:12:27.259Z,1400771547.259 [HFRCMVirtualSurfaceDrifter](DEBUG): Initializing HFRCMVirtualSurfaceDrifter component.
2014-05-22T15:12:27.261Z,1400771547.261 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-05-22T15:12:27.290Z,1400771547.290 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-22T15:12:27.315Z,1400771547.315 [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-05-22T15:12:27.316Z,1400771547.316 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-05-22T15:12:27.413Z,1400771547.413 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2014-05-22T15:12:27.415Z,1400771547.415 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2014-05-22T15:12:27.423Z,1400771547.423 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-22T15:12:27.452Z,1400771547.452 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2014-05-22T15:12:27.473Z,1400771547.473 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-22T15:12:27.488Z,1400771547.488 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-05-22T15:12:27.523Z,1400771547.523 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-05-22T15:12:27.532Z,1400771547.532 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-22T15:12:27.560Z,1400771547.560 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
xmlns:Control="Tethys/Control"
xmlns:Guidance="Tethys/Guidance" 
xmlns:Units="Tethys/Units"
xmlns:Universal="Tethys/Universal"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
Id="Default">

    <DefineArg Name="NeedGPS"><True/></DefineArg>

    <Aggregate Id="GPS">

        <When>
            <Arg Name="NeedGPS"/>
        </When>

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface>
            <Sequence/>
        </Guidance:GoToSurface>

<!-- Get GPS fix -->

        <ReadDatum Id="Read_GPS">
            <Universal:latitude_fix/>
        </ReadDatum>

        <Assign><Sequence/><Arg Name="NeedGPS"/><False/></Assign>

    </Aggregate>

    <Aggregate Id="Iridium">

        <Sequence/>

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface>
            <Sequence/>
        </Guidance:GoToSurface>

<!-- 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="CallIridium">

        <When>
            <Elapsed><Universal:platform_communications/></Elapsed>
            <Gt><Units:minute/><Value>5.0</Value></Gt>
            <And><Universal:platform_conversation/><Eq><True/></Eq></And>
            <Or><Elapsed><Universal:platform_communications/></Elapsed><Gt><Units:hour/><Value>1.0</Value></Gt></Or>
        </When>

        <Assign><Sequence/><Arg Name="NeedGPS"/><True/></Assign>

        <Call RefId="Iridium"/>

    </Aggregate>

    <Aggregate Id="WaitAtTheSurface">

        <Sequence/>

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

        <Guidance:GoToSurface>
            <Parallel/>
        </Guidance:GoToSurface>

    </Aggregate>

</Mission>


2014-05-22T15:12:27.575Z,1400771547.575 [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,HFRadarModelCalc,HFRadarCompactModelForecaster,HFRCMSpaceInterpolator,HFRCMTimeInterpolator,HFRCMSurfaceCurrentAtVehicleLocation,HFRCMVirtualSurfaceDrifter,DeadReckonUsingMultipleVelocitySources,DeadReckonWithRespectToWater,DeadReckonWithRespectToSeafloor,DeadReckonUsingDVLWaterTrack,DeadReckonUsingCompactModelForecast,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2014-05-22T15:12:27.714Z,1400771547.714 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-05-22T15:12:28.466Z,1400771548.466 [DVL_micro](INFO): Initializing
2014-05-22T15:12:28.501Z,1400771548.501 [NAL9602](INFO): Powering up NAL9602
2014-05-22T15:12:29.188Z,1400771549.188 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-05-22T15:12:29.196Z,1400771549.196 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-05-22T15:12:29.228Z,1400771549.228 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-05-22T15:12:29.232Z,1400771549.232 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-05-22T15:12:29.238Z,1400771549.238 [MassServo](DEBUG): Initializing EZServoServo.
2014-05-22T15:12:29.244Z,1400771549.244 [MassServo](DEBUG): Initializing MassServo.
2014-05-22T15:12:29.269Z,1400771549.269 [RudderServo](DEBUG): Initializing EZServoServo.
2014-05-22T15:12:29.276Z,1400771549.276 [RudderServo](DEBUG): Initializing RudderServo.
2014-05-22T15:12:29.294Z,1400771549.294 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-05-22T15:12:29.300Z,1400771549.300 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-05-22T15:12:30.101Z,1400771550.101 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2014-05-22T15:12:30.101Z,1400771550.101 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2014-05-22T15:12:30.101Z,1400771550.101 [BuoyancyServo] Communications Fault, FailCount= 1
2014-05-22T15:12:30.101Z,1400771550.101 [BuoyancyServo](ERROR): Communications Fault
2014-05-22T15:12:30.340Z,1400771550.340 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2014-05-22T15:12:30.762Z,1400771550.762 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-05-22T15:12:30.762Z,1400771550.762 [BuoyancyServo](INFO): Powering down
2014-05-22T15:12:33.024Z,1400771553.024 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2014-05-22T15:12:33.024Z,1400771553.024 [BuoyancyServo] No Fault, FailCount= 1
2014-05-22T15:12:33.475Z,1400771553.475 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-05-22T15:12:33.594Z,1400771553.594 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-05-22T15:12:33.872Z,1400771553.872 [SBIT](IMPORTANT): Beginning Startup BIT
2014-05-22T15:12:33.875Z,1400771553.875 [CBIT](IMPORTANT): Beginning GF scan
2014-05-22T15:12:39.500Z,1400771559.500 [NAL9602](INFO): NAL9602 initialized
2014-05-22T15:13:00.739Z,1400771580.739 [CBIT](IMPORTANT): No ground fault detected
2014-05-22T15:13:28.169Z,1400771608.169 [SBIT](IMPORTANT): SBIT PASSED
2014-05-22T15:13:28.603Z,1400771608.603 [MissionManager](IMPORTANT): Started mission Startup
2014-05-22T15:13:28.603Z,1400771608.603 [Startup] Running Loop=1
2014-05-22T15:13:28.603Z,1400771608.603 [Startup](INFO): Aggregate::initialize Startup
2014-05-22T15:13:28.603Z,1400771608.603 [Startup:A.GoToSurface] Running Loop=1
2014-05-22T15:13:28.603Z,1400771608.603 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-22T15:13:28.609Z,1400771608.609 [Startup:StartupSatComms] Running Loop=1
2014-05-22T15:13:28.609Z,1400771608.609 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-05-22T15:13:28.610Z,1400771608.610 [Startup:StartupSatComms:A] Running Loop=1
2014-05-22T15:13:29.035Z,1400771609.035 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-05-22T15:14:28.624Z,1400771668.624 [Startup:StartupSatComms:A](INFO): Timed out from 2014-05-22T15:13:28.6Z
2014-05-22T15:14:28.625Z,1400771668.625 [Startup:StartupSatComms:A] Stopped
2014-05-22T15:14:28.625Z,1400771668.625 [Startup:StartupSatComms:B] Running Loop=1
2014-05-22T15:14:29.024Z,1400771669.024 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-05-22T15:15:28.818Z,1400771728.818 [Startup:StartupSatComms:B](INFO): Timed out from 2014-05-22T15:14:28.6Z
2014-05-22T15:15:28.818Z,1400771728.818 [Startup:StartupSatComms:B] Stopped
2014-05-22T15:15:28.818Z,1400771728.818 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2014-05-22T15:15:28.818Z,1400771728.818 [Startup:StartupSatComms] Stopped
2014-05-22T15:15:28.818Z,1400771728.818 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2014-05-22T15:15:28.819Z,1400771728.819 [Startup](INFO): Completed Startup
2014-05-22T15:15:28.819Z,1400771728.819 [Startup] Stopped
2014-05-22T15:15:28.819Z,1400771728.819 [Startup](INFO): Aggregate::uninitialize Startup
2014-05-22T15:15:28.819Z,1400771728.819 [Startup:A.GoToSurface] Stopped
2014-05-22T15:15:28.820Z,1400771728.820 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-22T15:15:29.273Z,1400771729.273 [MissionManager](IMPORTANT): Started mission Default
2014-05-22T15:15:29.273Z,1400771729.273 [Default] Running Loop=1
2014-05-22T15:15:29.273Z,1400771729.273 [Default](INFO): Aggregate::initialize Default
2014-05-22T15:15:29.273Z,1400771729.273 [Default:Iridium] Running Loop=1
2014-05-22T15:15:29.273Z,1400771729.273 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-05-22T15:15:29.273Z,1400771729.273 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-05-22T15:15:29.274Z,1400771729.274 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-05-22T15:15:29.274Z,1400771729.274 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-05-22T15:15:29.274Z,1400771729.274 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-22T15:15:29.274Z,1400771729.274 [Default:CallIridium] Running Loop=1
2014-05-22T15:15:29.275Z,1400771729.275 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-05-22T15:15:29.275Z,1400771729.275 [Default:CallIridium:A] Running Loop=1
2014-05-22T15:15:29.277Z,1400771729.277 [Default:CallIridium:A] Stopped
2014-05-22T15:15:29.277Z,1400771729.277 [Default:CallIridium:B] Running Loop=1
2014-05-22T15:15:29.277Z,1400771729.277 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-05-22T15:15:29.282Z,1400771729.282 [Default:Iridium:B.GoToSurface] Stopped
2014-05-22T15:15:29.282Z,1400771729.282 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-22T15:15:29.283Z,1400771729.283 [Default:Iridium:Read_Iridium] Running Loop=1
2014-05-22T15:15:29.283Z,1400771729.283 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-05-22T15:15:29.288Z,1400771729.288 [Default:GPS] Running Loop=1
2014-05-22T15:15:29.288Z,1400771729.288 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-05-22T15:15:29.288Z,1400771729.288 [Default:GPS:A.SetSpeed] Running Loop=1
2014-05-22T15:15:29.288Z,1400771729.288 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-05-22T15:15:29.288Z,1400771729.288 [Default:GPS:B.GoToSurface] Running Loop=1
2014-05-22T15:15:29.288Z,1400771729.288 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-22T15:15:29.312Z,1400771729.312 [Default:GPS:B.GoToSurface] Stopped
2014-05-22T15:15:29.312Z,1400771729.312 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-22T15:15:29.312Z,1400771729.312 [Default:GPS:Read_GPS] Running Loop=1
2014-05-22T15:15:29.312Z,1400771729.312 [Default:GPS:A.SetSpeed] Running Loop=1
2014-05-22T15:15:29.743Z,1400771729.743 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-05-22T15:15:29.746Z,1400771729.746 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-05-22T15:15:34.147Z,1400771734.147 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-22T15:15:34.147Z,1400771734.147 [DVL_micro] Data Fault, FailCount= 1
2014-05-22T15:15:34.147Z,1400771734.147 [DVL_micro](ERROR): Data Fault
2014-05-22T15:15:34.206Z,1400771734.206 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-22T15:15:34.619Z,1400771734.619 [DVL_micro](INFO): uninitialize:Powering down
2014-05-22T15:15:35.009Z,1400771735.009 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-22T15:15:35.009Z,1400771735.009 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-22T15:15:35.009Z,1400771735.009 [DVL_micro](ERROR): Hardware Fault
2014-05-22T15:15:35.425Z,1400771735.425 [DVL_micro](INFO): Initializing
2014-05-22T15:15:35.460Z,1400771735.460 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-22T15:15:35.460Z,1400771735.460 [DVL_micro] No Fault, FailCount= 1
2014-05-22T15:17:44.214Z,1400771864.214 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2014-05-22T15:18:17.900Z,1400771897.900 [NAL9602](FAULT): Queried for signal strength and failed to receive proper response. serial timeout
2014-05-22T15:18:18.421Z,1400771898.421 [NAL9602](ERROR): received: 
2014-05-22T15:18:18.421Z,1400771898.421 [NAL9602] Data Fault, FailCount= 1
2014-05-22T15:18:18.421Z,1400771898.421 [NAL9602](ERROR): Data Fault
2014-05-22T15:18:18.470Z,1400771898.470 [CBIT](ERROR): Data Fault in component: NAL9602
2014-05-22T15:18:18.872Z,1400771898.872 [NAL9602](INFO): Powering down
2014-05-22T15:18:19.717Z,1400771899.717 [CBIT](INFO): Clearing failed state for component NAL9602
2014-05-22T15:18:19.717Z,1400771899.717 [NAL9602] No Fault, FailCount= 1
2014-05-22T15:18:24.217Z,1400771904.217 [NAL9602](INFO): Powering up NAL9602
2014-05-22T15:18:34.977Z,1400771914.977 [NAL9602](INFO): NAL9602 initialized
2014-05-22T15:18:39.691Z,1400771919.691 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-22T15:18:39.691Z,1400771919.691 [DVL_micro] Data Fault, FailCount= 1
2014-05-22T15:18:39.691Z,1400771919.691 [DVL_micro](ERROR): Data Fault
2014-05-22T15:18:39.774Z,1400771919.774 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-22T15:18:40.203Z,1400771920.203 [DVL_micro](INFO): uninitialize:Powering down
2014-05-22T15:18:40.653Z,1400771920.653 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-22T15:18:40.653Z,1400771920.653 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-22T15:18:40.653Z,1400771920.653 [DVL_micro](ERROR): Hardware Fault
2014-05-22T15:18:41.148Z,1400771921.148 [DVL_micro](INFO): Initializing
2014-05-22T15:18:41.212Z,1400771921.212 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-22T15:18:41.212Z,1400771921.212 [DVL_micro] No Fault, FailCount= 1
2014-05-22T15:21:45.466Z,1400772105.466 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-22T15:21:45.466Z,1400772105.466 [DVL_micro] Data Fault, FailCount= 1
2014-05-22T15:21:45.466Z,1400772105.466 [DVL_micro](ERROR): Data Fault
2014-05-22T15:21:45.551Z,1400772105.551 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-22T15:21:45.971Z,1400772105.971 [DVL_micro](INFO): uninitialize:Powering down
2014-05-22T15:21:46.381Z,1400772106.381 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-22T15:21:46.381Z,1400772106.381 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-22T15:21:46.381Z,1400772106.381 [DVL_micro](ERROR): Hardware Fault
2014-05-22T15:21:46.820Z,1400772106.820 [DVL_micro](INFO): Initializing
2014-05-22T15:21:46.888Z,1400772106.888 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-22T15:21:46.889Z,1400772106.889 [DVL_micro] No Fault, FailCount= 1
2014-05-22T15:22:44.184Z,1400772164.184 [NAL9602](FAULT): GPS failed to acquire within timeout.
2014-05-22T15:22:44.184Z,1400772164.184 [NAL9602] Data Fault, FailCount= 2
2014-05-22T15:22:44.184Z,1400772164.184 [NAL9602](ERROR): Data Fault
2014-05-22T15:22:44.244Z,1400772164.244 [CBIT](ERROR): Data Fault in component: NAL9602
2014-05-22T15:22:44.244Z,1400772164.244 [CBIT](CRITICAL): Data Fault in component: NAL9602
2014-05-22T15:22:44.584Z,1400772164.584 [NAL9602](INFO): Powering down
2014-05-22T15:22:44.616Z,1400772164.616 [CommandLine](FAULT): Scheduling is paused
2014-05-22T15:24:44.526Z,1400772284.526 [CBIT](INFO): Clearing failed count for component NAL9602
2014-05-22T15:24:44.526Z,1400772284.526 [NAL9602] No Fault, FailCount= 2
2014-05-22T15:24:44.879Z,1400772284.879 [NAL9602](INFO): Powering up NAL9602
2014-05-22T15:24:51.436Z,1400772291.436 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-22T15:24:51.436Z,1400772291.436 [DVL_micro] Data Fault, FailCount= 1
2014-05-22T15:24:51.436Z,1400772291.436 [DVL_micro](ERROR): Data Fault
2014-05-22T15:24:51.516Z,1400772291.516 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-22T15:24:51.971Z,1400772291.971 [DVL_micro](INFO): uninitialize:Powering down
2014-05-22T15:24:52.361Z,1400772292.361 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-22T15:24:52.361Z,1400772292.361 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-22T15:24:52.362Z,1400772292.362 [DVL_micro](ERROR): Hardware Fault
2014-05-22T15:24:52.767Z,1400772292.767 [DVL_micro](INFO): Initializing
2014-05-22T15:24:52.825Z,1400772292.825 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-22T15:24:52.825Z,1400772292.825 [DVL_micro] No Fault, FailCount= 1
2014-05-22T15:24:55.673Z,1400772295.673 [NAL9602](INFO): NAL9602 initialized
2014-05-22T15:25:17.426Z,1400772317.426 [NAL9602](INFO): SBD MO Status=2, MOMSN=30279, MT Status=2, MTMSN=0
2014-05-22T15:25:17.426Z,1400772317.426 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-05-22T15:25:45.939Z,1400772345.939 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#4 STATUS: 65535
2014-05-22T15:25:51.776Z,1400772351.776 [NAL9602](INFO): SBD MO Status=2, MOMSN=30279, MT Status=2, MTMSN=0
2014-05-22T15:25:51.777Z,1400772351.777 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-05-22T15:27:22.158Z,1400772442.158 [CommandLine](IMPORTANT): got command burn 5.000000
2014-05-22T15:27:27.192Z,1400772447.192 [CommandLine](IMPORTANT): Deactivating dropweight wire
2014-05-22T15:27:57.545Z,1400772477.545 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-22T15:27:57.545Z,1400772477.545 [DVL_micro] Data Fault, FailCount= 1
2014-05-22T15:27:57.546Z,1400772477.546 [DVL_micro](ERROR): Data Fault
2014-05-22T15:27:57.627Z,1400772477.627 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-22T15:27:58.056Z,1400772478.056 [DVL_micro](INFO): uninitialize:Powering down
2014-05-22T15:27:58.510Z,1400772478.510 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-22T15:27:58.510Z,1400772478.510 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-22T15:27:58.510Z,1400772478.510 [DVL_micro](ERROR): Hardware Fault
2014-05-22T15:27:59.001Z,1400772479.001 [DVL_micro](INFO): Initializing
2014-05-22T15:27:59.075Z,1400772479.075 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-22T15:27:59.075Z,1400772479.075 [DVL_micro] No Fault, FailCount= 1
2014-05-22T15:31:03.273Z,1400772663.273 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-22T15:31:03.273Z,1400772663.273 [DVL_micro] Data Fault, FailCount= 1
2014-05-22T15:31:03.273Z,1400772663.273 [DVL_micro](ERROR): Data Fault
2014-05-22T15:31:03.354Z,1400772663.354 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-22T15:31:03.760Z,1400772663.760 [DVL_micro](INFO): uninitialize:Powering down
2014-05-22T15:31:04.170Z,1400772664.170 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-22T15:31:04.170Z,1400772664.170 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-22T15:31:04.170Z,1400772664.170 [DVL_micro](ERROR): Hardware Fault
2014-05-22T15:31:04.646Z,1400772664.646 [DVL_micro](INFO): Initializing
2014-05-22T15:31:04.722Z,1400772664.722 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-22T15:31:04.722Z,1400772664.722 [DVL_micro] No Fault, FailCount= 1
2014-05-22T15:33:01.158Z,1400772781.158 [NAL9602](INFO): SBD MO Status=1, MOMSN=30279, MT Status=0, MTMSN=0
2014-05-22T15:33:01.202Z,1400772781.202 [NAL9602](INFO): Sent 193 bytes from file Logs/20140522T021013/Courier0000.lzma
2014-05-22T15:33:01.203Z,1400772781.203 [NAL9602](INFO): Packets left to send: 0
2014-05-22T15:33:01.204Z,1400772781.204 [NAL9602](INFO): Stored copy of sent data in Logs/20140522T021013/Courier0000.lzma.parts/0000.sbd
2014-05-22T15:33:01.205Z,1400772781.205 [NAL9602](INFO): Completed sending Logs/20140522T021013/Courier0000.lzma
2014-05-22T15:33:18.333Z,1400772798.333 [NAL9602](INFO): SBD MO Status=2, MOMSN=30280, MT Status=2, MTMSN=0
2014-05-22T15:33:18.333Z,1400772798.333 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-05-22T15:34:09.237Z,1400772849.237 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-22T15:34:09.237Z,1400772849.237 [DVL_micro] Data Fault, FailCount= 1
2014-05-22T15:34:09.237Z,1400772849.237 [DVL_micro](ERROR): Data Fault
2014-05-22T15:34:09.332Z,1400772849.332 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-22T15:34:09.796Z,1400772849.796 [DVL_micro](INFO): uninitialize:Powering down
2014-05-22T15:34:10.226Z,1400772850.226 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-22T15:34:10.226Z,1400772850.226 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-22T15:34:10.227Z,1400772850.227 [DVL_micro](ERROR): Hardware Fault
2014-05-22T15:34:10.707Z,1400772850.707 [DVL_micro](INFO): Initializing
2014-05-22T15:34:10.784Z,1400772850.784 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-22T15:34:10.784Z,1400772850.784 [DVL_micro] No Fault, FailCount= 1
2014-05-22T15:34:57.168Z,1400772897.168 [NAL9602](FAULT): GPS failed to acquire within timeout.
2014-05-22T15:34:57.168Z,1400772897.168 [NAL9602] Data Fault, FailCount= 1
2014-05-22T15:34:57.168Z,1400772897.168 [NAL9602](ERROR): Data Fault
2014-05-22T15:34:57.200Z,1400772897.200 [CBIT](ERROR): Data Fault in component: NAL9602
2014-05-22T15:34:57.577Z,1400772897.577 [NAL9602](INFO): Powering down
2014-05-22T15:34:58.458Z,1400772898.458 [CBIT](INFO): Clearing failed state for component NAL9602
2014-05-22T15:34:58.458Z,1400772898.458 [NAL9602] No Fault, FailCount= 1
2014-05-22T15:35:02.998Z,1400772902.998 [NAL9602](INFO): Powering up NAL9602
2014-05-22T15:35:13.763Z,1400772913.763 [NAL9602](INFO): NAL9602 initialized
2014-05-22T15:37:14.945Z,1400773034.945 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-22T15:37:14.945Z,1400773034.945 [DVL_micro] Data Fault, FailCount= 1
2014-05-22T15:37:14.945Z,1400773034.945 [DVL_micro](ERROR): Data Fault
2014-05-22T15:37:14.981Z,1400773034.981 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-22T15:37:15.432Z,1400773035.432 [DVL_micro](INFO): uninitialize:Powering down
2014-05-22T15:37:15.834Z,1400773035.834 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-22T15:37:15.834Z,1400773035.834 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-22T15:37:15.834Z,1400773035.834 [DVL_micro](ERROR): Hardware Fault
2014-05-22T15:37:16.273Z,1400773036.273 [DVL_micro](INFO): Initializing
2014-05-22T15:37:16.828Z,1400773036.828 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-22T15:37:16.828Z,1400773036.828 [DVL_micro] No Fault, FailCount= 1
2014-05-22T15:40:20.817Z,1400773220.817 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-22T15:40:20.817Z,1400773220.817 [DVL_micro] Data Fault, FailCount= 1
2014-05-22T15:40:20.817Z,1400773220.817 [DVL_micro](ERROR): Data Fault
2014-05-22T15:40:20.913Z,1400773220.913 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-22T15:40:21.336Z,1400773221.336 [DVL_micro](INFO): uninitialize:Powering down
2014-05-22T15:40:21.743Z,1400773221.743 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-22T15:40:21.743Z,1400773221.743 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-22T15:40:21.743Z,1400773221.743 [DVL_micro](ERROR): Hardware Fault
2014-05-22T15:40:22.212Z,1400773222.212 [DVL_micro](INFO): Initializing
2014-05-22T15:40:22.247Z,1400773222.247 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-22T15:40:22.247Z,1400773222.247 [DVL_micro] No Fault, FailCount= 1
2014-05-22T15:40:29.702Z,1400773229.702 [CommandLine](IMPORTANT): got command ibit
2014-05-22T15:40:30.043Z,1400773230.043 [IBIT](IMPORTANT): Beginning Initiated BIT
2014-05-22T15:40:30.043Z,1400773230.043 [IBIT](IMPORTANT): Beginning control surface checks.
2014-05-22T15:40:30.044Z,1400773230.044 [CBIT](IMPORTANT): Beginning GF scan
2014-05-22T15:40:56.775Z,1400773256.775 [CBIT](IMPORTANT): No ground fault detected
2014-05-22T15:41:31.966Z,1400773291.966 [CommandLine](IMPORTANT): got command maintain control SpeedControl.propOmegaAction 1.000000 revolution_per_minute
2014-05-22T15:41:31.968Z,1400773291.968 [ComponentRegistry](DEBUG): SyncComponent "Maintain_SpeedControl.propOmegaAction" handled in the control thread.
2014-05-22T15:41:32.093Z,1400773292.093 [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,HFRadarModelCalc,HFRadarCompactModelForecaster,HFRCMSpaceInterpolator,HFRCMTimeInterpolator,HFRCMSurfaceCurrentAtVehicleLocation,HFRCMVirtualSurfaceDrifter,DeadReckonUsingMultipleVelocitySources,DeadReckonWithRespectToWater,DeadReckonWithRespectToSeafloor,DeadReckonUsingDVLWaterTrack,DeadReckonUsingCompactModelForecast,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintain_SpeedControl.propOmegaAction,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2014-05-22T15:41:44.441Z,1400773304.441 [CommandLine](IMPORTANT): got command get ThrusterServo.component_voltage
2014-05-22T15:41:44.442Z,1400773304.442 [CommandLine](IMPORTANT): ThrusterServo.component_voltage 15.963901 V
2014-05-22T15:42:13.400Z,1400773333.400 [IBIT](IMPORTANT): Communications Status:
Fix Status: 1
Iridium Signal Strength: 1
Latitude: 0.000000 Longitude: 0.000000
2014-05-22T15:42:13.916Z,1400773333.916 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 231.510010
Voltage: 16.055126
2014-05-22T15:42:13.917Z,1400773333.917 [IBIT](IMPORTANT): batteryCapacityThreshold: 5.000000 Ah
2014-05-22T15:42:13.917Z,1400773333.917 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.500000 V
2014-05-22T15:42:16.430Z,1400773336.430 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2014-05-22T15:42:16.430Z,1400773336.430 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2014-05-22T15:42:16.430Z,1400773336.430 [IBIT](IMPORTANT): Pressure:10.734123 PSI
2014-05-22T15:42:16.431Z,1400773336.431 [IBIT](IMPORTANT): Humidity:9.699471 %
2014-05-22T15:42:17.025Z,1400773337.025 [IBIT](IMPORTANT): surfaceThreshold: 0.500000 m
2014-05-22T15:42:17.025Z,1400773337.025 [IBIT](IMPORTANT): buoyancyNeutral: 300.000000 cc
2014-05-22T15:42:17.025Z,1400773337.025 [IBIT](IMPORTANT): massDefault: 0.000000 cm
2014-05-22T15:42:17.026Z,1400773337.026 [IBIT](IMPORTANT): stopDepth: 112.000000 m
2014-05-22T15:42:17.026Z,1400773337.026 [IBIT](IMPORTANT): abortDepth: 130.000000 m
2014-05-22T15:42:17.026Z,1400773337.026 [IBIT](IMPORTANT): IBIT PASSED
2014-05-22T15:42:26.486Z,1400773346.486 [CommandLine](IMPORTANT): got command maintain clear
2014-05-22T15:42:26.526Z,1400773346.526 [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,HFRadarModelCalc,HFRadarCompactModelForecaster,HFRCMSpaceInterpolator,HFRCMTimeInterpolator,HFRCMSurfaceCurrentAtVehicleLocation,HFRCMVirtualSurfaceDrifter,DeadReckonUsingMultipleVelocitySources,DeadReckonWithRespectToWater,DeadReckonWithRespectToSeafloor,DeadReckonUsingDVLWaterTrack,DeadReckonUsingCompactModelForecast,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2014-05-22T15:42:26.875Z,1400773346.875 [NAL9602](INFO): SBD MO Status=2, MOMSN=30280, MT Status=2, MTMSN=0
2014-05-22T15:42:26.875Z,1400773346.875 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-05-22T15:43:26.562Z,1400773406.562 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-22T15:43:26.562Z,1400773406.562 [DVL_micro] Data Fault, FailCount= 1
2014-05-22T15:43:26.562Z,1400773406.562 [DVL_micro](ERROR): Data Fault
2014-05-22T15:43:26.650Z,1400773406.650 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-22T15:43:27.104Z,1400773407.104 [DVL_micro](INFO): uninitialize:Powering down
2014-05-22T15:43:27.530Z,1400773407.530 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-22T15:43:27.531Z,1400773407.531 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-22T15:43:27.531Z,1400773407.531 [DVL_micro](ERROR): Hardware Fault
2014-05-22T15:43:27.965Z,1400773407.965 [DVL_micro](INFO): Initializing
2014-05-22T15:43:28.024Z,1400773408.024 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-22T15:43:28.024Z,1400773408.024 [DVL_micro] No Fault, FailCount= 1
2014-05-22T15:44:25.054Z,1400773465.054 [CommandLine](IMPORTANT): got command restart application
2014-05-22T15:44:26.064Z,1400773466.064 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-22T15:44:26.064Z,1400773466.064 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:26.179Z,1400773466.179 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2014-05-22T15:44:26.179Z,1400773466.179 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:26.180Z,1400773466.180 [CommandLine](INFO): Join timeout helper Thread ID is 970
2014-05-22T15:44:26.181Z,1400773466.181 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2014-05-22T15:44:26.181Z,1400773466.181 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:26.181Z,1400773466.181 [NavChartDb](INFO): Join timeout helper Thread ID is 971
2014-05-22T15:44:26.296Z,1400773466.296 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-22T15:44:26.296Z,1400773466.296 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:26.300Z,1400773466.300 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2014-05-22T15:44:26.300Z,1400773466.300 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:26.300Z,1400773466.300 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 972
2014-05-22T15:44:26.472Z,1400773466.472 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-22T15:44:26.473Z,1400773466.473 [WetLabsBB2FL](INFO): Powering down
2014-05-22T15:44:26.473Z,1400773466.473 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:26.480Z,1400773466.480 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2014-05-22T15:44:26.480Z,1400773466.480 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:26.481Z,1400773466.481 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 973
2014-05-22T15:44:26.633Z,1400773466.633 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-22T15:44:26.633Z,1400773466.633 [CTD_NeilBrown](INFO): Powering down
2014-05-22T15:44:26.633Z,1400773466.633 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:26.642Z,1400773466.642 [ComponentRegistry](INFO): Shutting down Radio_Freewave ThreadHandler
2014-05-22T15:44:26.642Z,1400773466.642 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:26.643Z,1400773466.643 [Radio_Freewave](INFO): Join timeout helper Thread ID is 974
2014-05-22T15:44:26.773Z,1400773466.773 [Radio_Freewave ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-22T15:44:26.917Z,1400773466.917 [Radio_Freewave](INFO): Powering down
2014-05-22T15:44:27.322Z,1400773467.322 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:27.340Z,1400773467.340 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2014-05-22T15:44:27.341Z,1400773467.341 [logger ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:27.341Z,1400773467.341 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-22T15:44:27.342Z,1400773467.342 [logger ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:27.342Z,1400773467.342 [logger](INFO): Join timeout helper Thread ID is 977
2014-05-22T15:44:27.362Z,1400773467.362 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2014-05-22T15:44:27.362Z,1400773467.362 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:27.362Z,1400773467.362 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2014-05-22T15:44:27.363Z,1400773467.363 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:27.363Z,1400773467.363 [controlThread](INFO): Join timeout helper Thread ID is 978
2014-05-22T15:44:27.428Z,1400773467.428 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-22T15:44:27.428Z,1400773467.428 [controlThread](DEBUG): Uninitializing ControlThread
2014-05-22T15:44:27.429Z,1400773467.429 [AHRS_sp3003D](INFO): Powering down
2014-05-22T15:44:27.586Z,1400773467.586 [DVL_micro](INFO): uninitialize:Powering down
2014-05-22T15:44:27.587Z,1400773467.587 [NAL9602](INFO): Powering down
2014-05-22T15:44:27.590Z,1400773467.590 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-05-22T15:44:27.593Z,1400773467.593 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2014-05-22T15:44:27.593Z,1400773467.593 [Default] Stopped
2014-05-22T15:44:27.593Z,1400773467.593 [Default](INFO): Aggregate::uninitialize Default
2014-05-22T15:44:27.593Z,1400773467.593 [Default:GPS] Stopped
2014-05-22T15:44:27.594Z,1400773467.594 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-05-22T15:44:27.594Z,1400773467.594 [Default:GPS:A.SetSpeed] Stopped
2014-05-22T15:44:27.594Z,1400773467.594 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-05-22T15:44:27.594Z,1400773467.594 [Default:GPS:Read_GPS] Stopped
2014-05-22T15:44:27.594Z,1400773467.594 [Default:Iridium] Stopped
2014-05-22T15:44:27.594Z,1400773467.594 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-05-22T15:44:27.594Z,1400773467.594 [Default:Iridium:A.SetSpeed] Stopped
2014-05-22T15:44:27.594Z,1400773467.594 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-05-22T15:44:27.594Z,1400773467.594 [Default:Iridium:Read_Iridium] Stopped
2014-05-22T15:44:27.594Z,1400773467.594 [Default:CallIridium] Stopped
2014-05-22T15:44:27.595Z,1400773467.595 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-05-22T15:44:27.595Z,1400773467.595 [Default:CallIridium:B] Stopped
2014-05-22T15:44:27.595Z,1400773467.595 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-05-22T15:44:27.600Z,1400773467.600 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2014-05-22T15:44:27.600Z,1400773467.600 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2014-05-22T15:44:27.600Z,1400773467.600 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2014-05-22T15:44:27.601Z,1400773467.601 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2014-05-22T15:44:27.601Z,1400773467.601 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-05-22T15:44:27.601Z,1400773467.601 [BuoyancyServo](INFO): Powering down
2014-05-22T15:44:27.614Z,1400773467.614 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2014-05-22T15:44:27.614Z,1400773467.614 [ElevatorServo](INFO): Powering down
2014-05-22T15:44:27.615Z,1400773467.615 [MassServo](DEBUG): Uninitialize Mass Servo.
2014-05-22T15:44:27.615Z,1400773467.615 [MassServo](INFO): Powering down
2014-05-22T15:44:27.616Z,1400773467.616 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2014-05-22T15:44:27.616Z,1400773467.616 [RudderServo](INFO): Powering down
2014-05-22T15:44:27.617Z,1400773467.617 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2014-05-22T15:44:27.617Z,1400773467.617 [ThrusterServo](INFO): Powering down
2014-05-22T15:44:27.618Z,1400773467.618 [SBIT](DEBUG): Uninitialize SBIT Component.
2014-05-22T15:44:27.618Z,1400773467.618 [IBIT](DEBUG): Uninitialize IBIT Component.
2014-05-22T15:44:27.618Z,1400773467.618 [CBIT](DEBUG): Uninitialize CBIT Component.
2014-05-22T15:44:27.663Z,1400773467.663 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:27.665Z,1400773467.665 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:27.740Z,1400773467.740 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:27.743Z,1400773467.743 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:27.790Z,1400773467.790 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-05-22T15:44:27.823Z,1400773467.823 [logger ThreadHandler](INFO): Thread cancelled.