Hourly Login failed in owncloud.log

[wassereimer86]

Steps to reproduce

1. Unclear

Expected behaviour

No failed logins

Actual behaviour

Login failed messages in Log. Mostly hourly. Often at other times. From all users.

Server configuration

Operating system:
Ubuntu 22.04.2 LTS

Web server:
Apache

Database:
MariaDB 10.6.12

PHP version:
7.4.33

ownCloud version: (see ownCloud admin page)
10.11.0.6

Updated from an older ownCloud or fresh install:
Always updated as soon as new Version was available. Since years.

Where did you install ownCloud from:
Sources from Website

Signing status (ownCloud 9.0 and above):
No errors have been found.

The content of config/config.php:
https://gist.github.com/wassereimer86/b88e074850e24daa6d7f1dab5e7306f7

List of activated apps:
https://gist.github.com/wassereimer86/9f6ebb8b32ec8df457f4434d675c13fb

Are you using external storage, if yes which one: local/smb/sftp/...
no

Are you using encryption: yes/no
no

Are you using an external user-backend, if yes which one: LDAP/ActiveDirectory/Webdav/...
no

Client configuration

Not relevant because this happens to all users on different systems

Logs

Web server error log

Except for many "404 GET [/remote.php/dav/avatars/usernames/128.png] HTTP/1.0"" nothing interesting in there.

ownCloud log (data/owncloud.log)

Exemple:

{"reqId":"c680d52e-c283-4039-98e2-981a090b98c5","level":2,"time":"2023-04-28T10:28:57+02:00","remoteAddr":"***REMOVED SENSITIVE VALUE***","user":"***REMOVED SENSITIVE VALUE***","app":"core","method":"POST","url":"\/index.php\/apps\/oauth2\/api\/v1\/token","message":"Login failed: '***REMOVED SENSITIVE VALUE***' (Remote IP: '***REMOVED SENSITIVE VALUE***')"}
{"reqId":"7073cc71-224a-49e2-be05-47b26fa79a80","level":2,"time":"2023-04-28T11:28:58+02:00","remoteAddr":"***REMOVED SENSITIVE VALUE***","user":"***REMOVED SENSITIVE VALUE***","app":"core","method":"POST","url":"\/index.php\/apps\/oauth2\/api\/v1\/token","message":"Login failed: '***REMOVED SENSITIVE VALUE***' (Remote IP: '***REMOVED SENSITIVE VALUE***')"}
{"reqId":"3662e577-d5c1-4cff-8d31-bf4549e7593c","level":2,"time":"2023-04-28T12:28:59+02:00","remoteAddr":"***REMOVED SENSITIVE VALUE***","user":"***REMOVED SENSITIVE VALUE***","app":"core","method":"POST","url":"\/index.php\/apps\/oauth2\/api\/v1\/token","message":"Login failed: '***REMOVED SENSITIVE VALUE***' (Remote IP: '***REMOVED SENSITIVE VALUE***')"}
{"reqId":"e5ed8d79-0d4e-462a-9a45-277caee4e1dd","level":2,"time":"2023-04-28T13:29:30+02:00","remoteAddr":"***REMOVED SENSITIVE VALUE***","user":"***REMOVED SENSITIVE VALUE***","app":"core","method":"POST","url":"\/index.php\/apps\/oauth2\/api\/v1\/token","message":"Login failed: '***REMOVED SENSITIVE VALUE***' (Remote IP: '***REMOVED SENSITIVE VALUE***')"}
{"reqId":"538d7b50-f8c9-4e3e-bdb4-9bbf1cdce0bb","level":2,"time":"2023-04-28T14:30:01+02:00","remoteAddr":"***REMOVED SENSITIVE VALUE***,"user":"***REMOVED SENSITIVE VALUE***","app":"core","method":"POST","url":"\/index.php\/apps\/oauth2\/api\/v1\/token","message":"Login failed: '***REMOVED SENSITIVE VALUE***' (Remote IP: '***REMOVED SENSITIVE VALUE***')"}

Browser log

Not relevant because this happens to all users on different systems

[wassereimer86]

It's definitely the Windows Client. I activated logging and found it. But I don't know where exactly the problem is.

23-05-06 22:40:17:407 [ info gui.folder ]:	Trying to check "https://xxx/remote.php/dav/files/xxx/" for changes via ETag check. (time since last sync: 2749 s)
23-05-06 22:40:17:407 [ debug gui.folder.manager ]	[ OCC::FolderMan::slotRunOneEtagJob ]:	Scheduling "https://xxx/remote.php/dav/files/xxx/" to check remote ETag
23-05-06 22:40:17:407 [ info sync.httplogger ]:	"d262bd88-fc9c-4a33-abb2-cc783df8d2d3: Request: PROPFIND https://xxx/remote.php/dav/files/xxx/ Header: { Depth: 0, Prefer: return=minimal, Authorization: Bearer [redacted], User-Agent: Mozilla/5.0 (Windows) mirall/3.2.1.10355 (ownCloud, windows-10.0.22621 ClientArchitecture: x86_64 OsArchitecture: x86_64), Accept: */*, Content-Type: text/xml; charset=utf-8, X-Request-ID: d262bd88-fc9c-4a33-abb2-cc783df8d2d3, Original-Request-ID: d262bd88-fc9c-4a33-abb2-cc783df8d2d3, Content-Length: 108, Cookie: xxx; oc_sessionPassphrase=xxx, } Data: [<?xml version=\"1.0\" encoding=\"utf-8\"?><d:propfind xmlns:d=\"DAV:\"><d:prop><d:getetag/></d:prop></d:propfind>\n]"
23-05-06 22:40:17:407 [ info sync.networkjob ]:	Created OCC::RequestEtagJob(OCC::Account("xxx@xxx"), "https://xxx/remote.php/dav/files/xxx/", "PROPFIND", Original-Request-ID: "d262bd88-fc9c-4a33-abb2-cc783df8d2d3", X-Request-ID: "d262bd88-fc9c-4a33-abb2-cc783df8d2d3") for OCC::Folder(0x24d3e5ec1c0)
23-05-06 22:40:17:557 [ info sync.httplogger ]:	"d262bd88-fc9c-4a33-abb2-cc783df8d2d3: Response: PROPFIND 401 (Error: Der Host verlangt eine Authentifizierung,150ms) https://xxx/remote.php/dav/files/xxx/ Header: { Server: nginx, Date: Sat, 06 May 2023 20:40:17 GMT, Content-Type: application/xml; charset=utf-8, Transfer-Encoding: chunked, Connection: keep-alive, X-Powered-By: PHP/7.4.33, Expires: Thu, 19 Nov 1981 08:52:00 GMT, Cache-Control: no-store, no-cache, must-revalidate, Pragma: no-cache, Content-Security-Policy: default-src 'none';, WWW-Authenticate: Bearer realm=\"ownCloud\", Basic realm=\"ownCloud\", charset=\"UTF-8\", Set-Cookie: oc_sessionPassphrase=xxx; expires=Sat, 06-May-2023 21:00:17 GMT; Max-Age=1200; path=/; secure; HttpOnly; SameSite=Strict, X-Content-Type-Options: nosniff, X-XSS-Protection: 0, X-Robots-Tag: none, X-Frame-Options: SAMEORIGIN, X-Download-Options: noopen, X-Permitted-Cross-Domain-Policies: none, Strict-Transport-Security: max-age=15768000; includeSubDomains, } Data: [<?xml version=\"1.0\" encoding=\"utf-8\"?>\n<d:error xmlns:d=\"DAV:\" xmlns:s=\"http://sabredav.org/ns\">\n  <s:exception>Sabre\\DAV\\Exception\\NotAuthenticated</s:exception>\n  <s:message>No public access to this resource., Bearer token was incorrect, No 'Authorization: Basic' header found. Either the client didn't send one, or the server is misconfigured</s:message>\n</d:error>\n]"
23-05-06 22:40:17:557 [ debug sync.credentials.http ]	[ OCC::HttpCredentials::slotAuthentication ]:	void __cdecl OCC::HttpCredentials::slotAuthentication(class QNetworkReply *,class QAuthenticator *) QNetworkReplyHttpImpl(0x24d40f194d0)
23-05-06 22:40:17:557 [ warning sync.credentials.http ]:	Stop request: Authentication failed for  "https://xxx/remote.php/dav/files/xxx/" "d262bd88-fc9c-4a33-abb2-cc783df8d2d3"
23-05-06 22:40:17:557 [ info sync.credentials.http ]:	Refreshing token

[wassereimer86]

I am now testing if it is related to: https://doc.owncloud.com/server/next/admin_manual/troubleshooting/general_troubleshooting.html#owncloud-clients-cannot-connect-to-the-owncloud-server

[wassereimer86]

No, that wasn´t the solution. Still getting failed logins.

[wassereimer86]

Any ideas?

[VicDeo]

@wassereimer86 I guess the auth token is expiring and then being automatically refreshed by client.

[wassereimer86]

But that shouldn't result in failed Login Attempts, or?

[VicDeo]

Login attempt using expired oauth token is a failed login attempt.

[cortho]

@VicDeo how does this affect the brute_force_protection app?

Let's say a single user account has got a lots of clients connected on desktop computers and mobile devices and brute force settings are like https://doc.owncloud.com/server/next/admin_manual/configuration/server/security/brute_force_protection.html : ban after 3 failed login attempts within 60 seconds.

So if three of the clients have got expired oauth tokens within one minute all clients would be blocked?

[michaelstingl]

So if three of the clients have got expired oauth tokens within one minute all clients would be blocked?

Only when they're from the same originating IP address I'd say, but I have no prior experience with brut force protection, sorry.

I'd need to have a look at more lines in the desktop log. Posted lines doesn't include [ info sync.httplogger ] from the token renewal.