"SA has outstanding requests" Killing VPN?

pitviperpitviper Member Posts: 1,376 ■■■■■■■□□□
in CCNP Security
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 **** 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?
CCNP:Collaboration, CCNP:R&S, CCNA:S, CCNA:V, CCNA, CCENT
· Share on FacebookShare on Twitter

Comments

  • chmodchmod Member Posts: 360 ■■■□□□□□□□
    Basically VPN rekeying process failing. Can you post config?
    · Share on FacebookShare on Twitter
  • pitviperpitviper Member Posts: 1,376 ■■■■■■■□□□
    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
    Mar 17 21:07:59.679: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005):Sending an IKE IPv4 Packet.
Mar 17 21:07:59.679: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005):deleting node 1375622869 error FALSE reason "No Error"
Mar 17 21:07:59.679: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005):Node 1375622869, Input = IKE_MESG_FROM_PEER, IKE_QM_EXCH
Mar 17 21:07:59.679: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]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[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]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[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005): sending packet to 10.20.30.40 my_port 500 peer_port 500 (I) QM_IDLE
Mar 17 21:08:02.471: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005):Sending an IKE IPv4 Packet.
Mar 17 21:08:02.471: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005):purging node 1862331164
Mar 17 21:08:02.471: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005):Input = IKE_MESG_FROM_IPSEC, IKE_PHASE2_DEL
Mar 17 21:08:02.471: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]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[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005): sitting IDLE. Starting QM immediately (QM_IDLE      )
Mar 17 21:08:06.303: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005):beginning Quick Mode exchange, M-ID of 1584435147
Mar 17 21:08:06.303: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005):QM Initiator gets spi
Mar 17 21:08:06.303: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005): sending packet to 10.20.30.40 my_port 500 peer_port 500 (I) QM_IDLE
Mar 17 21:08:06.303: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005):Sending an IKE IPv4 Packet.
Mar 17 21:08:06.303: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005):Node 1584435147, Input = IKE_MESG_INTERNAL, IKE_INIT_QM
Mar 17 21:08:06.303: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]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[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005): processing HASH payload. message ID = 1584435147
Mar 17 21:08:06.355: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005): processing SA payload. message ID = 1584435147
Mar 17 21:08:06.355: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]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[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]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[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005): processing NONCE payload. message ID = 1584435147
Mar 17 21:08:06.359: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005): processing ID payload. message ID = 1584435147
Mar 17 21:08:06.359: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005): processing ID payload. message ID = 1584435147
Mar 17 21:08:06.359: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]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[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005): sending packet to 10.20.30.40 my_port 500 peer_port 500 (I) QM_IDLE
Mar 17 21:08:06.359: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005):Sending an IKE IPv4 Packet.
Mar 17 21:08:06.359: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005):deleting node 1584435147 error FALSE reason "No Error"
Mar 17 21:08:06.359: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005):Node 1584435147, Input = IKE_MESG_FROM_PEER, IKE_QM_EXCH
Mar 17 21:08:06.359: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]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[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]1005):purging node 1215217968
Mar 17 21:08:49.679: ISAKMP[IMG]https://us.v-cdn.net/6030959/uploads/images/smilies/icon_sad.gif[/IMG]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.
    CCNP:Collaboration, CCNP:R&S, CCNA:S, CCNA:V, CCNA, CCENT
    · Share on FacebookShare on Twitter
  • pitviperpitviper Member Posts: 1,376 ■■■■■■■□□□
    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?
    CCNP:Collaboration, CCNP:R&S, CCNA:S, CCNA:V, CCNA, CCENT
    · Share on FacebookShare on Twitter
  • pitviperpitviper Member Posts: 1,376 ■■■■■■■□□□
    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.
    CCNP:Collaboration, CCNP:R&S, CCNA:S, CCNA:V, CCNA, CCENT
    · Share on FacebookShare on Twitter
Sign In or Register to comment.