search

nm-l2tp / NetworkManager-l2tp

L2TP and L2TP/IPsec support for NetworkManager
GNU General Public License v2.0
486 stars 83 forks source link

Timeout trying to establish IPsec connection #130

Closed darwincr closed 4 years ago

darwincr commented 4 years ago

System logs:

Mar 23 22:57:42 darwin-srv NetworkManager[6412]: <info>  [1584964662.3919] audit: op="connection-activate" uuid="7e047375-3fb8-41ec-a9b6-15defc8562d2" name="ON MGMT" pid=16021 uid=1000 result="success"
Mar 23 22:57:42 darwin-srv NetworkManager[6412]: <info>  [1584964662.4053] vpn-connection[0x55a6ff5b8440,7e047375-3fb8-41ec-a9b6-15defc8562d2,"ON MGMT",0]: Started the VPN service, PID 31042
Mar 23 22:57:42 darwin-srv NetworkManager[6412]: <info>  [1584964662.4128] vpn-connection[0x55a6ff5b8440,7e047375-3fb8-41ec-a9b6-15defc8562d2,"ON MGMT",0]: Saw the service appear; activating connection
Mar 23 22:57:42 darwin-srv NetworkManager[6412]: <info>  [1584964662.4188] vpn-connection[0x55a6ff5b8440,7e047375-3fb8-41ec-a9b6-15defc8562d2,"ON MGMT",0]: VPN connection: (ConnectInteractive) reply received
Mar 23 22:57:42 darwin-srv nm-l2tp-service[31042]: Check port 1701
Mar 23 22:57:42 darwin-srv NetworkManager[6412]: Stopping strongSwan IPsec failed: starter is not running
Mar 23 22:57:44 darwin-srv NetworkManager[6412]: Starting strongSwan 5.6.2 IPsec [starter]...
Mar 23 22:57:44 darwin-srv NetworkManager[6412]: Loading config setup
Mar 23 22:57:44 darwin-srv NetworkManager[6412]: Loading conn '7e047375-3fb8-41ec-a9b6-15defc8562d2'
Mar 23 22:57:44 darwin-srv NetworkManager[6412]: found netkey IPsec stack
Mar 23 22:57:44 darwin-srv charon: 00[DMN] Starting IKE charon daemon (strongSwan 5.6.2, Linux 5.3.0-40-generic, x86_64)
Mar 23 22:57:44 darwin-srv charon: 00[CFG] PKCS11 module '<name>' lacks library path
Mar 23 22:57:44 darwin-srv charon: 00[CFG] disabling load-tester plugin, not configured
Mar 23 22:57:44 darwin-srv charon: 00[LIB] plugin 'load-tester': failed to load - load_tester_plugin_create returned NULL
Mar 23 22:57:44 darwin-srv charon: 00[CFG] dnscert plugin is disabled
Mar 23 22:57:44 darwin-srv charon: 00[CFG] ipseckey plugin is disabled
Mar 23 22:57:44 darwin-srv charon: 00[CFG] attr-sql plugin: database URI not set
Mar 23 22:57:44 darwin-srv charon: 00[CFG] loading ca certificates from '/etc/ipsec.d/cacerts'
Mar 23 22:57:44 darwin-srv charon: 00[CFG]   loaded ca certificate "O=Digital Signature Trust Co., CN=DST Root CA X3" from '/etc/ipsec.d/cacerts/DST_Root_CA_X3.pem'
Mar 23 22:57:44 darwin-srv charon: 00[CFG] loading aa certificates from '/etc/ipsec.d/aacerts'
Mar 23 22:57:44 darwin-srv charon: 00[CFG] loading ocsp signer certificates from '/etc/ipsec.d/ocspcerts'
Mar 23 22:57:44 darwin-srv charon: 00[CFG] loading attribute certificates from '/etc/ipsec.d/acerts'
Mar 23 22:57:44 darwin-srv charon: 00[CFG] loading crls from '/etc/ipsec.d/crls'
Mar 23 22:57:44 darwin-srv charon: 00[CFG] loading secrets from '/etc/ipsec.secrets'
Mar 23 22:57:44 darwin-srv charon: 00[CFG] loading secrets from '/etc/ipsec.d/nm-l2tp-ipsec-745f5db8-ed31-42fe-ac5f-5f5873480a29.secrets'
Mar 23 22:57:44 darwin-srv charon: 00[CFG]   loaded IKE secret for %any
Mar 23 22:57:44 darwin-srv charon: 00[CFG] loading secrets from '/etc/ipsec.d/nm-l2tp-ipsec-7e047375-3fb8-41ec-a9b6-15defc8562d2.secrets'
Mar 23 22:57:44 darwin-srv charon: 00[CFG]   loaded IKE secret for %any
Mar 23 22:57:44 darwin-srv charon: 00[CFG] loading secrets from '/etc/ipsec.d/nm-l2tp-ipsec-dfb3d21c-a468-405d-848c-83a33edf1669.secrets'
Mar 23 22:57:44 darwin-srv charon: 00[CFG]   loaded IKE secret for %any
Mar 23 22:57:44 darwin-srv charon: 00[CFG] loading secrets from '/etc/ipsec.d/nm-l2tp-ipsec-ed9f7e42-5ce6-4791-9295-33fd3f1082ec.secrets'
Mar 23 22:57:44 darwin-srv charon: 00[CFG]   loaded IKE secret for %any
Mar 23 22:57:44 darwin-srv charon: 00[CFG]   loaded EAP secret for darwin
Mar 23 22:57:44 darwin-srv charon: 00[CFG] sql plugin: database URI not set
Mar 23 22:57:44 darwin-srv charon: 00[CFG] opening triplet file /etc/ipsec.d/triplets.dat failed: No such file or directory
Mar 23 22:57:44 darwin-srv charon: 00[CFG] eap-simaka-sql database URI missing
Mar 23 22:57:44 darwin-srv charon: 00[CFG] loaded 0 RADIUS server configurations
Mar 23 22:57:44 darwin-srv charon: 00[CFG] HA config misses local/remote address
Mar 23 22:57:44 darwin-srv charon: 00[CFG] no threshold configured for systime-fix, disabled
Mar 23 22:57:44 darwin-srv charon: 00[CFG] coupling file path unspecified
Mar 23 22:57:44 darwin-srv charon: 00[LIB] loaded plugins: charon test-vectors unbound ldap pkcs11 tpm aesni aes rc2 sha2 sha1 md4 md5 mgf1 random nonce x509 revocation constraints acert pubkey pkcs1 pkcs7 pkcs8 pkcs12 pgp dnskey sshkey dnscert ipseckey pem openssl gcrypt af-alg fips-prf gmp curve25519 agent chapoly xcbc cmac hmac ctr ccm gcm ntru bliss curl soup mysql sqlite attr kernel-netlink resolve socket-default connmark farp stroke updown eap-identity eap-sim eap-sim-pcsc eap-aka eap-aka-3gpp2 eap-simaka-pseudonym eap-simaka-reauth eap-md5 eap-gtc eap-mschapv2 eap-dynamic eap-radius eap-tls eap-ttls eap-peap eap-tnc xauth-generic xauth-eap xauth-pam xauth-noauth tnc-tnccs tnccs-20 tnccs-11 tnccs-dynamic dhcp whitelist lookip error-notify certexpire led radattr addrblock unity counters
Mar 23 22:57:44 darwin-srv charon: 00[LIB] dropped capabilities, running as uid 0, gid 0
Mar 23 22:57:44 darwin-srv charon: 00[JOB] spawning 16 worker threads
Mar 23 22:57:44 darwin-srv charon: 05[CFG] received stroke: add connection '7e047375-3fb8-41ec-a9b6-15defc8562d2'
Mar 23 22:57:44 darwin-srv charon: 05[CFG] added configuration '7e047375-3fb8-41ec-a9b6-15defc8562d2'
Mar 23 22:57:45 darwin-srv charon: 08[CFG] rereading secrets
Mar 23 22:57:45 darwin-srv charon: 08[CFG] loading secrets from '/etc/ipsec.secrets'
Mar 23 22:57:45 darwin-srv charon: 08[CFG] loading secrets from '/etc/ipsec.d/nm-l2tp-ipsec-745f5db8-ed31-42fe-ac5f-5f5873480a29.secrets'
Mar 23 22:57:45 darwin-srv charon: 08[CFG]   loaded IKE secret for %any
Mar 23 22:57:45 darwin-srv charon: 08[CFG] loading secrets from '/etc/ipsec.d/nm-l2tp-ipsec-7e047375-3fb8-41ec-a9b6-15defc8562d2.secrets'
Mar 23 22:57:45 darwin-srv charon: 08[CFG]   loaded IKE secret for %any
Mar 23 22:57:45 darwin-srv charon: 08[CFG] loading secrets from '/etc/ipsec.d/nm-l2tp-ipsec-dfb3d21c-a468-405d-848c-83a33edf1669.secrets'
Mar 23 22:57:45 darwin-srv charon: 08[CFG]   loaded IKE secret for %any
Mar 23 22:57:45 darwin-srv charon: 08[CFG] loading secrets from '/etc/ipsec.d/nm-l2tp-ipsec-ed9f7e42-5ce6-4791-9295-33fd3f1082ec.secrets'
Mar 23 22:57:45 darwin-srv charon: 08[CFG]   loaded IKE secret for %any
Mar 23 22:57:45 darwin-srv charon: 08[CFG]   loaded EAP secret for darwin
Mar 23 22:57:45 darwin-srv charon: 10[CFG] received stroke: initiate '7e047375-3fb8-41ec-a9b6-15defc8562d2'
Mar 23 22:57:45 darwin-srv charon: 12[IKE] initiating Main Mode IKE_SA 7e047375-3fb8-41ec-a9b6-15defc8562d2[1] to 103.227.60.6
Mar 23 22:57:45 darwin-srv charon: 12[ENC] generating ID_PROT request 0 [ SA V V V V V ]
Mar 23 22:57:45 darwin-srv charon: 12[NET] sending packet: from 192.168.1.113[500] to 103.227.60.6[500] (532 bytes)
Mar 23 22:57:45 darwin-srv charon: 13[NET] received packet: from 103.227.60.6[500] to 192.168.1.113[500] (160 bytes)
Mar 23 22:57:45 darwin-srv charon: 13[ENC] parsed ID_PROT response 0 [ SA V V V V ]
Mar 23 22:57:45 darwin-srv charon: 13[IKE] received NAT-T (RFC 3947) vendor ID
Mar 23 22:57:45 darwin-srv charon: 13[IKE] received XAuth vendor ID
Mar 23 22:57:45 darwin-srv charon: 13[IKE] received DPD vendor ID
Mar 23 22:57:45 darwin-srv charon: 13[IKE] received FRAGMENTATION vendor ID
Mar 23 22:57:45 darwin-srv charon: 13[ENC] generating ID_PROT request 0 [ KE No NAT-D NAT-D ]
Mar 23 22:57:45 darwin-srv charon: 13[NET] sending packet: from 192.168.1.113[500] to 103.227.60.6[500] (244 bytes)
Mar 23 22:57:45 darwin-srv charon: 14[NET] received packet: from 103.227.60.6[500] to 192.168.1.113[500] (236 bytes)
Mar 23 22:57:45 darwin-srv charon: 14[ENC] parsed ID_PROT response 0 [ KE No NAT-D NAT-D ]
Mar 23 22:57:45 darwin-srv charon: 14[IKE] local host is behind NAT, sending keep alives
Mar 23 22:57:45 darwin-srv charon: 14[ENC] generating ID_PROT request 0 [ ID HASH ]
Mar 23 22:57:45 darwin-srv charon: 14[NET] sending packet: from 192.168.1.113[4500] to 103.227.60.6[4500] (76 bytes)
Mar 23 22:57:49 darwin-srv charon: 07[IKE] sending retransmit 1 of request message ID 0, seq 3
Mar 23 22:57:49 darwin-srv charon: 07[NET] sending packet: from 192.168.1.113[4500] to 103.227.60.6[4500] (76 bytes)
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: Stopping strongSwan IPsec...
Mar 23 22:57:55 darwin-srv charon: 00[DMN] signal of type SIGINT received. Shutting down
Mar 23 22:57:55 darwin-srv charon: 00[IKE] destroying IKE_SA in state CONNECTING without notification
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: initiating Main Mode IKE_SA 7e047375-3fb8-41ec-a9b6-15defc8562d2[1] to 103.227.60.6
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: generating ID_PROT request 0 [ SA V V V V V ]
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: sending packet: from 192.168.1.113[500] to 103.227.60.6[500] (532 bytes)
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: received packet: from 103.227.60.6[500] to 192.168.1.113[500] (160 bytes)
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: parsed ID_PROT response 0 [ SA V V V V ]
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: received NAT-T (RFC 3947) vendor ID
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: received XAuth vendor ID
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: received DPD vendor ID
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: received FRAGMENTATION vendor ID
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: generating ID_PROT request 0 [ KE No NAT-D NAT-D ]
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: sending packet: from 192.168.1.113[500] to 103.227.60.6[500] (244 bytes)
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: received packet: from 103.227.60.6[500] to 192.168.1.113[500] (236 bytes)
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: parsed ID_PROT response 0 [ KE No NAT-D NAT-D ]
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: local host is behind NAT, sending keep alives
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: generating ID_PROT request 0 [ ID HASH ]
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: sending packet: from 192.168.1.113[4500] to 103.227.60.6[4500] (76 bytes)
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: sending retransmit 1 of request message ID 0, seq 3
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: sending packet: from 192.168.1.113[4500] to 103.227.60.6[4500] (76 bytes)
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: destroying IKE_SA in state CONNECTING without notification
Mar 23 22:57:55 darwin-srv NetworkManager[6412]: establishing connection '7e047375-3fb8-41ec-a9b6-15defc8562d2' failed
Mar 23 22:57:55 darwin-srv nm-l2tp-service[31042]: g_dbus_method_invocation_take_error: assertion 'error != NULL' failed

Output of: sudo CHARONDEBUG="knl 1, ike 2, esp 2, lib 1, cfg 3" /usr/lib/NetworkManager/nm-l2tp-service --debug:

nm-l2tp[28692] <debug> nm-l2tp-service (version 1.2.8) starting...
nm-l2tp[28692] <debug>  uses default --bus-name "org.freedesktop.NetworkManager.l2tp"
nm-l2tp[28692] <info>  ipsec enable flag: yes
** Message: 22:49:08.361: Check port 1701
connection
    id : "ON MGMT" (s)
    uuid : "7e047375-3fb8-41ec-a9b6-15defc8562d2" (s)
    interface-name : NULL (sd)
    type : "vpn" (s)
    permissions : ["user:darwin:"] (s)
    autoconnect : FALSE (s)
    autoconnect-priority : 0 (sd)
    autoconnect-retries : -1 (sd)
    timestamp : 0 (sd)
    read-only : FALSE (sd)
    zone : "trusted" (s)
    master : NULL (sd)
    slave-type : NULL (sd)
    autoconnect-slaves : ((NMSettingConnectionAutoconnectSlaves) NM_SETTING_CONNECTION_AUTOCONNECT_SLAVES_DEFAULT) (sd)
    secondaries : NULL (sd)
    gateway-ping-timeout : 0 (sd)
    metered : ((NMMetered) NM_METERED_UNKNOWN) (sd)
    lldp : -1 (sd)
    mdns : -1 (sd)
    stable-id : NULL (sd)
    auth-retries : -1 (sd)

ipv6
    method : "auto" (s)
    dns : [] (s)
    dns-search : [] (s)
    dns-options : NULL (sd)
    dns-priority : 0 (sd)
    addresses : ((GPtrArray*) 0x55ef3940ce00) (s)
    gateway : NULL (sd)
    routes : ((GPtrArray*) 0x55ef3940ce20) (s)
    route-metric : -1 (sd)
    route-table : 0 (sd)
    ignore-auto-routes : FALSE (sd)
    ignore-auto-dns : FALSE (sd)
    dhcp-hostname : NULL (sd)
    dhcp-send-hostname : TRUE (sd)
    never-default : FALSE (sd)
    may-fail : TRUE (sd)
    dad-timeout : -1 (sd)
    dhcp-timeout : 0 (sd)
    ip6-privacy : ((NMSettingIP6ConfigPrivacy) NM_SETTING_IP6_CONFIG_PRIVACY_DISABLED) (s)
    addr-gen-mode : 1 (sd)
    token : NULL (sd)

proxy
    method : 0 (sd)
    browser-only : FALSE (sd)
    pac-url : NULL (sd)
    pac-script : NULL (sd)

vpn
    service-type : "org.freedesktop.NetworkManager.l2tp" (s)
    user-name : NULL (sd)
    persistent : FALSE (sd)
    data : ((GHashTable*) 0x7fc1b00075e0) (s)
    secrets : ((GHashTable*) 0x55ef393ead80) (s)
    timeout : 0 (sd)

ipv4
    method : "auto" (s)
    dns : [] (s)
    dns-search : [] (s)
    dns-options : NULL (sd)
    dns-priority : 0 (sd)
    addresses : ((GPtrArray*) 0x55ef3940cee0) (s)
    gateway : NULL (sd)
    routes : ((GPtrArray*) 0x55ef3940cf00) (s)
    route-metric : -1 (sd)
    route-table : 0 (sd)
    ignore-auto-routes : FALSE (sd)
    ignore-auto-dns : TRUE (s)
    dhcp-hostname : NULL (sd)
    dhcp-send-hostname : TRUE (sd)
    never-default : FALSE (sd)
    may-fail : TRUE (sd)
    dad-timeout : -1 (sd)
    dhcp-timeout : 0 (sd)
    dhcp-client-id : NULL (sd)
    dhcp-fqdn : NULL (sd)

nm-l2tp[28692] <info>  starting ipsec
Stopping strongSwan IPsec failed: starter is not running
Starting strongSwan 5.6.2 IPsec [starter]...
Loading config setup
Loading conn '7e047375-3fb8-41ec-a9b6-15defc8562d2'
found netkey IPsec stack
nm-l2tp[28692] <info>  Spawned ipsec up script with PID 28789.
initiating Main Mode IKE_SA 7e047375-3fb8-41ec-a9b6-15defc8562d2[1] to 103.227.60.6
generating ID_PROT request 0 [ SA V V V V V ]
sending packet: from 192.168.1.113[500] to 103.227.60.6[500] (532 bytes)
received packet: from 103.227.60.6[500] to 192.168.1.113[500] (160 bytes)
parsed ID_PROT response 0 [ SA V V V V ]
received NAT-T (RFC 3947) vendor ID
received XAuth vendor ID
received DPD vendor ID
received FRAGMENTATION vendor ID
generating ID_PROT request 0 [ KE No NAT-D NAT-D ]
sending packet: from 192.168.1.113[500] to 103.227.60.6[500] (244 bytes)
received packet: from 103.227.60.6[500] to 192.168.1.113[500] (236 bytes)
parsed ID_PROT response 0 [ KE No NAT-D NAT-D ]
local host is behind NAT, sending keep alives
generating ID_PROT request 0 [ ID HASH ]
sending packet: from 192.168.1.113[4500] to 103.227.60.6[4500] (76 bytes)
sending retransmit 1 of request message ID 0, seq 3
sending packet: from 192.168.1.113[4500] to 103.227.60.6[4500] (76 bytes)
nm-l2tp[28692] <warn>  Timeout trying to establish IPsec connection
nm-l2tp[28692] <info>  Terminating ipsec script with PID 28789.
Stopping strongSwan IPsec...
destroying IKE_SA in state CONNECTING without notification
establishing connection '7e047375-3fb8-41ec-a9b6-15defc8562d2' failed
nm-l2tp[28692] <warn>  Could not establish IPsec tunnel.

(nm-l2tp-service:28692): GLib-GIO-CRITICAL **: 22:49:21.534: g_dbus_method_invocation_take_error: assertion 'error != NULL' failed

Output of IKE Scan:

    SA=(Enc=3DES Hash=SHA1 Auth=PSK Group=2:modp1024 LifeType=Seconds LifeDuration(4)=0x00007080)
    SA=(Enc=3DES Hash=SHA1 Auth=PSK Group=14:modp2048 LifeType=Seconds LifeDuration(4)=0x00007080)
    SA=(Enc=AES Hash=SHA1 Auth=PSK Group=2:modp1024 KeyLength=128 LifeType=Seconds LifeDuration(4)=0x00007080)
    SA=(Enc=AES Hash=SHA1 Auth=PSK Group=14:modp2048 KeyLength=128 LifeType=Seconds LifeDuration(4)=0x00007080)

The VPN Server is running RouterOS The VPN Client on windows connects without issues

Can you help?

dkosovic commented 4 years ago

You seem to be running a pretty old version of NetworkManager-l2tp and I can see lots of stray /etc/ipsec.d/nm-l2tp-ipsec-*.secrets files being loaded, so it might be using the wrong PSK. Try deleting those files, and trying again e.g.:

sudo su -
rm -f /etc/ipsec.d/nm-l2tp-ipsec-*.secrets

If you are running Ubuntu or a derivative, you can get a newer version of network-mnager-l2tp which isn't prone to those issues from:

darwincr commented 4 years ago

Deleted secrets did not solve it

Upgraded Network Manager with the PPA and rebooted the machine

Issue is solved

Thanks