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

Smashbox test_basicSync fails when encryption is on #17956

Closed
PVince81 opened this issue Jul 29, 2015 · 25 comments
Closed

Smashbox test_basicSync fails when encryption is on #17956

PVince81 opened this issue Jul 29, 2015 · 25 comments
Labels

Comments

@PVince81
Copy link
Contributor

Steps

  1. Setup stable8.1 (73da1ca)
  2. Check out smashbox master (owncloud/smashbox@6a20846)
  3. Run the test_basicSync test with -a:

Expected result

No errors

Actual result:

± % bin/smash -a lib/test_basicSync.py                                                                                                                               
SUMMARY:smash.:runid: 150729-135958
SUMMARY:smash.:URL: http://test:***@127.0.0.1/owncloud/remote.php/webdav/
SUMMARY:smash.:Running iteration 1
SUMMARY:smash.:running lib/test_basicSync.py in /home/vincent/work/smashdir/test_basicSync as test testset #0 {'basicSync_filesizeKB': 1, 'basicSync_rmLocalStateDB': False}
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
SUMMARY:smash.:running lib/test_basicSync.py in /home/vincent/work/smashdir/test_basicSync as test testset #1 {'basicSync_filesizeKB': 5000, 'basicSync_rmLocalStateDB': False}
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
SUMMARY:smash.:running lib/test_basicSync.py in /home/vincent/work/smashdir/test_basicSync as test testset #2 {'basicSync_filesizeKB': 15000, 'basicSync_rmLocalStateDB': False}
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
SUMMARY:smash.:running lib/test_basicSync.py in /home/vincent/work/smashdir/test_basicSync as test testset #3 {'basicSync_filesizeKB': 50000, 'basicSync_rmLocalStateDB': False}
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
SUMMARY:smash.:running lib/test_basicSync.py in /home/vincent/work/smashdir/test_basicSync as test testset #4 {'basicSync_filesizeKB': 1, 'basicSync_rmLocalStateDB': True}
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
SUMMARY:smash.:running lib/test_basicSync.py in /home/vincent/work/smashdir/test_basicSync as test testset #5 {'basicSync_filesizeKB': 5000, 'basicSync_rmLocalStateDB': True}
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
SUMMARY:smash.:running lib/test_basicSync.py in /home/vincent/work/smashdir/test_basicSync as test testset #6 {'basicSync_filesizeKB': 15000, 'basicSync_rmLocalStateDB': False}
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
SUMMARY:smash.:running lib/test_basicSync.py in /home/vincent/work/smashdir/test_basicSync as test testset #7 {'basicSync_filesizeKB': 50000, 'basicSync_rmLocalStateDB': True}
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1
2015-07-29 14:03:39,349 - ERROR - checker - expected 2 got 1 deleted files error_check(len(expected_deleted_files) == len(actual_deleted_files), "expected %d got %d deleted files"%(len(expected_deleted_files),len(actual_deleted_files))) failed in expect_deleted_files() ["/home/vincent/work/workspace/smashbox/lib/test_basicSync.py" at line 70]
2015-07-29 14:03:39,351 - ERROR - checker - expected deleted file for TEST_FILE_DELETED_WINNER.dat not found error_check(any([fn in dfn for dfn in actual_deleted_files]), "expected deleted file for %s not found"%fn) failed in expect_deleted_files() ["/home/vincent/work/workspace/smashbox/lib/test_basicSync.py" at line 73]
2015-07-29 14:03:39,353 - ERROR - winner - expected 2 got 1 deleted files error_check(len(expected_deleted_files) == len(actual_deleted_files), "expected %d got %d deleted files"%(len(expected_deleted_files),len(actual_deleted_files))) failed in expect_deleted_files() ["/home/vincent/work/workspace/smashbox/lib/test_basicSync.py" at line 70]
2015-07-29 14:03:39,355 - ERROR - winner - expected deleted file for TEST_FILE_DELETED_WINNER.dat not found error_check(any([fn in dfn for dfn in actual_deleted_files]), "expected deleted file for %s not found"%fn) failed in expect_deleted_files() ["/home/vincent/work/workspace/smashbox/lib/test_basicSync.py" at line 73]
2015-07-29 14:03:39,402 - ERROR - creator - expected 2 got 1 deleted files error_check(len(expected_deleted_files) == len(actual_deleted_files), "expected %d got %d deleted files"%(len(expected_deleted_files),len(actual_deleted_files))) failed in expect_deleted_files() ["/home/vincent/work/workspace/smashbox/lib/test_basicSync.py" at line 70]
2015-07-29 14:03:39,404 - ERROR - creator - expected deleted file for TEST_FILE_DELETED_WINNER.dat not found error_check(any([fn in dfn for dfn in actual_deleted_files]), "expected deleted file for %s not found"%fn) failed in expect_deleted_files() ["/home/vincent/work/workspace/smashbox/lib/test_basicSync.py" at line 73]
md5sum: /home/vincent/work/smashdir/test_basicSync/checker/TEST_FILE_DELETED_WINNER.dat: No such file or directory
2015-07-29 14:03:39,495 - ERROR - checker - inconsistent md5 of /home/vincent/work/smashdir/test_basicSync/checker/TEST_FILE_DELETED_WINNER.dat: expected 863f3ed728e4ef9afa7de307f09f1bd1, got NO_CHECKSUM_ERROR error_check(actual_md5 == md5, "inconsistent md5 of %s: expected %s, got %s"%(fn,md5,actual_md5)) failed in expect_content() ["/home/vincent/work/workspace/smashbox/lib/test_basicSync.py" at line 61]
md5sum: /home/vincent/work/smashdir/test_basicSync/winner/TEST_FILE_DELETED_WINNER.dat: No such file or directory
2015-07-29 14:03:39,514 - ERROR - winner - inconsistent md5 of /home/vincent/work/smashdir/test_basicSync/winner/TEST_FILE_DELETED_WINNER.dat: expected 863f3ed728e4ef9afa7de307f09f1bd1, got NO_CHECKSUM_ERROR error_check(actual_md5 == md5, "inconsistent md5 of %s: expected %s, got %s"%(fn,md5,actual_md5)) failed in expect_content() ["/home/vincent/work/workspace/smashbox/lib/test_basicSync.py" at line 61]
md5sum: /home/vincent/work/smashdir/test_basicSync/creator/TEST_FILE_DELETED_WINNER.dat: No such file or directory
2015-07-29 14:03:39,546 - ERROR - creator - inconsistent md5 of /home/vincent/work/smashdir/test_basicSync/creator/TEST_FILE_DELETED_WINNER.dat: expected 863f3ed728e4ef9afa7de307f09f1bd1, got NO_CHECKSUM_ERROR error_check(actual_md5 == md5, "inconsistent md5 of %s: expected %s, got %s"%(fn,md5,actual_md5)) failed in expect_content() ["/home/vincent/work/workspace/smashbox/lib/test_basicSync.py" at line 61]
2015-07-29 14:03:40,545 - ERROR - creator - 3 error(s) reported
2015-07-29 14:03:40,550 - ERROR - winner - 3 error(s) reported
2015-07-29 14:03:40,550 - ERROR - checker - 3 error(s) reported
CRITICAL:smash.:Aborting run -- non-zero exit code (2)

@schiesbn please have a look. Thanks.

@PVince81
Copy link
Contributor Author

Disabling files_locking did not solve the issue.
It also happens when running only that test set alone (the one with 500000 bytes files)

owncloud.log shows this:

{"reqId":"wmvLEZTPBrbwUvFzKOO6","remoteAddr":"127.0.0.1","app":"ocs_api","message":"Successful addUser call with userid: test","level":1,"time":"2015-07-30T10:31:11+00:00","method":"POST","url":"\/owncloud\/ocs\/v1.php\/cloud\/users"}
{"reqId":"ZUC\/MxvGoNVhLNZAVp65","remoteAddr":"127.0.0.1","app":"files_skeleton","message":"copying skeleton for test from \/srv\/www\/htdocs\/owncloud\/core\/skeleton to \/test\/files\/","level":0,"time":"2015-07-30T10:31:11+00:00","method":"GET","url":"\/owncloud\/index.php"}
{"reqId":"\/zFnCgyW5r96odRPleWq","remoteAddr":"127.0.0.1","app":"webdav","message":"Exception: {\"Message\":\"HTTP\\\/1.1 500 An exception occurred while executing 'UPDATE `oc_filecache` SET `mtime` = ?, `size` = ?, `etag` = ?, `storage_mtime` = ?, `parent`=? WHERE (`mtime` <> ? OR `size` <> ? OR `etag` <> ? OR `storage_mtime` <> ? OR `parent` <> ? ) AND `fileid` = ? ' with params [1438252307, -1, \\\"55b9fd137bd9d\\\", 1438252307, null, 1438252307, -1, \\\"55b9fd137bd9d\\\", 1438252307, null, 1693]:\\n\\nSQLSTATE[23000]: Integrity constraint violation: 1048 Column 'parent' cannot be null\",\"Code\":0,\"Trace\":\"
#0 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/file.php(398): OC\\\\Connector\\\\Sabre\\\\File->convertToSabreException(Object(Doctrine\\\\DBAL\\\\Exception\\\\NotNullConstraintViolationException))\\n
#1 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/file.php(100): OC\\\\Connector\\\\Sabre\\\\File->createFileChunked(Resource id #262)\\n
#2 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/directory.php(113): OC\\\\Connector\\\\Sabre\\\\File->put(Resource id #262)\\n
#3 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1053): OC\\\\Connector\\\\Sabre\\\\Directory->createFile('TEST_FILE_DELET...', Resource id #262)\\n
#4 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(513): Sabre\\\\DAV\\\\Server->createFile('TEST_FILE_DELET...', Resource id #262, NULL)\\n
#5 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n
#6 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n
#7 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(469): Sabre\\\\Event\\\\EventEmitter->emit('method:PUT', Array)\\n
#8 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n
#9 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/apps\\\/files\\\/appinfo\\\/remote.php(83): Sabre\\\\DAV\\\\Server->exec()\\n
#10 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/remote.php(132): require_once('\\\/srv\\\/www\\\/htdocs...')\\n
#11 {main}\",\"File\":\"\\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/file.php\",\"Line\":460}","level":4,"time":"2015-07-30T10:31:47+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/TEST_FILE_DELETED_WINNER.dat-chunking-3657632047-10-9"}

@PVince81
Copy link
Contributor Author

I tried logging the cause too:


{
  "reqId": "K7JymF99thhOQiDpYy\\/U",
  "remoteAddr": "127.0.0.1",
  "app": "ocs_api",
  "message": "Successful addUser call with userid: test",
  "level": 1,
  "time": "2015-07-30T10:35:48+00:00",
  "method": "POST",
  "url": "\\/owncloud\\/ocs\\/v1.php\\/cloud\\/users"
}
{
  "reqId": "IZVtV0RTqHOm+hivJbKC",
  "remoteAddr": "127.0.0.1",
  "app": "files_skeleton",
  "message": "copying skeleton for test from \\/srv\\/www\\/htdocs\\/owncloud\\/core\\/skeleton to \\/test\\/files\\/",
  "level": 0,
  "time": "2015-07-30T10:35:48+00:00",
  "method": "GET",
  "url": "\\/owncloud\\/index.php"
}
{
  "reqId": "nwU3pWuw339hEPZcake8",
  "remoteAddr": "127.0.0.1",
  "app": "webdav",
  "message": "Exception: {\"Message\":\"An exception occurred while executing 'UPDATE `oc_filecache` SET `mtime` = ?, `size` = ?, `etag` = ?, `storage_mtime` = ?, `parent`=? WHERE (`mtime` <> ? OR `size` <> ? OR `etag` <> ? OR `storage_mtime` <> ? OR `parent` <> ? ) AND `fileid` = ? ' with params [1438252582, -1, \\\"55b9fe2654251\\\", 1438252582, null, 1438252582, -1, \\\"55b9fe2654251\\\", 1438252582, null, 2144]:\n\nSQLSTATE[23000]: Integrity constraint violation: 1048 Column 'parent' cannot be null\",\"Code\":0,\"Trace\":\"
#0 /srv/www/htdocs/owncloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/DBALException.php(116): Doctrine\DBAL\Driver\AbstractMySQLDriver->convertException('An exception oc...', Object(Doctrine\DBAL\Driver\PDOException))\n
#1 /srv/www/htdocs/owncloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Statement.php(172): Doctrine\DBAL\DBALException::driverExceptionDuringQuery(Object(Doctrine\DBAL\Driver\PDOMySql\Driver), Object(Doctrine\DBAL\Driver\PDOException), 'UPDATE `oc_file...', Array)\n
#2 /srv/www/htdocs/owncloud/lib/private/db/statementwrapper.php(73): Doctrine\DBAL\Statement->execute(Array)\n
#3 /srv/www/htdocs/owncloud/lib/private/db.php(147): OC_DB_StatementWrapper->execute(Array)\n
#4 /srv/www/htdocs/owncloud/lib/private/files/cache/cache.php(364): OC_DB::executeAudited('UPDATE `*PREFIX...', Array)\n
#5 /srv/www/htdocs/owncloud/lib/private/files/cache/scanner.php(222): OC\Files\Cache\Cache->update(2144, Array)\n
#6 /srv/www/htdocs/owncloud/lib/private/files/cache/scanner.php(188): OC\Files\Cache\Scanner->addToCache('files_encryptio...', Array, 2144)\n
#7 /srv/www/htdocs/owncloud/lib/private/files/cache/scanner.php(265): OC\Files\Cache\Scanner->scanFile('files_encryptio...', 3, -1, NULL, false)\n
#8 /srv/www/htdocs/owncloud/lib/private/files/cache/updater.php(114): OC\Files\Cache\Scanner->scan('files_encryptio...', false, -1, false)\n
#9 /srv/www/htdocs/owncloud/lib/private/files/view.php(1021): OC\Files\Cache\Updater->update('/test/files_enc...')\n
#10 /srv/www/htdocs/owncloud/lib/private/files/view.php(246): OC\Files\View->basicOperation('mkdir', '/test/files_enc...', Array)\n
#11 /srv/www/htdocs/owncloud/lib/private/encryption/keys/storage.php(314): OC\Files\View->mkdir('/test/files_enc...')\n
#12 /srv/www/htdocs/owncloud/lib/private/encryption/keys/storage.php(205): OC\Encryption\Keys\Storage->keySetPreparation('/test/files_enc...')\n
#13 /srv/www/htdocs/owncloud/lib/private/encryption/keys/storage.php(111): OC\Encryption\Keys\Storage->setKey('/test/files_enc...', '\\\xC4Rs]\x9F\xF8\x8B\xD5\xCD\xC9\x9DD\x9A\xC5...')\n
#14 /srv/www/htdocs/owncloud/apps/encryption/lib/keymanager.php(269): OC\Encryption\Keys\Storage->setFileKey('/test/files/TES...', 'fileKey', '\\\xC4Rs]\x9F\xF8\x8B\xD5\xCD\xC9\x9DD\x9A\xC5...', 'OC_DEFAULT_MODU...')\n
#15 /srv/www/htdocs/owncloud/apps/encryption/lib/keymanager.php(279): OCA\Encryption\KeyManager->setFileKey('/test/files/TES...', '\\\xC4Rs]\x9F\xF8\x8B\xD5\xCD\xC9\x9DD\x9A\xC5...')\n
#16 /srv/www/htdocs/owncloud/apps/encryption/lib/crypto/encryption.php(206): OCA\Encryption\KeyManager->setAllFileKeys('/test/files/TES...', Array)\n
#17 /srv/www/htdocs/owncloud/lib/private/files/stream/encryption.php(396): OCA\Encryption\Crypto\Encryption->end('/test/files/TES...')\n
#18 [internal function]: OC\Files\Stream\Encryption->stream_close()\n
#19 /srv/www/htdocs/owncloud/lib/private/filechunking.php(220): fclose(Resource id #338)\n
#20 /srv/www/htdocs/owncloud/lib/private/connector/sabre/file.php(363): OC_FileChunking->file_assemble('//TEST_FILE_DEL...')\n
#21 /srv/www/htdocs/owncloud/lib/private/connector/sabre/file.php(100): OC\Connector\Sabre\File->createFileChunked(Resource id #262)\n
#22 /srv/www/htdocs/owncloud/lib/private/connector/sabre/directory.php(113): OC\Connector\Sabre\File->put(Resource id #262)\n
#23 /srv/www/htdocs/owncloud/3rdparty/sabre/dav/lib/DAV/Server.php(1053): OC\Connector\Sabre\Directory->createFile('TEST_FILE_DELET...', Resource id #262)\n
#24 /srv/www/htdocs/owncloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php(513): Sabre\DAV\Server->createFile('TEST_FILE_DELET...', Resource id #262, NULL)\n
#25 [internal function]: Sabre\DAV\CorePlugin->httpPut(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))\n
#26 /srv/www/htdocs/owncloud/3rdparty/sabre/event/lib/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\n
#27 /srv/www/htdocs/owncloud/3rdparty/sabre/dav/lib/DAV/Server.php(469): Sabre\Event\EventEmitter->emit('method:PUT', Array)\n
#28 /srv/www/htdocs/owncloud/3rdparty/sabre/dav/lib/DAV/Server.php(254): Sabre\DAV\Server->invokeMethod(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))\n
#29 /srv/www/htdocs/owncloud/apps/files/appinfo/remote.php(83): Sabre\DAV\Server->exec()\n
#30 /srv/www/htdocs/owncloud/remote.php(132): require_once('/srv/www/htdocs...')\n
#31 {main}\",\"File\":\"/srv/www/htdocs/owncloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Driver/AbstractMySQLDriver.php\",\"Line\":112}",
  "level": 4,
  "time": "2015-07-30T10:36:22+00:00",
  "method": "PUT",
  "url": "\\/owncloud\\/remote.php\\/webdav\\/TEST_FILE_DELETED_WINNER.dat-chunking-3657632730-10-9"
}

@schiessle
Copy link
Contributor

Tried it three times but couldn't reproduce it

@PVince81
Copy link
Contributor Author

Looks like another weird race condition. For some very strange reason it is trying to update the cache entry of a file, but tries to set the "parent" column to null which is an invalid value.

I'll try and debug it.

@PVince81
Copy link
Contributor Author

Tried again with SQLite and it works fine.

The stack trace shows some strange characters "\x9F\xF8\x8B\xD5\xCD\xC9\x9DD\x9A\xC5", possibly randomly generated. As per another discussion today it was said that Mariadb had trouble with some UTF-8 characters.
Some part of the code is trying to find the parent folder to add an entry for the child. If the parent folder cannot be found because of UTF-8 mismatch, then the returned parent id is null, which fits the error.

Will try and dig deeper.

@PVince81
Copy link
Contributor Author

Just realized the strange characters are actually the file key, not the file name.

Still, there is something that breaks with Mysql that doesn't in SQLite.

@DeepDiver1975
Copy link
Member

Can somebody fire up the same on postgres?

@PVince81
Copy link
Contributor Author

It seems that I have messed up the test cases (I edited test_basicSync to have a single test case only and mistakenly reset my changes).

Tried again with SQLite: FAIL
And MySQL: FAIL

Sorry for the confusion.
I'll try and dig deeper.

@PVince81
Copy link
Contributor Author

Ok, got more info.

First, that specific test case with 500k is using chunking. The others don't.

The problem is that encryption is trying to store keys here:
'files_encryption/keys/files/TEST_FILE_DELETED_WINNER.dat.ocTransferId3657487546.part/OC_DEFAULT_MODULE'

As you can see this is a ".part" folder.
However ".part" files and folders are never indexed in oc_filecache.

This means that the previous call to $this->scanFile() on that ".part" folder did not return any data, and this is the reason why $data['parent'] is null.

Now the mysterious part is why this works on @schiesbn's computer and why we didn't spot this earlier.

@PVince81
Copy link
Contributor Author

v8.1.0 works fine. I'll bisect.

@DeepDiver1975
Copy link
Member

v8.1.0 works fine. I'll bisect.

THX - you rock!

@PVince81
Copy link
Contributor Author

Wrong again. Seems I forgot to enable encryption when resetting to v8.1.0 😡
v8.1.0 also fails. I'll try travelling even further back in time then.

@PVince81
Copy link
Contributor Author

Hmmm, I just tried with the sync client and the "parent == null" situation happens, but doesn't cause any errors:

{"reqId":"3qcxuNO1fYXsYqh8r9Pq","remoteAddr":"127.0.0.1","app":"ENCDEBUG","message":"addToCache: \"files_encryption\/keys\/files\/data1.dat.ocTransferId3145437456.part\/OC_DEFAULT_MODULE\" {\"mimetype\":\"httpd\\\/unix-directory\",\"mtime\":1438264288,\"size\":-1,\"etag\":\"55ba2be0a3d09\",\"storage_mtime\":1438264288,\"permissions\":31,\"parent\":null}","level":0,"time":"2015-07-30T13:51:28+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/data1.dat-chunking-3145437456-25-24"}
{"reqId":"3qcxuNO1fYXsYqh8r9Pq","remoteAddr":"127.0.0.1","app":"ENCDEBUG","message":"addToCache: \"files_encryption\/keys\/files\/data1.dat.ocTransferId3145437456.part\/OC_DEFAULT_MODULE\/fileKey\" {\"mimetype\":\"application\\\/octet-stream\",\"mtime\":1438264288,\"size\":44,\"etag\":\"7678be977a1fa73ae6ae5a037858ac2c\",\"storage_mtime\":1438264288,\"permissions\":27,\"parent\":\"578\"}","level":0,"time":"2015-07-30T13:51:28+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/data1.dat-chunking-3145437456-25-24"}

It is still a bogus situation that we need to avoid.

@PVince81
Copy link
Contributor Author

This is the stack trace leading to addToCache when using the sync client directly with a big file:

0  OC\Files\Cache\Scanner->addToCache() /srv/www/htdocs/owncloud/lib/private/files/cache/scanner.php:220
1  OC\Files\Cache\Scanner->scanFile() /srv/www/htdocs/owncloud/lib/private/files/cache/scanner.php:188
2  OC\Files\Cache\Scanner->scan() /srv/www/htdocs/owncloud/lib/private/files/cache/scanner.php:269
3  OC\Files\Cache\Updater->update() /srv/www/htdocs/owncloud/lib/private/files/cache/updater.php:114
4  OC\Files\View->basicOperation() /srv/www/htdocs/owncloud/lib/private/files/view.php:1021
5  OC\Files\View->mkdir() /srv/www/htdocs/owncloud/lib/private/files/view.php:246
6  OC\Encryption\Keys\Storage->keySetPreparation() /srv/www/htdocs/owncloud/lib/private/encryption/keys/storage.php:314
7  OC\Encryption\Keys\Storage->setKey() /srv/www/htdocs/owncloud/lib/private/encryption/keys/storage.php:205
8  OC\Encryption\Keys\Storage->setFileKey() /srv/www/htdocs/owncloud/lib/private/encryption/keys/storage.php:111
9  OCA\Encryption\KeyManager->setFileKey() /srv/www/htdocs/owncloud/apps/encryption/lib/keymanager.php:269
10 OCA\Encryption\KeyManager->setAllFileKeys() /srv/www/htdocs/owncloud/apps/encryption/lib/keymanager.php:279
11 OCA\Encryption\Crypto\Encryption->end() /srv/www/htdocs/owncloud/apps/encryption/lib/crypto/encryption.php:206
12 OC\Files\Stream\Encryption->stream_close() /srv/www/htdocs/owncloud/lib/private/files/stream/encryption.php:396
13 fclose()        /srv/www/htdocs/owncloud/lib/private/filechunking.php:220
14 OC_FileChunking->file_assemble() /srv/www/htdocs/owncloud/lib/private/filechunking.php:220
15 OC\Connector\Sabre\File->createFileChunked() /srv/www/htdocs/owncloud/lib/private/connector/sabre/file.php:363
16 OC\Connector\Sabre\File->put() /srv/www/htdocs/owncloud/lib/private/connector/sabre/file.php:100
17 OC\Connector\Sabre\Directory->createFile() /srv/www/htdocs/owncloud/lib/private/connector/sabre/directory.php:113
18 Sabre\DAV\Server->createFile() /srv/www/htdocs/owncloud/3rdparty/sabre/dav/lib/DAV/Server.php:1053
19 Sabre\DAV\CorePlugin->httpPut() /srv/www/htdocs/owncloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php:513
20 call_user_func_array:{/srv/www/htdocs/owncloud/3rdparty/sabre/event/lib/EventEmitterTrait.php:105}() /srv/www/htdocs/owncloud/3rdparty/sabre/event/lib/EventEmitterTrait.php:105
21 Sabre\Event\EventEmitter->emit() /srv/www/htdocs/owncloud/3rdparty/sabre/event/lib/EventEmitterTrait.php:105
22 Sabre\DAV\Server->invokeMethod() /srv/www/htdocs/owncloud/3rdparty/sabre/dav/lib/DAV/Server.php:469
23 Sabre\DAV\Server->exec() /srv/www/htdocs/owncloud/3rdparty/sabre/dav/lib/DAV/Server.php:254
24 require_once()  /srv/www/htdocs/owncloud/apps/files/appinfo/remote.php:83
25 {main}          /srv/www/htdocs/owncloud/remote.php:132

The difference with test_basicSync is that the target folder does not exist at all:

$path                            = (string[83]) 'files_encryption/keys/files/data1.dat.ocTransferId4040295251.part/OC_DEFAULT_MODULE';

The "data1.dat.ocTransferId4040295251.part" doesn't exist on disk.

However with test_basicSync, that folder already existed.

Apparently doing an INSERT with a null parent is acceptable, but not an UPDATE.
Note that the "UPDATE" operation has a WHERE clause to avoid updating values that already exist (for performance), and it's the WHERE clause that fails when we say "parent === null". Well maybe it should be rewritten as "parent is null" then.
That would be the quickfix...

But in general the bigger issue is that the ".part" folder has no entry because part files are never indexed. So basically there's a hole in the tree in oc_filecache if we let it through.

So the following points have been identified:

  1. Syncing with sync client and chunking creates a part folder that does not get indexed. There is a hole in the tree during the upload because part folders are not indexed. So there is no entry for "files_encryption/keys/files/data1.dat.ocTransferId4040295251.part" but there is one for its subdir "files_encryption/keys/files/data1.dat.ocTransferId4040295251.part/OC_DEFAULT_MODULE". The hole disappears as soon as the part file is renamed to the final file.

  2. The hole above doesn't cause any errors because INSERT is used

  3. In the case of test_basicSync with parallel upload, something is causing the folder entry to already exist (still unexplained), so instead of INSERT it does an UPDATE. Update: it's a transferid collision, see explanation later Smashbox test_basicSync fails when encryption is on #17956 (comment)

  4. The UPDATE operation has a problem with "parent == null" while INSERT doesn't.

We can fix 4) short-term to make it work. But 3) is still unexplained.
Long-term we need to fix 1) to avoid holes in the tree.

@schiesbn @icewind1991 @DeepDiver1975 thoughts ?

@PVince81
Copy link
Contributor Author

Another alternative is to allow ".part" folders to be indexed, but not files (unless one day we really use .part folders for something else #13756). Might need checking the mime type at insertion time though...

@PVince81
Copy link
Contributor Author

@schiesbn why aren't we stripping ocTransferId + .part any more ? I thought that when overwriting a file we'd just reuse the same keys ?
It seems that this new approach (compared to OC 8.0) it would create a new set of keys for the part file, which would be kept when renaming to the final file ?

@schiessle
Copy link
Contributor

@PVince81 the final keys get renamed with the final file because all this happens in the storage wrapper now which gets called for part files the same way it get called for real files. This makes it much easier with less exceptions and special cases.

@PVince81
Copy link
Contributor Author

I'm trying to analyze 3). It is very strange that it tries to recreate the OC_DEFAULT_MODULE folder twice for the same transfer id but not when done with the regular sync client.

By the way I have sync client owncloud-client-1.8.4-2.5.x86_64

Here is with the regular sync client:

{"reqId":"SNpu7kiuKjBFUo5xzuYE","remoteAddr":"127.0.0.1","app":"ENCDEBUG","message":"file_assemble: \/\/data3.dat.ocTransferId2717706887.part","level":0,"time":"2015-07-30T14:53:30+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/data3.dat-chunking-2717706887-25-24"}
{"reqId":"SNpu7kiuKjBFUo5xzuYE","remoteAddr":"127.0.0.1","app":"ENCDEBUG","message":"addToCache: \"files_encryption\/keys\/files\/data3.dat.ocTransferId2717706887.part\/OC_DEFAULT_MODULE\" {\"mimetype\":\"httpd\\\/unix-directory\",\"mtime\":1438268012,\"size\":-1,\"etag\":\"55ba3a6c8df78\",\"storage_mtime\":1438268012,\"permissions\":31,\"parent\":null}","level":0,"time":"2015-07-30T14:53:32+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/data3.dat-chunking-2717706887-25-24"}
{"reqId":"SNpu7kiuKjBFUo5xzuYE","remoteAddr":"127.0.0.1","app":"ENCDEBUG","message":"Cache::put: \"files_encryption\/keys\/files\/data3.dat.ocTransferId2717706887.part\/OC_DEFAULT_MODULE\" {\"mimetype\":\"httpd\\\/unix-directory\",\"mtime\":1438268012,\"size\":-1,\"etag\":\"55ba3a6c8df78\",\"storage_mtime\":1438268012,\"permissions\":31,\"parent\":null}","level":0,"time":"2015-07-30T14:53:32+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/data3.dat-chunking-2717706887-25-24"}
{"reqId":"SNpu7kiuKjBFUo5xzuYE","remoteAddr":"127.0.0.1","app":"ENCDEBUG","message":"addToCache: \"files_encryption\/keys\/files\/data3.dat.ocTransferId2717706887.part\/OC_DEFAULT_MODULE\/fileKey\" {\"mimetype\":\"application\\\/octet-stream\",\"mtime\":1438268012,\"size\":44,\"etag\":\"dd8522a9d56596825ec7fb69e8f5e7e6\",\"storage_mtime\":1438268012,\"permissions\":27,\"parent\":\"570\"}","level":0,"time":"2015-07-30T14:53:32+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/data3.dat-chunking-2717706887-25-24"}
{"reqId":"SNpu7kiuKjBFUo5xzuYE","remoteAddr":"127.0.0.1","app":"ENCDEBUG","message":"Cache::put: \"files_encryption\/keys\/files\/data3.dat.ocTransferId2717706887.part\/OC_DEFAULT_MODULE\/fileKey\" {\"mimetype\":\"application\\\/octet-stream\",\"mtime\":1438268012,\"size\":44,\"etag\":\"dd8522a9d56596825ec7fb69e8f5e7e6\",\"storage_mtime\":1438268012,\"permissions\":27,\"parent\":\"570\"}","level":0,"time":"2015-07-30T14:53:32+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/data3.dat-chunking-2717706887-25-24"}
{"reqId":"SNpu7kiuKjBFUo5xzuYE","remoteAddr":"127.0.0.1","app":"ENCDEBUG","message":"addToCache: \"files_encryption\/keys\/files\/data3.dat.ocTransferId2717706887.part\/OC_DEFAULT_MODULE\/root.shareKey\" {\"mimetype\":\"application\\\/octet-stream\",\"mtime\":1438268012,\"size\":512,\"etag\":\"2b2c34603cf98a539c9ebfd077c2667d\",\"storage_mtime\":1438268012,\"permissions\":27,\"parent\":\"570\"}","level":0,"time":"2015-07-30T14:53:32+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/data3.dat-chunking-2717706887-25-24"}
{"reqId":"SNpu7kiuKjBFUo5xzuYE","remoteAddr":"127.0.0.1","app":"ENCDEBUG","message":"Cache::put: \"files_encryption\/keys\/files\/data3.dat.ocTransferId2717706887.part\/OC_DEFAULT_MODULE\/root.shareKey\" {\"mimetype\":\"application\\\/octet-stream\",\"mtime\":1438268012,\"size\":512,\"etag\":\"2b2c34603cf98a539c9ebfd077c2667d\",\"storage_mtime\":1438268012,\"permissions\":27,\"parent\":\"570\"}","level":0,"time":"2015-07-30T14:53:32+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/data3.dat-chunking-2717706887-25-24"}

Here we can see that file_assemble is done once, and after that the keys are written.
This means the part folder only gets created once, then its contents get written.

But now look what happens with test_basicSync:

{"reqId":"V4DTQqCkvfNrbvOpG5Br","remoteAddr":"127.0.0.1","app":"ENCDEBUG","message":"file_assemble: \/\/TEST_FILE_DELETED_WINNER.dat.ocTransferId3657486019.part","level":0,"time":"2015-07-30T14:56:32+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-9"}
{"reqId":"V4DTQqCkvfNrbvOpG5Br","remoteAddr":"127.0.0.1","app":"ENCDEBUG","message":"addToCache: \"files_encryption\/keys\/files\/TEST_FILE_DELETED_WINNER.dat.ocTransferId3657486019.part\/OC_DEFAULT_MODULE\" {\"mimetype\":\"httpd\\\/unix-directory\",\"mtime\":1438268193,\"size\":-1,\"etag\":\"55ba3b21a3a9a\",\"storage_mtime\":1438268193,\"permissions\":31,\"parent\":null}","level":0,"time":"2015-07-30T14:56:33+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-9"}
{"reqId":"V4DTQqCkvfNrbvOpG5Br","remoteAddr":"127.0.0.1","app":"ENCDEBUG","message":"Cache::put: \"files_encryption\/keys\/files\/TEST_FILE_DELETED_WINNER.dat.ocTransferId3657486019.part\/OC_DEFAULT_MODULE\" {\"mimetype\":\"httpd\\\/unix-directory\",\"mtime\":1438268193,\"size\":-1,\"etag\":\"55ba3b21a3a9a\",\"storage_mtime\":1438268193,\"permissions\":31,\"parent\":null}","level":0,"time":"2015-07-30T14:56:33+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-9"}
{"reqId":"V4DTQqCkvfNrbvOpG5Br","remoteAddr":"127.0.0.1","app":"ENCDEBUG","message":"addToCache: \"files_encryption\/keys\/files\/TEST_FILE_DELETED_WINNER.dat.ocTransferId3657486019.part\/OC_DEFAULT_MODULE\/fileKey\" {\"mimetype\":\"application\\\/octet-stream\",\"mtime\":1438268193,\"size\":44,\"etag\":\"fbf1f6fda21ace36c723f8bd5c34bb17\",\"storage_mtime\":1438268193,\"permissions\":27,\"parent\":\"629\"}","level":0,"time":"2015-07-30T14:56:33+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-9"}
{"reqId":"V4DTQqCkvfNrbvOpG5Br","remoteAddr":"127.0.0.1","app":"ENCDEBUG","message":"Cache::put: \"files_encryption\/keys\/files\/TEST_FILE_DELETED_WINNER.dat.ocTransferId3657486019.part\/OC_DEFAULT_MODULE\/fileKey\" {\"mimetype\":\"application\\\/octet-stream\",\"mtime\":1438268193,\"size\":44,\"etag\":\"fbf1f6fda21ace36c723f8bd5c34bb17\",\"storage_mtime\":1438268193,\"permissions\":27,\"parent\":\"629\"}","level":0,"time":"2015-07-30T14:56:33+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-9"}
{"reqId":"V4DTQqCkvfNrbvOpG5Br","remoteAddr":"127.0.0.1","app":"ENCDEBUG","message":"addToCache: \"files_encryption\/keys\/files\/TEST_FILE_DELETED_WINNER.dat.ocTransferId3657486019.part\/OC_DEFAULT_MODULE\/test.shareKey\" {\"mimetype\":\"application\\\/octet-stream\",\"mtime\":1438268193,\"size\":512,\"etag\":\"cbcc459b9ba647a8bea9ec0c001f9f79\",\"storage_mtime\":1438268193,\"permissions\":27,\"parent\":\"629\"}","level":0,"time":"2015-07-30T14:56:33+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-9"}
{"reqId":"V4DTQqCkvfNrbvOpG5Br","remoteAddr":"127.0.0.1","app":"ENCDEBUG","message":"Cache::put: \"files_encryption\/keys\/files\/TEST_FILE_DELETED_WINNER.dat.ocTransferId3657486019.part\/OC_DEFAULT_MODULE\/test.shareKey\" {\"mimetype\":\"application\\\/octet-stream\",\"mtime\":1438268193,\"size\":512,\"etag\":\"cbcc459b9ba647a8bea9ec0c001f9f79\",\"storage_mtime\":1438268193,\"permissions\":27,\"parent\":\"629\"}","level":0,"time":"2015-07-30T14:56:33+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-9"}
{"reqId":"8lqdkSYydDAFU5th+b5i","remoteAddr":"127.0.0.1","app":"ENCDEBUG","message":"file_assemble: \/\/TEST_FILE_DELETED_WINNER.dat.ocTransferId3657486019.part","level":0,"time":"2015-07-30T14:56:59+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-9"}
{"reqId":"8lqdkSYydDAFU5th+b5i","remoteAddr":"127.0.0.1","app":"ENCDEBUG","message":"addToCache: \"files_encryption\/keys\/files\/TEST_FILE_DELETED_WINNER.dat.ocTransferId3657486019.part\/OC_DEFAULT_MODULE\" {\"mtime\":1438268220,\"size\":-1,\"etag\":\"55ba3b3c38798\",\"storage_mtime\":1438268220,\"parent\":null}","level":0,"time":"2015-07-30T14:57:00+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-9"}

It looks like we get two separate PUT requests with the same transferId ?!
And that would do a second mkdir on the part folder which already exists, which then triggers the UPDATE bug from 4)

@PVince81
Copy link
Contributor Author

@ogoffart @guruz how is the transfer id generated by the server ? I hope it's not just a plain timestamp 😕

@PVince81
Copy link
Contributor Author

So far I suspect that test_basicSync is a bit aggressive and tries uploading the same file at the same time from two separate clients. If that happens at exactly the same milliseconds (I have a fast laptop with SSD, and the smashdir is a ramdisk), and if the transferid is the current time, then there's the risk of having transferid collision as observed above.

@PVince81
Copy link
Contributor Author

I found the matching access log entries:

127.0.0.1 - test [30/Jul/2015:16:56:30 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-0 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:30 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-1 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:30 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-2 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:30 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-3 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:31 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-4 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:31 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-5 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:31 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-6 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:31 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-7 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:31 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-8 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:32 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-9 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:57 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-0 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:57 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-1 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:57 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-2 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:57 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-3 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:58 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-4 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:58 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-5 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:58 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-6 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:58 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-7 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:58 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-8 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Linux) mirall/1.8.4"
127.0.0.1 - test [30/Jul/2015:16:56:59 +0200] "PUT /owncloud/remote.php/webdav/TEST_FILE_DELETED_WINNER.dat-chunking-3657486019-10-9 HTTP/1.1" 500 665 "-" "Mozilla/5.0 (Linux) mirall/1.8.4"

You can see that the same transferid is reused.
Coming from the smashbox test these must be two separate clients operating at exactly the same millisecond. This would explain why we only observe this in my environment.

@DeepDiver1975 I suggest to defer this ticket to 8.1.2, this shouldn't be a showstopper as this situation is very unlikely to happen.

@PVince81
Copy link
Contributor Author

TODOs:

@PVince81
Copy link
Contributor Author

Update: fixing the collision on the client also make the test pass, see owncloud/client#3522 (comment)

@PVince81 PVince81 modified the milestones: 8.1.2-next-maintenance, 8.1.1-current-maintenance Jul 30, 2015
@PVince81
Copy link
Contributor Author

I raised all issues as separate tickets: #17956 (comment)

Actually I don't see anything to be done in 8.1.2 apart from maybe providing the client fix in the 1.8.x series. (CC @guruz)

Closing.

@PVince81 PVince81 removed this from the 8.1.2-next-maintenance milestone Jul 30, 2015
@DeepDiver1975
Copy link
Member

This is awesome - thanks a lot!

@lock lock bot locked as resolved and limited conversation to collaborators Aug 10, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Projects
None yet
Development

No branches or pull requests

3 participants