diff --git a/cmd/autosnap.go b/cmd/autosnap.go index 0af4a44..116d210 100644 --- a/cmd/autosnap.go +++ b/cmd/autosnap.go @@ -45,7 +45,7 @@ func (a *IntervalAutosnap) Run(ctx context.Context, didSnaps chan struct{}) { a.log.Debug("examine filesystem state") for i, d := range ds { - l := a.log.WithField("filesystem", d.ToString()) + l := a.log.WithField(logFSField, d.ToString()) fsvs, err := zfs.ZFSListFilesystemVersions(d, &PrefixSnapshotFilter{a.Prefix}) if err != nil { @@ -129,7 +129,7 @@ func (a *IntervalAutosnap) doSnapshots(didSnaps chan struct{}) { suffix := time.Now().In(time.UTC).Format("20060102_150405_000") snapname := fmt.Sprintf("%s%s", a.Prefix, suffix) - a.log.WithField("filesystem", d.ToString()). + a.log.WithField(logFSField, d.ToString()). WithField("snapname", snapname). Info("create snapshot") diff --git a/cmd/config_job_local.go b/cmd/config_job_local.go index 8cc93d2..99abd21 100644 --- a/cmd/config_job_local.go +++ b/cmd/config_job_local.go @@ -90,7 +90,7 @@ func (j *LocalJob) JobStart(ctx context.Context) { // All local datasets will be passed to its Map() function, // but only those for which a mapping exists will actually be pulled. // We can pay this small performance penalty for now. - handler := NewHandler(log.WithField("task", "handler"), localPullACL{}, &PrefixSnapshotFilter{j.SnapshotPrefix}) + handler := NewHandler(log.WithField(logTaskField, "handler"), localPullACL{}, &PrefixSnapshotFilter{j.SnapshotPrefix}) registerEndpoints(local, handler) @@ -112,7 +112,7 @@ func (j *LocalJob) JobStart(ctx context.Context) { } makeCtx := func(parent context.Context, taskName string) (ctx context.Context) { - return context.WithValue(parent, contextKeyLog, log.WithField("task", taskName)) + return context.WithValue(parent, contextKeyLog, log.WithField(logTaskField, taskName)) } var snapCtx, plCtx, prCtx, pullCtx context.Context snapCtx = makeCtx(ctx, "autosnap") diff --git a/cmd/config_job_pull.go b/cmd/config_job_pull.go index 15d8000..c305f99 100644 --- a/cmd/config_job_pull.go +++ b/cmd/config_job_pull.go @@ -119,7 +119,7 @@ start: log.Printf("starting pull") - pullLog := log.WithField("task", "pull") + pullLog := log.WithField(logTaskField, "pull") err = doPull(PullContext{client, pullLog, j.Mapping, j.InitialReplPolicy}) if err != nil { log.Printf("error doing pull: %s", err) @@ -128,7 +128,7 @@ start: closeRPCWithTimeout(log, client, time.Second*10, "") log.Printf("starting prune") - prunectx := context.WithValue(ctx, contextKeyLog, log.WithField("task", "prune")) + prunectx := context.WithValue(ctx, contextKeyLog, log.WithField(logTaskField, "prune")) pruner, err := j.Pruner(PrunePolicySideDefault, false) if err != nil { log.Printf("error creating pruner: %s", err) diff --git a/cmd/config_job_source.go b/cmd/config_job_source.go index 735c227..238b875 100644 --- a/cmd/config_job_source.go +++ b/cmd/config_job_source.go @@ -84,9 +84,9 @@ func (j *SourceJob) JobStart(ctx context.Context) { return } - snapContext := context.WithValue(ctx, contextKeyLog, log.WithField("task", "autosnap")) - prunerContext := context.WithValue(ctx, contextKeyLog, log.WithField("task", "prune")) - serveContext := context.WithValue(ctx, contextKeyLog, log.WithField("task", "serve")) + snapContext := context.WithValue(ctx, contextKeyLog, log.WithField(logTaskField, "autosnap")) + prunerContext := context.WithValue(ctx, contextKeyLog, log.WithField(logTaskField, "prune")) + serveContext := context.WithValue(ctx, contextKeyLog, log.WithField(logTaskField, "serve")) didSnaps := make(chan struct{}) go j.serve(serveContext) diff --git a/cmd/config_logging.go b/cmd/config_logging.go index 652cbc0..3157e37 100644 --- a/cmd/config_logging.go +++ b/cmd/config_logging.go @@ -3,75 +3,101 @@ package cmd import ( "github.com/mitchellh/mapstructure" "github.com/pkg/errors" - //"github.com/rifflock/lfshook" "github.com/sirupsen/logrus" + "os" ) type LoggingConfig struct { Stdout struct { - Level logrus.Level + Level logrus.Level + Format LogFormat } - //LFS lfshook.PathMap } func parseLogging(i interface{}) (c *LoggingConfig, err error) { c = &LoggingConfig{} c.Stdout.Level = logrus.WarnLevel + c.Stdout.Format = LogFormatHuman if i == nil { return c, nil } var asMap struct { - Mate string - Stdout map[string]string - LFS map[string]string + Stdout struct { + Level string + Format string + } } if err = mapstructure.Decode(i, &asMap); err != nil { return nil, errors.Wrap(err, "mapstructure error") } - //if asMap.LFS != nil { - // c.LFS = make(map[logrus.Level]string, len(asMap.LFS)) - // for level_str, path := range asMap.LFS { - // level, err := logrus.ParseLevel(level_str) - // if err != nil { - // return nil, errors.Wrapf(err, "cannot parse level '%s'", level_str) - // } - // if len(path) <= 0 { - // return nil, errors.Errorf("path must be longer than 0") - // } - // c.LFS[level] = path - // } - //} - - if asMap.Stdout != nil { - lvl, err := logrus.ParseLevel(asMap.Stdout["level"]) + if asMap.Stdout.Level != "" { + lvl, err := logrus.ParseLevel(asMap.Stdout.Level) if err != nil { return nil, errors.Wrap(err, "cannot parse stdout log level") } c.Stdout.Level = lvl } + if asMap.Stdout.Format != "" { + format, err := parseLogFormat(asMap.Stdout.Format) + if err != nil { + return nil, errors.Wrap(err, "cannot parse log format") + } + c.Stdout.Format = format + } return c, nil } +type LogFormat string + +const ( + LogFormatHuman LogFormat = "human" + LogFormatLogfmt LogFormat = "logfmt" + LogFormatJSON LogFormat = "json" +) + +func (f LogFormat) Formatter() logrus.Formatter { + switch f { + case LogFormatHuman: + return HumanFormatter{} + case LogFormatLogfmt: + return &logrus.TextFormatter{} + case LogFormatJSON: + return &logrus.JSONFormatter{} + default: + panic("incomplete implementation") + } +} + +var LogFormats []LogFormat = []LogFormat{LogFormatHuman, LogFormatLogfmt, LogFormatJSON} + +func parseLogFormat(i interface{}) (f LogFormat, err error) { + var is string + switch j := i.(type) { + case string: + is = j + default: + return "", errors.Errorf("invalid log format: wrong type: %T", i) + } + + for _, f := range LogFormats { + if string(f) == is { + return f, nil + } + } + return "", errors.Errorf("invalid log format: '%s'", is) +} + func (c *LoggingConfig) MakeLogrus() (l logrus.FieldLogger) { log := logrus.New() - log.Out = nopWriter(0) - log.Level = logrus.DebugLevel - - //log.Level = logrus.DebugLevel - // - //if len(c.LFS) > 0 { - // lfshook := lfshook.NewHook(c.LFS) - // log.Hooks.Add(lfshook) - //} - - stdhook := NewStdHook() - log.Hooks.Add(stdhook) + log.Out = os.Stdout + log.Level = c.Stdout.Level + log.Formatter = c.Stdout.Format.Formatter() return log diff --git a/cmd/daemon.go b/cmd/daemon.go index 9580471..31e4b4c 100644 --- a/cmd/daemon.go +++ b/cmd/daemon.go @@ -73,7 +73,7 @@ func (d *Daemon) Loop(ctx context.Context) { for _, job := range d.conf.Jobs { log.Printf("starting job %s", job.JobName()) - logger := log.WithField("job", job.JobName()) + logger := log.WithField(logJobField, job.JobName()) i++ jobCtx := context.WithValue(ctx, contextKeyLog, logger) go func(j Job) { diff --git a/cmd/logrus.go b/cmd/logrus.go index 097f9a5..9010898 100644 --- a/cmd/logrus.go +++ b/cmd/logrus.go @@ -2,52 +2,123 @@ package cmd import ( "bytes" + "encoding/json" "fmt" + "github.com/pkg/errors" "github.com/sirupsen/logrus" - "os" + "strings" + "time" ) -type CLIFormatter struct { +const ( + logJobField string = "job" + logTaskField string = "task" + logFSField string = "filesystem" + logMapFromField string = "map_from" + logMapToField string = "map_to" + logIncFromField string = "inc_from" + logIncToField string = "inc_to" +) + +type NoFormatter struct{} + +func (f NoFormatter) Format(e *logrus.Entry) ([]byte, error) { + return []byte(e.Message), nil } -func (f CLIFormatter) Format(e *logrus.Entry) (out []byte, err error) { - var buf bytes.Buffer - fmt.Fprintf(&buf, "%s\n", e.Message) - return buf.Bytes(), nil -} +type HumanFormatter struct{} -var stdhookStderrLevels []logrus.Level = []logrus.Level{ - logrus.PanicLevel, logrus.FatalLevel, logrus.ErrorLevel, logrus.WarnLevel, -} - -type Stdhook struct { -} - -func NewStdHook() *Stdhook { - return &Stdhook{} -} - -func (h *Stdhook) Levels() []logrus.Level { - // Accept all so we can filter the output later - return []logrus.Level{ - logrus.PanicLevel, logrus.FatalLevel, logrus.ErrorLevel, logrus.WarnLevel, - logrus.InfoLevel, logrus.DebugLevel, +func (f HumanFormatter) shortLevel(l logrus.Level) string { + switch l { + case logrus.DebugLevel: + return "DBG" + case logrus.InfoLevel: + return "INF" + case logrus.WarnLevel: + return "WRN" + case logrus.ErrorLevel: + return "ERR" + case logrus.PanicLevel: + return "PNC" } + panic("incomplete implementation") } -func (h *Stdhook) Fire(entry *logrus.Entry) error { - s, err := entry.String() - if err != nil { - return err - } - for _, l := range stdhookStderrLevels { - if l == entry.Level { - fmt.Fprint(os.Stderr, s) - return nil +func (f HumanFormatter) Format(e *logrus.Entry) (out []byte, err error) { + + var line bytes.Buffer + + fmt.Fprintf(&line, "[%s]", f.shortLevel(e.Level)) + + prefixFields := []string{logJobField, logTaskField, logFSField} + prefixed := make(map[string]bool, len(prefixFields)+2) + for _, field := range prefixFields { + val, ok := e.Data[field].(string) + if ok { + fmt.Fprintf(&line, "[%s]", val) + prefixed[field] = true + } else { + break } } - fmt.Fprint(os.Stdout, s) - return nil + // even more prefix fields + mapFrom, mapFromOk := e.Data[logMapFromField].(string) + mapTo, mapToOk := e.Data[logMapToField].(string) + if mapFromOk && mapToOk { + fmt.Fprintf(&line, "[%s => %s]", mapFrom, mapTo) + prefixed[logMapFromField], prefixed[logMapToField] = true, true + } + incFrom, incFromOk := e.Data[logIncFromField].(string) + incTo, incToOk := e.Data[logIncToField].(string) + if incFromOk && incToOk { + fmt.Fprintf(&line, "[%s => %s]", incFrom, incTo) + prefixed[logIncFromField], prefixed[logIncToField] = true, true + } + + fmt.Fprintf(&line, ": %s", e.Message) + + for field, value := range e.Data { + + if prefixed[field] { + continue + } + + if strings.ContainsAny(field, " \t") { + return nil, errors.Errorf("field must not contain whitespace: '%s'", field) + } + fmt.Fprintf(&line, " %s=\"%s\"", field, value) + } + + fmt.Fprintf(&line, "\n") + + return line.Bytes(), nil +} + +type JSONFormatter struct{} + +func (f JSONFormatter) Format(e *logrus.Entry) ([]byte, error) { + data := make(logrus.Fields, len(e.Data)+3) + for k, v := range e.Data { + switch v := v.(type) { + case error: + // Otherwise errors are ignored by `encoding/json` + // https://github.com/sirupsen/logrus/issues/137 + data[k] = v.Error() + default: + _, err := json.Marshal(v) + if err != nil { + return nil, errors.Errorf("field is not JSON encodable: %s", k) + } + data[k] = v + } + } + + data["msg"] = e.Message + data["time"] = e.Time.Format(time.RFC3339) + data["level"] = e.Level + + return json.Marshal(data) + } type nopWriter int diff --git a/cmd/prune.go b/cmd/prune.go index 29ad269..419223c 100644 --- a/cmd/prune.go +++ b/cmd/prune.go @@ -2,7 +2,6 @@ package cmd import ( "context" - "encoding/json" "fmt" "github.com/zrepl/zrepl/zfs" "time" @@ -45,7 +44,7 @@ func (p *Pruner) Run(ctx context.Context) (r []PruneResult, err error) { for _, fs := range filesystems { - log := log.WithField("filesystem", fs.ToString()) + log := log.WithField(logFSField, fs.ToString()) fsversions, err := zfs.ZFSListFilesystemVersions(fs, &PrefixSnapshotFilter{p.SnapshotPrefix}) if err != nil { @@ -57,26 +56,16 @@ func (p *Pruner) Run(ctx context.Context) (r []PruneResult, err error) { continue } - dbgj, err := json.Marshal(fsversions) - if err != nil { - panic(err) - } - log.WithField("fsversions", string(dbgj)).Debug() - keep, remove, err := p.PrunePolicy.Prune(fs, fsversions) if err != nil { log.WithError(err).Error("error evaluating prune policy") continue } - dbgj, err = json.Marshal(keep) - if err != nil { - panic(err) - } - log.WithField("keep", string(dbgj)).Debug() - - dbgj, err = json.Marshal(remove) - log.WithField("remove", string(dbgj)).Debug() + log.WithField("fsversions", fsversions). + WithField("keep", keep). + WithField("remove", remove). + Debug("prune policy debug dump") r = append(r, PruneResult{fs, fsversions, keep, remove}) diff --git a/cmd/replication.go b/cmd/replication.go index cf67e62..77a764a 100644 --- a/cmd/replication.go +++ b/cmd/replication.go @@ -90,8 +90,8 @@ func doPull(pull PullContext) (err error) { if localFs == nil { continue } - log.WithField("map_remote", remoteFilesystems[fs].ToString()). - WithField("map_local", localFs.ToString()).Debug() + log.WithField(logMapFromField, remoteFilesystems[fs].ToString()). + WithField(logMapToField, localFs.ToString()).Debug() m := RemoteLocalMapping{remoteFilesystems[fs], localFs} replMapping[m.Local.ToString()] = m localTraversal.Add(m.Local) @@ -107,7 +107,7 @@ func doPull(pull PullContext) (err error) { log.Info("start per-filesystem sync") localTraversal.WalkTopDown(func(v zfs.DatasetPathVisit) bool { - log := log.WithField("filesystem", v.Path.ToString()) + log := log.WithField(logFSField, v.Path.ToString()) if v.FilledIn { if _, exists := localFilesystemState[v.Path.ToString()]; exists { @@ -129,8 +129,8 @@ func doPull(pull PullContext) (err error) { panic("internal inconsistency: replMapping should contain mapping for any path that was not filled in by WalkTopDown()") } - log = log.WithField("map_remote", m.Remote.ToString()). - WithField("map_local", m.Local.ToString()) + log = log.WithField(logMapToField, m.Remote.ToString()). + WithField(logMapFromField, m.Local.ToString()) log.Debug("examing local filesystem state") localState, localExists := localFilesystemState[m.Local.ToString()] @@ -245,7 +245,7 @@ func doPull(pull PullContext) (err error) { from, to := diff.IncrementalPath[i], diff.IncrementalPath[i+1] - log, _ := log.WithField("inc_from", from.Name).WithField("inc_to", to.Name), 0 + log, _ := log.WithField(logIncFromField, from.Name).WithField(logIncToField, to.Name), 0 log.Debug("requesting incremental snapshot stream") r := IncrementalTransferRequest{ diff --git a/cmd/test.go b/cmd/test.go index f03eb94..91a07fb 100644 --- a/cmd/test.go +++ b/cmd/test.go @@ -65,7 +65,7 @@ func init() { func testCmdGlobalInit(cmd *cobra.Command, args []string) { log := logrus.New() - log.Formatter = CLIFormatter{} + log.Formatter = NoFormatter{} testCmdGlobal.log = log var err error