From: cwelton at greenplum.com (Caleb Welton) Date: Thu, 22 Jul 2010 11:23:58 -0700 Subject: [Pljava-dev] pljava error logging levels In-Reply-To: <201007211505.50676.fluca1978@infinito.it> References: <3F082C5B-116B-4CB7-9755-B3D306B8C942@greenplum.com> <201007211505.50676.fluca1978@infinito.it> Message-ID: <910AD504-DD44-40EC-9592-426A84F5FA05@greenplum.com> 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 at the time of JVM initialization. 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 Thanks, Caleb -------------- next part -------------- An HTML attachment was scrubbed... URL: