2014-05-13T16:07:06.075Z,1399997226.075 [Supervisor](DEBUG): Initializing supervisor.
2014-05-13T16:07:06.077Z,1399997226.077 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-05-13T16:07:06.078Z,1399997226.078 [SyncHandler](INFO): Protected caller Thread ID is 1103
2014-05-13T16:07:06.078Z,1399997226.078 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-05-13T16:07:06.079Z,1399997226.079 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2014-05-13T16:07:06.080Z,1399997226.080 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1104
2014-05-13T16:07:06.083Z,1399997226.083 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-05-13T16:07:06.095Z,1399997226.095 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-05-13T16:07:06.096Z,1399997226.096 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2014-05-13T16:07:06.096Z,1399997226.096 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1105
2014-05-13T16:07:06.097Z,1399997226.097 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-05-13T16:07:06.098Z,1399997226.098 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2014-05-13T16:07:06.099Z,1399997226.099 [logger ThreadHandler](INFO): Protected caller Thread ID is 1106
2014-05-13T16:07:06.101Z,1399997226.101 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-05-13T16:07:06.101Z,1399997226.101 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-05-13T16:07:06.103Z,1399997226.103 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-05-13T16:07:06.490Z,1399997226.490 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-05-13T16:07:06.491Z,1399997226.491 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-05-13T16:07:06.790Z,1399997226.790 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-05-13T16:07:06.790Z,1399997226.790 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-05-13T16:07:06.877Z,1399997226.877 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-05-13T16:07:06.878Z,1399997226.878 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-05-13T16:07:07.073Z,1399997227.073 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-05-13T16:07:07.073Z,1399997227.073 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-05-13T16:07:07.242Z,1399997227.242 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-05-13T16:07:07.243Z,1399997227.243 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-05-13T16:07:07.569Z,1399997227.569 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-05-13T16:07:07.569Z,1399997227.569 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-05-13T16:07:07.785Z,1399997227.785 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-05-13T16:07:07.785Z,1399997227.786 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-05-13T16:07:08.158Z,1399997228.158 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-05-13T16:07:08.159Z,1399997228.159 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-05-13T16:07:08.272Z,1399997228.272 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-05-13T16:07:08.272Z,1399997228.272 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-05-13T16:07:08.802Z,1399997228.802 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-05-13T16:07:08.803Z,1399997228.803 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-05-13T16:07:08.915Z,1399997228.915 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-05-13T16:07:08.916Z,1399997228.916 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-05-13T16:07:09.004Z,1399997229.004 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-05-13T16:07:09.116Z,1399997229.116 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-05-13T16:07:09.116Z,1399997229.116 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-05-13T16:07:09.222Z,1399997229.222 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-05-13T16:07:09.222Z,1399997229.222 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-05-13T16:07:09.366Z,1399997229.366 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-05-13T16:07:09.368Z,1399997229.368 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-05-13T16:07:09.369Z,1399997229.369 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-05-13T16:07:09.480Z,1399997229.480 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-05-13T16:07:09.618Z,1399997229.618 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-05-13T16:07:09.718Z,1399997229.718 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-05-13T16:07:09.814Z,1399997229.814 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-05-13T16:07:09.968Z,1399997229.968 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-05-13T16:07:10.092Z,1399997230.092 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-05-13T16:07:10.180Z,1399997230.180 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-05-13T16:07:10.289Z,1399997230.289 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-05-13T16:07:10.394Z,1399997230.394 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-05-13T16:07:10.494Z,1399997230.494 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-05-13T16:07:10.584Z,1399997230.584 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-05-13T16:07:10.684Z,1399997230.684 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2014-05-13T16:07:10.686Z,1399997230.686 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-05-13T16:07:11.032Z,1399997231.032 [AHRS_sp3003D] Loaded
2014-05-13T16:07:11.033Z,1399997231.033 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-05-13T16:07:11.347Z,1399997231.347 [Batt_Ocean_Server] Loaded
2014-05-13T16:07:11.347Z,1399997231.347 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-05-13T16:07:11.361Z,1399997231.361 [Depth_Keller] Loaded
2014-05-13T16:07:11.362Z,1399997231.362 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-05-13T16:07:11.367Z,1399997231.367 [DropWeight] Loaded
2014-05-13T16:07:11.367Z,1399997231.367 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-05-13T16:07:11.517Z,1399997231.517 [DVL_micro] Loaded
2014-05-13T16:07:11.518Z,1399997231.518 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2014-05-13T16:07:11.625Z,1399997231.625 [NAL9602] Loaded
2014-05-13T16:07:11.625Z,1399997231.625 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-05-13T16:07:11.680Z,1399997231.680 [Onboard] Loaded
2014-05-13T16:07:11.681Z,1399997231.681 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-05-13T16:07:11.688Z,1399997231.688 [Radio_Freewave] Loaded
2014-05-13T16:07:11.688Z,1399997231.688 [ComponentRegistry](DEBUG): Component "Radio_Freewave" handled in its own thread.
2014-05-13T16:07:11.690Z,1399997231.690 [Radio_Freewave ThreadHandler](DEBUG): Created PCaller Thread at 406074E0
2014-05-13T16:07:11.690Z,1399997231.690 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 1188
2014-05-13T16:07:11.697Z,1399997231.697 [SCPI] Loaded
2014-05-13T16:07:11.698Z,1399997231.698 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-05-13T16:07:11.698Z,1399997231.698 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-05-13T16:07:11.699Z,1399997231.699 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-05-13T16:07:11.872Z,1399997231.872 [InternalSim] Loaded
2014-05-13T16:07:11.873Z,1399997231.873 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-05-13T16:07:11.873Z,1399997231.873 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-05-13T16:07:11.874Z,1399997231.874 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-05-13T16:07:12.133Z,1399997232.133 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-05-13T16:07:12.134Z,1399997232.134 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-05-13T16:07:12.140Z,1399997232.140 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2014-05-13T16:07:12.145Z,1399997232.145 [AsyncPiEstimator] Loaded
2014-05-13T16:07:12.145Z,1399997232.145 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2014-05-13T16:07:12.147Z,1399997232.147 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406E44E0
2014-05-13T16:07:12.147Z,1399997232.147 [AsyncPiEstimator ThreadHandler](INFO): Protected caller Thread ID is 1189
2014-05-13T16:07:12.148Z,1399997232.148 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-05-13T16:07:12.148Z,1399997232.148 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-05-13T16:07:12.234Z,1399997232.234 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-05-13T16:07:12.234Z,1399997232.234 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-05-13T16:07:12.283Z,1399997232.283 [DeadReckonWithRespectToWater] Loaded
2014-05-13T16:07:12.283Z,1399997232.283 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToWater" handled in the control thread.
2014-05-13T16:07:12.332Z,1399997232.332 [DeadReckonWithRespectToSeafloor] Loaded
2014-05-13T16:07:12.333Z,1399997232.333 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2014-05-13T16:07:12.384Z,1399997232.384 [DeadReckonUsingDVLWaterTrack] Loaded
2014-05-13T16:07:12.384Z,1399997232.384 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingDVLWaterTrack" handled in the control thread.
2014-05-13T16:07:12.401Z,1399997232.401 [NavChart] Loaded
2014-05-13T16:07:12.402Z,1399997232.402 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-05-13T16:07:12.406Z,1399997232.406 [UniversalFixResidualReporter] Loaded
2014-05-13T16:07:12.406Z,1399997232.406 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-05-13T16:07:12.407Z,1399997232.407 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-05-13T16:07:12.408Z,1399997232.408 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-05-13T16:07:12.461Z,1399997232.461 [VerticalControl](DEBUG): Construct VerticalControl.
2014-05-13T16:07:12.579Z,1399997232.579 [VerticalControl] Loaded
2014-05-13T16:07:12.579Z,1399997232.579 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-05-13T16:07:12.580Z,1399997232.580 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-05-13T16:07:12.654Z,1399997232.654 [HorizontalControl] Loaded
2014-05-13T16:07:12.654Z,1399997232.654 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-05-13T16:07:12.654Z,1399997232.654 [SpeedControl](DEBUG): Construct SpeedControl.
2014-05-13T16:07:12.657Z,1399997232.657 [SpeedControl] Loaded
2014-05-13T16:07:12.657Z,1399997232.657 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-05-13T16:07:12.658Z,1399997232.658 [LoopControl](DEBUG): Construct LoopControl.
2014-05-13T16:07:12.658Z,1399997232.658 [LoopControl] Loaded
2014-05-13T16:07:12.658Z,1399997232.658 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-05-13T16:07:12.659Z,1399997232.659 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-05-13T16:07:12.659Z,1399997232.659 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-05-13T16:07:12.685Z,1399997232.685 [DepthRateCalculator] Loaded
2014-05-13T16:07:12.686Z,1399997232.686 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-05-13T16:07:12.692Z,1399997232.692 [PitchRateCalculator] Loaded
2014-05-13T16:07:12.692Z,1399997232.692 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-05-13T16:07:12.703Z,1399997232.703 [SpeedCalculator] Loaded
2014-05-13T16:07:12.704Z,1399997232.704 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-05-13T16:07:12.721Z,1399997232.721 [TempGradientCalculator] Loaded
2014-05-13T16:07:12.722Z,1399997232.722 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-05-13T16:07:12.727Z,1399997232.727 [YawRateCalculator] Loaded
2014-05-13T16:07:12.727Z,1399997232.727 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-05-13T16:07:12.728Z,1399997232.728 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-05-13T16:07:12.729Z,1399997232.729 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-05-13T16:07:12.862Z,1399997232.862 [CTD_NeilBrown] Loaded
2014-05-13T16:07:12.862Z,1399997232.862 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-05-13T16:07:12.863Z,1399997232.863 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407864E0
2014-05-13T16:07:12.864Z,1399997232.864 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1190
2014-05-13T16:07:12.877Z,1399997232.877 [ISUS] Loaded
2014-05-13T16:07:12.878Z,1399997232.878 [ComponentRegistry](DEBUG): SyncComponent "ISUS" handled in the control thread.
2014-05-13T16:07:12.894Z,1399997232.894 [PAR_Licor] Loaded
2014-05-13T16:07:12.894Z,1399997232.894 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-05-13T16:07:12.933Z,1399997232.933 [WetLabsBB2FL] Loaded
2014-05-13T16:07:12.933Z,1399997232.933 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-05-13T16:07:12.934Z,1399997232.934 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407B64E0
2014-05-13T16:07:12.934Z,1399997232.934 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1191
2014-05-13T16:07:12.935Z,1399997232.935 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-05-13T16:07:12.935Z,1399997232.935 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-05-13T16:07:13.037Z,1399997233.037 [SBIT](DEBUG): Construct Startup Built In Test.
2014-05-13T16:07:13.050Z,1399997233.050 [SBIT] Loaded
2014-05-13T16:07:13.050Z,1399997233.050 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-05-13T16:07:13.051Z,1399997233.051 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-05-13T16:07:13.064Z,1399997233.064 [IBIT] Loaded
2014-05-13T16:07:13.065Z,1399997233.065 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-05-13T16:07:13.067Z,1399997233.067 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-05-13T16:07:13.141Z,1399997233.141 [CBIT] Loaded
2014-05-13T16:07:13.141Z,1399997233.141 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-05-13T16:07:13.142Z,1399997233.142 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-05-13T16:07:13.142Z,1399997233.142 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-05-13T16:07:13.186Z,1399997233.186 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-05-13T16:07:13.187Z,1399997233.187 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-05-13T16:07:13.293Z,1399997233.293 [BuoyancyServo] Loaded
2014-05-13T16:07:13.293Z,1399997233.293 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-05-13T16:07:13.306Z,1399997233.306 [ElevatorServo] Loaded
2014-05-13T16:07:13.306Z,1399997233.306 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-05-13T16:07:13.319Z,1399997233.319 [MassServo] Loaded
2014-05-13T16:07:13.319Z,1399997233.319 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-05-13T16:07:13.332Z,1399997233.332 [RudderServo] Loaded
2014-05-13T16:07:13.332Z,1399997233.332 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-05-13T16:07:13.345Z,1399997233.345 [ThrusterServo] Loaded
2014-05-13T16:07:13.346Z,1399997233.346 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-05-13T16:07:13.346Z,1399997233.346 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-05-13T16:07:13.347Z,1399997233.347 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-05-13T16:07:13.371Z,1399997233.371 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-05-13T16:07:13.373Z,1399997233.373 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-05-13T16:07:13.374Z,1399997233.374 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-05-13T16:07:13.380Z,1399997233.380 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-05-13T16:07:13.382Z,1399997233.382 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 408854E0
2014-05-13T16:07:13.382Z,1399997233.382 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1192
2014-05-13T16:07:13.387Z,1399997233.387 [Supervisor](INFO): Main Thread ID is 772
2014-05-13T16:07:13.387Z,1399997233.387 [Supervisor](DEBUG): Running supervisor.
2014-05-13T16:07:13.388Z,1399997233.388 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1193
2014-05-13T16:07:13.390Z,1399997233.390 [controlThread ThreadHandler](INFO): Handler Thread ID is 1194
2014-05-13T16:07:13.391Z,1399997233.391 [controlThread](DEBUG): Initializing ControlThread
2014-05-13T16:07:13.394Z,1399997233.394 [logger ThreadHandler](INFO): Handler Thread ID is 1195
2014-05-13T16:07:13.414Z,1399997233.414 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 1196
2014-05-13T16:07:13.430Z,1399997233.430 [AsyncPiEstimator ThreadHandler](INFO): Handler Thread ID is 1197
2014-05-13T16:07:13.430Z,1399997233.430 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2014-05-13T16:07:13.454Z,1399997233.454 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1198
2014-05-13T16:07:13.454Z,1399997233.454 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-05-13T16:07:13.458Z,1399997233.458 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-05-13T16:07:13.467Z,1399997233.467 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1200
2014-05-13T16:07:13.468Z,1399997233.468 [WetLabsBB2FL](INFO): Powering down
2014-05-13T16:07:13.496Z,1399997233.496 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1201
2014-05-13T16:07:13.499Z,1399997233.499 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-05-13T16:07:13.500Z,1399997233.500 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-05-13T16:07:13.500Z,1399997233.500 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-05-13T16:07:13.500Z,1399997233.500 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-05-13T16:07:13.501Z,1399997233.501 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-05-13T16:07:13.501Z,1399997233.501 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-05-13T16:07:13.502Z,1399997233.502 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-05-13T16:07:13.502Z,1399997233.502 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-05-13T16:07:13.502Z,1399997233.502 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-05-13T16:07:15.015Z,1399997235.015 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-05-13T16:07:15.047Z,1399997235.047 [InternalSim](DEBUG):  InternalSim initializing...
2014-05-13T16:07:15.153Z,1399997235.153 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-05-13T16:07:15.153Z,1399997235.153 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component.
2014-05-13T16:07:15.154Z,1399997235.154 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component.
2014-05-13T16:07:15.154Z,1399997235.154 [DeadReckonUsingDVLWaterTrack](DEBUG): Initializing DeadReckonUsingDVLWaterTrack component.
2014-05-13T16:07:15.155Z,1399997235.155 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-05-13T16:07:15.155Z,1399997235.155 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-05-13T16:07:15.155Z,1399997235.155 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-05-13T16:07:15.164Z,1399997235.164 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-05-13T16:07:15.165Z,1399997235.165 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-05-13T16:07:15.165Z,1399997235.165 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-05-13T16:07:15.166Z,1399997235.166 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-05-13T16:07:15.166Z,1399997235.166 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-05-13T16:07:15.166Z,1399997235.166 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-05-13T16:07:15.167Z,1399997235.167 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-05-13T16:07:15.167Z,1399997235.167 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-05-13T16:07:15.169Z,1399997235.169 [SBIT](INFO): Initialize SBIT Component.
2014-05-13T16:07:15.169Z,1399997235.169 [SBIT](IMPORTANT): Tethys CM Info: 
 $Rev:11288
2014-05-13T16:07:15.170Z,1399997235.170 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2014-05-13T16:07:15.170Z,1399997235.170 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-05-13T16:07:15.170Z,1399997235.170 [IBIT](INFO): Initialize IBIT Component.
2014-05-13T16:07:15.171Z,1399997235.171 [CBIT](DEBUG): Initialize CBIT Component.
2014-05-13T16:07:15.172Z,1399997235.172 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2014-05-13T16:07:15.202Z,1399997235.202 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-05-13T16:07:15.236Z,1399997235.236 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-13T16:07:15.261Z,1399997235.261 [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-13T16:07:15.261Z,1399997235.261 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-05-13T16:07:15.329Z,1399997235.329 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2014-05-13T16:07:15.331Z,1399997235.331 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2014-05-13T16:07:15.359Z,1399997235.359 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-13T16:07:15.383Z,1399997235.383 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2014-05-13T16:07:15.386Z,1399997235.386 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-13T16:07:15.408Z,1399997235.408 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-05-13T16:07:15.519Z,1399997235.519 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-05-13T16:07:15.539Z,1399997235.539 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-13T16:07:15.587Z,1399997235.587 [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-13T16:07:15.593Z,1399997235.593 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,SCPI,ISUS,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,DeadReckonUsingMultipleVelocitySources,DeadReckonWithRespectToWater,DeadReckonWithRespectToSeafloor,DeadReckonUsingDVLWaterTrack,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2014-05-13T16:07:15.725Z,1399997235.725 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-05-13T16:07:15.814Z,1399997235.814 [Radio_Freewave](INFO): Powering up
2014-05-13T16:07:16.005Z,1399997236.005 [DVL_micro](INFO): Initializing
2014-05-13T16:07:16.619Z,1399997236.619 [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-13T16:07:16.783Z,1399997236.783 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-05-13T16:07:16.799Z,1399997236.799 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-05-13T16:07:16.809Z,1399997236.809 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-05-13T16:07:16.823Z,1399997236.823 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-05-13T16:07:16.853Z,1399997236.853 [MassServo](DEBUG): Initializing EZServoServo.
2014-05-13T16:07:16.867Z,1399997236.867 [MassServo](DEBUG): Initializing MassServo.
2014-05-13T16:07:16.889Z,1399997236.889 [RudderServo](DEBUG): Initializing EZServoServo.
2014-05-13T16:07:16.903Z,1399997236.903 [RudderServo](DEBUG): Initializing RudderServo.
2014-05-13T16:07:16.933Z,1399997236.933 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-05-13T16:07:16.951Z,1399997236.951 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-05-13T16:07:17.427Z,1399997237.427 [NAL9602](INFO): Powering up NAL9602
2014-05-13T16:07:28.201Z,1399997248.201 [NAL9602](INFO): NAL9602 initialized
2014-05-13T16:07:31.242Z,1399997251.242 [SBIT](IMPORTANT): Beginning Startup BIT
2014-05-13T16:07:31.245Z,1399997251.245 [CBIT](IMPORTANT): Beginning GF scan
2014-05-13T16:07:45.470Z,1399997265.470 [NAL9602](INFO): SBD MO Status=0, MOMSN=28378, MT Status=0, MTMSN=0
2014-05-13T16:07:45.470Z,1399997265.470 [NAL9602](INFO): No messages in MT queue
2014-05-13T16:07:51.564Z,1399997271.564 [NAL9602](IMPORTANT): GPS fix at: 1399997269.00
2014-05-13T16:07:58.344Z,1399997278.344 [CBIT](IMPORTANT): No ground fault detected
2014-05-13T16:08:00.048Z,1399997280.048 [NAL9602](INFO): Powering down
2014-05-13T16:08:26.041Z,1399997306.041 [SBIT](IMPORTANT): SBIT PASSED
2014-05-13T16:08:26.705Z,1399997306.705 [MissionManager](IMPORTANT): Started mission Startup
2014-05-13T16:08:26.705Z,1399997306.705 [Startup] Running Loop=1
2014-05-13T16:08:26.706Z,1399997306.706 [Startup](INFO): Aggregate::initialize Startup
2014-05-13T16:08:26.706Z,1399997306.706 [Startup:A.GoToSurface] Running Loop=1
2014-05-13T16:08:26.706Z,1399997306.706 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-13T16:08:26.756Z,1399997306.756 [Startup:StartupSatComms] Running Loop=1
2014-05-13T16:08:26.756Z,1399997306.756 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-05-13T16:08:26.756Z,1399997306.756 [Startup:StartupSatComms:A] Running Loop=1
2014-05-13T16:08:27.362Z,1399997307.362 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latit