From ece7b8b23746436324d3a99afb336587e98bdf86 Mon Sep 17 00:00:00 2001 From: Andrew Kryczka Date: Mon, 23 Sep 2019 23:37:03 -0700 Subject: [PATCH 1/2] c-deps: bump rocksdb for unique cache IDs on Windows Picks up https://github.com/cockroachdb/rocksdb/pull/58. We found a corruption caused by multiple FAT32 files assigned the same block cache key prefix. We don't know the extent to which this problem affects other filesystems or other Windows file ID generation mechanisms. We decided to turn off the reliance on filesystem for generating cache keys on Windows. Instead we use randomization per table reader. This would cause a performance penalty for use cases that open multiple table readers per file, but I believe cockroach is not such a use case. Fixes #40918, fixes #40950. Release justification: Prevents corruption on some Windows filesystems Release note: None --- c-deps/rocksdb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/c-deps/rocksdb b/c-deps/rocksdb index 8978e86a8161..217d7a121d7a 160000 --- a/c-deps/rocksdb +++ b/c-deps/rocksdb @@ -1 +1 @@ -Subproject commit 8978e86a8161157fac5fdc5483934cf55fb2029e +Subproject commit 217d7a121d7ac8db4b742c3fef1e0605af536841 From 70be7ebee42141708df198650751ab09e5a4f119 Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Tue, 24 Sep 2019 10:00:14 +0200 Subject: [PATCH 2/2] util/log: fix GC of secondary loggers Release justification: bug fix Release note (bug fix): CockroachDB will now properly remove excess secondary log files (SQL audit logging, statement execution logging, and RocksDB events). --- pkg/util/log/clog.go | 2 +- pkg/util/log/clog_test.go | 84 ---------------- pkg/util/log/file.go | 2 +- pkg/util/log/log_gc_test.go | 192 ++++++++++++++++++++++++++++++++++++ 4 files changed, 194 insertions(+), 86 deletions(-) create mode 100644 pkg/util/log/log_gc_test.go diff --git a/pkg/util/log/clog.go b/pkg/util/log/clog.go index 6dc021a77f15..7076c4c9e1b6 100644 --- a/pkg/util/log/clog.go +++ b/pkg/util/log/clog.go @@ -1161,7 +1161,7 @@ func (sb *syncBuffer) rotateFile(now time.Time) error { } select { - case logging.gcNotify <- struct{}{}: + case sb.logger.gcNotify <- struct{}{}: default: } return nil diff --git a/pkg/util/log/clog_test.go b/pkg/util/log/clog_test.go index a5fb5f0911a0..f447f3fb4b11 100644 --- a/pkg/util/log/clog_test.go +++ b/pkg/util/log/clog_test.go @@ -27,7 +27,6 @@ import ( "regexp" "strings" "sync" - "sync/atomic" "testing" "time" @@ -559,89 +558,6 @@ func TestRollover(t *testing.T) { } } -func TestGC(t *testing.T) { - s := ScopeWithoutShowLogs(t) - defer s.Close(t) - - logging.mu.Lock() - logging.disableDaemons = true - defer func(previous bool) { - logging.mu.Lock() - logging.disableDaemons = previous - logging.mu.Unlock() - }(logging.disableDaemons) - logging.mu.Unlock() - - setFlags() - - const newLogFiles = 20 - - // Prevent writes to stderr from being sent to log files which would screw up - // the expected number of log file calculation below. - logging.noStderrRedirect = true - - // Create 1 log file to figure out its size. - Infof(context.Background(), "0") - - allFilesOriginal, err := ListLogFiles() - if err != nil { - t.Fatal(err) - } - if e, a := 1, len(allFilesOriginal); e != a { - t.Fatalf("expected %d files, but found %d", e, a) - } - dir, err := logging.logDir.get() - if err != nil { - t.Fatal(err) - } - f, err := os.Open(filepath.Join(dir, allFilesOriginal[0].Name)) - if err != nil { - t.Fatal(err) - } - stat, err := f.Stat() - if err != nil { - t.Fatal(err) - } - if err := f.Close(); err != nil { - t.Fatal(err) - } - // logFileSize is the size of the first log file we wrote to. - logFileSize := stat.Size() - const expectedFilesAfterGC = 2 - // Pick a max total size that's between 2 and 3 log files in size. - maxTotalLogFileSize := logFileSize*expectedFilesAfterGC + logFileSize // 2 - - defer func(previous int64) { LogFileMaxSize = previous }(LogFileMaxSize) - LogFileMaxSize = 1 // ensure rotation on every log write - defer func(previous int64) { - atomic.StoreInt64(&LogFilesCombinedMaxSize, previous) - }(LogFilesCombinedMaxSize) - atomic.StoreInt64(&LogFilesCombinedMaxSize, maxTotalLogFileSize) - - for i := 1; i < newLogFiles; i++ { - Infof(context.Background(), "%d", i) - Flush() - } - - allFilesBefore, err := ListLogFiles() - if err != nil { - t.Fatal(err) - } - if e, a := newLogFiles, len(allFilesBefore); e != a { - t.Fatalf("expected %d files, but found %d", e, a) - } - - logging.gcOldFiles() - - allFilesAfter, err := ListLogFiles() - if err != nil { - t.Fatal(err) - } - if e, a := expectedFilesAfterGC, len(allFilesAfter); e != a { - t.Fatalf("expected %d files, but found %d", e, a) - } -} - func TestLogBacktraceAt(t *testing.T) { s := ScopeWithoutShowLogs(t) defer s.Close(t) diff --git a/pkg/util/log/file.go b/pkg/util/log/file.go index a94bd2061306..254876c345fe 100644 --- a/pkg/util/log/file.go +++ b/pkg/util/log/file.go @@ -277,7 +277,7 @@ func ListLogFiles() ([]FileInfo, error) { func (l *loggingT) listLogFiles() ([]FileInfo, error) { var results []FileInfo - dir, err := logging.logDir.get() + dir, err := l.logDir.get() if err != nil { // No log directory configured: simply indicate that there are no // log files. diff --git a/pkg/util/log/log_gc_test.go b/pkg/util/log/log_gc_test.go new file mode 100644 index 000000000000..60405754aba4 --- /dev/null +++ b/pkg/util/log/log_gc_test.go @@ -0,0 +1,192 @@ +// Copyright 2019 The Cockroach Authors. +// +// Use of this software is governed by the Business Source License +// included in the file licenses/BSL.txt. +// +// As of the Change Date specified in that file, in accordance with +// the Business Source License, use of this software will be governed +// by the Apache License, Version 2.0, included in the file +// licenses/APL.txt. + +package log + +import ( + "context" + "fmt" + "io/ioutil" + "os" + "path/filepath" + "sync/atomic" + "testing" + "time" + + "github.com/cockroachdb/cockroach/pkg/util/timeutil" +) + +func TestGC(t *testing.T) { + s := ScopeWithoutShowLogs(t) + defer s.Close(t) + + setFlags() + + testLogGC(t, &logging, Infof) +} + +func TestSecondaryGC(t *testing.T) { + s := ScopeWithoutShowLogs(t) + defer s.Close(t) + + setFlags() + + tmpDir, err := ioutil.TempDir(logging.logDir.String(), "gctest") + if err != nil { + t.Fatal(err) + } + defer func() { + if !t.Failed() { + // If the test failed, we'll want to keep the artifacts for + // troubleshooting. + _ = os.RemoveAll(tmpDir) + } + }() + tmpDirName := DirName{name: tmpDir} + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + l := NewSecondaryLogger(ctx, &tmpDirName, "woo", false /*enableGc*/, false /*syncWrites*/, true /*msgCount*/) + + testLogGC(t, &l.logger, l.Logf) +} + +func testLogGC( + t *testing.T, + logger *loggingT, + logFn func(ctx context.Context, format string, args ...interface{}), +) { + logging.mu.Lock() + logging.disableDaemons = true + defer func(previous bool) { + logging.mu.Lock() + logging.disableDaemons = previous + logging.mu.Unlock() + }(logging.disableDaemons) + logging.mu.Unlock() + + const newLogFiles = 20 + + // Prevent writes to stderr from being sent to log files which would screw up + // the expected number of log file calculation below. + logging.noStderrRedirect = true + + // Ensure the main log has at least one entry. This serves two + // purposes. One is to serve as baseline for the file size. The + // other is to ensure that the TestLogScope does not erase the + // temporary directory, preventing further investigation. + Infof(context.Background(), "0") + + // Make an entry in the target logger. This ensures That there is at + // least one file in the target directory for the logger being + // tested. + logFn(context.Background(), "0") + + // Check that the file was created. + allFilesOriginal, err := logger.listLogFiles() + if err != nil { + t.Fatal(err) + } + if e, a := 1, len(allFilesOriginal); e != a { + t.Fatalf("expected %d files, but found %d", e, a) + } + + // Check that the file exists, and also measure its size. + // We'll use this as base value for the maximum combined size + // below, to force GC. + dir, err := logger.logDir.get() + if err != nil { + t.Fatal(err) + } + stat, err := os.Stat(filepath.Join(dir, allFilesOriginal[0].Name)) + if err != nil { + t.Fatal(err) + } + // logFileSize is the size of the first log file we wrote to. + logFileSize := stat.Size() + const expectedFilesAfterGC = 2 + // Pick a max total size that's between 2 and 3 log files in size. + maxTotalLogFileSize := logFileSize*expectedFilesAfterGC + logFileSize // 2 + + // We want to create multiple log files below. For this we need to + // override the size/number limits first to the values suitable for + // the test. + defer func(previous int64) { LogFileMaxSize = previous }(LogFileMaxSize) + LogFileMaxSize = 1 // ensure rotation on every log write + defer func(previous int64) { + atomic.StoreInt64(&LogFilesCombinedMaxSize, previous) + }(LogFilesCombinedMaxSize) + atomic.StoreInt64(&LogFilesCombinedMaxSize, maxTotalLogFileSize) + + // Create the number of expected log files. + for i := 1; i < newLogFiles; i++ { + logFn(context.Background(), "%d", i) + Flush() + } + + allFilesBefore, err := logger.listLogFiles() + if err != nil { + t.Fatal(err) + } + if e, a := newLogFiles, len(allFilesBefore); e != a { + t.Fatalf("expected %d files, but found %d", e, a) + } + + // Re-enable GC, so that the GC daemon can pick up the files. + logger.mu.Lock() + logger.disableDaemons = false + logger.mu.Unlock() + // Start the GC daemon, using a context that will terminate it + // at the end of the test. + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + go logger.gcDaemon(ctx) + + // Emit a log line which will rotate the files and trigger GC. + logFn(context.Background(), "final") + Flush() + + succeedsSoon(t, func() error { + allFilesAfter, err := logger.listLogFiles() + if err != nil { + return err + } + if e, a := expectedFilesAfterGC, len(allFilesAfter); e != a { + return fmt.Errorf("expected %d files, but found %d", e, a) + } + return nil + }) +} + +// succeedsSoon is a simplified version of testutils.SucceedsSoon. +// The main implementation cannot be used here because of +// an import cycle. +func succeedsSoon(t *testing.T, fn func() error) { + t.Helper() + tBegin := timeutil.Now() + deadline := tBegin.Add(5 * time.Second) + var lastErr error + for wait := time.Duration(1); timeutil.Now().Before(deadline); wait *= 2 { + lastErr = fn() + if lastErr == nil { + return + } + if wait > time.Second { + wait = time.Second + } + if timeutil.Since(tBegin) > 3*time.Second { + InfofDepth(context.Background(), 2, "SucceedsSoon: %+v", lastErr) + } + time.Sleep(wait) + } + if lastErr != nil { + t.Fatalf("condition failed to evalute: %+v", lastErr) + } +}