2015-01-22T19:01:31.869Z,1421953291.869 [Supervisor](DEBUG): Initializing supervisor.
2015-01-22T19:01:31.881Z,1421953291.881 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2015-01-22T19:01:31.881Z,1421953291.881 [SyncHandler](INFO): Protected caller Thread ID is 773
2015-01-22T19:01:31.882Z,1421953291.882 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2015-01-22T19:01:31.892Z,1421953291.892 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2015-01-22T19:01:31.893Z,1421953291.893 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 774
2015-01-22T19:01:31.896Z,1421953291.896 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2015-01-22T19:01:31.919Z,1421953291.919 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2015-01-22T19:01:31.929Z,1421953291.929 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2015-01-22T19:01:31.929Z,1421953291.929 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 775
2015-01-22T19:01:31.930Z,1421953291.930 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2015-01-22T19:01:31.941Z,1421953291.941 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2015-01-22T19:01:31.941Z,1421953291.941 [logger ThreadHandler](INFO): Protected caller Thread ID is 776
2015-01-22T19:01:31.943Z,1421953291.943 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2015-01-22T19:01:31.944Z,1421953291.944 [Supervisor](INFO): Looking for Config files in directory: Config/
2015-01-22T19:01:31.957Z,1421953291.957 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2015-01-22T19:01:32.385Z,1421953292.385 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2015-01-22T19:01:32.387Z,1421953292.387 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2015-01-22T19:01:32.714Z,1421953292.714 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2015-01-22T19:01:32.714Z,1421953292.714 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2015-01-22T19:01:33.061Z,1421953293.061 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2015-01-22T19:01:33.061Z,1421953293.061 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2015-01-22T19:01:33.478Z,1421953293.478 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2015-01-22T19:01:33.478Z,1421953293.478 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2015-01-22T19:01:33.720Z,1421953293.720 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2015-01-22T19:01:34.456Z,1421953294.456 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2015-01-22T19:01:34.456Z,1421953294.456 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2015-01-22T19:01:34.726Z,1421953294.726 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2015-01-22T19:01:34.726Z,1421953294.726 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2015-01-22T19:01:35.430Z,1421953295.430 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2015-01-22T19:01:35.431Z,1421953295.431 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2015-01-22T19:01:41.214Z,1421953301.214 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2015-01-22T19:01:41.214Z,1421953301.214 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2015-01-22T19:01:43.041Z,1421953303.041 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2015-01-22T19:01:43.042Z,1421953303.042 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2015-01-22T19:01:43.560Z,1421953303.560 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2015-01-22T19:01:43.561Z,1421953303.561 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2015-01-22T19:01:43.771Z,1421953303.771 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2015-01-22T19:01:43.772Z,1421953303.772 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2015-01-22T19:01:43.880Z,1421953303.880 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2015-01-22T19:01:43.881Z,1421953303.881 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2015-01-22T19:01:44.326Z,1421953304.326 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2015-01-22T19:01:44.327Z,1421953304.327 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2015-01-22T19:01:48.536Z,1421953308.536 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2015-01-22T19:01:48.538Z,1421953308.538 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2015-01-22T19:01:48.539Z,1421953308.539 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2015-01-22T19:01:53.245Z,1421953313.245 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2015-01-22T19:01:53.245Z,1421953313.245 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2015-01-22T19:01:53.367Z,1421953313.367 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Estimation.cfg
2015-01-22T19:01:53.471Z,1421953313.471 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2015-01-22T19:01:56.147Z,1421953316.147 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2015-01-22T19:01:56.268Z,1421953316.268 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2015-01-22T19:01:56.416Z,1421953316.416 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2015-01-22T19:01:56.596Z,1421953316.596 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2015-01-22T19:01:56.701Z,1421953316.701 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2015-01-22T19:01:56.794Z,1421953316.794 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2015-01-22T19:01:56.899Z,1421953316.899 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2015-01-22T19:01:56.000Z,1421953317.000 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2015-01-22T19:01:57.190Z,1421953317.190 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2015-01-22T19:01:57.192Z,1421953317.192 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2015-01-22T19:01:57.268Z,1421953317.268 [VerticalControl](DEBUG): Construct VerticalControl.
2015-01-22T19:01:57.389Z,1421953317.389 [VerticalControl] Loaded
2015-01-22T19:01:57.389Z,1421953317.389 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2015-01-22T19:01:57.390Z,1421953317.390 [HorizontalControl](DEBUG): Construct HorizontalControl.
2015-01-22T19:01:57.462Z,1421953317.462 [HorizontalControl] Loaded
2015-01-22T19:01:57.462Z,1421953317.462 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2015-01-22T19:01:57.463Z,1421953317.463 [SpeedControl](DEBUG): Construct SpeedControl.
2015-01-22T19:01:57.469Z,1421953317.469 [SpeedControl] Loaded
2015-01-22T19:01:57.469Z,1421953317.469 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2015-01-22T19:01:57.470Z,1421953317.470 [LoopControl](DEBUG): Construct LoopControl.
2015-01-22T19:01:57.470Z,1421953317.470 [LoopControl] Loaded
2015-01-22T19:01:57.471Z,1421953317.471 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2015-01-22T19:01:57.471Z,1421953317.471 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2015-01-22T19:01:57.472Z,1421953317.472 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2015-01-22T19:01:57.597Z,1421953317.597 [SBIT](DEBUG): Construct Startup Built In Test.
2015-01-22T19:01:57.609Z,1421953317.609 [SBIT] Loaded
2015-01-22T19:01:57.609Z,1421953317.609 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2015-01-22T19:01:57.610Z,1421953317.610 [IBIT](DEBUG): Construct Initiated Built In Test.
2015-01-22T19:01:57.639Z,1421953317.639 [IBIT] Loaded
2015-01-22T19:01:57.639Z,1421953317.639 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2015-01-22T19:01:57.642Z,1421953317.642 [CBIT](DEBUG): Construct CBIT Built In Test.
2015-01-22T19:01:57.762Z,1421953317.762 [CBIT] Loaded
2015-01-22T19:01:57.762Z,1421953317.762 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2015-01-22T19:01:57.763Z,1421953317.763 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2015-01-22T19:01:57.763Z,1421953317.763 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2015-01-22T19:01:57.793Z,1421953317.793 [DepthRateCalculator] Loaded
2015-01-22T19:01:57.793Z,1421953317.793 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2015-01-22T19:01:57.799Z,1421953317.799 [PitchRateCalculator] Loaded
2015-01-22T19:01:57.799Z,1421953317.799 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2015-01-22T19:01:57.811Z,1421953317.811 [SpeedCalculator] Loaded
2015-01-22T19:01:57.811Z,1421953317.811 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2015-01-22T19:01:57.828Z,1421953317.828 [TempGradientCalculator] Loaded
2015-01-22T19:01:57.828Z,1421953317.828 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2015-01-22T19:01:57.834Z,1421953317.834 [YawRateCalculator] Loaded
2015-01-22T19:01:57.834Z,1421953317.834 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2015-01-22T19:01:57.835Z,1421953317.835 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2015-01-22T19:01:57.835Z,1421953317.835 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2015-01-22T19:01:57.928Z,1421953317.928 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2015-01-22T19:01:57.929Z,1421953317.929 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2015-01-22T19:01:58.206Z,1421953318.206 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2015-01-22T19:01:58.206Z,1421953318.206 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2015-01-22T19:01:58.272Z,1421953318.272 [NavChart] Loaded
2015-01-22T19:01:58.272Z,1421953318.272 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2015-01-22T19:01:58.279Z,1421953318.279 [UniversalFixResidualReporter] Loaded
2015-01-22T19:01:58.279Z,1421953318.279 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2015-01-22T19:01:58.280Z,1421953318.280 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2015-01-22T19:01:58.280Z,1421953318.280 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2015-01-22T19:01:58.290Z,1421953318.290 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2015-01-22T19:01:58.290Z,1421953318.290 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2015-01-22T19:01:58.410Z,1421953318.410 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2015-01-22T19:01:58.410Z,1421953318.410 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2015-01-22T19:01:59.049Z,1421953319.049 [DataOverHttps] Loaded
2015-01-22T19:01:59.049Z,1421953319.049 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2015-01-22T19:01:59.131Z,1421953319.131 [Depth_Keller] Loaded
2015-01-22T19:01:59.131Z,1421953319.131 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2015-01-22T19:01:59.226Z,1421953319.226 [NAL9602] Loaded
2015-01-22T19:01:59.226Z,1421953319.226 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2015-01-22T19:01:59.268Z,1421953319.268 [Onboard] Loaded
2015-01-22T19:01:59.268Z,1421953319.268 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2015-01-22T19:01:59.275Z,1421953319.275 [Radio_Surface] Loaded
2015-01-22T19:01:59.275Z,1421953319.275 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2015-01-22T19:01:59.276Z,1421953319.276 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078B4E0
2015-01-22T19:01:59.277Z,1421953319.277 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 868
2015-01-22T19:02:01.144Z,1421953321.144 [BPC1] Loaded
2015-01-22T19:02:01.144Z,1421953321.144 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2015-01-22T19:02:01.144Z,1421953321.144 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2015-01-22T19:02:01.145Z,1421953321.145 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2015-01-22T19:02:07.194Z,1421953327.194 [BuoyancyServo] Loaded
2015-01-22T19:02:07.194Z,1421953327.194 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2015-01-22T19:02:07.207Z,1421953327.207 [ElevatorServo] Loaded
2015-01-22T19:02:07.207Z,1421953327.207 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2015-01-22T19:02:07.219Z,1421953327.219 [RudderServo] Loaded
2015-01-22T19:02:07.219Z,1421953327.219 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2015-01-22T19:02:07.231Z,1421953327.231 [ThrusterServo] Loaded
2015-01-22T19:02:07.231Z,1421953327.231 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2015-01-22T19:02:07.232Z,1421953327.232 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2015-01-22T19:02:07.232Z,1421953327.232 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2015-01-22T19:02:07.371Z,1421953327.371 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2015-01-22T19:02:07.371Z,1421953327.371 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2015-01-22T19:02:07.412Z,1421953327.412 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2015-01-22T19:02:07.414Z,1421953327.414 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2015-01-22T19:02:07.415Z,1421953327.415 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2015-01-22T19:02:07.421Z,1421953327.421 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2015-01-22T19:02:07.422Z,1421953327.422 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 4083C4E0
2015-01-22T19:02:07.423Z,1421953327.423 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 869
2015-01-22T19:02:07.428Z,1421953327.428 [Supervisor](INFO): Main Thread ID is 770
2015-01-22T19:02:07.428Z,1421953327.428 [Supervisor](DEBUG): Running supervisor.
2015-01-22T19:02:07.429Z,1421953327.429 [CommandLine ThreadHandler](INFO): Handler Thread ID is 870
2015-01-22T19:02:07.433Z,1421953327.433 [controlThread ThreadHandler](INFO): Handler Thread ID is 871
2015-01-22T19:02:07.433Z,1421953327.433 [controlThread](DEBUG): Initializing ControlThread
2015-01-22T19:02:07.434Z,1421953327.434 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2015-01-22T19:02:07.436Z,1421953327.436 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2015-01-22T19:02:07.436Z,1421953327.436 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2015-01-22T19:02:07.437Z,1421953327.437 [LoopControl](DEBUG): Initialize LoopControlComponent.
2015-01-22T19:02:07.437Z,1421953327.437 [SBIT](INFO): Initialize SBIT Component.
2015-01-22T19:02:07.438Z,1421953327.438 [SBIT](IMPORTANT): Tethys CM Info: SVN revision:11963
2015-01-22T19:02:07.438Z,1421953327.438 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2015-01-22T19:02:07.438Z,1421953327.438 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2015-01-22T19:02:07.439Z,1421953327.439 [IBIT](INFO): Initialize IBIT Component.
2015-01-22T19:02:07.440Z,1421953327.440 [CBIT](DEBUG): Initialize CBIT Component.
2015-01-22T19:02:07.440Z,1421953327.440 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2015-01-22T19:02:07.440Z,1421953327.440 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2015-01-22T19:02:07.441Z,1421953327.441 [logger ThreadHandler](INFO): Handler Thread ID is 872
2015-01-22T19:02:07.460Z,1421953327.460 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 873
2015-01-22T19:02:07.466Z,1421953327.466 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2015-01-22T19:02:07.466Z,1421953327.466 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2015-01-22T19:02:07.467Z,1421953327.467 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2015-01-22T19:02:07.467Z,1421953327.467 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2015-01-22T19:02:07.468Z,1421953327.468 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2015-01-22T19:02:07.468Z,1421953327.468 [NavChart](DEBUG): Initialize NavChart Navigation.
2015-01-22T19:02:07.469Z,1421953327.469 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2015-01-22T19:02:07.474Z,1421953327.474 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2015-01-22T19:02:07.475Z,1421953327.475 [Radio_Surface](INFO): Powering up
2015-01-22T19:02:07.497Z,1421953327.497 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2015-01-22T19:02:07.504Z,1421953327.504 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 874
2015-01-22T19:02:07.512Z,1421953327.512 [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>


2015-01-22T19:02:07.513Z,1421953327.513 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2015-01-22T19:02:07.516Z,1421953327.516 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2015-01-22T19:02:07.517Z,1421953327.517 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2015-01-22T19:02:07.518Z,1421953327.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2015-01-22T19:02:07.518Z,1421953327.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2015-01-22T19:02:07.518Z,1421953327.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2015-01-22T19:02:07.518Z,1421953327.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2015-01-22T19:02:07.519Z,1421953327.519 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2015-01-22T19:02:07.519Z,1421953327.519 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2015-01-22T19:02:07.519Z,1421953327.519 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2015-01-22T19:02:07.617Z,1421953327.617 [MissionManager](INFO): DefineArg Default.TimeMissionWasStarted = 0.000000 h
2015-01-22T19:02:07.620Z,1421953327.620 [MissionManager](INFO): DefineArg Default.ElapsedSinceMissionWasStarted = 0.000000 h
2015-01-22T19:02:07.649Z,1421953327.649 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2015-01-22T19:02:07.674Z,1421953327.674 [Default:CheckIn:A.SetSpeed](DEBUG): Construct.
2015-01-22T19:02:07.680Z,1421953327.680 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2015-01-22T19:02:07.704Z,1421953327.704 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Construct.
2015-01-22T19:02:07.730Z,1421953327.730 [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>


2015-01-22T19:02:07.740Z,1421953327.740 [controlThread](DEBUG): Component order: CycleStarter,DataOverHttps,Depth_Keller,NAL9602,Onboard,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2015-01-22T19:02:07.975Z,1421953327.975 [NAL9602](INFO): Start
2015-01-22T19:02:07.976Z,1421953327.976 [NAL9602](INFO): Powering up NAL9602
2015-01-22T19:02:08.278Z,1421953328.278 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2015-01-22T19:02:08.285Z,1421953328.285 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2015-01-22T19:02:08.307Z,1421953328.307 [ElevatorServo](DEBUG): Initializing EZServoServo.
2015-01-22T19:02:08.313Z,1421953328.313 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2015-01-22T19:02:08.327Z,1421953328.327 [RudderServo](DEBUG): Initializing EZServoServo.
2015-01-22T19:02:08.333Z,1421953328.333 [RudderServo](DEBUG): Initializing RudderServo.
2015-01-22T19:02:08.339Z,1421953328.339 [ThrusterServo](DEBUG): Initializing EZServoServo.
2015-01-22T19:02:08.345Z,1421953328.345 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2015-01-22T19:02:13.841Z,1421953333.841 [CommandLine](IMPORTANT): got command quit
2015-01-22T19:02:14.846Z,1421953334.846 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-22T19:02:14.846Z,1421953334.846 [CommandLine ThreadHandler](INFO): Thread cancelled.
2015-01-22T19:02:14.935Z,1421953334.935 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2015-01-22T19:02:14.935Z,1421953334.935 [CommandLine ThreadHandler](INFO): Thread cancelled.
2015-01-22T19:02:14.936Z,1421953334.936 [CommandLine](INFO): Join timeout helper Thread ID is 879
2015-01-22T19:02:14.959Z,1421953334.959 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2015-01-22T19:02:14.959Z,1421953334.959 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2015-01-22T19:02:14.960Z,1421953334.960 [NavChartDb](INFO): Join timeout helper Thread ID is 880
2015-01-22T19:02:16.782Z,1421953336.782 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-22T19:02:16.782Z,1421953336.782 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2015-01-22T19:02:16.790Z,1421953336.790 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2015-01-22T19:02:16.790Z,1421953336.790 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2015-01-22T19:02:16.791Z,1421953336.791 [Radio_Surface](INFO): Join timeout helper Thread ID is 881
2015-01-22T19:02:17.163Z,1421953337.163 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-22T19:02:17.163Z,1421953337.163 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2015-01-22T19:02:17.167Z,1421953337.167 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2015-01-22T19:02:17.167Z,1421953337.167 [logger ThreadHandler](INFO): Thread cancelled.
2015-01-22T19:02:17.167Z,1421953337.167 [logger](INFO): Join timeout helper Thread ID is 882
2015-01-22T19:02:17.195Z,1421953337.195 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-22T19:02:17.196Z,1421953337.196 [logger ThreadHandler](INFO): Thread cancelled.
2015-01-22T19:02:17.203Z,1421953337.203 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2015-01-22T19:02:17.203Z,1421953337.203 [CommandLine ThreadHandler](INFO): Thread cancelled.
2015-01-22T19:02:17.203Z,1421953337.203 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2015-01-22T19:02:17.203Z,1421953337.203 [controlThread ThreadHandler](INFO): Thread cancelled.
2015-01-22T19:02:17.204Z,1421953337.204 [controlThread](INFO): Join timeout helper Thread ID is 883
2015-01-22T19:02:17.519Z,1421953337.519 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-22T19:02:17.519Z,1421953337.519 [controlThread](DEBUG): Uninitializing ControlThread
2015-01-22T19:02:17.523Z,1421953337.523 [NAL9602](INFO): Uninitialize
2015-01-22T19:02:17.523Z,1421953337.523 [NAL9602](INFO): Powering down
2015-01-22T19:02:17.544Z,1421953337.544 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2015-01-22T19:02:17.544Z,1421953337.544 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2015-01-22T19:02:17.548Z,1421953337.548 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2015-01-22T19:02:17.549Z,1421953337.549 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2015-01-22T19:02:17.549Z,1421953337.549 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2015-01-22T19:02:17.549Z,1421953337.549 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2015-01-22T19:02:17.550Z,1421953337.550 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2015-01-22T19:02:17.551Z,1421953337.551 [BuoyancyServo](INFO): Powering down
2015-01-22T19:02:17.588Z,1421953337.588 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2015-01-22T19:02:17.588Z,1421953337.588 [ElevatorServo](INFO): Powering down
2015-01-22T19:02:17.607Z,1421953337.607 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2015-01-22T19:02:17.607Z,1421953337.607 [RudderServo](INFO): Powering down
2015-01-22T19:02:17.625Z,1421953337.625 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2015-01-22T19:02:17.625Z,1421953337.625 [ThrusterServo](INFO): Powering down
2015-01-22T19:02:17.643Z,1421953337.643 [SBIT](DEBUG): Uninitialize SBIT Component.
2015-01-22T19:02:17.644Z,1421953337.644 [IBIT](DEBUG): Uninitialize IBIT Component.
2015-01-22T19:02:17.644Z,1421953337.644 [CBIT](DEBUG): Uninitialize CBIT Component.
2015-01-22T19:02:17.676Z,1421953337.676 [controlThread ThreadHandler](INFO): Thread cancelled.
2015-01-22T19:02:17.785Z,1421953337.785 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2015-01-22T19:02:18.303Z,1421953338.303 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2015-01-22T19:02:18.351Z,1421953338.351 [logger ThreadHandler](INFO): Thread cancelled.