"File with id not found" log message when on available ext storage

[tflidd]

Steps to reproduce

1. Upgrade from 8.2.x to 9.0.5

Expected behaviour

Clean update

Actual behaviour

My logfile is flooded with NotFoundException messages. I can really find out if there is a malfunction related to that.

ownCloud log (data/owncloud.log)

{"reqId":"B89Tav5iqlC2B0OB++2V","remoteAddr":"my-ip","app":"no app in context","message":"Exception: {\"Exception\":\"OCP\\\\Files\\\\NotFoundException\",\"Message\":\"File with id \\\"223808\\\" has not been found.\",\"Code\":0,\"Trace\":\"
#0 \\\/var\\\/www\\\/owncloud\\\/apps\\\/files_sharing\\\/lib\\\/sharedstorage.php(90): OC\\\\Files\\\\View->getPath(223808)\\n
#1 \\\/var\\\/www\\\/owncloud\\\/apps\\\/files_sharing\\\/lib\\\/sharedstorage.php(581): OC\\\\Files\\\\Storage\\\\Shared->init()\\n
#2 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/storage\\\/wrapper\\\/wrapper.php(381): OC\\\\Files\\\\Storage\\\\Shared->getCache('', Object(OCA\\\\Files_Trashbin\\\\Storage))\\n
#3 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/view.php(1340): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->getCache('')\\n
#4 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/node\\\/root.php(179): OC\\\\Files\\\\View->getFileInfo('\\\/myuser')\\n
#5 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/node\\\/root.php(341): OC\\\\Files\\\\Node\\\\Root->get('\\\/user2')\\n
#6 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/server.php(742): OC\\\\Files\\\\Node\\\\Root->getUserFolder('user2')\\n
#7 \\\/var\\\/www\\\/owncloud\\\/apps\\\/mail\\\/appinfo\\\/application.php(44): OC\\\\Server->getUserFolder('user2')\\n
#8 \\\/var\\\/www\\\/owncloud\\\/apps\\\/mail\\\/appinfo\\\/routes.php(23): OCA\\\\Mail\\\\AppInfo\\\\Application->__construct()\\n
#9 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/route\\\/router.php(330): include_once('\\\/var\\\/www\\\/ownclo...')\\n
#10 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/route\\\/router.php(145): OC\\\\Route\\\\Router->requireRouteFile('\\\/var\\\/www\\\/ownclo...', 'mail')\\n
#11 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/route\\\/router.php(247): OC\\\\Route\\\\Router->loadRoutes()\\n
#12 \\\/var\\\/www\\\/owncloud\\\/ocs\\\/v1.php(54): OC\\\\Route\\\\Router->match('\\\/ocs\\\/apps\\\/notif...')\\n
#13 \\\/var\\\/www\\\/owncloud\\\/ocs\\\/v2.php(22): require_once('\\\/var\\\/www\\\/ownclo...')\\n#14 {main}\",\"File\":\"\\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/view.php\",\"Line\":1677}","level":3,"time":"October 11, 2016 11:00:25","method":"GET","url":"\/owncloud\/ocs\/v2.php\/apps\/notifications\/api\/v1\/notifications?format=json","user":"user2"}

I did some investigation with this file id, I have this entry in the filecache table:
Full texts fileid storage path path_hash parent name mimetype mimepart size mtime encrypted etag unencrypted_size storage_mtime permissions checksum
223808 90 d41d8cd98f00b204e9800998ecf8427e -1 2 1 5887492 1202123016 0 55e482656f490 0 1202123016 23 NULL

The storage id 90 is a external SFTP storage:
sftp::[email protected]// 80 1 1469864325
note that there are really two slashes in the end. There is a different storage id for this connection. Perhaps a bit more information about this storage:

I use a dedicated user who accesses this external sftp storage. This folder is then shared within owncloud to other users. The error occurs under a user that uses this share, even without accessing it. But you can open the share and see all files.

Server configuration

Operating system: Debian 8/apache/mod_php7.0(dotdeb)

Database: mariadb

ownCloud version: 9.0.5

Updated from an older ownCloud or fresh install: update from 8.2.7

Where did you install ownCloud from: manual upgrade

Signing status (ownCloud 9.0 and above): no problems

List of activated apps:

Enabled:
  - activity: 2.2.1
  - announcementcenter: 1.1.2
  - bookmarks: 0.9.0
  - calendar: 1.4.0
  - comments: 0.2
  - contacts: 1.4.0.0
  - dav: 0.1.6
  - external: 1.2
  - 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
  - galleryplus: 15.1.1
  - mail: 0.5.3
  - news: 8.8.3
  - notes: 2.0.2
  - notifications: 0.2.3
  - provisioning_api: 0.4.1
  - systemtags: 0.2
  - updatenotification: 0.1.0

Are you using external storage, if yes which one: sftp

Are you using encryption: no

Are you using an external user-backend, if yes which one: No

[Xuanwo]

I have the same problem, and I can't open the apps page.

[PVince81]

The error occurs under a user that uses this share, even without accessing it. But you can open the share and see all files.

Hmm ok, so it doesn't break functionality but still causes some log messages.
If the SFTP storage is accessible from a dedicated user (where password is stored in the config), then this shouldn't happen. Needs further research.

[PVince81]

Steps I tried:

1. Setup a system-wide SFTP external storage with username/password, mount as "/sftp"
2. Set it to be available only for the "admin" user
3. Go to advanced storage options and enable sharing for this storage
4. Create a user "user1"
5. Upload a file "bacon.txt" into "/sftp"
6. Share "/sftp/bacon.txt" with "user1"
7. Login as "user1"
8. Download "bacon.txt"
9. Login as "admin"
10. Create a folder "/sftp/sub"
11. Upload a file "bacon.txt" into "/sftp/sub"
12. Share "sub" with "user1"
13. Login as "user1"
14. Download the file "/sub/bacon.txt"
15. Login as "admin"
16. Delete the external storage
17. Login as "user1"

After the last login, the share disappeared from the web UI.
But there is no log message about "File with id XYZ not found".

This message usually appears when a share is pointing at a file/folder that is in trash or deleted completely but the share info remain. Such stray info gets cleared when running cron.php.

@tflidd can you give more details about how you created the external storage and how the user is accessing it (download?)

[tflidd]

All the sharing setting were set up a few versions ago (dates back at least to OC 7.0).

1. Allow users to use external storage
2. create user1, user2
3. user1 sets up external sftp storage
4. user1 shares the external sftp storage with user2 (read+write) (and other users, mostly read only)

I see the error when I login with user2. The error started to show up with the upgrade to OC 9.0.5 (from 8.2.7).

Now I logged in as user1 and get this error:

{"reqId":"lWS2PtkMS04zebfCc+rv","remoteAddr":"my-ip","app":"no app in context","message":"Exception: {\"Exception\":\"OCP\\\\Files\\\\NotFoundException\",\"Message\":\"File with id \\\"223808\\\" has not been found.\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/owncloud\\\/apps\\\/files_sharing\\\/lib\\\/sharedstorage.php(90): OC\\\\Files\\\\View->getPath(223808)\\n#1 \\\/var\\\/www\\\/owncloud\\\/apps\\\/files_sharing\\\/lib\\\/sharedstorage.php(581): OC\\\\Files\\\\Storage\\\\Shared->init()\\n#2 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/storage\\\/wrapper\\\/wrapper.php(381): OC\\\\Files\\\\Storage\\\\Shared->getCache('', Object(OCA\\\\Files_Trashbin\\\\Storage))\\n#3 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/view.php(1340): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->getCache('')\\n#4 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/node\\\/root.php(179): OC\\\\Files\\\\View->getFileInfo('\\\/user2')\\n#5 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/avatarmanager.php(93): OC\\\\Files\\\\Node\\\\Root->get('\\\/user2')\\n#6 \\\/var\\\/www\\\/owncloud\\\/core\\\/controller\\\/avatarcontroller.php(117): OC\\\\AvatarManager->getAvatar('user2')\\n#7 [internal function]: OC\\\\Core\\\\Controller\\\\AvatarController->getAvatar('user2', 28)\\n#8 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/appframework\\\/http\\\/dispatcher.php(159): call_user_func_array(Array, Array)\\n#9 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/appframework\\\/http\\\/dispatcher.php(89): OC\\\\AppFramework\\\\Http\\\\Dispatcher->executeController(Object(OC\\\\Core\\\\Controller\\\\AvatarController), 'getAvatar')\\n#10 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/appframework\\\/app.php(110): OC\\\\AppFramework\\\\Http\\\\Dispatcher->dispatch(Object(OC\\\\Core\\\\Controller\\\\AvatarController), 'getAvatar')\\n#11 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/appframework\\\/routing\\\/routeactionhandler.php(45): OC\\\\AppFramework\\\\App::main('AvatarControlle...', 'getAvatar', Object(OC\\\\AppFramework\\\\DependencyInjection\\\\DIContainer), Array)\\n#12 [internal function]: OC\\\\AppFramework\\\\routing\\\\RouteActionHandler->__invoke(Array)\\n#13 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/route\\\/router.php(276): call_user_func(Object(OC\\\\AppFramework\\\\routing\\\\RouteActionHandler), Array)\\n#14 \\\/var\\\/www\\\/owncloud\\\/lib\\\/base.php(907): OC\\\\Route\\\\Router->match('\\\/avatar\\\/user2\\\/28')\\n#15 \\\/var\\\/www\\\/owncloud\\\/index.php(39): OC::handleRequest()\\n#16 {main}\",\"File\":\"\\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/view.php\",\"Line\":1677}","level":3,"time":"October 12, 2016 21:23:57","method":"GET","url":"\/owncloud\/index.php\/avatar\/user2\/28","user":"user1"}

The error message is only about the fileid 223808 (database entry is in my first post).

For the SFTP storage, most uploads were done directly via SFTP. If I now navigate as user1 through the external storage, I get this error:

{"reqId":"ZOhSsPWGkgg8Q1M1SM\/O","remoteAddr":"my-ip","app":"PHP","message":"Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in \/var\/www\/owncloud\/lib\/private\/files\/filesystem.php:798\nStack trace:\n#0 \/var\/www\/owncloud\/lib\/private\/files\/view.php(2011): OC\\Files\\Filesystem::normalizePath('\/user1\/files\/do...')\n#1 \/var\/www\/owncloud\/lib\/private\/files\/view.php(1129): OC\\Files\\View->unlockFile('\/download\/bette...', 1)\n#2 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()\n#3 \/var\/www\/owncloud\/apps\/files_external\/3rdparty\/icewind\/streams\/src\/CallbackWrapper.php(109): call_user_func(Object(Closure))\n#4 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()\n#5 {main}\n  thrown at \/var\/www\/owncloud\/lib\/private\/files\/filesystem.php#798","level":3,"time":"October 12, 2016 21:33:40","method":"PROPFIND","url":"\/owncloud\/remote.php\/webdav\/download","user":"user1"}

When I want to download a file I get this error (user1):

{"reqId":"emMsRMgKsKPjWZsUCGDn","remoteAddr":"my-ip","app":"PHP","message":"rewinddir(): 48 is not a valid Directory resource at \/var\/www\/owncloud\/apps\/files_external\/3rdparty\/icewind\/streams\/src\/Wrapper.php#31","level":0,"time":"October 12, 2016 21:35:46","method":"GET","url":"\/owncloud\/remote.php\/webdav\/download\/folder\/filename.extension","user":"user1"}

I got 2 more with 54 and 58 is not a valid Directory resource. But finally the download starts.

If I navigate through the folders as user2, I get the File-id 223808 error on each folder I open. When I download a file, I get a similar messages:

{"reqId":"Ul+u9ZsHkjwPpE3f3CUv","remoteAddr":"my-ip","app":"PHP","message":"rewinddir(): 49 is not a valid Directory resource at \/var\/www\/owncloud\/apps\/files_external\/3rdparty\/icewind\/streams\/src\/Wrapper.php#31","level":0,"time":"October 12, 2016 21:39:15","method":"GET","url":"\/owncloud\/remote.php\/webdav\/download\/folder\/file.extension","user":"user2"}
{"reqId":"Ul+u9ZsHkjwPpE3f3CUv","remoteAddr":"my-ip","app":"PHP","message":"rewinddir(): 55 is not a valid Directory resource at \/var\/www\/owncloud\/apps\/files_external\/3rdparty\/icewind\/streams\/src\/Wrapper.php#31","level":0,"time":"October 12, 2016 21:39:15","method":"GET","url":"\/owncloud\/remote.php\/webdav\/download\/folder\/file.extension","user":"user2"}
{"reqId":"Ul+u9ZsHkjwPpE3f3CUv","remoteAddr":"my-ip","app":"PHP","message":"rewinddir(): 59 is not a valid Directory resource at \/var\/www\/owncloud\/apps\/files_external\/3rdparty\/icewind\/streams\/src\/Wrapper.php#31","level":0,"time":"October 12, 2016 21:39:15","method":"GET","url":"\/owncloud\/remote.php\/webdav\/download\/folder\/file.extension","user":"user2"}

[tflidd]

I run the occ files:scan on user1, it detected all files but it doesn't change anything.

[PVince81]

I tried with your steps and neither on 8.2.8 not 9.0.5 do I see any of the mentioned errors.
Downloading of files that existed on SFTP before mounting also works.

I suspect that there is something else broken in the DB structure on your env.
Does the SFTP storage appear only once in oc_storages or are there duplicates ?

So far what you posted looks good: the storage exists and the share points there, so it should work.

[PVince81]

Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache

ah, you using PHP 7 ? I tested on PHP 5.6

[tflidd]

the storages-table (I don't use a prefix) has several entries:

sftp::[email protected]//path1/  76  1   NULL
sftp::[email protected]//home/user/  77  1   NULL
sftp::[email protected]/     78  1   NULL
sftp::[email protected]//home/user/path3     79  1   NULL
sftp::[email protected]//    80  1   1476308311

sftp is on a different host and it is the user's home directory. A user on owncloud mounts this external storage and shares it to other users. path1 is the name under which the shared directory is used by one of the users. I don't have the time right now, but I can try to associate different users to the storage id.

I'm using the php7.0 packages (version 7.0.12) of dotdeb under debian 8. It's with apache as php module, I did activate the correct directory setting:

<Directory /var/www/owncloud/>
  Options +FollowSymlinks
  AllowOverride All

 <IfModule mod_dav.c>
  Dav off
 </IfModule>

 SetEnv HOME /var/www/owncloud
 SetEnv HTTP_HOME /var/www/owncloud

</Directory>

[PVince81]

Could not reproduce with PHP7 either.

I reformatted the original stack trace and found this:
#10 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/route\\\/router.php(145): OC\\\\Route\\\\Router->requireRouteFile('\\\/var\\\/www\\\/ownclo...', 'mail')

looks like it's from the mail app, it seems to call getUserFolder of the user very earlier at the time the routes are loaded. Not sure if this is a real issue though. Maybe some stuff isn't fully initialized yet.

[tflidd]

I disabled the mail app but that doesn't change anything.

I looked up the wrong storage id in the db-table. Situation is slightly different:
file-id 223808 is in the filecache-table, it is associated to storage_id=90. Storage_id=90 refers to an external SFTP resource I added a long time ago (OC 7 or OC 8.0) for testing purposes but removed it afterwards. I don't have it mounted anymore. However there is still this entry in the storage-table and the filecache also refers to some more files. The storage id looks like:
sftp::b***@example.org//home/b/b***/subfolder/(the stars replace a username, all small letters, no special chars).

This sql-query is empty (I don't use a table-prefix, the table is not empty):
SELECT * FROMmountsWHEREstorage_id= 90

Questions:

• somehow this storage_id is still linked with one user account but where is this link?
• why doesn't a filecache-scan change anything?
• why are old storage-entries not cleaned from the database?

Perhaps I now need to check manually if there are some old storages that are not used any more but which are still indexed on the filecache-table.

[tflidd]

Just tried on php 5.6.27, it's the same.

[tflidd]

I did some more digging. I probably added this share when experiencing this issue: #18720

I installed a fresh OC 8.0.6 (Debian 8, php5, mysql, apache, all default, no caching, no encryption) and then upgraded to OC 9.0.5 (over 8.0.15, 8.1.10, 8.2.8). In 8.0.6, I only activated files_external and added the SFTP-storage on the personal page. I accessed the folder, then I deleted the external storage. This created two storages:

sftp::b*@example.org//home/b/b*/ 
sftp::b*@example.org//home/b/b*/subfolder/

In the filecache-table, I have entries for the second storage. After removing this external storage, the entries persisted over all upgrades to OC 9.0.5.

Unfortunately, I could not reproduce the error like in my productive system. In this setup, I haven't enabled all apps I normally use and I do not have the same history (original install dates back to OC 4.5 or 5.0.x).

Shouldn't there be a clean-up routine for old external_storages when you delete them?

[PVince81]

Shouldn't there be a clean-up routine for old external_storages when you delete them?

There is one when you delete them manually, but not if they use the $user variable.

But there is another bug that when you change the storage's config, it would simply create new storage ids and leave the old ones...

[tflidd]

Finally, I didn't manage to find a way to reproduce this and I corrected the error manually. The file-ids probably were kept because it was in the trash bin although if you opened the users trash-bin they were not inside.

What I did:
Delete from storages the storage id 90, then I removed from filecache all entries related to this storage id and in a last step, I configured trash-bin retention that all files older than 200 days are deleted.

All these tables regarding storages are not consistent, e.g. I have home storages in the storages table, some of these home-storages are as well in the mounts table with a mount point. But not for all users? It's neither the newest nor the oldest users which are missing?

[PVince81]

Yes... we badly need to introduce foreign keys #13143 and cascading delete to get rid of so many inconsistencies and orphaned entries

[PVince81]

Closing as this is old and I couldn't reproduce this. If more people report this issue in the future for 10.0.4 we can invest more time to dig into the code...

[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.