March 7, 2018

Tags

Debugging a Nextcloud error

A couple of days ago I had a problem with the Nextcloud instance on my server: A certain user could not access his files; the web interface only gave the error message Operation not permitted in a popup. ​

This blog post describes how I debugged and solved the issue. ​

Error log message decryption​

I found a log entry in /var/lib/owncloud/wolke/data/nextcloud.log that looked like this: ​

{"reqId":"hbknW8t3PU72y4L3Cm09","level":4,"time":"2018-03-02T19:15:51+00:00","remoteAddr":"81.82.83.84","user":"alice@example.org","app":"webdav","method":"PROPFIND","url":"\/remote.php\/webdav\/","message":"Exception: {\"Exception\":\"OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Exception\\\\Forbidden\",\"Message\":\"No read permissions\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/system\\\/wolke.cweiske.de\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/TagsPlugin.php(222): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory->getChildren()\\n#1 [internal function]: OCA\\\\DAV\\\\Connector\\\\Sabre\\\\TagsPlugin->handleGetProperties(Object(Sabre\\\\DAV\\\\PropFind), Object(OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory))\\n#2 \\\/var\\\/www\\\/system\\\/wolke.cweiske.de\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#3 \\\/var\\\/www\\\/system\\\/wolke.cweiske.de\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1059): Sabre\\\\Event\\\\EventEmitter->emit('propFind', Array)\\n#4 \\\/var\\\/www\\\/system\\\/wolke.cweiske.de\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(981): Sabre\\\\DAV\\\\Server->getPropertiesByNode(Object(Sabre\\\\DAV\\\\PropFind), Object(OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory))\\n#5 \\\/var\\\/www\\\/system\\\/wolke.cweiske.de\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1666): Sabre\\\\DAV\\\\Server->getPropertiesIteratorForPath('', Array, 1)\\n#6 \\\/var\\\/www\\\/system\\\/wolke.cweiske.de\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(355): Sabre\\\\DAV\\\\Server->generateMultiStatus(Object(Generator), false)\\n#7 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPropFind(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#8 \\\/var\\\/www\\\/system\\\/wolke.cweiske.de\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#9 \\\/var\\\/www\\\/system\\\/wolke.cweiske.de\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(479): Sabre\\\\Event\\\\EventEmitter->emit('method:PROPFIND', Array)\\n#10 \\\/var\\\/www\\\/system\\\/wolke.cweiske.de\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#11 \\\/var\\\/www\\\/system\\\/wolke.cweiske.de\\\/apps\\\/dav\\\/appinfo\\\/v1\\\/webdav.php(76): Sabre\\\\DAV\\\\Server->exec()\\n#12 \\\/var\\\/www\\\/system\\\/wolke.cweiske.de\\\/remote.php(162): require_once('\\\/var\\\/www\\\/system...')\\n#13 {main}\",\"File\":\"\\\/var\\\/www\\\/system\\\/wolke.cweiske.de\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Directory.php\",\"Line\":254}","userAgent":"Mozilla\/5.0 (X11; Ubuntu; Linux x86_64; rv:58.0) Gecko\/20100101 Firefox\/58.0","version":"12.0.5.3"}​

Unreadable.
But strings beginning with { are usually JSON encoded, so I put the line into a file error.json and let jq format it: ​

$ jq . < error.json
{
  "reqId": "hbknW8t3PU72y4L3Cm09",
  "level": 4,
  "time": "2018-03-02T19:15:51+00:00",
  "remoteAddr": "81.82.83.84",
  "user": "alice@example.org",
  "app": "webdav",
  "method": "PROPFIND",
  "url": "/remote.php/webdav/",
  "message": "Exception: {\"Exception\":\"OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Exception\\\\Forbidden\",\"Message\":\"No read permissions\",\"Code\":0,\"Trace\":\"#0 \\/var\\/www\\/system\\/wolke.cweiske.de\\/apps\\/dav\\/lib\\/Connector\\/Sabre\\/TagsPlugin.php(222): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory->getChildren()\\n#1 [internal function]: OCA\\\\DAV\\\\Connector\\\\Sabre\\\\TagsPlugin->handleGetProperties(Object(Sabre\\\\DAV\\\\PropFind), Object(OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory))\\n#2 \\/var\\/www\\/system\\/wolke.cweiske.de\\/3rdparty\\/sabre\\/event\\/lib\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#3 \\/var\\/www\\/system\\/wolke.cweiske.de\\/3rdparty\\/sabre\\/dav\\/lib\\/DAV\\/Server.php(1059): Sabre\\\\Event\\\\EventEmitter->emit('propFind', Array)\\n#4 \\/var\\/www\\/system\\/wolke.cweiske.de\\/3rdparty\\/sabre\\/dav\\/lib\\/DAV\\/Server.php(981): Sabre\\\\DAV\\\\Server->getPropertiesByNode(Object(Sabre\\\\DAV\\\\PropFind), Object(OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory))\\n#5 \\/var\\/www\\/system\\/wolke.cweiske.de\\/3rdparty\\/sabre\\/dav\\/lib\\/DAV\\/Server.php(1666): Sabre\\\\DAV\\\\Server->getPropertiesIteratorForPath('', Array, 1)\\n#6 \\/var\\/www\\/system\\/wolke.cweiske.de\\/3rdparty\\/sabre\\/dav\\/lib\\/DAV\\/CorePlugin.php(355): Sabre\\\\DAV\\\\Server->generateMultiStatus(Object(Generator), false)\\n#7 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPropFind(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#8 \\/var\\/www\\/system\\/wolke.cweiske.de\\/3rdparty\\/sabre\\/event\\/lib\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#9 \\/var\\/www\\/system\\/wolke.cweiske.de\\/3rdparty\\/sabre\\/dav\\/lib\\/DAV\\/Server.php(479): Sabre\\\\Event\\\\EventEmitter->emit('method:PROPFIND', Array)\\n#10 \\/var\\/www\\/system\\/wolke.cweiske.de\\/3rdparty\\/sabre\\/dav\\/lib\\/DAV\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#11 \\/var\\/www\\/system\\/wolke.cweiske.de\\/apps\\/dav\\/appinfo\\/v1\\/webdav.php(76): Sabre\\\\DAV\\\\Server->exec()\\n#12 \\/var\\/www\\/system\\/wolke.cweiske.de\\/remote.php(162): require_once('\\/var\\/www\\/system...')\\n#13 {main}\",\"File\":\"\\/var\\/www\\/system\\/wolke.cweiske.de\\/apps\\/dav\\/lib\\/Connector\\/Sabre\\/Directory.php\",\"Line\":254}",
  "userAgent": "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:58.0) Gecko/20100101 Firefox/58.0",
  "version": "12.0.5.3"
}​

This is more redable, but the message is again JSON-encoded. Let's store it into a file: ​

$ jq -r .message < error.json > error2.json​

Then I edited error2.json and removed the leading Exception: , so that I could again run it through jq: ​

$ jq . < error2.json
{
  "Exception": "OCA\\DAV\\Connector\\Sabre\\Exception\\Forbidden",
  "Message": "No read permissions",
  "Code": 0,
  "Trace": "#0 /var/www/system/wolke.cweiske.de/apps/dav/lib/Connector/Sabre/TagsPlugin.php(222): OCA\\DAV\\Connector\\Sabre\\Directory->getChildren()\n#1 [internal function]: OCA\\DAV\\Connector\\Sabre\\TagsPlugin->handleGetProperties(Object(Sabre\\DAV\\PropFind), Object(OCA\\DAV\\Connector\\Sabre\\Directory))\n#2 /var/www/system/wolke.cweiske.de/3rdparty/sabre/event/lib/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\n#3 /var/www/system/wolke.cweiske.de/3rdparty/sabre/dav/lib/DAV/Server.php(1059): Sabre\\Event\\EventEmitter->emit('propFind', Array)\n#4 /var/www/system/wolke.cweiske.de/3rdparty/sabre/dav/lib/DAV/Server.php(981): Sabre\\DAV\\Server->getPropertiesByNode(Object(Sabre\\DAV\\PropFind), Object(OCA\\DAV\\Connector\\Sabre\\Directory))\n#5 /var/www/system/wolke.cweiske.de/3rdparty/sabre/dav/lib/DAV/Server.php(1666): Sabre\\DAV\\Server->getPropertiesIteratorForPath('', Array, 1)\n#6 /var/www/system/wolke.cweiske.de/3rdparty/sabre/dav/lib/DAV/CorePlugin.php(355): Sabre\\DAV\\Server->generateMultiStatus(Object(Generator), false)\n#7 [internal function]: Sabre\\DAV\\CorePlugin->httpPropFind(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#8 /var/www/system/wolke.cweiske.de/3rdparty/sabre/event/lib/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\n#9 /var/www/system/wolke.cweiske.de/3rdparty/sabre/dav/lib/DAV/Server.php(479): Sabre\\Event\\EventEmitter->emit('method:PROPFIND', Array)\n#10 /var/www/system/wolke.cweiske.de/3rdparty/sabre/dav/lib/DAV/Server.php(254): Sabre\\DAV\\Server->invokeMethod(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#11 /var/www/system/wolke.cweiske.de/apps/dav/appinfo/v1/webdav.php(76): Sabre\\DAV\\Server->exec()\n#12 /var/www/system/wolke.cweiske.de/remote.php(162): require_once('/var/www/system...')\n#13 {main}",
  "File": "/var/www/system/wolke.cweiske.de/apps/dav/lib/Connector/Sabre/Directory.php",
  "Line": 254
}​

Here I actually had an error message No read permissions that helped me find the bug that others reported way earlier: [12.0.x] DAV not working after upgrading from 11.0.x #6292. First success. ​

The bug report had no solution, so I had to dig deeper. ​

The Trace was again unreadable, so let's find out how it really looks. jq again: ​

$ jq -r .Trace < error2.json
#0 /var/www/system/wolke.cweiske.de/apps/dav/lib/Connector/Sabre/TagsPlugin.php(222): OCA\DAV\Connector\Sabre\Directory->getChildren()
#1 [internal function]: OCA\DAV\Connector\Sabre\TagsPlugin->handleGetProperties(Object(Sabre\DAV\PropFind), Object(OCA\DAV\Connector\Sabre\Directory))
#2 /var/www/system/wolke.cweiske.de/3rdparty/sabre/event/lib/EventEmitterTrait.php(105): call_user_func_array(Array, Array)
#3 /var/www/system/wolke.cweiske.de/3rdparty/sabre/dav/lib/DAV/Server.php(1059): Sabre\Event\EventEmitter->emit('propFind', Array)
#4 /var/www/system/wolke.cweiske.de/3rdparty/sabre/dav/lib/DAV/Server.php(981): Sabre\DAV\Server->getPropertiesByNode(Object(Sabre\DAV\PropFind), Object(OCA\DAV\Connector\Sabre\Directory))
#5 /var/www/system/wolke.cweiske.de/3rdparty/sabre/dav/lib/DAV/Server.php(1666): Sabre\DAV\Server->getPropertiesIteratorForPath('', Array, 1)
#6 /var/www/system/wolke.cweiske.de/3rdparty/sabre/dav/lib/DAV/CorePlugin.php(355): Sabre\DAV\Server->generateMultiStatus(Object(Generator), false)
#7 [internal function]: Sabre\DAV\CorePlugin->httpPropFind(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))
#8 /var/www/system/wolke.cweiske.de/3rdparty/sabre/event/lib/EventEmitterTrait.php(105): call_user_func_array(Array, Array)
#9 /var/www/system/wolke.cweiske.de/3rdparty/sabre/dav/lib/DAV/Server.php(479): Sabre\Event\EventEmitter->emit('method:PROPFIND', Array)
#10 /var/www/system/wolke.cweiske.de/3rdparty/sabre/dav/lib/DAV/Server.php(254): Sabre\DAV\Server->invokeMethod(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))
#11 /var/www/system/wolke.cweiske.de/apps/dav/appinfo/v1/webdav.php(76): Sabre\DAV\Server->exec()
#12 /var/www/system/wolke.cweiske.de/remote.php(162): require_once('/var/www/system...')
#13 {main}​

That's something we can work with: The backtrace of all functions that had been called until the error occured. ​

Finding the error's source​

The first stop is OCA\DAV\Connector\Sabre\Directory->getChildren(). Some of its parts are the same as in the calling path: ​

/var/www/system/wolke.cweiske.de/apps/dav/lib/Connector/Sabre/TagsPlugin.php(222)​

so that I guessed that Directory.php would be in the same directory. Opening it at line 245 gave is the exception's source: ​

if (!$this->info->isReadable()) {
    // return 403 instead of 404 because a 404 would make
    // the caller believe that the collection itself does not exist
    throw new Forbidden('No read permissions');
}

So we have a $this->info with an isReadable method. The class itself does not define the $info property, so I looked into the Sabre\Node class that Directory extends. ​

Node defines $info, it's of type \OCP\Files\FileInfo. Node's constructor also set a $path property, which I var_dump()'ed just befor the exception is thrown: ​

/alice@example.org/files​

So it's the root directory for the files that is unaccessible. ​

The next step: Finding isReadable(). \OCP\Files\FileInfo is located in lib/public/Files/FileInfo.php (OCP stands for "OwnCloud Public"), but it's an interface only. ​

The actual implementation is in the lib/private/ directory. isReadable() calls checkPermissions(), which itself calls getPermissions(), which uses $this->data. Where does that come from? ​

Searching for $this->data = leads to the constructor, where $data is passed to. Kind of a dead end. ​

So let's look into $data. I added a new dump command before the exception, using getData() because FileInfo::$data is private: ​

var_dump($this->info->getData());

and got: ​

array(
    'fileid' => 1590,
    'storage' => 9,
    'path' => 'files',
    'path_hash' => '45b963397aa40d4a0063e0d85e4fe7a1',
    'parent' => 1589,
    'name' => 'files',
    'mimetype' => 'httpd/unix-directory',
    'mimepart' => 'httpd',
    'size' => 0,
    'mtime' => 1443465491,
    'storage_mtime' => 1387968313,
    'encrypted' => false,
    'etag' => '56098913aff3c',
    'permissions' => 0,
    'checksum' => NULL,
    'encryptedVersion' => 0,
    'storage_id' => '9',
    'type' => 'dir',
)

permissions is 0. That's the problem. ​

Now I looked through the Nextcloud database tables (via adminer) to see which tables have this structure, and found oc_filecache. ​

Nearly all of the rows in that table had permissions = 31, except two of them. I changed them to 31 and the problem was gone. ​

Automatic fixing?​

Fixing the database manually is not something that one should have to do, so I looked for a way to achieve this with official tools. ​

php occ gave me a list of commands, including file commands. The one that looked helpful for this task was files:scan, which was described as ​

rescan filesystem ​

user_id - will rescan all files of the given user(s) ​

​

Since the oc_filecache table is only a cache, re-scanning should fix the error. ​

$ ./occ files:scan alice@example.org

Afterwards, the 0 permissions in the file cache table were set to 31, and all worked as it should. ​

Now everything was done, and I could report my findings in the bug report. ​

The whole process took about 2 hours. ​

Written by Christian Weiske.

Comments? Please send an e-mail.