Dropbox Synchronization fails (delete OC->DB)

[faulix]

Steps to reproduce

1. Configure OC-Dropbox synchronization
2. Delete files/folders in OC

Expected behaviour

Files should get deleted in Dropbox and OC.

Actual behaviour

Nothing, the web-interface shows the loading symbol forever (no error reported).

Server configuration

Operating system: Debian 8, Linux version 3.16.0-4-amd64

Web server: Apache/2.4.10
Database: mysql 5.5.49-0+deb8u1
PHP version: PHP 5.6.20-0+deb8u1
ownCloud version: 9.0.2 (stable)
Updated from an older ownCloud or fresh install: Fresh install
Where did you install ownCloud from: Package manager (APT)
Signing status (ownCloud 9.0 and above): No errors have been found.
List of activated apps:
Enabled:

• activity: 2.2.1
• calendar: 1.1
• comments: 0.2
• contacts: 1.2.0.0
• dav: 0.1.6
• federatedfilesharing: 0.1.0
• files: 1.4.4
• files_external: 0.5.2
• files_pdfviewer: 0.8.1
• files_sharing: 0.9.1
• files_texteditor: 2.1
• files_trashbin: 0.8.0
• files_versions: 1.2.0
• files_videoplayer: 0.9.8
• firstrunwizard: 1.1
• gallery: 14.5.0
• notifications: 0.2.3
• provisioning_api: 0.4.1
• systemtags: 0.2
• templateeditor: 0.1
• updatenotification: 0.1.0
  Disabled:
• encryption
• external
• federation
• files_antivirus
• user_external
• user_ldap

The content of config/config.php:
{
"system": {
"updatechecker": false,
"instanceid": "ocrjwhl0os72",
"passwordsalt": "_REMOVED SENSITIVE VALUE",
"secret": "_REMOVED SENSITIVE VALUE",
"trusted_domains": [
"stefankuhn.biz"
],
"datadirectory": "/var/www/owncloud/data",
"overwrite.cli.url": "https://mydomain.biz/owncloud",
"dbtype": "mysql",
"version": "9.0.2.2",
"dbname": "c4_owncloud",
"dbhost": "localhost",
"dbtableprefix": "oc_",
"dbuser": "_REMOVED SENSITIVE VALUE",
"dbpassword": "_REMOVED SENSITIVE VALUE",
"logtimezone": "UTC",
"installed": true,
"mail_smtpmode": "php",
"mail_smtpsecure": "ssl",
"mail_from_address": "owncloud",
"mail_domain": "mydomain.biz",
"mail_smtphost": "mail.mydomain.biz",
"mail_smtpport": "587",
"mail_smtpauth": 1
}
}

Are you using external storage, if yes which one: Dropbox
Are you using encryption: no
Are you using an external user-backend, if yes which one: No

Client configuration

Browser: Google Chrome Version 50.0.2661.94 (64-bit)
Operating system: Mac OS X 10.10.5 (14F1713)

Logs

Web server error log

Nothing

ownCloud log (data/owncloud.log)

{"reqId":"DacX6Oc9F6oIauzUJuTY","remoteAddr":"130.83.73.18","app":"files_external","message":"Resource at uri: https://api.dropbox.com/1/fileops/delete could not be found","level":3,"time":"2016-05-08T06:36:03+00:00","method":"DELETE","url":"/owncloud/remote.php/webdav/Dropbox-Privat/Mac-SIK/ServerSIK","user":"stefan"}
{"reqId":"DacX6Oc9F6oIauzUJuTY","remoteAddr":"130.83.73.18","app":"webdav","message":"Exception: {"Message":"HTTP\/1.1 423 \"Dropbox-Privat\/Mac-SIK\/ServerSIK\" is locked","Exception":"OCA\DAV\Connector\Sabre\Exception\FileLocked","Code":0,"Trace":"#0 \/var\/www\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Tree.php(179): OCA\DAV\Connector\Sabre\Directory->delete()\n#1 \/var\/www\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/CorePlugin.php(285): Sabre\DAV\Tree->delete('Dropbox-Privat\/...')\n#2 [internal function]: Sabre\DAV\CorePlugin->httpDelete(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))\n#3 \/var\/www\/owncloud\/3rdparty\/sabre\/event\/lib\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\n#4 \/var\/www\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Server.php(459): Sabre\Event\EventEmitter->emit('method:DELETE', Array)\n#5 \/var\/www\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Server.php(248): Sabre\DAV\Server->invokeMethod(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))\n#6 \/var\/www\/owncloud\/apps\/dav\/appinfo\/v1\/webdav.php(55): Sabre\DAV\Server->exec()\n#7 \/var\/www\/owncloud\/remote.php(138): require_once('\/var\/www\/ownclo...')\n#8 {main}","File":"\/var\/www\/owncloud\/apps\/dav\/lib\/connector\/sabre\/directory.php","Line":279,"User":"stefan"}","level":4,"time":"2016-05-08T06:36:03+00:00","method":"DELETE","url":"/owncloud/remote.php/webdav/Dropbox-Privat/Mac-SIK/ServerSIK","user":"stefan"}
{"reqId":"WQy9zAcuwoR72ey4dLVd","remoteAddr":"130.83.73.18","app":"files_external","message":"Resource at uri: https://api.dropbox.com/1/fileops/delete could not be found","level":3,"time":"2016-05-08T06:44:49+00:00","method":"DELETE","url":"/owncloud/remote.php/webdav/Dropbox-Privat/Mac-SIK/ServerSIK","user":"stefan"}
{"reqId":"WQy9zAcuwoR72ey4dLVd","remoteAddr":"130.83.73.18","app":"PHP","message":"fread() expects parameter 1 to be resource, boolean given at /var/www/owncloud/lib/private/files/storage/wrapper/encryption.php#849","level":3,"time":"2016-05-08T06:44:50+00:00","method":"DELETE","url":"/owncloud/remote.php/webdav/Dropbox-Privat/Mac-SIK/ServerSIK","user":"stefan"}
{"reqId":"WQy9zAcuwoR72ey4dLVd","remoteAddr":"130.83.73.18","app":"PHP","message":"fclose() expects parameter 1 to be resource, boolean given at /var/www/owncloud/lib/private/files/storage/wrapper/encryption.php#850","level":3,"time":"2016-05-08T06:44:50+00:00","method":"DELETE","url":"/owncloud/remote.php/webdav/Dropbox-Privat/Mac-SIK/ServerSIK","user":"stefan"}
{"reqId":"WQy9zAcuwoR72ey4dLVd","remoteAddr":"130.83.73.18","app":"files_external","message":"Resource at uri: https://api.dropbox.com/1/fileops/delete could not be found","level":3,"time":"2016-05-08T06:44:51+00:00","method":"DELETE","url":"/owncloud/remote.php/webdav/Dropbox-Privat/Mac-SIK/ServerSIK","user":"stefan"}

[faulix]

I checked it more detailed and added the JSON return of Dropbox to the error-log. That's the return:
{"read_only":false,"is_deleted":true,"revision":122052,"bytes":0,"thumb_exists":false,"rev":"1dcc404daff92","modified":"Sun, 08 May 2016 16:06:18 +0000","mime_type":"application/octet-stream","size":"0 bytes","path":"/Iconuf00d","is_dir":false,"modifier":null,"root":"dropbox","client_mtime":"Wed, 31 Dec 1969 23:59:59 +0000","icon":"page_white"}
As it shows the delete was successful, therefore the error shouldn't get thrown. Why it gets thrown I didn't investigate, but I believe now we are little bit closer to the problem.

The folder actually really gets deleted, but I need to refresh the window to see that.

[faulix]

Today I identified an additional problem: Because of Dropbox synchronization problems I had a ghost file in the file_cache, which caused the problem, that I couldn't delete the file neither synchronize it with my desktop client.
{"reqId":"4invgeU1qUdFVXVeUOBP","remoteAddr":"103.228.223.235","app":"webdav","message":"Exception: {\"Message\":\"HTTP\\\/1.1 503 Could not open file\",\"Exception\":\"Sabre\\\\DAV\\\\Exception\\\\ServiceUnavailable\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(83): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->get()\\n#1 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpGet(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#2 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#3 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(459): Sabre\\\\Event\\\\EventEmitter->emit('method:GET', Array)\\n#4 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(248): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#5 \\\/var\\\/www\\\/owncloud\\\/apps\\\/dav\\\/appinfo\\\/v1\\\/webdav.php(55): Sabre\\\\DAV\\\\Server->exec()\\n#6 \\\/var\\\/www\\\/owncloud\\\/remote.php(138): require_once('\\\/var\\\/www\\\/ownclo...')\\n#7 {main}\",\"File\":\"\\\/var\\\/www\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/connector\\\/sabre\\\/file.php\",\"Line\":306,\"User\":\"stefan\"}","level":4,"time":"2016-05-09T06:55:39+00:00","method":"GET","url":"\/owncloud\/remote.php\/webdav\/Dropbox-Privat\/FleetVision\/Syngenta\/xendpay.png","user":"stefan"}
I think in this case the cache should get flushed and regenerated or the file should get checked with dropbox again to avoid ghost files.

[PVince81]

Raised #24499 to auto-repair "ghost" files.

The alternative is running occ files:scan --all manually.

@faulix did your syncing work properly after deleting the ghost entry ?

[faulix]

@PVince81 the desktop client syncs normally now. The dropbox problem still exists, I assume there is something programmed wrong so it throws an exception (deletion unsuccessful), so the file doesn't get deleted from the file cache. Most of the time through synchronization Dropbox deletes afterwards the file in owncloud, but sometimes it creates ghost files.

[PVince81]

@faulix usually deleting a file will download+move the file to trash. I suspect that it's a big file and maybe it runs into a PHP request timeout

[faulix]

@PVince81 indeed it was a folder with more than 300MB files. So I don't know if the whole folder action is handles by one php execution or several. In case it's done by one execution I suggest to split it into several operations (X for each file) and storing them in a pending operations table. You can check the status with JSON and with each status check you start a new batch.
If we are only talking about a timeout because of the file size, then we might adapt the timeout for this execution by estimating the execution time based on the file size (i.e. XMB*2s).

[PVince81]

Yeah... that seems to fall under a similar category like #12097.
I'll make a new ticket to discuss this. So far ownCloud doesn't have such async file operation system, so it would be a huge change. Also, it might not be compatible with Webdav clients so the protocol might need to be changed/adjusted too.

Raised #24509.
Closing in favor of that one.

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.