From 65d3f269aa837ea5587045baa499a2c6b8f692c5 Mon Sep 17 00:00:00 2001 From: Chressie Himpel Date: Tue, 7 Jan 2025 20:08:44 +0100 Subject: [PATCH 1/3] glog: Don't try to create/rotate a given syncBuffer twice in the same second If you do, then you truncate the existing file. So logging too much too quickly would lose log data. cl/709080575 (google-internal) --- glog_file.go | 11 +++++++-- glog_test.go | 64 ++++++++++++++++++++++++++++++++++++++++++---------- 2 files changed, 61 insertions(+), 14 deletions(-) diff --git a/glog_file.go b/glog_file.go index 2b478ae6..58e22486 100644 --- a/glog_file.go +++ b/glog_file.go @@ -248,6 +248,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 +256,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) @@ -276,6 +282,7 @@ func (sb *syncBuffer) rotateFile(now time.Time) error { var err error pn := "" 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..c1bf553d 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) { From f64253318f461eb4e5a3e0e669073d721e10da70 Mon Sep 17 00:00:00 2001 From: Chressie Himpel Date: Wed, 8 Jan 2025 12:44:22 +0100 Subject: [PATCH 2/3] glog: introduce createInDir function as in internal version --- glog_file.go | 44 ++++++++++++++++++++++++++++++-------------- 1 file changed, 30 insertions(+), 14 deletions(-) diff --git a/glog_file.go b/glog_file.go index 58e22486..9a56a69b 100644 --- a/glog_file.go +++ b/glog_file.go @@ -116,32 +116,48 @@ 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) + f, err = os.Create(fname) + 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 @@ -281,7 +297,7 @@ 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 { From b8741656e406e66d6992bc2c9575e460ecaa0ec2 Mon Sep 17 00:00:00 2001 From: Chressie Himpel Date: Wed, 8 Jan 2025 12:44:22 +0100 Subject: [PATCH 3/3] glog: have createInDir fail if the file already exists This prevents an attack like the one described [here](https://owasp.org/www-community/vulnerabilities/Insecure_Temporary_File#:~:text=On%20Unix%20based,with%20elevated%20permissions.). An unprivileged attacker could use symlinks to trick a privileged logging process to follow a symlink from the log dir and write logs over an arbitrary file. The components of the log names are program, host, username, tag, date, time and PID. These are all predictable. It's not at all unusual for the logdir to be writable by unprivileged users, and one of the fallback directories (/tmp) traditionally has broad write privs with the sticky bit set on Unix systems. As a concrete example, let's say I've got a glog-enabled binary running as a root cronjob. I can gauge when that cron job will run and then use a bash script to spray the log dir with glog-looking symlinks to `/etc/shadow` with predicted times and PIDs. When the cronjob runs, the `os.Create` call will follow the symlink, truncate `/etc/shadow` and then fill it with logs. This change defeats that by setting `O_EXCL`, which will cause the open call to fail if the file already exists. Fixes CVE-2024-45339 cl/712795111 (google-internal) --- glog_file.go | 7 ++++++- glog_test.go | 11 +++++++++++ 2 files changed, 17 insertions(+), 1 deletion(-) diff --git a/glog_file.go b/glog_file.go index 9a56a69b..b54bd405 100644 --- a/glog_file.go +++ b/glog_file.go @@ -143,7 +143,12 @@ func create(tag string, t time.Time, dir string) (f *os.File, filename string, e 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) - f, err = os.Create(fname) + // 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 diff --git a/glog_test.go b/glog_test.go index c1bf553d..8fd15cdf 100644 --- a/glog_test.go +++ b/glog_test.go @@ -772,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") + } +}