Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Client disconnected after a few minutes #21

Closed
DatCanCode opened this issue Sep 21, 2023 · 13 comments
Closed

Client disconnected after a few minutes #21

DatCanCode opened this issue Sep 21, 2023 · 13 comments

Comments

@DatCanCode
Copy link

DatCanCode commented Sep 21, 2023 •
edited
Loading

Thank you for your library. I can successfully use Azure AD to login.
But after just a few minutes, client was disconnected with OpenVPN server. Can you help me figure out why this is happening.

OpenVPN server log:

2023-09-21 10:35:56 Note: --cipher is not set. OpenVPN versions before 2.5 defaulted to BF-CBC as fallback when cipher negotiation failed in this case. If you need this fallback please add '--data-ciphers-fallback BF-CBC' to your configuration and/or add BF-CBC to --data-ciphers.
2023-09-21 10:35:56 Note: Kernel support for ovpn-dco missing, disabling data channel offload.
2023-09-21 10:35:56 WARNING: Using --management on a TCP port WITHOUT passwords is STRONGLY discouraged and considered insecure
2023-09-21 10:35:56 OpenVPN 2.6.6 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] [DCO]
2023-09-21 10:35:56 library versions: OpenSSL 1.1.1f  31 Mar 2020, LZO 2.10
2023-09-21 10:35:56 DCO version: N/A
2023-09-21 10:35:56 MANAGEMENT: TCP Socket listening on [AF_INET][undef]:8081
2023-09-21 10:35:56 Need hold release from management interface, waiting...
2023-09-21 10:41:41 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:59898
2023-09-21 10:41:41 MANAGEMENT: CMD 'hold release'
2023-09-21 10:41:41 net_route_v4_best_gw query: dst 0.0.0.0
2023-09-21 10:41:41 net_route_v4_best_gw result: via 172.16.7.1 dev eth0
2023-09-21 10:41:41 TUN/TAP device tun0 opened
2023-09-21 10:41:41 net_iface_mtu_set: mtu 1500 for tun0
2023-09-21 10:41:41 net_iface_up: set tun0 up
2023-09-21 10:41:41 net_addr_v4_add: 10.8.0.1/24 dev tun0
2023-09-21 10:41:41 Could not determine IPv4/IPv6 protocol. Using AF_INET
2023-09-21 10:41:41 Socket Buffers: R=[212992->212992] S=[212992->212992]
2023-09-21 10:41:41 UDPv4 link local (bound): [AF_INET][undef]:1194
2023-09-21 10:41:41 UDPv4 link remote: [AF_UNSPEC]
2023-09-21 10:41:41 UID set to nobody
2023-09-21 10:41:41 GID set to nogroup
2023-09-21 10:41:41 Capabilities retained: CAP_NET_ADMIN
2023-09-21 10:41:41 MULTI: multi_init called, r=256 v=256
2023-09-21 10:41:41 IFCONFIG POOL IPv4: base=10.8.0.2 size=253
2023-09-21 10:41:41 Initialization Sequence Completed
2023-09-21 10:41:41 MANAGEMENT: CMD 'version'
2023-09-21 10:42:04 A.B.C.D:50849 VERIFY OK: depth=1, CN=Easy-RSA CA
2023-09-21 10:42:04 A.B.C.D:50849 VERIFY OK: depth=0, CN=client
2023-09-21 10:42:04 A.B.C.D:50849 peer info: IV_VER=v3.7.1
2023-09-21 10:42:04 A.B.C.D:50849 peer info: IV_PLAT=linux
2023-09-21 10:42:04 A.B.C.D:50849 peer info: IV_NCP=2
2023-09-21 10:42:04 A.B.C.D:50849 peer info: IV_TCPNL=1
2023-09-21 10:42:04 A.B.C.D:50849 peer info: IV_PROTO=30
2023-09-21 10:42:04 A.B.C.D:50849 peer info: IV_CIPHERS=AES-128-GCM:AES-192-GCM:AES-256-GCM:CHACHA20-POLY1305
2023-09-21 10:42:04 A.B.C.D:50849 peer info: IV_AUTO_SESS=1
2023-09-21 10:42:04 A.B.C.D:50849 peer info: IV_GUI_VER=OpenVPN3/Linux/v19_beta
2023-09-21 10:42:04 A.B.C.D:50849 peer info: IV_SSO=openurl,webauth
2023-09-21 10:42:04 A.B.C.D:50849 peer info: IV_BS64DL=1
2023-09-21 10:42:04 A.B.C.D:50849 TLS: Username/Password authentication deferred for username '' 
2023-09-21 10:42:04 A.B.C.D:50849 TLS: move_session: dest=TM_ACTIVE src=TM_INITIAL reinit_src=1
2023-09-21 10:42:04 A.B.C.D:50849 TLS: tls_multi_process: initial untrusted session promoted to semi-trusted
2023-09-21 10:42:04 MANAGEMENT: CMD 'client-pending-auth 0 1 "WEB_AUTH::https://placeholder.com/oauth2/start?state=nJwAv54EWmnB%2B5OvIG9mZuEn1w0wCD2O4q53d6r05ApNNkb9DEv0oUmvn3agIUyknxTRoxLWZ4fVBR3xx3lqFSOQWsUmHxSRRHpjWdO7i8wun8s8bw8NrMbJYXORGApFHYQyi584LWu5QA%3D%3D" 600'
2023-09-21 10:42:04 SENT CONTROL [client]: 'AUTH_PENDING,timeout 60' (status=1)
2023-09-21 10:42:04 SENT CONTROL [client]: 'INFO_PRE,WEB_AUTH::https://placeholder.com/oauth2/start?state=nJwAv54EWmnB%2B5OvIG9mZuEn1w0wCD2O4q53d6r05ApNNkb9DEv0oUmvn3agIUyknxTRoxLWZ4fVBR3xx3lqFSOQWsUmHxSRRHpjWdO7i8wun8s8bw8NrMbJYXORGApFHYQyi584LWu5QA%3D%3D' (status=1)
2023-09-21 10:42:04 A.B.C.D:50849 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 253 bit ED25519, signature: ED25519
2023-09-21 10:42:04 A.B.C.D:50849 [client] Peer Connection Initiated with [AF_INET]A.B.C.D:50849
2023-09-21 10:42:04 A.B.C.D:50849 PUSH: Received control message: 'PUSH_REQUEST'
2023-09-21 10:42:05 A.B.C.D:50849 PUSH: Received control message: 'PUSH_REQUEST'
2023-09-21 10:42:13 A.B.C.D:50849 PUSH: Received control message: 'PUSH_REQUEST'
2023-09-21 10:42:21 A.B.C.D:50849 PUSH: Received control message: 'PUSH_REQUEST'
2023-09-21 10:42:29 A.B.C.D:50849 PUSH: Received control message: 'PUSH_REQUEST'
2023-09-21 10:42:37 A.B.C.D:50849 PUSH: Received control message: 'PUSH_REQUEST'
2023-09-21 10:42:45 A.B.C.D:50849 PUSH: Received control message: 'PUSH_REQUEST'
2023-09-21 10:42:46 MANAGEMENT: Client disconnected
2023-09-21 10:42:53 A.B.C.D:50849 PUSH: Received control message: 'PUSH_REQUEST'
2023-09-21 10:43:01 A.B.C.D:50849 PUSH: Received control message: 'PUSH_REQUEST'
2023-09-21 10:43:04 A.B.C.D:50849 Delayed exit in 5 seconds
2023-09-21 10:43:04 A.B.C.D:50849 SENT CONTROL [UNDEF]: 'AUTH_FAILED' (status=1)
2023-09-21 10:43:04 A.B.C.D:50849 SENT CONTROL [client]: 'AUTH_FAILED' (status=1)
2023-09-21 10:43:09 A.B.C.D:50849 SIGTERM[soft,delayed-exit] received, client-instance exiting
2023-09-21 10:43:53 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:59752
2023-09-21 10:43:53 MANAGEMENT: CMD 'hold release'
2023-09-21 10:43:53 MANAGEMENT: CMD 'version'
2023-09-21 10:44:13 A.B.C.D:50550 VERIFY OK: depth=0, CN=client
2023-09-21 10:44:13 A.B.C.D:50550 peer info: IV_VER=v3.7.1
2023-09-21 10:44:13 A.B.C.D:50550 peer info: IV_PLAT=linux
2023-09-21 10:44:13 A.B.C.D:50550 peer info: IV_NCP=2
2023-09-21 10:44:13 A.B.C.D:50550 peer info: IV_TCPNL=1
2023-09-21 10:44:13 A.B.C.D:50550 peer info: IV_PROTO=30
2023-09-21 10:44:13 A.B.C.D:50550 peer info: IV_CIPHERS=AES-128-GCM:AES-192-GCM:AES-256-GCM:CHACHA20-POLY1305
2023-09-21 10:44:13 A.B.C.D:50550 peer info: IV_AUTO_SESS=1
2023-09-21 10:44:13 A.B.C.D:50550 peer info: IV_GUI_VER=OpenVPN3/Linux/v19_beta
2023-09-21 10:44:13 A.B.C.D:50550 peer info: IV_SSO=openurl,webauth
2023-09-21 10:44:13 A.B.C.D:50550 peer info: IV_BS64DL=1
2023-09-21 10:44:13 A.B.C.D:50550 TLS: Username/Password authentication deferred for username '' 
2023-09-21 10:44:13 A.B.C.D:50550 TLS: move_session: dest=TM_ACTIVE src=TM_INITIAL reinit_src=1
2023-09-21 10:44:13 A.B.C.D:50550 TLS: tls_multi_process: initial untrusted session promoted to semi-trusted
2023-09-21 10:44:13 MANAGEMENT: CMD 'client-pending-auth 1 1 "WEB_AUTH::https://placeholder.com/oauth2/start?state=ePEZ1OSTa9XOPamzzWE1nZ6eATmjHiOFtyyj7TfkNHBkYWUtwjtv57WtApkvu3OG45XNqr2YBBu%2B%2F%2B0DKdwyDsyYyQZ29HG8JmZMGZXnkiLx2WjuXvvQFEESdvufWklaKCY2ZNtpmNbAkw%3D%3D" 600'
2023-09-21 10:44:13 SENT CONTROL [client]: 'AUTH_PENDING,timeout 60' (status=1)
2023-09-21 10:44:13 SENT CONTROL [client]: 'INFO_PRE,WEB_AUTH::https://placeholder.com/oauth2/start?state=ePEZ1OSTa9XOPamzzWE1nZ6eATmjHiOFtyyj7TfkNHBkYWUtwjtv57WtApkvu3OG45XNqr2YBBu%2B%2F%2B0DKdwyDsyYyQZ29HG8JmZMGZXnkiLx2WjuXvvQFEESdvufWklaKCY2ZNtpmNbAkw%3D%3D' (status=1)
2023-09-21 10:44:13 A.B.C.D:50550 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 253 bit ED25519, signature: ED25519
2023-09-21 10:44:13 A.B.C.D:50550 [client] Peer Connection Initiated with [AF_INET]A.B.C.D:50550
2023-09-21 10:44:13 A.B.C.D:50550 PUSH: Received control message: 'PUSH_REQUEST'
2023-09-21 10:44:14 A.B.C.D:50550 PUSH: Received control message: 'PUSH_REQUEST'
2023-09-21 10:44:17 MANAGEMENT: CMD 'client-auth-nt 1 1'
2023-09-21 10:44:22 A.B.C.D:50550 PUSH: Received control message: 'PUSH_REQUEST'
2023-09-21 10:44:22 client/A.B.C.D:50550 MULTI_sva: pool returned IPv4=10.8.0.2, IPv6=(Not enabled)
2023-09-21 10:44:22 client/A.B.C.D:50550 MULTI: Learn: 10.8.0.2 -> client/A.B.C.D:50550
2023-09-21 10:44:22 client/A.B.C.D:50550 MULTI: primary virtual IP for client/A.B.C.D:50550: 10.8.0.2
2023-09-21 10:44:22 client/A.B.C.D:50550 SENT CONTROL [client]: 'PUSH_REPLY,redirect-gateway def1 bypass-dhcp,dhcp-option DNS 208.67.222.222,dhcp-option DNS 208.67.220.220,route-gateway 10.8.0.1,topology subnet,ping 10,ping-restart 60,ifconfig 10.8.0.2 255.255.255.0,peer-id 0,cipher AES-256-GCM,key-derivation tls-ekm' (status=1)
2023-09-21 10:44:23 client/A.B.C.D:50550 Data Channel: cipher 'AES-256-GCM', peer-id: 0
2023-09-21 10:44:23 client/A.B.C.D:50550 Timers: ping 10, ping-restart 120
2023-09-21 10:44:23 client/A.B.C.D:50550 Protocol options: explicit-exit-notify 1, protocol-flags tls-ekm
2023-09-21 10:45:12 client/A.B.C.D:50550 TLS: soft reset sec=59/59 bytes=375191/-1 pkts=1096/0
2023-09-21 10:45:14 client/A.B.C.D:50550 VERIFY OK: depth=1, CN=Easy-RSA CA
2023-09-21 10:45:14 client/A.B.C.D:50550 VERIFY OK: depth=0, CN=client
2023-09-21 10:45:14 client/A.B.C.D:50550 peer info: IV_VER=v3.7.1
2023-09-21 10:45:14 client/A.B.C.D:50550 peer info: IV_PLAT=linux
2023-09-21 10:45:14 client/A.B.C.D:50550 peer info: IV_NCP=2
2023-09-21 10:45:14 client/A.B.C.D:50550 peer info: IV_TCPNL=1
2023-09-21 10:45:14 client/A.B.C.D:50550 peer info: IV_PROTO=30
2023-09-21 10:45:14 client/A.B.C.D:50550 peer info: IV_CIPHERS=AES-128-GCM:AES-192-GCM:AES-256-GCM:CHACHA20-POLY1305
2023-09-21 10:45:14 client/A.B.C.D:50550 peer info: IV_AUTO_SESS=1
2023-09-21 10:45:14 client/A.B.C.D:50550 peer info: IV_GUI_VER=OpenVPN3/Linux/v19_beta
2023-09-21 10:45:14 client/A.B.C.D:50550 peer info: IV_SSO=openurl,webauth
2023-09-21 10:45:14 client/A.B.C.D:50550 TLS: Username/Password authentication deferred for username '' 
2023-09-21 10:45:14 MANAGEMENT: CMD 'client-pending-auth 1 3 "WEB_AUTH::https://placeholder.com/oauth2/start?state=5%2FEh5MMw%2BIjZZQau1gRhvMIxnr8PSI%2B9SsTowA1yCjhDo0trR7JA3Vo5xAvL0BUo%2FvxUYCw8hhN6AbkT0QKMsSz53%2B3VWzn3TFlKydvJ4tvFmhDFGqynH%2F%2FNEWOMtJAo9UhbuQO4WDQP7g%3D%3D" 600'
2023-09-21 10:45:14 SENT CONTROL [client]: 'AUTH_PENDING,timeout 58' (status=1)
2023-09-21 10:45:14 SENT CONTROL [client]: 'INFO_PRE,WEB_AUTH::https://placeholder.com/oauth2/start?state=5%2FEh5MMw%2BIjZZQau1gRhvMIxnr8PSI%2B9SsTowA1yCjhDo0trR7JA3Vo5xAvL0BUo%2FvxUYCw8hhN6AbkT0QKMsSz53%2B3VWzn3TFlKydvJ4tvFmhDFGqynH%2F%2FNEWOMtJAo9UhbuQO4WDQP7g%3D%3D' (status=1)
2023-09-21 10:45:14 client/A.B.C.D:50550 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 253 bit ED25519, signature: ED25519
2023-09-21 10:46:13 client/A.B.C.D:50550 Delayed exit in 5 seconds
2023-09-21 10:46:13 client/A.B.C.D:50550 SENT CONTROL [UNDEF]: 'AUTH_FAILED' (status=1)
2023-09-21 10:46:13 client/A.B.C.D:50550 SENT CONTROL [client]: 'AUTH_FAILED' (status=1)
2023-09-21 10:46:18 client/A.B.C.D:50550 SIGTERM[soft,delayed-exit] received, client-instance exiting

server.conf:

dev tun
server 10.8.0.0 255.255.255.0
verb 3
ca /etc/openvpn/pki/ca.crt
key /etc/openvpn/pki/private/server.key
cert /etc/openvpn/pki/issued/server.crt
dh none
keepalive 10 60
persist-key
persist-tun
explicit-exit-notify

push "redirect-gateway def1 bypass-dhcp"
push "dhcp-option DNS 208.67.222.222"
push "dhcp-option DNS 208.67.220.220"


tls-cert-profile preferred

topology subnet
proto udp
port 1194

fast-io
user nobody
group nogroup

management 0.0.0.0 8081
management-hold
management-client-auth
#auth-gen-token 0 external-auth

reneg-sec 60
auth-user-pass-optional

client.ovpn:

client
dev tun
nobind
remote A.B.C.D 1194 udp4
remote-cert-tls server
resolv-retry infinite
tls-cert-profile preferred
persist-tun
verb 3

<key></key>
<cert></cert>
<ca></ca>
@jkroepke
Copy link
Owner

Hi,

the reneg-sec 60 is way to low for production scenario, use 3600 at minimum here.

reneg-sec define the interval in seconds to re-authenticate the session.

@DatCanCode
Copy link
Author

You've saved my day!
So after reneg-sec seconds, client need to re-authenticate but in the log I see some AUTH_FAILED and the client was disconnected with the server. Is this a correct behavior?

@jkroepke
Copy link
Owner

Seems like that the user does not finish the auth flow on the browser. OpenVPN waits only 1 Minute, then AUTH_FAILED

@DatCanCode
Copy link
Author

Just saw that client-pending-auth CMD. So, according to the log, the OpenVPN server initiated a semi-trusted session and is waiting for the client to complete the login flow. But in client side when I run command to connect, it open my browser and after I logged in. It redirect to https://placeholder.com/oauth2/callback?code= saying that "You have logged into OpenVPN!
You can close this window now"

@jkroepke
Copy link
Owner

jkroepke commented Sep 21, 2023 •
edited
Loading

hm. so maybe we have an bug here.

On my local system, we works for multiple hours. (reauth each 60 seconds).

Any logs from the service? Please mention the project is new and I have to add more logging.

@DatCanCode
Copy link
Author

DatCanCode commented Sep 21, 2023 •
edited
Loading

When I start the OpenVPN server, it said:

2023-09-21 12:14:06 Note: --cipher is not set. OpenVPN versions before 2.5 defaulted to BF-CBC as fallback when cipher negotiation failed in this case. If you need this fallback please add '--data-ciphers-fallback BF-CBC' to your configuration and/or add BF-CBC to --data-ciphers.
2023-09-21 12:14:06 Note: Kernel support for ovpn-dco missing, disabling data channel offload.
2023-09-21 12:14:06 WARNING: Using --management on a TCP port WITHOUT passwords is STRONGLY discouraged and considered insecure
2023-09-21 12:14:06 OpenVPN 2.6.6 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] [DCO]
2023-09-21 12:14:06 library versions: OpenSSL 1.1.1f  31 Mar 2020, LZO 2.10
2023-09-21 12:14:06 DCO version: N/A
2023-09-21 12:14:06 MANAGEMENT: TCP Socket listening on [AF_INET][undef]:8081
2023-09-21 12:14:06 Need hold release from management interface, waiting...

then I run openvpn-auth-oauth2 with following arguments:

openvpn-auth-oauth2 \
  --oauth2.issuer https://login.microsoftonline.com/**/v2.0 \
  --oauth2.client.id ** \
  --oauth2.client.secret ** \ 
  --http.secret ** \
  --openvpn.addr tcp://127.0.0.1:8081 \
  --http.baseUrl **

openvpn-auth-oauth2 said:

{"level":"info","ts":1695298554.2670147,"msg":"discover OIDC auto configuration for issuer https://login.microsoftonline.com/***/v2.0"}
{"level":"info","ts":1695298554.6035926,"msg":"HTTP server listen on :80"}
{"level":"info","ts":1695298554.6041052,"msg":"Connection to OpenVPN management interfaced established."}
{"level":"info","ts":1695298554.614297,"msg":"OpenVPN Version: OpenVPN 2.6.6 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] [DCO]\r\nManagement Version: 5\r\nEND\r\n"}

OpenVPN server said:

2023-09-21 12:15:54 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:49814
2023-09-21 12:15:54 MANAGEMENT: CMD 'hold release'
2023-09-21 12:15:54 net_route_v4_best_gw query: dst 0.0.0.0
2023-09-21 12:15:54 net_route_v4_best_gw result: via 172.16.7.1 dev eth0
2023-09-21 12:15:54 TUN/TAP device tun0 opened
2023-09-21 12:15:54 net_iface_mtu_set: mtu 1500 for tun0
2023-09-21 12:15:54 net_iface_up: set tun0 up
2023-09-21 12:15:54 net_addr_v4_add: 10.8.0.1/24 dev tun0
2023-09-21 12:15:54 Could not determine IPv4/IPv6 protocol. Using AF_INET
2023-09-21 12:15:54 Socket Buffers: R=[212992->212992] S=[212992->212992]
2023-09-21 12:15:54 UDPv4 link local (bound): [AF_INET][undef]:1194
2023-09-21 12:15:54 UDPv4 link remote: [AF_UNSPEC]
2023-09-21 12:15:54 UID set to nobody
2023-09-21 12:15:54 GID set to nogroup
2023-09-21 12:15:54 Capabilities retained: CAP_NET_ADMIN
2023-09-21 12:15:54 MULTI: multi_init called, r=256 v=256
2023-09-21 12:15:54 IFCONFIG POOL IPv4: base=10.8.0.2 size=253
2023-09-21 12:15:54 Initialization Sequence Completed
2023-09-21 12:15:54 MANAGEMENT: CMD 'version'

When I start openvpn client connection. The client said:

2023-09-21 19:18:40 [STATUS] Connection, Configuration OK: config_path=/net/openvpn/v3/configuration/ca351894xf8c6x4d54xbd62x62f99c70e01c
2023-09-21 19:18:40 Client INFO: Starting connection
2023-09-21 19:18:40 [STATUS] Connection, Client connecting
2023-09-21 19:18:40 Client INFO: Connecting
2023-09-21 19:18:40 [STATUS] Connection, Client connecting
2023-09-21 19:18:40 [STATUS] Session, URL authentication: https://placeholder.com/oauth2/start?state=cFcJ1GgWlwFjvP%2Br3kYtJ6givkPHRN%2B0bI%2BmGPG7Wjc2hCO3HMYgd%2Bth1q2xXq69INxebEGD67EYF2QOQXYxb4Z4BB8JzXJkJpEqL4EhgZZMwJ%2BQt9w5cccFFPXJDfaVpsQS1xF%2BOWgBPQ%3D%3D
2023-09-21 19:18:49 Client INFO: Connected: A.B.C.D:1194 (A.B.C.D) via /UDPv4 on tun/10.8.0.2/ gw=[10.8.0.1/]
2023-09-21 19:18:49 [STATUS] Connection, Client connected

then it opens my browser which I already logged in my azure AD account. This moment, the OpenVPN server said:

2023-09-21 12:18:40 115.79.139.87:42275 VERIFY OK: depth=1, CN=Easy-RSA CA
2023-09-21 12:18:40 115.79.139.87:42275 VERIFY OK: depth=0, CN=client
2023-09-21 12:18:40 115.79.139.87:42275 peer info: IV_VER=v3.7.1
2023-09-21 12:18:40 115.79.139.87:42275 peer info: IV_PLAT=linux
2023-09-21 12:18:40 115.79.139.87:42275 peer info: IV_NCP=2
2023-09-21 12:18:40 115.79.139.87:42275 peer info: IV_TCPNL=1
2023-09-21 12:18:40 115.79.139.87:42275 peer info: IV_PROTO=30
2023-09-21 12:18:40 115.79.139.87:42275 peer info: IV_CIPHERS=AES-128-GCM:AES-192-GCM:AES-256-GCM:CHACHA20-POLY1305
2023-09-21 12:18:40 115.79.139.87:42275 peer info: IV_AUTO_SESS=1
2023-09-21 12:18:40 115.79.139.87:42275 peer info: IV_GUI_VER=OpenVPN3/Linux/v19_beta
2023-09-21 12:18:40 115.79.139.87:42275 peer info: IV_SSO=openurl,webauth
2023-09-21 12:18:40 115.79.139.87:42275 peer info: IV_BS64DL=1
2023-09-21 12:18:40 115.79.139.87:42275 TLS: Username/Password authentication deferred for username '' 
2023-09-21 12:18:40 115.79.139.87:42275 TLS: move_session: dest=TM_ACTIVE src=TM_INITIAL reinit_src=1
2023-09-21 12:18:40 115.79.139.87:42275 TLS: tls_multi_process: initial untrusted session promoted to semi-trusted
2023-09-21 12:18:40 MANAGEMENT: CMD 'client-pending-auth 0 1 "WEB_AUTH::https://placeholder.com/oauth2/start?state=cFcJ1GgWlwFjvP%2Br3kYtJ6givkPHRN%2B0bI%2BmGPG7Wjc2hCO3HMYgd%2Bth1q2xXq69INxebEGD67EYF2QOQXYxb4Z4BB8JzXJkJpEqL4EhgZZMwJ%2BQt9w5cccFFPXJDfaVpsQS1xF%2BOWgBPQ%3D%3D" 600'
2023-09-21 12:18:40 SENT CONTROL [client]: 'AUTH_PENDING,timeout 60' (status=1)
2023-09-21 12:18:40 SENT CONTROL [client]: 'INFO_PRE,WEB_AUTH::https://placeholder.com/oauth2/start?state=cFcJ1GgWlwFjvP%2Br3kYtJ6givkPHRN%2B0bI%2BmGPG7Wjc2hCO3HMYgd%2Bth1q2xXq69INxebEGD67EYF2QOQXYxb4Z4BB8JzXJkJpEqL4EhgZZMwJ%2BQt9w5cccFFPXJDfaVpsQS1xF%2BOWgBPQ%3D%3D' (status=1)
2023-09-21 12:18:40 115.79.139.87:42275 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 253 bit ED25519, signature: ED25519
2023-09-21 12:18:40 115.79.139.87:42275 [client] Peer Connection Initiated with [AF_INET]115.79.139.87:42275
2023-09-21 12:18:40 115.79.139.87:42275 PUSH: Received control message: 'PUSH_REQUEST'
2023-09-21 12:18:41 115.79.139.87:42275 PUSH: Received control message: 'PUSH_REQUEST'
2023-09-21 12:18:44 MANAGEMENT: CMD 'client-auth-nt 0 1'
2023-09-21 12:18:49 115.79.139.87:42275 PUSH: Received control message: 'PUSH_REQUEST'
2023-09-21 12:18:49 client/115.79.139.87:42275 MULTI_sva: pool returned IPv4=10.8.0.2, IPv6=(Not enabled)
2023-09-21 12:18:49 client/115.79.139.87:42275 MULTI: Learn: 10.8.0.2 -> client/115.79.139.87:42275
2023-09-21 12:18:49 client/115.79.139.87:42275 MULTI: primary virtual IP for client/115.79.139.87:42275: 10.8.0.2
2023-09-21 12:18:49 client/115.79.139.87:42275 SENT CONTROL [client]: 'PUSH_REPLY,redirect-gateway def1 bypass-dhcp,dhcp-option DNS 208.67.222.222,dhcp-option DNS 208.67.220.220,route-gateway 10.8.0.1,topology subnet,ping 10,ping-restart 60,ifconfig 10.8.0.2 255.255.255.0,peer-id 0,cipher AES-256-GCM,key-derivation tls-ekm' (status=1)
2023-09-21 12:18:50 client/115.79.139.87:42275 Data Channel: cipher 'AES-256-GCM', peer-id: 0
2023-09-21 12:18:50 client/115.79.139.87:42275 Timers: ping 10, ping-restart 120
2023-09-21 12:18:50 client/115.79.139.87:42275 Protocol options: explicit-exit-notify 1, protocol-flags tls-ekm

at this point, client can connect to the openvpn server.

after 50s, the OpenVPN server said:

2023-09-21 12:19:40 client/115.79.139.87:42275 TLS: soft reset sec=60/60 bytes=135312/-1 pkts=605/0
2023-09-21 12:19:40 client/115.79.139.87:42275 VERIFY OK: depth=1, CN=Easy-RSA CA
2023-09-21 12:19:40 client/115.79.139.87:42275 VERIFY OK: depth=0, CN=client
2023-09-21 12:19:40 client/115.79.139.87:42275 peer info: IV_VER=v3.7.1
2023-09-21 12:19:40 client/115.79.139.87:42275 peer info: IV_PLAT=linux
2023-09-21 12:19:40 client/115.79.139.87:42275 peer info: IV_NCP=2
2023-09-21 12:19:40 client/115.79.139.87:42275 peer info: IV_TCPNL=1
2023-09-21 12:19:40 client/115.79.139.87:42275 peer info: IV_PROTO=30
2023-09-21 12:19:40 client/115.79.139.87:42275 peer info: IV_CIPHERS=AES-128-GCM:AES-192-GCM:AES-256-GCM:CHACHA20-POLY1305
2023-09-21 12:19:40 client/115.79.139.87:42275 peer info: IV_AUTO_SESS=1
2023-09-21 12:19:40 client/115.79.139.87:42275 peer info: IV_GUI_VER=OpenVPN3/Linux/v19_beta
2023-09-21 12:19:40 client/115.79.139.87:42275 peer info: IV_SSO=openurl,webauth
2023-09-21 12:19:40 client/115.79.139.87:42275 TLS: Username/Password authentication deferred for username '' 
2023-09-21 12:19:40 MANAGEMENT: CMD 'client-pending-auth 0 3 "WEB_AUTH::https://placeholder.com/oauth2/start?state=sJI51v%2BtwbGgCnef24%2Ft1Iix06W06Ax%2FLTnQrn3n1qvQtD56P1tOJZgZ5PdLg8VGOlTNSDa2iEiM6ZqQzPo3AOl5KDP%2BcNKT8opWxJGSP3mEdy%2FbbYrdpEkbL0ntjvC663oypptuqSaNIw%3D%3D" 600'
2023-09-21 12:19:40 SENT CONTROL [client]: 'AUTH_PENDING,timeout 60' (status=1)
2023-09-21 12:19:40 SENT CONTROL [client]: 'INFO_PRE,WEB_AUTH::https://placeholder.com/oauth2/start?state=sJI51v%2BtwbGgCnef24%2Ft1Iix06W06Ax%2FLTnQrn3n1qvQtD56P1tOJZgZ5PdLg8VGOlTNSDa2iEiM6ZqQzPo3AOl5KDP%2BcNKT8opWxJGSP3mEdy%2FbbYrdpEkbL0ntjvC663oypptuqSaNIw%3D%3D' (status=1)
2023-09-21 12:19:40 client/115.79.139.87:42275 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 253 bit ED25519, signature: ED25519

the client said:

2023-09-21 19:19:40 [STATUS] Session, URL authentication: https://placeholder.com/oauth2/start?state=sJI51v%2BtwbGgCnef24%2Ft1Iix06W06Ax%2FLTnQrn3n1qv
QtD56P1tOJZgZ5PdLg8VGOlTNSDa2iEiM6ZqQzPo3AOl5KDP%2BcNKT8opWxJGSP3mEdy%2FbbYrdpEkbL0ntjvC663oypptuqSaNIw%3D%3D

1 min later the OpenVPN server said:

2023-09-21 12:20:40 client/115.79.139.87:42275 Delayed exit in 5 seconds
2023-09-21 12:20:40 client/115.79.139.87:42275 SENT CONTROL [UNDEF]: 'AUTH_FAILED' (status=1)
2023-09-21 12:20:40 client/115.79.139.87:42275 SENT CONTROL [client]: 'AUTH_FAILED' (status=1)
2023-09-21 12:20:45 client/115.79.139.87:42275 SIGTERM[soft,delayed-exit] received, client-instance exiting

and the client said:

2023-09-21 19:20:40 [STATUS] Connection, Client authentication failed: Authentication failed

at this time, my client disconnected to my Openvpn server.
Here is the remaining log of your plugin:

{"level":"info","ts":1695298720.7956803,"msg":"new client connection","cid":0,"kid":1,"reason":"CONNECT","common_name":"client","username":""}
{"level":"info","ts":1695298720.7958891,"msg":"start pending auth","cid":0,"kid":1,"reason":"CONNECT","common_name":"client","username":""}
{"level":"info","ts":1695298722.0466757,"msg":"initialize authorization via oauth2","common_name":"client","cid":0,"kid":1}
{"level":"info","ts":1695298724.6437254,"msg":"successful authorization via oauth2","subject":"QA6EBQ8beCWEqR1LvOrMVgJDSDdYEe9KZgL1xZihP-A","preferred_username":"name@my.company","common_name":"client","cid":0,"kid":1}
{"level":"warn","ts":1695298729.826991,"msg":"client established","cid":0,"reason":"ESTABLISHED","common_name":"client","username":""}
{"level":"info","ts":1695298780.2115407,"msg":"new client connection","cid":0,"kid":3,"reason":"REAUTH","common_name":"client","username":""}
{"level":"info","ts":1695298780.2116747,"msg":"start pending auth","cid":0,"kid":3,"reason":"REAUTH","common_name":"client","username":""}
{"level":"warn","ts":1695298845.4822593,"msg":"client disconnected","cid":0,"reason":"DISCONNECT","common_name":"client","username":""}
{"level":"warn","ts":1695298891.9407601,"msg":"invalid state: cFcJ1GgWlwFjvP+r3kYtJ6givkPHRN+0bI+mGPG7Wjc"}
{"level":"warn","ts":1695299415.0266154,"msg":"invalid state: sJI51v+twbGgCnef24/t1Iix06W06Ax/LTnQrn3n1qv"}

@jkroepke
Copy link
Owner

What I notice:

This is one line:

2023-09-21 12:19:40 SENT CONTROL [client]: 'INFO_PRE,WEB_AUTH::https://placeholder.com/oauth2/start?state=sJI51v%2BtwbGgCnef24%2Ft1Iix06W06Ax%2FLTnQrn3n1qvQtD56P1tOJZgZ5PdLg8VGOlTNSDa2iEiM6ZqQzPo3AOl5KDP%2BcNKT8opWxJGSP3mEdy%2FbbYrdpEkbL0ntjvC663oypptuqSaNIw%3D%3D' (status=1)

but on client logs, the URL has a newline.

2023-09-21 19:19:40 [STATUS] Session, URL authentication: https://placeholder.com/oauth2/start?state=sJI51v%2BtwbGgCnef24%2Ft1Iix06W06Ax%2FLTnQrn3n1qv
QtD56P1tOJZgZ5PdLg8VGOlTNSDa2iEiM6ZqQzPo3AOl5KDP%2BcNKT8opWxJGSP3mEdy%2FbbYrdpEkbL0ntjvC663oypptuqSaNIw%3D%3D

then, I see

{"level":"warn","ts":1695299415.0266154,"msg":"invalid state: sJI51v+twbGgCnef24/t1Iix06W06Ax/LTnQrn3n1qv"}

in the logs. It seems like OpenVPN opens a wrong URL on REAUTH. OpenVPN is cutting he URL which results into a invalid state.

I tested the whole workflow with OpenVPN 2 on Windows. Not sure, if OpenVPN 3 has a different behavior here.

@DatCanCode
Copy link
Author

The newline is here because I use MS Teams as a temporary storage for logs; it added new lines. Please remove that newline then everything is the same in the client log, OpenVPN server log, and your plugin log

@jkroepke
Copy link
Owner

I mention this, because the plugin log is

{"level":"warn","ts":1695299415.0266154,"msg":"invalid state: sJI51v+twbGgCnef24/t1Iix06W06Ax/LTnQrn3n1qv"}

report the invalid state exactly on the same part, the newline was introduced.

Somehow, the OpenVPN client opens the URL wrongly.

The plugin return the URL

https://placeholder.com/oauth2/start?state=sJI51v%2BtwbGgCnef24%2Ft1Iix06W06Ax%2FLTnQrn3n1qvQtD56P1tOJZgZ5PdLg8VGOlTNSDa2iEiM6ZqQzPo3AOl5KDP%2BcNKT8opWxJGSP3mEdy%2FbbYrdpEkbL0ntjvC663oypptuqSaNIw%3D%3D

but somehow, the client opens this

https://placeholder.com/oauth2/start?state=sJI51v%2BtwbGgCnef24%2Ft1Iix06W06Ax%2FLTnQrn3n1qv

@DatCanCode
Copy link
Author

I just read about how OpenVPN Management interface works. The above session (#21 (comment)) shows that my client made the first login successfully. When reneg-sec expired, the OpenVPN server sent an REAUTH request to my client, but this time, my client couldn't log in, and then it was disconnected from the OpenVPN server. And I noticed that openvpn3 client didn't open browser (Firefox, in my case) on the second client-pending-auth so it couldn't REAUTH. Maybe this is a bug in openvpn3 client.
So I decided to remove reneg-sec directive. Everything is OK now. I really appreciate your support. Thank you!

@jkroepke
Copy link
Owner

Maybe this is a bug in openvpn3 client.

I can confirm for OpenVPN2 together with MacOS Client Tunnelblick, that the client opens the Browser on REAUTH.

I'll add some notes to the Readme and let me know if there is an issue to link.

@jkroepke
Copy link
Owner

So I decided to remove reneg-sec directive.

Instead this, try auth-gen-token where OpenVPN server issues something like an auth cookie which can be reused on REAUTH to skip the SSO login. However it wont work on OpenVPN2 clients well.

@jkroepke jkroepke closed this as not planned Won't fix, can't repro, duplicate, stale Sep 22, 2023
@jkroepke
Copy link
Owner

@DatCanCode I could verify this behavior with the OpenVPN Connect v3 Client for Mac, too.

See OpenVPN/openvpn3#282

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@jkroepke @DatCanCode