[Openswan Users] "cannot install eroute" after remote IP change
Michael Smith
msmith at cbnco.com
Mon Feb 28 08:20:51 EST 2011
Hi,
I'm still having this "cannot install eroute" problem with Openswan
2.6.33.
What does the number in square brackets after a connection name mean? It
seems to increment once in a while, but I'm not clear when. Is it supposed
to indicate concurrent connections?
Feb 27 15:14:51 vpngw pluto[26638]: "bldg-othersite-phones"[6] 1.2.3.4
#649: cannot install route -- it is in use for "bldg-othersite-phones"[5]
1.2.3.4 #473
Thanks
Mike
On Tue, 8 Feb 2011, Michael Smith wrote:
> 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.
> _______________________________________________
> Users at openswan.org
> http://lists.openswan.org/mailman/listinfo/users
> Micropayments: https://flattr.com/thing/38387/IPsec-for-Linux-made-easy
> Building and Integrating Virtual Private Networks with Openswan:
> http://www.amazon.com/gp/product/1904811256/104-3099591-2946327?n=283155
>
More information about the Users
mailing list