Re: statement logging / extended query protocol issues

Simon Riggs wrote:
> On Tue, 2005-09-06 at 07:47 +0000, Oliver Jowett wrote:
>
>>Simon Riggs wrote:
>>
>>
>>>Looking more closely, I don't think either is correct. Both can be reset
>>>according to rewind operations - see DoPortalRewind().
>>>
>>>We'd need to add another bool onto the Portal status data structure.
>>
>>AFAIK this is only an issue with SCROLLABLE cursors, which v3 portals
>>aren't.
>
> OK, that may be so, but the internals don't know that. If I use atEnd or
> atStart then messages would differ from v3 to v2. It would then be easy
> to confuse v2 cursor actions with multiple re-executions in v3. I want
> to be able to look at the log and work out what happened, not to start
> asking questions like "do you use v2, v3 or a mix of both?".

Uh, but the logging in question only runs from exec_execute_message,
which is explicitly handling a v3 Execute message, not an EXECUTE or
FETCH from somewhere else? If that can be confused with a v2 query, then
we should be logging it in such a way that it doesn't get confused (this
is one reason why I don't like your approach of synthesizing
FETCH/EXECUTE statements that were never actually submitted by the client).

I don't think we should worry about trying to support v3 Execute against
a SCROLLABLE cursor created via DECLARE that has been rewound -- that's
a strange case and there was some discussion previously about separating
the v3 portal vs. cursor namespaces anyway.

> Oliver, would it be possible to show a simplified call sequence and what
> you would like to see logged for each call?

The JDBC driver generates one of these sequences:

(1)
Parse (unnamed statement) "SELECT 1"
Bind (unnamed statement -> unnamed portal)
Execute (unnamed portal, no row limit)

(2)
Parse (named statement S_1) "SELECT 1"
repeatedly:
Bind (named statement S_1 -> unnamed portal)
Execute (unnamed portal, no row limit)

(3)
Parse (named statement S_2) "SELECT 1"
repeatedly:
Bind (named statement S_2 -> named portal C_2)
repeatedly:
Execute (named portal C_2, row limit 42)

Ideal output is:

(1) LOG: statement: SELECT 1

(2) LOG: statement: SELECT 1
LOG: statement: SELECT 1
LOG: statement: SELECT 1

(3) LOG: statement: SELECT 1
LOG: statement: SELECT 1
LOG: statement: SELECT 1

In case (3), that's one log line per repeat of the outer loop,
regardless of how many Executes are sent in the inner loop.

Syntax error case (on Parse):
LOG: statement: I AM A SYNTAX ERROR
ERROR: syntax error ....

or something like this if it's easier:
ERROR: syntax error ....
LOG: failing statement: I AM A SYNTAX ERROR

This would require special handling of Parse messages to grab the error
case somehow.

Second best would be something like:

(1) LOG: parse statement: SELECT 1
LOG: exec statement: SELECT 1

(2) LOG: parse statement: SELECT 1
LOG: exec statement: SELECT 1
LOG: exec statement: SELECT 1
LOG: exec statement: SELECT 1

(3) LOG: parse statement: SELECT 1
LOG: exec statement: SELECT 1
LOG: exec statement: SELECT 1
LOG: exec statement: SELECT 1

Same notes apply to (3) here.

Syntax error case:
LOG: parse statement: I AM A SYNTAX ERROR
ERROR: syntax error ....

Note that case (1) is the most common case for application queries via
the JDBC driver, and case (2) is the most common for internally
generated statements like BEGIN.

As you can see from the output I'd like, I don't think that synthesizing
FETCH / EXECUTE queries that don't actually exist or logging statement /
portal names are useful things to do, at least at the Joe Average User
level.

Also note that the JDBC driver doesn't exercise all of the extended
protocol -- for example it's possible to re-Bind the same unnamed
statement repeatedly, or have multiple Executes on an unnamed portal
with a row limit, but the JDBC driver never does that.

-O