Skip to content

Commit eb095e7

Browse files
bolekkbolekk
committed
Improve Beholder Logger
1. Don't drop errors 2. Protect against blocking calls
1 parent a209f30 commit eb095e7

File tree

2 files changed

+158
-31
lines changed

2 files changed

+158
-31
lines changed

‎pkg/custmsg/logger.go

Lines changed: 140 additions & 28 deletions
Original file line numberDiff line numberDiff line change
@@ -3,125 +3,232 @@ package custmsg
33
import (
44
"context"
55
"fmt"
6+
"time"
67

78
"github.com/smartcontractkit/chainlink-common/pkg/logger"
89
)
910

10-
const LogLevelKey = "log_level"
11+
const (
12+
LogLevelKey = "log_level"
13+
defaultBeholderEmitTimeoutMs = 100
14+
)
1115

1216
type beholderLogger struct {
13-
underlying logger.Logger
14-
emitter MessageEmitter
17+
underlying logger.Logger
18+
emitter MessageEmitter
19+
emitTimeout time.Duration
1520
}
1621

1722
func NewBeholderLogger(underlying logger.Logger, emitter MessageEmitter) *beholderLogger {
1823
return &beholderLogger{
19-
underlying: logger.Helper(underlying, 1),
20-
emitter: emitter,
24+
underlying: logger.Helper(underlying, 1),
25+
emitter: emitter,
26+
emitTimeout: defaultBeholderEmitTimeoutMs * time.Millisecond,
2127
}
2228
}
2329

2430
func (b *beholderLogger) With(args ...any) *beholderLogger {
25-
emitterWithLabels := b.emitter.WithMapLabels(getLabelMap(args...))
26-
underlyingWith := logger.With(b.underlying, args...)
27-
return NewBeholderLogger(underlyingWith, emitterWithLabels)
31+
return &beholderLogger{
32+
underlying: logger.With(b.underlying, args...),
33+
emitter: b.emitter.WithMapLabels(getLabelMap(args...)),
34+
emitTimeout: b.emitTimeout,
35+
}
36+
}
37+
38+
func (b *beholderLogger) WithEmitTimeout(name string, emitTimeout time.Duration) *beholderLogger {
39+
return &beholderLogger{
40+
underlying: b.underlying,
41+
emitter: b.emitter,
42+
emitTimeout: emitTimeout,
43+
}
2844
}
2945

3046
func (b *beholderLogger) Named(name string) *beholderLogger {
3147
return &beholderLogger{
32-
underlying: logger.Named(b.underlying, name),
33-
emitter: b.emitter,
48+
underlying: logger.Named(b.underlying, name),
49+
emitter: b.emitter,
50+
emitTimeout: b.emitTimeout,
3451
}
3552
}
3653

3754
func (b *beholderLogger) Debug(args ...any) {
38-
_ = b.emitter.With(LogLevelKey, "debug").Emit(context.Background(), fmt.Sprint(args...))
3955
b.underlying.Debug(args...)
56+
ctx, cancel := getBeholderCallContext()
57+
defer cancel()
58+
err := b.emitter.With(LogLevelKey, "debug").Emit(ctx, fmt.Sprint(args...))
59+
if err != nil {
60+
b.underlying.Errorw("error emitting log to Beholder", "error", err)
61+
}
4062
}
4163

4264
func (b *beholderLogger) Info(args ...any) {
43-
_ = b.emitter.With(LogLevelKey, "info").Emit(context.Background(), fmt.Sprint(args...))
4465
b.underlying.Info(args...)
66+
ctx, cancel := getBeholderCallContext()
67+
defer cancel()
68+
err := b.emitter.With(LogLevelKey, "info").Emit(ctx, fmt.Sprint(args...))
69+
if err != nil {
70+
b.underlying.Errorw("error emitting log to Beholder", "error", err)
71+
}
4572
}
4673

4774
func (b *beholderLogger) Warn(args ...any) {
48-
_ = b.emitter.With(LogLevelKey, "warn").Emit(context.Background(), fmt.Sprint(args...))
4975
b.underlying.Warn(args...)
76+
ctx, cancel := getBeholderCallContext()
77+
defer cancel()
78+
err := b.emitter.With(LogLevelKey, "warn").Emit(ctx, fmt.Sprint(args...))
79+
if err != nil {
80+
b.underlying.Errorw("error emitting log to Beholder", "error", err)
81+
}
5082
}
5183

5284
func (b *beholderLogger) Error(args ...any) {
53-
_ = b.emitter.With(LogLevelKey, "error").Emit(context.Background(), fmt.Sprint(args...))
5485
b.underlying.Error(args...)
86+
ctx, cancel := getBeholderCallContext()
87+
defer cancel()
88+
err := b.emitter.With(LogLevelKey, "error").Emit(ctx, fmt.Sprint(args...))
89+
if err != nil {
90+
b.underlying.Errorw("error emitting log to Beholder", "error", err)
91+
}
5592
}
5693

5794
func (b *beholderLogger) Panic(args ...any) {
58-
_ = b.emitter.With(LogLevelKey, "panic").Emit(context.Background(), fmt.Sprint(args...))
5995
b.underlying.Panic(args...)
96+
ctx, cancel := getBeholderCallContext()
97+
defer cancel()
98+
err := b.emitter.With(LogLevelKey, "panic").Emit(ctx, fmt.Sprint(args...))
99+
if err != nil {
100+
b.underlying.Errorw("error emitting log to Beholder", "error", err)
101+
}
60102
}
61103

62104
func (b *beholderLogger) Fatal(args ...any) {
63-
_ = b.emitter.With(LogLevelKey, "fatal").Emit(context.Background(), fmt.Sprint(args...))
64105
b.underlying.Fatal(args...)
106+
ctx, cancel := getBeholderCallContext()
107+
defer cancel()
108+
err := b.emitter.With(LogLevelKey, "fatal").Emit(ctx, fmt.Sprint(args...))
109+
if err != nil {
110+
b.underlying.Errorw("error emitting log to Beholder", "error", err)
111+
}
65112
}
66113

67114
func (b *beholderLogger) Debugf(format string, values ...any) {
68-
_ = b.emitter.With(LogLevelKey, "debug").Emit(context.Background(), fmt.Sprintf(format, values...))
69115
b.underlying.Debugf(format, values...)
116+
ctx, cancel := getBeholderCallContext()
117+
defer cancel()
118+
err := b.emitter.With(LogLevelKey, "debug").Emit(ctx, fmt.Sprintf(format, values...))
119+
if err != nil {
120+
b.underlying.Errorw("error emitting log to Beholder", "error", err)
121+
}
70122
}
71123

72124
func (b *beholderLogger) Infof(format string, values ...any) {
73-
_ = b.emitter.With(LogLevelKey, "info").Emit(context.Background(), fmt.Sprintf(format, values...))
74125
b.underlying.Infof(format, values...)
126+
ctx, cancel := getBeholderCallContext()
127+
defer cancel()
128+
err := b.emitter.With(LogLevelKey, "info").Emit(ctx, fmt.Sprintf(format, values...))
129+
if err != nil {
130+
b.underlying.Errorw("error emitting log to Beholder", "error", err)
131+
}
75132
}
76133

77134
func (b *beholderLogger) Warnf(format string, values ...any) {
78-
_ = b.emitter.With(LogLevelKey, "warn").Emit(context.Background(), fmt.Sprintf(format, values...))
79135
b.underlying.Warnf(format, values...)
136+
ctx, cancel := getBeholderCallContext()
137+
defer cancel()
138+
err := b.emitter.With(LogLevelKey, "warn").Emit(ctx, fmt.Sprintf(format, values...))
139+
if err != nil {
140+
b.underlying.Errorw("error emitting log to Beholder", "error", err)
141+
}
80142
}
81143

82144
func (b *beholderLogger) Errorf(format string, values ...any) {
83-
_ = b.emitter.With(LogLevelKey, "error").Emit(context.Background(), fmt.Sprintf(format, values...))
84145
b.underlying.Errorf(format, values...)
146+
ctx, cancel := getBeholderCallContext()
147+
defer cancel()
148+
err := b.emitter.With(LogLevelKey, "error").Emit(ctx, fmt.Sprintf(format, values...))
149+
if err != nil {
150+
b.underlying.Errorw("error emitting log to Beholder", "error", err)
151+
}
85152
}
86153

87154
func (b *beholderLogger) Panicf(format string, values ...any) {
88-
_ = b.emitter.With(LogLevelKey, "panic").Emit(context.Background(), fmt.Sprintf(format, values...))
89155
b.underlying.Panicf(format, values...)
156+
ctx, cancel := getBeholderCallContext()
157+
defer cancel()
158+
err := b.emitter.With(LogLevelKey, "panic").Emit(ctx, fmt.Sprintf(format, values...))
159+
if err != nil {
160+
b.underlying.Errorw("error emitting log to Beholder", "error", err)
161+
}
90162
}
91163

92164
func (b *beholderLogger) Fatalf(format string, values ...any) {
93-
_ = b.emitter.With(LogLevelKey, "fatal").Emit(context.Background(), fmt.Sprintf(format, values...))
94165
b.underlying.Fatalf(format, values...)
166+
ctx, cancel := getBeholderCallContext()
167+
defer cancel()
168+
err := b.emitter.With(LogLevelKey, "fatal").Emit(ctx, fmt.Sprintf(format, values...))
169+
if err != nil {
170+
b.underlying.Errorw("error emitting log to Beholder", "error", err)
171+
}
95172
}
96173

97174
func (b *beholderLogger) Debugw(msg string, keysAndValues ...any) {
98-
_ = b.emitter.With(LogLevelKey, "debug").WithMapLabels(getLabelMap(keysAndValues...)).Emit(context.Background(), msg)
99175
b.underlying.Debugw(msg, keysAndValues...)
176+
ctx, cancel := getBeholderCallContext()
177+
defer cancel()
178+
err := b.emitter.With(LogLevelKey, "debug").WithMapLabels(getLabelMap(keysAndValues...)).Emit(ctx, msg)
179+
if err != nil {
180+
b.underlying.Errorw("error emitting log to Beholder", "error", err)
181+
}
100182
}
101183

102184
func (b *beholderLogger) Infow(msg string, keysAndValues ...any) {
103-
_ = b.emitter.With(LogLevelKey, "info").WithMapLabels(getLabelMap(keysAndValues...)).Emit(context.Background(), msg)
104185
b.underlying.Infow(msg, keysAndValues...)
186+
ctx, cancel := getBeholderCallContext()
187+
defer cancel()
188+
err := b.emitter.With(LogLevelKey, "info").WithMapLabels(getLabelMap(keysAndValues...)).Emit(ctx, msg)
189+
if err != nil {
190+
b.underlying.Errorw("error emitting log to Beholder", "error", err)
191+
}
105192
}
106193

107194
func (b *beholderLogger) Warnw(msg string, keysAndValues ...any) {
108-
_ = b.emitter.With(LogLevelKey, "warn").WithMapLabels(getLabelMap(keysAndValues...)).Emit(context.Background(), msg)
109195
b.underlying.Warnw(msg, keysAndValues...)
196+
ctx, cancel := getBeholderCallContext()
197+
defer cancel()
198+
err := b.emitter.With(LogLevelKey, "warn").WithMapLabels(getLabelMap(keysAndValues...)).Emit(ctx, msg)
199+
if err != nil {
200+
b.underlying.Errorw("error emitting log to Beholder", "error", err)
201+
}
110202
}
111203

112204
func (b *beholderLogger) Errorw(msg string, keysAndValues ...any) {
113-
_ = b.emitter.With(LogLevelKey, "error").WithMapLabels(getLabelMap(keysAndValues...)).Emit(context.Background(), msg)
114205
b.underlying.Errorw(msg, keysAndValues...)
206+
ctx, cancel := getBeholderCallContext()
207+
defer cancel()
208+
err := b.emitter.With(LogLevelKey, "error").WithMapLabels(getLabelMap(keysAndValues...)).Emit(ctx, msg)
209+
if err != nil {
210+
b.underlying.Errorw("error emitting log to Beholder", "error", err)
211+
}
115212
}
116213

117214
func (b *beholderLogger) Panicw(msg string, keysAndValues ...any) {
118-
_ = b.emitter.With(LogLevelKey, "panic").WithMapLabels(getLabelMap(keysAndValues...)).Emit(context.Background(), msg)
119215
b.underlying.Panicw(msg, keysAndValues...)
216+
ctx, cancel := getBeholderCallContext()
217+
defer cancel()
218+
err := b.emitter.With(LogLevelKey, "panic").WithMapLabels(getLabelMap(keysAndValues...)).Emit(ctx, msg)
219+
if err != nil {
220+
b.underlying.Errorw("error emitting log to Beholder", "error", err)
221+
}
120222
}
121223

122224
func (b *beholderLogger) Fatalw(msg string, keysAndValues ...any) {
123-
_ = b.emitter.With(LogLevelKey, "fatal").WithMapLabels(getLabelMap(keysAndValues...)).Emit(context.Background(), msg)
124225
b.underlying.Fatalw(msg, keysAndValues...)
226+
ctx, cancel := getBeholderCallContext()
227+
defer cancel()
228+
err := b.emitter.With(LogLevelKey, "fatal").WithMapLabels(getLabelMap(keysAndValues...)).Emit(ctx, msg)
229+
if err != nil {
230+
b.underlying.Errorw("error emitting log to Beholder", "error", err)
231+
}
125232
}
126233

127234
func (b *beholderLogger) Sync() error {
@@ -146,3 +253,8 @@ func getLabelMap(keysAndValues ...any) map[string]string {
146253
}
147254
return labels
148255
}
256+
257+
func getBeholderCallContext() (context.Context, context.CancelFunc) {
258+
// Beholder Emit() should not block for logs wrapped in a custom event but let's be safe
259+
return context.WithTimeout(context.Background(), defaultBeholderEmitTimeoutMs*time.Millisecond)
260+
}

‎pkg/custmsg/logger_test.go

Lines changed: 18 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
package custmsg
22

33
import (
4+
"context"
45
"testing"
56

67
"github.com/smartcontractkit/chainlink-common/pkg/logger"
@@ -11,19 +12,33 @@ func TestBeholderLogger(t *testing.T) {
1112
emitter := newMockMessageEmitter(t)
1213
lggr := NewBeholderLogger(logger.Test(t), emitter)
1314

14-
emitter.EXPECT().With("log_level", "debug").Return(emitter).Once()
15+
emitter.EXPECT().With(LogLevelKey, "debug").Return(emitter).Once()
1516
emitter.EXPECT().Emit(matches.AnyContext, "message").Return(nil).Once()
1617
lggr.Debug("message")
1718

18-
emitter.EXPECT().With("log_level", "debug").Return(emitter).Once()
19+
emitter.EXPECT().With(LogLevelKey, "debug").Return(emitter).Once()
1920
emitter.EXPECT().Emit(matches.AnyContext, ">message<").Return(nil).Once()
2021
lggr.Debugf(">%s<", "message")
2122

22-
emitter.EXPECT().With("log_level", "debug").Return(emitter).Once()
23+
emitter.EXPECT().With(LogLevelKey, "debug").Return(emitter).Once()
2324
emitter.EXPECT().WithMapLabels(map[string]string{"keyX": "valueX"}).Return(emitter).Once()
2425
emitter.EXPECT().Emit(matches.AnyContext, "message").Return(nil).Once()
2526
lggr.Debugw("message", "keyX", "valueX")
2627

2728
emitter.EXPECT().WithMapLabels(map[string]string{"keyY": "valueY"}).Return(emitter).Once()
2829
_ = lggr.With("keyY", "valueY")
2930
}
31+
32+
func TestBeholderLogger_Blocking(t *testing.T) {
33+
emitter := newMockMessageEmitter(t)
34+
lggr := NewBeholderLogger(logger.Test(t), emitter)
35+
36+
emitter.EXPECT().With(LogLevelKey, "debug").Return(emitter).Once()
37+
// simulate a blocking call
38+
emitter.EXPECT().Emit(matches.AnyContext, "message").RunAndReturn(func(ctx context.Context, msg string) error {
39+
<-ctx.Done()
40+
return ctx.Err()
41+
}).Once()
42+
// should eventually cancel the context
43+
lggr.Debug("message")
44+
}

0 commit comments

Comments
 (0)