search

nm-l2tp / NetworkManager-l2tp

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

Connection Problems to VPN #74

Closed rdbisme closed 6 years ago

rdbisme commented 6 years ago 
        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)
        SA=(Enc=AES Hash=SHA1 Auth=PSK Group=2:modp1024 KeyLength=192 LifeType=Seconds LifeDuration(4)=0x00007080)
        SA=(Enc=AES Hash=SHA1 Auth=PSK Group=14:modp2048 KeyLength=192 LifeType=Seconds LifeDuration(4)=0x00007080)
        SA=(Enc=AES Hash=SHA1 Auth=PSK Group=2:modp1024 KeyLength=256 LifeType=Seconds LifeDuration(4)=0x00007080)
        SA=(Enc=AES Hash=SHA1 Auth=PSK Group=14:modp2048 KeyLength=256 LifeType=Seconds LifeDuration(4)=0x00007080)

I then configured manually the algorithms for phase 1 and 2 as this:

Phase1: aes256-sha1-modp2048
Phase2: aes256-sha1-modp1024

This is the debug log:

nm-l2tp[22647] <debug> nm-l2tp-service (version 1.2.8) starting...
nm-l2tp[22647] <debug>  uses default --bus-name "org.freedesktop.NetworkManager.l2tp"
nm-l2tp[22647] <info>  ipsec enable flag: yes
** Message: Check port 1701
connection
    id : "Work" (s)
    uuid : "95118aae-acad-4101-b472-8d4c2d89528c" (s)
    interface-name : NULL (sd)
    type : "vpn" (s)
    permissions : ["user:tid:"] (s)
    autoconnect : TRUE (sd)
    autoconnect-priority : 0 (sd)
    autoconnect-retries : -1 (sd)
    timestamp : 0 (sd)
    read-only : FALSE (sd)
    zone : NULL (sd)
    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)
    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*) 0x564bffc1aae0) (s)
    gateway : NULL (sd)
    routes : ((GPtrArray*) 0x564bffc1aae0) (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_UNKNOWN) (sd)
    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*) 0x564bffc15520) (s)
    secrets : ((GHashTable*) 0x7f74fc006ea0) (s)
    timeout : 0 (sd)

ipv4
    method : "auto" (s)
    dns : [] (s)
    dns-search : [] (s)
    dns-options : NULL (sd)
    dns-priority : 0 (sd)
    addresses : ((GPtrArray*) 0x564bffc1ab80) (s)
    gateway : NULL (sd)
    routes : ((GPtrArray*) 0x564bffc1b400) (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)
    dhcp-client-id : NULL (sd)
    dhcp-fqdn : NULL (sd)

nm-l2tp[22647] <info>  starting ipsec
Stopping strongSwan IPsec failed: starter is not running
Starting strongSwan 5.6.1 IPsec [starter]...
Loading config setup
Loading conn '95118aae-acad-4101-b472-8d4c2d89528c'
found netkey IPsec stack
nm-l2tp[22647] <info>  Spawned ipsec up script with PID 22703.
nm-l2tp[22647] <warn>  Timeout trying to establish IPsec connection
nm-l2tp[22647] <info>  Terminating ipsec script with PID 22703.
Stopping strongSwan IPsec...
initiating Main Mode IKE_SA 95118aae-acad-4101-b472-8d4c2d89528c[1] to x.x.x.x
generating ID_PROT request 0 [ SA V V V V V ]
sending packet: from 10.0.2.15[500] to x.x.x.x[500] (240 bytes)
received packet: from x.x.x.x[500] to 10.0.2.15[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 10.0.2.15[500] to x.x.x.x[500] (372 bytes)
received packet: from x.x.x.x[500] to 10.0.2.15[500] (364 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 10.0.2.15[4500] to x.x.x.x[4500] (76 bytes)
sending retransmit 1 of request message ID 0, seq 3
sending packet: from 10.0.2.15[4500] to x.x.x.x[4500] (76 bytes)
destroying IKE_SA in state CONNECTING without notification
establishing connection '95118aae-acad-4101-b472-8d4c2d89528c' failed
nm-l2tp[22647] <warn>  Could not establish IPsec tunnel.

(nm-l2tp-service:22647): GLib-GIO-CRITICAL **: g_dbus_method_invocation_take_error: assertion 'error != NULL' failed

This is the journal -b output:

Feb 03 13:21:20 iridium NetworkManager[297]: <info>  [1517660480.5144] audit: op="connection-update" uuid="95118aae-acad-4101-b472-8d4c2d89528c" name="Work" pid=21665 uid=1000 result="success"
Feb 03 13:21:22 iridium NetworkManager[297]: <info>  [1517660482.7551] audit: op="connection-activate" uuid="95118aae-acad-4101-b472-8d4c2d89528c" name="Work" pid=21665 uid=1000 result="success"
Feb 03 13:21:22 iridium NetworkManager[297]: <info>  [1517660482.7639] vpn-connection[0x55b0e1e92500,95118aae-acad-4101-b472-8d4c2d89528c,"Work",0]: Started the VPN service, PID 22138
Feb 03 13:21:22 iridium NetworkManager[297]: <info>  [1517660482.7834] vpn-connection[0x55b0e1e92500,95118aae-acad-4101-b472-8d4c2d89528c,"Work",0]: Saw the service appear; activating connection
Feb 03 13:21:22 iridium nm-l2tp-service[22138]: Check port 1701
Feb 03 13:21:22 iridium NetworkManager[297]: Stopping strongSwan IPsec failed: starter is not running
Feb 03 13:21:24 iridium NetworkManager[297]: Starting strongSwan 5.6.1 IPsec [starter]...
Feb 03 13:21:24 iridium NetworkManager[297]: Loading config setup
Feb 03 13:21:24 iridium NetworkManager[297]: Loading conn '95118aae-acad-4101-b472-8d4c2d89528c'
Feb 03 13:21:24 iridium ipsec_starter[22151]: Starting strongSwan 5.6.1 IPsec [starter]...
Feb 03 13:21:24 iridium ipsec_starter[22151]: Loading config setup
Feb 03 13:21:24 iridium ipsec_starter[22151]: Loading conn '95118aae-acad-4101-b472-8d4c2d89528c'
Feb 03 13:21:24 iridium NetworkManager[297]: found netkey IPsec stack
Feb 03 13:21:24 iridium ipsec_starter[22151]: found netkey IPsec stack
Feb 03 13:21:24 iridium ipsec_starter[22168]: Attempting to start charon...
Feb 03 13:21:24 iridium charon[22169]: 00[DMN] Starting IKE charon daemon (strongSwan 5.6.1, Linux 4.14.15-1-ARCH, x86_64)
Feb 03 13:21:24 iridium charon[22169]: 00[CFG] attr-sql plugin: database URI not set
Feb 03 13:21:24 iridium charon[22169]: 00[NET] using forecast interface enp0s3
Feb 03 13:21:24 iridium charon[22169]: 00[CFG] joining forecast multicast groups: 224.0.0.1,224.0.0.22,224.0.0.251,224.0.0.252,239.255.255.250
Feb 03 13:21:24 iridium charon[22169]: 00[CFG] loading ca certificates from '/etc/ipsec.d/cacerts'
Feb 03 13:21:24 iridium charon[22169]: 00[CFG] loading aa certificates from '/etc/ipsec.d/aacerts'
Feb 03 13:21:24 iridium charon[22169]: 00[CFG] loading ocsp signer certificates from '/etc/ipsec.d/ocspcerts'
Feb 03 13:21:24 iridium charon[22169]: 00[CFG] loading attribute certificates from '/etc/ipsec.d/acerts'
Feb 03 13:21:24 iridium charon[22169]: 00[CFG] loading crls from '/etc/ipsec.d/crls'
Feb 03 13:21:24 iridium charon[22169]: 00[CFG] loading secrets from '/etc/ipsec.secrets'
Feb 03 13:21:24 iridium charon[22169]: 00[CFG] loading secrets from '/etc/ipsec.d/nm-l2tp-ipsec-95118aae-acad-4101-b472-8d4c2d89528c.secrets'
Feb 03 13:21:24 iridium charon[22169]: 00[CFG]   loaded IKE secret for %any
Feb 03 13:21:24 iridium charon[22169]: 00[CFG] sql plugin: database URI not set
Feb 03 13:21:24 iridium charon[22169]: 00[CFG] opening triplet file /etc/ipsec.d/triplets.dat failed: No such file or directory
Feb 03 13:21:24 iridium charon[22169]: 00[CFG] loaded 0 RADIUS server configurations
Feb 03 13:21:24 iridium charon[22169]: 00[CFG] HA config misses local/remote address
Feb 03 13:21:24 iridium charon[22169]: 00[CFG] no script for ext-auth script defined, disabled
Feb 03 13:21:24 iridium charon[22169]: 00[LIB] loaded plugins: charon ldap aesni aes des rc2 sha2 sha3 sha1 md5 mgf1 random nonce x509 revocation constraints pubkey pkcs1 pkcs7 pkcs8 pkcs12 pgp dnskey sshkey pem openssl fips-prf gmp curve25519 agent chapoly xcbc cmac hmac ntru newhope bliss curl mysql sqlite attr kernel-netlink resolve socket-default bypass-lan connmark forecast farp stroke vici updown eap-identity eap-sim 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 xauth-generic xauth-eap xauth-pam xauth-noauth dhcp radattr unity counters
Feb 03 13:21:24 iridium charon[22169]: 00[LIB] dropped capabilities, running as uid 0, gid 0
Feb 03 13:21:24 iridium charon[22169]: 00[JOB] spawning 16 worker threads
Feb 03 13:21:24 iridium ipsec_starter[22168]: charon (22169) started after 40 ms
Feb 03 13:21:24 iridium charon[22169]: 04[IKE] installed bypass policy for 10.0.2.0/24
Feb 03 13:21:24 iridium charon[22169]: 04[KNL] received netlink error: Invalid argument (22)
Feb 03 13:21:24 iridium charon[22169]: 04[KNL] unable to install source route for %any6
Feb 03 13:21:24 iridium charon[22169]: 04[IKE] installed bypass policy for ::1/128
Feb 03 13:21:24 iridium charon[22169]: 04[IKE] installed bypass policy for fe80::/64
Feb 03 13:21:24 iridium charon[22169]: 06[CFG] received stroke: add connection '95118aae-acad-4101-b472-8d4c2d89528c'
Feb 03 13:21:24 iridium charon[22169]: 06[CFG] added configuration '95118aae-acad-4101-b472-8d4c2d89528c'
Feb 03 13:21:26 iridium charon[22169]: 08[CFG] rereading secrets
Feb 03 13:21:26 iridium charon[22169]: 08[CFG] loading secrets from '/etc/ipsec.secrets'
Feb 03 13:21:26 iridium charon[22169]: 08[CFG] loading secrets from '/etc/ipsec.d/nm-l2tp-ipsec-95118aae-acad-4101-b472-8d4c2d89528c.secrets'
Feb 03 13:21:26 iridium charon[22169]: 08[CFG]   loaded IKE secret for %any
Feb 03 13:21:26 iridium charon[22169]: 10[CFG] received stroke: initiate '95118aae-acad-4101-b472-8d4c2d89528c'
Feb 03 13:21:26 iridium charon[22169]: 04[IKE] initiating Main Mode IKE_SA 95118aae-acad-4101-b472-8d4c2d89528c[1] to x.x.x.x
Feb 03 13:21:26 iridium charon[22169]: 04[IKE] initiating Main Mode IKE_SA 95118aae-acad-4101-b472-8d4c2d89528c[1] to x.x.x.x
Feb 03 13:21:26 iridium charon[22169]: 04[ENC] generating ID_PROT request 0 [ SA V V V V V ]
Feb 03 13:21:26 iridium charon[22169]: 04[NET] sending packet: from 10.0.2.15[500] to x.x.x.x[500] (180 bytes)
Feb 03 13:21:26 iridium charon[22169]: 12[NET] received packet: from x.x.x.x[500] to 10.0.2.15[500] (160 bytes)
Feb 03 13:21:26 iridium charon[22169]: 12[ENC] parsed ID_PROT response 0 [ SA V V V V ]
Feb 03 13:21:26 iridium charon[22169]: 12[IKE] received NAT-T (RFC 3947) vendor ID
Feb 03 13:21:26 iridium charon[22169]: 12[IKE] received XAuth vendor ID
Feb 03 13:21:26 iridium charon[22169]: 12[IKE] received DPD vendor ID
Feb 03 13:21:26 iridium charon[22169]: 12[IKE] received FRAGMENTATION vendor ID
Feb 03 13:21:26 iridium charon[22169]: 12[ENC] generating ID_PROT request 0 [ KE No NAT-D NAT-D ]
Feb 03 13:21:26 iridium charon[22169]: 12[NET] sending packet: from 10.0.2.15[500] to x.x.x.x[500] (372 bytes)
Feb 03 13:21:26 iridium charon[22169]: 14[NET] received packet: from x.x.x.x[500] to 10.0.2.15[500] (364 bytes)
Feb 03 13:21:26 iridium charon[22169]: 14[ENC] parsed ID_PROT response 0 [ KE No NAT-D NAT-D ]
Feb 03 13:21:26 iridium charon[22169]: 14[IKE] local host is behind NAT, sending keep alives
Feb 03 13:21:26 iridium charon[22169]: 14[ENC] generating ID_PROT request 0 [ ID HASH ]
Feb 03 13:21:26 iridium charon[22169]: 14[NET] sending packet: from 10.0.2.15[4500] to x.x.x.x[4500] (76 bytes)
Feb 03 13:21:30 iridium charon[22169]: 07[IKE] sending retransmit 1 of request message ID 0, seq 3
Feb 03 13:21:30 iridium charon[22169]: 07[NET] sending packet: from 10.0.2.15[4500] to x.x.x.x[4500] (76 bytes)
Feb 03 13:21:36 iridium NetworkManager[297]: Stopping strongSwan IPsec...
Feb 03 13:21:36 iridium charon[22169]: 00[DMN] signal of type SIGINT received. Shutting down
Feb 03 13:21:36 iridium charon[22169]: 00[IKE] destroying IKE_SA in state CONNECTING without notification
Feb 03 13:21:36 iridium NetworkManager[297]: initiating Main Mode IKE_SA 95118aae-acad-4101-b472-8d4c2d89528c[1] to x.x.x.x
Feb 03 13:21:36 iridium NetworkManager[297]: generating ID_PROT request 0 [ SA V V V V V ]
Feb 03 13:21:36 iridium NetworkManager[297]: sending packet: from 10.0.2.15[500] to x.x.x.x[500] (180 bytes)
Feb 03 13:21:36 iridium NetworkManager[297]: received packet: from x.x.x.x[500] to 10.0.2.15[500] (160 bytes)
Feb 03 13:21:36 iridium NetworkManager[297]: parsed ID_PROT response 0 [ SA V V V V ]
Feb 03 13:21:36 iridium NetworkManager[297]: received NAT-T (RFC 3947) vendor ID
Feb 03 13:21:36 iridium NetworkManager[297]: received XAuth vendor ID
Feb 03 13:21:36 iridium NetworkManager[297]: received DPD vendor ID
Feb 03 13:21:36 iridium NetworkManager[297]: received FRAGMENTATION vendor ID
Feb 03 13:21:36 iridium NetworkManager[297]: generating ID_PROT request 0 [ KE No NAT-D NAT-D ]
Feb 03 13:21:36 iridium NetworkManager[297]: sending packet: from 10.0.2.15[500] to x.x.x.x[500] (372 bytes)
Feb 03 13:21:36 iridium NetworkManager[297]: received packet: from x.x.x.x[500] to 10.0.2.15[500] (364 bytes)
Feb 03 13:21:36 iridium NetworkManager[297]: parsed ID_PROT response 0 [ KE No NAT-D NAT-D ]
Feb 03 13:21:36 iridium NetworkManager[297]: local host is behind NAT, sending keep alives
Feb 03 13:21:36 iridium NetworkManager[297]: generating ID_PROT request 0 [ ID HASH ]
Feb 03 13:21:36 iridium NetworkManager[297]: sending packet: from 10.0.2.15[4500] to x.x.x.x[4500] (76 bytes)
Feb 03 13:21:36 iridium NetworkManager[297]: sending retransmit 1 of request message ID 0, seq 3
Feb 03 13:21:36 iridium NetworkManager[297]: sending packet: from 10.0.2.15[4500] to x.x.x.x[4500] (76 bytes)
Feb 03 13:21:36 iridium NetworkManager[297]: destroying IKE_SA in state CONNECTING without notification
Feb 03 13:21:36 iridium NetworkManager[297]: establishing connection '95118aae-acad-4101-b472-8d4c2d89528c' failed
Feb 03 13:21:36 iridium charon[22169]: 00[IKE] uninstalling bypass policy for ::1/128
Feb 03 13:21:36 iridium charon[22169]: 00[IKE] uninstalling bypass policy for 10.0.2.0/24
Feb 03 13:21:36 iridium charon[22169]: 00[IKE] uninstalling bypass policy for fe80::/64
Feb 03 13:21:36 iridium ipsec_starter[22168]: child 22169 (charon) has quit (exit code 0)
Feb 03 13:21:36 iridium ipsec_starter[22168]: 
Feb 03 13:21:36 iridium ipsec_starter[22168]: charon stopped after 200 ms
Feb 03 13:21:36 iridium ipsec_starter[22168]: ipsec starter stopped
Feb 03 13:21:36 iridium nm-l2tp-service[22138]: g_dbus_method_invocation_take_error: assertion 'error != NULL' failed
Feb 03 13:21:36 iridium NetworkManager[297]: <info>  [1517660496.1541] vpn-connection[0x55b0e1e92500,95118aae-acad-4101-b472-8d4c2d89528c,"Work",0]: VPN plugin: state changed: stopped (6)
Feb 03 13:21:36 iridium NetworkManager[297]: <warn>  [1517660496.1575] vpn-connection[0x55b0e1e92500,95118aae-acad-4101-b472-8d4c2d89528c,"Work",0]: VPN connection: failed to connect: 'Message recipient disconnected from message bus without replying'
Feb 03 13:21:51 iridium NetworkManager[297]: <info>  [1517660511.6709] audit: op="connection-activate" uuid="95118aae-acad-4101-b472-8d4c2d89528c" name="Work" pid=679 uid=1000 result="success"
Feb 03 13:21:51 iridium NetworkManager[297]: <info>  [1517660511.6739] vpn-connection[0x55b0e1e92300,95118aae-acad-4101-b472-8d4c2d89528c,"Work",0]: Saw the service appear; activating connection
Feb 03 13:22:05 iridium NetworkManager[297]: <info>  [1517660525.0107] vpn-connection[0x55b0e1e92300,95118aae-acad-4101-b472-8d4c2d89528c,"Work",0]: VPN plugin: state changed: stopped (6)
Feb 03 13:23:31 iridium NetworkManager[297]: <info>  [1517660611.8483] settings-connection[0x55b0e1d3fb60,95118aae-acad-4101-b472-8d4c2d89528c]: write: successfully commited (keyfile: update /etc/NetworkManager/system-connections/Work (95118aae-acad-4101-b472-8d4c2d89528c,"Work"))
Feb 03 13:23:57 iridium NetworkManager[297]: <info>  [1517660637.4483] settings-connection[0x55b0e1d3fb60,95118aae-acad-4101-b472-8d4c2d89528c]: write: successfully updated (keyfile: update /etc/NetworkManager/system-connections/Work (95118aae-acad-4101-b472-8d4c2d89528c,"Work"))
Feb 03 13:23:57 iridium NetworkManager[297]: <info>  [1517660637.4493] audit: op="connection-update" uuid="95118aae-acad-4101-b472-8d4c2d89528c" name="Work" args="vpn.data" pid=22296 uid=1000 result="success"
Feb 03 13:24:07 iridium NetworkManager[297]: <info>  [1517660647.0510] audit: op="connection-activate" uuid="95118aae-acad-4101-b472-8d4c2d89528c" name="Work" pid=679 uid=1000 result="success"
Feb 03 13:24:07 iridium NetworkManager[297]: <info>  [1517660647.0531] vpn-connection[0x55b0e1e92100,95118aae-acad-4101-b472-8d4c2d89528c,"Work",0]: Saw the service appear; activating connection
Feb 03 13:24:32 iridium NetworkManager[297]: <warn>  [1517660672.0612] vpn-connection[0x55b0e1e92100,95118aae-acad-4101-b472-8d4c2d89528c,"Work",0]: VPN connection: failed to connect: 'Timeout was reached'
Feb 03 13:25:11 iridium NetworkManager[297]: <info>  [1517660711.0913] audit: op="connection-activate" uuid="95118aae-acad-4101-b472-8d4c2d89528c" name="Work" pid=679 uid=1000 result="success"
Feb 03 13:25:11 iridium NetworkManager[297]: <info>  [1517660711.0942] vpn-connection[0x55b0e1e92100,95118aae-acad-4101-b472-8d4c2d89528c,"Work",0]: Saw the service appear; activating connection
Feb 03 13:25:24 iridium NetworkManager[297]: <info>  [1517660724.4259] vpn-connection[0x55b0e1e92100,95118aae-acad-4101-b472-8d4c2d89528c,"Work",0]: VPN plugin: state changed: stopped (6)
Feb 03 13:27:10 iridium NetworkManager[297]: <info>  [1517660830.6013] settings-connection[0x55b0e1d3fb60,95118aae-acad-4101-b472-8d4c2d89528c]: write: successfully commited (keyfile: update /etc/NetworkManager/system-connections/Work (95118aae-acad-4101-b472-8d4c2d89528c,"Work"))
Feb 03 13:28:00 iridium NetworkManager[297]: <info>  [1517660880.3814] settings-connection[0x55b0e1d3fb60,95118aae-acad-4101-b472-8d4c2d89528c]: write: successfully updated (keyfile: update /etc/NetworkManager/system-connections/Work (95118aae-acad-4101-b472-8d4c2d89528c,"Work"))
Feb 03 13:28:00 iridium NetworkManager[297]: <info>  [1517660880.3829] audit: op="connection-update" uuid="95118aae-acad-4101-b472-8d4c2d89528c" name="Work" args="vpn.data" pid=22621 uid=1000 result="success"
Feb 03 13:28:14 iridium NetworkManager[297]: <info>  [1517660894.7412] audit: op="connection-activate" uuid="95118aae-acad-4101-b472-8d4c2d89528c" name="Work" pid=679 uid=1000 result="success"
Feb 03 13:28:14 iridium NetworkManager[297]: <info>  [1517660894.7465] vpn-connection[0x55b0e1e92300,95118aae-acad-4101-b472-8d4c2d89528c,"Work",0]: Saw the service appear; activating connection
Feb 03 13:28:28 iridium NetworkManager[297]: <info>  [1517660908.0922] vpn-connection[0x55b0e1e92300,95118aae-acad-4101-b472-8d4c2d89528c,"Work",0]: VPN plugin: state changed: stopped (6)
Feb 03 13:30:36 iridium NetworkManager[297]: <info>  [1517661036.2032] settings-connection[0x55b0e1d3fb60,95118aae-acad-4101-b472-8d4c2d89528c]: write: successfully commited (keyfile: update /etc/NetworkManager/system-connections/Work (95118aae-acad-4101-b472-8d4c2d89528c,"Work"))

System

uname -a Linux iridium 4.14.15-1-ARCH #1 SMP PREEMPT Tue Jan 23 21:49:25 UTC 2018 x86_64 GNU/Linux

What I'm missing here? Thanks in advance for the help.

dkosovic commented 6 years ago

The syntax for phase 1 is : cipher-hash-modpgroup,cipher-hash-modpgroup,...

The syntax for phase 2 is : cipher-hash,cipher-hash,...

So I would try a phase 2 that doesn't have modpgroup, e.g. :

phase 1 : aes256-sha1-modp2048,aes256-sha1-modp1024,aes192-sha1-modp2048,aes192-sha1-modp1024 phase 2 : aes256-sha1, aes192-sha1

Note: the ike-scan.sh is only for phase 1, but fortunately phase 2 is often based on the algorithms used in phase 1. Unfortunately some VPN servers have phase 2 configurations that are totally different to phase 1, but have only seen that in a small number of cases.

rdbisme commented 6 years ago

Thanks for you fast response.

I tried as you suggest but still getting exactly the same output. :(

How do I debug furtherly? Because the only strange entries I see are: nm-l2tp[26182] <warn> Timeout trying to establish IPsec connection

and Feb 03 14:54:47 iridium charon[26512]: 03[KNL] received netlink error: Invalid argument (22) Feb 03 14:54:47 iridium charon[26512]: 03[KNL] unable to install source route for %any6

That %any6 looks wrong...

dkosovic commented 6 years ago

There is a 10 second timeout for establishing an IPsec connection and then a kill SIGINT signal is sent to strongswan to stop it, you are seeing the warning message.

I'm not sure about the kernel messages, earlier versions of kernel 4.14 broke IPsec transport mode in the xfrm kernel module. It could possibly be a new kernel bug, I haven't tried kernel-4.14.15.

You could try using libreswan instead of strongswan, sometimes switching solves interoperability issues with VPN servers.

dkosovic commented 6 years ago

You could use libreswan or strongswan on the command-line with the generated ipsec config file for further debugging. The below ipsec commands are identical to what this VPN client uses ( except it doesn't use the sleep 2 command, but a for loop to determine when it is ready).

first make sure nm-l2tp-service isn't running :

sudo killall -TERM nm-l2tp-service

for strongswan:

sudo ipsec restart --conf /var/run/nm-l2tp-ipsec-95118aae-acad-4101-b472-8d4c2d89528c.conf --debug
sleep 2
sudo ipsec up 95118aae-acad-4101-b472-8d4c2d89528c

sudo ipsec status

For libreswan:

sudo ipsec restart
sleep 2
sudo ipsec auto --config /var/run/nm-l2tp-ipsec-95118aae-acad-4101-b472-8d4c2d89528c.conf --verbose --add 95118aae-acad-4101-b472-8d4c2d89528c
sudo ipsec auto --up 95118aae-acad-4101-b472-8d4c2d89528c

sudo ipsec status

See the libreswan or strongswan documentation for debugging verbosity and ipsec.conf syntax.

nm-l2tp-service will need to be restarted if you switch between libreswan and strongswan so that a compatible ipsec config file is generated under /var/run/.

rdbisme commented 6 years ago

@dkosovic I did not succeed to make it work. I'm not able to connect to a VPN that is working on Windows 10.

I'll search better to understand what's going on.

dkosovic commented 6 years ago

From the log output IPv6 is definitely involved somehow (e.g. uninstalling bypass policy for fe80::/64, unable to install source route for %any6), so I suspect the issue is something to do with IPv6. I'm not able to reproduce the log output as I don't have IPv6.

rdbisme commented 6 years ago

With the latest update I did today (I updated also Archlinux system packages), the VPN is now working (without any modification).

Still don't know if it's working because of an update of system packages or because of the 1.2.10-1 update of the AUR package.

dkosovic commented 6 years ago

Glad to hear it is now working.

NetworkManger-1.2.10 only had two minor bug fixes, one was a workaround for libreswan when the PSK is < 8 characters in length and the other correctly shows UDP encapsulation as ticked (if it was originally ticked) on subsequent times the IPSec Options dialog box is reopened.

So I suspect it was due to updates other than NetworkManger-1.2.10.