[Openswan Users]
"Trouble parsing newly built pfkey message, error=-22"
Brian Candler
B.Candler at pobox.com
Fri Mar 10 10:14:30 CET 2006
I have an interoperability problem between Openswan 2.4.5rc5 and Cisco PIX
7.0.2 with PFS enabled. Phase 1 comes up successfully, but phase 2 fails
with a pfkey error: "Trouble parsing newly built pfkey message, error=-22"
After this openswan *says* that the quick mode SA was actually brought up
successfully, and I can send outbound pings (they appear as UDP 4500
encapsulated), but I don't see any replies.
The setup is like this:
dynamic static
10.1.50.0/28 172.151 x.x.x.x p.p.p.p 10.1.1.0/24
------------ Openswan ------- NAT =================== PIX -----------
(Linux) rtr
Openswan is running under Linux 2.4.30 (actually an OpenWRT box, where I've
recompiled the openswan package to bring it up to 2.4.5rc5)
Because the openswan 'client' box is on a dynamic IP address, I'm using
aggressive mode so that the PIX can choose the correct pre-shared key to
use.
Here's what I see at the openswan side:
----- 8< -----------------------------------------------------------------
root at OpenWrt:~# ipsec auto --verbose --up pix
002 "pix" #1: initiating Aggressive Mode #1, connection "pix"
112 "pix" #1: STATE_AGGR_I1: initiate
003 "pix" #1: received Vendor ID payload [Cisco-Unity]
003 "pix" #1: received Vendor ID payload [XAUTH]
003 "pix" #1: received Vendor ID payload [Dead Peer Detection]
003 "pix" #1: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] method set to=106
003 "pix" #1: ignoring unknown Vendor ID payload [4048b7d56ebce88525e7de7f00d6c2d3c0000000]
003 "pix" #1: ignoring unknown Vendor ID payload [6b8867abc3fe3413c7ce86b0c1846e0f]
003 "pix" #1: ignoring Vendor ID payload [Cisco VPN 3000 Series]
003 "pix" #1: protocol/port in Phase 1 ID Payload must be 0/0 or 17/500 but are 17/0
002 "pix" #1: Aggressive mode peer ID is ID_IPV4_ADDR: 'p.p.p.p'
003 "pix" #1: NAT-Traversal: Result using draft-ietf-ipsec-nat-t-ike-02/03: i am NATed
002 "pix" #1: Aggressive mode peer ID is ID_IPV4_ADDR: 'p.p.p.p'
002 "pix" #1: transition from state STATE_AGGR_I1 to state STATE_AGGR_I2
004 "pix" #1: STATE_AGGR_I2: sent AI2, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192 prf=oakley_md5 group=modp1024}
002 "pix" #2: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+AGGRESSIVE {using isakmp#1}
117 "pix" #2: STATE_QUICK_I1: initiate
002 "pix" #2: transition from state STATE_QUICK_I1 to state STATE_QUICK_I2
003 "pix" #2: pfkey_msg_build of Add SA esp.bb858f85 at 172.151.113.52 failed, code -22
004 "pix" #2: STATE_QUICK_I2: sent QI2, IPsec SA established {ESP=>0x7c8ba761 <0xbb858f85 xfrm=3DES_0-HMAC_MD5 NATD=none DPD=none}
----- 8< -----------------------------------------------------------------
I have pfkey debugging turned on, so here's the more specific debug logs:
----- 8< -----------------------------------------------------------------
Jan 1 18:17:53 (none) kern.warn pluto[6463]: "pix" #2: transition from state STATE_QUICK_I1 to state STATE_QUICK_I2
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | NAT-T: new mapping p.p.p.p:4500/500)
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | processing connection pix
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_msg_hdr_build:
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_msg_hdr_build: on_entry &pfkey_ext=0p0x7ffe7160 pfkey_ext=0p0x7ffe71c0 *pfkey_ext=0p(nil).
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_msg_hdr_build: on_exit &pfkey_ext=0p0x7ffe7160 pfkey_ext=0p0x7ffe71c0 *pfkey_ext=0p0x1001eb90.
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_sa_build: spi=bb858f85 replay=0 sa_state=1 auth=1 encrypt=0 flags=0
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_address_build: exttype=5 proto=0 prefixlen=0
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_address_build: found address family AF_INET.
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_address_build: found address=p.p.p.p:0.
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_address_build: successful created len: 3.
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_address_build: exttype=6 proto=0 prefixlen=0
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_address_build: found address family AF_INET.
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_address_build: found address=172.151.113.52:0.
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_address_build: successful created len: 3.
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_msg_build: pfkey_msg=0p0x10020f18 allocated 88 bytes, &(extensions[0])=0p0x7ffe71c0
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_msg_build: copying 24 bytes from extensions[1] (type=1)
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_msg_build: copying 24 bytes from extensions[5] (type=5)
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_msg_build: copying 24 bytes from extensions[6] (type=6)
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_msg_build: extensions permitted=30001fff, seen=00000063, required=00000063.
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_msg_parse: parsing message ver=2, type=2(update), errno=0, satype=0(UNKNOWN), len=11, res=0, seq=13, pid=6463.
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_msg_parse: satype 0 conversion to proto failed for msg_type 2 (update).
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | pfkey_lib_debug:pfkey_msg_build: Trouble parsing newly built pfkey message, error=-22.
Jan 1 18:17:53 (none) kern.warn pluto[6463]: "pix" #2: pfkey_msg_build of Add SA esp.bb858f85 at 172.151.113.52 failed, code -22
Jan 1 18:17:53 (none) kern.debug pluto[6463]: | processing connection pix
Jan 1 18:17:53 (none) kern.warn pluto[6463]: "pix" #2: STATE_QUICK_I2: sent QI2, IPsec SA established {ESP=>0x7c8ba761 <0xbb858f85 xfrm=3DES_0-HMAC_MD5 NATD=none DPD=none}
----- 8< -----------------------------------------------------------------
Here's my /etc/ipsec.conf:
----- 8< -----------------------------------------------------------------
version 2.0 # conforms to second version of ipsec.conf specification
# basic configuration
config setup
interfaces=%defaultroute
# plutodebug / klipsdebug = "all", "none" or a combation from below:
# "raw crypt parsing emitting control klips pfkey natt x509 private"
plutodebug="pfkey"
# NAT-TRAVERSAL support, see README.NAT-Traversal
nat_traversal=yes
# Add connections here
conn pix
ike=3des-md5-modp1024
esp=3des-md5-96
aggrmode=yes
authby=secret
left=%defaultroute
leftid=@gprstesting1
leftsubnet=10.1.50.0/28
right=p.p.p.p
rightsubnet=10.1.1.0/24
pfs=yes
auto=add
#Disable Opportunistic Encryption
include /etc/ipsec.d/examples/no_oe.conf
----- 8< -----------------------------------------------------------------
(I tried both with and without the esp= line, it seemed to make no
difference)
And /etc/ipsec.secrets:
----- 8< -----------------------------------------------------------------
@gprstesting1 p.p.p.p : PSK "xxxxxxxx"
----- 8< -----------------------------------------------------------------
The relevant bits of the PIX configuration are:
access-list acl_vpn_gprs_to_dc extended permit ip 10.1.1.0 255.255.255.0 10.1.50.0 255.255.255.240
crypto ipsec transform-set 3des_md5 esp-3des esp-md5-hmac
crypto dynamic-map vpn_ras 100 set pfs
crypto dynamic-map vpn_ras 100 set transform-set 3des_md5
crypto dynamic-map vpn_ras 100 set reverse-route
crypto map vpns_to_internet 100 ipsec-isakmp dynamic vpn_ras
crypto map vpns_to_internet interface outside
isakmp identity address
isakmp enable outside
isakmp policy 10 authentication pre-share
isakmp policy 10 encryption 3des
isakmp policy 10 hash md5
isakmp policy 10 group 2
isakmp policy 10 lifetime 86400
tunnel-group gprstesting1 type ipsec-l2l
tunnel-group gprstesting1 ipsec-attributes
pre-shared-key *
Anybody got any ideas what's going on here, or is there some more debugging
I can turn on to help pin this down? As far as I can tell from the source,
it seems that openswan is generating a message, running it through its own
parser before sending it, and failing to parse it. This implies the problem
is either with the format of the message it generates or with its own
parser, and not with the PIX.
Thanks,
Brian Candler.
More information about the Users
mailing list