Sync error

irdi

Hey folks! Since i did not find an introduction post i am doing an introduction here since this is my first post.

First of all thank you all for contributing to this amazing project. I am Irdi, i am a FLOSS hacktivist and a Linux sysadmin. I work mostly with Nextcloud, helping people move away from GAFAM. Lately i have been working with mailcow and it is amazing how easy the process of setting your mail server is with mailcow but maintenance and debugging is another thing which has taken me here, to the community.

I am not sure if i am in the right direction but im gonna try to explain and hopefully someone can point me into the right direction to solve the issue im encountering.

I use mailcow as mail server and Nextcloud Mail as a client and it works fine, but at least once a day i get an error that sync failed and as soon as i restart the mailcow server it all works again so i came to the conclusion that it must be something that has to be fixed on mailcow. I also realised that Dovecot is responsible for imap and sync (correct me if im wrong) but in the logs i can not find anything meaningful to help me solve the issue.

p.s i went through the posts but i could not find a similar issue reported before. If there was one please point me to it. Thanks a lot!

The error i get in Nextcloud (formated to make it easier to read).

{ "ExceptionType": "OCA\\Mail\\Exception\\ServiceException", "Message": "Sync failed for 554:INBOX: Error connecting to mail server.", "Code": 0, "Trace": [ { "file": "/var/www/html/custom_apps/mail/lib/Service/Sync/SyncService.php", "line": 126, "function": "sync", "class": "OCA\\Mail\\Service\\Sync\\ImapToDbSynchronizer", "type": "->", "args": ["*** sensitive parameters replaced ***"] }, { "file": "/var/www/html/custom_apps/mail/lib/Controller/MailboxesController.php", "line": 154, "function": "syncMailbox", "class": "OCA\\Mail\\Service\\Sync\\SyncService", "type": "->", "args": ["*** sensitive parameters replaced ***"] }, { "file": "/var/www/html/lib/private/AppFramework/Http/Dispatcher.php", "line": 230, "function": "sync", "class": "OCA\\Mail\\Controller\\MailboxesController", "type": "->", "args": ["*** sensitive parameters replaced ***"] }, { "file": "/var/www/html/lib/private/AppFramework/Http/Dispatcher.php", "line": 137, "function": "executeController", "class": "OC\\AppFramework\\Http\\Dispatcher", "type": "->", "args": [["OCA\\Mail\\Controller\\MailboxesController"],"sync"] }, { "file": "/var/www/html/lib/private/AppFramework/App.php", "line": 183, "function": "dispatch", "class": "OC\\AppFramework\\Http\\Dispatcher", "type": "->", "args": [["OCA\\Mail\\Controller\\MailboxesController"],"sync"] }, { "file": "/var/www/html/lib/private/Route/Router.php", "line": 315, "function": "main", "class": "OC\\AppFramework\\App", "type": "::", "args": ["OCA\\Mail\\Controller\\MailboxesController","sync",["OC\\AppFramework\\DependencyInjection\\DIContainer"],["2660","mail.mailboxes.sync"]] }, { "file": "/var/www/html/lib/base.php", "line": 1068, "function": "match", "class": "OC\\Route\\Router", "type": "->", "args": ["/apps/mail/api/mailboxes/2660/sync"] }, { "file": "/var/www/html/index.php", "line": 36, "function": "handleRequest", "class": "OC", "type": "::", "args": [] } ], "File": "/var/www/html/custom_apps/mail/lib/Service/Sync/ImapToDbSynchronizer.php", "Line": 263, "Previous": { "Exception": "Horde_Imap_Client_Exception", "Message": "Error connecting to mail server.", "Code": 11, "Trace": [ { "file": "/var/www/html/custom_apps/mail/vendor/bytestream/horde-imap-client/lib/Horde/Imap/Client/Socket.php", "line": 375, "function": "_connect", "class": "Horde_Imap_Client_Socket", "type": "->", "args": [] }, { "file": "/var/www/html/custom_apps/mail/lib/IMAP/ImapClientRateLimitingDecorator.php", "line": 73, "function": "_login", "class": "Horde_Imap_Client_Socket", "type": "->", "args": ["*** sensitive parameters replaced ***"] }, // ... (more trace details) { "file": "/var/www/html/custom_apps/mail/vendor/bytestream/horde-imap-client/lib/Horde/Imap/Client/Socket.php", "line": 606 } ] }, "Message": "Sync failed for 554:INBOX: Error connecting to mail server.", "Exception": {}, "CustomMessage": "Sync failed for 554:INBOX: Error connecting to mail server." }

esackbauer

That sounds like a firewall/iptables/routing problem for me.
The Nextcloud component cannot connect to the TCP socket of mailcows IMAP port.
That would also explain why you don’t see anything in dovecot’s logs

irdi

esackbauer Thank you very much for taking the time to help out.

Maybe out of the scope of this forum but ill give it a shot. Is it possible that the firewall is fine for most of the time but once a day it gives this issue?

Im gonna look it up and ill come back with any findings i may have in case someone else encounters the same issue.

Thanks a gain!

esackbauer

irdi Is it possible that the firewall is fine for most of the time but once a day it gives this issue?

Unlikely. Does it happen always around the same time? I run a backup script each night, that halts mailcow with all its containers for a short time. So any other component accessing mailcow will get timeouts during that time, but in this case that is intended behaviour.
If it happens randomly, it could also be a resource problem, like mailcow not getting enough CPU or I/O.

irdi

esackbauer

After verifying that ports 25 and 465 are open i checked the logs to see if there was something wrong and i got this in kern.log but i do not really know if it has anything to do with the problem.

Nov 20 08:10:36 localhost kernel: [227475.993028] br-mailcow: port 13(veth6d150be) entered disabled state Nov 20 08:10:36 localhost kernel: [227475.993122] veth5179178: renamed from eth0 Nov 20 08:10:36 localhost kernel: [227476.103025] br-mailcow: port 13(veth6d150be) entered disabled state Nov 20 08:10:36 localhost kernel: [227476.104264] device veth6d150be left promiscuous mode Nov 20 08:10:36 localhost kernel: [227476.104272] br-mailcow: port 13(veth6d150be) entered disabled state Nov 20 08:10:36 localhost kernel: [227476.244551] br-mailcow: port 13(veth049003a) entered blocking state Nov 20 08:10:36 localhost kernel: [227476.244557] br-mailcow: port 13(veth049003a) entered disabled state Nov 20 08:10:36 localhost kernel: [227476.244652] device veth049003a entered promiscuous mode Nov 20 08:10:36 localhost kernel: [227476.244960] br-mailcow: port 13(veth049003a) entered blocking state Nov 20 08:10:36 localhost kernel: [227476.244965] br-mailcow: port 13(veth049003a) entered forwarding state

It does not happen always at the same time and it is not a resource issue. Resource spike can barely get to 35% of the resources. A server restart solves the problem but it is annoying having to restart once a day, especially in workdays.

esackbauer

Those messages are describing the problem. Seems to be with your hoster and his hardware.

irdi

esackbauer Ill give it a shot by contacting their support. Thank you very much for your help so far!

irdi

Update, in case someone else goes through the same error there is material on the forums to help out.

I got in touch with Linode support, which is the provider of the server and they asked me to run a couple of mtr commands

While logged into your Linode:

mtr -rwbzc100 <local.IP.Address>
|
Results:

root@localhost:~# mtr -rwbzc100 <local.IP.Address>
Start: 2023-11-21T16:16:03+0000
HOST: localhost Loss% Snt Last Avg Best Wrst StDev
1. AS63949 mail.domain.com (69.164.210.61) 0.0% 100 0.1 0.1 0.0 0.1 0.0

While logged into your desktop: I ran this from the Nextcloud server.

mtr -rwbzc100 <linode.IP.Address>

Results:

root@aw-nextcloud:~# mtr -rwbzc100 <local.IP.Address>
Start: 2023-11-21T16:22:04+0000
HOST: nextcloud Loss% Snt Last Avg Best Wrst StDev
1. AS??? ??? 100.0 100 0.0 0.0 0.0 0.0 0.0
2. AS??? 10.76.194.68 0.0% 100 0.8 1.3 0.5 31.9 3.9
3. AS??? 143.198.252.2 0.0% 100 0.4 0.5 0.3 1.0 0.1
4. AS??? 143.244.192.86 0.0% 100 0.5 0.5 0.3 3.9 0.4
5. AS14061 143.244.224.230 0.0% 100 1.1 1.0 0.8 1.3 0.1
6. AS14061 143.244.224.207 0.0% 100 0.7 0.8 0.6 4.7 0.4
7. AS2914 ae-61.a02.sngpsi07.sg.bb.gin.ntt.net (116.51.17.165) 2.0% 100 0.9 1.8 0.6 23.5 3.8
8. AS2914 ae-5.r23.sngpsi07.sg.bb.gin.ntt.net (129.250.5.65) 99.0% 100 3.5 3.5 3.5 3.5 0.0
9. AS2914 ae-13.r33.tokyjp05.jp.bb.gin.ntt.net (129.250.2.243) 25.0% 100 70.9 70.1 67.8 80.3 2.1
10. AS2914 ae-4.r25.lsanca07.us.bb.gin.ntt.net (129.250.3.193) 21.0% 100 167.5 169.3 167.3 189.6 3.8
11. AS2914 ae-1.a02.lsanca20.us.bb.gin.ntt.net (129.250.2.114) 0.0% 100 173.4 175.0 173.1 195.8 4.0
12. AS2914 ae-0.akamai.lsanca20.us.bb.gin.ntt.net (128.241.7.121) 0.0% 100 178.4 186.2 170.9 316.9 26.8
13. AS20940 ae10.r02.lax01.icn.netarch.akamai.com (23.203.155.248) 0.0% 100 173.3 173.4 173.1 176.7 0.4
14. AS20940 ae3.r02.ord01.icn.netarch.akamai.com (23.32.63.28) 25.0% 100 228.3 228.4 228.1 236.5 1.0
15. AS20940 ae3.r01.lga01.icn.netarch.akamai.com (23.32.63.4) 0.0% 100 237.8 269.1 228.4 406.0 49.7
16. AS20940 ae3.r01.ewr01.icn.netarch.akamai.com (23.32.63.61) 0.0% 100 226.0 226.5 225.8 241.9 2.1
17. AS20940 ae1.r02.ewr01.ien.netarch.akamai.com (23.203.154.37) 0.0% 100 232.7 232.8 232.6 239.2 0.7
18. AS20940 a23-203-154-43.deploy.static.akamaitechnologies.com (23.203.154.43) 0.0% 100 231.0 257.5 230.4 361.2 32.2
19. AS??? ??? 100.0 100 0.0 0.0 0.0 0.0 0.0
20. AS??? ??? 100.0 100 0.0 0.0 0.0 0.0 0.0
21. AS??? ??? 100.0 100 0.0 0.0 0.0 0.0 0.0
22. AS63949 mail.domain.com (69.164.210.61) 38.0% 100 227.4 227.7 227.1 232.4 1.0

Their answer after i provided the logs was:

“Taking a look at the results, there is both some packet loss and latency at different points along the route, although your traffic does seem to make it to the destination. This packet loss may be causing the sync and connection issues that you’re seeing, however, we are unable to influence the route your traffic takes outside of our own network.”

And i went back looking at Mailcow logs and i found some related to SSL which might be an issue but still confused how to proceed from now on.

Dovecot logs:

mailcowdockerized-dovecot-mailcow-1 | Nov 21 22:32:59 
951b0a83c51e dovecot: imap-login: Disconnected: Connection closed: 
SSL_accept() failed: error:14209102:SSL routines:tls_early_post_process_client_hello:unsupported protocol 
(no auth attempts in 0 secs): user=<>, rip=106.75.98.199, lip=172.22.1.250, 
TLS handshaking: SSL_accept() failed: error:14209102:SSL routines:tls_early_post_process_client_hello:unsupported protocol

mailcowdockerized-dovecot-mailcow-1 | Nov 21 22:33:01 
951b0a83c51e dovecot: imap-login: Disconnected: Connection closed: 
SSL_accept() failed: error:142090C1:SSL routines:tls_early_post_process_client_hello:no shared cipher 
(no auth attempts in 0 secs): user=<>, rip=106.75.98.199, lip=172.22.1.250, 
TLS handshaking: SSL_accept() failed: error:142090C1:SSL routines:tls_early_post_process_client_hello:no shared cipher

mailcowdockerized-dovecot-mailcow-1 | Nov 21 22:33:01 
951b0a83c51e dovecot: imap-login: Disconnected: Connection closed: 
SSL_accept() failed: error:141CF06C:SSL routines:tls_parse_ctos_key_share:bad key share 
(no auth attempts in 0 secs): user=<>, rip=106.75.98.199, lip=172.22.1.250, 
TLS handshaking: SSL_accept() failed: error:141CF06C:SSL routines:tls_parse_ctos_key_share:bad key share

...

mailcowdockerized-dovecot-mailcow-1 | Nov 22 04:31:30 
951b0a83c51e dovecot: imap-login: Disconnected: Connection closed: 
SSL_accept() failed: error:1408F10B:SSL routines:ssl3_get_record:wrong version number 
(no auth attempts in 0 secs): user=<>, rip=103.79.111.71, lip=172.22.1.250, 
TLS handshaking: SSL_accept() failed: error:1408F10B:SSL routines:ssl3_get_record:wrong version number

Any idea how to proceed from here?

Thank you!

DocFraggle

irdi Hi, it looks like this is an issue about TLS version and/or ciphers being used, so that the client isn’t able to establish a secure connection. Maybe check the available SSL/TLS versions on your Nextcloud installation? Maybe you are enforcing TLS 1.3 which the Nextcloud server isn’t capable yet?

TLS handshaking: SSL_accept() failed: error:1408F10B:SSL routines:ssl3_get_record:wrong version number

irdi

DocFraggle Indeed Nextcloud is using TLS 1.3 but this error happens only once a day. It is not something constant. I will try to remove TLS 1.3 enforcing and see what happens.

Thank you!

irdi

DocFraggle I checked the config once again and it seems alright.

SSLProtocol             -all +TLSv1.2 +TLSv1.3

Im stuck but ill let you know when i figure it out.

irdi

I came up with another error on the logs of one of the users who is having the problem.

DEBUG: .../IO/Socket/SSL.pm:1177: global error: Undefined SSL object
Still lookng for a solution to this..