Skip to content
This repository was archived by the owner on Nov 7, 2025. It is now read-only.

Commit 56a1047

Browse files
trzysiektrzysiek
authored
Better logging for schema transformation errors (#1376)
Also a bit better tooling experience for logging. I see in telemetry that e.g. `error` field is empty or almost always empty - that'll be a bit improved with this PR. For me at least now it'll be a bit easier to debug things that use `InfoFull`, `ErrorFull` etc.
1 parent 078b00b commit 56a1047

File tree

6 files changed

+124
-11
lines changed

6 files changed

+124
-11
lines changed

‎platform/frontend_connectors/schema_array_transformer.go‎

Lines changed: 10 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -84,9 +84,10 @@ func (v *arrayTypeResolver) dbColumnType(columName string) string {
8484
return field.InternalPropertyType
8585
}
8686

87-
func NewArrayTypeVisitor(resolver arrayTypeResolver) model.ExprVisitor {
87+
func NewArrayTypeVisitor(resolver arrayTypeResolver) (exprVisitor model.ExprVisitor, anyError bool) {
8888

8989
visitor := model.NewBaseVisitor()
90+
anyError = false
9091

9192
visitor.OverrideVisitInfix = func(b *model.BaseExprVisitor, e model.InfixExpr) interface{} {
9293

@@ -110,7 +111,10 @@ func NewArrayTypeVisitor(resolver arrayTypeResolver) model.ExprVisitor {
110111
return model.NewFunction("has", e.Left, e.Right.Accept(b).(model.Expr))
111112

112113
default:
113-
logger.Error().Msgf("Unhandled array infix operation '%s', column '%v' ('%v')", e.Op, column.ColumnName, dbType)
114+
anyError = true
115+
// add context to log line below (already introduced in unmerged Krzysiek's PR)
116+
logger.ErrorWithReason("unhandled array infix operation").
117+
Msgf("op: %s, column '%v' ('%v')", e.Op, column.ColumnName, dbType)
114118
}
115119
}
116120
}
@@ -160,12 +164,14 @@ func NewArrayTypeVisitor(resolver arrayTypeResolver) model.ExprVisitor {
160164
visitor.OverrideVisitColumnRef = func(b *model.BaseExprVisitor, e model.ColumnRef) interface{} {
161165
dbType := resolver.dbColumnType(e.ColumnName)
162166
if strings.HasPrefix(dbType, "Array") {
163-
logger.Error().Msgf("Unhandled array column ref %v (%v)", e.ColumnName, dbType)
167+
anyError = true
168+
// add context to log line below (already introduced in unmerged Krzysiek's PR)
169+
logger.ErrorWithReason("unhandled array column ref").Msgf("column '%v' ('%v')", e.ColumnName, dbType)
164170
}
165171
return e
166172
}
167173

168-
return visitor
174+
return visitor, anyError
169175
}
170176

171177
func checkIfGroupingByArrayColumn(selectCommand model.SelectCommand, resolver arrayTypeResolver) bool {

‎platform/frontend_connectors/schema_transformer.go‎

Lines changed: 9 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -316,18 +316,25 @@ func (s *SchemaCheckPass) applyArrayTransformations(indexSchema schema.Schema, q
316316
return query, nil
317317
}
318318

319-
var visitor model.ExprVisitor
319+
var (
320+
visitor model.ExprVisitor
321+
visitorHadError bool
322+
)
320323

321324
if checkIfGroupingByArrayColumn(query.SelectCommand, arrayTypeResolver) {
322325
visitor = NewArrayJoinVisitor(arrayTypeResolver)
323326
} else {
324-
visitor = NewArrayTypeVisitor(arrayTypeResolver)
327+
visitor, visitorHadError = NewArrayTypeVisitor(arrayTypeResolver)
325328
}
326329

327330
expr := query.SelectCommand.Accept(visitor)
328331
if _, ok := expr.(*model.SelectCommand); ok {
329332
query.SelectCommand = *expr.(*model.SelectCommand)
330333
}
334+
if visitorHadError {
335+
selectAsStr := model.AsString(query.SelectCommand)
336+
logger.ErrorWithReason("array transformation error").Msgf("Query: %s", selectAsStr)
337+
}
331338
return query, nil
332339
}
333340

‎platform/ingest/processor.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -883,7 +883,7 @@ func (ip *IngestProcessor) executeStatements(ctx context.Context, queries []stri
883883

884884
err := ip.execute(ctx, q)
885885
if err != nil {
886-
logger.ErrorWithCtx(ctx).Msgf("error executing statement: %v", err)
886+
logger.ErrorFull(ctx, "error executing ingest statement", err).Msgf("query: %s", q)
887887
return err
888888
}
889889
}

‎platform/logger/logger.go‎

Lines changed: 44 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@ import (
77
"fmt"
88
"github.com/QuesmaOrg/quesma/platform/stats/errorstats"
99
quesma_v2 "github.com/QuesmaOrg/quesma/platform/v2/core"
10+
"github.com/QuesmaOrg/quesma/platform/v2/core/tracing"
1011
"github.com/rs/zerolog"
1112
"io"
1213
"net/http"
@@ -219,6 +220,19 @@ func DebugWithCtx(ctx context.Context) *zerolog.Event {
219220
return logger.DebugWithCtx(ctx)
220221
}
221222

223+
func DebugWithReason(reason string) *zerolog.Event {
224+
return logger.DebugWithReason(reason)
225+
}
226+
227+
func DebugWithCtxAndReason(ctx context.Context, reason string) *zerolog.Event {
228+
return logger.DebugWithCtxAndReason(ctx, reason)
229+
}
230+
231+
func DebugFull(ctx context.Context, reason string, err error) *zerolog.Event {
232+
ctx = context.WithValue(ctx, tracing.ErrorCtxKey, err)
233+
return logger.DebugWithCtxAndReason(ctx, reason)
234+
}
235+
222236
func Info() *zerolog.Event {
223237
return logger.Info()
224238
}
@@ -227,6 +241,18 @@ func InfoWithCtx(ctx context.Context) *zerolog.Event {
227241
return logger.InfoWithCtx(ctx)
228242
}
229243

244+
func InfoWithReason(reason string) *zerolog.Event {
245+
return logger.InfoWithReason(reason)
246+
}
247+
248+
func InfoWithCtxAndReason(ctx context.Context, reason string) *zerolog.Event {
249+
return logger.InfoWithCtxAndReason(ctx, reason)
250+
}
251+
252+
func InfoFull(ctx context.Context, reason string, err error) *zerolog.Event {
253+
return logger.InfoFull(ctx, reason, err)
254+
}
255+
230256
// MarkTraceEndWithCtx marks the end of a trace with the given context.
231257
// Calling this functions at end of a trace is crucial from the transactional logging perspective.
232258
func MarkTraceEndWithCtx(ctx context.Context) *zerolog.Event {
@@ -241,10 +267,19 @@ func WarnWithCtx(ctx context.Context) *zerolog.Event {
241267
return logger.WarnWithCtx(ctx)
242268
}
243269

270+
func WarnWithReason(reason string) *zerolog.Event {
271+
return logger.WarnWithReason(reason)
272+
}
273+
244274
func WarnWithCtxAndReason(ctx context.Context, reason string) *zerolog.Event {
245275
return logger.WarnWithCtxAndReason(ctx, reason)
246276
}
247277

278+
func WarnFull(ctx context.Context, reason string, err error) *zerolog.Event {
279+
ctx = context.WithValue(ctx, tracing.ErrorCtxKey, err)
280+
return logger.WarnWithCtxAndReason(ctx, reason)
281+
}
282+
248283
func Error() *zerolog.Event {
249284
return logger.Error()
250285
}
@@ -253,10 +288,19 @@ func ErrorWithCtx(ctx context.Context) *zerolog.Event {
253288
return logger.ErrorWithCtx(ctx)
254289
}
255290

291+
func ErrorWithReason(reason string) *zerolog.Event {
292+
return logger.ErrorWithReason(reason)
293+
}
294+
256295
func ErrorWithCtxAndReason(ctx context.Context, reason string) *zerolog.Event {
257296
return logger.ErrorWithCtxAndReason(ctx, reason)
258297
}
259298

299+
func ErrorFull(ctx context.Context, reason string, err error) *zerolog.Event {
300+
ctx = context.WithValue(ctx, tracing.ErrorCtxKey, err)
301+
return logger.ErrorWithCtxAndReason(ctx, reason)
302+
}
303+
260304
func Fatal() *zerolog.Event {
261305
return logger.Fatal()
262306
}

‎platform/v2/core/quesma_logger.go‎

Lines changed: 56 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -45,9 +45,21 @@ type QuesmaLogger interface {
4545
WarnWithCtx(ctx context.Context) *zerolog.Event
4646
ErrorWithCtx(ctx context.Context) *zerolog.Event
4747

48+
DebugWithReason(reason string) *zerolog.Event
49+
InfoWithReason(reason string) *zerolog.Event
50+
WarnWithReason(reason string) *zerolog.Event
51+
ErrorWithReason(reason string) *zerolog.Event
52+
53+
DebugWithCtxAndReason(ctx context.Context, reason string) *zerolog.Event
54+
InfoWithCtxAndReason(ctx context.Context, reason string) *zerolog.Event
4855
WarnWithCtxAndReason(ctx context.Context, reason string) *zerolog.Event
4956
ErrorWithCtxAndReason(ctx context.Context, reason string) *zerolog.Event
5057

58+
DebugFull(ctx context.Context, reason string, err error) *zerolog.Event
59+
InfoFull(ctx context.Context, reason string, err error) *zerolog.Event
60+
WarnFull(ctx context.Context, reason string, err error) *zerolog.Event
61+
ErrorFull(ctx context.Context, reason string, err error) *zerolog.Event
62+
5163
MarkTraceEndWithCtx(ctx context.Context) *zerolog.Event
5264

5365
WithComponent(name string) QuesmaLogger
@@ -78,6 +90,30 @@ func (l *QuesmaLoggerImpl) MarkTraceEndWithCtx(ctx context.Context) *zerolog.Eve
7890
return event
7991
}
8092

93+
func (l *QuesmaLoggerImpl) DebugWithReason(reason string) *zerolog.Event {
94+
return l.DebugWithCtx(context.WithValue(context.Background(), tracing.ReasonCtxKey, reason))
95+
}
96+
97+
func (l *QuesmaLoggerImpl) InfoWithReason(reason string) *zerolog.Event {
98+
return l.InfoWithCtx(context.WithValue(context.Background(), tracing.ReasonCtxKey, reason))
99+
}
100+
101+
func (l *QuesmaLoggerImpl) WarnWithReason(reason string) *zerolog.Event {
102+
return l.InfoWithCtx(context.WithValue(context.Background(), tracing.ReasonCtxKey, reason))
103+
}
104+
105+
func (l *QuesmaLoggerImpl) ErrorWithReason(reason string) *zerolog.Event {
106+
return l.ErrorWithCtx(context.WithValue(context.Background(), tracing.ReasonCtxKey, reason))
107+
}
108+
109+
func (l *QuesmaLoggerImpl) DebugWithCtxAndReason(ctx context.Context, reason string) *zerolog.Event {
110+
return l.DebugWithCtx(context.WithValue(ctx, tracing.ReasonCtxKey, reason))
111+
}
112+
113+
func (l *QuesmaLoggerImpl) InfoWithCtxAndReason(ctx context.Context, reason string) *zerolog.Event {
114+
return l.InfoWithCtx(context.WithValue(ctx, tracing.ReasonCtxKey, reason))
115+
}
116+
81117
func (l *QuesmaLoggerImpl) WarnWithCtxAndReason(ctx context.Context, reason string) *zerolog.Event {
82118
return l.WarnWithCtx(context.WithValue(ctx, tracing.ReasonCtxKey, reason))
83119
}
@@ -86,6 +122,26 @@ func (l *QuesmaLoggerImpl) ErrorWithCtxAndReason(ctx context.Context, reason str
86122
return l.ErrorWithCtx(context.WithValue(ctx, tracing.ReasonCtxKey, reason))
87123
}
88124

125+
func (l *QuesmaLoggerImpl) DebugFull(ctx context.Context, reason string, err error) *zerolog.Event {
126+
ctx = context.WithValue(ctx, tracing.ErrorCtxKey, err)
127+
return l.DebugWithCtxAndReason(ctx, reason)
128+
}
129+
130+
func (l *QuesmaLoggerImpl) InfoFull(ctx context.Context, reason string, err error) *zerolog.Event {
131+
ctx = context.WithValue(ctx, tracing.ErrorCtxKey, err)
132+
return l.InfoWithCtxAndReason(ctx, reason)
133+
}
134+
135+
func (l *QuesmaLoggerImpl) WarnFull(ctx context.Context, reason string, err error) *zerolog.Event {
136+
ctx = context.WithValue(ctx, tracing.ErrorCtxKey, err)
137+
return l.WarnWithCtxAndReason(ctx, reason)
138+
}
139+
140+
func (l *QuesmaLoggerImpl) ErrorFull(ctx context.Context, reason string, err error) *zerolog.Event {
141+
ctx = context.WithValue(ctx, tracing.ErrorCtxKey, err)
142+
return l.ErrorWithCtxAndReason(ctx, reason)
143+
}
144+
89145
func (l *QuesmaLoggerImpl) addKnownContextValues(event *zerolog.Event, ctx context.Context) *zerolog.Event {
90146

91147
if requestId, ok := ctx.Value(tracing.RequestIdCtxKey).(string); ok {
@@ -126,7 +182,6 @@ func (l *QuesmaLoggerImpl) WarnWithCtx(ctx context.Context) *zerolog.Event {
126182
event := l.Warn().Ctx(ctx)
127183
event = l.addKnownContextValues(event, ctx)
128184
return event
129-
130185
}
131186

132187
func (l *QuesmaLoggerImpl) ErrorWithCtx(ctx context.Context) *zerolog.Event {

‎platform/v2/core/tracing/context.go‎

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -10,12 +10,13 @@ import (
1010
type ContextKey string
1111

1212
const (
13-
RequestIdCtxKey ContextKey = "RequestId"
13+
OpaqueIdCtxKey ContextKey = "OpaqueId"
14+
AsyncIdCtxKey ContextKey = "AsyncId"
15+
ErrorCtxKey ContextKey = "Error"
1416
ReasonCtxKey ContextKey = "Reason"
17+
RequestIdCtxKey ContextKey = "RequestId"
1518
RequestPath ContextKey = "RequestPath"
16-
AsyncIdCtxKey ContextKey = "AsyncId"
1719
TraceEndCtxKey ContextKey = "TraceEnd"
18-
OpaqueIdCtxKey ContextKey = "OpaqueId"
1920

2021
AsyncIdPrefix = "quesma_async_"
2122
)

0 commit comments

Comments
 (0)