diff --git a/clientapi/producers/syncapi.go b/clientapi/producers/syncapi.go index bd6af5f1..9b1d6b1a 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 e7501a90..4f8ab3e3 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 dbfd3ff9..524fd510 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/go.mod b/go.mod index 01cff763..bd695e6d 100644 --- a/go.mod +++ b/go.mod @@ -40,7 +40,7 @@ require ( github.com/matrix-org/go-http-js-libp2p v0.0.0-20200518170932-783164aeeda4 github.com/matrix-org/go-sqlite3-js v0.0.0-20210709140738-b0d1ba599a6d github.com/matrix-org/gomatrix v0.0.0-20210324163249-be2af5ef2e16 - github.com/matrix-org/gomatrixserverlib v0.0.0-20220128100033-8d79e0c35e32 + github.com/matrix-org/gomatrixserverlib v0.0.0-20220131095121-cde7ac8c5bb8 github.com/matrix-org/pinecone v0.0.0-20220121094951-351265543ddf github.com/matrix-org/util v0.0.0-20200807132607-55161520e1d4 github.com/mattn/go-sqlite3 v1.14.10 diff --git a/go.sum b/go.sum index f0475429..8952d034 100644 --- a/go.sum +++ b/go.sum @@ -429,7 +429,6 @@ github.com/go-openapi/jsonreference v0.19.3/go.mod h1:rjx6GuL8TTa9VaixXglHmQmIL9 github.com/go-openapi/spec v0.19.3/go.mod h1:FpwSN1ksY1eteniUU7X0N/BgJ7a4WvBFVA8Lj9mJglo= github.com/go-openapi/swag v0.19.2/go.mod h1:POnQmlKehdgb5mhVOsnJFsivZCEZ/vjK9gh66Z9tfKk= github.com/go-openapi/swag v0.19.5/go.mod h1:POnQmlKehdgb5mhVOsnJFsivZCEZ/vjK9gh66Z9tfKk= -github.com/go-playground/assert/v2 v2.0.1 h1:MsBgLAaY856+nPRTKrp3/OZK38U/wa0CcBYNjji3q3A= github.com/go-playground/assert/v2 v2.0.1/go.mod h1:VDjEfimB/XKnb+ZQfWdccd7VUvScMdVu0Titje2rxJ4= github.com/go-playground/locales v0.13.0 h1:HyWk6mgj5qFqCT5fjGBuRArbVDfE4hi8+e8ceBS/t7Q= github.com/go-playground/locales v0.13.0/go.mod h1:taPMhCMXrRLJO55olJkUXHZBHCxTMfnGwq/HNwmWNS8= @@ -553,9 +552,7 @@ github.com/gorilla/handlers v0.0.0-20150720190736-60c7bfde3e33/go.mod h1:Qkdc/uu github.com/gorilla/mux v1.7.2/go.mod h1:1lud6UwP+6orDFRuTfBEV8e9/aOM/c4fVVCaMa2zaAs= github.com/gorilla/mux v1.8.0 h1:i40aqfkR1h2SlN9hojwV5ZA91wcXFOvkdNIeFDP5koI= github.com/gorilla/mux v1.8.0/go.mod h1:DVbg23sWSpFRCP0SfiEN6jmj59UnW/n46BH5rLB71So= -github.com/gorilla/securecookie v1.1.1 h1:miw7JPhV+b/lAHSXz4qd/nN9jRiAFV5FwjeKyCS8BvQ= github.com/gorilla/securecookie v1.1.1/go.mod h1:ra0sb63/xPlUeL+yeDciTfxMRAA+MP+HVt/4epWDjd4= -github.com/gorilla/sessions v1.2.1 h1:DHd3rPN5lE3Ts3D8rKkQ8x/0kqfeNmBAaiSi+o7FsgI= github.com/gorilla/sessions v1.2.1/go.mod h1:dk2InVEVJ0sfLlnXv9EAgkf6ecYs/i80K/zI+bUmuGM= github.com/gorilla/websocket v0.0.0-20170926233335-4201258b820c/go.mod h1:E7qHFY5m1UJ88s3WnNqhKjPHQ0heANvMoAMk2YaljkQ= github.com/gorilla/websocket v1.4.0/go.mod h1:E7qHFY5m1UJ88s3WnNqhKjPHQ0heANvMoAMk2YaljkQ= @@ -1024,8 +1021,8 @@ github.com/matrix-org/go-sqlite3-js v0.0.0-20210709140738-b0d1ba599a6d/go.mod h1 github.com/matrix-org/gomatrix v0.0.0-20190528120928-7df988a63f26/go.mod h1:3fxX6gUjWyI/2Bt7J1OLhpCzOfO/bB3AiX0cJtEKud0= github.com/matrix-org/gomatrix v0.0.0-20210324163249-be2af5ef2e16 h1:ZtO5uywdd5dLDCud4r0r55eP4j9FuUNpl60Gmntcop4= github.com/matrix-org/gomatrix v0.0.0-20210324163249-be2af5ef2e16/go.mod h1:/gBX06Kw0exX1HrwmoBibFA98yBk/jxKpGVeyQbff+s= -github.com/matrix-org/gomatrixserverlib v0.0.0-20220128100033-8d79e0c35e32 h1:DiWPsGAYMlBQq/urm7TJkIeSf9FnfzegcaQUpgwIbUs= -github.com/matrix-org/gomatrixserverlib v0.0.0-20220128100033-8d79e0c35e32/go.mod h1:qFvhfbQ5orQxlH9vCiFnP4dW27xxnWHdNUBKyj/fbiY= +github.com/matrix-org/gomatrixserverlib v0.0.0-20220131095121-cde7ac8c5bb8 h1:DeGMNY2iJ2u2zEOvUIJdrTPjh5mAa3Mim14hhAvS5zs= +github.com/matrix-org/gomatrixserverlib v0.0.0-20220131095121-cde7ac8c5bb8/go.mod h1:qFvhfbQ5orQxlH9vCiFnP4dW27xxnWHdNUBKyj/fbiY= github.com/matrix-org/pinecone v0.0.0-20220121094951-351265543ddf h1:/nqfHUdQHr3WVdbZieaYFvHF1rin5pvDTa/NOZ/qCyE= github.com/matrix-org/pinecone v0.0.0-20220121094951-351265543ddf/go.mod h1:r6dsL+ylE0yXe/7zh8y/Bdh6aBYI1r+u4yZni9A4iyk= github.com/matrix-org/util v0.0.0-20190711121626-527ce5ddefc7/go.mod h1:vVQlW/emklohkZnOPwD3LrZUBqdfsbiyO3p1lNV8F6U= @@ -1169,7 +1166,6 @@ github.com/nats-io/nkeys v0.3.0 h1:cgM5tL53EvYRU+2YLXIK0G2mJtK12Ft9oeooSZMA2G8= github.com/nats-io/nkeys v0.3.0/go.mod h1:gvUNGjVcM2IPr5rCsRsC6Wb3Hr2CQAm08dsxtV6A5y4= github.com/nats-io/nuid v1.0.1 h1:5iA8DT8V7q8WK2EScv2padNa/rTESc1KdnPw4TC2paw= github.com/nats-io/nuid v1.0.1/go.mod h1:19wcPz3Ph3q0Jbyiqsd0kePYG7A95tJPxeL+1OSON2c= -github.com/nbio/st v0.0.0-20140626010706-e9e8d9816f32 h1:W6apQkHrMkS0Muv8G/TipAy/FJl/rCYT0+EuS8+Z0z4= github.com/nbio/st v0.0.0-20140626010706-e9e8d9816f32/go.mod h1:9wM+0iRr9ahx58uYLpLIr5fm8diHn0JbqRycJi6w0Ms= github.com/ncw/swift v1.0.47/go.mod h1:23YIA4yWVnGwv2dQlN4bB7egfYX6YLn0Yo/S6zZO/ZM= github.com/neelance/astrewrite v0.0.0-20160511093645-99348263ae86/go.mod h1:kHJEU3ofeGjhHklVoIGuVj85JJwZ6kWPaJwCIxgnFmo= @@ -1579,7 +1575,6 @@ golang.org/x/exp v0.0.0-20191129062945-2f5052295587/go.mod h1:2RIsYlXP63K8oxa1u0 golang.org/x/exp v0.0.0-20191227195350-da58074b4299/go.mod h1:2RIsYlXP63K8oxa1u096TMicItID8zy7Y6sNkU49FU4= golang.org/x/exp v0.0.0-20200119233911-0405dc783f0a/go.mod h1:2RIsYlXP63K8oxa1u096TMicItID8zy7Y6sNkU49FU4= golang.org/x/exp v0.0.0-20200207192155-f17229e696bd/go.mod h1:J/WKrq2StrnmMY6+EHIKF9dgMWnmCNThgcyBT1FY9mM= -golang.org/x/exp v0.0.0-20200224162631-6cc2880d07d6 h1:QE6XYQK6naiK1EPAe1g/ILLxN5RBoH5xkJk3CqlMI/Y= golang.org/x/exp v0.0.0-20200224162631-6cc2880d07d6/go.mod h1:3jZMyOhIsHpP37uCMkUooju7aAi5cS1Q23tOzKc+0MU= golang.org/x/image v0.0.0-20180708004352-c73c2afc3b81/go.mod h1:ux5Hcp/YLpHSI86hEcLt0YII63i6oz57MZXIpbrjZUs= golang.org/x/image v0.0.0-20190227222117-0694c2d4d067/go.mod h1:kZ7UVZpmo3dzQBMxlp+ypCbDeSB+sBbTgSJuh5dn5js= @@ -1890,9 +1885,7 @@ golang.zx2c4.com/wireguard v0.0.0-20210604143328-f9b48a961cd2/go.mod h1:laHzsbfM golang.zx2c4.com/wireguard v0.0.0-20210927201915-bb745b2ea326/go.mod h1:SDoazCvdy7RDjBPNEMBwrXhomlmtG7svs8mgwWEqtVI= golang.zx2c4.com/wireguard/windows v0.3.14/go.mod h1:3P4IEAsb+BjlKZmpUXgy74c0iX9AVwwr3WcVJ8nPgME= gonum.org/v1/gonum v0.0.0-20180816165407-929014505bf4/go.mod h1:Y+Yx5eoAFn32cQvJDxZx5Dpnq+c3wtXuadVZAcxbbBo= -gonum.org/v1/gonum v0.8.2 h1:CCXrcPKiGGotvnN6jfUsKk4rRqm7q09/YbKb5xCEvtM= gonum.org/v1/gonum v0.8.2/go.mod h1:oe/vMfY3deqTw+1EZJhuvEW2iwGF1bW9wwu7XCu0+v0= -gonum.org/v1/netlib v0.0.0-20190313105609-8cb42192e0e0 h1:OE9mWmgKkjJyEmDAAtGMPjXu+YNeGvK9VTSHY6+Qihc= gonum.org/v1/netlib v0.0.0-20190313105609-8cb42192e0e0/go.mod h1:wa6Ws7BG/ESfp6dHfk7C6KdzKA7wR7u/rKwOGE66zvw= gonum.org/v1/plot v0.0.0-20190515093506-e2840ee46a6b/go.mod h1:Wt8AAjI+ypCyYX3nZBvf6cAIx93T+c/OS2HFAYskSZc= google.golang.org/api v0.0.0-20160322025152-9bf6e6e569ff/go.mod h1:4mhQ8q/RsB7i+udVvVy5NUi08OU8ZlA0gRVgrF7VFY0= diff --git a/keyserver/producers/keychange.go b/keyserver/producers/keychange.go index fd143c6c..9e1c4c64 100644 --- a/keyserver/producers/keychange.go +++ b/keyserver/producers/keychange.go @@ -65,7 +65,7 @@ func (p *KeyChange) ProduceKeyChanges(keys []api.DeviceMessage) error { logrus.WithFields(logrus.Fields{ "user_id": userID, "num_key_changes": count, - }).Infof("Produced to key change topic '%s'", p.Topic) + }).Tracef("Produced to key change topic '%s'", p.Topic) } return nil } @@ -103,6 +103,6 @@ func (p *KeyChange) ProduceSigningKeyUpdate(key eduapi.CrossSigningKeyUpdate) er logrus.WithFields(logrus.Fields{ "user_id": key.UserID, - }).Infof("Produced to cross-signing update topic '%s'", p.Topic) + }).Tracef("Produced to cross-signing update topic '%s'", p.Topic) return nil } diff --git a/mediaapi/routing/download.go b/mediaapi/routing/download.go index 2358915e..4ce738b6 100644 --- a/mediaapi/routing/download.go +++ b/mediaapi/routing/download.go @@ -157,7 +157,7 @@ func (r *downloadRequest) jsonErrorResponse(w http.ResponseWriter, res util.JSON // Set status code and write the body w.WriteHeader(res.Code) - r.Logger.WithField("code", res.Code).Infof("Responding (%d bytes)", len(resBytes)) + r.Logger.WithField("code", res.Code).Tracef("Responding (%d bytes)", len(resBytes)) // we don't really care that much if we fail to write the error response w.Write(resBytes) // nolint: errcheck @@ -293,11 +293,11 @@ func (r *downloadRequest) respondFromLocalFile( "Base64Hash": r.MediaMetadata.Base64Hash, "FileSizeBytes": r.MediaMetadata.FileSizeBytes, "ContentType": r.MediaMetadata.ContentType, - }).Info("No good thumbnail found. Responding with original file.") + }).Trace("No good thumbnail found. Responding with original file.") responseFile = file responseMetadata = r.MediaMetadata } else { - r.Logger.Info("Responding with thumbnail") + r.Logger.Trace("Responding with thumbnail") responseFile = thumbFile responseMetadata = thumbMetadata.MediaMetadata } @@ -307,7 +307,7 @@ func (r *downloadRequest) respondFromLocalFile( "Base64Hash": r.MediaMetadata.Base64Hash, "FileSizeBytes": r.MediaMetadata.FileSizeBytes, "ContentType": r.MediaMetadata.ContentType, - }).Info("Responding with file") + }).Trace("Responding with file") responseFile = file responseMetadata = r.MediaMetadata if err := r.addDownloadFilenameToHeaders(w, responseMetadata); err != nil { @@ -436,7 +436,7 @@ func (r *downloadRequest) getThumbnailFile( "Width": thumbnailSize.Width, "Height": thumbnailSize.Height, "ResizeMethod": thumbnailSize.ResizeMethod, - }).Info("Pre-generating thumbnail for immediate response.") + }).Debug("Pre-generating thumbnail for immediate response.") thumbnail, err = r.generateThumbnail( ctx, filePath, *thumbnailSize, activeThumbnailGeneration, maxThumbnailGenerators, db, @@ -574,7 +574,7 @@ func (r *downloadRequest) getMediaMetadataFromActiveRequest(activeRemoteRequests defer activeRemoteRequests.Unlock() if activeRemoteRequestResult, ok := activeRemoteRequests.MXCToResult[mxcURL]; ok { - r.Logger.Info("Waiting for another goroutine to fetch the remote file.") + r.Logger.Trace("Waiting for another goroutine to fetch the remote file.") // NOTE: Wait unlocks and locks again internally. There is still a deferred Unlock() that will unlock this. activeRemoteRequestResult.Cond.Wait() @@ -604,7 +604,7 @@ func (r *downloadRequest) broadcastMediaMetadata(activeRemoteRequests *types.Act defer activeRemoteRequests.Unlock() mxcURL := "mxc://" + string(r.MediaMetadata.Origin) + "/" + string(r.MediaMetadata.MediaID) if activeRemoteRequestResult, ok := activeRemoteRequests.MXCToResult[mxcURL]; ok { - r.Logger.Info("Signalling other goroutines waiting for this goroutine to fetch the file.") + r.Logger.Trace("Signalling other goroutines waiting for this goroutine to fetch the file.") activeRemoteRequestResult.MediaMetadata = r.MediaMetadata activeRemoteRequestResult.Error = err activeRemoteRequestResult.Cond.Broadcast() @@ -635,7 +635,7 @@ func (r *downloadRequest) fetchRemoteFileAndStoreMetadata( "UploadName": r.MediaMetadata.UploadName, "FileSizeBytes": r.MediaMetadata.FileSizeBytes, "ContentType": r.MediaMetadata.ContentType, - }).Info("Storing file metadata to media repository database") + }).Debug("Storing file metadata to media repository database") // FIXME: timeout db request if err := db.StoreMediaMetadata(ctx, r.MediaMetadata); err != nil { @@ -669,7 +669,7 @@ func (r *downloadRequest) fetchRemoteFileAndStoreMetadata( "Base64Hash": r.MediaMetadata.Base64Hash, "FileSizeBytes": r.MediaMetadata.FileSizeBytes, "ContentType": r.MediaMetadata.ContentType, - }).Infof("Remote file cached") + }).Debug("Remote file cached") return nil } @@ -717,7 +717,7 @@ func (r *downloadRequest) fetchRemoteFile( absBasePath config.Path, maxFileSizeBytes config.FileSizeBytes, ) (types.Path, bool, error) { - r.Logger.Info("Fetching remote file") + r.Logger.Debug("Fetching remote file") // create request for remote file resp, err := r.createRemoteRequest(ctx, client) @@ -762,7 +762,7 @@ func (r *downloadRequest) fetchRemoteFile( } } - r.Logger.Info("Transferring remote file") + r.Logger.Trace("Transferring remote file") // The file data is hashed but is NOT used as the MediaID, unlike in Upload. The hash is useful as a // method of deduplicating files to save storage, as well as a way to conduct @@ -776,7 +776,7 @@ func (r *downloadRequest) fetchRemoteFile( return "", false, errors.New("file could not be downloaded from remote server") } - r.Logger.Info("Remote file transferred") + r.Logger.Trace("Remote file transferred") // It's possible the bytesWritten to the temporary file is different to the reported Content-Length from the remote // request's response. bytesWritten is therefore used as it is what would be sent to clients when reading from the local @@ -790,7 +790,7 @@ func (r *downloadRequest) fetchRemoteFile( return "", false, fmt.Errorf("fileutils.MoveFileWithHashCheck: %w", err) } if duplicate { - r.Logger.WithField("dst", finalPath).Info("File was stored previously - discarding duplicate") + r.Logger.WithField("dst", finalPath).Trace("File was stored previously - discarding duplicate") // Continue on to store the metadata in the database } diff --git a/roomserver/internal/input/input.go b/roomserver/internal/input/input.go index 938d5ac1..a38d56d7 100644 --- a/roomserver/internal/input/input.go +++ b/roomserver/internal/input/input.go @@ -33,6 +33,7 @@ import ( "github.com/matrix-org/gomatrixserverlib" "github.com/nats-io/nats.go" "github.com/prometheus/client_golang/prometheus" + "github.com/sirupsen/logrus" log "github.com/sirupsen/logrus" "github.com/tidwall/gjson" ) @@ -104,6 +105,11 @@ func (r *Inputer) Start() error { if !errors.Is(err, context.DeadlineExceeded) && !errors.Is(err, context.Canceled) { sentry.CaptureException(err) } + logrus.WithError(err).WithFields(logrus.Fields{ + "room_id": roomID, + "event_id": inputRoomEvent.Event.EventID(), + "type": inputRoomEvent.Event.Type(), + }).Warn("Roomserver failed to process async event") } _ = msg.Ack() }) @@ -146,6 +152,10 @@ func (r *Inputer) InputRoomEvents( return } if _, err = r.JetStream.PublishMsg(msg); err != nil { + logrus.WithError(err).WithFields(logrus.Fields{ + "room_id": roomID, + "event_id": e.Event.EventID(), + }).Error("Roomserver failed to queue async event") return } } @@ -173,6 +183,10 @@ func (r *Inputer) InputRoomEvents( if !errors.Is(err, context.DeadlineExceeded) && !errors.Is(err, context.Canceled) { sentry.CaptureException(err) } + logrus.WithError(err).WithFields(logrus.Fields{ + "room_id": roomID, + "event_id": inputRoomEvent.Event.EventID(), + }).Warn("Roomserver failed to process sync event") } select { case <-ctx.Done(): diff --git a/roomserver/internal/input/input_missing.go b/roomserver/internal/input/input_missing.go index 862b3a7f..aa2b94f8 100644 --- a/roomserver/internal/input/input_missing.go +++ b/roomserver/internal/input/input_missing.go @@ -327,7 +327,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 @@ -382,7 +382,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: @@ -429,7 +429,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 @@ -442,7 +442,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), ) @@ -454,7 +454,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() } @@ -474,7 +474,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, ) @@ -565,7 +565,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 @@ -577,7 +577,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) } @@ -589,7 +589,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. @@ -626,7 +626,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 85b2322f..e23ed47b 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 a1ffab5d..2b0bccda 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 eac528ea..b1991649 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) } diff --git a/syncapi/consumers/clientapi.go b/syncapi/consumers/clientapi.go index 1ec9beb0..3d340a16 100644 --- a/syncapi/consumers/clientapi.go +++ b/syncapi/consumers/clientapi.go @@ -85,7 +85,7 @@ func (s *OutputClientDataConsumer) onMessage(msg *nats.Msg) { log.WithFields(log.Fields{ "type": output.Type, "room_id": output.RoomID, - }).Info("received data from client API server") + }).Debug("Received data from client API server") streamPos, err := s.db.UpsertAccountData( s.ctx, userID, output.RoomID, output.Type,