Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Assertion failure with cursor #10

Closed
hlinnaka opened this issue May 6, 2024 · 2 comments · Fixed by #11 or #14
Closed

Assertion failure with cursor #10

hlinnaka opened this issue May 6, 2024 · 2 comments · Fixed by #11 or #14

Comments

@hlinnaka
Copy link
Contributor

hlinnaka commented May 6, 2024

postgres=# create table foo (i int);
CREATE TABLE
postgres=# insert into foo select g from generate_series(1, 100000) g;
INSERT 0 100000
postgres=# set pg_tracing.sample_rate = 1.0;
SET
postgres=# begin;
BEGIN
postgres=*# declare foocur CURSOR FOR SELECT * from foo;
DECLARE CURSOR
postgres=*# fetch forward 10 from foocur;
server closed the connection unexpectedly
	This probably means the server terminated abnormally
	before or while processing the request.
The connection to the server was lost. Attempting reset: Failed.
TRAP: failed Assert("nested_level <= max_nested_level"), File: "src/pg_tracing.c", Line: 620, PID: 510625
postgres: heikki postgres [local] FETCH(ExceptionalCondition+0xaf)[0x55fb74f9651f]
/home/heikki/pgsql.master/lib/pg_tracing.so(+0x7242)[0x7f96b5563242]
/home/heikki/pgsql.master/lib/pg_tracing.so(+0x4940)[0x7f96b5560940]
postgres: heikki postgres [local] FETCH(ExecutorRun+0x45)[0x55fb74a77db5]
postgres: heikki postgres [local] FETCH(+0x720924)[0x55fb74d76924]
postgres: heikki postgres [local] FETCH(+0x7217ec)[0x55fb74d777ec]
postgres: heikki postgres [local] FETCH(PortalRunFetch+0x179)[0x55fb74d77149]
postgres: heikki postgres [local] FETCH(PerformPortalFetch+0x191)[0x55fb749d7f31]
postgres: heikki postgres [local] FETCH(standard_ProcessUtility+0x515)[0x55fb74d78b25]
/home/heikki/pgsql.master/lib/pg_tracing.so(+0x5366)[0x7f96b5561366]
postgres: heikki postgres [local] FETCH(ProcessUtility+0x132)[0x55fb74d785d2]
postgres: heikki postgres [local] FETCH(+0x721c7a)[0x55fb74d77c7a]
postgres: heikki postgres [local] FETCH(+0x720734)[0x55fb74d76734]
postgres: heikki postgres [local] FETCH(PortalRun+0x29f)[0x55fb74d7637f]
postgres: heikki postgres [local] FETCH(+0x71b727)[0x55fb74d71727]
postgres: heikki postgres [local] FETCH(PostgresMain+0x922)[0x55fb74d70992]
postgres: heikki postgres [local] FETCH(+0x713063)[0x55fb74d69063]
postgres: heikki postgres [local] FETCH(postmaster_child_launch+0xe7)[0x55fb74c69867]
postgres: heikki postgres [local] FETCH(+0x61a6fa)[0x55fb74c706fa]
postgres: heikki postgres [local] FETCH(+0x617b99)[0x55fb74c6db99]
postgres: heikki postgres [local] FETCH(PostmasterMain+0x18e7)[0x55fb74c6cd87]
postgres: heikki postgres [local] FETCH(+0x4bd7dd)[0x55fb74b137dd]
/lib/x86_64-linux-gnu/libc.so.6(+0x2724a)[0x7f96b484824a]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x85)[0x7f96b4848305]
postgres: heikki postgres [local] FETCH(_start+0x21)[0x55fb74730b21]
2024-05-06 20:44:22.611 EEST [510617] LOG:  server process (PID 510625) was terminated by signal 6: Aborted
2024-05-06 20:44:22.611 EEST [510617] DETAIL:  Failed process was running: fetch forward 10 from foocur;
2024-05-06 20:44:22.611 EEST [510617] LOG:  terminating any other active server processes
bonnefoa added a commit that referenced this issue May 7, 2024
When fetching an existing cursors, the portal already exists and the
query directly starts from ExecutorRun without going through planner,
post_parse or ExecutorStart. Since top spans were only initialised
within those 3 hooks, cursor fetch wouldn't have a matching top span.

This commit fixes the issue by creating the top span in ExecutorRun if
it doesn't exist.

Fixes #10
bonnefoa added a commit that referenced this issue May 7, 2024
When fetching an existing cursors, the portal already exists and the
query directly starts from ExecutorRun without going through planner,
post_parse or ExecutorStart. Since top spans were only initialised
within those 3 hooks, cursor fetch wouldn't have a matching top span.

This commit fixes the issue by creating the top span in ExecutorRun if
it doesn't exist.

Fixes #10
bonnefoa added a commit that referenced this issue May 7, 2024
When fetching an existing cursors, the portal already exists and the
query directly starts from ExecutorRun without going through planner,
post_parse or ExecutorStart. Since top spans were only initialised
within those 3 hooks, cursor fetch wouldn't have a matching top span.

This commit fixes the issue by creating the top span in ExecutorRun if
it doesn't exist.

Fixes #10
@hlinnaka
Copy link
Contributor Author

hlinnaka commented May 7, 2024

Thanks for the fix!

This still fails:

postgres=# begin;
BEGIN
postgres=*# declare foocur CURSOR FOR SELECT * from foo;
DECLARE CURSOR
postgres=*# move forward 100 foocur;
MOVE 100
postgres=*# close foocur;
server closed the connection unexpectedly
	This probably means the server terminated abnormally
	before or while processing the request.
The connection to the server was lost. Attempting reset: Failed.
TRAP: failed Assert("nested_level <= max_nested_level"), File: "src/pg_tracing.c", Line: 620, PID: 560011
postgres: heikki postgres ::1(57476) CLOSE CURSOR(ExceptionalCondition+0xaf)[0x55900b67551f]
/home/heikki/pgsql.master/lib/pg_tracing.so(+0x7272)[0x7f045eeab272]
/home/heikki/pgsql.master/lib/pg_tracing.so(+0x4cc2)[0x7f045eea8cc2]
postgres: heikki postgres ::1(57476) CLOSE CURSOR(ExecutorFinish+0x27)[0x55900b1572d7]
postgres: heikki postgres ::1(57476) CLOSE CURSOR(PortalCleanup+0xdd)[0x55900b0b71dd]
postgres: heikki postgres ::1(57476) CLOSE CURSOR(PortalDrop+0x187)[0x55900b6c4e77]
postgres: heikki postgres ::1(57476) CLOSE CURSOR(PerformPortalClose+0x156)[0x55900b0b70f6]
postgres: heikki postgres ::1(57476) CLOSE CURSOR(standard_ProcessUtility+0x4ff)[0x55900b457b0f]
/home/heikki/pgsql.master/lib/pg_tracing.so(+0x5396)[0x7f045eea9396]
postgres: heikki postgres ::1(57476) CLOSE CURSOR(ProcessUtility+0x132)[0x55900b4575d2]
postgres: heikki postgres ::1(57476) CLOSE CURSOR(+0x721c7a)[0x55900b456c7a]
postgres: heikki postgres ::1(57476) CLOSE CURSOR(+0x720e56)[0x55900b455e56]
postgres: heikki postgres ::1(57476) CLOSE CURSOR(PortalRun+0x330)[0x55900b455410]
postgres: heikki postgres ::1(57476) CLOSE CURSOR(+0x71b727)[0x55900b450727]
postgres: heikki postgres ::1(57476) CLOSE CURSOR(PostgresMain+0x922)[0x55900b44f992]
postgres: heikki postgres ::1(57476) CLOSE CURSOR(+0x713063)[0x55900b448063]
postgres: heikki postgres ::1(57476) CLOSE CURSOR(postmaster_child_launch+0xe7)[0x55900b348867]
postgres: heikki postgres ::1(57476) CLOSE CURSOR(+0x61a6fa)[0x55900b34f6fa]
postgres: heikki postgres ::1(57476) CLOSE CURSOR(+0x617b99)[0x55900b34cb99]
postgres: heikki postgres ::1(57476) CLOSE CURSOR(PostmasterMain+0x18e7)[0x55900b34bd87]
postgres: heikki postgres ::1(57476) CLOSE CURSOR(+0x4bd7dd)[0x55900b1f27dd]
/lib/x86_64-linux-gnu/libc.so.6(+0x2724a)[0x7f045e24824a]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x85)[0x7f045e248305]
postgres: heikki postgres ::1(57476) CLOSE CURSOR(_start+0x21)[0x55900ae0fb21]
2024-05-07 15:28:08.445 EEST [556193] LOG:  server process (PID 560011) was terminated by signal 6: Aborted
2024-05-07 15:28:08.445 EEST [556193] DETAIL:  Failed process was running: close foocur;
2024-05-07 15:28:08.445 EEST [556193] LOG:  terminating any other active server processes

bonnefoa added a commit that referenced this issue May 7, 2024
Closing a cursor will directly call ExecutorFinish. We need to create
the top span for those cases.

Also, as ExecutorEnd will be called, we will try to generate spans from
planstate. However, traced planstates won't be available and representing
planstate spans for cursor execution doesn't fit our current model. To
fix this, we disable full query instrumentation for cursors.

Fixes #10
bonnefoa added a commit that referenced this issue May 7, 2024
Closing a cursor will directly call ExecutorFinish. We need to create
the top span for those cases.

Also, as ExecutorEnd will be called, we will try to generate spans from
planstate. However, traced planstates won't be available and representing
planstate spans for cursor execution doesn't fit our current model. To
fix this, we disable full query instrumentation for cursors.

Fixes #10
@bonnefoa
Copy link
Collaborator

bonnefoa commented May 7, 2024

Thanks for the report.
I've pushed another fix that handles cursor close.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
2 participants