Postgres logs to syslog LOCAL0

I tested LOCAL5 here and got lines like:

Oct 14 08:41:06 candle postgres[8668]: [1-1] LOG: duration: 1.210 ms
statement: select 100;

I don't see any SELECT: entry in there. In fact, SELECT: is coming from
syslog, not from PostgreSQL. We only generate the stuff after the
closing ].

---------------------------------------------------------------------------

han.holl@informationslogik.nl wrote:

Hi,

I've noticed that, even though I specified LOCAL5 as syslog facility, postgres
nevertheless logs _some_ events to LOCAL0.
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

(It's a bit messy). Anyway, the essentila difference is the SELECT: entry
which is not present in regular logging to LOCAL5.
These events are _not_ reported in LOCAL5.

Because it's shorter that a complet postgresql.conf,here's the diff against
/usr/share/pgsql/postgresql.conf.sample, from postgresql-8.0.3-1PGDG for RH9.

Have I missed something ?

Cheers,

Han Holl

--- /usr/share/pgsql/postgresql.conf.sample	2005-09-22 15:49:14.000000000 
+0200
+++ /u/postgres/postgresql.conf	2005-10-14 00:08:55.000000000 +0200
@@ -45,7 +45,7 @@

# - Connection Settings -

-#listen_addresses = 'localhost'	# what IP interface(s) to listen on; 
+listen_addresses = '*'	# what IP interface(s) to listen on; 
# defaults to localhost, '*' = any
#port = 5432
#max_connections = 100
@@ -86,7 +86,7 @@
# - Kernel Resource Usage -

#max_files_per_process = 1000	# min 25
-#preload_libraries = ''
+preload_libraries = 
'/usr/prod/postgres/rubriek:rub_initialize,/usr/prod/postgres/drap,/usr/prod/postgres/naam'

# - Cost-Based Vacuum Delay -

@@ -173,7 +173,7 @@

# - Where to Log -

-#log_destination = 'stderr'	# Valid values are combinations of stderr,
+log_destination = 'syslog'	# Valid values are combinations of stderr,
# syslog and eventlog, depending on
# platform.

@@ -197,7 +197,7 @@
# so many kilobytes of log output. 0 to disable.

# These are relevant when logging to syslog:
-#syslog_facility = 'LOCAL0'
+syslog_facility = 'LOCAL5'
#syslog_ident = 'postgres'

@@ -218,7 +218,7 @@
# debug5, debug4, debug3, debug2, debug1,
# info, notice, warning, error, panic(off)

-#log_min_duration_statement = -1 # -1 is disabled, in milliseconds.
+log_min_duration_statement = 500 # -1 is disabled, in milliseconds.

#silent_mode = false # DO NOT USE without syslog or redirect_stderr

@@ -239,7 +239,7 @@
# %s=session start timestamp %x=transaction id
# %q=stop here in non-session processes
# %%='%'
-#log_statement = 'none'		# none, mod, ddl, all
+log_statement = 'none'		# none, mod, ddl, all
#log_hostname = false

@@ -278,7 +278,7 @@

# - Locale and Formatting -

-#datestyle = 'iso, mdy'
+datestyle = 'iso, dmy'
#timezone = unknown # actually, defaults to TZ environment setting
#australian_timezones = false
#extra_float_digits = 0 # min -15, max 2

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073

Bruce Momjian <pgman@candle.pha.pa.us> writes:

I don't see any SELECT: entry in there. In fact, SELECT: is coming from
syslog, not from PostgreSQL. We only generate the stuff after the
closing ].

The SELECT: is probably coming from syslog_ident. I note the following
comment in the Linux man page for syslog(3):

The parameter ident in the call of openlog() is probably stored as-is.
Thus, if the string it points to is changed, syslog() may start
prepending the changed string, and if the string it points to ceases to
exist, the results are undefined. Most portable is to use a string
constant.

This is troubling since a reload of the config file could well move
things around. We should probably pass strdup(Syslog_ident) to openlog,
not just Syslog_ident.

However, that doesn't explain the change in facility ...

regards, tom lane

On Friday 14 October 2005 17:06, Tom Lane wrote:

This is troubling since a reload of the config file could well move
things around. We should probably pass strdup(Syslog_ident) to openlog,
not just Syslog_ident.

I can confirm that we use reload quite a lot to switch between full statement
logging and quieter behaviour.

None of our applications is using this format, that's for sure.

Cheers

Han Holl

[ 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