From 866229bc323619bc8686bad99951f95d5d46fe19 Mon Sep 17 00:00:00 2001
From: Gusted <postmaster@gusted.xyz>
Date: Sun, 14 Jan 2024 00:01:39 +0100
Subject: [PATCH] [GITEA] Log SQL queries when the database return error

- When the database returns an error about the SQL query, the error is
logged but not the SQL query and arguments, which is just as valuable as
the vague deeply hidden documented error that the database returns.
It's possible to log the SQL query by logging **all** SQL queries. For
bigger instances such as Codeberg, this is not a viable option.
- Adds a new hook, enabled by default, to log SQL queries with their
arguments and the error returned by the database when the database
returns an error.
- This likely needs some fine tuning in the future to decide when to
enable this, as the error is already logged and if people have the
`[database].LOG_SQL` option enabled, the SQL would be logged twice. But
given that it's an rare occurence for SQL queries to error, it's fine to
leave that as-is.
- Ref: https://codeberg.org/forgejo/forgejo/issues/1998
---
 models/db/engine.go      | 20 ++++++++++++++++++++
 models/db/engine_test.go | 28 ++++++++++++++++++++++++++++
 2 files changed, 48 insertions(+)

diff --git a/models/db/engine.go b/models/db/engine.go
index 6591b496d6..6362baa9c6 100755
--- a/models/db/engine.go
+++ b/models/db/engine.go
@@ -153,6 +153,9 @@ func InitEngine(ctx context.Context) error {
 			Logger:   log.GetLogger("xorm"),
 		})
 	}
+	xormEngine.AddHook(&ErrorQueryHook{
+		Logger: log.GetLogger("xorm"),
+	})
 
 	SetDefaultEngine(ctx, xormEngine)
 	return nil
@@ -325,3 +328,20 @@ func (h *SlowQueryHook) AfterProcess(c *contexts.ContextHook) error {
 	}
 	return nil
 }
+
+type ErrorQueryHook struct {
+	Logger log.Logger
+}
+
+var _ contexts.Hook = &ErrorQueryHook{}
+
+func (ErrorQueryHook) BeforeProcess(c *contexts.ContextHook) (context.Context, error) {
+	return c.Ctx, nil
+}
+
+func (h *ErrorQueryHook) AfterProcess(c *contexts.ContextHook) error {
+	if c.Err != nil {
+		h.Logger.Log(8, log.ERROR, "[Error SQL Query] %s %v - %v", c.SQL, c.Args, c.Err)
+	}
+	return nil
+}
diff --git a/models/db/engine_test.go b/models/db/engine_test.go
index ba922821b0..e8f1c19b1c 100644
--- a/models/db/engine_test.go
+++ b/models/db/engine_test.go
@@ -123,3 +123,31 @@ func TestSlowQuery(t *testing.T) {
 	_, stopped = lc.Check(100 * time.Millisecond)
 	assert.True(t, stopped)
 }
+
+func TestErrorQuery(t *testing.T) {
+	lc, cleanup := test.NewLogChecker("error-query")
+	lc.StopMark("[Error SQL Query]")
+	defer cleanup()
+
+	e := db.GetEngine(db.DefaultContext)
+	engine, ok := e.(*xorm.Engine)
+	assert.True(t, ok)
+
+	// It's not possible to clean this up with XORM, but it's luckily not harmful
+	// to leave around.
+	engine.AddHook(&db.ErrorQueryHook{
+		Logger: log.GetLogger("error-query"),
+	})
+
+	// Valid query.
+	e.Exec("SELECT 1 WHERE false;")
+
+	_, stopped := lc.Check(100 * time.Millisecond)
+	assert.False(t, stopped)
+
+	// Table doesn't exist.
+	e.Exec("SELECT column FROM table;")
+
+	_, stopped = lc.Check(100 * time.Millisecond)
+	assert.True(t, stopped)
+}