postfix logs show dodgy connections

Question

I have regular connections from an IP that appears in OpenBL list and I would like to understand what it does.

If it failed at authentication phase, I would get auth errors (and he would be banned by fail2ban).

If it succeeded in sending messages, I would see log lines about messages being delivered.

Before doing anything, I'd like to understand what is happening.

Here's a log in double verbose mode (-v -v):

Jun 19 16:27:21 localhost postfix/smtpd[12172]: name_mask: all
Jun 19 16:27:21 localhost postfix/smtpd[12172]: inet_addr_local: configured 2 IPv4 addresses
Jun 19 16:27:21 localhost postfix/smtpd[12172]: inet_addr_local: configured 3 IPv6 addresses
Jun 19 16:27:21 localhost postfix/smtpd[12172]: process generation: 730 (730)
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: mynetworks ~? debug_peer_list
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: mynetworks ~? fast_flush_domains
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: mynetworks ~? mynetworks
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: relay_domains ~? debug_peer_list
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: relay_domains ~? fast_flush_domains
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: relay_domains ~? mynetworks
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: relay_domains ~? permit_mx_backup_networks
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: relay_domains ~? qmqpd_authorized_clients
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: relay_domains ~? smtpd_access_maps
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_list_match: relay_domains: no match
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: permit_mx_backup_networks ~? debug_peer_list
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: permit_mx_backup_networks ~? fast_flush_domains
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: permit_mx_backup_networks ~? mynetworks
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: permit_mx_backup_networks ~? permit_mx_backup_networks
Jun 19 16:27:21 localhost postfix/smtpd[12172]: connect to subsystem private/proxymap
Jun 19 16:27:21 localhost postfix/smtpd[12172]: send attr request = open
Jun 19 16:27:21 localhost postfix/smtpd[12172]: send attr table = unix:passwd.byname
Jun 19 16:27:21 localhost postfix/smtpd[12172]: send attr flags = 0
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/proxymap socket: wanted attribute: status
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: status
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute value: 0
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/proxymap socket: wanted attribute: flags
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: flags
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute value: 16
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/proxymap socket: wanted attribute: (list terminator)
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: (end)
Jun 19 16:27:21 localhost postfix/smtpd[12172]: dict_proxy_open: connect to map=unix:passwd.byname status=0 server_flags=fixed
Jun 19 16:27:21 localhost postfix/smtpd[12172]: dict_open: proxy:unix:passwd.byname
Jun 19 16:27:21 localhost postfix/smtpd[12172]: Compiled against Berkeley DB: 5.1.29?
Jun 19 16:27:21 localhost postfix/smtpd[12172]: Run-time linked against Berkeley DB: 5.1.29?
Jun 19 16:27:21 localhost postfix/smtpd[12172]: dict_open: hash:/etc/aliases
Jun 19 16:27:21 localhost postfix/smtpd[12172]: Compiled against Berkeley DB: 5.1.29?
Jun 19 16:27:21 localhost postfix/smtpd[12172]: Run-time linked against Berkeley DB: 5.1.29?
Jun 19 16:27:21 localhost postfix/smtpd[12172]: dict_open: hash:/var/lib/mailman/data/aliases
Jun 19 16:27:21 localhost postfix/smtpd[12172]: send attr request = open
Jun 19 16:27:21 localhost postfix/smtpd[12172]: send attr table = pgsql:/etc/postfix/virtual-alias-maps.cf
Jun 19 16:27:21 localhost postfix/smtpd[12172]: send attr flags = 0
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/proxymap socket: wanted attribute: status 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: status 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute value: 0 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/proxymap socket: wanted attribute: flags 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: flags 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute value: 16 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/proxymap socket: wanted attribute: (list terminator) 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: (end) 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: dict_proxy_open: connect to map=pgsql:/etc/postfix/virtual-alias-maps.cf status=0 server_flags=fixed 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: dict_open: proxy:pgsql:/etc/postfix/virtual-alias-maps.cf 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: Compiled against Berkeley DB: 5.1.29? 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: Run-time linked against Berkeley DB: 5.1.29? 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: dict_open: hash:/var/lib/mailman/data/virtual-mailman 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: send attr request = open 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: send attr table = pgsql:/etc/postfix/virtual-mailbox-maps.cf 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: send attr flags = 0 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/proxymap socket: wanted attribute: status 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: status 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute value: 0 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/proxymap socket: wanted attribute: flags 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: flags 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute value: 16 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/proxymap socket: wanted attribute: (list terminator) 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: (end) 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: dict_proxy_open: connect to map=pgsql:/etc/postfix/virtual-mailbox-maps.cf status=0 server_flags=fixed 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: dict_open: proxy:pgsql:/etc/postfix/virtual-mailbox-maps.cf 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: smtpd_access_maps ~? debug_peer_list 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: smtpd_access_maps ~? fast_flush_domains 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: smtpd_access_maps ~? mynetworks 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: smtpd_access_maps ~? permit_mx_backup_networks 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: smtpd_access_maps ~? qmqpd_authorized_clients 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: smtpd_access_maps ~? smtpd_access_maps 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: unknown_helo_hostname_tempfail_action = defer_if_permit 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: unknown_address_tempfail_action = defer_if_permit 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: unverified_recipient_tempfail_action = defer_if_permit 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: unverified_sender_tempfail_action = defer_if_permit 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: name_mask: 0 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: auto_clnt_create: transport=local endpoint=private/tlsmgr 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: auto_clnt_open: connected to private/tlsmgr 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: send attr request = seed 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: send attr size = 32 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/tlsmgr: wanted attribute: status 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: status 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute value: 0 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/tlsmgr: wanted attribute: seed 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: seed 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute value: BkwSErqQCehWb7QFIVoqNQDFcWGDIzh7N7jY0LHfZxM= 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/tlsmgr: wanted attribute: (list terminator) 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: (end) 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: send attr request = policy 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: send attr cache_type = smtpd 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/tlsmgr: wanted attribute: status 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: status 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute value: 0 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/tlsmgr: wanted attribute: cachable 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: cachable 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute value: 1 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/tlsmgr: wanted attribute: (list terminator) 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: (end) 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: fast_flush_domains ~? debug_peer_list 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_string: fast_flush_domains ~? fast_flush_domains 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: auto_clnt_create: transport=local endpoint=private/anvil 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: connection established 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: master_notify: status 0 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: name_mask: resource 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: name_mask: software
Jun 19 16:27:21 localhost postfix/smtpd[12172]: connect from s72-38-252-2.static.datacom.cgocable.net[72.38.252.2] 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_list_match: s72-38-252-2.static.datacom.cgocable.net: no match 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_list_match: 72.38.252.2: no match 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_list_match: s72-38-252-2.static.datacom.cgocable.net: no match 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_list_match: 72.38.252.2: no match 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: smtp_stream_setup: maxtime=300 enable_deadline=0 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_hostname: s72-38-252-2.static.datacom.cgocable.net ~? 127.0.0.0/8 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_hostaddr: 72.38.252.2 ~? 127.0.0.0/8 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_list_match: s72-38-252-2.static.datacom.cgocable.net: no match 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_list_match: 72.38.252.2: no match 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: auto_clnt_open: connected to private/anvil 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: send attr request = connect 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: send attr ident = smtp:72.38.252.2 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/anvil: wanted attribute: status 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: status 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute value: 0 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/anvil: wanted attribute: count 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: count 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute value: 1 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/anvil: wanted attribute: rate 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: rate 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute value: 1 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/anvil: wanted attribute: (list terminator) 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: (end) 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: > s72-38-252-2.static.datacom.cgocable.net[72.38.252.2]: 220 domain.tld ESMTP Postfix (Debian/GNU) 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: xsasl_dovecot_server_create: SASL service=smtp, realm=(null) 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: name_mask: noanonymous 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: xsasl_dovecot_server_connect: Connecting 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: xsasl_dovecot_server_connect: auth reply: VERSION?1?1 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: xsasl_dovecot_server_connect: auth reply: MECH?PLAIN?plaintext 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: name_mask: plaintext 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: xsasl_dovecot_server_connect: auth reply: SPID?11468 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: xsasl_dovecot_server_connect: auth reply: CUID?91 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: xsasl_dovecot_server_connect: auth reply: COOKIE?9df14148adb89ae414e824bc836238da 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: xsasl_dovecot_server_connect: auth reply: DONE 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: xsasl_dovecot_server_mech_filter: keep mechanism: PLAIN 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: < s72-38-252-2.static.datacom.cgocable.net[72.38.252.2]: EHLO User 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_list_match: s72-38-252-2.static.datacom.cgocable.net: no match 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_list_match: 72.38.252.2: no match 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: > s72-38-252-2.static.datacom.cgocable.net[72.38.252.2]: 250-domain.tld 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: > s72-38-252-2.static.datacom.cgocable.net[72.38.252.2]: 250-PIPELINING 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: > s72-38-252-2.static.datacom.cgocable.net[72.38.252.2]: 250-SIZE 10240000 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: > s72-38-252-2.static.datacom.cgocable.net[72.38.252.2]: 250-ETRN 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: > s72-38-252-2.static.datacom.cgocable.net[72.38.252.2]: 250-STARTTLS 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: > s72-38-252-2.static.datacom.cgocable.net[72.38.252.2]: 250-AUTH PLAIN 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: > s72-38-252-2.static.datacom.cgocable.net[72.38.252.2]: 250-ENHANCEDSTATUSCODES 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: > s72-38-252-2.static.datacom.cgocable.net[72.38.252.2]: 250-8BITMIME 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: > s72-38-252-2.static.datacom.cgocable.net[72.38.252.2]: 250 DSN 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: < s72-38-252-2.static.datacom.cgocable.net[72.38.252.2]: QUIT 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: > s72-38-252-2.static.datacom.cgocable.net[72.38.252.2]: 221 2.0.0 Bye 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_hostname: s72-38-252-2.static.datacom.cgocable.net ~? 127.0.0.0/8 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_hostaddr: 72.38.252.2 ~? 127.0.0.0/8 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_list_match: s72-38-252-2.static.datacom.cgocable.net: no match 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: match_list_match: 72.38.252.2: no match 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: send attr request = disconnect 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: send attr ident = smtp:72.38.252.2 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/anvil: wanted attribute: status 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: status 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute value: 0 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: private/anvil: wanted attribute: (list terminator) 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: input attribute name: (end) 
Jun 19 16:27:21 localhost postfix/smtpd[12172]: disconnect from s72-38-252-2.static.datacom.cgocable.net[72.38.252.2]
Jun 19 16:27:21 localhost postfix/smtpd[12172]: master_notify: status 1
Jun 19 16:27:21 localhost postfix/smtpd[12172]: connection closed
Jun 19 16:27:26 localhost postfix/smtpd[12172]: proxymap stream disconnect
Jun 19 16:27:26 localhost postfix/smtpd[12172]: auto_clnt_close: disconnect private/tlsmgr stream

Thanks for any hint.

Answer 1

The remote SMTP client doesn’t even try to authenticate and makes no attempt to send a message. Your log file shows that it simply QUITs after it receives a response to its EHLO User command:

< s72-38-252-2.static.datacom.cgocable.net[72.38.252.2]: EHLO User
...
< s72-38-252-2.static.datacom.cgocable.net[72.38.252.2]: QUIT

I’d suspect that the remote client is checking for something specific in the response to its EHLO command (which should have a fully qualified domain name rather than User). Different SMTP servers respond differently to such commands e.g., your Postfix smtpd indicates that it supports STARTTLS and AUTH PLAIN.

The EHLO command itself is the Extended SMTP extension of the original SMTP HELO command; ESMTP servers respond to it with success (code 250 followed by a list of the server’s capabilities), failure (code 550) or error (code 500, 501, 502, 504, or 421), depending on its configuration.

The remote host may be checking for a specific response that would indicate the potential for an exploit that it could use. If it doesn’t get that indication, it simply gives up.

In my experience that there are wide variations in how "brutish" cracking attempts are; some are more subtle than others (presumably to avoid drawing unwanted attention to themselves).

Rejecting invalid HELO commands

If you’ll be accepting connections from many different SMTP clients, it would be better not to reject invalid EHLO command without a FQDN. I’ve encountered a few SMTP clients (on printer/scanners, old Windows software which include mail functionality, etc.) which did not send correctly formatted, fully-qualified domain names with their HELO/EHLO command. The default Postfix configuration provided by Red Hat Enterprise Linux 5 doesn’t restrict HELO usage or to even require it.

If you know that all legitimate clients will send a valid HELO, it may help to cut down on the processing used to deal with illegitimate attempts (I haven’t tried this myself).