Problem with Linux-2.6.x+ipsec-tools & Linksys BEFSX41

[Krzysztof Oledzki <olel@xxxxxx>]

Hello,

I have problem with IPSec between 2.6.x Linux native IPsec and Linksys BEFSX41 
router. Everything works fine until key renegotiation. Routers are able to 
exchange keys & setup IPSec connection:

Feb 11 12:29:16 gw1 racoon: INFO: @(#)ipsec-tools 0.4 
(http://ipsec-tools.sourceforge.net)
Feb 11 12:29:16 gw1 racoon: INFO: @(#)This product linked OpenSSL 0.9.7e 25 Oct 
2004 (http://www.openssl.org/)
Feb 11 12:29:16 gw1 racoon: INFO: BBB.BB.BB.BB[500] used as isakmp port (fd=7)
Feb 11 12:29:16 gw1 racoon: INFO: IPsec-SA request for AA.AA.AAA.AAA queued due 
to no phase1 found.
Feb 11 12:29:16 gw1 racoon: INFO: initiate new phase 1 negotiation: 
BBB.BB.BB.BB[500]<=>AA.AA.AAA.AAA[500]
Feb 11 12:29:16 gw1 racoon: INFO: begin Identity Protection mode.
Feb 11 12:29:19 gw1 racoon: INFO: ISAKMP-SA established 
BBB.BB.BB.BB[500]-AA.AA.AAA.AAA[500] spi:5e657591032b23ce:3f6df2be5d610c99
Feb 11 12:29:20 gw1 racoon: INFO: initiate new phase 2 negotiation: 
BBB.BB.BB.BB[0]<=>AA.AA.AAA.AAA[0]
Feb 11 12:29:22 gw1 racoon: WARNING: attribute has been modified.
Feb 11 12:29:22 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
AA.AA.AAA.AAA->BBB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 12:29:22 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
BBB.BB.BB.BB->AA.AA.AAA.AAA spi=1042970307(0x3e2a76c3)

After 48 minutes (hard limit is 3600s and soft 2880s) racoon starts negotiating 
new keys and then tunnel stops working.

Feb 11 13:17:22 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:17:22 gw1 racoon: INFO: IPsec-SA request for AA.AA.AAA.AAA queued due 
to no phase1 found.
Feb 11 13:17:22 gw1 racoon: INFO: initiate new phase 1 negotiation: 
BB.BB.BB.BB[500]<=>AA.AA.AAA.AAA[500]
Feb 11 13:17:22 gw1 racoon: INFO: begin Identity Protection mode.
Feb 11 13:17:22 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel 
BB.BB.BB.BB->AA.AA.AAA.AAA spi=1042970307(0x3e2a76c3)
Feb 11 13:17:31 gw1 racoon: INFO: ISAKMP-SA established 
BB.BB.BB.BB[500]-AA.AA.AAA.AAA[500] spi:14cb86caec437624:0c11453a860aa178
Feb 11 13:17:32 gw1 racoon: INFO: initiate new phase 2 negotiation: 
BB.BB.BB.BB[0]<=>AA.AA.AAA.AAA[0]
Feb 11 13:17:35 gw1 racoon: WARNING: attribute has been modified.
Feb 11 13:17:35 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:17:35 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
BB.BB.BB.BB->AA.AA.AAA.AAA spi=456046736(0x1b2eb890)
Feb 11 13:17:36 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:17:36 gw1 racoon: INFO: initiate new phase 2 negotiation: 
BB.BB.BB.BB[0]<=>AA.AA.AAA.AAA[0]
Feb 11 13:17:48 gw1 racoon: WARNING: attribute has been modified.
Feb 11 13:17:48 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:17:48 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
BB.BB.BB.BB->AA.AA.AAA.AAA spi=984883126(0x3ab41fb6)
Feb 11 13:17:49 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:17:49 gw1 racoon: INFO: initiate new phase 2 negotiation: 
BB.BB.BB.BB[0]<=>AA.AA.AAA.AAA[0]
Feb 11 13:17:50 gw1 racoon: WARNING: attribute has been modified.
Feb 11 13:17:50 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:17:50 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
BB.BB.BB.BB->AA.AA.AAA.AAA spi=2443714535(0x91a81fe7)
Feb 11 13:17:51 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:17:51 gw1 racoon: INFO: initiate new phase 2 negotiation: 
BB.BB.BB.BB[0]<=>AA.AA.AAA.AAA[0]
Feb 11 13:17:52 gw1 racoon: WARNING: attribute has been modified.
Feb 11 13:17:52 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:17:52 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
BB.BB.BB.BB->AA.AA.AAA.AAA spi=891474119(0x3522d0c7)
Feb 11 13:17:53 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:17:53 gw1 racoon: INFO: initiate new phase 2 negotiation: 
BB.BB.BB.BB[0]<=>AA.AA.AAA.AAA[0]
Feb 11 13:17:56 gw1 racoon: WARNING: attribute has been modified.
Feb 11 13:17:56 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:17:56 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
BB.BB.BB.BB->AA.AA.AAA.AAA spi=3294034757(0xc456fb45)
Feb 11 13:17:57 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:17:57 gw1 racoon: INFO: initiate new phase 2 negotiation: 
BB.BB.BB.BB[0]<=>AA.AA.AAA.AAA[0]
Feb 11 13:17:59 gw1 racoon: WARNING: attribute has been modified.
Feb 11 13:17:59 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:17:59 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
BB.BB.BB.BB->AA.AA.AAA.AAA spi=1251852702(0x4a9dc19e)
Feb 11 13:18:00 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:18:00 gw1 racoon: INFO: initiate new phase 2 negotiation: 
BB.BB.BB.BB[0]<=>AA.AA.AAA.AAA[0]
Feb 11 13:18:02 gw1 racoon: WARNING: attribute has been modified.
Feb 11 13:18:02 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:18:02 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
BB.BB.BB.BB->AA.AA.AAA.AAA spi=522496593(0x1f24aa51)
Feb 11 13:18:03 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:18:03 gw1 racoon: INFO: initiate new phase 2 negotiation: 
BB.BB.BB.BB[0]<=>AA.AA.AAA.AAA[0]
Feb 11 13:18:06 gw1 racoon: WARNING: attribute has been modified.
Feb 11 13:18:06 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:18:06 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
BB.BB.BB.BB->AA.AA.AAA.AAA spi=1163930963(0x45602d53)
Feb 11 13:18:07 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:18:07 gw1 racoon: INFO: initiate new phase 2 negotiation: 
BB.BB.BB.BB[0]<=>AA.AA.AAA.AAA[0]
Feb 11 13:18:08 gw1 racoon: WARNING: attribute has been modified.
Feb 11 13:18:08 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:18:08 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
BB.BB.BB.BB->AA.AA.AAA.AAA spi=3167100563(0xbcc61e93)
Feb 11 13:18:09 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:18:09 gw1 racoon: INFO: initiate new phase 2 negotiation: 
BB.BB.BB.BB[0]<=>AA.AA.AAA.AAA[0]
(...)
 <more messages like those>
(...)
Feb 11 13:23:46 gw1 racoon: ERROR: AA.AA.AAA.AAA give up to get IPsec-SA due to 
time up to wait.

and finally...

Feb 11 13:29:22 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel 
AA.AA.AAA.AAA->BB.BB.BB.BB spi=151969078(0x90edd36)
Feb 11 13:29:22 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel 
BB.BB.BB.BB->AA.AA.AAA.AAA spi=1042970307(0x3e2a76c3)

And then I need to restart reacoon.


I have already asked this question Ipsec-tools-devel ML but after some 
additional test it seems that this it may be a bug in IPsec implementatnio 
on Linux - this tunnel works just fine on FreeBSD 4.10 & both racoons from 
KAME & ipsec-tools package. I tested Linux 2.4.10, 2.4.11-rc (1,2,3 & 4) 
and finally 2.4.11 kernel, but this problem still exists.

As far as I understand linux IPSec code, when a SA's soft limit is reached 
kernel sends notification to userspace daemon (racoon for example) and 
asks it to get a new SA. I have changed expiration time to much smaller 
values (hard: 120s, soft: 96s) and found that "renegotiation loop" only 
exists in 96s-120s window. After 120s both SAs 
(AA.AA.AAA.AAA->BBB.BB.BB.BB & BBB.BB.BB.BB->AA.AA.AAA.AAA) are removed 
and then renegotiation loop stops. It is not clear to my why kernel tels 
racoon about SA expiration more than once and why racoon can't simply 
ignores additional messages?

Anyway, such behavior can also be sometimes observerd between my two Linux 
routers but it happend very, very rarely.

Best regards,


                    Krzysztof Olędzki