05-20-2002 05:29 AM - edited 02-21-2020 11:45 AM
Hi:
We have a VPN solution based on the securID with ACE server seems to be not working with Cisco client 3.5.1 and Cisco 2621 .The actual problem is with the authentication phase. Please find the log and debug files for the same as attached and somebody do advise me if anyone faced and solved the same problem as ours.
Thnx
Raj
VPN client log
1 22:06:08.187 04/08/02 Sev=Info/6 DIALER/0x63300006
Disconnecting connection.
2 22:06:08.203 04/08/02 Sev=Info/4 CM/0x6310000A
Secure connections terminated
3 22:06:08.203 04/08/02 Sev=Info/5 IKE/0x63000018
Deleting IPsec SA: (OUTBOUND SPI = 28A5CE19 INBOUND SPI = CB7E3DF1)
4 22:06:08.203 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK INFO *(HASH, DEL) to 203.199.202.73
5 22:06:08.203 04/08/02 Sev=Info/5 IKE/0x63000018
Deleting IPsec SA: (OUTBOUND SPI = CC9F7C93 INBOUND SPI = 44C27972)
6 22:06:08.203 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK INFO *(HASH, DEL) to 203.199.202.73
7 22:06:08.203 04/08/02 Sev=Info/5 IKE/0x63000017
Marking IKE SA for deletion (COOKIES = 924C7FA1CAEF88CB 54C4ACECFFF2ECAE) reason = DEL_REASON_RESET_SADB
8 22:06:08.203 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK INFO *(HASH, DEL) to 203.199.202.73
9 22:06:08.203 04/08/02 Sev=Info/4 CM/0x63100013
Phase 1 SA deleted cause by DEL_REASON_RESET_SADB. 0 Phase 1 SA currently in the system
10 22:06:08.203 04/08/02 Sev=Info/5 CM/0x63100029
Initializing CVPNDrv
11 22:06:08.203 04/08/02 Sev=Info/6 CM/0x63100035
Tunnel to headend device 203.199.202.73 disconnected: duration: 0 days 0:4:7
12 22:06:08.203 04/08/02 Sev=Info/5 CM/0x63100029
Initializing CVPNDrv
13 22:06:08.671 04/08/02 Sev=Info/6 DIALER/0x63300007
Disconnected.
14 22:06:08.671 04/08/02 Sev=Info/6 DIALER/0x63300008
MAPI32 Information - Outlook not default mail client
15 22:06:08.687 04/08/02 Sev=Info/4 IPSEC/0x63700013
Delete internal key with SPI=0xf13d7ecb
16 22:06:08.687 04/08/02 Sev=Info/4 IPSEC/0x63700013
Delete internal key with SPI=0x7279c244
17 22:06:08.687 04/08/02 Sev=Info/4 IPSEC/0x63700013
Delete internal key with SPI=0x937c9fcc
18 22:06:08.687 04/08/02 Sev=Info/4 IPSEC/0x63700013
Delete internal key with SPI=0x19cea528
19 22:06:08.687 04/08/02 Sev=Info/4 IPSEC/0x63700014
Deleted all keys
20 22:06:08.687 04/08/02 Sev=Info/4 IPSEC/0x63700014
Deleted all keys
21 22:06:08.687 04/08/02 Sev=Info/4 IPSEC/0x63700014
Deleted all keys
22 22:06:08.687 04/08/02 Sev=Info/4 IPSEC/0x63700014
Deleted all keys
23 22:06:17.984 04/08/02 Sev=Info/6 DIALER/0x63300002
Initiating connection.
24 22:06:17.984 04/08/02 Sev=Info/4 CM/0x63100002
Begin connection process
25 22:06:17.984 04/08/02 Sev=Info/4 CM/0x63100004
Establish secure connection using Ethernet
26 22:06:17.984 04/08/02 Sev=Info/4 CM/0x63100026
Attempt connection with server "203.199.202.73"
27 22:06:17.984 04/08/02 Sev=Info/6 IKE/0x6300003B
Attempting to establish a connection with 203.199.202.73.
28 22:06:17.984 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK AG (SA, KE, NON, ID, VID, VID, VID) to 203.199.202.73
29 22:06:18.546 04/08/02 Sev=Info/4 IPSEC/0x63700014
Deleted all keys
30 22:06:18.562 04/08/02 Sev=Info/5 IKE/0x6300002F
Received ISAKMP packet: peer = 203.199.202.73
31 22:06:18.562 04/08/02 Sev=Info/4 IKE/0x63000014
RECEIVING <<< ISAKMP OAK AG (SA, VID, VID, VID, VID, KE, ID, NON, HASH) from 203.199.202.73
32 22:06:18.562 04/08/02 Sev=Info/5 IKE/0x63000059
Vendor ID payload = 12F5F28C457168A9702D9FE274CC0100
33 22:06:18.562 04/08/02 Sev=Info/5 IKE/0x63000001
Peer is a Cisco-Unity compliant peer
34 22:06:18.562 04/08/02 Sev=Info/5 IKE/0x63000059
Vendor ID payload = AFCAD71368A1F1C96B8696FC77570100
35 22:06:18.562 04/08/02 Sev=Info/5 IKE/0x63000001
Peer supports DPD
36 22:06:18.562 04/08/02 Sev=Info/5 IKE/0x63000059
Vendor ID payload = A1030BF1FFE8EAECDA734DEBAE1DDF2C
37 22:06:18.562 04/08/02 Sev=Info/5 IKE/0x63000059
Vendor ID payload = 09002689DFD6B712
38 22:06:18.562 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK AG *(HASH, NOTIFY:STATUS_INITIAL_CONTACT) to 203.199.202.73
39 22:06:18.843 04/08/02 Sev=Info/5 IKE/0x6300002F
Received ISAKMP packet: peer = 203.199.202.73
40 22:06:18.843 04/08/02 Sev=Info/4 IKE/0x63000014
RECEIVING <<< ISAKMP OAK INFO *(HASH, NOTIFY:STATUS_RESP_LIFETIME) from 203.199.202.73
41 22:06:18.843 04/08/02 Sev=Info/5 IKE/0x63000044
RESPONDER-LIFETIME notify has value of 86400 seconds
42 22:06:18.843 04/08/02 Sev=Info/5 IKE/0x63000046
This SA has already been alive for 1 seconds, setting expiry to 86399 seconds from now
43 22:06:18.875 04/08/02 Sev=Info/5 IKE/0x6300002F
Received ISAKMP packet: peer = 203.199.202.73
44 22:06:18.875 04/08/02 Sev=Info/4 IKE/0x63000014
RECEIVING <<< ISAKMP OAK TRANS *(HASH, ATTR) from 203.199.202.73
45 22:06:18.875 04/08/02 Sev=Info/4 CM/0x63100015
Launch xAuth application
46 22:06:23.859 04/08/02 Sev=Info/5 IKE/0x6300002F
Received ISAKMP packet: peer = 203.199.202.73
47 22:06:23.859 04/08/02 Sev=Info/4 IKE/0x63000014
RECEIVING <<< ISAKMP OAK TRANS *(Retransmission) from 203.199.202.73
48 22:06:28.859 04/08/02 Sev=Info/5 IKE/0x6300002F
Received ISAKMP packet: peer = 203.199.202.73
49 22:06:28.859 04/08/02 Sev=Info/4 IKE/0x63000014
RECEIVING <<< ISAKMP OAK TRANS *(Retransmission) from 203.199.202.73
50 22:06:33.859 04/08/02 Sev=Info/5 IKE/0x6300002F
Received ISAKMP packet: peer = 203.199.202.73
51 22:06:33.859 04/08/02 Sev=Info/4 IKE/0x63000014
RECEIVING <<< ISAKMP OAK TRANS *(Retransmission) from 203.199.202.73
52 22:07:09.000 04/08/02 Sev=Info/4 CM/0x63100017
xAuth application returned
53 22:07:09.000 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK TRANS *(HASH, ATTR) to 203.199.202.73
54 22:07:14.046 04/08/02 Sev=Info/4 IKE/0x63000056
Phase 2 exchange timed out (message id = 0xB5106BE6). Retry count: 1
55 22:07:14.046 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK TRANS *(Retransmission) to 203.199.202.73
56 22:07:19.046 04/08/02 Sev=Info/4 IKE/0x63000056
Phase 2 exchange timed out (message id = 0xB5106BE6). Retry count: 2
57 22:07:19.046 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK TRANS *(Retransmission) to 203.199.202.73
58 22:07:24.046 04/08/02 Sev=Info/4 IKE/0x63000056
Phase 2 exchange timed out (message id = 0xB5106BE6). Retry count: 3
59 22:07:24.046 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK TRANS *(Retransmission) to 203.199.202.73
60 22:07:29.046 04/08/02 Sev=Info/4 IKE/0x63000053
Phase-2 retransmission count exceeded, message id = 0x00000003
61 22:07:29.046 04/08/02 Sev=Info/6 IKE/0x6300003D
Sending DPD request to 203.199.202.73, seq# = 2264229020
62 22:07:29.046 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK INFO *(HASH, NOTIFY:DPD_REQUEST) to 203.199.202.73
63 22:07:34.046 04/08/02 Sev=Info/6 IKE/0x6300003D
Sending DPD request to 203.199.202.73, seq# = 2264229021
64 22:07:34.046 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK INFO *(HASH, NOTIFY:DPD_REQUEST) to 203.199.202.73
65 22:07:39.046 04/08/02 Sev=Info/6 IKE/0x6300003D
Sending DPD request to 203.199.202.73, seq# = 2264229022
66 22:07:39.046 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK INFO *(HASH, NOTIFY:DPD_REQUEST) to 203.199.202.73
67 22:07:44.046 04/08/02 Sev=Info/6 IKE/0x6300003D
Sending DPD request to 203.199.202.73, seq# = 2264229023
68 22:07:44.046 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK INFO *(HASH, NOTIFY:DPD_REQUEST) to 203.199.202.73
69 22:07:49.046 04/08/02 Sev=Info/6 IKE/0x6300003D
Sending DPD request to 203.199.202.73, seq# = 2264229024
70 22:07:49.046 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK INFO *(HASH, NOTIFY:DPD_REQUEST) to 203.199.202.73
71 22:07:54.046 04/08/02 Sev=Info/6 IKE/0x6300003D
Sending DPD request to 203.199.202.73, seq# = 2264229025
72 22:07:54.046 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK INFO *(HASH, NOTIFY:DPD_REQUEST) to 203.199.202.73
73 22:07:59.046 04/08/02 Sev=Info/6 IKE/0x6300003D
Sending DPD request to 203.199.202.73, seq# = 2264229026
74 22:07:59.046 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK INFO *(HASH, NOTIFY:DPD_REQUEST) to 203.199.202.73
75 22:08:04.046 04/08/02 Sev=Info/6 IKE/0x6300003D
Sending DPD request to 203.199.202.73, seq# = 2264229027
76 22:08:04.046 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK INFO *(HASH, NOTIFY:DPD_REQUEST) to 203.199.202.73
77 22:08:09.046 04/08/02 Sev=Info/6 IKE/0x6300003D
Sending DPD request to 203.199.202.73, seq# = 2264229028
78 22:08:09.046 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK INFO *(HASH, NOTIFY:DPD_REQUEST) to 203.199.202.73
79 22:08:14.046 04/08/02 Sev=Info/6 IKE/0x6300003D
Sending DPD request to 203.199.202.73, seq# = 2264229029
80 22:08:14.046 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK INFO *(HASH, NOTIFY:DPD_REQUEST) to 203.199.202.73
81 22:08:18.921 04/08/02 Sev=Info/6 DIALER/0x63300004
Canceling connection.
82 22:08:18.921 04/08/02 Sev=Info/4 CM/0x63100006
Abort connection attempt before Phase 1 SA up
83 22:08:18.921 04/08/02 Sev=Info/5 IKE/0x63000017
Marking IKE SA for deletion (COOKIES = 81B8645543FCCD80 54C4ACECFFE9EAEC) reason = DEL_REASON_RESET_SADB
84 22:08:18.921 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK INFO *(HASH, DEL) to 203.199.202.73
85 22:08:18.937 04/08/02 Sev=Info/5 CM/0x63100029
Initializing CVPNDrv
86 22:08:18.984 04/08/02 Sev=Info/6 DIALER/0x63300005
Connection canceled.
87 22:08:19.937 04/08/02 Sev=Info/4 IPSEC/0x63700014
Deleted all keys
88 22:08:19.937 04/08/02 Sev=Info/4 IPSEC/0x63700014
Deleted all keys
89 22:08:19.937 04/08/02 Sev=Info/4 IPSEC/0x63700014
Deleted all keys
90 22:08:25.062 04/08/02 Sev=Info/6 DIALER/0x63300002
Initiating connection.
91 22:08:25.062 04/08/02 Sev=Info/4 CM/0x63100002
Begin connection process
92 22:08:25.062 04/08/02 Sev=Info/4 CM/0x63100004
Establish secure connection using Ethernet
93 22:08:25.062 04/08/02 Sev=Info/4 CM/0x63100026
Attempt connection with server "203.199.202.73"
94 22:08:25.062 04/08/02 Sev=Info/6 IKE/0x6300003B
Attempting to establish a connection with 203.199.202.73.
95 22:08:25.078 04/08/02 Sev=Info/4 IKE/0x63000013
SENDING >>> ISAKMP OAK AG (SA, KE, NON, ID, VID, VID, VID) to 203.199.202.73
96 22:08:25.609 04/08/02 Sev=Info/5 IKE/0x6300002F
Received ISAKMP packet: peer = 203.199.202.73
97 22:08:25.609 04/08/02 Sev=Info/4 IKE/0x63000014
RECEIVING <<< ISAKMP OAK AG (SA, VID, VID, VID, VID, KE, ID, NON, HASH) from 203.199.202.73
98 22:08:25.609 04/08/02 Sev=Info/5 IKE/0x63000059
Vendor ID payload = 12F5F28C457168A9702D9FE274CC0100
99 22:08:25.625 04/08/02 Sev=Info/5 IKE/0x63000001
Peer is a Cisco-Unity compliant peer
100 22:08:25.625 04/08/02 Sev=Info/5 IKE/0x63000059
Vendor ID payload = AFCAD71368A1F1C96B8696FC77570100
101 22:08:25.625 04/08/02 Sev=Info/5 IKE/0x63000001
Peer supports DPD
102 22:08:25.625 04/08/02 Sev=Info/5 IKE/0x63000059
Vendor ID payload = A1030BF12EBCCD41495FCC8B6F7E7306
103 22:08:25.625 04/08/02 Sev=Info/5 IKE/0x63000059
Vendor ID payload = 09002689DFD6B712
Router Debug output:
May 20 12:52:21 UTC: %CRYPTO-4-IKMP_BAD_MESSAGE: IKE message from 63.82.81.166
failed its sanity check or is malformed
May 20 12:52:27 UTC: TAC+: Opening TCP/IP to 172.23.86.105/49 timeout=5
May 20 12:52:27 UTC: TAC+: Opened TCP/IP handle 0x832E00C8 to 172.23.86.105/49
May 20 12:52:27 UTC: TAC+: periodic timer started
May 20 12:52:27 UTC: TAC+: 172.23.86.105 req=8313C8E0 Qd id=3512101476 ver=192 h
andle=0x832E00C8 (ESTAB) expire=5 AUTHEN/START/LOGIN/ASCII queued
May 20 12:52:27 UTC: TAC+: 172.23.86.105 ESTAB id=3512101476 wrote 49 of 49 byte
s
May 20 12:52:27 UTC: TAC+: 172.23.86.105 req=8313C8E0 Qd id=3512101476 ver=192 h
andle=0x832E00C8 (ESTAB) expire=4 AUTHEN/START/LOGIN/ASCII sent
May 20 12:52:27 UTC: TAC+: 172.23.86.105 ESTAB read=12 wanted=12 alloc=12 got=12
May 20 12:52:27 UTC: TAC+: 172.23.86.105 ESTAB read=34 wanted=34 alloc=34 got=22
May 20 12:52:27 UTC: TAC+: 172.23.86.105 received 34 byte reply for 8313C8E0
May 20 12:52:27 UTC: TAC+: req=8313C8E0 Tx id=3512101476 ver=192 handle=0x832E00
C8 (ESTAB) expire=4 AUTHEN/START/LOGIN/ASCII processed
May 20 12:52:27 UTC: TAC+: periodic timer stopped (queue empty)
May 20 12:52:27 UTC: TAC+: periodic timer started
May 20 12:52:27 UTC: TAC+: 172.23.86.105 req=8313C8E0 Qd id=3512101476 ver=192 h
andle=0x832E00C8 (ESTAB) expire=5 AUTHEN/CONT queued
May 20 12:52:27 UTC: TAC+: 172.23.86.105 ESTAB id=3512101476 wrote 23 of 23 byte
s
May 20 12:52:27 UTC: TAC+: 172.23.86.105 req=8313C8E0 Qd id=3512101476 ver=192 h
andle=0x832E00C8 (ESTAB) expire=4 AUTHEN/CONT sent
May 20 12:52:29 UTC: TAC+: 172.23.86.105 ESTAB read=12 wanted=12 alloc=12 got=12
May 20 12:52:29 UTC: TAC+: 172.23.86.105 ESTAB read=66 wanted=66 alloc=66 got=54
May 20 12:52:29 UTC: TAC+: 172.23.86.105 received 66 byte reply for 8313C8E0
May 20 12:52:29 UTC: TAC+: req=8313C8E0 Tx id=3512101476 ver=192 handle=0x832E00
C8 (ESTAB) expire=3 AUTHEN/CONT processed
May 20 12:52:29 UTC: TAC+: periodic timer stopped (queue empty)
May 20 12:52:29 UTC: TAC+: Closing TCP/IP 0x832E00C8 connection to 172.23.86.105
/49
May 20 12:53:26 UTC: %CRYPTO-4-IKMP_BAD_MESSAGE: IKE message from 63.82.81.166
failed its sanity check or is malformed
May 20 12:53:32 UTC: %CRYPTO-4-IKMP_NO_SA: IKE message from 203.199.231.187 has
no SA and is not an initialization offer
May 20 12:54:04 UTC: TAC+: Opening TCP/IP to 172.23.86.105/49 timeout=5
May 20 12:54:04 UTC: TAC+: Opened TCP/IP handle 0x8317B804 to 172.23.86.105/49
May 20 12:54:04 UTC: TAC+: periodic timer started
May 20 12:54:04 UTC: TAC+: 172.23.86.105 req=8313C7F0 Qd id=553051766 ver=192 ha
ndle=0x8317B804 (ESTAB) expire=5 AUTHEN/START/LOGIN/ASCII queued
May 20 12:54:04 UTC: TAC+: 172.23.86.105 ESTAB id=553051766 wrote 49 of 49 bytes
May 20 12:54:04 UTC: TAC+: 172.23.86.105 req=8313C7F0 Qd id=553051766 ver=192 ha
ndle=0x8317B804 (ESTAB) expire=4 AUTHEN/START/LOGIN/ASCII sent
May 20 12:54:05 UTC: TAC+: 172.23.86.105 ESTAB read=12 wanted=12 alloc=12 got=12
May 20 12:54:05 UTC: TAC+: 172.23.86.105 ESTAB read=34 wanted=34 alloc=34 got=22
May 20 12:54:05 UTC: TAC+: 172.23.86.105 received 34 byte reply for 8313C7F0
May 20 12:54:05 UTC: TAC+: req=8313C7F0 Tx id=553051766 ver=192 handle=0x8317B80
4 (ESTAB) expire=4 AUTHEN/START/LOGIN/ASCII processed
May 20 12:54:05 UTC: TAC+: periodic timer stopped (queue empty)
May 20 12:54:05 UTC: TAC+: periodic timer started
May 20 12:54:05 UTC: TAC+: 172.23.86.105 req=83167E3C Qd id=553051766 ver=192 ha
ndle=0x8317B804 (ESTAB) expire=5 AUTHEN/CONT queued
May 20 12:54:05 UTC: TAC+: 172.23.86.105 ESTAB id=553051766 wrote 21 of 21 bytes
May 20 12:54:05 UTC: TAC+: 172.23.86.105 req=83167E3C Qd id=553051766 ver=192 ha
ndle=0x8317B804 (ESTAB) expire=4 AUTHEN/CONT sent
May 20 12:54:06 UTC: TAC+: 172.23.86.105 ESTAB read=12 wanted=12 alloc=12 got=12
May 20 12:54:06 UTC: TAC+: 172.23.86.105 ESTAB read=18 wanted=18 alloc=18 got=6
May 20 12:54:06 UTC: TAC+: 172.23.86.105 received 18 byte reply for 83167E3C
May 20 12:54:06 UTC: TAC+: req=83167E3C Tx id=553051766 ver=192 handle=0x8317B80
4 (ESTAB) expire=3 AUTHEN/CONT processed
May 20 12:54:06 UTC: TAC+: periodic timer stopped (queue empty)
May 20 12:54:06 UTC: TAC+: Closing TCP/IP 0x8317B804 connection to 172.23.86.105
/49
05-21-2002 05:58 AM
Hi,
Are you using D-H group 2 in your isakmp settings? Also, I assume that if you are talking directly to the ACE server from the router, it is with RADIUS. Is the ACE/Server log showing any attempts for xauth from the router?
Dave
05-21-2002 07:45 PM
Dave:
We are using D-H group 2 and we do use TACACS to talk to ACE server. The ACE server log shows the attempt for xauth and it seems to be that it prompted user to set his PIN, which it doesnt.
Raj
Find answers to your questions by entering keywords or phrases in the Search bar above. New here? Use these resources to familiarize yourself with the community: