search

OpenVPN / openvpn3-linux

OpenVPN 3 Linux client
GNU Affero General Public License v3.0
547 stars 142 forks source link

Failed to start new session: Connection not ready to connect yet (object does not exist) #13

Closed isac322 closed 4 years ago

isac322 commented 4 years ago

when I run sudo openvpn3 session-start --config client.ovpn on ubuntu 18.04 It failed, it prints:

Using configuration profile from file: client.ovpn
Session path: /net/openvpn/v3/sessions/f004337ds9e88s4d23s8d9esd5027a5b0972
Auth User name:
Auth Password: 
Enter Google Authenticator Code: 165297
session-start: ** ERROR ** Failed to start new session: Connection not ready to connect yet (object does not exist)

and on journalctl -ex:

 1월 20 00:23:19 bhyoo-virtual-machine dbus-daemon[927]: [system] Activating service name='net.openvpn.v3.sessions' requested by ':1.115' (uid=0 pid=5804 comm="openvpn3 session-start --config client.ovpn " label
 1월 20 00:23:19 bhyoo-virtual-machine net.openvpn.v3.sessions[927]: OpenVPN 3/Linux v7_beta (openvpn3-service-sessionmgr)
 1월 20 00:23:19 bhyoo-virtual-machine net.openvpn.v3.sessions[927]: OpenVPN core 3.git:HEAD:1668f1cd linux x86_64 64-bit
 1월 20 00:23:19 bhyoo-virtual-machine net.openvpn.v3.sessions[927]: Copyright (C) 2012-2017 OpenVPN Inc. All rights reserved.
 1월 20 00:23:19 bhyoo-virtual-machine net.openvpn.v3.log[4958]: Logger VERB2: Attached: {tag:4455907153902855771}  [:1.116/net.openvpn.v3.sessions]
 1월 20 00:23:19 bhyoo-virtual-machine dbus-daemon[927]: [system] Successfully activated service 'net.openvpn.v3.sessions'
 1월 20 00:23:20 bhyoo-virtual-machine net.openvpn.v3.log[4958]: {tag:15979736196443158099} Config Manager INFO: Parsed single-use configuration 'client.ovpn', owner: root
 1월 20 00:23:20 bhyoo-virtual-machine dbus-daemon[927]: [system] Activating service name='net.openvpn.v3.backends' requested by ':1.116' (uid=122 pid=5808 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3
 1월 20 00:23:20 bhyoo-virtual-machine net.openvpn.v3.backends[927]: OpenVPN 3/Linux v7_beta (openvpn3-service-backendstart)
 1월 20 00:23:20 bhyoo-virtual-machine net.openvpn.v3.backends[927]: OpenVPN core 3.git:HEAD:1668f1cd linux x86_64 64-bit
 1월 20 00:23:20 bhyoo-virtual-machine net.openvpn.v3.backends[927]: Copyright (C) 2012-2017 OpenVPN Inc. All rights reserved.
 1월 20 00:23:20 bhyoo-virtual-machine net.openvpn.v3.log[4958]: Logger VERB2: Attached: {tag:3185898936652274477}  [:1.117/net.openvpn.v3.backends]
 1월 20 00:23:20 bhyoo-virtual-machine dbus-daemon[927]: [system] Successfully activated service 'net.openvpn.v3.backends'
 1월 20 00:23:20 bhyoo-virtual-machine net.openvpn.v3.backends[927]: Re-initiated process from pid 5817 to backend process pid 5818
 1월 20 00:23:20 bhyoo-virtual-machine net.openvpn.v3.backends[927]: OpenVPN 3/Linux v7_beta (openvpn3-service-client)
 1월 20 00:23:20 bhyoo-virtual-machine net.openvpn.v3.backends[927]: OpenVPN core 3.git:HEAD:1668f1cd linux x86_64 64-bit
 1월 20 00:23:20 bhyoo-virtual-machine net.openvpn.v3.backends[927]: Copyright (C) 2012-2017 OpenVPN Inc. All rights reserved.
 1월 20 00:23:20 bhyoo-virtual-machine net.openvpn.v3.log[4958]: Logger VERB2: Attached: {tag:15086041118856162295}  [:1.118/net.openvpn.v3.backends]
 1월 20 00:23:20 bhyoo-virtual-machine net.openvpn.v3.log[4958]: Logger VERB2: Attached: {tag:15921432625201831649}  [:1.118/net.openvpn.v3.sessions]
 1월 20 00:23:20 bhyoo-virtual-machine net.openvpn.v3.log[4958]: {tag:15086041118856162295} Client VERB1: Initializing VPN client session, token 8e178843t404ct4f28t84e7t9760cc0a3c2e
 1월 20 00:23:21 bhyoo-virtual-machine openvpn3-servic[5818]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
 1월 20 00:23:21 bhyoo-virtual-machine dbus-daemon[927]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.118" (uid=122 pid=5818 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/op
 1월 20 00:23:26 bhyoo-virtual-machine net.openvpn.v3.log[4958]: Logger VERB2: Detached: {tag:3185898936652274477}  [:1.117/net.openvpn.v3.backends]
 1월 20 00:23:27 bhyoo-virtual-machine openvpn3-servic[5818]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
 1월 20 00:23:27 bhyoo-virtual-machine dbus-daemon[927]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.118" (uid=122 pid=5818 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/op
 1월 20 00:23:32 bhyoo-virtual-machine openvpn3-servic[5818]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
 1월 20 00:23:32 bhyoo-virtual-machine dbus-daemon[927]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.118" (uid=122 pid=5818 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/op
 1월 20 00:23:32 bhyoo-virtual-machine net.openvpn.v3.log[4958]: {tag:15086041118856162295} Client INFO: Starting connection
 1월 20 00:23:32 bhyoo-virtual-machine net.openvpn.v3.log[4958]: {tag:15086041118856162295} Client VERB1: Username/password provided successfully for 'isac.yoo'
 1월 20 00:23:32 bhyoo-virtual-machine net.openvpn.v3.log[4958]: {tag:15086041118856162295} Client VERB1: Waiting for server response
 1월 20 00:23:32 bhyoo-virtual-machine net.openvpn.v3.log[4958]: {tag:17621744109520087757} Network Configuration INFO: Virtual device '8e178843t404ct4f28t84e7t9760cc0a3c2e' registered on /net/openvpn/v3/netcfg/
 1월 20 00:23:32 bhyoo-virtual-machine net.openvpn.v3.netcfg[927]: Error while executing NetlinkRoute4(add: 1) ens33: -17
 1월 20 00:23:32 bhyoo-virtual-machine net.openvpn.v3.log[4958]: {tag:17621744109520087757} Network Configuration INFO: Add bypass route to 52.68.183.173 ipv6: no
 1월 20 00:23:32 bhyoo-virtual-machine net.openvpn.v3.log[4958]: {tag:15086041118856162295} Client INFO: Connecting
 1월 20 00:23:34 bhyoo-virtual-machine openvpn3-servic[5818]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
 1월 20 00:23:34 bhyoo-virtual-machine dbus-daemon[927]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.118" (uid=122 pid=5818 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/op
 1월 20 00:23:36 bhyoo-virtual-machine openvpn3-servic[5818]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
 1월 20 00:23:36 bhyoo-virtual-machine dbus-daemon[927]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.118" (uid=122 pid=5818 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/op
 1월 20 00:23:36 bhyoo-virtual-machine kernel: openvpn3-servic[5818]: segfault at 18 ip 000055d134a3481b sp 00007ffc7cf3c9a0 error 4 in openvpn3-service-client[55d1349f5000+147000]
 1월 20 00:23:36 bhyoo-virtual-machine kernel: Code: 48 8b 7d 00 48 85 ff 74 0f 48 89 44 24 08 e8 8c 50 ff ff 48 8b 44 24 08 48 89 45 00 48 89 45 08 48 05 40 02 00 00 48 89 45 10 <48> 8b 43 18 0f b6 90 e9 03 00 
 1월 20 00:23:36 bhyoo-virtual-machine net.openvpn.v3.sessions[927]: terminate called after throwing an instance of 'openvpn::DBusException'
 1월 20 00:23:36 bhyoo-virtual-machine net.openvpn.v3.sessions[927]:   what():  Failed retrieving property value for 'device_path': The name :1.118 was not provided by any .service files
dsommers commented 4 years ago

Hey, and sorry for the delay. I've been out of office for a bit, so didn't have time to dig into this before now.

The log lines here which looks like is causing this issue is:

 [...] net.openvpn.v3.netcfg[927]: Error while executing NetlinkRoute4(add: 1) ens33: -17
 [...] net.openvpn.v3.sessions[927]:   what():  Failed retrieving property value for 'device_path': The name :1.118 was not provided by any .service files

It would be good to ensure you're running the right versions of all the backend services required in OpenVPN 3 Linux. Can you please provide the output of:

sudo openvpn3-admin version --service

If all services uses the same v7_beta reference, that's a good starting point. Next then is to increase the log level:

sudo openvpn3-admin log-service --log-level 6

and then try again. And when failing, extract the log data like this:

sudo journalctl -u dbus --since today SYSLOG_IDENTIFIER=openvpn3-service-logger

And a final notice, you do not need to sudo the openvpn2 and openvpn3 calls. OpenVPN 3 Linux allows unprivileged users to start VPN sessions and manager their own sessions. If you want root to be able to manage a session you started as an unprivileged user, have a look at openpvn3 session-acl(1)

isac322 commented 4 years ago

Hi @dsommers, also sorry for delay. It was holiday on my country.

Output of sudo openvpn3-admin version --service:

OpenVPN 3 D-Bus services:

  - Client backend starter service
     openvpn3-service-backendstart: v7_beta

  - Configuration Service
     openvpn3-service-configmgr:    v7_beta

  - Log Service
     openvpn3-service-logger:       v7_beta

  - Network Configuration Service
     openvpn3-service-netcfg:       v7_beta

  - Session Manager Service
     openvpn3-service-sessionmgr:   v7_beta

And because sudo journalctl -u dbus --since today SYSLOG_IDENTIFIER=openvpn3-service-logger prints -- No entries --, I tried sudo journalctl -u dbus --since today SYSLOG_IDENTIFIER=net.openvpn.v3.log and it prints

-- Logs begin at Mon 2020-01-20 00:06:04 KST, end at Tue 2020-01-28 23:59:57 KST. --
 1월 28 23:45:51 bhyoo-virtual-machine net.openvpn.v3.log[989]: OpenVPN 3/Linux v7_beta (openvpn3-service-logger)
 1월 28 23:45:51 bhyoo-virtual-machine net.openvpn.v3.log[989]: OpenVPN core 3.git:HEAD:1668f1cd linux x86_64 64-bit
 1월 28 23:45:51 bhyoo-virtual-machine net.openvpn.v3.log[989]: Copyright (C) 2012-2017 OpenVPN Inc. All rights reserved.
 1월 28 23:45:51 bhyoo-virtual-machine net.openvpn.v3.log[989]: Idle exit set to 10 minutes
 1월 28 23:45:51 bhyoo-virtual-machine net.openvpn.v3.log[12189]: Logger VERB2: Attached: {tag:14774919844982071610}  [:1.123/net.openvpn.v3.backends]
 1월 28 23:45:52 bhyoo-virtual-machine net.openvpn.v3.log[12189]: Logger VERB2: Attached: {tag:6103691262343558561}  [:1.125/net.openvpn.v3.configuration]
 1월 28 23:45:53 bhyoo-virtual-machine net.openvpn.v3.log[12189]: Logger VERB2: Attached: {tag:14289632613223472912}  [:1.126/net.openvpn.v3.netcfg]
 1월 28 23:45:53 bhyoo-virtual-machine net.openvpn.v3.log[12189]: Logger VERB2: Attached: {tag:7660244428571076208}  [:1.126/net.openvpn.v3.netcfg.core]
 1월 28 23:45:53 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:14289632613223472912} Network Configuration VERB1: Redirect method: host-route
 1월 28 23:45:54 bhyoo-virtual-machine net.openvpn.v3.log[12189]: Logger VERB2: Attached: {tag:5893166342581689704}  [:1.127/net.openvpn.v3.sessions]
 1월 28 23:45:57 bhyoo-virtual-machine net.openvpn.v3.log[12189]: Logger VERB2: Detached: {tag:14774919844982071610}  [:1.123/net.openvpn.v3.backends]
 1월 28 23:48:53 bhyoo-virtual-machine net.openvpn.v3.log[12189]: Logger VERB1: Log level changed to 6
 1월 28 23:50:30 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:6103691262343558561} Config Manager INFO: Parsed single-use configuration 'client.ovpn', owner: root
 1월 28 23:50:30 bhyoo-virtual-machine net.openvpn.v3.log[12189]: Logger VERB2: Attached: {tag:15067968577780944010}  [:1.144/net.openvpn.v3.backends]
 1월 28 23:50:30 bhyoo-virtual-machine net.openvpn.v3.log[12189]: Logger VERB2: Attached: {tag:4518311142645221373}  [:1.145/net.openvpn.v3.backends]
 1월 28 23:50:30 bhyoo-virtual-machine net.openvpn.v3.log[12189]: Logger VERB2: Attached: {tag:15989938200057676767}  [:1.145/net.openvpn.v3.sessions]
 1월 28 23:50:30 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client VERB1: Initializing VPN client session, token 58edd6b0tdae8t4aedtbfc3t5a23fcbf0a57
 1월 28 23:50:30 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Backend Session Process VERB2: Backend client process started as pid 19483 daemonized as pid 19484
 1월 28 23:50:30 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Backend Session Process DEBUG: BackendClientDBus registered on 'net.openvpn.v3.backends.be19484': /net/openvpn/v3/backends/session
 1월 28 23:50:30 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: Registration confirmation: 58edd6b0tdae8t4aedtbfc3t5a23fcbf0a57 == 58edd6b0tdae8t4aedtbfc3t5a23fcbf0a57 => true
 1월 28 23:50:30 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client VERB2: Retrieving configuration from /net/openvpn/v3/configuration/e26e1866x8eb0x4c39xafd7xe5f6b3bc8916
 1월 28 23:50:36 bhyoo-virtual-machine net.openvpn.v3.log[12189]: Logger VERB2: Detached: {tag:15067968577780944010}  [:1.144/net.openvpn.v3.backends]
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client INFO: Starting connection
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client VERB1: Username/password provided successfully for 'isac.yoo'
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: OpenVPN core 3.git:HEAD:1668f1cd linux x86_64 64-bit
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: Frame=512/2048/512 mssfix-ctrl=1250
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: UNUSED OPTIONS
                                                                   4 [nobind] 
                                                                   18 [sndbuf] [0] 
                                                                   19 [rcvbuf] [0] 
                                                                   23 [verb] [3]
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client VERB2: Resolving
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: Contacting 52.68.183.173:1194 via UDP
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client VERB1: Waiting for server response
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:14289632613223472912} Network Configuration DEBUG: CreateVirtualInterface('58edd6b0tdae8t4aedtbfc3t5a23fcbf0a57')
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:14289632613223472912} Network Configuration VERB2: Network device '58edd6b0tdae8t4aedtbfc3t5a23fcbf0a57' prepared
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:14289632613223472912} Network Configuration INFO: Virtual device '58edd6b0tdae8t4aedtbfc3t5a23fcbf0a57' registered on /net/openvpn/v3/netcfg/19484_58edd6b0tdae8t4aedtbfc3t5a23fcbf0a57 (owner uid 122)
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:7660244428571076208} Network Configuration DEBUG: [Core] net_route_best_gw query IPv4: 52.68.183.173/32
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:7660244428571076208} Network Configuration DEBUG: [Core] sitnl_route_best_gw result: via 192.168.10.2 dev ens33
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:7660244428571076208} Network Configuration DEBUG: [Core] net_route_add: 52.68.183.173/32 via 192.168.10.2 dev ens33 table 0 metric 0
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:14289632613223472912} Network Configuration INFO: Add bypass route to 52.68.183.173 ipv6: no
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: Connecting to [52.68.183.173]:1194 (52.68.183.173) via UDPv4
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client INFO: Connecting
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: Tunnel Options:V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA1,keysize 256,tls-auth,key-method 2,tls-client
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: Creds: Username/Password
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: Peer Info:
                                                                   IV_VER=3.git:HEAD:1668f1cd
                                                                   IV_PLAT=linux
                                                                   IV_NCP=2
                                                                   IV_TCPNL=1
                                                                   IV_PROTO=2
                                                                   IV_LZO_STUB=1
                                                                   IV_COMP_STUB=1
                                                                   IV_COMP_STUBv2=1
                                                                   IV_GUI_VER=OpenVPN 3/Linux v7_beta/3.git:HEAD:1668f1cd linux x86_64 64-bit
                                                                   IV_SSL=OpenSSL 1.1.1  11 Sep 2018
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: VERIFY OK: depth=1, /CN=OpenVPN CA
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: VERIFY OK: depth=0, /CN=OpenVPN Server
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: SSL Handshake: CN=OpenVPN Server, TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: Session is ACTIVE
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client VERB2: Retrieving configuration from server
 1월 28 23:53:37 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: Sending PUSH_REQUEST to server...
 1월 28 23:53:38 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: Sending PUSH_REQUEST to server...
 1월 28 23:53:38 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: AUTH_FAILED
 1월 28 23:53:38 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: DYNAMIC_CHALLENGE: |CRV1:R,E:NK4+GZSqQCQmjAXax9Ul0HyPx81Qu1iu:aXNhYy55b28=:Enter Google Authenticator Code|
 1월 28 23:54:52 bhyoo-virtual-machine net.openvpn.v3.log[12189]: Logger VERB2: Detached: {tag:6103691262343558561}  [:1.125/net.openvpn.v3.configuration]
schwabe commented 4 years ago

1월 28 23:53:38 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: DYNAMIC_CHALLENGE: |CRV1:R,E:NK4+GZSqQCQmjAXax9Ul0HyPx81Qu1iu:aXNhYy55b28=:Enter Google Authenticator Code|

This looks like your server requires 2FA, which I think this client does not support yet.

dsommers commented 4 years ago

1월 28 23:53:38 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:4518311142645221373} Client DEBUG: DYNAMIC_CHALLENGE: |CRV1:R,E:NK4+GZSqQCQmjAXax9Ul0HyPx81Qu1iu:aXNhYy55b28=:Enter Google Authenticator Code|

This looks like your server requires 2FA, which I think this client does not support yet.

@schwabe If 2FA doesn't work, it's a regression. I'll retest this with my test server. But that should work.

@isac322 From the log entries you reported now (good job finding the other SYSLOG_IDENTIFIER), it looks like everything is connecting as it should - and it is now the server rejecting the connection. The initial log had some more critical issues where one of the backend services (openvpn3-service-* processes), so unless that appears again - then I have a hunch it was some old versions of one or more of the openvpn3 services running - but you probably rebooted since last time, so that environment is long gone. By the way, is it an Access Server you are trying to connect to?

isac322 commented 4 years ago

@dsommers When I set SYSLOG_IDENTIFIER to net.openvpn.v3.sessions, it still prints:

 1월 28 23:45:54 bhyoo-virtual-machine net.openvpn.v3.sessions[989]: OpenVPN 3/Linux v7_beta (openvpn3-service-sessionmgr)
 1월 28 23:45:54 bhyoo-virtual-machine net.openvpn.v3.sessions[989]: OpenVPN core 3.git:HEAD:1668f1cd linux x86_64 64-bit
 1월 28 23:45:54 bhyoo-virtual-machine net.openvpn.v3.sessions[989]: Copyright (C) 2012-2017 OpenVPN Inc. All rights reserved.
 1월 28 23:53:43 bhyoo-virtual-machine net.openvpn.v3.sessions[989]: terminate called after throwing an instance of 'openvpn::DBusException'
 1월 28 23:53:43 bhyoo-virtual-machine net.openvpn.v3.sessions[989]:   what():  Failed retrieving property value for 'device_path': The name :1.145 was not provided by any .service files

(FYI. as you can see in timestamp, it is related with the last log that I post, not a separated one)

Because I paused the VM after the first issue instead of reboot, I guess the environment still exists and let me know if you need those. Yeap I'm trying to connect Access Server and its version is 2.6.1.

I guess this is full log of openvpn3 session-start --config client.ovpn

``` 1월 29 21:14:29 bhyoo-virtual-machine dbus-daemon[989]: [system] Activating service name='net.openvpn.v3.configuration' requested by ':1.215' (uid=1000 pid=24013 comm="openvpn3 session-start --config client.ovpn " label="unconfined") (using servicehelper) 1월 29 21:14:29 bhyoo-virtual-machine net.openvpn.v3.configuration[989]: OpenVPN 3/Linux v7_beta (openvpn3-service-configmgr) 1월 29 21:14:29 bhyoo-virtual-machine net.openvpn.v3.configuration[989]: OpenVPN core 3.git:HEAD:1668f1cd linux x86_64 64-bit 1월 29 21:14:29 bhyoo-virtual-machine net.openvpn.v3.configuration[989]: Copyright (C) 2012-2017 OpenVPN Inc. All rights reserved. 1월 29 21:14:29 bhyoo-virtual-machine net.openvpn.v3.log[12189]: Logger VERB2: Attached: {tag:10038039409484995346} [:1.216/net.openvpn.v3.configuration] 1월 29 21:14:29 bhyoo-virtual-machine dbus-daemon[989]: [system] Successfully activated service 'net.openvpn.v3.configuration' 1월 29 21:14:30 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:10038039409484995346} Config Manager INFO: Parsed single-use configuration 'client.ovpn', owner: bhyoo 1월 29 21:14:30 bhyoo-virtual-machine dbus-daemon[989]: [system] Activating service name='net.openvpn.v3.backends' requested by ':1.207' (uid=122 pid=23015 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") (using servicehelper) 1월 29 21:14:30 bhyoo-virtual-machine net.openvpn.v3.backends[989]: OpenVPN 3/Linux v7_beta (openvpn3-service-backendstart) 1월 29 21:14:30 bhyoo-virtual-machine net.openvpn.v3.backends[989]: OpenVPN core 3.git:HEAD:1668f1cd linux x86_64 64-bit 1월 29 21:14:30 bhyoo-virtual-machine net.openvpn.v3.backends[989]: Copyright (C) 2012-2017 OpenVPN Inc. All rights reserved. 1월 29 21:14:30 bhyoo-virtual-machine net.openvpn.v3.log[12189]: Logger VERB2: Attached: {tag:13500574870050280773} [:1.217/net.openvpn.v3.backends] 1월 29 21:14:30 bhyoo-virtual-machine dbus-daemon[989]: [system] Successfully activated service 'net.openvpn.v3.backends' 1월 29 21:14:30 bhyoo-virtual-machine net.openvpn.v3.backends[989]: Re-initiated process from pid 24026 to backend process pid 24027 1월 29 21:14:30 bhyoo-virtual-machine net.openvpn.v3.backends[989]: OpenVPN 3/Linux v7_beta (openvpn3-service-client) 1월 29 21:14:30 bhyoo-virtual-machine net.openvpn.v3.backends[989]: OpenVPN core 3.git:HEAD:1668f1cd linux x86_64 64-bit 1월 29 21:14:30 bhyoo-virtual-machine net.openvpn.v3.backends[989]: Copyright (C) 2012-2017 OpenVPN Inc. All rights reserved. 1월 29 21:14:30 bhyoo-virtual-machine net.openvpn.v3.log[12189]: Logger VERB2: Attached: {tag:8869862730241784378} [:1.218/net.openvpn.v3.backends] 1월 29 21:14:30 bhyoo-virtual-machine net.openvpn.v3.log[12189]: Logger VERB2: Attached: {tag:17348333048130766432} [:1.218/net.openvpn.v3.sessions] 1월 29 21:14:30 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client VERB1: Initializing VPN client session, token 89baf630tc22at426dta617t05695ee5f257 1월 29 21:14:30 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Backend Session Process VERB2: Backend client process started as pid 24026 daemonized as pid 24027 1월 29 21:14:30 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Backend Session Process DEBUG: BackendClientDBus registered on 'net.openvpn.v3.backends.be24027': /net/openvpn/v3/backends/session 1월 29 21:14:30 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client DEBUG: Registration confirmation: 89baf630tc22at426dta617t05695ee5f257 == 89baf630tc22at426dta617t05695ee5f257 => true 1월 29 21:14:30 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client VERB2: Retrieving configuration from /net/openvpn/v3/configuration/fecfd7bdx6d7dx4f81xb722xca867324580a 1월 29 21:14:31 bhyoo-virtual-machine openvpn3-servic[24027]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed 1월 29 21:14:31 bhyoo-virtual-machine dbus-daemon[989]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.218" (uid=122 pid=24027 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.207" (uid=122 pid=23015 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") 1월 29 21:14:33 bhyoo-virtual-machine openvpn3-servic[24027]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed 1월 29 21:14:33 bhyoo-virtual-machine dbus-daemon[989]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.218" (uid=122 pid=24027 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.207" (uid=122 pid=23015 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") 1월 29 21:14:36 bhyoo-virtual-machine net.openvpn.v3.log[12189]: Logger VERB2: Detached: {tag:13500574870050280773} [:1.217/net.openvpn.v3.backends] 1월 29 21:14:40 bhyoo-virtual-machine openvpn3-servic[24027]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed 1월 29 21:14:40 bhyoo-virtual-machine dbus-daemon[989]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.218" (uid=122 pid=24027 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.207" (uid=122 pid=23015 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client INFO: Starting connection 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client VERB1: Username/password provided successfully for 'isac.yoo' 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client DEBUG: OpenVPN core 3.git:HEAD:1668f1cd linux x86_64 64-bit 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client DEBUG: Frame=512/2048/512 mssfix-ctrl=1250 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client DEBUG: UNUSED OPTIONS 4 [nobind] 18 [sndbuf] [0] 19 [rcvbuf] [0] 23 [verb] [3] 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client VERB2: Resolving 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client DEBUG: Contacting 52.68.183.173:1194 via UDP 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client VERB1: Waiting for server response 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:14289632613223472912} Network Configuration DEBUG: CreateVirtualInterface('89baf630tc22at426dta617t05695ee5f257') 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:14289632613223472912} Network Configuration VERB2: Network device '89baf630tc22at426dta617t05695ee5f257' prepared 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:14289632613223472912} Network Configuration INFO: Virtual device '89baf630tc22at426dta617t05695ee5f257' registered on /net/openvpn/v3/netcfg/24027_89baf630tc22at426dta617t05695ee5f257 (owner uid 122) 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:7660244428571076208} Network Configuration DEBUG: [Core] net_route_best_gw query IPv4: 52.68.183.173/32 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:7660244428571076208} Network Configuration DEBUG: [Core] sitnl_route_best_gw result: via 192.168.10.2 dev ens33 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:7660244428571076208} Network Configuration DEBUG: [Core] net_route_add: 52.68.183.173/32 via 192.168.10.2 dev ens33 table 0 metric 0 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:14289632613223472912} Network Configuration INFO: Add bypass route to 52.68.183.173 ipv6: no 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client DEBUG: Connecting to [52.68.183.173]:1194 (52.68.183.173) via UDPv4 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client INFO: Connecting 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client DEBUG: Tunnel Options:V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA1,keysize 256,tls-auth,key-method 2,tls-client 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client DEBUG: Creds: Username/Password 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client DEBUG: Peer Info: IV_VER=3.git:HEAD:1668f1cd IV_PLAT=linux IV_NCP=2 IV_TCPNL=1 IV_PROTO=2 IV_LZO_STUB=1 IV_COMP_STUB=1 IV_COMP_STUBv2=1 IV_GUI_VER=OpenVPN 3/Linux v7_beta/3.git:HEAD:1668f1cd linux x86_64 64-bit IV_SSL=OpenSSL 1.1.1 11 Sep 2018 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client DEBUG: VERIFY OK: depth=1, /CN=OpenVPN CA 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client DEBUG: VERIFY OK: depth=0, /CN=OpenVPN Server 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client DEBUG: SSL Handshake: CN=OpenVPN Server, TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client DEBUG: Session is ACTIVE 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client VERB2: Retrieving configuration from server 1월 29 21:14:40 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client DEBUG: Sending PUSH_REQUEST to server... 1월 29 21:14:41 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client DEBUG: Sending PUSH_REQUEST to server... 1월 29 21:14:41 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client DEBUG: AUTH_FAILED 1월 29 21:14:41 bhyoo-virtual-machine net.openvpn.v3.log[12189]: {tag:8869862730241784378} Client DEBUG: DYNAMIC_CHALLENGE: |CRV1:R,E:HrZgBYQ6S/0/HASPXyNKeI6PahHmdJBM:aXNhYy55b28=:Enter Google Authenticator Code| 1월 29 21:14:41 bhyoo-virtual-machine openvpn3-servic[24027]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed 1월 29 21:14:41 bhyoo-virtual-machine dbus-daemon[989]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.218" (uid=122 pid=24027 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.207" (uid=122 pid=23015 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") 1월 29 21:14:47 bhyoo-virtual-machine openvpn3-servic[24027]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed 1월 29 21:14:47 bhyoo-virtual-machine dbus-daemon[989]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.218" (uid=122 pid=24027 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.207" (uid=122 pid=23015 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") 1월 29 21:14:47 bhyoo-virtual-machine kernel: openvpn3-servic[24027]: segfault at 18 ip 0000559ddc3fe81b sp 00007ffee4a1f6a0 error 4 in openvpn3-service-client[559ddc3bf000+147000] 1월 29 21:14:47 bhyoo-virtual-machine kernel: Code: 48 8b 7d 00 48 85 ff 74 0f 48 89 44 24 08 e8 8c 50 ff ff 48 8b 44 24 08 48 89 45 00 48 89 45 08 48 05 40 02 00 00 48 89 45 10 <48> 8b 43 18 0f b6 90 e9 03 00 00 84 d2 74 76 4c 8b a8 c8 01 00 00 1월 29 21:14:47 bhyoo-virtual-machine net.openvpn.v3.sessions[989]: terminate called after throwing an instance of 'openvpn::DBusException' 1월 29 21:14:47 bhyoo-virtual-machine net.openvpn.v3.sessions[989]: what(): Failed retrieving property value for 'device_path': The name :1.218 was not provided by any .service files ```

dsommers commented 4 years ago

Can you, please, also provide the logs for SYSLOG_IDENTIFIER=net.openvpn.v3.netcfg?

isac322 commented 4 years ago

Sure!

 1월 28 23:45:53 bhyoo-virtual-machine net.openvpn.v3.netcfg[989]: OpenVPN 3/Linux v7_beta (openvpn3-service-netcfg)
 1월 28 23:45:53 bhyoo-virtual-machine net.openvpn.v3.netcfg[989]: OpenVPN core 3.git:HEAD:1668f1cd linux x86_64 64-bit
 1월 28 23:45:53 bhyoo-virtual-machine net.openvpn.v3.netcfg[989]: Copyright (C) 2012-2017 OpenVPN Inc. All rights reserved.
 1월 29 21:05:52 bhyoo-virtual-machine net.openvpn.v3.netcfg[989]: Error while executing NetlinkRoute4(add: 1) ens33: -17
dsommers commented 4 years ago

Thanks, even though this process looks tedious, it gives information about these lines from our initial log:

 1월 20 00:23:21 bhyoo-virtual-machine dbus-daemon[927]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.118" (uid=122 pid=5818 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/op
 1월 20 00:23:26 bhyoo-virtual-machine net.openvpn.v3.log[4958]: Logger VERB2: Detached: {tag:3185898936652274477}  [:1.117/net.openvpn.v3.backends]
 1월 20 00:23:27 bhyoo-virtual-machine openvpn3-servic[5818]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
 1월 20 00:23:27 bhyoo-virtual-machine dbus-daemon[927]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.118" (uid=122 pid=5818 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/op
 1월 20 00:23:32 bhyoo-virtual-machine openvpn3-servic[5818]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
 1월 20 00:23:32 bhyoo-virtual-machine dbus-daemon[927]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.118" (uid=122 pid=5818 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/op

I am now fairly confident these comes from the openvpn3-service-client process, and this is the most tricky part to get a core dump out of. And I believe this process crashes/dies; due to this error by the session manager:

Failed retrieving property value for 'device_path': The name :1.145 was not provided by any .service files

To get further, without fighting whatever coredump setup you have on your Linux distro ... lets start this process step by step via Python. This will be a "quick debugging with GDB crash course". First, ensure you have gdb installed on your system, then import the VPN configuration profile into the configuration manager unless you have done so already:

$ openvpn3 config-import --config client.ovpn

Since you connect against an Access Server, you can also do it this way:

$ openvpn3-as https://as.example.com/

where the https://as.example.com/ is the proper URL to your Access Server. To see already imported configuration profiles, use openvpn3 configs-list

This returns a Configuration path which we will use next. The Python script below is needed:

import dbus
import sys
import time
import getpass

if len(sys.argv) != 2:
    print "Usage: %s <config path>" % (sys.argv[0])
    sys.exit(1);

configpath = sys.argv[1]

# Get a connection to the system bus
bus = dbus.SystemBus()

# Retrieve the main session manager object
manager_object = bus.get_object('net.openvpn.v3.sessions',
                           '/net/openvpn/v3/sessions')

# Retireve access to the proper interface in the object
sessions_interface = dbus.Interface(manager_object,
                                  dbus_interface='net.openvpn.v3.sessions')

# Start a new tunnel session
session_path = sessions_interface.NewTunnel(dbus.ObjectPath(configpath))
print("Session path: " + session_path)

time.sleep(1.2)

session_obj = bus.get_object('net.openvpn.v3.sessions', session_path);
sessinterface = dbus.Interface(session_obj, dbus_interface='net.openvpn.v3.sessions')

done = False
while not done:
    try:
        sessinterface.Ready()

        try:
            input("Press enter to call Connect() ...")
        except:
            pass

        sessinterface.Connect()
    time.sleep(5)

        try:
            input("Press enter to call Ready() ...")
        except:
            pass
        sessinterface.Ready()

        try:
            input("Press enter to call Disconnect() ...")
        except:
            pass

        sessinterface.Disconnect()
        done = True

    except dbus.exceptions.DBusException, excep:
        if str(excep).find(' Missing user credentials') > 0:
            print("Credentials needed")

            for qgrp in (1,3):
                for id in sessinterface.UserInputQueueCheck(1, qgrp):
                    uiq = sessinterface.UserInputQueueFetch(1, qgrp, id)

                    if uiq[5] == False:
                        response = raw_input(uiq[4] + ": ")
                    else:
                        response = getpass.getpass(uiq[4] + ": ")

                    sessinterface.UserInputProvide(1, qgrp, id, response)
        else:
            print excep
            done = True

Start this script like this: $ python3 debug-vpn.py /net/openvpn/v3/configuration/....... The line above is the line where you use the configuration path from the openvpn3 config-import.

When this script starts, you will see something like this:

Session path: /net/openvpn/v3/sessions/3869ec90s37cbs49aasb5fbsd47c036f11e3
Press enter to call Connect() ...

Do not "press enter" just yet. Run the openvpn3 sessions-list command, where you will see a PID value. Use this one and attach GDB to it. If the sessions-list says your session runs with PID: 1234, then your command line will be gdb --pid 1234. The gdb command needs to be run as root.

Once gdb has started, type cont and hit enter in the gdb window. Now you can hit enter in the the window of the Python script, which will take it one step further. You will probably need to enter your user credentials and hit enter a few more times before you see the crash in the GDB window.

When the a crash (segfault, abort, etc) happens in the GDB window, you will ge the gdb prompt. Now type: thread apply all bt (hit enter until you're back to the gdb command prompt) and please provide the output from gdb. This will help me understand where and hopefully why openvpn3-service-client crashed.

dsommers commented 4 years ago

I think I have found the issue to this bug. If this is the same issue, it is related to the fix in commit 004a0505363b64e32f79683878460aec936fec3a

isac322 commented 4 years ago

I think I have found the issue to this bug. If this is the same issue, it is related to the fix in commit 004a050

@dsommers Wow it works!! Sorry for delay and thank you so much for your work. Finally I can connect my company's VPN with my linux laptop!!

dsommers commented 4 years ago

Good to hear this release works for you!

The v8_beta was released on just a few days ago with this fix, so I consider this issue resolved.