2019-07-11T01:26:41.595Z,1562808401.595 [CommandLine](IMPORTANT): got command restart logs
2019-07-11T01:26:44.550Z,1562808404.550 [NAL9602](DEBUG): Fix Requested
2019-07-11T01:26:47.378Z,1562808407.378 [NAL9602](DEBUG): Fix Requested
2019-07-11T01:26:48.207Z,1562808408.207 [RDI_Pathfinder](ERROR): only read 0 of 4 data items
2019-07-11T01:26:48.207Z,1562808408.207 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,    +,    -5,A
2019-07-11T01:26:50.614Z,1562808410.614 [NAL9602](DEBUG): Fix Requested
2019-07-11T01:26:53.442Z,1562808413.442 [NAL9602](DEBUG): Fix Requested
2019-07-11T01:26:56.674Z,1562808416.674 [NAL9602](DEBUG): Fix Requested
2019-07-11T01:26:59.502Z,1562808419.502 [NAL9602](DEBUG): Fix Requested
2019-07-11T01:27:02.326Z,1562808422.326 [NAL9602](DEBUG): Fix Requested
2019-07-11T01:27:05.562Z,1562808425.562 [NAL9602](DEBUG): Fix Requested
2019-07-11T01:27:08.386Z,1562808428.386 [NAL9602](DEBUG): Fix Requested
2019-07-11T01:27:11.618Z,1562808431.618 [NAL9602](DEBUG): Fix Requested
2019-07-11T01:27:14.446Z,1562808434.446 [NAL9602](DEBUG): Fix Requested
2019-07-11T01:27:17.678Z,1562808437.678 [NAL9602](DEBUG): Fix Requested
2019-07-11T01:27:20.506Z,1562808440.506 [NAL9602](DEBUG): Fix Requested
2019-07-11T01:27:23.334Z,1562808443.334 [NAL9602](DEBUG): Fix Requested
2019-07-11T01:27:26.570Z,1562808446.570 [NAL9602](DEBUG): Fix Requested
2019-07-11T01:27:27.148Z,1562808447.148 [CommandLine](IMPORTANT): got command run ./Missions/DUSBL_Tracking.xml
2019-07-11T01:27:27.148Z,1562808447.148 [MissionManager](INFO): Loading Mission: ./Missions/DUSBL_Tracking.xml
2019-07-11T01:27:27.172Z,1562808447.172 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 10.000000 min
2019-07-11T01:27:27.174Z,1562808447.174 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-07-11T01:27:27.178Z,1562808447.178 [MissionManager](INFO): DefineArg DUSBL.TrackingUpdatePeriod = 4.000000 s
2019-07-11T01:27:27.180Z,1562808447.180 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-07-11T01:27:27.182Z,1562808447.182 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-07-11T01:27:27.183Z,1562808447.183 [DUSBL:A.Pitch](DEBUG): Construct.
2019-07-11T01:27:27.212Z,1562808447.212 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-07-11T01:27:27.237Z,1562808447.237 [DUSBL:RequestRepeater:A.Wait](DEBUG): Construct Wait.
2019-07-11T01:27:27.247Z,1562808447.247 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="DUSBL">

    <Description>
        This mission is requests a DUSBL arming.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        How long to let the mission run.
    </Description><Units:minute/><Value>10</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>
    
    <DefineArg Name="TrackingUpdatePeriod"><Description>
        How long to wait between acoustic queries
    </Description><Units:second/><Value>4</Value></DefineArg>
    
    <DefineArg Name="NumberOfPings"><Description>
        Number of pings requested each time.
    </Description><Units:count/><Value>1</Value></DefineArg>
    
    <DefineArg Name="EnabledDUSBL"><Description>
        Automatically set to true if the DUSBL is enabled. Set to false to disable
        reading from the DUSBL.
    </Description><Sensor:DUSBL_Hydroid.loadAtStartup/></DefineArg>    

    <Timeout Duration="MissionTimeout"/>

    <Guidance:Pitch>
        <Parallel/>
        <Setting><Guidance:Pitch.massPosition/><Control:VerticalControl.massDefault/></Setting>
    </Guidance:Pitch>

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

    
        <Estimation:TrackAcousticContact>
            <Parallel/>
            <Setting><Estimation:TrackAcousticContact.contactLabelSetting/><Arg Name="TransponderCode"/></Setting>
            <Setting><Estimation:TrackAcousticContact.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
            <Setting><Estimation:TrackAcousticContact.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
        </Estimation:TrackAcousticContact>
        
      <Aggregate Id="RequestRepeater">

        <Sequence/>
        
          <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="MissionTimeout"/></Setting>            
          </Guidance:Wait>
      </Aggregate>

</Mission>


2019-07-11T01:27:27.248Z,1562808447.248 [CommandLine](IMPORTANT): Running ./Missions/DUSBL_Tracking.xml
2019-07-11T01:27:27.418Z,1562808447.418 [Default] Stopped
2019-07-11T01:27:27.418Z,1562808447.418 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-11T01:27:27.418Z,1562808447.418 [Default:B.GoToSurface] Stopped
2019-07-11T01:27:27.418Z,1562808447.418 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-11T01:27:27.418Z,1562808447.418 [Default:CheckIn] Stopped
2019-07-11T01:27:27.418Z,1562808447.418 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-11T01:27:27.418Z,1562808447.418 [Default:CheckIn:Read_GPS] Stopped
2019-07-11T01:27:27.419Z,1562808447.419 [MissionManager](IMPORTANT): Started mission DUSBL
2019-07-11T01:27:27.419Z,1562808447.419 [DUSBL] Running Loop=1
2019-07-11T01:27:27.419Z,1562808447.419 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-07-11T01:27:27.419Z,1562808447.419 [DUSBL:A.Pitch] Running Loop=1
2019-07-11T01:27:27.419Z,1562808447.419 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-07-11T01:27:27.419Z,1562808447.419 [DUSBL:B.SetSpeed] Running Loop=1
2019-07-11T01:27:27.419Z,1562808447.419 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-07-11T01:27:27.419Z,1562808447.419 [DUSBL:C.] Running Loop=1
2019-07-11T01:27:27.420Z,1562808447.420 [DUSBL:C.](INFO): Initializing TrackAcousticContact.
2019-07-11T01:27:27.420Z,1562808447.420 [DUSBL:RequestRepeater] Running Loop=1
2019-07-11T01:27:27.420Z,1562808447.420 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-07-11T01:27:27.420Z,1562808447.420 [DUSBL:RequestRepeater:A.Wait] Running Loop=1
2019-07-11T01:27:27.420Z,1562808447.420 [DUSBL:RequestRepeater:A.Wait](DEBUG): Initialize Wait Component.
2019-07-11T01:27:27.420Z,1562808447.420 [DUSBL:C.] Running Loop=1
2019-07-11T01:27:27.421Z,1562808447.421 [DUSBL:B.SetSpeed] Running Loop=1
2019-07-11T01:27:27.421Z,1562808447.421 [DUSBL:A.Pitch] Running Loop=1
2019-07-11T01:27:31.430Z,1562808451.430 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T01:27:31.845Z,1562808451.845 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-07-11T01:27:31.845Z,1562808451.845 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-07-11T01:27:31.845Z,1562808451.845 [DUSBL_Hydroid](INFO): Arming DUSBL. rangeReq: #U1,P,02,014,800,19,00,00,5DC
2019-07-11T01:27:31.846Z,1562808451.846 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-07-11T01:27:32.208Z,1562808452.208 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
CFB,000,003B8,18A,80,80,0A,FF
2019-07-11T01:27:32.208Z,1562808452.208 [DUSBL_Hydroid](INFO): Command Ack
2019-07-11T01:27:32.208Z,1562808452.208 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-07-11T01:27:32.209Z,1562808452.209 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-07-11T01:27:32.571Z,1562808452.571 [CommandLine](IMPORTANT): got command stop
2019-07-11T01:27:32.571Z,1562808452.571 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-07-11T01:27:32.630Z,1562808452.630 [Micromodem](INFO): Nmea in: $SNPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*4E

2019-07-11T01:27:32.679Z,1562808452.679 [MissionManager](INFO): MissionManager is completed.
2019-07-11T01:27:32.679Z,1562808452.679 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-07-11T01:27:32.679Z,1562808452.679 [DUSBL] Stopped
2019-07-11T01:27:32.679Z,1562808452.679 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-07-11T01:27:32.679Z,1562808452.679 [DUSBL:A.Pitch] Stopped
2019-07-11T01:27:32.679Z,1562808452.679 [DUSBL:B.SetSpeed] Stopped
2019-07-11T01:27:32.679Z,1562808452.679 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-07-11T01:27:32.679Z,1562808452.679 [DUSBL:C.] Stopped
2019-07-11T01:27:32.679Z,1562808452.679 [DUSBL:RequestRepeater] Stopped
2019-07-11T01:27:32.680Z,1562808452.680 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-07-11T01:27:32.680Z,1562808452.680 [DUSBL:RequestRepeater:A.Wait] Stopped
2019-07-11T01:27:32.680Z,1562808452.680 [DUSBL:RequestRepeater:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-11T01:27:33.068Z,1562808453.068 [MissionManager](IMPORTANT): Started mission Default
2019-07-11T01:27:33.068Z,1562808453.068 [Default] Running Loop=1
2019-07-11T01:27:33.068Z,1562808453.068 [Default](DEBUG): Aggregate::initialize Default
2019-07-11T01:27:33.068Z,1562808453.068 [Default:B.GoToSurface] Running Loop=1
2019-07-11T01:27:33.069Z,1562808453.069 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-11T01:27:33.069Z,1562808453.069 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-11T01:27:33.069Z,1562808453.069 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-11T01:27:33.069Z,1562808453.069 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-11T01:27:33.070Z,1562808453.070 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-11T01:27:33.074Z,1562808453.074 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-11T01:27:33.075Z,1562808453.075 [Default:A.Wait] Running Loop=1
2019-07-11T01:27:33.075Z,1562808453.075 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-11T01:27:46.390Z,1562808466.390 [Default:A.Wait](INFO): Done Waiting.
2019-07-11T01:27:46.394Z,1562808466.394 [Default:A.Wait] Stopped
2019-07-11T01:27:46.394Z,1562808466.394 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-11T01:27:46.829Z,1562808466.829 [Default:CheckIn] Running Loop=1
2019-07-11T01:27:46.829Z,1562808466.829 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-11T01:27:46.829Z,1562808466.829 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-11T01:27:48.383Z,1562808468.383 [NAL9602](DEBUG): Fix Requested
2019-07-11T01:27:48.785Z,1562808468.785 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,012635.00,A,3648.16575,N,12147.28718,W,0.117,98.86,110719,,,A*44
2019-07-11T01:27:48.802Z,1562808468.802 [NAL9602](INFO): GPS fix at 20190711T012635: (36.802763, -121.788120)
2019-07-11T01:27:48.894Z,1562808468.894 [Default:CheckIn:Read_GPS] Stopped
2019-07-11T01:27:48.898Z,1562808468.898 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-07-11T01:27:49.227Z,1562808469.227 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-07-11T01:27:49.944Z,1562808469.944 [Micromodem](ERROR): Buffer fill timout failure.
2019-07-11T01:27:52.520Z,1562808472.520 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 078B265D040001005D00000400540100000000000000151D80030C5669BF3148E2FA22188B6A3173E5573572661C0BCBDFFAB423BD32D9A51E8904B0A920CE9A
2019-07-11T01:27:52.520Z,1562808472.520 [Micromodem](INFO): Outgoing frame #2, 64 bytes: EF9F66414C9B9FD6761AD008C3E3DC4FCA2E4E25B6359B14B772C256AEDD60B95108769F11B6F1CAFDFCAA023BD2A6AC8267BF03117F45C2DD2DCA8C8EEBE5F9
2019-07-11T01:27:52.521Z,1562808472.521 [Micromodem](INFO): Outgoing frame #3, 64 bytes: 7BD9043D223D555CF9F8C344436B63EF13BFE530A3AD5AB43B65A7E1E292F063AFC71143C404EE6C0C15F8C294BA7D7D572AA2D9A090B022FCD5E97BF3E54EB0
2019-07-11T01:27:52.521Z,1562808472.521 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,3*53

2019-07-11T01:27:53.508Z,1562808473.508 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,3*51

2019-07-11T01:27:53.905Z,1562808473.905 [Micromodem](INFO): Nmea in: $CADRQ,012753,1,9,0,64,1*4C

2019-07-11T01:27:53.905Z,1562808473.905 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,078B265D040001005D00000400540100000000000000151D80030C5669BF3148E2FA22188B6A3173E5573572661C0BCBDFFAB423BD32D9A51E8904B0A920CE9A*7F

2019-07-11T01:27:54.312Z,1562808474.312 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-11T01:27:54.716Z,1562808474.716 [Micromodem](INFO): Nmea in: $CADRQ,012754,1,9,0,64,2*48

2019-07-11T01:27:54.717Z,1562808474.717 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,EF9F66414C9B9FD6761AD008C3E3DC4FCA2E4E25B6359B14B772C256AEDD60B95108769F11B6F1CAFDFCAA023BD2A6AC8267BF03117F45C2DD2DCA8C8EEBE5F9*70

2019-07-11T01:27:55.117Z,1562808475.117 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-11T01:27:55.524Z,1562808475.524 [Micromodem](INFO): Nmea in: $CADRQ,012755,1,9,0,64,3*48

2019-07-11T01:27:55.525Z,1562808475.525 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,7BD9043D223D555CF9F8C344436B63EF13BFE530A3AD5AB43B65A7E1E292F063AFC71143C404EE6C0C15F8C294BA7D7D572AA2D9A090B022FCD5E97BF3E54EB0*7A

2019-07-11T01:27:55.928Z,1562808475.928 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-11T01:27:56.328Z,1562808476.328 [Micromodem](INFO): Nmea in: $CATXP,192*48

2019-07-11T01:27:57.822Z,1562808477.822 [DataOverHttps](INFO): Sending 187 bytes from file Logs/20190711T010407/Courier0004.lzma
2019-07-11T01:27:58.620Z,1562808478.620 [DataOverHttps](INFO): Moved sent file to Logs/20190711T010407/Courier0004.lzma.bak
2019-07-11T01:27:58.620Z,1562808478.620 [DataOverHttps](INFO): SBD MOMSN=11438641
2019-07-11T01:28:04.008Z,1562808484.008 [Micromodem](INFO): Nmea in: $CATXF,192*5E

2019-07-11T01:28:05.218Z,1562808485.218 [Micromodem](INFO): Nmea in: $CAXST,6,20190711,012756.350198,3,0,200,2000,14500,1,1,9,1,3,3,3,192*4B

2019-07-11T01:28:11.378Z,1562808491.378 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190711T012641/Courier0000.lzma
2019-07-11T01:28:12.292Z,1562808492.292 [CommandLine](IMPORTANT): got command restart logs