moira

1
package logging
2

3
import (
4
	"fmt"
5
	"math/big"
6
	"os"
7
	"path"
8
	"runtime"
9
	"strings"
10
	"time"
11

12
	"go.avito.ru/DO/moira"
13
	"go.avito.ru/DO/moira/logging/go-logging"
14
	"go.avito.ru/DO/moira/metrics"
15
)
16

17
type Config struct {
18
	Enabled  bool
19
	Host     string
20
	Port     int
21
	Level    string
22
	Fallback string
23
	Debug    bool
24
}
25

26
type Logger struct {
27
	appComponent string
28
	callCounter  int
29
	contextID    ContextID
30
	config       *loggerConfig
31
}
32

33
func Init(appComponent string, config Config, rateLimit moira.RateLimit) error {
34
	initMu.Lock()
35
	defer initMu.Unlock()
36

37
	if cfg != nil {
38
		return ErrAlreadyInitialized{}
39
	}
40

41
	hostname, err := os.Hostname()
42
	if err != nil {
43
		return ErrFailedInitialize{reason: err}
44
	}
45

46
	level, weight := parseLogLevel(config.Level)
47
	cfg = &loggerConfig{
48
		app:     appComponent,
49
		debug:   config.Debug,
50
		enabled: config.Enabled,
51
		limits:  rateLimit,
52
		host:    config.Host,
53
		port:    config.Port,
54
		this:    hostname,
55
		level:   level,
56
		weight:  weight,
57
	}
58

59
	fallback, _ = logging.ConfigureLog(config.Fallback, level, appComponent)
60
	loggersStore = newStore()
61
	statsd = metrics.NewLoggerMetric()
62

63
	worker, err = newLoggingWorker()
64
	if err != nil {
65
		return ErrFailedInitialize{reason: err}
66
	}
67
	go worker.lifeCycle()
68

69
	return nil
70
}
71

72
// GetLogger returns logger instance for given id
73
// id must be either uuid or empty string
74
func GetLogger(id string) *Logger {
75
	if cfg == nil || loggersStore == nil {
76
		panic(ErrNotInitialized{})
77
	}
78

79
	return loggersStore.getOrCreate(id)
80
}
81

82
// GetLoggerSafe is equivalent to GetLogger
83
// but returns an error instead of panic
84
// if something goes wrong
85
func GetLoggerSafe(id string) (logger *Logger, err error) {
86
	defer func() {
87
		if r := recover(); r != nil {
88
			err = fmt.Errorf("failed to get logger: panic = %v", r)
89
		}
90
	}()
91

92
	logger = GetLogger(id)
93
	return
94
}
95

96
func (logger *Logger) Debug(message string) {
97
	logger.log(logLevelDebug, message, nil)
98
}
99

100
func (logger *Logger) DebugE(message string, extra interface{}) {
101
	logger.log(logLevelDebug, message, extra)
102
}
103

104
func (logger *Logger) DebugF(format string, args ...interface{}) {
105
	logger.log(logLevelDebug, fmt.Sprintf(format, args...), nil)
106
}
107

108
func (logger *Logger) Info(message string) {
109
	logger.log(logLevelInfo, message, nil)
110
}
111

112
func (logger *Logger) InfoE(message string, extra interface{}) {
113
	logger.log(logLevelInfo, message, extra)
114
}
115

116
func (logger *Logger) InfoF(format string, args ...interface{}) {
117
	logger.log(logLevelInfo, fmt.Sprintf(format, args...), nil)
118
}
119

120
func (logger *Logger) Warn(message string) {
121
	logger.log(logLevelWarn, message, nil)
122
}
123

124
func (logger *Logger) WarnE(message string, extra interface{}) {
125
	logger.log(logLevelWarn, message, extra)
126
}
127

128
func (logger *Logger) WarnF(format string, args ...interface{}) {
129
	logger.log(logLevelWarn, fmt.Sprintf(format, args...), nil)
130
}
131

132
func (logger *Logger) Error(message string) {
133
	logger.log(logLevelError, message, nil)
134
}
135

136
func (logger *Logger) ErrorE(message string, extra interface{}) {
137
	logger.log(logLevelError, message, extra)
138
}
139

140
func (logger *Logger) ErrorF(format string, args ...interface{}) {
141
	logger.log(logLevelError, fmt.Sprintf(format, args...), nil)
142
}
143

144
func (logger *Logger) Fatal(message string) {
145
	logger.log(logLevelFatal, message, nil)
146
	os.Exit(1)
147
}
148

149
func (logger *Logger) FatalE(message string, extra interface{}) {
150
	logger.log(logLevelFatal, message, extra)
151
	os.Exit(1)
152
}
153

154
func (logger *Logger) FatalF(format string, args ...interface{}) {
155
	logger.log(logLevelFatal, fmt.Sprintf(format, args...), nil)
156
	os.Exit(1)
157
}
158

159
func (logger *Logger) TracePanic(message string, extra interface{}) {
160
	logger.ErrorE(message, extra)
161
	useFallbackLogger(logLevelError, message, extra)
162
}
163

164
func (logger *Logger) TraceSelfStats(id string, started time.Time) {
165
	margin := moira.TriggerCheckThreshold * time.Second
166
	passed := time.Since(started)
167

168
	log := newInstance("self-stats")
169
	msg := fmt.Sprintf("Total log calls for id %s: %d", id, logger.callCounter)
170
	extra := map[string]interface{}{
171
		"calls":    logger.callCounter,
172
		"duration": passed.String(),
173
		"id":       id,
174
	}
175

176
	if passed < margin {
177
		log.InfoE(msg, extra)
178
	} else {
179
		log.ErrorE(msg, extra)
180
	}
181
}
182

183
func (logger *Logger) log(level, message string, extra interface{}) {
184
	logger.callCounter++
185
	worker.queue <- &logDelayedMessage{
186
		component: logger.appComponent,
187
		contextId: logger.contextID,
188
		dateTime:  time.Now(),
189
		level:     level,
190
		message:   message,
191
		path:      formatPath(3),
192
		extraData: extra,
193
	}
194
}
195

196
func (logger *Logger) setContextID(contextID uint64) {
197
	logger.contextID = ContextID(contextID)
198
}
199

200
func (logger *Logger) setContextIDFromUUID(uuidRaw string) {
201
	// remove all dashes and prepend leading zero if needed
202
	uuid := strings.Replace(uuidRaw, "-", "", -1)
203
	if len(uuid) < 32 {
204
		uuid = strings.Repeat("0", 32-len(uuid)) + uuid
205
	}
206

207
	// split uuid to 2 equal parts and parse them as integers
208
	x1, _ := big.NewInt(0).SetString(uuid[:16], 16)
209
	x2, _ := big.NewInt(0).SetString(uuid[16:], 16)
210

211
	// 2 ** 64
212
	mod := big.NewInt(2)
213
	mod.Exp(mod, big.NewInt(64), nil)
214

215
	// (x1 + x2) % (2 ** 64)
216
	x3 := big.NewInt(0)
217
	x3.Add(x1, x2)
218
	x3.Mod(x3, mod)
219

220
	if !x3.IsUint64() {
221
		panic(fmt.Sprintf("Could not parse %s as integer", uuidRaw))
222
	} else {
223
		logger.setContextID(x3.Uint64())
224
	}
225
}
226

227
func formatPath(skipFrames int) string {
228
	pc, file, line, _ := runtime.Caller(skipFrames)
229
	_, fileName := path.Split(file)
230
	parts := strings.Split(runtime.FuncForPC(pc).Name(), ".")
231
	partsTotal := len(parts)
232

233
	packageName := ""
234
	funcName := parts[partsTotal-1]
235

236
	if parts[partsTotal-2][0] == '(' {
237
		funcName = parts[partsTotal-2] + "." + funcName
238
		packageName = strings.Join(parts[0:partsTotal-2], ".")
239
	} else {
240
		packageName = strings.Join(parts[0:partsTotal-1], ".")
241
	}
242

243
	return fmt.Sprintf("[%s] %s: %s#%d", packageName, fileName, funcName, line)
244
}
245

246
func newInstance(id string) *Logger {
247
	logger := &Logger{
248
		appComponent: cfg.app,
249
		config:       cfg,
250
	}
251

252
	if id == "" {
253
		logger.setContextID(defaultContextId)
254
	} else if id == "panic" {
255
		logger.setContextID(panicContextId)
256
	} else if id == "self-stats" {
257
		logger.setContextID(selfStatsContextId)
258
	} else {
259
		logger.setContextIDFromUUID(id)
260
	}
261

262
	return logger
263
}
264