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

ozy · 2024-08-22T14:10:58+00:00

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 my...

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 #

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

@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.

ozy

So my MySQL tuning above doesn't resolve entirely the problem, it just makes the POP/IMAP delays happen way more less, so there's definitly room for improvement.

I still get a couple mysql errors:

2024-08-26 10:07:45 7 [Warning] Aborted connection 7 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got timeout reading communication packets)
2024-08-26 10:07:45 9 [Warning] Aborted connection 9 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got timeout reading communication packets)
2024-08-26 11:07:45 54 [Warning] Aborted connection 54 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got timeout reading communication packets)
2024-08-26 12:07:45 89 [Warning] Aborted connection 89 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got timeout reading communication packets)
2024-08-26 13:07:45 105 [Warning] Aborted connection 105 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got timeout reading communication packets)
2024-08-26 14:07:45 132 [Warning] Aborted connection 132 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got timeout reading communication packets)

I'll try a bit more tuning. Currently trying to raise connect_timeout.

ozy

GeneralProbe Do you have any aborted connection entries in mysql logs ?

crpb

GeneralProbe

how the mails show up in imap. well, new mails seems to come in ok. read/unread status seems a bit fonky..