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 [email protected]
Aug 11 09:08:53 ruggedcom pluto[25039]: | delete inbound eroute
192.168.20.0/24:0 --0-> 192.168.30.0/24:0 => [email protected]
(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 [email protected]
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" [email protected] [email protected]
[email protected] [email protected] 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" [email protected] [email protected]
[email protected] [email protected] 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" [email protected] [email protected]
[email protected] [email protected] 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" [email protected] [email protected]
[email protected] [email protected] 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" [email protected] [email protected]
[email protected] [email protected] 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" [email protected] [email protected]
[email protected] [email protected] 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" [email protected] [email protected]
[email protected] [email protected] 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" [email protected] [email protected]
[email protected] [email protected] 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" [email protected] [email protected]
[email protected] [email protected] 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" [email protected] [email protected]
[email protected] [email protected] 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
_______________________________________________
Swan-dev mailing list
[email protected]
https://lists.libreswan.org/mailman/listinfo/swan-dev
