summaryrefslogtreecommitdiffstats
path: root/utils/logger/logger.go
blob: 227cf405e7f7aef287cfc1cdab9c81dc5d858e11 (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
// this is a new logger interface for mattermost

package logger

import (
	"context"
	"encoding/json"
	"fmt"
	"path/filepath"
	"runtime"

	l4g "github.com/alecthomas/log4go"

	"strings"

	"github.com/mattermost/mattermost-server/model"
	"github.com/mattermost/mattermost-server/utils"
	"github.com/pkg/errors"
)

// this pattern allows us to "mock" the underlying l4g code when unit testing
var debugLog = l4g.Debug
var infoLog = l4g.Info
var errorLog = l4g.Error

func init() {
	initL4g(utils.Cfg.LogSettings)
}

// listens for configuration changes that we might need to respond to
var configListenerID = utils.AddConfigListener(func(oldConfig *model.Config, newConfig *model.Config) {
	infoLog("Configuration change detected, reloading log settings")
	initL4g(newConfig.LogSettings)
})

// assumes that ../config.go::configureLog has already been called, and has in turn called l4g.close() to clean up
// any old filters that we might have previously created
func initL4g(logSettings model.LogSettings) {
	// TODO: add support for newConfig.LogSettings.EnableConsole. Right now, ../config.go sets it up in its configureLog
	// method. If we also set it up here, messages will be written to the console twice. Eventually, when all instances
	// of l4g have been replaced by this logger, we can move that code to here
	if logSettings.EnableFile {
		level := l4g.DEBUG
		if logSettings.FileLevel == "INFO" {
			level = l4g.INFO
		} else if logSettings.FileLevel == "WARN" {
			level = l4g.WARNING
		} else if logSettings.FileLevel == "ERROR" {
			level = l4g.ERROR
		}

		// create a logger that writes JSON objects to a file, and override our log methods to use it
		flw := NewJSONFileLogger(level, utils.GetLogFileLocation(logSettings.FileLocation)+".jsonl")
		debugLog = flw.Debug
		infoLog = flw.Info
		errorLog = flw.Error
	}
}

// contextKey lets us add contextual information to log messages
type contextKey string

func (c contextKey) String() string {
	return string(c)
}

const contextKeyUserID contextKey = contextKey("user_id")
const contextKeyRequestID contextKey = contextKey("request_id")

// any contextKeys added to this array will be serialized in every log message
var contextKeys = [2]contextKey{contextKeyUserID, contextKeyRequestID}

// WithUserId adds a user id to the specified context. If the returned Context is subsequently passed to a logging
// method, the user id will automatically be included in the logged message
func WithUserId(ctx context.Context, userID string) context.Context {
	return context.WithValue(ctx, contextKeyUserID, userID)
}

// WithRequestId adds a request id to the specified context. If the returned Context is subsequently passed to a logging
// method, the request id will automatically be included in the logged message
func WithRequestId(ctx context.Context, requestID string) context.Context {
	return context.WithValue(ctx, contextKeyRequestID, requestID)
}

// extracts known contextKey values from the specified Context and assembles them into the returned map
func serializeContext(ctx context.Context) map[string]string {
	serialized := make(map[string]string)
	for _, key := range contextKeys {
		value, ok := ctx.Value(key).(string)
		if ok {
			serialized[string(key)] = value
		}
	}
	return serialized
}

// Returns the path to the next file up the callstack that has a different name than this file
// in other words, finds the path to the file that is doing the logging.
// Removes machine-specific prefix, so returned path starts with /mattermost-server.
// Looks a maximum of 10 frames up the call stack to find a file that has a different name than this one.
func getCallerFilename() (string, error) {
	_, currentFilename, _, ok := runtime.Caller(0)
	if !ok {
		return "", errors.New("Failed to traverse stack frame")
	}

	platformDirectory := currentFilename
	for filepath.Base(platformDirectory) != "platform" {
		platformDirectory = filepath.Dir(platformDirectory)
		if platformDirectory == "." || platformDirectory == string(filepath.Separator) {
			break
		}
	}

	for i := 1; i < 10; i++ {
		_, parentFilename, _, ok := runtime.Caller(i)
		if !ok {
			return "", errors.New("Failed to traverse stack frame")
		} else if parentFilename != currentFilename && strings.Contains(parentFilename, platformDirectory) {
			// trim parentFilename such that we return the path to parentFilename, relative to platformDirectory
			return parentFilename[strings.LastIndex(parentFilename, platformDirectory)+len(platformDirectory)+1:], nil
		}
	}
	return "", errors.New("Failed to traverse stack frame")
}

// creates a JSON representation of a log message
func serializeLogMessage(ctx context.Context, message string) string {
	callerFilename, err := getCallerFilename()
	if err != nil {
		callerFilename = "Unknown"
	}

	bytes, err := json.Marshal(&struct {
		Context map[string]string `json:"context"`
		File    string            `json:"file"`
		Message string            `json:"message"`
	}{
		serializeContext(ctx),
		callerFilename,
		message,
	})
	if err != nil {
		errorLog("Failed to serialize log message %v", message)
	}
	return string(bytes)
}

func formatMessage(args ...interface{}) string {
	msg, ok := args[0].(string)
	if !ok {
		panic("Second argument is not of type string")
	}
	if len(args) > 1 {
		variables := args[1:]
		msg = fmt.Sprintf(msg, variables...)
	}
	return msg
}

// Debugc logs a debugLog level message, including context information that is stored in the first parameter.
// If two parameters are supplied, the second must be a message string, and will be logged directly.
// If more than two parameters are supplied, the second parameter must be a format string, and the remaining parameters
// must be the variables to substitute into the format string, following the convention of the fmt.Sprintf(...) function.
func Debugc(ctx context.Context, args ...interface{}) {
	debugLog(func() string {
		msg := formatMessage(args...)
		return serializeLogMessage(ctx, msg)
	})
}

// Debugf logs a debugLog level message.
// If one parameter is supplied, it must be a message string, and will be logged directly.
// If two or more parameters are specified, the first parameter must be a format string, and the remaining parameters
// must be the variables to substitute into the format string, following the convention of the fmt.Sprintf(...) function.
func Debugf(args ...interface{}) {
	debugLog(func() string {
		msg := formatMessage(args...)
		return serializeLogMessage(context.Background(), msg)
	})
}

// Infoc logs an infoLog level message, including context information that is stored in the first parameter.
// If two parameters are supplied, the second must be a message string, and will be logged directly.
// If more than two parameters are supplied, the second parameter must be a format string, and the remaining parameters
// must be the variables to substitute into the format string, following the convention of the fmt.Sprintf(...) function.
func Infoc(ctx context.Context, args ...interface{}) {
	infoLog(func() string {
		msg := formatMessage(args...)
		return serializeLogMessage(ctx, msg)
	})
}

// Infof logs an infoLog level message.
// If one parameter is supplied, it must be a message string, and will be logged directly.
// If two or more parameters are specified, the first parameter must be a format string, and the remaining parameters
// must be the variables to substitute into the format string, following the convention of the fmt.Sprintf(...) function.
func Infof(args ...interface{}) {
	infoLog(func() string {
		msg := formatMessage(args...)
		return serializeLogMessage(context.Background(), msg)
	})
}

// Errorc logs an error level message, including context information that is stored in the first parameter.
// If two parameters are supplied, the second must be a message string, and will be logged directly.
// If more than two parameters are supplied, the second parameter must be a format string, and the remaining parameters
// must be the variables to substitute into the format string, following the convention of the fmt.Sprintf(...) function.
func Errorc(ctx context.Context, args ...interface{}) {
	errorLog(func() string {
		msg := formatMessage(args...)
		return serializeLogMessage(ctx, msg)
	})
}

// Errorf logs an error level message.
// If one parameter is supplied, it must be a message string, and will be logged directly.
// If two or more parameters are specified, the first parameter must be a format string, and the remaining parameters
// must be the variables to substitute into the format string, following the convention of the fmt.Sprintf(...) function.
func Errorf(args ...interface{}) {
	errorLog(func() string {
		msg := formatMessage(args...)
		return serializeLogMessage(context.Background(), msg)
	})
}