[Pljava-dev] pljava error logging levels

On Jul 21, 2010, at 6:05 AM, Luca Ferrari wrote:

On Monday, July 12, 2010 10:47:27 pm Caleb Welton's cat walking on the
keyboard wrote:
Hello, I had several questions about the ELogHandler in pljava, was hoping
someone could comment on it.

In postgres there is code to handle the filtering of logging levels and
this is controlled by several gucs for different types of logging. For
instance log_min_messages is used to control the logging level that gets
written to the log file, while client_min_messages is used to control the
logging level that gets displayed to the client. Looking at
ELogHandler.java I see that pljava bases its own decision on how the JVM
should filter logging level based on the setting of log_min_messages <b>at
the time of JVM initialization</b>.

Not sure to get it straight, however what I see is that:
1) the Backend.c has a method to set the log level that is used in JNICalls.c
in the printStackTraceMethod using DEBUG1 as thresold to print out logs (this
sounds ok to me);

Agreed.

2) in ELogHandler.java the publish method calls the Backend.log method, that
resolves to a native one that uses the ereport method in the Backend.c with
the declared level.

The problem is that the ELogHandler.publish() method only seems to be called when
the item being logged is within the current LogHandler level. If it is not in the LogHandler
level then the Backend.c ereport method is never called.

So what can happen is that, once the pljava process has started, someone on
the server increases the logging level (log_min_messages) and pljava continues
to use the old value. This is due to the fact that the correct reading of the
log_min_messages is done only in the init() method (more exactly in the
getPgLevel one). If this is the issue you are talking about the only solution
I see is to correct the Backend.log method in order to call the getPgLevel
before issuing the log record. However, this should not be a problem, since
the logging system of the server should ignore any message with a wrong
logging category. So, let's say you must log an DEBUG3 message and the server
has an INFO level, the message should be ignored at all, even if issued. When
the log_min_messages is raised to DEBUG3, another message should be logged.
Isn't it?

The changing of the setting is one of the problems I was commenting on.

The other point that you missed is that log_min_messages and client_min_messages
are different settings with different meanings.

In my configuration I have these settings:
log_min_messages = 'warning'
client_min_messages = 'info'

Which is to say that I want INFO messages returned to the client, but I do not want them
logged to the database log.

In this configuration what I see is that PL/Python has set its logging level to 'WARNING'
and as such the LogHandler never calls publish on messages of level 'INFO' and thus
these messages never get returned to the client like they should due to the current
setting of client_min_messages.

This is demonstratable using the "logMessage" function from the pljava examples.jar.

postgres=# show client_min_messages;
client_min_messages
---------------------
notice
(1 row)

postgres=# show log_min_messages;
log_min_messages
------------------
warning
(1 row)

postgres=# SELECT javatest.logMessage('INFO', 'hello');
logmessage
------------

(1 row)

postgres=# SELECT javatest.logMessage('WARNING', 'hello');
WARNING: 22 Jul 10 11:17:00 org.postgresql.example.LoggerTest hello
logmessage
------------

(1 row)

Note how the WARNING message was output, but the INFO message was not.

Starting a new session I can get different results if I change log_min_messages to match client_min_messages,
despite the fact that log_min_messages should not affect what messages are returned to the client.

postgres=# set log_min_messages=notice;
SET
postgres=# SELECT javatest.logMessage('INFO', 'hello');
INFO: 22 Jul 10 11:20:31 org.postgresql.example.LoggerTest hello
logmessage
------------

(1 row)

Question) Why does PLJava even try to install its own log level filtering
when the Postgres logger already is handling this?

I don't get this, in my opinion the pljava is not installing a filter handler,
but a translation handler from the Java levels to the Pg ones.

The example above clearly indicates that the logLevel is being used as a filter as well as a translation.

In Java there are the following logging levels, from highest to lowest:
SEVERE, WARNING, INFO, CONFIG, FINE, FINER, FINEST In Postgres the logging
levels, from highest to lowest are: PANIC, FATAL, ERROR, WARNING, NOTICE,
INFO, LOG, DEBUG1, DEBUG2, ...

pljava creates a mapping as follows:
SEVERE => ERROR
WARNING => WARNING
INFO => INFO
CONFIG => NOTICE

Right, pg's notice is mapped over Java's config, that is higher than INFO-
INFO. Moreover I don't understand why fatal is mapped to OFF and not to
SEVERE. Maybe the patch I attach can fix the problem, but since we are mapping
more levels than those available in Java we have some clashes.

Luca

<log.patch>

Thanks,
Caleb

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.pgfoundry.org/pipermail/pljava-dev/attachments/20100722/bc5e2f72/attachment.html>