Thread: Re: [GENERAL] Postgres logs to syslog LOCAL0

[ redirecting to a more appropriate list ]

han.holl@informationslogik.nl writes:
> I've noticed that, even though I specified LOCAL5 as syslog facility, postgres
> nevertheless logs _some_ events to LOCAL0.

I've thought of a theory about this: if the first write_syslog() call
occurs before guc.c has read the config file and set Syslog_facility
to LOCAL5, then the facility value would get locked down as the default
LOCAL0 and subsequently never changed.

Since write_syslog() certainly wouldn't be called until Log_destination
is changed from its default, the triggering situation would have to be
an elog call occuring between the assignments to Log_destination and
Syslog_facility --- ie, an elog coming from guc.c itself.  But that
doesn't seem out of the question at all.

The problem with this theory as an explanation for Han's report is that
he says only "some" events are reported to LOCAL0.  Under this theory
a postmaster that had gotten into this mode would *always* report to
LOCAL0, and so would all its children (at least in non-EXEC_BACKEND
builds, which is to say any non-Windows build).  Han, can you quantify
"some" any better?

> Log lines look like:
> Oct 14 08:55:02 pavenlo  root palga [local] SELECT: [17-1] LOG:  duration: \
> 2953.658 ms  statement: select rapnaam from udps where ((geboortedatum = \
> '1954-01-21') and (naamman ~ '^thie'))
> Oct 14 08:55:02 pavenlo  root palga [local] SELECT: [17-2]  limit 1000

Another strange thing here is that the funny log entries don't show the
PID of the originating process.  Since we *always* call openlog() with
the LOG_PID flag bit, this should be impossible.

> +preload_libraries =
> '/usr/prod/postgres/rubriek:rub_initialize,/usr/prod/postgres/drap,/usr/prod/postgres/naam'

Han, what are these libraries?  Is it possible that any of them are
issuing openlog() calls?

            regards, tom lane

han.holl@informationslogik.nl writes:
> On Friday 14 October 2005 19:05, you wrote:
>> [ redirecting to a more appropriate list ]
>>> +preload_libraries =
>>> '/usr/prod/postgres/rubriek:rub_initialize,/usr/prod/postgres/drap,/usr/p
>>> rod/postgres/naam'
>>
>> Han, what are these libraries?  Is it possible that any of them are
>> issuing openlog() calls?
>>
> Yes, it does:
> static void log_error(const char *mess, int code)
> {
>         openlog("PG_FETCH", 0, LOG_LOCAL0);
>         syslog(LOG_ERR, "%s %d", mess, code);
>         closelog();
> }

> I didn't think of this because I didn't see the PG_FETCH in the log.

Well, that explains both the disappearance of the LOG_PID bit and the
reversion to LOCAL0 ... I think.  One issue is that if that openlog()
call overrode our original one, then why didn't we see PG_FETCH in the
log messages?

What platform are you on, exactly?  I'm hoping it's something we can
look at the source of openlog for ...

            regards, tom lane

han.holl@informationslogik.nl writes:
> On Monday 17 October 2005 15:57, you wrote:
>> What platform are you on, exactly?  I'm hoping it's something we can
>> look at the source of openlog for ...
>>
> You sure can: Redhat Linux 9, glibc-2.3.2-27.9.7

Hmm, the closest I can find in Red Hat's archives is glibc-2.3.2-27.9.6 ??
Should be close enough for this though.

Digging around in that source tree, I see that:

* openlog stores its first argument in a static variable LogTag,
  if the first argument isn't NULL.

* closelog resets LogTag to NULL, but it doesn't touch the other saved
  values.

* syslog does this:

        if (LogTag == NULL)
          LogTag = __progname;
        if (LogTag != NULL)
          fputs_unlocked (LogTag, f);

where __progname is an internal glibc variable initialized by crt0.
I didn't bother to track down the details of __progname, but it seems
highly likely that it points to the original value of argv[0].

So now we can explain all the symptoms:

    * elog.c does an initial openlog() call, which it relies on
      being good henceforth.

    * your routine overwrites the parameters by doing another openlog().

    * then you do closelog().  At this point LogTag is reset to NULL
      but the option and facility settings remain as you set them.

    * the next syslog() call sets LogTag to point into the original
      argv space, then does an implicit openlog().

If you look at ps_status.c, it's not too surprising that LogTag would
end up pointing at some part of our current process status string.
Therefore we now understand the bizarre appearance of the status string
where "postgres" should be, plus the disappearance of the pid (LOG_PID
got turned off), plus the selection of LOG_LOCAL0.

In short, you've got to change that preloaded library.  It has no
business calling either openlog or closelog.  The only way the backend
could defend itself against this is to call openlog again for every
syslog call, which we are certainly not going to do because of
performance considerations.

The changes I made in elog.c over the weekend seem not to be related
to your problem at all.  Still, I think they are good robustness
improvements and I don't plan to revert them.

            regards, tom lane