diff --git a/glog_file.go b/glog_file.go index 2b478ae6..b54bd405 100644 --- a/glog_file.go +++ b/glog_file.go @@ -116,32 +116,53 @@ var onceLogDirs sync.Once // contains tag ("INFO", "FATAL", etc.) and t. If the file is created // successfully, create also attempts to update the symlink for that tag, ignoring // errors. -func create(tag string, t time.Time) (f *os.File, filename string, err error) { +func create(tag string, t time.Time, dir string) (f *os.File, filename string, err error) { + if dir != "" { + f, name, err := createInDir(dir, tag, t) + if err == nil { + return f, name, err + } + return nil, "", fmt.Errorf("log: cannot create log: %v", err) + } + onceLogDirs.Do(createLogDirs) if len(logDirs) == 0 { return nil, "", errors.New("log: no log dirs") } - name, link := logName(tag, t) var lastErr error for _, dir := range logDirs { - fname := filepath.Join(dir, name) - f, err := os.Create(fname) + f, name, err := createInDir(dir, tag, t) if err == nil { - symlink := filepath.Join(dir, link) - os.Remove(symlink) // ignore err - os.Symlink(name, symlink) // ignore err - if *logLink != "" { - lsymlink := filepath.Join(*logLink, link) - os.Remove(lsymlink) // ignore err - os.Symlink(fname, lsymlink) // ignore err - } - return f, fname, nil + return f, name, err } lastErr = err } return nil, "", fmt.Errorf("log: cannot create log: %v", lastErr) } +func createInDir(dir, tag string, t time.Time) (f *os.File, name string, err error) { + name, link := logName(tag, t) + fname := filepath.Join(dir, name) + // O_EXCL is important here, as it prevents a vulnerability. The general idea is that logs often + // live in an insecure directory (like /tmp), so an unprivileged attacker could create fname in + // advance as a symlink to a file the logging process can access, but the attacker cannot. O_EXCL + // fails the open if it already exists, thus prevent our this code from opening the existing file + // the attacker points us to. + f, err = os.OpenFile(fname, os.O_RDWR|os.O_CREATE|os.O_EXCL, 0666) + if err == nil { + symlink := filepath.Join(dir, link) + os.Remove(symlink) // ignore err + os.Symlink(name, symlink) // ignore err + if *logLink != "" { + lsymlink := filepath.Join(*logLink, link) + os.Remove(lsymlink) // ignore err + os.Symlink(fname, lsymlink) // ignore err + } + return f, fname, nil + } + return nil, "", err +} + // flushSyncWriter is the interface satisfied by logging destinations. type flushSyncWriter interface { Flush() error @@ -248,6 +269,7 @@ type syncBuffer struct { names []string sev logsink.Severity nbytes uint64 // The number of bytes written to this file + madeAt time.Time } func (sb *syncBuffer) Sync() error { @@ -255,9 +277,14 @@ func (sb *syncBuffer) Sync() error { } func (sb *syncBuffer) Write(p []byte) (n int, err error) { + // Rotate the file if it is too large, but ensure we only do so, + // if rotate doesn't create a conflicting filename. if sb.nbytes+uint64(len(p)) >= MaxSize { - if err := sb.rotateFile(time.Now()); err != nil { - return 0, err + now := timeNow() + if now.After(sb.madeAt.Add(1*time.Second)) || now.Second() != sb.madeAt.Second() { + if err := sb.rotateFile(now); err != nil { + return 0, err + } } } n, err = sb.Writer.Write(p) @@ -275,7 +302,8 @@ const footer = "\nCONTINUED IN NEXT FILE\n" func (sb *syncBuffer) rotateFile(now time.Time) error { var err error pn := "" - file, name, err := create(sb.sev.String(), now) + file, name, err := create(sb.sev.String(), now, "") + sb.madeAt = now if sb.file != nil { // The current log file becomes the previous log at the end of diff --git a/glog_test.go b/glog_test.go index 54762c5f..8fd15cdf 100644 --- a/glog_test.go +++ b/glog_test.go @@ -521,6 +521,17 @@ func logAtVariousLevels() { func TestRollover(t *testing.T) { setFlags() + defer func(previous func() time.Time) { timeNow = previous }(timeNow) + + // Initialize a fake clock that can be advanced with the tick func. + fakeNow := time.Date(2024, 12, 23, 1, 23, 45, 0, time.Local) + timeNow = func() time.Time { + return fakeNow + } + + tick := func(d time.Duration) { + fakeNow = fakeNow.Add(d) + } Info("x") // Be sure we have a file. info, ok := sinks.file.file[logsink.Info].(*syncBuffer) @@ -528,14 +539,6 @@ func TestRollover(t *testing.T) { t.Fatal("info wasn't created") } - // Make sure the next log file gets a file name with a different - // time stamp. - // - // TODO: determine whether we need to support subsecond log - // rotation. C++ does not appear to handle this case (nor does it - // handle Daylight Savings Time properly). - time.Sleep(1 * time.Second) - // Measure the current size of the log file. info.Flush() fi, err := info.file.Stat() @@ -550,7 +553,9 @@ func TestRollover(t *testing.T) { fname0 := info.file.Name() - // Force a rotation. + // Advance clock by 1.5 seconds to force rotation by size. + // (The .5 will be important for the last test as well). + tick(1500 * time.Millisecond) Info(longMessage) Info(longMessage) info.Flush() @@ -610,14 +615,49 @@ func TestRollover(t *testing.T) { // Make sure Names returned the right names. n, err := Names("INFO") - if len(n) != 2 && err != nil && n[0] != fname0 && n[1] != fname1 { + if (len(n) != 2 || err != nil) && n[0] != fname0 && n[1] != fname1 { t.Errorf("Names(INFO) wanted [%s, %s]/nil, got %v/%v", fname0, fname1, n, err) } + // The following tests assume that previous test left clock at .5 seconds. + if fakeNow.Nanosecond() != 5e8 { + t.Fatalf("BUG: fake clock should be exactly at .5 seconds") + } + + // Same second would create conflicting filename, no rotation expected. + tick(499 * time.Millisecond) + Info(longMessage) + Info(longMessage) + n, err = Names("INFO") + if got, want := len(n), 2; got != want || err != nil { + t.Errorf("Names(INFO) = %v (len=%v), %v, want %d names: expected no rotation within same second", n, got, err, want) + } + + // Trigger a subsecond rotation in next fakeClock second. + tick(1 * time.Millisecond) + Info(longMessage) + Info(longMessage) + n, err = Names("INFO") + if got, want := len(n), 3; got != want || err != nil { + t.Errorf("Names(INFO) = %v (len=%v), %v, want %d names: expected a rotation after under a second when filename does not conflict", n, got, err, want) + } + + // Trigger a rotation within a minute since the last rotation. + tick(time.Minute) + Info(longMessage) + Info(longMessage) + n, err = Names("INFO") + if got, want := len(n), 4; got != want || err != nil { + t.Errorf("Names(INFO) = %v (len=%v), %v, want %d names: expected a rotation after one minute since last rotation", n, got, err, want) + } + if t.Failed() { - t.Logf("%v:\n%q", fname0, f0) - t.Logf("%v:\n%q", fname1, f1) + t.Logf("========================================================") + t.Logf("%s:\n%s", fname0, f0) + t.Logf("========================================================") + t.Logf("%s:\n%s", fname1, f1) } + } func TestLogBacktraceAt(t *testing.T) { @@ -732,3 +772,14 @@ func TestLogLength(t *testing.T) { len(c), logsink.MaxLogMessageLen, c) } } + +func TestCreateFailsIfExists(t *testing.T) { + tmp := t.TempDir() + now := time.Now() + if _, _, err := create("INFO", now, tmp); err != nil { + t.Errorf("create() failed on first call: %v", err) + } + if _, _, err := create("INFO", now, tmp); err == nil { + t.Errorf("create() succeeded on second call, want error") + } +}