Bug 422309

Summary:	Akonadi dies after suspend to RAM
Product:	[Frameworks and Libraries] Akonadi	Reporter:	Ariadne Conill <ariadne>
Component:	server	Assignee:	kdepim bugs <kdepim-bugs>
Status:	REPORTED ---
Severity:	normal	CC:	bugs
Priority:	NOR
Version:	unspecified
Target Milestone:	---
Platform:	Other
OS:	Linux
Latest Commit:		Version Fixed In:

Description Ariadne Conill 2020-06-01 03:13:21 UTC

After suspending to RAM, akonadi-server 20.04 falls over with MySQL errors and crashes on Alpine Linux edge.

Monitoring the debug log yields:

org.kde.pim.akonadiserver: Database "akonadi" opened using driver "QMYSQL"
org.kde.pim.akonadicore: "QLocalSocket: Remote closed" "/run/user/1000/akonadi/akonadiserver-cmd.socket"org.kde.pim.akonadiserver: Database error: Cannot open database.

org.kde.pim.akonadiserver:   Last driver error: "QMYSQL: Unable to connect"
org.kde.pim.akonadiserver:   Last database error: "Lost connection to MySQL server at 'reading authorization packet', system error: 9"
org.kde.pim.akonadicore: "QLocalSocket: Remote closed" "/run/user/1000/akonadi/akonadiserver-cmd.socket"org.kde.pim.akonadicore: Socket error occurred: "QLocalSocket: Remote closed"

QSocketNotifier: Invalid socket 17 and type 'Read', disabling...
org.kde.pim.akonadicore: Socket error occurred: "QLocalSocket: Remote closed"
QSocketNotifier: Invalid socket 13 and type 'Read', disabling...
QSocketNotifier: Invalid socket 15 and type 'Read', disabling...
org.kde.pim.akonadicore: "QLocalSocket: Remote closed" "/run/user/1000/akonadi/akonadiserver-cmd.socket"
org.kde.pim.akonadicore: "QLocalSocket: Remote closed" "/run/user/1000/akonadi/akonadiserver-cmd.socket"
org.kde.pim.akonadicore: Socket error occurred: "QLocalSocket: Remote closed"
org.kde.pim.akonadiserver: DATABASE ERROR while PREPARING QUERY:
org.kde.pim.akonadicore: Socket error occurred: "QLocalSocket: Remote closed"
KCrash: crashing... crashRecursionCounter = 2
KCrash: Application Name = akonadiserver path = /usr/bin pid = 7984
KCrash: Arguments: /usr/bin/akonadiserver 
KCrash: Attempting to start /usr/lib/libexec/drkonqi
org.kde.pim.akonadiserver: Database error: Cannot open database.
QSqlQuery::exec: database not open
org.kde.pim.akonadiserver: Database "akonadi" opened using driver "QMYSQL"
org.kde.pim.akonadiserver: Database error: Cannot open database.
org.kde.pim.akonadiserver:   Last driver error: "QMYSQL: Unable to connect"
org.kde.pim.akonadiserver:   Last database error: "Got packets out of order"
QSqlQuery::exec: database not open
org.kde.pim.akonadicore: "QLocalSocket: Remote closed" "/run/user/1000/akonadi/akonadiserver-cmd.socket"QSocketNotifier: Invalid socket 35 and type 'Read', disabling...
org.kde.pim.akonadiserver:   Last driver error: "QMYSQL: Unable to open database 'akonadi'"
org.kde.pim.akonadiserver:   Last database error: "Lost connection to MySQL server during query"
QSqlQuery::exec: database not open
org.kde.pim.akonadiserver: Database "akonadi" opened using driver "QMYSQL"
org.kde.pim.akonadiserver: DATABASE ERROR while PREPARING QUERY:
org.kde.pim.akonadiserver:   Error code: "2006"
org.kde.pim.akonadiserver: Database error: Cannot open database.
org.kde.pim.akonadiserver:   DB error:  "MySQL server has gone away"

The MySQL server appears to be alive:

localhost:~$ mysql -S ~/.local/share/akonadi/socket-localhost-default/mysql.socket 
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 257
Server version: 10.4.13-MariaDB MariaDB Server

Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

MariaDB [(none)]> show databases;
+--------------------+
| Database           |
+--------------------+
| akonadi            |
| information_schema |
| mysql              |
| performance_schema |
| test               |
+--------------------+
5 rows in set (0.000 sec)

Restarting the service fails...

petrie:~$ akonadictl restart
org.kde.pim.akonadicontrol: Service ":1.146" owner changed from "" to ":1.146"
org.kde.pim.akonadicontrol: Application '/usr/bin/akonadi_migration_agent' exited normally...
org.kde.pim.kimap: Received BYE:  "Logging out "
org.kde.pim.kimap: close
org.kde.pim.kimap: close
org.kde.pim.akonadicontrol: ProcessControl: Application "/usr/bin/akonadi_indexing_agent" stopped unexpectedly ( "Process crashed" )
org.kde.pim.akonadicontrol: Application '/usr/bin/akonadi_indexing_agent' crashed. No restart!
org.kde.pim.akonadicontrol: ProcessControl: Application "/usr/bin/akonadi_archivemail_agent" stopped unexpectedly ( "Process crashed" )
org.kde.pim.akonadicontrol: Application '/usr/bin/akonadi_archivemail_agent' crashed. No restart!
org.kde.pim.akonadicontrol: ProcessControl: Application "/usr/bin/akonadi_newmailnotifier_agent" stopped unexpectedly ( "Process crashed" )
org.kde.pim.akonadicontrol: Application '/usr/bin/akonadi_newmailnotifier_agent' crashed. No restart!
org.kde.pim.akonadicontrol: ProcessControl: Application "/usr/bin/akonadi_followupreminder_agent" stopped unexpectedly ( "Process crashed" )
org.kde.pim.akonadicontrol: Application '/usr/bin/akonadi_followupreminder_agent' crashed. No restart!
org.kde.pim.akonadicontrol: Application '/usr/bin/akonadi_maildispatcher_agent' exited normally...
org.kde.pim.akonadicontrol: ProcessControl: Application "/usr/bin/akonadi_imap_resource" stopped unexpectedly ( "Process crashed" )
org.kde.pim.akonadicontrol: Application '/usr/bin/akonadi_imap_resource' crashed. No restart!
org.kde.pim.akonadicontrol: Application '/usr/bin/akonadi_unifiedmailbox_agent' exited normally...
org.kde.pim.akonadicontrol: Application '/usr/bin/akonadi_notes_agent' exited normally...
org.kde.pim.akonadicontrol: Application '/usr/bin/akonadi_sendlater_agent' exited normally...
org.kde.pim.akonadicontrol: Application '/usr/bin/akonadi_maildir_resource' exited normally...
org.kde.pim.akonadicontrol: ProcessControl: Application "/usr/bin/akonadi_mailfilter_agent" stopped unexpectedly ( "Process crashed" )
org.kde.pim.akonadicontrol: Application '/usr/bin/akonadi_mailfilter_agent' crashed. No restart!

It remains dead after restarting.  If I kill all Akonadi processes manually (but not mysqld) and run "akonadictl start", it recovers and behaves as normal.

I'm not sure what further information I can provide.  Unfortunately I don't have any logs for the crashed processes that I am aware of.

Comment 1 Martin van Es 2020-06-07 08:12:13 UTC

I, too am seeing Akonadi crashes that seem to be related to suspend/resume cycles. It is impossible to restart the akonadi process unless I kill the mysqld-akonadi process and then see no crashes untill at least the next day (which involves a suspend/resume cycle).

Operating System: Kubuntu 20.04
KDE Plasma Version: 5.18.5
KDE Frameworks Version: 5.68.0
Qt Version: 5.12.8
Kernel Version: 5.7.0
OS Type: 64-bit
Processors: 4 × Intel® Core™ i7-7500U CPU @ 2.70GHz
Memory: 15.5 GiB of RAM

$ dpkg -l | grep akonadi
ii  akonadi-backend-mysql                           4:19.12.3-0ubuntu2
ii  akonadi-server                                  4:19.12.3-0ubuntu2
ii  akonadiconsole                                  4:19.12.3-0ubuntu1
ii  kmailtransport-akonadi:amd64                    19.12.3-0ubuntu1  
ii  libkf5akonadi-data                              4:19.12.3-0ubuntu2
ii  libkf5akonadiagentbase5:amd64                   4:19.12.3-0ubuntu2
ii  libkf5akonadicalendar-data                      4:19.12.3-0ubuntu1
ii  libkf5akonadicalendar5abi2:amd64                4:19.12.3-0ubuntu1
ii  libkf5akonadicontact-data                       4:19.12.3-0ubuntu1
ii  libkf5akonadicontact5abi1:amd64                 4:19.12.3-0ubuntu1
ii  libkf5akonadicore-bin                           4:19.12.3-0ubuntu2
ii  libkf5akonadicore5abi2:amd64                    4:19.12.3-0ubuntu2
ii  libkf5akonadimime-data                          4:19.12.3-0ubuntu1
ii  libkf5akonadimime5:amd64                        4:19.12.3-0ubuntu1
ii  libkf5akonadinotes-data                         4:19.12.3-0ubuntu1
ii  libkf5akonadinotes5:amd64                       4:19.12.3-0ubuntu1
ii  libkf5akonadiprivate5abi2:amd64                 4:19.12.3-0ubuntu2
ii  libkf5akonadisearch-bin                         4:19.12.3-0ubuntu1
ii  libkf5akonadisearch-data                        4:19.12.3-0ubuntu1
ii  libkf5akonadisearch-plugins:amd64               4:19.12.3-0ubuntu1
ii  libkf5akonadisearchcore5:amd64                  4:19.12.3-0ubuntu1
ii  libkf5akonadisearchdebug5:amd64                 4:19.12.3-0ubuntu1
ii  libkf5akonadisearchpim5:amd64                   4:19.12.3-0ubuntu1
ii  libkf5akonadisearchxapian5:amd64                4:19.12.3-0ubuntu1
ii  libkf5akonadiwidgets5abi1:amd64                 4:19.12.3-0ubuntu2
ii  libkf5akonadixml5:amd64                         4:19.12.3-0ubuntu2
ii  libkf5libkdepimakonadi5:amd64                   4:19.12.3-0ubuntu1
ii  libkf5mailimporterakonadi5:amd64                4:19.12.3-0ubuntu1
ii  libkf5mailtransportakonadi5:amd64               19.12.3-0ubuntu1  
ii  libkf5pimcommonakonadi5:amd64                   4:19.12.3-0ubuntu1

Comment 2 Martin van Es 2020-06-17 08:40:22 UTC

This is what the mysql.err.old and mysql.err look like after a crash

- mysql.err.old

2020-06-15 22:18:22 0 [Note] /usr/sbin/mysqld-akonadi: ready for connections.
Version: '10.3.22-MariaDB-1ubuntu1'  socket: '/run/user/1000/akonadi/mysql.socket'  port: 0  Ubuntu 20.04
2020-06-15 22:18:22 0 [Note] InnoDB: Buffer pool(s) load completed at 200615 22:18:22
2020-06-17  8:24:58 10 [Warning] Aborted connection 10 to db: 'akonadi' user: 'martin' host: '' (Got an error reading communication packets)
2020-06-17  8:24:58 11 [Warning] Aborted connection 11 to db: 'akonadi' user: 'martin' host: '' (Got an error reading communication packets)
2020-06-17  8:24:58 13 [Warning] Aborted connection 13 to db: 'akonadi' user: 'martin' host: '' (Got an error reading communication packets)
2020-06-17  8:24:58 12 [Warning] Aborted connection 12 to db: 'akonadi' user: 'martin' host: '' (Got an error reading communication packets)
2020-06-17  8:24:58 38 [Warning] Aborted connection 38 to db: 'akonadi' user: 'martin' host: '' (Got an error reading communication packets)

- mesql.err

2020-06-17  8:26:04 0 [ERROR] mysqld-akonadi: Can't lock aria control file '/home/martin/.local/share/akonadi/db_data/aria_log_control' for exclusive use, error: 11. Will retry for 30 seconds
2020-06-17  8:26:35 0 [ERROR] mysqld-akonadi: Got error 'Could not get an exclusive lock; file is probably in use by another process' when trying to use aria control file '/home/martin/.local/share/akonadi/db_data/aria_log_control'
2020-06-17  8:26:35 0 [ERROR] Plugin 'Aria' init function returned error.
2020-06-17  8:26:35 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
2020-06-17  8:26:35 0 [Note] InnoDB: Using Linux native AIO
2020-06-17  8:26:35 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-06-17  8:26:35 0 [Note] InnoDB: Uses event mutexes
2020-06-17  8:26:35 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-06-17  8:26:35 0 [Note] InnoDB: Number of pools: 1
2020-06-17  8:26:35 0 [Note] InnoDB: Using SSE2 crc32 instructions
2020-06-17  8:26:35 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2020-06-17  8:26:35 0 [Note] InnoDB: Completed initialization of buffer pool
2020-06-17  8:26:35 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-06-17  8:26:35 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
2020-06-17  8:26:35 0 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
2020-06-17  8:26:35 0 [Note] InnoDB: Retrying to lock the first data file
2020-06-17  8:26:36 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
2020-06-17  8:26:36 0 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
...

Comment 3 Martin van Es 2020-08-03 07:32:47 UTC

I switched Akonadi backend to postgresql a couple of weeks ago and have not encountered another crash ever since. So far, so good.