Understanding IOS IPSec and IKE debugs - IKEv1 Aggressive Mode.

Marcin Latosiewicz — Tue, 29 Aug 2017 09:38:43 GMT

Disclaimer: This is best effort work only, it may (and probably is) not 100% correct. This work will be corrected as corrective feedback is received.

1. Introduction

This document will attempt to describe how to understand debugs on ASA when aggressive mode and pre shared key (PSK) is being used.

How to translate certain debug lines into configuration.

What will not be discussed:

- passing traffic after tunnel has been established.

- basic concepts of IPSec or IKE.

2. Core issue

IKE and IPSec debugs tend to get cryptic, TAC will very often use them to understand where a problem with IPSec VPN tunnel establishment is located.

3. Scenario

Aggressive mode is typically used in case of EZVPN, both software (Cisco VPN client) and hardware clients (ASA 5505 or IOS routers), but only when using pre shared key (PSK).

Those debugs are from IOS 15.0.1M5 EZVPN headend, EZVPN client will be a router (same version), in client mode.

On server side I will be using DVTI, and client side no DVTI.

3.1 Debugs used.

debug crypto isakmp

debug crypto ipsec

Optional debugs on client:

debug crypto ipsec client ezvpn

Optional debugs on both (internal and containing WAY too much info to be discussed here)

debug crypto isakmp detail

debug crypto isakmp packet

3.2 Hardware client configuration.

crypto ipsec client ezvpn EZ

connect manual

group cisco key cisco

mode client

peer 192.2.0.1 default

peer 192.2.0.2

username cisco password cisco

xauth userid mode local

interface Ethernet0/0

ip address 192.2.1.2 255.255.255.0

crypto ipsec client ezvpn EZ

interface Ethernet1/0

ip address 192.168.101.1 255.255.255.0

crypto ipsec client ezvpn EZ inside

3.3 Headend configuration.

DVTI_Server#sh run | s aaa|crypto|Virtual

aaa authentication login AAA local

aaa authentication login AUTH local

aaa authorization network AUTH local

crypto isakmp policy 10

encr aes

authentication pre-share

group 2

crypto isakmp keepalive 120 5

crypto isakmp client configuration group cisco

key cisco

pool PRIMARY

save-password

crypto isakmp profile ISA_PRO

match identity group cisco

client authentication list AUTH

isakmp authorization list AUTH

client configuration address respond

virtual-template 1

crypto ipsec transform-set TRA esp-aes esp-sha-hmac

crypto ipsec profile PRO

set transform-set TRA

interface Virtual-Template1 type tunnel

no ip address

tunnel mode ipsec ipv4

tunnel protection ipsec profile PRO

4. Debugging

4.1 Phase 1 - Aggressive mode.

4.1.1 Aggressive mode message 1 (AM1); sent from client to server.

Includes:

- capabilities (Vendor IDs)

- isakmp proposals

- group (identity)

- PSK

- Diffie-Hellman exchange.

- Landing on a profile.

*Jun 17 07:33:19.035: ISAKMP (0): received packet from 192.2.1.2 dport 500 sport 500 Global (N) NEW SA

*Jun 17 07:33:19.035: ISAKMP: Created a peer struct for 192.2.1.2, peer port 500

*Jun 17 07:33:19.035: ISAKMP: New peer created peer = 0x5BFDED8 peer_handle = 0x80000007

*Jun 17 07:33:19.035: ISAKMP: Locking peer struct 0x5BFDED8, refcount 1 for crypto_isakmp_process_block

*Jun 17 07:33:19.035: ISAKMP: local port 500, remote port 500

*Jun 17 07:33:19.035: ISAKMP:(0):insert sa successfully sa = 64487E8

*Jun 17 07:33:19.035: ISAKMP:(0): processing SA payload. message ID = 0

*Jun 17 07:33:19.035: ISAKMP:(0): processing ID payload. message ID = 0

*Jun 17 07:33:19.035: ISAKMP (0): ID payload

next-payload : 13

type : 11

group id : cisco

protocol : 17

port : 0

length : 13

*Jun 17 07:33:19.035: ISAKMP:(0):: peer matches ISA_PRO profile

*Jun 17 07:33:19.035: ISAKMP:(0):Setting client config settings 6407F30

*Jun 17 07:33:19.035: ISAKMP:(0):(Re)Setting client xauth list and state

*Jun 17 07:33:19.035: ISAKMP/xauth: initializing AAA request

*Jun 17 07:33:19.035: ISAKMP:(0): processing vendor id payload

*Jun 17 07:33:19.035: ISAKMP:(0): vendor ID seems Unity/DPD but major 69 mismatch

*Jun 17 07:33:19.035: ISAKMP (0): vendor ID is NAT-T RFC 3947

*Jun 17 07:33:19.035: ISAKMP:(0): processing vendor id payload

*Jun 17 07:33:19.035: ISAKMP:(0): vendor ID seems Unity/DPD but major 245 mismatch

*Jun 17 07:33:19.035: ISAKMP (0): vendor ID is NAT-T v7

*Jun 17 07:33:19.035: ISAKMP:(0): processing vendor id payload

*Jun 17 07:33:19.035: ISAKMP:(0): vendor ID seems Unity/DPD but major 157 mismatch

*Jun 17 07:33:19.035: ISAKMP:(0): vendor ID is NAT-T v3

*Jun 17 07:33:19.035: ISAKMP:(0): processing vendor id payload

*Jun 17 07:33:19.035: ISAKMP:(0): vendor ID seems Unity/DPD but major 123 mismatch

*Jun 17 07:33:19.035: ISAKMP:(0): vendor ID is NAT-T v2

*Jun 17 07:33:19.035: ISAKMP:(0): Authentication by xauth preshared

*Jun 17 07:33:19.035: ISAKMP:(0):Checking ISAKMP transform 1 against priority 10 policy

*Jun 17 07:33:19.035: ISAKMP: encryption AES-CBC

*Jun 17 07:33:19.035: ISAKMP: keylength of 128

*Jun 17 07:33:19.035: ISAKMP: hash SHA

*Jun 17 07:33:19.035: ISAKMP: default group 2

*Jun 17 07:33:19.035: ISAKMP: auth XAUTHInitPreShared

*Jun 17 07:33:19.035: ISAKMP: life type in seconds

*Jun 17 07:33:19.035: ISAKMP: life duration (VPI) of 0x0 0x20 0xC4 0x9B

*Jun 17 07:33:19.035: ISAKMP:(0):atts are acceptable. Next payload is 3

*Jun 17 07:33:19.035: ISAKMP:(0):Acceptable atts:actual life: 86400

*Jun 17 07:33:19.035: ISAKMP:(0):Acceptable atts:life: 0

*Jun 17 07:33:19.035: ISAKMP:(0):Fill atts in sa vpi_length:4

*Jun 17 07:33:19.035: ISAKMP:(0):Fill atts in sa life_in_seconds:2147483

*Jun 17 07:33:19.035: ISAKMP:(0):Returning Actual lifetime: 86400

*Jun 17 07:33:19.035: ISAKMP:(0)::Started lifetime timer: 86400.

Relevant configuration.

ISAKMP being enabled on interface and at least one policy defined and matching what client sent.

crypto isakmp policy 10

encr aes

authentication pre-share

group 2

crypto isakmp profile ISA_PRO

match identity group cisco

isakmp authorization list AUTH

crypto isakmp client configuration group cisco

key cisco

4.1.2 Aggressive mode message 2 (AM2); sent from server to client.

Includes:

- capabilities

- DH exchange

- Identity

*Jun 17 07:33:19.035: ISAKMP:(0): processing vendor id payload

*Jun 17 07:33:19.035: ISAKMP:(0): vendor ID seems Unity/DPD but major 69 mismatch

*Jun 17 07:33:19.035: ISAKMP (0): vendor ID is NAT-T RFC 3947

*Jun 17 07:33:19.035: ISAKMP:(0): processing vendor id payload

*Jun 17 07:33:19.035: ISAKMP:(0): vendor ID seems Unity/DPD but major 245 mismatch

*Jun 17 07:33:19.035: ISAKMP (0): vendor ID is NAT-T v7

*Jun 17 07:33:19.035: ISAKMP:(0): processing vendor id payload

*Jun 17 07:33:19.035: ISAKMP:(0): vendor ID seems Unity/DPD but major 157 mismatch

*Jun 17 07:33:19.035: ISAKMP:(0): vendor ID is NAT-T v3

*Jun 17 07:33:19.035: ISAKMP:(0): processing vendor id payload

*Jun 17 07:33:19.035: ISAKMP:(0): vendor ID seems Unity/DPD but major 123 mismatch

*Jun 17 07:33:19.035: ISAKMP:(0): vendor ID is NAT-T v2

*Jun 17 07:33:19.035: ISAKMP:(0): processing KE payload. message ID = 0

*Jun 17 07:33:19.043: ISAKMP:(0): processing NONCE payload. message ID = 0

*Jun 17 07:33:19.043: ISAKMP:(0): processing vendor id payload

*Jun 17 07:33:19.043: ISAKMP:(0): vendor ID is DPD

*Jun 17 07:33:19.043: ISAKMP:(0): processing vendor id payload

*Jun 17 07:33:19.043: ISAKMP:(0): vendor ID seems Unity/DPD but major 33 mismatch

*Jun 17 07:33:19.043: ISAKMP:(0): vendor ID is XAUTH

*Jun 17 07:33:19.043: ISAKMP:(0): processing vendor id payload

*Jun 17 07:33:19.043: ISAKMP:(0): claimed IOS but failed authentication

*Jun 17 07:33:19.043: ISAKMP:(0): processing vendor id payload

*Jun 17 07:33:19.043: ISAKMP:(0): vendor ID is Unity

*Jun 17 07:33:19.043: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_AM_EXCH

*Jun 17 07:33:19.043: ISAKMP:(0):Old State = IKE_READY New State = IKE_R_AM_AAA_AWAIT

*Jun 17 07:33:19.063: ISAKMP:(1021): constructed NAT-T vendor-rfc3947 ID

*Jun 17 07:33:19.063: ISAKMP:(1021):SA is doing pre-shared key authentication plus XAUTH using id type ID_IPV4_ADDR

*Jun 17 07:33:19.063: ISAKMP (1021): ID payload

next-payload : 10

type : 1

address : 192.2.0.1

protocol : 0

port : 0

length : 12

*Jun 17 07:33:19.063: ISAKMP:(1021):Total payload length: 12

*Jun 17 07:33:19.063: ISAKMP:(1021): sending packet to 192.2.1.2 my_port 500 peer_port 500 (R) AG_INIT_EXCH

*Jun 17 07:33:19.063: ISAKMP:(1021):Sending an IKE IPv4 Packet.

*Jun 17 07:33:19.063: ISAKMP:(1021):Input = IKE_MESG_FROM_AAA, PRESHARED_KEY_REPLY

*Jun 17 07:33:19.063: ISAKMP:(1021):Old State = IKE_R_AM_AAA_AWAIT New State = IKE_R_AM2

4.1.3 Aggressive mode message 3 (AM3); Finish phase 1.

Contains:

- NAT discovery and decision.

*Jun 17 07:33:19.091: ISAKMP (1021): received packet from 192.2.1.2 dport 500 sport 500 Global (R) AG_INIT_EXCH

*Jun 17 07:33:19.091: ISAKMP:(1021): processing HASH payload. message ID = 0

*Jun 17 07:33:19.091: ISAKMP:received payload type 20

*Jun 17 07:33:19.091: ISAKMP (1021): His hash no match - this node outside NAT

*Jun 17 07:33:19.091: ISAKMP:received payload type 20

*Jun 17 07:33:19.091: ISAKMP (1021): No NAT Found for self or peer

*Jun 17 07:33:19.091: ISAKMP:(1021): processing NOTIFY INITIAL_CONTACT protocol 1

spi 0, message ID = 0, sa = 64487E8

*Jun 17 07:33:19.091: ISAKMP:(1021):SA authentication status:

authenticated

*Jun 17 07:33:19.091: ISAKMP:(1021):SA has been authenticated with 192.2.1.2

*Jun 17 07:33:19.091: ISAKMP:(1021):SA authentication status:

authenticated

*Jun 17 07:33:19.091: ISAKMP:(1021): Process initial contact,

bring down existing phase 1 and 2 SA's with local 192.2.0.1 remote 192.2.1.2 remote port 500

*Jun 17 07:33:19.091: ISAKMP:(1021):returning IP addr to the address pool

*Jun 17 07:33:19.091: ISAKMP: Trying to insert a peer 192.2.0.1/192.2.1.2/500/, and inserted successfully 5BFDED8.

*Jun 17 07:33:19.091: ISAKMP:(1021):Returning Actual lifetime: 86400

*Jun 17 07:33:19.091: ISAKMP: set new node -110506246 to CONF_XAUTH

*Jun 17 07:33:19.091: ISAKMP:(1021):Sending NOTIFY RESPONDER_LIFETIME protocol 1

spi 95630072, message ID = -110506246

*Jun 17 07:33:19.091: ISAKMP:(1021): sending packet to 192.2.1.2 my_port 500 peer_port 500 (R) QM_IDLE

*Jun 17 07:33:19.091: ISAKMP:(1021):Sending an IKE IPv4 Packet.

*Jun 17 07:33:19.091: ISAKMP:(1021):purging node -110506246

*Jun 17 07:33:19.091: ISAKMP: Sending phase 1 responder lifetime 86400

*Jun 17 07:33:19.091: ISAKMP:(1021):Input = IKE_MESG_FROM_PEER, IKE_AM_EXCH

*Jun 17 07:33:19.091: ISAKMP:(1021):Old State = IKE_R_AM2 New State = IKE_P1_COMPLETE

4.2 Phase 1.5 - Xauth and Mode config.

Xauth - eXtended AUTHentication. User authentication.

Authentication request sent from server to client.

*Jun 17 07:33:19.095: IPSEC(key_engine): got a queue event with 1 KMI message(s)

*Jun 17 07:33:19.095: ISAKMP:(1021):Need XAUTH

*Jun 17 07:33:19.095: ISAKMP: set new node 212826605 to CONF_XAUTH

*Jun 17 07:33:19.095: ISAKMP/xauth: request attribute XAUTH_USER_NAME_V2

*Jun 17 07:33:19.095: ISAKMP/xauth: request attribute XAUTH_USER_PASSWORD_V2

*Jun 17 07:33:19.095: ISAKMP:(1021): initiating peer config to 192.2.1.2. ID = 212826605

*Jun 17 07:33:19.095: ISAKMP:(1021): sending packet to 192.2.1.2 my_port 500 peer_port 500 (R) CONF_XAUTH

*Jun 17 07:33:19.095: ISAKMP:(1021):Sending an IKE IPv4 Packet.

*Jun 17 07:33:19.095: ISAKMP:(1021):Input = IKE_MESG_INTERNAL, IKE_PHASE1_COMPLETE

*Jun 17 07:33:19.095: ISAKMP:(1021):Old State = IKE_P1_COMPLETE New State = IKE_XAUTH_REQ_SENT

Authentication reply from client to server:

*Jun 17 07:33:19.135: ISAKMP (1021): received packet from 192.2.1.2 dport 500 sport 500 Global (R) CONF_XAUTH

*Jun 17 07:33:19.135: ISAKMP:(1021):processing transaction payload from 192.2.1.2. message ID = 212826605

*Jun 17 07:33:19.135: ISAKMP: Config payload REPLY

*Jun 17 07:33:19.135: ISAKMP/xauth: reply attribute XAUTH_USER_NAME_V2

*Jun 17 07:33:19.135: ISAKMP/xauth: reply attribute XAUTH_USER_PASSWORD_V2

*Jun 17 07:33:19.135: ISAKMP:(1021):deleting node 212826605 error FALSE reason "Done with xauth request/reply exchange"

*Jun 17 07:33:19.135: ISAKMP:(1021):Input = IKE_MESG_FROM_PEER, IKE_CFG_REPLY

*Jun 17 07:33:19.135: ISAKMP:(1021):Old State = IKE_XAUTH_REQ_SENT New State = IKE_XAUTH_AAA_CONT_LOGIN_AWAIT

Server is checking xauth against AAA method specified.

*Jun 17 07:33:19.135: ISAKMP: set new node 1203692846 to CONF_XAUTH

*Jun 17 07:33:19.135: ISAKMP:(1021): initiating peer config to 192.2.1.2. ID = 1203692846

*Jun 17 07:33:19.135: ISAKMP:(1021): sending packet to 192.2.1.2 my_port 500 peer_port 500 (R) CONF_XAUTH

*Jun 17 07:33:19.135: ISAKMP:(1021):Sending an IKE IPv4 Packet.

*Jun 17 07:33:19.135: ISAKMP:(1021):Input = IKE_MESG_FROM_AAA, IKE_AAA_CONT_LOGIN

*Jun 17 07:33:19.135: ISAKMP:(1021):Old State = IKE_XAUTH_AAA_CONT_LOGIN_AWAIT New State = IKE_XAUTH_SET_SENT

*Jun 17 07:33:19.139: ISAKMP (1021): received packet from 192.2.1.2 dport 500 sport 500 Global (R) CONF_XAUTH

*Jun 17 07:33:19.139: ISAKMP:(1021):processing transaction payload from 192.2.1.2. message ID = 1203692846

*Jun 17 07:33:19.139: ISAKMP: Config payload ACK

*Jun 17 07:33:19.139: ISAKMP:(1021): XAUTH ACK Processed

*Jun 17 07:33:19.139: ISAKMP:(1021):deleting node 1203692846 error FALSE reason "Transaction mode done"

*Jun 17 07:33:19.139: ISAKMP:(1021):Talking to a Unity Client

*Jun 17 07:33:19.139: ISAKMP:(1021):Input = IKE_MESG_FROM_PEER, IKE_CFG_ACK

*Jun 17 07:33:19.139: ISAKMP:(1021):Old State = IKE_XAUTH_SET_SENT New State = IKE_P1_COMPLETE

*Jun 17 07:33:19.139: ISAKMP:(1021):IKE_DPD is enabled, initializing timers

*Jun 17 07:33:19.139: ISAKMP:(1021):Input = IKE_MESG_INTERNAL, IKE_PHASE1_COMPLETE

*Jun 17 07:33:19.139: ISAKMP:(1021):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

Relevant configuration.

crypto isakmp profile ISA_PRO

client authentication list AUTH

Mode config - request and provide authentication attributes.

Contains:

- Request for parameters to configure client.

- Reply - at least and IP address and mask in typical scenario.

What the client request, you will not that the client asks for IP address and if it's allowed to have the password saved.(Among other things).

*Jun 17 07:33:19.139: ISAKMP (1021): received packet from 192.2.1.2 dport 500 sport 500 Global (R) QM_IDLE

*Jun 17 07:33:19.139: ISAKMP: set new node 659439105 to QM_IDLE

*Jun 17 07:33:19.139: ISAKMP:(1021):processing transaction payload from 192.2.1.2. message ID = 659439105

*Jun 17 07:33:19.139: ISAKMP: Config payload REQUEST

*Jun 17 07:33:19.139: ISAKMP:(1021):checking request:

*Jun 17 07:33:19.139: ISAKMP: IP4_ADDRESS

*Jun 17 07:33:19.139: ISAKMP: IP4_NETMASK

*Jun 17 07:33:19.139: ISAKMP: MODECFG_CONFIG_URL

*Jun 17 07:33:19.139: ISAKMP: MODECFG_CONFIG_VERSION

*Jun 17 07:33:19.139: ISAKMP: MODECFG_IPSEC_INT_CONF

*Jun 17 07:33:19.139: ISAKMP: IP4_DNS

*Jun 17 07:33:19.139: ISAKMP: IP4_NBNS

*Jun 17 07:33:19.139: ISAKMP: SPLIT_INCLUDE

*Jun 17 07:33:19.139: ISAKMP: SPLIT_DNS

*Jun 17 07:33:19.139: ISAKMP: DEFAULT_DOMAIN

*Jun 17 07:33:19.139: ISAKMP: MODECFG_SAVEPWD

*Jun 17 07:33:19.139: ISAKMP: INCLUDE_LOCAL_LAN

*Jun 17 07:33:19.139: ISAKMP: PFS

*Jun 17 07:33:19.139: ISAKMP: BACKUP_SERVER

*Jun 17 07:33:19.139: ISAKMP: APPLICATION_VERSION

*Jun 17 07:33:19.139: ISAKMP: MODECFG_BANNER

*Jun 17 07:33:19.139: ISAKMP: MODECFG_HOSTNAME

*Jun 17 07:33:19.139: ISAKMP/author: Author request for group ciscosuccessfully sent to AAA

*Jun 17 07:33:19.139: ISAKMP:(1021):Input = IKE_MESG_FROM_PEER, IKE_CFG_REQUEST

*Jun 17 07:33:19.139: ISAKMP:(1021):Old State = IKE_P1_COMPLETE New State = IKE_CONFIG_AUTHOR_AAA_AWAIT

Serer replies with:

- Here is your IP address - 10.1.1.100

- I am capable of doing VTI

- You can save passwords

*Jun 17 07:33:19.139: IPSEC(key_engine): got a queue event with 1 KMI message(s)

*Jun 17 07:33:19.143: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access3, changed state to down

*Jun 17 07:33:19.143: ISAKMP:(1021):attributes sent in message:

*Jun 17 07:33:19.143: Address: 0.2.0.0

*Jun 17 07:33:19.147: ISAKMP:(1021):allocating address 10.1.1.100

*Jun 17 07:33:19.147: ISAKMP: Sending private address: 10.1.1.100

*Jun 17 07:33:19.147: ISAKMP: Sending IPsec Interface Config reply value 1

*Jun 17 07:33:19.147: ISAKMP: Sending save password reply value 1

*Jun 17 07:33:19.147: ISAKMP: Sending APPLICATION_VERSION string: Cisco IOS Softwarea), Version 15.0(1)M5,

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

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

*Jun 17 07:33:19.147: ISAKMP (1021): Unknown Attr: MODECFG_HOSTNAME (0x700A)

*Jun 17 07:33:19.147: ISAKMP:(1021): responding to peer config from 192.2.1.2. ID = 659439105

*Jun 17 07:33:19.147: ISAKMP: Marking node 659439105 for late deletion

*Jun 17 07:33:19.147: ISAKMP:(1021): sending packet to 192.2.1.2 my_port 500 peer_port 500 (R) CONF_ADDR

*Jun 17 07:33:19.147: ISAKMP:(1021):Sending an IKE IPv4 Packet.

*Jun 17 07:33:19.147: ISAKMP:(1021):Talking to a Unity Client

*Jun 17 07:33:19.147: ISAKMP:(1021):Input = IKE_MESG_FROM_AAA, IKE_AAA_GROUP_ATTR

*Jun 17 07:33:19.147: ISAKMP:(1021):Old State = IKE_CONFIG_AUTHOR_AAA_AWAIT New State = IKE_P1_COMPLETE

*Jun 17 07:33:19.147: ISAKMP:FSM error - Message from AAA grp/user.

And phase 1.5 completes.

*Jun 17 07:33:19.147: ISAKMP:(1021):IKE_DPD is enabled, initializing timers

*Jun 17 07:33:19.147: ISAKMP:(1021):Input = IKE_MESG_INTERNAL, IKE_PHASE1_COMPLETE

*Jun 17 07:33:19.147: ISAKMP:(1021):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

*Jun 17 07:33:19.155: ISAKMP:(1021):IKE_DPD is enabled, initializing timers

*Jun 17 07:33:19.155: ISAKMP:(1021):Input = IKE_MESG_INTERNAL, IKE_PHASE1_COMPLETE

*Jun 17 07:33:19.155: ISAKMP:(1021):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

Relevant configuration:

crypto isakmp client configuration group cisco

pool PRIMARY

save-password

crypto isakmp profile ISA_PRO

client configuration address respond

virtual-template 1

4.3 Phase 2 - Quick mode.

4.3.1 Quick mode message 1 (QM1)

- phase two encryption algorithms (IPsec transform sets)

- tunnel type and encryption.

- proxy ID - "what I would like to put in the tunnel?"

*Jun 17 07:33:19.179: ISAKMP (1021): received packet from 192.2.1.2 dport 500 sport 500 Global (R) QM_IDLE

*Jun 17 07:33:19.179: ISAKMP: set new node 226234965 to QM_IDLE

*Jun 17 07:33:19.179: ISAKMP:(1021): processing HASH payload. message ID = 226234965

*Jun 17 07:33:19.179: ISAKMP:(1021): processing SA payload. message ID = 226234965

*Jun 17 07:33:19.179: ISAKMP:(1021):Checking IPSec proposal 1

*Jun 17 07:33:19.179: ISAKMP: transform 1, ESP_AES

*Jun 17 07:33:19.179: ISAKMP: attributes in transform:

*Jun 17 07:33:19.179: ISAKMP: encaps is 1 (Tunnel)

*Jun 17 07:33:19.179: ISAKMP: SA life type in seconds

*Jun 17 07:33:19.179: ISAKMP: SA life duration (VPI) of 0x0 0x20 0xC4 0x9B

*Jun 17 07:33:19.179: ISAKMP: SA life type in kilobytes

*Jun 17 07:33:19.179: ISAKMP: SA life duration (VPI) of 0x0 0x46 0x50 0x0

*Jun 17 07:33:19.179: ISAKMP: authenticator is HMAC-SHA

*Jun 17 07:33:19.179: ISAKMP: key length is 128

*Jun 17 07:33:19.179: ISAKMP:(1021):atts are acceptable.

*Jun 17 07:33:19.179: IPSEC(validate_proposal_request): proposal part #1

*Jun 17 07:33:19.179: IPSEC(validate_proposal_request): proposal part #1,

(key eng. msg.) INBOUND local= 192.2.0.1, remote= 192.2.1.2,

local_proxy= 0.0.0.0/0.0.0.0/0/0 (type=4),

remote_proxy= 10.1.1.100/255.255.255.255/0/0 (type=1),

protocol= ESP, transform= NONE (Tunnel),

lifedur= 0s and 0kb,

spi= 0x0(0), conn_id= 0, keysize= 128, flags= 0x0

*Jun 17 07:33:19.179: insert of map into mapdb AVL failed, map + ace pair already exists on the mapdb

*Jun 17 07:33:19.179: Crypto mapdb : proxy_match

src addr : 0.0.0.0

dst addr : 10.1.1.100

protocol : 0

src port : 0

dst port : 0

*Jun 17 07:33:19.179: ISAKMP:(1021): processing NONCE payload. message ID = 226234965

*Jun 17 07:33:19.179: ISAKMP:(1021): processing ID payload. message ID = 226234965

*Jun 17 07:33:19.179: ISAKMP:(1021):QM Responder gets spi

*Jun 17 07:33:19.179: ISAKMP:(1021):Node 226234965, Input = IKE_MESG_FROM_PEER, IKE_QM_EXCH

*Jun 17 07:33:19.179: ISAKMP:(1021):Old State = IKE_QM_READY New State = IKE_QM_SPI_STARVE

Relevant config

crypto ipsec transform-set TRA esp-aes esp-sha-hmac

crypto ipsec profile PRO

set transform-set TRA

interface Virtual-Template1 type tunnel

tunnel protection ipsec profile PRO

4.3.2 Quick mode message 2 (QM2) - sever's reply and creation of SAs.

*Jun 17 07:33:19.179: ISAKMP:(1021):deleting node 659439105 error FALSE reason "No Error"

*Jun 17 07:33:19.179: ISAKMP:(1021): Creating IPSec SAs

*Jun 17 07:33:19.179: inbound SA from 192.2.1.2 to 192.2.0.1 (f/i) 0/ 0

(proxy 10.1.1.100 to 0.0.0.0)

*Jun 17 07:33:19.179: has spi 0x1E448340 and conn_id 0

*Jun 17 07:33:19.179: lifetime of 2147483 seconds

*Jun 17 07:33:19.179: lifetime of 4608000 kilobytes

*Jun 17 07:33:19.179: outbound SA from 192.2.0.1 to 192.2.1.2 (f/i) 0/0

(proxy 0.0.0.0 to 10.1.1.100)

*Jun 17 07:33:19.179: has spi 0x3D7E4D33 and conn_id 0

*Jun 17 07:33:19.179: lifetime of 2147483 seconds

*Jun 17 07:33:19.179: lifetime of 4608000 kilobytes

*Jun 17 07:33:19.179: ISAKMP:(1021): sending packet to 192.2.1.2 my_port 500 peer_port 500 (R) QM_IDLE

*Jun 17 07:33:19.179: ISAKMP:(1021):Sending an IKE IPv4 Packet.

*Jun 17 07:33:19.179: ISAKMP:(1021):Node 226234965, Input = IKE_MESG_INTERNAL, IKE_GOT_SPI

*Jun 17 07:33:19.179: ISAKMP:(1021):Old State = IKE_QM_SPI_STARVE New State = IKE_QM_R_QM2

*Jun 17 07:33:19.179: IPSEC(key_engine): got a queue event with 1 KMI message(s)

*Jun 17 07:33:19.179: Crypto mapdb : proxy_match

src addr : 0.0.0.0

dst addr : 10.1.1.100

protocol : 0

src port : 0

dst port : 0

*Jun 17 07:33:19.179: IPSEC(crypto_ipsec_sa_find_ident_head): reconnecting with the same proxies and peer 192.2.1.2

*Jun 17 07:33:19.179: IPSEC(rte_mgr): VPN Route Event Peer has changed but same proxies for peer 192.2.1.2

*Jun 17 07:33:19.179: IPSEC(rte_mgr): VPN Route Event create SA based on crypto ACL in real time for 192.2.1.2

*Jun 17 07:33:19.179: IPSEC(rte_mgr): VPN Route Refcount 1 Virtual-Access3

*Jun 17 07:33:19.179: IPSEC(rte_mgr): VPN Route Added 10.1.1.100 255.255.255.255 via Virtual-Access3 in IP DEFAULT TABLE with tag 0 distance1

*Jun 17 07:33:19.179: IPSEC(policy_db_add_ident): src 0.0.0.0, dest 10.1.1.100, dest_port 0

*Jun 17 07:33:19.179: IPSEC(create_sa): sa created,

(sa) sa_dest= 192.2.0.1, sa_proto= 50,

sa_spi= 0x1E448340(507806528),

sa_trans= esp-aes esp-sha-hmac , sa_conn_id= 73

sa_lifetime(k/sec)= (4444443/3600)

*Jun 17 07:33:19.179: IPSEC(create_sa): sa created,

(sa) sa_dest= 192.2.1.2, sa_proto= 50,

sa_spi= 0x3D7E4D33(1031687475),

sa_trans= esp-aes esp-sha-hmac , sa_conn_id= 74

sa_lifetime(k/sec)= (4444443/3600)

4.3.3 Quick mode message 3 (QM3) - Finishing.

*Jun 17 07:33:19.195: ISAKMP (1021): received packet from 192.2.1.2 dport 500 sport 500 Global (R) QM_IDLE

*Jun 17 07:33:19.195: ISAKMP:(1021):deleting node 226234965 error FALSE reason "QM done (await)"

*Jun 17 07:33:19.195: ISAKMP:(1021):Node 226234965, Input = IKE_MESG_FROM_PEER, IKE_QM_EXCH

*Jun 17 07:33:19.195: ISAKMP:(1021):Old State = IKE_QM_R_QM2 New State = IKE_QM_PHASE2_COMPLETE

*Jun 17 07:33:19.195: IPSEC(key_engine): got a queue event with 1 KMI message(s)

*Jun 17 07:33:19.195: IPSEC(key_engine_enable_outbound): rec'd enable notify from ISAKMP

*Jun 17 07:33:19.195: IPSEC(key_engine_enable_outbound): enable SA with spi 1031687475/50

DVTI_Server#

*Jun 17 07:33:19.195: IPSEC(update_current_outbound_sa): updated peer 192.2.1.2 current outbound sa to SPI 3D7E4D33

*Jun 17 07:33:19.771: ISAKMP (1021): received packet from 192.2.1.2 dport 500 sport 500 Global (R) QM_IDLE

*Jun 17 07:33:19.771: ISAKMP: set new node -472138210 to QM_IDLE

*Jun 17 07:33:19.771: ISAKMP:(1021): processing HASH payload. message ID = -472138210

*Jun 17 07:33:19.771: ISAKMP:(1021): processing NOTIFY CLIENT_UPDATE protocol 1

spi 0, message ID = -472138210, sa = 64487E8

*Jun 17 07:33:19.771: ISAKMP:(0):Attribute type CLIENT_HOSTNAME, length = 13

*Jun 17 07:33:19.771: ISAKMP:(0):Attribute type CLIENT_PLATFORM_NAME, length = 12

DVTI_Server#

*Jun 17 07:33:19.771: ISAKMP:(0):Attribute type CLIENT_HARDWARE_SERIAL, length = 6

*Jun 17 07:33:19.771: ISAKMP:(0):Attribute type CLIENT_MEMORY_SIZE, length = 8

*Jun 17 07:33:19.771: ISAKMP:(0):Attribute type CLIENT_AVAILABLE_MEMORY, length = 8

*Jun 17 07:33:19.771: ISAKMP:(0):Attribute type CLIENT_IMAGE_VERSION, length = 42

*Jun 17 07:33:19.771: ISAKMP:(1021):deleting node -472138210 error FALSE reason "Informational (in) state 1"

*Jun 17 07:33:19.771: ISAKMP:(1021):Input = IKE_MESG_FROM_PEER, IKE_INFO_NOTIFY

*Jun 17 07:33:19.771: ISAKMP:(1021):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

5. Verification of tunnel.

Let's have a look at established tunnel.

5.1 ISAKMP

Let's understand if phase 1 is up and running.

Command:

sh cry isa sa det

Output:

DVTI_Server#show crypto isa sa det

(...)

C-id Local Remote I-VRF Status Encr Hash Auth DH Lifetime Cap.

1021 192.2.0.1 192.2.1.2 ACTIVE aes sha 2 23:18:02 CDX

5.2 IPSec

Let's check if the device is ready to encrypt traffic (i.e. if both inbound and outbound SPIs are present).

Command:

show crypto ipsec sa peer 192.2.1.2

Output:

(Some output omitted)

interface: Virtual-Access3

Crypto map tag: Virtual-Access3-head-0, local addr 192.2.0.1

protected vrf: (none)

local ident (addr/mask/prot/port): (0.0.0.0/0.0.0.0/0/0)

remote ident (addr/mask/prot/port): (10.1.1.100/255.255.255.255/0/0)

current_peer 192.2.1.2 port 500

PERMIT, flags={origin_is_acl,}

#pkts encaps: 0, #pkts encrypt: 0, #pkts digest: 0

#pkts decaps: 0, #pkts decrypt: 0, #pkts verify: 0

#pkts compressed: 0, #pkts decompressed: 0

#pkts not compressed: 0, #pkts compr. failed: 0

#pkts not decompressed: 0, #pkts decompress failed: 0

#send errors 0, #recv errors 0

local crypto endpt.: 192.2.0.1, remote crypto endpt.: 192.2.1.2

path mtu 1500, ip mtu 1500, ip mtu idb Ethernet0/0

current outbound spi: 0x3D7E4D33(1031687475)

PFS (Y/N): N, DH group: none

inbound esp sas:

spi: 0x1E448340(507806528)

transform: esp-aes esp-sha-hmac ,

in use settings ={Tunnel, }

conn id: 73, flow_id: SW:73, sibling_flags 80000046, crypto map: Virtual-Access3-head-0

sa timing: remaining key lifetime (k/sec): (4444443/969)

IV size: 16 bytes

replay detection support: Y

Status: ACTIVE

outbound esp sas:

spi: 0x3D7E4D33(1031687475)

transform: esp-aes esp-sha-hmac ,

in use settings ={Tunnel, }

conn id: 74, flow_id: SW:74, sibling_flags 80000046, crypto map: Virtual-Access3-head-0

sa timing: remaining key lifetime (k/sec): (4444443/969)

IV size: 16 bytes

replay detection support: Y

Status: ACTIVE

6. Further reading

A good place to start is wikipedia article on IPSec.

Standard and references contains a lot of useful information:

http://en.wikipedia.org/wiki/IPsec

Understanding main mode debugs on ASA:

https://supportforums.cisco.com/docs/DOC-14044

Understanding aggresive mode debug on ASA:

https://supportforums.cisco.com/docs/DOC-13715

artículo Understanding IOS IPSec and IKE debugs - IKEv1 Aggressive Mode. en Security Knowledge Base

Understanding IOS IPSec and IKE debugs - IKEv1 Aggressive Mode.

1. Introduction

2. Core issue

3. Scenario

3.1 Debugs used.

3.2 Hardware client configuration.

3.3 Headend configuration.

4. Debugging

4.1 Phase 1 - Aggressive mode.

4.1.1 Aggressive mode message 1 (AM1); sent from client to server.

Relevant configuration.

4.1.2 Aggressive mode message 2 (AM2); sent from server to client.

4.1.3 Aggressive mode message 3 (AM3); Finish phase 1.

4.2 Phase 1.5 - Xauth and Mode config.

Xauth - eXtended AUTHentication. User authentication.

Relevant configuration.

Mode config - request and provide authentication attributes.

Relevant configuration:

4.3 Phase 2 - Quick mode.

4.3.1 Quick mode message 1 (QM1)

Relevant config

4.3.2 Quick mode message 2 (QM2) - sever's reply and creation of SAs.

4.3.3 Quick mode message 3 (QM3) - Finishing.

5. Verification of tunnel.

5.1 ISAKMP

5.2 IPSec

6. Further reading

7. Comments? feedback?

Re: Understanding IOS IPSec and IKE debugs - IKEv1 Aggressive Mode.