[Openswan Users] xl2tpd stalls and must be killed -9

[alet at librelogiciel.com]

Hi,

I've got a Debian VPN gateway running openswan 2.6.28+dfsg-3 and xl2tpd
1.2.7+dfsg-1 with a 2.6.26 kernel. All are standard Debian packages from
Debian's repositories.

For openswan we use X.509 certificates, and for the user auth we use PAP
PPP authentication through a Radius server.

While the openswan part works just fine, xl2tpd very often stalls and
refuses to accept connections anymore.

I can't even manually stop xl2tpd using "/etc/init.d/xl2tpd stop" and I
have to kill -9 this daemon instead.

>From my understanding, it seems to be related to MacOSX clients, because
from GNU/Linux and Windows clients I've always been able to
connect/disconnect several times in a row without stalling xl2tpd.
For OSX ones it seems sometimes at the time of disconnecting something
bad happens.

Here's a complete log of the last time this problem occured :

Nov 23 16:47:22 gwvpn xl2tpd[1452]: network_thread: recv packet from 192.0.2.1, size = 60, tunnel = 0, call = 0 ref=0 refhim=0
Nov 23 16:47:22 gwvpn xl2tpd[1452]: get_call: allocating new tunnel for host 192.0.2.1, port 58139.
Nov 23 16:47:22 gwvpn xl2tpd[1452]: handle_avps: handling avp's for tunnel 63152, call 0
Nov 23 16:47:22 gwvpn xl2tpd[1452]: message_type_avp: message type 1 (Start-Control-Connection-Request)
Nov 23 16:47:22 gwvpn xl2tpd[1452]: protocol_version_avp: peer is using version 1, revision 0.
Nov 23 16:47:22 gwvpn xl2tpd[1452]: framing_caps_avp: supported peer frames: async sync
Nov 23 16:47:22 gwvpn xl2tpd[1452]: hostname_avp: peer reports hostname ''
Nov 23 16:47:22 gwvpn xl2tpd[1452]: assigned_tunnel_avp: using peer's tunnel 9
Nov 23 16:47:22 gwvpn xl2tpd[1452]: receive_window_size_avp: peer wants RWS of 4.  Will use flow control.
Nov 23 16:47:22 gwvpn xl2tpd[1452]: control_finish: message type is Start-Control-Connection-Request(1).  Tunnel is 9, call is 0.
Nov 23 16:47:22 gwvpn xl2tpd[1452]: control_finish: sending SCCRP
Nov 23 16:47:24 gwvpn xl2tpd[1452]: build_fdset: closing down tunnel 23129
Nov 23 16:47:24 gwvpn xl2tpd[1452]: network_thread: recv packet from 192.0.2.1, size = 60, tunnel = 0, call = 0 ref=0 refhim=0
Nov 23 16:47:24 gwvpn xl2tpd[1452]: get_call: allocating new tunnel for host 192.0.2.1, port 58139.
Nov 23 16:47:24 gwvpn xl2tpd[1452]: handle_avps: handling avp's for tunnel 15637, call 53326
Nov 23 16:47:24 gwvpn xl2tpd[1452]: message_type_avp: message type 1 (Start-Control-Connection-Request)
Nov 23 16:47:24 gwvpn xl2tpd[1452]: protocol_version_avp: peer is using version 1, revision 0.
Nov 23 16:47:24 gwvpn xl2tpd[1452]: framing_caps_avp: supported peer frames: async sync
Nov 23 16:47:24 gwvpn xl2tpd[1452]: hostname_avp: peer reports hostname ''
Nov 23 16:47:24 gwvpn xl2tpd[1452]: assigned_tunnel_avp: using peer's tunnel 9
Nov 23 16:47:24 gwvpn xl2tpd[1452]: receive_window_size_avp: peer wants RWS of 4.  Will use flow control.
Nov 23 16:47:24 gwvpn xl2tpd[1452]: control_finish: message type is Start-Control-Connection-Request(1).  Tunnel is 9, call is 0.
Nov 23 16:47:24 gwvpn xl2tpd[1452]: control_finish: Peer requested tunnel 9 twice, ignoring second one.
Nov 23 16:47:24 gwvpn xl2tpd[1452]: build_fdset: closing down tunnel 15637
Nov 23 16:47:24 gwvpn xl2tpd[1452]: network_thread: recv packet from 192.0.2.1, size = 20, tunnel = 63152, call = 0 ref=0 refhim=0
Nov 23 16:47:24 gwvpn xl2tpd[1452]: handle_avps: handling avp's for tunnel 63152, call 0
Nov 23 16:47:24 gwvpn xl2tpd[1452]: message_type_avp: message type 3 (Start-Control-Connection-Connected)
Nov 23 16:47:24 gwvpn xl2tpd[1452]: control_finish: message type is Start-Control-Connection-Connected(3).  Tunnel is 9, call is 0.
Nov 23 16:47:24 gwvpn xl2tpd[1452]: Connection established to 192.0.2.1, 58139.  Local: 63152, Remote: 9 (ref=0/0).  LNS session is 'default'
Nov 23 16:47:24 gwvpn xl2tpd[1452]: network_thread: recv packet from 192.0.2.1, size = 38, tunnel = 63152, call = 0 ref=0 refhim=0
Nov 23 16:47:24 gwvpn xl2tpd[1452]: handle_avps: handling avp's for tunnel 63152, call 0
Nov 23 16:47:24 gwvpn xl2tpd[1452]: message_type_avp: message type 10 (Incoming-Call-Request)
Nov 23 16:47:24 gwvpn xl2tpd[1452]: message_type_avp: new incoming call
Nov 23 16:47:24 gwvpn xl2tpd[1452]: assigned_call_avp: using peer's call 5198
Nov 23 16:47:24 gwvpn xl2tpd[1452]: call_serno_avp: serial number is 1
Nov 23 16:47:24 gwvpn xl2tpd[1452]: control_finish: message type is Incoming-Call-Request(10).  Tunnel is 9, call is 0.
Nov 23 16:47:24 gwvpn xl2tpd[1452]: control_finish: Sending ICRP
Nov 23 16:47:24 gwvpn xl2tpd[1452]: network_thread: recv packet from 192.0.2.1, size = 40, tunnel = 63152, call = 14149 ref=0 refhim=0
Nov 23 16:47:24 gwvpn xl2tpd[1452]: handle_avps: handling avp's for tunnel 63152, call 14149
Nov 23 16:47:24 gwvpn xl2tpd[1452]: message_type_avp: message type 12 (Incoming-Call-Connected)
Nov 23 16:47:24 gwvpn xl2tpd[1452]: tx_speed_avp: transmit baud rate is 1000000
Nov 23 16:47:24 gwvpn xl2tpd[1452]: frame_type_avp: peer uses: async frames
Nov 23 16:47:24 gwvpn xl2tpd[1452]: control_finish: message type is Incoming-Call-Connected(12).  Tunnel is 9, call is 5198.
Nov 23 16:47:24 gwvpn xl2tpd[1452]: start_pppd: I'm running:
Nov 23 16:47:24 gwvpn xl2tpd[1452]: "/usr/sbin/pppd"
Nov 23 16:47:24 gwvpn xl2tpd[1452]: "passive"
Nov 23 16:47:24 gwvpn xl2tpd[1452]: "nodetach"
Nov 23 16:47:24 gwvpn xl2tpd[1452]: "10.10.66.254:10.10.66.1"
Nov 23 16:47:24 gwvpn xl2tpd[1452]: "refuse-chap"
Nov 23 16:47:24 gwvpn xl2tpd[1452]: "auth"
Nov 23 16:47:24 gwvpn xl2tpd[1452]: "require-pap"
Nov 23 16:47:24 gwvpn xl2tpd[1452]: "debug"
Nov 23 16:47:24 gwvpn xl2tpd[1452]: "file"
Nov 23 16:47:24 gwvpn xl2tpd[1452]: "/etc/ppp/options.l2tpd.lns"
Nov 23 16:47:24 gwvpn xl2tpd[1452]: "/dev/pts/0"
Nov 23 16:47:24 gwvpn xl2tpd[1452]: Call established with 192.0.2.1, Local: 14149, Remote: 5198, Serial: 1
Nov 23 16:47:24 gwvpn xl2tpd[1452]: network_thread: recv packet from 192.0.2.1, size = 32, tunnel = 63152, call = 14149 ref=0 refhim=0
Nov 23 16:47:24 gwvpn xl2tpd[1452]: network_thread: recv packet from 192.0.2.1, size = 40, tunnel = 63152, call = 14149 ref=0 refhim=0
Nov 23 16:47:24 gwvpn xl2tpd[1452]: network_thread: recv packet from 192.0.2.1, size = 20, tunnel = 63152, call = 14149 ref=0 refhim=0

... lots of identical lines

Nov 23 16:56:55 gwvpn xl2tpd[1452]: network_thread: recv packet from 192.0.2.1, size = 20, tunnel = 63152, call = 14149 ref=0 refhim=0
Nov 23 16:57:03 gwvpn xl2tpd[1452]: network_thread: recv packet from 192.0.2.1, size = 28, tunnel = 63152, call = 14149 ref=0 refhim=0
Nov 23 16:57:03 gwvpn xl2tpd[1452]: network_thread: recv packet from 192.0.2.1, size = 42, tunnel = 63152, call = 14149 ref=0 refhim=0
Nov 23 16:57:03 gwvpn xl2tpd[1452]: handle_avps: handling avp's for tunnel 63152, call 14149
Nov 23 16:57:03 gwvpn xl2tpd[1452]: message_type_avp: message type 14 (Call-Disconnect-Notify)
Nov 23 16:57:03 gwvpn xl2tpd[1452]: assigned_call_avp: using peer's call 5198
Nov 23 16:57:03 gwvpn xl2tpd[1452]: result_code_avp: result code out of range (768 0 14).  Ignoring.
Nov 23 16:57:03 gwvpn xl2tpd[1452]: control_finish: message type is Call-Disconnect-Notify(14).  Tunnel is 9, call is 5198.
Nov 23 16:57:03 gwvpn xl2tpd[1452]: control_finish: Peer tried to disconnect without specifying result code.
Nov 23 16:57:03 gwvpn xl2tpd[1452]: network_thread: bad packet
Nov 23 16:57:03 gwvpn xl2tpd[1452]: network_thread: recv packet from 192.0.2.1, size = 42, tunnel = 63152, call = 0 ref=0 refhim=0
Nov 23 16:57:03 gwvpn xl2tpd[1452]: handle_avps: handling avp's for tunnel 63152, call 0
Nov 23 16:57:03 gwvpn xl2tpd[1452]: message_type_avp: message type 4 (Stop-Control-Connection-Notification)
Nov 23 16:57:03 gwvpn xl2tpd[1452]: assigned_tunnel_avp: using peer's tunnel 9
Nov 23 16:57:03 gwvpn xl2tpd[1452]: result_code_avp: result code out of range (256 0 14).  Ignoring.
Nov 23 16:57:03 gwvpn xl2tpd[1452]: control_finish: message type is Stop-Control-Connection-Notification(4).  Tunnel is 9, call is 0.
Nov 23 16:57:03 gwvpn xl2tpd[1452]: control_finish: Peer tried to disconnect without specifying result code.
Nov 23 16:57:03 gwvpn xl2tpd[1452]: network_thread: bad packet
Nov 23 16:57:06 gwvpn xl2tpd[1452]: child_handler : pppd exited for call 5198 with code 16

There's absolutely NOTHING more here, xl2tpd seems to be dead, doesn't
log anything even when other clients try to connect, and doesn't accept
connections anymore.

Now we do an "/etc/init.d/xl2tpd stop" :

Nov 25 06:41:19 gwvpn xl2tpd[1452]: udp_xmit failed with err=-1:Interrupted system call should be restarted
Nov 25 06:41:19 gwvpn xl2tpd[1452]: call_close: Call 14149 to 192.0.2.1 disconnected

But in fact we must kill -9 xl2tpd otherwise it wouldn't die.

Between Nov 23 16:57 and Nov 25 06:41, every 30 seconds, there's a line
like this one in /var/log/auth.log :

Nov 25 06:30:39 gwvpn pluto[1110]: initiate on demand from MYVPNGWIPADDRESS:1701 to 192.0.2.1:58139 proto=17 state: fos_start because: acquire

Any idea what could be wrong ?

Thanks in advance.

Jerome Alet