Bug 1526203 - Kernel 4.14 breaks L2TP/IPsec VPN
Summary: Kernel 4.14 breaks L2TP/IPsec VPN
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: kernel
Version: 27
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Kernel Maintainer List
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Keywords:
: 1529082 1529938 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-12-15 00:05 UTC by Erik Indresovde
Modified: 2018-01-12 15:13 UTC (History)
35 users (show)

(edit)
Clone Of:
(edit)
Last Closed: 2018-01-12 15:13:17 UTC


Attachments (Terms of Use)

Description Erik Indresovde 2017-12-15 00:05:39 UTC
Description of problem:

After installing Kernel 4.14 L2TP VPN connections fail.Have tried 4.14.3 and 4.14.5, connection consistently fails. See log below.

When booting with 4.13 kernels VPN works as expected with no issues.
Currently running NetworkManager L2TP ver 1.2.8. 


Actual results:
des. 14 18:52:21 yoga-900-fedora NetworkManager[970]: <info>  [1513295541.9188] audit: op="connection-activate" uuid="c5c4d23e-2eee-4782-9d87-c23a4cc897e9" name="Russia" pid=2102 uid=1000 result="success"
des. 14 18:52:21 yoga-900-fedora NetworkManager[970]: <info>  [1513295541.9265] vpn-connection[0x563c775582f0,c5c4d23e-2eee-4782-9d87-c23a4cc897e9,"Russia",0]: Started the VPN service, PID 10424
des. 14 18:52:21 yoga-900-fedora NetworkManager[970]: <info>  [1513295541.9435] vpn-connection[0x563c775582f0,c5c4d23e-2eee-4782-9d87-c23a4cc897e9,"Russia",0]: Saw the service appear; activating connection
des. 14 18:52:21 yoga-900-fedora NetworkManager[970]: <info>  [1513295541.9537] vpn-connection[0x563c775582f0,c5c4d23e-2eee-4782-9d87-c23a4cc897e9,"Russia",0]: VPN connection: (ConnectInteractive) reply received
des. 14 18:52:22 yoga-900-fedora nm-l2tp-service[10424]: Check port 1701
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: Redirecting to: systemctl stop ipsec.service
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: warning: could not open include filename: '/etc/ipsec.d/*.conf'
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: warning: could not open include filename: '/etc/ipsec.d/*.conf'
des. 14 18:52:22 yoga-900-fedora ipsec_starter[10454]: warning: could not open include filename: '/etc/ipsec.d/*.conf'
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: mkdir: klarte ikke å opprette mappa «@FINALRUNDIR@»: Ikke tilgang
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: warning: could not open include filename: '/etc/ipsec.d/*.conf'
des. 14 18:52:22 yoga-900-fedora ipsec_starter[10467]: warning: could not open include filename: '/etc/ipsec.d/*.conf'
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: warning: could not open include filename: '/etc/ipsec.d/*.conf'
des. 14 18:52:22 yoga-900-fedora ipsec_starter[10472]: warning: could not open include filename: '/etc/ipsec.d/*.conf'
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: Redirecting to: systemctl start ipsec.service
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: 002 listening for IKE messages
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: 002 adding interface virbr0/virbr0 192.168.122.1:500
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: 002 adding interface virbr0/virbr0 192.168.122.1:4500
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: 002 adding interface wlp1s0/wlp1s0 192.168.1.177:500
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: 002 adding interface wlp1s0/wlp1s0 192.168.1.177:4500
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: 002 adding interface lo/lo 127.0.0.1:500
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: 002 adding interface lo/lo 127.0.0.1:4500
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: 002 adding interface wlp1s0/wlp1s0 2605:a601:81a6:9f00:4195:1bec:21fc:655b:500
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: 002 adding interface lo/lo ::1:500
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: 002 loading secrets from "/etc/ipsec.secrets"
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: 002 loading secrets from "/etc/ipsec.d/nm-l2tp-ipsec-c5c4d23e-2eee-4782-9d87-c23a4cc897e9.secrets"
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: debugging mode enabled
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: end of file /var/run/nm-l2tp-ipsec-c5c4d23e-2eee-4782-9d87-c23a4cc897e9.conf
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: Loading conn c5c4d23e-2eee-4782-9d87-c23a4cc897e9
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: starter: left is KH_DEFAULTROUTE
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: conn: "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" labeled_ipsec=0
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: conn: "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" modecfgdomain=(null)
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: conn: "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" modecfgbanner=(null)
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: conn: "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" mark-in=(null)
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: conn: "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" mark-out=(null)
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: conn: "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" vti_iface=(null)
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: opening file: /var/run/nm-l2tp-ipsec-c5c4d23e-2eee-4782-9d87-c23a4cc897e9.conf
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: loading named conns: c5c4d23e-2eee-4782-9d87-c23a4cc897e9
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: seeking_src = 1, seeking_gateway = 1, has_peer = 1
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: seeking_src = 0, seeking_gateway = 1, has_dst = 1
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: dst  via 192.168.1.1 dev wlp1s0 src  table 254
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: set nexthop: 192.168.1.1
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: dst 192.168.1.0 via  dev wlp1s0 src 192.168.1.177 table 254
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: dst 192.168.122.0 via  dev virbr0 src 192.168.122.1 table 254
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: dst 127.0.0.0 via  dev lo src 127.0.0.1 table 255 (ignored)
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: dst 127.0.0.1 via  dev lo src 127.0.0.1 table 255 (ignored)
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: dst 127.255.255.255 via  dev lo src 127.0.0.1 table 255 (ignored)
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: dst 192.168.1.0 via  dev wlp1s0 src 192.168.1.177 table 255 (ignored)
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: dst 192.168.1.177 via  dev wlp1s0 src 192.168.1.177 table 255 (ignored)
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: dst 192.168.1.255 via  dev wlp1s0 src 192.168.1.177 table 255 (ignored)
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: dst 192.168.122.0 via  dev virbr0 src 192.168.122.1 table 255 (ignored)
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: dst 192.168.122.1 via  dev virbr0 src 192.168.122.1 table 255 (ignored)
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: dst 192.168.122.255 via  dev virbr0 src 192.168.122.1 table 255 (ignored)
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: seeking_src = 1, seeking_gateway = 0, has_peer = 1
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: seeking_src = 1, seeking_gateway = 0, has_dst = 1
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: dst 192.168.1.1 via  dev wlp1s0 src 192.168.1.177 table 254
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: set addr: 192.168.1.177
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: seeking_src = 0, seeking_gateway = 0, has_peer = 1
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: 002 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" #1: initiating Main Mode
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: 104 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" #1: STATE_MAIN_I1: initiate
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: 002 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" #1: WARNING: connection c5c4d23e-2eee-4782-9d87-c23a4cc897e9 PSK length of 9 bytes is too short for sha PRF in FIPS mode (10 bytes required)
des. 14 18:52:22 yoga-900-fedora NetworkManager[970]: 106 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" #1: STATE_MAIN_I2: sent MI2, expecting MR2
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: 108 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" #1: STATE_MAIN_I3: sent MI3, expecting MR3
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: 002 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" #1: Peer ID is ID_IPV4_ADDR: '95.213.136.222'
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: 004 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" #1: STATE_MAIN_I4: ISAKMP SA established {auth=PRESHARED_KEY cipher=aes_128 integ=sha group=MODP2048}
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: 002 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" #2: initiating Quick Mode PSK+ENCRYPT+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO {using isakmp#1 msgid:bc1521d1 proposal=defaults pfsgroup=no-pfs}
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: 117 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" #2: STATE_QUICK_I1: initiate
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: 003 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" #2: NAT-Traversal: received 2 NAT-OA. Ignored because peer is not NATed
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: 003 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" #2: our client subnet returned doesn't match my proposal - us:192.168.1.177/32 vs them:136.56.72.60/32
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: 003 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" #2: Allowing questionable proposal anyway [ALLOW_MICROSOFT_BAD_PROPOSAL]
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: 004 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" #2: STATE_QUICK_I2: sent QI2, IPsec SA established transport mode {ESP/NAT=>0xcd2cd2e2 <0x8e67894d xfrm=AES_CBC_128-HMAC_SHA1_96 NATOA=none NATD=95.213.136.222:4500 DPD=passive}
des. 14 18:52:23 yoga-900-fedora nm-l2tp-service[10424]: xl2tpd started with pid 11068
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: xl2tpd[11068]: Not looking for kernel SAref support.
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: xl2tpd[11068]: Using l2tp kernel support.
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: xl2tpd[11068]: xl2tpd version xl2tpd-1.3.8 started on yoga-900-fedora PID:11068
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: xl2tpd[11068]: Written by Mark Spencer, Copyright (C) 1998, Adtran, Inc.
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: xl2tpd[11068]: Forked by Scott Balmos and David Stipp, (C) 2001
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: xl2tpd[11068]: Inherited by Jeff McAdams, (C) 2002
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: xl2tpd[11068]: Forked again by Xelerance (www.xelerance.com) (C) 2006-2016
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: xl2tpd[11068]: Listening on IP address 0.0.0.0, port 1701
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: <info>  [1513295543.4777] vpn-connection[0x563c775582f0,c5c4d23e-2eee-4782-9d87-c23a4cc897e9,"Russia",0]: VPN plugin: state changed: starting (3)
des. 14 18:52:23 yoga-900-fedora NetworkManager[970]: xl2tpd[11068]: Connecting to host 95.213.136.222, port 1701
des. 14 18:52:37 yoga-900-fedora NetworkManager[970]: <warn>  [1513295557.4822] vpn-connection[0x563c775582f0,c5c4d23e-2eee-4782-9d87-c23a4cc897e9,"Russia",0]: VPN plugin: failed: connect-failed (1)
des. 14 18:52:37 yoga-900-fedora NetworkManager[970]: xl2tpd[11068]: death_handler: Fatal signal 15 received
des. 14 18:52:37 yoga-900-fedora NetworkManager[970]: xl2tpd[11068]: Connection 0 closed to 95.213.136.222, port 1701 (Server closing)
des. 14 18:52:37 yoga-900-fedora NetworkManager[970]: <warn>  [1513295557.4824] vpn-connection[0x563c775582f0,c5c4d23e-2eee-4782-9d87-c23a4cc897e9,"Russia",0]: VPN plugin: failed: connect-failed (1)
des. 14 18:52:37 yoga-900-fedora NetworkManager[970]: <info>  [1513295557.4829] vpn-connection[0x563c775582f0,c5c4d23e-2eee-4782-9d87-c23a4cc897e9,"Russia",0]: VPN plugin: state changed: stopping (5)
des. 14 18:52:37 yoga-900-fedora NetworkManager[970]: 002 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9": deleting non-instance connection
des. 14 18:52:37 yoga-900-fedora NetworkManager[970]: 002 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" #3: deleting state (STATE_QUICK_I2) and sending notification
des. 14 18:52:37 yoga-900-fedora NetworkManager[970]: 005 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" #3: ESP traffic information: in=0B out=0B
des. 14 18:52:37 yoga-900-fedora NetworkManager[970]: 002 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" #2: deleting state (STATE_QUICK_I2) and sending notification
des. 14 18:52:37 yoga-900-fedora NetworkManager[970]: 005 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" #2: ESP traffic information: in=0B out=0B
des. 14 18:52:37 yoga-900-fedora NetworkManager[970]: 002 "c5c4d23e-2eee-4782-9d87-c23a4cc897e9" #1: deleting state (STATE_MAIN_I4) and sending notification
des. 14 18:52:37 yoga-900-fedora nm-l2tp-service[10424]: ipsec shut down
des. 14 18:52:37 yoga-900-fedora NetworkManager[970]: <info>  [1513295557.5320] vpn-connection[0x563c775582f0,c5c4d23e-2eee-4782-9d87-c23a4cc897e9,"Russia",0]: VPN plugin: state changed: stopped (6)
des. 14 18:52:37 yoga-900-fedora NetworkManager[970]: <info>  [1513295557.5343] vpn-connection[0x563c775582f0,c5c4d23e-2eee-4782-9d87-c23a4cc897e9,"Russia",0]: VPN service disappeared

Comment 1 Douglas Kosovic 2017-12-15 13:15:42 UTC
With kernel-4.14.5-300.fc27, I've reproduced the issue with a locally built xl2tpd-1.3.10.1 that has the following line commented out in the xl2tpd Makefile :

#OSFLAGS+= -DUSE_KERNEL

I've added a comment to the following bug report :
  https://bugzilla.redhat.com/show_bug.cgi?id=1446914

Although I didn't see the 'ppp0: recursion detected' error as in that report, but might not have the debugging turned up to see it.


Others have reported issues with kernel 4.14 also, here is the upstream libreswan bug report :

https://github.com/libreswan/libreswan/issues/140

Comment 2 Douglas Kosovic 2017-12-15 13:32:26 UTC
I tried kernel-4.15.0-0.rc3.git0.1.fc28.x86_64 on Fedora 27 and can confirm I'm able to able to establish a L2TP/IPsec VPN connection.

Comment 3 Douglas Kosovic 2017-12-15 23:44:38 UTC
Unfortunately kernel-4.14.6-300.fc27 in testing still has the issue.

Comment 4 Douglas Kosovic 2017-12-16 06:31:49 UTC
I've changed the bug component from NetworkManager-l2tp to kernel as the bug appears to only exist with kernel 4.14.x

Comment 5 Helmut Schlattl 2017-12-20 09:02:01 UTC
I can confirm that this is very probably a kernel bug, since I cannot establish a host-to-host tunnel with the ipsec-tools (not the NetworkManager).

Comment 6 Laura Abbott 2017-12-20 22:38:01 UTC
Can you test 4.14.8? If 4.15-rc3 works that means there is a good chance a fix may have made its way to stable and there were a bunch of networking fixes bewteen 4.14.6 and 4.14.8

Comment 7 Jake Arkinstall 2017-12-22 03:28:58 UTC
After getting the same issue (and spending hours picking through logs and getting nowhere), I found this thread. I have tried this on the --enablerepo=updates-testing, which takes me to kernel 4.14.8. The problem is still occurring. Exactly the same symptoms, with the same 14 second delay.

I have set plutodebug="all" and directed the debug information to a file, which I have copied from the normal stages to where things get weird. Unfortunately, networking is not my forte and I'm not too familiar with the codebase, the terminology, and even what data should/should not be published. As such I've redacted everything that I can't see as being useful through some quick heavy-handed regexps. If there's something that may help, please let me know and I'll add it back in.

I'm not sure how useful this will be, but it might help to get a timeline of events here.


Dec 22 01:55:59: | complete v1 state transition with STF_OK
Dec 22 01:55:59: | doing_xauth:no, t_xauth_client_done:no
Dec 22 01:55:59: | serialno table: hash serialno #1 to head 0x..............
Dec 22 01:55:59: | IKEv1: transition from state STATE_QUICK_I1 to state STATE_QUICK_I2
Dec 22 01:55:59: | child state #3: STATE_QUICK_I1(authenticated-ipsec) => STATE_QUICK_I2(authenticated-ipsec)
Dec 22 01:55:59: | ignore states: 0
Dec 22 01:55:59: | half-open-ike states: 0
Dec 22 01:55:59: | open-ike states: 0
Dec 22 01:55:59: | established-anonymous-ike states: 0
Dec 22 01:55:59: | established-authenticated-ike states: 1
Dec 22 01:55:59: | anonymous-ipsec states: 0
Dec 22 01:55:59: | authenticated-ipsec states: 2
Dec 22 01:55:59: | informational states: 0
Dec 22 01:55:59: | unknown states: 0
Dec 22 01:55:59: | category states: 3 count states: 3
Dec 22 01:55:59: | event_already_set, deleting event
Dec 22 01:55:59: | state #3 requesting EVENT_v1_RETRANSMIT to be deleted
Dec 22 01:55:59: | free_event_entry: release EVENT_v1_RETRANSMIT-pe@.........
Dec 22 01:55:59: | sending reply packet to **.***.***.***:4500 (from port 4500)
Dec 22 01:55:59: | sending 56 bytes for STATE_QUICK_I1 through wlp5s0:4500 to **.***.***.***:4500 (using #3)
Dec 22 01:55:59: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. ..
Dec 22 01:55:59: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. ..
Dec 22 01:55:59: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. ..
Dec 22 01:55:59: |   .. .. .. ..  .. .. .. ..
Dec 22 01:55:59: | !event_already_set at reschedule
Dec 22 01:55:59: | event_schedule_ms called for about 27838000 ms
Dec 22 01:55:59: | event_schedule_tv: new EVENT_SA_REPLACE-pe@.........
Dec 22 01:55:59: | event_schedule_tv called for about 27838 seconds and change
Dec 22 01:55:59: | inserting event EVENT_SA_REPLACE, timeout in 27838.000000 seconds for #3
Dec 22 01:55:59: | NAT-T: NAT Traversal detected - their IKE port is '500'
Dec 22 01:55:59: | NAT-T: encaps is 'auto'
Dec 22 01:55:59: "********-****-****-****-************" #3: STATE_QUICK_I2: sent QI2, IPsec SA established transport mode {ESP/NAT=>0x******** <0x******** xfrm=3DES_CBC_0-HMAC_SHA1_96 NATOA=none NATD=**.***.***.***:4500 DPD=passive}
Dec 22 01:55:59: | modecfg pull: noquirk policy:push not-client
Dec 22 01:55:59: | phase 1 is done, looking for phase 2 to unpend
Dec 22 01:55:59: | pluto_sd: executing action action: reloading(4), status 0
Dec 22 01:55:59: listening for IKE messages
Dec 22 01:55:59: | Inspecting interface lo 
Dec 22 01:55:59: | found lo with address 127.0.0.1
Dec 22 01:55:59: | Inspecting interface wlp5s0 
Dec 22 01:55:59: | found wlp5s0 with address ***.***.***.***
Dec 22 01:55:59: | found lo with address 0000:0000:0000:0000:0000:0000:0000:0001
Dec 22 01:55:59: | free_event_entry: release EVENT_NULL-pe@0x..............
Dec 22 01:55:59: | refresh. setup callback for interface lo:500 81
Dec 22 01:55:59: | setup callback for interface lo:500 fd 81
Dec 22 01:55:59: | free_event_entry: release EVENT_NULL-pe@0x..............
Dec 22 01:55:59: | refresh. setup callback for interface lo:4500 80
Dec 22 01:55:59: | setup callback for interface lo:4500 fd 80
Dec 22 01:55:59: | free_event_entry: release EVENT_NULL-pe@0x..............
Dec 22 01:55:59: | refresh. setup callback for interface lo:500 79
Dec 22 01:55:59: | setup callback for interface lo:500 fd 79
Dec 22 01:55:59: | free_event_entry: release EVENT_NULL-pe@0x..............
Dec 22 01:55:59: | refresh. setup callback for interface wlp5s0:4500 78
Dec 22 01:55:59: | setup callback for interface wlp5s0:4500 fd 78
Dec 22 01:55:59: | free_event_entry: release EVENT_NULL-pe@0x..............
Dec 22 01:55:59: | refresh. setup callback for interface wlp5s0:500 77
Dec 22 01:55:59: | setup callback for interface wlp5s0:500 fd 77
Dec 22 01:55:59: | certs and keys locked by 'free_preshared_secrets'
Dec 22 01:55:59: forgetting secrets
Dec 22 01:55:59: | certs and keys unlocked by 'free_preshard_secrets'
Dec 22 01:55:59: loading secrets from "/etc/ipsec.secrets"
Dec 22 01:55:59: loading secrets from "/etc/ipsec.d/nm-l2tp-ipsec-********-****-****-****-************.secrets"
Dec 22 01:55:59: | id type added to secret(0x..............) PPK_PSK: %any
Dec 22 01:55:59: | id type added to secret(0x..............) PPK_PSK: ***.***.***.***
Dec 22 01:55:59: | Processing PSK at line 1: passed
Dec 22 01:55:59: | certs and keys locked by 'process_secret'
Dec 22 01:55:59: | certs and keys unlocked by 'process_secret'
Dec 22 01:55:59: | pluto_sd: executing action action: ready(5), status 0
Dec 22 01:55:59: | waitpid returned pid 4246 - status 0 exit status 0
Dec 22 01:55:59: | reaped addconn helper child (status 0)
Dec 22 01:55:59: | waitpid returned no more children


#
# Nothing happens for 10 seconds
#


Dec 22 01:56:09: | received 84 bytes from **.***.***.***:4500 on wlp5s0 (port=4500)
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. .. 
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. .. 
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. .. 
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. .. 
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. .. 
Dec 22 01:56:09: |   .. .. .. ..
Dec 22 01:56:09: | parse ISAKMP Message:
Dec 22 01:56:09: |    initiator cookie:
Dec 22 01:56:09: |   ** ** ** **  ** ** ** **
Dec 22 01:56:09: |    responder cookie:
Dec 22 01:56:09: |   ** ** ** **  ** ** ** **
Dec 22 01:56:09: |    next payload type: ISAKMP_NEXT_HASH (0x8)
Dec 22 01:56:09: |    ISAKMP version: ISAKMP Version 1.0 (rfc2407) (0x10)
Dec 22 01:56:09: |    exchange type: ISAKMP_XCHG_INFO (0x5)
Dec 22 01:56:09: |    flags: ISAKMP_FLAG_v1_ENCRYPTION (0x1)
Dec 22 01:56:09: |    message ID:  ** ** ** **
Dec 22 01:56:09: |    length: 84 (0x54)
Dec 22 01:56:09: |  processing version=1.0 packet with exchange type=ISAKMP_XCHG_INFO (5)
Dec 22 01:56:09: | cookies table: hash icookie ..:..... rcookie ..:..... to ........... head 0x..............
Dec 22 01:56:09: | peer and cookies match on #3; msgid=00000000 st_msgid=1ee7db5b st_msgid_phase15=00000000
Dec 22 01:56:09: | peer and cookies match on #2; msgid=00000000 st_msgid=124acbbb st_msgid_phase15=00000000
Dec 22 01:56:09: | peer and cookies match on #1; msgid=00000000 st_msgid=00000000 st_msgid_phase15=00000000
Dec 22 01:56:09: | p15 state object #1 found, in STATE_MAIN_I4
Dec 22 01:56:09: | processing connection "********-****-****-****-************" #1 **.***.***.***
Dec 22 01:56:09: | last Phase 1 IV:  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: | current Phase 1 IV:  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: | IV hash sha init
Dec 22 01:56:09: | IV sha hasher: context 0x..............
Dec 22 01:56:09: | IV hash sha digest PH1_IV-bytes@0x.............. (length 8)
Dec 22 01:56:09: | IV hash sha digest MSGID-bytes@0x.............. (length 4)
Dec 22 01:56:09: | IV hash sha final bytes@0x.............. (length 20)
Dec 22 01:56:09: | IV  .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: | IV  .. .. .. ..
Dec 22 01:56:09: | computed Phase 2 IV:
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: |   .. .. .. ..
Dec 22 01:56:09: | #1 state_busy:2553 st != NULL && st->st_calculating == FALSE;
Dec 22 01:56:09: | received encrypted packet from **.***.***.***:4500
Dec 22 01:56:09: | decrypting 56 bytes using algorithm 3DES_CBC
Dec 22 01:56:09: | NSS ike_alg_nss_cbc: 3des_cbc - enter
Dec 22 01:56:09: | NSS ike_alg_nss_cbc: 3des_cbc - exit
Dec 22 01:56:09: | decrypted:
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: | next IV:  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: | got payload 0x100  (ISAKMP_NEXT_HASH) needed: 0x100opt: 0x0
Dec 22 01:56:09: | ***parse ISAKMP Hash Payload:
Dec 22 01:56:09: |    next payload type: ISAKMP_NEXT_N (0xb)
Dec 22 01:56:09: |    length: 24 (0x18)
Dec 22 01:56:09: | got payload 0x800  (ISAKMP_NEXT_N) needed: 0x0opt: 0x0
Dec 22 01:56:09: | ***parse ISAKMP Notification Payload:
Dec 22 01:56:09: |    next payload type: ISAKMP_NEXT_NONE (0x0)
Dec 22 01:56:09: |    length: 32 (0x20)
Dec 22 01:56:09: |    DOI: ISAKMP_DOI_IPSEC (0x1)
Dec 22 01:56:09: |    protocol ID: 1 (0x1)
Dec 22 01:56:09: |    SPI size: 16 (0x10)
Dec 22 01:56:09: |    Notify Message Type: R_U_THERE (0x8d28)
Dec 22 01:56:09: | info:  .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: | info:  .. .. .. ..
Dec 22 01:56:09: | processing informational R_U_THERE (36136)
Dec 22 01:56:09: | DPD: received R_U_THERE seq:0 monotime:61 (state=#1 name="********-****-****-****-************")
Dec 22 01:56:09: | **emit ISAKMP Message:
Dec 22 01:56:09: |    initiator cookie:
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: |    responder cookie:
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: |    next payload type: ISAKMP_NEXT_HASH (0x8)
Dec 22 01:56:09: |    ISAKMP version: ISAKMP Version 1.0 (rfc2407) (0x10)
Dec 22 01:56:09: |    exchange type: ISAKMP_XCHG_INFO (0x5)
Dec 22 01:56:09: |    flags: ISAKMP_FLAG_v1_ENCRYPTION (0x1)
Dec 22 01:56:09: |    message ID:  .. .. .. ..
Dec 22 01:56:09: | ***emit ISAKMP Hash Payload:
Dec 22 01:56:09: |    next payload type: ISAKMP_NEXT_N (0xb)
Dec 22 01:56:09: | emitting 20 zero bytes of HASH into ISAKMP Hash Payload
Dec 22 01:56:09: | emitting length of ISAKMP Hash Payload: 24
Dec 22 01:56:09: | ***emit ISAKMP Notification Payload:
Dec 22 01:56:09: |    next payload type: ISAKMP_NEXT_NONE (0x0)
Dec 22 01:56:09: |    DOI: ISAKMP_DOI_IPSEC (0x1)
Dec 22 01:56:09: |    protocol ID: 1 (0x1)
Dec 22 01:56:09: |    SPI size: 16 (0x10)
Dec 22 01:56:09: |    Notify Message Type: R_U_THERE_ACK (0x8d29)
Dec 22 01:56:09: | emitting 8 raw bytes of notify icookie into ISAKMP Notification Payload
Dec 22 01:56:09: | notify icookie  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: | emitting 8 raw bytes of notify rcookie into ISAKMP Notification Payload
Dec 22 01:56:09: | notify rcookie  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: | emitting 4 raw bytes of notify data into ISAKMP Notification Payload
Dec 22 01:56:09: | notify data  .. .. .. ..
Dec 22 01:56:09: | emitting length of ISAKMP Notification Payload: 32
Dec 22 01:56:09: | hmac PRF sha init symkey-key@0x.............. (size 20)
Dec 22 01:56:09: | extract symkey clone for NSS algorithm: sha, mechanism: SHA_1_HMAC(545), flags: 800
Dec 22 01:56:09: | EXTRACT_KEY_FROM_KEY: key@0x.............., key-offset: 0, key-size: 20, flags: 0x800 -> target: SHA_1_HMAC
Dec 22 01:56:09: | EXTRACT_KEY_FROM_KEY: key-key@0x.............., size: 20 bytes, type/mechanism: EXTRACT_KEY_FROM_KEY (0x..............)
Dec 22 01:56:09: | EXTRACT_KEY_FROM_KEY: new result-key@0x.............., size: 20 bytes, type/mechanism: SHA_1_HMAC (0x..............)
Dec 22 01:56:09: | hmac prf: created sha context 0x.............. from symkey-key@0x..............
Dec 22 01:56:09: | hmac prf: begin sha with context 0x.............. from symkey-key@0x..............
Dec 22 01:56:09: | hmac: release clone-key@0x..............
Dec 22 01:56:09: | hmac PRF sha crypt-prf@0x..............
Dec 22 01:56:09: | hmac PRF sha update data-bytes@0x.............. (length 4)
Dec 22 01:56:09: | hmac PRF sha update data-bytes@0x.............. (length 32)
Dec 22 01:56:09: | hmac PRF sha final-bytes ...
Dec 22 01:56:09: | hmac PRF sha final-bytes@0x.............. (length 20)
Dec 22 01:56:09: | HASH computed:
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: |   .. .. .. ..
Dec 22 01:56:09: | last Phase 1 IV:  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: | current Phase 1 IV:  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: | IV hash sha init
Dec 22 01:56:09: | IV sha hasher: context 0x..............
Dec 22 01:56:09: | IV hash sha digest PH1_IV-bytes@0x.............. (length 8)
Dec 22 01:56:09: | IV hash sha digest MSGID-bytes@0x.............. (length 4)
Dec 22 01:56:09: | IV hash sha final bytes@0x.............. (length 20)
Dec 22 01:56:09: | IV  .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: | IV  .. .. .. ..
Dec 22 01:56:09: | computed Phase 2 IV:
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: |   .. .. .. ..
Dec 22 01:56:09: | encrypting: ......
Dec 22 01:56:09: | encrypting: ......
Dec 22 01:56:09: | encrypting: ......
Dec 22 01:56:09: | encrypting: ......
Dec 22 01:56:09: | IV:  .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: | IV:  .. .. .. ..
Dec 22 01:56:09: | unpadded size is: 56
Dec 22 01:56:09: | encrypting 56 using 3DES_CBC
Dec 22 01:56:09: | NSS ike_alg_nss_cbc: 3des_cbc - enter
Dec 22 01:56:09: | NSS ike_alg_nss_cbc: 3des_cbc - exit
Dec 22 01:56:09: | next IV:  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: | no IKEv1 message padding required
Dec 22 01:56:09: | emitting length of ISAKMP Message: 84
Dec 22 01:56:09: | sending 88 bytes for ISAKMP notify through wlp5s0:4500 to **.***.***.***:4500 (using #1)
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..  .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: |   .. .. .. ..  .. .. .. ..
Dec 22 01:56:09: | complete v1 state transition with STF_IGNORE

#
# 4 seconds later, xl2tpd is killed with signal 15 and cleanup begins...
#

Dec 22 01:56:13: | processing connection "********-****-****-****-************"
Dec 22 01:56:13: "********-****-****-****-************": deleting non-instance connection

Comment 8 Douglas Kosovic 2017-12-23 12:51:08 UTC
I think the issue is related to the following commit in kernel-stable 4.14 :

https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux-stable.git/commit/net/xfrm?h=v4.14.8&id=c9f3f813d462c72dbe412cee6a5cbacf13c4ad5e

which was reverted in kernel 4.15-rc1 :
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/net/xfrm?h=v4.15-rc4&id=94802151894d482e82c324edf2c658f8e6b96508

As mentioned in the comment on the following page for the revert, IPsec is unusable for some people without this revert :

https://patchwork.ozlabs.org/patch/838470/

And looks like the request to queue it up for v4.14-stable didn't make it through.

I haven't been able to test a patched kernel-4.14.8 with that reverted patch as I currently have limited access to resources while on holiday.

Comment 9 Douglas Kosovic 2017-12-26 11:17:39 UTC
*** Bug 1529082 has been marked as a duplicate of this bug. ***

Comment 10 Will Foster 2017-12-31 10:55:08 UTC
I seemed to have opened a duplicate here:

https://bugzilla.redhat.com/show_bug.cgi?id=1529938

Needless to say I'm having the same issue.

Comment 11 Will Foster 2017-12-31 10:58:44 UTC
*** Bug 1529938 has been marked as a duplicate of this bug. ***

Comment 12 Erik Indresovde 2018-01-05 03:52:16 UTC
Tested 4.14.11 today, disappointed to find same problem. This has been a known issue for weeks causing issues for a lot of users, why keep releasing new kernels with the same bug?

Comment 13 Kambiz Aghaiepour 2018-01-05 22:03:50 UTC
Same issue.

Comment 14 Micah Roth 2018-01-11 04:50:11 UTC
Same issue, but it appears to also be happening when I boot into 4.13.9

https://paste.fedoraproject.org/paste/YnQIE00Lc9kXpS4wmuMQHg

Comment 15 Jeremy Cline 2018-01-11 16:13:24 UTC
The fix for this issue landed in (In reply to Douglas Kosovic from comment #8)
> I think the issue is related to the following commit in kernel-stable 4.14 :
> 
> https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux-stable.git/
> commit/net/xfrm?h=v4.14.8&id=c9f3f813d462c72dbe412cee6a5cbacf13c4ad5e
> 
> which was reverted in kernel 4.15-rc1 :
> https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/
> net/xfrm?h=v4.15-rc4&id=94802151894d482e82c324edf2c658f8e6b96508

This landed in v4.14.12, can you test the latest build (https://koji.fedoraproject.org/koji/buildinfo?buildID=1015631 which should make it to updates-testing today) to make sure it's fixed?

Thanks!

Comment 16 Jason Dillaman 2018-01-11 16:20:36 UTC
Tested w/ the 4.14.13 kernel and I am able to connect to IPsec/L2TP VPNs again.

Comment 17 Nicholas Kudriavtsev 2018-01-12 08:01:01 UTC
Fixed.

Comment 18 Helmut Schlattl 2018-01-12 13:18:47 UTC
Host-to-host ipsec with pre-shared keys is also working again with kernel-4.14.13-300.fc27

Comment 19 Jeremy Cline 2018-01-12 15:13:17 UTC
Great, thanks for testing!


Note You need to log in before you can comment on or make changes to this bug.