Re: off by one error in 3des cbc keying

Re: off by one error in 3des cbc keying

[bert hubert]

[alexey's nameserver is off, cc to netdev@oss.sgi.com, perhaps he sees it
there]

On Mon, Nov 11, 2002 at 04:51:36AM +0300, kuznet@ms2.inr.ac.ru wrote:

> Yes, connect() is broken... The patch is enclosed. Alternatively, you
> could allow connections to remote isakmp ports via policy.

Ok, with careful tuning, it will work now. But not for the general case.

If a policy is setup that only applies to ICMP, IKE converges and works (as
it works over UDP).

I wonder, is 'incoming bypass' implemented yet? If there is an incoming
policy, racoon does not see any traffic.

Key refreshing/updating doesn't appear to work either, after they key has
expired, all bets are off.

Regards,

bert

-- 
http://www.PowerDNS.com          Versatile DNS Software & Services
http://lartc.org           Linux Advanced Routing & Traffic Control HOWTO

Re: off by one error in 3des cbc keying

[bert hubert]

On Mon, Nov 11, 2002 at 11:01:09AM +0100, bert hubert wrote:

> Ok, with careful tuning, it will work now. But not for the general case.

http://lartc.org/howto/lartc.ipsec.automatic.keying.html <- how to get this
to work

-- 
http://www.PowerDNS.com          Versatile DNS Software & Services
http://lartc.org           Linux Advanced Routing & Traffic Control HOWTO

Re: off by one error in 3des cbc keying

[kuznet]

Hello!

> [alexey's nameserver is off, cc to netdev@oss.sgi.com, perhaps he sees it
> there]

Unlikely. I think while our network is down list exploders just
drop mails unlike normal mail agents. :-)


> I wonder, is 'incoming bypass' implemented yet?

It is. But your example shows that something is wrong there. Fix will follow
later.


> Key refreshing/updating doesn't appear to work either, after they key has
> expired, all bets are off.

What does happen in logs/setkey -D? Actually, before sending previous
large patch dealing with expire timers I got it to the point where keys
are refreshed nicely at _one_ side, another required reboot and the test
was not accomplished.

Alexey

Re: off by one error in 3des cbc keying

[bert hubert]

On Mon, Nov 11, 2002 at 08:18:55PM +0300, kuznet@ms2.inr.ac.ru wrote:

> Unlikely. I think while our network is down list exploders just
> drop mails unlike normal mail agents. :-)

Yeah - I had this vague idea maybe you read this list from another address
:-)

> > I wonder, is 'incoming bypass' implemented yet?
> 
> It is. But your example shows that something is wrong there. Fix will follow
> later.

Ok, let me know if I can test. The IPSEC pages on lartc now have had over
3000 real visits, by the way. This is a lot.

> What does happen in logs/setkey -D? Actually, before sending previous
> large patch dealing with expire timers I got it to the point where keys

Communications work, then *something* expires after 30 seconds, and then
there is 10 minute where everything works. Then things break down, and after
a while, renegotiation succeeds. Racoon configuration identical to the
previous one.

Logs of setup:
20:40:12: INFO: main.c:170:main(): @(#)racoon 20001216 20001216
sakane@kame.net
20:40:12: INFO: main.c:171:main(): @(#)This product linked
OpenSSL 0.9.6c 21 dec 2001 (http://www.openssl.org/)
20:40:12: INFO: isakmp.c:1365:isakmp_open(): 127.0.0.1[500] used
as isakmp port (fd=7)
20:40:12: INFO: isakmp.c:1365:isakmp_open(): 10.0.0.216[500] used
as isakmp port (fd=8)
20:40:12: ERROR: isakmp.c:1357:isakmp_open(): failed to bind
(Address already in use).
20:40:12: ERROR: isakmp.c:1357:isakmp_open(): failed to bind
(Address already in use).

Tried to connect to 10.0.0.11:

20:41:06: INFO: isakmp.c:1689:isakmp_post_acquire(): IPsec-SA
request for 10.0.0.11 queued due to no phase1 found.
20:41:06: INFO: isakmp.c:794:isakmp_ph1begin_i(): initiate new
phase 1 negotiation: 10.0.0.216[500]<=>10.0.0.11[500]
20:41:06: INFO: isakmp.c:799:isakmp_ph1begin_i(): begin
Aggressive mode.
20:41:07: INFO: vendorid.c:128:check_vendorid(): received Vendor
ID: KAME/racoon
20:41:07: NOTIFY: oakley.c:2037:oakley_skeyid(): couldn't find
the proper pskey, try to get one by the peer's address.
20:41:07: INFO: isakmp.c:2417:log_ph1established(): ISAKMP-SA
established 10.0.0.216[500]-10.0.0.11[500]
spi:7f7352a7dbd917ba:087da64152cda86a
20:41:07: INFO: isakmp.c:938:isakmp_ph2begin_i(): initiate new
phase 2 negotiation: 10.0.0.216[0]<=>10.0.0.11[0]
20:41:07: INFO: pfkey.c:1106:pk_recvupdate(): IPsec-SA
established: ESP/Transport 10.0.0.11->10.0.0.216 spi=137313584(0x82f3d30)
20:41:07: INFO: pfkey.c:1318:pk_recvadd(): IPsec-SA established:
ESP/Transport 10.0.0.216->10.0.0.11 spi=98734594(0x5e29202)

After thirty seconds:
20:41:36: INFO: pfkey.c:1364:pk_recvexpire(): IPsec-SA expired:
ESP/Transport 10.0.0.216->10.0.0.11 

After a few minutes, lifetime is 10 minutes:
20:49:07: INFO: pfkey.c:1364:pk_recvexpire(): IPsec-SA expired:
ESP/Transport 10.0.0.11->10.0.0.216 spi=137313584(0x82f3d30)
20:49:07: INFO: isakmp.c:938:isakmp_ph2begin_i(): initiate new
phase 2 negotiation: 10.0.0.216[0]<=>10.0.0.11[0]
20:49:07: INFO: pfkey.c:1364:pk_recvexpire(): IPsec-SA expired:
ESP/Transport 10.0.0.216->10.0.0.11 spi=98734594(0x5e29202)
20:49:07: INFO: pfkey.c:1106:pk_recvupdate(): IPsec-SA
established: ESP/Transport 10.0.0.11->10.0.0.216 spi=137313584(0x82f3d30)
20:49:07: ERROR: pfkey.c:206:pfkey_handler(): pfkey ADD failed:
File exists

Period of silence:
20:51:07: INFO: pfkey.c:1364:pk_recvexpire(): IPsec-SA expired:
ESP/Transport 10.0.0.216->10.0.0.11 spi=98734594(0x5e29202)
20:51:07: INFO: isakmp.c:938:isakmp_ph2begin_i(): initiate new
phase 2 negotiation: 10.0.0.216[0]<=>10.0.0.11[0]
20:51:07: INFO: isakmp.c:1521:isakmp_ph1expire(): ISAKMP-SA
expired 10.0.0.216[500]-10.0.0.11[500] spi:7f7352a7dbd917ba:087da64152cda86a
20:51:07: ERROR: isakmp.c:1741:isakmp_post_getspi(): the
negotiation is stopped, because there is no suitable ISAKMP-SA.
20:51:07: ERROR: pfkey.c:894:pk_recvgetspi(): failed to start
post getspi.
20:51:08: INFO: isakmp.c:1521:isakmp_ph1expire(): ISAKMP-SA
expired 10.0.0.216[500]-10.0.0.11[500] spi:7f7352a7dbd917ba:087da64152cda86a
20:51:09: INFO: isakmp.c:1569:isakmp_ph1delete(): ISAKMP-SA
deleted 10.0.0.216[500]-10.0.0.11[500] spi:7f7352a7dbd917ba:087da64152cda86a

20:51:36: INFO: isakmp.c:1689:isakmp_post_acquire(): IPsec-SA
request for 10.0.0.11 queued due to no phase1 found.
20:51:36: INFO: isakmp.c:794:isakmp_ph1begin_i(): initiate new
phase 1 negotiation: 10.0.0.216[500]<=>10.0.0.11[500]
20:51:36: INFO: isakmp.c:799:isakmp_ph1begin_i(): begin
Aggressive mode.
20:51:37: INFO: vendorid.c:128:check_vendorid(): received Vendor
ID: KAME/racoon
20:51:37: NOTIFY: oakley.c:2037:oakley_skeyid(): couldn't find
the proper pskey, try to get one by the peer's address.
20:51:37: INFO: isakmp.c:2417:log_ph1established(): ISAKMP-SA
established 10.0.0.216[500]-10.0.0.11[500]
spi:48e6122ec72e2b47:55ea41d31553b4c2
20:51:37: INFO: isakmp.c:938:isakmp_ph2begin_i(): initiate new
phase 2 negotiation: 10.0.0.216[0]<=>10.0.0.11[0]
20:51:37: INFO: pfkey.c:1106:pk_recvupdate(): IPsec-SA
established: ESP/Transport 10.0.0.11->10.0.0.216 spi=137313584(0x82f3d30)
20:51:37: INFO: pfkey.c:1318:pk_recvadd(): IPsec-SA established:
ESP/Transport 10.0.0.216->10.0.0.11 spi=98734594(0x5e29202)

20:52:06: INFO: pfkey.c:1364:pk_recvexpire(): IPsec-SA expired:
ESP/Transport 10.0.0.216->10.0.0.11 

Communications now work again.

In the meantime on the responding site, 10.0.0.11:

20:51:36: INFO: pfkey.c:1106:pk_recvupdate(): IPsec-SA
established: ESP/Transport 10.0.0.216->10.0.0.11 spi=98734594(0x5e29202)
20:51:36: INFO: pfkey.c:1318:pk_recvadd(): IPsec-SA established:
ESP/Transport 10.0.0.11->10.0.0.216 spi=137313584(0x82f3d30)
20:59:36: INFO: pfkey.c:1364:pk_recvexpire(): IPsec-SA expired:
ESP/Transport 10.0.0.216->10.0.0.11 spi=98734594(0x5e29202)
20:59:36: INFO: pfkey.c:1364:pk_recvexpire(): IPsec-SA expired:
ESP/Transport 10.0.0.11->10.0.0.216 spi=137313584(0x82f3d30)
20:59:36: INFO: isakmp.c:1045:isakmp_ph2begin_r(): respond new
phase 2 negotiation: 10.0.0.11[0]<=>10.0.0.216[0]
20:59:37: INFO: pfkey.c:1106:pk_recvupdate(): IPsec-SA
established: ESP/Transport 10.0.0.216->10.0.0.11 spi=98734594(0x5e29202)
20:59:37: ERROR: pfkey.c:206:pfkey_handler(): pfkey ADD failed:
File exists


setkey -DP with working communications prints the following two real
entries (on 10.0.0.11):
10.0.0.216[any] 10.0.0.11[any] tcp
	
	esp/transport//require
	created:Nov 11 20:40:56 2002 lastused:Nov 11 20:41:25 2002
	lifetime:0(s) validtime:0(s)
	spid=2296 seq=5 pid=1061
	refcnt=21
10.0.0.11[any] 10.0.0.216[any] tcp
	
	esp/transport//require
	created:Nov 11 20:40:56 2002 lastused:Nov 11 20:41:25 2002
	lifetime:0(s) validtime:0(s)
	spid=2289 seq=4 pid=1061
	refcnt=3

And the following apparently bogus ones:

0.0.0.0/0[any] 0.0.0.0/0[any] any
	in none
	created:Nov 11 20:40:58 2002 lastused:                    
	lifetime:0(s) validtime:0(s)
	spid=2323 seq=3 pid=1061
	refcnt=2
0.0.0.0/0[any] 0.0.0.0/0[any] any
	in none
	created:Nov 11 20:40:58 2002 lastused:                    
	lifetime:0(s) validtime:0(s)
	spid=2307 seq=2 pid=1061
	refcnt=2
0.0.0.0/0[any] 0.0.0.0/0[any] any
	out none
	created:Nov 11 20:40:58 2002 lastused:Nov 11 20:41:06 2002
	lifetime:0(s) validtime:0(s)
	spid=2332 seq=1 pid=1061
	refcnt=2
0.0.0.0/0[any] 0.0.0.0/0[any] any
	out none
	created:Nov 11 20:40:58 2002 lastused:                    
	lifetime:0(s) validtime:0(s)
	spid=2316 seq=0 pid=1061
	refcnt=2

Regards,

bert 

-- 
http://www.PowerDNS.com          Versatile DNS Software & Services
http://lartc.org           Linux Advanced Routing & Traffic Control HOWTO

Re: off by one error in 3des cbc keying

[kuznet]

Hello!

> Communications work, then *something* expires after 30 seconds,

It is harmless, it is original request expired. However, this implies a bug,
original request must be replaced while installing negotiated SA.

It would be good if you made setkey -D before the entry expired
and started "setkey -x >& pfkey.log &" to collect pfkey traffic.



> After a few minutes, lifetime is 10 minutes:
> 20:49:07: INFO: pfkey.c:1364:pk_recvexpire(): IPsec-SA expired:
> ESP/Transport 10.0.0.11->10.0.0.216 spi=137313584(0x82f3d30)

That's soft expire notification, now keys should be updated now...


> 20:49:07: ERROR: pfkey.c:206:pfkey_handler(): pfkey ADD failed:
> File exists

Wow! I see. This is an explanation. racoon uses ADD instead of UPDATE...
It should not. Oh, well, but Maxim confirmed hour ago that it works.
This is puzzle. :-) OK, I have to dig in racoon to understand what
the hell it expects.

If you prepare "setkey -x >& pfkey.log &" it will make the things
much easier to track. Please, remember, at the moment I do not have
capabilities to make any experiments here. Probably, this is for good
(stimulates imagination :-)), but I really need to have full information
to debug and not to imagine too far. :-)


> 20:51:07: INFO: pfkey.c:1364:pk_recvexpire(): IPsec-SA expired:
> ESP/Transport 10.0.0.216->10.0.0.11 spi=98734594(0x5e29202)

And this is hard expire. The further is mess, apparently because
racoon is out of sync with kernel.


> And the following apparently bogus ones:

No, these are racoon's own ones. Do not worry about them. They are not used
for any packets but racoon's ones.

Alexey

Re: off by one error in 3des cbc keying

[bert hubert]

On Tue, Nov 12, 2002 at 12:35:38AM +0300, kuznet@ms2.inr.ac.ru wrote:

> It would be good if you made setkey -D before the entry expired
> and started "setkey -x >& pfkey.log &" to collect pfkey traffic.

Before the 30 second entry expired:

10.0.0.216 10.0.0.11 
	esp mode=transport spi=57115683(0x03678423) reqid=0(0x00000000)
	E: 3des-cbc  cc8e8e4f 91d41b7b ea6cbb3c 24a465cb a08b33aa c8ec1274
	A: hmac-sha1  f454ab03 3a803ca4 05239de3 100ce68f d283f10a
	seq=0x00000000 replay=4 flags=0x00000000 state=mature 
	created: Nov 11 22:42:38 2002	current: Nov 11 22:43:05 2002
	diff: 27(s)	hard: 600(s)	soft: 480(s)
	last:                     	hard: 0(s)	soft: 0(s)
	current: 0(bytes)	hard: 0(bytes)	soft: 0(bytes)
	allocated: 0	hard: 0	soft: 0
	sadb_seq=2 pid=8126 refcnt=0
10.0.0.216 10.0.0.11 
	esp mode=transport spi=0(0x00000000) reqid=0(0x00000000)
	seq=0x00000000 replay=0 flags=0x00000000 state=larval 
	created: Nov 11 22:42:37 2002	current: Nov 11 22:43:05 2002
	diff: 28(s)	hard: 30(s)	soft: 0(s)
	last:                     	hard: 0(s)	soft: 0(s)
	current: 0(bytes)	hard: 0(bytes)	soft: 0(bytes)
	allocated: 0	hard: 0	soft: 0
	sadb_seq=1 pid=8126 refcnt=0
10.0.0.11 10.0.0.216 
	esp mode=transport spi=222275495(0x0d3fa7a7) reqid=0(0x00000000)
	E: 3des-cbc  f5fbb657 9b12bea6 b7d2eeda 587a0961 8a94ff6e d7b79a28
	A: hmac-sha1  20c2a282 1909e8ab 1e4690c1 1ee6cb40 c6b24190
	seq=0x00000000 replay=4 flags=0x00000000 state=mature 
	created: Nov 11 22:42:38 2002	current: Nov 11 22:43:05 2002
	diff: 27(s)	hard: 600(s)	soft: 480(s)
	last:                     	hard: 0(s)	soft: 0(s)
	current: 0(bytes)	hard: 0(bytes)	soft: 0(bytes)
	allocated: 0	hard: 0	soft: 0
	sadb_seq=0 pid=8126 refcnt=0

The middle one disappears after 30 seconds.

Log:

22:42:37: INFO: isakmp.c:1689:isakmp_post_acquire(): IPsec-SA
request for 10.0.0.11 queued due to no phase1 found.
22:42:37: INFO: isakmp.c:794:isakmp_ph1begin_i(): initiate new
phase 1 negotiation: 10.0.0.216[500]<=>10.0.0.11[500]
22:42:37: INFO: isakmp.c:799:isakmp_ph1begin_i(): begin
Aggressive mode.
22:42:38: INFO: vendorid.c:128:check_vendorid(): received Vendor
ID: KAME/racoon
22:42:38: NOTIFY: oakley.c:2037:oakley_skeyid(): couldn't find
the proper pskey, try to get one by the peer's address.
22:42:38: INFO: isakmp.c:2417:log_ph1established(): ISAKMP-SA
established 10.0.0.216[500]-10.0.0.11[500]
spi:50397abe512587b4:7fbfed906953a464
22:42:38: INFO: isakmp.c:938:isakmp_ph2begin_i(): initiate new
phase 2 negotiation: 10.0.0.216[0]<=>10.0.0.11[0]
22:42:38: INFO: pfkey.c:1106:pk_recvupdate(): IPsec-SA
established: ESP/Transport 10.0.0.11->10.0.0.216 spi=222275495(0xd3fa7a7)
22:42:38: INFO: pfkey.c:1318:pk_recvadd(): IPsec-SA established:
ESP/Transport 10.0.0.216->10.0.0.11 spi=57115683(0x3678423)

22:43:07: INFO: pfkey.c:1364:pk_recvexpire(): IPsec-SA expired:
ESP/Transport 10.0.0.216->10.0.0.11 


pfkey.log:


22:42:37.809959 
sadb_msg{ version=2 type=6 errno=0 satype=3
  len=47 reserved=0 seq=14 pid=0
sadb_ext{ len=3 type=5 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=2 type=18 }
sadb_x_policy{ type=2 dir=2 id=81 }
sadb_ext{ len=37 type=13 }
sadb_prop{ replay=32
sadb_comb{ auth=2 encrypt=1 flags=0x0000 reserved=0x00000000
  auth_minbits=128 auth_maxbits=128 encrypt_minbits=64 encrypt_maxbits=64
  soft_alloc=0 hard_alloc=0 soft_bytes=0 hard_bytes=0
  soft_alloc=72000 hard_alloc=86400 soft_bytes=25200 hard_bytes=28800 }
sadb_comb{ auth=3 encrypt=1 flags=0x0000 reserved=0x00000000
  auth_minbits=160 auth_maxbits=160 encrypt_minbits=64 encrypt_maxbits=64
  soft_alloc=0 hard_alloc=0 soft_bytes=0 hard_bytes=0
  soft_alloc=72000 hard_alloc=86400 soft_bytes=25200 hard_bytes=28800 }
sadb_comb{ auth=2 encrypt=2 flags=0x0000 reserved=0x00000000
  auth_minbits=128 auth_maxbits=128 encrypt_minbits=192 encrypt_maxbits=192
  soft_alloc=0 hard_alloc=0 soft_bytes=0 hard_bytes=0
  soft_alloc=72000 hard_alloc=86400 soft_bytes=25200 hard_bytes=28800 }
sadb_comb{ auth=3 encrypt=2 flags=0x0000 reserved=0x00000000
  auth_minbits=160 auth_maxbits=160 encrypt_minbits=192 encrypt_maxbits=192
  soft_alloc=0 hard_alloc=0 soft_bytes=0 hard_bytes=0
  soft_alloc=72000 hard_alloc=86400 soft_bytes=25200 hard_bytes=28800 }
}

22:42:38.078871 
sadb_msg{ version=2 type=1 errno=0 satype=3
  len=10 reserved=0 seq=14 pid=8107
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=255 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=255 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }

22:42:38.079002 
sadb_msg{ version=2 type=1 errno=0 satype=3
  len=24 reserved=0 seq=14 pid=8107
sadb_ext{ len=2 type=1 }
sadb_sa{ spi=222275495 replay=0 state=0
  auth=0 encrypt=0 flags=0x00000000 }
sadb_ext{ len=4 type=3 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=30, usetime=0 }
sadb_ext{ len=4 type=4 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=0, usetime=0 }
sadb_ext{ len=4 type=2 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=1037050958, usetime=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }

22:42:38.079056 
sadb_msg{ version=2 type=10 errno=0 satype=0
  len=2 reserved=0 seq=0 pid=8107

22:42:38.079073 
sadb_msg{ version=2 type=10 errno=0 satype=3
  len=24 reserved=0 seq=1 pid=8107
sadb_ext{ len=2 type=1 }
sadb_sa{ spi=0 replay=0 state=0
  auth=0 encrypt=0 flags=0x00000000 }
sadb_ext{ len=4 type=3 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=30, usetime=0 }
sadb_ext{ len=4 type=4 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=0, usetime=0 }
sadb_ext{ len=4 type=2 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=1037050957, usetime=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }

22:42:38.079122 
sadb_msg{ version=2 type=10 errno=0 satype=3
  len=24 reserved=0 seq=0 pid=8107
sadb_ext{ len=2 type=1 }
sadb_sa{ spi=222275495 replay=0 state=0
  auth=0 encrypt=0 flags=0x00000000 }
sadb_ext{ len=4 type=3 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=30, usetime=0 }
sadb_ext{ len=4 type=4 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=0, usetime=0 }
sadb_ext{ len=4 type=2 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=1037050958, usetime=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }

22:42:38.144461 
sadb_msg{ version=2 type=2 errno=0 satype=3
  len=28 reserved=0 seq=14 pid=8107
sadb_ext{ len=2 type=1 }
sadb_sa{ spi=222275495 replay=4 state=0
  auth=3 encrypt=2 flags=0x00000000 }
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=255 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=255 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=4 type=9 }
sadb_key{ bits=192 reserved=0
  key= f5fbb657 9b12bea6 b7d2eeda 587a0961 8a94ff6e d7b79a28 }
sadb_ext{ len=4 type=8 }
sadb_key{ bits=160 reserved=0
  key= 20c2a282 1909e8ab 1e4690c1 1ee6cb40 c6b24190 }
sadb_ext{ len=4 type=3 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=600, usetime=0 }
sadb_ext{ len=4 type=4 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=480, usetime=0 }

22:42:38.144673 
sadb_msg{ version=2 type=2 errno=0 satype=3
  len=27 reserved=0 seq=14 pid=8107
sadb_ext{ len=2 type=1 }
sadb_sa{ spi=222275495 replay=4 state=1
  auth=3 encrypt=2 flags=0x00000000 }
sadb_ext{ len=4 type=3 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=600, usetime=0 }
sadb_ext{ len=4 type=4 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=480, usetime=0 }
sadb_ext{ len=4 type=2 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=1037050958, usetime=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=3 type=7 }
sadb_address{ proto=255 prefixlen=0 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 00000000  }
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }

22:42:38.144729 
sadb_msg{ version=2 type=2 errno=0 satype=3
  len=27 reserved=0 seq=14 pid=8107
sadb_ext{ len=2 type=1 }
sadb_sa{ spi=222275495 replay=4 state=1
  auth=3 encrypt=2 flags=0x00000000 }
sadb_ext{ len=4 type=3 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=600, usetime=0 }
sadb_ext{ len=4 type=4 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=480, usetime=0 }
sadb_ext{ len=4 type=2 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=1037050958, usetime=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=3 type=7 }
sadb_address{ proto=255 prefixlen=0 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 00000000  }
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }

22:42:38.144836 
sadb_msg{ version=2 type=3 errno=0 satype=3
  len=28 reserved=0 seq=14 pid=8107
sadb_ext{ len=2 type=1 }
sadb_sa{ spi=57115683 replay=4 state=0
  auth=3 encrypt=2 flags=0x00000000 }
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=255 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=255 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=4 type=9 }
sadb_key{ bits=192 reserved=0
  key= cc8e8e4f 91d41b7b ea6cbb3c 24a465cb a08b33aa c8ec1274 }
sadb_ext{ len=4 type=8 }
sadb_key{ bits=160 reserved=0
  key= f454ab03 3a803ca4 05239de3 100ce68f d283f10a }
sadb_ext{ len=4 type=3 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=600, usetime=0 }
sadb_ext{ len=4 type=4 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=480, usetime=0 }

22:42:38.144909 
sadb_msg{ version=2 type=3 errno=0 satype=3
  len=27 reserved=0 seq=14 pid=8107
sadb_ext{ len=2 type=1 }
sadb_sa{ spi=57115683 replay=4 state=1
  auth=3 encrypt=2 flags=0x00000000 }
sadb_ext{ len=4 type=3 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=600, usetime=0 }
sadb_ext{ len=4 type=4 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=480, usetime=0 }
sadb_ext{ len=4 type=2 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=1037050958, usetime=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=3 type=7 }
sadb_address{ proto=255 prefixlen=0 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 00000000  }
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }

22:42:38.145008 
sadb_msg{ version=2 type=3 errno=0 satype=3
  len=27 reserved=0 seq=14 pid=8107
sadb_ext{ len=2 type=1 }
sadb_sa{ spi=57115683 replay=4 state=1
  auth=3 encrypt=2 flags=0x00000000 }
sadb_ext{ len=4 type=3 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=600, usetime=0 }
sadb_ext{ len=4 type=4 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=480, usetime=0 }
sadb_ext{ len=4 type=2 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=1037050958, usetime=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=3 type=7 }
sadb_address{ proto=255 prefixlen=0 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 00000000  }
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }

22:42:39.661881 
sadb_msg{ version=2 type=10 errno=0 satype=0
  len=2 reserved=0 seq=0 pid=8112

22:42:39.661992 
sadb_msg{ version=2 type=10 errno=0 satype=3
  len=35 reserved=0 seq=2 pid=8112
sadb_ext{ len=2 type=1 }
sadb_sa{ spi=57115683 replay=4 state=1
  auth=3 encrypt=2 flags=0x00000000 }
sadb_ext{ len=4 type=3 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=600, usetime=0 }
sadb_ext{ len=4 type=4 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=480, usetime=0 }
sadb_ext{ len=4 type=2 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=1037050958, usetime=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=3 type=7 }
sadb_address{ proto=255 prefixlen=0 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 00000000  }
sadb_ext{ len=4 type=8 }
sadb_key{ bits=160 reserved=0
  key= f454ab03 3a803ca4 05239de3 100ce68f d283f10a }
sadb_ext{ len=4 type=9 }
sadb_key{ bits=192 reserved=0
  key= cc8e8e4f 91d41b7b ea6cbb3c 24a465cb a08b33aa c8ec1274 }
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }

22:42:39.662090 
sadb_msg{ version=2 type=10 errno=0 satype=3
  len=24 reserved=0 seq=1 pid=8112
sadb_ext{ len=2 type=1 }
sadb_sa{ spi=0 replay=0 state=0
  auth=0 encrypt=0 flags=0x00000000 }
sadb_ext{ len=4 type=3 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=30, usetime=0 }
sadb_ext{ len=4 type=4 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=0, usetime=0 }
sadb_ext{ len=4 type=2 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=1037050957, usetime=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }

22:42:39.662139 
sadb_msg{ version=2 type=10 errno=0 satype=3
  len=35 reserved=0 seq=0 pid=8112
sadb_ext{ len=2 type=1 }
sadb_sa{ spi=222275495 replay=4 state=1
  auth=3 encrypt=2 flags=0x00000000 }
sadb_ext{ len=4 type=3 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=600, usetime=0 }
sadb_ext{ len=4 type=4 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=480, usetime=0 }
sadb_ext{ len=4 type=2 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=1037050958, usetime=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=3 type=7 }
sadb_address{ proto=255 prefixlen=0 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 00000000  }
sadb_ext{ len=4 type=8 }
sadb_key{ bits=160 reserved=0
  key= 20c2a282 1909e8ab 1e4690c1 1ee6cb40 c6b24190 }
sadb_ext{ len=4 type=9 }
sadb_key{ bits=192 reserved=0
  key= f5fbb657 9b12bea6 b7d2eeda 587a0961 8a94ff6e d7b79a28 }
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }

22:43:05.077434 
sadb_msg{ version=2 type=10 errno=0 satype=0
  len=2 reserved=0 seq=0 pid=8126

22:43:05.077549 
sadb_msg{ version=2 type=10 errno=0 satype=3
  len=35 reserved=0 seq=2 pid=8126
sadb_ext{ len=2 type=1 }
sadb_sa{ spi=57115683 replay=4 state=1
  auth=3 encrypt=2 flags=0x00000000 }
sadb_ext{ len=4 type=3 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=600, usetime=0 }
sadb_ext{ len=4 type=4 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=480, usetime=0 }
sadb_ext{ len=4 type=2 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=1037050958, usetime=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=3 type=7 }
sadb_address{ proto=255 prefixlen=0 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 00000000  }
sadb_ext{ len=4 type=8 }
sadb_key{ bits=160 reserved=0
  key= f454ab03 3a803ca4 05239de3 100ce68f d283f10a }
sadb_ext{ len=4 type=9 }
sadb_key{ bits=192 reserved=0
  key= cc8e8e4f 91d41b7b ea6cbb3c 24a465cb a08b33aa c8ec1274 }
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }

22:43:05.077646 
sadb_msg{ version=2 type=10 errno=0 satype=3
  len=24 reserved=0 seq=1 pid=8126
sadb_ext{ len=2 type=1 }
sadb_sa{ spi=0 replay=0 state=0
  auth=0 encrypt=0 flags=0x00000000 }
sadb_ext{ len=4 type=3 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=30, usetime=0 }
sadb_ext{ len=4 type=4 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=0, usetime=0 }
sadb_ext{ len=4 type=2 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=1037050957, usetime=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }

22:43:05.077694 
sadb_msg{ version=2 type=10 errno=0 satype=3
  len=35 reserved=0 seq=0 pid=8126
sadb_ext{ len=2 type=1 }
sadb_sa{ spi=222275495 replay=4 state=1
  auth=3 encrypt=2 flags=0x00000000 }
sadb_ext{ len=4 type=3 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=600, usetime=0 }
sadb_ext{ len=4 type=4 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=480, usetime=0 }
sadb_ext{ len=4 type=2 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=1037050958, usetime=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=3 type=7 }
sadb_address{ proto=255 prefixlen=0 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 00000000  }
sadb_ext{ len=4 type=8 }
sadb_key{ bits=160 reserved=0
  key= 20c2a282 1909e8ab 1e4690c1 1ee6cb40 c6b24190 }
sadb_ext{ len=4 type=9 }
sadb_key{ bits=192 reserved=0
  key= f5fbb657 9b12bea6 b7d2eeda 587a0961 8a94ff6e d7b79a28 }
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }

22:43:07.781122 
sadb_msg{ version=2 type=8 errno=0 satype=3
  len=20 reserved=0 seq=0 pid=0
sadb_ext{ len=2 type=1 }
sadb_sa{ spi=0 replay=0 state=3
  auth=0 encrypt=0 flags=0x00000000 }
sadb_ext{ len=4 type=3 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=30, usetime=0 }
sadb_ext{ len=4 type=2 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=1037050957, usetime=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }

22:43:11.444772 
sadb_msg{ version=2 type=10 errno=0 satype=0
  len=2 reserved=0 seq=0 pid=8130

22:43:11.444967 
sadb_msg{ version=2 type=10 errno=0 satype=3
  len=35 reserved=0 seq=1 pid=8130
sadb_ext{ len=2 type=1 }
sadb_sa{ spi=57115683 replay=4 state=1
  auth=3 encrypt=2 flags=0x00000000 }
sadb_ext{ len=4 type=3 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=600, usetime=0 }
sadb_ext{ len=4 type=4 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=480, usetime=0 }
sadb_ext{ len=4 type=2 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=1037050958, usetime=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=3 type=7 }
sadb_address{ proto=255 prefixlen=0 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 00000000  }
sadb_ext{ len=4 type=8 }
sadb_key{ bits=160 reserved=0
  key= f454ab03 3a803ca4 05239de3 100ce68f d283f10a }
sadb_ext{ len=4 type=9 }
sadb_key{ bits=192 reserved=0
  key= cc8e8e4f 91d41b7b ea6cbb3c 24a465cb a08b33aa c8ec1274 }
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }

22:43:11.445063 
sadb_msg{ version=2 type=10 errno=0 satype=3
  len=35 reserved=0 seq=0 pid=8130
sadb_ext{ len=2 type=1 }
sadb_sa{ spi=222275495 replay=4 state=1
  auth=3 encrypt=2 flags=0x00000000 }
sadb_ext{ len=4 type=3 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=600, usetime=0 }
sadb_ext{ len=4 type=4 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=480, usetime=0 }
sadb_ext{ len=4 type=2 }
sadb_lifetime{ alloc=0, bytes=0
  addtime=1037050958, usetime=0 }
sadb_ext{ len=3 type=5 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a00000b  }
sadb_ext{ len=3 type=6 }
sadb_address{ proto=0 prefixlen=32 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 0a0000d8  }
sadb_ext{ len=3 type=7 }
sadb_address{ proto=255 prefixlen=0 reserved=0x0000 }
sockaddr{ len=16 family=2 port=0
 00000000  }
sadb_ext{ len=4 type=8 }
sadb_key{ bits=160 reserved=0
  key= 20c2a282 1909e8ab 1e4690c1 1ee6cb40 c6b24190 }
sadb_ext{ len=4 type=9 }
sadb_key{ bits=192 reserved=0
  key= f5fbb657 9b12bea6 b7d2eeda 587a0961 8a94ff6e d7b79a28 }
sadb_ext{ len=2 type=19 }
sadb_x_sa2{ mode=1 reqid=0
  reserved1=0 reserved2=0 sequence=0 }

> If you prepare "setkey -x >& pfkey.log &" it will make the things
> much easier to track. Please, remember, at the moment I do not have
> capabilities to make any experiments here. Probably, this is for good
> (stimulates imagination :-)), but I really need to have full information
> to debug and not to imagine too far. :-)

I can give you access to my computers if you want? I have three available
here.

I hope this helps. Full setup on both sides:

On 10.0.0.216:

#!/home/ahu/download/kametools/setkey/setkey -f
flush;
spdflush;

spdadd 10.0.0.216 10.0.0.11 tcp -P out ipsec
        esp/transport//require;

spdadd 10.0.0.11 10.0.0.216 tcp -P in ipsec  
        esp/transport//require;

On 10.0.0.11:

#!./setkey -f
flush;
spdflush;

spdadd 10.0.0.11 10.0.0.216 tcp -P out ipsec
	esp/transport//require;

spdadd 10.0.0.216 10.0.0.11 tcp -P in ipsec
	esp/transport//require;


racoon.conf, identical on both (verified):

path pre_shared_key "./psk.txt" ;

remote anonymous
{
 	exchange_mode aggressive,main;
	doi ipsec_doi;
	situation identity_only;

	my_identifier address;

	nonce_size 16;
	lifetime time 10 min;   # sec,min,hour
	initial_contact on;
	support_mip6 on;
	proposal_check obey;	# obey, strict or claim

	proposal {
                encryption_algorithm 3des;
		hash_algorithm sha1;
		authentication_method pre_shared_key ;
		dh_group 2 ;
	}
}

sainfo anonymous
{
 	pfs_group 1;
	lifetime time 10 min;
	encryption_algorithm 3des ;
	authentication_algorithm hmac_sha1;
	compression_algorithm deflate ;
}


Regards,

bert

-- 
http://www.PowerDNS.com          Versatile DNS Software & Services
http://lartc.org           Linux Advanced Routing & Traffic Control HOWTO

Re: off by one error in 3des cbc keying

[kuznet]

Hello!

> > It is. But your example shows that something is wrong there. Fix will follow
> > later.
> 
> Ok, let me know if I can test.

Enclosed.

Comments for Dave:

1. udp.c: silly bug, local input policy did not work on udp sockets.
2. ah.c,esp.c: even sillier bug: 0 was used as  tunnels protocol. Funny enough,
   it worked between linuxes. :-) By <gem@asplinux.ru>


Another fix for wrongly formatted ICV for ESP will follow
tonight after test for interoperability with freebsd.

The problem with expiration remains unsolved. I still cannot reproduce this
and cannot find a situation when kernel can create two larvals with one
identity. :-( Searching.

Alexey


===== net/ipv4/ah.c 1.6 vs edited =====
--- 1.6/net/ipv4/ah.c	Fri Nov  8 11:34:37 2002
+++ edited/net/ipv4/ah.c	Tue Nov 12 02:43:59 2002
@@ -189,7 +189,7 @@
 		top_iph->saddr = x->props.saddr.xfrm4_addr;
 		top_iph->daddr = x->id.daddr.xfrm4_addr;
 		ah = (struct ip_auth_hdr*)(top_iph+1);
-		ah->nexthdr = IPPROTO_IP;
+		ah->nexthdr = IPPROTO_IPIP;
 	} else {
 		memcpy(&tmp_iph, skb->data, iph->ihl*4);
 		top_iph = (struct iphdr*)skb_push(skb, x->props.header_len);
===== net/ipv4/esp.c 1.4 vs edited =====
--- 1.4/net/ipv4/esp.c	Fri Nov  8 11:34:37 2002
+++ edited/net/ipv4/esp.c	Tue Nov 12 02:43:59 2002
@@ -370,7 +370,7 @@
 	if (x->props.mode) {
 		top_iph = (struct iphdr*)skb_push(skb, x->props.header_len);
 		esph = (struct ip_esp_hdr*)(top_iph+1);
-		*(u8*)(trailer->tail - 1) = IPPROTO_IP;
+		*(u8*)(trailer->tail - 1) = IPPROTO_IPIP;
 		top_iph->ihl = 5;
 		top_iph->version = 4;
 		top_iph->tos = iph->tos;	/* DS disclosed */
===== net/ipv4/udp.c 1.27 vs edited =====
--- 1.27/net/ipv4/udp.c	Tue Nov 12 02:37:12 2002
+++ edited/net/ipv4/udp.c	Tue Nov 12 16:30:49 2002
@@ -944,7 +944,7 @@
 	/*
 	 *	Charge it to the socket, dropping if the queue is full.
 	 */
-	if (!xfrm_policy_check(NULL, XFRM_POLICY_IN, skb)) {
+	if (!xfrm_policy_check(sk, XFRM_POLICY_IN, skb)) {
 		kfree_skb(skb);
 		return -1;
 	}
===== net/ipv4/xfrm_input.c 1.3 vs edited =====
--- 1.3/net/ipv4/xfrm_input.c	Fri Nov  8 11:34:37 2002
+++ edited/net/ipv4/xfrm_input.c	Tue Nov 12 02:43:59 2002
@@ -91,7 +91,7 @@
 		iph = skb->nh.iph;
 
 		if (x->props.mode) {
-			if (iph->protocol != IPPROTO_IP)
+			if (iph->protocol != IPPROTO_IPIP)
 				goto drop;
 			skb->nh.raw = skb->data;
 			iph = skb->nh.iph;

Re: off by one error in 3des cbc keying

[bert hubert]

On Tue, Nov 12, 2002 at 04:55:57PM +0300, kuznet@ms2.inr.ac.ru wrote:

> 1. udp.c: silly bug, local input policy did not work on udp sockets.
> 2. ah.c,esp.c: even sillier bug: 0 was used as  tunnels protocol. Funny enough,
>    it worked between linuxes. :-) By <gem@asplinux.ru>

Thanks, will test tonight. Very very sadly, user mode linux does not compile
for me in 2.5.47 and furthermore does not appear to be aware of the crypto
subsystem.

I added this patch to the larc IPSEC pages.

> The problem with expiration remains unsolved. I still cannot reproduce this
> and cannot find a situation when kernel can create two larvals with one
> identity. :-( Searching.

Sure you saw that? I only saw the one larval in the output I sent you, with
everything set to zero. But perhaps I'm missing something. I'll have all my
computers together again tonight.

Regards,

bert

-- 
http://www.PowerDNS.com          Versatile DNS Software & Services
http://lartc.org           Linux Advanced Routing & Traffic Control HOWTO

Re: off by one error in 3des cbc keying

[kuznet]

Hello!

> > The problem with expiration remains unsolved. I still cannot reproduce this
> > and cannot find a situation when kernel can create two larvals with one
> > identity. :-( Searching.
> 
> Sure you saw that? I only saw the one larval in the output I sent you,

Sure, unless my sick cisco router corrupts mails. But I hope it is not
so malicious. :-)

Joke aparts, of course, I did not see this, it exists for short time,
you see one of them already grown to mature.

10.0.0.216 10.0.0.11 
	esp mode=transport spi=57115683(0x03678423) reqid=0(0x00000000)
	E: 3des-cbc  cc8e8e4f 91d41b7b ea6cbb3c 24a465cb a08b33aa c8ec1274
	A: hmac-sha1  f454ab03 3a803ca4 05239de3 100ce68f d283f10a
	seq=0x00000000 replay=4 flags=0x00000000 state=mature 
	created: Nov 11 22:42:38 2002	current: Nov 11 22:43:05 2002
	diff: 27(s)	hard: 600(s)	soft: 480(s)
	last:                     	hard: 0(s)	soft: 0(s)
	current: 0(bytes)	hard: 0(bytes)	soft: 0(bytes)
	allocated: 0	hard: 0	soft: 0
	sadb_seq=2 pid=8126 refcnt=0
10.0.0.216 10.0.0.11 
	esp mode=transport spi=0(0x00000000) reqid=0(0x00000000)
	seq=0x00000000 replay=0 flags=0x00000000 state=larval 
	created: Nov 11 22:42:37 2002	current: Nov 11 22:43:05 2002
	diff: 28(s)	hard: 30(s)	soft: 0(s)
	last:                     	hard: 0(s)	soft: 0(s)
	current: 0(bytes)	hard: 0(bytes)	soft: 0(bytes)
	allocated: 0	hard: 0	soft: 0
	sadb_seq=1 pid=8126 refcnt=0

This MUST NOT happen. The first one was larval while for a second
before line:

22:42:38: INFO: pfkey.c:1106:pk_recvupdate(): IPsec-SA
established: ESP/Transport 10.0.0.11->10.0.0.216 spi=222275495(0xd3fa7a7)

Essentially, seeing this you see a bug in kernel.

Alexey

Re: off by one error in 3des cbc keying

[bert hubert]

[-- Attachment #1: Type: text/plain, Size: 2056 bytes --]

On Tue, Nov 12, 2002 at 06:29:06PM +0300, kuznet@ms2.inr.ac.ru wrote:
> Hello!
> 
> > > The problem with expiration remains unsolved. I still cannot reproduce this
> > > and cannot find a situation when kernel can create two larvals with one
> > > identity. :-( Searching.
> > 
> > Sure you saw that? I only saw the one larval in the output I sent you,
> 
> Sure, unless my sick cisco router corrupts mails. But I hope it is not
> so malicious. :-)
> 
> Joke aparts, of course, I did not see this, it exists for short time,
> you see one of them already grown to mature.

I've made a movie, the output of: 
while true; do date ; sudo download/kametools/setkey/setkey -D ; done > logs

Please find it attached.

This corresponds to:
20:01:43: INFO: isakmp.c:1689:isakmp_post_acquire(): IPsec-SA
request for 10.0.0.11 queued due to no phase1 found.
20:01:43: INFO: isakmp.c:794:isakmp_ph1begin_i(): initiate new
phase 1 negotiation: 10.0.0.216[500]<=>10.0.0.11[500]
20:01:43: INFO: isakmp.c:799:isakmp_ph1begin_i(): begin
Aggressive mode.
20:01:43: INFO: vendorid.c:128:check_vendorid(): received Vendor
ID: KAME/racoon
20:01:43: NOTIFY: oakley.c:2037:oakley_skeyid(): couldn't find
the proper pskey, try to get one by the peer's address.
20:01:43: INFO: isakmp.c:2417:log_ph1established(): ISAKMP-SA
established 10.0.0.216[500]-10.0.0.11[500]
spi:abf1baea48b9c16d:e422bce8c6b9f015
20:01:44: INFO: isakmp.c:938:isakmp_ph2begin_i(): initiate new
phase 2 negotiation: 10.0.0.216[0]<=>10.0.0.11[0]
20:01:44: INFO: pfkey.c:1106:pk_recvupdate(): IPsec-SA
established: ESP/Transport 10.0.0.11->10.0.0.216 spi=251701380(0xf00a884)
20:01:44: INFO: pfkey.c:1318:pk_recvadd(): IPsec-SA established:
ESP/Transport 10.0.0.216->10.0.0.11 spi=43499516(0x297bffc)

20:02:13: INFO: pfkey.c:1364:pk_recvexpire(): IPsec-SA expired:
ESP/Transport 10.0.0.216->10.0.0.11 

Note how it changes very nearly atomically.

Regards,

bert

-- 
http://www.PowerDNS.com          Versatile DNS Software & Services
http://lartc.org           Linux Advanced Routing & Traffic Control HOWTO

[-- Attachment #2: logs.bz2 --]
[-- Type: application/octet-stream, Size: 2288 bytes --]

Re: off by one error in 3des cbc keying

[David S. Miller]

   From: kuznet@ms2.inr.ac.ru
   Date: Tue, 12 Nov 2002 16:55:57 +0300 (MSK)

   Comments for Dave:
   
   1. udp.c: silly bug, local input policy did not work on udp sockets.
   2. ah.c,esp.c: even sillier bug: 0 was used as  tunnels protocol. Funny enough,
      it worked between linuxes. :-) By <gem@asplinux.ru>
   
Applied, thanks.
   
   Another fix for wrongly formatted ICV for ESP will follow
   tonight after test for interoperability with freebsd.
   
   The problem with expiration remains unsolved. I still cannot reproduce this
   and cannot find a situation when kernel can create two larvals with one
   identity. :-( Searching.
   
Ok, I continue with xfrm_user.  Damn I must finish this crap :)

Re: off by one error in 3des cbc keying

[kuznet]

Hello!

> Applied, thanks.
>    
>    Another fix for wrongly formatted ICV for ESP will follow
>    tonight after test for interoperability with freebsd.

So, this piece is by Maxim. Bert, beware, it is required to talk
to another stacks but breaks communication with linuxes before this patch.

For log: authentication signature for MD5/SHA was not truncated to conform RFC.

Side note: well, my fault, but damn common sense requires not to break
nice good MD5 digest to some absolutely unmotivated length.

Alexey


===== net/ipv4/esp.c 1.4 vs edited =====
--- 1.4/net/ipv4/esp.c	Fri Nov  8 11:34:37 2002
+++ edited/net/ipv4/esp.c	Wed Nov 13 03:00:52 2002
@@ -190,11 +190,10 @@
 	struct crypto_tfm *tfm = esp->auth.tfm;
 	char *digest = esp->auth.work_digest;
 
-	memset(auth_data, 0, esp->auth.authlen);
  	crypto_hmac_init(tfm, esp->auth.key, &esp->auth.key_len);
 	skb_digest_walk(skb, tfm, offset, len);
 	crypto_hmac_final(tfm, esp->auth.key, &esp->auth.key_len, digest);
-	memcpy(auth_data, digest, crypto_tfm_alg_digestsize(tfm));
+	memcpy(auth_data, digest, esp->auth.authlen);
 }
 
 /* Check that skb data bits are writable. If they are not, copy data
@@ -463,16 +462,16 @@
 
 	/* If integrity check is required, do this. */
 	if (esp->auth.authlen) {
-		int icvsize = crypto_tfm_alg_digestsize(esp->auth.tfm);
-		u8 sum[icvsize];
-		u8 sum1[icvsize];
+		u8 sum[esp->auth.authlen];
+		u8 sum1[esp->auth.authlen];
 
 		esp->auth.digest(esp, skb, 0, skb->len-esp->auth.authlen, sum);
 
-		if (skb_copy_bits(skb, skb->len-esp->auth.authlen, sum1, icvsize))
+		if (skb_copy_bits(skb, skb->len-esp->auth.authlen, sum1, 
+				esp->auth.authlen))
 			BUG();
 
-		if (unlikely(memcmp(sum, sum1, icvsize))) {
+		if (unlikely(memcmp(sum, sum1, esp->auth.authlen))) {
 			x->stats.integrity_failed++;
 			goto out;
 		}
@@ -605,14 +604,20 @@
 	memset(esp, 0, sizeof(*esp));
 
 	if (x->aalg) {
+		int digestsize;
+
 		esp->auth.key = x->aalg->alg_key;
 		esp->auth.key_len = (x->aalg->alg_key_len+7)/8;
 		esp->auth.tfm = crypto_alloc_tfm(x->aalg->alg_name, 0);
 		if (esp->auth.tfm == NULL)
 			goto error;
 		esp->auth.digest = esp_hmac_digest;
-		esp->auth.authlen = crypto_tfm_alg_digestsize(esp->auth.tfm);
-		esp->auth.work_digest = kmalloc(esp->auth.authlen, GFP_KERNEL);
+		digestsize = crypto_tfm_alg_digestsize(esp->auth.tfm);
+		/* XXX RFC2403 and RFC 2404 truncate auth to 96 bit */
+		esp->auth.authlen = 12;
+		if (esp->auth.authlen > digestsize) /* XXX */
+			BUG();
+		esp->auth.work_digest = kmalloc(digestsize, GFP_KERNEL);
 		if (!esp->auth.work_digest)
 			goto error;
 	}

Re: off by one error in 3des cbc keying

[kuznet]

Hello!

>    The problem with expiration remains unsolved.

Patch #2. Bert, this is supposed to fix the first strange phenomenon
in your experiment. But I still do not know what will happen after that.
Please, check.

Dave, do not take this patch. It is a bit ugly and I would like
to finish with Bert's problem, which may require sequence of incremental
fixes to the same place.

Alexey


===== include/net/xfrm.h 1.5 vs edited =====
--- 1.5/include/net/xfrm.h	Tue Nov 12 02:37:12 2002
+++ edited/include/net/xfrm.h	Wed Nov 13 03:38:20 2002
@@ -473,7 +473,7 @@
 struct xfrm_policy *xfrm_policy_byid(int dir, u32 id, int delete);
 void xfrm_policy_flush(void);
 void xfrm_alloc_spi(struct xfrm_state *x, u32 minspi, u32 maxspi);
-struct xfrm_state * xfrm_find_acq(u8 mode, u16 reqid, u8 proto, u32 daddr, u32 saddr);
+struct xfrm_state * xfrm_find_acq(u8 mode, u16 reqid, u8 proto, u32 daddr, u32 saddr, int create);
 extern void xfrm_policy_flush(void);
 extern void xfrm_policy_kill(struct xfrm_policy *);
 extern int xfrm_sk_policy_insert(struct sock *sk, int dir, struct xfrm_policy *pol);
===== net/ipv4/xfrm_state.c 1.6 vs edited =====
--- 1.6/net/ipv4/xfrm_state.c	Tue Nov 12 02:37:12 2002
+++ edited/net/ipv4/xfrm_state.c	Wed Nov 13 03:38:26 2002
@@ -386,7 +386,7 @@
 }
 
 struct xfrm_state *
-xfrm_find_acq(u8 mode, u16 reqid, u8 proto, u32 daddr, u32 saddr)
+xfrm_find_acq(u8 mode, u16 reqid, u8 proto, u32 daddr, u32 saddr, int create)
 {
 	struct xfrm_state *x, *x0;
 	unsigned h = ntohl(daddr);
@@ -411,7 +411,7 @@
 	}
 	if (x0) {
 		atomic_inc(&x0->refcnt);
-	} else if ((x0 = xfrm_state_alloc()) != NULL) {
+	} else if (create && (x0 = xfrm_state_alloc()) != NULL) {
 		x0->sel.daddr.xfrm4_addr = daddr;
 		x0->sel.daddr.xfrm4_mask = ~0;
 		x0->sel.saddr.xfrm4_addr = saddr;
===== net/key/af_key.c 1.7 vs edited =====
--- 1.7/net/key/af_key.c	Tue Nov 12 02:37:12 2002
+++ edited/net/key/af_key.c	Wed Nov 13 03:48:17 2002
@@ -528,8 +528,7 @@
 
 	switch (((struct sockaddr *)(addr + 1))->sa_family) {
 	case AF_INET:
-		x = xfrm_state_lookup(
-				      ((struct sockaddr_in*)(addr + 1))->sin_addr.s_addr,
+		x = xfrm_state_lookup(((struct sockaddr_in*)(addr + 1))->sin_addr.s_addr,
 				      sa->sadb_sa_spi, proto);
 		break;
 	case AF_INET6:
@@ -1043,7 +1042,7 @@
 	daddr = (struct sockaddr_in*)(addr + 1);
 
 	x = xfrm_find_acq(mode, reqid, proto, daddr->sin_addr.s_addr,
-			  saddr->sin_addr.s_addr);
+			  saddr->sin_addr.s_addr, 1);
 	if (x == NULL)
 		return -ENOENT;
 
@@ -1122,7 +1121,17 @@
 
 	/* XXX there is race condition */
 	x1 = pfkey_xfrm_state_lookup(hdr, ext_hdrs);
-	if (x1 && hdr->sadb_msg_type == SADB_ADD) {
+	if (!x1) {
+		x1 = xfrm_find_acq(x->props.mode, x->props.reqid, x->id.proto,
+				   x->id.daddr.xfrm4_addr,
+				   x->props.saddr.xfrm4_addr, 0);
+		if (x1 && x1->id.spi != x->id.spi && x1->id.spi) {
+			xfrm_state_put(x1);
+			x1 = NULL;
+		}
+	}
+
+	if (x1 && x1->id.spi && hdr->sadb_msg_type == SADB_ADD) {
 		x->km.state = XFRM_STATE_DEAD;
 		xfrm_state_put(x);
 		xfrm_state_put(x1);
@@ -1131,7 +1140,7 @@
 
 	xfrm_state_insert(x);
 
-	if (x1 && hdr->sadb_msg_type != SADB_ADD) {
+	if (x1) {
 		xfrm_state_delete(x1);
 		xfrm_state_put(x1);
 	}

Re: off by one error in 3des cbc keying

[David S. Miller]

   From: kuznet@ms2.inr.ac.ru
   Date: Wed, 13 Nov 2002 04:04:15 +0300 (MSK)

   For log: authentication signature for MD5/SHA was not truncated to conform RFC.
   
Applied, thanks.

   Side note: well, my fault, but damn common sense requires not to break
   nice good MD5 digest to some absolutely unmotivated length.

Yes, seems really stupid.

automatic keying works! Re: off by one error in 3des cbc keying

[bert hubert]

On Wed, Nov 13, 2002 at 04:09:26AM +0300, kuznet@ms2.inr.ac.ru wrote:
> Hello!
> 
> >    The problem with expiration remains unsolved.
> 
> Patch #2. Bert, this is supposed to fix the first strange phenomenon
> in your experiment. But I still do not know what will happen after that.
> Please, check.

Resolves strange larvals, thanks. Patch #1 works fine but changes nothing
for linux-linux IPSEC, if both have the patch. Scenario I see now:

Initial setup is wonderful, 10.0.0.11 and 10.0.0.216 setup SAs.

At the soft expiration, both ends renegotiate and UPDATE their *incoming*
SA, using pk_sendupdate which calls pfkey_send_update in libipsec.

The outgoing SA however is updated using pk_sendadd which calls
pfkey_send_add, which Linux hates because there is already an SA there.

I changed it to call pfkey_sendupdate and then everything works as intended.
You spotted this problem earlier, by the way.

This brings us to the point that everything I try works. Key rollover is now
completely seamless. My patch to racoon is really ugly as it now also uses
UPDATE to add the initial outbound SA, I can improve it if you want?

Regards,

bert

-- 
http://www.PowerDNS.com          Versatile DNS Software & Services
http://lartc.org           Linux Advanced Routing & Traffic Control HOWTO

Re: automatic keying works! Re: off by one error in 3des cbc keying

[bert hubert]

On Wed, Nov 13, 2002 at 11:46:40PM +0300, kuznet@ms2.inr.ac.ru wrote:

> We traced all this today. It was not true reason of bad behaviour,
> real mistake was in absolutely different place. The patch (not incremental
> wrt patch of yesterday, so backout that one).

Done. http://ds9a.nl/ipsec now contains patches:

[TXT] 01-bypass-connect.diff        11-Nov-2002 08:59    16k  
[TXT] 02-udp-bypass.diff            12-Nov-2002 15:14     2k  
[TXT] 03-interop-breaks-compat.diff 13-Nov-2002 08:25     3k  
[TXT] 04-larval-2.diff              13-Nov-2002 21:53     5k  

When applied together, it now *really* works as intended :-)

> No, really. The trace showed another problem: one of them looks like
> a bug in racoon namely, after SA internal to IKE expires racoon
> does not initiate new connection to peer when some real kernel

I now see a proper soft expire, new SAs being setup, old SAs in state 'dying',
and traffic flowing nicely. Even with soft expire and no traffic, I see a
new SA being negotiated.

Until the old SAs die, I see linux sending with the old SPI, is that right?

Regards,

bert

-- 
http://www.PowerDNS.com          Versatile DNS Software & Services
http://lartc.org           Linux Advanced Routing & Traffic Control HOWTO

Re: automatic keying works! Re: off by one error in 3des cbc keying

[kuznet]

Hello!

> I now see a proper soft expire, new SAs being setup, old SAs in state 'dying',
> and traffic flowing nicely. Even with soft expire and no traffic, I see a
> new SA being negotiated.

Wait for a while and you will see message sort of:

Nov 13 20:48:59 mops  [291/0/0] racoon: INFO: isakmp.c:1521:isakmp_ph1expire():
ISAKMP-SA expired 192.168.1.202[500]-192.168.1.106[500] spi:c9549e2b4f33f8a3:655bf176d4531765

Note word "ISAKMP", this SA has nothing to do with IPsec, it is to protect
exchange between IKE's.

An IPsec SA soft-expires follows this. Then new IPsec SA will _not_ be
negotiated! So, old SA will be used until final hard expire, and
the next packet will trigger all the renegotiation from the very beginning
introducing a small gap in service and losing one or more packets.

Nov 13 20:45:59 mops  [291/0/0] racoon: INFO: pfkey.c:1364:pk_recvexpire(): IPsec-SA expired: AH/Transport 192.168.1.106->192.168.1.202 spi=21148383(0x142b2df)
Nov 13 20:45:59 mops  [291/0/0] racoon: INFO: isakmp.c:1569:isakmp_ph1delete():
ISAKMP-SA deleted 192.168.1.202[500]-192.168.1.106[500] spi:a5eb75bdffbc0e6b:6b829e67c9bcfb3c
Nov 13 20:45:59 mops  [291/0/0] racoon: INFO: pfkey.c:1364:pk_recvexpire(): IPsec-SA expired: AH/Transport 192.168.1.202->192.168.1.106 spi=218761938(0xd0a0ad2)
Nov 13 20:45:59 mops  [291/0/0] racoon: INFO: isakmp.c:1689:isakmp_post_acquire(): IPsec-SA request for 192.168.1.106 queued due to no phase1 found.


Apparently, racoon must reconnect to peer not waiting for timeout
when it sees that this SA was used recently enough. It does not.
Well, it is bug but not serious.



> Until the old SAs die, I see linux sending with the old SPI, is that right?

No, really. We prefer new one, when reselection is requested. We can
enforce reselection when some SA becomes close to death (dying),
and, probably, we will do. Well, KAME _always_ prefers old SA
which results in real loss of packets under freebsd. It is _disgusting_,
so we considered this as a bug in freebsd and forgot that linux can
behave in the same way when doing tcp, rather not ping. :-) :-)

Alexey

Re: automatic keying works! Re: off by one error in 3des cbc keying

[David S. Miller]

   From: kuznet@ms2.inr.ac.ru
   Date: Wed, 13 Nov 2002 23:46:40 +0300 (MSK)

   Log message for Dave:
   
   - xfrm_state.c: never return mature SAs on getspi.
   - af_key.c: do not forget to delete dummy super-larvals when they are resolved
   - af_key.c: wow! specially for this case I added gfp argument
               to xfrm_alloc_policy() and forgot to use it really.

Applied, thanks.

Re: automatic keying works! Re: off by one error in 3des cbc keying

[bert hubert]

On Thu, Nov 14, 2002 at 01:35:39AM +0300, kuznet@ms2.inr.ac.ru wrote:
> > I now see a proper soft expire, new SAs being setup, old SAs in state 'dying',
> > and traffic flowing nicely. Even with soft expire and no traffic, I see a
> > new SA being negotiated.
> 
> Wait for a while and you will see message sort of:
> 
> Nov 13 20:48:59 mops  [291/0/0] racoon: INFO: isakmp.c:1521:isakmp_ph1expire():
> ISAKMP-SA expired 192.168.1.202[500]-192.168.1.106[500] spi:c9549e2b4f33f8a3:655bf176d4531765

Did IPSEC die in 2.5.48? I can't get automatic keying to work, it only says
this once every two minutes:

2002-11-18 20:54:15: DEBUG: pfkey.c:191:pfkey_handler(): get pfkey EXPIRE
message
2002-11-18 20:54:15: INFO: pfkey.c:1364:pk_recvexpire(): IPsec-SA expired:
ESP/Transport 10.0.0.216->10.0.0.11 
2002-11-18 20:54:15: DEBUG: pfkey.c:1376:pk_recvexpire(): no such a SA
found: ESP/Transport 10.0.0.216->10.0.0.11 

I did turn on CONFIG_XFRM_USER, does it conflict with PF_KEY?

Regards,

bert

-- 
http://www.PowerDNS.com          Versatile DNS Software & Services
http://lartc.org           Linux Advanced Routing & Traffic Control HOWTO

Re: automatic keying works! Re: off by one error in 3des cbc keying

[kuznet]

Hello!

> I did turn on CONFIG_XFRM_USER, does it conflict with PF_KEY?

Yes, their interaction is still... mmm... not polished.
Build both xfrm_user and af_key as modules and load only one for now.

Alexey

Re: automatic keying works! Re: off by one error in 3des cbc keying

[David S. Miller]

   From: bert hubert <ahu@ds9a.nl>
   Date: Mon, 18 Nov 2002 20:56:19 +0100

   I did turn on CONFIG_XFRM_USER, does it conflict with PF_KEY?

No.

Re: automatic keying works! Re: off by one error in 3des cbc keying

[David S. Miller]

   From: kuznet@ms2.inr.ac.ru
   Date: Mon, 18 Nov 2002 23:04:47 +0300 (MSK)
   
   > I did turn on CONFIG_XFRM_USER, does it conflict with PF_KEY?
   
   Yes, their interaction is still... mmm... not polished.
   Build both xfrm_user and af_key as modules and load only one for now.
   
You added xfrm netlink support to libipsec?

If not, the only thing which should get in the way is that there
are two key managers registered but that should "just work" :)

Re: automatic keying works! Re: off by one error in 3des cbc keying

[kuznet]

Hello!

> If not, the only thing which should get in the way is that there
> are two key managers registered but that should "just work" :)

At the moment km_acquire stops after the first manager accepts the acquisition.
Both of them always accept, so that guy how stands first in the list,
wins, another sees nothing.

Alexey

Re: automatic keying works! Re: off by one error in 3des cbc keying

[bert hubert]

On Mon, Nov 18, 2002 at 12:10:47PM -0800, David S. Miller wrote:

>    Yes, their interaction is still... mmm... not polished.

I love the way you say this :-)

>    Build both xfrm_user and af_key as modules and load only one for now.
>    
> You added xfrm netlink support to libipsec?
> 
> If not, the only thing which should get in the way is that there
> are two key managers registered but that should "just work" :)

It does not, Alexey is right. Without CONFIG_XFRM_USER, racoon works again.
Would you perhaps want to explain what CONFIG_XFRM_USER is going to be like?
Netlink instead of PFKEY, but other notable things?

Regards,

bert

-- 
http://www.PowerDNS.com          Versatile DNS Software & Services
http://lartc.org           Linux Advanced Routing & Traffic Control HOWTO

Re: automatic keying works! Re: off by one error in 3des cbc keying

[David S. Miller]

   From: bert hubert <ahu@ds9a.nl>
   Date: Mon, 18 Nov 2002 21:22:29 +0100

   Would you perhaps want to explain what CONFIG_XFRM_USER is going to be like?
   Netlink instead of PFKEY, but other notable things?

What you see in the code is what it will be like :-)

The only really mentionable thing is that when we notice that
PFKEY side has shit semantics, we will make netlink side saner :)

The only immediate difference is that with table dump operations
netlink queues where PFKEY does not.

Re: automatic keying works! Re: off by one error in 3des cbc keying

[David S. Miller]

   From: kuznet@ms2.inr.ac.ru
   Date: Mon, 18 Nov 2002 23:20:13 +0300 (MSK)
   
   At the moment km_acquire stops after the first manager accepts the acquisition.
   Both of them always accept, so that guy how stands first in the list,
   wins, another sees nothing.

Crap, indeed.

It should just keep sending to all key managers, right?

Re: automatic keying works! Re: off by one error in 3des cbc keying

[kuznet]

Hello!

> It should just keep sending to all key managers, right?

Just now no choice.

I repaired af_key to return error when nobody is registered to get acquires.
(the patch is enclosed. NOT TESTED!) If you can do the same with xfrm_user,
we can be more clever.

Bert, could you help woth testing? The patch adds timeing out policies.
To test this it is necessary to configure racoon on one end as "passive",
in this case it should update policy on demand and delete them in time.

Alexey




===== include/net/xfrm.h 1.9 vs edited =====
--- 1.9/include/net/xfrm.h	Thu Nov 14 20:30:23 2002
+++ edited/include/net/xfrm.h	Sat Nov 16 12:29:57 2002
@@ -195,6 +195,7 @@
 	/* This lock only affects elements except for entry. */
 	rwlock_t		lock;
 	atomic_t		refcnt;
+	struct timer_list	timer;
 
 	u32			priority;
 	u32			index;
===== net/netsyms.c 1.37 vs edited =====
--- 1.37/net/netsyms.c	Mon Nov 11 12:03:55 2002
+++ edited/net/netsyms.c	Sat Nov 16 10:29:42 2002
@@ -283,6 +283,7 @@
 EXPORT_SYMBOL(dlci_ioctl_hook);
 #endif
 
+EXPORT_SYMBOL(km_waitq);
 EXPORT_SYMBOL(xfrm_cfg_sem);
 EXPORT_SYMBOL(xfrm_policy_alloc);
 EXPORT_SYMBOL(__xfrm_policy_destroy);
===== net/ipv4/xfrm_policy.c 1.10 vs edited =====
--- 1.10/net/ipv4/xfrm_policy.c	Mon Nov 11 12:03:55 2002
+++ edited/net/ipv4/xfrm_policy.c	Sat Nov 16 12:34:33 2002
@@ -204,6 +204,50 @@
 		__MOD_DEC_USE_COUNT(type->owner);
 }
 
+static inline unsigned long make_jiffies(long secs)
+{
+	if (secs >= (MAX_SCHEDULE_TIMEOUT-1)/HZ)
+		return MAX_SCHEDULE_TIMEOUT-1;
+	else
+	        return secs*HZ;
+}
+
+static void xfrm_policy_timer(unsigned long data)
+{
+	struct xfrm_policy *xp = (struct xfrm_policy*)data;
+	unsigned long now = (unsigned long)xtime.tv_sec;
+	long next = LONG_MAX;
+
+	if (xp->dead)
+		goto out;
+
+	if (xp->lft.hard_add_expires_seconds) {
+		long tmo = xp->lft.hard_add_expires_seconds +
+			xp->curlft.add_time - now;
+		if (tmo <= 0)
+			goto expired;
+		if (tmo < next)
+			next = tmo;
+	}
+	if (next != LONG_MAX &&
+	    !mod_timer(&xp->timer, jiffies + make_jiffies(next)))
+		atomic_inc(&xp->refcnt);
+
+out:
+	xfrm_pol_put(xp);
+	return;
+
+expired:
+	xfrm_pol_put(xp);
+
+	/* Not 100% correct. id can be recycled in theory */
+	xp = xfrm_policy_byid(0, xp->index, 1);
+	if (xp) {
+		xfrm_policy_kill(xp);
+		xfrm_pol_put(xp);
+	}
+}
+
 
 /* Allocate xfrm_policy. Not used here, it is supposed to be used by pfkeyv2
  * SPD calls.
@@ -219,6 +263,9 @@
 		memset(policy, 0, sizeof(struct xfrm_policy));
 		atomic_set(&policy->refcnt, 1);
 		policy->lock = RW_LOCK_UNLOCKED;
+		init_timer(&policy->timer);
+		policy->timer.data = (unsigned long)policy;
+		policy->timer.function = xfrm_policy_timer;
 	}
 	return policy;
 }
@@ -233,6 +280,9 @@
 	if (policy->bundles)
 		BUG();
 
+	if (del_timer(&policy->timer))
+		BUG();
+
 	kfree(policy);
 }
 
@@ -255,6 +305,9 @@
 		dst_free(dst);
 	}
 
+	if (del_timer(&policy->timer))
+		atomic_dec(&policy->refcnt);
+
 out:
 	write_unlock_bh(&policy->lock);
 }
@@ -302,6 +355,9 @@
 	policy->index = pol ? pol->index : xfrm_gen_index(dir);
 	policy->curlft.add_time = (unsigned long)xtime.tv_sec;
 	policy->curlft.use_time = 0;
+	if (policy->lft.hard_add_expires_seconds &&
+	    !mod_timer(&policy->timer, jiffies + HZ))
+		atomic_inc(&policy->refcnt);
 	write_unlock_bh(&xfrm_policy_lock);
 
 	if (pol) {
@@ -380,7 +436,7 @@
 	int count = 0;
 	int error = 0;
 
-	read_lock(&xfrm_policy_lock);
+	read_lock_bh(&xfrm_policy_lock);
 	for (dir = 0; dir < 2*XFRM_POLICY_MAX; dir++) {
 		for (xp = xfrm_policy_list[dir]; xp; xp = xp->next)
 			count++;
@@ -400,7 +456,7 @@
 	}
 
 out:
-	read_unlock(&xfrm_policy_lock);
+	read_unlock_bh(&xfrm_policy_lock);
 	return error;
 }
 
@@ -411,7 +467,7 @@
 {
 	struct xfrm_policy *pol;
 
-	read_lock(&xfrm_policy_lock);
+	read_lock_bh(&xfrm_policy_lock);
 	for (pol = xfrm_policy_list[dir]; pol; pol = pol->next) {
 		struct xfrm_selector *sel = &pol->selector;
 
@@ -420,7 +476,7 @@
 			break;
 		}
 	}
-	read_unlock(&xfrm_policy_lock);
+	read_unlock_bh(&xfrm_policy_lock);
 	return pol;
 }
 
@@ -428,14 +484,14 @@
 {
 	struct xfrm_policy *pol;
 
-	read_lock(&xfrm_policy_lock);
+	read_lock_bh(&xfrm_policy_lock);
 	if ((pol = sk->policy[dir]) != NULL) {
 		if (xfrm4_selector_match(&pol->selector, fl))
 			atomic_inc(&pol->refcnt);
 		else
 			pol = NULL;
 	}
-	read_unlock(&xfrm_policy_lock);
+	read_unlock_bh(&xfrm_policy_lock);
 	return pol;
 }
 
@@ -727,8 +783,7 @@
 			return 0;
 	}
 
-	if (!policy->curlft.use_time)
-		policy->curlft.use_time = (unsigned long)xtime.tv_sec;
+	policy->curlft.use_time = (unsigned long)xtime.tv_sec;
 
 	switch (policy->action) {
 	case XFRM_POLICY_BLOCK:
@@ -936,8 +991,7 @@
 	if (!pol)
 		return 1;
 
-	if (!pol->curlft.use_time)
-		pol->curlft.use_time = (unsigned long)xtime.tv_sec;
+	pol->curlft.use_time = (unsigned long)xtime.tv_sec;
 
 	if (pol->action == XFRM_POLICY_ALLOW) {
 		if (pol->xfrm_nr != 0) {
===== net/ipv4/xfrm_state.c 1.7 vs edited =====
--- 1.7/net/ipv4/xfrm_state.c	Thu Nov 14 19:52:45 2002
+++ edited/net/ipv4/xfrm_state.c	Sat Nov 16 12:34:32 2002
@@ -28,7 +28,7 @@
 
 static void __xfrm_state_delete(struct xfrm_state *x);
 
-unsigned long make_jiffies(long secs)
+static inline unsigned long make_jiffies(long secs)
 {
 	if (secs >= (MAX_SCHEDULE_TIMEOUT-1)/HZ)
 		return MAX_SCHEDULE_TIMEOUT-1;
@@ -92,7 +92,14 @@
 	goto out;
 
 expired:
-	km_expired(x);
+	if (x->km.state == XFRM_STATE_ACQ && x->id.spi == 0) {
+		x->km.state = XFRM_STATE_EXPIRED;
+		wake_up(&km_waitq);
+		next = 2;
+		goto resched;
+	}
+	if (x->id.spi != 0)
+		km_expired(x);
 	__xfrm_state_delete(x);
 
 out:
@@ -298,11 +305,13 @@
 			x->km.state = XFRM_STATE_DEAD;
 			xfrm_state_put(x);
 			x = NULL;
+			error = 1;
 		}
 	}
 	spin_unlock_bh(&xfrm_state_lock);
 	if (!x)
-		*err = acquire_in_progress ? -EAGAIN : -ENOMEM;
+		*err = acquire_in_progress ? -EAGAIN :
+			(error ? -ESRCH : -ENOMEM);
 	return x;
 }
 
@@ -612,6 +621,7 @@
 	list_for_each_entry(km, &xfrm_km_list, list)
 		km->notify(x, 1);
 	read_unlock(&xfrm_km_lock);
+	wake_up(&km_waitq);
 }
 
 int km_query(struct xfrm_state *x, struct xfrm_tmpl *t, struct xfrm_policy *pol)
===== net/key/af_key.c 1.9 vs edited =====
--- 1.9/net/key/af_key.c	Thu Nov 14 19:52:45 2002
+++ edited/net/key/af_key.c	Sat Nov 16 11:41:37 2002
@@ -196,9 +196,11 @@
 	return 0;
 }
 
-static void pfkey_broadcast_one(struct sk_buff *skb, struct sk_buff **skb2,
-				int allocation, struct sock *sk)
+static int pfkey_broadcast_one(struct sk_buff *skb, struct sk_buff **skb2,
+			       int allocation, struct sock *sk)
 {
+	int err = -ENOBUFS;
+
 	sock_hold(sk);
 	if (*skb2 == NULL) {
 		if (atomic_read(&skb->users) != 1) {
@@ -215,9 +217,11 @@
 			skb_queue_tail(&sk->receive_queue, *skb2);
 			sk->data_ready(sk, (*skb2)->len);
 			*skb2 = NULL;
+			err = 0;
 		}
 	}
 	sock_put(sk);
+	return err;
 }
 
 /* Send SKB to all pfkey sockets matching selected criteria.  */
@@ -225,21 +229,23 @@
 #define BROADCAST_ONE		1
 #define BROADCAST_REGISTERED	2
 #define BROADCAST_PROMISC_ONLY	4
-static void pfkey_broadcast(struct sk_buff *skb, int allocation,
-			    int broadcast_flags, struct sock *one_sk)
+static int pfkey_broadcast(struct sk_buff *skb, int allocation,
+			   int broadcast_flags, struct sock *one_sk)
 {
 	struct sock *sk;
 	struct sk_buff *skb2 = NULL;
+	int err = -ESRCH;
 
 	/* XXX Do we need something like netlink_overrun?  I think
 	 * XXX PF_KEY socket apps will not mind current behavior.
 	 */
 	if (!skb)
-		return;
+		return -ENOMEM;
 
 	pfkey_lock_table();
 	for (sk = pfkey_table; sk; sk = sk->next) {
 		struct pfkey_opt *pfk = pfkey_sk(sk);
+		int err2;
 
 		/* Yes, it means that if you are meant to receive this
 		 * pfkey message you receive it twice as promiscuous
@@ -261,16 +267,22 @@
 				continue;
 		}
 
-		pfkey_broadcast_one(skb, &skb2, allocation, sk);
+		err2 = pfkey_broadcast_one(skb, &skb2, allocation, sk);
+
+		/* Error is cleare after succecful sending to at least one
+		 * registered KM */
+		if ((broadcast_flags & BROADCAST_REGISTERED) && err)
+			err = err2;
 	}
 	pfkey_unlock_table();
 
 	if (one_sk != NULL)
-		pfkey_broadcast_one(skb, &skb2, allocation, one_sk);
+		err = pfkey_broadcast_one(skb, &skb2, allocation, one_sk);
 
 	if (skb2)
 		kfree_skb(skb2);
 	kfree_skb(skb);
+	return err;
 }
 
 static inline void pfkey_hdr_dup(struct sadb_msg *new, struct sadb_msg *orig)
@@ -1101,8 +1113,12 @@
 	if (x == NULL)
 		return 0;
 
-	if (x->km.state == XFRM_STATE_ACQ)
-		xfrm_state_delete(x);
+	spin_lock_bh(&x->lock);
+	if (x->km.state == XFRM_STATE_ACQ) {
+		x->km.state = XFRM_STATE_ERROR;
+		wake_up(&km_waitq);
+	}
+	spin_unlock_bh(&x->lock);
 	xfrm_state_put(x);
 	return 0;
 }
@@ -1783,14 +1799,10 @@
 	struct sk_buff *out_skb;
 	struct sadb_msg *out_hdr;
 
-	if (!ext_hdrs[SADB_X_EXT_POLICY-1])
+	if ((pol = ext_hdrs[SADB_X_EXT_POLICY-1]) == NULL)
 		return -EINVAL;
 
-	pol = ext_hdrs[SADB_X_EXT_POLICY-1];
-	if (!pol->sadb_x_policy_dir || pol->sadb_x_policy_dir >= IPSEC_DIR_MAX)
-		return -EINVAL;
-
-	xp = xfrm_policy_byid(pol->sadb_x_policy_dir-1, pol->sadb_x_policy_id,
+	xp = xfrm_policy_byid(0, pol->sadb_x_policy_id,
 			      hdr->sadb_msg_type == SADB_X_SPDDELETE2);
 	if (xp == NULL)
 		return -ENOENT;
@@ -2142,9 +2154,7 @@
 	else if (x->id.proto == IPPROTO_ESP)
 		dump_esp_combs(skb, t);
 
-	pfkey_broadcast(skb, GFP_ATOMIC, BROADCAST_REGISTERED, NULL);
-
-	return 0;
+	return pfkey_broadcast(skb, GFP_ATOMIC, BROADCAST_REGISTERED, NULL);
 }
 
 static struct xfrm_policy *pfkey_compile_policy(int opt, u8 *data, int len, int *dir)

Re: automatic keying works! Re: off by one error in 3des cbc keying

[bert hubert]

On Mon, Nov 18, 2002 at 11:32:12PM +0300, kuznet@ms2.inr.ac.ru wrote:

> Bert, could you help woth testing? The patch adds timeing out policies.
> To test this it is necessary to configure racoon on one end as "passive",
> in this case it should update policy on demand and delete them in time.

Works. This also needs 'generate_policy on;', by the way. Racoon does not
however log if a policy times out. It normally does not because the remote
racoon keeps renewing the SA, which also renews the SP.

If the remote recoon is STOPped, the passive side nicely times out the SP,
although it does not tell the user this.

Wonderful stuff, I'm starting to like racoon a bit better.

2002-11-18 22:18:15: INFO: isakmp.c:890:isakmp_ph1begin_r(): respond new
phase 1 negotiation: 10.0.0.11[500]<=>10.0.0.216[500]
2002-11-18 22:18:15: INFO: isakmp.c:895:isakmp_ph1begin_r(): begin
Aggressive mode.
2002-11-18 22:18:16: INFO: isakmp.c:2417:log_ph1established(): ISAKMP-SA
established 10.0.0.11[500]-10.0.0.216[500]
spi:d65a99e9df6d6eea:4e21da098172dfda
2002-11-18 22:18:16: INFO: isakmp.c:1045:isakmp_ph2begin_r(): respond new
phase 2 negotiation: 10.0.0.11[0]<=>10.0.0.216[0]
2002-11-18 22:18:16: INFO: isakmp_quick.c:2014:get_proposal_r(): no policy
found, try to generate the policy : 10.0.0.216/32[0] 10.0.0.11/32[0]
proto=any dir=in2002-11-18 22:18:16: INFO: pfkey.c:1106:pk_recvupdate():
IPsec-SA established: ESP/Transport 10.0.0.216->10.0.0.11
spi=230551900(0xdbdf15c)
2002-11-18 22:18:16: INFO: pfkey.c:1318:pk_recvadd(): IPsec-SA established:
ESP/Transport 10.0.0.11->10.0.0.216 spi=264801187(0xfc88ba3)

2002-11-18 22:19:52: INFO: pfkey.c:1364:pk_recvexpire(): IPsec-SA expired:
ESP/Transport 10.0.0.216->10.0.0.11 spi=230551900(0xdbdf15c)
2002-11-18 22:19:52: INFO: pfkey.c:1364:pk_recvexpire(): IPsec-SA expired:
ESP/Transport 10.0.0.11->10.0.0.216 spi=264801187(0xfc88ba3)
2002-11-18 22:19:52: INFO: isakmp.c:1045:isakmp_ph2begin_r(): respond new
phase 2 negotiation: 10.0.0.11[0]<=>10.0.0.216[0]
2002-11-18 22:19:52: INFO: isakmp_quick.c:2014:get_proposal_r(): no policy
found, try to generate the policy : 10.0.0.216/32[0] 10.0.0.11/32[0]
proto=any dir=in2002-11-18 22:19:52: INFO: pfkey.c:1106:pk_recvupdate():
IPsec-SA established: ESP/Transport 10.0.0.216->10.0.0.11
spi=127223206(0x79545a6)
2002-11-18 22:19:52: INFO: pfkey.c:1318:pk_recvadd(): IPsec-SA established:
ESP/Transport 10.0.0.11->10.0.0.216 spi=140990312(0x8675768)
2002-11-18 22:20:16: INFO: pfkey.c:1364:pk_recvexpire(): IPsec-SA expired:
ESP/Transport 10.0.0.216->10.0.0.11 spi=230551900(0xdbdf15c)
2002-11-18 22:20:16: INFO: pfkey.c:1364:pk_recvexpire(): IPsec-SA expired:
ESP/Transport 10.0.0.11->10.0.0.216 spi=264801187(0xfc88ba3)



-- 
http://www.PowerDNS.com          Versatile DNS Software & Services
http://lartc.org           Linux Advanced Routing & Traffic Control HOWTO

Re: automatic keying works! Re: off by one error in 3des cbc keying

[David S. Miller]

   From: kuznet@ms2.inr.ac.ru
   Date: Mon, 18 Nov 2002 23:32:12 +0300 (MSK)

   I repaired af_key to return error when nobody is registered to get acquires.
   (the patch is enclosed. NOT TESTED!) If you can do the same with xfrm_user,
   we can be more clever.

I applied this patch since Bert tested it :-)  I will take care of
xfrm_user's acquire handling right now.