Logging improvements (#195)

- Fix (and test) filtering of lines
- Filter out shadowsocks cannot resolve error
- Change tinyproxy color
- Deduct logging level according to message content

cmd/gluetun/main.go

@@ -5,7 +5,6 @@ import (
 	"fmt"
 	"os"
 	"os/signal"
-	"regexp"
 	"strings"
 	"sync"
 	"syscall"
@@ -19,6 +18,7 @@ import (
 	"github.com/qdm12/private-internet-access-docker/internal/cli"
 	"github.com/qdm12/private-internet-access-docker/internal/dns"
 	"github.com/qdm12/private-internet-access-docker/internal/firewall"
+	gluetunLogging "github.com/qdm12/private-internet-access-docker/internal/logging"
 	"github.com/qdm12/private-internet-access-docker/internal/openvpn"
 	"github.com/qdm12/private-internet-access-docker/internal/params"
 	"github.com/qdm12/private-internet-access-docker/internal/publicip"
@@ -26,7 +26,6 @@ import (
 	"github.com/qdm12/private-internet-access-docker/internal/server"
 	"github.com/qdm12/private-internet-access-docker/internal/settings"
 	"github.com/qdm12/private-internet-access-docker/internal/shadowsocks"
-	"github.com/qdm12/private-internet-access-docker/internal/splash"
 	"github.com/qdm12/private-internet-access-docker/internal/tinyproxy"
 )
 
@@ -58,7 +57,7 @@ func _main(background context.Context, args []string) int {
 	wg := &sync.WaitGroup{}
 	fatalOnError := makeFatalOnError(logger, cancel, wg)
 	paramsReader := params.NewReader(logger)
-	fmt.Println(splash.Splash(
+	fmt.Println(gluetunLogging.Splash(
 		paramsReader.GetVersion(),
 		paramsReader.GetVcsRef(),
 		paramsReader.GetBuildDate()))
@@ -263,8 +262,18 @@ func collectStreamLines(ctx context.Context, streamMerger command.StreamMerger,
 	// Blocking line merging paramsReader for all programs: openvpn, tinyproxy, unbound and shadowsocks
 	logger.Info("Launching standard output merger")
 	streamMerger.CollectLines(ctx, func(line string) {
-		line = trimEventualProgramPrefix(line)
+		line, level := gluetunLogging.PostProcessLine(line)
-		logger.Info(line)
+		if line == "" {
+			return
+		}
+		switch level {
+		case logging.InfoLevel:
+			logger.Info(line)
+		case logging.WarnLevel:
+			logger.Warn(line)
+		case logging.ErrorLevel:
+			logger.Error(line)
+		}
 		if strings.Contains(line, "Initialization Sequence Completed") {
 			signalConnected()
 		}
@@ -273,27 +282,6 @@ func collectStreamLines(ctx context.Context, streamMerger command.StreamMerger,
 	})
 }
 
-func trimEventualProgramPrefix(s string) string {
-	switch {
-	case strings.HasPrefix(s, "unbound: "):
-		prefixRegex := regexp.MustCompile(`unbound: \[[0-9]{10}\] unbound\[[0-9]+:0\] `)
-		prefix := prefixRegex.FindString(s)
-		return fmt.Sprintf("unbound: %s", s[len(prefix):])
-	case strings.HasPrefix(s, "shadowsocks: "):
-		prefixRegex := regexp.MustCompile(`shadowsocks:[ ]+2[0-9]{3}\-[0-1][0-9]\-[0-3][0-9] [0-2][0-9]:[0-5][0-9]:[0-5][0-9] `)
-		prefix := prefixRegex.FindString(s)
-		return fmt.Sprintf("shadowsocks: %s", s[len(prefix):])
-	case strings.HasPrefix(s, "tinyproxy: "):
-		logLevelRegex := regexp.MustCompile(`INFO|CONNECT|NOTICE|WARNING|ERROR|CRITICAL`)
-		logLevel := logLevelRegex.FindString(s)
-		prefixRegex := regexp.MustCompile(`tinyproxy: (INFO|CONNECT|NOTICE|WARNING|ERROR|CRITICAL)[ ]+(Jan|Feb|Mar|Apr|May|Jun|Jul|Aug|Sep|Oct|Nov|Dec) [0-3][0-9] [0-2][0-9]:[0-5][0-9]:[0-5][0-9] \[[0-9]+\]: `)
-		prefix := prefixRegex.FindString(s)
-		return fmt.Sprintf("tinyproxy: %s %s", logLevel, s[len(prefix):])
-	default:
-		return s
-	}
-}
-
 func onConnected(allSettings settings.Settings, logger logging.Logger, routingConf routing.Routing,
 	portForward, restartUnbound, restartPublicIP chan<- struct{},
 ) {

internal/constants/colors.go

@@ -2,22 +2,22 @@ package constants
 
 import "github.com/fatih/color"
 
-func ColorUnbound() color.Color {
+func ColorUnbound() *color.Color {
-	return *color.New(color.FgCyan)
+	return color.New(color.FgCyan)
 }
 
-func ColorTinyproxy() color.Color {
+func ColorTinyproxy() *color.Color {
-	return *color.New(color.FgHiMagenta)
+	return color.New(color.FgHiGreen)
 }
 
-func ColorShadowsocks() color.Color {
+func ColorShadowsocks() *color.Color {
-	return *color.New(color.FgHiYellow)
+	return color.New(color.FgHiYellow)
 }
 
-func ColorShadowsocksError() color.Color {
+func ColorShadowsocksError() *color.Color {
-	return *color.New(color.FgHiRed)
+	return color.New(color.FgHiRed)
 }
 
-func ColorOpenvpn() color.Color {
+func ColorOpenvpn() *color.Color {
-	return *color.New(color.FgHiMagenta)
+	return color.New(color.FgHiMagenta)
 }

internal/dns/loop.go

@@ -102,8 +102,7 @@ func (l *looper) Run(ctx context.Context, restart <-chan struct{}, wg *sync.Wait
 		}
 
 		// Started successfully
-		go l.streamMerger.Merge(unboundCtx, stream,
+		go l.streamMerger.Merge(unboundCtx, stream, command.MergeName("unbound"))
-			command.MergeName("unbound"), command.MergeColor(constants.ColorUnbound()))
 		l.conf.UseDNSInternally(net.IP{127, 0, 0, 1})                                                    // use Unbound
 		if err := l.conf.UseDNSSystemWide(net.IP{127, 0, 0, 1}, l.settings.KeepNameserver); err != nil { // use Unbound
 			l.logger.Error(err)

internal/logging/line.go

@@ -0,0 +1,93 @@
+package logging
+
+import (
+	"fmt"
+	"regexp"
+	"strings"
+
+	"github.com/qdm12/golibs/logging"
+	"github.com/qdm12/private-internet-access-docker/internal/constants"
+)
+
+var regularExpressions = struct { //nolint:gochecknoglobals
+	unboundPrefix          *regexp.Regexp
+	shadowsocksPrefix      *regexp.Regexp
+	shadowsocksErrorPrefix *regexp.Regexp
+	tinyproxyLoglevel      *regexp.Regexp
+	tinyproxyPrefix        *regexp.Regexp
+}{
+	unboundPrefix:          regexp.MustCompile(`unbound: \[[0-9]{10}\] unbound\[[0-9]+:0\] `),
+	shadowsocksPrefix:      regexp.MustCompile(`shadowsocks:[ ]+2[0-9]{3}\-[0-1][0-9]\-[0-3][0-9] [0-2][0-9]:[0-5][0-9]:[0-5][0-9] `),
+	shadowsocksErrorPrefix: regexp.MustCompile(`shadowsocks error:[ ]+2[0-9]{3}\-[0-1][0-9]\-[0-3][0-9] [0-2][0-9]:[0-5][0-9]:[0-5][0-9] `),
+	tinyproxyLoglevel:      regexp.MustCompile(`INFO|CONNECT|NOTICE|WARNING|ERROR|CRITICAL`),
+	tinyproxyPrefix:        regexp.MustCompile(`tinyproxy: .+[ ]+(Jan|Feb|Mar|Apr|May|Jun|Jul|Aug|Sep|Oct|Nov|Dec) [0-3][0-9] [0-2][0-9]:[0-5][0-9]:[0-5][0-9] \[[0-9]+\]: `),
+}
+
+func PostProcessLine(s string) (filtered string, level logging.Level) {
+	switch {
+	case strings.HasPrefix(s, "openvpn: "):
+		filtered = constants.ColorOpenvpn().Sprintf(s)
+		return filtered, logging.InfoLevel
+	case strings.HasPrefix(s, "unbound: "):
+		prefix := regularExpressions.unboundPrefix.FindString(s)
+		filtered = s[len(prefix):]
+		switch {
+		case strings.HasPrefix(filtered, "notice: "):
+			filtered = strings.TrimPrefix(filtered, "notice: ")
+			level = logging.InfoLevel
+		case strings.HasPrefix(filtered, "info: "):
+			filtered = strings.TrimPrefix(filtered, "info: ")
+			level = logging.InfoLevel
+		case strings.HasPrefix(filtered, "warn: "):
+			filtered = strings.TrimPrefix(filtered, "warn: ")
+			level = logging.WarnLevel
+		case strings.HasPrefix(filtered, "error: "):
+			filtered = strings.TrimPrefix(filtered, "error: ")
+			level = logging.ErrorLevel
+		default:
+			level = logging.ErrorLevel
+		}
+		filtered = fmt.Sprintf("unbound: %s", filtered)
+		filtered = constants.ColorUnbound().Sprintf(filtered)
+		return filtered, level
+	case strings.HasPrefix(s, "shadowsocks: "):
+		prefix := regularExpressions.shadowsocksPrefix.FindString(s)
+		filtered = s[len(prefix):]
+		switch {
+		case strings.HasPrefix(filtered, "INFO: "):
+			level = logging.InfoLevel
+			filtered = strings.TrimPrefix(filtered, "INFO: ")
+		default:
+			level = logging.WarnLevel
+		}
+		filtered = fmt.Sprintf("shadowsocks: %s", filtered)
+		filtered = constants.ColorShadowsocks().Sprintf(filtered)
+		return filtered, level
+	case strings.HasPrefix(s, "shadowsocks error: "):
+		if strings.Contains(s, "ERROR: unable to resolve") { // caused by DNS blocking
+			return "", logging.ErrorLevel
+		}
+		prefix := regularExpressions.shadowsocksErrorPrefix.FindString(s)
+		filtered = s[len(prefix):]
+		filtered = strings.TrimPrefix(filtered, "ERROR: ")
+		filtered = fmt.Sprintf("shadowsocks: %s", filtered)
+		filtered = constants.ColorShadowsocksError().Sprintf(filtered)
+		return filtered, logging.ErrorLevel
+	case strings.HasPrefix(s, "tinyproxy: "):
+		logLevel := regularExpressions.tinyproxyLoglevel.FindString(s)
+		prefix := regularExpressions.tinyproxyPrefix.FindString(s)
+		filtered = fmt.Sprintf("tinyproxy: %s", s[len(prefix):])
+		filtered = constants.ColorTinyproxy().Sprintf(filtered)
+		switch logLevel {
+		case "INFO", "CONNECT", "NOTICE":
+			return filtered, logging.InfoLevel
+		case "WARNING":
+			return filtered, logging.WarnLevel
+		case "ERROR", "CRITICAL":
+			return filtered, logging.ErrorLevel
+		default:
+			return filtered, logging.ErrorLevel
+		}
+	}
+	return s, logging.InfoLevel
+}

internal/logging/line_test.go

@@ -0,0 +1,93 @@
+package logging
+
+import (
+	"testing"
+
+	"github.com/qdm12/golibs/logging"
+	"github.com/stretchr/testify/assert"
+)
+
+func Test_PostProcessLine(t *testing.T) {
+	t.Parallel()
+	tests := map[string]struct {
+		s        string
+		filtered string
+		level    logging.Level
+	}{
+		"empty string":  {"", "", logging.InfoLevel},
+		"random string": {"asdasqdb", "asdasqdb", logging.InfoLevel},
+		"unbound notice": {
+			"unbound: [1594595249] unbound[75:0] notice: init module 0: validator",
+			"unbound: init module 0: validator",
+			logging.InfoLevel},
+		"unbound info": {
+			"unbound: [1594595249] unbound[75:0] info: init module 0: validator",
+			"unbound: init module 0: validator",
+			logging.InfoLevel},
+		"unbound warn": {
+			"unbound: [1594595249] unbound[75:0] warn: init module 0: validator",
+			"unbound: init module 0: validator",
+			logging.WarnLevel},
+		"unbound error": {
+			"unbound: [1594595249] unbound[75:0] error: init module 0: validator",
+			"unbound: init module 0: validator",
+			logging.ErrorLevel},
+		"unbound unknown": {
+			"unbound: [1594595249] unbound[75:0] BLA: init module 0: validator",
+			"unbound: BLA: init module 0: validator",
+			logging.ErrorLevel},
+		"shadowsocks stdout info": {
+			"shadowsocks:  2020-07-12 23:07:25 INFO: UDP relay enabled",
+			"shadowsocks: UDP relay enabled",
+			logging.InfoLevel},
+		"shadowsocks stdout other": {
+			"shadowsocks:  2020-07-12 23:07:25 BLABLA: UDP relay enabled",
+			"shadowsocks: BLABLA: UDP relay enabled",
+			logging.WarnLevel},
+		"shadowsocks stderr": {
+			"shadowsocks error:  2020-07-12 23:07:25 Some error",
+			"shadowsocks: Some error",
+			logging.ErrorLevel},
+		"shadowsocks stderr unable to resolve muted": {
+			"shadowsocks error:  2020-07-12 23:07:25 ERROR: unable to resolve",
+			"",
+			logging.ErrorLevel},
+		"tinyproxy info": {
+			"tinyproxy: INFO      Jul 12 23:07:25 [32]: Reloading config file",
+			"tinyproxy: Reloading config file",
+			logging.InfoLevel},
+		"tinyproxy connect": {
+			"tinyproxy: CONNECT      Jul 12 23:07:25 [32]: Reloading config file",
+			"tinyproxy: Reloading config file",
+			logging.InfoLevel},
+		"tinyproxy notice": {
+			"tinyproxy: NOTICE      Jul 12 23:07:25 [32]: Reloading config file",
+			"tinyproxy: Reloading config file",
+			logging.InfoLevel},
+		"tinyproxy warning": {
+			"tinyproxy: WARNING      Jul 12 23:07:25 [32]: Reloading config file",
+			"tinyproxy: Reloading config file",
+			logging.WarnLevel},
+		"tinyproxy error": {
+			"tinyproxy: ERROR      Jul 12 23:07:25 [32]: Reloading config file",
+			"tinyproxy: Reloading config file",
+			logging.ErrorLevel},
+		"tinyproxy critical": {
+			"tinyproxy: CRITICAL      Jul 12 23:07:25 [32]: Reloading config file",
+			"tinyproxy: Reloading config file",
+			logging.ErrorLevel},
+		"tinyproxy unknown": {
+			"tinyproxy: BLABLA      Jul 12 23:07:25 [32]: Reloading config file",
+			"tinyproxy: Reloading config file",
+			logging.ErrorLevel},
+	}
+	for name, tc := range tests {
+		tc := tc
+		t.Run(name, func(t *testing.T) {
+			t.Parallel()
+			filtered, level := PostProcessLine(tc.s)
+			assert.Equal(t, tc.filtered, filtered)
+			assert.Equal(t, tc.level, level)
+		})
+	}
+}

internal/logging/splash.go

@@ -1,4 +1,4 @@
-package splash
+package logging
 
 import (
 	"fmt"

internal/openvpn/loop.go

@@ -10,7 +10,6 @@ import (
 	"github.com/qdm12/golibs/files"
 	"github.com/qdm12/golibs/logging"
 	"github.com/qdm12/golibs/network"
-	"github.com/qdm12/private-internet-access-docker/internal/constants"
 	"github.com/qdm12/private-internet-access-docker/internal/firewall"
 	"github.com/qdm12/private-internet-access-docker/internal/models"
 	"github.com/qdm12/private-internet-access-docker/internal/provider"
@@ -112,8 +111,7 @@ func (l *looper) Run(ctx context.Context, restart, portForward <-chan struct{},
 			}
 		}(openvpnCtx)
 
-		go l.streamMerger.Merge(openvpnCtx, stream,
+		go l.streamMerger.Merge(openvpnCtx, stream, command.MergeName("openvpn"))
-			command.MergeName("openvpn"), command.MergeColor(constants.ColorOpenvpn()))
 		waitError := make(chan error)
 		go func() {
 			err := waitFn() // blocking

internal/shadowsocks/loop.go

@@ -7,7 +7,6 @@ import (
 
 	"github.com/qdm12/golibs/command"
 	"github.com/qdm12/golibs/logging"
-	"github.com/qdm12/private-internet-access-docker/internal/constants"
 	"github.com/qdm12/private-internet-access-docker/internal/firewall"
 	"github.com/qdm12/private-internet-access-docker/internal/settings"
 )
@@ -96,10 +95,8 @@ func (l *looper) Run(ctx context.Context, restart <-chan struct{}, wg *sync.Wait
 			l.logAndWait(ctx, err)
 			continue
 		}
-		go l.streamMerger.Merge(shadowsocksCtx, stdout,
+		go l.streamMerger.Merge(shadowsocksCtx, stdout, command.MergeName("shadowsocks"))
-			command.MergeName("shadowsocks"), command.MergeColor(constants.ColorShadowsocks()))
+		go l.streamMerger.Merge(shadowsocksCtx, stderr, command.MergeName("shadowsocks error"))
-		go l.streamMerger.Merge(shadowsocksCtx, stderr,
-			command.MergeName("shadowsocks error"), command.MergeColor(constants.ColorShadowsocksError()))
 		waitError := make(chan error)
 		go func() {
 			err := waitFn() // blocking

internal/tinyproxy/loop.go

@@ -7,7 +7,6 @@ import (
 
 	"github.com/qdm12/golibs/command"
 	"github.com/qdm12/golibs/logging"
-	"github.com/qdm12/private-internet-access-docker/internal/constants"
 	"github.com/qdm12/private-internet-access-docker/internal/firewall"
 	"github.com/qdm12/private-internet-access-docker/internal/settings"
 )
@@ -90,8 +89,7 @@ func (l *looper) Run(ctx context.Context, restart <-chan struct{}, wg *sync.Wait
 			l.logAndWait(ctx, err)
 			continue
 		}
-		go l.streamMerger.Merge(tinyproxyCtx, stream,
+		go l.streamMerger.Merge(tinyproxyCtx, stream, command.MergeName("tinyproxy"))
-			command.MergeName("tinyproxy"), command.MergeColor(constants.ColorTinyproxy()))
 		waitError := make(chan error)
 		go func() {
 			err := waitFn() // blocking