Bug 1109470 - l2tpd/ipsec breaks when "ipsec saref" not set
Summary: l2tpd/ipsec breaks when "ipsec saref" not set
Keywords:
Status: CLOSED EOL
Alias: None
Product: Fedora
Classification: Fedora
Component: xl2tpd
Version: 20
Hardware: x86_64
OS: Linux
unspecified
medium
Target Milestone: ---
Assignee: Paul Wouters
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-06-14 06:35 UTC by Ryan
Modified: 2015-06-30 01:03 UTC (History)
3 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2015-06-30 01:03:04 UTC
Type: Bug
Embargoed:

Attachments (Terms of Use)

Description Ryan 2014-06-14 06:35:49 UTC 
Description of problem:

Not including "ipsec saref" configuration line in xl2tpd.conf breaks ipsec/l2tpd server. According to the xl2tpd(8) not including this line should be the same as setting it to no, however different results are observed.


Version-Release number of selected component (if applicable): 1.3.6-1


How reproducible:
Have only tried on one machine running Fedora 20, using OSx 10.9 and iOS 10.7 as clients. Reproducible by adding and removing "ipsec saref = no" config option.


Steps to Reproduce:
1. Setup IPSec/l2tpd VPN (config files below), with out "ipsec saref" config line
2. Connect with iOS 10.7 or OSx 10.9 (haven't tested any other clients)


Actual results:
Unable to connect to IPSec/l2tpd server.

Expected results:
Able to connect to IPSec/l2tpd server.

Additional info:

#/etc/ipsec.conf:
config setup
	protostack=netkey
	dumpdir=/var/run/pluto/
	nat_traversal=yes
	virtual_private=%v4:10.0.0.0/8,%v4:192.168.0.0/16,%v4:172.16.0.0/12,%v4:!10.152.2.0/24
conn L2TP-PSK
        left = 24.96.62.52
        leftprotoport = 17/%any
        leftnexthop= 24.96.62.52
        right = %any
        rightprotoport=17/%any
        authby = secret
        auto = add
        type = transport
        pfs = no	overridemtu=1420




#/etc/xl2tpd/xl2tpd.conf:
   [global]
   auth file = '/etc/xl2tpd/l2tp-secrets'

   [lns default]
   ip range = 192.168.210.10-192.168.210.254
   local ip = 192.168.210.1
   hostname = l2tpd
   ppp debug = yes
   pppoptfile = /etc/ppp/options.xl2tpd

#/etc/ppp/options.xl2tpd:
   debug

#Log with the above configuration, (shows me not being able to connect):

Jun 14 01:24:57 asdf xl2tpd[2518]: xl2tpd[2518]: Connection established to 192.168.250.201, 61563.  Local: 11139, Remote: 99 (ref=0/0).  LNS session is 'default'
Jun 14 01:24:57 asdf xl2tpd[2518]: xl2tpd[2518]: Call established with 192.168.250.201, Local: 64460, Remote: 6335, Serial: 1
Jun 14 01:24:57 asdf pppd[2551]: Plugin pppol2tp.so loaded.
Jun 14 01:24:57 asdf pppd[2551]: pppd 2.4.5 started by root, uid 0
Jun 14 01:24:57 asdf pppd[2551]: using channel 60
Jun 14 01:24:57 asdf pppd[2551]: Using interface ppp0
Jun 14 01:24:57 asdf pppd[2551]: Connect: ppp0 <-->
Jun 14 01:24:57 asdf pppd[2551]: PPPoL2TP options: lnsmode tid 11139 sid 64460 debugmask 0
Jun 14 01:24:57 asdf pppd[2551]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb20398a0>]
Jun 14 01:24:57 asdf xl2tpd[2518]: xl2tpd[2518]: write_packet: tty is not open yet.
Jun 14 01:24:57 asdf systemd-sysctl[2553]: Overwriting earlier assignment of net/ipv4/conf/default/rp_filter in file '/etc/sysctl.d/99-sysctl.conf'.
Jun 14 01:24:57 asdf xl2tpd[2518]: xl2tpd[2518]: network_thread: recvfrom returned error 111 (Connection refused)
Jun 14 01:24:57 asdf xl2tpd[2518]: xl2tpd[2518]: Can not find tunnel 4073 (refhim=0)
Jun 14 01:24:57 asdf xl2tpd[2518]: xl2tpd[2518]: network_thread: unable to find call or tunnel to handle packet.  call = 21792, tunnel = 4073 Dumping.
Jun 14 01:25:00 asdf xl2tpd[2518]: xl2tpd[2518]: write_packet: tty is not open yet.
Jun 14 01:25:00 asdf pppd[2551]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb20398a0>]
Jun 14 01:25:01 asdf xl2tpd[2518]: xl2tpd[2518]: Can not find tunnel 4073 (refhim=0)
Jun 14 01:25:01 asdf xl2tpd[2518]: xl2tpd[2518]: network_thread: unable to find call or tunnel to handle packet.  call = 21792, tunnel = 4073 Dumping.
Jun 14 01:25:03 asdf xl2tpd[2518]: xl2tpd[2518]: write_packet: tty is not open yet.
Jun 14 01:25:03 asdf pppd[2551]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb20398a0>]
Jun 14 01:25:05 asdf xl2tpd[2518]: xl2tpd[2518]: Can not find tunnel 4073 (refhim=0)
Jun 14 01:25:05 asdf xl2tpd[2518]: xl2tpd[2518]: network_thread: unable to find call or tunnel to handle packet.  call = 21792, tunnel = 4073 Dumping.
Jun 14 01:25:06 asdf xl2tpd[2518]: xl2tpd[2518]: write_packet: tty is not open yet.
Jun 14 01:25:06 asdf pppd[2551]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb20398a0>]
Jun 14 01:25:09 asdf xl2tpd[2518]: xl2tpd[2518]: write_packet: tty is not open yet.
Jun 14 01:25:09 asdf pppd[2551]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb20398a0>]
Jun 14 01:25:09 asdf xl2tpd[2518]: xl2tpd[2518]: Can not find tunnel 4073 (refhim=0)
Jun 14 01:25:09 asdf xl2tpd[2518]: xl2tpd[2518]: network_thread: unable to find call or tunnel to handle packet.  call = 21792, tunnel = 4073 Dumping.
Jun 14 01:25:12 asdf xl2tpd[2518]: xl2tpd[2518]: write_packet: tty is not open yet.
Jun 14 01:25:12 asdf pppd[2551]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb20398a0>]
Jun 14 01:25:13 asdf xl2tpd[2518]: xl2tpd[2518]: Can not find tunnel 4073 (refhim=0)
Jun 14 01:25:13 asdf xl2tpd[2518]: xl2tpd[2518]: network_thread: unable to find call or tunnel to handle packet.  call = 21792, tunnel = 4073 Dumping.
Jun 14 01:25:15 asdf xl2tpd[2518]: xl2tpd[2518]: write_packet: tty is not open yet.
Jun 14 01:25:15 asdf pppd[2551]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb20398a0>]
Jun 14 01:25:17 asdf xl2tpd[2518]: xl2tpd[2518]: Can not find tunnel 4073 (refhim=0)
Jun 14 01:25:17 asdf xl2tpd[2518]: xl2tpd[2518]: network_thread: unable to find call or tunnel to handle packet.  call = 21792, tunnel = 4073 Dumping.
Jun 14 01:25:18 asdf xl2tpd[2518]: xl2tpd[2518]: write_packet: tty is not open yet.
Jun 14 01:25:18 asdf pppd[2551]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb20398a0>]
Jun 14 01:25:21 asdf xl2tpd[2518]: xl2tpd[2518]: write_packet: tty is not open yet.
Jun 14 01:25:21 asdf pppd[2551]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb20398a0>]
Jun 14 01:25:24 asdf xl2tpd[2518]: xl2tpd[2518]: write_packet: tty is not open yet.
Jun 14 01:25:24 asdf pppd[2551]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb20398a0>]
Jun 14 01:25:27 asdf xl2tpd[2518]: xl2tpd[2518]: result_code_avp: result code endianness fix for buggy Apple client. network=768, le=3
Jun 14 01:25:27 asdf xl2tpd[2518]: xl2tpd[2518]: control_finish: Connection closed to 192.168.250.201, serial 1 ()
Jun 14 01:25:27 asdf xl2tpd[2518]: xl2tpd[2518]: result_code_avp: result code endianness fix for buggy Apple client. network=256, le=1
Jun 14 01:25:27 asdf xl2tpd[2518]: xl2tpd[2518]: control_finish: Connection closed to 192.168.250.201, port 61563 (), Local: 11139, Remote: 99






#Logs with 'ip saref = no' included in xl2tpd.conf

Jun 14 01:23:21 asdf xl2tpd[2175]: xl2tpd[2175]: Connection established to 192.168.250.201, 63571.  Local: 4073, Remote: 98 (ref=0/0).  LNS session is 'default'
Jun 14 01:23:21 asdf xl2tpd[2175]: xl2tpd[2175]: Call established with 192.168.250.201, Local: 21792, Remote: 6326, Serial: 1
Jun 14 01:23:21 asdf pppd[2336]: pppd 2.4.5 started by root, uid 0
Jun 14 01:23:21 asdf pppd[2336]: using channel 59
Jun 14 01:23:21 asdf pppd[2336]: Using interface ppp0
Jun 14 01:23:21 asdf pppd[2336]: Connect: ppp0 <--> /dev/pts/5
Jun 14 01:23:21 asdf pppd[2336]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x373be444> <pcomp> <accomp>]
Jun 14 01:23:21 asdf systemd-sysctl[2338]: Overwriting earlier assignment of net/ipv4/conf/default/rp_filter in file '/etc/sysctl.d/99-sysctl.conf'.
Jun 14 01:23:21 asdf pppd[2336]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x373be444> <pcomp> <accomp>]
Jun 14 01:23:24 asdf pppd[2336]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x68de38c3> <pcomp> <accomp>]
Jun 14 01:23:24 asdf pppd[2336]: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x68de38c3> <pcomp> <accomp>]
Jun 14 01:23:24 asdf pppd[2336]: sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
Jun 14 01:23:24 asdf pppd[2336]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 192.168.210.1>]
Jun 14 01:23:24 asdf pppd[2336]: rcvd [LCP EchoReq id=0x0 magic=0x68de38c3]
Jun 14 01:23:24 asdf pppd[2336]: sent [LCP EchoRep id=0x0 magic=0x373be444]
Jun 14 01:23:24 asdf pppd[2336]: rcvd [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Jun 14 01:23:24 asdf pppd[2336]: sent [IPCP ConfRej id=0x1 <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Jun 14 01:23:24 asdf pppd[2336]: rcvd [IPV6CP ConfReq id=0x1 <addr fe80::c62c:03ff:fe23:4396>]
Jun 14 01:23:24 asdf pppd[2336]: Unsupported protocol 'IPv6 Control Protocol' (0x8057) received
Jun 14 01:23:24 asdf pppd[2336]: sent [LCP ProtRej id=0x2 80 57 01 01 00 0e 01 0a c6 2c 03 ff fe 23 43 96]
Jun 14 01:23:24 asdf pppd[2336]: rcvd [LCP ProtRej id=0x2 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15 03 2f]
Jun 14 01:23:24 asdf pppd[2336]: Protocol-Reject for 'Compression Control Protocol' (0x80fd) received
Jun 14 01:23:24 asdf pppd[2336]: rcvd [proto=0x8235] 01 01 00 10 01 06 00 00 00 01 02 06 00 00 00 01
Jun 14 01:23:24 asdf pppd[2336]: Unsupported protocol 'Apple Client Server Protocol Control' (0x8235) received
Jun 14 01:23:24 asdf pppd[2336]: sent [LCP ProtRej id=0x3 82 35 01 01 00 10 01 06 00 00 00 01 02 06 00 00 00 01]
Jun 14 01:23:24 asdf pppd[2336]: rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>]
Jun 14 01:23:24 asdf pppd[2336]: sent [IPCP ConfReq id=0x2 <addr 192.168.210.1>]
Jun 14 01:23:24 asdf pppd[2336]: rcvd [IPCP ConfReq id=0x2 <addr 0.0.0.0>]
Jun 14 01:23:24 asdf pppd[2336]: sent [IPCP ConfNak id=0x2 <addr 192.168.210.10>]
Jun 14 01:23:24 asdf pppd[2336]: rcvd [IPCP ConfAck id=0x2 <addr 192.168.210.1>]
Jun 14 01:23:24 asdf pppd[2336]: rcvd [IPCP ConfReq id=0x3 <addr 192.168.210.10>]
Jun 14 01:23:24 asdf pppd[2336]: sent [IPCP ConfAck id=0x3 <addr 192.168.210.10>]
Jun 14 01:23:24 asdf pppd[2336]: local  IP address 192.168.210.1
Jun 14 01:23:24 asdf pppd[2336]: remote IP address 192.168.210.10
Jun 14 01:23:24 asdf pppd[2336]: Script /etc/ppp/ip-up started (pid 2340)
Jun 14 01:23:24 asdf pppd[2336]: Script /etc/ppp/ip-up finished (pid 2340), status = 0x0
Jun 14 01:23:44 asdf pppd[2336]: rcvd [LCP EchoReq id=0x1 magic=0x68de38c3]
Jun 14 01:23:44 asdf pppd[2336]: sent [LCP EchoRep id=0x1 magic=0x373be444]


Note that setting "ipsec saref" to yes also allows me to connect.
Comment 1 Paul Wouters 2014-06-14 16:48:16 UTC 
can you try this test build and let me know if the problem is still there?

 http://koji.fedoraproject.org/koji/taskinfo?taskID=7045324
Comment 2 Ryan 2014-06-14 21:46:18 UTC 
Installed the test build in that link.

Same issue is occurring. Able to connect when 'ip saref' is set to yes or no, but fails when it is commented out.

Initially the install was giving me the following errors:

[ryan@asdf]~% rpm -Uvh ./xl2tpd-1.3.6-4.fc21.x86_64.rpm 
error: Failed dependencies:
	kmod(l2tp_ppp.ko) is needed by xl2tpd-1.3.6-4.fc21.x86_64

However kernel-modules-extra was installed and up to date so I just ran 'rpm -Uvh -nodeps ./xl2tpd-1.3.6-4.fc21.x86_64.rpm'



#Log file when 'ip saref' is commented out with xl2tpd-1.3.6-4:

Jun 14 16:36:12 asdf xl2tpd[3432]: xl2tpd[3432]: Connection established to 192.168.250.201, 58403.  Local: 19706, Remote: 3 (ref=0/0).  LNS session is 'default'
Jun 14 16:36:12 asdf xl2tpd[3432]: xl2tpd[3432]: Call established with 192.168.250.201, Local: 64946, Remote: 991, Serial: 1
Jun 14 16:36:12 asdf xl2tpd[3432]: xl2tpd[3432]: write_packet: tty is not open yet.
Jun 14 16:36:12 asdf pppd[3452]: Plugin pppol2tp.so loaded.
Jun 14 16:36:12 asdf pppd[3452]: pppd 2.4.5 started by root, uid 0
Jun 14 16:36:12 asdf pppd[3452]: using channel 3
Jun 14 16:36:12 asdf pppd[3452]: Using interface ppp0
Jun 14 16:36:12 asdf pppd[3452]: Connect: ppp0 <-->
Jun 14 16:36:12 asdf pppd[3452]: Overriding mtu 1500 to 1410
Jun 14 16:36:12 asdf pppd[3452]: PPPoL2TP options: lnsmode tid 19706 sid 64946 debugmask 0
Jun 14 16:36:12 asdf pppd[3452]: Overriding mru 1500 to mtu value 1410
Jun 14 16:36:12 asdf pppd[3452]: sent [LCP ConfReq id=0x1 <mru 1410> <asyncmap 0x0> <auth chap MD5> <magic 0x66569ee5>]
Jun 14 16:36:12 asdf xl2tpd[3432]: xl2tpd[3432]: network_thread: recvfrom returned error 111 (Connection refused)
Jun 14 16:36:12 asdf systemd-sysctl[3455]: Overwriting earlier assignment of net/ipv4/conf/default/rp_filter in file '/etc/sysctl.d/99-sysctl.conf'.
Jun 14 16:36:12 asdf pluto[2436]: "L2TP-PSK"[3] 192.168.250.201 #6: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
Jun 14 16:36:12 asdf pluto[2436]: "L2TP-PSK"[3] 192.168.250.201 #6: STATE_QUICK_R2: IPsec SA established transport mode {ESP=>0x05077d96 <0xa11fa97c xfrm=AES_256-HMAC_SHA1 NATOA=...none DPD=none}
Jun 14 16:36:15 asdf xl2tpd[3432]: xl2tpd[3432]: write_packet: tty is not open yet.
Jun 14 16:36:15 asdf pppd[3452]: sent [LCP ConfReq id=0x1 <mru 1410> <asyncmap 0x0> <auth chap MD5> <magic 0x66569ee5>]
Jun 14 16:36:18 asdf xl2tpd[3432]: xl2tpd[3432]: write_packet: tty is not open yet.
Jun 14 16:36:18 asdf pppd[3452]: sent [LCP ConfReq id=0x1 <mru 1410> <asyncmap 0x0> <auth chap MD5> <magic 0x66569ee5>]
Jun 14 16:36:21 asdf xl2tpd[3432]: xl2tpd[3432]: write_packet: tty is not open yet.
Jun 14 16:36:21 asdf pppd[3452]: sent [LCP ConfReq id=0x1 <mru 1410> <asyncmap 0x0> <auth chap MD5> <magic 0x66569ee5>]
Jun 14 16:36:24 asdf xl2tpd[3432]: xl2tpd[3432]: write_packet: tty is not open yet.
Jun 14 16:36:24 asdf pppd[3452]: sent [LCP ConfReq id=0x1 <mru 1410> <asyncmap 0x0> <auth chap MD5> <magic 0x66569ee5>]
Jun 14 16:36:27 asdf xl2tpd[3432]: xl2tpd[3432]: write_packet: tty is not open yet.
Jun 14 16:36:27 asdf pppd[3452]: sent [LCP ConfReq id=0x1 <mru 1410> <asyncmap 0x0> <auth chap MD5> <magic 0x66569ee5>]
Jun 14 16:36:30 asdf xl2tpd[3432]: xl2tpd[3432]: write_packet: tty is not open yet.
Jun 14 16:36:30 asdf pppd[3452]: sent [LCP ConfReq id=0x1 <mru 1410> <asyncmap 0x0> <auth chap MD5> <magic 0x66569ee5>]
Jun 14 16:36:33 asdf xl2tpd[3432]: xl2tpd[3432]: write_packet: tty is not open yet.
Jun 14 16:36:33 asdf pppd[3452]: sent [LCP ConfReq id=0x1 <mru 1410> <asyncmap 0x0> <auth chap MD5> <magic 0x66569ee5>]
Jun 14 16:36:36 asdf xl2tpd[3432]: xl2tpd[3432]: write_packet: tty is not open yet.
Jun 14 16:36:36 asdf pppd[3452]: sent [LCP ConfReq id=0x1 <mru 1410> <asyncmap 0x0> <auth chap MD5> <magic 0x66569ee5>]
Jun 14 16:36:39 asdf xl2tpd[3432]: xl2tpd[3432]: write_packet: tty is not open yet.
Jun 14 16:36:39 asdf pppd[3452]: sent [LCP ConfReq id=0x1 <mru 1410> <asyncmap 0x0> <auth chap MD5> <magic 0x66569ee5>]
Jun 14 16:36:42 asdf xl2tpd[3432]: xl2tpd[3432]: result_code_avp: result code endianness fix for buggy Apple client. network=768, le=3
Jun 14 16:36:42 asdf xl2tpd[3432]: xl2tpd[3432]: control_finish: Connection closed to 192.168.250.201, serial 1 ()
Jun 14 16:36:42 asdf avahi-daemon[1252]: Withdrawing workstation service for ppp0.
Jun 14 16:36:42 asdf xl2tpd[3432]: xl2tpd[3432]: result_code_avp: result code endianness fix for buggy Apple client. network=256, le=1
Jun 14 16:36:42 asdf xl2tpd[3432]: xl2tpd[3432]: control_finish: Connection closed to 192.168.250.201, port 58403 (), Local: 19706, Remote: 3
Jun 14 16:36:42 asdf pluto[2436]: "L2TP-PSK"[3] 192.168.250.201 #5: received Delete SA(0x05077d96) payload: deleting IPSEC State #6
Jun 14 16:36:42 asdf pluto[2436]: "L2TP-PSK"[3] 192.168.250.201 #5: ESP traffic information: in=0B out=0B
Jun 14 16:36:42 asdf pluto[2436]: "L2TP-PSK"[3] 192.168.250.201 #5: received and ignored empty informational notification payload
Jun 14 16:36:42 asdf pluto[2436]: "L2TP-PSK"[3] 192.168.250.201 #5: received Delete SA payload: deleting ISAKMP State #5
Jun 14 16:36:42 asdf pluto[2436]: "L2TP-PSK"[3] 192.168.250.201: deleting connection "L2TP-PSK" instance with peer 192.168.250.201 {isakmp=#0/ipsec=#0}
Jun 14 16:36:42 asdf pluto[2436]: packet from 192.168.250.201:500: received and ignored empty informational notification payload
Comment 3 Fedora End Of Life 2015-05-29 12:06:38 UTC 
This message is a reminder that Fedora 20 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 20. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '20'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 20 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.
Comment 4 Fedora End Of Life 2015-06-30 01:03:04 UTC 
Fedora 20 changed to end-of-life (EOL) status on 2015-06-23. Fedora 20 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.
Note You need to log in before you can comment on or make changes to this bug.