Skip to content

Commit af8fabb

Browse files
author
Andrew Werner
committed
cli: improve usability of debug merge-logs flags
Before this change, `debug merge-logs` was only useful with log files which use the default naming convention. As @tbg has pointed out, cockroachdb log files often carry different naming conventions. The coupling to the default log file name format came in two places, the policy for which files to examine and the rendering of a message prefix based on file name information. For the format we used to reject all files which failed filename parsing in util/log. This change adds a new `file-pattern` flag which defaults to the log package's format. To match on all files passed to the command, one might use '.*' as their file-pattern. Secondly, we used to render a text/template over log.FileInfo, now instead we use regular expression expansion and named capture groups from the file-pattern to create the message prefix. This is ultimately a more flexible approach which shows its worth in an upcoming commit that allows useful prefix information to be included in a merged stream of logs from a local roachprod cluster even though the FileInfo does not contain any useful differentiating information. Fixes #32919 Release note: None
1 parent 92f5727 commit af8fabb

8 files changed

Lines changed: 170 additions & 143 deletions

File tree

‎pkg/cli/debug.go‎

Lines changed: 47 additions & 67 deletions
Original file line numberDiff line numberDiff line change
@@ -29,7 +29,6 @@ import (
2929
"sort"
3030
"strconv"
3131
"strings"
32-
"text/template"
3332
"time"
3433

3534
"github.com/cockroachdb/cockroach/pkg/cli/debug"
@@ -51,6 +50,7 @@ import (
5150
"github.com/cockroachdb/cockroach/pkg/ts/tspb"
5251
"github.com/cockroachdb/cockroach/pkg/util/encoding"
5352
"github.com/cockroachdb/cockroach/pkg/util/envutil"
53+
"github.com/cockroachdb/cockroach/pkg/util/flagutil"
5454
"github.com/cockroachdb/cockroach/pkg/util/hlc"
5555
"github.com/cockroachdb/cockroach/pkg/util/humanizeutil"
5656
"github.com/cockroachdb/cockroach/pkg/util/log"
@@ -1253,77 +1253,26 @@ efficient time filtering as well as multiline regexp pattern matching via flags.
12531253
RunE: runDebugMergeLogs,
12541254
}
12551255

1256+
var debugMergeLogsOpts = struct {
1257+
from time.Time
1258+
to time.Time
1259+
filter *regexp.Regexp
1260+
program *regexp.Regexp
1261+
file *regexp.Regexp
1262+
prefix string
1263+
}{
1264+
program: regexp.MustCompile("^cockroach$"),
1265+
file: regexp.MustCompile(log.FilePattern),
1266+
}
1267+
12561268
func runDebugMergeLogs(cmd *cobra.Command, args []string) error {
1257-
from, to, filter, program, prefix, err := parseDebugMergeLogsArgs(cmd)
1258-
if err != nil {
1259-
return err
1260-
}
1269+
o := debugMergeLogsOpts
12611270
s, err := newMergedStreamFromPatterns(context.Background(),
1262-
args, program, from, to)
1271+
args, o.file, o.program, o.from, o.to)
12631272
if err != nil {
12641273
return err
12651274
}
1266-
return writeLogStream(s, cmd.OutOrStdout(), filter, prefix)
1267-
}
1268-
1269-
func parseDebugMergeLogsArgs(
1270-
cmd *cobra.Command,
1271-
) (from, to time.Time, filter, program *regexp.Regexp, prefix *template.Template, err error) {
1272-
if from, err = parseTime(cmd.Flag("from").Value.String()); err != nil {
1273-
err = errors.Errorf("failed to parse from: %v", err)
1274-
} else if to, err = parseTime(cmd.Flag("to").Value.String()); err != nil {
1275-
err = errors.Errorf("failed to parse to: %v", err)
1276-
} else if filter, err = parseRegexp(cmd, "filter"); err != nil {
1277-
err = errors.Errorf("failed to parse filter: %v", err)
1278-
} else if program, err = parseRegexp(cmd, "program"); err != nil {
1279-
err = errors.Errorf("failed to parse program: %v", err)
1280-
} else if prefix, err = template.New("prefix").
1281-
Parse(cmd.Flag("prefix").Value.String()); err != nil {
1282-
err = errors.Errorf("failed to compile prefix template: %v", err)
1283-
}
1284-
return
1285-
}
1286-
1287-
func parseTime(ts string) (time.Time, error) {
1288-
if ts == "" {
1289-
return time.Time{}, nil
1290-
}
1291-
t, err := time.Parse("060102 15:04:05.999999", ts)
1292-
if err != nil {
1293-
return t, errors.Errorf("failed to parse %s as time: %v", ts, err)
1294-
}
1295-
return t.UTC(), nil
1296-
}
1297-
1298-
func parseRegexp(cmd *cobra.Command, flagName string) (*regexp.Regexp, error) {
1299-
str := cmd.Flag(flagName).Value.String()
1300-
if str == "" {
1301-
return nil, nil
1302-
}
1303-
return regexp.Compile(str)
1304-
}
1305-
1306-
func init() {
1307-
DebugCmd.AddCommand(debugCmds...)
1308-
1309-
f := debugSyncBenchCmd.Flags()
1310-
f.IntVarP(&syncBenchOpts.Concurrency, "concurrency", "c", syncBenchOpts.Concurrency,
1311-
"number of concurrent writers")
1312-
f.DurationVarP(&syncBenchOpts.Duration, "duration", "d", syncBenchOpts.Duration,
1313-
"duration to run the test for")
1314-
f.BoolVarP(&syncBenchOpts.LogOnly, "log-only", "l", syncBenchOpts.LogOnly,
1315-
"only write to the WAL, not to sstables")
1316-
1317-
f = debugUnsafeRemoveDeadReplicasCmd.Flags()
1318-
f.IntSliceVar(&removeDeadReplicasOpts.deadStoreIDs, "dead-store-ids", nil,
1319-
"list of dead store IDs")
1320-
1321-
f = debugMergeLogsCommand.Flags()
1322-
f.String("from", "", "Time (in format \"060102 15:04:05.999999\") before which messages should be filtered.")
1323-
f.String("to", "", "Time (in format \"060102 15:04:05.999999\") after which messages should be filtered.")
1324-
f.String("filter", "", "If present acts as a regexp to filter log messages.")
1325-
f.String("prefix", "{{ .Details.Host }}> ", "Template pattern used a prefix to merged log messages. Evaluated on log.FileInfo")
1326-
f.String("program", "^cockroach$", "Regular expression used to select whether a program's log files should be read")
1275+
return writeLogStream(s, cmd.OutOrStdout(), o.filter, o.prefix)
13271276
}
13281277

13291278
// DebugCmdsForRocksDB lists debug commands that access rocksdb through the engine
@@ -1368,3 +1317,34 @@ process that has failed and cannot restart.
13681317
`,
13691318
RunE: usageAndErr,
13701319
}
1320+
1321+
func init() {
1322+
DebugCmd.AddCommand(debugCmds...)
1323+
1324+
f := debugSyncBenchCmd.Flags()
1325+
f.IntVarP(&syncBenchOpts.Concurrency, "concurrency", "c", syncBenchOpts.Concurrency,
1326+
"number of concurrent writers")
1327+
f.DurationVarP(&syncBenchOpts.Duration, "duration", "d", syncBenchOpts.Duration,
1328+
"duration to run the test for")
1329+
f.BoolVarP(&syncBenchOpts.LogOnly, "log-only", "l", syncBenchOpts.LogOnly,
1330+
"only write to the WAL, not to sstables")
1331+
1332+
f = debugUnsafeRemoveDeadReplicasCmd.Flags()
1333+
f.IntSliceVar(&removeDeadReplicasOpts.deadStoreIDs, "dead-store-ids", nil,
1334+
"list of dead store IDs")
1335+
1336+
f = debugMergeLogsCommand.Flags()
1337+
f.Var(flagutil.Time(&debugMergeLogsOpts.from), "from",
1338+
"time before which messages should be filtered")
1339+
f.Var(flagutil.Time(&debugMergeLogsOpts.to), "to",
1340+
"time after which messages should be filtered")
1341+
f.Var(flagutil.Regexp(&debugMergeLogsOpts.filter), "filter",
1342+
"re which filters log messages")
1343+
f.Var(flagutil.Regexp(&debugMergeLogsOpts.file), "file-pattern",
1344+
"re which filters log files based on path, also used with prefix and program-filter")
1345+
f.Var(flagutil.Regexp(&debugMergeLogsOpts.program), "program-filter",
1346+
"re which filter log files that operates on the capture group named \"program\" in file-pattern, "+
1347+
"if no such group exists, program-filter is ignored")
1348+
f.StringVar(&debugMergeLogsOpts.prefix, "prefix", "${host}> ",
1349+
"expansion template (see regexp.Expand) used as prefix to merged log messages evaluated on file-pattern")
1350+
}

‎pkg/cli/debug_merge_logs.go‎

Lines changed: 58 additions & 67 deletions
Original file line numberDiff line numberDiff line change
@@ -20,56 +20,47 @@ import (
2020
"bytes"
2121
"container/heap"
2222
"context"
23-
"fmt"
2423
"io"
2524
"os"
2625
"path/filepath"
2726
"regexp"
2827
"sort"
2928
"sync"
30-
"text/template"
3129
"time"
3230

3331
"github.com/cockroachdb/cockroach/pkg/util/log"
34-
"github.com/cockroachdb/cockroach/pkg/util/timeutil"
3532
"golang.org/x/sync/errgroup"
3633
)
3734

3835
type logStream interface {
39-
fileInfo() *log.FileInfo // FileInfo for the current entry available in peek.
36+
fileInfo() *fileInfo // FileInfo for the current entry available in peek.
4037
peek() (log.Entry, bool)
4138
pop() (log.Entry, bool) // If called after peek, must return the same values.
4239
error() error
4340
}
4441

4542
// writeLogStream pops messages off of s and writes them to out prepending
4643
// prefix per message and filtering messages which match filter.
47-
func writeLogStream(
48-
s logStream, out io.Writer, filter *regexp.Regexp, prefix *template.Template,
49-
) error {
44+
func writeLogStream(s logStream, out io.Writer, filter *regexp.Regexp, prefix string) error {
5045
const chanSize = 1 << 16 // 64k
5146
const maxWriteBufSize = 1 << 18 // 256kB
5247

53-
prefixCache := map[*log.FileInfo][]byte{}
54-
getPrefix := func(fi *log.FileInfo) ([]byte, error) {
48+
prefixCache := map[*fileInfo][]byte{}
49+
getPrefix := func(fi *fileInfo) ([]byte, error) {
5550
if prefixBuf, ok := prefixCache[fi]; ok {
5651
return prefixBuf, nil
5752
}
58-
var prefixBuf bytes.Buffer
59-
if err := prefix.Execute(&prefixBuf, fi); err != nil {
60-
return nil, err
61-
}
62-
prefixCache[fi] = prefixBuf.Bytes()
53+
prefixCache[fi] = fi.pattern.ExpandString(nil, prefix, fi.path, fi.matches)
6354
return prefixCache[fi], nil
6455
}
6556

6657
type entryInfo struct {
6758
log.Entry
68-
*log.FileInfo
59+
*fileInfo
6960
}
7061
render := func(ei entryInfo, w io.Writer) (err error) {
7162
var prefixBytes []byte
72-
if prefixBytes, err = getPrefix(ei.FileInfo); err != nil {
63+
if prefixBytes, err = getPrefix(ei.fileInfo); err != nil {
7364
return err
7465
}
7566
if _, err = w.Write(prefixBytes); err != nil {
@@ -85,7 +76,7 @@ func writeLogStream(
8576
defer close(entryChan)
8677
for e, ok := s.peek(); ok; e, ok = s.peek() {
8778
select {
88-
case entryChan <- entryInfo{Entry: e, FileInfo: s.fileInfo()}:
79+
case entryChan <- entryInfo{Entry: e, fileInfo: s.fileInfo()}:
8980
case <-ctx.Done():
9081
return nil
9182
}
@@ -146,22 +137,37 @@ type mergedStream []logStream
146137

147138
// newMergedStreamFromPatterns creates a new logStream by first glob
148139
// expanding pattern, then filtering for matching files which conform to the
149-
// log filename pattern and match the program. The returned stream will only
150-
// return log entries in [from, to].
140+
// filePattern and if program is non-nil, they match the program which is
141+
// extracted from matching files via the named capture group with the name
142+
// "program". The returned stream will only return log entries in [from, to].
143+
// If no program capture group exists all files match.
151144
func newMergedStreamFromPatterns(
152-
ctx context.Context, patterns []string, program *regexp.Regexp, from, to time.Time,
145+
ctx context.Context,
146+
patterns []string,
147+
filePattern, programFilter *regexp.Regexp,
148+
from, to time.Time,
153149
) (logStream, error) {
154150
paths, err := expandPatterns(patterns)
155151
if err != nil {
156152
return nil, err
157153
}
158-
files, err := findLogFiles(paths, program, to)
154+
files, err := findLogFiles(paths, filePattern, programFilter,
155+
groupIndex(filePattern, "program"), to)
159156
if err != nil {
160157
return nil, err
161158
}
162159
return newMergedStream(ctx, files, from, to)
163160
}
164161

162+
func groupIndex(re *regexp.Regexp, groupName string) int {
163+
for i, n := range re.SubexpNames() {
164+
if n == groupName {
165+
return i
166+
}
167+
}
168+
return -1
169+
}
170+
165171
func newMergedStream(
166172
ctx context.Context, files []fileInfo, from, to time.Time,
167173
) (*mergedStream, error) {
@@ -246,7 +252,7 @@ func (l *mergedStream) pop() (log.Entry, bool) {
246252
return e, true
247253
}
248254

249-
func (l *mergedStream) fileInfo() *log.FileInfo {
255+
func (l *mergedStream) fileInfo() *fileInfo {
250256
if len(*l) == 0 {
251257
return nil
252258
}
@@ -285,57 +291,43 @@ func removeDuplicates(strings []string) (filtered []string) {
285291
return filtered
286292
}
287293

288-
type parseLogFilenameError struct {
289-
path string
290-
err error
291-
}
292-
293-
func (e *parseLogFilenameError) Error() string {
294-
return fmt.Sprintf("failed to parse filename for %v: %v", e.path, e.err)
295-
}
296-
297-
func getLogFileInfo(path string) (fileInfo, error) {
298-
filename := filepath.Base(path)
299-
details, err := log.ParseLogFilename(filename)
300-
if err != nil {
301-
return fileInfo{}, &parseLogFilenameError{path: path, err: err}
302-
}
303-
fi, err := os.Stat(path)
304-
if err != nil {
305-
return fileInfo{}, err
294+
func getLogFileInfo(path string, filePattern *regexp.Regexp) (fileInfo, bool) {
295+
if matches := filePattern.FindStringSubmatchIndex(path); matches != nil {
296+
return fileInfo{path: path, matches: matches, pattern: filePattern}, true
306297
}
307-
return fileInfo{
308-
path: path,
309-
FileInfo: log.MakeFileInfo(details, fi),
310-
}, nil
298+
return fileInfo{}, false
311299
}
312300

313301
type fileInfo struct {
314-
path string
315-
log.FileInfo
302+
path string
303+
pattern *regexp.Regexp
304+
matches []int
316305
}
317306

318-
func findLogFiles(paths []string, program *regexp.Regexp, to time.Time) ([]fileInfo, error) {
319-
to = to.Truncate(time.Second) // Log files only have second resolution.
307+
func findLogFiles(
308+
paths []string, filePattern, programFilter *regexp.Regexp, programGroup int, to time.Time,
309+
) ([]fileInfo, error) {
310+
to = to.Truncate(time.Second) // log files only have second resolution
320311
fileChan := make(chan fileInfo, len(paths))
321-
var g errgroup.Group
322-
for i := range paths {
323-
p := paths[i]
324-
g.Go(func() error {
325-
fi, err := getLogFileInfo(p)
326-
if err == nil && program.MatchString(fi.Details.Program) {
327-
if to.IsZero() || timeutil.Unix(0, fi.Details.Time).Before(to) {
328-
fileChan <- fi
312+
var wg sync.WaitGroup
313+
wg.Add(len(paths))
314+
for _, p := range paths {
315+
go func(p string) {
316+
defer wg.Done()
317+
fi, ok := getLogFileInfo(p, filePattern)
318+
if !ok {
319+
return
320+
}
321+
if programGroup > 0 {
322+
program := fi.path[fi.matches[2*programGroup]:fi.matches[2*programGroup+1]]
323+
if !programFilter.MatchString(program) {
324+
return
329325
}
330-
} else if _, isParseErr := err.(*parseLogFilenameError); isParseErr {
331-
err = nil
332326
}
333-
return err
334-
})
335-
}
336-
if err := g.Wait(); err != nil {
337-
return nil, err
327+
fileChan <- fi
328+
}(p)
338329
}
330+
wg.Wait()
339331
files := make([]fileInfo, 0, len(fileChan))
340332
close(fileChan)
341333
for f := range fileChan {
@@ -393,7 +385,7 @@ func (bs *bufferedLogStream) run() {
393385

394386
func (bs *bufferedLogStream) peek() (log.Entry, bool) {
395387
if bs.ok && !bs.read {
396-
if bs.c == nil { // Indicates that run has not been called.
388+
if bs.c == nil { // indicates that run has not been called
397389
bs.runOnce.Do(bs.run)
398390
}
399391
bs.e, bs.ok = <-bs.c
@@ -431,7 +423,6 @@ type fileLogStream struct {
431423
// file is always closed before returning from this constructor so the initial
432424
// peek does not consume resources.
433425
func newFileLogStream(fi fileInfo, from, to time.Time) (logStream, error) {
434-
// we want to create the struct, do a peek, then close the file
435426
s := &fileLogStream{
436427
fi: fi,
437428
from: from,
@@ -511,8 +502,8 @@ func (s *fileLogStream) pop() (e log.Entry, ok bool) {
511502
return e, ok
512503
}
513504

514-
func (s *fileLogStream) fileInfo() *log.FileInfo { return &s.fi.FileInfo }
515-
func (s *fileLogStream) error() error { return s.err }
505+
func (s *fileLogStream) fileInfo() *fileInfo { return &s.fi }
506+
func (s *fileLogStream) error() error { return s.err }
516507

517508
// seekToFirstAfterFrom uses binary search to seek to an offset after all
518509
// entries which occur before from.

0 commit comments

Comments
 (0)