Source file src/github.com/golang/glog/glog_test.go

Documentation: github.com/golang/glog

     1  package glog
     2  
     3  import (
     4  	"bytes"
     5  	"context"
     6  	"flag"
     7  	"fmt"
     8  	"io/ioutil"
     9  	stdLog "log"
    10  	"path/filepath"
    11  	"runtime"
    12  	"strconv"
    13  	"strings"
    14  	"testing"
    15  	"time"
    16  
    17  	"github.com/golang/glog/internal/logsink"
    18  )
    19  
    20  // Test that shortHostname works as advertised.
    21  func TestShortHostname(t *testing.T) {
    22  	for hostname, expect := range map[string]string{
    23  		"":                     "",
    24  		"host":                 "host",
    25  		"host.google.com":      "host",
    26  		"host.corp.google.com": "host",
    27  	} {
    28  		if got := shortHostname(hostname); expect != got {
    29  			t.Errorf("shortHostname(%q): expected %q, got %q", hostname, expect, got)
    30  		}
    31  	}
    32  }
    33  
    34  // flushBuffer wraps a bytes.Buffer to satisfy flushSyncWriter.
    35  type flushBuffer struct {
    36  	bytes.Buffer
    37  }
    38  
    39  func (f *flushBuffer) Flush() error {
    40  	f.Buffer.Reset()
    41  	return nil
    42  }
    43  
    44  func (f *flushBuffer) Sync() error {
    45  	return nil
    46  }
    47  
    48  func (f *flushBuffer) filenames() []string {
    49  	return []string{"<local name>"}
    50  }
    51  
    52  // swap sets the log writers and returns the old array.
    53  func (s *fileSink) swap(writers severityWriters) (old severityWriters) {
    54  	s.mu.Lock()
    55  	defer s.mu.Unlock()
    56  	old = s.file
    57  	for i, w := range writers {
    58  		s.file[i] = w
    59  	}
    60  	return
    61  }
    62  
    63  // newBuffers sets the log writers to all new byte buffers and returns the old array.
    64  func (s *fileSink) newBuffers() severityWriters {
    65  	return s.swap(severityWriters{new(flushBuffer), new(flushBuffer), new(flushBuffer), new(flushBuffer)})
    66  }
    67  
    68  func (s *fileSink) resetBuffers() {
    69  	s.mu.Lock()
    70  	defer s.mu.Unlock()
    71  	for _, buf := range s.file {
    72  		if buf != nil {
    73  			buf.Flush()
    74  		}
    75  	}
    76  }
    77  
    78  // contents returns the specified log value as a string.
    79  func contents(s logsink.Severity) string {
    80  	return sinks.file.file[s].(*flushBuffer).String()
    81  }
    82  
    83  // contains reports whether the string is contained in the log.
    84  func contains(s logsink.Severity, str string, t *testing.T) bool {
    85  	return strings.Contains(contents(s), str)
    86  }
    87  
    88  // setFlags configures the logging flags how the test expects them.
    89  func setFlags() {
    90  	toStderr = false
    91  }
    92  
    93  // Test that Info works as advertised.
    94  func TestInfo(t *testing.T) {
    95  	setFlags()
    96  	defer sinks.file.swap(sinks.file.newBuffers())
    97  	funcs := []func(args ...any){
    98  		Info,
    99  		func(args ...any) { InfoContext(context.Background(), args) },
   100  	}
   101  
   102  	for _, f := range funcs {
   103  		sinks.file.resetBuffers()
   104  		f("test")
   105  		if !contains(logsink.Info, "I", t) {
   106  			t.Errorf("Info has wrong character: %q", contents(logsink.Info))
   107  		}
   108  		if !contains(logsink.Info, "test", t) {
   109  			t.Error("Info failed")
   110  		}
   111  	}
   112  }
   113  
   114  func TestInfoDepth(t *testing.T) {
   115  	setFlags()
   116  	defer sinks.file.swap(sinks.file.newBuffers())
   117  
   118  	funcs := []func(d int, args ...any){
   119  		InfoDepth,
   120  		func(d int, args ...any) { InfoContextDepth(context.Background(), d+1, args) },
   121  	}
   122  
   123  	for _, infoDepth := range funcs {
   124  		sinks.file.resetBuffers()
   125  		f := func() { infoDepth(1, "depth-test1") }
   126  
   127  		// The next three lines must stay together
   128  		_, _, wantLine, _ := runtime.Caller(0)
   129  		infoDepth(0, "depth-test0")
   130  		f()
   131  
   132  		msgs := strings.Split(strings.TrimSuffix(contents(logsink.Info), "\n"), "\n")
   133  		if len(msgs) != 2 {
   134  			t.Fatalf("Got %d lines, expected 2", len(msgs))
   135  		}
   136  
   137  		for i, m := range msgs {
   138  			if !strings.HasPrefix(m, "I") {
   139  				t.Errorf("InfoDepth[%d] has wrong character: %q", i, m)
   140  			}
   141  			w := fmt.Sprintf("depth-test%d", i)
   142  			if !strings.Contains(m, w) {
   143  				t.Errorf("InfoDepth[%d] missing %q: %q", i, w, m)
   144  			}
   145  
   146  			// pull out the line number (between : and ])
   147  			msg := m[strings.LastIndex(m, ":")+1:]
   148  			x := strings.Index(msg, "]")
   149  			if x < 0 {
   150  				t.Errorf("InfoDepth[%d]: missing ']': %q", i, m)
   151  				continue
   152  			}
   153  			line, err := strconv.Atoi(msg[:x])
   154  			if err != nil {
   155  				t.Errorf("InfoDepth[%d]: bad line number: %q", i, m)
   156  				continue
   157  			}
   158  			wantLine++
   159  			if wantLine != line {
   160  				t.Errorf("InfoDepth[%d]: got line %d, want %d", i, line, wantLine)
   161  			}
   162  		}
   163  	}
   164  }
   165  
   166  func init() {
   167  	CopyStandardLogTo("INFO")
   168  }
   169  
   170  // Test that CopyStandardLogTo panics on bad input.
   171  func TestCopyStandardLogToPanic(t *testing.T) {
   172  	defer func() {
   173  		if s, ok := recover().(string); !ok || !strings.Contains(s, "LOG") {
   174  			t.Errorf(`CopyStandardLogTo("LOG") should have panicked: %v`, s)
   175  		}
   176  	}()
   177  	CopyStandardLogTo("LOG")
   178  }
   179  
   180  // Test that using the standard log package logs to INFO.
   181  func TestStandardLog(t *testing.T) {
   182  	setFlags()
   183  	defer sinks.file.swap(sinks.file.newBuffers())
   184  	stdLog.Print("test")
   185  	if !contains(logsink.Info, "I", t) {
   186  		t.Errorf("Info has wrong character: %q", contents(logsink.Info))
   187  	}
   188  	if !contains(logsink.Info, "test", t) {
   189  		t.Error("Info failed")
   190  	}
   191  }
   192  
   193  // Test that the header has the correct format.
   194  func TestHeader(t *testing.T) {
   195  	setFlags()
   196  	defer func(previous func() time.Time) { timeNow = previous }(timeNow)
   197  	timeNow = func() time.Time {
   198  		return time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.Local)
   199  	}
   200  
   201  	oldPID := pid
   202  	defer func() { pid = oldPID }()
   203  	pid = 1234
   204  
   205  	defer sinks.file.swap(sinks.file.newBuffers())
   206  
   207  	Info("testHeader")
   208  	var line int
   209  	format := "I0102 15:04:05.067890 %7d glog_test.go:%d] testHeader\n"
   210  	var gotPID int64
   211  	n, err := fmt.Sscanf(contents(logsink.Info), format, &gotPID, &line)
   212  	if n != 2 || err != nil {
   213  		t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(logsink.Info))
   214  	}
   215  
   216  	if want := int64(pid); gotPID != want {
   217  		t.Errorf("expected log line to be logged with process ID %d, got %d", want, gotPID)
   218  	}
   219  
   220  	// Scanf treats multiple spaces as equivalent to a single space,
   221  	// so check for correct space-padding also.
   222  	want := fmt.Sprintf(format, gotPID, line)
   223  	if contents(logsink.Info) != want {
   224  		t.Errorf("log format error: got:\n\t%q\nwant:\n\t%q", contents(logsink.Info), want)
   225  	}
   226  
   227  }
   228  
   229  // Test that an Error log goes to Warning and Info.
   230  // Even in the Info log, the source character will be E, so the data should
   231  // all be identical.
   232  func TestError(t *testing.T) {
   233  	setFlags()
   234  	defer sinks.file.swap(sinks.file.newBuffers())
   235  
   236  	funcs := []func(args ...any){
   237  		Error,
   238  		func(args ...any) { ErrorContext(context.Background(), args) },
   239  	}
   240  
   241  	for _, error := range funcs {
   242  		sinks.file.resetBuffers()
   243  		error("test")
   244  		if !contains(logsink.Error, "E", t) {
   245  			t.Errorf("Error has wrong character: %q", contents(logsink.Error))
   246  		}
   247  		if !contains(logsink.Error, "test", t) {
   248  			t.Error("Error failed")
   249  		}
   250  		str := contents(logsink.Error)
   251  		if !contains(logsink.Warning, str, t) {
   252  			t.Error("Warning failed")
   253  		}
   254  		if !contains(logsink.Info, str, t) {
   255  			t.Error("Info failed")
   256  		}
   257  	}
   258  }
   259  
   260  // Test that a Warning log goes to Info.
   261  // Even in the Info log, the source character will be W, so the data should
   262  // all be identical.
   263  func TestWarning(t *testing.T) {
   264  	setFlags()
   265  	defer sinks.file.swap(sinks.file.newBuffers())
   266  
   267  	funcs := []func(args ...any){
   268  		Warning,
   269  		func(args ...any) { WarningContext(context.Background(), args) },
   270  	}
   271  
   272  	for _, warning := range funcs {
   273  		sinks.file.resetBuffers()
   274  		warning("test")
   275  		if !contains(logsink.Warning, "W", t) {
   276  			t.Errorf("Warning has wrong character: %q", contents(logsink.Warning))
   277  		}
   278  		if !contains(logsink.Warning, "test", t) {
   279  			t.Error("Warning failed")
   280  		}
   281  		str := contents(logsink.Warning)
   282  		if !contains(logsink.Info, str, t) {
   283  			t.Error("Info failed")
   284  		}
   285  	}
   286  }
   287  
   288  // Test that a V log goes to Info.
   289  func TestV(t *testing.T) {
   290  	setFlags()
   291  	defer sinks.file.swap(sinks.file.newBuffers())
   292  	if err := flag.Lookup("v").Value.Set("2"); err != nil {
   293  		t.Fatalf("Failed to set -v=2: %v", err)
   294  	}
   295  	defer flag.Lookup("v").Value.Set("0")
   296  
   297  	funcs := []func(args ...any){
   298  		V(2).Info,
   299  		func(args ...any) { V(2).InfoContext(context.Background(), args) },
   300  	}
   301  	for _, info := range funcs {
   302  		sinks.file.resetBuffers()
   303  		info("test")
   304  		if !contains(logsink.Info, "I", t) {
   305  			t.Errorf("Info has wrong character: %q", contents(logsink.Info))
   306  		}
   307  		if !contains(logsink.Info, "test", t) {
   308  			t.Error("Info failed")
   309  		}
   310  	}
   311  }
   312  
   313  // Test that updating -v at runtime, while -vmodule is set to a non-empty
   314  // value, resets the modules cache correctly.
   315  func TestVFlagUpdates(t *testing.T) {
   316  	setFlags()
   317  	defer sinks.file.swap(sinks.file.newBuffers())
   318  	// Set -vmodule to some arbitrary value to make values read from cache.
   319  	// See log_flags.go:/func .* enabled/.
   320  	if err := flag.Lookup("vmodule").Value.Set("non_existent_module=3"); err != nil {
   321  		t.Fatalf("Failed to set -vmodule=log_test=3: %v", err)
   322  	}
   323  	defer flag.Lookup("vmodule").Value.Set("")
   324  	if err := flag.Lookup("v").Value.Set("3"); err != nil {
   325  		t.Fatalf("Failed to set -v=3: %v", err)
   326  	}
   327  	defer flag.Lookup("v").Value.Set("0")
   328  
   329  	if !V(2) {
   330  		t.Error("V(2) not enabled for 2")
   331  	}
   332  	if !V(3) {
   333  		t.Error("V(3) not enabled for 3")
   334  	}
   335  
   336  	// Setting a lower level should reset the modules cache.
   337  	if err := flag.Lookup("v").Value.Set("2"); err != nil {
   338  		t.Fatalf("Failed to set -v=2: %v", err)
   339  	}
   340  	if !V(2) {
   341  		t.Error("V(2) not enabled for 2")
   342  	}
   343  	if V(3) {
   344  		t.Error("V(3) enabled for 3")
   345  	}
   346  }
   347  
   348  // Test that an arbitrary log.Level value does not modify -v.
   349  func TestLevel(t *testing.T) {
   350  	setFlags()
   351  	defer sinks.file.swap(sinks.file.newBuffers())
   352  	if err := flag.Lookup("v").Value.Set("3"); err != nil {
   353  		t.Fatalf("Failed to set -v=3: %v", err)
   354  	}
   355  	defer flag.Lookup("v").Value.Set("0")
   356  
   357  	var l Level
   358  	if got, want := l.String(), "0"; got != want {
   359  		t.Errorf("l.String() = %q, want %q", got, want)
   360  	}
   361  	if err := l.Set("2"); err != nil {
   362  		t.Fatalf("l.Set(2) failed: %v", err)
   363  	}
   364  	if got, want := l.String(), "2"; got != want {
   365  		t.Errorf("l.String() = %q, want %q", got, want)
   366  	}
   367  	// -v flag should still be "3".
   368  	if got, want := flag.Lookup("v").Value.String(), "3"; got != want {
   369  		t.Errorf("-v=%v, want %v", got, want)
   370  	}
   371  }
   372  
   373  // Test that a vmodule enables a log in this file.
   374  func TestVmoduleOn(t *testing.T) {
   375  	setFlags()
   376  	defer sinks.file.swap(sinks.file.newBuffers())
   377  	if err := flag.Lookup("vmodule").Value.Set("glog_test=2"); err != nil {
   378  		t.Fatalf("Failed to set -vmodule=log_test=2: %v", err)
   379  	}
   380  	defer flag.Lookup("vmodule").Value.Set("")
   381  
   382  	if !V(1) {
   383  		t.Error("V not enabled for 1")
   384  	}
   385  	if !V(2) {
   386  		t.Error("V not enabled for 2")
   387  	}
   388  	if V(3) {
   389  		t.Error("V enabled for 3")
   390  	}
   391  	V(2).Info("test")
   392  	if !contains(logsink.Info, "I", t) {
   393  		t.Errorf("Info has wrong character: %q", contents(logsink.Info))
   394  	}
   395  	if !contains(logsink.Info, "test", t) {
   396  		t.Error("Info failed")
   397  	}
   398  }
   399  
   400  // Test that a VDepth calculates the depth correctly.
   401  func TestVDepth(t *testing.T) {
   402  	setFlags()
   403  	defer sinks.file.swap(sinks.file.newBuffers())
   404  	if err := flag.Lookup("vmodule").Value.Set("glog_test=3"); err != nil {
   405  		t.Fatalf("Failed to set -vmodule=glog_test=3: %v", err)
   406  	}
   407  	defer flag.Lookup("vmodule").Value.Set("")
   408  
   409  	if !V(3) {
   410  		t.Error("V not enabled for 3")
   411  	}
   412  	if !VDepth(0, 2) {
   413  		t.Error("VDepth(0) not enabled for 2")
   414  	}
   415  	if !VDepth(0, 3) {
   416  		t.Error("VDepth(0) not enabled for 3")
   417  	}
   418  	if VDepth(0, 4) {
   419  		t.Error("VDepth(0) enabled for 4")
   420  	}
   421  
   422  	// Since vmodule is set to glog_test=3, V(3) is true only for frames in
   423  	// glog_test. runInAnotherModule's stack frame is in log_vmodule_test, whereas
   424  	// this test and the provided closures are in glog_test. Therefore VDepth(0, 3)
   425  	// and VDepth(2, 3) are true, while VDepth(1, 3) is false.
   426  	if !runInAnotherModule(func() bool { return bool(VDepth(0, 3)) }) {
   427  		t.Error("VDepth(0) in closure not enabled for 3")
   428  	}
   429  	if runInAnotherModule(func() bool { return bool(VDepth(1, 3)) }) {
   430  		t.Error("VDepth(1) in closure enabled for 3")
   431  	}
   432  	if !runInAnotherModule(func() bool { return bool(VDepth(2, 3)) }) {
   433  		t.Error("VDepth(2) in closure not enabled for 3")
   434  	}
   435  }
   436  
   437  // Test that a vmodule of another file does not enable a log in this file.
   438  func TestVmoduleOff(t *testing.T) {
   439  	setFlags()
   440  	defer sinks.file.swap(sinks.file.newBuffers())
   441  	if err := flag.Lookup("vmodule").Value.Set("notthisfile=2"); err != nil {
   442  		t.Fatalf("Failed to set -vmodule=notthisfile=2: %v", err)
   443  	}
   444  	defer flag.Lookup("vmodule").Value.Set("")
   445  
   446  	for i := 1; i <= 3; i++ {
   447  		if V(Level(i)) {
   448  			t.Errorf("V enabled for %d", i)
   449  		}
   450  	}
   451  	V(2).Info("test")
   452  	if contents(logsink.Info) != "" {
   453  		t.Error("V logged incorrectly")
   454  	}
   455  }
   456  
   457  // vGlobs are patterns that match/don't match this file at V=2.
   458  var vGlobs = map[string]bool{
   459  	// Easy to test the numeric match here.
   460  	"glog_test=1": false, // If -vmodule sets V to 1, V(2) will fail.
   461  	"glog_test=2": true,
   462  	"glog_test=3": true, // If -vmodule sets V to 1, V(3) will succeed.
   463  	// These all use 2 and check the patterns. All are true.
   464  	"*=2":           true,
   465  	"?l*=2":         true,
   466  	"????_*=2":      true,
   467  	"??[mno]?_*t=2": true,
   468  	// These all use 2 and check the patterns. All are false.
   469  	"*x=2":         false,
   470  	"m*=2":         false,
   471  	"??_*=2":       false,
   472  	"?[abc]?_*t=2": false,
   473  }
   474  
   475  // Test that vmodule globbing works as advertised.
   476  func testVmoduleGlob(pat string, match bool, t *testing.T) {
   477  	t.Helper()
   478  	setFlags()
   479  	defer sinks.file.swap(sinks.file.newBuffers())
   480  	if err := flag.Lookup("vmodule").Value.Set(pat); err != nil {
   481  		t.Errorf("Failed to set -vmodule=%s: %v", pat, err)
   482  	}
   483  	defer flag.Lookup("vmodule").Value.Set("")
   484  
   485  	if V(2) != Verbose(match) {
   486  		t.Errorf("incorrect match for %q: got %t expected %t", pat, V(2), match)
   487  	}
   488  }
   489  
   490  // Test that a vmodule globbing works as advertised.
   491  func TestVmoduleGlob(t *testing.T) {
   492  	for glob, match := range vGlobs {
   493  		testVmoduleGlob(glob, match, t)
   494  	}
   495  }
   496  
   497  // Test that a vmodule globbing on a full path works as advertised.
   498  func TestVmoduleFullGlob(t *testing.T) {
   499  	_, file, _, _ := runtime.Caller(0)
   500  	for glob, match := range vGlobs {
   501  		testVmoduleGlob(filepath.Join(filepath.Dir(file), glob), match, t)
   502  	}
   503  }
   504  
   505  // Test that a vmodule globbing across multiple directories works as advertised.
   506  func TestVmoduleFullGlobMultipleDirectories(t *testing.T) {
   507  	// Note: only covering here what
   508  	// TestVmoduleGlob does not.
   509  	_, file, _, _ := runtime.Caller(0)
   510  	dir := filepath.Dir(filepath.Dir(file))
   511  	testVmoduleGlob(filepath.Join(dir, "*/glog_test=2"), true, t)
   512  	testVmoduleGlob(filepath.Join(dir, "*/glog_????=2"), true, t)
   513  }
   514  
   515  func logAtVariousLevels() {
   516  	V(3).Infof("level 3 message")
   517  	V(2).Infof("level 2 message")
   518  	V(1).Infof("level 1 message")
   519  	Infof("default level message")
   520  }
   521  
   522  func TestRollover(t *testing.T) {
   523  	setFlags()
   524  
   525  	Info("x") // Be sure we have a file.
   526  	info, ok := sinks.file.file[logsink.Info].(*syncBuffer)
   527  	if !ok {
   528  		t.Fatal("info wasn't created")
   529  	}
   530  
   531  	// Make sure the next log file gets a file name with a different
   532  	// time stamp.
   533  	//
   534  	// TODO: determine whether we need to support subsecond log
   535  	// rotation.  C++ does not appear to handle this case (nor does it
   536  	// handle Daylight Savings Time properly).
   537  	time.Sleep(1 * time.Second)
   538  
   539  	// Measure the current size of the log file.
   540  	info.Flush()
   541  	fi, err := info.file.Stat()
   542  	if err != nil {
   543  		t.Fatalf("Unable to stat log file %s: %v", info.file.Name(), err)
   544  	}
   545  
   546  	// Set MaxSize to a value that will accept one longMessage, but not two.
   547  	longMessage := strings.Repeat("x", 1024)
   548  	defer func(previous uint64) { MaxSize = previous }(MaxSize)
   549  	MaxSize = uint64(fi.Size()) + uint64(2*len(longMessage)) - 1
   550  
   551  	fname0 := info.file.Name()
   552  
   553  	// Force a rotation.
   554  	Info(longMessage)
   555  	Info(longMessage)
   556  	info.Flush()
   557  
   558  	fname1 := info.file.Name()
   559  	if fname0 == fname1 {
   560  		t.Errorf("info.f.Name did not change: %v", fname0)
   561  	}
   562  	if info.nbytes >= MaxSize {
   563  		t.Errorf("file size was not reset: %d", info.nbytes)
   564  	}
   565  
   566  	// Check to see if the original file has the continued footer.
   567  	f0, err := ioutil.ReadFile(fname0)
   568  	if err != nil {
   569  		t.Fatalf("Unable to read file %s: %v", fname0, err)
   570  	}
   571  	if !bytes.HasSuffix(f0, []byte(footer)) {
   572  		t.Errorf("%v: Missing footer %q", fname0, footer)
   573  	}
   574  	found := false
   575  	for _, l := range bytes.Split(f0, []byte("\n")) {
   576  		var file string
   577  		_, err = fmt.Sscanf(string(l), "Next log: %s\n", &file)
   578  		if err != nil {
   579  			continue
   580  		}
   581  		if file != fname1 {
   582  			t.Errorf("%v: Wanted next filename %s, got %s", fname0, fname1, file)
   583  		}
   584  		found = true
   585  	}
   586  	if !found {
   587  		t.Errorf("%v: Next log footer not found", fname0)
   588  	}
   589  
   590  	// Check to see if the previous file header is there in the new file
   591  	f1, err := ioutil.ReadFile(fname1)
   592  	if err != nil {
   593  		t.Fatalf("Unable to read file %s: %v", fname1, err)
   594  	}
   595  	found = false
   596  	for _, l := range bytes.Split(f1, []byte("\n")) {
   597  		var file string
   598  		_, err = fmt.Sscanf(string(l), "Previous log: %s\n", &file)
   599  		if err != nil {
   600  			continue
   601  		}
   602  		if file != fname0 {
   603  			t.Errorf("%v: Wanted previous filename %s, got %s", fname1, fname0, file)
   604  		}
   605  		found = true
   606  	}
   607  	if !found {
   608  		t.Errorf("%v: Previous log header not found", fname1)
   609  	}
   610  
   611  	// Make sure Names returned the right names.
   612  	n, err := Names("INFO")
   613  	if len(n) != 2 && err != nil && n[0] != fname0 && n[1] != fname1 {
   614  		t.Errorf("Names(INFO) wanted [%s, %s]/nil, got %v/%v", fname0, fname1, n, err)
   615  	}
   616  
   617  	if t.Failed() {
   618  		t.Logf("%v:\n%q", fname0, f0)
   619  		t.Logf("%v:\n%q", fname1, f1)
   620  	}
   621  }
   622  
   623  func TestLogBacktraceAt(t *testing.T) {
   624  	setFlags()
   625  	defer sinks.file.swap(sinks.file.newBuffers())
   626  	// The peculiar style of this code simplifies line counting and maintenance of the
   627  	// tracing block below.
   628  	var infoLine string
   629  	setTraceLocation := func(file string, line int, ok bool, delta int) {
   630  		if !ok {
   631  			t.Fatal("could not get file:line")
   632  		}
   633  		_, file = filepath.Split(file)
   634  		infoLine = fmt.Sprintf("%s:%d", file, line+delta)
   635  		err := logBacktraceAt.Set(infoLine)
   636  		if err != nil {
   637  			t.Fatal("error setting log_backtrace_at: ", err)
   638  		}
   639  	}
   640  	{
   641  		// Start of tracing block. These lines know about each other's relative position.
   642  		_, file, line, ok := runtime.Caller(0)
   643  		setTraceLocation(file, line, ok, +2) // Two lines between Caller and Info calls.
   644  		Info("we want a stack trace here")
   645  	}
   646  	numAppearances := strings.Count(contents(logsink.Info), infoLine)
   647  	if numAppearances < 2 {
   648  		// Need 2 appearances, one in the log header and one in the trace:
   649  		//   log_test.go:281: I0511 16:36:06.952398 02238 log_test.go:280] we want a stack trace here
   650  		//   ...
   651  		//   .../glog/glog_test.go:280 (0x41ba91)
   652  		//   ...
   653  		// We could be more precise but that would require knowing the details
   654  		// of the traceback format, which may not be dependable.
   655  		t.Fatal("got no trace back; log is ", contents(logsink.Info))
   656  	}
   657  }
   658  
   659  func TestNewStandardLoggerLogBacktraceAt(t *testing.T) {
   660  	setFlags()
   661  	defer sinks.file.swap(sinks.file.newBuffers())
   662  	s := NewStandardLogger("INFO")
   663  	// The peculiar style of this code simplifies line counting and maintenance of the
   664  	// tracing block below.
   665  	var infoLine string
   666  	setTraceLocation := func(file string, line int, ok bool, delta int) {
   667  		if !ok {
   668  			t.Fatal("could not get file:line")
   669  		}
   670  		_, file = filepath.Split(file)
   671  		infoLine = fmt.Sprintf("%s:%d", file, line+delta)
   672  		err := logBacktraceAt.Set(infoLine)
   673  		if err != nil {
   674  			t.Fatal("error setting log_backtrace_at: ", err)
   675  		}
   676  	}
   677  	{
   678  		// Start of tracing block. These lines know about each other's relative position.
   679  		_, file, line, ok := runtime.Caller(0)
   680  		setTraceLocation(file, line, ok, +2) // Two lines between Caller and Info calls.
   681  		s.Printf("we want a stack trace here")
   682  	}
   683  	infoContents := contents(logsink.Info)
   684  	if strings.Contains(infoContents, infoLine+"] [") {
   685  		t.Fatal("got extra bracketing around log line contents; log is ", infoContents)
   686  	}
   687  	numAppearances := strings.Count(infoContents, infoLine)
   688  	if numAppearances < 2 {
   689  		// Need 2 appearances, one in the log header and one in the trace:
   690  		//   log_test.go:281: I0511 16:36:06.952398 02238 log_test.go:280] we want a stack trace here
   691  		//   ...
   692  		//   .../glog/glog_test.go:280 (0x41ba91)
   693  		//   ...
   694  		// We could be more precise but that would require knowing the details
   695  		// of the traceback format, which may not be dependable.
   696  		t.Fatal("got no trace back; log is ", infoContents)
   697  	}
   698  }
   699  
   700  // Test to make sure the log naming function works properly.
   701  func TestLogNames(t *testing.T) {
   702  	setFlags()
   703  	defer sinks.file.swap(sinks.file.newBuffers())
   704  	n, e := Names("FOO")
   705  	if e == nil {
   706  		t.Errorf("Names(FOO) was %v/nil, should be []/error", n)
   707  	}
   708  
   709  	// Set the infoLog to nil to simulate "log not yet written to"
   710  	h := sinks.file.file[logsink.Info]
   711  	sinks.file.file[logsink.Info] = nil
   712  	n, e = Names("INFO")
   713  	if e != ErrNoLog {
   714  		t.Errorf("Names(INFO) was %v/%v, should be [], ErrNoLog", n, e)
   715  	}
   716  	sinks.file.file[logsink.Info] = h
   717  
   718  	// Get the name; testing has a fixed fake name for these.
   719  	Info("test")
   720  	n, e = Names("INFO")
   721  	if len(n) != 1 && n[0] != "<local name>" {
   722  		t.Errorf("Names(INFO) got %s, want <local name>", n)
   723  	}
   724  }
   725  
   726  func TestLogLength(t *testing.T) {
   727  	setFlags()
   728  	defer sinks.file.swap(sinks.file.newBuffers())
   729  	Info(strings.Repeat("X", logsink.MaxLogMessageLen*2))
   730  	if c := contents(logsink.Info); len(c) != logsink.MaxLogMessageLen {
   731  		t.Errorf("Info was not truncated: got length %d, want %d, contents %q",
   732  			len(c), logsink.MaxLogMessageLen, c)
   733  	}
   734  }
   735  

View as plain text