From d146ec7a1fa7bfa01ceea5b5a8aec179f58612a7 Mon Sep 17 00:00:00 2001 From: David Zhao Date: Wed, 30 Nov 2022 22:17:28 -0800 Subject: [PATCH] Improve logging messages with RoomService (#1203) --- .github/workflows/buildtest.yaml | 2 +- pkg/service/roomservice.go | 15 +++++++++++++++ pkg/service/twirp.go | 23 ++++++++++++++++------- 3 files changed, 32 insertions(+), 8 deletions(-) diff --git a/.github/workflows/buildtest.yaml b/.github/workflows/buildtest.yaml index 5a0cdc3c2..a5948bf7d 100644 --- a/.github/workflows/buildtest.yaml +++ b/.github/workflows/buildtest.yaml @@ -24,7 +24,7 @@ jobs: go-version: '>=1.17' - name: Set up gotestfmt - run: go install github.com/haveyoudebuggedit/gotestfmt/v2/cmd/gotestfmt@latest + run: go install github.com/gotesttools/gotestfmt/v2/cmd/gotestfmt@v2.4.1 - name: Replace mutexes run: | diff --git a/pkg/service/roomservice.go b/pkg/service/roomservice.go index 9260cd195..8740ec95a 100644 --- a/pkg/service/roomservice.go +++ b/pkg/service/roomservice.go @@ -49,6 +49,7 @@ func NewRoomService( } func (s *RoomService) CreateRoom(ctx context.Context, req *livekit.CreateRoomRequest) (*livekit.Room, error) { + AppendLogFields(ctx, "room", req.Name, "request", req) if err := EnsureCreatePermission(ctx); err != nil { return nil, twirpAuthError(err) } else if req.Egress != nil && s.egressLauncher == nil { @@ -99,6 +100,7 @@ func (s *RoomService) CreateRoom(ctx context.Context, req *livekit.CreateRoomReq } func (s *RoomService) ListRooms(ctx context.Context, req *livekit.ListRoomsRequest) (*livekit.ListRoomsResponse, error) { + AppendLogFields(ctx, "room", req.Names) err := EnsureListPermission(ctx) if err != nil { return nil, twirpAuthError(err) @@ -121,6 +123,7 @@ func (s *RoomService) ListRooms(ctx context.Context, req *livekit.ListRoomsReque } func (s *RoomService) DeleteRoom(ctx context.Context, req *livekit.DeleteRoomRequest) (*livekit.DeleteRoomResponse, error) { + AppendLogFields(ctx, "room", req.Room) if err := EnsureCreatePermission(ctx); err != nil { return nil, twirpAuthError(err) } @@ -152,6 +155,7 @@ func (s *RoomService) DeleteRoom(ctx context.Context, req *livekit.DeleteRoomReq } func (s *RoomService) ListParticipants(ctx context.Context, req *livekit.ListParticipantsRequest) (*livekit.ListParticipantsResponse, error) { + AppendLogFields(ctx, "room", req.Room) if err := EnsureAdminPermission(ctx, livekit.RoomName(req.Room)); err != nil { return nil, twirpAuthError(err) } @@ -168,6 +172,7 @@ func (s *RoomService) ListParticipants(ctx context.Context, req *livekit.ListPar } func (s *RoomService) GetParticipant(ctx context.Context, req *livekit.RoomParticipantIdentity) (*livekit.ParticipantInfo, error) { + AppendLogFields(ctx, "room", req.Room, "participant", req.Identity) if err := EnsureAdminPermission(ctx, livekit.RoomName(req.Room)); err != nil { return nil, twirpAuthError(err) } @@ -181,6 +186,7 @@ func (s *RoomService) GetParticipant(ctx context.Context, req *livekit.RoomParti } func (s *RoomService) RemoveParticipant(ctx context.Context, req *livekit.RoomParticipantIdentity) (*livekit.RemoveParticipantResponse, error) { + AppendLogFields(ctx, "room", req.Room, "participant", req.Identity) err := s.writeParticipantMessage(ctx, livekit.RoomName(req.Room), livekit.ParticipantIdentity(req.Identity), &livekit.RTCNodeMessage{ Message: &livekit.RTCNodeMessage_RemoveParticipant{ RemoveParticipant: req, @@ -208,6 +214,7 @@ func (s *RoomService) RemoveParticipant(ctx context.Context, req *livekit.RoomPa } func (s *RoomService) MutePublishedTrack(ctx context.Context, req *livekit.MuteRoomTrackRequest) (*livekit.MuteRoomTrackResponse, error) { + AppendLogFields(ctx, "room", req.Room, "participant", req.Identity, "track", req.TrackSid, "muted", req.Muted) if err := EnsureAdminPermission(ctx, livekit.RoomName(req.Room)); err != nil { return nil, twirpAuthError(err) } @@ -252,6 +259,7 @@ func (s *RoomService) MutePublishedTrack(ctx context.Context, req *livekit.MuteR } func (s *RoomService) UpdateParticipant(ctx context.Context, req *livekit.UpdateParticipantRequest) (*livekit.ParticipantInfo, error) { + AppendLogFields(ctx, "room", req.Room, "participant", req.Identity) if s.conf.MaxMetadataSize > 0 && len(req.Metadata) > int(s.conf.MaxMetadataSize) { return nil, twirp.InvalidArgumentError(ErrMetadataExceedsLimits.Error(), strconv.Itoa(int(s.conf.MaxMetadataSize))) } @@ -287,6 +295,11 @@ func (s *RoomService) UpdateParticipant(ctx context.Context, req *livekit.Update } func (s *RoomService) UpdateSubscriptions(ctx context.Context, req *livekit.UpdateSubscriptionsRequest) (*livekit.UpdateSubscriptionsResponse, error) { + trackSIDs := append(make([]string, 0), req.TrackSids...) + for _, pt := range req.ParticipantTracks { + trackSIDs = append(trackSIDs, pt.TrackSids...) + } + AppendLogFields(ctx, "room", req.Room, "participant", req.Identity, "track", trackSIDs) err := s.writeParticipantMessage(ctx, livekit.RoomName(req.Room), livekit.ParticipantIdentity(req.Identity), &livekit.RTCNodeMessage{ Message: &livekit.RTCNodeMessage_UpdateSubscriptions{ UpdateSubscriptions: req, @@ -301,6 +314,7 @@ func (s *RoomService) UpdateSubscriptions(ctx context.Context, req *livekit.Upda func (s *RoomService) SendData(ctx context.Context, req *livekit.SendDataRequest) (*livekit.SendDataResponse, error) { roomName := livekit.RoomName(req.Room) + AppendLogFields(ctx, "room", roomName, "size", len(req.Data)) if err := EnsureAdminPermission(ctx, roomName); err != nil { return nil, twirpAuthError(err) } @@ -318,6 +332,7 @@ func (s *RoomService) SendData(ctx context.Context, req *livekit.SendDataRequest } func (s *RoomService) UpdateRoomMetadata(ctx context.Context, req *livekit.UpdateRoomMetadataRequest) (*livekit.Room, error) { + AppendLogFields(ctx, "room", req.Room, "size", len(req.Metadata)) if s.conf.MaxMetadataSize > 0 && len(req.Metadata) > int(s.conf.MaxMetadataSize) { return nil, twirp.InvalidArgumentError(ErrMetadataExceedsLimits.Error(), strconv.Itoa(int(s.conf.MaxMetadataSize))) } diff --git a/pkg/service/twirp.go b/pkg/service/twirp.go index b62487e17..4c36c271a 100644 --- a/pkg/service/twirp.go +++ b/pkg/service/twirp.go @@ -27,7 +27,7 @@ import ( ) var ( - logKey = struct{}{} + loggerKey = struct{}{} ) // logging handling inspired by https://github.com/bakins/twirpzap @@ -37,7 +37,7 @@ func TwirpLogger(logger logger.Logger) *twirp.ServerHooks { New: func() interface{} { return &requestLogger{ logger: logger, - fieldsOrig: make([]interface{}, 0, 20), + fieldsOrig: make([]interface{}, 0, 30), } }, } @@ -63,6 +63,15 @@ type requestLogger struct { startedAt time.Time } +func AppendLogFields(ctx context.Context, fields ...interface{}) { + r, ok := ctx.Value(loggerKey).(*requestLogger) + if !ok || r == nil { + return + } + + r.fields = append(r.fields, fields...) +} + func requestReceived(ctx context.Context, requestLoggerPool *sync.Pool) (context.Context, error) { r := requestLoggerPool.Get().(*requestLogger) r.startedAt = time.Now() @@ -74,13 +83,13 @@ func requestReceived(ctx context.Context, requestLoggerPool *sync.Pool) (context r.fields = append(r.fields, "service", svc) } - ctx = context.WithValue(ctx, logKey, r) + ctx = context.WithValue(ctx, loggerKey, r) return ctx, nil } func responseRouted(ctx context.Context) (context.Context, error) { if meth, ok := twirp.MethodName(ctx); ok { - l, ok := ctx.Value(logKey).(*requestLogger) + l, ok := ctx.Value(loggerKey).(*requestLogger) if !ok || l == nil { return ctx, nil } @@ -92,7 +101,7 @@ func responseRouted(ctx context.Context) (context.Context, error) { } func responseSent(ctx context.Context, requestLoggerPool *sync.Pool) { - r, ok := ctx.Value(logKey).(*requestLogger) + r, ok := ctx.Value(loggerKey).(*requestLogger) if !ok || r == nil { return } @@ -106,7 +115,7 @@ func responseSent(ctx context.Context, requestLoggerPool *sync.Pool) { r.fields = append(r.fields, "error", r.error.Msg()) r.fields = append(r.fields, "code", r.error.Code()) } - + serviceMethod := "API " + r.service + "." + r.method r.logger.Infow(serviceMethod, r.fields...) @@ -117,7 +126,7 @@ func responseSent(ctx context.Context, requestLoggerPool *sync.Pool) { } func errorReceived(ctx context.Context, e twirp.Error) context.Context { - r, ok := ctx.Value(logKey).(*requestLogger) + r, ok := ctx.Value(loggerKey).(*requestLogger) if !ok || r == nil { return ctx }