WIP patch - INSERT-able log statements

On Sat, 17 Feb 2007, FAST PostgreSQL wrote:

#log_output_type = 'text' #Valid values are 'SQL' or 'text'
Defaults to 'text' which is status quo. If it is set to 'SQL' log will
be output as INSERT commands.

This assumes someone wants either the INSERT-able logs or the current,
easily readable ones. I know I don't want either--I want both. There are
times I want to look through the logs with a text editor, there are times
where I want to query against them.

I would suggest treating this similarly to how the Windows eventlog is
handled: made SQL INSERT format another option available to
log_destination, so it can be combined with the existing formats. In
addition to the syslog concerns you already mentioned (which are
themselves a showstopper for using this feature in companies that rely on
or aggregate syslogs), I know I'd want to keep the existing logs rolling
in parallel while I tested out the SQL-based version for a while, before
cutting over to exclusively INSERT format logs.

I've thought a bit about how to implement this TODO already (I have a log
file parser and I hate maintaining it), and the only thing that made sense
to me was giving a new parameter with the filename to output to in this
format. For example, make a new log_sql_filename with the same syntax
already used for log_filename. There will probably need to be a second
parameter for the table name to insert into as you've already commented
on. And like Joshua has already suggested, the main useful applications
for this feature I've thought of all involve reading from the INSERT-able
logs in real-time, using something like "tail -f", and pumping that data
immediately into a logger table.

Also, I feel that supporting the whole log_line_prefix syntax for this
feature is not just overkill, it's a bad idea. Output everything in a
standard, complete format instead, and then it becomes easy for the
community at large to build tools on top of that to analyze the log
database entries instead of having so many ad-hoc approaches. You want a
subset, use a view or copy just the fields you want into another table.
I would guess this simplifies the patch as well.

--
* Greg Smith gsmith@gregsmith.com http://www.gregsmith.com Baltimore, MD

Added -hackers to CC:.

On 2/18/07, Greg Smith <gsmith@gregsmith.com> wrote:

I've thought a bit about how to implement this TODO already (I have a log
file parser and I hate maintaining it)

Any problem using pgFouine?

Also, I feel that supporting the whole log_line_prefix syntax for this
feature is not just overkill, it's a bad idea. Output everything in a
standard, complete format instead, and then it becomes easy for the
community at large to build tools on top of that to analyze the log
database entries instead of having so many ad-hoc approaches. You want a
subset, use a view or copy just the fields you want into another table.
I would guess this simplifies the patch as well.

I agree with you on this point. We need every information we can put
in the database (database, user and so on) in a structured way.

Logging statements is not the only thing to do IMHO. Logging errors in
another table is important too. I'm pretty sure there are a lot people
who don't know if there are errors in their statements.

Anyway, if something is developed to do that, I'll extend pgFouine to
support it (or I'll write another application to do it) and I'm pretty
sure others will do. The most annoying and difficult part of the work
on pgFouine/PQA/... is to maintain the parser. If we don't have to do
that anymore, we'll have more time to think about new features.
In fact, it was a long plan for pgFouine to be able to store the
results of its analysis in a database so it's a good news if it's
implemented in core.

--
Guillaume

On Tue, 20 Feb 2007, FAST PostgreSQL wrote:

I think adding the 'format' of the log as an option in the 'destination'
may be confusing. We can have a new boolean variable like
'output_sql_log' or 'log_sql_format' which will trigger the output of
INSERT-able log in addition to syslog/stderr/eventlog in text format as
it is now.

What's confusing about it? Consider this hypothetical postgresql.conf
snippet:

log_destination = 'stderr,sql' # Valid values are combinations of
# stderr, syslog, sql, and eventlog,
# depending on platform.

# These are relevant when logging to sql:
log_sql_table = 'pg_log' # Table SQL formatted logs INSERT into
# Default is 'pg_log'

Adding new GUC variables isn't without cost; no reason to add a new one
when there's a perfectly good destination one already whose syntax is
completely appropriate for this task.

I personally would just ignore the duration two entries per statement
problem and make that the log analyzer software's job to fix, but I'm
likely biased here because I don't ever do anything with that data.

My preference would be for the sql-logs to use the same variables as
that of redirect_stderr. In the directory mentioned by the user on
log_directory we just output the sql logs in a file with an '.SQL'
appended to the filename specified by the user in log_filename. This
also means we can make use of the log_truncation and log_rotate options
(I hope. I will have a look at that).

You're talking along the same lines here I was trying to suggest in my
previous message. Keep all the current behavior as far as truncation and
rotation go, just provide a different name for the file. If you just
appended a suffix like .sql to the existing name, that would remove
another GUC variable requirement. I think eventually people will complain
about this, and want a separately formatted filename altogether, but
there's nothing wrong with the approach you suggest for a first version of
this feature. I know I'm so desparate for a better solution to log
importing that I'd be happy with any workable improvement.

--
* Greg Smith gsmith@gregsmith.com http://www.gregsmith.com Baltimore, MD

On 2/19/07, Greg Smith <gsmith@gregsmith.com> wrote:

log_destination = 'stderr,sql' # Valid values are combinations of
# stderr, syslog, sql, and eventlog,
# depending on platform.

+1

# These are relevant when logging to sql:
log_sql_table = 'pg_log' # Table SQL formatted logs INSERT into
# Default is 'pg_log'

Is there really a need for that? Why not simply put something like
%log_table% in the sql file and let the admin replace it with sed or
whatever he likes?
And it could allow us to move to copy without having to drop the code
added to manage the new GUC variable.

I personally would just ignore the duration two entries per statement
problem and make that the log analyzer software's job to fix, but I'm
likely biased here because I don't ever do anything with that data.

We have basically 4 different cases:
* log_min_duration_statement = 0: every query is logged with the
duration on the same line,
* log_statement = all: we don't have any duration,
* log_statement = all & log_duration = on: we have every query and the
duration on another line,
* log_min_duration_statement = n > 0 & log_duration = on: we have
duration lines for every query and statement + duration if the query
is slower than n ms.

There are other variants but I think they are the main cases to deal with.

--
Guillaume

Guillaume Smet escribi�:

On 2/19/07, Greg Smith <gsmith@gregsmith.com> wrote:

log_destination = 'stderr,sql' # Valid values are combinations of
# stderr, syslog, sql, and eventlog,
# depending on platform.

+1

Please don't do that. We already have a "combined GUC option" that is
used to change two different things (DateStyle) and I regularly see
people confused about how to use it.

Also, "sql" is not really a destination -- it is a format. Maybe have a
"format=plain,sql" GUC var is best: plain format is logged as currently,
and SQL format is logged somewhere else (maybe use the same name, and
stash a .sql suffix to the filename, or use .sql.log). That way you can
choose to have one or the other, or both if you're really dumb.

--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

On 2/19/07, Alvaro Herrera <alvherre@commandprompt.com> wrote:

Please don't do that. We already have a "combined GUC option" that is
used to change two different things (DateStyle) and I regularly see
people confused about how to use it.

Perhaps I don't understand your "combined GUC option" but ISTM it's
already the case for log_destination. I don't use this ability but the
current comment in postgresql.conf seems to be self explanatory:
log_destination = 'syslog' # Valid values are combinations of
# stderr, syslog and eventlog,
# depending on platform.

Also, "sql" is not really a destination -- it is a format. Maybe have a
"format=plain,sql" GUC var is best: plain format is logged as currently,
and SQL format is logged somewhere else (maybe use the same name, and
stash a .sql suffix to the filename, or use .sql.log). That way you can
choose to have one or the other, or both if you're really dumb.

I don't see how you will deal with your format GUC variable. Or it
won't be possible to have plain and sql at the same time? My problem
is how you will separate plain and sql if you put them in the stderr
or syslog.

The configuration which may interest me at first is to have syslog
plain text output to run pgFouine daily and from time to time use the
SQL output (I won't be able to insert into a db my daily logs so I
will do it sometimes if I need more details, ability to look for a
particular query and so on).
I don't know how other people plan to use it though.

--
Guillaume

Guillaume Smet escribi�:

On 2/19/07, Alvaro Herrera <alvherre@commandprompt.com> wrote:

Please don't do that. We already have a "combined GUC option" that is
used to change two different things (DateStyle) and I regularly see
people confused about how to use it.

Perhaps I don't understand your "combined GUC option" but ISTM it's
already the case for log_destination. I don't use this ability but the
current comment in postgresql.conf seems to be self explanatory:
log_destination = 'syslog' # Valid values are combinations of
# stderr, syslog and eventlog,
# depending on platform.

That defines one thing: where does the log output go. It can be syslog,
stderr, eventlog, or any combination thereof. But it's only one thing
that you're configuring.

In datestyle, you set two things: output format and input format.
That's problematic because people changes one of the settings and then
expect the other to change too, and get confused because it doesn't
work. What I'm saying is that this was not a very good design and
please let's not repeat the mistake here.

Also, "sql" is not really a destination -- it is a format. Maybe have a
"format=plain,sql" GUC var is best: plain format is logged as currently,
and SQL format is logged somewhere else (maybe use the same name, and
stash a .sql suffix to the filename, or use .sql.log). That way you can
choose to have one or the other, or both if you're really dumb.

I don't see how you will deal with your format GUC variable. Or it
won't be possible to have plain and sql at the same time? My problem
is how you will separate plain and sql if you put them in the stderr
or syslog.

Well, to syslog or eventlog you don't send the SQL format, only plain.
If you configure the SQL format, then it's expected that stderr is
enabled, so it would be an error if you enable SQL format but not
stderr. If redirect_stderr is also enabled then you could enable both
plain format and SQL format, and have each logged to a different file
(though I repeat that IMHO that would be a dumb thing to do).

The configuration which may interest me at first is to have syslog
plain text output to run pgFouine daily and from time to time use the
SQL output (I won't be able to insert into a db my daily logs so I
will do it sometimes if I need more details, ability to look for a
particular query and so on).
I don't know how other people plan to use it though.

I don't think the syslog option is so nice to use these days; the
redirect_stderr stuff is more powerful and easy to use.

--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

On 2/19/07, Alvaro Herrera <alvherre@commandprompt.com> wrote:

I don't think the syslog option is so nice to use these days; the
redirect_stderr stuff is more powerful and easy to use.

Did you already analyze logs of a highly loaded platform using stderr?
It's impossible to guarantee the consistency of the queries because
you can have:
Query 1 Line 1
Query 2 Line 1
Query 3 Line 1
Query 1 Line 2
Query 2 Line 2
Query 1 Line 3
Query 3 Line 2
(each query is run on a different backend). With stderr you don't have
sufficient information to know the query you should append the text
to. Syslog adds useful context information (pid, command line, command
number) which allows you to guarantee the consistency.
It's a real problem for us and that's why I don't recommend using
stderr when you use pgFouine.
Moreover, syslog can send the log to the network which moves the I/O
needed to log on another box and it's necessary in our case.

--
Guillaume

Guillaume Smet escribi�:

On 2/19/07, Alvaro Herrera <alvherre@commandprompt.com> wrote:

I don't think the syslog option is so nice to use these days; the
redirect_stderr stuff is more powerful and easy to use.

Did you already analyze logs of a highly loaded platform using stderr?
It's impossible to guarantee the consistency of the queries because
you can have:
Query 1 Line 1
Query 2 Line 1
Query 3 Line 1
Query 1 Line 2
Query 2 Line 2
Query 1 Line 3
Query 3 Line 2
(each query is run on a different backend). With stderr you don't have
sufficient information to know the query you should append the text
to. Syslog adds useful context information (pid, command line, command
number) which allows you to guarantee the consistency.

So add the session ID (%c) to log_line_prefix.

--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.

On 2/19/07, Alvaro Herrera <alvherre@commandprompt.com> wrote:

So add the session ID (%c) to log_line_prefix.

It could work if log_line_prefix was added before every line but it's
definitely not the case:
myuser mydb 45d9d615.4abe LOG: duration : 185.223 ms, statement : SELECT *
FROM lieu
LIMIT 10;
if you execute:
SELECT *
FROM lieu
LIMIT 10;

I worked a *lot* on query logging and I really didn't find any
solution to use stderr in a safe way, reason why I don't use it at all
and I don't recommend it (even if pgFouine supports it, it outputs a
warning as soon as the parser finds a multiline query).

--
Guillaume

Guillaume Smet escribi�:

On 2/19/07, Alvaro Herrera <alvherre@commandprompt.com> wrote:

So add the session ID (%c) to log_line_prefix.

It could work if log_line_prefix was added before every line but it's
definitely not the case:
myuser mydb 45d9d615.4abe LOG: duration : 185.223 ms, statement : SELECT *
FROM lieu
LIMIT 10;
if you execute:
SELECT *
FROM lieu
LIMIT 10;

Interesting. I wonder why didn't you report this as a bug before?
Maybe we could have discussed it and fixed it.

This is irrelevant in this particular discussion anyway if we introduce
SQL format, because then the newline should be part of the COPY or INSERT
data. Let's just make sure to not make the same errors again.

--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.

On 2/19/07, Alvaro Herrera <alvherre@commandprompt.com> wrote:

Guillaume Smet escribió:

On 2/19/07, Alvaro Herrera <alvherre@commandprompt.com> wrote:

So add the session ID (%c) to log_line_prefix.

It could work if log_line_prefix was added before every line but it's
definitely not the case:
myuser mydb 45d9d615.4abe LOG: duration : 185.223 ms, statement : SELECT *
FROM lieu
LIMIT 10;
if you execute:
SELECT *
FROM lieu
LIMIT 10;

Interesting. I wonder why didn't you report this as a bug before?
Maybe we could have discussed it and fixed it.

Perhaps because I thought it was not really a bug but the intended behaviour.
Syslog has the same behaviour and it's quite logical when you consider
how queries are logged (I've spent a few hours in the logging code).
Syslog has exactly the same behaviour but adds the necessary context
information.
I'm pretty sure I have explained the problem a few times on the lists
though but perhaps it was just on IRC.

From the feedback I have on pgFouine, very few people think it's a
real problem, probably because they don't use query logging as we do:
our production servers have it enabled all the time and we have a high
load on them so this particular case is a common case for us.

(Second try to move this discussion to -hackers)

--
Guillaume

Guillaume Smet escribi�:

On 2/19/07, Alvaro Herrera <alvherre@commandprompt.com> wrote:

Guillaume Smet escribi�:

On 2/19/07, Alvaro Herrera <alvherre@commandprompt.com> wrote:

So add the session ID (%c) to log_line_prefix.

It could work if log_line_prefix was added before every line but it's
definitely not the case:
myuser mydb 45d9d615.4abe LOG: duration : 185.223 ms, statement :

SELECT *

FROM lieu
LIMIT 10;
if you execute:
SELECT *
FROM lieu
LIMIT 10;

Interesting. I wonder why didn't you report this as a bug before?
Maybe we could have discussed it and fixed it.

Perhaps because I thought it was not really a bug but the intended
behaviour.
Syslog has the same behaviour and it's quite logical when you consider
how queries are logged (I've spent a few hours in the logging code).
Syslog has exactly the same behaviour but adds the necessary context
information.

If it adds necessary context then it clear does not have "the same
behavior", because the problem is precisely that the context is missing.
I'd propose adding a log_entry_prefix separate from log_line_prefix; the
entry prefix would contain most of the stuff, and log_line_prefix would
be a minimal thing intended to be put in front of each _line_, so the
example you show above could be

myuser mydb 45d9d615.4abe LOG: duration : 185.223 ms, statement : SELECT *
45d9d615.4abe FROM lieu
45d9d615.4abe LIMIT 10;

where you have

log_entry_prefix="%d %u "
log_line_prefix="%c "

Really, prefixing with a tab does not strike me as a great idea
precisely because it's ambiguous.

--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

On 2/19/07, Alvaro Herrera <alvherre@commandprompt.com> wrote:

If it adds necessary context then it clear does not have "the same
behavior",

I mean log_line_prefix behaviour is the same. The other information
are syslog specific.

I'd propose adding a log_entry_prefix separate from log_line_prefix; the
entry prefix would contain most of the stuff, and log_line_prefix would
be a minimal thing intended to be put in front of each _line_, so the
example you show above could be

It could be a good idea.
It won't make me use stderr output but it will allow other people to
do so without any disadvantage :).

Really, prefixing with a tab does not strike me as a great idea
precisely because it's ambiguous.

Sure.

--
Guillaume

On Mon, 19 Feb 2007, Guillaume Smet wrote:

Why not simply put something like %log_table% in the sql file and let
the admin replace it with sed or whatever he likes?

This is a reasonable approach. I would suggest that no special characters
be used though, so that the SQL could be used as-is by a DBA who doesn't
even know about or want to use tools like sed. I also think the default
should be a pg_ name like the pg_log I suggested, partly because I'd like
this to be completely internal one day--just push the logs into the
database directly without even passing through an external file first.
Also, something like pg_log is unlikely to cause a conflict with existing
tables. I would bet there's already databases out there with tables
called log_table, for example, but everyone already avoids naming
application tables starting with pg_.

A workable syntax might be

INSERT INTO "pg_log" ...

The redundant quotation marks will make it easier to do a search/replace
to change the table name without worrying about accidentally impacting the
text of the message, so that even people who aren't aware how to build a
regular expression that only modifies the first match will probably be OK.

I consider using the same name as the default log directory helpful, but
would understand that others might consider it confusing to overload the
name like that.

--
* Greg Smith gsmith@gregsmith.com http://www.gregsmith.com Baltimore, MD

On Mon, 19 Feb 2007, Alvaro Herrera wrote:

We already have a "combined GUC option" that is used to change two
different things (DateStyle) and I regularly see people confused about
how to use it.

You already have a combined GUC option called log_destination that's
sitting in the appropriate area of the configuration file, doing something
similar to what's needed for the new feature. People confused by that are
already confused.

Also, "sql" is not really a destination -- it is a format.

A log file with a different name is another destination. eventlog is
certainly a different format and it's sitting happily as an option there.
I haven't heard anyone make a useful argument yet as to how insert/sql
logs are any different than the current way that stderr, syslog, and
eventlog are all possibilities now for log_destination, each with their
own little quirks (and in the case of syslog, their own additional GUC
parameters).

That way you can choose to have one or the other, or both if you're
really dumb.

The fact that you're characterizing people who might want both as "really
dumb" tells me you're not familiar with enterprise logging requirements. I
already commented on situations where wanting both types of output going
at once is going to absolutely be a requirement in some environments for
this feature addition to be useful; there are a lot of large operations
that rely heavily on features like syslog to help manage their systems.
Most of the places I've worked at, the syslog server where the analysis is
running wasn't necessarily even in the same state as the machine
generating the log entries.

I know I can't deploy this feature unless it operates in parallel with the
existing text-based info going to syslog, both because of that and because
of transition issues--I can't disrupt the existing logs to test a new log
mechanism until that new mechanism has proven itself. I'll probably
deploy it with both turned on forever once it's available.

As for your comments on syslog vs. stderr, I completely agree with
Guillaume's response to you on that subject. The stderr output is
difficult to use for the reasons he describes, but the kind of
environments that use complicated logging aren't relying on that anyway.
I wouldn't get distracted by fixing that implementation when it's
functional enough for most who are satisfied with stderr output.

--
* Greg Smith gsmith@gregsmith.com http://www.gregsmith.com Baltimore, MD

Greg Smith <gsmith@gregsmith.com> writes:

A workable syntax might be
INSERT INTO "pg_log" ...

Why is this still under discussion? I thought we'd agreed that COPY
format was the way to go.

regards, tom lane

Greg Smith <gsmith@gregsmith.com> writes:

On Mon, 19 Feb 2007, Alvaro Herrera wrote:

Also, "sql" is not really a destination -- it is a format.

A log file with a different name is another destination. eventlog is
certainly a different format and it's sitting happily as an option there.
I haven't heard anyone make a useful argument yet as to how insert/sql
logs are any different than the current way that stderr, syslog, and
eventlog are all possibilities now for log_destination, each with their
own little quirks (and in the case of syslog, their own additional GUC
parameters).

Since the "sql" format doesn't make any sense for syslog or eventlog
output, I tend to agree that treating it as a destination is a
reasonable answer. It's going to be a bit non-orthogonal no matter
which way we jump, but this seems like the most natural and useful
extension from where we are. To me anyway ... YMMV ...

regards, tom lane

"Guillaume Smet" <guillaume.smet@gmail.com> writes:

(each query is run on a different backend). With stderr you don't have
sufficient information to know the query you should append the text
to. Syslog adds useful context information (pid, command line, command
number) which allows you to guarantee the consistency.
It's a real problem for us and that's why I don't recommend using
stderr when you use pgFouine.

Of course, the other side of that coin is that syslog is known to drop
messages altogether under sufficient load. (At least on some platforms;
dunno about yours.)

regards, tom lane