[SOLVED] Big Problem, Kopano server could not connect to MariaDB-Server
-
Hello everybody!
First I want to apologize for my bad English. I hope you understand my problem description.
After my ESXi-Host crashes, I restart my VMs, also my Kopano Mailserver. At first everything looked ok. But after a few minutes I realized that Kopano was not working. The daemon kopano-server did not work. So I tried to start it manually with /etc/init.d/kopano-server start. This did not work, I received an error instead with “An error occurred (80000007). Please check /var/log/kopano/server.log for details.” So I looked at the server.log and saw the following entries:Mon Jan 1 19:12:57 2018: [ notice] Starting server version 8,3,4,12, pid 869 Mon Jan 1 19:12:59 2018: [warning] SQL [00000004] info: Try to reconnect Mon Jan 1 19:12:59 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (111) Mon Jan 1 19:12:59 2018: [error ] KDatabase::_Update() query failed: REPLACE INTO settings VALUES ('attachment_storage', 'database'): MYSQL not initialized Mon Jan 1 19:12:59 2018: [error ] Unable to update database settings Mon Jan 1 19:12:59 2018: [ notice] Server shutdown complete.
The MySQL daemon, however, seemed to be running. But a “/etc/init.d/mysql status” gave the following messages:
Jan 01 19:12:59 rohrpostix mysqld[1024]: 180101 19:12:59 [Note] InnoDB: Highest supported file format is Barracuda. Jan 01 19:12:59 rohrpostix mysqld[1024]: 180101 19:12:59 [Note] InnoDB: The log sequence numbers 8352532263 and 8352532263 in ibdata files do not...logfiles! Jan 01 19:12:59 rohrpostix mysqld[1024]: 180101 19:12:59 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer... Jan 01 19:12:59 rohrpostix mysqld[1024]: 180101 19:12:59 [Note] InnoDB: 128 rollback segment(s) are active. Jan 01 19:12:59 rohrpostix mysqld[1024]: 180101 19:12:59 [Note] InnoDB: Waiting for purge to start Jan 01 19:12:59 rohrpostix mysqld[1024]: 180101 19:12:59 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log sequenc...352532273 Jan 01 19:12:59 rohrpostix mysqld[1024]: 180101 19:12:59 [Note] Plugin 'FEEDBACK' is disabled. Jan 01 19:12:59 rohrpostix mysqld[1024]: 180101 19:12:59 [Note] Server socket created on IP: '127.0.0.1'. Jan 01 19:12:59 rohrpostix mysqld[1024]: 180101 19:12:59 [Note] /usr/sbin/mysqld: ready for connections. Jan 01 19:12:59 rohrpostix mysqld[1024]: Version: '10.0.32-MariaDB-0+deb8u1' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Debian) Hint: Some lines were ellipsized, use -l to show in full.
After that, I repeated the start of the kopano server daemon while watching kopano / server.log with tail -f. The following messages have now been generated:
Mon Jan 1 19:59:54 2018: [ notice] Starting server version 8,3,4,12, pid 5639 Mon Jan 1 19:59:55 2018: [warning] SQL [00000002] info: Try to reconnect Mon Jan 1 19:59:55 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (111) Mon Jan 1 19:59:55 2018: [error ] KDatabase::_Update() query failed: REPLACE INTO settings VALUES ('attachment_storage', 'database'): MYSQL not initialized Mon Jan 1 19:59:55 2018: [error ] Unable to update database settings Mon Jan 1 19:59:55 2018: [ notice] Server shutdown complete.
With “mysql -u root -p” I can connect to the MariaDB server.
Then I checked the Kopano database for errors with “mysqlcheck -u root -p --check --databases kopano”. Result:kopano.abchanges OK kopano.acl OK kopano.changes OK kopano.clientupdatestatus OK kopano.deferredupdate OK kopano.hierarchy OK kopano.indexedproperties OK kopano.lob OK kopano.mvproperties OK kopano.names OK kopano.object OK kopano.objectmvproperty OK kopano.objectproperty OK kopano.objectrelation OK kopano.outgoingqueue OK kopano.properties OK kopano.receivefolder OK kopano.searchresults OK kopano.settings OK kopano.singleinstances OK kopano.stores OK kopano.syncedmessages OK kopano.syncs OK kopano.tproperties OK kopano.users OK kopano.versions OK
Now I tried to backup the database with “mysqldump -v --single-transaction --password = xxx kopano> /<backuppath>/kopano.sql”. That, too, has apparently worked.
I do not know what to do next. Therefore I urge you for your help.
The following data to your info:
Debian Version: 8.9
Kopano Version: 8.3.4.12-0+23.1
MariaDB-Version: 10.0.32-0+deb8u1I hope you find this information useful.
Thanks in advance
Christian
-
Hi Christian,
no worries about your english, you’re easy to understand :) Regarding your issue: Could you please check if the connection to your db works with mysql_host = 127.0.0.1 in server.cfg (NOT localhost) - When localhost is defined, kopano-server always tries to use the socket instead. I can’t see anything obvious wrong, because your mysqld seems to run (according to your log-messages you provide) and kopano-server just bails out with not being able to connect. So I would first rule out that the socket (for whatever reason) is not accessible by kopano-server (e.g. permissions, etc.).
- mike
-
Hi Mike,
thanks for your fast response.
Unfortunately, changing the connection type did not work. The error message in server.log has not changed much.Mon Jan 1 21:50:36 2018: [ notice] Starting server version 8,3,4,12, pid 1528 Mon Jan 1 21:50:36 2018: [warning] SQL [00000002] info: Try to reconnect Mon Jan 1 21:50:36 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Mon Jan 1 21:50:36 2018: [error ] KDatabase::_Update() query failed: REPLACE INTO settings VALUES ('attachment_storage', 'database'): MYSQL not initialized Mon Jan 1 21:50:36 2018: [error ] Unable to update database settings Mon Jan 1 21:50:36 2018: [ notice] Server shutdown complete.
/etc/init.d/mysql status currently brings the following messages:
mysql.service - LSB: Start and stop the mysql database server daemon Loaded: loaded (/etc/init.d/mysql) Active: active (running) since Mo 2018-01-01 21:47:09 CET; 10min ago Process: 550 ExecStart=/etc/init.d/mysql start (code=exited, status=0/SUCCESS) CGroup: /system.slice/mysql.service ├─ 633 /bin/bash /usr/bin/mysqld_safe ├─1564 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --skip-log-error --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306 └─1565 logger -t mysqld -p daemon.error Jan 01 21:50:36 rohrpostix mysqld[1565]: 180101 21:50:36 [Note] InnoDB: Highest supported file format is Barracuda. Jan 01 21:50:36 rohrpostix mysqld[1565]: 180101 21:50:36 [Note] InnoDB: The log sequence numbers 8352532333 and 8352532333 in ibdata files do not match the log sequence number 8352532373 in the ib_logfiles! Jan 01 21:50:36 rohrpostix mysqld[1565]: 180101 21:50:36 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer... Jan 01 21:50:36 rohrpostix mysqld[1565]: 180101 21:50:36 [Note] InnoDB: 128 rollback segment(s) are active. Jan 01 21:50:36 rohrpostix mysqld[1565]: 180101 21:50:36 [Note] InnoDB: Waiting for purge to start Jan 01 21:50:37 rohrpostix mysqld[1565]: 180101 21:50:37 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log sequence number 8352532373 Jan 01 21:50:37 rohrpostix mysqld[1565]: 180101 21:50:37 [Note] Plugin 'FEEDBACK' is disabled. Jan 01 21:50:37 rohrpostix mysqld[1565]: 180101 21:50:37 [Note] Server socket created on IP: '127.0.0.1'. Jan 01 21:50:37 rohrpostix mysqld[1565]: 180101 21:50:37 [Note] /usr/sbin/mysqld: ready for connections. Jan 01 21:50:37 rohrpostix mysqld[1565]: Version: '10.0.32-MariaDB-0+deb8u1' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Debian)
That is very strange. Everything went right before the server failed.
Thanks again for the fast support.
Best regards,
Christian -
@kamikaze2508 said in Big Problem, Kopano server could not connect to MariaDB-Server:
MYSQL not initialized
So, not even a connect is possible, as per “Can’t connect to MySQL server on ‘127.0.0.1’ (111)”.
Please post the output of
netstat -tulpen | grep mysqld
Thanks!
- mike
-
OK, here it is:
root@rohrpostix:~# netstat -tulpen | grep mysqld tcp 0 0 127.0.0.1:3306 0.0.0.0:* LISTEN 108 11048 1025/mysqld
If it does work, here is the output of ps ax | grep mysqld
root@rohrpostix:~# ps ax | grep mysqld 634 ? S 0:00 /bin/bash /usr/bin/mysqld_safe 1025 ? Sl 0:00 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --skip-log-error --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306 1026 ? S 0:00 logger -t mysqld -p daemon.error 1580 pts/0 S+ 0:00 grep mysqld
-
Hi Mike!
In the meantime, I was able to find out why the Kopano server daemon was unable to connect through 127.0.0.1. I restricted the user with which Kopano wants to connect to the database to localhost. After 127.0.0.1 was added as an authorized host, it looked good at first. But a few seconds later I got the following entries in server.log:
Tue Jan 2 06:55:42 2018: [ notice] Starting server version 8,3,4,12, pid 1923 Tue Jan 2 06:56:08 2018: [warning] SQL [00000048] info: Try to reconnect Tue Jan 2 06:56:08 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 06:56:08 2018: [error ] KDatabase::_Update() query failed: UPDATE syncs SET change_id = 55730, sync_time = FROM_UNIXTIME(1514872568) WHERE id = 1: MYSQL not initialized Tue Jan 2 06:56:08 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 06:56:08 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 06:56:13 2018: [warning] SQL [00000049] info: Try to reconnect Tue Jan 2 06:56:13 2018: [warning] SQL [00000045] info: Try to reconnect Tue Jan 2 06:56:14 2018: [warning] SQL [00000003] info: Try to reconnect Tue Jan 2 06:56:14 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 06:56:14 2018: [error ] KDatabase::_Update() query failed: UPDATE syncs SET change_id = 55730, sync_time = FROM_UNIXTIME(1514872573) WHERE id = 1: MYSQL not initialized Tue Jan 2 06:56:14 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 06:56:14 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 06:56:19 2018: [warning] SQL [00000046] info: Try to reconnect Tue Jan 2 06:56:19 2018: [warning] SQL [00000047] info: Try to reconnect Tue Jan 2 06:56:19 2018: [warning] SQL [00000003] info: Try to reconnect Tue Jan 2 06:56:19 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 06:56:19 2018: [error ] KDatabase::_Update() query failed: UPDATE syncs SET change_id = 55730, sync_time = FROM_UNIXTIME(1514872579) WHERE id = 1: MYSQL not initialized Tue Jan 2 06:56:19 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 06:56:19 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 06:56:24 2018: [warning] SQL [00000043] info: Try to reconnect Tue Jan 2 06:56:24 2018: [warning] SQL [00000044] info: Try to reconnect ... and so on
So I stoped the Daemon and started it again.
Now I get the old message again:Tue Jan 2 07:11:37 2018: [ notice] Starting server version 8,3,4,12, pid 4242 Tue Jan 2 07:11:38 2018: [warning] SQL [00000004] info: Try to reconnect Tue Jan 2 07:11:38 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:11:38 2018: [error ] KDatabase::_Update() query failed: REPLACE INTO settings VALUES ('attachment_storage', 'database'): MYSQL not initialized Tue Jan 2 07:11:38 2018: [error ] Unable to update database settings Tue Jan 2 07:11:38 2018: [ notice] Server shutdown complete.
I can log in with the Kopano database user via the mysql console without any problems. The following hosts are authorized in MariaDB:
+------------------+------------+ | User | Host | +------------------+------------+ | kopano | % | | kopano | 127.0.0.1 | | root | 127.0.0.1 | | root | ::1 | | debian-sys-maint | localhost | | kopano | localhost | | phpmyadmin | localhost | | root | localhost | | root | rohrpostix | +------------------+------------+
-
Hi!
It get’s more and more strange.
After I try to start kopano-server sometimes kopano-server is terminated directly and sometimes it keeps running, but throw out a lot of error messages:Tue Jan 2 07:31:02 2018: [ notice] Starting server version 8,3,4,12, pid 5828 Tue Jan 2 07:31:22 2018: [warning] SQL [00000028] info: Try to reconnect Tue Jan 2 07:31:22 2018: [warning] SQL [00000020] info: Try to reconnect Tue Jan 2 07:31:22 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:31:22 2018: [error ] KDatabsae::DoSelect(): query failed: SELECT hierarchy_id FROM stores WHERE stores.user_id=3: MYSQL not initialized Tue Jan 2 07:31:22 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:31:22 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:31:22 2018: [error ] KDatabase::_Update() query failed: UPDATE syncs SET change_id = 55730, sync_time = FROM_UNIXTIME(1514874682) WHERE id = 1: MYSQL not initialized Tue Jan 2 07:31:22 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:31:22 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:31:22 2018: [error ] KDatabsae::DoSelect(): query failed: SELECT hierarchy_id FROM stores WHERE stores.user_id=3: MYSQL not initialized Tue Jan 2 07:31:22 2018: [warning] Writeout of logon/off time cache unsuccessful Tue Jan 2 07:31:25 2018: [warning] SQL [00000022] info: Try to reconnect Tue Jan 2 07:31:25 2018: [warning] SQL [00000024] info: Try to reconnect Tue Jan 2 07:31:25 2018: [warning] SQL [00000029] info: Try to reconnect Tue Jan 2 07:31:25 2018: [warning] SQL [00000025] info: Try to reconnect Tue Jan 2 07:31:25 2018: [warning] SQL [00000026] info: Try to reconnect Tue Jan 2 07:31:25 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:31:25 2018: [warning] SQL [00000023] info: Try to reconnect Tue Jan 2 07:31:25 2018: [warning] SQL [00000027] info: Try to reconnect Tue Jan 2 07:31:27 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:31:28 2018: [warning] SQL [00000009] info: Try to reconnect Tue Jan 2 07:31:28 2018: [warning] SQL [00000010] info: Try to reconnect Tue Jan 2 07:31:28 2018: [warning] SQL [00000008] info: Try to reconnect Tue Jan 2 07:31:28 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:31:28 2018: [error ] KDatabase::_Update() query failed: REPLACE INTO properties (tag, type, hierarchyid, val_hi, val_lo) VALUES(26274,64,10,30638995,1362692480): MYSQL not initialized Tue Jan 2 07:31:28 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:31:28 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:31:28 2018: [error ] KDatabsae::DoSelect(): query failed: SELECT 0,properties.tag,properties.type,properties.val_ulong,properties.val_strin g,properties.val_binary,properties.val_double,properties.val_longint,properties.val_hi,properties.val_lo FROM properties WHERE hierarchyid=1185 AND properties.tag IN (32781,32782,32803): MYSQL not initialized Tue Jan 2 07:31:28 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:31:28 2018: [warning] Writeout of logon/off time cache unsuccessful Tue Jan 2 07:31:28 2018: [warning] SQL [00000006] info: Try to reconnect Tue Jan 2 07:31:28 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:31:28 2018: [error ] KDatabsae::DoSelect(): query failed: SELECT pass.propname, pass.value, o.externid, modtime.value, op.value FROM object AS o JOIN objectproperty AS op ON o.id = op.objectid JOIN objectproperty AS pass ON pass.objectid = o.id LEFT JOIN objectproperty AS modtime ON modtime.objectid = o.id AND modtime.propname = 'modtime' WHERE o.objectclass = 65537 AND op.propname = 'loginname' AND op.value = 'christian' AND pass.propname = 'password': MYSQL not initialized Tue Jan 2 07:31:28 2018: [warning] Authentication error by plugin for user "christian": db_query: Unknown error -2147483641 Tue Jan 2 07:31:28 2018: [warning] Failed to authenticate user "christian" from "file:///var/run/kopano/server.sock" using program "apache2" Tue Jan 2 07:31:28 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:31:28 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:31:28 2018: [error ] KDatabsae::DoSelect(): query failed: SELECT pass.propname, pass.value, o.externid, modtime.value, op.value FROM object AS o JOIN objectproperty AS op ON o.id = op.objectid JOIN objectproperty AS pass ON pass.objectid = o.id LEFT JOIN objectproperty AS modtime ON modtime.objectid = o.id AND modtime.propname = 'modtime' WHERE o.objectclass = 65537 AND op.propname = 'loginname' AND op.value = 'christian' AND pass.propname = 'password': MYSQL not initialized Tue Jan 2 07:31:28 2018: [warning] Authentication error by plugin for user "christian": db_query: Unknown error -2147483641 Tue Jan 2 07:31:28 2018: [warning] Failed to authenticate user "christian" from "file:///var/run/kopano/server.sock" using program "apache2" Tue Jan 2 07:31:29 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:31:29 2018: [warning] SQL [00000002] info: Try to reconnect Tue Jan 2 07:31:29 2018: [warning] SQL [00000003] info: Try to reconnect Tue Jan 2 07:31:29 2018: [warning] SQL [00000007] info: Try to reconnect Tue Jan 2 07:31:29 2018: [warning] SQL [00000004] info: Try to reconnect Tue Jan 2 07:31:33 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:31:33 2018: [warning] SQL [00000008] info: Try to reconnect Tue Jan 2 07:31:33 2018: [warning] SQL [00000007] info: Try to reconnect Tue Jan 2 07:31:33 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:31:33 2018: [error ] KDatabase::_Update() query failed: REPLACE INTO properties (tag, type, hierarchyid, val_hi, val_lo) VALUES(26275,64,10,30638995,1382692480): MYSQL not initialized Tue Jan 2 07:31:33 2018: [error ] KDatabsae::DoSelect(): query failed: SELECT MAX(id) FROM changes: MYSQL not initialized Tue Jan 2 07:31:33 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:31:33 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:31:33 2018: [error ] KDatabsae::DoSelect(): query failed: SELECT hierarchy_id FROM stores WHERE stores.user_id=3: MYSQL not initialized Tue Jan 2 07:31:33 2018: [warning] Writeout of logon/off time cache unsuccessful Tue Jan 2 07:31:38 2018: [warning] SQL [00000005] info: Try to reconnect Tue Jan 2 07:31:38 2018: [warning] SQL [00000006] info: Try to reconnect Tue Jan 2 07:31:38 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:31:38 2018: [warning] SQL [00000002] info: Try to reconnect Tue Jan 2 07:31:38 2018: [warning] SQL [00000003] info: Try to reconnect Tue Jan 2 07:31:39 2018: [warning] SQL [00000004] info: Try to reconnect Tue Jan 2 07:31:39 2018: [warning] SQL [00000008] info: Try to reconnect Tue Jan 2 07:31:39 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:31:39 2018: [error ] KDatabase::_Update() query failed: UPDATE syncs SET change_id = 55730, sync_time = FROM_UNIXTIME(1514874698) WHERE id = 1: MYSQL not initialized Tue Jan 2 07:31:39 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:31:39 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:31:39 2018: [error ] KDatabsae::DoSelect(): query failed: SELECT DISTINCT o.externid, o.objectclass, modtime.value, user.value FROM object AS o JOIN objectproperty AS user ON user.objectid = o.id AND upper(user.value) = upper('christian') AND user.propname = 'loginname' LEFT JOIN objectproperty AS modtime ON modtime.propname = 'modtime' AND modtime.objectid = o.id WHERE (o.objectclass & 0xffff0000) = 65536: MYSQL not initialized Tue Jan 2 07:31:39 2018: [warning] Unable to resolve unknown user "christian": db_query: Unknown error -2147483641 Tue Jan 2 07:31:39 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:31:39 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:31:39 2018: [error ] KDatabsae::DoSelect(): query failed: SELECT pass.propname, pass.value, o.externid, modtime.value, op.value FROM object AS o JOIN objectproperty AS op ON o.id = op.objectid JOIN objectproperty AS pass ON pass.objectid = o.id LEFT JOIN objectproperty AS modtime ON modtime.objectid = o.id AND modtime.propname = 'modtime' WHERE o.objectclass = 65537 AND op.propname = 'loginname' AND op.value = 'christian' AND pass.propname = 'password': MYSQL not initialized Tue Jan 2 07:31:39 2018: [warning] Authentication error by plugin for user "christian": db_query: Unknown error -2147483641 Tue Jan 2 07:31:39 2018: [warning] Failed to authenticate user "christian" from "file:///var/run/kopano/server.sock" using program "kopano-dagent" Tue Jan 2 07:31:44 2018: [warning] SQL [00000007] info: Try to reconnect Tue Jan 2 07:31:44 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:31:44 2018: [warning] SQL [00000003] info: Try to reconnect Tue Jan 2 07:31:44 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:31:44 2018: [error ] KDatabase::_Update() query failed: UPDATE syncs SET change_id = 55730, sync_time = FROM_UNIXTIME(1514874704) WHERE id = 1: MYSQL not initialized Tue Jan 2 07:31:44 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:31:44 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:31:49 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:31:49 2018: [warning] SQL [00000005] info: Try to reconnect Tue Jan 2 07:31:50 2018: [warning] SQL [00000003] info: Try to reconnect Tue Jan 2 07:31:50 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:31:50 2018: [error ] KDatabase::_Update() query failed: UPDATE syncs SET change_id = 55730, sync_time = FROM_UNIXTIME(1514874709) WHERE id = 1: MYSQL not initialized Tue Jan 2 07:31:50 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:31:50 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:31:55 2018: [warning] SQL [00000004] info: Try to reconnect Tue Jan 2 07:31:55 2018: [warning] SQL [00000003] info: Try to reconnect Tue Jan 2 07:31:55 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:31:55 2018: [error ] KDatabase::_Update() query failed: UPDATE syncs SET change_id = 55730, sync_time = FROM_UNIXTIME(1514874715) WHERE id = 1: MYSQL not initialized Tue Jan 2 07:31:55 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:31:55 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:32:00 2018: [warning] SQL [00000005] info: Try to reconnect Tue Jan 2 07:32:00 2018: [warning] SQL [00000006] info: Try to reconnect Tue Jan 2 07:32:00 2018: [warning] SQL [00000003] info: Try to reconnect Tue Jan 2 07:32:00 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:32:00 2018: [error ] KDatabase::_Update() query failed: UPDATE syncs SET change_id = 55730, sync_time = FROM_UNIXTIME(1514874720) WHERE id = 1: MYSQL not initialized Tue Jan 2 07:32:00 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:32:00 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:32:06 2018: [warning] SQL [00000002] info: Try to reconnect Tue Jan 2 07:32:06 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:32:06 2018: [warning] SQL [00000003] info: Try to reconnect Tue Jan 2 07:32:06 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:32:06 2018: [error ] KDatabase::_Update() query failed: UPDATE syncs SET change_id = 55730, sync_time = FROM_UNIXTIME(1514874726) WHERE id = 1: MYSQL not initialized Tue Jan 2 07:32:06 2018: [warning] SQL [00000000] info: Try to reconnect Tue Jan 2 07:32:06 2018: [error ] KDatabase::Connect(): database access error -2147483641, mysql error: Can't connect to MySQL server on '127.0.0.1' (111) Tue Jan 2 07:32:08 2018: [warning] Shutting down Tue Jan 2 07:32:10 2018: [ notice] Server shutdown complete.
If I try to log in via WebApp during this time, I get the following message in WebApp:
-
Hi all!
In the meantime, I have made further attempts to restore the database connection.
After I copied the virtual machine, I tried to reinstall the MariaDB server with the command “apt-get --reinstall install mariadb-server mariadb-common mariab-server-10.0 mariadb-server-core-10.0”. The reinstallation was apparently also carried out by apt-get. The reinstallation has unfortunately brought no improvement. The connection error still exists. -
Hello @kamikaze2508,
you said this error occured after vm-crash. maybe the connection itself is working but it cant access the tables. Some error messages can mislead every admin :)
Since you reinstalled your mariadb and this didnt change a thing (cause the program itself is not the problem) there is the option to recreate the tables:
/usr/bin/mysqlcheck --all-databases --auto-repair --extended --optimize -u <user> -p<password>
Output should be following:
Table does not support optimize, doing recreate + analyze instead
and the table will be recreated. Note that the server require additional diskspace equal to the table which is currently recreating.
i think its worth a try even if the mysqlcheck output is
kopano.abchanges OK kopano.acl OK [...]
coffee_is_life
-
Hello Coffe_is_life,
thanks for your reply.
If I use the command above I’ve got this Error Message:mysqlcheck: Got error: 2013: Lost connection to MySQL server during query when executing 'OPTIMIZE TABLE ... '
I repeated the command while tracing /var/log/syslog. I’ve got this messages:
Jan 3 11:23:42 rohrpostix mysqld: InnoDB: Error: trying to access page number 4294962431 in space 0, Jan 3 11:23:42 rohrpostix mysqld: InnoDB: space name ./ibdata1, Jan 3 11:23:42 rohrpostix mysqld: InnoDB: which is outside the tablespace bounds. Jan 3 11:23:42 rohrpostix mysqld: InnoDB: Byte offset 0, len 16384, i/o type 10. Jan 3 11:23:42 rohrpostix mysqld: InnoDB: If you get this error at mysqld startup, please check that Jan 3 11:23:42 rohrpostix mysqld: InnoDB: your my.cnf matches the ibdata files that you have in the Jan 3 11:23:42 rohrpostix mysqld: InnoDB: MySQL server. Jan 3 11:23:42 rohrpostix mysqld: 2018-01-03 11:23:42 7f1285766700 InnoDB: Assertion failure in thread 139717525268224 in file fil0fil.cc line 5601 Jan 3 11:23:42 rohrpostix mysqld: InnoDB: We intentionally generate a memory trap. Jan 3 11:23:42 rohrpostix mysqld: InnoDB: Submit a detailed bug report to http://bugs.mysql.com. Jan 3 11:23:42 rohrpostix mysqld: InnoDB: If you get repeated assertion failures or crashes, even Jan 3 11:23:42 rohrpostix mysqld: InnoDB: immediately after the mysqld startup, there may be Jan 3 11:23:42 rohrpostix mysqld: InnoDB: corruption in the InnoDB tablespace. Please refer to Jan 3 11:23:42 rohrpostix mysqld: InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html Jan 3 11:23:42 rohrpostix mysqld: InnoDB: about forcing recovery. Jan 3 11:23:42 rohrpostix mysqld: 180103 11:23:42 [ERROR] mysqld got signal 6 ; Jan 3 11:23:42 rohrpostix mysqld: This could be because you hit a bug. It is also possible that this binary Jan 3 11:23:42 rohrpostix mysqld: or one of the libraries it was linked against is corrupt, improperly built, Jan 3 11:23:42 rohrpostix mysqld: or misconfigured. This error can also be caused by malfunctioning hardware. Jan 3 11:23:42 rohrpostix mysqld: Jan 3 11:23:42 rohrpostix mysqld: To report this bug, see https://mariadb.com/kb/en/reporting-bugs Jan 3 11:23:42 rohrpostix mysqld: Jan 3 11:23:42 rohrpostix mysqld: We will try our best to scrape up some info that will hopefully help Jan 3 11:23:42 rohrpostix mysqld: diagnose the problem, but since we have already crashed, Jan 3 11:23:42 rohrpostix mysqld: something is definitely wrong and this may fail. Jan 3 11:23:42 rohrpostix mysqld: Jan 3 11:23:42 rohrpostix mysqld: Server version: 10.0.32-MariaDB-0+deb8u1 Jan 3 11:23:42 rohrpostix mysqld: key_buffer_size=16777216 Jan 3 11:23:42 rohrpostix mysqld: read_buffer_size=131072 Jan 3 11:23:42 rohrpostix mysqld: max_used_connections=1 Jan 3 11:23:42 rohrpostix mysqld: max_threads=153 Jan 3 11:23:42 rohrpostix mysqld: thread_count=1 Jan 3 11:23:42 rohrpostix mysqld: It is possible that mysqld could use up to Jan 3 11:23:42 rohrpostix mysqld: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 352327 K bytes of memory Jan 3 11:23:42 rohrpostix mysqld: Hope that's ok; if not, decrease some variables in the equation. Jan 3 11:23:42 rohrpostix mysqld: Jan 3 11:23:42 rohrpostix mysqld: Thread pointer: 0x7f127124f008 Jan 3 11:23:42 rohrpostix mysqld: Attempting backtrace. You can use the following information to find out Jan 3 11:23:42 rohrpostix mysqld: where mysqld died. If you see no messages after this, something went Jan 3 11:23:42 rohrpostix mysqld: terribly wrong... Jan 3 11:23:42 rohrpostix mysqld: stack_bottom = 0x7f1285765e88 thread_stack 0x30000 Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0xc047de] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld(handle_fatal_signal+0x3af)[0x7362bf] Jan 3 11:23:42 rohrpostix mysqld: /lib/x86_64-linux-gnu/libpthread.so.0(+0xf890)[0x7f12853cf890] Jan 3 11:23:42 rohrpostix mysqld: /lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f1283f55067] Jan 3 11:23:42 rohrpostix mysqld: /lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f1283f56448] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld[0xa20229] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld[0x9e73b1] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld[0x9caaf1] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld[0xa2c4a3] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld[0x98f248] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld[0x97c6f5] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld[0x9b3d04] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld[0x95fde4] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld[0x9604fc] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld[0x91d750] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld[0x91dd32] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld[0x93cf02] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld[0x8b3feb] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld(_Z17mysql_alter_tableP3THDPcS1_P14HA_CREATE_INFOP10TABLE_LISTP10Alter_infojP8st_orderb+0x2c98)[0x651a28] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld(_Z20mysql_recreate_tableP3THDP10TABLE_LISTb+0x15c)[0x6528cc] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld[0x6a563b] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld(_ZN22Sql_cmd_optimize_table7executeEP3THD+0x8f)[0x6a624f] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x60e)[0x5bf8be] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x1ca)[0x5c5d0a] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1557)[0x5c77f7] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x25b)[0x6976cb] Jan 3 11:23:42 rohrpostix mysqld: /usr/sbin/mysqld(handle_one_connection+0x39)[0x697719] Jan 3 11:23:42 rohrpostix mysqld: /lib/x86_64-linux-gnu/libpthread.so.0(+0x8064)[0x7f12853c8064] Jan 3 11:23:42 rohrpostix mysqld: /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f128400862d] Jan 3 11:23:42 rohrpostix mysqld: Jan 3 11:23:42 rohrpostix mysqld: Trying to get some variables. Jan 3 11:23:42 rohrpostix mysqld: Some pointers may be invalid and cause the dump to abort. Jan 3 11:23:42 rohrpostix mysqld: Query (0x7f125ec20020): is an invalid pointer Jan 3 11:23:42 rohrpostix mysqld: Connection ID (thread ID): 4 Jan 3 11:23:42 rohrpostix mysqld: Status: NOT_KILLED Jan 3 11:23:42 rohrpostix mysqld: Jan 3 11:23:42 rohrpostix mysqld: Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on Jan 3 11:23:42 rohrpostix mysqld: Jan 3 11:23:42 rohrpostix mysqld: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains Jan 3 11:23:42 rohrpostix mysqld: information that should help you find out what is causing the crash. Jan 3 11:23:42 rohrpostix mysqld: Jan 3 11:23:42 rohrpostix mysqld: We think the query pointer is invalid, but we will try to print it anyway. Jan 3 11:23:42 rohrpostix mysqld: Query: OPTIMIZE TABLE `abchanges` Jan 3 11:23:42 rohrpostix mysqld: Jan 3 11:23:42 rohrpostix mysqld_safe: Number of processes running now: 0 Jan 3 11:23:42 rohrpostix mysqld_safe: mysqld restarted Jan 3 11:23:42 rohrpostix mysqld: 180103 11:23:42 [Note] /usr/sbin/mysqld (mysqld 10.0.32-MariaDB-0+deb8u1) starting as process 2245 ... Jan 3 11:23:42 rohrpostix mysqld: 180103 11:23:42 [Note] InnoDB: innodb_empty_free_list_algorithm has been changed to legacy because of small buffer pool size. In order to use backoff, increase buffer pool at least up to 20MB. Jan 3 11:23:42 rohrpostix mysqld: Jan 3 11:23:42 rohrpostix mysqld: 180103 11:23:42 [Note] InnoDB: Using mutexes to ref count buffer pool pages Jan 3 11:23:42 rohrpostix mysqld: 180103 11:23:42 [Note] InnoDB: The InnoDB memory heap is disabled Jan 3 11:23:42 rohrpostix mysqld: 180103 11:23:42 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins Jan 3 11:23:42 rohrpostix mysqld: 180103 11:23:42 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier Jan 3 11:23:42 rohrpostix mysqld: 180103 11:23:42 [Note] InnoDB: Compressed tables use zlib 1.2.8 Jan 3 11:23:42 rohrpostix mysqld: 180103 11:23:42 [Note] InnoDB: Using Linux native AIO Jan 3 11:23:42 rohrpostix mysqld: 180103 11:23:42 [Note] InnoDB: Using CPU crc32 instructions Jan 3 11:23:42 rohrpostix mysqld: 180103 11:23:42 [Note] InnoDB: Initializing buffer pool, size = 128.0M Jan 3 11:23:42 rohrpostix mysqld: 180103 11:23:42 [Note] InnoDB: Completed initialization of buffer pool Jan 3 11:23:42 rohrpostix mysqld: 180103 11:23:42 [Note] InnoDB: Highest supported file format is Barracuda. Jan 3 11:23:42 rohrpostix mysqld: 180103 11:23:42 [Note] InnoDB: Starting crash recovery from checkpoint LSN=8352553334 Jan 3 11:23:42 rohrpostix mysqld: 180103 11:23:42 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer... Jan 3 11:23:42 rohrpostix mysqld: 180103 11:23:42 [Note] InnoDB: Starting final batch to recover 11 pages from redo log Jan 3 11:23:43 rohrpostix mysqld: 180103 11:23:43 [Note] InnoDB: 128 rollback segment(s) are active. Jan 3 11:23:43 rohrpostix mysqld: 180103 11:23:43 [Note] InnoDB: Waiting for purge to start Jan 3 11:23:43 rohrpostix mysqld: 180103 11:23:43 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log sequence number 8352558259 Jan 3 11:23:43 rohrpostix mysqld: 180103 11:23:43 [Note] Plugin 'FEEDBACK' is disabled. Jan 3 11:23:43 rohrpostix mysqld: 180103 11:23:43 [Note] Server socket created on IP: '127.0.0.1'. Jan 3 11:23:43 rohrpostix mysqld: 180103 11:23:43 [Note] /usr/sbin/mysqld: ready for connections. Jan 3 11:23:43 rohrpostix mysqld: Version: '10.0.32-MariaDB-0+deb8u1' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Debian)
-
So we got definetly a problem while accessing specific tables or properties. (if you used user “root” and he should have access to everything)
the next step i would do to get this working is to drop every table on your (test/cloned)-Server, delete or change the data-folder and restore your previous created backup.
mysql <db name> -u <user> -p <password> < /path/to/DB.dmp
than try the recreate command again, if its working i bet kopano does aswell. if not… well thats bad :(
in this case its usefull to have a subsciption//EDIT: Maybe the db.dmp (or kopano.sql in your case) wont work, cause the error itself can be dumped aswell… do you have backup before crashing? - maybe there is some data loss with this, but better some data than everything
coffee_is_life
-
Sorry for my stupid question, but with data directory do you mean /var/lib/mysql, right? Can I just empty it completely, or do I have to leave something in there?
Unfortunately, I have only a database dump and a backup of configuration files. -
in standard there should be something like that in your my.cnf:
[mysqld] datadir=/var/lib/mysql socket=/var/lib/mysql/mysql.sock default-storage-engine=InnoDB [...] !includedir /etc/my.cnf.d
BUT:
if you have something in your include-directory like kopano.cnf which is overwriting the datadir[mysqld] datadir=/export/data/mail/db [...]
thats the right directory
coffee_is_life
-
OK, then it should be the right directory. I only have datadir=/var/lib/mysql in my my.cnf-file and there is no kopano.cnf in the include-directory /etc/mysql/conf.d. Rather, I have a subdirectory kopano in /var/lib/mysql. This looks like the right database directory for me.
I must say that I am particularly familiar with MySQL, so in advance sorry for any stupid questions. -
Better ask twice and maybe stupid question than doing something wrong…
i advise to connect to mysql (mysql kopano -u root -p <pw>)
than view the tables (show tables; )
and drop every single table (drop <table-name>; )
stop mariadb
after that delete the kopano-folder in var/lib/mysql
start mariadb again and restore your backupcoffee_is_life
-
OK, thank you so far. I’ll try that and then get in touch. But may take a while, as I copy my VM as a precaution again.
-
So, here I am again.
I have now tried in my cloned VM to delete the tables with “drop table <Tablename>;”. As soon as I try, I get the following error message:ERROR 2013 (HY000): Lost connection to MySQL server during query
At the same time I receive the following messages in the syslog:
Jan 3 14:21:15 rohrpostix mysqld: InnoDB: Error: trying to access page number 4294962431 in space 0, Jan 3 14:21:15 rohrpostix mysqld: InnoDB: space name ./ibdata1, Jan 3 14:21:15 rohrpostix mysqld: InnoDB: which is outside the tablespace bounds. Jan 3 14:21:15 rohrpostix mysqld: InnoDB: Byte offset 0, len 16384, i/o type 10. Jan 3 14:21:15 rohrpostix mysqld: InnoDB: If you get this error at mysqld startup, please check that Jan 3 14:21:15 rohrpostix mysqld: InnoDB: your my.cnf matches the ibdata files that you have in the Jan 3 14:21:15 rohrpostix mysqld: InnoDB: MySQL server. Jan 3 14:21:15 rohrpostix mysqld: 2018-01-03 14:21:15 7f682559e700 InnoDB: Assertion failure in thread 140085279975168 in file fil0fil.cc line 5601 Jan 3 14:21:15 rohrpostix mysqld: InnoDB: We intentionally generate a memory trap. Jan 3 14:21:15 rohrpostix mysqld: InnoDB: Submit a detailed bug report to http://bugs.mysql.com. Jan 3 14:21:15 rohrpostix mysqld: InnoDB: If you get repeated assertion failures or crashes, even Jan 3 14:21:15 rohrpostix mysqld: InnoDB: immediately after the mysqld startup, there may be Jan 3 14:21:15 rohrpostix mysqld: InnoDB: corruption in the InnoDB tablespace. Please refer to Jan 3 14:21:15 rohrpostix mysqld: InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html Jan 3 14:21:15 rohrpostix mysqld: InnoDB: about forcing recovery. Jan 3 14:21:15 rohrpostix mysqld: 180103 14:21:15 [ERROR] mysqld got signal 6 ; Jan 3 14:21:15 rohrpostix mysqld: This could be because you hit a bug. It is also possible that this binary Jan 3 14:21:15 rohrpostix mysqld: or one of the libraries it was linked against is corrupt, improperly built, Jan 3 14:21:15 rohrpostix mysqld: or misconfigured. This error can also be caused by malfunctioning hardware. Jan 3 14:21:15 rohrpostix mysqld: Jan 3 14:21:15 rohrpostix mysqld: To report this bug, see https://mariadb.com/kb/en/reporting-bugs Jan 3 14:21:15 rohrpostix mysqld: Jan 3 14:21:15 rohrpostix mysqld: We will try our best to scrape up some info that will hopefully help Jan 3 14:21:15 rohrpostix mysqld: diagnose the problem, but since we have already crashed, Jan 3 14:21:15 rohrpostix mysqld: something is definitely wrong and this may fail. Jan 3 14:21:15 rohrpostix mysqld: Jan 3 14:21:15 rohrpostix mysqld: Server version: 10.0.32-MariaDB-0+deb8u1 Jan 3 14:21:15 rohrpostix mysqld: key_buffer_size=16777216 Jan 3 14:21:15 rohrpostix mysqld: read_buffer_size=131072 Jan 3 14:21:15 rohrpostix mysqld: max_used_connections=1 Jan 3 14:21:15 rohrpostix mysqld: max_threads=153 Jan 3 14:21:15 rohrpostix mysqld: thread_count=1 Jan 3 14:21:15 rohrpostix mysqld: It is possible that mysqld could use up to Jan 3 14:21:15 rohrpostix mysqld: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 352327 K bytes of memory Jan 3 14:21:15 rohrpostix mysqld: Hope that's ok; if not, decrease some variables in the equation. Jan 3 14:21:15 rohrpostix mysqld: Jan 3 14:21:15 rohrpostix mysqld: Thread pointer: 0x7f68207fb008 Jan 3 14:21:15 rohrpostix mysqld: Attempting backtrace. You can use the following information to find out Jan 3 14:21:15 rohrpostix mysqld: where mysqld died. If you see no messages after this, something went Jan 3 14:21:15 rohrpostix mysqld: terribly wrong... Jan 3 14:21:15 rohrpostix mysqld: stack_bottom = 0x7f682559de88 thread_stack 0x30000 Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0xc047de] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld(handle_fatal_signal+0x3af)[0x7362bf] Jan 3 14:21:15 rohrpostix mysqld: /lib/x86_64-linux-gnu/libpthread.so.0(+0xf890)[0x7f682520f890] Jan 3 14:21:15 rohrpostix mysqld: /lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f6823d95067] Jan 3 14:21:15 rohrpostix mysqld: /lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f6823d96448] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld[0xa20229] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld[0x9e73b1] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld[0x9caaf1] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld[0xa2c4a3] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld[0x98f248] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld[0x97c6f5] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld[0x9b3d04] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld[0x95f8fd] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld[0x9604fc] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld[0x91d750] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld[0x91dd32] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld[0x943894] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld[0x89c03a] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld(_Z15ha_delete_tableP3THDP10handlertonPKcS4_S4_b+0x211)[0x73a4a1] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld(_Z23mysql_rm_table_no_locksP3THDP10TABLE_LISTbbbbb+0x59e)[0x64641e] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld(_Z14mysql_rm_tableP3THDP10TABLE_LISTcc+0x163)[0x6471a3] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x1650)[0x5c0900] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x1ca)[0x5c5d0a] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1557)[0x5c77f7] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x25b)[0x6976cb] Jan 3 14:21:15 rohrpostix mysqld: /usr/sbin/mysqld(handle_one_connection+0x39)[0x697719] Jan 3 14:21:15 rohrpostix mysqld: /lib/x86_64-linux-gnu/libpthread.so.0(+0x8064)[0x7f6825208064] Jan 3 14:21:15 rohrpostix mysqld: /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f6823e4862d] Jan 3 14:21:15 rohrpostix mysqld: Jan 3 14:21:15 rohrpostix mysqld: Trying to get some variables. Jan 3 14:21:15 rohrpostix mysqld: Some pointers may be invalid and cause the dump to abort. Jan 3 14:21:15 rohrpostix mysqld: Query (0x7f67ff020020): is an invalid pointer Jan 3 14:21:15 rohrpostix mysqld: Connection ID (thread ID): 2 Jan 3 14:21:15 rohrpostix mysqld: Status: NOT_KILLED Jan 3 14:21:15 rohrpostix mysqld: Jan 3 14:21:15 rohrpostix mysqld: Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on Jan 3 14:21:15 rohrpostix mysqld: Jan 3 14:21:15 rohrpostix mysqld: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains Jan 3 14:21:15 rohrpostix mysqld: information that should help you find out what is causing the crash. Jan 3 14:21:15 rohrpostix mysqld: Jan 3 14:21:15 rohrpostix mysqld: We think the query pointer is invalid, but we will try to print it anyway. Jan 3 14:21:15 rohrpostix mysqld: Query: drop table hierarchy Jan 3 14:21:15 rohrpostix mysqld: Jan 3 14:21:16 rohrpostix mysqld_safe: Number of processes running now: 0 Jan 3 14:21:16 rohrpostix mysqld_safe: mysqld restarted Jan 3 14:21:16 rohrpostix mysqld: 180103 14:21:16 [Note] /usr/sbin/mysqld (mysqld 10.0.32-MariaDB-0+deb8u1) starting as process 6491 ... Jan 3 14:21:16 rohrpostix mysqld: 180103 14:21:16 [Note] InnoDB: innodb_empty_free_list_algorithm has been changed to legacy because of small buffer pool size. In order to use backoff, increase buffer pool at least up to 20MB. Jan 3 14:21:16 rohrpostix mysqld: Jan 3 14:21:16 rohrpostix mysqld: 180103 14:21:16 [Note] InnoDB: Using mutexes to ref count buffer pool pages Jan 3 14:21:16 rohrpostix mysqld: 180103 14:21:16 [Note] InnoDB: The InnoDB memory heap is disabled Jan 3 14:21:16 rohrpostix mysqld: 180103 14:21:16 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins Jan 3 14:21:16 rohrpostix mysqld: 180103 14:21:16 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier Jan 3 14:21:16 rohrpostix mysqld: 180103 14:21:16 [Note] InnoDB: Compressed tables use zlib 1.2.8 Jan 3 14:21:16 rohrpostix mysqld: 180103 14:21:16 [Note] InnoDB: Using Linux native AIO Jan 3 14:21:16 rohrpostix mysqld: 180103 14:21:16 [Note] InnoDB: Using CPU crc32 instructions Jan 3 14:21:16 rohrpostix mysqld: 180103 14:21:16 [Note] InnoDB: Initializing buffer pool, size = 128.0M Jan 3 14:21:16 rohrpostix mysqld: 180103 14:21:16 [Note] InnoDB: Completed initialization of buffer pool Jan 3 14:21:16 rohrpostix mysqld: 180103 14:21:16 [Note] InnoDB: Highest supported file format is Barracuda. Jan 3 14:21:16 rohrpostix mysqld: 180103 14:21:16 [Note] InnoDB: Starting crash recovery from checkpoint LSN=8352629695 Jan 3 14:21:16 rohrpostix mysqld: 180103 14:21:16 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer... Jan 3 14:21:16 rohrpostix mysqld: 180103 14:21:16 [Note] InnoDB: Starting final batch to recover 7 pages from redo log Jan 3 14:21:17 rohrpostix mysqld: 180103 14:21:17 [Note] InnoDB: 128 rollback segment(s) are active. Jan 3 14:21:17 rohrpostix mysqld: 180103 14:21:17 [Note] InnoDB: Waiting for purge to start Jan 3 14:21:17 rohrpostix mysqld: 180103 14:21:17 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log sequence number 8352649957 Jan 3 14:21:17 rohrpostix mysqld: 180103 14:21:17 [Note] Plugin 'FEEDBACK' is disabled. Jan 3 14:21:17 rohrpostix mysqld: 180103 14:21:17 [Note] Server socket created on IP: '127.0.0.1'. Jan 3 14:21:17 rohrpostix mysqld: 180103 14:21:17 [Note] /usr/sbin/mysqld: ready for connections. Jan 3 14:21:17 rohrpostix mysqld: Version: '10.0.32-MariaDB-0+deb8u1' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Debian)
It looks to me as if the mariadb-daemon crash and start again directly. Can it be that MariaDB has problems with the InnoDB tablespace?
-
I’m using innoDB aswell without problems…
I think the ibdata1 file is corrupt…
try to stop mariadb, delete the kopano folder under /var/lib/mysql and change the datadir to something else like kopano_safe… just to give mysql another directory for data.
and than restore the dump. This should create the database and its tables
//EDIT: watch this page: https://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html maybe it can help
coffee_is_life -
Hello Coffee_is_life, hello Mike,
your tip helped!
However, I had to take a few extra steps to get everything going again. After stopping mariadb and changing the datadir, I had to execute the following commands so that mariadb could be restarted:First, I had to reinstall the system tables. For this I had to execute the following command:
mysql_install_db --user=mysql
Since I run my mail server on Debian, I had to grant rights to a system user with the following commands after starting mariadb:
mysql -uroot -p mysql> grant all privileges on *.* to 'debian-sys-maint'@'localhost' identified by '<Password>' with grant option;
The password to be assigned here can be found in the file /etc/mysql/debian.cnf.
I have also recreated the kopano database user and authorized it with:mysql> create user 'kopano'@'%' identified by '<Password>'; mysql> grant all privileges on *.* to 'kopano'@'%' identified by '<Password>' with grant option; mysql> exit
Then mariadb had to be restarted.
Then I had to set the password for the root user with:mysqladmin -u root password <new Password>
Now I could create a new empty database and import the dump.
After the import the Kopano server was restarted correctly. Access is now possible again.
Now everything works as it should. :smiley:Thanks for your support. I would not have done without you!