diff --git a/internal/logx/prefix.go b/internal/logx/prefix.go new file mode 100644 index 0000000..02f74c5 --- /dev/null +++ b/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...) } diff --git a/internal/logx/prefix_test.go b/internal/logx/prefix_test.go new file mode 100644 index 0000000..1138d8a --- /dev/null +++ b/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") + } +} diff --git a/internal/session/diagnostics_test.go b/internal/session/diagnostics_test.go new file mode 100644 index 0000000..4f81c1d --- /dev/null +++ b/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]) + } + } +} diff --git a/internal/session/session.go b/internal/session/session.go index 931108a..5d432fb 100644 --- a/internal/session/session.go +++ b/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