Merge pull request cockroachdb#8977 from petermattis/pmattis/log-goid

log: output the goroutine ID in log message headers

GLOCKFILE

@@ -88,6 +88,7 @@ github.com/opentracing/basictracer-go c7c0202a8a77f658aeb2193a27b6c0cfcc821038
 github.com/opentracing/opentracing-go 855519783f479520497c6b3445611b05fc42f009
 github.com/pborman/uuid c55201b036063326c5b1b89ccfe45a184973d073
 github.com/peterbourgon/g2s 5767a0b2078638d14800683fd0fe425604883f63
+github.com/petermattis/goid 208e1c5be6bf38853827abdc6290b5f6a0c404d5
 github.com/pkg/errors a22138067af1c4942683050411a841ade67fe1eb
 github.com/prometheus/client_model fa8ad6fec33561be4280a8f0514318c79d7f6cb6
 github.com/prometheus/common ebdfc6da46522d58825777cf1f90490a5b1ef1d8

ui/Makefile

@@ -54,10 +54,10 @@ JSPM_TARGET      = build/app.js
 GOBINDATA_TARGET = embedded.go
 
 .PHONY: all
-all: protobuf lint test $(GOBINDATA_TARGET)
+all: lint test $(GOBINDATA_TARGET)
 
-.PHONY: protobuf
-protobuf:
+# TODO(tamird): is there a way to not repeat this here? It's already in protobuf.mk
+app/js/protos.js generated/protos.json generated/protos.d.ts: $(addprefix $(REPO_ROOT)/, $(sort $(shell cd $(REPO_ROOT) && git ls-files --exclude-standard --cached --others -- '*.proto')))
 	$(MAKE) -C $(ORG_ROOT) -f cockroach/build/protobuf.mk
 
 .PHONY: lint
@@ -66,7 +66,7 @@ lint: npm.installed typings.installed
 	tslint -c tslint.json $(shell find $(TS_ROOT) -name '*.tsx' -or -name '*.ts')
 
 .PHONY: test
-test: protobuf npm.installed typings.installed jspm.installed
+test: npm.installed typings.installed jspm.installed
 	karma start
 
 GOBINDATA_SOURCES = $(JSPM_TARGET) assets fonts favicon.ico apple-touch-icon.png release.html
@@ -96,7 +96,7 @@ npm.installed: package.json npm-shrinkwrap.json
 	npm install --no-progress
 	touch $@
 
-typings.installed: typings.json npm.installed
+typings.installed: generated/protos.d.ts typings.json npm.installed
 	typings install
 	typings prune
 	touch $@

ui/app/js/protos.js

@@ -96,6 +96,12 @@ module.exports = require("protobufjs").newBuilder({})['import']({
                                     "name": "time",
                                     "id": 2
                                 },
+                                {
+                                    "rule": "optional",
+                                    "type": "int64",
+                                    "name": "goroutine",
+                                    "id": 6
+                                },
                                 {
                                     "rule": "optional",
                                     "type": "string",

ui/generated/protos.d.ts

@@ -231,6 +231,15 @@ getTime?() : Long;
 
 
 
+goroutine?: Long;
+
+
+getGoroutine?() : Long;
+		setGoroutine?(goroutine : Long): void;
+
+
+
+
 file?: string;
 
 

ui/generated/protos.json

@@ -95,6 +95,12 @@
                                     "name": "time",
                                     "id": 2
                                 },
+                                {
+                                    "rule": "optional",
+                                    "type": "int64",
+                                    "name": "goroutine",
+                                    "id": 6
+                                },
                                 {
                                     "rule": "optional",
                                     "type": "string",

util/log/clog.go

@@ -38,6 +38,7 @@ import (
 	"github.com/cockroachdb/cockroach/build"
 	"github.com/cockroachdb/cockroach/util/caller"
 	"github.com/cockroachdb/cockroach/util/syncutil"
+	"github.com/petermattis/goid"
 )
 
 // Severity identifies the sort of log: info, warning etc. It also implements
@@ -377,7 +378,7 @@ func (t *traceLocation) Set(value string) error {
 }
 
 var entryRE = regexp.MustCompile(
-	`(?m)^([IWEF])(\d{6} \d{2}:\d{2}:\d{2}.\d{6}) ([^:]+):(\d+)  (.*)`)
+	`(?m)^([IWEF])(\d{6} \d{2}:\d{2}:\d{2}.\d{6}) (?:(\d+) )?([^:]+):(\d+)  (.*)`)
 
 // EntryDecoder reads successive encoded log entries from the input
 // buffer. Each entry is preceded by a single big-ending uint32
@@ -413,13 +414,20 @@ func (d *EntryDecoder) Decode(entry *Entry) error {
 			return err
 		}
 		entry.Time = t.UnixNano()
-		entry.File = string(m[3])
-		line, err := strconv.Atoi(string(m[4]))
+		if len(m[3]) > 0 {
+			goroutine, err := strconv.Atoi(string(m[3]))
+			if err != nil {
+				return err
+			}
+			entry.Goroutine = int64(goroutine)
+		}
+		entry.File = string(m[4])
+		line, err := strconv.Atoi(string(m[5]))
 		if err != nil {
 			return err
 		}
 		entry.Line = int64(line)
-		entry.Message = string(m[5])
+		entry.Message = string(m[6])
 		return nil
 	}
 }
@@ -455,17 +463,18 @@ type flushSyncWriter interface {
 // line number. Log lines are colorized depending on severity.
 //
 // Log lines have this form:
-// 	Lyymmdd hh:mm:ss.uuuuuu file:line] msg...
+// 	Lyymmdd hh:mm:ss.uuuuuu goid file:line msg...
 // where the fields are defined as follows:
 // 	L                A single character, representing the log level (eg 'I' for INFO)
 // 	yy               The year (zero padded; ie 2016 is '16')
 // 	mm               The month (zero padded; ie May is '05')
 // 	dd               The day (zero padded)
 // 	hh:mm:ss.uuuuuu  Time in hours, minutes and fractional seconds
+// 	goid             The goroutine id (omitted if zero for use by tests)
 // 	file             The file name
 // 	line             The line number
 // 	msg              The user-supplied message
-func formatHeader(s Severity, now time.Time, file string, line int, colors *colorProfile) *buffer {
+func formatHeader(s Severity, now time.Time, gid int, file string, line int, colors *colorProfile) *buffer {
 	buf := logging.getBuffer()
 	if line < 0 {
 		line = 0 // not a real line number, but acceptable to someDigits
@@ -515,6 +524,11 @@ func formatHeader(s Severity, now time.Time, file string, line int, colors *colo
 	n += buf.nDigits(6, n, now.Nanosecond()/1000, '0')
 	tmp[n] = ' '
 	n++
+	if gid > 0 {
+		n += buf.someDigits(n, gid)
+		tmp[n] = ' '
+		n++
+	}
 	buf.Write(tmp[:n])
 	buf.WriteString(file)
 	tmp[0] = ':'
@@ -578,7 +592,7 @@ func (buf *buffer) someDigits(i, d int) int {
 
 func formatLogEntry(entry Entry, stacks []byte, colors *colorProfile) *buffer {
 	buf := formatHeader(entry.Severity, time.Unix(0, entry.Time),
-		entry.File, int(entry.Line), colors)
+		int(entry.Goroutine), entry.File, int(entry.Line), colors)
 	_, _ = buf.WriteString(entry.Message)
 	if buf.Bytes()[buf.Len()-1] != '\n' {
 		_ = buf.WriteByte('\n')
@@ -714,11 +728,12 @@ func (l *loggingT) outputLogEntry(s Severity, file string, line int, msg string)
 	// Set additional details in log entry.
 	now := time.Now()
 	entry := Entry{
-		Severity: s,
-		Time:     now.UnixNano(),
-		File:     file,
-		Line:     int64(line),
-		Message:  msg,
+		Severity:  s,
+		Time:      now.UnixNano(),
+		Goroutine: goid.Get(),
+		File:      file,
+		Line:      int64(line),
+		Message:   msg,
 	}
 	// On fatal log, set all stacks.
 	var stacks []byte
@@ -949,14 +964,15 @@ func (sb *syncBuffer) rotateFile(now time.Time) error {
 		fmt.Sprintf("[config] running on machine: %s\n", host),
 		fmt.Sprintf("[config] binary: %s\n", build.GetInfo().Short()),
 		fmt.Sprintf("[config] arguments: %s\n", os.Args),
-		fmt.Sprintf("line format: [IWEF]yymmdd hh:mm:ss.uuuuuu file:line msg\n"),
+		fmt.Sprintf("line format: [IWEF]yymmdd hh:mm:ss.uuuuuu goid file:line msg\n"),
 	} {
 		buf := formatLogEntry(Entry{
-			Severity: sb.sev,
-			Time:     now.UnixNano(),
-			File:     f,
-			Line:     int64(l),
-			Message:  msg,
+			Severity:  sb.sev,
+			Time:      now.UnixNano(),
+			Goroutine: goid.Get(),
+			File:      f,
+			Line:      int64(l),
+			Message:   msg,
 		}, nil, nil)
 		var n int
 		n, err = sb.file.Write(buf.Bytes())

util/log/clog_test.go

@@ -136,8 +136,8 @@ func TestStandardLog(t *testing.T) {
 
 // Verify that a log can be fetched in JSON format.
 func TestEntryDecoder(t *testing.T) {
-	formatEntry := func(s Severity, now time.Time, file string, line int, msg string) string {
-		buf := formatHeader(s, now, file, line, nil)
+	formatEntry := func(s Severity, now time.Time, gid int, file string, line int, msg string) string {
+		buf := formatHeader(s, now, gid, file, line, nil)
 		buf.WriteString(msg)
 		buf.WriteString("\n")
 		defer logging.putBuffer(buf)
@@ -149,10 +149,10 @@ func TestEntryDecoder(t *testing.T) {
 	t3 := t2.Add(time.Microsecond)
 	t4 := t3.Add(time.Microsecond)
 
-	contents := formatEntry(InfoLog, t1, "clog_test.go", 136, "info")
-	contents += formatEntry(WarningLog, t2, "clog_test.go", 137, "warning")
-	contents += formatEntry(ErrorLog, t3, "clog_test.go", 138, "error")
-	contents += formatEntry(FatalLog, t4, "clog_test.go", 139, "fatal")
+	contents := formatEntry(InfoLog, t1, 0, "clog_test.go", 136, "info")
+	contents += formatEntry(WarningLog, t2, 1, "clog_test.go", 137, "warning")
+	contents += formatEntry(ErrorLog, t3, 2, "clog_test.go", 138, "error")
+	contents += formatEntry(FatalLog, t4, 3, "clog_test.go", 139, "fatal")
 
 	readAllEntries := func(contents string) []Entry {
 		decoder := NewEntryDecoder(strings.NewReader(contents))
@@ -173,32 +173,36 @@ func TestEntryDecoder(t *testing.T) {
 	entries := readAllEntries(contents)
 	expected := []Entry{
 		{
-			Severity: 0,
-			Time:     t1.UnixNano(),
-			File:     `clog_test.go`,
-			Line:     136,
-			Message:  `info`,
+			Severity:  0,
+			Time:      t1.UnixNano(),
+			Goroutine: 0,
+			File:      `clog_test.go`,
+			Line:      136,
+			Message:   `info`,
 		},
 		{
-			Severity: 1,
-			Time:     t2.UnixNano(),
-			File:     `clog_test.go`,
-			Line:     137,
-			Message:  `warning`,
+			Severity:  1,
+			Time:      t2.UnixNano(),
+			Goroutine: 1,
+			File:      `clog_test.go`,
+			Line:      137,
+			Message:   `warning`,
 		},
 		{
-			Severity: 2,
-			Time:     t3.UnixNano(),
-			File:     `clog_test.go`,
-			Line:     138,
-			Message:  `error`,
+			Severity:  2,
+			Time:      t3.UnixNano(),
+			Goroutine: 2,
+			File:      `clog_test.go`,
+			Line:      138,
+			Message:   `error`,
 		},
 		{
-			Severity: 3,
-			Time:     t4.UnixNano(),
-			File:     `clog_test.go`,
-			Line:     139,
-			Message:  `fatal`,
+			Severity:  3,
+			Time:      t4.UnixNano(),
+			Goroutine: 3,
+			File:      `clog_test.go`,
+			Line:      139,
+			Message:   `fatal`,
 		},
 	}
 	if !reflect.DeepEqual(expected, entries) {
@@ -588,7 +592,7 @@ func TestFatalStacktraceStderr(t *testing.T) {
 
 func BenchmarkHeader(b *testing.B) {
 	for i := 0; i < b.N; i++ {
-		buf := formatHeader(InfoLog, time.Now(), "file.go", 100, nil)
+		buf := formatHeader(InfoLog, time.Now(), 200, "file.go", 100, nil)
 		logging.putBuffer(buf)
 	}
 }