Getmail says: socket error (('_ssl.c:563: The handshake operation timed out',))

NhFan · June 13, 2018, 9:06am

NethServer Version: NethServer release 7.5.1804 (final)
Module: POP3 Connector/ getmail
Kernel: 3.10.0-862.3.2.el7.x86_64

I have configured NS 7.5 to get mails from external mail server via POP3 connector module. I use the protocol settings ‘POP3 with SSL’ for the external mail account. I have installed a Let’sEncrypt Cert to use for SSL/ TLS function.
I mostly receive the mails but sometimes I won’t get a mail message, after a soft restart of NethServer I will receive this missed mail.
I think the reason is the “socket error ((’_ssl.c:563: The handshake operation timed out’,))”. I get this message via mail to root.
How can I debug/ solve this problem?

m.traeumner · June 13, 2018, 10:00am

Could you have a look at the logs for more infos please. I think at

var/log/messages

you could find some errors at the time it happened.

NhFan · June 13, 2018, 11:16am

Hi m.traeumner,
thank you for the reply.
This is my problem- I could not see any hints for this in “/var/log/messages”. In “/var/log/maillog” I can see something like this:

and nothing else like ‘error’ or ‘warning’ or ‘timeout’ from module getmail. But I think this is normal behaviour, isn’t it?
I get this kind of mails for root:

How can I find the cause?
Regards
Mario

giacomo · June 13, 2018, 12:59pm

Execute the command reported inside the mail without the “–quiet” option and check if you can find extra info.

Reading the error, I guess your provider doesn’t provide TLS.

NhFan · June 13, 2018, 1:01pm

I have just seen that there are many files (about 70) with the following names in “/var/lib/getmail/”:
“oldmail-[ext.mailserver]-[port]-[username]”, just like ‘oldmail-xxxx.kasserver.com-995-m12345678’. What is this, is there a relationship between these files and the ssl timeout error?
Normally I find such files here: “[email]@[domain].cfg”, e.g. “name@provider.de.cfg”

NhFan · June 13, 2018, 1:15pm

Thanks giacomo,
I took your advice, here is the result:

Does it matter that I pick up about 70 mailboxes, all at the same time controlled by the cron task every 10 minutes? By reading 70 mailboxes I get about 7 ssl-timeout-errors

NhFan · June 13, 2018, 1:21pm

Sorry, Picture before was without SSL, here is the result with SSL:

NhFan · June 13, 2018, 1:31pm

These are the capabilities of my external mail server:
maillog4

NhFan · June 14, 2018, 8:44am

After further tests I found that some tasks of ‘getmail’ remain active (1 or more):

ps -A |grep getmail
5171 ? 00:00:00 getmail

The cron invokes ‘getmail’ processes for every configured mail user (about 70). This process should be finished after mails have been seen/ retrieved. The next cron job will start after 10 minutes. Is it possible that remaining ‘getmail’ tasks will block the next call of ‘getmail’ for this user?

Furthermore I manually started this command with option ‘–trace’:

/usr/bin/flock -n -E 0 /var/lib/getmail/m.mustermann@ifam-erfurt.de.cfg -c "/usr/bin/getmail --getmaildir /var/lib/getmail/ --rcfile /var/lib/getmail/m.mustermann@ifam-erfurt.de.cfg --trace"

[root@mail ~]# /usr/bin/flock -n -E 0 /var/lib/getmail/m.mustermann@ifam-erfurt.de.cfg -c “/usr/bin/getmail --getmaildir /var/lib/getmail/ --rcfile /var/lib/getmail/m.mustermann@ifam-erfurt.de.cfg --trace”

parsed options: dump_config=“False”,ensure_value=“<bound method Values.ensure_value of <Values at 0x7f5dedeafcf8: {‘trace’: True, ‘override_delete’: None, ‘getmaildir’: ‘/var/lib/getmail/’, ‘idle’: ‘’, ‘override_fingerprint’: None, ‘override_read_all’: None, ‘override_verbose’: None, ‘dump_config’: False, ‘rcfile’: [‘/var/lib/getmail/m.mustermann@ifam-erfurt.de.cfg’]}>>”,getmaildir=“‘/var/lib/getmail/’”,idle=“‘’”,override_delete=“None”,override_fingerprint=“None”,override_read_all=“None”,override_verbose=“None”,rcfile=“[‘/var/lib/getmail/m.mustermann@ifam-erfurt.de.cfg’]”,read_file=“<bound method Values.read_file of <Values at 0x7f5dedeafcf8: {‘trace’: True, ‘override_delete’: None, ‘getmaildir’: ‘/var/lib/getmail/’, ‘idle’: ‘’, ‘override_fingerprint’: None, ‘override_read_all’: None, ‘override_verbose’: None, ‘dump_config’: False, ‘rcfile’: [‘/var/lib/getmail/m.mustermann@ifam-erfurt.de.cfg’]}>>”,read_module=“<bound method Values.read_module of <Values at 0x7f5dedeafcf8: {‘trace’: True, ‘override_delete’: None, ‘getmaildir’: ‘/var/lib/getmail/’, ‘idle’: ‘’, ‘override_fingerprint’: None, ‘override_read_all’: None, ‘override_verbose’: None, ‘dump_config’: False, ‘rcfile’: [‘/var/lib/getmail/m.mustermann@ifam-erfurt.de.cfg’]}>>”,trace=“True”
processing rcfile /var/lib/getmail/m.mustermann@ifam-erfurt.de.cfg
looking for option read_all …
got “false”
→ False

looking for option delete …
got “False”
→ False

looking for option delivered_to …
got “false”
→ False

looking for option received …
got “false”
→ False

looking for option message_log_verbose …
got “False”
→ False

looking for option message_log_syslog …
got “true”
→ True

looking for option fingerprint …
got “False”
→ False

looking for option delete_after …
got “7”
→ 7

looking for option delete_bigger_than …
got “0”
→ 0

looking for option max_message_size …
got “0”
→ 0

looking for option max_messages_per_session …
got “0”
→ 0

looking for option max_bytes_per_session …
got “0”
→ 0

looking for option verbose …
got “1”
→ 1

looking for option message_log …
got “None”
→ None

getting retriever
type=“SimplePOP3SSLRetriever”
parameter username=“user”
parameter password=*
parameter server=“xxxxxx.kasserver.com”
instantiating retriever SimplePOP3SSLRetriever with args configparser=“<ConfigParser.RawConfigParser instance at 0x7f5dedeafd88>”,getmaildir=“/var/lib/getmail/”,password=*,server=“xxxxxx.kasserver.com”,username=“user”
init() [baseclasses.py:285] trace
init() [baseclasses.py:297] setting username to “user” (<type ‘str’>)
init() [baseclasses.py:297] setting configparser to “<ConfigParser.RawConfigParser instance at 0x7f5dedeafd88>” (<type ‘instance’>)
init() [baseclasses.py:294] setting password to * (<type ‘str’>)
init() [baseclasses.py:297] setting getmaildir to “/var/lib/getmail/” (<type ‘str’>)
init() [baseclasses.py:297] setting server to “xxxxxx.kasserver.com” (<type ‘str’>)
checkconf() [baseclasses.py:303] trace
checkconf() [baseclasses.py:308] checking configparser
checkconf() [baseclasses.py:308] checking getmaildir
checkconf() [baseclasses.py:308] checking timeout
checkconf() [baseclasses.py:308] checking server
checkconf() [baseclasses.py:308] checking port
checkconf() [baseclasses.py:308] checking username
checkconf() [baseclasses.py:308] checking password
checkconf() [baseclasses.py:308] checking password_command
checkconf() [baseclasses.py:308] checking use_apop
checkconf() [baseclasses.py:308] checking delete_dup_msgids
checkconf() [baseclasses.py:308] checking keyfile
checkconf() [baseclasses.py:308] checking certfile
checkconf() [baseclasses.py:308] checking ca_certs
checkconf() [baseclasses.py:308] checking ssl_fingerprints
checkconf() [baseclasses.py:308] checking ssl_version
checkconf() [baseclasses.py:308] checking ssl_ciphers
checkconf() [baseclasses.py:308] checking ssl_cert_hostname
checkconf() [baseclasses.py:317] done
init() [_retrieverbases.py:989] trace
str() [retrievers.py:115] trace
checking retriever configuration for SimplePOP3SSLRetriever:user@xxxxxx.kasserver.com:995
checkconf() [baseclasses.py:303] trace
getting destination
type=“MDA_external”
parameter group=“vmail”
parameter user=“vmail”
parameter path=“/usr/libexec/dovecot/dovecot-lda”
parameter arguments=“(”-e",“-d”,"m.mustermann@ifam-erfurt.de")"
instantiating destination MDA_external with args arguments=“(”-e",“-d”,"m.mustermann@ifam-erfurt.de")“,configparser=”<ConfigParser.RawConfigParser instance at 0x7f5dedeafd88>“,group=“vmail”,path=”/usr/libexec/dovecot/dovecot-lda",user=“vmail”
init() [baseclasses.py:285] trace
init() [baseclasses.py:297] setting path to “/usr/libexec/dovecot/dovecot-lda” (<type ‘str’>)
init() [baseclasses.py:297] setting user to “vmail” (<type ‘str’>)
init() [baseclasses.py:297] setting group to “vmail” (<type ‘str’>)
init() [baseclasses.py:297] setting arguments to “(”-e",“-d”,"m.mustermann@ifam-erfurt.de")" (<type ‘str’>)
init() [baseclasses.py:297] setting configparser to “<ConfigParser.RawConfigParser instance at 0x7f5dedeafd88>” (<type ‘instance’>)
checkconf() [baseclasses.py:303] trace
checkconf() [baseclasses.py:308] checking configparser
checkconf() [baseclasses.py:308] checking path
checkconf() [baseclasses.py:308] checking arguments
checkconf() [baseclasses.py:308] checking user
checkconf() [baseclasses.py:308] checking group
checkconf() [baseclasses.py:308] checking allow_root_commands
checkconf() [baseclasses.py:308] checking unixfrom
checkconf() [baseclasses.py:308] checking ignore_stderr
checkconf() [baseclasses.py:317] done
initialize() [destinations.py:655] trace
init() [destinations.py:85] done
getting filters
processing filter section filter-1
type=“Filter_classifier”
parameter exitcodes_drop=“(1,)”
parameter user=“amavis”
parameter path=“/usr/bin/clamdscan”
parameter arguments=“(”-c", “/etc/clamd.d/amavisd.conf”, “–stdout”, “–no-summary”, “–infected”, “-”)"
instantiating filter Filter_classifier with args arguments=“(”-c", “/etc/clamd.d/amavisd.conf”, “–stdout”, “–no-summary”, “–infected”, “-”)“,configparser=”<ConfigParser.RawConfigParser instance at 0x7f5dedeafd88>“,exitcodes_drop=”(1,)“,path=”/usr/bin/clamdscan",user=“amavis”
init() [baseclasses.py:285] trace
init() [baseclasses.py:297] setting path to “/usr/bin/clamdscan” (<type ‘str’>)
init() [baseclasses.py:297] setting user to “amavis” (<type ‘str’>)
init() [baseclasses.py:297] setting exitcodes_drop to “(1,)” (<type ‘str’>)
init() [baseclasses.py:297] setting arguments to “(”-c", “/etc/clamd.d/amavisd.conf”, “–stdout”, “–no-summary”, “–infected”, “-”)" (<type ‘str’>)
init() [baseclasses.py:297] setting configparser to “<ConfigParser.RawConfigParser instance at 0x7f5dedeafd88>” (<type ‘instance’>)
checkconf() [baseclasses.py:303] trace
checkconf() [baseclasses.py:308] checking path
checkconf() [baseclasses.py:308] checking unixfrom
checkconf() [baseclasses.py:308] checking arguments
checkconf() [baseclasses.py:308] checking exitcodes_keep
checkconf() [baseclasses.py:308] checking exitcodes_drop
checkconf() [baseclasses.py:308] checking user
checkconf() [baseclasses.py:308] checking group
checkconf() [baseclasses.py:308] checking allow_root_commands
checkconf() [baseclasses.py:308] checking ignore_header_shrinkage
checkconf() [baseclasses.py:308] checking ignore_stderr
checkconf() [baseclasses.py:308] checking configparser
checkconf() [baseclasses.py:317] done
initialize() [filters.py:184] trace
init() [filters.py:70] done
processing filter section filter-2
type=“Filter_external”
parameter group=“amavis”
parameter user=“amavis”
parameter path=“/usr/bin/spamc”
parameter exitcodes_keep=“(0, 1)”
parameter arguments=“(”-E", “-s”, “250000”)"
instantiating filter Filter_external with args arguments=“(”-E", “-s”, “250000”)“,configparser=”<ConfigParser.RawConfigParser instance at 0x7f5dedeafd88>“,exitcodes_keep=”(0, 1)“,group=“amavis”,path=”/usr/bin/spamc",user=“amavis”
init() [baseclasses.py:285] trace
init() [baseclasses.py:297] setting group to “amavis” (<type ‘str’>)
init() [baseclasses.py:297] setting arguments to “(”-E", “-s”, “250000”)" (<type ‘str’>)
init() [baseclasses.py:297] setting path to “/usr/bin/spamc” (<type ‘str’>)
init() [baseclasses.py:297] setting configparser to “<ConfigParser.RawConfigParser instance at 0x7f5dedeafd88>” (<type ‘instance’>)
init() [baseclasses.py:297] setting exitcodes_keep to “(0, 1)” (<type ‘str’>)
init() [baseclasses.py:297] setting user to “amavis” (<type ‘str’>)
checkconf() [baseclasses.py:303] trace
checkconf() [baseclasses.py:308] checking path
checkconf() [baseclasses.py:308] checking unixfrom
checkconf() [baseclasses.py:308] checking arguments
checkconf() [baseclasses.py:308] checking exitcodes_keep
checkconf() [baseclasses.py:308] checking exitcodes_drop
checkconf() [baseclasses.py:308] checking user
checkconf() [baseclasses.py:308] checking group
checkconf() [baseclasses.py:308] checking allow_root_commands
checkconf() [baseclasses.py:308] checking ignore_header_shrinkage
checkconf() [baseclasses.py:308] checking ignore_stderr
checkconf() [baseclasses.py:308] checking configparser
checkconf() [baseclasses.py:317] done
initialize() [filters.py:184] trace
init() [filters.py:70] done
getmail version 5.5
Copyright (C) 1998-2012 Charles Cazabon. Licensed under the GNU GPL version 2.
str() [retrievers.py:115] trace
SimplePOP3SSLRetriever:user@xxxxxx.kasserver.com:995:
str() [retrievers.py:115] trace
initialize() [_retrieverbases.py:1114] trace
initialize() [_retrieverbases.py:919] trace
checkconf() [baseclasses.py:303] trace
_connect() [_retrieverbases.py:330] trace
_connect() [_retrieverbases.py:382] establishing POP3 SSL connection to xxxxxx.kasserver.com:995
_connect() [_retrieverbases.py:448] POP3 SSL connection <poplib.POP3_SSL instance at 0x7f5dedc0d7a0> established with fingerprint 9f06737b2f34faac568e340c0265467715fe5f8dbbc1204df4d92271eadf7990 using cipher ECDHE-RSA-AES128-GCM-SHA256:TLSv1/SSLv3:128
_getmsglist() [retrieverbases.py:1013] trace
UIDL response “+OK”, 0 octets
Message IDs: []
msgids: []
msgsizes: {}
retriever_info() [destinations.py:88] trace
read_oldmailfile() [retrieverbases.py:847] mailbox=None__str() [retrievers.py:115] trace
read 0 uids for SimplePOP3SSLRetriever:user@xxxxxx.kasserver.com:995:
read 0 uids in total for SimplePOP3SSLRetriever:user@xxxxxx.kasserver.com:995:
_getmsglist() [_retrieverbases.py:1013] trace
UIDL response “+OK”, 0 octets
Message IDs:
len() [_retrieverbases.py:810] trace
getitem() [retrieverbases.py:814] i == 0 0 messages (0 bytes) retrieved, 0 skipped
str() [retrievers.py:115] trace
retriever SimplePOP3SSLRetriever:user@xxxxxx.kasserver.com:995 finished
write_oldmailfile() [retrieverbases.py:888] mailbox=None__str() [retrievers.py:115] trace
wrote 0 uids for SimplePOP3SSLRetriever:user@xxxxxx.kasserver.com:995:
quit() [_retrieverbases.py:1176] trace
[root@mail ~]#

The SSL connection does not appear to be faulty. But I try to get a trace log for a ‘getmail’ process with an error result (SSL handshake operation timed out).
What else can I do?
Regards
Mario