Postfix logging without syslogd

[Wietse Venema]

postfix-3.4-20190121-nonprod-logger has lightly-tested code for
logging to file without using syslogd.

This solves a usability problem in MacOS, may help to work around
a logging bottleneck with systemd, and solves 99% of the problem
for logging to stdout in a container (hopefully we have 100% soon).

Available from ftp://ftp.porcupine.org/mirrors/postfix-release/experimental

    postfix-3.4-20190121-nonprod-logger.HISTORY
    postfix-3.4-20190121-nonprod-logger.RELEASE_NOTES
    postfix-3.4-20190121-nonprod-logger.tar.gz
    postfix-3.4-20190121-nonprod-logger.tar.gz.gpg1
    postfix-3.4-20190121-nonprod-logger.tar.gz.gpg2
    postfix-3.4-20190121-nonprod-logger.tar.gz.sig

See the RELEASE_NOTES file for instructions and limitations.

        Wietse

[Viktor Dukhovni]

On Mon, Jan 21, 2019 at 07:04:56PM -0500, Wietse Venema wrote:

> postfix-3.4-20190121-nonprod-logger has lightly-tested code for
> logging to file without using syslogd.

I see that the postlogd(8) service correctly uses a unix-dgram
service to avoid message reordering, so the usual attention to
detail has not deserted you. :-)  Thanks!

For log rotation instructions, I would add that the old file should
not be modified, compressed or otherwise assumed complete, until a
new file is observed to have been written by postlogd(8) after
processing the "reload" command.  If one is not sure whether Postfix
is running, one could use postlog(1) (as root) to cause a new file
to be written, one way or the other.

The only other nit that comes to mind, is that some syslog servers
needlessly delete and re-create their unix-dgram sockets on reload,
which leads to needless opportunities for brief loss of messages
written to the previous incarnation of the socket.

I've not looked to see what master(8) does with the unix-dgram
socket on reload... I expect it is left as-is, I can't think of a
good reason to rebind it.

--
        Viktor.

[James Brown]

On 22 Jan 2019, at 11:04 am, Wietse Venema <[hidden email]> wrote:

postfix-3.4-20190121-nonprod-logger has lightly-tested code for
logging to file without using syslogd.

This solves a usability problem in MacOS, may help to work around
a logging bottleneck with systemd, and solves 99% of the problem
for logging to stdout in a container (hopefully we have 100% soon).

Available from ftp://ftp.porcupine.org/mirrors/postfix-release/experimental

   postfix-3.4-20190121-nonprod-logger.HISTORY
   postfix-3.4-20190121-nonprod-logger.RELEASE_NOTES
   postfix-3.4-20190121-nonprod-logger.tar.gz
   postfix-3.4-20190121-nonprod-logger.tar.gz.gpg1
   postfix-3.4-20190121-nonprod-logger.tar.gz.gpg2
   postfix-3.4-20190121-nonprod-logger.tar.gz.sig

See the RELEASE_NOTES file for instructions and limitations.

Wietse

Thanks so much for doing this Wietse.

Just tried it on MacOS Mojave machine. Sudo make install ends with:

cc -I. -I../../include -DUSE_TLS -DUSE_SASL_AUTH -DDEF_SERVER_SASL_TYPE=\"dovecot\" -DDEF_COMMAND_DIR=\"/usr/local/sbin\" -DDEF_CONFIG_DIR=\"/usr/local/etc/postfix\" -DDEF_DAEMON_DIR=\"/usr/local/libexec/postfix\" -DHAS_PCRE -I/usr/local/opt//include -DHAS_SSL -I/usr/local/opt/openssl@1.1/1.1.1a/include -DHAS_MYSQL -I/usr/local/opt/mysql@5.7/include/mysql -DBIND_8_COMPAT -DNO_NETINFO -DRESOLVE_H_NEEDS_ARPA_NAMESER_COMPAT_H -DNO_EAI -DDEF_SMTPUTF8_ENABLE=\"no\" -DHAS_DEV_URANDOM -DSNAPSHOT -DNONPROD -DDEF_MAILQ_PATH=\"/usr/local/bin/mailq\" -DDEF_NEWALIAS_PATH=\"/usr/local/bin/newaliases\" -DDEF_SENDMAIL_PATH=\"/usr/local/sbin/sendmail\" -UUSE_DYNAMIC_LIBS -DDEF_SHLIB_DIR=\"no\" -UUSE_DYNAMIC_MAPS -Wmissing-prototypes -Wformat -Wno-comment  -g -O -I. -DMACOSX -c dict_cidr.c

cc -I. -I../../include -DUSE_TLS -DUSE_SASL_AUTH -DDEF_SERVER_SASL_TYPE=\"dovecot\" -DDEF_COMMAND_DIR=\"/usr/local/sbin\" -DDEF_CONFIG_DIR=\"/usr/local/etc/postfix\" -DDEF_DAEMON_DIR=\"/usr/local/libexec/postfix\" -DHAS_PCRE -I/usr/local/opt//include -DHAS_SSL -I/usr/local/opt/openssl@1.1/1.1.1a/include -DHAS_MYSQL -I/usr/local/opt/mysql@5.7/include/mysql -DBIND_8_COMPAT -DNO_NETINFO -DRESOLVE_H_NEEDS_ARPA_NAMESER_COMPAT_H -DNO_EAI -DDEF_SMTPUTF8_ENABLE=\"no\" -DHAS_DEV_URANDOM -DSNAPSHOT -DNONPROD -DDEF_MAILQ_PATH=\"/usr/local/bin/mailq\" -DDEF_NEWALIAS_PATH=\"/usr/local/bin/newaliases\" -DDEF_SENDMAIL_PATH=\"/usr/local/sbin/sendmail\" -UUSE_DYNAMIC_LIBS -DDEF_SHLIB_DIR=\"no\" -UUSE_DYNAMIC_MAPS -Wmissing-prototypes -Wformat -Wno-comment  -g -O -I. -DMACOSX -c dict_db.c

dict_db.c:768:2: error: "Unsupported Berkeley DB version"

#error "Unsupported Berkeley DB version"

 ^

1 error generated.

make: *** [dict_db.o] Error 1

make: *** [update] Error 1

I used:

make -f Makefile.init makefiles CCARGS='-DUSE_TLS -DUSE_SASL_AUTH \

-DDEF_SERVER_SASL_TYPE=\"dovecot\" \

-DDEF_COMMAND_DIR=\"/usr/local/sbin\" \

-DDEF_CONFIG_DIR=\"/usr/local/etc/postfix\" \

-DDEF_DAEMON_DIR=\"/usr/local/libexec/postfix\" \

-DHAS_PCRE -I/usr/local/opt//include \

-DHAS_SSL -I/usr/local/opt/openssl@1.1/1.1.1a/include \

-DHAS_MYSQL -I/usr/local/opt/mysql@5.7/include/mysql' AUXLIBS='-L/usr/local/lib -lpcre -L/usr/local/Cellar/openssl@1.1/1.1.1a/lib -lssl -lcrypto -L/usr/local/opt/mysql@5.7/lib \

-lmysqlclient -lz -lm'  sendmail_path=/usr/local/sbin/sendmail newaliases_path=/usr/local/bin/newaliases mailq_path=/usr/local/bin/mail

I tried adding ‘-lda’ to the AUXLIBS string but got the same result.

I have berkeley-db version 18.1.25 installed via Homebrew.

Don’t think I had this issue with the previous version of Postfix.

Thanks,

James.

[Viktor Dukhovni]

> On Jan 21, 2019, at 11:41 PM, James Brown <[hidden email]> wrote:
>
> Just tried it on MacOS Mojave machine. Sudo make install ends with:
>
> dict_db.c:768:2: error: "Unsupported Berkeley DB version"
> #error "Unsupported Berkeley DB version"
>  ^
>
> I used:
>
> I tried adding ‘-lda’ to the AUXLIBS string but got the same result.
>
> I have berkeley-db version 18.1.25 installed via Homebrew.
>
> Don’t think I had this issue with the previous version of Postfix.

You mean previous version of Berkeley DB.  While many projects
are moving to semantic versioning, Berkeley DB has no intention
of going with the crowd:

  https://download.oracle.com/otndocs/products/berkeleydb/html/changelog_18_1.html#idm140164927133552

  12. The version numbering scheme for Berkeley DB changed from a
      five-part number to a three-part number of the form
      <year>.<release>.<build>. This release is numbered 18.1.x,
      indicating that it is the first release of the year 2018.
      18.1.x is the successor to the 6.2.x (also known as 12.2.6.2.x)
      releases. The third and fourth parameters of db_full_version()
      are no longer meaningful and are now deprecated; if present,
      they are are set to zero. [#26743]

There's no longer any reason to expect a given version number to
convey anything about the API, or for the numbers to not go to
infinity and beyond. :-)

There's apparently now also an SQLite interface with Berkeley DB
as the storage backend.

   https://www.oracle.com/technetwork/database/database-technologies/berkeleydb/overview/sql-160887.html

though presumably in that case one no longer has a simple key-value
datastore.

--
        Viktor.

[Larry Stone]

On Jan 21, 2019, at 6:04 PM, Wietse Venema <[hidden email]> wrote:
>
> postfix-3.4-20190121-nonprod-logger has lightly-tested code for
> logging to file without using syslogd.
>

I just successfully built it on a Mojave system and so far, all looks good. One test email sent out (my Postfix is outgoing only) was properly logged. Have not tested anything yet involving log rotation. Unlike James Brown and his Unsupported Berkeley DB version, I do not have Berkeley DB on my system (unless a version comes with MacOS), do not use mySQL, and do not have anything from Homebrew on the system.

--
Larry Stone
[hidden email]

[James Brown]

On 22 Jan 2019, at 5:18 pm, Larry Stone <[hidden email]> wrote:

>
> On Jan 21, 2019, at 6:04 PM, Wietse Venema <[hidden email]> wrote:
>>
>> postfix-3.4-20190121-nonprod-logger has lightly-tested code for
>> logging to file without using syslogd.
>>
>
> I just successfully built it on a Mojave system and so far, all looks good. One test email sent out (my Postfix is outgoing only) was properly logged. Have not tested anything yet involving log rotation. Unlike James Brown and his Unsupported Berkeley DB version, I do not have Berkeley DB on my system (unless a version comes with MacOS), do not use mySQL, and do not have anything from Homebrew on the system.
>
> --
> Larry Stone
> [hidden email]

I’ll try removing Berkeley DB and give it another go. Thanks Larry.

James.

On 21 Jan 2019, at 22:13, Viktor Dukhovni <[hidden email]> wrote:
>  12. The version numbering scheme for Berkeley DB changed from a
>      five-part number to a three-part number of the form
>      <year>.<release>.<build>. This release is numbered 18.1.x,

Do you know why the current version in FreeBSD ports is 6.2.32_1? (or the older db5 is still current as well)

--
Can I borrow your underpants for 10 minutes?

[James Brown]

On 22 Jan 2019, at 5:22 pm, James Brown <[hidden email]> wrote:

On 22 Jan 2019, at 5:18 pm, Larry Stone <[hidden email]> wrote:

On Jan 21, 2019, at 6:04 PM, Wietse Venema <[hidden email]> wrote:

postfix-3.4-20190121-nonprod-logger has lightly-tested code for
logging to file without using syslogd.

I just successfully built it on a Mojave system and so far, all looks good. One test email sent out (my Postfix is outgoing only) was properly logged. Have not tested anything yet involving log rotation. Unlike James Brown and his Unsupported Berkeley DB version, I do not have Berkeley DB on my system (unless a version comes with MacOS), do not use mySQL, and do not have anything from Homebrew on the system.

--
Larry Stone
[hidden email]

I’ll try removing Berkeley DB and give it another go. Thanks Larry.

James.

I removed Berkeley DB (via Homebrew uninstall) and it gets much further. Now stops on:

In file included from abounce.c:187:

./mail_params.h:20:10: fatal error: 'openssl/opensslv.h' file not found

#include <openssl/opensslv.h>           /* OPENSSL_VERSION_NUMBER */

         ^~~~~~~~~~~~~~~~~~~~

1 error generated.

Shouldn’t this line in my make command find it?

-DHAS_SSL -I/usr/local/opt/openssl@1.1/1.1.1a/include

$locate openssl/opensslv.h

/usr/local/Cellar/openssl/1.0.2p/include/openssl/opensslv.h

/usr/local/Cellar/openssl/1.0.2q/include/openssl/opensslv.h

/usr/local/Cellar/openssl@1.1/1.1.1/include/openssl/opensslv.h

/usr/local/Cellar/openssl@1.1/1.1.1a/include/openssl/opensslv.h

[Wietse Venema]

Viktor Dukhovni:
> On Mon, Jan 21, 2019 at 07:04:56PM -0500, Wietse Venema wrote:
>
> > postfix-3.4-20190121-nonprod-logger has lightly-tested code for
> > logging to file without using syslogd.
>
> I see that the postlogd(8) service correctly uses a unix-dgram
> service to avoid message reordering, so the usual attention to
> detail has not deserted you. :-)  Thanks!

A lot of attention to detail went into this, but I have no control
over how the kernel's unix-domain datagram implementation buffers
messages until the postlogd service is ready. That's why messages
are time-stamped by the sender, not receiver.

> For log rotation instructions, I would add that the old file should
> not be modified, compressed or otherwise assumed complete, until a
> new file is observed to have been written by postlogd(8) after
> processing the "reload" command.  If one is not sure whether Postfix
> is running, one could use postlog(1) (as root) to cause a new file
> to be written, one way or the other.

The Postfix master immediately signals postlogd to terminate. This
being a single-instance event-driven service, it should terminate
immediately unless it is blocked on file writes.

> The only other nit that comes to mind, is that some syslog servers
> needlessly delete and re-create their unix-dgram sockets on reload,
> which leads to needless opportunities for brief loss of messages
> written to the previous incarnation of the socket.

The Postfix master does not close a socket, unless the service is
removed from master.cf, or master_service_disable is in effect.

        Wietse

[Larry Stone]

Oops. Inadvertently posted this reply in the wrong topic. Reposting it hear for proper threading.

===========

I noticed what appears to be a cosmetic problem: log entries from master are being time-stamped with the time they were last started or “postfix reload”-ed rather than the current time and log entries from qmgr are being time-stamped with the time of the first activity since the start or reload.

I did a postfix reload this morning while debugging my log file rotate/compress job:
Jan 23 07:16:00 albion postfix/postfix-script[61552]: refreshing the Postfix mail system
Jan 22 14:43:45 albion postfix/master[45505]: reload -- version 3.4-20190121-nonprod, configuration /usr/local/etc/postfix
^^^^^^^^^^^^^^^ time of last reload
Jan 23 07:30:10 albion postfix/pickup[61558]: 9C59C1032D4E: uid=501 from=<larry>
Jan 23 07:30:10 albion postfix/cleanup[61784]: 9C59C1032D4E: message-id=<[hidden email]>
Jan 23 07:30:10 albion postfix/qmgr[61559]: 9C59C1032D4E: from=<[hidden email]>, size=1041, nrcpt=1 (queue active)
Jan 23 07:30:11 albion postfix/smtp[61792]: Anonymous TLS connection established to smtp.your-site.com[205.233.73.98]:587: TLSv1.2 with cipher ADH-AES256-GCM-SHA384 (256/256 bits)
Jan 23 07:30:11 albion postfix/smtp[61792]: 9C59C1032D4E: to=<[hidden email]>, relay=smtp.your-site.com[205.233.73.98]:587, delay=0.88, delays=0.12/0.16/0.44/0.16, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 43l5kW2zJ5zycF)
Jan 23 07:30:10 albion postfix/qmgr[61559]: 9C59C1032D4E: removed
Jan 23 07:30:10 albion postfix/pickup[61558]: 2AF4E1032E6B: uid=501 from=<larry>
Jan 23 07:55:36 albion postfix/cleanup[62203]: 2AF4E1032E6B: message-id=<[hidden email]>
Jan 23 07:30:10 albion postfix/qmgr[61559]: 2AF4E1032E6B: from=<[hidden email]>, size=843, nrcpt=1 (queue active)
^^^^^^^^^^^^^^^ time of first activity above

And from a few minutes ago to provide some greater time separation from the last reload:
Jan 23 10:31:00 albion postfix/pickup[64766]: C81A61033C87: uid=501 from=<[hidden email]>
Jan 23 10:31:00 albion postfix/cleanup[64795]: C81A61033C87: message-id=<[hidden email]>
Jan 23 07:30:10 albion postfix/qmgr[61559]: C81A61033C87: from=<[hidden email]>, size=1590, nrcpt=1 (queue active)
^^^^^^^^^^^^^^^ time of first activity above
Jan 23 10:31:01 albion postfix/smtp[64798]: Anonymous TLS connection established to smtp.your-site.com[205.233.73.98]:587: TLSv1.2 with cipher ADH-AES256-GCM-SHA384 (256/256 bits)
Jan 23 10:31:01 albion postfix/smtp[64798]: C81A61033C87: to=<[hidden email]>, relay=smtp.your-site.com[205.233.73.98]:587, delay=0.63, delays=0.05/0.03/0.43/0.11, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 43l9l92Zkzz16xT)
Jan 23 07:30:10 albion postfix/qmgr[61559]: C81A61033C87: removed
^^^^^^^^^^^^^^^ time of first activity above

--
Larry Stone
[hidden email]

> On Jan 22, 2019, at 6:20 AM, Wietse Venema <[hidden email]> wrote:
>
> Viktor Dukhovni:
>> On Mon, Jan 21, 2019 at 07:04:56PM -0500, Wietse Venema wrote:
>>
>>> postfix-3.4-20190121-nonprod-logger has lightly-tested code for
>>> logging to file without using syslogd.
>>
>> I see that the postlogd(8) service correctly uses a unix-dgram
>> service to avoid message reordering, so the usual attention to
>> detail has not deserted you. :-)  Thanks!
>
> A lot of attention to detail went into this, but I have no control
> over how the kernel's unix-domain datagram implementation buffers
> messages until the postlogd service is ready. That's why messages
> are time-stamped by the sender, not receiver.
>
>> For log rotation instructions, I would add that the old file should
>> not be modified, compressed or otherwise assumed complete, until a
>> new file is observed to have been written by postlogd(8) after
>> processing the "reload" command.  If one is not sure whether Postfix
>> is running, one could use postlog(1) (as root) to cause a new file
>> to be written, one way or the other.
>
> The Postfix master immediately signals postlogd to terminate. This
> being a single-instance event-driven service, it should terminate
> immediately unless it is blocked on file writes.
>
>> The only other nit that comes to mind, is that some syslog servers
>> needlessly delete and re-create their unix-dgram sockets on reload,
>> which leads to needless opportunities for brief loss of messages
>> written to the previous incarnation of the socket.
>
> The Postfix master does not close a socket, unless the service is
> removed from master.cf, or master_service_disable is in effect.
>
> Wietse

[Wietse Venema]

Wietse Venema:
> postfix-3.4-20190123-nonprod-logger has lightly-tested code for
> logging to file without using syslogd.
>
> This solves a usability problem in MacOS, may help to work around
> a logging bottleneck with systemd, and solves 99% of the problem
> for logging to stdout in a container (hopefully we have 100% soon).

This is updated with a time stamp fix, documentation, and better
handling of some edge case where a new postlogd process can receive
messages from a process that was already running before maillog_file
was set to empty. Attention to detail...

Available from ftp://ftp.porcupine.org/mirrors/postfix-release/experimental

    postfix-3.4-20190123-nonprod-logger.HISTORY
    postfix-3.4-20190123-nonprod-logger.RELEASE_NOTES
    postfix-3.4-20190123-nonprod-logger.tar.gz
    postfix-3.4-20190123-nonprod-logger.tar.gz.gpg1
    postfix-3.4-20190123-nonprod-logger.tar.gz.gpg2
    postfix-3.4-20190123-nonprod-logger.tar.gz.sig

See the RELEASE_NOTES file for instructions and limitations.

        Wietse

[Wietse Venema]

Postfix logging without syslog now supports logging to stdout. This
requires starting Postfix with "postfix start-fg" and main.cf with
"maillog_file = /dev/stdout". It does not get easier than this.

Available from ftp://ftp.porcupine.org/mirrors/postfix-release/experimental

    postfix-3.4-20190126-nonprod-logger.HISTORY
    postfix-3.4-20190126-nonprod-logger.RELEASE_NOTES
    postfix-3.4-20190126-nonprod-logger.tar.gz
    postfix-3.4-20190126-nonprod-logger.tar.gz.gpg1
    postfix-3.4-20190126-nonprod-logger.tar.gz.gpg2
    postfix-3.4-20190126-nonprod-logger.tar.gz.sig

See the RELEASE_NOTES file for instructions and limitations.

        Wietse