From 4846acbc1e0d1679fa5317297e56c25c3ea973dc Mon Sep 17 00:00:00 2001 From: Neil Alexander Date: Mon, 31 Jan 2022 09:35:08 +0000 Subject: [PATCH] Modify some log levels --- clientapi/producers/syncapi.go | 2 +- eduserver/input/input.go | 8 +++--- federationapi/routing/send.go | 28 +++++++++---------- roomserver/internal/input/input_missing.go | 20 ++++++------- roomserver/internal/perform/perform_invite.go | 2 +- roomserver/internal/perform/perform_join.go | 5 ++++ roomserver/internal/perform/perform_leave.go | 10 ++++++- 7 files changed, 44 insertions(+), 31 deletions(-) diff --git a/clientapi/producers/syncapi.go b/clientapi/producers/syncapi.go index bd6af5f1f..9b1d6b1a2 100644 --- a/clientapi/producers/syncapi.go +++ b/clientapi/producers/syncapi.go @@ -51,7 +51,7 @@ func (p *SyncAPIProducer) SendData(userID string, roomID string, dataType string "user_id": userID, "room_id": roomID, "data_type": dataType, - }).Infof("Producing to topic '%s'", p.Topic) + }).Tracef("Producing to topic '%s'", p.Topic) _, err = p.JetStream.PublishMsg(m) return err diff --git a/eduserver/input/input.go b/eduserver/input/input.go index e7501a907..4f8ab3e34 100644 --- a/eduserver/input/input.go +++ b/eduserver/input/input.go @@ -98,7 +98,7 @@ func (t *EDUServerInputAPI) InputCrossSigningKeyUpdate( logrus.WithFields(logrus.Fields{ "user_id": request.UserID, - }).Infof("Producing to topic '%s'", t.OutputKeyChangeEventTopic) + }).Tracef("Producing to topic '%s'", t.OutputKeyChangeEventTopic) _, err = t.JetStream.PublishMsg(&nats.Msg{ Subject: t.OutputKeyChangeEventTopic, @@ -134,7 +134,7 @@ func (t *EDUServerInputAPI) sendTypingEvent(ite *api.InputTypingEvent) error { "room_id": ite.RoomID, "user_id": ite.UserID, "typing": ite.Typing, - }).Infof("Producing to topic '%s'", t.OutputTypingEventTopic) + }).Tracef("Producing to topic '%s'", t.OutputTypingEventTopic) _, err = t.JetStream.PublishMsg(&nats.Msg{ Subject: t.OutputTypingEventTopic, @@ -175,7 +175,7 @@ func (t *EDUServerInputAPI) sendToDeviceEvent(ise *api.InputSendToDeviceEvent) e "user_id": ise.UserID, "num_devices": len(devices), "type": ise.Type, - }).Infof("Producing to topic '%s'", t.OutputSendToDeviceEventTopic) + }).Tracef("Producing to topic '%s'", t.OutputSendToDeviceEventTopic) for _, device := range devices { ote := &api.OutputSendToDeviceEvent{ UserID: ise.UserID, @@ -208,7 +208,7 @@ func (t *EDUServerInputAPI) InputReceiptEvent( request *api.InputReceiptEventRequest, response *api.InputReceiptEventResponse, ) error { - logrus.WithFields(logrus.Fields{}).Infof("Producing to topic '%s'", t.OutputReceiptEventTopic) + logrus.WithFields(logrus.Fields{}).Tracef("Producing to topic '%s'", t.OutputReceiptEventTopic) output := &api.OutputReceiptEvent{ UserID: request.InputReceiptEvent.UserID, RoomID: request.InputReceiptEvent.RoomID, diff --git a/federationapi/routing/send.go b/federationapi/routing/send.go index dbfd3ff92..524fd510e 100644 --- a/federationapi/routing/send.go +++ b/federationapi/routing/send.go @@ -162,7 +162,7 @@ func Send( t.TransactionID = txnID t.Destination = cfg.Matrix.ServerName - util.GetLogger(httpReq.Context()).Infof("Received transaction %q from %q containing %d PDUs, %d EDUs", txnID, request.Origin(), len(t.PDUs), len(t.EDUs)) + util.GetLogger(httpReq.Context()).Debugf("Received transaction %q from %q containing %d PDUs, %d EDUs", txnID, request.Origin(), len(t.PDUs), len(t.EDUs)) resp, jsonErr := t.processTransaction(httpReq.Context()) if jsonErr != nil { @@ -221,7 +221,7 @@ func (t *txnReq) processTransaction(ctx context.Context) (*gomatrixserverlib.Res verReq := api.QueryRoomVersionForRoomRequest{RoomID: roomID} verRes := api.QueryRoomVersionForRoomResponse{} if err := t.rsAPI.QueryRoomVersionForRoom(ctx, &verReq, &verRes); err != nil { - util.GetLogger(ctx).WithError(err).Warn("Transaction: Failed to query room version for room", verReq.RoomID) + util.GetLogger(ctx).WithError(err).Debug("Transaction: Failed to query room version for room", verReq.RoomID) return "" } roomVersions[roomID] = verRes.RoomVersion @@ -234,7 +234,7 @@ func (t *txnReq) processTransaction(ctx context.Context) (*gomatrixserverlib.Res RoomID string `json:"room_id"` } if err := json.Unmarshal(pdu, &header); err != nil { - util.GetLogger(ctx).WithError(err).Warn("Transaction: Failed to extract room ID from event") + util.GetLogger(ctx).WithError(err).Debug("Transaction: Failed to extract room ID from event") // We don't know the event ID at this point so we can't return the // failure in the PDU results continue @@ -255,7 +255,7 @@ func (t *txnReq) processTransaction(ctx context.Context) (*gomatrixserverlib.Res JSON: jsonerror.BadJSON("PDU contains bad JSON"), } } - util.GetLogger(ctx).WithError(err).Warnf("Transaction: Failed to parse event JSON of event %s", string(pdu)) + util.GetLogger(ctx).WithError(err).Debugf("Transaction: Failed to parse event JSON of event %s", string(pdu)) continue } if api.IsServerBannedFromRoom(ctx, t.rsAPI, event.RoomID(), t.Origin) { @@ -265,7 +265,7 @@ func (t *txnReq) processTransaction(ctx context.Context) (*gomatrixserverlib.Res continue } if err = event.VerifyEventSignatures(ctx, t.keys); err != nil { - util.GetLogger(ctx).WithError(err).Warnf("Transaction: Couldn't validate signature of event %q", event.EventID()) + util.GetLogger(ctx).WithError(err).Debugf("Transaction: Couldn't validate signature of event %q", event.EventID()) results[event.EventID()] = gomatrixserverlib.PDUResult{ Error: err.Error(), } @@ -287,7 +287,7 @@ func (t *txnReq) processTransaction(ctx context.Context) (*gomatrixserverlib.Res nil, true, ); err != nil { - util.GetLogger(ctx).WithError(err).Warnf("Transaction: Couldn't submit event %q to input queue: %s", event.EventID(), err) + util.GetLogger(ctx).WithError(err).Errorf("Transaction: Couldn't submit event %q to input queue: %s", event.EventID(), err) results[event.EventID()] = gomatrixserverlib.PDUResult{ Error: err.Error(), } @@ -314,16 +314,16 @@ func (t *txnReq) processEDUs(ctx context.Context) { Typing bool `json:"typing"` } if err := json.Unmarshal(e.Content, &typingPayload); err != nil { - util.GetLogger(ctx).WithError(err).Error("Failed to unmarshal typing event") + util.GetLogger(ctx).WithError(err).Debug("Failed to unmarshal typing event") continue } _, domain, err := gomatrixserverlib.SplitID('@', typingPayload.UserID) if err != nil { - util.GetLogger(ctx).WithError(err).Error("Failed to split domain from typing event sender") + util.GetLogger(ctx).WithError(err).Debug("Failed to split domain from typing event sender") continue } if domain != t.Origin { - util.GetLogger(ctx).Warnf("Dropping typing event where sender domain (%q) doesn't match origin (%q)", domain, t.Origin) + util.GetLogger(ctx).Debugf("Dropping typing event where sender domain (%q) doesn't match origin (%q)", domain, t.Origin) continue } if err := eduserverAPI.SendTyping(ctx, t.eduAPI, typingPayload.UserID, typingPayload.RoomID, typingPayload.Typing, 30*1000); err != nil { @@ -333,7 +333,7 @@ func (t *txnReq) processEDUs(ctx context.Context) { // https://matrix.org/docs/spec/server_server/r0.1.3#m-direct-to-device-schema var directPayload gomatrixserverlib.ToDeviceMessage if err := json.Unmarshal(e.Content, &directPayload); err != nil { - util.GetLogger(ctx).WithError(err).Error("Failed to unmarshal send-to-device events") + util.GetLogger(ctx).WithError(err).Debug("Failed to unmarshal send-to-device events") continue } for userID, byUser := range directPayload.Messages { @@ -355,7 +355,7 @@ func (t *txnReq) processEDUs(ctx context.Context) { payload := map[string]eduserverAPI.FederationReceiptMRead{} if err := json.Unmarshal(e.Content, &payload); err != nil { - util.GetLogger(ctx).WithError(err).Error("Failed to unmarshal receipt event") + util.GetLogger(ctx).WithError(err).Debug("Failed to unmarshal receipt event") continue } @@ -363,11 +363,11 @@ func (t *txnReq) processEDUs(ctx context.Context) { for userID, mread := range receipt.User { _, domain, err := gomatrixserverlib.SplitID('@', userID) if err != nil { - util.GetLogger(ctx).WithError(err).Error("Failed to split domain from receipt event sender") + util.GetLogger(ctx).WithError(err).Debug("Failed to split domain from receipt event sender") continue } if t.Origin != domain { - util.GetLogger(ctx).Warnf("Dropping receipt event where sender domain (%q) doesn't match origin (%q)", domain, t.Origin) + util.GetLogger(ctx).Debugf("Dropping receipt event where sender domain (%q) doesn't match origin (%q)", domain, t.Origin) continue } if err := t.processReceiptEvent(ctx, userID, roomID, "m.read", mread.Data.TS, mread.EventIDs); err != nil { @@ -386,7 +386,7 @@ func (t *txnReq) processEDUs(ctx context.Context) { if err := json.Unmarshal(e.Content, &updatePayload); err != nil { util.GetLogger(ctx).WithError(err).WithFields(logrus.Fields{ "user_id": updatePayload.UserID, - }).Error("Failed to send signing key update to edu server") + }).Debug("Failed to send signing key update to edu server") continue } inputReq := &eduserverAPI.InputCrossSigningKeyUpdateRequest{ diff --git a/roomserver/internal/input/input_missing.go b/roomserver/internal/input/input_missing.go index 44710962c..4481d33e9 100644 --- a/roomserver/internal/input/input_missing.go +++ b/roomserver/internal/input/input_missing.go @@ -323,7 +323,7 @@ func (t *missingStateReq) lookupStateAfterEventLocally(ctx context.Context, room queryReq := api.QueryEventsByIDRequest{ EventIDs: missingEventList, } - util.GetLogger(ctx).WithField("count", len(missingEventList)).Infof("Fetching missing auth events") + util.GetLogger(ctx).WithField("count", len(missingEventList)).Debugf("Fetching missing auth events") var queryRes api.QueryEventsByIDResponse if err = t.queryer.QueryEventsByID(ctx, &queryReq, &queryRes); err != nil { return nil @@ -378,7 +378,7 @@ retryAllowedState: default: return nil, fmt.Errorf("missing auth event %s and failed to look it up: %w", missing.AuthEventID, err2) } - util.GetLogger(ctx).Infof("fetched event %s", missing.AuthEventID) + util.GetLogger(ctx).Tracef("fetched event %s", missing.AuthEventID) resolvedStateEvents = append(resolvedStateEvents, h.Unwrap()) goto retryAllowedState default: @@ -425,7 +425,7 @@ func (t *missingStateReq) getMissingEvents(ctx context.Context, e *gomatrixserve missingResp = &m break } else { - logger.WithError(err).Errorf("%s pushed us an event but %q did not respond to /get_missing_events", t.origin, server) + logger.WithError(err).Warnf("%s pushed us an event but %q did not respond to /get_missing_events", t.origin, server) if errors.Is(err, context.DeadlineExceeded) { select { case <-ctx.Done(): // the parent request context timed out @@ -438,7 +438,7 @@ func (t *missingStateReq) getMissingEvents(ctx context.Context, e *gomatrixserve } if missingResp == nil { - logger.WithError(err).Errorf( + logger.WithError(err).Warnf( "%s pushed us an event but %d server(s) couldn't give us details about prev_events via /get_missing_events - dropping this event until it can", t.origin, len(t.servers), ) @@ -450,7 +450,7 @@ func (t *missingStateReq) getMissingEvents(ctx context.Context, e *gomatrixserve // Make sure events from the missingResp are using the cache - missing events // will be added and duplicates will be removed. - logger.Infof("get_missing_events returned %d events", len(missingResp.Events)) + logger.Debugf("get_missing_events returned %d events", len(missingResp.Events)) for i, ev := range missingResp.Events { missingResp.Events[i] = t.cacheAndReturn(ev.Headered(roomVersion)).Unwrap() } @@ -470,7 +470,7 @@ Event: } if !hasPrevEvent { err = fmt.Errorf("called /get_missing_events but server %s didn't return any prev_events with IDs %v", t.origin, shouldHaveSomeEventIDs) - logger.WithError(err).Errorf( + logger.WithError(err).Warnf( "%s pushed us an event but couldn't give us details about prev_events via /get_missing_events - dropping this event until it can", t.origin, ) @@ -561,7 +561,7 @@ func (t *missingStateReq) lookupMissingStateViaStateIDs(ctx context.Context, roo concurrentRequests := 8 missingCount := len(missing) - util.GetLogger(ctx).WithField("room_id", roomID).WithField("event_id", eventID).Infof("lookupMissingStateViaStateIDs missing %d/%d events", missingCount, len(wantIDs)) + util.GetLogger(ctx).WithField("room_id", roomID).WithField("event_id", eventID).Debugf("lookupMissingStateViaStateIDs missing %d/%d events", missingCount, len(wantIDs)) // If over 50% of the auth/state events from /state_ids are missing // then we'll just call /state instead, otherwise we'll just end up @@ -573,7 +573,7 @@ func (t *missingStateReq) lookupMissingStateViaStateIDs(ctx context.Context, roo "room_id": roomID, "total_state": len(stateIDs.StateEventIDs), "total_auth_events": len(stateIDs.AuthEventIDs), - }).Info("Fetching all state at event") + }).Debug("Fetching all state at event") return t.lookupMissingStateViaState(ctx, roomID, eventID, roomVersion) } @@ -585,7 +585,7 @@ func (t *missingStateReq) lookupMissingStateViaStateIDs(ctx context.Context, roo "total_state": len(stateIDs.StateEventIDs), "total_auth_events": len(stateIDs.AuthEventIDs), "concurrent_requests": concurrentRequests, - }).Info("Fetching missing state at event") + }).Debug("Fetching missing state at event") // Create a queue containing all of the missing event IDs that we want // to retrieve. @@ -622,7 +622,7 @@ func (t *missingStateReq) lookupMissingStateViaStateIDs(ctx context.Context, roo util.GetLogger(ctx).WithFields(logrus.Fields{ "event_id": missingEventID, "room_id": roomID, - }).Info("Failed to fetch missing event") + }).Warn("Failed to fetch missing event") return } haveEventsMutex.Lock() diff --git a/roomserver/internal/perform/perform_invite.go b/roomserver/internal/perform/perform_invite.go index 85b2322fe..e23ed47be 100644 --- a/roomserver/internal/perform/perform_invite.go +++ b/roomserver/internal/perform/perform_invite.go @@ -60,7 +60,7 @@ func (r *Inviter) PerformInvite( "room_version": req.RoomVersion, "target_user_id": targetUserID, "room_info_exists": info != nil, - }).Info("processing invite event") + }).Debug("processing invite event") _, domain, _ := gomatrixserverlib.SplitID('@', targetUserID) isTargetLocal := domain == r.Cfg.Matrix.ServerName diff --git a/roomserver/internal/perform/perform_join.go b/roomserver/internal/perform/perform_join.go index a1ffab5dd..2b0bccda6 100644 --- a/roomserver/internal/perform/perform_join.go +++ b/roomserver/internal/perform/perform_join.go @@ -53,6 +53,11 @@ func (r *Joiner) PerformJoin( ) { roomID, joinedVia, err := r.performJoin(ctx, req) if err != nil { + logrus.WithContext(ctx).WithFields(logrus.Fields{ + "room_id": req.RoomIDOrAlias, + "user_id": req.UserID, + "servers": req.ServerNames, + }).WithError(err).Error("Failed to join room") sentry.CaptureException(err) perr, ok := err.(*rsAPI.PerformError) if ok { diff --git a/roomserver/internal/perform/perform_leave.go b/roomserver/internal/perform/perform_leave.go index eac528eaf..b19916491 100644 --- a/roomserver/internal/perform/perform_leave.go +++ b/roomserver/internal/perform/perform_leave.go @@ -27,6 +27,7 @@ import ( "github.com/matrix-org/dendrite/setup/config" "github.com/matrix-org/gomatrixserverlib" "github.com/matrix-org/util" + "github.com/sirupsen/logrus" ) type Leaver struct { @@ -51,7 +52,14 @@ func (r *Leaver) PerformLeave( return nil, fmt.Errorf("user %q does not belong to this homeserver", req.UserID) } if strings.HasPrefix(req.RoomID, "!") { - return r.performLeaveRoomByID(ctx, req, res) + output, err := r.performLeaveRoomByID(ctx, req, res) + if err != nil { + logrus.WithContext(ctx).WithFields(logrus.Fields{ + "room_id": req.RoomID, + "user_id": req.UserID, + }).WithError(err).Error("Failed to leave room") + } + return output, err } return nil, fmt.Errorf("room ID %q is invalid", req.RoomID) }