geth, geth/params: customized logger implemented

Makefile

@@ -73,7 +73,7 @@ test-geth:
 	@build/env.sh go tool cover -html=coverage.out -o coverage.html
 	@build/env.sh go tool cover -func=coverage.out
 
-test-config:
+test-params:
 	build/env.sh go test -v -coverprofile=coverage.out ./geth/params
 	@build/env.sh go tool cover -html=coverage.out -o coverage.html
 	@build/env.sh go tool cover -func=coverage.out

cmd/status/utils.go

@@ -1359,7 +1359,9 @@ func startTestNode(t *testing.T) <-chan struct{} {
 			"NetworkId": ` + strconv.Itoa(params.TestNetworkId) + `,
 			"DataDir": "` + geth.TestDataDir + `",
 			"HTTPPort": ` + strconv.Itoa(testConfig.Node.HTTPPort) + `,
-			"WSPort": ` + strconv.Itoa(testConfig.Node.WSPort) + `
+			"WSPort": ` + strconv.Itoa(testConfig.Node.WSPort) + `,
+			"LogEnabled": true,
+			"LogLevel": "INFO"
 		}`
 		response := StartNode(C.CString(configJSON))
 		err := geth.JSONError{}

geth/node.go

@@ -57,8 +57,12 @@ func (n *Node) GethStack() *node.Node {
 
 // MakeNode create a geth node entity
 func MakeNode(config *params.NodeConfig) *Node {
+	// setup logging
 	glog.CopyStandardLogTo("INFO")
 	glog.SetToStderr(true)
+	if _, err := params.SetupLogger(config); err != nil {
+		Fatalf(err)
+	}
 
 	// configure required node (should you need to update node's config, e.g. add bootstrap nodes, see node.Config)
 	stackConfig := &node.Config{

geth/params/config.go

@@ -130,6 +130,15 @@ type NodeConfig struct {
 	// handshake phase, counted separately for inbound and outbound connections.
 	MaxPendingPeers int
 
+	// LogToFile specified whether logs should be saved into file
+	LogEnabled bool
+
+	// LogFile is filename where exposed logs get written to
+	LogFile string
+
+	// LogLevel defines minimum log level. Valid names are "ERROR", "WARNING", "INFO", "DEBUG", and "DETAIL".
+	LogLevel string
+
 	// ChainConfig extra configuration for blockchain
 	*ChainConfig `json:"ChainConfig,"`
 
@@ -158,6 +167,8 @@ func NewNodeConfig(dataDir string, networkId int) (*NodeConfig, error) {
 		MaxPeers:        DefaultMaxPeers,
 		MaxPendingPeers: DefaultMaxPendingPeers,
 		IPCFile:         DefaultIPCFile,
+		LogFile:         DefaultLogFile,
+		LogLevel:        DefaultLogLevel,
 		ChainConfig:     &ChainConfig{},
 		LightEthConfig: &LightEthConfig{
 			DatabaseCache: DefaultDatabaseCache,

geth/params/defaults.go

@@ -45,6 +45,12 @@ const (
 	// DefaultDatabaseCache is memory (in MBs) allocated to internal caching (min 16MB / database forced)
 	DefaultDatabaseCache = 128
 
+	// DefaultLogFile defines where to write logs to
+	DefaultLogFile = "geth.log"
+
+	// DefaultLogLevel defines the minimum log level to report
+	DefaultLogLevel = "INFO"
+
 	// TestNetworkId is id of a test network
 	TestNetworkId = 3
 )

geth/params/logger.go

@@ -0,0 +1,145 @@
+package params
+
+import (
+	"bufio"
+	"fmt"
+	"io"
+	"os"
+	"path/filepath"
+	"sync"
+
+	"github.com/ethereum/go-ethereum/logger"
+	"github.com/ethereum/go-ethereum/logger/glog"
+)
+
+// Logger is wrapper for custom logging
+type Logger struct {
+	sync.Mutex
+	logFile  *os.File
+	observer chan string
+	started  chan struct{}
+	stopped  chan struct{}
+	stopFlag bool
+}
+
+var onceStartLogger sync.Once
+
+// SetupLogger configs logger using parameters in config
+func SetupLogger(config *NodeConfig) (nodeLogger *Logger, err error) {
+	if !config.LogEnabled {
+		return nil, nil
+	}
+
+	nodeLogger = &Logger{
+		started: make(chan struct{}, 1),
+		stopped: make(chan struct{}, 1),
+	}
+
+	onceStartLogger.Do(func() {
+		err = nodeLogger.createAndStartLogger(config)
+	})
+
+	return
+}
+
+// SetV allows to dynamically change log level of messages being written
+func (l *Logger) SetV(logLevel string) {
+	glog.SetV(parseLogLevel(logLevel))
+}
+
+// Stop marks logger as stopped, forcing to relinquish hold
+// on os.Stderr and restore it back to the original
+func (l *Logger) Stop() (stopped chan struct{}) {
+	l.Lock()
+	defer l.Unlock()
+
+	l.stopFlag = true
+	stopped = l.stopped
+	return
+}
+
+// Observe registers extra writer where logs should be written to.
+// This method is used in unit tests, and should NOT be relied upon otherwise.
+func (l *Logger) Observe(observer chan string) (started chan struct{}) {
+	l.observer = observer
+	started = l.started
+	return
+}
+
+// createAndStartLogger initializes and starts logger by replacing os.Stderr with custom writer.
+// Custom writer intercepts all requests to os.Stderr, then forwards to multiple readers, which
+// include log file and the original os.Stderr (so that logs output on screen as well)
+func (l *Logger) createAndStartLogger(config *NodeConfig) error {
+	// customize glog
+	glog.CopyStandardLogTo("INFO")
+	glog.SetToStderr(true)
+	glog.SetV(parseLogLevel(config.LogLevel))
+
+	// create log file
+	logFile, err := os.OpenFile(filepath.Join(config.DataDir, config.LogFile), os.O_CREATE|os.O_APPEND|os.O_RDWR, 0666)
+	if err != nil {
+		return err
+	}
+
+	// inject reader to pipe all writes to Stderr
+	r, w, err := os.Pipe()
+	if err != nil {
+		return err
+	}
+
+	// replace Stderr
+	origStderr := os.Stderr
+	os.Stderr = w
+	scanner := bufio.NewScanner(r)
+
+	// configure writer, send to the original os.Stderr and log file
+	logWriter := io.MultiWriter(origStderr, logFile)
+
+	go func() {
+		defer func() { // restore original Stderr
+			os.Stderr = origStderr
+			logFile.Close()
+			close(l.stopped)
+		}()
+
+		// notify observer that it can start polling (unit test, normally)
+		close(l.started)
+
+		for scanner.Scan() {
+			fmt.Fprintln(logWriter, scanner.Text())
+
+			if l.observer != nil {
+				l.observer <- scanner.Text()
+			}
+
+			// allow to restore original os.Stderr if logger is stopped
+			if l.stopFlag {
+				return
+			}
+		}
+
+		if err := scanner.Err(); err != nil {
+			fmt.Fprintf(origStderr, "error reading logs: %v\n", err)
+		}
+	}()
+
+	return nil
+}
+
+// parseLogLevel parses string and returns logger.* constant
+func parseLogLevel(logLevel string) int {
+	switch logLevel {
+	case "ERROR":
+		return logger.Error
+	case "WARNING":
+		return logger.Warn
+	case "INFO":
+		return logger.Info
+	case "DEBUG":
+		return logger.Debug
+	case "DETAIL":
+		return logger.Detail
+	}
+
+	return logger.Info
+}

geth/params/logger_test.go

@@ -0,0 +1,145 @@
+package params_test
+
+import (
+	"fmt"
+	"io/ioutil"
+	"log"
+	"os"
+	"path/filepath"
+	"testing"
+	"time"
+
+	"github.com/ethereum/go-ethereum/logger"
+	"github.com/ethereum/go-ethereum/logger/glog"
+	"github.com/status-im/status-go/geth/params"
+)
+
+func TestLogger(t *testing.T) {
+	tmpDir, err := ioutil.TempDir(os.TempDir(), "geth-logger-tests")
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer os.RemoveAll(tmpDir)
+
+	nodeConfig, err := params.NewNodeConfig(tmpDir, params.TestNetworkId)
+	if err != nil {
+		t.Fatal("cannot create config object")
+	}
+	nodeLogger, err := params.SetupLogger(nodeConfig)
+	if err != nil {
+		t.Fatal("cannot create logger object")
+	}
+	if nodeLogger != nil {
+		t.Fatalf("logger is not empty (while logs are disabled): %v", nodeLogger)
+	}
+
+	nodeConfig.LogEnabled = true
+	nodeLogger, err = params.SetupLogger(nodeConfig)
+	if err != nil {
+		t.Fatal("cannot create logger object")
+	}
+	if nodeLogger == nil {
+		t.Fatal("logger is empty (while logs are enabled)")
+	}
+
+	logReader := make(chan string, 100)
+	loggerStarted := nodeLogger.Observe(logReader)
+	<-loggerStarted // allow logger to setup itself
+
+	expectedLogTextInLogFile := "" // aggregate log contents accross all tests
+	validateLoggerObserverText := func(observer chan string, expectedLogText string) {
+		logText := ""
+
+		select {
+		case logText = <-observer:
+			expectedLogTextInLogFile += logText + "\n"
+			logText = logText[len(logText)-len(expectedLogText):] // as logs can be prepended with glog info
+		case <-time.After(3 * time.Second):
+		}
+
+		if logText != expectedLogText {
+			t.Fatalf("invalid log, expected: %#v, got: %#v", expectedLogText, logText)
+		}
+	}
+
+	loggerTestCases := []struct {
+		name     string
+		log      func()
+		validate func()
+	}{
+		{
+			"log using standard log package",
+			func() {
+				log.Println("use standard log package")
+			},
+			func() {
+				validateLoggerObserverText(logReader, "use standard log package")
+			},
+		},
+		{
+			"log using standard glog package",
+			func() {
+				glog.V(logger.Info).Infoln("use glog package")
+			},
+			func() {
+				validateLoggerObserverText(logReader, "use glog package")
+			},
+		},
+		{
+			"log using os.Stderr (write directly to it)",
+			func() {
+				fmt.Fprintln(os.Stderr, "use os.Stderr package")
+			},
+			func() {
+				validateLoggerObserverText(logReader, "use os.Stderr package")
+			},
+		},
+		{
+			"log using DEBUG log level (with appropriate level set)",
+			func() {
+				nodeLogger.SetV("DEBUG")
+				glog.V(logger.Debug).Info("logged DEBUG log level message")
+			},
+			func() {
+				validateLoggerObserverText(logReader, "logged DEBUG log level message")
+			},
+		},
+		{
+			"log using DEBUG log level (with appropriate level NOT set)",
+			func() {
+				nodeLogger.SetV("INFO")
+				glog.V(logger.Info).Info("logged INFO log level message")
+				glog.V(logger.Debug).Info("logged DEBUG log level message")
+			},
+			func() {
+				validateLoggerObserverText(logReader, "logged INFO log level message")
+			},
+		},
+	}
+
+	for _, testCase := range loggerTestCases {
+		t.Log("test: " + testCase.name)
+		testCase.log()
+		testCase.validate()
+	}
+
+	logFileContents, err := ioutil.ReadFile(filepath.Join(tmpDir, nodeConfig.LogFile))
+	if err != nil {
+		t.Fatalf("cannot read logs file: %v", err)
+	}
+	if string(logFileContents) != expectedLogTextInLogFile {
+		t.Fatalf("wrong content of log file, expected:\n%v\ngot:\n%v", expectedLogTextInLogFile, string(logFileContents))
+	}
+
+	go func() {
+		for i := 0; i < 10; i++ {
+			glog.Infoln("logging message: ", i)
+			time.Sleep(1 * time.Millisecond)
+		}
+	}()
+
+	// stop logger and see if os.Stderr and glog continue functioning
+	<-nodeLogger.Stop()
+
+	glog.Infoln("logging message: this message happens after custom logger has been stopped")
+}

geth/params/testdata/config.testnet.json

@@ -15,6 +15,9 @@
     "TLSEnabled": false,
     "MaxPeers": 25,
     "MaxPendingPeers": 0,
+    "LogEnabled": false,
+    "LogFile": "geth.log",
+    "LogLevel": "INFO",
     "ChainConfig": {
         "ChainId": 3,
         "HomesteadBlock": 0,

geth/txqueue_test.go

@@ -104,7 +104,7 @@ func TestQueuedContracts(t *testing.T) {
 	}
 
 	if !reflect.DeepEqual(txHash, txHashCheck) {
-		t.Errorf("Transaction hash returned from SendTransaction is invalid: expected %s, got %s", txHashCheck, txHash)
+		t.Errorf("Transaction hash returned from SendTransaction is invalid: expected %s, got %s", txHashCheck.Hex(), txHash.Hex())
 		return
 	}
 
@@ -203,7 +203,7 @@ func TestQueuedTransactions(t *testing.T) {
 	}
 
 	if !reflect.DeepEqual(txHash, txHashCheck) {
-		t.Errorf("Transaction hash returned from SendTransaction is invalid: expected %s, got %s", txHashCheck, txHash)
+		t.Errorf("Transaction hash returned from SendTransaction is invalid: expected %s, got %s", txHashCheck.Hex(), txHash.Hex())
 		return
 	}
 
@@ -321,7 +321,7 @@ func TestDoubleCompleteQueuedTransactions(t *testing.T) {
 	}
 
 	if !reflect.DeepEqual(txHash, txHashCheck) {
-		t.Errorf("tx hash returned from SendTransaction is invalid: expected %s, got %s", txHashCheck, txHash)
+		t.Errorf("tx hash returned from SendTransaction is invalid: expected %s, got %s", txHashCheck.Hex(), txHash.Hex())
 		return
 	}
 

geth/utils.go

@@ -184,6 +184,7 @@ func PrepareTestNode() (err error) {
 	}
 	config.HTTPPort = testConfig.Node.HTTPPort // to avoid conflicts with running app, using different port in tests
 	config.WSPort = testConfig.Node.WSPort     // ditto
+	config.LogEnabled = true
 
 	err = CreateAndRunNode(config)
 	if err != nil {