diff --git a/cmd/gluetun/main.go b/cmd/gluetun/main.go index 8b99f679..887229f4 100644 --- a/cmd/gluetun/main.go +++ b/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) - logger.Info(line) + line, level := gluetunLogging.PostProcessLine(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{}, ) { diff --git a/internal/constants/colors.go b/internal/constants/colors.go index d608e267..5ae633f1 100644 --- a/internal/constants/colors.go +++ b/internal/constants/colors.go @@ -2,22 +2,22 @@ package constants import "github.com/fatih/color" -func ColorUnbound() color.Color { - return *color.New(color.FgCyan) +func ColorUnbound() *color.Color { + return color.New(color.FgCyan) } -func ColorTinyproxy() color.Color { - return *color.New(color.FgHiMagenta) +func ColorTinyproxy() *color.Color { + return color.New(color.FgHiGreen) } -func ColorShadowsocks() color.Color { - return *color.New(color.FgHiYellow) +func ColorShadowsocks() *color.Color { + return color.New(color.FgHiYellow) } -func ColorShadowsocksError() color.Color { - return *color.New(color.FgHiRed) +func ColorShadowsocksError() *color.Color { + return color.New(color.FgHiRed) } -func ColorOpenvpn() color.Color { - return *color.New(color.FgHiMagenta) +func ColorOpenvpn() *color.Color { + return color.New(color.FgHiMagenta) } diff --git a/internal/dns/loop.go b/internal/dns/loop.go index 9b8d3055..6fffad7e 100644 --- a/internal/dns/loop.go +++ b/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, - command.MergeName("unbound"), command.MergeColor(constants.ColorUnbound())) + go l.streamMerger.Merge(unboundCtx, stream, command.MergeName("unbound")) 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) diff --git a/internal/logging/line.go b/internal/logging/line.go new file mode 100644 index 00000000..1827ebca --- /dev/null +++ b/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 +} diff --git a/internal/logging/line_test.go b/internal/logging/line_test.go new file mode 100644 index 00000000..4a42f800 --- /dev/null +++ b/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) + }) + } +} diff --git a/internal/splash/splash.go b/internal/logging/splash.go similarity index 99% rename from internal/splash/splash.go rename to internal/logging/splash.go index 11f9dc5c..29a933bb 100644 --- a/internal/splash/splash.go +++ b/internal/logging/splash.go @@ -1,4 +1,4 @@ -package splash +package logging import ( "fmt" diff --git a/internal/openvpn/loop.go b/internal/openvpn/loop.go index 5e2db08e..daebeb02 100644 --- a/internal/openvpn/loop.go +++ b/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, - command.MergeName("openvpn"), command.MergeColor(constants.ColorOpenvpn())) + go l.streamMerger.Merge(openvpnCtx, stream, command.MergeName("openvpn")) waitError := make(chan error) go func() { err := waitFn() // blocking diff --git a/internal/shadowsocks/loop.go b/internal/shadowsocks/loop.go index b476dd5b..d5dabec6 100644 --- a/internal/shadowsocks/loop.go +++ b/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, - command.MergeName("shadowsocks"), command.MergeColor(constants.ColorShadowsocks())) - go l.streamMerger.Merge(shadowsocksCtx, stderr, - command.MergeName("shadowsocks error"), command.MergeColor(constants.ColorShadowsocksError())) + go l.streamMerger.Merge(shadowsocksCtx, stdout, command.MergeName("shadowsocks")) + go l.streamMerger.Merge(shadowsocksCtx, stderr, command.MergeName("shadowsocks error")) waitError := make(chan error) go func() { err := waitFn() // blocking diff --git a/internal/tinyproxy/loop.go b/internal/tinyproxy/loop.go index 48430121..f01a48fb 100644 --- a/internal/tinyproxy/loop.go +++ b/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, - command.MergeName("tinyproxy"), command.MergeColor(constants.ColorTinyproxy())) + go l.streamMerger.Merge(tinyproxyCtx, stream, command.MergeName("tinyproxy")) waitError := make(chan error) go func() { err := waitFn() // blocking