feat(portforward): log subcommands outputs with "up/down command:" prefix

Co-authored-by: Matt Van Horn <455140+mvanhorn@users.noreply.github.com>
Co-authored-by: Quentin McGaw <quentin.mcgaw@gmail.com>

Thanks also to @arturhoo for also trying to resolve this issue in #3410

.github/workflows/ci.yml

@@ -241,3 +241,5 @@ jobs:
             VERSION=${{ fromJSON(steps.meta.outputs.json).labels['org.opencontainers.image.version'] }}
           tags: ${{ steps.meta.outputs.tags }}
           push: true
+          provenance: mode=max
+          sbom: true

internal/healthcheck/checker.go

@@ -8,7 +8,6 @@ import (
 	"net"
 	"net/netip"
 	"strings"
-	"sync"
 	"time"
 
 	"github.com/qdm12/gluetun/internal/healthcheck/dns"
@@ -24,7 +23,6 @@ type Checker struct {
 	icmpTargetIPs  []netip.Addr
 	smallCheckType string
 	startupOnFail  bool
-	configMutex    sync.Mutex
 
 	icmpNotPermitted *bool
 
@@ -55,8 +53,6 @@ func NewChecker(logger Logger) *Checker {
 func (c *Checker) SetConfig(tlsDialAddrs []string, icmpTargets []netip.Addr,
 	smallCheckType string, startupOnFail bool,
 ) {
-	c.configMutex.Lock()
-	defer c.configMutex.Unlock()
 	c.tlsDialAddrs = tlsDialAddrs
 	c.icmpTargetIPs = icmpTargets
 	c.smallCheckType = smallCheckType
@@ -166,10 +162,8 @@ func (c *Checker) Stop() error {
 }
 
 func (c *Checker) smallPeriodicCheck(ctx context.Context) error {
-	c.configMutex.Lock()
 	icmpTargetIPs := make([]netip.Addr, len(c.icmpTargetIPs))
 	copy(icmpTargetIPs, c.icmpTargetIPs)
-	c.configMutex.Unlock()
 	tryTimeouts := []time.Duration{
 		5 * time.Second,
 		5 * time.Second,

internal/portforward/service/helpers.go

@@ -49,3 +49,24 @@ func portPairToString(internal, external uint16) string {
 	}
 	return fmt.Sprintf("%d (internal port %d)", external, internal)
 }
+
+type loggerWithPrefix struct {
+	prefix string
+	logger Logger
+}
+
+func (l *loggerWithPrefix) Debug(msg string) {
+	l.logger.Debug(l.prefix + msg)
+}
+
+func (l *loggerWithPrefix) Info(msg string) {
+	l.logger.Info(l.prefix + msg)
+}
+
+func (l *loggerWithPrefix) Warn(msg string) {
+	l.logger.Warn(l.prefix + msg)
+}
+
+func (l *loggerWithPrefix) Error(msg string) {
+	l.logger.Error(l.prefix + msg)
+}

internal/portforward/service/service.go

@@ -6,6 +6,7 @@ import (
 	"fmt"
 	"net/http"
 	"slices"
+	"strings"
 	"sync"
 )
 
@@ -60,7 +61,8 @@ func (s *Service) SetPortsForwarded(ctx context.Context, ports []uint16) (err er
 	s.portMutex.Lock()
 	defer s.portMutex.Unlock()
 
-	if s.settings.PortForwarder != nil {
+	hasPortForwardingCodeRunning := !strings.HasSuffix(s.settings.PortForwarder.Name(), "[not supported]")
+	if hasPortForwardingCodeRunning {
 		return errors.New("setting port forwarded at runtime is not supported with internally running port forwarding code")
 	}
 

internal/portforward/service/start.go

@@ -133,7 +133,11 @@ func (s *Service) onNewPorts(ctx context.Context, internalToExternalPorts map[ui
 	copy(s.ports, externalPorts)
 
 	if s.settings.UpCommand != "" {
-		err = runCommand(ctx, s.cmder, s.logger, s.settings.UpCommand, externalPorts, s.settings.Interface)
+		logger := &loggerWithPrefix{
+			prefix: "up command: ",
+			logger: s.logger,
+		}
+		err = runCommand(ctx, s.cmder, logger, s.settings.UpCommand, externalPorts, s.settings.Interface)
 		if err != nil {
 			err = fmt.Errorf("running up command: %w", err)
 			s.logger.Error(err.Error())

internal/portforward/service/stop.go

@@ -32,7 +32,11 @@ func (s *Service) cleanup() (err error) {
 		const downTimeout = 60 * time.Second
 		ctx, cancel := context.WithTimeout(context.Background(), downTimeout)
 		defer cancel()
-		err = runCommand(ctx, s.cmder, s.logger, s.settings.DownCommand, s.ports, s.settings.Interface)
+		logger := &loggerWithPrefix{
+			prefix: "down command: ",
+			logger: s.logger,
+		}
+		err = runCommand(ctx, s.cmder, logger, s.settings.DownCommand, s.ports, s.settings.Interface)
 		if err != nil {
 			err = fmt.Errorf("running down command: %w", err)
 			s.logger.Error(err.Error())

internal/vpn/loop.go

@@ -45,6 +45,7 @@ type Loop struct {
 	start       <-chan struct{}
 	running     chan<- models.LoopStatus
 	userTrigger bool
+	healthDone  <-chan struct{}
 	// Internal constant values
 	backoffTime time.Duration
 }
@@ -70,6 +71,11 @@ func NewLoop(vpnSettings settings.VPN, ipv6SupportLevel netlink.IPv6SupportLevel
 	statusManager := loopstate.New(constants.Stopped, start, running, stop, stopped)
 	state := state.New(statusManager, vpnSettings)
 
+	// Initialize healthDone channel to a closed channel so that the first time
+	// we call <-l.healthDone it does not block
+	healthDone := make(chan struct{})
+	close(healthDone)
+
 	return &Loop{
 		statusManager:    statusManager,
 		state:            state,
@@ -98,6 +104,7 @@ func NewLoop(vpnSettings settings.VPN, ipv6SupportLevel netlink.IPv6SupportLevel
 		stop:             stop,
 		stopped:          stopped,
 		userTrigger:      true,
+		healthDone:       healthDone,
 		backoffTime:      defaultBackoffTime,
 	}
 }

internal/vpn/portforward.go

@@ -55,7 +55,7 @@ func newNoPortForwarder(providerName string) *noPortForwarder {
 }
 
 func (n *noPortForwarder) Name() string {
-	return n.providerName
+	return n.providerName + " [not supported]"
 }
 
 func (n *noPortForwarder) PortForward(context.Context, pfutils.PortForwardObjects) (

internal/vpn/tunnelup.go

@@ -81,6 +81,7 @@ func (l *Loop) onTunnelUp(ctx, loopCtx context.Context, data tunnelUpData) {
 
 	_, _ = l.dnsLooper.ApplyStatus(ctx, constants.Running)
 
+	<-l.healthDone // make sure the health checker is stopped before restarting it
 	icmpTargetIPs := l.healthSettings.ICMPTargetIPs
 	if len(icmpTargetIPs) == 1 && icmpTargetIPs[0].IsUnspecified() {
 		icmpTargetIPs = []netip.Addr{data.serverIP}
@@ -104,7 +105,12 @@ func (l *Loop) onTunnelUp(ctx, loopCtx context.Context, data tunnelUpData) {
 	// Start collecting health errors asynchronously, since
 	// we should not wait for the code below to complete
 	// to start monitoring health and auto-healing.
-	go l.collectHealthErrors(ctx, loopCtx, healthErrCh)
+	// We keep track of when this goroutine is done with the healthDone
+	// channel to avoid a race condition where the health checker is stopped
+	// after being reconfigured and restarted, instead of before.
+	healthDone := make(chan struct{})
+	l.healthDone = healthDone
+	go l.collectHealthErrors(ctx, loopCtx, healthDone, healthErrCh)
 
 	err = l.publicip.RunOnce(ctx)
 	if err != nil {
@@ -140,7 +146,10 @@ func (l *Loop) onTunnelUp(ctx, loopCtx context.Context, data tunnelUpData) {
 	}
 }
 
-func (l *Loop) collectHealthErrors(ctx, loopCtx context.Context, healthErrCh <-chan error) {
+func (l *Loop) collectHealthErrors(ctx, loopCtx context.Context,
+	done chan<- struct{}, healthErrCh <-chan error,
+) {
+	defer close(done)
 	var previousHealthErr error
 	for {
 		select {