Cisco vpn client asks for re-authentication! - Cisco Community

1133

Views

0

Helpful

2

Replies

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?

2 Replies 2

The re-authentication dialog happens after 49 minutes and after a while is terminated.

VPN CLIENT LOG

73 11:19:54.625 06/03/11 Sev=Warning/2 IKE/0xE300009B
Cannot accept a new Xauth message (NavigatorTM:318)

74 11:19:54.640 06/03/11 Sev=Warning/2 IKE/0xE300009B
Received unexpected TM message from peer (NavigatorTM:627)

75 11:20:09.625 06/03/11 Sev=Warning/2 IKE/0xE300009B
Cannot accept a new Xauth message (NavigatorTM:318)

76 11:20:09.625 06/03/11 Sev=Warning/2 IKE/0xE300009B
Received unexpected TM message from peer (NavigatorTM:627)

77 11:20:24.625 06/03/11 Sev=Warning/2 IKE/0xE300009B
Cannot accept a new Xauth message (NavigatorTM:318)

78 11:20:24.625 06/03/11 Sev=Warning/2 IKE/0xE300009B
Received unexpected TM message from peer (NavigatorTM:627)

79 11:20:39.625 06/03/11 Sev=Warning/2 IKE/0xE300009B
Cannot accept a new Xauth message (NavigatorTM:318)

80 11:20:39.625 06/03/11 Sev=Warning/2 IKE/0xE300009B
Received unexpected TM message from peer (NavigatorTM:627)

81 11:20:54.625 06/03/11 Sev=Warning/2 IKE/0xE300009B
Cannot accept a new Xauth message (NavigatorTM:318)

82 11:20:54.625 06/03/11 Sev=Warning/2 IKE/0xE300009B
Received unexpected TM message from peer (NavigatorTM:627)

83 11:21:09.640 06/03/11 Sev=Warning/2 IKE/0xE300009B
Cannot accept a new Xauth message (NavigatorTM:318)

84 11:21:09.640 06/03/11 Sev=Warning/2 IKE/0xE300009B
Received unexpected TM message from peer (NavigatorTM:627)

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

Learn, share, save

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

Log in to Community