-
Notifications
You must be signed in to change notification settings - Fork 25
/
config.go
317 lines (267 loc) · 9.97 KB
/
config.go
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
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
// Copyright (c) 2015-2021, NVIDIA CORPORATION.
// SPDX-License-Identifier: Apache-2.0
package logger
import (
"fmt"
"io"
"os"
"regexp"
"strings"
log "github.com/sirupsen/logrus"
"github.com/NVIDIA/proxyfs/conf"
)
// RFC3339 format with microsecond precision
//
const timeFormat = "2006-01-02T15:04:05.000000Z07:00"
var logFile *os.File = nil
// multiWriter groups multiple io.Writers into a single io.Writer. (Our
// immediate motivation for this is that logrus's SetOutput expects an
// io.Writer, but we might want to log to both the console and a file in
// development, and this seems potentially simpler in some aspects than
// defining a Hook. We may want to revisit this judgement—again—later.
//
// Supporting multiple writers is now a full-fledged feature of logger.
//
type multiWriter struct {
writers []io.Writer
}
// The global list of log targets to write to.
//
// logTargets should probably be protected by a lock or use some clever RCU
// update technique, but its really only changed for test cases.
//
var logTargets multiWriter
func (mw *multiWriter) addWriter(writer io.Writer) {
mw.writers = append(mw.writers, writer)
}
func (mw *multiWriter) Write(p []byte) (n int, err error) {
for _, writer := range mw.writers {
n, err = writer.Write(p)
// regrettably, the first thing that goes wrong determines our return
// values
if err != nil {
return
}
}
return
}
func (mw *multiWriter) Clear() {
mw.writers = []io.Writer{}
}
func addLogTarget(writer io.Writer) {
logTargets.addWriter(writer)
}
// This is used by LogTarget, which is a logging target that is useful for
// capturing the output logged by other packages for testing in test cases.
//
func (log LogTarget) write(p []byte) (n int, err error) {
log.LogBuf.Lock()
defer log.LogBuf.Unlock()
for i := len(log.LogBuf.LogEntries) - 1; i > 0; i-- {
log.LogBuf.LogEntries[i] = log.LogBuf.LogEntries[i-1]
}
log.LogBuf.LogEntries[0] = strings.TrimRight(string(p), " \t\n")
log.LogBuf.TotalEntries++
return 0, nil
}
// openLogFile is called to open the log file and (re-) int the logger. This
// really should be done before using it, but you can log things before calling.
// However, they will not appear in the logfile and will not be in the new text
// format.
//
// Config variables that affect logging include:
// Logging.LogFilePath string if present, pathname to log file
// Logging.LogToConsole bool if present and true, log to console as well as file
// Logging.TraceLevelLogging stringslice list of packages where tracing is enabled (name must
// also appear in packageTraceSettings)
// Logging.DebugLevelLogging stringslice
//
func openLogFile(confMap conf.ConfMap) (err error) {
log.SetFormatter(&log.TextFormatter{DisableColors: true, TimestampFormat: timeFormat})
// Fetch log file info, if provided
logFilePath, _ := confMap.FetchOptionValueString("Logging", "LogFilePath")
if logFilePath != "" {
logFile, err = os.OpenFile(logFilePath, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0666)
if err != nil {
log.Errorf("couldn't open log file '%s': %v", logFilePath, err)
return err
}
}
// Determine whether we should log to console. Default is false.
logToConsole, err := confMap.FetchOptionValueBool("Logging", "LogToConsole")
if err != nil {
logToConsole = false
err = nil
}
log.SetOutput(&logTargets)
if logFilePath == "" {
addLogTarget(os.Stderr)
} else {
addLogTarget(logFile)
if logToConsole {
addLogTarget(os.Stderr)
}
}
// NOTE: We always enable max logging in logrus, and either decide in
// this package whether to log OR log everything and parse it out of
// the logs after the fact
log.SetLevel(log.DebugLevel)
// Fetch trace and debug log settings, if provided
traceConfSlice, _ := confMap.FetchOptionValueStringSlice("Logging", "TraceLevelLogging")
setTraceLoggingLevel(traceConfSlice)
debugConfSlice, _ := confMap.FetchOptionValueStringSlice("Logging", "DebugLevelLogging")
setDebugLoggingLevel(debugConfSlice)
Infof("logger opened logfile '%s' (PID %d)", logFilePath, os.Getpid())
return
}
// closeLogFile closes the output log file as part of shutdown or as part of
// rotating to a new log file.
//
func closeLogFile(confMap conf.ConfMap) (err error) {
Infof("logger closing logfile (PID %d)", os.Getpid())
// We open and close our own logfile
if logFile != nil {
// Sync() flushes data cached in the kernel to disk, which is
// really only useful if the OS were to crash soon
logFile.Sync()
logFile.Close()
}
logTargets.Clear()
err = nil
return
}
// Up opens the logfile. This really should be done before using the logfile,
// but you can log things before calling. However, they will not appear in
// the logfile and will not be in the new text format.
//
// Config variables that affect logging include:
// Logging.LogFilePath string if present, pathname to log file
// Logging.LogToConsole bool if present and true, log to console as well as file
// Logging.TraceLevelLogging stringslice list of packages where tracing is enabled (name must
// also appear in packageTraceSettings)
// Logging.DebugLevelLogging stringslice
//
func Up(confMap conf.ConfMap) (err error) {
err = openLogFile(confMap)
if err != nil {
return
}
Infof("logger is starting up (PID %d)", os.Getpid())
return
}
func SignaledStart(confMap conf.ConfMap) (err error) {
err = nil
return
}
func SignaledFinish(confMap conf.ConfMap) (err error) {
Infof("logger is closing logfile (PID %d)", os.Getpid())
err = closeLogFile(confMap)
if nil == err {
err = openLogFile(confMap)
Infof("logger opened logfile (PID %d)", os.Getpid())
}
return
}
func Down(confMap conf.ConfMap) (err error) {
log.Infof("logger is shutting down (PID %d)", os.Getpid())
err = closeLogFile(confMap)
return
}
// Parse a log entry captured via LogTarget return the fields as key value pairs
// in a map.
//
// Match log entries look like:
//
// time="2017-07-27T01:30:46.060080Z" level=info msg="retry.RequestWithRetry(): swiftclient.testRetry.request(1) succeeded after 4 attempts in 0.031 sec" function=RequestWithRetry goroutine=6 package=swiftclient
//
// time="2017-07-27T02:18:19.214012Z" level=error msg="retry.RequestWithRetry(): swiftclient.testRetry.request(1) failed after 7 attempts in 0.053 sec with retriable error" error="Simulate a retriable errror" function=RequestWithRetry goroutine=6 package=swiftclient
//
// time="2017-07-27T02:09:32.259383Z" level=error msg="retry.RequestWithRetry(): swiftclient.testRetry.request(1) failed after 6 attempts in 0.054 sec with unretriable error" error="Simulate an unretriable error" function=RequestWithRetry goroutine=20 package=swiftclient
//
func parseLogEntry(entry string) (fields map[string]string, err error) {
var (
matches []string
)
var fieldRE = regexp.MustCompile(
`^time="(?P<time>[-:0-9.ZTt_]+)" level=(?P<level>[a-zA-Z]+) msg="(?P<msg>([^"]|\\")+)" (error="(?P<error>([^"]|\\")+)" )?function=(?P<function>\w+) goroutine=(?P<goroutine>\d+) package=(?P<package>\w+)`)
matches = fieldRE.FindStringSubmatch(entry)
if matches == nil {
fmt.Printf("parseLogEntry: log entry not matched by regular expression fieldRE: '%s'\n", entry)
err = fmt.Errorf("log entry not matched by regular expression fieldRE: '%s'", entry)
return
}
fields = make(map[string]string)
for idx, name := range fieldRE.SubexpNames() {
if name != "" && matches[idx] != "" {
fields[name] = matches[idx]
}
}
return
}
// Parse the log entries, starting with the most recent, looking for a message
// generated by the function funcName that matches the regular expression
// logEntryRE within the most recent maxEntries lines of the log.
//
// If found, return the parsed fields from the log message, which are a
// combination of the fields returned by ParseLogEntry() and the fields in the
// passed regular expression (which must use names for the matching parts).
// funcName must match the contents of the field "function" returned by
// ParseLogEntry(). entryIdx is the index of the entry in the log with 0 being
// the most recent.
//
// If not found, return an error.
//
// Example regexp from trackedlock/api_test.go that matches:
//
// msg="trackedlock watcher: *trackedlock.Mutex at 0xc420110000 locked for 2 sec; stack at Lock() call:\ngoroutine 19 [running]:..."
//
// watcherLogMatch = `^trackedlock watcher: (?P<type>[*a-zA-Z0-9_.]+) at (?P<ptr>0x[0-9a-f]+) locked for (?P<time>\d+) sec; stack at (?P<locker>[a-zA-Z0-9_()]+) call:\\n(?P<lockStack>.*)$`
//
func parseLogForFunc(logcopy LogTarget, funcName string, logEntryRE *regexp.Regexp, maxEntries int) (fields map[string]string, entryIdx int, err error) {
logcopy.LogBuf.Lock()
defer logcopy.LogBuf.Unlock()
if logcopy.LogBuf.TotalEntries < 1 {
err = fmt.Errorf("parseLogForFunc(): no log entries")
return
}
var logEntry string
for entryIdx, logEntry = range logcopy.LogBuf.LogEntries {
if entryIdx >= maxEntries {
err = fmt.Errorf(
"parseLogForFunc(): no matching log entry for function '%s' found in %d log entries",
funcName, maxEntries)
return
}
if logEntry == "" {
err = fmt.Errorf("parseLogForFunc(): exhausted all log entries without finding a match")
return
}
fields, err = ParseLogEntry(logEntry)
if err != nil {
err = fmt.Errorf("parseLogForFunc(): log entry '%s' unparsable by ParseLogEntry(): %v",
logEntry, err)
return
}
if fields["msg"] == "" {
err = fmt.Errorf("parseLogForFunc(): log entry does not contain a 'msg=' string: '%s'",
logEntry)
return
}
if fields["function"] != funcName {
continue
}
matches := logEntryRE.FindStringSubmatch(fields["msg"])
if matches == nil {
continue
}
// we found a matching log entry; copy the fields and we're done!
for idx, name := range logEntryRE.SubexpNames() {
if name != "" {
fields[name] = matches[idx]
}
}
return
}
err = fmt.Errorf("parseLogForFunc(): no matching log entry found: function '%s'", funcName)
return
}