Add trace logging to RoomserverInternalAPI (#1120)

This is a wrapper around whatever impl we have which then logs the function name/request/response/error. Also tweak when we log on kafka streams: only log on the producer side not the consumer side: we've never had issues with comms and having 1 message rather than N would be nice.
author: Kegsay <kegan@matrix.org> 2020-06-12 12:10:08 +0100
committer: GitHub <noreply@github.com> 2020-06-12 12:10:08 +0100
commit: 4675e1ddb6a48fe1425032dc4f3cef56cbde7243 (patch)
tree: c1f900ab4bf0a4fadc7ca81ba614977f4a973f29 /roomserver
parent: 079d8fe8fb521f76fee3bff5b47482d5fb911257 (diff)
2 files changed, 234 insertions, 0 deletions
diff --git a/roomserver/api/api_trace.go b/roomserver/api/api_trace.go
new file mode 100644
index 00000000..a478eeb9
--- /dev/null
+++ b/roomserver/api/api_trace.go
@@ -0,0 +1,218 @@
+package api
+
+import (
+	"context"
+	"encoding/json"
+	"fmt"
+
+	fsAPI "github.com/matrix-org/dendrite/federationsender/api"
+	"github.com/matrix-org/util"
+)
+
+// RoomserverInternalAPITrace wraps a RoomserverInternalAPI and logs the
+// complete request/response/error
+type RoomserverInternalAPITrace struct {
+	Impl RoomserverInternalAPI
+}
+
+func (t *RoomserverInternalAPITrace) SetFederationSenderAPI(fsAPI fsAPI.FederationSenderInternalAPI) {
+	t.Impl.SetFederationSenderAPI(fsAPI)
+}
+
+func (t *RoomserverInternalAPITrace) InputRoomEvents(
+	ctx context.Context,
+	req *InputRoomEventsRequest,
+	res *InputRoomEventsResponse,
+) error {
+	err := t.Impl.InputRoomEvents(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("InputRoomEvents req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func (t *RoomserverInternalAPITrace) PerformJoin(
+	ctx context.Context,
+	req *PerformJoinRequest,
+	res *PerformJoinResponse,
+) error {
+	err := t.Impl.PerformJoin(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("PerformJoin req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func (t *RoomserverInternalAPITrace) PerformLeave(
+	ctx context.Context,
+	req *PerformLeaveRequest,
+	res *PerformLeaveResponse,
+) error {
+	err := t.Impl.PerformLeave(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("PerformLeave req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func (t *RoomserverInternalAPITrace) QueryLatestEventsAndState(
+	ctx context.Context,
+	req *QueryLatestEventsAndStateRequest,
+	res *QueryLatestEventsAndStateResponse,
+) error {
+	err := t.Impl.QueryLatestEventsAndState(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("QueryLatestEventsAndState req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func (t *RoomserverInternalAPITrace) QueryStateAfterEvents(
+	ctx context.Context,
+	req *QueryStateAfterEventsRequest,
+	res *QueryStateAfterEventsResponse,
+) error {
+	err := t.Impl.QueryStateAfterEvents(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("QueryStateAfterEvents req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func (t *RoomserverInternalAPITrace) QueryEventsByID(
+	ctx context.Context,
+	req *QueryEventsByIDRequest,
+	res *QueryEventsByIDResponse,
+) error {
+	err := t.Impl.QueryEventsByID(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("QueryEventsByID req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func (t *RoomserverInternalAPITrace) QueryMembershipForUser(
+	ctx context.Context,
+	req *QueryMembershipForUserRequest,
+	res *QueryMembershipForUserResponse,
+) error {
+	err := t.Impl.QueryMembershipForUser(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("QueryMembershipForUser req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func (t *RoomserverInternalAPITrace) QueryMembershipsForRoom(
+	ctx context.Context,
+	req *QueryMembershipsForRoomRequest,
+	res *QueryMembershipsForRoomResponse,
+) error {
+	err := t.Impl.QueryMembershipsForRoom(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("QueryMembershipsForRoom req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func (t *RoomserverInternalAPITrace) QueryServerAllowedToSeeEvent(
+	ctx context.Context,
+	req *QueryServerAllowedToSeeEventRequest,
+	res *QueryServerAllowedToSeeEventResponse,
+) error {
+	err := t.Impl.QueryServerAllowedToSeeEvent(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("QueryServerAllowedToSeeEvent req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func (t *RoomserverInternalAPITrace) QueryMissingEvents(
+	ctx context.Context,
+	req *QueryMissingEventsRequest,
+	res *QueryMissingEventsResponse,
+) error {
+	err := t.Impl.QueryMissingEvents(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("QueryMissingEvents req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func (t *RoomserverInternalAPITrace) QueryStateAndAuthChain(
+	ctx context.Context,
+	req *QueryStateAndAuthChainRequest,
+	res *QueryStateAndAuthChainResponse,
+) error {
+	err := t.Impl.QueryStateAndAuthChain(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("QueryStateAndAuthChain req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func (t *RoomserverInternalAPITrace) PerformBackfill(
+	ctx context.Context,
+	req *PerformBackfillRequest,
+	res *PerformBackfillResponse,
+) error {
+	err := t.Impl.PerformBackfill(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("PerformBackfill req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func (t *RoomserverInternalAPITrace) QueryRoomVersionCapabilities(
+	ctx context.Context,
+	req *QueryRoomVersionCapabilitiesRequest,
+	res *QueryRoomVersionCapabilitiesResponse,
+) error {
+	err := t.Impl.QueryRoomVersionCapabilities(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("QueryRoomVersionCapabilities req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func (t *RoomserverInternalAPITrace) QueryRoomVersionForRoom(
+	ctx context.Context,
+	req *QueryRoomVersionForRoomRequest,
+	res *QueryRoomVersionForRoomResponse,
+) error {
+	err := t.Impl.QueryRoomVersionForRoom(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("QueryRoomVersionForRoom req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func (t *RoomserverInternalAPITrace) SetRoomAlias(
+	ctx context.Context,
+	req *SetRoomAliasRequest,
+	res *SetRoomAliasResponse,
+) error {
+	err := t.Impl.SetRoomAlias(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("SetRoomAlias req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func (t *RoomserverInternalAPITrace) GetRoomIDForAlias(
+	ctx context.Context,
+	req *GetRoomIDForAliasRequest,
+	res *GetRoomIDForAliasResponse,
+) error {
+	err := t.Impl.GetRoomIDForAlias(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("GetRoomIDForAlias req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func (t *RoomserverInternalAPITrace) GetAliasesForRoomID(
+	ctx context.Context,
+	req *GetAliasesForRoomIDRequest,
+	res *GetAliasesForRoomIDResponse,
+) error {
+	err := t.Impl.GetAliasesForRoomID(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("GetAliasesForRoomID req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func (t *RoomserverInternalAPITrace) GetCreatorIDForAlias(
+	ctx context.Context,
+	req *GetCreatorIDForAliasRequest,
+	res *GetCreatorIDForAliasResponse,
+) error {
+	err := t.Impl.GetCreatorIDForAlias(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("GetCreatorIDForAlias req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func (t *RoomserverInternalAPITrace) RemoveRoomAlias(
+	ctx context.Context,
+	req *RemoveRoomAliasRequest,
+	res *RemoveRoomAliasResponse,
+) error {
+	err := t.Impl.RemoveRoomAlias(ctx, req, res)
+	util.GetLogger(ctx).WithError(err).Infof("RemoveRoomAlias req=%+v res=%+v", js(req), js(res))
+	return err
+}
+
+func js(thing interface{}) string {
+	b, err := json.Marshal(thing)
+	if err != nil {
+		return fmt.Sprintf("Marshal error:%s", err)
+	}
+	return string(b)
+}
diff --git a/roomserver/internal/input.go b/roomserver/internal/input.go
index 932b4df4..e863af95 100644
--- a/roomserver/internal/input.go
+++ b/roomserver/internal/input.go
@@ -21,6 +21,7 @@ import (
 
 	"github.com/Shopify/sarama"
 	"github.com/matrix-org/dendrite/roomserver/api"
+	log "github.com/sirupsen/logrus"
 
 	fsAPI "github.com/matrix-org/dendrite/federationsender/api"
 )
@@ -40,6 +41,21 @@ func (r *RoomserverInternalAPI) WriteOutputEvents(roomID string, updates []api.O
 		if err != nil {
 			return err
 		}
+		logger := log.WithFields(log.Fields{
+			"room_id": roomID,
+			"type":    updates[i].Type,
+		})
+		if updates[i].NewRoomEvent != nil {
+			logger = logger.WithFields(log.Fields{
+				"event_type":     updates[i].NewRoomEvent.Event.Type(),
+				"event_id":       updates[i].NewRoomEvent.Event.EventID(),
+				"adds_state":     len(updates[i].NewRoomEvent.AddsStateEventIDs),
+				"removes_state":  len(updates[i].NewRoomEvent.RemovesStateEventIDs),
+				"send_as_server": updates[i].NewRoomEvent.SendAsServer,
+				"sender":         updates[i].NewRoomEvent.Event.Sender(),
+			})
+		}
+		logger.Infof("Producing to topic '%s'", r.OutputRoomEventTopic)
 		messages[i] = &sarama.ProducerMessage{
 			Topic: r.OutputRoomEventTopic,
 			Key:   sarama.StringEncoder(roomID),
author	Kegsay <kegan@matrix.org>	2020-06-12 12:10:08 +0100
committer	GitHub <noreply@github.com>	2020-06-12 12:10:08 +0100
commit	4675e1ddb6a48fe1425032dc4f3cef56cbde7243 (patch)
tree	c1f900ab4bf0a4fadc7ca81ba614977f4a973f29 /roomserver
parent	079d8fe8fb521f76fee3bff5b47482d5fb911257 (diff)