diff --git a/logger/adapter.go b/logger/adapter.go index e060cdd6..6617fdea 100644 --- a/logger/adapter.go +++ b/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 { diff --git a/logger/adapter_test.go b/logger/adapter_test.go new file mode 100644 index 00000000..ae931e31 --- /dev/null +++ b/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)) + }) + } +} diff --git a/service/executor/service.go b/service/executor/service.go index de72f190..c52550a9 100644 --- a/service/executor/service.go +++ b/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 diff --git a/service/reader/service.go b/service/reader/service.go index 70e7fb95..28c49b3e 100644 --- a/service/reader/service.go +++ b/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) } diff --git a/view/sql.go b/view/sql.go index ad527682..b9d1de67 100644 --- a/view/sql.go +++ b/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()