feat(diagnostics): связывать события сессии и попытки восстановления

internal/logx/prefix.go

@@ -0,0 +1,23 @@
+package logx
+
+import "strings"
+
+type prefixedLogger struct {
+	Logger
+	prefix string
+}
+
+// WithPrefix привязывает источник к логгеру, не к изменяемому глобальному состоянию.
+func WithPrefix(logger Logger, prefix string) Logger {
+	return &prefixedLogger{Logger: OrNop(logger), prefix: strings.ReplaceAll(prefix, "%", "%%")}
+}
+
+func (l *prefixedLogger) Debugf(format string, v ...any) {
+	if l.DebugEnabled() {
+		l.Logger.Debugf(l.prefix+format, v...)
+	}
+}
+
+func (l *prefixedLogger) Infof(format string, v ...any)  { l.Logger.Infof(l.prefix+format, v...) }
+func (l *prefixedLogger) Warnf(format string, v ...any)  { l.Logger.Warnf(l.prefix+format, v...) }
+func (l *prefixedLogger) Errorf(format string, v ...any) { l.Logger.Errorf(l.prefix+format, v...) }

internal/logx/prefix_test.go

@@ -0,0 +1,37 @@
+package logx
+
+import (
+	"fmt"
+	"testing"
+)
+
+type captureLogger struct {
+	nopLogger
+	lines []string
+}
+
+func (l *captureLogger) Infof(format string, args ...any) {
+	l.lines = append(l.lines, fmt.Sprintf(format, args...))
+}
+
+func TestPrefixRemainsBoundToLogger(t *testing.T) {
+	sink := &captureLogger{}
+	old := WithPrefix(sink, "[old 100%] ")
+	next := WithPrefix(sink, "[next] ")
+	next.Infof("ready %d", 2)
+	old.Infof("closed %d", 1)
+	if sink.lines[0] != "[next] ready 2" || sink.lines[1] != "[old 100%] closed 1" {
+		t.Fatalf("messages = %q", sink.lines)
+	}
+}
+
+func TestPrefixNilLogger(t *testing.T) {
+	l := WithPrefix(nil, "test ")
+	l.Debugf("%d", 1)
+	l.Infof("%d", 1)
+	l.Warnf("%d", 1)
+	l.Errorf("%d", 1)
+	if l.DebugEnabled() {
+		t.Fatal("nil logger enabled debug")
+	}
+}

internal/session/diagnostics_test.go

@@ -0,0 +1,56 @@
+package session
+
+import (
+	"context"
+	"errors"
+	"fmt"
+	"strings"
+	"sync"
+	"testing"
+
+	"github.com/samosvalishe/free-turn-proxy/internal/config"
+	"github.com/samosvalishe/free-turn-proxy/internal/logx"
+)
+
+type diagnosticLog struct {
+	logx.Logger
+	mu    sync.Mutex
+	lines []string
+}
+
+func (l *diagnosticLog) Infof(format string, args ...any) {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+	l.lines = append(l.lines, fmt.Sprintf(format, args...))
+}
+
+func TestRelayDiagnosticsKeepSessionIdentity(t *testing.T) {
+	log := &diagnosticLog{Logger: logx.Nop()}
+	first, err := New(&config.Client{}, Deps{Logger: log})
+	if err != nil {
+		t.Fatal(err)
+	}
+	second, err := New(&config.Client{}, Deps{Logger: log})
+	if err != nil {
+		t.Fatal(err)
+	}
+	failure := errors.New("test stop")
+	for _, s := range []*Session{first, second} {
+		if err := s.relayLoop(t.Context(), func(context.Context) error { return failure }); !errors.Is(err, failure) {
+			t.Fatalf("relay result = %v", err)
+		}
+	}
+	first.deps.Logger.Infof("late event")
+	if len(log.lines) != 5 {
+		t.Fatalf("events = %v", log.lines)
+	}
+	prefix := func(line string) string { return strings.SplitN(line, "]", 2)[0] }
+	if prefix(log.lines[0]) == prefix(log.lines[2]) || prefix(log.lines[0]) != prefix(log.lines[4]) {
+		t.Fatalf("session identity lost: %v", log.lines)
+	}
+	for _, i := range []int{1, 3} {
+		if !strings.Contains(log.lines[i], "generation=1 reason=finished elapsed=") {
+			t.Fatalf("missing attempt result: %s", log.lines[i])
+		}
+	}
+}

internal/session/session.go

@@ -10,6 +10,7 @@ import (
 	"sync/atomic"
 	"time"
 
+	"github.com/google/uuid"
 	"github.com/samosvalishe/free-turn-proxy/internal/client/dnsdial"
 	"github.com/samosvalishe/free-turn-proxy/internal/config"
 	"github.com/samosvalishe/free-turn-proxy/internal/logx"
@@ -141,6 +142,11 @@ func New(cfg *config.Client, deps Deps) (*Session, error) {
 	if deps.Logger == nil {
 		deps.Logger = logx.Nop()
 	}
+	id, err := uuid.NewRandom()
+	if err != nil {
+		return nil, fmt.Errorf("session diagnostic ID: %w", err)
+	}
+	deps.Logger = logx.WithPrefix(deps.Logger, "[session="+id.String()+"] ")
 
 	total := cfg.TURN.N * max(len(cfg.VK.Links), 1)
 
@@ -165,6 +171,11 @@ func (s *Session) Run(ctx context.Context) (err error) {
 	if !s.started.CompareAndSwap(false, true) {
 		return ErrAlreadyRun
 	}
+	startedAt := time.Now()
+	s.deps.Logger.Infof("lifecycle start mode=%s streams=%d", s.cfg.Proxy.Mode, s.total)
+	defer func() {
+		s.deps.Logger.Infof("lifecycle stop elapsed=%s error=%v", time.Since(startedAt).Truncate(time.Millisecond), err)
+	}()
 	s.publish(&statusInfo{phase: PhaseConnecting, total: s.total}, true)
 	defer func() {
 		if err != nil {
@@ -243,19 +254,28 @@ func (s *Session) runRelayLoop(ctx context.Context, prov provider.Provider, peer
 
 func (s *Session) relayLoop(ctx context.Context, attempt func(context.Context) error) error {
 	log := s.deps.Logger
-	for {
+	for generation := uint64(1); ; generation++ {
+		startedAt := time.Now()
+		log.Infof("relay start generation=%d", generation)
 		attemptCtx, attemptCancel := context.WithCancel(ctx)
 		done := make(chan error, 1)
 		go func() { done <- safego.Call(log, func() error { return attempt(attemptCtx) }) }()
 
 		var err error
+		reason := "finished"
 		select {
 		case err = <-done:
 		case <-s.reconnectCh:
+			reason = "reconnect"
 			attemptCancel()
 			err = <-done
 		}
 		attemptCancel()
+		if ctx.Err() != nil {
+			reason = "cancelled"
+		}
+		log.Infof("relay stop generation=%d reason=%s elapsed=%s error=%v", generation, reason,
+			time.Since(startedAt).Truncate(time.Millisecond), err)
 
 		if ctx.Err() != nil {
 			return err