[Openswan Users]
Stuck with rekeying problem, initiated QM from Openswan
Steffen Becker
becker at informatik.uni-oldenburg.de
Thu May 19 10:10:02 CEST 2005
Hi,
I use Openswan 1.0.8 built into IPCop and Win XP SP 2 as client using
IPSec/L2TP. I got a nice running setting - besides one annoying problem:
In case of rekeying of the SA and if the rekeying is initiated by Openswan
it fails:
----------------------
17:57:33 pluto[16368] "WLAN"[2] 192.168.254.3 #6: IPsec SA established
18:53:03 pluto[16368] "WLAN"[2] 192.168.254.3 #7: initiating Quick Mode
RSASIG+ENCRYPT to replace #6
18:53:04 pluto[16368] "WLAN"[2] 192.168.254.3 #5: ignoring informational
payload, type INVALID_ID_INFORMATION
18:53:04 pluto[16368] "WLAN"[2] 192.168.254.3 #5: received and ignored
informational message
18:54:13 pluto[16368] "WLAN"[2] 192.168.254.3 #7: max number of
retransmissions (2) reached STATE_QUICK_I1
18:54:13 pluto[16368] "WLAN"[2] 192.168.254.3 #7: starting keying attempt 2
of at most 5
18:54:13 pluto[16368] "WLAN"[2] 192.168.254.3 #8: initiating Quick Mode
RSASIG+ENCRYPT to replace #7
18:54:13 pluto[16368] "WLAN"[2] 192.168.254.3 #5: ignoring informational
payload, type INVALID_ID_INFORMATION
18:54:13 pluto[16368] "WLAN"[2] 192.168.254.3 #5: received and ignored
informational message
18:55:23 pluto[16368] "WLAN"[2] 192.168.254.3 #8: max number of
retransmissions (2) reached STATE_QUICK_I1
18:55:23 pluto[16368] "WLAN"[2] 192.168.254.3 #8: starting keying attempt 3
of at most 5
18:55:23 pluto[16368] "WLAN"[2] 192.168.254.3 #9: initiating Quick Mode
RSASIG+ENCRYPT to replace #8
18:55:23 pluto[16368] "WLAN"[2] 192.168.254.3 #5: ignoring informational
payload, type INVALID_ID_INFORMATION
18:55:23 pluto[16368] "WLAN"[2] 192.168.254.3 #5: received and ignored
informational message
18:56:33 pluto[16368] "WLAN"[2] 192.168.254.3 #9: max number of
retransmissions (2) reached STATE_QUICK_I1
18:56:33 pluto[16368] "WLAN"[2] 192.168.254.3 #9: starting keying attempt 4
of at most 5
18:56:33 pluto[16368] "WLAN"[2] 192.168.254.3 #10: initiating Quick Mode
RSASIG+ENCRYPT to replace #9
18:56:33 pluto[16368] "WLAN"[2] 192.168.254.3 #5: ignoring informational
payload, type INVALID_ID_INFORMATION
18:56:33 pluto[16368] "WLAN"[2] 192.168.254.3 #5: received and ignored
informational message
18:57:00 pluto[16368] "WLAN"[2] 192.168.254.3 #11: responding to Quick Mode
18:57:00 pluto[16368] "WLAN"[2] 192.168.254.3 #11: transition from state
(null) to state STATE_QUICK_R1
18:57:00 pluto[16368] "WLAN"[2] 192.168.254.3 #11: transition from state
STATE_QUICK_R1 to state STATE_QUICK_R2
18:57:00 pluto[16368] "WLAN"[2] 192.168.254.3 #11: IPsec SA established
----
What can be seen is that Win XP answers the QM Request with
INVALID_ID_INFORMATION. But as soon as Win XP initiates it is fine (see last
line). So I generated oaklay.log:
----
5-18: 18:57:45:781:d6c Receive: (get) SA = 0x000c94a0 from
192.168.254.1.500
5-18: 18:57:45:781:d6c ISAKMP Header: (V1.0), len = 180
5-18: 18:57:45:781:d6c I-COOKIE ea3247c2783d8477
5-18: 18:57:45:781:d6c R-COOKIE ce9b2456bc5689de
5-18: 18:57:45:781:d6c exchange: Oakley Quick Mode
5-18: 18:57:45:781:d6c flags: 1 ( encrypted )
5-18: 18:57:45:781:d6c next payload: HASH
5-18: 18:57:45:781:d6c message ID: dedbe539
5-18: 18:57:45:781:d6c processing HASH (QM)
5-18: 18:57:45:781:d6c ClearFragList
5-18: 18:57:45:781:d6c processing payload NONCE
5-18: 18:57:45:781:d6c processing payload ID
5-18: 18:57:45:781:d6c processing payload ID
5-18: 18:57:45:781:d6c processing payload SA
5-18: 18:57:45:781:d6c Negotiated Proxy ID: Src 192.168.254.1.1701 Dst
192.168.254.3.1701
5-18: 18:57:45:781:d6c Src id for subnet. Mask 255.255.255.255
5-18: 18:57:45:781:d6c Dst id for subnet. Mask 255.255.255.255
5-18: 18:57:45:781:d6c Checking Proposal 0: Proto= ESP(3), num trans=2
Next=0
5-18: 18:57:45:781:d6c Checking Transform # 0: ID=Dreifach-DES CBC(3)
5-18: 18:57:45:781:d6c tunnel mode is Übertragungsmodus(2)
5-18: 18:57:45:781:d6c SA life type in seconds
5-18: 18:57:45:781:d6c SA life duration 3600
5-18: 18:57:45:781:d6c HMAC algorithm is MD5(1)
5-18: 18:57:45:781:d6c Checking Transform # 1: ID=Dreifach-DES CBC(3)
5-18: 18:57:45:781:d6c tunnel mode is Übertragungsmodus(2)
5-18: 18:57:45:781:d6c SA life type in seconds
5-18: 18:57:45:781:d6c SA life duration 3600
5-18: 18:57:45:781:d6c HMAC algorithm is SHA(2)
5-18: 18:57:45:781:d6c Finding Responder Policy for SRC=192.168.254.1.1701
DST=192.168.254.3.1701, SRCMask=255.255.255.255, DSTMask=255.255.255.255,
Prot=17 InTunnelEndpt 3fea8c0 OutTunnelEndpt 1fea8c0
5-18: 18:57:45:791:d6c Failed to get TunnelPolicy 13015
5-18: 18:57:45:791:d6c Responder failed to match filter(Phase II) 13015
5-18: 18:57:45:791:d6c Datenschutzmodus (Schnellmodus)
5-18: 18:57:45:791:d6c Quell-IP-Adresse 192.168.254.3 Quell-IP-Adressmaske
255.255.255.255 Ziel-IP-Adresse 192.168.254.1 Ziel-IP-Adressmaske
255.255.255.255 Protokoll 17 Quellport 1701 Zielport 1701 Lokale
IKE-Adresse 192.168.254.3 Peer-IKE-Adresse 192.168.254.1
5-18: 18:57:45:791:d6c Zertifikatsbasierte Identität. Peerantragsteller
C=DE, S=Niedersachsen, L=Oldenburg, O=Uni Oldenburg, OU=StB,
CN=ipcop.zuhause.xx Peer-SHA-Fingerabdruck
afee433ca7589b1da3579ce4ff424e63b6ae953e Peer, der die
Zertifizierungsstelle ausstellt: C=DE, S=Niedersachsen, L=Oldenburg, O=Uni
Oldenburg, OU=StB, CN=IPSec WLAN Root CA,
E=becker at informatik.uni-oldenburg.de Stammzertifizierungsstelle C=DE,
S=Niedersachsen, L=Oldenburg, O=Uni Oldenburg, OU=StB, CN=IPSec WLAN Root
CA, E=becker at informatik.uni-oldenburg.de Eigener Antragsteller C=DE,
S=Niedersachsen, L=Oldenburg, O=Uni Oldenburg, OU=StB, CN=sam.zuhause.xx
Eigener SHA-Fingerabdruck 951f1d09764c86b3e1f8db8b6fdcc7514978ac52
Peer-IP-Adresse: 192.168.254.1
5-18: 18:57:45:791:d6c Benutzer
5-18: 18:57:45:791:d6c Keine Richtlinie konfiguriert.
5-18: 18:57:45:791:d6c 0x0 0x0
----
The important part is obiously the "Failed to get TunnelPolicy, Responder
failed to match filter(Phase II)" which to my opinion mean that the request
sent by Openswan is not of the type Win XP expects here. Is this normal
behaviour?
It would not mind as finally the tunnel persists, but sometimes, it even
fails:
----
19:37:22 pluto[12677] "WLAN"[4] 192.168.254.3 #7: IPsec SA established
20:35:05 pluto[12677] "WLAN"[4] 192.168.254.3 #6: received Delete SA
payload: deleting IPSEC State #7
20:35:09 pluto[12677] "WLAN"[4] 192.168.254.3 #6: received and ignored
informational message
20:35:09 pluto[12677] "WLAN"[4] 192.168.254.3 #8: responding to Quick Mode
20:35:09 pluto[12677] "WLAN"[4] 192.168.254.3 #8: transition from state
(null) to state STATE_QUICK_R1
20:35:09 pluto[12677] "WLAN"[4] 192.168.254.3 #8: discarding duplicate
packet; already STATE_QUICK_R1
20:35:09 pluto[12677] "WLAN"[4] 192.168.254.3 #9: initiating Quick Mode
RSASIG+ENCRYPT+TUNNEL+DONTREKEY
20:35:09 pluto[12677] ERROR: "WLAN"[4] 192.168.254.3 #8: pfkey write() of
SADB_X_ADDFLOW message 34 for flow esp.bcb13c26 at 192.168.254.3 failed. Errno
14: Bad address
20:35:09 pluto[12677] | 02 0e 00 03 17 00 00 00 22 00 00 00 85 31 00 00
20:35:09 pluto[12677] | 02 00 01 00 bc b1 3c 26 00 00 00 00 02 00 00 00
20:35:09 pluto[12677] | 03 00 05 00 00 00 00 00 02 00 06 a5 c0 a8 fe 01
20:35:09 pluto[12677] | 00 00 00 00 00 00 00 00 03 00 06 00 00 00 00 00
20:35:09 pluto[12677] | 02 00 06 a5 c0 a8 fe 03 00 00 00 00 00 00 00 00
20:35:09 pluto[12677] | 03 00 15 00 00 00 00 00 02 00 06 a5 c0 a8 fe 01
20:35:09 pluto[12677] | 00 00 00 00 00 00 00 00 03 00 16 00 00 00 00 00
20:35:09 pluto[12677] | 02 00 06 a5 c0 a8 fe 03 36 36 36 36 36 36 36 36
20:35:09 pluto[12677] | 03 00 17 00 00 00 00 00 02 00 ff ff ff ff ff ff
20:35:09 pluto[12677] | 2e 33 00 08 f0 e6 0f 08 03 00 18 00 00 00 00 00
20:35:09 pluto[12677] | 02 00 ff ff ff ff ff ff ec e6 0f 08 60 e6 0f 08
20:35:09 pluto[12677] | 01 00 1a 00 11 d2 00 00
20:35:10 pluto[12677] "WLAN"[4] 192.168.254.3 #6: ignoring informational
payload, type INVALID_ID_INFORMATION
20:35:10 pluto[12677] "WLAN"[4] 192.168.254.3 #6: received and ignored
informational message
20:35:19 pluto[12677] ERROR: "WLAN"[4] 192.168.254.3 #8: pfkey write() of
SADB_X_ADDFLOW message 38 for flow esp.bcb13c26 at 192.168.254.3 failed. Errno
14: Bad address
----
After this the tunnel breaks and reinitiation seems to be impossible until
long timeouts clean up both sides.
Im desperate and I googled for days now. Anyone with an idea or an
explanation what is wrong here??? One more hint: I tried the settings with
plain IPSec and it shows the same wrong behaviour. Only in the oakley.log
there is a different failure "Failed to create dynamic policy" which sound
totally bad. Maybe me XP setup is broken?
Cheers,
Steffen
------------------------------------------------------------------------
Dipl. Wirtsch. Inform. Steffen Becker, DFG Junior Research Group "Palladio",
Fk 2, Department of Computing Science, Software Engineering Group
CvO Universität Oldenburg / OFFIS, Escherweg 2, D-26121 Oldenburg
Email: becker at informatik.uni-oldenburg.de
URL: http://se.informatik.uni-oldenburg.de
Voice: +49 441 9722-582 (-501, secr.) Fax: +49 441 9722-502
------------------------------------------------------------------------
More information about the Users
mailing list