An exception occurred while executing 'UPDATE oc_filecache', General Error

[frankuit]

Hi Guys,

Since i upgraded to 7.03 last month, the load on my Mysql server seems to be increasing to a point of error.

First, i noticed the load on my mysql server increasing, and a couple of queries taking longer then they should.

in phpmyadmin i see:

stop proces     7547    owncloud    <removed ip>,55557  owncloud    Query   20  Updating    UPDATE oc_filecache SET mimepart = '3', mimetype = '12', mtime = '1415098260', size = '699

it runs for very long, about 50 seconds, and after that, it bails out giving the error below.

{core} Exception while scanning file "files_trashbin/files/result_d20081217t092358_Gm025s04.dat.d1415105363": An exception occurred while executing 'UPDATE `oc_filecache` SET `mimepart` = ?, `mimetype` = ?, `mtime` = ?, `size` = ?, `etag` = ?, `storage_mtime` = ?, `permissions` = ?, `parent`=? WHERE `fileid` = ?':#012#012SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction

I've tried increasing the general timeout value in mysql:

SET GLOBAL innodb_lock_wait_timeout = 400;

but then the processes stack up until there are (almost) no recources available.
i've tracked the files down in this message, and it belongs to a user who has about 6500 files in his trashbin.
Retention was at 30 days, I've lowered it to 7, to see if that helps, but it deletes only 1 file every 10 seconds or so, so that will take weeks...
I had to restart the mysql server twice now to prevent bigger problems.

Any hints please ?

Server configuration

Operating system:
Debian wheezy 64 bit
Web server:
Apache2 (latest version of Debian)
Database:
Server version: 5.5.40-0+wheezy1-log (Debian)
PHP version:
5.4.35-0+deb7u2
ownCloud version: (see ownCloud admin page)
owncloud 7.0.3-1

<?php
$CONFIG = array (
  'instanceid' => '',
  'passwordsalt' => '',
  'trusted_domains' => 
  array (
    0 => 'owncloud.somesite.com',
  ),
  'datadirectory' => '/zfs/owncloud/owncloud',
  'dbtype' => 'mysql',
  'version' => '7.0.3.4',
  'dbname' => 'owncloud',
  'dbhost' => 'somehost',
  'dbtableprefix' => 'oc_',
  'dbuser' => 'bla',
  'dbpassword' => 'blabla',
  'installed' => true,
  'ldapIgnoreNamingRules' => false,
  'trashbin_retention_obligation' => 7,
  'trashbin_auto_expire' => true,
  'log_authfailip' => true,
  'loglevel' => '0',
  'log_type' => 'syslog',
  'logfile' => '',
  'forcessl' => true,
  'maxZipInputSize' => 838860800,
  'allowZipDownload' => true,
  'mail_smtpmode' => 'smtp',
  'mail_smtphost' => 'mailserver.somehost.com',
  'mail_smtpport' => '25',
  'theme' => '',
  'maintenance' => false,
  'mail_from_address' => 'owncloud',
  'mail_domain' => 'somedomain.com',
);

Updated from an older ownCloud or fresh install:
Updated using dpkg as always.

[frankuit]

Also, my mysql-slow.log is spamming this.
thousands of lines per minute.

User@Host: owncloud[owncloud] @  []
Query_time: 0.000459  Lock_time: 0.000127 Rows_sent: 0  Rows_examined: 60
SET timestamp=1417688514;
SELECT `oc_share`.`id`, `item_type`, `item_source`, `item_target`,
                                                        `oc_share`.`parent`, `share_type`, `share_with`, `uid_owner`,
                                                        `file_source`, `path`, `file_target`, `oc_share`.`permissions`, `stime`, `expiration`, `token`, `storage`, `mail_send` FROM `oc_share` INNER JOIN `oc_filecache` ON `file_source` = `oc_filecache`.`fileid` WHERE `file_target` IS NOT NULL AND `share_type` IN ('0','1','2') AND `share_with` IN ('nddh','Users') AND `uid_owner` != 'nddh' ORDER BY `oc_share`.`id` ASC;

[PVince81]

Are you using external storage ?
Are you accessing files in the "data" folder outside of ownCloud ?

It almost looks like it's detecting changes on disk and updating the cache.

[PVince81]

Do you have symlinks in the "data" dir or an external storage that have some, with a possible infinite loop ?

[frankuit]

the client responsible seemed to be of version 1.6.1.
there is 1 symbolic link in the folder, but the client log says: symlinks are not supported in syncing.
external storage is not allowed for users(i was personally using it as a test to google drive, but that has 3 images in it or so)
we are not accessing files outside of the data folder from owncloud.

[frankuit]

I have now updated the client of the user from 1.6.1 to 1.7.0, and i've emptied the trash from that user.
next i restarted the apache and mysql server. and for now there does not seem to be a load increase yet. but lets not cheer to soon.
i will keep checking and let you know in an hour .

[frankuit]

It seems to have stabilized for now. what should we do, keep this ticket open in case it returns ? or should i then reopen it ?

[addy90]

same problem here with 7.0.4 - I am having the same amount of SQL queries in the processlist.
My apache freezes completely - I am not able to open any request at all. Both apache and mysql have full cpu load. When I restart apache, it works again.

Problem indeed starts with WebDAV uploads.

So the amount and content of SQL queries is the same.
Moreover, the owncloud.log inside the data-dir has incredibly many entries like the following:

{"app":"PHP","message":"filesize(): stat failed for \/var\/www\/owncloud\/data\/XXX\/files_trashbin\/files\/XXX at \/var\/www\/owncloud\/lib\/private\/files\/storage\/local.php#117","level":3,"time":"2014-12-14T12:48:50+00:00"}

no symlinks, client 1.7.0 - problem does not seem to start via client but via webdav. no access outside of the data dir and no external storage.
The trashbin of that user seems to be quite full - I will empty it and see if that stops the problem.

[frankuit]

I Have the same problem again.
Clients are latest version(1.7.0). one user told me he had the same word file open on 2 computers, both loaded from the owncloud dir.

temp fix for us is, stop apache. restart mysql, start apache.

[addy90]

With emptied trashbin of my user that had it full, the problem was gone for this morning - but the newest comment of frankuit does not sound well.
At least, there were no errors "stat failed" with empties trashbin in owncloud.log.

[frankuit]

correct, i confirm that i can (temporarily) fix the problem by emptying the trashbin of the user.
Just so you this isn't caused by 1 user, i've had this problem with 2 different kind of users now.

[frankuit]

Today, this problem is occuring again. and it's really wreaking havoc on my mysql server.
Is there anyone who has any idea what can be done about this ? or, can we add a function for admins to clear a trashbin for a specific user as a temp workaround ?

Thanks,
Frank

[PVince81]

@schiesbn can you have a look at the SQL query from #12591 (comment) ? It might be a clue to figure out what is happening.
Seems to be related to sharing.

[karlitschek]

@frankuit Which apps do you have enabled?

[karlitschek]

@schiesbn Can you have a look? Maybe related to files_trash

[frankuit]

@karlitschek Sorry for the late reply, was on vacation, i have:

Deleted files 0.6.2
External storage support 0.2.3
External user support 0.4
First Run Wizard 1.1
LDAP user and group backend 0.5.0
Pictures 0.6.0
Picture gallery for ownCloud.
Share Files 0.6.1
Versions 1.0.5

[PVince81]

Starting with OC 8.1, the trashbin expiration logic will be run in a background job. So it should hopefully not spam the database / logs that often.

[PVince81]

Possibly related to concurrent scanner processes: #16584
If I remember well, there is a code path that rescans the trashbin folder. If that would happen twice in a row for the same user, both scanners would try and update the same folder at the same time (in two separate folder-based transactions).

I'm closing this as duplicate of #16584. Hopefully locking can be implemented to prevent two scanners to scan the same folder at the same time.

Also, as stated above, in 8.1 the trashbin expiration will happen in a background job, which should hopefully (in the short term) reduce the number of occurrences.

[PVince81]

I'd also recommend you to upgrade to 8.0.3.
From what I see in the code, the scan command in the trashbin is actually used to find versions, see https://github.com/owncloud/core/blob/v8.0.3/apps/files_trashbin/lib/trashbin.php#L838 vs the old version https://github.com/owncloud/core/blob/v8.0.2/apps/files_trashbin/lib/trashbin.php#L830
In 8.0.2 and before it was scanning too much and too often.