Subject: [Pljava-dev] pljava error logging levels

From: cwelton at greenplum.com (Caleb Welton)
Date: Mon, 12 Jul 2010 13:47:27 -0700

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

---

From: fluca1978 at infinito.it (Luca Ferrari)
Date: Wed, 21 Jul 2010 15:05:50 +0200

On Monday, July 12, 2010 10:47:27 pm Caleb Welton's cat walking on the 
keyboard wrote:
> 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, ...
> 

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>

---

From: cwelton at greenplum.com (Caleb Welton)
Date: Thu, 22 Jul 2010 11:23:58 -0700

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.

Agreed.

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.

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)

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

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>

---

From: fluca1978 at infinito.it (Luca Ferrari)
Date: Mon, 26 Jul 2010 12:00:04 +0200

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>

---

From: cwelton at greenplum.com (Caleb Welton)
Date: Mon, 26 Jul 2010 14:08:34 -0700

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>

---

From: fluca1978 at infinito.it (Luca Ferrari)
Date: Tue, 27 Jul 2010 09:00:33 +0200

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

---

From: cwelton at greenplum.com (Caleb Welton)
Date: Tue, 27 Jul 2010 10:57:15 -0700

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

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

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.