PL/pgSQL, RAISE and error context

2013/8/21 Marko Tiikkaja <marko@joh.to>

Hi,

By default, PL/pgSQL does not print the error context of a RAISE
statement, for example:

=# create function foof() returns void as $$ begin raise exception 'foo';
end $$ language plpgsql;
CREATE FUNCTION

=# create function bar() returns void as $$ begin perform foof(); end $$
language plpgsql;
CREATE FUNCTION

=# select bar();
ERROR: foo
CONTEXT: SQL statement "SELECT foof()"
PL/pgSQL function "bar" line 1 at PERFORM

I find this extremely surprising, since if you raise the same exception
(or a DEBUG/NOTICE message) in multiple places, the error context is
missing valuable information. With a trivial change the last error could
be:

=# select bar();
ERROR: foo
CONTEXT: PL/pgSQL function "foof" line 1 RAISE
SQL statement "SELECT foof()"
PL/pgSQL function "bar" line 1 at PERFORM

which I find a lot better.

+1

Pavel

On 8/21/13 2:28 PM, I wrote:

By default, PL/pgSQL does not print the error context of a RAISE
statement, for example:

An even worse example:

=# create function foof() returns void as $$ begin raise exception
'foo'; end $$ language plpgsql;
CREATE FUNCTION

=# create function barf() returns void as $$ declare _ record; begin for
_ in execute 'select foof()' loop end loop; end $$ language plpgsql;
CREATE FUNCTION

=# select barf();
ERROR: foo
CONTEXT: PL/pgSQL function "barf" line 1 at FOR over EXECUTE statement

Notice how there's no mention at all about the function the error came
from, and compare that to:

=# select barf();
ERROR: foo
CONTEXT: PL/pgSQL function "foof" line 1 RAISE
PL/pgSQL function "barf" line 1 at FOR over EXECUTE statement

Regards,
Marko Tiikkaja

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Marko Tiikkaja <marko@joh.to> writes:

By default, PL/pgSQL does not print the error context of a RAISE
statement, for example:

It used to do so, in the beginning when we first added context-printing.
There were complaints that the result was too verbose; for instance if you
had a RAISE NOTICE inside a loop for progress-monitoring purposes, you'd
get two lines for every one you wanted. I think if we undid this we'd
get the same complaints again. I agree that in complicated nests of
functions the location info is more interesting than it is in trivial
cases, but that doesn't mean you're not going to hear such complaints from
people with trivial functions.

regards, tom lane

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On 8/21/13 4:22 PM, Tom Lane wrote:

Marko Tiikkaja <marko@joh.to> writes:

By default, PL/pgSQL does not print the error context of a RAISE
statement, for example:

It used to do so, in the beginning when we first added context-printing.
There were complaints that the result was too verbose; for instance if you
had a RAISE NOTICE inside a loop for progress-monitoring purposes, you'd
get two lines for every one you wanted. I think if we undid this we'd
get the same complaints again. I agree that in complicated nests of
functions the location info is more interesting than it is in trivial
cases, but that doesn't mean you're not going to hear such complaints from
people with trivial functions.

They have an option: they can reduce verbosity in their client. I
currently don't have any real options.

Regards,
Marko Tiikkaja

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Wed, Aug 21, 2013 at 9:22 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Marko Tiikkaja <marko@joh.to> writes:

By default, PL/pgSQL does not print the error context of a RAISE
statement, for example:

It used to do so, in the beginning when we first added context-printing.
There were complaints that the result was too verbose; for instance if you
had a RAISE NOTICE inside a loop for progress-monitoring purposes, you'd
get two lines for every one you wanted. I think if we undid this we'd
get the same complaints again. I agree that in complicated nests of
functions the location info is more interesting than it is in trivial
cases, but that doesn't mean you're not going to hear such complaints from
people with trivial functions.

It *is* (apologies for the hijack) too verbose but whatever context
suppressing we added doesn't work in pretty much any interesting case.
What is basically needed is for the console to honor
log_error_verbosity (which I would prefer) or a separate GUC in manage
the console logging verbosity:

set log_error_verbosity = 'terse';
SET

CREATE OR REPLACE FUNCTION Notice(_msg TEXT) RETURNS VOID AS
$$
BEGIN
RAISE NOTICE '[%] %', clock_timestamp()::timestamp(0)::text, _msg;
END;
$$ LANGUAGE PLPGSQL;

CREATE OR REPLACE FUNCTION foo() RETURNS VOID AS
$$
BEGIN
PERFORM Notice('test');
END;
$$ LANGUAGE PLPGSQL;

-- context will print
postgres=# select foo();
NOTICE: [2013-08-21 09:52:08] test
CONTEXT: SQL statement "SELECT Notice('test')"
PL/pgSQL function foo() line 4 at PERFORM

CREATE OR REPLACE FUNCTION bar() RETURNS VOID AS
$$
SELECT Notice('test');
$$ LANGUAGE SQL;

-- context will not print
postgres=# select bar();
NOTICE: [2013-08-21 09:54:55] test

-- context will print
CREATE OR REPLACE FUNCTION baz() RETURNS VOID AS
$$
select 0;
SELECT Notice('test');
$$ LANGUAGE SQL;

postgres=# select baz();
NOTICE: [2013-08-21 09:55:26] test
CONTEXT: SQL function "baz" statement 2

merlin

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On 8/21/13 5:05 PM, Merlin Moncure wrote:

On Wed, Aug 21, 2013 at 9:22 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Marko Tiikkaja <marko@joh.to> writes:

By default, PL/pgSQL does not print the error context of a RAISE
statement, for example:

It used to do so, in the beginning when we first added context-printing.
There were complaints that the result was too verbose; for instance if you
had a RAISE NOTICE inside a loop for progress-monitoring purposes, you'd
get two lines for every one you wanted. I think if we undid this we'd
get the same complaints again. I agree that in complicated nests of
functions the location info is more interesting than it is in trivial
cases, but that doesn't mean you're not going to hear such complaints from
people with trivial functions.

It *is* (apologies for the hijack) too verbose but whatever context
suppressing we added doesn't work in pretty much any interesting case.
What is basically needed is for the console to honor
log_error_verbosity (which I would prefer) or a separate GUC in manage
the console logging verbosity:

Why does \set VERBOSITY 'terse' not work for you?

Regards,
Marko Tiikkaja

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Wed, Aug 21, 2013 at 10:07 AM, Marko Tiikkaja <marko@joh.to> wrote:

On 8/21/13 5:05 PM, Merlin Moncure wrote:

On Wed, Aug 21, 2013 at 9:22 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Marko Tiikkaja <marko@joh.to> writes:

By default, PL/pgSQL does not print the error context of a RAISE
statement, for example:

It used to do so, in the beginning when we first added context-printing.
There were complaints that the result was too verbose; for instance if
you
had a RAISE NOTICE inside a loop for progress-monitoring purposes, you'd
get two lines for every one you wanted. I think if we undid this we'd
get the same complaints again. I agree that in complicated nests of
functions the location info is more interesting than it is in trivial
cases, but that doesn't mean you're not going to hear such complaints
from
people with trivial functions.

It *is* (apologies for the hijack) too verbose but whatever context
suppressing we added doesn't work in pretty much any interesting case.
What is basically needed is for the console to honor
log_error_verbosity (which I would prefer) or a separate GUC in manage
the console logging verbosity:

Why does \set VERBOSITY 'terse' not work for you?

Because it can't be controlled mid-function...that would suppress all
context of errors as well as messages and so it's useless. Also psql
directives for this purpose is a hack anyways -- what if I'm using a
non-psql client?

what I really want is:
SET LOCAL log_console_verbosity = 'x'

merlin

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

2013/8/21 Merlin Moncure <mmoncure@gmail.com>

On Wed, Aug 21, 2013 at 10:07 AM, Marko Tiikkaja <marko@joh.to> wrote:

On 8/21/13 5:05 PM, Merlin Moncure wrote:

On Wed, Aug 21, 2013 at 9:22 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Marko Tiikkaja <marko@joh.to> writes:

By default, PL/pgSQL does not print the error context of a RAISE
statement, for example:

It used to do so, in the beginning when we first added

context-printing.

There were complaints that the result was too verbose; for instance if
you
had a RAISE NOTICE inside a loop for progress-monitoring purposes,

you'd

get two lines for every one you wanted. I think if we undid this we'd
get the same complaints again. I agree that in complicated nests of
functions the location info is more interesting than it is in trivial
cases, but that doesn't mean you're not going to hear such complaints
from
people with trivial functions.

It *is* (apologies for the hijack) too verbose but whatever context
suppressing we added doesn't work in pretty much any interesting case.
What is basically needed is for the console to honor
log_error_verbosity (which I would prefer) or a separate GUC in manage
the console logging verbosity:

Why does \set VERBOSITY 'terse' not work for you?

Because it can't be controlled mid-function...that would suppress all
context of errors as well as messages and so it's useless. Also psql
directives for this purpose is a hack anyways -- what if I'm using a
non-psql client?

what I really want is:
SET LOCAL log_console_verbosity = 'x'

it is not bad idea

Pavel

On 2013-08-21 17:18, Merlin Moncure wrote:

On Wed, Aug 21, 2013 at 10:07 AM, Marko Tiikkaja <marko@joh.to> wrote:

Why does \set VERBOSITY 'terse' not work for you?

Because it can't be controlled mid-function...that would suppress all
context of errors as well as messages and so it's useless.

Fair enough.

what I really want is:
SET LOCAL log_console_verbosity = 'x'

log_min_messages vs. client_min_messages, so client_error_verbosity
sounds more appropriate IMO.

Regards,
Marko Tiikkaja

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Merlin Moncure <mmoncure@gmail.com> writes:

On Wed, Aug 21, 2013 at 10:07 AM, Marko Tiikkaja <marko@joh.to> wrote:

Why does \set VERBOSITY 'terse' not work for you?

Because it can't be controlled mid-function...that would suppress all
context of errors as well as messages and so it's useless. Also psql
directives for this purpose is a hack anyways -- what if I'm using a
non-psql client?

what I really want is:
SET LOCAL log_console_verbosity = 'x'

There was a protocol design decision a long time ago that verbosity
ought to be controlled on the client side. If we start suppressing
fields server-side I think we're going to have problems. In particular,
I'm going to throw the "what if I'm not using psql" argument right back
at you: what's the reason for thinking that a different client/application
would have the identical desires about what fields to see? It seems
unlikely that a Java application, say, would want the server to be
selective about what information it sends.

I'm entirely prepared to believe that psql's VERBOSITY behavior could
use more options, though.

regards, tom lane

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Wed, Aug 21, 2013 at 10:47 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Merlin Moncure <mmoncure@gmail.com> writes:

On Wed, Aug 21, 2013 at 10:07 AM, Marko Tiikkaja <marko@joh.to> wrote:

Why does \set VERBOSITY 'terse' not work for you?

Because it can't be controlled mid-function...that would suppress all
context of errors as well as messages and so it's useless. Also psql
directives for this purpose is a hack anyways -- what if I'm using a
non-psql client?

what I really want is:
SET LOCAL log_console_verbosity = 'x'

There was a protocol design decision a long time ago that verbosity
ought to be controlled on the client side. If we start suppressing
fields server-side I think we're going to have problems. In particular,
I'm going to throw the "what if I'm not using psql" argument right back
at you: what's the reason for thinking that a different client/application
would have the identical desires about what fields to see? It seems
unlikely that a Java application, say, would want the server to be
selective about what information it sends.

I didn't like that decision then and I don't like it now. Why should
the protocol mandate that error context always be sent? Why does this
have anything to do with the protocol at all? Just because we can't
imagine a case where a java application would not want context to be
sent in some or all contexts doesn't mean that operators should not
have control over it being emitted. What harm could providing an
option possibly cause?

I'm entirely prepared to believe that psql's VERBOSITY behavior could
use more options, though.

How would that be structured... \set VERBOSITY 'NOTICE:terse'?

merlin

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Hello

I played with this topic little bit

If I understand, the main problem is in console (or pgAdmin) output.

create or replace function foo()
returns void as $$
begin
for i in 1..5
loop
raise notice '>>>>> *****';
end loop;
raise exception '***************';
end;
$$ language plpgsql;

postgres=# select foo();
NOTICE: >>>>> *****
NOTICE: >>>>> *****
NOTICE: >>>>> *****
NOTICE: >>>>> *****
NOTICE: >>>>> *****
ERROR: ***************
Time: 2.024 ms
postgres=# \set VER
VERBOSITY VERSION
postgres=# \set VERBOSITY

postgres=# \set VERBOSITY

postgres=# \set VERBOSITY terse
postgres=# select foo();
NOTICE: >>>>> *****
NOTICE: >>>>> *****
NOTICE: >>>>> *****
NOTICE: >>>>> *****
NOTICE: >>>>> *****
ERROR: ***************
Time: 0.908 ms
postgres=# \set VERBOSITY verbose
postgres=# select foo();
NOTICE: 00000: >>>>> *****
LOCATION: exec_stmt_raise, pl_exec.c:3051
NOTICE: 00000: >>>>> *****
LOCATION: exec_stmt_raise, pl_exec.c:3051
NOTICE: 00000: >>>>> *****
LOCATION: exec_stmt_raise, pl_exec.c:3051
NOTICE: 00000: >>>>> *****
LOCATION: exec_stmt_raise, pl_exec.c:3051
NOTICE: 00000: >>>>> *****
LOCATION: exec_stmt_raise, pl_exec.c:3051
ERROR: P0001: ***************
LOCATION: exec_stmt_raise, pl_exec.c:3051

Time: 0.314 ms

I see a two little bit not nice issues:

a) in terse mode missing a CONTEXT for RAISED error
b) in verbose mode missing a CONTEXT for messages, for error too, and
useless LOCATION is showed.

LOCATION is absolutely useless for custom messages.

so I removed a context filtering

postgres=# select foo();
NOTICE: >>>>> *****
CONTEXT: PL/pgSQL function foo() line 5 at RAISE
NOTICE: >>>>> *****
CONTEXT: PL/pgSQL function foo() line 5 at RAISE
NOTICE: >>>>> *****
CONTEXT: PL/pgSQL function foo() line 5 at RAISE
NOTICE: >>>>> *****
CONTEXT: PL/pgSQL function foo() line 5 at RAISE
NOTICE: >>>>> *****
CONTEXT: PL/pgSQL function foo() line 5 at RAISE
ERROR: ***************
CONTEXT: PL/pgSQL function foo() line 7 at RAISE
Time: 3.842 ms
postgres=# \set VERBOSITY verbose
postgres=# select foo();
NOTICE: 00000: >>>>> *****
CONTEXT: PL/pgSQL function foo() line 5 at RAISE
LOCATION: exec_stmt_raise, pl_exec.c:3046
NOTICE: 00000: >>>>> *****
CONTEXT: PL/pgSQL function foo() line 5 at RAISE
LOCATION: exec_stmt_raise, pl_exec.c:3046
NOTICE: 00000: >>>>> *****
CONTEXT: PL/pgSQL function foo() line 5 at RAISE
LOCATION: exec_stmt_raise, pl_exec.c:3046
NOTICE: 00000: >>>>> *****
CONTEXT: PL/pgSQL function foo() line 5 at RAISE
LOCATION: exec_stmt_raise, pl_exec.c:3046
NOTICE: 00000: >>>>> *****
CONTEXT: PL/pgSQL function foo() line 5 at RAISE
LOCATION: exec_stmt_raise, pl_exec.c:3046
ERROR: P0001: ***************
CONTEXT: PL/pgSQL function foo() line 7 at RAISE
LOCATION: exec_stmt_raise, pl_exec.c:3046
Time: 0.761 ms

We should not see a CONTEXT for DEFAULT verbosity and NOTICE level, after
little bit change I got a satisfied output

postgres=# select foo();

NOTICE: >>>>> *****
NOTICE: >>>>> *****
NOTICE: >>>>> *****
NOTICE: >>>>> *****
NOTICE: >>>>> *****

ERROR: ***************
CONTEXT: PL/pgSQL function foo() line 7 at RAISE
Time: 2.434 ms
postgres=# \set VERBOSITY verbose
postgres=# select foo();

NOTICE: 00000: >>>>> *****

CONTEXT: PL/pgSQL function foo() line 5 at RAISE
LOCATION: exec_stmt_raise, pl_exec.c:3046

NOTICE: 00000: >>>>> *****

CONTEXT: PL/pgSQL function foo() line 5 at RAISE
LOCATION: exec_stmt_raise, pl_exec.c:3046

NOTICE: 00000: >>>>> *****

CONTEXT: PL/pgSQL function foo() line 5 at RAISE
LOCATION: exec_stmt_raise, pl_exec.c:3046

NOTICE: 00000: >>>>> *****

CONTEXT: PL/pgSQL function foo() line 5 at RAISE
LOCATION: exec_stmt_raise, pl_exec.c:3046

NOTICE: 00000: >>>>> *****

CONTEXT: PL/pgSQL function foo() line 5 at RAISE
LOCATION: exec_stmt_raise, pl_exec.c:3046
ERROR: P0001: ***************
CONTEXT: PL/pgSQL function foo() line 7 at RAISE
LOCATION: exec_stmt_raise, pl_exec.c:3046
Time: 0.594 ms

Probably we can introduce a new level of verbosity, but I am thinking so
this behave is reasonable. Everybody who use a VERBOSE level expect lot of
balast and it show expected info (context of error)

Can be this design good enough for you?

Regards

Pavel

On Thu, Aug 22, 2013 at 2:08 AM, Pavel Stehule <pavel.stehule@gmail.com> wrote:

Probably we can introduce a new level of verbosity, but I am thinking so
this behave is reasonable. Everybody who use a VERBOSE level expect lot of
balast and it show expected info (context of error)

Can be this design good enough for you?

yep :-).

merlin

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On 8/22/13 9:08 AM, Pavel Stehule wrote:

Probably we can introduce a new level of verbosity, but I am thinking so
this behave is reasonable. Everybody who use a VERBOSE level expect lot of
balast and it show expected info (context of error)

Can be this design good enough for you?

I like the idea, but I think this should be a new verbosity level. With
this patch you would have to go full VERBOSE just to debug PL/pgSQL code
with NOTICEs and DEBUGs in it, and that output then becomes harder to
parse with the useless C-code information.

Regards,
Marko Tiikkaja

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

2013/8/22 Marko Tiikkaja <marko@joh.to>

On 8/22/13 9:08 AM, Pavel Stehule wrote:

Probably we can introduce a new level of verbosity, but I am thinking so
this behave is reasonable. Everybody who use a VERBOSE level expect lot of
balast and it show expected info (context of error)

Can be this design good enough for you?

I like the idea, but I think this should be a new verbosity level. With
this patch you would have to go full VERBOSE just to debug PL/pgSQL code
with NOTICEs and DEBUGs in it, and that output then becomes harder to parse
with the useless C-code information.

word "DEBUG" is not good - it is used for Postgres debugging as log level

Pavel

2013/8/22 Marko Tiikkaja <marko@joh.to>

On 8/22/13 9:08 AM, Pavel Stehule wrote:

Probably we can introduce a new level of verbosity, but I am thinking so
this behave is reasonable. Everybody who use a VERBOSE level expect lot of
balast and it show expected info (context of error)

Can be this design good enough for you?

I like the idea, but I think this should be a new verbosity level. With
this patch you would have to go full VERBOSE just to debug PL/pgSQL code
with NOTICEs and DEBUGs in it, and that output then becomes harder to parse
with the useless C-code information.

do you prepare patch ?

Pavel

On 8/23/13 8:38 AM, Pavel Stehule wrote:

2013/8/22 Marko Tiikkaja <marko@joh.to>

I like the idea, but I think this should be a new verbosity level. With
this patch you would have to go full VERBOSE just to debug PL/pgSQL code
with NOTICEs and DEBUGs in it, and that output then becomes harder to parse
with the useless C-code information.

do you prepare patch ?

I should have the time to produce one for the September commitfest, but
if you (or anyone else) want to work on this, I won't object.

My opinion at this very moment is that we should leave the the DEFAULT
verbosity alone and add a new one (call it COMPACT or such) with the
suppressed context for non-ERRORs.

Regards,
Marko Tiikkaja

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

2013/8/23 Marko Tiikkaja <marko@joh.to>

On 8/23/13 8:38 AM, Pavel Stehule wrote:

2013/8/22 Marko Tiikkaja <marko@joh.to>

I like the idea, but I think this should be a new verbosity level. With
this patch you would have to go full VERBOSE just to debug PL/pgSQL code
with NOTICEs and DEBUGs in it, and that output then becomes harder to
parse
with the useless C-code information.

do you prepare patch ?

I should have the time to produce one for the September commitfest, but if
you (or anyone else) want to work on this, I won't object.

My opinion at this very moment is that we should leave the the DEFAULT
verbosity alone and add a new one (call it COMPACT or such) with the
suppressed context for non-ERRORs.

The name is not important. What I would, for DEFAULT verbosity, to see a
context when RAISE EXCEPTION is used. It is a bug now, I think

Regards

Pavel

On 23/08/2013 10:36, I wrote:

On 8/23/13 8:38 AM, Pavel Stehule wrote:

do you prepare patch ?

I should have the time to produce one for the September commitfest, but
if you (or anyone else) want to work on this, I won't object.

My opinion at this very moment is that we should leave the the DEFAULT
verbosity alone and add a new one (call it COMPACT or such) with the
suppressed context for non-ERRORs.

Well, turns out there isn't really any way to preserve complete
backwards compatibility if we want to do this change.

The attached patch (based on Pavel's patch) changes the default to be
slightly more verbose (the CONTEXT lines which were previously omitted
will be visible), but adds a new PGVerbosity called COMPACT which
suppresses CONTEXT in non-error messages. Now DEFAULT will be more
useful when debugging PL/PgSQL, and people who are annoyed by the new
behaviour can use the COMPACT mode.

Any thoughts?

Regards,
Marko Tiikkaja