From 16c2a9590002a2124cf7dae69da07aab0f13a5a8 Mon Sep 17 00:00:00 2001 From: Neil Alexander Date: Wed, 2 Nov 2022 11:30:49 +0000 Subject: [PATCH] Improve logging for `processEventWithMissingState` --- roomserver/internal/input/input_missing.go | 48 +++++++++++----------- 1 file changed, 23 insertions(+), 25 deletions(-) diff --git a/roomserver/internal/input/input_missing.go b/roomserver/internal/input/input_missing.go index d789c3a14..f788c5b3a 100644 --- a/roomserver/internal/input/input_missing.go +++ b/roomserver/internal/input/input_missing.go @@ -40,6 +40,7 @@ func (p *parsedRespState) Events() []*gomatrixserverlib.Event { } type missingStateReq struct { + log *logrus.Entry origin gomatrixserverlib.ServerName db storage.Database roomInfo *types.RoomInfo @@ -77,7 +78,7 @@ func (t *missingStateReq) processEventWithMissingState( // event ids and then use /event to fetch the individual events. // However not all version of synapse support /state_ids so you may // need to fallback to /state. - logger := util.GetLogger(ctx).WithFields(map[string]interface{}{ + t.log = util.GetLogger(ctx).WithFields(map[string]interface{}{ "txn_event": e.EventID(), "room_id": e.RoomID(), "txn_prev_events": e.PrevEventIDs(), @@ -96,7 +97,7 @@ func (t *missingStateReq) processEventWithMissingState( return nil, fmt.Errorf("expected to find missing events but didn't") } if isGapFilled { - logger.Infof("Gap filled by /get_missing_events, injecting %d new events", len(newEvents)) + t.log.Infof("Gap filled by /get_missing_events, injecting %d new events", len(newEvents)) // we can just inject all the newEvents as new as we may have only missed 1 or 2 events and have filled // in the gap in the DAG for _, newEvent := range newEvents { @@ -118,7 +119,7 @@ func (t *missingStateReq) processEventWithMissingState( // then there's nothing else to do, we have everything we need to deal // with the new event. if isGapFilled && prevStatesKnown { - logger.Infof("Gap filled and state found for all prev events") + t.log.Infof("Gap filled and state found for all prev events") return nil, nil } @@ -321,7 +322,7 @@ func (t *missingStateReq) lookupStateAfterEvent(ctx context.Context, roomVersion defer span.Finish() // try doing all this locally before we resort to querying federation - respState := t.lookupStateAfterEventLocally(ctx, roomID, eventID) + respState := t.lookupStateAfterEventLocally(ctx, eventID) if respState != nil { return respState, true, nil } @@ -373,7 +374,7 @@ func (t *missingStateReq) cacheAndReturn(ev *gomatrixserverlib.Event) *gomatrixs return ev } -func (t *missingStateReq) lookupStateAfterEventLocally(ctx context.Context, roomID, eventID string) *parsedRespState { +func (t *missingStateReq) lookupStateAfterEventLocally(ctx context.Context, eventID string) *parsedRespState { span, ctx := opentracing.StartSpanFromContext(ctx, "lookupStateAfterEventLocally") defer span.Finish() @@ -381,12 +382,12 @@ func (t *missingStateReq) lookupStateAfterEventLocally(ctx context.Context, room roomState := state.NewStateResolution(t.db, t.roomInfo) stateAtEvents, err := t.db.StateAtEventIDs(ctx, []string{eventID}) if err != nil { - util.GetLogger(ctx).WithField("room_id", roomID).WithError(err).Warnf("failed to get state after %s locally", eventID) + t.log.WithError(err).Warnf("failed to get state after %s locally", eventID) return nil } stateEntries, err := roomState.LoadCombinedStateAfterEvents(ctx, stateAtEvents) if err != nil { - util.GetLogger(ctx).WithField("room_id", roomID).WithError(err).Warnf("failed to load combined state after %s locally", eventID) + t.log.WithError(err).Warnf("failed to load combined state after %s locally", eventID) return nil } stateEventNIDs := make([]types.EventNID, 0, len(stateEntries)) @@ -395,7 +396,7 @@ func (t *missingStateReq) lookupStateAfterEventLocally(ctx context.Context, room } stateEvents, err := t.db.Events(ctx, stateEventNIDs) if err != nil { - util.GetLogger(ctx).WithField("room_id", roomID).WithError(err).Warnf("failed to load state events locally") + t.log.WithError(err).Warnf("failed to load state events locally") return nil } res.StateEvents = make([]*gomatrixserverlib.Event, 0, len(stateEvents)) @@ -429,7 +430,7 @@ func (t *missingStateReq) lookupStateAfterEventLocally(ctx context.Context, room for evID := range missingAuthEvents { missingEventList = append(missingEventList, evID) } - util.GetLogger(ctx).WithField("count", len(missingEventList)).Debugf("Fetching missing auth events") + t.log.WithField("count", len(missingEventList)).Debugf("Fetching missing auth events") events, err := t.db.EventsFromIDs(ctx, missingEventList) if err != nil { return nil @@ -485,7 +486,7 @@ retryAllowedState: default: return nil, fmt.Errorf("missing auth event %s and failed to look it up: %w", missing.AuthEventID, err2) } - util.GetLogger(ctx).Tracef("fetched event %s", missing.AuthEventID) + t.log.Tracef("fetched event %s", missing.AuthEventID) resolvedStateEvents = append(resolvedStateEvents, h) goto retryAllowedState default: @@ -504,7 +505,7 @@ func (t *missingStateReq) getMissingEvents(ctx context.Context, e *gomatrixserve span, ctx := opentracing.StartSpanFromContext(ctx, "getMissingEvents") defer span.Finish() - logger := util.GetLogger(ctx).WithField("event_id", e.EventID()).WithField("room_id", e.RoomID()) + logger := t.log.WithField("event_id", e.EventID()).WithField("room_id", e.RoomID()) latest, _, _, err := t.db.LatestEventIDs(ctx, t.roomInfo.RoomNID) if err != nil { return nil, false, false, fmt.Errorf("t.DB.LatestEventIDs: %w", err) @@ -666,7 +667,7 @@ func (t *missingStateReq) lookupMissingStateViaStateIDs(ctx context.Context, roo span, ctx := opentracing.StartSpanFromContext(ctx, "lookupMissingStateViaStateIDs") defer span.Finish() - util.GetLogger(ctx).WithField("room_id", roomID).Infof("lookupMissingStateViaStateIDs %s", eventID) + t.log.Infof("lookupMissingStateViaStateIDs %s", eventID) // fetch the state event IDs at the time of the event var stateIDs gomatrixserverlib.RespStateIDs var err error @@ -719,16 +720,15 @@ func (t *missingStateReq) lookupMissingStateViaStateIDs(ctx context.Context, roo concurrentRequests := 8 missingCount := len(missing) - util.GetLogger(ctx).WithField("room_id", roomID).WithField("event_id", eventID).Debugf("lookupMissingStateViaStateIDs missing %d/%d events", missingCount, len(wantIDs)) + t.log.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 // hammering the remote side with /event requests unnecessarily. if missingCount > concurrentRequests && missingCount > len(wantIDs)/2 { - util.GetLogger(ctx).WithFields(logrus.Fields{ + t.log.WithFields(logrus.Fields{ "missing": missingCount, "event_id": eventID, - "room_id": roomID, "total_state": len(stateIDs.StateEventIDs), "total_auth_events": len(stateIDs.AuthEventIDs), }).Debug("Fetching all state at event") @@ -736,10 +736,9 @@ func (t *missingStateReq) lookupMissingStateViaStateIDs(ctx context.Context, roo } if missingCount > 0 { - util.GetLogger(ctx).WithFields(logrus.Fields{ + t.log.WithFields(logrus.Fields{ "missing": missingCount, "event_id": eventID, - "room_id": roomID, "total_state": len(stateIDs.StateEventIDs), "total_auth_events": len(stateIDs.AuthEventIDs), "concurrent_requests": concurrentRequests, @@ -776,9 +775,8 @@ func (t *missingStateReq) lookupMissingStateViaStateIDs(ctx context.Context, roo case nil: break default: - util.GetLogger(ctx).WithFields(logrus.Fields{ - "event_id": missingEventID, - "room_id": roomID, + t.log.WithFields(logrus.Fields{ + "missing_event_id": missingEventID, }).WithError(herr).Warn("Failed to fetch missing event") return } @@ -847,7 +845,7 @@ func (t *missingStateReq) lookupEvent(ctx context.Context, roomVersion gomatrixs // fetch from the roomserver events, err := t.db.EventsFromIDs(ctx, []string{missingEventID}) if err != nil { - util.GetLogger(ctx).Warnf("Failed to query roomserver for missing event %s: %s - falling back to remote", missingEventID, err) + t.log.Warnf("Failed to query roomserver for missing event %s: %s - falling back to remote", missingEventID, err) } else if len(events) == 1 { return events[0].Event, nil } @@ -859,7 +857,7 @@ func (t *missingStateReq) lookupEvent(ctx context.Context, roomVersion gomatrixs defer cancel() txn, err := t.federation.GetEvent(reqctx, serverName, missingEventID) if err != nil || len(txn.PDUs) == 0 { - util.GetLogger(ctx).WithError(err).WithField("event_id", missingEventID).Warn("Failed to get missing /event for event ID") + t.log.WithError(err).WithField("missing_event_id", missingEventID).Warn("Failed to get missing /event for event ID") if errors.Is(err, context.DeadlineExceeded) { select { case <-reqctx.Done(): // this server took too long @@ -872,18 +870,18 @@ func (t *missingStateReq) lookupEvent(ctx context.Context, roomVersion gomatrixs } event, err = gomatrixserverlib.NewEventFromUntrustedJSON(txn.PDUs[0], roomVersion) if err != nil { - util.GetLogger(ctx).WithError(err).WithField("event_id", missingEventID).Warnf("Failed to parse event JSON of event returned from /event") + t.log.WithError(err).WithField("missing_event_id", missingEventID).Warnf("Failed to parse event JSON of event returned from /event") continue } found = true break } if !found { - util.GetLogger(ctx).WithField("event_id", missingEventID).Warnf("Failed to get missing /event for event ID from %d server(s)", len(t.servers)) + t.log.WithField("missing_event_id", missingEventID).Warnf("Failed to get missing /event for event ID from %d server(s)", len(t.servers)) return nil, fmt.Errorf("wasn't able to find event via %d server(s)", len(t.servers)) } if err := event.VerifyEventSignatures(ctx, t.keys); err != nil { - util.GetLogger(ctx).WithError(err).Warnf("Couldn't validate signature of event %q from /event", event.EventID()) + t.log.WithError(err).Warnf("Couldn't validate signature of event %q from /event", event.EventID()) return nil, verifySigError{event.EventID(), err} } return t.cacheAndReturn(event), nil