2012-01-04T23:07:54.08980Z,1325718474.0898 [NAL9601](INFO): SBD MO Status=1, MOMSN=40239, MT Status=0, MTMSN=0
2012-01-04T23:07:54.27520Z,1325718474.2752 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T212427/shore0009.lzma
2012-01-04T23:07:54.27540Z,1325718474.2754 [NAL9601](INFO): Packets left to send: 1
2012-01-04T23:07:54.27640Z,1325718474.2764 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000033
2012-01-04T23:08:01.40970Z,1325718481.4097 [NAL9601](INFO): SBD MO Status=1, MOMSN=40240, MT Status=0, MTMSN=0
2012-01-04T23:08:01.56710Z,1325718481.5671 [NAL9601](INFO): Sent 66 bytes from file Logs/20120104T212427/shore0009.lzma
2012-01-04T23:08:01.56730Z,1325718481.5673 [NAL9601](INFO): Packets left to send: 0
2012-01-04T23:08:01.56840Z,1325718481.5684 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000034
2012-01-04T23:08:11.13080Z,1325718491.1308 [NAL9601](INFO): SBD MO Status=1, MOMSN=40241, MT Status=0, MTMSN=0
2012-01-04T23:08:11.34720Z,1325718491.3472 [NAL9601](INFO): Sent 223 bytes from file Logs/20120104T212427/shore0010.lzma
2012-01-04T23:08:11.34740Z,1325718491.3474 [NAL9601](INFO): Packets left to send: 0
2012-01-04T23:08:11.34850Z,1325718491.3485 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000035
2012-01-04T23:08:20.33250Z,1325718500.3325 [NAL9601](INFO): SBD MO Status=0, MOMSN=40242, MT Status=0, MTMSN=0
2012-01-04T23:08:37.55360Z,1325718517.5536 [NAL9601](INFO): SBD MO Status=1, MOMSN=40243, MT Status=0, MTMSN=0
2012-01-04T23:08:37.70740Z,1325718517.7074 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0000.lzma
2012-01-04T23:08:37.70760Z,1325718517.7076 [NAL9601](INFO): Packets left to send: 2
2012-01-04T23:08:37.70870Z,1325718517.7087 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000036
2012-01-04T23:08:48.46170Z,1325718528.4617 [NAL9601](INFO): SBD MO Status=1, MOMSN=40244, MT Status=0, MTMSN=0
2012-01-04T23:08:48.59120Z,1325718528.5912 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0000.lzma
2012-01-04T23:08:48.59140Z,1325718528.5914 [NAL9601](INFO): Packets left to send: 1
2012-01-04T23:08:48.59320Z,1325718528.5932 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000037
2012-01-04T23:08:54.54970Z,1325718534.5497 [NAL9601](INFO): SBD MO Status=1, MOMSN=40245, MT Status=0, MTMSN=0
2012-01-04T23:08:54.68320Z,1325718534.6832 [NAL9601](INFO): Sent 2 bytes from file Logs/20120104T230740/shore0000.lzma
2012-01-04T23:08:54.68340Z,1325718534.6834 [NAL9601](INFO): Packets left to send: 0
2012-01-04T23:08:54.75180Z,1325718534.7518 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000038
2012-01-04T23:09:02.94960Z,1325718542.9496 [NAL9601](IMPORTANT): SBD MO Status=0, MOMSN=40246, MT Status=1, MTMSN=3350
2012-01-04T23:09:03.68430Z,1325718543.6843 [NAL9601](INFO): Received command:run Maintenance/dat_on.xml
2012-01-04T23:09:03.72330Z,1325718543.7233 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/dat_on.xml
2012-01-04T23:09:03.72360Z,1325718543.7236 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/dat_on.xml
2012-01-04T23:09:03.75170Z,1325718543.7517 [MissionManager](INFO): DefineArg dat_on.MassDefault = 0.0015 n/a
2012-01-04T23:09:03.75330Z,1325718543.7533 [dat_on:A.Pitch](DEBUG): Construct.
2012-01-04T23:09:03.77390Z,1325718543.7739 [dat_on:TestDrive:B.Wait](DEBUG): Construct Wait.
2012-01-04T23:09:03.77670Z,1325718543.7767 [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="dat_on">

    <DefineArg Name="MassDefault"><CustomUri Uri="Config/Control.massDefault"/></DefineArg>

    <Timeout Duration="P15M"/>

    <Guidance:Pitch RunIn="Parallel">
        <Setting><Guidance:Pitch.massPosition/><Arg Name="MassDefault"/></Setting>
    </Guidance:Pitch>

    <Aggregate Id="TestDrive">

        <ReadData>
            <Universal:homing_sensor_communications/>
        </ReadData>

        <Guidance:Wait RunIn="Sequence">
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>2</Value></Setting>
        </Guidance:Wait>

    </Aggregate>

</Mission>


2012-01-04T23:09:03.77710Z,1325718543.7771 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/dat_on.xml
2012-01-04T23:09:03.84020Z,1325718543.8402 [Default] Stopped
2012-01-04T23:09:03.84040Z,1325718543.8404 [Default](INFO): Aggregate::uninitialize Default
2012-01-04T23:09:03.84050Z,1325718543.8405 [Default:GPS] Stopped
2012-01-04T23:09:03.84060Z,1325718543.8406 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T23:09:03.84070Z,1325718543.8407 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T23:09:03.84080Z,1325718543.8408 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:09:03.84090Z,1325718543.8409 [Default:GPS:Read_GPS] Stopped
2012-01-04T23:09:03.84090Z,1325718543.8409 [Default:Iridium] Stopped
2012-01-04T23:09:03.84110Z,1325718543.8411 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-04T23:09:03.84110Z,1325718543.8411 [Default:Iridium:A.SetSpeed] Stopped
2012-01-04T23:09:03.84120Z,1325718543.8412 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:09:03.84130Z,1325718543.8413 [Default:Iridium:Read_Iridium] Stopped
2012-01-04T23:09:03.84130Z,1325718543.8413 [Default:CallGPS] Stopped
2012-01-04T23:09:03.84150Z,1325718543.8415 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T23:09:03.84150Z,1325718543.8415 [Default:CallGPS:A] Stopped
2012-01-04T23:09:03.84170Z,1325718543.8417 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T23:09:03.84180Z,1325718543.8418 [Default:CallIridium] Stopped
2012-01-04T23:09:03.84190Z,1325718543.8419 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-04T23:09:03.84200Z,1325718543.842 [Default:CallIridium:A] Stopped
2012-01-04T23:09:03.84210Z,1325718543.8421 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-04T23:09:03.84220Z,1325718543.8422 [Default:E.SetSpeed] Stopped
2012-01-04T23:09:03.84230Z,1325718543.8423 [Default:E.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:09:03.84230Z,1325718543.8423 [Default:F.GoToSurface] Stopped
2012-01-04T23:09:03.84240Z,1325718543.8424 [Default:F.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:09:03.84250Z,1325718543.8425 [Default:G.Wait] Stopped
2012-01-04T23:09:03.84250Z,1325718543.8425 [Default:G.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T23:09:03.84280Z,1325718543.8428 [MissionManager](IMPORTANT): Started mission dat_on
2012-01-04T23:09:03.84290Z,1325718543.8429 [dat_on] Running Loop=1
2012-01-04T23:09:03.84300Z,1325718543.843 [dat_on](INFO): Aggregate::initialize dat_on
2012-01-04T23:09:03.84310Z,1325718543.8431 [dat_on:A.Pitch] Running Loop=1
2012-01-04T23:09:03.84310Z,1325718543.8431 [dat_on:A.Pitch](DEBUG): Initialize.
2012-01-04T23:09:03.84350Z,1325718543.8435 [dat_on:TestDrive] Running Loop=1
2012-01-04T23:09:03.84370Z,1325718543.8437 [dat_on:TestDrive](INFO): Aggregate::initialize dat_on:TestDrive
2012-01-04T23:09:03.84370Z,1325718543.8437 [dat_on:TestDrive:A] Running Loop=1
2012-01-04T23:09:03.84400Z,1325718543.844 [dat_on:TestDrive:B.Wait] Running Loop=1
2012-01-04T23:09:03.84400Z,1325718543.844 [dat_on:TestDrive:B.Wait](DEBUG): Initialize Wait Component.
2012-01-04T23:09:03.84880Z,1325718543.8488 [dat_on:TestDrive:A] Running Loop=1
2012-01-04T23:09:03.84950Z,1325718543.8495 [dat_on:TestDrive:A](DEBUG): Initialize ReadDataComponent to sense homing_sensor_communications
2012-01-04T23:09:03.85090Z,1325718543.8509 [dat_on:A.Pitch] Running Loop=1
2012-01-04T23:09:04.23750Z,1325718544.2375 [DAT](INFO): Powering up
2012-01-04T23:09:11.05760Z,1325718551.0576 [NAL9601](INFO): Powering down
2012-01-04T23:09:31.52270Z,1325718571.5227 [DAT](ERROR): No response from remote modem
2012-01-04T23:09:43.89870Z,1325718583.8987 [DAT](ERROR): No response from remote modem
2012-01-04T23:09:56.69870Z,1325718596.6987 [DAT](ERROR): No response from remote modem
2012-01-04T23:10:09.14270Z,1325718609.1427 [DAT](ERROR): No response from remote modem
2012-01-04T23:10:21.90670Z,1325718621.9067 [DAT](ERROR): No response from remote modem
2012-01-04T23:10:34.69870Z,1325718634.6987 [DAT](ERROR): No response from remote modem
2012-01-04T23:10:47.10520Z,1325718647.1052 [DAT](ERROR): No response from remote modem
2012-01-04T23:10:59.89870Z,1325718659.8987 [DAT](ERROR): No response from remote modem
2012-01-04T23:11:03.89560Z,1325718663.8956 [dat_on:TestDrive:B.Wait](INFO): Done Waiting.
2012-01-04T23:11:03.89580Z,1325718663.8958 [dat_on:TestDrive:B.Wait] Stopped
2012-01-04T23:11:03.89590Z,1325718663.8959 [dat_on:TestDrive:B.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T23:11:03.89620Z,1325718663.8962 [dat_on:TestDrive](INFO): Completed dat_on:TestDrive
2012-01-04T23:11:03.89630Z,1325718663.8963 [dat_on:TestDrive] Stopped
2012-01-04T23:11:03.89650Z,1325718663.8965 [dat_on:TestDrive](INFO): Aggregate::uninitialize dat_on:TestDrive
2012-01-04T23:11:03.89660Z,1325718663.8966 [dat_on:TestDrive:A] Stopped
2012-01-04T23:11:03.89700Z,1325718663.897 [dat_on](INFO): Completed dat_on
2012-01-04T23:11:03.89710Z,1325718663.8971 [dat_on] Stopped
2012-01-04T23:11:03.89730Z,1325718663.8973 [dat_on](INFO): Aggregate::uninitialize dat_on
2012-01-04T23:11:03.89730Z,1325718663.8973 [dat_on:A.Pitch] Stopped
2012-01-04T23:11:04.24370Z,1325718664.2437 [MissionManager](IMPORTANT): Started mission Default
2012-01-04T23:11:04.24390Z,1325718664.2439 [Default] Running Loop=1
2012-01-04T23:11:04.24400Z,1325718664.244 [Default](INFO): Aggregate::initialize Default
2012-01-04T23:11:04.24410Z,1325718664.2441 [Default:E.SetSpeed] Running Loop=1
2012-01-04T23:11:04.24420Z,1325718664.2442 [Default:E.SetSpeed](DEBUG): Initialize.
2012-01-04T23:11:04.24430Z,1325718664.2443 [Default:F.GoToSurface] Running Loop=1
2012-01-04T23:11:04.24440Z,1325718664.2444 [Default:F.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:11:04.24480Z,1325718664.2448 [Default:GPS] Running Loop=1
2012-01-04T23:11:04.24500Z,1325718664.245 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T23:11:04.24510Z,1325718664.2451 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T23:11:04.24510Z,1325718664.2451 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T23:11:04.24530Z,1325718664.2453 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T23:11:04.24540Z,1325718664.2454 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:11:04.24690Z,1325718664.2469 [Default:CallIridium] Running Loop=1
2012-01-04T23:11:04.24710Z,1325718664.2471 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-04T23:11:04.24720Z,1325718664.2472 [Default:CallIridium:A] Running Loop=1
2012-01-04T23:11:04.24740Z,1325718664.2474 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-04T23:11:04.24750Z,1325718664.2475 [Default:CallGPS] Running Loop=1
2012-01-04T23:11:04.24760Z,1325718664.2476 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T23:11:04.24780Z,1325718664.2478 [Default:CallGPS:A] Running Loop=1
2012-01-04T23:11:04.24790Z,1325718664.2479 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T23:11:04.24840Z,1325718664.2484 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T23:11:04.24840Z,1325718664.2484 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:11:04.24860Z,1325718664.2486 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T23:11:04.64190Z,1325718664.6419 [DAT](INFO): Powering down
2012-01-04T23:11:04.65030Z,1325718664.6503 [Default:Iridium] Running Loop=1
2012-01-04T23:11:04.65040Z,1325718664.6504 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-04T23:11:04.65050Z,1325718664.6505 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-04T23:11:04.65080Z,1325718664.6508 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-04T23:11:04.65110Z,1325718664.6511 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-04T23:11:04.65110Z,1325718664.6511 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:11:04.65180Z,1325718664.6518 [Default:Iridium:B.GoToSurface] Stopped
2012-01-04T23:11:04.65190Z,1325718664.6519 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:11:04.65200Z,1325718664.652 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-04T23:11:05.05370Z,1325718665.0537 [NAL9601](INFO): Powering up
2012-01-04T23:12:10.76330Z,1325718730.7633 [NAL9601](INFO): NAL9601 initialized
2012-01-04T23:12:11.83530Z,1325718731.8353 [NAL9601](IMPORTANT): GPS fix at: 1325718740
2012-01-04T23:12:11.87810Z,1325718731.8781 [Default:GPS:Read_GPS] Stopped
2012-01-04T23:12:11.87850Z,1325718731.8785 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T23:12:11.88280Z,1325718731.8828 [Default:GPS] Stopped
2012-01-04T23:12:11.88300Z,1325718731.883 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T23:12:11.88300Z,1325718731.883 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T23:12:11.88310Z,1325718731.8831 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:12:12.34050Z,1325718732.3405 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T23:12:12.34060Z,1325718732.3406 [Default:CallGPS:A] Stopped
2012-01-04T23:12:12.34070Z,1325718732.3407 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T23:12:12.34090Z,1325718732.3409 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T23:12:12.34100Z,1325718732.341 [Default:CallGPS] Stopped
2012-01-04T23:12:12.34110Z,1325718732.3411 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T23:12:12.65120Z,1325718732.6512 [Default:CallGPS] Running Loop=1
2012-01-04T23:12:12.65140Z,1325718732.6514 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T23:12:12.65150Z,1325718732.6515 [Default:CallGPS:A] Running Loop=1
2012-01-04T23:12:12.65170Z,1325718732.6517 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T23:12:13.04990Z,1325718733.0499 [Default:GPS] Running Loop=1
2012-01-04T23:12:13.05010Z,1325718733.0501 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T23:12:13.05020Z,1325718733.0502 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T23:12:13.05030Z,1325718733.0503 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T23:12:13.05050Z,1325718733.0505 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T23:12:13.05060Z,1325718733.0506 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:12:13.05120Z,1325718733.0512 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T23:12:13.05130Z,1325718733.0513 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:12:13.05150Z,1325718733.0515 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T23:12:30.42970Z,1325718750.4297 [NAL9601](INFO): SBD MO Status=0, MOMSN=40247, MT Status=0, MTMSN=0
2012-01-04T23:12:30.73580Z,1325718750.7358 [Default:Iridium:Read_Iridium] Stopped
2012-01-04T23:12:30.73620Z,1325718750.7362 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-04T23:12:30.73630Z,1325718750.7363 [Default:Iridium] Stopped
2012-01-04T23:12:30.73650Z,1325718750.7365 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-04T23:12:30.73660Z,1325718750.7366 [Default:Iridium:A.SetSpeed] Stopped
2012-01-04T23:12:30.73660Z,1325718750.7366 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:12:30.73680Z,1325718750.7368 [Default:G.Wait] Running Loop=1
2012-01-04T23:12:30.73680Z,1325718750.7368 [Default:G.Wait](DEBUG): Initialize Wait Component.
2012-01-04T23:12:30.86310Z,1325718750.8631 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-04T23:12:30.86320Z,1325718750.8632 [Default:CallIridium:A] Stopped
2012-01-04T23:12:30.86330Z,1325718750.8633 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-04T23:12:30.86350Z,1325718750.8635 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-04T23:12:30.86360Z,1325718750.8636 [Default:CallIridium] Stopped
2012-01-04T23:12:30.86370Z,1325718750.8637 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-04T23:12:31.65110Z,1325718751.6511 [NAL9601](IMPORTANT): GPS fix at: 1325718760
2012-01-04T23:12:31.70110Z,1325718751.7011 [Default:GPS:Read_GPS] Stopped
2012-01-04T23:12:31.70160Z,1325718751.7016 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T23:12:31.70160Z,1325718751.7016 [Default:GPS] Stopped
2012-01-04T23:12:31.70180Z,1325718751.7018 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T23:12:31.70190Z,1325718751.7019 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T23:12:31.70190Z,1325718751.7019 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:12:32.06110Z,1325718752.0611 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T23:12:32.06120Z,1325718752.0612 [Default:CallGPS:A] Stopped
2012-01-04T23:12:32.06130Z,1325718752.0613 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T23:12:32.06160Z,1325718752.0616 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T23:12:32.06160Z,1325718752.0616 [Default:CallGPS] Stopped
2012-01-04T23:12:32.06180Z,1325718752.0618 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T23:12:52.38040Z,1325718772.3804 [NAL9601](INFO): Powering down
2012-01-04T23:17:32.40950Z,1325719052.4095 [Default:CallIridium] Running Loop=1
2012-01-04T23:17:32.40970Z,1325719052.4097 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-04T23:17:32.40990Z,1325719052.4099 [Default:CallIridium:A] Running Loop=1
2012-01-04T23:17:32.41000Z,1325719052.41 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-04T23:17:32.41010Z,1325719052.4101 [Default:CallGPS] Running Loop=1
2012-01-04T23:17:32.41030Z,1325719052.4103 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T23:17:32.41040Z,1325719052.4104 [Default:CallGPS:A] Running Loop=1
2012-01-04T23:17:32.41060Z,1325719052.4106 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T23:17:37.28040Z,1325719057.2804 [Default:Iridium] Running Loop=1
2012-01-04T23:17:37.28060Z,1325719057.2806 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-04T23:17:37.28070Z,1325719057.2807 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-04T23:17:37.28070Z,1325719057.2807 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-04T23:17:37.28090Z,1325719057.2809 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-04T23:17:37.28100Z,1325719057.281 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:17:37.28170Z,1325719057.2817 [Default:Iridium:B.GoToSurface] Stopped
2012-01-04T23:17:37.28170Z,1325719057.2817 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:17:37.28190Z,1325719057.2819 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-04T23:17:37.28220Z,1325719057.2822 [Default:GPS] Running Loop=1
2012-01-04T23:17:37.28230Z,1325719057.2823 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T23:17:37.28240Z,1325719057.2824 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T23:17:37.28250Z,1325719057.2825 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T23:17:37.28280Z,1325719057.2828 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T23:17:37.28290Z,1325719057.2829 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:17:37.28360Z,1325719057.2836 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T23:17:37.28360Z,1325719057.2836 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:17:37.28380Z,1325719057.2838 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T23:17:37.84770Z,1325719057.8477 [NAL9601](INFO): Powering up
2012-01-04T23:18:43.55940Z,1325719123.5594 [NAL9601](INFO): NAL9601 initialized
2012-01-04T23:18:44.64990Z,1325719124.6499 [NAL9601](IMPORTANT): GPS fix at: 1325719134
2012-01-04T23:18:44.66440Z,1325719124.6644 [Default:GPS:Read_GPS] Stopped
2012-01-04T23:18:44.66470Z,1325719124.6647 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T23:18:44.66480Z,1325719124.6648 [Default:GPS] Stopped
2012-01-04T23:18:44.66500Z,1325719124.665 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T23:18:44.66500Z,1325719124.665 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T23:18:44.66510Z,1325719124.6651 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:18:45.06200Z,1325719125.062 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T23:18:45.06210Z,1325719125.0621 [Default:CallGPS:A] Stopped
2012-01-04T23:18:45.06220Z,1325719125.0622 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T23:18:45.06250Z,1325719125.0625 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T23:18:45.06250Z,1325719125.0625 [Default:CallGPS] Stopped
2012-01-04T23:18:45.06270Z,1325719125.0627 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T23:18:45.51340Z,1325719125.5134 [Default:CallGPS] Running Loop=1
2012-01-04T23:18:45.51360Z,1325719125.5136 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T23:18:45.51380Z,1325719125.5138 [Default:CallGPS:A] Running Loop=1
2012-01-04T23:18:45.51390Z,1325719125.5139 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T23:18:45.92320Z,1325719125.9232 [Default:GPS] Running Loop=1
2012-01-04T23:18:45.92340Z,1325719125.9234 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T23:18:45.92350Z,1325719125.9235 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T23:18:45.92360Z,1325719125.9236 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T23:18:45.92380Z,1325719125.9238 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T23:18:45.92390Z,1325719125.9239 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:18:45.92460Z,1325719125.9246 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T23:18:45.92470Z,1325719125.9247 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:18:45.92480Z,1325719125.9248 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T23:19:07.36560Z,1325719147.3656 [NAL9601](INFO): SBD MO Status=1, MOMSN=40248, MT Status=0, MTMSN=0
2012-01-04T23:19:07.51120Z,1325719147.5112 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0001.lzma
2012-01-04T23:19:07.51140Z,1325719147.5114 [NAL9601](INFO): Packets left to send: 4
2012-01-04T23:19:07.51330Z,1325719147.5133 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000039
2012-01-04T23:19:18.28580Z,1325719158.2858 [NAL9601](INFO): SBD MO Status=1, MOMSN=40249, MT Status=0, MTMSN=0
2012-01-04T23:19:18.49120Z,1325719158.4912 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0001.lzma
2012-01-04T23:19:18.49150Z,1325719158.4915 [NAL9601](INFO): Packets left to send: 3
2012-01-04T23:19:18.62780Z,1325719158.6278 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000040
2012-01-04T23:19:24.46570Z,1325719164.4657 [NAL9601](INFO): SBD MO Status=2, MOMSN=40250, MT Status=2, MTMSN=0
2012-01-04T23:19:24.46600Z,1325719164.466 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-01-04T23:19:25.66310Z,1325719165.6631 [NAL9601](IMPORTANT): GPS fix at: 1325719175
2012-01-04T23:19:25.71790Z,1325719165.7179 [Default:GPS:Read_GPS] Stopped
2012-01-04T23:19:25.71830Z,1325719165.7183 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T23:19:25.71840Z,1325719165.7184 [Default:GPS] Stopped
2012-01-04T23:19:25.72270Z,1325719165.7227 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T23:19:25.72280Z,1325719165.7228 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T23:19:25.72290Z,1325719165.7229 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:19:26.12000Z,1325719166.12 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T23:19:26.12000Z,1325719166.12 [Default:CallGPS:A] Stopped
2012-01-04T23:19:26.12020Z,1325719166.1202 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T23:19:26.12040Z,1325719166.1204 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T23:19:26.12050Z,1325719166.1205 [Default:CallGPS] Stopped
2012-01-04T23:19:26.12060Z,1325719166.1206 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T23:19:26.58960Z,1325719166.5896 [Default:CallGPS] Running Loop=1
2012-01-04T23:19:26.58980Z,1325719166.5898 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T23:19:26.59000Z,1325719166.59 [Default:CallGPS:A] Running Loop=1
2012-01-04T23:19:26.59010Z,1325719166.5901 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T23:19:26.87370Z,1325719166.8737 [Default:GPS] Running Loop=1
2012-01-04T23:19:26.87390Z,1325719166.8739 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T23:19:26.87400Z,1325719166.874 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T23:19:26.87410Z,1325719166.8741 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T23:19:26.87430Z,1325719166.8743 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T23:19:26.87430Z,1325719166.8743 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:19:26.87510Z,1325719166.8751 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T23:19:26.87520Z,1325719166.8752 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:19:26.87540Z,1325719166.8754 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T23:19:42.40330Z,1325719182.4033 [NAL9601](INFO): SBD MO Status=1, MOMSN=40250, MT Status=0, MTMSN=0
2012-01-04T23:19:42.55520Z,1325719182.5552 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0001.lzma
2012-01-04T23:19:42.55550Z,1325719182.5555 [NAL9601](INFO): Packets left to send: 2
2012-01-04T23:19:42.55650Z,1325719182.5565 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000041
2012-01-04T23:19:54.45760Z,1325719194.4576 [NAL9601](INFO): SBD MO Status=1, MOMSN=40251, MT Status=0, MTMSN=0
2012-01-04T23:19:54.63520Z,1325719194.6352 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0001.lzma
2012-01-04T23:19:54.63540Z,1325719194.6354 [NAL9601](INFO): Packets left to send: 1
2012-01-04T23:19:54.63650Z,1325719194.6365 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000042
2012-01-04T23:20:03.80170Z,1325719203.8017 [NAL9601](INFO): SBD MO Status=1, MOMSN=40252, MT Status=0, MTMSN=0
2012-01-04T23:20:03.92320Z,1325719203.9232 [NAL9601](INFO): Sent 145 bytes from file Logs/20120104T230740/shore0001.lzma
2012-01-04T23:20:03.92340Z,1325719203.9234 [NAL9601](INFO): Packets left to send: 0
2012-01-04T23:20:03.92450Z,1325719203.9245 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000043
2012-01-04T23:20:12.60480Z,1325719212.6048 [NAL9601](INFO): SBD MO Status=0, MOMSN=40253, MT Status=0, MTMSN=0
2012-01-04T23:20:12.86030Z,1325719212.8603 [Default:Iridium:Read_Iridium] Stopped
2012-01-04T23:20:12.86080Z,1325719212.8608 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-04T23:20:12.86090Z,1325719212.8609 [Default:Iridium] Stopped
2012-01-04T23:20:12.86100Z,1325719212.861 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-04T23:20:12.86110Z,1325719212.8611 [Default:Iridium:A.SetSpeed] Stopped
2012-01-04T23:20:12.86120Z,1325719212.8612 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:20:13.04520Z,1325719213.0452 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-04T23:20:13.04530Z,1325719213.0453 [Default:CallIridium:A] Stopped
2012-01-04T23:20:13.04540Z,1325719213.0454 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-04T23:20:13.04570Z,1325719213.0457 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-04T23:20:13.04570Z,1325719213.0457 [Default:CallIridium] Stopped
2012-01-04T23:20:13.04590Z,1325719213.0459 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-04T23:20:13.80700Z,1325719213.807 [NAL9601](IMPORTANT): GPS fix at: 1325719223
2012-01-04T23:20:13.82130Z,1325719213.8213 [Default:GPS:Read_GPS] Stopped
2012-01-04T23:20:13.82170Z,1325719213.8217 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T23:20:13.82180Z,1325719213.8218 [Default:GPS] Stopped
2012-01-04T23:20:13.82190Z,1325719213.8219 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T23:20:13.82200Z,1325719213.822 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T23:20:13.82210Z,1325719213.8221 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:20:14.23570Z,1325719214.2357 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T23:20:14.23580Z,1325719214.2358 [Default:CallGPS:A] Stopped
2012-01-04T23:20:14.23590Z,1325719214.2359 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T23:20:14.23610Z,1325719214.2361 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T23:20:14.23620Z,1325719214.2362 [Default:CallGPS] Stopped
2012-01-04T23:20:14.23640Z,1325719214.2364 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T23:20:34.38180Z,1325719234.3818 [NAL9601](INFO): Powering down
2012-01-04T23:25:14.36650Z,1325719514.3665 [Default:CallIridium] Running Loop=1
2012-01-04T23:25:14.36670Z,1325719514.3667 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-04T23:25:14.36690Z,1325719514.3669 [Default:CallIridium:A] Running Loop=1
2012-01-04T23:25:14.36700Z,1325719514.367 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-04T23:25:14.36720Z,1325719514.3672 [Default:CallGPS] Running Loop=1
2012-01-04T23:25:14.36730Z,1325719514.3673 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T23:25:14.36750Z,1325719514.3675 [Default:CallGPS:A] Running Loop=1
2012-01-04T23:25:14.36760Z,1325719514.3676 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T23:25:19.47680Z,1325719519.4768 [Default:Iridium] Running Loop=1
2012-01-04T23:25:19.47700Z,1325719519.477 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-04T23:25:19.47710Z,1325719519.4771 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-04T23:25:19.47720Z,1325719519.4772 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-04T23:25:19.47740Z,1325719519.4774 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-04T23:25:19.47740Z,1325719519.4774 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:25:19.47810Z,1325719519.4781 [Default:Iridium:B.GoToSurface] Stopped
2012-01-04T23:25:19.47820Z,1325719519.4782 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:25:19.47830Z,1325719519.4783 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-04T23:25:19.47880Z,1325719519.4788 [Default:GPS] Running Loop=1
2012-01-04T23:25:19.47890Z,1325719519.4789 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T23:25:19.47900Z,1325719519.479 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T23:25:19.47910Z,1325719519.4791 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T23:25:19.47930Z,1325719519.4793 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T23:25:19.47940Z,1325719519.4794 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:25:19.48000Z,1325719519.48 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T23:25:19.48010Z,1325719519.4801 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:25:19.48020Z,1325719519.4802 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T23:25:20.01280Z,1325719520.0128 [NAL9601](INFO): Powering up
2012-01-04T23:26:25.82320Z,1325719585.8232 [NAL9601](INFO): NAL9601 initialized
2012-01-04T23:26:44.04890Z,1325719604.0489 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=40254, MT Status=1, MTMSN=3351
2012-01-04T23:26:44.19520Z,1325719604.1952 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0002.lzma
2012-01-04T23:26:44.19540Z,1325719604.1954 [NAL9601](INFO): Packets left to send: 2
2012-01-04T23:26:44.19650Z,1325719604.1965 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000044
2012-01-04T23:26:44.75230Z,1325719604.7523 [NAL9601](INFO): Received command:load Transport/transit_3km.xml;set transit_3km.Wpt1Lat 36.8183 degree;set transit_3km.Wpt1Lon -121.828 degree;run 
2012-01-04T23:26:44.77280Z,1325719604.7728 [CommandLine](IMPORTANT): got command load ./Missions/Transport/transit_3km.xml
2012-01-04T23:26:44.77310Z,1325719604.7731 [MissionManager](INFO): Loading Mission: ./Missions/Transport/transit_3km.xml
2012-01-04T23:26:44.80810Z,1325719604.8081 [MissionManager](INFO): DefineArg transit_3km.ApproachDepth = 10 m
2012-01-04T23:26:44.81140Z,1325719604.8114 [MissionManager](INFO): DefineArg transit_3km.Wpt1Lat = 36.806966 arcdeg
2012-01-04T23:26:44.81440Z,1325719604.8144 [MissionManager](INFO): DefineArg transit_3km.Wpt1Lon = -121.824326 arcdeg
2012-01-04T23:26:44.81740Z,1325719604.8174 [MissionManager](INFO): DefineArg transit_3km.Speed = 1 m/s
2012-01-04T23:26:44.81910Z,1325719604.8191 [transit_3km:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-01-04T23:26:44.82650Z,1325719604.8265 [transit_3km:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-01-04T23:26:44.83390Z,1325719604.8339 [transit_3km:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2012-01-04T23:26:44.84270Z,1325719604.8427 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-01-04T23:26:44.84840Z,1325719604.8484 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Construct.
2012-01-04T23:26:44.86040Z,1325719604.8604 [transit_3km:WaypointOne:A.Pitch](DEBUG): Construct.
2012-01-04T23:26:44.86860Z,1325719604.8686 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Construct.
2012-01-04T23:26:44.87210Z,1325719604.8721 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Construct Waypoint.
2012-01-04T23:26:44.88190Z,1325719604.8819 [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="transit_3km">

<!-- To be used within 6km of waypoint. No science collection.  -->

    <DefineArg Name="ApproachDepth"><Units:meter /><Value>10.0</Value></DefineArg>

    <DefineArg Name="Wpt1Lat"><Units:degree /><Value>36.806966</Value></DefineArg>

    <DefineArg Name="Wpt1Lon"><Units:degree /><Value>-121.824326</Value></DefineArg>

    <DefineArg Name="Speed"><Units:meter_per_second/><Value>1</Value></DefineArg>

    <Timeout Duration="P130M" />

    <Guidance:AltitudeEnvelope RunIn="Parallel">
        <Setting><Guidance:AltitudeEnvelope.minAltitude /><Units:meter /><Value>7</Value></Setting>
    </Guidance:AltitudeEnvelope>

    <Guidance:DepthEnvelope RunIn="Parallel">
        <Setting><Guidance:DepthEnvelope.maxDepth /><Units:meter /><Value>20</Value></Setting>
    </Guidance:DepthEnvelope>

    <Guidance:OffshoreEnvelope RunIn="Parallel">
        <Setting><Guidance:OffshoreEnvelope.minOffshore/><Units:kilometer/><Value>1</Value></Setting>
    </Guidance:OffshoreEnvelope>

    <Aggregate Id="SURFACECOMMS">

        <Guidance:GoToSurface RunIn="Progression" />

        <Aggregate>

            <Preemptive><True /></Preemptive>

            <Guidance:SetSpeed RunIn="Parallel">
                <Setting><Guidance:SetSpeed.speed /><Units:meter_per_second /><Value>0</Value></Setting>
            </Guidance:SetSpeed>

            <ReadDatum><Universal:latitude_fix />
            </ReadDatum>

            <ReadDatum>
                <Timeout Duration="P30M">
                    <Assign Id="TouchComms"><Universal:platform_communications/></Assign>
                </Timeout><Universal:platform_communications />
            </ReadDatum>

            <ReadDatum><Universal:latitude_fix />
            </ReadDatum>

        </Aggregate>

    </Aggregate>

<!-- GPS Update.  Don't go too long w/o a GPS fix. -->

    <Aggregate Id="NeedComms">

        <When>
            <Elapsed><Universal:time_fix /></Elapsed>
            <Gt><Units:minute/><Value>35</Value></Gt>
        </When>

        <Call Id="NEEDCOMMS" RefId="SURFACECOMMS" />

    </Aggregate>

    <Aggregate Id="WaypointOne">

<!-- Go to Wpt1 -->

        <Guidance:Pitch RunIn="Parallel">
            <Setting><Guidance:Pitch.depth /><Arg Name="ApproachDepth" /></Setting>
        </Guidance:Pitch>

        <Guidance:SetSpeed RunIn="Parallel">
            <Setting><Guidance:SetSpeed.speed/><Arg Name="Speed"/></Setting>
        </Guidance:SetSpeed>

        <Guidance:Waypoint Id="WaypointW1" RunIn="Sequence">
            <Setting><Guidance:Waypoint.latitude /><Arg Name="Wpt1Lat" /></Setting>
            <Setting><Guidance:Waypoint.longitude /><Arg Name="Wpt1Lon" /></Setting>
        </Guidance:Waypoint>

        <Call Id="PHONEHOMEWPT1" RefId="SURFACECOMMS" />

    </Aggregate>

</Mission>


2012-01-04T23:26:44.88240Z,1325719604.8824 [CommandLine](IMPORTANT): Loaded ./Missions/Transport/transit_3km.xml
2012-01-04T23:26:44.97340Z,1325719604.9734 [CommandLine](IMPORTANT): got command set transit_3km.Wpt1Lat 36.81829834 degree
2012-01-04T23:26:45.09130Z,1325719605.0913 [CommandLine](IMPORTANT): got command set transit_3km.Wpt1Lon -121.8280029 degree
2012-01-04T23:26:45.09270Z,1325719605.0927 [CommandLine](IMPORTANT): got command run 
2012-01-04T23:26:45.09290Z,1325719605.0929 [CommandLine](IMPORTANT): Running 
2012-01-04T23:26:45.10850Z,1325719605.1085 [Default] Stopped
2012-01-04T23:26:45.10860Z,1325719605.1086 [Default](INFO): Aggregate::uninitialize Default
2012-01-04T23:26:45.10870Z,1325719605.1087 [Default:GPS] Stopped
2012-01-04T23:26:45.10890Z,1325719605.1089 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T23:26:45.10900Z,1325719605.109 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T23:26:45.10900Z,1325719605.109 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:26:45.10910Z,1325719605.1091 [Default:GPS:Read_GPS] Stopped
2012-01-04T23:26:45.10920Z,1325719605.1092 [Default:Iridium] Stopped
2012-01-04T23:26:45.10930Z,1325719605.1093 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-04T23:26:45.10940Z,1325719605.1094 [Default:Iridium:A.SetSpeed] Stopped
2012-01-04T23:26:45.10950Z,1325719605.1095 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:26:45.10950Z,1325719605.1095 [Default:Iridium:Read_Iridium] Stopped
2012-01-04T23:26:45.10960Z,1325719605.1096 [Default:CallGPS] Stopped
2012-01-04T23:26:45.10970Z,1325719605.1097 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T23:26:45.10980Z,1325719605.1098 [Default:CallGPS:A] Stopped
2012-01-04T23:26:45.10990Z,1325719605.1099 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T23:26:45.11000Z,1325719605.11 [Default:CallIridium] Stopped
2012-01-04T23:26:45.11010Z,1325719605.1101 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-04T23:26:45.11020Z,1325719605.1102 [Default:CallIridium:A] Stopped
2012-01-04T23:26:45.11030Z,1325719605.1103 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-04T23:26:45.11040Z,1325719605.1104 [Default:E.SetSpeed] Stopped
2012-01-04T23:26:45.11050Z,1325719605.1105 [Default:E.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:26:45.11070Z,1325719605.1107 [Default:F.GoToSurface] Stopped
2012-01-04T23:26:45.11080Z,1325719605.1108 [Default:F.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:26:45.11090Z,1325719605.1109 [Default:G.Wait] Stopped
2012-01-04T23:26:45.11090Z,1325719605.1109 [Default:G.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T23:26:45.11110Z,1325719605.1111 [MissionManager](IMPORTANT): Started mission transit_3km
2012-01-04T23:26:45.11120Z,1325719605.1112 [transit_3km] Running Loop=1
2012-01-04T23:26:45.11130Z,1325719605.1113 [transit_3km](INFO): Aggregate::initialize transit_3km
2012-01-04T23:26:45.11140Z,1325719605.1114 [transit_3km:A.AltitudeEnvelope] Running Loop=1
2012-01-04T23:26:45.11150Z,1325719605.1115 [transit_3km:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-01-04T23:26:45.11160Z,1325719605.1116 [transit_3km:B.DepthEnvelope] Running Loop=1
2012-01-04T23:26:45.11170Z,1325719605.1117 [transit_3km:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-01-04T23:26:45.11290Z,1325719605.1129 [transit_3km:C.OffshoreEnvelope] Running Loop=1
2012-01-04T23:26:45.11300Z,1325719605.113 [transit_3km:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2012-01-04T23:26:45.11330Z,1325719605.1133 [transit_3km:SURFACECOMMS] Running Loop=1
2012-01-04T23:26:45.11340Z,1325719605.1134 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2012-01-04T23:26:45.11350Z,1325719605.1135 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-01-04T23:26:45.11360Z,1325719605.1136 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:26:45.11920Z,1325719605.1192 [transit_3km:SURFACECOMMS:B] Running Loop=1
2012-01-04T23:26:45.11930Z,1325719605.1193 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:B
2012-01-04T23:26:45.11940Z,1325719605.1194 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-01-04T23:26:45.11950Z,1325719605.1195 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-01-04T23:26:45.11980Z,1325719605.1198 [transit_3km:SURFACECOMMS:B:B] Running Loop=1
2012-01-04T23:26:45.11990Z,1325719605.1199 [transit_3km:C.OffshoreEnvelope] Running Loop=1
2012-01-04T23:26:45.12470Z,1325719605.1247 [transit_3km:B.DepthEnvelope] Running Loop=1
2012-01-04T23:26:45.12960Z,1325719605.1296 [transit_3km:A.AltitudeEnvelope] Running Loop=1
2012-01-04T23:26:45.44190Z,1325719605.4419 [transit_3km:SURFACECOMMS:B:B](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-01-04T23:26:45.44750Z,1325719605.4475 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-01-04T23:26:47.41980Z,1325719607.4198 [NAL9601](IMPORTANT): GPS fix at: 1325719617
2012-01-04T23:26:47.43360Z,1325719607.4336 [transit_3km:SURFACECOMMS:B:B] Stopped
2012-01-04T23:26:47.43380Z,1325719607.4338 [transit_3km:SURFACECOMMS:B:C] Running Loop=1
2012-01-04T23:26:47.80250Z,1325719607.8025 [transit_3km:SURFACECOMMS:B:C](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-01-04T23:27:01.73770Z,1325719621.7377 [NAL9601](INFO): SBD MO Status=1, MOMSN=40255, MT Status=0, MTMSN=0
2012-01-04T23:27:01.85520Z,1325719621.8552 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0002.lzma
2012-01-04T23:27:01.85540Z,1325719621.8554 [NAL9601](INFO): Packets left to send: 1
2012-01-04T23:27:01.85650Z,1325719621.8565 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000045
2012-01-04T23:27:09.11960Z,1325719629.1196 [NAL9601](INFO): SBD MO Status=1, MOMSN=40256, MT Status=0, MTMSN=0
2012-01-04T23:27:09.24310Z,1325719629.2431 [NAL9601](INFO): Sent 105 bytes from file Logs/20120104T230740/shore0002.lzma
2012-01-04T23:27:09.24340Z,1325719629.2434 [NAL9601](INFO): Packets left to send: 0
2012-01-04T23:27:09.24770Z,1325719629.2477 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000046
2012-01-04T23:27:15.49500Z,1325719635.495 [NAL9601](INFO): SBD MO Status=0, MOMSN=40257, MT Status=0, MTMSN=0
2012-01-04T23:27:27.87030Z,1325719647.8703 [NAL9601](INFO): SBD MO Status=1, MOMSN=40258, MT Status=0, MTMSN=0
2012-01-04T23:27:28.01520Z,1325719648.0152 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0003.lzma
2012-01-04T23:27:28.01540Z,1325719648.0154 [NAL9601](INFO): Packets left to send: 1
2012-01-04T23:27:28.31790Z,1325719648.3179 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000047
2012-01-04T23:27:37.38210Z,1325719657.3821 [NAL9601](INFO): SBD MO Status=1, MOMSN=40259, MT Status=0, MTMSN=0
2012-01-04T23:27:37.50320Z,1325719657.5032 [NAL9601](INFO): Sent 220 bytes from file Logs/20120104T230740/shore0003.lzma
2012-01-04T23:27:37.50340Z,1325719657.5034 [NAL9601](INFO): Packets left to send: 0
2012-01-04T23:27:37.50460Z,1325719657.5046 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000048
2012-01-04T23:27:44.60480Z,1325719664.6048 [NAL9601](INFO): SBD MO Status=0, MOMSN=40260, MT Status=0, MTMSN=0
2012-01-04T23:27:44.80410Z,1325719664.8041 [transit_3km:SURFACECOMMS:B:C] Stopped
2012-01-04T23:27:44.80430Z,1325719664.8043 [transit_3km:SURFACECOMMS:B:D] Running Loop=1
2012-01-04T23:27:45.02570Z,1325719665.0257 [transit_3km:SURFACECOMMS:B:D](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-01-04T23:27:46.97530Z,1325719666.9753 [NAL9601](IMPORTANT): GPS fix at: 1325719677
2012-01-04T23:27:46.98890Z,1325719666.9889 [transit_3km:SURFACECOMMS:B:D] Stopped
2012-01-04T23:27:46.98930Z,1325719666.9893 [transit_3km:SURFACECOMMS:B](INFO): Completed transit_3km:SURFACECOMMS:B
2012-01-04T23:27:46.98940Z,1325719666.9894 [transit_3km:SURFACECOMMS:B] Stopped
2012-01-04T23:27:46.98950Z,1325719666.9895 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:B
2012-01-04T23:27:46.98960Z,1325719666.9896 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-01-04T23:27:46.98960Z,1325719666.9896 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:27:46.99020Z,1325719666.9902 [transit_3km:SURFACECOMMS](INFO): Completed transit_3km:SURFACECOMMS
2012-01-04T23:27:46.99030Z,1325719666.9903 [transit_3km:SURFACECOMMS] Stopped
2012-01-04T23:27:46.99040Z,1325719666.9904 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2012-01-04T23:27:46.99050Z,1325719666.9905 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2012-01-04T23:27:46.99050Z,1325719666.9905 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:27:46.99090Z,1325719666.9909 [transit_3km:WaypointOne] Running Loop=1
2012-01-04T23:27:46.99100Z,1325719666.991 [transit_3km:WaypointOne](INFO): Aggregate::initialize transit_3km:WaypointOne
2012-01-04T23:27:46.99110Z,1325719666.9911 [transit_3km:WaypointOne:A.Pitch] Running Loop=1
2012-01-04T23:27:46.99120Z,1325719666.9912 [transit_3km:WaypointOne:A.Pitch](DEBUG): Initialize.
2012-01-04T23:27:46.99140Z,1325719666.9914 [transit_3km:WaypointOne:B.SetSpeed] Running Loop=1
2012-01-04T23:27:46.99150Z,1325719666.9915 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Initialize.
2012-01-04T23:27:46.99180Z,1325719666.9918 [transit_3km:WaypointOne:WaypointW1.Waypoint] Running Loop=1
2012-01-04T23:27:46.99180Z,1325719666.9918 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Initialize WaypointComponent.
2012-01-04T23:27:47.53410Z,1325719667.5341 [transit_3km:WaypointOne:B.SetSpeed] Running Loop=1
2012-01-04T23:27:47.53840Z,1325719667.5384 [transit_3km:WaypointOne:A.Pitch] Running Loop=1
2012-01-04T23:27:48.70690Z,1325719668.7069 [ThrusterServo](ERROR): Thruster uart error: serial timeout
2012-01-04T23:27:48.70700Z,1325719668.707 [ThrusterServo] Communications Fault, FailCount= 1
2012-01-04T23:27:48.70710Z,1325719668.7071 [ThrusterServo](ERROR): Communications Fault
2012-01-04T23:27:48.70890Z,1325719668.7089 [CBIT](ERROR): Communications Fault in component: ThrusterServo
2012-01-04T23:27:49.50770Z,1325719669.5077 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2012-01-04T23:27:49.50820Z,1325719669.5082 [ThrusterServo](INFO): Powering down
2012-01-04T23:27:49.51090Z,1325719669.5109 [CBIT](INFO): Clearing failed state for component ThrusterServo
2012-01-04T23:27:49.51100Z,1325719669.511 [ThrusterServo] No Fault, FailCount= 1
2012-01-04T23:27:50.39560Z,1325719670.3956 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-01-04T23:27:50.52770Z,1325719670.5277 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-01-04T23:27:53.41240Z,1325719673.4124 [NAL9601](INFO): Powering down
2012-01-04T23:46:40.23050Z,1325720800.2305 [transit_3km:WaypointOne:WaypointW1.Waypoint](INFO): Reached Waypoint: 36.81829865,-121.8280078
2012-01-04T23:46:40.23080Z,1325720800.2308 [transit_3km:WaypointOne:WaypointW1.Waypoint] Stopped
2012-01-04T23:46:40.23090Z,1325720800.2309 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Uninitialize WaypointComponent.
2012-01-04T23:46:40.23100Z,1325720800.231 [transit_3km:WaypointOne:PHONEHOMEWPT1] Running Loop=1
2012-01-04T23:46:40.23120Z,1325720800.2312 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Aggregate::initialize transit_3km:WaypointOne:PHONEHOMEWPT1
2012-01-04T23:46:40.67170Z,1325720800.6717 [transit_3km:SURFACECOMMS] Running Loop=1
2012-01-04T23:46:40.67200Z,1325720800.672 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2012-01-04T23:46:40.67200Z,1325720800.672 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-01-04T23:46:40.67210Z,1325720800.6721 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:49:27.57850Z,1325720967.5785 [transit_3km:SURFACECOMMS:B] Running Loop=1
2012-01-04T23:49:27.57870Z,1325720967.5787 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:B
2012-01-04T23:49:27.57880Z,1325720967.5788 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-01-04T23:49:27.57890Z,1325720967.5789 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-01-04T23:49:27.57910Z,1325720967.5791 [transit_3km:SURFACECOMMS:B:B] Running Loop=1
2012-01-04T23:49:28.81950Z,1325720968.8195 [NAL9601](INFO): Powering up
2012-01-04T23:50:34.63120Z,1325721034.6312 [NAL9601](INFO): NAL9601 initialized
2012-01-04T23:50:35.64060Z,1325721035.6406 [NAL9601](IMPORTANT): GPS fix at: 1325721047
2012-01-04T23:50:35.65400Z,1325721035.654 [transit_3km:SURFACECOMMS:B:B] Stopped
2012-01-04T23:50:35.65420Z,1325721035.6542 [transit_3km:SURFACECOMMS:B:C] Running Loop=1
2012-01-04T23:50:57.18570Z,1325721057.1857 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=40261, MT Status=1, MTMSN=3352
2012-01-04T23:50:57.38320Z,1325721057.3832 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0004.lzma
2012-01-04T23:50:57.38340Z,1325721057.3834 [NAL9601](INFO): Packets left to send: 4
2012-01-04T23:50:57.38470Z,1325721057.3847 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000049
2012-01-04T23:50:58.00020Z,1325721058.0002 [NAL9601](INFO): Received command:run Maintenance/dat_on.xml
2012-01-04T23:50:58.05910Z,1325721058.0591 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/dat_on.xml
2012-01-04T23:50:58.05920Z,1325721058.0592 [transit_3km] Stopped
2012-01-04T23:50:58.05940Z,1325721058.0594 [transit_3km](INFO): Aggregate::uninitialize transit_3km
2012-01-04T23:50:58.05950Z,1325721058.0595 [transit_3km:A.AltitudeEnvelope] Stopped
2012-01-04T23:50:58.05960Z,1325721058.0596 [transit_3km:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-01-04T23:50:58.05960Z,1325721058.0596 [transit_3km:B.DepthEnvelope] Stopped
2012-01-04T23:50:58.05970Z,1325721058.0597 [transit_3km:B.DepthEnvelope](DEBUG): Uninitialize.
2012-01-04T23:50:58.05980Z,1325721058.0598 [transit_3km:C.OffshoreEnvelope] Stopped
2012-01-04T23:50:58.05980Z,1325721058.0598 [transit_3km:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2012-01-04T23:50:58.05990Z,1325721058.0599 [transit_3km:SURFACECOMMS] Stopped
2012-01-04T23:50:58.06000Z,1325721058.06 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2012-01-04T23:50:58.06010Z,1325721058.0601 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2012-01-04T23:50:58.06020Z,1325721058.0602 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:50:58.06020Z,1325721058.0602 [transit_3km:SURFACECOMMS:B] Stopped
2012-01-04T23:50:58.06040Z,1325721058.0604 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:B
2012-01-04T23:50:58.06040Z,1325721058.0604 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-01-04T23:50:58.06050Z,1325721058.0605 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:50:58.06060Z,1325721058.0606 [transit_3km:SURFACECOMMS:B:C] Stopped
2012-01-04T23:50:58.06070Z,1325721058.0607 [transit_3km:WaypointOne] Stopped
2012-01-04T23:50:58.06080Z,1325721058.0608 [transit_3km:WaypointOne](INFO): Aggregate::uninitialize transit_3km:WaypointOne
2012-01-04T23:50:58.06090Z,1325721058.0609 [transit_3km:WaypointOne:A.Pitch] Stopped
2012-01-04T23:50:58.06090Z,1325721058.0609 [transit_3km:WaypointOne:B.SetSpeed] Stopped
2012-01-04T23:50:58.06100Z,1325721058.061 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:50:58.06100Z,1325721058.061 [transit_3km:WaypointOne:PHONEHOMEWPT1] Stopped
2012-01-04T23:50:58.06120Z,1325721058.0612 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Aggregate::uninitialize transit_3km:WaypointOne:PHONEHOMEWPT1
2012-01-04T23:50:58.06720Z,1325721058.0672 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/dat_on.xml
2012-01-04T23:50:58.10840Z,1325721058.1084 [MissionManager](INFO): DefineArg dat_on.MassDefault = 0.0015 n/a
2012-01-04T23:50:58.10990Z,1325721058.1099 [dat_on:A.Pitch](DEBUG): Construct.
2012-01-04T23:50:58.12050Z,1325721058.1205 [dat_on:TestDrive:B.Wait](DEBUG): Construct Wait.
2012-01-04T23:50:58.12500Z,1325721058.125 [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="dat_on">

    <DefineArg Name="MassDefault"><CustomUri Uri="Config/Control.massDefault"/></DefineArg>

    <Timeout Duration="P15M"/>

    <Guidance:Pitch RunIn="Parallel">
        <Setting><Guidance:Pitch.massPosition/><Arg Name="MassDefault"/></Setting>
    </Guidance:Pitch>

    <Aggregate Id="TestDrive">

        <ReadData>
            <Universal:homing_sensor_communications/>
        </ReadData>

        <Guidance:Wait RunIn="Sequence">
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>2</Value></Setting>
        </Guidance:Wait>

    </Aggregate>

</Mission>


2012-01-04T23:50:58.12570Z,1325721058.1257 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/dat_on.xml
2012-01-04T23:50:58.16000Z,1325721058.16 [MissionManager](IMPORTANT): Started mission dat_on
2012-01-04T23:50:58.16010Z,1325721058.1601 [dat_on] Running Loop=1
2012-01-04T23:50:58.16020Z,1325721058.1602 [dat_on](INFO): Aggregate::initialize dat_on
2012-01-04T23:50:58.16030Z,1325721058.1603 [dat_on:A.Pitch] Running Loop=1
2012-01-04T23:50:58.16040Z,1325721058.1604 [dat_on:A.Pitch](DEBUG): Initialize.
2012-01-04T23:50:58.16060Z,1325721058.1606 [dat_on:TestDrive] Running Loop=1
2012-01-04T23:50:58.16080Z,1325721058.1608 [dat_on:TestDrive](INFO): Aggregate::initialize dat_on:TestDrive
2012-01-04T23:50:58.16090Z,1325721058.1609 [dat_on:TestDrive:A] Running Loop=1
2012-01-04T23:50:58.16110Z,1325721058.1611 [dat_on:TestDrive:B.Wait] Running Loop=1
2012-01-04T23:50:58.16120Z,1325721058.1612 [dat_on:TestDrive:B.Wait](DEBUG): Initialize Wait Component.
2012-01-04T23:50:58.16220Z,1325721058.1622 [dat_on:TestDrive:A] Running Loop=1
2012-01-04T23:50:58.16270Z,1325721058.1627 [dat_on:TestDrive:A](DEBUG): Initialize ReadDataComponent to sense homing_sensor_communications
2012-01-04T23:50:58.16350Z,1325721058.1635 [dat_on:A.Pitch] Running Loop=1
2012-01-04T23:50:58.53780Z,1325721058.5378 [DAT](INFO): Powering up
2012-01-04T23:51:03.31240Z,1325721063.3124 [NAL9601](INFO): Powering down
2012-01-04T23:51:25.75470Z,1325721085.7547 [DAT](ERROR): No response from remote modem
2012-01-04T23:51:38.55470Z,1325721098.5547 [DAT](ERROR): No response from remote modem
2012-01-04T23:51:50.97880Z,1325721110.9788 [DAT](ERROR): No response from remote modem
2012-01-04T23:52:03.35870Z,1325721123.3587 [DAT](ERROR): No response from remote modem
2012-01-04T23:52:16.16270Z,1325721136.1627 [DAT](ERROR): No response from remote modem
2012-01-04T23:52:29.00270Z,1325721149.0027 [DAT](ERROR): No response from remote modem
2012-01-04T23:52:41.75470Z,1325721161.7547 [DAT](ERROR): No response from remote modem
2012-01-04T23:52:54.18670Z,1325721174.1867 [DAT](ERROR): No response from remote modem
2012-01-04T23:52:58.18460Z,1325721178.1846 [dat_on:TestDrive:B.Wait](INFO): Done Waiting.
2012-01-04T23:52:58.18490Z,1325721178.1849 [dat_on:TestDrive:B.Wait] Stopped
2012-01-04T23:52:58.18500Z,1325721178.185 [dat_on:TestDrive:B.Wait](DEBUG): Uninitialize Wait Component.
2012-01-04T23:52:58.18530Z,1325721178.1853 [dat_on:TestDrive](INFO): Completed dat_on:TestDrive
2012-01-04T23:52:58.18540Z,1325721178.1854 [dat_on:TestDrive] Stopped
2012-01-04T23:52:58.18550Z,1325721178.1855 [dat_on:TestDrive](INFO): Aggregate::uninitialize dat_on:TestDrive
2012-01-04T23:52:58.18560Z,1325721178.1856 [dat_on:TestDrive:A] Stopped
2012-01-04T23:52:58.18600Z,1325721178.186 [dat_on](INFO): Completed dat_on
2012-01-04T23:52:58.18610Z,1325721178.1861 [dat_on] Stopped
2012-01-04T23:52:58.18630Z,1325721178.1863 [dat_on](INFO): Aggregate::uninitialize dat_on
2012-01-04T23:52:58.18630Z,1325721178.1863 [dat_on:A.Pitch] Stopped
2012-01-04T23:52:58.66410Z,1325721178.6641 [MissionManager](IMPORTANT): Started mission Default
2012-01-04T23:52:58.66430Z,1325721178.6643 [Default] Running Loop=1
2012-01-04T23:52:58.66440Z,1325721178.6644 [Default](INFO): Aggregate::initialize Default
2012-01-04T23:52:58.66450Z,1325721178.6645 [Default:E.SetSpeed] Running Loop=1
2012-01-04T23:52:58.66460Z,1325721178.6646 [Default:E.SetSpeed](DEBUG): Initialize.
2012-01-04T23:52:58.66470Z,1325721178.6647 [Default:F.GoToSurface] Running Loop=1
2012-01-04T23:52:58.66480Z,1325721178.6648 [Default:F.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:52:58.66520Z,1325721178.6652 [Default:GPS] Running Loop=1
2012-01-04T23:52:58.66530Z,1325721178.6653 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T23:52:58.66540Z,1325721178.6654 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T23:52:58.66550Z,1325721178.6655 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T23:52:58.66570Z,1325721178.6657 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T23:52:58.66580Z,1325721178.6658 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:52:58.66730Z,1325721178.6673 [Default:CallIridium] Running Loop=1
2012-01-04T23:52:58.66750Z,1325721178.6675 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-04T23:52:58.66760Z,1325721178.6676 [Default:CallIridium:A] Running Loop=1
2012-01-04T23:52:58.66770Z,1325721178.6677 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-04T23:52:58.66790Z,1325721178.6679 [Default:CallGPS] Running Loop=1
2012-01-04T23:52:58.66800Z,1325721178.668 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T23:52:58.66820Z,1325721178.6682 [Default:CallGPS:A] Running Loop=1
2012-01-04T23:52:58.66830Z,1325721178.6683 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T23:52:58.66870Z,1325721178.6687 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T23:52:58.66870Z,1325721178.6687 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:52:58.66890Z,1325721178.6689 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T23:52:58.90590Z,1325721178.9059 [DAT](INFO): Powering down
2012-01-04T23:52:58.93040Z,1325721178.9304 [Default:Iridium] Running Loop=1
2012-01-04T23:52:58.93050Z,1325721178.9305 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-04T23:52:58.93070Z,1325721178.9307 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-04T23:52:58.93080Z,1325721178.9308 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-04T23:52:58.93100Z,1325721178.931 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-04T23:52:58.93110Z,1325721178.9311 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:52:58.93170Z,1325721178.9317 [Default:Iridium:B.GoToSurface] Stopped
2012-01-04T23:52:58.93180Z,1325721178.9318 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:52:58.93190Z,1325721178.9319 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-04T23:52:59.30030Z,1325721179.3003 [NAL9601](INFO): Powering up
2012-01-04T23:54:05.01120Z,1325721245.0112 [NAL9601](INFO): NAL9601 initialized
2012-01-04T23:54:06.09520Z,1325721246.0952 [NAL9601](IMPORTANT): GPS fix at: 1325721258
2012-01-04T23:54:06.11180Z,1325721246.1118 [Default:GPS:Read_GPS] Stopped
2012-01-04T23:54:06.11220Z,1325721246.1122 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T23:54:06.11230Z,1325721246.1123 [Default:GPS] Stopped
2012-01-04T23:54:06.11240Z,1325721246.1124 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T23:54:06.11250Z,1325721246.1125 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T23:54:06.11260Z,1325721246.1126 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:54:06.62150Z,1325721246.6215 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T23:54:06.62160Z,1325721246.6216 [Default:CallGPS:A] Stopped
2012-01-04T23:54:06.62170Z,1325721246.6217 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T23:54:06.62190Z,1325721246.6219 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T23:54:06.62200Z,1325721246.622 [Default:CallGPS] Stopped
2012-01-04T23:54:06.62210Z,1325721246.6221 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T23:54:06.90500Z,1325721246.905 [Default:CallGPS] Running Loop=1
2012-01-04T23:54:06.90510Z,1325721246.9051 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-04T23:54:06.90530Z,1325721246.9053 [Default:CallGPS:A] Running Loop=1
2012-01-04T23:54:06.90540Z,1325721246.9054 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-04T23:54:07.30540Z,1325721247.3054 [Default:GPS] Running Loop=1
2012-01-04T23:54:07.30560Z,1325721247.3056 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-04T23:54:07.30570Z,1325721247.3057 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-04T23:54:07.30580Z,1325721247.3058 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-04T23:54:07.30600Z,1325721247.306 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-04T23:54:07.30600Z,1325721247.306 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-04T23:54:07.30670Z,1325721247.3067 [Default:GPS:B.GoToSurface] Stopped
2012-01-04T23:54:07.30680Z,1325721247.3068 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-04T23:54:07.30690Z,1325721247.3069 [Default:GPS:Read_GPS] Running Loop=1
2012-01-04T23:54:30.36480Z,1325721270.3648 [NAL9601](INFO): SBD MO Status=1, MOMSN=40262, MT Status=0, MTMSN=0
2012-01-04T23:54:30.55910Z,1325721270.5591 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0004.lzma
2012-01-04T23:54:30.55940Z,1325721270.5594 [NAL9601](INFO): Packets left to send: 3
2012-01-04T23:54:30.56070Z,1325721270.5607 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000050
2012-01-04T23:54:38.93360Z,1325721278.9336 [NAL9601](INFO): SBD MO Status=1, MOMSN=40263, MT Status=0, MTMSN=0
2012-01-04T23:54:39.14720Z,1325721279.1472 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0004.lzma
2012-01-04T23:54:39.14740Z,1325721279.1474 [NAL9601](INFO): Packets left to send: 2
2012-01-04T23:54:39.14850Z,1325721279.1485 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000051
2012-01-04T23:54:47.50480Z,1325721287.5048 [NAL9601](INFO): SBD MO Status=1, MOMSN=40264, MT Status=0, MTMSN=0
2012-01-04T23:54:47.63530Z,1325721287.6353 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0004.lzma
2012-01-04T23:54:47.63550Z,1325721287.6355 [NAL9601](INFO): Packets left to send: 1
2012-01-04T23:54:47.73270Z,1325721287.7327 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000052
2012-01-04T23:54:57.18970Z,1325721297.1897 [NAL9601](INFO): SBD MO Status=1, MOMSN=40265, MT Status=0, MTMSN=0
2012-01-04T23:54:57.31910Z,1325721297.3191 [NAL9601](INFO): Sent 88 bytes from file Logs/20120104T230740/shore0004.lzma
2012-01-04T23:54:57.31940Z,1325721297.3194 [NAL9601](INFO): Packets left to send: 0
2012-01-04T23:54:58.07300Z,1325721298.073 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000053
2012-01-04T23:55:05.41650Z,1325721305.4165 [NAL9601](INFO): SBD MO Status=0, MOMSN=40266, MT Status=0, MTMSN=0
2012-01-04T23:55:05.62020Z,1325721305.6202 [Default:Iridium:Read_Iridium] Stopped
2012-01-04T23:55:05.62070Z,1325721305.6207 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-04T23:55:05.62080Z,1325721305.6208 [Default:Iridium] Stopped
2012-01-04T23:55:05.62100Z,1325721305.621 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-04T23:55:05.62100Z,1325721305.621 [Default:Iridium:A.SetSpeed] Stopped
2012-01-04T23:55:05.62110Z,1325721305.6211 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:55:05.62130Z,1325721305.6213 [Default:G.Wait] Running Loop=1
2012-01-04T23:55:05.62140Z,1325721305.6214 [Default:G.Wait](DEBUG): Initialize Wait Component.
2012-01-04T23:55:05.78690Z,1325721305.7869 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-04T23:55:05.78700Z,1325721305.787 [Default:CallIridium:A] Stopped
2012-01-04T23:55:05.78710Z,1325721305.7871 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-04T23:55:05.78740Z,1325721305.7874 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-04T23:55:05.78740Z,1325721305.7874 [Default:CallIridium] Stopped
2012-01-04T23:55:05.78760Z,1325721305.7876 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-04T23:55:06.57900Z,1325721306.579 [NAL9601](IMPORTANT): GPS fix at: 1325721319
2012-01-04T23:55:06.59270Z,1325721306.5927 [Default:GPS:Read_GPS] Stopped
2012-01-04T23:55:06.59320Z,1325721306.5932 [Default:GPS](INFO): Completed Default:GPS
2012-01-04T23:55:06.59330Z,1325721306.5933 [Default:GPS] Stopped
2012-01-04T23:55:06.59350Z,1325721306.5935 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-04T23:55:06.59350Z,1325721306.5935 [Default:GPS:A.SetSpeed] Stopped
2012-01-04T23:55:06.59360Z,1325721306.5936 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-04T23:55:07.00750Z,1325721307.0075 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-04T23:55:07.00760Z,1325721307.0076 [Default:CallGPS:A] Stopped
2012-01-04T23:55:07.00770Z,1325721307.0077 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-04T23:55:07.00790Z,1325721307.0079 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-04T23:55:07.00800Z,1325721307.008 [Default:CallGPS] Stopped
2012-01-04T23:55:07.00810Z,1325721307.0081 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-04T23:55:27.15630Z,1325721327.1563 [NAL9601](INFO): Powering down
2012-01-05T00:00:07.15720Z,1325721607.1572 [Default:CallIridium] Running Loop=1
2012-01-05T00:00:07.15740Z,1325721607.1574 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-05T00:00:07.15750Z,1325721607.1575 [Default:CallIridium:A] Running Loop=1
2012-01-05T00:00:07.15770Z,1325721607.1577 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-05T00:00:07.15780Z,1325721607.1578 [Default:CallGPS] Running Loop=1
2012-01-05T00:00:07.15790Z,1325721607.1579 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-05T00:00:07.15810Z,1325721607.1581 [Default:CallGPS:A] Running Loop=1
2012-01-05T00:00:07.15820Z,1325721607.1582 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-05T00:00:12.33370Z,1325721612.3337 [Default:Iridium] Running Loop=1
2012-01-05T00:00:12.33390Z,1325721612.3339 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-05T00:00:12.33400Z,1325721612.334 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-05T00:00:12.33410Z,1325721612.3341 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:00:12.33430Z,1325721612.3343 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-05T00:00:12.33430Z,1325721612.3343 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:00:12.33510Z,1325721612.3351 [Default:Iridium:B.GoToSurface] Stopped
2012-01-05T00:00:12.33520Z,1325721612.3352 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:00:12.33530Z,1325721612.3353 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-05T00:00:12.33570Z,1325721612.3357 [Default:GPS] Running Loop=1
2012-01-05T00:00:12.33590Z,1325721612.3359 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-05T00:00:12.33590Z,1325721612.3359 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-05T00:00:12.33600Z,1325721612.336 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:00:12.33620Z,1325721612.3362 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-05T00:00:12.33630Z,1325721612.3363 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:00:12.33690Z,1325721612.3369 [Default:GPS:B.GoToSurface] Stopped
2012-01-05T00:00:12.33690Z,1325721612.3369 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:00:12.33710Z,1325721612.3371 [Default:GPS:Read_GPS] Running Loop=1
2012-01-05T00:00:12.82830Z,1325721612.8283 [NAL9601](INFO): Powering up
2012-01-05T00:01:18.63920Z,1325721678.6392 [NAL9601](INFO): NAL9601 initialized
2012-01-05T00:01:19.64330Z,1325721679.6433 [NAL9601](IMPORTANT): GPS fix at: 1325721692
2012-01-05T00:01:19.70160Z,1325721679.7016 [Default:GPS:Read_GPS] Stopped
2012-01-05T00:01:19.70200Z,1325721679.702 [Default:GPS](INFO): Completed Default:GPS
2012-01-05T00:01:19.70210Z,1325721679.7021 [Default:GPS] Stopped
2012-01-05T00:01:19.70220Z,1325721679.7022 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-05T00:01:19.70230Z,1325721679.7023 [Default:GPS:A.SetSpeed] Stopped
2012-01-05T00:01:19.70240Z,1325721679.7024 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:01:20.08450Z,1325721680.0845 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-05T00:01:20.08460Z,1325721680.0846 [Default:CallGPS:A] Stopped
2012-01-05T00:01:20.08480Z,1325721680.0848 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-05T00:01:20.08500Z,1325721680.085 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-05T00:01:20.08510Z,1325721680.0851 [Default:CallGPS] Stopped
2012-01-05T00:01:20.08520Z,1325721680.0852 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-05T00:01:20.44810Z,1325721680.4481 [Default:CallGPS] Running Loop=1
2012-01-05T00:01:20.44830Z,1325721680.4483 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-05T00:01:20.44850Z,1325721680.4485 [Default:CallGPS:A] Running Loop=1
2012-01-05T00:01:20.44860Z,1325721680.4486 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-05T00:01:20.91930Z,1325721680.9193 [Default:GPS] Running Loop=1
2012-01-05T00:01:20.91940Z,1325721680.9194 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-05T00:01:20.91950Z,1325721680.9195 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-05T00:01:20.91960Z,1325721680.9196 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:01:20.91980Z,1325721680.9198 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-05T00:01:20.91990Z,1325721680.9199 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:01:20.92060Z,1325721680.9206 [Default:GPS:B.GoToSurface] Stopped
2012-01-05T00:01:20.92070Z,1325721680.9207 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:01:20.92080Z,1325721680.9208 [Default:GPS:Read_GPS] Running Loop=1
2012-01-05T00:01:43.12170Z,1325721703.1217 [NAL9601](INFO): SBD MO Status=1, MOMSN=40267, MT Status=0, MTMSN=0
2012-01-05T00:01:43.29110Z,1325721703.2911 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0005.lzma
2012-01-05T00:01:43.29140Z,1325721703.2914 [NAL9601](INFO): Packets left to send: 4
2012-01-05T00:01:43.29320Z,1325721703.2932 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000054
2012-01-05T00:01:52.41770Z,1325721712.4177 [NAL9601](INFO): SBD MO Status=1, MOMSN=40268, MT Status=0, MTMSN=0
2012-01-05T00:01:52.58720Z,1325721712.5872 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0005.lzma
2012-01-05T00:01:52.58740Z,1325721712.5874 [NAL9601](INFO): Packets left to send: 3
2012-01-05T00:01:52.58850Z,1325721712.5885 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000055
2012-01-05T00:02:05.53360Z,1325721725.5336 [NAL9601](INFO): SBD MO Status=1, MOMSN=40269, MT Status=0, MTMSN=0
2012-01-05T00:02:05.65520Z,1325721725.6552 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0005.lzma
2012-01-05T00:02:05.65540Z,1325721725.6554 [NAL9601](INFO): Packets left to send: 2
2012-01-05T00:02:05.65650Z,1325721725.6565 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000056
2012-01-05T00:02:17.25670Z,1325721737.2567 [NAL9601](INFO): SBD MO Status=1, MOMSN=40270, MT Status=0, MTMSN=0
2012-01-05T00:02:17.43520Z,1325721737.4352 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0005.lzma
2012-01-05T00:02:17.43540Z,1325721737.4354 [NAL9601](INFO): Packets left to send: 1
2012-01-05T00:02:17.43730Z,1325721737.4373 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000057
2012-01-05T00:02:22.58150Z,1325721742.5815 [NAL9601](INFO): SBD MO Status=2, MOMSN=40271, MT Status=2, MTMSN=0
2012-01-05T00:02:22.58180Z,1325721742.5818 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-01-05T00:02:23.76140Z,1325721743.7614 [NAL9601](IMPORTANT): GPS fix at: 1325721757
2012-01-05T00:02:23.77770Z,1325721743.7777 [Default:GPS:Read_GPS] Stopped
2012-01-05T00:02:23.77810Z,1325721743.7781 [Default:GPS](INFO): Completed Default:GPS
2012-01-05T00:02:23.77820Z,1325721743.7782 [Default:GPS] Stopped
2012-01-05T00:02:23.77840Z,1325721743.7784 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-05T00:02:23.77840Z,1325721743.7784 [Default:GPS:A.SetSpeed] Stopped
2012-01-05T00:02:23.77850Z,1325721743.7785 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:02:24.18230Z,1325721744.1823 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-05T00:02:24.18240Z,1325721744.1824 [Default:CallGPS:A] Stopped
2012-01-05T00:02:24.18250Z,1325721744.1825 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-05T00:02:24.18280Z,1325721744.1828 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-05T00:02:24.18290Z,1325721744.1829 [Default:CallGPS] Stopped
2012-01-05T00:02:24.18300Z,1325721744.183 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-05T00:02:24.60160Z,1325721744.6016 [Default:CallGPS] Running Loop=1
2012-01-05T00:02:24.60180Z,1325721744.6018 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-05T00:02:24.60190Z,1325721744.6019 [Default:CallGPS:A] Running Loop=1
2012-01-05T00:02:24.60210Z,1325721744.6021 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-05T00:02:25.02410Z,1325721745.0241 [Default:GPS] Running Loop=1
2012-01-05T00:02:25.02430Z,1325721745.0243 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-05T00:02:25.02440Z,1325721745.0244 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-05T00:02:25.02450Z,1325721745.0245 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:02:25.02470Z,1325721745.0247 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-05T00:02:25.02470Z,1325721745.0247 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:02:25.02540Z,1325721745.0254 [Default:GPS:B.GoToSurface] Stopped
2012-01-05T00:02:25.02550Z,1325721745.0255 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:02:25.02570Z,1325721745.0257 [Default:GPS:Read_GPS] Running Loop=1
2012-01-05T00:02:40.40170Z,1325721760.4017 [NAL9601](INFO): SBD MO Status=1, MOMSN=40271, MT Status=0, MTMSN=0
2012-01-05T00:02:40.59920Z,1325721760.5992 [NAL9601](INFO): Sent 6 bytes from file Logs/20120104T230740/shore0005.lzma
2012-01-05T00:02:40.59940Z,1325721760.5994 [NAL9601](INFO): Packets left to send: 0
2012-01-05T00:02:40.60050Z,1325721760.6005 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000058
2012-01-05T00:02:48.81920Z,1325721768.8192 [NAL9601](INFO): SBD MO Status=0, MOMSN=40272, MT Status=0, MTMSN=0
2012-01-05T00:02:49.00020Z,1325721769.0002 [Default:Iridium:Read_Iridium] Stopped
2012-01-05T00:02:49.00060Z,1325721769.0006 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-05T00:02:49.00070Z,1325721769.0007 [Default:Iridium] Stopped
2012-01-05T00:02:49.00090Z,1325721769.0009 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-05T00:02:49.00090Z,1325721769.0009 [Default:Iridium:A.SetSpeed] Stopped
2012-01-05T00:02:49.00100Z,1325721769.001 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:02:49.21300Z,1325721769.213 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-05T00:02:49.21310Z,1325721769.2131 [Default:CallIridium:A] Stopped
2012-01-05T00:02:49.21330Z,1325721769.2133 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-05T00:02:49.21350Z,1325721769.2135 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-05T00:02:49.21360Z,1325721769.2136 [Default:CallIridium] Stopped
2012-01-05T00:02:49.21370Z,1325721769.2137 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-05T00:02:50.00320Z,1325721770.0032 [NAL9601](IMPORTANT): GPS fix at: 1325721783
2012-01-05T00:02:50.01710Z,1325721770.0171 [Default:GPS:Read_GPS] Stopped
2012-01-05T00:02:50.01750Z,1325721770.0175 [Default:GPS](INFO): Completed Default:GPS
2012-01-05T00:02:50.01760Z,1325721770.0176 [Default:GPS] Stopped
2012-01-05T00:02:50.01770Z,1325721770.0177 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-05T00:02:50.01780Z,1325721770.0178 [Default:GPS:A.SetSpeed] Stopped
2012-01-05T00:02:50.01790Z,1325721770.0179 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:02:50.41410Z,1325721770.4141 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-05T00:02:50.41420Z,1325721770.4142 [Default:CallGPS:A] Stopped
2012-01-05T00:02:50.41430Z,1325721770.4143 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-05T00:02:50.41470Z,1325721770.4147 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-05T00:02:50.41480Z,1325721770.4148 [Default:CallGPS] Stopped
2012-01-05T00:02:50.41500Z,1325721770.415 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-05T00:03:10.59850Z,1325721790.5985 [NAL9601](INFO): Powering down
2012-01-05T00:07:50.64650Z,1325722070.6465 [Default:CallIridium] Running Loop=1
2012-01-05T00:07:50.64690Z,1325722070.6469 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-05T00:07:50.64700Z,1325722070.647 [Default:CallIridium:A] Running Loop=1
2012-01-05T00:07:50.64720Z,1325722070.6472 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-05T00:07:50.64730Z,1325722070.6473 [Default:CallGPS] Running Loop=1
2012-01-05T00:07:50.64740Z,1325722070.6474 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-05T00:07:50.64760Z,1325722070.6476 [Default:CallGPS:A] Running Loop=1
2012-01-05T00:07:50.64770Z,1325722070.6477 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-05T00:07:55.90070Z,1325722075.9007 [Default:Iridium] Running Loop=1
2012-01-05T00:07:55.90090Z,1325722075.9009 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-05T00:07:55.90100Z,1325722075.901 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-05T00:07:55.90100Z,1325722075.901 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:07:55.90120Z,1325722075.9012 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-05T00:07:55.90130Z,1325722075.9013 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:07:55.90200Z,1325722075.902 [Default:Iridium:B.GoToSurface] Stopped
2012-01-05T00:07:55.90210Z,1325722075.9021 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:07:55.90230Z,1325722075.9023 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-05T00:07:55.90260Z,1325722075.9026 [Default:GPS] Running Loop=1
2012-01-05T00:07:55.90280Z,1325722075.9028 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-05T00:07:55.90280Z,1325722075.9028 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-05T00:07:55.90290Z,1325722075.9029 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:07:55.90310Z,1325722075.9031 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-05T00:07:55.90320Z,1325722075.9032 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:07:55.90380Z,1325722075.9038 [Default:GPS:B.GoToSurface] Stopped
2012-01-05T00:07:55.90390Z,1325722075.9039 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:07:55.90400Z,1325722075.904 [Default:GPS:Read_GPS] Running Loop=1
2012-01-05T00:07:56.43790Z,1325722076.4379 [NAL9601](INFO): Powering up
2012-01-05T00:09:02.14720Z,1325722142.1472 [NAL9601](INFO): NAL9601 initialized
2012-01-05T00:09:20.89370Z,1325722160.8937 [NAL9601](INFO): SBD MO Status=1, MOMSN=40273, MT Status=0, MTMSN=0
2012-01-05T00:09:21.11140Z,1325722161.1114 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0006.lzma
2012-01-05T00:09:21.11170Z,1325722161.1117 [NAL9601](INFO): Packets left to send: 2
2012-01-05T00:09:21.11280Z,1325722161.1128 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000059
2012-01-05T00:09:28.58160Z,1325722168.5816 [NAL9601](INFO): SBD MO Status=1, MOMSN=40274, MT Status=0, MTMSN=0
2012-01-05T00:09:28.79510Z,1325722168.7951 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0006.lzma
2012-01-05T00:09:28.79540Z,1325722168.7954 [NAL9601](INFO): Packets left to send: 1
2012-01-05T00:09:28.79660Z,1325722168.7966 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000060
2012-01-05T00:09:35.09570Z,1325722175.0957 [NAL9601](INFO): SBD MO Status=1, MOMSN=40275, MT Status=0, MTMSN=0
2012-01-05T00:09:35.28760Z,1325722175.2876 [NAL9601](INFO): Sent 139 bytes from file Logs/20120104T230740/shore0006.lzma
2012-01-05T00:09:35.28780Z,1325722175.2878 [NAL9601](INFO): Packets left to send: 0
2012-01-05T00:09:35.28900Z,1325722175.289 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000061
2012-01-05T00:09:41.07290Z,1325722181.0729 [NAL9601](INFO): SBD MO Status=0, MOMSN=40276, MT Status=0, MTMSN=0
2012-01-05T00:09:41.28860Z,1325722181.2886 [Default:Iridium:Read_Iridium] Stopped
2012-01-05T00:09:41.28910Z,1325722181.2891 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-05T00:09:41.28920Z,1325722181.2892 [Default:Iridium] Stopped
2012-01-05T00:09:41.28940Z,1325722181.2894 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-05T00:09:41.28940Z,1325722181.2894 [Default:Iridium:A.SetSpeed] Stopped
2012-01-05T00:09:41.28950Z,1325722181.2895 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:09:41.48450Z,1325722181.4845 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-05T00:09:41.48460Z,1325722181.4846 [Default:CallIridium:A] Stopped
2012-01-05T00:09:41.48470Z,1325722181.4847 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-05T00:09:41.48490Z,1325722181.4849 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-05T00:09:41.48500Z,1325722181.485 [Default:CallIridium] Stopped
2012-01-05T00:09:41.48510Z,1325722181.4851 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-05T00:10:58.27940Z,1325722258.2794 [NAL9601](IMPORTANT): GPS fix at: 1325722272
2012-01-05T00:10:58.29340Z,1325722258.2934 [Default:GPS:Read_GPS] Stopped
2012-01-05T00:10:58.29390Z,1325722258.2939 [Default:GPS](INFO): Completed Default:GPS
2012-01-05T00:10:58.29400Z,1325722258.294 [Default:GPS] Stopped
2012-01-05T00:10:58.29410Z,1325722258.2941 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-05T00:10:58.29420Z,1325722258.2942 [Default:GPS:A.SetSpeed] Stopped
2012-01-05T00:10:58.29430Z,1325722258.2943 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:10:58.68480Z,1325722258.6848 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-05T00:10:58.68490Z,1325722258.6849 [Default:CallGPS:A] Stopped
2012-01-05T00:10:58.68510Z,1325722258.6851 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-05T00:10:58.68530Z,1325722258.6853 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-05T00:10:58.68540Z,1325722258.6854 [Default:CallGPS] Stopped
2012-01-05T00:10:58.68550Z,1325722258.6855 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-05T00:11:18.86640Z,1325722278.8664 [NAL9601](INFO): Powering down
2012-01-05T00:12:43.80440Z,1325722363.8044 [Batt_Ocean_Server](INFO): Over Temperature Alarm! Battery Bank #9 STATUS: 5911
2012-01-05T00:12:43.80470Z,1325722363.8047 [Batt_Ocean_Server](INFO): Not Initialized - Battery Bank #9 STATUS: 5911
2012-01-05T00:14:43.83800Z,1325722483.838 [Default:CallIridium] Running Loop=1
2012-01-05T00:14:43.83810Z,1325722483.8381 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-05T00:14:43.83830Z,1325722483.8383 [Default:CallIridium:A] Running Loop=1
2012-01-05T00:14:43.83840Z,1325722483.8384 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-05T00:14:43.83860Z,1325722483.8386 [Default:CallGPS] Running Loop=1
2012-01-05T00:14:43.83870Z,1325722483.8387 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-05T00:14:43.83890Z,1325722483.8389 [Default:CallGPS:A] Running Loop=1
2012-01-05T00:14:43.83900Z,1325722483.839 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-05T00:14:48.86520Z,1325722488.8652 [Default:Iridium] Running Loop=1
2012-01-05T00:14:48.86540Z,1325722488.8654 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-05T00:14:48.86550Z,1325722488.8655 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-05T00:14:48.86560Z,1325722488.8656 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:14:48.86580Z,1325722488.8658 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-05T00:14:48.86590Z,1325722488.8659 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:14:48.86650Z,1325722488.8665 [Default:Iridium:B.GoToSurface] Stopped
2012-01-05T00:14:48.86660Z,1325722488.8666 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:14:48.86680Z,1325722488.8668 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-05T00:14:48.86710Z,1325722488.8671 [Default:GPS] Running Loop=1
2012-01-05T00:14:48.86720Z,1325722488.8672 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-05T00:14:48.86730Z,1325722488.8673 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-05T00:14:48.86740Z,1325722488.8674 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:14:48.86760Z,1325722488.8676 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-05T00:14:48.86770Z,1325722488.8677 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:14:48.86830Z,1325722488.8683 [Default:GPS:B.GoToSurface] Stopped
2012-01-05T00:14:48.86830Z,1325722488.8683 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:14:48.86850Z,1325722488.8685 [Default:GPS:Read_GPS] Running Loop=1
2012-01-05T00:14:49.47630Z,1325722489.4763 [NAL9601](INFO): Powering up
2012-01-05T00:15:55.18720Z,1325722555.1872 [NAL9601](INFO): NAL9601 initialized
2012-01-05T00:15:56.27490Z,1325722556.2749 [NAL9601](IMPORTANT): GPS fix at: 1325722570
2012-01-05T00:15:56.28880Z,1325722556.2888 [Default:GPS:Read_GPS] Stopped
2012-01-05T00:15:56.28920Z,1325722556.2892 [Default:GPS](INFO): Completed Default:GPS
2012-01-05T00:15:56.28930Z,1325722556.2893 [Default:GPS] Stopped
2012-01-05T00:15:56.28940Z,1325722556.2894 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-05T00:15:56.28950Z,1325722556.2895 [Default:GPS:A.SetSpeed] Stopped
2012-01-05T00:15:56.28960Z,1325722556.2896 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:15:56.68460Z,1325722556.6846 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-05T00:15:56.68470Z,1325722556.6847 [Default:CallGPS:A] Stopped
2012-01-05T00:15:56.68480Z,1325722556.6848 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-05T00:15:56.68500Z,1325722556.685 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-05T00:15:56.68510Z,1325722556.6851 [Default:CallGPS] Stopped
2012-01-05T00:15:56.68520Z,1325722556.6852 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-05T00:15:57.09330Z,1325722557.0933 [Default:CallGPS] Running Loop=1
2012-01-05T00:15:57.09350Z,1325722557.0935 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-05T00:15:57.09370Z,1325722557.0937 [Default:CallGPS:A] Running Loop=1
2012-01-05T00:15:57.09380Z,1325722557.0938 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-05T00:15:57.53530Z,1325722557.5353 [Default:GPS] Running Loop=1
2012-01-05T00:15:57.53550Z,1325722557.5355 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-05T00:15:57.53560Z,1325722557.5356 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-05T00:15:57.53560Z,1325722557.5356 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:15:57.53580Z,1325722557.5358 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-05T00:15:57.53590Z,1325722557.5359 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:15:57.53650Z,1325722557.5365 [Default:GPS:B.GoToSurface] Stopped
2012-01-05T00:15:57.53660Z,1325722557.5366 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:15:57.53680Z,1325722557.5368 [Default:GPS:Read_GPS] Running Loop=1
2012-01-05T00:16:34.62170Z,1325722594.6217 [NAL9601](INFO): SBD MO Status=2, MOMSN=40277, MT Status=0, MTMSN=0
2012-01-05T00:16:34.62190Z,1325722594.6219 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-01-05T00:16:35.84080Z,1325722595.8408 [NAL9601](IMPORTANT): GPS fix at: 1325722610
2012-01-05T00:16:35.85510Z,1325722595.8551 [Default:GPS:Read_GPS] Stopped
2012-01-05T00:16:35.85550Z,1325722595.8555 [Default:GPS](INFO): Completed Default:GPS
2012-01-05T00:16:35.85560Z,1325722595.8556 [Default:GPS] Stopped
2012-01-05T00:16:35.85570Z,1325722595.8557 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-05T00:16:35.85580Z,1325722595.8558 [Default:GPS:A.SetSpeed] Stopped
2012-01-05T00:16:35.85590Z,1325722595.8559 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:16:36.23380Z,1325722596.2338 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-05T00:16:36.23390Z,1325722596.2339 [Default:CallGPS:A] Stopped
2012-01-05T00:16:36.23400Z,1325722596.234 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-05T00:16:36.23430Z,1325722596.2343 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-05T00:16:36.23430Z,1325722596.2343 [Default:CallGPS] Stopped
2012-01-05T00:16:36.23450Z,1325722596.2345 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-05T00:16:36.67590Z,1325722596.6759 [Default:CallGPS] Running Loop=1
2012-01-05T00:16:36.67600Z,1325722596.676 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-05T00:16:36.67620Z,1325722596.6762 [Default:CallGPS:A] Running Loop=1
2012-01-05T00:16:36.67630Z,1325722596.6763 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-05T00:16:37.05750Z,1325722597.0575 [Default:GPS] Running Loop=1
2012-01-05T00:16:37.05770Z,1325722597.0577 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-05T00:16:37.05780Z,1325722597.0578 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-05T00:16:37.05790Z,1325722597.0579 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:16:37.05810Z,1325722597.0581 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-05T00:16:37.05820Z,1325722597.0582 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:16:37.05890Z,1325722597.0589 [Default:GPS:B.GoToSurface] Stopped
2012-01-05T00:16:37.05890Z,1325722597.0589 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:16:37.05910Z,1325722597.0591 [Default:GPS:Read_GPS] Running Loop=1
2012-01-05T00:16:51.37770Z,1325722611.3777 [NAL9601](INFO): SBD MO Status=1, MOMSN=40277, MT Status=0, MTMSN=0
2012-01-05T00:16:51.58720Z,1325722611.5872 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0007.lzma
2012-01-05T00:16:51.58740Z,1325722611.5874 [NAL9601](INFO): Packets left to send: 2
2012-01-05T00:16:51.58850Z,1325722611.5885 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000062
2012-01-05T00:17:05.45770Z,1325722625.4577 [NAL9601](INFO): SBD MO Status=1, MOMSN=40278, MT Status=0, MTMSN=0
2012-01-05T00:17:05.66710Z,1325722625.6671 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0007.lzma
2012-01-05T00:17:05.66740Z,1325722625.6674 [NAL9601](INFO): Packets left to send: 1
2012-01-05T00:17:05.66850Z,1325722625.6685 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000063
2012-01-05T00:17:13.18080Z,1325722633.1808 [NAL9601](INFO): SBD MO Status=1, MOMSN=40279, MT Status=0, MTMSN=0
2012-01-05T00:17:13.35510Z,1325722633.3551 [NAL9601](INFO): Sent 138 bytes from file Logs/20120104T230740/shore0007.lzma
2012-01-05T00:17:13.35540Z,1325722633.3554 [NAL9601](INFO): Packets left to send: 0
2012-01-05T00:17:13.35650Z,1325722633.3565 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000064
2012-01-05T00:17:22.74160Z,1325722642.7416 [NAL9601](INFO): SBD MO Status=0, MOMSN=40280, MT Status=0, MTMSN=0
2012-01-05T00:17:22.95220Z,1325722642.9522 [Default:Iridium:Read_Iridium] Stopped
2012-01-05T00:17:22.95270Z,1325722642.9527 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-05T00:17:22.95280Z,1325722642.9528 [Default:Iridium] Stopped
2012-01-05T00:17:22.95300Z,1325722642.953 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-05T00:17:22.95300Z,1325722642.953 [Default:Iridium:A.SetSpeed] Stopped
2012-01-05T00:17:22.95310Z,1325722642.9531 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:17:23.14830Z,1325722643.1483 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-05T00:17:23.14840Z,1325722643.1484 [Default:CallIridium:A] Stopped
2012-01-05T00:17:23.14850Z,1325722643.1485 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-05T00:17:23.14880Z,1325722643.1488 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-05T00:17:23.14880Z,1325722643.1488 [Default:CallIridium] Stopped
2012-01-05T00:17:23.14900Z,1325722643.149 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-05T00:17:23.94320Z,1325722643.9432 [NAL9601](IMPORTANT): GPS fix at: 1325722658
2012-01-05T00:17:23.95680Z,1325722643.9568 [Default:GPS:Read_GPS] Stopped
2012-01-05T00:17:23.95720Z,1325722643.9572 [Default:GPS](INFO): Completed Default:GPS
2012-01-05T00:17:23.95730Z,1325722643.9573 [Default:GPS] Stopped
2012-01-05T00:17:23.95740Z,1325722643.9574 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-05T00:17:23.95750Z,1325722643.9575 [Default:GPS:A.SetSpeed] Stopped
2012-01-05T00:17:23.95760Z,1325722643.9576 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:17:24.39740Z,1325722644.3974 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-05T00:17:24.39750Z,1325722644.3975 [Default:CallGPS:A] Stopped
2012-01-05T00:17:24.39760Z,1325722644.3976 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-05T00:17:24.39780Z,1325722644.3978 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-05T00:17:24.39790Z,1325722644.3979 [Default:CallGPS] Stopped
2012-01-05T00:17:24.39800Z,1325722644.398 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-05T00:17:44.57980Z,1325722664.5798 [NAL9601](INFO): Powering down
2012-01-05T00:22:24.52950Z,1325722944.5295 [Default:CallIridium] Running Loop=1
2012-01-05T00:22:24.52970Z,1325722944.5297 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-05T00:22:24.52990Z,1325722944.5299 [Default:CallIridium:A] Running Loop=1
2012-01-05T00:22:24.53000Z,1325722944.53 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-05T00:22:24.53010Z,1325722944.5301 [Default:CallGPS] Running Loop=1
2012-01-05T00:22:24.53030Z,1325722944.5303 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-05T00:22:24.53040Z,1325722944.5304 [Default:CallGPS:A] Running Loop=1
2012-01-05T00:22:24.53050Z,1325722944.5305 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-05T00:22:29.55800Z,1325722949.558 [Default:Iridium] Running Loop=1
2012-01-05T00:22:29.55820Z,1325722949.5582 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-05T00:22:29.55820Z,1325722949.5582 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-05T00:22:29.55830Z,1325722949.5583 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:22:29.55850Z,1325722949.5585 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-05T00:22:29.55870Z,1325722949.5587 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:22:29.55940Z,1325722949.5594 [Default:Iridium:B.GoToSurface] Stopped
2012-01-05T00:22:29.55950Z,1325722949.5595 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:22:29.55960Z,1325722949.5596 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-05T00:22:29.56000Z,1325722949.56 [Default:GPS] Running Loop=1
2012-01-05T00:22:29.56010Z,1325722949.5601 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-05T00:22:29.56020Z,1325722949.5602 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-05T00:22:29.56030Z,1325722949.5603 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:22:29.56050Z,1325722949.5605 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-05T00:22:29.56060Z,1325722949.5606 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:22:29.56120Z,1325722949.5612 [Default:GPS:B.GoToSurface] Stopped
2012-01-05T00:22:29.56130Z,1325722949.5613 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:22:29.56140Z,1325722949.5614 [Default:GPS:Read_GPS] Running Loop=1
2012-01-05T00:22:30.16740Z,1325722950.1674 [NAL9601](INFO): Powering up
2012-01-05T00:23:35.87920Z,1325723015.8792 [NAL9601](INFO): NAL9601 initialized
2012-01-05T00:23:36.94330Z,1325723016.9433 [NAL9601](IMPORTANT): GPS fix at: 1325723032
2012-01-05T00:23:36.95800Z,1325723016.958 [Default:GPS:Read_GPS] Stopped
2012-01-05T00:23:36.95840Z,1325723016.9584 [Default:GPS](INFO): Completed Default:GPS
2012-01-05T00:23:36.95850Z,1325723016.9585 [Default:GPS] Stopped
2012-01-05T00:23:36.95870Z,1325723016.9587 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-05T00:23:36.95880Z,1325723016.9588 [Default:GPS:A.SetSpeed] Stopped
2012-01-05T00:23:36.95880Z,1325723016.9588 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:23:37.36190Z,1325723017.3619 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-05T00:23:37.36200Z,1325723017.362 [Default:CallGPS:A] Stopped
2012-01-05T00:23:37.36220Z,1325723017.3622 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-05T00:23:37.36240Z,1325723017.3624 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-05T00:23:37.36250Z,1325723017.3625 [Default:CallGPS] Stopped
2012-01-05T00:23:37.36270Z,1325723017.3627 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-05T00:23:37.75680Z,1325723017.7568 [Default:CallGPS] Running Loop=1
2012-01-05T00:23:37.75700Z,1325723017.757 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-05T00:23:37.75720Z,1325723017.7572 [Default:CallGPS:A] Running Loop=1
2012-01-05T00:23:37.75730Z,1325723017.7573 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-05T00:23:38.34930Z,1325723018.3493 [Default:GPS] Running Loop=1
2012-01-05T00:23:38.34940Z,1325723018.3494 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-05T00:23:38.34950Z,1325723018.3495 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-05T00:23:38.34960Z,1325723018.3496 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:23:38.34980Z,1325723018.3498 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-05T00:23:38.34990Z,1325723018.3499 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:23:38.35060Z,1325723018.3506 [Default:GPS:B.GoToSurface] Stopped
2012-01-05T00:23:38.35070Z,1325723018.3507 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:23:38.35090Z,1325723018.3509 [Default:GPS:Read_GPS] Running Loop=1
2012-01-05T00:23:52.81760Z,1325723032.8176 [NAL9601](INFO): SBD MO Status=1, MOMSN=40281, MT Status=0, MTMSN=0
2012-01-05T00:23:52.94320Z,1325723032.9432 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0008.lzma
2012-01-05T00:23:52.94340Z,1325723032.9434 [NAL9601](INFO): Packets left to send: 2
2012-01-05T00:23:52.94460Z,1325723032.9446 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000065
2012-01-05T00:24:02.52910Z,1325723042.5291 [NAL9601](INFO): SBD MO Status=1, MOMSN=40282, MT Status=0, MTMSN=0
2012-01-05T00:24:02.72720Z,1325723042.7272 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0008.lzma
2012-01-05T00:24:02.72740Z,1325723042.7274 [NAL9601](INFO): Packets left to send: 1
2012-01-05T00:24:03.33780Z,1325723043.3378 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000066
2012-01-05T00:24:11.11370Z,1325723051.1137 [NAL9601](INFO): SBD MO Status=1, MOMSN=40283, MT Status=0, MTMSN=0
2012-01-05T00:24:11.31510Z,1325723051.3151 [NAL9601](INFO): Sent 141 bytes from file Logs/20120104T230740/shore0008.lzma
2012-01-05T00:24:11.31540Z,1325723051.3154 [NAL9601](INFO): Packets left to send: 0
2012-01-05T00:24:11.31650Z,1325723051.3165 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000067
2012-01-05T00:24:36.71370Z,1325723076.7137 [NAL9601](INFO): SBD MO Status=2, MOMSN=40284, MT Status=2, MTMSN=0
2012-01-05T00:24:36.71390Z,1325723076.7139 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-01-05T00:24:37.96110Z,1325723077.9611 [NAL9601](IMPORTANT): GPS fix at: 1325723093
2012-01-05T00:24:38.01730Z,1325723078.0173 [Default:GPS:Read_GPS] Stopped
2012-01-05T00:24:38.01770Z,1325723078.0177 [Default:GPS](INFO): Completed Default:GPS
2012-01-05T00:24:38.01780Z,1325723078.0178 [Default:GPS] Stopped
2012-01-05T00:24:38.01800Z,1325723078.018 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-05T00:24:38.01800Z,1325723078.018 [Default:GPS:A.SetSpeed] Stopped
2012-01-05T00:24:38.01810Z,1325723078.0181 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:24:38.32600Z,1325723078.326 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-05T00:24:38.32610Z,1325723078.3261 [Default:CallGPS:A] Stopped
2012-01-05T00:24:38.32620Z,1325723078.3262 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-05T00:24:38.32640Z,1325723078.3264 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-05T00:24:38.32650Z,1325723078.3265 [Default:CallGPS] Stopped
2012-01-05T00:24:38.32670Z,1325723078.3267 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-05T00:24:38.72970Z,1325723078.7297 [Default:CallGPS] Running Loop=1
2012-01-05T00:24:38.72990Z,1325723078.7299 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-05T00:24:38.73000Z,1325723078.73 [Default:CallGPS:A] Running Loop=1
2012-01-05T00:24:38.73020Z,1325723078.7302 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-05T00:24:39.12080Z,1325723079.1208 [Default:GPS] Running Loop=1
2012-01-05T00:24:39.12090Z,1325723079.1209 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-05T00:24:39.12100Z,1325723079.121 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-05T00:24:39.12110Z,1325723079.1211 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:24:39.12130Z,1325723079.1213 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-05T00:24:39.12140Z,1325723079.1214 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:24:39.12200Z,1325723079.122 [Default:GPS:B.GoToSurface] Stopped
2012-01-05T00:24:39.12210Z,1325723079.1221 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:24:39.12220Z,1325723079.1222 [Default:GPS:Read_GPS] Running Loop=1
2012-01-05T00:24:44.95370Z,1325723084.9537 [NAL9601](INFO): SBD MO Status=0, MOMSN=40284, MT Status=0, MTMSN=0
2012-01-05T00:24:45.17310Z,1325723085.1731 [Default:Iridium:Read_Iridium] Stopped
2012-01-05T00:24:45.17350Z,1325723085.1735 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-05T00:24:45.17360Z,1325723085.1736 [Default:Iridium] Stopped
2012-01-05T00:24:45.17380Z,1325723085.1738 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-05T00:24:45.17390Z,1325723085.1739 [Default:Iridium:A.SetSpeed] Stopped
2012-01-05T00:24:45.17390Z,1325723085.1739 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:24:45.36130Z,1325723085.3613 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-05T00:24:45.36140Z,1325723085.3614 [Default:CallIridium:A] Stopped
2012-01-05T00:24:45.36150Z,1325723085.3615 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-05T00:24:45.36170Z,1325723085.3617 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-05T00:24:45.36180Z,1325723085.3618 [Default:CallIridium] Stopped
2012-01-05T00:24:45.36200Z,1325723085.362 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-05T00:24:46.19450Z,1325723086.1945 [NAL9601](IMPORTANT): GPS fix at: 1325723101
2012-01-05T00:24:46.20860Z,1325723086.2086 [Default:GPS:Read_GPS] Stopped
2012-01-05T00:24:46.20900Z,1325723086.209 [Default:GPS](INFO): Completed Default:GPS
2012-01-05T00:24:46.20910Z,1325723086.2091 [Default:GPS] Stopped
2012-01-05T00:24:46.20920Z,1325723086.2092 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-05T00:24:46.20930Z,1325723086.2093 [Default:GPS:A.SetSpeed] Stopped
2012-01-05T00:24:46.20940Z,1325723086.2094 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:24:46.58370Z,1325723086.5837 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-05T00:24:46.58380Z,1325723086.5838 [Default:CallGPS:A] Stopped
2012-01-05T00:24:46.58400Z,1325723086.584 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-05T00:24:46.58420Z,1325723086.5842 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-05T00:24:46.58430Z,1325723086.5843 [Default:CallGPS] Stopped
2012-01-05T00:24:46.58440Z,1325723086.5844 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-05T00:25:06.71230Z,1325723106.7123 [NAL9601](INFO): Powering down
2012-01-05T00:29:46.80150Z,1325723386.8015 [Default:CallIridium] Running Loop=1
2012-01-05T00:29:46.80160Z,1325723386.8016 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-05T00:29:46.80180Z,1325723386.8018 [Default:CallIridium:A] Running Loop=1
2012-01-05T00:29:46.80190Z,1325723386.8019 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-05T00:29:46.80210Z,1325723386.8021 [Default:CallGPS] Running Loop=1
2012-01-05T00:29:46.80220Z,1325723386.8022 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-05T00:29:46.80230Z,1325723386.8023 [Default:CallGPS:A] Running Loop=1
2012-01-05T00:29:46.80250Z,1325723386.8025 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-05T00:29:51.75470Z,1325723391.7547 [Default:Iridium] Running Loop=1
2012-01-05T00:29:51.75490Z,1325723391.7549 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-05T00:29:51.75500Z,1325723391.755 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-05T00:29:51.75510Z,1325723391.7551 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:29:51.75530Z,1325723391.7553 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-05T00:29:51.75530Z,1325723391.7553 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:29:51.75600Z,1325723391.756 [Default:Iridium:B.GoToSurface] Stopped
2012-01-05T00:29:51.75600Z,1325723391.756 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:29:51.75620Z,1325723391.7562 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-05T00:29:51.75660Z,1325723391.7566 [Default:GPS] Running Loop=1
2012-01-05T00:29:51.75670Z,1325723391.7567 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-05T00:29:51.75680Z,1325723391.7568 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-05T00:29:51.75690Z,1325723391.7569 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:29:51.75710Z,1325723391.7571 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-05T00:29:51.75710Z,1325723391.7571 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:29:51.75780Z,1325723391.7578 [Default:GPS:B.GoToSurface] Stopped
2012-01-05T00:29:51.75790Z,1325723391.7579 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:29:51.75810Z,1325723391.7581 [Default:GPS:Read_GPS] Running Loop=1
2012-01-05T00:29:52.34760Z,1325723392.3476 [NAL9601](INFO): Powering up
2012-01-05T00:30:58.15920Z,1325723458.1592 [NAL9601](INFO): NAL9601 initialized
2012-01-05T00:30:59.15520Z,1325723459.1552 [NAL9601](IMPORTANT): GPS fix at: 1325723475
2012-01-05T00:30:59.16910Z,1325723459.1691 [Default:GPS:Read_GPS] Stopped
2012-01-05T00:30:59.16940Z,1325723459.1694 [Default:GPS](INFO): Completed Default:GPS
2012-01-05T00:30:59.16950Z,1325723459.1695 [Default:GPS] Stopped
2012-01-05T00:30:59.16970Z,1325723459.1697 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-05T00:30:59.16970Z,1325723459.1697 [Default:GPS:A.SetSpeed] Stopped
2012-01-05T00:30:59.16980Z,1325723459.1698 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:30:59.56610Z,1325723459.5661 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-05T00:30:59.56610Z,1325723459.5661 [Default:CallGPS:A] Stopped
2012-01-05T00:30:59.56630Z,1325723459.5663 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-05T00:30:59.56650Z,1325723459.5665 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-05T00:30:59.56660Z,1325723459.5666 [Default:CallGPS] Stopped
2012-01-05T00:30:59.56680Z,1325723459.5668 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-05T00:30:59.99480Z,1325723459.9948 [Default:CallGPS] Running Loop=1
2012-01-05T00:30:59.99490Z,1325723459.9949 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-05T00:30:59.99510Z,1325723459.9951 [Default:CallGPS:A] Running Loop=1
2012-01-05T00:30:59.99520Z,1325723459.9952 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-05T00:31:00.40960Z,1325723460.4096 [Default:GPS] Running Loop=1
2012-01-05T00:31:00.40980Z,1325723460.4098 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-05T00:31:00.40990Z,1325723460.4099 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-05T00:31:00.40990Z,1325723460.4099 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:31:00.41010Z,1325723460.4101 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-05T00:31:00.41020Z,1325723460.4102 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:31:00.41110Z,1325723460.4111 [Default:GPS:B.GoToSurface] Stopped
2012-01-05T00:31:00.41120Z,1325723460.4112 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:31:00.41140Z,1325723460.4114 [Default:GPS:Read_GPS] Running Loop=1
2012-01-05T00:31:22.61370Z,1325723482.6137 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=40285, MT Status=1, MTMSN=3353
2012-01-05T00:31:22.81930Z,1325723482.8193 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0009.lzma
2012-01-05T00:31:22.81950Z,1325723482.8195 [NAL9601](INFO): Packets left to send: 2
2012-01-05T00:31:22.82060Z,1325723482.8206 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000068
2012-01-05T00:31:23.32430Z,1325723483.3243 [NAL9601](INFO): Received command:run Maintenance/dat_on.xml
2012-01-05T00:31:23.38310Z,1325723483.3831 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/dat_on.xml
2012-01-05T00:31:23.38340Z,1325723483.3834 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/dat_on.xml
2012-01-05T00:31:23.39610Z,1325723483.3961 [MissionManager](INFO): DefineArg dat_on.MassDefault = 0.0015 n/a
2012-01-05T00:31:23.39750Z,1325723483.3975 [dat_on:A.Pitch](DEBUG): Construct.
2012-01-05T00:31:23.40520Z,1325723483.4052 [dat_on:TestDrive:B.Wait](DEBUG): Construct Wait.
2012-01-05T00:31:23.41000Z,1325723483.41 [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="dat_on">

    <DefineArg Name="MassDefault"><CustomUri Uri="Config/Control.massDefault"/></DefineArg>

    <Timeout Duration="P15M"/>

    <Guidance:Pitch RunIn="Parallel">
        <Setting><Guidance:Pitch.massPosition/><Arg Name="MassDefault"/></Setting>
    </Guidance:Pitch>

    <Aggregate Id="TestDrive">

        <ReadData>
            <Universal:homing_sensor_communications/>
        </ReadData>

        <Guidance:Wait RunIn="Sequence">
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>2</Value></Setting>
        </Guidance:Wait>

    </Aggregate>

</Mission>


2012-01-05T00:31:23.41050Z,1325723483.4105 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/dat_on.xml
2012-01-05T00:31:23.44200Z,1325723483.442 [Default] Stopped
2012-01-05T00:31:23.44220Z,1325723483.4422 [Default](INFO): Aggregate::uninitialize Default
2012-01-05T00:31:23.44230Z,1325723483.4423 [Default:GPS] Stopped
2012-01-05T00:31:23.44240Z,1325723483.4424 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-05T00:31:23.44250Z,1325723483.4425 [Default:GPS:A.SetSpeed] Stopped
2012-01-05T00:31:23.44260Z,1325723483.4426 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:31:23.44270Z,1325723483.4427 [Default:GPS:Read_GPS] Stopped
2012-01-05T00:31:23.44280Z,1325723483.4428 [Default:Iridium] Stopped
2012-01-05T00:31:23.44290Z,1325723483.4429 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-05T00:31:23.44300Z,1325723483.443 [Default:Iridium:A.SetSpeed] Stopped
2012-01-05T00:31:23.44300Z,1325723483.443 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:31:23.44310Z,1325723483.4431 [Default:Iridium:Read_Iridium] Stopped
2012-01-05T00:31:23.44320Z,1325723483.4432 [Default:CallGPS] Stopped
2012-01-05T00:31:23.44330Z,1325723483.4433 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-05T00:31:23.44340Z,1325723483.4434 [Default:CallGPS:A] Stopped
2012-01-05T00:31:23.44350Z,1325723483.4435 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-05T00:31:23.44360Z,1325723483.4436 [Default:CallIridium] Stopped
2012-01-05T00:31:23.44370Z,1325723483.4437 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-05T00:31:23.44380Z,1325723483.4438 [Default:CallIridium:A] Stopped
2012-01-05T00:31:23.44390Z,1325723483.4439 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-05T00:31:23.44400Z,1325723483.444 [Default:E.SetSpeed] Stopped
2012-01-05T00:31:23.44410Z,1325723483.4441 [Default:E.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:31:23.44420Z,1325723483.4442 [Default:F.GoToSurface] Stopped
2012-01-05T00:31:23.44420Z,1325723483.4442 [Default:F.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:31:23.44430Z,1325723483.4443 [Default:G.Wait] Stopped
2012-01-05T00:31:23.44440Z,1325723483.4444 [Default:G.Wait](DEBUG): Uninitialize Wait Component.
2012-01-05T00:31:23.44450Z,1325723483.4445 [MissionManager](IMPORTANT): Started mission dat_on
2012-01-05T00:31:23.44460Z,1325723483.4446 [dat_on] Running Loop=1
2012-01-05T00:31:23.44480Z,1325723483.4448 [dat_on](INFO): Aggregate::initialize dat_on
2012-01-05T00:31:23.44480Z,1325723483.4448 [dat_on:A.Pitch] Running Loop=1
2012-01-05T00:31:23.44490Z,1325723483.4449 [dat_on:A.Pitch](DEBUG): Initialize.
2012-01-05T00:31:23.44520Z,1325723483.4452 [dat_on:TestDrive] Running Loop=1
2012-01-05T00:31:23.44530Z,1325723483.4453 [dat_on:TestDrive](INFO): Aggregate::initialize dat_on:TestDrive
2012-01-05T00:31:23.44540Z,1325723483.4454 [dat_on:TestDrive:A] Running Loop=1
2012-01-05T00:31:23.44550Z,1325723483.4455 [dat_on:TestDrive:B.Wait] Running Loop=1
2012-01-05T00:31:23.44560Z,1325723483.4456 [dat_on:TestDrive:B.Wait](DEBUG): Initialize Wait Component.
2012-01-05T00:31:23.44660Z,1325723483.4466 [dat_on:TestDrive:A] Running Loop=1
2012-01-05T00:31:23.44720Z,1325723483.4472 [dat_on:TestDrive:A](DEBUG): Initialize ReadDataComponent to sense homing_sensor_communications
2012-01-05T00:31:23.44990Z,1325723483.4499 [dat_on:A.Pitch] Running Loop=1
2012-01-05T00:31:23.81840Z,1325723483.8184 [DAT](INFO): Powering up
2012-01-05T00:31:24.23300Z,1325723484.233 [NAL9601](IMPORTANT): GPS fix at: 1325723500
2012-01-05T00:31:30.60750Z,1325723490.6075 [NAL9601](INFO): Powering down
2012-01-05T00:32:07.03230Z,1325723527.0323 [DAT](ERROR): Unexpected response:01:32:21.7062 , ROT= 103.5, 45.2
01:32:25.7545 , ROT= 104.1, 50.9
Compass 332.6
2012-01-05T00:32:28.68160Z,1325723548.6816 [DAT](ERROR): Unexpected response:01:32:39.3304 , ROT= 106.2, 50.9
01:32:40.2034 , ROT= 111.8,-15.1
Response Not Received
2012-01-05T00:32:51.04710Z,1325723571.0471 [Batt_Ocean_Server](INFO): Over Temperature Alarm! Battery Bank #4 STATUS: 5911
2012-01-05T00:32:51.04750Z,1325723571.0475 [Batt_Ocean_Server](INFO): Not Initialized - Battery Bank #4 STATUS: 5911
2012-01-05T00:33:23.44840Z,1325723603.4484 [dat_on:TestDrive:B.Wait](INFO): Done Waiting.
2012-01-05T00:33:23.44870Z,1325723603.4487 [dat_on:TestDrive:B.Wait] Stopped
2012-01-05T00:33:23.44880Z,1325723603.4488 [dat_on:TestDrive:B.Wait](DEBUG): Uninitialize Wait Component.
2012-01-05T00:33:23.44910Z,1325723603.4491 [dat_on:TestDrive](INFO): Completed dat_on:TestDrive
2012-01-05T00:33:23.44920Z,1325723603.4492 [dat_on:TestDrive] Stopped
2012-01-05T00:33:23.44930Z,1325723603.4493 [dat_on:TestDrive](INFO): Aggregate::uninitialize dat_on:TestDrive
2012-01-05T00:33:23.44940Z,1325723603.4494 [dat_on:TestDrive:A] Stopped
2012-01-05T00:33:23.44980Z,1325723603.4498 [dat_on](INFO): Completed dat_on
2012-01-05T00:33:23.44990Z,1325723603.4499 [dat_on] Stopped
2012-01-05T00:33:23.45000Z,1325723603.45 [dat_on](INFO): Aggregate::uninitialize dat_on
2012-01-05T00:33:23.45010Z,1325723603.4501 [dat_on:A.Pitch] Stopped
2012-01-05T00:33:23.82100Z,1325723603.821 [MissionManager](IMPORTANT): Started mission Default
2012-01-05T00:33:23.82110Z,1325723603.8211 [Default] Running Loop=1
2012-01-05T00:33:23.82120Z,1325723603.8212 [Default](INFO): Aggregate::initialize Default
2012-01-05T00:33:23.82130Z,1325723603.8213 [Default:E.SetSpeed] Running Loop=1
2012-01-05T00:33:23.82140Z,1325723603.8214 [Default:E.SetSpeed](DEBUG): Initialize.
2012-01-05T00:33:23.82150Z,1325723603.8215 [Default:F.GoToSurface] Running Loop=1
2012-01-05T00:33:23.82160Z,1325723603.8216 [Default:F.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:33:23.82200Z,1325723603.822 [Default:GPS] Running Loop=1
2012-01-05T00:33:23.82220Z,1325723603.8222 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-05T00:33:23.82220Z,1325723603.8222 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-05T00:33:23.82230Z,1325723603.8223 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:33:23.82250Z,1325723603.8225 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-05T00:33:23.82260Z,1325723603.8226 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:33:23.82410Z,1325723603.8241 [Default:CallIridium] Running Loop=1
2012-01-05T00:33:23.82430Z,1325723603.8243 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-05T00:33:23.82440Z,1325723603.8244 [Default:CallIridium:A] Running Loop=1
2012-01-05T00:33:23.82450Z,1325723603.8245 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-05T00:33:23.82470Z,1325723603.8247 [Default:CallGPS] Running Loop=1
2012-01-05T00:33:23.82480Z,1325723603.8248 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-05T00:33:23.82490Z,1325723603.8249 [Default:CallGPS:A] Running Loop=1
2012-01-05T00:33:23.82510Z,1325723603.8251 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-05T00:33:23.82550Z,1325723603.8255 [Default:GPS:B.GoToSurface] Stopped
2012-01-05T00:33:23.82560Z,1325723603.8256 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:33:23.82570Z,1325723603.8257 [Default:GPS:Read_GPS] Running Loop=1
2012-01-05T00:33:24.26180Z,1325723604.2618 [DAT](INFO): Powering down
2012-01-05T00:33:24.28620Z,1325723604.2862 [Default:Iridium] Running Loop=1
2012-01-05T00:33:24.28640Z,1325723604.2864 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-05T00:33:24.28650Z,1325723604.2865 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-05T00:33:24.28650Z,1325723604.2865 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:33:24.28680Z,1325723604.2868 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-05T00:33:24.28690Z,1325723604.2869 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:33:24.28750Z,1325723604.2875 [Default:Iridium:B.GoToSurface] Stopped
2012-01-05T00:33:24.28760Z,1325723604.2876 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:33:24.28770Z,1325723604.2877 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-05T00:33:24.60830Z,1325723604.6083 [NAL9601](INFO): Powering up
2012-01-05T00:34:30.31920Z,1325723670.3192 [NAL9601](INFO): NAL9601 initialized
2012-01-05T00:34:31.43950Z,1325723671.4395 [NAL9601](IMPORTANT): GPS fix at: 1325723688
2012-01-05T00:34:31.50550Z,1325723671.5055 [Default:GPS:Read_GPS] Stopped
2012-01-05T00:34:31.50590Z,1325723671.5059 [Default:GPS](INFO): Completed Default:GPS
2012-01-05T00:34:31.50600Z,1325723671.506 [Default:GPS] Stopped
2012-01-05T00:34:31.50610Z,1325723671.5061 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-05T00:34:31.50620Z,1325723671.5062 [Default:GPS:A.SetSpeed] Stopped
2012-01-05T00:34:31.50630Z,1325723671.5063 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:34:31.82100Z,1325723671.821 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-05T00:34:31.82110Z,1325723671.8211 [Default:CallGPS:A] Stopped
2012-01-05T00:34:31.82120Z,1325723671.8212 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-05T00:34:31.82140Z,1325723671.8214 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-05T00:34:31.82150Z,1325723671.8215 [Default:CallGPS] Stopped
2012-01-05T00:34:31.82170Z,1325723671.8217 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-05T00:34:32.22970Z,1325723672.2297 [Default:CallGPS] Running Loop=1
2012-01-05T00:34:32.22980Z,1325723672.2298 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-05T00:34:32.23000Z,1325723672.23 [Default:CallGPS:A] Running Loop=1
2012-01-05T00:34:32.23010Z,1325723672.2301 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-05T00:34:32.62120Z,1325723672.6212 [Default:GPS] Running Loop=1
2012-01-05T00:34:32.62140Z,1325723672.6214 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-05T00:34:32.62150Z,1325723672.6215 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-05T00:34:32.62150Z,1325723672.6215 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:34:32.62170Z,1325723672.6217 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-05T00:34:32.62180Z,1325723672.6218 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:34:32.62240Z,1325723672.6224 [Default:GPS:B.GoToSurface] Stopped
2012-01-05T00:34:32.62250Z,1325723672.6225 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:34:32.62270Z,1325723672.6227 [Default:GPS:Read_GPS] Running Loop=1
2012-01-05T00:34:55.70560Z,1325723695.7056 [NAL9601](INFO): SBD MO Status=1, MOMSN=40286, MT Status=0, MTMSN=0
2012-01-05T00:34:55.86720Z,1325723695.8672 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0009.lzma
2012-01-05T00:34:55.86740Z,1325723695.8674 [NAL9601](INFO): Packets left to send: 1
2012-01-05T00:34:55.86860Z,1325723695.8686 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000069
2012-01-05T00:35:02.18560Z,1325723702.1856 [NAL9601](INFO): SBD MO Status=1, MOMSN=40287, MT Status=0, MTMSN=0
2012-01-05T00:35:02.35910Z,1325723702.3591 [NAL9601](INFO): Sent 59 bytes from file Logs/20120104T230740/shore0009.lzma
2012-01-05T00:35:02.35940Z,1325723702.3594 [NAL9601](INFO): Packets left to send: 0
2012-01-05T00:35:02.36060Z,1325723702.3606 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000070
2012-01-05T00:35:11.38120Z,1325723711.3812 [NAL9601](INFO): SBD MO Status=0, MOMSN=40288, MT Status=0, MTMSN=0
2012-01-05T00:35:11.55630Z,1325723711.5563 [Default:Iridium:Read_Iridium] Stopped
2012-01-05T00:35:11.55680Z,1325723711.5568 [Default:Iridium](INFO): Completed Default:Iridium
2012-01-05T00:35:11.55690Z,1325723711.5569 [Default:Iridium] Stopped
2012-01-05T00:35:11.55700Z,1325723711.557 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-05T00:35:11.55710Z,1325723711.5571 [Default:Iridium:A.SetSpeed] Stopped
2012-01-05T00:35:11.55720Z,1325723711.5572 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:35:11.55740Z,1325723711.5574 [Default:G.Wait] Running Loop=1
2012-01-05T00:35:11.55740Z,1325723711.5574 [Default:G.Wait](DEBUG): Initialize Wait Component.
2012-01-05T00:35:11.84080Z,1325723711.8408 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2012-01-05T00:35:11.84090Z,1325723711.8409 [Default:CallIridium:A] Stopped
2012-01-05T00:35:11.84110Z,1325723711.8411 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-05T00:35:11.84130Z,1325723711.8413 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-01-05T00:35:11.84140Z,1325723711.8414 [Default:CallIridium] Stopped
2012-01-05T00:35:11.84150Z,1325723711.8415 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-05T00:35:12.58320Z,1325723712.5832 [NAL9601](IMPORTANT): GPS fix at: 1325723729
2012-01-05T00:35:12.60250Z,1325723712.6025 [Default:GPS:Read_GPS] Stopped
2012-01-05T00:35:12.60300Z,1325723712.603 [Default:GPS](INFO): Completed Default:GPS
2012-01-05T00:35:12.60310Z,1325723712.6031 [Default:GPS] Stopped
2012-01-05T00:35:12.60320Z,1325723712.6032 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-05T00:35:12.60330Z,1325723712.6033 [Default:GPS:A.SetSpeed] Stopped
2012-01-05T00:35:12.60340Z,1325723712.6034 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:35:12.99830Z,1325723712.9983 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-05T00:35:12.99840Z,1325723712.9984 [Default:CallGPS:A] Stopped
2012-01-05T00:35:12.99850Z,1325723712.9985 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-05T00:35:12.99880Z,1325723712.9988 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-05T00:35:12.99880Z,1325723712.9988 [Default:CallGPS] Stopped
2012-01-05T00:35:12.99900Z,1325723712.999 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-05T00:35:33.17620Z,1325723733.1762 [NAL9601](INFO): Powering down
2012-01-05T00:37:38.09190Z,1325723858.0919 [Batt_Ocean_Server](INFO): Over Temperature Alarm! Battery Bank #7 STATUS: 5911
2012-01-05T00:37:38.09230Z,1325723858.0923 [Batt_Ocean_Server](INFO): Not Initialized - Battery Bank #7 STATUS: 5911
2012-01-05T00:40:13.19000Z,1325724013.19 [Default:CallIridium] Running Loop=1
2012-01-05T00:40:13.19010Z,1325724013.1901 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-01-05T00:40:13.19030Z,1325724013.1903 [Default:CallIridium:A] Running Loop=1
2012-01-05T00:40:13.19040Z,1325724013.1904 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2012-01-05T00:40:13.19060Z,1325724013.1906 [Default:CallGPS] Running Loop=1
2012-01-05T00:40:13.19070Z,1325724013.1907 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-05T00:40:13.19090Z,1325724013.1909 [Default:CallGPS:A] Running Loop=1
2012-01-05T00:40:13.19100Z,1325724013.191 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-05T00:40:18.13270Z,1325724018.1327 [Default:Iridium] Running Loop=1
2012-01-05T00:40:18.13280Z,1325724018.1328 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-01-05T00:40:18.13290Z,1325724018.1329 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-01-05T00:40:18.13300Z,1325724018.133 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:40:18.13320Z,1325724018.1332 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-01-05T00:40:18.13330Z,1325724018.1333 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:40:18.13390Z,1325724018.1339 [Default:Iridium:B.GoToSurface] Stopped
2012-01-05T00:40:18.13400Z,1325724018.134 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:40:18.13410Z,1325724018.1341 [Default:Iridium:Read_Iridium] Running Loop=1
2012-01-05T00:40:18.13450Z,1325724018.1345 [Default:GPS] Running Loop=1
2012-01-05T00:40:18.13470Z,1325724018.1347 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-05T00:40:18.13480Z,1325724018.1348 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-05T00:40:18.13490Z,1325724018.1349 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:40:18.13510Z,1325724018.1351 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-05T00:40:18.13510Z,1325724018.1351 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:40:18.13580Z,1325724018.1358 [Default:GPS:B.GoToSurface] Stopped
2012-01-05T00:40:18.13590Z,1325724018.1359 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:40:18.13600Z,1325724018.136 [Default:GPS:Read_GPS] Running Loop=1
2012-01-05T00:40:18.79640Z,1325724018.7964 [NAL9601](INFO): Powering up
2012-01-05T00:41:24.60720Z,1325724084.6072 [NAL9601](INFO): NAL9601 initialized
2012-01-05T00:41:25.71940Z,1325724085.7194 [NAL9601](IMPORTANT): GPS fix at: 1325724102
2012-01-05T00:41:25.74550Z,1325724085.7455 [Default:GPS:Read_GPS] Stopped
2012-01-05T00:41:25.74590Z,1325724085.7459 [Default:GPS](INFO): Completed Default:GPS
2012-01-05T00:41:25.74600Z,1325724085.746 [Default:GPS] Stopped
2012-01-05T00:41:25.74610Z,1325724085.7461 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-05T00:41:25.74620Z,1325724085.7462 [Default:GPS:A.SetSpeed] Stopped
2012-01-05T00:41:25.74620Z,1325724085.7462 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:41:26.15140Z,1325724086.1514 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2012-01-05T00:41:26.15150Z,1325724086.1515 [Default:CallGPS:A] Stopped
2012-01-05T00:41:26.15160Z,1325724086.1516 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-05T00:41:26.15190Z,1325724086.1519 [Default:CallGPS](INFO): Completed Default:CallGPS
2012-01-05T00:41:26.15190Z,1325724086.1519 [Default:CallGPS] Stopped
2012-01-05T00:41:26.15210Z,1325724086.1521 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-05T00:41:26.53720Z,1325724086.5372 [Default:CallGPS] Running Loop=1
2012-01-05T00:41:26.53740Z,1325724086.5374 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2012-01-05T00:41:26.53760Z,1325724086.5376 [Default:CallGPS:A] Running Loop=1
2012-01-05T00:41:26.53770Z,1325724086.5377 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2012-01-05T00:41:26.99520Z,1325724086.9952 [Default:GPS] Running Loop=1
2012-01-05T00:41:26.99540Z,1325724086.9954 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-05T00:41:26.99550Z,1325724086.9955 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-05T00:41:26.99560Z,1325724086.9956 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-05T00:41:26.99580Z,1325724086.9958 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-05T00:41:26.99590Z,1325724086.9959 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:41:26.99660Z,1325724086.9966 [Default:GPS:B.GoToSurface] Stopped
2012-01-05T00:41:26.99660Z,1325724086.9966 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:41:26.99680Z,1325724086.9968 [Default:GPS:Read_GPS] Running Loop=1
2012-01-05T00:41:50.50010Z,1325724110.5001 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=40289, MT Status=1, MTMSN=3354
2012-01-05T00:41:50.65520Z,1325724110.6552 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0010.lzma
2012-01-05T00:41:50.65540Z,1325724110.6554 [NAL9601](INFO): Packets left to send: 5
2012-01-05T00:41:50.65660Z,1325724110.6566 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000071
2012-01-05T00:41:51.30780Z,1325724111.3078 [NAL9601](INFO): Received command:load Engineering/Homing_altitude.xml;set homing_altitude.dockBearing 348.5 degree;run 
2012-01-05T00:41:51.33120Z,1325724111.3312 [CommandLine](IMPORTANT): got command load ./Missions/Engineering/Homing_altitude.xml
2012-01-05T00:41:51.33150Z,1325724111.3315 [MissionManager](INFO): Loading Mission: ./Missions/Engineering/Homing_altitude.xml
2012-01-05T00:41:51.38560Z,1325724111.3856 [MissionManager](INFO): DefineArg homing_altitude.Wpt1Lat = 36.8134 arcdeg
2012-01-05T00:41:51.38870Z,1325724111.3887 [MissionManager](INFO): DefineArg homing_altitude.Wpt1Lon = -121.827 arcdeg
2012-01-05T00:41:51.39170Z,1325724111.3917 [MissionManager](INFO): DefineArg homing_altitude.Altitude = 10 m
2012-01-05T00:41:51.39470Z,1325724111.3947 [MissionManager](INFO): DefineArg homing_altitude.Speed = 1 m/s
2012-01-05T00:41:51.39810Z,1325724111.3981 [MissionManager](INFO): DefineArg homing_altitude.MassDefault = 0.0015 n/a
2012-01-05T00:41:51.40140Z,1325724111.4014 [MissionManager](INFO): DefineArg homing_altitude.BuoyancyNeutral = 0.000418 n/a
2012-01-05T00:41:51.40510Z,1325724111.4051 [MissionManager](INFO): DefineArg homing_altitude.dockBearing = 10 arcdeg
2012-01-05T00:41:51.40810Z,1325724111.4081 [MissionManager](INFO): DefineArg homing_altitude.inTrkOffset = 0 m
2012-01-05T00:41:51.41120Z,1325724111.4112 [MissionManager](INFO): DefineArg homing_altitude.xTrkOffset = 0 m
2012-01-05T00:41:51.41420Z,1325724111.4142 [MissionManager](INFO): DefineArg homing_altitude.finalApproach = 200 m
2012-01-05T00:41:51.41730Z,1325724111.4173 [MissionManager](INFO): DefineArg homing_altitude.clusterRadius = 20 m
2012-01-05T00:41:51.42050Z,1325724111.4205 [MissionManager](INFO): DefineArg homing_altitude.kpAltitude = -0.08 n/a
2012-01-05T00:41:51.42350Z,1325724111.4235 [MissionManager](INFO): DefineArg homing_altitude.kiAltitude = 0 n/a
2012-01-05T00:41:51.42640Z,1325724111.4264 [MissionManager](INFO): DefineArg homing_altitude.kdAltitude = 0 n/a
2012-01-05T00:41:51.42810Z,1325724111.4281 [homing_altitude:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-01-05T00:41:51.43790Z,1325724111.4379 [homing_altitude:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-01-05T00:41:51.44580Z,1325724111.4458 [homing_altitude:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2012-01-05T00:41:51.45440Z,1325724111.4544 [MissionManager](INFO): Inserting Stack: Missions/Insert/Surface.xml
2012-01-05T00:41:51.47190Z,1325724111.4719 [MissionManager](INFO): DefineArg homing_altitude:SURFACECOMMS.SurfaceDepthRate = nan m/s
2012-01-05T00:41:51.47480Z,1325724111.4748 [MissionManager](INFO): DefineArg homing_altitude:SURFACECOMMS.SurfacePitch = nan arcdeg
2012-01-05T00:41:51.47780Z,1325724111.4778 [MissionManager](INFO): DefineArg homing_altitude:SURFACECOMMS.SurfaceSpeed = 0.5 m/s
2012-01-05T00:41:51.48100Z,1325724111.481 [MissionManager](INFO): DefineArg homing_altitude:SURFACECOMMS.IridiumTimeout = 30 min
2012-01-05T00:41:51.48220Z,1325724111.4822 [homing_altitude:SURFACECOMMS:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-01-05T00:41:51.49340Z,1325724111.4934 [homing_altitude:WaypointOne:A.Pitch](DEBUG): Construct.
2012-01-05T00:41:51.50190Z,1325724111.5019 [homing_altitude:WaypointOne:B.Buoyancy](DEBUG): Construct Buoyancy.
2012-01-05T00:41:51.50590Z,1325724111.5059 [homing_altitude:WaypointOne:C.SetSpeed](DEBUG): Construct.
2012-01-05T00:41:51.50940Z,1325724111.5094 [homing_altitude:WaypointOne:D.PitchServo](DEBUG): Construct.
2012-01-05T00:41:51.53790Z,1325724111.5379 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Construct Waypoint.
2012-01-05T00:41:51.54210Z,1325724111.5421 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Construct Homing.
2012-01-05T00:41:51.56520Z,1325724111.5652 [homing_altitude:H.Execute](DEBUG): Construct Execute.
2012-01-05T00:41:51.57300Z,1325724111.573 [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="homing_altitude">

<!-- Wpt1 d=74m; Wpt2 d=75m; Wpt3 d=77m -->

    <DefineArg Name="Wpt1Lat"><Units:degree/><Value>36.8134</Value></DefineArg>

    <DefineArg Name="Wpt1Lon"><Units:degree/><Value>-121.827</Value></DefineArg>

    <DefineArg Name="Altitude"><Units:meter/><Value>10</Value></DefineArg>

    <DefineArg Name="Speed"><Units:meter_per_second/><Value>1</Value></DefineArg>

    <DefineArg Name="MassDefault"><CustomUri Uri="Config/Control.massDefault"/></DefineArg>

    <DefineArg Name="BuoyancyNeutral"><CustomUri Uri="Config/Control.buoyancyNeutral"/></DefineArg>

    <DefineArg Name="dockBearing"><Units:degree/><Value>10</Value></DefineArg>

    <DefineArg Name="inTrkOffset"><Units:meter/><Value>0</Value></DefineArg>

    <DefineArg Name="xTrkOffset"><Units:meter/><Value>0</Value></DefineArg>

    <DefineArg Name="finalApproach"><Units:meter/><Value>200</Value></DefineArg>

    <DefineArg Name="clusterRadius"><Units:meter/><Value>20</Value></DefineArg>

    <DefineArg Name="kpAltitude"><Description>
        PID loop parameter for following the bottom.
    </Description><Units:none/><Value>-0.08</Value></DefineArg>

    <DefineArg Name="kiAltitude"><Description>
        PID loop parameter for following the bottom.
    </Description><Units:none/><Value>0</Value></DefineArg>

    <DefineArg Name="kdAltitude"><Description>
        PID loop parameter for following the bottom.
    </Description><Units:none/><Value>0</Value></DefineArg>

    <Timeout Duration="P40.0M"/>

    <Guidance:AltitudeEnvelope RunIn="Parallel">
        <Setting><Guidance:AltitudeEnvelope.minAltitude/><Units:meter/><Value>7</Value></Setting>
    </Guidance:AltitudeEnvelope>

    <Guidance:DepthEnvelope RunIn="Parallel">
        <Setting><Guidance:DepthEnvelope.minDepth/><Units:meter/><Value>0</Value></Setting>
        <Setting><Guidance:DepthEnvelope.maxDepth/><Units:meter/><Value>37</Value></Setting>
    </Guidance:DepthEnvelope>

    <Guidance:OffshoreEnvelope RunIn="Parallel">
        <Setting><Guidance:OffshoreEnvelope.minOffshore/><Units:kilometer/><Value>2.0</Value></Setting>
    </Guidance:OffshoreEnvelope>

    <ReadData Strategy="AllDevices">
        <Universal:platform_orientation/>
    </ReadData>

    <Insert Filename="Insert/Surface.xml" Id="SURFACECOMMS" />

    <Aggregate Id="WaypointOne">

<!-- Home to Wpt1  -->

        <Guidance:Pitch RunIn="Parallel">
            <Setting><Guidance:Pitch.massPosition/><Arg Name="MassDefault"/></Setting>
        </Guidance:Pitch>

        <Guidance:Buoyancy RunIn="Parallel">
            <Setting><Guidance:Buoyancy.position /><Arg Name="BuoyancyNeutral"/></Setting>
        </Guidance:Buoyancy>

        <Guidance:SetSpeed RunIn="Parallel">
            <Setting><Guidance:SetSpeed.speed/><Units:meter_per_second/><Value>1</Value></Setting>
        </Guidance:SetSpeed>

        <Guidance:PitchServo RunIn="Parallel">
            <Setting>
            <Guidance:PitchServo.uri/><Universal:height_above_sea_floor/></Setting>
            <Setting><Guidance:PitchServo.holdValue/><Arg Name="Altitude"/></Setting>
            <Setting><Guidance:PitchServo.proportionalGain/><Arg Name="kpAltitude"/></Setting>
            <Setting><Guidance:PitchServo.integralGain/><Arg Name="kiAltitude"/></Setting>
            <Setting><Guidance:PitchServo.derivativeGain/><Arg Name="kdAltitude"/></Setting>
            <Setting><Guidance:PitchServo.changePerMeter/><Units:meter/><Value>-1</Value></Setting>
        </Guidance:PitchServo>

        <Guidance:Homing Id="WaypointW1" RunIn="Sequence">
            <Setting><Guidance:Homing.dockBearing/><Arg Name="dockBearing"/></Setting>
            <Setting><Guidance:Homing.inTrkOffset/><Arg Name="inTrkOffset"/></Setting>
            <Setting><Guidance:Homing.xTrkOffset/><Arg Name="xTrkOffset"/></Setting>
            <Setting><Guidance:Homing.finalApproach/><Arg Name="finalApproach"/></Setting>
            <Setting><Guidance:Homing.clusterRadius/><Arg Name="clusterRadius"/></Setting>
            <Setting><Guidance:Homing.latitude/><Arg Name="Wpt1Lat"/></Setting>
            <Setting><Guidance:Homing.longitude/><Arg Name="Wpt1Lon"/></Setting>
        </Guidance:Homing>

    </Aggregate>

    <Call Id="PHONEHOMEWPT1" RefId="SURFACECOMMS"/>

    <Guidance:Execute RunIn="Sequence">
        <Setting>
        <Guidance:Execute.command/><String>restart logs</String></Setting>
    </Guidance:Execute>

</Mission>


2012-01-05T00:41:51.57350Z,1325724111.5735 [CommandLine](IMPORTANT): Loaded ./Missions/Engineering/Homing_altitude.xml
2012-01-05T00:41:51.69840Z,1325724111.6984 [CommandLine](IMPORTANT): got command set homing_altitude.dockBearing 348.5 degree
2012-01-05T00:41:51.69980Z,1325724111.6998 [CommandLine](IMPORTANT): got command run 
2012-01-05T00:41:51.70000Z,1325724111.7 [CommandLine](IMPORTANT): Running 
2012-01-05T00:41:51.71260Z,1325724111.7126 [Default] Stopped
2012-01-05T00:41:51.71280Z,1325724111.7128 [Default](INFO): Aggregate::uninitialize Default
2012-01-05T00:41:51.71290Z,1325724111.7129 [Default:GPS] Stopped
2012-01-05T00:41:51.71300Z,1325724111.713 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-01-05T00:41:51.71310Z,1325724111.7131 [Default:GPS:A.SetSpeed] Stopped
2012-01-05T00:41:51.71320Z,1325724111.7132 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:41:51.71330Z,1325724111.7133 [Default:GPS:Read_GPS] Stopped
2012-01-05T00:41:51.71330Z,1325724111.7133 [Default:Iridium] Stopped
2012-01-05T00:41:51.71340Z,1325724111.7134 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-01-05T00:41:51.71350Z,1325724111.7135 [Default:Iridium:A.SetSpeed] Stopped
2012-01-05T00:41:51.71360Z,1325724111.7136 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:41:51.71370Z,1325724111.7137 [Default:Iridium:Read_Iridium] Stopped
2012-01-05T00:41:51.71370Z,1325724111.7137 [Default:CallGPS] Stopped
2012-01-05T00:41:51.71380Z,1325724111.7138 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2012-01-05T00:41:51.71390Z,1325724111.7139 [Default:CallGPS:A] Stopped
2012-01-05T00:41:51.71400Z,1325724111.714 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2012-01-05T00:41:51.71410Z,1325724111.7141 [Default:CallIridium] Stopped
2012-01-05T00:41:51.71420Z,1325724111.7142 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-01-05T00:41:51.71430Z,1325724111.7143 [Default:CallIridium:A] Stopped
2012-01-05T00:41:51.71440Z,1325724111.7144 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2012-01-05T00:41:51.71450Z,1325724111.7145 [Default:E.SetSpeed] Stopped
2012-01-05T00:41:51.71460Z,1325724111.7146 [Default:E.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:41:51.71470Z,1325724111.7147 [Default:F.GoToSurface] Stopped
2012-01-05T00:41:51.71480Z,1325724111.7148 [Default:F.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:41:51.71490Z,1325724111.7149 [Default:G.Wait] Stopped
2012-01-05T00:41:51.71490Z,1325724111.7149 [Default:G.Wait](DEBUG): Uninitialize Wait Component.
2012-01-05T00:41:51.71510Z,1325724111.7151 [MissionManager](IMPORTANT): Started mission homing_altitude
2012-01-05T00:41:51.71520Z,1325724111.7152 [homing_altitude] Running Loop=1
2012-01-05T00:41:51.71530Z,1325724111.7153 [homing_altitude](INFO): Aggregate::initialize homing_altitude
2012-01-05T00:41:51.71540Z,1325724111.7154 [homing_altitude:A.AltitudeEnvelope] Running Loop=1
2012-01-05T00:41:51.71550Z,1325724111.7155 [homing_altitude:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-01-05T00:41:51.71560Z,1325724111.7156 [homing_altitude:B.DepthEnvelope] Running Loop=1
2012-01-05T00:41:51.71570Z,1325724111.7157 [homing_altitude:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-01-05T00:41:51.71700Z,1325724111.717 [homing_altitude:C.OffshoreEnvelope] Running Loop=1
2012-01-05T00:41:51.71710Z,1325724111.7171 [homing_altitude:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2012-01-05T00:41:51.71720Z,1325724111.7172 [homing_altitude:D] Running Loop=1
2012-01-05T00:41:51.71740Z,1325724111.7174 [homing_altitude:SURFACECOMMS] Running Loop=1
2012-01-05T00:41:51.71750Z,1325724111.7175 [homing_altitude:SURFACECOMMS](INFO): Aggregate::initialize homing_altitude:SURFACECOMMS
2012-01-05T00:41:51.71760Z,1325724111.7176 [homing_altitude:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-01-05T00:41:51.71770Z,1325724111.7177 [homing_altitude:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:41:51.72330Z,1325724111.7233 [homing_altitude:SURFACECOMMS:B] Running Loop=1
2012-01-05T00:41:51.72340Z,1325724111.7234 [homing_altitude:SURFACECOMMS:B](INFO): Aggregate::initialize homing_altitude:SURFACECOMMS:B
2012-01-05T00:41:51.72370Z,1325724111.7237 [homing_altitude:SURFACECOMMS:B:A] Running Loop=1
2012-01-05T00:41:51.72380Z,1325724111.7238 [homing_altitude:D] Running Loop=1
2012-01-05T00:41:51.72440Z,1325724111.7244 [homing_altitude:D](DEBUG): Initialize ReadDataComponent to sense platform_orientation
2012-01-05T00:41:51.72580Z,1325724111.7258 [homing_altitude:C.OffshoreEnvelope] Running Loop=1
2012-01-05T00:41:51.73050Z,1325724111.7305 [homing_altitude:B.DepthEnvelope] Running Loop=1
2012-01-05T00:41:51.73530Z,1325724111.7353 [homing_altitude:A.AltitudeEnvelope] Running Loop=1
2012-01-05T00:41:52.12360Z,1325724112.1236 [homing_altitude:SURFACECOMMS:B:A](DEBUG): Initialize ReadDataComponent to sense time_fix
2012-01-05T00:41:54.11510Z,1325724114.1151 [NAL9601](IMPORTANT): GPS fix at: 1325724131
2012-01-05T00:41:54.12870Z,1325724114.1287 [homing_altitude:SURFACECOMMS:B:A] Stopped
2012-01-05T00:41:54.12890Z,1325724114.1289 [homing_altitude:SURFACECOMMS:B:B] Running Loop=1
2012-01-05T00:41:54.51920Z,1325724114.5192 [homing_altitude:SURFACECOMMS:B:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-01-05T00:42:12.15120Z,1325724132.1512 [NAL9601](INFO): SBD MO Status=1, MOMSN=40290, MT Status=0, MTMSN=0
2012-01-05T00:42:12.32310Z,1325724132.3231 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0010.lzma
2012-01-05T00:42:12.32340Z,1325724132.3234 [NAL9601](INFO): Packets left to send: 4
2012-01-05T00:42:12.32450Z,1325724132.3245 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000072
2012-01-05T00:42:21.10440Z,1325724141.1044 [NAL9601](INFO): SBD MO Status=1, MOMSN=40291, MT Status=0, MTMSN=0
2012-01-05T00:42:21.30720Z,1325724141.3072 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0010.lzma
2012-01-05T00:42:21.30750Z,1325724141.3075 [NAL9601](INFO): Packets left to send: 3
2012-01-05T00:42:21.53280Z,1325724141.5328 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000073
2012-01-05T00:42:32.63390Z,1325724152.6339 [NAL9601](INFO): SBD MO Status=1, MOMSN=40292, MT Status=0, MTMSN=0
2012-01-05T00:42:32.79130Z,1325724152.7913 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0010.lzma
2012-01-05T00:42:32.79150Z,1325724152.7915 [NAL9601](INFO): Packets left to send: 2
2012-01-05T00:42:32.79270Z,1325724152.7927 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000074
2012-01-05T00:42:40.48230Z,1325724160.4823 [NAL9601](INFO): SBD MO Status=1, MOMSN=40293, MT Status=0, MTMSN=0
2012-01-05T00:42:40.67920Z,1325724160.6792 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0010.lzma
2012-01-05T00:42:40.67940Z,1325724160.6794 [NAL9601](INFO): Packets left to send: 1
2012-01-05T00:42:40.68060Z,1325724160.6806 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000075
2012-01-05T00:42:46.50860Z,1325724166.5086 [NAL9601](INFO): SBD MO Status=1, MOMSN=40294, MT Status=0, MTMSN=0
2012-01-05T00:42:46.67120Z,1325724166.6712 [NAL9601](INFO): Sent 125 bytes from file Logs/20120104T230740/shore0010.lzma
2012-01-05T00:42:46.67140Z,1325724166.6714 [NAL9601](INFO): Packets left to send: 0
2012-01-05T00:42:46.67250Z,1325724166.6725 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000076
2012-01-05T00:42:53.33370Z,1325724173.3337 [NAL9601](INFO): SBD MO Status=0, MOMSN=40295, MT Status=0, MTMSN=0
2012-01-05T00:43:12.25210Z,1325724192.2521 [NAL9601](INFO): SBD MO Status=1, MOMSN=40296, MT Status=0, MTMSN=0
2012-01-05T00:43:12.42730Z,1325724192.4273 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0011.lzma
2012-01-05T00:43:12.42750Z,1325724192.4275 [NAL9601](INFO): Packets left to send: 2
2012-01-05T00:43:12.42870Z,1325724192.4287 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000077
2012-01-05T00:43:21.13450Z,1325724201.1345 [NAL9601](INFO): SBD MO Status=1, MOMSN=40297, MT Status=0, MTMSN=0
2012-01-05T00:43:21.31520Z,1325724201.3152 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0011.lzma
2012-01-05T00:43:21.31540Z,1325724201.3154 [NAL9601](INFO): Packets left to send: 1
2012-01-05T00:43:21.31680Z,1325724201.3168 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000078
2012-01-05T00:43:27.60980Z,1325724207.6098 [NAL9601](INFO): SBD MO Status=1, MOMSN=40298, MT Status=0, MTMSN=0
2012-01-05T00:43:27.80330Z,1325724207.8033 [NAL9601](INFO): Sent 15 bytes from file Logs/20120104T230740/shore0011.lzma
2012-01-05T00:43:27.80350Z,1325724207.8035 [NAL9601](INFO): Packets left to send: 0
2012-01-05T00:43:27.80470Z,1325724207.8047 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000079
2012-01-05T00:43:36.41780Z,1325724216.4178 [NAL9601](INFO): SBD MO Status=0, MOMSN=40299, MT Status=0, MTMSN=0
2012-01-05T00:43:36.60400Z,1325724216.604 [homing_altitude:SURFACECOMMS:B:B] Stopped
2012-01-05T00:43:36.60420Z,1325724216.6042 [homing_altitude:SURFACECOMMS:B:C] Running Loop=1
2012-01-05T00:43:36.81650Z,1325724216.8165 [homing_altitude:SURFACECOMMS:B:C](DEBUG): Initialize ReadDataComponent to sense time_fix
2012-01-05T00:43:38.82360Z,1325724218.8236 [NAL9601](IMPORTANT): GPS fix at: 1325724236
2012-01-05T00:43:38.83760Z,1325724218.8376 [homing_altitude:SURFACECOMMS:B:C] Stopped
2012-01-05T00:43:38.83780Z,1325724218.8378 [homing_altitude:SURFACECOMMS:B](INFO): Completed homing_altitude:SURFACECOMMS:B
2012-01-05T00:43:38.83790Z,1325724218.8379 [homing_altitude:SURFACECOMMS:B] Stopped
2012-01-05T00:43:38.83810Z,1325724218.8381 [homing_altitude:SURFACECOMMS:B](INFO): Aggregate::uninitialize homing_altitude:SURFACECOMMS:B
2012-01-05T00:43:38.85870Z,1325724218.8587 [homing_altitude:SURFACECOMMS](INFO): Completed homing_altitude:SURFACECOMMS
2012-01-05T00:43:38.85880Z,1325724218.8588 [homing_altitude:SURFACECOMMS] Stopped
2012-01-05T00:43:38.85900Z,1325724218.859 [homing_altitude:SURFACECOMMS](INFO): Aggregate::uninitialize homing_altitude:SURFACECOMMS
2012-01-05T00:43:38.85900Z,1325724218.859 [homing_altitude:SURFACECOMMS:A.GoToSurface] Stopped
2012-01-05T00:43:38.85910Z,1325724218.8591 [homing_altitude:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T00:43:38.85930Z,1325724218.8593 [homing_altitude:WaypointOne] Running Loop=1
2012-01-05T00:43:38.85940Z,1325724218.8594 [homing_altitude:WaypointOne](INFO): Aggregate::initialize homing_altitude:WaypointOne
2012-01-05T00:43:38.85950Z,1325724218.8595 [homing_altitude:WaypointOne:A.Pitch] Running Loop=1
2012-01-05T00:43:38.85960Z,1325724218.8596 [homing_altitude:WaypointOne:A.Pitch](DEBUG): Initialize.
2012-01-05T00:43:38.85980Z,1325724218.8598 [homing_altitude:WaypointOne:B.Buoyancy] Running Loop=1
2012-01-05T00:43:38.85990Z,1325724218.8599 [homing_altitude:WaypointOne:B.Buoyancy](DEBUG): Initialize Buoyancy Component.
2012-01-05T00:43:38.86030Z,1325724218.8603 [homing_altitude:WaypointOne:C.SetSpeed] Running Loop=1
2012-01-05T00:43:38.86040Z,1325724218.8604 [homing_altitude:WaypointOne:C.SetSpeed](DEBUG): Initialize.
2012-01-05T00:43:38.86050Z,1325724218.8605 [homing_altitude:WaypointOne:D.PitchServo] Running Loop=1
2012-01-05T00:43:38.86060Z,1325724218.8606 [homing_altitude:WaypointOne:D.PitchServo](DEBUG): Initialize.
2012-01-05T00:43:38.86090Z,1325724218.8609 [homing_altitude:WaypointOne:D.PitchServo](INFO): Initialize with holdValue=height_above_sea_floor
2012-01-05T00:43:38.86180Z,1325724218.8618 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint] Running Loop=1
2012-01-05T00:43:38.86190Z,1325724218.8619 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Initialize HomingComponent.
2012-01-05T00:43:38.86210Z,1325724218.8621 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Initialize WaypointComponent.
2012-01-05T00:43:39.29170Z,1325724219.2917 [homing_altitude:WaypointOne:D.PitchServo] Running Loop=1
2012-01-05T00:43:39.29640Z,1325724219.2964 [homing_altitude:WaypointOne:C.SetSpeed] Running Loop=1
2012-01-05T00:43:39.30100Z,1325724219.301 [homing_altitude:WaypointOne:B.Buoyancy] Running Loop=1
2012-01-05T00:43:39.30590Z,1325724219.3059 [homing_altitude:WaypointOne:A.Pitch] Running Loop=1
2012-01-05T00:43:45.29600Z,1325724225.296 [NAL9601](INFO): Powering down
2012-01-05T00:43:59.71770Z,1325724239.7177 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Homing:: Beacon is in the DAT FOV with dtw = 778.18. Turning DAT on.
2012-01-05T00:44:00.12070Z,1325724240.1207 [DAT](INFO): Powering up
2012-01-05T00:44:27.48270Z,1325724267.4827 [DAT](ERROR): No response from remote modem
2012-01-05T00:44:40.23870Z,1325724280.2387 [DAT](ERROR): No response from remote modem
2012-01-05T00:44:53.06670Z,1325724293.0667 [DAT](ERROR): No response from remote modem
2012-01-05T00:45:05.53870Z,1325724305.5387 [DAT](ERROR): No response from remote modem
2012-01-05T00:45:18.24670Z,1325724318.2467 [DAT](ERROR): No response from remote modem
2012-01-05T00:45:22.60640Z,1325724322.6064 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Homing:: The Usbl has 1 transponder hits.
2012-01-05T00:45:23.00470Z,1325724323.0047 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Homing:: Beacon has exited the DAT FOV with dtw = 511.74.  Turning DAT off.
2012-01-05T00:45:23.77520Z,1325724323.7752 [DAT](INFO): Powering down
2012-01-05T00:45:32.63650Z,1325724332.6365 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Homing:: Beacon is in the DAT FOV with dtw = 514.72. Turning DAT on.
2012-01-05T00:45:32.99900Z,1325724332.999 [DAT](INFO): Powering up
2012-01-05T00:45:52.63200Z,1325724352.632 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Homing:: The Usbl has 2 transponder hits.
2012-01-05T00:45:57.07710Z,1325724357.0771 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Homing:: The Usbl has 3 transponder hits.
2012-01-05T00:46:09.92270Z,1325724369.9227 [DAT](ERROR): No response from remote modem
2012-01-05T00:46:14.64070Z,1325724374.6407 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Homing:: The Usbl has 4 transponder hits.
2012-01-05T00:46:23.57760Z,1325724383.5776 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Homing:: The Usbl has 5 transponder hits; the filter is now engaged.
2012-01-05T00:46:23.57790Z,1325724383.5779 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Homing::  The vehicle lat,lon is (36.8194, -121.8304) with dtw = 486.9
2012-01-05T00:46:23.57920Z,1325724383.5792 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Homing:: Pure pursuit active. dtw = 486.5 m.
2012-01-05T00:47:24.83480Z,1325724444.8348 [DAT](ERROR): No response from remote modem
2012-01-05T00:47:59.28280Z,1325724479.2828 [DAT](ERROR): No response from remote modem
2012-01-05T00:48:12.03470Z,1325724492.0347 [DAT](ERROR): No response from remote modem
2012-01-05T00:48:24.45890Z,1325724504.4589 [DAT](ERROR): No response from remote modem
2012-01-05T00:48:37.23470Z,1325724517.2347 [DAT](ERROR): No response from remote modem
2012-01-05T00:48:49.63870Z,1325724529.6387 [DAT](ERROR): No response from remote modem
2012-01-05T00:49:02.47080Z,1325724542.4708 [DAT](ERROR): No response from remote modem
2012-01-05T00:49:14.87070Z,1325724554.8707 [DAT](ERROR): No response from remote modem
2012-01-05T00:49:27.32680Z,1325724567.3268 [DAT](ERROR): No response from remote modem
2012-01-05T00:49:39.87470Z,1325724579.8747 [DAT](ERROR): No response from remote modem
2012-01-05T00:49:52.69070Z,1325724592.6907 [DAT](ERROR): No response from remote modem
2012-01-05T00:50:05.06280Z,1325724605.0628 [DAT](ERROR): No response from remote modem
2012-01-05T00:50:17.85070Z,1325724617.8507 [DAT](ERROR): No response from remote modem
2012-01-05T00:50:30.24270Z,1325724630.2427 [DAT](ERROR): No response from remote modem
2012-01-05T00:50:43.04270Z,1325724643.0427 [DAT](ERROR): No response from remote modem
2012-01-05T00:50:55.84670Z,1325724655.8467 [DAT](ERROR): No response from remote modem
2012-01-05T00:51:08.64270Z,1325724668.6427 [DAT](ERROR): No response from remote modem
2012-01-05T00:51:21.07470Z,1325724681.0747 [DAT](ERROR): No response from remote modem
2012-01-05T00:51:33.85870Z,1325724693.8587 [DAT](ERROR): No response from remote modem
2012-01-05T00:51:46.65470Z,1325724706.6547 [DAT](ERROR): No response from remote modem
2012-01-05T00:51:59.45470Z,1325724719.4547 [DAT](ERROR): No response from remote modem
2012-01-05T00:52:11.86270Z,1325724731.8627 [DAT](ERROR): No response from remote modem
2012-01-05T00:52:24.51470Z,1325724744.5147 [DAT](ERROR): No response from remote modem
2012-01-05T00:52:37.22670Z,1325724757.2267 [DAT](ERROR): No response from remote modem
2012-01-05T00:52:42.82760Z,1325724762.8276 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Homing:: Cross-track control active. dtw = 199.8 m.
2012-01-05T00:52:49.66670Z,1325724769.6667 [DAT](ERROR): No response from remote modem
2012-01-05T00:53:02.48610Z,1325724782.4861 [DAT](ERROR): No response from remote modem
2012-01-05T00:53:14.94270Z,1325724794.9427 [DAT](ERROR): No response from remote modem
2012-01-05T00:53:27.38270Z,1325724807.3827 [DAT](ERROR): No response from remote modem
2012-01-05T00:53:39.95870Z,1325724819.9587 [DAT](ERROR): No response from remote modem
2012-01-05T00:53:52.72670Z,1325724832.7267 [DAT](ERROR): No response from remote modem
2012-01-05T00:54:05.19070Z,1325724845.1907 [DAT](ERROR): No response from remote modem
2012-01-05T00:54:17.61070Z,1325724857.6107 [DAT](ERROR): No response from remote modem
2012-01-05T00:54:30.75470Z,1325724870.7547 [DAT](ERROR): No response from remote modem
2012-01-05T00:54:43.55870Z,1325724883.5587 [DAT](ERROR): No response from remote modem
2012-01-05T00:54:45.12770Z,1325724885.1277 [Batt_Ocean_Server](INFO): Over Temperature Alarm! Battery Bank #1 STATUS: 5911
2012-01-05T00:54:45.12800Z,1325724885.128 [Batt_Ocean_Server](INFO): Not Initialized - Battery Bank #1 STATUS: 5911
2012-01-05T00:54:55.99070Z,1325724895.9907 [DAT](ERROR): No response from remote modem
2012-01-05T00:55:08.41870Z,1325724908.4187 [DAT](ERROR): No response from remote modem
2012-01-05T00:55:21.16670Z,1325724921.1667 [DAT](ERROR): No response from remote modem
2012-01-05T00:55:34.01470Z,1325724934.0147 [DAT](ERROR): No response from remote modem
2012-01-05T00:55:46.38670Z,1325724946.3867 [DAT](ERROR): No response from remote modem
2012-01-05T00:55:48.79900Z,1325724948.799 [ElevatorServo](FAULT): Overload Error
2012-01-05T00:55:48.79920Z,1325724948.7992 [ElevatorServo] Hardware Fault, FailCount= 1
2012-01-05T00:55:48.79920Z,1325724948.7992 [ElevatorServo](ERROR): Hardware Fault
2012-01-05T00:55:48.87310Z,1325724948.8731 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-01-05T00:55:49.11920Z,1325724949.1192 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-01-05T00:55:49.11940Z,1325724949.1194 [ElevatorServo](INFO): Powering down
2012-01-05T00:55:49.21260Z,1325724949.2126 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-01-05T00:55:49.21270Z,1325724949.2127 [ElevatorServo] No Fault, FailCount= 1
2012-01-05T00:55:49.91770Z,1325724949.9177 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-01-05T00:55:50.03570Z,1325724950.0357 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-01-05T00:55:58.76500Z,1325724958.765 [DAT](ERROR): No response from remote modem
2012-01-05T00:56:11.46670Z,1325724971.4667 [DAT](ERROR): No response from remote modem
2012-01-05T00:56:23.89070Z,1325724983.8907 [DAT](ERROR): No response from remote modem
2012-01-05T00:56:36.27070Z,1325724996.2707 [DAT](ERROR): No response from remote modem
2012-01-05T00:56:48.65470Z,1325725008.6547 [DAT](ERROR): No response from remote modem
2012-01-05T00:57:01.65080Z,1325725021.6508 [DAT](ERROR): No response from remote modem
2012-01-05T00:57:14.35480Z,1325725034.3548 [DAT](ERROR): No response from remote modem
2012-01-05T00:57:19.10710Z,1325725039.1071 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](IMPORTANT): Homing:: Terminating now. dtw = -0.2 m, DATRange = nan m.
2012-01-05T00:57:19.10780Z,1325725039.1078 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](INFO): Homing::Reached Waypoint 36.82339181,-121.8282482
2012-01-05T00:57:19.10800Z,1325725039.108 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint] Stopped
2012-01-05T00:57:19.10810Z,1325725039.1081 [homing_altitude:WaypointOne:WaypointW1.HomingWaypoint](DEBUG): Uninitialize HomingComponent.
2012-01-05T00:57:19.10950Z,1325725039.1095 [homing_altitude:WaypointOne](INFO): Completed homing_altitude:WaypointOne
2012-01-05T00:57:19.10960Z,1325725039.1096 [homing_altitude:WaypointOne] Stopped
2012-01-05T00:57:19.10970Z,1325725039.1097 [homing_altitude:WaypointOne](INFO): Aggregate::uninitialize homing_altitude:WaypointOne
2012-01-05T00:57:19.10980Z,1325725039.1098 [homing_altitude:WaypointOne:A.Pitch] Stopped
2012-01-05T00:57:19.10990Z,1325725039.1099 [homing_altitude:WaypointOne:B.Buoyancy] Stopped
2012-01-05T00:57:19.10990Z,1325725039.1099 [homing_altitude:WaypointOne:B.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2012-01-05T00:57:19.11000Z,1325725039.11 [homing_altitude:WaypointOne:C.SetSpeed] Stopped
2012-01-05T00:57:19.11010Z,1325725039.1101 [homing_altitude:WaypointOne:C.SetSpeed](DEBUG): Uninitialize.
2012-01-05T00:57:19.11010Z,1325725039.1101 [homing_altitude:WaypointOne:D.PitchServo] Stopped
2012-01-05T00:57:19.11020Z,1325725039.1102 [homing_altitude:WaypointOne:D.PitchServo](DEBUG): Uninitialize.
2012-01-05T00:57:19.11040Z,1325725039.1104 [homing_altitude:PHONEHOMEWPT1] Running Loop=1
2012-01-05T00:57:19.11050Z,1325725039.1105 [homing_altitude:PHONEHOMEWPT1](INFO): Aggregate::initialize homing_altitude:PHONEHOMEWPT1
2012-01-05T00:57:19.51240Z,1325725039.5124 [homing_altitude:SURFACECOMMS] Running Loop=1
2012-01-05T00:57:19.51260Z,1325725039.5126 [homing_altitude:SURFACECOMMS](INFO): Aggregate::initialize homing_altitude:SURFACECOMMS
2012-01-05T00:57:19.51270Z,1325725039.5127 [homing_altitude:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-01-05T00:57:19.51280Z,1325725039.5128 [homing_altitude:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T00:57:19.87840Z,1325725039.8784 [DAT](INFO): Powering down
2012-01-05T00:59:53.90160Z,1325725193.9016 [homing_altitude:SURFACECOMMS:B] Running Loop=1
2012-01-05T00:59:53.90170Z,1325725193.9017 [homing_altitude:SURFACECOMMS:B](INFO): Aggregate::initialize homing_altitude:SURFACECOMMS:B
2012-01-05T00:59:53.90190Z,1325725193.9019 [homing_altitude:SURFACECOMMS:B:A] Running Loop=1
2012-01-05T00:59:54.63780Z,1325725194.6378 [NAL9601](INFO): Powering up
2012-01-05T01:01:00.45120Z,1325725260.4512 [NAL9601](INFO): NAL9601 initialized
2012-01-05T01:01:01.47350Z,1325725261.4735 [NAL9601](IMPORTANT): GPS fix at: 1325725280
2012-01-05T01:01:01.48740Z,1325725261.4874 [homing_altitude:SURFACECOMMS:B:A] Stopped
2012-01-05T01:01:01.48770Z,1325725261.4877 [homing_altitude:SURFACECOMMS:B:B] Running Loop=1
2012-01-05T01:01:15.77940Z,1325725275.7794 [NAL9601](INFO): SBD MO Status=1, MOMSN=40300, MT Status=0, MTMSN=0
2012-01-05T01:01:15.91120Z,1325725275.9112 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0012.lzma
2012-01-05T01:01:15.91140Z,1325725275.9114 [NAL9601](INFO): Packets left to send: 9
2012-01-05T01:01:15.91270Z,1325725275.9127 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000080
2012-01-05T01:01:23.51780Z,1325725283.5178 [NAL9601](INFO): SBD MO Status=1, MOMSN=40301, MT Status=0, MTMSN=0
2012-01-05T01:01:23.69910Z,1325725283.6991 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0012.lzma
2012-01-05T01:01:23.69940Z,1325725283.6994 [NAL9601](INFO): Packets left to send: 8
2012-01-05T01:01:23.70060Z,1325725283.7006 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000081
2012-01-05T01:01:32.40070Z,1325725292.4007 [NAL9601](INFO): SBD MO Status=1, MOMSN=40302, MT Status=0, MTMSN=0
2012-01-05T01:01:32.58720Z,1325725292.5872 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0012.lzma
2012-01-05T01:01:32.58740Z,1325725292.5874 [NAL9601](INFO): Packets left to send: 7
2012-01-05T01:01:32.58860Z,1325725292.5886 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000082
2012-01-05T01:01:40.13420Z,1325725300.1342 [NAL9601](INFO): SBD MO Status=1, MOMSN=40303, MT Status=0, MTMSN=0
2012-01-05T01:01:40.27520Z,1325725300.2752 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0012.lzma
2012-01-05T01:01:40.27540Z,1325725300.2754 [NAL9601](INFO): Packets left to send: 6
2012-01-05T01:01:40.27740Z,1325725300.2774 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000083
2012-01-05T01:01:47.98310Z,1325725307.9831 [NAL9601](INFO): SBD MO Status=1, MOMSN=40304, MT Status=0, MTMSN=0
2012-01-05T01:01:48.16320Z,1325725308.1632 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0012.lzma
2012-01-05T01:01:48.16350Z,1325725308.1635 [NAL9601](INFO): Packets left to send: 5
2012-01-05T01:01:48.16470Z,1325725308.1647 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000084
2012-01-05T01:02:00.51770Z,1325725320.5177 [NAL9601](INFO): SBD MO Status=1, MOMSN=40305, MT Status=0, MTMSN=0
2012-01-05T01:02:00.64320Z,1325725320.6432 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0012.lzma
2012-01-05T01:02:00.64340Z,1325725320.6434 [NAL9601](INFO): Packets left to send: 4
2012-01-05T01:02:00.64460Z,1325725320.6446 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000085
2012-01-05T01:02:10.98560Z,1325725330.9856 [NAL9601](INFO): SBD MO Status=1, MOMSN=40306, MT Status=0, MTMSN=0
2012-01-05T01:02:11.12720Z,1325725331.1272 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0012.lzma
2012-01-05T01:02:11.12740Z,1325725331.1274 [NAL9601](INFO): Packets left to send: 3
2012-01-05T01:02:11.12860Z,1325725331.1286 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000086
2012-01-05T01:02:23.95950Z,1325725343.9595 [NAL9601](INFO): SBD MO Status=1, MOMSN=40307, MT Status=0, MTMSN=0
2012-01-05T01:02:24.10720Z,1325725344.1072 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0012.lzma
2012-01-05T01:02:24.10750Z,1325725344.1075 [NAL9601](INFO): Packets left to send: 2
2012-01-05T01:02:24.10880Z,1325725344.1088 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000087
2012-01-05T01:02:33.71940Z,1325725353.7194 [NAL9601](INFO): SBD MO Status=1, MOMSN=40308, MT Status=0, MTMSN=0
2012-01-05T01:02:33.89120Z,1325725353.8912 [NAL9601](INFO): Sent 332 bytes from file Logs/20120104T230740/shore0012.lzma
2012-01-05T01:02:33.89140Z,1325725353.8914 [NAL9601](INFO): Packets left to send: 1
2012-01-05T01:02:33.89260Z,1325725353.8926 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000088
2012-01-05T01:02:44.22030Z,1325725364.2203 [NAL9601](INFO): SBD MO Status=1, MOMSN=40309, MT Status=0, MTMSN=0
2012-01-05T01:02:44.37520Z,1325725364.3752 [NAL9601](INFO): Sent 49 bytes from file Logs/20120104T230740/shore0012.lzma
2012-01-05T01:02:44.37540Z,1325725364.3754 [NAL9601](INFO): Packets left to send: 0
2012-01-05T01:02:44.37670Z,1325725364.3767 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000089
2012-01-05T01:02:54.19780Z,1325725374.1978 [NAL9601](INFO): SBD MO Status=0, MOMSN=40310, MT Status=0, MTMSN=0
2012-01-05T01:02:54.37260Z,1325725374.3726 [homing_altitude:SURFACECOMMS:B:B] Stopped
2012-01-05T01:02:54.37280Z,1325725374.3728 [homing_altitude:SURFACECOMMS:B:C] Running Loop=1
2012-01-05T01:02:56.61340Z,1325725376.6134 [NAL9601](IMPORTANT): GPS fix at: 1325725395
2012-01-05T01:02:56.62710Z,1325725376.6271 [homing_altitude:SURFACECOMMS:B:C] Stopped
2012-01-05T01:02:56.62730Z,1325725376.6273 [homing_altitude:SURFACECOMMS:B](INFO): Completed homing_altitude:SURFACECOMMS:B
2012-01-05T01:02:56.62740Z,1325725376.6274 [homing_altitude:SURFACECOMMS:B] Stopped
2012-01-05T01:02:56.62750Z,1325725376.6275 [homing_altitude:SURFACECOMMS:B](INFO): Aggregate::uninitialize homing_altitude:SURFACECOMMS:B
2012-01-05T01:02:56.62810Z,1325725376.6281 [homing_altitude:SURFACECOMMS](INFO): Completed homing_altitude:SURFACECOMMS
2012-01-05T01:02:56.62820Z,1325725376.6282 [homing_altitude:SURFACECOMMS] Stopped
2012-01-05T01:02:56.62830Z,1325725376.6283 [homing_altitude:SURFACECOMMS](INFO): Aggregate::uninitialize homing_altitude:SURFACECOMMS
2012-01-05T01:02:56.62840Z,1325725376.6284 [homing_altitude:SURFACECOMMS:A.GoToSurface] Stopped
2012-01-05T01:02:56.62850Z,1325725376.6285 [homing_altitude:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T01:02:57.00470Z,1325725377.0047 [homing_altitude:PHONEHOMEWPT1](INFO): Completed homing_altitude:PHONEHOMEWPT1
2012-01-05T01:02:57.00480Z,1325725377.0048 [homing_altitude:PHONEHOMEWPT1] Stopped
2012-01-05T01:02:57.00500Z,1325725377.005 [homing_altitude:PHONEHOMEWPT1](INFO): Aggregate::uninitialize homing_altitude:PHONEHOMEWPT1
2012-01-05T01:02:57.00510Z,1325725377.0051 [homing_altitude:H.Execute] Running Loop=1
2012-01-05T01:02:57.42180Z,1325725377.4218 [homing_altitude:H.Execute](INFO): Executing command restart logs
2012-01-05T01:02:57.42740Z,1325725377.4274 [homing_altitude:H.Execute] Stopped
2012-01-05T01:02:57.42840Z,1325725377.4284 [homing_altitude](INFO): Completed homing_altitude
2012-01-05T01:02:57.42850Z,1325725377.4285 [homing_altitude] Stopped
2012-01-05T01:02:57.42860Z,1325725377.4286 [homing_altitude](INFO): Aggregate::uninitialize homing_altitude
2012-01-05T01:02:57.42870Z,1325725377.4287 [homing_altitude:A.AltitudeEnvelope] Stopped
2012-01-05T01:02:57.42880Z,1325725377.4288 [homing_altitude:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-01-05T01:02:57.42890Z,1325725377.4289 [homing_altitude:B.DepthEnvelope] Stopped
2012-01-05T01:02:57.42890Z,1325725377.4289 [homing_altitude:B.DepthEnvelope](DEBUG): Uninitialize.
2012-01-05T01:02:57.42900Z,1325725377.429 [homing_altitude:C.OffshoreEnvelope] Stopped
2012-01-05T01:02:57.42910Z,1325725377.4291 [homing_altitude:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2012-01-05T01:02:57.42910Z,1325725377.4291 [homing_altitude:D] Stopped
2012-01-05T01:02:57.50710Z,1325725377.5071 [CommandLine](IMPORTANT): got command restart logs
2012-01-05T01:02:57.86390Z,1325725377.8639 [MissionManager](IMPORTANT): Started mission Default
2012-01-05T01:02:57.86400Z,1325725377.864 [Default] Running Loop=1
2012-01-05T01:02:57.86420Z,1325725377.8642 [Default](INFO): Aggregate::initialize Default
2012-01-05T01:02:57.86430Z,1325725377.8643 [Default:E.SetSpeed] Running Loop=1
2012-01-05T01:02:57.86430Z,1325725377.8643 [Default:E.SetSpeed](DEBUG): Initialize.
2012-01-05T01:02:57.86450Z,1325725377.8645 [Default:F.GoToSurface] Running Loop=1
2012-01-05T01:02:57.86450Z,1325725377.8645 [Default:F.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T01:02:57.86500Z,1325725377.865 [Default:GPS] Running Loop=1
2012-01-05T01:02:57.86510Z,1325725377.8651 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-01-05T01:02:57.86520Z,1325725377.8652 [Default:GPS:A.SetSpeed] Running Loop=1
2012-01-05T01:02:57.86530Z,1325725377.8653 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-01-05T01:02:57.86550Z,1325725377.8655 [Default:GPS:B.GoToSurface] Running Loop=1
2012-01-05T01:02:57.86550Z,1325725377.8655 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-01-05T01:02:57.86730Z,1325725377.8673 [Default:GPS:B.GoToSurface] Stopped
2012-01-05T01:02:57.86730Z,1325725377.8673 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-01-05T01:02:57.86750Z,1325725377.8675 [Default:GPS:Read_GPS] Running Loop=1