Topic: mail server not accepting email from certain addresses

[henry44]

Version and add-ons
SME 9.2
dehydrated certificate manager add-on

Email from a few addresses have stopped being accepted by the SME mail server. The sender gets some version of this email after a while.

-------- Forwarded Message --------
Subject:   Returned mail: see transcript for details
Date:   Mon, 13 Jul 2020 12:29:36 -0700
From:   postmaster <postmaster@junctioncity.k12.or.us>
To:   kroddennord@junctioncity.k12.or.us

The original message was received at Fri, 10 Jul 2020 09:55:56 -0700
from:
<kroddennord@junctioncity.k12.or.us>

----- The following addresses had permanent fatal errors -----
<jcea-pres@mrlistersir.com>

----- Transcript of session follows -----
451 4.4.1 reply: read error from mail.mrlistersir.com.
<jcea-pres@mrlistersir.com>... Deferred: Connection timed out with mail.mrlistersir.com.
Message could not be delivered for 3 days
Message will be deleted from queue

I've looked at the mail logs, but they seem to be documenting sent mail, not received mail.
Email from other addresses appears to be delivered in a reasonable time.

My experience with addresses with permanent fatal errors is usually a mis-spelling or the server isn't online. I've tested sending mail to two different addresses in the mrlistersir.com domain from an affected email address and had a failed delivery each time, even though the mrlistersir.com server was online (I was sitting next to it).

Could there be some list of email addresses that are being rejected? Where would I start looking? What log files might be useful?

[ReetP]

Check

Code: [Select]

tail -f /var/log/qpsmtpd/current

[henry44]

Thanks for your help. I did as you suggested, but am not experienced enough to know what I'm looking for.
I don't want to ask for help that I can learn to do for myself, so is there an information source that I can look at that will help me? I'll then do what I can and come back when I'm smart enough to ask better questions.

In case it's helpful, here is what the IT manager of the sending organization sent the person helping me. I'm trying to get the screenshot.

"This address isn't being treated in any particular way from within
our mail filter (see screenshot) - I am not sure how mail is hosted for
@mrlistersir.com but it is likely a result of earlier bad behavior from the
system.
If they can provide our mail gateway name (fortimail.lesd.k12.or.us) or IP
(163.41.62.10) and ask the mail provider to either whitelist it or remove it
from whatever deferral/delay policy it may have ended up on, it will resolve
the problem, but there is nothing LESD can do to affect this behavior from our
side."

[ReetP]

Thanks for your help. I did as you suggested, but am not experienced enough to know what I'm looking for.
I don't want to ask for help that I can learn to do for myself, so is there an information source that I can look at that will help me? I'll then do what I can and come back when I'm smart enough to ask better questions.

A good read of the wiki will help.

A good read of qpsmtpd on the forums too. The more you read the more you will understand.

Also look for grep and tai64nlocal and 'Pipes'

Like this:

Code: [Select]

cat /var/log/qpsmtpd/current |grep 30142| tai64nlocal

In case it's helpful, here is what the IT manager of the sending organization sent the person helping me. I'm trying to get the screenshot.

"This address isn't being treated in any particular way from within
our mail filter (see screenshot) - I am not sure how mail is hosted for
@mrlistersir.com but it is likely a result of earlier bad behavior from the
system.
If they can provide our mail gateway name (fortimail.lesd.k12.or.us) or IP
(163.41.62.10) and ask the mail provider to either whitelist it or remove it
from whatever deferral/delay policy it may have ended up on, it will resolve
the problem, but there is nothing LESD can do to affect this behavior from our
side."

Most likely they have been spamming somewhere and the block lists on your server have caught them out.

Checking the logs

First, have we got a record of a connection from their server?

grep -rn "k12.or.us" /var/log/qpsmtpd/*

Probably a lot of goobledygook - but it all means something.

A sample on mine looking for outlook.com

Code: [Select]

/var/log/qpsmtpd/current:@400000005f0de74c208a2594 22387 Accepted connection 0/40 from 40.107.10.120 / mail-eopbgr100120.outbound.protection.outlook.com

We want 22387 as that is the transaction ID and we can search again for that

grep -rn 22387 /var/log/qpsmtpd/current

That gives us the record for ONE connection for an email.

Here's the start

Code: [Select]

22387 Accepted connection 0/40 from 40.107.10.120 / mail-eopbgr100120.outbound.protection.outlook.com
Blah blah

Code: [Select]

11518:@400000005f0de75f304e728c 22387 Lost connection to client, cannot send response.
11519:@400000005f0de75f304e7e44 22387 click, disconnecting
So - now we can fid a record why was it blcoked. deby reveals all.

Here's is someone we don't like from Russia (I block a lot of countries entirely)

Code: [Select]

9767:@400000005f0dbdb2024e2044 13699 Accepted connection 0/40 from 77.40.3.134 / 134.3.dialup.mari-el.ru
9768:@400000005f0dbdb20253350c 13699 Connection from 134.3.dialup.mari-el.ru [77.40.3.134]
9769:@400000005f0dbdb32c159754 13699 (connect) earlytalker: pass, not spontaneous
9770:@400000005f0dbdb32c2ec0bc 13699 (connect) relay: skip, no match
9771:@400000005f0dbdb3325bf9b4 13699 (connect) check_badcountries: GeoIP RemoteIP: 77.40.3.134
9772:@400000005f0dbdb3325c0184 13699 (connect) check_badcountries: GeoIP City: Yoshkar-Ola
9773:@400000005f0dbdb3325c056c 13699 (connect) check_badcountries: GeoIP Country: RU
9774:@400000005f0dbdb3326e8f84 13699 (deny) logging::logterse: ` 77.40.3.134 134.3.dialup.mari-el.ru check_badcountries 901 Country is on Blocked List msg denied before queued
9775:@400000005f0dbdb3326fb094 13699 550 Country is on Blocked List
9776:@400000005f0dbdb33271df2c 13699 click, disconnecting
9777:@400000005f0dbdb33837fd9c 3776 cleaning up after 13699

(deny) logging::logterse    check_badcountries   901   Country is on Blocked List

Here's a different one

(deny) logging::logterse: ` 192.30.252.202   Unknown   out-19.smtp.github.com         naughty   903   (helo) error getting reverse DNS for 192.30.252.202

And a another

(deny) logging::logterse: ` 51.161.93.239   disadvantage.50secextrakind.top   disadvantage.50secextrakind.top   naughty   901   (dnsbl) https://www.spamhaus.org/sbl/query/SBLCSS   

So, go and have a look through your qpsmtpd logs and try to find their emails.

The we can look at WHY they were blocked, and then whether or not you want to whitelist them, and how.

[henry44]

Hi, I'm back.

I've been reading this:

https://wiki.contribs.org/Mail_log_file_analysis#View_log_files

and followed the directions to view the log file through the SME server manager portal:

In order to view only these one-line-per-message summaries from the qpsmtpd log:

Select View log files in server-manager
Specify qpsmtpd/current (or another qpsmtpd log file) under Choose a log file to view
Specify ` (a single back-tick) under "Filter Pattern (optional)"
Click Next
Sample results are shown below
hopefully you will actually have some real email arriving at your server (not all dnsbl entries as shown here)
results are <tab> delimited, so you can easily Copy and Paste Special / Text into Excel for further analysis

Here is the output I have questions about. This came from the last column of output for the a different
email address in question.

No, score=-2.1 required=4.0 autolearn=disable

I am guessing that the autolearn=disable could be a problem. Any info on what this all means?

[henry44]

Ok, now I'm confused about another issue.

I did this:
grep -rn "k12.or.us" /var/log/qpsmtpd/*

That returned a bunch of log entries where the connection was accepted.

I then did:
grep -rn "k12.or.us" /var/log/qpsmtpd/current

That also returned what I assume to be the most recent log entries indicating that a connection was accepted.

Here is where I'm confused.

If I look at /var/log/qpsmtpd/current in the SME server manager, there are no entries for the k12.or.us domain.

Why are the logs different?

The server manager versions easier for me to navigate around in so I'd like to use it if possible.

[henry44]

Ok, now I'm confused about another issue.

I did this:
grep -rn "k12.or.us" /var/log/qpsmtpd/*

That returned a bunch of log entries where the connection was accepted.

I then did:
grep -rn "k12.or.us" /var/log/qpsmtpd/current

That also returned what I assume to be the most recent log entries indicating that a connection was accepted.

Here is where I'm confused.

If I look at /var/log/qpsmtpd/current in the SME server manager, there are no entries for the k12.or.us domain.

Why are the logs different?

The server manager versions easier for me to navigate around in so I'd like to use it if possible.

Ignore this bit. I sorted it out.

Filtering the /var/log/qpsmtpd/current log for "k12.or.us" returns several of these entries:

2020-07-14 12:59:59.736908500 8182 Accepted connection 0/40 from 163.41.62.10 / fortimail.lesd.k12.or.us
2020-07-14 12:59:59.736983500 8182 Connection from fortimail.lesd.k12.or.us [163.41.62.10]

Here is the most recent bounce message from the affected email address.

  **********************************************
    **      THIS IS A WARNING MESSAGE ONLY      **
    **  YOU DO NOT NEED TO RESEND YOUR MESSAGE  **
    **********************************************

The original message was received at Mon, 13 Jul 2020 22:20:11 -0700
from:
<kgillowwiles@junctioncity.k12.or.us>

   ----- Transcript of session follows -----
451 4.4.1 reply: read error from mail.mrlistersir.com.
<henry@mrlistersir.com>... Deferred: Connection timed out with mail.mrlistersir.com.
Warning: message still undelivered after 2 hours
Will keep trying until message is 3 days old
Reporting-MTA: dns; fortimail.lesd.k12.or.us
Arrival-Date: Mon, 13 Jul 2020 22:20:11 -0700

Final-Recipient: RFC822; henry@mrlistersir.com
Action: delayed
Status: 4.4.2
Last-Attempt-Date: Tue, 14 Jul 2020 02:35:30 -0700
Will-Retry-Until: Thu, 16 Jul 2020 22:20:11 -0700

From my untrained thinking, it looks like the connection was accepted, but the actual email wasn't delivered.

[ReetP]

Getting there.

It's not getting through but we need to find out why (sending end keeps trying to resend a while as it should)

2020-07-14 12:59:59.736908500 8182 Accepted connection 0/40 from 163.41.62.10 / fortimail.lesd.k12.or.us


Cool. That's a transaction so filter or grep 8182 and you should get the individual transaction.

Lets see what it says.

[henry44]

Here is the output from the server manager.

View log files
/var/log/qpsmtpd/current: Viewed at Tue 14 Jul 2020 02:42:03 PM PDT.
Displaying lines matching: "8182".

2020-07-14 14:35:10.404895500 9554 in config(loglevel)
2020-07-14 14:35:10.404895500 9554 config(loglevel): hook returned (0,)
2020-07-14 14:35:10.404994500 9554 dispatching AUTH LOGIN
2020-07-14 14:35:10.405005500 9554 (unrecognized_command) running plugin: tls
2020-07-14 14:35:10.405061500 9554 Plugin tls, hook unrecognized_command returned DECLINED,
2020-07-14 14:35:10.405062500 9554 (unrecognized_command) running plugin: count_unrecognized_commands
2020-07-14 14:35:10.405112500 9554 (unrecognized_command) count_unrecognized_commands: 'auth', (1)
2020-07-14 14:35:10.405123500 9554 Plugin count_unrecognized_commands, hook unrecognized_command returned DECLINED,
2020-07-14 14:35:10.405168500 9554 500 Unrecognized command

[ReetP]

Hmmm.... no that is for 9554

Try grepping in a terminal

Code: [Select]

grep 8182 /var/log/qpsmtpd/current

[henry44]

I sent another email from the problem address and looked at the /var/log/qpsmtpd/current log.

View log files
/var/log/qpsmtpd/current: Viewed at Tue 14 Jul 2020 03:06:22 PM PDT.
Displaying lines matching: "k12.or.us".

2020-07-14 15:01:32.143606500 9785 Accepted connection 0/40 from 163.41.62.10 / fortimail.lesd.k12.or.us
2020-07-14 15:01:32.143672500 9785 Connection from fortimail.lesd.k12.or.us [163.41.62.10]
2020-07-14 15:01:36.810904500 9787 Accepted connection 2/40 from 163.41.62.10 / fortimail.lesd.k12.or.us
2020-07-14 15:01:36.810973500 9787 Connection from fortimail.lesd.k12.or.us [163.41.62.10]

I then filtered for 9785.

2020-07-14 15:01:32.143606500 9785 Accepted connection 0/40 from 163.41.62.10 / fortimail.lesd.k12.or.us
2020-07-14 15:01:32.143672500 9785 Connection from fortimail.lesd.k12.or.us [163.41.62.10]
2020-07-14 15:01:32.143967500 9785 in config(plugins)
2020-07-14 15:01:32.143985500 9785 config(plugins): hook returned (0,)
2020-07-14 15:01:32.145560500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.145561500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.146815500 9785 Loading hosts_allow from /usr/share/qpsmtpd/plugins/hosts_allow
2020-07-14 15:01:32.146922500 9785 hosts_allow hooking pre-connection
2020-07-14 15:01:32.147064500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.147065500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.147862500 9785 Loading peers from /usr/share/qpsmtpd/plugins/peers
2020-07-14 15:01:32.147873500 9785 in config(peers/0)
2020-07-14 15:01:32.147885500 9785 config(peers/0): hook returned (0,)
2020-07-14 15:01:32.148124500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.148124500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.173252500 9785 (init) peers: Loading tls ssl/cert.pem ssl/cert.pem ssl/cert.pem ssl/dhparam.pem from /usr/share/qpsmtpd/plugins/tls
2020-07-14 15:01:32.174593500 9785 (init) peers: Loading auth/auth_cvm_unix_local cvm_socket /var/lib/cvm/cvm-unix-local.socket enable_smtp no enable_ssmtp yes from /usr/share/qpsmtpd/plugins/auth/auth_cvm_unix_local
2020-07-14 15:01:32.175559500 9785 (init) peers: Loading earlytalker from /usr/share/qpsmtpd/plugins/earlytalker
2020-07-14 15:01:32.175917500 9785 (init) peers: Loading bogus_bounce from /usr/share/qpsmtpd/plugins/bogus_bounce
2020-07-14 15:01:32.176361500 9785 (init) peers: Loading count_unrecognized_commands 4 from /usr/share/qpsmtpd/plugins/count_unrecognized_commands
2020-07-14 15:01:32.177637500 9785 (init) peers: Loading relay from /usr/share/qpsmtpd/plugins/relay
2020-07-14 15:01:32.179122500 9785 (init) peers: Loading helo policy lenient reject naughty from /usr/share/qpsmtpd/plugins/helo
2020-07-14 15:01:32.181827500 9785 (init) peers: Loading resolvable_fromhost from /usr/share/qpsmtpd/plugins/resolvable_fromhost
2020-07-14 15:01:32.185853500 9785 (init) peers: Loading headers from /usr/share/qpsmtpd/plugins/headers
2020-07-14 15:01:32.186389500 9785 (init) peers: Loading loadcheck max_load 7 from /usr/share/qpsmtpd/plugins/loadcheck
2020-07-14 15:01:32.187105500 9785 (init) peers: Loading rhsbl from /usr/share/qpsmtpd/plugins/rhsbl
2020-07-14 15:01:32.188462500 9785 (init) peers: Loading sender_permitted_from reject 1 no_dmarc_policy 0 from /usr/share/qpsmtpd/plugins/sender_permitted_from
2020-07-14 15:01:32.190480500 9785 (init) peers: Loading dkim reject 0 from /usr/share/qpsmtpd/plugins/dkim
2020-07-14 15:01:32.192315500 9785 (init) peers: Loading dmarc reject 0 reporting 1 from /usr/share/qpsmtpd/plugins/dmarc
2020-07-14 15:01:32.193168500 9785 (init) peers: Loading dnsbl reject naughty from /usr/share/qpsmtpd/plugins/dnsbl
2020-07-14 15:01:32.193669500 9785 (init) peers: Loading naughty reject mail from /usr/share/qpsmtpd/plugins/naughty
2020-07-14 15:01:32.194172500 9785 (init) peers: Loading badmailfrom from /usr/share/qpsmtpd/plugins/badmailfrom
2020-07-14 15:01:32.194818500 9785 (init) peers: Loading badrcptto more_badrcptto badrcptto_ext from /usr/share/qpsmtpd/plugins/badrcptto
2020-07-14 15:01:32.195338500 9785 (init) peers: Loading check_goodrcptto extn - from /usr/share/qpsmtpd/plugins/check_goodrcptto
2020-07-14 15:01:32.195900500 9785 (init) peers: Loading rcpt_ok from /usr/share/qpsmtpd/plugins/rcpt_ok
2020-07-14 15:01:32.196427500 9785 (init) peers: Loading virus/pattern_filter check=patterns action=deny from /usr/share/qpsmtpd/plugins/virus/pattern_filter
2020-07-14 15:01:32.237485500 9785 (init) peers: Loading tnef2mime from /usr/share/qpsmtpd/plugins/tnef2mime
2020-07-14 15:01:32.239770500 9785 (init) peers: Loading spamassassin reject_threshold 12 from /usr/share/qpsmtpd/plugins/spamassassin
2020-07-14 15:01:32.241450500 9785 (init) peers: Loading virus/clamdscan scan_all yes clamd_socket /var/clamav/clamd.socket defer_on_error yes max_size 25000 from /usr/share/qpsmtpd/plugins/virus/clamdscan
2020-07-14 15:01:32.242173500 9785 (init) peers: Loading queue/qmail-queue from /usr/share/qpsmtpd/plugins/queue/qmail-queue
2020-07-14 15:01:32.242251500 9785 peers hooking valid_auth
2020-07-14 15:01:32.242261500 9785 peers hooking set_hooks
2020-07-14 15:01:32.242371500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.242372500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.242541500 9785 in config(tls_ciphers)
2020-07-14 15:01:32.242541500 9785 config(tls_ciphers): hook returned (0,)
2020-07-14 15:01:32.242661500 9785 in config(tls_protocols)
2020-07-14 15:01:32.242661500 9785 config(tls_protocols): hook returned (0,)
2020-07-14 15:01:32.242785500 9785 tls: ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2020-07-14 15:01:32.243915500 9785 tls hooking connect
2020-07-14 15:01:32.243926500 9785 tls hooking ehlo
2020-07-14 15:01:32.243972500 9785 tls hooking helo
2020-07-14 15:01:32.243985500 9785 tls hooking rcpt
2020-07-14 15:01:32.244032500 9785 tls hooking mail
2020-07-14 15:01:32.244032500 9785 tls hooking data
2020-07-14 15:01:32.244100500 9785 tls hooking post-connection
2020-07-14 15:01:32.244110500 9785 tls hooking unrecognized_command
2020-07-14 15:01:32.244190500 9785 (set_hooks) running plugin: peers
2020-07-14 15:01:32.244289500 9785 in config(peers/0)
2020-07-14 15:01:32.244290500 9785 config(peers/0): hook returned (0,)
2020-07-14 15:01:32.244527500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.244527500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.244637500 9785 in config(peers/0)
2020-07-14 15:01:32.244637500 9785 config(peers/0): hook returned (0,)
2020-07-14 15:01:32.244847500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.244847500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.245102500 9785 peers hooking valid_auth
2020-07-14 15:01:32.245109500 9785 peers hooking set_hooks
2020-07-14 15:01:32.245161500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.245162500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.245342500 9785 logging::logterse hooking queue
2020-07-14 15:01:32.245386500 9785 logging::logterse hooking deny
2020-07-14 15:01:32.245406500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.245419500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.245525500 9785 in config(tls_ciphers)
2020-07-14 15:01:32.245538500 9785 config(tls_ciphers): hook returned (0,)
2020-07-14 15:01:32.245610500 9785 in config(tls_protocols)
2020-07-14 15:01:32.245623500 9785 config(tls_protocols): hook returned (0,)
2020-07-14 15:01:32.245698500 9785 tls: ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2020-07-14 15:01:32.246351500 9785 tls hooking connect
2020-07-14 15:01:32.246376500 9785 tls hooking ehlo
2020-07-14 15:01:32.246395500 9785 tls hooking helo
2020-07-14 15:01:32.246428500 9785 tls hooking rcpt
2020-07-14 15:01:32.246448500 9785 tls hooking mail
2020-07-14 15:01:32.246467500 9785 tls hooking data
2020-07-14 15:01:32.246496500 9785 tls hooking post-connection
2020-07-14 15:01:32.246516500 9785 tls hooking unrecognized_command
2020-07-14 15:01:32.246542500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.246556500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.246781500 9785 auth::auth_cvm_unix_local: skip: enable_smtp=no
2020-07-14 15:01:32.246799500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.246812500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.247016500 9785 earlytalker hooking connect
2020-07-14 15:01:32.247037500 9785 earlytalker hooking data
2020-07-14 15:01:32.247060500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.247073500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.247235500 9785 bogus_bounce hooking data_post
2020-07-14 15:01:32.247300500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.247314500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.247500500 9785 count_unrecognized_commands hooking unrecognized_command
2020-07-14 15:01:32.247541500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.247555500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.247667500 9785 relay hooking connect
2020-07-14 15:01:32.247767500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.247780500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.248030500 9785 helo hooking helo
2020-07-14 15:01:32.248050500 9785 helo hooking ehlo
2020-07-14 15:01:32.248068500 9785 helo hooking data_post
2020-07-14 15:01:32.248090500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.248104500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.248257500 9785 resolvable_fromhost hooking mail
2020-07-14 15:01:32.248363500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.248376500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.248546500 9785 headers hooking data_post
2020-07-14 15:01:32.248613500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.248627500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.248899500 9785 loadcheck hooking connect
2020-07-14 15:01:32.248923500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.248936500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.249079500 9785 rhsbl hooking mail
2020-07-14 15:01:32.249155500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.249169500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.273947500 9785 sender_permitted_from hooking mail
2020-07-14 15:01:32.273960500 9785 sender_permitted_from hooking data_post_headers
2020-07-14 15:01:32.273972500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.274015500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.291232500 9785 dkim hooking data_post_headers
2020-07-14 15:01:32.291243500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.291252500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.374191500 9785 dmarc hooking data_post_headers
2020-07-14 15:01:32.374211500 9785 dmarc hooking data_post
2020-07-14 15:01:32.374259500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.374259500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.374434500 9785 dnsbl hooking connect
2020-07-14 15:01:32.374498500 9785 dnsbl hooking rcpt
2020-07-14 15:01:32.374584500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.374584500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.374813500 9785 naughty hooking data_post
2020-07-14 15:01:32.374823500 9785 naughty: registering hook mail
2020-07-14 15:01:32.374829500 9785 naughty hooking mail
2020-07-14 15:01:32.374875500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.374876500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.375045500 9785 badmailfrom hooking mail
2020-07-14 15:01:32.375116500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.375117500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.375277500 9785 badrcptto hooking rcpt
2020-07-14 15:01:32.375348500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.375348500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.375562500 9785 check_goodrcptto hooking rcpt
2020-07-14 15:01:32.375569500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.375602500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.375741500 9785 rcpt_ok hooking rcpt
2020-07-14 15:01:32.375817500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.375817500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.376016500 9785 virus::pattern_filter hooking data_post
2020-07-14 15:01:32.376040500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.376053500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.376244500 9785 tnef2mime hooking data_post
2020-07-14 15:01:32.376270500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.376283500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.376496500 9785 spamassassin hooking data_post
2020-07-14 15:01:32.376522500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.376535500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.379000500 9785 virus::clamdscan hooking data_post
2020-07-14 15:01:32.379027500 9785 in config(plugin_dirs)
2020-07-14 15:01:32.379042500 9785 config(plugin_dirs): hook returned (0,)
2020-07-14 15:01:32.379229500 9785 queue::qmail_2dqueue hooking queue
2020-07-14 15:01:32.379461500 9785 Plugin peers, hook set_hooks returned DECLINED,
2020-07-14 15:01:32.379520500 9785 (connect) running plugin: tls
2020-07-14 15:01:32.379551500 9785 (connect) tls: skip, not SMTPS
2020-07-14 15:01:32.379578500 9785 Plugin tls, hook connect returned DECLINED,
2020-07-14 15:01:32.379591500 9785 (connect) running plugin: earlytalker
2020-07-14 15:01:33.380782500 9785 (connect) earlytalker: pass, not spontaneous
2020-07-14 15:01:33.380795500 9785 Plugin earlytalker, hook connect returned DECLINED,
2020-07-14 15:01:33.380814500 9785 (connect) running plugin: relay
2020-07-14 15:01:33.380864500 9785 in config(norelayclients)
2020-07-14 15:01:33.380865500 9785 config(norelayclients): hook returned (0,)
2020-07-14 15:01:33.381038500 9785 (connect) relay: no match in norelayclients
2020-07-14 15:01:33.381038500 9785 in config(relayclients)
2020-07-14 15:01:33.381048500 9785 config(relayclients): hook returned (0,)
2020-07-14 15:01:33.381225500 9785 (connect) relay: no cidr match
2020-07-14 15:01:33.381225500 9785 in config(morerelayclients)
2020-07-14 15:01:33.381235500 9785 config(morerelayclients): hook returned (0,)
2020-07-14 15:01:33.381307500 9785 (connect) relay: no octet match
2020-07-14 15:01:33.381308500 9785 (connect) relay: skip, no match
2020-07-14 15:01:33.381328500 9785 Plugin relay, hook connect returned DECLINED,
2020-07-14 15:01:33.381339500 9785 (connect) running plugin: loadcheck
2020-07-14 15:01:33.381433500 9785 (connect) loadcheck: /proc/loadavg reported: 0.27
2020-07-14 15:01:33.381455500 9785 Plugin loadcheck, hook connect returned DECLINED, continuing with load: 0.27
2020-07-14 15:01:33.381462500 9785 (connect) running plugin: dnsbl
2020-07-14 15:01:33.381529500 9785 (connect) dnsbl: RBLSMTPD not set for 163.41.62.10
2020-07-14 15:01:33.381530500 9785 in config(dnsbl_allow)
2020-07-14 15:01:33.381540500 9785 config(dnsbl_allow): hook returned (0,)
2020-07-14 15:01:33.381660500 9785 in config(dnsbl_zones)
2020-07-14 15:01:33.381661500 9785 config(dnsbl_zones): hook returned (0,)
2020-07-14 15:01:33.381837500 9785 (connect) dnsbl: Checking 10.62.41.163.zen.spamhaus.org for TXT record
2020-07-14 15:01:33.687919500 9785 (connect) dnsbl: Checking 10.62.41.163.dnsbl.njabl.org for TXT record
2020-07-14 15:02:04.000102500 9785 (connect) dnsbl: dnsbl.njabl.org query failed:  query timed out
2020-07-14 15:02:04.000114500 9785 (connect) dnsbl: Checking 10.62.41.163.whois.rfc-ignorant.org for TXT record
2020-07-14 15:02:04.095979500 9785 (connect) dnsbl: pass
2020-07-14 15:02:04.096000500 9785 Plugin dnsbl, hook connect returned DECLINED,
2020-07-14 15:02:04.096059500 9785 in config(smtpgreeting)
2020-07-14 15:02:04.096059500 9785 config(smtpgreeting): hook returned (0,)
2020-07-14 15:02:04.096196500 9785 220 larry-server.mrlistersir.com ESMTP
2020-07-14 15:02:04.096227500 9785 in config(timeoutsmtpd)
2020-07-14 15:02:04.096242500 9785 config(timeoutsmtpd): hook returned (0,)
2020-07-14 15:02:04.096409500 9785 DESTROY called by Qpsmtpd::TcpServer, /usr/share/perl5/vendor_perl/Qpsmtpd/TcpServer.pm, 135
2020-07-14 15:02:04.096456500 9785 (post-connection) running plugin: tls
2020-07-14 15:02:04.096507500 9785 Plugin tls, hook post-connection returned DECLINED,
2020-07-14 15:02:04.097361500 9785 DESTROY called by main, /usr/bin/qpsmtpd-forkserver, 0
2020-07-14 15:02:04.834608500 2360 cleaning up after 9785

Seems like there are several lines with the word "decline". Is that part of the issue?

[ReetP]

Hmmm. How odd.

Code: [Select]

Seems like there are several lines with the word "decline". Is that part of the issue?
No. we'd expect to see 'deny' I think.

Have you enabled debugging ? Looks like it.

I think this may be the issue - the sending server giving up the will to live while your server tries a lookup that fails taking 30 seconds or so:

2020-07-14 15:01:33.687919500 9785 (connect) dnsbl: Checking 10.62.41.163.dnsbl.njabl.org for TXT record
2020-07-14 15:02:04.000102500 9785 (connect) dnsbl: dnsbl.njabl.org query failed:  query timed out

Think you have an old or obsolete list.

https://wiki.contribs.org/Email#Real-time_Blackhole_List_.28RBL.29

Run a terminal and please show the output of:

Code: [Select]

config show qpsmtpd

[henry44]

qpsmtpd=service
Bcc=disabled
BccMode=cc
BccUser=maillog
DNSBL=enabled
LogLevel=8
MaxScannerSize=25000000
RBLList=whois.rfc-ignorant.org,dnsbl.njabl.org,zen.spamhaus.org
RHSBL=enabled
RelayRequiresAuth=enabled
SBLList=mulit.surbl.org,black.uribl.com,rhsbl.sorbs.net
TlsBeforeAuth=1
UBLList=mulit.surbl.org:8-16-64-128,black.uribl.com,rhsbl.sorbs.net
URIBL=disabled
access=public
qplogsumm=disabled
status=enabled

[henry44]

i read the wiki. It might be a quick fix, but is it a good idea to add the problem domain to the whitelist?

[ReetP]

i read the wiki. It might be a quick fix, but is it a good idea to add the problem domain to the whitelist?

Nope. Always better to fix it properly.

And whitelisting probably won't actually fix this issue anyway - just create more confusion. Understand the issue, fix it, and then add whitelist if required.

My guess is your list servers are very old and not been updated.

Here are mine on my main server - uceprotect is a bit savage. Hey ho. Don't send junk.

RBLList=bl.spamcop.net,dnsbl-1.uceprotect.net,dnsbl-2.uceprotect.net,psbl.surriel.com,zen.spamhaus.org
SBLList=multi.surbl.org,rhsbl.sorbs.net,dbl.spamhaus.org
UBLList=multi.surbl.org:8-16-64-128,rhsbl.sorbs.net

Make sure you read up about what each one does and that it is functioning correctly.

Note yours:

RBLList=whois.rfc-ignorant.org,dnsbl.njabl.org,zen.spamhaus.org

So something like this - leave out the uce servers if you want:

Code: [Select]

config setprop qpsmtpd RBLList bl.spamcop.net,dnsbl-1.uceprotect.net,dnsbl-2.uceprotect.net,psbl.surriel.com,zen.spamhaus.org
or

Code: [Select]

config setprop qpsmtpd RBLList bl.spamcop.net,psbl.surriel.com,zen.spamhaus.org
Then

Code: [Select]

signal-event email-update
That will remove the problem server 'dnsbl.njabl.org' and I'd guess things will work.

Code: [Select]

tail -f /var/log/qpsmtpd/current
and watch for your test mail.

[henry44]

I made the changes you suggested and we're good to go.

Thanks for all your help. You've been very patient and clear with your directions. This has not only helped me solve my problem, but has helped me learn more about how to better manage my mail system.

Thanks again, Henry

[ReetP]

I made the changes you suggested and we're good to go.

Job done then

I presume this was probably a v8 or earlier box that has been upgraded?

Thanks for all your help. You've been very patient and clear with your directions. This has not only helped me solve my problem, but has helped me learn more about how to better manage my mail system.

No worries. Lots of people helped me when I started. I just try and put a bit back now!

B. Rgds
John

[henry44]

I presume this was probably a v8 or earlier box that has been upgraded?

You're correct. This particular box started out as a fresh install of V7 (I might be wrong here) and has been upgraded to V9.2. I started using SME back when it was e-smith with the original release version. I've had to do very little to keep everything running smoothly ever since. That's a testament to those who create and maintain SME. It's also why I'm not as well versed in what goes on under the hood as I might be if I had to fix stuff all the time.

[ReetP]

Ahhh I thought so. Caught quite a few over time.

Yes, it can make you a bit lazy..... keep up to date!!

NB v10 is being worked on. Please help test. There are notes elsewhere here.

[henry44]

Here's a tidbit that might interest you and that I don't know what to do with.

I like the server manager for doing most of the management tasks I need to do, like backup scheduling and user management, so I installed a contrib that put a RBL management tab on the server manger page. I was able to make changes to the whitelist easy enough, but when I changed the RBLList as you suggested, the changes didn't take effect. I had to go into a terminal and run the signal-event email-update command for the changes to be applied.

I did the whitelist thing to see if I was actually able to receive emails before I started to mess with the RBLList stuff. The whitelist change was applied when I clicked on the save tab in the management contrib. Making the other changes and hitting save did nothing.

Is this a bug? Should I make a bug report? It seems like the contrib is broken in some way, but I'm not sure what to do about it.

Thanks,
Henry

[ReetP]

Which contrib/s did you install please?

[henry44]

This one.

https://wiki.contribs.org/Email_Whitelist-Blacklist_Control

It entirely possible that I'm missing something on how to use it.

[ReetP]

Crap day. A few beers to de stress.


I'll reply tomoz

[henry44]

No worries. There is no urgency here.

Take care....

H

[ReetP]

Ahhh yes.

OK - that contrib does not let you modify which lists you can or cannot use - they can only be set by the CLI (that's a NFR for WBL in v10)

So you cannot change the actual RBLList, SBLList or URIBLList values.

Yo have to set those as previously indicated eg config setprop qpsmtpd RBLList blah.

What you CAN do with it is whitelist or blacklist certain hosts or domains to let then pass through unmolested so they do not get checked by the relevant lists.

So if odd domains or email addresses or hosts get blocked and you know they are safe you can whitelist them. Equally if you have some bad boys that always get through you can block them specifically.

Does that make sense?

[henry44]

Ahhh yes.

OK - that contrib does not let you modify which lists you can or cannot use - they can only be set by the CLI (that's a NFR for WBL in v10)

So you cannot change the actual RBLList, SBLList or URIBLList values.

Your explanation makes sense, but not being able to change the list values doesn't. Why even have those being editable if the changes are not applied? The contrib could inform you of the list contents and then give directions on how to change them via cli, like the yum update tells you to run the two signal-event commands after running yum update.

Thinking I was actually making the desired changes when I wasn't cost me probably 2 hours of extra work.

There, soapbox mode off.

Thanks again for sharing your knowledge.

[ReetP]

Your explanation makes sense, but not being able to change the list values doesn't. Why even have those being editable if the changes are not applied? The contrib could inform you of the list contents and then give directions on how to change them via cli, like the yum update tells you to run the two signal-event commands after running yum update.

Hmmm. It is pretty clear. It does not mention changing the Lists. Not every contrib does everything. Of course, if it doesn't do what you want you can always write it yourself..... we love patches...

For most people all they want is too white list an address or server. Messing with lists is more complicated.

Wanting more is a NFR - feel free to add one...... you can add one at bugs.contribs.org. And contribute your patch too.....

Thinking I was actually making the desired changes when I wasn't cost me probably 2 hours of extra work.

So, did you bother to check what changed after you originally upgraded? Did you check the release notes? Do any testing? Check any config entries? Or did you just assume that it was all the same?? That nothing of course EVER changes? Whose fault is that??

You know the old saying about never ASS U ME?

To be brutal your issue was a few years in the making, and self inflicted through a lack of knowledge.

Don't feel bad. Put it down to experience..... we've all done it. Just some of us decided we'd never get caught again.....

And remember, every one one of us here who works in SME does not get paid. We do this in our spare time. For fun, or something. Have you ANY idea of the hours that WE put in to make sure the base system is actually workable?? How long some people have give up on their families and babies to work on v10??

2 hours ? If my wife knew how much I spent just making Terrys bloody wsdd work she'd have a fit - we don't even run fcuking Windows !!!!! I can tell you it was a damn sight more than 2 hours for something I'll never need. In my own company time.

https://forums.contribs.org/index.php/topic,54268.0.html

So, I call your hours, and I'll raise a patch to WBL. Especially if you had spent the 2 hours trying to understand your problem.....

There, soapbox mode off.

You can soap box all you want. But this is open source. The responsibility is in your own hands, not anyone elses.

The best way to avoid that happening is to get involved. The more you help, the more you learn, and the less stupid you feel. Simple

So, ask for a me for a rocket chat login and come and chat and help (and avoid future embarrassment )

Note - I am not trying to be harsh. Just putting you straight. I am glad we got your problem sorted.

I don't expect you to PAY for my help, which has taken more than a few of my very expensive hours, because this is Open Source.

But I DO expect you to contribute something back somehow.

Your call.

[henry44]

Wow. I'm sorry to have sounded like a dick. My comment about time spent wasn't in terms of value, but in terms of my frustration with not getting the results I expected.

I've been really happy with e-smith and now SME and everything it offers. I have sent money when I had it to spare and have supported OSS in various ways since the early days.

I really appreciate all the help you and others have given me over the years and didn't mean to trivialize the value of your time. Thanks again.