Compare commits

...

5 Commits

Author SHA1 Message Date
Hein
9572bfc7b8 Fix qualified column reference (like APIL.rid_hub) in a preload: 2025-12-09 14:46:33 +02:00
Hein
f0962ea1ec Added EnableQueryDebug log 2025-12-09 14:37:09 +02:00
Hein
8fcb065b42 Better Query Debugging 2025-12-09 14:31:26 +02:00
Hein
dc3b621380 Fixed test for session id changes 2025-12-09 14:07:00 +02:00
Hein
a4dd2a7086 exposed types FromString 2025-12-09 14:03:55 +02:00
5 changed files with 313 additions and 22 deletions

View File

@@ -0,0 +1,67 @@
package database
import (
"testing"
)
func TestNormalizeTableAlias(t *testing.T) {
tests := []struct {
name string
query string
expectedAlias string
tableName string
want string
}{
{
name: "strips incorrect alias from simple condition",
query: "APIL.rid_hub = 2576",
expectedAlias: "apiproviderlink",
tableName: "apiproviderlink",
want: "rid_hub = 2576",
},
{
name: "keeps correct alias",
query: "apiproviderlink.rid_hub = 2576",
expectedAlias: "apiproviderlink",
tableName: "apiproviderlink",
want: "apiproviderlink.rid_hub = 2576",
},
{
name: "strips incorrect alias with multiple conditions",
query: "APIL.rid_hub = ? AND APIL.active = ?",
expectedAlias: "apiproviderlink",
tableName: "apiproviderlink",
want: "rid_hub = ? AND active = ?",
},
{
name: "handles mixed correct and incorrect aliases",
query: "APIL.rid_hub = ? AND apiproviderlink.active = ?",
expectedAlias: "apiproviderlink",
tableName: "apiproviderlink",
want: "rid_hub = ? AND apiproviderlink.active = ?",
},
{
name: "handles parentheses",
query: "(APIL.rid_hub = ?)",
expectedAlias: "apiproviderlink",
tableName: "apiproviderlink",
want: "(rid_hub = ?)",
},
{
name: "no alias in query",
query: "rid_hub = ?",
expectedAlias: "apiproviderlink",
tableName: "apiproviderlink",
want: "rid_hub = ?",
},
}
for _, tt := range tests {
t.Run(tt.name, func(t *testing.T) {
got := normalizeTableAlias(tt.query, tt.expectedAlias, tt.tableName)
if got != tt.want {
t.Errorf("normalizeTableAlias() = %q, want %q", got, tt.want)
}
})
}
}

View File

@@ -6,6 +6,7 @@ import (
"fmt" "fmt"
"reflect" "reflect"
"strings" "strings"
"time"
"github.com/uptrace/bun" "github.com/uptrace/bun"
@@ -15,6 +16,24 @@ import (
"github.com/bitechdev/ResolveSpec/pkg/reflection" "github.com/bitechdev/ResolveSpec/pkg/reflection"
) )
// QueryDebugHook is a Bun query hook that logs all SQL queries including preloads
type QueryDebugHook struct{}
func (h *QueryDebugHook) BeforeQuery(ctx context.Context, event *bun.QueryEvent) context.Context {
return ctx
}
func (h *QueryDebugHook) AfterQuery(ctx context.Context, event *bun.QueryEvent) {
query := event.Query
duration := time.Since(event.StartTime)
if event.Err != nil {
logger.Error("SQL Query Failed [%s]: %s. Error: %v", duration, query, event.Err)
} else {
logger.Debug("SQL Query Success [%s]: %s", duration, query)
}
}
// BunAdapter adapts Bun to work with our Database interface // BunAdapter adapts Bun to work with our Database interface
// This demonstrates how the abstraction works with different ORMs // This demonstrates how the abstraction works with different ORMs
type BunAdapter struct { type BunAdapter struct {
@@ -26,6 +45,20 @@ func NewBunAdapter(db *bun.DB) *BunAdapter {
return &BunAdapter{db: db} return &BunAdapter{db: db}
} }
// EnableQueryDebug enables query debugging which logs all SQL queries including preloads
// This is useful for debugging preload queries that may be failing
func (b *BunAdapter) EnableQueryDebug() {
b.db.AddQueryHook(&QueryDebugHook{})
logger.Info("Bun query debug mode enabled - all SQL queries will be logged")
}
// DisableQueryDebug removes all query hooks
func (b *BunAdapter) DisableQueryDebug() {
// Create a new DB without hooks
// Note: Bun doesn't have a RemoveQueryHook, so we'd need to track hooks manually
logger.Info("To disable query debug, recreate the BunAdapter without adding the hook")
}
func (b *BunAdapter) NewSelect() common.SelectQuery { func (b *BunAdapter) NewSelect() common.SelectQuery {
return &BunSelectQuery{ return &BunSelectQuery{
query: b.db.NewSelect(), query: b.db.NewSelect(),
@@ -156,10 +189,56 @@ func (b *BunSelectQuery) ColumnExpr(query string, args ...interface{}) common.Se
} }
func (b *BunSelectQuery) Where(query string, args ...interface{}) common.SelectQuery { func (b *BunSelectQuery) Where(query string, args ...interface{}) common.SelectQuery {
// If we have a table alias defined, check if the query references a different alias
// This can happen in preloads where the user expects a certain alias but Bun generates another
if b.tableAlias != "" && b.tableName != "" {
// Detect if query contains a qualified column reference (e.g., "APIL.column")
// and replace it with the unqualified version or the correct alias
query = normalizeTableAlias(query, b.tableAlias, b.tableName)
}
b.query = b.query.Where(query, args...) b.query = b.query.Where(query, args...)
return b return b
} }
// normalizeTableAlias replaces table alias prefixes in SQL conditions
// This handles cases where a user references a table alias that doesn't match
// what Bun generates (common in preload contexts)
func normalizeTableAlias(query, expectedAlias, tableName string) string {
// Pattern: <word>.<column> where <word> might be an incorrect alias
// We'll look for patterns like "APIL.column" and either:
// 1. Remove the alias prefix entirely (safest)
// 2. Replace with the expected alias
// For now, we'll use a simple approach: if the query contains a dot (qualified reference)
// and that prefix is not the expected alias or table name, strip it
// Split on spaces and parentheses to find qualified references
parts := strings.FieldsFunc(query, func(r rune) bool {
return r == ' ' || r == '(' || r == ')' || r == ','
})
modified := query
for _, part := range parts {
// Check if this looks like a qualified column reference
if dotIndex := strings.Index(part, "."); dotIndex > 0 {
prefix := part[:dotIndex]
column := part[dotIndex+1:]
// Check if the prefix matches our expected alias or table name (case-insensitive)
if !strings.EqualFold(prefix, expectedAlias) &&
!strings.EqualFold(prefix, tableName) &&
!strings.EqualFold(prefix, strings.ToLower(tableName)) {
// This is a different alias - remove the prefix
logger.Debug("Stripping incorrect alias '%s' from WHERE condition, keeping just '%s'", prefix, column)
// Replace the qualified reference with just the column name
modified = strings.ReplaceAll(modified, part, column)
}
}
}
return modified
}
func (b *BunSelectQuery) WhereOr(query string, args ...interface{}) common.SelectQuery { func (b *BunSelectQuery) WhereOr(query string, args ...interface{}) common.SelectQuery {
b.query = b.query.WhereOr(query, args...) b.query = b.query.WhereOr(query, args...)
return b return b
@@ -350,6 +429,28 @@ func (b *BunSelectQuery) PreloadRelation(relation string, apply ...func(common.S
db: b.db, db: b.db,
} }
// Try to extract table name and alias from the preload model
if model := sq.GetModel(); model != nil && model.Value() != nil {
modelValue := model.Value()
// Extract table name if model implements TableNameProvider
if provider, ok := modelValue.(common.TableNameProvider); ok {
fullTableName := provider.TableName()
wrapper.schema, wrapper.tableName = parseTableName(fullTableName)
}
// Extract table alias if model implements TableAliasProvider
if provider, ok := modelValue.(common.TableAliasProvider); ok {
wrapper.tableAlias = provider.TableAlias()
// Apply the alias to the Bun query so conditions can reference it
if wrapper.tableAlias != "" {
// Note: Bun's Relation() already sets up the table, but we can add
// the alias explicitly if needed
logger.Debug("Preload relation '%s' using table alias: %s", relation, wrapper.tableAlias)
}
}
}
// Start with the interface value (not pointer) // Start with the interface value (not pointer)
current := common.SelectQuery(wrapper) current := common.SelectQuery(wrapper)
@@ -410,6 +511,9 @@ func (b *BunSelectQuery) Scan(ctx context.Context, dest interface{}) (err error)
// Execute the main query first // Execute the main query first
err = b.query.Scan(ctx, dest) err = b.query.Scan(ctx, dest)
if err != nil { if err != nil {
// Log SQL string for debugging
sqlStr := b.query.String()
logger.Error("BunSelectQuery.Scan failed. SQL: %s. Error: %v", sqlStr, err)
return err return err
} }
@@ -438,6 +542,9 @@ func (b *BunSelectQuery) ScanModel(ctx context.Context) (err error) {
// Execute the main query first // Execute the main query first
err = b.query.Scan(ctx) err = b.query.Scan(ctx)
if err != nil { if err != nil {
// Log SQL string for debugging
sqlStr := b.query.String()
logger.Error("BunSelectQuery.ScanModel failed. SQL: %s. Error: %v", sqlStr, err)
return err return err
} }
@@ -573,15 +680,25 @@ func (b *BunSelectQuery) Count(ctx context.Context) (count int, err error) {
// If Model() was set, use bun's native Count() which works properly // If Model() was set, use bun's native Count() which works properly
if b.hasModel { if b.hasModel {
count, err := b.query.Count(ctx) count, err := b.query.Count(ctx)
if err != nil {
// Log SQL string for debugging
sqlStr := b.query.String()
logger.Error("BunSelectQuery.Count failed. SQL: %s. Error: %v", sqlStr, err)
}
return count, err return count, err
} }
// Otherwise, wrap as subquery to avoid "Model(nil)" error // Otherwise, wrap as subquery to avoid "Model(nil)" error
// This is needed when only Table() is set without a model // This is needed when only Table() is set without a model
err = b.db.NewSelect(). countQuery := b.db.NewSelect().
TableExpr("(?) AS subquery", b.query). TableExpr("(?) AS subquery", b.query).
ColumnExpr("COUNT(*)"). ColumnExpr("COUNT(*)")
Scan(ctx, &count) err = countQuery.Scan(ctx, &count)
if err != nil {
// Log SQL string for debugging
sqlStr := countQuery.String()
logger.Error("BunSelectQuery.Count (subquery) failed. SQL: %s. Error: %v", sqlStr, err)
}
return count, err return count, err
} }
@@ -592,7 +709,13 @@ func (b *BunSelectQuery) Exists(ctx context.Context) (exists bool, err error) {
exists = false exists = false
} }
}() }()
return b.query.Exists(ctx) exists, err = b.query.Exists(ctx)
if err != nil {
// Log SQL string for debugging
sqlStr := b.query.String()
logger.Error("BunSelectQuery.Exists failed. SQL: %s. Error: %v", sqlStr, err)
}
return exists, err
} }
// BunInsertQuery implements InsertQuery for Bun // BunInsertQuery implements InsertQuery for Bun
@@ -729,6 +852,11 @@ func (b *BunUpdateQuery) Exec(ctx context.Context) (res common.Result, err error
} }
}() }()
result, err := b.query.Exec(ctx) result, err := b.query.Exec(ctx)
if err != nil {
// Log SQL string for debugging
sqlStr := b.query.String()
logger.Error("BunUpdateQuery.Exec failed. SQL: %s. Error: %v", sqlStr, err)
}
return &BunResult{result: result}, err return &BunResult{result: result}, err
} }
@@ -759,6 +887,11 @@ func (b *BunDeleteQuery) Exec(ctx context.Context) (res common.Result, err error
} }
}() }()
result, err := b.query.Exec(ctx) result, err := b.query.Exec(ctx)
if err != nil {
// Log SQL string for debugging
sqlStr := b.query.String()
logger.Error("BunDeleteQuery.Exec failed. SQL: %s. Error: %v", sqlStr, err)
}
return &BunResult{result: result}, err return &BunResult{result: result}, err
} }

View File

@@ -23,6 +23,22 @@ func NewGormAdapter(db *gorm.DB) *GormAdapter {
return &GormAdapter{db: db} return &GormAdapter{db: db}
} }
// EnableQueryDebug enables query debugging which logs all SQL queries including preloads
// This is useful for debugging preload queries that may be failing
func (g *GormAdapter) EnableQueryDebug() *GormAdapter {
g.db = g.db.Debug()
logger.Info("GORM query debug mode enabled - all SQL queries will be logged")
return g
}
// DisableQueryDebug disables query debugging
func (g *GormAdapter) DisableQueryDebug() *GormAdapter {
// GORM's Debug() creates a new session, so we need to get the base DB
// This is a simplified implementation
logger.Info("GORM debug mode - create a new adapter without Debug() to disable")
return g
}
func (g *GormAdapter) NewSelect() common.SelectQuery { func (g *GormAdapter) NewSelect() common.SelectQuery {
return &GormSelectQuery{db: g.db} return &GormSelectQuery{db: g.db}
} }
@@ -282,7 +298,15 @@ func (g *GormSelectQuery) Scan(ctx context.Context, dest interface{}) (err error
err = logger.HandlePanic("GormSelectQuery.Scan", r) err = logger.HandlePanic("GormSelectQuery.Scan", r)
} }
}() }()
return g.db.WithContext(ctx).Find(dest).Error err = g.db.WithContext(ctx).Find(dest).Error
if err != nil {
// Log SQL string for debugging
sqlStr := g.db.ToSQL(func(tx *gorm.DB) *gorm.DB {
return tx.Find(dest)
})
logger.Error("GormSelectQuery.Scan failed. SQL: %s. Error: %v", sqlStr, err)
}
return err
} }
func (g *GormSelectQuery) ScanModel(ctx context.Context) (err error) { func (g *GormSelectQuery) ScanModel(ctx context.Context) (err error) {
@@ -294,7 +318,15 @@ func (g *GormSelectQuery) ScanModel(ctx context.Context) (err error) {
if g.db.Statement.Model == nil { if g.db.Statement.Model == nil {
return fmt.Errorf("ScanModel requires Model() to be set before scanning") return fmt.Errorf("ScanModel requires Model() to be set before scanning")
} }
return g.db.WithContext(ctx).Find(g.db.Statement.Model).Error err = g.db.WithContext(ctx).Find(g.db.Statement.Model).Error
if err != nil {
// Log SQL string for debugging
sqlStr := g.db.ToSQL(func(tx *gorm.DB) *gorm.DB {
return tx.Find(g.db.Statement.Model)
})
logger.Error("GormSelectQuery.ScanModel failed. SQL: %s. Error: %v", sqlStr, err)
}
return err
} }
func (g *GormSelectQuery) Count(ctx context.Context) (count int, err error) { func (g *GormSelectQuery) Count(ctx context.Context) (count int, err error) {
@@ -306,6 +338,13 @@ func (g *GormSelectQuery) Count(ctx context.Context) (count int, err error) {
}() }()
var count64 int64 var count64 int64
err = g.db.WithContext(ctx).Count(&count64).Error err = g.db.WithContext(ctx).Count(&count64).Error
if err != nil {
// Log SQL string for debugging
sqlStr := g.db.ToSQL(func(tx *gorm.DB) *gorm.DB {
return tx.Count(&count64)
})
logger.Error("GormSelectQuery.Count failed. SQL: %s. Error: %v", sqlStr, err)
}
return int(count64), err return int(count64), err
} }
@@ -318,6 +357,13 @@ func (g *GormSelectQuery) Exists(ctx context.Context) (exists bool, err error) {
}() }()
var count int64 var count int64
err = g.db.WithContext(ctx).Limit(1).Count(&count).Error err = g.db.WithContext(ctx).Limit(1).Count(&count).Error
if err != nil {
// Log SQL string for debugging
sqlStr := g.db.ToSQL(func(tx *gorm.DB) *gorm.DB {
return tx.Limit(1).Count(&count)
})
logger.Error("GormSelectQuery.Exists failed. SQL: %s. Error: %v", sqlStr, err)
}
return count > 0, err return count > 0, err
} }
@@ -456,6 +502,13 @@ func (g *GormUpdateQuery) Exec(ctx context.Context) (res common.Result, err erro
} }
}() }()
result := g.db.WithContext(ctx).Updates(g.updates) result := g.db.WithContext(ctx).Updates(g.updates)
if result.Error != nil {
// Log SQL string for debugging
sqlStr := g.db.ToSQL(func(tx *gorm.DB) *gorm.DB {
return tx.Updates(g.updates)
})
logger.Error("GormUpdateQuery.Exec failed. SQL: %s. Error: %v", sqlStr, result.Error)
}
return &GormResult{result: result}, result.Error return &GormResult{result: result}, result.Error
} }
@@ -488,6 +541,13 @@ func (g *GormDeleteQuery) Exec(ctx context.Context) (res common.Result, err erro
} }
}() }()
result := g.db.WithContext(ctx).Delete(g.model) result := g.db.WithContext(ctx).Delete(g.model)
if result.Error != nil {
// Log SQL string for debugging
sqlStr := g.db.ToSQL(func(tx *gorm.DB) *gorm.DB {
return tx.Delete(g.model)
})
logger.Error("GormDeleteQuery.Exec failed. SQL: %s. Error: %v", sqlStr, result.Error)
}
return &GormResult{result: result}, result.Error return &GormResult{result: result}, result.Error
} }

View File

@@ -71,14 +71,14 @@ func (n *SqlNull[T]) Scan(value any) error {
// Fallback: parse from string/bytes. // Fallback: parse from string/bytes.
switch v := value.(type) { switch v := value.(type) {
case string: case string:
return n.fromString(v) return n.FromString(v)
case []byte: case []byte:
return n.fromString(string(v)) return n.FromString(string(v))
default: default:
return n.fromString(fmt.Sprintf("%v", value)) return n.FromString(fmt.Sprintf("%v", value))
} }
} }
func (n *SqlNull[T]) fromString(s string) error { func (n *SqlNull[T]) FromString(s string) error {
s = strings.TrimSpace(s) s = strings.TrimSpace(s)
n.Valid = false n.Valid = false
n.Val = *new(T) n.Val = *new(T)
@@ -156,7 +156,7 @@ func (n *SqlNull[T]) UnmarshalJSON(b []byte) error {
// Fallback: unmarshal as string and parse. // Fallback: unmarshal as string and parse.
var s string var s string
if err := json.Unmarshal(b, &s); err == nil { if err := json.Unmarshal(b, &s); err == nil {
return n.fromString(s) return n.FromString(s)
} }
return fmt.Errorf("cannot unmarshal %s into SqlNull[%T]", b, n.Val) return fmt.Errorf("cannot unmarshal %s into SqlNull[%T]", b, n.Val)
@@ -514,6 +514,30 @@ func Null[T any](v T, valid bool) SqlNull[T] {
return SqlNull[T]{Val: v, Valid: valid} return SqlNull[T]{Val: v, Valid: valid}
} }
func NewSql[T any](value any) SqlNull[T] {
n := SqlNull[T]{}
if value == nil {
return n
}
// Fast path: exact match
if v, ok := value.(T); ok {
n.Val = v
n.Valid = true
return n
}
// Try from another SqlNull
if sn, ok := value.(SqlNull[T]); ok {
return sn
}
// Convert via string
_ = n.FromString(fmt.Sprintf("%v", value))
return n
}
func NewSqlInt16(v int16) SqlInt16 { func NewSqlInt16(v int16) SqlInt16 {
return SqlInt16{Val: v, Valid: true} return SqlInt16{Val: v, Valid: true}
} }

View File

@@ -16,8 +16,8 @@ import (
// MockDatabase implements common.Database interface for testing // MockDatabase implements common.Database interface for testing
type MockDatabase struct { type MockDatabase struct {
QueryFunc func(ctx context.Context, dest interface{}, query string, args ...interface{}) error QueryFunc func(ctx context.Context, dest interface{}, query string, args ...interface{}) error
ExecFunc func(ctx context.Context, query string, args ...interface{}) (common.Result, error) ExecFunc func(ctx context.Context, query string, args ...interface{}) (common.Result, error)
RunInTransactionFunc func(ctx context.Context, fn func(common.Database) error) error RunInTransactionFunc func(ctx context.Context, fn func(common.Database) error) error
} }
@@ -161,9 +161,9 @@ func TestExtractInputVariables(t *testing.T) {
handler := NewHandler(&MockDatabase{}) handler := NewHandler(&MockDatabase{})
tests := []struct { tests := []struct {
name string name string
sqlQuery string sqlQuery string
expectedVars []string expectedVars []string
}{ }{
{ {
name: "No variables", name: "No variables",
@@ -340,9 +340,9 @@ func TestSqlQryWhere(t *testing.T) {
// TestGetIPAddress tests IP address extraction // TestGetIPAddress tests IP address extraction
func TestGetIPAddress(t *testing.T) { func TestGetIPAddress(t *testing.T) {
tests := []struct { tests := []struct {
name string name string
setupReq func() *http.Request setupReq func() *http.Request
expected string expected string
}{ }{
{ {
name: "X-Forwarded-For header", name: "X-Forwarded-For header",
@@ -782,9 +782,10 @@ func TestReplaceMetaVariables(t *testing.T) {
handler := NewHandler(&MockDatabase{}) handler := NewHandler(&MockDatabase{})
userCtx := &security.UserContext{ userCtx := &security.UserContext{
UserID: 123, UserID: 123,
UserName: "testuser", UserName: "testuser",
SessionID: "456", SessionID: "ABC456",
SessionRID: 456,
} }
metainfo := map[string]interface{}{ metainfo := map[string]interface{}{
@@ -821,6 +822,12 @@ func TestReplaceMetaVariables(t *testing.T) {
expectedCheck: func(result string) bool { expectedCheck: func(result string) bool {
return strings.Contains(result, "456") return strings.Contains(result, "456")
}, },
}, {
name: "Replace [id_session]",
sqlQuery: "SELECT * FROM sessions WHERE session_id = [id_session]",
expectedCheck: func(result string) bool {
return strings.Contains(result, "ABC456")
},
}, },
} }