Too many log out and Cannot authenticate over ajax calls

Abdelkarim_Mateos_Sa · September 25, 2019, 7:19pm

Steps to reproduce

User logged on web
User tries send some files (20)
Owncloud show error Cannot authenticate over ajax calls. User is out. Users needs log in.

Expected behaviour

The user should not have problems

Actual behaviour

This is a simple test. The customer complaint comes from the web and from the apps. Many times clients and / or web users disconnect

Server configuration

Operating system:
Ubuntu 18.04.3 LTS updated
Web server:
Server version: Apache/2.4.29 (Ubuntu)
Database:
5.7.27-0ubuntu0.18.04.1
PHP version:
PHP 7.2.19-0ubuntu0.18.04.2
ownCloud version: (see ownCloud admin page)
10.2.1.4

Updated from an older ownCloud or fresh install:
Fresh from 10 (one year ~ working)

Where did you install ownCloud from:
apt-get

Login as admin user into your ownCloud and access 
http://example.com/index.php/settings/integrity/failed 
paste the results into https://gist.github.com/ and puth the link here.

No errors have been found.

The content of config/config.php:

{
    "system": {
        "updatechecker": false,
        "instanceid": "ocd7zqha1jjg",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "kvm494.avanzait.com"
        ],
        "datadirectory": "\/data",
        "overwrite.cli.url": "http:\/\/kvm494.avanzait.com",
        "dbtype": "mysql",
        "version": "10.2.1.4",
        "dbname": "owncloud",
        "dbhost": "localhost",
        "dbtableprefix": "oc_",
        "mysql.utf8mb4": true,
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "logtimezone": "UTC",
        "installed": true,
        "filelocking.enabled": true,
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "redis": {
            "host": "\/var\/run\/redis\/redis-server.sock",
            "port": 0,
            "timeout": 0,
            "dbindex": 0
        },
        "memcache.local": "\\OC\\Memcache\\APCu",
        "memcache.distributed": "\\OC\\Memcache\\Redis",
        "memcached_servers": [
            [
                "localhost",
                11211
            ]
        ],
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpmode": "php",
        "theme": "",
        "loglevel": 2,
        "maintenance": false
    }
}

List of activated apps:

Enabled:
  - comments: 0.3.0
  - configreport: 0.2.0
  - dav: 0.4.0
  - federatedfilesharing: 0.4.0
  - federation: 0.1.0
  - files: 1.5.2
  - files_external: 0.7.1
  - files_sharing: 0.11.0
  - files_trashbin: 0.9.1
  - files_versions: 1.3.0
  - files_videoplayer: 0.10.1
  - firstrunwizard: 1.2.0
  - market: 0.5.0
  - notifications: 0.5.0
  - provisioning_api: 0.5.0
  - systemtags: 0.3.0
  - updatenotification: 0.2.1
Disabled:
  - encryption
  - external
  - user_external

Are you using encryption: no

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

Client configuration

Browser:
Chrome Versión 77.0.3865.90 (Build oficial) (64 bits)
Fail also with Opera 63.0.3368.94
Operating system:
Ubuntu 18.04

Logs

Web server error log

Date time is newer that last errors…
Wed Sep 25 19:08:36 UTC 2019
https://paste.tamainut.info/view/999d2684

ownCloud log (data/owncloud.log)

Not log 0 bytes

Browser log

https://paste.tamainut.info/view/c3828b32

eneubauer · September 26, 2019, 9:52am

What was last changed? Did it stop working with an upgrade?
I can see that there is the following error message:
Failed to connect to the database
Can you check that your MySQL server if it is running correctly?
systemctl status mysql

Perhaps also check with ss that mysql is listening on 3306:
ss -tulpen '( sport = 3306 )'

The output should look something like this:

root@ubuntu1804:~# ss -tulpen '( sport = 3306 )'
Netid               State                 Recv-Q                 Send-Q                                  Local Address:Port                                 Peer Address:Port                
tcp                 LISTEN                0                      80                                            0.0.0.0:3306                                      0.0.0.0:*                    users:(("mysqld",pid=535,fd=24)) uid:107 ino:17649 sk:3 <->

Abdelkarim_Mateos_Sa · September 28, 2019, 7:13pm

Hi,.

A lot of thanks…

After read your response tunning mysql. Very small config for query_cache…

wel… Now owncloud get some minutes after break withg same problem, and now NOT log any problem about mysql connections

Below last error BEFORE modify my.cnf

Now time is Sat Sep 28 19:10:11 UTC 2019 and log not wrote any thing… but still same problem.

[Sat Sep 28 19:01:41.959914 2019] [proxy_fcgi:error] [pid 1485] [client 2.155.236.21:62811] AH01071: Got error 'PHP message: PHP Fatal error:  Uncaught Doctrine\\DBAL\\DBALException: Failed to connect to the database: An exception occured in driver: SQLSTATE[HY000] [2002] No such file or directory in /var/www/owncloud/lib/private/DB/Connection.php:62\nStack trace:\n#0 /var/www/owncloud/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/Connection.php(429): OC\\DB\\Connection->connect()\n#1 /var/www/owncloud/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/Connection.php(389): Doctrine\\DBAL\\Connection->getDatabasePlatformVersion()\n#2 /var/www/owncloud/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/Connection.php(328): Doctrine\\DBAL\\Connection->detectDatabasePlatform()\n#3 /var/www/owncloud/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/Connection.php(623): Doctrine\\DBAL\\Connection->getDatabasePlatform()\n#4 /var/www/owncloud/lib/private/DB/Connection.php(144): Doctrine\\DBAL\\Connection->setTransactionIsolation(2)\n#5 /var/www/owncloud/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/DriverManager.php(172): OC\\DB\\Connection->__construct(Array, O...\nPHP message: PHP Fatal error:  Uncaught Doctrine\\DBAL\\DBALException: Failed to connect to the database: An exception occured in driver: SQLSTATE[HY000] [2002] No such file or directory in /var/www/owncloud/lib/private/DB/Connection.php:62\nStack trace:\n#0 /var/www/owncloud/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/Connection.php(429): OC\\DB\\Connection->connect()\n#1 /var/www/owncloud/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/Connection.php(389): Doctrine\\DBAL\\Connection->getDatabasePlatformVersion()\n#2 /var/www/owncloud/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/Connection.php(328): Doctrine\\DBAL\\Connection->detectDatabasePlatform()\n#3 /var/www/owncloud/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/Connection.php(623): Doctrine\\DBAL\\Connection->getDatabasePlatform()\n#4 /var/www/owncloud/lib/private/DB/Connection.php(144): Doctrine\\DBAL\\Connection->setTransactionIsolation(2)\n#5 /var/www/owncloud/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/DriverManager.php(172): OC\\DB\\Connection->__construct(Array, O...\n'

On Onwcloud log any error about my ip…

● mysql.service - MySQL Community Server
   Loaded: loaded (/lib/systemd/system/mysql.service; enabled; vendor preset: enabled)
   Active: active (running) since Sat 2019-09-28 19:01:51 UTC; 12min ago
  Process: 13649 ExecStart=/usr/sbin/mysqld --daemonize --pid-file=/run/mysqld/mysqld.pid (code=exited, status=0/SUCCESS)
  Process: 13619 ExecStartPre=/usr/share/mysql/mysql-systemd-start pre (code=exited, status=0/SUCCESS)
 Main PID: 13651 (mysqld)
    Tasks: 33 (limit: 4660)
   CGroup: /system.slice/mysql.service
           └─13651 /usr/sbin/mysqld --daemonize --pid-file=/run/mysqld/mysqld.pid

Sep 28 19:00:38 kvm494 systemd[1]: Starting MySQL Community Server...
Sep 28 19:01:51 kvm494 systemd[1]: Started MySQL Community Server.

Best regards.

anon21401411 · September 29, 2019, 7:13am

Hey,

it looks to me that the Database server’s socket isn’t running / available at the location where ownCloud is expecting / you have configured it.

Maybe posts like e.g. the following are helping you to solve your configuration issue?

Abdelkarim_Mateos_Sa · October 2, 2019, 4:40pm

Well.

If not in location of mysql, why work and after for example 60 seconds not work?

If thre’re a problem with location, is simple., Why Users can login ?

Also, logs for problem with mysql is older to actual problem.

anon21401411 · October 2, 2019, 5:23pm

Hey,

maybe you can then provide more recent log files and try to see if there are not additional logs in the web server or PHP logfile about this?

I have just found the following in your web servers logfile:

proxy_fcgi:error

From what i have read in the past ownCloud is only supporting mod_php on Apache and php-fpm on nginx so maybe you can try to switch to one of the following options:

anon21401411 · October 2, 2019, 5:38pm

Hey,

i also did the following search Search results for 'proxy_fcgi' - ownCloud Central and found various threads mentioning that this web server modules requires a special configuration for an authentication:

It looks to me that those could be related to your problem caused by this web server module.

Abdelkarim_Mateos_Sa · October 2, 2019, 5:58pm

Well.

I can back to Server requeriments with A Apache 2.4 with prefork and mod_php

apachectl -V | grep -i mpm
Server MPM:     prefork

No errors in any log

tail -f /var/log/redis/redis-server.log /data/owncloud.log /var/log/mysql/error.log /var/log/apache2/error.log

But problem persists…

anon21401411 · October 2, 2019, 6:09pm

Hey,

i don’t think that the prefork module is enough. Maybe you can check via apachectl -M if mod_php is used?

Abdelkarim_Mateos_Sa · October 2, 2019, 6:35pm

root@dropbox:~# apachectl -M |  grep prefork
 mpm_prefork_module (shared)
root@dropbox:~# 


root@dropbox:~# tail -f /var/log/redis/redis-server.log /data/owncloud.log /var/log/mysql/error.log /var/log/apache2/error.log
==> /var/log/redis/redis-server.log <==
1876:M 02 Oct 20:28:41.779 * Removing the pid file.
1876:M 02 Oct 20:28:41.780 * Removing the unix socket file.
1876:M 02 Oct 20:28:41.780 # Redis is now ready to exit, bye bye...
1672:C 02 Oct 20:29:58.164 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
1672:C 02 Oct 20:29:58.194 # Redis version=4.0.9, bits=64, commit=00000000, modified=0, pid=1672, just started
1672:C 02 Oct 20:29:58.194 # Configuration loaded
1871:M 02 Oct 20:29:58.205 * Running mode=standalone, port=0.
1871:M 02 Oct 20:29:58.206 # Server initialized
1871:M 02 Oct 20:29:58.232 * DB loaded from disk: 0.026 seconds
1871:M 02 Oct 20:29:58.232 * The server is now ready to accept connections at /var/run/redis/redis.sock

==> /data/owncloud.log <==

==> /var/log/mysql/error.log <==
2019-10-02 20:30:00 140656254393472 [Note] InnoDB: Completed initialization of buffer pool
2019-10-02 20:30:00 140656254393472 [Note] InnoDB: Highest supported file format is Barracuda.
2019-10-02 20:30:00 140656254393472 [Note] InnoDB: 128 rollback segment(s) are active.
2019-10-02 20:30:00 140656254393472 [Note] InnoDB: Waiting for purge to start
2019-10-02 20:30:01 140656254393472 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.44-86.0 started; log sequence number 1050937324621
2019-10-02 20:30:01 140656254393472 [Note] Plugin 'FEEDBACK' is disabled.
2019-10-02 20:30:01 140654554380032 [Note] InnoDB: Dumping buffer pool(s) not yet started
2019-10-02 20:30:01 140656254393472 [Note] Server socket created on IP: '::'.
2019-10-02 20:30:01 140656254393472 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.1.41-MariaDB-0ubuntu0.18.04.1'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  Ubuntu 18.04

==> /var/log/apache2/error.log <==
[Wed Oct 02 20:24:11.089899 2019] [core:notice] [pid 11137] AH00094: Command line: '/usr/sbin/apache2'
[Wed Oct 02 20:28:42.251688 2019] [mpm_prefork:notice] [pid 11137] AH00169: caught SIGTERM, shutting down
[Wed Oct 02 20:29:59.577669 2019] [suexec:notice] [pid 1747] AH01232: suEXEC mechanism enabled (wrapper: /usr/lib/apache2/suexec)
[Wed Oct 02 20:29:59.677307 2019] [:error] [pid 2184] python_init: Python version mismatch, expected '2.7.6', found '2.7.15+'.
[Wed Oct 02 20:29:59.709657 2019] [:error] [pid 2184] python_init: Python executable found '/usr/bin/python'.
[Wed Oct 02 20:29:59.709687 2019] [:error] [pid 2184] python_init: Python path being used '/usr/lib/python2.7:/usr/lib/python2.7/plat-x86_64-linux-gnu:/usr/lib/python2.7/lib-tk:/usr/lib/python2.7/lib-old:/usr/lib/python2.7/lib-dynload'.
[Wed Oct 02 20:29:59.709740 2019] [:notice] [pid 2184] mod_python: Creating 8 session mutexes based on 150 max processes and 0 max threads.
[Wed Oct 02 20:29:59.709752 2019] [:notice] [pid 2184] mod_python: using mutex_directory /tmp 
[Wed Oct 02 20:29:59.951951 2019] [mpm_prefork:notice] [pid 2184] AH00163: Apache/2.4.29 (Ubuntu) mod_fcgid/2.3.9 mod_python/3.3.1 Python/2.7.15+ OpenSSL/1.1.1c configured -- resuming normal operations
[Wed Oct 02 20:29:59.952013 2019] [core:notice] [pid 2184] AH00094: Command line: '/usr/sbin/apache2'

anon21401411 · October 2, 2019, 8:52pm

Hey,

i think prefork and mod_php are two completely different things and if i’m understand this correctly:

you are still running proxy_fcgid/mod_fcgid instead of the recommended mod_php.

eneubauer · October 4, 2019, 9:25am

Can you check the state of your MySQL installation and double check that tables don’t need repairing. Perhaps once you boot up MySQL is trying to start but somehow fails later on and goes away after about a minute?
I just want to make sure that the issue absolutely doesn’t lie with MySQL. Perhaps once the error appears, try to run the mysql command on your DB server and try to browse your databases and tables:

mysql #use flags like -h to connect to specific host and -u for a username and -p for password
show databases;
use owncloud;
show tables;
select * from oc_activity;
exit;

If this doesn’t work check the mysql unit, journalctl and the mysql logs for messages:

systemctl status mysql #type `q` to exit pager
journalctl -xef # ctrl+c to exit this one
less /var/log/mysql/error.log #type `q` again to exit less