2014-05-21T00:37:38.471Z,1400632658.471 [Supervisor](DEBUG): Initializing supervisor.
2014-05-21T00:37:38.474Z,1400632658.474 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-05-21T00:37:38.474Z,1400632658.474 [SyncHandler](INFO): Protected caller Thread ID is 919
2014-05-21T00:37:38.475Z,1400632658.475 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-05-21T00:37:38.476Z,1400632658.476 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2014-05-21T00:37:38.476Z,1400632658.476 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 920
2014-05-21T00:37:38.479Z,1400632658.479 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-05-21T00:37:38.490Z,1400632658.490 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-05-21T00:37:38.492Z,1400632658.492 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2014-05-21T00:37:38.492Z,1400632658.492 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 921
2014-05-21T00:37:38.493Z,1400632658.493 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-05-21T00:37:38.494Z,1400632658.494 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2014-05-21T00:37:38.494Z,1400632658.494 [logger ThreadHandler](INFO): Protected caller Thread ID is 922
2014-05-21T00:37:38.497Z,1400632658.497 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-05-21T00:37:38.497Z,1400632658.497 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-05-21T00:37:38.498Z,1400632658.498 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-05-21T00:37:38.866Z,1400632658.866 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-05-21T00:37:38.867Z,1400632658.867 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-05-21T00:37:39.155Z,1400632659.155 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-05-21T00:37:39.155Z,1400632659.155 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-05-21T00:37:39.243Z,1400632659.243 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-05-21T00:37:39.244Z,1400632659.244 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-05-21T00:37:39.432Z,1400632659.432 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-05-21T00:37:39.432Z,1400632659.432 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-05-21T00:37:39.599Z,1400632659.599 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-05-21T00:37:39.599Z,1400632659.599 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-05-21T00:37:39.915Z,1400632659.915 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-05-21T00:37:39.916Z,1400632659.916 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-05-21T00:37:40.102Z,1400632660.102 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-05-21T00:37:40.102Z,1400632660.102 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-05-21T00:37:40.450Z,1400632660.450 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-05-21T00:37:40.450Z,1400632660.450 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-05-21T00:37:40.562Z,1400632660.562 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-05-21T00:37:40.563Z,1400632660.563 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-05-21T00:37:41.070Z,1400632661.070 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-05-21T00:37:41.071Z,1400632661.071 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-05-21T00:37:41.182Z,1400632661.182 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-05-21T00:37:41.183Z,1400632661.183 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-05-21T00:37:41.270Z,1400632661.270 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-05-21T00:37:41.385Z,1400632661.385 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-05-21T00:37:41.386Z,1400632661.386 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-05-21T00:37:41.491Z,1400632661.491 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-05-21T00:37:41.491Z,1400632661.491 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-05-21T00:37:41.633Z,1400632661.633 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-05-21T00:37:41.634Z,1400632661.634 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-05-21T00:37:41.635Z,1400632661.635 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-05-21T00:37:41.766Z,1400632661.766 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-05-21T00:37:41.947Z,1400632661.947 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-05-21T00:37:42.047Z,1400632662.047 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-05-21T00:37:42.143Z,1400632662.143 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-05-21T00:37:42.294Z,1400632662.294 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-05-21T00:37:42.416Z,1400632662.416 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-05-21T00:37:42.505Z,1400632662.505 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-05-21T00:37:42.613Z,1400632662.613 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-05-21T00:37:42.718Z,1400632662.718 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-05-21T00:37:42.818Z,1400632662.818 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-05-21T00:37:42.909Z,1400632662.909 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-05-21T00:37:43.011Z,1400632663.011 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/
2014-05-21T00:37:43.011Z,1400632663.011 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2014-05-21T00:37:43.014Z,1400632663.014 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-05-21T00:37:43.362Z,1400632663.362 [AHRS_sp3003D] Loaded
2014-05-21T00:37:43.362Z,1400632663.362 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-05-21T00:37:43.666Z,1400632663.666 [Batt_Ocean_Server] Loaded
2014-05-21T00:37:43.666Z,1400632663.666 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-05-21T00:37:43.680Z,1400632663.680 [Depth_Keller] Loaded
2014-05-21T00:37:43.680Z,1400632663.680 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-05-21T00:37:43.823Z,1400632663.823 [DVL_micro] Loaded
2014-05-21T00:37:43.824Z,1400632663.824 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2014-05-21T00:37:43.925Z,1400632663.925 [NAL9602] Loaded
2014-05-21T00:37:43.925Z,1400632663.925 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-05-21T00:37:43.978Z,1400632663.978 [Onboard] Loaded
2014-05-21T00:37:43.979Z,1400632663.979 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-05-21T00:37:43.986Z,1400632663.986 [Radio_Freewave] Loaded
2014-05-21T00:37:43.986Z,1400632663.986 [ComponentRegistry](DEBUG): Component "Radio_Freewave" handled in its own thread.
2014-05-21T00:37:43.988Z,1400632663.988 [Radio_Freewave ThreadHandler](DEBUG): Created PCaller Thread at 4060F4E0
2014-05-21T00:37:43.988Z,1400632663.988 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 1004
2014-05-21T00:37:43.995Z,1400632663.995 [SCPI] Loaded
2014-05-21T00:37:43.995Z,1400632663.995 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-05-21T00:37:43.996Z,1400632663.996 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-05-21T00:37:43.996Z,1400632663.996 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-05-21T00:37:44.162Z,1400632664.162 [InternalSim] Loaded
2014-05-21T00:37:44.162Z,1400632664.162 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-05-21T00:37:44.163Z,1400632664.163 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-05-21T00:37:44.163Z,1400632664.163 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-05-21T00:37:44.416Z,1400632664.416 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-05-21T00:37:44.416Z,1400632664.416 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-05-21T00:37:44.422Z,1400632664.422 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-05-21T00:37:44.423Z,1400632664.423 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-05-21T00:37:44.503Z,1400632664.503 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-05-21T00:37:44.504Z,1400632664.504 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-05-21T00:37:44.550Z,1400632664.550 [DeadReckonWithRespectToWater] Loaded
2014-05-21T00:37:44.550Z,1400632664.550 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToWater" handled in the control thread.
2014-05-21T00:37:44.597Z,1400632664.597 [DeadReckonWithRespectToSeafloor] Loaded
2014-05-21T00:37:44.597Z,1400632664.597 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2014-05-21T00:37:44.645Z,1400632664.645 [DeadReckonUsingDVLWaterTrack] Loaded
2014-05-21T00:37:44.645Z,1400632664.645 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingDVLWaterTrack" handled in the control thread.
2014-05-21T00:37:44.694Z,1400632664.694 [DeadReckonUsingCompactModelForecast] Loaded
2014-05-21T00:37:44.695Z,1400632664.695 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingCompactModelForecast" handled in the control thread.
2014-05-21T00:37:44.711Z,1400632664.711 [NavChart] Loaded
2014-05-21T00:37:44.711Z,1400632664.711 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-05-21T00:37:44.715Z,1400632664.715 [UniversalFixResidualReporter] Loaded
2014-05-21T00:37:44.716Z,1400632664.716 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-05-21T00:37:44.716Z,1400632664.716 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-05-21T00:37:44.717Z,1400632664.717 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-05-21T00:37:44.766Z,1400632664.766 [VerticalControl](DEBUG): Construct VerticalControl.
2014-05-21T00:37:44.879Z,1400632664.879 [VerticalControl] Loaded
2014-05-21T00:37:44.879Z,1400632664.879 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-05-21T00:37:44.880Z,1400632664.880 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-05-21T00:37:44.950Z,1400632664.950 [HorizontalControl] Loaded
2014-05-21T00:37:44.950Z,1400632664.950 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-05-21T00:37:44.951Z,1400632664.951 [SpeedControl](DEBUG): Construct SpeedControl.
2014-05-21T00:37:44.952Z,1400632664.952 [SpeedControl] Loaded
2014-05-21T00:37:44.953Z,1400632664.953 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-05-21T00:37:44.953Z,1400632664.953 [LoopControl](DEBUG): Construct LoopControl.
2014-05-21T00:37:44.954Z,1400632664.954 [LoopControl] Loaded
2014-05-21T00:37:44.954Z,1400632664.954 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-05-21T00:37:44.955Z,1400632664.955 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-05-21T00:37:44.955Z,1400632664.955 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-05-21T00:37:44.974Z,1400632664.974 [DepthRateCalculator] Loaded
2014-05-21T00:37:44.974Z,1400632664.974 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-05-21T00:37:44.980Z,1400632664.980 [PitchRateCalculator] Loaded
2014-05-21T00:37:44.980Z,1400632664.980 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-05-21T00:37:44.987Z,1400632664.987 [SpeedCalculator] Loaded
2014-05-21T00:37:44.988Z,1400632664.988 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-05-21T00:37:45.004Z,1400632665.004 [TempGradientCalculator] Loaded
2014-05-21T00:37:45.005Z,1400632665.005 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-05-21T00:37:45.010Z,1400632665.010 [YawRateCalculator] Loaded
2014-05-21T00:37:45.011Z,1400632665.011 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-05-21T00:37:45.011Z,1400632665.011 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-05-21T00:37:45.012Z,1400632665.012 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-05-21T00:37:45.118Z,1400632665.118 [CTD_NeilBrown] Loaded
2014-05-21T00:37:45.119Z,1400632665.119 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-05-21T00:37:45.120Z,1400632665.120 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4075E4E0
2014-05-21T00:37:45.120Z,1400632665.120 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1005
2014-05-21T00:37:45.134Z,1400632665.134 [ISUS] Loaded
2014-05-21T00:37:45.134Z,1400632665.134 [ComponentRegistry](DEBUG): SyncComponent "ISUS" handled in the control thread.
2014-05-21T00:37:45.149Z,1400632665.149 [PAR_Licor] Loaded
2014-05-21T00:37:45.150Z,1400632665.150 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-05-21T00:37:45.186Z,1400632665.186 [WetLabsBB2FL] Loaded
2014-05-21T00:37:45.186Z,1400632665.186 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-05-21T00:37:45.187Z,1400632665.187 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4078E4E0
2014-05-21T00:37:45.187Z,1400632665.187 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1006
2014-05-21T00:37:45.188Z,1400632665.188 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-05-21T00:37:45.188Z,1400632665.188 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-05-21T00:37:45.284Z,1400632665.284 [SBIT](DEBUG): Construct Startup Built In Test.
2014-05-21T00:37:45.296Z,1400632665.296 [SBIT] Loaded
2014-05-21T00:37:45.296Z,1400632665.296 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-05-21T00:37:45.297Z,1400632665.297 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-05-21T00:37:45.310Z,1400632665.310 [IBIT] Loaded
2014-05-21T00:37:45.310Z,1400632665.310 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-05-21T00:37:45.312Z,1400632665.312 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-05-21T00:37:45.382Z,1400632665.382 [CBIT] Loaded
2014-05-21T00:37:45.383Z,1400632665.383 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-05-21T00:37:45.383Z,1400632665.383 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-05-21T00:37:45.384Z,1400632665.384 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-05-21T00:37:50.217Z,1400632670.217 [HFRadarModelCalc] Loaded
2014-05-21T00:37:50.218Z,1400632670.218 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2014-05-21T00:37:53.801Z,1400632673.801 [HFRadarCompactModelForecaster] Loaded
2014-05-21T00:37:53.801Z,1400632673.801 [ComponentRegistry](DEBUG): SyncComponent "HFRadarCompactModelForecaster" handled in the control thread.
2014-05-21T00:37:54.893Z,1400632674.893 [HFRCMSpaceInterpolator] Loaded
2014-05-21T00:37:54.893Z,1400632674.893 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSpaceInterpolator" handled in the control thread.
2014-05-21T00:37:54.896Z,1400632674.896 [HFRCMTimeInterpolator] Loaded
2014-05-21T00:37:54.896Z,1400632674.896 [ComponentRegistry](DEBUG): SyncComponent "HFRCMTimeInterpolator" handled in the control thread.
2014-05-21T00:37:54.909Z,1400632674.909 [HFRCMSurfaceCurrentAtVehicleLocation] Loaded
2014-05-21T00:37:54.909Z,1400632674.909 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSurfaceCurrentAtVehicleLocation" handled in the control thread.
2014-05-21T00:37:54.937Z,1400632674.937 [HFRCMVirtualSurfaceDrifter] Loaded
2014-05-21T00:37:54.937Z,1400632674.937 [ComponentRegistry](DEBUG): SyncComponent "HFRCMVirtualSurfaceDrifter" handled in the control thread.
2014-05-21T00:37:54.938Z,1400632674.938 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-05-21T00:37:54.938Z,1400632674.938 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-05-21T00:37:55.039Z,1400632675.039 [BuoyancyServo] Loaded
2014-05-21T00:37:55.039Z,1400632675.039 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-05-21T00:37:55.052Z,1400632675.052 [ElevatorServo] Loaded
2014-05-21T00:37:55.052Z,1400632675.052 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-05-21T00:37:55.064Z,1400632675.064 [MassServo] Loaded
2014-05-21T00:37:55.065Z,1400632675.065 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-05-21T00:37:55.077Z,1400632675.077 [RudderServo] Loaded
2014-05-21T00:37:55.077Z,1400632675.077 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-05-21T00:37:55.089Z,1400632675.089 [ThrusterServo] Loaded
2014-05-21T00:37:55.089Z,1400632675.089 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-05-21T00:37:55.090Z,1400632675.090 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-05-21T00:37:55.090Z,1400632675.090 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-05-21T00:37:55.115Z,1400632675.115 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-05-21T00:37:55.117Z,1400632675.117 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-05-21T00:37:55.118Z,1400632675.118 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-05-21T00:37:55.124Z,1400632675.124 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-05-21T00:37:55.125Z,1400632675.125 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A4D4E0
2014-05-21T00:37:55.126Z,1400632675.126 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1007
2014-05-21T00:37:55.130Z,1400632675.130 [Supervisor](INFO): Main Thread ID is 768
2014-05-21T00:37:55.131Z,1400632675.131 [Supervisor](DEBUG): Running supervisor.
2014-05-21T00:37:55.131Z,1400632675.131 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1008
2014-05-21T00:37:55.136Z,1400632675.136 [controlThread ThreadHandler](INFO): Handler Thread ID is 1009
2014-05-21T00:37:55.136Z,1400632675.136 [controlThread](DEBUG): Initializing ControlThread
2014-05-21T00:37:55.139Z,1400632675.139 [logger ThreadHandler](INFO): Handler Thread ID is 1010
2014-05-21T00:37:55.158Z,1400632675.158 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 1011
2014-05-21T00:37:55.174Z,1400632675.174 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1012
2014-05-21T00:37:55.174Z,1400632675.174 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-05-21T00:37:55.177Z,1400632675.177 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-05-21T00:37:55.187Z,1400632675.187 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1014
2014-05-21T00:37:55.189Z,1400632675.189 [WetLabsBB2FL](INFO): Powering down
2014-05-21T00:37:55.218Z,1400632675.218 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1015
2014-05-21T00:37:55.220Z,1400632675.220 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-05-21T00:37:55.221Z,1400632675.221 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-05-21T00:37:55.222Z,1400632675.222 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-05-21T00:37:55.222Z,1400632675.222 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-05-21T00:37:55.222Z,1400632675.222 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-05-21T00:37:55.222Z,1400632675.222 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-05-21T00:37:55.222Z,1400632675.222 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-05-21T00:37:55.223Z,1400632675.223 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-05-21T00:37:55.223Z,1400632675.223 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-05-21T00:37:56.699Z,1400632676.699 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-05-21T00:37:56.729Z,1400632676.729 [InternalSim](DEBUG):  InternalSim initializing...
2014-05-21T00:37:56.826Z,1400632676.826 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-05-21T00:37:56.827Z,1400632676.827 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component.
2014-05-21T00:37:56.827Z,1400632676.827 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component.
2014-05-21T00:37:56.827Z,1400632676.827 [DeadReckonUsingDVLWaterTrack](DEBUG): Initializing DeadReckonUsingDVLWaterTrack component.
2014-05-21T00:37:56.844Z,1400632676.844 [DeadReckonUsingCompactModelForecast](DEBUG): Initializing DeadReckonUsingCompactModelForecast component.
2014-05-21T00:37:56.844Z,1400632676.844 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-05-21T00:37:56.845Z,1400632676.845 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-05-21T00:37:56.845Z,1400632676.845 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-05-21T00:37:56.847Z,1400632676.847 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-05-21T00:37:56.848Z,1400632676.848 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-05-21T00:37:56.848Z,1400632676.848 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-05-21T00:37:56.849Z,1400632676.849 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-05-21T00:37:56.849Z,1400632676.849 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-05-21T00:37:56.849Z,1400632676.849 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-05-21T00:37:56.850Z,1400632676.850 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-05-21T00:37:56.850Z,1400632676.850 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-05-21T00:37:56.852Z,1400632676.852 [SBIT](INFO): Initialize SBIT Component.
2014-05-21T00:37:56.852Z,1400632676.852 [SBIT](IMPORTANT): Tethys CM Info: 
 $Rev:11321
2014-05-21T00:37:56.853Z,1400632676.853 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2014-05-21T00:37:56.853Z,1400632676.853 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-05-21T00:37:56.854Z,1400632676.854 [IBIT](INFO): Initialize IBIT Component.
2014-05-21T00:37:56.854Z,1400632676.854 [CBIT](DEBUG): Initialize CBIT Component.
2014-05-21T00:37:56.855Z,1400632676.855 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2014-05-21T00:37:56.887Z,1400632676.887 [HFRadarCompactModelForecaster](DEBUG): Found new ECs!
2014-05-21T00:37:56.887Z,1400632676.887 [HFRadarCompactModelForecaster](ERROR): Most recent ECs are more than six hours old.
2014-05-21T00:37:57.479Z,1400632677.479 [Radio_Freewave](INFO): Powering up
2014-05-21T00:37:58.287Z,1400632678.287 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0
2014-05-21T00:38:06.203Z,1400632686.203 [HFRadarCompactModelForecaster](IMPORTANT): Forecast time 201405201600: published 50 modes in rows, 61 hours in columns, 3050 elements.
2014-05-21T00:38:06.206Z,1400632686.206 [HFRCMSpaceInterpolator](DEBUG): Initializing HFRCMSpaceInterpolator component.
2014-05-21T00:38:06.218Z,1400632686.218 [HFRCMTimeInterpolator](DEBUG): Initializing HFRCMTimeInterpolator component.
2014-05-21T00:38:06.219Z,1400632686.219 [HFRCMSurfaceCurrentAtVehicleLocation](DEBUG): Initializing HFRCMSurfaceCurrentAtVehicleLocation component.
2014-05-21T00:38:06.219Z,1400632686.219 [HFRCMVirtualSurfaceDrifter](DEBUG): Initializing HFRCMVirtualSurfaceDrifter component.
2014-05-21T00:38:06.221Z,1400632686.221 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-05-21T00:38:06.253Z,1400632686.253 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-21T00:38:06.282Z,1400632686.282 [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-21T00:38:06.291Z,1400632686.291 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-05-21T00:38:06.369Z,1400632686.369 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2014-05-21T00:38:06.375Z,1400632686.375 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2014-05-21T00:38:06.387Z,1400632686.387 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-21T00:38:06.415Z,1400632686.415 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2014-05-21T00:38:06.426Z,1400632686.426 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-21T00:38:06.433Z,1400632686.433 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-05-21T00:38:06.479Z,1400632686.479 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-05-21T00:38:06.503Z,1400632686.503 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-05-21T00:38:06.523Z,1400632686.523 [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-21T00:38:06.530Z,1400632686.530 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DVL_micro,NAL9602,Onboard,SCPI,ISUS,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,HFRadarModelCalc,HFRadarCompactModelForecaster,HFRCMSpaceInterpolator,HFRCMTimeInterpolator,HFRCMSurfaceCurrentAtVehicleLocation,HFRCMVirtualSurfaceDrifter,DeadReckonUsingMultipleVelocitySources,DeadReckonWithRespectToWater,DeadReckonWithRespectToSeafloor,DeadReckonUsingDVLWaterTrack,DeadReckonUsingCompactModelForecast,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2014-05-21T00:38:06.605Z,1400632686.605 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-05-21T00:38:07.539Z,1400632687.539 [DVL_micro](INFO): Initializing
2014-05-21T00:38:07.555Z,1400632687.555 [NAL9602](INFO): Powering up NAL9602
2014-05-21T00:38:08.098Z,1400632688.098 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-05-21T00:38:08.106Z,1400632688.106 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-05-21T00:38:08.128Z,1400632688.128 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-05-21T00:38:08.133Z,1400632688.133 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-05-21T00:38:08.147Z,1400632688.147 [MassServo](DEBUG): Initializing EZServoServo.
2014-05-21T00:38:08.154Z,1400632688.154 [MassServo](DEBUG): Initializing MassServo.
2014-05-21T00:38:08.167Z,1400632688.167 [RudderServo](DEBUG): Initializing EZServoServo.
2014-05-21T00:38:08.174Z,1400632688.174 [RudderServo](DEBUG): Initializing RudderServo.
2014-05-21T00:38:08.191Z,1400632688.191 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-05-21T00:38:08.198Z,1400632688.198 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-05-21T00:38:08.722Z,1400632688.722 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2014-05-21T00:38:08.722Z,1400632688.722 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2014-05-21T00:38:08.722Z,1400632688.722 [AHRS_sp3003D] Hardware Fault, FailCount= 1
2014-05-21T00:38:08.723Z,1400632688.723 [AHRS_sp3003D](ERROR): Hardware Fault
2014-05-21T00:38:09.181Z,1400632689.181 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2014-05-21T00:38:09.199Z,1400632689.199 [AHRS_sp3003D](INFO): Powering down
2014-05-21T00:38:10.591Z,1400632690.591 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2014-05-21T00:38:10.591Z,1400632690.591 [AHRS_sp3003D] No Fault, FailCount= 1
2014-05-21T00:38:10.797Z,1400632690.797 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-05-21T00:38:11.935Z,1400632691.935 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2014-05-21T00:38:11.935Z,1400632691.935 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2014-05-21T00:38:11.935Z,1400632691.935 [AHRS_sp3003D] Hardware Fault, FailCount= 2
2014-05-21T00:38:11.935Z,1400632691.935 [AHRS_sp3003D](ERROR): Hardware Fault
2014-05-21T00:38:12.563Z,1400632692.563 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2014-05-21T00:38:12.605Z,1400632692.605 [AHRS_sp3003D](INFO): Powering down
2014-05-21T00:38:13.078Z,1400632693.078 [SBIT](IMPORTANT): Beginning Startup BIT
2014-05-21T00:38:13.096Z,1400632693.096 [CBIT](IMPORTANT): Beginning GF scan
2014-05-21T00:38:14.059Z,1400632694.059 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2014-05-21T00:38:14.059Z,1400632694.059 [AHRS_sp3003D] No Fault, FailCount= 2
2014-05-21T00:38:14.322Z,1400632694.322 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-05-21T00:38:15.645Z,1400632695.645 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2014-05-21T00:38:15.645Z,1400632695.645 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2014-05-21T00:38:15.645Z,1400632695.645 [AHRS_sp3003D] Hardware Fault, FailCount= 3
2014-05-21T00:38:15.645Z,1400632695.645 [AHRS_sp3003D](ERROR): Hardware Fault
2014-05-21T00:38:15.901Z,1400632695.901 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2014-05-21T00:38:15.926Z,1400632695.926 [AHRS_sp3003D](INFO): Powering down
2014-05-21T00:38:17.379Z,1400632697.379 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2014-05-21T00:38:17.379Z,1400632697.379 [AHRS_sp3003D] No Fault, FailCount= 3
2014-05-21T00:38:17.516Z,1400632697.516 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-05-21T00:38:18.649Z,1400632698.649 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2014-05-21T00:38:18.650Z,1400632698.650 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2014-05-21T00:38:18.650Z,1400632698.650 [AHRS_sp3003D] Hardware Fault, FailCount= 4
2014-05-21T00:38:18.650Z,1400632698.650 [AHRS_sp3003D](ERROR): Hardware Fault
2014-05-21T00:38:18.790Z,1400632698.790 [NAL9602](INFO): NAL9602 initialized
2014-05-21T00:38:18.981Z,1400632698.981 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2014-05-21T00:38:19.046Z,1400632699.046 [AHRS_sp3003D](INFO): Powering down
2014-05-21T00:38:20.420Z,1400632700.420 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2014-05-21T00:38:20.420Z,1400632700.420 [AHRS_sp3003D] No Fault, FailCount= 4
2014-05-21T00:38:20.620Z,1400632700.620 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-05-21T00:38:21.754Z,1400632701.754 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2014-05-21T00:38:21.754Z,1400632701.754 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2014-05-21T00:38:21.755Z,1400632701.755 [AHRS_sp3003D] Hardware Fault, FailCount= 5
2014-05-21T00:38:21.755Z,1400632701.755 [AHRS_sp3003D](ERROR): Hardware Fault
2014-05-21T00:38:21.958Z,1400632701.958 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2014-05-21T00:38:21.959Z,1400632701.959 [CBIT](CRITICAL): Hardware Fault in component: AHRS_sp3003D
2014-05-21T00:38:21.992Z,1400632701.992 [AHRS_sp3003D](INFO): Powering down
2014-05-21T00:38:22.222Z,1400632702.222 [CommandLine](FAULT): Scheduling is paused
2014-05-21T00:38:40.067Z,1400632720.067 [CBIT](IMPORTANT): No ground fault detected
2014-05-21T00:39:06.875Z,1400632746.875 [SBIT](IMPORTANT): SBIT PASSED
2014-05-21T00:39:07.196Z,1400632747.196 [MissionManager](IMPORTANT): Started mission Startup
2014-05-21T00:39:07.196Z,1400632747.196 [Startup] Running Loop=1
2014-05-21T00:39:07.196Z,1400632747.196 [Startup](INFO): Aggregate::initialize Startup
2014-05-21T00:39:07.196Z,1400632747.196 [Startup:A.GoToSurface] Running Loop=1
2014-05-21T00:39:07.196Z,1400632747.196 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-21T00:39:07.203Z,1400632747.203 [Startup:StartupSatComms] Running Loop=1
2014-05-21T00:39:07.203Z,1400632747.203 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-05-21T00:39:07.204Z,1400632747.204 [Startup:StartupSatComms:A] Running Loop=1
2014-05-21T00:39:07.613Z,1400632747.613 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-05-21T00:40:07.617Z,1400632807.617 [Startup:StartupSatComms:A](INFO): Timed out from 2014-05-21T00:39:07.2Z
2014-05-21T00:40:07.617Z,1400632807.617 [Startup:StartupSatComms:A] Stopped
2014-05-21T00:40:07.617Z,1400632807.617 [Startup:StartupSatComms:B] Running Loop=1
2014-05-21T00:40:08.049Z,1400632808.049 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-05-21T00:41:08.015Z,1400632868.015 [Startup:StartupSatComms:B](INFO): Timed out from 2014-05-21T00:40:07.6Z
2014-05-21T00:41:08.015Z,1400632868.015 [Startup:StartupSatComms:B] Stopped
2014-05-21T00:41:08.015Z,1400632868.015 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2014-05-21T00:41:08.015Z,1400632868.015 [Startup:StartupSatComms] Stopped
2014-05-21T00:41:08.015Z,1400632868.015 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2014-05-21T00:41:08.016Z,1400632868.016 [Startup](INFO): Completed Startup
2014-05-21T00:41:08.016Z,1400632868.016 [Startup] Stopped
2014-05-21T00:41:08.016Z,1400632868.016 [Startup](INFO): Aggregate::uninitialize Startup
2014-05-21T00:41:08.016Z,1400632868.016 [Startup:A.GoToSurface] Stopped
2014-05-21T00:41:08.016Z,1400632868.016 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-21T00:41:08.451Z,1400632868.451 [MissionManager](IMPORTANT): Started mission Default
2014-05-21T00:41:08.451Z,1400632868.451 [Default] Running Loop=1
2014-05-21T00:41:08.451Z,1400632868.451 [Default](INFO): Aggregate::initialize Default
2014-05-21T00:41:08.451Z,1400632868.451 [Default:Iridium] Running Loop=1
2014-05-21T00:41:08.451Z,1400632868.451 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-05-21T00:41:08.451Z,1400632868.451 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-05-21T00:41:08.451Z,1400632868.451 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-05-21T00:41:08.452Z,1400632868.452 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-05-21T00:41:08.452Z,1400632868.452 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-21T00:41:08.452Z,1400632868.452 [Default:CallIridium] Running Loop=1
2014-05-21T00:41:08.452Z,1400632868.452 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-05-21T00:41:08.453Z,1400632868.453 [Default:CallIridium:A] Running Loop=1
2014-05-21T00:41:08.455Z,1400632868.455 [Default:CallIridium:A] Stopped
2014-05-21T00:41:08.455Z,1400632868.455 [Default:CallIridium:B] Running Loop=1
2014-05-21T00:41:08.455Z,1400632868.455 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-05-21T00:41:08.461Z,1400632868.461 [Default:Iridium:B.GoToSurface] Stopped
2014-05-21T00:41:08.461Z,1400632868.461 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-21T00:41:08.461Z,1400632868.461 [Default:Iridium:Read_Iridium] Running Loop=1
2014-05-21T00:41:08.461Z,1400632868.461 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-05-21T00:41:08.466Z,1400632868.466 [Default:GPS] Running Loop=1
2014-05-21T00:41:08.467Z,1400632868.467 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-05-21T00:41:08.467Z,1400632868.467 [Default:GPS:A.SetSpeed] Running Loop=1
2014-05-21T00:41:08.467Z,1400632868.467 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-05-21T00:41:08.467Z,1400632868.467 [Default:GPS:B.GoToSurface] Running Loop=1
2014-05-21T00:41:08.467Z,1400632868.467 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-05-21T00:41:08.473Z,1400632868.473 [Default:GPS:B.GoToSurface] Stopped
2014-05-21T00:41:08.473Z,1400632868.473 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-05-21T00:41:08.473Z,1400632868.473 [Default:GPS:Read_GPS] Running Loop=1
2014-05-21T00:41:08.473Z,1400632868.473 [Default:GPS:A.SetSpeed] Running Loop=1
2014-05-21T00:41:08.840Z,1400632868.840 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-05-21T00:41:08.843Z,1400632868.843 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-05-21T00:41:13.174Z,1400632873.174 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-21T00:41:13.174Z,1400632873.174 [DVL_micro] Data Fault, FailCount= 1
2014-05-21T00:41:13.174Z,1400632873.174 [DVL_micro](ERROR): Data Fault
2014-05-21T00:41:13.252Z,1400632873.252 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-21T00:41:13.673Z,1400632873.673 [DVL_micro](INFO): uninitialize:Powering down
2014-05-21T00:41:13.975Z,1400632873.975 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-21T00:41:13.975Z,1400632873.975 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-21T00:41:13.975Z,1400632873.975 [DVL_micro](ERROR): Hardware Fault
2014-05-21T00:41:14.377Z,1400632874.377 [DVL_micro](INFO): Initializing
2014-05-21T00:41:14.446Z,1400632874.446 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-21T00:41:14.446Z,1400632874.446 [DVL_micro] No Fault, FailCount= 1
2014-05-21T00:43:21.970Z,1400633001.970 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2014-05-21T00:43:22.030Z,1400633002.030 [CBIT](INFO): Clearing failed count for component AHRS_sp3003D
2014-05-21T00:43:22.030Z,1400633002.030 [AHRS_sp3003D] No Fault, FailCount= 5
2014-05-21T00:43:22.363Z,1400633002.363 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-05-21T00:43:55.991Z,1400633035.991 [NAL9602](FAULT): Queried for signal strength and failed to receive proper response. no error
2014-05-21T00:43:56.065Z,1400633036.065 [NAL9602](ERROR): received: 
+CSQ:0

OK: Started
2014-05-21T00:43:56.065Z,1400633036.065 [NAL9602] Data Fault, FailCount= 1
2014-05-21T00:43:56.065Z,1400633036.065 [NAL9602](ERROR): Data Fault
2014-05-21T00:43:56.128Z,1400633036.128 [CBIT](ERROR): Data Fault in component: NAL9602
2014-05-21T00:43:56.471Z,1400633036.471 [NAL9602](INFO): Powering down
2014-05-21T00:43:57.340Z,1400633037.340 [CBIT](INFO): Clearing failed state for component NAL9602
2014-05-21T00:43:57.340Z,1400633037.340 [NAL9602] No Fault, FailCount= 1
2014-05-21T00:44:01.854Z,1400633041.854 [NAL9602](INFO): Powering up NAL9602
2014-05-21T00:44:12.579Z,1400633052.579 [NAL9602](INFO): NAL9602 initialized
2014-05-21T00:44:19.048Z,1400633059.048 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2014-05-21T00:44:19.048Z,1400633059.048 [DVL_micro] Data Fault, FailCount= 1
2014-05-21T00:44:19.048Z,1400633059.048 [DVL_micro](ERROR): Data Fault
2014-05-21T00:44:19.133Z,1400633059.133 [CBIT](ERROR): Data Fault in component: DVL_micro
2014-05-21T00:44:19.550Z,1400633059.550 [DVL_micro](INFO): uninitialize:Powering down
2014-05-21T00:44:19.943Z,1400633059.943 [DVL_micro](FAULT): LCB fault:  Software Overcurrent.
2014-05-21T00:44:19.943Z,1400633059.943 [DVL_micro] Hardware Fault, FailCount= 1
2014-05-21T00:44:19.943Z,1400633059.943 [DVL_micro](ERROR): Hardware Fault
2014-05-21T00:44:20.350Z,1400633060.350 [DVL_micro](INFO): Initializing
2014-05-21T00:44:20.384Z,1400633060.384 [CBIT](INFO): Clearing failed state for component DVL_micro
2014-05-21T00:44:20.384Z,1400633060.384 [DVL_micro] No Fault, FailCount= 1
2014-05-21T00:46:17.943Z,1400633177.943 [CommandLine](IMPORTANT): got command restart system
2014-05-21T00:46:20.953Z,1400633180.953 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-21T00:46:20.954Z,1400633180.954 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:21.053Z,1400633181.053 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2014-05-21T00:46:21.054Z,1400633181.054 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:21.054Z,1400633181.054 [CommandLine](INFO): Join timeout helper Thread ID is 1093
2014-05-21T00:46:21.057Z,1400633181.057 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2014-05-21T00:46:21.058Z,1400633181.058 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:21.058Z,1400633181.058 [NavChartDb](INFO): Join timeout helper Thread ID is 1094
2014-05-21T00:46:21.438Z,1400633181.438 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-21T00:46:21.439Z,1400633181.439 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:21.442Z,1400633181.442 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2014-05-21T00:46:21.442Z,1400633181.442 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:21.443Z,1400633181.443 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1095
2014-05-21T00:46:21.673Z,1400633181.673 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-21T00:46:21.673Z,1400633181.673 [WetLabsBB2FL](INFO): Powering down
2014-05-21T00:46:21.674Z,1400633181.674 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:21.687Z,1400633181.687 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2014-05-21T00:46:21.687Z,1400633181.687 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:21.687Z,1400633181.687 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1096
2014-05-21T00:46:21.995Z,1400633181.995 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-21T00:46:21.995Z,1400633181.995 [CTD_NeilBrown](INFO): Powering down
2014-05-21T00:46:21.996Z,1400633181.996 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:22.007Z,1400633182.007 [ComponentRegistry](INFO): Shutting down Radio_Freewave ThreadHandler
2014-05-21T00:46:22.007Z,1400633182.007 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:22.007Z,1400633182.007 [Radio_Freewave](INFO): Join timeout helper Thread ID is 1097
2014-05-21T00:46:22.035Z,1400633182.035 [Radio_Freewave ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-21T00:46:22.138Z,1400633182.138 [Radio_Freewave](INFO): Powering down
2014-05-21T00:46:22.544Z,1400633182.544 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:22.553Z,1400633182.553 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2014-05-21T00:46:22.553Z,1400633182.553 [logger ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:22.553Z,1400633182.553 [logger](INFO): Join timeout helper Thread ID is 1099
2014-05-21T00:46:22.572Z,1400633182.572 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-21T00:46:22.572Z,1400633182.572 [logger ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:22.593Z,1400633182.593 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2014-05-21T00:46:22.593Z,1400633182.593 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:22.593Z,1400633182.593 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2014-05-21T00:46:22.594Z,1400633182.594 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:22.594Z,1400633182.594 [controlThread](INFO): Join timeout helper Thread ID is 1100
2014-05-21T00:46:22.801Z,1400633182.801 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2014-05-21T00:46:22.801Z,1400633182.801 [controlThread](DEBUG): Uninitializing ControlThread
2014-05-21T00:46:22.802Z,1400633182.802 [AHRS_sp3003D](INFO): Powering down
2014-05-21T00:46:22.961Z,1400633182.961 [DVL_micro](INFO): uninitialize:Powering down
2014-05-21T00:46:22.962Z,1400633182.962 [NAL9602](INFO): Powering down
2014-05-21T00:46:22.965Z,1400633182.965 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-05-21T00:46:22.967Z,1400633182.967 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2014-05-21T00:46:22.968Z,1400633182.968 [Default] Stopped
2014-05-21T00:46:22.968Z,1400633182.968 [Default](INFO): Aggregate::uninitialize Default
2014-05-21T00:46:22.968Z,1400633182.968 [Default:GPS] Stopped
2014-05-21T00:46:22.968Z,1400633182.968 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-05-21T00:46:22.968Z,1400633182.968 [Default:GPS:A.SetSpeed] Stopped
2014-05-21T00:46:22.968Z,1400633182.968 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-05-21T00:46:22.968Z,1400633182.968 [Default:GPS:Read_GPS] Stopped
2014-05-21T00:46:22.968Z,1400633182.968 [Default:Iridium] Stopped
2014-05-21T00:46:22.969Z,1400633182.969 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-05-21T00:46:22.969Z,1400633182.969 [Default:Iridium:A.SetSpeed] Stopped
2014-05-21T00:46:22.969Z,1400633182.969 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-05-21T00:46:22.969Z,1400633182.969 [Default:Iridium:Read_Iridium] Stopped
2014-05-21T00:46:22.969Z,1400633182.969 [Default:CallIridium] Stopped
2014-05-21T00:46:22.969Z,1400633182.969 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-05-21T00:46:22.969Z,1400633182.969 [Default:CallIridium:B] Stopped
2014-05-21T00:46:22.969Z,1400633182.969 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-05-21T00:46:22.974Z,1400633182.974 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2014-05-21T00:46:22.975Z,1400633182.975 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2014-05-21T00:46:22.975Z,1400633182.975 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2014-05-21T00:46:22.975Z,1400633182.975 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2014-05-21T00:46:22.976Z,1400633182.976 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-05-21T00:46:22.976Z,1400633182.976 [BuoyancyServo](INFO): Powering down
2014-05-21T00:46:22.989Z,1400633182.989 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2014-05-21T00:46:22.989Z,1400633182.989 [ElevatorServo](INFO): Powering down
2014-05-21T00:46:22.990Z,1400633182.990 [MassServo](DEBUG): Uninitialize Mass Servo.
2014-05-21T00:46:22.990Z,1400633182.990 [MassServo](INFO): Powering down
2014-05-21T00:46:22.991Z,1400633182.991 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2014-05-21T00:46:22.991Z,1400633182.991 [RudderServo](INFO): Powering down
2014-05-21T00:46:22.992Z,1400633182.992 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2014-05-21T00:46:22.992Z,1400633182.992 [ThrusterServo](INFO): Powering down
2014-05-21T00:46:22.993Z,1400633182.993 [SBIT](DEBUG): Uninitialize SBIT Component.
2014-05-21T00:46:22.993Z,1400633182.993 [IBIT](DEBUG): Uninitialize IBIT Component.
2014-05-21T00:46:22.993Z,1400633182.993 [CBIT](DEBUG): Uninitialize CBIT Component.
2014-05-21T00:46:23.040Z,1400633183.040 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:23.054Z,1400633183.054 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:23.127Z,1400633183.127 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:23.131Z,1400633183.131 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:23.178Z,1400633183.178 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-05-21T00:46:23.212Z,1400633183.212 [logger ThreadHandler](INFO): Thread cancelled.