[10.0.9]Trying to get owner from an erased file #32346

cdamken · 2018-08-15T15:45:36Z

After upgrading from 10.0.8 to 10.0.9 I'm getting a lot of this errors:

{"reqId":"aVZ86bwUZOHjbSkPtaCu","level":3,"time":"2018-08-14T17:45:07+02:00","remoteAddr":"","user":"--","app":"no app in context","method":"--","url":"--","message":"Exception: {"Exception":"OCP\Files\NotFoundException","Message":"/trabajos/xxxxxxs.xlsx.v1526485490 not found while trying to get owner","Code":0,"Trace":"
#0 /var/www/owncloud/lib/private/Files/Filesystem.php(960): OC\Files\View->getOwner('/trabajos/aries...')
#1 /var/www/owncloud/lib/private/Preview.php(1315): OC\Files\Filesystem::getOwner('/trabajos/xxxxx...')
#2 /var/www/owncloud/lib/private/Preview.php(1303): OC\Preview::post_delete(Array, 'files/')
#3 /var/www/owncloud/lib/private/legacy/hook.php(105): OC\Preview::post_delete_versions(Array)
#4 /var/www/owncloud/apps/files_versions/lib/Storage.php(504): OC_Hook::emit('\OCP\Versions', 'delete', Array)
#5 /var/www/owncloud/apps/files_versions/lib/BackgroundJob/ExpireVersions.php(75): OCA\Files_Versions\Storage::expireOlderThanMaxForUser('lizzardts')
#6 /var/www/owncloud/lib/private/User/Manager.php(440): OCA\Files_Versions\BackgroundJob\ExpireVersions->OCA\Files_Versions\BackgroundJob\{closure}(Object(OC\User\User))
#7 /var/www/owncloud/lib/private/User/AccountMapper.php(233): OC\User\Manager->OC\User\{closure}(Object(OC\User\Account))
#8 /var/www/owncloud/lib/private/User/Manager.php(441): OC\User\AccountMapper->callForAllUsers(Object(Closure), '', true)
#9 /var/www/owncloud/lib/private/User/Manager.php(459): OC\User\Manager->callForAllUsers(Object(Closure), '', true)
#10 /var/www/owncloud/apps/files_versions/lib/BackgroundJob/ExpireVersions.php(76): OC\User\Manager->callForSeenUsers(Object(Closure))
#11 /var/www/owncloud/lib/private/BackgroundJob/Job.php(57): OCA\Files_Versions\BackgroundJob\ExpireVersions->run(NULL)
#12 /var/www/owncloud/lib/private/BackgroundJob/TimedJob.php(53): OC\BackgroundJob\Job->execute(Object(OC\BackgroundJob\JobList), Object(OC\Log))
#13 /var/www/owncloud/cron.php(121): OC\BackgroundJob\TimedJob->execute(Object(OC\BackgroundJob\JobList), Object(OC\Log))
#14 {main}","File":"/var/www/owncloud/lib/private/Files/View.php","Line":1718}"}

It doesn't look like a big error, but the log is full of those messages

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

ownclouders · 2018-08-15T16:09:07Z

GitMate.io thinks the contributor most likely able to help you is @PVince81.

Possibly related issues are #27770 (File version preview icon not showing up after upgrading from 9.1.5 to 10.0.0), #30537 (Bump phpseclib/phpseclib from 2.0.9 to 2.0.10), #28331 (DB issues after upgrade from 9.1.5 to 10.0.2), #5176 (Preview for avi files), and #4785 (OC 5.0.10 Gallery bug: Gallery treats a ZIP file as image and tries to show a preview image for a zip file .zip).

PVince81 · 2018-08-22T15:23:00Z

seems the version expiry code is triggering the thumbnail/preview deletion code which itself is running into the error.

we should probably catch the error in the preview handler in case we try to delete a preview for an already deleted version.

now it's not guaranteed that the current state works, maybe it's actually leaving the previews on-disk... needs to be tested.

PVince81 · 2018-10-15T20:08:11Z

Steps to reproduce

Create a text file "test.txt"
Edit the file three times in the text editor and save each time, will create three versions
Open the versions panel to have it generate previews
Run cron.php and observe the logs

Expected result

No errors

Actual result

{"reqId":"viyF6aTvAF41QBIxIu9B","level":3,"time":"2018-10-15T19:37:42+00:00","remoteAddr":"","user":"--","app":"no app in context","method":"--","url":"--","message":"Exception: {\"Exception\":\"OCP\\\\Files\\\\NotFoundException\",\"Message\":\"\\\/test.txt.v1539632201 not found while trying to get owner\",\"Code\":0,\"Trace\":\"#0 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/Files\\\/Filesystem.php(961): OC\\\\Files\\\\View->getOwner('\\\/test.txt.v1539...')\\n#1 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/Preview.php(1241): OC\\\\Files\\\\Filesystem::getOwner('\\\/test.txt.v1539...')\\n#2 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/legacy\\\/hook.php(105): OC\\\\Preview::prepare_delete(Array)\\n#3 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/apps\\\/files_versions\\\/lib\\\/Storage.php(765): OC_Hook::emit('\\\\\\\\OCP\\\\\\\\Versions', 'preDelete', Array)\\n#4 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/apps\\\/files_versions\\\/lib\\\/Command\\\/Expire.php(60): OCA\\\\Files_Versions\\\\Storage::expire('\\\/test.txt', 'admin')\\n#5 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/Command\\\/CommandJob.php(34): OCA\\\\Files_Versions\\\\Command\\\\Expire->handle()\\n#6 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/BackgroundJob\\\/Job.php(57): OC\\\\Command\\\\CommandJob->run('O:33:\\\"OCA\\\\\\\\Files...')\\n#7 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/BackgroundJob\\\/QueuedJob.php(42): OC\\\\BackgroundJob\\\\Job->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#8 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/cron.php(120): OC\\\\BackgroundJob\\\\QueuedJob->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#9 {main}\",\"File\":\"\\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/Files\\\/View.php\",\"Line\":1717}"}
{"reqId":"viyF6aTvAF41QBIxIu9B","level":3,"time":"2018-10-15T19:37:42+00:00","remoteAddr":"","user":"--","app":"no app in context","method":"--","url":"--","message":"Exception: {\"Exception\":\"OCP\\\\Files\\\\NotFoundException\",\"Message\":\"\\\/test.txt.v1539632201 not found while trying to get owner\",\"Code\":0,\"Trace\":\"#0 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/Files\\\/Filesystem.php(961): OC\\\\Files\\\\View->getOwner('\\\/test.txt.v1539...')\\n#1 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/Preview.php(1311): OC\\\\Files\\\\Filesystem::getOwner('\\\/test.txt.v1539...')\\n#2 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/Preview.php(1299): OC\\\\Preview::post_delete(Array, 'files\\\/')\\n#3 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/legacy\\\/hook.php(105): OC\\\\Preview::post_delete_versions(Array)\\n#4 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/apps\\\/files_versions\\\/lib\\\/Storage.php(767): OC_Hook::emit('\\\\\\\\OCP\\\\\\\\Versions', 'delete', Array)\\n#5 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/apps\\\/files_versions\\\/lib\\\/Command\\\/Expire.php(60): OCA\\\\Files_Versions\\\\Storage::expire('\\\/test.txt', 'admin')\\n#6 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/Command\\\/CommandJob.php(34): OCA\\\\Files_Versions\\\\Command\\\\Expire->handle()\\n#7 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/BackgroundJob\\\/Job.php(57): OC\\\\Command\\\\CommandJob->run('O:33:\\\"OCA\\\\\\\\Files...')\\n#8 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/BackgroundJob\\\/QueuedJob.php(42): OC\\\\BackgroundJob\\\\Job->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#9 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/cron.php(120): OC\\\\BackgroundJob\\\\QueuedJob->execute(Object(OC\\\\BackgroundJob\\\\JobList), Object(OC\\\\Log))\\n#10 {main}\",\"File\":\"\\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/Files\\\/View.php\",\"Line\":1717}"}

Version

v10.0.10 from git

Bisect points at commit b09846b which points to b09846b regarding the change related to version previews.

This is a regression from v10.0.8

PVince81 · 2018-10-15T20:10:02Z

From what I see in past versions we didn't call getOwner() in the post_delete hook handler.
Since the move to the new previews endpoint, we need it.

PVince81 · 2018-10-15T20:18:56Z

The issue happens because the $path seems to be a relative path instead of absolute and looks like "/test.txt.v123456678". It also only does this getOwner() fallback because no user id was passed as arguments.

There are two fixes we can do here:

Fix the $path to be absolute
Add user id argument in https://github.com/owncloud/core/blob/v10.0.10/apps/files_versions/lib/Storage.php#L767 to remove the need for calling getOwner()
Check for other code paths to make sure there are no other such cases!

PVince81 · 2018-10-15T20:22:04Z

hmmm, making $path arg absolute could be dangerous as it could affect old hooks.

I diffed the files_versions/lib/Storage.php class with v10.0.8 and there was no notable changes, so the path was always absolute. It seems that in v10.0.8 the Preview::post_delete was mostly based on the logged in user. Not sure how this could even work back then with cron where there is no logged in user, maybe it didn't and just failed silently.

PVince81 · 2018-10-15T20:33:43Z

I've checked v10.0.8 and observed the following:

Preview::post_delete is called for deleting previews when overwriting a file, which is ok.
$path is always relative to the user, whether deleting from overwrite or from an expiry
expiry of versions doesn't actually find the versions previews as we never have a logged in user when running cron, so version previews are never deleted through this mechanism... The Preview constructor even tries to create the path with an empty user, so the root path becomes "//files/" and it tries to look for "//files/test.txt.v123456789"

The assumption that $path is relative in v10.0.9+ is wrong. We better not change the semantics of the hook as it could break other implementations.

When running in cron I suggest to pass in the user id argument as we have it. If no user id argument is given, the handler should abort and log a debug message about a missing arg.

PVince81 · 2018-10-15T20:42:45Z

Hmm even user id is not enough, and neither is the relative path "/test.txt.v123456789" because it's missing the "/files_version" prefix.

Looks like the prefix specified in "post_delete_versions" is incorrect.

PVince81 · 2018-10-15T21:00:03Z

It seems that even fixing the prefix and passing in the user is not enough: the v10.0.10 code tries to get "/$user/files/test.txt.v123456789" which of course it cannot find. We'll likely need to implement version-specific code here, maybe in "post_delete_versions" instead of relying on "post_delete".

PVince81 · 2018-10-15T21:07:39Z

also from what I saw, the preview folders location for versions has changed and is now a subdir of "$fileid/$timestamp" instead of having its own fileid, so it is likely that deletion needs to be done completely differently.

@DeepDiver1975 I'll need your guidance to continue here. Here's my PR so far: #33188

Next up would be to write new methods "Preview::prepare_delete_versions" and "Preview::post_delete_versions" with its own specific code. I'm not sure if Preview::deleteAllPreviews() is the right approach now with the new versions location.

Also it seems that Preview::addPathToDeleteFileMapper is thinking it's receiving an absolute path but my observation is that hook paths are always relative, scary 🙈

PVince81 · 2018-10-16T07:37:25Z

and since we're using the node API now I'm wondering whether the query should rather go to "meta" to get the versioned node, then have logic in the preview delete methods that detect the versioned node and know where to delete the thumbnails in "$fileid/$timestamp".

PVince81 · 2018-10-17T16:27:02Z

The previews behavior is also a little bit strange when restoring a file: since the original file gets overwritten, the folder "thumbnails/$fileid" gets deleted, so all version previews also get deleted. At that stage, the versions tab still displays cached previews. Once I refresh the page, it will regenerate a preview for each version displayed in the versions tab. So version previews aren't kept.

This is only a minor issue as regenerating is only for few entries and the final outcome is the same: all previews are displayed correctly in the web UI.

I mostly wanted to see if there was an actual explicit code path for deleting a version thumbnail when restoring a version file. Since the parent folder gets deleted such logic wouldn't be needed.

PVince81 · 2018-10-20T08:13:52Z

Once this is fixed, we'll likely also want an occ command and/or repair step to clean up all orphaned previews that failed to be deleted on expiration. Raised here: #33240

DeepDiver1975 · 2018-11-12T08:21:08Z

Steps to reproduce
1.

@PVince81 what is your expiration config? THX

PVince81 · 2018-11-12T13:46:35Z

@DeepDiver1975 all default.

I use the trick where I reset oc_jobs timestamp to make sure the cron job will run.

DeepDiver1975 · 2018-11-26T11:55:39Z

I use the trick where I reset oc_jobs timestamp to make sure the cron job will run.

I tried this with default behavior - and the occ command ...
.... will try with cron next ....

PVince81 · 2019-01-11T09:59:17Z

in the meantime, here's an attempt at mitigation: #34118

this would prevent the exception but would also leave some stray previews

PVince81 · 2019-01-21T15:31:27Z

I realize that I missed one crucial step for reproduction, added now:
"3. Open the versions panel to have it generate previews"

IljaN changed the title ~~[10.0.9]Trying to get a preview from an erased file~~ [10.0.9]Trying to get owner from an erased file Aug 15, 2018

PVince81 added Type:Bug p3-medium Normal priority labels Aug 22, 2018

PVince81 added this to the backlog milestone Aug 22, 2018

PVince81 self-assigned this Oct 11, 2018

PVince81 mentioned this issue Oct 15, 2018

[stable10] Backport all objectstore related changes #31050

Merged

8 tasks

PVince81 added the regression label Oct 15, 2018

PVince81 added the feature:previews label Oct 15, 2018

PVince81 mentioned this issue Oct 15, 2018

Attempt to fix version preview deletion #33188

Closed

13 tasks

PVince81 mentioned this issue Oct 20, 2018

occ command to delete orphaned previews #33240

Closed

PVince81 modified the milestones: backlog, development Oct 23, 2018

PVince81 mentioned this issue Nov 2, 2018

Exception is shown in owncloud.log when we have several versions of a file #33028

Closed

PVince81 mentioned this issue Jan 11, 2019

Skip preview expiry when owner cannot be determined #34118

Merged

11 tasks

PVince81 assigned VicDeo and unassigned PVince81 Jan 28, 2019

VicDeo mentioned this issue Jan 28, 2019

Fixup preview issues with trashbin/versions #34283

Merged

10 tasks

PVince81 closed this as completed in #34283 Feb 18, 2019

VicDeo mentioned this issue Feb 18, 2019

[stable10] Fixup preview issues with trashbin/versions #34533

Merged

9 tasks

lock bot locked as resolved and limited conversation to collaborators Feb 18, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[10.0.9]Trying to get owner from an erased file #32346

[10.0.9]Trying to get owner from an erased file #32346

cdamken commented Aug 15, 2018

ownclouders commented Aug 15, 2018

PVince81 commented Aug 22, 2018

PVince81 commented Oct 15, 2018 •

edited

Loading

PVince81 commented Oct 15, 2018

PVince81 commented Oct 15, 2018

PVince81 commented Oct 15, 2018 •

edited

Loading

PVince81 commented Oct 15, 2018 •

edited

Loading

PVince81 commented Oct 15, 2018

PVince81 commented Oct 15, 2018

PVince81 commented Oct 15, 2018

PVince81 commented Oct 16, 2018

PVince81 commented Oct 17, 2018

PVince81 commented Oct 20, 2018

DeepDiver1975 commented Nov 12, 2018 •

edited

Loading

Steps to reproduce

PVince81 commented Nov 12, 2018

DeepDiver1975 commented Nov 26, 2018

PVince81 commented Jan 11, 2019

PVince81 commented Jan 21, 2019

[10.0.9]Trying to get owner from an erased file #32346

[10.0.9]Trying to get owner from an erased file #32346

Comments

cdamken commented Aug 15, 2018

ownclouders commented Aug 15, 2018

PVince81 commented Aug 22, 2018

PVince81 commented Oct 15, 2018 • edited Loading

Steps to reproduce

Expected result

Actual result

Version

PVince81 commented Oct 15, 2018

PVince81 commented Oct 15, 2018

PVince81 commented Oct 15, 2018 • edited Loading

PVince81 commented Oct 15, 2018 • edited Loading

PVince81 commented Oct 15, 2018

PVince81 commented Oct 15, 2018

PVince81 commented Oct 15, 2018

PVince81 commented Oct 16, 2018

PVince81 commented Oct 17, 2018

PVince81 commented Oct 20, 2018

DeepDiver1975 commented Nov 12, 2018 • edited Loading

Steps to reproduce

PVince81 commented Nov 12, 2018

DeepDiver1975 commented Nov 26, 2018

PVince81 commented Jan 11, 2019

PVince81 commented Jan 21, 2019

PVince81 commented Oct 15, 2018 •

edited

Loading

PVince81 commented Oct 15, 2018 •

edited

Loading

PVince81 commented Oct 15, 2018 •

edited

Loading

DeepDiver1975 commented Nov 12, 2018 •

edited

Loading