Log entry file source not found in log when uploading to inner reshares

[PVince81]

Follow up from #14764 (comment).

Steps

1. As "root" create two users "user1" and "user2"
2. Create folder "test"
3. Share "test" with "user1"
4. Login as "user1"
5. Create a subfolder "test/inside"
6. Share "inside" with "user2"
7. Login as "user2"
8. Upload a picture into "inside"

Getting this:

{"reqId":"8OAtSUxMON6k+RMx36Zn","remoteAddr":"127.0.0.1","app":"files_sharing","message":"File source not found for: ","level":0,"time":"2015-04-27T12:34:14+00:00","method":"POST","url":"\/owncloud\/index.php\/apps\/files\/ajax\/upload.php"}
{"reqId":"8OAtSUxMON6k+RMx36Zn","remoteAddr":"127.0.0.1","app":"files_sharing","message":"File source not found for: \/test","level":0,"time":"2015-04-27T12:34:14+00:00","method":"POST","url":"\/owncloud\/index.php\/apps\/files\/ajax\/upload.php"}
{"reqId":"8OAtSUxMON6k+RMx36Zn","remoteAddr":"127.0.0.1","app":"files_sharing","message":"File source not found for: inside","level":0,"time":"2015-04-27T12:34:14+00:00","method":"POST","url":"\/owncloud\/index.php\/apps\/files\/ajax\/upload.php"}
{"reqId":"8OAtSUxMON6k+RMx36Zn","remoteAddr":"127.0.0.1","app":"files_sharing","message":"File source not found for: inside","level":0,"time":"2015-04-27T12:34:14+00:00","method":"POST","url":"\/owncloud\/index.php\/apps\/files\/ajax\/upload.php"}
{"reqId":"rLbDcikMeickRlQrf\/yV","remoteAddr":"127.0.0.1","app":"core","message":"Generating preview for \"\/inside\/IMAG0279.jpg\" with \"OC\\Preview\\JPEG\"","level":0,"time":"2015-04-27T12:34:15+00:00","method":"GET","url":"\/owncloud\/index.php\/core\/preview.png?file=%2Finside%2FIMAG0279.jpg&c=3a05ac1232efb080ad15dcafb6cf5c52&x=36&y=36&forceIcon=0"}
{"reqId":"rLbDcikMeickRlQrf\/yV","remoteAddr":"127.0.0.1","app":"core","message":"OC_Image->fixOrientation() Orientation: -1","level":0,"time":"2015-04-27T12:34:15+00:00","method":"GET","url":"\/owncloud\/index.php\/core\/preview.png?file=%2Finside%2FIMAG0279.jpg&c=3a05ac1232efb080ad15dcafb6cf5c52&x=36&y=36&forceIcon=0"}

Stack:

0  OC_Share_Backend_File::getSource() /srv/www/htdocs/owncloud/apps/files_sharing/lib/share/file.php:228
1  OC\Files\Cache\Shared_Cache->getSourceCache() /srv/www/htdocs/owncloud/apps/files_sharing/lib/cache.php:63
2  OC\Files\Cache\Shared_Cache->get() /srv/www/htdocs/owncloud/apps/files_sharing/lib/cache.php:98
3  OC\Files\Cache\ChangePropagator->propagateChanges() /srv/www/htdocs/owncloud/lib/private/files/cache/changepropagator.php:78
4  OCA\Files_Sharing\Propagation\ChangeWatcher->propagateForOwner() /srv/www/htdocs/owncloud/apps/files_sharing/lib/propagation/changewatcher.php:73
5  OCA\Files_Sharing\Propagation\ChangeWatcher->writeHook() /srv/www/htdocs/owncloud/apps/files_sharing/lib/propagation/changewatcher.php:40
6  call_user_func:{/srv/www/htdocs/owncloud/lib/private/hook.php:103}() /srv/www/htdocs/owncloud/lib/private/hook.php:103
7  OC_Hook::emit() /srv/www/htdocs/owncloud/lib/private/hook.php:103
8  OC\Files\View->emit_file_hooks_post() /srv/www/htdocs/owncloud/lib/private/files/view.php:513
9  OC\Files\View->file_put_contents() /srv/www/htdocs/owncloud/lib/private/files/view.php:543
10 OC\Files\View->fromTmpFile() /srv/www/htdocs/owncloud/lib/private/files/view.php:840
11 OC\Files\Filesystem::fromTmpFile() /srv/www/htdocs/owncloud/lib/private/files/filesystem.php:700
12 require_once()  /srv/www/htdocs/owncloud/apps/files/ajax/upload.php:191
13 __lambda_func() /srv/www/htdocs/owncloud/lib/private/route/route.php%28153%29%20:%20runtime-created%20function:1
14 call_user_func:{/srv/www/htdocs/owncloud/lib/private/route/router.php:272}() /srv/www/htdocs/owncloud/lib/private/route/router.php:272
15 OC\Route\Router->match() /srv/www/htdocs/owncloud/lib/private/route/router.php:272
16 OC::handleRequest() /srv/www/htdocs/owncloud/lib/base.php:853
17 {main}          /srv/www/htdocs/owncloud/index.php:40

Can also be reproduced by running the unit test "testReshareRecipientWritesToReshare" which matches the case. The test doesn't fail because it's only logged as DEBUG. Maybe the consequence is harmless or the situation is expected.
We should still add some checks to avoid logging this (or even going this code path) when expected.

Versions

ownCloud master (557b4a2)

@icewind1991

[karlitschek]

@PVince81 What is the status here?

[PVince81]

@icewind1991 asked me to raise this for him after reviewing etag propagation.
I'm not sure whether the message is harmless or could hide further potential logic issues.

[ghost]

This bug will fall off 8.2 if not resolved by 6 Oct

[PVince81]

Still happening on 9.1.0 beta2:

{"reqId":"29+WHPwZduVs8IdO79xk","remoteAddr":"127.0.0.1","app":"core","message":"File with id \"121\" has not been found.","level":3,"time":"2016-06-14T08:24:38+00:00","method":"GET","url":"\/owncloudtest\/index.php\/avatar\/user2\/41","user":"user1"}
{"reqId":"mpoxXjH3oEXdJD3zIlTp","remoteAddr":"127.0.0.1","app":"core","message":"File with id \"121\" has not been found.","level":3,"time":"2016-06-14T08:25:00+00:00","method":"POST","url":"\/owncloudtest\/index.php\/login","user":"user2"}
{"reqId":"mpoxXjH3oEXdJD3zIlTp","remoteAddr":"127.0.0.1","app":"files_skeleton","message":"copying skeleton for user2 from \/srv\/www\/htdocs\/owncloudtest\/core\/skeleton to \/user2\/files\/","level":0,"time":"2016-06-14T08:25:00+00:00","method":"POST","url":"\/owncloudtest\/index.php\/login","user":"user2"}
{"reqId":"PRRQLBaDe9lVcrCpykJR","remoteAddr":"127.0.0.1","app":"core","message":"File with id \"121\" has not been found.","level":3,"time":"2016-06-14T08:25:03+00:00","method":"GET","url":"\/owncloudtest\/index.php\/apps\/files\/","user":"user2"}
{"reqId":"xCm8UJrIKunzgea5CU\/k","remoteAddr":"127.0.0.1","app":"core","message":"File with id \"121\" has not been found.","level":3,"time":"2016-06-14T08:25:05+00:00","method":"GET","url":"\/owncloudtest\/index.php\/apps\/gallery\/config?extramediatypes=1","user":"user2"}
{"reqId":"WYUrUHJFpR+V+ewwS1ed","remoteAddr":"127.0.0.1","app":"core","message":"File with id \"121\" has not been found.","level":3,"time":"2016-06-14T08:25:06+00:00","method":"PROPFIND","url":"\/owncloudtest\/remote.php\/webdav\/","user":"user2"}
{"reqId":"K9B3+JZkitz+CBsSZxCs","remoteAddr":"127.0.0.1","app":"core","message":"File with id \"121\" has not been found.","level":3,"time":"2016-06-14T08:25:09+00:00","method":"PROPFIND","url":"\/owncloudtest\/remote.php\/webdav\/inside","user":"user2"}
{"reqId":"8zv\/8ue\/ThdHU4qSQ3U5","remoteAddr":"127.0.0.1","app":"core","message":"Generating preview for \"\/inside\/Huoguo.jpg\" with \"OC\\Preview\\JPEG\"","level":0,"time":"2016-06-14T08:25:18+00:00","method":"GET","url":"\/owncloudtest\/index.php\/core\/preview.png?file=%2Finside%2FHuoguo.jpg&c=def793bd529c64591cb1529af622ebbf&x=41&y=41&forceIcon=0","user":"user2"}
{"reqId":"8zv\/8ue\/ThdHU4qSQ3U5","remoteAddr":"127.0.0.1","app":"core","message":"OC_Image->fixOrientation() Orientation: 1","level":0,"time":"2016-06-14T08:25:18+00:00","method":"GET","url":"\/owncloudtest\/index.php\/core\/preview.png?file=%2Finside%2FHuoguo.jpg&c=def793bd529c64591cb1529af622ebbf&x=41&y=41&forceIcon=0","user":"user2"}

@owncloud/sharing

[PVince81]

Not reproducible in v9.1.1

[lock]

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.