Adjust Mojang's queue behavior

This commit is contained in:
ErickSkrauch 2019-05-05 23:06:29 +03:00
parent f3a8af6866
commit 9dde5715f5
8 changed files with 109 additions and 67 deletions

View File

@ -5,6 +5,12 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/),
and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
## [Unreleased]
### Changed
- Improved Keep-Alive settings for HTTP client used to perform requests to Mojang's APIs
- Mojang's textures queue now has static delay of 1 second after each iteration to prevent strange `429` errors.
- Mojang's textures queue now caches even errored responses for signed textures to avoid `429` errors.
- Mojang's textures queue now caches textures data for 70 seconds to avoid strange `429` errors.
- Mojang's textures queue now doesn't log timeout errors.
## [4.2.0] - 2019-05-02
### Added

View File

@ -10,6 +10,9 @@ import (
var HttpClient = &http.Client{
Timeout: 3 * time.Second,
Transport: &http.Transport{
MaxIdleConnsPerHost: 1024,
},
}
type SignedTexturesResponse struct {

View File

@ -9,8 +9,8 @@ import (
"github.com/tevino/abool"
)
var inMemoryStorageGCPeriod = time.Second
var inMemoryStoragePersistPeriod = time.Second * 60
var inMemoryStorageGCPeriod = 10 * time.Second
var inMemoryStoragePersistPeriod = time.Minute + 10*time.Second
var now = time.Now
type inMemoryItem struct {
@ -59,25 +59,33 @@ func (s *inMemoryTexturesStorage) GetTextures(uuid string) (*mojang.SignedTextur
defer s.lock.Unlock()
item, exists := s.data[uuid]
if !exists || now().Add(inMemoryStoragePersistPeriod*time.Duration(-1)).UnixNano()/10e5 > item.timestamp {
validRange := getMinimalNotExpiredTimestamp()
if !exists || validRange > item.timestamp {
return nil, &ValueNotFound{}
}
return item.textures, nil
}
func (s *inMemoryTexturesStorage) StoreTextures(textures *mojang.SignedTexturesResponse) {
func (s *inMemoryTexturesStorage) StoreTextures(uuid string, textures *mojang.SignedTexturesResponse) {
var timestamp int64
if textures != nil {
decoded := textures.DecodeTextures()
if decoded == nil {
panic("unable to decode textures")
}
timestamp = decoded.Timestamp
} else {
timestamp = unixNanoToUnixMicro(now().UnixNano())
}
s.lock.Lock()
defer s.lock.Unlock()
decoded := textures.DecodeTextures()
if decoded == nil {
panic("unable to decode textures")
}
s.data[textures.Id] = &inMemoryItem{
s.data[uuid] = &inMemoryItem{
textures: textures,
timestamp: decoded.Timestamp,
timestamp: timestamp,
}
}
@ -85,10 +93,18 @@ func (s *inMemoryTexturesStorage) gc() {
s.lock.Lock()
defer s.lock.Unlock()
maxTime := now().Add(inMemoryStoragePersistPeriod*time.Duration(-1)).UnixNano() / 10e5
maxTime := getMinimalNotExpiredTimestamp()
for uuid, value := range s.data {
if maxTime > value.timestamp {
delete(s.data, uuid)
}
}
}
func getMinimalNotExpiredTimestamp() int64 {
return unixNanoToUnixMicro(now().Add(inMemoryStoragePersistPeriod * time.Duration(-1)).UnixNano())
}
func unixNanoToUnixMicro(unixNano int64) int64 {
return unixNano / 10e5
}

View File

@ -59,7 +59,7 @@ func TestInMemoryTexturesStorage_GetTextures(t *testing.T) {
assert := testify.New(t)
storage := CreateInMemoryTexturesStorage()
storage.StoreTextures(texturesWithSkin)
storage.StoreTextures("dead24f9a4fa4877b7b04c8c6c72bb46", texturesWithSkin)
result, err := storage.GetTextures("dead24f9a4fa4877b7b04c8c6c72bb46")
assert.Equal(texturesWithSkin, result)
@ -70,7 +70,7 @@ func TestInMemoryTexturesStorage_GetTextures(t *testing.T) {
assert := testify.New(t)
storage := CreateInMemoryTexturesStorage()
storage.StoreTextures(texturesWithSkin)
storage.StoreTextures("dead24f9a4fa4877b7b04c8c6c72bb46", texturesWithSkin)
now = func() time.Time {
return time.Now().Add(time.Minute * 2)
@ -90,7 +90,7 @@ func TestInMemoryTexturesStorage_StoreTextures(t *testing.T) {
assert := testify.New(t)
storage := CreateInMemoryTexturesStorage()
storage.StoreTextures(texturesWithSkin)
storage.StoreTextures("dead24f9a4fa4877b7b04c8c6c72bb46", texturesWithSkin)
result, err := storage.GetTextures("dead24f9a4fa4877b7b04c8c6c72bb46")
assert.Equal(texturesWithSkin, result)
@ -101,8 +101,8 @@ func TestInMemoryTexturesStorage_StoreTextures(t *testing.T) {
assert := testify.New(t)
storage := CreateInMemoryTexturesStorage()
storage.StoreTextures(texturesWithoutSkin)
storage.StoreTextures(texturesWithSkin)
storage.StoreTextures("dead24f9a4fa4877b7b04c8c6c72bb46", texturesWithoutSkin)
storage.StoreTextures("dead24f9a4fa4877b7b04c8c6c72bb46", texturesWithSkin)
result, err := storage.GetTextures("dead24f9a4fa4877b7b04c8c6c72bb46")
assert.NotEqual(texturesWithoutSkin, result)
@ -110,6 +110,17 @@ func TestInMemoryTexturesStorage_StoreTextures(t *testing.T) {
assert.Nil(err)
})
t.Run("store nil textures", func(t *testing.T) {
assert := testify.New(t)
storage := CreateInMemoryTexturesStorage()
storage.StoreTextures("dead24f9a4fa4877b7b04c8c6c72bb46", nil)
result, err := storage.GetTextures("dead24f9a4fa4877b7b04c8c6c72bb46")
assert.Nil(result)
assert.Nil(err)
})
t.Run("should panic if textures prop is not decoded", func(t *testing.T) {
assert := testify.New(t)
@ -121,7 +132,7 @@ func TestInMemoryTexturesStorage_StoreTextures(t *testing.T) {
assert.PanicsWithValue("unable to decode textures", func() {
storage := CreateInMemoryTexturesStorage()
storage.StoreTextures(toStore)
storage.StoreTextures("xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx", toStore)
})
})
}
@ -164,8 +175,8 @@ func TestInMemoryTexturesStorage_GarbageCollection(t *testing.T) {
}
storage := CreateInMemoryTexturesStorage()
storage.StoreTextures(textures1)
storage.StoreTextures(textures2)
storage.StoreTextures("dead24f9a4fa4877b7b04c8c6c72bb46", textures1)
storage.StoreTextures("b5d58475007d4f9e9ddd1403e2497579", textures2)
storage.Start()

View File

@ -2,6 +2,7 @@ package queue
import (
"net"
"net/url"
"regexp"
"strings"
"sync"
@ -15,7 +16,7 @@ import (
var usernamesToUuids = mojang.UsernamesToUuids
var uuidToTextures = mojang.UuidToTextures
var uuidsQueuePeriod = time.Second
var uuidsQueueIterationDelay = time.Second
var forever = func() bool {
return true
}
@ -96,13 +97,13 @@ func (ctx *JobsQueue) GetTexturesForUsername(username string) chan *mojang.Signe
func (ctx *JobsQueue) startQueue() {
go func() {
time.Sleep(uuidsQueuePeriod)
time.Sleep(uuidsQueueIterationDelay)
for forever() {
start := time.Now()
ctx.queueRound()
elapsed := time.Since(start)
ctx.Logger.RecordTimer("mojang_textures.usernames.round_time", elapsed)
time.Sleep(uuidsQueuePeriod - elapsed)
time.Sleep(uuidsQueueIterationDelay)
}
}()
}
@ -123,7 +124,7 @@ func (ctx *JobsQueue) queueRound() {
profiles, err := usernamesToUuids(usernames)
if err != nil {
ctx.handleResponseError(err)
ctx.handleResponseError(err, "usernames")
for _, job := range jobs {
job.RespondTo <- nil
}
@ -134,7 +135,7 @@ func (ctx *JobsQueue) queueRound() {
for _, job := range jobs {
go func(job *jobItem) {
var uuid string
// Profiles in response not ordered, so we must search each username over full array
// The profiles in the response are not ordered, so we must search each username over full array
for _, profile := range profiles {
if strings.EqualFold(job.Username, profile.Name) {
uuid = profile.Id
@ -166,26 +167,23 @@ func (ctx *JobsQueue) getTextures(uuid string) *mojang.SignedTexturesResponse {
start := time.Now()
result, err := uuidToTextures(uuid, true)
ctx.Logger.RecordTimer("mojang_textures.textures.request_time", time.Since(start))
shouldCache := true
if err != nil {
ctx.handleResponseError(err)
shouldCache = false
ctx.handleResponseError(err, "textures")
}
if shouldCache && result != nil {
ctx.Storage.StoreTextures(result)
}
// Mojang can respond with an error, but count it as a hit, so store result even if the textures is nil
ctx.Storage.StoreTextures(uuid, result)
return result
}
func (ctx *JobsQueue) handleResponseError(err error) {
ctx.Logger.Debug("Got response error :err", wd.ErrParam(err))
func (ctx *JobsQueue) handleResponseError(err error, threadName string) {
ctx.Logger.Debug(":name: Got response error :err", wd.NameParam(threadName), wd.ErrParam(err))
switch err.(type) {
case mojang.ResponseError:
if _, ok := err.(*mojang.TooManyRequestsError); ok {
ctx.Logger.Warning("Got 429 Too Many Requests :err", wd.ErrParam(err))
ctx.Logger.Warning(":name: Got 429 Too Many Requests :err", wd.NameParam(threadName), wd.ErrParam(err))
}
return
@ -194,6 +192,10 @@ func (ctx *JobsQueue) handleResponseError(err error) {
return
}
if _, ok := err.(*url.Error); ok {
return
}
if opErr, ok := err.(*net.OpError); ok && (opErr.Op == "dial" || opErr.Op == "read") {
return
}
@ -203,5 +205,5 @@ func (ctx *JobsQueue) handleResponseError(err error) {
}
}
ctx.Logger.Emergency("Unknown Mojang response error: :err", wd.ErrParam(err))
ctx.Logger.Emergency(":name: Unknown Mojang response error: :err", wd.NameParam(threadName), wd.ErrParam(err))
}

View File

@ -5,16 +5,19 @@ import (
"encoding/base64"
"errors"
"net"
"net/url"
"strings"
"syscall"
"time"
"github.com/elyby/chrly/api/mojang"
mocks "github.com/elyby/chrly/tests"
"testing"
"github.com/stretchr/testify/mock"
"github.com/stretchr/testify/suite"
"testing"
mocks "github.com/elyby/chrly/tests"
)
type mojangApiMocks struct {
@ -64,8 +67,8 @@ func (m *mockStorage) GetTextures(uuid string) (*mojang.SignedTexturesResponse,
return result, args.Error(1)
}
func (m *mockStorage) StoreTextures(textures *mojang.SignedTexturesResponse) {
m.Called(textures)
func (m *mockStorage) StoreTextures(uuid string, textures *mojang.SignedTexturesResponse) {
m.Called(uuid, textures)
}
type queueTestSuite struct {
@ -81,7 +84,7 @@ type queueTestSuite struct {
}
func (suite *queueTestSuite) SetupSuite() {
uuidsQueuePeriod = 0
uuidsQueueIterationDelay = 0
}
func (suite *queueTestSuite) SetupTest() {
@ -132,7 +135,7 @@ func (suite *queueTestSuite) TestReceiveTexturesForOneUsernameWithoutAnyCache()
suite.Storage.On("GetUuid", "maksimkurb").Once().Return("", &ValueNotFound{})
suite.Storage.On("StoreUuid", "maksimkurb", "0d252b7218b648bfb86c2ae476954d32").Once()
suite.Storage.On("GetTextures", "0d252b7218b648bfb86c2ae476954d32").Once().Return(nil, &ValueNotFound{})
suite.Storage.On("StoreTextures", expectedResult).Once()
suite.Storage.On("StoreTextures", "0d252b7218b648bfb86c2ae476954d32", expectedResult).Once()
suite.MojangApi.On("UsernamesToUuids", []string{"maksimkurb"}).Once().Return([]*mojang.ProfileInfo{
{Id: "0d252b7218b648bfb86c2ae476954d32", Name: "maksimkurb"},
@ -167,8 +170,8 @@ func (suite *queueTestSuite) TestReceiveTexturesForFewUsernamesWithoutAnyCache()
suite.Storage.On("StoreUuid", "Thinkofdeath", "4566e69fc90748ee8d71d7ba5aa00d20").Once()
suite.Storage.On("GetTextures", "0d252b7218b648bfb86c2ae476954d32").Once().Return(nil, &ValueNotFound{})
suite.Storage.On("GetTextures", "4566e69fc90748ee8d71d7ba5aa00d20").Once().Return(nil, &ValueNotFound{})
suite.Storage.On("StoreTextures", expectedResult1).Once()
suite.Storage.On("StoreTextures", expectedResult2).Once()
suite.Storage.On("StoreTextures", "0d252b7218b648bfb86c2ae476954d32", expectedResult1).Once()
suite.Storage.On("StoreTextures", "4566e69fc90748ee8d71d7ba5aa00d20", expectedResult2).Once()
suite.MojangApi.On("UsernamesToUuids", []string{"maksimkurb", "Thinkofdeath"}).Once().Return([]*mojang.ProfileInfo{
{Id: "0d252b7218b648bfb86c2ae476954d32", Name: "maksimkurb"},
@ -198,7 +201,7 @@ func (suite *queueTestSuite) TestReceiveTexturesForUsernameWithCachedUuid() {
suite.Storage.On("GetUuid", "maksimkurb").Once().Return("0d252b7218b648bfb86c2ae476954d32", nil)
// Storage.StoreUuid shouldn't be called
suite.Storage.On("GetTextures", "0d252b7218b648bfb86c2ae476954d32").Once().Return(nil, &ValueNotFound{})
suite.Storage.On("StoreTextures", expectedResult).Once()
suite.Storage.On("StoreTextures", "0d252b7218b648bfb86c2ae476954d32", expectedResult).Once()
// MojangApi.UsernamesToUuids shouldn't be called
suite.MojangApi.On("UuidToTextures", "0d252b7218b648bfb86c2ae476954d32", true).Once().Return(expectedResult, nil)
@ -307,7 +310,7 @@ func (suite *queueTestSuite) TestReceiveTexturesForTheSameUsernames() {
suite.Storage.On("GetUuid", "maksimkurb").Twice().Return("", &ValueNotFound{})
suite.Storage.On("StoreUuid", "maksimkurb", "0d252b7218b648bfb86c2ae476954d32").Once()
suite.Storage.On("GetTextures", "0d252b7218b648bfb86c2ae476954d32").Once().Return(nil, &ValueNotFound{})
suite.Storage.On("StoreTextures", expectedResult).Once()
suite.Storage.On("StoreTextures", "0d252b7218b648bfb86c2ae476954d32", expectedResult).Once()
suite.MojangApi.On("UsernamesToUuids", []string{"maksimkurb"}).Once().Return([]*mojang.ProfileInfo{
{Id: "0d252b7218b648bfb86c2ae476954d32", Name: "maksimkurb"},
}, nil)
@ -339,7 +342,7 @@ func (suite *queueTestSuite) TestReceiveTexturesForUsernameThatAlreadyProcessing
suite.Storage.On("GetUuid", "maksimkurb").Twice().Return("", &ValueNotFound{})
suite.Storage.On("StoreUuid", "maksimkurb", "0d252b7218b648bfb86c2ae476954d32").Once()
suite.Storage.On("GetTextures", "0d252b7218b648bfb86c2ae476954d32").Once().Return(nil, &ValueNotFound{})
suite.Storage.On("StoreTextures", expectedResult).Once()
suite.Storage.On("StoreTextures", "0d252b7218b648bfb86c2ae476954d32", expectedResult).Once()
suite.MojangApi.On("UsernamesToUuids", []string{"maksimkurb"}).Once().Return([]*mojang.ProfileInfo{
{Id: "0d252b7218b648bfb86c2ae476954d32", Name: "maksimkurb"},
@ -402,6 +405,7 @@ var expectedErrors = []error{
&mojang.TooManyRequestsError{},
&mojang.ServerError{},
&timeoutError{},
&url.Error{Op: "GET", URL: "http://localhost"},
&net.OpError{Op: "read"},
&net.OpError{Op: "dial"},
syscall.ECONNREFUSED,
@ -411,8 +415,8 @@ func (suite *queueTestSuite) TestShouldNotLogErrorWhenExpectedErrorReturnedFromU
suite.Logger.On("IncCounter", mock.Anything, mock.Anything)
suite.Logger.On("UpdateGauge", mock.Anything, mock.Anything)
suite.Logger.On("RecordTimer", mock.Anything, mock.Anything)
suite.Logger.On("Debug", "Got response error :err", mock.Anything).Times(len(expectedErrors))
suite.Logger.On("Warning", "Got 429 Too Many Requests :err", mock.Anything).Once()
suite.Logger.On("Debug", ":name: Got response error :err", mock.Anything, mock.Anything).Times(len(expectedErrors))
suite.Logger.On("Warning", ":name: Got 429 Too Many Requests :err", mock.Anything, mock.Anything).Once()
suite.Storage.On("GetUuid", "maksimkurb").Return("", &ValueNotFound{})
@ -431,8 +435,8 @@ func (suite *queueTestSuite) TestShouldLogEmergencyOnUnexpectedErrorReturnedFrom
suite.Logger.On("IncCounter", mock.Anything, mock.Anything)
suite.Logger.On("UpdateGauge", mock.Anything, mock.Anything)
suite.Logger.On("RecordTimer", mock.Anything, mock.Anything)
suite.Logger.On("Debug", "Got response error :err", mock.Anything).Once()
suite.Logger.On("Emergency", "Unknown Mojang response error: :err", mock.Anything).Once()
suite.Logger.On("Debug", ":name: Got response error :err", mock.Anything, mock.Anything).Once()
suite.Logger.On("Emergency", ":name: Unknown Mojang response error: :err", mock.Anything, mock.Anything).Once()
suite.Storage.On("GetUuid", "maksimkurb").Return("", &ValueNotFound{})
@ -447,13 +451,13 @@ func (suite *queueTestSuite) TestShouldNotLogErrorWhenExpectedErrorReturnedFromU
suite.Logger.On("IncCounter", mock.Anything, mock.Anything)
suite.Logger.On("UpdateGauge", mock.Anything, mock.Anything)
suite.Logger.On("RecordTimer", mock.Anything, mock.Anything)
suite.Logger.On("Debug", "Got response error :err", mock.Anything).Times(len(expectedErrors))
suite.Logger.On("Warning", "Got 429 Too Many Requests :err", mock.Anything).Once()
suite.Logger.On("Debug", ":name: Got response error :err", mock.Anything, mock.Anything).Times(len(expectedErrors))
suite.Logger.On("Warning", ":name: Got 429 Too Many Requests :err", mock.Anything, mock.Anything).Once()
suite.Storage.On("GetUuid", "maksimkurb").Return("", &ValueNotFound{})
suite.Storage.On("StoreUuid", "maksimkurb", "0d252b7218b648bfb86c2ae476954d32")
suite.Storage.On("GetTextures", "0d252b7218b648bfb86c2ae476954d32").Return(nil, &ValueNotFound{})
// Storage.StoreTextures shouldn't be called
suite.Storage.On("StoreTextures", "0d252b7218b648bfb86c2ae476954d32", (*mojang.SignedTexturesResponse)(nil))
for _, err := range expectedErrors {
suite.MojangApi.On("UsernamesToUuids", []string{"maksimkurb"}).Once().Return([]*mojang.ProfileInfo{
@ -473,13 +477,13 @@ func (suite *queueTestSuite) TestShouldLogEmergencyOnUnexpectedErrorReturnedFrom
suite.Logger.On("IncCounter", mock.Anything, mock.Anything)
suite.Logger.On("UpdateGauge", mock.Anything, mock.Anything)
suite.Logger.On("RecordTimer", mock.Anything, mock.Anything)
suite.Logger.On("Debug", "Got response error :err", mock.Anything).Once()
suite.Logger.On("Emergency", "Unknown Mojang response error: :err", mock.Anything).Once()
suite.Logger.On("Debug", ":name: Got response error :err", mock.Anything, mock.Anything).Once()
suite.Logger.On("Emergency", ":name: Unknown Mojang response error: :err", mock.Anything, mock.Anything).Once()
suite.Storage.On("GetUuid", "maksimkurb").Return("", &ValueNotFound{})
suite.Storage.On("StoreUuid", "maksimkurb", "0d252b7218b648bfb86c2ae476954d32")
suite.Storage.On("GetTextures", "0d252b7218b648bfb86c2ae476954d32").Return(nil, &ValueNotFound{})
// Storage.StoreTextures shouldn't be called
suite.Storage.On("StoreTextures", "0d252b7218b648bfb86c2ae476954d32", (*mojang.SignedTexturesResponse)(nil))
suite.MojangApi.On("UsernamesToUuids", []string{"maksimkurb"}).Once().Return([]*mojang.ProfileInfo{
{Id: "0d252b7218b648bfb86c2ae476954d32", Name: "maksimkurb"},

View File

@ -7,12 +7,12 @@ type UuidsStorage interface {
StoreUuid(username string, uuid string)
}
// nil value can be passed to the storage to indicate that there is no textures
// for uuid and we know about it. Return err only in case, when storage completely
// unable to load any information about textures
type TexturesStorage interface {
// nil can be returned to indicate that there is no textures for uuid
// and we know about it. Return err only in case, when storage completely
// don't know anything about uuid
GetTextures(uuid string) (*mojang.SignedTexturesResponse, error)
StoreTextures(textures *mojang.SignedTexturesResponse)
StoreTextures(uuid string, textures *mojang.SignedTexturesResponse)
}
type Storage interface {
@ -39,8 +39,8 @@ func (s *SplittedStorage) GetTextures(uuid string) (*mojang.SignedTexturesRespon
return s.TexturesStorage.GetTextures(uuid)
}
func (s *SplittedStorage) StoreTextures(textures *mojang.SignedTexturesResponse) {
s.TexturesStorage.StoreTextures(textures)
func (s *SplittedStorage) StoreTextures(uuid string, textures *mojang.SignedTexturesResponse) {
s.TexturesStorage.StoreTextures(uuid, textures)
}
// This error can be used to indicate, that requested

View File

@ -35,8 +35,8 @@ func (m *texturesStorageMock) GetTextures(uuid string) (*mojang.SignedTexturesRe
return result, args.Error(1)
}
func (m *texturesStorageMock) StoreTextures(textures *mojang.SignedTexturesResponse) {
m.Called(textures)
func (m *texturesStorageMock) StoreTextures(uuid string, textures *mojang.SignedTexturesResponse) {
m.Called(uuid, textures)
}
func TestSplittedStorage(t *testing.T) {
@ -74,10 +74,10 @@ func TestSplittedStorage(t *testing.T) {
})
t.Run("StoreTextures", func(t *testing.T) {
toStore := &mojang.SignedTexturesResponse{Id: "mock id"}
toStore := &mojang.SignedTexturesResponse{}
storage, _, texturesMock := createMockedStorage()
texturesMock.On("StoreTextures", toStore).Once()
storage.StoreTextures(toStore)
texturesMock.On("StoreTextures", "mock id", toStore).Once()
storage.StoreTextures("mock id", toStore)
texturesMock.AssertExpectations(t)
})
}