06-03-2011 12:38 AM
Hi there,
We have configured an cisco 2800 for vpn clients. The weird thing is that after some time (not specific time interval and no idle connection) asks for re-authentication. Some times after re-authenticating session disconnects. Any ideas?
06-03-2011 01:31 AM
The re-authentication dialog happens after 49 minutes and after a while is terminated.
VPN CLIENT LOG
06-03-2011 05:25 AM
And the debug from the Router side :
.Jun 3 08:24:26.962: ISAKMP (0:0): received packet from x.x.x.31 dport 4500 sport 3350 Global (N) NEW SA
.Jun 3 08:24:26.962: ISAKMP: Found a peer struct for x.x.x.31, peer port 3350
.Jun 3 08:24:26.962: ISAKMP: Locking peer struct 0x43F9EF34, IKE refcount 2 for crypto_isakmp_process_block
.Jun 3 08:24:26.962: ISAKMP:(0:0:N/A:0):(Re)Setting client xauth list default and state
.Jun 3 08:24:26.962: ISAKMP/xauth: initializing AAA request
.Jun 3 08:24:26.966: ISAKMP: local port 4500, remote port 3350
.Jun 3 08:24:26.966: ISAKMP: Find a dup sa in the avl tree during calling isadb_insert sa = 43F1BFC8
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0): processing SA payload. message ID = 0
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0): processing ID payload. message ID = 0
.Jun 3 08:24:26.966: ISAKMP (0:0): ID payload
next-payload : 13
type : 11
group id : libgroup
protocol : 17
port : 0
length : 16
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0):: peer matches *none* of the profiles
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0): processing vendor id payload
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0): vendor ID seems Unity/DPD but major 215 mismatch
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0): vendor ID is XAUTH
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0): processing vendor id payload
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0): vendor ID is DPD
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0): processing vendor id payload
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0): vendor ID seems Unity/DPD but major 194 mismatch
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0): processing vendor id payload
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0): vendor ID seems Unity/DPD but major 123 mismatch
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0): vendor ID is NAT-T v2
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0): processing vendor id payload
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0): vendor ID is Unity
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0): local preshared key found
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0): Authentication by xauth preshared
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0):Checking ISAKMP transform 1 against priority 1 policy
.Jun 3 08:24:26.966: ISAKMP: encryption 3DES-CBC
.Jun 3 08:24:26.966: ISAKMP: hash SHA
.Jun 3 08:24:26.966: ISAKMP: default group 2
.Jun 3 08:24:26.966: ISAKMP: auth XAUTHInitPreShared
.Jun 3 08:24:26.966: ISAKMP: life type in seconds
.Jun 3 08:24:26.966: ISAKMP: life duration (VPI) of 0x0 0x20 0xC4 0x9B
.Jun 3 08:24:26.966: ISAKMP:(0:0:N/A:0):atts are acceptable. Next payload is 0
.Jun 3 08:24:26.970: CryptoEngine0: generating alg parameter for connid 695
.Jun 3 08:24:27.014: CRYPTO_ENGINE: Dh phase 1 status: 0
.Jun 3 08:24:27.014: CRYPTO_ENGINE: Dh phase 1 status: OK
.Jun 3 08:24:27.014: ISAKMP:(0:695:SW:1): processing KE payload. message ID = 0
.Jun 3 08:24:27.014: CryptoEngine0: generating alg parameter for connid 0
.Jun 3 08:24:27.062: ISAKMP:(0:695:SW:1): processing NONCE payload. message ID = 0
.Jun 3 08:24:27.066: CryptoEngine0: create ISAKMP SKEYID for conn id 695
.Jun 3 08:24:27.066: ISAKMP:(0:695:SW:1):SKEYID state generated
.Jun 3 08:24:27.066: ISAKMP:(0:695:SW:1): vendor ID is NAT-T v2
.Jun 3 08:24:27.066: ISAKMP:(0:695:SW:1): constructed NAT-T vendor-02 ID
.Jun 3 08:24:27.066: ISAKMP:(0:695:SW:1):SA is doing pre-shared key authentication plus XAUTH using id type ID_IPV4_ADDR
.Jun 3 08:24:27.066: ISAKMP (0:134218423): ID payload
next-payload : 10
type : 1
address : x.x.x.98
protocol : 0
port : 0
length : 12
.Jun 3 08:24:27.066: ISAKMP:(0:695:SW:1):Total payload length: 12
.Jun 3 08:24:27.066: CryptoEngine0: generate hmac context for conn id 695
.Jun 3 08:24:27.070: ISAKMP:(0:695:SW:1): sending packet to x.x.x.31 my_port 4500 peer_port 3350 (R) AG_INIT_EXCH
.Jun 3 08:24:27.070: ISAKMP:(0:695:SW:1):Input = IKE_MESG_FROM_PEER, IKE_AM_EXCH
.Jun 3 08:24:27.070: ISAKMP:(0:695:SW:1):Old State = IKE_READY New State = IKE_R_AM2
.Jun 3 08:24:27.130: ISAKMP (0:134218423): received packet from x.x.x.31 dport 4500 sport 3350 Global (R) AG_INIT_EXCH
.Jun 3 08:24:27.130: ISAKMP:(0:695:SW:1): processing HASH payload. message ID = 0
.Jun 3 08:24:27.130: CryptoEngine0: generate hmac context for conn id 695
.Jun 3 08:24:27.130: ISAKMP:received payload type 20
.Jun 3 08:24:27.130: ISAKMP:received payload type 20
.Jun 3 08:24:27.130: ISAKMP (0:134218423): NAT found, the node outside NAT
.Jun 3 08:24:27.130: ISAKMP:(0:695:SW:1):SA authentication status:
authenticated
.Jun 3 08:24:27.130: ISAKMP:(0:695:SW:1):SA has been authenticated with x.x.x.31
.Jun 3 08:24:27.130: CryptoEngine0: clear dh number for conn id 1
.Jun 3 08:24:27.130: ISAKMP:(0:695:SW:1):Detected port,floating to port = 3350
.Jun 3 08:24:27.130: ISAKMP:(0:695:SW:1):IKE_DPD is enabled, initializing timers
.Jun 3 08:24:27.134: ISAKMP: set new node 513846090 to CONF_XAUTH
.Jun 3 08:24:27.134: CryptoEngine0: generate hmac context for conn id 695
.Jun 3 08:24:27.134: ISAKMP:(0:695:SW:1):Sending NOTIFY RESPONDER_LIFETIME protocol 1
spi 1131454480, message ID = 513846090
.Jun 3 08:24:27.134: ISAKMP:(0:695:SW:1): sending packet to x.x.x.31 my_port 4500 peer_port 3350 (R) QM_IDLE
.Jun 3 08:24:27.134: ISAKMP:(0:695:SW:1):purging node 513846090
.Jun 3 08:24:27.134: ISAKMP: Sending phase 1 responder lifetime 3600
.Jun 3 08:24:27.134: ISAKMP:(0:695:SW:1):Input = IKE_MESG_FROM_PEER, IKE_AM_EXCH
.Jun 3 08:24:27.134: ISAKMP:(0:695:SW:1):Old State = IKE_R_AM2 New State = IKE_P1_COMPLETE
.Jun 3 08:24:27.134: ISAKMP:(0:695:SW:1):Need XAUTH
.Jun 3 08:24:27.134: ISAKMP: set new node -1912145085 to CONF_XAUTH
.Jun 3 08:24:27.134: ISAKMP/xauth: request attribute XAUTH_USER_NAME_V2
.Jun 3 08:24:27.134: ISAKMP/xauth: request attribute XAUTH_USER_PASSWORD_V2
.Jun 3 08:24:27.134: CryptoEngine0: generate hmac context for conn id 695
.Jun 3 08:24:27.138: ISAKMP:(0:695:SW:1): initiating peer config to x.x.x.31. ID = -1912145085
.Jun 3 08:24:27.138: ISAKMP:(0:695:SW:1): sending packet to x.x.x.31 my_port 4500 peer_port 3350 (R) CONF_XAUTH
.Jun 3 08:24:27.138: ISAKMP:(0:695:SW:1):Input = IKE_MESG_INTERNAL, IKE_PHASE1_COMPLETE
.Jun 3 08:24:27.138: ISAKMP:(0:695:SW:1):Old State = IKE_P1_COMPLETE New State = IKE_XAUTH_REQ_SENT
.Jun 3 08:24:35.239: ISAKMP (0:134218419): received packet from x.x.x.31 dport 4500 sport 3350 Global (R) QM_IDLE
.Jun 3 08:24:35.239: ISAKMP: set new node -286091061 to CONF_XAUTH
.Jun 3 08:24:35.243: CryptoEngine0: generate hmac context for conn id 691
.Jun 3 08:24:35.243: ISAKMP:(0:691:SW:1): processing HASH payload. message ID = -286091061
.Jun 3 08:24:35.243: ISAKMP:(0:691:SW:1): processing NOTIFY DPD/R_U_THERE protocol 1
spi 0, message ID = -286091061, sa = 43EB9BD4
.Jun 3 08:24:35.243: ISAKMP:(0:691:SW:1):deleting node -286091061 error FALSE reason "Informational (in) state 1"
.Jun 3 08:24:35.243: ISAKMP:(0:691:SW:1):Input = IKE_MESG_FROM_PEER, IKE_INFO_NOTIFY
.Jun 3 08:24:35.243: ISAKMP:(0:691:SW:1):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE
.Jun 3 08:24:35.243: ISAKMP:(0:691:SW:1):DPD/R_U_THERE received from peer x.x.x.31, sequence 0x2F42D3CD
.Jun 3 08:24:35.243: ISAKMP: set new node 833161988 to CONF_XAUTH
.Jun 3 08:24:35.243: CryptoEngine0: generate hmac context for conn id 691
.Jun 3 08:24:35.243: ISAKMP:(0:691:SW:1):Sending NOTIFY DPD/R_U_THERE_ACK protocol 1
spi 1131454520, message ID = 833161988
.Jun 3 08:24:35.243: ISAKMP:(0:691:SW:1): seq. no 0x2F42D3CD
.Jun 3 08:24:35.247: ISAKMP:(0:691:SW:1): sending packet to x.x.x.31 my_port 4500 peer_port 3350 (R) QM_IDLE
.Jun 3 08:24:35.247: ISAKMP:(0:691:SW:1):purging node 833161988
.Jun 3 08:24:35.247: ISAKMP:(0:691:SW:1):Input = IKE_MESG_FROM_PEER, IKE_MESG_KEEP_ALIVE
.Jun 3 08:24:35.247: ISAKMP:(0:691:SW:1):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE
.Jun 3 08:24:40.783: ISAKMP (0:134218419): received packet from x.x.x.31 dport 4500 sport 3350 Global (R) QM_IDLE
.Jun 3 08:24:40.783: ISAKMP: set new node -1441252788 to CONF_XAUTH
.Jun 3 08:24:40.783: ISAKMP:(0:691:SW:1):Need XAUTH
.Jun 3 08:24:40.783: ISAKMP: set new node 383198132 to CONF_XAUTH
.Jun 3 08:24:40.783: ISAKMP/xauth: request attribute XAUTH_USER_PASSWORD_V2
.Jun 3 08:24:40.783: ISAKMP/xauth: request attribute XAUTH_REQ_NUMBER
.Jun 3 08:24:40.783: CryptoEngine0: generate hmac context for conn id 691
.Jun 3 08:24:40.787: ISAKMP:(0:691:SW:1): initiating peer config to x.x.x.31. ID = 383198132
.Jun 3 08:24:40.787: ISAKMP:(0:691:SW:1): sending packet to x.x.x.31 my_port 4500 peer_port 3350 (R) CONF_XAUTH
.Jun 3 08:24:40.787: ISAKMP:(0:691:SW:1):Input = IKE_MESG_INTERNAL, IKE_PHASE1_COMPLETE
.Jun 3 08:24:40.787: ISAKMP:(0:691:SW:1):Old State = IKE_P1_COMPLETE New State = IKE_XAUTH_REQ_SENT
.Jun 3 08:24:42.139: ISAKMP:(0:695:SW:1): retransmitting phase 2 CONF_XAUTH -1912145085 ...
.Jun 3 08:24:42.139: ISAKMP (0:134218423): incrementing error counter on node, attempt 1 of 5: retransmit phase 2
.Jun 3 08:24:42.139: ISAKMP (0:134218423): incrementing error counter on sa, attempt 1 of 5: retransmit phase 2
.Jun 3 08:24:42.139: ISAKMP:(0:695:SW:1): retransmitting phase 2 -1912145085 CONF_XAUTH
.Jun 3 08:24:42.139: ISAKMP:(0:695:SW:1): sending packet to x.x.x.31 my_port 4500 peer_port 3350 (R) CONF_XAUTH
.Jun 3 08:24:43.079: ISAKMP (0:134218423): received packet from x.x.x.31 dport 4500 sport 3350 Global (R) CONF_XAUTH
.Jun 3 08:24:43.079: ISAKMP:(0:695:SW:1):processing transaction payload from x.x.x.31. message ID = -1912145085
.Jun 3 08:24:43.079: CryptoEngine0: generate hmac context for conn id 695
.Jun 3 08:24:43.079: ISAKMP: Config payload REPLY
.Jun 3 08:24:43.079: ISAKMP/xauth: reply attribute XAUTH_USER_NAME_V2 unexpected.
.Jun 3 08:24:43.079: ISAKMP/xauth: reply attribute XAUTH_USER_PASSWORD_V2
.Jun 3 08:24:43.079: ISAKMP:(0:695:SW:1):deleting node -1912145085 error FALSE reason "Done with xauth request/reply exchange"
.Jun 3 08:24:43.079: ISAKMP:(0:695:SW:1):Input = IKE_MESG_FROM_PEER, IKE_CFG_REPLY
.Jun 3 08:24:43.079: ISAKMP:(0:695:SW:1):Old State = IKE_XAUTH_REQ_SENT New State = IKE_XAUTH_AAA_CONT_LOGIN_AWAIT
.Jun 3 08:24:43.079: RADIUS/ENCODE(00001E0B):Orig. component type = VPN_IPSEC
.Jun 3 08:24:43.079: RADIUS: AAA Unsupported Attr: interface [157] 14
.Jun 3 08:24:43.083: RADIUS: 31 39 35 2E 31 36 37 2E 31 30 32 2E [195.167.102.]
.Jun 3 08:24:43.083: RADIUS/ENCODE(00001E0B): dropping service type, "radius-server attribute 6 on-for-login-auth" is off
.Jun 3 08:24:43.083: RADIUS(00001E0B): Config NAS IP: 10.65.127.251
.Jun 3 08:24:43.083: RADIUS/ENCODE(00001E0B): acct_session_id: 7691
.Jun 3 08:24:43.083: RADIUS(00001E0B): sending
.Jun 3 08:24:43.083: RADIUS(00001E0B): Send Access-Request to 10.65.2.8:1812 id 1645/50, len 93
.Jun 3 08:24:43.083: RADIUS: authenticator C9 1B CD 5E 66 EB 06 9A - AA EA A5 B2 FA 90 58 5D
.Jun 3 08:24:43.083: RADIUS: User-Name [1] 8 "vpnlib"
.Jun 3 08:24:43.083: RADIUS: User-Password [2] 18 *
.Jun 3 08:24:43.083: RADIUS: Calling-Station-Id [31] 13 "x.x.x.31"
.Jun 3 08:24:43.083: RADIUS: NAS-Port-Type [61] 6 Virtual [5]
.Jun 3 08:24:43.083: RADIUS: NAS-Port [5] 6 4
.Jun 3 08:24:43.083: RADIUS: NAS-Port-Id [87] 16 "x.x.x.98"
.Jun 3 08:24:43.083: RADIUS: NAS-IP-Address [4] 6 10.65.127.251
.Jun 3 08:24:43.095: RADIUS: Received from id 1645/50 10.65.2.8:1812, Access-Accept, len 107
.Jun 3 08:24:43.095: RADIUS: authenticator 70 90 D1 B6 75 55 24 48 - 29 4F 5A 36 5E 85 56 DD
.Jun 3 08:24:43.095: RADIUS: Service-Type [6] 6 Login [1]
.Jun 3 08:24:43.095: RADIUS: Class [25] 32
.Jun 3 08:24:43.095: RADIUS: 24 71 03 79 00 00 01 37 00 01 0A 41 02 08 01 CC [$q?y???7???A????]
.Jun 3 08:24:43.095: RADIUS: 16 08 30 22 37 80 00 00 00 00 00 00 00 F6 [??0"7?????????]
.Jun 3 08:24:43.095: RADIUS: Vendor, Cisco [26] 25
.Jun 3 08:24:43.095: RADIUS: Cisco AVpair [1] 19 "shell:priv-lvl=15"
.Jun 3 08:24:43.095: RADIUS: Vendor, Microsoft [26] 12
.Jun 3 08:24:43.095: RADIUS: MS-MPPE-Enc-Policy [7] 6
.Jun 3 08:24:43.095: RADIUS: 00 00 00 01 [????]
.Jun 3 08:24:43.095: RADIUS: Vendor, Microsoft [26] 12
.Jun 3 08:24:43.099: RADIUS: MS-MPPE-Enc-Type [8] 6
.Jun 3 08:24:43.099: RADIUS: 00 00 00 00 [????]
.Jun 3 08:24:43.099: RADIUS(00001E0B): Received from id 1645/50
.Jun 3 08:24:43.099: ISAKMP: set new node -780195774 to CONF_XAUTH
.Jun 3 08:24:43.099: CryptoEngine0: generate hmac context for conn id 695
.Jun 3 08:24:43.099: ISAKMP:(0:695:SW:1): initiating peer config to x.x.x.31. ID = -780195774
.Jun 3 08:24:43.099: ISAKMP:(0:695:SW:1): sending packet to x.x.x.31 my_port 4500 peer_port 3350 (R) CONF_XAUTH
.Jun 3 08:24:43.103: ISAKMP:(0:695:SW:1):Input = IKE_MESG_FROM_AAA, IKE_AAA_CONT_LOGIN
.Jun 3 08:24:43.103: ISAKMP:(0:695:SW:1):Old State = IKE_XAUTH_AAA_CONT_LOGIN_AWAIT New State = IKE_XAUTH_SET_SENT
.Jun 3 08:24:43.123: ISAKMP (0:134218423): received packet from x.x.x.31 dport 4500 sport 3350 Global (R) CONF_XAUTH
.Jun 3 08:24:43.123: ISAKMP:(0:695:SW:1):processing transaction payload from x.x.x.31. message ID = -780195774
.Jun 3 08:24:43.127: CryptoEngine0: generate hmac context for conn id 695
.Jun 3 08:24:43.127: ISAKMP: Config payload ACK
.Jun 3 08:24:43.127: ISAKMP:(0:695:SW:1): (blank) XAUTH ACK Processed
.Jun 3 08:24:43.127: ISAKMP:(0:695:SW:1):deleting node -780195774 error FALSE reason "Transaction mode done"
.Jun 3 08:24:43.127: ISAKMP:(0:695:SW:1):Input = IKE_MESG_FROM_PEER, IKE_CFG_ACK
.Jun 3 08:24:43.127: ISAKMP:(0:695:SW:1):Old State = IKE_XAUTH_SET_SENT New State = IKE_P1_COMPLETE
.Jun 3 08:24:43.127: ISAKMP:(0:695:SW:1):Input = IKE_MESG_INTERNAL, IKE_PHASE1_COMPLETE
.Jun 3 08:24:43.127: ISAKMP:(0:695:SW:1):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE
.Jun 3 08:24:46.259: ISAKMP (0:134218419): received packet from x.x.x.31 dport 4500 sport 3350 Global (R) CONF_XAUTH
.Jun 3 08:24:51.259: ISAKMP (0:134218419): received packet from x.x.x.31 dport 4500 sport 3350 Global (R) CONF_XAUTH
Discover and save your favorite ideas. Come back to expert answers, step-by-step guides, recent topics, and more.
New here? Get started with these tips. How to use Community New member guide