2014-10-08T15:03:48.925Z,1412780628.925 [Supervisor](DEBUG): Initializing supervisor.
2014-10-08T15:03:48.928Z,1412780628.928 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-10-08T15:03:48.928Z,1412780628.928 [SyncHandler](INFO): Protected caller Thread ID is 768
2014-10-08T15:03:48.929Z,1412780628.929 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-10-08T15:03:48.930Z,1412780628.930 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2014-10-08T15:03:48.930Z,1412780628.930 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 769
2014-10-08T15:03:48.933Z,1412780628.933 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-10-08T15:03:48.945Z,1412780628.945 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-10-08T15:03:48.946Z,1412780628.946 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2014-10-08T15:03:48.946Z,1412780628.946 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 770
2014-10-08T15:03:48.947Z,1412780628.947 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-10-08T15:03:48.948Z,1412780628.948 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2014-10-08T15:03:48.948Z,1412780628.948 [logger ThreadHandler](INFO): Protected caller Thread ID is 771
2014-10-08T15:03:48.950Z,1412780628.950 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-10-08T15:03:48.951Z,1412780628.951 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-10-08T15:03:48.955Z,1412780628.955 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-10-08T15:03:49.296Z,1412780629.296 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-10-08T15:03:49.298Z,1412780629.298 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-10-08T15:03:49.454Z,1412780629.454 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-10-08T15:03:49.455Z,1412780629.455 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-10-08T15:03:49.564Z,1412780629.564 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-10-08T15:03:49.566Z,1412780629.566 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-10-08T15:03:49.691Z,1412780629.691 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-10-08T15:03:49.691Z,1412780629.691 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-10-08T15:03:49.779Z,1412780629.779 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-10-08T15:03:49.922Z,1412780629.922 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-10-08T15:03:49.922Z,1412780629.922 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-10-08T15:03:50.010Z,1412780630.010 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-10-08T15:03:50.011Z,1412780630.011 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-10-08T15:03:50.208Z,1412780630.208 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-10-08T15:03:50.210Z,1412780630.210 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-10-08T15:03:50.542Z,1412780630.542 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-10-08T15:03:50.542Z,1412780630.542 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-10-08T15:03:50.840Z,1412780630.840 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-10-08T15:03:50.842Z,1412780630.842 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-10-08T15:03:51.327Z,1412780631.327 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-10-08T15:03:51.329Z,1412780631.329 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-10-08T15:03:51.520Z,1412780631.520 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-10-08T15:03:51.520Z,1412780631.520 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-10-08T15:03:51.626Z,1412780631.626 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-10-08T15:03:51.626Z,1412780631.626 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-10-08T15:03:52.034Z,1412780632.034 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-10-08T15:03:52.036Z,1412780632.036 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-10-08T15:03:52.147Z,1412780632.147 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-10-08T15:03:52.149Z,1412780632.149 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-10-08T15:03:52.152Z,1412780632.152 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-10-08T15:03:52.262Z,1412780632.262 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-10-08T15:03:52.384Z,1412780632.384 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-10-08T15:03:54.175Z,1412780634.175 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-10-08T15:03:54.292Z,1412780634.292 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-10-08T15:03:54.392Z,1412780634.392 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-10-08T15:03:54.520Z,1412780634.520 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-10-08T15:03:54.676Z,1412780634.676 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-10-08T15:03:54.779Z,1412780634.779 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-10-08T15:03:54.868Z,1412780634.868 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-10-08T15:03:54.951Z,1412780634.951 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-10-08T15:03:55.049Z,1412780635.049 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-10-08T15:03:55.160Z,1412780635.160 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2014-10-08T15:03:55.170Z,1412780635.170 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-10-08T15:03:55.241Z,1412780635.241 [VerticalControl](DEBUG): Construct VerticalControl.
2014-10-08T15:03:55.357Z,1412780635.357 [VerticalControl] Loaded
2014-10-08T15:03:55.357Z,1412780635.357 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-10-08T15:03:55.357Z,1412780635.357 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-10-08T15:03:55.428Z,1412780635.428 [HorizontalControl] Loaded
2014-10-08T15:03:55.428Z,1412780635.428 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-10-08T15:03:55.429Z,1412780635.429 [SpeedControl](DEBUG): Construct SpeedControl.
2014-10-08T15:03:55.435Z,1412780635.435 [SpeedControl] Loaded
2014-10-08T15:03:55.435Z,1412780635.435 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-10-08T15:03:55.436Z,1412780635.436 [LoopControl](DEBUG): Construct LoopControl.
2014-10-08T15:03:55.436Z,1412780635.436 [LoopControl] Loaded
2014-10-08T15:03:55.436Z,1412780635.436 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-10-08T15:03:55.437Z,1412780635.437 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-10-08T15:03:55.439Z,1412780635.439 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-10-08T15:03:55.558Z,1412780635.558 [SBIT](DEBUG): Construct Startup Built In Test.
2014-10-08T15:03:55.569Z,1412780635.569 [SBIT] Loaded
2014-10-08T15:03:55.569Z,1412780635.569 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-10-08T15:03:55.570Z,1412780635.570 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-10-08T15:03:55.598Z,1412780635.598 [IBIT] Loaded
2014-10-08T15:03:55.598Z,1412780635.598 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-10-08T15:03:55.600Z,1412780635.600 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-10-08T15:03:55.707Z,1412780635.707 [CBIT] Loaded
2014-10-08T15:03:55.707Z,1412780635.707 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-10-08T15:03:55.707Z,1412780635.707 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-10-08T15:03:55.708Z,1412780635.708 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-10-08T15:03:55.737Z,1412780635.737 [DepthRateCalculator] Loaded
2014-10-08T15:03:55.737Z,1412780635.737 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-10-08T15:03:55.742Z,1412780635.742 [PitchRateCalculator] Loaded
2014-10-08T15:03:55.743Z,1412780635.743 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-10-08T15:03:55.754Z,1412780635.754 [SpeedCalculator] Loaded
2014-10-08T15:03:55.754Z,1412780635.754 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-10-08T15:03:55.770Z,1412780635.770 [TempGradientCalculator] Loaded
2014-10-08T15:03:55.771Z,1412780635.771 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-10-08T15:03:55.776Z,1412780635.776 [YawRateCalculator] Loaded
2014-10-08T15:03:55.776Z,1412780635.776 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-10-08T15:03:55.776Z,1412780635.776 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-10-08T15:03:55.777Z,1412780635.777 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-10-08T15:03:55.861Z,1412780635.861 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-10-08T15:03:55.862Z,1412780635.862 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-10-08T15:03:56.126Z,1412780636.126 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-10-08T15:03:56.128Z,1412780636.128 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-10-08T15:03:56.221Z,1412780636.221 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-10-08T15:03:56.221Z,1412780636.221 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-10-08T15:03:56.265Z,1412780636.265 [DeadReckonUsingSpeedCalculator] Loaded
2014-10-08T15:03:56.265Z,1412780636.265 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2014-10-08T15:03:56.309Z,1412780636.309 [DeadReckonWithRespectToWater] Loaded
2014-10-08T15:03:56.309Z,1412780636.309 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToWater" handled in the control thread.
2014-10-08T15:03:56.354Z,1412780636.354 [DeadReckonWithRespectToSeafloor] Loaded
2014-10-08T15:03:56.354Z,1412780636.354 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2014-10-08T15:03:56.449Z,1412780636.449 [DeadReckonUsingDVLWaterTrack] Loaded
2014-10-08T15:03:56.449Z,1412780636.449 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingDVLWaterTrack" handled in the control thread.
2014-10-08T15:03:56.497Z,1412780636.497 [DeadReckonUsingCompactModelForecast] Loaded
2014-10-08T15:03:56.498Z,1412780636.498 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingCompactModelForecast" handled in the control thread.
2014-10-08T15:03:56.514Z,1412780636.514 [NavChart] Loaded
2014-10-08T15:03:56.514Z,1412780636.514 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-10-08T15:03:56.518Z,1412780636.518 [UniversalFixResidualReporter] Loaded
2014-10-08T15:03:56.519Z,1412780636.519 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-10-08T15:03:56.519Z,1412780636.519 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-10-08T15:03:56.520Z,1412780636.520 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-10-08T15:03:56.528Z,1412780636.528 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-10-08T15:03:56.529Z,1412780636.529 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-10-08T15:03:56.724Z,1412780636.724 [Aanderaa_O2] Loaded
2014-10-08T15:03:56.724Z,1412780636.724 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2014-10-08T15:03:56.760Z,1412780636.760 [CTD_NeilBrown] Loaded
2014-10-08T15:03:56.760Z,1412780636.760 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-10-08T15:03:56.761Z,1412780636.761 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 405634E0
2014-10-08T15:03:56.762Z,1412780636.762 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 854
2014-10-08T15:03:56.777Z,1412780636.777 [PAR_Licor] Loaded
2014-10-08T15:03:56.777Z,1412780636.777 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-10-08T15:03:56.812Z,1412780636.812 [WetLabsBB2FL] Loaded
2014-10-08T15:03:56.812Z,1412780636.812 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-10-08T15:03:56.814Z,1412780636.814 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 405934E0
2014-10-08T15:03:56.814Z,1412780636.814 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 855
2014-10-08T15:03:56.815Z,1412780636.815 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-10-08T15:03:56.815Z,1412780636.815 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-10-08T15:03:57.494Z,1412780637.494 [AHRS_sp3003D] Loaded
2014-10-08T15:03:57.494Z,1412780637.494 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-10-08T15:03:57.508Z,1412780637.508 [Depth_Keller] Loaded
2014-10-08T15:03:57.508Z,1412780637.508 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-10-08T15:03:57.513Z,1412780637.513 [DropWeight] Loaded
2014-10-08T15:03:57.513Z,1412780637.513 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-10-08T15:03:57.631Z,1412780637.631 [NAL9602] Loaded
2014-10-08T15:03:57.631Z,1412780637.631 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-10-08T15:03:57.676Z,1412780637.676 [Onboard] Loaded
2014-10-08T15:03:57.676Z,1412780637.676 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-10-08T15:03:57.683Z,1412780637.683 [Radio_Freewave] Loaded
2014-10-08T15:03:57.684Z,1412780637.684 [ComponentRegistry](DEBUG): Component "Radio_Freewave" handled in its own thread.
2014-10-08T15:03:57.685Z,1412780637.685 [Radio_Freewave ThreadHandler](DEBUG): Created PCaller Thread at 407DD4E0
2014-10-08T15:03:57.685Z,1412780637.685 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 856
2014-10-08T15:03:57.692Z,1412780637.692 [Radio_Surface] Loaded
2014-10-08T15:03:57.692Z,1412780637.692 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2014-10-08T15:03:57.693Z,1412780637.693 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4080D4E0
2014-10-08T15:03:57.693Z,1412780637.693 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 857
2014-10-08T15:03:57.816Z,1412780637.816 [DAT] Loaded
2014-10-08T15:03:57.816Z,1412780637.816 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2014-10-08T15:03:57.999Z,1412780637.999 [Rowe_600] Loaded
2014-10-08T15:03:57.999Z,1412780637.999 [ComponentRegistry](DEBUG): SyncComponent "Rowe_600" handled in the control thread.
2014-10-08T15:03:57.000Z,1412780638.000 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-10-08T15:03:58.000Z,1412780638.000 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-10-08T15:03:58.122Z,1412780638.122 [BuoyancyServo] Loaded
2014-10-08T15:03:58.123Z,1412780638.123 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-10-08T15:03:58.135Z,1412780638.135 [ElevatorServo] Loaded
2014-10-08T15:03:58.135Z,1412780638.135 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-10-08T15:03:58.147Z,1412780638.147 [MassServo] Loaded
2014-10-08T15:03:58.147Z,1412780638.147 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-10-08T15:03:58.158Z,1412780638.158 [RudderServo] Loaded
2014-10-08T15:03:58.159Z,1412780638.159 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-10-08T15:03:58.170Z,1412780638.170 [ThrusterServo] Loaded
2014-10-08T15:03:58.170Z,1412780638.170 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-10-08T15:03:58.170Z,1412780638.170 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-10-08T15:03:58.171Z,1412780638.171 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-10-08T15:03:58.356Z,1412780638.356 [InternalSim] Loaded
2014-10-08T15:03:58.356Z,1412780638.356 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-10-08T15:03:58.357Z,1412780638.357 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-10-08T15:03:58.357Z,1412780638.357 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-10-08T15:03:58.396Z,1412780638.396 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-10-08T15:03:58.398Z,1412780638.398 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-10-08T15:03:58.399Z,1412780638.399 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-10-08T15:03:58.405Z,1412780638.405 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-10-08T15:03:58.406Z,1412780638.406 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 408BE4E0
2014-10-08T15:03:58.407Z,1412780638.407 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 858
2014-10-08T15:03:58.411Z,1412780638.411 [Supervisor](INFO): Main Thread ID is 763
2014-10-08T15:03:58.411Z,1412780638.411 [Supervisor](DEBUG): Running supervisor.
2014-10-08T15:03:58.412Z,1412780638.412 [CommandLine ThreadHandler](INFO): Handler Thread ID is 859
2014-10-08T15:03:58.415Z,1412780638.415 [controlThread ThreadHandler](INFO): Handler Thread ID is 860
2014-10-08T15:03:58.415Z,1412780638.415 [controlThread](DEBUG): Initializing ControlThread
2014-10-08T15:03:58.416Z,1412780638.416 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-10-08T15:03:58.418Z,1412780638.418 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-10-08T15:03:58.419Z,1412780638.419 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-10-08T15:03:58.419Z,1412780638.419 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-10-08T15:03:58.420Z,1412780638.420 [SBIT](INFO): Initialize SBIT Component.
2014-10-08T15:03:58.420Z,1412780638.420 [SBIT](IMPORTANT): Tethys CM Info: SVN revision:11762
2014-10-08T15:03:58.420Z,1412780638.420 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2014-10-08T15:03:58.421Z,1412780638.421 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-10-08T15:03:58.421Z,1412780638.421 [IBIT](INFO): Initialize IBIT Component.
2014-10-08T15:03:58.422Z,1412780638.422 [CBIT](DEBUG): Initialize CBIT Component.
2014-10-08T15:03:58.422Z,1412780638.422 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2014-10-08T15:03:58.423Z,1412780638.423 [logger ThreadHandler](INFO): Handler Thread ID is 861
2014-10-08T15:03:58.444Z,1412780638.444 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 862
2014-10-08T15:03:58.445Z,1412780638.445 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-10-08T15:03:58.448Z,1412780638.448 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-10-08T15:03:58.448Z,1412780638.448 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-10-08T15:03:58.449Z,1412780638.449 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-10-08T15:03:58.449Z,1412780638.449 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-10-08T15:03:58.449Z,1412780638.449 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-10-08T15:03:58.450Z,1412780638.450 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-10-08T15:03:58.450Z,1412780638.450 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2014-10-08T15:03:58.450Z,1412780638.450 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component.
2014-10-08T15:03:58.451Z,1412780638.451 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component.
2014-10-08T15:03:58.451Z,1412780638.451 [DeadReckonUsingDVLWaterTrack](DEBUG): Initializing DeadReckonUsingDVLWaterTrack component.
2014-10-08T15:03:58.451Z,1412780638.451 [DeadReckonUsingCompactModelForecast](DEBUG): Initializing DeadReckonUsingCompactModelForecast component.
2014-10-08T15:03:58.452Z,1412780638.452 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-10-08T15:03:58.452Z,1412780638.452 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2014-10-08T15:03:58.464Z,1412780638.464 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-10-08T15:03:58.473Z,1412780638.473 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 864
2014-10-08T15:03:58.475Z,1412780638.475 [WetLabsBB2FL](INFO): Powering down
2014-10-08T15:03:58.499Z,1412780638.499 [InternalSim](DEBUG):  InternalSim initializing...
2014-10-08T15:03:58.504Z,1412780638.504 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 865
2014-10-08T15:03:58.546Z,1412780638.546 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 867
2014-10-08T15:03:58.564Z,1412780638.564 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 868
2014-10-08T15:03:58.573Z,1412780638.573 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-10-08T15:03:58.575Z,1412780638.575 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-10-08T15:03:58.576Z,1412780638.576 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-10-08T15:03:58.576Z,1412780638.576 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-10-08T15:03:58.576Z,1412780638.576 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-10-08T15:03:58.577Z,1412780638.577 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-10-08T15:03:58.577Z,1412780638.577 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-10-08T15:03:58.577Z,1412780638.577 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-10-08T15:03:58.577Z,1412780638.577 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-10-08T15:03:58.925Z,1412780638.925 [Radio_Freewave](INFO): Powering up
2014-10-08T15:03:58.941Z,1412780638.941 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-10-08T15:03:58.981Z,1412780638.981 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-10-08T15:03:59.007Z,1412780639.007 [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-10-08T15:03:59.007Z,1412780639.007 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-10-08T15:03:59.089Z,1412780639.089 [MissionManager](INFO): DefineArg Default.TimeMissionWasStarted = 0.000000 h
2014-10-08T15:03:59.092Z,1412780639.092 [MissionManager](INFO): DefineArg Default.ElapsedSinceMissionWasStarted = 0.000000 h
2014-10-08T15:03:59.096Z,1412780639.096 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-10-08T15:03:59.125Z,1412780639.125 [Default:CheckIn:A.SetSpeed](DEBUG): Construct.
2014-10-08T15:03:59.147Z,1412780639.147 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-10-08T15:03:59.167Z,1412780639.167 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-10-08T15:03:59.189Z,1412780639.189 [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="TimeMissionWasStarted"><Units:hour/><Value>0</Value></DefineArg>

    <DefineArg Name="ElapsedSinceMissionWasStarted"><Units:hour/><Value>0</Value></DefineArg>

    <Aggregate Id="StartClock">

        <Sequence/>

        <Assign><Arg Name="TimeMissionWasStarted"/><Universal:time/></Assign>

    </Aggregate>

    <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="UpdateAndReportMinutesSinceMissionStarted">

        <When>
            <Elapsed><Arg Name="ElapsedSinceMissionWasStarted"/></Elapsed>
            <Gt><Units:minute/><Value>5.0</Value></Gt>
        </When>

        <Assign><Arg Name="ElapsedSinceMissionWasStarted"/><Universal:time/><Sub><Arg Name="TimeMissionWasStarted"/></Sub></Assign>

        <Syslog Severity="Important">Default mission has been running for <Arg Name="ElapsedSinceMissionWasStarted"/><Units:minute/></Syslog>

    </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-10-08T15:03:59.195Z,1412780639.195 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,Aanderaa_O2,PAR_Licor,AHRS_sp3003D,Depth_Keller,DropWeight,NAL9602,Onboard,DAT,Rowe_600,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,DeadReckonWithRespectToWater,DeadReckonWithRespectToSeafloor,DeadReckonUsingDVLWaterTrack,DeadReckonUsingCompactModelForecast,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2014-10-08T15:03:59.431Z,1412780639.431 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-10-08T15:03:59.622Z,1412780639.622 [DAT](INFO): Powering up
2014-10-08T15:03:59.622Z,1412780639.622 [DAT](DEBUG): Initializing DAT.
2014-10-08T15:03:59.647Z,1412780639.647 [Rowe_600](INFO): Initializing
2014-10-08T15:03:59.650Z,1412780639.650 [Rowe_600](INFO): Powering up
2014-10-08T15:03:59.731Z,1412780639.731 [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-10-08T15:03:59.772Z,1412780639.772 [DeadReckonUsingMultipleVelocitySources](DEBUG): Could not determine rotation from vehicle frame to navigation frame.
2014-10-08T15:03:59.789Z,1412780639.789 [DeadReckonUsingSpeedCalculator](DEBUG): Could not determine rotation from vehicle frame to navigation frame.
2014-10-08T15:03:59.820Z,1412780639.820 [DeadReckonWithRespectToWater](DEBUG): Could not determine rotation from vehicle frame to navigation frame.
2014-10-08T15:03:59.854Z,1412780639.854 [DeadReckonWithRespectToSeafloor](DEBUG): Could not determine rotation from vehicle frame to navigation frame.
2014-10-08T15:03:59.877Z,1412780639.877 [DeadReckonUsingDVLWaterTrack](DEBUG): Could not determine rotation from vehicle frame to navigation frame.
2014-10-08T15:03:59.908Z,1412780639.908 [DeadReckonUsingCompactModelForecast](DEBUG): Could not determine rotation from vehicle frame to navigation frame.
2014-10-08T15:04:00.063Z,1412780640.063 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-10-08T15:04:00.074Z,1412780640.074 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-10-08T15:04:00.097Z,1412780640.097 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-10-08T15:04:00.102Z,1412780640.102 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-10-08T15:04:00.130Z,1412780640.130 [MassServo](DEBUG): Initializing EZServoServo.
2014-10-08T15:04:00.143Z,1412780640.143 [MassServo](DEBUG): Initializing MassServo.
2014-10-08T15:04:00.172Z,1412780640.172 [RudderServo](DEBUG): Initializing EZServoServo.
2014-10-08T15:04:00.183Z,1412780640.183 [RudderServo](DEBUG): Initializing RudderServo.
2014-10-08T15:04:00.196Z,1412780640.196 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-10-08T15:04:00.203Z,1412780640.203 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-10-08T15:04:00.624Z,1412780640.624 [DeadReckonUsingMultipleVelocitySources](DEBUG): Could not determine rotation from vehicle frame to navigation frame.
2014-10-08T15:04:00.625Z,1412780640.625 [DeadReckonUsingSpeedCalculator](DEBUG): Could not determine rotation from vehicle frame to navigation frame.
2014-10-08T15:04:00.627Z,1412780640.627 [DeadReckonWithRespectToWater](DEBUG): Could not determine rotation from vehicle frame to navigation frame.
2014-10-08T15:04:00.644Z,1412780640.644 [DeadReckonWithRespectToSeafloor](DEBUG): Could not determine rotation from vehicle frame to navigation frame.
2014-10-08T15:04:00.645Z,1412780640.645 [DeadReckonUsingDVLWaterTrack](DEBUG): Could not determine rotation from vehicle frame to navigation frame.
2014-10-08T15:04:00.647Z,1412780640.647 [DeadReckonUsingCompactModelForecast](DEBUG): Could not determine rotation from vehicle frame to navigation frame.
2014-10-08T15:04:00.992Z,1412780640.992 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2014-10-08T15:04:00.992Z,1412780640.992 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2014-10-08T15:04:00.992Z,1412780640.992 [BuoyancyServo] Communications Fault, FailCount= 1
2014-10-08T15:04:00.992Z,1412780640.992 [BuoyancyServo](ERROR): Communications Fault
2014-10-08T15:04:01.222Z,1412780641.222 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2014-10-08T15:04:01.654Z,1412780641.654 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-10-08T15:04:01.655Z,1412780641.655 [BuoyancyServo](INFO): Powering down
2014-10-08T15:04:02.849Z,1412780642.849 [NAL9602](INFO): Powering up NAL9602
2014-10-08T15:04:03.067Z,1412780643.067 [Aanderaa_O2](INFO): Powering down
2014-10-08T15:04:04.440Z,1412780644.440 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2014-10-08T15:04:04.440Z,1412780644.440 [BuoyancyServo] No Fault, FailCount= 1
2014-10-08T15:04:05.005Z,1412780645.005 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-10-08T15:04:05.123Z,1412780645.123 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-10-08T15:04:13.146Z,1412780653.146 [DAT](DEBUG): 
2014-10-08T15:04:13.147Z,1412780653.147 [DAT](DEBUG): Teledyne Benthos ATM-900 Series
2014-10-08T15:04:13.148Z,1412780653.148 [DAT](DEBUG): MF Frequency Band
2014-10-08T15:04:13.156Z,1412780653.156 [DAT](DEBUG): Directional Acoustic Transponder version 8.3.1
2014-10-08T15:04:13.819Z,1412780653.819 [DAT](DEBUG): Oct  8 2014 16:03:53 
2014-10-08T15:04:14.003Z,1412780654.003 [SBIT](IMPORTANT): Beginning Startup BIT
2014-10-08T15:04:14.006Z,1412780654.006 [CBIT](IMPORTANT): Beginning GF scan
2014-10-08T15:04:14.385Z,1412780654.385 [NAL9602](INFO): NAL9602 initialized
2014-10-08T15:04:15.001Z,1412780655.001 [DAT](INFO): entering command mode
2014-10-08T15:04:15.641Z,1412780655.641 [DAT](DEBUG): checking for command mode acknowledgment
2014-10-08T15:04:15.642Z,1412780655.642 [DAT](DEBUG): read user prompt 1: user:1>
2014-10-08T15:04:15.642Z,1412780655.642 [DAT](INFO): command mode acknowledged
2014-10-08T15:04:16.270Z,1412780656.270 [DAT](INFO): setting local address to 2
2014-10-08T15:04:17.378Z,1412780657.378 [DAT](DEBUG): checking for local address setting acknowledgment
2014-10-08T15:04:17.379Z,1412780657.379 [DAT](INFO): set local address to 2
2014-10-08T15:04:40.927Z,1412780680.927 [CBIT](FAULT): Chan 1 High side GF detected
mA:
CHAN 5 (24V): 0.108374
CHAN 4 (Batt): 0.067052
CHAN 2 (12V): 0.047826
CHAN 1 (5V): 0.016548
CHAN 0 (3.3V): 0.011765
OPEN: 0.000574
Full Scale Calc: 0.392
2014-10-08T15:04:42.491Z,1412780682.491 [NAL9602](IMPORTANT): GPS fix at: 1412780673.00
2014-10-08T15:04:49.450Z,1412780689.450 [NAL9602](INFO): Powering down
2014-10-08T15:05:08.741Z,1412780708.741 [SBIT](IMPORTANT): SBIT PASSED
2014-10-08T15:05:09.289Z,1412780709.289 [MissionManager](IMPORTANT): Started mission Startup
2014-10-08T15:05:09.289Z,1412780709.289 [Startup] Running Loop=1
2014-10-08T15:05:09.290Z,1412780709.290 [Startup](INFO): Aggregate::initialize Startup
2014-10-08T15:05:09.290Z,1412780709.290 [Startup:A.GoToSurface] Running Loop=1
2014-10-08T15:05:09.290Z,1412780709.290 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-10-08T15:05:09.290Z,1412780709.290 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-10-08T15:05:09.291Z,1412780709.291 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-10-08T15:05:09.291Z,1412780709.291 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-10-08T15:05:09.297Z,1412780709.297 [Startup:StartupSatComms] Running Loop=1
2014-10-08T15:05:09.297Z,1412780709.297 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-10-08T15:05:09.297Z,1412780709.297 [Startup:StartupSatComms:A] Running Loop=1
2014-10-08T15:05:09.865Z,1412780709.865 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-10-08T15:05:10.254Z,1412780710.254 [NAL9602](INFO): Powering up
2014-10-08T15:05:21.610Z,1412780721.610 [NAL9602](INFO): NAL9602 initialized
2014-10-08T15:05:42.668Z,1412780742.668 [NAL9602](IMPORTANT): GPS fix at: 1412780733.00
2014-10-08T15:05:42.825Z,1412780742.825 [Startup:StartupSatComms:A] Stopped
2014-10-08T15:05:42.826Z,1412780742.826 [Startup:StartupSatComms:B] Running Loop=1
2014-10-08T15:05:43.381Z,1412780743.381 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-10-08T15:06:09.005Z,1412780769.005 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=44475, MT Status=1, MTMSN=2841
2014-10-08T15:06:09.059Z,1412780769.059 [NAL9602](INFO): Sent 51 bytes from file Logs/20141008T144139/Courier0012.lzma
2014-10-08T15:06:09.059Z,1412780769.059 [NAL9602](INFO): Packets left to send: 0
2014-10-08T15:06:09.060Z,1412780769.060 [NAL9602](INFO): Stored copy of sent data in Logs/20141008T144139/Courier0012.lzma.parts/0000.sbd
2014-10-08T15:06:09.061Z,1412780769.061 [NAL9602](INFO): Completed sending Logs/20141008T144139/Courier0012.lzma
2014-10-08T15:06:09.868Z,1412780769.868 [NAL9602](INFO): Received command:configSet Batt_Ocean_Server.loadAtStartup 0 bool persist
2014-10-08T15:06:10.070Z,1412780770.070 [CommandLine](IMPORTANT): got command configSet Batt_Ocean_Server.loadAtStartup 0.000000 bool persist
2014-10-08T15:06:10.071Z,1412780770.071 [CommandLine](IMPORTANT): configSet Batt_Ocean_Server.loadAtStartup requires a restart to take effect.
2014-10-08T15:06:41.003Z,1412780801.003 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=44476, MT Status=1, MTMSN=2842
2014-10-08T15:06:41.056Z,1412780801.056 [NAL9602](INFO): Sent 217 bytes from file Logs/20141008T144139/Courier0016.lzma
2014-10-08T15:06:41.056Z,1412780801.056 [NAL9602](INFO): Packets left to send: 0
2014-10-08T15:06:41.058Z,1412780801.058 [NAL9602](INFO): Stored copy of sent data in Logs/20141008T144139/Courier0016.lzma.parts/0000.sbd
2014-10-08T15:06:41.058Z,1412780801.058 [NAL9602](INFO): Completed sending Logs/20141008T144139/Courier0016.lzma
2014-10-08T15:06:41.890Z,1412780801.890 [NAL9602](INFO): Received command:restart app
2014-10-08T15:06:41.938Z,1412780801.938 [CommandLine](IMPORTANT): got command restart application
2014-10-08T15:06:42.946Z,1412780802.946 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2014-10-08T15:06:42.946Z,1412780802.946 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:42.947Z,1412780802.947 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2014-10-08T15:06:42.947Z,1412780802.947 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:42.947Z,1412780802.947 [CommandLine](INFO): Join timeout helper Thread ID is 906
2014-10-08T15:06:42.948Z,1412780802.948 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2014-10-08T15:06:42.948Z,1412780802.948 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:42.948Z,1412780802.948 [NavChartDb](INFO): Join timeout helper Thread ID is 907
2014-10-08T15:06:43.141Z,1412780803.141 [Startup:StartupSatComms:B](INFO): Timed out from 2014-10-08T15:05:42.8Z
2014-10-08T15:06:43.141Z,1412780803.141 [Startup:StartupSatComms:B] Stopped
2014-10-08T15:06:43.141Z,1412780803.141 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2014-10-08T15:06:43.141Z,1412780803.141 [Startup:StartupSatComms] Stopped
2014-10-08T15:06:43.141Z,1412780803.141 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2014-10-08T15:06:43.142Z,1412780803.142 [Startup](INFO): Completed Startup
2014-10-08T15:06:43.142Z,1412780803.142 [Startup] Stopped
2014-10-08T15:06:43.142Z,1412780803.142 [Startup](INFO): Aggregate::uninitialize Startup
2014-10-08T15:06:43.142Z,1412780803.142 [Startup:A.GoToSurface] Stopped
2014-10-08T15:06:43.142Z,1412780803.142 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-10-08T15:06:43.311Z,1412780803.311 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2014-10-08T15:06:43.312Z,1412780803.312 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:43.312Z,1412780803.312 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2014-10-08T15:06:43.313Z,1412780803.313 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:43.313Z,1412780803.313 [Radio_Surface](INFO): Join timeout helper Thread ID is 908
2014-10-08T15:06:43.480Z,1412780803.480 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2014-10-08T15:06:43.480Z,1412780803.480 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:43.492Z,1412780803.492 [ComponentRegistry](INFO): Shutting down Radio_Freewave ThreadHandler
2014-10-08T15:06:43.492Z,1412780803.492 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:43.492Z,1412780803.492 [Radio_Freewave](INFO): Join timeout helper Thread ID is 909
2014-10-08T15:06:43.705Z,1412780803.705 [MissionManager](IMPORTANT): Started mission Default
2014-10-08T15:06:43.705Z,1412780803.705 [Default] Running Loop=1
2014-10-08T15:06:43.705Z,1412780803.705 [Default](INFO): Aggregate::initialize Default
2014-10-08T15:06:43.705Z,1412780803.705 [Default:B.GoToSurface] Running Loop=1
2014-10-08T15:06:43.705Z,1412780803.705 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-10-08T15:06:43.705Z,1412780803.705 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2014-10-08T15:06:43.706Z,1412780803.706 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2014-10-08T15:06:43.706Z,1412780803.706 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2014-10-08T15:06:43.706Z,1412780803.706 [Default:StartClock] Running Loop=1
2014-10-08T15:06:43.706Z,1412780803.706 [Default:StartClock](INFO): Aggregate::initialize Default:StartClock
2014-10-08T15:06:43.707Z,1412780803.707 [Default:StartClock:A] Running Loop=1
2014-10-08T15:06:43.707Z,1412780803.707 [Default:CheckIn] Running Loop=1
2014-10-08T15:06:43.707Z,1412780803.707 [Default:CheckIn](INFO): Aggregate::initialize Default:CheckIn
2014-10-08T15:06:43.707Z,1412780803.707 [Default:CheckIn:A.SetSpeed] Running Loop=1
2014-10-08T15:06:43.707Z,1412780803.707 [Default:CheckIn:A.SetSpeed](DEBUG): Initialize.
2014-10-08T15:06:43.707Z,1412780803.707 [Default:CheckIn:Read_GPS] Running Loop=1
2014-10-08T15:06:43.724Z,1412780803.724 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-10-08T15:06:43.726Z,1412780803.726 [Default:CheckIn:A.SetSpeed] Running Loop=1
2014-10-08T15:06:43.756Z,1412780803.756 [Default:StartClock:A] Stopped
2014-10-08T15:06:43.757Z,1412780803.757 [Default:StartClock](INFO): Completed Default:StartClock
2014-10-08T15:06:43.757Z,1412780803.757 [Default:StartClock] Stopped
2014-10-08T15:06:43.757Z,1412780803.757 [Default:StartClock](INFO): Aggregate::uninitialize Default:StartClock
2014-10-08T15:06:43.792Z,1412780803.792 [Radio_Freewave ThreadHandler](INFO): Uninitializing protected caller thread.
2014-10-08T15:06:43.919Z,1412780803.919 [Radio_Freewave](INFO): Powering down
2014-10-08T15:06:44.321Z,1412780804.321 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:44.338Z,1412780804.338 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2014-10-08T15:06:44.339Z,1412780804.339 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:44.339Z,1412780804.339 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 911
2014-10-08T15:06:44.350Z,1412780804.350 [Default:WaitAtTheSurface] Running Loop=1
2014-10-08T15:06:44.350Z,1412780804.350 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface
2014-10-08T15:06:44.350Z,1412780804.350 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2014-10-08T15:06:44.350Z,1412780804.350 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Initialize.
2014-10-08T15:06:44.501Z,1412780804.501 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2014-10-08T15:06:44.502Z,1412780804.502 [WetLabsBB2FL](INFO): Powering down
2014-10-08T15:06:44.502Z,1412780804.502 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:44.510Z,1412780804.510 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2014-10-08T15:06:44.510Z,1412780804.510 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:44.511Z,1412780804.511 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 912
2014-10-08T15:06:44.766Z,1412780804.766 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2014-10-08T15:06:44.766Z,1412780804.766 [CTD_NeilBrown](INFO): Powering down
2014-10-08T15:06:44.767Z,1412780804.767 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:44.778Z,1412780804.778 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2014-10-08T15:06:44.779Z,1412780804.779 [logger ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:44.779Z,1412780804.779 [logger](INFO): Join timeout helper Thread ID is 913
2014-10-08T15:06:44.779Z,1412780804.779 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2014-10-08T15:06:44.780Z,1412780804.780 [logger ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:44.781Z,1412780804.781 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2014-10-08T15:06:44.782Z,1412780804.782 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:44.782Z,1412780804.782 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2014-10-08T15:06:44.782Z,1412780804.782 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:44.782Z,1412780804.782 [controlThread](INFO): Join timeout helper Thread ID is 914
2014-10-08T15:06:44.903Z,1412780804.903 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2014-10-08T15:06:44.921Z,1412780804.921 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2014-10-08T15:06:44.921Z,1412780804.921 [controlThread](DEBUG): Uninitializing ControlThread
2014-10-08T15:06:44.922Z,1412780804.922 [Aanderaa_O2](INFO): Powering down
2014-10-08T15:06:44.923Z,1412780804.923 [AHRS_sp3003D](INFO): Powering down
2014-10-08T15:06:44.924Z,1412780804.924 [NAL9602](INFO): Powering down
2014-10-08T15:06:44.925Z,1412780804.925 [DAT](INFO): Powering down
2014-10-08T15:06:44.947Z,1412780804.947 [Rowe_600](INFO): Powering down
2014-10-08T15:06:44.967Z,1412780804.967 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-10-08T15:06:44.969Z,1412780804.969 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2014-10-08T15:06:44.969Z,1412780804.969 [Default] Stopped
2014-10-08T15:06:44.969Z,1412780804.969 [Default](INFO): Aggregate::uninitialize Default
2014-10-08T15:06:44.969Z,1412780804.969 [Default:B.GoToSurface] Stopped
2014-10-08T15:06:44.969Z,1412780804.969 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-10-08T15:06:44.970Z,1412780804.970 [Default:CheckIn] Stopped
2014-10-08T15:06:44.970Z,1412780804.970 [Default:CheckIn](INFO): Aggregate::uninitialize Default:CheckIn
2014-10-08T15:06:44.970Z,1412780804.970 [Default:CheckIn:A.SetSpeed] Stopped
2014-10-08T15:06:44.970Z,1412780804.970 [Default:CheckIn:A.SetSpeed](DEBUG): Uninitialize.
2014-10-08T15:06:44.970Z,1412780804.970 [Default:CheckIn:Read_GPS] Stopped
2014-10-08T15:06:44.970Z,1412780804.970 [Default:WaitAtTheSurface] Stopped
2014-10-08T15:06:44.970Z,1412780804.970 [Default:WaitAtTheSurface](INFO): Aggregate::uninitialize Default:WaitAtTheSurface
2014-10-08T15:06:44.971Z,1412780804.971 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Stopped
2014-10-08T15:06:44.971Z,1412780804.971 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Uninitialize.
2014-10-08T15:06:44.974Z,1412780804.974 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2014-10-08T15:06:44.974Z,1412780804.974 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2014-10-08T15:06:44.974Z,1412780804.974 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2014-10-08T15:06:44.975Z,1412780804.975 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2014-10-08T15:06:44.975Z,1412780804.975 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-10-08T15:06:44.975Z,1412780804.975 [BuoyancyServo](INFO): Powering down
2014-10-08T15:06:44.990Z,1412780804.990 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2014-10-08T15:06:44.990Z,1412780804.990 [ElevatorServo](INFO): Powering down
2014-10-08T15:06:44.991Z,1412780804.991 [MassServo](DEBUG): Uninitialize Mass Servo.
2014-10-08T15:06:44.991Z,1412780804.991 [MassServo](INFO): Powering down
2014-10-08T15:06:44.992Z,1412780804.992 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2014-10-08T15:06:44.992Z,1412780804.992 [RudderServo](INFO): Powering down
2014-10-08T15:06:44.993Z,1412780804.993 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2014-10-08T15:06:44.993Z,1412780804.993 [ThrusterServo](INFO): Powering down
2014-10-08T15:06:44.994Z,1412780804.994 [SBIT](DEBUG): Uninitialize SBIT Component.
2014-10-08T15:06:44.994Z,1412780804.994 [IBIT](DEBUG): Uninitialize IBIT Component.
2014-10-08T15:06:44.995Z,1412780804.995 [CBIT](DEBUG): Uninitialize CBIT Component.
2014-10-08T15:06:45.039Z,1412780805.039 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:45.102Z,1412780805.102 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:45.105Z,1412780805.105 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:45.120Z,1412780805.120 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:45.121Z,1412780805.121 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:45.160Z,1412780805.160 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-10-08T15:06:45.216Z,1412780805.216 [logger ThreadHandler](INFO): Thread cancelled.