Problem with tcp_table server
Philipp Leusmann
to stop backscattering I wrote a tcp_table server which checks quota availability for incoming messages.
I read <http://www.postfix.org/tcp_table.5.html> over and over again, but still I am getting messages like
Jul 8 17:46:24 s15277780 postfix/smtpd[3325]: warning: read TCP map reply from localhost:1337: unexpected EOF (Success)
Jul 8 17:46:25 s15277780 postfix/smtpd[3325]: warning: tcp:localhost:1337: table lookup problem
in the logfile, when the server returns a 400 or 500 reply. For a 200-reply it works ok and the mail is delivered.
For a 400-reply, my server generates the following (from my logfile):
The encoded reply is [400 User%20over%20quota
]
The server sends everything between [ and ] . I think that should be ok. Or isn't it?
When I try a
postmap -vv -q "benny" tcp:localhost:1337
(benny is over quota)
the output ends with:
postmap: loaded dict_tcp_open = 7f50d057bd20
postmap: dict_open: calling tcp open routine
postmap: dict_open: tcp:localhost:1337
postmap: dict_tcp_lookup: key benny
postmap: trying... [127.0.0.1]
postmap: dict_tcp_lookup: send: get benny
postmap: dict_tcp_lookup: recv: 400 User%20over%20quota
postmap: dict_tcp_lookup: soft error: 400 User%20over%20quota
For a user having available space, it looks like:
postmap: loaded dict_tcp_open = 7f30f5c76d20
postmap: dict_open: calling tcp open routine
postmap: dict_open: tcp:localhost:1337
postmap: dict_tcp_lookup: key laus
postmap: trying... [127.0.0.1]
postmap: dict_tcp_lookup: send: get laus
postmap: dict_tcp_lookup: recv: 200 OK
postmap: dict_tcp_lookup: found: OK
OK
Can anybody tell me, what is wrong?
And what does postfix return the the delivering client in my current case? a 500 ?
Regards,
Philipp
Noel Jones
The 200, 400, and 500 codes indicate the status of the lookup
itself, and do not indicate the result.
200, the lookup found something, here it is: (OK, DEFER,
REJECT ... other access(5) actions)
400, the lookup table is broken, try later
500, the key wasn't found
In the case of an over-quota user, your table should return
200 REJECT User over quota
or DEFER if that's the action you want.
This isn't documented explicitly in the README because tcp
tables can be used for purposes other than access maps.
-- Noel Jones
Philipp Leusmann
Noel,
thanks for your advice. This really should be pointed out more explicitly in the documentation.
As for 500, would it be a good practice to return 500, if the key, which in this case is the email-adress is not known at all?
I also use a local_recipients_map, which already decides if a user exists or not.
So, which of the both is evaluated first? local_recipient_maps or smtpd_recipient_restrictions ?
What would be the best practice for my case?
Regards,
Philipp
Philipp Leusmann
Sorry for quoting my own mail, but there is one more question: I just implemented Noels suggestuons, and mail get rejected properly now. Thanks for that.
But I still get the odd
warning: read TCP map reply from localhost:1337: unexpected EOF (Success)
log entry. Is there missing anything?
Regards,
Philipp
Phil Howard
<philipp....@rwth-aachen.de> wrote:
> But I still get the odd
>
> warning: read TCP map reply from localhost:1337: unexpected EOF (Success)
>
> log entry. Is there missing anything?
I gather from the documentation the connection is maintained for more
requests. If your server disconnects after each request is answered,
that would explain it. A persistent connection in a high traffic
system would make sense to me.
--
sHiFt HaPpEnS!
Noel Jones
I expect returning 500 for users under quota or non-existent
users would be appropriate.
Alternately, you could return "200 REJECT" for non-existent
users, and "200 DUNNO" for under-quota users.
You probably don't want to use "200 OK" for under-quota users
since that will bypass any further antispam checks you might
want to do.
local_recipient_maps is evaluated at the point you specify
"reject_unlisted_recipient" or at the end of the RCPT TO stage
if you just rely on the default
smtpd_reject_unlisted_recipient setting. So you will get
queries for non-existent recipients.
>>
>
> Sorry for quoting my own mail, but there is one more question: I just implemented Noels suggestuons, and mail get rejected properly now. Thanks for that.
> But I still get the odd
>
> warning: read TCP map reply from localhost:1337: unexpected EOF (Success)
>
> log entry. Is there missing anything?
>
> Regards,
> Philipp
Leave the connection open so postfix can send more queries
over the same connection for better performance. OTOH, this
is a fairly harmless warning.
-- Noel Jones
Philipp Leusmann
Noel,
I guess at least one "under quota" should read "over quota", doesn't it?
Also, is there any any reference documentation about the possible response string?
For example DUNNO would not be something, which I would try to use naturally.
Also in my logfiles, I notice entries like
warning: restriction `User' after `defer' is ignored
when I return something like
200 DEFER User is over quota
I guess there is some special string expected after DEFER ?
Regards,
Philipp
Wietse Venema
> warning: restriction `User' after `defer' is ignored
>
> when I return something like
>
> 200 DEFER User is over quota
>
> I guess there is some special string expected after DEFER ?
No. When the first word is "defer" or "DEFER" etc., then the rest
of the text sent to the client.
Can you show verbose logging of tcp_table when it returns this
result?
Wietse
Philipp Leusmann
what kind auf verbose logging are you talking about? "postmap -vv -q" ? Or a more verbose logging for tcp_table in mail.log ? How could I turn this on?
Philipp
Wietse Venema
> warning: restriction `User' after `defer' is ignored
>
> when I return something like
>
> 200 DEFER User is over quota
>
> I guess there is some special string expected after DEFER ?
Wietse:
> No. When the first word is "defer" or "DEFER" etc., then the rest
> of the text sent to the client.
>
> Can you show verbose logging of tcp_table when it returns this
> result?
Philipp Leusmann{
> what kind auf verbose logging are you talking about? "postmap -vv
> -q" ? Or a more verbose logging for tcp_table in mail.log ? How
> could I turn this on?
I need to see ONE example of verbose logging that shows
(
tcp_table returning the string that is giving the above error,
AND
the Postfix SMTP server processing that result
).
Wietse
Philipp Leusmann
Sorry, I still don't get, what you mean.
This is from my tcp_table-server logfile:
16:07:00,622 DEBUG QuotaCheckerServer:139 - Checking quota for user [silvia89]
16:07:00,624 DEBUG QuotaCheckerServer:170 - Quota status of user [silvia89] is : 102402KB used, -2KB free
16:07:00,624 DEBUG QuotaCheckerServer:193 - no space available for user [silvia89]
16:07:00,624 DEBUG QuotaCheckerServer:265 - Encoded Input String [DEFER User over quota] as [DEFER%20User%20over%20quota]
16:07:00,624 DEBUG QuotaCheckerServer:239 - The encoded reply is [200 DEFER%20User%20over%20quota
]
and this is the corresponding mail.log:
Jul 9 16:07:00 s15277780 postfix/smtpd[18805]: warning: 186.9.10.210: hostname client-186-9-10-210.imovil.entelpcs.cl verification failed: Name or service not known
Jul 9 16:07:00 s15277780 postfix/smtpd[18805]: connect from unknown[186.9.10.210]
Jul 9 16:07:00 s15277780 postfix/smtpd[18815]: NOQUEUE: reject: RCPT from c-68-57-126-48.hsd1.va.comcast.net[68.57.126.48]: 450 4.3.2 <silv...@XXX.de>: Recipient address rejected: Try again later; from=<hazexa...@comcast.net> to=<silv...@XXX.de> proto=ESMTP helo=<comcast.net>
Jul 9 16:07:00 s15277780 postfix/smtpd[18815]: warning: restriction `User' after `defer' is ignored
Jul 9 16:07:00 s15277780 postfix/smtpd[18815]: disconnect from c-68-57-126-48.hsd1.va.comcast.net[68.57.126.48]
When I use postmap -vv -q "silvia89" tcp:localhost:1337 I get the following:
[...]
postmap: dict_open: calling tcp open routine
postmap: dict_open: tcp:localhost:1337
postmap: dict_tcp_lookup: key silvia89
postmap: trying... [127.0.0.1]
postmap: dict_tcp_lookup: send: get silvia89
postmap: dict_tcp_lookup: recv: 200 DEFER%20User%20over%20quota
postmap: dict_tcp_lookup: found: DEFER User over quota
DEFER User over quota
Hope this helps.
Philipp
Noel Jones
No, my advice is correct as written above.
Returning "no match" for both under quota and non-existent
users should be fine.
When you're using tcp_table as an access map, the possible
results are documented in access(5)
In general it's better to REJECT over-quota recipients rather
than DEFER. The exception would be if you expect the
over-quota users will always clear space in their mailbox
quickly. With REJECT the sender gets immediate feedback that
the recipient didn't receive the message. With DEFER, that
non-delivery notification could be delayed for several days.
>
> Also, is there any any reference documentation about the possible response string?
> For example DUNNO would not be something, which I would try to use naturally.
> Also in my logfiles, I notice entries like
>
> warning: restriction `User' after `defer' is ignored
>
> when I return something like
>
> 200 DEFER User is over quota
>
> I guess there is some special string expected after DEFER ?
>
> Regards,
> Philipp
>
>
That sounds as if the table is not being used as an access
map, and postfix is expecting a main.cf restriction with no
text allowed.
Victor Duchovni
> Jul 9 16:07:00 s15277780 postfix/smtpd[18815]: NOQUEUE: reject:
> RCPT from c-68-57-126-48.hsd1.va.comcast.net[68.57.126.48]:
> 450 4.3.2 <silv...@XXX.de>: Recipient address rejected:
> Try again later; from=<hazexa...@comcast.net> to=<silv...@XXX.de>
> proto=ESMTP helo=<comcast.net>
This is how "defer" gets processed when it is processed in a restriction
class definition, rather than access table lookup result.
> Jul 9 16:07:00 s15277780 postfix/smtpd[18815]: warning: restriction
> `User' after `defer' is ignored
This does not look possible for a result of "DEFER ..." found in a lookup
table. Can you run the smtpd(8) server with debug_peer_list setting
that matches a test ip from which you can initiate a test transaction,
and report log entries just above, matching and just below:
smtpd[pid]: check_table_result: ...
I can only explain your observations if "DEFER" is not the first
token in the table return value. It would be helpful to see your
"postconf -n" also, so we can see the context in which the tcp
table is used.
--
Viktor.
Wietse Venema
> > I need to see ONE example of verbose logging that shows
> >
> > (
> >
> > tcp_table returning the string that is giving the above error,
> >
> > AND
> >
> > the Postfix SMTP server processing that result
> >
> > ).
>
> Sorry, I still don't get, what you mean.
I need to see VERBOSE LOGGING FROM POSTFIX that shows:
Philipp Leusmann
Hi Victor,
this is from the verbose lofile:
Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: dict_tcp_lookup: send: get be...@XXX.de
Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: dict_tcp_lookup: recv: 200 DEFER%20User%20over%20quota
Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: dict_tcp_lookup: found: DEFER User over quota
Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: check_table_result: tcp:localhost:1337 DEFER User over quota be...@XXX.de
Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: >>> START Recipient address RESTRICTIONS <<<
Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: generic_checks: name=DEFER
Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: NOQUEUE: reject: RCPT from mta-2.ms.rz.RWTH-Aachen.DE[134.130.7.73]: 450 4.3.2 <be...@XXX.de>: Recipient address rejected: Try again later; from=<philipp....@rwth-aachen.de> to=<be...@XXX.de> proto=ESMTP helo=<mta-2.ms.rz.rwth-aachen.de>
Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: warning: restriction `User' after `defer' is ignored
Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: generic_checks: name=DEFER status=2
Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: generic_checks: name=check_recipient_access status=2
postconf -n shows this:
alias_database = hash:/etc/aliases
alias_maps = hash:/etc/aliases
append_dot_mydomain = no
biff = no
broken_sasl_auth_clients = yes
config_directory = /etc/postfix
debug_peer_list = 134.130.7.73, 134.130.7.72
fallback_transport = cyrus
inet_interfaces = all
local_recipient_maps = proxy:unix:passwd.byname, $alias_maps, mysql:/etc/postfix/my_recipient_maps.cf
mailbox_command = procmail -a "$EXTENSION"
mailbox_size_limit = 0
mailbox_transport = dspam
mydestination = XXX.de, YYY.de, localhost
myhostname = YYY.de
mynetworks = 127.0.0.0/8
myorigin = /etc/mailname
recipient_delimiter = +
relayhost =
smtp_tls_session_cache_database = btree:${queue_directory}/smtp_scache
smtpd_banner = $myhostname ESMTP $mail_name (Debian/GNU)
smtpd_recipient_restrictions = permit_mynetworks, reject_unauth_destination, reject_unlisted_recipient , check_recipient_access tcp:localhost:1337
smtpd_sasl_auth_enable = yes
smtpd_sasl_local_domain =
smtpd_sasl_path = smtpd
smtpd_sasl_security_options = noanonymous
smtpd_tls_cert_file = /etc/ssl/certs/ssl-cert-snakeoil.pem
smtpd_tls_key_file = /etc/ssl/private/ssl-cert-snakeoil.key
smtpd_tls_session_cache_database = btree:${queue_directory}/smtpd_scache
smtpd_use_tls = yes
Hope that helps.
BTW: I am running Postfix 2.5.5-1.1 on Debian Etch (?. I never can remember. The latest one :) )
Philipp
Victor Duchovni
> Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: dict_tcp_lookup: send: get be...@XXX.de
> Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: dict_tcp_lookup: recv: 200 DEFER%20User%20over%20quota
> Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: dict_tcp_lookup: found: DEFER User over quota
> Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: check_table_result: tcp:localhost:1337 DEFER User over quota be...@XXX.de
So far, so good.
> Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: >>> START Recipient address RESTRICTIONS <<<
It should never get here, the code in check_table_result() handles strings
starting with "DEFER <SPACE or TAB> ..." directly, without delegating
to the "generic_checks" code.
Either your Postfix source is modified, miscompiled, the binaries are
corrupted, or CPU is mal-functioning.
> Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: generic_checks: name=DEFER
> Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: NOQUEUE: reject: RCPT from mta-2.ms.rz.RWTH-Aachen.DE[134.130.7.73]: 450 4.3.2 <be...@XXX.de>: Recipient address rejected: Try again later; from=<philipp....@rwth-aachen.de> to=<be...@XXX.de> proto=ESMTP helo=<mta-2.ms.rz.rwth-aachen.de>
> Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: warning: restriction `User' after `defer' is ignored
> Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: generic_checks: name=DEFER status=2
> Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: generic_checks: name=check_recipient_access status=2
>
> postconf -n shows this:
>
> smtpd_recipient_restrictions =
> permit_mynetworks,
> reject_unauth_destination,
> reject_unlisted_recipient,
> check_recipient_access tcp:localhost:1337
OK, this is an access(5) check as expected, and goes through
check_table_result(), which implements "DEFER <text>". So your system
is not behaving as the original Postfix would on a working machine
running correctly compiled code.
> BTW: I am running Postfix 2.5.5-1.1 on Debian Etch (?. I never can
> remember. The latest one :) )
The relevant code has not changed in quite some time.
--
Viktor.
Philipp Leusmann
It would be nice, if somebody else, also running a Debian Lenny (it's lenny, not etch) system could verify this behavior.
Anybody here?
I will also reinstall postfix and try again.
Philipp
Wietse Venema
> On Fri, Jul 09, 2010 at 07:25:45PM +0200, Philipp Leusmann wrote:
>
> > Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: dict_tcp_lookup: send: get be...@XXX.de
> > Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: dict_tcp_lookup: recv: 200 DEFER%20User%20over%20quota
> > Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: dict_tcp_lookup: found: DEFER User over quota
> > Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: check_table_result: tcp:localhost:1337 DEFER User over quota be...@XXX.de
>
> So far, so good.
>
> > Jul 9 19:15:25 s15277780 postfix/smtpd[22232]: >>> START Recipient address RESTRICTIONS <<<
>
> It should never get here, the code in check_table_result() handles strings
> starting with "DEFER <SPACE or TAB> ..." directly, without delegating
> to the "generic_checks" code.
>
> Either your Postfix source is modified, miscompiled, the binaries are
> corrupted, or CPU is mal-functioning.
Or he is running a Postfix version before 2.6.
Citing the access(5) manpage:
DEFER optional text...
Reject the address etc. that matches the pattern. Reply with
"$access_map_defer_code optional text..." when the optional text
is specified, otherwise reply with a generic error response mes-
sage.
This feature is available in Postfix 2.6 and later.
Wietse
Victor Duchovni
> It would be nice, if somebody else, also running a Debian Lenny (it's lenny, not etch) system could verify this behavior.
>
> Anybody here?
>
> I will also reinstall postfix and try again.
If it is compiled with debugging symbols, you could try to single-step
through check_table_result() to see why the "DEFER" case is not matched.
#define STREQUAL(x,y,l) (strncasecmp((x), (y), (l)) == 0 && (y)[l] == 0)
...
if (STREQUAL(value, "DEFER", cmd_len)) {
dsn_split(&dp, "4.7.1", cmd_text);
return (smtpd_check_reject(state, MAIL_ERROR_POLICY,
var_map_defer_code,
smtpd_dsn_fix(DSN_STATUS(dp.dsn),
reply_class),
"<%s>: %s rejected: %s",
reply_name, reply_class,
*dp.text ? dp.text : "Access denied"));
}
So assuming that strncasecmp() is working correctly, the length cmd_len
computed via strcspn() is correct, and your result starts with
"DEFER<SPACE_or_TAB>" (which logs suggest), there is no way to get past
this block and not return before the generic_checks() call lower in the
function.
--
Viktor.
Victor Duchovni
> > Either your Postfix source is modified, miscompiled, the binaries are
> > corrupted, or CPU is mal-functioning.
>
> Or he is running a Postfix version before 2.6.
>
> Citing the access(5) manpage:
>
> DEFER optional text...
> Reject the address etc. that matches the pattern. Reply with
> "$access_map_defer_code optional text..." when the optional text
> is specified, otherwise reply with a generic error response mes-
> sage.
>
> This feature is available in Postfix 2.6 and later.
Oops, I thought this was older. He reported running 2.5.5, so that
would explain the whole mess. In 2.5 "DEFER" is not an access(5) action
and so falls through to generic_checks, with the reported symptoms.
--
Viktor.
Wietse Venema
For the record:
Postfix has always supported
smtpd_mumble_restrictions = ... defer other_restrictions...
And access map lookup results of
... defer other_restrictions...
But only Postfix 2.6 and later support acces map lookup results of
defer optional-text-for-sender
Wietse
Philipp Leusmann
Ok, then this Problem should be solved for me.
Thanks for all your help, guys.
Philipp