Bug 456983

Summary: mysql.err.old grows too large (over 20 GB)
Product: [Frameworks and Libraries] Akonadi Reporter: ratijas <me>
Component: generalAssignee: kdepim bugs <kdepim-bugs>
Status: RESOLVED FIXED    
Severity: normal CC: carl, dpbasti, luis.davila.pc, me, michele.mazza, post
Priority: NOR    
Version: unspecified   
Target Milestone: ---   
Platform: Other   
OS: Linux   
See Also: https://bugs.kde.org/show_bug.cgi?id=460172
Latest Commit: https://invent.kde.org/pim/akonadi/-/commit/d1738fa348e79bc4abf781f0512ef256460d78b2 Version Fixed In: 23.04.0
Sentry Crash Report:
Attachments: Akonadi appetite
Akonadi - MySQL errors

Description ratijas 2022-07-21 13:49:44 UTC 
Created attachment 150791 [details]
Akonadi appetite

SUMMARY

Akonadi has some unhealthy appetite when it comes to disk storage diet.


STEPS TO REPRODUCE
1. Live your life.
2. Run out of disk space eventually.
3. Check your home folder in Filelight.

OBSERVED RESULT
akonadi/db_data/mysql.err.old contains 23.9 GiB of *something*

EXPECTED RESULT
Limited/controlled log rotation.

SOFTWARE/OS VERSIONS
Operating System: Arch Linux
KDE: git master
Qt Version: 5.15.5
Kernel Version: 5.18.12-arch1-1 (64-bit)
Graphics Platform: X11
Processors: 8 × Intel® Core™ i7-6700HQ CPU @ 2.60GHz
Memory: 15.6 GiB of RAM
Graphics Processor: NVIDIA GeForce GTX 970M/PCIe/SSE2
Manufacturer: ASUSTeK COMPUTER INC.
Product Name: G752VT
System Version: 1.0
Comment 1 ratijas 2022-10-12 08:42:03 UTC 
Created attachment 152729 [details]
Akonadi - MySQL errors

These are the prime suspects in causing my btrfs partition failure recently, so I had to backup-reformat-recover everything. Log files just keep growing, no matter what. I had three accounts on KMail (not anymore, migrated to Thunderbird for now). I've never seen any errors in KMail GUI.

~/.local/share/akonadi/db_data/mysql.err file contains mostly errors from bad DB schema migration. It keeps growing even after removing KMail accounts, so the next thing I tried is running `akonadictl stop`. The file is full of pairs of messages:

> 2022-10-11 23:42:45 181 [ERROR] Incorrect definition of table mysql.column_stats: expected column 'hist_type' at position 9 to have type enum('SINGLE_PREC_HB','DOUBLE_PREC_HB','JSON_HB'), found type enum('SINGLE_PREC_HB','DOUBLE_PREC_HB').
> 2022-10-11 23:42:45 181 [ERROR] Incorrect definition of table mysql.column_stats: expected column 'histogram' at position 10 to have type longblob, found type varbinary(255).
Comment 2 ratijas 2022-10-12 10:53:48 UTC 
I'd like to add that akonadi restarts itself and keeps spamming those logs even after explicitly being stopped with `akonadictl stop`. Maybe this setting is not persistent between reboots?

Also why am I suspecting it was the cause of filesystem breakage? Because while recovering, btrfs had problems with this particular file. Its metadata was broken or something like that. Without the `--ignore-errors` option it wasn't able to get past this huge log. I'd wish I could instruct btrfs-restore to skip this file completely, but there is no such option currently.
Comment 3 Knut Hildebrandt 2022-10-24 18:41:15 UTC 
Same here and that already for an while and long before the right now installed Akonadi version came out.

Akonadi: 22.08.1-2
mariadb: 10.9.3-1
Operating System: Manjaro Linux
KDE Plasma Version: 5.25.5
KDE Frameworks Version: 5.98.0
Qt Version: 5.15.6
Kernel Version: 5.10.148-1-MANJARO (64-bit)
Graphics Platform: X11

BTW, I've got thousands of error messages like the ones I paste here including the messages generated by the shutdown of Akonadi:
...
2022-10-24 20:07:45 67 [ERROR] Incorrect definition of table mysql.column_stats: expected column 'hist_type' at position 9 to have type enum('SINGLE_PREC_HB','DOUBLE_PREC_HB','JSON_HB'), found type enum('SINGLE_PREC_HB','DOUBLE_PREC_HB').
2022-10-24 20:07:45 67 [ERROR] Incorrect definition of table mysql.column_stats: expected column 'histogram' at position 10 to have type longblob, found type varbinary(255).
2022-10-24 20:07:45 67 [ERROR] Incorrect definition of table mysql.column_stats: expected column 'hist_type' at position 9 to have type enum('SINGLE_PREC_HB','DOUBLE_PREC_HB','JSON_HB'), found type enum('SINGLE_PREC_HB','DOUBLE_PREC_HB').
2022-10-24 20:07:45 67 [ERROR] Incorrect definition of table mysql.column_stats: expected column 'histogram' at position 10 to have type longblob, found type varbinary(255).
2022-10-24 20:07:45 67 [ERROR] Incorrect definition of table mysql.column_stats: expected column 'hist_type' at position 9 to have type enum('SINGLE_PREC_HB','DOUBLE_PREC_HB','JSON_HB'), found type enum('SINGLE_PREC_HB','DOUBLE_PREC_HB').
2022-10-24 20:07:45 67 [ERROR] Incorrect definition of table mysql.column_stats: expected column 'histogram' at position 10 to have type longblob, found type varbinary(255).
2022-10-24 20:07:51 0 [Note] /usr/bin/mysqld (initiated by: unknown): Normal shutdown
2022-10-24 20:07:51 0 [Note] InnoDB: FTS optimize thread exiting.
2022-10-24 20:07:51 0 [Note] InnoDB: Starting shutdown...
2022-10-24 20:07:51 0 [Note] InnoDB: Dumping buffer pool(s) to /home/knut/.local/share/akonadi/db_data/ib_buffer_pool
2022-10-24 20:07:51 0 [Note] InnoDB: Restricted to 2016 pages due to innodb_buf_pool_dump_pct=25
2022-10-24 20:07:51 0 [Note] InnoDB: Buffer pool(s) dump completed at 221024 20:07:51
2022-10-24 20:07:51 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1"
2022-10-24 20:07:51 0 [Note] InnoDB: Shutdown completed; log sequence number 25265153099; transaction id 170786390
2022-10-24 20:07:51 0 [Note] /usr/bin/mysqld: Shutdown complete

At startup there are a couple of warnings before the error messages start again:
2022-10-24 20:27:12 0 [Warning] option 'innodb-log-buffer-size': unsigned value 1048576 adjusted to 2097152
2022-10-24 20:27:12 0 [Note] InnoDB: Compressed tables use zlib 1.2.12
2022-10-24 20:27:12 0 [Note] InnoDB: Number of transaction pools: 1
2022-10-24 20:27:12 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2022-10-24 20:27:12 0 [Note] InnoDB: Using Linux native AIO
2022-10-24 20:27:12 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 2.000MiB
2022-10-24 20:27:12 0 [Note] InnoDB: Completed initialization of buffer pool
2022-10-24 20:27:12 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
2022-10-24 20:27:12 0 [Note] InnoDB: 128 rollback segments are active.
2022-10-24 20:27:12 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
2022-10-24 20:27:12 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
2022-10-24 20:27:12 0 [Note] InnoDB: log sequence number 25265153099; transaction id 170786391
2022-10-24 20:27:12 0 [Note] InnoDB: Loading buffer pool(s) from /home/knut/.local/share/akonadi/db_data/ib_buffer_pool
2022-10-24 20:27:12 1 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 1 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 0 [Note] /usr/bin/mysqld: ready for connections.
Version: '10.9.3-MariaDB'  socket: '/run/user/1000/akonadi/mysql.socket'  port: 0  Arch Linux
2022-10-24 20:27:12 0 [Note] InnoDB: Buffer pool(s) load completed at 221024 20:27:12
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_table_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 4 [Warning] InnoDB: Table mysql.innodb_index_stats has length mismatch in the column name table_name. Please run mariadb-upgrade
2022-10-24 20:27:12 5 [ERROR] Incorrect definition of table mysql.column_stats: expected column 'hist_type' at position 9 to have type enum('SINGLE_PREC_HB','DOUBLE_PREC_HB','JSON_HB'), found type enum('SINGLE_PREC_HB','DOUBLE_PREC_HB').
2022-10-24 20:27:12 5 [ERROR] Incorrect definition of table mysql.column_stats: expected column 'histogram' at position 10 to have type longblob, found type varbinary(255).
2022-10-24 20:27:12 5 [ERROR] Incorrect definition of table mysql.column_stats: expected column 'hist_type' at position 9 to have type enum('SINGLE_PREC_HB','DOUBLE_PREC_HB','JSON_HB'), found type enum('SINGLE_PREC_HB','DOUBLE_PREC_HB').
...

BTW, that's what I get when I try to upgrade mariadb:
$ mariadb-upgrade
Reading datadir from the MariaDB server failed. Got the following error when executing the 'mysql' command line client
ERROR 2002 (HY000): Can't connect to local server through socket '/run/mysqld/mysqld.sock' (2)
FATAL ERROR: Upgrade failed
Comment 4 Iyán Méndez Veiga 2022-10-25 13:50:25 UTC 
I was about to report a new bug about this. I was running out of space, didn't know why, and I checked my disk with du (forgot about Filelight :S), and I saw a .local/share/akonadi/db_data/mysql.err.old of 81 GiB and and a growing .local/share/akonadi/db_data/mysql.err of already 1.5 GiB.
Comment 5 Iyán Méndez Veiga 2022-10-25 14:12:28 UTC 
I changed the driver to QPSQL. Will see if it gets better than using MariaDB.
Comment 6 Carl Schwan 2023-04-25 11:01:09 UTC 
The '> 2022-10-11 23:42:45 181 [ERROR] Incorrect definition of table mysql.column_stats: expected column 'histogram' at position 10 to have type longblob, found type varbinary(255).' issue was fixed with https://invent.kde.org/pim/akonadi/-/commit/9cda58ef9045b567c54feea774f73d045949e6c8
Comment 7 Sebastian Turzański 2023-10-10 08:33:31 UTC 
please reopen
this is still the case with current

Linux/KDE Plasma: 5.27.8
(available in About System)
KDE Plasma Version: 5.27.8
KDE Frameworks Version: 5.110.0
Qt Version: 5.15.10

mysql error log grew to 90GB !
Comment 8 Carl Schwan 2023-10-10 23:26:25 UTC 
(In reply to Sebastian Turzański from comment #7)
> please reopen
> this is still the case with current
> 
> Linux/KDE Plasma: 5.27.8
> (available in About System)
> KDE Plasma Version: 5.27.8
> KDE Frameworks Version: 5.110.0
> Qt Version: 5.15.10
> 
> mysql error log grew to 90GB !

Do you see some lines inside the log which repeats very often?
Comment 9 Sebastian Turzański 2023-10-11 05:23:53 UTC 
I had to delete the file and so far (since yesterday) it remains small (kiloBytes) 
I will keep en eye on it next time, 
I suggest to mark the bug  as needsInfo.
Comment 10 ratijas 2023-10-11 14:35:12 UTC 
One obvious solution to this bug would be to configure MySQL for log rotation and other file size limits. It's not reasonable to allow it to grow in Gigabytes.
Comment 11 Sebastian Turzański 2023-10-12 08:53:25 UTC 
(In reply to ratijas from comment #10)
> One obvious solution to this bug would be to configure MySQL for log
> rotation and other file size limits. It's not reasonable to allow it to grow
> in Gigabytes.

I completely agree, there should be a default low limit like 100MB but i guess this for a dedicated MYSQL instance that handles akonadi db so the config should be somehow in akonadi. Don't know the design so I'm guessing it's not for user to mess with it.
Comment 12 Bug Janitor Service 2023-10-19 12:41:59 UTC 
A possibly relevant merge request was started @ https://invent.kde.org/pim/akonadi/-/merge_requests/146
Comment 13 Carl Schwan 2023-10-19 15:10:09 UTC 
Git commit 897d583942e7acb2bce5b65b56a6c0c19260d6f9 by Carl Schwan.
Committed on 19/10/2023 at 17:10.
Pushed by carlschwan into branch 'release/23.08'.

Only keep mysql log from the last session

Previously mysql.err.old would grow infinively and reaching multiple
dozens of gigabit in some cases. With this change we keep the log from
the current session in mysql.err and from the previous session in
mysql.err.old only.


(cherry picked from commit d1738fa348e79bc4abf781f0512ef256460d78b2)

M  +1    -1    src/server/storage/dbconfigmysql.cpp

https://invent.kde.org/pim/akonadi/-/commit/897d583942e7acb2bce5b65b56a6c0c19260d6f9
Comment 14 Carl Schwan 2023-10-19 15:25:40 UTC 
Git commit d1738fa348e79bc4abf781f0512ef256460d78b2 by Carl Schwan.
Committed on 19/10/2023 at 17:09.
Pushed by carlschwan into branch 'master'.

Only keep mysql log from the last session

Previously mysql.err.old would grow infinively and reaching multiple
dozens of gigabit in some cases. With this change we keep the log from
the current session in mysql.err and from the previous session in
mysql.err.old only.

M  +1    -1    src/server/storage/dbconfigmysql.cpp

https://invent.kde.org/pim/akonadi/-/commit/d1738fa348e79bc4abf781f0512ef256460d78b2