> On 8/21/25 14:02, Frédéric Yhuel wrote:
> > This v6 patch includes the TAP test that I sent in my previous email,
> > with some enhancements.
>
> The meson test system was overlooked by this patch, and the attached v7
> fixes that.
This version needs another rebase, but I don't think this is a proper solution
yet. It's dropping the portal in an area I don't think we should be concerned
with, and it's not covering some simple cases, like a bind/execute followed
by a simple query. Also, I don't like we have to incur an extra GetPortalByName
lookup in the simple query case.
What about we just drop the unnamed portal before setting the
debug_query_string,
as Tom pointed out, but we also track if we have an active unnamed portal before
incurring the GetPortalName.
I am attaching v8 which does that. In this version, a new routine called
drop_unnamed_portal checks if there is an unnamed portal (tracked by a
backend flag),
and drops the unnamed portal inside exec_simple_query and
exec_bind_message before setting debug_query_string; so early on in the routine
before creating the new portal.
```
2025-08-29 13:03:33.412 CDT [54069] STATEMENT: SELECT a FROM foo
ORDER BY a OFFSET $1
2025-08-29 13:03:33.412 CDT [54069] LOG: statement: SELECT 1;
2025-08-29 13:03:33.412 CDT [54069] ERROR: current transaction is
aborted, commands ignored until end of transaction block
2025-08-29 13:03:33.412 CDT [54069] STATEMENT: SELECT 1;
2025-08-29 13:03:33.501 CDT [54069] LOG: statement: COMMIT;
2025-08-29 13:05:11.617 CDT [54656] LOG: statement: BEGIN;
2025-08-29 13:05:11.618 CDT [54656] LOG: execute <unnamed>: SELECT a
FROM foo ORDER BY a OFFSET $1
2025-08-29 13:05:11.618 CDT [54656] DETAIL: Parameters: $1 = '4999'
2025-08-29 13:05:11.619 CDT [54656] LOG: temporary file: path
"base/pgsql_tmp/pgsql_tmp54656.0", size 73728
2025-08-29 13:05:11.619 CDT [54656] LOG: statement: SELECT 1;
2025-08-29 13:05:11.619 CDT [54656] LOG: statement: COMMIT
```
> From a user's point of view, Sami's patch is much better, because it
> always logs the right query (except for the SQL cursor),
I think the temp logging on the cursor close is OK and expected, and we
are blaming the correct cursor.
```
DECLARE CURSOR
test=*# fetch foo;
LOG: statement: fetch foo;
a
---
2
(1 row)
test=*# fetch foo;
LOG: statement: fetch foo;
a
---
3
(1 row)
test=*# SELECT $1 \bind 1
test-*# ;
LOG: execute <unnamed>: SELECT $1
;
DETAIL: Parameters: $1 = '1'
?column?
----------
1
(1 row)
test=*# close foo;
LOG: statement: close foo;
LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp55603.0", size 90112
CLOSE CURSOR
test=*#
```
When we rollback, is the one case I can think of in which we will not be able
to blame the correct query, such as the example below. So I don't think
we will be able to make logging work correctly for all cases, since the
temp logging happens at a far lower layer.
```
test=# begin;
LOG: statement: begin;
BEGIN
test=*# declare foo cursor for SELECT a FROM foo ORDER BY a OFFSET 1;
LOG: statement: declare foo cursor for SELECT a FROM foo ORDER BY a OFFSET 1;
DECLARE CURSOR
test=*# fetch foo;
LOG: statement: fetch foo;
a
---
2
(1 row)
test=*# fetch foo;
LOG: statement: fetch foo;
a
---
3
(1 row)
test=*# fetch foo;
LOG: statement: fetch foo;
a
---
4
(1 row)
test=*# fetch all foo;
LOG: statement: fetch all foo;
LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp56184.1", size 69944
a
------
5
...
....
test=*# SELECT $1 \bind 1
test-*# ;
LOG: execute <unnamed>: SELECT $1
;
DETAIL: Parameters: $1 = '1'
?column?
----------
1
(1 row)
test=*# close foo_noexist;
LOG: statement: close foo_noexist;
ERROR: cursor "foo_noexist" does not exist
LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp56184.0", size 90112
test=!#
```
Thoughts on v8?
--
Sami Imseih
Amazon Web Services (AWS)
