diff --git a/CHANGELOG.md b/CHANGELOG.md index 752e1c3..a03a99d 100644 --- a/CHANGELOG.md +++ b/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. diff --git a/eventsubscribers/stats_reporter.go b/eventsubscribers/stats_reporter.go index ad0e449..2a1ce2b 100644 --- a/eventsubscribers/stats_reporter.go +++ b/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}, ".") } diff --git a/eventsubscribers/stats_reporter_test.go b/eventsubscribers/stats_reporter_test.go index 7d0ea24..fc7e74b 100644 --- a/eventsubscribers/stats_reporter_test.go +++ b/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 - Args []interface{} + Events map[string][]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", - Args: []interface{}{httptest.NewRequest("GET", "http://localhost/skins/username", nil)}, + Events: map[string][]interface{}{ + "skinsystem:before_request": {httptest.NewRequest("GET", "http://localhost/skins/username", nil)}, + }, ExpectedCalls: [][]interface{}{ {"IncCounter", "mock_prefix.skins.request", int64(1)}, }, }, { - Topic: "skinsystem:before_request", - Args: []interface{}{httptest.NewRequest("GET", "http://localhost/skins?name=username", nil)}, + Events: map[string][]interface{}{ + "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", - Args: []interface{}{httptest.NewRequest("GET", "http://localhost/cloaks/username", nil)}, + Events: map[string][]interface{}{ + "skinsystem:before_request": {httptest.NewRequest("GET", "http://localhost/cloaks/username", nil)}, + }, ExpectedCalls: [][]interface{}{ {"IncCounter", "mock_prefix.capes.request", int64(1)}, }, }, { - Topic: "skinsystem:before_request", - Args: []interface{}{httptest.NewRequest("GET", "http://localhost/cloaks?name=username", nil)}, + Events: map[string][]interface{}{ + "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", - Args: []interface{}{httptest.NewRequest("GET", "http://localhost/textures/username", nil)}, + Events: map[string][]interface{}{ + "skinsystem:before_request": {httptest.NewRequest("GET", "http://localhost/textures/username", nil)}, + }, ExpectedCalls: [][]interface{}{ {"IncCounter", "mock_prefix.textures.request", int64(1)}, }, }, { - Topic: "skinsystem:before_request", - Args: []interface{}{httptest.NewRequest("GET", "http://localhost/textures/signed/username", nil)}, + Events: map[string][]interface{}{ + "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", - Args: []interface{}{httptest.NewRequest("POST", "http://localhost/api/skins", nil)}, + Events: map[string][]interface{}{ + "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", - Args: []interface{}{httptest.NewRequest("DELETE", "http://localhost/api/skins/username", nil)}, + Events: map[string][]interface{}{ + "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", - Args: []interface{}{httptest.NewRequest("DELETE", "http://localhost/api/skins/id:1", nil)}, + Events: map[string][]interface{}{ + "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", - Args: []interface{}{httptest.NewRequest("GET", "http://localhost/unknown", nil)}, + Events: map[string][]interface{}{ + "skinsystem:before_request": {httptest.NewRequest("GET", "http://localhost/unknown", nil)}, + }, ExpectedCalls: nil, }, // After request { - Topic: "skinsystem:after_request", - Args: []interface{}{httptest.NewRequest("POST", "http://localhost/api/skins", nil), 201}, + Events: map[string][]interface{}{ + "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", - Args: []interface{}{httptest.NewRequest("POST", "http://localhost/api/skins", nil), 400}, + Events: map[string][]interface{}{ + "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", - Args: []interface{}{httptest.NewRequest("DELETE", "http://localhost/api/skins/username", nil), 204}, + Events: map[string][]interface{}{ + "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", - Args: []interface{}{httptest.NewRequest("DELETE", "http://localhost/api/skins/username", nil), 404}, + Events: map[string][]interface{}{ + "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", - Args: []interface{}{httptest.NewRequest("DELETE", "http://localhost/api/skins/id:1", nil), 204}, + Events: map[string][]interface{}{ + "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", - Args: []interface{}{httptest.NewRequest("DELETE", "http://localhost/api/skins/id:1", nil), 404}, + Events: map[string][]interface{}{ + "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", - Args: []interface{}{httptest.NewRequest("DELETE", "http://localhost/unknown", nil), 404}, + Events: map[string][]interface{}{ + "skinsystem:after_request": {httptest.NewRequest("DELETE", "http://localhost/unknown", nil), 404}, + }, ExpectedCalls: nil, }, // Authenticator { - Topic: "authenticator:success", - Args: []interface{}{}, + Events: map[string][]interface{}{ + "authenticator:success": {}, + }, ExpectedCalls: [][]interface{}{ {"IncCounter", "mock_prefix.authentication.challenge", int64(1)}, {"IncCounter", "mock_prefix.authentication.success", int64(1)}, }, }, { - Topic: "authentication:error", - Args: []interface{}{errors.New("error")}, + Events: map[string][]interface{}{ + "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) })