Dual-Hub DMVPN with PKI and 'subject-name' don't work

Anton Pestov · ‎09-25-2011

I have a Dual-Hub DMVPN with PKI dep[oyment infrastructure and with 2 Hub on Cisco 1811 and Spokes on Cisco 1841. When I enter the 'subject-name' parameter (pki trustpoint configuration mode) on a Spoke routers, one of two Tunnel is up, but the second Tunnel is not up. ISAKMP-negotiation select the rsa-sig-mode is correctly. If I select pre-shared-mode or if i remove 'subject-name' from Spokes, DMVPN work is fine!

In what there can be a problem?

Configuration example:

1. HUB:

--------------------------------------------------------------------------------

Cisco IOS Software, C181X Software (C181X-ADVENTERPRISEK9-M), Version 12.4(15)T15, RELEASE SOFTWARE (fc3)

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

Compiled Tue 08-Mar-11 06:09 by prod_rel_team

--------------------------------------------------------------------------------

crypto pki trustpoint TRUSTPOINT-CA1

enrollment mode ra

enrollment url http://.../certsrv/mscep/mscep.dll

password ...

subject-name cn=HUB-CE1,dc=GL,o=Central Office

revocation-check none

rsakeypair TRUSTPOINT-CA1 1024 1024

!

crypto pki certificate chain TRUSTPOINT-CA1

certificate ... nvram:...#28.cer

certificate ... nvram:...#29.cer

certificate ca ... nvram:...#1111CA.cer

dot11 syslog

!

ip cef

!

password encryption aes

!

crypto isakmp policy 10

encr aes

hash md5

authentication rsa-encr

group 2

lifetime 43200

!

crypto isakmp policy 20

encr aes 192

hash md5

group 2

lifetime 43200

!

crypto isakmp policy 30

encr 3des

authentication pre-share

group 2

lifetime 21600

crypto isakmp key ... address 0.0.0.0 0.0.0.0

crypto isakmp keepalive 10

crypto isakmp nat keepalive 5

!

crypto ipsec transform-set TS-DMVPN1 esp-3des esp-md5-hmac

!

crypto ipsec profile PROFILE-DMVPN1

set transform-set TS-DMVPN1

!

interface Tunnel1

bandwidth 3200

ip address 172.20.254.254 255.255.255.0

no ip redirects

no ip unreachables

no ip proxy-arp

ip mtu 1400

ip flow ingress

ip flow egress

ip nhrp authentication nh10001

ip nhrp map multicast dynamic

ip nhrp network-id 10001

ip nhrp holdtime 300

ip tcp adjust-mss 1360

no ip split-horizon eigrp 1

ip ospf network point-to-multipoint

ip ospf cost 5

delay 1000

qos pre-classify

tunnel source FastEthernet0

tunnel mode gre multipoint

tunnel key 10001

tunnel protection ipsec profile PROFILE-DMVPN1

!

2. SPOKE (with 'subject-name'):

----------------------------------------------------------------------------------

Cisco IOS Software, 1841 Software (C1841-ADVENTERPRISEK9-M), Version 15.1(4)M, RELEASE SOFTWARE (fc1)

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

Compiled Thu 24-Mar-11 13:12 by prod_rel_team

-----------------------------------------------------------------------------------

password encryption aes

crypto pki token default removal timeout 0

!

crypto pki trustpoint TRUSTPOINT-CA1

enrollment mode ra

enrollment url http://.../certsrv/mscep/mscep.dll

password ...

subject-name cn=SPOKE-CE1,dc=GL,o=Branch Office

revocation-check none

rsakeypair TRUSTPOINT-CA1 1024 1024

!

crypto pki certificate chain TRUSTPOINT-CA1

certificate ... nvram:...#96.cer

certificate ... nvram:...#97.cer

certificate ca ... nvram:...#118FCA.cer

!

crypto isakmp policy 10

encr aes

hash md5

authentication rsa-encr

group 2

lifetime 43200

!

crypto isakmp policy 20

encr aes 192

hash md5

group 2

lifetime 43200

!

crypto isakmp policy 30

encr 3des

authentication pre-share

group 2

lifetime 21600

crypto isakmp key ... address 0.0.0.0 0.0.0.0

crypto isakmp invalid-spi-recovery

crypto isakmp keepalive 10

!

crypto ipsec transform-set TS-DMVPN esp-3des esp-md5-hmac

!

crypto ipsec profile PROFILE-DMVPN

set security-association lifetime seconds 21600

set transform-set TS-DMVPN

!

interface Tunnel1

bandwidth 1600

ip address 172.20.254.1 255.255.255.0

no ip redirects

no ip unreachables

no ip proxy-arp

ip mtu 1400

ip flow ingress

ip flow egress

ip nhrp authentication nh10001

ip nhrp map 172.20.254.254 92.255.23.238

ip nhrp map multicast 92.255.23.238

ip nhrp network-id 10001

ip nhrp holdtime 300

ip nhrp nhs 172.20.254.254

ip tcp adjust-mss 1360

ip ospf network point-to-multipoint

ip ospf cost 5

delay 1000

tunnel source FastEthernet0/0

tunnel mode gre multipoint

tunnel key 10001

tunnel protection ipsec profile PROFILE-DMVPN shared

!

interface Tunnel2

bandwidth 1600

ip address 172.20.253.1 255.255.255.0

no ip redirects

no ip unreachables

no ip proxy-arp

ip mtu 1400

ip flow ingress

ip flow egress

ip nhrp authentication nh10002

ip nhrp map 172.20.253.254 83.242.229.102

ip nhrp map multicast 83.242.229.102

ip nhrp network-id 10002

ip nhrp holdtime 300

ip nhrp nhs 172.20.253.254

ip tcp adjust-mss 1360

ip ospf network point-to-multipoint

ip ospf cost 5

delay 1000

keepalive 10 5

tunnel source FastEthernet0/0

tunnel mode gre multipoint

tunnel key 10002

tunnel protection ipsec profile PROFILE-DMVPN shared

!

Marcin Latosiewicz · ‎09-26-2011

Anton,

For starters you need to remove tunnel keepalives from tunnel2 on spoke. tunnel keepalives are supported only with crypto maps and not with tunnel protection, they especially do not make sense in case of multipoint GRE.

When you say tunnel is down do you mean tunnel status as showin in "show interface" or that you are not able to pass traffic.

On a completly separate note subject-name is not to be modified after enrollment is done, unless you are to re-enroll the trustpoint?

If the IKE session for the other tunnel does not come up I think it would make sense to run debugging:

-------

deb cry pki m

deb crypto pk t

debug crypto pki v

debug cry isa

-------

should give us some more info ;-)

Marcin

Anton Pestov · ‎09-26-2011

Yes, I know about keepalive on tunnel interfaces, i have forgotten to remove this line. IKE session for Tunnel1 does not come up.

Part of debug messages from Spoke (A.A.A.A - HUB1 [Tunnel1 on Spoke], B.B.B.B - HUB2 [Tunnel2 on Spoke], X.X.X.X - SPOKE1):

SPOKE-CE1#debug crypto pki t

Crypto PKI Trans debugging is on

SPOKE-CE1#debug crypto pki m

Crypto PKI Msg debugging is on

SPOKE-CE1#de

SPOKE-CE1#

*Sep 26 12:26:54.167: CRYPTO_PKI: unlocked trustpoint TRUSTPOINT-CA1, refcount is 0

SPOKE-CE1#debu

SPOKE-CE1#debug cry

SPOKE-CE1#debug crypto isa

SPOKE-CE1#debug crypto isakmp

Crypto ISAKMP debugging is on

SPOKE-CE1#

*Sep 26 12:27:02.951: ISAKMP:(1001):purging node 12224853

SPOKE-CE1#

*Sep 26 12:27:08.159: ISAKMP: DPD received KMI message.

*Sep 26 12:27:08.159: ISAKMP: set new node -248870263 to QM_IDLE

*Sep 26 12:27:08.159: ISAKMP:(1001):Sending NOTIFY DPD/R_U_THERE protocol 1

spi 1730674960, message ID = 4046097033

*Sep 26 12:27:08.159: ISAKMP:(1001): seq. no 0x138ACE4B

*Sep 26 12:27:08.159: ISAKMP:(1001): sending packet to B.B.B.B my_port 500 peer_port 500 (I) QM_IDLE

*Sep 26 12:27:08.159: ISAKMP:(1001):Sending an IKE IPv4 Packet.

*Sep 26 12:27:08.159: ISAKMP:(1001):purging node -248870263

*Sep 26 12:27:08.175: ISAKMP (1001): received packet from B.B.B.B dport 500 sport 500 Global (I) QM_IDLE

*Sep 26 12:27:08.175: ISAKMP: set new node -1029760522 to QM_IDLE

*Sep 26 12:27:08.175: ISAKMP:(1001): processing HASH payload. message ID = 3265206774

*Sep 26 12:27:08.179: ISAKMP:(1001): processing NOTIFY DPD/R_U_THERE_ACK protocol 1

spi 0, message ID = 3265206774, sa = 0x6725E260

*Sep 26 12:27:08.179: ISAKMP:(1001): DPD/R_U_THERE_ACK received from peer B.B.B.B, sequence 0x138ACE4B

*Sep 26 12:27:08.179: ISAKMP:(1001):deleting node -1029760522 error FALSE reason "Informational (in) state 1"

*Sep 26 12:27:08.179: ISAKMP:(1001):Input = IKE_MESG_FROM_PEER, IKE_INFO_NOTIFY

SPOKE-CE1#

*Sep 26 12:27:08.179: ISAKMP:(1001):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

SPOKE-CE1#

*Sep 26 12:27:10.883: ISAKMP:(0): SA request profile is (NULL)

*Sep 26 12:27:10.883: ISAKMP: Created a peer struct for A.A.A.A, peer port 500

*Sep 26 12:27:10.883: ISAKMP: New peer created peer = 0x6850E014 peer_handle = 0x80000005

*Sep 26 12:27:10.883: ISAKMP: Locking peer struct 0x6850E014, refcount 1 for isakmp_initiator

*Sep 26 12:27:10.883: ISAKMP: local port 500, remote port 500

*Sep 26 12:27:10.883: ISAKMP: set new node 0 to QM_IDLE

*Sep 26 12:27:10.883: ISAKMP: Find a dup sa in the avl tree during calling isadb_insert sa = 68519418

*Sep 26 12:27:10.883: ISAKMP:(0):Can not start Aggressive mode, trying Main mode.

*Sep 26 12:27:10.883: ISAKMP:(0):found peer pre-shared key matching A.A.A.A

*Sep 26 12:27:10.883: ISAKMP:(0): IKE->PKI Get configured TrustPoints state (I) MM_NO_STATE (peer A.A.A.A)

*Sep 26 12:27:10.883: ISAKMP:(0): PKI->IKE Got configured TrustPoints state (I) MM_NO_STATE (peer A.A.A.A)

*Sep 26 12:27:10.883: ISAKMP:(0): constructed NAT-T vendor-rfc3947 ID

*Sep 26 12:27:10.883: ISAKMP:(0): constructed NAT-T vendor-07 ID

*Sep 26 12:27:10.883: ISAKMP:(0): constructed NAT-T vendor-03 ID

*Sep 26 12:27:10.887: ISAKMP:(0): constructed NAT-T vendor-02 ID

*Sep 26 12:27:10.887: ISAKMP:(0):Input = IKE_MESG_FROM_IPSEC, IKE_SA_REQ_MM

*Sep 26 12:27:10.887: ISAKMP:(0):Old State = IKE_READY New State = IKE_I_MM1

*Sep 26 12:27:10.887: ISAKMP:(0): beginning Main Mode exchange

*Sep 26 12:27:10.887: ISAKMP:(0): sending packet to A.A.A.A my_port 500 peer_port 500 (I) MM_NO_STATE

*Sep 26 12:27:10.887: ISAKMP:(0):Sending an IKE IPv4 Packet.

*Sep 26 12:27:10.907: ISAKMP (0): received packet from A.A.A.A dport 500 sport 500 Global (I) MM_NO_STATE

*Sep 26 12:27:10.907: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH

*Sep 26 12:27:10.907: ISAKMP:(0):Old State = IKE_I_MM1 New State = IKE_I_MM2

*Sep 26 12:27:10.907: ISAKMP:(0): processing SA payload. message ID = 0

*Sep 26 12:27:10.907: ISAKMP:(0): processing vendor id payload

*Sep 26 12:27:10.

SPOKE-CE1#907: ISAKMP:(0): vendor ID seems Unity/DPD but major 69 mismatch

*Sep 26 12:27:10.907: ISAKMP (0): vendor ID is NAT-T RFC 3947

*Sep 26 12:27:10.907: ISAKMP:(0):found peer pre-shared key matching A.A.A.A

*Sep 26 12:27:10.907: ISAKMP:(0): local preshared key found

*Sep 26 12:27:10.907: ISAKMP : Scanning profiles for xauth ...

*Sep 26 12:27:10.907: ISAKMP:(0): IKE->PKI Get configured TrustPoints state (I) MM_NO_STATE (peer A.A.A.A)

*Sep 26 12:27:10.907: ISAKMP:(0): PKI->IKE Got configured TrustPoints state (I) MM_NO_STATE (peer A.A.A.A)

*Sep 26 12:27:10.907: ISAKMP:(0):Checking ISAKMP transform 1 against priority 10 policy

*Sep 26 12:27:10.907: ISAKMP: encryption AES-CBC

*Sep 26 12:27:10.907: ISAKMP: keylength of 192

*Sep 26 12:27:10.907: ISAKMP: hash MD5

*Sep 26 12:27:10.911: ISAKMP: default group 2

*Sep 26 12:27:10.911: ISAKMP: auth RSA sig

*Sep 26 12:27:10.911: ISAKMP: life type in seconds

*Sep 26 12:27:10.911: ISAKMP: life duration (basic) of 43200

*Sep 26 12:27:10.911: ISAKMP:(0):Authentication method offered does not match policy!

*Sep 26 12:27:10.911: ISAKMP:(0):atts are not acceptable. Next payload is 0

*Sep 26 12:27:10.911: ISAKMP:(0):Checking ISAKMP transform 1 against priority 20 policy

*Sep 26 12:27:10.911: ISAKMP: encryption AES-CBC

*Sep 26 12:27:10.911: ISAKMP: keylength of 192

*Sep 26 12:27:10.911: ISAKMP: hash MD5

*Sep 26 12:27:10.911: ISAKMP: default group 2

*Sep 26 12:27:10.911: ISAKMP: auth RSA sig

*Sep 26 12:27:10.911: ISAKMP: life type in seconds

*Sep 26 12:27:10.911: ISAKMP: life duration (basic) of 43200

*Sep 26 12:27:10.911: ISAKMP:(0):atts are acceptable. Next payload is 0

*Sep 26 12:27:10.911: ISAKMP:(0):Acceptable atts:actual life: 0

*Sep 26 12:27:10.911: ISAKMP:(0):Acceptable atts:life: 0

*Sep 26 12:27:10.911: ISAKMP:(0):Basic life_in_seconds:43200

*Sep 26 12:27:10.911: ISAKMP:(0): IKE->PKI Start PKI Session state (I) MM_NO_STATE (peer A.A.A.A)

*Sep 26 12:27:10.911: CRYPTO_PKI: Identity not specified for session 10005

*Sep 26 12:27:10.911: ISAKMP:(0): PKI->IKE Started PKI Session state (I) MM_NO_STATE (peer A.A.A.A)

*Sep 26 12:27:10.911: ISAKMP:(0):Returning Actual lifetime: 43200

*Sep 26 12:27:10.911: ISAKMP:(0)::Started lifetime timer: 43200.

*Sep 26 12:27:10.911: ISAKMP:(0): processing vendor id payload

*Sep 26 12:27:10.911: ISAKMP:(0): vendor ID seems Unity/DPD but major 69 mismatch

*Sep 26 12:27:10.911: ISAKMP (0): vendor ID is NAT-T RFC 3947

*Sep 26 12:27:10.911: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE

*Sep 26 12:27:10.911: ISAKMP:(0):Old State = IKE_I_MM2 New State = IKE_I_MM2

*Sep 26 12:27:10.915: ISAKMP:(0): IKE->PKI Get configured TrustPoints state (I) MM_SA_SETUP (peer A.A.A.A)

*Sep 26 12:27:10.915: ISAKMP:(0): PKI->IKE Got configured TrustPoints state (I) MM_SA_SETUP (peer A.A.A.A)

*Sep 26 12:27:10.915: ISAKMP:(0): IKE->PKI Get IssuerNames state (I) MM_SA_SETUP (peer A.A.A.A)

*Sep 26 12:27:10.915: ISAKMP:(0): PKI->IKE Got IssuerNames state (I) MM_SA_SETUP (peer A.A.A.A)

*Sep 26 12:27:10.915: ISAKMP (0): constructing CERT_REQ for issuer cn=SPTEST2-CA,dc=GL

*Sep 26 12:27:10.915: ISAKMP:(0): sending packet to A.A.A.A my_port 500 peer_port 500 (I) MM_SA_SETUP

*Sep 26 12:27:10.915: ISAKMP:(0):Sending an IKE IPv4 Packet.

*Sep 26 12:27:10.915: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE

*Sep 26 12:27:10.915: ISAKMP:(0):Old State = IKE_I_MM2 New State = IKE_I_MM3

*Sep 26 12:27:10.967: ISAKMP (0): received packet from A.A.A.A dport 500 sport 500 Global (I) MM_SA_SETUP

*Sep 26 12:27:10.967: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH

*Sep 26 12:27:10.967: ISAKMP:(0):Old State = IKE_I_MM3 New State = IKE_I_MM4

*Sep 26 12:27:10.967: ISAKMP:(0): processing KE payload. message ID = 0

*Sep 26 12:27:11.039: ISAKMP:(0): processing NONCE payload. message ID = 0

*Sep 26 12:27:11.039: ISAKMP:(1003): processing CERT_REQ payload. message ID = 0

*Sep 26 12:27:11.039: ISAKMP:(1003): peer wants a CT_X509_SIGNATURE cert

*Sep 26 12:27:11.039: ISAKMP:(1003): peer wants cert issued by cn=SPTEST2-CA,dc=GL

*Sep 26 12:27:11.039: CRYPTO_PKI: Trust-Point TRUSTPOINT-CA1 picked up

*Sep 26 12:27:11.039: CRYPTO_PKI: 1 matching trustpoints found

*Sep 26 12:27:11.039: CRYPTO_PKI: Identity selected (TRUSTPOINT-CA1) for session 20006

*Sep 26 12:27:11.039: Choosing trustpoint TRUSTPOINT-CA1 as issuer

*Sep 26 12:27:11.043: CRYPTO_PKI: unlocked trustpoint TRUSTPOINT-CA1, refcount is 0

*Sep 26 12:27:11.043: CRYPTO_PKI: locked trustpoint TRUSTPOINT-CA1, refcount is 1

*Sep 26 12:27:11.043: CRYPTO_PKI: Identity bound (TRUSTPOINT-CA1) for session 10005

*Sep 26 12:27:11.043: ISAKMP:(1003): processing vendor id payload

*Sep 26 12:27:11.043: ISAKMP:(1003): vendor ID is Unity

*Sep 26 12:27:11.043: ISAKMP:(1003): processing vendor id payload

*Sep 26 12:27:11.043: ISAKMP:(1003): vendor ID is DPD

*Sep 26 12:27:11.043: ISAKMP:(1003): processing vendor id payload

*Sep 26 12:27:11.043: ISAKMP:(1003): speaking to another IOS box!

*Sep 26 12:27:11.043: ISAKMP:received payload type 20

*Sep 26 12:27:11.043: ISAKMP (1003): His hash no match - this node outside NAT

*Sep 26 12:27:11.043: ISAKMP:received payload type 20

*Sep 26 12:27:11.043: ISAKMP (1003): No NAT Found for self or peer

*Sep 26 12:27:11.043: ISAKMP:(1003):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE

*Sep 26 12:27:11.043: ISAKMP:(1003):Old State = IKE_I_MM4 New State = IKE_I_MM4

*Sep 26 12:27:11.043: ISAKMP:(1003):Send initial contact

*Sep 26 12:27:11.043: ISAKMP:(1003): IKE->PKI Get self CertificateChain state (I) MM_KEY_EXCH (peer A.A.A.A)

*Sep 26 12:27:11.047: ISAKMP:(1003): PKI->IKE Got self CertificateChain state (I) MM_KEY_EXCH (peer A.A.A.A)

*Sep 26 12:27:11.047: ISAKMP:(1003): IKE->PKI Get SubjectName state (I) MM_KEY_EXCH (peer A.A.A.A)

*Sep 26 12:27:11.051: ISAKMP:(1003): PKI->IKE Got SubjectName state (I) MM_KEY_EXCH (peer A.A.A.A)

*Sep 26 12:27:11.051: ISAKMP:(1003):My ID configured as IPv4 Addr, but Addr not in Cert!

*Sep 26 12:27:11.051: ISAKMP:(1003):Using FQDN as My ID

*Sep 26 12:27:11.051: ISAKMP:(1003):SA is doing RSA signature authentication using id type ID_FQDN

*Sep 26 12:27:11.051: ISAKMP (1003): ID payload

next-payload : 6

type : 2

FQDN name : SPOKE-CE1.GL

protocol : 17

port : 500

length : 24

*Sep 26 12:27:11.051: ISAKMP:(1003):Total payload length: 24

*Sep 26 12:27:11.055: ISAKMP:(1003): IKE->PKI Get CertificateChain to be sent to peer state (I) MM_KEY_EXCH (peer A.A.A.A)

*Sep 26 12:27:11.059: ISAKMP:(1003): PKI->IKE Got CertificateChain to be sent to peer state (I) MM_KEY_EXCH (peer A.A.A.A)

*Sep 26 12:27:11.067: ISAKMP (1003): constructing CERT payload for cn=SPOKE-CE1,o=Branch Office,dc=GL,hostname=SPOKE-CE1.GL

*Sep 26 12:27:11.067: ISKAMP: growing send buffer from 1024 to 3072

*Sep 26 12:27:11.067: ISAKMP:(1003): using the TRUSTPOINT-CA1 trustpoint's keypair to sign

*Sep 26 12:27:11.187: ISAKMP:(1003): sending packet to A.A.A.A my_port 500 peer_port 500 (I) MM_KEY_EXCH

*Sep 26 12:27:11.187: ISAKMP:(1003):Sending an IKE IPv4 Packet.

*Sep 26 12:27:11.187: ISAKMP:(1003):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE

*Sep 26 12:27:11.187: ISAKMP:(1003):Old State = IKE_I_MM4 New State = IKE_I_MM5

*Sep 26 12:27:20.963: ISAKMP (1003): received packet from A.A.A.A dport 500 sport 500 Global (I) MM_KEY_EXCH

*Sep 26 12:27:20.963: ISAKMP:(1003): phase 1 packet is a duplicate of a previous packet.

*Sep 26 12:27:20.963: ISAKMP:(1003): retransmitting due to retransmit phase 1

*Sep 26 12:27:21.463: ISAKMP:(1003): retransmitting phase 1 MM_KEY_EXCH...

*Sep 26 12:27:21.463: ISAKMP (1003): incrementing error counter on sa, attempt 1 of 5: retransmit phase 1

*Sep 26 12:27:21.463: ISAKMP:(1003): retransmitting phase 1 MM_KEY_EXCH

*Sep 26 12:27:21.463: ISAKMP:(1003): sending packet to A.A.A.A my_port 500 peer_port 500 (I) MM_KEY_EXCH

SPOKE-CE1#

*Sep 26 12:27:21.463: ISAKMP:(1003):Sending an IKE IPv4 Packet.

SPOKE-CE1#sh cry

SPOKE-CE1#sh crypto isa

SPOKE-CE1#sh crypto isakmp sa

IPv4 Crypto ISAKMP SA

dst src state conn-id status

B.B.B.B X.X.X.X QM_IDLE 1001 ACTIVE

A.A.A.A X.X.X.X MM_KEY_EXCH 1003 ACTIVE

A.A.A.A X.X.X.X MM_NO_STATE 1002 ACTIVE (deleted)

IPv6 Crypto ISAKMP SA

SPOKE-CE1#

*Sep 26 12:27:30.075: ISAKMP:(1001):purging node -355527512

*Sep 26 12:27:30.963: ISAKMP (1003): received packet from A.A.A.A dport 500 sport 500 Global (I) MM_KEY_EXCH

*Sep 26 12:27:30.963: ISAKMP:(1003): phase 1 packet is a duplicate of a previous packet.

*Sep 26 12:27:30.963: ISAKMP:(1003): retransmitting due to retransmit phase 1

SPOKE-CE1#

*Sep 26 12:27:31.463: ISAKMP:(1003): retransmitting phase 1 MM_KEY_EXCH...

*Sep 26 12:27:31.463: ISAKMP (1003): incrementing error counter on sa, attempt 2 of 5: retransmit phase 1

*Sep 26 12:27:31.463: ISAKMP:(1003): retransmitting phase 1 MM_KEY_EXCH

*Sep 26 12:27:31.463: ISAKMP:(1003): sending packet to A.A.A.A my_port 500 peer_port 500 (I) MM_KEY_EXCH

*Sep 26 12:27:31.463: ISAKMP:(1003):Sending an IKE IPv4 Packet.

SPOKE-CE1#

*Sep 26 12:27:40.963: ISAKMP (1003): received packet from A.A.A.A dport 500 sport 500 Global (I) MM_KEY_EXCH

*Sep 26 12:27:40.963: ISAKMP:(1003): phase 1 packet is a duplicate of a previous packet.

*Sep 26 12:27:40.963: ISAKMP:(1003): retransmitting due to retransmit phase 1

*Sep 26 12:27:41.463: ISAKMP:(1003): retransmitting phase 1 MM_KEY_EXCH...

*Sep 26 12:27:41.463: ISAKMP (1003): incrementing error counter on sa, attempt 3 of 5: retransmit phase 1

*Sep 26 12:27:41.463: ISAKMP:(1003): retransmitting phase 1 MM_KEY_EXCH

*Sep 26 12:27:41.463: ISAKMP:(1003): sending packet to A.A.A.A my_port 500 peer_port 500 (I) MM_KEY_EXCH

SPOKE-CE1#

*Sep 26 12:27:41.463: ISAKMP:(1003):Sending an IKE IPv4 Packet.

SPOKE-CE1#

*Sep 26 12:27:44.167: ISAKMP:(1002):purging node 2040754712

*Sep 26 12:27:44.167: ISAKMP:(1002):purging node -1784885475

*Sep 26 12:27:44.167: ISAKMP:(1002):purging node 1925340164

SPOKE-CE1#

*Sep 26 12:27:50.963: ISAKMP (1003): received packet from A.A.A.A dport 500 sport 500 Global (I) MM_KEY_EXCH

*Sep 26 12:27:50.967: ISAKMP:(1003): phase 1 packet is a duplicate of a previous packet.

*Sep 26 12:27:50.967: ISAKMP:(1003): retransmitting due to retransmit phase 1

*Sep 26 12:27:51.467: ISAKMP:(1003): retransmitting phase 1 MM_KEY_EXCH...

*Sep 26 12:27:51.467: ISAKMP (1003): incrementing error counter on sa, attempt 4 of 5: retransmit phase 1

*Sep 26 12:27:51.467: ISAKMP:(1003): retransmitting phase 1 MM_KEY_EXCH

*Sep 26 12:27:51.467: ISAKMP:(1003): sending packet to A.A.A.A my_port 500 peer_port 500 (I) MM_KEY_EXCH

SPOKE-CE1#

*Sep 26 12:27:51.467: ISAKMP:(1003):Sending an IKE IPv4 Packet.

SPOKE-CE1#

*Sep 26 12:27:54.167: ISAKMP:(1002):purging SA., sa=67FD3520, delme=67FD3520

SPOKE-CE1#

Marcin Latosiewicz · ‎09-26-2011

Anton,

You can see that the spoke send MM5 and never recived MM6. Same debugs on hub?

Marcin

Anton Pestov · ‎09-26-2011

Debug from HUB1 (A.A.A.A):

HUB-CE1#debug crypto isakmp

Crypto ISAKMP debugging is on

HUB-CE1#

*Sep 26 14:25:11.047: ISAKMP:(0): retransmitting phase 1 MM_SA_SETUP...

*Sep 26 14:25:11.047: ISAKMP (0:0): incrementing error counter on sa, attempt 1 of 5: retransmit phase 1

*Sep 26 14:25:11.047: ISAKMP:(0): retransmitting phase 1 MM_SA_SETUP

*Sep 26 14:25:11.047: ISAKMP:(0): sending packet to X.X.X.X my_port 500 peer_port 500 (R) MM_SA_SETUP

*Sep 26 14:25:11.047: ISAKMP:(0):Sending an IKE IPv4 Packet.

*Sep 26 14:25:11.067: ISAKMP (0:0): received packet from X.X.X.X dport 500 sport 500 Global (R) MM_SA_SETUP

*Sep 26 14:25:11.067: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH

*Sep 26 14:25:11.067: ISAKMP:(0):Old State = IKE_R_MM2 New State = IKE_R_MM3

*Sep 26 14:25:11.067: ISAKMP:(0): processing KE payload. message ID = 0

*Sep 26 14:25:11.099: ISAKMP:(0): processing NONCE payload. message ID = 0

*Sep 26 14:25:11.099: ISAKMP:(2001): processing CERT_REQ payload. message ID = 0

*Sep 26 14:25:11.099: ISAKMP:(2001): peer wants a CT_X509_SIGNATURE cert

*

HUB-CE1#de

Sep 26 14:25:11.099: ISAKMP:(2001): peer wants cert issued by cn=SPTEST2-CA,dc=GL

*Sep 26 14:25:11.099: Choosing trustpoint TRUSTPOINT-CA1 as issuer

*Sep 26 14:25:11.099: ISAKMP:(2001): processing vendor id payload

*Sep 26 14:25:11.099: ISAKMP:(2001): vendor ID is DPD

*Sep 26 14:25:11.099: ISAKMP:(2001): processing vendor id payload

*Sep 26 14:25:11.099: ISAKMP:(2001): speaking to another IOS box!

*Sep 26 14:25:11.099: ISAKMP:(2001): processing vendor id payload

*Sep 26 14:25:11.099: ISAKMP:(2001): vendor ID seems Unity/DPD but major 229 mismatch

*Sep 26 14:25:11.099: ISAKMP:(2001): vendor ID is XAUTH

*Sep 26 14:25:11.099: ISAKMP:received payload type 20

*Sep 26 14:25:11.099: ISAKMP:(2001):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE

*Sep 26 14:25:11.099: ISAKMP:(2001):Old State = IKE_R_MM3 New State = IKE_R_MM3

*Sep 26 14:25:11.099: ISAKMP (0:2001): constructing CERT_REQ for issuer cn=SPTEST2-CA,dc=GL

*Sep 26 14:25:11.099: ISAKMP:(2001): sending packet to X.X.X.X my_port 500 peer_port 500 (R) MM_KEY_EXCH

*Sep 26 14:25:11.099: ISAKMP:(2001):Sending an IKE IPv4 Packet.

*Sep 26 14:25:11.103: ISAKMP:(2001):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE

*Sep 26 14:25:11.103: ISAKMP:(2001):Old State = IKE_R_MM3 New State = IKE_R_MM4

HUB-CE1#debu

HUB-CE1#debug cry

HUB-CE1#debug crypto pki

HUB-CE1#debug crypto pki t

Crypto PKI Trans debugging is on

HUB-CE1#debug crypto pki v

Crypto PKI Validation Path debugging is on

HUB-CE1#debug crypto pki m

Crypto PKI Msg debugging is on

HUB-CE1#

*Sep 26 14:25:21.103: ISAKMP:(2001): retransmitting phase 1 MM_KEY_EXCH...

*Sep 26 14:25:21.103: ISAKMP (0:2001): incrementing error counter on sa, attempt 1 of 5: retransmit phase 1

*Sep 26 14:25:21.103: ISAKMP:(2001): retransmitting phase 1 MM_KEY_EXCH

*Sep 26 14:25:21.103: ISAKMP:(2001): sending packet to X.X.X.X my_port 500 peer_port 500 (R) MM_KEY_EXCH

*Sep 26 14:25:21.103: ISAKMP:(2001):Sending an IKE IPv4 Packet.

HUB-CE1#

*Sep 26 14:25:31.103: ISAKMP:(2001): retransmitting phase 1 MM_KEY_EXCH...

*Sep 26 14:25:31.103: ISAKMP (0:2001): incrementing error counter on sa, attempt 2 of 5: retransmit phase 1

*Sep 26 14:25:31.103: ISAKMP:(2001): retransmitting phase 1 MM_KEY_EXCH

*Sep 26 14:25:31.103: ISAKMP:(2001): sending packet to X.X.X.X my_port 500 peer_port 500 (R) MM_KEY_EXCH

*Sep 26 14:25:31.103: ISAKMP:(2001):Sending an IKE IPv4 Packet.

HUB-CE1#

*Sep 26 14:25:41.103: ISAKMP:(2001): retransmitting phase 1 MM_KEY_EXCH...

*Sep 26 14:25:41.103: ISAKMP (0:2001): incrementing error counter on sa, attempt 3 of 5: retransmit phase 1

*Sep 26 14:25:41.103: ISAKMP:(2001): retransmitting phase 1 MM_KEY_EXCH

*Sep 26 14:25:41.103: ISAKMP:(2001): sending packet to X.X.X.X my_port 500 peer_port 500 (R) MM_KEY_EXCH

*Sep 26 14:25:41.103: ISAKMP:(2001):Sending an IKE IPv4 Packet.

HUB-CE1#

*Sep 26 14:25:51.103: ISAKMP:(2001): retransmitting phase 1 MM_KEY_EXCH...

*Sep 26 14:25:51.103: ISAKMP (0:2001): incrementing error counter on sa, attempt 4 of 5: retransmit phase 1

*Sep 26 14:25:51.103: ISAKMP:(2001): retransmitting phase 1 MM_KEY_EXCH

*Sep 26 14:25:51.103: ISAKMP:(2001): sending packet to X.X.X.X my_port 500 peer_port 500 (R) MM_KEY_EXCH

*Sep 26 14:25:51.103: ISAKMP:(2001):Sending an IKE IPv4 Packet.

HUB-CE1#

*Sep 26 14:26:01.103: ISAKMP:(2001): retransmitting phase 1 MM_KEY_EXCH...

*Sep 26 14:26:01.103: ISAKMP (0:2001): incrementing error counter on sa, attempt 5 of 5: retransmit phase 1

*Sep 26 14:26:01.103: ISAKMP:(2001): retransmitting phase 1 MM_KEY_EXCH

*Sep 26 14:26:01.103: ISAKMP:(2001): sending packet to X.X.X.X my_port 500 peer_port 500 (R) MM_KEY_EXCH

*Sep 26 14:26:01.103: ISAKMP:(2001):Sending an IKE IPv4 Packet.

HUB-CE1#

*Sep 26 14:26:11.103: ISAKMP:(2001): retransmitting phase 1 MM_KEY_EXCH...

*Sep 26 14:26:11.103: ISAKMP:(2001):peer does not do paranoid keepalives.

*Sep 26 14:26:11.103: ISAKMP:(2001):deleting SA reason "Death by retransmission P1" state (R) MM_KEY_EXCH (peer X.X.X.X)

*Sep 26 14:26:11.103: ISAKMP: Unlocking peer struct 0x847E0A54 for isadb_mark_sa_deleted(), count 0

*Sep 26 14:26:11.103: ISAKMP: Deleting peer node by peer_reap for X.X.X.X: 847E0A54

*Sep 26 14:26:11.103: CRYPTO_PKI: unlocked trustpoint TRUSTPOINT-CA1, refcount is 0

HUB-CE1#

*Sep 26 14:26:11.103: ISAKMP:(2001):Input = IKE_MESG_INTERNAL, IKE_PHASE1_DEL

*Sep 26 14:26:11.103: ISAKMP:(2001):Old State = IKE_R_MM4 New State = IKE_DEST_SA

HUB-CE1#

*Sep 26 14:26:22.995: ISAKMP (0:0): received packet from X.X.X.X dport 500 sport 500 Global (N) NEW SA

*Sep 26 14:26:22.995: ISAKMP: Created a peer struct for X.X.X.X, peer port 500

*Sep 26 14:26:22.995: ISAKMP: New peer created peer = 0x847E0A54 peer_handle = 0x80000003

*Sep 26 14:26:22.995: ISAKMP: Locking peer struct 0x847E0A54, refcount 1 for crypto_isakmp_process_block

*Sep 26 14:26:22.995: ISAKMP: local port 500, remote port 500

*Sep 26 14:26:22.995: ISAKMP: Find a dup sa in the avl tree during calling isadb_insert sa = 847B762C

*Sep 26 14:26:22.995: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH

*Sep 26 14:26:22.995: ISAKMP:(0):Old State = IKE_READY New State = IKE_R_MM1

*Sep 26 14:26:22.995: ISAKMP:(0): processing SA payload. message ID = 0

*Sep 26 14:26:22.995: ISAKMP:(0): processing vendor id payload

*Sep 26 14:26:22.995: ISAKMP:(0): vendor ID seems Unity/DPD but major 69 mismatch

*Sep 26 14:26:22.995: ISAKMP (0:0): vendor ID is NAT-T RFC 394

HUB-CE1#7

*Sep 26 14:26:22.995: ISAKMP:(0): processing vendor id payload

*Sep 26 14:26:22.995: ISAKMP:(0): vendor ID seems Unity/DPD but major 245 mismatch

*Sep 26 14:26:22.995: ISAKMP (0:0): vendor ID is NAT-T v7

*Sep 26 14:26:22.995: ISAKMP:(0): processing vendor id payload

*Sep 26 14:26:22.995: ISAKMP:(0): vendor ID seems Unity/DPD but major 157 mismatch

*Sep 26 14:26:22.995: ISAKMP:(0): vendor ID is NAT-T v3

*Sep 26 14:26:22.995: ISAKMP:(0): processing vendor id payload

*Sep 26 14:26:22.995: ISAKMP:(0): vendor ID seems Unity/DPD but major 123 mismatch

*Sep 26 14:26:22.995: ISAKMP:(0): vendor ID is NAT-T v2

*Sep 26 14:26:22.995: ISAKMP:(0):found peer pre-shared key matching X.X.X.X

*Sep 26 14:26:22.995: ISAKMP:(0): local preshared key found

*Sep 26 14:26:22.995: ISAKMP : Scanning profiles for xauth ...

*Sep 26 14:26:22.995: ISAKMP:(0):Checking ISAKMP transform 1 against priority 10 policy

*Sep 26 14:26:22.995: ISAKMP: encryption AES-CBC

*Sep 26 14:26:22.995: ISAKMP: keylength of 192

*Sep 26 14:26:22.995: ISAKMP: hash MD5

*Sep 26 14:26:22.995: ISAKMP: default group 2

*Sep 26 14:26:22.995: ISAKMP: auth RSA sig

*Sep 26 14:26:22.995: ISAKMP: life type in seconds

*Sep 26 14:26:22.995: ISAKMP: life duration (basic) of 43200

*Sep 26 14:26:22.995: ISAKMP:(0):Authentication method offered does not match policy!

*Sep 26 14:26:22.995: ISAKMP:(0):atts are not acceptable. Next payload is 3

*Sep 26 14:26:22.995: ISAKMP:(0):Checking ISAKMP transform 2 against priority 10 policy

*Sep 26 14:26:22.995: ISAKMP: encryption 3DES-CBC

*Sep 26 14:26:22.995: ISAKMP: hash SHA

*Sep 26 14:26:22.995: ISAKMP: default group 2

*Sep 26 14:26:22.995: ISAKMP: auth pre-share

*Sep 26 14:26:22.995: ISAKMP: life type in seconds

*Sep 26 14:26:22.995: ISAKMP: life duration (basic) of 21600

*Sep 26 14:26:22.999: ISAKMP:(0):Encryption algorithm offered does not match policy!

*Sep 26 14:26:22.999: ISAKMP:(0):atts are not acceptable. Next payload is 0

*Sep 26 14:26:22.999: ISAKMP:(0):Checking ISAKMP transform 1 against priority 20 policy

*Sep 26 14:26:22.999: ISAKMP: encryption AES-CBC

*Sep 26 14:26:22.999: ISAKMP: keylength of 192

*Sep 26 14:26:22.999: ISAKMP: hash MD5

*Sep 26 14:26:22.999: ISAKMP: default group 2

*Sep 26 14:26:22.999: ISAKMP: auth RSA sig

*Sep 26 14:26:22.999: ISAKMP: life type in seconds

*Sep 26 14:26:22.999: ISAKMP: life duration (basic) of 43200

*Sep 26 14:26:22.999: ISAKMP:(0):atts are acceptable. Next payload is 3

*Sep 26 14:26:22.999: ISAKMP:(0):Acceptable atts:actual life: 0

*Sep 26 14:26:22.999: ISAKMP:(0):Acceptable atts:life: 0

*Sep 26 14:26:22.999: ISAKMP:(0):Basic life_in_seconds:43200

*Sep 26 14:26:22.999: ISAKMP:(0):Returning Actual lifetime: 43200

*Sep 26 14:26:22.999: ISAKMP:(0)::Started lifetime timer: 43200.

*Sep 26 14:26:22.999: ISAKMP:(0): processing vendor id payload

*Sep 26 14:26:22.999: ISAKMP:(0): vendor ID seems Unity/DPD but major 69 mismatch

*Sep 26 14:26:22.999: ISAKMP (0:0): vendor ID is NAT-T RFC 3947

*Sep 26 14:26:22.999: ISAKMP:(0): processing vendor id payload

*Sep 26 14:26:22.999: ISAKMP:(0): vendor ID seems Unity/DPD but major 245 mismatch

*Sep 26 14:26:22.999: ISAKMP (0:0): vendor ID is NAT-T v7

*Sep 26 14:26:22.999: ISAKMP:(0): processing vendor id payload

*Sep 26 14:26:22.999: ISAKMP:(0): vendor ID seems Unity/DPD but major 157 mismatch

*Sep 26 14:26:22.999: ISAKMP:(0): vendor ID is NAT-T v3

*Sep 26 14:26:22.999: ISAKMP:(0): processing vendor id payload

*Sep 26 14:26:22.999: ISAKMP:(0): vendor ID seems Unity/DPD but major 123 mismatch

*Sep 26 14:26:22.999: ISAKMP:(0): vendor ID is NAT-T v2

*Sep 26 14:26:22.999: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE

*Sep 26 14:26:22.999: ISAKMP:(0):Old State = IKE_R_MM1 New State = IKE_R_MM1

*Sep 26 14:26:22.999: ISAKMP:(0): constructed NAT-T vendor-rfc3947 ID

*Sep 26 14:26:22.999: ISAKMP:(0): sending packet to X.X.X.X my_port 500 peer_port 500 (R) MM_SA_SETUP

*Sep 26 14:26:22.999: ISAKMP:(0):Sending an IKE IPv4 Packet.

*Sep 26 14:26:22.999: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE

*Sep 26 14:26:22.999: ISAKMP:(0):Old State = IKE_R_MM1 New State = IKE_R_MM2

*Sep 26 14:26:23.019: ISAKMP (0:0): received packet from X.X.X.X dport 500 sport 500 Global (R) MM_SA_SETUP

*Sep 26 14:26:23.023: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH

*Sep 26 14:26:23.023: ISAKMP:(0):Old State = IKE_R_MM2 New State = IKE_R_MM3

*Sep 26 14:26:23.023: ISAKMP:(0): processing KE payload. message ID = 0

*Sep 26 14:26:23.051: ISAKMP:(0): processing NONCE payload. message ID = 0

*Sep 26 14:26:23.051: ISAKMP:(2002): processing CERT_REQ payload. message ID = 0

*Sep 26 14:26:23.051: ISAKMP:(2002): peer wants a CT_X509_SIGNATURE cert

*Sep 26 14:26:23.051: ISAKMP:(2002): peer wants cert issued by cn=SPTEST2-CA,dc=GL

*Sep 26 14:26:23.051: CRYPTO_PKI: Trust-Point TRUSTPOINT-CA1 picked up

*Sep 26 14:26:23.051: Choosing trustpoint TRUSTPOINT-CA1 as issuer

*Sep 26 14:26:23.051: CRYPTO_PKI: unlocked trustpoint TRUSTPOINT-CA1, refcount is 0

*Sep 26 14:26:23.051: CRYPTO_PKI: locked trustpoint TRUSTPOINT-CA1, refcount is 1

*Sep 26 14:26:23.051: ISAKMP:(2002): processing vendor id payload

*Sep 26 14:26:23.051: ISAKMP:(2002): vendor ID is DPD

*Sep 26 14:26:23.051: ISAKMP:(2002): processing vendor id payload

*Sep 26 14:26:23.051: ISAKMP:(2002): speaking to another IOS box!

*Sep 26 14:26:23.051: ISAKMP:(2002): processing vendor id payload

*Sep 26 14:26:23.051: ISAKMP:(2002): vendor ID seems Unity/DPD but major 236 mismatch

*Sep 26 14:26:23.051: ISAKMP:(2002): vendor ID is XAUTH

*Sep 26 14:26:23.051: ISAKMP:received payload type 20

*Sep 26 14:26:23.051: ISAKMP:(2002):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE

*Sep 26 14:26:23.055: ISAKMP:(2002):Old State = IKE_R_MM3 New State = IKE_R_MM3

*Sep 26 14:26:23.055: ISAKMP (0:2002): constructing CERT_REQ for issuer cn=SPTEST2-CA,dc=GL

*Sep 26 14:26:23.055: ISAKMP:(2002): sending packet to X.X.X.X my_port 500 peer_port 500 (R) MM_KEY_EXCH

*Sep 26 14:26:23.055: ISAKMP:(2002):Sending an IKE IPv4 Packet.

*Sep 26 14:26:23.055: ISAKMP:(2002):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE

*Sep 26 14:26:23.055: ISAKMP:(2002):Old State = IKE_R_MM3 New State = IKE_R_MM4

HUB-CE1#

*Sep 26 14:26:33.055: ISAKMP:(2002): retransmitting phase 1 MM_KEY_EXCH...

*Sep 26 14:26:33.055: ISAKMP (0:2002): incrementing error counter on sa, attempt 1 of 5: retransmit phase 1

*Sep 26 14:26:33.055: ISAKMP:(2002): retransmitting phase 1 MM_KEY_EXCH

*Sep 26 14:26:33.055: ISAKMP:(2002): sending packet to X.X.X.X my_port 500 peer_port 500 (R) MM_KEY_EXCH

*Sep 26 14:26:33.055: ISAKMP:(2002):Sending an IKE IPv4 Packet.

*Sep 26 14:26:43.055: ISAKMP:(2002): retransmitting phase 1 MM_KEY_EXCH...

*Sep 26 14:26:43.055: ISAKMP (0:2002): incrementing error counter on sa, attempt 2 of 5: retransmit phase 1

*Sep 26 14:26:43.055: ISAKMP:(2002): retransmitting phase 1 MM_KEY_EXCH

*Sep 26 14:26:43.055: ISAKMP:(2002): sending packet to X.X.X.X my_port 500 peer_port 500 (R) MM_KEY_EXCH

*Sep 26 14:26:43.055: ISAKMP:(2002):Sending an IKE IPv4 Packet.

HUB-CE1#

*Sep 26 14:26:53.055: ISAKMP:(2002): retransmitting phase 1 MM_KEY_EXCH...

*Sep 26 14:26:53.055: ISAKMP (0:2002): incrementing error counter on sa, attempt 3 of 5: retransmit phase 1

*Sep 26 14:26:53.055: ISAKMP:(2002): retransmitting phase 1 MM_KEY_EXCH

*Sep 26 14:26:53.055: ISAKMP:(2002): sending packet to X.X.X.X my_port 500 peer_port 500 (R) MM_KEY_EXCH

*Sep 26 14:26:53.055: ISAKMP:(2002):Sending an IKE IPv4 Packet.

Marcin Latosiewicz · ‎09-26-2011

Anton,

The MM5 packet sent by spoke never makes it to the hub as you can see.

Maybe packet containing certificate is too big/gets fragments/lost?

Marcin

Anton Pestov · ‎09-26-2011

Thanks, Marcin!

For some reason hasn't thought immediately of it. I have changed the ISP for HUB1(get IP from HUB2 ISP pool IP) and Tunnel1 is up! But i have new question with this situation: how have been changed the IP-paket format, if I insert 'subject-name' parameter? What new size of paket (MTU)? How I can resolve this problem itself, without request my ISP?

Marcin Latosiewicz · ‎09-27-2011

Anton,

Wish I had an easy answer. ;-)

My guess is that you put additional info in the certificate itself which will cause fragmentataion.

We'd need to compare a sniffer trace + debug for working and non-working scenario.

Marcin

Anton Pestov · ‎09-28-2011

This problem has repeated again with same ("previously worked") ISP for two HUBs: one Tunnel and IKE is up, second Tunnel and IKE-session haven't been established. (((

Marcin Latosiewicz · ‎09-28-2011

Anton,

At this stage I would say it's best to open up a TAC case, someone needs to have a look into this in more detail than forums allow.

M.

Anton Pestov · ‎09-28-2011

I think that all problems with CA Server (Standalone MS ADCS). This server doesn't response to requests which have been generated by HUB Routers.

Crypto PKI debug examples:

1. From work HUB Router:

...

*Sep 28 14:52:37.247: CRYPTO_PKI: validation path has 1 certs

*Sep 28 14:52:37.247: CRYPTO_PKI: Check for identical certs

*Sep 28 14:52:37.247: CRYPTO_PKI: Create a list of suitable trustpoints

*Sep 28 14:52:37.247: CRYPTO_PKI: Found a issuer match

*Sep 28 14:52:37.247: CRYPTO_PKI: Suitable trustpoints are: TRUSTPOINT-CA1,

*Sep 28 14:52:37.247: CRYPTO_PKI: Attempting to validate certificate using TRUSTPOINT-CA1

*Sep 28 14:52:37.247: CRYPTO_PKI: Using TRUSTPOINT-CA1 to validate certificate

*Sep 28 14:52:37.251: ../crypto/ca/provider/path/pkix/pkixpath.c(5734) : E_PATH_PROVIDER : path provider specific warning (BasicConstraints extension found in end entity cert)

*Sep 28 14:52:37.259: CRYPTO_PKI: Certificate is verified

*Sep 28 14:52:37.259: CRYPTO_PKI: Checking certificate revocation

*Sep 28 14:52:37.259: CRYPTO_PKI: Starting CRL revocation

*Sep 28 14:52:37.259: CRYPTO_PKI: CDP does not exist. Use SCEP to query CRL.

*Sep 28 14:52:37.259: CRYPTO_PKI: pki request queued properly

*Sep 28 14:52:37.259: CRYPTO_PKI: status = 0: poll CRL

*Sep 28 14:52:37.263: CRYPTO_PKI: Sending CA Certificate Request:

GET /certsrv/mscep/mscep.dll/pkiclient.exe?operation=GetCACert&message=TRUSTPOINT-CA1 HTTP/1.0

User-Agent: Mozilla/4.0 (compatible; MSIE 5.0; Cisco PKI)

Host: SRSPTEST2

*Sep 28 14:52:37.263: CRYPTO_PKI: locked trustpoint TRUSTPOINT-CA1, refcount is 2

*Sep 28 14:52:37.263: CRYPTO_PKI: http connection opened

*Sep 28 14:52:37.263: CRYPTO_PKI: Sending HTTP message

*Sep 28 14:52:37.263: CRYPTO_PKI: Reply HTTP header:

HTTP/1.0

User-Agent: Mozilla/4.0 (compatible; MSIE 5.0; Cisco PKI)

Host: SRSPTEST2

*Sep 28 14:52:37.263: CRYPTO_PKI: unlocked trustpoint TRUSTPOINT-CA1, refcount is 1

*Sep 28 14:52:37.263: CRYPTO_PKI: locked trustpoint TRUSTPOINT-CA1, refcount is 2

*Sep 28 14:52:37.271: CRYPTO_PKI: unlocked trustpoint TRUSTPOINT-CA1, refcount is 1

*Sep 28 14:52:37.271: CRYPTO_PKI: Reply HTTP header:

HTTP/1.1 200 OK

Content-Length: 3402

Content-Type: application/x-x509-ca-ra-cert

Server: Microsoft-IIS/7.5

Date: Wed, 28 Sep 2011 13:38:46 GMT

Connection: close

Content-Type indicates we have received CA and RA certificates.

*Sep 28 14:52:37.271: CRYPTO_PKI:crypto_process_ca_ra_cert(trustpoint=TRUSTPOINT-CA1)

*Sep 28 14:52:37.279: The PKCS #7 message contains 3 certificates.

*Sep 28 14:52:37.283: CRYPTO_PKI:crypto_pkcs7_insert_ra_certs found RA certs

*Sep 28 14:52:37.291: CRYPTO_PKI:crypto_pkcs7_insert_ra_certs found RA certs

*Sep 28 14:52:37.295: CRYPTO_PKI: Sending Get Capabilities Request:

GET /certsrv/mscep/mscep.dll/pkiclient.exe?operation=GetCACaps&message=TRUSTPOINT-CA1 HTTP/1.0

User-Agent: Mozilla/4.0 (compatible; MSIE 5.0; Cisco PKI)

Host: SRSPTEST2

*Sep 28 14:52:37.295: CRYPTO_PKI: locked trustpoint TRUSTPOINT-CA1, refcount is 2

*Sep 28 14:52:37.295: CRYPTO_PKI: http connection opened

*Sep 28 14:52:37.295: CRYPTO_PKI: Sending HTTP message

*Sep 28 14:52:37.295: CRYPTO_PKI: Reply HTTP header:

HTTP/1.0

User-Agent: Mozilla/4.0 (compatible; MSIE 5.0; Cisco PKI)

Host: SRSPTEST2

*Sep 28 14:52:37.295: CRYPTO_PKI: unlocked trustpoint TRUSTPOINT-CA1, refcount is 1

*Sep 28 14:52:37.295: CRYPTO_PKI: locked trustpoint TRUSTPOINT-CA1, refcount is 2

*Sep 28 14:52:37.299: CRYPTO_PKI: unlocked trustpoint TRUSTPOINT-CA1, refcount is 1

*Sep 28 14:52:37.299: CRYPTO_PKI: Reply HTTP header:

HTTP/1.1 200 OK

Server: Microsoft-IIS/7.5

Date: Wed, 28 Sep 2011 13:38:46 GMT

Connection: close

Content-Length: 0

*Sep 28 14:52:37.299: CRYPTO-PKI: Server returned no capabilities

Capabilities not retrieved

*Sep 28 14:52:37.299: PKI:PKCS7 to issuer cn=SPTEST2-CA,dc=GL serial 61 47 35 8D 00 00 00 00 00 03

*Sep 28 14:52:37.323: PKI: Trustpoint TRUSTPOINT-CA1 has router cert and loaded

*Sep 28 14:52:37.323: PKI: Signing pkcs7 with TRUSTPOINT-CA1 trustpoint router cert

*Sep 28 14:52:37.323: PKI: key rollover configured

*Sep 28 14:52:37.443: CRYPTO_PKI: locked trustpoint TRUSTPOINT-CA1, refcount is 2

*Sep 28 14:52:37.443: CRYPTO_PKI: http connection opened

*Sep 28 14:52:37.443: CRYPTO_PKI: Sending HTTP message

*Sep 28 14:52:37.443: CRYPTO_PKI: Reply HTTP header:

HTTP/1.0

Host: SRSPTEST2

*Sep 28 14:52:37.651: CRYPTO_PKI: unlocked trustpoint TRUSTPOINT-CA1, refcount is 1

*Sep 28 14:52:37.651: CRYPTO_PKI: locked trustpoint TRUSTPOINT-CA1, refcount is 2

*Sep 28 14:52:37.879: CRYPTO_PKI: unlocked trustpoint TRUSTPOINT-CA1, refcount is 1

*Sep 28 14:52:37.879: CRYPTO_PKI: received msg of 4092 bytes

*Sep 28 14:52:37.879: CRYPTO_PKI: Reply HTTP header:

HTTP/1.1 200 OK

Content-Length: 3927

Content-Type: application/x-pki-message

Server: Microsoft-IIS/7.5

Date: Wed, 28 Sep 2011 13:38:46 GMT

Connection: close

*Sep 28 14:52:37.879: CRYPTO_PKI: make trustedCerts list for TRUSTPOINT-CA1

...

2. From doesn't work HUB Router:

*Sep 28 14:46:19.247: CRYPTO_PKI: validation path has 1 certs

*Sep 28 14:46:19.247: CRYPTO_PKI: Check for identical certs

*Sep 28 14:46:19.247: CRYPTO_PKI: Create a list of suitable trustpoints

*Sep 28 14:46:19.247: CRYPTO_PKI: Found a issuer match

*Sep 28 14:46:19.247: CRYPTO_PKI: Suitable trustpoints are: TRUSTPOINT-CA1,

*Sep 28 14:46:19.247: CRYPTO_PKI: Attempting to validate certificate using TRUSTPOINT-CA1

*Sep 28 14:46:19.247: CRYPTO_PKI: Using TRUSTPOINT-CA1 to validate certificate

*Sep 28 14:46:19.251: ../crypto/ca/provider/path/pkix/pkixpath.c(5734) : E_PATH_PROVIDER : path provider specific warning (BasicConstraints extension found in end entity cert)

*Sep 28 14:46:19.259: CRYPTO_PKI: Certificate is verified

*Sep 28 14:46:19.259: CRYPTO_PKI: Checking certificate revocation

*Sep 28 14:46:19.259: CRYPTO_PKI: Starting CRL revocation

*Sep 28 14:46:19.259: CRYPTO_PKI: CDP does not exist. Use SCEP to query CRL.

*Sep 28 14:46:19.259: CRYPTO_PKI: pki request queued properly

*Sep 28 14:46:19.259: CRYPTO_PKI: status = 0: poll CRL

*Sep 28 14:46:22.263: CRYPTO_PKI: Sending CA Certificate Request:

GET /certsrv/mscep/mscep.dll/pkiclient.exe?operation=GetCACert&message=TRUSTPOINT-CA1 HTTP/1.0

User-Agent: Mozilla/4.0 (compatible; MSIE 5.0; Cisco PKI)

Host: SRSPTEST2

*Sep 28 14:46:22.263: CRYPTO_PKI: locked trustpoint TRUSTPOINT-CA1, refcount is 2

*Sep 28 14:46:22.263: CRYPTO_PKI: http connection opened

*Sep 28 14:46:22.263: CRYPTO_PKI: Sending HTTP message

*Sep 28 14:46:22.263: CRYPTO_PKI: Reply HTTP header:

HTTP/1.0

User-Agent: Mozilla/4.0 (compatible; MSIE 5.0; Cisco PKI)

Host: SRSPTEST2

*Sep 28 14:46:37.263: CRYPTO_PKI: Retry 1

*Sep 28 14:46:52.275: CRYPTO_PKI: Retry 2

*Sep 28 14:46:52.275: %PKI-3-SOCKETSEND: Failed to send out message to CA server.

*Sep 28 14:46:52.275: CRYPTO_PKI: unlocked trustpoint TRUSTPOINT-CA1, refcount is 1

*Sep 28 14:46:52.275: CRYPTO_PKI: status = 65535: failed to send out the pki message

Marcin Latosiewicz · ‎09-30-2011

Anton,

Sorry for late reply, I head a few hectic days.

Indeed it looks like there is a problem to reach the CA for some reason, alhought it looks like we ARE reciving something in reply.

I guess we need to sniff traffic between CA and router to see what is happening on the wire ;/

Or maybe you already figured it out?

Marcin

Anton Pestov · ‎10-05-2011

At present I see 2 problems:

- In the provider through whom don't take place IKE_MM3 answers from HUB

- In CA the server which sometimes doesn't answer inquiries simultaneously from two HUB (only one of them receives the answer)

Marcin Latosiewicz · ‎10-05-2011

Anton,

Just to be sure I would open up a TAC case, would help us;

1) Understand if no mistake was done on our part

2) Doublecheck the findings.

It's of course up to you.

Marcin

Anton Pestov · ‎10-05-2011

Ok, Marcin! Open, please, a TAC case. Thank you!