Improve SQL error logging context

logger/adapter.go

@@ -1,7 +1,9 @@
 package logger
 
 import (
+	"context"
 	"fmt"
+	"github.com/viant/datly/internal/requesttrace"
 	"github.com/viant/datly/shared"
 	"github.com/viant/datly/utils/debug"
 	"strings"
@@ -86,9 +88,41 @@ func (l *Adapter) Inherit(adapter *Adapter) {
 	l.log = adapter.log
 }
 
-func (l *Adapter) LogDatabaseErr(SQL string, err error, args ...interface{}) {
+func (l *Adapter) LogDatabaseErr(ctx context.Context, view string, SQL string, err error, args ...interface{}) {
 	SQL = shared.ExpandSQL(SQL, args)
-	fmt.Printf("error occured while executing SQL: %v, SQL: %v, params: %v\n", err, strings.ReplaceAll(SQL, "\n", "\\n"), args)
+	fmt.Printf("[ERROR] datly sql reqTraceId=%s view=%s error=%q sql=%q params=%v\n",
+		reqTraceID(ctx),
+		view,
+		normalizeDatabaseError(err),
+		strings.ReplaceAll(SQL, "\n", "\\n"),
+		args)
+}
+
+func reqTraceID(ctx context.Context) string {
+	if traceID := requesttrace.Current(ctx); traceID != "" {
+		return traceID
+	}
+	return "unknown"
+}
+
+func normalizeDatabaseError(err error) string {
+	if err == nil {
+		return ""
+	}
+	message := err.Error()
+	if idx := strings.LastIndex(message, ", due to "); idx >= 0 {
+		return strings.TrimSpace(message[idx+len(", due to "):])
+	}
+	if idx := strings.LastIndex(message, " due to "); idx >= 0 {
+		return strings.TrimSpace(message[idx+len(" due to "):])
+	}
+	if idx := strings.LastIndex(message, " failed to run query: "); idx >= 0 {
+		return strings.TrimSpace(message[:idx])
+	}
+	if strings.HasPrefix(message, "failed to run query: ") {
+		return "failed to run query"
+	}
+	return message
 }
 
 func NewLogger(name string, logger Logger) *Adapter {

logger/adapter_test.go

@@ -0,0 +1,58 @@
+package logger
+
+import (
+	"context"
+	"errors"
+	"testing"
+
+	"github.com/stretchr/testify/require"
+	"github.com/viant/datly/internal/requesttrace"
+)
+
+func TestReqTraceID(t *testing.T) {
+	require.Equal(t, "unknown", reqTraceID(nil))
+	require.Equal(t, "unknown", reqTraceID(context.Background()))
+
+	ctx := requesttrace.Ensure(context.Background(), "trace-123")
+	require.Equal(t, "trace-123", reqTraceID(ctx))
+}
+
+func TestNormalizeDatabaseError(t *testing.T) {
+	testCases := []struct {
+		name     string
+		err      error
+		expected string
+	}{
+		{
+			name:     "nil",
+			err:      nil,
+			expected: "",
+		},
+		{
+			name:     "bigquery due to",
+			err:      errors.New("failed to run query: SELECT * FROM table, due to googleapi: Error 400: invalidQuery"),
+			expected: "googleapi: Error 400: invalidQuery",
+		},
+		{
+			name:     "sqlx wrapped query",
+			err:      errors.New("database error occured while fetching Data for view v failed to run query: SELECT * FROM table WHERE id = ?"),
+			expected: "database error occured while fetching Data for view v",
+		},
+		{
+			name:     "raw failed query",
+			err:      errors.New("failed to run query: SELECT * FROM table WHERE id = ?"),
+			expected: "failed to run query",
+		},
+		{
+			name:     "plain error",
+			err:      errors.New("connection refused"),
+			expected: "connection refused",
+		},
+	}
+
+	for _, testCase := range testCases {
+		t.Run(testCase.name, func(t *testing.T) {
+			require.Equal(t, testCase.expected, normalizeDatabaseError(testCase.err))
+		})
+	}
+}

service/executor/service.go

@@ -333,7 +333,7 @@ func (e *Executor) executeStatement(ctx context.Context, tx *sql.Tx, stmt *expan
 	_, err := tx.ExecContext(ctx, stmt.SQL, stmt.Args...)
 	if err != nil {
 		if sess.logger != nil {
-			sess.logger.LogDatabaseErr(stmt.SQL, err, stmt.Args...)
+			sess.logger.LogDatabaseErr(ctx, databaseLogView(ctx), stmt.SQL, err, stmt.Args...)
 		}
 
 		err = fmt.Errorf("error occured while connecting to database")
@@ -342,6 +342,14 @@ func (e *Executor) executeStatement(ctx context.Context, tx *sql.Tx, stmt *expan
 	return err
 }
 
+func databaseLogView(ctx context.Context) string {
+	aView := view.Context(ctx)
+	if aView == nil {
+		return ""
+	}
+	return aView.Name
+}
+
 func (s *dbSession) collection(executable *expand2.Executable) *batcher.Collection {
 	if collection, ok := s.collections[executable.Table]; ok {
 		return collection

service/reader/service.go

@@ -911,7 +911,7 @@ BEGIN:
 	}
 	if err != nil {
 		stats.SetError(err)
-		anExec, err := s.HandleSQLError(err, session, aView, parametrizedSQL, stats)
+		anExec, err := s.HandleSQLError(ctx, err, aView, parametrizedSQL, stats)
 		return []*response.SQLExecution{anExec}, err
 	}
 
@@ -938,7 +938,7 @@ BEGIN:
 	logCacheRead(ctx, aView, cacheStats, end.Sub(begin), *readData, parametrizedSQL.Args)
 	if err != nil {
 		stats.SetError(err)
-		anExec, err := s.HandleSQLError(err, session, aView, parametrizedSQL, stats)
+		anExec, err := s.HandleSQLError(ctx, err, aView, parametrizedSQL, stats)
 		return []*response.SQLExecution{anExec}, err
 	}
 	return []*response.SQLExecution{stats}, nil
@@ -1043,8 +1043,8 @@ func (s *Service) queryWithPartitions(ctx context.Context, session *Session, aVi
 	return executions, err
 }
 
-func (s *Service) HandleSQLError(err error, session *Session, aView *view.View, matcher *cache.ParmetrizedQuery, stats *response.SQLExecution) (*response.SQLExecution, error) {
-	aView.Logger.LogDatabaseErr(matcher.SQL, err, matcher.Args...)
+func (s *Service) HandleSQLError(ctx context.Context, err error, aView *view.View, matcher *cache.ParmetrizedQuery, stats *response.SQLExecution) (*response.SQLExecution, error) {
+	aView.Logger.LogDatabaseErr(ctx, aView.Name, matcher.SQL, err, matcher.Args...)
 	stats.Error = err.Error()
 	return stats, fmt.Errorf("database error occured while fetching Data for view %v %w", aView.Name, err)
 }

view/sql.go

@@ -53,7 +53,7 @@ func detectColumns(ctx context.Context, evaluation *TemplateEvaluation, v *View)
 	}
 	query, err := aDb.QueryContext(ctx, SQL, args...)
 	if err != nil {
-		v.Logger.LogDatabaseErr(SQL, err, args...)
+		v.Logger.LogDatabaseErr(ctx, v.Name, SQL, err, args...)
 		return nil, SQL, err
 	}
 	defer query.Close()