search

advplyr / audiobookshelf

Self-hosted audiobook and podcast server
https://audiobookshelf.org
GNU General Public License v3.0
6.03k stars 426 forks source link

[Bug]: Synology SSO "Error in Callback" #2440

Closed Drakon74 closed 4 months ago

Drakon74 commented 7 months ago

Describe the issue

Configured OICD with a Synology SSO Server Endpoint.

Auto discovering the URLs worked just fine.

When trying to log-in, back on the login page, i get an "Error in callback" message. The log of the container just says:

[2023-12-23 00:13:06.976] ERROR: [Auth] Error in openid callback - OPError: server_error (Auth.js:426)

I'm using the "edge" image, with the "latest" image, i get a white page with just "internal server error" and this in the log:

at async /node_modules/openid-client/lib/passport_strategy.js:166:22
at async Client.callback (/node_modules/openid-client/lib/client.js:493:24)
at processTicksAndRejections (node:internal/process/task_queues:96:5)
at runMicrotasks (<anonymous>)
at Client.grant (/node_modules/openid-client/lib/client.js:1354:22)
at processResponse (/node_modules/openid-client/lib/helpers/process_response.js:38:13)
OPError: server_error

I checked the callback URL, but it is as it should be according to the documentation:

https://[Domain]:5001/auth/openid/callback

The SSO Server Log just says this though:

User [USER] signed in to application [Audiobookshelf] via SSO.

I also already tried to restart the container.

Steps to reproduce the issue

  1. Configure via webinterface
  2. try to login
  3. Error

Audiobookshelf version

2.6.0

How are you running audiobookshelf?

Docker

nichwall commented 7 months ago

Is this the same issue? https://github.com/advplyr/audiobookshelf/issues/2412

Most recent commit is https://github.com/advplyr/audiobookshelf/commit/2738402aacbe43f21061667b417da35ceb8d5c10, with the only commits for the last few days being related to adding the Year In Review (assuming the edge tag was pulled within the past day or two) for future reference

Drakon74 commented 7 months ago

It sounds like the same issue, however Synology SSO doesn't give me enough "deepthness" so i can check if userinfo_signing_algorithm is on RS265. However the same SSO works just fine with a "gitea" instance.

Also "edge" was pulled basically yesterday.

Drakon74 commented 7 months ago

So i did some further digging and testing.

I tried this test here: https://openidconnect.net

And it works fine stating that the token is valid at the end, at the end it also states that the token is signed with RS256. Which, from my understanding, is correct. As the problem in the other issue was that the configuration was wrong in the sense that also the userinfo was signed with RS256.

So i am not entirely sure what i could further do right now...

Drakon74 commented 7 months ago

So, i found the reason for the issue... for some reason on the app secret the last character was missing...

I managed to SSH onto the Synology and find the SSO Servers logfile under /var/packages/SSOServer/target/etc/ssoserver.log

Where it stated this:

Dec 23 18:10:01 SSOOauth.cpp:line 722 OIDC User[USER] login from AppName[Audiobookshelf]
Dec 23 18:10:01 SSOAccessToken.cpp:line 283 Wrong client_secret: [SECRET]

So i checked the secret and indeed the last character was missing. No clue how.

However... it is still not working.

i fixed the secret and restarted the container, now i simply get "Unauthorized". The logs on both sides say nothing now. SSO Server Logs just state the successful login now and the audiobookshelf logs mention.. nothing. Only that a socket connected, but nothing more.

Bildschirmfoto 2023-12-23 um 18 17 43

The user trying to login already exists on Audiobookstation (same username), could this be an issue? I tried to match the username and e-mail, but it's also not working. Username and e-mail are exactly the same on both sides. Even down to upper / lower case. Am i still missing something?

Drakon74 commented 7 months ago

I also updated to 2.7.0 (latest) now and the log at least does mention something now:

[2023-12-24 14:27:54.328] ERROR: [Auth] No data in openid callback - Unauthorized (Auth.js:426)

Which sounds like the openid response is empty? But again, it works with gitea and the openid test above. The latter even showing all user information like username, e-mail etc. The SSO Server on the synology is not reporting anything new. Just successful login.

Also i tripple checked everything now, all URLs are correct (i even let it auto-populate again, was no issue), ID and secret are correct, username and e-mail are exactly the same on both sides, callback URL is correct (otherwise the SSO Server complains)...

I have no idea what else i could check or do... i probably miss something still... do i need to put something specific in the reverse proxy settings? Currently there is only the websocket upgrade, as well as the standard like "Host", "X-Forwarded-Proto" and "X-Forwarded-For".

If anyone has an idea, i am open for anything.

Sapd commented 7 months ago

Which sounds like the openid response is empty?

Yes, but it is empty because the server (synology) sent back a "Forbidden / 403".

Actually a user in the Discord had the same issue as you (he eventually switched to Authentik). So there must be something special with Synology which we don't know yet about.

Do you have maybe a way to configure the reverse proxy in front of synology to output you detailed http logs?

Drakon74 commented 7 months ago

By default it seems only the nginx error log is enabled.

The error log does mention a couple "forbidden", but these are 3 days ago, probably when i was testing and messing around, also they mainly mention the socket connection.

I was able to enable the access log of the nginx however. I censored the log a little, to get the domainname, IPs (public and local) and the client_ID out. But on first glance i cannot see the issue. The snipped is from when i tried to login, so there might be a little bit of other stuff in between as multiple things run on the Synology:

[Client_IP] - - [25/Dec/2023:14:16:42 +0100] "GET /webman/sso/SSOOauth.cgi?client_id=[Client_ID]&scope=openid%20profile%20email&response_type=code&redirect_uri=https%3A%2F%2F[DOMAIN]%3A5001%2Fauth%2Fopenid%2Fcallback&state=ZNbZrLK0aDQ6zexJKnSraRjMgnxqe9weWK6449Gy9zE&code_challenge=58nUGjnwkanBvo61VVW9ov-cDGbnhKFW7ViUWG4E1bI&code_challenge_method=S256 HTTP/1.1" 302 5 "https://[DOMAIN]:5001/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "[Client_IP]"
[Client_IP] - - [25/Dec/2023:14:16:42 +0100] "GET /webman/sso/SSOOauth.cgi?client_id=[Client_ID]&scope=openid%20profile%20email&response_type=code&redirect_uri=https%3A%2F%2F[DOMAIN]%3A5001%2Fauth%2Fopenid%2Fcallback&state=ZNbZrLK0aDQ6zexJKnSraRjMgnxqe9weWK6449Gy9zE&code_challenge=58nUGjnwkanBvo61VVW9ov-cDGbnhKFW7ViUWG4E1bI&code_challenge_method=S256 HTTP/2.0" 302 0 "https://[DOMAIN]:5001/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-"
[Local_IP] - - [25/Dec/2023:14:16:42 +0100] "POST /webapi/entry.cgi HTTP/2.0" 200 86 "https://[Synology_local_IP]:5001/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-"
[Local_IP] - - [25/Dec/2023:14:16:42 +0100] "POST /webapi/entry.cgi HTTP/2.0" 200 86 "https://[Synology_local_IP]:5001/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-"
[Client_IP] - - [25/Dec/2023:14:16:42 +0100] "GET /sw.js HTTP/2.0" 200 3545 "" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-"
[Local_IP] - - [25/Dec/2023:14:16:42 +0100] "POST /webapi/entry.cgi HTTP/2.0" 200 80 "https://[Synology_local_IP]:5001/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-"
[Local_IP] - [Client_ID] [25/Dec/2023:14:16:43 +0100] "POST /webman/sso/SSOAccessToken.cgi HTTP/1.1" 200 858 "-" "openid-client/5.6.1 (https://github.com/panva/node-openid-client)" "[Local_IP]"
[Local_IP] - [Client_ID] [25/Dec/2023:14:16:43 +0100] "POST /webman/sso/SSOAccessToken.cgi HTTP/1.1" 200 858 "-" "openid-client/5.6.1 (https://github.com/panva/node-openid-client)" "-"
[Local_IP] - - [25/Dec/2023:14:16:43 +0100] "GET /webman/sso/openid-jwks.json HTTP/1.1" 200 545 "-" "openid-client/5.6.1 (https://github.com/panva/node-openid-client)" "[Local_IP]"
[Local_IP] - - [25/Dec/2023:14:16:43 +0100] "GET /webman/sso/openid-jwks.json HTTP/1.1" 200 545 "-" "openid-client/5.6.1 (https://github.com/panva/node-openid-client)" "-"
[Local_IP] - - [25/Dec/2023:14:16:43 +0100] "GET /webman/sso/SSOUserInfo.cgi HTTP/1.1" 200 99 "-" "openid-client/5.6.1 (https://github.com/panva/node-openid-client)" "[Local_IP]"
[Local_IP] - - [25/Dec/2023:14:16:43 +0100] "GET /webman/sso/SSOUserInfo.cgi HTTP/1.1" 200 99 "-" "openid-client/5.6.1 (https://github.com/panva/node-openid-client)" "-"
[Client_IP] - - [25/Dec/2023:14:16:43 +0100] "GET /auth/openid/callback?code=fqqgYaeZPLnkMOivnFE1sCHa3O2BSgm8&state=ZNbZrLK0aDQ6zexJKnSraRjMgnxqe9weWK6449Gy9zE HTTP/2.0" 302 128 "https://[DOMAIN]:5001/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-"
[Client_IP] - - [25/Dec/2023:14:16:43 +0100] "GET /login?error=Unauthorized&autoLaunch=0 HTTP/2.0" 301 249 "https://[DOMAIN]:5001/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-"
[Client_IP] - - [25/Dec/2023:14:16:43 +0100] "GET /login/?error=Unauthorized&autoLaunch=0 HTTP/2.0" 200 3738 "https://[DOMAIN]:5001/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-"
[Client_IP] - - [25/Dec/2023:14:16:43 +0100] "GET /_nuxt/manifest.31bfdee8.json HTTP/2.0" 200 372 "https://[DOMAIN]:5001/login/?error=Unauthorized&autoLaunch=0" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-"

From what i am getting, it seems a proper code and state is returned via the callback URL?

[Client_IP] - - [25/Dec/2023:14:16:43 +0100] "GET /auth/openid/callback?code=fqqgYaeZPLnkMOivnFE1sCHa3O2BSgm8&state=ZNbZrLK0aDQ6zexJKnSraRjMgnxqe9weWK6449Gy9zE HTTP/2.0" 302 128 "https://[DOMAIN]:5001/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-"

Drakon74 commented 7 months ago

So i updated to Version 2.7.1 now and tried it again.

This time i get these errors:

Audiobookshelf:

[2024-01-04 22:24:34.607] ERROR: [Auth] Error in openid callback - OPError: server_error (Auth.js:426)

Synology SSO Server however gives a new error message:

Jan 4 22:24:34 SSOAccessToken.cpp:line 337 code challenge not passed: method=[S256] challenge=[jXYMFADBPHMOnKkpVwAlWfAMaiReiIMZU0R4cs7G7eg] verifier=[f848pWnCkngcm-4pv-AQuaY0FVMD_67v8oG-8ZltMRU]

I checked again, but all links, client ID and secret are the same as before and the same as in the SSO Servers settings.

Any idea what this could be? Would it make sense to perhaps question the Synology Support as well?

Sapd commented 7 months ago

Jan 4 22:24:34 SSOAccessToken.cpp:line 337 code challenge not passed: method=[S256] challenge=[jXYMFADBPHMOnKkpVwAlWfAMaiReiIMZU0R4cs7G7eg] verifier=[f848pWnCkngcm-4pv-AQuaY0FVMD_67v8oG-8ZltMRU]

Not sure if this error message means, that the PKCE challenge failed or the "code" sent is incorrect. When inserting here the verifier: https://tonyxu-io.github.io/pkce-generator/ then it returns exactly the challenge from the log message. Which means that PKCE should work.

The library we are using enforces PKCE.

To check if PKCE really works on synology, can you try this in a shell where you have CURL installed? Before, add https://oidcdebugger.com/debug as allowed redirect URL in synology.

# Keep this as is, I generated them before
export CODE_VERIFIER=2dY-FAfh6hXlyAuzZ3mcEuirTlbE_IpWIoW9lfvDCnI
export CODE_CHALLENGE=_dV2zmStSxk0RtjMKeU575a5CSC4CfVton3tdn_O3QE

# REPLACE this url
export AUTHORIZATION_ENDPOINT="YOURAUTHORIZATIONURL"
# REPLACE this client id
export CLIENT_ID="YOURCLIENTID"

#keep as is
export REDIRECT_URI="https://oidcdebugger.com/debug"
export SCOPE="openid email profile"

# Open a browser window for user login
# if the open command does not work on your OS, simply replace it with echo or so and copy paste the resulting URL in your browser
open "$AUTHORIZATION_ENDPOINT?client_id=$CLIENT_ID&response_type=code&scope=$SCOPE&redirect_uri=$REDIRECT_URI&code_challenge_method=S256&code_challenge=$CODE_CHALLENGE"

The website will show you a code then. Insert this code in the following variable and run this. Note that you only have a short time for this after you have the code (less than 1-2 minutes)

# Replace AUTHORIZATION_CODE with the code you received
export AUTHORIZATION_CODE="THECODEFROMTHEWEBSITE"
# The secret of your client as configured in synology
export CLIENT_SECRET="REPLACECLIENTSECRET"
# Insert here the token endpoint
export TOKEN_ENDPOINT="REPLACEHERETOKENENDPOINT"

# Exchange the authorization code for an access token
curl -X POST $TOKEN_ENDPOINT \
-d "grant_type=authorization_code" \
-d "client_id=$CLIENT_ID" \
-d "client_secret=$CLIENT_SECRET" \
-d "code_verifier=$CODE_VERIFIER" \
-d "code=$AUTHORIZATION_CODE" \
-d "redirect_uri=$REDIRECT_URI"

On success, it should show you a access_token in a JSON

Drakon74 commented 7 months ago

Yep, seems to work:

{
   "access_token" : "...",
   "expires_in" : 180,
   "id_token" : "...",
   "token_type" : "Bearer"
}

Tried it on an external Linux system i have at a hoster.

Used the same client id, secret and links as in the Audiobookshelf config.

(As i am unsure how sensitive the tokens are, i cut them down a little and replaced the rest of them with "..." Hope thats fine, if you need the full tokens, just say a word)

Sapd commented 7 months ago

Thats weird. So the issue must somewhere else. Maybe node-openid-client does something weird which specifically bothers synology. Maybe also some URL is weird.

Tbh I think you must configure full logging in front of the synology reverse proxy (headers and full body; and if you dont have a reverse proxy in front of it, you probably must configure one). If you dont have a reverse proxy in front mitmproxy https://docs.mitmproxy.org/stable/ might be easier. So we can see how the requests from ABS look like and what the response is

(As i am unsure how sensitive the tokens are, i cut them down a little and replaced the rest of them with "..." Hope thats fine, if you need the full tokens, just say a word)

Generally you should remove all tokens, they are not needed for understanding the logs.

Drakon74 commented 7 months ago

headers and full body

How would you do that in NGINX? I have the built in NGINX setup for both the usually DSM (includes the SSO Server as well) and Audiobookshelf.

My current Log format is like this (i added the request body as well here now):

log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '
        '$status $body_bytes_sent "$http_referer" '
        '"$http_user_agent" "$http_x_forwarded_for" - $request_body';

I separated the logs this time, to make things a bit clearer and it seems with the request body you get more info? Not sure if it is enough though:

Audiobookshelf:

[Client IP] - - [06/Jan/2024:10:27:54 +0100] "GET /status HTTP/2.0" 200 208 "https://[DOMAIN]:5001/login" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-" - -
[Client IP] - - [06/Jan/2024:10:27:55 +0100] "GET /sw.js HTTP/2.0" 200 3545 "" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-" - -
[Client IP] - - [06/Jan/2024:10:27:55 +0100] "GET /auth/openid?callback=https://[DOMAIN]:5001/login HTTP/2.0" 302 856 "https://[DOMAIN]:5001/login" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-" - -
[Client IP] - - [06/Jan/2024:10:27:55 +0100] "GET /auth/openid/callback?code=[CODE]&state=[STATE] HTTP/2.0" 302 128 "https://[DOMAIN]:5001/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-" - -
[Client IP] - - [06/Jan/2024:10:27:55 +0100] "GET /login?error=Unauthorized&autoLaunch=0 HTTP/2.0" 301 249 "https://[DOMAIN]:5001/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-" - -
[Client IP] - - [06/Jan/2024:10:27:55 +0100] "GET /login/?error=Unauthorized&autoLaunch=0 HTTP/2.0" 200 3738 "https://[DOMAIN]:5001/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-" - -
[Client IP] - - [06/Jan/2024:10:27:56 +0100] "GET /_nuxt/manifest.31bfdee8.json HTTP/2.0" 200 372 "https://[DOMAIN]:5001/login/?error=Unauthorized&autoLaunch=0" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-" - -
[Client IP] - - [06/Jan/2024:10:27:56 +0100] "GET /_nuxt/7678e44.js HTTP/2.0" 200 5254 "https://[DOMAIN]:5001/login/?error=Unauthorized&autoLaunch=0" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-" - -
[Client IP] - - [06/Jan/2024:10:27:56 +0100] "GET /_nuxt/4888c44.js HTTP/2.0" 200 14045 "https://[DOMAIN]:5001/login/?error=Unauthorized&autoLaunch=0" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-" - -
[Client IP] - - [06/Jan/2024:10:27:56 +0100] "GET /_nuxt/b5ba881.js HTTP/2.0" 200 12559 "https://[DOMAIN]:5001/login/?error=Unauthorized&autoLaunch=0" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-" - -
[Client IP] - - [06/Jan/2024:10:27:56 +0100] "GET /_nuxt/fonts/SourceSansPro-Regular.df87f53.ttf HTTP/2.0" 200 248132 "https://[DOMAIN]:5001/login/?error=Unauthorized&autoLaunch=0" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-" - -
[Client IP] - - [06/Jan/2024:10:27:56 +0100] "GET /status HTTP/2.0" 200 208 "https://[DOMAIN]:5001/login/?error=Unauthorized&autoLaunch=0" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-" - -
[Client IP] - - [06/Jan/2024:10:27:56 +0100] "GET /sw.js HTTP/2.0" 200 3545 "" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-" - -

DSM / SSO Server:

[Client IP] - - [06/Jan/2024:10:27:55 +0100] "GET /webman/sso/SSOOauth.cgi?client_id=[Client ID]&scope=openid%20profile%20email&response_type=code&redirect_uri=https%3A%2F%2F[DOMAIN]%3A5001%2Fauth%2Fopenid%2Fcallback&state=[STATE]&code_challenge=[Challenge]&code_challenge_method=S256 HTTP/2.0" 302 0 "https://[DOMAIN]:5001/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.2.1 Safari/605.1.15" "-" - -
[Local IP] - 50d97585c238ad5740649d84584e24d8 [06/Jan/2024:10:27:55 +0100] "POST /webman/sso/SSOAccessToken.cgi HTTP/1.1" 200 858 "-" "openid-client/5.6.1 (https://github.com/panva/node-openid-client)" "-" - grant_type=authorization_code&code=[CODE]&redirect_uri=https%3A%2F%2F[DOMAIN]%3A5001%2Fauth%2Fopenid%2Fcallback&code_verifier=[Verifier]
[Local IP] - - [06/Jan/2024:10:27:55 +0100] "GET /webman/sso/SSOUserInfo.cgi HTTP/1.1" 200 99 "-" "openid-client/5.6.1 (https://github.com/panva/node-openid-client)" "-" - -

EDIT: Also i just noticed, that we're back to just "Unauthorized" the Error i got last time in the SSO Server log is gone now as well... Just mentions login again.

Jan 6 10:27:55 SSOOauth.cpp:line 730 OIDC User[USER] login from AppName[Audiobookshelf]

Sapd commented 7 months ago

Seems according to the logs authentication worked: Even the call to userinfo seems to have worked:

[Local IP] - - [06/Jan/2024:10:27:55 +0100] "GET /webman/sso/SSOUserInfo.cgi HTTP/1.1" 200 99 "-" "openid-client/5.6.1 (https://github.com/panva/node-openid-client)" "-" - -

Status 200 and it transmitted 99 bytes. So node-openid-client is probably not able to parse the userinfo it gets.

Does the ABS log say now something else?

Drakon74 commented 7 months ago

Ah right, sorry, docker logs say this:

[2024-01-06 10:27:55.897] ERROR: [Auth] No data in openid callback - Unauthorized (Auth.js:426)

Are there any other logs you can check? In the docker container itself perhaps?

Sapd commented 7 months ago

[2024-01-06 10:27:55.897] ERROR: [Auth] No data in openid callback - Unauthorized (Auth.js:426)

Im not really sure where that "Unauthorized" comes from. Its neither in the node-openid-client code nor in ABS, so it must come from some request. But on the other hand all requests from your logs show status 200 haha.

Are there any other logs you can check? In the docker container itself perhaps?

As far as I can see the logging mechanisms of node-openid-client are not really great. To debug it further it gets a bit more complicated (at least I dont have a simpler idea)... I think if you want to tackle that you need to run ABS from your computer in VSCode via the debugger and then set a breakpoint at this line: https://github.com/advplyr/audiobookshelf/blob/a426da534c89a33ff28e6299d690a82ab2fc2081/server/Auth.js#L466 and then follow the calls inside it. A bit similar to the guy here in his screenshots: https://github.com/panva/node-openid-client/issues/275 Then take a look at which line exactly throws that error with what reason.

Drakon74 commented 7 months ago

Before i do that, since it would be some effort, do you think it would make sense to ask Synology too?

I mean, i guess they just push it to the application, but maybe they have an idea what it could cause? Their support can be helpful (at times xD)

Sapd commented 7 months ago

Before i do that, since it would be some effort, do you think it would make sense to ask Synology too?

I mean, i guess they just push it to the application, but maybe they have an idea what it could cause? Their support can be helpful (at times xD)

Well does not hurt to try, maybe some engineer has more information about his implementation. But most companies probably would not look into detail.

Drakon74 commented 7 months ago

So i contacted them, and they actually tried to at least investigate some.

They added a own user to both the Synology and Audiobookshelf and tried it themselves, however still getting the same error. They do confirm though that the Synology SSO apparently returns the information.

After conducting a thorough check, we have confirmed that Synology SSO has successfully received the access token and correctly returned the following information to Audiobookshelf:

{
    "email" : "",
    "sub" : "syno_test",
    "username" : "syno_test"
}

In the backend, the user account 'syno_test' has been created, which matches the provided username. However, despite these actions, Audiobookshelf continues to display an 'Unauthorized' message.

So i guess i will look into the whole thing with VSCode at some day in the near future xD.

Sapd commented 7 months ago

They added a own user to both the Synology and Audiobookshelf and tried it themselves, however still getting the same error. They do confirm though that the Synology SSO apparently returns the information.

I think it's really cool that they tested it. I would have not expected it tbh, makes a good impression on Synology.

In the backend, the user account 'syno_test' has been created, which matches the provided username. However, despite these actions, Audiobookshelf continues to display an 'Unauthorized' message.

What do you mean by backend? You mean the user is created in ABS?

Edit: With debug logs on, is the message: "[Auth] openid callback userinfo=" displayed in the logs of ABS?

Drakon74 commented 7 months ago

What do you mean by backend? You mean the user is created in ABS?

Yes. They created the user "syno_test" on both sides, Synology and ABS and then tried to login on ABS over SSO, but received the same "Unauthorized" error as before.

Edit: With debug logs on, is the message: "[Auth] openid callback userinfo=" displayed in the logs of ABS?

How do you enable debug logs?

Sapd commented 7 months ago

How do you enable debug logs?

Ah you didnt do yet. You simply go into ABS admin interface, click on logs. And then on the drop down on the top right you can change the log level.

Try to retest it, could be that there is an important hint.

Drakon74 commented 7 months ago

I updated the image to the latest version now too, and enabled debug logs.

DEBUG: [Auth] Oidc redirect_uri=https://[DOMAIN]:5001/auth/openid/callback (Auth.js:310)
DEBUG: [Auth] openid callback userinfo= { email: '[My MAIL]', sub: 'Drakon', username: 'Drakon' } (Auth.js:98)
ERROR: [Auth] No data in openid callback - Unauthorized (Auth.js:426)

Nothing on the synology side. Though according to the log, it does seem to get the data and all?

Sapd commented 7 months ago

Ahhh okay, then the error is actually on our side.

It must be a problem somewhere here: https://github.com/advplyr/audiobookshelf/blob/90f4833c9e0957f08799af15966d1909516b335e/server/Auth.js#L98

@advplyr any ideas? The Unauthorized maybe comes from this line: https://github.com/advplyr/audiobookshelf/blob/90f4833c9e0957f08799af15966d1909516b335e/server/Auth.js#L150

Sapd commented 7 months ago

@Drakon74 What really weird is, in the userinfo, color information (ANSI control characters) are included:

DEBUG: [Auth] openid callback userinfo= { email: �[32m'[My MAIL]'�[39m, sub: �[32m'Drakon'�[39m, username: �[32m'Drakon'�[39m } (Auth.js:98)

Basically 32m is the color green, and 39m is the stop color. Can you contact the synology support, and ask if it is intended that there seems that there are color information encoded into the string? Or also if there is a specific encoding required or so.

As far as I can see we are simply outputting the received string, so I don't know where this can come from except possibly form Synology.

Drakon74 commented 7 months ago

@Sapd I actually wondered what these would mean as well, good to knows these are the color control characters!

The ticket at Synology was still open, so i relayed the question to them.

Sapd commented 7 months ago

So I indeed, on a normal instance (I rechecked) it should output something like: "[Auth] openid callback userinfo= [object Object]" because the response will be converted to a JSON-object. Instead it cannot do so, because the string received is not valid JSON, giving you the output you have.

Sapd commented 7 months ago

@Drakon74 Just to make sure: When you set the log level to debug and you get the same message from above. How does the message look like from the container or application log? (Instead of the log-webinterface in ABS?)

Drakon74 commented 7 months ago

This is super weird, i changed nothing, i just set the log level to debug again, and now i am getting "error in callback", despite nothing changed on either side.

The log from yesterday was from the container logs, i think in the web interface it just showed "[Auth] openid callback userinfo= [object Object]" too. Are the logs being written somewhere in the container? I didn't restarted it since yesterday so maybe they're somewhere still.

But yes, now i am getting this: (It's the same between docker and webinterface logs)

2024-01-20 09:42:14.261 DEBUG [Auth] Oidc redirect_uri=https://DOMAIN:5001/auth/openid/callback
2024-01-20 09:42:23.195 ERROR [Auth] Error in openid callback - OPError: server_error
2024-01-20 09:42:23.196 DEBUG
POST /webman/sso/SSOAccessToken.cgi HTTP/1.1
 Accept: application/json
 Authorization: REDACTED
 User-Agent: openid-client/5.6.1 (https://github.com/panva/node-openid-client)
 Host: DOMAIN:5001
 content-type: application/x-www-form-urlencoded
 content-length: 218
 Connection: close

 [object Object]

I'm really confused slowly xD.

Drakon74 commented 7 months ago

Hm nevermind, i reloaded the nginx and now we're back to "Unauthorized" ... super weird.

Anyway, the logs again:

Webinterface:

2024-01-20 09:50:55.464 DEBUG [Auth] Oidc redirect_uri=https://DOMAIN:5001/auth/openid/callback
2024-01-20 09:51:04.990 DEBUG [Auth] openid callback userinfo= [object Object]
2024-01-20 09:51:04.994 ERROR [Auth] No data in openid callback - Unauthorized

Docker Logs:

[2024-01-20 09:50:55.464] DEBUG: [Auth] Oidc redirect_uri=https://DOMAIN:5001/auth/openid/callback (Auth.js:310)
[2024-01-20 09:51:04.989] DEBUG: [Auth] openid callback userinfo= { email: 'E-Mail', sub: 'Drakon', username: 'Drakon' } (Auth.js:98)
[2024-01-20 09:51:04.994] ERROR: [Auth] No data in openid callback - Unauthorized (Auth.js:426)
Sapd commented 7 months ago

Hm nevermind, i reloaded the nginx and now we're back to "Unauthorized" ... super weird.

Really weird, something is not consistent in that setup.

Anyway, the logs again

Yeah the string is really just coming from outputting the response directly into console.debug. So the control characters seem to come in fact from Synology, messing up the JSON. Lets wait what the support says.

Drakon74 commented 6 months ago

So the Synology support responded this:

After our developer checked, these special characters should not be returned by Synology SSO Server.

They also sent me this screenshot, showing they, apparently, went into the Audiobookshelf docker container and ran curl. And i guess no color characters showed up / no color change occurred in the terminal.

image

Sapd commented 6 months ago

Can you do the same again but call curl with the parameter -vvv

Sapd commented 6 months ago

Im not sure about your detailed setup. But if your OIDC endpoint is reachable from the Internet, you can send me if you wish the details (i.e. via email, see my GitHub Profile). I can try to debug it on the weekend or so (but no promise on timings)

Drakon74 commented 6 months ago

Hey @Sapd,

sorry for the silence. I am sadly rather busy since last week and will still be for about the next 2 weeks. Though i will probably taking you up on that offer of debugging, and no worries about any times! I will contact you via Mail, once i have enough time again.

Still thanks so far!

nanokatz commented 6 months ago

Just wanted to add I am having a similar issue but with authentik. Authentik reports succesfull login and as far as i can see ABS gets the info but then ignores it. Unlike the case above though no issue with json conversion.

From the debug logs with info removed:


[2024-02-15 08:42:24.379] DEBUG: [Auth] Oidc redirect_uri=https://XXXXX.com/auth/openid/callback (Auth.js:310)
[2024-02-15 08:42:32.170] DEBUG: [Auth] openid callback userinfo= {
  email: 'XXXXX.',
  email_verified: true,
  name: 'XXXXX.',
  given_name: 'XXXXX.',
  preferred_username: 'XXXXX.',
  nickname: 'nanokatz',
  groups: [ XXXXX.],
  sub: 'XXXXX.'
} (Auth.js:98)
[2024-02-15 08:42:32.180] ERROR: [Auth] No data in openid callback - Unauthorized (Auth.js:426)

I am running ABS behind a traefik reverse proxy and this is what the og there shows me:

192.168.0.11 - - [15/Feb/2024:08:59:16 +0000] "GET /auth/openid?callback=https://XXXXXX.com/login/ HTTP/2.0" 302 830 "-" "-" 556 "abs@docker" "http://172.21.0.2:80" 5ms
192.168.0.11 - - [15/Feb/2024:08:59:17 +0000] "GET /sw.js HTTP/2.0" 304 0 "-" "-" 557 "abs@docker" "http://172.21.0.2:80" 2ms
192.168.0.11 - - [15/Feb/2024:08:59:17 +0000] "GET /auth/openid/callback?code=b233bed9cdce44cdaaa071a8f22dd2ab&state=3PvIq1xtKc18EdMtn2fUta4cfsjFstgHv7MiSovU3W0 HTTP/2.0" 302 128 "-" "-" 558 "abs@docker" "http://172.21.0.2:80" 923ms
192.168.0.11 - - [15/Feb/2024:08:59:18 +0000] "GET /login?error=Unauthorized&autoLaunch=0 HTTP/2.0" 301 249 "-" "-" 559 "abs@docker" "http://172.21.0.2:80" 44ms
192.168.0.11 - - [15/Feb/2024:08:59:19 +0000] "GET /sw.js HTTP/2.0" 304 0 "-" "-" 560 "abs@docker" "http://172.21.0.2:80" 2ms
192.168.0.11 - - [15/Feb/2024:08:59:19 +0000] "GET /login/?error=Unauthorized&autoLaunch=0 HTTP/2.0" 200 3738 "-" "-" 561 "abs@docker" "http://172.21.0.2:80" 2ms
Sapd commented 6 months ago

@nanokatz Best would be to open up a separate issue I think, because its probably not the same (even when Im not 100% sure).

Your error maybe comes from here

      if (!user?.isActive) {
        if (user && !user.isActive) {
          failureMessage = 'Unauthorized'
        }
        // deny login
        done(null, null, failureMessage)
        return
      }

Maybe you try to login with an user which is disabled in abs?

Sapd commented 5 months ago

To update: Drakon gave me the OpenID Credentials of his Synology instance, and created an account for me to test logging in.

So I booted up an ABS instance locally, and put in his OpenID credentials. Funny thing is, for me it works. I can log in via Openid via his Synology instance. Not quite sure currently why it works for me but not for him (using the very same! synology device) - what is different is that it was a new account on his device.

l3of0x commented 4 months ago

I am having the same issue, also with Synology. Unfortunately for me creating a new user made no difference. From the logs I see that the JSON coming back to the callback appears to be valid, but still getting the "No data in openid callback" error.

2024/03/28 20:03:00 stderr [2024-03-28 20:03:00.357] ERROR: [Auth] No data in openid callback - Unauthorized (Auth.js:427) 2024/03/28 20:03:00 stdout [2024-03-28 20:03:00.354] DEBUG: [Auth] openid callback userinfo= { email: '', sub: 'testt', username: 'testt' } (Auth.js:101) 2024/03/28 20:00:08 stdout [2024-03-28 20:00:08.045] DEBUG: [Auth] OIDC redirect_uri=https://[redacted]/auth/openid/callback (Auth.js:323) 2024/03/28 19:59:47 stderr [2024-03-28 19:59:47.907] ERROR: [Auth] No data in openid callback - Unauthorized (Auth.js:427) 2024/03/28 19:59:47 stdout [2024-03-28 19:59:47.903] DEBUG: [Auth] openid callback userinfo= { email: '[redacted]', sub: 'john', username: 'john' } (Auth.js:101) 2024/03/28 19:59:38 stdout [2024-03-28 19:59:38.146] DEBUG: [Auth] OIDC redirect_uri=https://[redacted]/auth/openid/callback (Auth.js:323)

I've tried the Match by Username and Match by Email options, the user is active.

I enabled Auto Register, and that created a duplicate user with the same username when I logged in with OIDC, so I guess this is a workaround, but I would like to be able to create users ahead of time and then match on username.

Looking at the SQLite db: image

The 2 rows have the same value for username, 2nd row is the autocreated user, and for some reason email was not populated despite being provided in the callback.

Sapd commented 4 months ago

2024/03/28 19:59:47 stdout [2024-03-28 19:59:47.903] DEBUG: [Auth] openid callback userinfo= { email: '[redacted]', sub: 'john', username: 'john' } (Auth.js:101)

@l3of0x What I noticed here is, that email_verified: true, is missing. Which OIDC must sent with to indicate wether the e-mail is trustworthy. Without it, ABS will simply skip matching by email.

Still it does not explain why username matching does not work. It also seems that @Drakon74 is observing the same behaviour.

Sapd commented 4 months ago

Oh wait... preferred_username is missing, too. Without that it will also skip matching username.

Do you have any options in Synology to set it?

l3of0x commented 4 months ago

Oh wait... preferred_username is missing, too. Without that it will also skip matching username.

Do you have any options in Synology to set it?

There are no options in Synology to set the fields that get sent back, but regarding matching as I mentioned when I have Auto Register turned on in ABS after the user is created I am able to log in on subsequent attempts. Also looking at the code it appears that ABS first tries to match on "sub" which is populated by Synology.

image

Sapd commented 4 months ago

Oh wait... preferred_username is missing, too. Without that it will also skip matching username. Do you have any options in Synology to set it?

There are no options in Synology to set the fields that get sent back, but regarding matching as I mentioned when I have Auto Register turned on in ABS after the user is created I am able to log in on subsequent attempts. Also looking at the code it appears that ABS first tries to match on "sub" which is populated by Synology.

@l3of0x Yeah that is normal. Sub is the main identifier in OpenID which always takes precedence.

Actually username is not defined in the specs, it must be preferred_username which synology does not seem to honor.

I deployed a fix here if you would like to test: https://github.com/advplyr/audiobookshelf/pull/2769 It also checks for just username and allows email_verified to be null.

advplyr commented 3 months ago

Fixed in v2.9.0