Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Bug]: external files app calls same function unnecessarily multiple times #38861

Closed
5 of 8 tasks
spamcopilot2 opened this issue Jun 16, 2023 · 9 comments
Closed
5 of 8 tasks

Comments

@spamcopilot2
Copy link

spamcopilot2 commented Jun 16, 2023

⚠️ This issue respects the following points: ⚠️

Bug description

In an attempt to improve the performance of the external files app, I have added some loggers here and noticed that the same method is called several times for the same file and I wonder what the point is and whether this is intended.

If not, this could be a bug

Steps to reproduce

  1. Install Nextcloud (v. 26.0.2) and external files App (v 0.18)
  2. Add a folder to another Nextcloud
  3. Add a logger in line 288 of file DAV.PHP
  4. Either start a scan process (sudo -u www-data php occ files:scan ) or open the external folder via Nextcloud Webinterface
  5. Check either your Nextcloud.log or the Nextcloud Log site under settings

Expected behavior

A propfind for an (external) file should only be called once.
Either its in the cache or not. If not request the info.

Don´t call the propfind function multiple times and only once receive an answer.

Installation method

Community Manual installation with Archive

Nextcloud Server version

26

Operating system

RHEL/CentOS

PHP engine version

PHP 8.2

Web server

Nginx

Database engine version

PostgreSQL

Is this bug present after an update or on a fresh install?

None

Are you using the Nextcloud Server Encryption module?

Encryption is Disabled

What user-backends are you using?

  • 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": [
            "my.site.com",
        ],
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "overwrite.cli.url": "https:\/\/my.site.com",
        "overwriteprotocol": "https",
        "dbtype": "pgsql",
        "version": "26.0.2.1",
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "***REMOVED SENSITIVE VALUE***",
        "dbtableprefix": "oc_",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "installed": true,
        "forcessl": true,
        "forceSSLforSubdomains": true,
        "theme": "",
        "maintenance": false,
        "appstore.experimental.enabled": true,
        "loglevel": 0,
        "trashbin_retention_obligation": "auto",
        "updatechecker": false,
        "updater.server.url": "https:\/\/updates.nextcloud.com\/updater_server\/",
        "updater.release.channel": "stable",
        "htaccess.RewriteBase": "\/",
        "filelocking.enabled": "true",
        "memcache.local": "\\OC\\Memcache\\APCu",
        "memcache.distributed": "\\OC\\Memcache\\Redis",
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "redis": {
            "host": "***REMOVED SENSITIVE VALUE***",
            "port": 0,
            "timeout": 0
        },
        "mysql.utf8mb4": true,
        "mail_smtpmode": "smtp",
        "mail_smtpsecure": "tls",
        "mail_sendmailmode": "smtp",
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpauthtype": "LOGIN",
        "mail_smtpauth": 1,
        "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
        "mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
        "app_install_overwrite": [
            "sharerenamer"
        ],
        "default_phone_region": "DE"
    }
}

List of activated Apps

Enabled:
  - activity: 2.18.0
  - admin_audit: 1.16.0
  - calendar: 4.4.2
  - circles: 26.0.0
  - cloud_federation_api: 1.9.0
  - comments: 1.16.0
  - contacts: 5.3.1
  - contactsinteraction: 1.7.0
  - cospend: 1.5.10
  - dashboard: 7.6.0
  - dav: 1.25.0
  - deck: 1.9.2
  - federatedfilesharing: 1.16.0
  - federation: 1.16.0
  - files: 1.21.1
  - files_external: 1.18.0
  - files_pdfviewer: 2.7.0
  - files_rightclick: 1.5.0
  - files_sharing: 1.18.0
  - files_trashbin: 1.16.0
  - files_versions: 1.19.1
  - firstrunwizard: 2.15.0
  - logreader: 2.11.0
  - lookup_server_connector: 1.14.0
  - nextcloud_announcements: 1.15.0
  - notes: 4.8.0
  - notifications: 2.14.0
  - oauth2: 1.14.0
  - password_policy: 1.16.0
  - photos: 2.2.0
  - privacy: 1.10.0
  - provisioning_api: 1.16.0
  - recommendations: 1.5.0
  - related_resources: 1.1.0-alpha1
  - serverinfo: 1.16.0
  - settings: 1.8.0
  - sharebymail: 1.16.0
  - sharerenamer: 3.2.0
  - spreed: 16.0.4
  - support: 1.9.0
  - survey_client: 1.14.0
  - systemtags: 1.16.0
  - tasks: 0.15.0
  - text: 3.7.2
  - theming: 2.1.1
  - twofactor_backupcodes: 1.15.0
  - updatenotification: 1.16.0
  - user_status: 1.6.0
  - viewer: 1.10.0
  - weather_status: 1.6.0
  - workflowengine: 2.8.0
Disabled:
  - appointments: 1.15.1 (installed 1.15.1)
  - bruteforcesettings: 2.6.0 (installed 1.3.0)
  - drawio: 2.1.1 (installed 2.1.1)
  - encryption: 2.14.0
  - polls: 5.1.0-beta1 (installed 5.1.0-beta1)
  - richdocuments: 8.0.2 (installed 8.0.2)
  - suspicious_login: 4.4.0
  - twofactor_totp: 8.0.0
  - user_ldap: 1.16.0

Nextcloud Signing status

No errors have been found.

Nextcloud Logs

{"reqId":"XRgc2Xpd40BH5JLrIWOO","level":0,"time":"2023-06-16T15:59:55+00:00","remoteAddr":"","user":"--","app":"dav","method":"","url":"--","message":"starting dav propfind Android/Download/DCIM/OpenCamera/IMG_20210911_212900.webptime 0.29786000 1686931195","userAgent":"--","version":"26.0.2.1","data":{"app":"dav"}}
{"reqId":"XRgc2Xpd40BH5JLrIWOO","level":0,"time":"2023-06-16T15:59:55+00:00","remoteAddr":"","user":"--","app":"dav","method":"","url":"--","message":"Android/Download/DCIM/OpenCamera/IMG_20210911_212900.webp not in cache. requesting now","userAgent":"--","version":"26.0.2.1","data":{"app":"dav"}}
{"reqId":"XRgc2Xpd40BH5JLrIWOO","level":0,"time":"2023-06-16T15:59:57+00:00","remoteAddr":"","user":"--","app":"dav","method":"","url":"--","message":"starting dav propfind Android/Download/DCIM/OpenCamera/IMG_20210911_212900.webptime 0.07201500 1686931197","userAgent":"--","version":"26.0.2.1","data":{"app":"dav"}}
{"reqId":"XRgc2Xpd40BH5JLrIWOO","level":0,"time":"2023-06-16T15:59:57+00:00","remoteAddr":"","user":"--","app":"dav","method":"","url":"--","message":"Path known Android/Download/DCIM/OpenCamera/IMG_20210911_212900.webp","userAgent":"--","version":"26.0.2.1","data":{"app":"dav"}}
{"reqId":"XRgc2Xpd40BH5JLrIWOO","level":0,"time":"2023-06-16T15:59:57+00:00","remoteAddr":"","user":"--","app":"dav","method":"","url":"--","message":"starting dav propfind Android/Download/DCIM/OpenCamera/IMG_20210911_212900.webptime 0.07237700 1686931197","userAgent":"--","version":"26.0.2.1","data":{"app":"dav"}}
{"reqId":"XRgc2Xpd40BH5JLrIWOO","level":0,"time":"2023-06-16T15:59:57+00:00","remoteAddr":"","user":"--","app":"dav","method":"","url":"--","message":"Path known Android/Download/DCIM/OpenCamera/IMG_20210911_212900.webp","userAgent":"--","version":"26.0.2.1","data":{"app":"dav"}}
{"reqId":"XRgc2Xpd40BH5JLrIWOO","level":0,"time":"2023-06-16T15:59:57+00:00","remoteAddr":"","user":"--","app":"dav","method":"","url":"--","message":"starting dav propfind Android/Download/DCIM/OpenCamera/IMG_20210911_212900.webptime 0.07260000 1686931197","userAgent":"--","version":"26.0.2.1","data":{"app":"dav"}}
{"reqId":"XRgc2Xpd40BH5JLrIWOO","level":0,"time":"2023-06-16T15:59:57+00:00","remoteAddr":"","user":"--","app":"dav","method":"","url":"--","message":"Path known Android/Download/DCIM/OpenCamera/IMG_20210911_212900.webp","userAgent":"--","version":"26.0.2.1","data":{"app":"dav"}}
{"reqId":"XRgc2Xpd40BH5JLrIWOO","level":0,"time":"2023-06-16T15:59:57+00:00","remoteAddr":"","user":"--","app":"dav","method":"","url":"--","message":"starting dav propfind Android/Download/DCIM/OpenCamera/IMG_20210911_212900.webptime 0.07281600 1686931197","userAgent":"--","version":"26.0.2.1","data":{"app":"dav"}}
{"reqId":"XRgc2Xpd40BH5JLrIWOO","level":0,"time":"2023-06-16T15:59:57+00:00","remoteAddr":"","user":"--","app":"dav","method":"","url":"--","message":"Path known Android/Download/DCIM/OpenCamera/IMG_20210911_212900.webp","userAgent":"--","version":"26.0.2.1","data":{"app":"dav"}}
{"reqId":"XRgc2Xpd40BH5JLrIWOO","level":0,"time":"2023-06-16T15:59:57+00:00","remoteAddr":"","user":"--","app":"dav","method":"","url":"--","message":"starting dav propfind Android/Download/DCIM/OpenCamera/IMG_20210911_212900.webptime 0.07302700 1686931197","userAgent":"--","version":"26.0.2.1","data":{"app":"dav"}}
{"reqId":"XRgc2Xpd40BH5JLrIWOO","level":0,"time":"2023-06-16T15:59:57+00:00","remoteAddr":"","user":"--","app":"dav","method":"","url":"--","message":"Path known Android/Download/DCIM/OpenCamera/IMG_20210911_212900.webp","userAgent":"--","version":"26.0.2.1","data":{"app":"dav"}}

Additional info

In the logs you can see the multiple function calls.
There are 3 possible logs:

  • starting dav propfind <FILE_PATH> microtime(false) [Beginning the propfind method]
  • <FILE_PATH> not in cache. requesting now [File is not in cache and will be requested from remote server]
  • Path known <FILE_PATH> [File is in cache and will be returned without request]

I added the microtime to be sure that its not the same log just printed multiple times. but you can see different timestamps, so i assume its different function calls.

@spamcopilot2 spamcopilot2 added 0. Needs triage Pending check for reproducibility or if it fits our roadmap bug labels Jun 16, 2023
@szaimen
Copy link
Contributor

szaimen commented Jun 16, 2023

Cc @icewind1991 @nextcloud/server-backend

@kesselb
Copy link
Contributor

kesselb commented Jun 16, 2023

https://www.php.net/manual/en/function.debug-backtrace.php to enhance your debug log with a stack trace.

@come-nc
Copy link
Contributor

come-nc commented Jun 19, 2023

Fixed by #38418 ?

@Alexandero89
Copy link

Fixed by #38418 ?

Seems familiar and could be a fix. I will later cherry pick this commit and test this issue again.

@Alexandero89
Copy link

@come-nc unfortunately the amount of function calls stays the same. So no fix

@solracsf
Copy link
Member

What about #38945 ?

@Alexandero89
Copy link

Alexandero89 commented Jun 23, 2023

It seems the performance gets better, and there are three calls less. So 3 calls to propfind instead of 6.
But the cache is working better now and it seems the calls are kind of necessary.

Here are all calls for one file:

  1. callstack to propfind:
DAV.php:281, OC\Files\Storage\DAV->propfind()
DAV.php:828, OC\Files\Storage\DAV->hasUpdated()
Wrapper.php:378, OC\Files\Storage\Wrapper\Wrapper->hasUpdated()
Wrapper.php:378, OC\Files\Storage\Wrapper\Wrapper->hasUpdated()
Availability.php:386, OC\Files\Storage\Wrapper\Availability->hasUpdated()
Wrapper.php:378, OC\Files\Storage\Wrapper\Wrapper->hasUpdated()
Watcher.php:134, OC\Files\Cache\Watcher->needsUpdate()
View.php:1319, OC\Files\View->getCacheEntry()
View.php:1356, OC\Files\View->getFileInfo()
HookConnector.php:230, OC\Files\Node\HookConnector->getNodeForPath()
HookConnector.php:221, OC\Files\Node\HookConnector->read()
OC_Hook.php:105, OC_Hook::emit()
View.php:1261, OC\Files\View->runHooks()
View.php:1126, OC\Files\View->basicOperation()
View.php:969, OC\Files\View->fopen()
File.php:116, OC\Files\Node\File->fopen()
ProviderV2.php:90, OC\Preview\ProviderV2->getLocalFile()
Image.php:49, OC\Preview\Image->getThumbnail()
GeneratorHelper.php:64, OC\Preview\GeneratorHelper->getThumbnail()
Generator.php:397, OC\Preview\Generator->generateProviderPreview()
Generator.php:373, OC\Preview\Generator->getMaxPreview()
Generator.php:166, OC\Preview\Generator->generatePreviews()
Generator.php:116, OC\Preview\Generator->getPreview()
PreviewManager.php:192, OC\PreviewManager->getPreview()
PreviewController.php:144, OC\Core\Controller\PreviewController->fetchPreview()
PreviewController.php:113, OC\Core\Controller\PreviewController->getPreviewByFileId()
Dispatcher.php:230, OC\AppFramework\Http\Dispatcher->executeController()
Dispatcher.php:137, OC\AppFramework\Http\Dispatcher->dispatch()
App.php:183, OC\AppFramework\App::main()
Router.php:315, OC\Route\Router->match()
base.php:1064, OC::handleRequest()
index.php:36, {main}()
  1. callstack to propfind:
DAV.php:281, OC\Files\Storage\DAV->propfind()
DAV.php:326, OC\Files\Storage\DAV->filetype()
Common.php:117, OC\Files\Storage\Common->is_dir()
Wrapper.php:114, OC\Files\Storage\Wrapper\Wrapper->is_dir()
Wrapper.php:114, OC\Files\Storage\Wrapper\Wrapper->is_dir()
Availability.php:131, OC\Files\Storage\Wrapper\Availability->is_dir()
Wrapper.php:114, OC\Files\Storage\Wrapper\Wrapper->is_dir()
Watcher.php:111, OC\Files\Cache\Watcher->update()
View.php:1321, OC\Files\View->getCacheEntry()
View.php:1356, OC\Files\View->getFileInfo()
HookConnector.php:230, OC\Files\Node\HookConnector->getNodeForPath()
HookConnector.php:221, OC\Files\Node\HookConnector->read()
OC_Hook.php:105, OC_Hook::emit()
View.php:1261, OC\Files\View->runHooks()
View.php:1126, OC\Files\View->basicOperation()
View.php:969, OC\Files\View->fopen()
File.php:116, OC\Files\Node\File->fopen()
ProviderV2.php:90, OC\Preview\ProviderV2->getLocalFile()
Image.php:49, OC\Preview\Image->getThumbnail()
GeneratorHelper.php:64, OC\Preview\GeneratorHelper->getThumbnail()
Generator.php:397, OC\Preview\Generator->generateProviderPreview()
Generator.php:373, OC\Preview\Generator->getMaxPreview()
Generator.php:166, OC\Preview\Generator->generatePreviews()
Generator.php:116, OC\Preview\Generator->getPreview()
PreviewManager.php:192, OC\PreviewManager->getPreview()
PreviewController.php:144, OC\Core\Controller\PreviewController->fetchPreview()
PreviewController.php:113, OC\Core\Controller\PreviewController->getPreviewByFileId()
Dispatcher.php:230, OC\AppFramework\Http\Dispatcher->executeController()
Dispatcher.php:137, OC\AppFramework\Http\Dispatcher->dispatch()
App.php:183, OC\AppFramework\App::main()
Router.php:315, OC\Route\Router->match()
base.php:1064, OC::handleRequest()
index.php:36, {main}()
  1. callstack to propfind:
DAV.php:281, OC\Files\Storage\DAV->propfind()
DAV.php:615, OC\Files\Storage\DAV->getMetaData()
Wrapper.php:596, OC\Files\Storage\Wrapper\Wrapper->getMetaData()
PermissionsMask.php:140, OC\Files\Storage\Wrapper\PermissionsMask->getMetaData()
Wrapper.php:596, OC\Files\Storage\Wrapper\Wrapper->getMetaData()
Availability.php:447, OC\Files\Storage\Wrapper\Availability->getMetaData()
Wrapper.php:596, OC\Files\Storage\Wrapper\Wrapper->getMetaData()
Scanner.php:121, OC\Files\Cache\Scanner->getData()
Scanner.php:158, OC\Files\Cache\Scanner->scanFile()
Watcher.php:114, OC\Files\Cache\Watcher->update()
View.php:1321, OC\Files\View->getCacheEntry()
View.php:1356, OC\Files\View->getFileInfo()
HookConnector.php:230, OC\Files\Node\HookConnector->getNodeForPath()
HookConnector.php:221, OC\Files\Node\HookConnector->read()
OC_Hook.php:105, OC_Hook::emit()
View.php:1261, OC\Files\View->runHooks()
View.php:1126, OC\Files\View->basicOperation()
View.php:969, OC\Files\View->fopen()
File.php:116, OC\Files\Node\File->fopen()
ProviderV2.php:90, OC\Preview\ProviderV2->getLocalFile()
Image.php:49, OC\Preview\Image->getThumbnail()
GeneratorHelper.php:64, OC\Preview\GeneratorHelper->getThumbnail()
Generator.php:397, OC\Preview\Generator->generateProviderPreview()
Generator.php:373, OC\Preview\Generator->getMaxPreview()
Generator.php:166, OC\Preview\Generator->generatePreviews()
Generator.php:116, OC\Preview\Generator->getPreview()
PreviewManager.php:192, OC\PreviewManager->getPreview()
PreviewController.php:144, OC\Core\Controller\PreviewController->fetchPreview()
PreviewController.php:113, OC\Core\Controller\PreviewController->getPreviewByFileId()
Dispatcher.php:230, OC\AppFramework\Http\Dispatcher->executeController()
Dispatcher.php:137, OC\AppFramework\Http\Dispatcher->dispatch()
App.php:183, OC\AppFramework\App::main()
Router.php:315, OC\Route\Router->match()
base.php:1064, OC::handleRequest()
index.php:36, {main}()

After the first call the cache successfully returns the metadata.

@joshtrichards
Copy link
Member

Is this Issue done (closeable) or are we still keeping it open to track some specific remaining improvements?

@joshtrichards
Copy link
Member

Fixed in #38945

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

7 participants