Error while running version expire background job #24914

mmattel · 2016-05-31T09:35:51Z

Steps to reproduce

Setup a federated share, my system is connecting to it
Sync with the sync client (latest) against this share
It works from the syncing perspective, but continious fills up the owncloud log with errors

Expected behaviour

Syncing without errors

Actual behaviour

Syncing and errors are logged

Server configuration

Operating system: Ubuntu 14.04

Web server: nginx 1.9.14

Database: mysql

PHP version: 5.5.9

ownCloud version: (see ownCloud admin page)
ownCloud 9.1.0 beta 1 (daily) Build:2016-05-30T03:09:20+00:00 c870e77
But this is also with 9.0.2

Updated from an older ownCloud or fresh install:
This was a upgrade from 9.0.2, daily channel

Where did you install ownCloud from:
originally tar

List of activated apps:

Enabled:
  - activity: 2.2.1
  - comments: 0.2
  - dav: 0.1.6
  - federatedfilesharing: 0.1.0
  - federation: 0.0.4
  - files: 1.4.4
  - files_external: 0.5.2
  - files_pdfviewer: 0.8.1
  - files_sharing: 0.9.1
  - files_texteditor: 2.1
  - files_trashbin: 0.8.0
  - files_versions: 1.2.0
  - files_videoplayer: 0.9.8
  - firstrunwizard: 1.1
  - gallery: 14.5.0
  - notifications: 0.2.3
  - provisioning_api: 0.4.1
  - systemtags: 0.2
  - templateeditor: 0.1
  - updatenotification: 0.1.0
Disabled:
  - encryption
  - external
  - user_external
  - user_ldap

The content of config/config.php:

{
    "system": {
        "instanceid": "ock982ae3c5s",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "xxxx"
        ],
        "datadirectory": "\/var\/www\/owncloud\/data",
        "overwrite.cli.url": "https:\/\/xxxx",
        "dbtype": "mysql",
        "version": "9.0.2.0",
        "dbname": "owncloud",
        "dbhost": "localhost",
        "dbtableprefix": "oc_",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "logtimezone": "Europe\/Vienna",
        "installed": true,
        "filelocking.enabled": "true",
        "memcache.local": "\\OC\\Memcache\\Redis",
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "memcache.distributed": "\\OC\\Memcache\\Redis",
        "redis": {
            "host": "localhost",
            "port": 6379,
            "timeout": 0,
            "dbindex": 0
        },
        "assetdirectory": "\/var\/www\/owncloud",
        "asset-pipeline.enabled": true,
        "filesystem_check_changes": 1,
        "preview_max_scale_factor": 1,
        "enabledPreviewProviders": [
            "OC\\Preview\\PNG",
            "OC\\Preview\\JPEG",
            "OC\\Preview\\GIF",
            "OC\\Preview\\Illustrator",
            "OC\\Preview\\Postscript",
            "OC\\Preview\\Photoshop",
            "OC\\Preview\\TIFF",
            "OC\\Preview\\Raw"
        ],
        "loglevel": 2,
        "maintenance": false,
        "mail_smtpmode": "smtp",
        "mail_smtpsecure": "tls",
        "mail_from_address": "owncloud",
        "mail_domain": "xxxx",
        "mail_smtpauthtype": "LOGIN",
        "mail_smtpauth": 1,
        "mail_smtphost": "xxxx",
        "mail_smtpport": "587",
        "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
        "mail_smtppassword": "***REMOVED SENSITIVE VALUE***"
    }
}

Are you using external storage, if yes which one: local/smb/sftp/...
SMB

Are you using encryption: yes/no
No

Are you using an external user-backend, if yes which one: LDAP/ActiveDirectory/Webdav/...
No

Client configuration

Browser: Opera

Operating system: W7x64

Logs

owncloud.log

{"reqId":"dWCsjhrg6zxhGh3IAKD\/","remoteAddr":"80.110.35.173","app":"core","message":"Error while running background job (class: OC\\Command\\CommandJob, arguments: O:33:\"OCA\\Files_Versions\\Command\\Expire\":2:{s:43:\"\u0000OCA\\Files_Versions\\Command\\Expire\u0000fileName\";s:146:\"\/a_folder_1\/a_folder_2\/a_file\";s:39:\"\u0000OCA\\Files_Versions\\Command\\Expire\u0000user\";s:8:\"user_x\";}): {\"Exception\":\"OCP\\\\Files\\\\NotFoundException\",\"Message\":\"\",\"Code\":0,\"Trace\":\"
#0 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/Share20\\\/DefaultShareProvider.php(436): OC\\\\Share20\\\\Share->getNode()\\
n#1 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/Share20\\\/Manager.php(871): OC\\\\Share20\\\\DefaultShareProvider->move(Object(OC\\\\Share20\\\\Share), 'user_x')\\
n#2 \\\/var\\\/www\\\/owncloud\\\/apps\\\/files_sharing\\\/lib\\\/SharedMount.php(109): OC\\\\Share20\\\\Manager->moveShare(Object(OC\\\\Share20\\\\Share), 'user_x')\\
n#3 \\\/var\\\/www\\\/owncloud\\\/apps\\\/files_sharing\\\/lib\\\/SharedMount.php(94): OCA\\\\Files_Sharing\\\\SharedMount->updateFileTarget('\\\/Solutions (2)', Object(OC\\\\Share20\\\\Share))\\
n#4 \\\/var\\\/www\\\/owncloud\\\/apps\\\/files_sharing\\\/lib\\\/SharedMount.php(65): OCA\\\\Files_Sharing\\\\SharedMount->verifyMountPoint(Object(OC\\\\Share20\\\\Share), Array)\\
n#5 \\\/var\\\/www\\\/owncloud\\\/apps\\\/files_sharing\\\/lib\\\/MountProvider.php(78): OCA\\\\Files_Sharing\\\\SharedMount->__construct('\\\\OC\\\\Files\\\\Stora...', Array, Array, Object(OC\\\\Files\\\\Storage\\\\StorageFactory))\\
n#6 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/Files\\\/Config\\\/MountProviderCollection.php(76): OCA\\\\Files_Sharing\\\\MountProvider->getMountsForUser(Object(OC\\\\User\\\\User), Object(OC\\\\Files\\\\Storage\\\\StorageFactory))\\
n#7 [internal function]: OC\\\\Files\\\\Config\\\\MountProviderCollection->OC\\\\Files\\\\Config\\\\{closure}(Object(OCA\\\\Files_Sharing\\\\MountProvider))\\
n#8 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/Files\\\/Config\\\/MountProviderCollection.php(77): array_map(Object(Closure), Array)\\
n#9 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/Files\\\/Filesystem.php(422): OC\\\\Files\\\\Config\\\\MountProviderCollection->getMountsForUser(Object(OC\\\\User\\\\User))\\
n#10 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/Files\\\/Filesystem.php(370): OC\\\\Files\\\\Filesystem::initMountPoints('user_x')\\
n#11 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/legacy\\\/util.php(225): OC\\\\Files\\\\Filesystem::init('user_x', '\\\/user_x\\\/files')\\
n#12 \\\/var\\\/www\\\/owncloud\\\/apps\\\/files_versions\\\/lib\\\/Command\\\/Expire.php(60): OC_Util::setupFS('user_x')\\
n#13 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/Command\\\/CommandJob.php(34): OCA\\\\Files_Versions\\\\Command\\\\Expire->handle()\\
n#14 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/BackgroundJob\\\/Job.php(52): OC\\\\Command\\\\CommandJob->run('O:33:\\\"OCA\\\\Files...')\\
n#15 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/BackgroundJob\\\/QueuedJob.php(42): OC\\\\BackgroundJob\\\\Job->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\
n#16 \\\/var\\\/www\\\/owncloud\\\/cron.php(144): OC\\\\BackgroundJob\\\\QueuedJob->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\
n#17 {main}\",\"File\":\"\\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/Share20\\\/Share.php\",\"Line\":162}","level":3,"time":"2016-05-31T09:06:10+02:00","method":"GET","url":"\/cron.php","user":"--"}

webserver.log

There is no corresponding webserver error log

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

PVince81 · 2016-05-31T09:51:33Z

Could be versions or sharing.

Maybe it's trying to expire a file on a non-available federated share ?

@owncloud/sharing @owncloud/filesystem

mmattel · 2016-05-31T10:26:25Z

The federated share is (at least seems to me) fully available.
I have not seen this more or less at higher or lower load times or any pattern.

mmattel · 2016-05-31T11:23:57Z

Update: the error message additionally pops up when I try to logon.

PVince81 · 2016-06-23T10:03:40Z

I tried the following:

Create a file "test.txt"
Edit it several times to create versions
Rename "test.txt" to "testx.txt"
Check oc_jobs: the old versions expire job for "test.txt" still exists (known issue, no automatic cleanup)
Run cron.php

The cron silently discarded the versions expire job for the file "test.txt", no exception observed.
So it might be something else.

PVince81 · 2016-06-23T10:06:12Z

Looking at the stack trace it looks more like it's "initMountPoints" that is causing the issue, not the expire job in itself. This explains why you saw it at login time too.

So the FS setup triggers this error, for some reason it tries to change the target of a share to "/Solutions (2)" but after trying it, it doesn't find the original file for that share. So this is potentially an orphaned share for which the original file doesn't exist any more.

I'll see if I can recreate this situation locally.

PVince81 · 2016-06-23T10:27:44Z

Two unsuccessful cases I tried.

Case A:

Create three users "user1" and "user2" and "user3"
Login as "user1"
Create a folder "test"
Share "test" with "user2"
Delete "test" directly in the data folder
Run "occ files:scan"
select * from oc_share where file_target='/test' and find the entry for this share
Check that select * from oc_filecache where fileid=$itemsource doesn't exist, where $itemsource is the item_source value from the previous query
Now login as "user2", see that the folder is not there
Login as "user3"
Create a folder "test" (same name!)
Share "test" with "user2"
Login as "user2" again

Case B:

Create three users "user1", "user2", "user3"
Login as "user1"
Create folder "test"
Share "test" with "user3"
Login as "user2"
Create folder "test" (same name!)
Share "test" with "user3"
Log out (do NOT login as user3 yet)
Check "oc_share" and see that the two shares are there
In the data folder, delete the two "test" folders
Run "occ files:scan user1" and "occ files:scan user2"
Check "oc_share" and see that the two shares are still there
Now login as user3

In both cases, the error messages look like:

{"reqId":"mL6YKW\/0k+SUESA+bymW","remoteAddr":"127.0.0.1","app":"core","message":"File with id \"17\" has not been found.","level":3,"time":"2016-06-23T10:26:35+00:00","method":"GET","url":"\/owncloud\/index.php\/avatar\/user3\/28","user":"user3"}
{"reqId":"hEoM49zv8Xw2btUghH8g","remoteAddr":"127.0.0.1","app":"core","message":"File with id \"28\" has not been found.","level":3,"time":"2016-06-23T10:26:35+00:00","method":"GET","url":"\/owncloud\/index.php\/apps\/files\/ajax\/getstoragestats.php?dir=%2F","user":"user3"}

However, the orphaned shares get cleared up by subsequent cron runs so the error disappears.

Needs further research to reproduce the original issue.

PVince81 · 2016-06-23T10:34:52Z

Not related to #25186 since you said 9.0.2 is affected.

PVince81 · 2016-06-23T10:54:22Z

I did more tests with different scenarios, this time on v9.0.2 but was unable to reproduce the issue so far.
The thing I'm trying to do is trigger the code from moveShare which only happens when a user receives shares with duplicate names. The moveShare logic is the one that adds the "(2)" for a second one.

My interpretation of the stack trace of the error is that there is a situation in which there is a duplicate received share name, but when attempting to move/create the second share with the name "/Solutions (2)" the original source node from the share is not found, likely missing from oc_filecache but the oc_share entry still exists.

Create three users "user1", "user2", "user3"
As "user1" share a folder "test" with "user3"
Login as "user3", see the folder (this also sets up FS for user3)
As "user2" share a folder "test" (same name!) with "user3"
Log out (do NOT login as "user3" yet)
Delete the folder "data/user2/files/test" (only for user2)
Run "occ files:scan user2"
Login as "user3"

Unfortunately this doesn't trigger the "moveShare" logic at all. It seems an earlier code path detected already that the "test" folder from "user2" was gone and didn't bother.

PVince81 · 2016-06-23T11:02:03Z

OH NO! Now I found another bug on v9.0.2 😦
If you login as "user3" when receiving a folder "test" from both "user1" and "user2" the logic for deduplication isn't triggered either and "user3" only receives the folder from two.
Will raise separately... #25244

PVince81 · 2016-06-23T11:44:34Z

I'm out of ideas now.

@mmattel would be good to get more details about that user and their shares.

select * from oc_share where share_with='user_x' or file_target like '%Solutions%'.
Then if there are entries, take the "item_source" of each and check the filecache table:
select * from oc_filecache where fileid=$item_source.

I expect that some of the oc_share entries have no linked entry.

bcutter · 2016-07-04T21:42:19Z

Same here. After having some trouble with external share syncs (GoogleDrive, #24253) now I see those messages every 15 minutes (cron run):

Error while running background job (class: OC\Command\CommandJob, arguments: O:33:"OCA\Files_Versions\Command\Expire":2:{s:43:"OCA\Files_Versions\Command\ExpirefileName";s:30:"/External_GoogleDrive/Test Doc";s:39:"OCA\Files_Versions\Command\Expireuser";s:5:"Chris";}): {"Exception":"OC\\User\\NoUserException","Message":"Attempted to initialize mount points for null user and no user in session","Code":0,"Trace":"#0 \/var\/www\/owncloud\/apps\/files_versions\/lib\/storage.php(102): OC\\Files\\Filesystem::initMountPoints(false)\n#1 \/var\/www\/owncloud\/apps\/files_versions\/lib\/storage.php(682): OCA\\Files_Versions\\Storage::getUidAndFilename('\/External_Googl...')\n#2 \/var\/www\/owncloud\/apps\/files_versions\/command\/expire.php(61): OCA\\Files_Versions\\Storage::expire('\/External_Googl...')\n#3 \/var\/www\/owncloud\/lib\/private\/command\/commandjob.php(34): OCA\\Files_Versions\\Command\\Expire->handle()\n#4 \/var\/www\/owncloud\/lib\/private\/backgroundjob\/job.php(52): OC\\Command\\CommandJob->run('O:33:\"OCA\\\\Files...')\n#5 \/var\/www\/owncloud\/lib\/private\/backgroundjob\/queuedjob.php(42): OC\\BackgroundJob\\Job->execute(Object(OC\\BackgroundJob\\JobList), Object(OC\\Log))\n#6 \/var\/www\/owncloud\/cron.php(145): OC\\BackgroundJob\\QueuedJob->execute(Object(OC\\BackgroundJob\\JobList), Object(OC\\Log))\n#7 {main}","File":"\/var\/www\/owncloud\/lib\/private\/files\/filesystem.php","Line":376}
Error while running background job (class: OC\Command\CommandJob, arguments: O:33:"OCA\Files_Versions\Command\Expire":2:{s:43:"OCA\Files_Versions\Command\ExpirefileName";s:30:"/External_GoogleDrive/Test Doc";s:39:"OCA\Files_Versions\Command\Expireuser";s:5:"Chris";}): {"Exception":"OC\\User\\NoUserException","Message":"Attempted to initialize mount points for null user and no user in session","Code":0,"Trace":"#0 \/var\/www\/owncloud\/apps\/files_versions\/lib\/storage.php(102): OC\\Files\\Filesystem::initMountPoints(false)\n#1 \/var\/www\/owncloud\/apps\/files_versions\/lib\/storage.php(682): OCA\\Files_Versions\\Storage::getUidAndFilename('\/External_Googl...')\n#2 \/var\/www\/owncloud\/apps\/files_versions\/command\/expire.php(61): OCA\\Files_Versions\\Storage::expire('\/External_Googl...')\n#3 \/var\/www\/owncloud\/lib\/private\/command\/commandjob.php(34): OCA\\Files_Versions\\Command\\Expire->handle()\n#4 \/var\/www\/owncloud\/lib\/private\/backgroundjob\/job.php(52): OC\\Command\\CommandJob->run('O:33:\"OCA\\\\Files...')\n#5 \/var\/www\/owncloud\/lib\/private\/backgroundjob\/queuedjob.php(42): OC\\BackgroundJob\\Job->execute(Object(OC\\BackgroundJob\\JobList), Object(OC\\Log))\n#6 \/var\/www\/owncloud\/cron.php(145): OC\\BackgroundJob\\QueuedJob->execute(Object(OC\\BackgroundJob\\JobList), Object(OC\\Log))\n#7 {main}","File":"\/var\/www\/owncloud\/lib\/private\/files\/filesystem.php","Line":376}

Seems to be a file versions issue... any Ideas (beside "flush all versions" (not an option at the moment))? Pretty annoying ... :(

PVince81 · 2016-07-05T07:32:29Z

@bcutter mind using the issue template ? It looks like you're using external storage (Gdrive).
Would be good to know which exact OC version you use and how you mounted said external storage (system-wide mount or personal mount,etc)

bcutter · 2016-07-05T08:12:50Z

Hmm, it seems to have stopped 11 hours ago. If I'll see this again in owncloud.log I'll provide all necessary information.

PVince81 · 2016-09-20T09:28:52Z

@mmattel did you still see this happening with 9.1.1RC2 ?

mmattel · 2016-09-26T12:10:53Z

I have upgraded to 9.1.1 yesterday and have not identified that the error gets logged. Seems that the issue is solved. Closing. Will reopen if it raises again.

ownclouders · 2017-12-21T01:08:13Z

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

(This is an automated comment from GitMate.io.

lock · 2019-07-31T14:00:48Z

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

mmattel added the Type:Bug label May 31, 2016

PVince81 changed the title ~~Error while running background job~~ Error while running version expire background job May 31, 2016

PVince81 added feature:sharing app:files_versions labels May 31, 2016

PVince81 added this to the 9.1-current milestone May 31, 2016

PVince81 added the sev3-medium label May 31, 2016

PVince81 added needs info and removed app:files_versions labels Jun 23, 2016

PVince81 modified the milestones: 9.1-current, 9.1.1-next-maintenance Jun 30, 2016

PVince81 modified the milestones: 9.1.2, 9.1.1 Sep 21, 2016

mmattel closed this as completed Sep 26, 2016

lock bot locked as resolved and limited conversation to collaborators Jul 31, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Error while running version expire background job #24914

Error while running version expire background job #24914

mmattel commented May 31, 2016

PVince81 commented May 31, 2016

mmattel commented May 31, 2016

mmattel commented May 31, 2016

PVince81 commented Jun 23, 2016

PVince81 commented Jun 23, 2016

PVince81 commented Jun 23, 2016

PVince81 commented Jun 23, 2016

PVince81 commented Jun 23, 2016

PVince81 commented Jun 23, 2016

PVince81 commented Jun 23, 2016

bcutter commented Jul 4, 2016

PVince81 commented Jul 5, 2016

bcutter commented Jul 5, 2016

PVince81 commented Sep 20, 2016

mmattel commented Sep 26, 2016

ownclouders commented Dec 21, 2017

lock bot commented Jul 31, 2019

Error while running version expire background job #24914

Error while running version expire background job #24914

Comments

mmattel commented May 31, 2016

Steps to reproduce

Expected behaviour

Actual behaviour

Server configuration

Client configuration

Logs

owncloud.log

webserver.log

PVince81 commented May 31, 2016

mmattel commented May 31, 2016

mmattel commented May 31, 2016

PVince81 commented Jun 23, 2016

PVince81 commented Jun 23, 2016

PVince81 commented Jun 23, 2016

PVince81 commented Jun 23, 2016

PVince81 commented Jun 23, 2016

PVince81 commented Jun 23, 2016

PVince81 commented Jun 23, 2016

bcutter commented Jul 4, 2016

PVince81 commented Jul 5, 2016

bcutter commented Jul 5, 2016

PVince81 commented Sep 20, 2016

mmattel commented Sep 26, 2016

ownclouders commented Dec 21, 2017

lock bot commented Jul 31, 2019