Improve logging messages with RoomService (#1203)

This commit is contained in:
David Zhao
2022-11-30 22:17:28 -08:00
committed by GitHub
parent c6eb834e17
commit d146ec7a1f
3 changed files with 32 additions and 8 deletions

View File

@@ -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: |

View File

@@ -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)))
}

View File

@@ -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
}