OpenWrt Forum Archive

Topic: L2TP over IPsec with PSK using racoon/xl2tpd

The content of this topic has been archived between 26 Mar 2018 and 19 Apr 2018. There are no obvious gaps in this topic, but there may still be some posts missing at the end.

Post #51
languagegame
24 Jun 2012, 17:29
alfredlim wrote:

Sorry to bring up this thread.

Any idea what does this error means?

xl2tpd[6049]: control_finish: Peer requested tunnel 15 twice, ignoring second one.
xl2tpd[6049]: control_finish: Peer requested tunnel 15 twice, ignoring second one.
xl2tpd[6049]: Maximum retries exceeded for tunnel 17563.  Closing.
xl2tpd[6049]: Connection 15 closed to x.x.x.x, port 61760 (Timeout)
xl2tpd[6049]: control_finish: Peer requested tunnel 15 twice, ignoring second one.
xl2tpd[6049]: Unable to deliver closing message for tunnel 17563. Destroying anyway.
xl2tpd[6049]: control_finish: Peer requested tunnel 15 twice, ignoring second one.
xl2tpd[6049]: Maximum retries exceeded for tunnel 14753.  Closing.
xl2tpd[6049]: Connection 15 closed to x.x.x.x, port 61760 (Timeout)
xl2tpd[6049]: Unable to deliver closing message for tunnel 14753. Destroying anyway.

where x.x.x.x is my public ip address

This means that setkey.conf was not run.  Check the /etc/init.d/racoon script and make sure it passes the WAN IP address to setkey.conf when it executes it.

Post #52
languagegame
24 Jun 2012, 22:07
TheCondor wrote:

Hi, someone can help me with strongswan+xl2tp? I can't use racoon because there aren't some package (like zlib, kmod-cbc and other) for my openwrt version (10.03.1 final on tplink wr1043nd).

I was able to get this to work on 10.03.1 final on an WNDR3700.  Trick is that two of the packages must be installed from the latest trunk.  Rest of packages can be installed from the 10.03.1 final packages.

Specifically, install libopenssl and ip-sect tools from trunk (replace the hardware version, ar71xx, with your router version):

opkg install http://downloads.openwrt.org/snapshots/trunk/ar71xx/packages/libopenssl_1.0.1c-1_ar71xx.ipk
opkg install http://downloads.openwrt.org/snapshots/trunk/ar71xx/packages/ipsec-tools_0.8.0-2_ar71xx.ipk

Then install these packages from 10.03.1 final:

opkg install kmod-ipsec4
opkg install iptables-mod-ipsec
opkg install kmod-crypto-authenc
opkg install xl2tpd

This will install enough to get up and running. 

You'll need to modify /etc/init.d/racoon though, as it references some items that don't apply in 10.03.1 final.

#!/bin/sh /etc/rc.common

START=49

start() {
  include /lib/network
  scan_interfaces
  wan_ip="$(uci_get_state network wan ipaddr)"

  /etc/setkey.conf $wan_ip

  test -d /var/racoon || mkdir /var/racoon

  start-stop-daemon -S -x racoon
}

stop() {
  start-stop-daemon -K -q -x racoon
}

(Last edited by languagegame on 25 Jun 2012, 06:33)

Post #53
Tu13es
28 Jun 2012, 15:56

I think I've got everything set up for this but I'm still not able to connect via both my iPhone and Mac.  I get a "server not responding" message.

I'm not sure if the issue with racoon not running or a firewall issue.  The racoon process is running, but I don't see a /var/log/racoon.txt.  Should I be looking somewhere else?  Where is this logfile defined?

I have the firewall rules configured like in the OP, but I'm wondering if one of my zones is preventing it from working?  Here's what I have:

config defaults
    option syn_flood '1'
    option input 'ACCEPT'
    option output 'ACCEPT'
    option forward 'REJECT'
    option drop_invalid '1'

config zone
    option name 'lan'
    option input 'ACCEPT'
    option output 'ACCEPT'
    option forward 'REJECT'

config zone
    option name 'wan'
    option input 'REJECT'
    option output 'ACCEPT'
    option forward 'REJECT'
    option masq '1'
    option mtu_fix '1'

config forwarding
    option src 'lan'
    option dest 'wan'

I'm running arokh's WNDR3700 alternate build.  I'm assuming the L2TP packages in it are sufficient to run this VPN.  Or do I need to manually install packages still?

Edit: This ended up being a problem with racoon that I have yet to solve, not a firewall issue.

(Last edited by Tu13es on 22 Oct 2012, 13:44)

Post #54
netbus
3 Jul 2012, 13:51

My tunnel is not comming up cause I get "avp is incorrect size" message
I am trying to create a tunnel with an android smartphone

Jul  3 14:48:46 Gateway daemon.debug xl2tpd[18375]: handle_avps: handling avp's for tunnel 43998, call 0
Jul  3 14:48:46 Gateway daemon.debug xl2tpd[18375]: message_type_avp: message type 4 (Stop-Control-Connection-Notification)
Jul  3 14:48:46 Gateway daemon.debug xl2tpd[18375]: assigned_tunnel_avp: using peer's tunnel 24425
Jul  3 14:48:46 Gateway daemon.debug xl2tpd[18375]: result_code_avp: avp is incorrect size.  8 < 10
Jul  3 14:48:46 Gateway daemon.warn xl2tpd[18375]: handle_avps: Bad exit status handling attribute 1 (Result Code) on mandatory packet.
Jul  3 14:48:46 Gateway daemon.debug xl2tpd[18375]: handle_packet: bad AVP handling!
Jul  3 14:48:46 Gateway daemon.debug xl2tpd[18375]: network_thread: bad packet

anybody an idea?

Post #55
username2r
25 Sep 2012, 08:26

Received    Severity    Tag    Message   
09/24/12 15:49:09    Debug    xl2tpd[2395]    Unable to deliver closing message for tunnel 44902. Destroying anyway.   
09/24/12 15:49:04    Info    xl2tpd[2395]    Connection 3 closed to XX.XX.XXX.XXX, port 57588 (Timeout)   
09/24/12 15:49:04    Notice    xl2tpd[2395]    Maximum retries exceeded for tunnel 44902.  Closing.   
09/24/12 15:49:02    Info    racoon    INFO: KA remove: YY.YYY.YY.YY[4500]->XX.XX.XXX.XXX[43924]   
09/24/12 15:49:02    Info    racoon    INFO: ISAKMP-SA deleted YY.YYY.YY.YY[4500]-XX.XX.XXX.XXX[43924] spi:0da7a1945cb31062:65e3f5e2b144a172   
09/24/12 15:49:02    Info    racoon    INFO: ISAKMP-SA expired YY.YYY.YY.YY[4500]-XX.XX.XXX.XXX[43924] spi:0da7a1945cb31062:65e3f5e2b144a172   
09/24/12 15:49:02    Info    racoon    INFO: purged IPsec-SA proto_id=ESP spi=228808141.   
09/24/12 15:49:02    Info    racoon    INFO: deleting a generated policy.   
09/24/12 15:49:01    Debug    xl2tpd[2395]    control_finish: Peer requested tunnel 3 twice, ignoring second one.   
09/24/12 15:48:53    Debug    xl2tpd[2395]    Unable to deliver closing message for tunnel 20249. Destroying anyway.   
09/24/12 15:48:53    Debug    xl2tpd[2395]    control_finish: Peer requested tunnel 3 twice, ignoring second one.   
09/24/12 15:48:49    Debug    xl2tpd[2395]    control_finish: Peer requested tunnel 3 twice, ignoring second one.   
09/24/12 15:48:48    Info    xl2tpd[2395]    Connection 3 closed to XX.XX.XXX.XXX, port 57588 (Timeout)   
09/24/12 15:48:48    Notice    xl2tpd[2395]    Maximum retries exceeded for tunnel 20249.  Closing.   
09/24/12 15:48:45    Debug    xl2tpd[2395]    control_finish: Peer requested tunnel 3 twice, ignoring second one.   
09/24/12 15:48:43    Debug    xl2tpd[2395]    control_finish: Peer requested tunnel 3 twice, ignoring second one.   
09/24/12 15:48:41    Info    racoon    INFO: IPsec-SA established: ESP/Transport YY.YYY.YY.YY[4500]->XX.XX.XXX.XXX[43924] spi=228808141(0xda355cd)   
09/24/12 15:48:41    Info    racoon    INFO: IPsec-SA established: ESP/Transport YY.YYY.YY.YY[4500]->XX.XX.XXX.XXX[43924] spi=45329826(0x2b3ada2)   
09/24/12 15:48:41    Info    racoon    INFO: Adjusting peer's encmode UDP-Transport(4)->Transport(2)   
09/24/12 15:48:41    Info    racoon    INFO: Adjusting my encmode UDP-Transport->Transport   
09/24/12 15:48:41    Info    racoon    INFO: no policy found, try to generate the policy : 192.168.1.3/32[57588] YY.YYY.YY.YY/32[1701] proto=udp dir=in   
09/24/12 15:48:41    Info    racoon    INFO: respond new phase 2 negotiation: YY.YYY.YY.YY[4500]<=>XX.XX.XXX.XXX[43924]   
09/24/12 15:48:40    Info    racoon    INFO: ISAKMP-SA established YY.YYY.YY.YY[4500]-XX.XX.XXX.XXX[43924] spi:0da7a1945cb31062:65e3f5e2b144a172   
09/24/12 15:48:40    Info    racoon    INFO: purging spi=264787826.   
09/24/12 15:48:40    Info    racoon    [XX.XX.XXX.XXX] INFO: received INITIAL-CONTACT   
09/24/12 15:48:40    Info    racoon    INFO: KA list add: YY.YYY.YY.YY[4500]->XX.XX.XXX.XXX[43924]   
09/24/12 15:48:40    Info    racoon    INFO: NAT-T: ports changed to: XX.XX.XXX.XXX[43924]<->YY.YYY.YY.YY[4500]   
09/24/12 15:48:40    Info    racoon    [XX.XX.XXX.XXX] NOTIFY: Using default PSK.   
09/24/12 15:48:40    Info    racoon    [XX.XX.XXX.XXX] ERROR: couldn't find the pskey for XX.XX.XXX.XXX.   
09/24/12 15:48:40    Info    racoon    INFO: Adding remote and local NAT-D payloads.   
09/24/12 15:48:40    Info    racoon    [YY.YYY.YY.YY] INFO: Hashing YY.YYY.YY.YY[500] with algo #2    
09/24/12 15:48:40    Info    racoon    [XX.XX.XXX.XXX] INFO: Hashing XX.XX.XXX.XXX[61672] with algo #2    
09/24/12 15:48:40    Info    racoon    INFO: NAT detected: PEER   
09/24/12 15:48:40    Info    racoon    INFO: NAT-D payload #1 doesn't match   
09/24/12 15:48:40    Info    racoon    [XX.XX.XXX.XXX] INFO: Hashing XX.XX.XXX.XXX[61672] with algo #2    
09/24/12 15:48:40    Info    racoon    INFO: NAT-D payload #0 verified   
09/24/12 15:48:40    Info    racoon    [YY.YYY.YY.YY] INFO: Hashing YY.YYY.YY.YY[500] with algo #2    
09/24/12 15:48:40    Info    racoon    [XX.XX.XXX.XXX] INFO: Selected NAT-T version: RFC 3947   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: DPD   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-03   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-04   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-05   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-06   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-07   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-08   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: RFC 3947   
09/24/12 15:48:40    Info    racoon    INFO: begin Identity Protection mode.   
09/24/12 15:48:40    Info    racoon    INFO: respond new phase 1 negotiation: YY.YYY.YY.YY[500]<=>XX.XX.XXX.XXX[61672]

I cant connect from my iPad, above is the syslog from the period where I attempt. Can anyone help?

Post #56
Tu13es
22 Oct 2012, 04:12
username2r wrote:

Received    Severity    Tag    Message   
09/24/12 15:49:09    Debug    xl2tpd[2395]    Unable to deliver closing message for tunnel 44902. Destroying anyway.   
09/24/12 15:49:04    Info    xl2tpd[2395]    Connection 3 closed to XX.XX.XXX.XXX, port 57588 (Timeout)   
09/24/12 15:49:04    Notice    xl2tpd[2395]    Maximum retries exceeded for tunnel 44902.  Closing.   
09/24/12 15:49:02    Info    racoon    INFO: KA remove: YY.YYY.YY.YY[4500]->XX.XX.XXX.XXX[43924]   
09/24/12 15:49:02    Info    racoon    INFO: ISAKMP-SA deleted YY.YYY.YY.YY[4500]-XX.XX.XXX.XXX[43924] spi:0da7a1945cb31062:65e3f5e2b144a172   
09/24/12 15:49:02    Info    racoon    INFO: ISAKMP-SA expired YY.YYY.YY.YY[4500]-XX.XX.XXX.XXX[43924] spi:0da7a1945cb31062:65e3f5e2b144a172   
09/24/12 15:49:02    Info    racoon    INFO: purged IPsec-SA proto_id=ESP spi=228808141.   
09/24/12 15:49:02    Info    racoon    INFO: deleting a generated policy.   
09/24/12 15:49:01    Debug    xl2tpd[2395]    control_finish: Peer requested tunnel 3 twice, ignoring second one.   
09/24/12 15:48:53    Debug    xl2tpd[2395]    Unable to deliver closing message for tunnel 20249. Destroying anyway.   
09/24/12 15:48:53    Debug    xl2tpd[2395]    control_finish: Peer requested tunnel 3 twice, ignoring second one.   
09/24/12 15:48:49    Debug    xl2tpd[2395]    control_finish: Peer requested tunnel 3 twice, ignoring second one.   
09/24/12 15:48:48    Info    xl2tpd[2395]    Connection 3 closed to XX.XX.XXX.XXX, port 57588 (Timeout)   
09/24/12 15:48:48    Notice    xl2tpd[2395]    Maximum retries exceeded for tunnel 20249.  Closing.   
09/24/12 15:48:45    Debug    xl2tpd[2395]    control_finish: Peer requested tunnel 3 twice, ignoring second one.   
09/24/12 15:48:43    Debug    xl2tpd[2395]    control_finish: Peer requested tunnel 3 twice, ignoring second one.   
09/24/12 15:48:41    Info    racoon    INFO: IPsec-SA established: ESP/Transport YY.YYY.YY.YY[4500]->XX.XX.XXX.XXX[43924] spi=228808141(0xda355cd)   
09/24/12 15:48:41    Info    racoon    INFO: IPsec-SA established: ESP/Transport YY.YYY.YY.YY[4500]->XX.XX.XXX.XXX[43924] spi=45329826(0x2b3ada2)   
09/24/12 15:48:41    Info    racoon    INFO: Adjusting peer's encmode UDP-Transport(4)->Transport(2)   
09/24/12 15:48:41    Info    racoon    INFO: Adjusting my encmode UDP-Transport->Transport   
09/24/12 15:48:41    Info    racoon    INFO: no policy found, try to generate the policy : 192.168.1.3/32[57588] YY.YYY.YY.YY/32[1701] proto=udp dir=in   
09/24/12 15:48:41    Info    racoon    INFO: respond new phase 2 negotiation: YY.YYY.YY.YY[4500]<=>XX.XX.XXX.XXX[43924]   
09/24/12 15:48:40    Info    racoon    INFO: ISAKMP-SA established YY.YYY.YY.YY[4500]-XX.XX.XXX.XXX[43924] spi:0da7a1945cb31062:65e3f5e2b144a172   
09/24/12 15:48:40    Info    racoon    INFO: purging spi=264787826.   
09/24/12 15:48:40    Info    racoon    [XX.XX.XXX.XXX] INFO: received INITIAL-CONTACT   
09/24/12 15:48:40    Info    racoon    INFO: KA list add: YY.YYY.YY.YY[4500]->XX.XX.XXX.XXX[43924]   
09/24/12 15:48:40    Info    racoon    INFO: NAT-T: ports changed to: XX.XX.XXX.XXX[43924]<->YY.YYY.YY.YY[4500]   
09/24/12 15:48:40    Info    racoon    [XX.XX.XXX.XXX] NOTIFY: Using default PSK.   
09/24/12 15:48:40    Info    racoon    [XX.XX.XXX.XXX] ERROR: couldn't find the pskey for XX.XX.XXX.XXX.   
09/24/12 15:48:40    Info    racoon    INFO: Adding remote and local NAT-D payloads.   
09/24/12 15:48:40    Info    racoon    [YY.YYY.YY.YY] INFO: Hashing YY.YYY.YY.YY[500] with algo #2    
09/24/12 15:48:40    Info    racoon    [XX.XX.XXX.XXX] INFO: Hashing XX.XX.XXX.XXX[61672] with algo #2    
09/24/12 15:48:40    Info    racoon    INFO: NAT detected: PEER   
09/24/12 15:48:40    Info    racoon    INFO: NAT-D payload #1 doesn't match   
09/24/12 15:48:40    Info    racoon    [XX.XX.XXX.XXX] INFO: Hashing XX.XX.XXX.XXX[61672] with algo #2    
09/24/12 15:48:40    Info    racoon    INFO: NAT-D payload #0 verified   
09/24/12 15:48:40    Info    racoon    [YY.YYY.YY.YY] INFO: Hashing YY.YYY.YY.YY[500] with algo #2    
09/24/12 15:48:40    Info    racoon    [XX.XX.XXX.XXX] INFO: Selected NAT-T version: RFC 3947   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: DPD   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-03   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-04   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-05   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-06   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-07   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-08   
09/24/12 15:48:40    Info    racoon    INFO: received Vendor ID: RFC 3947   
09/24/12 15:48:40    Info    racoon    INFO: begin Identity Protection mode.   
09/24/12 15:48:40    Info    racoon    INFO: respond new phase 1 negotiation: YY.YYY.YY.YY[500]<=>XX.XX.XXX.XXX[61672]

I cant connect from my iPad, above is the syslog from the period where I attempt. Can anyone help?

I'm hitting the same thing on my iPhone.  I also see the following line:

Oct 21 23:11:10 OpenWrt daemon.info racoon: ERROR: phase1 negotiation failed due to time up. e82e51960155b572:ca721a6e60ceec9c

Post #57
mmhorda
22 Nov 2012, 21:16

Hi everyone. sorry for double post.
How can i connect another router with openwt to this setup which is on first page?
thanks in advance.

Post #58
Dickie
26 Nov 2012, 23:17

Can someone post a successful log from starting the racoon/xl2tpd , through to connecting a client please? 
I'm sure we could all figure out at least where the issues are if we had some point of reference.   For example I can initiate the connection fine, but the last stage I get is;

racoon: INFO: KA list add:   etc etc

then I never get anything else.  So I'm not sure if the problem is with my xl2tp config of firewall etc.

Post #60
phukit
6 Dec 2012, 18:33

Hi,

I am trying to setup this IPSec VPN however I get this error for every package I try to install.

Installing xl2tpd (1.3.1-1) to root...
Downloading http://downloads.openwrt.org/attitude_adjustment/12.09-rc1/ar71xx/generic/packages/xl2tpd_1.3.1-1_ar71xx.ipk.

                    Collected errors:
 * satisfy_dependencies_for: Cannot satisfy the following dependencies for xl2tpd:
 *     kernel (= 3.3.8-1-5440da3a2c45184a32da6bba25b8dd2a) *     kernel (= 3.3.8-1-5440da3a2c45184a32da6bba25b8dd2a) * 
 * opkg_install_cmd: Cannot install package xl2tpd.

I am on kernel 3.3.8 is it saying I need to update to 3.3.8-1?

Thanks

Post #61
avbohemen
14 Dec 2012, 17:23
rolfl wrote:

http://downloads.openwrt.org/snapshots/trunk/ar71xx/ doesn't have xl2tp package anymore.

Is there any other l2tp package that would work? If so what would need to be changed in the setup?

xl2tpd is not in the downloads anymore because it fails to compile. See https://dev.openwrt.org/ticket/12577 I just created a working patch, so hopefully it will be taken by the devs.

However, on the newer builds (kernel 3.6+) I have some trouble getting L2TP over IPsec to work automatically.

After a reboot, racoon wil not start, with an error in setkey.conf ("pfkey_open: Address family not supported by protocol"). This can be fixed by entering "insmod af_key", but I'm not really sure why that is not automatic anymore.

Post #62
Szczesny
4 Jan 2013, 09:13
avbohemen wrote:

After a reboot, racoon wil not start, with an error in setkey.conf ("pfkey_open: Address family not supported by protocol"). This can be fixed by entering "insmod af_key", but I'm not really sure why that is not automatic anymore.

Hi,
I have solution for that.

The xfrm modules must be loaded before af_key. So, change content of /etc/modules.d/30-ipsec file to this one:
xfrm_ipcomp
xfrm_algo
xfrm_user
af_key

Post #63
Szczesny
11 Jan 2013, 10:43

Hi,
Ok, now I have the problem. Here is the log:
Jan 11 10:38:58 bane daemon.info racoon: INFO: respond new phase 1 negotiation: xxWAN_IPxx[500]<=>xxREMOTE_IPxx[500]
Jan 11 10:38:58 bane daemon.info racoon: INFO: begin Identity Protection mode.
Jan 11 10:38:58 bane daemon.info racoon: INFO: received Vendor ID: RFC 3947
Jan 11 10:38:58 bane daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02
Jan 11 10:38:58 bane daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02
Jan 11 10:38:58 bane daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-00
Jan 11 10:38:58 bane daemon.info racoon: INFO: received broken Microsoft ID: FRAGMENTATION
Jan 11 10:38:58 bane daemon.info racoon: INFO: received Vendor ID: DPD
Jan 11 10:38:58 bane daemon.info racoon: [xxREMOTE_IPxx] INFO: Selected NAT-T version: RFC 3947
Jan 11 10:38:58 bane daemon.info racoon: [xxWAN_IPxx] INFO: Hashing xxWAN_IPxx[500] with algo #2
Jan 11 10:38:58 bane daemon.info racoon: INFO: NAT-D payload #0 verified
Jan 11 10:38:58 bane daemon.info racoon: [xxREMOTE_IPxx] INFO: Hashing xxREMOTE_IPxx[500] with algo #2
Jan 11 10:38:58 bane daemon.info racoon: INFO: NAT-D payload #1 doesn't match
Jan 11 10:38:58 bane daemon.info racoon: INFO: NAT detected: PEER
Jan 11 10:38:58 bane daemon.info racoon: [xxREMOTE_IPxx] INFO: Hashing xxREMOTE_IPxx[500] with algo #2
Jan 11 10:38:58 bane daemon.info racoon: [xxWAN_IPxx] INFO: Hashing xxWAN_IPxx[500] with algo #2
Jan 11 10:38:58 bane daemon.info racoon: INFO: Adding remote and local NAT-D payloads.
Jan 11 10:38:58 bane daemon.info racoon: [xxREMOTE_IPxx] ERROR: couldn't find the pskey for xxREMOTE_IPxx.
Jan 11 10:38:58 bane daemon.info racoon: [xxREMOTE_IPxx] NOTIFY: Using default PSK.
Jan 11 10:39:48 bane daemon.info racoon: ERROR: phase1 negotiation failed due to time up. 1d512a7e8de8fae5:9adf8602175e7a5d


I'm unable to connect via VPN. Does anyone have solution for that?

BR,
Rafal

Post #64
dborca
20 Feb 2013, 16:04

Hello,

to people seeing racoon: [xxREMOTE_IPxx] ERROR: couldn't find the pskey for xxREMOTE_IPxx
and NOT seeing racoon: [xxREMOTE_IPxx] NOTIFY: Using default PSK.

Most probably racoon cannot find pre-shared key. PSK file has the following format:
IDENTIFIER1 SHAREDKEY1
IDENTIFIER2 SHAREDKEY2
...

Standard (non-patched) racoon does not recognize * as a wildcard IDENTIFIER.  The patch is here:
https://dev.openwrt.org/browser/package … -psk.patch

More troubleshooting:

P: tools complain about some protocol not being registered
S: make sure you have l2tp in /etc/services

P: racoon and xl2tpd started up, racoon connects but xl2tpd is not receiving anything
S: make sure you have the relevant kernel modules loaded.  By relevant, I mean:
    modprobe xfrm_user # ip xfrm policy
    modprobe xt_policy # iptables ... -m policy
    modprobe af_key # racoon
    modprobe esp4 # racoon
    modprobe xfrm4_mode_transport # racoon <-> xl2tpd

P: xl2tpd says something about "Peer requested tunnel 22 twice, ignoring second one."
S: make sure you have the right policies
    ip xfrm policy add src $WANIP dst 0.0.0.0/0 proto udp sport 1701 dir out tmpl proto esp mode transport level required
    ip xfrm policy add src 0.0.0.0/0 dst $WANIP proto udp dport 1701 dir in tmpl proto esp mode transport level required

P: xl2tpd says something about "LCP: timeout sending Config-Requests"
S: make sure you have "force userspace = yes" in xl2tpd.conf
xl2tpd <= v1.3.1 lies about "IPsec SAref does not work with L2TP kernel mode yet, enabling forceuserspace=yes"
Actually it does NOT force userspace.

P: Ok, I connected, but DNS is not responding
S: most probably the DNS daemon does not listen on the newly created pppX interface.

I would like to thank @arokh for his great tutorial which helped me a lot.  I suggest he adds a troubleshooting section in the original post smile

-dborca

Post #65
jol
23 Feb 2013, 20:25

Thanks for this thread. I tried to set this up, using backfire 10.03.1 and the instructions in post #52 above (I am using openwrt-ar71xx-wndr3700-jffs2-sysupgrade), but did not succeed so far. There is one thing totally different in my setup, which is that I am running OpenWRT as an access point and bridge (including an OpenVPN bridge) behind another router and thus I am not using the WAN interface and firewall at all (so far). Of course I configured the other router to forward ESP, UDP ports 500, 4500, and 1701 to OpenWRT. In this setup, do I need to enter the external address (I am using `wget http://ipecho.net/plain -O - -q ; echo` ) or the internal address in /etc/init.d/racoon? How can I enable debug output and where can I locate that? Any other issue to watch out for?
Thanks & Best regards, jol

Post #66
avbohemen
24 May 2013, 10:53

Ever since trunk got updated with iptables 1.4.18 and/or firewall3, I get the following errors in my firewall config, regarding this section:

# L2TP/ESP
config 'rule'
        option 'target' 'ACCEPT'
        option '_name' 'L2TP ESP'   
        option 'src' 'wan'     
        option 'proto' 'udp'
        option 'dest_port' '1701'
        option 'extra' '-m policy --strict --dir in --pol ipsec --proto esp'

After doing "/etc/init.d/firewall reload", I get:

Warning: Unable to locate ipset utility, disabling ipset support
* Clearing IPv4 filter table
* Clearing IPv4 nat table
* Clearing IPv4 mangle table
* Clearing IPv4 raw table
* Populating IPv4 filter table
   * Zone 'lan'
   * Zone 'wan'
   * Rule 'IPsec NAT-T'
   * Rule 'IPsec IKE'
   * Rule 'IPsec ESP'
   * Rule 'L2TP ESP'
   * Rule 'Allow-Network-Printer'
   * Rule 'Allow-DHCP-Renew'
   * Rule 'Allow-Ping'
   * Redirect 'Kerio-WebMail'
   * Redirect 'Kerio-IMAP'
   * Forward 'lan' -> 'wan'
* Populating IPv4 nat table
   * Zone 'lan'
   * Zone 'wan'
   * Redirect 'Kerio-WebMail'
   * Redirect 'Kerio-IMAP'
* Populating IPv4 mangle table
   * Zone 'lan'
   * Zone 'wan'
* Populating IPv4 raw table
   * Zone 'lan'
   * Zone 'wan'
* Clearing IPv6 filter table
* Clearing IPv6 mangle table
* Clearing IPv6 raw table
* Populating IPv6 filter table
   * Zone 'lan'
   * Zone 'wan'
   * Rule 'IPsec NAT-T'
   * Rule 'IPsec IKE'
   * Rule 'IPsec ESP'
   * Rule 'L2TP ESP'
/usr/lib/iptables/libxt_policy.so: no "policy" extension found for this protocol
fw3_ipt_rule_append(): Can't find match 'policy'
   * Rule 'Allow-Network-Printer'
   * Rule 'Allow-DHCPv6'
   * Rule 'Allow-ICMPv6-Input'
   * Rule 'Allow-ICMPv6-Forward'
   * Rule 'Enforce-ULA-Border-Src'
   * Rule 'Enforce-ULA-Border-Dest'
   * Forward 'lan' -> 'wan'
* Populating IPv6 mangle table
   * Zone 'lan'
   * Zone 'wan'
* Populating IPv6 raw table
   * Zone 'lan'
   * Zone 'wan'
* Set tcp_ecn to off
* Set tcp_syncookies to on
* Set tcp_window_scaling to on
* Running script '/usr/share/miniupnpd/firewall.include'

The error only appears in the IPv6 section, and after adding "option family ipv4", the rule works fine. It looks like a bug in firewall3 in to me. I also tried the old stanzas:

iptables -A zone_wan_input -p udp -m policy --strict --dir in --pol ipsec --proto esp -m udp --dport 1701 -j ACCEPT
iptables -A zone_wan_input -m policy --strict --dir in --pol ipsec --proto esp -j REJECT

and they work fine, even without a specific ipv4-only definition.  For now I am adding these to /etc/firewall.user again, but I would like to know if these methods are the same before I file a ticket.

(Last edited by avbohemen on 24 May 2013, 11:03)

Post #67
xtdv
20 Jun 2013, 08:07

Hi all,
I folowed the wiki page to setup VPN server with xl2tpd and openswan: http://wiki.openwrt.org/inbox/openswanxl2tpvpn

Everything seem fine but my Windows machine connect to the router, this is the log I got:

Jun 20 14:00:03 OpenWrt authpriv.warn pluto[3400]: listening for IKE messages
Jun 20 14:00:03 OpenWrt authpriv.warn pluto[3400]: adding interface eth0.2/eth0.2 10.84.0.184:500
Jun 20 14:00:03 OpenWrt authpriv.warn pluto[3400]: adding interface eth0.2/eth0.2 10.84.0.184:4500
Jun 20 14:00:03 OpenWrt authpriv.warn pluto[3400]: adding interface br-lan/br-lan 192.168.1.1:500
Jun 20 14:00:03 OpenWrt authpriv.warn pluto[3400]: adding interface br-lan/br-lan 192.168.1.1:4500
Jun 20 14:00:03 OpenWrt authpriv.warn pluto[3400]: adding interface lo/lo 127.0.0.1:500
Jun 20 14:00:03 OpenWrt authpriv.warn pluto[3400]: adding interface lo/lo 127.0.0.1:4500
Jun 20 14:00:03 OpenWrt authpriv.warn pluto[3400]: loading secrets from "/etc/ipsec.secrets"
Jun 20 14:00:03 OpenWrt authpriv.warn pluto[3400]: loading secrets from "/etc/ipsec.uci.secrets"
Jun 20 14:00:09 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [MS NT5 ISAKMPOAKLEY 00000008]
Jun 20 14:00:09 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: received Vendor ID payload [RFC 3947] method set to=115 
Jun 20 14:00:09 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but already using method 115
Jun 20 14:00:09 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [FRAGMENTATION]
Jun 20 14:00:09 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [MS-Negotiation Discovery Capable]
Jun 20 14:00:09 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [Vid-Initial-Contact]
Jun 20 14:00:09 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [IKE CGA version 1]
Jun 20 14:00:09 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: initial Main Mode message received on 10.84.0.184:500 but no connection has been authorized with policy=PSK
Jun 20 14:00:10 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [MS NT5 ISAKMPOAKLEY 00000008]
Jun 20 14:00:10 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: received Vendor ID payload [RFC 3947] method set to=115 
Jun 20 14:00:10 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but already using method 115
Jun 20 14:00:10 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [FRAGMENTATION]
Jun 20 14:00:10 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [MS-Negotiation Discovery Capable]
Jun 20 14:00:10 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [Vid-Initial-Contact]
Jun 20 14:00:10 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [IKE CGA version 1]
Jun 20 14:00:10 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: initial Main Mode message received on 10.84.0.184:500 but no connection has been authorized with policy=PSK
Jun 20 14:00:12 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [MS NT5 ISAKMPOAKLEY 00000008]
Jun 20 14:00:12 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: received Vendor ID payload [RFC 3947] method set to=115 
Jun 20 14:00:12 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but already using method 115
Jun 20 14:00:12 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [FRAGMENTATION]
Jun 20 14:00:12 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [MS-Negotiation Discovery Capable]
Jun 20 14:00:12 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [Vid-Initial-Contact]
Jun 20 14:00:12 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [IKE CGA version 1]
Jun 20 14:00:12 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: initial Main Mode message received on 10.84.0.184:500 but no connection has been authorized with policy=PSK
Jun 20 14:00:16 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [MS NT5 ISAKMPOAKLEY 00000008]
Jun 20 14:00:16 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: received Vendor ID payload [RFC 3947] method set to=115 
Jun 20 14:00:16 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but already using method 115
Jun 20 14:00:16 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [FRAGMENTATION]
Jun 20 14:00:16 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [MS-Negotiation Discovery Capable]
Jun 20 14:00:16 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [Vid-Initial-Contact]
Jun 20 14:00:16 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: ignoring Vendor ID payload [IKE CGA version 1]
Jun 20 14:00:16 OpenWrt authpriv.warn pluto[3400]: packet from 10.84.0.203:500: initial Main Mode message received on 10.84.0.184:500 but no connection has been authorized with policy=PSK

Could anyone please help me identify my problems? Thank you so much.

Post #68
kop48
10 Dec 2013, 05:00

Hi folks,

I was wondering whether anyone would be able to shed any insight into why my IPSec tunnel isn't working. I'm using Arokh's WNDR3700 alternate build which is supposedly configured for IPSec already. Unfortunately, I'm getting the error below when I try to connect using my Mac. I can't figure out why - I've checked racoon.conf and it's calling setkey from what I can see. However, I get an error about duplicate tunnels being requested, and the link is finally disconnected.

Update: Evidently, I can't test things very well! :-/ It worked fine once I tried to connect from outside the network.

Mon Dec  9 19:46:19 2013 daemon.debug xl2tpd[5494]: death_handler: Fatal signal 15 received
Mon Dec  9 19:46:19 2013 daemon.debug xl2tpd[6567]: setsockopt recvref[30]: Protocol not available
Mon Dec  9 19:46:19 2013 daemon.info xl2tpd[6567]: Not looking for kernel support.
Mon Dec  9 19:46:19 2013 daemon.info xl2tpd[6568]: xl2tpd version xl2tpd-1.3.1 started on OpenWrt PID:6568
Mon Dec  9 19:46:19 2013 daemon.info xl2tpd[6568]: Written by Mark Spencer, Copyright (C) 1998, Adtran, Inc.
Mon Dec  9 19:46:19 2013 daemon.info xl2tpd[6568]: Forked by Scott Balmos and David Stipp, (C) 2001
Mon Dec  9 19:46:19 2013 daemon.info xl2tpd[6568]: Inherited by Jeff McAdams, (C) 2002
Mon Dec  9 19:46:19 2013 daemon.info xl2tpd[6568]: Forked again by Xelerance (www.xelerance.com) (C) 2006
Mon Dec  9 19:46:19 2013 daemon.info xl2tpd[6568]: Listening on IP address 0.0.0.0, port 1701
Mon Dec  9 19:46:25 2013 daemon.info racoon: INFO: respond new phase 1 negotiation: xx.xx.xx.xx.xx[500]<=>192.168.1.182[500]
Mon Dec  9 19:46:25 2013 daemon.info racoon: INFO: begin Identity Protection mode.
Mon Dec  9 19:46:25 2013 daemon.info racoon: INFO: received Vendor ID: RFC 3947
Mon Dec  9 19:46:25 2013 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-08
Mon Dec  9 19:46:25 2013 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-07
Mon Dec  9 19:46:25 2013 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-06
Mon Dec  9 19:46:25 2013 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-05
Mon Dec  9 19:46:25 2013 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-04
Mon Dec  9 19:46:25 2013 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-03
Mon Dec  9 19:46:25 2013 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02
Mon Dec  9 19:46:25 2013 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02

Mon Dec  9 19:46:25 2013 daemon.info racoon: [xx.xx.xx.xx.xx] INFO: Hashing xx.xx.xx.xx.xx[500] with algo #2 
Mon Dec  9 19:46:25 2013 daemon.info racoon: INFO: NAT-D payload #0 verified
Mon Dec  9 19:46:25 2013 daemon.info racoon: [192.168.1.182] INFO: Hashing 192.168.1.182[500] with algo #2 
Mon Dec  9 19:46:25 2013 daemon.info racoon: INFO: NAT-D payload #1 verified
Mon Dec  9 19:46:25 2013 daemon.info racoon: INFO: NAT not detected 
Mon Dec  9 19:46:25 2013 daemon.info racoon: [192.168.1.182] INFO: Hashing 192.168.1.182[500] with algo #2 
Mon Dec  9 19:46:25 2013 daemon.info racoon: [xx.xx.xx.xx.xx] INFO: Hashing xx.xx.xx.xx.xx[500] with algo #2 
Mon Dec  9 19:46:25 2013 daemon.info racoon: INFO: Adding remote and local NAT-D payloads.
Mon Dec  9 19:46:25 2013 daemon.info racoon: [192.168.1.182] ERROR: couldn't find the pskey for 192.168.1.182.
Mon Dec  9 19:46:25 2013 daemon.info racoon: [192.168.1.182] NOTIFY: Using default PSK.
Mon Dec  9 19:46:25 2013 daemon.info racoon: [192.168.1.182] INFO: received INITIAL-CONTACT
Mon Dec  9 19:46:25 2013 daemon.info racoon: INFO: purging spi=213299205.
Mon Dec  9 19:46:25 2013 daemon.info racoon: INFO: ISAKMP-SA established xx.xx.xx.xx.xx[500]-192.168.1.182[500] spi:bef67780ab57fc68:d6cf27ee2a013141
Mon Dec  9 19:46:27 2013 daemon.info racoon: INFO: respond new phase 2 negotiation: xx.xx.xx.xx.xx[500]<=>192.168.1.182[500]
Mon Dec  9 19:46:27 2013 daemon.info racoon: INFO: Update the generated policy : 192.168.1.182/32[57808] xx.xx.xx.xx.xx/32[1701] proto=udp dir=in
Mon Dec  9 19:46:27 2013 daemon.info racoon: INFO: IPsec-SA established: ESP/Transport xx.xx.xx.xx.xx[500]->192.168.1.182[500] spi=261335155(0xf93a873)
Mon Dec  9 19:46:27 2013 daemon.info racoon: INFO: IPsec-SA established: ESP/Transport xx.xx.xx.xx.xx[500]->192.168.1.182[500] spi=197284226(0xbc25182)
Mon Dec  9 19:46:27 2013 daemon.none xl2tpd[6568]: network_thread: recv packet from 192.168.1.182, size = 76, tunnel = 0, call = 0 ref=0 refhim=0
Mon Dec  9 19:46:27 2013 daemon.none xl2tpd[6568]: get_call: allocating new tunnel for host 192.168.1.182, port 57808.
Mon Dec  9 19:46:27 2013 daemon.none xl2tpd[6568]: control_finish: message type is Start-Control-Connection-Request(1).  Tunnel is 5, call is 0.
Mon Dec  9 19:46:27 2013 daemon.none xl2tpd[6568]: control_finish: sending SCCRP
Mon Dec  9 19:46:29 2013 daemon.none xl2tpd[6568]: network_thread: recv packet from 192.168.1.182, size = 76, tunnel = 0, call = 0 ref=0 refhim=0
Mon Dec  9 19:46:29 2013 daemon.none xl2tpd[6568]: get_call: allocating new tunnel for host 192.168.1.182, port 57808.
Mon Dec  9 19:46:29 2013 daemon.none xl2tpd[6568]: control_finish: message type is Start-Control-Connection-Request(1).  Tunnel is 5, call is 0.
Mon Dec  9 19:46:29 2013 daemon.none xl2tpd[6568]: control_finish: Peer requested tunnel 5 twice, ignoring second one.
Mon Dec  9 19:46:29 2013 daemon.none xl2tpd[6568]: build_fdset: closing down tunnel 62959
Mon Dec  9 19:46:30 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:31 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:32 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:33 2013 daemon.none xl2tpd[6568]: network_thread: recv packet from 192.168.1.182, size = 76, tunnel = 0, call = 0 ref=0 refhim=0
Mon Dec  9 19:46:33 2013 daemon.none xl2tpd[6568]: get_call: allocating new tunnel for host 192.168.1.182, port 57808.
Mon Dec  9 19:46:33 2013 daemon.none xl2tpd[6568]: control_finish: message type is Start-Control-Connection-Request(1).  Tunnel is 5, call is 0.
Mon Dec  9 19:46:33 2013 daemon.none xl2tpd[6568]: control_finish: Peer requested tunnel 5 twice, ignoring second one.
Mon Dec  9 19:46:33 2013 daemon.none xl2tpd[6568]: build_fdset: closing down tunnel 1234
Mon Dec  9 19:46:33 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:34 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:34 2013 daemon.error xl2tpd[6568]: Maximum retries exceeded for tunnel 57327.  Closing.
Mon Dec  9 19:46:34 2013 daemon.info xl2tpd[6568]: Connection 5 closed to 192.168.1.182, port 57808 (Timeout)
Mon Dec  9 19:46:35 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:36 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:37 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:37 2013 daemon.none xl2tpd[6568]: network_thread: recv packet from 192.168.1.182, size = 76, tunnel = 0, call = 0 ref=0 refhim=0
Mon Dec  9 19:46:37 2013 daemon.none xl2tpd[6568]: get_call: allocating new tunnel for host 192.168.1.182, port 57808.
Mon Dec  9 19:46:37 2013 daemon.none xl2tpd[6568]: control_finish: message type is Start-Control-Connection-Request(1).  Tunnel is 5, call is 0.
Mon Dec  9 19:46:37 2013 daemon.none xl2tpd[6568]: control_finish: Peer requested tunnel 5 twice, ignoring second one.
Mon Dec  9 19:46:37 2013 daemon.none xl2tpd[6568]: build_fdset: closing down tunnel 18582
Mon Dec  9 19:46:38 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:39 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:39 2013 daemon.none xl2tpd[6568]: Unable to deliver closing message for tunnel 57327. Destroying anyway.
Mon Dec  9 19:46:41 2013 daemon.none xl2tpd[6568]: network_thread: recv packet from 192.168.1.182, size = 76, tunnel = 0, call = 0 ref=0 refhim=0
Mon Dec  9 19:46:41 2013 daemon.none xl2tpd[6568]: get_call: allocating new tunnel for host 192.168.1.182, port 57808.
Mon Dec  9 19:46:41 2013 daemon.none xl2tpd[6568]: control_finish: message type is Start-Control-Connection-Request(1).  Tunnel is 5, call is 0.
Mon Dec  9 19:46:41 2013 daemon.none xl2tpd[6568]: control_finish: sending SCCRP
Mon Dec  9 19:46:44 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:45 2013 daemon.none xl2tpd[6568]: network_thread: recv packet from 192.168.1.182, size = 76, tunnel = 0, call = 0 ref=0 refhim=0
Mon Dec  9 19:46:45 2013 daemon.none xl2tpd[6568]: get_call: allocating new tunnel for host 192.168.1.182, port 57808.
Mon Dec  9 19:46:45 2013 daemon.none xl2tpd[6568]: control_finish: message type is Start-Control-Connection-Request(1).  Tunnel is 5, call is 0.
Mon Dec  9 19:46:45 2013 daemon.none xl2tpd[6568]: control_finish: Peer requested tunnel 5 twice, ignoring second one.
Mon Dec  9 19:46:45 2013 daemon.none xl2tpd[6568]: build_fdset: closing down tunnel 59973
Mon Dec  9 19:46:45 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:46 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:47 2013 daemon.info racoon: INFO: deleting a generated policy.
Mon Dec  9 19:46:47 2013 daemon.info racoon: INFO: purged IPsec-SA proto_id=ESP spi=197284226.
Mon Dec  9 19:46:47 2013 daemon.info racoon: INFO: ISAKMP-SA expired xx.xx.xx.xx.xx[500]-192.168.1.182[500] spi:bef67780ab57fc68:d6cf27ee2a013141
Mon Dec  9 19:46:47 2013 daemon.info racoon: INFO: ISAKMP-SA deleted xx.xx.xx.xx.xx[500]-192.168.1.182[500] spi:bef67780ab57fc68:d6cf27ee2a013141
Mon Dec  9 19:46:47 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:48 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:48 2013 daemon.error xl2tpd[6568]: Maximum retries exceeded for tunnel 65259.  Closing.
Mon Dec  9 19:46:48 2013 daemon.info xl2tpd[6568]: Connection 5 closed to 192.168.1.182, port 57808 (Timeout)
Mon Dec  9 19:46:49 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:50 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:51 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:52 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:53 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec  9 19:46:53 2013 daemon.none xl2tpd[6568]: Unable to deliver closing message for tunnel 65259. Destroying anyway.

Any help would be greatly appreciated!

Cheers,

(Last edited by kop48 on 23 Feb 2014, 19:11)

Post #69
morganfw
23 Feb 2014, 18:44

Hi all,
I've compiled latest trunk r39719 with all packages and custom files required on the 1st post.
/etc/init.d/racoon was modified with following options to acquire WAN IP on /etc/setkey.conf:

#!/bin/sh /etc/rc.common
# Copyright (C) 2009-2011 OpenWrt.org
# Copyright (C) 2011 Artem Makhutov

START=49

SERVICE_USE_PID=1

start() {
        wan_ip="$(uci get network.wan.ipaddr)"
        mkdir -m 0700 -p /var/racoon
       [ -f /etc/ipsec.conf ] && /usr/sbin/setkey -f /etc/ipsec.conf
        /etc/setkey.conf $wan_ip
        service_start /usr/sbin/racoon -f /etc/racoon.conf
}

stop() {
        service_stop /usr/sbin/racoon
}

/etc/setkey.conf was chmoded 755 and I've restarted racoon and xl2tpd, with following error:

Sun Feb 23 18:42:32 2014 daemon.crit xl2tpd[17155]: setsockopt recvref[30]: Protocol not available

Now I've issues with VPN connection from my Android 4.4.2 device, log report following message:

Sun Feb 23 18:16:37 2014 daemon.debug xl2tpd[16118]: result_code_avp: avp is incorrect size.  8 < 10
Sun Feb 23 18:16:37 2014 daemon.warn xl2tpd[16118]: handle_avps: Bad exit status handling attribute 1 (Result Code) on mandatory packet.

and VPN disconnect.

Any suggestion?
Regards.

(Last edited by morganfw on 23 Feb 2014, 18:50)

Post #70
morganfw
23 Feb 2014, 20:44
morganfw wrote:

Hi all,
I've compiled latest trunk r39719 with all packages and custom files required on the 1st post.
/etc/init.d/racoon was modified with following options to acquire WAN IP on /etc/setkey.conf:

#!/bin/sh /etc/rc.common
# Copyright (C) 2009-2011 OpenWrt.org
# Copyright (C) 2011 Artem Makhutov

START=49

SERVICE_USE_PID=1

start() {
        wan_ip="$(uci get network.wan.ipaddr)"
        mkdir -m 0700 -p /var/racoon
       [ -f /etc/ipsec.conf ] && /usr/sbin/setkey -f /etc/ipsec.conf
        /etc/setkey.conf $wan_ip
        service_start /usr/sbin/racoon -f /etc/racoon.conf
}

stop() {
        service_stop /usr/sbin/racoon
}

/etc/setkey.conf was chmoded 755 and I've restarted racoon and xl2tpd, with following error:

Sun Feb 23 18:42:32 2014 daemon.crit xl2tpd[17155]: setsockopt recvref[30]: Protocol not available

Now I've issues with VPN connection from my Android 4.4.2 device, log report following message:

Sun Feb 23 18:16:37 2014 daemon.debug xl2tpd[16118]: result_code_avp: avp is incorrect size.  8 < 10
Sun Feb 23 18:16:37 2014 daemon.warn xl2tpd[16118]: handle_avps: Bad exit status handling attribute 1 (Result Code) on mandatory packet.

and VPN disconnect.

Any suggestion?
Regards.

I've found the issue, so I've commented out in file /etc/ppp/options.xl2tpd following line:

#dump

then restarted racoon and xl2tpd, now VPN works like a charm with my Android 4.4.2 device!!! smile

PS: In PPPD manual page both options dryrun and dump are described as follow:

dryrun
With the dryrun option, pppd will print out all the option values which have been set and then exit, after parsing the command line and options files and checking the option values, but before initiating the link. The option values are logged at level info, and also printed to standard output unless the device on standard output is the device that pppd would be using to communicate with the peer.

dump
With the dump option, pppd will print out all the option values which have been set. This option is like the dryrun option except that pppd proceeds as normal rather than exiting.

(Last edited by morganfw on 23 Feb 2014, 22:32)

Post #71
nlh
23 Mar 2014, 08:17
morganfw wrote:

...
I've found the issue, so I've commented out in file /etc/ppp/options.xl2tpd following line:

#dump

...

The "#dump" and "#dryrun" options can sometimes cause pppd to crash.  You'll turn on these debugging options to try to figure out why your connections are not working, but end up causing other problems instead.

See: http://patchwork.openwrt.org/patch/3245/

(Last edited by nlh on 23 Mar 2014, 08:20)

Post #72
morganfw
28 Mar 2014, 21:26
nlh wrote:
morganfw wrote:

...
I've found the issue, so I've commented out in file /etc/ppp/options.xl2tpd following line:

#dump

...

The "#dump" and "#dryrun" options can sometimes cause pppd to crash.  You'll turn on these debugging options to try to figure out why your connections are not working, but end up causing other problems instead.

See: http://patchwork.openwrt.org/patch/3245/

Thx nlh, I'll try install your patch and recompile OpenWrt on my WNDR3700.

Post #73
morganfw
29 Mar 2014, 12:59

@nlh
I've applied patch and build again trunk r40296 for WNDR3700 kernel 3.10.34, but with dump enabled VPN doesn't start.
With #dump disabled all works fine!
Any suggestion?

Post #74
nlh
30 Mar 2014, 11:13

@morganfw
No idea.  I'll give it a try w/ racoon tomorrow.   What does "logread" show when you try to connect?  Does it perform the dump as expected from pppd, or does pppd stop abruptly?  Can you post the /etc/ppp/options.xl2tpd file you are using (from when it fails) in case there is some other option in there that is causing a crash?

Post #75
morganfw
31 Mar 2014, 20:53
nlh wrote:

@morganfw
No idea.  I'll give it a try w/ racoon tomorrow.   What does "logread" show when you try to connect?  Does it perform the dump as expected from pppd, or does pppd stop abruptly?  Can you post the /etc/ppp/options.xl2tpd file you are using (from when it fails) in case there is some other option in there that is causing a crash?

I've enabled dump option again then I've restarted racoon and xl2tpd with

/etc/init.d/racoon restart && /etc/init.d/xl2tpd restart

when I try to connect from Cellular Mobile to Router VPN it hangs, logread reports following (where XXX.XXX.XXX.XXX is my Mobile Network IP, YYY.YYY.YYY.YYY is my ISP NAT Public IP, 192.168.1.128 is first Private IP assigned by ISP HAG/CPE [ISP assign me Privates IP from 192.168.1.128 to 192.168.1.254 and in my WNDR3700 Router I use only first IP manually configured in static mode):

Mon Mar 31 21:01:04 2014 daemon.info racoon: INFO: respond new phase 1 negotiation: 192.168.1.128[500]<=>XXX.XXX.XXX.XXX[28542]
Mon Mar 31 21:01:04 2014 daemon.info racoon: INFO: begin Identity Protection mode.
Mon Mar 31 21:01:04 2014 daemon.info racoon: INFO: received Vendor ID: RFC 3947
Mon Mar 31 21:01:04 2014 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02
Mon Mar 31 21:01:04 2014 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02

Mon Mar 31 21:01:04 2014 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-00
Mon Mar 31 21:01:04 2014 daemon.info racoon: INFO: received broken Microsoft ID: FRAGMENTATION
Mon Mar 31 21:01:04 2014 daemon.info racoon: INFO: received Vendor ID: DPD
Mon Mar 31 21:01:04 2014 daemon.info racoon: [XXX.XXX.XXX.XXX] INFO: Selected NAT-T version: RFC 3947
Mon Mar 31 21:01:04 2014 daemon.info racoon: [192.168.1.128] INFO: Hashing 192.168.1.128[500] with algo #2 
Mon Mar 31 21:01:04 2014 daemon.info racoon: INFO: NAT-D payload #0 doesn't match
Mon Mar 31 21:01:04 2014 daemon.info racoon: [XXX.XXX.XXX.XXX] INFO: Hashing XXX.XXX.XXX.XXX[28542] with algo #2 
Mon Mar 31 21:01:04 2014 daemon.info racoon: INFO: NAT-D payload #1 doesn't match
Mon Mar 31 21:01:04 2014 daemon.info racoon: INFO: NAT detected: ME PEER
Mon Mar 31 21:01:04 2014 daemon.info racoon: [XXX.XXX.XXX.XXX] INFO: Hashing XXX.XXX.XXX.XXX[28542] with algo #2 
Mon Mar 31 21:01:04 2014 daemon.info racoon: [192.168.1.128] INFO: Hashing 192.168.1.128[500] with algo #2 
Mon Mar 31 21:01:04 2014 daemon.info racoon: INFO: Adding remote and local NAT-D payloads.
Mon Mar 31 21:01:04 2014 daemon.info racoon: [XXX.XXX.XXX.XXX] ERROR: couldn't find the pskey for XXX.XXX.XXX.XXX.
Mon Mar 31 21:01:04 2014 daemon.info racoon: [XXX.XXX.XXX.XXX] NOTIFY: Using default PSK.
Mon Mar 31 21:01:05 2014 daemon.info racoon: INFO: NAT-T: ports changed to: XXX.XXX.XXX.XXX[16100]<->192.168.1.128[4500]
Mon Mar 31 21:01:05 2014 daemon.info racoon: INFO: KA list add: 192.168.1.128[4500]->XXX.XXX.XXX.XXX[16100]
Mon Mar 31 21:01:05 2014 daemon.info racoon: INFO: ISAKMP-SA established 192.168.1.128[4500]-XXX.XXX.XXX.XXX[16100] spi:1a08c5c0aa8acc42:bb5f00ecd0600361
Mon Mar 31 21:01:05 2014 daemon.info racoon: [XXX.XXX.XXX.XXX] INFO: received INITIAL-CONTACT
Mon Mar 31 21:01:06 2014 daemon.info racoon: INFO: respond new phase 2 negotiation: 192.168.1.128[4500]<=>XXX.XXX.XXX.XXX[16100]
Mon Mar 31 21:01:06 2014 daemon.info racoon: INFO: no policy found, try to generate the policy : 100.71.198.100/32[0] YYY.YYY.YYY.YYY/32[1701] proto=udp dir=in
Mon Mar 31 21:01:06 2014 daemon.info racoon: INFO: Adjusting my encmode UDP-Transport->Transport
Mon Mar 31 21:01:06 2014 daemon.info racoon: INFO: Adjusting peer's encmode UDP-Transport(4)->Transport(2)
Mon Mar 31 21:01:06 2014 daemon.info racoon: INFO: IPsec-SA established: ESP/Transport 192.168.1.128[4500]->XXX.XXX.XXX.XXX[16100] spi=99386219(0x5ec836b)
Mon Mar 31 21:01:06 2014 daemon.info racoon: INFO: IPsec-SA established: ESP/Transport 192.168.1.128[4500]->XXX.XXX.XXX.XXX[16100] spi=103237369(0x62746f9)
Mon Mar 31 21:01:08 2014 daemon.debug xl2tpd[12114]: control_finish: Peer requested tunnel 50792 twice, ignoring second one.
Mon Mar 31 21:01:08 2014 daemon.notice xl2tpd[12114]: Connection established to XXX.XXX.XXX.XXX, 42731.  Local: 53008, Remote: 50792 (ref=0/0).  LNS session is 'default'
Mon Mar 31 21:01:09 2014 daemon.debug xl2tpd[12114]: start_pppd: I'm running: 
Mon Mar 31 21:01:09 2014 daemon.debug xl2tpd[12114]: "/usr/sbin/pppd" 
Mon Mar 31 21:01:09 2014 daemon.debug xl2tpd[12114]: "passive" 
Mon Mar 31 21:01:09 2014 daemon.debug xl2tpd[12114]: "nodetach" 
Mon Mar 31 21:01:09 2014 daemon.debug xl2tpd[12114]: "192.168.1.80:192.168.1.81" 
Mon Mar 31 21:01:09 2014 daemon.debug xl2tpd[12114]: "refuse-pap" 
Mon Mar 31 21:01:09 2014 daemon.debug xl2tpd[12114]: "auth" 
Mon Mar 31 21:01:09 2014 daemon.debug xl2tpd[12114]: "require-chap" 
Mon Mar 31 21:01:09 2014 daemon.debug xl2tpd[12114]: "name" 
Mon Mar 31 21:01:09 2014 daemon.debug xl2tpd[12114]: "VPNServer" 
Mon Mar 31 21:01:09 2014 daemon.debug xl2tpd[12114]: "debug" 
Mon Mar 31 21:01:09 2014 daemon.info pppd[14039]: Plugin pppol2tp.so loaded.
Mon Mar 31 21:01:09 2014 daemon.info pppd[14039]: pppd options in effect:
Mon Mar 31 21:01:09 2014 daemon.info pppd[14039]: debug        # (from command line)
Mon Mar 31 21:01:09 2014 daemon.info pppd[14039]: nodetach        # (from command line)
Mon Mar 31 21:01:09 2014 daemon.info pppd[14039]: idle 1800        # (from /etc/ppp/options.xl2tpd)
Mon Mar 31 21:01:09 2014 daemon.info pppd[14039]: logfile /dev/null        # (from /etc/ppp/options)
Mon Mar 31 21:01:09 2014 daemon.info pppd[14039]: maxfail 0        # (from /etc/ppp/options)
Mon Mar 31 21:01:09 2014 daemon.info pppd[14039]: connect-delay 5000        # (from /etc/ppp/options.xl2tpd)
Mon Mar 31 21:01:09 2014 daemon.info pppd[14039]: dump        # (from /etc/ppp/options.xl2tpd)
Mon Mar 31 21:01:09 2014 daemon.info pppd[14039]: plugin pppol2tp.so        # (from command line)
Mon Mar 31 21:01:09 2014 daemon.info pppd[14039]: require-mschap-v2        # (from /etc/ppp/options.xl2tpd)
Mon Mar 31 21:01:09 2014 daemon.info pppd[14039]: refuse-pap        # (from command line)
Mon Mar 31 21:01:09 2014 daemon.info pppd[14039]: name l2tp-server        # (from /etc/ppp/options.xl2tpd)
Mon Mar 31 21:01:09 2014 daemon.debug xl2tpd[12114]: child_handler : pppd terminated for call 14570 by signal 11
Mon Mar 31 21:01:09 2014 daemon.info xl2tpd[12114]: call_close: Call 41623 to XXX.XXX.XXX.XXX disconnected
Mon Mar 31 21:01:09 2014 daemon.debug xl2tpd[12114]: result_code_avp: avp is incorrect size.  8 < 10
Mon Mar 31 21:01:09 2014 daemon.warn xl2tpd[12114]: handle_avps: Bad exit status handling attribute 1 (Result Code) on mandatory packet.
Mon Mar 31 21:01:09 2014 daemon.debug xl2tpd[12114]: Terminating pppd: sending TERM signal to pid 14039
Mon Mar 31 21:01:09 2014 daemon.info xl2tpd[12114]: Connection 50792 closed to XXX.XXX.XXX.XXX, port 42731 (Result Code: expected at least 10, got 8)

and following my /etc/ppp/options.xl2tpd with dump enabled:

## Frequently Used Options ##
lock
auth
## Options ##
name "l2tp-server"
dump
# CCP seems to confuse Android clients, better turn it off
noccp
novj
novjccomp
nopcomp
noaccomp
#require-mschap
require-mschap-v2
ms-dns 192.168.1.80
lcp-echo-interval 120
lcp-echo-failure 10
idle 1800
connect-delay 5000
nodefaultroute
noipdefault

proxyarp
mtu 1410
mru 1410

if I comment dump option it works like a charm!