Merge pull request #91 from CarlJi/log_enhance

feat(log): make Lmodule option as deprecated and add  Lintermediatefile model to enhance log library

log/logext.go

@@ -5,7 +5,9 @@ import (
 	"fmt"
 	"io"
 	"os"
+	"path/filepath"
 	"runtime"
+	"runtime/debug"
 	"strings"
 	"sync"
 	"time"
@@ -17,16 +19,18 @@ const (
 	// order they appear (the order listed here) or the format they present (as
 	// described in the comments).  A colon appears after these items:
 	//	2009/0123 01:23:23.123123 /a/b/c/d.go:23: message
-	Ldate         = 1 << iota                     // the date: 2009/0123
-	Ltime                                         // the time: 01:23:23
-	Lmicroseconds                                 // microsecond resolution: 01:23:23.123123.  assumes Ltime.
-	Llongfile                                     // full file name and line number: /a/b/c/d.go:23
-	Lshortfile                                    // final file name element and line number: d.go:23. overrides Llongfile
-	Lmodule                                       // module name
-	Llevel                                        // level: 0(Debug), 1(Info), 2(Warn), 3(Error), 4(Panic), 5(Fatal)
-	LstdFlags     = Ldate | Ltime | Lmicroseconds // initial values for the standard logger
-	Ldefault      = Lmodule | Llevel | Lshortfile | LstdFlags
-) // [prefix][time][level][module][shortfile|longfile]
+	Ldate         = 1 << iota // the date: 2009/0123
+	Ltime                     // the time: 01:23:23
+	Lmicroseconds             // microsecond resolution: 01:23:23.123123.  assumes Ltime.
+	Llongfile                 // full file name and line number: /a/b/c/d.go:23
+	Lshortfile                // final file name element and line number: d.go:23. overrides Llongfile
+	// Deprecated: recommend to use Lintermediatefile option instead.
+	Lmodule                                           // module name
+	Llevel                                            // level: 0(Debug), 1(Info), 2(Warn), 3(Error), 4(Panic), 5(Fatal)
+	Lintermediatefile                                 // final file format output is typically in the format c/d.go:23, which includes the last two paths. If the compilation includes the '-trimpath' parameter, this format will just exclude the module path prefix.
+	LstdFlags         = Ldate | Ltime | Lmicroseconds // initial values for the standard logger
+	Ldefault          = Llevel | Lintermediatefile | LstdFlags
+) // [prefix][time][level][shortfile|longfile|intermediatefile]: message
 
 const (
 	// Ldebug is a log output level that prints debug information.
@@ -52,6 +56,17 @@ var levels = []string{
 	"[FATAL]",
 }
 
+// module path which will be used as the prefix to be trimmed.
+var modulePath string
+
+func init() {
+	info, ok := debug.ReadBuildInfo()
+	if ok {
+		// initialize module path.
+		modulePath = info.Main.Path
+	}
+}
+
 // A Logger represents an active logging object that generates lines of
 // output to an io.Writer.  Each logging operation makes a single call to
 // the Writer's Write method.  A Logger can be used simultaneously from
@@ -102,16 +117,30 @@ func itoa(buf *bytes.Buffer, i int, wid int) {
 	}
 }
 
-func shortFile(file string, flag int) string {
-	sep := "/"
-	if (flag & Lmodule) != 0 {
-		sep = "/src/"
+func trimModPrefix(file string) string {
+	return strings.TrimPrefix(file, modulePath+"/")
+}
+
+// formatFile returns last N path elements if file path is absolute path,
+// otherwise return the path which relative to the module path.
+func formatFile(file string, lastN int) string {
+	if !filepath.IsAbs(file) {
+		return trimModPrefix(file)
 	}
-	pos := strings.LastIndex(file, sep)
-	if pos != -1 {
-		return file[pos+5:]
+
+	var lastNthSlash = -1
+	var path = file
+	for lastN > 0 {
+		lastN--
+		if pos := strings.LastIndex(path, "/"); pos >= 0 {
+			lastNthSlash = pos
+			path = path[:pos]
+		} else {
+			lastNthSlash = -1
+			break
+		}
 	}
-	return file
+	return file[lastNthSlash+1:]
 }
 
 func (l *Logger) formatHeader(buf *bytes.Buffer, t time.Time, file string, line int, lvl int, reqID string) {
@@ -151,9 +180,11 @@ func (l *Logger) formatHeader(buf *bytes.Buffer, t time.Time, file string, line
 	if flag&Llevel != 0 {
 		buf.WriteString(levels[lvl])
 	}
-	if flag&(Lshortfile|Llongfile) != 0 {
-		if flag&Lshortfile != 0 {
-			file = shortFile(file, flag)
+	if flag&(Lshortfile|Llongfile|Lintermediatefile) != 0 {
+		if l.flag&Lintermediatefile != 0 {
+			file = formatFile(file, 2)
+		} else if l.flag&Lshortfile != 0 {
+			file = formatFile(file, 1)
 		}
 		buf.WriteByte(' ')
 		buf.WriteString(file)
@@ -180,7 +211,7 @@ func (l *Logger) Output(reqID string, lvl int, calldepth int, s string) error {
 	var line int
 	l.mu.Lock()
 	defer l.mu.Unlock()
-	if l.flag&(Lshortfile|Llongfile|Lmodule) != 0 {
+	if l.flag&(Lshortfile|Llongfile|Lintermediatefile) != 0 {
 		// release lock while getting caller info - it's expensive.
 		l.mu.Unlock()
 		var ok bool

log/logext_test.go

@@ -0,0 +1,78 @@
+//go:build unix
+// +build unix
+
+package log
+
+import (
+	"bytes"
+	"regexp"
+	"strings"
+	"testing"
+)
+
+func TestFormatFile(t *testing.T) {
+	tcs := []struct {
+		file     string
+		lastN    int
+		expected string
+	}{
+		{"github.com/qiniu/log.v1/logext_test.go", 1, "github.com/qiniu/log.v1/logext_test.go"},
+		{"/qbox/github.com/qiniu/log.v1/logext_test.go", 2, "log.v1/logext_test.go"},
+		{"/qbox/github.com/qiniu/log.v1/logext_test.go", 1, "logext_test.go"},
+		{"logext_test.go", 2, "logext_test.go"},
+		{"/logext_test.go", 2, "/logext_test.go"},
+		{"/a/logext_test.go", 2, "a/logext_test.go"},
+	}
+	for _, tc := range tcs {
+		if actual := formatFile(tc.file, tc.lastN); actual != tc.expected {
+			t.Errorf("formatFile(%v, %v) = %v, expected %v", tc.file, tc.lastN, actual, tc.expected)
+		}
+	}
+}
+
+func TestLog(t *testing.T) {
+	out := bytes.Buffer{}
+	logx := New(&out, Std.Prefix(), Std.Flags())
+	logx.Info("hello")
+	result := out.String()
+
+	// check time prefix
+	actual := result[:26]
+	if !regexp.MustCompile(`^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2}.\d{6}$`).MatchString(actual) {
+		t.Errorf("time prefix of logx.Info() = %v, expected %v ", actual, "yyyy/mm/dd hh:mm:ss.xxxxxx")
+	}
+
+	// check level prefix
+	actual = result[27:33]
+	if actual != "[INFO]" {
+		t.Errorf("level prefix of logx.Info() = %v, expected %v ", actual, "[INFO]")
+	}
+
+	// check file prefix
+	actual = result[34:53]
+	if actual != "log/logext_test.go:" {
+		t.Errorf("file prefix of logx.Info() = %v, expected %v ", actual, " logext_test.go: ")
+	}
+}
+
+func TestLongFile(t *testing.T) {
+	out := bytes.Buffer{}
+	logx := New(&out, Std.Prefix(), Llongfile|Llevel|LstdFlags)
+	logx.Info("hello")
+	result := out.String()
+	suffix := "x/log/logext_test.go:61: hello\n"
+	if !strings.HasSuffix(result, suffix) {
+		t.Errorf("Llongfile mode, logx.Info() = %v, which expected to include suffix %v ", result, suffix)
+	}
+}
+
+func TestShortFile(t *testing.T) {
+	out := bytes.Buffer{}
+	logx := New(&out, Std.Prefix(), Lshortfile|Llevel|LstdFlags)
+	logx.Info("hello")
+	result := out.String()
+	suffix := "logext_test.go:72: hello\n"
+	if !strings.HasSuffix(result, suffix) {
+		t.Errorf("Lshortfile mode, logx.Info() = %v, which expected to include suffix %v ", result, suffix)
+	}
+}

log/logext_windows_test.go

@@ -0,0 +1,25 @@
+//go:build windows
+// +build windows
+
+package log
+
+import (
+	"testing"
+)
+
+func TestFormatFile(t *testing.T) {
+	tcs := []struct {
+		file     string
+		lastN    int
+		expected string
+	}{
+		{"C:/log.v1/logext_test.go", 1, "logext_test.go"},
+		{"C:/log.v1/logext_test.go", 2, "log.v1/logext_test.go"},
+		{"github.com/log.v1/logext_test.go", 2, "github.com/log.v1/logext_test.go"},
+	}
+	for _, tc := range tcs {
+		if actual := formatFile(tc.file, tc.lastN); actual != tc.expected {
+			t.Errorf("formatFile(%v, %v) = %v, expected %v", tc.file, tc.lastN, actual, tc.expected)
+		}
+	}
+}

xlog/xlog.go

@@ -18,7 +18,6 @@ const (
 	Lmicroseconds = log.Lmicroseconds
 	Llongfile     = log.Llongfile
 	Lshortfile    = log.Lshortfile
-	Lmodule       = log.Lmodule
 	Llevel        = log.Llevel
 	LstdFlags     = log.LstdFlags
 	Ldefault      = log.Ldefault