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

Missing required parameter: refresh_token #338

Open
ncgee opened this issue Oct 31, 2024 · 6 comments · May be fixed by #341
Open

Missing required parameter: refresh_token #338

ncgee opened this issue Oct 31, 2024 · 6 comments · May be fixed by #341
Labels
❓ question Further information is requested

Comments

@ncgee
Copy link

ncgee commented Oct 31, 2024 •
edited
Loading

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

  • openvpn-auth-oauth2 Version: 1.22.0
  • OpenVPN Server Version: 2.6.3-1+deb12u2
  • Server OS: Debian 12 Bookworm
  • OpenVPN Client (flavor, OS): Multiple, provided logs based on OpenVPN Connect for Mac OS
@ncgee ncgee added the ❓ question Further information is requested label Oct 31, 2024
@jkroepke
Copy link
Owner

I was a bit confused, why

openvpn-auth-oauth2/internal/oauth2/providers/generic/oidc.go

Line 22 in 8db1c93

return "", errors.New("no refresh token received from provider")

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
Copy link
Author

ncgee commented Oct 31, 2024

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
Copy link
Owner

jkroepke commented Oct 31, 2024 •
edited
Loading

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
Copy link
Author

ncgee commented Nov 1, 2024

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 jkroepke linked a pull request Nov 1, 2024 that will close this issue
Open
3 tasks
@jkroepke
Copy link
Owner

jkroepke commented Nov 1, 2024 •
edited
Loading

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
Copy link
Author

ncgee commented Nov 4, 2024

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

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

Successfully merging a pull request may close this issue.

fix: do not update refresh token on session refresh, if empty jkroepke/openvpn-auth-oauth2
2 participants
@jkroepke @ncgee