Fail if log file already exists

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,16 +269,22 @@ 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 {
 	return sb.file.Sync()
 }
 
 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 := "<none>"
-	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

glog_test.go

@@ -521,21 +521,24 @@ 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)
 	if !ok {
 		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")
+	}
+}