VPN randomly drops

marcusauman · ‎09-19-2011

Below is a debug from an IOS router. The VPN comes up and encryps/decrypts traffic fine. The IPSec SA lifetime is 3600 seconds. In the output below you will see the IPSec SA attempt to renew and fail. I put some of the output in bold that I'm unfamiliar with. The IPSec SA doesn't establish and then the whole phase 1 and phase 2 process has to take place. This increases the down time of the tunnel and is an issue. Thanks in advance for the help.

*Sep 19 11:56:25.218 CDT: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 65.118.89.72, remote= 216.189.255.7,
    local_proxy= 65.118.89.72/255.255.255.255/47/0 (type=1),
    remote_proxy= 216.189.255.7/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= esp-3des esp-md5-hmac (Transport),
    lifedur= 3600s and 4608000kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
*Sep 19 11:56:25.218 CDT: IPSEC(lifetime_expiry): SA lifetime threshold reached, expiring in 111 seconds
*Sep 19 11:56:25.218 CDT: ISAKMP: set new node 0 to QM_IDLE
*Sep 19 11:56:25.218 CDT: SA has outstanding requests (local 134.5.225.124 port 500, remote 134.5.225.96 port 500)
*Sep 19 11:56:25.218 CDT: ISAKMP:(2083): sitting IDLE. Starting QM immediately (QM_IDLE      )
*Sep 19 11:56:25.218 CDT: ISAKMP:(2083):beginning Quick Mode exchange, M-ID of 1586099655
*Sep 19 11:56:25.218 CDT: ISAKMP:(2083):QM Initiator gets spi
*Sep 19 11:56:25.218 CDT: crypto_engine: Generate IKE hash
*Sep 19 11:56:25.218 CDT: crypto_engine: Encrypt IKE packet
*Sep 19 11:56:25.218 CDT: ISAKMP:(2083): sending packet to 216.189.255.7 my_port 500 peer_port 500 (I) QM_IDLE
*Sep 19 11:56:25.218 CDT: ISAKMP:(2083):Sending an IKE IPv4 Packet.
*Sep 19 11:56:25.218 CDT: ISAKMP:(2083):Node 1586099655, Input = IKE_MESG_INTERNAL, IKE_INIT_QM
*Sep 19 11:56:25.218 CDT: ISAKMP:(2083):Old State = IKE_QM_READY New State = IKE_QM_I_QM1
*Sep 19 11:56:35.218 CDT: ISAKMP:(2083): retransmitting phase 2 QM_IDLE       1586099655 ...
*Sep 19 11:56:35.218 CDT: ISAKMP (2083): incrementing error counter on node, attempt 1 of 5: retransmit phase 2
*Sep 19 11:56:35.218 CDT: ISAKMP (2083): incrementing error counter on sa, attempt 1 of 5: retransmit phase 2
*Sep 19 11:56:35.218 CDT: ISAKMP:(2083): retransmitting phase 2 1586099655 QM_IDLE
*Sep 19 11:56:35.218 CDT: ISAKMP:(2083): sending packet to 216.189.255.7 my_port 500 peer_port 500 (I) QM_IDLE
*Sep 19 11:56:35.218 CDT: ISAKMP:(2083):Sending an IKE IPv4 Packet.
*Sep 19 11:56:45.218 CDT: ISAKMP:(2083): retransmitting phase 2 QM_IDLE       1586099655 ...
*Sep 19 11:56:45.218 CDT: ISAKMP (2083): incrementing error counter on node, attempt 2 of 5: retransmit phase 2
*Sep 19 11:56:45.218 CDT: ISAKMP (2083): incrementing error counter on sa, attempt 2 of 5: retransmit phase 2
*Sep 19 11:56:45.218 CDT: ISAKMP:(2083): retransmitting phase 2 1586099655 QM_IDLE
*Sep 19 11:56:45.218 CDT: ISAKMP:(2083): sending packet to 216.189.255.7 my_port 500 peer_port 500 (I) QM_IDLE
*Sep 19 11:56:45.218 CDT: ISAKMP:(2083):Sending an IKE IPv4 Packet.
*Sep 19 11:56:55.218 CDT: ISAKMP:(2083): retransmitting phase 2 QM_IDLE       1586099655 ...
*Sep 19 11:56:55.218 CDT: ISAKMP (2083): incrementing error counter on node, attempt 3 of 5: retransmit phase 2
*Sep 19 11:56:55.218 CDT: ISAKMP (2083): incrementing error counter on sa, attempt 3 of 5: retransmit phase 2
*Sep 19 11:56:55.218 CDT: ISAKMP:(2083): retransmitting phase 2 1586099655 QM_IDLE
*Sep 19 11:56:55.218 CDT: ISAKMP:(2083): sending packet to 216.189.255.7 my_port 500 peer_port 500 (I) QM_IDLE
*Sep 19 11:56:55.218 CDT: ISAKMP:(2083):Sending an IKE IPv4 Packet.
*Sep 19 11:56:55.218 CDT: IPSEC(key_engine): request timer fired: count = 1,
(identity) local= 65.118.89.72, remote= 216.189.255.7,
    local_proxy= 65.118.89.72/255.255.255.255/47/0 (type=1),
    remote_proxy= 216.189.255.7/255.255.255.255/47/0 (type=1)
*Sep 19 11:56:55.218 CDT: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 65.118.89.72, remote= 216.189.255.7,
    local_proxy= 65.118.89.72/255.255.255.255/47/0 (type=1),
    remote_proxy= 216.189.255.7/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= esp-3des esp-md5-hmac (Transport),
    lifedur= 3600s and 4608000kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
*Sep 19 11:56:55.218 CDT: ISAKMP: set new node 0 to QM_IDLE
*Sep 19 11:56:55.218 CDT: SA has outstanding requests (local 134.5.225.124 port 500, remote 134.5.225.96 port 500)
*Sep 19 11:56:55.218 CDT: ISAKMP:(2083): sitting IDLE. Starting QM immediately (QM_IDLE      )
*Sep 19 11:56:55.218 CDT: ISAKMP:(2083):beginning Quick Mode exchange, M-ID of 664301548
*Sep 19 11:56:55.218 CDT: ISAKMP:(2083):QM Initiator gets spi
*Sep 19 11:56:55.218 CDT: crypto_engine: Generate IKE hash
*Sep 19 11:56:55.218 CDT: crypto_engine: Encrypt IKE packet
*Sep 19 11:56:55.218 CDT: ISAKMP:(2083): sending packet to 216.189.255.7 my_port 500 peer_port 500 (I) QM_IDLE
*Sep 19 11:56:55.218 CDT: ISAKMP:(2083):Sending an IKE IPv4 Packet.
*Sep 19 11:56:55.222 CDT: ISAKMP:(2083):Node 664301548, Input = IKE_MESG_INTERNAL, IKE_INIT_QM
*Sep 19 11:56:55.222 CDT: ISAKMP:(2083):Old State = IKE_QM_READY New State = IKE_QM_I_QM1
*Sep 19 11:57:05.218 CDT: ISAKMP:(2083): retransmitting phase 2 QM_IDLE       1586099655 ...
*Sep 19 11:57:05.218 CDT: ISAKMP (2083): incrementing error counter on node, attempt 4 of 5: retransmit phase 2
*Sep 19 11:57:05.218 CDT: ISAKMP (2083): incrementing error counter on sa, attempt 4 of 5: retransmit phase 2
*Sep 19 11:57:05.218 CDT: ISAKMP:(2083): retransmitting phase 2 1586099655 QM_IDLE
*Sep 19 11:57:05.218 CDT: ISAKMP:(2083): sending packet to 216.189.255.7 my_port 500 peer_port 500 (I) QM_IDLE
*Sep 19 11:57:05.218 CDT: ISAKMP:(2083):Sending an IKE IPv4 Packet.
*Sep 19 11:57:05.222 CDT: ISAKMP:(2083): retransmitting phase 2 QM_IDLE       664301548 ...
*Sep 19 11:57:05.222 CDT: ISAKMP (2083): incrementing error counter on node, attempt 1 of 5: retransmit phase 2
*Sep 19 11:57:05.222 CDT: ISAKMP (2083): incrementing error counter on sa, attempt 5 of 5: retransmit phase 2
*Sep 19 11:57:05.222 CDT: ISAKMP:(2083): retransmitting phase 2 664301548 QM_IDLE
*Sep 19 11:57:05.222 CDT: ISAKMP:(2083): sending packet to 216.189.255.7 my_port 500 peer_port 500 (I) QM_IDLE
*Sep 19 11:57:05.222 CDT: ISAKMP:(2083):Sending an IKE IPv4 Packet.
*Sep 19 11:57:15.218 CDT: ISAKMP:(2083): retransmitting phase 2 QM_IDLE       1586099655 ...
*Sep 19 11:57:15.218 CDT: ISAKMP:(2083):peer does not do paranoid keepalives.

*Sep 19 11:57:15.218 CDT: ISAKMP:(2083):deleting SA reason "Death by retransmission P2" state (I) QM_IDLE       (peer 216.189.255.7)
*Sep 19 11:57:15.218 CDT: ISAKMP: set new node 670443879 to QM_IDLE
*Sep 19 11:57:15.218 CDT: crypto_engine: Generate IKE hash
*Sep 19 11:57:15.218 CDT: crypto_engine: Encrypt IKE packet
*Sep 19 11:57:15.218 CDT: ISAKMP:(2083): sending packet to 216.189.255.7 my_port 500 peer_port 500 (I) QM_IDLE
*Sep 19 11:57:15.218 CDT: ISAKMP:(2083):Sending an IKE IPv4 Packet.
*Sep 19 11:57:15.218 CDT: ISAKMP:(2083):purging node 670443879
*Sep 19 11:57:15.218 CDT: ISAKMP:(2083):Input = IKE_MESG_INTERNAL, IKE_PHASE1_DEL
*Sep 19 11:57:15.218 CDT: ISAKMP:(2083):Old State = IKE_P1_COMPLETE New State = IKE_DEST_SA

*Sep 19 11:57:15.218 CDT: ISAKMP:(2083):deleting SA reason "Death by retransmission P2" state (I) QM_IDLE (peer 216.189.255.7)
*Sep 19 11:57:15.218 CDT: ISAKMP:(0):Can't decrement IKE Call Admission Control stat outgoing_active since it's already 0.
*Sep 19 11:57:15.218 CDT: ISAKMP: Unlocking peer struct 0x867831E8 for isadb_mark_sa_deleted(), count 0
*Sep 19 11:57:15.218 CDT: ISAKMP:(2083):deleting node 1586099655 error FALSE reason "IKE deleted"
*Sep 19 11:57:15.218 CDT: ISAKMP:(2083):deleting node 664301548 error FALSE reason "IKE deleted"
*Sep 19 11:57:15.218 CDT: crypto engine: deleting IKE SA SW:83
*Sep 19 11:57:15.218 CDT: crypto_engine: Delete IKE SA
*Sep 19 11:57:15.218 CDT: ISAKMP:(2083):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
*Sep 19 11:57:15.218 CDT: ISAKMP:(2083):Old State = IKE_DEST_SA New State = IKE_DEST_SA

*Sep 19 11:57:25.218 CDT: IPSEC(key_engine): request timer fired: count = 2,
(identity) local= 65.118.89.72, remote= 216.189.255.7,
    local_proxy= 65.118.89.72/255.255.255.255/47/0 (type=1),
    remote_proxy= 216.189.255.7/255.255.255.255/47/0 (type=1)
*Sep 19 11:58:05.218 CDT: ISAKMP:(2083):purging node 1586099655
*Sep 19 11:58:05.218 CDT: ISAKMP:(2083):purging node 664301548
*Sep 19 11:58:15.218 CDT: ISAKMP:(2083):purging SA., sa=8605DFF8, delme=8605DFF8
*Sep 19 11:58:16.302 CDT: IPSEC(delete_sa): deleting SA,
(sa) sa_dest= 65.118.89.72, sa_proto= 50,
    sa_spi= 0x61E8898F(1642629519),
    sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 63
    sa_lifetime(k/sec)= (4542840/3600),
(identity) local= 65.118.89.72, remote= 216.189.255.7,
    local_proxy= 65.118.89.72/255.255.255.255/47/0 (type=1),
    remote_proxy= 216.189.255.7/255.255.255.255/47/0 (type=1)
*Sep 19 11:58:16.302 CDT: crypto engine: deleting IPSec SA Onboard VPN:63
*Sep 19 11:58:16.302 CDT: crypto_engine: Delete IPSec SA
*Sep 19 11:58:16.302 CDT: completed_delete_ipsec_sa: flow_id = 1400003F
*Sep 19 11:58:16.302 CDT: IPSEC(update_current_outbound_sa): updated peer 216.189.255.7 current outbound sa to SPI 0
*Sep 19 11:58:16.302 CDT: IPSEC(delete_sa): deleting SA,
(sa) sa_dest= 216.189.255.7, sa_proto= 50,
    sa_spi= 0x731F2A7(120713895),
    sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 64
    sa_lifetime(k/sec)= (4542840/3600),
(identity) local= 65.118.89.72, remote= 216.189.255.7,
    local_proxy= 65.118.89.72/255.255.255.255/47/0 (type=1),
    remote_proxy= 216.189.255.7/255.255.255.255/47/0 (type=1)
*Sep 19 11:58:16.302 CDT: crypto engine: deleting IPSec SA Onboard VPN:64
*Sep 19 11:58:16.302 CDT: ISAKMP: Deleting peer node by peer_reap for 216.189.255.7: 867831E8
*Sep 19 11:58:16.302 CDT: ISAKMP: ignoring request to send delete notify (no ISAKMP sa) src 65.118.89.72 dst 216.189.255.7 for SPI 0x61E8898F
*Sep 19 11:58:16.302 CDT: IPSEC(key_engine): got a queue event with 1 KMI message(s)
*Sep 19 11:58:16.302 CDT: crypto_engine: Delete IPSec SA
*Sep 19 11:58:16.302 CDT: completed_delete_ipsec_sa: flow_id = 14000040
*Sep 19 11:58:16.306 CDT: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 65.118.89.72, remote= 216.189.255.7,
    local_proxy= 65.118.89.72/255.255.255.255/47/0 (type=1),
    remote_proxy= 216.189.255.7/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= esp-3des esp-md5-hmac (Transport),
    lifedur= 3600s and 4608000kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
*Sep 19 11:58:16.330 CDT: ISAKMP:(0): SA request profile is (NULL)
*Sep 19 11:58:16.330 CDT: ISAKMP: Created a peer struct for 216.189.255.7, peer port 500
*Sep 19 11:58:16.330 CDT: ISAKMP: New peer created peer = 0x85C73A58 peer_handle = 0x80000412
*Sep 19 11:58:16.330 CDT: ISAKMP: Locking peer struct 0x85C73A58, refcount 1 for isakmp_initiator
*Sep 19 11:58:16.330 CDT: ISAKMP: local port 500, remote port 500
*Sep 19 11:58:16.330 CDT: ISAKMP: set new node 0 to QM_IDLE
*Sep 19 11:58:16.330 CDT: ISAKMP:(0):insert sa successfully sa = 86158224
*Sep 19 11:58:16.330 CDT: ISAKMP:(0):Can not start Aggressive mode, trying Main mode.
*Sep 19 11:58:16.330 CDT: ISAKMP:(0):found peer pre-shared key matching 216.189.255.7
*Sep 19 11:58:16.330 CDT: ISAKMP:(0): constructed NAT-T vendor-rfc3947 ID
*Sep 19 11:58:16.330 CDT: ISAKMP:(0): constructed NAT-T vendor-07 ID
*Sep 19 11:58:16.330 CDT: ISAKMP:(0): constructed NAT-T vendor-03 ID
*Sep 19 11:58:16.330 CDT: ISAKMP:(0): constructed NAT-T vendor-02 ID
*Sep 19 11:58:16.330 CDT: ISAKMP:(0):Input = IKE_MESG_FROM_IPSEC, IKE_SA_REQ_MM
*Sep 19 11:58:16.330 CDT: ISAKMP:(0):Old State = IKE_READY New State = IKE_I_MM1

*Sep 19 11:58:16.330 CDT: ISAKMP:(0): beginning Main Mode exchange
*Sep 19 11:58:16.330 CDT: ISAKMP:(0): sending packet to 216.189.255.7 my_port 500 peer_port 500 (I) MM_NO_STATE
*Sep 19 11:58:16.330 CDT: ISAKMP:(0):Sending an IKE IPv4 Packet.
*Sep 19 11:58:16.406 CDT: ISAKMP (0): received packet from 216.189.255.7 dport 500 sport 500 Global (I) MM_NO_STATE
*Sep 19 11:58:16.406 CDT: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
*Sep 19 11:58:16.406 CDT: ISAKMP:(0):Old State = IKE_I_MM1 New State = IKE_I_MM2

*Sep 19 11:58:16.406 CDT: ISAKMP:(0): processing SA payload. message ID = 0
*Sep 19 11:58:16.406 CDT: ISAKMP:(0): processing vendor id payload
*Sep 19 11:58:16.406 CDT: ISAKMP:(0): vendor ID seems Unity/DPD but major 245 mismatch
*Sep 19 11:58:16.406 CDT: ISAKMP (0): vendor ID is NAT-T v7
*Sep 19 11:58:16.406 CDT: ISAKMP:(0):found peer pre-shared key matching 216.189.255.7
*Sep 19 11:58:16.406 CDT: ISAKMP:(0): local preshared key found
*Sep 19 11:58:16.406 CDT: ISAKMP : Scanning profiles for xauth ...
*Sep 19 11:58:16.406 CDT: ISAKMP:(0):Checking ISAKMP transform 1 against priority 10 policy
*Sep 19 11:58:16.406 CDT: ISAKMP:      encryption 3DES-CBC
*Sep 19 11:58:16.406 CDT: ISAKMP:      hash MD5
*Sep 19 11:58:16.406 CDT: ISAKMP:      default group 2
*Sep 19 11:58:16.406 CDT: ISAKMP:      auth pre-share
*Sep 19 11:58:16.406 CDT: ISAKMP:      life type in seconds
*Sep 19 11:58:16.406 CDT: ISAKMP:      life duration (VPI) of 0x0 0x1 0x51 0x80
*Sep 19 11:58:16.410 CDT: ISAKMP:(0):atts are acceptable. Next payload is 0
*Sep 19 11:58:16.410 CDT: ISAKMP:(0):Acceptable atts:actual life: 0
*Sep 19 11:58:16.410 CDT: ISAKMP:(0):Acceptable atts:life: 0
*Sep 19 11:58:16.410 CDT: ISAKMP:(0):Fill atts in sa vpi_length:4
*Sep 19 11:58:16.410 CDT: ISAKMP:(0):Fill atts in sa life_in_seconds:86400
*Sep 19 11:58:16.410 CDT: ISAKMP:(0):Returning Actual lifetime: 86400
*Sep 19 11:58:16.410 CDT: ISAKMP:(0)::Started lifetime timer: 86400.

*Sep 19 11:58:16.410 CDT: ISAKMP:(0): processing vendor id payload
*Sep 19 11:58:16.410 CDT: ISAKMP:(0): vendor ID seems Unity/DPD but major 245 mismatch
*Sep 19 11:58:16.410 CDT: ISAKMP (0): vendor ID is NAT-T v7
*Sep 19 11:58:16.410 CDT: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
*Sep 19 11:58:16.410 CDT: ISAKMP:(0):Old State = IKE_I_MM2 New State = IKE_I_MM2

*Sep 19 11:58:16.410 CDT: ISAKMP:(0): sending packet to 216.189.255.7 my_port 500 peer_port 500 (I) MM_SA_SETUP
*Sep 19 11:58:16.410 CDT: ISAKMP:(0):Sending an IKE IPv4 Packet.
*Sep 19 11:58:16.410 CDT: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
*Sep 19 11:58:16.410 CDT: ISAKMP:(0):Old State = IKE_I_MM2 New State = IKE_I_MM3

*Sep 19 11:58:16.490 CDT: ISAKMP (0): received packet from 216.189.255.7 dport 500 sport 500 Global (I) MM_SA_SETUP
*Sep 19 11:58:16.490 CDT: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
*Sep 19 11:58:16.490 CDT: ISAKMP:(0):Old State = IKE_I_MM3 New State = IKE_I_MM4

*Sep 19 11:58:16.490 CDT: ISAKMP:(0): processing KE payload. message ID = 0
*Sep 19 11:58:16.494 CDT: crypto_engine: Create DH shared secret
*Sep 19 11:58:16.522 CDT: ISAKMP:(0): processing NONCE payload. message ID = 0
*Sep 19 11:58:16.522 CDT: ISAKMP:(0):found peer pre-shared key matching 216.189.255.7
*Sep 19 11:58:16.522 CDT: crypto_engine: Create IKE SA
*Sep 19 11:58:16.522 CDT: crypto engine: deleting DH phase 2 SW:119
*Sep 19 11:58:16.522 CDT: crypto_engine: Delete DH shared secret
*Sep 19 11:58:16.522 CDT: ISAKMP:(2087): processing vendor id payload
*Sep 19 11:58:16.522 CDT: ISAKMP:(2087): vendor ID is Unity
*Sep 19 11:58:16.522 CDT: ISAKMP:(2087): processing vendor id payload
*Sep 19 11:58:16.522 CDT: ISAKMP:(2087): vendor ID is DPD
*Sep 19 11:58:16.522 CDT: ISAKMP:(2087): processing vendor id payload
*Sep 19 11:58:16.522 CDT: ISAKMP:(2087): speaking to another IOS box!
*Sep 19 11:58:16.522 CDT: ISAKMP (2087): His hash no match - this node outside NAT
*Sep 19 11:58:16.522 CDT: ISAKMP (2087): No NAT Found for self or peer
*Sep 19 11:58:16.522 CDT: ISAKMP:(2087):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
*Sep 19 11:58:16.522 CDT: ISAKMP:(2087):Old State = IKE_I_MM4 New State = IKE_I_MM4

*Sep 19 11:58:16.522 CDT: ISAKMP:(2087):Send initial contact
*Sep 19 11:58:16.522 CDT: ISAKMP:(2087):SA is doing pre-shared key authentication using id type ID_IPV4_ADDR
*Sep 19 11:58:16.522 CDT: ISAKMP (2087): ID payload
        next-payload : 8
        type         : 1
        address      : 65.118.89.72
        protocol     : 17
        port         : 500
        length       : 12
*Sep 19 11:58:16.522 CDT: ISAKMP:(2087):Total payload length: 12
*Sep 19 11:58:16.522 CDT: crypto_engine: Generate IKE hash
*Sep 19 11:58:16.522 CDT: crypto_engine: Encrypt IKE packet
*Sep 19 11:58:16.522 CDT: ISAKMP:(2087): sending packet to 216.189.255.7 my_port 500 peer_port 500 (I) MM_KEY_EXCH
*Sep 19 11:58:16.522 CDT: ISAKMP:(2087):Sending an IKE IPv4 Packet.
*Sep 19 11:58:16.522 CDT: ISAKMP:(2087):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
*Sep 19 11:58:16.522 CDT: ISAKMP:(2087):Old State = IKE_I_MM4 New State = IKE_I_MM5

*Sep 19 11:58:16.598 CDT: ISAKMP (2087): received packet from 216.189.255.7 dport 500 sport 500 Global (I) MM_KEY_EXCH
*Sep 19 11:58:16.598 CDT: crypto_engine: Decrypt IKE packet
*Sep 19 11:58:16.598 CDT: ISAKMP:(2087): processing ID payload. message ID = 0
*Sep 19 11:58:16.598 CDT: ISAKMP (2087): ID payload
        next-payload : 8
        type         : 1
        address      : 216.189.255.7
        protocol     : 17
        port         : 500
        length       : 12
*Sep 19 11:58:16.598 CDT: ISAKMP:(0):: peer matches *none* of the profiles
*Sep 19 11:58:16.598 CDT: ISAKMP:(2087): processing HASH payload. message ID = 0
*Sep 19 11:58:16.598 CDT: crypto_engine: Generate IKE hash
*Sep 19 11:58:16.598 CDT: ISAKMP:(2087):SA authentication status:
        authenticated
*Sep 19 11:58:16.598 CDT: ISAKMP:(2087):SA has been authenticated with 216.189.255.7
*Sep 19 11:58:16.598 CDT: ISAKMP: Trying to insert a peer 65.118.89.72/216.189.255.7/500/, and inserted successfully 85C73A58.
*Sep 19 11:58:16.598 CDT: ISAKMP:(2087):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
*Sep 19 11:58:16.598 CDT: ISAKMP:(2087):Old State = IKE_I_MM5 New State = IKE_I_MM6

*Sep 19 11:58:16.598 CDT: ISAKMP:(2087):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
*Sep 19 11:58:16.602 CDT: ISAKMP:(2087):Old State = IKE_I_MM6 New State = IKE_I_MM6

*Sep 19 11:58:16.602 CDT: ISAKMP:(2087):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
*Sep 19 11:58:16.602 CDT: ISAKMP:(2087):Old State = IKE_I_MM6 New State = IKE_P1_COMPLETE

*Sep 19 11:58:16.602 CDT: ISAKMP:(2087):beginning Quick Mode exchange, M-ID of 237114336
*Sep 19 11:58:16.602 CDT: ISAKMP:(2087):QM Initiator gets spi
*Sep 19 11:58:16.602 CDT: crypto_engine: Generate IKE hash
*Sep 19 11:58:16.602 CDT: crypto_engine: Encrypt IKE packet
*Sep 19 11:58:16.602 CDT: ISAKMP:(2087): sending packet to 216.189.255.7 my_port 500 peer_port 500 (I) QM_IDLE
*Sep 19 11:58:16.602 CDT: ISAKMP:(2087):Sending an IKE IPv4 Packet.
*Sep 19 11:58:16.602 CDT: ISAKMP:(2087):Node 237114336, Input = IKE_MESG_INTERNAL, IKE_INIT_QM
*Sep 19 11:58:16.602 CDT: ISAKMP:(2087):Old State = IKE_QM_READY New State = IKE_QM_I_QM1
*Sep 19 11:58:16.602 CDT: ISAKMP:(2087):Input = IKE_MESG_INTERNAL, IKE_PHASE1_COMPLETE
*Sep 19 11:58:16.602 CDT: ISAKMP:(2087):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

*Sep 19 11:58:16.682 CDT: ISAKMP (2087): received packet from 216.189.255.7 dport 500 sport 500 Global (I) QM_IDLE
*Sep 19 11:58:16.682 CDT: crypto_engine: Decrypt IKE packet
*Sep 19 11:58:16.682 CDT: crypto_engine: Generate IKE hash
*Sep 19 11:58:16.682 CDT: ISAKMP:(2087): processing HASH payload. message ID = 237114336
*Sep 19 11:58:16.682 CDT: ISAKMP:(2087): processing SA payload. message ID = 237114336
*Sep 19 11:58:16.682 CDT: ISAKMP:(2087):Checking IPSec proposal 1
*Sep 19 11:58:16.682 CDT: ISAKMP: transform 1, ESP_3DES
*Sep 19 11:58:16.682 CDT: ISAKMP:   attributes in transform:
*Sep 19 11:58:16.682 CDT: ISAKMP:      encaps is 2 (Transport)
*Sep 19 11:58:16.682 CDT: ISAKMP:      SA life type in seconds
*Sep 19 11:58:16.682 CDT: ISAKMP:      SA life duration (basic) of 3600
*Sep 19 11:58:16.682 CDT: ISAKMP:      SA life type in kilobytes
*Sep 19 11:58:16.682 CDT: ISAKMP:      SA life duration (VPI) of 0x0 0x46 0x50 0x0
*Sep 19 11:58:16.682 CDT: ISAKMP:      authenticator is HMAC-MD5
*Sep 19 11:58:16.682 CDT: ISAKMP:(2087):atts are acceptable.
*Sep 19 11:58:16.686 CDT: IPSEC(validate_proposal_request): proposal part #1
*Sep 19 11:58:16.686 CDT: IPSEC(validate_proposal_request): proposal part #1,
(key eng. msg.) INBOUND local= 65.118.89.72, remote= 216.189.255.7,
    local_proxy= 65.118.89.72/255.255.255.255/47/0 (type=1),
    remote_proxy= 216.189.255.7/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= NONE (Transport),
    lifedur= 0s and 0kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
*Sep 19 11:58:16.686 CDT: Crypto mapdb : proxy_match
        src addr     : 65.118.89.72
        dst addr     : 216.189.255.7
        protocol     : 47
        src port     : 0
        dst port     : 0
*Sep 19 11:58:16.686 CDT: ISAKMP:(2087): processing NONCE payload. message ID = 237114336
*Sep 19 11:58:16.686 CDT: ISAKMP:(2087): processing ID payload. message ID = 237114336
*Sep 19 11:58:16.686 CDT: ISAKMP:(2087): processing ID payload. message ID = 237114336
*Sep 19 11:58:16.686 CDT: crypto_engine: Generate IKE hash
*Sep 19 11:58:16.686 CDT: crypto_engine: Generate IKE QM keys
*Sep 19 11:58:16.686 CDT: crypto_engine: Create IPSec SA (by keys)
*Sep 19 11:58:16.686 CDT: crypto_engine: Generate IKE QM keys
*Sep 19 11:58:16.686 CDT: crypto_engine: Create IPSec SA (by keys)
*Sep 19 11:58:16.686 CDT: ISAKMP:(2087): Creating IPSec SAs
*Sep 19 11:58:16.686 CDT:         inbound SA from 216.189.255.7 to 65.118.89.72 (f/i) 0/ 0
        (proxy 216.189.255.7 to 65.118.89.72)
*Sep 19 11:58:16.686 CDT:         has spi 0x1354F3A7 and conn_id 0
*Sep 19 11:58:16.686 CDT:         lifetime of 3600 seconds
*Sep 19 11:58:16.686 CDT:         lifetime of 4608000 kilobytes
*Sep 19 11:58:16.686 CDT:         outbound SA from 65.118.89.72 to 216.189.255.7 (f/i) 0/0
        (proxy 65.118.89.72 to 216.189.255.7)
*Sep 19 11:58:16.686 CDT:         has spi 0x9FBC2BBA and conn_id 0
*Sep 19 11:58:16.686 CDT:         lifetime of 3600 seconds
*Sep 19 11:58:16.686 CDT:         lifetime of 4608000 kilobytes
*Sep 19 11:58:16.686 CDT: crypto_engine: Encrypt IKE packet
*Sep 19 11:58:16.686 CDT: ISAKMP:(2087): sending packet to 216.189.255.7 my_port 500 peer_port 500 (I) QM_IDLE
*Sep 19 11:58:16.686 CDT: ISAKMP:(2087):Sending an IKE IPv4 Packet.
*Sep 19 11:58:16.686 CDT: ISAKMP:(2087):deleting node 237114336 error FALSE reason "No Error"
*Sep 19 11:58:16.686 CDT: ISAKMP:(2087):Node 237114336, Input = IKE_MESG_FROM_PEER, IKE_QM_EXCH
*Sep 19 11:58:16.686 CDT: ISAKMP:(2087):Old State = IKE_QM_I_QM1 New State = IKE_QM_PHASE2_COMPLETE
*Sep 19 11:58:16.690 CDT: IPSEC(key_engine): got a queue event with 1 KMI message(s)
*Sep 19 11:58:16.690 CDT: Crypto mapdb : proxy_match
        src addr     : 65.118.89.72
        dst addr     : 216.189.255.7
        protocol     : 47
        src port     : 0
        dst port     : 0
*Sep 19 11:58:16.690 CDT: IPSEC(crypto_ipsec_sa_find_ident_head): reconnecting with the same proxies and peer 216.189.255.7
*Sep 19 11:58:16.690 CDT: IPSEC(crypto_ipsec_sa_find_ident_head): added peer 216.189.255.7
*Sep 19 11:58:16.690 CDT: IPSEC(policy_db_add_ident): src 65.118.89.72, dest 216.189.255.7, dest_port 0

*Sep 19 11:58:16.690 CDT: IPSEC(create_sa): sa created,
(sa) sa_dest= 65.118.89.72, sa_proto= 50,
    sa_spi= 0x1354F3A7(324334503),
    sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 67
    sa_lifetime(k/sec)= (4445516/3600)
*Sep 19 11:58:16.690 CDT: IPSEC(create_sa): sa created,
(sa) sa_dest= 216.189.255.7, sa_proto= 50,
    sa_spi= 0x9FBC2BBA(2679909306),
    sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 68
    sa_lifetime(k/sec)= (4445516/3600)
*Sep 19 11:58:16.690 CDT: crypto engine: updating MTU size of IPSec SA Onboard VPN:68
*Sep 19 11:58:16.690 CDT: crypto_engine: Set IPSec MTU
*Sep 19 11:58:16.690 CDT: IPSEC(update_current_outbound_sa): updated peer 216.189.255.7 current outbound sa to SPI 9FBC2BBA
*Sep 19 11:59:06.686 CDT: ISAKMP:(2087):purging node 237114337

marcusauman · ‎09-28-2011

Anyone please help???

Mohammad Alhyari · ‎09-28-2011

Hi ,

an intresting would be what the other side is saying at the failure time !

please share the debugs and the config from that device

marcusauman · ‎09-28-2011

The other device is a production hub router terminating hundreds of vpn customers. I won't be able to run a debug on the production side. What are some other options? Have you seen this before?

Mohammad Alhyari · ‎09-28-2011

try conditional debugs :

debug crypto condition peer [ip address of the peer]

debug crypto isakmp

debug crypto ipsec

do you have a matching phase 1 and phase 2 lifetimes

cheers !

marcusauman · ‎09-28-2011

The life times are the same on both sides.

Below is the output from the other side of the vpn.

Sep 28 16:55:02.716: ISAKMP:(0):deleting SA reason "Death by retransmission P1" state (I) MM_NO_STATE (peer X.X.X.X)