9.1.1 RC1: Long time to open administrator page

[martin-zh]

Steps to reproduce

1. Upgraded from 9.0.x to 9.1.0 and 9.1.1 RC
2. Log in
3. Open Administrator Page

Expected behaviour
Page should load as fast as the other ones.

Actual behaviour
It take forever to load the page. It shows up after a couple of minutes but still wainting for something.

Server configuration
Operating system: Ubuntu 16.04
Web server: Apache
Database: mysql
PHP version:
ownCloud version (see ownCloud admin page): 9.1.1 RC
Updated from an older ownCloud or fresh install: updated from 9.1.0

ownCloud log (data/owncloud.log, see https://central.owncloud.org/t/how-to-find-webserver-or-oc-logfile-enable-php-logfile/808):
{"reqId":"VC1FcF0BfVFcc79lNUWy","remoteAddr":"192.168.1.218","app":"index","message":"Exception: {"Exception":"OC\NeedsUpdateException","Message":"","Code":0,"Trace":"#0 /var/www/owncloud/lib/private/legacy/app.php(119): OC_App::loadApp('dav')\n#1 /var/www/owncloud/lib/private/legacy/util.php(135): OC_App::loadApps(Array)\n#2 /var/www/owncloud/lib/base.php(890): OC_Util::setupFS()\n#3 /var/www/owncloud/index.php(39): OC::handleRequest()\n#4 {main}","File":"/var/www/owncloud/lib/private/legacy/app.php","Line":147}","level":3,"time":"2016-08-24T05:52:09+00:00","method":"GET","url":"/index.php/core/js/oc.js?v=8017b0bd05b37ab6dbf39a9190ac521e","user":"--"}
{"reqId":"A8+UJvfRoAWPR8tjiLBW","remoteAddr":"192.168.1.218","app":"core","message":"starting upgrade from 9.1.0.15 to 9.1.1.0","level":0,"time":"2016-08-24T05:52:11+00:00","method":"GET","url":"/core/ajax/update.php?requesttoken=KCkICjc%2FMQAOQH88ZT91djYwAw4GAWhMM3wnOVs%2BER0%3D%3AnbQpBQHbW38p4PACTCOLalP9T5lXnqETuX%2BkBFTa9Do%3D","user":"--"}
{"reqId":"mRrN2zE6Pqpro9fRuLbm","remoteAddr":"192.168.1.49","app":"PHP","message":"Uncaught Error: Access to undeclared static property: OC\Files\Filesystem::$normalizedPathCache in /var/www/owncloud/lib/private/Files/Filesystem.php:772\nStack trace:\n#0 /var/www/owncloud/lib/private/Files/View.php(2039): OC\Files\Filesystem::normalizePath('/tobiasbausch@g...')\n#1 /var/www/owncloud/lib/private/Files/View.php(1151): OC\Files\View->unlockFile('/MyFriends/Komm...', 1)\n#2 [internal function]: OC\Files\View->OC\Files{closure}()\n#3 /var/www/owncloud/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#772","level":3,"time":"2016-08-29T10:31:44+00:00","method":"PROPFIND","url":"/remote.php/webdav/","user":"jstaub@cfc.ch"}
{"reqId":"AqQ1OZ5pz1s9Wc12oevw","remoteAddr":"192.168.1.49","app":"PHP","message":"Uncaught Error: Access to undeclared static property: OC\Files\Filesystem::$normalizedPathCache in /var/www/owncloud/lib/private/Files/Filesystem.php:772\nStack trace:\n#0 /var/www/owncloud/lib/private/Files/View.php(2039): OC\Files\Filesystem::normalizePath('/tobiasbausch@g...')\n#1 /var/www/owncloud/lib/private/Files/View.php(1151): OC\Files\View->unlockFile('/MyFriends/Komm...', 1)\n#2 [internal function]: OC\Files\View->OC\Files{closure}()\n#3 /var/www/owncloud/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#772","level":3,"time":"2016-08-29T10:33:14+00:00","method":"PROPFIND","url":"/remote.php/webdav/","user":"jstaub@cfc.ch"}
Special configuration (external storage, external authentication, reverse proxy, server-side-encryption):
Integrity status for oC9+

Login as admin user into your ownCloud and access
http://example.com/index.php/settings/integrity/failed
No errors have been found.

I'm not shure if this issue started with 9.1.1 RC1 - 9.1.0 was very slow. Personal, user and help are working as expected, logout takes a long time too.

[PVince81]

forever to load the page

Do you see a blank page until it loads ? Or does the page load partially but isn't finished ?
Can you check the network console of the browser to see which request takes a long time ?

[martin-zh]

It stays at the old page. After 2 minutes, the admin page fully loads. during this time, it hangs at
curl "https://xxx/ocs/v2.php/apps/notifications/api/v1/notifications?format=json" -H "Accept: */*" -H "requesttoken: xxxxxFCRwUkHFdDJAE7MQg=:mX6mV7276Y7UOOxaDSB5qh1ujotOgMFx/mA/yRKOGhw=" -H "X-Requested-With: XMLHttpRequest" -H "User-Agent: Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36" -H "OCS-APIREQUEST: true" --compressed
(I've modified the URL and the token)

I also see the error
Failed to parse SourceMap: https://xxx/core/vendor/jquery/dist/jquery.min.map

[martin-zh]

Same issue with 9.1.1RC2

[martin-zh]

When the admin page finally loads, I'll get the following error in the Apache error log:
[Fri Sep 09 08:05:09.842893 2016] [authz_core:error] [pid 5488] [client 192.168.1.218:2455] AH01630: client denied by server configuration: /var/www/owncloud/data/htaccesstest.txt

[PVince81]

Hmm, try disabling the notifications app ? I don't see why it would take that long, and why on the users page and not the files view.

Anyway, you said it stays at the old page while loading, so this means that in fact it's the PHP process that builds the page that is taking a long time. Do you have a lot of groups ? Maybe it's loading and building the groups section. These aren't ajax loaded yet. (future task: #10994)

[martin-zh]

deactivating the notifications app doesn't help at all. the issue affects the Administrator page only - CPU goes up.
There are only 5 groups. Users page loads fast...

[PVince81]

Ah! Sorry, I misunderstood... Most of the time people complain about the users page being slow.

Ok, most of the admin page is built on the server side. So there might be an app that takes longer to build it.

How big is your owncloud.log at the moment ? There were reports that the log section is taking a long time to load even though it's supposed to properly use fseek.

Let's find out if the problem is with the log, you can try applying this patch:

diff --git a/lib/private/Log/Owncloud.php b/lib/private/Log/Owncloud.php
index 07106be..7cb9488 100644
--- a/lib/private/Log/Owncloud.php
+++ b/lib/private/Log/Owncloud.php
@@ -131,6 +131,7 @@ class Owncloud {
         * @return array
         */
        public static function getEntries($limit=50, $offset=0) {
+               return [];
                self::init();
                $minLevel = \OC::$server->getSystemConfig()->getValue("loglevel", \OCP\Util::WARN);
                $entries = array();

This will make the log fetcher return nothing.

[martin-zh]

wow - yes, this resolves the issue!! The file is only 62MB.
I now moved the log file to /var/log/ using 'logfile' => '/var/log/owncloud.log' in the config file and reverted the changes from your patch file. Issue is resolved!

[PVince81]

Hmm, but this doesn't make sense. Where was the log file stored before ?

If the log file size is the same as before, it can't take longer to read from the former location than to read it from /var/log

[martin-zh]

The log file was at the default location. The log file in ist new Location is now empty instead 62MB

[PVince81]

Okay, then it makes sense.

Now the question is why it takes that long to read on your environment.

[martin-zh]

anything I can do to help troubleshooting?

[PVince81]

@martin-zh I'd say simply post your PHP and web server version. Maybe it's related.

[martin-zh]

Apache2: 2.4.18-2ubun
PHP7: 7.0.8-0ubunt

[ccheveaux]

Hello,

I add this line : + return [];
My admin panel is now load.

I configure my log to level 4 but the 'owncloud.log' show me the same of level 0 :/
And the file grows very quickly ...

[PVince81]

Note that changing the log level only applies to new entries appended to the log, old entries will stay.
If changing the log level setting doesn't work, see #26131

[ccheveaux]

Ok better !
Thx a lot 👍

[PVince81]

From what I see the log reading code parses the log file byte by byte from the end, looking for newlines and stops when the limit is reached.

Not sure why this would be slow on some systems ? I'd think that modern operating systems would cache the file in memory and make such jumping fast.

It should be possible to optimize this a bit by making it jump block-wise instead of byte-wise.
Basically: jump 1kb back and gather the lines, then jump the next 1kb bytes, etc. Would reduce the number of required fseek.

[PVince81]

and: always ajax load the log. So if it's slow it would still display the admin page and the slowness would only be in the log level section (spinner)

[ccheveaux]

I have same issue for just one group of my users page.
And like when you open this page, it defaults to all users, the page is blocked directly.
Finally I want to say that load without stopping.

[PVince81]

Hmmm, indeed the original reporter @martin-zh had the issue on the users page.
But the users page isn't supposed to load the logs.

[PVince81]

I just tried with a debugger and the log-loading code doesn't run when opening the users page. Weird...

[ccheveaux]

It's only for 'ENS_DGM_Profs' group

[PVince81]

Okay, I managed to recreate this: I added sleep(1); in the log loading code.

Here is what is likely happening:

• browser tab 1: open the admin page, it is slow. This starts the PHP process that reads the log file. Even if you close the tab, it will continue running until the end or until a PHP timeout occurs
• browser tab 2: open the users page => slow

Why would it be slow ? Maybe it is trying to write entries into the log while the log is still being parsed.
So this would mean that the log file is locked while the admin page is being loaded, which also means that ANY process trying to log anything will block. This is bad because it means an administrator can slow down their whole instance just by browsing the admin page.

Will try and confirm this.

[PVince81]

Just did a local test and it seems to only affect the currently logged in user, not other sessions.
So it's probably a session issue.

The solution for this is to make the log only be loaded in ajax.

But I wonder whether we should simply remove it completely because I find that it's barely usable and best is to use a better log viewer app instead.

[martin-zh]

IMHO it should be removed completely. A log viewer app can be used if someone needs to dig into the log ifle.

[PVince81]

Sounds good, that's also what @DeepDiver1975 @butonic said.

We can't remove this in a stable version but could do it for 9.2.

@RealRancor have you heard of many users using the log viewer on the admin page ?

[PVince81]

Ok, so this PR would remove the log entries table #26225 but keep the "download log" button.

[ghost]

@RealRancor have you heard of many users using the log viewer on the admin page ?

We are mostly pointing the users to the data/owncloud.log file itself.

[ownclouders]

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]

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.