Deleted files sometimes aren't deleted properly due to timestamp conflict

[mirekys]

Steps to reproduce

1. Have some files files possibly with a frequently occuring name/sub-path pattern in your storage:
   • /dir1/file.txt
   • /dir1/dir2/file.txt
   • /dir3/dir4/file.txt
     ...
     // this is just a hypothesis from observation, didn't manage to reproduce it by myself yet //
2. Delete /dir1/dir2/file.txt (will be moved to trash correctly)
3. Delete /dir1/file.txt (no entry created in oc_files_trash table, still presented as regular file, download fails)

Expected behaviour

Deleted files may not be presented by the server on its original path as regular files
and should be accessible through files_trashbin.

Actual behaviour

Deleted file is unlinked on underlying storage (on path 'data/userid/files/dir1/file.txt'), but is still presented together with other regular files on its original path on web, and in response to PROPFIND. Download fails with 404 (web) or 503 - Could not open file (sync client). Synchronization stops on that error.

Server configuration

Operating system:
RHEL 6.4

Web server:
Apache/2.4.12

Database:
PostgreSQL 9.2

PHP version:
5.6.5

ownCloud version:
8.2.2

Updated from an older ownCloud or fresh install:
from 8.1.5

Where did you install ownCloud from:
https://owncloud.org/changelog/

List of activated apps:

• activity: 2.1.3
• calendar: 0.8.2
• contacts: 0.5.0.0
• documents: 0.11.1
• files: 1.2.0
• files_pdfviewer: 0.7
• files_sharing: 0.7.0
• files_texteditor: 2.0
• files_trashbin: 0.7.0
• files_versions: 1.1.0
• firstrunwizard: 1.1
• notifications: 0.1.0

The content of config/config.php:
// unrelated items omitted //
'dbtype' => 'pgsql',
'version' => '8.2.2.2',
'installed' => true,
'forcessl' => true,
'maintenance' => false,
'enable_previews' => false,
'singleuser' => false,
'share_folder' => '/Shared',
'trashbin_retention_obligation' => 'auto',
'memcache.local' => '\OC\Memcache\APCu',
'memcache.locking' => '\OC\Memcache\Redis',
'allow_user_to_change_display_name' => true,
'asset-pipeline.enabled' => true,
'session_keepalive' => true,

Are you using external storage, if yes which one: local/smb/sftp/...
no
Are you using encryption: yes/no
no
Are you using an external user-backend, if yes which one: LDAP/ActiveDirectory/Webdav/...
no

Client configuration

Seen on:

• Mozilla/5.0 (Macintosh) mirall/2.1.1 (3 clients using 1 user account)
• Mozilla/5.0 (Windows) mirall/2.0.2

Logs

Web server error log

userid [28/Feb/2016:12:01:25 +0100] "DELETE /remote.php/webdav/documents/somedir/file.log HTTP/1.1" 403 193 "-" "Mozilla/5.0 (Macintosh) mirall/2.1.1"
userid [09/Mar/2016:20:05:58 +0100] "DELETE /remote.php/webdav/somedir/file.log HTTP/1.1" 403 193 "-" "Mozilla/5.0 (Macintosh) mirall/2.1.1"
userid [11/Mar/2016:09:11:26 +0100] "GET /remote.php/webdav/somedir/file.log HTTP/1.1" 503 221 "-" "Mozilla/5.0 (Macintosh) mirall/2.1.1"

ownCloud log (data/owncloud.log)

{"reqId":"XXX","remoteAddr":"XXX","app":"webdav","message":"Exception: {\"Message\":\"An exception occurred while executing 'UPDATE \\\"oc_filecache\\\" SET \\\"storage\\\" =  ?, \\\"path\\\" = ?, \\\"path_hash\\\" = ?, \\\"name\\\" = ?, \\\"parent\\\" =? WHERE \\\"fileid\\\" = ?' with params [1234, \\\"files_trashbin\\\\\\\/files\\\\\\\/file.log.d1456657282\\\", \\\"064a43c00ee3a548e9a04ac8b581c19a\\\", \\\"file.log.d1456657282\\\", 29989946, 31007805]:\\n\\nSQLSTATE[23505]: Unique violation: 7 ERROR:  duplicate key value violates unique constraint \\\"fs_storage_path_hash\\\"\\nDETAIL:  Key (storage, path_hash)=(1234, 064a43c00ee3a548e9a04ac8b581c19a) already exists.\",\"Exception\":\"Doctrine\\\\DBAL\\\\Exception\\\\UniqueConstraintViolationException\",\"Code\":0,\"Trace\":\"
#0 \\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/DBALException.php(116): Doctrine\\\\DBAL\\\\Driver\\\\AbstractPostgreSQLDriver->convertException('An exception oc...', Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOException))\\n
#1 \\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/Statement.php(172): Doctrine\\\\DBAL\\\\DBALException::driverExceptionDuringQuery(Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOPgSql\\\\Driver), Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOException), 'UPDATE \\\"oc_file...', Array)\\n
#2 \\\/lib\\\/private\\\/db\\\/statementwrapper.php(73): Doctrine\\\\DBAL\\\\Statement->execute(Array)\\n
#3 \\\/lib\\\/private\\\/db.php(147): OC_DB_StatementWrapper->execute(Array)\\n
#4 \\\/lib\\\/private\\\/files\\\/cache\\\/cache.php(500): OC_DB::executeAudited('UPDATE `*PREFIX...', Array)\\n
#5 \\\/lib\\\/private\\\/files\\\/cache\\\/cache.php(447): OC\\\\Files\\\\Cache\\\\Cache->moveFromCache(Object(OC\\\\Files\\\\Cache\\\\HomeCache), 'files\\\/documents...', 'files_trashbin\\\/...')\\n
#6 \\\/lib\\\/private\\\/files\\\/cache\\\/updater.php(179): OC\\\\Files\\\\Cache\\\\Cache->move('files\\\/documents...', 'files_trashbin\\\/...')\\n
#7 \\\/apps\\\/files_trashbin\\\/lib\\\/trashbin.php(225): OC\\\\Files\\\\Cache\\\\Updater->rename('\\\/files\\\/document...', '\\\/files_trashbin...')\\n
#8 \\\/apps\\\/files_trashbin\\\/lib\\\/storage.php(160): OCA\\\\Files_Trashbin\\\\Trashbin::move2trash('documents\\\/other...')\\n
#9 \\\/apps\\\/files_trashbin\\\/lib\\\/storage.php(95): OCA\\\\Files_Trashbin\\\\Storage->doDelete('files\\\/documents...', 'unlink')\\n
#10 \\\/lib\\\/private\\\/files\\\/view.php(1023): OCA\\\\Files_Trashbin\\\\Storage->unlink('files\\\/documents...')\\n
#11 \\\/lib\\\/private\\\/files\\\/view.php(604): OC\\\\Files\\\\View->basicOperation('unlink', '\\\/documents\\\/othe...', Array)\\n
#12 \\\/lib\\\/private\\\/connector\\\/sabre\\\/file.php(293): OC\\\\Files\\\\View->unlink('\\\/documents\\\/othe...')\\n
#13 \\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Tree.php(179): OC\\\\Connector\\\\Sabre\\\\File->delete()\\n
#14 \\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(287): Sabre\\\\DAV\\\\Tree->delete('documents\\\/other...')\\n
#15 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpDelete(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n
#16 \\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n
#17 \\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(469): Sabre\\\\Event\\\\EventEmitter->emit('method:DELETE', Array)\\n
#18 \\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n
#19 \\\/apps\\\/files\\\/appinfo\\\/remote.php(56): Sabre\\\\DAV\\\\Server->exec()\\n
#20 \\\/remote.php(137): require_once('\\\/gpfs\\\/owncloud\\\/...')\\n
#21 {main}\",\"File\":\"\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/Driver\\\/AbstractPostgreSQLDriver.php\",\"Line\":63}","level":4,"time":"2016-02-28T12:01:22+01:00"}
{"reqId":"XXX","remoteAddr":"XXX","app":"PHP","message":"fopen(\/data\/userid\/files\/somedir\/file.log): failed to open stream: No such file or directory at \/lib\/private\/files\/storage\/local.php#247","level":3,"time":"2016-03-11T09:11:27+01:00"}

[PVince81]

Weird duplicate key issue when inserting files into the trashbin.

@mirekys did you try deleting these files multiple times in the past ? Maybe something already created the trashbin entries and left them there and now re-deleting the same file fails with this error.

@schiesbn

[mirekys]

There are about 24 entries with the same id(filename) in the oc_files_trash table for that user. However,
each one comes from a different location. But there are 2 entries for the incriminated timestamp (.d1456657282). I believe that the same filename got deleted from both directories at the same time.

> SELECT * FROM oc_files_trash WHERE id LIKE '%file.log%' AND timestamp = '1456657282';
    id     |     user      | timestamp  |      location               | type | mime | auto_id 
-----------+---------------+------------+------------------------+------+------+---------
 file.log | userid | 1456657282 | documents/somedir  |         |         |  513310
 file.log | userid | 1456657282 | documents/anotherdir  |          |         |  513306

And there really is only one entry for that name in the filecache:

> SELECT * FROM oc_filecache WHERE name = 'file.log.d1456657282';
  fileid  | storage |                    path                    |            path_hash             |  parent  |         name          | mimetype | mimepart | size |   mtime    | storage_mtime | encrypted | unencrypted_size |     etag      | permissions 
----------+---------+--------------------------------------------+----------------------------------+----------+-----------------------+----------+----------+------+------------+---------------+-----------+------------------+---------------+-------------
 31007837 |    1234 | files_trashbin/files/file.log.d1456657282 | 064a43c00ee3a548e9a04ac8b581c19a | 29989946 | file.log.d1456657282 |       10 |        3 | 4775 | 1099587016 |    1099587016 |         0 |                0 | 55684106d0f91 |          27
(1 row)

More strangely, the second DELETE (from apache log above) failed partially without any further trace in logs, leaving the following in filecache.

> SELECT * FROM oc_filecache WHERE path = 'files/somedir/file.log';
  fileid  | storage |                  path                  |            path_hash             |  parent  |   name    | mimetype | mimepart | size |   mtime    | storage_mtime | encrypted | unencrypted_size |               etag               | permissions 
----------+---------+----------------------------------------+----------------------------------+----------+-----------+----------+----------+------+------------+---------------+-----------+------------------+----------------------------------+-------------
 70000264 |    1234 | files/somedir/file.log | d183a33bfae19c3c23dff51188d1747d | 70000263 | file.log |       10 |        3 | 8241 | 1174550418 |    1174550418 |         0 |                0 | ab32953d4c2e93b6fb60c69fd4db0489 |          27

No sign of that particular file in the oc_files_trash:

> SELECT * FROM oc_files_trash WHERE location = 'files/somedir' AND id = 'file.log';
 id | user | timestamp | location | type | mime | auto_id 
----+------+-----------+----------+------+------+---------
(0 rows)

And the file does no longer exist on the filesystem. I have tried to delete it on the web,
but it reappears on page reload and no error message is shown. Is it safe to run the
files:scan on the user's home to fix the issue?

[mirekys]

I have managed to reproduce the first problem:

• Create 2 files in 2 separate directories: a/test.txt (with content 'a') and b/test.txt (with content 'b').
• Delete both files exactly at the same time (I have done it using sync client)

rm -f {a,b}/test.txt

• Look into trashbin, you can restore only one of the files that got deleted last, the second one was overwritten:

cat data/userid/files_trashbin/files/test.txt.d1458208753
b

[PVince81]

Ahhhh, right, because they both get the same timestamp...

[mirekys]

Any news on this? Even if it affects an already deleted files, there still is some potential for data loss. Maybe something more unique like etag+timestamp should be used in a filename. Another way i can think of, is to put deleted files into a directory tree.

[PVince81]

Discussed this with @schiesbn and @nickvergessen a while ago, I don't remember the outcome though.

A simple way would be to add either the file id or the etag like you said into the file name.

[ownclouders]

Hey, this issue has been closed because the label status/STALE is set and there were no updates for 7 days. Feel free to reopen this issue if you deem it appropriate.

(This is an automated comment from GitMate.io.)