Thread: BUG #7559: syslogger doesn't close stdout and stderr

BUG #7559: syslogger doesn't close stdout and stderr

From
reinhard@m4x.de
Date:
The following bug has been logged on the website:

Bug reference:      7559
Logged by:          Reinhard Max
Email address:      reinhard@m4x.de
PostgreSQL version: 9.1.5
Operating system:   openSUSE
Description:        =


When initially starting up, syslogger keeps stdout and stderr open instead
of closing them and reopening them from /dev/null for proper daemonisation.
This causes the process that triggers PostgreSQL to hang if it uses a pipe
to synchronize itself with the backgrounding of the server.

I've sent a proposed fix to Peter Eisentraut.

Re: BUG #7559: syslogger doesn't close stdout and stderr

From
Tom Lane
Date:
reinhard@m4x.de writes:
> When initially starting up, syslogger keeps stdout and stderr open instead
> of closing them and reopening them from /dev/null for proper daemonisation.

How exactly could it "close and reopen" them without losing their
identity?  And what makes /dev/null necessarily the right substitute?

I don't think we should change this within Postgres.  We removed logic
associated with daemonization altogether in 9.2 --- it's the
responsibility of the calling script to close any files it doesn't want
left open.

            regards, tom lane

Re: BUG #7559: syslogger doesn't close stdout and stderr

From
Reinhard Max
Date:
On Wed, 19 Sep 2012 at 12:39, Tom Lane wrote:

> reinhard@m4x.de writes:
>> When initially starting up, syslogger keeps stdout and stderr open
>> instead of closing them and reopening them from /dev/null for
>> proper daemonisation.
>
> How exactly could it "close and reopen" them without losing their
> identity?

I am not sure what you mean by "losing their identity", but the code
for what I think is the right thing to do was already there. It opens
/dev/null and then calls dup2() to copy it to FDs 1 and 2.

All my patch does is removing the check for the redirection_done
variable which caused this code to only be executed when the logger
gets restarted from postmaster after it has been killed.

> And what makes /dev/null necessarily the right substitute?

Because it is what virtually all deamons have been doing for the last
3..4 decades?

> I don't think we should change this within Postgres. We removed
> logic associated with daemonization altogether in 9.2

Huh - why that?

> it's the responsibility of the calling script to close any files it
> doesn't want left open.

Sorry, but that's nonsense.

Under Unix it has always been the responsibility of a deamon to
properly deamonize itself, which consists of forking, giving up the
controlling TTY and reopening stdin, stdout and stderr from /dev/null.

If you make it the responsibility of the calling sctipt to do the
/dev/null redirection, PostgreSQL has no chance of reporting any
errors it might run into before its own logging has been set up.

cu
     Reinhard

Re: BUG #7559: syslogger doesn't close stdout and stderr

From
Heikki Linnakangas
Date:
On 20.09.2012 00:05, Reinhard Max wrote:
> On Wed, 19 Sep 2012 at 12:39, Tom Lane wrote:
>> reinhard@m4x.de writes:
>> And what makes /dev/null necessarily the right substitute?
>
> Because it is what virtually all deamons have been doing for the last
> 3..4 decades?
>
>> I don't think we should change this within Postgres. We removed logic
>> associated with daemonization altogether in 9.2
>
> Huh - why that?

I believe Tom is referring to the removal of silent_mode in 9.2, see
http://archives.postgresql.org/pgsql-general/2011-06/msg00796.php and
http://archives.postgresql.org/pgsql-hackers/2011-06/msg02156.php. "We
removed logic associated with daemonization" meant that the logic was
removed from postmaster, because the preferred way to do it is by
calling "pg_ctl start". pg_ctl redirects to /dev/null as you'd expect.

- Heikki

Re: BUG #7559: syslogger doesn't close stdout and stderr

From
Reinhard Max
Date:
On Thu, 20 Sep 2012 at 10:31, Heikki Linnakangas wrote:

> I believe Tom is referring to the removal of silent_mode in 9.2, see
> http://archives.postgresql.org/pgsql-general/2011-06/msg00796.php
> and
> http://archives.postgresql.org/pgsql-hackers/2011-06/msg02156.php.
> "We removed logic associated with daemonization" meant that the
> logic was removed from postmaster, because the preferred way to do
> it is by calling "pg_ctl start". pg_ctl redirects to /dev/null as
> you'd expect.

Well, I was involved in that discussion and as a consequence stopped
using silent_mode in the SUSE RPMs. That's what triggered the problem
and I just verified that it still exists on 9.2.

After starting PostgreSQL with pg_init, stdout and stderr of all
processes are pipes to the logger (as intended), but the logger itself
still has FDs 1 and 2 open as inherited from pg_init. I think
requiring the caller of pg_init to redirect them is not practical,
because then pg_init itself can't give feedback to the user. So it has
to be done either in pg_init or in the logger when those channels
aren't needed anymore. I'd prefer doing it in the logger, because the
code for it is already there and so that it also works when starting
PostgreSQL without using pg_init.

I've attached the patch I sent to Peter which applies to 9.1 and 9.2.

It also fixes a problem with the reopening of stdout and stderr from
/dev/null where the temporary FD must not be closed if it is either 1
or 2, which is quite likely to happen as we've just closed these two
and open() typically gets the lowest unused FD number.

BTW, I think the other dup2() for stderr in syslogger.c should get
such a check as well, even if the clash is less likely to happen
there.

cu
     Reinhard

Re: BUG #7559: syslogger doesn't close stdout and stderr

From
Tom Lane
Date:
Reinhard Max <reinhard@m4x.de> writes:
> After starting PostgreSQL with pg_init, stdout and stderr of all
> processes are pipes to the logger (as intended), but the logger itself
> still has FDs 1 and 2 open as inherited from pg_init. I think
> requiring the caller of pg_init to redirect them is not practical,
> because then pg_init itself can't give feedback to the user.

That's a fair point.  (I assume you mean pg_ctl not pg_init?)

> So it has
> to be done either in pg_init or in the logger when those channels
> aren't needed anymore. I'd prefer doing it in the logger, because the
> code for it is already there and so that it also works when starting
> PostgreSQL without using pg_init.

Well, I would have no objection to changing pg_ctl so that it redirects
the postmaster's stdout/stderr when a -l switch is given (actually,
I thought it did that already...).  I do object to changing the logger's
behavior as you suggest, because that will break use-cases that work
today.  One that I've used personally is adding "fprintf(stderr)" calls
in the logger for debugging the logger itself.

            regards, tom lane

Re: BUG #7559: syslogger doesn't close stdout and stderr

From
Tom Lane
Date:
Reinhard Max <reinhard@m4x.de> writes:
> On Thu, 20 Sep 2012 at 11:06, Tom Lane wrote:
>> Well, I would have no objection to changing pg_ctl so that it
>> redirects the postmaster's stdout/stderr when a -l switch is given
>> (actually, I thought it did that already...).

> Well, going that route forces me to either introduce yet another log
> file for the user to look into when something goes wrong with
> PostgreSQL, or to suppress that information completely (when using -l
> /dev/null). I think it is common practice for daemons to report early
> errors to stderr (so that the user starting the serivice gets to see
> them on the terminal) and after successfull startup redirect to
> /dev/null and log to syslog or their own logging mechanism.

Well, at least in the Fedora/RHEL packages I had such an additional log
file for years.  Printing complaints to "the terminal" turns out to not
be tremendously useful in service start scripts, because even if there's
somebody watching the console during boot, the info tends to fly
offscreen pretty quick.  (systemd finally improved that by connecting
services' stdout/stderr to syslog by default --- but it's still not
going to the user's screen.)

>> I do object to changing the logger's behavior as you suggest,
>> because that will break use-cases that work today. One that I've
>> used personally is adding "fprintf(stderr)" calls in the logger for
>> debugging the logger itself.

> Do you also have use cases in mind that are relevant for end users of
> PostgreSQL who never even look into the source code?

Sure.  Under systemd the logger's stderr will go to /var/log/messages.
Admittedly, it shouldn't ever print anything there during normal
operation, but we don't have control over all the code in the process.
For instance, if glibc were to detect malloc-arena corruption, its
complaints about that would end up in /var/log/messages.  Under your
proposal they'd end up in /dev/null.

            regards, tom lane

Re: BUG #7559: syslogger doesn't close stdout and stderr

From
Reinhard Max
Date:
On Thu, 20 Sep 2012 at 11:06, Tom Lane wrote:

> (I assume you mean pg_ctl not pg_init?)

Yes, sorry for the confusion.

> Well, I would have no objection to changing pg_ctl so that it
> redirects the postmaster's stdout/stderr when a -l switch is given
> (actually, I thought it did that already...).

Well, going that route forces me to either introduce yet another log
file for the user to look into when something goes wrong with
PostgreSQL, or to suppress that information completely (when using -l
/dev/null). I think it is common practice for daemons to report early
errors to stderr (so that the user starting the serivice gets to see
them on the terminal) and after successfull startup redirect to
/dev/null and log to syslog or their own logging mechanism.

> I do object to changing the logger's behavior as you suggest,
> because that will break use-cases that work today. One that I've
> used personally is adding "fprintf(stderr)" calls in the logger for
> debugging the logger itself.

Do you also have use cases in mind that are relevant for end users of
PostgreSQL who never even look into the source code? If not (i.e. if
the use cases are more developer-centric), I think the default should
be to let the logger do the redirection and having a command line
switch or postgresql.conf variable to suppress it for debugging
purposes.

cu
     Reinhard

Re: BUG #7559: syslogger doesn't close stdout and stderr

From
Peter Eisentraut
Date:
On 9/20/12 11:06 AM, Tom Lane wrote:
> Well, I would have no objection to changing pg_ctl so that it redirects
> the postmaster's stdout/stderr when a -l switch is given (actually,
> I thought it did that already...).  I do object to changing the logger's
> behavior as you suggest, because that will break use-cases that work
> today.  One that I've used personally is adding "fprintf(stderr)" calls
> in the logger for debugging the logger itself.

The weird thing is, when the logger process dies and is restarted by the
postmaster, then both stdout and stderr point to /dev/null.  So the
behavior is inconsistent either way.

Re: BUG #7559: syslogger doesn't close stdout and stderr

From
Tom Lane
Date:
Peter Eisentraut <peter_e@gmx.net> writes:
> On 9/20/12 11:06 AM, Tom Lane wrote:
>> Well, I would have no objection to changing pg_ctl so that it redirects
>> the postmaster's stdout/stderr when a -l switch is given (actually,
>> I thought it did that already...).  I do object to changing the logger's
>> behavior as you suggest, because that will break use-cases that work
>> today.  One that I've used personally is adding "fprintf(stderr)" calls
>> in the logger for debugging the logger itself.

> The weird thing is, when the logger process dies and is restarted by the
> postmaster, then both stdout and stderr point to /dev/null.  So the
> behavior is inconsistent either way.

Yeah, that's annoying but there's no very good way to work around it.
Fortunately, the logger doesn't die very often.  All of the use-cases
I've thought of for wanting to capture stderr output for it amount to
debugging of some form or other, so it's probably good enough for that
to only work in the first logger incarnation after database start ---
but Reinhard is proposing to make it not work at all, and that I don't
like.

            regards, tom lane

Re: BUG #7559: syslogger doesn't close stdout and stderr

From
Reinhard Max
Date:
On Fri, 21 Sep 2012 at 14:17, Tom Lane wrote:

> All of the use-cases I've thought of for wanting to capture stderr
> output for it amount to debugging of some form or other, so it's
> probably good enough for that to only work in the first logger
> incarnation after database start --- but Reinhard is proposing to
> make it not work at all, and that I don't like.

No, I am proposing to have consistent behaviour between the first and
subsequent incarnations by default and add a switch to turn on
debugging mode for the first incarnation, if needed.

AFAICS the /dev/null redirection as per my patch would happen *after*
postmaster and/or logger have had a chance to speak up about early
errors that might prevent PostgreSQL from starting up at all, so
errors that happen during startup in production scenarios won't be
suppressed regardless where the user or init script redirects them.

Only stuff like the glibc memory debugging output you mentioned before
(which only get produced when glibc itself runs in some debugging
mode) would get suppressed by default if it happens after the
syslogger has done the redirection.


cu
     Reinhard