2014-08-06T01:22:13.480Z,1407288133.480 [Supervisor](DEBUG): Initializing supervisor.
2014-08-06T01:22:13.484Z,1407288133.484 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-08-06T01:22:13.484Z,1407288133.484 [SyncHandler](INFO): Protected caller Thread ID is 1510
2014-08-06T01:22:13.485Z,1407288133.485 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-08-06T01:22:13.486Z,1407288133.486 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2014-08-06T01:22:13.486Z,1407288133.486 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1511
2014-08-06T01:22:13.490Z,1407288133.490 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-08-06T01:22:13.503Z,1407288133.503 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-08-06T01:22:13.504Z,1407288133.504 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2014-08-06T01:22:13.504Z,1407288133.504 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1512
2014-08-06T01:22:13.505Z,1407288133.505 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-08-06T01:22:13.506Z,1407288133.506 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2014-08-06T01:22:13.510Z,1407288133.510 [logger ThreadHandler](INFO): Protected caller Thread ID is 1513
2014-08-06T01:22:13.513Z,1407288133.513 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-08-06T01:22:13.513Z,1407288133.513 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-08-06T01:22:13.515Z,1407288133.515 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-08-06T01:22:13.893Z,1407288133.893 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-08-06T01:22:13.894Z,1407288133.894 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-08-06T01:22:14.063Z,1407288134.063 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-08-06T01:22:14.064Z,1407288134.064 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-08-06T01:22:14.177Z,1407288134.177 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-08-06T01:22:14.177Z,1407288134.177 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-08-06T01:22:14.323Z,1407288134.323 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-08-06T01:22:14.324Z,1407288134.324 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-08-06T01:22:14.413Z,1407288134.413 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-08-06T01:22:14.556Z,1407288134.556 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-08-06T01:22:14.557Z,1407288134.557 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-08-06T01:22:14.646Z,1407288134.646 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-08-06T01:22:14.646Z,1407288134.646 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-08-06T01:22:14.839Z,1407288134.839 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-08-06T01:22:14.840Z,1407288134.840 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-08-06T01:22:15.161Z,1407288135.161 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-08-06T01:22:15.162Z,1407288135.162 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-08-06T01:22:15.500Z,1407288135.500 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-08-06T01:22:15.500Z,1407288135.500 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-08-06T01:22:16.049Z,1407288136.049 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-08-06T01:22:16.049Z,1407288136.049 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-08-06T01:22:16.263Z,1407288136.263 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-08-06T01:22:16.264Z,1407288136.264 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-08-06T01:22:16.372Z,1407288136.372 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-08-06T01:22:16.372Z,1407288136.372 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-08-06T01:22:16.814Z,1407288136.814 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-08-06T01:22:16.815Z,1407288136.815 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-08-06T01:22:16.930Z,1407288136.930 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-08-06T01:22:16.933Z,1407288136.933 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-08-06T01:22:16.934Z,1407288136.934 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-08-06T01:22:17.044Z,1407288137.044 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-08-06T01:22:17.169Z,1407288137.169 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-08-06T01:22:17.286Z,1407288137.286 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-08-06T01:22:17.387Z,1407288137.387 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-08-06T01:22:17.524Z,1407288137.524 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-08-06T01:22:17.683Z,1407288137.683 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-08-06T01:22:17.790Z,1407288137.790 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-08-06T01:22:17.879Z,1407288137.879 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-08-06T01:22:17.980Z,1407288137.980 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-08-06T01:22:18.081Z,1407288138.081 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-08-06T01:22:18.198Z,1407288138.198 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-08-06T01:22:18.290Z,1407288138.290 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/
2014-08-06T01:22:18.290Z,1407288138.290 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2014-08-06T01:22:18.292Z,1407288138.292 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-08-06T01:22:18.346Z,1407288138.346 [VerticalControl](DEBUG): Construct VerticalControl.
2014-08-06T01:22:18.472Z,1407288138.472 [VerticalControl] Loaded
2014-08-06T01:22:18.473Z,1407288138.473 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-08-06T01:22:18.473Z,1407288138.473 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-08-06T01:22:18.549Z,1407288138.549 [HorizontalControl] Loaded
2014-08-06T01:22:18.549Z,1407288138.549 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-08-06T01:22:18.550Z,1407288138.550 [SpeedControl](DEBUG): Construct SpeedControl.
2014-08-06T01:22:18.556Z,1407288138.556 [SpeedControl] Loaded
2014-08-06T01:22:18.556Z,1407288138.556 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-08-06T01:22:18.557Z,1407288138.557 [LoopControl](DEBUG): Construct LoopControl.
2014-08-06T01:22:18.557Z,1407288138.557 [LoopControl] Loaded
2014-08-06T01:22:18.557Z,1407288138.557 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-08-06T01:22:18.558Z,1407288138.558 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-08-06T01:22:18.559Z,1407288138.559 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-08-06T01:22:18.702Z,1407288138.702 [SBIT](DEBUG): Construct Startup Built In Test.
2014-08-06T01:22:18.714Z,1407288138.714 [SBIT] Loaded
2014-08-06T01:22:18.714Z,1407288138.714 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-08-06T01:22:18.715Z,1407288138.715 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-08-06T01:22:18.745Z,1407288138.745 [IBIT] Loaded
2014-08-06T01:22:18.746Z,1407288138.746 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-08-06T01:22:18.748Z,1407288138.748 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-08-06T01:22:18.884Z,1407288138.884 [CBIT] Loaded
2014-08-06T01:22:18.885Z,1407288138.885 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-08-06T01:22:18.885Z,1407288138.885 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-08-06T01:22:18.886Z,1407288138.886 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-08-06T01:22:18.905Z,1407288138.905 [DepthRateCalculator] Loaded
2014-08-06T01:22:18.906Z,1407288138.906 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-08-06T01:22:18.912Z,1407288138.912 [PitchRateCalculator] Loaded
2014-08-06T01:22:18.912Z,1407288138.912 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-08-06T01:22:18.924Z,1407288138.924 [SpeedCalculator] Loaded
2014-08-06T01:22:18.924Z,1407288138.924 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-08-06T01:22:18.941Z,1407288138.941 [TempGradientCalculator] Loaded
2014-08-06T01:22:18.942Z,1407288138.942 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-08-06T01:22:18.947Z,1407288138.947 [YawRateCalculator] Loaded
2014-08-06T01:22:18.948Z,1407288138.948 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-08-06T01:22:18.948Z,1407288138.948 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-08-06T01:22:18.949Z,1407288138.949 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-08-06T01:22:25.219Z,1407288145.219 [HFRadarModelCalc] Loaded
2014-08-06T01:22:25.219Z,1407288145.219 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2014-08-06T01:22:29.920Z,1407288149.920 [HFRadarCompactModelForecaster] Loaded
2014-08-06T01:22:29.920Z,1407288149.920 [ComponentRegistry](DEBUG): SyncComponent "HFRadarCompactModelForecaster" handled in the control thread.
2014-08-06T01:22:31.149Z,1407288151.149 [HFRCMSpaceInterpolator] Loaded
2014-08-06T01:22:31.150Z,1407288151.150 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSpaceInterpolator" handled in the control thread.
2014-08-06T01:22:31.152Z,1407288151.152 [HFRCMTimeInterpolator] Loaded
2014-08-06T01:22:31.152Z,1407288151.152 [ComponentRegistry](DEBUG): SyncComponent "HFRCMTimeInterpolator" handled in the control thread.
2014-08-06T01:22:32.409Z,1407288152.409 [HFRCMReconstructedInterpolator] Loaded
2014-08-06T01:22:32.409Z,1407288152.409 [ComponentRegistry](DEBUG): SyncComponent "HFRCMReconstructedInterpolator" handled in the control thread.
2014-08-06T01:22:32.421Z,1407288152.421 [HFRCMSurfaceCurrentAtVehicleLocation] Loaded
2014-08-06T01:22:32.422Z,1407288152.422 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSurfaceCurrentAtVehicleLocation" handled in the control thread.
2014-08-06T01:22:32.450Z,1407288152.450 [HFRCMVirtualSurfaceDrifter] Loaded
2014-08-06T01:22:32.450Z,1407288152.450 [ComponentRegistry](DEBUG): SyncComponent "HFRCMVirtualSurfaceDrifter" handled in the control thread.
2014-08-06T01:22:32.451Z,1407288152.451 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-08-06T01:22:32.452Z,1407288152.452 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-08-06T01:22:32.702Z,1407288152.702 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-08-06T01:22:32.703Z,1407288152.703 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-08-06T01:22:32.791Z,1407288152.791 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-08-06T01:22:32.791Z,1407288152.791 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-08-06T01:22:32.838Z,1407288152.838 [DeadReckonWithRespectToWater] Loaded
2014-08-06T01:22:32.839Z,1407288152.839 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToWater" handled in the control thread.
2014-08-06T01:22:32.887Z,1407288152.887 [DeadReckonWithRespectToSeafloor] Loaded
2014-08-06T01:22:32.888Z,1407288152.888 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2014-08-06T01:22:32.951Z,1407288152.951 [DeadReckonUsingDVLWaterTrack] Loaded
2014-08-06T01:22:32.951Z,1407288152.951 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingDVLWaterTrack" handled in the control thread.
2014-08-06T01:22:33.001Z,1407288153.001 [DeadReckonUsingCompactModelForecast] Loaded
2014-08-06T01:22:33.002Z,1407288153.002 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingCompactModelForecast" handled in the control thread.
2014-08-06T01:22:33.019Z,1407288153.019 [NavChart] Loaded
2014-08-06T01:22:33.020Z,1407288153.020 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-08-06T01:22:33.024Z,1407288153.024 [UniversalFixResidualReporter] Loaded
2014-08-06T01:22:33.025Z,1407288153.025 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-08-06T01:22:33.025Z,1407288153.025 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-08-06T01:22:33.026Z,1407288153.026 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-08-06T01:22:33.032Z,1407288153.032 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-08-06T01:22:33.033Z,1407288153.033 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-08-06T01:22:33.213Z,1407288153.213 [CTD_NeilBrown] Loaded
2014-08-06T01:22:33.213Z,1407288153.213 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-08-06T01:22:33.214Z,1407288153.214 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407B94E0
2014-08-06T01:22:33.215Z,1407288153.215 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1595
2014-08-06T01:22:33.231Z,1407288153.231 [PAR_Licor] Loaded
2014-08-06T01:22:33.231Z,1407288153.231 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-08-06T01:22:33.268Z,1407288153.268 [WetLabsBB2FL] Loaded
2014-08-06T01:22:33.269Z,1407288153.269 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-08-06T01:22:33.270Z,1407288153.270 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407E94E0
2014-08-06T01:22:33.270Z,1407288153.270 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1596
2014-08-06T01:22:33.271Z,1407288153.271 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-08-06T01:22:33.271Z,1407288153.271 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-08-06T01:22:33.577Z,1407288153.577 [AHRS_sp3003D] Loaded
2014-08-06T01:22:33.577Z,1407288153.577 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-08-06T01:22:33.848Z,1407288153.848 [Batt_Ocean_Server] Loaded
2014-08-06T01:22:33.848Z,1407288153.848 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-08-06T01:22:33.862Z,1407288153.862 [Depth_Keller] Loaded
2014-08-06T01:22:33.863Z,1407288153.863 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-08-06T01:22:33.868Z,1407288153.868 [DropWeight] Loaded
2014-08-06T01:22:33.868Z,1407288153.868 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-08-06T01:22:34.008Z,1407288154.008 [DVL_micro] Loaded
2014-08-06T01:22:34.008Z,1407288154.008 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2014-08-06T01:22:34.106Z,1407288154.106 [NAL9602] Loaded
2014-08-06T01:22:34.106Z,1407288154.106 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-08-06T01:22:34.150Z,1407288154.150 [Onboard] Loaded
2014-08-06T01:22:34.151Z,1407288154.151 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-08-06T01:22:34.158Z,1407288154.158 [Radio_Freewave] Loaded
2014-08-06T01:22:34.159Z,1407288154.159 [ComponentRegistry](DEBUG): Component "Radio_Freewave" handled in its own thread.
2014-08-06T01:22:34.160Z,1407288154.160 [Radio_Freewave ThreadHandler](DEBUG): Created PCaller Thread at 40A204E0
2014-08-06T01:22:34.160Z,1407288154.160 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 1597
2014-08-06T01:22:34.296Z,1407288154.296 [DAT] Loaded
2014-08-06T01:22:34.296Z,1407288154.296 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2014-08-06T01:22:34.303Z,1407288154.303 [SCPI] Loaded
2014-08-06T01:22:34.304Z,1407288154.304 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-08-06T01:22:34.304Z,1407288154.304 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-08-06T01:22:34.305Z,1407288154.305 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-08-06T01:22:34.412Z,1407288154.412 [BuoyancyServo] Loaded
2014-08-06T01:22:34.412Z,1407288154.412 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-08-06T01:22:34.425Z,1407288154.425 [ElevatorServo] Loaded
2014-08-06T01:22:34.426Z,1407288154.426 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-08-06T01:22:34.438Z,1407288154.438 [MassServo] Loaded
2014-08-06T01:22:34.438Z,1407288154.438 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-08-06T01:22:34.451Z,1407288154.451 [RudderServo] Loaded
2014-08-06T01:22:34.451Z,1407288154.451 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-08-06T01:22:34.463Z,1407288154.463 [ThrusterServo] Loaded
2014-08-06T01:22:34.463Z,1407288154.463 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-08-06T01:22:34.464Z,1407288154.464 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-08-06T01:22:34.465Z,1407288154.465 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-08-06T01:22:34.634Z,1407288154.634 [InternalSim] Loaded
2014-08-06T01:22:34.634Z,1407288154.634 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-08-06T01:22:34.635Z,1407288154.635 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-08-06T01:22:34.635Z,1407288154.635 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-08-06T01:22:34.661Z,1407288154.661 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-08-06T01:22:34.663Z,1407288154.663 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-08-06T01:22:34.664Z,1407288154.664 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-08-06T01:22:34.671Z,1407288154.671 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-08-06T01:22:34.672Z,1407288154.672 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD14E0
2014-08-06T01:22:34.673Z,1407288154.673 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1598
2014-08-06T01:22:34.678Z,1407288154.678 [Supervisor](INFO): Main Thread ID is 774
2014-08-06T01:22:34.678Z,1407288154.678 [Supervisor](DEBUG): Running supervisor.
2014-08-06T01:22:34.679Z,1407288154.679 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1599
2014-08-06T01:22:34.684Z,1407288154.684 [controlThread ThreadHandler](INFO): Handler Thread ID is 1600
2014-08-06T01:22:34.684Z,1407288154.684 [controlThread](DEBUG): Initializing ControlThread
2014-08-06T01:22:34.685Z,1407288154.685 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-08-06T01:22:34.687Z,1407288154.687 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-08-06T01:22:34.687Z,1407288154.687 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-08-06T01:22:34.688Z,1407288154.688 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-08-06T01:22:34.688Z,1407288154.688 [SBIT](INFO): Initialize SBIT Component.
2014-08-06T01:22:34.689Z,1407288154.689 [SBIT](IMPORTANT): Tethys CM Info: SVN revision: 11481
2014-08-06T01:22:34.689Z,1407288154.689 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2014-08-06T01:22:34.689Z,1407288154.689 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-08-06T01:22:34.690Z,1407288154.690 [IBIT](INFO): Initialize IBIT Component.
2014-08-06T01:22:34.691Z,1407288154.691 [CBIT](DEBUG): Initialize CBIT Component.
2014-08-06T01:22:34.691Z,1407288154.691 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2014-08-06T01:22:34.692Z,1407288154.692 [logger ThreadHandler](INFO): Handler Thread ID is 1601
2014-08-06T01:22:34.712Z,1407288154.712 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1602
2014-08-06T01:22:34.713Z,1407288154.713 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-08-06T01:22:34.716Z,1407288154.716 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-08-06T01:22:34.716Z,1407288154.716 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-08-06T01:22:34.717Z,1407288154.717 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-08-06T01:22:34.717Z,1407288154.717 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-08-06T01:22:34.717Z,1407288154.717 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-08-06T01:22:34.726Z,1407288154.726 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-08-06T01:22:34.728Z,1407288154.728 [HFRadarCompactModelForecaster](DEBUG): Found new ECs!
2014-08-06T01:22:34.741Z,1407288154.741 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1604
2014-08-06T01:22:34.745Z,1407288154.745 [WetLabsBB2FL](INFO): Powering down
2014-08-06T01:22:34.765Z,1407288154.765 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 1605
2014-08-06T01:22:34.789Z,1407288154.789 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1606
2014-08-06T01:22:34.812Z,1407288154.812 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-08-06T01:22:34.813Z,1407288154.813 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-08-06T01:22:34.813Z,1407288154.813 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-08-06T01:22:34.813Z,1407288154.813 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-08-06T01:22:34.814Z,1407288154.814 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-08-06T01:22:34.814Z,1407288154.814 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-08-06T01:22:34.814Z,1407288154.814 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-08-06T01:22:34.815Z,1407288154.815 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-08-06T01:22:34.815Z,1407288154.815 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-08-06T01:22:44.088Z,1407288164.088 [HFRadarCompactModelForecaster](IMPORTANT): forecast time 201408052200: published 50 modes in rows, 61 hours in columns
2014-08-06T01:22:44.091Z,1407288164.091 [HFRadarCompactModelForecaster](IMPORTANT): expansionCoefficients_[0][48] = 19.649141 for 2014-08-05T22:00:00.000Z
2014-08-06T01:22:44.099Z,1407288164.099 [HFRCMSpaceInterpolator](DEBUG): Initializing HFRCMSpaceInterpolator component with verbosity level 0.
2014-08-06T01:22:44.100Z,1407288164.100 [HFRCMTimeInterpolator](DEBUG): Initializing HFRCMTimeInterpolator component.
2014-08-06T01:22:44.101Z,1407288164.101 [HFRCMReconstructedInterpolator](INFO): Initializing HFRCMReconstructedInterpolator component with velocityAccuracy_ = 0.300000 m/s.
2014-08-06T01:22:44.102Z,1407288164.102 [HFRCMSurfaceCurrentAtVehicleLocation](DEBUG): Initializing HFRCMSurfaceCurrentAtVehicleLocation component.
2014-08-06T01:22:44.110Z,1407288164.110 [HFRCMVirtualSurfaceDrifter](DEBUG): Initializing HFRCMVirtualSurfaceDrifter component.
2014-08-06T01:22:44.111Z,1407288164.111 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-08-06T01:22:44.111Z,1407288164.111 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component.
2014-08-06T01:22:44.111Z,1407288164.111 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component.
2014-08-06T01:22:44.112Z,1407288164.112 [DeadReckonUsingDVLWaterTrack](DEBUG): Initializing DeadReckonUsingDVLWaterTrack component.
2014-08-06T01:22:44.112Z,1407288164.112 [DeadReckonUsingCompactModelForecast](DEBUG): Initializing DeadReckonUsingCompactModelForecast component.
2014-08-06T01:22:44.113Z,1407288164.113 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-08-06T01:22:44.113Z,1407288164.113 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-08-06T01:22:46.387Z,1407288166.387 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-08-06T01:22:46.426Z,1407288166.426 [InternalSim](DEBUG):  InternalSim initializing...
2014-08-06T01:22:46.540Z,1407288166.540 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-08-06T01:22:46.567Z,1407288166.567 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-08-06T01:22:46.585Z,1407288166.585 [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-06T01:22:46.585Z,1407288166.585 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-08-06T01:22:46.657Z,1407288166.657 [Default:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-08-06T01:22:46.699Z,1407288166.699 [Default:CheckIn:A.SetSpeed](DEBUG): Construct.
2014-08-06T01:22:46.706Z,1407288166.706 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-08-06T01:22:46.725Z,1407288166.725 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-08-06T01:22:46.745Z,1407288166.745 [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-06T01:22:46.754Z,1407288166.754 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,PAR_Licor,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,DAT,SCPI,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-06T01:22:46.947Z,1407288166.947 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-08-06T01:22:46.996Z,1407288166.996 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2014-08-06T01:22:47.058Z,1407288167.058 [Radio_Freewave](INFO): Powering up
2014-08-06T01:22:47.061Z,1407288167.061 [DVL_micro](INFO): Initializing
2014-08-06T01:22:47.078Z,1407288167.078 [NAL9602](INFO): Powering up NAL9602
2014-08-06T01:22:47.271Z,1407288167.271 [DAT](INFO): Powering up
2014-08-06T01:22:47.271Z,1407288167.271 [DAT](DEBUG): Initializing DAT.
2014-08-06T01:22:47.869Z,1407288167.869 [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-06T01:22:54.552Z,1407288174.552 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-08-06T01:22:54.559Z,1407288174.559 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-08-06T01:22:54.585Z,1407288174.585 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-08-06T01:22:54.591Z,1407288174.591 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-08-06T01:22:54.605Z,1407288174.605 [MassServo](DEBUG): Initializing EZServoServo.
2014-08-06T01:22:54.611Z,1407288174.611 [MassServo](DEBUG): Initializing MassServo.
2014-08-06T01:22:54.624Z,1407288174.624 [RudderServo](DEBUG): Initializing EZServoServo.
2014-08-06T01:22:54.631Z,1407288174.631 [RudderServo](DEBUG): Initializing RudderServo.
2014-08-06T01:22:54.650Z,1407288174.650 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-08-06T01:22:54.659Z,1407288174.659 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-08-06T01:22:55.681Z,1407288175.681 [SBIT](IMPORTANT): Beginning Startup BIT
2014-08-06T01:22:55.684Z,1407288175.684 [CBIT](IMPORTANT): Beginning GF scan
2014-08-06T01:22:57.888Z,1407288177.888 [NAL9602](INFO): NAL9602 initialized
2014-08-06T01:23:07.782Z,1407288187.782 [DAT](INFO): Powering down
2014-08-06T01:23:23.136Z,1407288203.136 [CBIT](IMPORTANT): No ground fault detected
2014-08-06T01:23:49.637Z,1407288229.637 [SBIT](IMPORTANT): SBIT PASSED
2014-08-06T01:23:50.044Z,1407288230.044 [MissionManager](IMPORTANT): Started mission Startup
2014-08-06T01:23:50.044Z,1407288230.044 [Startup] Running Loop=1
2014-08-06T01:23:50.044Z,1407288230.044 [Startup](INFO): Aggregate::initialize Startup
2014-08-06T01:23:50.044Z,1407288230.044 [Startup:A.GoToSurface] Running Loop=1
2014-08-06T01:23:50.086Z,1407288230.086 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-08-06T01:23:50.086Z,1407288230.086 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-08-06T01:23:50.087Z,1407288230.087 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-08-06T01:23:50.087Z,1407288230.087 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-08-06T01:23:50.106Z,1407288230.106 [Startup:StartupSatComms] Running Loop=1
2014-08-06T01:23:50.106Z,1407288230.106 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-08-06T01:23:50.107Z,1407288230.107 [Startup:StartupSatComms:A] Running Loop=1
2014-08-06T01:23:50.496Z,1407288230.496 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-08-06T01:24:50.371Z,1407288290.371 [Startup:StartupSatComms:A](INFO): Timed out from 2014-08-06T01:23:50.1Z
2014-08-06T01:24:50.371Z,1407288290.371 [Startup:StartupSatComms:A] Stopped
2014-08-06T01:24:50.371Z,1407288290.371 [Startup:StartupSatComms:B] Running Loop=1
2014-08-06T01:24:50.776Z,1407288290.776 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-08-06T01:25:50.730Z,1407288350.730 [Startup:StartupSatComms:B](INFO): Timed out from 2014-08-06T01:24:50.4Z
2014-08-06T01:25:50.730Z,1407288350.730 [Startup:StartupSatComms:B] Stopped
2014-08-06T01:25:50.731Z,1407288350.731 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2014-08-06T01:25:50.731Z,1407288350.731 [Startup:StartupSatComms] Stopped
2014-08-06T01:25:50.731Z,1407288350.731 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2014-08-06T01:25:50.732Z,1407288350.732 [Startup](INFO): Completed Startup
2014-08-06T01:25:50.732Z,1407288350.732 [Startup] Stopped
2014-08-06T01:25:50.732Z,1407288350.732 [Startup](INFO): Aggregate::uninitialize Startup
2014-08-06T01:25:50.732Z,1407288350.732 [Startup:A.GoToSurface] Stopped
2014-08-06T01:25:50.732Z,1407288350.732 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-08-06T01:25:51.239Z,1407288351.239 [MissionManager](IMPORTANT): Started mission Default
2014-08-06T01:25:51.239Z,1407288351.239 [Default] Running Loop=1
2014-08-06T01:25:51.239Z,1407288351.239 [Default](INFO): Aggregate::initialize Default
2014-08-06T01:25:51.239Z,1407288351.239 [Default:A.GoToSurface] Running Loop=1
2014-08-06T01:25:51.239Z,1407288351.239 [Default:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-08-06T01:25:51.240Z,1407288351.240 [Default:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-08-06T01:25:51.241Z,1407288351.241 [Default:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.