[Swan-dev] IKEv1: Remove all IPsec SA's of a connection when newest SA is removedrefs/heads/master
Lennart Sorensen
lsorense at csclub.uwaterloo.ca
Fri Aug 28 21:04:18 EEST 2015
On Wed, Aug 26, 2015 at 11:26:08AM -0400, Lennart Sorensen wrote:
> On Wed, Aug 26, 2015 at 11:23:39AM -0400, Paul Wouters wrote:
> > On Wed, 26 Aug 2015, Lennart Sorensen wrote:
> >
> > >>>Aug 5 14:50:13 ruggedcom pluto[8239]: "Test" #3: ignoring Delete SA payload:
> > >>>PROTO_IPSEC_ESP SA(0xbd111c17) not found (our SPI - bogus implementation)
> >
> > >>Although why am I not seeing the spi 0xbd111c17 anywhere? Does your bug
> > >>report have more plutologs that we can trace down 0xbd111c17 and see if
> > >>this is indeed an ESP SPI and not an ISAKMPD SPI?
> >
> > >Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #44: STATE_QUICK_R2: IPsec SA established tunnel mode {ESP=>0xe701c648 <0x43b180e5 xfrm=3DES_0-HMAC_MD5 NATOA=none NATD=none DPD=none}
> > >Aug 11 09:08:23 ruggedcom pluto[25039]: "Test" #45: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
> > >Aug 11 09:08:23 ruggedcom pluto[25039]: "Test" #45: STATE_QUICK_R2: IPsec SA established tunnel mode {ESP=>0x20e9b4b8 <0x65bd9c08 xfrm=3DES_0-HMAC_MD5 NATOA=none NATD=none DPD=none}
> >
> > the SPI's don't match and neither do the state numbers. The delete is
> > from state #3 but the SPIs are from #44 and #45 :)
> >
> > These are nog the logs we are looking for :)
>
> Well Jeff is off today, but maybe tomorrow he can run the test again
> and capture logs that match.
>
> Any particular debug options you would like enabled?
>
> At least you seem to have an idea where the problem occurs now.
So here is some logs Jeff gave me (he is still trying to get subscribed
to the list himself).
Here is the /var/log/auth.log (openswan side) during tunnel establishment:
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #43: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192 prf=oakley_md5 group=modp1536}
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #43: the peer proposed: 192.168.30.0/24:0/0 -> 192.168.20.0/24:0/0
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #44: responding to Quick Mode proposal {msgid:58750a85}
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #44: us: 192.168.30.0/24===192.168.10.1<192.168.10.1>[+S=C]
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #44: them: 192.168.10.2<192.168.10.2>[+S=C]===192.168.20.0/24
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #44: keeping refhim=4294901761 during rekey
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #44: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #44: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #43: the peer proposed: 192.168.30.0/24:0/0 -> 192.168.20.0/24:0/0
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #45: responding to Quick Mode proposal {msgid:ae48e9ab}
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #45: us: 192.168.30.0/24===192.168.10.1<192.168.10.1>[+S=C]
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #45: them: 192.168.10.2<192.168.10.2>[+S=C]===192.168.20.0/24
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #45: keeping refhim=4294901761 during rekey
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #45: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #45: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #44: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
Aug 11 09:08:22 ruggedcom pluto[25039]: "Test" #44: STATE_QUICK_R2: IPsec SA established tunnel mode {ESP=>0xe701c648 <0x43b180e5 xfrm=3DES_0-HMAC_MD5 NATOA=none NATD=none DPD=none}
Aug 11 09:08:23 ruggedcom pluto[25039]: "Test" #45: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
Aug 11 09:08:23 ruggedcom pluto[25039]: "Test" #45: STATE_QUICK_R2: IPsec SA established tunnel mode {ESP=>0x20e9b4b8 <0x65bd9c08 xfrm=3DES_0-HMAC_MD5 NATOA=none NATD=none DPD=none}
Here is the /var/log/auth.log (openswan side) after tunnel established (with command "ipsec whack --name Test --debug-all"):
Aug 11 09:08:48 ruggedcom pluto[25039]: "Test" #43: extra debugging enabled for connection: raw+crypt+parsing+emitting+control+lifecycle+klips+dns+oppo+controlmore+pfkey+nattraversal+x509+dpd+oppoinfo
Aug 11 09:08:48 ruggedcom pluto[25039]: | processing connection Test
Aug 11 09:08:48 ruggedcom pluto[25039]: | last Phase 1 IV: 3d cc a4 3c 3c 18 7a 43
Aug 11 09:08:48 ruggedcom pluto[25039]: | current Phase 1 IV: 3d cc a4 3c 3c 18 7a 43
Aug 11 09:08:48 ruggedcom pluto[25039]: | computed Phase 2 IV:
Aug 11 09:08:48 ruggedcom pluto[25039]: | 31 c1 e0 24 58 05 d5 9f ed b1 72 e8 7e 5d e3 58
Aug 11 09:08:48 ruggedcom pluto[25039]: | received encrypted packet from 192.168.10.2:500
Aug 11 09:08:48 ruggedcom pluto[25039]: | decrypting 40 bytes using algorithm OAKLEY_3DES_CBC
Aug 11 09:08:48 ruggedcom pluto[25039]: | decrypted:
Aug 11 09:08:48 ruggedcom pluto[25039]: | 0c 00 00 14 0a 15 f0 d1 41 a6 50 92 c9 1b 35 e7
Aug 11 09:08:48 ruggedcom pluto[25039]: | ec 4e 2e be 00 00 00 10 00 00 00 01 03 04 00 01
Aug 11 09:08:48 ruggedcom pluto[25039]: | 65 bd 9c 08 00 00 00 00
Aug 11 09:08:48 ruggedcom pluto[25039]: | next IV: c6 95 d6 09 9d 42 ef 07
Aug 11 09:08:48 ruggedcom pluto[25039]: | got payload 0x100(ISAKMP_NEXT_HASH) needed: 0x100 opt: 0x0
Aug 11 09:08:48 ruggedcom pluto[25039]: | ***parse ISAKMP Hash Payload:
Aug 11 09:08:48 ruggedcom pluto[25039]: | next payload type: ISAKMP_NEXT_D
Aug 11 09:08:48 ruggedcom pluto[25039]: | length: 20
Aug 11 09:08:48 ruggedcom pluto[25039]: | got payload 0x1000(ISAKMP_NEXT_D) needed: 0x0 opt: 0x0
Aug 11 09:08:48 ruggedcom pluto[25039]: | ***parse ISAKMP Delete Payload:
Aug 11 09:08:48 ruggedcom pluto[25039]: | next payload type: ISAKMP_NEXT_NONE
Aug 11 09:08:48 ruggedcom pluto[25039]: | length: 16
Aug 11 09:08:48 ruggedcom pluto[25039]: | DOI: ISAKMP_DOI_IPSEC
Aug 11 09:08:48 ruggedcom pluto[25039]: | protocol ID: 3
Aug 11 09:08:48 ruggedcom pluto[25039]: | SPI size: 4
Aug 11 09:08:48 ruggedcom pluto[25039]: | number of SPIs: 1
Aug 11 09:08:48 ruggedcom pluto[25039]: | removing 4 bytes of padding
Aug 11 09:08:48 ruggedcom pluto[25039]: "Test" #43: ignoring Delete SA payload: PROTO_IPSEC_ESP SA(0x65bd9c08) not found (our SPI - bogus implementation)
Aug 11 09:08:48 ruggedcom pluto[25039]: | del: 65 bd 9c 08
Aug 11 09:08:48 ruggedcom pluto[25039]: "Test" #43: received and ignored informational message
Aug 11 09:08:48 ruggedcom pluto[25039]: | complete state transition with STF_IGNORE
Aug 11 09:08:53 ruggedcom pluto[25039]: "Test" #43: extra debugging enabled for connection: raw+crypt+parsing+emitting+control+lifecycle+klips+dns+oppo+controlmore+pfkey+nattraversal+x509+dpd+oppoinfo
Aug 11 09:08:53 ruggedcom pluto[25039]: | processing connection Test
Aug 11 09:08:53 ruggedcom pluto[25039]: | last Phase 1 IV: 3d cc a4 3c 3c 18 7a 43
Aug 11 09:08:53 ruggedcom pluto[25039]: | current Phase 1 IV: 3d cc a4 3c 3c 18 7a 43
Aug 11 09:08:53 ruggedcom pluto[25039]: | computed Phase 2 IV:
Aug 11 09:08:53 ruggedcom pluto[25039]: | 5f 6c ee 59 c2 83 6e 3e 09 42 2a 99 8c e3 e1 80
Aug 11 09:08:53 ruggedcom pluto[25039]: | received encrypted packet from 192.168.10.2:500
Aug 11 09:08:53 ruggedcom pluto[25039]: | decrypting 40 bytes using algorithm OAKLEY_3DES_CBC
Aug 11 09:08:53 ruggedcom pluto[25039]: | decrypted:
Aug 11 09:08:53 ruggedcom pluto[25039]: | 0c 00 00 14 12 66 f7 0f 4f 03 1b 3a e3 c2 89 f0
Aug 11 09:08:53 ruggedcom pluto[25039]: | ba 7e a6 ea 00 00 00 10 00 00 00 01 03 04 00 01
Aug 11 09:08:53 ruggedcom pluto[25039]: | 20 e9 b4 b8 00 00 00 00
Aug 11 09:08:53 ruggedcom pluto[25039]: | 20 e9 b4 b8 00 00 00 00
Aug 11 09:08:53 ruggedcom pluto[25039]: | next IV: 1c 41 18 b8 ab 1a f4 f0
Aug 11 09:08:53 ruggedcom pluto[25039]: | got payload 0x100(ISAKMP_NEXT_HASH) needed: 0x100 opt: 0x0
Aug 11 09:08:53 ruggedcom pluto[25039]: | ***parse ISAKMP Hash Payload:
Aug 11 09:08:53 ruggedcom pluto[25039]: | next payload type: ISAKMP_NEXT_D
Aug 11 09:08:53 ruggedcom pluto[25039]: | length: 20
Aug 11 09:08:53 ruggedcom pluto[25039]: | got payload 0x1000(ISAKMP_NEXT_D) needed: 0x0 opt: 0x0
Aug 11 09:08:53 ruggedcom pluto[25039]: | ***parse ISAKMP Delete Payload:
Aug 11 09:08:53 ruggedcom pluto[25039]: | next payload type: ISAKMP_NEXT_NONE
Aug 11 09:08:53 ruggedcom pluto[25039]: | length: 16
Aug 11 09:08:53 ruggedcom pluto[25039]: | DOI: ISAKMP_DOI_IPSEC
Aug 11 09:08:53 ruggedcom pluto[25039]: | protocol ID: 3
Aug 11 09:08:53 ruggedcom pluto[25039]: | SPI size: 4
Aug 11 09:08:53 ruggedcom pluto[25039]: | number of SPIs: 1
Aug 11 09:08:53 ruggedcom pluto[25039]: | removing 4 bytes of padding
Aug 11 09:08:53 ruggedcom pluto[25039]: "Test" #43: extra debugging enabled for connection: none
Aug 11 09:08:53 ruggedcom pluto[25039]: | processing connection Test
Aug 11 09:08:53 ruggedcom pluto[25039]: "Test" #43: received Delete SA(0x20e9b4b8) payload: deleting IPSEC State #45
Aug 11 09:08:53 ruggedcom pluto[25039]: | deleting state #45
Aug 11 09:08:53 ruggedcom pluto[25039]: | **emit ISAKMP Message:
Aug 11 09:08:53 ruggedcom pluto[25039]: | initiator cookie:
Aug 11 09:08:53 ruggedcom pluto[25039]: | cc 1a e1 80 60 9a 7b da
Aug 11 09:08:53 ruggedcom pluto[25039]: | responder cookie:
Aug 11 09:08:53 ruggedcom pluto[25039]: | a9 7a 17 04 04 05 4f 8e
Aug 11 09:08:53 ruggedcom pluto[25039]: | next payload type: ISAKMP_NEXT_HASH
Aug 11 09:08:53 ruggedcom pluto[25039]: | ISAKMP version: ISAKMP Version 1.0 (rfc2407)
Aug 11 09:08:53 ruggedcom pluto[25039]: | exchange type: ISAKMP_XCHG_INFO
Aug 11 09:08:53 ruggedcom pluto[25039]: | flags: ISAKMP_FLAG_ENCRYPTION
Aug 11 09:08:53 ruggedcom pluto[25039]: | message ID: 6a ba 48 ed
Aug 11 09:08:53 ruggedcom pluto[25039]: | ***emit ISAKMP Hash Payload:
Aug 11 09:08:53 ruggedcom pluto[25039]: | next payload type: ISAKMP_NEXT_D
Aug 11 09:08:53 ruggedcom pluto[25039]: | emitting 16 zero bytes of HASH(1) into ISAKMP Hash Payload
Aug 11 09:08:53 ruggedcom pluto[25039]: | emitting length of ISAKMP Hash Payload: 20
Aug 11 09:08:53 ruggedcom pluto[25039]: | ***emit ISAKMP Delete Payload:
Aug 11 09:08:53 ruggedcom pluto[25039]: | next payload type: ISAKMP_NEXT_NONE
Aug 11 09:08:53 ruggedcom pluto[25039]: | DOI: ISAKMP_DOI_IPSEC
Aug 11 09:08:53 ruggedcom pluto[25039]: | protocol ID: 3
Aug 11 09:08:53 ruggedcom pluto[25039]: | SPI size: 4
Aug 11 09:08:53 ruggedcom pluto[25039]: | number of SPIs: 1
Aug 11 09:08:53 ruggedcom pluto[25039]: | emitting 4 raw bytes of delete payload into ISAKMP Delete Payload
Aug 11 09:08:53 ruggedcom pluto[25039]: | delete payload 65 bd 9c 08
Aug 11 09:08:53 ruggedcom pluto[25039]: | emitting length of ISAKMP Delete Payload: 16
Aug 11 09:08:53 ruggedcom pluto[25039]: | HASH(1) computed:
Aug 11 09:08:53 ruggedcom pluto[25039]: | e2 ea b5 b7 ab 52 40 4d 0c fc 22 5c e7 15 8f 72
Aug 11 09:08:53 ruggedcom pluto[25039]: | last Phase 1 IV: 3d cc a4 3c 3c 18 7a 43
Aug 11 09:08:53 ruggedcom pluto[25039]: | current Phase 1 IV: 3d cc a4 3c 3c 18 7a 43
Aug 11 09:08:53 ruggedcom pluto[25039]: | computed Phase 2 IV:
Aug 11 09:08:53 ruggedcom pluto[25039]: | f4 a3 6f 49 68 2b c7 77 01 b5 87 a3 af be 80 d7
Aug 11 09:08:53 ruggedcom pluto[25039]: | encrypting:
Aug 11 09:08:53 ruggedcom pluto[25039]: | 0c 00 00 14 e2 ea b5 b7 ab 52 40 4d 0c fc 22 5c
Aug 11 09:08:53 ruggedcom pluto[25039]: | e7 15 8f 72 00 00 00 10 00 00 00 01 03 04 00 01
Aug 11 09:08:53 ruggedcom pluto[25039]: | 65 bd 9c 08
Aug 11 09:08:53 ruggedcom pluto[25039]: | IV:
Aug 11 09:08:53 ruggedcom pluto[25039]: | f4 a3 6f 49 68 2b c7 77 01 b5 87 a3 af be 80 d7
Aug 11 09:08:53 ruggedcom pluto[25039]: | unpadded size is: 36
Aug 11 09:08:53 ruggedcom pluto[25039]: | emitting 4 zero bytes of encryption padding into ISAKMP Message
Aug 11 09:08:53 ruggedcom pluto[25039]: | encrypting 40 using OAKLEY_3DES_CBC
Aug 11 09:08:53 ruggedcom pluto[25039]: | next IV: 66 15 8a 39 d3 bc 7f 25
Aug 11 09:08:53 ruggedcom pluto[25039]: | emitting length of ISAKMP Message: 68
Aug 11 09:08:53 ruggedcom pluto[25039]: | sending 68 bytes for delete notify through switch.0010:500 to 192.168.10.2:500 (using #43)
Aug 11 09:08:53 ruggedcom pluto[25039]: | cc 1a e1 80 60 9a 7b da a9 7a 17 04 04 05 4f 8e
Aug 11 09:08:53 ruggedcom pluto[25039]: | 08 10 05 01 6a ba 48 ed 00 00 00 44 c5 74 6a a6
Aug 11 09:08:53 ruggedcom pluto[25039]: | a8 2d c5 27 6a e1 35 2e 0a a5 b6 c2 8e 76 99 d4
Aug 11 09:08:53 ruggedcom pluto[25039]: | 10 c8 90 a9 50 e9 3d 10 d9 20 70 b0 66 15 8a 39
Aug 11 09:08:53 ruggedcom pluto[25039]: | d3 bc 7f 25
Aug 11 09:08:53 ruggedcom pluto[25039]: | deleting event for #45
Aug 11 09:08:53 ruggedcom pluto[25039]: | no suspended cryptographic state for 45
Aug 11 09:08:53 ruggedcom pluto[25039]: | ICOOKIE: cc 1a e1 80 60 9a 7b da
Aug 11 09:08:53 ruggedcom pluto[25039]: | RCOOKIE: a9 7a 17 04 04 05 4f 8e
Aug 11 09:08:53 ruggedcom pluto[25039]: | state hash entry 12
Aug 11 09:08:53 ruggedcom pluto[25039]: | command executing down-client
Aug 11 09:08:53 ruggedcom pluto[25039]: | executing down-client: 2>&1 PLUTO_VERB='down-client' PLUTO_VERSION='2.0' PLUTO_CONNECTION='Test' PLUTO_INTERFACE='switch.0010' PLUTO_NEXT_HOP='192.168.10.2' PLUTO_ME='192.168.10.1' PLUTO_MY_ID='192.168.10.1' PLUTO_MY_CLIENT='192.168.30.0/24' PLUTO_MY_CLIENT_NET='192.168.30.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL='0' PLUTO_PEER='192.168.10.2' PLUTO_PEER_ID='192.168.10.2' PLUTO_PEER_CLIENT='192.168.20.0/24' PLUTO_PEER_CLIENT_NET='192.168.20.0' PLUTO_PEER_CLIENT_MASK='255.255.255.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_STACK='netkey' PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+PFS+IKEv2ALLOW+SAREFTRACK' PLUTO_CONN_ADDRFAMILY='ipv4' PLUTO_XAUTH_USERNAME='' PLUTO_CISCO_DNS_INFO='' PLUTO_CISCO_DOMAIN_INFO='' PLUTO_PEER_BANNER='' PLUTO_NM_CONFIGURED='0' ipsec _updown --route yes
Aug 11 09:08:53 ruggedcom pluto[25039]: | popen(): cmd is 822 chars long
Aug 11 09:08:53 ruggedcom pluto[25039]: | cmd( 0):2>&1 PLUTO_VERB='down-client' PLUTO_VERSION='2.0' PLUTO_CONNECTION='Test' PLUTO_:
Aug 11 09:08:53 ruggedcom pluto[25039]: | cmd( 80):INTERFACE='switch.0010' PLUTO_NEXT_HOP='192.168.10.2' PLUTO_ME='192.168.10.1' PL:
Aug 11 09:08:53 ruggedcom pluto[25039]: | cmd( 160):UTO_MY_ID='192.168.10.1' PLUTO_MY_CLIENT='192.168.30.0/24' PLUTO_MY_CLIENT_NET=':
Aug 11 09:08:53 ruggedcom pluto[25039]: | cmd( 240):192.168.30.0' PLUTO_MY_CLIENT_MASK='255.255.255.0' PLUTO_MY_PORT='0' PLUTO_MY_PR:
Aug 11 09:08:53 ruggedcom pluto[25039]: | cmd( 320):OTOCOL='0' PLUTO_PEER='192.168.10.2' PLUTO_PEER_ID='192.168.10.2' PLUTO_PEER_CLI:
Aug 11 09:08:53 ruggedcom pluto[25039]: | cmd( 400):ENT='192.168.20.0/24' PLUTO_PEER_CLIENT_NET='192.168.20.0' PLUTO_PEER_CLIENT_MAS:
Aug 11 09:08:53 ruggedcom pluto[25039]: | cmd( 480):K='255.255.255.0' PLUTO_PEER_PORT='0' PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' P:
Aug 11 09:08:53 ruggedcom pluto[25039]: | cmd( 560):LUTO_STACK='netkey' PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+PFS+IKEv2ALLOW+SAREF:
Aug 11 09:08:53 ruggedcom pluto[25039]: | cmd( 640):TRACK' PLUTO_CONN_ADDRFAMILY='ipv4' PLUTO_XAUTH_USERNAME='' PLUTO_CISCO_DNS_INF:
Aug 11 09:08:53 ruggedcom pluto[25039]: | cmd( 720):O='' PLUTO_CISCO_DOMAIN_INFO='' PLUTO_PEER_BANNER='' PLUTO_NM_CONFIGURED='0' ips:
Aug 11 09:08:53 ruggedcom pluto[25039]: | cmd( 800):ec _updown --route yes:
Aug 11 09:08:53 ruggedcom pluto[25039]: | request to replace with shunt a prospective erouted policy with netkey kernel --- experimental
Aug 11 09:08:53 ruggedcom pluto[25039]: | satype(0) is not used in netlink_raw_eroute.
Aug 11 09:08:53 ruggedcom pluto[25039]: | delete esp.20e9b4b8 at 192.168.10.2
Aug 11 09:08:53 ruggedcom pluto[25039]: | delete inbound eroute 192.168.20.0/24:0 --0-> 192.168.30.0/24:0 => unk255.100 at 192.168.10.1 (raw_eroute)
Aug 11 09:08:53 ruggedcom pluto[25039]: | satype(0) is not used in netlink_raw_eroute.
Aug 11 09:08:53 ruggedcom pluto[25039]: | raw_eroute result=1
Aug 11 09:08:53 ruggedcom pluto[25039]: | delete esp.65bd9c08 at 192.168.10.1
Aug 11 09:08:53 ruggedcom pluto[25039]: "Test" #43: received and ignored informational message
========Below is the ipsec.conf on Openswan:==============
conn Test
connaddrfamily=ipv4
authby=secret
auto=add
phase2=esp
phase2alg=3des-md5
ike=3des-md5
left=192.168.10.1
leftsubnet=192.168.30.0/24
leftupdown="ipsec _updown --route yes"
pfs=yes
right=192.168.10.2
rightsubnet=192.168.20.0/24
rightupdown="ipsec _updown --route yes"
type=tunnel
============Below is the config from the Cisco device:===============
crypto isakmp policy 1
encr 3des
hash md5
authentication pre-share
group 5
lifetime 28800
crypto isakmp key 6 ruggedcom address 192.168.10.1 255.255.255.0 no-xauth
crypto isakmp keepalive 30
!
crypto ipsec transform-set myset esp-3des esp-md5-hmac
!
crypto map mymap 10 ipsec-isakmp
set peer 192.168.10.1
set transform-set myset
set pfs group5
match address 100
!
interface FastEthernet0/0
ip address 192.168.10.2 255.255.255.0
duplex auto
speed auto
crypto map mymap
!
interface FastEthernet0/1
ip address 192.168.20.1 255.255.255.0
duplex auto
speed auto
!
ip forward-protocol nd
ip route 192.168.30.0 255.255.255.0 192.168.10.1
no ip http server
no ip http secure-server
!
access-list 100 permit ip 192.168.20.0 0.0.0.255 192.168.30.0 0.0.0.255
===============Below is the second test case===============
Aug 13 10:33:09 R4 pluto[12035]: packet from 192.168.10.2:500: received Vendor ID payload [RFC 3947]
Aug 13 10:33:09 R4 pluto[12035]: packet from 192.168.10.2:500: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-07]
Aug 13 10:33:09 R4 pluto[12035]: packet from 192.168.10.2:500: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03]
Aug 13 10:33:09 R4 pluto[12035]: packet from 192.168.10.2:500: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n]
Aug 13 10:33:09 R4 pluto[12035]: "Test" #19: enabling possible NAT-traversal with method RFC 3947 (NAT-Traversal)
Aug 13 10:33:09 R4 pluto[12035]: "Test" #19: responding to Main Mode
Aug 13 10:33:09 R4 pluto[12035]: "Test" #19: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Aug 13 10:33:09 R4 pluto[12035]: "Test" #19: STATE_MAIN_R1: sent MR1, expecting MI2
Aug 13 10:33:09 R4 pluto[12035]: "Test" #19: received Vendor ID payload [Dead Peer Detection]
Aug 13 10:33:09 R4 pluto[12035]: "Test" #19: ignoring unknown Vendor ID payload [04977a9f8429b8614a8707a2e2ba73a1]
Aug 13 10:33:09 R4 pluto[12035]: "Test" #19: received Vendor ID payload [XAUTH]
Aug 13 10:33:09 R4 pluto[12035]: "Test" #19: NAT-Traversal: Result using RFC 3947 (NAT-Traversal) sender port 500: no NAT detected
Aug 13 10:33:10 R4 pluto[12035]: "Test" #19: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Aug 13 10:33:10 R4 pluto[12035]: "Test" #19: STATE_MAIN_R2: sent MR2, expecting MI3
Aug 13 10:33:10 R4 pluto[12035]: "Test" #19: ignoring informational payload IPSEC_INITIAL_CONTACT, msgid=00000000, length=28
Aug 13 10:33:10 R4 pluto[12035]: | ISAKMP Notification Payload
Aug 13 10:33:10 R4 pluto[12035]: | 00 00 00 1c 00 00 00 01 01 10 60 02
Aug 13 10:33:10 R4 pluto[12035]: "Test" #19: Main mode peer ID is ID_IPV4_ADDR: '192.168.10.2'
Aug 13 10:33:10 R4 pluto[12035]: "Test" #19: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Aug 13 10:33:10 R4 pluto[12035]: "Test" #19: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=PRESHARED_KEY cipher=aes_128 integ=sha group=MODP1536}
Aug 13 10:33:10 R4 pluto[12035]: "Test" #19: the peer proposed: 192.168.30.0/24:0/0 -> 192.168.20.0/24:0/0
Aug 13 10:33:10 R4 pluto[12035]: "Test" #19: the peer proposed: 192.168.30.0/24:0/0 -> 192.168.20.0/24:0/0
Aug 13 10:33:10 R4 pluto[12035]: "Test" #20: responding to Quick Mode proposal {msgid:f1068019}
Aug 13 10:33:10 R4 pluto[12035]: "Test" #20: us: 192.168.30.0/24===192.168.10.1<192.168.10.1>
Aug 13 10:33:10 R4 pluto[12035]: "Test" #20: them: 192.168.10.2<192.168.10.2>===192.168.20.0/24
Aug 13 10:33:10 R4 pluto[12035]: "Test" #20: keeping refhim=4294901761 during rekey
Aug 13 10:33:10 R4 pluto[12035]: "Test" #20: soft_use_expires_seconds: 28800 soft_byte_limit: 0MB
Aug 13 10:33:10 R4 pluto[12035]: "Test" #20: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
Aug 13 10:33:10 R4 pluto[12035]: "Test" #20: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2 tunnel mode {ESP=>0x94e7e714 <0xe4ac1f8d xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=passive}
Aug 13 10:33:10 R4 pluto[12035]: "Test" #21: responding to Quick Mode proposal {msgid:c6a47297}
Aug 13 10:33:10 R4 pluto[12035]: "Test" #21: us: 192.168.30.0/24===192.168.10.1<192.168.10.1>
Aug 13 10:33:10 R4 pluto[12035]: "Test" #21: them: 192.168.10.2<192.168.10.2>===192.168.20.0/24
Aug 13 10:33:10 R4 pluto[12035]: "Test" #21: keeping refhim=4294901761 during rekey
Aug 13 10:33:10 R4 pluto[12035]: "Test" #21: soft_use_expires_seconds: 28800 soft_byte_limit: 0MB
Aug 13 10:33:10 R4 pluto[12035]: "Test" #21: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
Aug 13 10:33:10 R4 pluto[12035]: "Test" #21: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2 tunnel mode {ESP=>0x0676e281 <0x6ddd1804 xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=passive}
Aug 13 10:33:10 R4 pluto[12035]: "Test" #20: soft_use_expires_seconds: 28800 soft_byte_limit: 0MB
Aug 13 10:33:10 R4 pluto[12035]: "Test" #20: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
Aug 13 10:33:10 R4 pluto[12035]: "Test" #20: STATE_QUICK_R2: IPsec SA established tunnel mode {ESP=>0x94e7e714 <0xe4ac1f8d xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=passive}
Aug 13 10:33:10 R4 pluto[12035]: "Test" #21: soft_use_expires_seconds: 28800 soft_byte_limit: 0MB
Aug 13 10:33:10 R4 pluto[12035]: "Test" #21: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
Aug 13 10:33:10 R4 pluto[12035]: "Test" #21: STATE_QUICK_R2: IPsec SA established tunnel mode {ESP=>0x0676e281 <0x6ddd1804 xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=passive}
As you see, two IPSec SA are created when it receives message from Cisco router.
Below, you will see one of the IPSec SA is removed as it receives the message from Cisco router.
I found that sometimes, the newest SA is removed, when it happens, the tunnel goes to prospective erouted status. In this case, the tunnel is down.
Sometimes, the first SA (not the newest SA) is removed, the tunnel is still in erouted status. In this case, the tunnel is fine.
Aug 13 10:33:35 R4 pluto[12035]: "Test" #19: ignoring Delete SA payload: PROTO_IPSEC_ESP SA(0x6ddd1804) not found (our SPI - bogus implementation)
Aug 13 10:33:35 R4 pluto[12035]: "Test" #19: received and ignored empty informational notification payload
Aug 13 10:33:40 R4 pluto[12035]: "Test" #19: received Delete SA(0x0676e281) payload: deleting IPSEC State #21
Aug 13 10:33:40 R4 pluto[12035]: "Test" #19: deleting state #21 (STATE_QUICK_R2)
Aug 13 10:33:40 R4 pluto[12035]: "Test" #19: ESP traffic information: in=1000B out=1000B
Aug 13 10:33:40 R4 pluto[12035]: "Test" #19: received and ignored empty informational notification payload
==================below is the ipsec status when the problem happen =============================
000 stats db_ops: {curr_cnt, total_cnt, maxsz} :context={0,0,0} trans={0,0,0} attrs={0,0,0}
000
000 Connection list:
000
000 "Test": 192.168.30.0/24===192.168.10.1<192.168.10.1>...192.168.10.2<192.168.10.2>===192.168.20.0/24; prospective erouted; eroute owner: #0
000 "Test": oriented; my_ip=unset; their_ip=unset; myup=ipsec _updown --route yes; theirup=ipsec _updown --route yes
000 "Test": xauth info: us:none, them:none, my_xauthuser=[any]; their_xauthuser=[any]
000 "Test": modecfg info: us:none, them:none, modecfg policy:push, dns1:unset, dns2:unset, domain:unset, banner:unset;
000 "Test": labeled_ipsec:no;
000 "Test": policy_label:unset;
000 "Test": ike_life: 3600s; ipsec_life: 28800s; ipsec_traffic: 0MB; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 0;
000 "Test": retransmit-interval: 500ms; retransmit-timeout: 60s;
000 "Test": sha2_truncbug:no; initial_contact:no; cisco_unity:no; send_vendorid:no;
000 "Test": policy: PSK+ENCRYPT+TUNNEL+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW;
000 "Test": conn_prio: 24,24; interface: switch.0013; metric: 0; mtu: unset; sa_prio:auto; nflog-group: unset;
000 "Test": newest ISAKMP SA: #19; newest IPsec SA: #0;
000 "Test": IKE algorithms wanted: AES_CBC(7)_000-SHA1(2)_000-MODP2048(14), AES_CBC(7)_000-SHA1(2)_000-MODP1536(5), AES_CBC(7)_000-SHA1(2)_000-MODP1024(2)
000 "Test": IKE algorithms found: AES_CBC(7)_128-SHA1(2)_160-MODP2048(14), AES_CBC(7)_128-SHA1(2)_160-MODP1536(5), AES_CBC(7)_128-SHA1(2)_160-MODP1024(2)
000 "Test": IKE algorithm newest: AES_CBC_128-SHA1-MODP1536
000 "Test": ESP algorithms wanted: AES(12)_000-SHA1(2)_000
000 "Test": ESP algorithms loaded: AES(12)_000-SHA1(2)_000
000
000 Total IPsec connections: loaded 1, active 0
000
000 State Information: DDoS cookies not required, Accepting new IKE connections
000 IKE SAs: total(10), half-open(0), open(0), authenticated(10), anonymous(0)
000 IPsec SAs: total(10), authenticated(10), anonymous(0)
000
000 #20: "Test":500 STATE_QUICK_R2 (IPsec SA established); EVENT_SA_REPLACE in 3295s; isakmp#19; idle; import:not set
000 #20: "Test" esp.94e7e714 at 192.168.10.2 esp.e4ac1f8d at 192.168.10.1 tun.0 at 192.168.10.2 tun.0 at 192.168.10.1 ref=0 refhim=4294901761 Traffic: ESPin=0B ESPout=0B! ESPmax=4500B
000 #19: "Test":500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 3295s; newest ISAKMP; lastdpd=-1s(seq in:0 out:0); idle; import:not set
000 #12: "Test":500 STATE_QUICK_R2 (IPsec SA established); EVENT_SA_REPLACE in 2869s; isakmp#11; idle; import:not set
000 #12: "Test" esp.cfa134d5 at 192.168.10.2 esp.dd32e2b3 at 192.168.10.1 tun.0 at 192.168.10.2 tun.0 at 192.168.10.1 ref=0 refhim=4294901761 Traffic: ESPin=900B ESPout=900B! ESPmax=4500B
000 #11: "Test":500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 2869s; lastdpd=-1s(seq in:0 out:0); idle; import:not set
000 #8: "Test":500 STATE_QUICK_R2 (IPsec SA established); EVENT_SA_REPLACE in 2727s; isakmp#7; idle; import:not set
000 #8: "Test" esp.ec8dc53f at 192.168.10.2 esp.defcc240 at 192.168.10.1 tun.0 at 192.168.10.2 tun.0 at 192.168.10.1 ref=0 refhim=4294901761 Traffic: ESPin=700B ESPout=700B! ESPmax=4500B
000 #7: "Test":500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 2727s; lastdpd=-1s(seq in:0 out:0); idle; import:not set
000 #16: "Test":500 STATE_QUICK_R2 (IPsec SA established); EVENT_SA_REPLACE in 3015s; isakmp#15; idle; import:not set
000 #16: "Test" esp.7183052e at 192.168.10.2 esp.73f6d743 at 192.168.10.1 tun.0 at 192.168.10.2 tun.0 at 192.168.10.1 ref=0 refhim=4294901761 Traffic: ESPin=1KB ESPout=1KB! ESPmax=4500B
000 #15: "Test":500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 3015s; lastdpd=238s(seq in:0 out:0); idle; import:not set
000 #14: "Test":500 STATE_QUICK_R2 (IPsec SA established); EVENT_SA_REPLACE in 2935s; isakmp#13; idle; import:not set
000 #14: "Test" esp.d7ef8df3 at 192.168.10.2 esp.d1351091 at 192.168.10.1 tun.0 at 192.168.10.2 tun.0 at 192.168.10.1 ref=0 refhim=4294901761 Traffic: ESPin=800B ESPout=800B! ESPmax=4500B
000 #13: "Test":500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 2935s; lastdpd=-1s(seq in:0 out:0); idle; import:not set
000 #6: "Test":500 STATE_QUICK_R2 (IPsec SA established); EVENT_SA_REPLACE in 2621s; isakmp#5; idle; import:not set
000 #6: "Test" esp.6274a60b at 192.168.10.2 esp.4312d8a8 at 192.168.10.1 tun.0 at 192.168.10.2 tun.0 at 192.168.10.1 ref=0 refhim=4294901761 Traffic: ESPin=900B ESPout=900B! ESPmax=4500B
000 #5: "Test":500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 2621s; lastdpd=-1s(seq in:0 out:0); idle; import:not set
000 #10: "Test":500 STATE_QUICK_R2 (IPsec SA established); EVENT_SA_REPLACE in 2815s; isakmp#9; idle; import:not set
000 #10: "Test" esp.95caf986 at 192.168.10.2 esp.9e692948 at 192.168.10.1 tun.0 at 192.168.10.2 tun.0 at 192.168.10.1 ref=0 refhim=4294901761 Traffic: ESPin=800B ESPout=800B! ESPmax=4500B
000 #9: "Test":500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 2815s; lastdpd=-1s(seq in:0 out:0); idle; import:not set
000 #4: "Test":500 STATE_QUICK_R2 (IPsec SA established); EVENT_SA_REPLACE in 2542s; isakmp#3; idle; import:not set
000 #4: "Test" esp.2a1c3d5d at 192.168.10.2 esp.6f511be8 at 192.168.10.1 tun.0 at 192.168.10.2 tun.0 at 192.168.10.1 ref=0 refhim=4294901761 Traffic: ESPin=600B ESPout=600B! ESPmax=4500B
000 #3: "Test":500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 2542s; lastdpd=-1s(seq in:0 out:0); idle; import:not set
000 #18: "Test":500 STATE_QUICK_R2 (IPsec SA established); EVENT_SA_REPLACE in 3180s; isakmp#17; idle; import:not set
000 #18: "Test" esp.9f26593f at 192.168.10.2 esp.74d51327 at 192.168.10.1 tun.0 at 192.168.10.2 tun.0 at 192.168.10.1 ref=0 refhim=4294901761 Traffic: ESPin=800B ESPout=800B! ESPmax=4500B
000 #17: "Test":500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 3180s; lastdpd=-1s(seq in:0 out:0); idle; import:not set
000 #2: "Test":500 STATE_QUICK_R2 (IPsec SA established); EVENT_SA_REPLACE in 2471s; isakmp#1; idle; import:not set
000 #2: "Test" esp.ae3943bc at 192.168.10.2 esp.2310be88 at 192.168.10.1 tun.0 at 192.168.10.2 tun.0 at 192.168.10.1 ref=0 refhim=4294901761 Traffic: ESPin=1KB ESPout=1KB! ESPmax=4500B
000 #1: "Test":500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 2470s; lastdpd=-1s(seq in:0 out:0); idle; import:not set
000
000 Bare Shunt list:
000
Hopefully these logs are in fact the right ones.
--
Len Sorensen
More information about the Swan-dev
mailing list