ezVPN stuck at IKE

ZbigniewJ · ‎12-18-2012

Hello, i'd like to ask more experienced colleagues to help me solve my problem.

I have hub and spoke ezVPN network with 2901 as the hub and aprox. 30 1941's as spokes connected via Internet (aDSL)

The configuration on all of them is identical yet sometimes some of them drop the ezVPN tunnel and fail to establish new one.

To be clear - the tunnel works and suddenly, out of nowhere, with no configuration change it goes belly up. In example below it happened yesterday, in the middle of the night.

As a hint i'll add that there is a DMVPN tunnel terminated on this router and it works perfectly fine

Please help!

Here's my debug:

C1941#

.Dec 18 10:14:52.413 CET: %CRYPTO-4-EZVPN_FAILED_TO_CONNECT: EZVPN(XXX) Ezvpn is in state READY, previous state was CONNECT_REQUIRED and event is CONN_UP. Session is not up after 180 seconds of initiating session, resetting the connection

.Dec 18 10:14:52.413 CET: %CRYPTO-6-EZVPN_CONNECTION_DOWN: (Client) User=bsezvpn Group=GR-EZVPN Server_public_addr=x.x.160.6

.Dec 18 10:14:52.413 CET: ISAKMP:isadb_key_addr_delete: no key for address x.x.160.6 (NULL root)

.Dec 18 10:14:52.417 CET: ISAKMP:(1624):peer does not do paranoid keepalives.

.Dec 18 10:14:52.417 CET: ISAKMP:(1624):deleting SA reason "gen_ipsec_isakmp_delete but doi isakmp" state (I) CONF_ADDR (peer x.x.160.6)

.Dec 18 10:14:52.417 CET: ISAKMP: set new node 612223480 to CONF_ADDR

.Dec 18 10:14:52.417 CET: ISAKMP:(1624): sending packet to x.x.160.6 my_port 4500 peer_port 4500 (I) CONF_ADDR

.Dec 18 10:14:52.417 CET: ISAKMP:(1624):Sending an IKE IPv4 Packet.

.Dec 18 10:14:52.417 CET: ISAKMP:(1624):purging node 612223480

.Dec 18 10:14:52.417 CET: ISAKMP:(1624):Input = IKE_MESG_INTERNAL, IKE_PHASE1_DEL

.Dec 18 10:14:52.417 CET: ISAKMP:(1624):Old State = IKE_CONFIG_MODE_REQ_SENT New State = IKE_DEST_SA

.Dec 18 10:14:52.417 CET: ISAKMP:(1624):deleting SA reason "gen_ipsec_isakmp_delete but doi isakmp" state (I) CONF_ADDR (peer x.x.160.6)

.Dec 18 10:14:52.417 CET: ISAKMP:(0):Can't decrement IKE Call Admission Control stat outgoing_active since it's already 0.

.Dec 18 10:14:52.417 CET: ISAKMP: Unlocking peer struct 0x31310A08 for isadb_mark_sa_deleted(), count 174

.Dec 18 10:14:52.417 CET: ISAKMP:(1624):deleting node -1802304850 error FALSE reason "IKE deleted"

C1941#

.Dec 18 10:14:52.417 CET: ISAKMP:(1624):deleting node -2038444066 error FALSE reason "IKE deleted"

.Dec 18 10:14:52.417 CET: ISAKMP:(1624):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH

.Dec 18 10:14:52.417 CET: ISAKMP:(1624):Old State = IKE_DEST_SA New State = IKE_DEST_SA

.Dec 18 10:14:52.417 CET: ISAKMP:isadb_key_addr_delete: no key for address x.x.160.6 (NULL root)

.Dec 18 10:14:52.441 CET: ISAKMP (1624): received packet from x.x.160.6 dport 4500 sport 4500 Global (I) MM_NO_STATE

.Dec 18 10:14:54.077 CET: del_node src y.y.30.142:4500 dst x.x.160.6:4500 fvrf 0x0, ivrf 0x0

.Dec 18 10:14:54.077 CET: ISAKMP:(1624):peer does not do paranoid keepalives.

.Dec 18 10:14:54.077 CET: ISAKMP:(0): SA request profile is (NULL)

.Dec 18 10:14:54.077 CET: ISAKMP: Created a peer struct for x.x.160.6, peer port 500

.Dec 18 10:14:54.077 CET: ISAKMP: New peer created peer = 0x3164DEB0 peer_handle = 0x80000510

.Dec 18 10:14:54.077 CET: ISAKMP: Locking peer struct 0x3164DEB0, refcount 1 for isakmp_initiator

.Dec 18 10:14:54.077 CET: ISAKMP:(0):Setting client config settings 276E6B28

.Dec 18 10:14:54.077 CET: ISAKMP: local port 500, remote port 500

.Dec 18 10:14:54.077 CET: ISAKMP: Find a dup sa in the avl tree during calling isadb_insert sa = 276E4968

.Dec 18 10:14:54.077 CET: ISAKMP:(0): client mode configured.

.Dec 18 10:14:54.077 CET: ISAKMP:(0): constructed NAT-T vendor-rfc3947 ID

.Dec 18 10:14:54.077 CET: ISAKMP:(0): constructed NAT-T vendor-07 ID

.Dec 18 10:14:54.077 CET: ISAKMP:(0): constructed NAT-T vendor-03 ID

.Dec 18 10:14:54.077 CET: ISAKMP:(0): constructed NAT-T vendor-02 ID

.Dec 18 10:14:54.097 CET: ISKAMP: growing send buffer from 1024 to 3072

.Dec 18 10:14:54.097 CET: ISAKMP:(0):SA is doing pre-shared key authentication plus XAUTH using id type ID_KEY_ID

.Dec 18 10:14:54.097 CET: ISAKMP (0): ID payload

next-payload : 13

type : 11

group id : GR-XX-EZVPN

protocol : 17

port : 0

length : 19

.Dec 18 10:14:54.097 CET: ISAKMP:(0):Total payload length: 19

.Dec 18 10:14:54.097 CET: ISAKMP:(0):Input = IKE_MESG_FROM_IPSEC, IKE_SA_REQ_AM

.Dec 18 10:14:54.097 CET: ISAKMP:(0):Old State = IKE_READY New State = IKE_I_AM1

.Dec 18 10:14:54.097 CET: ISAKMP:(0): beginning Aggressive Mode exchange

.Dec 18 10:14:54.097 CET: ISAKMP:(0): sending packet to x.x.160.6 my_port 500 peer_port 500 (I) AG_INIT_EXCH

.Dec 18 10:14:54.097 CET: ISAKMP:(0):Sending an IKE IPv4 Packet.

.Dec 18 10:14:54.169 CET: ISAKMP (0): received packet from x.x.160.6 dport 500 sport 500 Global (I) AG_INIT_EXCH

.Dec 18 10:14:54.173 CET: ISAKMP:(0): processing SA payload. message ID = 0

.Dec 18 10:14:54.173 CET: ISAKMP:(0): processing ID payload. message ID = 0

.Dec 18 10:14:54.173 CET: ISAKMP:(0):: peer matches *none* of the profiles

.Dec 18 10:14:54.173 CET: ISAKMP:(0): processing vendor id payload

.Dec 18 10:14:54.173 CET: ISAKMP:(0): vendor ID is Unity

.Dec 18 10:14:54.173 CET: ISAKMP:(0): processing vendor id payload

.Dec 18 10:14:54.173 CET: ISAKMP:(0): vendor ID is DPD

.Dec 18 10:14:54.173 CET: ISAKMP:(0): processing vendor id payload

.Dec 18 10:14:54.173 CET: ISAKMP:(0): speaking to another IOS box!

.Dec 18 10:14:54.173 CET: ISAKMP:(0):found peer pre-shared key matching x.x.160.6

.Dec 18 10:14:54.173 CET: ISAKMP:(0): local preshared key found

.Dec 18 10:14:54.173 CET: ISAKMP : Scanning profiles for xauth ...

.Dec 18 10:14:54.173 CET: ISAKMP:(0): Authentication by xauth preshared

.Dec 18 10:14:54.173 CET: ISAKMP:(0):Checking ISAKMP transform 1 against priority 65515 policy

.Dec 18 10:14:54.173 CET: ISAKMP: ......

<ommit>

ISAKKMP proposals

</ommit>

.Dec 18 10:14:54.173 CET: ISAKMP:(0):Acceptable atts:actual life: 2147483

.Dec 18 10:14:54.173 CET: ISAKMP:(0):Acceptable atts:life: 0

.Dec 18 10:14:54.173 CET: ISAKMP:(0):Fill atts in sa vpi_length:4

.Dec 18 10:14:54.173 CET: ISAKMP:(0):Fill atts in sa life_in_seconds:2147483

.Dec 18 10:14:54.173 CET: ISAKMP:(0):Returning Actual lifetime: 2147483

.Dec 18 10:14:54.173 CET: ISAKMP:(0)::Started lifetime timer: 2147483.

.Dec 18 10:14:54.173 CET: ISAKMP (0): vendor ID is NAT-T RFC 3947

.Dec 18 10:14:54.173 CET: ISAKMP:(0): processing KE payload. message ID = 0

.Dec 18 10:14:54.201 CET: ISAKMP:(0): processing NONCE payload. message ID = 0

.Dec 18 10:14:54.201 CET: ISAKMP: no pre-shared key based on address 10.7.197.31!

.Dec 18 10:14:54.201 CET: ISAKMP:(0):found peer pre-shared key matching x.x.160.6

.Dec 18 10:14:54.201 CET: ISAKMP:(1625): processing HASH payload. message ID = 0

.Dec 18 10:14:54.201 CET: ISAKMP:received payload type 20

.Dec 18 10:14:54.201 CET: ISAKMP (1625): His hash no match - this node outside NAT

.Dec 18 10:14:54.201 CET: ISAKMP:received payload type 20

.Dec 18 10:14:54.201 CET: ISAKMP (1625): His hash no match - this node outside NAT

.Dec 18 10:14:54.201 CET: ISAKMP:(1625):SA authentication status:

authenticated

.Dec 18 10:14:54.201 CET: ISAKMP:(1625):SA has been authenticated with x.x.160.6

.Dec 18 10:14:54.201 CET: ISAKMP: Trying to insert a peer y.y.30.142/x.x.160.6/4500/, and found existing one 31310A08 to reuse, free 3164DEB0

.Dec 18 10:14:54.201 CET: ISAKMP: Unlocking peer struct 0x3164DEB0 Reuse existing peer, count 0

.Dec 18 10:14:54.201 CET: ISAKMP: Deleting peer node by peer_reap for x.x.160.6: 3164DEB0

.Dec 18 10:14:54.201 CET: ISAKMP: Locking peer struct 0x31310A08, refcount 176 for Reuse existing peer

.Dec 18 10:14:54.201 CET: ISAKMP:(1625):Send initial contact

.Dec 18 10:14:54.201 CET: ISAKMP:(1625): sending packet to x.x.160.6 my_port 4500 peer_port 4500 (I) AG_INIT_EXCH

.Dec 18 10:14:54.201 CET: ISAKMP:(1625):Sending an IKE IPv4 Packet.

.Dec 18 10:14:54.201 CET: ISAKMP:(1625):Input = IKE_MESG_FROM_PEER, IKE_AM_EXCH

.Dec 18 10:14:54.201 CET: ISAKMP:(1625):Old State = IKE_I_AM1 New State = IKE_P1_COMPLETE

.Dec 18 10:14:54.201 CET: ISAKMP:(1625):Need config/address

.Dec 18 10:14:54.201 CET: ISAKMP: set new node 1499583236 to CONF_ADDR

.Dec 18 10:14:54.201 CET: ISAKMP: Sending APPLICATION_VERSION string: Cisco IOS Software, C1900 Software (C1900-UNIVERSALK9-M), Version 15.0(1)M2, RELEASE SOFTWARE (fc2)

Technical Support: http://www.cisco.com/techsupport

Compiled Wed 10-Mar-10 22:27 by prod_rel_team

.Dec 18 10:14:54.201 CET: ISAKMP:(1625): initiating peer config to x.x.160.6. ID = 1499583236

.Dec 18 10:14:54.201 CET: ISAKMP:(1625): sending packet to x.x.160.6 my_port 4500 peer_port 4500 (I) CONF_ADDR

.Dec 18 10:14:54.201 CET: ISAKMP:(1625):Sending an IKE IPv4 Packet.

.Dec 18 10:14:54.205 CET: ISAKMP:(1625):Input = IKE_MESG_INTERNAL, IKE_PHASE1_COMPLETE

.Dec 18 10:14:54.205 CET: ISAKMP:(1625):Old State = IKE_P1_COMPLETE New State = IKE_CONFIG_MODE_REQ_SENT

.Dec 18 10:14:54.373 CET: ISAKMP (1625): received packet from x.x.160.6 dport 4500 sport 4500 Global (I) CONF_ADDR

.Dec 18 10:14:54.373 CET: ISAKMP: set new node -1008400979 to CONF_ADDR

.Dec 18 10:14:54.377 CET: ISAKMP:(1625): processing HASH payload. message ID = -1008400979

.Dec 18 10:14:54.377 CET: ISAKMP:(1625): processing NOTIFY RESPONDER_LIFETIME protocol 1

spi 0, message ID = -1008400979, sa = 276E4968

.Dec 18 10:14:54.377 CET: ISAKMP:(1625):SA authentication status:

authenticated

.Dec 18 10:14:54.377 CET: ISAKMP:(1625): processing responder lifetime

.Dec 18 10:14:54.377 CET: ISAKMP:(1625): start processing isakmp responder lifetime

.Dec 18 10:14:54.377 CET: ISAKMP:(1625):Returning Actual lifetime: 2147483

.Dec 18 10:14:54.377 CET: ISAKMP:(1625): restart ike sa timer to 86400 secs

.Dec 18 10:14:54.377 CET: ISAKMP:(1625):Started lifetime timer: 0.

.Dec 18 10:14:54.377 CET: ISAKMP:(1625):deleting node -1008400979 error FALSE reason "Informational (in) state 1"

.Dec 18 10:14:54.377 CET: ISAKMP:(1625):Input = IKE_MESG_FROM_PEER, IKE_INFO_NOTIFY

.Dec 18 10:14:54.377 CET: ISAKMP:(1625):Old State = IKE_CONFIG_MODE_REQ_SENT New State = IKE_CONFIG_MODE_REQ_SENT

**************** more interesting things now ************

.Dec 18 10:14:54.377 CET: ISAKMP (1625): received packet from x.x.160.6 dport 4500 sport 4500 Global (I) CONF_ADDR

.Dec 18 10:14:54.377 CET: ISAKMP: set new node -823043370 to CONF_ADDR

.Dec 18 10:14:54.377 CET: ISAKMP:(1625):processing transaction payload from x.x.160.6. message ID = -823043370

.Dec 18 10:14:54.377 CET: ISAKMP: Config payload REQUEST

.Dec 18 10:14:54.377 CET: ISAKMP (1625): Unknown Input IKE_MESG_FROM_PEER, IKE_CFG_REQUEST: state = IKE_CONFIG_MODE_REQ_SENT

.Dec 18 10:14:54.377 CET: ISAKMP:(1625):Input = IKE_MESG_FROM_PEER, IKE_CFG_REQUEST

.Dec 18 10:14:54.377 CET: ISAKMP:(1625):Old State = IKE_CONFIG_MODE_REQ_SENT New State = IKE_CONFIG_MODE_REQ_SENT.

C1941#

.Dec 18 10:15:09.377 CET: ISAKMP (1625): received packet from x.x.160.6 dport 4500 sport 4500 Global (I) CONF_ADDR

.Dec 18 10:15:09.377 CET: ISAKMP:(1625):processing transaction payload from x.x.160.6. message ID = -823043370

.Dec 18 10:15:09.377 CET: ISAKMP: Config payload REQUEST

.Dec 18 10:15:09.377 CET: ISAKMP (1625): Unknown Input IKE_MESG_FROM_PEER, IKE_CFG_REQUEST: state = IKE_CONFIG_MODE_REQ_SENT

.Dec 18 10:15:09.377 CET: ISAKMP:(1625):Input = IKE_MESG_FROM_PEER, IKE_CFG_REQUEST

.Dec 18 10:15:09.377 CET: ISAKMP:(1625):Old State = IKE_CONFIG_MODE_REQ_SENT New State = IKE_CONFIG_MODE_REQ_SENT

C1941#

.Dec 18 10:15:24.373 CET: ISAKMP (1625): received packet from x.x.160.6 dport 4500 sport 4500 Global (I) CONF_ADDR

.Dec 18 10:15:24.373 CET: ISAKMP:(1625):processing transaction payload from x.x.160.6. message ID = -823043370

.Dec 18 10:15:24.373 CET: ISAKMP: Config payload REQUEST

.Dec 18 10:15:24.373 CET: ISAKMP (1625): Unknown Input IKE_MESG_FROM_PEER, IKE_CFG_REQUEST: state = IKE_CONFIG_MODE_REQ_SENT

.Dec 18 10:15:24.373 CET: ISAKMP:(1625):Input = IKE_MESG_FROM_PEER, IKE_CFG_REQUEST

.Dec 18 10:15:24.373 CET: ISAKMP:(1625):Old State = IKE_CONFIG_MODE_REQ_SENT New State = IKE_CONFIG_MODE_REQ_SENT

C1941#

.Dec 18 10:15:54.373 CET: ISAKMP (1625): received packet from x.x.160.6 dport 4500 sport 4500 Global (I) CONF_ADDR

.Dec 18 10:15:54.373 CET: ISAKMP:(1625):processing transaction payload from x.x.160.6. message ID = -823043370

.Dec 18 10:15:54.373 CET: ISAKMP: Config payload REQUEST

.Dec 18 10:15:54.373 CET: ISAKMP (1625): Unknown Input IKE_MESG_FROM_PEER, IKE_CFG_REQUEST: state = IKE_CONFIG_MODE_REQ_SENT

.Dec 18 10:15:54.377 CET: ISAKMP:(1625):Input = IKE_MESG_FROM_PEER, IKE_CFG_REQUEST

.Dec 18 10:15:54.377 CET: ISAKMP:(1625):Old State = IKE_CONFIG_MODE_REQ_SENT New State = IKE_CONFIG_MODE_REQ_SENT

over and over........

Vitaliy Buchyn · ‎10-13-2015

Hello,

a bit late answer, but anyway, I've got the same issue, and the reason was a double NAT\PAT from one of the tunnel side, because of LTE modem and provider IP addressing policy.

hope this will help.