Sorry for not being anymore specific, but I have it that sometimes I have two copies of mysqld running. Reproducible: Sometimes Steps to Reproduce: I am not sure. I seem to have this when I do akonadictl stop and then start it again. Often I check whether it really quits old mysqld process. But sometimes I forget this step. Maybe it did not shutdown yet. It seems to happen more easily when there is a lot of load on the MySQL server, for example when some search folders are updated. Actual Results: ms@mango:~> ps aux | grep mysql ms 2391 97.2 5.2 3640268 638488 ? Sl 09:50 15:05 /usr/sbin/mysqld --defaults-file=/home/ms/.local/share/akonadi/mysql.conf --datadir=/home/ms/.local/share/akonadi/db_data/ --socket=/tmp/akonadi-ms.1pzYYX/mysql.socket ms 4435 0.2 3.0 1598552 372952 ? Sl 10:04 0:00 /usr/sbin/mysqld --defaults-file=/home/ms/.local/share/akonadi/mysql.conf --datadir=/home/ms/.local/share/akonadi/db_data/ --socket=/tmp/akonadi-ms.1pzYYX/mysql.socket ms 4678 0.0 0.0 12676 1708 pts/11 S+ 10:05 0:00 grep mysql Expected Results: Never ever there will be two mysqld processes with Akonadi. Actually I wonder why I didn't see any visible database corruption yet. In akonadiserver.error.old log I got: DATABASE ERROR: Error code: 1452 DB error: "Cannot add or update a child row: a foreign key constraint fails (`akonadi`.`collectionpimitemrelation`, CONSTRAINT `collectionpimitemrelation_ibfk_2` FOREIGN KEY (`PimItem_id`) REFERENCES `pimitemtable` (`id`) ON DELETE CASCADE ON UPDATE CASCADE)" Error text: "Cannot add or update a child row: a foreign key constraint fails (`akonadi`.`collectionpimitemrelation`, CONSTRAINT `collectionpimitemrelation_ibfk_2` FOREIGN KEY (`PimItem_id`) REFERENCES `pimitemtable` (`id`) ON DELETE CASCADE ON UPDATE CASCADE) QMYSQL3: Unable to execute statement" Query: "INSERT INTO CollectionPimItemRelation (Collection_id, PimItem_id) VALUES (:0, :1)" In old mysql.err log I have: InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 I will attach the complete logs. I am tempted to raise this to critical due to the potential of having data loss, but seems mysqld locks the files just fine. So far I didn't see any inconsistencies which doesn't mean that there are none.
Created attachment 89518 [details] Old MySQL error log This seems to be of the old mysqld process which actually got some shutdown requests it seems to me.
Created attachment 89519 [details] Old akonadiserver log
This does still happen (this is with Akonadi 1.13 master git branch with database optimizations and KDEPIM + Runtime 4.14.2 as packages in Debian unstable): ms@merkaba:~> akonadictl stop Akonadi is not running. ms@merkaba:~#4> akonadictl status Akonadi Control: stopped Akonadi Server: stopped search paths: ("/usr/local/lib/kde4", "/home/ms/.kde/lib/kde4/plugins/", "/usr/lib/kde4/plugins/", "/usr/local/lib/plugins/", "/usr/lib/x86_64-linux-gnu/qt4/plugins", "/usr/local/bin", "/usr/lib/kde4/plugins", "/usr/local/lib/plugins", "/home/ms/.kde/lib/kde4/", "/usr/lib/kde4/") Akonadi Server Search Support: available (Remote Search, Akonadi Baloo Search Plugin) Available Agent Types: akonadi_akonotes_resource, akonadi_archivemail_agent, akonadi_baloo_indexer, akonadi_birthdays_resource, akonadi_contacts_resource, akonadi_davgroupware_resource, akonadi_folderarchive_agent, akonadi_followupreminder_agent, akonadi_googlecalendar_resource, akonadi_googlecontacts_resource, akonadi_ical_resource, akonadi_icaldir_resource, akonadi_imap_resource, akonadi_invitations_agent, akonadi_kabc_resource, akonadi_kalarm_dir_resource, akonadi_kalarm_resource, akonadi_kcal_resource, akonadi_kdeaccounts_resource, akonadi_knut_resource, akonadi_kolab_resource, akonadi_kolabproxy_resource, akonadi_localbookmarks_resource, akonadi_maildir_resource, akonadi_maildispatcher_agent, akonadi_mailfilter_agent, akonadi_mailtransport_dummy_resource, akonadi_mbox_resource, akonadi_migration_agent, akonadi_mixedmaildir_resource, akonadi_nepomuk_feeder, akonadi_newmailnotifier_agent, akonadi_nntp_resource, akonadi_notes_agent, akonadi_notes_resource, akonadi_openxchange_resource, akonadi_pop3_resource, akonadi_sendlater_agent, akonadi_vcard_resource, akonadi_vcarddir_resource ms@merkaba:~> ps aux | grep "[m]ysql" | grep ms ms 4006 0.4 3.8 2809592 631456 ? Sl Jan27 6:26 /usr/sbin/mysqld --defaults-file=/home/ms/.local/share/akonadi/mysql.conf --datadir=/home/ms/.local/share/akonadi/db_data/ --socket=/tmp/akonadi-ms.QEKpW0/mysql.socket After minutes after issuing akonadictl stop: ms@merkaba:~> ps aux | grep "[m]ysql" | grep ms ms 4006 0.4 3.8 2809592 631456 ? Sl Jan27 6:27 /usr/sbin/mysqld --defaults-file=/home/ms/.local/share/akonadi/mysql.conf --datadir=/home/ms/.local/share/akonadi/db_data/ --socket=/tmp/akonadi-ms.QEKpW0/mysql.socket And look when I start it again: ms@merkaba:~> ps aux | grep "[m]ysql" | grep ms ms 4006 0.4 3.8 2809592 632112 ? Sl Jan27 6:40 /usr/sbin/mysqld --defaults-file=/home/ms/.local/share/akonadi/mysql.conf --datadir=/home/ms/.local/share/akonadi/db_data/ --socket=/tmp/akonadi-ms.QEKpW0/mysql.socket ms 29368 1.0 0.5 787196 85964 ? Sl 09:54 0:00 /usr/sbin/mysqld --defaults-file=/home/ms/.local/share/akonadi/mysql.conf --datadir=/home/ms/.local/share/akonadi/db_data/ --socket=/tmp/akonadi-ms.QEKpW0/mysql.socket This is a *huge*, *big* *no-go*. At no point of time Akonadi should there *ever* be *two* instances of MySQL running for the same user and the *same* database. As this bug is about the stopping of Akonadi I will file a new bug about having two instances of MySQL running. From all I know this just is a very, very bad idea. And I think I lost my private Akonadi MySQL database due to this in combination with some impatience of mine as I saw mysqld replaying from log file and bursting writes of about 150-300 MiB/s sustained for *minutes*, totalling to several times the size of the complete MySQL database. I stopped it with SIGKILL to end the excessive writing. As I think that this causes *real* data loss, loss of the complete Akonadi MySQL database I am raising bug severity. I think I still have the MySQL error log available. Now even after writing all of this, the initial left over mysqld still did not end: ms@merkaba:~> ps aux | grep "[m]ysql" | grep ms ms 4006 0.4 3.9 2809592 632260 ? Sl Jan27 6:45 /usr/sbin/mysqld --defaults-file=/home/ms/.local/share/akonadi/mysql.conf --datadir=/home/ms/.local/share/akonadi/db_data/ --socket=/tmp/akonadi-ms.QEKpW0/mysql.socket Yet a friendly SIGTERM finishes it: ms@merkaba:~> kill 4006 ms@merkaba:~> ps aux | grep "[m]ysql" | grep ms ms@merkaba:~#1> And I have this: ms@merkaba:~/.local/share/akonadi/db_data> cat mysql.err 150128 9:54:11 [Note] Plugin 'FEDERATED' is disabled. 150128 9:54:11 InnoDB: The InnoDB memory heap is disabled 150128 9:54:11 InnoDB: Mutexes and rw_locks use GCC atomic builtins 150128 9:54:11 InnoDB: Compressed tables use zlib 1.2.8 150128 9:54:11 InnoDB: Using Linux native AIO 150128 9:54:11 InnoDB: Initializing buffer pool, size = 512.0M 150128 9:54:11 InnoDB: Completed initialization of buffer pool InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. 150128 9:54:11 InnoDB: Retrying to lock the first data file InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. InnoDB: Unable to lock ./ibdata1, error: 11 InnoDB: Check that you do not already have another mysqld process InnoDB: using the same InnoDB data or log files. And a mysql.err.old that is 875 KiB. I will attach it in a moment.
Created attachment 90734 [details] mysql.err.old with corruption that I think may have happened due to this bug This is related to my last comment and it clearly shows that MySQL wasn´t too happy about running twice on the same database. I did not shutdown any mysqld process uncleanly, so that message may just be related to that another mysqld process was still running at the time of the message in the log. I will now start akonadi again and watch the error log. I didn´t kill the old instance of mysqld here on purpose to show this bug again, I hope the database is still sound and mysql is able to recover. 141029 13:49:02 [Note] Plugin 'FEDERATED' is disabled. 141029 13:49:02 InnoDB: The InnoDB memory heap is disabled 141029 13:49:02 InnoDB: Mutexes and rw_locks use GCC atomic builtins 141029 13:49:02 InnoDB: Compressed tables use zlib 1.2.8 141029 13:49:02 InnoDB: Using Linux native AIO 141029 13:49:02 InnoDB: Initializing buffer pool, size = 512.0M 141029 13:49:02 InnoDB: Completed initialization of buffer pool 141029 13:49:02 InnoDB: highest supported file format is Barracuda. InnoDB: The log sequence number in ibdata files does not match InnoDB: the log sequence number in the ib_logfiles! 141029 13:49:02 InnoDB: Database was not shut down normally! InnoDB: Starting crash recovery. InnoDB: Reading tablespace information from the .ibd files... InnoDB: Restoring possible half-written data pages from the doublewrite InnoDB: buffer... 141029 13:49:03 InnoDB: Waiting for the background threads to start 141029 13:49:04 InnoDB: 5.5.39 started; log sequence number 30133605273 141029 13:49:04 [Note] /usr/sbin/mysqld: ready for connections. Version: '5.5.39-1' socket: '/tmp/akonadi-ms.L69DqH/mysql.socket' port: 0 (Debian) Status information: Current dir: /home/ms/.local/share/akonadi/db_data/ Running threads: 34 Stack size: 262144 Current locks: lock: 0x7f9bec1c9db0: lock: 0x7f9bec1c2bd0: lock: 0x7f9bec1c0630: lock: 0x7f9bec1bde60: […] 141029 14:38:11 [Note] Plugin 'FEDERATED' is disabled. 141029 14:38:11 InnoDB: The InnoDB memory heap is disabled 141029 14:38:11 InnoDB: Mutexes and rw_locks use GCC atomic builtins 141029 14:38:11 InnoDB: Compressed tables use zlib 1.2.8 141029 14:38:11 InnoDB: Using Linux native AIO 141029 14:38:11 InnoDB: Initializing buffer pool, size = 512.0M 141029 14:38:11 InnoDB: Completed initialization of buffer pool 141029 14:38:11 InnoDB: highest supported file format is Barracuda. InnoDB: The log sequence number in ibdata files does not match InnoDB: the log sequence number in the ib_logfiles! 141029 14:38:11 InnoDB: Database was not shut down normally! InnoDB: Starting crash recovery. InnoDB: Reading tablespace information from the .ibd files... InnoDB: Restoring possible half-written data pages from the doublewrite InnoDB: buffer... 141029 14:38:12 InnoDB: Waiting for the background threads to start 141029 14:38:13 InnoDB: 5.5.39 started; log sequence number 30141310511 141029 14:38:13 [Note] /usr/sbin/mysqld: ready for connections. Version: '5.5.39-1' socket: '/tmp/akonadi-ms.ixkIX5/mysql.socket' port: 0 (Debian) 141029 15:10:51 [Note] /usr/sbin/mysqld: Normal shutdown
I think I had luck: 150128 10:14:24 [Note] Plugin 'FEDERATED' is disabled. 150128 10:14:24 InnoDB: The InnoDB memory heap is disabled 150128 10:14:24 InnoDB: Mutexes and rw_locks use GCC atomic builtins 150128 10:14:24 InnoDB: Compressed tables use zlib 1.2.8 150128 10:14:24 InnoDB: Using Linux native AIO 150128 10:14:24 InnoDB: Initializing buffer pool, size = 512.0M 150128 10:14:24 InnoDB: Completed initialization of buffer pool 150128 10:14:24 InnoDB: highest supported file format is Barracuda. 150128 10:14:24 InnoDB: Waiting for the background threads to start 150128 10:14:25 InnoDB: 5.5.40 started; log sequence number 54593147801 150128 10:14:25 [Note] /usr/sbin/mysqld: ready for connections. Version: '5.5.40-1' socket: '/tmp/akonadi-ms.QEKpW0/mysql.socket' port: 0 (Debian) Seems fine to far, I will now look into the mysql.err copy I made for as I lost the database completely.
Okay, I think I deleted the mysql.err log I had on my private KDEPIM / Akonadi setup after restoring from scratch by letting it build a new database, cause I was just too angry at all of this. What happened there was: I had two instanced for mysqld running after stopping and starting Akonadi after I put SizeTreshold=32768 running and I didn´t notice that. Due to this bug I usually check whether a MySQL daemon is still around and kill it manually with SIGTERM friendly if it still is around after some time. At this time I forgot about this. What happened on one of the next restarts was that mysqld was trying to recover from log file and it wrote in bursts of 150 to 300 MiB per seconds onto the Dual SSD BTRFS RAID 1 for minutes. Akonadi was almost totally blocked. The MySQL easily wrote more than ten times or even more data than the whole size the database had as this time (around 2 GiB). At one time I lost my patience and also wanted to avoid needless excessive writes to the SSD. So I went on to kill mysqld with SIGTERM. It didn´t respond. I then after some time did SIGKILL. On the next restart of Akonadi it started to write excessively again, while it may be that the mysqld at some point would have been able to repair itself from logfile, I cannot tell, as I lost my patience after a while and well, I even tough SSD can take lots, I didn´t want to have mysqld to write onto it like this for hours. Thus I send redid my Akonadi setup from scratch. Okay, since I cannot prove the data loss as it may have completed I am downgrading the bug again a bit, but still I think its a grave issue that Akonadi tolerates two mysqld processing running on the same database. At least on akonadictl start if it finds an old MySQL process for the database still around I think it is good if it prints a BIG FAT WARNING, and does not continue with starting up Akonadi. But I think for usability it may be good if after some timeout Akonadi also sends the mysqld process a SIGTERM and also complains if it doesn´t respond to it without some time. For robustness sake, I think thats very important. I am pondering to use a central MySQL or PostgreSQL server again for this reason. On any account two mysqld process on the same database is a pretty bad idea.
Okay, I think I got a hint today on why it might not finished MySQL properly. Today I got connection losses with Exchange again (its seems quite easy to trigger these, I am at the moment using archivemail to reduce amount of mails on the server to see whether it may help). And to bring things back up I stopped Akonadi with the intention to start it again. Yet on stopping I got: ms@merkaba:~> tail -f ~/.xsession-errors Executing search "kmail2-1312955980-SearchSession" Search done "kmail2-1312955980-SearchSession" (without remote search) Result: 0 matches posting retrieval request for item 1890571 there are 1 queues and 0 items in mine request for item 1890571 still pending - waiting processing retrieval request for item 1890571 parts: ("RFC822") of resource: "akonadi_imap_resource_0" QFileSystemWatcher: failed to add paths: /home/ms/.kde/share/config/activitymanager-pluginsrc konsole(3229) Konsole::Session::run: Attempted to re-run an already running session. konsole(3229) Konsole::Session::run: Attempted to re-run an already running session. akonadi_imap_resource_0(3221) ChangeItemsFlagsTask::onSelectDone: Select failed: "Die Verbindung zum Server ist abgebrochen." This is up to the connection loss I think. "Die Verbindung zum Server ist abgebrochen" means "the connection to the server aborted" Then I stop akonadi with akonadictl stop and get: X Error: BadWindow (invalid Window parameter) 3 Major opcode: 2 (X_ChangeWindowAttributes) Resource id: 0x221afce QFileSystemWatcher: failed to add paths: /home/ms/.kde/share/config/activitymanager-pluginsrc QFileSystemWatcher: failed to add paths: /home/ms/.kde/share/config/activitymanager-pluginsrc QFileSystemWatcher: failed to add paths: /home/ms/.kde/share/config/activitymanager-pluginsrc Lost connection to resource "org.freedesktop.Akonadi.Resource.akonadi_contacts_resource_0" , discarding cached interface Lost connection to resource "org.freedesktop.Akonadi.Resource.akonadi_akonotes_resource_0" , discarding cached interface Lost connection to resource "org.freedesktop.Akonadi.Resource.akonadi_akonotes_resource_1" , discarding cached interface void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "AkonadiAgentServer_3218_fhsA1R" now serving: () Lost connection to resource "org.freedesktop.Akonadi.Resource.akonadi_icaldir_resource_0" , discarding cached interface void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "AkonadiAgentServer_3214_GN8Sxx" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_maildispatcher_agent_3225_ScB4Dq" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_maildispatcher_agent_3225_B0L8JT" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_maildispatcher_agent_3225_ietFlF" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_migration_agent_3227_ndcikE" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "AkonadiAgentServer_3215_D1kzHt" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_icaldir_resource_0_3220_eX2EKU" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_followupreminder_agent_3219_2ncps7" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_notes_agent_3230_1JJLlc" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_notes_agent_3230_OLDXpN" now serving: () Application '/usr/bin/akonadi_sendlater_agent' exited normally... Application '/usr/local/bin/akonadi_agent_launcher' exited normally... void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_sendlater_agent_3231_VHVu4n" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "AkonadiAgentServer_3223_mmVsO9" now serving: () Unregistering search instance "akonadi_imap_resource_1" Lost connection to resource "org.freedesktop.Akonadi.Resource.akonadi_maildir_resource_0" , discarding cached interface Lost connection to resource "org.freedesktop.Akonadi.Resource.akonadi_imap_resource_1" , discarding cached interface void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_imap_resource_1_3222_X2bKII" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_mailfilter_agent_3226_Wh4lFI" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_mailfilter_agent_3226_bbfMOe" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_mailfilter_agent_3226_wkptgo" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_mailfilter_agent_3226_ukXz5K" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_newmailnotifier_agent_3228_6sBmRQ" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_newmailnotifier_agent_3228_0WUgjM" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_archivemail_agent_3216_SLxcKa" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_archivemail_agent_3216_3uG0RH" now serving: () void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_archivemail_agent_3216_bbIJIP" now serving: () Application '/usr/bin/akonadi_baloo_indexer' exited normally... Application '/usr/bin/akonadi_followupreminder_agent' exited normally... Application '/usr/local/bin/akonadi_agent_launcher' exited normally... Application '/usr/local/bin/akonadi_maildispatcher_agent' exited normally... void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_baloo_indexer_3217_8C5pnp" now serving: () ProcessControl: Application /usr/local/bin/akonadi_imap_resource stopped unexpectedly ( "Process crashed" ) Application '/usr/local/bin/akonadi_imap_resource' crashed. No restart! Application '/usr/local/bin/akonadi_agent_launcher' exited normally... Lost connection to resource "org.freedesktop.Akonadi.Resource.akonadi_imap_resource_0" , discarding cached interface Unregistering search instance "akonadi_imap_resource_0" Application '/usr/local/bin/akonadi_imap_resource' exited normally... continuing request for item 1890571 "59316" failed: "Unable to retrieve item from resource: Message did not receive a reply (timeout by message bus)" Application '/usr/bin/akonadi_mailfilter_agent' exited normally... Application '/usr/bin/akonadi_archivemail_agent' exited normally... void Akonadi::Server::NotificationSource::serviceUnregistered(const QString&) Notification source "akonadi_imap_resource_0_3221_Q97d5S" now serving: () Application '/usr/local/bin/akonadi_icaldir_resource' exited normally... Application '/usr/local/bin/akonadi_migration_agent' exited normally... Application '/usr/local/bin/akonadi_newmailnotifier_agent' exited normally... Application '/usr/local/bin/akonadi_agent_launcher' exited normally... Application '/usr/bin/akonadi_notes_agent' exited normally... terminating service threads ItemRetrieverException : Unable to retrieve item from resource: Message did not receive a reply (timeout by message bus) terminating connection threads plasma-desktop(3121)/libakonadi Akonadi::SessionPrivate::socketError: Socket error occurred: "QLocalSocket: Remote closed" ktp-contactlist(3330)/libakonadi Akonadi::SessionPrivate::socketError: Socket error occurred: "QLocalSocket: Remote closed" plasma-desktop(3121)/libakonadi Akonadi::SessionPrivate::socketError: Socket error occurred: "QLocalSocket: Remote closed" kontact(3474)/libakonadi Akonadi::SessionPrivate::socketError: Socket error occurred: "QLocalSocket: Remote closed" krunner(3212)/libakonadi Akonadi::SessionPrivate::socketError: Socket error occurred: "QLocalSocket: Remote closed" kontact(3474)/libakonadi Akonadi::SessionPrivate::socketError: Socket error occurred: "QLocalSocket: Remote closed" korgac(3514)/libakonadi Akonadi::SessionPrivate::socketError: Socket error occurred: "QLocalSocket: Remote closed" korgac(3514)/libakonadi Akonadi::SessionPrivate::socketError: Socket error occurred: "QLocalSocket: Remote closed" kmail2(3544)/libakonadi Akonadi::SessionPrivate::socketError: Socket error occurred: "QLocalSocket: Remote closed" "[ 0: akonadiserver(_Z11akBacktracev+0x36) [0x4d677c] 1: akonadiserver() [0x4d69c8] 2: /lib/x86_64-linux-gnu/libc.so.6(+0x35180) [0x7f7494d98180] 3: /usr/lib/x86_64-linux-gnu/libQtCore.so.4(_ZN14QReadWriteLock12lockForWriteEv+0x1d) [0x7f74968cc3cd] 4: akonadiserver(_ZN7Akonadi6Server20ItemRetrievalManager19requestItemDeliveryEPNS0_20ItemRetrievalRequestE+0x31) [0x5680cd] 5: akonadiserver(_ZN7Akonadi6Server13ItemRetriever4execEv+0x664) [0x5f2342] 6: akonadiserver(_ZN7Akonadi6Server11FetchHelper10fetchItemsERK10QByteArray+0x176) [0x5bd68a] 7: akonadiserver(_ZN7Akonadi6Server5Fetch11parseStreamEv+0x192) [0x5bab74] 8: akonadiserver(_ZN7Akonadi6Server10Connection11slotNewDataEv+0x3a3) [0x5aa075] 9: akonadiserver() [0x5a2d4a] 10: /usr/lib/x86_64-linux-gnu/libQtCore.so.4(_ZN11QMetaObject8activateEP7QObjectPKS_iPPv+0x32c) [0x7f74969eff4c] 11: /usr/lib/x86_64-linux-gnu/libQtCore.so.4(_ZN11QMetaObject8activateEP7QObjectPKS_iPPv+0x32c) [0x7f74969eff4c] 12: /usr/lib/x86_64-linux-gnu/libQtNetwork.so.4(+0xc836e) [0x7f74965cc36e] 13: /usr/lib/x86_64-linux-gnu/libQtNetwork.so.4(+0xd2f6d) [0x7f74965d6f6d] 14: /usr/lib/x86_64-linux-gnu/libQtCore.so.4(_ZN16QCoreApplication14notifyInternalEP7QObjectP6QEvent+0x8d) [0x7f74969daf8d] 15: /usr/lib/x86_64-linux-gnu/libQtCore.so.4(+0x1b5b50) [0x7f7496a0ab50] 16: /lib/x86_64-linux-gnu/libglib-2.0.so.0(g_main_context_dispatch+0x24d) [0x7f7494461c5d] 17: /lib/x86_64-linux-gnu/libglib-2.0.so.0(+0x49f48) [0x7f7494461f48] 18: /lib/x86_64-linux-gnu/libglib-2.0.so.0(g_main_context_iteration+0x2c) [0x7f7494461ffc] 19: /usr/lib/x86_64-linux-gnu/libQtCore.so.4(_ZN20QEventDispatcherGlib13processEventsE6QFlagsIN10QEventLoop17ProcessEventsFlagEE+0x77) [0x7f7496a0a507] 20: /usr/lib/x86_64-linux-gnu/libQtCore.so.4(_ZN10QEventLoop13processEventsE6QFlagsINS_17ProcessEventsFlagEE+0x41) [0x7f74969d9ae1] 21: /usr/lib/x86_64-linux-gnu/libQtCore.so.4(_ZN10QEventLoop4execE6QFlagsINS_17ProcessEventsFlagEE+0x1a5) [0x7f74969d9e45] 22: /usr/lib/x86_64-linux-gnu/libQtCore.so.4(_ZN7QThread4execEv+0x109) [0x7f74968ceb89] 23: akonadiserver(_ZN7Akonadi6Server16ConnectionThread3runEv+0x69) [0x4ddfd9] 24: /usr/lib/x86_64-linux-gnu/libQtCore.so.4(+0x7c3ef) [0x7f74968d13ef] 25: /lib/x86_64-linux-gnu/libpthread.so.0(+0x80a4) [0x7f7494b4e0a4] 26: /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f7494e4904d] ] " ProcessControl: Application 'akonadiserver' returned with exit code 255 (Unknown error) kmail2(3544)/libakonadi Akonadi::SessionPrivate::socketError: Socket error occurred: "QLocalSocket: Remote closed" kmail2(3544)/libakonadi Akonadi::SessionPrivate::socketError: Socket error occurred: "QLocalSocket: Remote closed" kmail2(3544)/libakonadi Akonadi::SessionPrivate::socketError: Socket error occurred: "QLocalSocket: Remote closed" May it be that akonadiserver crashed here before triggering a MySQL shutdown? The MySQL server is still happily running: ms@merkaba:~/Backup#2> ps aux |grep "[m]ysql" | grep "^ms" ms 3162 2.9 3.9 2817028 643416 ? Sl 09:06 1:47 /usr/sbin/mysqld --defaults-file=/home/ms/.local/share/akonadi/mysql.conf --datadir=/home/ms/.local/share/akonadi/db_data/ --socket=/tmp/akonadi-ms.eMC6wS/mysql.socket while akonadictl stop tells: ms@merkaba:~#130> akonadictl stop Akonadi is not running. ms@merkaba:~#4> akonadictl status Akonadi Control: stopped Akonadi Server: stopped search paths: ("/usr/local/lib/kde4", "/home/ms/.kde/lib/kde4/plugins/", "/usr/local/lib/kde4/plugins/", "/usr/lib/kde4/plugins/", "/usr/local/lib/plugins/", "/usr/lib/x86_64-linux-gnu/qt4/plugins", "/usr/local/bin", "/usr/local/lib/kde4/plugins", "/usr/lib/kde4/plugins", "/usr/local/lib/plugins", "/home/ms/.kde/lib/kde4/", "/usr/local/lib/kde4/", "/usr/lib/kde4/") Akonadi Server Search Support: available (Remote Search, Akonadi Baloo Search Plugin) Available Agent Types: akonadi_airsyncdownload_resource, akonadi_akonotes_resource, akonadi_archivemail_agent, akonadi_baloo_indexer, akonadi_birthdays_resource, akonadi_contacts_resource, akonadi_davgroupware_resource, akonadi_folderarchive_agent, akonadi_followupreminder_agent, akonadi_googlecalendar_resource, akonadi_googlecontacts_resource, akonadi_ical_resource, akonadi_icaldir_resource, akonadi_imap_resource, akonadi_invitations_agent, akonadi_kabc_resource, akonadi_kalarm_dir_resource, akonadi_kalarm_resource, akonadi_kcal_resource, akonadi_kdeaccounts_resource, akonadi_knut_resource, akonadi_kolab_resource, akonadi_kolabproxy_resource, akonadi_localbookmarks_resource, akonadi_maildir_resource, akonadi_maildispatcher_agent, akonadi_mailfilter_agent, akonadi_mailtransport_dummy_resource, akonadi_mbox_resource, akonadi_migration_agent, akonadi_mixedmaildir_resource, akonadi_nepomuk_feeder, akonadi_newmailnotifier_agent, akonadi_nntp_resource, akonadi_notes_agent, akonadi_notes_resource, akonadi_openxchange_resource, akonadi_pop3_resource, akonadi_sendlater_agent, akonadi_vcard_resource, akonadi_vcarddir_resource I bet Akonadi didn´t even tell the MySQL to quit yet. Can this be logged? "About to quit MySQL process <pid>" maybe? A graceful SIGTERM to the mysqld process just ended it within two seconds, so I bet its not MySQL refusing to exit here, but Akonadi not even trying to stop it due to above crash on exit. Maybe a shell script to stop Akonadi would be more robust than a C++ application that crashes on attempting to shut down Akonadi. And I pretty much bet akonadictl start would start a second copy of mysqld again, which again, in my eyes is a big, huge, no-go. Never *ever* do this.
*** Bug 367638 has been marked as a duplicate of this bug. ***
I'm not sure if this helps, but I also run into situations where Akonadi seems to initiate two mysqld processes. This is with the latest KDE packages (16.08) from openSUSE Tumbleweed. The first one is just after startup, I can often read and browse emails for 10 seconds or so, then kmail says akonadi is not running properly. I then have to killall mysqld and restart akonadi. The second one, and this happens reliably each time, is when I initiate an email search, having deleted all prior search folders. Kmail states that it can't connect to akonadi-service, and stops working properly. After this, I always have two mysqld processes running. akonadiserver.error.old contains just one line: Connecting to deprecated signal QDBusConnectionInterface::serviceOwnerChanged(QString,QString,QString) If there's any additional specific error logs or debug information you'd like to see, just let me know.
Git commit 2ef0fe95bd83643d0a1e69b0b59124fa76be5b2f by Daniel Vrátil. Committed on 14/09/2016 at 13:19. Pushed by dvratil into branch 'master'. If the mysql server is already running, try to connect Instead of starting another mysqld process on top of the same data, try to reconnect to the running server. Generally this situation should not really happen, but there are some cases when the database cannot be properly shut down, like when the server crashes. FIXED-IN: 16.12.0 M +57 -50 src/server/storage/dbconfigmysql.cpp http://commits.kde.org/akonadi/2ef0fe95bd83643d0a1e69b0b59124fa76be5b2f
Yay! Thank you, Dan! Would you backport this to 16.08 as well?
I am not 100% sure that this works flawlessly, so I don't feel like putting it into to stable branch now without enough real-life testing. I don't want to risk breaking starting of database on Akonadi startup.
So here's an additional observation, from 4.13.3/ akonadi 1.13.1 but maybe still useful. As I just reported in a duplicate (https://bugs.kde.org/show_bug.cgi?id=367638) I get the 1452 error even when I don't have 2 mysql daemons running. Not continuously at least. Looking at it today I first thought that they were generated only after a full sync (Ctrl-L) but then I noticed the error messages also appeared while I was browsing an email and no sync activity was occurring. I then made the link with the search folder I created yesterday, which was designed to combine the entries from several folders in a virtual folder. For that, I defined a search working on the folders of interest and returning all items with a total size >= 0kb. I left the 2nd field empty. When I deleted that search folder the error messages disappeared, but the unread email in one of the target folders disappeared too. From kmail; Claws shows they're still there, fortunately.