2015-01-27T23:00:50.836Z,1422399650.836 [Supervisor](DEBUG): Initializing supervisor.
2015-01-27T23:00:50.838Z,1422399650.838 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2015-01-27T23:00:50.839Z,1422399650.839 [SyncHandler](INFO): Protected caller Thread ID is 2910
2015-01-27T23:00:50.839Z,1422399650.839 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2015-01-27T23:00:50.840Z,1422399650.840 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2015-01-27T23:00:50.841Z,1422399650.841 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2911
2015-01-27T23:00:50.843Z,1422399650.843 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2015-01-27T23:00:50.855Z,1422399650.855 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2015-01-27T23:00:50.856Z,1422399650.856 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2015-01-27T23:00:50.856Z,1422399650.856 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2912
2015-01-27T23:00:50.857Z,1422399650.857 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2015-01-27T23:00:50.858Z,1422399650.858 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2015-01-27T23:00:50.858Z,1422399650.858 [logger ThreadHandler](INFO): Protected caller Thread ID is 2913
2015-01-27T23:00:50.861Z,1422399650.861 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2015-01-27T23:00:50.861Z,1422399650.861 [Supervisor](INFO): Looking for Config files in directory: Config/
2015-01-27T23:00:50.862Z,1422399650.862 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2015-01-27T23:00:51.181Z,1422399651.181 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2015-01-27T23:00:51.181Z,1422399651.181 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2015-01-27T23:00:51.334Z,1422399651.334 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2015-01-27T23:00:51.335Z,1422399651.335 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2015-01-27T23:00:51.440Z,1422399651.440 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2015-01-27T23:00:51.441Z,1422399651.441 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2015-01-27T23:00:51.559Z,1422399651.559 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2015-01-27T23:00:51.560Z,1422399651.560 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2015-01-27T23:00:51.642Z,1422399651.642 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2015-01-27T23:00:51.809Z,1422399651.809 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2015-01-27T23:00:51.809Z,1422399651.809 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2015-01-27T23:00:51.892Z,1422399651.892 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2015-01-27T23:00:51.893Z,1422399651.893 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2015-01-27T23:00:52.095Z,1422399652.095 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2015-01-27T23:00:52.096Z,1422399652.096 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2015-01-27T23:00:52.459Z,1422399652.459 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2015-01-27T23:00:52.460Z,1422399652.460 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2015-01-27T23:00:52.904Z,1422399652.904 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2015-01-27T23:00:52.904Z,1422399652.904 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2015-01-27T23:00:53.420Z,1422399653.420 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2015-01-27T23:00:53.421Z,1422399653.421 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2015-01-27T23:00:53.607Z,1422399653.607 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2015-01-27T23:00:53.608Z,1422399653.608 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2015-01-27T23:00:53.709Z,1422399653.709 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2015-01-27T23:00:53.710Z,1422399653.710 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2015-01-27T23:00:54.138Z,1422399654.138 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2015-01-27T23:00:54.139Z,1422399654.139 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2015-01-27T23:00:54.246Z,1422399654.246 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2015-01-27T23:00:54.248Z,1422399654.248 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2015-01-27T23:00:54.249Z,1422399654.249 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2015-01-27T23:00:54.489Z,1422399654.489 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2015-01-27T23:00:54.490Z,1422399654.490 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2015-01-27T23:00:54.602Z,1422399654.602 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Estimation.cfg
2015-01-27T23:00:54.696Z,1422399654.696 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2015-01-27T23:00:54.800Z,1422399654.800 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2015-01-27T23:00:54.910Z,1422399654.910 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2015-01-27T23:00:55.045Z,1422399655.045 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2015-01-27T23:00:55.223Z,1422399655.223 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2015-01-27T23:00:55.320Z,1422399655.320 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2015-01-27T23:00:55.406Z,1422399655.406 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2015-01-27T23:00:55.503Z,1422399655.503 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2015-01-27T23:00:55.596Z,1422399655.596 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2015-01-27T23:00:55.770Z,1422399655.770 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/root/
2015-01-27T23:00:55.771Z,1422399655.771 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2015-01-27T23:00:55.784Z,1422399655.784 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2015-01-27T23:00:55.836Z,1422399655.836 [VerticalControl](DEBUG): Construct VerticalControl.
2015-01-27T23:00:55.953Z,1422399655.953 [VerticalControl] Loaded
2015-01-27T23:00:55.953Z,1422399655.953 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2015-01-27T23:00:55.954Z,1422399655.954 [HorizontalControl](DEBUG): Construct HorizontalControl.
2015-01-27T23:00:56.025Z,1422399656.025 [HorizontalControl] Loaded
2015-01-27T23:00:56.026Z,1422399656.026 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2015-01-27T23:00:56.026Z,1422399656.026 [SpeedControl](DEBUG): Construct SpeedControl.
2015-01-27T23:00:56.032Z,1422399656.032 [SpeedControl] Loaded
2015-01-27T23:00:56.032Z,1422399656.032 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2015-01-27T23:00:56.033Z,1422399656.033 [LoopControl](DEBUG): Construct LoopControl.
2015-01-27T23:00:56.033Z,1422399656.033 [LoopControl] Loaded
2015-01-27T23:00:56.034Z,1422399656.034 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2015-01-27T23:00:56.034Z,1422399656.034 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2015-01-27T23:00:56.035Z,1422399656.035 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2015-01-27T23:00:56.139Z,1422399656.139 [SBIT](DEBUG): Construct Startup Built In Test.
2015-01-27T23:00:56.150Z,1422399656.150 [SBIT] Loaded
2015-01-27T23:00:56.150Z,1422399656.150 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2015-01-27T23:00:56.151Z,1422399656.151 [IBIT](DEBUG): Construct Initiated Built In Test.
2015-01-27T23:00:56.180Z,1422399656.180 [IBIT] Loaded
2015-01-27T23:00:56.180Z,1422399656.180 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2015-01-27T23:00:56.182Z,1422399656.182 [CBIT](DEBUG): Construct CBIT Built In Test.
2015-01-27T23:00:56.302Z,1422399656.302 [CBIT] Loaded
2015-01-27T23:00:56.302Z,1422399656.302 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2015-01-27T23:00:56.303Z,1422399656.303 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2015-01-27T23:00:56.303Z,1422399656.303 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2015-01-27T23:00:56.322Z,1422399656.322 [DepthRateCalculator] Loaded
2015-01-27T23:00:56.322Z,1422399656.322 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2015-01-27T23:00:56.328Z,1422399656.328 [PitchRateCalculator] Loaded
2015-01-27T23:00:56.328Z,1422399656.328 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2015-01-27T23:00:56.339Z,1422399656.339 [SpeedCalculator] Loaded
2015-01-27T23:00:56.339Z,1422399656.339 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2015-01-27T23:00:56.356Z,1422399656.356 [TempGradientCalculator] Loaded
2015-01-27T23:00:56.356Z,1422399656.356 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2015-01-27T23:00:56.362Z,1422399656.362 [YawRateCalculator] Loaded
2015-01-27T23:00:56.362Z,1422399656.362 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2015-01-27T23:00:56.362Z,1422399656.362 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2015-01-27T23:00:56.363Z,1422399656.363 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2015-01-27T23:00:56.413Z,1422399656.413 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2015-01-27T23:00:56.414Z,1422399656.414 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2015-01-27T23:00:56.646Z,1422399656.646 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2015-01-27T23:00:56.646Z,1422399656.646 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2015-01-27T23:00:56.690Z,1422399656.690 [NavChart] Loaded
2015-01-27T23:00:56.690Z,1422399656.690 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2015-01-27T23:00:56.696Z,1422399656.696 [UniversalFixResidualReporter] Loaded
2015-01-27T23:00:56.697Z,1422399656.697 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2015-01-27T23:00:56.697Z,1422399656.697 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2015-01-27T23:00:56.698Z,1422399656.698 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2015-01-27T23:00:56.704Z,1422399656.704 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2015-01-27T23:00:56.704Z,1422399656.704 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2015-01-27T23:00:56.791Z,1422399656.791 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2015-01-27T23:00:56.792Z,1422399656.792 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2015-01-27T23:00:57.119Z,1422399657.119 [DataOverHttps] Loaded
2015-01-27T23:00:57.119Z,1422399657.119 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2015-01-27T23:00:57.200Z,1422399657.200 [Depth_Keller] Loaded
2015-01-27T23:00:57.200Z,1422399657.200 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2015-01-27T23:00:57.297Z,1422399657.297 [NAL9602] Loaded
2015-01-27T23:00:57.298Z,1422399657.298 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2015-01-27T23:00:57.339Z,1422399657.339 [Onboard] Loaded
2015-01-27T23:00:57.339Z,1422399657.339 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2015-01-27T23:00:57.346Z,1422399657.346 [Radio_Surface] Loaded
2015-01-27T23:00:57.346Z,1422399657.346 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2015-01-27T23:00:57.347Z,1422399657.347 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078B4E0
2015-01-27T23:00:57.348Z,1422399657.348 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 2995
2015-01-27T23:00:59.312Z,1422399659.312 [BPC1] Loaded
2015-01-27T23:00:59.312Z,1422399659.312 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2015-01-27T23:00:59.313Z,1422399659.313 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2015-01-27T23:00:59.313Z,1422399659.313 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2015-01-27T23:00:59.413Z,1422399659.413 [BuoyancyServo] Loaded
2015-01-27T23:00:59.414Z,1422399659.414 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2015-01-27T23:00:59.425Z,1422399659.425 [ElevatorServo] Loaded
2015-01-27T23:00:59.426Z,1422399659.426 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2015-01-27T23:00:59.437Z,1422399659.437 [RudderServo] Loaded
2015-01-27T23:00:59.438Z,1422399659.438 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2015-01-27T23:00:59.449Z,1422399659.449 [ThrusterServo] Loaded
2015-01-27T23:00:59.449Z,1422399659.449 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2015-01-27T23:00:59.450Z,1422399659.450 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2015-01-27T23:00:59.450Z,1422399659.450 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2015-01-27T23:00:59.553Z,1422399659.553 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2015-01-27T23:00:59.553Z,1422399659.553 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2015-01-27T23:00:59.578Z,1422399659.578 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2015-01-27T23:00:59.580Z,1422399659.580 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2015-01-27T23:00:59.580Z,1422399659.580 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2015-01-27T23:00:59.587Z,1422399659.587 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2015-01-27T23:00:59.588Z,1422399659.588 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 4083C4E0
2015-01-27T23:00:59.588Z,1422399659.588 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 2996
2015-01-27T23:00:59.593Z,1422399659.593 [Supervisor](INFO): Main Thread ID is 2909
2015-01-27T23:00:59.593Z,1422399659.593 [Supervisor](DEBUG): Running supervisor.
2015-01-27T23:00:59.594Z,1422399659.594 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2997
2015-01-27T23:00:59.598Z,1422399659.598 [controlThread ThreadHandler](INFO): Handler Thread ID is 2998
2015-01-27T23:00:59.598Z,1422399659.598 [controlThread](DEBUG): Initializing ControlThread
2015-01-27T23:00:59.599Z,1422399659.599 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2015-01-27T23:00:59.601Z,1422399659.601 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2015-01-27T23:00:59.601Z,1422399659.601 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2015-01-27T23:00:59.602Z,1422399659.602 [LoopControl](DEBUG): Initialize LoopControlComponent.
2015-01-27T23:00:59.602Z,1422399659.602 [SBIT](INFO): Initialize SBIT Component.
2015-01-27T23:00:59.602Z,1422399659.602 [SBIT](IMPORTANT): Tethys CM Info: SVN revision:11963
2015-01-27T23:00:59.603Z,1422399659.603 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2015-01-27T23:00:59.603Z,1422399659.603 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2015-01-27T23:00:59.604Z,1422399659.604 [IBIT](INFO): Initialize IBIT Component.
2015-01-27T23:00:59.605Z,1422399659.605 [CBIT](DEBUG): Initialize CBIT Component.
2015-01-27T23:00:59.605Z,1422399659.605 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2015-01-27T23:00:59.606Z,1422399659.606 [logger ThreadHandler](INFO): Handler Thread ID is 2999
2015-01-27T23:00:59.625Z,1422399659.625 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 3000
2015-01-27T23:00:59.629Z,1422399659.629 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2015-01-27T23:00:59.629Z,1422399659.629 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2015-01-27T23:00:59.630Z,1422399659.630 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2015-01-27T23:00:59.630Z,1422399659.630 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2015-01-27T23:00:59.631Z,1422399659.631 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2015-01-27T23:00:59.631Z,1422399659.631 [NavChart](DEBUG): Initialize NavChart Navigation.
2015-01-27T23:00:59.631Z,1422399659.631 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2015-01-27T23:00:59.637Z,1422399659.637 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2015-01-27T23:00:59.647Z,1422399659.647 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2015-01-27T23:00:59.649Z,1422399659.649 [Radio_Surface](INFO): Powering up
2015-01-27T23:00:59.661Z,1422399659.661 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 3001
2015-01-27T23:00:59.664Z,1422399659.664 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2015-01-27T23:00:59.665Z,1422399659.665 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2015-01-27T23:00:59.665Z,1422399659.665 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2015-01-27T23:00:59.666Z,1422399659.666 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2015-01-27T23:00:59.666Z,1422399659.666 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2015-01-27T23:00:59.666Z,1422399659.666 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2015-01-27T23:00:59.667Z,1422399659.667 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2015-01-27T23:00:59.667Z,1422399659.667 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2015-01-27T23:00:59.667Z,1422399659.667 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2015-01-27T23:00:59.691Z,1422399659.691 [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-27T23:00:59.692Z,1422399659.692 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2015-01-27T23:00:59.789Z,1422399659.789 [MissionManager](INFO): DefineArg Default.TimeMissionWasStarted = 0.000000 h
2015-01-27T23:00:59.792Z,1422399659.792 [MissionManager](INFO): DefineArg Default.ElapsedSinceMissionWasStarted = 0.000000 h
2015-01-27T23:00:59.808Z,1422399659.808 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2015-01-27T23:00:59.832Z,1422399659.832 [Default:CheckIn:A.SetSpeed](DEBUG): Construct.
2015-01-27T23:00:59.854Z,1422399659.854 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2015-01-27T23:00:59.905Z,1422399659.905 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Construct.
2015-01-27T23:00:59.919Z,1422399659.919 [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-27T23:00:59.923Z,1422399659.923 [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-27T23:01:00.081Z,1422399660.081 [NAL9602](INFO): Start
2015-01-27T23:01:00.518Z,1422399660.518 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2015-01-27T23:01:00.526Z,1422399660.526 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2015-01-27T23:01:00.540Z,1422399660.540 [ElevatorServo](DEBUG): Initializing EZServoServo.
2015-01-27T23:01:00.546Z,1422399660.546 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2015-01-27T23:01:00.560Z,1422399660.560 [RudderServo](DEBUG): Initializing EZServoServo.
2015-01-27T23:01:00.566Z,1422399660.566 [RudderServo](DEBUG): Initializing RudderServo.
2015-01-27T23:01:00.589Z,1422399660.589 [ThrusterServo](DEBUG): Initializing EZServoServo.
2015-01-27T23:01:00.595Z,1422399660.595 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2015-01-27T23:01:00.760Z,1422399660.760 [NAL9602](INFO): Start
2015-01-27T23:01:09.683Z,1422399669.682 [NAL9602](INFO): Start
2015-01-27T23:01:09.683Z,1422399669.683 [NAL9602](INFO): Powering up NAL9602
2015-01-27T23:01:10.842Z,1422399670.842 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003300
2015-01-27T23:01:14.918Z,1422399674.918 [SBIT](IMPORTANT): Beginning Startup BIT
2015-01-27T23:01:14.921Z,1422399674.921 [CBIT](IMPORTANT): Beginning GF scan
2015-01-27T23:01:20.851Z,1422399680.851 [NAL9602](INFO): ************** CMDMODE **************

2015-01-27T23:01:20.851Z,1422399680.851 [NAL9602](INFO): NAL9602 initialized
2015-01-27T23:01:24.040Z,1422399684.040 [NAL9602](INFO): Bytes:2
2015-01-27T23:01:24.041Z,1422399684.041 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:01:24.445Z,1422399684.445 [NAL9602](INFO): Bytes:12
2015-01-27T23:01:24.445Z,1422399684.445 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:

+CSQ:0

OK
2015-01-27T23:01:24.842Z,1422399684.842 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:01:28.159Z,1422399688.159 [SBIT](ERROR): Could not read massPosReader_.
2015-01-27T23:01:28.840Z,1422399688.840 [NAL9602](INFO): Bytes:10
2015-01-27T23:01:28.840Z,1422399688.840 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:01:29.244Z,1422399689.244 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:01:29.641Z,1422399689.641 [NAL9602](INFO): Bytes:10
2015-01-27T23:01:29.641Z,1422399689.641 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:01:30.041Z,1422399690.041 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:01:34.040Z,1422399694.040 [NAL9602](INFO): Bytes:10
2015-01-27T23:01:34.040Z,1422399694.040 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:01:34.445Z,1422399694.445 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:01:34.845Z,1422399694.845 [NAL9602](INFO): Bytes:10
2015-01-27T23:01:34.845Z,1422399694.845 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:01:35.245Z,1422399695.245 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:01:39.244Z,1422399699.244 [NAL9602](INFO): Bytes:10
2015-01-27T23:01:39.244Z,1422399699.244 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:01:39.644Z,1422399699.644 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:01:40.045Z,1422399700.045 [NAL9602](INFO): Bytes:10
2015-01-27T23:01:40.045Z,1422399700.045 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:01:40.446Z,1422399700.446 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:01:41.374Z,1422399701.374 [CBIT](IMPORTANT): No ground fault detected
2015-01-27T23:01:44.444Z,1422399704.444 [NAL9602](INFO): Bytes:10
2015-01-27T23:01:44.444Z,1422399704.444 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:01:44.840Z,1422399704.840 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:01:45.245Z,1422399705.245 [NAL9602](INFO): Bytes:10
2015-01-27T23:01:45.246Z,1422399705.246 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:01:45.642Z,1422399705.642 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:01:49.243Z,1422399709.243 [NAL9602](INFO): Bytes:10
2015-01-27T23:01:49.244Z,1422399709.244 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:01:49.640Z,1422399709.640 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:01:52.040Z,1422399712.040 [NAL9602](INFO): Bytes:10
2015-01-27T23:01:52.040Z,1422399712.040 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:01:52.445Z,1422399712.445 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:01:54.588Z,1422399714.588 [SBIT](ERROR): Could not read massPosReader_.
2015-01-27T23:01:54.589Z,1422399714.589 [SBIT](FAULT): Control surface position failure.
2015-01-27T23:02:00.445Z,1422399720.445 [NAL9602](INFO): Bytes:10
2015-01-27T23:02:00.445Z,1422399720.445 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:02:06.503Z,1422399726.503 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:02:08.281Z,1422399728.281 [SBIT](ERROR): Could not read massPosReader_.
2015-01-27T23:02:08.282Z,1422399728.282 [SBIT](FAULT): Control surface position failure.
2015-01-27T23:02:08.649Z,1422399728.649 [SBIT](CRITICAL): SBIT FAILED
2015-01-27T23:02:08.650Z,1422399728.650 [CommandLine](FAULT): Scheduling is paused
2015-01-27T23:02:09.030Z,1422399729.030 [NAL9602](INFO): Bytes:10
2015-01-27T23:02:09.031Z,1422399729.031 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:02:09.084Z,1422399729.084 [MissionManager](IMPORTANT): Started mission Startup
2015-01-27T23:02:09.084Z,1422399729.084 [Startup] Running Loop=1
2015-01-27T23:02:09.084Z,1422399729.084 [Startup](INFO): Aggregate::initialize Startup
2015-01-27T23:02:09.084Z,1422399729.084 [Startup:A.GoToSurface] Running Loop=1
2015-01-27T23:02:09.084Z,1422399729.084 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2015-01-27T23:02:09.085Z,1422399729.085 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2015-01-27T23:02:09.086Z,1422399729.086 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2015-01-27T23:02:09.086Z,1422399729.086 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2015-01-27T23:02:09.092Z,1422399729.092 [Startup:StartupSatComms] Running Loop=1
2015-01-27T23:02:09.092Z,1422399729.092 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2015-01-27T23:02:09.092Z,1422399729.092 [Startup:StartupSatComms:A] Running Loop=1
2015-01-27T23:02:09.431Z,1422399729.431 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:02:09.453Z,1422399729.453 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2015-01-27T23:02:09.832Z,1422399729.832 [NAL9602](INFO): Bytes:10
2015-01-27T23:02:09.832Z,1422399729.832 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:02:10.232Z,1422399730.232 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:02:14.230Z,1422399734.230 [NAL9602](INFO): Bytes:10
2015-01-27T23:02:14.231Z,1422399734.231 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:02:14.631Z,1422399734.631 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:02:15.032Z,1422399735.032 [NAL9602](INFO): Bytes:10
2015-01-27T23:02:15.032Z,1422399735.032 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:02:15.432Z,1422399735.432 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:02:23.833Z,1422399743.833 [NAL9602](INFO): Bytes:10
2015-01-27T23:02:23.833Z,1422399743.833 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:02:24.234Z,1422399744.234 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:02:27.832Z,1422399747.832 [NAL9602](INFO): Bytes:10
2015-01-27T23:02:27.832Z,1422399747.832 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:02:28.228Z,1422399748.228 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:02:32.234Z,1422399752.234 [NAL9602](INFO): Bytes:10
2015-01-27T23:02:32.235Z,1422399752.235 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:02:32.631Z,1422399752.631 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:02:41.030Z,1422399761.030 [NAL9602](INFO): Bytes:10
2015-01-27T23:02:41.031Z,1422399761.031 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:02:41.429Z,1422399761.429 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:02:45.435Z,1422399765.435 [NAL9602](INFO): Bytes:10
2015-01-27T23:02:45.435Z,1422399765.435 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:02:45.832Z,1422399765.832 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:02:49.429Z,1422399769.429 [NAL9602](INFO): Bytes:10
2015-01-27T23:02:49.429Z,1422399769.429 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:02:49.837Z,1422399769.837 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:02:53.834Z,1422399773.834 [NAL9602](INFO): Bytes:10
2015-01-27T23:02:53.834Z,1422399773.834 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:02:54.235Z,1422399774.235 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:02:54.635Z,1422399774.635 [NAL9602](INFO): Bytes:10
2015-01-27T23:02:54.636Z,1422399774.636 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:02:55.036Z,1422399775.036 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:02:58.635Z,1422399778.635 [NAL9602](INFO): Bytes:10
2015-01-27T23:02:58.636Z,1422399778.636 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:02:59.030Z,1422399779.030 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:02:59.435Z,1422399779.435 [NAL9602](INFO): Bytes:10
2015-01-27T23:02:59.435Z,1422399779.435 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:02:59.835Z,1422399779.835 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:03:03.846Z,1422399783.846 [NAL9602](INFO): Bytes:10
2015-01-27T23:03:03.846Z,1422399783.846 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:03:04.024Z,1422399784.024 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:03:04.376Z,1422399784.376 [NAL9602](INFO): Bytes:10
2015-01-27T23:03:04.376Z,1422399784.376 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:03:04.777Z,1422399784.777 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:03:08.782Z,1422399788.782 [NAL9602](INFO): Bytes:10
2015-01-27T23:03:08.782Z,1422399788.782 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:03:09.168Z,1422399789.168 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:03:09.198Z,1422399789.198 [Startup:StartupSatComms:A](INFO): Timed out from 2015-01-27T23:02:09.1Z
2015-01-27T23:03:09.198Z,1422399789.198 [Startup:StartupSatComms:A] Stopped
2015-01-27T23:03:09.198Z,1422399789.198 [Startup:StartupSatComms:B] Running Loop=1
2015-01-27T23:03:09.588Z,1422399789.588 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2015-01-27T23:03:13.566Z,1422399793.566 [NAL9602](INFO): Bytes:10
2015-01-27T23:03:13.566Z,1422399793.566 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:03:13.688Z,1422399793.688 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:03:14.029Z,1422399794.029 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20150127T223757/Courier0004.lzma
2015-01-27T23:03:14.828Z,1422399794.828 [DataOverHttps](INFO): Moved sent file to Logs/20150127T223757/Courier0004.lzma.bak
2015-01-27T23:03:14.828Z,1422399794.828 [DataOverHttps](INFO): SBD MOMSN=1508792
2015-01-27T23:03:20.141Z,1422399800.141 [NAL9602](INFO): Bytes:10
2015-01-27T23:03:20.141Z,1422399800.141 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:1

OKOK
2015-01-27T23:03:20.543Z,1422399800.543 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:03:23.861Z,1422399803.861 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20150127T224530/Courier0000.lzma
2015-01-27T23:03:24.649Z,1422399804.649 [DataOverHttps](INFO): Moved sent file to Logs/20150127T224530/Courier0000.lzma.bak
2015-01-27T23:03:24.649Z,1422399804.649 [DataOverHttps](INFO): SBD MOMSN=1508794
2015-01-27T23:03:28.631Z,1422399808.631 [NAL9602](INFO): Bytes:10
2015-01-27T23:03:28.631Z,1422399808.631 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:03:28.754Z,1422399808.754 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:03:29.904Z,1422399809.904 [NAL9602](INFO): Bytes:10
2015-01-27T23:03:29.904Z,1422399809.904 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:0

OKOK
2015-01-27T23:03:30.299Z,1422399810.299 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:03:34.332Z,1422399814.332 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20150127T230050/Courier0000.lzma
2015-01-27T23:03:35.131Z,1422399815.131 [DataOverHttps](INFO): Moved sent file to Logs/20150127T230050/Courier0000.lzma.bak
2015-01-27T23:03:35.131Z,1422399815.131 [DataOverHttps](INFO): SBD MOMSN=1508798
2015-01-27T23:03:39.185Z,1422399819.185 [NAL9602](INFO): Bytes:10
2015-01-27T23:03:39.185Z,1422399819.185 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:1

OKOK
2015-01-27T23:03:39.331Z,1422399819.331 [NAL9602](INFO): MT Sig Qty requested
2015-01-27T23:03:51.044Z,1422399831.044 [DataOverHttps](INFO): Sending 114 bytes from file Logs/20150127T222937/Express0005.lzma
2015-01-27T23:03:51.057Z,1422399831.057 [NAL9602](INFO): Bytes:10
2015-01-27T23:03:51.058Z,1422399831.058 [NAL9602](INFO): MTQueue SIGNAL QUALITY RESPONSE RECEIVED:
+CSQ:2

OKOK
2015-01-27T23:03:51.066Z,1422399831.066 [NAL9602](INFO): questing MT sbdi session. Quality is:
2015-01-27T23:03:51.177Z,1422399831.177 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T23:03:51.537Z,1422399831.537 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T23:03:51.933Z,1422399831.933 [DataOverHttps](INFO): Moved sent file to Logs/20150127T222937/Express0005.lzma.bak
2015-01-27T23:03:51.934Z,1422399831.934 [DataOverHttps](INFO): SBD MOMSN=1508802
2015-01-27T23:03:51.958Z,1422399831.958 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T23:03:52.702Z,1422399832.702 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T23:03:52.823Z,1422399832.823 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T23:03:56.013Z,1422399836.013 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T23:03:56.121Z,1422399836.121 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T23:03:56.493Z,1422399836.493 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T23:03:56.894Z,1422399836.894 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T23:03:57.298Z,1422399837.298 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T23:03:57.695Z,1422399837.695 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T23:04:00.877Z,1422399840.877 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T23:04:00.879Z,1422399840.879 [NAL9602](INFO): SBD MO Status=0, MOMSN=5441, MT Status=0, MTMSN=0
2015-01-27T23:04:00.879Z,1422399840.879 [NAL9602](INFO): sendFilename:resendFilename:
2015-01-27T23:04:00.879Z,1422399840.879 [NAL9602](INFO): No messages in MT queue
2015-01-27T23:04:00.949Z,1422399840.949 [DataOverHttps](INFO): Sending 663 bytes from file Logs/20150127T223757/Express0001.lzma
2015-01-27T23:04:01.737Z,1422399841.737 [DataOverHttps](INFO): Moved sent file to Logs/20150127T223757/Express0001.lzma.bak
2015-01-27T23:04:01.737Z,1422399841.737 [DataOverHttps](INFO): SBD MOMSN=1508808
2015-01-27T23:04:08.294Z,1422399848.294 [BPC1](ERROR): B bank expecting battery number:1 and read number: uart read:X
$S,01,270F,02,00,04,5E%57
$C1,01,FF,02,00,03,FF,04,00,05,00,06,00,07,00%72
$B11,0A,FFFC%36
$B12,0A,0000%30
$B13,0A,FFFB%35
$B14,0A,FFFC%33
$B15,0A,0000%37
$B16,0A,0000%34
$B17,0A,0000%35
$B18,0A,FFD3%4D
$S,01,270F,02,00,04,5E%57
$C1,01,FF,02,00,03,FF,04,00,05,00,06,00,07,00%72
$B11,02,000A,01,026C,03,0001,08,0B91,09,3C52,0A,FFFC,0B,FFFC%4A
$B11,0C,0001,0D,0059,0E,0056,0F,14B1,10,1787,11,FFFF,12,FFFF%35
$B11,13,FFFF,14,0BB8,15,41A0,16,00C0,17,0002,18,1838,19,3840%41
$B11,1A,0031,1B,4357,1C,00A7%42
$B12,02,000A,01,026C,03,0001,08,0B8F,09,3C24,0A,0000,0B,0000%3E
$B12,0C,0001,0D,0064,0E,0060,0F,170F,10,170F,11,FFFF,12,FFFF%42
$B12,13,FFFF,14,0000,15,41A0,16,00E0,17,0001,18,1838,19,3840%4F
$B12,1A,0031,1B,4357,1C,009E%4B
$B13,02,000A,01,026C,03,0001,08,0B96,09,3C57,0A,FFFB,0B,FFFB%4A
$B13,0C,0001,0D,0060,0E,0054,0F,1456,10,17AC,11,F408,12,F408%42
$B13,13,FFFF,14,0BB8,15,41A0,16,00C0,17,0002,18,1838,19,3840%43
$B13,1A,0031,1B,4357,1C,0089%37
$B14,02,000A,01,026C,03,0001,08,0B99,09,3C57,0A,FFFC,0B,FFFC%42
$B14,0C,0001,0D,0059,0E,0054,0F,1438,10,16F6,11,FFFF,12,FFFF%34
$B14,13,FFFF,14,0BB8,15,41A0,16,00C0,17,0002,18,1838,19,3840%44
$B14,1A,0031,1B,4357,1C,00A6%46
$B15,02,000A,01,026C,03,0001,08,0B92,09,3C15,0A,0000,0B,0000%4E
$B15,0C,0001,0D,0064,0E,005C,0F,162F,10,171F,11,FFFF,12,FFFF%37
$B15,13,FFFF,14,0000,15,41A0,16,00E0,17,0001,18,1838,19,3840%48
$B15,1A,0031,1B,4357,1C,00A9%48
$B16,02,000A,01,026C,03,0001,08,0B8D,09,3C5C,0A,0000,0B,0000%48
$B16,0C,0001,0D,0061,0E,0057,0F,1501,10,1698,11,FFFF,12,FFFF%44
$B16,13,FFFF,14,0BB8,15,41A0,16,00C0,17,0001,18,1838,19,3840%45
$B16,1A,0031,1B,4357,1C,00A8%4A
$B17,02,000A,01,026C,03,0001,08,0B8F,09,3C56,0A,0000,0B,0000%3E
$B17,0C,0001,0D,005E,0E,0057,0F,14E5,10,16E3,11,FFFF,12,FFFF%35
$B17,13,FFFF,14,0BB8,15,41A0,16,00C0,17,0001,18,1838,19,3840%44
$B17,1A,0031,1B,4357,1C,0096%3D
$B18,02,000A,01,026C,03,0001,08,0B91,09,3C36,0A,FFD8,0B,FFD6%4F
$B18,0C,0001,0D,0059,0E,0056,0F,14A4,10,17BD,11,1EF6,12,1D7D%31
$B18,13,FFFF,14,0BB8,15,41A0,16,00C0,17,0002,18,1838,19,3840%48
$B18,1A,0031,1B,4357,1C,009B%46

2015-01-27T23:04:08.294Z,1422399848.294 [BPC1](FAULT): Failed to parse bank B battery data
2015-01-27T23:04:08.295Z,1422399848.295 [BPC1] Data Fault, FailCount= 1
2015-01-27T23:04:08.295Z,1422399848.295 [BPC1](ERROR): Data Fault
2015-01-27T23:04:08.364Z,1422399848.364 [CBIT](ERROR): Data Fault in component: BPC1
2015-01-27T23:04:11.485Z,1422399851.485 [Startup:StartupSatComms:B](INFO): Timed out from 2015-01-27T23:03:09.2Z
2015-01-27T23:04:11.485Z,1422399851.485 [Startup:StartupSatComms:B] Stopped
2015-01-27T23:04:11.485Z,1422399851.485 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2015-01-27T23:04:11.485Z,1422399851.485 [Startup:StartupSatComms] Stopped
2015-01-27T23:04:11.485Z,1422399851.485 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2015-01-27T23:04:11.486Z,1422399851.486 [Startup](INFO): Completed Startup
2015-01-27T23:04:11.486Z,1422399851.486 [Startup] Stopped
2015-01-27T23:04:11.487Z,1422399851.487 [Startup](INFO): Aggregate::uninitialize Startup
2015-01-27T23:04:11.487Z,1422399851.487 [Startup:A.GoToSurface] Stopped
2015-01-27T23:04:11.487Z,1422399851.487 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2015-01-27T23:04:11.583Z,1422399851.583 [MissionManager](IMPORTANT): Started mission Default
2015-01-27T23:04:11.583Z,1422399851.583 [Default] Running Loop=1
2015-01-27T23:04:11.584Z,1422399851.584 [Default](INFO): Aggregate::initialize Default
2015-01-27T23:04:11.584Z,1422399851.584 [Default:B.GoToSurface] Running Loop=1
2015-01-27T23:04:11.584Z,1422399851.584 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2015-01-27T23:04:11.584Z,1422399851.584 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2015-01-27T23:04:11.584Z,1422399851.584 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2015-01-27T23:04:11.585Z,1422399851.585 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2015-01-27T23:04:11.585Z,1422399851.585 [Default:StartClock] Running Loop=1
2015-01-27T23:04:11.585Z,1422399851.585 [Default:StartClock](INFO): Aggregate::initialize Default:StartClock
2015-01-27T23:04:11.585Z,1422399851.585 [Default:StartClock:A] Running Loop=1
2015-01-27T23:04:11.586Z,1422399851.586 [Default:CheckIn] Running Loop=1
2015-01-27T23:04:11.586Z,1422399851.586 [Default:CheckIn](INFO): Aggregate::initialize Default:CheckIn
2015-01-27T23:04:11.586Z,1422399851.586 [Default:CheckIn:A.SetSpeed] Running Loop=1
2015-01-27T23:04:11.586Z,1422399851.586 [Default:CheckIn:A.SetSpeed](DEBUG): Initialize.
2015-01-27T23:04:11.586Z,1422399851.586 [Default:CheckIn:Read_GPS] Running Loop=1
2015-01-27T23:04:11.587Z,1422399851.587 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2015-01-27T23:04:11.589Z,1422399851.589 [Default:CheckIn:A.SetSpeed] Running Loop=1
2015-01-27T23:04:11.609Z,1422399851.609 [Default:StartClock:A] Stopped
2015-01-27T23:04:11.609Z,1422399851.609 [Default:StartClock](INFO): Completed Default:StartClock
2015-01-27T23:04:11.610Z,1422399851.610 [Default:StartClock] Stopped
2015-01-27T23:04:11.610Z,1422399851.610 [Default:StartClock](INFO): Aggregate::uninitialize Default:StartClock
2015-01-27T23:04:11.931Z,1422399851.931 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20150127T223757/Express0005.lzma
2015-01-27T23:04:11.980Z,1422399851.980 [Default:WaitAtTheSurface] Running Loop=1
2015-01-27T23:04:11.981Z,1422399851.981 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface
2015-01-27T23:04:11.981Z,1422399851.981 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2015-01-27T23:04:11.981Z,1422399851.981 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Initialize.
2015-01-27T23:04:11.989Z,1422399851.989 [CBIT](INFO): Clearing failed state for component BPC1
2015-01-27T23:04:11.989Z,1422399851.989 [BPC1] No Fault, FailCount= 1
2015-01-27T23:04:12.418Z,1422399852.418 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2015-01-27T23:04:12.730Z,1422399852.730 [DataOverHttps](INFO): Moved sent file to Logs/20150127T223757/Express0005.lzma.bak
2015-01-27T23:04:12.730Z,1422399852.730 [DataOverHttps](INFO): SBD MOMSN=1508828
2015-01-27T23:04:23.846Z,1422399863.846 [CommandLine](IMPORTANT): got command quit
2015-01-27T23:04:24.851Z,1422399864.851 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-27T23:04:24.851Z,1422399864.851 [CommandLine ThreadHandler](INFO): Thread cancelled.
2015-01-27T23:04:24.924Z,1422399864.924 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2015-01-27T23:04:24.924Z,1422399864.924 [CommandLine ThreadHandler](INFO): Thread cancelled.
2015-01-27T23:04:24.925Z,1422399864.925 [CommandLine](INFO): Join timeout helper Thread ID is 3008
2015-01-27T23:04:24.925Z,1422399864.925 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2015-01-27T23:04:24.925Z,1422399864.925 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2015-01-27T23:04:24.926Z,1422399864.926 [NavChartDb](INFO): Join timeout helper Thread ID is 3009
2015-01-27T23:04:25.145Z,1422399865.145 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-27T23:04:25.145Z,1422399865.145 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2015-01-27T23:04:25.165Z,1422399865.165 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2015-01-27T23:04:25.165Z,1422399865.165 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2015-01-27T23:04:25.165Z,1422399865.165 [Radio_Surface](INFO): Join timeout helper Thread ID is 3010
2015-01-27T23:04:25.397Z,1422399865.397 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-27T23:04:25.397Z,1422399865.397 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2015-01-27T23:04:25.409Z,1422399865.409 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2015-01-27T23:04:25.409Z,1422399865.409 [logger ThreadHandler](INFO): Thread cancelled.
2015-01-27T23:04:25.409Z,1422399865.409 [logger](INFO): Join timeout helper Thread ID is 3011
2015-01-27T23:04:25.429Z,1422399865.429 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-27T23:04:25.429Z,1422399865.429 [logger ThreadHandler](INFO): Thread cancelled.
2015-01-27T23:04:25.449Z,1422399865.449 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2015-01-27T23:04:25.449Z,1422399865.449 [CommandLine ThreadHandler](INFO): Thread cancelled.
2015-01-27T23:04:25.449Z,1422399865.449 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2015-01-27T23:04:25.449Z,1422399865.449 [controlThread ThreadHandler](INFO): Thread cancelled.
2015-01-27T23:04:25.450Z,1422399865.450 [controlThread](INFO): Join timeout helper Thread ID is 3012
2015-01-27T23:04:25.565Z,1422399865.565 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-27T23:04:25.565Z,1422399865.565 [controlThread](DEBUG): Uninitializing ControlThread
2015-01-27T23:04:25.566Z,1422399865.566 [NAL9602](INFO): Uninitialize
2015-01-27T23:04:25.566Z,1422399865.566 [NAL9602](INFO): Powering down
2015-01-27T23:04:25.568Z,1422399865.568 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2015-01-27T23:04:25.568Z,1422399865.568 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2015-01-27T23:04:25.569Z,1422399865.569 [Default] Stopped
2015-01-27T23:04:25.569Z,1422399865.569 [Default](INFO): Aggregate::uninitialize Default
2015-01-27T23:04:25.569Z,1422399865.569 [Default:B.GoToSurface] Stopped
2015-01-27T23:04:25.569Z,1422399865.569 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2015-01-27T23:04:25.569Z,1422399865.569 [Default:CheckIn] Stopped
2015-01-27T23:04:25.569Z,1422399865.569 [Default:CheckIn](INFO): Aggregate::uninitialize Default:CheckIn
2015-01-27T23:04:25.569Z,1422399865.569 [Default:CheckIn:A.SetSpeed] Stopped
2015-01-27T23:04:25.569Z,1422399865.569 [Default:CheckIn:A.SetSpeed](DEBUG): Uninitialize.
2015-01-27T23:04:25.570Z,1422399865.570 [Default:CheckIn:Read_GPS] Stopped
2015-01-27T23:04:25.570Z,1422399865.570 [Default:WaitAtTheSurface] Stopped
2015-01-27T23:04:25.570Z,1422399865.570 [Default:WaitAtTheSurface](INFO): Aggregate::uninitialize Default:WaitAtTheSurface
2015-01-27T23:04:25.570Z,1422399865.570 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Stopped
2015-01-27T23:04:25.570Z,1422399865.570 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Uninitialize.
2015-01-27T23:04:25.573Z,1422399865.573 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2015-01-27T23:04:25.574Z,1422399865.574 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2015-01-27T23:04:25.574Z,1422399865.574 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2015-01-27T23:04:25.574Z,1422399865.574 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2015-01-27T23:04:25.574Z,1422399865.574 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2015-01-27T23:04:25.575Z,1422399865.575 [BuoyancyServo](INFO): Powering down
2015-01-27T23:04:25.589Z,1422399865.589 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2015-01-27T23:04:25.589Z,1422399865.589 [ElevatorServo](INFO): Powering down
2015-01-27T23:04:25.590Z,1422399865.590 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2015-01-27T23:04:25.590Z,1422399865.590 [RudderServo](INFO): Powering down
2015-01-27T23:04:25.591Z,1422399865.591 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2015-01-27T23:04:25.591Z,1422399865.591 [ThrusterServo](INFO): Powering down
2015-01-27T23:04:25.592Z,1422399865.592 [SBIT](DEBUG): Uninitialize SBIT Component.
2015-01-27T23:04:25.592Z,1422399865.592 [IBIT](DEBUG): Uninitialize IBIT Component.
2015-01-27T23:04:25.593Z,1422399865.593 [CBIT](DEBUG): Uninitialize CBIT Component.
2015-01-27T23:04:25.626Z,1422399865.626 [controlThread ThreadHandler](INFO): Thread cancelled.
2015-01-27T23:04:25.726Z,1422399865.726 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2015-01-27T23:04:25.766Z,1422399865.766 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2015-01-27T23:04:25.807Z,1422399865.807 [logger ThreadHandler](INFO): Thread cancelled.