Thoughts-on-logging
Thoughts on logging
Update: This turns out to be more timely than I realized—PL/Pythonu is also developing a patch (starting last month) to the same end.
On their client side, psycopg2 already exposes a documented, supported PostgreSQL-specific Diagnostics object.
Note: this page does not describe how PL/Java currently works, except in the “Background” part. It is a proposal for further development.
Also, to anyone reading this for review or comment, a lot of this material may be more familiar than it is to me. If I seem to describe it in excessive detail, please regard that as my effort to have it straight in my own head.
Also also, to some it may seem strange that I use phrases like “log event” without insisting on any essential difference between thrown exceptions and calls on loggers. It’s true, I’m not marking any such essential difference, and I hope, before this is done, that won’t seem so strange.
So, here goes.
… logging isn’t particularly magical.
—Dave Cramer
… it’s what you do with it.
—variously attributed
Background
PostgreSQL has supremely good log messages.
It even has a style guide for writing them, and it pays off in the well-known quality and helpfulness of PostgreSQL messages.
Part of the excellence of PostgreSQL’s messages can be traced to their rich structure. A message is not a blob of text with whatever details seemed useful while writing the code. It is a structured record with information serving several specific purposes and at several distinct levels of detail:
| item | pq | PL/pgSQL | pgjdbc (+ -ng Notice) | pgjdbc-ng Exc | PL/Java |
|---|---|---|---|---|---|
| elevel | S | getSeverity | getErrorLevel | ||
| sqlstate | C | RETURNED_SQLSTATE | getSQLState getCode | getSQLState | getSqlState |
| message | M | MESSAGE_TEXT | getMessage | getMessage | getMessage |
| detail | D | PG_EXCEPTION_DETAIL | getDetail | getDetail | |
| hint | H | PG_EXCEPTION_HINT | getHint | getHint | |
| context | W | PG_EXCEPTION_CONTEXT | getWhere | getContextMessage | |
| schema_name | s | SCHEMA_NAME | getSchema | getSchema | |
| table_name | t | TABLE_NAME | getTable | getTable | |
| column_name | c | COLUMN_NAME | getColumn | getColumn | |
| datatype_name | d | PG_DATATYPE_NAME | getDatatype | getDatatype | |
| constraint_name | n | CONSTRAINT_NAME | getConstraint | getConstraint | |
| cursorpos | P | getPosition | getCursorPos | ||
| internalpos | p | getInternalPosition | getInternalPos | ||
| internalquery | q | getInternalQuery | getInternalQuery | ||
| filename | F | getFile | getFilename | ||
| lineno | L | getLine | getLineno | ||
| funcname | R | getRoutine | getFuncname | ||
| output_to_server | isOutputToServer | ||||
| output_to_client | isOutputToClient | ||||
| show_funcname | isShowFuncname | ||||
| saved_errno | getSavedErrno | ||||
| hide_stmt | |||||
| hide_ctx | |||||
| domain | |||||
| context_domain |
The libpq on-the-wire protocol preserves this structure, sending these
components (the ones with pq codes) distinctly and intact to the front end.
This gives client code enormous flexibility to catch and handle conditions
appropriately. If the condition has to be logged or reported to a user, it can
be shown at any appropriate level of detail, or even with a user interface that
permits drilling down from generalities to specifics.
How awesome is that? Consider this: I have seen, with my own eyes, non-technical users entering stuff into a PostgreSQL database (using something as generic as LibreOffice Base as the front end) have an error dialog pop up, read it, understand what had to be corrected in the entry, and recover on their own.
I challenge anyone who has had support experience to tell me that ain’t magic.
By and large, messages in PostgreSQL really are that good.
Original log event life cycle
A message that originates in the PostgreSQL backend proper begins as a call
to ereport or elog in elog.c. The rules there are just a bit
special:
If the message has any severity below
ERROR(so,DEBUG5,DEBUG4,DEBUG3,DEBUG2,DEBUG1,LOG,COMMERROR,INFO,NOTICE, orWARNING) or aboveERROR(so,FATAL,PANIC), it gets written immediately to logs / reported to the front end (according to thelog_min_messagesandclient_min_messagessettings), and then control returns to the call site if it was belowERROR, and does not return if it was above.If the severity is exactly
ERROR, it gets thrown PostgreSQL-style, and can be caught inPG_TRY/PG_CATCHconstructs. The elog code does not send it to the server log or the front end at all at that point, but only when (if ever) it bubbles up toPostgresMainwithout having been handled. If it gets caught and handled, then any logging becomes the responsibility of whatever code caught it.
Handling logged events in front-end code
Events from the server that arrive at the front end show up in a form the
front-end code can inspect and choose how to handle, either by polling for
them (libpq PQresultErrorField, JDBC getWarnings if less severe than
ERROR), or catching an exception (JDBC if severity is ERROR).
This code in turn might want to log an event (whether one received from the
backend as just described, or one originating in the front-end code itself).
To do that, it will probably use some convenient library available to it,
such as java.util.logging in Java.
For code that is really running in a front end, that’s the end of the story, but for code running in a backend PL, the story has only begun.
Handling logged events in a back-end PL
The first requirements for server-side code are the same as for the front end: it should be able to intercept, examine, and handle or not handle as appropriate, events that originate during its calls into the backend. PL/pgSQL makes a good example, with the trapping of errors built into the language, and inspection of (most) elements of the structure. Naturally, whatever isn’t caught in PL/pgSQL code should continue propagating outward with all its structured information intact.
In PL/pgSQL, all of that applies to events with the exact severity ERROR:
warnings/notices/etc. are invisible to PL/pgSQL code, as the
elog logic sends those right out from under the PL and straight
to the front-end client (conditioned only on the client_min_messages
setting). That might not be always ideal: there can be a tension between ease
of development/troubleshooting, favoring lots of logging, and confidentiality
demands, which could require that some messages be edited or suppressed, which
the PL code can’t do if they zip right past it.
As for PL/Java
PL/Java is at parity with PL/pgSQL as far as the ability to catch error events
from the backend (as Java SQLExceptions), or to propagate them up the stack
without information loss if they are not caught, or are caught and rethrown
without change.
Internally, it has good provisions for examining individual properties of
the event (currently not including the schema, table, column, datatype, and
constraint names that appeared in 9.3). However, these provisions
aren’t quite exposed yet to ordinary developers writing PL/Java code. Although
[[documented|Exception handling]] in the wiki, they aren’t accessible to
PL/Java code compiled normally against pljava-api.jar; it would have to
be compiled against the full pljava.jar and refer explicitly to
ServerException and ErrorData in the
org.postgresql.pljava.internal package.
(In passing, the current design where the magic only happens for a single
ServerException subclass of SQLException stands in the way of implementing
the categorized exceptions for JDBC 4.0.)
This is one area where a good API should be worked out and published.
PL/Java provides a JDBC interface to the backend, because that is how
the SQL/JRT standard is written, which PL/Java is meant to implement.
As far as JDBC is concerned, access to these implementation-specific error
details would be an extension, such as might be accessed
by unwrap on a standard JDBC object. Being committed to a JDBC
interface
to PostgreSQL, it would be ideal to agree on the details with the other,
front-end JDBC interfaces to PostgreSQL, as front-ends also receive finely
structured PostgreSQL error details that client code may want to examine.
(Again in passing, the fact that PL/Java presents a JDBC interface could raise
hopes that PL/Java functions are also able to examine warnings using the
standard JDBC mechanism. At the moment, they aren’t, and the
PG_TRY/PG_CATCH constructs aren’t enough to fix that, because only severity
level ERROR is handled that way. PL/Java would have to also use the
emit_log_hook in order to present a behavior analogous to JDBC on the
front end. It would then pull ahead of PL/pgSQL on that dimension.)
How do the other PostgreSQL JDBCs give access to error details?
pgjdbc
If you have an SQLException and it can be cast to
org.postgresql.util.PSQLException, then you can call
getServerErrorMessage() on it, and get a ServerErrorMessage.
Same deal if you have an SQLWarning that is castable to
org.postgresql.util.PSQLWarning. (None of this is
exactly trumpeted in the docs, and as you can see, the
PSQLException and PSQLWarning links above are to privateapi pages,
though the classes are public and accessible.)
Just as in PL/Java, the design here with a single PSQLException class is an
obstacle to moving forward with the categorized exceptions in JDBC 4.0.
pgjdbc-ng
In pgjdbc-ng, categorized exceptions are partially implemented: at least
there is one PGSQLIntegrityConstraintViolationException, and one
PGSQLSimpleException for everything else. To allow for multiple
categories, these share a common interface, PGSQLExceptionInfo.
Calling code does not need to test for a bunch of implementation-specific
class names, but can simply catch JDBC exceptions by their standard java.sql
names, and test for castability to a single interface.
Interestingly, the interface gives access only to the column, constraint,
datatype, schema, and table names available from PostgreSQL 9.3 onward (exactly
the five things PL/Java currently doesn’t expose!) and none of the much more
anciently supported detail, hint, context, etc. And pgjdbc-ng doesn’t supply
any SQLWarning subclass that implements it.
All of the elements the protocol can forward are available on a different
object, com.impossibl.postgres.protocol.Notice, but I am not sure
user code has any way to get one. The classes that use it seem fairly internal.
Unlike both PL/Java’s ErrorData and pgjdbc’s
ServerErrorMessage, in pgjdbc-ng both the
PGSQLExceptionInfo and the Notice are mutable,
providing setter methods as well as getters … leading naturally into
the next section.
Originating loggable events
Whether running client-side or in a server-side PL, it’s often helpful to look at the details of events from below, as the last section explored. But for a server-side PL, it doesn’t stop there, because server-side code is usually implementing logic that may have its own events to report, and as far as the client-side is concerned, those are just more events from the backend. Ideally, a PL function would be a “full citizen” and able to originate events (or rethrow caught ones wrapped in higher-level descriptions) with the same structure and quality one expects to see from PostgreSQL itself.
Here again, PL/pgSQL makes a good example. Using RAISE, code can generate an event with direct control of eleven of its most interesting attributes. (The ones not settable from PL/pgSQL, cursor positions, line numbers, and such, are at a level of detail few PL/pgSQL functions would want to work at anyway.)
PL/pgSQL has hit a kind of sweet spot with syntax that is so easy and clear it invites writing good messages that an ultimate user could find helpful. A statement like:
RAISE invalid_text_representation USING
MESSAGE = 'Unrecognized prefix in telephone number ' || tno,
DETAIL = 'The digits at the start of the number do not match any known '
'international number prefix. Are you sure it is right?',
HINT = 'If you are sure it''s right, ask the IT people if '
'there is a more recent "ITU-T bulletin 994" they can load. '
'Meanwhile, you can enter the number with a ! in front, '
'but it may be flagged on data quality reports until fixed.';
is about as clear as can be in the code, as well as giving anyone who receives it a fighting chance at understanding what has happened.
As for PL/Java
PL/Java is not yet at parity with PL/pgSQL on this dimension. If PL/Java code
catches any exception that began as a PostgreSQL ereport, that
Java exception will wrap an ErrorData object; if that same
exception is rethrown, it is transparently turned back into a PostgreSQL
event and continues on its way without information loss. But there is no way
for PL/Java code to create an exception with those properties. At best, it
can create an ordinary SQLException, which will turn into a PostgreSQL log
event using its SQLState and with its class name and message used as the
message.
For any other kind of exception, only message is set (from the exception
class name and message), and SQLState of XX000 for “internal error”.
When the origin is a Java exception, the severity will always be ERROR.
The other way for PL/Java code to originate a log event is to use the
logging API. PL/Java presents mostly Java standard APIs for code to use,
so in this case the API is java.util.logging, and PL/Java has
wired it so log events created that way are handed off to the PostgreSQL
logging system. (As a side effect of the way that system works, ‘logging’
any event with a severity that maps to PostgreSQL ERROR turns out to have
the same effect as throwing it, while at any other severity it simply gets
logged.)
When passed on to PostgreSQL, the details include the timestamp, class name
or logger name, the message, and the stack trace of any associated Java
throwable—but at present, all of that ends up strung together in the
message attribute of the PostgreSQL event, using a severity mapped from
the java.util.logging.Level. There are some other low-hanging-fruit
mappings that could be made automatically,
like the Java SourceClassName and SourceMethodName to
PostgreSQL filename and funcname, but for the present they are not,
and no other programmatic control over the created log event is yet available
to PL/Java code.
Mapping of severity levels
Because there are only seven predefined java.util.logging.Levels and
some of their names are different from PostgreSQL’s, PL/Java maps them as
follows:
| FINEST | FINER | FINE | INFO | WARNING | SEVERE | |||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|
| DEBUG5 | DEBUG4 | DEBUG3 | DEBUG2 | DEBUG1 | LOG | COMMERROR | INFO | NOTICE | WARNING | ERROR | FATAL | PANIC |
The Java level CONFIG isn’t explicitly mapped, and anything that isn’t
explicit will map to the PostgreSQL level LOG. For completeness, I’ve
shown the PostgreSQL levels FATAL and PANIC, though a good case could be
made that no PL code should ever be allowed to use them.)
How can JDBC front-end code originate events?
While the front-end situation may be simpler (there is no need to make
logging interoperate with server code in both directions, as PL/Java must),
some of the same considerations can be carried over. Even on the client end,
JDBC is not the client, it’s still part of the stack. It may originate
its own log messages or throw its own SQLExceptions for reasons other than
events it forwards from the backend. Layers above it see a clean, consistent
picture of “the database stack” when those events are of similar form, no
matter the level they come from.
These days, there could even be another sophisticated layer or three sitting on top of JDBC and beneath the application code, and it might want to have the same facilities available to it.
A day that I would like to see—and I think it can be reached—is the day when a PostgreSQL error can be raised by the backend, caught by PL/Java, examined in all its structured detail by Java code using some extension of the JDBC API, rethrown, piped to the frontend JDBC and thrown again to the client code, caught there, and examined again in the same structured detail using the same extended API.
This becomes even more appealing, and maybe even more achievable, if PL/Java and a front-end JDBC work toward sharing more code.
when throwing
Being JDBC interfaces, both pgjdbc and pgjdbc-ng throw the standard JDBC
SQLException (or, more precisely, subclasses of it), and create instances
of the standard SQLWarning, which are collected and polled for, rather than
thrown.
JDBC categorized exceptions are not yet supported by pgjdbc, and are
partly supported by pgjdbc-ng.
The pgjdbc-ng exceptions that implement PGSQLExceptionInfo can be
instantiated from scratch, and can have the column, constraint,
datatype, schema, and table names set, as well as the JDBC standard
SQLException attributes.
The pgjdbc PSQLException and PSQLWarning throwables
can be instantiated from scratch, and can be constructed from a
ServerErrorMessage that can also be built from scratch, allowing
control over all of the same log event attributes that would be sent to the
front-end for a backend event. However, the only way at present to construct
that ServerErrorMessage is to supply a String in the exact format of the
v3 protocol message that would come from the backend to represent the event.
The constructed exception’s message then is set to the entire result of
toString on the ServerErrorMessage.
when logging
Logging in pgjdbc, which is older than java.util.logging, is done with
the project-specific org.postgresql.core.Logger. This simple class identifies
messages with a connection ID prefix, filters them by severity, timestamps
them, and writes them to the DriverManager’s LogWriter. Unlike
java.util.logging, it doesn’t do message formatting or internationalization,
but a separate class org.postgresql.util.GT (also excluded from the
public API) does both when used in calls
to the logger. It gets translations from ResourceBundles, the same
form java.util.logging uses.
When logging a PSQLException instance that carries a
ServerErrorMessage, the result looks much like a message logged by the
backend, because ServerErrorMessage.toString produces that form (and it was
entirely stuffed into the message attribute of the exception).
Logging in pgjdbc-ng is done using java.util.logging, as in PL/Java,
and in keeping with the appearance of java.util.logging-related API in
JDBC itself starting in 4.1. In the existing examples in the code where a
NoticeException or SQLException are passed directly to the logger, most
of the available Notice or PGSQLExceptionInfo will
not be seen, as far as I can see, as toString has not been overridden.
ErrorUtils will create the SQLException subclasses using only
the message and sqlstate from the original Notice. A
NoticeException holds a reference to the Notice it was constructed
from, and has a method to retrieve it, but the exception’s message is set using
only the additional String passed to its constructor.
What would a nice API look like?
By this point it should be clear why I’ve been writing about “log events” as
one concept, when I might be expected to talk of log messages and exceptions
as separate things. In PostgreSQL and in JDBC, both are forms the same
information may take as it travels between A and B. It may be passed along
as a message on a log channel, received, and thrown as an exception; something
thrown as an exception can be caught and stuffed onto a log channel, where
“log channel” might mean the ereport conveyor in the server code, the
network protocol to the front end, the SQL warnings chain in JDBC, ….
This shapeshifting is not only possible but downright common in PostgreSQL and JDBC, and especially in PL/Java, where the same event may be batted about between those two forms repeatedly (how deep can the call stack get with PL/Java functions making SQL queries that call other functions also made in PL/Java?). And all of that is just fine as long as the conversion at each step is information-preserving and reversible.
An abstract LogRecord class (not derived from Exception)
We’ve seen that all three of (pgjdbc, pgjdbc-ng, PL/Java) include a
class of some sort (ServerErrorMessage, Notice, and
ErrorData, respectively) that is meant to carry all the information
about a PostgreSQL log event in its intact structured form, and can be
carried over a log channel or wrapped in an exception, and recovered at the
end of a journey either way.
So, my proposal starts here: there should be such a class, and it should be
documented and available as PostgreSQL extended JDBC API. For this discussion,
I’ll call it LogRecord. (There will be time for polishing name choices.
There is an existing Java class LogRecord but of course the package is
different.)
An interface for exceptions that carry LogRecords
To allow moving forward with the categorized exceptions in
JDBC 4.0, there needs to be an interface rather than a common parent class,
and simply has a setter and getter for attaching a LogRecord to the
exception. These would ordinarily not be used directly, but rather through
methods of LogRecord.
Different concrete subclasses of LogRecord
PL/Java would supply its special concrete implementation that wraps a native error-data block; a front-end JDBC would supply one (or two) that are initialized from the on-the-wire protocol. In all cases, there would be a plain pure-Java one that can be filled in from scratch.
An ereport-like API for creating a LogRecord from scratch
… starting with a static method on LogRecord and with method chaining:
import static org.postgresql.something.LogRecord.ereport;
...
logrec = ereport(Level.ERROR).errcode(ERRCODE_DIVISION_BY_ZERO)
.errmsg("You''ve tried to divide {0} by zero", dividend)
// .log() OR
// .throwAs(SQLException.class)
Methods for the conversions into/out of log system or exception
Examples log() and throwAs() were seen above, with throwAs a convenience
built on asException(...). If the LogRecord has been freshly constructed,
asException creates the correct JDBC 4 categorized exception with a reference
to the log record and vice versa. If that has happened already, it just returns
the already created exception object.
The static fromException() method does the reverse: if the exception was
created from a LogRecord originally (so, it implements the interface and its
log record reference isn’t null), just returns that original LogRecord. If
not, creates a new LogRecord initialized as informatively as possible with
whatever can be gleaned from the exception.
Those methods are what make possible the repeated batting around that an event might live through on its way from a deep call stack in PL/Java all the way out to a handler on the front end, without having serious identity crises. (It will be trickier inside PL/Java than I need to spend time on here, but should not be prohibitively so.)
In concert with existing standard API
I propose to converge on java.util.logging, and for this extended
LogRecord class to be derived from the standard LogRecord.
(Soon below I will touch on how to “converge on java.util.logging” without
serious disruption of pgjdbc, which currently uses the homegrown logging
class.)
The specialized class will have several extra methods, and some overridden
ones just to give it a reasonable default behavior when treated as an
ordinary java.util.logging.LogRecord. For example its overridden
getMessage method may do some formatting by default and return
more information than just the message field, while different methods would
be provided for a caller in the know to examine specific individual fields.
None of those differences stop it from being a valid instance of
java.util.logging.LogRecord, and it can be passed into the logging system
by calling log just like any other record. So can other, non-extended
LogRecords and normal calls on the convenience methods of
Logger, all at the same time. Code ported from other environments,
knowing nothing of the extensions and using the standard logger API will work
fine, and can be mixed with code using the extended features.
Call sites that aren’t trying to make good user-visible messages (all the
usual logger.finest("sent an M, got two dollar signs and a comma") kind of
thing) don’t have any need to change.
Using familiar level names
The current implementation in PL/Java maps PostgreSQL severity levels onto
the (smaller set of) standard Levels. This adds another bit of
cognitive load in the development process: I have to remember, for example,
SET log_min_messages TO DEBUG2;
SELECT javatest.logmessage('FINER', 'Hello world');
are talking about the same severity level, and it’s an error to forget and use the other name either place, and the mapping loses information—it’s not invertible.
A feature of the design of Level is it can be subclassed, and
additional levels can be defined; the numeric values of the standard ones
are spaced widely apart to allow new ones between them, and the parser even
learns the names of new levels so they “just work”. I propose defining the
PostgreSQL levels whose names do not already match Level names,
with a possible relationship like this:
| PostgreSQL | Java |
|---|---|
| ALL | |
| FINEST? | |
| DEBUG5 | |
| FINEST? | |
| DEBUG4 | |
| DEBUG3 | |
| FINER | |
| DEBUG2 | |
| FINE | |
| DEBUG1 | |
| CONFIG | |
| LOG | |
| COMMERROR | |
| INFO | INFO |
| NOTICE | |
| WARNING | WARNING |
| SEVERE? | |
| ERROR | |
| SEVERE? | |
| FATAL | |
| PANIC | |
| OFF |
As you can see, I’m still considering arguments about where FINEST and
SEVERE should go.
The effect, again, is that code from elsewhere that only expects the usual names from the standard library will work fine, code with more PostgreSQLy origins can use those familiar names, and a developer or admin can set the logging level using any of them, whichever seems more natural at the time.
Could pgjdbc move to java.util.logging without disruption?
I think so. The class org.postgresql.core.Logger could be kept, and
simply delegate to other classes; the changes at points where log events
are read off the wire and exceptions are created should be fairly internal
and localized. I’d like to give it a shot.
I think the categorized exceptions in JDBC 4 are worth moving to, and
offer a much nicer way for client code to distinguish what kind of thing
went wrong, but changing that might actually turn out to be what needs
the most coordination with client code. I would like to hope there isn’t
much client code out there that has linked to PSQLException by name
(when it is only shown on “privateapi” javadocs), but I can only imagine
there is some.
A place to pause
I have not managed to squeeze in every relevant thought here, but this is already long and enough to elicit some discussion and questions, and if I keep writing I will probably just be answering the wrong ones, so this seems a good place to stop and listen.