2014-08-01T04:06:21.811Z,1406865981.811 [Supervisor](DEBUG): Initializing supervisor.
2014-08-01T04:06:21.814Z,1406865981.814 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-08-01T04:06:21.814Z,1406865981.814 [SyncHandler](INFO): Protected caller Thread ID is 2580
2014-08-01T04:06:21.815Z,1406865981.815 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-08-01T04:06:21.816Z,1406865981.816 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2014-08-01T04:06:21.816Z,1406865981.816 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2581
2014-08-01T04:06:21.820Z,1406865981.820 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-08-01T04:06:21.832Z,1406865981.832 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-08-01T04:06:21.833Z,1406865981.833 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2014-08-01T04:06:21.833Z,1406865981.833 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2582
2014-08-01T04:06:21.834Z,1406865981.834 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-08-01T04:06:21.835Z,1406865981.835 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2014-08-01T04:06:21.835Z,1406865981.835 [logger ThreadHandler](INFO): Protected caller Thread ID is 2583
2014-08-01T04:06:21.837Z,1406865981.837 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-08-01T04:06:21.838Z,1406865981.838 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-08-01T04:06:21.840Z,1406865981.840 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-08-01T04:06:22.321Z,1406865982.321 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-08-01T04:06:22.322Z,1406865982.322 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-08-01T04:06:22.475Z,1406865982.475 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-08-01T04:06:22.476Z,1406865982.476 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-08-01T04:06:22.582Z,1406865982.582 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-08-01T04:06:22.583Z,1406865982.583 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-08-01T04:06:22.704Z,1406865982.704 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-08-01T04:06:22.705Z,1406865982.705 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-08-01T04:06:22.790Z,1406865982.790 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-08-01T04:06:22.923Z,1406865982.923 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-08-01T04:06:22.923Z,1406865982.923 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-08-01T04:06:23.008Z,1406865983.008 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-08-01T04:06:23.009Z,1406865983.009 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-08-01T04:06:23.185Z,1406865983.185 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-08-01T04:06:23.185Z,1406865983.185 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-08-01T04:06:23.470Z,1406865983.470 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-08-01T04:06:23.471Z,1406865983.471 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-08-01T04:06:23.770Z,1406865983.770 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-08-01T04:06:23.771Z,1406865983.771 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-08-01T04:06:24.257Z,1406865984.257 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-08-01T04:06:24.257Z,1406865984.257 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-08-01T04:06:24.444Z,1406865984.444 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-08-01T04:06:24.445Z,1406865984.445 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-08-01T04:06:24.547Z,1406865984.547 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-08-01T04:06:24.547Z,1406865984.547 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-08-01T04:06:24.935Z,1406865984.935 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-08-01T04:06:24.935Z,1406865984.935 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-08-01T04:06:25.043Z,1406865985.043 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-08-01T04:06:25.046Z,1406865985.046 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-08-01T04:06:25.046Z,1406865985.046 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-08-01T04:06:25.168Z,1406865985.168 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-08-01T04:06:25.284Z,1406865985.284 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-08-01T04:06:25.392Z,1406865985.392 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-08-01T04:06:25.488Z,1406865985.488 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-08-01T04:06:25.614Z,1406865985.614 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-08-01T04:06:25.756Z,1406865985.756 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-08-01T04:06:25.856Z,1406865985.856 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-08-01T04:06:25.941Z,1406865985.941 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-08-01T04:06:26.039Z,1406865986.039 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-08-01T04:06:26.273Z,1406865986.273 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-08-01T04:06:26.382Z,1406865986.382 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-08-01T04:06:26.470Z,1406865986.470 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/
2014-08-01T04:06:26.470Z,1406865986.470 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2014-08-01T04:06:26.472Z,1406865986.472 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-08-01T04:06:26.523Z,1406865986.523 [VerticalControl](DEBUG): Construct VerticalControl.
2014-08-01T04:06:26.638Z,1406865986.638 [VerticalControl] Loaded
2014-08-01T04:06:26.638Z,1406865986.638 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-08-01T04:06:26.639Z,1406865986.639 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-08-01T04:06:26.708Z,1406865986.708 [HorizontalControl] Loaded
2014-08-01T04:06:26.708Z,1406865986.708 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-08-01T04:06:26.709Z,1406865986.709 [SpeedControl](DEBUG): Construct SpeedControl.
2014-08-01T04:06:26.714Z,1406865986.714 [SpeedControl] Loaded
2014-08-01T04:06:26.714Z,1406865986.714 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-08-01T04:06:26.715Z,1406865986.715 [LoopControl](DEBUG): Construct LoopControl.
2014-08-01T04:06:26.715Z,1406865986.715 [LoopControl] Loaded
2014-08-01T04:06:26.716Z,1406865986.716 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-08-01T04:06:26.716Z,1406865986.716 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-08-01T04:06:26.717Z,1406865986.717 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-08-01T04:06:26.813Z,1406865986.813 [SBIT](DEBUG): Construct Startup Built In Test.
2014-08-01T04:06:26.824Z,1406865986.824 [SBIT] Loaded
2014-08-01T04:06:26.825Z,1406865986.825 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-08-01T04:06:26.825Z,1406865986.825 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-08-01T04:06:26.853Z,1406865986.853 [IBIT] Loaded
2014-08-01T04:06:26.853Z,1406865986.853 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-08-01T04:06:26.856Z,1406865986.856 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-08-01T04:06:26.969Z,1406865986.969 [CBIT] Loaded
2014-08-01T04:06:26.969Z,1406865986.969 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-08-01T04:06:26.970Z,1406865986.970 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-08-01T04:06:26.970Z,1406865986.970 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-08-01T04:06:26.989Z,1406865986.989 [DepthRateCalculator] Loaded
2014-08-01T04:06:26.990Z,1406865986.990 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-08-01T04:06:26.995Z,1406865986.995 [PitchRateCalculator] Loaded
2014-08-01T04:06:26.995Z,1406865986.995 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-08-01T04:06:27.006Z,1406865987.006 [SpeedCalculator] Loaded
2014-08-01T04:06:27.006Z,1406865987.006 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-08-01T04:06:27.022Z,1406865987.022 [TempGradientCalculator] Loaded
2014-08-01T04:06:27.022Z,1406865987.022 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-08-01T04:06:27.027Z,1406865987.027 [YawRateCalculator] Loaded
2014-08-01T04:06:27.028Z,1406865987.028 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-08-01T04:06:27.028Z,1406865987.028 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-08-01T04:06:27.029Z,1406865987.029 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-08-01T04:06:31.967Z,1406865991.967 [HFRadarModelCalc] Loaded
2014-08-01T04:06:31.967Z,1406865991.967 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2014-08-01T04:06:35.926Z,1406865995.926 [HFRadarCompactModelForecaster] Loaded
2014-08-01T04:06:35.926Z,1406865995.926 [ComponentRegistry](DEBUG): SyncComponent "HFRadarCompactModelForecaster" handled in the control thread.
2014-08-01T04:06:37.014Z,1406865997.014 [HFRCMSpaceInterpolator] Loaded
2014-08-01T04:06:37.014Z,1406865997.014 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSpaceInterpolator" handled in the control thread.
2014-08-01T04:06:37.016Z,1406865997.016 [HFRCMTimeInterpolator] Loaded
2014-08-01T04:06:37.017Z,1406865997.017 [ComponentRegistry](DEBUG): SyncComponent "HFRCMTimeInterpolator" handled in the control thread.
2014-08-01T04:06:38.075Z,1406865998.075 [HFRCMReconstructedInterpolator] Loaded
2014-08-01T04:06:38.075Z,1406865998.075 [ComponentRegistry](DEBUG): SyncComponent "HFRCMReconstructedInterpolator" handled in the control thread.
2014-08-01T04:06:38.087Z,1406865998.087 [HFRCMSurfaceCurrentAtVehicleLocation] Loaded
2014-08-01T04:06:38.087Z,1406865998.087 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSurfaceCurrentAtVehicleLocation" handled in the control thread.
2014-08-01T04:06:38.113Z,1406865998.113 [HFRCMVirtualSurfaceDrifter] Loaded
2014-08-01T04:06:38.113Z,1406865998.113 [ComponentRegistry](DEBUG): SyncComponent "HFRCMVirtualSurfaceDrifter" handled in the control thread.
2014-08-01T04:06:38.114Z,1406865998.114 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-08-01T04:06:38.115Z,1406865998.115 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-08-01T04:06:38.344Z,1406865998.344 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-08-01T04:06:38.345Z,1406865998.345 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-08-01T04:06:38.425Z,1406865998.425 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-08-01T04:06:38.425Z,1406865998.425 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-08-01T04:06:38.469Z,1406865998.469 [DeadReckonWithRespectToWater] Loaded
2014-08-01T04:06:38.469Z,1406865998.469 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToWater" handled in the control thread.
2014-08-01T04:06:38.514Z,1406865998.514 [DeadReckonWithRespectToSeafloor] Loaded
2014-08-01T04:06:38.514Z,1406865998.514 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2014-08-01T04:06:38.573Z,1406865998.573 [DeadReckonUsingDVLWaterTrack] Loaded
2014-08-01T04:06:38.573Z,1406865998.573 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingDVLWaterTrack" handled in the control thread.
2014-08-01T04:06:38.619Z,1406865998.619 [DeadReckonUsingCompactModelForecast] Loaded
2014-08-01T04:06:38.620Z,1406865998.620 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingCompactModelForecast" handled in the control thread.
2014-08-01T04:06:38.636Z,1406865998.636 [NavChart] Loaded
2014-08-01T04:06:38.637Z,1406865998.637 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-08-01T04:06:38.641Z,1406865998.641 [UniversalFixResidualReporter] Loaded
2014-08-01T04:06:38.641Z,1406865998.641 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-08-01T04:06:38.641Z,1406865998.641 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-08-01T04:06:38.642Z,1406865998.642 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-08-01T04:06:38.648Z,1406865998.648 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-08-01T04:06:38.649Z,1406865998.649 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-08-01T04:06:38.824Z,1406865998.824 [CTD_NeilBrown] Loaded
2014-08-01T04:06:38.824Z,1406865998.824 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-08-01T04:06:38.831Z,1406865998.831 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407B94E0
2014-08-01T04:06:38.832Z,1406865998.832 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 2665
2014-08-01T04:06:38.847Z,1406865998.847 [PAR_Licor] Loaded
2014-08-01T04:06:38.848Z,1406865998.848 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-08-01T04:06:38.882Z,1406865998.882 [WetLabsBB2FL] Loaded
2014-08-01T04:06:38.882Z,1406865998.882 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-08-01T04:06:38.883Z,1406865998.883 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407E94E0
2014-08-01T04:06:38.883Z,1406865998.883 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 2666
2014-08-01T04:06:38.884Z,1406865998.884 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-08-01T04:06:38.885Z,1406865998.885 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-08-01T04:06:39.223Z,1406865999.223 [AHRS_sp3003D] Loaded
2014-08-01T04:06:39.224Z,1406865999.224 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-08-01T04:06:39.477Z,1406865999.477 [Batt_Ocean_Server] Loaded
2014-08-01T04:06:39.477Z,1406865999.477 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-08-01T04:06:39.490Z,1406865999.490 [Depth_Keller] Loaded
2014-08-01T04:06:39.490Z,1406865999.490 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-08-01T04:06:39.495Z,1406865999.495 [DropWeight] Loaded
2014-08-01T04:06:39.495Z,1406865999.495 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-08-01T04:06:39.624Z,1406865999.624 [DVL_micro] Loaded
2014-08-01T04:06:39.625Z,1406865999.625 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2014-08-01T04:06:39.716Z,1406865999.716 [NAL9602] Loaded
2014-08-01T04:06:39.716Z,1406865999.716 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-08-01T04:06:39.770Z,1406865999.770 [Onboard] Loaded
2014-08-01T04:06:39.770Z,1406865999.770 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-08-01T04:06:39.777Z,1406865999.777 [Radio_Freewave] Loaded
2014-08-01T04:06:39.778Z,1406865999.778 [ComponentRegistry](DEBUG): Component "Radio_Freewave" handled in its own thread.
2014-08-01T04:06:39.781Z,1406865999.781 [Radio_Freewave ThreadHandler](DEBUG): Created PCaller Thread at 40A1E4E0
2014-08-01T04:06:39.782Z,1406865999.782 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 2667
2014-08-01T04:06:39.936Z,1406865999.936 [DAT] Loaded
2014-08-01T04:06:39.936Z,1406865999.936 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2014-08-01T04:06:39.942Z,1406865999.942 [SCPI] Loaded
2014-08-01T04:06:39.943Z,1406865999.943 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-08-01T04:06:40.248Z,1406866000.248 [BPC1] Loaded
2014-08-01T04:06:40.248Z,1406866000.248 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2014-08-01T04:06:40.248Z,1406866000.248 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-08-01T04:06:40.249Z,1406866000.249 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-08-01T04:06:40.347Z,1406866000.347 [BuoyancyServo] Loaded
2014-08-01T04:06:40.347Z,1406866000.347 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-08-01T04:06:40.359Z,1406866000.359 [ElevatorServo] Loaded
2014-08-01T04:06:40.360Z,1406866000.360 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-08-01T04:06:40.371Z,1406866000.371 [MassServo] Loaded
2014-08-01T04:06:40.371Z,1406866000.371 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-08-01T04:06:40.383Z,1406866000.383 [RudderServo] Loaded
2014-08-01T04:06:40.383Z,1406866000.383 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-08-01T04:06:40.394Z,1406866000.394 [ThrusterServo] Loaded
2014-08-01T04:06:40.394Z,1406866000.394 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-08-01T04:06:40.395Z,1406866000.395 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-08-01T04:06:40.395Z,1406866000.395 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-08-01T04:06:40.548Z,1406866000.548 [InternalSim] Loaded
2014-08-01T04:06:40.549Z,1406866000.549 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-08-01T04:06:40.549Z,1406866000.549 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-08-01T04:06:40.550Z,1406866000.550 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-08-01T04:06:40.575Z,1406866000.575 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-08-01T04:06:40.577Z,1406866000.577 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-08-01T04:06:40.578Z,1406866000.578 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-08-01T04:06:40.585Z,1406866000.585 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-08-01T04:06:40.588Z,1406866000.588 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ACF4E0
2014-08-01T04:06:40.588Z,1406866000.588 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 2668
2014-08-01T04:06:40.594Z,1406866000.594 [Supervisor](INFO): Main Thread ID is 2579
2014-08-01T04:06:40.594Z,1406866000.594 [Supervisor](DEBUG): Running supervisor.
2014-08-01T04:06:40.594Z,1406866000.594 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2669
2014-08-01T04:06:40.598Z,1406866000.598 [controlThread ThreadHandler](INFO): Handler Thread ID is 2670
2014-08-01T04:06:40.599Z,1406866000.599 [controlThread](DEBUG): Initializing ControlThread
2014-08-01T04:06:40.600Z,1406866000.600 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-08-01T04:06:40.601Z,1406866000.601 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-08-01T04:06:40.602Z,1406866000.602 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-08-01T04:06:40.602Z,1406866000.602 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-08-01T04:06:40.603Z,1406866000.603 [SBIT](INFO): Initialize SBIT Component.
2014-08-01T04:06:40.603Z,1406866000.603 [SBIT](IMPORTANT): Tethys CM Info: SVN revision: 11462
2014-08-01T04:06:40.604Z,1406866000.604 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2014-08-01T04:06:40.604Z,1406866000.604 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-08-01T04:06:40.604Z,1406866000.604 [IBIT](INFO): Initialize IBIT Component.
2014-08-01T04:06:40.605Z,1406866000.605 [CBIT](DEBUG): Initialize CBIT Component.
2014-08-01T04:06:40.606Z,1406866000.606 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2014-08-01T04:06:40.607Z,1406866000.607 [logger ThreadHandler](INFO): Handler Thread ID is 2671
2014-08-01T04:06:40.626Z,1406866000.626 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 2672
2014-08-01T04:06:40.627Z,1406866000.627 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-08-01T04:06:40.630Z,1406866000.630 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-08-01T04:06:40.630Z,1406866000.630 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-08-01T04:06:40.630Z,1406866000.630 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-08-01T04:06:40.631Z,1406866000.631 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-08-01T04:06:40.631Z,1406866000.631 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-08-01T04:06:40.634Z,1406866000.634 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-08-01T04:06:40.646Z,1406866000.646 [HFRadarCompactModelForecaster](DEBUG): Found new ECs!
2014-08-01T04:06:40.648Z,1406866000.648 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 2674
2014-08-01T04:06:40.650Z,1406866000.650 [WetLabsBB2FL](INFO): Powering down
2014-08-01T04:06:40.694Z,1406866000.694 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 2675
2014-08-01T04:06:40.699Z,1406866000.699 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 2676
2014-08-01T04:06:40.706Z,1406866000.706 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-08-01T04:06:40.707Z,1406866000.707 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-08-01T04:06:40.707Z,1406866000.707 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-08-01T04:06:40.708Z,1406866000.708 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-08-01T04:06:40.708Z,1406866000.708 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-08-01T04:06:40.708Z,1406866000.708 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-08-01T04:06:40.708Z,1406866000.708 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-08-01T04:06:40.709Z,1406866000.709 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-08-01T04:06:40.709Z,1406866000.709 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-08-01T04:06:49.407Z,1406866009.407 [HFRadarCompactModelForecaster](IMPORTANT): forecast time 201408010100: published 50 modes in rows, 61 hours in columns
2014-08-01T04:06:49.431Z,1406866009.431 [HFRadarCompactModelForecaster](IMPORTANT): expansionCoefficients_[0][48] = -10.333895 for 2014-08-01T01:00:00.000Z
2014-08-01T04:06:49.432Z,1406866009.432 [HFRCMSpaceInterpolator](DEBUG): Initializing HFRCMSpaceInterpolator component with verbosity level 0.
2014-08-01T04:06:49.434Z,1406866009.434 [HFRCMTimeInterpolator](DEBUG): Initializing HFRCMTimeInterpolator component.
2014-08-01T04:06:49.434Z,1406866009.434 [HFRCMReconstructedInterpolator](INFO): Initializing HFRCMReconstructedInterpolator component with velocityAccuracy_ = 0.300000 m/s.
2014-08-01T04:06:49.436Z,1406866009.436 [HFRCMSurfaceCurrentAtVehicleLocation](DEBUG): Initializing HFRCMSurfaceCurrentAtVehicleLocation component.
2014-08-01T04:06:49.436Z,1406866009.436 [HFRCMVirtualSurfaceDrifter](DEBUG): Initializing HFRCMVirtualSurfaceDrifter component.
2014-08-01T04:06:49.436Z,1406866009.436 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-08-01T04:06:49.437Z,1406866009.437 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component.
2014-08-01T04:06:49.437Z,1406866009.437 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component.
2014-08-01T04:06:49.438Z,1406866009.438 [DeadReckonUsingDVLWaterTrack](DEBUG): Initializing DeadReckonUsingDVLWaterTrack component.
2014-08-01T04:06:49.438Z,1406866009.438 [DeadReckonUsingCompactModelForecast](DEBUG): Initializing DeadReckonUsingCompactModelForecast component.
2014-08-01T04:06:49.439Z,1406866009.439 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-08-01T04:06:49.455Z,1406866009.455 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-08-01T04:06:51.501Z,1406866011.501 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-08-01T04:06:51.535Z,1406866011.535 [InternalSim](DEBUG):  InternalSim initializing...
2014-08-01T04:06:51.644Z,1406866011.644 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-08-01T04:06:51.691Z,1406866011.691 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-08-01T04:06:51.712Z,1406866011.712 [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-08-01T04:06:51.713Z,1406866011.713 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-08-01T04:06:51.749Z,1406866011.749 [Default:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-08-01T04:06:51.778Z,1406866011.778 [Default:CheckIn:A.SetSpeed](DEBUG): Construct.
2014-08-01T04:06:51.804Z,1406866011.804 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-08-01T04:06:51.824Z,1406866011.824 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-08-01T04:06:51.829Z,1406866011.829 [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">

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

    <Aggregate Id="CheckIn">

        <When>
            <Elapsed><Universal:platform_communications/></Elapsed>
            <Gt><Units:minute/><Value>5.0</Value></Gt>
            <And><Universal:platform_conversation/><Eq><True/></Eq></And>
            <Or><Elapsed><Universal:platform_communications/></Elapsed><Gt><Units:hour/><Value>1.0</Value></Gt></Or>
        </When>
<!-- TODO: Do we really want this When operating on platform_communications? or on something else like time_fix? -->

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

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

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

        <!-- Do data comms -->

        <ReadDatum Id="Read_Iridium">
            <Timeout Duration="P2H">
                <Guidance:Execute>
                    <Sequence/>
                    <Setting><Guidance:Execute.command/><String>Burn 300</String></Setting>
                </Guidance:Execute>
                <Syslog Severity="Critical">Dropped drop weight due to communications timeout</Syslog>
            </Timeout>
            <Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

    <Aggregate Id="WaitAtTheSurface">

        <Sequence/>

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

    </Aggregate>

</Mission>


2014-08-01T04:06:51.851Z,1406866011.851 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,PAR_Licor,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,DAT,SCPI,BPC1,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,HFRadarModelCalc,HFRadarCompactModelForecaster,HFRCMSpaceInterpolator,HFRCMTimeInterpolator,HFRCMReconstructedInterpolator,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-08-01T04:06:52.020Z,1406866012.020 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-08-01T04:06:52.232Z,1406866012.232 [DVL_micro](INFO): Initializing
2014-08-01T04:06:52.262Z,1406866012.262 [NAL9602](INFO): Powering up NAL9602
2014-08-01T04:06:52.351Z,1406866012.351 [Radio_Freewave](INFO): Powering up
2014-08-01T04:06:52.394Z,1406866012.394 [DAT](INFO): Powering up
2014-08-01T04:06:52.394Z,1406866012.394 [DAT](DEBUG): Initializing DAT.
2014-08-01T04:06:52.422Z,1406866012.422 [BPC1](DEBUG): Initializing BPC1.
2014-08-01T04:06:53.158Z,1406866013.158 [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-08-01T04:06:59.842Z,1406866019.842 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-08-01T04:06:59.848Z,1406866019.848 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-08-01T04:06:59.874Z,1406866019.874 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-08-01T04:06:59.880Z,1406866019.880 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-08-01T04:06:59.897Z,1406866019.897 [MassServo](DEBUG): Initializing EZServoServo.
2014-08-01T04:06:59.904Z,1406866019.904 [MassServo](DEBUG): Initializing MassServo.
2014-08-01T04:06:59.917Z,1406866019.917 [RudderServo](DEBUG): Initializing EZServoServo.
2014-08-01T04:06:59.924Z,1406866019.924 [RudderServo](DEBUG): Initializing RudderServo.
2014-08-01T04:06:59.938Z,1406866019.938 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-08-01T04:06:59.944Z,1406866019.944 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-08-01T04:07:00.320Z,1406866020.320 [AHRS_sp3003D](ERROR): readHeadingMagBin got 0x420DA4090D
2014-08-01T04:07:00.320Z,1406866020.320 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2014-08-01T04:07:00.320Z,1406866020.320 [AHRS_sp3003D] Hardware Fault, FailCount= 1
2014-08-01T04:07:00.321Z,1406866020.321 [AHRS_sp3003D](ERROR): Hardware Fault
2014-08-01T04:07:00.942Z,1406866020.942 [SBIT](IMPORTANT): Beginning Startup BIT
2014-08-01T04:07:00.945Z,1406866020.945 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2014-08-01T04:07:00.945Z,1406866020.945 [CBIT](IMPORTANT): Beginning GF scan
2014-08-01T04:07:01.026Z,1406866021.026 [AHRS_sp3003D](INFO): Powering down
2014-08-01T04:07:02.720Z,1406866022.720 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2014-08-01T04:07:02.720Z,1406866022.720 [AHRS_sp3003D] No Fault, FailCount= 1
2014-08-01T04:07:03.009Z,1406866023.009 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-08-01T04:07:03.069Z,1406866023.069 [NAL9602](INFO): NAL9602 initialized
2014-08-01T04:07:10.909Z,1406866030.909 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items. Got 23 of 46
2014-08-01T04:07:10.909Z,1406866030.909 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 151 134 187 149 3 3 4 3 -48.0 -20.099
2014-08-01T04:07:12.568Z,1406866032.568 [DAT](INFO): Powering down
2014-08-01T04:07:28.001Z,1406866048.001 [CBIT](IMPORTANT): No ground fault detected
2014-08-01T04:07:54.746Z,1406866074.746 [SBIT](IMPORTANT): SBIT PASSED
2014-08-01T04:07:55.163Z,1406866075.163 [MissionManager](IMPORTANT): Started mission Startup
2014-08-01T04:07:55.164Z,1406866075.164 [Startup] Running Loop=1
2014-08-01T04:07:55.164Z,1406866075.164 [Startup](INFO): Aggregate::initialize Startup
2014-08-01T04:07:55.164Z,1406866075.164 [Startup:A.GoToSurface] Running Loop=1
2014-08-01T04:07:55.164Z,1406866075.164 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-08-01T04:07:55.165Z,1406866075.165 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-08-01T04:07:55.165Z,1406866075.165 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-08-01T04:07:55.165Z,1406866075.165 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-08-01T04:07:55.171Z,1406866075.171 [Startup:StartupSatComms] Running Loop=1
2014-08-01T04:07:55.172Z,1406866075.172 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-08-01T04:07:55.172Z,1406866075.172 [Startup:StartupSatComms:A] Running Loop=1
2014-08-01T04:07:55.623Z,1406866075.623 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-08-01T04:08:55.237Z,1406866135.237 [Startup:StartupSatComms:A](INFO): Timed out from 2014-08-01T04:07:55.2Z
2014-08-01T04:08:55.237Z,1406866135.237 [Startup:StartupSatComms:A] Stopped
2014-08-01T04:08:55.237Z,1406866135.237 [Startup:StartupSatComms:B] Running Loop=1
2014-08-01T04:08:55.674Z,1406866135.674 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-08-01T04:09:55.755Z,1406866195.755 [Startup:StartupSatComms:B](INFO): Timed out from 2014-08-01T04:08:55.2Z
2014-08-01T04:09:55.755Z,1406866195.755 [Startup:StartupSatComms:B] Stopped
2014-08-01T04:09:55.756Z,1406866195.756 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2014-08-01T04:09:55.756Z,1406866195.756 [Startup:StartupSatComms] Stopped
2014-08-01T04:09:55.756Z,1406866195.756 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2014-08-01T04:09:55.785Z,1406866195.785 [Startup](INFO): Completed Startup
2014-08-01T04:09:55.785Z,1406866195.785 [Startup] Stopped
2014-08-01T04:09:55.785Z,1406866195.785 [Startup](INFO): Aggregate::uninitialize Startup
2014-08-01T04:09:55.785Z,1406866195.785 [Startup:A.GoToSurface] Stopped
2014-08-01T04:09:55.785Z,1406866195.785 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-08-01T04:09:56.329Z,1406866196.329 [MissionManager](IMPORTANT): Started mission Default
2014-08-01T04:09:56.329Z,1406866196.329 [Default] Running Loop=1
2014-08-01T04:09:56.329Z,1406866196.329 [Default](INFO): Aggregate::initialize Default
2014-08-01T04:09:56.329Z,1406866196.329 [Default:A.GoToSurface] Running Loop=1
2014-08-01T04:09:56.329Z,1406866196.329 [Default:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-08-01T04:09:56.330Z,1406866196.330 [Default:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-08-01T04:09:56.330Z,1406866196.330 [Default:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-08-01T04:09:56.330Z,1406866196.330 [Default:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-08-01T04:09:56.331Z,1406866196.331 [Default:CheckIn] Running Loop=1
2014-08-01T04:09:56.331Z,1406866196.331 [Default:CheckIn](INFO): Aggregate::initialize Default:CheckIn
2014-08-01T04:09:56.331Z,1406866196.331 [Default:CheckIn:A.SetSpeed] Running Loop=1
2014-08-01T04:09:56.331Z,1406866196.331 [Default:CheckIn:A.SetSpeed](DEBUG): Initialize.
2014-08-01T04:09:56.331Z,1406866196.331 [Default:CheckIn:Read_GPS] Running Loop=1
2014-08-01T04:09:56.332Z,1406866196.332 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-08-01T04:09:56.335Z,1406866196.335 [Default:CheckIn:A.SetSpeed] Running Loop=1
2014-08-01T04:09:56.362Z,1406866196.362 [Default:WaitAtTheSurface] Running Loop=1
2014-08-01T04:09:56.362Z,1406866196.362 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface
2014-08-01T04:09:56.362Z,1406866196.362 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2014-08-01T04:09:56.362Z,1406866196.362 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Initialize.
2014-08-01T04:09:56.804Z,1406866196.804 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2014-08-01T04:10:05.053Z,1406866205.053 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-08-01T04:10:05.053Z,1406866205.053 [DVL_micro] Data Fault, FailCount= 1
2014-08-01T04:10:05.053Z,1406866205.053 [DVL_micro](ERROR): Data Fault
2014-08-01T04:10:05.129Z,1406866205.129 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-08-01T04:10:05.494Z,1406866205.494 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T04:10:05.914Z,1406866205.914 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-08-01T04:10:05.914Z,1406866205.914 [DVL_micro] Hardware Fault, FailCount= 1
2014-08-01T04:10:05.914Z,1406866205.914 [DVL_micro](ERROR): Hardware Fault
2014-08-01T04:10:06.402Z,1406866206.402 [DVL_micro](INFO): Initializing
2014-08-01T04:10:06.470Z,1406866206.470 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-08-01T04:10:06.470Z,1406866206.470 [DVL_micro] No Fault, FailCount= 1
2014-08-01T04:13:10.456Z,1406866390.456 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-08-01T04:13:10.456Z,1406866390.456 [DVL_micro] Data Fault, FailCount= 1
2014-08-01T04:13:10.456Z,1406866390.456 [DVL_micro](ERROR): Data Fault
2014-08-01T04:13:10.530Z,1406866390.530 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-08-01T04:13:10.885Z,1406866390.885 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T04:13:11.362Z,1406866391.362 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-08-01T04:13:11.362Z,1406866391.362 [DVL_micro] Hardware Fault, FailCount= 1
2014-08-01T04:13:11.362Z,1406866391.362 [DVL_micro](ERROR): Hardware Fault
2014-08-01T04:13:11.794Z,1406866391.794 [DVL_micro](INFO): Initializing
2014-08-01T04:13:11.868Z,1406866391.868 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-08-01T04:13:11.868Z,1406866391.868 [DVL_micro] No Fault, FailCount= 1
2014-08-01T04:14:56.493Z,1406866496.493 [Default:CheckIn:Read_GPS](INFO): Timed out from 2014-08-01T04:09:56.3Z
2014-08-01T04:14:56.493Z,1406866496.493 [Default:CheckIn:Read_GPS] Stopped
2014-08-01T04:14:56.493Z,1406866496.493 [Default:CheckIn:Read_Iridium] Running Loop=1
2014-08-01T04:14:56.941Z,1406866496.941 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-08-01T04:16:15.707Z,1406866575.707 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-08-01T04:16:15.707Z,1406866575.707 [DVL_micro] Data Fault, FailCount= 1
2014-08-01T04:16:15.707Z,1406866575.707 [DVL_micro](ERROR): Data Fault
2014-08-01T04:16:15.818Z,1406866575.818 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-08-01T04:16:16.239Z,1406866576.239 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T04:16:16.801Z,1406866576.801 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-08-01T04:16:16.801Z,1406866576.801 [DVL_micro] Hardware Fault, FailCount= 1
2014-08-01T04:16:16.801Z,1406866576.801 [DVL_micro](ERROR): Hardware Fault
2014-08-01T04:16:17.300Z,1406866577.300 [DVL_micro](INFO): Initializing
2014-08-01T04:16:17.911Z,1406866577.911 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-08-01T04:16:17.912Z,1406866577.912 [DVL_micro] No Fault, FailCount= 1
2014-08-01T04:17:08.974Z,1406866628.974 [NAL9602](FAULT): GPS failed to acquire within timeout.
2014-08-01T04:17:08.974Z,1406866628.974 [NAL9602] Data Fault, FailCount= 1
2014-08-01T04:17:08.974Z,1406866628.974 [NAL9602](ERROR): Data Fault
2014-08-01T04:17:09.047Z,1406866629.047 [CBIT](ERROR): Data Fault in component: NAL9602
2014-08-01T04:17:09.419Z,1406866629.419 [NAL9602](INFO): Powering down
2014-08-01T04:17:10.311Z,1406866630.311 [CBIT](INFO): Clearing failed state for component NAL9602
2014-08-01T04:17:10.311Z,1406866630.311 [NAL9602] No Fault, FailCount= 1
2014-08-01T04:17:14.569Z,1406866634.569 [NAL9602](INFO): Powering up NAL9602
2014-08-01T04:17:25.336Z,1406866645.336 [NAL9602](INFO): NAL9602 initialized
2014-08-01T04:19:22.309Z,1406866762.309 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-08-01T04:19:22.309Z,1406866762.309 [DVL_micro] Data Fault, FailCount= 1
2014-08-01T04:19:22.309Z,1406866762.309 [DVL_micro](ERROR): Data Fault
2014-08-01T04:19:22.861Z,1406866762.861 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-08-01T04:19:23.284Z,1406866763.284 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T04:19:24.708Z,1406866764.708 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-08-01T04:19:24.709Z,1406866764.709 [DVL_micro] Hardware Fault, FailCount= 1
2014-08-01T04:19:24.709Z,1406866764.709 [DVL_micro](ERROR): Hardware Fault
2014-08-01T04:19:25.140Z,1406866765.140 [DVL_micro](INFO): Initializing
2014-08-01T04:19:25.209Z,1406866765.209 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-08-01T04:19:25.210Z,1406866765.210 [DVL_micro] No Fault, FailCount= 1
2014-08-01T04:21:45.981Z,1406866905.981 [CommandLine](IMPORTANT): got command quit
2014-08-01T04:21:46.990Z,1406866906.990 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T04:21:46.990Z,1406866906.990 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:47.179Z,1406866907.179 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2014-08-01T04:21:47.179Z,1406866907.179 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:47.180Z,1406866907.180 [CommandLine](INFO): Join timeout helper Thread ID is 2756
2014-08-01T04:21:47.187Z,1406866907.187 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2014-08-01T04:21:47.187Z,1406866907.187 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:47.188Z,1406866907.188 [NavChartDb](INFO): Join timeout helper Thread ID is 2757
2014-08-01T04:21:47.504Z,1406866907.504 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T04:21:47.504Z,1406866907.504 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:47.520Z,1406866907.520 [ComponentRegistry](INFO): Shutting down Radio_Freewave ThreadHandler
2014-08-01T04:21:47.520Z,1406866907.520 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:47.520Z,1406866907.520 [Radio_Freewave](INFO): Join timeout helper Thread ID is 2758
2014-08-01T04:21:47.824Z,1406866907.824 [Radio_Freewave ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T04:21:48.022Z,1406866908.022 [Radio_Freewave](INFO): Powering down
2014-08-01T04:21:48.425Z,1406866908.425 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:48.426Z,1406866908.426 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2014-08-01T04:21:48.426Z,1406866908.426 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:48.426Z,1406866908.426 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 2760
2014-08-01T04:21:48.441Z,1406866908.441 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T04:21:48.442Z,1406866908.442 [WetLabsBB2FL](INFO): Powering down
2014-08-01T04:21:48.442Z,1406866908.442 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:48.445Z,1406866908.445 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2014-08-01T04:21:48.445Z,1406866908.445 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:48.446Z,1406866908.446 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 2761
2014-08-01T04:21:48.525Z,1406866908.525 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T04:21:48.526Z,1406866908.526 [CTD_NeilBrown](INFO): Powering down
2014-08-01T04:21:48.526Z,1406866908.526 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:48.538Z,1406866908.538 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2014-08-01T04:21:48.539Z,1406866908.539 [logger ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:48.539Z,1406866908.539 [logger](INFO): Join timeout helper Thread ID is 2762
2014-08-01T04:21:48.561Z,1406866908.561 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T04:21:48.562Z,1406866908.562 [logger ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:48.578Z,1406866908.578 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2014-08-01T04:21:48.578Z,1406866908.578 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:48.578Z,1406866908.578 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2014-08-01T04:21:48.579Z,1406866908.579 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:48.579Z,1406866908.579 [controlThread](INFO): Join timeout helper Thread ID is 2763
2014-08-01T04:21:48.844Z,1406866908.844 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2014-08-01T04:21:48.844Z,1406866908.844 [controlThread](DEBUG): Uninitializing ControlThread
2014-08-01T04:21:48.845Z,1406866908.845 [AHRS_sp3003D](INFO): Powering down
2014-08-01T04:21:48.846Z,1406866908.846 [DVL_micro](INFO): uninitialize:Powering down
2014-08-01T04:21:48.847Z,1406866908.847 [NAL9602](INFO): Powering down
2014-08-01T04:21:48.848Z,1406866908.848 [DAT](INFO): Powering down
2014-08-01T04:21:48.850Z,1406866908.850 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-08-01T04:21:48.852Z,1406866908.852 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2014-08-01T04:21:48.853Z,1406866908.853 [Default] Stopped
2014-08-01T04:21:48.853Z,1406866908.853 [Default](INFO): Aggregate::uninitialize Default
2014-08-01T04:21:48.853Z,1406866908.853 [Default:A.GoToSurface] Stopped
2014-08-01T04:21:48.853Z,1406866908.853 [Default:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-08-01T04:21:48.853Z,1406866908.853 [Default:CheckIn] Stopped
2014-08-01T04:21:48.853Z,1406866908.853 [Default:CheckIn](INFO): Aggregate::uninitialize Default:CheckIn
2014-08-01T04:21:48.854Z,1406866908.854 [Default:CheckIn:A.SetSpeed] Stopped
2014-08-01T04:21:48.854Z,1406866908.854 [Default:CheckIn:A.SetSpeed](DEBUG): Uninitialize.
2014-08-01T04:21:48.854Z,1406866908.854 [Default:CheckIn:Read_Iridium] Stopped
2014-08-01T04:21:48.854Z,1406866908.854 [Default:WaitAtTheSurface] Stopped
2014-08-01T04:21:48.854Z,1406866908.854 [Default:WaitAtTheSurface](INFO): Aggregate::uninitialize Default:WaitAtTheSurface
2014-08-01T04:21:48.854Z,1406866908.854 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Stopped
2014-08-01T04:21:48.854Z,1406866908.854 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Uninitialize.
2014-08-01T04:21:48.857Z,1406866908.857 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2014-08-01T04:21:48.857Z,1406866908.857 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2014-08-01T04:21:48.858Z,1406866908.858 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2014-08-01T04:21:48.858Z,1406866908.858 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2014-08-01T04:21:48.858Z,1406866908.858 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-08-01T04:21:48.859Z,1406866908.859 [BuoyancyServo](INFO): Powering down
2014-08-01T04:21:48.874Z,1406866908.874 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2014-08-01T04:21:48.874Z,1406866908.874 [ElevatorServo](INFO): Powering down
2014-08-01T04:21:48.875Z,1406866908.875 [MassServo](DEBUG): Uninitialize Mass Servo.
2014-08-01T04:21:48.875Z,1406866908.875 [MassServo](INFO): Powering down
2014-08-01T04:21:48.876Z,1406866908.876 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2014-08-01T04:21:48.876Z,1406866908.876 [RudderServo](INFO): Powering down
2014-08-01T04:21:48.877Z,1406866908.877 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2014-08-01T04:21:48.877Z,1406866908.877 [ThrusterServo](INFO): Powering down
2014-08-01T04:21:48.878Z,1406866908.878 [SBIT](DEBUG): Uninitialize SBIT Component.
2014-08-01T04:21:48.878Z,1406866908.878 [IBIT](DEBUG): Uninitialize IBIT Component.
2014-08-01T04:21:48.879Z,1406866908.879 [CBIT](DEBUG): Uninitialize CBIT Component.
2014-08-01T04:21:48.923Z,1406866908.923 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:49.013Z,1406866909.013 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:49.017Z,1406866909.017 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:49.031Z,1406866909.031 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:49.078Z,1406866909.078 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-08-01T04:21:49.124Z,1406866909.124 [logger ThreadHandler](INFO): Thread cancelled.