nextcloud
[Bug]: One user and only that user account fails to load its files
⚠️ This issue respects the following points: ⚠️
- [X] This is a bug, not a question or a configuration/webserver/proxy issue.
- [X] This issue is not already reported on Github OR Nextcloud Community Forum (I've searched it).
- [X] Nextcloud Server is up to date. See Maintenance and Release Schedule for supported versions.
- [X] I agree to follow Nextcloud's Code of Conduct.
Bug description
It seems that one user, and only that user (happens to be me) cannot access its files from the web. When logging in the files app just displays a spinning circle for a while before ending with "No files could be found". Attempting to create a file fails. The files are all there on the server (checking the data storage folder), and existing sync seems to still work:
- Desktop app is successfully syncing one folder set up earlier, adding new folder works after waiting for a very long time at listing remote folders
- Keepass2Android is also successfully syncing a keepass file
- Les Pas app also seems to manage to sync
- Notes app in the web loads its notes
- Nextcloud app seems to manage to sync but extremely slowly (spinner shows for 3+mins when opening the app)
- Gallery app shows images but it takes a couple of minutes until it appears.
The weirdest part is that seemingly all other users don't have any issues, files load fast. This includes new users created just to test after issue was found.
occ files:scan was performed for the user (--all)
It not very clear when exactly the issue appeared, as the files where not accessed frequently, just the notes during the timeframe. However I noted that the files started loading very slowly before it stopped entirely. During the time-frame the server was being prepared for migration to new hardware, which really only included two things:
- removing the portforward to the server, as a reverse proxy was being set up, during which the account in question (that is an admin) was accessing the instance over LAN
- updating the nextcloud to the latest version.
The instance is spewing out issues, as will be seen below, but I'm having a hard time solving anything from them. The logs are cut to this year's, during which almost exclusively the problematic account "Rinkana" was logged in (exception when other accounts tested their file access). And to my untrained eye most of the logs stem from that user. The problem was found approx in the middle of january, after the update to nc28.
I have tested copying all of the problematic accounts files to a new account, followed by a occ files:scan on that account. The problem does not occur on the new account, everything is very snappy. Here is the difference in occ:files scan directly after moving the files from the troubled account to a new test acc:
Starting scan for user 1 out of 1 (nyadmin)
+---------+-------+-----+---------+---------+--------+--------------+
| Folders | Files | New | Updated | Removed | Errors | Elapsed time |
+---------+-------+-----+---------+---------+--------+--------------+
| 215 | 11348 | 0 | 11558 | 7 | 0 | 00:00:20 |
+---------+-------+-----+---------+---------+--------+--------------+
bash-4.4$ php occ files:scan Rinkana
Starting scan for user 1 out of 1 (Rinkana)
+---------+-------+-----+---------+---------+--------+--------------+
| Folders | Files | New | Updated | Removed | Errors | Elapsed time |
+---------+-------+-----+---------+---------+--------+--------------+
| 560 | 15061 | 0 | 1 | 0 | 0 | 00:05:11 |
+---------+-------+-----+---------+---------+--------+--------------+
I only moved the files, not files_versions, cache or trash bin etc. - the difference in files count is probably there? Could some of those folders be the problem? They don't look very troubling in size:
bash-4.4$ du -sh *
4.0K cache
271G files
46G files_trashbin
9.9G files_versions
40K uploads
I suspect something is wrong in the database for the user? I ran some of the maintenance occ commands without any success..
Steps to reproduce
I don't think this is easily reproducible for others, but on my instance and that user account it is a problem since it began little more than two weeks ago.
- Log in as user A -> files work and load fast
- Log in as user B -> spinning circle for a long time before "No files could be found".
- Check server, files are there.
occ files:scandoes not help if step 2 is repeated. - Copy files from troubled acc to a new test-acc -> everything is fast in the new acc..
Expected behavior
All users can access their files fast and snappy
Installation method
Community Manual installation with Archive
Nextcloud Server version
28
Operating system
RHEL/CentOS
PHP engine version
PHP 8.1
Web server
Apache (supported)
Database engine version
MariaDB
Is this bug present after an update or on a fresh install?
Upgraded to a MAJOR version (ex. 22 to 23)
Are you using the Nextcloud Server Encryption module?
Encryption is Disabled
What user-backends are you using?
- [X] Default user-backend (database)
- [ ] LDAP/ Active Directory
- [ ] SSO - SAML
- [ ] Other
Configuration report
{
"system": {
"instanceid": "***REMOVED SENSITIVE VALUE***",
"passwordsalt": "***REMOVED SENSITIVE VALUE***",
"secret": "***REMOVED SENSITIVE VALUE***",
"trusted_domains": [
"10.42.3.36",
"xn--skmolnet-8za.aftt.eu",
"\u00e5skmolnet.aftt.eu"
],
"datadirectory": "***REMOVED SENSITIVE VALUE***",
"dbtype": "mysql",
"version": "28.0.1.1",
"overwrite.cli.url": "https:\/\/10.42.3.36\/",
"dbname": "***REMOVED SENSITIVE VALUE***",
"dbhost": "***REMOVED SENSITIVE VALUE***",
"dbport": "",
"dbtableprefix": "oc_",
"mysql.utf8mb4": true,
"dbuser": "***REMOVED SENSITIVE VALUE***",
"dbpassword": "***REMOVED SENSITIVE VALUE***",
"installed": true,
"log_type": "file",
"loglevel": 3,
"simpleSignUpLink.shown": false,
"logtimezone": "Europe\/Stockholm",
"default_phone_region": "SE",
"default_language": "sv",
"default_locale": "sv_SE",
"skeletondirectory": "\/var\/www\/html\/skeleton\/custom-skeleton",
"templatedirectory": "\/var\/www\/html\/skeleton\/custom-templates",
"enabledPreviewProviders": [
"OC\\Preview\\PNG",
"OC\\Preview\\JPEG",
"OC\\Preview\\GIF",
"OC\\Preview\\BMP",
"OC\\Preview\\XBitmap",
"OC\\Preview\\MP3",
"OC\\Preview\\TXT",
"OC\\Preview\\MarkDown",
"OC\\Preview\\OpenDocument",
"OC\\Preview\\Krita",
"OC\\Preview\\Movie"
],
"token_auth_enforced": true,
"htaccess.RewriteBase": "\/",
"memcache.local": "\\OC\\Memcache\\APCu",
"memcache.distributed": "\\OC\\Memcache\\Redis",
"memcache.locking": "\\OC\\Memcache\\Redis",
"filelocking.enabled": "true",
"redis": {
"host": "***REMOVED SENSITIVE VALUE***",
"port": 0
},
"mail_smtpmode": "smtp",
"mail_smtpsecure": "ssl",
"mail_sendmailmode": "smtp",
"mail_smtpauthtype": "LOGIN",
"mail_from_address": "***REMOVED SENSITIVE VALUE***",
"mail_domain": "***REMOVED SENSITIVE VALUE***",
"mail_smtpauth": 1,
"mail_smtphost": "***REMOVED SENSITIVE VALUE***",
"mail_smtpname": "***REMOVED SENSITIVE VALUE***",
"mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
"mail_smtpport": "465",
"maintenance": false,
"integrity.check.disabled": false,
"theme": "",
"app_install_overwrite": [
"maps"
]
}
}
List of activated Apps
Enabled:
- activity: 2.20.0
- admin_audit: 1.18.0
- calendar: 4.6.4
- camerarawpreviews: 0.8.4
- checksum: 1.2.3
- circles: 28.0.0-dev
- cloud_federation_api: 1.11.0
- comments: 1.18.0
- contacts: 5.5.1
- dav: 1.29.1
- federatedfilesharing: 1.18.0
- federation: 1.18.0
- files: 2.0.0
- files_accesscontrol: 1.18.0
- files_automatedtagging: 1.18.0
- files_external: 1.20.0
- files_pdfviewer: 2.9.0
- files_reminders: 1.1.0
- files_sharing: 1.20.0
- files_trashbin: 1.18.0
- files_versions: 1.21.0
- fileslibreofficeedit: 1.1.0
- firstrunwizard: 2.17.0
- forms: 4.0.0
- logreader: 2.13.0
- lookup_server_connector: 1.16.0
- maps: 1.3.1
- notes: 4.9.2
- notifications: 2.16.0
- oauth2: 1.16.3
- password_policy: 1.18.0
- photos: 2.4.0
- privacy: 1.12.0
- provisioning_api: 1.18.0
- recommendations: 2.0.0
- registration: 2.3.0
- related_resources: 1.3.0
- serverinfo: 1.18.0
- settings: 1.10.1
- sharebymail: 1.18.0
- systemtags: 1.18.0
- text: 3.9.1
- theming: 2.3.0
- twofactor_backupcodes: 1.17.0
- updatenotification: 1.18.0
- viewer: 2.2.0
- workflowengine: 2.10.0
Disabled:
- appointments: 1.15.5 (installed 1.15.5)
- bruteforcesettings: 2.8.0 (installed 2.4.0)
- contactsinteraction: 1.9.0 (installed 1.2.0)
- dashboard: 7.8.0 (installed 7.2.0)
- encryption: 2.16.0
- nextcloud_announcements: 1.17.0 (installed 1.11.0)
- previewgenerator: 5.4.0 (installed 5.4.0)
- support: 1.11.0 (installed 1.5.0)
- survey_client: 1.16.0 (installed 1.10.0)
- suspicious_login: 6.0.0
- twofactor_totp: 10.0.0-beta.2
- user_ldap: 1.19.0
- user_status: 1.8.1 (installed 1.2.0)
- weather_status: 1.8.0 (installed 1.1.0)
Nextcloud Signing status
No errors have been found.
Nextcloud Logs
Log was too long, will provide file with this month's logs.
Additional info
No response
The promised logfiles are attached here. Some rows are ridicolously long. I just ran tail -n +20042 nextcloud.log > test.log
The logs are not very telling. Some errors related to dns failure, some from the maps app and the photos app - but none looks related to what you are describing. Could you take a screenshot of the web developer console when loading the file list? This might be a duplicate of #43269
Yeah I felt the same when browsing the logs..
Here is the console filtered to errors:
The propfind error:
Sorry forgot so switch to English, but most messages already are so I hope it's okay.
It just seems the files load so slowly the web times out, so I guess its about finding out why this user has so slow file loads (especially since copying all files to a new test acc has very performant loads..).
Some additional information I gained while testing yesterday is: The trash-bin manages to load its files. Clearing the ~40 GB there didn't do any difference. Latest files and favourites manage to load but very slow (approx 2min+) Shares fail to display any shares Tags load rather quick, but clicking on any while it eventually shows files it again takes a very long time. The account only has notes tagged.
The test account that had the same files copied to it loads in <1s after the background loads over the local network.
Well... the logs migth be interesting after all. Your console also looks like it's a 500 response to the PROPFIND that causes the trouble. There are a lot of such errors in the logs. They fall in two categories:
- dns failures - could you make sure your server can reach a DNS server?
- maps app errors (see below) - please check if disabling the maps app fixes the issue. The error also points to some code path that might be worth investigating:
{
"reqId": "ZayHOnk@URiJbJx2t83bDAAAAEo",
"level": 4,
"time": "2024-01-21T03:53:46+01:00",
"remoteAddr": "185.65.134.246",
"user": "Rinkana",
"app": "no app in context",
"method": "PROPFIND",
"url": "/remote.php/dav/files/Rinkana/Filijonken",
"message": "Could not boot maps: Call to undefined method OC\\Server::getEventDispatcher()",
"userAgent": "Mozilla/5.0 (Linux) mirall/3.11.0git (Nextcloud, fedora-6.6.11-200.fc39.x86_64 ClientArchitecture: x86_64 OsArchitecture: x86_64)",
"version": "28.0.1.1",
"exception": {
"Exception": "Error",
"Message": "Call to undefined method OC\\Server::getEventDispatcher()",
"Code": 0,
"Trace": [
{
"file": "/var/www/html/nextcloud/apps/maps/lib/AppInfo/Application.php",
"line": 88,
"function": "registerFeaturePolicy",
"class": "OCA\\Maps\\AppInfo\\Application",
"type": "->"
},
{
"file": "/var/www/html/nextcloud/lib/private/AppFramework/Bootstrap/Coordinator.php",
"line": 200,
"function": "boot",
"class": "OCA\\Maps\\AppInfo\\Application",
"type": "->"
},
{
"file": "/var/www/html/nextcloud/lib/private/App/AppManager.php",
"line": 434,
"function": "bootApp",
"class": "OC\\AppFramework\\Bootstrap\\Coordinator",
"type": "->"
},
{
"file": "/var/www/html/nextcloud/lib/private/App/AppManager.php",
"line": 213,
"function": "loadApp",
"class": "OC\\App\\AppManager",
"type": "->"
},
{
"file": "/var/www/html/nextcloud/lib/private/legacy/OC_App.php",
"line": 125,
"function": "loadApps",
"class": "OC\\App\\AppManager",
"type": "->"
},
{
"file": "/var/www/html/nextcloud/remote.php",
"line": 157,
"function": "loadApps",
"class": "OC_App",
"type": "::"
}
],
"File": "/var/www/html/nextcloud/apps/maps/lib/AppInfo/Application.php",
"Line": 92,
"message": "Could not boot maps: Call to undefined method OC\\Server::getEventDispatcher()",
"exception": {},
"CustomMessage": "Could not boot maps: Call to undefined method OC\\Server::getEventDispatcher()"
}
}
The server has a configured DNS that seems to be working, pinged a couple of random sites and cat /etc/resolv.conf shows the correct DNS. I just realised these DNS errors would probably occur if the server was without connectivity, which it has been occasionally (ethernet disconnected), and sometimes for a longer while.
When the web developer console images were taken the ethernet was ofcourse connected however, and I don't see any DNS errors at the time I took the images or since.
I suspected the maps-app from the logs, and I disabled it a while ago to see if it made any difference - which I didn't see. I actually thought it was still disabled, but I must have activated it again after seeing no difference.. I tested disabling/removing it again without any success.
Possibly interesting thing: the user with issues (Rinkana) is the only one to have opened the mapps app (99% certain). I also saw some logs from yesterday that the mapps app was exhausting the php memory limit - which is probably because of me copying the user files (which contain a lot of pictures) to the test account yesterday triggering a large amount of images being scanned -> memory leak in maps.
I tested opening the maps app on the account i copied Rinkanas (the acc with issues) files to, and found the app finished loading much faster than when logged in as Rinkana (checks out with other apps behaviours - file loads are sloow) and no problems arose immediately (files still load really quick).
I looked at some of the files and lines mentioned in the error logs, such as the one you found, but I really don't know what to make of it..
I will activate mariaDB "slow logs" and see if they give something just for good measure - I'll get back when I have the time to check those.
Btw, the logs page in admin setting first displays "could not load logfiles" but after a long while seems to load them (loading older logs..). This might have something to do with the ridiculous log file size? On my desktop opening the file complains about a line being 12k characters long maybe that is a problem for the webUI..?
In general each line of the log represents one event. If they include error messages and stack traces they can become fairly long. It's still helpful to be able to operate on the lines as single entries. They can then be pretty printed with tools like jq.
The "could not load logfiles" was unrelated to the logsize or this issue and was because of https://github.com/nextcloud/logreader/issues/1058
I have not managed to find anything in the mariadb slow log (set to log anything that takes more than a second), as nothing takes much more than a second..
/usr/libexec/mysqld, Version: 10.3.39-MariaDB-log (MariaDB Server). started with:
Tcp port: 0 Unix socket: /var/lib/mysql/mysql.sock
Time Id Command Argument
# Time: 240208 0:25:04
# User@Host: nextcloud[nextcloud] @ localhost []
# Thread_id: 13 Schema: nextcloud QC_hit: No
# Query_time: 1.081698 Lock_time: 0.000033 Rows_sent: 0 Rows_examined: 272864
# Rows_affected: 0 Bytes_sent: 79
use nextcloud;
SET timestamp=1707348304;
SELECT `a`.`name` FROM `oc_filecache` `a` LEFT JOIN `oc_filecache` `b` ON `a`.`name` = `b`.`fileid` WHERE (`a`.`storage` = '1') AND (`b`.`fileid` IS NULL) AND (`a`.`path` LIKE 'appdata\\_oc82uk0ssuox/preview/_/_/_/_/_/_/_/%') AND (`a`.`mimetype` = '2');
/usr/libexec/mysqld, Version: 10.3.39-MariaDB-log (MariaDB Server). started with:
Tcp port: 3306 Unix socket: /var/lib/mysql/mysql.sock
Time Id Command Argument
/usr/libexec/mysqld, Version: 10.3.39-MariaDB-log (MariaDB Server). started with:
Tcp port: 0 Unix socket: /var/lib/mysql/mysql.sock
Time Id Command Argument
# Time: 240219 23:00:04
# User@Host: nextcloud[nextcloud] @ localhost []
# Thread_id: 31 Schema: nextcloud QC_hit: No
# Query_time: 1.004322 Lock_time: 0.000032 Rows_sent: 0 Rows_examined: 272873
# Rows_affected: 0 Bytes_sent: 79
use nextcloud;
SET timestamp=1708380004;
SELECT `a`.`name` FROM `oc_filecache` `a` LEFT JOIN `oc_filecache` `b` ON `a`.`name` = `b`.`fileid` WHERE (`a`.`storage` = '1') AND (`b`.`fileid` IS NULL) AND (`a`.`path` LIKE 'appdata\\_oc82uk0ssuox/preview/_/_/_/_/_/_/_/%') AND (`a`.`mimetype` = '2');
I also had php-fpm slow log active, also set to 1s: (for some reason the www-slow.log is empty, but error.log logged some) This one seems to mirror what we saw earlier about propfind, but I dont feel any wiser from it:
[19-Feb-2024 22:55:57] NOTICE: ready to handle connections
[19-Feb-2024 22:55:57] NOTICE: systemd monitor interval set to 10000ms
[19-Feb-2024 23:01:27] ERROR: failed to ptrace(ATTACH) child 1986: Operation not permitted (1)
[19-Feb-2024 23:01:27] WARNING: [pool www] child 1986, script '/var/www/html/nextcloud/remote.php' (request: "PROPFIND /remote.php") executing too slow (66.444553 sec), logging
[19-Feb-2024 23:11:40] NOTICE: Terminating ...
[19-Feb-2024 23:11:40] NOTICE: exiting, bye-bye!
[19-Feb-2024 23:11:40] NOTICE: fpm is running, pid 6599
[19-Feb-2024 23:11:40] NOTICE: ready to handle connections
[19-Feb-2024 23:11:40] NOTICE: systemd monitor interval set to 10000ms
[19-Feb-2024 23:11:50] ERROR: failed to ptrace(ATTACH) child 6600: Operation not permitted (1)
[19-Feb-2024 23:11:50] WARNING: [pool www] child 6600, script '/var/www/html/nextcloud/index.php' (request: "GET /index.php") executing too slow (1.051775 sec), logging
[19-Feb-2024 23:11:51] ERROR: failed to ptrace(ATTACH) child 6601: Operation not permitted (1)
[19-Feb-2024 23:11:51] WARNING: [pool www] child 6601, script '/var/www/html/nextcloud/index.php' (request: "GET /index.php") executing too slow (1.114086 sec), logging
[19-Feb-2024 23:12:04] ERROR: failed to ptrace(ATTACH) child 6602: Operation not permitted (1)
[19-Feb-2024 23:12:04] WARNING: [pool www] child 6602, script '/var/www/html/nextcloud/ocs/v2.php' (request: "GET /ocs/v2.php") executing too slow (1.162557 sec), logging
[19-Feb-2024 23:12:13] ERROR: failed to ptrace(ATTACH) child 6605: Operation not permitted (1)
[19-Feb-2024 23:12:13] WARNING: [pool www] child 6605, script '/var/www/html/nextcloud/remote.php' (request: "PROPFIND /remote.php") executing too slow (1.187088 sec), logging
[19-Feb-2024 23:13:18] ERROR: failed to ptrace(ATTACH) child 6601: Operation not permitted (1)
[19-Feb-2024 23:13:18] WARNING: [pool www] child 6601, script '/var/www/html/nextcloud/remote.php' (request: "PROPFIND /remote.php") executing too slow (1.249486 sec), logging
I will close this issue with this, as I have not managed to debug this further, nor do I really have time to and the instance where the one account that constantly reproduces the issue exists is to be turned of and disassembled (was planned already for January). Since I suspect you have not nor will easily manage to reproduce the issue, it would end up just dead.
My best guess is that something is crazy in the database, making propfind error out just for that user, but it really feels like it should show up in logs in that case.. I don't know what else could make only one user account have issues.
Please let me know if you would want the virtual disks for the vm, I could clear out any personal files from it of you want to give the debugging a try somewhere where the issue exists. Or I could make the instance accessible for you from backup during a set time, if its not to far in the future. Either of these would be handled over pm in that case.
The new instance I have set up on new hardware has had the problematic users files moved to it, displaying none at all of the issues, mirroring what happened in the earlier test I did on the old instance.