Piping mail logs to another process fails

[Jonathan Hammer-2]

Hi,

We are running Postfix on macOS and making use of `maillog_file = /dev/stdout` and `postfix start-fg` to send our logs to stdout. Not using Docker.

We would like to pipe the logs from stdout to another process to do some analysis and post-processing, like so:

        $ postfix start-fg | our-custom-log-analyzer…

However, in this configuration, Postfix fails to start and logs this error:

        fatal: open logfile ‘/dev/stdout’: file has 0 hard links

If we don’t pipe the output, it starts just fine.

It looks like this check in `safe_open_exist` is to blame:

    } else if (fstat_st->st_nlink != 1) {
        vstring_sprintf(why, "file has %d hard links",
                        (int) fstat_st->st_nlink);
        errno = EPERM;

When we pipe the output, st_nlink is 0, causing this check to fail. Do you think it would be acceptable to relax this check to `if (fstat_st->st_nlink > 1)`, as shown in the attached patch?

Thanks!
Jonathan Hammer
e3 Software
https://e3software.com

[Wietse Venema]

Jonathan Hammer:
> Hi,
>
> We are running Postfix on macOS and making use of `maillog_file =
> /dev/stdout` and `postfix start-fg` to send our logs to stdout.
> Not using Docker.

"postfix start-fg" ands "maillog_file = /dev/stdout" are for use
with containers. I am surprised that it works at all elsewhere. For
example, stdout logging cannot work correctly when a non-root user
invokes a Postfix program (the program can't talk to postlogd, and
will try to write to its own stdout). I have done no analysis of
what else might not work when a contasiner configuration is used
for stand-alone operation.

> We would like to pipe the logs from stdout to another process to
> do some analysis and post-processing, like so:
>
> $ postfix start-fg | our-custom-log-analyzer?

Run it in a container. What you are doing is a nightmare. If the
custom analyzer fails then Postfix will continue to run but logging
will be lost (postlogd has no way for it to tell you so). At least
in the docker case I might hope that SIGPIPE will have some effect.

> However, in this configuration, Postfix fails to start and logs this error:
>
> fatal: open logfile ?/dev/stdout?: file has 0 hard links
>
> If we don?t pipe the output, it starts just fine.

See above.

> It looks like this check in `safe_open_exist` is to blame:
>
>     } else if (fstat_st->st_nlink != 1) {
> vstring_sprintf(why, "file has %d hard links",
> (int) fstat_st->st_nlink);
> errno = EPERM;
>
> When we pipe the output, st_nlink is 0, causing this check to fail.
> Do you think it would be acceptable to relax this check to `if
> (fstat_st->st_nlink > 1)`, as shown in the attached patch?

This function is security critical, so I can't quickly say if this
would introduce a security hole. On Linux and *BSD, /dev/stdout is
a symlink to a file that has exactly one hard link, so this hack
should not be implemented for those systems,

        Wietse

[Wietse Venema]

Jonathan Hammer:

> Hi,
>
> We are running Postfix on macOS and making use of `maillog_file = /dev/stdout` and `postfix start-fg` to send our logs to stdout. Not using Docker.
>
> We would like to pipe the logs from stdout to another process to do some analysis and post-processing, like so:
>
> $ postfix start-fg | our-custom-log-analyzer?
>
> However, in this configuration, Postfix fails to start and logs this error:
>
> fatal: open logfile ?/dev/stdout?: file has 0 hard links

Here is one suggestion to make this more robust. Insteead of

        postfix start-fg  | analyzer

which requires restarting Postfix when the analyzer needs to be restarted.
use a named pipe, like thisL

        test -e /path/to/fifo || mkfifo /path/to/fifo

        analyzer < /path/to/fifo &

        postfix start-fg >  /path/to/fifo

With this, you can restart the analyzer independently from Postfix.

It also avoids the nonsense with stdout having a zero link count.

Quick demo on Macos:

    $ mkfifo fifo
    $ cat <fifo&
    [1] 45582
    $ ls -lL /dev/stdout >fifo
    prw-r--r--  1 wietse  eng  0 Sep 24 10:22 /dev/stdout
    [1]+  Done                    cat < fifo
    $

Note the link count of '1'.

That said, stdout logging is intended for containers that don't run
other programs. It does not work when a non-root user runs a Postfix
command; in that case, stdout logging may be intermingled with
normal command output.

        Wietse

[Wietse Venema]

Wietse Venema:
If you can use the fifo solution, then it would be easier to run Postfix
in the background with maillog_file=/path/to/fifo.

- Ensure that the analyzer is running, reading from /path/to/fifo;
  this should be configured as a start-up dependency for Postfix.
  This may alse be a good place to create the FIFO if one does not exist.

        test -p /path/to/fifo || {
                rm -f /path/to/fifo # in case it is a regular file
                mkfifo /path/to/fifo || exitt 1
                ... chown and chmod as appropriate... || exit 1
        }

- Configure the fifo as the maillog file:

    /etc/postfix/main.cf:
        maillog_file = /path/to/fifo

- Start Postfix in the background (postfix start).

I follow up with 2-day intervals, it is becasue I am rather busy.

        Wietse

[Wietse Venema]

Wietse Venema:

> Wietse Venema:
> If you can use the fifo solution, then it would be easier to run Postfix
> in the background with maillog_file=/path/to/fifo.
>
> - Ensure that the analyzer is running, reading from /path/to/fifo;
>   this should be configured as a start-up dependency for Postfix.
>   This may alse be a good place to create the FIFO if one does not exist.
>
> test -p /path/to/fifo || {
> rm -f /path/to/fifo # in case it is a regular file
> mkfifo /path/to/fifo || exitt 1
> ... chown and chmod as appropriate... || exit 1
> }
>
> - Configure the fifo as the maillog file:
>
>     /etc/postfix/main.cf:
>         maillog_file = /path/to/fifo
>
> - Start Postfix in the background (postfix start).

Downside of this approach is that "postfix reload" will "close" the
FIFO, so that the logfile analyzer reads EOF. Some extra action is
needed to re-open FIFO or to restart the analyzer.

        Wietse

[Viktor Dukhovni]

On Mon, Sep 28, 2020 at 09:42:44AM -0400, Wietse Venema wrote:

> Downside of this approach is that "postfix reload" will "close" the
> FIFO, so that the logfile analyzer reads EOF. Some extra action is
> needed to re-open FIFO or to restart the analyzer.

A custom analyzer can open both sides of the FIFO, ensuring that EOF
never happens, of course that still leaves the case where Postfix sees
EPIPE when the analyzer exits...

--
    Viktor.

[Jonathan Hammer-2]

Wietse and Viktor:

Many thanks for your help, insight, and advice on this issue. I really appreciate it.

Thanks!
Jonathan Hammer
e3 Software
https://e3software.com

On Sep 28, 2020, at 1:14 PM, Viktor Dukhovni <[hidden email]> wrote:

On Mon, Sep 28, 2020 at 09:42:44AM -0400, Wietse Venema wrote:

Downside of this approach is that "postfix reload" will "close" the
FIFO, so that the logfile analyzer reads EOF. Some extra action is
needed to re-open FIFO or to restart the analyzer.

A custom analyzer can open both sides of the FIFO, ensuring that EOF
never happens, of course that still leaves the case where Postfix sees
EPIPE when the analyzer exits...

--
   Viktor.