[Openswan Users] "cannot install eroute" after remote IP change
Michael Smith
msmith at cbnco.com
Tue Feb 8 12:52:28 EST 2011
Hi,
I'm using Openswan 2.6.31, Linux 2.6.35.10, and NETKEY. One of my remote
sites is behind NAT and the public IP changes every couple of hours (!).
There are several IPsec SAs for the peer. After one or two IP changes,
one or more of the IPsec SAs keeps failing to negotiate with a message
like the following:
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site111-laptops"[2] 5.6.7.8
#25879: cannot install eroute -- it is in use for
"bldg-site111-laptops"[1] 5.6.7.8 #0
This repeats every 10-40 seconds. After about 600,000 times, the machine
runs out of memory and the OOM killer takes out pluto.
Notice the "#0" at the end. I thought that was odd. After still another
IP address change, the "#0" changes to the number of a real IPsec SA
instance:
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site111-laptops"[657]
9.10.11.12 #29492: cannot install eroute -- it is in use for
"bldg-site111-laptops"[656] 9.10.11.12 #29483
I'm pretty baffled. Here's the configuration I'm using:
conn bldg-site111-laptops
rightsubnet=192.168.111.0/24
also=bldg-site-common
also=bldg-common-laptops
auto=add
conn bldg-site111-support
rightsubnet=192.168.111.0/24
also=bldg-site-common
also=bldg-common-support
auto=add
conn bldg-site112-laptops
rightsubnet=192.168.112.0/24
also=bldg-site-common
also=bldg-common-laptops
auto=add
conn bldg-site112-support
rightsubnet=192.168.112.0/24
also=bldg-site-common
also=bldg-common-support
auto=add
conn bldg-site49_32-phones
rightsubnet=192.168.49.32/29
also=bldg-site-common
also=bldg-common-phones
auto=add
<some other tunnels not shown>
conn bldg-site-common
right=%any
rightid=@remote-vpngw
rekey=no
conn bldg-common-laptops
leftsubnet=10.1.2.0/24
left=44.44.44.44
leftid=@vpngw.cbnco.com
leftcert=/etc/x509cert.der
conn bldg-common-support
leftsubnet=10.1.1.0/24
left=44.44.44.44
leftid=@vpngw.cbnco.com
leftcert=/etc/x509cert.der
conn bldg-common-phones
leftsubnet=192.168.49.32/29
left=44.44.44.44
leftid=@vpngw.cbnco.com
leftcert=/etc/x509cert.der
Above those tunnels, the default settings are:
conn %default
keyingtries=0
disablearrivalcheck=no
authby=rsasig
leftrsasigkey=%cert
rightrsasigkey=%cert
ike=aes256-sha,aes256-md5
esp=aes256-sha1,aes256-md5
Up until today, I didn't have "rekey=no" and the tunnels were set to
"auto=start" instead of "auto=add". I don't expect those changes to fix
the problem, but I figured I'd better rule them out first. I looked
through the change log since 2.6.31 and didn't see anything that looked
related, but I could be missing something.
I'll paste more logs with comments below.
Thanks,
Mike
#24010: quick mode for bldg-site49_32-phones
#24506: quick mode for bldg-site112-support
#24522: main mode
IP changes from 1.2.3.4 to 5.6.7.8:
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site49_32-phones"[1] 1.2.3.4
#24010: new NAT mapping for #24010, was 1.2.3.4:10000, now 5.6.7.8:10000
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site49_32-phones"[1] 5.6.7.8
#24522: received Delete SA(0xcf8c44aa) payload: deleting IPSEC State #24010
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site49_32-phones"[1] 5.6.7.8
#24522: ERROR: netlink response for Del SA esp.cf8c44aa at 5.6.7.8 included
errno 3: No such process
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site49_32-phones"[1] 5.6.7.8
#24522: received and ignored informational message
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site112-support"[1] 1.2.3.4
#24506: new NAT mapping for #24506, was 1.2.3.4:10000, now 5.6.7.8:10000
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site49_32-phones"[1] 5.6.7.8
#24522: received Delete SA(0xc225dbb4) payload: deleting IPSEC State #24506
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site49_32-phones"[1] 5.6.7.8
#24522: ERROR: netlink response for Del SA esp.c225dbb4 at 5.6.7.8 included
errno 3: No such process
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site49_32-phones"[1] 5.6.7.8
#24522: deleting connection "bldg-site112-support" instance with peer
5.6.7.8 {isakmp=#0/ipsec=#0}
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site49_32-phones"[1] 5.6.7.8
#24522: received and ignored informational message
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site112-laptops"[1] 1.2.3.4
#24483: new NAT mapping for #24483, was 1.2.3.4:10000, now 5.6.7.8:10000
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site49_32-phones"[1] 5.6.7.8
#24522: received Delete SA(0xf963a582) payload: deleting IPSEC State #24483
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site49_32-phones"[1] 5.6.7.8
#24522: ERROR: netlink response for Del SA esp.f963a582 at 5.6.7.8 included
errno 3: No such process
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site49_32-phones"[1] 5.6.7.8
#24522: deleting connection "bldg-site112-laptops" instance with peer
5.6.7.8 {isakmp=#0/ipsec=#0}
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site49_32-phones"[1] 5.6.7.8
#24522: received and ignored informational message
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site211-support"[1] 1.2.3.4
#24492: new NAT mapping for #24492, was 1.2.3.4:10000, now 5.6.7.8:10000
First "cannot install eroute message" follows - for only one of the
IPsec SAs:
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site49_32-phones"[2] 5.6.7.8
#25878: responding to Main Mode from unknown peer 5.6.7.8
...
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site49_32-phones"[2] 5.6.7.8
#25878: STATE_MAIN_R3: sent MR3, ISAKMP SA established
{auth=OAKLEY_RSA_SIG cipher=aes_256 prf=oakley_sha group=modp1536}
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site49_32-phones"[2] 5.6.7.8
#25878: the peer proposed: 10.1.2.0/24:0/0 -> 192.168.111.0/24:0/0
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site111-laptops"[2] 5.6.7.8
#25879: responding to Quick Mode proposal {msgid:d0045689}
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site111-laptops"[2] 5.6.7.8
#25879: us:
10.1.2.0/24===44.44.44.44<44.44.44.44>[@vpngw.cbnco.com,+S=C]---99.99.99.99
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site111-laptops"[2] 5.6.7.8
#25879: them: 5.6.7.8[@remote-vpngw,+S=C]===192.168.111.0/24
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site111-laptops"[2] 5.6.7.8
#25879: cannot install eroute -- it is in use for
"bldg-site111-laptops"[1] 5.6.7.8 #0
Feb 7 16:45:42 vpngw pluto[10130]: "bldg-site111-laptops"[2] 5.6.7.8:
deleting connection "bldg-site111-laptops" instance with peer 5.6.7.8
{isakmp=#0/ipsec=#0}
...
Feb 7 16:45:52 vpngw pluto[10130]: "bldg-site49_32-phones"[2] 5.6.7.8
#25878: the peer proposed: 10.1.2.0/24:0/0 -> 192.168.111.0/24:0/0
Feb 7 16:45:52 vpngw pluto[10130]: "bldg-site111-laptops"[3] 5.6.7.8
#25896: responding to Quick Mode proposal {msgid:d0045689}
Feb 7 16:45:52 vpngw pluto[10130]: "bldg-site111-laptops"[3] 5.6.7.8
#25896: us:
10.1.2.0/24===44.44.44.44<44.44.44.44>[@vpngw.cbnco.com,+S=C]---99.99.99.99
Feb 7 16:45:52 vpngw pluto[10130]: "bldg-site111-laptops"[3] 5.6.7.8
#25896: them: 5.6.7.8[@remote-vpngw,+S=C]===192.168.111.0/24
Feb 7 16:45:52 vpngw pluto[10130]: "bldg-site111-laptops"[3] 5.6.7.8
#25896: cannot install eroute -- it is in use for
"bldg-site111-laptops"[1] 5.6.7.8 #0
Feb 7 16:45:52 vpngw pluto[10130]: "bldg-site111-laptops"[3] 5.6.7.8:
deleting connection "bldg-site111-laptops" instance with peer 5.6.7.8
{isakmp=#0/ipsec=#0}
<repeats every 10-40 seconds>
More time passes, same behaviour:
Feb 7 20:59:22 vpngw pluto[10130]: "bldg-site111-laptops"[655] 5.6.7.8
#29472: responding to Quick Mode proposal {msgid:17e0a038}
Feb 7 20:59:22 vpngw pluto[10130]: "bldg-site111-laptops"[655] 5.6.7.8
#29472: us:
10.1.2.0/24===44.44.44.44<44.44.44.44>[@vpngw.cbnco.com,+S=C]---99.99.99.99
Feb 7 20:59:22 vpngw pluto[10130]: "bldg-site111-laptops"[655] 5.6.7.8
#29472: them: 5.6.7.8[@remote-vpngw,+S=C]===192.168.111.0/24
Feb 7 20:59:22 vpngw pluto[10130]: "bldg-site111-laptops"[655] 5.6.7.8
#29472: cannot install eroute -- it is in use for
"bldg-site111-laptops"[1] 5.6.7.8 #0
Feb 7 20:59:22 vpngw pluto[10130]: "bldg-site111-laptops"[655] 5.6.7.8:
deleting connection "bldg-site111-laptops" instance with peer 5.6.7.8
{isakmp=#0/ipsec=#0}
IP changes again, from 5.6.7.8 to 9.10.11.2:
Feb 7 21:01:12 vpngw pluto[10130]: "bldg-site112-support"[2] 5.6.7.8
#29300: the peer proposed: 10.1.2.0/24:0/0 -> 192.168.111.0/24:0/0
Feb 7 21:01:12 vpngw pluto[10130]: "bldg-site111-laptops"[656] 5.6.7.8
#29483: new NAT mapping for #29483, was 5.6.7.8:10000, now 9.10.11.12:10000
Feb 7 21:01:12 vpngw pluto[10130]: "bldg-site111-laptops"[656]
9.10.11.12 #29483: responding to Quick Mode proposal {msgid:c585783b}
Feb 7 21:01:12 vpngw pluto[10130]: "bldg-site111-laptops"[656]
9.10.11.12 #29483: us:
10.1.2.0/24===44.44.44.44<44.44.44.44>[@vpngw.cbnco.com,+S=C]---99.99.99.99
Feb 7 21:01:12 vpngw pluto[10130]: "bldg-site111-laptops"[656]
9.10.11.12 #29483: them: 9.10.11.12[@remote-vpngw,+S=C]===192.168.111.0/24
Feb 7 21:01:12 vpngw pluto[10130]: "bldg-site111-laptops"[656]
9.10.11.12 #29483: route to peer's client conflicts with
"bldg-site111-support" 5.6.7.8; releasing old connection to free the route
Feb 7 21:01:12 vpngw pluto[10130]: "bldg-site111-laptops"[656]
9.10.11.12 #29483: deleting connection "bldg-site111-support" instance
with peer 5.6.7.8 {isakmp=#0/ipsec=#25880}
Feb 7 21:01:12 vpngw pluto[10130]: "bldg-site111-support" #25880:
deleting state (STATE_QUICK_R2)
Feb 7 21:01:12 vpngw pluto[10130]: "bldg-site111-laptops"[656]
9.10.11.12 #29483: route to peer's client conflicts with
"bldg-site111-laptops" 5.6.7.8; releasing old connection to free the route
Feb 7 21:01:12 vpngw pluto[10130]: "bldg-site111-laptops"[656]
9.10.11.12 #29483: deleting connection "bldg-site111-laptops" instance
with peer 5.6.7.8 {isakmp=#0/ipsec=#0}
Feb 7 21:01:12 vpngw pluto[10130]: "bldg-site111-laptops" #29444:
deleting state (STATE_MAIN_I1)
Feb 7 21:01:12 vpngw pluto[10130]: "bldg-site111-laptops"[656]
9.10.11.12 #29483: transition from state STATE_QUICK_R0 to state
STATE_QUICK_R1
Feb 7 21:01:12 vpngw pluto[10130]: "bldg-site111-laptops"[656]
9.10.11.12 #29483: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed,
expecting QI2
Feb 7 21:01:12 vpngw pluto[10130]: "bldg-site111-laptops"[656]
9.10.11.12 #29483: transition from state STATE_QUICK_R1 to state
STATE_QUICK_R2
Feb 7 21:01:12 vpngw pluto[10130]: "bldg-site111-laptops"[656]
9.10.11.12 #29483: STATE_QUICK_R2: IPsec SA established tunnel mode
{ESP=>0x3f1a6c7f <0xb8de6703 xfrm=AES_256-HMAC_SHA1 NATOA=none
NATD=9.10.11.12:10000 DPD=none}
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site49_32-phones"[2] 5.6.7.8
#25885: new NAT mapping for #25885, was 5.6.7.8:10000, now 9.10.11.12:10000
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site112-support"[2] 5.6.7.8
#29300: received Delete SA(0xf8836391) payload: deleting IPSEC State #25885
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site112-support"[2] 5.6.7.8
#29300: ERROR: netlink response for Del SA esp.f8836391 at 9.10.11.12
included errno 3: No such process
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site112-support"[2] 5.6.7.8
#29300: received and ignored informational message
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site112-support"[2] 5.6.7.8
#29300: new NAT mapping for #29300, was 5.6.7.8:10000, now 9.10.11.12:10000
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site112-support"[2] 9.10.11.12
#29300: received Delete SA payload: deleting ISAKMP State #29300
Feb 7 21:02:24 vpngw pluto[10130]: packet from 9.10.11.12:10000:
received and ignored informational message
Feb 7 21:02:24 vpngw pluto[10130]: packet from 9.10.11.12:10002:
ignoring unknown Vendor ID payload [4f45617f4671486b6e574b67]
Feb 7 21:02:24 vpngw pluto[10130]: packet from 9.10.11.12:10002:
received Vendor ID payload [Dead Peer Detection]
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site49_32-phones"[3]
9.10.11.12 #29491: responding to Main Mode from unknown peer 9.10.11.12
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site49_32-phones"[3]
9.10.11.12 #29491: transition from state STATE_MAIN_R0 to state
STATE_MAIN_R1
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site49_32-phones"[3]
9.10.11.12 #29491: STATE_MAIN_R1: sent MR1, expecting MI2
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site49_32-phones"[3]
9.10.11.12 #29491: NAT-Traversal: Result using RFC 3947 (NAT-Traversal):
peer is NATed
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site49_32-phones"[3]
9.10.11.12 #29491: transition from state STATE_MAIN_R1 to state
STATE_MAIN_R2
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site49_32-phones"[3]
9.10.11.12 #29491: STATE_MAIN_R2: sent MR2, expecting MI3
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site49_32-phones"[3]
9.10.11.12 #29491: Main mode peer ID is ID_FQDN: '@remote-vpngw'
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site49_32-phones"[3]
9.10.11.12 #29491: crl update for "C=CA, ST=Ontario, L=Ottawa,
O=Canadian Bank Note Company, Ltd., OU=Information Services, CN=CBN
Certification Authority, E=certmaster at cbnco.com" is overdue since Dec 07
20:58:53 UTC 2003
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site49_32-phones"[3]
9.10.11.12 #29491: I am sending my cert
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site49_32-phones"[3]
9.10.11.12 #29491: deleting connection "bldg-site112-laptops" instance
with peer 5.6.7.8 {isakmp=#0/ipsec=#29475}
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site112-laptops" #25883:
deleting state (STATE_QUICK_R2)
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site112-laptops" #29475:
deleting state (STATE_QUICK_R2)
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site49_32-phones"[3]
9.10.11.12 #29491: deleting connection "bldg-site211-support" instance
with peer 5.6.7.8 {isakmp=#0/ipsec=#25882}
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site211-support" #25882:
deleting state (STATE_QUICK_R2)
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site49_32-phones"[3]
9.10.11.12 #29491: deleting connection "bldg-site211-laptops" instance
with peer 5.6.7.8 {isakmp=#0/ipsec=#25881}
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site211-laptops" #25881:
deleting state (STATE_QUICK_R2)
First "cannot install eroute" that doesn't end in "#0":
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site49_32-phones"[3]
9.10.11.12 #29491: transition from state STATE_MAIN_R2 to state
STATE_MAIN_R3
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site49_32-phones"[3]
9.10.11.12 #29491: new NAT mapping for #29491, was 9.10.11.12:10002, now
9.10.11.12:10000
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site49_32-phones"[3]
9.10.11.12 #29491: STATE_MAIN_R3: sent MR3, ISAKMP SA established
{auth=OAKLEY_RSA_SIG cipher=aes_256 prf=oakley_sha group=modp1536}
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site49_32-phones"[3]
9.10.11.12 #29491: the peer proposed: 10.1.2.0/24:0/0 ->
192.168.111.0/24:0/0
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site111-laptops"[657]
9.10.11.12 #29492: responding to Quick Mode proposal {msgid:79d2eba4}
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site111-laptops"[657]
9.10.11.12 #29492: us:
10.1.2.0/24===44.44.44.44<44.44.44.44>[@vpngw.cbnco.com,+S=C]---99.99.99.99
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site111-laptops"[657]
9.10.11.12 #29492: them: 9.10.11.12[@remote-vpngw,+S=C]===192.168.111.0/24
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site111-laptops"[657]
9.10.11.12 #29492: cannot install eroute -- it is in use for
"bldg-site111-laptops"[656] 9.10.11.12 #29483
Feb 7 21:02:24 vpngw pluto[10130]: "bldg-site111-laptops"[657]
9.10.11.12: deleting connection "bldg-site111-laptops" instance with
peer 9.10.11.12 {isakmp=#0/ipsec=#0}
#29483 is a quick mode tunnel negotiated right after the IP changed
at 21:01:12.
More information about the Users
mailing list