custom python3 filter dies with Status: 120 with specific mail

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
2 messages Options
Reply | Threaded
Open this post in threaded view
|

custom python3 filter dies with Status: 120 with specific mail

Hans-Peter Jansen
Hi,

we're using a custom python3 mail filter since ages here, but today, we
stumbled across a strange behavior, that I cannot explain.

First some environment specifications: Postfix 3.4.7/Python3.6.10 running on
OpenSUSE Leap 15.2.

The filter adheres to the simple filter "specification" from
http://www.postfix.org/FILTER_README.html

and is executed as:

mfilter   unix  -       n       n       -       4       pipe
  flags=Rq user=mfilter argv=/usr/bin/mail_filter -f ${sender} -- ${recipient}

Now, the interesting part is, when executed with the same data stand alone, it
exits correctly with return code 0. The Python interpreter does exit with 120,
if some sort of I/O issue happens after SystemExit happened, and this fact
cannot be signaled with an exception in this state (i.e. flushing buffered
data on standard streams failed, pipe signals).

What's unusual with this specific mail is, that it triggers quite some output
on the standard channels (~2kb). Further examination showed, that postfix
limits the amount of I/O, that it allows, and seems to proactively tear down
the pipe for some reason. This is underscored by truncated output. But even if
the process is executed successfully, postfix cuts off the output, that it
usually logs:

2020-09-02T20:03:43.309719+02:00 server postfix/pipe[104219]: 7743D38BFD728:
to=<[hidden email]>, relay=mfilter, delay=2.8, delays=0.14/0/0/2.7,
dsn=2.0.0, status=sent (delivered via mfilter
 service (106294: <793450b583c84abfa737ef1a8f07a606@messageid> /var/spool/
mail_filter/tmp/mf.2))
                    ^
               output truncated

Be assured, that the script does flush its output correctly before
terminating. After limiting the output to one line with about 50 bytes, the
mail, that triggered the exit code 120 reproducibly, is processed fine again.

It smells like some kind of race on the postfix side (pipe is teared down, but
some I/O is still in flight).

Could somebody explain this postfix behavior? What limits do I need to take
into account? I'm able to upgrade Postfix to version 3.5.6 easily, but would
like to understand this before taking any actions.

Thanks,
Pete


Reply | Threaded
Open this post in threaded view
|

Re: custom python3 filter dies with Status: 120 with specific mail

Wietse Venema
TL;DR: programs that receive email from the Postfix pipe daemon
should not produce large amounts of output.

When Postfix logs output from a pipe-to-command delivery, there are
three output limits in effect:

- The capacity of a UNIX pipe. The pipe daemon does not read any
command output until AFTER it has written the entire email message
to the command. That is one reason why the command should not produce
lots of output. The number is platform dependent. It is not PIPE_BUF
- that is an entirely different thing, concerned with atmoic writes.

- The amount of command output that the pipe daemon will read before
it closes the pipe. That's 4096 bytes, the Postfix internal buffer
size. A program that tries to write more than that may experience
a write error.

- The size of logging output. Postfix limits the size to 2000 bytes.

As for status 120, see https://bugs.python.org/issue5319, it appears
to be related to stdout write errors in Python 3.6 and later.

        Wietse