logfile support for MacOS

classic Classic list List threaded Threaded
13 messages Options
Reply | Threaded
Open this post in threaded view
|

logfile support for MacOS

Wietse Venema
I'm implementing logfile support for Postfix on MacOS, because not
providing results in a bad experience.

This is a retrofit workaround, therefore it will have limitations
that do not exist with the default syslog-based implementation.

- The logfile pathname is configured in main.cf, and therefore the
  logfile cannot contain information from programs that fail before
  they finish processing main.cf and command-line options.

- The logfile is written by a new postlogd daemon. This program is
  start-up critical, meaning that if the postlogd daemon fails
  during "postfix start" or "postfix reload", then the Postfix
  master(8) daemon will terminate.

- During Postfix start-up, before the postlogd daemon runs, programs
  such as postfix(1), postlog(1) and master(8) will write directly
  to the logfile. These programs will log a fatal error if they
  cannot create or append to the logfile.

- The low-privilege setgid Postfix programs postqueue(1) and
  postdrop(1) can send logging to the postlog daemon. If the postlog
  daemon is down, the logging from these programs will be lost.
  These programs will still log to stderr.

- The unprivileged Postfix sendmail(1) program cannot talk to the
  postlogd daemon. This program can log only to stderr.

- Logfile rotation is not built into Postfix. To rotate the file,
  run a cron job that renames the current file, and that excecutes
  "postfix reload" before compressing the file. The postlogd daemon
  will automatically create a logfile if it does not exist.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: logfile support for MacOS

Larry Stone



On Jan 18, 2019, at 2:18 PM, Wietse Venema <[hidden email]> wrote:

> I'm implementing logfile support for Postfix on MacOS, because not
> providing results in a bad experience.

Wietse, I’m impressed. As I run Postfix on a couple of Macs in a non-critical environment (outgoing only for messages from system processes and monitoring jobs), I’ll be happy to do some testing when you have it ready.

--
Larry Stone
[hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: logfile support for MacOS

John Stoffel-2
In reply to this post by Wietse Venema
>>>>> "Wietse" == Wietse Venema <[hidden email]> writes:

Wietse> I'm implementing logfile support for Postfix on MacOS, because not
Wietse> providing results in a bad experience.

Wietse> This is a retrofit workaround, therefore it will have limitations
Wietse> that do not exist with the default syslog-based implementation.

Why not just provide a syslog daemon configured for only Postfix use
on MACs?  Then you don't have to hack the main postfix code, and
syslog isn't anything difficult either?  It can log to a private
postfix log file using a non-standard port as well.

Seems simpler and less error prone.  Just have it startup first, and
maybe put in the checks for postfix to die if it can't reach the
private syslog server.

It just seems like you're re-inventing the wheel here, when the real
problem is more native OS support for standards.

John
Reply | Threaded
Open this post in threaded view
|

Re: logfile support for MacOS

Pau Amma
On Fri, January 18, 2019 9:24 pm, John Stoffel wrote:

>>>>>> "Wietse" == Wietse Venema <[hidden email]> writes:
>
> Wietse> I'm implementing logfile support for Postfix on MacOS, because not
> Wietse> providing results in a bad experience.
>
> Wietse> This is a retrofit workaround, therefore it will have limitations
> Wietse> that do not exist with the default syslog-based implementation.
>
> Why not just provide a syslog daemon configured for only Postfix use
> on MACs?  Then you don't have to hack the main postfix code, and
> syslog isn't anything difficult either?  It can log to a private
> postfix log file using a non-standard port as well.

Isn't that what postlogd is all about?


Reply | Threaded
Open this post in threaded view
|

Re: logfile support for MacOS

Wietse Venema
In reply to this post by John Stoffel-2
John Stoffel:

> >>>>> "Wietse" == Wietse Venema <[hidden email]> writes:
>
> Wietse> I'm implementing logfile support for Postfix on MacOS, because not
> Wietse> providing results in a bad experience.
>
> Wietse> This is a retrofit workaround, therefore it will have limitations
> Wietse> that do not exist with the default syslog-based implementation.
>
> Why not just provide a syslog daemon configured for only Postfix use
> on MACs?

Sorry, I will not support syslogd or other non-Postfix programs.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: logfile support for MacOS

John Stoffel-2
>>>>> "Wietse" == Wietse Venema <[hidden email]> writes:

Wietse> John Stoffel:
>> >>>>> "Wietse" == Wietse Venema <[hidden email]> writes:
>>
Wietse> I'm implementing logfile support for Postfix on MacOS, because not
Wietse> providing results in a bad experience.
>>
Wietse> This is a retrofit workaround, therefore it will have limitations
Wietse> that do not exist with the default syslog-based implementation.
>>
>> Why not just provide a syslog daemon configured for only Postfix use
>> on MACs?

Wietse> Sorry, I will not support syslogd or other non-Postfix programs.

I can understand that, but I was more thinking of writing a syslogd
compatible receiver for macOS, so that you dno't have to change all
the rest of the postfix base.  Yes, it's not ideal, but supporting
MACs isn't ideal these days either.

John

Reply | Threaded
Open this post in threaded view
|

Re: logfile support for MacOS

Larry Stone
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 19, 2019, at 3:10 PM, John Stoffel <[hidden email]> wrote:
>
>>>>>> "Wietse" == Wietse Venema <[hidden email]> writes:
>
> Wietse> John Stoffel:
>>>>>>>> "Wietse" == Wietse Venema <[hidden email]> writes:
>>>
> Wietse> I'm implementing logfile support for Postfix on MacOS, because not
> Wietse> providing results in a bad experience.
>>>
> Wietse> This is a retrofit workaround, therefore it will have limitations
> Wietse> that do not exist with the default syslog-based implementation.
>>>
>>> Why not just provide a syslog daemon configured for only Postfix use
>>> on MACs?
>
> Wietse> Sorry, I will not support syslogd or other non-Postfix programs.
>
> I can understand that, but I was more thinking of writing a syslogd
> compatible receiver for macOS, so that you dno't have to change all
> the rest of the postfix base.  Yes, it's not ideal, but supporting
> MACs isn't ideal these days either.
>
> John
>

Reply | Threaded
Open this post in threaded view
|

Re: logfile support for MacOS

Larry Stone
Disregard. Reposted in the proper topic.

--
Larry Stone
[hidden email]


> On Jan 23, 2019, at 10:35 AM, Larry Stone <[hidden email]> wrote:
>
> 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.

Reply | Threaded
Open this post in threaded view
|

Re: logfile support for MacOS

Wietse Venema
In reply to this post by Larry Stone
Larry Stone:
> 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.

postlogd may receive events that were sent earlier (by smtpd, qmgr,
etc.) and that were still queued up in the kernel.

The time stamp prefix string in a logfile record is formatted in
the sending process, at the time that that process gets from the
kernel using the time() system call. If the clock inside a process
does not advance, then MacOS is doing something unusual.

        Wietse

> 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 19, 2019, at 3:10 PM, John Stoffel <[hidden email]> wrote:
> >
> >>>>>> "Wietse" == Wietse Venema <[hidden email]> writes:
> >
> > Wietse> John Stoffel:
> >>>>>>>> "Wietse" == Wietse Venema <[hidden email]> writes:
> >>>
> > Wietse> I'm implementing logfile support for Postfix on MacOS, because not
> > Wietse> providing results in a bad experience.
> >>>
> > Wietse> This is a retrofit workaround, therefore it will have limitations
> > Wietse> that do not exist with the default syslog-based implementation.
> >>>
> >>> Why not just provide a syslog daemon configured for only Postfix use
> >>> on MACs?
> >
> > Wietse> Sorry, I will not support syslogd or other non-Postfix programs.
> >
> > I can understand that, but I was more thinking of writing a syslogd
> > compatible receiver for macOS, so that you dno't have to change all
> > the rest of the postfix base.  Yes, it's not ideal, but supporting
> > MACs isn't ideal these days either.
> >
> > John
> >
>
>
Reply | Threaded
Open this post in threaded view
|

Re: logfile support for MacOS

Wietse Venema
Wietse Venema:

> Larry Stone:
> > 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.
>
> postlogd may receive events that were sent earlier (by smtpd, qmgr,
> etc.) and that were still queued up in the kernel.
>
> The time stamp prefix string in a logfile record is formatted in
> the sending process, at the time that that process gets from the
> kernel using the time() system call. If the clock inside a process
> does not advance, then MacOS is doing something unusual.
>
> Wietse
>
> > 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

Note that these are out of order; apparently, the Jan 22 14:43:45
event was not logged until the next day, when "postfix reload" was
logged by the postlog program which triggered the execution of a new
postlogd process.

> > 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

I suppose that after "postfix reload" the queue manager was not
restarted immediately at 07:16:00, as a MacOS battery saving feature.

> > 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)

I guess this message was posted 25 minutes later, based on the cleanup time stamp.

Same pickup process ID, and same time stamp as with the previous message.

Same qmgr process ID, and same time stamp as with the previous message.

Apparently, the pickup and qmgr clocks have not advanced, as if MacOS is caching the
lookup result from the time() system call.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: logfile support for MacOS

Wietse Venema
Larry, can you insert one line in src/util/msg_logger.c,
or apply the patch at the end of this message?

        Wietse

     lt = localtime(&now)
+    VSTRING_RESET(msg_logger_buf);
     if ((len = strftime(vstring_end(msg_logger_buf), \
                       vstring_avail(msg_logger_buf),
 
*** ./msg_logger.c- 2019-01-23 14:28:25.000000000 -0500
--- ./msg_logger.c 2019-01-23 14:28:24.000000000 -0500
***************
*** 151,157 ****
      if (time(&now) < 0)
  msg_fatal("no time: %m");
      lt = localtime(&now);
!     if ((len = strftime(vstring_end(msg_logger_buf), \
  vstring_avail(msg_logger_buf),
  "%b %d %H:%M:%S ", lt)) == 0)
  msg_fatal("strftime: %m");
--- 151,158 ----
      if (time(&now) < 0)
  msg_fatal("no time: %m");
      lt = localtime(&now);
!     VSTRING_RESET(msg_logger_buf);
!     if ((len = strftime(vstring_str(msg_logger_buf),
  vstring_avail(msg_logger_buf),
  "%b %d %H:%M:%S ", lt)) == 0)
  msg_fatal("strftime: %m");
Reply | Threaded
Open this post in threaded view
|

Re: logfile support for MacOS

Larry Stone


> On Jan 23, 2019, at 1:29 PM, Wietse Venema <[hidden email]> wrote:
>
> Larry, can you insert one line in src/util/msg_logger.c,
> or apply the patch at the end of this message?

Wietse, thanks - that did it! I’m seeing the timestamps I expect. With reference to the earlier notes, I do not have the expertise to argue one way or the other about MacOS doing something weird. But it should not have been any power-saving / battery issue as this was on a desktop iMac. If your patch just works around another MacOS weirdness, thanks.

For the record, I have tested the patch both on the my server (a 2010 iMac running High Sierra (10.13) as it is too old for Mojave) and my 2012 MacBookPro running Mojave (10.14). Both had the same issue and both now look good with the patch.

Log extract: Started at 14:04:26, two test messages sent at 14:07:16 and 14:07:22, and then a postfix reload at 14:09:28. All looks correct:
Jan 23 14:04:26 albion postfix/postfix-script[71395]: starting the Postfix mail system
Jan 23 14:04:26 albion postfix/master[71397]: daemon started -- version 3.4-20190121-nonprod, configuration /usr/local/etc/postfix
Jan 23 14:07:16 albion postfix/pickup[71398]: 7A3DD10343F8: uid=501 from=<[hidden email]>
Jan 23 14:07:16 albion postfix/cleanup[71457]: 7A3DD10343F8: message-id=<[hidden email]>
Jan 23 14:07:16 albion postfix/qmgr[71399]: 7A3DD10343F8: from=<[hidden email]>, size=468, nrcpt=1 (queue active)
Jan 23 14:07:16 albion postfix/smtp[71460]: 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 14:07:17 albion postfix/smtp[71460]: 7A3DD10343F8: to=<[hidden email]>, relay=smtp.your-site.com[205.233.73.98]:587, delay=0.63, delays=0.04/0.05/0.37/0.16, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 43lGXh6s5wz10N1)
Jan 23 14:07:17 albion postfix/qmgr[71399]: 7A3DD10343F8: removed
Jan 23 14:07:21 albion postfix/pickup[71398]: E856410343FA: uid=501 from=<[hidden email]>
Jan 23 14:07:21 albion postfix/cleanup[71457]: E856410343FA: message-id=<[hidden email]>
Jan 23 14:07:21 albion postfix/qmgr[71399]: E856410343FA: from=<[hidden email]>, size=468, nrcpt=1 (queue active)
Jan 23 14:07:22 albion postfix/smtp[71460]: 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 14:07:22 albion postfix/smtp[71460]: E856410343FA: to=<[hidden email]>, relay=smtp.your-site.com[205.233.73.98]:587, delay=0.51, delays=0/0/0.36/0.14, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 43lGXp2P8lz10g1)
Jan 23 14:07:22 albion postfix/qmgr[71399]: E856410343FA: removed
Jan 23 14:09:28 albion postfix/postfix-script[71490]: refreshing the Postfix mail system
Jan 23 14:09:28 albion postfix/master[71397]: reload -- version 3.4-20190121-nonprod, configuration /usr/local/etc/postfix

--
Larry Stone
[hidden email]




Reply | Threaded
Open this post in threaded view
|

Re: logfile support for MacOS

Wietse Venema
Larry Stone:

>
>
> > On Jan 23, 2019, at 1:29 PM, Wietse Venema <[hidden email]> wrote:
> >
> > Larry, can you insert one line in src/util/msg_logger.c,
> > or apply the patch at the end of this message?
>
> Wietse, thanks - that did it! I?m seeing the timestamps I expect.
> With reference to the earlier notes, I do not have the expertise
> to argue one way or the other about MacOS doing something weird.
> But it should not have been any power-saving / battery issue as
> this was on a desktop iMac. If your patch just works around another
> MacOS weirdness, thanks.

No, this was a Postfix bug. I did lots of tests, but each test ran
in a very short time span, so the frozen time stamp was not obvious.

        Wietse