Bug 4952

Summary: IPSec incompabilty. Linux kernel waits to long to start using new SA for outbound traffic.
Product: Networking Reporter: Krzysztof Oledzki (ole)
Component: OtherAssignee: Arnaldo Carvalho de Melo (acme)
Status: CLOSED CODE_FIX    
Severity: high    
Priority: P2    
Hardware: i386   
OS: Linux   
Kernel Version: 2.6.12.3 Subsystem:
Regression: --- Bisected commit-id:

Description Krzysztof Oledzki 2005-07-27 14:31:13 UTC
Problem Description:

Linux kernel waits to long to start using new SA for outbound traffic. This is
wrong, and creates real problems when peer stops supporting old SA faster than
it should.

Steps to reproduce:

I started pinging over IPSec tunnel. Racoon created the pair of IPsec-SA:

Jul 27 21:18:06 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel
YYY.YY.YYY.YYY[0]->XXX.XX.XX.XXX[0] spi=209244
158(0xc78cffe)
Jul 27 21:18:06 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel
XXX.XX.XX.XXX[0]->YYY.YY.YYY.YYY[0] spi=282443
5949(0xa85978ed)

Everything worked fine:

2005-07-27 21:18:24.451903 IP XXX.XX.XX.XXX > YYY.YY.YYY.YYY:
ESP(spi=0xa85978ed,seq=0x1), length 116
2005-07-27 21:18:24.486625 IP YYY.YY.YYY.YYY > XXX.XX.XX.XXX:
ESP(spi=0x0c78cffe,seq=0x1), length 116
2005-07-27 21:18:25.453360 IP XXX.XX.XX.XXX > YYY.YY.YYY.YYY:
ESP(spi=0xa85978ed,seq=0x2), length 116
2005-07-27 21:18:25.482251 IP YYY.YY.YYY.YYY > XXX.XX.XX.XXX:
ESP(spi=0x0c78cffe,seq=0x2), length 116

After ~2880s keys expired:

Jul 27 22:06:06 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel
YYY.YY.YYY.YYY[0]->XXX.XX.XX.XXX[0] spi=209244158(
0xc78cffe)
Jul 27 22:06:06 gw1 racoon: INFO: initiate new phase 2 negotiation:
XXX.XX.XX.XXX[0]<=>YYY.YY.YYY.YYY[0]
Jul 27 22:06:06 gw1 racoon: INFO: IPsec-SA expired: ESP/Tunnel
XXX.XX.XX.XXX[0]->YYY.YY.YYY.YYY[0] spi=2824435949
(0xa85978ed)

Racoon negotiated new SA:

Jul 27 22:06:10 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel
YYY.YY.YYY.YYY[0]->XXX.XX.XX.XXX[0] spi=150510
678(0x8f89c56)
Jul 27 22:06:10 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel
XXX.XX.XX.XXX[0]->YYY.YY.YYY.YYY[0] spi=360860
9595(0xd717033b)

Linux kernel was still using old SA (spi=0xa85978ed), peer switched into new SA
(spi=0x08f89c56)

2005-07-27 22:06:10.634929 IP XXX.XX.XX.XXX > YYY.YY.YYY.YYY:
ESP(spi=0xa85978ed,seq=0xb2c), length 116
2005-07-27 22:06:10.987012 IP YYY.YY.YYY.YYY > XXX.XX.XX.XXX:
ESP(spi=0x0c78cffe,seq=0xb28), length 116
2005-07-27 22:06:10.992134 IP YYY.YY.YYY.YYY > XXX.XX.XX.XXX:
ESP(spi=0x0c78cffe,seq=0xb29), length 116
2005-07-27 22:06:10.997382 IP YYY.YY.YYY.YYY > XXX.XX.XX.XXX:
ESP(spi=0x0c78cffe,seq=0xb2a), length 116
2005-07-27 22:06:11.636814 IP XXX.XX.XX.XXX > YYY.YY.YYY.YYY:
ESP(spi=0xa85978ed,seq=0xb2d), length 116
2005-07-27 22:06:11.665220 IP YYY.YY.YYY.YYY > XXX.XX.XX.XXX:
ESP(spi=0x0c78cffe,seq=0xb2b), length 116
2005-07-27 22:06:12.638681 IP XXX.XX.XX.XXX > YYY.YY.YYY.YYY:
ESP(spi=0xa85978ed,seq=0xb2e), length 116
2005-07-27 22:06:12.666848 IP YYY.YY.YYY.YYY > XXX.XX.XX.XXX:
ESP(spi=0x08f89c56,seq=0x1), length 116
2005-07-27 22:06:13.640549 IP XXX.XX.XX.XXX > YYY.YY.YYY.YYY:
ESP(spi=0xa85978ed,seq=0xb2f), length 116
2005-07-27 22:06:13.673727 IP YYY.YY.YYY.YYY > XXX.XX.XX.XXX:
ESP(spi=0x08f89c56,seq=0x2), length 116
2005-07-27 22:06:14.642430 IP XXX.XX.XX.XXX > YYY.YY.YYY.YYY:
ESP(spi=0xa85978ed,seq=0xb30), length 116
2005-07-27 22:06:14.670360 IP YYY.YY.YYY.YYY > XXX.XX.XX.XXX:
ESP(spi=0x08f89c56,seq=0x3), length 116
2005-07-27 22:06:15.643304 IP XXX.XX.XX.XXX > YYY.YY.YYY.YYY:
ESP(spi=0xa85978ed,seq=0xb31), length 116
2005-07-27 22:06:15.670616 IP YYY.YY.YYY.YYY > XXX.XX.XX.XXX:
ESP(spi=0x08f89c56,seq=0x4), length 116

IPSec peer initiated new key renegotiation:
Jul 27 22:06:52 gw1 racoon: INFO: respond new phase 1 negotiation:
XXX.XX.XX.XXX[500]<=>YYY.YY.YYY.YYY[500]
Jul 27 22:06:52 gw1 racoon: INFO: begin Identity Protection mode.
Jul 27 22:06:58 gw1 racoon: INFO: ISAKMP-SA established
XXX.XX.XX.XXX[500]-YYY.YY.YYY.YYY[500] spi:aa103d22d3e480
b3:1b470506cfc95a33
Jul 27 22:07:02 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel
YYY.YY.YYY.YYY[0]->XXX.XX.XX.XXX[0] spi=383529
4(0x3a859e)
Jul 27 22:07:02 gw1 racoon: INFO: IPsec-SA established: ESP/Tunnel
XXX.XX.XX.XXX[0]->YYY.YY.YYY.YYY[0] spi=299727
8258(0xb2a6d632)

Linux was still using old SA(spi=0xa85978ed), peer stopped accepting this SA:

2005-07-27 22:07:03.691323 IP XXX.XX.XX.XXX > YYY.YY.YYY.YYY:
ESP(spi=0xa85978ed,seq=0xb61), length 116
2005-07-27 22:07:03.718660 IP YYY.YY.YYY.YYY > XXX.XX.XX.XXX:
ESP(spi=0x08f89c56,seq=0x34), length 116
2005-07-27 22:07:04.692194 IP XXX.XX.XX.XXX > YYY.YY.YYY.YYY:
ESP(spi=0xa85978ed,seq=0xb62), length 116
2005-07-27 22:07:05.692064 IP XXX.XX.XX.XXX > YYY.YY.YYY.YYY:
ESP(spi=0xa85978ed,seq=0xb63), length 116
2005-07-27 22:07:06.691950 IP XXX.XX.XX.XXX > YYY.YY.YYY.YYY:
ESP(spi=0xa85978ed,seq=0xb64), length 116
2005-07-27 22:07:07.691825 IP XXX.XX.XX.XXX > YYY.YY.YYY.YYY:
ESP(spi=0xa85978ed,seq=0xb65), length 116

After 5 minutes linux kernel started using newest SA, ping started working again:

05-07-27 22:12:10.697040 IP XXX.XX.XX.XXX > YYY.YY.YYY.YYY:
ESP(spi=0xa85978ed,seq=0xc94), length 116
2005-07-27 22:12:11.697012 IP XXX.XX.XX.XXX > YYY.YY.YYY.YYY:
ESP(spi=0xb2a6d632,seq=0x1), length 116
2005-07-27 22:12:11.724977 IP YYY.YY.YYY.YYY > XXX.XX.XX.XXX:
ESP(spi=0x003a859e,seq=0x1), length 116
2005-07-27 22:12:12.697803 IP XXX.XX.XX.XXX > YYY.YY.YYY.YYY:
ESP(spi=0xb2a6d632,seq=0x2), length 116
2005-07-27 22:12:12.726600 IP YYY.YY.YYY.YYY > XXX.XX.XX.XXX:
ESP(spi=0x003a859e,seq=0x2), length 116
Comment 1 Krzysztof Oledzki 2006-01-30 16:33:05 UTC
Fixed in 2.6.14.5 and 2.6.15. Thank you.