github.com/m3db/m3@v1.5.1-0.20231129193456-75a402aa583b/src/dbnode/persist/fs/commitlog/commit_log_test.go (about) 1 // Copyright (c) 2016 Uber Technologies, Inc. 2 // 3 // Permission is hereby granted, free of charge, to any person obtaining a copy 4 // of this software and associated documentation files (the "Software"), to deal 5 // in the Software without restriction, including without limitation the rights 6 // to use, copy, modify, merge, publish, distribute, sublicense, and/or sell 7 // copies of the Software, and to permit persons to whom the Software is 8 // furnished to do so, subject to the following conditions: 9 // 10 // The above copyright notice and this permission notice shall be included in 11 // all copies or substantial portions of the Software. 12 // 13 // THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR 14 // IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, 15 // FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE 16 // AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER 17 // LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, 18 // OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN 19 // THE SOFTWARE. 20 21 package commitlog 22 23 import ( 24 "bytes" 25 "errors" 26 "fmt" 27 "io/ioutil" 28 "math/rand" 29 "os" 30 "strings" 31 "sync" 32 "sync/atomic" 33 "testing" 34 "time" 35 36 "github.com/m3db/bitset" 37 38 "github.com/m3db/m3/src/dbnode/persist" 39 "github.com/m3db/m3/src/dbnode/persist/fs" 40 "github.com/m3db/m3/src/dbnode/ts" 41 "github.com/m3db/m3/src/dbnode/ts/writes" 42 "github.com/m3db/m3/src/x/checked" 43 "github.com/m3db/m3/src/x/clock" 44 "github.com/m3db/m3/src/x/context" 45 "github.com/m3db/m3/src/x/ident" 46 xtime "github.com/m3db/m3/src/x/time" 47 48 "github.com/fortytw2/leaktest" 49 "github.com/stretchr/testify/require" 50 "github.com/uber-go/tally" 51 ) 52 53 type mockTime struct { 54 sync.Mutex 55 t xtime.UnixNano 56 } 57 58 func (m *mockTime) Now() time.Time { 59 m.Lock() 60 defer m.Unlock() 61 return m.t.ToTime() 62 } 63 64 func (m *mockTime) Add(d time.Duration) { 65 m.Lock() 66 defer m.Unlock() 67 m.t = m.t.Add(d) 68 } 69 70 type overrides struct { 71 nowFn clock.NowFn 72 flushInterval *time.Duration 73 backlogQueueSize *int 74 strategy Strategy 75 } 76 77 var testOpts = NewOptions(). 78 SetBlockSize(2 * time.Hour). 79 SetFlushSize(4096). 80 SetFlushInterval(100 * time.Millisecond). 81 SetBacklogQueueSize(1024) 82 83 func newTestOptions( 84 t *testing.T, 85 overrides overrides, 86 ) ( 87 Options, 88 tally.TestScope, 89 ) { 90 dir, err := ioutil.TempDir("", "foo") 91 require.NoError(t, err) 92 93 var nowFn clock.NowFn 94 if overrides.nowFn != nil { 95 nowFn = overrides.nowFn 96 } else { 97 nowFn = func() time.Time { return time.Now() } 98 } 99 100 scope := tally.NewTestScope("", nil) 101 102 opts := testOpts. 103 SetClockOptions(testOpts.ClockOptions().SetNowFn(nowFn)). 104 SetInstrumentOptions(testOpts.InstrumentOptions().SetMetricsScope(scope)). 105 SetFilesystemOptions(testOpts.FilesystemOptions().SetFilePathPrefix(dir)) 106 107 if overrides.flushInterval != nil { 108 opts = opts.SetFlushInterval(*overrides.flushInterval) 109 } 110 111 if overrides.backlogQueueSize != nil { 112 opts = opts.SetBacklogQueueSize(*overrides.backlogQueueSize) 113 } 114 115 opts = opts.SetStrategy(overrides.strategy) 116 117 return opts, scope 118 } 119 120 func randomByteSlice(len int) []byte { 121 arr := make([]byte, len) 122 rand.Read(arr) 123 return arr 124 } 125 126 func cleanup(t *testing.T, opts Options) { 127 filePathPrefix := opts.FilesystemOptions().FilePathPrefix() 128 require.NoError(t, os.RemoveAll(filePathPrefix)) 129 } 130 131 type testWrite struct { 132 series ts.Series 133 t xtime.UnixNano 134 v float64 135 u xtime.Unit 136 a []byte 137 expectedErr error 138 } 139 140 func testSeries( 141 t *testing.T, 142 opts Options, 143 uniqueIndex uint64, 144 id string, 145 tags ident.Tags, 146 shard uint32, 147 ) ts.Series { 148 var ( 149 tagEncoderPool = opts.FilesystemOptions().TagEncoderPool() 150 tagSliceIter = ident.NewTagsIterator(ident.Tags{}) 151 ) 152 tagSliceIter.Reset(tags) 153 154 tagEncoder := tagEncoderPool.Get() 155 err := tagEncoder.Encode(tagSliceIter) 156 require.NoError(t, err) 157 158 encodedTagsChecked, ok := tagEncoder.Data() 159 require.True(t, ok) 160 161 return ts.Series{ 162 UniqueIndex: uniqueIndex, 163 Namespace: ident.StringID("testNS"), 164 ID: ident.StringID(id), 165 EncodedTags: encodedTagsChecked.Bytes(), 166 Shard: shard, 167 } 168 } 169 170 func (w testWrite) assert( 171 t *testing.T, 172 series ts.Series, 173 datapoint ts.Datapoint, 174 unit xtime.Unit, 175 annotation []byte, 176 ) { 177 require.Equal(t, w.series.UniqueIndex, series.UniqueIndex) 178 require.True(t, w.series.ID.Equal(series.ID), fmt.Sprintf("write ID '%s' does not match actual ID '%s'", w.series.ID.String(), series.ID.String())) 179 require.Equal(t, w.series.Shard, series.Shard) 180 181 // ident.Tags.Equal will compare length 182 require.True(t, bytes.Equal(w.series.EncodedTags, series.EncodedTags)) 183 184 require.Equal(t, w.t, datapoint.TimestampNanos) 185 require.Equal(t, w.v, datapoint.Value) 186 require.Equal(t, w.u, unit) 187 require.Equal(t, w.a, annotation) 188 } 189 190 func snapshotCounterValue( 191 scope tally.TestScope, 192 counter string, 193 ) (tally.CounterSnapshot, bool) { 194 counters := scope.Snapshot().Counters() 195 c, ok := counters[tally.KeyForPrefixedStringMap(counter, nil)] 196 return c, ok 197 } 198 199 type mockCommitLogWriter struct { 200 openFn func() (persist.CommitLogFile, error) 201 writeFn func(ts.Series, ts.Datapoint, xtime.Unit, ts.Annotation) error 202 flushFn func(sync bool) error 203 closeFn func() error 204 setOnFlushFn func(f func(err error)) 205 } 206 207 func newMockCommitLogWriter() *mockCommitLogWriter { 208 return &mockCommitLogWriter{ 209 openFn: func() (persist.CommitLogFile, error) { 210 return persist.CommitLogFile{}, nil 211 }, 212 writeFn: func(ts.Series, ts.Datapoint, xtime.Unit, ts.Annotation) error { 213 return nil 214 }, 215 flushFn: func(sync bool) error { 216 return nil 217 }, 218 closeFn: func() error { 219 return nil 220 }, 221 setOnFlushFn: func(f func(err error)) { 222 }, 223 } 224 } 225 226 func (w *mockCommitLogWriter) Open() (persist.CommitLogFile, error) { 227 return w.openFn() 228 } 229 230 func (w *mockCommitLogWriter) Write( 231 series ts.Series, 232 datapoint ts.Datapoint, 233 unit xtime.Unit, 234 annotation ts.Annotation, 235 ) error { 236 return w.writeFn(series, datapoint, unit, annotation) 237 } 238 239 func (w *mockCommitLogWriter) Flush(sync bool) error { 240 return w.flushFn(sync) 241 } 242 243 func (w *mockCommitLogWriter) Close() error { 244 return w.closeFn() 245 } 246 247 func (w *mockCommitLogWriter) setOnFlush(f func(err error)) { 248 w.setOnFlushFn(f) 249 } 250 251 func newTestCommitLog(t *testing.T, opts Options) *commitLog { 252 return newTestCommitLogWithOpts(t, opts, testOnlyOpts{}) 253 } 254 255 func newTestCommitLogWithOpts(t *testing.T, opts Options, testOpts testOnlyOpts) *commitLog { 256 commitLogI, err := newCommitLog(opts, testOpts) 257 require.NoError(t, err) 258 commitLog := commitLogI.(*commitLog) 259 require.NoError(t, commitLog.Open()) 260 261 // Ensure files present 262 fsopts := opts.FilesystemOptions() 263 files, err := fs.SortedCommitLogFiles(fs.CommitLogsDirPath(fsopts.FilePathPrefix())) 264 require.NoError(t, err) 265 require.True(t, len(files) == 2) 266 267 return commitLog 268 } 269 270 func writeCommitLogs( 271 t *testing.T, 272 scope tally.TestScope, 273 commitLog CommitLog, 274 writes []testWrite, 275 ) *sync.WaitGroup { 276 wg := sync.WaitGroup{} 277 278 getAllWrites := func() int { 279 result := int64(0) 280 success, ok := snapshotCounterValue(scope, "commitlog.writes.success") 281 if ok { 282 result += success.Value() 283 } 284 errors, ok := snapshotCounterValue(scope, "commitlog.writes.errors") 285 if ok { 286 result += errors.Value() 287 } 288 return int(result) 289 } 290 291 ctx := context.NewBackground() 292 defer ctx.Close() 293 294 preWrites := getAllWrites() 295 296 for i, write := range writes { 297 i := i 298 write := write 299 300 // Wait for previous writes to enqueue 301 for getAllWrites() != preWrites+i { 302 time.Sleep(time.Microsecond) 303 } 304 305 wg.Add(1) 306 go func() { 307 defer wg.Done() 308 309 series := write.series 310 datapoint := ts.Datapoint{TimestampNanos: write.t, Value: write.v} 311 err := commitLog.Write(ctx, series, datapoint, write.u, write.a) 312 313 if write.expectedErr != nil { 314 if !strings.Contains(fmt.Sprintf("%v", err), fmt.Sprintf("%v", write.expectedErr)) { 315 panic(fmt.Sprintf("unexpected error: %v", err)) 316 } 317 } else { 318 if err != nil { 319 panic(err) 320 } 321 } 322 }() 323 } 324 325 // Wait for all writes to enqueue 326 for getAllWrites() != preWrites+len(writes) { 327 time.Sleep(time.Microsecond) 328 } 329 330 return &wg 331 } 332 333 type seriesTestWritesAndReadPosition struct { 334 writes []testWrite 335 readPosition int 336 } 337 338 func assertCommitLogWritesByIterating(t *testing.T, l *commitLog, writes []testWrite) { 339 iterOpts := IteratorOpts{ 340 CommitLogOptions: l.opts, 341 FileFilterPredicate: ReadAllPredicate(), 342 } 343 iter, corruptFiles, err := NewIterator(iterOpts) 344 require.NoError(t, err) 345 require.Equal(t, 0, len(corruptFiles)) 346 defer iter.Close() 347 348 // Convert the writes to be in-order, but keyed by series ID because the 349 // commitlog reader only guarantees the same order on disk within a 350 // given series 351 writesBySeries := map[string]seriesTestWritesAndReadPosition{} 352 for _, write := range writes { 353 seriesWrites := writesBySeries[write.series.ID.String()] 354 if seriesWrites.writes == nil { 355 seriesWrites.writes = []testWrite{} 356 } 357 seriesWrites.writes = append(seriesWrites.writes, write) 358 writesBySeries[write.series.ID.String()] = seriesWrites 359 } 360 361 for iter.Next() { 362 entry := iter.Current() 363 364 id := entry.Series.ID.String() 365 seriesWrites := writesBySeries[id] 366 write := seriesWrites.writes[seriesWrites.readPosition] 367 368 write.assert(t, entry.Series, entry.Datapoint, entry.Unit, entry.Annotation) 369 370 seriesWrites.readPosition++ 371 writesBySeries[id] = seriesWrites 372 } 373 374 require.NoError(t, iter.Err()) 375 } 376 377 func setupCloseOnFail(t *testing.T, l *commitLog) *sync.WaitGroup { 378 wg := sync.WaitGroup{} 379 wg.Add(1) 380 l.commitLogFailFn = func(err error) { 381 go func() { 382 l.Close() 383 wg.Done() 384 }() 385 } 386 return &wg 387 } 388 389 func TestCommitLogWrite(t *testing.T) { 390 opts, scope := newTestOptions(t, overrides{ 391 strategy: StrategyWriteWait, 392 }) 393 394 testCases := []struct { 395 testName string 396 writes []testWrite 397 }{ 398 { 399 "Attempt to perform 2 write log writes in parallel to a commit log", 400 []testWrite{ 401 { 402 testSeries(t, opts, 0, "foo.bar", ident.NewTags(ident.StringTag("name1", "val1")), 127), 403 xtime.Now(), 123.456, xtime.Second, 404 []byte{1, 2, 3}, 405 nil, 406 }, 407 { 408 testSeries(t, opts, 1, "foo.baz", ident.NewTags(ident.StringTag("name2", "val2")), 150), 409 xtime.Now(), 456.789, xtime.Second, nil, nil, 410 }, 411 }, 412 }, 413 { 414 "Buffer almost full after first write. Second write almost fills the buffer", 415 []testWrite{ 416 { 417 testSeries(t, opts, 0, "foo.bar", ident.NewTags(ident.StringTag("name1", "val1")), 127), 418 xtime.Now(), 123.456, xtime.Second, randomByteSlice(opts.FlushSize() - 200), nil, 419 }, 420 { 421 testSeries(t, opts, 1, "foo.baz", ident.NewTags(ident.StringTag("name2", "val2")), 150), 422 xtime.Now(), 456.789, xtime.Second, randomByteSlice(40), nil, 423 }, 424 }, 425 }, 426 { 427 "Buffer almost full after first write. Second write almost fills 2*buffer total", 428 []testWrite{ 429 { 430 testSeries(t, opts, 0, "foo.bar", ident.NewTags(ident.StringTag("name1", "val1")), 127), 431 xtime.Now(), 123.456, xtime.Second, randomByteSlice(opts.FlushSize() - 200), nil, 432 }, 433 { 434 testSeries(t, opts, 1, "foo.baz", ident.NewTags(ident.StringTag("name2", "val2")), 150), 435 xtime.Now(), 456.789, xtime.Second, randomByteSlice(40 + opts.FlushSize()), nil, 436 }, 437 }, 438 }, 439 { 440 "Buffer almost full after first write. Second write almost fills 3*buffer total", 441 []testWrite{ 442 { 443 testSeries(t, opts, 0, "foo.bar", ident.NewTags(ident.StringTag("name1", "val1")), 127), 444 xtime.Now(), 123.456, xtime.Second, randomByteSlice(opts.FlushSize() - 200), nil, 445 }, 446 { 447 testSeries(t, opts, 1, "foo.baz", ident.NewTags(ident.StringTag("name2", "val2")), 150), 448 xtime.Now(), 456.789, xtime.Second, randomByteSlice(40 + 2*opts.FlushSize()), nil, 449 }, 450 }, 451 }, 452 { 453 "Attempts to perform a write equal to the flush size", 454 []testWrite{ 455 { 456 testSeries(t, opts, 0, "foo.bar", ident.NewTags(ident.StringTag("name1", "val1")), 127), 457 xtime.Now(), 123.456, xtime.Second, randomByteSlice(opts.FlushSize()), nil, 458 }, 459 }, 460 }, 461 { 462 "Attempts to perform a write double the flush size", 463 []testWrite{ 464 { 465 testSeries(t, opts, 0, "foo.bar", ident.NewTags(ident.StringTag("name1", "val1")), 127), 466 xtime.Now(), 123.456, xtime.Second, randomByteSlice(2 * opts.FlushSize()), nil, 467 }, 468 }, 469 }, 470 { 471 "Attempts to perform a write three times the flush size", 472 []testWrite{ 473 { 474 testSeries(t, opts, 0, "foo.bar", ident.NewTags(ident.StringTag("name1", "val1")), 127), 475 xtime.Now(), 123.456, xtime.Second, randomByteSlice(3 * opts.FlushSize()), nil, 476 }, 477 }, 478 }, 479 } 480 481 for _, testCase := range testCases { 482 t.Run(testCase.testName, func(t *testing.T) { 483 defer cleanup(t, opts) 484 485 commitLog := newTestCommitLog(t, opts) 486 487 // Call write sync 488 writeCommitLogs(t, scope, commitLog, testCase.writes).Wait() 489 490 // Close the commit log and consequently flush 491 require.NoError(t, commitLog.Close()) 492 493 // Assert writes occurred by reading the commit log 494 assertCommitLogWritesByIterating(t, commitLog, testCase.writes) 495 }) 496 } 497 } 498 499 func TestReadCommitLogMissingMetadata(t *testing.T) { 500 readConc := 4 501 // Make sure we're not leaking goroutines 502 defer leaktest.CheckTimeout(t, 10*time.Second)() 503 504 opts, scope := newTestOptions(t, overrides{ 505 strategy: StrategyWriteWait, 506 }) 507 // Set read concurrency so that the parallel path is definitely tested 508 opts.SetReadConcurrency(readConc) 509 defer cleanup(t, opts) 510 511 // Replace bitset in writer with one that configurably returns true or false 512 // depending on the series 513 commitLog := newTestCommitLog(t, opts) 514 primary := commitLog.writerState.primary.writer.(*writer) 515 secondary := commitLog.writerState.secondary.writer.(*writer) 516 517 bitSet := bitset.NewBitSet(0) 518 519 // Generate fake series, where approximately half will be missing metadata. 520 // This works because the commitlog writer uses the bitset to determine if 521 // the metadata for a particular series had already been written to disk. 522 allSeries := []ts.Series{} 523 for i := 0; i < 200; i++ { 524 willNotHaveMetadata := !(i%2 == 0) 525 allSeries = append(allSeries, testSeries(t, opts, 526 uint64(i), 527 "hax", 528 ident.NewTags(ident.StringTag("name", "val")), 529 uint32(i%100), 530 )) 531 if willNotHaveMetadata { 532 bitSet.Set(uint(i)) 533 } 534 } 535 primary.seen = bitSet 536 secondary.seen = bitSet 537 538 // Generate fake writes for each of the series 539 writes := []testWrite{} 540 for _, series := range allSeries { 541 for i := 0; i < 10; i++ { 542 val := rand.Float64() //nolint: gosec 543 writes = append(writes, testWrite{ 544 series, xtime.Now(), val, 545 xtime.Second, 546 []byte{1, 2, 3}, 547 nil, 548 }) 549 } 550 } 551 552 // Call write sync 553 writeCommitLogs(t, scope, commitLog, writes).Wait() 554 555 // Close the commit log and consequently flush 556 require.NoError(t, commitLog.Close()) 557 558 // Make sure we don't panic / deadlock 559 iterOpts := IteratorOpts{ 560 CommitLogOptions: opts, 561 FileFilterPredicate: ReadAllPredicate(), 562 } 563 iter, corruptFiles, err := NewIterator(iterOpts) 564 require.NoError(t, err) 565 require.Equal(t, 0, len(corruptFiles)) 566 567 for iter.Next() { 568 require.NoError(t, iter.Err()) 569 } 570 require.Equal(t, errCommitLogReaderMissingMetadata, iter.Err()) 571 iter.Close() 572 require.NoError(t, commitLog.Close()) 573 } 574 575 func TestCommitLogReaderIsNotReusable(t *testing.T) { 576 // Make sure we're not leaking goroutines 577 defer leaktest.CheckTimeout(t, time.Second)() 578 579 overrideFlushInterval := 10 * time.Millisecond 580 opts, scope := newTestOptions(t, overrides{ 581 strategy: StrategyWriteWait, 582 flushInterval: &overrideFlushInterval, 583 }) 584 defer cleanup(t, opts) 585 586 commitLog := newTestCommitLog(t, opts) 587 588 writes := []testWrite{ 589 { 590 testSeries(t, opts, 0, "foo.bar", testTags1, 127), 591 xtime.Now(), 123.456, xtime.Second, 592 []byte{1, 2, 3}, 593 nil, 594 }, 595 { 596 testSeries(t, opts, 1, "foo.baz", testTags2, 150), 597 xtime.Now(), 456.789, xtime.Second, nil, nil, 598 }, 599 } 600 601 // Call write sync 602 writeCommitLogs(t, scope, commitLog, writes).Wait() 603 604 // Close the commit log and consequently flush 605 require.NoError(t, commitLog.Close()) 606 607 // Assert writes occurred by reading the commit log 608 assertCommitLogWritesByIterating(t, commitLog, writes) 609 610 // Assert commitlog file exists and retrieve path 611 fsopts := opts.FilesystemOptions() 612 files, err := fs.SortedCommitLogFiles(fs.CommitLogsDirPath(fsopts.FilePathPrefix())) 613 require.NoError(t, err) 614 require.Equal(t, 2, len(files)) 615 616 // Assert commitlog cannot be opened more than once 617 reader := NewReader(ReaderOptions{commitLogOptions: opts}) 618 _, err = reader.Open(files[0]) 619 require.NoError(t, err) 620 reader.Close() 621 _, err = reader.Open(files[0]) 622 require.Equal(t, errCommitLogReaderIsNotReusable, err) 623 } 624 625 func TestCommitLogIteratorUsesPredicateFilterForNonCorruptFiles(t *testing.T) { 626 start := xtime.Now() 627 ft := &mockTime{t: start} 628 opts, scope := newTestOptions(t, overrides{ 629 nowFn: ft.Now, 630 strategy: StrategyWriteWait, 631 }) 632 633 // Writes spaced apart by block size. 634 writes := []testWrite{ 635 { 636 testSeries(t, opts, 0, "foo.bar", testTags1, 127), start, 123.456, 637 xtime.Millisecond, nil, nil, 638 }, 639 { 640 testSeries(t, opts, 1, "foo.baz", testTags2, 150), start.Add(1 * time.Second), 641 456.789, xtime.Millisecond, nil, nil, 642 }, 643 { 644 testSeries(t, opts, 2, "foo.qux", testTags3, 291), start.Add(2 * time.Second), 645 789.123, xtime.Millisecond, nil, nil, 646 }, 647 } 648 defer cleanup(t, opts) 649 650 commitLog := newTestCommitLog(t, opts) 651 652 // Write, making sure that the clock is set properly for each write. 653 for _, write := range writes { 654 // Modify the time to make sure we're generating commitlog files with different 655 // start times. 656 now := xtime.ToUnixNano(ft.Now()) 657 ft.Add(write.t.Sub(now)) 658 // Rotate frequently to ensure we're generating multiple files. 659 _, err := commitLog.RotateLogs() 660 require.NoError(t, err) 661 writeCommitLogs(t, scope, commitLog, []testWrite{write}) 662 } 663 664 // Close the commit log and consequently flush. 665 require.NoError(t, commitLog.Close()) 666 667 // Make sure multiple commitlog files were generated. 668 fsopts := opts.FilesystemOptions() 669 files, err := fs.SortedCommitLogFiles(fs.CommitLogsDirPath(fsopts.FilePathPrefix())) 670 require.NoError(t, err) 671 require.Equal(t, 5, len(files)) 672 673 // This predicate should eliminate the first commitlog file. 674 commitLogPredicate := func(f FileFilterInfo) bool { 675 require.False(t, f.IsCorrupt) 676 return f.File.Index > 0 677 } 678 679 // Assert that the commitlog iterator honors the predicate and only uses 680 // 2 of the 3 files. 681 iterOpts := IteratorOpts{ 682 CommitLogOptions: opts, 683 FileFilterPredicate: commitLogPredicate, 684 } 685 iter, corruptFiles, err := NewIterator(iterOpts) 686 require.NoError(t, err) 687 require.True(t, len(corruptFiles) <= 1) 688 689 iterStruct := iter.(*iterator) 690 require.True(t, len(iterStruct.files) >= 4) 691 } 692 693 func TestCommitLogIteratorUsesPredicateFilterForCorruptFiles(t *testing.T) { 694 now := xtime.Now() 695 ft := &mockTime{t: now} 696 opts, _ := newTestOptions(t, overrides{ 697 nowFn: ft.Now, 698 strategy: StrategyWriteWait, 699 }) 700 defer cleanup(t, opts) 701 702 commitLog := newTestCommitLog(t, opts) 703 // Close the commit log and consequently flush. 704 require.NoError(t, commitLog.Close()) 705 706 // Make sure a valid commitlog was created. 707 fsopts := opts.FilesystemOptions() 708 files, err := fs.SortedCommitLogFiles(fs.CommitLogsDirPath(fsopts.FilePathPrefix())) 709 require.NoError(t, err) 710 require.Equal(t, 2, len(files)) 711 712 // Write out a corrupt commitlog file. 713 nextCommitlogFilePath, _, err := NextFile(opts) 714 require.NoError(t, err) 715 err = ioutil.WriteFile( 716 nextCommitlogFilePath, []byte("not-a-valid-commitlog-file"), os.FileMode(0o666)) 717 require.NoError(t, err) 718 719 // Make sure the corrupt file is visibile. 720 files, err = fs.SortedCommitLogFiles(fs.CommitLogsDirPath(fsopts.FilePathPrefix())) 721 require.NoError(t, err) 722 require.Equal(t, 3, len(files)) 723 724 // Assert that the corrupt file is returned from the iterator. 725 iterOpts := IteratorOpts{ 726 CommitLogOptions: opts, 727 FileFilterPredicate: ReadAllPredicate(), 728 } 729 iter, corruptFiles, err := NewIterator(iterOpts) 730 require.NoError(t, err) 731 require.Equal(t, 1, len(corruptFiles)) 732 733 iterStruct := iter.(*iterator) 734 require.Equal(t, 2, len(iterStruct.files)) 735 736 // Assert that the iterator ignores the corrupt file given an appropriate predicate. 737 ignoreCorruptPredicate := func(f FileFilterInfo) bool { 738 return !f.IsCorrupt 739 } 740 741 iterOpts = IteratorOpts{ 742 CommitLogOptions: opts, 743 FileFilterPredicate: ignoreCorruptPredicate, 744 } 745 iter, corruptFiles, err = NewIterator(iterOpts) 746 require.NoError(t, err) 747 require.Equal(t, 0, len(corruptFiles)) 748 749 iterStruct = iter.(*iterator) 750 require.Equal(t, 2, len(iterStruct.files)) 751 } 752 753 func TestCommitLogWriteBehind(t *testing.T) { 754 opts, scope := newTestOptions(t, overrides{ 755 strategy: StrategyWriteBehind, 756 }) 757 defer cleanup(t, opts) 758 759 commitLog := newTestCommitLog(t, opts) 760 761 writes := []testWrite{ 762 { 763 testSeries(t, opts, 0, "foo.bar", testTags1, 127), xtime.Now(), 764 123.456, xtime.Millisecond, nil, nil, 765 }, 766 { 767 testSeries(t, opts, 1, "foo.baz", testTags2, 150), xtime.Now(), 768 456.789, xtime.Millisecond, nil, nil, 769 }, 770 { 771 testSeries(t, opts, 2, "foo.qux", testTags3, 291), xtime.Now(), 772 789.123, xtime.Millisecond, nil, nil, 773 }, 774 } 775 776 // Call write behind 777 writeCommitLogs(t, scope, commitLog, writes) 778 779 // Close the commit log and consequently flush 780 require.NoError(t, commitLog.Close()) 781 782 // Assert writes occurred by reading the commit log 783 assertCommitLogWritesByIterating(t, commitLog, writes) 784 } 785 786 func TestCommitLogWriteErrorOnClosed(t *testing.T) { 787 opts, _ := newTestOptions(t, overrides{}) 788 defer cleanup(t, opts) 789 790 commitLog := newTestCommitLog(t, opts) 791 require.NoError(t, commitLog.Close()) 792 793 series := testSeries(t, opts, 0, "foo.bar", testTags1, 127) 794 datapoint := ts.Datapoint{TimestampNanos: xtime.Now(), Value: 123.456} 795 796 ctx := context.NewBackground() 797 defer ctx.Close() 798 799 err := commitLog.Write(ctx, series, datapoint, xtime.Millisecond, nil) 800 require.Error(t, err) 801 require.Equal(t, errCommitLogClosed, err) 802 } 803 804 func TestCommitLogWriteErrorOnFull(t *testing.T) { 805 // Set backlog of size one and don't automatically flush. 806 backlogQueueSize := 1 807 flushInterval := time.Duration(0) 808 opts, _ := newTestOptions(t, overrides{ 809 backlogQueueSize: &backlogQueueSize, 810 flushInterval: &flushInterval, 811 strategy: StrategyWriteBehind, 812 }) 813 defer cleanup(t, opts) 814 var wg sync.WaitGroup 815 wg.Add(1) 816 817 commitLog := newTestCommitLogWithOpts(t, opts, testOnlyOpts{ 818 beforeAsyncWriteFn: func() { 819 // block the background writer from running until after all the commit log entries have been added to 820 // avoid flakes in checking the queue size. 821 wg.Wait() 822 }, 823 }) 824 825 // Test filling queue 826 var writes []testWrite 827 series := testSeries(t, opts, 0, "foo.bar", testTags1, 127) 828 dp := ts.Datapoint{TimestampNanos: xtime.Now(), Value: 123.456} 829 unit := xtime.Millisecond 830 831 ctx := context.NewBackground() 832 defer ctx.Close() 833 834 for { 835 if err := commitLog.Write(ctx, series, dp, unit, nil); err != nil { 836 // Ensure queue full error. 837 require.Equal(t, ErrCommitLogQueueFull, err) 838 require.Equal(t, int64(backlogQueueSize), commitLog.QueueLength()) 839 break 840 } 841 writes = append(writes, testWrite{series, dp.TimestampNanos, dp.Value, unit, nil, nil}) 842 843 // Increment timestamp and value for next write. 844 dp.TimestampNanos = dp.TimestampNanos.Add(time.Second) 845 dp.Value += 1.0 846 } 847 wg.Done() 848 849 // Close and consequently flush. 850 require.NoError(t, commitLog.Close()) 851 852 // Assert write flushed by reading the commit log. 853 assertCommitLogWritesByIterating(t, commitLog, writes) 854 } 855 856 func TestCommitLogQueueLength(t *testing.T) { 857 // Set backlog of size one and don't automatically flush. 858 backlogQueueSize := 10 859 flushInterval := time.Duration(0) 860 opts, _ := newTestOptions(t, overrides{ 861 backlogQueueSize: &backlogQueueSize, 862 flushInterval: &flushInterval, 863 strategy: StrategyWriteBehind, 864 }) 865 defer cleanup(t, opts) 866 var wg sync.WaitGroup 867 wg.Add(1) 868 869 commitLog := newTestCommitLogWithOpts(t, opts, testOnlyOpts{ 870 beforeAsyncWriteFn: func() { 871 // block the background writer from running until after all the commit log entries have been added to 872 // avoid flakes in checking the queue size. 873 wg.Wait() 874 }, 875 }) 876 defer commitLog.Close() 877 878 var ( 879 series = testSeries(t, opts, 0, "foo.bar", testTags1, 127) 880 dp = ts.Datapoint{TimestampNanos: xtime.Now(), Value: 123.456} 881 unit = xtime.Millisecond 882 ctx = context.NewBackground() 883 ) 884 defer ctx.Close() 885 886 for i := 0; ; i++ { 887 // Write in a loop and check the queue length until the queue is full. 888 require.Equal(t, int64(i), commitLog.QueueLength()) 889 if err := commitLog.Write(ctx, series, dp, unit, nil); err != nil { 890 require.Equal(t, ErrCommitLogQueueFull, err) 891 break 892 } 893 894 // Increment timestamp and value for next write. 895 dp.TimestampNanos = dp.TimestampNanos.Add(time.Second) 896 dp.Value += 1.0 897 } 898 wg.Done() 899 } 900 901 func TestCommitLogFailOnWriteError(t *testing.T) { 902 opts, scope := newTestOptions(t, overrides{ 903 strategy: StrategyWriteBehind, 904 }) 905 defer cleanup(t, opts) 906 907 commitLogI, err := NewCommitLog(opts) 908 require.NoError(t, err) 909 commitLog := commitLogI.(*commitLog) 910 writer := newMockCommitLogWriter() 911 912 writer.writeFn = func(ts.Series, ts.Datapoint, xtime.Unit, ts.Annotation) error { 913 return fmt.Errorf("an error") 914 } 915 916 writer.openFn = func() (persist.CommitLogFile, error) { 917 return persist.CommitLogFile{}, nil 918 } 919 920 writer.flushFn = func(bool) error { 921 commitLog.writerState.primary.onFlush(nil) 922 return nil 923 } 924 925 commitLog.newCommitLogWriterFn = func( 926 _ flushFn, 927 _ Options, 928 ) commitLogWriter { 929 return writer 930 } 931 932 require.NoError(t, commitLog.Open()) 933 934 wg := setupCloseOnFail(t, commitLog) 935 936 writes := []testWrite{ 937 { 938 testSeries(t, opts, 0, "foo.bar", testTags1, 127), xtime.Now(), 939 123.456, xtime.Millisecond, nil, nil, 940 }, 941 } 942 943 writeCommitLogs(t, scope, commitLog, writes) 944 945 wg.Wait() 946 947 // Check stats 948 errors, ok := snapshotCounterValue(scope, "commitlog.writes.errors") 949 require.True(t, ok) 950 require.Equal(t, int64(1), errors.Value()) 951 } 952 953 func TestCommitLogFailOnOpenError(t *testing.T) { 954 opts, scope := newTestOptions(t, overrides{ 955 strategy: StrategyWriteBehind, 956 }) 957 defer cleanup(t, opts) 958 959 commitLogI, err := NewCommitLog(opts) 960 require.NoError(t, err) 961 commitLog := commitLogI.(*commitLog) 962 writer := newMockCommitLogWriter() 963 964 var opens int64 965 writer.openFn = func() (persist.CommitLogFile, error) { 966 if atomic.AddInt64(&opens, 1) >= 3 { 967 return persist.CommitLogFile{}, fmt.Errorf("an error") 968 } 969 return persist.CommitLogFile{}, nil 970 } 971 972 writer.flushFn = func(bool) error { 973 commitLog.writerState.primary.onFlush(nil) 974 return nil 975 } 976 977 commitLog.newCommitLogWriterFn = func( 978 _ flushFn, 979 _ Options, 980 ) commitLogWriter { 981 return writer 982 } 983 984 require.NoError(t, commitLog.Open()) 985 986 wg := setupCloseOnFail(t, commitLog) 987 988 writes := []testWrite{ 989 { 990 testSeries(t, opts, 0, "foo.bar", testTags1, 127), xtime.Now(), 991 123.456, xtime.Millisecond, nil, nil, 992 }, 993 } 994 995 writeCommitLogs(t, scope, commitLog, writes) 996 997 // Rotate the commitlog so that it requires a new open. 998 commitLog.RotateLogs() 999 1000 wg.Wait() 1001 // Secondary writer open is async so wait for it to complete before asserting 1002 // that it failed. 1003 commitLog.waitForSecondaryWriterAsyncResetComplete() 1004 1005 // Check stats 1006 errors, ok := snapshotCounterValue(scope, "commitlog.writes.errors") 1007 require.True(t, ok) 1008 require.Equal(t, int64(1), errors.Value()) 1009 1010 openErrors, ok := snapshotCounterValue(scope, "commitlog.writes.open-errors") 1011 require.True(t, ok) 1012 require.Equal(t, int64(1), openErrors.Value()) 1013 } 1014 1015 func TestCommitLogFailOnFlushError(t *testing.T) { 1016 opts, scope := newTestOptions(t, overrides{ 1017 strategy: StrategyWriteBehind, 1018 }) 1019 defer cleanup(t, opts) 1020 1021 commitLogI, err := NewCommitLog(opts) 1022 require.NoError(t, err) 1023 commitLog := commitLogI.(*commitLog) 1024 writer := newMockCommitLogWriter() 1025 1026 var flushes int64 1027 writer.flushFn = func(bool) error { 1028 if atomic.AddInt64(&flushes, 1) >= 2 { 1029 commitLog.writerState.primary.onFlush(fmt.Errorf("an error")) 1030 } else { 1031 commitLog.writerState.primary.onFlush(nil) 1032 } 1033 return nil 1034 } 1035 1036 commitLog.newCommitLogWriterFn = func( 1037 _ flushFn, 1038 _ Options, 1039 ) commitLogWriter { 1040 return writer 1041 } 1042 1043 require.NoError(t, commitLog.Open()) 1044 1045 wg := setupCloseOnFail(t, commitLog) 1046 1047 writes := []testWrite{ 1048 { 1049 testSeries(t, opts, 0, "foo.bar", testTags1, 127), xtime.Now(), 1050 123.456, xtime.Millisecond, nil, nil, 1051 }, 1052 } 1053 1054 writeCommitLogs(t, scope, commitLog, writes) 1055 1056 wg.Wait() 1057 1058 // Check stats 1059 errors, ok := snapshotCounterValue(scope, "commitlog.writes.errors") 1060 require.True(t, ok) 1061 require.Equal(t, int64(2), errors.Value()) 1062 1063 flushErrors, ok := snapshotCounterValue(scope, "commitlog.writes.flush-errors") 1064 require.True(t, ok) 1065 require.Equal(t, int64(2), flushErrors.Value()) 1066 } 1067 1068 func TestCommitLogActiveLogs(t *testing.T) { 1069 opts, _ := newTestOptions(t, overrides{ 1070 strategy: StrategyWriteBehind, 1071 }) 1072 defer cleanup(t, opts) 1073 1074 commitLog := newTestCommitLog(t, opts) 1075 1076 writer := newMockCommitLogWriter() 1077 writer.flushFn = func(bool) error { 1078 return nil 1079 } 1080 commitLog.newCommitLogWriterFn = func( 1081 _ flushFn, 1082 _ Options, 1083 ) commitLogWriter { 1084 return writer 1085 } 1086 1087 logs, err := commitLog.ActiveLogs() 1088 require.NoError(t, err) 1089 require.Equal(t, 2, len(logs)) 1090 1091 // Close the commit log and consequently flush 1092 require.NoError(t, commitLog.Close()) 1093 _, err = commitLog.ActiveLogs() 1094 require.Error(t, err) 1095 } 1096 1097 func TestCommitLogRotateLogs(t *testing.T) { 1098 var ( 1099 start = xtime.Now() 1100 clock = &mockTime{t: start} 1101 opts, scope = newTestOptions(t, overrides{ 1102 nowFn: clock.Now, 1103 strategy: StrategyWriteWait, 1104 }) 1105 ) 1106 defer cleanup(t, opts) 1107 1108 commitLog := newTestCommitLog(t, opts) 1109 1110 // Writes spaced such that they should appear within the same commitlog block. 1111 writes := []testWrite{ 1112 { 1113 testSeries(t, opts, 0, "foo.bar", testTags1, 127), 1114 start, 1115 123.456, xtime.Millisecond, nil, nil, 1116 }, 1117 { 1118 testSeries(t, opts, 1, "foo.baz", testTags2, 150), 1119 start.Add(1 * time.Second), 1120 456.789, xtime.Millisecond, nil, nil, 1121 }, 1122 { 1123 testSeries(t, opts, 2, "foo.qux", testTags3, 291), 1124 start.Add(2 * time.Second), 1125 789.123, xtime.Millisecond, nil, nil, 1126 }, 1127 } 1128 1129 for i, write := range writes { 1130 // Set clock to align with the write. 1131 clock.Add(write.t.Sub(start)) 1132 // Write entry. 1133 writeCommitLogs(t, scope, commitLog, []testWrite{write}) 1134 1135 file, err := commitLog.RotateLogs() 1136 require.NoError(t, err) 1137 require.Equal(t, file.Index, int64(i+1)) 1138 require.Contains(t, file.FilePath, "commitlog-0") 1139 } 1140 1141 // Secondary writer open is async so wait for it to complete so that its safe to assert 1142 // on the number of files that should be on disk otherwise test will flake depending 1143 // on whether or not the async open completed in time. 1144 commitLog.waitForSecondaryWriterAsyncResetComplete() 1145 1146 // Ensure files present for each call to RotateLogs(). 1147 fsopts := opts.FilesystemOptions() 1148 files, err := fs.SortedCommitLogFiles(fs.CommitLogsDirPath(fsopts.FilePathPrefix())) 1149 require.NoError(t, err) 1150 require.Equal(t, len(writes)+2, len(files)) // +2 to account for the initial files. 1151 1152 // Close and consequently flush. 1153 require.NoError(t, commitLog.Close()) 1154 1155 // Assert write flushed by reading the commit log. 1156 assertCommitLogWritesByIterating(t, commitLog, writes) 1157 } 1158 1159 var ( 1160 testTag0 = ident.StringTag("name0", "val0") 1161 testTag1 = ident.StringTag("name1", "val1") 1162 testTag2 = ident.StringTag("name2", "val2") 1163 testTag3 = ident.StringTag("name3", "val3") 1164 1165 testTags0 = ident.NewTags(testTag0) 1166 testTags1 = ident.NewTags(testTag1) 1167 testTags2 = ident.NewTags(testTag2) 1168 testTags3 = ident.NewTags(testTag3) 1169 ) 1170 1171 func TestCommitLogBatchWriteDoesNotAddErroredOrSkippedSeries(t *testing.T) { 1172 opts, scope := newTestOptions(t, overrides{ 1173 strategy: StrategyWriteWait, 1174 }) 1175 1176 defer cleanup(t, opts) 1177 commitLog := newTestCommitLog(t, opts) 1178 finalized := 0 1179 finalizeFn := func(_ writes.WriteBatch) { 1180 finalized++ 1181 } 1182 1183 writes := writes.NewWriteBatch(0, ident.StringID("ns"), finalizeFn) 1184 1185 testSeriesWrites := []ts.Series{ 1186 testSeries(t, opts, 0, "foo.bar", testTags0, 42), 1187 testSeries(t, opts, 1, "foo.baz", testTags1, 127), 1188 testSeries(t, opts, 2, "biz.qaz", testTags2, 321), 1189 testSeries(t, opts, 3, "biz.qux", testTags3, 511), 1190 } 1191 alignedStart := xtime.Now().Truncate(time.Hour) 1192 for i := 0; i < 4; i++ { 1193 tt := alignedStart.Add(time.Minute * time.Duration(i)) 1194 tagsIter := opts.FilesystemOptions().TagDecoderPool().Get() 1195 tagsIter.Reset(checked.NewBytes(testSeriesWrites[i].EncodedTags, nil)) 1196 require.NoError(t, writes.AddTagged(i, testSeriesWrites[i].ID, 1197 testSeriesWrites[i].EncodedTags, 1198 tt, float64(i)*10.5, xtime.Second, nil)) 1199 } 1200 1201 writes.SetSkipWrite(0) 1202 writes.SetSeries(1, testSeries(t, opts, 1, "foo.baz", testTags1, 127)) 1203 writes.SetError(2, errors.New("oops")) 1204 writes.SetSeries(3, testSeries(t, opts, 3, "biz.qux", testTags3, 511)) 1205 1206 // Call write batch sync 1207 wg := sync.WaitGroup{} 1208 1209 getAllWrites := func() int { 1210 result := int64(0) 1211 success, ok := snapshotCounterValue(scope, "commitlog.writes.success") 1212 if ok { 1213 result += success.Value() 1214 } 1215 errors, ok := snapshotCounterValue(scope, "commitlog.writes.errors") 1216 if ok { 1217 result += errors.Value() 1218 } 1219 return int(result) 1220 } 1221 1222 ctx := context.NewBackground() 1223 defer ctx.Close() 1224 1225 wg.Add(1) 1226 go func() { 1227 defer wg.Done() 1228 err := commitLog.WriteBatch(ctx, writes) 1229 require.NoError(t, err) 1230 }() 1231 1232 // Wait for all writes to enqueue 1233 for getAllWrites() != 2 { 1234 time.Sleep(time.Microsecond) 1235 } 1236 1237 wg.Wait() 1238 1239 // Close the commit log and consequently flush 1240 require.NoError(t, commitLog.Close()) 1241 1242 // Assert writes occurred by reading the commit log 1243 expected := []testWrite{ 1244 { 1245 testSeries(t, opts, 1, "foo.baz", testTags1, 127), 1246 alignedStart.Add(time.Minute), 10.5, xtime.Second, nil, nil, 1247 }, 1248 { 1249 testSeries(t, opts, 3, "biz.qux", testTags3, 511), 1250 alignedStart.Add(time.Minute * 3), 31.5, xtime.Second, nil, nil, 1251 }, 1252 } 1253 1254 assertCommitLogWritesByIterating(t, commitLog, expected) 1255 require.Equal(t, 1, finalized) 1256 }