Turn off redundant logging in TiDB tests

#1

Currently TiDB CI reports contain a large number of logs redundant, see this example.

Such large number of logs is unnecessary burden for CI. Most open source projects turn off logging in test environment and retain only the failed cases info. One can turn on logging locally, debug and push a fix. CI only verifies whether the case is recovered.

I’m unfamiliar with TiDB log configuration, but notice a log refactor is happening. Maybe we can join force and enable turning off redundant logging in TiDB tests.

What do you think?

Discuss: Simplify unit test log
Proposal: Restructure TiDB Tests
#2

TiDB CI calls make to run test. And logging is configured in makefile under gotest command.


There are many hack code in TiDB tests. These tests read env directly then pass to log initializer. Just search the whole project with “os.Getenv(“log_level”)”.
Attention: These hack code won’t affect production logging logic. Users config TiDB log with config file and cmd parameter, but not env variables.

To fix too-many-log issue in CI, simply modify these two line:


#3

This is because there are non-deterministic tests in TiDB: some developers using sleep or random number in unit tests. When these tests failed, it may not be easy to reproduce. The log is useful to analyze the problem.

#4

Are all tests turn on logging in this case?

Even though, we can try to make these tests deterministic, or report significant information instead of all INFO level logs.

#5

I don’t think they treat the log special. I agree to make these tests deterministic or move them to another place, i.e. Ti-Case, Tipocket :slight_smile:

#6

for normal gotest… it’s better to redirect log to testing.T like fgrosse/zaptest: Test helpers to use a github.com/uber-go/zap logger in unit tests.… so it will only be shown if the test fails or if the -v flag was set

but in TiDB…our pingcap/check seems ignore go’s testing framework… :neutral_face:

#7

also passthrough logger is not easy in go(compare with java’s MDC )…we tried context.Context but it often lost in some logic(e.g. some ddl code) which make zaptest like solution hard to work

#8

but I agree to turn off log in default CI for now :grinning:

#9

@lysu does setting envvar log_level to error or warn work?

I think what @SabaPing mentioned above is reasonable.

#10

Instead of logging everything and search for the problem when some non-deterministic test case fails, can we do things smarter, like only preserve those logs of failed test cases?

#11

I’m starting working on this.

@nolouch do you know why we develop pingcap/log on the top of zap? What are the significant changes?

From the design document written by @SabaPing, I can see that this module

  • Provides the standard config schema.
  • Provides a factory method for creating log handlers.
  • Hard code the log format according to unified-log-format RFC standard.
  • Encapsulates the logic of the rolling file.
  • Provides global log handler and related methods for package dimension.
#12

As zap has done in zaptest,

type testingWriter struct {
	t TestingT
	markFailed bool
}

func newTestingWriter(t TestingT) testingWriter {
	return testingWriter{t: t}
}

// WithMarkFailed returns a copy of this testingWriter with markFailed set to
// the provided value.
func (w testingWriter) WithMarkFailed(v bool) testingWriter {
	w.markFailed = v
	return w
}

func (w testingWriter) Write(p []byte) (n int, err error) {
	n = len(p)

	// Strip trailing newline because t.Log always adds one.
	p = bytes.TrimRight(p, "\n")

	// Note: t.Log is safe for concurrent use.
	w.t.Logf("%s", p)
	if w.markFailed {
		w.t.Fail()
	}

	return n, nil
}

func (w testingWriter) Sync() error {
	return nil
}

we’d better factor out WriteSyncer parameter of InitLoggerWithWriteSyncer and expose builder for both

  • TestingWriter
  • lumberjack.Logger
  • zap.Open([]string{"stdout"}...)

We may expose two functions:

func BuildWriteSyncer(cfg *Config) (zapcore.WriteSyncer, error) {
    var writeSyncer zapcore.WriteSyncer
    if len(cfg.File.Filename) > 0 {
        logger, err := initFileLog(&cfg.File)
        if err != nil {
            return nil, err
        }
        return zapcore.AddSync(logger)
    } else {
        stdout, _, err := zap.Open([]string{"stdout"}...)
        if err != nil {
            return nil, err
        }
        return stdout
    }
}

func BuildTestingWriter(t zaptest.TestingT) TestingWriter {
    return TestingWriter{t: t}
}

In this way, we could enable logging only if test failed when testing.

Remove pingcap/errors and switch to testify
#13

Yep. We use log.ReplaceGlobals to modify global logger. It is really brittle. But we can first export the customize ability to WriteSyncer so that we can prevent unnecessary logging for successful tests.

See also

What do you think? @lysu @nolouch

1 Like
Can we improve TiDB log?
#14

FYI