Bug#1010576: (no subject)

[gis-w]

It seems to me that indeed akonadiserver is the culprit. I kept kontact 
running and only stopped akonadiserver, killed mariadb and resarted 
akonadiserver. Then kontact started to work again.

More info: I suspect that this is due to a deadlock in the db updates, 
akonadiserver even logs this:
org.kde.pim.akonadiserver: "Deadlock found when trying to get lock; try 
restarting transaction QMYSQL3: Der Befehl konnte nicht ausgeführt werden"

So I had a look at mariadb like this:
mysql --socket=/run/user/1000/akonadi/mysql.socket

MariaDB [(none)]> show engine innodb status;
[...]

LATEST DETECTED DEADLOCK

2022-06-13 07:24:55 0x7f8a1c681640
*** (1) TRANSACTION:
TRANSACTION 78342, ACTIVE 0 sec starting index read
mysql tables in use 6, locked 6
LOCK WAIT 6 lock struct(s), heap size 1128, 3 row lock(s), undo log entries 1
MariaDB thread id 41, OS thread handle 140231158797888, query id 165472 
localhost user Updating
UPDATE PimItemTable SET rev = ?, remoteId = ?, remoteRevision = ?, gid = ?, 
collectionId = ?, mimeTypeId = ?, datetime = ?, atime = ?, dirty = ?, size = ? 
WHERE ( id = ? )
*** WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 9 page no 3493 n bits 1080 index 
PimItemTable_idSortIndex of table `akonadi`.`pimitemtable` trx id 78342 
lock_mode X locks rec but not gap waiting
Record lock, heap no 855 PHYSICAL RECORD: n_fields 1; compact format; info 
bits 0
 0: len 8; hex 8004cb8d; asc ;;

*** CONFLICTING WITH:
RECORD LOCKS space id 9 page no 3493 n bits 1080 index 
PimItemTable_idSortIndex of table `akonadi`.`pimitemtable` trx id 78344 
lock_mode X locks rec but not gap
Record lock, heap no 855 PHYSICAL RECORD: n_fields 1; compact format; info 
bits 0
 0: len 8; hex 8004cb8d; asc ;;


*** (2) TRANSACTION:
TRANSACTION 78344, ACTIVE 0 sec starting index read
mysql tables in use 6, locked 6
LOCK WAIT 3 lock struct(s), heap size 1128, 2 row lock(s)
MariaDB thread id 40, OS thread handle 140231159105088, query id 165015 
localhost user Updating
UPDATE PimItemTable SET atime = ? WHERE ( ( PimItemTable.id = ? ) )
*** WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 9 page no 3872 n bits 208 index PRIMARY of table 
`akonadi`.`pimitemtable` trx id 78344 lock_mode X locks rec but not gap 
waiting
Record lock, heap no 169 PHYSICAL RECORD: n_fields 13; compact format; info 
bits 0
 0: len 8; hex 8004cb8d; asc ;;
 1: len 6; hex 00013205; asc 2 ;;
 2: len 7; hex 73080d03f1; asc s  ;;
 3: len 4; hex 8001; asc ;;
 4: len 5; hex 3834383038; asc 84808;;
 5: SQL NULL;
 6: SQL NULL;
 7: len 8; hex 8028; asc(;;
 8: len 8; hex 8005; asc ;;
 9: len 4; hex 62a6ae07; asc b   ;;
 10: len 4; hex 62a6ae07; asc b   ;;
 11: len 1; hex 80; asc  ;;
 12: len 8; hex 80005f14; asc   _ ;;

*** CONFLICTING WITH:
RECORD LOCKS space id 9 page no 3872 n bits 208 index PRIMARY of table 
`akonadi`.`pimitemtable` trx id 78342 lock_mode X locks rec but not gap
Record lock, heap no 169 PHYSICAL RECORD: n_fields 13; compact format; info 
bits 0
 0: len 8; hex 8004cb8d; asc ;;
 1: len 6; hex 00013205; asc 2 ;;
 2: len 7; hex 73080d03f1; asc s  ;;
 3: len 4; hex 8001; asc ;;
 4: len 5; hex 3834383038; asc 84808;;
 5: SQL NULL;
 6: SQL NULL;
 7: len 8; hex 8028; asc(;;
 8: len 8; hex 8005; asc ;;
 9: len 4; hex 62a6ae07; asc b   ;;
 10: len 4; hex 62a6ae07; asc b   ;;
 11: len 1; hex 80; asc  ;;
 12: len 8; hex 80005f14; asc   _ ;;

*** WE ROLL BACK TRANSACTION (0)

TRANSACTIONS

Trx id counter 78442
Purge done for trx's n:o < 78439 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 78441, ACTIVE 2344 sec inserting
mysql tables in use 1, locked 1
8 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 427
MariaDB thread id 47, OS thread handle 140231558207040, query id 233232 
localhost user Update
INSERT INTO PimItemTable (rev, remoteId, remoteRevision, gid, collectionId, 
mimeTypeId, datetime, atime, dirty, size) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, 
?)
---TRANSACTION (0x7f8a422bcd80), not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION (0x7f8a422a4c80), not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION (0x7f8a422a4180), not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION (0x7f8a422a3680), not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION (0x7f8a422a2b80), not started
0 lock struct(s), heap size 1128, 0 row lock(s)




And:
MariaDB [(none)]> show full processlist;
++--+---+-+-+--+--

Bug#1010576: (no subject)

[gis-w]

Note that my previous message on https://bugs.debian.org/cgi-bin/
bugreport.cgi?bug=1010576 is incomplete, please see the referenced Message 
Part 2 (https://bugs.debian.org/cgi-bin/bugreport.cgi?
att=1;bug=1010576;msg=25) for the full contents.

Bug#1010576: (no subject)

[gis-w]

I collected some information that might help with debugging, unfortunately some 
output uses 
German localization, I can translate these if needed:

In the shell where I started akonadi with akonadictl start, I got this output 
(many
lines duplicated and removed for brevity):

"Das Objekt existiert nicht am Pfad 
»/org/freedesktop/NetworkManager/ActiveConnection/2«"
[...]
org.kde.pim.kimap: Connection to server lost  QAbstractSocket::HostNotFoundError
[...]
QIODevice::write (QSslSocket): device not open
org.kde.pim.kimap: Connection to server lost  QAbstractSocket::NetworkError
org.kde.pim.kimap: Connection to server lost  QAbstractSocket::NetworkError
org.kde.pim.kimap: Connection to server lost  QAbstractSocket::HostNotFoundError
org.kde.pim.kimap: Connection to server lost  QAbstractSocket::HostNotFoundError
[...]
"Das Objekt existiert nicht am Pfad 
»/org/freedesktop/NetworkManager/ActiveConnection/2«"
[...]
QIODevice::write (QSslSocket): device not open
org.kde.pim.kimap: Connection to server lost  
QAbstractSocket::RemoteHostClosedError
org.kde.pim.kimap: Connection to server lost  QAbstractSocket::NetworkError
[...]
"Das Objekt existiert nicht am Pfad 
»/org/freedesktop/NetworkManager/ActiveConnection/2«"
[...]
QIODevice::write (QSslSocket): device not open
"Das Objekt existiert nicht am Pfad 
»/org/freedesktop/NetworkManager/ActiveConnection/2«"
[...]
QIODevice::write (QSslSocket): device not open
org.kde.pim.akonadiserver.search: Executing search 
"kontact-2268689595-SearchSession"
org.kde.pim.akonadiserver.search: Search  "kontact-2268689595-SearchSession" 
done 
(without remote search)
org.kde.pim.akonadiserver.search: Executing search 
"kontact-2268689595-SearchSession"
org.kde.pim.akonadiserver.search: Search  "kontact-2268689595-SearchSession" 
done 
(without remote search)
org.kde.pim.akonadiserver.search: Executing search 
"kontact-2268689595-SearchSession"
[...]
org.kde.pim.akonadiserver: QueryBuilder::exec(): database reported transaction 
timeout, 
retrying transaction
org.kde.pim.akonadiserver: "Lock wait timeout exceeded; try restarting 
transaction QMYSQL3: 
Der Befehl konnte nicht ausgeführt werden"
org.kde.pim.akonadiserver: QueryBuilder::exec(): database reported transaction 
timeout, 
retrying transaction
org.kde.pim.akonadiserver: "Lock wait timeout exceeded; try restarting 
transaction QMYSQL3: 
Der Befehl konnte nicht ausgeführt werden"


stracing akonadiserver shows this for example:

[pid 110942] write(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 110942] poll([{fd=10, events=POLLIN}, {fd=26, events=POLLIN}, {fd=28, 
events=POLLIN}, 
{fd=36, events=POLLIN}, {fd=38, events=POLLIN}, {fd=42, events=POLLIN}, {fd=47, 
events=POLLIN}, {fd=52, events=POLLIN}, {fd=61, events=POLLIN}, {fd=69, 
events=POLLIN}, 
{fd=76, events=POLLIN}, {fd=77, events=POLLIN}, {fd=79, events=POLLIN}, {fd=86, 
events=POLLIN}, {fd=89, events=POLLIN}, {fd=90, events=POLLIN}, {fd=95, 
events=POLLIN}, 
{fd=96, events=POLLIN}, {fd=99, events=POLLIN}, {fd=100, events=POLLIN}, 
{fd=110, 
events=POLLIN}, {fd=114, events=POLLIN}, {fd=116, events=POLLIN}, {fd=121, 
events=POLLIN}, {fd=122, events=POLLIN}, {fd=125, events=POLLIN}, {fd=126, 
events=POLLIN}, {fd=129, events=POLLIN}, {fd=132, events=POLLIN}, {fd=136, 
events=POLLIN}, {fd=142, events=POLLIN}, {fd=146, events=POLLIN}, ...], 46, 48) 
= 1 
([{fd=10, revents=POLLIN}])
[pid 110942] read(10, "\2\0\0\0\0\0\0\0", 16) = 8
[pid 110942] poll([{fd=10, events=POLLIN}, {fd=26, events=POLLIN}, {fd=28, 
events=POLLIN}, 
{fd=36, events=POLLIN}, {fd=38, events=POLLIN}, {fd=42, events=POLLIN}, {fd=47, 
events=POLLIN}, {fd=52, events=POLLIN}, {fd=61, events=POLLIN}, {fd=69, 
events=POLLIN}, 
{fd=76, events=POLLIN}, {fd=77, events=POLLIN}, {fd=79, events=POLLIN}, {fd=86, 
events=POLLIN}, {fd=89, events=POLLIN}, {fd=90, events=POLLIN}, {fd=95, 
events=POLLIN}, 
{fd=96, events=POLLIN}, {fd=99, events=POLLIN}, {fd=100, events=POLLIN}, 
{fd=110, 
events=POLLIN}, {fd=114, events=POLLIN}, {fd=116, events=POLLIN}, {fd=121, 
events=POLLIN}, {fd=122, events=POLLIN}, {fd=125, events=POLLIN}, {fd=126, 
events=POLLIN}, {fd=129, events=POLLIN}, {fd=132, events=POLLIN}, {fd=136, 
events=POLLIN}, {fd=142, events=POLLIN}, {fd=146, events=POLLIN}, ...], 46, 47) 
= 0 
(Timeout)

[...]

[pid 110942] read(89, 
"\3\0\0\0\0\0\0\0u\0\20\0\0\377\377\377\377\377\377\377\377\0\0\0\0\1\0\0\0\25\0\0"...,
 70) = 
70
[pid 110942] write(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 110942] ppoll([{fd=89, events=POLLIN|POLLOUT}], 1, {tv_sec=30, tv_nsec=0}, 
NULL, 8) = 
1 ([{fd=89, revents=POLLOUT}], left {tv_sec=29, tv_nsec=96833})
[pid 110942] write(89, "\3\0\0\0\0\0\0\0\365\0\0\0\0\377\377\377\377", 17) = 17
[pid 110942] write(10, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 110942] poll([{fd=10, events=POLLIN}, {fd=26, events=POLLIN}, {fd=28, 
events=POLLIN}, 
{fd=36, events=POLLIN}, {fd=38, events=POLLIN}, {fd=42, events=POLLIN}, {fd=47, 
events=POLLIN}, {fd=52, events=POLLIN}, {fd=61, events=POLLIN}, {fd=69, 
events=POLLIN},