[Pljava-dev] pljava error logging levels

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

This has several consequences, including:
1) Future changes to the logging level are ignored by the JVM which will continue to use the setting at JVM initialization.
2) The setting of client_min_messages is ignored, so a setting where INFO messages should be returned to the client but not written to the log is not handled correctly.

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

Additionally there seems to an additional problem with the actual mapping of logging levels.

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

Note that in Java "CONFIG" is a finer logging level than "INFO", whereas in Postgres "NOTICE" is a coarser logging level than "INFO", which makes this mapping of error levels incorrect.

Thanks,
Caleb

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

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?

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

> 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

-------------- next part --------------
A non-text attachment was scrubbed...
Name: log.patch
Type: text/x-patch
Size: 2381 bytes
Desc: not available
URL: <http://lists.pgfoundry.org/pipermail/pljava-dev/attachments/20100721/d710e9d0/attachment.bin>

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>

Maybe now I get the point:
1) Session calls ELogHandler.init() that initializes the parameters, including
the logging level;
2) the Java logging framework does not call publish if the logging level is
not adeguate, and therefore changes in the log/client_min_messages are not
seen.

In this situation there are three solutions I guess:
1) each time a logging is successful (i.e., publish has been called), we need
to reconfigure the log level of the handler. The problem with this is that we
risk to get unlogged messages for a while, until one pass the publish method.
2) once a new handler is created it must self update its value of the log
level. The problem with this is that if the handler is kept for a while, the
changes are not seen.
3) create a thread that, once a while, reloads the log level and set it into
the current log level, but this causes a lot of threads (one per handler)
4) keep a map of all created handlers and update them each time a new one is
created. The problem is that the thread will execute when the control is on
the java space, due to the locking mechanism of the backend, and therefore it
will update the handlers with a little lag once a java call is made. This
should not represent a big problem, because before a java call is made there
is no need to change the java logging setting. I attach a patch also for this
solution mixed with the number 2.

Any comments?

Luca
-------------- next part --------------
A non-text attachment was scrubbed...
Name: eloghandler.thread.patch
Type: text/x-patch
Size: 10671 bytes
Desc: not available
URL: <http://lists.pgfoundry.org/pipermail/pljava-dev/attachments/20100726/385cc939/attachment.bin>

Well the original question I asked was "Why does PL/Java try to filter log levels at all?". If we simply disabled the log filtering from PL/Java and let the log filtering happen naturally in Postgres then all of these problems just go away.

This could be accomplished using the attached patch.

Alternatively, significant improvement could be made by at least setting the log level correctly at init time by checking both log_min_messages AND client_min_messages and setting the log level to whichever is FINER grained logging. But since this still doesn't address changes to the GUCs over time it seems like a less desirable approach.

Regards,
Caleb

-------------- next part --------------
A non-text attachment was scrubbed...
Name: logHandler.patch
Type: application/octet-stream
Size: 4589 bytes
Desc: logHandler.patch
URL: <http://lists.pgfoundry.org/pipermail/pljava-dev/attachments/20100726/ada19b3b/attachment.obj>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: ATT00001..txt
URL: <http://lists.pgfoundry.org/pipermail/pljava-dev/attachments/20100726/ada19b3b/attachment.txt>

On Monday, July 26, 2010 11:08:34 pm Caleb Welton's cat walking on the
keyboard wrote:
> Well the original question I asked was "Why does PL/Java try to filter log
> levels at all?". If we simply disabled the log filtering from PL/Java and
> let the log filtering happen naturally in Postgres then all of these
> problems just go away.
>
> This could be accomplished using the attached patch.
>
> Alternatively, significant improvement could be made by at least setting
> the log level correctly at init time by checking both log_min_messages AND
> client_min_messages and setting the log level to whichever is FINER
> grained logging. But since this still doesn't address changes to the
> GUCs over time it seems like a less desirable approach.

The patch is doing exactly this: choosing the finer logging level between
client and log_min_messages, but this is a static setup, as you say. I think
we should have a way to get notified of when the server settings have changed.
Moreover, what happen if you change the client_min_messages within an
interactive session before calling a Java method? With a setup done at the
initialization phase we could have the same problem of logs missed.
So I guess we should re-initialize log levels at least as soon as the handler
is created (not only at the jvm initialization) and maybe each time (or each
n-times) the publish method is called. That's why I proposed a threaded
solution. However, the best is to be notified about changes in the configuration
of the session and/or of the server.

Luca

On Jul 27, 2010, at 12:00 AM, Luca Ferrari wrote:

> On Monday, July 26, 2010 11:08:34 pm Caleb Welton's cat walking on the
> keyboard wrote:
>> Well the original question I asked was "Why does PL/Java try to filter log
>> levels at all?". If we simply disabled the log filtering from PL/Java and
>> let the log filtering happen naturally in Postgres then all of these
>> problems just go away.
>>
>> This could be accomplished using the attached patch.
>
> The patch is doing exactly this: choosing the finer logging level between
> client and log_min_messages, but this is a static setup, as you say.

I direct your attention to the line:

props.setProperty(".level", getPgLevel().getName());

Which my patch removed from ELogHandler.init().

By removing this property setting the instantiated log handler no longer
filters log messages as they come in and all log messages get published
and passed to Postgres.

That alone fixes the problem. At which point getPgLevel() becomes
largely obsolete, but I figured I would "fix" it as well since it was defined
as a public method and it was conceivable that someone might be
using it. Removing and/or deprecating getPgLevel() would also be an option.

> I think
> we should have a way to get notified of when the server settings have changed.
> Moreover, what happen if you change the client_min_messages within an
> interactive session before calling a Java method?

That was never an issue to begin with. Since setup occurs on the first function call
any GUC changes that occur prior to that simply look like the normal server settings.

> With a setup done at the
> initialization phase we could have the same problem of logs missed.
> So I guess we should re-initialize log levels at least as soon as the handler
> is created (not only at the jvm initialization) and maybe each time (or each
> n-times) the publish method is called. That's why I proposed a threaded
> solution.

I didn't like the threaded solution because behavior would be non-deterministic
depending on thread execution timing.

> However, the best is to be notified about changes in the configuration
> of the session and/or of the server.

I think this and not having Java pre-filter the messages are roughly equivalent,
and since not pre-filtering seemed less complicated it was what I did in the patch.