`408 Request timeout` error on file upload

alyaeanyx commented 8 months ago

⚠️ Before posting ⚠️

[X] This is a bug, not a question or an enhancement.
[X] I've searched for similar issues and didn't find a duplicate.
[X] I've written a clear and descriptive title for this issue, not just "Bug" or "Crash".
[X] I agree to follow Nextcloud's Code of Conduct.

Steps to reproduce

The error occurs while uploading a file via the Nextcloud app. I do not know how to reproduce it, as it was just reported to me by one of the users of my Nextcloud server.

Expected behaviour

The file upload should succeed, and the PUT request to the /remote.php/dav/files/<path> endpoint return with status code 201.

Actual behaviour

After 30s-60s, the upload fails with the following error message: Restarting the upload yields the same error most of the time, until it randomly succeeds after 10-20 retries.

Uploading the file via the Nextcloud webinterface works flawlessly.

The Nginx reverse proxy log is attached.

Android version

13 (lineage_pdx214-userdebug 13 TQ3A.230901.001 eng.root.20231212.172335 dev-keys)

Device brand and model

Sony Xperia 5 III

Stock or custom OS?

Custom (explain in "additional information")

Nextcloud android app version

3.26.0

Nextcloud server version

27.1.5

Using a reverse proxy?

Yes

Android logs

No response

Server error logs

Nginx:
220.135.71.106 - Alexander [05/Jan/2024:22:05:10 +0000] "HEAD /remote.php/dav/files/Alexander/Alexander/02%20Bilder/01%20Bilder/202x/2024_01%20Taipeh%20und%20Bangkok/01.%20-%2002.%20PVG/20240101_132708.JPG HTTP/1.1" 404 0 "-" "Mozilla/5.0
 (Android) Nextcloud-android/3.26.0"
220.135.71.106 - Alexander [05/Jan/2024:22:06:24 +0000] "PUT /remote.php/dav/files/Alexander/Alexander/02%20Bilder/01%20Bilder/202x/2024_01%20Taipeh%20und%20Bangkok/01.%20-%2002.%20PVG/20240101_132708.JPG HTTP/1.1" 408 0 "-" "Mozilla/5.0 
(Android) Nextcloud-android/3.26.0"

Additional information

The Android app is running on LineageOS, and the Nextcloud server on NixOS unstable.

Nginx config:

                location ~ \.php(?:$|/) {
                        # legacy support (i.e. static files and directories in cfg.package)
                        rewrite ^/(?!index|remote|public|cron|core\/ajax\/update|status|ocs\/v[12]|updater\/.+|oc[s]-provider\/.+|.+\/richdocumentscode\/proxy) /index.php$request_uri;
                        include /nix/store/4595gizbhh4grdynsb4pv8d0zhi09dqw-nginx-1.24.0/conf/fastcgi.conf;
                        fastcgi_split_path_info ^(.+?\.php)(\\/.*)$;
                        set $path_info $fastcgi_path_info;
                        try_files $fastcgi_script_name =404;
                        fastcgi_param PATH_INFO $path_info;
                        fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
                        fastcgi_param HTTPS on;
                        fastcgi_param modHeadersAvailable true;
                        fastcgi_param front_controller_active true;
                        fastcgi_pass unix:/run/phpfpm/nextcloud.sock;
                        fastcgi_intercept_errors on;
                        fastcgi_request_buffering off;
                        fastcgi_read_timeout 120s;
                }

I am unable to post logcat logs because the person experiencing the bug is on the other side of the planet, without a computer that can run adb.

joshtrichards commented 8 months ago

Hi @alyaeanyx - Maybe I'm missing something, but what does this have to do with the client?

The 408 is coming from the server-side. Not much the client can do about that.

I'd suggest checking the following for clues:

your Nextcloud Server log
your server's PHP-FPM log

That path though does look a little weird though. Is the duplication legit? /Alexander/Alexander/

alyaeanyx commented 8 months ago

Hi,

as mentioned in the PR, the error doesn't occur when uploading files via the webinterface - that's why I filed the issue here. I suspect that there might be some sort of rare condition that causes the Android client to delay the transmission of the HTTP body.

joshtrichards commented 8 months ago

Okay, I admit I was totally thinking of a gateway timeout (504) when I wrote that oops!

It still would be useful to see the Nextcloud Server log entries as well as the FPM log for the same period in case part of the issue is something unexpected being sent to the client before the timeout.

Any idea if the duplicate string in the path being sent by the client is valid?

alyaeanyx commented 8 months ago

- The duplicate string in the path is valid - there is indeed a directory called Alexander in the files of the user Alexander.

Relevant entry from phpfpm log:

Jan 05 22:06:24 aidoskyneen Nextcloud[2352114]: {"reqId":"RjkwrVm4NRh0Rsq1MbGM","level":3,"time":"2024-01-05T22:06:24+00:00","remoteAddr":"220.135.71.106","user":"Alexander","app":"no app in context","method":"PUT","url":"/remote.php/dav/files/Alexander/Alexander/02%20Bilder/01%20Bilder/202x/2024_01%20Taipeh%20und%20Bangkok/01.%20-%2002.%20PVG/20240101_132708.JPG","message":"{\"Exception\":\"Sabre\\\\DAV\\\\Exception\\\\BadRequest\",\"Message\":\"Expected filesize of 2603272 bytes but read (from Nextcloud client) and wrote (to Nextcloud storage) 335872 bytes. Could either be a network problem on the sending side or a problem writing to the storage on the server side.\",\"Code\":0,\"Trace\":[{\"file\":\"/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/apps/dav/lib/Connector/Sabre/Directory.php\",\"line\":149,\"function\":\"put\",\"class\":\"OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File\",\"type\":\"->\"},{\"file\":\"/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/3rdparty/sabre/dav/lib/DAV/Server.php\",\"line\":1098,\"function\":\"createFile\",\"class\":\"OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory\",\"type\":\"->\",\"args\":[\"*** sensitive parameters replaced ***\"]},{\"file\":\"/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/3rdparty/sabre/dav/lib/DAV/CorePlugin.php\",\"line\":504,\"function\":\"createFile\",\"class\":\"Sabre\\\\DAV\\\\Server\",\"type\":\"->\",\"args\":[\"*** sensitive parameters replaced ***\"]},{\"file\":\"/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/3rdparty/sabre/event/lib/WildcardEmitterTrait.php\",\"line\":89,\"function\":\"httpPut\",\"class\":\"Sabre\\\\DAV\\\\CorePlugin\",\"type\":\"->\"},{\"file\":\"/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/3rdparty/sabre/dav/lib/DAV/Server.php\",\"line\":472,\"function\":\"emit\",\"class\":\"Sabre\\\\DAV\\\\Server\",\"type\":\"->\"},{\"file\":\"/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/3rdparty/sabre/dav/lib/DAV/Server.php\",\"line\":253,\"function\":\"invokeMethod\",\"class\":\"Sabre\\\\DAV\\\\Server\",\"type\":\"->\"},{\"file\":\"/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/3rdparty/sabre/dav/lib/DAV/Server.php\",\"line\":321,\"function\":\"start\",\"class\":\"Sabre\\\\DAV\\\\Server\",\"type\":\"->\"},{\"file\":\"/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/apps/dav/lib/Server.php\",\"line\":365,\"function\":\"exec\",\"class\":\"Sabre\\\\DAV\\\\Server\",\"type\":\"->\"},{\"file\":\"/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/apps/dav/appinfo/v2/remote.php\",\"line\":35,\"function\":\"exec\",\"class\":\"OCA\\\\DAV\\\\Server\",\"type\":\"->\"},{\"file\":\"/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/remote.php\",\"line\":172,\"args\":[\"/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/apps/dav/appinfo/v2/remote.php\"],\"function\":\"require_once\"}],\"File\":\"/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/apps/dav/lib/Connector/Sabre/File.php\",\"Line\":297,\"message\":\"Expected filesize of 2603272 bytes but read (from Nextcloud client) and wrote (to Nextcloud storage) 335872 bytes. Could either be a network problem on the sending side or a problem writing to the storage on the server side.\",\"exception\":{},\"CustomMessage\":\"Expected filesize of 2603272 bytes but read (from Nextcloud client) and wrote (to Nextcloud storage) 335872 bytes. Could either be a network problem on the sending side or a problem writing to the storage on the server side.\"}","userAgent":"Mozilla/5.0 (Android) Nextcloud-android/3.26.0","version":"27.1.5.1"}

message field prettified:

{
"Exception": "Sabre\\DAV\\Exception\\BadRequest",
"Message": "Expected filesize of 2603272 bytes but read (from Nextcloud client) and wrote (to Nextcloud storage) 335872 bytes. Could either be a network problem on the sending side or a problem writing to the storage on the server side.",
"Code": 0,
"Trace": [
{
"file": "/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/apps/dav/lib/Connector/Sabre/Directory.php",
"line": 149,
"function": "put",
"class": "OCA\\DAV\\Connector\\Sabre\\File",
"type": "->"
},
{
"file": "/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/3rdparty/sabre/dav/lib/DAV/Server.php",
"line": 1098,
"function": "createFile",
"class": "OCA\\DAV\\Connector\\Sabre\\Directory",
"type": "->",
"args": [
"*** sensitive parameters replaced ***"
]
},
{
"file": "/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/3rdparty/sabre/dav/lib/DAV/CorePlugin.php",
"line": 504,
"function": "createFile",
"class": "Sabre\\DAV\\Server",
"type": "->",
"args": [
"*** sensitive parameters replaced ***"
]
},
{
"file": "/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/3rdparty/sabre/event/lib/WildcardEmitterTrait.php",
"line": 89,
"function": "httpPut",
"class": "Sabre\\DAV\\CorePlugin",
"type": "->"
},
{
"file": "/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/3rdparty/sabre/dav/lib/DAV/Server.php",
"line": 472,
"function": "emit",
"class": "Sabre\\DAV\\Server",
"type": "->"
},
{
"file": "/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/3rdparty/sabre/dav/lib/DAV/Server.php",
"line": 253,
"function": "invokeMethod",
"class": "Sabre\\DAV\\Server",
"type": "->"
},
{
"file": "/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/3rdparty/sabre/dav/lib/DAV/Server.php",
"line": 321,
"function": "start",
"class": "Sabre\\DAV\\Server",
"type": "->"
},
{
"file": "/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/apps/dav/lib/Server.php",
"line": 365,
"function": "exec",
"class": "Sabre\\DAV\\Server",
"type": "->"
},
{
"file": "/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/apps/dav/appinfo/v2/remote.php",
"line": 35,
"function": "exec",
"class": "OCA\\DAV\\Server",
"type": "->"
},
{
"file": "/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/remote.php",
"line": 172,
"args": [
"/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/apps/dav/appinfo/v2/remote.php"
],
"function": "require_once"
}
],
"File": "/nix/store/8v71sprzg7zc9plyqhdym76x16z333m2-nextcloud-27.1.5/apps/dav/lib/Connector/Sabre/File.php",
"Line": 297,
"message": "Expected filesize of 2603272 bytes but read (from Nextcloud client) and wrote (to Nextcloud storage) 335872 bytes. Could either be a network problem on the sending side or a problem writing to the storage on the server side.",
"exception": {},
"CustomMessage": "Expected filesize of 2603272 bytes but read (from Nextcloud client) and wrote (to Nextcloud storage) 335872 bytes. Could either be a network problem on the sending side or a problem writing to the storage on the server side."
}

Unfortunately, up until now, the logfile setting of my Nextcloud instance was pointing to a non-existent directory, so no logs were recorded. Sorry for that!! I've fixed it now, and I will attach the relevant exerpts from the Nextcloud log once the error occurs again.

alyaeanyx commented 8 months ago

Oh, and looking at the FPM logs, the number of read bytes is always either 335872 bytes or 344064 for this file.

stoamandl commented 7 months ago

Hi @joshtrichards , same problem with NC 27.1.6 and Android App 3.27.0 on Pixel7 Android14 (no root). Upload via the App breaks with always missing one byte. Always the same Picture. It doesn't matter if I upload it via auto upload or manually.

[no app in context] Fehler: Sabre\DAV\Exception\BadRequest: Erwartete Dateigröße von 11771905 bytes, aber 11771904 bytes gelesen (vom Nextcloud-Client) und geschrieben (in den Nextcloud-Speicher). Dies kann entweder ein Netzwerkproblem auf der sendenden Seite oder ein Problem beim Schreiben in den Speicher auf der Serverseite sein. at <>

/home/binaryfour/domains/ sensitive parameters replaced /public_html/apps/dav/lib/Connector/Sabre/Directory.php line 149 OCA\DAV\Connector\Sabre\File->put()
/home/binaryfour/domains/ sensitive parameters replaced /public_html/apps/dav/lib/Upload/UploadFolder.php line 50 OCA\DAV\Connector\Sabre\Directory->createFile(" sensitive parameters replaced ")
/home/binaryfour/domains/ sensitive parameters replaced /public_html/3rdparty/sabre/dav/lib/DAV/Server.php line 1098 OCA\DAV\Upload\UploadFolder->createFile(" sensitive parameters replaced ")
/home/binaryfour/domains/ sensitive parameters replaced /public_html/3rdparty/sabre/dav/lib/DAV/CorePlugin.php line 504 Sabre\DAV\Server->createFile(" sensitive parameters replaced ")
/home/binaryfour/domains/ sensitive parameters replaced /public_html/3rdparty/sabre/event/lib/WildcardEmitterTrait.php line 89 Sabre\DAV\CorePlugin->httpPut()
/home/binaryfour/domains/ sensitive parameters replaced /public_html/3rdparty/sabre/dav/lib/DAV/Server.php line 472 Sabre\DAV\Server->emit()
/home/binaryfour/domains/ sensitive parameters replaced /public_html/3rdparty/sabre/dav/lib/DAV/Server.php line 253 Sabre\DAV\Server->invokeMethod()
/home/binaryfour/domains/ sensitive parameters replaced /public_html/3rdparty/sabre/dav/lib/DAV/Server.php line 321 Sabre\DAV\Server->start()
/home/binaryfour/domains/ sensitive parameters replaced /public_html/apps/dav/lib/Server.php line 365 Sabre\DAV\Server->exec()
/home/binaryfour/domains/ sensitive parameters replaced /public_html/apps/dav/appinfo/v2/remote.php line 35 OCA\DAV\Server->exec()
1. /home/binaryfour/domains/ sensitive parameters replaced /public_html/remote.php line 172 require_once("/home/ sensitive parameters replaced ... p")

The strange thing is, I can easily upload other pictures that are bigger or smaller.

stoamandl commented 7 months ago

@joshtrichards i tried the last Nextcloud DEV Version from fDroid (20240213) with the same error. At first I thought it had something to do with the chunk size you can set in apache. I set the size to 0. And restarted the Service. With the same result. Should I provide more data to help you?

nextcloud / android