Merge pull request #2136 from fjl/glog-prefix

logger/glog: improve vmodule

7 files changed, 112 insertions, 92 deletions

diff --git a/logger/glog/glog.go b/logger/glog/glog.go
index 008c0e036..b8eaf9359 100644
--- a/logger/glog/glog.go
+++ b/logger/glog/glog.go
@@ -63,11 +63,17 @@
 //		Enable V-leveled logging at the specified level.
 //	-vmodule=""
 //		The syntax of the argument is a comma-separated list of pattern=N,
-//		where pattern is a literal file name (minus the ".go" suffix) or
-//		"glob" pattern and N is a V level. For instance,
-//			-vmodule=gopher*=3
-//		sets the V level to 3 in all Go files whose names begin "gopher".
+//		where pattern is a literal file name or "glob" pattern matching
+//		and N is a V level. For instance,
 //
+//			-vmodule=gopher.go=3
+//		sets the V level to 3 in all Go files named "gopher.go".
+//
+//			-vmodule=foo=3
+//		sets V to 3 in all files of any packages whose import path ends in "foo".
+//
+//			-vmodule=foo/*=3
+//		sets V to 3 in all files of any packages whose import path contains "foo".
 package glog
 
 import (
@@ -78,7 +84,7 @@ import (
 	"io"
 	stdLog "log"
 	"os"
-	"path/filepath"
+	"regexp"
 	"runtime"
 	"strconv"
 	"strings"
@@ -113,11 +119,30 @@ var severityName = []string{
 	fatalLog:   "FATAL",
 }
 
+// these path prefixes are trimmed for display, but not when
+// matching vmodule filters.
+var trimPrefixes = []string{
+	"/github.com/ethereum/go-ethereum",
+	"/github.com/ethereum/ethash",
+}
+
+func trimToImportPath(file string) string {
+	if root := strings.LastIndex(file, "src/"); root != 0 {
+		file = file[root+3:]
+	}
+	return file
+}
+
 // SetV sets the global verbosity level
 func SetV(v int) {
 	logging.verbosity.set(Level(v))
 }
 
+// SetVmodule sets the global verbosity patterns.
+func SetVmodule(pat string) error {
+	return logging.vmodule.Set(pat)
+}
+
 // SetToStderr sets the global output style
 func SetToStderr(toStderr bool) {
 	logging.toStderr = toStderr
@@ -261,21 +286,10 @@ type moduleSpec struct {
 // modulePat contains a filter for the -vmodule flag.
 // It holds a verbosity level and a file pattern to match.
 type modulePat struct {
-	pattern string
-	literal bool // The pattern is a literal string
+	pattern *regexp.Regexp
 	level   Level
 }
 
-// match reports whether the file matches the pattern. It uses a string
-// comparison if the pattern contains no metacharacters.
-func (m *modulePat) match(file string) bool {
-	if m.literal {
-		return file == m.pattern
-	}
-	match, _ := filepath.Match(m.pattern, file)
-	return match
-}
-
 func (m *moduleSpec) String() string {
 	// Lock because the type is not atomic. TODO: clean this up.
 	logging.mu.Lock()
@@ -322,7 +336,8 @@ func (m *moduleSpec) Set(value string) error {
 			continue // Ignore. It's harmless but no point in paying the overhead.
 		}
 		// TODO: check syntax of filter?
-		filter = append(filter, modulePat{pattern, isLiteral(pattern), Level(v)})
+		re, _ := compileModulePattern(pattern)
+		filter = append(filter, modulePat{re, Level(v)})
 	}
 	logging.mu.Lock()
 	defer logging.mu.Unlock()
@@ -330,10 +345,21 @@ func (m *moduleSpec) Set(value string) error {
 	return nil
 }
 
-// isLiteral reports whether the pattern is a literal string, that is, has no metacharacters
-// that require filepath.Match to be called to match the pattern.
-func isLiteral(pattern string) bool {
-	return !strings.ContainsAny(pattern, `\*?[]`)
+// compiles a vmodule pattern to a regular expression.
+func compileModulePattern(pat string) (*regexp.Regexp, error) {
+	re := ".*"
+	for _, comp := range strings.Split(pat, "/") {
+		if comp == "*" {
+			re += "(/.*)?"
+		} else if comp != "" {
+			// TODO: maybe return error if comp contains *
+			re += "/" + regexp.QuoteMeta(comp)
+		}
+	}
+	if !strings.HasSuffix(pat, ".go") {
+		re += "/[^/]+\\.go"
+	}
+	return regexp.Compile(re + "$")
 }
 
 // traceLocation represents the setting of the -log_backtrace_at flag.
@@ -556,10 +582,14 @@ func (l *loggingT) header(s severity, depth int) (*buffer, string, int) {
 		file = "???"
 		line = 1
 	} else {
-		slash := strings.LastIndex(file, "/")
-		if slash >= 0 {
-			file = file[slash+1:]
+		file = trimToImportPath(file)
+		for _, p := range trimPrefixes {
+			if strings.HasPrefix(file, p) {
+				file = file[len(p):]
+				break
+			}
 		}
+		file = file[1:] // drop '/'
 	}
 	return l.formatHeader(s, file, line), file, line
 }
@@ -592,9 +622,7 @@ func (l *loggingT) formatHeader(s severity, file string, line int) *buffer {
 	buf.tmp[14] = '.'
 	buf.nDigits(6, 15, now.Nanosecond()/1000, '0')
 	buf.tmp[21] = ' '
-	buf.nDigits(7, 22, pid, ' ') // TODO: should be TID
-	buf.tmp[29] = ' '
-	buf.Write(buf.tmp[:30])
+	buf.Write(buf.tmp[:22])
 	buf.WriteString(file)
 	buf.tmp[0] = ':'
 	n := buf.someDigits(1, line)
@@ -976,15 +1004,9 @@ func (lb logBridge) Write(b []byte) (n int, err error) {
 func (l *loggingT) setV(pc uintptr) Level {
 	fn := runtime.FuncForPC(pc)
 	file, _ := fn.FileLine(pc)
-	// The file is something like /a/b/c/d.go. We want just the d.
-	if strings.HasSuffix(file, ".go") {
-		file = file[:len(file)-3]
-	}
-	if slash := strings.LastIndex(file, "/"); slash >= 0 {
-		file = file[slash+1:]
-	}
+	file = trimToImportPath(file)
 	for _, filter := range l.vmodule.filter {
-		if filter.match(file) {
+		if filter.pattern.MatchString(file) {
 			l.vmap[pc] = filter.level
 			return filter.level
 		}
diff --git a/logger/glog/glog_test.go b/logger/glog/glog_test.go
index 0fb376e1f..30861a48d 100644
--- a/logger/glog/glog_test.go
+++ b/logger/glog/glog_test.go
@@ -180,7 +180,7 @@ func TestHeader(t *testing.T) {
 	pid = 1234
 	Info("test")
 	var line int
-	format := "I0102 15:04:05.067890    1234 glog_test.go:%d] test\n"
+	format := "I0102 15:04:05.067890 logger/glog/glog_test.go:%d] test\n"
 	n, err := fmt.Sscanf(contents(infoLog), format, &line)
 	if n != 1 || err != nil {
 		t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(infoLog))
@@ -253,7 +253,7 @@ func TestV(t *testing.T) {
 func TestVmoduleOn(t *testing.T) {
 	setFlags()
 	defer logging.swap(logging.newBuffers())
-	logging.vmodule.Set("glog_test=2")
+	logging.vmodule.Set("glog_test.go=2")
 	defer logging.vmodule.Set("")
 	if !V(1) {
 		t.Error("V not enabled for 1")
@@ -290,22 +290,43 @@ func TestVmoduleOff(t *testing.T) {
 	}
 }
 
+var patternTests = []struct{ input, want string }{
+	{"foo/bar/x.go", ".*/foo/bar/x\\.go$"},
+	{"foo/*/x.go", ".*/foo(/.*)?/x\\.go$"},
+	{"foo/*", ".*/foo(/.*)?/[^/]+\\.go$"},
+}
+
+func TestCompileModulePattern(t *testing.T) {
+	for _, test := range patternTests {
+		re, err := compileModulePattern(test.input)
+		if err != nil {
+			t.Fatalf("%s: %v", err)
+		}
+		if re.String() != test.want {
+			t.Errorf("mismatch for %q: got %q, want %q", test.input, re.String(), test.want)
+		}
+	}
+}
+
 // vGlobs are patterns that match/don't match this file at V=2.
 var vGlobs = map[string]bool{
 	// Easy to test the numeric match here.
-	"glog_test=1": false, // If -vmodule sets V to 1, V(2) will fail.
-	"glog_test=2": true,
-	"glog_test=3": true, // If -vmodule sets V to 1, V(3) will succeed.
-	// These all use 2 and check the patterns. All are true.
-	"*=2":           true,
-	"?l*=2":         true,
-	"????_*=2":      true,
-	"??[mno]?_*t=2": true,
-	// These all use 2 and check the patterns. All are false.
-	"*x=2":         false,
-	"m*=2":         false,
-	"??_*=2":       false,
-	"?[abc]?_*t=2": false,
+	"glog_test.go=1": false, // If -vmodule sets V to 1, V(2) will fail.
+	"glog_test.go=2": true,
+	"glog_test.go=3": true, // If -vmodule sets V to 1, V(3) will succeed.
+
+	// Import path prefix matching
+	"logger/glog=1": false,
+	"logger/glog=2": true,
+	"logger/glog=3": true,
+
+	// Import path glob matching
+	"logger/*=1": false,
+	"logger/*=2": true,
+	"logger/*=3": true,
+
+	// These all use 2 and check the patterns.
+	"*=2": true,
 }
 
 // Test that vmodule globbing works as advertised.
diff --git a/node/api.go b/node/api.go
index a44ee16c0..909329e57 100644
--- a/node/api.go
+++ b/node/api.go
@@ -138,6 +138,11 @@ func (api *PrivateDebugAPI) Verbosity(level int) {
 	glog.SetV(level)
 }
 
+// Vmodule updates the node's logging verbosity pattern.
+func (api *PrivateDebugAPI) Vmodule(pattern string) error {
+	return glog.SetVmodule(pattern)
+}
+
 // PublicDebugAPI is the collection of debugging related API methods exposed over
 // both secure and unsecure RPC channels.
 type PublicDebugAPI struct {
diff --git a/rpc/api/admin.go b/rpc/api/admin.go
index 1133c9bca..daf2f31b4 100644
--- a/rpc/api/admin.go
+++ b/rpc/api/admin.go
@@ -31,7 +31,6 @@ import (
 	"github.com/ethereum/go-ethereum/core/types"
 	"github.com/ethereum/go-ethereum/crypto"
 	"github.com/ethereum/go-ethereum/eth"
-	"github.com/ethereum/go-ethereum/logger/glog"
 	"github.com/ethereum/go-ethereum/node"
 	"github.com/ethereum/go-ethereum/p2p/discover"
 	"github.com/ethereum/go-ethereum/rlp"
@@ -55,7 +54,6 @@ var (
 		"admin_nodeInfo":           (*adminApi).NodeInfo,
 		"admin_exportChain":        (*adminApi).ExportChain,
 		"admin_importChain":        (*adminApi).ImportChain,
-		"admin_verbosity":          (*adminApi).Verbosity,
 		"admin_setSolc":            (*adminApi).SetSolc,
 		"admin_datadir":            (*adminApi).DataDir,
 		"admin_startRPC":           (*adminApi).StartRPC,
@@ -225,16 +223,6 @@ func (self *adminApi) ExportChain(req *shared.Request) (interface{}, error) {
 	return true, nil
 }
 
-func (self *adminApi) Verbosity(req *shared.Request) (interface{}, error) {
-	args := new(VerbosityArgs)
-	if err := self.coder.Decode(req.Params, &args); err != nil {
-		return nil, shared.NewDecodeParamError(err.Error())
-	}
-
-	glog.SetV(args.Level)
-	return true, nil
-}
-
 func (self *adminApi) SetSolc(req *shared.Request) (interface{}, error) {
 	args := new(SetSolcArgs)
 	if err := self.coder.Decode(req.Params, &args); err != nil {
diff --git a/rpc/api/admin_args.go b/rpc/api/admin_args.go
index e3a2f72bf..e09597ad4 100644
--- a/rpc/api/admin_args.go
+++ b/rpc/api/admin_args.go
@@ -69,28 +69,6 @@ func (args *ImportExportChainArgs) UnmarshalJSON(b []byte) (err error) {
 	return nil
 }
 
-type VerbosityArgs struct {
-	Level int
-}
-
-func (args *VerbosityArgs) UnmarshalJSON(b []byte) (err error) {
-	var obj []interface{}
-	if err := json.Unmarshal(b, &obj); err != nil {
-		return shared.NewDecodeParamError(err.Error())
-	}
-
-	if len(obj) != 1 {
-		return shared.NewDecodeParamError("Expected enode as argument")
-	}
-
-	level, err := numString(obj[0])
-	if err == nil {
-		args.Level = int(level.Int64())
-	}
-
-	return nil
-}
-
 type SetSolcArgs struct {
 	Path string
 }
diff --git a/rpc/api/admin_js.go b/rpc/api/admin_js.go
index 413ea8d47..e6171cc74 100644
--- a/rpc/api/admin_js.go
+++ b/rpc/api/admin_js.go
@@ -46,12 +46,6 @@ web3._extend({
 			inputFormatter: [null, null]
 		}),
 		new web3._extend.Method({
-			name: 'verbosity',
-			call: 'admin_verbosity',
-			params: 1,
-			inputFormatter: [web3._extend.utils.fromDecimal]
-		}),
-		new web3._extend.Method({
 			name: 'setSolc',
 			call: 'admin_setSolc',
 			params: 1,
diff --git a/rpc/api/debug_js.go b/rpc/api/debug_js.go
index 03755ada0..030511add 100644
--- a/rpc/api/debug_js.go
+++ b/rpc/api/debug_js.go
@@ -62,7 +62,19 @@ web3._extend({
 			call: 'debug_metrics',
 			params: 1,
 			inputFormatter: [null]
-		})
+		}),
+		new web3._extend.Method({
+			name: 'verbosity',
+			call: 'debug_verbosity',
+			params: 1,
+			inputFormatter: [web3._extend.utils.fromDecimal]
+		}),
+		new web3._extend.Method({
+			name: 'vmodule',
+			call: 'debug_vmodule',
+			params: 1,
+			inputFormatter: [null]
+		}),
 	],
 	properties:
 	[