From 112d6fc18bfecdf1383312ced26cd5504d8fc48a Mon Sep 17 00:00:00 2001 From: David Zhao Date: Thu, 29 Dec 2022 23:47:36 -0800 Subject: [PATCH] Reduced log verbosity for pieces that are stable (#1274) --- pkg/rtc/participant.go | 16 ++++++++-------- pkg/rtc/signalhandler.go | 2 -- pkg/rtc/subscribedtrack.go | 25 ++++++++++++++++++++----- pkg/rtc/transport.go | 2 +- pkg/rtc/uptrackmanager.go | 6 ++---- pkg/service/roommanager.go | 4 ++-- pkg/sfu/downtrack.go | 4 ++-- pkg/sfu/forwarder.go | 4 ++-- 8 files changed, 37 insertions(+), 26 deletions(-) diff --git a/pkg/rtc/participant.go b/pkg/rtc/participant.go index 1694ac2b5..844947973 100644 --- a/pkg/rtc/participant.go +++ b/pkg/rtc/participant.go @@ -448,7 +448,7 @@ func (p *ParticipantImpl) OnClaimsChanged(callback func(types.LocalParticipant)) // HandleOffer an offer from remote participant, used when clients make the initial connection func (p *ParticipantImpl) HandleOffer(offer webrtc.SessionDescription) { - p.params.Logger.Infow("received offer", "transport", livekit.SignalTarget_PUBLISHER) + p.params.Logger.Debugw("received offer", "transport", livekit.SignalTarget_PUBLISHER) shouldPend := false if p.MigrateState() == types.MigrateStateInit { shouldPend = true @@ -462,7 +462,7 @@ func (p *ParticipantImpl) HandleOffer(offer webrtc.SessionDescription) { // HandleAnswer handles a client answer response, with subscriber PC, server initiates the // offer and client answers func (p *ParticipantImpl) HandleAnswer(answer webrtc.SessionDescription) { - p.params.Logger.Infow("received answer", "transport", livekit.SignalTarget_SUBSCRIBER) + p.params.Logger.Debugw("received answer", "transport", livekit.SignalTarget_SUBSCRIBER) /* from server received join request to client answer * 1. server send join response & offer @@ -476,7 +476,7 @@ func (p *ParticipantImpl) HandleAnswer(answer webrtc.SessionDescription) { } func (p *ParticipantImpl) onPublisherAnswer(answer webrtc.SessionDescription) error { - p.params.Logger.Infow("sending answer", "transport", livekit.SignalTarget_PUBLISHER) + p.params.Logger.Debugw("sending answer", "transport", livekit.SignalTarget_PUBLISHER) answer = p.configurePublisherAnswer(answer) if err := p.writeMessage(&livekit.SignalResponse{ Message: &livekit.SignalResponse_Answer{ @@ -937,14 +937,14 @@ func (p *ParticipantImpl) AddSubscribedTrack(subTrack types.SubscribedTrack, sou if v, ok := p.trackPublisherVersion[subTrack.ID()]; ok && v > subTrack.PublisherVersion() { p.supervisor.SetSubscribedTrack(subTrack.ID(), subTrack, sourceTrack) p.lock.Unlock() - p.params.Logger.Infow("ignoring add subscribedTrack from older version", + p.params.Logger.Debugw("ignoring add subscribedTrack from older version", "current", v, "requesting", subTrack.PublisherVersion(), "trackID", subTrack.ID(), ) return } - p.params.Logger.Infow("added subscribedTrack", + p.params.Logger.Debugw("added subscribedTrack", "publisherID", subTrack.PublisherID(), "publisherIdentity", subTrack.PublisherIdentity(), "trackID", subTrack.ID()) @@ -985,14 +985,14 @@ func (p *ParticipantImpl) RemoveSubscribedTrack(subTrack types.SubscribedTrack, if v, ok := p.trackPublisherVersion[subTrack.ID()]; ok && v > subTrack.PublisherVersion() { p.supervisor.ClearSubscribedTrack(subTrack.ID(), subTrack, sourceTrack) p.lock.Unlock() - p.params.Logger.Infow("ignoring remove subscribedTrack from older version", + p.params.Logger.Debugw("ignoring remove subscribedTrack from older version", "current", v, "requesting", subTrack.PublisherVersion(), "trackID", subTrack.ID(), ) return } - p.params.Logger.Infow("removed subscribedTrack", + p.params.Logger.Debugw("removed subscribedTrack", "publisherID", subTrack.PublisherID(), "publisherIdentity", subTrack.PublisherIdentity(), "trackID", subTrack.ID(), "kind", subTrack.DownTrack().Kind()) @@ -1198,7 +1198,7 @@ func (p *ParticipantImpl) updateState(state livekit.ParticipantInfo_State) { // when the server has an offer for participant func (p *ParticipantImpl) onSubscriberOffer(offer webrtc.SessionDescription) error { - p.params.Logger.Infow("sending offer", "transport", livekit.SignalTarget_SUBSCRIBER) + p.params.Logger.Debugw("sending offer", "transport", livekit.SignalTarget_SUBSCRIBER) return p.writeMessage(&livekit.SignalResponse{ Message: &livekit.SignalResponse_Offer{ Offer: ToProtoSessionDescription(offer), diff --git a/pkg/rtc/signalhandler.go b/pkg/rtc/signalhandler.go index c4dad5661..e4a441494 100644 --- a/pkg/rtc/signalhandler.go +++ b/pkg/rtc/signalhandler.go @@ -57,8 +57,6 @@ func HandleParticipantSignal(room types.Room, participant types.LocalParticipant pLogger.Errorw("failed to update subscribed track settings", err, "trackID", sid) continue } - - pLogger.Infow("updated subscribed track settings", "trackID", sid, "settings", msg.TrackSetting) } case *livekit.SignalRequest_Leave: pLogger.Infow("client leaving room") diff --git a/pkg/rtc/subscribedtrack.go b/pkg/rtc/subscribedtrack.go index 996d4bf4e..adc0f039b 100644 --- a/pkg/rtc/subscribedtrack.go +++ b/pkg/rtc/subscribedtrack.go @@ -8,6 +8,7 @@ import ( "go.uber.org/atomic" "github.com/livekit/protocol/livekit" + "github.com/livekit/protocol/logger" "github.com/livekit/livekit-server/pkg/rtc/types" "github.com/livekit/livekit-server/pkg/sfu" @@ -32,7 +33,8 @@ type SubscribedTrack struct { params SubscribedTrackParams subMuted atomic.Bool pubMuted atomic.Bool - settings atomic.Value // *livekit.UpdateTrackSettings + settings atomic.Pointer[livekit.UpdateTrackSettings] + logger logger.Logger onBind atomic.Value // func() bound atomic.Bool @@ -42,7 +44,12 @@ type SubscribedTrack struct { func NewSubscribedTrack(params SubscribedTrackParams) *SubscribedTrack { s := &SubscribedTrack{ - params: params, + params: params, + logger: params.Subscriber.GetLogger().WithValues( + "trackID", params.DownTrack.ID(), + "publisherID", params.PublisherID, + "publisher", params.PublisherIdentity, + ), debouncer: debounce.New(subscriptionDebounceInterval), } @@ -120,6 +127,11 @@ func (t *SubscribedTrack) SetPublisherMuted(muted bool) { func (t *SubscribedTrack) UpdateSubscriberSettings(settings *livekit.UpdateTrackSettings) { prevDisabled := t.subMuted.Swap(settings.Disabled) t.settings.Store(settings) + + if prevDisabled != settings.Disabled { + t.logger.Infow("updated subscribed track enabled", "enabled", !settings.Disabled) + } + // avoid frequent changes to mute & video layers, unless it became visible if prevDisabled != settings.Disabled && !settings.Disabled { t.UpdateVideoLayer() @@ -133,13 +145,16 @@ func (t *SubscribedTrack) UpdateVideoLayer() { if t.DownTrack().Kind() != webrtc.RTPCodecTypeVideo { return } - t.Subscriber().GetLogger().Debugw("updating video layer") - settings, ok := t.settings.Load().(*livekit.UpdateTrackSettings) - if !ok { + settings := t.settings.Load() + if settings == nil { return } + t.logger.Debugw("updating video layer", + "settings", settings, + ) + quality := settings.Quality if settings.Width > 0 { quality = t.MediaTrack().GetQualityForDimension(settings.Width, settings.Height) diff --git a/pkg/rtc/transport.go b/pkg/rtc/transport.go index ba841a71a..dc969248e 100644 --- a/pkg/rtc/transport.go +++ b/pkg/rtc/transport.go @@ -1365,7 +1365,7 @@ func (t *PCTransport) handleRemoteICECandidate(e *event) error { } func (t *PCTransport) handleLogICECandidates(e *event) error { - t.params.Logger.Infow( + t.params.Logger.Debugw( "ice candidates", "lc", t.allowedLocalCandidates, "rc", t.allowedRemoteCandidates, diff --git a/pkg/rtc/uptrackmanager.go b/pkg/rtc/uptrackmanager.go index 391d603d1..210aa2e03 100644 --- a/pkg/rtc/uptrackmanager.go +++ b/pkg/rtc/uptrackmanager.go @@ -123,10 +123,8 @@ func (u *UpTrackManager) AddSubscriber(sub types.LocalParticipant, params types. for _, track := range tracks { trackIDs = append(trackIDs, track.ID()) } - u.params.Logger.Debugw("subscribing participant to tracks", - "subscriber", sub.Identity(), - "subscriberID", sub.ID(), - "trackIDs", trackIDs) + sub.GetLogger().Debugw("subscribing to tracks", + "trackID", trackIDs) n := 0 for _, track := range tracks { diff --git a/pkg/service/roommanager.go b/pkg/service/roommanager.go index f93377164..e55c10a0a 100644 --- a/pkg/service/roommanager.go +++ b/pkg/service/roommanager.go @@ -258,7 +258,7 @@ func (r *RoomManager) StartSession( return errors.New("could not restart participant") } - logger.Infow("starting RTC session", + logger.Debugw("starting RTC session", "room", roomName, "nodeID", r.currentNode.Id, "participant", pi.Identity, @@ -456,7 +456,7 @@ func (r *RoomManager) getOrCreateRoom(ctx context.Context, roomName livekit.Room // manages an RTC session for a participant, runs on the RTC node func (r *RoomManager) rtcSessionWorker(room *rtc.Room, participant types.LocalParticipant, requestSource routing.MessageSource) { defer func() { - logger.Infow("RTC session finishing", + logger.Debugw("RTC session finishing", "participant", participant.Identity(), "pID", participant.ID(), "room", room.Name(), diff --git a/pkg/sfu/downtrack.go b/pkg/sfu/downtrack.go index 5cee4ca38..ca1a63d8c 100644 --- a/pkg/sfu/downtrack.go +++ b/pkg/sfu/downtrack.go @@ -689,7 +689,7 @@ func (d *DownTrack) CloseWithFlush(flush bool) { } d.bindLock.Lock() - d.logger.Infow("close down track", "flushBlankFrame", flush) + d.logger.Debugw("close down track", "flushBlankFrame", flush) if d.bound.Load() { if d.forwarder != nil { d.forwarder.Mute(true) @@ -717,7 +717,7 @@ func (d *DownTrack) CloseWithFlush(flush bool) { d.receiver.DeleteDownTrack(d.subscriberID) if d.rtcpReader != nil { - logger.Infow("downtrack close rtcp reader") + logger.Debugw("downtrack close rtcp reader") d.rtcpReader.Close() d.rtcpReader.OnPacket(nil) } diff --git a/pkg/sfu/forwarder.go b/pkg/sfu/forwarder.go index 018e25d6f..cc1b136e9 100644 --- a/pkg/sfu/forwarder.go +++ b/pkg/sfu/forwarder.go @@ -302,7 +302,7 @@ func (f *Forwarder) Mute(muted bool) (bool, VideoLayers) { return false, f.maxLayers } - f.logger.Infow("setting forwarder mute", "muted", muted) + f.logger.Debugw("setting forwarder mute", "muted", muted) f.muted = muted // resync when muted so that sequence numbers do not jump on unmute @@ -1271,7 +1271,7 @@ func (f *Forwarder) updateAllocation(alloc VideoAllocation, reason string) Video } if alloc.state != f.lastAllocation.state || alloc.targetLayers != f.lastAllocation.targetLayers { - f.logger.Infow(fmt.Sprintf("stream allocation: %s", reason), "allocation", alloc) + f.logger.Debugw(fmt.Sprintf("stream allocation: %s", reason), "allocation", alloc) } f.lastAllocation = alloc