diff --git a/cmd/gluetun/main.go b/cmd/gluetun/main.go index 6d5f2a57..df1402a4 100644 --- a/cmd/gluetun/main.go +++ b/cmd/gluetun/main.go @@ -7,7 +7,6 @@ import ( "net/http" nativeos "os" "os/signal" - "strings" "sync" "syscall" "time" @@ -33,7 +32,6 @@ import ( "github.com/qdm12/gluetun/internal/unix" "github.com/qdm12/gluetun/internal/updater" versionpkg "github.com/qdm12/gluetun/internal/version" - "github.com/qdm12/golibs/command" "github.com/qdm12/golibs/logging" "github.com/qdm12/golibs/os" "github.com/qdm12/golibs/os/user" @@ -141,7 +139,6 @@ func _main(background context.Context, buildInfo models.BuildInformation, "/etc/unbound", "/usr/sbin/unbound", cacertsPath) routingConf := routing.NewRouting(logger) firewallConf := firewall.NewConfigurator(logger, routingConf, os.OpenFile) - streamMerger := command.NewStreamMerger() paramsReader := params.NewReader(logger, os) fmt.Println(gluetunLogging.Splash(buildInfo)) @@ -266,11 +263,8 @@ func _main(background context.Context, buildInfo models.BuildInformation, wg := &sync.WaitGroup{} - wg.Add(1) - go collectStreamLines(ctx, wg, streamMerger, logger, tunnelReadyCh) - openvpnLooper := openvpn.NewLooper(allSettings.OpenVPN, nonRootUsername, puid, pgid, allServers, - ovpnConf, firewallConf, routingConf, logger, httpClient, os.OpenFile, streamMerger, cancel) + ovpnConf, firewallConf, routingConf, logger, httpClient, os.OpenFile, tunnelReadyCh, cancel) wg.Add(1) // wait for restartOpenvpn go openvpnLooper.Run(ctx, wg) @@ -282,7 +276,7 @@ func _main(background context.Context, buildInfo models.BuildInformation, go updaterLooper.Run(ctx, wg) unboundLooper := dns.NewLooper(dnsConf, allSettings.DNS, httpClient, - logger, streamMerger, nonRootUsername, puid, pgid) + logger, nonRootUsername, puid, pgid) wg.Add(1) // wait for unboundLooper.Restart or its ticker launched with RunRestartTicker go unboundLooper.Run(ctx, wg, dnsReadyCh) @@ -352,42 +346,6 @@ func printVersions(ctx context.Context, logger logging.Logger, } } -func collectStreamLines(ctx context.Context, wg *sync.WaitGroup, - streamMerger command.StreamMerger, - logger logging.Logger, tunnelReadyCh chan<- struct{}) { - defer wg.Done() - // Blocking line merging paramsReader for openvpn and unbound - logger.Info("Launching standard output merger") - streamMerger.CollectLines(ctx, func(line string) { - line, level := gluetunLogging.PostProcessLine(line) - if line == "" { - return - } - switch level { - case logging.DebugLevel: - logger.Debug(line) - case logging.InfoLevel: - logger.Info(line) - case logging.WarnLevel: - logger.Warn(line) - case logging.ErrorLevel: - logger.Error(line) - } - switch { - case strings.Contains(line, "Initialization Sequence Completed"): - tunnelReadyCh <- struct{}{} - case strings.Contains(line, "TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)"): //nolint:lll - logger.Warn("This means that either...") - logger.Warn("1. The VPN server IP address you are trying to connect to is no longer valid, see https://github.com/qdm12/gluetun/wiki/Update-servers-information") //nolint:lll - logger.Warn("2. The VPN server crashed, try changing region") - logger.Warn("3. Your Internet connection is not working, ensure it works") - logger.Warn("Feel free to create an issue at https://github.com/qdm12/gluetun/issues/new/choose") - } - }, func(err error) { - logger.Warn(err) - }) -} - func routeReadyEvents(ctx context.Context, wg *sync.WaitGroup, buildInfo models.BuildInformation, tunnelReadyCh, dnsReadyCh <-chan struct{}, unboundLooper dns.Looper, updaterLooper updater.Looper, publicIPLooper publicip.Looper, diff --git a/go.mod b/go.mod index af7dc52c..76111230 100644 --- a/go.mod +++ b/go.mod @@ -6,8 +6,8 @@ require ( github.com/fatih/color v1.10.0 github.com/golang/mock v1.4.4 github.com/kyokomi/emoji v2.2.4+incompatible - github.com/qdm12/dns v1.4.0-rc4 - github.com/qdm12/golibs v0.0.0-20210110211000-0a3a4541ae09 + github.com/qdm12/dns v1.4.0-rc5 + github.com/qdm12/golibs v0.0.0-20210124192933-79a950eaf217 github.com/qdm12/ss-server v0.1.0 github.com/qdm12/updated v0.0.0-20210102005021-dd457d77f94a github.com/stretchr/testify v1.7.0 diff --git a/go.sum b/go.sum index 8affedfa..1b78859a 100644 --- a/go.sum +++ b/go.sum @@ -92,13 +92,11 @@ github.com/pkg/errors v0.8.1 h1:iURUrRGxPUNPdy5/HRSm+Yj6okJ6UtLINN0Q9M4+h3I= github.com/pkg/errors v0.8.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= -github.com/qdm12/dns v1.4.0-rc4 h1:pCcFMqismbktPQX7yrtdmJZq30Y05JBfWRTXY1ZLVFw= -github.com/qdm12/dns v1.4.0-rc4/go.mod h1:JhUKBhuDRYBUQ2XwW/jbeWx/qS0sSJjIFjGTCFGP5I8= +github.com/qdm12/dns v1.4.0-rc5 h1:XXjYaFI3pDY1U4YFH5t5AI5IEKlIALmnE34VFhgkdQE= +github.com/qdm12/dns v1.4.0-rc5/go.mod h1:WUY4/U8Z2O8888DPrahrIBv8GdYeoIcEy4aUDecZ+UM= github.com/qdm12/golibs v0.0.0-20201227203847-2fd99ffdfdba/go.mod h1:pikkTN7g7zRuuAnERwqW1yAFq6pYmxrxpjiwGvb0Ysc= -github.com/qdm12/golibs v0.0.0-20210102020307-17bc97def973 h1:5YeJALmDjvg2wSi6XB8MpQQekbT/eBnwGahJrh01HHQ= -github.com/qdm12/golibs v0.0.0-20210102020307-17bc97def973/go.mod h1:pikkTN7g7zRuuAnERwqW1yAFq6pYmxrxpjiwGvb0Ysc= -github.com/qdm12/golibs v0.0.0-20210110211000-0a3a4541ae09 h1:zP+ZRwV3GldgTWFgKNBQ2zoFA8mIczb+fvTvrX8LZRo= -github.com/qdm12/golibs v0.0.0-20210110211000-0a3a4541ae09/go.mod h1:pikkTN7g7zRuuAnERwqW1yAFq6pYmxrxpjiwGvb0Ysc= +github.com/qdm12/golibs v0.0.0-20210124192933-79a950eaf217 h1:/eMBq0vbc/KmVPXbwLfssp547pp6APRS1x/JNmPvm0s= +github.com/qdm12/golibs v0.0.0-20210124192933-79a950eaf217/go.mod h1:pikkTN7g7zRuuAnERwqW1yAFq6pYmxrxpjiwGvb0Ysc= github.com/qdm12/ss-server v0.1.0 h1:WV9MkHCDEWRwe4WpnYFeR/zcZAxYoTbfntLDnw9AQ50= github.com/qdm12/ss-server v0.1.0/go.mod h1:ABVUkxubboL3vqBkOwDV9glX1/x7SnYrckBe5d+M/zw= github.com/qdm12/updated v0.0.0-20210102005021-dd457d77f94a h1:gkyP+gMEeBgMgyRYGrVNcoy6cL1065IvXsyfB6xboIc= diff --git a/internal/dns/logs.go b/internal/dns/logs.go new file mode 100644 index 00000000..2b6e1037 --- /dev/null +++ b/internal/dns/logs.go @@ -0,0 +1,61 @@ +package dns + +import ( + "regexp" + "strings" + "sync" + + "github.com/qdm12/gluetun/internal/constants" + "github.com/qdm12/golibs/logging" +) + +func (l *looper) collectLines(wg *sync.WaitGroup, stdout, stderr <-chan string) { + defer wg.Done() + var line string + var ok bool + for { + select { + case line, ok = <-stderr: + case line, ok = <-stdout: + } + if !ok { + return + } + line, level := processLogLine(line) + switch level { + case logging.DebugLevel: + l.logger.Debug(line) + case logging.InfoLevel: + l.logger.Info(line) + case logging.WarnLevel: + l.logger.Warn(line) + case logging.ErrorLevel: + l.logger.Error(line) + } + } +} + +var unboundPrefix = regexp.MustCompile(`\[[0-9]{10}\] unbound\[[0-9]+:[0|1]\] `) + +func processLogLine(s string) (filtered string, level logging.Level) { + prefix := 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.InfoLevel + } + filtered = constants.ColorUnbound().Sprintf(filtered) + return filtered, level +} diff --git a/internal/dns/logs_test.go b/internal/dns/logs_test.go new file mode 100644 index 00000000..c47efdf4 --- /dev/null +++ b/internal/dns/logs_test.go @@ -0,0 +1,49 @@ +package dns + +import ( + "testing" + + "github.com/qdm12/golibs/logging" + "github.com/stretchr/testify/assert" +) + +func Test_processLogLine(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": { + "[1594595249] unbound[75:0] notice: init module 0: validator", + "init module 0: validator", + logging.InfoLevel}, + "unbound info": { + "[1594595249] unbound[75:0] info: init module 0: validator", + "init module 0: validator", + logging.InfoLevel}, + "unbound warn": { + "[1594595249] unbound[75:0] warn: init module 0: validator", + "init module 0: validator", + logging.WarnLevel}, + "unbound error": { + "[1594595249] unbound[75:0] error: init module 0: validator", + "init module 0: validator", + logging.ErrorLevel}, + "unbound unknown": { + "[1594595249] unbound[75:0] BLA: init module 0: validator", + "BLA: init module 0: validator", + logging.InfoLevel}, + } + for name, tc := range tests { + tc := tc + t.Run(name, func(t *testing.T) { + t.Parallel() + filtered, level := processLogLine(tc.s) + assert.Equal(t, tc.filtered, filtered) + assert.Equal(t, tc.level, level) + }) + } +} diff --git a/internal/dns/loop.go b/internal/dns/loop.go index 17282fdf..a48e245a 100644 --- a/internal/dns/loop.go +++ b/internal/dns/loop.go @@ -12,7 +12,6 @@ import ( "github.com/qdm12/gluetun/internal/constants" "github.com/qdm12/gluetun/internal/models" "github.com/qdm12/gluetun/internal/settings" - "github.com/qdm12/golibs/command" "github.com/qdm12/golibs/logging" ) @@ -30,7 +29,6 @@ type looper struct { conf unbound.Configurator client *http.Client logger logging.Logger - streamMerger command.StreamMerger username string puid int pgid int @@ -48,8 +46,7 @@ type looper struct { const defaultBackoffTime = 10 * time.Second func NewLooper(conf unbound.Configurator, settings settings.DNS, client *http.Client, - logger logging.Logger, streamMerger command.StreamMerger, - username string, puid, pgid int) Looper { + logger logging.Logger, username string, puid, pgid int) Looper { return &looper{ state: state{ status: constants.Stopped, @@ -61,7 +58,6 @@ func NewLooper(conf unbound.Configurator, settings settings.DNS, client *http.Cl username: username, puid: puid, pgid: pgid, - streamMerger: streamMerger, start: make(chan struct{}), running: make(chan models.LoopStatus), stop: make(chan struct{}), @@ -107,8 +103,10 @@ func (l *looper) Run(ctx context.Context, wg *sync.WaitGroup, dnsReadyCh chan<- for ctx.Err() == nil { // Upper scope variables for Unbound only - var unboundCancel context.CancelFunc = func() {} - waitError := make(chan error) + // Their values are to be used if DOT=off + var waitError chan error + var unboundCancel context.CancelFunc + var closeStreams func() for l.GetSettings().Enabled { if ctx.Err() != nil { @@ -116,7 +114,7 @@ func (l *looper) Run(ctx context.Context, wg *sync.WaitGroup, dnsReadyCh chan<- return } var err error - unboundCancel, err = l.setupUnbound(ctx, crashed, waitError) + unboundCancel, waitError, closeStreams, err = l.setupUnbound(ctx, wg, crashed) if err != nil { if !errors.Is(err, errUpdateFiles) { const fallback = true @@ -130,6 +128,9 @@ func (l *looper) Run(ctx context.Context, wg *sync.WaitGroup, dnsReadyCh chan<- if !l.GetSettings().Enabled { const fallback = false l.useUnencryptedDNS(fallback) + waitError := make(chan error) + unboundCancel = func() { waitError <- nil } + closeStreams = func() {} } dnsReadyCh <- struct{}{} @@ -142,6 +143,7 @@ func (l *looper) Run(ctx context.Context, wg *sync.WaitGroup, dnsReadyCh chan<- unboundCancel() <-waitError close(waitError) + closeStreams() return case <-l.stop: l.logger.Info("stopping") @@ -163,7 +165,7 @@ func (l *looper) Run(ctx context.Context, wg *sync.WaitGroup, dnsReadyCh chan<- } } close(waitError) - unboundCancel() + closeStreams() } } @@ -172,28 +174,29 @@ var errUpdateFiles = errors.New("cannot update files") // Returning cancel == nil signals we want to re-run setupUnbound // Returning err == errUpdateFiles signals we should not fall back // on the plaintext DNS as DOT is still up and running. -func (l *looper) setupUnbound(ctx context.Context, - previousCrashed bool, waitError chan<- error) (cancel context.CancelFunc, err error) { +func (l *looper) setupUnbound(ctx context.Context, wg *sync.WaitGroup, + previousCrashed bool) (cancel context.CancelFunc, waitError chan error, + closeStreams func(), err error) { err = l.updateFiles(ctx) if err != nil { l.state.setStatusWithLock(constants.Crashed) - return nil, errUpdateFiles + return nil, nil, nil, errUpdateFiles } settings := l.GetSettings() unboundCtx, cancel := context.WithCancel(context.Background()) - stream, waitFn, err := l.conf.Start(unboundCtx, settings.Unbound.VerbosityDetailsLevel) + stdoutLines, stderrLines, waitError, err := l.conf.Start(unboundCtx, settings.Unbound.VerbosityDetailsLevel) if err != nil { cancel() if !previousCrashed { l.running <- constants.Crashed } - return nil, err + return nil, nil, nil, err } - // Started successfully - go l.streamMerger.Merge(unboundCtx, stream, command.MergeName("unbound")) + wg.Add(1) + go l.collectLines(wg, stdoutLines, stderrLines) l.conf.UseDNSInternally(net.IP{127, 0, 0, 1}) // use Unbound if err := l.conf.UseDNSSystemWide(net.IP{127, 0, 0, 1}, settings.KeepNameserver); err != nil { // use Unbound @@ -205,14 +208,13 @@ func (l *looper) setupUnbound(ctx context.Context, l.running <- constants.Crashed } cancel() - return nil, err + <-waitError + close(waitError) + close(stdoutLines) + close(stderrLines) + return nil, nil, nil, err } - go func() { - err := waitFn() // blocking - waitError <- err - }() - l.logger.Info("ready") if !previousCrashed { l.running <- constants.Running @@ -220,7 +222,13 @@ func (l *looper) setupUnbound(ctx context.Context, l.backoffTime = defaultBackoffTime l.state.setStatusWithLock(constants.Running) } - return cancel, nil + + closeStreams = func() { + close(stdoutLines) + close(stderrLines) + } + + return cancel, waitError, closeStreams, nil } func (l *looper) useUnencryptedDNS(fallback bool) { diff --git a/internal/logging/line.go b/internal/logging/line.go deleted file mode 100644 index 4a7e9b84..00000000 --- a/internal/logging/line.go +++ /dev/null @@ -1,78 +0,0 @@ -package logging - -import ( - "fmt" - "regexp" - "strings" - - "github.com/fatih/color" - "github.com/qdm12/gluetun/internal/constants" - "github.com/qdm12/golibs/logging" -) - -var regularExpressions = struct { //nolint:gochecknoglobals - unboundPrefix *regexp.Regexp -}{ - unboundPrefix: regexp.MustCompile(`unbound: \[[0-9]{10}\] unbound\[[0-9]+:[0|1]\] `), -} - -func PostProcessLine(s string) (filtered string, level logging.Level) { - switch { - case strings.HasPrefix(s, "openvpn: "): - for _, ignored := range []string{ - "openvpn: WARNING: you are using user/group/chroot/setcon without persist-tun -- this may cause restarts to fail", - "openvpn: NOTE: UID/GID downgrade will be delayed because of --client, --pull, or --up-delay", - } { - if s == ignored { - return "", "" - } - } - switch { - case strings.HasPrefix(s, "openvpn: NOTE: "): - filtered = strings.TrimPrefix(s, "openvpn: NOTE: ") - filtered = "openvpn: " + filtered - level = logging.InfoLevel - case strings.HasPrefix(s, "openvpn: WARNING: "): - filtered = strings.TrimPrefix(s, "openvpn: WARNING: ") - filtered = "openvpn: " + filtered - level = logging.WarnLevel - case strings.HasPrefix(s, "openvpn: Options error: "): - filtered = strings.TrimPrefix(s, "openvpn: Options error: ") - filtered = "openvpn: " + filtered - level = logging.ErrorLevel - case s == "openvpn: Initialization Sequence Completed": - return color.HiGreenString(s), logging.InfoLevel - case s == "openvpn: AUTH: Received control message: AUTH_FAILED": - filtered = s + "\n\n (IF YOU ARE USING PIA servers, MAYBE CHECK OUT https://github.com/qdm12/gluetun/issues/265)\n" //nolint:lll - level = logging.ErrorLevel - default: - filtered = s - level = logging.InfoLevel - } - filtered = constants.ColorOpenvpn().Sprintf(filtered) - return filtered, level - 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 - } - return s, logging.InfoLevel -} diff --git a/internal/logging/line_test.go b/internal/logging/line_test.go deleted file mode 100644 index 4f697e67..00000000 --- a/internal/logging/line_test.go +++ /dev/null @@ -1,77 +0,0 @@ -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}, - "openvpn unknown": { - "openvpn: message", - "openvpn: message", - logging.InfoLevel}, - "openvpn note": { - "openvpn: NOTE: message", - "openvpn: message", - logging.InfoLevel}, - "openvpn warning": { - "openvpn: WARNING: message", - "openvpn: message", - logging.WarnLevel}, - "openvpn options error": { - "openvpn: Options error: message", - "openvpn: message", - logging.ErrorLevel}, - "openvpn ignored message": { - "openvpn: NOTE: UID/GID downgrade will be delayed because of --client, --pull, or --up-delay", - "", - ""}, - "openvpn success": { - "openvpn: Initialization Sequence Completed", - "openvpn: Initialization Sequence Completed", - logging.InfoLevel}, - "openvpn auth failed": { - "openvpn: AUTH: Received control message: AUTH_FAILED", - "openvpn: AUTH: Received control message: AUTH_FAILED\n\n (IF YOU ARE USING PIA servers, MAYBE CHECK OUT https://github.com/qdm12/gluetun/issues/265)\n", //nolint:lll - 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/openvpn/command.go b/internal/openvpn/command.go index 13b805ce..0e9a35a5 100644 --- a/internal/openvpn/command.go +++ b/internal/openvpn/command.go @@ -3,16 +3,14 @@ package openvpn import ( "context" "fmt" - "io" "strings" "github.com/qdm12/gluetun/internal/constants" ) -func (c *configurator) Start(ctx context.Context) (stdout io.ReadCloser, waitFn func() error, err error) { +func (c *configurator) Start(ctx context.Context) (stdoutLines, stderrLines chan string, waitError chan error, err error) { c.logger.Info("starting openvpn") - stdout, _, waitFn, err = c.commander.Start(ctx, "openvpn", "--config", string(constants.OpenVPNConf)) - return stdout, waitFn, err + return c.commander.Start(ctx, "openvpn", "--config", string(constants.OpenVPNConf)) } func (c *configurator) Version(ctx context.Context) (string, error) { diff --git a/internal/openvpn/logs.go b/internal/openvpn/logs.go new file mode 100644 index 00000000..31ac73f5 --- /dev/null +++ b/internal/openvpn/logs.go @@ -0,0 +1,100 @@ +package openvpn + +import ( + "strings" + "sync" + + "github.com/fatih/color" + "github.com/qdm12/gluetun/internal/constants" + "github.com/qdm12/golibs/logging" +) + +func (l *looper) collectLines(wg *sync.WaitGroup, stdout, stderr <-chan string) { + defer wg.Done() + var line string + var ok, errLine bool + + for { + errLine = false + select { + case line, ok = <-stdout: + case line, ok = <-stderr: + errLine = true + } + if !ok { + return + } + line, level := processLogLine(line) + if len(line) == 0 { + continue // filtered out + } + if errLine { + level = logging.ErrorLevel + } + switch level { + case logging.DebugLevel: + l.logger.Debug(line) + case logging.InfoLevel: + l.logger.Info(line) + case logging.WarnLevel: + l.logger.Warn(line) + case logging.ErrorLevel: + l.logger.Error(line) + } + if strings.Contains(line, "Initialization Sequence Completed") { + l.tunnelReady <- struct{}{} + } + } +} + +func processLogLine(s string) (filtered string, level logging.Level) { + for _, ignored := range []string{ + "WARNING: you are using user/group/chroot/setcon without persist-tun -- this may cause restarts to fail", + "NOTE: UID/GID downgrade will be delayed because of --client, --pull, or --up-delay", + } { + if s == ignored { + return "", "" + } + } + switch { + case strings.HasPrefix(s, "NOTE: "): + filtered = strings.TrimPrefix(s, "NOTE: ") + level = logging.InfoLevel + case strings.HasPrefix(s, "WARNING: "): + filtered = strings.TrimPrefix(s, "WARNING: ") + level = logging.WarnLevel + case strings.HasPrefix(s, "Options error: "): + filtered = strings.TrimPrefix(s, "Options error: ") + level = logging.ErrorLevel + case s == "Initialization Sequence Completed": + return color.HiGreenString(s), logging.InfoLevel + case s == "AUTH: Received control message: AUTH_FAILED": + filtered = s + ` + +Your credentials might be wrong ๐Ÿคจ + +๐Ÿ’ก If you use Private Internet Access, check https://github.com/qdm12/gluetun/issues/265 + +` + level = logging.ErrorLevel + case strings.Contains(s, "TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)"): + s += ` +๐Ÿš’๐Ÿš’๐Ÿš’๐Ÿš’๐Ÿš’๐Ÿšจ๐Ÿšจ๐Ÿšจ๐Ÿšจ๐Ÿšจ๐Ÿšจ๐Ÿš’๐Ÿš’๐Ÿš’๐Ÿš’๐Ÿš’ +That error usually happens because either: + +1. The VPN server IP address you are trying to connect to is no longer valid ๐Ÿ”Œ + Update your server information using https://github.com/qdm12/gluetun/wiki/Updating-Servers + +2. The VPN server crashed ๐Ÿ’ฅ, try changing your VPN servers filtering options such as REGION + +3. Your Internet connection is not working ๐Ÿคฏ, ensure it works + +4. Something else โžก๏ธ https://github.com/qdm12/gluetun/issues/new/choose +` + default: + filtered = s + level = logging.InfoLevel + } + filtered = constants.ColorOpenvpn().Sprintf(filtered) + return filtered, level +} diff --git a/internal/openvpn/logs_test.go b/internal/openvpn/logs_test.go new file mode 100644 index 00000000..be8236a1 --- /dev/null +++ b/internal/openvpn/logs_test.go @@ -0,0 +1,57 @@ +package openvpn + +import ( + "testing" + + "github.com/qdm12/golibs/logging" + "github.com/stretchr/testify/assert" +) + +func Test_processLogLine(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}, + "openvpn unknown": { + "message", + "message", + logging.InfoLevel}, + "openvpn note": { + "NOTE: message", + "message", + logging.InfoLevel}, + "openvpn warning": { + "WARNING: message", + "message", + logging.WarnLevel}, + "openvpn options error": { + "Options error: message", + "message", + logging.ErrorLevel}, + "openvpn ignored message": { + "NOTE: UID/GID downgrade will be delayed because of --client, --pull, or --up-delay", + "", + ""}, + "openvpn success": { + "Initialization Sequence Completed", + "Initialization Sequence Completed", + logging.InfoLevel}, + "openvpn auth failed": { + "AUTH: Received control message: AUTH_FAILED", + "AUTH: Received control message: AUTH_FAILED\n\nYour credentials might be wrong ๐Ÿคจ\n\n๐Ÿ’ก If you use Private Internet Access, check https://github.com/qdm12/gluetun/issues/265\n\n", //nolint:lll + logging.ErrorLevel}, + } + for name, tc := range tests { + tc := tc + t.Run(name, func(t *testing.T) { + t.Parallel() + filtered, level := processLogLine(tc.s) + assert.Equal(t, tc.filtered, filtered) + assert.Equal(t, tc.level, level) + }) + } +} diff --git a/internal/openvpn/loop.go b/internal/openvpn/loop.go index a5f218d0..ff64b8c2 100644 --- a/internal/openvpn/loop.go +++ b/internal/openvpn/loop.go @@ -14,7 +14,6 @@ import ( "github.com/qdm12/gluetun/internal/provider" "github.com/qdm12/gluetun/internal/routing" "github.com/qdm12/gluetun/internal/settings" - "github.com/qdm12/golibs/command" "github.com/qdm12/golibs/logging" "github.com/qdm12/golibs/os" ) @@ -45,7 +44,7 @@ type looper struct { logger, pfLogger logging.Logger client *http.Client openFile os.OpenFileFunc - streamMerger command.StreamMerger + tunnelReady chan<- struct{} cancel context.CancelFunc // Internal channels and locks loopLock sync.Mutex @@ -63,7 +62,7 @@ func NewLooper(settings settings.OpenVPN, username string, puid, pgid int, allServers models.AllServers, conf Configurator, fw firewall.Configurator, routing routing.Routing, logger logging.Logger, client *http.Client, openFile os.OpenFileFunc, - streamMerger command.StreamMerger, cancel context.CancelFunc) Looper { + tunnelReady chan<- struct{}, cancel context.CancelFunc) Looper { return &looper{ state: state{ status: constants.Stopped, @@ -80,7 +79,7 @@ func NewLooper(settings settings.OpenVPN, pfLogger: logger.WithPrefix("port forwarding: "), client: client, openFile: openFile, - streamMerger: streamMerger, + tunnelReady: tunnelReady, cancel: cancel, start: make(chan struct{}), running: make(chan models.LoopStatus), @@ -144,7 +143,7 @@ func (l *looper) Run(ctx context.Context, wg *sync.WaitGroup) { openvpnCtx, openvpnCancel := context.WithCancel(context.Background()) - stream, waitFn, err := l.conf.Start(openvpnCtx) + stdoutLines, stderrLines, waitError, err := l.conf.Start(openvpnCtx) if err != nil { openvpnCancel() l.signalCrashedStatus() @@ -152,6 +151,9 @@ func (l *looper) Run(ctx context.Context, wg *sync.WaitGroup) { continue } + wg.Add(1) + go l.collectLines(wg, stdoutLines, stderrLines) + // Needs the stream line from main.go to know when the tunnel is up go func(ctx context.Context) { for { @@ -166,13 +168,6 @@ func (l *looper) Run(ctx context.Context, wg *sync.WaitGroup) { } }(openvpnCtx) - go l.streamMerger.Merge(openvpnCtx, stream, command.MergeName("openvpn")) - waitError := make(chan error) - go func() { - err := waitFn() // blocking - waitError <- err - }() - if l.crashed { l.crashed = false l.backoffTime = defaultBackoffTime @@ -189,6 +184,8 @@ func (l *looper) Run(ctx context.Context, wg *sync.WaitGroup) { openvpnCancel() <-waitError close(waitError) + close(stdoutLines) + close(stderrLines) return case <-l.stop: l.logger.Info("stopping") @@ -207,6 +204,8 @@ func (l *looper) Run(ctx context.Context, wg *sync.WaitGroup) { } } close(waitError) + close(stdoutLines) + close(stderrLines) openvpnCancel() // just for the linter } } diff --git a/internal/openvpn/openvpn.go b/internal/openvpn/openvpn.go index 62f796a4..6148bb6c 100644 --- a/internal/openvpn/openvpn.go +++ b/internal/openvpn/openvpn.go @@ -2,7 +2,6 @@ package openvpn import ( "context" - "io" "github.com/qdm12/gluetun/internal/unix" "github.com/qdm12/golibs/command" @@ -15,7 +14,8 @@ type Configurator interface { WriteAuthFile(user, password string, puid, pgid int) error CheckTUN() error CreateTUN() error - Start(ctx context.Context) (stdout io.ReadCloser, waitFn func() error, err error) + Start(ctx context.Context) (stdoutLines, stderrLines chan string, + waitError chan error, err error) } type configurator struct {