Re: [Ipsec-tools-devel] more phase 2 reinitiation problems

[Krzysztof Oledzki <olel@xxxxxx>]

On Sat, 12 Mar 2005, Wilfried Weissmann wrote:

> Hi,
Hi,

> The rekeying also fails with debian's racoon 0.5 <=<internet>=> WinXP (see 
> Problem with Linux-2.6.x+ipsec-tools-0.4/0.5-rc1/0.5rc2 & Linksys BEFSX41). I 
> am running the linux 2.6.11.2 kernel with IPSec connection tracking patches. 
> The configuration file and the log is attached.
> I also have problems between 2 linux boxes in the LAN but the other box is 
> still running racoon 0.3.3 which might be the cause of the LAN trouble.

Please giva a try try the 2.6.12-rc1 kernel. I have just upgraded my 
system to this kernel and it seems that IPSec is able to survive first 
rekeying. Unfortunately only a first one - after a while (just before 
removing old expired keys) one of newly generated keys get removed and new 
traffic racoon generates two news keys. OK, it is _much_ better but 
still... not perfect.

My log with some comments:

Mar 18 11:47:36 gw1 racoon: INFO: @(#)ipsec-tools 0.5 
(http://ipsec-tools.sourceforge.net)
Mar 18 11:47:36 gw1 racoon: INFO: @(#)This product linked OpenSSL 0.9.7e 25 Oct 
2004 (http://www.openssl.org/)
Mar 18 11:47:36 gw1 racoon: INFO: XXX.XX.XX.XX[500] used as isakmp port (fd=7)
Mar 18 11:47:36 gw1 racoon: INFO: XXX.XX.XX.XX[500] used for NAT-T
Mar 18 11:48:09 gw1 racoon: INFO: IPsec-SA request for YY.YY.YYY.YYY queued due 
to no phase1 found.
Mar 18 11:48:09 gw1 racoon: INFO: initiate new phase 1 negotiation: 
XXX.XX.XX.XX[500]<=>YY.YY.YYY.YYY[500]
Mar 18 11:48:09 gw1 racoon: INFO: begin Identity Protection mode.
Mar 18 11:48:19 gw1 racoon: INFO: ISAKMP-SA established 
XXX.XX.XX.XX[500]-YY.YY.YYY.YYY[500] spi:a2acc8844df9591b:29621f95bfa3 8d45
Mar 18 11:48:20 gw1 racoon: INFO: initiate new phase 2 negotiation: 
XXX.XX.XX.XX[0]<=>YY.YY.YYY.YYY[0]
Mar 18 11:48:23 gw1 racoon: WARNING: attribute has been modified.
Mar 18 11:48:23 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
YY.YY.YYY.YYY->XXX.XX.XX.XX spi=172047746(0xa413d82)
Mar 18 11:48:23 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel 
XXX.XX.XX.XX->YY.YY.YYY.YYY spi=993793125(0x3b3c1465)
OK. Kernel noticed some traffic and racooon generates new keys.

Mar 18 12:36:23 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel YY.YY.YYY.YYY->XXX.XX.XX.XX spi=172047746(0xa413d82)
Mar 18 12:36:23 gw1 racoon: INFO: initiate new phase 2 negotiation: XXX.XX.XX.XX[0]<=>YY.YY.YYY.YYY[0]
Mar 18 12:36:23 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel XXX.XX.XX.XX->YY.YY.YYY.YYY spi=993793125(0x3b3c1465)
Mar 18 12:36:27 gw1 racoon: WARNING: attribute has been modified.
Mar 18 12:36:27 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel YY.YY.YYY.YYY->XXX.XX.XX.XX spi=31676947(0x1e35a13)
Mar 18 12:36:27 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel XXX.XX.XX.XX->YY.YY.YYY.YYY spi=677995285(0x28696315)
OK! :) Old keys have just expired and racoon generates new ones. No 
infinite loop! ;-) Yes!

Mar 18 12:48:18 gw1 racoon: INFO: purged IPsec-SA proto_id=ESP spi=677995285.
But what is this? We have just generated new key with spi=677995285. Why 
it is now purged?

Mar 18 12:48:19 gw1 racoon: INFO: purged ISAKMP-SA proto_id=ISAKMP 
spi=a2acc8844df9591b:29621f95bfa38d45.
Mar 18 12:48:20 gw1 racoon: INFO: ISAKMP-SA deleted 
XXX.XX.XX.XX[500]-YY.YY.YYY.YYY[500] spi:a2acc8844df9591b:29621f95bfa38d45

Mar 18 12:48:20 gw1 racoon: ERROR: unknown Informational exchange received.
Mar 18 12:48:23 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel 
YY.YY.YYY.YYY->XXX.XX.XX.XX spi=172047746(0xa413d82)
Mar 18 12:48:23 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel 
XXX.XX.XX.XX->YY.YY.YYY.YYY spi=993793125(0x3b3c1465)
OK. Oldest keys now really expired, they are removed.

Mar 18 12:51:31 gw1 racoon: INFO: IPsec-SA request for YY.YY.YYY.YYY queued due to no phase1 found.
Mar 18 12:51:31 gw1 racoon: INFO: initiate new phase 1 negotiation: XXX.XX.XX.XX[500]<=>YY.YY.YYY.YYY[500]
Mar 18 12:51:31 gw1 racoon: INFO: begin Identity Protection mode.
Mar 18 12:51:40 gw1 racoon: INFO: ISAKMP-SA established XXX.XX.XX.XX[500]-YY.YY.YYY.YYY[500] spi:8f29dd5a50fd83dd:ae84b9eee139 89e5
Mar 18 12:51:41 gw1 racoon: INFO: initiate new phase 2 negotiation: XXX.XX.XX.XX[0]<=>YY.YY.YYY.YYY[0]
Mar 18 12:51:43 gw1 racoon: WARNING: attribute has been modified.
Mar 18 12:51:43 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel YY.YY.YYY.YYY->XXX.XX.XX.XX spi=140244397(0x85bf5ad)
Mar 18 12:51:43 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel XXX.XX.XX.XX->YY.YY.YYY.YYY spi=3173924318(0xbd2e3dde)
Kernel noticed some traffic (again), there is no known key for encription 
(it was pugred @12:48:18), racooon generates new keys.

Mar 18 13:24:27 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel YY.YY.YYY.YYY->XXX.XX.XX.XX spi=31676947(0x1e35a13)
Mar 18 13:36:27 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel YY.YY.YYY.YYY->XXX.XX.XX.XX spi=31676947(0x1e35a13)
Mar 18 13:39:43 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel YY.YY.YYY.YYY->XXX.XX.XX.XX spi=140244397(0x85bf5ad) 
Old keys get expired. BTW: Why key with spi=31676947 is expired twice?
(...)

Best regards,

                        Krzysztof Olędzki