util/log: timezone support for formats crdb-v1 and crdb-v2

Release note (cli change): The log output formats `crdb-v1` and
`crdb-v2` now support the format option `timezone`. When specified,
the corresponding time zone is used to produce the timestamp column.

For example:
```yaml
file-defaults:
   format: crdb-v2
   format-options: {timezone: america/new_york}
```

Example logging output:
```
I230606 12:43:01.553407-040000 1 1@cli/start.go:575 ⋮ [n?] 4  soft memory limit of Go runtime is set to 35 GiB
                       ^^^^^^^ indicates GMT-4 was used.
```

The timezone offset is also always included in the format if it is not
zero (e.g. for non-UTC time zones). This is necessary to ensure that
the times can be read back precisely.

Release note (cli change): The command `cockroach debug merge-log` was
adapted to understand time zones in input files read with format
`crdb-v1` or `crdb-v2`.

Release note (backward-incompatible change): When a deployment is
configured to use a time zone (new feature) for log file output using
formats `crdb-v1` or `crdb-v2`, it becomes impossible to process the
new output log files using the `cockroach debug merge-log` command
from a previous version. The newest `cockroach debug merge-log` code
must be used instead.

docs/generated/logformats.md

@@ -112,6 +112,7 @@ Additional options recognized via `format-options`:
 |--------|-------------|
 | `show-counter` | Whether to include the counter column in the line header. Without it, the format may be ambiguous due to the optionality of tags. |
 | `colors` | The color profile to use. Possible values: none, auto, ansi, 256color. Default is auto. |
+| `timezone` | The timezone to use for the timestamp column. The value can be any timezone name recognized by the Go standard library. Default is `UTC` |
 
 
 
@@ -271,6 +272,7 @@ Additional options recognized via `format-options`:
 | Option | Description |
 |--------|-------------|
 | `colors` | The color profile to use. Possible values: none, auto, ansi, 256color. Default is auto. |
+| `timezone` | The timezone to use for the timestamp column. The value can be any timezone name recognized by the Go standard library. Default is `UTC` |
 
 
 

pkg/util/flagutil/flagutil.go

@@ -25,6 +25,7 @@ import (
 // as described in time.Parse.
 var TimeFormats = []string{
 	log.MessageTimeFormat,
+	log.MessageTimeFormatWithTZ,
 	log.FileTimeFormat,
 	time.RFC3339Nano,
 	time.RFC3339,

pkg/util/log/format_crdb.go

@@ -29,6 +29,10 @@ const severityChar = "IWEF"
 // as used in time.Parse and time.Format.
 const MessageTimeFormat = "060102 15:04:05.999999"
 
+// MessageTimeFormatWithTZ is like MessageTimeFormat but with a numeric
+// time zone included.
+const MessageTimeFormatWithTZ = "060102 15:04:05.999999-070000"
+
 // FormatLegacyEntry writes the contents of the legacy log entry struct to the specified writer.
 func FormatLegacyEntry(e logpb.Entry, w io.Writer) error {
 	return FormatLegacyEntryWithOptionalColors(e, w, nil /* cp */)
@@ -37,7 +41,7 @@ func FormatLegacyEntry(e logpb.Entry, w io.Writer) error {
 // FormatLegacyEntryWithOptionalColors is like FormatLegacyEntry but the caller can specify
 // a color profile.
 func FormatLegacyEntryWithOptionalColors(e logpb.Entry, w io.Writer, cp ttycolor.Profile) error {
-	buf := formatLogEntryInternalV1(e, false /* isHeader */, true /* showCounter */, cp)
+	buf := formatLogEntryInternalV1(e, false /* isHeader */, true /* showCounter */, cp, nil /* loc */)
 	defer putBuffer(buf)
 	_, err := w.Write(buf.Bytes())
 	return err

pkg/util/log/format_crdb_v1.go

@@ -39,6 +39,10 @@ type formatCrdbV1 struct {
 	// colorProfileName is the name of the color profile, used for
 	// documentation purposes.
 	colorProfileName string
+	// loc is the time zone to use. When non-nil, it forces the
+	// presentation of a time zone specification after the time stamp.
+	// The corresponding code path is much slower.
+	loc *time.Location
 }
 
 func (f *formatCrdbV1) setOption(k string, v string) error {
@@ -74,6 +78,18 @@ func (f *formatCrdbV1) setOption(k string, v string) error {
 		f.colorProfileName = v
 		return nil
 
+	case "timezone":
+		l, err := timeutil.LoadLocation(v)
+		if err != nil {
+			return errors.Wrapf(err, "invalid timezone: %q", v)
+		}
+		if l == time.UTC {
+			// Avoid triggering the slow path in the entry formatter.
+			l = nil
+		}
+		f.loc = l
+		return nil
+
 	default:
 		return errors.Newf("unknown format option: %q", redact.Safe(k))
 	}
@@ -195,6 +211,7 @@ Additional options recognized via ` + "`format-options`" + `:
 |--------|-------------|
 | ` + "`show-counter`" + ` | Whether to include the counter column in the line header. Without it, the format may be ambiguous due to the optionality of tags. |
 | ` + "`colors`" + ` | The color profile to use. Possible values: none, auto, ansi, 256color. Default is auto. |
+| ` + "`timezone`" + ` | The timezone to use for the timestamp column. The value can be any timezone name recognized by the Go standard library. Default is ` + "`UTC`" + ` |
 
 `)
 
@@ -203,15 +220,15 @@ Additional options recognized via ` + "`format-options`" + `:
 
 func (f formatCrdbV1) formatEntry(entry logEntry) *buffer {
 	return formatLogEntryInternalV1(entry.convertToLegacy(),
-		entry.header, f.showCounter, f.colorProfile)
+		entry.header, f.showCounter, f.colorProfile, f.loc)
 }
 
 // formatEntryInternalV1 renders a log entry.
 // Log lines are colorized depending on severity.
 // It uses a newly allocated *buffer. The caller is responsible
 // for calling putBuffer() afterwards.
 func formatLogEntryInternalV1(
-	entry logpb.Entry, isHeader, showCounter bool, cp ttycolor.Profile,
+	entry logpb.Entry, isHeader, showCounter bool, cp ttycolor.Profile, loc *time.Location,
 ) *buffer {
 	buf := getBuffer()
 	if entry.Line < 0 {
@@ -233,33 +250,47 @@ func formatLogEntryInternalV1(
 		prefix = cp[ttycolor.Red]
 	}
 	n += copy(tmp, prefix)
-	// Avoid Fprintf, for speed. The format is so simple that we can do it quickly by hand.
-	// It's worth about 3X. Fprintf is hard.
-	now := timeutil.Unix(0, entry.Time)
-	year, month, day := now.Date()
-	hour, minute, second := now.Clock()
-	// Lyymmdd hh:mm:ss.uuuuuu file:line
 	tmp[n] = severityChar[entry.Severity-1]
 	n++
-	if year < 2000 {
-		year = 2000
+
+	if loc == nil {
+		// Default time zone (UTC).
+		// Avoid Fprintf, for speed. The format is so simple that we can do it quickly by hand.
+		// It's worth about 3X. Fprintf is hard.
+		now := timeutil.Unix(0, entry.Time)
+		year, month, day := now.Date()
+		hour, minute, second := now.Clock()
+		// Lyymmdd hh:mm:ss.uuuuuu file:line
+		if year < 2000 {
+			year = 2000
+		}
+		n += buf.twoDigits(n, year-2000)
+		n += buf.twoDigits(n, int(month))
+		n += buf.twoDigits(n, day)
+		n += copy(tmp[n:], cp[ttycolor.Gray]) // gray for time, file & line
+		tmp[n] = ' '
+		n++
+		n += buf.twoDigits(n, hour)
+		tmp[n] = ':'
+		n++
+		n += buf.twoDigits(n, minute)
+		tmp[n] = ':'
+		n++
+		n += buf.twoDigits(n, second)
+		tmp[n] = '.'
+		n++
+		n += buf.nDigits(6, n, now.Nanosecond()/1000, '0')
+	} else {
+		// Time zone was specified.
+		// Slooooow path.
+		buf.Write(tmp[:n])
+		n = 0
+		now := timeutil.Unix(0, entry.Time).In(loc)
+		buf.WriteString(now.Format("060102"))
+		buf.Write(cp[ttycolor.Gray])
+		buf.WriteByte(' ')
+		buf.WriteString(now.Format("15:04:05.000000-070000"))
 	}
-	n += buf.twoDigits(n, year-2000)
-	n += buf.twoDigits(n, int(month))
-	n += buf.twoDigits(n, day)
-	n += copy(tmp[n:], cp[ttycolor.Gray]) // gray for time, file & line
-	tmp[n] = ' '
-	n++
-	n += buf.twoDigits(n, hour)
-	tmp[n] = ':'
-	n++
-	n += buf.twoDigits(n, minute)
-	tmp[n] = ':'
-	n++
-	n += buf.twoDigits(n, second)
-	tmp[n] = '.'
-	n++
-	n += buf.nDigits(6, n, now.Nanosecond()/1000, '0')
 	tmp[n] = ' '
 	n++
 	if entry.Goroutine > 0 {
@@ -345,7 +376,7 @@ func formatLogEntryInternalV1(
 var entryREV1 = regexp.MustCompile(
 	`(?m)^` +
 		/* Severity         */ `([` + severityChar + `])` +
-		/* Date and time    */ `(\d{6} \d{2}:\d{2}:\d{2}.\d{6}) ` +
+		/* Date and time    */ `(\d{6} \d{2}:\d{2}:\d{2}.\d{6}(?:[---+]\d{6})?) ` +
 		/* Goroutine ID     */ `(?:(\d+) )?` +
 		/* Channel/File/Line*/ `([^:]+):(\d+) ` +
 		/* Redactable flag  */ `((?:` + redactableIndicator + `)?) ` +
@@ -380,7 +411,13 @@ func (d *entryDecoderV1) Decode(entry *logpb.Entry) error {
 		entry.Severity = Severity(strings.IndexByte(severityChar, m[1][0]) + 1)
 
 		// Process the timestamp.
-		t, err := time.Parse(MessageTimeFormat, string(m[2]))
+		ts := string(m[2])
+		timeFormat := MessageTimeFormat
+		if len(ts) > 7 && (ts[len(ts)-7] == '+' || ts[len(ts)-7] == '-') {
+			// The timestamp has a timezone offset.
+			timeFormat = MessageTimeFormatWithTZ
+		}
+		t, err := time.Parse(timeFormat, ts)
 		if err != nil {
 			return err
 		}

pkg/util/log/format_crdb_v1_test.go

@@ -42,6 +42,17 @@ func TestCrdbV1EncodeDecode(t *testing.T) {
 			}
 
 		case "entries":
+			var loc *time.Location
+			if arg, ok := td.Arg("tz"); ok {
+				var err error
+				var tz string
+				arg.Scan(t, 0, &tz)
+				loc, err = timeutil.LoadLocation(tz)
+				if err != nil {
+					td.Fatalf(t, "invalid tz: %v", err)
+				}
+			}
+
 			var inputEntries []logpb.Entry
 			for _, line := range strings.Split(td.Input, "\n") {
 				entry := templateEntry
@@ -54,7 +65,9 @@ func TestCrdbV1EncodeDecode(t *testing.T) {
 			var buf bytes.Buffer
 			// Encode.
 			for _, entry := range inputEntries {
-				_ = FormatLegacyEntry(entry, &buf)
+				lbuf := formatLogEntryInternalV1(entry, false /* header */, true /* showCounter */, nil /* colorProfile */, loc)
+				buf.Write(lbuf.Bytes())
+				putBuffer(lbuf)
 			}
 			// Decode.
 			entryStr := buf.String()

pkg/util/log/format_crdb_v2.go

@@ -47,6 +47,10 @@ type formatCrdbV2 struct {
 	// colorProfileName is the name of the color profile, used for
 	// documentation purposes.
 	colorProfileName string
+	// loc is the time zone to use. When non-nil, it forces the
+	// presentation of a time zone specification after the time stamp.
+	// The corresponding code path is much slower.
+	loc *time.Location
 }
 
 func (f *formatCrdbV2) setOption(k string, v string) error {
@@ -69,6 +73,18 @@ func (f *formatCrdbV2) setOption(k string, v string) error {
 		f.colorProfileName = v
 		return nil
 
+	case "timezone":
+		l, err := timeutil.LoadLocation(v)
+		if err != nil {
+			return errors.Wrapf(err, "invalid timezone: %q", v)
+		}
+		if l == time.UTC {
+			// Avoid triggering the slow path in the entry formatter.
+			l = nil
+		}
+		f.loc = l
+		return nil
+
 	default:
 		return errors.Newf("unknown format option: %q", redact.Safe(k))
 	}
@@ -226,6 +242,7 @@ Additional options recognized via ` + "`format-options`" + `:
 | Option | Description |
 |--------|-------------|
 | ` + "`colors`" + ` | The color profile to use. Possible values: none, auto, ansi, 256color. Default is auto. |
+| ` + "`timezone`" + ` | The timezone to use for the timestamp column. The value can be any timezone name recognized by the Go standard library. Default is ` + "`UTC`" + ` |
 
 `)
 
@@ -258,33 +275,47 @@ func (f formatCrdbV2) formatEntry(entry logEntry) *buffer {
 		prefix = cp[ttycolor.Red]
 	}
 	n += copy(tmp, prefix)
-	// Avoid Fprintf, for speed. The format is so simple that we can do it quickly by hand.
-	// It's worth about 3X. Fprintf is hard.
-	now := timeutil.Unix(0, entry.ts)
-	year, month, day := now.Date()
-	hour, minute, second := now.Clock()
 	// Lyymmdd hh:mm:ss.uuuuuu file:line
 	tmp[n] = severityChar[entry.sev-1]
 	n++
-	if year < 2000 {
-		year = 2000
+
+	if f.loc == nil {
+		// Default time zone (UTC).
+		// Avoid Fprintf, for speed. The format is so simple that we can do it quickly by hand.
+		// It's worth about 3X. Fprintf is hard.
+		now := timeutil.Unix(0, entry.ts)
+		year, month, day := now.Date()
+		hour, minute, second := now.Clock()
+		if year < 2000 {
+			year = 2000
+		}
+		n += buf.twoDigits(n, year-2000)
+		n += buf.twoDigits(n, int(month))
+		n += buf.twoDigits(n, day)
+		n += copy(tmp[n:], cp[ttycolor.Gray]) // gray for time, file & line
+		tmp[n] = ' '
+		n++
+		n += buf.twoDigits(n, hour)
+		tmp[n] = ':'
+		n++
+		n += buf.twoDigits(n, minute)
+		tmp[n] = ':'
+		n++
+		n += buf.twoDigits(n, second)
+		tmp[n] = '.'
+		n++
+		n += buf.nDigits(6, n, now.Nanosecond()/1000, '0')
+	} else {
+		// Time zone was specified.
+		// Slooooow path.
+		buf.Write(tmp[:n])
+		n = 0
+		now := timeutil.Unix(0, entry.ts).In(f.loc)
+		buf.WriteString(now.Format("060102"))
+		buf.Write(cp[ttycolor.Gray])
+		buf.WriteByte(' ')
+		buf.WriteString(now.Format("15:04:05.000000-070000"))
 	}
-	n += buf.twoDigits(n, year-2000)
-	n += buf.twoDigits(n, int(month))
-	n += buf.twoDigits(n, day)
-	n += copy(tmp[n:], cp[ttycolor.Gray]) // gray for time, file & line
-	tmp[n] = ' '
-	n++
-	n += buf.twoDigits(n, hour)
-	tmp[n] = ':'
-	n++
-	n += buf.twoDigits(n, minute)
-	tmp[n] = ':'
-	n++
-	n += buf.twoDigits(n, second)
-	tmp[n] = '.'
-	n++
-	n += buf.nDigits(6, n, now.Nanosecond()/1000, '0')
 	tmp[n] = ' '
 	n++
 	n += buf.someDigits(n, int(entry.gid))
@@ -520,7 +551,7 @@ var (
 	entryREV2 = regexp.MustCompile(
 		`(?m)^` +
 			/* Severity                 */ `(?P<severity>[` + severityChar + `])` +
-			/* Date and time            */ `(?P<datetime>\d{6} \d{2}:\d{2}:\d{2}.\d{6}) ` +
+			/* Date and time            */ `(?P<datetime>\d{6} \d{2}:\d{2}:\d{2}.\d{6}(?:[---+]\d{6})?) ` +
 			/* Goroutine ID             */ `(?:(?P<goroutine>\d+) )` +
 			/* Go standard library flag */ `(\(gostd\) )?` +
 			/* Channel                  */ `(?:(?P<channel>\d+)@)?` +
@@ -714,7 +745,13 @@ func (f entryDecoderV2Fragment) getGoroutine() int64 {
 }
 
 func (f entryDecoderV2Fragment) getTimestamp() (unixNano int64) {
-	t, err := time.Parse(MessageTimeFormat, string(f[v2DateTimeIdx]))
+	ts := string(f[v2DateTimeIdx])
+	timeFormat := MessageTimeFormat
+	if len(ts) > 7 && (ts[len(ts)-7] == '+' || ts[len(ts)-7] == '-') {
+		// The timestamp has a timezone offset.
+		timeFormat = MessageTimeFormatWithTZ
+	}
+	t, err := time.Parse(timeFormat, ts)
 	if err != nil {
 		panic(err)
 	}