log file unmodified attached

May  5 09:39:45 tsogo1 sogod[50784]: [21717]: [ERROR] <0x0x401439592228[GSCBufferString]> json parser: Expected value while parsing array, attempting once more after unescaping...
May  5 09:39:45 tsogo1 sogod[50784]: [21717]: [ERROR] <0x0x401439592228[GSCBufferString]> total failure. Original string is: e0c^M
May  5 09:39:45 tsogo1 sogod[50784]: {"issuer":"https://auth.test.ec-m.fr/oidc","scopes_supported":["openid","profile","email","address","phone","offline_access","client_configuration_scope","uma_authorization","uma_protection","client_registration_scope"],"response_types_supported":["code","token","id_token","id_token token","device_code"],"response_modes_supported":["query","fragment","form_post"],"subject_types_supported":["public","pairwise"],"claim_types_supported":["normal"],"claims_supported":["sub","acr","name","preferred_username","family_name","given_name","middle_name","profile","picture","nickname","website","zoneinfo","locale","updated_at","birthdate","email","email_verified","phone_number","phone_number_verified","address","gender"],"grant_types_supported":["authorization_code","password","client_credentials","refresh_token","urn:ietf:params:oauth:grant-type:uma-ticket"],"id_token_signing_alg_values_supported":["none","RS256","RS384","RS512","PS256","PS384","PS512","ES256","ES384","ES512","HS256","HS384","HS512"],"dpop_signing_alg_values_supported":["RS256","RS384","RS512","ES256","ES384","ES512"],"id_token_encryption_alg_values_supported":["RSA1_5","RSA-OAEP","RSA-OAEP-256","A128KW","A192KW","A256KW","A128GCMKW","A192GCMKW","A256GCMKW","ECDH-ES","ECDH-ES+A128KW","ECDH-ES+A192KW","ECDH-ES+A256KW"],"id_token_encryption_enc_values_supported":["A128CBC-HS256","A192CBC-HS384","A256CBC-HS512","A128GCM","A192GCM","A256GCM"],"userinfo_signing_alg_values_supported":["none","RS256","RS384","RS512","PS256","PS384","PS512","ES256","ES384","ES512","HS256","HS384","HS512"],"userinfo_encryption_alg_values_supported":["RSA1_5","RSA-OAEP","RSA-OAEP-256","A128KW","A192KW","A256KW","A128GCMKW","A192GCMKW","A256GCMKW","ECDH-ES","ECDH-ES+A128KW","ECDH-ES+A192KW","ECDH-ES+A256KW"],"userinfo_encryption_enc_values_supported":["A128CBC-HS256","A192CBC-HS384","A256CBC-HS512","A128GCM","A192GCM","A256GCM"],"acr_values_supported":["mfa-simple"],"request_object_signing_alg_values_supported":["none","RS256","RS384","RS512","PS256","PS384","PS512","ES256","ES384","ES512","HS256","HS384","HS512"],"request_object_encryption_alg_values_supported":["RSA1_5","RSA-OAEP","RSA-OAEP-256","A128KW","A192KW","A256KW","A128GCMKW","A192GCMKW","A256GCMKW","ECDH-ES","ECDH-ES+A128KW","ECDH-ES+A192KW","ECDH-ES+A256KW"],"request_object_encryption_enc_values_supported":["A128CBC-HS256","A192CBC-HS384","A256CBC-HS512","A128GCM","A192GCM","A256GCM"],"introspection_endpoint_auth_methods_supported":["client_secret_basic"],"token_endpoint_auth_methods_supported":["client_secret_basic","client_secret_post","client_secret_jwt","private_key_jwt"],"code_challenge_methods_supported":["plain","S256"],"prompt_values_supported":["none","login","consent"],"claims_parameter_supported":true,"request_uri_parameter_supported":true,"request_parameter_supported":true,"backchannel_logout_supported":true,"frontchannel_logout_supported":true,"pushed_authorization_request_endpoint":"https://auth.test.ec-m.fr/oidc/oidcPushAuthorize","backchannel_logout_session_supported":true,"frontchannel_logout_session_supported":true,"authorization_endpoint":"https://auth.test.ec-m.fr/oidc/oidcAuthorize","token_endpoint":"https://auth.test.ec-m.fr/oidc/oidcAccessToken","userinfo_endpoint":"https://auth.test.ec-m.fr/oidc/oidcProfile","registration_endpoint":"https://auth.test.ec-m.fr/oidc/register","end_session_endpoint":"https://auth.test.ec-m.fr/oidc/oidcLogout","introspection_endpoint":"https://auth.test.ec-m.fr/oidc/introspect","revocation_endpoint":"https://auth.test.ec-m.fr/oidc/revoke","jwks_uri":"https://auth.test.ec-m.fr/oidc/jwks"}^M
May  5 09:39:45 tsogo1 sogod[50784]: 0^M
May  5 09:39:45 tsogo1 sogod[50784]: ^M
May  5 09:39:45 tsogo1 sogod[50784]: 
May  5 09:39:45 tsogo1 sogod[50784]: [21717:102018] EXCEPTION: <NSException: 0x4014390b11c8> NAME:NSInvalidArgumentException REASON:Tried to add nil value for key 'authorization_endpoint' to dictionary INFO:{}

Hello, found the problem.
Your endpoint use this for the get response
HTTP/1.1 200 200
Transfer-Encoding: chunked
...

This header, deprecated for HTTP/2.0 (https://developer.mozilla.org/en-US/docs/Web/HTTP/Reference/Headers/Transfer-Encoding) is not supported by sogo.

The data received for the endpoint in this transfer mode is:
<size of chunk>
<chunk of data>
<size of chunk>
....
<0>

As sogo don't support this, he thinks that the size of chunk is actual data meaning it will read something like this
e0c
{"issuer"...
Hence the fail of the json parser.

I see that your apereo CAs 6.5.15 has reach end of life (https://apereo.github.io/cas/developer/Maintenance-Policy.html#eol-schedule)
I'm not sure the 7.x.x version doesn't use this header anymore, though. Would you be able to install a fresh apereo cas server with their last version and test it?

Thank you, I'll try, but not very quickly…

Hi

Just FYI I have the same issue with Authentik and Traefik as reverse proxy (both using the latest version):
sogod [3371513]: [ERROR] <0x0x55566c8d1b10[GSCBufferString]> json parser: Expected value while parsing array, attempting once more after unescaping...
sogod [3371513]: [ERROR] <0x0x55566c8d1b10[GSCBufferString]> total failure. Original string is: 75c
...
sogod[3371513:3371513] EXCEPTION: <NSException: 0x55566c8fdf50> NAME:NSInvalidArgumentException REASON:Tried to add nil value for key 'authorization_endpoint' to dictionary INFO:{}

Checking with curl (limiting it to HTTP 1.1) chunking is used:
< Transfer-Encoding: chunked

I suspect there will be many other reverseproxies using this encoding.

Would it be possible for Sogo to use HTTP/2 instead?

Hello,
So for now SOGo uses a internal lib to make request for openid. But I have so much problem with it that I change it for the libcurl (https://curl.se/libcurl/)
I test it with my current keycloak, that was already working, and it seems ok. SOGo also manage to fetch correctly your own server auth.test.ec-m.fr which it couldn't before. Of course I'm stuck just after because my app is not registered.

However, before putting this in the nightly, I want to make a custom package for you to try it and confirm/deny it works better now.
Could you tell me wich repo are you using (OS/version) so I can build a custom package for you ?

I currently use Sogo from the RHEL8 nightly repo (x64). I could test the update.

OK first remove sogo and change the repo url to:
https://packages.sogo.nu/custom/openid_curl/rhel/8
No need to change anything in your sogo.conf

Here we use FreeBSD and locally-compiled packages, I just need source patches to test :)

Hello, this is this branch -> https://github.com/Alinto/sogo/tree/openid_curl no change in SOPE so still master.

I've updated the branch and package to show more logs with the server response
SOGoOpenIDDebugEnabled = YES;
It may give clues if this is still not working.

I just tested: this bug is patched for us (even if oidc login is still not OK, but I have to check the IDP side on this other problem…)

Thank you !

Great, let me know if there is other problems. I'll wait for some other feedback before pushing this into the nightly

Thank you, the OIDC login does work now.

However there seems to be strange behavior at first:
sogod[886797:886797] OpenId perform request: GET https://auth.example.com/application/o/userinfo/
sogod[886797:886797] OpenId perform request, headers {authorization = "Bearer (null)"; "content-type" = "application/x-www-form-urlencoded"; }
sogod[886797:886797] OpenId perform request: response is: <SimpleOpenIdResponse> <status: 401>, <headers: HTTP/1.1 401 Unauthorized

The headers show:
Www-Authenticate: error="invalid_token", error_description="The access token provided is expired, revoked, malformed, or invalid for other reasons"

The issue could be related to the token endpoint which cannot be queried:
sogod[886797:886797] OpenId perform request: POST https://auth.example.com/application/o/token/
sogod[886797:886797] OpenId perform request, headers {"content-type" = "application/x-www-form-urlencoded"; }
sogod[886797:886797] OpenId perform request: response is: <SimpleOpenIdResponse> <status: 400>, <headers: HTTP/1.1 400 Bad Request

Content:
{"error": "invalid_client", "error_description": "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)"}

Note: This happens like 4 times in a row, after that the logs show a token being correctly issued and the login succeeding with the correct user info.

Additionally there seems to be an error updating rhe OIDC session table:
sogod [886797]: [ERROR] <0x0x55cc58127d50[GCSOpenIdFolder]> -[GCSOpenIdFolder writeOpenIdSession:withOldSession:withRefreshToken:withExpire:withRefreshExpire:]: cannot write record: <MySQL4Exception: 0x55cc581357a0> NAME:ExecutionFailed REASON:Field 'c_access_token_expires_in' doesn't have a default value
sogod [886797]: [ERROR] <0x0x7f1868242320[SOGoSession]> Value to be secured is too big (2238 > 1575) -- secured value will be corrupted

For the OIDC table see https://bugs.sogo.nu/view.php?id=6122#c18218
I now added a default value to c_access_token_expires_in when creating the table but preexisting table would need to have that manually.

I will take a look for the first point.

Hello, @sogouser123
I've made a fix for the failures and also for c_access_token_expires_in, in the same custom repo can you test it?

Aldo @dgeo if you can rebuild and check that everything's ok.

Sorry for the delay. Tested it with v5.12.2. Works fine now. No errors observed.
Thank you for your efforts.

I've run some more tests and observed another potential issue: When logging in with OIDC it seems the first request is not using the correct auth mechanism, it always tries to use LDAP/PLAIN:
dovecot[1887]: auth: ldap(user@example.com,::1,<a4H6n8g4ENoAAAAAAAAAAAAAAAAAAAAB>): Password mismatch (for LDAP bind) (given password: JWT_TOKEN_HERE) - trying the next passdb
dovecot[1887]: imap-login: Login: user=<user@example.com>, method=XOAUTH2, rip=::1, lip=::1, mpid=104738, secured, session=<a4H6n8g4ENoAAAAAAAAAAAAAAAAAAAAB>

This fails and dovecot then accepts the login when trying xoauth2. The problem is the user gets locked out on LDAP after a few retries.

Is this something sogo can change or is this a configuration error? Dovecot is configured as follows:
auth_mechanisms = $auth_mechanisms oauthbearer xoauth2
passdb {
driver = oauth2
mechanisms = xoauth2 oauthbearer
args = /etc/dovecot/dovecot-oauth2.conf.ext
}

With the OIDC config beeing the following:
openid_configuration_url = https://idp.example.com/application/o/example-mail/.well-known/openid-configuration
username_attribute = email
introspection_mode = post
introspection_url = https://ID:SECRET@idp.example.com/application/o/introspect/
tls_ca_cert_file = /etc/ssl/certs/ca-bundle.crt
active_attribute = active
active_value = true

Yes dovecot does all the passdb configured. I'm assuming you have a ldap configured somewhere in your dovecot files.

I'm not sure if this is possible and how to force dovecot to only make the proper passdb. You should ask their support -> https://www.dovecot.org/support

Yes I have LDAP configured. I still need LDAP to authenticate Cal/CardDav connections which use regular username/pw auth.
I would assume sogo uses XOAUTH2 for Web and LDAP for Cal/CardDav for ActiveSync? Then this should not happen.
It is a bit wierd to me that sogo sends the JWT Token form OAuth as "Plain" auth mechanism to Dovecot.

It is a bit wierd to me that sogo sends the JWT Token form OAuth as "Plain" auth mechanism to Dovecot.

It doesn't. But dovecot will still try to do passdb ldap even with an xoauth2. I'm not sure why. From what I understand, dovecot will try each passdb until success.

I managed to fix the issue with the ldap logins with a login mechanism restriction on the passdb:
passdb {
driver = ldap
mechanisms = plain login
args = /etc/dovecot/dovecot-ldap.conf.ext
}

This works as expected and logins are using the correct passdb. Cal/CardDav use plain and Web uses oauth2.
However ActiveSync does not seem to be using the correct auth mechanism, it seems sogo is forwarding the auth requests for active sync as oauth:
Sogo Logs:
sogod [1807070]: "POST /SOGo/Microsoft-Server-ActiveSync?User=user@example.com&DeviceId=XXXXX&DeviceType=iPhone&Cmd=Sync HTTP/1.1" 200 0/100 0.211 - - 0 - 13
sogod [1807070]: [ERROR] <0x0x55f897078430[NGImap4ConnectionManager]> IMAP4 login failed:
host=localhost, user=user@example.com, pwd=yes
url=imap://user%40example.com@localhost/?tls=NO&tlsVerifyMode=default
base=(null)
base-class=(null))
= <0x0x55f89725e2b0[NGImap4Client]: login=user@example.com(pwd) socket=<NGActiveSocket[0x0x55f8972e4940]: mode=rw address=<0x0x55f8972e49b0[NGInternetSocketAddress]: host=localhost port=48390> connectedTo=<0x0x55f8972e5020[NGInternetSocketAddress]: host=localhost port=143>>>
sogod [1807070]: <0x55f8971d1130[SOGoMailAccount]:0> renewing imap4 password
sogod [1807070]: [ERROR] <0x0x55f897078430[NGImap4ConnectionManager]> IMAP4 login failed:
host=localhost, user=user@example.com, pwd=yes
url=imap://user%40example.com@localhost/?tls=NO&tlsVerifyMode=default
base=(null)
base-class=(null))
= <0x0x55f8972efca0[NGImap4Client]: login=user@example.com(pwd) socket=<NGActiveSocket[0x0x55f8972e56d0]: mode=rw address=<0x0x55f8972e5740[NGInternetSocketAddress]: host=localhost port=48404> connectedTo=<0x0x55f8972f0440[NGInternetSocketAddress]: host=localhost port=143>>>
sogod [1807070]: [ERROR] <0x55f8971d1130[SOGoMailAccount]:0> Could not connect IMAP4

Dovecot Logs
dovecot[1807041]: auth: oauth2(user@example.com,::1,<edikiBo5IpcAAAAAAAAAAAAAAAAAAAAB>): oauth2 failed: Introspection failed: Provided token is not valid
dovecot[1807041]: imap-login: Disconnected: Connection closed (client didn't finish SASL auth, waited 0 secs): user=<>, method=XOAUTH2, rip=::1, lip=::1, secured, session=<edikiBo5IpcAAAAAAAAAAAAAAAAAAAAB>

This causes the ActiveSync to fail. It would be nice if sogo could choose the correct auth mechanism with ActiveSync as it does with Cal/CardDav.

Additionally I observed a DB error when logging in:
Jul 04 15:29:54 sogod [1807072]: [ERROR] <0x0x55f897601800[GCSSessionsFolder]> -[GCSSessionsFolder writeRecordForEntryWithID:value:creationDate:lastSeenDate:]: cannot write record: <MySQL4Exception: 0x55f8976e23f0> NAME:ExecutionFailed REASON:Data too long for column 'c_value' at row 1

The c_value column has a length of 4096 in my DB. The session seems to work however.