[Swan] negotiation hangs for connections with many SAs
Noam Singer
noam at fortycloud.com
Thu Dec 29 14:55:54 UTC 2016
Hello team,
I suspect there is a race condition related to negotiation (and there may
be a simple workaround).
I am using LibreSwan 3.16, and I've created a simple IPSec tunnel between
two nano machines in AWS, one in Ireland, and the other is in Frankfurt.
The only complexity is that these connections use lots of left and right
subnets, causing the creation of many SAs.
What happen is that pluto gets stuck completely. Executing anything like
ipsec auto --status, would just hang.
The workaround:
===============
Add to /etc/ipsec.conf
nhelpers=0
Although I am not 100% sure this resolves the problem in all cases.
Here is an example of the configuration files with the problem:
---------------------------------------------------------------
root at ip-172-31-16-203:/home/ubuntu# cat /etc/ipsec.conf
config setup
plutodebug=all
include /etc/ipsec.d/*.conf
root at ip-172-31-16-203:/home/ubuntu# cat /etc/ipsec.d/connST1439.conf
conn connST1439
authby=rsasig
auto=start
dpdaction=restart
dpddelay=30
dpdtimeout=120
forceencaps=yes
ike=aes128-sha1
ikelifetime=86400s
keyingtries=3
left=%defaultroute
leftid=@54.93.130.169
leftrsasigkey=0sAQPJ1YxE+mxELI/qyHuIqkoFEUrwgSp2sq5ylvAOwxJtyPt0EBLtXdAPBjBw+ZCA8xl28XDssu+oZ6mKZ6aRVKksBAf69VNyNp8d8PYBs2fACkedXYHhLwvPVeyW3HsT26DqfY0oyesoj4ykaH91HUAjMHyS40dEj9+c+y3HJp7LQKgbp3beBNCKnx9ZKbzg1YXXHGe0REqrQnRIcDvXZ3eohjZtHjsHXuKQaWCukSWwgSlOI2Zer5Ag7c44imxlmNPDozm1IegtHC39qxGbxT5cVrWVF332YmxP6Q+Y8uJOpspxOASUNfxCpiOHqLGZBjHg21UylkFf7SsGSdFvxizDK7EEhcIM2Fa6OGDcplY6bCdD
leftsubnets=
10.254.129.0/24,172.31.16.0/20,172.31.42.0/28,172.31.42.112/28,172.31.42.128/28,172.31.42.144/28,172.31.42.16/28,172.31.42.160/28,172.31.42.176/28,172.31.42.192/28,172.31.42.208/28,172.31.42.224/28,172.31.42.240/28,172.31.42.32/28,172.31.42.48/28,172.31.42.64/28,172.31.42.80/28,172.31.42.96/28
leftupdown=/usr/fortycloud/libreSwanUpDown.sh
pfs=no
phase2alg=aes128-sha1
right=54.171.1.11
rightid=@54.171.1.11
rightrsasigkey=0sAQPCXrYVHB4PX47nOXvfiRlHiXZQFqBj6TLEyVH5WzOrJN8xeKiy3/X8Q3Y6hX8aH2MASCsDqvbGXEvA/HfHvFjIaPuzxd7i8cNrsMbCUVAYe7wAl9Duwzq/dPdp6G3WkAFEi0wo8ocAwKanef7Xd7DmldUFjKe96S6Z01TNRQsX3H8+mKQQOcBgNJoj6CniHD5GGSbtibJWEQU4pmeuYSp4YZc5kGnpYWt5sU0F0wVcFRaY71Y9wqe4BiNJi05lnvwq6Z+MN527C18tUbGyfaJuqk2IE4dM8yTp/p6FC8MhNjwZmFZwk4TOVYPX16X6JYQm+ieoKl3Gpc74kpnujJax2lhLdEkVUFRZIJ9plytV9Ow1
rightsubnets=
10.10.10.0/24,10.10.42.0/28,10.10.42.112/28,10.10.42.128/28,10.10.42.144/28,10.10.42.16/28,10.10.42.160/28,10.10.42.176/28,10.10.42.192/28,10.10.42.208/28,10.10.42.224/28,10.10.42.240/28,10.10.42.32/28,10.10.42.48/28,10.10.42.64/28,10.10.42.80/28,10.10.42.96/28,10.254.128.0/24
salifetime=28800s
type=tunnel
Here are the last log lines in /var/log/auth.log:
-------------------------------------------------
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | #198
send_crypto_helper_request:613 st->st_calculating = TRUE;
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | state: #198 requesting
EVENT_SO_DISCARD to be deleted
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | event_schedule called for
60 seconds
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | event_schedule_tv called
for about 60 seconds and change
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | inserting event
EVENT_CRYPTO_FAILED, timeout in 60.000000 seconds for #198
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | removing pending policy for
"none" {0x7f585a9705e0}
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | unqueuing pending Quick
Mode with 54.171.1.11 "connST1439/11x18" import:admin initiate
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | creating state object #199
at 0x7f585a9ee1e0
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | parent state #199: new >
STATE_UNDEFINED(ignore)
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | duplicating state object #1
as #199
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | #199 quick_outI1:921
st->st_calculating == FALSE;
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | processing connection
"connST1439/11x18"
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | child state #199:
STATE_UNDEFINED(ignore) > STATE_QUICK_I1(authenticated-ipsec)
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | ignore states: 0
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | half-open-ike states: 0
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | open-ike states: 0
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | established-anonymous-ike
states: 0
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: |
established-authenticated-ike states: 1
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | anonymous-ipsec states: 0
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | authenticated-ipsec states:
198
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | informational states: 0
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | unknown states: 0
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | category states: 199 count
states: 199
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | inserting state object #199
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | finding hash chain in state
hash table
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | ICOOKIE: 0e e5 16 96 4e
c3 51 d4
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | RCOOKIE: 67 1c 39 6d eb
bb 26 d0
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | found hash chain 2
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | list 0x7f5859f49318 first
entry 0x7f585a9edf18
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | inserted state
0x7f585a9ee1e0 entry 0x7f585a9ee848 next 0x7f585a9edf18 prev-next
0x7f5859f49318 into list
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | updated next state
0x7f585a9ed8b0 entry 0x7f585a9edf18 next 0x7f585a9ed5e8 prev-next
0x7f585a9ee848
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | finding hash chain in
icookie hash table
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | ICOOKIE: 0e e5 16 96 4e
c3 51 d4
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | RCOOKIE: 00 00 00 00 00
00 00 00
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | found hash chain 23
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | list 0x7f5859f49500 first
entry 0x7f585a9edf30
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | inserted state
0x7f585a9ee1e0 entry 0x7f585a9ee860 next 0x7f585a9edf30 prev-next
0x7f5859f49500 into list
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | updated next state
0x7f585a9ed8b0 entry 0x7f585a9edf30 next 0x7f585a9ed600 prev-next
0x7f585a9ee860
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | event_schedule called for 0
seconds
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | event_schedule_tv called
for about 0 seconds and change
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | inserting event
EVENT_SO_DISCARD, timeout in 0.000000 seconds for #199
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: |
check_kernel_encrypt_alg(12,0): OK
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: "connST1439/11x18" #199:
initiating Quick Mode
RSASIG+ENCRYPT+TUNNEL+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW
{using isakmp#1 msgid:d7e131fe proposal=AES(12)_128-SHA1(2)_000
pfsgroup=no-pfs}
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | crypto helper 0: pcw_work:
197
Dec 29 14:28:15 ip-172-31-16-203 pluto[2294]: | asking crypto helper 0 to
do build nonce; request ID 200 (len=2776, pcw_work=197)
I would appreciate your thoughts on this issue
Thanks in advance
Noam Singer
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan/attachments/20161229/5ec7a4fe/attachment.html>
More information about the Swan
mailing list