Improve reporting of errors in extension script files.

tglsfdc · tglsfdc · commit 774171c4f640 · 2024-10-22T11:31:45.000-04:00
Previously, CREATE/ALTER EXTENSION gave basically no useful context about errors reported while executing script files. I think the idea was that you could run the same commands manually to see the error, but that's often quite inconvenient. Let's improve that. If we get an error during raw parsing, we won't have a current statement identified by a RawStmt node, but we should always get a syntax error position. Show the portion of the script from the last semicolon-newline before the error position to the first one after it. There are cases where this might show only a fragment of a statement, but that should be uncommon, and it seems better than showing the whole script file. Without an error cursor, if we have gotten past raw parsing (which we probably have), we can report just the current SQL statement as an item of error context. In any case also report the script file name as error context, since it might not be entirely obvious which of a series of update scripts failed. We can also show an approximate script line number in case whatever we printed of the query isn't sufficiently identifiable. The error-context code path is already exercised by some test_extensions test cases, but add tests for the syntax-error path. Discussion: https://postgr.es/m/ZvV1ClhnbJLCz7Sm@msg.df7cb.de
diff --git a/src/backend/commands/extension.c b/src/backend/commands/extension.c
@@ -54,6 +54,7 @@
 #include "funcapi.h"
 #include "mb/pg_wchar.h"
 #include "miscadmin.h"
+#include "nodes/queryjumble.h"
 #include "storage/fd.h"
 #include "tcop/utility.h"
 #include "utils/acl.h"
@@ -107,6 +108,17 @@ typedef struct ExtensionVersionInfo
 	struct ExtensionVersionInfo *previous;	/* current best predecessor */
 } ExtensionVersionInfo;
 
+/*
+ * Information for script_error_callback()
+ */
+typedef struct
+{
+	const char *sql;			/* entire script file contents */
+	const char *filename;		/* script file pathname */
+	ParseLoc	stmt_location;	/* current stmt start loc, or -1 if unknown */
+	ParseLoc	stmt_len;		/* length in bytes; 0 means "rest of string" */
+} script_error_callback_arg;
+
 /* Local functions */
 static List *find_update_path(List *evi_list,
 							  ExtensionVersionInfo *evi_start,
@@ -670,9 +682,139 @@ read_extension_script_file(const ExtensionControlFile *control,
 	return dest_str;
 }
 
+/*
+ * error context callback for failures in script-file execution
+ */
+static void
+script_error_callback(void *arg)
+{
+	script_error_callback_arg *callback_arg = (script_error_callback_arg *) arg;
+	const char *query = callback_arg->sql;
+	int			location = callback_arg->stmt_location;
+	int			len = callback_arg->stmt_len;
+	int			syntaxerrposition;
+	const char *lastslash;
+
+	/*
+	 * If there is a syntax error position, convert to internal syntax error;
+	 * otherwise report the current query as an item of context stack.
+	 *
+	 * Note: we'll provide no context except the filename if there's neither
+	 * an error position nor any known current query.  That shouldn't happen
+	 * though: all errors reported during raw parsing should come with an
+	 * error position.
+	 */
+	syntaxerrposition = geterrposition();
+	if (syntaxerrposition > 0)
+	{
+		/*
+		 * If we do not know the bounds of the current statement (as would
+		 * happen for an error occurring during initial raw parsing), we have
+		 * to use a heuristic to decide how much of the script to show.  We'll
+		 * also use the heuristic in the unlikely case that syntaxerrposition
+		 * is outside what we think the statement bounds are.
+		 */
+		if (location < 0 || syntaxerrposition < location ||
+			(len > 0 && syntaxerrposition > location + len))
+		{
+			/*
+			 * Our heuristic is pretty simple: look for semicolon-newline
+			 * sequences, and break at the last one strictly before
+			 * syntaxerrposition and the first one strictly after.  It's
+			 * certainly possible to fool this with semicolon-newline embedded
+			 * in a string literal, but it seems better to do this than to
+			 * show the entire extension script.
+			 */
+			int			slen = strlen(query);
+
+			location = len = 0;
+			for (int loc = 0; loc < slen; loc++)
+			{
+				if (query[loc] != ';')
+					continue;
+				if (query[loc + 1] == '\r')
+					loc++;
+				if (query[loc + 1] == '\n')
+				{
+					int			bkpt = loc + 2;
+
+					if (bkpt < syntaxerrposition)
+						location = bkpt;
+					else if (bkpt > syntaxerrposition)
+					{
+						len = bkpt - location;
+						break;	/* no need to keep searching */
+					}
+				}
+			}
+		}
+
+		/* Trim leading/trailing whitespace, for consistency */
+		query = CleanQuerytext(query, &location, &len);
+
+		/*
+		 * Adjust syntaxerrposition.  It shouldn't be pointing into the
+		 * whitespace we just trimmed, but cope if it is.
+		 */
+		syntaxerrposition -= location;
+		if (syntaxerrposition < 0)
+			syntaxerrposition = 0;
+		else if (syntaxerrposition > len)
+			syntaxerrposition = len;
+
+		/* And report. */
+		errposition(0);
+		internalerrposition(syntaxerrposition);
+		internalerrquery(pnstrdup(query, len));
+	}
+	else if (location >= 0)
+	{
+		/*
+		 * Since no syntax cursor will be shown, it's okay and helpful to trim
+		 * the reported query string to just the current statement.
+		 */
+		query = CleanQuerytext(query, &location, &len);
+		errcontext("SQL statement \"%.*s\"", len, query);
+	}
+
+	/*
+	 * Trim the reported file name to remove the path.  We know that
+	 * get_extension_script_filename() inserted a '/', regardless of whether
+	 * we're on Windows.
+	 */
+	lastslash = strrchr(callback_arg->filename, '/');
+	if (lastslash)
+		lastslash++;
+	else
+		lastslash = callback_arg->filename; /* shouldn't happen, but cope */
+
+	/*
+	 * If we have a location (which, as said above, we really always should)
+	 * then report a line number to aid in localizing problems in big scripts.
+	 */
+	if (location >= 0)
+	{
+		int			linenumber = 1;
+
+		for (query = callback_arg->sql; *query; query++)
+		{
+			if (--location < 0)
+				break;
+			if (*query == '\n')
+				linenumber++;
+		}
+		errcontext("extension script file \"%s\", near line %d",
+				   lastslash, linenumber);
+	}
+	else
+		errcontext("extension script file \"%s\"", lastslash);
+}
+
 /*
  * Execute given SQL string.
  *
+ * The filename the string came from is also provided, for error reporting.
+ *
  * Note: it's tempting to just use SPI to execute the string, but that does
  * not work very well.  The really serious problem is that SPI will parse,
  * analyze, and plan the whole string before executing any of it; of course
@@ -682,12 +824,27 @@ read_extension_script_file(const ExtensionControlFile *control,
  * could be very long.
  */
 static void
-execute_sql_string(const char *sql)
+execute_sql_string(const char *sql, const char *filename)
 {
+	script_error_callback_arg callback_arg;
+	ErrorContextCallback scripterrcontext;
 	List	   *raw_parsetree_list;
 	DestReceiver *dest;
 	ListCell   *lc1;
 
+	/*
+	 * Setup error traceback support for ereport().
+	 */
+	callback_arg.sql = sql;
+	callback_arg.filename = filename;
+	callback_arg.stmt_location = -1;
+	callback_arg.stmt_len = -1;
+
+	scripterrcontext.callback = script_error_callback;
+	scripterrcontext.arg = (void *) &callback_arg;
+	scripterrcontext.previous = error_context_stack;
+	error_context_stack = &scripterrcontext;
+
 	/*
 	 * Parse the SQL string into a list of raw parse trees.
 	 */
@@ -709,6 +866,10 @@ execute_sql_string(const char *sql)
 		List	   *stmt_list;
 		ListCell   *lc2;
 
+		/* Report location of this query for error context callback */
+		callback_arg.stmt_location = parsetree->stmt_location;
+		callback_arg.stmt_len = parsetree->stmt_len;
+
 		/*
 		 * We do the work for each parsetree in a short-lived context, to
 		 * limit the memory used when there are many commands in the string.
@@ -778,6 +939,8 @@ execute_sql_string(const char *sql)
 		MemoryContextDelete(per_parsetree_context);
 	}
 
+	error_context_stack = scripterrcontext.previous;
+
 	/* Be sure to advance the command counter after the last script command */
 	CommandCounterIncrement();
 }
@@ -1054,7 +1217,7 @@ execute_extension_script(Oid extensionOid, ExtensionControlFile *control,
 		/* And now back to C string */
 		c_sql = text_to_cstring(DatumGetTextPP(t_sql));
 
-		execute_sql_string(c_sql);
+		execute_sql_string(c_sql, filename);
 	}
 	PG_FINALLY();
 	{
diff --git a/src/test/modules/test_extensions/Makefile b/src/test/modules/test_extensions/Makefile
@@ -13,7 +13,9 @@ EXTENSION = test_ext1 test_ext2 test_ext3 test_ext4 test_ext5 test_ext6 \
 
 DATA = test_ext1--1.0.sql test_ext2--1.0.sql test_ext3--1.0.sql \
        test_ext4--1.0.sql test_ext5--1.0.sql test_ext6--1.0.sql \
-       test_ext7--1.0.sql test_ext7--1.0--2.0.sql test_ext8--1.0.sql \
+       test_ext7--1.0.sql test_ext7--1.0--2.0.sql \
+       test_ext7--2.0--2.1bad.sql test_ext7--2.0--2.2bad.sql \
+       test_ext8--1.0.sql \
        test_ext9--1.0.sql \
        test_ext_cine--1.0.sql test_ext_cine--1.0--1.1.sql \
        test_ext_cor--1.0.sql \
diff --git a/src/test/modules/test_extensions/expected/test_extensions.out b/src/test/modules/test_extensions/expected/test_extensions.out
@@ -72,6 +72,22 @@ Objects in extension "test_ext7"
  type ext7_table2[]
 (4 rows)
 
+-- test reporting of errors in extension scripts
+alter extension test_ext7 update to '2.1bad';
+ERROR:  syntax error at or near "FUNCTIN"
+LINE 1: CREATE FUNCTIN my_erroneous_func(int) RETURNS int LANGUAGE S...
+               ^
+QUERY:  CREATE FUNCTIN my_erroneous_func(int) RETURNS int LANGUAGE SQL
+AS $$ SELECT $1 + 1 $$;
+CONTEXT:  extension script file "test_ext7--2.0--2.1bad.sql", near line 10
+alter extension test_ext7 update to '2.2bad';
+ERROR:  syntax error at or near ","
+LINE 1:  SELECT $1 + , 1 
+                     ^
+QUERY:   SELECT $1 + , 1 
+CONTEXT:  SQL statement "CREATE FUNCTION my_erroneous_func(int) RETURNS int LANGUAGE SQL
+AS $$ SELECT $1 + , 1 $$"
+extension script file "test_ext7--2.0--2.2bad.sql", near line 9
 -- test handling of temp objects created by extensions
 create extension test_ext8;
 -- \dx+ would expose a variable pg_temp_nn schema name, so we can't use it here
@@ -295,6 +311,9 @@ CREATE FUNCTION ext_cor_func() RETURNS text
 CREATE EXTENSION test_ext_cor;  -- fail
 ERROR:  function ext_cor_func() is not a member of extension "test_ext_cor"
 DETAIL:  An extension is not allowed to replace an object that it does not own.
+CONTEXT:  SQL statement "CREATE OR REPLACE FUNCTION ext_cor_func() RETURNS text
+  AS $$ SELECT 'ext_cor_func: from extension'::text $$ LANGUAGE sql"
+extension script file "test_ext_cor--1.0.sql", near line 8
 SELECT ext_cor_func();
       ext_cor_func      
 ------------------------
@@ -307,6 +326,9 @@ CREATE VIEW ext_cor_view AS
 CREATE EXTENSION test_ext_cor;  -- fail
 ERROR:  view ext_cor_view is not a member of extension "test_ext_cor"
 DETAIL:  An extension is not allowed to replace an object that it does not own.
+CONTEXT:  SQL statement "CREATE OR REPLACE VIEW ext_cor_view AS
+  SELECT 'ext_cor_view: from extension'::text AS col"
+extension script file "test_ext_cor--1.0.sql", near line 11
 SELECT ext_cor_func();
 ERROR:  function ext_cor_func() does not exist
 LINE 1: SELECT ext_cor_func();
@@ -323,6 +345,8 @@ CREATE TYPE test_ext_type;
 CREATE EXTENSION test_ext_cor;  -- fail
 ERROR:  type test_ext_type is not a member of extension "test_ext_cor"
 DETAIL:  An extension is not allowed to replace an object that it does not own.
+CONTEXT:  SQL statement "CREATE TYPE test_ext_type AS ENUM('x', 'y')"
+extension script file "test_ext_cor--1.0.sql", near line 17
 DROP TYPE test_ext_type;
 -- this makes a shell "point <<@@ polygon" operator too
 CREATE OPERATOR @@>> ( PROCEDURE = poly_contain_pt,
@@ -331,6 +355,9 @@ CREATE OPERATOR @@>> ( PROCEDURE = poly_contain_pt,
 CREATE EXTENSION test_ext_cor;  -- fail
 ERROR:  operator <<@@(point,polygon) is not a member of extension "test_ext_cor"
 DETAIL:  An extension is not allowed to replace an object that it does not own.
+CONTEXT:  SQL statement "CREATE OPERATOR <<@@ ( PROCEDURE = pt_contained_poly,
+  LEFTARG = point, RIGHTARG = polygon )"
+extension script file "test_ext_cor--1.0.sql", near line 19
 DROP OPERATOR <<@@ (point, polygon);
 CREATE EXTENSION test_ext_cor;  -- now it should work
 SELECT ext_cor_func();
@@ -379,37 +406,52 @@ CREATE COLLATION ext_cine_coll
 CREATE EXTENSION test_ext_cine;  -- fail
 ERROR:  collation ext_cine_coll is not a member of extension "test_ext_cine"
 DETAIL:  An extension may only use CREATE ... IF NOT EXISTS to skip object creation if the conflicting object is one that it already owns.
+CONTEXT:  SQL statement "CREATE COLLATION IF NOT EXISTS ext_cine_coll
+  ( LC_COLLATE = "POSIX", LC_CTYPE = "POSIX" )"
+extension script file "test_ext_cine--1.0.sql", near line 10
 DROP COLLATION ext_cine_coll;
 CREATE MATERIALIZED VIEW ext_cine_mv AS SELECT 11 AS f1;
 CREATE EXTENSION test_ext_cine;  -- fail
 ERROR:  materialized view ext_cine_mv is not a member of extension "test_ext_cine"
 DETAIL:  An extension may only use CREATE ... IF NOT EXISTS to skip object creation if the conflicting object is one that it already owns.
+CONTEXT:  SQL statement "CREATE MATERIALIZED VIEW IF NOT EXISTS ext_cine_mv AS SELECT 42 AS f1"
+extension script file "test_ext_cine--1.0.sql", near line 13
 DROP MATERIALIZED VIEW ext_cine_mv;
 CREATE FOREIGN DATA WRAPPER dummy;
 CREATE SERVER ext_cine_srv FOREIGN DATA WRAPPER dummy;
 CREATE EXTENSION test_ext_cine;  -- fail
 ERROR:  server ext_cine_srv is not a member of extension "test_ext_cine"
 DETAIL:  An extension may only use CREATE ... IF NOT EXISTS to skip object creation if the conflicting object is one that it already owns.
+CONTEXT:  SQL statement "CREATE SERVER IF NOT EXISTS ext_cine_srv FOREIGN DATA WRAPPER ext_cine_fdw"
+extension script file "test_ext_cine--1.0.sql", near line 17
 DROP SERVER ext_cine_srv;
 CREATE SCHEMA ext_cine_schema;
 CREATE EXTENSION test_ext_cine;  -- fail
 ERROR:  schema ext_cine_schema is not a member of extension "test_ext_cine"
 DETAIL:  An extension may only use CREATE ... IF NOT EXISTS to skip object creation if the conflicting object is one that it already owns.
+CONTEXT:  SQL statement "CREATE SCHEMA IF NOT EXISTS ext_cine_schema"
+extension script file "test_ext_cine--1.0.sql", near line 19
 DROP SCHEMA ext_cine_schema;
 CREATE SEQUENCE ext_cine_seq;
 CREATE EXTENSION test_ext_cine;  -- fail
 ERROR:  sequence ext_cine_seq is not a member of extension "test_ext_cine"
 DETAIL:  An extension may only use CREATE ... IF NOT EXISTS to skip object creation if the conflicting object is one that it already owns.
+CONTEXT:  SQL statement "CREATE SEQUENCE IF NOT EXISTS ext_cine_seq"
+extension script file "test_ext_cine--1.0.sql", near line 21
 DROP SEQUENCE ext_cine_seq;
 CREATE TABLE ext_cine_tab1 (x int);
 CREATE EXTENSION test_ext_cine;  -- fail
 ERROR:  table ext_cine_tab1 is not a member of extension "test_ext_cine"
 DETAIL:  An extension may only use CREATE ... IF NOT EXISTS to skip object creation if the conflicting object is one that it already owns.
+CONTEXT:  SQL statement "CREATE TABLE IF NOT EXISTS ext_cine_tab1 (x int)"
+extension script file "test_ext_cine--1.0.sql", near line 23
 DROP TABLE ext_cine_tab1;
 CREATE TABLE ext_cine_tab2 AS SELECT 42 AS y;
 CREATE EXTENSION test_ext_cine;  -- fail
 ERROR:  table ext_cine_tab2 is not a member of extension "test_ext_cine"
 DETAIL:  An extension may only use CREATE ... IF NOT EXISTS to skip object creation if the conflicting object is one that it already owns.
+CONTEXT:  SQL statement "CREATE TABLE IF NOT EXISTS ext_cine_tab2 AS SELECT 42 AS y"
+extension script file "test_ext_cine--1.0.sql", near line 25
 DROP TABLE ext_cine_tab2;
 CREATE EXTENSION test_ext_cine;
 \dx+ test_ext_cine
diff --git a/src/test/modules/test_extensions/meson.build b/src/test/modules/test_extensions/meson.build
@@ -15,6 +15,8 @@ test_install_data += files(
   'test_ext6.control',
   'test_ext7--1.0--2.0.sql',
   'test_ext7--1.0.sql',
+  'test_ext7--2.0--2.1bad.sql',
+  'test_ext7--2.0--2.2bad.sql',
   'test_ext7.control',
   'test_ext8--1.0.sql',
   'test_ext8.control',
diff --git a/src/test/modules/test_extensions/sql/test_extensions.sql b/src/test/modules/test_extensions/sql/test_extensions.sql
@@ -28,6 +28,10 @@ create extension test_ext7;
 alter extension test_ext7 update to '2.0';
 \dx+ test_ext7
 
+-- test reporting of errors in extension scripts
+alter extension test_ext7 update to '2.1bad';
+alter extension test_ext7 update to '2.2bad';
+
 -- test handling of temp objects created by extensions
 create extension test_ext8;
 
diff --git a/src/test/modules/test_extensions/test_ext7--2.0--2.1bad.sql b/src/test/modules/test_extensions/test_ext7--2.0--2.1bad.sql
@@ -0,0 +1,14 @@
+/* src/test/modules/test_extensions/test_ext7--2.0--2.1bad.sql */
+
+-- complain if script is sourced in psql, rather than via ALTER EXTENSION
+\echo Use "ALTER EXTENSION test_ext7 UPDATE TO '2.1bad'" to load this file. \quit
+
+-- test reporting of a simple syntax error in an extension script
+CREATE FUNCTION my_okay_func(int) RETURNS int LANGUAGE SQL
+AS $$ SELECT $1 + 1 $$;
+
+CREATE FUNCTIN my_erroneous_func(int) RETURNS int LANGUAGE SQL
+AS $$ SELECT $1 + 1 $$;
+
+CREATE FUNCTION my_other_func(int) RETURNS int LANGUAGE SQL
+AS $$ SELECT $1 + 1 $$;
diff --git a/src/test/modules/test_extensions/test_ext7--2.0--2.2bad.sql b/src/test/modules/test_extensions/test_ext7--2.0--2.2bad.sql
@@ -0,0 +1,13 @@
+/* src/test/modules/test_extensions/test_ext7--2.0--2.2bad.sql */
+
+-- complain if script is sourced in psql, rather than via ALTER EXTENSION
+\echo Use "ALTER EXTENSION test_ext7 UPDATE TO '2.2bad'" to load this file. \quit
+
+-- test reporting of a nested syntax error in an extension script
+SET LOCAL check_function_bodies = on;
+
+CREATE FUNCTION my_erroneous_func(int) RETURNS int LANGUAGE SQL
+AS $$ SELECT $1 + , 1 $$;
+
+CREATE FUNCTION my_other_func(int) RETURNS int LANGUAGE SQL
+AS $$ SELECT $1 + 1 $$;
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
