sampler_test.go

Documentation: go.uber.org/zap/zapcore

     1  // Copyright (c) 2016-2022 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 zapcore_test
    22  
    23  import (
    24  	"fmt"
    25  	"runtime"
    26  	"sync"
    27  	"sync/atomic"
    28  	"testing"
    29  	"time"
    30  
    31  	"go.uber.org/zap/internal/ztest"
    32  	//revive:disable:dot-imports
    33  	. "go.uber.org/zap/zapcore"
    34  	"go.uber.org/zap/zaptest/observer"
    35  
    36  	"github.com/stretchr/testify/assert"
    37  	"github.com/stretchr/testify/require"
    38  )
    39  
    40  func fakeSampler(lvl LevelEnabler, tick time.Duration, first, thereafter int) (Core, *observer.ObservedLogs) {
    41  	core, logs := observer.New(lvl)
    42  	// Keep using deprecated constructor for cc.
    43  	core = NewSampler(core, tick, first, thereafter)
    44  	return core, logs
    45  }
    46  
    47  func assertSequence(t testing.TB, logs []observer.LoggedEntry, lvl Level, seq ...int64) {
    48  	seen := make([]int64, len(logs))
    49  	for i, entry := range logs {
    50  		require.Equal(t, "", entry.Message, "Message wasn't created by writeSequence.")
    51  		require.Equal(t, 1, len(entry.Context), "Unexpected number of fields.")
    52  		require.Equal(t, lvl, entry.Level, "Unexpected level.")
    53  		f := entry.Context[0]
    54  		require.Equal(t, "iter", f.Key, "Unexpected field key.")
    55  		require.Equal(t, Int64Type, f.Type, "Unexpected field type")
    56  		seen[i] = f.Integer
    57  	}
    58  	assert.Equal(t, seq, seen, "Unexpected sequence logged at level %v.", lvl)
    59  }
    60  
    61  func writeSequence(core Core, n int, lvl Level) {
    62  	// All tests using writeSequence verify that counters are shared between
    63  	// parent and child cores.
    64  	core = core.With([]Field{makeInt64Field("iter", n)})
    65  	if ce := core.Check(Entry{Level: lvl, Time: time.Now()}, nil); ce != nil {
    66  		ce.Write()
    67  	}
    68  }
    69  
    70  func TestSampler(t *testing.T) {
    71  	for _, lvl := range []Level{DebugLevel, InfoLevel, WarnLevel, ErrorLevel, DPanicLevel, PanicLevel, FatalLevel} {
    72  		sampler, logs := fakeSampler(DebugLevel, time.Minute, 2, 3)
    73  
    74  		// Ensure that counts aren't shared between levels.
    75  		probeLevel := DebugLevel
    76  		if lvl == DebugLevel {
    77  			probeLevel = InfoLevel
    78  		}
    79  		for i := 0; i < 10; i++ {
    80  			writeSequence(sampler, 1, probeLevel)
    81  		}
    82  		// Clear any output.
    83  		logs.TakeAll()
    84  
    85  		for i := 1; i < 10; i++ {
    86  			writeSequence(sampler, i, lvl)
    87  		}
    88  		assertSequence(t, logs.TakeAll(), lvl, 1, 2, 5, 8)
    89  	}
    90  }
    91  
    92  func TestLevelOfSampler(t *testing.T) {
    93  	levels := []Level{DebugLevel, InfoLevel, WarnLevel, ErrorLevel, DPanicLevel, PanicLevel, FatalLevel}
    94  	for _, lvl := range levels {
    95  		lvl := lvl
    96  		t.Run(lvl.String(), func(t *testing.T) {
    97  			t.Parallel()
    98  
    99  			sampler, _ := fakeSampler(lvl, time.Minute, 2, 3)
   100  			assert.Equal(t, lvl, LevelOf(sampler), "Sampler level did not match.")
   101  		})
   102  	}
   103  }
   104  
   105  func TestSamplerDisabledLevels(t *testing.T) {
   106  	sampler, logs := fakeSampler(InfoLevel, time.Minute, 1, 100)
   107  
   108  	// Shouldn't be counted, because debug logging isn't enabled.
   109  	writeSequence(sampler, 1, DebugLevel)
   110  	writeSequence(sampler, 2, InfoLevel)
   111  	assertSequence(t, logs.TakeAll(), InfoLevel, 2)
   112  }
   113  
   114  func TestSamplerTicking(t *testing.T) {
   115  	// Ensure that we're resetting the sampler's counter every tick.
   116  	sampler, logs := fakeSampler(DebugLevel, 10*time.Millisecond, 5, 10)
   117  
   118  	// If we log five or fewer messages every tick, none of them should be
   119  	// dropped.
   120  	for tick := 0; tick < 2; tick++ {
   121  		for i := 1; i <= 5; i++ {
   122  			writeSequence(sampler, i, InfoLevel)
   123  		}
   124  		ztest.Sleep(15 * time.Millisecond)
   125  	}
   126  	assertSequence(
   127  		t,
   128  		logs.TakeAll(),
   129  		InfoLevel,
   130  		1, 2, 3, 4, 5, // first tick
   131  		1, 2, 3, 4, 5, // second tick
   132  	)
   133  
   134  	// If we log quickly, we should drop some logs. The first five statements
   135  	// each tick should be logged, then every tenth.
   136  	for tick := 0; tick < 3; tick++ {
   137  		for i := 1; i < 18; i++ {
   138  			writeSequence(sampler, i, InfoLevel)
   139  		}
   140  		ztest.Sleep(10 * time.Millisecond)
   141  	}
   142  
   143  	assertSequence(
   144  		t,
   145  		logs.TakeAll(),
   146  		InfoLevel,
   147  		1, 2, 3, 4, 5, 15, // first tick
   148  		1, 2, 3, 4, 5, 15, // second tick
   149  		1, 2, 3, 4, 5, 15, // third tick
   150  	)
   151  }
   152  
   153  type countingCore struct {
   154  	logs atomic.Uint32
   155  }
   156  
   157  func (c *countingCore) Check(ent Entry, ce *CheckedEntry) *CheckedEntry {
   158  	return ce.AddCore(ent, c)
   159  }
   160  
   161  func (c *countingCore) Write(Entry, []Field) error {
   162  	c.logs.Add(1)
   163  	return nil
   164  }
   165  
   166  func (c *countingCore) With([]Field) Core { return c }
   167  func (*countingCore) Enabled(Level) bool  { return true }
   168  func (*countingCore) Sync() error         { return nil }
   169  
   170  func TestSamplerConcurrent(t *testing.T) {
   171  	const (
   172  		logsPerTick   = 10
   173  		numMessages   = 5
   174  		numTicks      = 25
   175  		numGoroutines = 10
   176  		tick          = 10 * time.Millisecond
   177  
   178  		// We'll make a total of,
   179  		// (numGoroutines * numTicks * logsPerTick * 2) log attempts
   180  		// with numMessages unique messages.
   181  		numLogAttempts = numGoroutines * logsPerTick * numTicks * 2
   182  		// Of those, we'll accept (logsPerTick * numTicks) entries
   183  		// for each unique message.
   184  		expectedCount = numMessages * logsPerTick * numTicks
   185  		// The rest will be dropped.
   186  		expectedDropped = numLogAttempts - expectedCount
   187  	)
   188  
   189  	clock := ztest.NewMockClock()
   190  
   191  	cc := &countingCore{}
   192  
   193  	hook, dropped, sampled := makeSamplerCountingHook()
   194  	sampler := NewSamplerWithOptions(cc, tick, logsPerTick, 100000, SamplerHook(hook))
   195  
   196  	stop := make(chan struct{})
   197  	var wg sync.WaitGroup
   198  	for i := 0; i < numGoroutines; i++ {
   199  		wg.Add(1)
   200  		go func(i int, ticker *time.Ticker) {
   201  			defer wg.Done()
   202  			defer ticker.Stop()
   203  
   204  			for {
   205  				select {
   206  				case <-stop:
   207  					return
   208  
   209  				case <-ticker.C:
   210  					for j := 0; j < logsPerTick*2; j++ {
   211  						msg := fmt.Sprintf("msg%v", i%numMessages)
   212  						ent := Entry{
   213  							Level:   DebugLevel,
   214  							Message: msg,
   215  							Time:    clock.Now(),
   216  						}
   217  						if ce := sampler.Check(ent, nil); ce != nil {
   218  							ce.Write()
   219  						}
   220  
   221  						// Give a chance for other goroutines to run.
   222  						runtime.Gosched()
   223  					}
   224  				}
   225  			}
   226  		}(i, clock.NewTicker(tick))
   227  	}
   228  
   229  	clock.Add(tick * numTicks)
   230  	close(stop)
   231  	wg.Wait()
   232  
   233  	assert.Equal(
   234  		t,
   235  		expectedCount,
   236  		int(cc.logs.Load()),
   237  		"Unexpected number of logs",
   238  	)
   239  	assert.Equal(t,
   240  		expectedCount,
   241  		int(sampled.Load()),
   242  		"Unexpected number of logs sampled",
   243  	)
   244  	assert.Equal(t,
   245  		expectedDropped,
   246  		int(dropped.Load()),
   247  		"Unexpected number of logs dropped",
   248  	)
   249  }
   250  
   251  func TestSamplerRaces(t *testing.T) {
   252  	sampler, _ := fakeSampler(DebugLevel, time.Minute, 1, 1000)
   253  
   254  	var wg sync.WaitGroup
   255  	start := make(chan struct{})
   256  
   257  	for i := 0; i < 100; i++ {
   258  		wg.Add(1)
   259  		go func() {
   260  			<-start
   261  			for j := 0; j < 100; j++ {
   262  				writeSequence(sampler, j, InfoLevel)
   263  			}
   264  			wg.Done()
   265  		}()
   266  	}
   267  
   268  	close(start)
   269  	wg.Wait()
   270  }
   271  
   272  func TestSamplerUnknownLevels(t *testing.T) {
   273  	// Prove that out-of-bounds levels don't panic.
   274  	unknownLevels := []Level{
   275  		DebugLevel - 1,
   276  		FatalLevel + 1,
   277  	}
   278  
   279  	for _, lvl := range unknownLevels {
   280  		t.Run(lvl.String(), func(t *testing.T) {
   281  			sampler, logs := fakeSampler(lvl, time.Minute, 2, 3)
   282  			for i := 1; i < 10; i++ {
   283  				writeSequence(sampler, i, lvl)
   284  			}
   285  
   286  			// Expect no sampling for unknown levels.
   287  			assertSequence(t, logs.TakeAll(), lvl, 1, 2, 3, 4, 5, 6, 7, 8, 9)
   288  		})
   289  	}
   290  }
   291  
   292  func TestSamplerWithZeroThereafter(t *testing.T) {
   293  	var counter countingCore
   294  
   295  	// Logs two messages per second.
   296  	sampler := NewSamplerWithOptions(&counter, time.Second, 2, 0)
   297  
   298  	now := time.Now()
   299  
   300  	for i := 0; i < 1000; i++ {
   301  		ent := Entry{
   302  			Level:   InfoLevel,
   303  			Message: "msg",
   304  			Time:    now,
   305  		}
   306  		if ce := sampler.Check(ent, nil); ce != nil {
   307  			ce.Write()
   308  		}
   309  	}
   310  
   311  	assert.Equal(t, 2, int(counter.logs.Load()),
   312  		"Unexpected number of logs")
   313  
   314  	now = now.Add(time.Second)
   315  
   316  	for i := 0; i < 1000; i++ {
   317  		ent := Entry{
   318  			Level:   InfoLevel,
   319  			Message: "msg",
   320  			Time:    now,
   321  		}
   322  		if ce := sampler.Check(ent, nil); ce != nil {
   323  			ce.Write()
   324  		}
   325  	}
   326  
   327  	assert.Equal(t, 4, int(counter.logs.Load()),
   328  		"Unexpected number of logs")
   329  }
   330
View as plain text