Smashbox basicSync failing on master with encryption

[PVince81]

± % bin/smash -a lib/test_basicSync.py                                                                                                                                           !10182
SUMMARY:smash.:runid: 150813-102929
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
md5sum: /home/vincent/work/smashdir/test_basicSync/creator/TEST_FILE_ADDED_LOSER.dat: No such file or directory
md5sum: /home/vincent/work/smashdir/test_basicSync/winner/TEST_FILE_ADDED_LOSER.dat: No such file or directory
md5sum: /home/vincent/work/smashdir/test_basicSync/checker/TEST_FILE_ADDED_LOSER.dat: No such file or directory
2015-08-13 10:31:15,095 - ERROR - winner - inconsistent md5 of /home/vincent/work/smashdir/test_basicSync/winner/TEST_FILE_ADDED_LOSER.dat: expected f00aea5276fee4aa8ad4e8394cf09749, 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-08-13 10:31:15,101 - ERROR - checker - inconsistent md5 of /home/vincent/work/smashdir/test_basicSync/checker/TEST_FILE_ADDED_LOSER.dat: expected f00aea5276fee4aa8ad4e8394cf09749, 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/checker/TEST_FILE_MODIFIED_LOSER.dat: No such file or directory
2015-08-13 10:31:15,107 - ERROR - checker - inconsistent md5 of /home/vincent/work/smashdir/test_basicSync/checker/TEST_FILE_MODIFIED_LOSER.dat: expected f00aea5276fee4aa8ad4e8394cf09749, 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-08-13 10:31:15,111 - ERROR - creator - inconsistent md5 of /home/vincent/work/smashdir/test_basicSync/creator/TEST_FILE_ADDED_LOSER.dat: expected f00aea5276fee4aa8ad4e8394cf09749, 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-08-13 10:31:15,231 - ERROR - winner - inconsistent md5 of /home/vincent/work/smashdir/test_basicSync/winner/TEST_FILE_MODIFIED_LOSER.dat: expected f00aea5276fee4aa8ad4e8394cf09749, got 863f3ed728e4ef9afa7de307f09f1bd1 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-08-13 10:31:15,261 - ERROR - creator - inconsistent md5 of /home/vincent/work/smashdir/test_basicSync/creator/TEST_FILE_MODIFIED_LOSER.dat: expected f00aea5276fee4aa8ad4e8394cf09749, got 863f3ed728e4ef9afa7de307f09f1bd1 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-08-13 10:31:16,821 - ERROR - winner - 2 error(s) reported
2015-08-13 10:31:16,821 - ERROR - creator - 2 error(s) reported
2015-08-13 10:31:16,826 - ERROR - checker - 2 error(s) reported
CRITICAL:smash.:Aborting run -- non-zero exit code (2)

On master 55dc74b with encryption and locking enabled.

[PVince81]

Did a few tests, and the problem happens when encryption is enabled. It works fine when encryption is disabled.
Nothing to do with locking.

[PVince81]

Hmmmm, also happens on the stable8.1.1 branch and also v8.1.1.

It seems the tests don't always fail in the same test set.

[PVince81]

I see it happening on v8.1.1beta1 too. Hmmm... but I remember that it worked on these versions before.
Very strange.

[PVince81]

@nickvergessen do you also see this ? Does it ring any bells ?

This failure sounds familiar somehow.

[PVince81]

Okay, this sounds familiar too:

{"reqId":"iyOa8EpFCxoQ8wimMkq2","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 [1439458732, -1, \\\"55cc65aca3fae\\\", 1439458732, null, 1439458732, -1, \\\"55cc65aca3fae\\\", 1439458732, null, 1008]:\\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-08-13T09:38:52+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/TEST_FILE_DELETED_WINNER.dat-chunking-3665203281-10-9"}

I think we had a ticket, searching...

[nickvergessen]

basicSync fails with any thing atm it seems like:
https://ci.owncloud.org/job/smashbox/

Will dive into it later today

[PVince81]

The "parent" is null, I remember having discussed it with @schiesbn before. Something to do with having ".part" folders. I need to find the ticket.

[PVince81]

Ok, the "parent is null" issue is here: #17997

And this issue is a duplicate of #17956.

The problem is about transferid collisions which are solved in the next sync client version: owncloud/client#3522