How to setup L2TP over IPsec with PSK using racoon/xl2tpd

Installing and Using OpenWrt Network and Wireless Configuration
1

Hello everybody!

I would like continue with discussion in this https://forum.archive.openwrt.org/viewtopic.php?id=30982&p=1 thread.

I am trying to create VPN server based on L2TP over IPsec (later for Android phone). I followed tutorial to set-up the connection from mentioned thread. But I have still no success with connection (tested with native Linux, Windows and Android).

racoon: INFO: @(#)ipsec-tools 0.8.2 (http://ipsec-tools.sourceforge.net)
racoon: INFO: @(#)This product linked OpenSSL 1.0.2n  7 Dec 2017 (http://www.openssl.org/)
racoon: INFO: Reading configuration from "/opt/etc/racoon.conf"
racoon: INFO: Reading configuration from "/opt/etc/racoon.conf"
racoon: INFO: 10.0.0.1[500] used for NAT-T
racoon: INFO: 10.0.0.1[500] used as isakmp port (fd=8)
racoon: INFO: 10.0.0.1[4500] used for NAT-T
racoon: INFO: 10.0.0.1[4500] used as isakmp port (fd=9)
racoon: INFO: 92.52.x.x[500] used for NAT-T
   <--- domain IP
racoon: INFO: 92.52.x.x[500] used as isakmp port (fd=10)
racoon: INFO: 92.52.x.x[4500] used for NAT-T
racoon: INFO: 92.52.x.x[4500] used as isakmp port (fd=11)
racoon: INFO: 127.0.0.0[500] used for NAT-T
racoon: INFO: 127.0.0.0[500] used as isakmp port (fd=12)
racoon: INFO: 127.0.0.0[4500] used for NAT-T
racoon: INFO: 127.0.0.0[4500] used as isakmp port (fd=13)
racoon: INFO: 127.0.0.1[500] used for NAT-T
racoon: INFO: 127.0.0.1[500] used as isakmp port (fd=14)
racoon: INFO: 127.0.0.1[4500] used for NAT-T
racoon: INFO: 127.0.0.1[4500] used as isakmp port (fd=15)
xl2tpd[4464]: xl2tpd version xl2tpd-1.3.10 started on RT-N65U PID:4464
   <--- seems to be, that everything was started without problems

racoon: INFO: respond new phase 1 negotiation: 92.52.x.x[500]<=>151.236.x.x[16132]
racoon: INFO: begin Identity Protection mode.
racoon: INFO: received Vendor ID: RFC 3947
racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02
racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-00
racoon: INFO: received broken Microsoft ID: FRAGMENTATION
racoon: INFO: received Vendor ID: DPD
racoon: [151.236.x.x] INFO: Selected NAT-T version: RFC 3947
racoon: [92.52.x.x] INFO: Hashing 92.52.x.x[500] with algo #2
racoon: INFO: NAT-D payload #0 verified
racoon: [151.236.x.x] INFO: Hashing 151.236.x.x[16132] with algo #2
racoon: INFO: NAT-D payload #1 doesn't match
racoon: INFO: NAT detected: PEER
racoon: [151.236.x.x] INFO: Hashing 151.236.x.x[16132] with algo #2
racoon: [92.52.x.x] INFO: Hashing 92.52.x.x[500] with algo #2
racoon: INFO: Adding remote and local NAT-D payloads.
racoon: [151.236.x.x] ERROR: couldn't find the pskey for 151.236.x.x.
racoon: [151.236.x.x] NOTIFY: Using default PSK.
racoon: INFO: NAT-T: ports changed to: 151.236.x.x[16133]<->92.52.x.x[4500]
racoon: INFO: KA list add: 92.52.x.x[4500]->151.236.x.x[16133]
racoon: INFO: ISAKMP-SA established 92.52.x.x[4500]-151.236.x.x[16133] spi:ba1e7bxxxxxxxxxx:340212xxxxxxxxxx
racoon: [151.236.x.x] INFO: received INITIAL-CONTACT
racoon: INFO: respond new phase 2 negotiation: 92.52.x.x[4500]<=>151.236.x.x[16133]
racoon: INFO: no policy found, try to generate the policy : 100.125.69.230/32[0] 92.52.x.x/32[1701] proto=udp dir=in
racoon: INFO: Adjusting my encmode UDP-Transport->Transport
racoon: INFO: Adjusting peer's encmode UDP-Transport(4)->Transport(2)
racoon: WARNING: authtype mismatched: my:hmac-sha peer:hmac-sha512
racoon: WARNING: authtype mismatched: my:hmac-sha256 peer:hmac-sha512 
   <---- multiple proposals, hmac-sha512 matched

racoon: INFO: IPsec-SA established: ESP/Transport 92.52.x.x[4500]->151.236.x.x[16133] spi=46632247(0x2c78d37)
racoon: INFO: IPsec-SA established: ESP/Transport 92.52.x.x[4500]->151.236.x.x[16133] spi=55463204(0x34e4d24)
xl2tpd[4464]: network_thread: recv packet from 151.236.x.x, size = 69, tunnel = 0, call = 0 ref=0 refhim=0
xl2tpd[4464]: get_call: allocating new tunnel for host 151.236.x.x, port 40531.
xl2tpd[4464]: control_finish: message type is Start-Control-Connection-Request(1).  Tunnel is 28729, call is 0.
xl2tpd[4464]: control_finish: sending SCCRP
   <--- looks fine SCCRP was sent

xl2tpd[4464]: network_thread: recv packet from 151.236.x.x, size = 69, tunnel = 0, call = 0 ref=0 refhim=0
xl2tpd[4464]: get_call: allocating new tunnel for host 151.236.x.x, port 40531.
xl2tpd[4464]: control_finish: message type is Start-Control-Connection-Request(1).  Tunnel is 28729, call is 0.
xl2tpd[4464]: control_finish: Peer requested tunnel 28729 twice, ignoring second one.
xl2tpd[4464]: build_fdset: closing down tunnel 14508
xl2tpd[4464]: network_thread: recv packet from 151.236.x.x, size = 69, tunnel = 0, call = 0 ref=0 refhim=0
xl2tpd[4464]: get_call: allocating new tunnel for host 151.236.x.x, port 40531.
xl2tpd[4464]: control_finish: message type is Start-Control-Connection-Request(1).  Tunnel is 28729, call is 0.
xl2tpd[4464]: control_finish: Peer requested tunnel 28729 twice, ignoring second one.
xl2tpd[4464]: build_fdset: closing down tunnel 61236
xl2tpd[4464]: network_thread: recv packet from 151.236.x.x, size = 69, tunnel = 0, call = 0 ref=0 refhim=0
xl2tpd[4464]: get_call: allocating new tunnel for host 151.236.x.x, port 40531.
xl2tpd[4464]: control_finish: message type is Start-Control-Connection-Request(1).  Tunnel is 28729, call is 0.
xl2tpd[4464]: control_finish: Peer requested tunnel 28729 twice, ignoring second one.
xl2tpd[4464]: build_fdset: closing down tunnel 36039
xl2tpd[4464]: network_thread: recv packet from 151.236.x.x, size = 69, tunnel = 0, call = 0 ref=0 refhim=0
xl2tpd[4464]: get_call: allocating new tunnel for host 151.236.x.x, port 40531.
xl2tpd[4464]: control_finish: message type is Start-Control-Connection-Request(1).  Tunnel is 28729, call is 0.
xl2tpd[4464]: control_finish: Peer requested tunnel 28729 twice, ignoring second one.
xl2tpd[4464]: build_fdset: closing down tunnel 3762
xl2tpd[4464]: network_thread: recv packet from 151.236.x.x, size = 69, tunnel = 0, call = 0 ref=0 refhim=0
xl2tpd[4464]: get_call: allocating new tunnel for host 151.236.x.x, port 40531.
xl2tpd[4464]: control_finish: message type is Start-Control-Connection-Request(1).  Tunnel is 28729, call is 0.
xl2tpd[4464]: control_finish: Peer requested tunnel 28729 twice, ignoring second one.
xl2tpd[4464]: build_fdset: closing down tunnel 31561
xl2tpd[4464]: network_thread: recv packet from 151.236.x.x, size = 69, tunnel = 0, call = 0 ref=0 refhim=0
xl2tpd[4464]: get_call: allocating new tunnel for host 151.236.x.x, port 40531.
xl2tpd[4464]: control_finish: message type is Start-Control-Connection-Request(1).  Tunnel is 28729, call is 0.
xl2tpd[4464]: control_finish: Peer requested tunnel 28729 twice, ignoring second one.
xl2tpd[4464]: build_fdset: closing down tunnel 30238

As you can see, it only loops in tunnel creation, without any additional movements forward.
As I understood it correctly, pppd daemon has to be started from xl2tpd, but wasn't ... .

/opt/etc/xl2tpd/xl2tpd.conf:

[lns default]
...
pppoptfile = /opt/etc/ppp/options.xl2tpd

Doesn't matter, what I have written after pppoptfile = xxx, it wasn't processed.

Do you have some info, what could be wrong?

Many thanks for any help
Andy

2

After some testing, I have fixed my problem by myself. Just for the info, spadd for "ipsec esp/transport//require" was missing. After fixing it, VPN was working as expected.

But... I have another problem. VPN is working on all tested devices, but not for the main one. Which is to most important one. Windows 7, iPhone 6s, Xiaomi MI4 are working fine, but Xiaomi MI8 with Android 9 has a problem. It's working, but after 1.6 minutes is always disconnected.

From the log, seems to be, that phase 1 was not successful.

2019-04-20 21:24:01: INFO: Reading configuration from "/opt/etc/racoon.conf"
2019-04-20 21:24:02: INFO: 92.52.x.x[4500] used for NAT-T
2019-04-20 21:24:02: INFO: 92.52.x.x[4500] used as isakmp port (fd=7)
2019-04-20 21:24:02: INFO: 92.52.x.x[500] used for NAT-T
2019-04-20 21:24:02: INFO: 92.52.x.x[500] used as isakmp port (fd=8)
   <--- racoon was successfully started
2019-04-20 21:24:56: INFO: respond new phase 1 negotiation: 92.52.x.x[500]<=>62.197.x.x[500]
   <--- device connected
2019-04-20 21:24:56: INFO: begin Identity Protection mode.
2019-04-20 21:24:56: INFO: received Vendor ID: RFC 3947
2019-04-20 21:24:56: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02
2019-04-20 21:24:56: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02
2019-04-20 21:24:56: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-00
2019-04-20 21:24:56: INFO: received broken Microsoft ID: FRAGMENTATION
2019-04-20 21:24:56: INFO: received Vendor ID: DPD
2019-04-20 21:24:56: [62.197.x.x] INFO: Selected NAT-T version: RFC 3947
2019-04-20 21:24:56: [92.52.x.x] INFO: Hashing 92.52.x.x[500] with algo #2 
2019-04-20 21:24:56: INFO: NAT-D payload #0 verified
2019-04-20 21:24:56: [62.197.x.x] INFO: Hashing 62.197.x.x[500] with algo #2 
2019-04-20 21:24:56: INFO: NAT-D payload #1 doesn't match
2019-04-20 21:24:56: INFO: NAT detected: PEER
2019-04-20 21:24:56: [62.197.x.x] INFO: Hashing 62.197.x.x[500] with algo #2 
2019-04-20 21:24:56: [92.52.x.x] INFO: Hashing 92.52.x.x[500] with algo #2 
2019-04-20 21:24:56: INFO: Adding remote and local NAT-D payloads.
2019-04-20 21:24:56: [62.197.x.x] ERROR: couldn't find the pskey for 62.197.x.x.
2019-04-20 21:24:56: [62.197.x.x] NOTIFY: Using default PSK.
2019-04-20 21:24:56: INFO: NAT-T: ports changed to: 62.197.x.x[4500]<->92.52.x.x[4500]
2019-04-20 21:24:56: INFO: KA list add: 92.52.x.x[4500]->62.197.x.x[4500]
2019-04-20 21:24:56: INFO: ISAKMP-SA established 92.52.x.x[4500]-62.197.x.x[4500] spi:e05fxxxxxxxxxxxx:71ddxxxxxxxxxxxx
2019-04-20 21:24:56: [62.197.x.x] INFO: received INITIAL-CONTACT
2019-04-20 21:24:57: INFO: respond new phase 2 negotiation: 92.52.x.x[4500]<=>62.197.x.x[4500]
2019-04-20 21:24:57: INFO: Update the generated policy : 192.168.1.107/32[0] 92.52.x.x/32[1701] proto=udp dir=in
2019-04-20 21:24:57: INFO: Adjusting my encmode UDP-Transport->Transport
2019-04-20 21:24:57: INFO: Adjusting peer's encmode UDP-Transport(4)->Transport(2)
2019-04-20 21:24:57: WARNING: authtype mismatched: my:hmac-sha peer:hmac-sha512
2019-04-20 21:24:57: WARNING: authtype mismatched: my:hmac-sha256 peer:hmac-sha512
2019-04-20 21:24:57: INFO: IPsec-SA established: ESP/Transport 92.52.x.x[4500]->62.197.x.x[4500] spi=100636673(0x5ff9801)
2019-04-20 21:24:57: INFO: IPsec-SA established: ESP/Transport 92.52.x.x[4500]->62.197.x.x[4500] spi=214494796(0xcc8ee4c)
   <--- disconnected after 1.6 minute
2019-04-20 21:26:32: INFO: deleting a generated policy.
2019-04-20 21:26:32: INFO: purged IPsec-SA proto_id=ESP spi=214494796.
2019-04-20 21:26:32: INFO: ISAKMP-SA expired 92.52.x.x[4500]-62.197.x.x[4500] spi:e05fxxxxxxxxxxxx:71ddxxxxxxxxxxxx
2019-04-20 21:26:32: INFO: ISAKMP-SA deleted 92.52.x.x[4500]-62.197.x.x[4500] spi:e05fxxxxxxxxxxxx:71ddxxxxxxxxxxxx
2019-04-20 21:26:32: INFO: KA remove: 92.52.x.x[4500]->62.197.x.x[4500]
2019-04-20 21:26:36: INFO: IPsec-SA request for 62.197.x.x queued due to no phase1 found.
2019-04-20 21:26:36: INFO: initiate new phase 1 negotiation: 92.52.x.x[500]<=>62.197.x.x[500]
2019-04-20 21:26:36: INFO: begin Identity Protection mode.
2019-04-20 21:27:07: [62.197.x.x] ERROR: phase2 negotiation failed due to time up waiting for phase1. ESP 62.197.x.x[0]->92.52.x.x[0] 
2019-04-20 21:27:07: INFO: delete phase 2 handler.

racoon.conf

path pre_shared_key "/opt/etc/racoon/psk.txt";

remote anonymous {
        exchange_mode main;
        verify_identifier off;
        nat_traversal on;
        generate_policy on;
        proposal_check obey;    # obey, strict, or claim
  
        proposal {
                encryption_algorithm aes;
                hash_algorithm sha1;
                authentication_method pre_shared_key;
                dh_group 2;
        }
        proposal {
                encryption_algorithm 3des;
                hash_algorithm sha1;
                authentication_method pre_shared_key;
                dh_group 2;
        }
}

sainfo anonymous {
        lifetime time 30 minutes;
        encryption_algorithm aes;
        authentication_algorithm hmac_sha1, hmac_sha256, hmac_sha512;
        compression_algorithm deflate;
        pfs_group 2;
}

What could be wrong? Why is on another devices working as well?