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鈥檒l occasionally send you account related emails.

Already on GitHub? Sign in to your account

MOVING files already present in NC to new, encrypted folder causes problems #2519

Closed
ho1ger opened this issue Aug 25, 2020 · 17 comments 路 Fixed by #2824
Closed

MOVING files already present in NC to new, encrypted folder causes problems #2519

ho1ger opened this issue Aug 25, 2020 · 17 comments 路 Fixed by #2824

Comments

@ho1ger
Copy link

ho1ger commented Aug 25, 2020

How to use GitHub

  • Please use the 馃憤 reaction to show that you are affected by the same issue.
  • Please don't comment if you have no relevant information to add. It's just extra noise for everyone subscribed to this issue.

Steps to reproduce

  1. Enable E2EE, create folder, select as being encrypted (I used the MacOS desktop app)
  2. MOVE files/folders into encrypted folder

Expected behaviour

Data encrypted and sync'd to server

Actual behaviour

  • No sync to server.

  • Suddenly system got unresponsive

  • Found that many MySQL processes run at full whack --> needed to restart mysql server --> server responsive again

  • Tried to delete the encrypted folder --> got a 403 message displayed in client --> disabled e2ee --> deleted folder

Server configuration

Operating system:

Ubuntu 20.04.1 aarch64

Web server:

Nginx 1.18

Database:

Mysql / MariaDB 10.3

PHP version:

7.4.3

Nextcloud version: (see Nextcloud admin page)

19.0.1

Updated from an older Nextcloud/ownCloud or fresh install:

From old NC, intially v15 or so...

Where did you install Nextcloud from:

ZIP -> no docker, native installation

List of activated apps:

e2ee: 1.5.2

Logs

Web server error log

2020/08/25 11:06:58 [error] 2054369#2054369: *244807 upstream timed out (110: Connection timed out) while reading response header from upstream, client: yyy, server: xxx, request: "PROPFIND /remote.php/webdav HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "xxx"
2020/08/25 11:06:58 [error] 2054369#2054369: *244807 upstream timed out (110: Connection timed out) while reading response header from upstream, client: yyy, server: xxx, request: "PROPFIND /remote.php/webdav HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "xxx"
2020/08/25 11:19:49 [error] 2054369#2054369: *245454 upstream timed out (110: Connection timed out) while reading response header from upstream, client: yyy, server: xxx, request: "PROPFIND /remote.php/webdav HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "xxx"
2020/08/25 11:23:23 [error] 2054369#2054369: *245519 upstream timed out (110: Connection timed out) while reading response header from upstream, client: yyy, server: xxx, request: "PROPFIND /remote.php/webdav HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "xxx"
2020/08/25 11:33:15 [error] 2054370#2054370: *245875 upstream timed out (110: Connection timed out) while reading response header from upstream, client: yyy, server: xxx, request: "PROPFIND /remote.php/webdav HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "xxx"
2020/08/25 11:34:37 [error] 2054369#2054369: *245857 upstream timed out (110: Connection timed out) while reading response header from upstream, client: yyy, server: xxx, request: "PROPFIND /remote.php/webdav HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "xxx"

Nextcloud log (data/nextcloud.log)

...
I omitted the duplicates...

{"reqId":"trx5rjQqU3zamrGrjGGs","level":3,"time":"2020-08-25T11:36:08+02:00","remoteAddr":"yyy","user":"user","app":"PHP","method":"GET","url":"/ocs/v1.php/cloud/user?format=json","message":"Unknown: send of 5 bytes failed with errno=32 Broken pipe at Unknown#0","userAgent":"Mozilla/5.0 (Macintosh) mirall/3.0.0git (build 3292) (Nextcloud)","version":"19.0.1.1","id":"5f44e2083d4fb"}

...

{"reqId":"gMzTT1cCVTipPhZArk35","level":3,"time":"2020-08-25T11:35:46+02:00","remoteAddr":"yyy","user":"--","app":"PHP","method":"PROPFIND","url":"/remote.php/dav/files/user/Photos","message":"Error: Class 'OCA\\DAV\\Connector\\Sabre\\ExceptionLoggerPlugin' not found at /var/www/html/nextcloud/remote.php#61","userAgent":"Mozilla/5.0 (Macintosh) mirall/3.0.0git (build 3292) (Nextcloud)","version":"19.0.1.1","id":"5f44e2083d724"}

...

{"reqId":"oJbf0m2KWn1uFOWhJbRb","level":4,"time":"2020-08-25T11:35:46+02:00","remoteAddr":"yyy","user":"user","app":"webdav","method":"PROPFIND","url":"/remote.php/webdav","message":{"Exception":"Doctrine\\DBAL\\Exception\\DriverException","Message":"An exception occurred while executing 'SELECT `filecache`.`fileid`, `storage`, `path`, `path_hash`, `filecache`.`parent`, `name`, `mimetype`, `mimepart`, `size`, `mtime`, `storage_mtime`, `encrypted`, `etag`, `permissions`, `checksum`, `metadata_etag`, `creation_time`, `upload_time` FROM `oc_filecache` `filecache` LEFT JOIN `oc_filecache_extended` `fe` ON `filecache`.`fileid` = `fe`.`fileid` WHERE (`storage` = ?) AND (`path_hash` = ?)' with params [30, \"7ec2f9d9543868a8a57c7ea88e34b62f\"]:\n\nSQLSTATE[HY000]: General error: 2006 MySQL server has gone away","Code":0,"Trace":[{"file":"/var/www/html/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/DBALException.php","line":169,"function":"convertException","class":"Doctrine\\DBAL\\Driver\\AbstractMySQLDriver","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/DBALException.php","line":145,"function":"wrapException","class":"Doctrine\\DBAL\\DBALException","type":"::"},{"file":"/var/www/html/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Connection.php","line":911,"function":"driverExceptionDuringQuery","class":"Doctrine\\DBAL\\DBALException","type":"::"},{"file":"/var/www/html/nextcloud/lib/private/DB/Connection.php","line":194,"function":"executeQuery","class":"Doctrine\\DBAL\\Connection","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Query/QueryBuilder.php","line":200,"function":"executeQuery","class":"OC\\DB\\Connection","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/DB/QueryBuilder/QueryBuilder.php","line":216,"function":"execute","class":"Doctrine\\DBAL\\Query\\QueryBuilder","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/Files/Cache/Cache.php","line":154,"function":"execute","class":"OC\\DB\\QueryBuilder\\QueryBuilder","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/Files/Cache/Wrapper/CacheWrapper.php","line":72,"function":"get","class":"OC\\Files\\Cache\\Cache","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/Files/View.php","line":1328,"function":"get","class":"OC\\Files\\Cache\\Wrapper\\CacheWrapper","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/Files/View.php","line":1444,"function":"getCacheEntry","class":"OC\\Files\\View","type":"->"},{"file":"/var/www/html/nextcloud/apps/dav/lib/Connector/Sabre/Directory.php","line":263,"function":"getDirectoryContent","class":"OC\\Files\\View","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Tree.php","line":204,"function":"getChildren","class":"OCA\\DAV\\Connector\\Sabre\\Directory","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":905,"function":"getChildren","class":"Sabre\\DAV\\Tree","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":919,"function":"generatePathNodes","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":919,"function":"generatePathNodes","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":919,"function":"generatePathNodes","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":919,"function":"generatePathNodes","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":987,"function":"generatePathNodes","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":1678,"function":"getPropertiesIteratorForPath","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":1661,"function":"writeMultiStatus","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php","line":363,"function":"generateMultiStatus","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/event/lib/WildcardEmitterTrait.php","line":89,"function":"httpPropFind","class":"Sabre\\DAV\\CorePlugin","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":474,"function":"emit","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":251,"function":"invokeMethod","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":319,"function":"start","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/apps/dav/appinfo/v1/webdav.php","line":82,"function":"exec","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/remote.php","line":167,"args":["/var/www/html/nextcloud/apps/dav/appinfo/v1/webdav.php"],"function":"require_once"}],"File":"/var/www/html/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Driver/AbstractMySQLDriver.php","Line":106,"Previous":{"Exception":"Doctrine\\DBAL\\Driver\\PDOException","Message":"SQLSTATE[HY000]: General error: 2006 MySQL server has gone away","Code":"HY000","Trace":[{"file":"/var/www/html/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Connection.php","line":903,"function":"execute","class":"Doctrine\\DBAL\\Driver\\PDOStatement","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/DB/Connection.php","line":194,"function":"executeQuery","class":"Doctrine\\DBAL\\Connection","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Query/QueryBuilder.php","line":200,"function":"executeQuery","class":"OC\\DB\\Connection","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/DB/QueryBuilder/QueryBuilder.php","line":216,"function":"execute","class":"Doctrine\\DBAL\\Query\\QueryBuilder","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/Files/Cache/Cache.php","line":154,"function":"execute","class":"OC\\DB\\QueryBuilder\\QueryBuilder","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/Files/Cache/Wrapper/CacheWrapper.php","line":72,"function":"get","class":"OC\\Files\\Cache\\Cache","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/Files/View.php","line":1328,"function":"get","class":"OC\\Files\\Cache\\Wrapper\\CacheWrapper","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/Files/View.php","line":1444,"function":"getCacheEntry","class":"OC\\Files\\View","type":"->"},{"file":"/var/www/html/nextcloud/apps/dav/lib/Connector/Sabre/Directory.php","line":263,"function":"getDirectoryContent","class":"OC\\Files\\View","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Tree.php","line":204,"function":"getChildren","class":"OCA\\DAV\\Connector\\Sabre\\Directory","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":905,"function":"getChildren","class":"Sabre\\DAV\\Tree","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":919,"function":"generatePathNodes","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":919,"function":"generatePathNodes","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":919,"function":"generatePathNodes","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":919,"function":"generatePathNodes","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":987,"function":"generatePathNodes","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":1678,"function":"getPropertiesIteratorForPath","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":1661,"function":"writeMultiStatus","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php","line":363,"function":"generateMultiStatus","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/event/lib/WildcardEmitterTrait.php","line":89,"function":"httpPropFind","class":"Sabre\\DAV\\CorePlugin","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":474,"function":"emit","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":251,"function":"invokeMethod","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":319,"function":"start","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/apps/dav/appinfo/v1/webdav.php","line":82,"function":"exec","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/remote.php","line":167,"args":["/var/www/html/nextcloud/apps/dav/appinfo/v1/webdav.php"],"function":"require_once"}],"File":"/var/www/html/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php","Line":119,"Previous":{"Exception":"PDOException","Message":"SQLSTATE[HY000]: General error: 2006 MySQL server has gone away","Code":"HY000","Trace":[{"file":"/var/www/html/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php","line":117,"function":"execute","class":"PDOStatement","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Connection.php","line":903,"function":"execute","class":"Doctrine\\DBAL\\Driver\\PDOStatement","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/DB/Connection.php","line":194,"function":"executeQuery","class":"Doctrine\\DBAL\\Connection","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Query/QueryBuilder.php","line":200,"function":"executeQuery","class":"OC\\DB\\Connection","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/DB/QueryBuilder/QueryBuilder.php","line":216,"function":"execute","class":"Doctrine\\DBAL\\Query\\QueryBuilder","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/Files/Cache/Cache.php","line":154,"function":"execute","class":"OC\\DB\\QueryBuilder\\QueryBuilder","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/Files/Cache/Wrapper/CacheWrapper.php","line":72,"function":"get","class":"OC\\Files\\Cache\\Cache","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/Files/View.php","line":1328,"function":"get","class":"OC\\Files\\Cache\\Wrapper\\CacheWrapper","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/Files/View.php","line":1444,"function":"getCacheEntry","class":"OC\\Files\\View","type":"->"},{"file":"/var/www/html/nextcloud/apps/dav/lib/Connector/Sabre/Directory.php","line":263,"function":"getDirectoryContent","class":"OC\\Files\\View","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Tree.php","line":204,"function":"getChildren","class":"OCA\\DAV\\Connector\\Sabre\\Directory","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":905,"function":"getChildren","class":"Sabre\\DAV\\Tree","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":919,"function":"generatePathNodes","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":919,"function":"generatePathNodes","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":919,"function":"generatePathNodes","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":919,"function":"generatePathNodes","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":987,"function":"generatePathNodes","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":1678,"function":"getPropertiesIteratorForPath","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":1661,"function":"writeMultiStatus","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php","line":363,"function":"generateMultiStatus","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/event/lib/WildcardEmitterTrait.php","line":89,"function":"httpPropFind","class":"Sabre\\DAV\\CorePlugin","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":474,"function":"emit","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":251,"function":"invokeMethod","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":319,"function":"start","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/apps/dav/appinfo/v1/webdav.php","line":82,"function":"exec","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/remote.php","line":167,"args":["/var/www/html/nextcloud/apps/dav/appinfo/v1/webdav.php"],"function":"require_once"}],"File":"/var/www/html/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php","Line":117}},"CustomMessage":"--"},"userAgent":"Mozilla/5.0 (Macintosh) mirall/3.0.0git (build 3292) (Nextcloud)","version":"19.0.1.1","id":"5f44e2083de8a"}

...

{"reqId":"TSwTm9973yX9AmUg2gLQ","level":3,"time":"2020-08-25T11:26:22+02:00","remoteAddr":"yyy","user":"user","app":"no app in context","method":"DELETE","url":"/ocs/v2.php/apps/end_to_end_encryption/api/v1/lock/1406?format=json&e2e-token=WfPN88kHREkGqGou9ZRmdg0XZeceBC8k98dRW1kCQwqiqhlobkDeCL2epmIC1Slo","message":{"Exception":"OCA\\EndToEndEncryption\\Exceptions\\MissingMetaDataException","Message":"Intermediate meta-data file missing","Code":0,"Trace":[{"file":"/var/www/html/nextcloud/apps/end_to_end_encryption/lib/Controller/LockingController.php","line":146,"function":"saveIntermediateFile","class":"OCA\\EndToEndEncryption\\MetaDataStorage","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/AppFramework/Http/Dispatcher.php","line":170,"function":"unlockFolder","class":"OCA\\EndToEndEncryption\\Controller\\LockingController","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/AppFramework/Http/Dispatcher.php","line":100,"function":"executeController","class":"OC\\AppFramework\\Http\\Dispatcher","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/AppFramework/App.php","line":137,"function":"dispatch","class":"OC\\AppFramework\\Http\\Dispatcher","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/AppFramework/Routing/RouteActionHandler.php","line":47,"function":"main","class":"OC\\AppFramework\\App","type":"::"},{"function":"__invoke","class":"OC\\AppFramework\\Routing\\RouteActionHandler","type":"->"},{"file":"/var/www/html/nextcloud/lib/private/Route/Router.php","line":297,"function":"call_user_func"},{"file":"/var/www/html/nextcloud/ocs/v1.php","line":88,"function":"match","class":"OC\\Route\\Router","type":"->"},{"file":"/var/www/html/nextcloud/ocs/v2.php","line":24,"args":["/var/www/html/nextcloud/ocs/v1.php"],"function":"require_once"}],"File":"/var/www/html/nextcloud/apps/end_to_end_encryption/lib/MetaDataStorage.php","Line":186,"CustomMessage":"--"},"userAgent":"Mozilla/5.0 (iOS) Nextcloud-iOS/3.0.5","version":"19.0.1.1","id":"5f44e20849d4d"}

...

{"reqId":"aIlGaW4EmodehUdi7Hi0","level":4,"time":"2020-08-25T11:26:07+02:00","remoteAddr":"yyy","user":"user","app":"webdav","method":"DELETE","url":"/remote.php/webdav/Dokumente/Privat/ENC","message":{"Exception":"OCA\\DAV\\Connector\\Sabre\\Exception\\Forbidden","Message":"Cannot copy or move files from non-encrypted folders to end to end encrypted folders or vice versa.","Code":0,"Trace":[{"file":"/var/www/html/nextcloud/3rdparty/sabre/event/lib/WildcardEmitterTrait.php","line":89,"function":"checkLock","class":"OCA\\EndToEndEncryption\\Connector\\Sabre\\LockPlugin","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":458,"function":"emit","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/apps/end_to_end_encryption/lib/Connector/Sabre/RedirectRequestPlugin.php","line":131,"function":"invokeMethod","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/event/lib/WildcardEmitterTrait.php","line":89,"function":"httpDelete","class":"OCA\\EndToEndEncryption\\Connector\\Sabre\\RedirectRequestPlugin","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":474,"function":"emit","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":251,"function":"invokeMethod","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":319,"function":"start","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/apps/dav/appinfo/v1/webdav.php","line":82,"function":"exec","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/remote.php","line":167,"args":["/var/www/html/nextcloud/apps/dav/appinfo/v1/webdav.php"],"function":"require_once"}],"File":"/var/www/html/nextcloud/apps/end_to_end_encryption/lib/Connector/Sabre/LockPlugin.php","Line":122,"CustomMessage":"--"},"userAgent":"Mozilla/5.0 (iOS) Nextcloud-iOS/3.0.5","version":"19.0.1.1","id":"5f44e2084a073"}

{"reqId":"LBsLZKuzVmMaSRDlAquser","level":4,"time":"2020-08-25T11:22:01+02:00","remoteAddr":"yyy","user":"user","app":"webdav","method":"DELETE","url":"/remote.php/dav/files/user/Dokumente/Privat/ENC","message":{"Exception":"OCA\\DAV\\Connector\\Sabre\\Exception\\Forbidden","Message":"Write access to end-to-end encrypted folder requires token - no token sent","Code":0,"Trace":[{"file":"/var/www/html/nextcloud/apps/end_to_end_encryption/lib/Connector/Sabre/LockPlugin.php","line":153,"function":"verifyTokenOnWriteAccess","class":"OCA\\EndToEndEncryption\\Connector\\Sabre\\LockPlugin","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/event/lib/WildcardEmitterTrait.php","line":89,"function":"checkLock","class":"OCA\\EndToEndEncryption\\Connector\\Sabre\\LockPlugin","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":458,"function":"emit","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":251,"function":"invokeMethod","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":319,"function":"start","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/apps/dav/lib/Server.php","line":320,"function":"exec","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/apps/dav/appinfo/v2/remote.php","line":35,"function":"exec","class":"OCA\\DAV\\Server","type":"->"},{"file":"/var/www/html/nextcloud/remote.php","line":167,"args":["/var/www/html/nextcloud/apps/dav/appinfo/v2/remote.php"],"function":"require_once"}],"File":"/var/www/html/nextcloud/apps/end_to_end_encryption/lib/Connector/Sabre/LockPlugin.php","Line":169,"CustomMessage":"--"},"userAgent":"Mozilla/5.0 (Macintosh) mirall/3.0.0git (build 3292) (Nextcloud)","version":"19.0.1.1","id":"5f44e2084a170"}

If you need the full log, ping me, I can email it to you.

For me it looks like that MOVING the files from one nextcloud folder into the encrypted one caused the problem. As a DIFFERENT test user I could add new files to an encrypted folder without issues.

@georgehrke
Copy link
Member

@misch7 @camilasan This issue seems to be isolated to the Desktop client. Can you reproduce it?
In that case i would move it to https://github.com/nextcloud/desktop/

@camilasan
Copy link
Member

Is the desktop client version 3.0?

@ho1ger
Copy link
Author

ho1ger commented Aug 25, 2020

Yepp.

@camilasan
Copy link
Member

Could you provide desktop client logs? Please run the client with --logdebug
https://docs.nextcloud.com/desktop/2.6/troubleshooting.html#log-files

@camilasan
Copy link
Member

Also If you ever tried end-to-end encryption before version 3.0, please follow the instructions from this post:
https://help.nextcloud.com/t/help-test-the-latest-version-of-e2ee/87590

to clean up the keys as that can break the functioning of >3.0 if you had a malformed key.

@bcutter
Copy link

bcutter commented Aug 29, 2020

As soon as E2E app is enabled desktop clients (3.0.0 / 3.0.1) sync like forever. Before enabling e2ee sync took few seconds, now one iteration doesn麓t matter if and how much to sync takes at least 5 minutes.

Significant load on the server (PHP-FPM and MYSQL). Even when the desktop client is closed server is still busy. Looks like there麓s an issue in terms of communication and server tries to satisfy huge mysql select requests (I guess on the filecache table).

iOS client sync works instantly, nevertheless the nextcloud/desktop guys pointed us over here (issue seems to be part of the server component).

Basically e2ee isn麓t usable currently so the "big bang blog announcement" ("production ready e2ee!") is far away from being true.

@mjanssens
Copy link

mjanssens commented Aug 29, 2020

I experienced similar issues:

  • substantial increase of cpu load and network traffic between my nextcloud server and separate DB server (postgresql)
  • slow and long sync from desktop client.

Unfortunately I did not find time to really troubleshoot in depth and poke through logging of all components, that's on my to do list. I disabled and uninstalled the E2E app in the server, but this load still remained, also after reboot of all components.
Shutting down nextcloud server resulted in normal load for the database server, starting it, load was back again.

But one thing I noticed during this increased load, there also was a substantial load increase (cpu and traffic) on my samba server.
At that moment I had a samba share configured inside nextcloud external storage.
So I deleted this share in external storage, load was normal again and it still is. So this is the workaround I use in my configuration.
I hope I can find some more clues soon.

edit: in the mean time I upgraded from NC 19.0.1 to 19.0.2, above behavior in this comment is not reproducible anymore.
Samba share doesn't seem to make any difference, so no relation I guess.
Now I have same behavior as https://github.com/nextcloud/end_to_end_encryption/issues/191#issuecomment-686662632

@kruthoff
Copy link

kruthoff commented Sep 3, 2020

I've observed the same, huge load on php-fpm and database (postgres).
E2E enabled. Desktop client 3.0.1 (linux). --logdebug is quiet. Add a file to the encrypted dir (I've 2 files, a txt and a png).

The following SQL statements are executed in the database, within miliseconds, millions of those(!):

2020-09-03 20:01:39.710 CEST [8361] www-data@nextcloud DETAIL: parameters: $1 = '3', $2 = '6f10dcb83941330bab331e98635e59bf' 2020-09-03 20:01:39.713 CEST [8361] www-data@nextcloud LOG: execute <unnamed>: SELECT "filecache"."fileid", "storage", "path", "path_hash", "filecache"."parent", "name", "mimetype", "mimepart", "size", "mtime", "storage_mtime", "encrypted", "etag", "permissions", "checksum", "metadata_etag", "creation_time", "upload_time" FROM "oc_filecache" "filecache" LEFT JOIN "oc_filecache_extended" "fe" ON "filecache"."fileid" = "fe"."fileid" WHERE ("storage" = $1) AND ("path_hash" = $2) 2020-09-03 20:01:39.713 CEST [8361] www-data@nextcloud DETAIL: parameters: $1 = '3', $2 = '45b963397aa40d4a0063e0d85e4fe7a1'

2020-09-03 20:01:39.715 CEST [8361] www-data@nextcloud LOG: execute <unnamed>: SELECT "filecache"."fileid", "storage", "path", "path_hash", "filecache"."parent", "name", "mimetype", "mimepart", "size", "mtime", "storage_mtime", "encrypted", "etag", "permissions", "checksum", "metadata_etag", "creation_time", "upload_time" FROM "oc_filecache" "filecache" LEFT JOIN "oc_filecache_extended" "fe" ON "filecache"."fileid" = "fe"."fileid" WHERE ("storage" = $1) AND ("path_hash" = $2) 2020-09-03 20:01:39.715 CEST [8361] www-data@nextcloud DETAIL: parameters: $1 = '3', $2 = 'd41d8cd98f00b204e9800998ecf8427e'

2020-09-03 20:01:39.717 CEST [8361] www-data@nextcloud LOG: execute <unnamed>: SELECT "filecache"."fileid", "storage", "path", "path_hash", "filecache"."parent", "name", "mimetype", "mimepart", "size", "mtime", "storage_mtime", "encrypted", "etag", "permissions", "checksum", "metadata_etag", "creation_time", "upload_time" FROM "oc_filecache" "filecache" LEFT JOIN "oc_filecache_extended" "fe" ON "filecache"."fileid" = "fe"."fileid" WHERE ("storage" = $1) AND ("path_hash" = $2)

I hope it helps to debug the issue.

As soon as I disable E2E on the server, things are stable as expected.

@bcutter
Copy link

bcutter commented Sep 5, 2020

I see similiar SELECT commands occupying the MySQL (and PHP-FPM) for a loooooooong time. What next?

@georgehrke
Copy link
Member

@kruthoff @bcutter Could either of you please check the access.log of the server. Just before the MySQL server's load starts going up, is there a lot of PROPFIND requests coming in?

@bcutter
Copy link

bcutter commented Sep 8, 2020

@kruthoff @bcutter Could either of you please check the access.log of the server. Just before the MySQL server's load starts going up, is there a lot of PROPFIND requests coming in?

Can't check currently sorry, maybe in a few days or @kruthoff is faster.

@kruthoff
Copy link

kruthoff commented Sep 8, 2020

@kruthoff @bcutter Could either of you please check the access.log of the server. Just before the MySQL server's load starts going up, is there a lot of PROPFIND requests coming in?

These are the access.log lines when a nextcloud client starts up. Not too much, I think.
access.log

The postgresql.log at the same time, oc_filecache table with 266063 entries, oc_filecache_extended table with 2240 entries. Looks like it's selecting the whole oc_filecache table...?
postgresql-11-main.log

@bcutter
Copy link

bcutter commented Oct 3, 2020

No activity... I can confirm this issue still persists with latest desktop client v3.0.2 and current Nextcloud v19.0.3.1.

@tobiasKaminsky
Copy link
Member

This is desktop related, so I move it to desktop repo.

@tobiasKaminsky tobiasKaminsky transferred this issue from nextcloud/end_to_end_encryption Oct 6, 2020
@tobiasKaminsky
Copy link
Member

@er-vin

@er-vin
Copy link
Member

er-vin commented Oct 6, 2020

@tobiasKaminsky got a couple of duplicates of that one already, actually I think it was good this one was on the e2ee app repository. Yes the desktop client is apparently revealing something but to me there are strong chances the bug is on the server side (could be wrong of course, but so far with all the data points I got I couldn't pin point it to something concrete on the client end).

What makes me think this is that very often in those cases, the client isn't doing much apart from waiting for a PROPFIND (in one of the reports I got it basically times out after a while), that can also be seen in some of the comments here where someone mention nothing happens in the client debug log but there's a storm of SQL requests going on server side. Clearly the client issued a command and waits for an answer that never comes because something went haywire on the server.

I'd like someone with knowledge on how that components work to actually look into it. If I'm right that'd explain all the "sync gets stuck when e2ee is in the mix" and "server load massively increased" reports which I got so far.

@bcutter
Copy link

bcutter commented Oct 16, 2020

Where to find someone with that specific knowledge - isn't this the place to look for one?

Unfortunately I'm struggling with it too from a users perspective while at the same time not being able to have a "developers view" on it.

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

Successfully merging a pull request may close this issue.

8 participants