Add events handlers to reimplement all statsd metrics, available before refactoring.

Tests aren't working at this time :(
Removed mojang_textures.invalid_username metric.

CHANGELOG.md

@@ -34,6 +34,9 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 - **BREAKING**: Event `ely.skinsystem.{hostname}.app.mojang_textures.already_in_queue` has been renamed into
   `ely.skinsystem.{hostname}.app.mojang_textures.already_scheduled`.
 
+### Removed
+- **BREAKING**: `ely.skinsystem.{hostname}.app.mojang_textures.invalid_username` counter has been removed.
+
 ## [4.3.0] - 2019-11-08
 ### Added
 - 403 Forbidden errors from the Mojang's API are now logged.

eventsubscribers/stats_reporter.go

@@ -3,25 +3,104 @@ package eventsubscribers
 import (
 	"net/http"
 	"strings"
+	"sync"
+	"time"
 
 	"github.com/mono83/slf"
 
+	"github.com/elyby/chrly/api/mojang"
 	"github.com/elyby/chrly/dispatcher"
 )
 
 type StatsReporter struct {
 	Reporter slf.StatsReporter
 	Prefix   string
+
+	timersMap sync.Map
 }
 
 func (s *StatsReporter) ConfigureWithDispatcher(d dispatcher.EventDispatcher) {
+	// Per request events
 	d.Subscribe("skinsystem:before_request", s.handleBeforeRequest)
 	d.Subscribe("skinsystem:after_request", s.handleAfterRequest)
 
+	// Authentication events
 	d.Subscribe("authenticator:success", s.incCounterHandler("authentication.challenge")) // TODO: legacy, remove in v5
 	d.Subscribe("authenticator:success", s.incCounterHandler("authentication.success"))
 	d.Subscribe("authentication:error", s.incCounterHandler("authentication.challenge")) // TODO: legacy, remove in v5
 	d.Subscribe("authentication:error", s.incCounterHandler("authentication.failed"))
+
+	// Mojang signed textures source events
+	d.Subscribe("mojang_textures:call", s.incCounterHandler("mojang_textures.request"))
+	d.Subscribe("mojang_textures:usernames:after_cache", func(username string, uuid string, err error) {
+		if err != nil {
+			return
+		}
+
+		if uuid == "" {
+			s.incCounter("mojang_textures:usernames:cache_hit_nil")
+		} else {
+			s.incCounter("mojang_textures:usernames:cache_hit")
+		}
+	})
+	d.Subscribe("mojang_textures:textures:after_cache", func(uuid string, textures *mojang.SignedTexturesResponse, err error) {
+		if err != nil {
+			return
+		}
+
+		if textures != nil {
+			s.incCounter("mojang_textures.textures.cache_hit")
+		}
+	})
+	d.Subscribe("mojang_textures:already_processing", s.incCounterHandler("mojang_textures.already_scheduled"))
+	d.Subscribe("mojang_textures:usernames:after_call", func(username string, profile *mojang.ProfileInfo, err error) {
+		if err != nil {
+			return
+		}
+
+		if profile == nil {
+			s.incCounter("mojang_textures.usernames.uuid_miss")
+		} else {
+			s.incCounter("mojang_textures.usernames.uuid_hit")
+		}
+	})
+	d.Subscribe("mojang_textures:textures:before_call", s.incCounterHandler("mojang_textures.textures.request"))
+	d.Subscribe("mojang_textures:textures:after_call", func(uuid string, textures *mojang.SignedTexturesResponse, err error) {
+		if err != nil {
+			return
+		}
+
+		if textures == nil {
+			s.incCounter("mojang_textures.usernames.textures_miss")
+		} else {
+			s.incCounter("mojang_textures.usernames.textures_hit")
+		}
+	})
+	d.Subscribe("mojang_textures:before_result", func(username string, uuid string) {
+		s.startTimeRecording("mojang_textures_result_time_" + username)
+	})
+	d.Subscribe("mojang_textures:after_result", func(username string, textures *mojang.SignedTexturesResponse, err error) {
+		s.finalizeTimeRecording("mojang_textures_result_time_"+username, "mojang_textures.result_time")
+	})
+	d.Subscribe("mojang_textures:textures:before_call", func(uuid string) {
+		s.startTimeRecording("mojang_textures_provider_time_" + uuid)
+	})
+	d.Subscribe("mojang_textures:textures:after_call", func(uuid string, textures *mojang.SignedTexturesResponse, err error) {
+		s.finalizeTimeRecording("mojang_textures_provider_time_"+uuid, "mojang_textures.textures.request_time")
+	})
+
+	// Mojang UUIDs batch provider metrics
+	d.Subscribe("mojang_textures:batch_uuids_provider:queued", s.incCounterHandler("mojang_textures.usernames.queued"))
+	d.Subscribe("mojang_textures:batch_uuids_provider:round", func(usernames []string, queueSize int) {
+		s.updateGauge("mojang_textures.usernames.iteration_size", int64(len(usernames)))
+		s.updateGauge("mojang_textures.usernames.queue_size", int64(queueSize))
+	})
+	d.Subscribe("mojang_textures:batch_uuids_provider:before_round", func() {
+		s.startTimeRecording("batch_uuids_provider_round_time")
+	})
+	d.Subscribe("mojang_textures:batch_uuids_provider:after_round", func() {
+		s.finalizeTimeRecording("batch_uuids_provider_round_time", "mojang_textures.usernames.round_time")
+	})
 }
 
 func (s *StatsReporter) handleBeforeRequest(req *http.Request) {
@@ -76,10 +155,36 @@ func (s *StatsReporter) incCounterHandler(name string) func(...interface{}) {
 	}
 }
 
+func (s *StatsReporter) startTimeRecording(timeKey string) {
+	s.timersMap.Store(timeKey, time.Now())
+}
+
+func (s *StatsReporter) finalizeTimeRecording(timeKey string, statName string) {
+	startedAtUncasted, ok := s.timersMap.Load(timeKey)
+	if !ok {
+		return
+	}
+
+	startedAt, ok := startedAtUncasted.(time.Time)
+	if !ok {
+		panic("unable to cast map value to the time.Time")
+	}
+
+	s.recordTimer(statName, time.Since(startedAt))
+}
+
 func (s *StatsReporter) incCounter(name string) {
 	s.Reporter.IncCounter(s.key(name), 1)
 }
 
+func (s *StatsReporter) updateGauge(name string, value int64) {
+	s.Reporter.UpdateGauge(s.key(name), value)
+}
+
+func (s *StatsReporter) recordTimer(name string, duration time.Duration) {
+	s.Reporter.RecordTimer(s.key(name), duration)
+}
+
 func (s *StatsReporter) key(name string) string {
 	return strings.Join([]string{s.Prefix, name}, ".")
 }

eventsubscribers/stats_reporter_test.go

@@ -5,156 +5,239 @@ import (
 	"net/http/httptest"
 	"testing"
 
+	"github.com/stretchr/testify/mock"
+
+	"github.com/elyby/chrly/api/mojang"
 	"github.com/elyby/chrly/dispatcher"
 	"github.com/elyby/chrly/tests"
 )
 
 type StatsReporterTestCase struct {
-	Topic         string
+	Events        map[string][]interface{}
-	Args          []interface{}
 	ExpectedCalls [][]interface{}
 }
 
+type NilErr struct {
+}
+
+func (n *NilErr) Error() string {
+	panic("don't call me")
+}
+
+// This let me to test events with nil error arguments.
+// I can't just use `var nilErr error = nil`, because when Golang calls reflect.ValueOf()
+// its returns only nil, without type. But when he calls reflection on specific structure (or pointer in this case),
+// everything works fine. This is a memorial of 2 hours of my life, debugging and learning from the reflection
+// about Go's types system. Nothing to regret.
+var nilErr *NilErr = nil
+
 var statsReporterTestCases = []*StatsReporterTestCase{
 	// Before request
 	{
-		Topic:         "skinsystem:before_request",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{httptest.NewRequest("GET", "http://localhost/skins/username", nil)},
+			"skinsystem:before_request": {httptest.NewRequest("GET", "http://localhost/skins/username", nil)},
+		},
 		ExpectedCalls: [][]interface{}{
 			{"IncCounter", "mock_prefix.skins.request", int64(1)},
 		},
 	},
 	{
-		Topic:         "skinsystem:before_request",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{httptest.NewRequest("GET", "http://localhost/skins?name=username", nil)},
+			"skinsystem:before_request": {httptest.NewRequest("GET", "http://localhost/skins?name=username", nil)},
+		},
 		ExpectedCalls: [][]interface{}{
 			{"IncCounter", "mock_prefix.skins.get_request", int64(1)},
 		},
 	},
 	{
-		Topic:         "skinsystem:before_request",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{httptest.NewRequest("GET", "http://localhost/cloaks/username", nil)},
+			"skinsystem:before_request": {httptest.NewRequest("GET", "http://localhost/cloaks/username", nil)},
+		},
 		ExpectedCalls: [][]interface{}{
 			{"IncCounter", "mock_prefix.capes.request", int64(1)},
 		},
 	},
 	{
-		Topic:         "skinsystem:before_request",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{httptest.NewRequest("GET", "http://localhost/cloaks?name=username", nil)},
+			"skinsystem:before_request": {httptest.NewRequest("GET", "http://localhost/cloaks?name=username", nil)},
+		},
 		ExpectedCalls: [][]interface{}{
 			{"IncCounter", "mock_prefix.capes.get_request", int64(1)},
 		},
 	},
 	{
-		Topic:         "skinsystem:before_request",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{httptest.NewRequest("GET", "http://localhost/textures/username", nil)},
+			"skinsystem:before_request": {httptest.NewRequest("GET", "http://localhost/textures/username", nil)},
+		},
 		ExpectedCalls: [][]interface{}{
 			{"IncCounter", "mock_prefix.textures.request", int64(1)},
 		},
 	},
 	{
-		Topic:         "skinsystem:before_request",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{httptest.NewRequest("GET", "http://localhost/textures/signed/username", nil)},
+			"skinsystem:before_request": {httptest.NewRequest("GET", "http://localhost/textures/signed/username", nil)},
+		},
 		ExpectedCalls: [][]interface{}{
 			{"IncCounter", "mock_prefix.signed_textures.request", int64(1)},
 		},
 	},
 	{
-		Topic:         "skinsystem:before_request",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{httptest.NewRequest("POST", "http://localhost/api/skins", nil)},
+			"skinsystem:before_request": {httptest.NewRequest("POST", "http://localhost/api/skins", nil)},
+		},
 		ExpectedCalls: [][]interface{}{
 			{"IncCounter", "mock_prefix.api.skins.post.request", int64(1)},
 		},
 	},
 	{
-		Topic:         "skinsystem:before_request",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{httptest.NewRequest("DELETE", "http://localhost/api/skins/username", nil)},
+			"skinsystem:before_request": {httptest.NewRequest("DELETE", "http://localhost/api/skins/username", nil)},
+		},
 		ExpectedCalls: [][]interface{}{
 			{"IncCounter", "mock_prefix.api.skins.delete.request", int64(1)},
 		},
 	},
 	{
-		Topic:         "skinsystem:before_request",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{httptest.NewRequest("DELETE", "http://localhost/api/skins/id:1", nil)},
+			"skinsystem:before_request": {httptest.NewRequest("DELETE", "http://localhost/api/skins/id:1", nil)},
+		},
 		ExpectedCalls: [][]interface{}{
 			{"IncCounter", "mock_prefix.api.skins.delete.request", int64(1)},
 		},
 	},
 	{
-		Topic:         "skinsystem:before_request",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{httptest.NewRequest("GET", "http://localhost/unknown", nil)},
+			"skinsystem:before_request": {httptest.NewRequest("GET", "http://localhost/unknown", nil)},
+		},
 		ExpectedCalls: nil,
 	},
 	// After request
 	{
-		Topic:         "skinsystem:after_request",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{httptest.NewRequest("POST", "http://localhost/api/skins", nil), 201},
+			"skinsystem:after_request": {httptest.NewRequest("POST", "http://localhost/api/skins", nil), 201},
+		},
 		ExpectedCalls: [][]interface{}{
 			{"IncCounter", "mock_prefix.api.skins.post.success", int64(1)},
 		},
 	},
 	{
-		Topic:         "skinsystem:after_request",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{httptest.NewRequest("POST", "http://localhost/api/skins", nil), 400},
+			"skinsystem:after_request": {httptest.NewRequest("POST", "http://localhost/api/skins", nil), 400},
+		},
 		ExpectedCalls: [][]interface{}{
 			{"IncCounter", "mock_prefix.api.skins.post.validation_failed", int64(1)},
 		},
 	},
 	{
-		Topic:         "skinsystem:after_request",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{httptest.NewRequest("DELETE", "http://localhost/api/skins/username", nil), 204},
+			"skinsystem:after_request": {httptest.NewRequest("DELETE", "http://localhost/api/skins/username", nil), 204},
+		},
 		ExpectedCalls: [][]interface{}{
 			{"IncCounter", "mock_prefix.api.skins.delete.success", int64(1)},
 		},
 	},
 	{
-		Topic:         "skinsystem:after_request",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{httptest.NewRequest("DELETE", "http://localhost/api/skins/username", nil), 404},
+			"skinsystem:after_request": {httptest.NewRequest("DELETE", "http://localhost/api/skins/username", nil), 404},
+		},
 		ExpectedCalls: [][]interface{}{
 			{"IncCounter", "mock_prefix.api.skins.delete.not_found", int64(1)},
 		},
 	},
 	{
-		Topic:         "skinsystem:after_request",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{httptest.NewRequest("DELETE", "http://localhost/api/skins/id:1", nil), 204},
+			"skinsystem:after_request": {httptest.NewRequest("DELETE", "http://localhost/api/skins/id:1", nil), 204},
+		},
 		ExpectedCalls: [][]interface{}{
 			{"IncCounter", "mock_prefix.api.skins.delete.success", int64(1)},
 		},
 	},
 	{
-		Topic:         "skinsystem:after_request",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{httptest.NewRequest("DELETE", "http://localhost/api/skins/id:1", nil), 404},
+			"skinsystem:after_request": {httptest.NewRequest("DELETE", "http://localhost/api/skins/id:1", nil), 404},
+		},
 		ExpectedCalls: [][]interface{}{
 			{"IncCounter", "mock_prefix.api.skins.delete.not_found", int64(1)},
 		},
 	},
 	{
-		Topic:         "skinsystem:after_request",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{httptest.NewRequest("DELETE", "http://localhost/unknown", nil), 404},
+			"skinsystem:after_request": {httptest.NewRequest("DELETE", "http://localhost/unknown", nil), 404},
+		},
 		ExpectedCalls: nil,
 	},
 	// Authenticator
 	{
-		Topic:         "authenticator:success",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{},
+			"authenticator:success": {},
+		},
 		ExpectedCalls: [][]interface{}{
 			{"IncCounter", "mock_prefix.authentication.challenge", int64(1)},
 			{"IncCounter", "mock_prefix.authentication.success", int64(1)},
 		},
 	},
 	{
-		Topic:         "authentication:error",
+		Events: map[string][]interface{}{
-		Args:          []interface{}{errors.New("error")},
+			"authentication:error": {errors.New("error")},
+		},
 		ExpectedCalls: [][]interface{}{
 			{"IncCounter", "mock_prefix.authentication.challenge", int64(1)},
 			{"IncCounter", "mock_prefix.authentication.failed", int64(1)},
 		},
 	},
+	// Mojang signed textures provider
+	{
+		Events: map[string][]interface{}{
+			"mojang_textures:before_result": {"username", ""},
+			"mojang_textures:after_result":  {"username", &mojang.SignedTexturesResponse{}, nilErr},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"RecordTimer", "mock_prefix.mojang_textures.result_time", mock.AnythingOfType("time.Duration")},
+		},
+	},
+	{
+		Events: map[string][]interface{}{
+			"mojang_textures:textures:before_call": {"аааааааааааааааааааааааааааааааа"},
+			"mojang_textures:textures:after_call":  {"аааааааааааааааааааааааааааааааа", &mojang.SignedTexturesResponse{}, nilErr},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "mock_prefix.mojang_textures.textures.request", int64(1)},
+			{"IncCounter", "mock_prefix.mojang_textures.usernames.textures_hit", int64(1)},
+			{"RecordTimer", "mock_prefix.mojang_textures.textures.request_time", mock.AnythingOfType("time.Duration")},
+		},
+	},
+	// Batch UUIDs provider
+	{
+		Events: map[string][]interface{}{
+			"mojang_textures:batch_uuids_provider:queued": {"username"},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "mock_prefix.mojang_textures.usernames.queued", int64(1)},
+		},
+	},
+	{
+		Events: map[string][]interface{}{
+			"mojang_textures:batch_uuids_provider:round": {[]string{"username1", "username2"}, 5},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"UpdateGauge", "mock_prefix.mojang_textures.usernames.iteration_size", int64(2)},
+			{"UpdateGauge", "mock_prefix.mojang_textures.usernames.queue_size", int64(5)},
+		},
+	},
+	{
+		Events: map[string][]interface{}{
+			"mojang_textures:batch_uuids_provider:before_round": {},
+			"mojang_textures:batch_uuids_provider:after_round":  {},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"RecordTimer", "mock_prefix.mojang_textures.usernames.round_time", mock.AnythingOfType("time.Duration")},
+		},
+	},
 }
 
-func TestStatsReporter_handleHTTPRequest(t *testing.T) {
+func TestStatsReporter_handleEvents(t *testing.T) {
 	for _, c := range statsReporterTestCases {
-		t.Run(c.Topic, func(t *testing.T) {
+		t.Run("handle events", func(t *testing.T) {
 			wdMock := &tests.WdMock{}
 			if c.ExpectedCalls != nil {
 				for _, c := range c.ExpectedCalls {
@@ -170,7 +253,9 @@ func TestStatsReporter_handleHTTPRequest(t *testing.T) {
 
 			d := dispatcher.New()
 			reporter.ConfigureWithDispatcher(d)
-			d.Emit(c.Topic, c.Args...)
+			for event, args := range c.Events {
+				d.Emit(event, args...)
+			}
 
 			wdMock.AssertExpectations(t)
 		})