search

jkroepke / openvpn-auth-oauth2

openvpn-auth-oauth2 is a plugin/management interface client for OpenVPN server to handle an OIDC based single sign-on (SSO) auth flows
https://github.com/jkroepke/openvpn-auth-oauth2/wiki
MIT License
180 stars 27 forks source link

Missing required parameter: refresh_token #338

Closed ncgee closed 2 weeks ago

ncgee commented 3 weeks ago

Problem Statement

Users are reporting having to reauthenticate more frequently than the configuration would suggest, seemingly randomly as well. The openvpn-auth-oauth2 plugin logs suggest that the problem is a missing refresh token, but it's unclear why this would be.

Current configurations (limited to what seemed most relevant)

openvpn-auth-oauth2 (via /etc/sysconfig/openvpn-auth-oauth2):

CONFIG_OAUTH2_PROVIDER=google
CONFIG_OAUTH2_ISSUER=https://accounts.google.com
CONFIG_OAUTH2_CLIENT_ID=<redacted>.apps.googleusercontent.com
CONFIG_OAUTH2_CLIENT_SECRET=<redacted>
CONFIG_OAUTH2_REFRESH_ENABLED=true
CONFIG_OAUTH2_REFRESH_EXPIRES=24h
CONFIG_OAUTH2_REFRESH_SECRET=<redacted>
CONFIG_OAUTH2_REFRESH_USE__SESSION__ID=true

OpenVPN:

management /run/openvpn/server.sock unix /etc/openvpn/password.txt
management-client-auth
auth-user-pass-optional
auth-gen-token 86400 external-auth
reneg-sec 86400
verify-client-cert optional

The same users that have the missing refresh tokens associated with their sessions will at other times have successfully authenticate with a refresh token, for example the log line for the same user as the other attached log:

okt 31 11:33:06 vpn2-europe-west1-mrwh openvpn-auth-oauth2[101143]: time=2024-10-31T11:33:06.479Z level=INFO msg="successful authenticate via refresh token" ip=<client IP>:54797 cid=18 kid=5 common_name="" reason=REAUTH session_id=ja8wSBiRjmgF4jHL session_state=AuthenticatedEmptyUser

We found some indication that Google doesn't always return a refresh token, could this be the cause? Or are we missing some bit of essential configuration?

openvpn-auth-oauth2 logs

okt 31 12:33:06 vpn2-europe-west1-mrwh openvpn-auth-oauth2[101143]: time=2024-10-31T12:33:06.395Z level=INFO msg="new client reauth" ip=<client IP>:54797 cid=18 kid=6 common_name="" reason=REAUTH session_id=ja8wSBiRjmgF4jHL session_state=AuthenticatedEmptyUser
okt 31 12:33:06 vpn2-europe-west1-mrwh openvpn-auth-oauth2[101143]: time=2024-10-31T12:33:06.395Z level=INFO msg="initiate non-interactive authentication via refresh token" ip=<client IP>:54797 cid=18 kid=6 common_name="" reason=REAUTH session_id=ja8wSBiRjmgF4jHL session_state=AuthenticatedEmptyUser
okt 31 12:33:06 vpn2-europe-west1-mrwh openvpn-auth-oauth2[101143]: time=2024-10-31T12:33:06.432Z level=WARN msg="error from token exchange: error from token exchange: ErrorType=invalid_request Description=Missing required parameter: refresh_token" ip=<client IP>:54797 cid=18 kid=6 common_name="" reason=REAUTH session_id=ja8wSBiRjmgF4jHL session_state=AuthenticatedEmptyUser
okt 31 12:33:06 vpn2-europe-west1-mrwh openvpn-auth-oauth2[101143]: time=2024-10-31T12:33:06.432Z level=INFO msg="start pending auth" ip=<client IP>:54797 cid=18 kid=6 common_name="" reason=REAUTH session_id=ja8wSBiRjmgF4jHL session_state=AuthenticatedEmptyUser
okt 31 12:33:11 vpn2-europe-west1-mrwh openvpn-auth-oauth2[101143]: time=2024-10-31T12:33:11.374Z level=INFO msg="successful authorization via oauth2" ip=<client IP>:54797 cid=18 kid=6 session_id=ja8wSBiRjmgF4jHL common_name="" idtoken.subject=<redacted> idtoken.email=<redacted> idtoken.preferred_username="" user.subject=117292161575721077112 user.preferred_username=""
okt 31 12:33:11 vpn2-europe-west1-mrwh openvpn-auth-oauth2[101143]: time=2024-10-31T12:33:11.375Z level=INFO msg="accept OpenVPN client cid 18, kid 6" ip=<client IP>:54797 cid=18 kid=6 session_id=ja8wSBiRjmgF4jHL common_name="" idtoken.subject=<redacted> idtoken.email=<redacted> idtoken.preferred_username="" user.subject=117292161575721077112 user.preferred_username=""

Environment

jkroepke commented 3 weeks ago

I was a bit confused, why

https://github.com/jkroepke/openvpn-auth-oauth2/blob/8db1c93e460473447b6b4ec1d4a3f0ca7a20c0da/internal/oauth2/providers/generic/oidc.go#L22

did not note before. Bit that changed was introduced in 1.22.0

It would be helpful, it you could update to 1.22.0.

There are some fixed between both. it may resolved your issue.

We found some indication that Google doesn't always return a refresh token, could this be the cause? Or are we missing some bit of essential configuration?

openvpn-auth-oauth2 is aware of that issue. That why openvpn-auth-oauth2 always sets prompt=consent&access_type=offline to each login which should ask the user for approval on each login.

ncgee commented 3 weeks ago

Apologies, I submitted the issue incorrectly, the installed version is in fact 1.22.0. From the server directly:

$ openvpn-auth-oauth2 --version
version: 1.22.0
commit: eeafc7e03283fc8b010c05542a9ecd5629c1981a
date: 2024-08-13T17:13:58Z
go: go1.22.5

That should teach me to type things out instead of copying them.

jkroepke commented 3 weeks ago

Current configurations (limited to what seemed most relevant)

There are more CONFIG_OAUTH2_REFRESH options?

Could it be possible, that the initial re-auth works, but then the second fails?

Maybe there is an regression with #298 where I store the new refresh token after reauthentication, but I didn't check is the refesh token is present.

ncgee commented 3 weeks ago

There are more CONFIG_OAUTH2_REFRESH options?

We have set no other CONFIG_OAUTH2_REFRESH options, if that's your question. The configuration I omitted included CONFIG_HTTP_ and CONFIG_OPENVPN_ settings.

Could it be possible, that the initial re-auth works, but then the second fails?

A pattern does seem to emerge that, after the initial authentication, the first re-auth succeeds but the second one fails. This is the log from a session I started that follows this pattern (timezone GMT+1). I'm using the openvpn3 client from the upstream repository on Ubuntu 22.0.4:

Waiting for session to start ... Done
Attaching to session /net/openvpn/v3/sessions/1363a2c7sb5b6s44ffsa615s3914a8e73401
2024-10-31 14:38:03  Client DEBUG: Network configuration cleanup requested
2024-10-31 14:38:03  [STATUS] Connection, Configuration OK: config_path=/net/openvpn/v3/configuration/5d706d8cxe663x4112x8ca8xb99a3cb16f70
2024-10-31 14:38:03  Client INFO: Starting connection
2024-10-31 14:38:03  Client DEBUG: Using DNS resolver scope: global
2024-10-31 14:38:03  Client DEBUG: [Connect] DCO flag: disabled
2024-10-31 14:38:03  [STATUS] Connection, Client connecting
2024-10-31 14:38:03  Client DEBUG: [Core] OpenVPN core v3.10.1 linux x86_64 64-bit OVPN-DCO
2024-10-31 14:38:03  Client DEBUG: [Core] Frame=512/2112/512 mssfix-ctrl=1250
2024-10-31 14:38:03  Client VERB2: Resolving
2024-10-31 14:38:03  Client DEBUG: [Core] Contacting <server IP>:1194 via UDP
2024-10-31 14:38:03  Client VERB1: Waiting for server response
2024-10-31 14:38:03  Client DEBUG: [Core] Connecting to [<server hostname>]:1194 (<server IP>) via UDP
2024-10-31 14:38:03  Client INFO: Connecting
2024-10-31 14:38:03  [STATUS] Connection, Client connecting
2024-10-31 14:38:03  Client DEBUG: [Core] Tunnel Options:V4,dev-type tun,link-mtu 1541,tun-mtu 1500,proto UDPv4,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client
2024-10-31 14:38:03  Client DEBUG: [Core] Creds: UsernameEmpty/PasswordEmpty
2024-10-31 14:38:03  Client DEBUG: [Core] Sending Peer Info:
                       IV_VER=v3.10.1
                       IV_PLAT=linux
                       IV_NCP=2
                       IV_TCPNL=1
                       IV_PROTO=2974
                       IV_MTU=1600
                       IV_CIPHERS=AES-128-GCM:AES-192-GCM:AES-256-GCM:CHACHA20-POLY1305
                       IV_AUTO_SESS=1
                       IV_GUI_VER=OpenVPN3/Linux/v23
                       IV_SSO=openurl,webauth,crtext
                       IV_BS64DL=1
2024-10-31 14:38:03  Client DEBUG: [Core] VERIFY OK: depth=1, /<issuer>, signature: RSA-SHA512
2024-10-31 14:38:03  Client DEBUG: [Core] VERIFY OK: depth=0, /<subject>, signature: RSA-SHA512
2024-10-31 14:38:03  Client DEBUG: [Core] SSL Handshake: peer certificate: CN=<subject>, 4096 bit RSA, cipher: TLS_AES_256_GCM_SHA384         TLSv1.3 Kx=any      Au=any   Enc=AESGCM(256)            Mac=AEAD
2024-10-31 14:38:03  Client DEBUG: [Core] Session is ACTIVE
2024-10-31 14:38:03  Client VERB2: Retrieving configuration from server
2024-10-31 14:38:03  Client DEBUG: [Core] Sending PUSH_REQUEST to server...
2024-10-31 14:38:03  Client DEBUG: Auth pending request received, timeout: 180
2024-10-31 14:38:03  [STATUS] Session, URL authentication: https://<server hostname>/oauth2/start?state=hDH5vACx2kIrrVrgNlpiMGpaShGtbfWk2vDpG12ABRM1Zx0nw_9n09jRtRR8D8Dw4CQ8VFWwwPmhFrXYb_0gGEes1cS5YX6MFL3vQOtcGnM
2024-10-31 14:38:04  Client DEBUG: [Core] Sending PUSH_REQUEST to server...
...snip, repeated push requests while I authenticate...
2024-10-31 14:39:24  Client DEBUG: [Core] Sending PUSH_REQUEST to server...
2024-10-31 14:39:24  Client DEBUG: [Core] OPTIONS:
                       ...snip, several routes pushed...
                       9 [topology] [net30]
                       10 [ping] [10]
                       11 [ping-restart] [120]
                       12 [auth-token-user] [<redacted>]
                       13 [ifconfig] [<IP>] [<IP>]
                       14 [peer-id] [2]
                       15 [auth-token] ...
                       16 [cipher] [AES-256-GCM]
                       17 [protocol-flags] [cc-exit] [tls-ekm] [dyn-tls-crypt]
                       18 [tun-mtu] [1500]
2024-10-31 14:39:24  Client DEBUG: [Core] Session user: <token sub>
2024-10-31 14:39:24  Client DEBUG: [Core] Session token: [redacted]
2024-10-31 14:39:24  Client DEBUG: [Core] PROTOCOL OPTIONS:
                         cipher: AES-256-GCM
                         digest: none
                         key-derivation: TLS Keying Material Exporter [RFC5705]
                         compress: NONE
                         peer ID: 2
                         control channel: dynamic tls-crypt enabled
2024-10-31 14:39:24  Client VERB2: Session name: '<server hostname>'
2024-10-31 14:39:24  Client DEBUG: [Core] Connected via tun
2024-10-31 14:39:24  Client INFO: Connected: <token sub>@<server hostname>:1194 (<server IP>) via /UDP on tun/<IP>/ gw=[<IP>/] mtu=1500
2024-10-31 14:39:24  [STATUS] Connection, Client connected

2024-10-31 15:38:03  Client DEBUG: [Core] Tunnel Options:V4,dev-type tun,link-mtu 1541,tun-mtu 1500,proto UDPv4,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client
2024-10-31 15:38:03  Client DEBUG: [Core] Creds: Username/SessionID
2024-10-31 15:38:03  Client DEBUG: [Core] Sending Peer Info:
                       IV_VER=v3.10.1
                       IV_PLAT=linux
                       IV_NCP=2
                       IV_TCPNL=1
                       IV_PROTO=2974
                       IV_MTU=1600
                       IV_CIPHERS=AES-128-GCM:AES-192-GCM:AES-256-GCM:CHACHA20-POLY1305
                       IV_AUTO_SESS=1
                       IV_GUI_VER=OpenVPN3/Linux/v23
                       IV_SSO=openurl,webauth,crtext
2024-10-31 15:38:03  Client DEBUG: [Core] VERIFY OK: depth=1, /<issuer>, signature: RSA-SHA512
2024-10-31 15:38:03  Client DEBUG: [Core] VERIFY OK: depth=0, /<subject>, signature: RSA-SHA512
2024-10-31 15:38:03  Client DEBUG: [Core] SSL Handshake: peer certificate: CN=<subject>, 4096 bit RSA, cipher: TLS_AES_256_GCM_SHA384         TLSv1.3 Kx=any      Au=any   Enc=AESGCM(256)            Mac=AEAD
2024-10-31 15:38:19  Client DEBUG: [Core] Session token: [redacted]

2024-10-31 16:38:03  Client DEBUG: [Core] Tunnel Options:V4,dev-type tun,link-mtu 1541,tun-mtu 1500,proto UDPv4,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client
2024-10-31 16:38:03  Client DEBUG: [Core] Creds: Username/SessionID
2024-10-31 16:38:03  Client DEBUG: [Core] Sending Peer Info:
                       IV_VER=v3.10.1
                       IV_PLAT=linux
                       IV_NCP=2
                       IV_TCPNL=1
                       IV_PROTO=2974
                       IV_MTU=1600
                       IV_CIPHERS=AES-128-GCM:AES-192-GCM:AES-256-GCM:CHACHA20-POLY1305
                       IV_AUTO_SESS=1
                       IV_GUI_VER=OpenVPN3/Linux/v23
                       IV_SSO=openurl,webauth,crtext
2024-10-31 16:38:03  Client DEBUG: [Core] VERIFY OK: depth=1, /<issuer>, signature: RSA-SHA512
2024-10-31 16:38:03  Client DEBUG: [Core] VERIFY OK: depth=0, /<subject>, signature: RSA-SHA512
2024-10-31 16:38:03  Client DEBUG: [Core] SSL Handshake: peer certificate: CN=<subject>, 4096 bit RSA, cipher: TLS_AES_256_GCM_SHA384         TLSv1.3 Kx=any      Au=any   Enc=AESGCM(256)            Mac=AEAD
2024-10-31 16:38:03  [STATUS] Session, URL authentication: https://<server hostname>/oauth2/start?state=W4xLfR0tXM6yxtYOCoSnEvUjZPdKG65yRKpZ-SEupEhZVPAwV5_6rCITOLftCFR7vImWSmKlUdBtGsxc1qePTThMoma2mLzlmbMGREyoVG0
2024-10-31 16:41:04  Client DEBUG: [Core] need_user_interaction: 1, pw_needed: 0, pw_defined: 0, reconnect: 0
2024-10-31 16:41:04  Client DEBUG: [Core] SESSION_EXPIRED
2024-10-31 16:41:04  Client **!! FATAL !!**: [SESSION_EXPIRED] 
2024-10-31 16:41:04  [STATUS] Connection, Client disconnected
2024-10-31 16:41:04  Client INFO: Disconnected
Session closed

The failed re-auth aligns with this log message for the openvpn-auth-oauth2 service (timezone UTC):

okt 31 15:38:03 vpn2-europe-west1-mrwh openvpn-auth-oauth2[101143]: time=2024-10-31T15:38:03.208Z level=WARN msg="error from token exchange: error from token exchange: ErrorType=invalid_request Description=Missing required parameter: refresh_token" ip=<client IP>:47837 cid=35 kid=4 common_name="" reason=REAUTH session_id=G/bHhKokW5T7nS98 session_state=AuthenticatedEmptyUser

At this point it failed silently, I did not get (or notice) a new browser window asking me to log in again.

jkroepke commented 3 weeks ago

Hi @ncgee

are you able to test a snapshot version from #341?

https://github.com/jkroepke/openvpn-auth-oauth2/actions/runs/11630986235/artifacts/2133355072

NEW: https://github.com/jkroepke/openvpn-auth-oauth2/actions/runs/11644456646/artifacts/2136622418

ncgee commented 2 weeks ago

Thanks for the quick responses! We have testing of your updated build planned for tomorrow, I'll let you know our findings.

ncgee commented 2 weeks ago

Hi @jkroepke ,

We've installed the new version and users report improvement, however it's logging the following, a lot:

nov 05 15:46:12 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:12.121Z level=INFO msg="client established" ip=<client IP>:62421 cid=333 kid=0 common_name="" reason=ESTABLISHED session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser vpn_ip=""
nov 05 15:46:12 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:12.780Z level=INFO msg="client disconnected" ip=<client IP>:64900 cid=252 kid=0 common_name="" reason=DISCONNECT session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser
nov 05 15:46:14 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:14.174Z level=INFO msg="new client authentication" ip=<client IP>:59895 cid=334 kid=1 common_name="" reason=CONNECT session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser
nov 05 15:46:14 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:14.174Z level=INFO msg="initiate non-interactive authentication via refresh token" ip=<client IP>:59895 cid=334 kid=1 common_name="" reason=CONNECT session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser
nov 05 15:46:14 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:14.240Z level=INFO msg="successful authenticate via refresh token" ip=<client IP>:59895 cid=334 kid=1 common_name="" reason=CONNECT session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser
nov 05 15:46:14 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:14.240Z level=INFO msg="accept OpenVPN client cid 334, kid 1" ip=<client IP>:59895 cid=334 kid=1 common_name="" reason=CONNECT session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser
nov 05 15:46:15 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:15.185Z level=INFO msg="client established" ip=<client IP>:59895 cid=334 kid=0 common_name="" reason=ESTABLISHED session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser vpn_ip=""
nov 05 15:46:15 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:15.718Z level=INFO msg="client disconnected" ip=<client IP>:62459 cid=253 kid=0 common_name="" reason=DISCONNECT session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser
nov 05 15:46:17 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:17.239Z level=INFO msg="new client authentication" ip=<client IP>:59950 cid=335 kid=1 common_name="" reason=CONNECT session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser
nov 05 15:46:17 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:17.239Z level=INFO msg="initiate non-interactive authentication via refresh token" ip=<client IP>:59950 cid=335 kid=1 common_name="" reason=CONNECT session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser
nov 05 15:46:17 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:17.317Z level=INFO msg="successful authenticate via refresh token" ip=<client IP>:59950 cid=335 kid=1 common_name="" reason=CONNECT session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser
nov 05 15:46:17 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:17.317Z level=INFO msg="accept OpenVPN client cid 335, kid 1" ip=<client IP>:59950 cid=335 kid=1 common_name="" reason=CONNECT session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser
nov 05 15:46:18 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:18.171Z level=INFO msg="client disconnected" ip=<client IP>:60681 cid=254 kid=0 common_name="" reason=DISCONNECT session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser
nov 05 15:46:18 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:18.254Z level=INFO msg="client established" ip=<client IP>:59950 cid=335 kid=0 common_name="" reason=ESTABLISHED session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser vpn_ip=10.253.2.30
nov 05 15:46:20 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:20.317Z level=INFO msg="new client authentication" ip=<client IP>:55519 cid=297 kid=2 common_name="" reason=REAUTH session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser
nov 05 15:46:20 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:20.317Z level=INFO msg="initiate non-interactive authentication via refresh token" ip=<client IP>:55519 cid=297 kid=2 common_name="" reason=REAUTH session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser
nov 05 15:46:20 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:20.383Z level=INFO msg="successful authenticate via refresh token" ip=<client IP>:55519 cid=297 kid=2 common_name="" reason=REAUTH session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser
nov 05 15:46:20 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:20.384Z level=INFO msg="accept OpenVPN client cid 297, kid 2" ip=<client IP>:55519 cid=297 kid=2 common_name="" reason=REAUTH session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser
nov 05 15:46:21 vpn2-europe-west1-mrwh openvpn-auth-oauth2[686498]: time=2024-11-05T15:46:21.517Z level=INFO msg="client disconnected" ip=<client IP>:49989 cid=255 kid=0 common_name="" reason=DISCONNECT session_id=eM49CXmoAsk2/n9F session_state=AuthenticatedEmptyUser

The OpenVPN logs seem to confirm that the user is constantly disconnected and reconnected, with a few message like this in between:

read UDPv4 [ECONNREFUSED]: Connection refused (fd=8,code=111)

And reports this every few seconds:

nov 05 16:02:36 vpn2-europe-west1-mrwh ovpn-<redacted>[686481]: <client IP>:57567 [UNDEF] Inactivity timeout (--ping-restart), restarting
nov 05 16:02:36 vpn2-europe-west1-mrwh ovpn-<redacted>[686481]: <client IP>:57567 SIGUSR1[soft,ping-restart] received, client-instance restarting

No other configuration was changed. The user also had this in their client side log, which I did not see before. Their client configuration wasn't changed either:

[Nov 5, 2024, 16:57:33] Client exception in transport_recv: ERR_INVALID_OPTION_VAL: option_error: option 'auth-token-user' must have at least 1 arguments
jkroepke commented 2 weeks ago

For unknown reasons, openvpn-auth-oauth2 tried to set auth-token-user even if no username is given.

The error may exists before, but covered because non-interactive authentication via refresh token not worked and fall back to interactive auth. It seems like the errors appears only on non-interactive authentication via refresh token code path

ncgee commented 2 weeks ago

I may have been mistaken about the exact circumstances under which the disconnect loop occurs. I'll investigate this again tomorrow and post a reply with any new information I find.

On Tue, Nov 5, 2024, 5:51 PM Jan-Otto Kröpke @.***> wrote:

For unknown reasons, openvpn-auth-oauth2 tried to set auth-token-user even if no username is given.

The error may exists before, but covered because non-interactive authentication via refresh token not worked and fall back to interactive auth. It seems like the errors appears only on non-interactive authentication via refresh token code path

— Reply to this email directly, view it on GitHub https://github.com/jkroepke/openvpn-auth-oauth2/issues/338#issuecomment-2457692138, or unsubscribe https://github.com/notifications/unsubscribe-auth/AGYR2XNKQII54GRPID464JTZ7DZSZAVCNFSM6AAAAABQ6PO7OGVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDINJXGY4TEMJTHA . You are receiving this because you were mentioned.Message ID: @.***>

jkroepke commented 2 weeks ago

[Nov 5, 2024, 16:57:33] Client exception in transport_recv: ERR_INVALID_OPTION_VAL: option_error: option 'auth-token-user' must have at least 1 arguments

That could be a valid reason for that disconnect. There is an issue, if no common name is given and toke-user as well as refresh is enabled.

Before investigate, try out the lastest snapshot build from #341 - In any case, the logged exception is valid and should be prevent. https://github.com/jkroepke/openvpn-auth-oauth2/actions/runs/11690284867/artifacts/2148348958

ncgee commented 2 weeks ago

It appears the disconnect loop was related to the client device going to sleep and waking back up, and the client application not properly disconnecting and reconnecting itself. We've been testing with your latest build since yesterday and it looks like the results are positive, even after device sleep.

The only strange (to me) thing I currently see recurring in the logs is the following, but this may be intentional:

nov 07 09:20:56 vpn2-europe-west1-mrwh openvpn-auth-oauth2[776859]: time=2024-11-07T09:20:56.998Z level=WARN msg="oauth2.refresh is enabled, but no refresh token received from provider"

This seems to have no negative effect on the user sessions however.

jkroepke commented 2 weeks ago

The only strange (to me) thing I currently see recurring in the logs is the following, but this may be intentional:

Could you verify that this issue appears only, if the device wake up?

There are already so many cases and it maybe be intentional only on very few specific scenarion.

Wake up from device + oauth2.refresh.use-session-id + google provider.

ncgee commented 2 weeks ago

Given the frequency and recurring nature for some sessions it seems unlikely that this is related to device wake up, though it may be related to client connection loss:

nov 07 09:02:58 vpn2-europe-west1-mrwh openvpn-auth-oauth2[776859]: time=2024-11-07T09:02:58.349Z level=INFO msg="successful authenticate via refresh token" ip=<client IP 1>:58858 cid=39 kid=3 common_name="" reason=REAUTH session_id=0+ZrSwPeVD/IXn+D session_state=AuthenticatedEmptyUser
nov 07 09:02:58 vpn2-europe-west1-mrwh openvpn-auth-oauth2[776859]: time=2024-11-07T09:02:58.350Z level=WARN msg="oauth2.refresh is enabled, but no refresh token received from provider"
--
nov 07 09:13:17 vpn2-europe-west1-mrwh openvpn-auth-oauth2[776859]: time=2024-11-07T09:13:17.003Z level=INFO msg="successful authenticate via refresh token" ip=<client IP 1>:59650 cid=45 kid=1 common_name="" reason=CONNECT session_id=0+ZrSwPeVD/IXn+D session_state=AuthenticatedEmptyUser
nov 07 09:13:17 vpn2-europe-west1-mrwh openvpn-auth-oauth2[776859]: time=2024-11-07T09:13:17.003Z level=WARN msg="oauth2.refresh is enabled, but no refresh token received from provider"
--
nov 07 09:20:02 vpn2-europe-west1-mrwh openvpn-auth-oauth2[776859]: time=2024-11-07T09:20:02.102Z level=INFO msg="successful authenticate via refresh token" ip=<client IP 2>:55173 cid=46 kid=1 common_name="" reason=CONNECT session_id=SzpZd3U8HnGTQjeu session_state=AuthenticatedEmptyUser
nov 07 09:20:02 vpn2-europe-west1-mrwh openvpn-auth-oauth2[776859]: time=2024-11-07T09:20:02.103Z level=WARN msg="oauth2.refresh is enabled, but no refresh token received from provider"
--
nov 07 09:20:56 vpn2-europe-west1-mrwh openvpn-auth-oauth2[776859]: time=2024-11-07T09:20:56.998Z level=INFO msg="successful authenticate via refresh token" ip=<client IP 2>:52096 cid=47 kid=1 common_name="" reason=CONNECT session_id=SzpZd3U8HnGTQjeu session_state=AuthenticatedEmptyUser
nov 07 09:20:56 vpn2-europe-west1-mrwh openvpn-auth-oauth2[776859]: time=2024-11-07T09:20:56.998Z level=WARN msg="oauth2.refresh is enabled, but no refresh token received from provider"
--
nov 07 09:45:33 vpn2-europe-west1-mrwh openvpn-auth-oauth2[776859]: time=2024-11-07T09:45:33.225Z level=INFO msg="successful authenticate via refresh token" ip=<client IP 3>:56531 cid=33 kid=14 common_name="" reason=REAUTH session_id=a2VuV2QZZzxfP2Qk session_state=AuthenticatedEmptyUser
nov 07 09:45:33 vpn2-europe-west1-mrwh openvpn-auth-oauth2[776859]: time=2024-11-07T09:45:33.226Z level=WARN msg="oauth2.refresh is enabled, but no refresh token received from provider"
--
nov 07 10:20:56 vpn2-europe-west1-mrwh openvpn-auth-oauth2[776859]: time=2024-11-07T10:20:56.880Z level=INFO msg="successful authenticate via refresh token" ip=<client IP 2>:52096 cid=47 kid=3 common_name="" reason=REAUTH session_id=SzpZd3U8HnGTQjeu session_state=AuthenticatedEmptyUser
nov 07 10:20:56 vpn2-europe-west1-mrwh openvpn-auth-oauth2[776859]: time=2024-11-07T10:20:56.880Z level=WARN msg="oauth2.refresh is enabled, but no refresh token received from provider"
--
nov 07 11:14:03 vpn2-europe-west1-mrwh openvpn-auth-oauth2[776859]: time=2024-11-07T11:14:03.340Z level=INFO msg="successful authenticate via refresh token" ip=<client IP 1>:56542 cid=48 kid=3 common_name="" reason=REAUTH session_id=+f/p0bvEh3qHrnYj session_state=AuthenticatedEmptyUser
nov 07 11:14:03 vpn2-europe-west1-mrwh openvpn-auth-oauth2[776859]: time=2024-11-07T11:14:03.340Z level=WARN msg="oauth2.refresh is enabled, but no refresh token received from provider"
--
nov 07 11:20:56 vpn2-europe-west1-mrwh openvpn-auth-oauth2[776859]: time=2024-11-07T11:20:56.877Z level=INFO msg="successful authenticate via refresh token" ip=<client IP 2>:52096 cid=47 kid=4 common_name="" reason=REAUTH session_id=SzpZd3U8HnGTQjeu session_state=AuthenticatedEmptyUser
nov 07 11:20:56 vpn2-europe-west1-mrwh openvpn-auth-oauth2[776859]: time=2024-11-07T11:20:56.877Z level=WARN msg="oauth2.refresh is enabled, but no refresh token received from provider"
jkroepke commented 2 weeks ago

Ah, okay it appears also on normal reason=REAUTH (which is not connection lost, it's the TLS Session Renegotiation Interval which is by default 1 hour).

But in any case, the warning should be logged only, if session_state is Initial. I will fix that soon.

ncgee commented 2 weeks ago

In case it's relevant, our reneg-sec value is much larger than 1 hour currently as part of earlier attempts to work around issues with the setup, prior to upgrading to the test build. If it turns out to be as stable as it currently seems with the fixes in your test build, would it be safe to reduce that again do you think?

jkroepke commented 2 weeks ago

1 hour is a good default value.

In integration tests, I'm using 1 minute interval.

https://github.com/jkroepke/openvpn-auth-oauth2/blob/ea55dbf22e4abc4ee6ce89c576ce737773fb7821/tests/docker-compose.yaml#L88

Anything below 1 minute does not work.

I highly recommend to set reneg-sec 0 on client and define the value only on server side. (Which is recommend by man page)

ncgee commented 1 week ago

Hi @jkroepke , I'm not sure if I should reopen this issue or create a new one, but it seems like the problem isn't quite fixed yet.

Yesterday we replaced the snapshot build from #341 with v1.22.3 and set reneg-sec 3600 in the OpenVPN configuration. Today users are reporting frequent reauthorizations being required, it looks like this happens every second reauth again. The logs contain messages like the following:

nov 12 14:08:48 vpn2-europe-west1-mrwh openvpn-auth-oauth2[1302759]: time=2024-11-12T14:08:48.420Z level=WARN msg="stored refresh token is empty. This should not happen. Please report this issue." ip=<client IP>:56354 cid=34 kid=4 common_name="" reason=REAUTH session_id=2T0CbB8GJRdKDiRc session_state=AuthenticatedEmptyUser

Almost exactly one hour before this the auth server was able to use the refresh token:

nov 12 13:09:13 vpn2-europe-west1-mrwh openvpn-auth-oauth2[1302759]: time=2024-11-12T13:09:13.634Z level=INFO msg="successful authenticate via refresh token" ip=<client IP>:56354 cid=34 kid=3 common_name="" reason=REAUTH session_id=2T0CbB8GJRdKDiRc session_state=AuthenticatedEmptyUser

In case it helps:

openvpn-auth-oauth2 --version
version: 1.22.3
commit: 07998c30c9d99af7b75fdc8ae6a64ba9f8f4a301
date: 2024-11-08T19:00:30Z
go: go1.23.2
jkroepke commented 1 week ago

It makes me sad, however I'm happy for adding logging cases than should never happens. I added a test case for this scenario, and it didn't as well. :/

I fixed the test case and add a fix on the logic it self. That should fixed your case as well.

Sorry for that.

jkroepke commented 1 week ago

Should be fixed in https://github.com/jkroepke/openvpn-auth-oauth2/releases/tag/v1.22.4

ncgee commented 1 week ago

So far it looks like the new version fixed the problem, if not I'll reply again. Thanks for your work and quick responses!