1205 Lock wait timeout exceeded when trying to access a file on external storage before it's ready #19457

oparoz · 2015-09-29T20:35:22Z

Steps to reproduce

Add this code somewhere

$scanner = new \OC\Files\Utils\Scanner($user, \OC::$server->getDatabaseConnection());
$scanner->listen('\OC\Files\Utils\Scanner', 'scanFile', function ($path) use ($output) {
    $path = normalizePathToMakeItWorkWithPreview($path);
    $preview = new Preview($user, 'files', $path);
    $preview->setMaxX($this->thumbnailWidth);
    $preview->setMaxY($this->thumbnailHeight);
    $preview->setKeepAspect(true);
    $preview->getPreview();
});

Connect your instance to another oC instance using files_ external -> WebDAV
Upload a new file in the external cloud
Launch your script

Now the scanner is going loopy. It tries a hundred time to access the newly uploaded file, but it's never ready (unlocked?). A possible race condition?

Change mount option to "Every time the filesytem is used" (value 2).
Launch your script again

This time it's worse, the scanner keeps trying to access the external folder until the command is killed.

Notes

I think this happens because getPreview() tries to access the file before it's stored in the cache
New thumbnails, as they're generated, are also sent to the preview generator via the scanFile event
When using postScanFile things seem to work as expected, but some people have reported experiencing the same issue with it
Utils\Scanner does not use transactional locking

Logs

This is for the last operation, when always getting the folder.

{"reqId":"o2g1Y985c54xz\/5dY2C1","remoteAddr":"10.0.2.2","app":"webdav","message":"Exception: {\"Message\":\"An exception occurred while executing 'UPDATE `oc_file_locks` SET `lock` = `lock` + 1, `ttl` = ? WHERE `key` = ? AND `lock` >= 0' with params [1443562215, \\\"files\\\\\\\/a3594fd4eca7119cb937772e1f8f5415\\\"]:\\n\\nSQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction\",\"Exception\":\"Doctrine\\\\DBAL\\\\Exception\\\\DriverException\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/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 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/Connection.php(996): Doctrine\\\\DBAL\\\\DBALException::driverExceptionDuringQuery(Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOMySql\\\\Driver), Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOException), 'UPDATE `oc_file...', Array)\\n#2 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/db\\\/connection.php(203): Doctrine\\\\DBAL\\\\Connection->executeUpdate('UPDATE `oc_file...', Array, Array)\\n#3 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/lock\\\/dblockingprovider.php(112): OC\\\\DB\\\\Connection->executeUpdate('UPDATE `*PREFIX...', Array)\\n#4 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/storage\\\/common.php(638): OC\\\\Lock\\\\DBLockingProvider->acquireLock('files\\\/a3594fd4e...', 1)\\n#5 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/storage\\\/wrapper\\\/wrapper.php(571): OC\\\\Files\\\\Storage\\\\Common->acquireLock('files', 1, Object(OC\\\\Lock\\\\DBLockingProvider))\\n#6 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/view.php(1779): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->acquireLock('files', 1, Object(OC\\\\Lock\\\\DBLockingProvider))\\n#7 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/view.php(1874): OC\\\\Files\\\\View->lockPath('', 1, false)\\n#8 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/view.php(1190): OC\\\\Files\\\\View->lockFile('', 1)\\n#9 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/serverfactory.php(83): OC\\\\Files\\\\View->getFileInfo('')\\n#10 [internal function]: OC\\\\Connector\\\\Sabre\\\\ServerFactory->OC\\\\Connector\\\\Sabre\\\\{closure}(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#11 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Object(Closure), Array)\\n#12 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(456): Sabre\\\\Event\\\\EventEmitter->emit('beforeMethod', Array)\\n#13 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#14 \\\/var\\\/www\\\/owncloud\\\/apps\\\/files\\\/appinfo\\\/remote.php(56): Sabre\\\\DAV\\\\Server->exec()\\n#15 \\\/var\\\/www\\\/owncloud\\\/remote.php(137): require_once('\\\/var\\\/www\\\/ownclo...')\\n#16 {main}\",\"File\":\"\\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/Driver\\\/AbstractMySQLDriver.php\",\"Line\":115}","level":4,"time":"2015-09-29T20:31:06+00:00","method":"PROPFIND","url":"\/owncloud\/remote.php\/webdav\/"}
{"reqId":"Qb5n+Cq7CxO6bRP1sZRI","remoteAddr":"10.0.2.2","app":"webdav","message":"Exception: {\"Message\":\"HTTP\\\/1.1 401 No basic authentication headers were found\",\"Exception\":\"Sabre\\\\DAV\\\\Exception\\\\NotAuthenticated\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/auth.php(149): Sabre\\\\DAV\\\\Auth\\\\Backend\\\\AbstractBasic->authenticate(Object(OC\\\\Connector\\\\Sabre\\\\Server), 'ownCloud')\\n#1 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/auth.php(122): OC\\\\Connector\\\\Sabre\\\\Auth->auth(Object(OC\\\\Connector\\\\Sabre\\\\Server), 'ownCloud')\\n#2 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Plugin.php(118): OC\\\\Connector\\\\Sabre\\\\Auth->authenticate(Object(OC\\\\Connector\\\\Sabre\\\\Server), 'ownCloud')\\n#3 [internal function]: Sabre\\\\DAV\\\\Auth\\\\Plugin->beforeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#4 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#5 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(456): Sabre\\\\Event\\\\EventEmitter->emit('beforeMethod', Array)\\n#6 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#7 \\\/var\\\/www\\\/owncloud\\\/apps\\\/files\\\/appinfo\\\/remote.php(56): Sabre\\\\DAV\\\\Server->exec()\\n#8 \\\/var\\\/www\\\/owncloud\\\/remote.php(137): require_once('\\\/var\\\/www\\\/ownclo...')\\n#9 {main}\",\"File\":\"\\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Backend\\\/AbstractBasic.php\",\"Line\":70}","level":0,"time":"2015-09-29T20:31:19+00:00","method":"PROPFIND","url":"\/owncloud\/remote.php\/webdav\/"}

Config

$CONFIG = array (
  'datadirectory' => '/var/www/owncloud/data',
  'dbtype' => 'mysql',
  'version' => '8.2.0.6',
  'logtimezone' => 'UTC',
  'installed' => true,
  'loglevel' => 0,
  'theme' => '',
  'maintenance' => false,
  'enabledPreviewProviders' =>
  array (
    0 => 'OC\\Preview\\JPEG',
    1 => 'OC\\Preview\\PNG',
    2 => 'OC\\Preview\\GIF',
    3 => 'OC\\Preview\\Postscript',
    4 => 'OC\\Preview\\Font',
    10 => 'OC\\Preview\\Photoshop',
    11 => 'OC\\Preview\\Illustrator',
    12 => 'OC\\Preview\\TIFF',
    14 => 'OC\\Preview\\Raw',
  ),
  'preview_max_x' => 2048,
  'preview_max_y' => 2048,
  'debug' => true,
  'updatechecker' => 'false',
  'singleuser' => false,
  'memcache.local' => '\\OC\\Memcache\\APCu',
);

@icewind1991 @PVince81

The text was updated successfully, but these errors were encountered:

oparoz · 2015-09-29T23:16:01Z

The problem seems to be that the file is not ready to be worked on when just scanned. If I do a files:scan --all, then the filecache is updated and I can then create the thumbnails.
"scanFile" is sent before the file is ready, but there doesn't seem to be another event which is sent when the file is ready, except if data has changed.

oparoz · 2015-09-30T00:06:43Z

This PR #19460 fixes scanFile() so that postScanFile fires after a file is scanned allowing any operation which needs a working file to be triggered at the appropriate time.

mmattel · 2015-10-01T17:09:24Z

owncloud/gallery#387 (comment)
The test instance was down and it was challanging to get it up and running again.
In an production environment, this would cause a longer downtime

MorrisJobke · 2015-10-02T09:23:31Z

This PR #19460 fixes scanFile() so that postScanFile fires after a file is scanned allowing any operation which needs a working file to be triggered at the appropriate time.

#19460 is now merged. Can this ticket be closed?

oparoz · 2015-10-02T09:36:59Z

@MorrisJobke - I think the problem remain. The locking mechanism should not lock up ownCloud because there is a problem accessing a file.
@icewind1991 @PVince81 maybe have a maximum iteration number and give up after that?

icewind1991 · 2015-10-02T12:50:16Z

We dont retry locks with transactional locking

oparoz · 2015-10-02T13:32:36Z

OK. It seems to be disabled in Utils\Scanner.

In #10922 you say

When doing an explicit file system scan we don't need to worry about timeouts so there is no reason to commit the session often to save progress in case the scan aborts.

But the scan aborting is apparently not the only problem here. Maybe the locking issue is not experienced during most scans as each file is accessed for a short amount of time, but it could still be triggered on large installations, no?

oparoz · 2015-10-03T16:22:07Z

I've updated the OP to make it easier to isolate the issue and with a collection of notes about what I've observed.

It's not possible to force people to not use scanFile, If an app uses it to collect files to process, then there could be some unfortunate consequences for that instance.

DeepDiver1975 · 2015-10-06T10:40:03Z

@icewind1991 any idea on what we can do to face this issue? THX

icewind1991 · 2015-10-06T13:29:13Z

From what I can tell this is caused by the preview generation triggering the file scanner while it's still in the transaction of the scanner causing a lock with the transactions

oparoz · 2015-10-06T13:56:13Z

There is something I don't understand. Here is the workflow:

Start the DB collector
Lock the folder
Start scanning the folder recursively
Start generating previews as file events arrive
Unlock the folder
Commit detected changes to the DB
Finish generating previews

How does 4) happen when the folder is locked? I've verified in the UI and you can't access the files while they're being scanned, yet, I'm able to generate previews.

oparoz · 2015-10-06T14:29:07Z

Is it only locking files for the user?

icewind1991 · 2015-10-06T14:35:57Z

Iirc the scanner only gets a read lock on the files, and generating previews only needs write access to the preview file

oparoz · 2015-10-06T14:52:09Z

Iirc the scanner only gets a read lock on the files

Yes, so that should prevent the preview class from reading the files

icewind1991 · 2015-10-06T15:08:46Z

No, only a write lock prevents from reading

oparoz · 2015-10-06T15:36:15Z

OK, got it (https://en.wikipedia.org/wiki/Two-phase_locking)

From what I can tell this is caused by the preview generation triggering the file scanner while it's still in the transaction of the scanner causing a lock with the transactions

So generating a preview, triggers another scan? If yes, is there any way to disable that?

icewind1991 · 2015-10-06T17:36:46Z

It triggers a scan on the preview file it generated

oparoz · 2015-10-06T18:30:27Z

OK, but the original scan locks /user/files/SMB and the thumbnails are written to /user/thumbnails, so there should be no conflict and yet the GUI can't access the folder.

oparoz · 2015-10-06T18:33:09Z

Actually, all the files of the user are locked down (just tried to browse another folder). It shouldn't happen with a lock on a single folder.

icewind1991 · 2015-10-06T20:35:29Z

It's probably related the the transaction, not the lock

How does the request fail when you try to browser?

oparoz · 2015-10-06T20:46:05Z

I get the spinner and it just waits for the request to complete before loading the list of files. I suspect that if this takes too long, then things start to fail, probably with error 1205

icewind1991 · 2015-10-08T12:38:53Z

This seems to only happen when using the db locking backend

icewind1991 · 2015-10-08T13:30:40Z

Fix is here: #19654

oparoz added the Type:Bug label Sep 29, 2015

oparoz added this to the 8.2-current milestone Sep 29, 2015

oparoz changed the title ~~External WebDAV, 1205 Lock wait timeout exceeded when enabling "Every time the filesytem is used"~~ 1205 Lock wait timeout exceeded when trying to access a file on external storage before it's ready Sep 30, 2015

oparoz mentioned this issue Oct 1, 2015

New occ commands to manage thumbnails owncloud/gallery#387

Closed

15 tasks

ghost added the sev2-high label Oct 1, 2015

ghost assigned icewind1991 Oct 6, 2015

icewind1991 mentioned this issue Oct 8, 2015

Dont use a transaction in the scanner while using db based locking #19654

Merged

MorrisJobke added the 3 - To Review label Oct 8, 2015

icewind1991 closed this as completed in #19654 Oct 9, 2015

ghost mentioned this issue Feb 4, 2016

Owncloud Desktop Sync Client stalls #22116

Closed

lock bot locked as resolved and limited conversation to collaborators Aug 8, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

1205 Lock wait timeout exceeded when trying to access a file on external storage before it's ready #19457

1205 Lock wait timeout exceeded when trying to access a file on external storage before it's ready #19457

oparoz commented Sep 29, 2015

oparoz commented Sep 29, 2015

oparoz commented Sep 30, 2015

mmattel commented Oct 1, 2015

MorrisJobke commented Oct 2, 2015

oparoz commented Oct 2, 2015

icewind1991 commented Oct 2, 2015

oparoz commented Oct 2, 2015

oparoz commented Oct 3, 2015

DeepDiver1975 commented Oct 6, 2015

icewind1991 commented Oct 6, 2015

oparoz commented Oct 6, 2015

oparoz commented Oct 6, 2015

icewind1991 commented Oct 6, 2015

oparoz commented Oct 6, 2015

icewind1991 commented Oct 6, 2015

oparoz commented Oct 6, 2015

icewind1991 commented Oct 6, 2015

oparoz commented Oct 6, 2015

oparoz commented Oct 6, 2015

icewind1991 commented Oct 6, 2015

oparoz commented Oct 6, 2015

icewind1991 commented Oct 8, 2015

icewind1991 commented Oct 8, 2015

1205 Lock wait timeout exceeded when trying to access a file on external storage before it's ready #19457

1205 Lock wait timeout exceeded when trying to access a file on external storage before it's ready #19457

Comments

oparoz commented Sep 29, 2015

Steps to reproduce

Notes

Logs

Config

oparoz commented Sep 29, 2015

oparoz commented Sep 30, 2015

mmattel commented Oct 1, 2015

MorrisJobke commented Oct 2, 2015

oparoz commented Oct 2, 2015

icewind1991 commented Oct 2, 2015

oparoz commented Oct 2, 2015

oparoz commented Oct 3, 2015

DeepDiver1975 commented Oct 6, 2015

icewind1991 commented Oct 6, 2015

oparoz commented Oct 6, 2015

oparoz commented Oct 6, 2015

icewind1991 commented Oct 6, 2015

oparoz commented Oct 6, 2015

icewind1991 commented Oct 6, 2015

oparoz commented Oct 6, 2015

icewind1991 commented Oct 6, 2015

oparoz commented Oct 6, 2015

oparoz commented Oct 6, 2015

icewind1991 commented Oct 6, 2015

oparoz commented Oct 6, 2015

icewind1991 commented Oct 8, 2015

icewind1991 commented Oct 8, 2015