[SOLVED] Mail delivery issues for POP/IMAP in latest Grommunio releases
@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".
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 #
Also G-Web performs better when this modification is in place.
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.
- Edited
When you encounter postfix lookup errors, there are 2 options:
remove this line
skip_name_resolve=ON
from/etc/my.cnf.d/grommunio.cnf
and 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 belocalhost
like:hosts = localhost
, if you see127.0.0.1
change ist tolocalhost
and restart mariadb and postfix.
Reason:skip_name_resolve=ON
disables name resolution for Maria DB, so127.0.0.1
do not get resolved aslocalhost
any longer.
- Edited
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.
- Edited
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 ...)
It isn't persistent for me aswell... laggs are happening again..
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
.
- Edited
GeneralProbe Do you have any aborted connection entries in mysql logs ?
how the mails show up in imap. well, new mails seems to come in ok. read/unread status seems a bit fonky..
today I see the "[Warning] Aborted connection" again for all three servers.
- Edited
@crpb Not persistent for me too. There must be some side effect somewhere which is triggered by restarting mysql.
I've implemented the midb cache/reload settings too meanwhile.
Still, server runs faster with the mysql settings.
The final settings I use which don't show any other connections error since 2 hours:
Note that I added connect_timeout
which seems to handle the remaining errors.
[mysqld]
table_cache = 1000
innodb_buffer_pool_size = 1G
read_rnd_buffer_size = 8M
sort_buffer_size = 8M
max_allowed_packet = 256M
innodb_log_file_size = 256M
wait_timeout = 288000
innodb-file-per-table = 1
net_read_timeout = 3600
net_write_timeout = 3600
connect_timeout = 3600
I have no warnings / aborted connections yet.
So the above mysql tuning with connect_timout
set does not produce any errors since 6 hours.
Strange part is, POP/IMAP has no delay with these setups for a while, and then fades back to delays defined by midb reload/cache settings.
There's definitly some relation, but I can't understand which one.
Sorry if I suggested this completely solves the delay issues, but I guess it will help diagnose them somehow.
Right,
2024-08-26 11:02:45 0 [Note] Starting MariaDB 10.5.22-MariaDB source revision 7e650253dc488debcb0898ebe6d385bf6dfa3656 as process 992
2024-08-26 11:02:45 0 [Note] InnoDB: Uses event mutexes
2024-08-26 11:02:45 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2024-08-26 11:02:45 0 [Note] InnoDB: Number of pools: 1
2024-08-26 11:02:45 0 [Note] InnoDB: Using ARMv8 crc32 + pmull instructions
2024-08-26 11:02:45 0 [Note] InnoDB: Using Linux native AIO
2024-08-26 11:02:45 0 [Note] InnoDB: Initializing buffer pool, total size = 1073741824, chunk size = 134217728
2024-08-26 11:02:45 0 [Note] InnoDB: Completed initialization of buffer pool
2024-08-26 11:02:45 0 [Note] InnoDB: 128 rollback segments are active.
2024-08-26 11:02:45 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2024-08-26 11:02:45 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2024-08-26 11:02:45 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2024-08-26 11:02:45 0 [Note] InnoDB: 10.5.22 started; log sequence number 658220; transaction id 1920
2024-08-26 11:02:45 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2024-08-26 11:02:45 0 [Note] Plugin 'FEEDBACK' is disabled.
2024-08-26 11:02:45 0 [Note] Server socket created on IP: '::1'.
2024-08-26 11:02:45 0 [Note] InnoDB: Buffer pool(s) load completed at 240826 11:02:45
2024-08-26 11:02:46 0 [Warning] 'proxies_priv' entry '@% root@mail.example.com' ignored in --skip-name-resolve mode.
2024-08-26 11:02:46 0 [Note] Reading of all Master_info entries succeeded
2024-08-26 11:02:46 0 [Note] Added new Master_info '' to hash table
2024-08-26 11:02:46 0 [Note] /usr/libexec/mariadbd: ready for connections.
Version: '10.5.22-MariaDB' socket: '/var/lib/mysql/mysql.sock' port: 3306 MariaDB Server
that's my log.
But I do get the delays just after receiving the first mail.