Desktop: Server flooded with requests from 2.5.0 client (activity)

[klada]

Version 2.5.0 of the Nextcloud client bombs the server with requests to /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json.

I am seeing up to 16 requests per second per user with the new client, this is way too much. The new client can bring down a home server easily with just a few users. Even in larger environments this can be problematic, as there are potentially even more users.

The strange part is that not all 2.5.0 clients cause this amount of traffic. Some clients (including the one I am using) only hit the activity endpoint once a minute.

First of all, this is the relevant client identifier from the server log:

Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)

After locking out this one client (return 403 for this source IP) the client hit the server with 150 requests/second.

I can tell for sure that this is not an attack, it is definitely a faulty client. Maybe someone could check the code path for polling the activity log how this can happen.

Expected behaviour

The client should only poll once a minute (like in older releases).

Actual behaviour

_Some_ 2.5.0 clients poll without sleeping in between, up to 150 times a second in my case.

Steps to reproduce

I am not sure, as I do not have that particular client under my control.

Client configuration

Client version: 2.5.0

Operating system: Windows

Server configuration

Operating system: CentOS 7.5

Web server: Apache 2.4.6-80

Database: Postgres

PHP version:7.2.12

Nextcloud version: 14.0.3

Storage backend (external storage): -

Logs

1. Client logfile: Output of nextcloud --logwindow or nextcloud --logfile log.txt
   (On Windows using cmd.exe, you might need to first cd into the Nextcloud directory)
   (See also https://docs.nextcloud.com/desktop/2.3/troubleshooting.html#log-files)

2. Web server access log:

192.168.12.9 - user12 [15/Nov/2018:14:56:07 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0
192.168.12.9 - user12 [15/Nov/2018:14:56:08 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0
192.168.12.9 - user12 [15/Nov/2018:14:56:08 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0
192.168.12.9 - user12 [15/Nov/2018:14:56:08 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0
192.168.12.9 - user12 [15/Nov/2018:14:56:08 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0
192.168.12.9 - user12 [15/Nov/2018:14:56:08 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0
192.168.12.9 - user12 [15/Nov/2018:14:56:08 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0
192.168.12.9 - user12 [15/Nov/2018:14:56:08 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0
192.168.12.9 - user12 [15/Nov/2018:14:56:08 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0
192.168.12.9 - user12 [15/Nov/2018:14:56:08 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0
192.168.12.9 - user12 [15/Nov/2018:14:56:08 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0
192.168.12.9 - user12 [15/Nov/2018:14:56:08 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0
192.168.12.9 - user12 [15/Nov/2018:14:56:08 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0
192.168.12.9 - user12 [15/Nov/2018:14:56:08 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0
192.168.12.9 - user12 [15/Nov/2018:14:56:08 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0
192.168.12.9 - user12 [15/Nov/2018:14:56:08 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0
192.168.12.9 - user12 [15/Nov/2018:14:56:08 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0
192.168.12.9 - user12 [15/Nov/2018:14:56:09 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0
192.168.12.9 - user12 [15/Nov/2018:14:56:09 +0100] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)" 0

[rullzer]

Thanks for the detailed report.
I'll see if I can reproduce this.

[dinkonin]

Same problem on
Server configuration
Operating system: Arch
Web server: nginx/1.14.1
Database: mariadb
PHP version: 7.2.12
Redis: 5.0.1
Nextcloud version: 14.0.3

There are thousands of lines like this in nginx log
```
10.1.1.10 - user [16/Nov/2018:11:08:45 +0200] "GET /ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json HTTP/2.0" 404 0 "-" "Mozilla/5.0 (Windows) mirall/2.5.0v2.5.0 (build 20181112) (Nextcloud)"
````
The server CPU is at 100%

Reverting to client v2.3.3 fixes it.

[gaetandossantos]

We have the same flood problem but we have enable the activity app.
We are on nextcloud 13.0.6.

The problem occurs with client mirall/2.5.0v2.5.0 (build 20181112)

Is there an other problem?

[klada]

I don't see how #859 fixes this. I also have the activity app enabled, so I think the requests are caused by something else. You can also see from my logs that the client actually gets a HTTP 200 reply.

And even if activities are fetched when they should not, why is this being done 150 times per second? There must be something seriously wrong with a polling interval or a timer here.

[rullzer]

There is indeed another issue. I am looking into it. but i can't trigger it reliably locally. Once I do I'll see if I can come up with a fix.

[madpilot78]

I was seeing the original issue because I had the activity tab disabled. Enabling it I stumbled in the issue described in by @klada.

I recompiled the client importing the patch in #859 and while it's not flooding the server anymore I now see the client hogging the CPU in a tight loop. Nothing is written in the log but it keeps running on a CPU core. This when the activity app is disabled.

If it is enabled the log window is flooded with messages like:

[OCC::AbstractNetworkJob::start OCC::JsonApiJob created for "https://URL/" + "ocs/v2.php/cloud/activity" "OCC::ActivityListModel"
[OCC::WebFlowCredentials::slotFinished request finished
[OCC::WebFlowCredentials::stillValid Still valid?
[OCC::WebFlowCredentials::stillValid QNetworkReply::NetworkError(NoError)
[OCC::WebFlowCredentials::stillValid "Unknown error"
[OCC::JsonApiJob::finished JsonApiJob of QUrl("https://URL/ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json") FINISHED WITH STATUS "OK"
[OCC::ActivityListModel::startFetchJob Start fetching activities for "USER@URL"
[OCC::AccessManager::createRequest 2 "" "https://URL/ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json" has X-Request-ID "80bfab60-3e97-48e1-8314-d67782fb2485"
[OCC::AbstractNetworkJob::start OCC::JsonApiJob created for "https://URL/" + "ocs/v2.php/cloud/activity" "OCC::ActivityListModel"
[OCC::ActivityListModel::startFetchJob Start fetching activities for "USER@URL"
[OCC::AccessManager::createRequest 2 "" "https://URL/ocs/v2.php/cloud/activity?page=0&pagesize=100&format=json" has X-Request-ID "21296182-9e52-4fa1-b6b5-1486dd40bccd"

Interesting thing is if I open the client window, go to the activity screen and then the General one, it stops hogging he CPU. It starts doing that again if some activity happens (file added or removed, for example).

Hope this information helps.

[rullzer]

I think https://github.com/nextcloud/desktop/pull/874 fixes this.

[madpilot78]

Yes, applying #874 the problem disappears. Thank you!