From 356615e73b41e9e9ae5c9ab7896557e987a652a8 Mon Sep 17 00:00:00 2001 From: gmhdbjd Date: Wed, 14 May 2025 00:33:00 +0800 Subject: [PATCH 1/4] precheck log file permission --- log.go | 35 ++++++++++++++++++++++++++-- zap_log_test.go | 61 +++++++++++++++++++++++++++++++++++++++++++++---- 2 files changed, 89 insertions(+), 7 deletions(-) diff --git a/log.go b/log.go index 8774f34..f97af16 100644 --- a/log.go +++ b/log.go @@ -18,6 +18,7 @@ import ( "errors" "fmt" "os" + "path/filepath" "sync" "sync/atomic" "time" @@ -174,12 +175,42 @@ func (s *lockWithTimeoutWrapper) Sync() error { // initFileLog initializes file based logging options. func initFileLog(cfg *FileLogConfig) (*lumberjack.Logger, error) { + // Verify file permissions early to prevent silent failures. + // Since lumberjack creates log files lazily, permission issues wouldn't be detected + // until the first write attempt. This is problematic when tools redirect their + // error output to these log files. + // e.g. dumpling use the log file as ErrorOutputPath, but the log file will not be created + // if there has permission issues, and dumpling will not print any error message. + + // Create the directory if it doesn't exist + dir := filepath.Dir(cfg.Filename) + if err := os.MkdirAll(dir, 0755); err != nil { + return nil, fmt.Errorf("cannot create log directory: %v", err) + } + + // Check if the path is a directory which is invalid if st, err := os.Stat(cfg.Filename); err == nil { if st.IsDir() { return nil, errors.New("can't use directory as log file name") } - } else if !os.IsNotExist(err) { - return nil, err + + // Check if the file is writable + file, err := os.OpenFile(cfg.Filename, os.O_WRONLY|os.O_APPEND, 0666) + if err != nil { + return nil, fmt.Errorf("can't write to log file: %v", err) + } + file.Close() + } else if os.IsNotExist(err) { + // File doesn't exist, verify we can create it + file, err := os.Create(cfg.Filename) + if err != nil { + return nil, fmt.Errorf("can't create log file: %v", err) + } + file.Close() + // Remove the empty file since lumberjack will create it + os.Remove(cfg.Filename) + } else { + return nil, fmt.Errorf("error checking log file: %v", err) } if cfg.MaxSize == 0 { diff --git a/zap_log_test.go b/zap_log_test.go index 4e9649a..4166eb6 100644 --- a/zap_log_test.go +++ b/zap_log_test.go @@ -19,6 +19,7 @@ import ( "math" "net" "os" + "path/filepath" "strings" "testing" "time" @@ -288,23 +289,73 @@ func TestCompressError(t *testing.T) { } func TestLogFileNoPermission(t *testing.T) { - tempDir, _ := os.MkdirTemp("/tmp", "tests-log") - defer os.RemoveAll(tempDir) + tempDir := t.TempDir() + + // Directory permission denied + dirPath := filepath.Join(tempDir, "noperm-dir") + require.NoError(t, os.Mkdir(dirPath, 0755)) conf := &Config{ Level: "info", File: FileLogConfig{ - Filename: tempDir + "/test.log", + Filename: filepath.Join(dirPath, "test.log"), MaxSize: 1, }, } _, _, err := InitLogger(conf) require.NoError(t, err) + require.NoError(t, os.Chmod(dirPath, 0)) + _, _, err = InitLogger(conf) + require.Contains(t, err.Error(), "permission denied") + require.NoError(t, os.Chmod(dirPath, 0755)) + + // Directory exists but doesn't allow file creation + readOnlyDirPath := filepath.Join(tempDir, "readonly-dir") + require.NoError(t, os.Mkdir(readOnlyDirPath, 0755)) + require.NoError(t, os.Chmod(readOnlyDirPath, 0555)) // Read-only directory + conf = &Config{ + Level: "info", + File: FileLogConfig{ + Filename: filepath.Join(readOnlyDirPath, "test.log"), + MaxSize: 1, + }, + } + _, _, err = InitLogger(conf) + require.Contains(t, err.Error(), "permission denied") + require.NoError(t, os.Chmod(readOnlyDirPath, 0755)) + + // Using a directory as log file + dirLogPath := filepath.Join(tempDir, "dir-as-log") + require.NoError(t, os.Mkdir(dirLogPath, 0755)) + conf = &Config{ + Level: "info", + File: FileLogConfig{ + Filename: dirLogPath, + MaxSize: 1, + }, + } + _, _, err = InitLogger(conf) + require.Contains(t, err.Error(), "can't use directory as log file name") - err = os.Chmod(tempDir, 0) + // File exists but is not writable + filePath := filepath.Join(tempDir, "readonly.log") + file, err := os.Create(filePath) require.NoError(t, err) + file.Close() + require.NoError(t, os.Chmod(filePath, 0444)) + // Ensure parent directory is created successfully + nestedPath := filepath.Join(tempDir, "nested/path/to") + conf = &Config{ + Level: "info", + File: FileLogConfig{ + Filename: filepath.Join(nestedPath, "test.log"), + MaxSize: 1, + }, + } _, _, err = InitLogger(conf) - require.Contains(t, err.Error(), "permission denied") + require.NoError(t, err) + _, err = os.Stat(nestedPath) + require.NoError(t, err) } // testLogSpy is a testing.TB that captures logged messages. From 4465a290ef9e4ce5b515aff4071d1c329afad762 Mon Sep 17 00:00:00 2001 From: gmhdbjd Date: Wed, 14 May 2025 00:42:09 +0800 Subject: [PATCH 2/4] fix ut --- zap_log_test.go | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/zap_log_test.go b/zap_log_test.go index 4166eb6..d97bc73 100644 --- a/zap_log_test.go +++ b/zap_log_test.go @@ -100,16 +100,16 @@ func TestLog(t *testing.T) { zap.Duration("duration", 10*time.Second), ) ts.assertMessages( - `[INFO] [zap_log_test.go:49] ["failed to fetch URL"] [url=http://example.com] [attempt=3] [backoff=1s]`, - `[INFO] [zap_log_test.go:54] ["failed to \"fetch\" [URL]: http://example.com"]`, - `[DEBUG] [zap_log_test.go:55] ["Slow query"] [sql="SELECT * FROM TABLE\n\tWHERE ID=\"abc\""] [duration=1.3s] ["process keys"=1500]`, - `[INFO] [zap_log_test.go:61] [Welcome]`, - `[INFO] [zap_log_test.go:62] ["Welcome TiDB"]`, - `[INFO] [zap_log_test.go:63] [欢迎]`, - `[INFO] [zap_log_test.go:64] ["欢迎来到 TiDB"]`, - `[WARN] [zap_log_test.go:65] [Type] [Counter=NaN] [Score=+Inf]`, - `[INFO] [zap_log_test.go:70] ["new connection"] [connID=1] [traceID=dse1121]`, - `[INFO] [zap_log_test.go:71] ["Testing typs"] [filed1=noquote] `+ + `[INFO] [zap_log_test.go:50] ["failed to fetch URL"] [url=http://example.com] [attempt=3] [backoff=1s]`, + `[INFO] [zap_log_test.go:55] ["failed to \"fetch\" [URL]: http://example.com"]`, + `[DEBUG] [zap_log_test.go:56] ["Slow query"] [sql="SELECT * FROM TABLE\n\tWHERE ID=\"abc\""] [duration=1.3s] ["process keys"=1500]`, + `[INFO] [zap_log_test.go:62] [Welcome]`, + `[INFO] [zap_log_test.go:63] ["Welcome TiDB"]`, + `[INFO] [zap_log_test.go:64] [欢迎]`, + `[INFO] [zap_log_test.go:65] ["欢迎来到 TiDB"]`, + `[WARN] [zap_log_test.go:66] [Type] [Counter=NaN] [Score=+Inf]`, + `[INFO] [zap_log_test.go:71] ["new connection"] [connID=1] [traceID=dse1121]`, + `[INFO] [zap_log_test.go:72] ["Testing typs"] [filed1=noquote] `+ `[filed2="in quote"] [urls="[http://mock1.com:2347,http://mock2.com:2432]"] `+ `[urls-peer="[t1,\"t2 fine\"]"] ["store ids"="[1,4,5]"] [object="{username=user1}"] `+ `[object2="{username=\"user 2\"}"] [binary="YWIxMjM="] ["is processed"=true] `+ From 4a789894230aa9399835524310217dcfb6fba49c Mon Sep 17 00:00:00 2001 From: gmhdbjd Date: Wed, 14 May 2025 00:54:49 +0800 Subject: [PATCH 3/4] fix ut --- zap_log_test.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/zap_log_test.go b/zap_log_test.go index d97bc73..c37a9fd 100644 --- a/zap_log_test.go +++ b/zap_log_test.go @@ -232,8 +232,8 @@ func TestLogJSON(t *testing.T) { "backoff", time.Second, ) logger.With(zap.String("connID", "1"), zap.String("traceID", "dse1121")).Info("new connection") - ts.assertMessages("{\"level\":\"INFO\",\"caller\":\"zap_log_test.go:228\",\"message\":\"failed to fetch URL\",\"url\":\"http://example.com\",\"attempt\":3,\"backoff\":\"1s\"}", - "{\"level\":\"INFO\",\"caller\":\"zap_log_test.go:233\",\"message\":\"new connection\",\"connID\":\"1\",\"traceID\":\"dse1121\"}") + ts.assertMessages("{\"level\":\"INFO\",\"caller\":\"zap_log_test.go:229\",\"message\":\"failed to fetch URL\",\"url\":\"http://example.com\",\"attempt\":3,\"backoff\":\"1s\"}", + "{\"level\":\"INFO\",\"caller\":\"zap_log_test.go:234\",\"message\":\"new connection\",\"connID\":\"1\",\"traceID\":\"dse1121\"}") } func TestRotateLogWithCompress(t *testing.T) { From 3b10a50ffe13584dd70a424a4796841721da76ad Mon Sep 17 00:00:00 2001 From: gmhdbjd Date: Wed, 14 May 2025 10:21:28 +0800 Subject: [PATCH 4/4] address comment --- log.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/log.go b/log.go index f97af16..6788631 100644 --- a/log.go +++ b/log.go @@ -185,7 +185,7 @@ func initFileLog(cfg *FileLogConfig) (*lumberjack.Logger, error) { // Create the directory if it doesn't exist dir := filepath.Dir(cfg.Filename) if err := os.MkdirAll(dir, 0755); err != nil { - return nil, fmt.Errorf("cannot create log directory: %v", err) + return nil, fmt.Errorf("cannot create log directory: %w", err) } // Check if the path is a directory which is invalid @@ -197,20 +197,20 @@ func initFileLog(cfg *FileLogConfig) (*lumberjack.Logger, error) { // Check if the file is writable file, err := os.OpenFile(cfg.Filename, os.O_WRONLY|os.O_APPEND, 0666) if err != nil { - return nil, fmt.Errorf("can't write to log file: %v", err) + return nil, fmt.Errorf("can't write to log file: %w", err) } file.Close() } else if os.IsNotExist(err) { // File doesn't exist, verify we can create it file, err := os.Create(cfg.Filename) if err != nil { - return nil, fmt.Errorf("can't create log file: %v", err) + return nil, fmt.Errorf("can't create log file: %w", err) } file.Close() // Remove the empty file since lumberjack will create it os.Remove(cfg.Filename) } else { - return nil, fmt.Errorf("error checking log file: %v", err) + return nil, fmt.Errorf("error checking log file: %w", err) } if cfg.MaxSize == 0 {