diff --git a/cmd/geth/main.go b/cmd/geth/main.go index 9ee1e9e6d0..e42aab30ac 100644 --- a/cmd/geth/main.go +++ b/cmd/geth/main.go @@ -200,11 +200,11 @@ func init() { app.Before = func(ctx *cli.Context) error { runtime.GOMAXPROCS(runtime.NumCPU()) - disklogs := "" + logdir := "" if ctx.GlobalBool(utils.DashboardEnabledFlag.Name) { - disklogs = (&node.Config{DataDir: utils.MakeDataDir(ctx)}).ResolvePath("logs") + logdir = (&node.Config{DataDir: utils.MakeDataDir(ctx)}).ResolvePath("logs") } - if err := debug.Setup(ctx, disklogs); err != nil { + if err := debug.Setup(ctx, logdir); err != nil { return err } // Cap the cache allowance and tune the garbage collector diff --git a/cmd/swarm/main.go b/cmd/swarm/main.go index 3995b0e82f..fbcd31d57c 100644 --- a/cmd/swarm/main.go +++ b/cmd/swarm/main.go @@ -432,11 +432,7 @@ pv(1) tool to get a progress bar: app.Flags = append(app.Flags, swarmmetrics.Flags...) app.Before = func(ctx *cli.Context) error { runtime.GOMAXPROCS(runtime.NumCPU()) - disklogs := "" - if ctx.GlobalBool(utils.DashboardEnabledFlag.Name) { - disklogs = (&node.Config{DataDir: utils.MakeDataDir(ctx)}).ResolvePath("logs") - } - if err := debug.Setup(ctx, disklogs); err != nil { + if err := debug.Setup(ctx, ""); err != nil { return err } swarmmetrics.Setup(ctx) diff --git a/dashboard/assets.go b/dashboard/assets.go index b819b6a165..07bc9c4e4d 100644 --- a/dashboard/assets.go +++ b/dashboard/assets.go @@ -10389,12 +10389,16 @@ var _bundleJs = []byte((((((((((`!function(modules) { default: lvl = ""; } - if ("" === lvl || "string" != typeof t || t.length < 19 || "string" != typeof msg || !Array.isArray(ctx)) return void (content += 'Invalid log record
'); - ctx.length > 0 && (msg += " ".repeat(Math.max(40 - msg.length, 0))), content += '' + lvl + "[" + t.substr(5, 5) + "|" + t.substr(11, 8) + "] " + msg; + var time = new Date(t); + if ("" === lvl || !(time instanceof Date) || isNaN(time) || "string" != typeof msg || !Array.isArray(ctx)) return void (content += 'Invalid log record
'); + ctx.length > 0 && (msg += " ".repeat(Math.max(40 - msg.length, 0))); + var month = ("0" + (time.getMonth() + 1)).slice(-2), date = ("0" + time.getDate()).slice(-2), hours = ("0" + time.getHours()).slice(-2), minutes = ("0" + time.getMinutes()).slice(-2), seconds = ("0" + time.getSeconds()).slice(-2); + content += '' + lvl + "[" + month + "-" + date + "|" + hours + ":" + minutes + ":" + seconds + "] " + msg; for (var i = 0; i < ctx.length; i += 2) { - var key = ctx[i], value = ctx[i + 1], padding = fieldPadding.get(key); - (void 0 === padding || padding < value.length) && (padding = value.length, fieldPadding.set(key, padding)), - content += ' ' + key + "=" + value + " ".repeat(padding - value.length); + var key = ctx[i], val = ctx[i + 1], padding = fieldPadding.get(key); + ("number" != typeof padding || padding < val.length) && (padding = val.length, fieldPadding.set(key, padding)); + var p = ""; + i < ctx.length - 2 && (p = " ".repeat(padding - val.length)), content += ' ' + key + "=" + val + p; } content += "
"; }), content; @@ -10403,19 +10407,19 @@ var _bundleJs = []byte((((((((((`!function(modules) { if (prev.topChanged = 0, prev.bottomChanged = 0, !Array.isArray(update.chunk) || update.chunk.length < 1) return prev; Array.isArray(prev.chunks) || (prev.chunks = []); var content = createChunk(update.chunk); - if (!update.old) return prev.endBottom ? prev.chunks.length < 1 ? [ { + if (!update.source) return prev.endBottom ? prev.chunks.length < 1 ? [ { content: content, name: "00000000000000.log" } ] : (prev.chunks[prev.chunks.length - 1].content += content, prev.bottomChanged = 1, prev) : prev; var chunk = { content: content, - name: update.old.name + name: update.source.name }; - return update.old.past ? (update.old.last && (prev.endTop = !0), prev.chunks.length >= limit && (prev.endBottom = !1, - prev.chunks.splice(limit - 1, prev.chunks.length - limit + 1), prev.bottomChanged = -1), - prev.chunks = [ chunk ].concat(_toConsumableArray(prev.chunks)), prev.topChanged = 1, - prev) : (update.old.last && (prev.endBottom = !0), prev.chunks.length >= limit && (prev.endTop = !1, + return prev.chunks.length > 0 && update.source.name < prev.chunks[0].name ? (update.source.last && (prev.endTop = !0), + prev.chunks.length >= limit && (prev.endBottom = !1, prev.chunks.splice(limit - 1, prev.chunks.length - limit + 1), + prev.bottomChanged = -1), prev.chunks = [ chunk ].concat(_toConsumableArray(prev.chunks)), + prev.topChanged = 1, prev) : (update.source.last && (prev.endBottom = !0), prev.chunks.length >= limit && (prev.endTop = !1, prev.chunks.splice(0, prev.chunks.length - limit + 1), prev.topChanged = -1), prev.chunks = [].concat(_toConsumableArray(prev.chunks), [ chunk ]), prev.bottomChanged = 1, prev); }; @@ -40575,7 +40579,7 @@ func bundleJs() (*asset, error) { } info := bindataFileInfo{name: "bundle.js", size: 0, mode: os.FileMode(0), modTime: time.Unix(0, 0)} - a := &asset{bytes: bytes, info: info, digest: [32]uint8{0x69, 0xa2, 0xe, 0x5a, 0x74, 0x8, 0xb1, 0x63, 0x1c, 0x5d, 0xae, 0x27, 0x7, 0x18, 0x9f, 0xbe, 0xee, 0x93, 0x92, 0x88, 0x93, 0xd6, 0xfd, 0xfd, 0x5b, 0xf, 0xe8, 0x45, 0xcb, 0x8f, 0xbe, 0x60}} + a := &asset{bytes: bytes, info: info, digest: [32]uint8{0xc1, 0xd0, 0xe9, 0xd3, 0xae, 0x7d, 0x57, 0x66, 0x4, 0xc8, 0xf9, 0x40, 0x68, 0xff, 0x8b, 0xa0, 0x4d, 0x0, 0xca, 0x4b, 0x3d, 0x7f, 0xb9, 0x40, 0xd, 0xae, 0xe0, 0x75, 0xd0, 0xd1, 0xfc, 0x7b}} return a, nil } diff --git a/dashboard/assets/components/Logs.jsx b/dashboard/assets/components/Logs.jsx index cb7a05224a..2030142768 100644 --- a/dashboard/assets/components/Logs.jsx +++ b/dashboard/assets/components/Logs.jsx @@ -67,25 +67,34 @@ const createChunk = (records: Array) => { default: lvl = ''; } - if (lvl === '' || typeof t !== 'string' || t.length < 19 || typeof msg !== 'string' || !Array.isArray(ctx)) { - content += `Invalid log record
`; + const time = new Date(t); + if (lvl === '' || !(time instanceof Date) || isNaN(time) || typeof msg !== 'string' || !Array.isArray(ctx)) { + content += 'Invalid log record
'; return; } if (ctx.length > 0) { msg += ' '.repeat(Math.max(40 - msg.length, 0)); } - // Time format: 2006-01-02T15:04:05-0700 -> 01-02|15:04:05 - content += `${lvl}[${t.substr(5, 5)}|${t.substr(11, 8)}] ${msg}`; + const month = `0${time.getMonth() + 1}`.slice(-2); + const date = `0${time.getDate()}`.slice(-2); + const hours = `0${time.getHours()}`.slice(-2); + const minutes = `0${time.getMinutes()}`.slice(-2); + const seconds = `0${time.getSeconds()}`.slice(-2); + content += `${lvl}[${month}-${date}|${hours}:${minutes}:${seconds}] ${msg}`; for (let i = 0; i < ctx.length; i += 2) { const key = ctx[i]; - const value = ctx[i + 1]; + const val = ctx[i + 1]; let padding = fieldPadding.get(key); - if (typeof padding === 'undefined' || padding < value.length) { - padding = value.length; + if (typeof padding !== 'number' || padding < val.length) { + padding = val.length; fieldPadding.set(key, padding); } - content += ` ${key}=${value}${' '.repeat(padding - value.length)}`; + let p = ''; + if (i < ctx.length - 2) { + p = ' '.repeat(padding - val.length); + } + content += ` ${key}=${val}${p}`; } content += '
'; }); @@ -104,7 +113,7 @@ export const inserter = (limit: number) => (update: LogsMessage, prev: LogsType) prev.chunks = []; } const content = createChunk(update.chunk); - if (!update.old) { + if (!update.source) { // In case of stream chunk. if (!prev.endBottom) { return prev; @@ -119,10 +128,10 @@ export const inserter = (limit: number) => (update: LogsMessage, prev: LogsType) } const chunk = { content, - name: update.old.name, + name: update.source.name, }; - if (update.old.past) { - if (update.old.last) { + if (prev.chunks.length > 0 && update.source.name < prev.chunks[0].name) { + if (update.source.last) { prev.endTop = true; } if (prev.chunks.length >= limit) { @@ -134,7 +143,7 @@ export const inserter = (limit: number) => (update: LogsMessage, prev: LogsType) prev.topChanged = 1; return prev; } - if (update.old.last) { + if (update.source.last) { prev.endBottom = true; } if (prev.chunks.length >= limit) { diff --git a/dashboard/assets/types/content.jsx b/dashboard/assets/types/content.jsx index b41d51e73e..ff82c3572d 100644 --- a/dashboard/assets/types/content.jsx +++ b/dashboard/assets/types/content.jsx @@ -86,12 +86,11 @@ export type Logs = { }; export type LogsMessage = { - old: ?LogFile, - chunk: Array, + source: ?LogFile, + chunk: Array, }; export type LogFile = { name: string, - past: string, last: string, }; diff --git a/dashboard/dashboard.go b/dashboard/dashboard.go index c1272ce16f..f3dec8df01 100644 --- a/dashboard/dashboard.go +++ b/dashboard/dashboard.go @@ -40,6 +40,7 @@ import ( "github.com/ethereum/go-ethereum/rpc" "github.com/mohae/deepcopy" "golang.org/x/net/websocket" + "io" ) const ( @@ -243,15 +244,16 @@ func (db *Dashboard) apiHandler(conn *websocket.Conn) { db.lock.Unlock() }() for { - var r Request - err := websocket.JSON.Receive(conn, &r) - if err != nil { - client.logger.Warn("Failed to receive request", "err", err) + r := new(Request) + if err := websocket.JSON.Receive(conn, r); err != nil { + if err != io.EOF { + client.logger.Warn("Failed to receive request", "err", err) + } close(done) return } if r.Logs != nil { - db.handleLogRequest(r.Logs, client) // TODO (kurkomisi): concurrent function call? + db.handleLogRequest(r.Logs, client) } } } @@ -292,8 +294,6 @@ func (db *Dashboard) collectData() { frequency = float64(db.config.Refresh / time.Second) numCPU = float64(runtime.NumCPU()) - - sys = db.history.System ) for { @@ -360,6 +360,8 @@ func (db *Dashboard) collectData() { Time: now, Value: float64(deltaDiskWrite) / frequency, } + sys := db.history.System + db.lock.Lock() sys.ActiveMemory = append(sys.ActiveMemory[1:], activeMemory) sys.VirtualMemory = append(sys.VirtualMemory[1:], virtualMemory) sys.NetworkIngress = append(sys.NetworkIngress[1:], networkIngress) @@ -368,6 +370,7 @@ func (db *Dashboard) collectData() { sys.SystemCPU = append(sys.SystemCPU[1:], systemCPU) sys.DiskRead = append(sys.DiskRead[1:], diskRead) sys.DiskWrite = append(sys.DiskRead[1:], diskWrite) + db.lock.Unlock() db.sendToAll(&Message{ System: &SystemMessage{ diff --git a/dashboard/log.go b/dashboard/log.go index c12dd8a8b8..0dc39a18ef 100644 --- a/dashboard/log.go +++ b/dashboard/log.go @@ -27,125 +27,121 @@ import ( "regexp" "sort" "time" + "bytes" ) -// embrace inserts buf into brackets. -func embrace(buf []byte) []byte { - b := make([]byte, len(buf)+2) +var emptyChunk = json.RawMessage("[]") + +// prepLogs creates a JSON array from the given log record buffer. +// Returns the prepared array and the position of the last '\n' +// character in the original buffer, or -1 if it doesn't contain any. +func prepLogs(buf []byte) (json.RawMessage, int) { + b := make(json.RawMessage, 1, len(buf) + 1) b[0] = '[' - copy(b[1:], buf) - b[len(buf)+1] = ']' - - return b -} - -// replaceNewLinesWithCommas replaces the '\n' characters with ',' characters and returns the last replaced position. -func replaceNewLinesWithCommas(buf []byte) int { + b = append(b, buf...) last := -1 - for i := 0; i < len(buf); i++ { - if buf[i] == '\n' { - buf[i] = ',' + for i := 1; i < len(b); i++ { + if b[i] == '\n' { + b[i] = ',' last = i } } - return last + if last < 0 { + return emptyChunk, -1 + } + b[last] = ']' + return b[:last+1], last - 1 } -// handleLogRequest searches for the log file specified by the timestamp of the request, creates a JSON array out of it -// and sends it to the requesting client. +// handleLogRequest searches for the log file specified by the timestamp of the +// request, creates a JSON array out of it and sends it to the requesting client. func (db *Dashboard) handleLogRequest(r *LogsRequest, c *client) { files, err := ioutil.ReadDir(db.logdir) if err != nil { log.Warn("Failed to open logdir", "path", db.logdir, "err", err) return } - re := regexp.MustCompile(".log$") - fileNames := make([]string, len(files)) - n := 0 + re := regexp.MustCompile("\\.log$") + fileNames := make([]string, 0, len(files)) for _, f := range files { - if f.Mode().IsRegular() && re.Match([]byte(f.Name())) { - fileNames[n] = f.Name() - n++ + if f.Mode().IsRegular() && re.MatchString(f.Name()) { + fileNames = append(fileNames, f.Name()) } } - if n < 1 { - log.Warn("There isn't any log file in the logdir", "path", db.logdir) + if len(fileNames) < 1 { + log.Warn("No log files in logdir", "path", db.logdir) return } - i := sort.Search(n, func(i int) bool { - return fileNames[i] >= r.Name // Returns the smallest index such as fileNames[i] >= r.Name. + idx := sort.Search(len(fileNames), func(idx int) bool { + // Returns the smallest index such as fileNames[idx] >= r.Name, + // if there is no such index, returns n. + return fileNames[idx] >= r.Name }) - if i >= n || fileNames[i] != r.Name { - log.Warn("The requested file isn't in the logdir", "path", filepath.Join(db.logdir, r.Name)) + switch { + case idx < 0: return - } - - last := false - if r.Past { - if i <= 0 { - return - } - i-- - if i == 0 { - last = true - } - } else { - if i >= n-1 { - return - } - if i == n-2 { - // The last file is continuously updated, and its chunks are streamed, - // so in order to avoid log record duplication on the client side, it is - // handled differently. Its actual content is always saved in the history. - db.lock.Lock() - if db.history.Logs != nil { - c.msg <- &Message{ - Logs: db.history.Logs, - } + case idx == 0 && r.Past: + return + case idx >= len(fileNames): + return + case r.Past: + idx-- + case idx == len(fileNames)-1 && fileNames[idx] == r.Name: + return + case idx == len(fileNames)-1 || (idx == len(fileNames)-2 && fileNames[idx] == r.Name): + // The last file is continuously updated, and its chunks are streamed, + // so in order to avoid log record duplication on the client side, it is + // handled differently. Its actual content is always saved in the history. + db.lock.Lock() + if db.history.Logs != nil { + c.msg <- &Message{ + Logs: db.history.Logs, } - db.lock.Unlock() - return } - i++ + db.lock.Unlock() + return + case fileNames[idx] == r.Name: + idx++ } - path := filepath.Join(db.logdir, fileNames[i]) - f, err := os.OpenFile(path, os.O_RDONLY, 0644) - if err != nil { - log.Warn("Failed to open file", "path", path, "err", err) - return - } - defer f.Close() + path := filepath.Join(db.logdir, fileNames[idx]) var buf []byte - if buf, err = ioutil.ReadAll(f); err != nil { + if buf, err = ioutil.ReadFile(path); err != nil { log.Warn("Failed to read file", "path", path, "err", err) return } - lastComma := replaceNewLinesWithCommas(buf) - if lastComma < 0 { + chunk, end := prepLogs(buf) + if end < 0 { log.Warn("The file doesn't contain valid logs", "path", path) return } - db.lock.Lock() c.msg <- &Message{ Logs: &LogsMessage{ - Old: &LogFile{ - Name: fileNames[i], - Past: r.Past, - Last: last, + Source: &LogFile{ + Name: fileNames[idx], + Last: r.Past && idx == 0, }, - Chunk: embrace(buf[:lastComma]), + Chunk: chunk, }, } - db.lock.Unlock() } -// streamLogs watches the file system, and when the logger writes the new log records into the files, picks them up, -// then makes JSON array out of them and sends them to the clients. -// This could be embedded into collectData, but they shouldn't depend on each other, and also cleaner this way. +// streamLogs watches the file system, and when the logger writes +// the new log records into the files, picks them up, then makes +// JSON array out of them and sends them to the clients. func (db *Dashboard) streamLogs() { defer db.wg.Done() + var ( + err error + errc chan error + ) + defer func() { + if errc == nil { + errc = <-db.quit + } + errc <- err + }() files, err := ioutil.ReadDir(db.logdir) if err != nil { @@ -158,15 +154,16 @@ func (db *Dashboard) streamLogs() { ) // The log records are always written into the last file in alphabetical order, because of the timestamp. - re := regexp.MustCompile(".log$") - var i int - for i = len(files) - 1; i >= 0 && (!files[i].Mode().IsRegular() || !re.Match([]byte(files[i].Name()))); i-- { + re := regexp.MustCompile("\\.log$") + i := len(files) - 1 + for i >= 0 && (!files[i].Mode().IsRegular() || !re.MatchString(files[i].Name())) { + i-- } if i < 0 { - log.Warn("There isn't any log file in the logdir", "path", db.logdir) + log.Warn("No log files in logdir", "path", db.logdir) return } - if opened, err = os.OpenFile(filepath.Join(db.logdir, files[i].Name()), os.O_RDONLY, 0644); err != nil { + if opened, err = os.OpenFile(filepath.Join(db.logdir, files[i].Name()), os.O_RDONLY, 0600); err != nil { log.Warn("Failed to open file", "name", files[i].Name(), "err", err) return } @@ -178,12 +175,11 @@ func (db *Dashboard) streamLogs() { } db.lock.Lock() db.history.Logs = &LogsMessage{ - Old: &LogFile{ + Source: &LogFile{ Name: fi.Name(), - Past: false, Last: true, }, - Chunk: json.RawMessage("[]"), + Chunk: emptyChunk, } db.lock.Unlock() @@ -202,7 +198,8 @@ func (db *Dashboard) streamLogs() { ticker := time.NewTicker(db.config.Refresh) defer ticker.Stop() - for { +loop: + for err == nil || errc == nil { select { case event := <-watcher.Events: // Make sure that new log file was created. @@ -211,9 +208,10 @@ func (db *Dashboard) streamLogs() { } if opened == nil { log.Warn("The last log file is not opened") - return + break loop } - // The new log file's name is always greater, because it is created using the actual log record's time. + // The new log file's name is always greater, + // because it is created using the actual log record's time. if opened.Name() >= event.Name { break } @@ -221,25 +219,22 @@ func (db *Dashboard) streamLogs() { chunk, err := ioutil.ReadAll(opened) if err != nil { log.Warn("Failed to read file", "name", opened.Name(), "err", err) - return + break loop } - b := make([]byte, len(buf)+len(chunk)) - copy(b, buf) - copy(b[len(buf):], chunk) - buf = b + buf = append(buf, chunk...) opened.Close() - if last := replaceNewLinesWithCommas(buf); last >= 0 { + if chunk, last := prepLogs(buf); last >= 0 { // Send the rest of the previously opened file. db.sendToAll(&Message{ Logs: &LogsMessage{ - Chunk: embrace(buf[:last]), + Chunk: chunk, }, }) } if opened, err = os.OpenFile(event.Name, os.O_RDONLY, 0644); err != nil { log.Warn("Failed to open file", "name", event.Name, "err", err) - return + break loop } buf = buf[:0] @@ -247,62 +242,55 @@ func (db *Dashboard) streamLogs() { fi, err := opened.Stat() if err != nil { log.Warn("Problem with file", "name", opened.Name(), "err", err) - return + break loop } db.lock.Lock() - db.history.Logs.Old.Name = fi.Name() - db.history.Logs.Chunk = json.RawMessage("[]") + db.history.Logs.Source.Name = fi.Name() + db.history.Logs.Chunk = emptyChunk db.lock.Unlock() case err := <-watcher.Errors: if err != nil { log.Warn("Fs watcher error", "err", err) } - return - case errc := <-db.quit: - errc <- nil - return - // Send log updates to the client. - case <-ticker.C: + case <-ticker.C: // Send log updates to the client. if opened == nil { log.Warn("The last log file is not opened") - return + break loop } - // Read the new logs created since the last read. chunk, err := ioutil.ReadAll(opened) if err != nil { log.Warn("Failed to read file", "name", opened.Name(), "err", err) - return + break loop } - b := make([]byte, len(buf)+len(chunk)) - copy(b, buf) - copy(b[len(buf):], chunk) + b := append(buf, chunk...) - last := replaceNewLinesWithCommas(b) + chunk, last := prepLogs(b) if last < 0 { break } // Only keep the invalid part of the buffer, which can be valid after the next read. buf = b[last+1:] - msg := embrace(b[:last]) var l *LogsMessage // Update the history. db.lock.Lock() - if len(db.history.Logs.Chunk) == 2 { - db.history.Logs.Chunk = msg + if bytes.Equal(db.history.Logs.Chunk, emptyChunk) { + db.history.Logs.Chunk = chunk l = deepcopy.Copy(db.history.Logs).(*LogsMessage) } else { - b = make([]byte, len(db.history.Logs.Chunk)+len(msg)-1) + b = make([]byte, len(db.history.Logs.Chunk)+len(chunk)-1) copy(b, db.history.Logs.Chunk) b[len(db.history.Logs.Chunk)-1] = ',' - copy(b[len(db.history.Logs.Chunk):], msg[1:]) + copy(b[len(db.history.Logs.Chunk):], chunk[1:]) db.history.Logs.Chunk = b - l = &LogsMessage{Chunk: msg} + l = &LogsMessage{Chunk: chunk} } db.lock.Unlock() db.sendToAll(&Message{Logs: l}) + case errc = <-db.quit: + break loop } } } diff --git a/dashboard/message.go b/dashboard/message.go index 4a5e4f971b..46856b9e6e 100644 --- a/dashboard/message.go +++ b/dashboard/message.go @@ -70,17 +70,19 @@ type SystemMessage struct { DiskWrite ChartEntries `json:"diskWrite,omitempty"` } +// LogsMessage wraps up a log chunk. If Source isn't present, the chunk is a stream chunk. type LogsMessage struct { - Old *LogFile `json:"old,omitempty"` // Attributes of the log file. - Chunk json.RawMessage `json:"chunk"` // Contains log records. + Source *LogFile `json:"source,omitempty"` // Attributes of the log file. + Chunk json.RawMessage `json:"chunk"` // Contains log records. } +// LogFile contains the attributes of a log file. type LogFile struct { Name string `json:"name"` // The name of the file. - Past bool `json:"past"` // Denotes if the file is the previous or the next one. - Last bool `json:"last"` // Denotes if there isn't more file. + Last bool `json:"last"` // Denotes if the actual log file is the last one in the directory. } +// Request represents the client request. type Request struct { Logs *LogsRequest `json:"logs,omitempty"` } diff --git a/internal/debug/flags.go b/internal/debug/flags.go index c782abd0f0..7d7eba98a7 100644 --- a/internal/debug/flags.go +++ b/internal/debug/flags.go @@ -112,18 +112,19 @@ func init() { // Setup initializes profiling and logging based on the CLI flags. // It should be called as early as possible in the program. -func Setup(ctx *cli.Context, disklogs string) error { +func Setup(ctx *cli.Context, logdir string) error { // logging log.PrintOrigins(ctx.GlobalBool(debugFlag.Name)) - if disklogs != "" { - glogger.SetHandler(log.MultiHandler( - ostream, - log.RotatingFileHandler( - disklogs, - 262144, - log.JsonFormatOrderedCtx(false, true), - ), - )) + if logdir != "" { + rfh, err := log.RotatingFileHandler( + logdir, + 262144, + log.JSONFormatOrderedEx(false, true), + ) + if err != nil { + return err + } + glogger.SetHandler(log.MultiHandler(ostream, rfh)) } glogger.Verbosity(log.Lvl(ctx.GlobalInt(verbosityFlag.Name))) glogger.Vmodule(ctx.GlobalString(vmoduleFlag.Name)) diff --git a/log/format.go b/log/format.go index 69d0953232..7902b296e6 100644 --- a/log/format.go +++ b/log/format.go @@ -202,16 +202,16 @@ func JSONFormat() Format { return JSONFormatEx(false, true) } -// JsonFormatOrderedCtx is similar to JsonFormatEx, except instead of a map this creates an array out of the ctx -// in order to keep the original order. -func JsonFormatOrderedCtx(pretty, lineSeparated bool) Format { +// JSONFormatOrderedEx formats log records as JSON arrays. If pretty is true, +// records will be pretty-printed. If lineSeparated is true, records +// will be logged with a new line between each record. +func JSONFormatOrderedEx(pretty, lineSeparated bool) Format { jsonMarshal := json.Marshal if pretty { jsonMarshal = func(v interface{}) ([]byte, error) { return json.MarshalIndent(v, "", " ") } } - return FormatFunc(func(r *Record) []byte { props := make(map[string]interface{}) @@ -226,7 +226,6 @@ func JsonFormatOrderedCtx(pretty, lineSeparated bool) Format { props[errorKey] = fmt.Sprintf("%+v is not a string key,", r.Ctx[i]) } ctx[i] = k - // TODO (kurkomisi): display hash fields entirely - possibly logger independently ctx[i+1] = formatLogfmtValue(r.Ctx[i+1], true) } props[r.KeyNames.Ctx] = ctx @@ -238,11 +237,9 @@ func JsonFormatOrderedCtx(pretty, lineSeparated bool) Format { }) return b } - if lineSeparated { b = append(b, '\n') } - return b }) } diff --git a/log/handler.go b/log/handler.go index cab03b6a92..62480922ce 100644 --- a/log/handler.go +++ b/log/handler.go @@ -74,92 +74,100 @@ func FileHandler(path string, fmtr Format) (Handler, error) { return closingHandler{f, StreamHandler(f, fmtr)}, nil } -type writeCounter struct { - w io.Writer - count uint +// countingWriter wraps a WriteCloser object in order to count the written bytes. +type countingWriter struct { + w io.WriteCloser // the wrapped object + count uint // number of bytes written } -func (w *writeCounter) Write(p []byte) (n int, err error) { +// Write increments the byte counter by the number of bytes written. +// Implements the WriteCloser interface. +func (w *countingWriter) Write(p []byte) (n int, err error) { n, err = w.w.Write(p) w.count += uint(n) return n, err } +// Close implements the WriteCloser interface. +func (w *countingWriter) Close() error { + return w.w.Close() +} + +// prepFile opens the log file at the given path, and cuts off the invalid part +// from the end, because the previous execution could have been finished by interruption. +// Assumes that every line ended by '\n' contains a valid log record. +func prepFile(path string) (*countingWriter, error) { + f, err := os.OpenFile(path, os.O_RDWR|os.O_APPEND, 0600) + if err != nil { + return nil, err + } + _, err = f.Seek(-1, io.SeekEnd) + if err != nil { + return nil, err + } + buf := make([]byte, 1) + var cut int64 + for { + if _, err := f.Read(buf); err != nil { + return nil, err + } + if buf[0] == '\n' { + break + } + if _, err = f.Seek(-2, io.SeekCurrent); err != nil { + return nil, err + } + cut++ + } + fi, err := f.Stat() + if err != nil { + return nil, err + } + ns := fi.Size() - cut + if err = f.Truncate(ns); err != nil { + return nil, err + } + return &countingWriter{w: f, count: uint(ns)}, nil +} + // RotatingFileHandler returns a handler which writes log records to file chunks // at the given path. When a file's size reaches the limit, the handler creates // a new file named after the timestamp of the first log record it will contain. -func RotatingFileHandler(path string, limit uint, formatter Format) Handler { - if err := os.MkdirAll(path, 0755); err != nil { - panic(err) +func RotatingFileHandler(path string, limit uint, formatter Format) (Handler, error) { + if err := os.MkdirAll(path, 0700); err != nil { + return nil, err } files, err := ioutil.ReadDir(path) if err != nil { - panic(err) + return nil, err + } + re := regexp.MustCompile("\\.log$") + last := len(files) - 1 + for last >= 0 && (!files[last].Mode().IsRegular() || !re.MatchString(files[last].Name())) { + last-- + } + var counter *countingWriter + if last >= 0 && files[last].Size() < int64(limit){ + // Open the last file, and continue to write into it until it's size reaches the limit. + if counter, err = prepFile(filepath.Join(path, files[last].Name())); err != nil { + return nil, err + } + } + if counter == nil { + counter = new(countingWriter) } - counter := new(writeCounter) h := StreamHandler(counter, formatter) - re := regexp.MustCompile(".log$") - var i int - for i = len(files) - 1; i >= 0 && (!files[i].Mode().IsRegular() || !re.Match([]byte(files[i].Name()))); i-- { - } - if i >= 0 { - // Open the last file, and continue to write into it until it's size reaches the limit. - last := files[i] - if last.Size() >= int64(limit) { - goto createNew - } - f, err := os.OpenFile(filepath.Join(path, last.Name()), os.O_RDWR|os.O_APPEND, 0644) - if err != nil { - goto createNew - } - // The previous execution could have been finished by interruption, in this case cut the invalid - // record from the end. Assume that every line ended by '\n' contains a valid log record. - bufSize := int64(100) - buf := make([]byte, bufSize) - cut := bufSize - if _, err = f.Seek(-bufSize, 2); err != nil { - goto createNew - } - n, err := f.Read(buf) - for err == nil { - for ; n > 0 && buf[n-1] != '\n'; n-- { - } - if n > 0 { - break - } - if _, err = f.Seek(-2*bufSize, 1); err != nil { - break - } - cut += bufSize - n, err = f.Read(buf) - } - if err != nil { - goto createNew - } - cut -= int64(n) - - ns := last.Size() - cut - if err = f.Truncate(ns); err != nil { - goto createNew - } - counter.w = f - counter.count = uint(ns) - } -createNew: - return FuncHandler(func(r *Record) error { - if counter.count > limit || counter.w == nil { - // TODO (kurkomisi): close the last file too. - if f, ok := counter.w.(*os.File); ok { - if err := f.Close(); err != nil { - return err - } - } + if counter.count > limit { + counter.Close() + counter.w = nil + } + if counter.w == nil { f, err := os.OpenFile( filepath.Join(path, fmt.Sprintf("%s.log", strings.Replace(r.Time.Format("060102150405.00"), ".", "", 1))), os.O_CREATE|os.O_APPEND|os.O_WRONLY, - 0644, + 0600, ) if err != nil { return err @@ -168,7 +176,7 @@ createNew: counter.count = 0 } return h.Log(r) - }) + }), nil } // NetHandler opens a socket to the given address and writes records