Autoprovisioning user failed with panic for some users

[0x1a8510f2]

Describe the bug

While using oauth, one user is autoprovisioned correctly and can log in, while another is stuck on a "You were automatically logged out for security reasons" loop. See logs below.

Steps to reproduce

Unclear. Autoprovisioning fails for user with username 0x1a8510f2 but succeeds for username l1qu1d. No other significant differences between the users.

Expected behavior

The user is autoprovisioned and signed in correctly.

Actual behavior

The user is presented with the following screen, and errors appear in logs:

2023-04-30T11:42:58.151643208Z ERR Error creating user | service=proxy error=400 Bad Request
2023-04-30T11:42:58.151657188Z ERR Autoprovisioning user failed | service=proxy error=400 Bad Request
2023/04/30 11:42:58 http: panic serving 172.125.0.200:32796: runtime error: invalid memory address or nil pointer dereference
goroutine 358401 [running]:
net/http.(*conn).serve.func1()
    net/http/server.go:1854 +0xbf
panic({0x3d91600, 0x5a40c60})
    runtime/panic.go:890 +0x263
github.com/owncloud/ocis/v2/services/proxy/pkg/middleware.accountResolver.ServeHTTP({{0x42700e0, 0xc001ccc6c0}, {{{0x427f110, 0xc0014a1850}, 0x3, {0x0, 0x0}, {0xc001948400, 0x12, 0x1f4}, ...}}, ...}, ...)
    github.com/owncloud/ocis/v2/services/proxy/pkg/middleware/account_resolver.go:82 +0x575
github.com/owncloud/ocis/v2/services/proxy/pkg/middleware.Authentication.func1.1({0x7f480f6cb358, 0xc000e53140}, 0xc0000c1300)
    github.com/owncloud/ocis/v2/services/proxy/pkg/middleware/authentication.go:64 +0x1fa
net/http.HandlerFunc.ServeHTTP(0x428bf08?, {0x7f480f6cb358?, 0xc000e53140?}, 0x5cf8e40?)
    net/http/server.go:2122 +0x2f
github.com/owncloud/ocis/v2/services/proxy/pkg/router.Middleware.func1.1({0x7f480f6cb358, 0xc000e53140}, 0xc0000c1200)
    github.com/owncloud/ocis/v2/services/proxy/pkg/router/router.go:31 +0x205
net/http.HandlerFunc.ServeHTTP(0xc000779ce4?, {0x7f480f6cb358?, 0xc000e53140?}, 0xc001aa9730?)
    net/http/server.go:2122 +0x2f
github.com/owncloud/ocis/v2/services/proxy/pkg/middleware.OIDCWellKnownRewrite.func1.1({0x7f480f6cb358, 0xc000e53140}, 0xc0000c1200?)
    github.com/owncloud/ocis/v2/services/proxy/pkg/middleware/oidc_well-known.go:45 +0x313
net/http.HandlerFunc.ServeHTTP(0xc0094f7140?, {0x7f480f6cb358?, 0xc000e53140?}, 0xc71ea5?)
    net/http/server.go:2122 +0x2f
github.com/owncloud/ocis/v2/services/proxy/pkg/middleware.HTTPSRedirect.func1({0x7f480f6cb358, 0xc000e53140}, 0xc0000c1200)
    github.com/owncloud/ocis/v2/services/proxy/pkg/middleware/https_redirect.go:17 +0x142
net/http.HandlerFunc.ServeHTTP(0x4289a30?, {0x7f480f6cb358?, 0xc000e53140?}, 0xc0000c1200?)
    net/http/server.go:2122 +0x2f
github.com/owncloud/ocis/v2/services/proxy/pkg/middleware.AccessLog.func1.1({0x4289a30, 0xc00140cee0}, 0xc0000c1200)
    github.com/owncloud/ocis/v2/services/proxy/pkg/middleware/accesslog.go:17 +0xc8
net/http.HandlerFunc.ServeHTTP(0x428be60?, {0x4289a30?, 0xc00140cee0?}, 0x39fd198?)
    net/http/server.go:2122 +0x2f
github.com/go-chi/chi/v5/middleware.RequestID.func1({0x4289a30, 0xc00140cee0}, 0xc0000c1100)
    github.com/go-chi/chi/v5@v5.0.8/middleware/request_id.go:76 +0x22d
net/http.HandlerFunc.ServeHTTP(0xc0000c1100?, {0x4289a30?, 0xc00140cee0?}, 0xc000094c00?)
    net/http/server.go:2122 +0x2f
github.com/go-chi/chi/v5/middleware.RealIP.func1({0x4289a30, 0xc00140cee0}, 0xc0000c1100)
    github.com/go-chi/chi/v5@v5.0.8/middleware/realip.go:36 +0x9e
net/http.HandlerFunc.ServeHTTP(0x57080b?, {0x4289a30?, 0xc00140cee0?}, 0x428b350?)
    net/http/server.go:2122 +0x2f
github.com/owncloud/ocis/v2/ocis-pkg/middleware.TraceContext.func1({0x4289a30, 0xc00140cee0}, 0xc0000c0f00)
    github.com/owncloud/ocis/v2/ocis-pkg/middleware/tracing.go:19 +0x184
net/http.HandlerFunc.ServeHTTP(0x0?, {0x4289a30?, 0xc00140cee0?}, 0x46f9d0?)
    net/http/server.go:2122 +0x2f
net/http.serverHandler.ServeHTTP({0xc0094f7110?}, {0x4289a30, 0xc00140cee0}, 0xc0000c0f00)
    net/http/server.go:2936 +0x316
net/http.(*conn).serve(0xc0091477a0, {0x428bf08, 0xc0017c4d20})
    net/http/server.go:1995 +0x612
created by net/http.(*Server).Serve
    net/http/server.go:3089 +0x5ed

Setup

Fresh installation via docker using `owncloud/ocis:latest` updated today.  Caddy proxy in front of container with the following config: ``` files.l1qu1d.net { import tls import sec import log # Compression encode zstd gzip reverse_proxy * { to https://ocis:9200 transport http { tls_insecure_skip_verify } } } ``` Auth handled by ZITADEL with the following config:  

[micbar]

seems to be an issue with the username. @rhafer Any ideas?

[rhafer]

@0x1a8510f2 Can you set GRAPH_LOG_LEVEL=debug and PROXY_LOG_LEVEL=debug and upload the logs after you rerun the test?

[0x1a8510f2]

Sure thing @rhafer. Currently on mobile so I wasn't able to get the complete log, but the below seems like the relevant bit.

Logs

``` 2023-05-10T10:50:24.222741000Z 2023-05-10T10:50:24.222536775Z DBG director found | service=proxy policy=ocis method=GET prefix=/ocs/ path=/ocs/v1.php/cloud/user routeType=prefix line=github.com/owncloud/ocis/v2/services/proxy/pkg/router/router.go:222 2023-05-10T10:50:24.222868000Z 2023-05-10T10:50:24.222642174Z DBG cache hit for userinfo | service=proxy claims={"email":"0x1a@l1qu1d.net","email_verified":true,"family_name":"8510f2","gender":"diverse","given_name":"0x1a","locale":"en","name":"0x1a8510f2","nickname":"0x1a","picture":"https://auth.l1qu1d.net/assets/v1//users//avatar?v=","preferred_username":"0x1a@l1qu1d.net","sub":"","updated_at":1673744610} line=github.com/owncloud/ocis/v2/services/proxy/pkg/middleware/oidc_auth.go:66 2023-05-10T10:50:24.223019000Z 2023-05-10T10:50:24.222663854Z DBG successfully authenticated request | service=proxy authenticator=oidc path=/ocs/v1.php/cloud/user line=github.com/owncloud/ocis/v2/services/proxy/pkg/middleware/oidc_auth.go:168 2023-05-10T10:50:24.224802000Z 2023-05-10T10:50:24.224587208Z DBG User by claim not found | service=proxy claim=preferred_username value=0x1a@l1qu1d.net line=github.com/owncloud/ocis/v2/services/proxy/pkg/middleware/account_resolver.go:71 2023-05-10T10:50:24.224958000Z 2023-05-10T10:50:24.22464116Z DBG Autoprovisioning user | service=proxy claims={"email":"0x1a@l1qu1d.net","email_verified":true,"family_name":"8510f2","gender":"diverse","given_name":"0x1a","locale":"en","name":"0x1a8510f2","nickname":"0x1a","picture":"https://auth.l1qu1d.net/assets/v1//users//avatar?v=","preferred_username":"0x1a@l1qu1d.net","sub":"","updated_at":1673744610} line=github.com/owncloud/ocis/v2/services/proxy/pkg/middleware/account_resolver.go:77 2023-05-10T10:50:24.225437000Z 2023-05-10T10:50:24.225266587Z INF calling create user | service=graph request-id=470af10e6bd5/Ugmysq5ojR-000085 body={} line=github.com/owncloud/ocis/v2/services/graph/pkg/service/v0/users.go:265 2023-05-10T10:50:24.225544000Z 2023-05-10T10:50:24.225322468Z DBG could not create user: username must be at least the local part of an email | service=graph request-id=470af10e6bd5/Ugmysq5ojR-000085 username=0x1a@l1qu1d.net line=github.com/owncloud/ocis/v2/services/graph/pkg/service/v0/users.go:281 2023-05-10T10:50:24.225629000Z 2023-05-10T10:50:24.225399198Z DBG service=graph request-id= proto=HTTP/1.1 method=POST status=400 path=/graph/v1.0/users duration=0.426486 bytes=208 line=github.com/owncloud/ocis/v2/ocis-pkg/middleware/logger.go:27 2023-05-10T10:50:24.225711000Z 2023-05-10T10:50:24.225561685Z ERR Error creating user | service=proxy error=400 Bad Request line=github.com/owncloud/ocis/v2/services/proxy/pkg/user/backend/cs3.go:174 2023-05-10T10:50:24.225869000Z 2023-05-10T10:50:24.225582384Z ERR Autoprovisioning user failed | service=proxy error=400 Bad Request line=github.com/owncloud/ocis/v2/services/proxy/pkg/middleware/account_resolver.go:80 ```

Let me know if you need more logs.

[rhafer]

Let me know if you need more logs.

@0x1a8510f2 Thanks, that should be enough. Ok, by default we require usernames to start with a letter. That's why the user creation fails. But it should definitely not cause a nil pointer panic. So there is a bug in the error handling somewhere.

You can switch of the username restrictions by setting GRAPH_USERNAME_MATCH=none. That would allow the user name you're using.

[0x1a8510f2]

Great, thanks for your help! Was able to log in successfully with GRAPH_USERNAME_MATCH=none. Leaving the issue open to track the error handling panic.

[mmattel]

@rhafer The envvar GRAPH_USERNAME_MATCH is described with Option to allow legacy usernames. Supported options are 'default' and 'none'.

Reading this context, the description is not sufficient, clear and needs a fix. Based on such a fix, we can add a note to the documentation to highlight this envvar.

[mmattel]

@rhafer ping, as offered, pls provide us with the required details so we can proceed