mirror of
https://github.com/zrepl/zrepl.git
synced 2024-11-29 11:55:03 +01:00
10a14a8c50
package trace:
- introduce the concept of tasks and spans, tracked as linked list within ctx
- see package-level docs for an overview of the concepts
- **main feature 1**: unique stack of task and span IDs
- makes it easy to follow a series of log entries in concurrent code
- **main feature 2**: ability to produce a chrome://tracing-compatible trace file
- either via an env variable or a `zrepl pprof` subcommand
- this is not a CPU profile, we already have go pprof for that
- but it is very useful to visually inspect where the
replication / snapshotter / pruner spends its time
( fixes #307 )
usage in package daemon/logging:
- goal: every log entry should have a trace field with the ID stack from package trace
- make `logging.GetLogger(ctx, Subsys)` the authoritative `logger.Logger` factory function
- the context carries a linked list of injected fields which
`logging.GetLogger` adds to the logger it returns
- `logging.GetLogger` also uses package `trace` to get the
task-and-span-stack and injects it into the returned logger's fields
87 lines
2.7 KiB
Go
87 lines
2.7 KiB
Go
package main
|
|
|
|
import (
|
|
"testing"
|
|
"time"
|
|
|
|
"github.com/stretchr/testify/require"
|
|
|
|
"github.com/zrepl/zrepl/daemon/logging"
|
|
)
|
|
|
|
func TestParseHumanFormatter(t *testing.T) {
|
|
|
|
type testCase struct {
|
|
Name string
|
|
Input string
|
|
Expect *RuntimeLine
|
|
ExpectErr string
|
|
}
|
|
|
|
secs := func(s string) time.Duration {
|
|
d, err := parseSecs(s)
|
|
require.NoError(t, err)
|
|
return d
|
|
}
|
|
|
|
logTime, err := time.Parse(logging.HumanFormatterDateFormat, "2020-04-04T00:00:05+02:00")
|
|
require.NoError(t, err)
|
|
|
|
tcs := []testCase{
|
|
{
|
|
Name: "human-formatter-noerror",
|
|
Input: `2020-04-04T00:00:05+02:00 [DEBG][jobname][zfs.cmd][task$stack$span.stack]: command exited without error usertime_s="0.008445" cmd="zfs list -H -p -o name -r -t filesystem,volume" systemtime_s="0.033783" invocation="84" total_time_s="0.037828619"`,
|
|
Expect: &RuntimeLine{
|
|
Cmd: "zfs list -H -p -o name -r -t filesystem,volume",
|
|
TotalTime: secs("0.037828619"),
|
|
Usertime: secs("0.008445"),
|
|
Systime: secs("0.033783"),
|
|
Error: "",
|
|
LogTime: logTime,
|
|
},
|
|
},
|
|
{
|
|
Name: "human-formatter-witherror",
|
|
Input: `2020-04-04T00:00:05+02:00 [DEBG][jobname][zfs.cmd][task$stack$span.stack]: command exited with error usertime_s="0.008445" cmd="zfs list -H -p -o name -r -t filesystem,volume" systemtime_s="0.033783" invocation="84" total_time_s="0.037828619" err="some error"`,
|
|
Expect: &RuntimeLine{
|
|
Cmd: "zfs list -H -p -o name -r -t filesystem,volume",
|
|
TotalTime: secs("0.037828619"),
|
|
Usertime: secs("0.008445"),
|
|
Systime: secs("0.033783"),
|
|
Error: "some error",
|
|
LogTime: logTime,
|
|
},
|
|
},
|
|
{
|
|
Name: "from graylog",
|
|
Input: `2020-04-04T00:00:05+02:00 [DEBG][csnas][zfs.cmd][task$stack$span.stack]: command exited without error usertime_s="0" cmd="zfs send -i zroot/ezjail/synapse-12@zrepl_20200329_095518_000 zroot/ezjail/synapse-12@zrepl_20200329_102454_000" total_time_s="0.101598591" invocation="85" systemtime_s="0.041581"`,
|
|
Expect: &RuntimeLine{
|
|
Cmd: "zfs send -i zroot/ezjail/synapse-12@zrepl_20200329_095518_000 zroot/ezjail/synapse-12@zrepl_20200329_102454_000",
|
|
TotalTime: secs("0.101598591"),
|
|
Systime: secs("0.041581"),
|
|
Usertime: secs("0"),
|
|
Error: "",
|
|
LogTime: logTime,
|
|
},
|
|
},
|
|
}
|
|
|
|
for _, c := range tcs {
|
|
t.Run(c.Name, func(t *testing.T) {
|
|
l, err := parseLogLine(c.Input)
|
|
t.Logf("l=%v", l)
|
|
t.Logf("err=%T %v", err, err)
|
|
if (c.Expect != nil && c.ExpectErr != "") || (c.Expect == nil && c.ExpectErr == "") {
|
|
t.Fatal("bad test case", c)
|
|
}
|
|
if c.Expect != nil {
|
|
require.Equal(t, *c.Expect, l)
|
|
}
|
|
if c.ExpectErr != "" {
|
|
require.EqualError(t, err, c.ExpectErr)
|
|
}
|
|
})
|
|
}
|
|
|
|
}
|