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

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.

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

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

WalterH

today I see the "[Warning] Aborted connection" again for all three servers.

ozy

@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

WalterH

ozy innodb-file-per-table = 1

you schuld never set this parameters in a config file like this one, this parameter change the behavior of the database and my render the database unusable.

Setting: innodb_buffer_pool_size = 1G is in most cases to big for a mail system.

GeneralProbe

I have no warnings / aborted connections yet.

ozy

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.

GeneralProbe

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.

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.

WalterH

Unfortunately, with all of this settings, I see this warnings: [Warning] Aborted connection some days more and some days less.

jengelh

gromox-2.31-40-gc6173b2c3

WalterH

jengelh Thank you.

GeneralProbe

Does anyone had success with the update?
On my first try, it did not help, so I reverted back to stable.

ozy

So yes, with the above mysql tuning, errors still come, just later.

What bugs me is that I also get mysql connection errors from chat, which makes me think that all connections must be exhausted at one point:

2024-09-02 15:17:30 1909819 [Warning] Aborted connection 1909819 to db: 'grommunio' user: 'grommunio' host: 'localhost' (Got an error reading communication packets)
2024-09-02 15:17:30 1909815 [Warning] Aborted connection 1909815 to db: 'grochat' user: 'grochat' host: 'localhost' (Got an error reading communication packets)
2024-09-02 15:17:30 1909805 [Warning] Aborted connection 1909805 to db: 'grochat' user: 'grochat' host: 'localhost' (Got an error reading communication packets)

I've just installed @jengelh 's suggested gromox-2.31.40.gc6173b2-lp155.17.1.x86_64 (along with all other current git updaes) on my personal email server and removed the mysql tuning in order to have proper environment.
Rebooted, and now wait to see.
I'll report later this day if I still have any mysql timeouts.

ozy

So it's been 7 hours, no mysql errors shown on my updated server.

Still, I get some sporadic delayed POP/IMAP mail. I'm quite sorry that the mysql stuff didn't resolve all the issues, but it's still better.

When POP/IMAP delays happens, I sometimes get the following error, perhaps this is related:

sept. 02 22:17:52 email gromox-midb[1505]: > sqlite3_exec(UPDATE folders SET sort_field=0 WHERE folder_id=13) inside a readonly TXN
sept. 02 22:17:52 email gromox-midb[1505]: > sqlite3_exec(DELETE FROM messages WHERE message_id=218710) inside a readonly TXN
sept. 02 22:17:47 email postfix/qmgr[1866]: A951E2F4A8: removed
sept. 02 22:17:47 email postfix/qmgr[1866]: A65212F4A7: removed

It looks like the first message always is delivered instantly, and later messages get delayed for POP/IMAP clients.

Anyway I still need the midb_reload_interval=3minutes setting in hope to see my mails appear at least every 3 minutes.

As a quick side question, does gromox trigger midb when a mail is received ?
Is there a way to debug log this ? I've tried to set midb_log_level=6 in /etc/gromox/midb.cfg but it doesn't add any more info to the logs.

crpb

ozy Still, I get some sporadic delayed POP/IMAP mail. I'm quite sorry that the mysql stuff didn't resolve all the issues, but it's still better.

YES, IT DIDN'T! 😥

ozy As a quick side question, does gromox trigger midb when a mail is received ?

Thats the actual problem i'm guessing but haven't got any response in my ticket for it...
And that other thread you already know about 😛.

ozy

Thats the actual problem i'm guessing but haven't got any response in my ticket for it...
And that other thread you already know about 😛.

Hmmm... I'm a Grommunio "peasant", I have two community instances, so no access to any fancy tickets or service 🙁
Would appreciate if you keep me updated. This is bugging me because although I use MAPI & ActiveSync for my devices, I do have a pop retriever which usually is much delayed.

I noticed this problem only recently (didn't have any use for POP/IMAP prior to a few weeks). For how many time did you notice the problem ? Was it always there or has there been a working previous release ?

Thanks ^^

crpb

ozy I noticed this problem only recently (didn't have any use for POP/IMAP prior to a few weeks). For how many time did you notice the problem ? Was it always there or has there been a working previous release ?

I first noticed July slightly but didn't even realize how serious the difference is for an IMAP user at first because i only used my client and only occasionally looked into the web-app.

And no it wasn't always there..
I had a smooth ride since ~spring '22 with Claws-Mail and only had a little issue here and there which wasn't serious and was fixed pretty quick IIRC.

I currently only use it to move server mails in a subfolder because that isn't fun in the webapp with like ~200-1000 mails and as an RSS-Reader 😛

I hope someone _/me *squints* at @jengelh _ will get a handle on it rather sooner than later as e.g Ticketsystems and alike are also affected. Some even could use EWS but the main focus for it on this point was Outlook for MAC and other EWS Clients aren't reallly working. (At least i haven't seen one..). Enough of it..

Fingers crossed, most people should be back from the summer vacation so we can only hope.

WalterH

crpb most people should be back from the summer vacation

Some grommunio developer come back this weekend.

« Previous Page Next Page »