+ Reply to Thread
Results 1 to 5 of 5
  1. Senior Member pitviper's Avatar
    Join Date
    May 2008
    Location
    Right Coast, US
    Posts
    1,363

    Certifications
    CCNP:Collaboration, CCNP:R+S, CCNA:R+S, CCNA:V(IIUC), CCNA:S, CCENT, CNSS 4011
    #1

    Default "SA has outstanding requests" Killing VPN?

    I have a remote site that keeps dropping its connection to corporate consistently after about 45 minutes idle, quicker when passing traffic. The site in question has an ISR2 2921 connecting back to an ASA 5510. I have the exact same config running over the same cable carrier, on identical hardware and IOS versions, in several other locations with no problem. The Tunnel seems to take a dump during the rekeying process and I think I may know why but can’t put my finger on it – seems like there is a rogue request in wait, but I can’t figure out where the heck it’s coming from. The ACLs pertaining to the VPN are pretty specific – I’m finding entries like this in the log after a re-connect, from several different external IPs (none of which belong to us):

    Mar 17 19:13:01.542: SA has outstanding requests (local 50.162.235.120 port 500, remote 50.162.235.92 port 500)

    Any tips?
    Reply With Quote Quote  

  2. SS -->
  3. Senior Member
    Join Date
    Apr 2007
    Location
    CR
    Posts
    332

    Certifications
    A+, LPI1, CCNA, Sec +
    #2
    Basically VPN rekeying process failing. Can you post config?
    Reply With Quote Quote  

  4. Senior Member pitviper's Avatar
    Join Date
    May 2008
    Location
    Right Coast, US
    Posts
    1,363

    Certifications
    CCNP:Collaboration, CCNP:R+S, CCNA:R+S, CCNA:V(IIUC), CCNA:S, CCENT, CNSS 4011
    #3
    Here's a sample of what I'm seeing in the log - nothing jumping out at me except the "SA has outstanding requests" again from a different IP - the tunnel comes back up but stops passing traffic for 5 minutes or so. I changed the external IP to 10.20.30.40

    Code:
    Mar 17 21:07:59.679: ISAKMP:(1005):Sending an IKE IPv4 Packet.
    Mar 17 21:07:59.679: ISAKMP:(1005):deleting node 1375622869 error FALSE reason "No Error"
    Mar 17 21:07:59.679: ISAKMP:(1005):Node 1375622869, Input = IKE_MESG_FROM_PEER, IKE_QM_EXCH
    Mar 17 21:07:59.679: ISAKMP:(1005):Old State = IKE_QM_I_QM1  New State = IKE_QM_PHASE2_COMPLETE
    Mar 17 21:07:59.679: IPSEC(key_engine): got a queue event with 1 KMI message(s)
    Mar 17 21:07:59.679: Crypto mapdb : proxy_match
            src addr     : 172.23.26.0
            dst addr     : 192.168.10.0
            protocol     : 0
            src port     : 0
            dst port     : 0
    Mar 17 21:07:59.679: IPSEC(crypto_ipsec_sa_find_ident_head): reconnecting with the same proxies and peer 10.20.30.40
    Mar 17 21:07:59.679: IPSEC(create_sa): sa created,
      (sa) sa_dest= 10.1.10.254, sa_proto= 50,
        sa_spi= 0x886F2AAA(2288986794),
        sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 2025
        sa_lifetime(k/sec)= (4550193/3600)
    Mar 17 21:07:59.679: IPSEC(create_sa): sa created,
      (sa) sa_dest= 10.20.30.40, sa_proto= 50,
        sa_spi= 0xD2127220(3524424224),
        sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 2026
        sa_lifetime(k/sec)= (4550193/3600)
    Mar 17 21:07:59.679: IPSEC(update_current_outbound_sa): get enable SA peer 10.20.30.40 current outbound sa to SPI D2127220
    Mar 17 21:07:59.679: IPSEC(update_current_outbound_sa): updated peer 10.20.30.40 current outbound sa to SPI D2127220
    Mar 17 21:07:59.895: ISAKMP:(1004):purging SA., sa=2D0B88A4, delme=2D0B88A4
    Mar 17 21:08:02.471: IPSEC(delete_sa): deleting SA,
      (sa) sa_dest= 10.1.10.254, sa_proto= 50,
        sa_spi= 0xC3C66E8F(3284561551),
        sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 2019
        sa_lifetime(k/sec)= (4467888/3600),
      (identity) local= 10.1.10.254:0, remote= 10.20.30.40:0,
        local_proxy= 172.23.26.0/255.255.255.0/0/0 (type=4),
        remote_proxy= 192.168.9.0/255.255.255.0/0/0 (type=4)
    Mar 17 21:08:02.471: IPSEC(update_current_outbound_sa): updated peer 10.20.30.40 current outbound sa to SPI 0
    Mar 17 21:08:02.471: IPSEC(delete_sa): deleting SA,
      (sa) sa_dest= 10.20.30.40, sa_proto= 50,
        sa_spi= 0xC555AFC3(3310727107),
        sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 2020
        sa_lifetime(k/sec)= (4467888/3600),
      (identity) local= 10.1.10.254:0, remote= 10.20.30.40:0,
        local_proxy= 172.23.26.0/255.255.255.0/0/0 (type=4),
        remote_proxy= 192.168.9.0/255.255.255.0/0/0 (type=4)
    Mar 17 21:08:02.471: ISAKMP: set new node 1862331164 to QM_IDLE
    Mar 17 21:08:02.471: ISAKMP:(1005): sending packet to 10.20.30.40 my_port 500 peer_port 500 (I) QM_IDLE
    Mar 17 21:08:02.471: ISAKMP:(1005):Sending an IKE IPv4 Packet.
    Mar 17 21:08:02.471: ISAKMP:(1005):purging node 1862331164
    Mar 17 21:08:02.471: ISAKMP:(1005):Input = IKE_MESG_FROM_IPSEC, IKE_PHASE2_DEL
    Mar 17 21:08:02.471: ISAKMP:(1005):Old State = IKE_P1_COMPLETE  New State = IKE_P1_COMPLETE
    
    Mar 17 21:08:06.303: IPSEC(sa_request): ,
      (key eng. msg.) OUTBOUND local= 10.1.10.254:500, remote= 10.20.30.40:500,
        local_proxy= 172.23.26.0/255.255.255.0/0/0 (type=4),
        remote_proxy= 192.168.9.0/255.255.255.0/0/0 (type=4),
        protocol= ESP, transform= esp-3des esp-md5-hmac  (Tunnel),
        lifedur= 3600s and 4608000kb,
        spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
    Mar 17 21:08:06.303: ISAKMP: set new node 0 to QM_IDLE
    Mar 17 21:08:06.303: SA has outstanding requests  (local 43.143.220.76 port 500, remote 43.143.220.48 port 500)
    Mar 17 21:08:06.303: ISAKMP:(1005): sitting IDLE. Starting QM immediately (QM_IDLE      )
    Mar 17 21:08:06.303: ISAKMP:(1005):beginning Quick Mode exchange, M-ID of 1584435147
    Mar 17 21:08:06.303: ISAKMP:(1005):QM Initiator gets spi
    Mar 17 21:08:06.303: ISAKMP:(1005): sending packet to 10.20.30.40 my_port 500 peer_port 500 (I) QM_IDLE
    Mar 17 21:08:06.303: ISAKMP:(1005):Sending an IKE IPv4 Packet.
    Mar 17 21:08:06.303: ISAKMP:(1005):Node 1584435147, Input = IKE_MESG_INTERNAL, IKE_INIT_QM
    Mar 17 21:08:06.303: ISAKMP:(1005):Old State = IKE_QM_READY  New State = IKE_QM_I_QM1
    Mar 17 21:08:06.355: ISAKMP (1005): received packet from 10.20.30.40 dport 500 sport 500 Global (I) QM_IDLE
    Mar 17 21:08:06.355: ISAKMP:(1005): processing HASH payload. message ID = 1584435147
    Mar 17 21:08:06.355: ISAKMP:(1005): processing SA payload. message ID = 1584435147
    Mar 17 21:08:06.355: ISAKMP:(1005):Checking IPSec proposal 1
    Mar 17 21:08:06.355: ISAKMP: transform 1, ESP_3DES
    Mar 17 21:08:06.355: ISAKMP:   attributes in transform:
    Mar 17 21:08:06.355: ISAKMP:      SA life type in seconds
    Mar 17 21:08:06.355: ISAKMP:      SA life duration (basic) of 
    Mar 17 21:08:06.355: ISAKMP:      SA life type in kilobytes
    Mar 17 21:08:06.355: ISAKMP:      SA life duration (VPI) of  0x0 0x46 0x50 0x0
    Mar 17 21:08:06.355: ISAKMP:      encaps is 1 (Tunnel)
    Mar 17 21:08:06.355: ISAKMP:      authenticator is HMAC-MD5
    Mar 17 21:08:06.355: ISAKMP:(1005):atts are acceptable.
    Mar 17 21:08:06.355: IPSEC(validate_proposal_request): proposal part #1
    Mar 17 21:08:06.355: IPSEC(validate_proposal_request): proposal part #1,
      (key eng. msg.) INBOUND local= 10.1.10.254:0, remote= 10.20.30.40:0,
        local_proxy= 172.23.26.0/255.255.255.0/0/0 (type=4),
        remote_proxy= 192.168.9.0/255.255.255.0/0/0 (type=4),
        protocol= ESP, transform= NONE  (Tunnel),
        lifedur= 0s and 0kb,
        spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
    Mar 17 21:08:06.355: Crypto mapdb : proxy_match
            src addr     : 172.23.26.0
            dst addr     : 192.168.9.0
            protocol     : 0
            src port     : 0
            dst port     : 0
    Mar 17 21:08:06.359: ISAKMP:(1005): processing NONCE payload. message ID = 1584435147
    Mar 17 21:08:06.359: ISAKMP:(1005): processing ID payload. message ID = 1584435147
    Mar 17 21:08:06.359: ISAKMP:(1005): processing ID payload. message ID = 1584435147
    Mar 17 21:08:06.359: ISAKMP:(1005): Creating IPSec SAs
    Mar 17 21:08:06.359:         inbound SA from 10.20.30.40 to 10.1.10.254 (f/i)  0/ 0
            (proxy 192.168.9.0 to 172.23.26.0)
    Mar 17 21:08:06.359:         has spi 0xCB83187A and conn_id 0
    Mar 17 21:08:06.359:         lifetime of 3600 seconds
    Mar 17 21:08:06.359:         lifetime of 4608000 kilobytes
    Mar 17 21:08:06.359:         outbound SA from 10.1.10.254 to 10.20.30.40 (f/i) 0/0
            (proxy 172.23.26.0 to 192.168.9.0)
    Mar 17 21:08:06.359:         has spi  0xD22EA726 and conn_id 0
    Mar 17 21:08:06.359:         lifetime of 3600 seconds
    Mar 17 21:08:06.359:         lifetime of 4608000 kilobytes
    Mar 17 21:08:06.359: ISAKMP:(1005): sending packet to 10.20.30.40 my_port 500 peer_port 500 (I) QM_IDLE
    Mar 17 21:08:06.359: ISAKMP:(1005):Sending an IKE IPv4 Packet.
    Mar 17 21:08:06.359: ISAKMP:(1005):deleting node 1584435147 error FALSE reason "No Error"
    Mar 17 21:08:06.359: ISAKMP:(1005):Node 1584435147, Input = IKE_MESG_FROM_PEER, IKE_QM_EXCH
    Mar 17 21:08:06.359: ISAKMP:(1005):Old State = IKE_QM_I_QM1  New State = IKE_QM_PHASE2_COMPLETE
    Mar 17 21:08:06.359: IPSEC(key_engine): got a queue event with 1 KMI message(s)
    Mar 17 21:08:06.359: Crypto mapdb : proxy_match
            src addr     : 172.23.26.0
            dst addr     : 192.168.9.0
            protocol     : 0
            src port     : 0
            dst port     : 0
    Mar 17 21:08:06.359: IPSEC(crypto_ipsec_sa_find_ident_head): reconnecting with the same proxies and peer 10.20.30.40
    Mar 17 21:08:06.359: IPSEC(policy_db_add_ident): src 172.23.26.0, dest 192.168.9.0, dest_port 0
    
    Mar 17 21:08:06.359: IPSEC(create_sa): sa created,
      (sa) sa_dest= 10.1.10.254, sa_proto= 50,
        sa_spi= 0xCB83187A(3414366330),
        sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 2027
        sa_lifetime(k/sec)= (4403869/3600)
    Mar 17 21:08:06.359: IPSEC(create_sa): sa created,
      (sa) sa_dest= 10.20.30.40, sa_proto= 50,
        sa_spi= 0xD22EA726(3526272806),
        sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 2028
        sa_lifetime(k/sec)= (4403869/3600)
    Mar 17 21:08:06.359: IPSEC(update_current_outbound_sa): get enable SA peer 10.20.30.40 current outbound sa to SPI D22EA726
    Mar 17 21:08:06.359: IPSEC(update_current_outbound_sa): updated peer 10.20.30.40 current outbound sa to SPI D22EA726
    Mar 17 21:08:49.627: ISAKMP:(1005):purging node 1215217968
    Mar 17 21:08:49.679: ISAKMP:(1005):purging node 1375622869
    Could that rogue request be breaking the rekey? I'll get a config together - lots to edit out but like I said it's fine @ a bunch of other locations.
    Reply With Quote Quote  

  5. Senior Member pitviper's Avatar
    Join Date
    May 2008
    Location
    Right Coast, US
    Posts
    1,363

    Certifications
    CCNP:Collaboration, CCNP:R+S, CCNA:R+S, CCNA:V(IIUC), CCNA:S, CCENT, CNSS 4011
    #4
    So the VPN config is solid – Last night I did a find replace on the IP and put the exact config on another piece of equipment / carrier and the tunnel rebuilds with no issues.

    I can’t for the life of me understand how the rogue external IPs are even getting to the router. I’m focusing on the ZBF config now, but the out-zone -> self policy is pretty tight – really only allowing VPN traffic from a single host (Corp ASA), and SSH/SDM traffic from a single external IP – AND it’s all being inspected on top of the ACLs. Everything else is dropped.

    Is my logic at least correct in thinking that the router is acknowledging the pending peer request instead of rekeying?
    Reply With Quote Quote  

  6. Senior Member pitviper's Avatar
    Join Date
    May 2008
    Location
    Right Coast, US
    Posts
    1,363

    Certifications
    CCNP:Collaboration, CCNP:R+S, CCNA:R+S, CCNA:V(IIUC), CCNA:S, CCENT, CNSS 4011
    #5
    Fixed now. Something between the remote site and corporate office was eating the keep-alive traffic. I requested a new block of IPs from the cable carrier and low and behold, the connection hasn’t dropped since. Looks like the “SA has outstanding requests” message was nothing more than a red herring.
    Last edited by pitviper; 03-26-2013 at 01:27 AM.
    Reply With Quote Quote  

+ Reply to Thread

Social Networking & Bookmarks