2014-08-01T04:22:06.588Z,1406866926.588 [Supervisor](DEBUG): Initializing supervisor.
2014-08-01T04:22:06.594Z,1406866926.594 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-08-01T04:22:06.594Z,1406866926.594 [SyncHandler](INFO): Protected caller Thread ID is 2772
2014-08-01T04:22:06.595Z,1406866926.595 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-08-01T04:22:06.596Z,1406866926.596 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2014-08-01T04:22:06.596Z,1406866926.596 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2773
2014-08-01T04:22:06.602Z,1406866926.602 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-08-01T04:22:06.618Z,1406866926.618 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-08-01T04:22:06.619Z,1406866926.619 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2014-08-01T04:22:06.619Z,1406866926.619 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2774
2014-08-01T04:22:06.622Z,1406866926.622 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-08-01T04:22:06.623Z,1406866926.623 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2014-08-01T04:22:06.623Z,1406866926.623 [logger ThreadHandler](INFO): Protected caller Thread ID is 2775
2014-08-01T04:22:06.626Z,1406866926.626 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-08-01T04:22:06.627Z,1406866926.627 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-08-01T04:22:06.628Z,1406866926.628 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-08-01T04:22:07.109Z,1406866927.109 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-08-01T04:22:07.110Z,1406866927.110 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-08-01T04:22:07.264Z,1406866927.264 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-08-01T04:22:07.264Z,1406866927.264 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-08-01T04:22:07.370Z,1406866927.370 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-08-01T04:22:07.371Z,1406866927.371 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-08-01T04:22:07.493Z,1406866927.493 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-08-01T04:22:07.493Z,1406866927.493 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-08-01T04:22:07.577Z,1406866927.577 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-08-01T04:22:07.711Z,1406866927.711 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-08-01T04:22:07.711Z,1406866927.711 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-08-01T04:22:07.796Z,1406866927.796 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-08-01T04:22:07.797Z,1406866927.797 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-08-01T04:22:07.972Z,1406866927.972 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-08-01T04:22:07.973Z,1406866927.973 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-08-01T04:22:08.258Z,1406866928.258 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-08-01T04:22:08.259Z,1406866928.259 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-08-01T04:22:08.558Z,1406866928.558 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-08-01T04:22:08.559Z,1406866928.559 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-08-01T04:22:09.065Z,1406866929.065 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-08-01T04:22:09.065Z,1406866929.065 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-08-01T04:22:09.657Z,1406866929.657 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-08-01T04:22:09.658Z,1406866929.658 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-08-01T04:22:10.417Z,1406866930.417 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-08-01T04:22:10.418Z,1406866930.418 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-08-01T04:22:10.806Z,1406866930.806 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-08-01T04:22:10.807Z,1406866930.807 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-08-01T04:22:10.915Z,1406866930.915 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-08-01T04:22:10.917Z,1406866930.917 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-08-01T04:22:10.918Z,1406866930.918 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-08-01T04:22:11.020Z,1406866931.020 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-08-01T04:22:11.135Z,1406866931.135 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-08-01T04:22:11.242Z,1406866931.242 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-08-01T04:22:11.338Z,1406866931.338 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-08-01T04:22:11.463Z,1406866931.463 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-08-01T04:22:11.604Z,1406866931.604 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-08-01T04:22:11.703Z,1406866931.703 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-08-01T04:22:11.789Z,1406866931.789 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-08-01T04:22:11.880Z,1406866931.880 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-08-01T04:22:11.975Z,1406866931.975 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-08-01T04:22:12.084Z,1406866932.084 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-08-01T04:22:12.171Z,1406866932.171 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/
2014-08-01T04:22:12.171Z,1406866932.171 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2014-08-01T04:22:12.173Z,1406866932.173 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-08-01T04:22:12.226Z,1406866932.226 [VerticalControl](DEBUG): Construct VerticalControl.
2014-08-01T04:22:12.342Z,1406866932.342 [VerticalControl] Loaded
2014-08-01T04:22:12.342Z,1406866932.342 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-08-01T04:22:12.343Z,1406866932.343 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-08-01T04:22:12.411Z,1406866932.411 [HorizontalControl] Loaded
2014-08-01T04:22:12.411Z,1406866932.411 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-08-01T04:22:12.412Z,1406866932.412 [SpeedControl](DEBUG): Construct SpeedControl.
2014-08-01T04:22:12.417Z,1406866932.417 [SpeedControl] Loaded
2014-08-01T04:22:12.418Z,1406866932.418 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-08-01T04:22:12.418Z,1406866932.418 [LoopControl](DEBUG): Construct LoopControl.
2014-08-01T04:22:12.419Z,1406866932.419 [LoopControl] Loaded
2014-08-01T04:22:12.419Z,1406866932.419 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-08-01T04:22:12.420Z,1406866932.420 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-08-01T04:22:12.420Z,1406866932.420 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-08-01T04:22:12.517Z,1406866932.517 [SBIT](DEBUG): Construct Startup Built In Test.
2014-08-01T04:22:12.528Z,1406866932.528 [SBIT] Loaded
2014-08-01T04:22:12.528Z,1406866932.528 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-08-01T04:22:12.529Z,1406866932.529 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-08-01T04:22:12.557Z,1406866932.557 [IBIT] Loaded
2014-08-01T04:22:12.557Z,1406866932.557 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-08-01T04:22:12.559Z,1406866932.559 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-08-01T04:22:12.674Z,1406866932.674 [CBIT] Loaded
2014-08-01T04:22:12.674Z,1406866932.674 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-08-01T04:22:12.675Z,1406866932.675 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-08-01T04:22:12.675Z,1406866932.675 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-08-01T04:22:12.694Z,1406866932.694 [DepthRateCalculator] Loaded
2014-08-01T04:22:12.694Z,1406866932.694 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-08-01T04:22:12.700Z,1406866932.700 [PitchRateCalculator] Loaded
2014-08-01T04:22:12.700Z,1406866932.700 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-08-01T04:22:12.711Z,1406866932.711 [SpeedCalculator] Loaded
2014-08-01T04:22:12.711Z,1406866932.711 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-08-01T04:22:12.727Z,1406866932.727 [TempGradientCalculator] Loaded
2014-08-01T04:22:12.727Z,1406866932.727 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-08-01T04:22:12.732Z,1406866932.732 [YawRateCalculator] Loaded
2014-08-01T04:22:12.733Z,1406866932.733 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-08-01T04:22:12.733Z,1406866932.733 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-08-01T04:22:12.734Z,1406866932.734 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-08-01T04:22:17.700Z,1406866937.700 [HFRadarModelCalc] Loaded
2014-08-01T04:22:17.700Z,1406866937.700 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2014-08-01T04:22:21.665Z,1406866941.665 [HFRadarCompactModelForecaster] Loaded
2014-08-01T04:22:21.665Z,1406866941.665 [ComponentRegistry](DEBUG): SyncComponent "HFRadarCompactModelForecaster" handled in the control thread.
2014-08-01T04:22:22.753Z,1406866942.753 [HFRCMSpaceInterpolator] Loaded
2014-08-01T04:22:22.753Z,1406866942.753 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSpaceInterpolator" handled in the control thread.
2014-08-01T04:22:22.755Z,1406866942.755 [HFRCMTimeInterpolator] Loaded
2014-08-01T04:22:22.756Z,1406866942.756 [ComponentRegistry](DEBUG): SyncComponent "HFRCMTimeInterpolator" handled in the control thread.
2014-08-01T04:22:23.816Z,1406866943.816 [HFRCMReconstructedInterpolator] Loaded
2014-08-01T04:22:23.816Z,1406866943.816 [ComponentRegistry](DEBUG): SyncComponent "HFRCMReconstructedInterpolator" handled in the control thread.
2014-08-01T04:22:23.828Z,1406866943.828 [HFRCMSurfaceCurrentAtVehicleLocation] Loaded
2014-08-01T04:22:23.828Z,1406866943.828 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSurfaceCurrentAtVehicleLocation" handled in the control thread.
2014-08-01T04:22:23.854Z,1406866943.854 [HFRCMVirtualSurfaceDrifter] Loaded
2014-08-01T04:22:23.854Z,1406866943.854 [ComponentRegistry](DEBUG): SyncComponent "HFRCMVirtualSurfaceDrifter" handled in the control thread.
2014-08-01T04:22:23.855Z,1406866943.855 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-08-01T04:22:23.855Z,1406866943.855 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-08-01T04:22:24.086Z,1406866944.086 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-08-01T04:22:24.087Z,1406866944.087 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-08-01T04:22:24.167Z,1406866944.167 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-08-01T04:22:24.167Z,1406866944.167 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-08-01T04:22:24.212Z,1406866944.212 [DeadReckonWithRespectToWater] Loaded
2014-08-01T04:22:24.212Z,1406866944.212 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToWater" handled in the control thread.
2014-08-01T04:22:24.257Z,1406866944.257 [DeadReckonWithRespectToSeafloor] Loaded
2014-08-01T04:22:24.258Z,1406866944.258 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2014-08-01T04:22:24.315Z,1406866944.315 [DeadReckonUsingDVLWaterTrack] Loaded
2014-08-01T04:22:24.316Z,1406866944.316 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingDVLWaterTrack" handled in the control thread.
2014-08-01T04:22:24.362Z,1406866944.362 [DeadReckonUsingCompactModelForecast] Loaded
2014-08-01T04:22:24.362Z,1406866944.362 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingCompactModelForecast" handled in the control thread.
2014-08-01T04:22:24.379Z,1406866944.379 [NavChart] Loaded
2014-08-01T04:22:24.379Z,1406866944.379 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-08-01T04:22:24.383Z,1406866944.383 [UniversalFixResidualReporter] Loaded
2014-08-01T04:22:24.384Z,1406866944.384 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-08-01T04:22:24.384Z,1406866944.384 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-08-01T04:22:24.385Z,1406866944.385 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-08-01T04:22:24.391Z,1406866944.391 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-08-01T04:22:24.391Z,1406866944.391 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-08-01T04:22:24.566Z,1406866944.566 [CTD_NeilBrown] Loaded
2014-08-01T04:22:24.566Z,1406866944.566 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-08-01T04:22:24.570Z,1406866944.570 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407B94E0
2014-08-01T04:22:24.570Z,1406866944.570 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 2857
2014-08-01T04:22:24.586Z,1406866944.586 [PAR_Licor] Loaded
2014-08-01T04:22:24.586Z,1406866944.586 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-08-01T04:22:24.620Z,1406866944.620 [WetLabsBB2FL] Loaded
2014-08-01T04:22:24.620Z,1406866944.620 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-08-01T04:22:24.621Z,1406866944.621 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407E94E0
2014-08-01T04:22:24.622Z,1406866944.622 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 2858
2014-08-01T04:22:24.622Z,1406866944.622 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-08-01T04:22:24.623Z,1406866944.623 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-08-01T04:22:24.907Z,1406866944.907 [AHRS_sp3003D] Loaded
2014-08-01T04:22:24.908Z,1406866944.908 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-08-01T04:22:25.163Z,1406866945.163 [Batt_Ocean_Server] Loaded
2014-08-01T04:22:25.163Z,1406866945.163 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-08-01T04:22:25.176Z,1406866945.176 [Depth_Keller] Loaded
2014-08-01T04:22:25.176Z,1406866945.176 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-08-01T04:22:25.181Z,1406866945.181 [DropWeight] Loaded
2014-08-01T04:22:25.181Z,1406866945.181 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-08-01T04:22:25.311Z,1406866945.311 [DVL_micro] Loaded
2014-08-01T04:22:25.311Z,1406866945.311 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2014-08-01T04:22:25.402Z,1406866945.402 [NAL9602] Loaded
2014-08-01T04:22:25.403Z,1406866945.403 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-08-01T04:22:25.444Z,1406866945.444 [Onboard] Loaded
2014-08-01T04:22:25.444Z,1406866945.444 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-08-01T04:22:25.451Z,1406866945.451 [Radio_Freewave] Loaded
2014-08-01T04:22:25.451Z,1406866945.451 [ComponentRegistry](DEBUG): Component "Radio_Freewave" handled in its own thread.
2014-08-01T04:22:25.454Z,1406866945.454 [Radio_Freewave ThreadHandler](DEBUG): Created PCaller Thread at 40A1E4E0
2014-08-01T04:22:25.455Z,1406866945.455 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 2859
2014-08-01T04:22:25.585Z,1406866945.585 [DAT] Loaded
2014-08-01T04:22:25.585Z,1406866945.585 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2014-08-01T04:22:25.591Z,1406866945.591 [SCPI] Loaded
2014-08-01T04:22:25.592Z,1406866945.592 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-08-01T04:22:25.896Z,1406866945.896 [BPC1] Loaded
2014-08-01T04:22:25.896Z,1406866945.896 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2014-08-01T04:22:25.897Z,1406866945.897 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-08-01T04:22:25.897Z,1406866945.897 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-08-01T04:22:25.995Z,1406866945.995 [BuoyancyServo] Loaded
2014-08-01T04:22:25.995Z,1406866945.995 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-08-01T04:22:26.007Z,1406866946.007 [ElevatorServo] Loaded
2014-08-01T04:22:26.008Z,1406866946.008 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-08-01T04:22:26.019Z,1406866946.019 [MassServo] Loaded
2014-08-01T04:22:26.020Z,1406866946.020 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-08-01T04:22:26.031Z,1406866946.031 [RudderServo] Loaded
2014-08-01T04:22:26.031Z,1406866946.031 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-08-01T04:22:26.042Z,1406866946.042 [ThrusterServo] Loaded
2014-08-01T04:22:26.043Z,1406866946.043 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-08-01T04:22:26.043Z,1406866946.043 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-08-01T04:22:26.044Z,1406866946.044 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-08-01T04:22:26.202Z,1406866946.202 [InternalSim] Loaded
2014-08-01T04:22:26.202Z,1406866946.202 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-08-01T04:22:26.203Z,1406866946.203 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-08-01T04:22:26.203Z,1406866946.203 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-08-01T04:22:26.228Z,1406866946.228 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-08-01T04:22:26.230Z,1406866946.230 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-08-01T04:22:26.231Z,1406866946.231 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-08-01T04:22:26.238Z,1406866946.238 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-08-01T04:22:26.241Z,1406866946.241 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ACF4E0
2014-08-01T04:22:26.242Z,1406866946.242 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 2860
2014-08-01T04:22:26.247Z,1406866946.247 [Supervisor](INFO): Main Thread ID is 2771
2014-08-01T04:22:26.247Z,1406866946.247 [Supervisor](DEBUG): Running supervisor.
2014-08-01T04:22:26.248Z,1406866946.248 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2861
2014-08-01T04:22:26.252Z,1406866946.252 [controlThread ThreadHandler](INFO): Handler Thread ID is 2862
2014-08-01T04:22:26.252Z,1406866946.252 [controlThread](DEBUG): Initializing ControlThread
2014-08-01T04:22:26.253Z,1406866946.253 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-08-01T04:22:26.255Z,1406866946.255 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-08-01T04:22:26.255Z,1406866946.255 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-08-01T04:22:26.256Z,1406866946.256 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-08-01T04:22:26.256Z,1406866946.256 [SBIT](INFO): Initialize SBIT Component.
2014-08-01T04:22:26.257Z,1406866946.257 [SBIT](IMPORTANT): Tethys CM Info: SVN revision: 11462
2014-08-01T04:22:26.257Z,1406866946.257 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2014-08-01T04:22:26.257Z,1406866946.257 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-08-01T04:22:26.258Z,1406866946.258 [IBIT](INFO): Initialize IBIT Component.
2014-08-01T04:22:26.259Z,1406866946.259 [CBIT](DEBUG): Initialize CBIT Component.
2014-08-01T04:22:26.259Z,1406866946.259 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2014-08-01T04:22:26.260Z,1406866946.260 [logger ThreadHandler](INFO): Handler Thread ID is 2863
2014-08-01T04:22:26.280Z,1406866946.280 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 2864
2014-08-01T04:22:26.281Z,1406866946.281 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-08-01T04:22:26.284Z,1406866946.284 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-08-01T04:22:26.284Z,1406866946.284 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-08-01T04:22:26.285Z,1406866946.285 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-08-01T04:22:26.285Z,1406866946.285 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-08-01T04:22:26.285Z,1406866946.285 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-08-01T04:22:26.288Z,1406866946.288 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-08-01T04:22:26.300Z,1406866946.300 [HFRadarCompactModelForecaster](DEBUG): Found new ECs!
2014-08-01T04:22:26.302Z,1406866946.302 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 2866
2014-08-01T04:22:26.303Z,1406866946.303 [WetLabsBB2FL](INFO): Powering down
2014-08-01T04:22:26.314Z,1406866946.314 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 2867
2014-08-01T04:22:26.351Z,1406866946.351 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 2868
2014-08-01T04:22:26.362Z,1406866946.362 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-08-01T04:22:26.363Z,1406866946.363 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-08-01T04:22:26.363Z,1406866946.363 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-08-01T04:22:26.363Z,1406866946.363 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-08-01T04:22:26.363Z,1406866946.363 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-08-01T04:22:26.364Z,1406866946.364 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-08-01T04:22:26.364Z,1406866946.364 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-08-01T04:22:26.364Z,1406866946.364 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-08-01T04:22:26.365Z,1406866946.365 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-08-01T04:22:35.105Z,1406866955.105 [HFRadarCompactModelForecaster](IMPORTANT): forecast time 201408010100: published 50 modes in rows, 61 hours in columns
2014-08-01T04:22:35.120Z,1406866955.120 [HFRadarCompactModelForecaster](IMPORTANT): expansionCoefficients_[0][48] = -10.333895 for 2014-08-01T01:00:00.000Z
2014-08-01T04:22:35.126Z,1406866955.126 [HFRCMSpaceInterpolator](DEBUG): Initializing HFRCMSpaceInterpolator component with verbosity level 0.
2014-08-01T04:22:35.127Z,1406866955.127 [HFRCMTimeInterpolator](DEBUG): Initializing HFRCMTimeInterpolator component.
2014-08-01T04:22:35.128Z,1406866955.128 [HFRCMReconstructedInterpolator](INFO): Initializing HFRCMReconstructedInterpolator component with velocityAccuracy_ = 0.300000 m/s.
2014-08-01T04:22:35.129Z,1406866955.129 [HFRCMSurfaceCurrentAtVehicleLocation](DEBUG): Initializing HFRCMSurfaceCurrentAtVehicleLocation component.
2014-08-01T04:22:35.146Z,1406866955.146 [HFRCMVirtualSurfaceDrifter](DEBUG): Initializing HFRCMVirtualSurfaceDrifter component.
2014-08-01T04:22:35.146Z,1406866955.146 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-08-01T04:22:35.146Z,1406866955.146 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component.
2014-08-01T04:22:35.147Z,1406866955.147 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component.
2014-08-01T04:22:35.147Z,1406866955.147 [DeadReckonUsingDVLWaterTrack](DEBUG): Initializing DeadReckonUsingDVLWaterTrack component.
2014-08-01T04:22:35.148Z,1406866955.148 [DeadReckonUsingCompactModelForecast](DEBUG): Initializing DeadReckonUsingCompactModelForecast component.
2014-08-01T04:22:35.148Z,1406866955.148 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-08-01T04:22:35.148Z,1406866955.148 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-08-01T04:22:37.045Z,1406866957.045 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-08-01T04:22:37.077Z,1406866957.077 [InternalSim](DEBUG):  InternalSim initializing...
2014-08-01T04:22:37.214Z,1406866957.214 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-08-01T04:22:37.238Z,1406866957.238 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-08-01T04:22:37.266Z,1406866957.266 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

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

    <Aggregate Id="StartupSatComms">

        <Sequence/>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:latitude_fix/>
        </ReadDatum>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

</Mission>


2014-08-01T04:22:37.267Z,1406866957.267 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-08-01T04:22:37.303Z,1406866957.303 [Default:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-08-01T04:22:37.328Z,1406866957.328 [Default:CheckIn:A.SetSpeed](DEBUG): Construct.
2014-08-01T04:22:37.350Z,1406866957.350 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-08-01T04:22:37.373Z,1406866957.373 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-08-01T04:22:37.379Z,1406866957.379 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
xmlns:Control="Tethys/Control"
xmlns:Guidance="Tethys/Guidance" 
xmlns:Units="Tethys/Units"
xmlns:Universal="Tethys/Universal"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
Id="Default">

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

    <Aggregate Id="CheckIn">

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

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

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

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

        <!-- Do data comms -->

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

    </Aggregate>

    <Aggregate Id="WaitAtTheSurface">

        <Sequence/>

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

    </Aggregate>

</Mission>


2014-08-01T04:22:37.391Z,1406866957.391 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,PAR_Licor,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,DAT,SCPI,BPC1,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,HFRadarModelCalc,HFRadarCompactModelForecaster,HFRCMSpaceInterpolator,HFRCMTimeInterpolator,HFRCMReconstructedInterpolator,HFRCMSurfaceCurrentAtVehicleLocation,HFRCMVirtualSurfaceDrifter,DeadReckonUsingMultipleVelocitySources,DeadReckonWithRespectToWater,DeadReckonWithRespectToSeafloor,DeadReckonUsingDVLWaterTrack,DeadReckonUsingCompactModelForecast,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2014-08-01T04:22:37.605Z,1406866957.605 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-08-01T04:22:37.667Z,1406866957.667 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2014-08-01T04:22:37.722Z,1406866957.722 [DVL_micro](INFO): Initializing
2014-08-01T04:22:37.762Z,1406866957.762 [NAL9602](INFO): Powering up NAL9602
2014-08-01T04:22:37.824Z,1406866957.824 [Radio_Freewave](INFO): Powering up
2014-08-01T04:22:37.826Z,1406866957.826 [DAT](INFO): Powering up
2014-08-01T04:22:37.826Z,1406866957.826 [DAT](DEBUG): Initializing DAT.
2014-08-01T04:22:37.844Z,1406866957.844 [DAT](CRITICAL): SIGSEGV: address not mapped to object
2014-08-01T04:22:37.845Z,1406866957.845 [DAT](CRITICAL): Bad address: 0x0
2014-08-01T04:22:37.845Z,1406866957.845 [DAT](CRITICAL): Backtrace: 
bin/LRAUV(_ZN7PCaller20DefaultSignalHandlerEiP7siginfoPv+0x20) [0x16ebc8]
/lib/libc.so.6(__default_rt_sa_restorer+0) [0x40212510]

2014-08-01T04:22:37.845Z,1406866957.845 [DAT] Software Fault, FailCount= 1
2014-08-01T04:22:37.845Z,1406866957.845 [DAT](ERROR): Software Fault
2014-08-01T04:22:37.866Z,1406866957.866 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-08-01T04:22:37.866Z,1406866957.866 [SyncHandler](INFO): Protected caller Thread ID is 2872
2014-08-01T04:22:37.872Z,1406866957.872 [BPC1](DEBUG): Initializing BPC1.
2014-08-01T04:22:38.632Z,1406866958.632 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0
2014-08-01T04:22:45.517Z,1406866965.517 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-08-01T04:22:45.526Z,1406866965.526 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-08-01T04:22:45.540Z,1406866965.540 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-08-01T04:22:45.546Z,1406866965.546 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-08-01T04:22:45.564Z,1406866965.564 [MassServo](DEBUG): Initializing EZServoServo.
2014-08-01T04:22:45.574Z,1406866965.574 [MassServo](DEBUG): Initializing MassServo.
2014-08-01T04:22:45.587Z,1406866965.587 [RudderServo](DEBUG): Initializing EZServoServo.
2014-08-01T04:22:45.594Z,1406866965.594 [RudderServo](DEBUG): Initializing RudderServo.
2014-08-01T04:22:45.607Z,1406866965.607 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-08-01T04:22:45.614Z,1406866965.614 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-08-01T04:22:45.673Z,1406866965.673 [CommandLine](FAULT): Scheduling is paused
2014-08-01T04:22:45.675Z,1406866965.675 [CBIT](ERROR): Software Fault in component: DAT
2014-08-01T04:22:46.297Z,1406866966.297 [DAT](INFO): Powering down
2014-08-01T04:22:46.696Z,1406866966.696 [SBIT](IMPORTANT): Beginning Startup BIT
2014-08-01T04:22:46.699Z,1406866966.699 [CBIT](IMPORTANT): Beginning GF scan
2014-08-01T04:22:47.734Z,1406866967.734 [CBIT](INFO): Clearing failed state for component DAT
2014-08-01T04:22:47.734Z,1406866967.734 [DAT] No Fault, FailCount= 1
2014-08-01T04:22:48.010Z,1406866968.010 [Radio_Freewave](INFO): Powering down
2014-08-01T04:22:48.787Z,1406866968.787 [NAL9602](INFO): NAL9602 initialized
2014-08-01T04:22:49.096Z,1406866969.096 [Radio_Freewave](INFO): Powering up
2014-08-01T04:22:49.417Z,1406866969.417 [DAT](INFO): Powering up
2014-08-01T04:22:49.417Z,1406866969.417 [DAT](DEBUG): Initializing DAT.
2014-08-01T04:22:49.447Z,1406866969.447 [DAT](CRITICAL): SIGSEGV: address not mapped to object
2014-08-01T04:22:49.447Z,1406866969.447 [DAT](CRITICAL): Bad address: 0x0
2014-08-01T04:22:49.447Z,1406866969.447 [DAT](CRITICAL): Backtrace: 
bin/LRAUV(_ZN7PCaller20DefaultSignalHandlerEiP7siginfoPv+0x20) [0x16ebc8]
/lib/libc.so.6(__default_rt_sa_restorer+0) [0x40212510]

2014-08-01T04:22:49.447Z,1406866969.447 [DAT] Software Fault, FailCount= 2
2014-08-01T04:22:49.448Z,1406866969.448 [DAT](ERROR): Software Fault
2014-08-01T04:22:49.460Z,1406866969.460 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-08-01T04:22:49.460Z,1406866969.460 [SyncHandler](INFO): Protected caller Thread ID is 2883
2014-08-01T04:22:49.855Z,1406866969.855 [CBIT](ERROR): Software Fault in component: DAT
2014-08-01T04:22:49.905Z,1406866969.905 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0
2014-08-01T04:22:50.312Z,1406866970.312 [DAT](INFO): Powering down
2014-08-01T04:22:51.843Z,1406866971.843 [CBIT](INFO): Clearing failed state for component DAT
2014-08-01T04:22:51.843Z,1406866971.843 [DAT] No Fault, FailCount= 2
2014-08-01T04:22:53.560Z,1406866973.560 [DAT](INFO): Powering up
2014-08-01T04:22:53.560Z,1406866973.560 [DAT](DEBUG): Initializing DAT.
2014-08-01T04:22:53.597Z,1406866973.597 [DAT](CRITICAL): SIGSEGV: address not mapped to object
2014-08-01T04:22:53.597Z,1406866973.597 [DAT](CRITICAL): Bad address: 0x0
2014-08-01T04:22:53.597Z,1406866973.597 [DAT](CRITICAL): Backtrace: 
bin/LRAUV(_ZN7PCaller20DefaultSignalHandlerEiP7siginfoPv+0x20) [0x16ebc8]
/lib/libc.so.6(__default_rt_sa_restorer+0) [0x40212510]

2014-08-01T04:22:53.597Z,1406866973.597 [DAT] Software Fault, FailCount= 3
2014-08-01T04:22:53.597Z,14068