[SOLVED] Mail delivery issues for POP/IMAP in latest Grommunio releases

ozy

I noticed that POP/IMAP clients had huge delays in mail delivery, whereas Exchange accounts worked just fine.

After some investigations, I found out that mysql refused sporadically connections from gromox:

2024-08-22 15:51:33 13 [Warning] Aborted connection 13 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got an error reading communication packets)
2024-08-22 15:51:33 14 [Warning] Aborted connection 14 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got an error reading communication packets)
2024-08-22 15:51:33 32 [Warning] Aborted connection 32 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got an error reading communication packets)
2024-08-22 15:51:33 18 [Warning] Aborted connection 18 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got an error reading communication packets)
2024-08-22 15:51:33 17 [Warning] Aborted connection 17 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got an error reading communication packets)
2024-08-22 15:51:33 33 [Warning] Aborted connection 33 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got an error reading communication packets)
2024-08-22 15:51:33 35 [Warning] Aborted connection 35 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got an error reading communication packets)
2024-08-22 15:51:33 34 [Warning] Aborted connection 34 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got an error reading communication packets)
2024-08-22 15:51:33 31 [Warning] Aborted connection 31 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got an error reading communication packets)
2024-08-22 15:51:33 30 [Warning] Aborted connection 30 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got an error reading communication packets)
2024-08-22 15:51:33 25 [Warning] Aborted connection 25 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got an error reading communication packets)
2024-08-22 15:51:33 26 [Warning] Aborted connection 26 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got an error reading communication packets)
2024-08-22 15:51:33 12 [Warning] Aborted connection 12 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got an error reading communication packets)

I've made multiple MySQL configs for other projects, so here's my take to fix this issue:

Create new file /etc/my.cnf.d/grommunio_tuning.cnf with following content:

[mysqld]

# NETPERFECT-BZ012: Optimisation des performances mono serveur
table_cache             = 1000
innodb_buffer_pool_size = 1G
read_rnd_buffer_size    = 8M
sort_buffer_size        = 8M
# NETPERFECT-BZ131: Permet l'import de fichiers SQL disposant de INSERT statements trop longs (ERROR 2006 (HY000) at line 696: MyS>
max_allowed_packet      = 256M
# NETPERFECT-BZ065: Augmenter la taille du fichier log INNODB pour permetttre de jouer de plus grandes requêtes (info: MySQL serve>
innodb_log_file_size    = 256M
# NETPERFECT-BZ213: Augmenter la durée maximale d'absence de requête pour éviter l'erreur (MySQL server has gone away)
wait_timeout            = 288000
# NETPERFECT-BZ003: Chaque table INNODB doit posséder son propre fichier afin de faciliter la récuperation de données en cas de cr>
innodb-file-per-table   = 1

# NETPERFECT-BZ511: En cas d'erreur Got timeout reading communication packets, augmenter les délais
net_read_timeout=3600
net_write_timeout=3600

Restart mysql with service restart mysql
Warning: restarting mysql will temporarily (10s) make your mail server respond 451 deferred to incomming messages.
After this, I did not encounter the mysql error anymore, and mails are not delayed anymore either.

Hope this might help someone.

Notes: These are my own tuning settings I carry between various mysql instances.
Perhaps the cache sizes and other tunables need to be set according to your server's workloads.

Also, @grommunio Perhaps this config or alike could make it into a next release ?

Mit Freundliche Grüsse / Best regards
Orsiris de Jong.

Tested with gromox-2.30.106.gf1d7ee1-lp155.7.1.x86_64 on latest OpenSuSE Leap 15.6.
Also references this older community thread

crpb

ozy 2024-08-22 15:51:33 13 [Warning] Aborted connection 13 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got an error reading communication packets)
2024-08-22 15:51:33 14 [Warning] Aborted connection 14 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got an error reading communication packets)

I have those aswell on a nother time tho because grommunio-spam-run has a custom time ^_^.

I don't see how this would help with the IMAP problematic.

WalterH

ozy How many connections you see, when you run this command: mysqladmin processlist ?
If you habe only the core components installed, all threads belong to the gromox MySQL database.
And how many mailboxes you have on thy system?

ozy

crpb While testing the issue, I found that webmail and exchange clients showed all emails, while POP / IMAP accounts didn't. I did tests with a fresh account and noticed that POP STAT command returned 0 messages when I've sent a couple of messages, which of course were visible in Exchange clients and webmail. And every message sent generated one of the MySQL error log lines.

Once I resolved the MySQL connection issues with the above tuning, POP & IMAP delivery was on par with Exchange one and POP STAT commands were correct.

crpb

Still very odd.. I don't see how a innbodb of 1gb for a database that is dumped not even 2MB big would help.

gromi:/tmp/tmp.YpU9GFlmzG # mysqldump -A > mysql.dump
gromi:/tmp/tmp.YpU9GFlmzG # wc mysql.dump
   1640  192575 1928729 mysql.dump
gromi:/tmp/tmp.YpU9GFlmzG # stat mysql.dump
  File: mysql.dump
  Size: 1928729         Blocks: 3768       IO Block: 4096   regular file
Device: 34h/52d Inode: 2173        Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2024-08-22 18:33:00.942107107 +0200
Modify: 2024-08-22 18:32:59.006076678 +0200
Change: 2024-08-22 18:32:59.006076678 +0200
 Birth: -
gromi:/tmp/tmp.YpU9GFlmzG # ls -l
total 1884
-rw-r--r-- 1 root root 1928729 Aug 22 18:32 mysql.dump
gromi:/tmp/tmp.YpU9GFlmzG #

Have you seen this this thread?

crpb

"Ich fress en besen!"

@ozy

I tried it nonetheless and with the first couple mails i'm just totaly astouned...

/me will refrain from ranting here...

`/etc/my.cnf.d/grommunio.cnf`

[mariadb]
max_allowed_packet=256M
net_read_timeout=3600
net_write_timeout=3600
read_rnd_buffer_size=8M
sort_buffer_size=8M
table_cache=1000
thread_cache_size=512
wait_timeout=288000

ozy

@crpb Hab schon seit sehr lang nicht mehr "Ich fress ein Besen" gehört 😉

But TBH, I don't really understand your response.
Did my solution work for you or did it fail and you just don't want to rant here ?

Btw, it's the timeouts that are required, I only set the other values since it's my default config on most setups, and they're usually working well and improve performance. Some of them date back when I still used the very old giraffe email server, like the file_per_table which is just easier to debug.

crpb

It seems to work, "as i am astouned". Already linked to this in the other thread to let them check aswell.
I haven't tested more now but let alone three mails with some time inbetween and the immediate availability, as i was used to for the last ₂ years. It must be it.

The rant would go somewhere completly else...

So that basically does keep the services not to timeout and therfore not getting stuck... as if nobody could have seen that who actually is writing/building/debugging that...

crpb

Sadly this didn't fix all my problems.
Writing (Composing/Sending/Copy-To-Send/) is still broken on my end with Claws-Mail (alpine worked)

The mail gets delivered just not stored in my mailbox o_0.

ozy

Well, I'm happy it did at least fix some problems 😉 I imagine that somehow there must be a memleak or else in gromox code that keeps the mysql connection in a TIME_WAIT state without refreshing it.

Anyway, after those modifications, do you still have some mysql error messages ?
Perhaps my settings aren't optimal for your setup.

crpb

ozy

It definitely went down.

armitage:/var/log/mysql # xzgrep -c Warning *
mysqld.log:0
mysqld.log-20240821.xz:33
mysqld.log-20240822.xz:31
mysqld.log-20240823.xz:28
armitage:/var/log/mysql # 

gromi:/var/log/mysql # xzgrep -c Warning *
mysqld.log:5
mysqld.log-20240821.xz:26
mysqld.log-20240822.xz:26
mysqld.log-20240823.xz:25
gromi:/var/log/mysql # 

gromi:/var/log/mysql # xzgrep -c Warning *
mysqld.log:0
mysqld.log-20240821.xz:25
mysqld.log-20240822.xz:25
mysqld.log-20240823.xz:24
gromi:/var/log/mysql # 

server-grommunio:/var/log/mysql # xzgrep -c Warning *
mysqld.log:15
mysqld.log-20240821.xz:34
mysqld.log-20240822.xz:37
mysqld.log-20240823.xz:34
server-grommunio:/var/log/mysql # 

gromi:/var/log/mysql # xzgrep -c Warning *
mysqld.log:0
mysqld.log-20240821.xz:25
mysqld.log-20240822.xz:25
mysqld.log-20240823.xz:25
gromi:/var/log/mysql # 

gromi:/var/log/mysql # xzgrep -c Warning *
mysqld.log:0
mysqld.log-20240821.xz:26
mysqld.log-20240822.xz:27
mysqld.log-20240823.xz:28
gromi:/var/log/mysql # 

gromi:/var/log/mysql # xzgrep -c Warning *
mysqld.log:0
mysqld.log-20240821.xz:25
mysqld.log-20240822.xz:25
mysqld.log-20240823.xz:25
gromi:/var/log/mysql # 

gromi:/var/log/mysql # xzgrep -c Warning *
mysqld.log:0
mysqld.log-20240821.xz:30
mysqld.log-20240822.xz:27
mysqld.log-20240823.xz:30
gromi:/var/log/mysql # 

gromi:/var/log/mysql # xzgrep -c Warning *
mysqld.log:0
mysqld.log-20240820.xz:24
mysqld.log-20240821.xz:24
mysqld.log-20240822.xz:32
mysqld.log-20240823.xz:26
gromi:/var/log/mysql #

ozy

@WalterH I have a 4 users community setup and another 5 user community setup. Both have chat, archive and jitsi installed. Both servers had the same POP/IMAP behavior, and both are up-to-date.

mysqladmin processlist result (on boths machines, above mysql tuning file is setup):

+--------+-----------+-----------------+-----------+---------+-------+----------+------------------+----------+
| Id     | User      | Host            | db        | Command | Time  | State    | Info             | Progress |
+--------+-----------+-----------------+-----------+---------+-------+----------+------------------+----------+
| 16     | grochat   | localhost:48122 | grochat   | Sleep   | 800   |          |                  | 0.000    |
| 20     | grommunio | localhost       | grommunio | Sleep   | 5     |          |                  | 0.000    |
| 21     | grommunio | localhost       | grommunio | Sleep   | 5     |          |                  | 0.000    |
| 26     | grommunio | localhost       | grommunio | Sleep   | 5     |          |                  | 0.000    |
| 39     | grommunio | localhost       | grommunio | Sleep   | 5     |          |                  | 0.000    |
| 40     | grommunio | localhost       | grommunio | Sleep   | 5     |          |                  | 0.000    |
| 87     | grommunio | localhost       | grommunio | Sleep   | 5     |          |                  | 0.000    |
| 88     | grommunio | localhost       | grommunio | Sleep   | 5     |          |                  | 0.000    |
| 89     | grommunio | localhost       | grommunio | Sleep   | 5     |          |                  | 0.000    |
| 394    | grommunio | localhost       | grommunio | Sleep   | 1009  |          |                  | 0.000    |
| 395    | grommunio | localhost       | grommunio | Sleep   | 1009  |          |                  | 0.000    |
| 1557   | grommunio | localhost       | grommunio | Sleep   | 39201 |          |                  | 0.000    |
| 1612   | grommunio | localhost       | grommunio | Sleep   | 47814 |          |                  | 0.000    |
| 1665   | grommunio | localhost       | grommunio | Sleep   | 40269 |          |                  | 0.000    |
| 4712   | grommunio | localhost       | grommunio | Sleep   | 61201 |          |                  | 0.000    |
| 5912   | grommunio | localhost       | grommunio | Sleep   | 60573 |          |                  | 0.000    |
| 11964  | grommunio | localhost       | grommunio | Sleep   | 57601 |          |                  | 0.000    |
| 19222  | grommunio | localhost       | grommunio | Sleep   | 54001 |          |                  | 0.000    |
| 26473  | grommunio | localhost       | grommunio | Sleep   | 50401 |          |                  | 0.000    |
| 33724  | grommunio | localhost       | grommunio | Sleep   | 46801 |          |                  | 0.000    |
| 40972  | grommunio | localhost       | grommunio | Sleep   | 43201 |          |                  | 0.000    |
| 48217  | grommunio | localhost       | grommunio | Sleep   | 39601 |          |                  | 0.000    |
| 55462  | grommunio | localhost       | grommunio | Sleep   | 36001 |          |                  | 0.000    |
| 62705  | grommunio | localhost       | grommunio | Sleep   | 32401 |          |                  | 0.000    |
| 69963  | grommunio | localhost       | grommunio | Sleep   | 28801 |          |                  | 0.000    |
| 77214  | grommunio | localhost       | grommunio | Sleep   | 25201 |          |                  | 0.000    |
| 84460  | grommunio | localhost       | grommunio | Sleep   | 21601 |          |                  | 0.000    |
| 91696  | grommunio | localhost       | grommunio | Sleep   | 18001 |          |                  | 0.000    |
| 98929  | grommunio | localhost       | grommunio | Sleep   | 14401 |          |                  | 0.000    |
| 106171 | grommunio | localhost       | grommunio | Sleep   | 10801 |          |                  | 0.000    |
| 113405 | grommunio | localhost       | grommunio | Sleep   | 7201  |          |                  | 0.000    |
| 120651 | grommunio | localhost       | grommunio | Sleep   | 3601  |          |                  | 0.000    |
| 121965 | grochat   | localhost:55942 | grochat   | Sleep   | 247   |          |                  | 0.000    |
| 125583 | grochat   | localhost:34004 | grochat   | Sleep   | 10    |          |                  | 0.000    |
| 127892 | grommunio | localhost       | grommunio | Sleep   | 1     |          |                  | 0.000    |
| 127897 | root      | localhost       |           | Query   | 0     | starting | show processlist | 0.000    |
+--------+-----------+-----------------+-----------+---------+-------+----------+------------------+----------+

My best guess about the problem:
gromox keeps the mysql connections open, ie in TIME_WAIT state, and mysql drops the connection after net_read_timeout and net_write_timeout is reached, which is 5 sec by default.
Since mysql doesn't store anything else than configuration, I guess the "notify" process from midb for POP/IMAP is not launched since the code path is not reached when mysql errors occur.

Indeed, the mysql tuning set, gromox will still have timeouts with mysql after the configured wait time, but at least it's a "hotfix".

jengelh

ozy gromox keeps the mysql connections open, ie in TIME_WAIT state

Yeah no. TIME_WAIT is a duplex-closed state, cf. https://datatracker.ietf.org/doc/html/rfc793#page-23 . It's also a TCP state and does not exist in Unix Domain Sockets (which are used here for SQL communications).

and mysql drops the connection after net_read_timeout and net_write_timeout is reached, which is 5 sec by default.

Indeed Gromox holds connections, but that counts as idle, and the corresponding mysqld variable is wait_timeout.
net_read_timeout is the maximum wait time to receive the rest of a command/query once the client has started issuing one. Queries are on the order of 200 bytes and local machine transfer speeds in excess of 10 GBps—all said, with practical overheads that should take just 12 µs. Of course, with enough system loading, debugger tricks (or bugs, for that matter), enough latency could theoretically be induced into the system to delay transmission and make processes run into said timeouts.

No need to bother with skip_name_resolve. Lookup of localhost/127 has a fastpath thanks to the static entry in /etc/hosts. It goes without saying that, because UDS are used, there is not even something to resolve in the first place.

crpb

@jengelh Could you maybe tell us why this happens or if it's already in the works to be fixed?

WalterH

Also G-Web performs better when this modification is in place.

WalterH

My results: on two server, this modification works perfect and the connection errors are gone. On a third server, Postfix can't access the virtual lookup tables in DB. Currently I did not have time to debug this, so I removed the configuration file from this server. Will post the results within the next days.

WalterH

When you encounter postfix lookup errors, there are 2 options:

remove this line skip_name_resolve=ON from /etc/my.cnf.d/grommunio.cnfand restart mariadb and postfix.

verify this 4 Postfix lookup files:

ls -1 /etc/postfix/grommunio-*.cf | sort
/etc/postfix/grommunio-bcc-forwards.cf
/etc/postfix/grommunio-virtual-mailbox-alias-maps.cf
/etc/postfix/grommunio-virtual-mailbox-domains.cf
/etc/postfix/grommunio-virtual-mailbox-maps.cf

cat /etc/postfix/grommunio-*.cf | grep hosts
The hosts string must be localhost like: hosts = localhost, if you see 127.0.0.1 change ist to localhost and restart mariadb and postfix.
Reason: skip_name_resolve=ON disables name resolution for Maria DB, so 127.0.0.1 do not get resolved as localhost any longer.

crpb

WalterH Reason: skip_name_resolve=ON disables name resolution for Maria DB, so 127.0.0.1 do not get resolved as localhost any longer.

even localhost? oh... should have read a bit further i guess 😛.

Fixed my config above.....

WalterH

Yes I run into this problem before and removing skip_name_resolve=ON was the quick fix.
See: https://community.grommunio.com/d/1769-solved-mail-delivery-issues-for-popimap-in-latest-grommunio-releases/15

skip_name_resolve=ON is a great option, saves some CPU time and it is not really needed as described above.

GeneralProbe

So I would like to cautiously throw my results into the round that the mysql tuning options on my server Rocky Linux 9.4 - aarch64) do not lead to the desired success. The mails still arrive every 10 minutes late (see midb.cfg)

I have created the following entry:
/etc/my.cnf.d/grommunio.cnf

[mariadb]
innodb_buffer_pool_size=1G
max_allowed_packet=256M
net_read_timeout=3600
net_write_timeout=3600
read_rnd_buffer_size=8M
skip_name_resolve=ON
sort_buffer_size=8M
table_cache=1000
thread_cache_size=512 #this value is not adopted from the configuration file in my case, I then set it myself in mariadb to be able to test it
wait_timeout=288000

The settings in /etc/gromox/midb.cfg

midb_cache_interval=5minutes
midb_reload_interval=10minutes

are still in place.

On a positive note, the mysql [Warning]s have actually disappeared.

(sorry for writing in German in the first place ...)

crpb

It isn't persistent for me aswell... laggs are happening again.. 🙁

GeneralProbe

crpb
What is not persistent for you?
The "thread_cache_size" entry?

@ozy for me it sadly does not change anything.
The first mail after restart is instant, the others are delayed around 10 mins.