Logging improvements for running and testing skywire-node

1. Fixed logging for skywire-node: there is only one MasterLogger creation now, fixed hooks on skywire-node level 2. Logging during tests: turned off by default, turn on by $TEST_LOGGING_LEVEL 3. Integragration tests customizable by $SYSLOG_OPTS variable 4. Makefile goal: `make run-syslog` - creates clean instance of syslog-ng with logs mounted to /tmp/syslog 5. README.md - changes documented with examples of usage Closes: #404
skycoin · Jun 19, 2019 · 8a01ff3 · 8a01ff3
1 parent 8a4da0b
commit 8a01ff3
Show file tree

Hide file tree

Showing 9 changed files with 171 additions and 56 deletions.
diff --git a/Makefile b/Makefile
@@ -170,6 +170,12 @@ docker-rerun: docker-stop
 	${DOCKER_OPTS} go build -race -o ./node/skywire-node ./cmd/skywire-node 
 	docker container start -i ${DOCKER_NODE}
 
+run-syslog: ## Run syslog-ng in docker. Logs are mounted under /tmp/syslog
+	-rm -rf /tmp/syslog
+	-mkdir -p /tmp/syslog
+	-docker container rm syslog-ng -f
+	docker run -d -p 514:514/udp  -v /tmp/syslog:/var/log  --name syslog-ng balabit/syslog-ng:latest 
+
 
 integration-startup: ## Starts up the required transports between 'skywire-node's of interactive testing environment
 	./integration/startup.sh

diff --git a/README.md b/README.md
@@ -2,6 +2,42 @@
 
 # Skywire Mainnet - Public Test Phase
 
+- [Skywire Mainnet - Public Test Phase](#Skywire-Mainnet---Public-Test-Phase)
+  - [Notes on this release](#Notes-on-this-release)
+  - [Architecture](#Architecture)
+  - [Build and run](#Build-and-run)
+    - [Requirements](#Requirements)
+    - [Build](#Build)
+    - [Run `skywire-node`](#Run-skywire-node)
+    - [Run `skywire-node` in docker container](#Run-skywire-node-in-docker-container)
+    - [Run `skywire-cli`](#Run-skywire-cli)
+    - [Apps](#Apps)
+    - [Transports](#Transports)
+  - [App programming API](#App-programming-API)
+  - [Testing](#Testing)
+    - [Testing with default settings](#Testing-with-default-settings)
+    - [Customization with environment variables](#Customization-with-environment-variables)
+      - [$TEST_OPTS](#TESTOPTS)
+      - [$TEST_LOGGING_LEVEL](#TESTLOGGINGLEVEL)
+      - [$SYSLOG_OPTS](#SYSLOGOPTS)
+  - [Updater](#Updater)
+  - [Running skywire in docker containers](#Running-skywire-in-docker-containers)
+    - [Run dockerized `skywire-node`](#Run-dockerized-skywire-node)
+      - [Structure of `./node`](#Structure-of-node)
+    - [Refresh and restart `SKY01`](#Refresh-and-restart-SKY01)
+    - [Customization of dockers](#Customization-of-dockers)
+      - [1. DOCKER_IMAGE](#1-DOCKERIMAGE)
+      - [2.DOCKER_NETWORK](#2DOCKERNETWORK)
+      - [3. DOCKER_NODE](#3-DOCKERNODE)
+      - [4. DOCKER_OPTS](#4-DOCKEROPTS)
+    - [Dockerized `skywire-node` recipes](#Dockerized-skywire-node-recipes)
+      - [1. Get Public Key of docker-node](#1-Get-Public-Key-of-docker-node)
+      - [2. Get an IP of node](#2-Get-an-IP-of-node)
+      - [3. Open in browser containerized `skychat` application](#3-Open-in-browser-containerized-skychat-application)
+      - [4. Create new dockerized `skywire-nodes`](#4-Create-new-dockerized-skywire-nodes)
+      - [5. Env-vars for develoment-/testing- purposes](#5-Env-vars-for-develoment-testing--purposes)
+      - [6. "Hello-Mike-Hello-Joe" test](#6-%22Hello-Mike-Hello-Joe%22-test)
+
 ## Notes on this release
 
 This is a public testing version of the Skywire mainnet and is intended for developers use to find bugs only. It is not yet intended to replace the testnet and miners should not install this software on their miners or they may lose their reward eligibility. 
@@ -156,6 +192,59 @@ func (app *App) Dial(raddr *Addr) (net.Conn, error) {}
 func (app *App) Close() error {}
 ```
 
+## Testing
+
+### Testing with default settings
+
+```bash
+$ make test
+```
+
+### Customization with environment variables
+
+#### $TEST_OPTS
+
+Options for `go test` could be customized with $TEST_OPTS variable
+
+E.g.
+```bash
+$ export TEST_OPTS="-race -tags no_ci -timeout 90s -v"
+$ make test
+```
+
+#### $TEST_LOGGING_LEVEL
+
+By default all log messages during tests are disabled.
+In case of need to turn on log messages it could be achieved by setting $TEST_LOGGING_LEVEL variable
+
+Possible values:
+- "debug"
+- "info", "notice"
+- "warn", "warning"
+- "error"
+- "fatal", "critical"
+- "panic"
+
+E.g.
+```bash 
+$ export TEST_LOGGING_LEVEL="info"
+$ go clean -testcache || go test ./pkg/transport -v -run ExampleManager_CreateTransport
+$ unset TEST_LOGGING_LEVEL
+$ go clean -testcache || go test ./pkg/transport -v
+```
+
+#### $SYSLOG_OPTS
+
+In case of need to collect logs in syslog during integration tests $SYSLOG_OPTS variable can be used.
+
+E.g.
+```bash
+$ make run_syslog ## run syslog-ng in docker container with logs mounted to /tmp/syslog
+$ export SYSLOG_OPTS='--syslog localhost:514'
+$ make integration-run-messaging ## or other integration-run-* goal
+$ sudo cat /tmp/syslog/messages ## collected logs from NodeA, NodeB, NodeC instances
+```
+
 ## Updater
 
 This software comes with an updater, which is located in this repo: https://github.com/skycoin/skywire-updater. Follow the instructions in the README.md for further information. It can be used with a CLI for now and will be usable with the manager interface.

diff --git a/cmd/skywire-node/commands/root.go b/cmd/skywire-node/commands/root.go
@@ -5,6 +5,7 @@ import (
 	"encoding/json"
 	"fmt"
 	"io"
+	"io/ioutil"
 	"log"
 	"log/syslog"
 	"os"
@@ -37,14 +38,47 @@ type runCfg struct {
 	port         string
 	args         []string
 
-	profileStop func()
-	logger      *logging.Logger
-	conf        node.Config
-	node        *node.Node
+	profileStop  func()
+	logger       *logging.Logger
+	masterLogger *logging.MasterLogger
+	conf         node.Config
+	node         *node.Node
 }
 
 var cfg *runCfg
 
+var rootCmd = &cobra.Command{
+	Use:   "skywire-node [config-path]",
+	Short: "App Node for skywire",
+	Run: func(_ *cobra.Command, args []string) {
+		cfg.args = args
+
+		cfg.startProfiler().
+			startLogger().
+			readConfig().
+			runNode().
+			waitOsSignals().
+			stopNode()
+	},
+	Version: node.Version,
+}
+
+func init() {
+	cfg = &runCfg{}
+	rootCmd.Flags().StringVarP(&cfg.syslogAddr, "syslog", "", "none", "syslog server address. E.g. localhost:514")
+	rootCmd.Flags().StringVarP(&cfg.tag, "tag", "", "skywire", "logging tag")
+	rootCmd.Flags().BoolVarP(&cfg.cfgFromStdin, "stdin", "i", false, "read config from STDIN")
+	rootCmd.Flags().StringVarP(&cfg.profileMode, "profile", "p", "none", "enable profiling with pprof. Mode:  none or one of: [cpu, mem, mutex, block, trace, http]")
+	rootCmd.Flags().StringVarP(&cfg.port, "port", "", "6060", "port for http-mode of pprof")
+}
+
+// Execute executes root CLI command.
+func Execute() {
+	if err := rootCmd.Execute(); err != nil {
+		log.Fatal(err)
+	}
+}
+
 func (cfg *runCfg) startProfiler() *runCfg {
 	var option func(*profile.Profile)
 	switch cfg.profileMode {
@@ -74,14 +108,16 @@ func (cfg *runCfg) startProfiler() *runCfg {
 }
 
 func (cfg *runCfg) startLogger() *runCfg {
-	cfg.logger = logging.MustGetLogger(cfg.tag)
+	cfg.masterLogger = logging.NewMasterLogger()
+	cfg.logger = cfg.masterLogger.PackageLogger(cfg.tag)
 
 	if cfg.syslogAddr != "none" {
 		hook, err := logrus_syslog.NewSyslogHook("udp", cfg.syslogAddr, syslog.LOG_INFO, cfg.tag)
 		if err != nil {
 			cfg.logger.Error("Unable to connect to syslog daemon")
 		} else {
-			logging.AddHook(hook)
+			cfg.masterLogger.AddHook(hook)
+			cfg.masterLogger.Out = ioutil.Discard
 		}
 	}
 	return cfg
@@ -109,7 +145,7 @@ func (cfg *runCfg) readConfig() *runCfg {
 }
 
 func (cfg *runCfg) runNode() *runCfg {
-	node, err := node.NewNode(&cfg.conf)
+	node, err := node.NewNode(&cfg.conf, cfg.masterLogger)
 	if err != nil {
 		cfg.logger.Fatal("Failed to initialize node: ", err)
 	}
@@ -152,35 +188,3 @@ func (cfg *runCfg) waitOsSignals() *runCfg {
 	}()
 	return cfg
 }
-
-var rootCmd = &cobra.Command{
-	Use:   "skywire-node [config-path]",
-	Short: "App Node for skywire",
-	Run: func(_ *cobra.Command, args []string) {
-		cfg.args = args
-
-		cfg.startProfiler().
-			startLogger().
-			readConfig().
-			runNode().
-			waitOsSignals().
-			stopNode()
-	},
-	Version: node.Version,
-}
-
-func init() {
-	cfg = &runCfg{}
-	rootCmd.Flags().StringVarP(&cfg.syslogAddr, "syslog", "", "none", "syslog server address. E.g. localhost:514")
-	rootCmd.Flags().StringVarP(&cfg.tag, "tag", "", "skywire", "logging tag")
-	rootCmd.Flags().BoolVarP(&cfg.cfgFromStdin, "stdin", "i", false, "read config from STDIN")
-	rootCmd.Flags().StringVarP(&cfg.profileMode, "profile", "p", "none", "enable profiling with pprof. Mode:  none or one of: [cpu, mem, mutex, block, trace, http]")
-	rootCmd.Flags().StringVarP(&cfg.port, "port", "", "6060", "port for http-mode of pprof")
-}
-
-// Execute executes root CLI command.
-func Execute() {
-	if err := rootCmd.Execute(); err != nil {
-		log.Fatal(err)
-	}
-}
diff --git a/integration/run-generic-env.sh b/integration/run-generic-env.sh
@@ -10,11 +10,14 @@ echo "Checking transport-discovery is up"
 curl --retry 5  --retry-connrefused 1 --connect-timeout 5 https://transport.discovery.skywire.skycoin.net/security/nonces/$PK_A   
 
 tmux rename-window -t skywire NodeA
-tmux send-keys -t NodeA './skywire-node ./integration/generic/nodeA.json --tag NodeA' C-m
+tmux send-keys -t NodeA -l "./skywire-node ./integration/generic/nodeA.json --tag NodeA $SYSLOG_OPTS"
+tmux send-keys C-m
 tmux new-window -t skywire -n NodeB
-tmux send-keys -t NodeB './skywire-node ./integration/intermediary-nodeB.json --tag NodeB' C-m
+tmux send-keys -t NodeB -l "./skywire-node ./integration/intermediary-nodeB.json --tag NodeB $SYSLOG_OPTS" 
+tmux send-keys C-m
 tmux new-window -t skywire -n NodeC
-tmux send-keys -t NodeC './skywire-node ./integration/generic/nodeC.json --tag NodeC' C-m
+tmux send-keys -t NodeC -l "./skywire-node ./integration/generic/nodeC.json --tag NodeC $SYSLOG_OPTS" 
+tmux send-keys C-m
 
 tmux new-window -t skywire -n shell
 

diff --git a/integration/run-messaging-env.sh b/integration/run-messaging-env.sh
@@ -10,11 +10,14 @@ echo "Checking transport-discovery is up"
 curl --retry 5  --retry-connrefused 1 --connect-timeout 5 https://transport.discovery.skywire.skycoin.net/security/nonces/$PK_A   
 
 tmux rename-window -t skywire NodeA
-tmux send-keys -t NodeA './skywire-node ./integration/messaging/nodeA.json --tag NodeA' C-m
+tmux send-keys -t NodeA -l "./skywire-node ./integration/messaging/nodeA.json --tag NodeA $SYSLOG_OPTS"
+tmux send-keys C-m
 tmux new-window -t skywire -n NodeB
-tmux send-keys -t NodeB './skywire-node ./integration/intermediary-nodeB.json --tag NodeB' C-m
+tmux send-keys -t NodeB -l "./skywire-node ./integration/intermediary-nodeB.json --tag NodeB $SYSLOG_OPTS" 
+tmux send-keys C-m
 tmux new-window -t skywire -n NodeC
-tmux send-keys -t NodeC './skywire-node ./integration/messaging/nodeC.json --tag NodeC' C-m
+tmux send-keys -t NodeC -l "./skywire-node ./integration/messaging/nodeC.json --tag NodeC $SYSLOG_OPTS" 
+tmux send-keys C-m
 
 tmux new-window -t skywire -n shell
 

diff --git a/integration/run-proxy-env.sh b/integration/run-proxy-env.sh
@@ -10,11 +10,14 @@ echo "Checking transport-discovery is up"
 curl --retry 5  --retry-connrefused 1 --connect-timeout 5 https://transport.discovery.skywire.skycoin.net/security/nonces/$PK_A   
 
 tmux rename-window -t skywire NodeA
-tmux send-keys -t NodeA './skywire-node ./integration/proxy/nodeA.json --tag NodeA' C-m
+tmux send-keys -t NodeA -l "./skywire-node ./integration/proxy/nodeA.json --tag NodeA $SYSLOG_OPTS"
+tmux send-keys C-m
 tmux new-window -t skywire -n NodeB
-tmux send-keys -t NodeB './skywire-node ./integration/intermediary-nodeB.json --tag NodeB' C-m
+tmux send-keys -t NodeB -l "./skywire-node ./integration/intermediary-nodeB.json --tag NodeB $SYSLOG_OPTS" 
+tmux send-keys C-m
 tmux new-window -t skywire -n NodeC
-tmux send-keys -t NodeC './skywire-node ./integration/proxy/nodeC.json --tag NodeC' C-m
+tmux send-keys -t NodeC -l "./skywire-node ./integration/proxy/nodeC.json --tag NodeC $SYSLOG_OPTS" 
+tmux send-keys C-m
 
 tmux new-window -t skywire -n shell
 

diff --git a/integration/run-ssh-env.sh b/integration/run-ssh-env.sh
@@ -10,11 +10,14 @@ echo "Checking transport-discovery is up"
 curl --retry 5  --retry-connrefused 1 --connect-timeout 5 https://transport.discovery.skywire.skycoin.net/security/nonces/$PK_A   
 
 tmux rename-window -t skywire NodeA
-tmux send-keys -t NodeA './skywire-node ./integration/ssh/nodeA.json --tag NodeA' C-m
+tmux send-keys -t NodeA -l "./skywire-node ./integration/ssh/nodeA.json --tag NodeA $SYSLOG_OPTS"
+tmux send-keys C-m
 tmux new-window -t skywire -n NodeB
-tmux send-keys -t NodeB './skywire-node ./integration/intermediary-nodeB.json --tag NodeB' C-m
+tmux send-keys -t NodeB -l "./skywire-node ./integration/intermediary-nodeB.json --tag NodeB $SYSLOG_OPTS" 
+tmux send-keys C-m
 tmux new-window -t skywire -n NodeC
-tmux send-keys -t NodeC './skywire-node ./integration/ssh/nodeC.json --tag NodeC' C-m
+tmux send-keys -t NodeC -l "./skywire-node ./integration/ssh/nodeC.json --tag NodeC $SYSLOG_OPTS" 
+tmux send-keys C-m
 
 tmux new-window -t skywire -n shell
 

diff --git a/pkg/node/node.go b/pkg/node/node.go
@@ -107,14 +107,14 @@ type Node struct {
 }
 
 // NewNode constructs new Node.
-func NewNode(config *Config) (*Node, error) {
+func NewNode(config *Config, masterLogger *logging.MasterLogger) (*Node, error) {
 	node := &Node{
 		config:      config,
 		executer:    newOSExecuter(),
 		startedApps: make(map[string]*appBind),
 	}
 
-	node.Logger = logging.NewMasterLogger()
+	node.Logger = masterLogger
 	node.logger = node.Logger.PackageLogger("skywire")
 
 	pk := config.Node.StaticPubKey

diff --git a/pkg/node/node_test.go b/pkg/node/node_test.go
@@ -4,6 +4,7 @@ import (
 	"context"
 	"encoding/json"
 	"errors"
+	"io/ioutil"
 	"log"
 	"net"
 	"os"
@@ -30,16 +31,19 @@ import (
 	"github.com/skycoin/skywire/pkg/transport"
 )
 
+var masterLogger *logging.MasterLogger
+
 func TestMain(m *testing.M) {
+	masterLogger = logging.NewMasterLogger()
 	loggingLevel, ok := os.LookupEnv("TEST_LOGGING_LEVEL")
 	if ok {
 		lvl, err := logging.LevelFromString(loggingLevel)
 		if err != nil {
 			log.Fatal(err)
 		}
-		logging.SetLevel(lvl)
+		masterLogger.SetLevel(lvl)
 	} else {
-		logging.Disable()
+		masterLogger.Out = ioutil.Discard
 	}
 
 	os.Exit(m.Run())
@@ -65,7 +69,7 @@ func TestNewNode(t *testing.T) {
 
 	defer os.RemoveAll("local")
 
-	node, err := NewNode(&conf)
+	node, err := NewNode(&conf, masterLogger)
 	require.NoError(t, err)
 
 	assert.NotNil(t, node.router)