Miscellaneous logging improvements #12662

knz · 2017-01-03T19:21:53Z

The main visible changes here are:

(most important) make acceptance now capture all generated temp files, including temp files and thus non-redirected log files, in the artifact directory.
--log-dir="" can now disable output to files as advertised
TestLogic puts non-essential log events to files.
Acceptance tests put non-essential log events to files.

This change is

jordanlewis · 2017-01-03T21:08:34Z

Reviewed 1 of 2 files at r1, 1 of 2 files at r2, 2 of 2 files at r3, 2 of 2 files at r4, 3 of 3 files at r5, 1 of 1 files at r6, 1 of 1 files at r7, 3 of 3 files at r8, 25 of 25 files at r9, 3 of 3 files at r10.
Review status: all files reviewed at latest revision, all discussions resolved, some commit checks failed.

Comments from Reviewable

tamird · 2017-01-03T21:23:02Z

Reviewed 1 of 2 files at r1, 1 of 2 files at r2, 2 of 2 files at r3, 2 of 2 files at r4, 3 of 3 files at r5, 1 of 1 files at r6, 1 of 1 files at r7, 3 of 3 files at r8.
Review status: all files reviewed at latest revision, 4 unresolved discussions, some commit checks failed.

pkg/cli/start.go, line 279 at r3 (raw file):

	pf := cockroachCmd.PersistentFlags()
	f := pf.Lookup(logflags.LogDirName)
	if !log.DirSet() && !f.Changed {

what if f.Changed but the value is non-empty?

pkg/sql/logic_test.go, line 370 at r8 (raw file):

	// logScope binds the lifetime of the log files to this test.
	logScope log.TestLogScope

ah I see, this is why you exported LogScope. I think you should combine those two commits, but also extract TestLogScope into its own package that both log_test and sql_test can depend on - then you won't need tShim.

pkg/sql/logic_test.go, line 397 at r8 (raw file):

// out emits a message both on stdout and the log files if
// verbose is set.
func (t *logicTest) out(format string, args ...interface{}) {

outf

pkg/util/log/test_log_scope.go, line 34 at r5 (raw file):

type TestLogScope string

// tShim is the part of testing.T used by TestLogScope.

This commit doesn't include any rationale - why did you need to export this stuff?

Comments from Reviewable

knz · 2017-01-04T10:07:25Z

Review status: 0 of 37 files reviewed at latest revision, 4 unresolved discussions.

pkg/cli/start.go, line 279 at r3 (raw file):

Previously, tamird (Tamir Duberstein) wrote…

what if f.Changed but the value is non-empty?

If the value is non-empty then log.DirSet() returns true.

pkg/sql/logic_test.go, line 370 at r8 (raw file):

Previously, tamird (Tamir Duberstein) wrote…

ah I see, this is why you exported LogScope. I think you should combine those two commits, but also extract TestLogScope into its own package that both log_test and sql_test can depend on - then you won't need tShim.

There is no log_test package currently. The tests in clog_test.go which would use the new package logscope would need to be extracted in their own package as well to avoid circular dependencies. I have tried doing that, and a large portion of the internal interface of the log package need to be exported to support these tests! (the diff has grown larger than 500 changed lines and 15 structs/functions exported before I threw the towel). I think that this loss of encapsulation is not worth the refactoring. You are free to follow-up in a separate PR 😸

I did combine the two subsequent commits though as you suggested.

pkg/sql/logic_test.go, line 397 at r8 (raw file):

Previously, tamird (Tamir Duberstein) wrote…

outf

Done.

Comments from Reviewable

tamird · 2017-01-04T12:17:44Z

Reviewed 1 of 3 files at r5, 37 of 38 files at r11, 2 of 2 files at r13, 2 of 2 files at r14, 1 of 1 files at r15, 1 of 1 files at r16, 4 of 4 files at r17, 1 of 5 files at r19.
Review status: 10 of 40 files reviewed at latest revision, 1 unresolved discussion, some commit checks pending.

pkg/sql/logic_test.go, line 370 at r8 (raw file):

The tests in clog_test.go which would use the new package logscope would need to be extracted in their own package as well to avoid circular dependencies.

Not true - if you can make them package log_test (without moving them) then you don't have a circular dependency.

Ah, I guess that's what you tried.

Comments from Reviewable

…derr Prior to this patch, if a log message was output to stderr (because --logtostderr or --alsologtostderr was set), then it wasn't output to the log files *at all* even if a log directory was available. This patch fixes this behavior by ensuring that log messages are *copied* to stderr (so they also appear in the log files). It also fixes another issue: although the help text for `--log-dir` says that an empty value disables logging to files, this was not honoured. With this patch `--log-dir=""` becomes effective.

Prior to this patch all the server logs were going to stderr, and separately the logic in `testing.T` would capture the test's stderr into an in-memory buffer and reproduce it on the real stderr upon encountering a failing test. This was a nuisance because pasting the entire logging output to the real stderr upon errors was only making the CI log very long and slow to load in browsers for no useful reason -- in most practical cases, when a logic test fails, the cause is in a non-logged part of the SQL code somewhere and not visible in the logs anyway. This patch changes the behavior as follows: - `TestLogic` now uses a `log.TestLogScope` and sets `log.EnableLogFileOutput()`, which causes: - the server logs to be output to files, - the files to be automatically deleted when the test terminates successfully, - the log directory to be reported in the error message when a test error occurs so that the user can go and look at the log files only if they want to. - `TestLogic` now also logs the "important" events of the input test data (new user, SQL queries, etc) both to the logging output (and thus the log files) and the standard output. This way a user who decides to inspect the log file later can still observe the time interleaving of test events and logging messages.

This patch causes acceptance logs to be emitted to files, with only errors (severity ERROR or higher) emitted to stderr. The files are deleted if the test succeeds, but preserved if a test fails and the location of the directory is printed in the test's failure message.

Prior to this patch, GetLogReader would get confused if the logDir wasn't relative to the current directory. This patch ensures that it can handle any path including absolute paths outside of the cwd or relative paths outside of the cwd or logDir.

This patch ensures that more logging output lands into the `artifacts` sub-directory, and also reports detailed tracing of shell script execution.

There is an ongoing issue in TestNodeRestart (chaos_test.go) which causes the Docker library to become very confused in all subsequent tests that also use Docker (i.e. most of them). This patch works around the issue (without solving it) by ensuring that TestNodeRestart runs last.

RaduBerinde · 2017-01-10T14:19:53Z

Just noticed this: test_log_scope.go:81: test log files left over in: /tmp/TestLogic028915605
Nice!! 👍

andreimatei · 2017-06-15T23:29:31Z

Review status: 0 of 43 files reviewed at latest revision, 2 unresolved discussions.

pkg/util/log/trace_test.go, line 95 at r26 (raw file):

	// The test below merely cares about observing events in traces.
	// Do not pollute the test's stderr with them.
	logging.stderrThreshold = Severity_FATAL

I believe this is funky. First of all, this is an atomic, and it has a setter. Second, I think it should be restored when the test is done. Third, I think modifying that global is generally horrible because... it's a global (think parallel tests).

I'm curious what motivated this change exactly. What did we want to keep out of stderr? If I run with TESTFLAGS=-v, I want all logs in stderr, right? And if I run without that, no logs go to stderr regardless of their level and this threshold, right?
And also it's unclear to me what log statements in this test are affected by this statement. As far as I can see, there's only one logging statement (as opposed to tracing events): VEvent(ctxWithSpan, logging.verbosity.get()+1, "test2"). Is that the target?

Comments from Reviewable

knz · 2017-06-15T23:37:56Z

Review status: 0 of 43 files reviewed at latest revision, 2 unresolved discussions.

pkg/util/log/trace_test.go, line 95 at r26 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I believe this is funky. First of all, this is an atomic, and it has a setter. Second, I think it should be restored when the test is done. Third, I think modifying that global is generally horrible because... it's a global (think parallel tests).

I'm curious what motivated this change exactly. What did we want to keep out of stderr? If I run with TESTFLAGS=-v, I want all logs in stderr, right? And if I run without that, no logs go to stderr regardless of their level and this threshold, right?
And also it's unclear to me what log statements in this test are affected by this statement. As far as I can see, there's only one logging statement (as opposed to tracing events): VEvent(ctxWithSpan, logging.verbosity.get()+1, "test2"). Is that the target?

Thank you for taking the time to review this, albeit late.

Since the PR is already merged it makes it hard(er) to have a discussion and iterate on code. Mind copy-pasting your concern into a new issue and assign it to me? (I would rather you do that in general in the future if you want to comment on closed PRs.)

Comments from Reviewable

andreimatei · 2017-06-15T23:51:11Z

Review status: 0 of 43 files reviewed at latest revision, 2 unresolved discussions.

pkg/util/log/trace_test.go, line 95 at r26 (raw file):

Previously, knz (kena) wrote…

Thank you for taking the time to review this, albeit late.

Since the PR is already merged it makes it hard(er) to have a discussion and iterate on code. Mind copy-pasting your concern into a new issue and assign it to me? (I would rather you do that in general in the future if you want to comment on closed PRs.)

Filed #16551

Comments from Reviewable

knz assigned jordanlewis Jan 3, 2017

knz force-pushed the fix-clog branch from fcceba0 to 3dddbd8 Compare January 4, 2017 10:07

knz force-pushed the fix-clog branch 2 times, most recently from 8eb4653 to ed8a2d4 Compare January 4, 2017 11:35

knz force-pushed the fix-clog branch 7 times, most recently from 895bf2d to 5547306 Compare January 4, 2017 14:01

knz added 12 commits January 4, 2017 14:46

acceptance: skip flaky TestPartitionBank - see cockroachdb#12654.

dc42004

log: properly check for remaining log files in logScope.close().

10e1541

log: ensure that the directory cleanup always runs in logScope.close().

2a1bd11

log: allow the caller of EnableLogFileOutput to specify the threshold.

ad43df6

log: ensure that all temp dirs are properly removed during tests.

813ed3c

log: quieten TestTrace.

f295155

log: fix GetLogReader.

3844fbb

Prior to this patch, GetLogReader would get confused if the logDir wasn't relative to the current directory. This patch ensures that it can handle any path including absolute paths outside of the cwd or relative paths outside of the cwd or logDir.

prod+test: capture more output in acceptance/CI builds.

9799556

This patch ensures that more logging output lands into the `artifacts` sub-directory, and also reports detailed tracing of shell script execution.

knz force-pushed the fix-clog branch from 8a56a79 to 50fb99a Compare January 4, 2017 14:48

knz mentioned this pull request Jan 4, 2017

acceptance: errors in iptables in TestPartitionBank not picked up properly by go-test-teamcity #12674

Closed

build: make the TC builds tee the full log to artifacts.

61cfc66

knz force-pushed the fix-clog branch from 50fb99a to 61cfc66 Compare January 4, 2017 14:54

knz merged commit e1ef4ec into cockroachdb:master Jan 4, 2017

knz deleted the fix-clog branch January 4, 2017 15:12

knz mentioned this pull request Jan 4, 2017

acceptance: TestPartitionBank is flaky / failing #12654

Closed

a-robinson mentioned this pull request Jan 5, 2017

cli: Missing output from failed Example_ tests in teamcity #12692

Closed

jseldess mentioned this pull request Jan 5, 2017

Miscellaneous logging improvements cockroachdb/docs#971

Closed

jseldess added the docs-todo label Jan 5, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Miscellaneous logging improvements #12662

Miscellaneous logging improvements #12662

knz commented Jan 3, 2017 •

edited by rjnn

Loading

jordanlewis commented Jan 3, 2017

tamird commented Jan 3, 2017

knz commented Jan 4, 2017

tamird commented Jan 4, 2017

RaduBerinde commented Jan 10, 2017

andreimatei commented Jun 15, 2017

knz commented Jun 15, 2017

andreimatei commented Jun 15, 2017

Miscellaneous logging improvements #12662

Miscellaneous logging improvements #12662

Conversation

knz commented Jan 3, 2017 • edited by rjnn Loading

jordanlewis commented Jan 3, 2017

tamird commented Jan 3, 2017

knz commented Jan 4, 2017

tamird commented Jan 4, 2017

RaduBerinde commented Jan 10, 2017

andreimatei commented Jun 15, 2017

knz commented Jun 15, 2017

andreimatei commented Jun 15, 2017

knz commented Jan 3, 2017 •

edited by rjnn

Loading