From 14b134cb9f9329ba30ad465d1dcf849cef66ef37 Mon Sep 17 00:00:00 2001 From: Anthonin Bonnefoy Date: Mon, 9 Sep 2024 11:30:42 +0200 Subject: [PATCH] On error, only pop spans from the current ongoing level Query may still proceed despite the thrown error so we need to keep spans from previous nested levels. --- Makefile | 2 +- expected/nested.out | 1 + expected/nested_17.out | 27 +++++++++++++++++++++++++++ expected/utility.out | 13 +++++++++++++ sql/nested.sql | 1 + sql/nested_17.sql | 8 ++++++++ sql/utility.sql | 14 ++++++++++++++ src/pg_tracing.c | 2 +- 8 files changed, 66 insertions(+), 2 deletions(-) create mode 100644 expected/nested_17.out create mode 100644 sql/nested_17.sql diff --git a/Makefile b/Makefile index ddb4e02..ed63159 100644 --- a/Makefile +++ b/Makefile @@ -40,7 +40,7 @@ endif ifeq ($(shell test $(PG_VERSION) -lt 17; echo $$?),0) REGRESSCHECKS += planstate_projectset else -REGRESSCHECKS += planstate_projectset_17 +REGRESSCHECKS += planstate_projectset_17 nested_17 endif # PG 18 contains additional psql metacommand to test extended protocol diff --git a/expected/nested.out b/expected/nested.out index 6846185..efddda5 100644 --- a/expected/nested.out +++ b/expected/nested.out @@ -295,5 +295,6 @@ select span_operation, lvl FROM peek_ordered_spans where trace_id='0000000000000 IndexOnlyScan using pg_class_oid_index on pg_class | 7 (12 rows) +CALL clean_spans(); -- Cleanup CALL clean_spans(); diff --git a/expected/nested_17.out b/expected/nested_17.out new file mode 100644 index 0000000..5445386 --- /dev/null +++ b/expected/nested_17.out @@ -0,0 +1,27 @@ +-- Test error thrown within a nested function +/*traceparent='00-00000000000000000000000000000001-0000000000000001-01'*/ SELECT + eval_expr(format('date %L + interval %L', '-infinity', 'infinity')), + eval_expr(format('date %L - interval %L', '-infinity', 'infinity')); + eval_expr | eval_expr +------------------------+----------- + timestamp out of range | -infinity +(1 row) + +select span_operation, lvl FROM peek_ordered_spans where trace_id='00000000000000000000000000000001'; + span_operation | lvl +----------------------------------------------------------------------+----- + SELECT eval_expr(format($1, $2, $3)), eval_expr(format($4, $5, $6)); | 1 + Planner | 2 + ExecutorRun | 2 + Result | 3 + $2||expr | 4 + Planner | 5 + Planner | 5 + select date $1 - interval $2 | 4 + Planner | 5 + ExecutorRun | 5 + Result | 6 +(11 rows) + +-- Cleanup +CALL clean_spans(); diff --git a/expected/utility.out b/expected/utility.out index 1b60f42..bb08d36 100644 --- a/expected/utility.out +++ b/expected/utility.out @@ -398,6 +398,19 @@ CREATE OR REPLACE FUNCTION function_with_error(IN anyarray, OUT x anyelement, OU RETURNS SETOF RECORD LANGUAGE sql STRICT IMMUTABLE PARALLEL SAFE AS 'select s from pg_catalog.generate_series(1, 1, 1) as g(s)'; +CREATE FUNCTION eval_expr(expr text) +RETURNS text AS +$$ +DECLARE + result text; +BEGIN + EXECUTE 'select '||expr INTO result; + RETURN result; +EXCEPTION WHEN OTHERS THEN + RETURN SQLERRM; +END +$$ +LANGUAGE plpgsql; -- Check that tracing a function call with the wrong number of arguments is managed correctly /*dddbs='postgres.db',traceparent='00-00000000000000000000000000000004-0000000000000004-01'*/ select function_with_error('{1,2,3}'::int[]); ERROR: return type mismatch in function declared to return record diff --git a/sql/nested.sql b/sql/nested.sql index cff9130..3d9146a 100644 --- a/sql/nested.sql +++ b/sql/nested.sql @@ -191,6 +191,7 @@ SELECT count(distinct query_id)=2 from pg_tracing_consume_spans where trace_id=' -- Trace a statement with multiple nested levels /*dddbs='postgres.db',traceparent='00-00000000000000000000000000000059-0000000000000059-01'*/ select * FROM test_2_nested_levels(1); select span_operation, lvl FROM peek_ordered_spans where trace_id='00000000000000000000000000000059'; +CALL clean_spans(); -- Cleanup CALL clean_spans(); diff --git a/sql/nested_17.sql b/sql/nested_17.sql new file mode 100644 index 0000000..6a7a763 --- /dev/null +++ b/sql/nested_17.sql @@ -0,0 +1,8 @@ +-- Test error thrown within a nested function +/*traceparent='00-00000000000000000000000000000001-0000000000000001-01'*/ SELECT + eval_expr(format('date %L + interval %L', '-infinity', 'infinity')), + eval_expr(format('date %L - interval %L', '-infinity', 'infinity')); +select span_operation, lvl FROM peek_ordered_spans where trace_id='00000000000000000000000000000001'; + +-- Cleanup +CALL clean_spans(); diff --git a/sql/utility.sql b/sql/utility.sql index 1ddefc6..ed64486 100644 --- a/sql/utility.sql +++ b/sql/utility.sql @@ -305,6 +305,20 @@ CREATE OR REPLACE FUNCTION function_with_error(IN anyarray, OUT x anyelement, OU LANGUAGE sql STRICT IMMUTABLE PARALLEL SAFE AS 'select s from pg_catalog.generate_series(1, 1, 1) as g(s)'; +CREATE FUNCTION eval_expr(expr text) +RETURNS text AS +$$ +DECLARE + result text; +BEGIN + EXECUTE 'select '||expr INTO result; + RETURN result; +EXCEPTION WHEN OTHERS THEN + RETURN SQLERRM; +END +$$ +LANGUAGE plpgsql; + -- Check that tracing a function call with the wrong number of arguments is managed correctly /*dddbs='postgres.db',traceparent='00-00000000000000000000000000000004-0000000000000004-01'*/ select function_with_error('{1,2,3}'::int[]); diff --git a/src/pg_tracing.c b/src/pg_tracing.c index dc12de1..acadc64 100644 --- a/src/pg_tracing.c +++ b/src/pg_tracing.c @@ -1382,7 +1382,7 @@ handle_pg_error(const Traceparent * traceparent, process_query_desc(traceparent, queryDesc, sql_error_code, false, span_end_time); } span = peek_active_span(); - while (span != NULL) + while (span != NULL && span->nested_level == nested_level) { /* Assign the error code to the latest top span */ span->sql_error_code = sql_error_code;