Add tracing support

cmd/root.go

@@ -18,6 +18,7 @@
 package cmd
 
 import (
+	"github.com/Unkn0wnCat/matrix-veles/internal/tracer"
 	"github.com/spf13/viper"
 	"log"
 	"os"
@@ -62,7 +63,18 @@ func init() {
 	viper.SetDefault("bot.web.listen", "127.0.0.1:8123")
 	viper.SetDefault("bot.web.secret", "hunter2")
 
+	viper.SetDefault("tracing.enable", false)
+	viper.SetDefault("tracing.jaeger.endpoint", "http://localhost:14268/api/traces")
+
 	cobra.OnInitialize(loadConfig)
+	cobra.OnInitialize(func() {
+		if viper.GetBool("tracing.enable") {
+			tracer.SetupJaeger()
+		}
+		if !viper.GetBool("tracing.enable") {
+			tracer.SetupDummy()
+		}
+	})
 }
 
 func loadConfig() {

go.mod

@@ -3,15 +3,22 @@ module github.com/Unkn0wnCat/matrix-veles
 go 1.16
 
 require (
-	github.com/766b/chi-prometheus v0.0.0-20211217152057-87afa9aa2ca8 // indirect
+	github.com/766b/chi-prometheus v0.0.0-20211217152057-87afa9aa2ca8
 	github.com/go-chi/chi v1.5.4 // indirect
 	github.com/go-chi/chi/v5 v5.0.7
 	github.com/golang-jwt/jwt/v4 v4.3.0
-	github.com/prometheus/client_golang v1.12.1 // indirect
+	github.com/opentracing/opentracing-go v1.2.0 // indirect
+	github.com/prometheus/client_golang v1.12.1
 	github.com/spf13/cobra v1.3.0
 	github.com/spf13/viper v1.10.1
+	github.com/uber/jaeger-client-go v2.30.0+incompatible // indirect
+	github.com/uber/jaeger-lib v2.4.1+incompatible // indirect
 	go.mongodb.org/mongo-driver v1.8.3
+	go.opentelemetry.io/otel v1.4.1
+	go.opentelemetry.io/otel/exporters/jaeger v1.4.1
+	go.opentelemetry.io/otel/sdk v1.4.1
+	go.opentelemetry.io/otel/trace v1.4.1
 	golang.org/x/crypto v0.0.0-20210817164053-32db794688a5
-	golang.org/x/sys v0.0.0-20220114195835-da31bd327af9 // indirect
+	golang.org/x/sys v0.0.0-20220227234510-4e6760a101f9 // indirect
 	maunium.net/go/mautrix v0.9.14
 )

go.sum

@@ -140,6 +140,10 @@ github.com/go-kit/log v0.1.0/go.mod h1:zbhenjAZHb184qTLMA9ZjW7ThYL0H2mk7Q6pNt4vb
 github.com/go-logfmt/logfmt v0.3.0/go.mod h1:Qt1PoO58o5twSAckw1HlFXLmHsOX5/0LbT9GBnD5lWE=
 github.com/go-logfmt/logfmt v0.4.0/go.mod h1:3RMwSq7FuexP4Kalkev3ejPJsZTpXXBr9+V4qmtdjCk=
 github.com/go-logfmt/logfmt v0.5.0/go.mod h1:wCYkCAKZfumFQihp8CzCvQ3paCTfi41vtzG1KdI/P7A=
+github.com/go-logr/logr v1.2.2 h1:ahHml/yUpnlb96Rp8HCvtYVPY8ZYpxq3g7UYchIYwbs=
+github.com/go-logr/logr v1.2.2/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
+github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag=
+github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE=
 github.com/go-stack/stack v1.8.0 h1:5SgMzNM5HxrEjV0ww2lTmX6E2Izsfxas4+YHWRs3Lsk=
 github.com/go-stack/stack v1.8.0/go.mod h1:v0f6uXyyMGvRgIKkXu+yp6POWl0qKG85gN/melR3HDY=
 github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
@@ -197,6 +201,8 @@ github.com/google/go-cmp v0.5.4/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/
 github.com/google/go-cmp v0.5.5/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
 github.com/google/go-cmp v0.5.6 h1:BKbKCqvP6I+rmFHt06ZmyQtvB8xAkWdhFyr0ZUNZcxQ=
 github.com/google/go-cmp v0.5.6/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
+github.com/google/go-cmp v0.5.7 h1:81/ik6ipDQS2aGcBfIN5dHDB36BwrStyeAQquSYCV4o=
+github.com/google/go-cmp v0.5.7/go.mod h1:n+brtR0CgQNWTVd5ZUFpTBC8YFBDLK/h/bpaJ8/DtOE=
 github.com/google/gofuzz v1.0.0/go.mod h1:dBl0BpW6vV/+mYPU4Po3pmUjxk6FQPldtuIdl/M65Eg=
 github.com/google/martian v2.1.0+incompatible/go.mod h1:9I4somxYTbIHy5NJKHRl3wXiIaQGbYVAs8BPL6v8lEs=
 github.com/google/martian/v3 v3.0.0/go.mod h1:y5Zk1BBys9G+gd6Jrk0W3cC1+ELVxBWuIGO+w/tUAp0=
@@ -329,6 +335,8 @@ github.com/mwitkow/go-conntrack v0.0.0-20190716064945-2f068394615f/go.mod h1:qRW
 github.com/onsi/ginkgo v1.6.0/go.mod h1:lLunBs/Ym6LB5Z9jYTR76FiuTmxDTDusOGeTQH+WWjE=
 github.com/onsi/ginkgo v1.7.0/go.mod h1:lLunBs/Ym6LB5Z9jYTR76FiuTmxDTDusOGeTQH+WWjE=
 github.com/onsi/gomega v1.4.3/go.mod h1:ex+gbHU/CVuBBDIJjb2X0qEXbFg53c61hWP/1CpauHY=
+github.com/opentracing/opentracing-go v1.2.0 h1:uEJPy/1a5RIPAJ0Ov+OIO8OxWu77jEv+1B0VhjKrZUs=
+github.com/opentracing/opentracing-go v1.2.0/go.mod h1:GxEUsuufX4nBwe+T+Wl9TAgYrxe9dPLANfrWvHYVTgc=
 github.com/pascaldekloe/goe v0.0.0-20180627143212-57f6aae5913c/go.mod h1:lzWF7FIEvWOWxwDKqyGYQf6ZUaNfKdP144TG7ZOy1lc=
 github.com/pascaldekloe/goe v0.1.0/go.mod h1:lzWF7FIEvWOWxwDKqyGYQf6ZUaNfKdP144TG7ZOy1lc=
 github.com/pelletier/go-toml v1.9.4 h1:tjENF6MfZAg8e4ZmZTeWaWiT2vXtsoO6+iuOjFhECwM=
@@ -410,6 +418,10 @@ github.com/tidwall/pretty v1.0.2 h1:Z7S3cePv9Jwm1KwS0513MRaoUe3S01WPbLNV40pwWZU=
 github.com/tidwall/pretty v1.0.2/go.mod h1:XNkn88O1ChpSDQmQeStsy+sBenx6DDtFZJxhVysOjyk=
 github.com/tidwall/sjson v1.1.5/go.mod h1:VuJzsZnTowhSxWdOgsAnb886i4AjEyTkk7tNtsL7EYE=
 github.com/tv42/httpunix v0.0.0-20150427012821-b75d8614f926/go.mod h1:9ESjWnEqriFuLhtthL60Sar/7RFoluCcXsuvEwTV5KM=
+github.com/uber/jaeger-client-go v2.30.0+incompatible h1:D6wyKGCecFaSRUpo8lCVbaOOb6ThwMmTEbhRwtKR97o=
+github.com/uber/jaeger-client-go v2.30.0+incompatible/go.mod h1:WVhlPFC8FDjOFMMWRy2pZqQJSXxYSwNYOkTr/Z6d3Kk=
+github.com/uber/jaeger-lib v2.4.1+incompatible h1:td4jdvLcExb4cBISKIpHuGoVXh+dVKhn2Um6rjCsSsg=
+github.com/uber/jaeger-lib v2.4.1+incompatible/go.mod h1:ComeNDZlWwrWnDv8aPp0Ba6+uUTzImX/AauajbLI56U=
 github.com/xdg-go/pbkdf2 v1.0.0 h1:Su7DPu48wXMwC3bs7MCNG+z4FhcyEuz5dlvchbq0B0c=
 github.com/xdg-go/pbkdf2 v1.0.0/go.mod h1:jrpuAogTd400dnrH08LKmI/xc1MbPOebTwRqcT5RDeI=
 github.com/xdg-go/scram v1.0.2 h1:akYIkZ28e6A96dkWNJQu3nmCzH3YfwMPQExUYDaRv7w=
@@ -435,7 +447,16 @@ go.opencensus.io v0.22.3/go.mod h1:yxeiOL68Rb0Xd1ddK5vPZ/oVn4vY4Ynel7k9FzqtOIw=
 go.opencensus.io v0.22.4/go.mod h1:yxeiOL68Rb0Xd1ddK5vPZ/oVn4vY4Ynel7k9FzqtOIw=
 go.opencensus.io v0.22.5/go.mod h1:5pWMHQbX5EPX2/62yrJeAkowc+lfs/XD7Uxpq3pI6kk=
 go.opencensus.io v0.23.0/go.mod h1:XItmlyltB5F7CS4xOC1DcqMoFqwtC6OG2xF7mCv7P7E=
+go.opentelemetry.io/otel v1.4.1 h1:QbINgGDDcoQUoMJa2mMaWno49lja9sHwp6aoa2n3a4g=
+go.opentelemetry.io/otel v1.4.1/go.mod h1:StM6F/0fSwpd8dKWDCdRr7uRvEPYdW0hBSlbdTiUde4=
+go.opentelemetry.io/otel/exporters/jaeger v1.4.1 h1:VHCK+2yTZDqDaVXj7JH2Z/khptuydo6C0ttBh2bxAbc=
+go.opentelemetry.io/otel/exporters/jaeger v1.4.1/go.mod h1:ZW7vkOu9nC1CxsD8bHNHCia5JUbwP39vxgd1q4Z5rCI=
+go.opentelemetry.io/otel/sdk v1.4.1 h1:J7EaW71E0v87qflB4cDolaqq3AcujGrtyIPGQoZOB0Y=
+go.opentelemetry.io/otel/sdk v1.4.1/go.mod h1:NBwHDgDIBYjwK2WNu1OPgsIc2IJzmBXNnvIJxJc8BpE=
+go.opentelemetry.io/otel/trace v1.4.1 h1:O+16qcdTrT7zxv2J6GejTPFinSwA++cYerC5iSiF8EQ=
+go.opentelemetry.io/otel/trace v1.4.1/go.mod h1:iYEVbroFCNut9QkwEczV9vMRPHNKSSwYZjulEtsmhFc=
 go.opentelemetry.io/proto/otlp v0.7.0/go.mod h1:PqfVotwruBrMGOCsRd/89rSnXhoiJIqeYNgFYFoEGnI=
+go.uber.org/atomic v1.7.0 h1:ADUqmZGgLDDfbSL9ZmPxKTybcoEYHgpYfELNoN+7hsw=
 go.uber.org/atomic v1.7.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc=
 go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU=
 go.uber.org/zap v1.17.0/go.mod h1:MXVU+bhUf/A7Xi2HNOnopQOrmycQ5Ih87HtOu4q5SSo=
@@ -620,6 +641,7 @@ golang.org/x/sys v0.0.0-20210320140829-1e4c9ba3b0c4/go.mod h1:h1NjWce9XRLGQEsW7w
 golang.org/x/sys v0.0.0-20210330210617-4fbd30eecc44/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20210403161142-5e06dd20ab57/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20210423082822-04245dca01da/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20210423185535-09eb48e85fd7/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20210510120138-977fb7262007/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20210514084401-e8d321eab015/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20210603081109-ebe580a85c40/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
@@ -638,6 +660,8 @@ golang.org/x/sys v0.0.0-20211205182925-97ca703d548d/go.mod h1:oPkhp1MJrh7nUepCBc
 golang.org/x/sys v0.0.0-20211210111614-af8b64212486/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220114195835-da31bd327af9 h1:XfKQ4OlFl8okEOr5UvAqFRVj8pY/4yfcXrddB8qAbU0=
 golang.org/x/sys v0.0.0-20220114195835-da31bd327af9/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.0.0-20220227234510-4e6760a101f9 h1:nhht2DYV/Sn3qOayu8lM+cU1ii9sTLUeBQwQQfUHtrs=
+golang.org/x/sys v0.0.0-20220227234510-4e6760a101f9/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/term v0.0.0-20201117132131-f5c789dd3221/go.mod h1:Nr5EML6q2oocZ2LXRh80K7BxOlk5/8JxuGnuhpl+muw=
 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=
 golang.org/x/text v0.0.0-20170915032832-14c0d48ead0c/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=

internal/bot/bot.go

@@ -19,9 +19,11 @@ package bot
 
 import (
 	"github.com/Unkn0wnCat/matrix-veles/internal/config"
+	"github.com/Unkn0wnCat/matrix-veles/internal/tracer"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promauto"
 	"github.com/spf13/viper"
+	"go.opentelemetry.io/otel/attribute"
 	"log"
 	"maunium.net/go/mautrix"
 	"maunium.net/go/mautrix/event"
@@ -104,8 +106,11 @@ func Run() {
 
 	matrixClient.StopSync()
 
+	tracer.TraceProvider.Shutdown(tracer.Ctx)
+
 	log.Printf("Goodbye!")
 
+	tracer.Cancel()
 	os.Exit(0)
 }
 
@@ -156,21 +161,29 @@ func performLogin(matrixClient *mautrix.Client) {
 
 // doInitialUpdate updates the config right after startup to catch up with joined/left rooms
 func doInitialUpdate(matrixClient *mautrix.Client) {
+	ctx, span := tracer.Tracer.Start(tracer.Ctx, "initial_update")
+	defer span.End()
+
+	_, requestSpan := tracer.Tracer.Start(ctx, "request_joined_rooms")
 	resp, err := matrixClient.JoinedRooms()
 	if err != nil {
 		log.Printf("matrix-veles could not read joined rooms, something is horribly wrong")
 		log.Fatalln(err)
 	}
+	requestSpan.End()
 
 	joinedRooms.Set(float64(len(resp.JoinedRooms)))
 
 	// Hand-off list to config helper
-	config.RoomConfigInitialUpdate(resp.JoinedRooms)
+	config.RoomConfigInitialUpdate(resp.JoinedRooms, ctx)
 }
 
 // handleMessageEvent wraps message handler taking the mautrix.Client and start timestamp as parameters
 func handleMessageEvent(matrixClient *mautrix.Client, startTs int64) mautrix.EventHandler {
 	return func(source mautrix.EventSource, evt *event.Event) {
+		ctx, span := tracer.Tracer.Start(tracer.Ctx, "handle_message_event")
+		defer span.End()
+
 		if evt.Timestamp < (startTs * 1000) {
 			// Ignore old events
 			return
@@ -192,20 +205,25 @@ func handleMessageEvent(matrixClient *mautrix.Client, startTs int64) mautrix.Eve
 		}
 
 		if content.URL != "" {
+			span.SetAttributes(attribute.Bool("has_attachment", true))
 			// This has an attachment!
-			handleHashing(content, evt, matrixClient) // -> handleHashing.go
+			handleHashing(content, evt, matrixClient, ctx) // -> handleHashing.go
 			return
 		}
+		span.SetAttributes(attribute.Bool("has_attachment", false))
 
 		// No attachment, is this a command?
 		if !strings.HasPrefix(content.Body, "!"+username) &&
 			!strings.HasPrefix(content.Body, "@"+username) &&
 			!(strings.HasPrefix(content.Body, username) && strings.HasPrefix(content.FormattedBody, "<a href=\"https://matrix.to/#/"+matrixClient.UserID.String()+"\">")) {
+			span.SetAttributes(attribute.Bool("is_command", false))
 			return
 		}
 
+		span.SetAttributes(attribute.Bool("is_command", true))
+
 		// It is a command!
-		handleCommand(content.Body, evt.Sender, evt.RoomID, matrixClient) // -> commandParser.go
+		handleCommand(content.Body, evt.Sender, evt.RoomID, matrixClient, ctx) // -> commandParser.go
 	}
 }
 

internal/bot/commandParser.go

@@ -18,6 +18,9 @@
 package bot
 
 import (
+	"context"
+	"github.com/Unkn0wnCat/matrix-veles/internal/tracer"
+	"go.opentelemetry.io/otel/attribute"
 	"log"
 	"maunium.net/go/mautrix"
 	"maunium.net/go/mautrix/id"
@@ -25,9 +28,15 @@ import (
 )
 
 // handleCommand takes a command, parses it and executes any actions it implies
-func handleCommand(command string, sender id.UserID, id id.RoomID, client *mautrix.Client) {
+func handleCommand(command string, sender id.UserID, id id.RoomID, client *mautrix.Client, parentCtx context.Context) {
+	ctx, span := tracer.Tracer.Start(parentCtx, "handle_command")
+	defer span.End()
+
+	_, prepSpan := tracer.Tracer.Start(ctx, "command_prepare")
+
 	myUsername, _, err := client.UserID.Parse()
 	if err != nil {
+		prepSpan.RecordError(err)
 		log.Panicln("Invalid user id in client")
 	}
 
@@ -39,6 +48,10 @@ func handleCommand(command string, sender id.UserID, id id.RoomID, client *mautr
 	command = strings.TrimPrefix(command, ":")        // Remove : (as in "@soccerbot:")
 	command = strings.TrimSpace(command)
 
+	prepSpan.End()
+
+	span.SetAttributes(attribute.String("veles.command_handler.command", command))
+
 	// TODO: Remove this, it is debug!
 	log.Println(command)
 

internal/bot/handleHashing.go

@@ -2,6 +2,7 @@ package bot
 
 import (
 	"bytes"
+	"context"
 	"crypto/sha512"
 	"encoding/hex"
 	"encoding/json"
@@ -10,9 +11,11 @@ import (
 	"github.com/Unkn0wnCat/matrix-veles/internal/config"
 	"github.com/Unkn0wnCat/matrix-veles/internal/db"
 	"github.com/Unkn0wnCat/matrix-veles/internal/db/model"
+	"github.com/Unkn0wnCat/matrix-veles/internal/tracer"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promauto"
 	"go.mongodb.org/mongo-driver/mongo"
+	"go.opentelemetry.io/otel/attribute"
 	"io"
 	"log"
 	"maunium.net/go/mautrix"
@@ -35,38 +38,62 @@ var (
 )
 
 // handleHashing hashes and checks a message, taking configured actions on match
-func handleHashing(content *event.MessageEventContent, evt *event.Event, matrixClient *mautrix.Client) {
+func handleHashing(content *event.MessageEventContent, evt *event.Event, matrixClient *mautrix.Client, parentCtx context.Context) {
+	ctx, span := tracer.Tracer.Start(parentCtx, "handle_hashing")
+	defer span.End()
+
 	url, err := content.URL.Parse()
 	if err != nil {
+		span.RecordError(err)
 		log.Printf("Error: Could not parse Content-URL: \"%s\" - %v", content.URL, err)
 		return
 	}
 
+	_, dlSpan := tracer.Tracer.Start(ctx, "download_and_hash_attachment")
+
 	reader, err := matrixClient.Download(url)
 	if err != nil {
 		log.Printf("Error: Could not read file from Content-URL: \"%s\" - %v", content.URL, err)
 		return
 	}
 
+	dlSpan.AddEvent("reader opened")
+
 	defer func(reader io.ReadCloser) { _ = reader.Close() }(reader)
 
 	hashWriter := sha512.New()
+
+	dlSpan.AddEvent("hash writer ready")
+
 	if _, err = io.Copy(hashWriter, reader); err != nil {
+		dlSpan.RecordError(err)
 		log.Printf("Error: Could not hash file from Content-URL: \"%s\" - %v", content.URL, err)
 		return
 	}
 
+	dlSpan.End()
+
 	sum := hex.EncodeToString(hashWriter.Sum(nil))
 
+	_, rcSpan := tracer.Tracer.Start(ctx, "db_fetch_room_config")
+
 	// Fetch room configuration for adjusting behaviour
 	roomConfig := config.GetRoomConfig(evt.RoomID.String())
 
+	rcSpan.End()
+
 	defer filesProcessed.Inc()
 
+	_, hashCheckSpan := tracer.Tracer.Start(ctx, "check_hash")
+
 	hashObj, err := db.GetEntryByHash(sum)
 	if err != nil {
 		if errors.Is(err, mongo.ErrNoDocuments) {
 			filesCleared.Inc()
+			hashCheckSpan.AddEvent("hash not in database - file cleared")
+			hashCheckSpan.SetAttributes(attribute.Bool("veles.hash_checker.hash_match", false))
+			hashCheckSpan.SetAttributes(attribute.Bool("veles.hash_checker.illegal_content", false))
+			hashCheckSpan.End()
 			if roomConfig.Debug {
 				matrixClient.SendNotice(evt.RoomID, fmt.Sprintf("DEBUG - This file is not on the hashlist: %s", sum))
 			}
@@ -75,10 +102,14 @@ func handleHashing(content *event.MessageEventContent, evt *event.Event, matrixC
 		if roomConfig.Debug {
 			matrixClient.SendNotice(evt.RoomID, "DEBUG - Failed to check file. See log.")
 		}
+		hashCheckSpan.RecordError(err)
 		fmt.Printf("Error trying to check database: %v", err)
 		return
 	}
 
+	hashCheckSpan.AddEvent("hash found in database")
+	hashCheckSpan.SetAttributes(attribute.Bool("veles.hash_checker.hash_match", true))
+
 	if roomConfig.Debug {
 		matrixClient.SendNotice(evt.RoomID, fmt.Sprintf("DEBUG !!! This file is on the hashlist: %s", sum))
 		jsonVal, _ := json.Marshal(hashObj)
@@ -86,12 +117,18 @@ func handleHashing(content *event.MessageEventContent, evt *event.Event, matrixC
 	}
 
 	if !checkSubscription(&roomConfig, hashObj) {
+		hashCheckSpan.AddEvent("room not subscribed to hash list - ignoring")
+		hashCheckSpan.SetAttributes(attribute.Bool("veles.hash_checker.illegal_content", false))
+		hashCheckSpan.End()
 		return
 	}
 
+	hashCheckSpan.SetAttributes(attribute.Bool("veles.hash_checker.illegal_content", true))
+	hashCheckSpan.End()
+
 	log.Printf("Illegal content detected in room %s!", roomConfig.RoomID)
 
-	handleIllegalContent(evt, matrixClient, hashObj, roomConfig)
+	handleIllegalContent(evt, matrixClient, hashObj, roomConfig, ctx)
 }
 
 // makeFancyJSON formats / indents a JSON string
@@ -135,49 +172,60 @@ func checkSubscription(roomConfig *config.RoomConfig, hashObj *model.DBEntry) bo
 }
 
 // handleIllegalContent is called when a hash-match is found to take configured actions
-func handleIllegalContent(evt *event.Event, matrixClient *mautrix.Client, hashObj *model.DBEntry, roomConfig config.RoomConfig) {
+func handleIllegalContent(evt *event.Event, matrixClient *mautrix.Client, hashObj *model.DBEntry, roomConfig config.RoomConfig, parentCtx context.Context) {
+	ctx, span := tracer.Tracer.Start(parentCtx, "handle_hashing")
+	defer span.End()
+
 	filesFlagged.Inc()
 
 	switch roomConfig.HashChecker.HashCheckMode {
 	case 0:
-		postNotice(evt, matrixClient, hashObj, roomConfig)
+		postNotice(evt, matrixClient, hashObj, roomConfig, ctx)
 		break
 	case 1:
-		redactMessage(evt, matrixClient, hashObj)
+		redactMessage(evt, matrixClient, hashObj, ctx)
 		if roomConfig.HashChecker.NoticeToChat {
-			postNotice(evt, matrixClient, hashObj, roomConfig)
+			postNotice(evt, matrixClient, hashObj, roomConfig, ctx)
 		}
 		break
 	case 2:
-		muteUser(evt, matrixClient)
+		muteUser(evt, matrixClient, ctx)
-		redactMessage(evt, matrixClient, hashObj)
+		redactMessage(evt, matrixClient, hashObj, ctx)
 		if roomConfig.HashChecker.NoticeToChat {
-			postNotice(evt, matrixClient, hashObj, roomConfig)
+			postNotice(evt, matrixClient, hashObj, roomConfig, ctx)
 		}
 		break
 	case 3:
-		banUser(evt, matrixClient, hashObj)
+		banUser(evt, matrixClient, hashObj, ctx)
-		redactMessage(evt, matrixClient, hashObj)
+		redactMessage(evt, matrixClient, hashObj, ctx)
 		if roomConfig.HashChecker.NoticeToChat {
-			postNotice(evt, matrixClient, hashObj, roomConfig)
+			postNotice(evt, matrixClient, hashObj, roomConfig, ctx)
 		}
 		break
 	}
 }
 
 // redactMessage deletes the message sent in the given event
-func redactMessage(evt *event.Event, matrixClient *mautrix.Client, hashObj *model.DBEntry) {
+func redactMessage(evt *event.Event, matrixClient *mautrix.Client, hashObj *model.DBEntry, ctx context.Context) {
+	ctx, span := tracer.Tracer.Start(ctx, "redact_message")
+	defer span.End()
+
 	opts := mautrix.ReqRedact{Reason: fmt.Sprintf("Veles has detected an hash-map-match! Tags: %s, ID: %s", hashObj.Tags, hashObj.ID.Hex())}
 	_, err := matrixClient.RedactEvent(evt.RoomID, evt.ID, opts)
 	if err != nil {
+		span.RecordError(err)
 		log.Printf("ERROR: Could not redact event - %v", err)
 	}
 }
 
 // muteUser sets a users power-level to -1 to prevent them from sending messages
-func muteUser(evt *event.Event, matrixClient *mautrix.Client) {
+func muteUser(evt *event.Event, matrixClient *mautrix.Client, ctx context.Context) {
+	ctx, span := tracer.Tracer.Start(ctx, "mute_user")
+	defer span.End()
+
 	plEventContent, err := GetRoomPowerLevelState(matrixClient, evt.RoomID)
 	if err != nil {
+		span.RecordError(err)
 		log.Printf("ERROR: Could mute user - %v", err)
 		return
 	}
@@ -186,31 +234,46 @@ func muteUser(evt *event.Event, matrixClient *mautrix.Client) {
 
 	_, err = matrixClient.SendStateEvent(evt.RoomID, event.StatePowerLevels, "", plEventContent)
 	if err != nil {
+		span.RecordError(err)
 		log.Printf("ERROR: Could mute user - %v", err)
 		return
 	}
 }
 
 // banUser bans the sender of an event from the room
-func banUser(evt *event.Event, matrixClient *mautrix.Client, hashObj *model.DBEntry) {
+func banUser(evt *event.Event, matrixClient *mautrix.Client, hashObj *model.DBEntry, ctx context.Context) {
+	ctx, span := tracer.Tracer.Start(ctx, "post_notice")
+	defer span.End()
+
 	req := mautrix.ReqBanUser{
 		Reason: fmt.Sprintf("Veles has detected an hash-map-match! Tags: %s, ID: %s", hashObj.Tags, hashObj.ID.Hex()),
 		UserID: evt.Sender,
 	}
 
-	matrixClient.BanUser(evt.RoomID, &req)
+	_, err := matrixClient.BanUser(evt.RoomID, &req)
+	if err != nil {
+		span.RecordError(err)
+	}
 }
 
 // postNotice posts a notice about the given event into its room
-func postNotice(evt *event.Event, matrixClient *mautrix.Client, hashObj *model.DBEntry, roomConfig config.RoomConfig) {
+func postNotice(evt *event.Event, matrixClient *mautrix.Client, hashObj *model.DBEntry, roomConfig config.RoomConfig, ctx context.Context) {
+	ctx, span := tracer.Tracer.Start(ctx, "post_notice")
+	defer span.End()
+
 	local, server, err := evt.Sender.Parse()
 	if err != nil {
+		span.RecordError(err)
 		return
 	}
-	matrixClient.SendNotice(evt.RoomID, fmt.Sprintf(
+	_, err = matrixClient.SendNotice(evt.RoomID, fmt.Sprintf(
 		`Veles Triggered: The message by %s (on %s) was flagged for containing material used by spammers or trolls!
 
 If you believe this action was an accident, please contact an room administrator or moderator. (Reference: %s)`, local, server, hashObj.ID.Hex()))
+	if err != nil {
+		span.RecordError(err)
+		return
+	}
 
 }
 

internal/config/helpers.go

@@ -21,6 +21,7 @@ import (
 	"context"
 	"errors"
 	"github.com/Unkn0wnCat/matrix-veles/internal/db"
+	"github.com/Unkn0wnCat/matrix-veles/internal/tracer"
 	"github.com/spf13/viper"
 	"go.mongodb.org/mongo-driver/bson"
 	"go.mongodb.org/mongo-driver/bson/primitive"
@@ -66,11 +67,16 @@ func GetRoomConfig(id string) RoomConfig {
 }
 
 // RoomConfigInitialUpdate updates all RoomConfig entries to set activity and create blank configs
-func RoomConfigInitialUpdate(ids []id.RoomID) {
+func RoomConfigInitialUpdate(ids []id.RoomID, parentCtx context.Context) {
+	ctx, span := tracer.Tracer.Start(parentCtx, "initial_room_config_update")
+	defer span.End()
+
+	_, dbGetAllSpan := tracer.Tracer.Start(ctx, "db_fetch_room_configs")
 	database := db.DbClient.Database(viper.GetString("bot.mongo.database"))
 
 	cursor, err := database.Collection("rooms").Find(context.TODO(), bson.D{}, nil)
 	if err != nil {
+		dbGetAllSpan.RecordError(err)
 		log.Panicf("Error querying room configs: %v", err)
 	}
 
@@ -78,9 +84,14 @@ func RoomConfigInitialUpdate(ids []id.RoomID) {
 
 	err = cursor.All(context.TODO(), &roomConfigs)
 	if err != nil {
+		dbGetAllSpan.RecordError(err)
 		log.Panicf("Error querying room configs: %v", err)
 	}
 
+	dbGetAllSpan.End()
+
+	ctx2, updateConfigs := tracer.Tracer.Start(ctx, "update_room_configs")
+
 	activeRooms := make(map[string]bool)
 
 	// Set all active states to "false" for a blank start
@@ -88,16 +99,22 @@ func RoomConfigInitialUpdate(ids []id.RoomID) {
 		activeRooms[roomConfig.RoomID] = false
 	}
 
+	_, updateRooms := tracer.Tracer.Start(ctx2, "update_joined_rooms")
 	// Go over all joined rooms
 	for _, roomID := range ids {
 		activeRooms[roomID.String()] = true
 
 		GetRoomConfig(roomID.String())
 	}
+	updateRooms.End()
 
+	_, saveConfigs := tracer.Tracer.Start(ctx2, "save_room_configs")
 	for roomID, isActive := range activeRooms {
 		SetRoomConfigActive(roomID, isActive)
 	}
+	saveConfigs.End()
+
+	updateConfigs.End()
 }
 
 func AddRoomConfig(id string) RoomConfig {

internal/tracer/setupJaeger.go

@@ -0,0 +1,69 @@
+package tracer
+
+import (
+	"context"
+	"github.com/spf13/viper"
+	"go.opentelemetry.io/otel"
+	"go.opentelemetry.io/otel/attribute"
+	"go.opentelemetry.io/otel/exporters/jaeger"
+	"go.opentelemetry.io/otel/sdk/resource"
+	tracesdk "go.opentelemetry.io/otel/sdk/trace"
+	semconv "go.opentelemetry.io/otel/semconv/v1.4.0"
+	"go.opentelemetry.io/otel/trace"
+	"log"
+	"os"
+	"runtime"
+	"runtime/debug"
+)
+
+var (
+	TraceProvider *tracesdk.TracerProvider
+	Ctx           context.Context
+	Cancel        context.CancelFunc
+	Tracer        trace.Tracer
+)
+
+func SetupDummy() {
+	tp := tracesdk.NewTracerProvider()
+	TraceProvider = tp
+	Ctx, Cancel = context.WithCancel(context.Background())
+	Tracer = tp.Tracer("matrix_veles")
+}
+
+func SetupJaeger() {
+	exp, err := jaeger.New(jaeger.WithCollectorEndpoint(jaeger.WithEndpoint(viper.GetString("tracing.jaeger.endpoint"))))
+	if err != nil {
+		log.Fatal(err)
+	}
+
+	bi, ok := debug.ReadBuildInfo()
+	if !ok {
+		log.Fatal(ok)
+	}
+
+	hostname, err := os.Hostname()
+	if err != nil {
+		log.Fatal(err)
+	}
+
+	tp := tracesdk.NewTracerProvider(
+		// Always be sure to batch in production.
+		tracesdk.WithBatcher(exp),
+		// Record information about this application in a Resource.
+		tracesdk.WithResource(resource.NewWithAttributes(
+			semconv.SchemaURL,
+			semconv.ServiceNameKey.String("matrix_veles"),
+			attribute.String("version", bi.Main.Version),
+			attribute.String("go_version", runtime.Version()),
+			attribute.String("hostname", hostname),
+			attribute.String("os", runtime.GOOS),
+			attribute.String("arch", runtime.GOARCH),
+		)),
+	)
+
+	otel.SetTracerProvider(tp)
+
+	TraceProvider = tp
+	Ctx, Cancel = context.WithCancel(context.Background())
+	Tracer = tp.Tracer("matrix_veles")
+}