2013-08-26T21:37:05.096Z,1377553025.096 [Supervisor](DEBUG): Initializing supervisor.
2013-08-26T21:37:05.098Z,1377553025.098 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2013-08-26T21:37:05.099Z,1377553025.099 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2013-08-26T21:37:05.100Z,1377553025.100 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2013-08-26T21:37:05.103Z,1377553025.103 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2013-08-26T21:37:05.114Z,1377553025.114 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2013-08-26T21:37:05.115Z,1377553025.115 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2013-08-26T21:37:05.116Z,1377553025.116 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2013-08-26T21:37:05.117Z,1377553025.117 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0
2013-08-26T21:37:05.117Z,1377553025.117 [Supervisor](INFO): Looking for Config files in directory: Config/
2013-08-26T21:37:05.119Z,1377553025.119 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2013-08-26T21:37:05.394Z,1377553025.394 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2013-08-26T21:37:05.394Z,1377553025.394 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2013-08-26T21:37:05.584Z,1377553025.584 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2013-08-26T21:37:05.584Z,1377553025.584 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2013-08-26T21:37:05.669Z,1377553025.669 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2013-08-26T21:37:05.670Z,1377553025.670 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2013-08-26T21:37:05.780Z,1377553025.780 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2013-08-26T21:37:05.781Z,1377553025.781 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2013-08-26T21:37:05.918Z,1377553025.918 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2013-08-26T21:37:05.918Z,1377553025.918 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2013-08-26T21:37:06.152Z,1377553026.152 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2013-08-26T21:37:06.152Z,1377553026.152 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2013-08-26T21:37:06.315Z,1377553026.315 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2013-08-26T21:37:06.315Z,1377553026.315 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2013-08-26T21:37:06.572Z,1377553026.572 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2013-08-26T21:37:06.573Z,1377553026.573 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2013-08-26T21:37:06.674Z,1377553026.674 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2013-08-26T21:37:06.674Z,1377553026.674 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2013-08-26T21:37:07.078Z,1377553027.078 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2013-08-26T21:37:07.079Z,1377553027.079 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2013-08-26T21:37:07.188Z,1377553027.188 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2013-08-26T21:37:07.189Z,1377553027.189 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2013-08-26T21:37:07.275Z,1377553027.275 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2013-08-26T21:37:07.276Z,1377553027.276 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2013-08-26T21:37:07.375Z,1377553027.375 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2013-08-26T21:37:07.500Z,1377553027.500 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2013-08-26T21:37:07.592Z,1377553027.592 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2013-08-26T21:37:07.697Z,1377553027.697 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2013-08-26T21:37:07.839Z,1377553027.839 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2013-08-26T21:37:07.953Z,1377553027.953 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2013-08-26T21:37:08.048Z,1377553028.048 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2013-08-26T21:37:08.133Z,1377553028.133 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2013-08-26T21:37:08.134Z,1377553028.134 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2013-08-26T21:37:08.291Z,1377553028.291 [InternalSim] Loaded
2013-08-26T21:37:08.291Z,1377553028.291 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2013-08-26T21:37:08.292Z,1377553028.292 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2013-08-26T21:37:08.292Z,1377553028.292 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2013-08-26T21:37:08.374Z,1377553028.374 [SBIT](DEBUG): Construct Startup Built In Test.
2013-08-26T21:37:08.402Z,1377553028.402 [SBIT] Loaded
2013-08-26T21:37:08.402Z,1377553028.402 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2013-08-26T21:37:08.403Z,1377553028.402 [IBIT](DEBUG): Construct Initiated Built In Test.
2013-08-26T21:37:08.431Z,1377553028.431 [IBIT] Loaded
2013-08-26T21:37:08.431Z,1377553028.431 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2013-08-26T21:37:08.433Z,1377553028.433 [CBIT](DEBUG): Construct CBIT Built In Test.
2013-08-26T21:37:08.544Z,1377553028.544 [CBIT] Loaded
2013-08-26T21:37:08.544Z,1377553028.544 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2013-08-26T21:37:08.544Z,1377553028.545 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2013-08-26T21:37:08.545Z,1377553028.545 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2013-08-26T21:37:08.710Z,1377553028.710 [BuoyancyServo] Loaded
2013-08-26T21:37:08.711Z,1377553028.711 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2013-08-26T21:37:08.722Z,1377553028.722 [ElevatorServo] Loaded
2013-08-26T21:37:08.722Z,1377553028.722 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2013-08-26T21:37:08.733Z,1377553028.733 [MassServo] Loaded
2013-08-26T21:37:08.734Z,1377553028.734 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2013-08-26T21:37:08.744Z,1377553028.744 [RudderServo] Loaded
2013-08-26T21:37:08.745Z,1377553028.745 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2013-08-26T21:37:08.756Z,1377553028.756 [ThrusterServo] Loaded
2013-08-26T21:37:08.756Z,1377553028.756 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2013-08-26T21:37:08.756Z,1377553028.756 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2013-08-26T21:37:08.757Z,1377553028.757 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2013-08-26T21:37:08.791Z,1377553028.791 [DepthRateCalculator] Loaded
2013-08-26T21:37:08.791Z,1377553028.791 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2013-08-26T21:37:11.844Z,1377553031.843 [HFRadarModelCalc] Loaded
2013-08-26T21:37:11.844Z,1377553031.844 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2013-08-26T21:37:11.859Z,1377553031.859 [NavChart] Loaded
2013-08-26T21:37:11.860Z,1377553031.860 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2013-08-26T21:37:11.865Z,1377553031.865 [PitchRateCalculator] Loaded
2013-08-26T21:37:11.865Z,1377553031.865 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2013-08-26T21:37:11.875Z,1377553031.875 [SpeedCalculator] Loaded
2013-08-26T21:37:11.876Z,1377553031.876 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2013-08-26T21:37:11.891Z,1377553031.891 [TempGradientCalculator] Loaded
2013-08-26T21:37:11.892Z,1377553031.892 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2013-08-26T21:37:11.897Z,1377553031.897 [YawRateCalculator] Loaded
2013-08-26T21:37:11.897Z,1377553031.897 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2013-08-26T21:37:11.942Z,1377553031.942 [Navigation] Loaded
2013-08-26T21:37:11.942Z,1377553031.942 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2013-08-26T21:37:11.943Z,1377553031.943 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2013-08-26T21:37:11.943Z,1377553031.943 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2013-08-26T21:37:12.169Z,1377553032.169 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2013-08-26T21:37:12.170Z,1377553032.170 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2013-08-26T21:37:12.192Z,1377553032.192 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2013-08-26T21:37:12.192Z,1377553032.193 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2013-08-26T21:37:12.238Z,1377553032.238 [VerticalControl](DEBUG): Construct VerticalControl.
2013-08-26T21:37:12.329Z,1377553032.329 [VerticalControl] Loaded
2013-08-26T21:37:12.329Z,1377553032.329 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2013-08-26T21:37:12.329Z,1377553032.329 [HorizontalControl](DEBUG): Construct HorizontalControl.
2013-08-26T21:37:12.385Z,1377553032.385 [HorizontalControl] Loaded
2013-08-26T21:37:12.385Z,1377553032.385 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2013-08-26T21:37:12.386Z,1377553032.386 [SpeedControl](DEBUG): Construct SpeedControl.
2013-08-26T21:37:12.388Z,1377553032.388 [SpeedControl] Loaded
2013-08-26T21:37:12.388Z,1377553032.388 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2013-08-26T21:37:12.389Z,1377553032.389 [LoopControl](DEBUG): Construct LoopControl.
2013-08-26T21:37:12.389Z,1377553032.389 [LoopControl] Loaded
2013-08-26T21:37:12.389Z,1377553032.389 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2013-08-26T21:37:12.390Z,1377553032.390 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2013-08-26T21:37:12.390Z,1377553032.390 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2013-08-26T21:37:12.396Z,1377553032.396 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2013-08-26T21:37:12.401Z,1377553032.401 [AsyncPiEstimator] Loaded
2013-08-26T21:37:12.401Z,1377553032.401 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2013-08-26T21:37:12.402Z,1377553032.402 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406474E0
2013-08-26T21:37:12.403Z,1377553032.403 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2013-08-26T21:37:12.403Z,1377553032.404 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2013-08-26T21:37:12.590Z,1377553032.590 [AHRS_sp3003D] Loaded
2013-08-26T21:37:12.590Z,1377553032.590 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2013-08-26T21:37:12.831Z,1377553032.832 [Batt_Ocean_Server] Loaded
2013-08-26T21:37:12.832Z,1377553032.832 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2013-08-26T21:37:12.845Z,1377553032.845 [Depth_Keller] Loaded
2013-08-26T21:37:12.845Z,1377553032.845 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2013-08-26T21:37:12.850Z,1377553032.850 [DropWeight] Loaded
2013-08-26T21:37:12.850Z,1377553032.851 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2013-08-26T21:37:13.027Z,1377553033.027 [DVL_micro] Loaded
2013-08-26T21:37:13.027Z,1377553033.027 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2013-08-26T21:37:13.028Z,1377553033.028 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 406D54E0
2013-08-26T21:37:13.113Z,1377553033.113 [NAL9602] Loaded
2013-08-26T21:37:13.113Z,1377553033.113 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2013-08-26T21:37:13.154Z,1377553033.154 [Onboard] Loaded
2013-08-26T21:37:13.154Z,1377553033.154 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2013-08-26T21:37:13.161Z,1377553033.161 [Radio_Freewave] Loaded
2013-08-26T21:37:13.161Z,1377553033.161 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2013-08-26T21:37:13.297Z,1377553033.297 [DAT] Loaded
2013-08-26T21:37:13.298Z,1377553033.297 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2013-08-26T21:37:13.298Z,1377553033.298 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2013-08-26T21:37:13.299Z,1377553033.299 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2013-08-26T21:37:13.360Z,1377553033.360 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2013-08-26T21:37:13.362Z,1377553033.362 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2013-08-26T21:37:13.363Z,1377553033.363 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2013-08-26T21:37:13.370Z,1377553033.370 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2013-08-26T21:37:13.371Z,1377553033.371 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407324E0
2013-08-26T21:37:13.375Z,1377553033.375 [Supervisor](DEBUG): Running supervisor.
2013-08-26T21:37:13.376Z,1377553033.376 [CommandLine](INFO): Thread ID is 897
2013-08-26T21:37:13.379Z,1377553033.379 [controlThread](INFO): Thread ID is 896
2013-08-26T21:37:13.379Z,1377553033.379 [controlThread](DEBUG): Initializing ControlThread
2013-08-26T21:37:13.379Z,1377553033.379 [CycleStarter](INFO): Thread ID is 895
2013-08-26T21:37:13.380Z,1377553033.380 [InternalSim](DEBUG):  InternalSim initializing...
2013-08-26T21:37:13.414Z,1377553033.414 [SBIT](INFO): Initialize SBIT Component.
2013-08-26T21:37:13.414Z,1377553033.414 [SBIT](IMPORTANT): Tethys CM Info: 
$ Rev:10573
2013-08-26T21:37:13.415Z,1377553033.415 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2013-08-26T21:37:13.415Z,1377553033.415 [SBIT](IMPORTANT): Kernel Version:#634 PREEMPT Wed Feb 13 10:21:48 PST 2013
2013-08-26T21:37:13.416Z,1377553033.416 [IBIT](INFO): Initialize IBIT Component.
2013-08-26T21:37:13.417Z,1377553033.417 [CBIT](DEBUG): Initialize CBIT Component.
2013-08-26T21:37:13.417Z,1377553033.417 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2013-08-26T21:37:13.417Z,1377553033.417 [logger](INFO): Thread ID is 898
2013-08-26T21:37:13.434Z,1377553033.434 [AsyncPiEstimator](INFO): Thread ID is 960
2013-08-26T21:37:13.434Z,1377553033.434 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2013-08-26T21:37:13.447Z,1377553033.447 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-08-26T21:37:13.447Z,1377553033.447 [NavChart](DEBUG): Initialize NavChart Derivation.
2013-08-26T21:37:13.448Z,1377553033.448 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2013-08-26T21:37:13.448Z,1377553033.448 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2013-08-26T21:37:13.448Z,1377553033.448 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2013-08-26T21:37:13.449Z,1377553033.449 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2013-08-26T21:37:13.449Z,1377553033.449 [Navigation](DEBUG): Initializing Navigation.
2013-08-26T21:37:13.449Z,1377553033.450 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2013-08-26T21:37:13.451Z,1377553033.451 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2013-08-26T21:37:13.452Z,1377553033.452 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2013-08-26T21:37:13.452Z,1377553033.453 [LoopControl](DEBUG): Initialize LoopControlComponent.
2013-08-26T21:37:13.466Z,1377553033.466 [DVL_micro](INFO): Thread ID is 961
2013-08-26T21:37:13.475Z,1377553033.475 [DVL_micro](INFO): Initializing
2013-08-26T21:37:13.475Z,1377553033.475 [DVL_micro](INFO): start:Powering up
2013-08-26T21:37:13.476Z,1377553033.476 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-08-26T21:37:13.477Z,1377553033.477 [DVL_micro](INFO): Cycling power to configure device.
2013-08-26T21:37:13.491Z,1377553033.491 [NavChartDb](INFO): Thread ID is 962
2013-08-26T21:37:13.493Z,1377553033.493 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2013-08-26T21:37:13.494Z,1377553033.494 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2013-08-26T21:37:13.494Z,1377553033.494 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2013-08-26T21:37:13.495Z,1377553033.495 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2013-08-26T21:37:13.495Z,1377553033.495 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2013-08-26T21:37:13.495Z,1377553033.495 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2013-08-26T21:37:13.495Z,1377553033.495 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2013-08-26T21:37:13.495Z,1377553033.496 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2013-08-26T21:37:13.496Z,1377553033.496 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2013-08-26T21:37:14.954Z,1377553034.954 [Batt_Ocean_Server](ERROR): Batt_Ocean_Server A initialization uart error: serial timeout
2013-08-26T21:37:14.954Z,1377553034.954 [Batt_Ocean_Server](ERROR): Ocean Server Batteries failed to initialize. Re-initializing
2013-08-26T21:37:14.954Z,1377553034.954 [Batt_Ocean_Server] Communications Fault, FailCount= 1
2013-08-26T21:37:14.954Z,1377553034.954 [Batt_Ocean_Server](ERROR): Communications Fault
2013-08-26T21:37:14.961Z,1377553034.961 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2013-08-26T21:37:14.973Z,1377553034.973 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2013-08-26T21:37:14.995Z,1377553034.995 [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 RunIn="Progression"/>

    <Aggregate Id="StartupSatComms" >

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

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

    </Aggregate>

</Mission>


2013-08-26T21:37:14.996Z,1377553034.996 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2013-08-26T21:37:15.074Z,1377553035.074 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2013-08-26T21:37:15.076Z,1377553035.076 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2013-08-26T21:37:15.088Z,1377553035.088 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-08-26T21:37:15.104Z,1377553035.104 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2013-08-26T21:37:15.118Z,1377553035.118 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-08-26T21:37:15.140Z,1377553035.140 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2013-08-26T21:37:15.165Z,1377553035.165 [Default:D.SetSpeed](DEBUG): Construct.
2013-08-26T21:37:15.172Z,1377553035.172 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2013-08-26T21:37:15.186Z,1377553035.186 [Default:F.Wait](DEBUG): Construct Wait.
2013-08-26T21:37:15.198Z,1377553035.198 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
xmlns:Control="Tethys/Control"
xmlns:Guidance="Tethys/Guidance" 
xmlns:Units="Tethys/Units"
xmlns:Universal="Tethys/Universal"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
Id="Default">

    <DefineArg Name="NeedGPS"><True/></DefineArg>

    <Aggregate Id="GPS" >

        <When>
            <Arg Name="NeedGPS"/>
        </When>

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Get GPS fix -->

        <ReadDatum Id="Read_GPS">
            <Universal:latitude_fix/>
        </ReadDatum>

        <Assign><Arg Name="NeedGPS"/><False/></Assign>

    </Aggregate>

    <Aggregate Id="Iridium" >

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Do data comms -->

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

    </Aggregate>

    <Aggregate Id="CallIridium" >

        <When>
            <Elapsed><Universal:platform_communications/></Elapsed>
            <Gt><Units:minute/><Value>5.0</Value></Gt>
            <And><Universal:platform_conversation/><Eq><True/></Eq></And>
            <Or><Elapsed><Universal:platform_communications/></Elapsed><Gt><Units:hour/><Value>1.0</Value></Gt></Or>
        </When>

        <Assign><Arg Name="NeedGPS"/><True/></Assign>

        <Call RefId="Iridium"/>

    </Aggregate>

<!-- Wait forever at the surface-->

<!-- Run at low speed -->

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

    <Guidance:GoToSurface RunIn="Parallel"/>

    <Guidance:Wait RunIn="Sequence"></Guidance:Wait>

</Mission>


2013-08-26T21:37:15.202Z,1377553035.202 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,NAL9602,Onboard,Radio_Freewave,DAT,Depth_Keller,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,
2013-08-26T21:37:15.272Z,1377553035.272 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-08-26T21:37:15.286Z,1377553035.286 [Depth_Keller](ERROR): Pressure reading out of range: 1831.078247 decibar
2013-08-26T21:37:15.366Z,1377553035.366 [Radio_Freewave](INFO): Powering up
2013-08-26T21:37:15.371Z,1377553035.371 [DAT](INFO): Powering up
2013-08-26T21:37:15.371Z,1377553035.371 [DAT](DEBUG): Initializing DAT.
2013-08-26T21:37:15.558Z,1377553035.558 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-08-26T21:37:15.558Z,1377553035.558 [DVL_micro](INFO): Querying output modes
2013-08-26T21:37:15.558Z,1377553035.559 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-08-26T21:37:15.563Z,1377553035.563 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-08-26T21:37:15.570Z,1377553035.570 [DVL_micro](DEBUG): cmdResponse: 01
2013-08-26T21:37:15.570Z,1377553035.570 [DVL_micro](INFO): NQ1 output enabled
2013-08-26T21:37:15.570Z,1377553035.570 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-08-26T21:37:15.571Z,1377553035.571 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-08-26T21:37:15.581Z,1377553035.581 [ElevatorServo](DEBUG): Initializing EZServoServo.
2013-08-26T21:37:15.582Z,1377553035.582 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2013-08-26T21:37:15.587Z,1377553035.587 [DVL_micro](INFO): pause:Powering down
2013-08-26T21:37:15.602Z,1377553035.602 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2013-08-26T21:37:15.607Z,1377553035.607 [MassServo](DEBUG): Initializing EZServoServo.
2013-08-26T21:37:15.614Z,1377553035.614 [MassServo](DEBUG): Initializing MassServo.
2013-08-26T21:37:15.619Z,1377553035.619 [RudderServo](DEBUG): Initializing EZServoServo.
2013-08-26T21:37:15.650Z,1377553035.650 [RudderServo](DEBUG): Initializing RudderServo.
2013-08-26T21:37:15.655Z,1377553035.655 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-08-26T21:37:15.662Z,1377553035.662 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-08-26T21:37:15.700Z,1377553035.700 [CBIT](ERROR): Communications Fault in component: Batt_Ocean_Server
2013-08-26T21:37:15.700Z,1377553035.700 [CBIT](INFO): Clearing failed state for component Batt_Ocean_Server
2013-08-26T21:37:15.700Z,1377553035.700 [Batt_Ocean_Server] No Fault, FailCount= 1
2013-08-26T21:37:17.234Z,1377553037.234 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2013-08-26T21:37:18.448Z,1377553038.448 [NAL9602](INFO): Powering up NAL9602
2013-08-26T21:37:29.198Z,1377553049.198 [NAL9602](INFO): NAL9602 initialized
2013-08-26T21:37:29.263Z,1377553049.263 [SBIT](IMPORTANT): Beginning Startup BIT
2013-08-26T21:37:29.274Z,1377553049.274 [CBIT](IMPORTANT): Beginning GF scan
2013-08-26T21:37:35.561Z,1377553055.561 [DAT](INFO): Powering down
2013-08-26T21:37:56.086Z,1377553076.086 [CBIT](IMPORTANT): No ground fault detected
2013-08-26T21:38:02.399Z,1377553082.399 [NAL9602](IMPORTANT): GPS fix at: 1377553052.00
2013-08-26T21:38:05.034Z,1377553085.034 [CommandLine](IMPORTANT): got command ibit
2013-08-26T21:38:05.260Z,1377553085.260 [IBIT](FAULT): Cannot run IBIT while SBIT is in progress.
2013-08-26T21:38:05.614Z,1377553085.615 [IBIT](IMPORTANT): surfaceThreshold: 0.500000 m
2013-08-26T21:38:05.615Z,1377553085.615 [IBIT](IMPORTANT): buoyancyNeutral: 400.000000 cc
2013-08-26T21:38:05.615Z,1377553085.615 [IBIT](IMPORTANT): massDefault: 0.000000 cm
2013-08-26T21:38:05.615Z,1377553085.615 [IBIT](IMPORTANT): stopDepth: 112.000000 m
2013-08-26T21:38:05.616Z,1377553085.616 [IBIT](IMPORTANT): abortDepth: 130.000000 m
2013-08-26T21:38:05.616Z,1377553085.616 [IBIT](IMPORTANT): IBIT FAILED
2013-08-26T21:38:09.607Z,1377553089.607 [NAL9602](INFO): Powering down
2013-08-26T21:38:23.469Z,1377553103.469 [SBIT](IMPORTANT): SBIT PASSED
2013-08-26T21:38:23.778Z,1377553103.778 [MissionManager](IMPORTANT): Started mission Startup
2013-08-26T21:38:23.778Z,1377553103.778 [Startup] Running Loop=1
2013-08-26T21:38:23.779Z,1377553103.779 [Startup](INFO): Aggregate::initialize Startup
2013-08-26T21:38:23.779Z,1377553103.779 [Startup:A.GoToSurface] Running Loop=1
2013-08-26T21:38:23.779Z,1377553103.779 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-08-26T21:38:23.784Z,1377553103.784 [Startup:StartupSatComms] Running Loop=1
2013-08-26T21:38:23.784Z,1377553103.784 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2013-08-26T21:38:23.785Z,1377553103.785 [Startup:StartupSatComms:A] Running Loop=1
2013-08-26T21:38:24.217Z,1377553104.217 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-08-26T21:38:24.567Z,1377553104.567 [NAL9602](INFO): Powering up
2013-08-26T21:38:32.042Z,1377553112.042 [CommandLine](IMPORTANT): got command ibit
2013-08-26T21:38:32.186Z,1377553112.186 [IBIT](IMPORTANT): Beginning Initiated BIT
2013-08-26T21:38:32.186Z,1377553112.186 [IBIT](IMPORTANT): Beginning control surface checks.

2013-08-26T21:38:32.187Z,1377553112.187 [CBIT](IMPORTANT): Beginning GF scan
2013-08-26T21:38:32.973Z,1377553112.973 [Radio_Freewave](INFO): Powering down
2013-08-26T21:38:33.821Z,1377553113.821 [Radio_Freewave](INFO): Powering up
2013-08-26T21:38:35.418Z,1377553115.418 [NAL9602](INFO): NAL9602 initialized
2013-08-26T21:38:58.646Z,1377553138.646 [CBIT](IMPORTANT): No ground fault detected
2013-08-26T21:39:01.390Z,1377553141.390 [NAL9602](IMPORTANT): GPS fix at: 1377553111.00
2013-08-26T21:39:04.286Z,1377553144.286 [NAL9602](IMPORTANT): GPS fix at: 1377553114.00
2013-08-26T21:39:07.494Z,1377553147.494 [NAL9602](IMPORTANT): GPS fix at: 1377553117.00
2013-08-26T21:39:10.338Z,1377553150.338 [NAL9602](IMPORTANT): GPS fix at: 1377553120.00
2013-08-26T21:39:13.138Z,1377553153.138 [NAL9602](IMPORTANT): GPS fix at: 1377553123.00
2013-08-26T21:39:16.334Z,1377553156.334 [NAL9602](IMPORTANT): GPS fix at: 1377553126.00
2013-08-26T21:39:19.166Z,1377553159.166 [NAL9602](IMPORTANT): GPS fix at: 1377553129.00
2013-08-26T21:39:22.338Z,1377553162.338 [NAL9602](IMPORTANT): GPS fix at: 1377553132.00
2013-08-26T21:39:25.138Z,1377553165.138 [NAL9602](IMPORTANT): GPS fix at: 1377553135.00
2013-08-26T21:39:28.334Z,1377553168.334 [NAL9602](IMPORTANT): GPS fix at: 1377553138.00
2013-08-26T21:39:31.170Z,1377553171.170 [NAL9602](IMPORTANT): GPS fix at: 1377553141.00
2013-08-26T21:39:34.334Z,1377553174.334 [NAL9602](IMPORTANT): GPS fix at: 1377553144.00
2013-08-26T21:39:37.138Z,1377553177.138 [NAL9602](IMPORTANT): GPS fix at: 1377553147.00
2013-08-26T21:39:40.338Z,1377553180.338 [NAL9602](IMPORTANT): GPS fix at: 1377553150.00
2013-08-26T21:39:43.134Z,1377553183.134 [NAL9602](IMPORTANT): GPS fix at: 1377553153.00
2013-08-26T21:39:46.339Z,1377553186.339 [NAL9602](IMPORTANT): GPS fix at: 1377553156.00
2013-08-26T21:39:49.138Z,1377553189.138 [NAL9602](IMPORTANT): GPS fix at: 1377553159.00
2013-08-26T21:39:52.370Z,1377553192.370 [NAL9602](IMPORTANT): GPS fix at: 1377553162.00
2013-08-26T21:39:55.190Z,1377553195.190 [NAL9602](IMPORTANT): GPS fix at: 1377553165.00
2013-08-26T21:39:58.334Z,1377553198.334 [NAL9602](IMPORTANT): GPS fix at: 1377553168.00
2013-08-26T21:40:01.138Z,1377553201.138 [NAL9602](IMPORTANT): GPS fix at: 1377553171.00
2013-08-26T21:40:04.363Z,1377553204.363 [NAL9602](IMPORTANT): GPS fix at: 1377553174.00
2013-08-26T21:40:07.138Z,1377553207.138 [NAL9602](IMPORTANT): GPS fix at: 1377553177.00
2013-08-26T21:40:10.383Z,1377553210.383 [NAL9602](IMPORTANT): GPS fix at: 1377553180.00
2013-08-26T21:40:13.138Z,1377553213.138 [NAL9602](IMPORTANT): GPS fix at: 1377553183.00
2013-08-26T21:40:16.370Z,1377553216.370 [NAL9602](IMPORTANT): GPS fix at: 1377553186.00
2013-08-26T21:40:19.138Z,1377553219.138 [NAL9602](IMPORTANT): GPS fix at: 1377553189.00
2013-08-26T21:40:21.934Z,1377553221.934 [NAL9602](IMPORTANT): GPS fix at: 1377553191.00
2013-08-26T21:40:23.152Z,1377553223.152 [IBIT](FAULT): Error acquiring IBIT communications status. Timeout expired.
2013-08-26T21:40:23.589Z,1377553223.589 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 228.639999
Voltage: 16.075001
2013-08-26T21:40:23.589Z,1377553223.589 [IBIT](IMPORTANT): batteryCapacityThreshold: 5.000000 Ah
2013-08-26T21:40:23.589Z,1377553223.589 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.500000 V
2013-08-26T21:40:23.959Z,1377553223.959 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2013-08-26T21:40:23.960Z,1377553223.960 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2013-08-26T21:40:23.960Z,1377553223.960 [IBIT](IMPORTANT): Pressure:18.699255 PSI
2013-08-26T21:40:23.961Z,1377553223.961 [IBIT](IMPORTANT): Humidity:20.460424 %
2013-08-26T21:40:24.351Z,1377553224.351 [IBIT](IMPORTANT): surfaceThreshold: 0.500000 m
2013-08-26T21:40:24.352Z,1377553224.352 [IBIT](IMPORTANT): buoyancyNeutral: 400.000000 cc
2013-08-26T21:40:24.352Z,1377553224.352 [IBIT](IMPORTANT): massDefault: 0.000000 cm
2013-08-26T21:40:24.352Z,1377553224.352 [IBIT](IMPORTANT): stopDepth: 112.000000 m
2013-08-26T21:40:24.352Z,1377553224.352 [IBIT](IMPORTANT): abortDepth: 130.000000 m
2013-08-26T21:40:24.353Z,1377553224.353 [IBIT](IMPORTANT): IBIT FAILED
2013-08-26T21:40:24.761Z,1377553224.761 [Startup:StartupSatComms:A](INFO): Timed out from 2013-08-26T21:38:23.8Z
2013-08-26T21:40:24.761Z,1377553224.761 [Startup:StartupSatComms:A:A_Timeout] Running Loop=1
2013-08-26T21:40:24.762Z,1377553224.762 [Startup:StartupSatComms:A:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A:A_Timeout
2013-08-26T21:40:24.762Z,1377553224.762 [Startup:StartupSatComms:A:A_Timeout](INFO): Completed Startup:StartupSatComms:A:A_Timeout
2013-08-26T21:40:24.762Z,1377553224.762 [Startup:StartupSatComms:A] Stopped
2013-08-26T21:40:24.762Z,1377553224.762 [Startup:StartupSatComms:B] Running Loop=1
2013-08-26T21:40:25.139Z,1377553225.138 [NAL9602](IMPORTANT): GPS fix at: 1377553195.00
2013-08-26T21:40:25.154Z,1377553225.154 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-08-26T21:41:24.797Z,1377553284.797 [Startup:StartupSatComms:B](INFO): Timed out from 2013-08-26T21:40:24.8Z
2013-08-26T21:41:24.798Z,1377553284.797 [Startup:StartupSatComms:B:A_Timeout] Running Loop=1
2013-08-26T21:41:24.798Z,1377553284.798 [Startup:StartupSatComms:B:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:B:A_Timeout
2013-08-26T21:41:24.798Z,1377553284.798 [Startup:StartupSatComms:B:A_Timeout](INFO): Completed Startup:StartupSatComms:B:A_Timeout
2013-08-26T21:41:24.798Z,1377553284.798 [Startup:StartupSatComms:B] Stopped
2013-08-26T21:41:24.798Z,1377553284.798 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2013-08-26T21:41:24.798Z,1377553284.798 [Startup:StartupSatComms] Stopped
2013-08-26T21:41:24.798Z,1377553284.798 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2013-08-26T21:41:24.799Z,1377553284.799 [Startup](INFO): Completed Startup
2013-08-26T21:41:24.799Z,1377553284.799 [Startup] Stopped
2013-08-26T21:41:24.799Z,1377553284.799 [Startup](INFO): Aggregate::uninitialize Startup
2013-08-26T21:41:24.799Z,1377553284.799 [Startup:A.GoToSurface] Stopped
2013-08-26T21:41:24.799Z,1377553284.799 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-08-26T21:41:25.735Z,1377553285.735 [MissionManager](IMPORTANT): Started mission Default
2013-08-26T21:41:25.735Z,1377553285.735 [Default] Running Loop=1
2013-08-26T21:41:25.735Z,1377553285.735 [Default](INFO): Aggregate::initialize Default
2013-08-26T21:41:25.735Z,1377553285.735 [Default:D.SetSpeed] Running Loop=1
2013-08-26T21:41:25.735Z,1377553285.736 [Default:D.SetSpeed](DEBUG): Initialize.
2013-08-26T21:41:25.736Z,1377553285.736 [Default:E.GoToSurface] Running Loop=1
2013-08-26T21:41:25.736Z,1377553285.736 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-08-26T21:41:25.736Z,1377553285.736 [Default:Iridium] Running Loop=1
2013-08-26T21:41:25.736Z,1377553285.736 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2013-08-26T21:41:25.736Z,1377553285.736 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-08-26T21:41:25.736Z,1377553285.736 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2013-08-26T21:41:25.736Z,1377553285.736 [Default:Iridium:B.GoToSurface] Running Loop=1
2013-08-26T21:41:25.736Z,1377553285.736 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-08-26T21:41:25.737Z,1377553285.737 [Default:E.GoToSurface] Running Loop=1
2013-08-26T21:41:25.742Z,1377553285.742 [Default:D.SetSpeed] Running Loop=1
2013-08-26T21:41:25.748Z,1377553285.748 [Default:CallIridium] Running Loop=1
2013-08-26T21:41:25.748Z,1377553285.748 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2013-08-26T21:41:25.748Z,1377553285.748 [Default:CallIridium:A] Running Loop=1
2013-08-26T21:41:25.750Z,1377553285.750 [Default:CallIridium:A] Stopped
2013-08-26T21:41:25.750Z,1377553285.750 [Default:CallIridium:B] Running Loop=1
2013-08-26T21:41:25.750Z,1377553285.750 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2013-08-26T21:41:25.756Z,1377553285.756 [Default:Iridium:B.GoToSurface] Stopped
2013-08-26T21:41:25.756Z,1377553285.756 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-08-26T21:41:25.756Z,1377553285.756 [Default:Iridium:Read_Iridium] Running Loop=1
2013-08-26T21:41:25.756Z,1377553285.756 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-08-26T21:41:25.761Z,1377553285.761 [Default:GPS] Running Loop=1
2013-08-26T21:41:25.761Z,1377553285.761 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2013-08-26T21:41:25.761Z,1377553285.761 [Default:GPS:A.SetSpeed] Running Loop=1
2013-08-26T21:41:25.761Z,1377553285.761 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2013-08-26T21:41:25.761Z,1377553285.761 [Default:GPS:B.GoToSurface] Running Loop=1
2013-08-26T21:41:25.761Z,1377553285.761 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-08-26T21:41:25.767Z,1377553285.767 [Default:GPS:B.GoToSurface] Stopped
2013-08-26T21:41:25.767Z,1377553285.767 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-08-26T21:41:25.767Z,1377553285.767 [Default:GPS:Read_GPS] Running Loop=1
2013-08-26T21:41:25.767Z,1377553285.767 [Default:GPS:A.SetSpeed] Running Loop=1
2013-08-26T21:41:26.007Z,1377553286.007 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-08-26T21:41:26.010Z,1377553286.010 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-08-26T21:41:27.178Z,1377553287.178 [NAL9602](IMPORTANT): GPS fix at: 1377553257.00
2013-08-26T21:41:27.194Z,1377553287.194 [Default:GPS:Read_GPS] Stopped
2013-08-26T21:41:27.194Z,1377553287.194 [Default:GPS:D] Running Loop=1
2013-08-26T21:41:27.649Z,1377553287.649 [Default:GPS:D] Stopped
2013-08-26T21:41:27.649Z,1377553287.649 [Default:GPS](INFO): Completed Default:GPS
2013-08-26T21:41:27.649Z,1377553287.649 [Default:GPS] Stopped
2013-08-26T21:41:27.650Z,1377553287.649 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2013-08-26T21:41:27.650Z,1377553287.649 [Default:GPS:A.SetSpeed] Stopped
2013-08-26T21:41:27.650Z,1377553287.650 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2013-08-26T21:41:37.266Z,1377553297.266 [CommandLine](IMPORTANT): got command ibit
2013-08-26T21:41:37.382Z,1377553297.382 [IBIT](IMPORTANT): Beginning Initiated BIT
2013-08-26T21:41:37.382Z,1377553297.382 [IBIT](IMPORTANT): Beginning control surface checks.

2013-08-26T21:41:37.384Z,1377553297.384 [CBIT](IMPORTANT): Beginning GF scan
2013-08-26T21:41:38.187Z,1377553298.187 [Radio_Freewave](INFO): Powering down
2013-08-26T21:41:38.574Z,1377553298.574 [NAL9602](IMPORTANT): GPS fix at: 1377553268.00
2013-08-26T21:41:38.987Z,1377553298.987 [Radio_Freewave](INFO): Powering up
2013-08-26T21:41:42.562Z,1377553302.562 [NAL9602](IMPORTANT): GPS fix at: 1377553272.00
2013-08-26T21:41:46.582Z,1377553306.582 [NAL9602](IMPORTANT): GPS fix at: 1377553276.00
2013-08-26T21:41:50.914Z,1377553310.914 [NAL9602](IMPORTANT): GPS fix at: 1377553281.00
2013-08-26T21:41:55.634Z,1377553315.634 [NAL9602](IMPORTANT): GPS fix at: 1377553285.00
2013-08-26T21:42:00.046Z,1377553320.046 [NAL9602](IMPORTANT): GPS fix at: 1377553290.00
2013-08-26T21:42:03.978Z,1377553323.978 [CommandLine](IMPORTANT): got command ! cat ./Config/lrauv-daphne/vehicle.cfg
2013-08-26T21:42:04.048Z,1377553324.048 [CommandLine](IMPORTANT): ////////////////////////////////////////////////////////////////////
//
// PURPOSE: List of vehicle parameters, such as mass properties
//          specific to target named lrauv-daphne 
//
// DATE:    2009/09/16
//
// NOTES:   All values (except "strings") must be followed by
//          a unit abbreviation (or one of the unit-like
//          abbreviations: n/a, bool, enum, count). 
//
//
////////////////////////////////////////////////////////////////////

   Vehicle.name                  = "daphne"; 
   Vehicle.hostname              = "lrauv-daphne.shore.mbari.org";  
   Vehicle.id                    = 3 enum;
   Vehicle.kmlColor              = "ffD8BC80"; // 4 hex bytes indicating alpha, blue, green, and red
                                       // See http://www.fender.com/support/colorchart/index.php?show=blue&color=5
   Vehicle.argoProgram           = "9228"; 
   Vehicle.argoPlatform          = "102115";
   Vehicle.imei                  = "300234011783940" // Subject of e-mails sent to this vehicle
   
   NAL9602.sendDataToShore       = 1 bool;           // If true, radio data to shore over Iridium 

   DAT.loadControl       = "/dev/loadB6";
   DAT.uart       = "/dev/ttyB6"; // No xmodem needed to use LCB
   DAT.baud       = 9600 bps;

2013-08-26T21:42:04.170Z,1377553324.171 [CBIT](IMPORTANT): No ground fault detected
2013-08-26T21:42:04.494Z,1377553324.494 [NAL9602](IMPORTANT): GPS fix at: 1377553294.00
2013-08-26T21:42:08.850Z,1377553328.850 [NAL9602](IMPORTANT): GPS fix at: 1377553298.00
2013-08-26T21:42:13.138Z,1377553333.138 [CommandLine](IMPORTANT): got command show variable nal9602
2013-08-26T21:42:13.145Z,1377553333.145 [CommandLine](INFO): NAL9602.sendDataToShore (bool)
2013-08-26T21:42:13.145Z,1377553333.145 [CommandLine](INFO): NAL9602.loadControl (none)
2013-08-26T21:42:13.146Z,1377553333.146 [CommandLine](INFO): NAL9602.uart (none)
2013-08-26T21:42:13.146Z,1377553333.146 [CommandLine](INFO): NAL9602.baud (bit_per_second)
2013-08-26T21:42:13.152Z,1377553333.152 [CommandLine](INFO): NAL9602.gpsFailTimeout (minute)
2013-08-26T21:42:13.152Z,1377553333.152 [CommandLine](INFO): NAL9602.requestGGA (bool)
2013-08-26T21:42:13.152Z,1377553333.152 [CommandLine](INFO): NAL9602.loadAtStartup (bool)
2013-08-26T21:42:13.153Z,1377553333.153 [CommandLine](INFO): NAL9602.simulateHardware (bool)
2013-08-26T21:42:13.153Z,1377553333.153 [CommandLine](INFO): NAL9602.power (watt)
2013-08-26T21:42:13.154Z,1377553333.154 [CommandLine](INFO): NAL9602.power_platform_communications (watt)
2013-08-26T21:42:13.175Z,1377553333.174 [CommandLine](INFO): NAL9602.sigQuality (count)
2013-08-26T21:42:13.175Z,1377553333.175 [CommandLine](INFO): NAL9602.goodFix (bool)
2013-08-26T21:42:13.185Z,1377553333.185 [CommandLine](INFO): NAL9602.SNRSatellite_0 (count)
2013-08-26T21:42:13.185Z,1377553333.185 [CommandLine](INFO): NAL9602.SNRSatellite_1 (count)
2013-08-26T21:42:13.186Z,1377553333.186 [CommandLine](INFO): NAL9602.SNRSatellite_2 (count)
2013-08-26T21:42:13.186Z,1377553333.186 [CommandLine](INFO): NAL9602.SNRSatellite_3 (count)
2013-08-26T21:42:13.187Z,1377553333.187 [CommandLine](INFO): NAL9602.SNRSatellite_4 (count)
2013-08-26T21:42:13.187Z,1377553333.187 [CommandLine](INFO): NAL9602.SNRSatellite_5 (count)
2013-08-26T21:42:13.187Z,1377553333.187 [CommandLine](INFO): NAL9602.SNRSatellite_6 (count)
2013-08-26T21:42:13.188Z,1377553333.188 [CommandLine](INFO): NAL9602.SNRSatellite_7 (count)
2013-08-26T21:42:13.188Z,1377553333.188 [CommandLine](INFO): NAL9602.SNRSatellite_8 (count)
2013-08-26T21:42:13.188Z,1377553333.188 [CommandLine](INFO): NAL9602.SNRSatellite_9 (count)
2013-08-26T21:42:13.189Z,1377553333.189 [CommandLine](INFO): NAL9602.SNRSatellite_10 (count)
2013-08-26T21:42:13.189Z,1377553333.189 [CommandLine](INFO): NAL9602.SNRSatellite_11 (count)
2013-08-26T21:42:13.206Z,1377553333.206 [CommandLine](INFO): NAL9602.numSatellites (count)
2013-08-26T21:42:13.206Z,1377553333.206 [CommandLine](INFO): NAL9602.SOG (knot)
2013-08-26T21:42:13.207Z,1377553333.207 [CommandLine](INFO): NAL9602.COG (degree)
2013-08-26T21:42:13.207Z,1377553333.207 [CommandLine](INFO): NAL9602.time_fix (second)
2013-08-26T21:42:13.207Z,1377553333.207 [CommandLine](INFO): NAL9602.latitude_fix (degree)
2013-08-26T21:42:13.208Z,1377553333.208 [CommandLine](INFO): NAL9602.longitude_fix (degree)
2013-08-26T21:42:13.208Z,1377553333.208 [CommandLine](INFO): NAL9602.platform_communications (bool)
2013-08-26T21:42:13.215Z,1377553333.216 [CommandLine](INFO): NAL9602.durationOfLastRun (second)
2013-08-26T21:42:13.244Z,1377553333.244 [CommandLine](INFO): NAL9602.component_voltage (volt)
2013-08-26T21:42:13.244Z,1377553333.244 [CommandLine](INFO): NAL9602.component_avgVoltage (volt)
2013-08-26T21:42:13.245Z,1377553333.245 [CommandLine](INFO): NAL9602.component_current (milliampere)
2013-08-26T21:42:13.245Z,1377553333.245 [CommandLine](INFO): NAL9602.component_avgCurrent (milliampere)
2013-08-26T21:42:13.786Z,1377553333.786 [NAL9602](IMPORTANT): GPS fix at: 1377553303.00
2013-08-26T21:42:18.545Z,1377553338.545 [NAL9602](IMPORTANT): GPS fix at: 1377553308.00
2013-08-26T21:42:22.854Z,1377553342.854 [NAL9602](IMPORTANT): GPS fix at: 1377553313.00
2013-08-26T21:42:27.594Z,1377553347.594 [CommandLine](IMPORTANT): got command get NAL9602.loadAtStartup
2013-08-26T21:42:27.594Z,1377553347.594 [CommandLine](IMPORTANT): NAL9602.loadAtStartup 1 bool
2013-08-26T21:42:27.643Z,1377553347.643 [NAL9602](IMPORTANT): GPS fix at: 1377553317.00
2013-08-26T21:42:31.954Z,1377553351.954 [NAL9602](IMPORTANT): GPS fix at: 1377553322.00
2013-08-26T21:42:36.674Z,1377553356.674 [NAL9602](IMPORTANT): GPS fix at: 1377553326.00
2013-08-26T21:42:41.008Z,1377553361.008 [NAL9602](IMPORTANT): GPS fix at: 1377553331.00
2013-08-26T21:42:45.330Z,1377553365.330 [NAL9602](IMPORTANT): GPS fix at: 1377553335.00
2013-08-26T21:42:49.646Z,1377553369.646 [NAL9602](IMPORTANT): GPS fix at: 1377553339.00
2013-08-26T21:42:53.566Z,1377553373.566 [NAL9602](IMPORTANT): GPS fix at: 1377553343.00
2013-08-26T21:42:57.967Z,1377553377.967 [NAL9602](IMPORTANT): GPS fix at: 1377553348.00
2013-08-26T21:43:02.655Z,1377553382.655 [NAL9602](IMPORTANT): GPS fix at: 1377553352.00
2013-08-26T21:43:09.557Z,1377553389.557 [IBIT](IMPORTANT): Communications Status:
Fix Status: 1
Iridium Signal Strength: 1
Latitude: 36.801991 Longitude: -121.787193
2013-08-26T21:43:09.895Z,1377553389.895 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 228.639999
Voltage: 16.075249
2013-08-26T21:43:09.896Z,1377553389.896 [IBIT](IMPORTANT): batteryCapacityThreshold: 5.000000 Ah
2013-08-26T21:43:09.896Z,1377553389.896 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.500000 V
2013-08-26T21:43:10.176Z,1377553390.176 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2013-08-26T21:43:10.177Z,1377553390.177 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2013-08-26T21:43:10.177Z,1377553390.177 [IBIT](IMPORTANT): Pressure:19.230263 PSI
2013-08-26T21:43:10.178Z,1377553390.178 [IBIT](IMPORTANT): Humidity:20.318634 %
2013-08-26T21:43:12.596Z,1377553392.596 [IBIT](IMPORTANT): surfaceThreshold: 0.500000 m
2013-08-26T21:43:12.596Z,1377553392.596 [IBIT](IMPORTANT): buoyancyNeutral: 400.000000 cc
2013-08-26T21:43:12.596Z,1377553392.596 [IBIT](IMPORTANT): massDefault: 0.000000 cm
2013-08-26T21:43:12.597Z,1377553392.597 [IBIT](IMPORTANT): stopDepth: 112.000000 m
2013-08-26T21:43:12.597Z,1377553392.597 [IBIT](IMPORTANT): abortDepth: 130.000000 m
2013-08-26T21:43:12.597Z,1377553392.597 [IBIT](IMPORTANT): IBIT PASSED
2013-08-26T21:43:29.992Z,1377553409.992 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:43:29.993Z,1377553409.993 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:43:56.528Z,1377553436.528 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:43:56.529Z,1377553436.529 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:44:05.128Z,1377553445.128 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:44:05.128Z,1377553445.128 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:44:22.532Z,1377553462.532 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:44:22.533Z,1377553462.533 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:44:31.128Z,1377553471.128 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:44:31.128Z,1377553471.128 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:44:39.765Z,1377553479.765 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:44:39.766Z,1377553479.766 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:44:48.296Z,1377553488.296 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:44:48.296Z,1377553488.296 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:44:56.936Z,1377553496.936 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:44:56.936Z,1377553496.936 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:45:05.832Z,1377553505.832 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:45:05.833Z,1377553505.833 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:45:14.088Z,1377553514.088 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:45:14.088Z,1377553514.088 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:45:22.775Z,1377553522.775 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:45:22.775Z,1377553522.775 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:45:31.360Z,1377553531.360 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:45:31.360Z,1377553531.360 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:45:40.328Z,1377553540.328 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:45:40.328Z,1377553540.328 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:45:57.327Z,1377553557.327 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:45:57.328Z,1377553557.328 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:46:06.026Z,1377553566.026 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:46:06.026Z,1377553566.026 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:46:14.516Z,1377553574.516 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:46:14.516Z,1377553574.516 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:46:23.140Z,1377553583.140 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:46:23.140Z,1377553583.141 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:46:31.775Z,1377553591.776 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:46:31.776Z,1377553591.776 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:46:40.716Z,1377553600.716 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:46:40.716Z,1377553600.716 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:46:49.315Z,1377553609.315 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:46:49.315Z,1377553609.316 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:46:57.924Z,1377553617.924 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:46:57.924Z,1377553617.924 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:47:14.180Z,1377553634.180 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:47:14.181Z,1377553634.181 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:47:22.492Z,1377553642.492 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:47:22.493Z,1377553642.493 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:47:31.068Z,1377553651.068 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:47:31.068Z,1377553651.068 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:47:40.139Z,1377553660.139 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:47:40.140Z,1377553660.140 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:47:49.148Z,1377553669.148 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:47:49.148Z,1377553669.148 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:48:06.956Z,1377553686.956 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:48:06.956Z,1377553686.956 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:48:23.597Z,1377553703.597 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:48:23.598Z,1377553703.598 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:48:40.956Z,1377553720.956 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:48:40.956Z,1377553720.956 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:49:07.528Z,1377553747.528 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:49:07.529Z,1377553747.529 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:50:01.759Z,1377553801.759 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:50:01.759Z,1377553801.759 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:50:19.964Z,1377553819.964 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:50:19.965Z,1377553819.965 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:50:45.765Z,1377553845.765 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:50:45.765Z,1377553845.765 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:51:06.323Z,1377553866.323 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:51:06.323Z,1377553866.323 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:51:14.864Z,1377553874.864 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:51:14.864Z,1377553874.865 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:51:23.432Z,1377553883.432 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:51:23.432Z,1377553883.432 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:51:34.674Z,1377553894.674 [CommandLine](IMPORTANT): got command show variable signal
2013-08-26T21:51:42.330Z,1377553902.330 [CommandLine](IMPORTANT): got command show variable quality
2013-08-26T21:51:42.348Z,1377553902.348 [CommandLine](INFO): NAL9602.sigQuality (count)
2013-08-26T21:51:47.235Z,1377553907.235 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:51:47.235Z,1377553907.235 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:51:51.510Z,1377553911.510 [CommandLine](IMPORTANT): got command report mod NAL9602.sigQuality
2013-08-26T21:51:52.176Z,1377553912.176 [Reporter](INFO): NAL9602.sigQuality 0 count
2013-08-26T21:52:29.836Z,1377553949.836 [Reporter](INFO): NAL9602.sigQuality 1 count
2013-08-26T21:52:41.468Z,1377553961.468 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:52:41.469Z,1377553961.469 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:52:46.442Z,1377553966.443 [Reporter](INFO): NAL9602.sigQuality 3 count
2013-08-26T21:52:50.881Z,1377553970.881 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:52:50.881Z,1377553970.881 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:52:55.848Z,1377553975.848 [Reporter](INFO): NAL9602.sigQuality 0 count
2013-08-26T21:52:59.027Z,1377553979.027 [Reporter](INFO): NAL9602.sigQuality 3 count
2013-08-26T21:53:07.480Z,1377553987.480 [NAL9602](INFO): SBD MO Status=2, MOMSN=14303, MT Status=2, MTMSN=0
2013-08-26T21:53:07.480Z,1377553987.480 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:53:10.118Z,1377553990.118 [CommandLine](IMPORTANT): got command report clear
2013-08-26T21:53:35.715Z,1377554015.715 [NAL9602](INFO): SBD MO Status=1, MOMSN=14303, MT Status=0, MTMSN=0
2013-08-26T21:53:35.766Z,1377554015.766 [NAL9602](INFO): Sent 296 bytes from file Logs/20130826T211429/Courier0000.lzma
2013-08-26T21:53:35.766Z,1377554015.766 [NAL9602](INFO): Packets left to send: 0
2013-08-26T21:53:35.773Z,1377554015.773 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T211429/Courier0000.lzma.parts/0000.sbd
2013-08-26T21:53:44.775Z,1377554024.775 [NAL9602](INFO): SBD MO Status=2, MOMSN=14304, MT Status=2, MTMSN=0
2013-08-26T21:53:44.776Z,1377554024.776 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:54:01.011Z,1377554041.011 [NAL9602](INFO): SBD MO Status=2, MOMSN=14304, MT Status=2, MTMSN=0
2013-08-26T21:54:01.012Z,1377554041.011 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:54:17.588Z,1377554057.588 [NAL9602](INFO): SBD MO Status=2, MOMSN=14304, MT Status=2, MTMSN=0
2013-08-26T21:54:17.588Z,1377554057.588 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:54:35.792Z,1377554075.792 [NAL9602](INFO): SBD MO Status=2, MOMSN=14304, MT Status=2, MTMSN=0
2013-08-26T21:54:35.792Z,1377554075.792 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:54:52.424Z,1377554092.424 [NAL9602](INFO): SBD MO Status=2, MOMSN=14304, MT Status=2, MTMSN=0
2013-08-26T21:54:52.424Z,1377554092.424 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:55:01.045Z,1377554101.045 [NAL9602](INFO): SBD MO Status=2, MOMSN=14304, MT Status=2, MTMSN=0
2013-08-26T21:55:01.045Z,1377554101.045 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:55:09.615Z,1377554109.615 [NAL9602](INFO): SBD MO Status=2, MOMSN=14304, MT Status=2, MTMSN=0
2013-08-26T21:55:09.615Z,1377554109.615 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:55:20.665Z,1377554120.665 [NAL9602](INFO): SBD MO Status=1, MOMSN=14304, MT Status=0, MTMSN=0
2013-08-26T21:55:20.714Z,1377554120.714 [NAL9602](INFO): Sent 77 bytes from file Logs/20130826T211429/Courier0004.lzma
2013-08-26T21:55:20.714Z,1377554120.714 [NAL9602](INFO): Packets left to send: 0
2013-08-26T21:55:20.716Z,1377554120.716 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T211429/Courier0004.lzma.parts/0000.sbd
2013-08-26T21:55:26.864Z,1377554126.864 [NAL9602](INFO): SBD MO Status=2, MOMSN=14305, MT Status=2, MTMSN=0
2013-08-26T21:55:26.864Z,1377554126.865 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:55:35.516Z,1377554135.516 [NAL9602](INFO): SBD MO Status=2, MOMSN=14305, MT Status=2, MTMSN=0
2013-08-26T21:55:35.516Z,1377554135.516 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:55:47.768Z,1377554147.768 [NAL9602](INFO): SBD MO Status=1, MOMSN=14305, MT Status=0, MTMSN=0
2013-08-26T21:55:47.822Z,1377554147.822 [NAL9602](INFO): Sent 295 bytes from file Logs/20130826T213705/Courier0000.lzma
2013-08-26T21:55:47.822Z,1377554147.822 [NAL9602](INFO): Packets left to send: 0
2013-08-26T21:55:47.823Z,1377554147.823 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T213705/Courier0000.lzma.parts/0000.sbd
2013-08-26T21:55:52.828Z,1377554152.828 [NAL9602](INFO): SBD MO Status=2, MOMSN=14306, MT Status=2, MTMSN=0
2013-08-26T21:55:52.828Z,1377554152.829 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T21:56:05.028Z,1377554165.028 [NAL9602](INFO): SBD MO Status=1, MOMSN=14306, MT Status=0, MTMSN=0
2013-08-26T21:56:05.078Z,1377554165.078 [NAL9602](INFO): Sent 332 bytes from file Logs/20130826T211429/Express0001.lzma
2013-08-26T21:56:05.078Z,1377554165.078 [NAL9602](INFO): Packets left to send: 1
2013-08-26T21:56:05.080Z,1377554165.080 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T211429/Express0001.lzma.parts/0001.sbd
2013-08-26T21:56:16.537Z,1377554176.537 [NAL9602](INFO): SBD MO Status=1, MOMSN=14307, MT Status=0, MTMSN=0
2013-08-26T21:56:16.586Z,1377554176.586 [NAL9602](INFO): Sent 252 bytes from file Logs/20130826T211429/Express0001.lzma
2013-08-26T21:56:16.586Z,1377554176.586 [NAL9602](INFO): Packets left to send: 0
2013-08-26T21:56:16.587Z,1377554176.587 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T211429/Express0001.lzma.parts/0000.sbd
2013-08-26T21:56:29.947Z,1377554189.947 [NAL9602](INFO): SBD MO Status=1, MOMSN=14308, MT Status=0, MTMSN=0
2013-08-26T21:56:29.998Z,1377554189.998 [NAL9602](INFO): Sent 332 bytes from file Logs/20130826T211429/Express0005.lzma
2013-08-26T21:56:29.998Z,1377554189.998 [NAL9602](INFO): Packets left to send: 2
2013-08-26T21:56:30.001Z,1377554190.000 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T211429/Express0005.lzma.parts/0002.sbd
2013-08-26T21:56:39.416Z,1377554199.416 [NAL9602](INFO): SBD MO Status=1, MOMSN=14309, MT Status=0, MTMSN=0
2013-08-26T21:56:39.466Z,1377554199.466 [NAL9602](INFO): Sent 332 bytes from file Logs/20130826T211429/Express0005.lzma
2013-08-26T21:56:39.466Z,1377554199.466 [NAL9602](INFO): Packets left to send: 1
2013-08-26T21:56:39.467Z,1377554199.467 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T211429/Express0005.lzma.parts/0001.sbd
2013-08-26T21:56:50.128Z,1377554210.128 [NAL9602](INFO): SBD MO Status=1, MOMSN=14310, MT Status=0, MTMSN=0
2013-08-26T21:56:50.178Z,1377554210.178 [NAL9602](INFO): Sent 155 bytes from file Logs/20130826T211429/Express0005.lzma
2013-08-26T21:56:50.178Z,1377554210.178 [NAL9602](INFO): Packets left to send: 0
2013-08-26T21:56:50.179Z,1377554210.179 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T211429/Express0005.lzma.parts/0000.sbd
2013-08-26T21:57:00.359Z,1377554220.359 [NAL9602](INFO): SBD MO Status=1, MOMSN=14311, MT Status=0, MTMSN=0
2013-08-26T21:57:00.410Z,1377554220.410 [NAL9602](INFO): Sent 332 bytes from file Logs/20130826T213705/Express0001.lzma
2013-08-26T21:57:00.410Z,1377554220.410 [NAL9602](INFO): Packets left to send: 3
2013-08-26T21:57:00.412Z,1377554220.412 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T213705/Express0001.lzma.parts/0003.sbd
2013-08-26T21:57:13.416Z,1377554233.416 [NAL9602](INFO): SBD MO Status=1, MOMSN=14312, MT Status=0, MTMSN=0
2013-08-26T21:57:13.466Z,1377554233.466 [NAL9602](INFO): Sent 332 bytes from file Logs/20130826T213705/Express0001.lzma
2013-08-26T21:57:13.466Z,1377554233.466 [NAL9602](INFO): Packets left to send: 2
2013-08-26T21:57:13.467Z,1377554233.467 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T213705/Express0001.lzma.parts/0002.sbd
2013-08-26T21:57:22.092Z,1377554242.092 [NAL9602](INFO): SBD MO Status=1, MOMSN=14313, MT Status=0, MTMSN=0
2013-08-26T21:57:22.150Z,1377554242.150 [NAL9602](INFO): Sent 332 bytes from file Logs/20130826T213705/Express0001.lzma
2013-08-26T21:57:22.150Z,1377554242.150 [NAL9602](INFO): Packets left to send: 1
2013-08-26T21:57:22.151Z,1377554242.151 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T213705/Express0001.lzma.parts/0001.sbd
2013-08-26T21:57:29.528Z,1377554249.528 [NAL9602](INFO): SBD MO Status=1, MOMSN=14314, MT Status=0, MTMSN=0
2013-08-26T21:57:29.578Z,1377554249.578 [NAL9602](INFO): Sent 186 bytes from file Logs/20130826T213705/Express0001.lzma
2013-08-26T21:57:29.578Z,1377554249.578 [NAL9602](INFO): Packets left to send: 0
2013-08-26T21:57:29.579Z,1377554249.579 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T213705/Express0001.lzma.parts/0000.sbd
2013-08-26T21:57:38.353Z,1377554258.353 [NAL9602](INFO): SBD MO Status=0, MOMSN=14315, MT Status=0, MTMSN=0
2013-08-26T21:57:42.073Z,1377554262.073 [Default:Iridium:Read_Iridium] Stopped
2013-08-26T21:57:42.073Z,1377554262.073 [Default:Iridium](INFO): Completed Default:Iridium
2013-08-26T21:57:42.074Z,1377554262.074 [Default:Iridium] Stopped
2013-08-26T21:57:42.074Z,1377554262.074 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2013-08-26T21:57:42.074Z,1377554262.074 [Default:Iridium:A.SetSpeed] Stopped
2013-08-26T21:57:42.074Z,1377554262.074 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2013-08-26T21:57:42.074Z,1377554262.074 [Default:F.Wait] Running Loop=1
2013-08-26T21:57:42.074Z,1377554262.074 [Default:F.Wait](DEBUG): Initialize Wait Component.
2013-08-26T21:57:42.446Z,1377554262.446 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2013-08-26T21:57:42.446Z,1377554262.446 [Default:CallIridium:B] Stopped
2013-08-26T21:57:42.446Z,1377554262.446 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2013-08-26T21:57:42.446Z,1377554262.446 [Default:CallIridium](INFO): Completed Default:CallIridium
2013-08-26T21:57:42.446Z,1377554262.446 [Default:CallIridium] Stopped
2013-08-26T21:57:42.447Z,1377554262.447 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2013-08-26T21:57:52.431Z,1377554272.431 [NAL9602](INFO): Powering down
2013-08-26T22:02:42.453Z,1377554562.453 [Default:CallIridium] Running Loop=1
2013-08-26T22:02:42.453Z,1377554562.453 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2013-08-26T22:02:42.453Z,1377554562.453 [Default:CallIridium:A] Running Loop=1
2013-08-26T22:02:42.454Z,1377554562.454 [Default:CallIridium:A] Stopped
2013-08-26T22:02:42.454Z,1377554562.454 [Default:CallIridium:B] Running Loop=1
2013-08-26T22:02:42.454Z,1377554562.454 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2013-08-26T22:02:47.466Z,1377554567.466 [Default:Iridium] Running Loop=1
2013-08-26T22:02:47.466Z,1377554567.466 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2013-08-26T22:02:47.466Z,1377554567.466 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-08-26T22:02:47.466Z,1377554567.466 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2013-08-26T22:02:47.467Z,1377554567.467 [Default:Iridium:B.GoToSurface] Running Loop=1
2013-08-26T22:02:47.467Z,1377554567.467 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-08-26T22:02:47.467Z,1377554567.467 [Default:Iridium:B.GoToSurface] Stopped
2013-08-26T22:02:47.468Z,1377554567.467 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-08-26T22:02:47.468Z,1377554567.468 [Default:Iridium:Read_Iridium] Running Loop=1
2013-08-26T22:02:47.468Z,1377554567.468 [Default:GPS] Running Loop=1
2013-08-26T22:02:47.468Z,1377554567.468 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2013-08-26T22:02:47.468Z,1377554567.468 [Default:GPS:A.SetSpeed] Running Loop=1
2013-08-26T22:02:47.468Z,1377554567.468 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2013-08-26T22:02:47.468Z,1377554567.468 [Default:GPS:B.GoToSurface] Running Loop=1
2013-08-26T22:02:47.468Z,1377554567.468 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-08-26T22:02:47.469Z,1377554567.469 [Default:GPS:B.GoToSurface] Stopped
2013-08-26T22:02:47.470Z,1377554567.470 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-08-26T22:02:47.470Z,1377554567.470 [Default:GPS:Read_GPS] Running Loop=1
2013-08-26T22:02:48.099Z,1377554568.099 [NAL9602](INFO): Powering up
2013-08-26T22:02:52.945Z,1377554572.945 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#6 STATUS: 65535
2013-08-26T22:02:58.510Z,1377554578.510 [NAL9602](INFO): NAL9602 initialized
2013-08-26T22:03:29.764Z,1377554609.764 [NAL9602](INFO): SBD MO Status=2, MOMSN=14316, MT Status=2, MTMSN=0
2013-08-26T22:03:29.765Z,1377554609.765 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T22:03:30.961Z,1377554610.961 [NAL9602](IMPORTANT): GPS fix at: 1377554583.00
2013-08-26T22:03:30.977Z,1377554610.977 [Default:GPS:Read_GPS] Stopped
2013-08-26T22:03:30.977Z,1377554610.977 [Default:GPS:D] Running Loop=1
2013-08-26T22:03:31.399Z,1377554611.399 [Default:GPS:D] Stopped
2013-08-26T22:03:31.399Z,1377554611.399 [Default:GPS](INFO): Completed Default:GPS
2013-08-26T22:03:31.399Z,1377554611.399 [Default:GPS] Stopped
2013-08-26T22:03:31.399Z,1377554611.399 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2013-08-26T22:03:31.399Z,1377554611.399 [Default:GPS:A.SetSpeed] Stopped
2013-08-26T22:03:31.399Z,1377554611.399 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2013-08-26T22:03:45.548Z,1377554625.548 [NAL9602](INFO): SBD MO Status=1, MOMSN=14316, MT Status=0, MTMSN=0
2013-08-26T22:03:45.598Z,1377554625.598 [NAL9602](INFO): Sent 76 bytes from file Logs/20130826T213705/Courier0004.lzma
2013-08-26T22:03:45.598Z,1377554625.598 [NAL9602](INFO): Packets left to send: 0
2013-08-26T22:03:45.600Z,1377554625.599 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T213705/Courier0004.lzma.parts/0000.sbd
2013-08-26T22:03:57.423Z,1377554637.423 [NAL9602](INFO): SBD MO Status=1, MOMSN=14317, MT Status=0, MTMSN=0
2013-08-26T22:03:57.474Z,1377554637.474 [NAL9602](INFO): Sent 332 bytes from file Logs/20130826T213705/Express0005.lzma
2013-08-26T22:03:57.474Z,1377554637.474 [NAL9602](INFO): Packets left to send: 4
2013-08-26T22:03:57.475Z,1377554637.476 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T213705/Express0005.lzma.parts/0004.sbd
2013-08-26T22:05:05.695Z,1377554705.695 [NAL9602](ERROR): Verify xmit timeout failure.
2013-08-26T22:05:06.521Z,1377554706.521 [NAL9602](ERROR): Fill buffer uart error: serial timeout
2013-08-26T22:05:06.522Z,1377554706.522 [NAL9602](ERROR): Failed to receive READY. Modem reported: 
2013-08-26T22:05:37.866Z,1377554737.866 [NAL9602](ERROR): Queried for signal strength and failed to receive response. serial timeout
2013-08-26T22:06:02.052Z,1377554762.052 [NAL9602](INFO): SBD MO Status=1, MOMSN=14319, MT Status=0, MTMSN=0
2013-08-26T22:06:02.110Z,1377554762.110 [NAL9602](INFO): Sent 332 bytes from file Logs/20130826T213705/Express0005.lzma
2013-08-26T22:06:02.110Z,1377554762.110 [NAL9602](INFO): Packets left to send: 3
2013-08-26T22:06:02.111Z,1377554762.111 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T213705/Express0005.lzma.parts/0003.sbd
2013-08-26T22:06:10.724Z,1377554770.724 [NAL9602](INFO): SBD MO Status=1, MOMSN=14320, MT Status=0, MTMSN=0
2013-08-26T22:06:10.774Z,1377554770.774 [NAL9602](INFO): Sent 332 bytes from file Logs/20130826T213705/Express0005.lzma
2013-08-26T22:06:10.774Z,1377554770.774 [NAL9602](INFO): Packets left to send: 2
2013-08-26T22:06:10.775Z,1377554770.775 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T213705/Express0005.lzma.parts/0002.sbd
2013-08-26T22:06:22.224Z,1377554782.224 [NAL9602](INFO): SBD MO Status=1, MOMSN=14321, MT Status=0, MTMSN=0
2013-08-26T22:06:22.274Z,1377554782.274 [NAL9602](INFO): Sent 332 bytes from file Logs/20130826T213705/Express0005.lzma
2013-08-26T22:06:22.274Z,1377554782.274 [NAL9602](INFO): Packets left to send: 1
2013-08-26T22:06:22.275Z,1377554782.275 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T213705/Express0005.lzma.parts/0001.sbd
2013-08-26T22:06:34.452Z,1377554794.452 [NAL9602](INFO): SBD MO Status=1, MOMSN=14322, MT Status=0, MTMSN=0
2013-08-26T22:06:34.510Z,1377554794.510 [NAL9602](INFO): Sent 196 bytes from file Logs/20130826T213705/Express0005.lzma
2013-08-26T22:06:34.510Z,1377554794.510 [NAL9602](INFO): Packets left to send: 0
2013-08-26T22:06:34.511Z,1377554794.511 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T213705/Express0005.lzma.parts/0000.sbd
2013-08-26T22:06:41.652Z,1377554801.652 [NAL9602](INFO): SBD MO Status=0, MOMSN=14323, MT Status=0, MTMSN=0
2013-08-26T22:06:45.199Z,1377554805.199 [Default:Iridium:Read_Iridium] Stopped
2013-08-26T22:06:45.199Z,1377554805.199 [Default:Iridium](INFO): Completed Default:Iridium
2013-08-26T22:06:45.199Z,1377554805.199 [Default:Iridium] Stopped
2013-08-26T22:06:45.199Z,1377554805.199 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2013-08-26T22:06:45.199Z,1377554805.199 [Default:Iridium:A.SetSpeed] Stopped
2013-08-26T22:06:45.199Z,1377554805.199 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2013-08-26T22:06:45.599Z,1377554805.599 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2013-08-26T22:06:45.599Z,1377554805.599 [Default:CallIridium:B] Stopped
2013-08-26T22:06:45.599Z,1377554805.599 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2013-08-26T22:06:45.599Z,1377554805.599 [Default:CallIridium](INFO): Completed Default:CallIridium
2013-08-26T22:06:45.600Z,1377554805.599 [Default:CallIridium] Stopped
2013-08-26T22:06:45.600Z,1377554805.600 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2013-08-26T22:06:55.596Z,1377554815.596 [NAL9602](INFO): Powering down
2013-08-26T22:11:25.628Z,1377555085.628 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2013-08-26T22:11:30.593Z,1377555090.593 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2013-08-26T22:11:35.666Z,1377555095.666 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2013-08-26T22:11:40.597Z,1377555100.597 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2013-08-26T22:11:45.621Z,1377555105.621 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2013-08-26T22:11:45.659Z,1377555105.659 [Default:CallIridium] Running Loop=1
2013-08-26T22:11:45.659Z,1377555105.659 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2013-08-26T22:11:45.659Z,1377555105.659 [Default:CallIridium:A] Running Loop=1
2013-08-26T22:11:45.660Z,1377555105.659 [Default:CallIridium:A] Stopped
2013-08-26T22:11:45.660Z,1377555105.659 [Default:CallIridium:B] Running Loop=1
2013-08-26T22:11:45.660Z,1377555105.660 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2013-08-26T22:11:50.589Z,1377555110.589 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2013-08-26T22:11:50.642Z,1377555110.642 [Default:Iridium] Running Loop=1
2013-08-26T22:11:50.642Z,1377555110.642 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2013-08-26T22:11:50.643Z,1377555110.643 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-08-26T22:11:50.643Z,1377555110.643 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2013-08-26T22:11:50.643Z,1377555110.643 [Default:Iridium:B.GoToSurface] Running Loop=1
2013-08-26T22:11:50.643Z,1377555110.643 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-08-26T22:11:50.644Z,1377555110.644 [Default:Iridium:B.GoToSurface] Stopped
2013-08-26T22:11:50.644Z,1377555110.644 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-08-26T22:11:50.644Z,1377555110.644 [Default:Iridium:Read_Iridium] Running Loop=1
2013-08-26T22:11:50.644Z,1377555110.644 [Default:GPS] Running Loop=1
2013-08-26T22:11:50.644Z,1377555110.644 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2013-08-26T22:11:50.644Z,1377555110.644 [Default:GPS:A.SetSpeed] Running Loop=1
2013-08-26T22:11:50.644Z,1377555110.644 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2013-08-26T22:11:50.644Z,1377555110.644 [Default:GPS:B.GoToSurface] Running Loop=1
2013-08-26T22:11:50.645Z,1377555110.645 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-08-26T22:11:50.646Z,1377555110.645 [Default:GPS:B.GoToSurface] Stopped
2013-08-26T22:11:50.646Z,1377555110.645 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-08-26T22:11:50.646Z,1377555110.646 [Default:GPS:Read_GPS] Running Loop=1
2013-08-26T22:11:51.247Z,1377555111.247 [NAL9602](INFO): Powering up
2013-08-26T22:11:52.135Z,1377555112.135 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2013-08-26T22:11:53.257Z,1377555113.257 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2013-08-26T22:11:54.853Z,1377555114.853 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2013-08-26T22:11:56.461Z,1377555116.461 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2013-08-26T22:11:58.057Z,1377555118.057 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2013-08-26T22:11:59.660Z,1377555119.661 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2013-08-26T22:12:01.260Z,1377555121.260 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2013-08-26T22:12:01.686Z,1377555121.686 [NAL9602](INFO): NAL9602 initialized
2013-08-26T22:12:02.527Z,1377555122.527 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2013-08-26T22:12:04.057Z,1377555124.057 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2013-08-26T22:12:05.652Z,1377555125.652 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2013-08-26T22:12:07.336Z,1377555127.336 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2013-08-26T22:12:19.864Z,1377555139.864 [NAL9602](INFO): SBD MO Status=1, MOMSN=14324, MT Status=0, MTMSN=0
2013-08-26T22:12:19.914Z,1377555139.914 [NAL9602](INFO): Sent 76 bytes from file Logs/20130826T213705/Courier0008.lzma
2013-08-26T22:12:19.914Z,1377555139.914 [NAL9602](INFO): Packets left to send: 0
2013-08-26T22:12:19.916Z,1377555139.916 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T213705/Courier0008.lzma.parts/0000.sbd
2013-08-26T22:12:30.121Z,1377555150.121 [NAL9602](INFO): SBD MO Status=1, MOMSN=14325, MT Status=0, MTMSN=0
2013-08-26T22:12:30.170Z,1377555150.170 [NAL9602](INFO): Sent 131 bytes from file Logs/20130826T213705/Express0009.lzma
2013-08-26T22:12:30.170Z,1377555150.170 [NAL9602](INFO): Packets left to send: 0
2013-08-26T22:12:30.172Z,1377555150.172 [NAL9602](INFO): Stored copy of sent data in Logs/20130826T213705/Express0009.lzma.parts/0000.sbd
2013-08-26T22:12:41.317Z,1377555161.317 [NAL9602](INFO): SBD MO Status=0, MOMSN=14326, MT Status=0, MTMSN=0
2013-08-26T22:12:44.913Z,1377555164.913 [Default:Iridium:Read_Iridium] Stopped
2013-08-26T22:12:44.913Z,1377555164.913 [Default:Iridium](INFO): Completed Default:Iridium
2013-08-26T22:12:44.913Z,1377555164.913 [Default:Iridium] Stopped
2013-08-26T22:12:44.914Z,1377555164.914 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2013-08-26T22:12:44.914Z,1377555164.914 [Default:Iridium:A.SetSpeed] Stopped
2013-08-26T22:12:44.914Z,1377555164.914 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2013-08-26T22:12:45.360Z,1377555165.360 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2013-08-26T22:12:45.360Z,1377555165.360 [Default:CallIridium:B] Stopped
2013-08-26T22:12:45.360Z,1377555165.360 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2013-08-26T22:12:45.360Z,1377555165.360 [Default:CallIridium](INFO): Completed Default:CallIridium
2013-08-26T22:12:45.360Z,1377555165.360 [Default:CallIridium] Stopped
2013-08-26T22:12:45.360Z,1377555165.360 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2013-08-26T22:13:01.166Z,1377555181.166 [NAL9602](IMPORTANT): GPS fix at: 1377555154.00
2013-08-26T22:13:01.182Z,1377555181.182 [Default:GPS:Read_GPS] Stopped
2013-08-26T22:13:01.182Z,1377555181.182 [Default:GPS:D] Running Loop=1
2013-08-26T22:13:01.599Z,1377555181.599 [Default:GPS:D] Stopped
2013-08-26T22:13:01.599Z,1377555181.599 [Default:GPS](INFO): Completed Default:GPS
2013-08-26T22:13:01.599Z,1377555181.599 [Default:GPS] Stopped
2013-08-26T22:13:01.599Z,1377555181.599 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2013-08-26T22:13:01.599Z,1377555181.599 [Default:GPS:A.SetSpeed] Stopped
2013-08-26T22:13:01.599Z,1377555181.599 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2013-08-26T22:13:22.152Z,1377555202.152 [NAL9602](INFO): Powering down
2013-08-26T22:17:42.178Z,1377555462.178 [Default:CallIridium] Running Loop=1
2013-08-26T22:17:42.178Z,1377555462.178 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2013-08-26T22:17:42.178Z,1377555462.178 [Default:CallIridium:A] Running Loop=1
2013-08-26T22:17:42.179Z,1377555462.179 [Default:CallIridium:A] Stopped
2013-08-26T22:17:42.179Z,1377555462.179 [Default:CallIridium:B] Running Loop=1
2013-08-26T22:17:42.179Z,1377555462.179 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2013-08-26T22:17:47.138Z,1377555467.138 [Default:Iridium] Running Loop=1
2013-08-26T22:17:47.138Z,1377555467.138 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2013-08-26T22:17:47.139Z,1377555467.138 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-08-26T22:17:47.139Z,1377555467.139 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2013-08-26T22:17:47.139Z,1377555467.139 [Default:Iridium:B.GoToSurface] Running Loop=1
2013-08-26T22:17:47.139Z,1377555467.139 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-08-26T22:17:47.140Z,1377555467.139 [Default:Iridium:B.GoToSurface] Stopped
2013-08-26T22:17:47.140Z,1377555467.140 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-08-26T22:17:47.140Z,1377555467.140 [Default:Iridium:Read_Iridium] Running Loop=1
2013-08-26T22:17:47.140Z,1377555467.140 [Default:GPS] Running Loop=1
2013-08-26T22:17:47.140Z,1377555467.140 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2013-08-26T22:17:47.140Z,1377555467.140 [Default:GPS:A.SetSpeed] Running Loop=1
2013-08-26T22:17:47.140Z,1377555467.140 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2013-08-26T22:17:47.140Z,1377555467.140 [Default:GPS:B.GoToSurface] Running Loop=1
2013-08-26T22:17:47.140Z,1377555467.141 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-08-26T22:17:47.141Z,1377555467.141 [Default:GPS:B.GoToSurface] Stopped
2013-08-26T22:17:47.141Z,1377555467.141 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-08-26T22:17:47.142Z,1377555467.142 [Default:GPS:Read_GPS] Running Loop=1
2013-08-26T22:17:47.758Z,1377555467.758 [NAL9602](INFO): Powering up
2013-08-26T22:17:58.194Z,1377555478.194 [NAL9602](INFO): NAL9602 initialized
2013-08-26T22:18:05.368Z,1377555485.368 [Radio_Freewave](INFO): Powering down
2013-08-26T22:18:06.218Z,1377555486.218 [Radio_Freewave](INFO): Powering up
2013-08-26T22:18:35.964Z,1377555515.964 [NAL9602](INFO): SBD MO Status=2, MOMSN=14327, MT Status=2, MTMSN=0
2013-08-26T22:18:35.965Z,1377555515.965 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-08-26T22:18:54.122Z,1377555534.122 [CommandLine](IMPORTANT): got command restart application
2013-08-26T22:18:55.237Z,1377555535.237 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2013-08-26T22:18:55.237Z,1377555535.237 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2013-08-26T22:18:55.277Z,1377555535.277 [ComponentRegistry](INFO): Shutting down DVL_micro ThreadHandler
2013-08-26T22:18:55.298Z,1377555535.298 [DVL_micro](INFO): uninitialize:Powering down
2013-08-26T22:18:55.317Z,1377555535.317 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2013-08-26T22:18:55.434Z,1377555535.434 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2013-08-26T22:18:55.438Z,1377555535.438 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2013-08-26T22:18:55.517Z,1377555535.517 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2013-08-26T22:18:55.519Z,1377555535.519 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2013-08-26T22:18:55.574Z,1377555535.574 [controlThread](DEBUG): Uninitializing ControlThread
2013-08-26T22:18:55.574Z,1377555535.574 [AHRS_sp3003D](INFO): Powering down
2013-08-26T22:18:55.663Z,1377555535.662 [NAL9602](INFO): Powering down
2013-08-26T22:18:55.664Z,1377555535.664 [DAT](INFO): Powering down
2013-08-26T22:18:55.665Z,1377555535.665 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-08-26T22:18:55.666Z,1377555535.666 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2013-08-26T22:18:55.667Z,1377555535.667 [Default] Stopped
2013-08-26T22:18:55.667Z,1377555535.667 [Default](INFO): Aggregate::uninitialize Default
2013-08-26T22:18:55.667Z,1377555535.667 [Default:GPS] Stopped
2013-08-26T22:18:55.667Z,1377555535.667 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2013-08-26T22:18:55.667Z,1377555535.667 [Default:GPS:A.SetSpeed] Stopped
2013-08-26T22:18:55.667Z,1377555535.667 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2013-08-26T22:18:55.667Z,1377555535.667 [Default:GPS:Read_GPS] Stopped
2013-08-26T22:18:55.667Z,1377555535.667 [Default:Iridium] Stopped
2013-08-26T22:18:55.667Z,1377555535.667 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2013-08-26T22:18:55.668Z,1377555535.668 [Default:Iridium:A.SetSpeed] Stopped
2013-08-26T22:18:55.668Z,1377555535.668 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2013-08-26T22:18:55.668Z,1377555535.668 [Default:Iridium:Read_Iridium] Stopped
2013-08-26T22:18:55.668Z,1377555535.668 [Default:CallIridium] Stopped
2013-08-26T22:18:55.668Z,1377555535.668 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2013-08-26T22:18:55.668Z,1377555535.668 [Default:CallIridium:B] Stopped
2013-08-26T22:18:55.668Z,1377555535.668 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2013-08-26T22:18:55.668Z,1377555535.668 [Default:D.SetSpeed] Stopped
2013-08-26T22:18:55.668Z,1377555535.668 [Default:D.SetSpeed](DEBUG): Uninitialize.
2013-08-26T22:18:55.668Z,1377555535.668 [Default:E.GoToSurface] Stopped
2013-08-26T22:18:55.668Z,1377555535.668 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-08-26T22:18:55.668Z,1377555535.668 [Default:F.Wait] Stopped
2013-08-26T22:18:55.668Z,1377555535.668 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2013-08-26T22:18:55.673Z,1377555535.673 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2013-08-26T22:18:55.673Z,1377555535.673 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2013-08-26T22:18:55.674Z,1377555535.674 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2013-08-26T22:18:55.674Z,1377555535.674 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2013-08-26T22:18:55.674Z,1377555535.674 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-08-26T22:18:55.674Z,1377555535.674 [BuoyancyServo](INFO): Powering down
2013-08-26T22:18:55.686Z,1377555535.686 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2013-08-26T22:18:55.686Z,1377555535.686 [ElevatorServo](INFO): Powering down
2013-08-26T22:18:55.687Z,1377555535.687 [MassServo](DEBUG): Uninitialize Mass Servo.
2013-08-26T22:18:55.687Z,1377555535.687 [MassServo](INFO): Powering down
2013-08-26T22:18:55.688Z,1377555535.688 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2013-08-26T22:18:55.688Z,1377555535.688 [RudderServo](INFO): Powering down
2013-08-26T22:18:55.688Z,1377555535.688 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2013-08-26T22:18:55.688Z,1377555535.688 [ThrusterServo](INFO): Powering down
2013-08-26T22:18:55.689Z,1377555535.690 [SBIT](DEBUG): Uninitialize SBIT Component.
2013-08-26T22:18:55.690Z,1377555535.690 [IBIT](DEBUG): Uninitialize IBIT Component.
2013-08-26T22:18:55.690Z,1377555535.690 [CBIT](DEBUG): Uninitialize CBIT Component.