Re: Call stacks and RAISE INFO

All,

I'm noticing some inconsistent and (I believe) undesirable behavior on
RAISE INFO.

If you call a function, and it posts progress reports using RAISE INFO,
then you get the INFO statements plain back to the client. However, if
that function calls another function, then you also get a three-line
CONTEXT message ... and if the functions are recursively called, the
CONTEXT message will emit 3 lines for every level of the call stack.

This seems like reasonable behavior for RAISE EXCEPTION but not RAISE
INFO. It pretty much makes INFO notices useless as end-user feedback if
you have functions calling other functions because of the amount of
garbage on the screen. Is this a bug?

--
Josh Berkus
PostgreSQL Experts Inc.
http://pgexperts.com

Excerpts from Josh Berkus's message of vie oct 14 13:52:32 -0300 2011:
> All,
>
> I'm noticing some inconsistent and (I believe) undesirable behavior on
> RAISE INFO.
>
> If you call a function, and it posts progress reports using RAISE INFO,
> then you get the INFO statements plain back to the client. However, if
> that function calls another function, then you also get a three-line
> CONTEXT message ... and if the functions are recursively called, the
> CONTEXT message will emit 3 lines for every level of the call stack.
>
> This seems like reasonable behavior for RAISE EXCEPTION but not RAISE
> INFO. It pretty much makes INFO notices useless as end-user feedback if
> you have functions calling other functions because of the amount of
> garbage on the screen. Is this a bug?

Maybe set the verbosity to a lower level in the function? I dunno if
plpgsql lets you do that though. We have a GUC that controls the server
log verbosity, and psql can do it too; but plpgsql is sort of in
between.

--
Álvaro Herrera <alvherre(at)commandprompt(dot)com>
The PostgreSQL Company - Command Prompt, Inc.
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

> Maybe set the verbosity to a lower level in the function? I dunno if
> plpgsql lets you do that though. We have a GUC that controls the server
> log verbosity, and psql can do it too; but plpgsql is sort of in
> between.

The problem is that there is no level of verbosity which will supress
the CONTEXT messages and not supress the INFO messages as well. Not
that I've found, anyway.

--
Josh Berkus
PostgreSQL Experts Inc.
http://pgexperts.com

Excerpts from Josh Berkus's message of vie oct 14 14:16:43 -0300 2011:
>
> > Maybe set the verbosity to a lower level in the function? I dunno if
> > plpgsql lets you do that though. We have a GUC that controls the server
> > log verbosity, and psql can do it too; but plpgsql is sort of in
> > between.
>
> The problem is that there is no level of verbosity which will supress
> the CONTEXT messages and not supress the INFO messages as well. Not
> that I've found, anyway.

I meant verbosity, not error level. This quick test shows what I meant
-- but it doesn't work; the server log is altered as I expected (and does not
include the context lines), but not plpgsql's:

alvherre=# create function f() returns void language plpgsql as $$ begin raise info 'hello'; end $$;
CREATE FUNCTION
alvherre=# select f();
INFO: hello
f
---

(1 fila)

alvherre=# create function g() returns void language plpgsql as $$ begin perform f(); end $$;
CREATE FUNCTION
alvherre=# select g();
INFO: hello
CONTEXTO: SQL statement "SELECT f()"
función PL/pgSQL «g» en la línea 1 en PERFORM
g
---

(1 fila)

alvherre=# alter function g() set log_error_verbosity to 'terse';
ALTER FUNCTION
alvherre=# select g();
INFO: hello
CONTEXTO: SQL statement "SELECT f()"
función PL/pgSQL «g» en la línea 1 en PERFORM
g
---

(1 fila)

alvherre=# alter function f() set log_error_verbosity to 'terse';
ALTER FUNCTION
alvherre=# select g();
INFO: hello
CONTEXTO: SQL statement "SELECT f()"
función PL/pgSQL «g» en la línea 1 en PERFORM
g
---

(1 fila)

--
Álvaro Herrera <alvherre(at)commandprompt(dot)com>
The PostgreSQL Company - Command Prompt, Inc.
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

> I meant verbosity, not error level. This quick test shows what I meant
> -- but it doesn't work; the server log is altered as I expected (and does not
> include the context lines), but not plpgsql's:

Yeah, what we'd need is a client_error_verbosity setting.

--
Josh Berkus
PostgreSQL Experts Inc.
http://pgexperts.com

On Oct14, 2011, at 19:27 , Josh Berkus wrote:
>> I meant verbosity, not error level. This quick test shows what I meant
>> -- but it doesn't work; the server log is altered as I expected (and does not
>> include the context lines), but not plpgsql's:
>
> Yeah, what we'd need is a client_error_verbosity setting.

We do transmit the individual parts of a NOTICE separately, so I'd say
suppressing some of them is the client's job. So, instead of a GUC I'd say
we'd need a psql setting ERROR_VERBOSITY.

best regards,
Florian Pflug

Excerpts from Florian Pflug's message of vie oct 14 14:41:11 -0300 2011:
>
> On Oct14, 2011, at 19:27 , Josh Berkus wrote:
> >> I meant verbosity, not error level. This quick test shows what I meant
> >> -- but it doesn't work; the server log is altered as I expected (and does not
> >> include the context lines), but not plpgsql's:
> >
> > Yeah, what we'd need is a client_error_verbosity setting.
>
> We do transmit the individual parts of a NOTICE separately, so I'd say
> suppressing some of them is the client's job. So, instead of a GUC I'd say
> we'd need a psql setting ERROR_VERBOSITY.

Well, we do have a psql setting as well (\set VERBOSITY). But is Josh
using psql?

--
Álvaro Herrera <alvherre(at)commandprompt(dot)com>
The PostgreSQL Company - Command Prompt, Inc.
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

>> We do transmit the individual parts of a NOTICE separately, so I'd say
>> suppressing some of them is the client's job. So, instead of a GUC I'd say
>> we'd need a psql setting ERROR_VERBOSITY.
>
> Well, we do have a psql setting as well (\set VERBOSITY). But is Josh
> using psql?

Not in this instance, no.

In any case, this doesn't address the inconsistency of supressing
CONTEXT for the first level of the call stack with RAISE INFO but not
for the others. (RAISE EXCEPTION shows CONTEXT for all levels of the
call stack).

--
Josh Berkus
PostgreSQL Experts Inc.
http://pgexperts.com

Josh Berkus <josh(at)agliodbs(dot)com> writes:
>> I meant verbosity, not error level. This quick test shows what I meant
>> -- but it doesn't work; the server log is altered as I expected (and does not
>> include the context lines), but not plpgsql's:

> Yeah, what we'd need is a client_error_verbosity setting.

It seems to me that a client-side facility would be unlikely to do the
right things, because it has not got enough information to know which
messages came from plpgsql RAISE commands. Moreover, it's not apparent
that a one-size-fits-all approach is suitable anyhow: it may be that
some RAISEs don't need context traceback while others could use it.

Now that we have syntax for adding miscellaneous options to RAISE
statements, what I suggest we consider is a RAISE option that suppresses
all context lines for the message, perhaps

RAISE NOTICE 'fee, fi, fo, fum' USING context = false;

regards, tom lane

Josh Berkus <josh(at)agliodbs(dot)com> writes:
> In any case, this doesn't address the inconsistency of supressing
> CONTEXT for the first level of the call stack with RAISE INFO but not
> for the others. (RAISE EXCEPTION shows CONTEXT for all levels of the
> call stack).

Oh? I don't see that. AFAICT the behavior is not dependent on the
error severity level. RAISE just automatically suppresses the context
line from the current plpgsql function. Not sure if we need to make
that part of the behavior configurable or not.

regards, tom lane

> Now that we have syntax for adding miscellaneous options to RAISE
> statements, what I suggest we consider is a RAISE option that suppresses
> all context lines for the message, perhaps
>
> RAISE NOTICE 'fee, fi, fo, fum' USING context = false;

Yeah, that would do it. Pavel? ;-)

--
Josh Berkus
PostgreSQL Experts Inc.
http://pgexperts.com

On Oct14, 2011, at 20:00 , Josh Berkus wrote:
>>> We do transmit the individual parts of a NOTICE separately, so I'd say
>>> suppressing some of them is the client's job. So, instead of a GUC I'd say
>>> we'd need a psql setting ERROR_VERBOSITY.
>>
>> Well, we do have a psql setting as well (\set VERBOSITY). But is Josh
>> using psql?

Yeah, I meant that we could split that into two settings, one for level >= ERROR
and one for level < ERROR. It'd certainly be nice to be able to report progress messages
from functions without seeing all the CONTEXT and STATEMENT noise when running them via
psql, yet still get that information if an actual error occurs.

> Not in this instance, no.

But I still believe this is something that should be done client-side.

best regards,
Florian Pflug

On Oct14, 2011, at 23:51 , Tom Lane wrote:
> Josh Berkus <josh(at)agliodbs(dot)com> writes:
>>> I meant verbosity, not error level. This quick test shows what I meant
>>> -- but it doesn't work; the server log is altered as I expected (and does not
>>> include the context lines), but not plpgsql's:
>
>> Yeah, what we'd need is a client_error_verbosity setting.
>
> It seems to me that a client-side facility would be unlikely to do the
> right things, because it has not got enough information to know which
> messages came from plpgsql RAISE commands. Moreover, it's not apparent
> that a one-size-fits-all approach is suitable anyhow: it may be that
> some RAISEs don't need context traceback while others could use it.

Hm, I think you'd usually want to adjust the verbosity of log messages
when you *run* code, not when you *write* it. That's the raison d'etre
for having logging infrastructure and verbosity settings, after all.

When I'm running a function from psql interactively, I probably want
to suppress CONTEXT and maybe STATEMENT lines for NOTICEs - presumably
the message itself tells me everything I need to know.

When I'm running the same function in a setting where there messages
go to a log file, I probably want to include as much context information
as necessary in order to be able to debug possible problems post-mortem.

Having said that, having the option to not emit CONTEXT lines in the
first place wouldn't hurt of course.

best regards,
Florian Pflug

Florian Pflug <fgp(at)phlo(dot)org> writes:
> On Oct14, 2011, at 23:51 , Tom Lane wrote:
>> It seems to me that a client-side facility would be unlikely to do the
>> right things, because it has not got enough information to know which
>> messages came from plpgsql RAISE commands. Moreover, it's not apparent
>> that a one-size-fits-all approach is suitable anyhow: it may be that
>> some RAISEs don't need context traceback while others could use it.

> Hm, I think you'd usually want to adjust the verbosity of log messages
> when you *run* code, not when you *write* it. That's the raison d'etre
> for having logging infrastructure and verbosity settings, after all.

No, I don't think so. The use-case for this sort of thing seems to me
to be messages that are directed to the user or DBA, and don't want to
be decorated with a lot of information about where they came from.
That determination is usually pretty clear when you write the code.

Moreover, if we don't attach the specification to particular RAISE
commands, it's going to be "all or nothing", which is most definitely
not the right thing.

Having said that, if we allow "USING context = boolean_expression",
it'd be possible for the plpgsql coder to make the behavior run-time
adjustable if he wanted.

regards, tom lane

Hello

2011/10/15 Josh Berkus <josh(at)agliodbs(dot)com>:
>
>> Now that we have syntax for adding miscellaneous options to RAISE
>> statements, what I suggest we consider is a RAISE option that suppresses
>> all context lines for the message, perhaps
>>
>> RAISE NOTICE 'fee, fi, fo, fum' USING context = false;
>
> Yeah, that would do it.  Pavel?  ;-)
>

I have no problem with this. A context can be false for info and true
for other in default. Please, use a different identifier than
"context", that can be use for reading context in future - maybe
"attach_context" or some similar.

Just note, when we are in this topis. I got a experience so debugging
functions that contains a pattern

BEGIN
.. do some .. that can raise exception ...
EXCEPT WHEN OTHERS ..
.. do some else
RAISE ... ;
END IF

is little bit difficult, because we lost a context information about
original exception

Regards

Pavel

> --
> Josh Berkus
> PostgreSQL Experts Inc.
> http://pgexperts.com
>
> --
> Sent via pgsql-hackers mailing list (pgsql-hackers(at)postgresql(dot)org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-hackers
>

On Sat, Oct 15, 2011 at 12:24 AM, Pavel Stehule <pavel(dot)stehule(at)gmail(dot)com> wrote:
> I have no problem with this.  A context can be false for info and true
> for other in default. Please, use a different identifier than
> "context", that can be use for reading context in future - maybe
> "attach_context" or some similar.

error_context?

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

2011/10/15 Robert Haas <robertmhaas(at)gmail(dot)com>:
> On Sat, Oct 15, 2011 at 12:24 AM, Pavel Stehule <pavel(dot)stehule(at)gmail(dot)com> wrote:
>> I have no problem with this.  A context can be false for info and true
>> for other in default. Please, use a different identifier than
>> "context", that can be use for reading context in future - maybe
>> "attach_context" or some similar.
>
> error_context?

what about show_context, hide_context, hold_context, use_context ??

>
> --
> Robert Haas
> EnterpriseDB: http://www.enterprisedb.com
> The Enterprise PostgreSQL Company
>

Pavel Stehule <pavel(dot)stehule(at)gmail(dot)com> writes:
> 2011/10/15 Robert Haas <robertmhaas(at)gmail(dot)com>:
>> On Sat, Oct 15, 2011 at 12:24 AM, Pavel Stehule <pavel(dot)stehule(at)gmail(dot)com> wrote:
>>> I have no problem with this. A context can be false for info and true
>>> for other in default. Please, use a different identifier than
>>> "context", that can be use for reading context in future - maybe
>>> "attach_context" or some similar.

>> error_context?

> what about show_context, hide_context, hold_context, use_context ??

I still think it should be CONTEXT, period. All the other options to
RAISE are named directly after the message lines they control; why
should this one be different?

regards, tom lane

2011/10/15 Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>:
> Pavel Stehule <pavel(dot)stehule(at)gmail(dot)com> writes:
>> 2011/10/15 Robert Haas <robertmhaas(at)gmail(dot)com>:
>>> On Sat, Oct 15, 2011 at 12:24 AM, Pavel Stehule <pavel(dot)stehule(at)gmail(dot)com> wrote:
>>>> I have no problem with this.  A context can be false for info and true
>>>> for other in default. Please, use a different identifier than
>>>> "context", that can be use for reading context in future - maybe
>>>> "attach_context" or some similar.
>
>>> error_context?
>
>> what about show_context, hide_context, hold_context, use_context ??
>
> I still think it should be CONTEXT, period.  All the other options to
> RAISE are named directly after the message lines they control; why
> should this one be different?

I had a idea to set CONTEXT from RAISE statement - for forwarding data
from handled exception

some like

BEGIN
...
EXCEPTION WHEN ...
GET DIAGNOSTICS _context = PG_EXCEPTION_CONTEXT;
REISE USING context = _context;
END;

Regards

Pavel Stehule

>
>                        regards, tom lane
>

> No, I don't think so. The use-case for this sort of thing seems to me
> to be messages that are directed to the user or DBA, and don't want to
> be decorated with a lot of information about where they came from.
> That determination is usually pretty clear when you write the code.

For my case, I agree with Tom. For example, in my recent debugging
session, I was debugging a recursive function ... one which calls
itself, up to 6 levels deep. For that function, I want to turn context
off because there's so much it becomes unreadable, and instead I put a
nesting counter in the INFO.

I don't want to turn of context for other functions universally -- even
in the same ETL session -- because I want to know what called them,
since some of them can be called on multiple paths.

--
Josh Berkus
PostgreSQL Experts Inc.
http://pgexperts.com