Debugging

discordextremelist · Aug 19, 2020 · 44a4b1d · 44a4b1d
1 parent 5f047b4
commit 44a4b1d
Show file tree

Hide file tree

Showing 9 changed files with 265 additions and 31 deletions.
diff --git a/entities/bot.go b/entities/bot.go
@@ -7,6 +7,7 @@ import (
 	log "github.com/sirupsen/logrus"
 	"go.mongodb.org/mongo-driver/bson"
 	"go.mongodb.org/mongo-driver/mongo"
+	"time"
 )
 
 type BotStatus struct {
@@ -76,20 +77,32 @@ func CleanupBot(rank UserRank, bot *Bot) *Bot {
 }
 
 func mongoLookupBot(id string) (error, *Bot) {
+	findStart := time.Now()
+	var findEnd int64
 	res := util.Database.Mongo.Collection("bots").FindOne(context.TODO(), bson.M{"_id": id})
 	if res.Err() != nil {
+		AddMongoLookupTime("bots", id, time.Since(findStart).Microseconds(), -1)
 		return res.Err(), nil
 	}
+	findEnd = time.Since(findStart).Microseconds()
 	bot := Bot{}
+	decodeStart := time.Now()
+	var decodeEnd int64
 	if err := res.Decode(&bot); err != nil {
+		AddMongoLookupTime("bots", id, findEnd, time.Since(decodeStart).Microseconds())
 		return err, nil
 	}
+	decodeEnd = time.Since(decodeStart).Microseconds()
+	AddMongoLookupTime("bots", id, findEnd, decodeEnd)
 	return nil, &bot
 }
 
 func LookupBot(id string, clean bool) (error, *Bot) {
+	findStart := time.Now()
+	var findEnd int64
 	redisBot, err := util.Database.Redis.HGet(context.TODO(), "bots", id).Result()
 	if err == nil {
+		findEnd = time.Since(findStart).Microseconds()
 		if redisBot == "" {
 			err, bot := mongoLookupBot(id)
 			bot.MongoID = ""
@@ -107,8 +120,10 @@ func LookupBot(id string, clean bool) (error, *Bot) {
 			}
 		}
 		bot := &Bot{}
+		decodeStart := time.Now()
 		err = json.Unmarshal([]byte(redisBot), &bot)
 		if err != nil {
+			AddRedisLookupTime("bots", id, findEnd, time.Since(decodeStart).Microseconds())
 			log.Errorf("Json parsing failed for LookupBot(%s): %v", id, err.Error())
 			return LookupError, nil
 		} else {
@@ -121,6 +136,7 @@ func LookupBot(id string, clean bool) (error, *Bot) {
 			if clean {
 				bot = CleanupBot(fakeRank, bot)
 			}
+			AddRedisLookupTime("bots", id, findEnd, time.Since(decodeStart).Microseconds())
 			return nil, bot
 		}
 	} else {

diff --git a/entities/debug.go b/entities/debug.go
@@ -0,0 +1,98 @@
+package entities
+
+import (
+	"sync"
+)
+
+type ResponseTime struct {
+	Path                 string `json:"path,omitempty"`
+	TimeTakenToLookup    int64  `json:"time_taken_to_lookup"`
+	TimeSpentDecoding    int64  `json:"time_spent_decoding"`
+	TimeSpentWritingBody int64  `json:"time_spent_writing_body"`
+}
+
+type LookupTimes struct {
+	Mongo map[string]map[string][]ResponseTime `json:"mongo"`
+	Redis map[string]map[string][]ResponseTime `json:"redis"`
+}
+
+type DebugStatistics struct {
+	MongoPing     int64          `json:"mongo_ping"`
+	RedisPing     int64          `json:"redis_ping"`
+	LookupTimes   LookupTimes    `json:"lookup_times"`
+	ResponseTimes []ResponseTime `json:"response_times"`
+	Hostname      string         `json:"hostname"`
+}
+
+var (
+	MongoLookupTimes = make(map[string]map[string][]ResponseTime)
+	RedisLookupTimes = make(map[string]map[string][]ResponseTime)
+	ResponseTimes    []ResponseTime
+	mutex            = &sync.Mutex{}
+)
+
+func AddMongoLookupTime(col, id string, lookup int64, unmarshal int64) {
+	mutex.Lock()
+	defer mutex.Unlock()
+	if _, ok := MongoLookupTimes[col]; ok {
+		if itemEntry, ok := MongoLookupTimes[col][id]; ok {
+			itemEntry = append(itemEntry, ResponseTime{
+				TimeTakenToLookup:    lookup,
+				TimeSpentDecoding:    unmarshal,
+				TimeSpentWritingBody: 0,
+			})
+			MongoLookupTimes[col][id] = itemEntry
+		} else {
+			MongoLookupTimes[col][id] = []ResponseTime{
+				{
+					TimeTakenToLookup:    lookup,
+					TimeSpentDecoding:    unmarshal,
+					TimeSpentWritingBody: 0,
+				},
+			}
+		}
+	} else {
+		MongoLookupTimes[col] = map[string][]ResponseTime{
+			id: {
+				{
+					TimeTakenToLookup:    lookup,
+					TimeSpentDecoding:    unmarshal,
+					TimeSpentWritingBody: 0,
+				},
+			},
+		}
+	}
+}
+
+func AddRedisLookupTime(col, id string, lookup int64, unmarshal int64) {
+	mutex.Lock()
+	defer mutex.Unlock()
+	if _, ok := RedisLookupTimes[col]; ok {
+		if itemEntry, ok := RedisLookupTimes[col][id]; ok {
+			itemEntry = append(itemEntry, ResponseTime{
+				TimeTakenToLookup:    lookup,
+				TimeSpentDecoding:    unmarshal,
+				TimeSpentWritingBody: -1,
+			})
+			RedisLookupTimes[col][id] = itemEntry
+		} else {
+			RedisLookupTimes[col][id] = []ResponseTime{
+				{
+					TimeTakenToLookup:    lookup,
+					TimeSpentDecoding:    unmarshal,
+					TimeSpentWritingBody: -1,
+				},
+			}
+		}
+	} else {
+		RedisLookupTimes[col] = map[string][]ResponseTime{
+			id: {
+				{
+					TimeTakenToLookup:    lookup,
+					TimeSpentDecoding:    unmarshal,
+					TimeSpentWritingBody: -1,
+				},
+			},
+		}
+	}
+}
diff --git a/entities/response.go b/entities/response.go
@@ -3,8 +3,12 @@ package entities
 import (
 	"encoding/json"
 	"errors"
+	"fmt"
 	"github.com/discordextremelist/api/util"
+	"github.com/go-chi/chi/middleware"
+	log "github.com/sirupsen/logrus"
 	"net/http"
+	"time"
 )
 
 type APIHealthResponse struct {
@@ -94,12 +98,46 @@ var (
 	BadContentType     = buildInternal(true, 415, "Unsupported Content Type, or non was provided!", nil, nil, nil, nil)
 )
 
+func doLog(start time.Time, w middleware.WrapResponseWriter, r *http.Request) {
+	ResponseTimes = append(ResponseTimes, ResponseTime{
+		Path:                 r.URL.String(),
+		TimeSpentWritingBody: time.Since(start).Microseconds(),
+	})
+	log.Info(fmt.Sprintf(
+		`%s - "%s %s %s" %d %d %s`,
+		r.RemoteAddr,
+		r.Method,
+		r.URL,
+		r.Proto,
+		w.BytesWritten(),
+		w.Status(),
+		time.Since(start),
+	))
+}
+
+func RequestLogger(handler http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		start := time.Now()
+		ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor)
+		defer doLog(start, ww, r)
+		handler.ServeHTTP(ww, r)
+	})
+}
+
 func WriteJson(status int, writer http.ResponseWriter, v interface{}) {
 	writer.Header().Set("Content-Type", "application/json")
 	writer.WriteHeader(status)
 	json.NewEncoder(writer).Encode(v)
 }
 
+func WritePrettyJson(status int, writer http.ResponseWriter, v interface{}) {
+	writer.Header().Set("Content-Type", "application/json")
+	writer.WriteHeader(status)
+	encoder := json.NewEncoder(writer)
+	encoder.SetIndent("", "    ")
+	encoder.Encode(v)
+}
+
 func WriteErrorResponse(w http.ResponseWriter, err error) {
 	WriteJson(500, w, buildInternal(true, 500, err.Error(), nil, nil, nil, nil))
 }
@@ -129,7 +167,7 @@ func WriteNotImplementedResponse(w http.ResponseWriter) {
 // DELAPI_xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx-000000000000000000
 func TokenValidator(next http.Handler) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		if r.URL.Path == "/health" || util.CheckIP(r.RemoteAddr) {
+		if r.URL.Path == "/health" || r.URL.Path == "/debug" || util.CheckIP(r.RemoteAddr) {
 			next.ServeHTTP(w, r)
 			return
 		}

diff --git a/entities/server.go b/entities/server.go
@@ -7,6 +7,7 @@ import (
 	log "github.com/sirupsen/logrus"
 	"go.mongodb.org/mongo-driver/bson"
 	"go.mongodb.org/mongo-driver/mongo"
+	"time"
 )
 
 type ServerLinks struct {
@@ -40,20 +41,32 @@ func CleanupServer(rank UserRank, server *Server) *Server {
 }
 
 func mongoLookupServer(id string) (error, *Server) {
+	findStart := time.Now()
+	var findEnd int64
 	res := util.Database.Mongo.Collection("servers").FindOne(context.TODO(), bson.M{"_id": id})
 	if res.Err() != nil {
+		AddMongoLookupTime("servers", id, time.Since(findStart).Microseconds(), -1)
 		return res.Err(), nil
 	}
+	findEnd = time.Since(findStart).Microseconds()
 	server := Server{}
+	decodeStart := time.Now()
+	var decodeEnd int64
 	if err := res.Decode(&server); err != nil {
+		AddMongoLookupTime("servers", id, findEnd, time.Since(decodeStart).Microseconds())
 		return err, nil
 	}
+	decodeEnd = time.Since(decodeStart).Microseconds()
+	AddMongoLookupTime("servers", id, findEnd, decodeEnd)
 	return nil, &server
 }
 
 func LookupServer(id string, clean bool) (error, *Server) {
+	findStart := time.Now()
+	var findEnd int64
 	redisServer, err := util.Database.Redis.HGet(context.TODO(), "servers", id).Result()
 	if err == nil {
+		findEnd = time.Since(findStart).Microseconds()
 		if redisServer == "" {
 			err, server := mongoLookupServer(id)
 			server.MongoID = ""
@@ -71,11 +84,10 @@ func LookupServer(id string, clean bool) (error, *Server) {
 			}
 		}
 		server := &Server{}
+		decodeStart := time.Now()
 		err = json.Unmarshal([]byte(redisServer), &server)
 		if err != nil {
-			if err == mongo.ErrNoDocuments {
-				return err, nil
-			}
+			AddRedisLookupTime("servers", id, findEnd, time.Since(decodeStart).Microseconds())
 			log.Errorf("Json parsing failed for LookupServer(%s): %v", id, err.Error())
 			return LookupError, nil
 		} else {
@@ -88,6 +100,7 @@ func LookupServer(id string, clean bool) (error, *Server) {
 			if clean {
 				server = CleanupServer(fakeRank, server)
 			}
+			AddRedisLookupTime("servers", id, findEnd, time.Since(decodeStart).Microseconds())
 			return nil, server
 		}
 	} else {

diff --git a/entities/template.go b/entities/template.go
@@ -7,6 +7,7 @@ import (
 	log "github.com/sirupsen/logrus"
 	"go.mongodb.org/mongo-driver/bson"
 	"go.mongodb.org/mongo-driver/mongo"
+	"time"
 )
 
 type Role struct {
@@ -67,20 +68,32 @@ type ServerTemplate struct {
 }
 
 func mongoLookupTemplate(id string) (error, *ServerTemplate) {
+	findStart := time.Now()
+	var findEnd int64
 	res := util.Database.Mongo.Collection("templates").FindOne(context.TODO(), bson.M{"_id": id})
 	if res.Err() != nil {
+		AddMongoLookupTime("templates", id, time.Since(findStart).Microseconds(), -1)
 		return res.Err(), nil
 	}
+	findEnd = time.Since(findStart).Microseconds()
 	template := ServerTemplate{}
+	decodeStart := time.Now()
+	var decodeEnd int64
 	if err := res.Decode(&template); err != nil {
+		AddMongoLookupTime("templates", id, findEnd, time.Since(decodeStart).Microseconds())
 		return err, nil
 	}
+	decodeEnd = time.Since(decodeStart).Microseconds()
+	AddMongoLookupTime("templates", id, findEnd, decodeEnd)
 	return nil, &template
 }
 
 func LookupTemplate(id string) (error, *ServerTemplate) {
+	findStart := time.Now()
+	var findEnd int64
 	redisTemplate, err := util.Database.Redis.HGet(context.TODO(), "templates", id).Result()
 	if err == nil {
+		findEnd = time.Since(findStart).Microseconds()
 		if redisTemplate == "" {
 			err, template := mongoLookupTemplate(id)
 			template.MongoID = ""
@@ -95,8 +108,10 @@ func LookupTemplate(id string) (error, *ServerTemplate) {
 			}
 		}
 		template := &ServerTemplate{}
+		decodeStart := time.Now()
 		err = json.Unmarshal([]byte(redisTemplate), &template)
 		if err != nil {
+			AddRedisLookupTime("templates", id, findEnd, time.Since(decodeStart).Microseconds())
 			log.Errorf("Json parsing failed for LookupTemplate(%s): %v", id, err.Error())
 			return LookupError, nil
 		} else {
@@ -106,6 +121,7 @@ func LookupTemplate(id string) (error, *ServerTemplate) {
 			} else {
 				template.MongoID = ""
 			}
+			AddRedisLookupTime("templates", id, findEnd, time.Since(decodeStart).Microseconds())
 			return nil, template
 		}
 	} else {