feat(media): share Browser encoding and complete local diagnostics

* fix: allow Linux interface discovery in embedded media service

* feat: expand local diagnostic reports

* research: validate independent Browser encoding producers

* feat: prototype Browser pool ownership and record remaining media gates

* feat: refine Browser shared encoders and native output reuse

* Refine carrier costs and simplify release entry points

* Close media phase and prepare piik design handoff
This commit is contained in:
AAA authored and GitHub committed 2026-09-09 20:59:44 +08:00
1 parent cfc323adce
commit c9a6642ac1
79 files changed
+3955 -1176

No files matched your search

+11 -3
View File
@@ -70,7 +70,7 @@ func Run(ctx context.Context, options Options) (returnedErr error) {
defer func() {
cancel()
if recorder != nil {
slog.Debug("screener-client", "event", "stopped", "failed", returnedErr != nil)
slog.Debug("screener-client", "event", "stopped", "failed", returnedErr != nil, diagnostics.Error(returnedErr))
if options.console.program == nil {
path, err := recorder.Export()
options.console.send(consoleExportResult{path: path, err: err})
@@ -88,15 +88,17 @@ func Run(ctx context.Context, options Options) (returnedErr error) {
return fmt.Errorf("Screener Client diagnostics are unavailable: %w", err)
}
previous, previousWriter, previousFlags := slog.Default(), log.Writer(), log.Flags()
var dependencyLog *diagnostics.LineWriter
restoreLogger = func() {
_ = dependencyLog.Close()
slog.SetDefault(previous)
log.SetOutput(previousWriter)
log.SetFlags(previousFlags)
}
options.logger = recorder.Logger()
slog.SetDefault(options.logger)
// Only structured application events belong in the persisted log.
log.SetOutput(previousWriter)
dependencyLog = diagnostics.Writer("stdlib")
log.SetOutput(dependencyLog)
log.SetFlags(previousFlags)
options.console.send(consoleDebug{logPath: recorder.LogPath(), export: recorder.Export})
}
@@ -131,6 +133,12 @@ func Run(ctx context.Context, options Options) (returnedErr error) {
}
}
nativeMedia := discoverNativeMedia(ctx, options.CaptureProcess)
if recorder != nil {
recorder.Context("configuration", map[string]any{"siteConfigured": config.Site != "", "local": options.Local,
"link": options.Link, "port": options.Port, "localAccessProtected": config.LocalAccessPassword != ""})
recorder.Context("capture", nativeMedia.capture)
recorder.Binary("captureExecutable", nativeMedia.captureProcess)
}
slog.Debug("screener-client", "event", "native-capabilities",
"video", nativeMedia.capabilities.Video, "processAudio", nativeMedia.capabilities.ProcessAudio,
"systemAudio", nativeMedia.capabilities.SystemAudio, "hardwareH264", nativeMedia.capabilities.HardwareH264,
+15 -8
View File
@@ -2,13 +2,13 @@ package mediaedge
import (
"errors"
"fmt"
"io"
"log/slog"
"strconv"
"strings"
"sync"
"github.com/TNTcraftHIM/Screener/internal/diagnostics"
"github.com/TNTcraftHIM/Screener/internal/media/forwarding"
"github.com/pion/ice/v4"
"github.com/pion/webrtc/v4"
@@ -89,6 +89,7 @@ func (engine *Engine) NewEdge(source *Source, options EdgeOptions) (*Edge, error
return nil, err
}
connection := transport.PC
log := slog.Default().With("connectionId", diagnostics.ID(options.ConnectionID), "rtcPeerId", diagnostics.ID(connection.ID()))
transport.SetAudioBitrate(options.Audio.configuredBitrate())
edge := &Edge{
connectionID: options.ConnectionID,
@@ -137,22 +138,22 @@ func (engine *Engine) NewEdge(source *Source, options EdgeOptions) (*Edge, error
edge.localCandidates.addPion(candidate)
})
connection.OnICEConnectionStateChange(func(state webrtc.ICEConnectionState) {
slog.Debug("screener-client", "event", "media-ice-state", "direction", "outbound", "local", options.Local, "state", state.String())
log.Debug("screener-client", "event", "media-ice-state", "direction", "outbound", "local", options.Local, "state", state.String())
})
if dtls := edge.sender.Transport(); dtls != nil {
dtls.OnStateChange(func(state webrtc.DTLSTransportState) {
slog.Debug("screener-client", "event", "media-dtls-state", "direction", "outbound", "local", options.Local, "state", state.String())
log.Debug("screener-client", "event", "media-dtls-state", "direction", "outbound", "local", options.Local, "state", state.String())
})
}
connection.OnConnectionStateChange(func(state webrtc.PeerConnectionState) {
debug := slog.Default().Enabled(engine.ctx, slog.LevelDebug)
if debug {
slog.Debug("screener-client", "event", "media-connection-state", "direction", "outbound", "local", options.Local, "state", state.String())
log.Debug("screener-client", "event", "media-connection-state", "direction", "outbound", "local", options.Local, "state", state.String())
}
if state == webrtc.PeerConnectionStateConnected {
if err := edge.transport.SetConnected(); err != nil {
if debug {
slog.Debug("screener-client", "event", "media-activation-failed", "errorType", fmt.Sprintf("%T", err))
log.Debug("screener-client", "event", "media-activation-failed", diagnostics.Error(err))
}
_ = connection.Close()
return
@@ -164,7 +165,7 @@ func (engine *Engine) NewEdge(source *Source, options EdgeOptions) (*Edge, error
if pair, pairErr := edge.SelectedPair(); pairErr == nil {
selected = &pair
if debug {
slog.Debug("screener-client", "event", "media-selected-path", "direction", "outbound", "local", options.Local,
log.Debug("screener-client", "event", "media-selected-path", "direction", "outbound", "local", options.Local,
"localType", pair.Local.String(), "remoteType", pair.Remote.String(), "natTraversalPath", pair.NatTraversalPath)
}
}
@@ -251,13 +252,16 @@ func (edge *Edge) SetAnswer(answer webrtc.SessionDescription) error {
for _, candidate := range pending {
// Candidates are disposable edge input. The connection state callback
// remains the authority for a real media failure.
_ = edge.connection.AddICECandidate(candidate)
if err := edge.connection.AddICECandidate(candidate); err != nil {
slog.Debug("media-candidate-rejected", "connectionId", diagnostics.ID(edge.connectionID), "stage", "drain", diagnostics.Error(err))
}
}
return nil
}
func (edge *Edge) AddRemoteCandidate(candidate *webrtc.ICECandidateInit) error {
if malformedRemoteCandidate(candidate) {
slog.Debug("media-candidate-rejected", "connectionId", diagnostics.ID(edge.connectionID), "stage", "malformed")
return nil
}
value := webrtc.ICECandidateInit{}
@@ -272,6 +276,7 @@ func (edge *Edge) AddRemoteCandidate(candidate *webrtc.ICECandidateInit) error {
if !edge.remoteDescriptionSet {
if len(edge.pendingCandidates) >= maxPendingCandidates {
edge.mu.Unlock()
slog.Debug("media-candidate-rejected", "connectionId", diagnostics.ID(edge.connectionID), "stage", "queue-full", "capacity", maxPendingCandidates)
return nil
}
edge.pendingCandidates = append(edge.pendingCandidates, value)
@@ -282,7 +287,9 @@ func (edge *Edge) AddRemoteCandidate(candidate *webrtc.ICECandidateInit) error {
// A candidate may become stale between validation and delivery. Dropping
// that one edge input keeps the shared control session alive; ICE state
// events still report whether the edge itself can connect.
_ = edge.connection.AddICECandidate(value)
if err := edge.connection.AddICECandidate(value); err != nil {
slog.Debug("media-candidate-rejected", "connectionId", diagnostics.ID(edge.connectionID), "stage", "apply", diagnostics.Error(err))
}
return nil
}
+10 -2
View File
@@ -3,6 +3,7 @@ package mediaedge
import (
"context"
"errors"
"log/slog"
"net"
"net/netip"
"strconv"
@@ -12,11 +13,11 @@ import (
"time"
"github.com/TNTcraftHIM/Screener/internal/client/portmapping"
"github.com/TNTcraftHIM/Screener/internal/diagnostics"
"github.com/TNTcraftHIM/Screener/internal/media/encoded"
"github.com/TNTcraftHIM/Screener/internal/media/forwarding"
"github.com/pion/ice/v4"
"github.com/pion/interceptor"
"github.com/pion/logging"
"github.com/pion/rtcp"
"github.com/pion/stun/v3"
"github.com/pion/webrtc/v4"
@@ -86,7 +87,7 @@ func NewEngine(options EngineOptions) (*Engine, error) {
if err != nil {
return nil, errors.New("native media UDP socket is unavailable")
}
loggerFactory := logging.NewDefaultLoggerFactory()
loggerFactory := diagnostics.PionLoggerFactory()
ready := make(chan struct{})
mux := ice.NewUniversalUDPMuxDefault(ice.UniversalUDPMuxParams{
Logger: loggerFactory.NewLogger("screener-ice"),
@@ -190,6 +191,7 @@ func (engine *Engine) surveySTUN(
}
addresses, err := net.DefaultResolver.LookupNetIP(ctx, "ip4", uri.Host)
if err != nil || len(addresses) == 0 {
slog.DebugContext(ctx, "nat-survey", "event", "resolve-failed", "host", uri.Host, diagnostics.Error(err))
continue
}
serverAddress, err := net.ResolveUDPAddr(
@@ -207,6 +209,7 @@ func (engine *Engine) surveySTUN(
results := make(chan mappedAddress, len(targets))
for _, target := range targets {
go func(address *net.UDPAddr) {
started := time.Now()
mapped, err := engine.mux.GetXORMappedAddrContext(
surveyContext,
address,
@@ -214,8 +217,13 @@ func (engine *Engine) surveySTUN(
)
if err != nil || mapped == nil || mapped.IP.To4() == nil ||
mapped.Port < 1 || mapped.Port > 65_535 {
slog.DebugContext(surveyContext, "nat-survey", "event", "binding-failed", "serverPort", address.Port,
"durationMs", time.Since(started).Milliseconds(), diagnostics.Error(err))
return
}
slog.DebugContext(surveyContext, "nat-survey", "event", "binding", "serverPort", address.Port,
"localPort", engine.localPort, "mappedAddress", diagnostics.ID(mapped.IP.String()), "mappedPort", mapped.Port,
"durationMs", time.Since(started).Milliseconds())
select {
case results <- mappedAddress{address: mapped.IP.String(), port: mapped.Port}:
case <-surveyContext.Done():
+61 -6
View File
@@ -2,8 +2,10 @@ package mediaedge
import (
"errors"
"log/slog"
"time"
"github.com/TNTcraftHIM/Screener/internal/diagnostics"
"github.com/TNTcraftHIM/Screener/internal/media/encoded"
"github.com/TNTcraftHIM/Screener/internal/media/forwarding"
"github.com/pion/rtcp"
@@ -93,6 +95,18 @@ func (source *Source) planGroups(demands []outputDemand) (OutputPlan, error) {
delete(source.memberships, consumer)
}
}
// The previous frame's active bit alone may outlive its last handoff.
inUse := func(group *outputGroup) bool {
if group == nil || !group.active {
return false
}
for _, demand := range demands {
if demand.active && (demand.consumer.CurrentSource() == group.media.Source || source.memberships[demand.consumer] == group) {
return true
}
}
return false
}
for _, demand := range demands {
if !demand.active || !demand.lower {
if source.memberships[demand.consumer] != nil {
@@ -105,14 +119,27 @@ func (source *Source) planGroups(demands []outputDemand) (OutputPlan, error) {
for slot := 0; slot < len(source.outputBitrates); slot++ {
group := source.groups[slot]
if group != nil && source.outputBitrates[slot] > 0 && group.budget == demand.budget {
selected = group
break
if selected == nil || inUse(group) {
selected = group
}
if inUse(group) {
break
}
}
}
if selected == nil {
if selected == nil || !inUse(selected) {
// A group's rates can change in place only when no other current or
// requested member still needs a different budget.
ordered := []*outputGroup{source.memberships[demand.consumer], source.groupForMedia(demand.consumer.CurrentSource())}
owned := []*outputGroup{source.memberships[demand.consumer], source.groupForMedia(demand.consumer.CurrentSource())}
var ordered []*outputGroup
for _, group := range owned {
if inUse(group) {
ordered = append(ordered, group)
}
}
// Keep an owned live pipeline before reviving an inactive cached match.
ordered = append(ordered, selected)
ordered = append(ordered, owned...)
for slot := 0; slot < len(source.outputBitrates); slot++ {
if group := source.groups[slot]; group != nil {
ordered = append(ordered, group)
@@ -156,6 +183,12 @@ func (source *Source) planGroups(demands []outputDemand) (OutputPlan, error) {
// membership. No timer, retry queue or temporary capacity exemption.
continue
}
if selected.budget != demand.budget || source.memberships[demand.consumer] != selected {
if slog.Default().Enabled(source.engine.ctx, slog.LevelDebug) {
slog.Debug("encoding-group", "event", "demand", "slot", selected.slot, "budget", demand.budget,
"localPort", source.engine.localPort, "rtcPeerId", groupConsumerID(demand.consumer))
}
}
selected.budget = demand.budget
if !selected.active {
selected.start = source.inputPTS
@@ -176,7 +209,11 @@ func (source *Source) planGroups(demands []outputDemand) (OutputPlan, error) {
active = true
}
}
group.active = active && source.outputBitrates[group.slot] > 0
nextActive := active && source.outputBitrates[group.slot] > 0
if group.active != nextActive {
slog.Debug("encoding-group", "event", "activity", "slot", group.slot, "active", nextActive, "localPort", source.engine.localPort)
}
group.active = nextActive
plan.Active[group.slot] = group.active
if group.active {
plan.Bitrates[group.slot] = uint32(max(1000, min(group.media.CodecBudget(0, int64(group.budget)), int64(source.outputBitrates[group.slot]))))
@@ -231,11 +268,29 @@ func (source *Source) installGroup(group *outputGroup, original bool) {
}
for consumer, wanted := range source.memberships {
if wanted == group && (original || group != nil) && consumer.CurrentSource() != next {
_ = consumer.ReplaceSource(next)
err := consumer.ReplaceSource(next)
if slog.Default().Enabled(source.engine.ctx, slog.LevelDebug) {
slot := -1
if group != nil {
slot = group.slot
}
slog.Debug("encoding-group", "event", "attachment", "slot", slot, "original", original,
"localPort", source.engine.localPort, "rtcPeerId", groupConsumerID(consumer), diagnostics.Error(err))
}
}
}
}
func groupConsumerID(consumer groupConsumer) string {
switch consumer := consumer.(type) {
case *forwarding.Transport:
return diagnostics.ID(consumer.PC.ID())
case *forwarding.Publication:
return diagnostics.ID(consumer.PC.ID())
}
return ""
}
func (source *Source) beginGroupFrame(pts time.Duration, at time.Time) error {
if err := source.media.BeginFrame(pts, at); err != nil {
return err
+25
View File
@@ -95,6 +95,11 @@ func TestOutputGroupsShareSplitRejoinAndRetire(t *testing.T) {
if retired.Active[gb.slot] {
t.Fatal("last lower member did not release its encoder")
}
demands[0].active = false
if inactive := plan(); inactive.Active[ga.slot] || inactive.Active[gb.slot] {
t.Fatal("disconnected consumer kept an output active")
}
demands[0].active = true
demands[0].lower = true
demands[0].original = false
demands[0].budget = 300_000
@@ -102,6 +107,26 @@ func TestOutputGroupsShareSplitRejoinAndRetire(t *testing.T) {
if !reactivated.Active[gb.slot] || reactivated.Active[1] || source.memberships[a] != gb {
t.Fatal("inactive compatible group could not reactivate")
}
source.installGroup(gb, false)
started := gb.start
source.groupRecovery.Store(0)
demands[0].budget = ga.budget
repriced := plan()
if source.memberships[a] != gb || a.CurrentSource() != gb.media.Source ||
!repriced.Active[gb.slot] || repriced.Active[ga.slot] || repriced.Bitrates[gb.slot] != ga.budget ||
gb.start != started || source.groupRecovery.Load() != 0 {
t.Fatalf("inactive budget match replaced live pipeline: member=%v source=%v active=%v rate=%d want=%d start=%v/%v recovery=%d", source.memberships[a] == gb, a.CurrentSource() == gb.media.Source, repriced.Active, repriced.Bitrates[gb.slot], ga.budget, gb.start, started, source.groupRecovery.Load())
}
c := &groupTestConsumer{source.media.Source}
demands = append(demands, outputDemand{consumer: c, budget: ga.budget, active: true, lower: true})
plan()
if source.memberships[c] != gb {
t.Fatal("inactive budget match took precedence over a compatible active output")
}
source.installGroup(gb, false)
if settled := plan(); settled.Active[ga.slot] || c.CurrentSource() != gb.media.Source {
t.Fatal("last handoff retained an unneeded output")
}
if err = gb.media.BeginFrame(tick+time.Nanosecond, time.Unix(0, 0).Add(tick+time.Nanosecond)); err != nil {
t.Fatal(err)
}
+11
View File
@@ -1,8 +1,10 @@
package mediaedge
import (
"log/slog"
"time"
"github.com/TNTcraftHIM/Screener/internal/diagnostics"
"github.com/TNTcraftHIM/Screener/internal/media/forwarding"
"github.com/pion/webrtc/v4"
)
@@ -68,6 +70,15 @@ func (edge *Edge) QualitySample(now time.Time) (QualitySample, bool) {
Width: uint32(format >> 32),
Height: uint32(format),
}
if slog.Default().Enabled(edge.engine.ctx, slog.LevelDebug) {
defer func() {
slog.Debug("media-sample", "connectionId", diagnostics.ID(edge.connectionID), "local", edge.local,
"rtcPeerId", diagnostics.ID(edge.connection.ID()), "windowMs", sample.SampleWindowMs,
"fps", sample.FramesPerSecond, "bitrateKbps", sample.BitrateKbps, "width", sample.Width, "height", sample.Height,
"availableOutgoingKbps", sample.AvailableOutgoingKbps, "state", sample.State, "reason", sample.Reason,
"egress", edge.transport.Egress(), "output", edge.transport.Output.State())
}()
}
target, observed := edge.targetBitrate()
if edge.State() != webrtc.PeerConnectionStateConnected || !observed ||
frames == 0 || bytes == 0 {
+4 -12
View File
@@ -5,7 +5,6 @@ import (
"errors"
"io"
"sync"
"sync/atomic"
"time"
"github.com/TNTcraftHIM/Screener/internal/client/nativecapture"
@@ -43,11 +42,10 @@ func relayBackend(codec string, options *RelayOptions) (nativecapture.EncodedVid
// relayDerivation owns only the optional missing lower representation. Raw RTP
// never waits for it. A retired process must exit before another one can start.
type relayDerivation struct {
source *Source
options RelayOptions
recovery atomic.Bool
mu sync.Mutex
run *relayRun
source *Source
options RelayOptions
mu sync.Mutex
run *relayRun
}
type relayPlan struct {
@@ -182,7 +180,6 @@ func (relay *relayDerivation) push(packet *rtp.Packet) {
done: make(chan struct{}), packets: make(chan *rtp.Packet, relayPacketLimit),
anchorRTP: packet.Timestamp, anchorTime: at,
}
relay.recovery.Store(true)
go relay.run.serve()
// Earlier packets of this frame used the raw path only. Begin assembly
// with the next complete frame, not this frame's trailing fragment.
@@ -310,11 +307,6 @@ func (run *relayRun) write(stream *nativecapture.Stream) error {
if !plan.wanted || plan.profile != run.plan.profile || plan.format != run.plan.format {
return context.Canceled
}
if run.owner.recovery.Swap(false) {
if err = stream.RequestKeyFrame(-1); err != nil {
return err
}
}
if err = stream.WriteFrame(frame); err != nil {
return err
}
-3
View File
@@ -603,9 +603,6 @@ func (source *Source) detach(edge *Edge) {
}
func (source *Source) requestLayerKeyFrame(layer int) {
if source.relay != nil && layer < len(source.formats)-1 {
source.relay.recovery.Store(true)
}
source.groupRecovery.Or(uint32(1) << layer)
source.RequestRecoveryFrame()
}
+23 -3
View File
@@ -7,12 +7,15 @@ import (
"errors"
"fmt"
"io"
"log/slog"
"os"
"os/exec"
"path/filepath"
"runtime"
"strings"
"time"
"github.com/TNTcraftHIM/Screener/internal/diagnostics"
)
const (
@@ -93,12 +96,14 @@ func Discover(parent context.Context, executable string) (Capabilities, error) {
ctx, cancel := context.WithTimeout(parent, probeTimeout)
defer cancel()
stdout := &boundedBuffer{limit: maxProbeOutputBytes}
stderr := &boundedBuffer{limit: maxProbeErrorBytes}
stderr := diagnostics.Writer("native-capture-probe")
defer stderr.Close()
command := exec.CommandContext(ctx, executable, "--probe")
command.Stdout = stdout
command.Stderr = stderr
hideWindow(command)
if err := command.Run(); err != nil {
slog.DebugContext(ctx, "screener-client", "event", "capture-probe-failed", diagnostics.Error(err), "canceled", ctx.Err() != nil)
if errors.Is(ctx.Err(), context.DeadlineExceeded) {
return Capabilities{}, errors.New("native capture probe timed out")
}
@@ -178,12 +183,27 @@ func decodeProbe(payload []byte) (Capabilities, error) {
}
type boundedBuffer struct {
buffer bytes.Buffer
limit int
buffer bytes.Buffer
limit int
discardOverflow bool
}
func (buffer *boundedBuffer) Write(payload []byte) (int, error) {
remaining := buffer.limit - buffer.buffer.Len()
if buffer.discardOverflow {
// Keep terminal failure codes even after a long stream of encoder statistics.
if len(payload) >= buffer.limit {
buffer.buffer.Reset()
payloadTail := payload[len(payload)-buffer.limit:]
_, _ = buffer.buffer.Write(payloadTail)
} else {
if len(payload) > remaining {
buffer.buffer.Next(len(payload) - remaining)
}
_, _ = buffer.buffer.Write(payload)
}
return len(payload), nil
}
if remaining <= 0 {
return 0, errors.New("native capture probe output exceeded its bound")
}
+48 -5
View File
@@ -14,6 +14,8 @@ import (
"sync"
"time"
"unicode/utf8"
"github.com/TNTcraftHIM/Screener/internal/diagnostics"
)
const (
@@ -125,6 +127,9 @@ type Stream struct {
controlMu sync.Mutex
closed bool
closeOnce sync.Once
readEnd sync.Once
logger *slog.Logger
ctx context.Context
}
func ListSources(parent context.Context, executable string) ([]CaptureTarget, error) {
@@ -133,9 +138,12 @@ func ListSources(parent context.Context, executable string) ([]CaptureTarget, er
stdout := &boundedBuffer{limit: maxProbeOutputBytes}
command := exec.CommandContext(ctx, executable, "--list")
command.Stdout = stdout
command.Stderr = &boundedBuffer{limit: maxProbeErrorBytes}
stderr := diagnostics.Writer("native-source-list")
defer stderr.Close()
command.Stderr = stderr
hideWindow(command)
if err := command.Run(); err != nil {
slog.DebugContext(ctx, "screener-client", "event", "capture-source-list-failed", diagnostics.Error(err), "canceled", ctx.Err() != nil)
return nil, errors.New("native capture source list is unavailable")
}
var targets []CaptureTarget
@@ -165,9 +173,12 @@ func PreviewSource(parent context.Context, executable string, target CaptureTarg
zeroWhenEmpty(target.CreationTime),
)
command.Stdout = stdout
command.Stderr = &boundedBuffer{limit: maxProbeErrorBytes}
stderr := diagnostics.Writer("native-source-preview")
defer stderr.Close()
command.Stderr = stderr
hideWindow(command)
if err := command.Run(); err != nil {
slog.DebugContext(ctx, "screener-client", "event", "capture-source-preview-failed", diagnostics.Error(err), "canceled", ctx.Err() != nil)
return nil, errors.New("native capture preview is unavailable")
}
preview := stdout.Bytes()
@@ -381,7 +392,14 @@ func startStreamWithEnvironment(
return nil, errors.New("native capture process is unavailable")
}
ctx, cancel := context.WithCancel(parent)
started := time.Now()
// A diagnostic-only process label correlates stderr while old/new captures overlap.
captureID := strconv.FormatInt(started.UnixNano(), 36)
logger := slog.Default().With("capture", captureID)
command := exec.CommandContext(ctx, executable, arguments...)
if logger.Enabled(ctx, slog.LevelDebug) {
environment = append(environment, "SCREENER_CAPTURE_DEBUG=1")
}
if len(environment) > 0 {
command.Env = append(os.Environ(), environment...)
}
@@ -395,22 +413,40 @@ func startStreamWithEnvironment(
cancel()
return nil, err
}
stderr := &boundedBuffer{limit: maxProbeErrorBytes}
command.Stderr = stderr
stderr := &boundedBuffer{limit: maxProbeErrorBytes, discardOverflow: true}
trace := diagnostics.Writer("native-capture/" + captureID)
command.Stderr = io.MultiWriter(stderr, trace)
hideWindow(command)
if err = command.Start(); err != nil {
_ = trace.Close()
cancel()
logger.DebugContext(ctx, "screener-client", "event", "capture-process-start-failed", diagnostics.Error(err))
return nil, fmt.Errorf("start native capture process: %w", err)
}
logger = logger.With("pid", command.Process.Pid)
mode := "capture"
if len(arguments) > 0 {
switch arguments[0] {
case "--capture-video", "--capture-audio", "--encoded-video":
mode = strings.TrimPrefix(arguments[0], "--")
}
}
logger.DebugContext(ctx, "screener-client", "event", "capture-process-started", "mode", mode)
stream := &Stream{
cancel: cancel,
input: stdout,
key: stdin,
done: make(chan error, 1),
logger: logger,
ctx: ctx,
}
go func() {
waitErr := command.Wait()
_ = trace.Close()
logCaptureFailure(ctx, waitErr, command.ProcessState.ExitCode(), stderr.Bytes())
logger.DebugContext(ctx, "screener-client", "event", "capture-process-ended", "mode", mode,
"durationMs", time.Since(started).Milliseconds(), "exitCode", command.ProcessState.ExitCode(),
"canceled", ctx.Err() != nil, "cancelReason", diagnostics.SafeText(fmt.Sprint(context.Cause(ctx))), diagnostics.Error(waitErr))
stream.done <- waitErr
close(stream.done)
}()
@@ -442,7 +478,14 @@ func logCaptureFailure(ctx context.Context, err error, exitCode int, stderr []by
}
func (stream *Stream) Read() (Frame, error) {
return readFrame(stream.input)
frame, err := readFrame(stream.input)
if err != nil && stream.logger != nil {
stream.readEnd.Do(func() {
stream.logger.DebugContext(stream.ctx, "screener-client", "event", "capture-stream-ended",
"eof", errors.Is(err, io.EOF), "canceled", stream.ctx.Err() != nil, diagnostics.Error(err))
})
}
return frame, err
}
// WriteFrame shares the existing stdin lock with control. Only encoded video
@@ -5,11 +5,28 @@ import (
"context"
"encoding/json"
"errors"
"io"
"log/slog"
"strings"
"testing"
)
func TestDiagnosticStderrOverflowDoesNotStopTheChildReader(t *testing.T) {
for _, discard := range []bool{false, true} {
buffer := &boundedBuffer{limit: 4, discardOverflow: discard}
var forwarded bytes.Buffer
writer := io.MultiWriter(buffer, &forwarded)
_, err := io.Copy(writer, strings.NewReader("stage=capture-closed\ndetail=more evidence\n"))
if discard {
if err != nil || string(buffer.Bytes()) != "nce\n" || !strings.Contains(forwarded.String(), "more evidence") {
t.Fatalf("diagnostic stderr stopped or lost its bounded tail: %q, %q, %v", buffer.Bytes(), forwarded.String(), err)
}
} else if err == nil {
t.Fatal("strict probe output no longer rejects overflow")
}
}
}
func TestVideoOutputGroupCountIsBoundedBeforeProcessStartup(t *testing.T) {
options := VideoOptions{
Target: CaptureTarget{Kind: "display", SourceID: "1", Title: "Display"},
+3 -3
View File
@@ -30,7 +30,7 @@ func (session *Session) handlePublication(envelope requestEnvelope, payload []by
}
offer, media, err := host.PreparePublication(identity.PublicationGeneration, identity.ConnectionID, servers)
if err != nil {
return operationFailure(envelope), nil
return operationFailure(envelope, err), nil
}
result.responseEnvelope, result.SDP, result.Media = response(envelope, "publication-offer"), offer.SDP, media
return result, nil
@@ -44,7 +44,7 @@ func (session *Session) handlePublication(envelope requestEnvelope, payload []by
}
publication, err := host.Publication(identity.PublicationGeneration, identity.ConnectionID)
if err != nil {
return operationFailure(envelope), nil
return operationFailure(envelope, err), nil
}
accepted := ""
switch envelope.Type {
@@ -77,7 +77,7 @@ func (session *Session) handlePublication(envelope requestEnvelope, payload []by
accepted = "publication-layers-accepted"
}
if err != nil {
return operationFailure(envelope), nil
return operationFailure(envelope, err), nil
}
return response(envelope, accepted), nil
}
+70 -33
View File
@@ -6,7 +6,6 @@ import (
"encoding/base64"
"encoding/json"
"errors"
"fmt"
"io"
"log/slog"
"net/url"
@@ -14,6 +13,7 @@ import (
"strconv"
"strings"
"sync"
"time"
"unicode"
"github.com/TNTcraftHIM/Screener/internal/client/loopback"
@@ -21,6 +21,7 @@ import (
"github.com/TNTcraftHIM/Screener/internal/client/nativecapture"
"github.com/TNTcraftHIM/Screener/internal/client/nativehost"
"github.com/TNTcraftHIM/Screener/internal/client/nativeviewer"
"github.com/TNTcraftHIM/Screener/internal/diagnostics"
"github.com/pion/webrtc/v4"
)
@@ -82,11 +83,18 @@ func (session *Session) Events() <-chan any {
return session.events
}
func (session *Session) Handle(ctx context.Context, payload []byte) (any, error) {
func (session *Session) Handle(ctx context.Context, payload []byte) (result any, returnedErr error) {
var envelope requestEnvelope
if err := decodeEnvelope(payload, &envelope); err != nil {
return nil, err
}
complete := session.traceRequest(envelope, payload)
asynchronous := false
defer func() {
if !asynchronous {
complete(result, returnedErr)
}
}()
switch envelope.Type {
case "prepare-publication", "publication-media", "publication-answer", "publication-candidate", "publication-layers", "close-publication":
return session.handlePublication(envelope, payload)
@@ -106,7 +114,7 @@ func (session *Session) Handle(ctx context.Context, payload []byte) (any, error)
}
targets, err := nativecapture.ListSources(session.ctx, session.captureProcess)
if err != nil {
return operationFailure(envelope), nil
return operationFailure(envelope, err), nil
}
return sourceListResponse{
responseEnvelope: response(envelope, "source-list"),
@@ -125,6 +133,8 @@ func (session *Session) Handle(ctx context.Context, payload []byte) (any, error)
data := ""
if err == nil {
data = base64.StdEncoding.EncodeToString(preview)
} else {
operationFailure(envelope, err)
}
return sourcePreviewResponse{
responseEnvelope: response(envelope, "source-preview"),
@@ -143,6 +153,9 @@ func (session *Session) Handle(ctx context.Context, payload []byte) (any, error)
!validQualitySettings(request.Profile) {
return nil, errors.New("native start-share request is invalid")
}
slog.Debug("screener-client", "event", "native-profile-requested", "requestId", envelope.ID,
"share", diagnostics.ID(request.ShareID), "profile", nativeQualityProfile(request.Profile), "codec", request.Codec, "audio", request.Audio,
"sourceKind", request.Source.Kind, "adapterIndex", request.AdapterIndex, "encoderIndex", request.EncoderIndex)
return session.startShare(ctx, envelope, request)
case "update-share":
var request updateShareRequest
@@ -153,9 +166,13 @@ func (session *Session) Handle(ctx context.Context, payload []byte) (any, error)
return nil, errors.New("native update-share request is invalid")
}
profile := nativeQualityProfile(request.Profile)
slog.Debug("screener-client", "event", "native-profile-requested", "requestId", envelope.ID,
"share", diagnostics.ID(request.ShareID), "profile", profile)
var err error
if host := session.current(request.ShareID); host != nil {
return session.updateHost(host, envelope, request.ShareID, profile), nil
result = session.updateHost(host, envelope, request.ShareID, profile, complete)
asynchronous = result == nil
return result, nil
} else if viewer := session.currentViewer(request.ShareID); viewer != nil {
err = viewer.UpdateProfile(profile.Video)
} else {
@@ -177,22 +194,24 @@ func (session *Session) Handle(ctx context.Context, payload []byte) (any, error)
updating := session.updateDone != nil
session.mu.Unlock()
if updating {
return operationFailure(envelope), nil
return operationFailure(envelope, errors.New("native quality update is still active")), nil
}
audio := request.Audio && session.capabilities.Summary().AudioFor(
request.Source.Kind,
)
slog.Debug("screener-client", "event", "native-source-requested", "requestId", envelope.ID,
"share", diagnostics.ID(request.ShareID), "sourceKind", request.Source.Kind, "audio", audio,
"adapterIndex", request.AdapterIndex, "encoderIndex", request.EncoderIndex)
err := host.ReplaceSource(ctx, nativecapture.VideoOptions{
Target: request.Source,
AdapterIndex: request.AdapterIndex,
EncoderIndex: request.EncoderIndex,
}, audio)
if slog.Default().Enabled(session.ctx, slog.LevelDebug) {
slog.Debug("screener-client", "event", "share-source-replace", "failed", err != nil, "errorType", fmt.Sprintf("%T", err))
}
if err != nil {
return operationFailure(envelope), nil
return operationFailure(envelope, err), nil
}
slog.Debug("screener-client", "event", "native-source-applied", "requestId", envelope.ID,
"share", diagnostics.ID(request.ShareID), "sourceKind", request.Source.Kind, "audio", audio)
return shareSourceReplacedResponse{
responseEnvelope: response(envelope, "share-source-replaced"),
ShareID: request.ShareID,
@@ -312,9 +331,6 @@ func (session *Session) Handle(ctx context.Context, payload []byte) (any, error)
return nil, errors.New("native stop-share request is invalid")
}
err := session.stopShare(request.ShareID)
if slog.Default().Enabled(session.ctx, slog.LevelDebug) {
slog.Debug("screener-client", "event", "share-stop", "failed", err != nil, "errorType", fmt.Sprintf("%T", err))
}
if err != nil {
return nil, err
}
@@ -331,6 +347,8 @@ func (session *Session) Handle(ctx context.Context, payload []byte) (any, error)
return nil, errors.New("native share does not exist")
}
host.SetPaused(request.Paused)
slog.Debug("screener-client", "event", "native-share-paused", "requestId", envelope.ID,
"share", diagnostics.ID(request.ShareID), "paused", request.Paused)
return response(envelope, "share-paused"), nil
default:
return nil, errors.New("native control message is unsupported")
@@ -363,11 +381,11 @@ func (session *Session) Close() error {
return nil
}
func (session *Session) updateHost(host *nativehost.Session, request requestEnvelope, shareID string, profile nativehost.QualityProfile) any {
func (session *Session) updateHost(host *nativehost.Session, request requestEnvelope, shareID string, profile nativehost.QualityProfile, complete func(any, error)) any {
session.mu.Lock()
if session.closed || session.host != host || session.updateDone != nil {
session.mu.Unlock()
return operationFailure(request)
return operationFailure(request, errors.New("native quality update is unavailable or already active"))
}
done := make(chan struct{})
session.updateDone = done
@@ -380,6 +398,7 @@ func (session *Session) updateHost(host *nativehost.Session, request requestEnve
err = errors.New("native share stopped during quality update")
}
result := session.shareUpdateResult(request, shareID, profile, err)
complete(result, err)
close(done)
if session.closed {
session.updateDone = nil
@@ -407,14 +426,11 @@ func (session *Session) updateHost(host *nativehost.Session, request requestEnve
}
func (session *Session) shareUpdateResult(request requestEnvelope, shareID string, profile nativehost.QualityProfile, err error) any {
if slog.Default().Enabled(session.ctx, slog.LevelDebug) {
slog.Debug("screener-client", "event", "share-update", "failed", err != nil, "errorType", fmt.Sprintf("%T", err),
"width", profile.Video.Width, "height", profile.Video.Height, "fps", profile.Video.Framerate,
"bitrate", profile.Video.Bitrate, "audioBitrate", profile.AudioBitrate)
}
if err != nil {
return operationFailure(request)
return operationFailure(request, err)
}
slog.Debug("screener-client", "event", "native-profile-applied", "requestId", request.ID,
"share", diagnostics.ID(shareID), "profile", profile)
return shareUpdatedResponse{responseEnvelope: response(request, "share-updated"), ShareID: shareID}
}
@@ -422,21 +438,12 @@ func (session *Session) startShare(
ctx context.Context,
envelope requestEnvelope,
request startShareRequest,
) (result any, returnedErr error) {
) (any, error) {
profile := nativeQualityProfile(request.Profile)
codec := request.Codec
defer func() {
if slog.Default().Enabled(session.ctx, slog.LevelDebug) {
_, rejected := result.(requestFailedResponse)
slog.Debug("screener-client", "event", "share-start", "failed", returnedErr != nil || rejected, "errorType", fmt.Sprintf("%T", returnedErr),
"codec", codec, "width", profile.Video.Width, "height", profile.Video.Height,
"fps", profile.Video.Framerate, "bitrate", profile.Video.Bitrate)
}
}()
session.mu.Lock()
if session.updateDone != nil {
session.mu.Unlock()
return operationFailure(envelope), nil
return operationFailure(envelope, errors.New("native quality update is still active")), nil
}
if session.closed || session.host != nil || session.viewer != nil {
session.mu.Unlock()
@@ -472,7 +479,9 @@ func (session *Session) startShare(
}
session.host = host
session.mu.Unlock()
codec = host.Codec()
codec := host.Codec()
slog.Debug("screener-client", "event", "native-profile-applied", "requestId", envelope.ID,
"share", diagnostics.ID(request.ShareID), "profile", profile, "codec", codec, "audio", host.HasAudio())
go session.watchHost(host)
return shareStartedResponse{
responseEnvelope: response(envelope, "share-started"),
@@ -929,9 +938,37 @@ func response(request requestEnvelope, responseType string) responseEnvelope {
}
}
func operationFailure(request requestEnvelope) requestFailedResponse {
func operationFailure(request requestEnvelope, causes ...error) requestFailedResponse {
if len(causes) > 0 {
slog.Debug("screener-client", "event", "native-operation-failed", "requestId", request.ID,
"requestType", diagnostics.SafeText(request.Type), diagnostics.Error(causes[0]))
}
return requestFailedResponse{
responseEnvelope: response(request, "request-failed"),
Code: "operation-failed",
}
}
func (session *Session) traceRequest(request requestEnvelope, payload []byte) func(any, error) {
if !slog.Default().Enabled(session.ctx, slog.LevelDebug) {
return func(any, error) {}
}
// Read only identities: source titles, SDP, candidates and media never enter the log.
var identity struct {
ShareID string `json:"shareId"`
ConnectionID string `json:"connectionId"`
SourceConnectionID string `json:"sourceConnectionId"`
PublicationGeneration string `json:"publicationGeneration"`
}
_ = json.Unmarshal(payload, &identity)
logger := slog.Default().With("requestId", request.ID, "requestType", diagnostics.SafeText(request.Type),
"share", diagnostics.ID(identity.ShareID), "connection", diagnostics.ID(identity.ConnectionID),
"sourceConnection", diagnostics.ID(identity.SourceConnectionID), "publication", diagnostics.ID(identity.PublicationGeneration))
started := time.Now()
logger.Debug("screener-client", "event", "native-request-started")
return func(result any, err error) {
failure, rejected := result.(requestFailedResponse)
logger.Debug("screener-client", "event", "native-request-ended", "durationMs", time.Since(started).Milliseconds(),
"failed", err != nil || rejected, "code", failure.Code, diagnostics.Error(err))
}
}
@@ -1,10 +1,12 @@
package nativecontrol
import (
"bytes"
"context"
"encoding/binary"
"encoding/json"
"io"
"log/slog"
"os"
"path/filepath"
"strconv"
@@ -94,6 +96,12 @@ func runQuietCaptureFixture(directory string) {
func TestQuietHostUpdatePreservesControlAndCancelsCleanly(t *testing.T) {
for _, outcome := range []string{"complete", "stop", "disconnect", "first-input-timeout", "backpressure-stop"} {
t.Run(outcome, func(t *testing.T) {
var trace bytes.Buffer
if outcome == "complete" {
previous := slog.Default()
t.Cleanup(func() { slog.SetDefault(previous) })
slog.SetDefault(slog.New(slog.NewJSONHandler(&trace, &slog.HandlerOptions{Level: slog.LevelDebug})))
}
directory := t.TempDir()
t.Setenv("SCREENER_QUIET_CAPTURE_FIXTURE", directory)
executable, err := os.Executable()
@@ -239,6 +247,30 @@ func TestQuietHostUpdatePreservesControlAndCancelsCleanly(t *testing.T) {
if _, ok := responseFor("request_followup").(shareUpdatedResponse); !ok {
t.Fatal("later update could not complete")
}
_ = session.Close()
var started, ended int
decoder := json.NewDecoder(&trace)
for decoder.More() {
var record map[string]any
if err := decoder.Decode(&record); err != nil {
t.Fatal(err)
}
if record["requestId"] != "request_update" {
continue
}
switch record["event"] {
case "native-request-started":
started++
case "native-request-ended":
ended++
if record["durationMs"].(float64) < 5_000 || record["failed"] != false || record["share"] == "share_123456" {
t.Fatalf("asynchronous request lost duration, outcome or private identity handling: %+v", record)
}
}
}
if started != 1 || ended != 1 {
t.Fatalf("async update logged %d starts and %d completions", started, ended)
}
}
})
}
+29 -6
View File
@@ -5,7 +5,6 @@ import (
"context"
"encoding/json"
"errors"
"fmt"
"io"
"log/slog"
"slices"
@@ -16,6 +15,7 @@ import (
"github.com/TNTcraftHIM/Screener/internal/client/mediaedge"
"github.com/TNTcraftHIM/Screener/internal/client/nativecapture"
"github.com/TNTcraftHIM/Screener/internal/diagnostics"
"github.com/TNTcraftHIM/Screener/internal/media/encoded"
"github.com/pion/webrtc/v4"
)
@@ -122,11 +122,15 @@ func Start(parent context.Context, options Options) (*Session, error) {
}
var audioStream *nativecapture.Stream
if options.AudioEnabled {
audioStream, _ = startAudioCapture(
var audioErr error
audioStream, audioErr = startAudioCapture(
parent,
options.CaptureProcess,
options.Video.Target,
)
if audioErr != nil {
slog.DebugContext(parent, "screener-client", "event", "capture-audio-unavailable", "share", diagnostics.ID(options.ShareID), diagnostics.Error(audioErr))
}
}
ctx, cancel := context.WithCancel(parent)
session := &Session{
@@ -151,6 +155,7 @@ func Start(parent context.Context, options Options) (*Session, error) {
options.EdgeCapacity, options.Profile.AudioBitrate,
)
if audioErr != nil {
slog.DebugContext(ctx, "screener-client", "event", "capture-audio-source-failed", "share", diagnostics.ID(options.ShareID), diagnostics.Error(audioErr))
_ = audioStream.Close()
audioStream = nil
session.audioStream = nil
@@ -637,7 +642,7 @@ func (session *Session) run() {
_ = audioStream.Close()
}
if slog.Default().Enabled(session.ctx, slog.LevelDebug) {
slog.Debug("screener-client", "event", "share-ended", "failed", result != nil, "errorType", fmt.Sprintf("%T", result))
slog.Debug("screener-client", "event", "share-ended", "share", diagnostics.ID(session.shareID), "failed", result != nil, diagnostics.Error(result))
}
session.done <- result
close(session.done)
@@ -674,6 +679,8 @@ func (session *Session) runVideo() error {
}
continue
}
slog.DebugContext(session.ctx, "screener-client", "event", "capture-video-read-ended",
"share", diagnostics.ID(session.shareID), "canceled", session.ctx.Err() != nil, "eof", errors.Is(err, io.EOF), diagnostics.Error(err))
return fail(errors.New("native capture process stopped unexpectedly"))
}
if next := session.currentStream(); next != current {
@@ -735,7 +742,10 @@ func (session *Session) runVideo() error {
}
session.mu.Unlock()
slog.Debug("screener-client", "event", "capture-state", "state", status.State, "codec", status.Codec,
"width", status.Width, "height", status.Height, "fps", status.FPS)
"share", diagnostics.ID(session.shareID), "width", status.Width, "height", status.Height, "fps", status.FPS,
"hardware", status.HardwareOnly, "adapterIndex", status.AdapterIndex, "encoderIndex", status.EncoderIndex,
"adapterName", diagnostics.SafeText(status.AdapterName), "encoderName", diagnostics.SafeText(status.EncoderName),
"profileLevelId", status.ProfileLevelID, "outputs", status.Outputs)
session.emit(Event{Type: "capture-state", ShareID: session.shareID, State: status.State})
if !ready {
ready = true
@@ -780,6 +790,8 @@ func (session *Session) runVideo() error {
}
}
case nativecapture.FrameLayerUnavailable:
slog.DebugContext(session.ctx, "screener-client", "event", "capture-output-unavailable",
"share", diagnostics.ID(session.shareID), "layer", frame.Layer, "detail", diagnostics.SafeText(string(frame.Data)))
if session.source == nil {
return fail(errors.New("native output ended before its source state"))
}
@@ -853,7 +865,7 @@ func (session *Session) currentStream() *nativecapture.Stream {
func captureProfileFailure(ctx context.Context, profile nativecapture.VideoProfile, stage string, err error) error {
slog.DebugContext(ctx, "screener-client", "event", "capture-profile-rejected", "stage", stage,
"width", profile.Width, "height", profile.Height, "fps", profile.Framerate, "bitrate", profile.Bitrate)
"width", profile.Width, "height", profile.Height, "fps", profile.Framerate, "bitrate", profile.Bitrate, diagnostics.Error(err))
return err
}
@@ -908,6 +920,10 @@ func waitForCaptureProfile(
send(result{stage: "status-invalid", err: err})
return
}
slog.DebugContext(ctx, "screener-client", "event", "capture-profile-observed", "state", state.State,
"expectedCodec", codec, "actualCodec", state.Codec, "expectedProfile", profile,
"actualWidth", state.Width, "actualHeight", state.Height, "actualFPS", state.FPS,
"expectedOutputs", stream.Outputs(), "actualOutputs", state.Outputs)
if !slices.Equal(state.Outputs, stream.Outputs()) {
send(result{stage: "outputs-mismatch", err: errors.New("native capture outputs were not applied")})
return
@@ -1020,10 +1036,17 @@ func (session *Session) runAudio() {
session.mu.Lock()
paused := session.paused
session.mu.Unlock()
if paused || session.audioSource.WritePCM(frame.Data, frame.Duration) == nil {
if paused {
continue
}
err = session.audioSource.WritePCM(frame.Data, frame.Duration)
if err == nil {
continue
}
}
slog.DebugContext(session.ctx, "screener-client", "event", "capture-audio-stream-ended",
"share", diagnostics.ID(session.shareID), "frameKind", frame.Kind, "eof", errors.Is(err, io.EOF),
"canceled", session.ctx.Err() != nil, diagnostics.Error(err))
// Audio failure leaves video live. Only an explicit source replacement
// changes this owner; its buffered wake also covers an earlier commit.
for session.currentAudioStream() == current {
+4 -3
View File
@@ -277,12 +277,12 @@ func TestCandidateForRetiredEdgeIsIgnored(t *testing.T) {
}
}
func TestCaptureProfileFailureLogsFixedStageWithoutPrivateError(t *testing.T) {
func TestCaptureProfileFailurePreservesCauseWithoutCredentials(t *testing.T) {
previous := slog.Default()
t.Cleanup(func() { slog.SetDefault(previous) })
var output bytes.Buffer
slog.SetDefault(slog.New(slog.NewJSONHandler(&output, &slog.HandlerOptions{Level: slog.LevelDebug})))
failure := errors.New("private capture path and window title")
failure := errors.New("profile failed: hresult=0x887a0005 token=private-capture-token")
profile := nativecapture.VideoProfile{Width: 1280, Height: 720, Framerate: 30, Bitrate: 3_000_000}
if captureProfileFailure(t.Context(), profile, "wait-timeout", failure) != failure {
t.Fatal("diagnostic changed the failure result")
@@ -293,7 +293,8 @@ func TestCaptureProfileFailureLogsFixedStageWithoutPrivateError(t *testing.T) {
}
if record["event"] != "capture-profile-rejected" || record["stage"] != "wait-timeout" ||
record["width"] != float64(1280) || record["height"] != float64(720) ||
record["fps"] != float64(30) || record["bitrate"] != float64(3_000_000) || strings.Contains(output.String(), "private") {
record["fps"] != float64(30) || record["bitrate"] != float64(3_000_000) ||
!strings.Contains(output.String(), "0x887a0005") || strings.Contains(output.String(), "private-capture-token") {
t.Fatalf("profile diagnostic changed or leaked: %s", output.String())
}
}
+9 -1
View File
@@ -2,9 +2,11 @@ package portmapping
import (
"context"
"log/slog"
"sync"
"time"
"github.com/TNTcraftHIM/Screener/internal/diagnostics"
nat "github.com/netbirdio/go-nat"
)
@@ -95,14 +97,18 @@ func (mapping *Mapping) Close() {
}
ctx, cancel := context.WithTimeout(context.Background(), deleteTimeout)
defer cancel()
_ = gateway.DeletePortMapping(ctx, "udp", mapping.localPort)
err := gateway.DeletePortMapping(ctx, "udp", mapping.localPort)
slog.Debug("nat-mapping", "event", "released", "localPort", mapping.localPort, diagnostics.Error(err))
}
func (mapping *Mapping) discover(parent context.Context) {
defer close(mapping.ready)
ctx, cancel := context.WithTimeout(parent, attemptTimeout)
defer cancel()
started := time.Now()
gateway, err := discoverGateway(ctx)
slog.Debug("nat-mapping", "event", "discovery", "localPort", mapping.localPort,
"durationMs", time.Since(started).Milliseconds(), "available", err == nil, diagnostics.Error(err))
if err != nil {
return
}
@@ -119,6 +125,8 @@ func (mapping *Mapping) mapPortLocked(ctx context.Context) {
externalPort, err := mapping.gateway.AddPortMapping(
ctx, "udp", mapping.localPort, "Screener", leaseDuration,
)
slog.Debug("nat-mapping", "event", "mapping-result", "localPort", mapping.localPort,
"externalPort", externalPort, "leaseSeconds", leaseDuration.Seconds(), diagnostics.Error(err))
if err != nil || externalPort < 1 || externalPort > 65535 {
mapping.mapped = false
mapping.externalPort = 0
+221
View File
@@ -0,0 +1,221 @@
package diagnostics
import (
"bytes"
"context"
"crypto/sha256"
"encoding/json"
"errors"
"fmt"
"log/slog"
"regexp"
"strings"
"sync"
"syscall"
"github.com/go-logr/logr"
medialog "github.com/livekit/protocol/logger"
"github.com/pion/logging"
"go.uber.org/zap/zapcore"
)
const maxLineBytes = 64 << 10
var (
privateKey = regexp.MustCompile(`(?s)-----BEGIN [A-Z ]*PRIVATE KEY-----.*?(?:-----END [A-Z ]*PRIVATE KEY-----|$)`)
bearer = regexp.MustCompile(`(?i)\b(Bearer|Basic)\s+[A-Za-z0-9._~+/=-]+`)
secretPair = regexp.MustCompile(`(?i)((?:[a-z_-]*(?:password|passwd|pwd|ufrag|credential|token|secret|authorization|cookie)|a=ice-(?:pwd|ufrag))["']?\s*[:=]\s*["']?)([^\s,"';}]+)`)
urlCredentials = regexp.MustCompile(`(?i)(https?|wss?)://[^\s/@]+:[^\s/@]+@`)
inviteFragment = regexp.MustCompile(`(?i)(https?://[^\s#"']+)#[^\s"']*`)
diagnosticID = regexp.MustCompile(`^id-[0-9a-f]{16}$`)
iceUsernameMismatch = regexp.MustCompile(`(?i)(username[^\r\n]*?expected\()[0-9a-f]+(\)\s+actual\()[0-9a-f]+(\))`)
iceUfragExtension = regexp.MustCompile(`(?i)(\bufrag\s+)[A-Za-z0-9+/=_-]+`)
iceUnlabelledCredentials = regexp.MustCompile(`(?i)((?:get(?: all)? TCP connections by ufrag|get port of UDPAddr from ListenUDPInPortRange):)[^\r\n]*`)
remoteTrackDump = regexp.MustCompile(`(?i)got new track:[^\r\n]*`)
)
// SafeText preserves technical causes and system codes, not authentication material.
// It is deliberately not a promise to anonymize system paths or network addresses.
func SafeText(text string) string {
text = privateKey.ReplaceAllString(text, "[private key redacted]")
text = remoteTrackDump.ReplaceAllString(text, "got new track: [opaque object omitted; see RTP statistics]")
// Pinned Pion also reports ICE usernames as hex and unlabelled candidate extensions.
text = iceUsernameMismatch.ReplaceAllString(text, "${1}[redacted]${2}[redacted]${3}")
text = iceUnlabelledCredentials.ReplaceAllString(text, "${1} [redacted ICE credentials]")
text = iceUfragExtension.ReplaceAllString(text, "${1}[redacted]")
text = bearer.ReplaceAllString(text, "$1 [redacted]")
text = secretPair.ReplaceAllString(text, "${1}[redacted]")
text = urlCredentials.ReplaceAllString(text, "$1://[redacted]@")
return inviteFragment.ReplaceAllString(text, "$1#[redacted]")
}
// ID permits matching one opaque media identity across separately exported reports.
func ID(value string) string {
if value == "" || diagnosticID.MatchString(value) {
return value
}
sum := sha256.Sum256([]byte(value))
return fmt.Sprintf("id-%x", sum[:8])
}
func Error(err error) slog.Attr {
if err == nil {
return slog.Attr{}
}
fields := []any{"type", fmt.Sprintf("%T", err), "message", SafeText(err.Error())}
var code syscall.Errno
if errors.As(err, &code) {
fields = append(fields, "systemCode", uint64(code))
}
return slog.Group("error", fields...)
}
func privateField(key string) bool {
key = strings.ToLower(strings.NewReplacer("_", "", "-", "").Replace(key))
return strings.Contains(key, "password") || strings.Contains(key, "token") ||
strings.Contains(key, "secret") || strings.Contains(key, "privatekey") ||
key == "authorization" || key == "cookie" || key == "setcookie" ||
strings.HasSuffix(key, "pwd") || strings.HasSuffix(key, "ufrag") || key == "sdp" || key == "credential"
}
func identityField(key string) bool {
switch strings.ToLower(strings.NewReplacer("_", "", "-", "").Replace(key)) {
case "peerid", "shareid", "connectionid", "trackid", "streamid", "subid", "publicationgeneration", "sid", "trackidentifier", "rtpstatsid", "rtcpeerid":
return true
}
return false
}
func safeValue(key string, value any) any {
if privateField(key) {
return "[redacted]"
}
switch value := value.(type) {
case string:
if identityField(key) {
return ID(value)
}
return SafeText(value)
case map[string]any:
for name, field := range value {
value[name] = safeValue(name, field)
}
case []any:
for i, field := range value {
value[i] = safeValue("", field)
}
}
return value
}
// ReplaceAttr applies the same secret policy to application and dependency records.
func ReplaceAttr(_ []string, attr slog.Attr) slog.Attr {
attr.Value = attr.Value.Resolve()
if privateField(attr.Key) {
return slog.String(attr.Key, "[redacted]")
}
if attr.Value.Kind() == slog.KindString {
return slog.Any(attr.Key, safeValue(attr.Key, attr.Value.String()))
}
if attr.Value.Kind() == slog.KindAny {
if err, ok := attr.Value.Any().(error); ok {
return slog.String(attr.Key, SafeText(err.Error()))
}
value := attr.Value.Any()
// LiveKit's RTP/BWE wrappers expose Zap fields, not JSON-visible struct fields.
switch object := value.(type) {
case zapcore.ObjectMarshaler:
encoder := zapcore.NewMapObjectEncoder()
if err := object.MarshalLogObject(encoder); err != nil {
return slog.String(attr.Key, "[diagnostic field failed: "+SafeText(err.Error())+"]")
}
value = encoder.Fields
case zapcore.ArrayMarshaler:
encoder := zapcore.NewMapObjectEncoder()
if err := encoder.AddArray("items", object); err != nil {
return slog.String(attr.Key, "[diagnostic field failed: "+SafeText(err.Error())+"]")
}
value = encoder.Fields["items"]
}
data, err := json.Marshal(value)
if err != nil {
return slog.String(attr.Key, "[diagnostic value unavailable]")
}
value = nil
decoder := json.NewDecoder(bytes.NewReader(data))
decoder.UseNumber()
if decoder.Decode(&value) == nil {
return slog.Any(attr.Key, safeValue(attr.Key, value))
}
}
return attr
}
// LineWriter turns dependency stderr into bounded records without writing on the TUI.
type LineWriter struct {
mu sync.Mutex
logger *slog.Logger
line []byte
omitted int
privateKey bool
}
func Writer(scope string) *LineWriter {
return &LineWriter{logger: slog.Default().With("library", scope)}
}
func (writer *LineWriter) Write(data []byte) (int, error) {
writer.mu.Lock()
defer writer.mu.Unlock()
for _, char := range data {
if char == '\n' {
writer.flush()
} else if len(writer.line) < maxLineBytes {
writer.line = append(writer.line, char)
} else {
writer.omitted++
}
}
return len(data), nil
}
func (writer *LineWriter) flush() {
line := strings.TrimSuffix(string(writer.line), "\r")
if strings.Contains(line, "-----BEGIN ") && strings.Contains(line, "PRIVATE KEY-----") {
writer.privateKey = true
}
if writer.privateKey {
writer.privateKey = !(strings.Contains(line, "-----END ") && strings.Contains(line, "PRIVATE KEY-----"))
line = "[private key redacted]"
}
if line != "" || writer.omitted > 0 {
writer.logger.Debug("dependency", "line", SafeText(line), "omittedBytes", writer.omitted)
}
writer.line = writer.line[:0]
writer.omitted = 0
}
func (writer *LineWriter) Close() error {
writer.mu.Lock()
defer writer.mu.Unlock()
writer.flush()
return nil
}
func PionLoggerFactory(fields ...any) logging.LoggerFactory {
factory := logging.NewDefaultLoggerFactory()
if slog.Default().Enabled(context.Background(), slog.LevelDebug) {
factory.DefaultLogLevel = logging.LogLevelDebug
writer := Writer("pion")
writer.logger = writer.logger.With(fields...)
factory.Writer = writer
}
return factory
}
func MediaLogger(scope string) medialog.Logger {
if !slog.Default().Enabled(context.Background(), slog.LevelDebug) {
return medialog.GetDiscardLogger()
}
return medialog.LogRLogger(logr.FromSlogHandler(slog.Default().With("library", "livekit", "scope", scope).Handler()))
}
+134 -47
View File
@@ -3,6 +3,8 @@ package diagnostics
import (
"archive/zip"
"bytes"
"crypto/sha256"
"encoding/json"
"errors"
"fmt"
@@ -11,6 +13,7 @@ import (
"os"
"path/filepath"
"runtime"
"runtime/debug"
"runtime/pprof"
"sync"
"time"
@@ -25,6 +28,8 @@ type Recorder struct {
component string
revision string
started time.Time
context map[string]any
closed bool
}
// Open appends to the component's current log, retaining one rotated backup.
@@ -57,9 +62,10 @@ func Open(directory, component, revision string) (*Recorder, error) {
if err != nil {
return nil, errors.Join(err, file.Close())
}
log := &rotatingLog{file: file, path: path, size: info.Size()}
_, backupErr := os.Stat(path + ".1")
log := &rotatingLog{file: file, path: path, size: info.Size(), preexisting: info.Size() > 0 || backupErr == nil}
return &Recorder{
log: log, logger: slog.New(slog.NewJSONHandler(log, &slog.HandlerOptions{Level: slog.LevelDebug})),
log: log, logger: slog.New(slog.NewJSONHandler(log, &slog.HandlerOptions{Level: slog.LevelDebug, ReplaceAttr: ReplaceAttr})),
component: component, revision: revision, started: time.Now(),
}, nil
}
@@ -67,16 +73,54 @@ func Open(directory, component, revision string) (*Recorder, error) {
func (r *Recorder) Logger() *slog.Logger { return r.logger }
func (r *Recorder) LogPath() string { return r.log.path }
// Export samples this process without forcing GC or collecting raw memory,
// configuration, environment variables, media, or arbitrary directory contents.
// Context snapshots explicitly selected startup facts; it never reads environment files.
func (r *Recorder) Context(name string, value any) {
r.exportMu.Lock()
defer r.exportMu.Unlock()
if r.context == nil {
r.context = make(map[string]any)
}
r.context[name] = ReplaceAttr(nil, slog.Any(name, value)).Value.Any()
}
// Binary records only the identity of an explicitly selected runtime executable.
func (r *Recorder) Binary(name, path string) {
if path == "" {
return
}
identity := map[string]any{"name": filepath.Base(path)}
file, err := os.Open(path)
if err == nil {
hash := sha256.New()
var size int64
size, err = io.Copy(hash, file)
_ = file.Close()
if err == nil {
identity["bytes"], identity["sha256"] = size, fmt.Sprintf("%x", hash.Sum(nil))
}
}
if err != nil {
identity["error"] = SafeText(err.Error())
}
r.Context(name, identity)
}
// Export retains useful evidence even when an optional collector fails. It never
// forces GC or collects raw process memory, media or arbitrary directory contents.
func (r *Recorder) Export() (path string, returnedErr error) {
r.exportMu.Lock()
defer r.exportMu.Unlock()
logs, err := r.log.snapshot()
if err != nil {
return "", fmt.Errorf("snapshot diagnostics logs: %w", err)
if r.closed {
return "", os.ErrClosed
}
now := time.Now()
reportID := fmt.Sprintf("%d-%d", os.Getpid(), now.UnixNano())
r.logger.Debug("diagnostic-report", "reportId", reportID)
logs, logErr := r.log.snapshot()
collectorErrors := []string{}
if logErr != nil {
collectorErrors = append(collectorErrors, SafeText(logErr.Error()))
}
var memory runtime.MemStats
runtime.ReadMemStats(&memory)
file, err := os.CreateTemp(filepath.Dir(r.LogPath()), r.component+"-diagnostics-"+now.UTC().Format("20060102T150405Z")+"-*.zip")
@@ -91,33 +135,33 @@ func (r *Recorder) Export() (path string, returnedErr error) {
path = ""
}
}()
for _, log := range logs {
entry, err := archive.Create(log.name)
files := []string{}
add := func(name string, data []byte) error {
entry, err := archive.Create(name)
if err != nil {
return "", err
return err
}
if _, err := entry.Write(log.data); err != nil {
if _, err := entry.Write(data); err != nil {
return err
}
files = append(files, name)
return nil
}
for _, log := range logs {
if err := add(log.name, log.data); err != nil {
return "", err
}
}
metadata := struct {
Component string `json:"component"`
Revision string `json:"revision"`
GOOS string `json:"goos"`
GOARCH string `json:"goarch"`
GoVersion string `json:"goVersion"`
CollectedAt time.Time `json:"collectedAt"`
UptimeSeconds float64 `json:"uptimeSeconds"`
}{r.component, r.revision, runtime.GOOS, runtime.GOARCH, runtime.Version(), now.UTC(), now.Sub(r.started).Seconds()}
for _, item := range []struct {
name string
value any
}{{"metadata.json", metadata}, {"memory.json", memory}} {
entry, err := archive.Create(item.name)
}{{"context.json", r.context}, {"memory.json", memory}} {
data, err := json.MarshalIndent(item.value, "", " ")
if err != nil {
return "", err
collectorErrors = append(collectorErrors, item.name+": "+SafeText(err.Error()))
continue
}
if err := json.NewEncoder(entry).Encode(item.value); err != nil {
if err := add(item.name, data); err != nil {
return "", err
}
}
@@ -126,13 +170,43 @@ func (r *Recorder) Export() (path string, returnedErr error) {
file string
debug int
}{{"heap", "heap.pprof", 0}, {"goroutine", "goroutines.txt", 1}} {
entry, err := archive.Create(profile.file)
if err != nil {
var data bytes.Buffer
if err := pprof.Lookup(profile.name).WriteTo(&boundedWriter{writer: &data, remaining: maxFileBytes}, profile.debug); err != nil {
collectorErrors = append(collectorErrors, profile.file+": "+SafeText(err.Error()))
continue
}
if err := add(profile.file, data.Bytes()); err != nil {
return "", err
}
if err := pprof.Lookup(profile.name).WriteTo(&boundedWriter{writer: entry, remaining: maxFileBytes}, profile.debug); err != nil {
return "", fmt.Errorf("write %s profile: %w", profile.name, err)
}
}
if err := add("README.txt", []byte("Screener diagnostic report / Screener 诊断报告\n\n"+
"Local opt-in report. Review before sharing: technical identifiers, paths and network/system details may remain.\n"+
"Credentials are filtered; raw media and process-memory contents are not collected. heap.pprof is an allocation profile.\n"+
"metadata.json lists retained files and collector failures. Rotated logs are a bounded history, not the entire session.\n\n"+
"本报告由本机主动导出。分享前请检查:可能含技术标识、路径和网络/系统信息。\n"+
"凭据已过滤;不采集原始媒体或进程内存内容。heap.pprof 是分配统计。\n"+
"metadata.json 记录文件及采集失败;轮转日志只保留有限历史。\n")); err != nil {
return "", err
}
retention := r.log.retention()
metadata := map[string]any{
"component": r.component, "revision": r.revision, "goos": runtime.GOOS,
"goarch": runtime.GOARCH, "goVersion": runtime.Version(), "collectedAt": now.UTC(),
"startedAt": r.started.UTC(), "uptimeSeconds": now.Sub(r.started).Seconds(),
"reportId": reportID, "pid": os.Getpid(), "cpuCount": runtime.NumCPU(),
"gomaxprocs": runtime.GOMAXPROCS(0), "goroutineCount": runtime.NumGoroutine(),
"files": append(files, "metadata.json"), "collectorErrors": collectorErrors,
"partial": len(collectorErrors) > 0 || retention["earlierHistoryMayBeMissing"] == true, "logRetention": retention,
}
if build, ok := debug.ReadBuildInfo(); ok {
metadata["mainModule"], metadata["dependencies"] = build.Main, build.Deps
}
data, err := json.MarshalIndent(metadata, "", " ")
if err != nil {
return "", err
}
if err := add("metadata.json", data); err != nil {
return "", err
}
return file.Name(), nil
}
@@ -141,6 +215,7 @@ func (r *Recorder) Export() (path string, returnedErr error) {
func (r *Recorder) Close() error {
r.exportMu.Lock()
defer r.exportMu.Unlock()
r.closed = true
r.log.mu.Lock()
defer r.log.mu.Unlock()
if r.log.file != nil {
@@ -151,11 +226,13 @@ func (r *Recorder) Close() error {
}
type rotatingLog struct {
mu sync.Mutex
file *os.File
path string
size int64
err error
mu sync.Mutex
file *os.File
path string
size int64
err error
rotations uint64
preexisting bool
}
func (l *rotatingLog) Write(data []byte) (n int, err error) {
@@ -197,9 +274,20 @@ func (l *rotatingLog) rotate() error {
}
l.file, err = os.OpenFile(l.path, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0600)
l.size = 0
if err == nil {
l.rotations++
}
return err
}
func (l *rotatingLog) retention() map[string]any {
l.mu.Lock()
defer l.mu.Unlock()
return map[string]any{"fileBytesLimit": maxFileBytes, "fileCountLimit": 2,
"rotationsThisProcess": l.rotations, "preexistingHistory": l.preexisting,
"earlierHistoryMayBeMissing": l.preexisting || l.rotations > 0}
}
type logSnapshot struct {
name string
data []byte
@@ -208,38 +296,37 @@ type logSnapshot struct {
func (l *rotatingLog) snapshot() ([]logSnapshot, error) {
l.mu.Lock()
defer l.mu.Unlock()
if l.err != nil {
return nil, l.err
}
if l.file == nil {
return nil, os.ErrClosed
}
if err := l.file.Sync(); err != nil {
return nil, err
issues := []error{l.err}
if l.file != nil {
issues = append(issues, l.file.Sync())
}
// ponytail: at most 16 MiB copied under the log lock; compression runs outside it.
var logs []logSnapshot
for _, path := range []string{l.path + ".1", l.path} {
if err := checkLogFile(path); err != nil {
return nil, err
issues = append(issues, err)
continue
}
file, err := os.Open(path)
if errors.Is(err, os.ErrNotExist) && path != l.path {
continue
}
if err != nil {
return nil, err
issues = append(issues, err)
continue
}
data, readErr := io.ReadAll(io.LimitReader(file, maxFileBytes+1))
if err := errors.Join(readErr, file.Close()); err != nil {
return nil, err
issues = append(issues, err)
continue
}
if len(data) > maxFileBytes {
return nil, errors.New("diagnostics log exceeds 8 MiB")
issues = append(issues, errors.New("diagnostics log exceeds 8 MiB"))
continue
}
logs = append(logs, logSnapshot{filepath.Base(path), data})
}
return logs, nil
return logs, errors.Join(issues...)
}
func checkLogFile(path string) error {
+86 -4
View File
@@ -6,12 +6,16 @@ import (
"compress/gzip"
"encoding/json"
"errors"
"fmt"
"go.uber.org/zap/zapcore"
"io"
"log/slog"
"os"
"path/filepath"
"runtime"
"strings"
"sync"
"syscall"
"testing"
)
@@ -52,7 +56,7 @@ func TestRecorderRotationAndExport(t *testing.T) {
t.Fatal(err)
}
defer archive.Close()
expected := map[string]bool{"client.log": false, "client.log.1": false, "metadata.json": false, "memory.json": false, "heap.pprof": false, "goroutines.txt": false}
expected := map[string]bool{"client.log": false, "client.log.1": false, "metadata.json": false, "memory.json": false, "heap.pprof": false, "goroutines.txt": false, "context.json": false, "README.txt": false}
for _, file := range archive.File {
if _, ok := expected[file.Name]; !ok {
t.Fatalf("unexpected archive entry: %s", file.Name)
@@ -79,7 +83,7 @@ func TestRecorderRotationAndExport(t *testing.T) {
if err := json.Unmarshal(data, &metadata); err != nil {
t.Fatal(err)
}
if metadata["revision"] != "test-revision" || metadata["component"] != "client" || metadata["goos"] != runtime.GOOS || len(metadata) != 7 {
if metadata["revision"] != "test-revision" || metadata["component"] != "client" || metadata["goos"] != runtime.GOOS || metadata["reportId"] == "" || metadata["partial"] != true {
t.Fatalf("unexpected metadata: %v", metadata)
}
case "memory.json":
@@ -114,6 +118,15 @@ func TestRecorderRotationAndExport(t *testing.T) {
if err != nil || second == archivePath {
t.Fatalf("export must have a unique path: %q, %v", second, err)
}
_ = recorder.Close()
reopened, err := Open(directory, "client", "next-process")
if err != nil {
t.Fatal(err)
}
defer reopened.Close()
if reopened.log.retention()["earlierHistoryMayBeMissing"] != true {
t.Fatal("restart incorrectly claimed complete prior history")
}
}
func TestRecorderCloseAndFailures(t *testing.T) {
@@ -172,8 +185,26 @@ func TestRecorderCloseAndFailures(t *testing.T) {
t.Fatal(err)
}
failing.Logger().Error("write fails")
if _, err := failing.Export(); !errors.Is(err, os.ErrClosed) {
t.Fatalf("export hid a log write failure: %v", err)
partial, err := failing.Export()
if err != nil {
t.Fatalf("one failed log writer discarded usable runtime evidence: %v", err)
}
archive, err := zip.OpenReader(partial)
if err != nil {
t.Fatal(err)
}
defer archive.Close()
entry, err := archive.Open("metadata.json")
if err != nil {
t.Fatal(err)
}
var metadata map[string]any
if err = json.NewDecoder(entry).Decode(&metadata); err != nil {
t.Fatal(err)
}
_ = entry.Close()
if metadata["partial"] != true || len(metadata["collectorErrors"].([]any)) == 0 {
t.Fatalf("partial export hid failed collection: %v", metadata)
}
if err := failing.Close(); !errors.Is(err, os.ErrClosed) {
t.Fatalf("close hid a log write failure: %v", err)
@@ -182,3 +213,54 @@ func TestRecorderCloseAndFailures(t *testing.T) {
t.Fatalf("profile output limit: %v", err)
}
}
func TestDependencyDiagnosticsPreserveCausesWithoutSecrets(t *testing.T) {
recorder, err := Open(t.TempDir(), "client", "test")
if err != nil {
t.Fatal(err)
}
defer recorder.Close()
previous := slog.Default()
slog.SetDefault(recorder.Logger())
defer slog.SetDefault(previous)
const secret = "must-not-appear-in-report"
recorder.Logger().Error("operation", Error(fmt.Errorf("interface enumeration: %w", syscall.EAFNOSUPPORT)),
"requestId", "request-17", "nested", map[string]any{"instanceToken": secret, "state": "checking"})
PionLoggerFactory().NewLogger("ice").Debugf("Started agent: remoteUfrag: %q, remotePwd: %q", secret, secret)
PionLoggerFactory().NewLogger("ice").Warnf("mismatch username expected(%x) actual(%x)", secret, secret)
PionLoggerFactory().NewLogger("pc").Errorf("dropping candidate with ufrag %s because it doesn't match", secret)
PionLoggerFactory().NewLogger("ice").Warnf("Failed to get TCP connections by ufrag: tcp4 127.0.0.1:1 %s", secret)
PionLoggerFactory().NewLogger("pc").Debugf("got new track: &{id:%s streamID:private-track-identity peeked:[1 2]}", secret)
writer := Writer("capture")
for _, part := range []string{"stage=device-open\nAuthorization: Bear", "er " + secret + "\n",
"-----BEGIN PRIVATE KEY-----\n", secret + "\n-----END PRIVATE KEY-----\n",
"https://example.test/r/1234#v=" + secret + "\n", "hresult=0x80070005"} {
if _, err := writer.Write([]byte(part)); err != nil {
t.Fatal(err)
}
}
_ = writer.Close()
MediaLogger("test").Warnw("media initialization", fmt.Errorf("network adapter unavailable"), "trackId", "private-track-identity", "stats", diagnosticObject{value: secret})
data, err := os.ReadFile(recorder.LogPath())
if err != nil {
t.Fatal(err)
}
for _, forbidden := range []string{secret, fmt.Sprintf("%x", secret), "private-track-identity"} {
if bytes.Contains(data, []byte(forbidden)) {
t.Fatalf("sensitive value retained: %q", forbidden)
}
}
for _, useful := range []string{"request-17", "interface enumeration", "systemCode", "device-open", "0x80070005", "network adapter unavailable", "checking", `"jitter":12`} {
if !bytes.Contains(data, []byte(useful)) {
t.Fatalf("missing diagnostic context: %q", useful)
}
}
}
type diagnosticObject struct{ value string }
func (object diagnosticObject) MarshalLogObject(encoder zapcore.ObjectEncoder) error {
encoder.AddInt("jitter", 12)
encoder.AddString("password", object.value)
return nil
}
+16 -5
View File
@@ -1,14 +1,17 @@
package forwarding
import (
"context"
"crypto/rand"
"errors"
"io"
"log/slog"
"strconv"
"sync"
"sync/atomic"
"time"
"github.com/TNTcraftHIM/Screener/internal/diagnostics"
"github.com/livekit/livekit-server/pkg/sfu"
"github.com/livekit/livekit-server/pkg/sfu/buffer"
"github.com/livekit/livekit-server/pkg/sfu/bwe"
@@ -17,7 +20,6 @@ import (
"github.com/livekit/livekit-server/pkg/sfu/pacer"
"github.com/livekit/livekit-server/pkg/sfu/streamallocator"
"github.com/livekit/protocol/livekit"
"github.com/livekit/protocol/logger"
"github.com/pion/interceptor"
"github.com/pion/rtcp"
"github.com/pion/rtp"
@@ -59,7 +61,7 @@ func NewPublication(options TransportOptions) (_ *Publication, err error) {
_ = publication.Close()
}
}()
log := logger.GetDiscardLogger()
log := diagnostics.MediaLogger("publication").WithValues("connectionId", diagnostics.ID(options.ConnectionID))
publication.bandwidth = &publicationBWE{SendSideBWE: sendsidebwe.NewSendSideBWE(sendsidebwe.SendSideBWEParams{
Config: sendsidebwe.DefaultSendSideBWEConfig, Logger: log,
})}
@@ -101,6 +103,9 @@ func NewPublication(options TransportOptions) (_ *Publication, err error) {
}
factory := buffer.NewFactoryOfBufferFactory(options.Source.maxPackets, buffer.InitPacketBufferSizeAudio).CreateBufferFactory()
settings := options.Settings
if slog.Default().Enabled(context.Background(), slog.LevelDebug) {
settings.LoggerFactory = diagnostics.PionLoggerFactory("connectionId", diagnostics.ID(options.ConnectionID))
}
settings.BufferFactory = func(kind packetio.BufferPacketType, ssrc uint32) io.ReadWriteCloser {
if kind == packetio.RTCPBufferPacket {
if reader := factory.GetRTCPReader(ssrc); reader != nil {
@@ -350,9 +355,15 @@ func (publication *Publication) Close() error {
return publication.closeErr
}
func (*Publication) OnBindAndConnected() {}
func (*Publication) OnStatsUpdate(*livekit.AnalyticsStat) {}
func (*Publication) OnMaxSubscribedLayerChanged(int32) {}
func (*Publication) OnBindAndConnected() {}
func (publication *Publication) OnStatsUpdate(stats *livekit.AnalyticsStat) {
if slog.Default().Enabled(context.Background(), slog.LevelDebug) {
slog.Debug("media-stats", "scope", "publication", "rtcPeerId", diagnostics.ID(publication.PC.ID()),
"rtp", stats, "egress", publication.pacer.stats(), "targetBitrate", publication.bandwidth.target.Load(),
"pendingPackets", publication.pacer.pendingCount(), "packetCapacity", publication.pacer.limit)
}
}
func (*Publication) OnMaxSubscribedLayerChanged(int32) {}
func (publication *Publication) OnRttUpdate(rtt uint32) {
publication.bandwidth.UpdateRTT(float64(rtt) / 1000)
}
+3 -3
View File
@@ -9,12 +9,12 @@ import (
"sync/atomic"
"time"
"github.com/TNTcraftHIM/Screener/internal/diagnostics"
"github.com/TNTcraftHIM/Screener/internal/media/encoded"
"github.com/livekit/livekit-server/pkg/sfu"
"github.com/livekit/livekit-server/pkg/sfu/buffer"
"github.com/livekit/mediatransportutil"
"github.com/livekit/protocol/livekit"
"github.com/livekit/protocol/logger"
"github.com/livekit/protocol/utils"
"github.com/livekit/protocol/utils/mono"
"github.com/pion/rtcp"
@@ -82,7 +82,7 @@ func NewSource(options SourceOptions) (*Source, error) {
ReceiverBase: sfu.NewReceiverBase(sfu.ReceiverBaseParams{
TrackID: livekit.TrackID(options.ID), StreamID: options.StreamID,
Kind: webrtc.RTPCodecTypeVideo, Codec: options.Codec,
HeaderExtensions: canonicalHeaderExtensions(options.HeaderExtensions), Logger: logger.GetDiscardLogger(),
HeaderExtensions: canonicalHeaderExtensions(options.HeaderExtensions), Logger: diagnostics.MediaLogger("source").WithValues("trackId", diagnostics.ID(options.ID)),
StreamTrackerManagerConfig: sfu.DefaultStreamTrackerManagerConfig,
}, info, sfu.ReceiverCodecStateNormal),
buffers: make([]*buffer.Buffer, len(options.Formats)),
@@ -209,7 +209,7 @@ func (source *Source) BindLayer(layer int, ssrc uint32, parameters webrtc.RTPPar
}
}
input := buffer.NewBuffer(ssrc, source.maxPackets, buffer.InitPacketBufferSizeAudio)
input.SetLogger(logger.GetDiscardLogger())
input.SetLogger(diagnostics.MediaLogger("rtp-buffer").WithValues("trackId", diagnostics.ID(string(source.TrackID()))))
if err := input.Bind(parameters, codec.RTPCodecCapability, int(source.TrackInfo().Layers[layer].Bitrate)); err != nil {
_ = input.Close()
return err
+23 -3
View File
@@ -1,13 +1,16 @@
package forwarding
import (
"context"
"errors"
"io"
"log/slog"
"slices"
"sync"
"sync/atomic"
"time"
"github.com/TNTcraftHIM/Screener/internal/diagnostics"
"github.com/livekit/livekit-server/pkg/sfu"
"github.com/livekit/livekit-server/pkg/sfu/buffer"
"github.com/livekit/livekit-server/pkg/sfu/bwe"
@@ -90,6 +93,9 @@ func NewTransport(options TransportOptions) (_ *Transport, err error) {
}
factory := buffer.NewFactoryOfBufferFactory(options.Source.maxPackets, buffer.InitPacketBufferSizeAudio).CreateBufferFactory()
settings := options.Settings
if slog.Default().Enabled(context.Background(), slog.LevelDebug) {
settings.LoggerFactory = diagnostics.PionLoggerFactory("connectionId", diagnostics.ID(options.ConnectionID))
}
settings.BufferFactory = func(kind packetio.BufferPacketType, ssrc uint32) io.ReadWriteCloser {
if kind == packetio.RTCPBufferPacket {
if reader := factory.GetRTCPReader(ssrc); reader != nil {
@@ -122,7 +128,9 @@ func NewTransport(options TransportOptions) (_ *Transport, err error) {
if err != nil {
return nil, err
}
log := logger.GetDiscardLogger()
log := diagnostics.MediaLogger("transport").WithValues("connectionId", diagnostics.ID(options.ConnectionID))
log.Debugw("transport-created", "rtcPeerId", diagnostics.ID(transport.PC.ID()), "codec", codec.MimeType,
"initialBitrate", options.InitialBitrate, "packetCapacity", options.Source.maxPackets)
transport.estimator = sendsidebwe.NewSendSideBWE(sendsidebwe.SendSideBWEParams{
Config: sendsidebwe.DefaultSendSideBWEConfig, Logger: log,
})
@@ -370,8 +378,14 @@ func (*Transport) BWEType() bwe.BWEType
func (*Transport) IsSubscribeMutable(*sfu.DownTrack) bool { return true }
func (transport *Transport) OnSubscriptionChanged(*sfu.DownTrack) { transport.Output.Reconcile() }
func (*Transport) OnBindAndConnected() {}
func (*Transport) OnStatsUpdate(*livekit.AnalyticsStat) {}
func (*Transport) OnMaxSubscribedLayerChanged(int32) {}
func (transport *Transport) OnStatsUpdate(stats *livekit.AnalyticsStat) {
if slog.Default().Enabled(context.Background(), slog.LevelDebug) {
slog.Debug("media-stats", "scope", "forwarding", "rtcPeerId", diagnostics.ID(transport.PC.ID()),
"rtp", stats, "egress", transport.Egress(), "targetBitrate", transport.target.Load(),
"pendingPackets", transport.pacer.pendingCount(), "packetCapacity", transport.pacer.limit)
}
}
func (*Transport) OnMaxSubscribedLayerChanged(int32) {}
func (transport *Transport) OnRttUpdate(rtt uint32) {
transport.mu.Lock()
defer transport.mu.Unlock()
@@ -603,6 +617,12 @@ func (queue *boundedPacer) stats() EgressStats {
return EgressStats{Packets: queue.packets.Load(), RTPBytes: queue.bytes.Load(), DroppedPackets: queue.dropped.Load()}
}
func (queue *boundedPacer) pendingCount() int {
queue.mu.Lock()
defer queue.mu.Unlock()
return len(queue.pending)
}
type pacedPacket struct {
owner *boundedPacer
packet *pacer.Packet
+5 -2
View File
@@ -30,6 +30,7 @@ import (
"sync/atomic"
"time"
"github.com/TNTcraftHIM/Screener/internal/diagnostics"
"github.com/TNTcraftHIM/Screener/internal/server/config"
"github.com/TNTcraftHIM/Screener/internal/server/room"
"github.com/TNTcraftHIM/Screener/internal/server/sfu"
@@ -265,8 +266,9 @@ func (s *Server) start(ctx context.Context) (int, error) {
_ = s.stopServing(ctx)
return 0, fmt.Errorf("Screener SFU listener failed: %w", listenErr)
}
s.mediaMux = ice.NewUDPMuxDefault(ice.UDPMuxParams{UDPConn: connection})
settings := webrtc.SettingEngine{}
factory := diagnostics.PionLoggerFactory()
s.mediaMux = ice.NewUDPMuxDefault(ice.UDPMuxParams{UDPConn: connection, Logger: factory.NewLogger("sfu-udp")})
settings := webrtc.SettingEngine{LoggerFactory: factory}
settings.SetNetworkTypes([]webrtc.NetworkType{webrtc.NetworkTypeUDP4})
settings.SetICEUDPMux(s.mediaMux)
settings.SetIncludeLoopbackCandidate(net.ParseIP(configuration.ListenHost).IsLoopback())
@@ -290,6 +292,7 @@ func (s *Server) start(ctx context.Context) (int, error) {
// causes; report it rather than serving nothing in silence.
if err := s.httpServer.Serve(listener); !errors.Is(err, http.ErrServerClosed) {
s.logger.Error("Screener HTTP server stopped unexpectedly", "errorType", fmt.Sprintf("%T", err))
s.logger.Debug("http-listener-failed", diagnostics.Error(err))
}
}()
port := listener.Addr().(*net.TCPAddr).Port