Merge pull request #17 from elyby/event_dispatcher_refactoring

Event dispatcher refactoring

CHANGELOG.md

@@ -18,11 +18,12 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
   username to its UUID. It can be used with some load balancing software to increase throughput of Mojang's textures
   proxy by splitting the load across multiple servers with its own IPs.
 - Textures extra param is now can be configured via `TEXTURES_EXTRA_PARAM_NAME` and `TEXTURES_EXTRA_PARAM_VALUE`.
-
 - New StatsD metrics:
   - Counters:
     - `ely.skinsystem.{hostname}.app.mojang_textures.usernames.textures_hit`
     - `ely.skinsystem.{hostname}.app.mojang_textures.usernames.textures_miss`
+- All incoming requests are now logging to the console in
+  [Apache Common Log Format](http://httpd.apache.org/docs/2.2/logs.html#common).
 
 ### Fixed
 - `ely.skinsystem.{hostname}.app.mojang_textures.usernames.iteration_size` and
@@ -34,6 +35,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.

Gopkg.lock

@@ -14,6 +14,15 @@
   revision = "f6df55f235c24f236d11dbcf665249a59ac2021f"
   version = "1.1"
 
+[[projects]]
+  branch = "publish_nil_values"
+  digest = "1:d02c8323070a3d8d8ca039d0d180198ead0a75eac4fb1003af812435a2b391e8"
+  name = "github.com/asaskevich/EventBus"
+  packages = ["."]
+  pruneopts = ""
+  revision = "33b3bc6a7ddca2f99683c5c3ee86b24f80a7a075"
+  source = "https://github.com/erickskrauch/EventBus.git"
+
 [[projects]]
   digest = "1:c7b11da9bf0707e6920e1b361fbbbbe9b277ef3a198377baa4527f6e31049be0"
   name = "github.com/certifi/gocertifi"
@@ -301,6 +310,7 @@
   input-imports = [
     "github.com/SermoDigital/jose/crypto",
     "github.com/SermoDigital/jose/jws",
+    "github.com/asaskevich/EventBus",
     "github.com/getsentry/raven-go",
     "github.com/gorilla/mux",
     "github.com/h2non/gock",
@@ -308,6 +318,7 @@
     "github.com/mediocregopher/radix.v2/redis",
     "github.com/mediocregopher/radix.v2/util",
     "github.com/mono83/slf",
+    "github.com/mono83/slf/params",
     "github.com/mono83/slf/rays",
     "github.com/mono83/slf/recievers/sentry",
     "github.com/mono83/slf/recievers/statsd",

Gopkg.toml

@@ -36,6 +36,11 @@ ignored = ["github.com/elyby/chrly"]
   name = "github.com/tevino/abool"
   branch = "master"
 
+[[constraint]]
+  name = "github.com/asaskevich/EventBus"
+  source = "https://github.com/erickskrauch/EventBus.git"
+  branch = "publish_nil_values"
+
 # Testing dependencies
 
 [[constraint]]

README.md

@@ -342,7 +342,7 @@ If your Redis instance isn't located at the `localhost`, you can change host by
 `STORAGE_REDIS_HOST`.
 
 After all of that `go run main.go serve` should successfully start the application.
-To run tests execute `go test ./...`. If your Go version is older than 1.9, then run a `/script/test`.
+To run tests execute `go test ./...`.
 
 [ico-lang]: https://img.shields.io/badge/lang-go%201.13-blue.svg?style=flat-square
 [ico-build]: https://img.shields.io/travis/elyby/chrly.svg?style=flat-square

api/mojang/mojang.go

@@ -3,8 +3,10 @@ package mojang
 import (
 	"bytes"
 	"encoding/json"
+	"fmt"
 	"io/ioutil"
 	"net/http"
+	"strings"
 	"time"
 )
 
@@ -85,7 +87,8 @@ func UsernamesToUuids(usernames []string) ([]*ProfileInfo, error) {
 // Obtains textures information for provided uuid
 // See https://wiki.vg/Mojang_API#UUID_-.3E_Profile_.2B_Skin.2FCape
 func UuidToTextures(uuid string, signed bool) (*SignedTexturesResponse, error) {
-	url := "https://sessionserver.mojang.com/session/minecraft/profile/" + uuid
+	normalizedUuid := strings.ReplaceAll(uuid, "-", "")
+	url := "https://sessionserver.mojang.com/session/minecraft/profile/" + normalizedUuid
 	if signed {
 		url += "?unsigned=false"
 	}
@@ -146,7 +149,7 @@ type EmptyResponse struct {
 }
 
 func (*EmptyResponse) Error() string {
-	return "Empty Response"
+	return "200: Empty Response"
 }
 
 func (*EmptyResponse) IsMojangError() bool {
@@ -161,7 +164,7 @@ type BadRequestError struct {
 }
 
 func (e *BadRequestError) Error() string {
-	return e.Message
+	return fmt.Sprintf("400 %s: %s", e.ErrorType, e.Message)
 }
 
 func (*BadRequestError) IsMojangError() bool {
@@ -174,7 +177,7 @@ type ForbiddenError struct {
 }
 
 func (*ForbiddenError) Error() string {
-	return "Forbidden"
+	return "403: Forbidden"
 }
 
 // When you exceed the set limit of requests, this error will be returned
@@ -183,7 +186,7 @@ type TooManyRequestsError struct {
 }
 
 func (*TooManyRequestsError) Error() string {
-	return "Too Many Requests"
+	return "429: Too Many Requests"
 }
 
 func (*TooManyRequestsError) IsMojangError() bool {
@@ -197,7 +200,7 @@ type ServerError struct {
 }
 
 func (e *ServerError) Error() string {
-	return "Server error"
+	return fmt.Sprintf("%d: %s", e.Status, "Server error")
 }
 
 func (*ServerError) IsMojangError() bool {

api/mojang/mojang_test.go

@@ -98,7 +98,7 @@ func TestUsernamesToUuids(t *testing.T) {
 		result, err := UsernamesToUuids([]string{""})
 		assert.Nil(result)
 		assert.IsType(&BadRequestError{}, err)
-		assert.EqualError(err, "profileName can not be null or empty.")
+		assert.EqualError(err, "400 IllegalArgumentException: profileName can not be null or empty.")
 		assert.Implements((*ResponseError)(nil), err)
 	})
 
@@ -119,7 +119,7 @@ func TestUsernamesToUuids(t *testing.T) {
 		result, err := UsernamesToUuids([]string{"Thinkofdeath", "maksimkurb"})
 		assert.Nil(result)
 		assert.IsType(&ForbiddenError{}, err)
-		assert.EqualError(err, "Forbidden")
+		assert.EqualError(err, "403: Forbidden")
 		assert.Implements((*ResponseError)(nil), err)
 	})
 
@@ -143,7 +143,7 @@ func TestUsernamesToUuids(t *testing.T) {
 		result, err := UsernamesToUuids([]string{"Thinkofdeath", "maksimkurb"})
 		assert.Nil(result)
 		assert.IsType(&TooManyRequestsError{}, err)
-		assert.EqualError(err, "Too Many Requests")
+		assert.EqualError(err, "429: Too Many Requests")
 		assert.Implements((*ResponseError)(nil), err)
 	})
 
@@ -164,7 +164,7 @@ func TestUsernamesToUuids(t *testing.T) {
 		result, err := UsernamesToUuids([]string{"Thinkofdeath", "maksimkurb"})
 		assert.Nil(result)
 		assert.IsType(&ServerError{}, err)
-		assert.EqualError(err, "Server error")
+		assert.EqualError(err, "500: Server error")
 		assert.Equal(500, err.(*ServerError).Status)
 		assert.Implements((*ResponseError)(nil), err)
 	})
@@ -205,7 +205,7 @@ func TestUuidToTextures(t *testing.T) {
 		}
 	})
 
-	t.Run("obtain signed textures", func(t *testing.T) {
+	t.Run("obtain signed textures with dashed uuid", func(t *testing.T) {
 		assert := testify.New(t)
 
 		defer gock.Off()
@@ -230,7 +230,7 @@ func TestUuidToTextures(t *testing.T) {
 
 		HttpClient = client
 
-		result, err := UuidToTextures("4566e69fc90748ee8d71d7ba5aa00d20", true)
+		result, err := UuidToTextures("4566e69f-c907-48ee-8d71-d7ba5aa00d20", true)
 		if assert.NoError(err) {
 			assert.Equal("4566e69fc90748ee8d71d7ba5aa00d20", result.Id)
 			assert.Equal("Thinkofdeath", result.Name)
@@ -258,7 +258,7 @@ func TestUuidToTextures(t *testing.T) {
 		result, err := UuidToTextures("4566e69fc90748ee8d71d7ba5aa00d20", false)
 		assert.Nil(result)
 		assert.IsType(&EmptyResponse{}, err)
-		assert.EqualError(err, "Empty Response")
+		assert.EqualError(err, "200: Empty Response")
 		assert.Implements((*ResponseError)(nil), err)
 	})
 
@@ -282,7 +282,7 @@ func TestUuidToTextures(t *testing.T) {
 		result, err := UuidToTextures("4566e69fc90748ee8d71d7ba5aa00d20", false)
 		assert.Nil(result)
 		assert.IsType(&TooManyRequestsError{}, err)
-		assert.EqualError(err, "Too Many Requests")
+		assert.EqualError(err, "429: Too Many Requests")
 		assert.Implements((*ResponseError)(nil), err)
 	})
 
@@ -303,7 +303,7 @@ func TestUuidToTextures(t *testing.T) {
 		result, err := UuidToTextures("4566e69fc90748ee8d71d7ba5aa00d20", false)
 		assert.Nil(result)
 		assert.IsType(&ServerError{}, err)
-		assert.EqualError(err, "Server error")
+		assert.EqualError(err, "500: Server error")
 		assert.Equal(500, err.(*ServerError).Status)
 		assert.Implements((*ResponseError)(nil), err)
 	})

auth/jwt_test.go

@@ -1,97 +0,0 @@
-package auth
-
-import (
-	"net/http/httptest"
-	"testing"
-
-	testify "github.com/stretchr/testify/assert"
-)
-
-const jwt = "eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiIxNTE2NjU4MTkzIiwic2NvcGVzIjoic2tpbiJ9.agbBS0qdyYMBaVfTZJAZcTTRgW1Y0kZty4H3N2JHBO8"
-
-func TestJwtAuth_NewToken_Success(t *testing.T) {
-	assert := testify.New(t)
-
-	jwt := &JwtAuth{[]byte("secret")}
-	token, err := jwt.NewToken(SkinScope)
-	assert.Nil(err)
-	assert.NotNil(token)
-}
-
-func TestJwtAuth_NewToken_KeyNotAvailable(t *testing.T) {
-	assert := testify.New(t)
-
-	jwt := &JwtAuth{}
-	token, err := jwt.NewToken(SkinScope)
-	assert.Error(err, "signing key not available")
-	assert.Nil(token)
-}
-
-func TestJwtAuth_Check_EmptyRequest(t *testing.T) {
-	assert := testify.New(t)
-
-	req := httptest.NewRequest("POST", "http://localhost", nil)
-	jwt := &JwtAuth{[]byte("secret")}
-
-	err := jwt.Check(req)
-	assert.IsType(&Unauthorized{}, err)
-	assert.EqualError(err, "Authentication header not presented")
-}
-
-func TestJwtAuth_Check_NonBearer(t *testing.T) {
-	assert := testify.New(t)
-
-	req := httptest.NewRequest("POST", "http://localhost", nil)
-	req.Header.Add("Authorization", "this is not jwt")
-	jwt := &JwtAuth{[]byte("secret")}
-
-	err := jwt.Check(req)
-	assert.IsType(&Unauthorized{}, err)
-	assert.EqualError(err, "Cannot recognize JWT token in passed value")
-}
-
-func TestJwtAuth_Check_BearerButNotJwt(t *testing.T) {
-	assert := testify.New(t)
-
-	req := httptest.NewRequest("POST", "http://localhost", nil)
-	req.Header.Add("Authorization", "Bearer thisIs.Not.Jwt")
-	jwt := &JwtAuth{[]byte("secret")}
-
-	err := jwt.Check(req)
-	assert.IsType(&Unauthorized{}, err)
-	assert.EqualError(err, "Cannot parse passed JWT token")
-}
-
-func TestJwtAuth_Check_SecretNotAvailable(t *testing.T) {
-	assert := testify.New(t)
-
-	req := httptest.NewRequest("POST", "http://localhost", nil)
-	req.Header.Add("Authorization", "Bearer " + jwt)
-	jwt := &JwtAuth{}
-
-	err := jwt.Check(req)
-	assert.Error(err, "Signing key not set")
-}
-
-func TestJwtAuth_Check_SecretInvalid(t *testing.T) {
-	assert := testify.New(t)
-
-	req := httptest.NewRequest("POST", "http://localhost", nil)
-	req.Header.Add("Authorization", "Bearer " + jwt)
-	jwt := &JwtAuth{[]byte("this is another secret")}
-
-	err := jwt.Check(req)
-	assert.IsType(&Unauthorized{}, err)
-	assert.EqualError(err, "JWT token have invalid signature. It may be corrupted or expired.")
-}
-
-func TestJwtAuth_Check_Valid(t *testing.T) {
-	assert := testify.New(t)
-
-	req := httptest.NewRequest("POST", "http://localhost", nil)
-	req.Header.Add("Authorization", "Bearer " + jwt)
-	jwt := &JwtAuth{[]byte("secret")}
-
-	err := jwt.Check(req)
-	assert.Nil(err)
-}

bootstrap/bootstrap.go

@@ -6,6 +6,7 @@ import (
 	"time"
 
 	"github.com/getsentry/raven-go"
+	"github.com/mono83/slf"
 	"github.com/mono83/slf/rays"
 	"github.com/mono83/slf/recievers/sentry"
 	"github.com/mono83/slf/recievers/statsd"
@@ -13,31 +14,18 @@ import (
 	"github.com/mono83/slf/wd"
 	"github.com/spf13/viper"
 
+	"github.com/elyby/chrly/dispatcher"
+	"github.com/elyby/chrly/http"
 	"github.com/elyby/chrly/mojangtextures"
 	"github.com/elyby/chrly/version"
 )
 
-func CreateLogger(statsdAddr string, sentryAddr string) (wd.Watchdog, error) {
+func CreateLogger(sentryAddr string) (slf.Logger, error) {
 	wd.AddReceiver(writer.New(writer.Options{
 		Marker:     false,
 		TimeFormat: "15:04:05.000",
 	}))
 
-	if statsdAddr != "" {
-		hostname, _ := os.Hostname()
-		statsdReceiver, err := statsd.NewReceiver(statsd.Config{
-			Address:    statsdAddr,
-			Prefix:     "ely.skinsystem." + hostname + ".app.",
-			FlushEvery: 1,
-		})
-
-		if err != nil {
-			return nil, err
-		}
-
-		wd.AddReceiver(statsdReceiver)
-	}
-
 	if sentryAddr != "" {
 		ravenClient, err := raven.New(sentryAddr)
 		if err != nil {
@@ -64,12 +52,28 @@ func CreateLogger(statsdAddr string, sentryAddr string) (wd.Watchdog, error) {
 	return wd.New("", "").WithParams(rays.Host), nil
 }
 
+func CreateStatsReceiver(statsdAddr string) (slf.StatsReporter, error) {
+	hostname, _ := os.Hostname()
+	statsdReceiver, err := statsd.NewReceiver(statsd.Config{
+		Address:    statsdAddr,
+		Prefix:     "ely.skinsystem." + hostname + ".app.",
+		FlushEvery: 1,
+	})
+	if err != nil {
+		return nil, err
+	}
+
+	wd.AddReceiver(statsdReceiver)
+
+	return wd.New("", "").WithParams(rays.Host), nil
+}
+
 func init() {
 	viper.SetDefault("queue.loop_delay", 2*time.Second+500*time.Millisecond)
 	viper.SetDefault("queue.batch_size", 10)
 }
 
-func CreateMojangUUIDsProvider(logger wd.Watchdog) (mojangtextures.UUIDsProvider, error) {
+func CreateMojangUUIDsProvider(emitter http.Emitter) (mojangtextures.UUIDsProvider, error) {
 	var uuidsProvider mojangtextures.UUIDsProvider
 	preferredUuidsProvider := viper.GetString("mojang_textures.uuids_provider.driver")
 	if preferredUuidsProvider == "remote" {
@@ -79,16 +83,20 @@ func CreateMojangUUIDsProvider(logger wd.Watchdog) (mojangtextures.UUIDsProvider
 		}
 
 		uuidsProvider = &mojangtextures.RemoteApiUuidsProvider{
-			Url:    *remoteUrl,
+			Emitter: emitter,
-			Logger: logger,
+			Url:     *remoteUrl,
 		}
 	} else {
 		uuidsProvider = &mojangtextures.BatchUuidsProvider{
+			Emitter:        emitter,
 			IterationDelay: viper.GetDuration("queue.loop_delay"),
 			IterationSize:  viper.GetInt("queue.batch_size"),
-			Logger:         logger,
 		}
 	}
 
 	return uuidsProvider, nil
 }
+
+func CreateEventDispatcher() dispatcher.EventDispatcher {
+	return dispatcher.New()
+}

cmd/serve.go

@@ -3,14 +3,15 @@ package cmd
 import (
 	"fmt"
 	"log"
+	"os"
 
 	"github.com/mono83/slf/wd"
 	"github.com/spf13/cobra"
 	"github.com/spf13/viper"
 
-	"github.com/elyby/chrly/auth"
 	"github.com/elyby/chrly/bootstrap"
 	"github.com/elyby/chrly/db"
+	"github.com/elyby/chrly/eventsubscribers"
 	"github.com/elyby/chrly/http"
 	"github.com/elyby/chrly/mojangtextures"
 )
@@ -19,21 +20,36 @@ var serveCmd = &cobra.Command{
 	Use:   "serve",
 	Short: "Starts HTTP handler for the skins system",
 	Run: func(cmd *cobra.Command, args []string) {
+		dispatcher := bootstrap.CreateEventDispatcher()
+
 		// TODO: this is a mess, need to organize this code somehow to make services initialization more compact
-		logger, err := bootstrap.CreateLogger(viper.GetString("statsd.addr"), viper.GetString("sentry.dsn"))
+		logger, err := bootstrap.CreateLogger(viper.GetString("sentry.dsn"))
 		if err != nil {
-			log.Fatal(fmt.Printf("Cannot initialize logger: %v", err))
+			log.Fatalf("Cannot initialize logger: %v", err)
 		}
 		logger.Info("Logger successfully initialized")
 
+		(&eventsubscribers.Logger{Logger: logger}).ConfigureWithDispatcher(dispatcher)
+
+		statsdAddr := viper.GetString("statsd.addr")
+		if statsdAddr != "" {
+			statsdReporter, err := bootstrap.CreateStatsReceiver(statsdAddr)
+			if err != nil {
+				logger.Emergency("Invalid statsd configuration :err", wd.ErrParam(err))
+				os.Exit(1)
+			}
+
+			(&eventsubscribers.StatsReporter{StatsReporter: statsdReporter}).ConfigureWithDispatcher(dispatcher)
+		}
+
 		storageFactory := db.StorageFactory{Config: viper.GetViper()}
 
 		logger.Info("Initializing skins repository")
 		redisFactory := storageFactory.CreateFactory("redis")
 		skinsRepo, err := redisFactory.CreateSkinsRepository()
 		if err != nil {
-			logger.Emergency(fmt.Sprintf("Error on creating skins repo: %+v", err))
+			logger.Emergency("Error on creating skins repo: :err", wd.ErrParam(err))
-			return
+			os.Exit(1)
 		}
 		logger.Info("Skins repository successfully initialized")
 
@@ -41,31 +57,31 @@ var serveCmd = &cobra.Command{
 		filesystemFactory := storageFactory.CreateFactory("filesystem")
 		capesRepo, err := filesystemFactory.CreateCapesRepository()
 		if err != nil {
-			logger.Emergency(fmt.Sprintf("Error on creating capes repo: %v", err))
+			logger.Emergency("Error on creating capes repo: :err", wd.ErrParam(err))
-			return
+			os.Exit(1)
 		}
 		logger.Info("Capes repository successfully initialized")
 
 		logger.Info("Preparing Mojang's textures queue")
 		mojangUuidsRepository, err := redisFactory.CreateMojangUuidsRepository()
 		if err != nil {
-			logger.Emergency(fmt.Sprintf("Error on creating mojang uuids repo: %v", err))
+			logger.Emergency("Error on creating mojang uuids repo: :err", wd.ErrParam(err))
-			return
+			os.Exit(1)
 		}
 
-		uuidsProvider, err := bootstrap.CreateMojangUUIDsProvider(logger)
+		uuidsProvider, err := bootstrap.CreateMojangUUIDsProvider(dispatcher)
 		if err != nil {
 			logger.Emergency("Unable to parse remote url :err", wd.ErrParam(err))
-			return
+			os.Exit(1)
 		}
 
 		texturesStorage := mojangtextures.NewInMemoryTexturesStorage()
 		texturesStorage.Start()
 		mojangTexturesProvider := &mojangtextures.Provider{
-			Logger:        logger,
+			Emitter:       dispatcher,
 			UUIDsProvider: uuidsProvider,
 			TexturesProvider: &mojangtextures.MojangApiTexturesProvider{
-				Logger: logger,
+				Emitter: dispatcher,
 			},
 			Storage: &mojangtextures.SeparatedStorage{
 				UuidsStorage:    mojangUuidsRepository,
@@ -74,28 +90,29 @@ var serveCmd = &cobra.Command{
 		}
 		logger.Info("Mojang's textures queue is successfully initialized")
 
-		cfg := &http.Skinsystem{
+		address := fmt.Sprintf("%s:%d", viper.GetString("server.host"), viper.GetInt("server.port"))
-			ListenSpec:              fmt.Sprintf("%s:%d", viper.GetString("server.host"), viper.GetInt("server.port")),
+		handler := (&http.Skinsystem{
+			Emitter:                 dispatcher,
 			SkinsRepo:               skinsRepo,
 			CapesRepo:               capesRepo,
 			MojangTexturesProvider:  mojangTexturesProvider,
-			Logger:                  logger,
+			Authenticator:           &http.JwtAuth{Key: []byte(viper.GetString("chrly.secret"))},
-			Auth:                    &auth.JwtAuth{Key: []byte(viper.GetString("chrly.secret"))},
 			TexturesExtraParamName:  viper.GetString("textures.extra_param_name"),
 			TexturesExtraParamValue: viper.GetString("textures.extra_param_value"),
-		}
+		}).CreateHandler()
 
 		finishChan := make(chan bool)
 		go func() {
-			if err := cfg.Run(); err != nil {
+			logger.Info("Starting the app, HTTP on: :addr", wd.StringParam("addr", address))
-				logger.Error(fmt.Sprintf("Error in main(): %v", err))
+			if err := http.Serve(address, handler); err != nil {
+				logger.Emergency("Error in main(): :err", wd.ErrParam(err))
 				finishChan <- true
 			}
 		}()
 
 		go func() {
 			s := waitForExitSignal()
-			logger.Info(fmt.Sprintf("Got signal: %v, exiting.", s))
+			logger.Info("Got signal: :signal, exiting", wd.StringParam("signal", s.String()))
 			finishChan <- true
 		}()
 

cmd/token.go

@@ -4,7 +4,7 @@ import (
 	"fmt"
 	"log"
 
-	"github.com/elyby/chrly/auth"
+	"github.com/elyby/chrly/http"
 
 	"github.com/spf13/cobra"
 	"github.com/spf13/viper"
@@ -14,8 +14,8 @@ var tokenCmd = &cobra.Command{
 	Use:   "token",
 	Short: "Creates a new token, which allows to interact with Chrly API",
 	Run: func(cmd *cobra.Command, args []string) {
-		jwtAuth := &auth.JwtAuth{Key: []byte(viper.GetString("chrly.secret"))}
+		jwtAuth := &http.JwtAuth{Key: []byte(viper.GetString("chrly.secret"))}
-		token, err := jwtAuth.NewToken(auth.SkinScope)
+		token, err := jwtAuth.NewToken(http.SkinScope)
 		if err != nil {
 			log.Fatalf("Unable to create new token. The error is %v\n", err)
 		}

cmd/worker.go

@@ -3,12 +3,14 @@ package cmd
 import (
 	"fmt"
 	"log"
+	"os"
 
 	"github.com/mono83/slf/wd"
 	"github.com/spf13/cobra"
 	"github.com/spf13/viper"
 
 	"github.com/elyby/chrly/bootstrap"
+	"github.com/elyby/chrly/eventsubscribers"
 	"github.com/elyby/chrly/http"
 )
 
@@ -16,35 +18,52 @@ var workerCmd = &cobra.Command{
 	Use:   "worker",
 	Short: "Starts HTTP handler for the Mojang usernames to UUIDs worker",
 	Run: func(cmd *cobra.Command, args []string) {
-		logger, err := bootstrap.CreateLogger(viper.GetString("statsd.addr"), viper.GetString("sentry.dsn"))
+		dispatcher := bootstrap.CreateEventDispatcher()
+
+		// TODO: need to find a way to unify this initialization with the serve command
+		logger, err := bootstrap.CreateLogger(viper.GetString("sentry.dsn"))
 		if err != nil {
-			log.Fatal(fmt.Printf("Cannot initialize logger: %v", err))
+			log.Fatalf("Cannot initialize logger: %v", err)
 		}
 		logger.Info("Logger successfully initialized")
 
-		uuidsProvider, err := bootstrap.CreateMojangUUIDsProvider(logger)
+		(&eventsubscribers.Logger{Logger: logger}).ConfigureWithDispatcher(dispatcher)
-		if err != nil {
+
-			logger.Emergency("Unable to parse remote url :err", wd.ErrParam(err))
+		statsdAddr := viper.GetString("statsd.addr")
-			return
+		if statsdAddr != "" {
+			statsdReporter, err := bootstrap.CreateStatsReceiver(statsdAddr)
+			if err != nil {
+				logger.Emergency("Invalid statsd configuration :err", wd.ErrParam(err))
+				os.Exit(1)
+			}
+
+			(&eventsubscribers.StatsReporter{StatsReporter: statsdReporter}).ConfigureWithDispatcher(dispatcher)
 		}
 
-		cfg := &http.UUIDsWorker{
+		uuidsProvider, err := bootstrap.CreateMojangUUIDsProvider(dispatcher)
-			ListenSpec:    fmt.Sprintf("%s:%d", viper.GetString("server.host"), viper.GetInt("server.port")),
+		if err != nil {
-			UUIDsProvider: uuidsProvider,
+			logger.Emergency("Unable to parse remote url :err", wd.ErrParam(err))
-			Logger:        logger,
+			os.Exit(1)
 		}
 
+		address := fmt.Sprintf("%s:%d", viper.GetString("server.host"), viper.GetInt("server.port"))
+		handler := (&http.UUIDsWorker{
+			Emitter:       dispatcher,
+			UUIDsProvider: uuidsProvider,
+		}).CreateHandler()
+
 		finishChan := make(chan bool)
 		go func() {
-			if err := cfg.Run(); err != nil {
+			logger.Info("Starting the worker, HTTP on: :addr", wd.StringParam("addr", address))
-				logger.Error(fmt.Sprintf("Error in main(): %v", err))
+			if err := http.Serve(address, handler); err != nil {
+				logger.Error("Error in main(): :err", wd.ErrParam(err))
 				finishChan <- true
 			}
 		}()
 
 		go func() {
 			s := waitForExitSignal()
-			logger.Info(fmt.Sprintf("Got signal: %v, exiting.", s))
+			logger.Info("Got signal: :code, exiting.", wd.StringParam("code", s.String()))
 			finishChan <- true
 		}()
 

dispatcher/dispatcher.go

@@ -0,0 +1,26 @@
+package dispatcher
+
+import "github.com/asaskevich/EventBus"
+
+type EventDispatcher interface {
+	Subscribe(topic string, fn interface{})
+	Emit(topic string, args ...interface{})
+}
+
+type LocalEventDispatcher struct {
+	bus EventBus.Bus
+}
+
+func (d *LocalEventDispatcher) Subscribe(topic string, fn interface{}) {
+	_ = d.bus.Subscribe(topic, fn)
+}
+
+func (d *LocalEventDispatcher) Emit(topic string, args ...interface{}) {
+	d.bus.Publish(topic, args...)
+}
+
+func New() EventDispatcher {
+	return &LocalEventDispatcher{
+		bus: EventBus.New(),
+	}
+}

eventsubscribers/logger.go

@@ -0,0 +1,94 @@
+package eventsubscribers
+
+import (
+	"net"
+	"net/http"
+	"net/url"
+	"strings"
+	"syscall"
+
+	"github.com/mono83/slf"
+	"github.com/mono83/slf/wd"
+
+	"github.com/elyby/chrly/api/mojang"
+)
+
+type Logger struct {
+	slf.Logger
+}
+
+func (l *Logger) ConfigureWithDispatcher(d Subscriber) {
+	d.Subscribe("skinsystem:after_request", l.handleAfterSkinsystemRequest)
+
+	d.Subscribe("mojang_textures:usernames:after_call", l.createMojangTexturesErrorHandler("usernames"))
+	d.Subscribe("mojang_textures:textures:after_call", l.createMojangTexturesErrorHandler("textures"))
+}
+
+func (l *Logger) handleAfterSkinsystemRequest(req *http.Request, statusCode int) {
+	path := req.URL.Path
+	if req.URL.RawQuery != "" {
+		path += "?" + req.URL.RawQuery
+	}
+
+	l.Info(
+		":ip - - \":method :path\" :statusCode - \":userAgent\" \":forwardedIp\"",
+		wd.StringParam("ip", trimPort(req.RemoteAddr)),
+		wd.StringParam("method", req.Method),
+		wd.StringParam("path", path),
+		wd.IntParam("statusCode", statusCode),
+		wd.StringParam("userAgent", req.UserAgent()),
+		wd.StringParam("forwardedIp", req.Header.Get("X-Forwarded-For")),
+	)
+}
+
+func (l *Logger) createMojangTexturesErrorHandler(provider string) func(identity string, result interface{}, err error) {
+	providerParam := wd.NameParam(provider)
+	return func(identity string, result interface{}, err error) {
+		if err == nil {
+			return
+		}
+
+		errParam := wd.ErrParam(err)
+
+		switch err.(type) {
+		case *mojang.BadRequestError:
+			l.logMojangTexturesWarning(providerParam, errParam)
+			return
+		case *mojang.ForbiddenError:
+			l.logMojangTexturesWarning(providerParam, errParam)
+			return
+		case *mojang.TooManyRequestsError:
+			l.logMojangTexturesWarning(providerParam, errParam)
+			return
+		case net.Error:
+			if err.(net.Error).Timeout() {
+				return
+			}
+
+			if _, ok := err.(*url.Error); ok {
+				return
+			}
+
+			if opErr, ok := err.(*net.OpError); ok && (opErr.Op == "dial" || opErr.Op == "read") {
+				return
+			}
+
+			if err == syscall.ECONNREFUSED {
+				return
+			}
+		}
+
+		l.Error(":name: Unexpected Mojang response error: :err", providerParam, errParam)
+	}
+}
+
+func (l *Logger) logMojangTexturesWarning(providerParam slf.Param, errParam slf.Param) {
+	l.Warning(":name: :err", providerParam, errParam)
+}
+
+func trimPort(ip string) string {
+	// Don't care about possible -1 result because RemoteAddr will always contain ip and port
+	cutTo := strings.LastIndexByte(ip, ':')
+
+	return ip[0:cutTo]
+}

eventsubscribers/logger_test.go

@@ -0,0 +1,256 @@
+package eventsubscribers
+
+import (
+	"net"
+	"net/http"
+	"net/http/httptest"
+	"net/url"
+	"syscall"
+	"testing"
+
+	"github.com/mono83/slf"
+	"github.com/mono83/slf/params"
+	"github.com/stretchr/testify/mock"
+
+	"github.com/elyby/chrly/api/mojang"
+	"github.com/elyby/chrly/dispatcher"
+)
+
+type LoggerMock struct {
+	mock.Mock
+}
+
+func prepareLoggerArgs(message string, params []slf.Param) []interface{} {
+	args := []interface{}{message}
+	for _, v := range params {
+		args = append(args, v.(interface{}))
+	}
+
+	return args
+}
+
+func (l *LoggerMock) Trace(message string, params ...slf.Param) {
+	l.Called(prepareLoggerArgs(message, params)...)
+}
+
+func (l *LoggerMock) Debug(message string, params ...slf.Param) {
+	l.Called(prepareLoggerArgs(message, params)...)
+}
+
+func (l *LoggerMock) Info(message string, params ...slf.Param) {
+	l.Called(prepareLoggerArgs(message, params)...)
+}
+
+func (l *LoggerMock) Warning(message string, params ...slf.Param) {
+	l.Called(prepareLoggerArgs(message, params)...)
+}
+
+func (l *LoggerMock) Error(message string, params ...slf.Param) {
+	l.Called(prepareLoggerArgs(message, params)...)
+}
+
+func (l *LoggerMock) Alert(message string, params ...slf.Param) {
+	l.Called(prepareLoggerArgs(message, params)...)
+}
+
+func (l *LoggerMock) Emergency(message string, params ...slf.Param) {
+	l.Called(prepareLoggerArgs(message, params)...)
+}
+
+type LoggerTestCase struct {
+	Events        [][]interface{}
+	ExpectedCalls [][]interface{}
+}
+
+var loggerTestCases = map[string]*LoggerTestCase{
+	"should log each request to the skinsystem": {
+		Events: [][]interface{}{
+			{"skinsystem:after_request",
+				(func() *http.Request {
+					req := httptest.NewRequest("GET", "http://localhost/skins/username.png", nil)
+					req.Header.Add("User-Agent", "Test user agent")
+
+					return req
+				})(),
+				201,
+			},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"Info",
+				":ip - - \":method :path\" :statusCode - \":userAgent\" \":forwardedIp\"",
+				mock.MatchedBy(func(strParam params.String) bool {
+					return strParam.Key == "ip" && strParam.Value == "192.0.2.1"
+				}),
+				mock.MatchedBy(func(strParam params.String) bool {
+					return strParam.Key == "method" && strParam.Value == "GET"
+				}),
+				mock.MatchedBy(func(strParam params.String) bool {
+					return strParam.Key == "path" && strParam.Value == "/skins/username.png"
+				}),
+				mock.MatchedBy(func(strParam params.Int) bool {
+					return strParam.Key == "statusCode" && strParam.Value == 201
+				}),
+				mock.MatchedBy(func(strParam params.String) bool {
+					return strParam.Key == "userAgent" && strParam.Value == "Test user agent"
+				}),
+				mock.MatchedBy(func(strParam params.String) bool {
+					return strParam.Key == "forwardedIp" && strParam.Value == ""
+				}),
+			},
+		},
+	},
+	"should log each request to the skinsystem 2": {
+		Events: [][]interface{}{
+			{"skinsystem:after_request",
+				(func() *http.Request {
+					req := httptest.NewRequest("GET", "http://localhost/skins/username.png?authlib=1.5.2", nil)
+					req.Header.Add("User-Agent", "Test user agent")
+					req.Header.Add("X-Forwarded-For", "1.2.3.4")
+
+					return req
+				})(),
+				201,
+			},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"Info",
+				":ip - - \":method :path\" :statusCode - \":userAgent\" \":forwardedIp\"",
+				mock.Anything, // Already tested
+				mock.Anything, // Already tested
+				mock.MatchedBy(func(strParam params.String) bool {
+					return strParam.Key == "path" && strParam.Value == "/skins/username.png?authlib=1.5.2"
+				}),
+				mock.Anything, // Already tested
+				mock.Anything, // Already tested
+				mock.MatchedBy(func(strParam params.String) bool {
+					return strParam.Key == "forwardedIp" && strParam.Value == "1.2.3.4"
+				}),
+			},
+		},
+	},
+}
+
+type timeoutError struct{}
+
+func (*timeoutError) Error() string   { return "timeout error" }
+func (*timeoutError) Timeout() bool   { return true }
+func (*timeoutError) Temporary() bool { return false }
+
+func init() {
+	// mojang_textures providers errors
+	for _, providerName := range []string{"usernames", "textures"} {
+		pn := providerName // Store pointer to iteration value
+		loggerTestCases["should not log when no error occurred for "+pn+" provider"] = &LoggerTestCase{
+			Events: [][]interface{}{
+				{"mojang_textures:" + pn + ":after_call", pn, &mojang.ProfileInfo{}, nil},
+			},
+			ExpectedCalls: nil,
+		}
+
+		loggerTestCases["should not log when some network errors occured for "+pn+" provider"] = &LoggerTestCase{
+			Events: [][]interface{}{
+				{"mojang_textures:" + pn + ":after_call", pn, nil, &timeoutError{}},
+				{"mojang_textures:" + pn + ":after_call", pn, nil, &url.Error{Op: "GET", URL: "http://localhost"}},
+				{"mojang_textures:" + pn + ":after_call", pn, nil, &net.OpError{Op: "read"}},
+				{"mojang_textures:" + pn + ":after_call", pn, nil, &net.OpError{Op: "dial"}},
+				{"mojang_textures:" + pn + ":after_call", pn, nil, syscall.ECONNREFUSED},
+			},
+			ExpectedCalls: nil,
+		}
+
+		loggerTestCases["should log expected mojang errors for "+pn+" provider"] = &LoggerTestCase{
+			Events: [][]interface{}{
+				{"mojang_textures:" + pn + ":after_call", pn, nil, &mojang.BadRequestError{
+					ErrorType: "IllegalArgumentException",
+					Message:   "profileName can not be null or empty.",
+				}},
+				{"mojang_textures:" + pn + ":after_call", pn, nil, &mojang.ForbiddenError{}},
+				{"mojang_textures:" + pn + ":after_call", pn, nil, &mojang.TooManyRequestsError{}},
+			},
+			ExpectedCalls: [][]interface{}{
+				{"Warning",
+					":name: :err",
+					mock.MatchedBy(func(strParam params.String) bool {
+						return strParam.Key == "name" && strParam.Value == pn
+					}),
+					mock.MatchedBy(func(errParam params.Error) bool {
+						if errParam.Key != "err" {
+							return false
+						}
+
+						if _, ok := errParam.Value.(*mojang.BadRequestError); ok {
+							return true
+						}
+
+						if _, ok := errParam.Value.(*mojang.ForbiddenError); ok {
+							return true
+						}
+
+						if _, ok := errParam.Value.(*mojang.TooManyRequestsError); ok {
+							return true
+						}
+
+						return false
+					}),
+				},
+			},
+		}
+
+		loggerTestCases["should call error when unexpected error occurred for "+pn+" provider"] = &LoggerTestCase{
+			Events: [][]interface{}{
+				{"mojang_textures:" + pn + ":after_call", pn, nil, &mojang.ServerError{Status: 500}},
+			},
+			ExpectedCalls: [][]interface{}{
+				{"Error",
+					":name: Unexpected Mojang response error: :err",
+					mock.MatchedBy(func(strParam params.String) bool {
+						return strParam.Key == "name" && strParam.Value == pn
+					}),
+					mock.MatchedBy(func(errParam params.Error) bool {
+						if errParam.Key != "err" {
+							return false
+						}
+
+						if _, ok := errParam.Value.(*mojang.ServerError); !ok {
+							return false
+						}
+
+						return true
+					}),
+				},
+			},
+		}
+	}
+}
+
+func TestLogger(t *testing.T) {
+	for name, c := range loggerTestCases {
+		t.Run(name, func(t *testing.T) {
+			loggerMock := &LoggerMock{}
+			if c.ExpectedCalls != nil {
+				for _, c := range c.ExpectedCalls {
+					topicName, _ := c[0].(string)
+					loggerMock.On(topicName, c[1:]...)
+				}
+			}
+
+			reporter := &Logger{
+				Logger: loggerMock,
+			}
+
+			d := dispatcher.New()
+			reporter.ConfigureWithDispatcher(d)
+			for _, args := range c.Events {
+				eventName, _ := args[0].(string)
+				d.Emit(eventName, args[1:]...)
+			}
+
+			if c.ExpectedCalls != nil {
+				for _, c := range c.ExpectedCalls {
+					topicName, _ := c[0].(string)
+					loggerMock.AssertCalled(t, topicName, c[1:]...)
+				}
+			}
+		})
+	}
+}

eventsubscribers/stats_reporter.go

@@ -0,0 +1,177 @@
+package eventsubscribers
+
+import (
+	"net/http"
+	"strings"
+	"sync"
+	"time"
+
+	"github.com/mono83/slf"
+
+	"github.com/elyby/chrly/api/mojang"
+)
+
+type StatsReporter struct {
+	slf.StatsReporter
+	Prefix string
+
+	timersMap   map[string]time.Time
+	timersMutex sync.Mutex
+}
+
+func (s *StatsReporter) ConfigureWithDispatcher(d Subscriber) {
+	s.timersMap = make(map[string]time.Time)
+
+	// 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", 1)
+		} else {
+			s.IncCounter("mojang_textures:usernames:cache_hit", 1)
+		}
+	})
+	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", 1)
+		}
+	})
+	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", 1)
+		} else {
+			s.IncCounter("mojang_textures.usernames.uuid_hit", 1)
+		}
+	})
+	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", 1)
+		} else {
+			s.IncCounter("mojang_textures.usernames.textures_hit", 1)
+		}
+	})
+	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) {
+	var key string
+	m := req.Method
+	p := req.URL.Path
+	if p == "/skins" {
+		key = "skins.get_request"
+	} else if strings.HasPrefix(p, "/skins/") {
+		key = "skins.request"
+	} else if p == "/cloaks" {
+		key = "capes.get_request"
+	} else if strings.HasPrefix(p, "/cloaks/") {
+		key = "capes.request"
+	} else if strings.HasPrefix(p, "/textures/signed/") {
+		key = "signed_textures.request"
+	} else if strings.HasPrefix(p, "/textures/") {
+		key = "textures.request"
+	} else if m == http.MethodPost && p == "/api/skins" {
+		key = "api.skins.post.request"
+	} else if m == http.MethodDelete && strings.HasPrefix(p, "/api/skins/") {
+		key = "api.skins.delete.request"
+	} else {
+		return
+	}
+
+	s.IncCounter(key, 1)
+}
+
+func (s *StatsReporter) handleAfterRequest(req *http.Request, code int) {
+	var key string
+	m := req.Method
+	p := req.URL.Path
+	if m == http.MethodPost && p == "/api/skins" && code == http.StatusCreated {
+		key = "api.skins.post.success"
+	} else if m == http.MethodPost && p == "/api/skins" && code == http.StatusBadRequest {
+		key = "api.skins.post.validation_failed"
+	} else if m == http.MethodDelete && strings.HasPrefix(p, "/api/skins/") && code == http.StatusNoContent {
+		key = "api.skins.delete.success"
+	} else if m == http.MethodDelete && strings.HasPrefix(p, "/api/skins/") && code == http.StatusNotFound {
+		key = "api.skins.delete.not_found"
+	} else {
+		return
+	}
+
+	s.IncCounter(key, 1)
+}
+
+func (s *StatsReporter) incCounterHandler(name string) func(...interface{}) {
+	return func(...interface{}) {
+		s.IncCounter(name, 1)
+	}
+}
+
+func (s *StatsReporter) startTimeRecording(timeKey string) {
+	s.timersMutex.Lock()
+	defer s.timersMutex.Unlock()
+	s.timersMap[timeKey] = time.Now()
+}
+
+func (s *StatsReporter) finalizeTimeRecording(timeKey string, statName string) {
+	s.timersMutex.Lock()
+	defer s.timersMutex.Unlock()
+	startedAt, ok := s.timersMap[timeKey]
+	if !ok {
+		return
+	}
+
+	delete(s.timersMap, timeKey)
+
+	s.RecordTimer(statName, time.Since(startedAt))
+}

eventsubscribers/stats_reporter_test.go

@@ -0,0 +1,383 @@
+package eventsubscribers
+
+import (
+	"errors"
+	"net/http/httptest"
+	"testing"
+	"time"
+
+	"github.com/mono83/slf"
+
+	"github.com/elyby/chrly/api/mojang"
+	"github.com/elyby/chrly/dispatcher"
+
+	"github.com/stretchr/testify/mock"
+)
+
+func prepareStatsReporterArgs(name string, value interface{}, params []slf.Param) []interface{} {
+	args := []interface{}{name, value}
+	for _, v := range params {
+		args = append(args, v.(interface{}))
+	}
+
+	return args
+}
+
+type StatsReporterMock struct {
+	mock.Mock
+}
+
+func (r *StatsReporterMock) IncCounter(name string, value int64, params ...slf.Param) {
+	r.Called(prepareStatsReporterArgs(name, value, params)...)
+}
+
+func (r *StatsReporterMock) UpdateGauge(name string, value int64, params ...slf.Param) {
+	r.Called(prepareStatsReporterArgs(name, value, params)...)
+}
+
+func (r *StatsReporterMock) RecordTimer(name string, duration time.Duration, params ...slf.Param) {
+	r.Called(prepareStatsReporterArgs(name, duration, params)...)
+}
+
+func (r *StatsReporterMock) Timer(name string, params ...slf.Param) slf.Timer {
+	return slf.NewTimer(name, params, r)
+}
+
+type StatsReporterTestCase struct {
+	Events        [][]interface{}
+	ExpectedCalls [][]interface{}
+}
+
+var statsReporterTestCases = []*StatsReporterTestCase{
+	// Before request
+	{
+		Events: [][]interface{}{
+			{"skinsystem:before_request", httptest.NewRequest("GET", "http://localhost/skins/username", nil)},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "skins.request", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"skinsystem:before_request", httptest.NewRequest("GET", "http://localhost/skins?name=username", nil)},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "skins.get_request", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"skinsystem:before_request", httptest.NewRequest("GET", "http://localhost/cloaks/username", nil)},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "capes.request", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"skinsystem:before_request", httptest.NewRequest("GET", "http://localhost/cloaks?name=username", nil)},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "capes.get_request", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"skinsystem:before_request", httptest.NewRequest("GET", "http://localhost/textures/username", nil)},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "textures.request", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"skinsystem:before_request", httptest.NewRequest("GET", "http://localhost/textures/signed/username", nil)},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "signed_textures.request", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"skinsystem:before_request", httptest.NewRequest("POST", "http://localhost/api/skins", nil)},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "api.skins.post.request", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"skinsystem:before_request", httptest.NewRequest("DELETE", "http://localhost/api/skins/username", nil)},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "api.skins.delete.request", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"skinsystem:before_request", httptest.NewRequest("DELETE", "http://localhost/api/skins/id:1", nil)},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "api.skins.delete.request", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"skinsystem:before_request", httptest.NewRequest("GET", "http://localhost/unknown", nil)},
+		},
+		ExpectedCalls: nil,
+	},
+	// After request
+	{
+		Events: [][]interface{}{
+			{"skinsystem:after_request", httptest.NewRequest("POST", "http://localhost/api/skins", nil), 201},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "api.skins.post.success", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"skinsystem:after_request", httptest.NewRequest("POST", "http://localhost/api/skins", nil), 400},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "api.skins.post.validation_failed", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"skinsystem:after_request", httptest.NewRequest("DELETE", "http://localhost/api/skins/username", nil), 204},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "api.skins.delete.success", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"skinsystem:after_request", httptest.NewRequest("DELETE", "http://localhost/api/skins/username", nil), 404},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "api.skins.delete.not_found", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"skinsystem:after_request", httptest.NewRequest("DELETE", "http://localhost/api/skins/id:1", nil), 204},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "api.skins.delete.success", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"skinsystem:after_request", httptest.NewRequest("DELETE", "http://localhost/api/skins/id:1", nil), 404},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "api.skins.delete.not_found", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"skinsystem:after_request", httptest.NewRequest("DELETE", "http://localhost/unknown", nil), 404},
+		},
+		ExpectedCalls: nil,
+	},
+	// Authenticator
+	{
+		Events: [][]interface{}{
+			{"authenticator:success"},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "authentication.challenge", int64(1)},
+			{"IncCounter", "authentication.success", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"authentication:error", errors.New("error")},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "authentication.challenge", int64(1)},
+			{"IncCounter", "authentication.failed", int64(1)},
+		},
+	},
+	// Mojang signed textures provider
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:call", "username"},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "mojang_textures.request", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:usernames:after_cache", "username", "", errors.New("error")},
+		},
+		ExpectedCalls: [][]interface{}{},
+	},
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:usernames:after_cache", "username", "", nil},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "mojang_textures:usernames:cache_hit_nil", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:usernames:after_cache", "username", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", nil},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "mojang_textures:usernames:cache_hit", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:textures:after_cache", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", nil, errors.New("error")},
+		},
+		ExpectedCalls: [][]interface{}{},
+	},
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:textures:after_cache", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", nil, nil},
+		},
+		ExpectedCalls: [][]interface{}{},
+	},
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:textures:after_cache", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", &mojang.SignedTexturesResponse{}, nil},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "mojang_textures.textures.cache_hit", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:already_processing", "username"},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "mojang_textures.already_scheduled", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:usernames:after_call", "username", nil, errors.New("error")},
+		},
+		ExpectedCalls: [][]interface{}{},
+	},
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:usernames:after_call", "username", nil, nil},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "mojang_textures.usernames.uuid_miss", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:usernames:after_call", "username", &mojang.ProfileInfo{}, nil},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "mojang_textures.usernames.uuid_hit", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:textures:after_call", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", nil, errors.New("error")},
+		},
+		ExpectedCalls: [][]interface{}{},
+	},
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:textures:after_call", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", nil, nil},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "mojang_textures.usernames.textures_miss", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:textures:after_call", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", &mojang.SignedTexturesResponse{}, nil},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "mojang_textures.usernames.textures_hit", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:before_result", "username", ""},
+			{"mojang_textures:after_result", "username", &mojang.SignedTexturesResponse{}, nil},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"RecordTimer", "mojang_textures.result_time", mock.AnythingOfType("time.Duration")},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:textures:before_call", "аааааааааааааааааааааааааааааааа"},
+			{"mojang_textures:textures:after_call", "аааааааааааааааааааааааааааааааа", &mojang.SignedTexturesResponse{}, nil},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "mojang_textures.textures.request", int64(1)},
+			{"IncCounter", "mojang_textures.usernames.textures_hit", int64(1)},
+			{"RecordTimer", "mojang_textures.textures.request_time", mock.AnythingOfType("time.Duration")},
+		},
+	},
+	// Batch UUIDs provider
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:batch_uuids_provider:queued", "username"},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"IncCounter", "mojang_textures.usernames.queued", int64(1)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:batch_uuids_provider:round", []string{"username1", "username2"}, 5},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"UpdateGauge", "mojang_textures.usernames.iteration_size", int64(2)},
+			{"UpdateGauge", "mojang_textures.usernames.queue_size", int64(5)},
+		},
+	},
+	{
+		Events: [][]interface{}{
+			{"mojang_textures:batch_uuids_provider:before_round"},
+			{"mojang_textures:batch_uuids_provider:after_round"},
+		},
+		ExpectedCalls: [][]interface{}{
+			{"RecordTimer", "mojang_textures.usernames.round_time", mock.AnythingOfType("time.Duration")},
+		},
+	},
+}
+
+func TestStatsReporter(t *testing.T) {
+	for _, c := range statsReporterTestCases {
+		t.Run("handle events", func(t *testing.T) {
+			statsReporterMock := &StatsReporterMock{}
+			if c.ExpectedCalls != nil {
+				for _, c := range c.ExpectedCalls {
+					topicName, _ := c[0].(string)
+					statsReporterMock.On(topicName, c[1:]...).Once()
+				}
+			}
+
+			reporter := &StatsReporter{
+				StatsReporter: statsReporterMock,
+				Prefix:        "mock_prefix",
+			}
+
+			d := dispatcher.New()
+			reporter.ConfigureWithDispatcher(d)
+			for _, e := range c.Events {
+				eventName, _ := e[0].(string)
+				d.Emit(eventName, e[1:]...)
+			}
+
+			statsReporterMock.AssertExpectations(t)
+		})
+	}
+}

eventsubscribers/subscriber.go

@@ -0,0 +1,5 @@
+package eventsubscribers
+
+type Subscriber interface {
+	Subscribe(topic string, fn interface{})
+}

http/http.go

@@ -2,9 +2,82 @@ package http
 
 import (
 	"encoding/json"
+	"net"
 	"net/http"
+	"strings"
+	"time"
+
+	"github.com/gorilla/mux"
 )
 
+type Emitter interface {
+	Emit(name string, args ...interface{})
+}
+
+func Serve(address string, handler http.Handler) error {
+	listener, err := net.Listen("tcp", address)
+	if err != nil {
+		return err
+	}
+
+	server := &http.Server{
+		ReadTimeout:    5 * time.Second,
+		WriteTimeout:   5 * time.Second,
+		IdleTimeout:    60 * time.Second,
+		MaxHeaderBytes: 1 << 16,
+		Handler:        handler,
+	}
+
+	return server.Serve(listener)
+}
+
+type loggingResponseWriter struct {
+	http.ResponseWriter
+	statusCode int
+}
+
+func (lrw *loggingResponseWriter) WriteHeader(code int) {
+	lrw.statusCode = code
+	lrw.ResponseWriter.WriteHeader(code)
+}
+
+func CreateRequestEventsMiddleware(emitter Emitter, prefix string) mux.MiddlewareFunc {
+	beforeTopic := strings.Join([]string{prefix, "before_request"}, ":")
+	afterTopic := strings.Join([]string{prefix, "after_request"}, ":")
+
+	return func(handler http.Handler) http.Handler {
+		return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) {
+			emitter.Emit(beforeTopic, req)
+
+			lrw := &loggingResponseWriter{
+				ResponseWriter: resp,
+				statusCode:     http.StatusOK,
+			}
+			handler.ServeHTTP(lrw, req)
+
+			emitter.Emit(afterTopic, req, lrw.statusCode)
+		})
+	}
+}
+
+type Authenticator interface {
+	Authenticate(req *http.Request) error
+}
+
+func CreateAuthenticationMiddleware(checker Authenticator) mux.MiddlewareFunc {
+	return func(handler http.Handler) http.Handler {
+		return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) {
+			err := checker.Authenticate(req)
+			if err != nil {
+				apiForbidden(resp, err.Error())
+				return
+			}
+
+			handler.ServeHTTP(resp, req)
+		})
+	}
+}
+
 func NotFound(response http.ResponseWriter, _ *http.Request) {
 	data, _ := json.Marshal(map[string]string{
 		"status":  "404",

http/http_test.go

@@ -1,14 +1,99 @@
 package http
 
 import (
+	"errors"
 	"io/ioutil"
+	"net/http"
 	"net/http/httptest"
 	"testing"
 
 	testify "github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/mock"
 )
 
-func TestConfig_NotFound(t *testing.T) {
+type emitterMock struct {
+	mock.Mock
+}
+
+func (e *emitterMock) Emit(name string, args ...interface{}) {
+	e.Called(append([]interface{}{name}, args...)...)
+}
+
+func TestCreateRequestEventsMiddleware(t *testing.T) {
+	req := httptest.NewRequest("GET", "http://example.com", nil)
+	resp := httptest.NewRecorder()
+
+	emitter := &emitterMock{}
+	emitter.On("Emit", "test_prefix:before_request", req)
+	emitter.On("Emit", "test_prefix:after_request", req, 400)
+
+	isHandlerCalled := false
+	middlewareFunc := CreateRequestEventsMiddleware(emitter, "test_prefix")
+	middlewareFunc.Middleware(http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) {
+		resp.WriteHeader(400)
+		isHandlerCalled = true
+	})).ServeHTTP(resp, req)
+
+	if !isHandlerCalled {
+		t.Fatal("Handler isn't called from the middleware")
+	}
+
+	emitter.AssertExpectations(t)
+}
+
+type authCheckerMock struct {
+	mock.Mock
+}
+
+func (m *authCheckerMock) Authenticate(req *http.Request) error {
+	args := m.Called(req)
+	return args.Error(0)
+}
+
+func TestCreateAuthenticationMiddleware(t *testing.T) {
+	t.Run("pass", func(t *testing.T) {
+		req := httptest.NewRequest("GET", "http://example.com", nil)
+		resp := httptest.NewRecorder()
+
+		auth := &authCheckerMock{}
+		auth.On("Authenticate", req).Once().Return(nil)
+
+		isHandlerCalled := false
+		middlewareFunc := CreateAuthenticationMiddleware(auth)
+		middlewareFunc.Middleware(http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) {
+			isHandlerCalled = true
+		})).ServeHTTP(resp, req)
+
+		testify.True(t, isHandlerCalled, "Handler isn't called from the middleware")
+
+		auth.AssertExpectations(t)
+	})
+
+	t.Run("fail", func(t *testing.T) {
+		req := httptest.NewRequest("GET", "http://example.com", nil)
+		resp := httptest.NewRecorder()
+
+		auth := &authCheckerMock{}
+		auth.On("Authenticate", req).Once().Return(errors.New("error reason"))
+
+		isHandlerCalled := false
+		middlewareFunc := CreateAuthenticationMiddleware(auth)
+		middlewareFunc.Middleware(http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) {
+			isHandlerCalled = true
+		})).ServeHTTP(resp, req)
+
+		testify.False(t, isHandlerCalled, "Handler shouldn't be called")
+		testify.Equal(t, 403, resp.Code)
+		body, _ := ioutil.ReadAll(resp.Body)
+		testify.JSONEq(t, `{
+			"error": "error reason"
+		}`, string(body))
+
+		auth.AssertExpectations(t)
+	})
+}
+
+func TestNotFound(t *testing.T) {
 	assert := testify.New(t)
 
 	req := httptest.NewRequest("GET", "http://example.com", nil)

http/jwt.go

@@ -1,4 +1,4 @@
-package auth
+package http
 
 import (
 	"errors"
@@ -21,6 +21,7 @@ var (
 )
 
 type JwtAuth struct {
+	Emitter
 	Key []byte
 }
 
@@ -41,42 +42,37 @@ func (t *JwtAuth) NewToken(scopes ...Scope) ([]byte, error) {
 	return token, nil
 }
 
-func (t *JwtAuth) Check(req *http.Request) error {
+func (t *JwtAuth) Authenticate(req *http.Request) error {
 	if len(t.Key) == 0 {
-		return &Unauthorized{"Signing key not set"}
+		return t.emitErr(errors.New("Signing key not set"))
 	}
 
 	bearerToken := req.Header.Get("Authorization")
 	if bearerToken == "" {
-		return &Unauthorized{"Authentication header not presented"}
+		return t.emitErr(errors.New("Authentication header not presented"))
 	}
 
 	if !strings.EqualFold(bearerToken[0:7], "BEARER ") {
-		return &Unauthorized{"Cannot recognize JWT token in passed value"}
+		return t.emitErr(errors.New("Cannot recognize JWT token in passed value"))
 	}
 
 	tokenStr := bearerToken[7:]
 	token, err := jws.ParseJWT([]byte(tokenStr))
 	if err != nil {
-		return &Unauthorized{"Cannot parse passed JWT token"}
+		return t.emitErr(errors.New("Cannot parse passed JWT token"))
 	}
 
 	err = token.Validate(t.Key, hashAlg)
 	if err != nil {
-		return &Unauthorized{"JWT token have invalid signature. It may be corrupted or expired."}
+		return t.emitErr(errors.New("JWT token have invalid signature. It may be corrupted or expired"))
 	}
 
+	t.Emit("authentication:success")
+
 	return nil
 }
 
-type Unauthorized struct {
+func (t *JwtAuth) emitErr(err error) error {
-	Reason string
+	t.Emit("authentication:error", err)
-}
+	return err
-
-func (e *Unauthorized) Error() string {
-	if e.Reason != "" {
-		return e.Reason
-	}
-
-	return "Unauthorized"
 }

http/jwt_test.go

@@ -0,0 +1,127 @@
+package http
+
+import (
+	"net/http/httptest"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/mock"
+)
+
+const jwt = "eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiIxNTE2NjU4MTkzIiwic2NvcGVzIjoic2tpbiJ9.agbBS0qdyYMBaVfTZJAZcTTRgW1Y0kZty4H3N2JHBO8"
+
+func TestJwtAuth_NewToken(t *testing.T) {
+	t.Run("success", func(t *testing.T) {
+		jwt := &JwtAuth{Key: []byte("secret")}
+		token, err := jwt.NewToken(SkinScope)
+		assert.Nil(t, err)
+		assert.NotNil(t, token)
+	})
+
+	t.Run("key not provided", func(t *testing.T) {
+		jwt := &JwtAuth{}
+		token, err := jwt.NewToken(SkinScope)
+		assert.Error(t, err, "signing key not available")
+		assert.Nil(t, token)
+	})
+}
+
+func TestJwtAuth_Authenticate(t *testing.T) {
+	t.Run("success", func(t *testing.T) {
+		emitter := &emitterMock{}
+		emitter.On("Emit", "authentication:success")
+
+		req := httptest.NewRequest("POST", "http://localhost", nil)
+		req.Header.Add("Authorization", "Bearer " + jwt)
+		jwt := &JwtAuth{Key: []byte("secret"), Emitter: emitter}
+
+		err := jwt.Authenticate(req)
+		assert.Nil(t, err)
+
+		emitter.AssertExpectations(t)
+	})
+
+	t.Run("request without auth header", func(t *testing.T) {
+		emitter := &emitterMock{}
+		emitter.On("Emit", "authentication:error", mock.MatchedBy(func(err error) bool {
+			assert.Error(t, err, "Authentication header not presented")
+			return true
+		}))
+
+		req := httptest.NewRequest("POST", "http://localhost", nil)
+		jwt := &JwtAuth{Key: []byte("secret"), Emitter: emitter}
+
+		err := jwt.Authenticate(req)
+		assert.Error(t, err, "Authentication header not presented")
+
+		emitter.AssertExpectations(t)
+	})
+
+	t.Run("no bearer token prefix", func(t *testing.T) {
+		emitter := &emitterMock{}
+		emitter.On("Emit", "authentication:error", mock.MatchedBy(func(err error) bool {
+			assert.Error(t, err, "Cannot recognize JWT token in passed value")
+			return true
+		}))
+
+		req := httptest.NewRequest("POST", "http://localhost", nil)
+		req.Header.Add("Authorization", "this is not jwt")
+		jwt := &JwtAuth{Key: []byte("secret"), Emitter: emitter}
+
+		err := jwt.Authenticate(req)
+		assert.Error(t, err, "Cannot recognize JWT token in passed value")
+
+		emitter.AssertExpectations(t)
+	})
+
+	t.Run("bearer token but not jwt", func(t *testing.T) {
+		emitter := &emitterMock{}
+		emitter.On("Emit", "authentication:error", mock.MatchedBy(func(err error) bool {
+			assert.Error(t, err, "Cannot parse passed JWT token")
+			return true
+		}))
+
+		req := httptest.NewRequest("POST", "http://localhost", nil)
+		req.Header.Add("Authorization", "Bearer thisIs.Not.Jwt")
+		jwt := &JwtAuth{Key: []byte("secret"), Emitter: emitter}
+
+		err := jwt.Authenticate(req)
+		assert.Error(t, err, "Cannot parse passed JWT token")
+
+		emitter.AssertExpectations(t)
+	})
+
+	t.Run("when secret is not set", func(t *testing.T) {
+		emitter := &emitterMock{}
+		emitter.On("Emit", "authentication:error", mock.MatchedBy(func(err error) bool {
+			assert.Error(t, err, "Signing key not set")
+			return true
+		}))
+
+		req := httptest.NewRequest("POST", "http://localhost", nil)
+		req.Header.Add("Authorization", "Bearer " + jwt)
+		jwt := &JwtAuth{Emitter: emitter}
+
+		err := jwt.Authenticate(req)
+		assert.Error(t, err, "Signing key not set")
+
+		emitter.AssertExpectations(t)
+	})
+
+	t.Run("invalid signature", func(t *testing.T) {
+		emitter := &emitterMock{}
+		emitter.On("Emit", "authentication:error", mock.MatchedBy(func(err error) bool {
+			assert.Error(t, err, "JWT token have invalid signature. It may be corrupted or expired")
+			return true
+		}))
+
+		req := httptest.NewRequest("POST", "http://localhost", nil)
+		req.Header.Add("Authorization", "Bearer " + jwt)
+		jwt := &JwtAuth{Key: []byte("this is another secret"), Emitter: emitter}
+
+		err := jwt.Authenticate(req)
+		assert.Error(t, err, "JWT token have invalid signature. It may be corrupted or expired")
+
+		emitter.AssertExpectations(t)
+	})
+}

http/skinsystem.go

@@ -5,19 +5,15 @@ import (
 	"errors"
 	"fmt"
 	"io"
-	"net"
 	"net/http"
 	"regexp"
 	"strconv"
 	"strings"
-	"time"
 
 	"github.com/gorilla/mux"
-	"github.com/mono83/slf/wd"
 	"github.com/thedevsaddam/govalidator"
 
 	"github.com/elyby/chrly/api/mojang"
-	"github.com/elyby/chrly/auth"
 	"github.com/elyby/chrly/model"
 )
 
@@ -67,7 +63,7 @@ type SkinNotFoundError struct {
 }
 
 func (e SkinNotFoundError) Error() string {
-	return "Skin data not found."
+	return "skin data not found"
 }
 
 type CapeNotFoundError struct {
@@ -75,74 +71,51 @@ type CapeNotFoundError struct {
 }
 
 func (e CapeNotFoundError) Error() string {
-	return "Cape file not found."
+	return "cape file not found"
 }
 
 type MojangTexturesProvider interface {
 	GetForUsername(username string) (*mojang.SignedTexturesResponse, error)
 }
 
-type AuthChecker interface {
-	Check(req *http.Request) error
-}
-
 type Skinsystem struct {
-	ListenSpec              string
+	Emitter
 	TexturesExtraParamName  string
 	TexturesExtraParamValue string
-
+	SkinsRepo               SkinsRepository
-	SkinsRepo              SkinsRepository
+	CapesRepo               CapesRepository
-	CapesRepo              CapesRepository
+	MojangTexturesProvider  MojangTexturesProvider
-	MojangTexturesProvider MojangTexturesProvider
+	Authenticator           Authenticator
-	Auth                   AuthChecker
-	Logger                 wd.Watchdog
-}
-
-func (ctx *Skinsystem) Run() error {
-	ctx.Logger.Info(fmt.Sprintf("Starting the app, HTTP on: %s\n", ctx.ListenSpec))
-
-	listener, err := net.Listen("tcp", ctx.ListenSpec)
-	if err != nil {
-		return err
-	}
-
-	server := &http.Server{
-		ReadTimeout:    60 * time.Second,
-		WriteTimeout:   60 * time.Second,
-		MaxHeaderBytes: 1 << 16,
-		Handler:        ctx.CreateHandler(),
-	}
-
-	return server.Serve(listener)
 }
 
 func (ctx *Skinsystem) CreateHandler() *mux.Router {
-	router := mux.NewRouter().StrictSlash(true)
+	requestEventsMiddleware := CreateRequestEventsMiddleware(ctx.Emitter, "skinsystem")
 
-	router.HandleFunc("/skins/{username}", ctx.Skin).Methods("GET")
+	router := mux.NewRouter().StrictSlash(true)
-	router.HandleFunc("/cloaks/{username}", ctx.Cape).Methods("GET").Name("cloaks")
+	router.Use(requestEventsMiddleware)
-	router.HandleFunc("/textures/{username}", ctx.Textures).Methods("GET")
+
-	router.HandleFunc("/textures/signed/{username}", ctx.SignedTextures).Methods("GET")
+	router.HandleFunc("/skins/{username}", ctx.Skin).Methods(http.MethodGet)
+	router.HandleFunc("/cloaks/{username}", ctx.Cape).Methods(http.MethodGet).Name("cloaks")
+	router.HandleFunc("/textures/{username}", ctx.Textures).Methods(http.MethodGet)
+	router.HandleFunc("/textures/signed/{username}", ctx.SignedTextures).Methods(http.MethodGet)
 	// Legacy
-	router.HandleFunc("/skins", ctx.SkinGET).Methods("GET")
+	router.HandleFunc("/skins", ctx.SkinGET).Methods(http.MethodGet)
-	router.HandleFunc("/cloaks", ctx.CapeGET).Methods("GET")
+	router.HandleFunc("/cloaks", ctx.CapeGET).Methods(http.MethodGet)
 	// API
 	apiRouter := router.PathPrefix("/api").Subrouter()
-	apiRouter.Use(ctx.AuthenticationMiddleware)
+	apiRouter.Use(CreateAuthenticationMiddleware(ctx.Authenticator))
-	apiRouter.Handle("/skins", http.HandlerFunc(ctx.PostSkin)).Methods("POST")
+	apiRouter.HandleFunc("/skins", ctx.PostSkin).Methods(http.MethodPost)
-	apiRouter.Handle("/skins/id:{id:[0-9]+}", http.HandlerFunc(ctx.DeleteSkinByUserId)).Methods("DELETE")
+	apiRouter.HandleFunc("/skins/id:{id:[0-9]+}", ctx.DeleteSkinByUserId).Methods(http.MethodDelete)
-	apiRouter.Handle("/skins/{username}", http.HandlerFunc(ctx.DeleteSkinByUsername)).Methods("DELETE")
+	apiRouter.HandleFunc("/skins/{username}", ctx.DeleteSkinByUsername).Methods(http.MethodDelete)
 	// 404
-	router.NotFoundHandler = http.HandlerFunc(NotFound)
+	// NotFoundHandler doesn't call for registered middlewares, so we must wrap it manually.
+	// See https://github.com/gorilla/mux/issues/416#issuecomment-600079279
+	router.NotFoundHandler = requestEventsMiddleware(http.HandlerFunc(NotFound))
 
 	return router
 }
 
 func (ctx *Skinsystem) Skin(response http.ResponseWriter, request *http.Request) {
-	if mux.Vars(request)["converted"] == "" {
-		ctx.Logger.IncCounter("skins.request", 1)
-	}
-
 	username := parseUsername(mux.Vars(request)["username"])
 	rec, err := ctx.SkinsRepo.FindByUsername(username)
 	if err == nil && rec.SkinId != 0 {
@@ -173,7 +146,6 @@ func (ctx *Skinsystem) SkinGET(response http.ResponseWriter, request *http.Reque
 		return
 	}
 
-	ctx.Logger.IncCounter("skins.get_request", 1)
 	mux.Vars(request)["username"] = username
 	mux.Vars(request)["converted"] = "1"
 
@@ -181,10 +153,6 @@ func (ctx *Skinsystem) SkinGET(response http.ResponseWriter, request *http.Reque
 }
 
 func (ctx *Skinsystem) Cape(response http.ResponseWriter, request *http.Request) {
-	if mux.Vars(request)["converted"] == "" {
-		ctx.Logger.IncCounter("capes.request", 1)
-	}
-
 	username := parseUsername(mux.Vars(request)["username"])
 	rec, err := ctx.CapesRepo.FindByUsername(username)
 	if err == nil {
@@ -216,7 +184,6 @@ func (ctx *Skinsystem) CapeGET(response http.ResponseWriter, request *http.Reque
 		return
 	}
 
-	ctx.Logger.IncCounter("capes.get_request", 1)
 	mux.Vars(request)["username"] = username
 	mux.Vars(request)["converted"] = "1"
 
@@ -224,7 +191,6 @@ func (ctx *Skinsystem) CapeGET(response http.ResponseWriter, request *http.Reque
 }
 
 func (ctx *Skinsystem) Textures(response http.ResponseWriter, request *http.Request) {
-	ctx.Logger.IncCounter("textures.request", 1)
 	username := parseUsername(mux.Vars(request)["username"])
 
 	var textures *mojang.TexturesResponse
@@ -261,8 +227,8 @@ func (ctx *Skinsystem) Textures(response http.ResponseWriter, request *http.Requ
 
 		texturesProp := mojangTextures.DecodeTextures()
 		if texturesProp == nil {
-			response.WriteHeader(http.StatusInternalServerError)
+			ctx.Emit("skinsystem:error", errors.New("unable to find textures property"))
-			ctx.Logger.Error("Unable to find textures property")
+			apiServerError(response)
 			return
 		}
 
@@ -275,7 +241,6 @@ func (ctx *Skinsystem) Textures(response http.ResponseWriter, request *http.Requ
 }
 
 func (ctx *Skinsystem) SignedTextures(response http.ResponseWriter, request *http.Request) {
-	ctx.Logger.IncCounter("signed_textures.request", 1)
 	username := parseUsername(mux.Vars(request)["username"])
 
 	var responseData *mojang.SignedTexturesResponse
@@ -316,10 +281,8 @@ func (ctx *Skinsystem) SignedTextures(response http.ResponseWriter, request *htt
 }
 
 func (ctx *Skinsystem) PostSkin(resp http.ResponseWriter, req *http.Request) {
-	ctx.Logger.IncCounter("api.skins.post.request", 1)
 	validationErrors := validatePostSkinRequest(req)
 	if validationErrors != nil {
-		ctx.Logger.IncCounter("api.skins.post.validation_failed", 1)
 		apiBadRequest(resp, validationErrors)
 		return
 	}
@@ -329,7 +292,7 @@ func (ctx *Skinsystem) PostSkin(resp http.ResponseWriter, req *http.Request) {
 
 	record, err := findIdentity(ctx.SkinsRepo, identityId, username)
 	if err != nil {
-		ctx.Logger.Error("Error on requesting a skin from the repository: :err", wd.ErrParam(err))
+		ctx.Emit("skinsystem:error", fmt.Errorf("error on requesting a skin from the repository: %w", err))
 		apiServerError(resp)
 		return
 	}
@@ -348,71 +311,45 @@ func (ctx *Skinsystem) PostSkin(resp http.ResponseWriter, req *http.Request) {
 
 	err = ctx.SkinsRepo.Save(record)
 	if err != nil {
-		ctx.Logger.Error("Unable to save record to the repository: :err", wd.ErrParam(err))
+		ctx.Emit("skinsystem:error", fmt.Errorf("unable to save record to the repository: %w", err))
 		apiServerError(resp)
 		return
 	}
 
-	ctx.Logger.IncCounter("api.skins.post.success", 1)
 	resp.WriteHeader(http.StatusCreated)
 }
 
 func (ctx *Skinsystem) DeleteSkinByUserId(resp http.ResponseWriter, req *http.Request) {
-	ctx.Logger.IncCounter("api.skins.delete.request", 1)
 	id, _ := strconv.Atoi(mux.Vars(req)["id"])
 	skin, err := ctx.SkinsRepo.FindByUserId(id)
-	if err != nil {
+	ctx.deleteSkin(skin, err, resp)
-		ctx.Logger.IncCounter("api.skins.delete.not_found", 1)
-		apiNotFound(resp, "Cannot find record for requested user id")
-		return
-	}
-
-	ctx.deleteSkin(skin, resp)
 }
 
 func (ctx *Skinsystem) DeleteSkinByUsername(resp http.ResponseWriter, req *http.Request) {
-	ctx.Logger.IncCounter("api.skins.delete.request", 1)
 	username := mux.Vars(req)["username"]
 	skin, err := ctx.SkinsRepo.FindByUsername(username)
+	ctx.deleteSkin(skin, err, resp)
+}
+
+func (ctx *Skinsystem) deleteSkin(skin *model.Skin, err error, resp http.ResponseWriter) {
 	if err != nil {
-		ctx.Logger.IncCounter("api.skins.delete.not_found", 1)
+		if _, ok := err.(*SkinNotFoundError); ok {
-		apiNotFound(resp, "Cannot find record for requested username")
+			apiNotFound(resp, "Cannot find record for the requested identifier")
+		} else {
+			ctx.Emit("skinsystem:error", fmt.Errorf("unable to find skin info from the repository: %w", err))
+			apiServerError(resp)
+		}
+
 		return
 	}
 
-	ctx.deleteSkin(skin, resp)
+	err = ctx.SkinsRepo.RemoveByUserId(skin.UserId)
-}
-
-func (ctx *Skinsystem) AuthenticationMiddleware(handler http.Handler) http.Handler {
-	return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) {
-		ctx.Logger.IncCounter("authentication.challenge", 1)
-		err := ctx.Auth.Check(req)
-		if err != nil {
-			if _, ok := err.(*auth.Unauthorized); ok {
-				ctx.Logger.IncCounter("authentication.failed", 1)
-				apiForbidden(resp, err.Error())
-			} else {
-				ctx.Logger.Error("Unknown error on validating api request: :err", wd.ErrParam(err))
-				apiServerError(resp)
-			}
-
-			return
-		}
-
-		ctx.Logger.IncCounter("authentication.success", 1)
-		handler.ServeHTTP(resp, req)
-	})
-}
-
-func (ctx *Skinsystem) deleteSkin(skin *model.Skin, resp http.ResponseWriter) {
-	err := ctx.SkinsRepo.RemoveByUserId(skin.UserId)
 	if err != nil {
-		ctx.Logger.Error("Cannot delete skin by error: :err", wd.ErrParam(err))
+		ctx.Emit("skinsystem:error", fmt.Errorf("cannot delete skin by error: %w", err))
 		apiServerError(resp)
 		return
 	}
 
-	ctx.Logger.IncCounter("api.skins.delete.success", 1)
 	resp.WriteHeader(http.StatusNoContent)
 }
 

http/skinsystem_test.go

@@ -3,8 +3,7 @@ package http
 import (
 	"bytes"
 	"encoding/base64"
-	"github.com/elyby/chrly/auth"
+	"errors"
-	testify "github.com/stretchr/testify/assert"
 	"image"
 	"image/png"
 	"io"
@@ -16,12 +15,12 @@ import (
 	"testing"
 	"time"
 
+	testify "github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/mock"
 	"github.com/stretchr/testify/suite"
 
 	"github.com/elyby/chrly/api/mojang"
 	"github.com/elyby/chrly/model"
-	"github.com/elyby/chrly/tests"
 )
 
 /***************
@@ -95,15 +94,6 @@ func (m *mojangTexturesProviderMock) GetForUsername(username string) (*mojang.Si
 	return result, args.Error(1)
 }
 
-type authCheckerMock struct {
-	mock.Mock
-}
-
-func (m *authCheckerMock) Check(req *http.Request) error {
-	args := m.Called(req)
-	return args.Error(0)
-}
-
 type skinsystemTestSuite struct {
 	suite.Suite
 
@@ -113,7 +103,7 @@ type skinsystemTestSuite struct {
 	CapesRepository        *capesRepositoryMock
 	MojangTexturesProvider *mojangTexturesProviderMock
 	Auth                   *authCheckerMock
-	Logger                 *tests.WdMock
+	Emitter                *emitterMock
 }
 
 /********************
@@ -125,14 +115,14 @@ func (suite *skinsystemTestSuite) SetupTest() {
 	suite.CapesRepository = &capesRepositoryMock{}
 	suite.MojangTexturesProvider = &mojangTexturesProviderMock{}
 	suite.Auth = &authCheckerMock{}
-	suite.Logger = &tests.WdMock{}
+	suite.Emitter = &emitterMock{}
 
 	suite.App = &Skinsystem{
 		SkinsRepo:              suite.SkinsRepository,
 		CapesRepo:              suite.CapesRepository,
 		MojangTexturesProvider: suite.MojangTexturesProvider,
-		Auth:                   suite.Auth,
+		Authenticator:          suite.Auth,
-		Logger:                 suite.Logger,
+		Emitter:                suite.Emitter,
 	}
 }
 
@@ -141,7 +131,7 @@ func (suite *skinsystemTestSuite) TearDownTest() {
 	suite.CapesRepository.AssertExpectations(suite.T())
 	suite.MojangTexturesProvider.AssertExpectations(suite.T())
 	suite.Auth.AssertExpectations(suite.T())
-	suite.Logger.AssertExpectations(suite.T())
+	suite.Emitter.AssertExpectations(suite.T())
 }
 
 func (suite *skinsystemTestSuite) RunSubTest(name string, subTest func()) {
@@ -215,7 +205,8 @@ var skinsTestsCases = []*skinsystemTestCase{
 func (suite *skinsystemTestSuite) TestSkin() {
 	for _, testCase := range skinsTestsCases {
 		suite.RunSubTest(testCase.Name, func() {
-			suite.Logger.On("IncCounter", "skins.request", int64(1)).Once()
+			suite.Emitter.On("Emit", "skinsystem:before_request", mock.Anything)
+			suite.Emitter.On("Emit", "skinsystem:after_request", mock.Anything, mock.Anything)
 			testCase.BeforeTest(suite)
 
 			req := httptest.NewRequest("GET", "http://chrly/skins/mock_username", nil)
@@ -228,7 +219,8 @@ func (suite *skinsystemTestSuite) TestSkin() {
 	}
 
 	suite.RunSubTest("Pass username with png extension", func() {
-		suite.Logger.On("IncCounter", "skins.request", int64(1)).Once()
+		suite.Emitter.On("Emit", "skinsystem:before_request", mock.Anything)
+		suite.Emitter.On("Emit", "skinsystem:after_request", mock.Anything, mock.Anything)
 		suite.SkinsRepository.On("FindByUsername", "mock_username").Return(createSkinModel("mock_username", false), nil)
 
 		req := httptest.NewRequest("GET", "http://chrly/skins/mock_username.png", nil)
@@ -245,7 +237,8 @@ func (suite *skinsystemTestSuite) TestSkin() {
 func (suite *skinsystemTestSuite) TestSkinGET() {
 	for _, testCase := range skinsTestsCases {
 		suite.RunSubTest(testCase.Name, func() {
-			suite.Logger.On("IncCounter", "skins.get_request", int64(1)).Once()
+			suite.Emitter.On("Emit", "skinsystem:before_request", mock.Anything)
+			suite.Emitter.On("Emit", "skinsystem:after_request", mock.Anything, mock.Anything)
 			testCase.BeforeTest(suite)
 
 			req := httptest.NewRequest("GET", "http://chrly/skins?name=mock_username", nil)
@@ -258,6 +251,9 @@ func (suite *skinsystemTestSuite) TestSkinGET() {
 	}
 
 	suite.RunSubTest("Do not pass name param", func() {
+		suite.Emitter.On("Emit", "skinsystem:before_request", mock.Anything)
+		suite.Emitter.On("Emit", "skinsystem:after_request", mock.Anything, mock.Anything)
+
 		req := httptest.NewRequest("GET", "http://chrly/skins", nil)
 		w := httptest.NewRecorder()
 
@@ -321,7 +317,8 @@ var capesTestsCases = []*skinsystemTestCase{
 func (suite *skinsystemTestSuite) TestCape() {
 	for _, testCase := range capesTestsCases {
 		suite.RunSubTest(testCase.Name, func() {
-			suite.Logger.On("IncCounter", "capes.request", int64(1)).Once()
+			suite.Emitter.On("Emit", "skinsystem:before_request", mock.Anything)
+			suite.Emitter.On("Emit", "skinsystem:after_request", mock.Anything, mock.Anything)
 			testCase.BeforeTest(suite)
 
 			req := httptest.NewRequest("GET", "http://chrly/cloaks/mock_username", nil)
@@ -334,7 +331,8 @@ func (suite *skinsystemTestSuite) TestCape() {
 	}
 
 	suite.RunSubTest("Pass username with png extension", func() {
-		suite.Logger.On("IncCounter", "capes.request", int64(1)).Once()
+		suite.Emitter.On("Emit", "skinsystem:before_request", mock.Anything)
+		suite.Emitter.On("Emit", "skinsystem:after_request", mock.Anything, mock.Anything)
 		suite.CapesRepository.On("FindByUsername", "mock_username").Return(createCapeModel(), nil)
 
 		req := httptest.NewRequest("GET", "http://chrly/cloaks/mock_username.png", nil)
@@ -353,7 +351,8 @@ func (suite *skinsystemTestSuite) TestCape() {
 func (suite *skinsystemTestSuite) TestCapeGET() {
 	for _, testCase := range capesTestsCases {
 		suite.RunSubTest(testCase.Name, func() {
-			suite.Logger.On("IncCounter", "capes.get_request", int64(1)).Once()
+			suite.Emitter.On("Emit", "skinsystem:before_request", mock.Anything)
+			suite.Emitter.On("Emit", "skinsystem:after_request", mock.Anything, mock.Anything)
 			testCase.BeforeTest(suite)
 
 			req := httptest.NewRequest("GET", "http://chrly/cloaks?name=mock_username", nil)
@@ -366,6 +365,9 @@ func (suite *skinsystemTestSuite) TestCapeGET() {
 	}
 
 	suite.RunSubTest("Do not pass name param", func() {
+		suite.Emitter.On("Emit", "skinsystem:before_request", mock.Anything)
+		suite.Emitter.On("Emit", "skinsystem:after_request", mock.Anything, mock.Anything)
+
 		req := httptest.NewRequest("GET", "http://chrly/cloaks", nil)
 		w := httptest.NewRecorder()
 
@@ -492,7 +494,8 @@ var texturesTestsCases = []*skinsystemTestCase{
 func (suite *skinsystemTestSuite) TestTextures() {
 	for _, testCase := range texturesTestsCases {
 		suite.RunSubTest(testCase.Name, func() {
-			suite.Logger.On("IncCounter", "textures.request", int64(1)).Once()
+			suite.Emitter.On("Emit", "skinsystem:before_request", mock.Anything)
+			suite.Emitter.On("Emit", "skinsystem:after_request", mock.Anything, mock.Anything)
 			testCase.BeforeTest(suite)
 
 			req := httptest.NewRequest("GET", "http://chrly/textures/mock_username", nil)
@@ -616,7 +619,8 @@ var signedTexturesTestsCases = []*signedTexturesTestCase{
 func (suite *skinsystemTestSuite) TestSignedTextures() {
 	for _, testCase := range signedTexturesTestsCases {
 		suite.RunSubTest(testCase.Name, func() {
-			suite.Logger.On("IncCounter", "signed_textures.request", int64(1)).Once()
+			suite.Emitter.On("Emit", "skinsystem:before_request", mock.Anything)
+			suite.Emitter.On("Emit", "skinsystem:after_request", mock.Anything, mock.Anything)
 			testCase.BeforeTest(suite)
 
 			var target string
@@ -769,16 +773,65 @@ var postSkinTestsCases = []*postSkinTestCase{
 			suite.Empty(body)
 		},
 	},
+	{
+		Name: "Handle an error when loading the data from the repository",
+		Form: bytes.NewBufferString(url.Values{
+			"identityId": {"1"},
+			"username":   {"mock_username"},
+			"uuid":       {"0f657aa8-bfbe-415d-b700-5750090d3af3"},
+			"skinId":     {"5"},
+			"is1_8":      {"1"},
+			"isSlim":     {"1"},
+			"url":        {"http://textures-server.com/skin.png"},
+		}.Encode()),
+		BeforeTest: func(suite *skinsystemTestSuite) {
+			suite.SkinsRepository.On("FindByUserId", 1).Return(createSkinModel("mock_username", false), nil)
+			err := errors.New("mock error")
+			suite.SkinsRepository.On("Save", mock.Anything).Return(err)
+			suite.Emitter.On("Emit", "skinsystem:error", mock.MatchedBy(func(cErr error) bool {
+				return cErr.Error() == "unable to save record to the repository: mock error" &&
+					errors.Is(cErr, err)
+			})).Once()
+		},
+		AfterTest: func(suite *skinsystemTestSuite, response *http.Response) {
+			suite.Equal(500, response.StatusCode)
+			body, _ := ioutil.ReadAll(response.Body)
+			suite.Empty(body)
+		},
+	},
+	{
+		Name: "Handle an error when saving the data into the repository",
+		Form: bytes.NewBufferString(url.Values{
+			"identityId": {"1"},
+			"username":   {"changed_username"},
+			"uuid":       {"0f657aa8-bfbe-415d-b700-5750090d3af3"},
+			"skinId":     {"5"},
+			"is1_8":      {"0"},
+			"isSlim":     {"0"},
+			"url":        {"http://example.com/skin.png"},
+		}.Encode()),
+		BeforeTest: func(suite *skinsystemTestSuite) {
+			err := errors.New("mock error")
+			suite.SkinsRepository.On("FindByUserId", 1).Return(nil, err)
+			suite.Emitter.On("Emit", "skinsystem:error", mock.MatchedBy(func(cErr error) bool {
+				return cErr.Error() == "error on requesting a skin from the repository: mock error" &&
+					errors.Is(cErr, err)
+			})).Once()
+		},
+		AfterTest: func(suite *skinsystemTestSuite, response *http.Response) {
+			suite.Equal(500, response.StatusCode)
+			body, _ := ioutil.ReadAll(response.Body)
+			suite.Empty(body)
+		},
+	},
 }
 
 func (suite *skinsystemTestSuite) TestPostSkin() {
 	for _, testCase := range postSkinTestsCases {
 		suite.RunSubTest(testCase.Name, func() {
-			suite.Logger.On("IncCounter", "authentication.challenge", int64(1)).Once()
+			suite.Emitter.On("Emit", "skinsystem:before_request", mock.Anything)
-			suite.Logger.On("IncCounter", "authentication.success", int64(1)).Once()
+			suite.Emitter.On("Emit", "skinsystem:after_request", mock.Anything, mock.Anything)
-			suite.Logger.On("IncCounter", "api.skins.post.request", int64(1)).Once()
+			suite.Auth.On("Authenticate", mock.Anything).Return(nil)
-			suite.Logger.On("IncCounter", "api.skins.post.success", int64(1)).Once()
-			suite.Auth.On("Check", mock.Anything).Return(nil)
 			testCase.BeforeTest(suite)
 
 			req := httptest.NewRequest("POST", "http://chrly/api/skins", testCase.Form)
@@ -792,11 +845,9 @@ func (suite *skinsystemTestSuite) TestPostSkin() {
 	}
 
 	suite.RunSubTest("Get errors about required fields", func() {
-		suite.Logger.On("IncCounter", "authentication.challenge", int64(1)).Once()
+		suite.Emitter.On("Emit", "skinsystem:before_request", mock.Anything)
-		suite.Logger.On("IncCounter", "authentication.success", int64(1)).Once()
+		suite.Emitter.On("Emit", "skinsystem:after_request", mock.Anything, mock.Anything)
-		suite.Logger.On("IncCounter", "api.skins.post.request", int64(1)).Once()
+		suite.Auth.On("Authenticate", mock.Anything).Return(nil)
-		suite.Logger.On("IncCounter", "api.skins.post.validation_failed", int64(1)).Once()
-		suite.Auth.On("Check", mock.Anything).Return(nil)
 
 		req := httptest.NewRequest("POST", "http://chrly/api/skins", bytes.NewBufferString(url.Values{
 			"mojangTextures": {"someBase64EncodedString"},
@@ -843,13 +894,13 @@ func (suite *skinsystemTestSuite) TestPostSkin() {
 	})
 
 	suite.RunSubTest("Send request without authorization", func() {
+		suite.Emitter.On("Emit", "skinsystem:before_request", mock.Anything)
+		suite.Emitter.On("Emit", "skinsystem:after_request", mock.Anything, mock.Anything)
 		req := httptest.NewRequest("POST", "http://chrly/api/skins", nil)
 		req.Header.Add("Authorization", "Bearer invalid.jwt.token")
 		w := httptest.NewRecorder()
 
-		suite.Auth.On("Check", mock.Anything).Return(&auth.Unauthorized{Reason: "Cannot parse passed JWT token"})
+		suite.Auth.On("Authenticate", mock.Anything).Return(errors.New("Cannot parse passed JWT token"))
-		suite.Logger.On("IncCounter", "authentication.challenge", int64(1)).Once()
-		suite.Logger.On("IncCounter", "authentication.failed", int64(1)).Once()
 
 		suite.App.CreateHandler().ServeHTTP(w, req)
 
@@ -863,11 +914,9 @@ func (suite *skinsystemTestSuite) TestPostSkin() {
 	})
 
 	suite.RunSubTest("Upload textures with skin as file", func() {
-		suite.Logger.On("IncCounter", "authentication.challenge", int64(1)).Once()
+		suite.Emitter.On("Emit", "skinsystem:before_request", mock.Anything)
-		suite.Logger.On("IncCounter", "authentication.success", int64(1)).Once()
+		suite.Emitter.On("Emit", "skinsystem:after_request", mock.Anything, mock.Anything)
-		suite.Logger.On("IncCounter", "api.skins.post.request", int64(1)).Once()
+		suite.Auth.On("Authenticate", mock.Anything).Return(nil)
-		suite.Logger.On("IncCounter", "api.skins.post.validation_failed", int64(1)).Once()
-		suite.Auth.On("Check", mock.Anything).Return(nil)
 
 		inputBody := &bytes.Buffer{}
 		writer := multipart.NewWriter(inputBody)
@@ -911,13 +960,11 @@ func (suite *skinsystemTestSuite) TestPostSkin() {
 
 func (suite *skinsystemTestSuite) TestDeleteByUserId() {
 	suite.RunSubTest("Delete skin by its identity id", func() {
-		suite.Auth.On("Check", mock.Anything).Return(nil)
+		suite.Emitter.On("Emit", "skinsystem:before_request", mock.Anything)
+		suite.Emitter.On("Emit", "skinsystem:after_request", mock.Anything, mock.Anything)
+		suite.Auth.On("Authenticate", mock.Anything).Return(nil)
 		suite.SkinsRepository.On("FindByUserId", 1).Return(createSkinModel("mock_username", false), nil)
 		suite.SkinsRepository.On("RemoveByUserId", 1).Once().Return(nil)
-		suite.Logger.On("IncCounter", "authentication.challenge", int64(1)).Once()
-		suite.Logger.On("IncCounter", "authentication.success", int64(1)).Once()
-		suite.Logger.On("IncCounter", "api.skins.delete.request", int64(1)).Once()
-		suite.Logger.On("IncCounter", "api.skins.delete.success", int64(1)).Once()
 
 		req := httptest.NewRequest("DELETE", "http://chrly/api/skins/id:1", nil)
 		w := httptest.NewRecorder()
@@ -932,12 +979,10 @@ func (suite *skinsystemTestSuite) TestDeleteByUserId() {
 	})
 
 	suite.RunSubTest("Try to remove not exists identity id", func() {
-		suite.Auth.On("Check", mock.Anything).Return(nil)
+		suite.Emitter.On("Emit", "skinsystem:before_request", mock.Anything)
+		suite.Emitter.On("Emit", "skinsystem:after_request", mock.Anything, mock.Anything)
+		suite.Auth.On("Authenticate", mock.Anything).Return(nil)
 		suite.SkinsRepository.On("FindByUserId", 1).Return(nil, &SkinNotFoundError{Who: "unknown"})
-		suite.Logger.On("IncCounter", "authentication.challenge", int64(1)).Once()
-		suite.Logger.On("IncCounter", "authentication.success", int64(1)).Once()
-		suite.Logger.On("IncCounter", "api.skins.delete.request", int64(1)).Once()
-		suite.Logger.On("IncCounter", "api.skins.delete.not_found", int64(1)).Once()
 
 		req := httptest.NewRequest("DELETE", "http://chrly/api/skins/id:1", nil)
 		w := httptest.NewRecorder()
@@ -949,7 +994,7 @@ func (suite *skinsystemTestSuite) TestDeleteByUserId() {
 		suite.Equal(404, resp.StatusCode)
 		body, _ := ioutil.ReadAll(resp.Body)
 		suite.JSONEq(`[
-			"Cannot find record for requested user id"
+			"Cannot find record for the requested identifier"
 		]`, string(body))
 	})
 }
@@ -960,13 +1005,11 @@ func (suite *skinsystemTestSuite) TestDeleteByUserId() {
 
 func (suite *skinsystemTestSuite) TestDeleteByUsername() {
 	suite.RunSubTest("Delete skin by its identity username", func() {
-		suite.Auth.On("Check", mock.Anything).Return(nil)
+		suite.Emitter.On("Emit", "skinsystem:before_request", mock.Anything)
+		suite.Emitter.On("Emit", "skinsystem:after_request", mock.Anything, mock.Anything)
+		suite.Auth.On("Authenticate", mock.Anything).Return(nil)
 		suite.SkinsRepository.On("FindByUsername", "mock_username").Return(createSkinModel("mock_username", false), nil)
 		suite.SkinsRepository.On("RemoveByUserId", 1).Once().Return(nil)
-		suite.Logger.On("IncCounter", "authentication.challenge", int64(1)).Once()
-		suite.Logger.On("IncCounter", "authentication.success", int64(1)).Once()
-		suite.Logger.On("IncCounter", "api.skins.delete.request", int64(1)).Once()
-		suite.Logger.On("IncCounter", "api.skins.delete.success", int64(1)).Once()
 
 		req := httptest.NewRequest("DELETE", "http://chrly/api/skins/mock_username", nil)
 		w := httptest.NewRecorder()
@@ -981,12 +1024,10 @@ func (suite *skinsystemTestSuite) TestDeleteByUsername() {
 	})
 
 	suite.RunSubTest("Try to remove not exists identity username", func() {
-		suite.Auth.On("Check", mock.Anything).Return(nil)
+		suite.Emitter.On("Emit", "skinsystem:before_request", mock.Anything)
+		suite.Emitter.On("Emit", "skinsystem:after_request", mock.Anything, mock.Anything)
+		suite.Auth.On("Authenticate", mock.Anything).Return(nil)
 		suite.SkinsRepository.On("FindByUsername", "mock_username").Return(nil, &SkinNotFoundError{Who: "mock_username"})
-		suite.Logger.On("IncCounter", "authentication.challenge", int64(1)).Once()
-		suite.Logger.On("IncCounter", "authentication.success", int64(1)).Once()
-		suite.Logger.On("IncCounter", "api.skins.delete.request", int64(1)).Once()
-		suite.Logger.On("IncCounter", "api.skins.delete.not_found", int64(1)).Once()
 
 		req := httptest.NewRequest("DELETE", "http://chrly/api/skins/mock_username", nil)
 		w := httptest.NewRecorder()
@@ -998,7 +1039,7 @@ func (suite *skinsystemTestSuite) TestDeleteByUsername() {
 		suite.Equal(404, resp.StatusCode)
 		body, _ := ioutil.ReadAll(resp.Body)
 		suite.JSONEq(`[
-			"Cannot find record for requested username"
+			"Cannot find record for the requested identifier"
 		]`, string(body))
 	})
 }

http/uuids_worker.go

@@ -2,13 +2,9 @@ package http
 
 import (
 	"encoding/json"
-	"fmt"
-	"net"
 	"net/http"
-	"time"
 
 	"github.com/gorilla/mux"
-	"github.com/mono83/slf/wd"
 
 	"github.com/elyby/chrly/api/mojang"
 	"github.com/elyby/chrly/mojangtextures"
@@ -19,31 +15,11 @@ type UuidsProvider interface {
 }
 
 type UUIDsWorker struct {
-	ListenSpec string
+	Emitter
-
 	UUIDsProvider mojangtextures.UUIDsProvider
-	Logger        wd.Watchdog
 }
 
-func (ctx *UUIDsWorker) Run() error {
+func (ctx *UUIDsWorker) CreateHandler() *mux.Router {
-	ctx.Logger.Info(fmt.Sprintf("Starting the worker, HTTP on: %s\n", ctx.ListenSpec))
-
-	listener, err := net.Listen("tcp", ctx.ListenSpec)
-	if err != nil {
-		return err
-	}
-
-	server := &http.Server{
-		ReadTimeout:    60 * time.Second,
-		WriteTimeout:   60 * time.Second, // TODO: should I adjust this values?
-		MaxHeaderBytes: 1 << 16,
-		Handler:        ctx.CreateHandler(),
-	}
-
-	return server.Serve(listener)
-}
-
-func (ctx *UUIDsWorker) CreateHandler() http.Handler {
 	router := mux.NewRouter().StrictSlash(true)
 	router.NotFoundHandler = http.HandlerFunc(NotFound)
 
@@ -56,13 +32,12 @@ func (ctx *UUIDsWorker) GetUUID(response http.ResponseWriter, request *http.Requ
 	username := parseUsername(mux.Vars(request)["username"])
 	profile, err := ctx.UUIDsProvider.GetUuid(username)
 	if err != nil {
+		ctx.Emit("uuids_provider:error", err) // TODO: do I need emitter here?
 		if _, ok := err.(*mojang.TooManyRequestsError); ok {
-			ctx.Logger.Warning("Got 429 Too Many Requests")
 			response.WriteHeader(http.StatusTooManyRequests)
 			return
 		}
 
-		ctx.Logger.Warning("Got non success response: :err", wd.ErrParam(err))
 		response.Header().Set("Content-Type", "application/json")
 		response.WriteHeader(http.StatusInternalServerError)
 		result, _ := json.Marshal(map[string]interface{}{

http/uuids_worker_test.go

@@ -2,14 +2,15 @@ package http
 
 import (
 	"errors"
-	"github.com/elyby/chrly/api/mojang"
-	"github.com/elyby/chrly/tests"
-	"github.com/stretchr/testify/mock"
-	"github.com/stretchr/testify/suite"
 	"io/ioutil"
 	"net/http"
 	"net/http/httptest"
 	"testing"
+
+	"github.com/stretchr/testify/mock"
+	"github.com/stretchr/testify/suite"
+
+	"github.com/elyby/chrly/api/mojang"
 )
 
 /***************
@@ -36,7 +37,7 @@ type uuidsWorkerTestSuite struct {
 	App *UUIDsWorker
 
 	UuidsProvider *uuidsProviderMock
-	Logger        *tests.WdMock
+	Emitter       *emitterMock
 }
 
 /********************
@@ -45,17 +46,17 @@ type uuidsWorkerTestSuite struct {
 
 func (suite *uuidsWorkerTestSuite) SetupTest() {
 	suite.UuidsProvider = &uuidsProviderMock{}
-	suite.Logger = &tests.WdMock{}
+	suite.Emitter = &emitterMock{}
 
 	suite.App = &UUIDsWorker{
 		UUIDsProvider: suite.UuidsProvider,
-		Logger:        suite.Logger,
+		Emitter:       suite.Emitter,
 	}
 }
 
 func (suite *uuidsWorkerTestSuite) TearDownTest() {
 	suite.UuidsProvider.AssertExpectations(suite.T())
-	suite.Logger.AssertExpectations(suite.T())
+	suite.Emitter.AssertExpectations(suite.T())
 }
 
 func (suite *uuidsWorkerTestSuite) RunSubTest(name string, subTest func()) {
@@ -115,8 +116,9 @@ var getUuidTestsCases = []*uuidsWorkerTestCase{
 	{
 		Name: "Receive error from UUIDs provider",
 		BeforeTest: func(suite *uuidsWorkerTestSuite) {
-			suite.UuidsProvider.On("GetUuid", "mock_username").Return(nil, errors.New("this is an error"))
+			err := errors.New("this is an error")
-			suite.Logger.On("Warning", "Got non success response: :err", mock.Anything).Times(1)
+			suite.UuidsProvider.On("GetUuid", "mock_username").Return(nil, err)
+			suite.Emitter.On("Emit", "uuids_provider:error", err).Times(1)
 		},
 		AfterTest: func(suite *uuidsWorkerTestSuite, response *http.Response) {
 			suite.Equal(500, response.StatusCode)
@@ -130,8 +132,9 @@ var getUuidTestsCases = []*uuidsWorkerTestCase{
 	{
 		Name: "Receive Too Many Requests from UUIDs provider",
 		BeforeTest: func(suite *uuidsWorkerTestSuite) {
-			suite.UuidsProvider.On("GetUuid", "mock_username").Return(nil, &mojang.TooManyRequestsError{})
+			err := &mojang.TooManyRequestsError{}
-			suite.Logger.On("Warning", "Got 429 Too Many Requests").Times(1)
+			suite.UuidsProvider.On("GetUuid", "mock_username").Return(nil, err)
+			suite.Emitter.On("Emit", "uuids_provider:error", err).Times(1)
 		},
 		AfterTest: func(suite *uuidsWorkerTestSuite, response *http.Response) {
 			suite.Equal(429, response.StatusCode)

mojangtextures/batch_uuids_provider.go

@@ -5,8 +5,6 @@ import (
 	"sync"
 	"time"
 
-	"github.com/mono83/slf/wd"
-
 	"github.com/elyby/chrly/api/mojang"
 )
 
@@ -68,9 +66,10 @@ var forever = func() bool {
 }
 
 type BatchUuidsProvider struct {
+	Emitter
+
 	IterationDelay time.Duration
 	IterationSize  int
-	Logger         wd.Watchdog
 
 	onFirstCall sync.Once
 	queue       jobsQueue
@@ -84,7 +83,7 @@ func (ctx *BatchUuidsProvider) GetUuid(username string) (*mojang.ProfileInfo, er
 
 	resultChan := make(chan *jobResult)
 	ctx.queue.Enqueue(&jobItem{username, resultChan})
-	ctx.Logger.IncCounter("mojang_textures.usernames.queued", 1)
+	ctx.Emit("mojang_textures:batch_uuids_provider:queued", username)
 
 	result := <-resultChan
 
@@ -95,10 +94,9 @@ func (ctx *BatchUuidsProvider) startQueue() {
 	go func() {
 		time.Sleep(ctx.IterationDelay)
 		for forever() {
-			start := time.Now()
+			ctx.Emit("mojang_textures:batch_uuids_provider:before_round")
 			ctx.queueRound()
-			elapsed := time.Since(start)
+			ctx.Emit("mojang_textures:batch_uuids_provider:after_round")
-			ctx.Logger.RecordTimer("mojang_textures.usernames.round_time", elapsed)
 			time.Sleep(ctx.IterationDelay)
 		}
 	}()
@@ -107,17 +105,17 @@ func (ctx *BatchUuidsProvider) startQueue() {
 func (ctx *BatchUuidsProvider) queueRound() {
 	queueSize := ctx.queue.Size()
 	jobs := ctx.queue.Dequeue(ctx.IterationSize)
-	ctx.Logger.UpdateGauge("mojang_textures.usernames.queue_size", int64(queueSize-len(jobs)))
-	ctx.Logger.UpdateGauge("mojang_textures.usernames.iteration_size", int64(len(jobs)))
-	if len(jobs) == 0 {
-		return
-	}
 
 	var usernames []string
 	for _, job := range jobs {
 		usernames = append(usernames, job.username)
 	}
 
+	ctx.Emit("mojang_textures:batch_uuids_provider:round", usernames, queueSize - len(jobs))
+	if len(usernames) == 0 {
+		return
+	}
+
 	profiles, err := usernamesToUuids(usernames)
 	for _, job := range jobs {
 		go func(job *jobItem) {

mojangtextures/batch_uuids_provider_test.go

@@ -11,7 +11,6 @@ import (
 	"github.com/stretchr/testify/suite"
 
 	"github.com/elyby/chrly/api/mojang"
-	mocks "github.com/elyby/chrly/tests"
 )
 
 func TestJobsQueue(t *testing.T) {
@@ -85,7 +84,7 @@ type batchUuidsProviderTestSuite struct {
 	Provider     *BatchUuidsProvider
 	GetUuidAsync func(username string) chan *batchUuidsProviderGetUuidResult
 
-	Logger    *mocks.WdMock
+	Emitter   *mockEmitter
 	MojangApi *mojangUsernamesToUuidsRequestMock
 
 	Iterate     func()
@@ -94,10 +93,10 @@ type batchUuidsProviderTestSuite struct {
 }
 
 func (suite *batchUuidsProviderTestSuite) SetupTest() {
-	suite.Logger = &mocks.WdMock{}
+	suite.Emitter = &mockEmitter{}
 
 	suite.Provider = &BatchUuidsProvider{
-		Logger:         suite.Logger,
+		Emitter:        suite.Emitter,
 		IterationDelay: 0,
 		IterationSize:  10,
 	}
@@ -120,7 +119,10 @@ func (suite *batchUuidsProviderTestSuite) SetupTest() {
 		// This dirty hack ensures, that the username will be queued before we return control to the caller.
 		// It's needed to keep expected calls order and prevent cases when iteration happens before all usernames
 		// will be queued.
-		suite.Logger.On("IncCounter", "mojang_textures.usernames.queued", int64(1)).Once().Run(func(args mock.Arguments) {
+		suite.Emitter.On("Emit",
+			"mojang_textures:batch_uuids_provider:queued",
+			username,
+		).Once().Run(func(args mock.Arguments) {
 			s <- true
 		})
 
@@ -144,8 +146,8 @@ func (suite *batchUuidsProviderTestSuite) SetupTest() {
 
 func (suite *batchUuidsProviderTestSuite) TearDownTest() {
 	suite.done()
+	suite.Emitter.AssertExpectations(suite.T())
 	suite.MojangApi.AssertExpectations(suite.T())
-	suite.Logger.AssertExpectations(suite.T())
 }
 
 func TestBatchUuidsProvider(t *testing.T) {
@@ -155,9 +157,9 @@ func TestBatchUuidsProvider(t *testing.T) {
 func (suite *batchUuidsProviderTestSuite) TestGetUuidForOneUsername() {
 	expectedResult := &mojang.ProfileInfo{Id: "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", Name: "username"}
 
-	suite.Logger.On("UpdateGauge", "mojang_textures.usernames.iteration_size", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:batch_uuids_provider:before_round").Once()
-	suite.Logger.On("UpdateGauge", "mojang_textures.usernames.queue_size", int64(0)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:batch_uuids_provider:round", []string{"username"}, 0).Once()
-	suite.Logger.On("RecordTimer", "mojang_textures.usernames.round_time", mock.Anything).Once()
+	suite.Emitter.On("Emit", "mojang_textures:batch_uuids_provider:after_round").Once()
 
 	suite.MojangApi.On("UsernamesToUuids", []string{"username"}).Once().Return([]*mojang.ProfileInfo{expectedResult}, nil)
 
@@ -174,9 +176,9 @@ func (suite *batchUuidsProviderTestSuite) TestGetUuidForTwoUsernames() {
 	expectedResult1 := &mojang.ProfileInfo{Id: "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", Name: "username1"}
 	expectedResult2 := &mojang.ProfileInfo{Id: "bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb", Name: "username2"}
 
-	suite.Logger.On("UpdateGauge", "mojang_textures.usernames.iteration_size", int64(2)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:batch_uuids_provider:before_round").Once()
-	suite.Logger.On("UpdateGauge", "mojang_textures.usernames.queue_size", int64(0)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:batch_uuids_provider:round", []string{"username1", "username2"}, 0).Once()
-	suite.Logger.On("RecordTimer", "mojang_textures.usernames.round_time", mock.Anything).Once()
+	suite.Emitter.On("Emit", "mojang_textures:batch_uuids_provider:after_round").Once()
 
 	suite.MojangApi.On("UsernamesToUuids", []string{"username1", "username2"}).Once().Return([]*mojang.ProfileInfo{
 		expectedResult1,
@@ -203,18 +205,13 @@ func (suite *batchUuidsProviderTestSuite) TestGetUuidForMoreThan10Usernames() {
 		usernames[i] = randStr(8)
 	}
 
-	suite.Logger.On("UpdateGauge", "mojang_textures.usernames.iteration_size", int64(10)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:batch_uuids_provider:before_round").Twice()
-	suite.Logger.On("UpdateGauge", "mojang_textures.usernames.iteration_size", int64(2)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:batch_uuids_provider:round", usernames[0:10], 2).Once()
-	suite.Logger.On("UpdateGauge", "mojang_textures.usernames.queue_size", int64(2)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:batch_uuids_provider:round", usernames[10:12], 0).Once()
-	suite.Logger.On("UpdateGauge", "mojang_textures.usernames.queue_size", int64(0)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:batch_uuids_provider:after_round").Twice()
-	suite.Logger.On("RecordTimer", "mojang_textures.usernames.round_time", mock.Anything).Twice()
 
-	suite.MojangApi.On("UsernamesToUuids", mock.MatchedBy(func(usernames []string) bool {
+	suite.MojangApi.On("UsernamesToUuids", usernames[0:10]).Once().Return([]*mojang.ProfileInfo{}, nil)
-		return len(usernames) == 10
+	suite.MojangApi.On("UsernamesToUuids", usernames[10:12]).Once().Return([]*mojang.ProfileInfo{}, nil)
-	})).Once().Return([]*mojang.ProfileInfo{}, nil)
-	suite.MojangApi.On("UsernamesToUuids", mock.MatchedBy(func(usernames []string) bool {
-		return len(usernames) == 2
-	})).Once().Return([]*mojang.ProfileInfo{}, nil)
 
 	channels := make([]chan *batchUuidsProviderGetUuidResult, len(usernames))
 	for i, username := range usernames {
@@ -230,10 +227,11 @@ func (suite *batchUuidsProviderTestSuite) TestGetUuidForMoreThan10Usernames() {
 }
 
 func (suite *batchUuidsProviderTestSuite) TestDoNothingWhenNoTasks() {
-	suite.Logger.On("UpdateGauge", "mojang_textures.usernames.iteration_size", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:batch_uuids_provider:before_round").Times(3)
-	suite.Logger.On("UpdateGauge", "mojang_textures.usernames.iteration_size", int64(0)).Twice()
+	suite.Emitter.On("Emit", "mojang_textures:batch_uuids_provider:round", []string{"username"}, 0).Once()
-	suite.Logger.On("UpdateGauge", "mojang_textures.usernames.queue_size", int64(0)).Times(3)
+	var nilStringSlice []string
-	suite.Logger.On("RecordTimer", "mojang_textures.usernames.round_time", mock.Anything)
+	suite.Emitter.On("Emit", "mojang_textures:batch_uuids_provider:round", nilStringSlice, 0).Twice()
+	suite.Emitter.On("Emit", "mojang_textures:batch_uuids_provider:after_round").Times(3)
 
 	suite.MojangApi.On("UsernamesToUuids", []string{"username"}).Once().Return([]*mojang.ProfileInfo{}, nil)
 
@@ -254,9 +252,9 @@ func (suite *batchUuidsProviderTestSuite) TestDoNothingWhenNoTasks() {
 func (suite *batchUuidsProviderTestSuite) TestGetUuidForTwoUsernamesWithAnError() {
 	expectedError := &mojang.TooManyRequestsError{}
 
-	suite.Logger.On("UpdateGauge", "mojang_textures.usernames.iteration_size", int64(2)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:batch_uuids_provider:before_round").Once()
-	suite.Logger.On("UpdateGauge", "mojang_textures.usernames.queue_size", int64(0)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:batch_uuids_provider:round", []string{"username1", "username2"}, 0).Once()
-	suite.Logger.On("RecordTimer", "mojang_textures.usernames.round_time", mock.Anything).Once()
+	suite.Emitter.On("Emit", "mojang_textures:batch_uuids_provider:after_round").Once()
 
 	suite.MojangApi.On("UsernamesToUuids", []string{"username1", "username2"}).Once().Return(nil, expectedError)
 

mojangtextures/mojang_api_textures_provider.go

@@ -1,25 +1,19 @@
 package mojangtextures
 
 import (
-	"time"
-
-	"github.com/mono83/slf/wd"
-
 	"github.com/elyby/chrly/api/mojang"
 )
 
 var uuidToTextures = mojang.UuidToTextures
 
 type MojangApiTexturesProvider struct {
-	Logger wd.Watchdog
+	Emitter
 }
 
 func (ctx *MojangApiTexturesProvider) GetTextures(uuid string) (*mojang.SignedTexturesResponse, error) {
-	ctx.Logger.IncCounter("mojang_textures.textures.request", 1)
+	ctx.Emit("mojang_textures:mojang_api_textures_provider:before_request", uuid)
-
-	start := time.Now()
 	result, err := uuidToTextures(uuid, true)
-	ctx.Logger.RecordTimer("mojang_textures.textures.request_time", time.Since(start))
+	ctx.Emit("mojang_textures:mojang_api_textures_provider:after_request", result, err)
 
 	return result, err
 }

mojangtextures/mojang_api_textures_provider_test.go

@@ -7,7 +7,6 @@ import (
 	"github.com/stretchr/testify/suite"
 
 	"github.com/elyby/chrly/api/mojang"
-	mocks "github.com/elyby/chrly/tests"
 )
 
 type mojangUuidToTexturesRequestMock struct {
@@ -28,16 +27,16 @@ type mojangApiTexturesProviderTestSuite struct {
 	suite.Suite
 
 	Provider  *MojangApiTexturesProvider
-	Logger    *mocks.WdMock
+	Emitter   *mockEmitter
 	MojangApi *mojangUuidToTexturesRequestMock
 }
 
 func (suite *mojangApiTexturesProviderTestSuite) SetupTest() {
-	suite.Logger = &mocks.WdMock{}
+	suite.Emitter = &mockEmitter{}
 	suite.MojangApi = &mojangUuidToTexturesRequestMock{}
 
 	suite.Provider = &MojangApiTexturesProvider{
-		Logger: suite.Logger,
+		Emitter: suite.Emitter,
 	}
 
 	uuidToTextures = suite.MojangApi.UuidToTextures
@@ -45,7 +44,7 @@ func (suite *mojangApiTexturesProviderTestSuite) SetupTest() {
 
 func (suite *mojangApiTexturesProviderTestSuite) TearDownTest() {
 	suite.MojangApi.AssertExpectations(suite.T())
-	suite.Logger.AssertExpectations(suite.T())
+	suite.Emitter.AssertExpectations(suite.T())
 }
 
 func TestMojangApiTexturesProvider(t *testing.T) {
@@ -59,8 +58,15 @@ func (suite *mojangApiTexturesProviderTestSuite) TestGetTextures() {
 	}
 	suite.MojangApi.On("UuidToTextures", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", true).Once().Return(expectedResult, nil)
 
-	suite.Logger.On("IncCounter", "mojang_textures.textures.request", int64(1)).Once()
+	suite.Emitter.On("Emit",
-	suite.Logger.On("RecordTimer", "mojang_textures.textures.request_time", mock.Anything).Once()
+		"mojang_textures:mojang_api_textures_provider:before_request",
+		"aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa",
+	).Once()
+	suite.Emitter.On("Emit",
+		"mojang_textures:mojang_api_textures_provider:after_request",
+		expectedResult,
+		nil,
+	).Once()
 
 	result, err := suite.Provider.GetTextures("aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa")
 
@@ -69,11 +75,19 @@ func (suite *mojangApiTexturesProviderTestSuite) TestGetTextures() {
 }
 
 func (suite *mojangApiTexturesProviderTestSuite) TestGetTexturesWithError() {
+	var expectedResponse *mojang.SignedTexturesResponse
 	expectedError := &mojang.TooManyRequestsError{}
 	suite.MojangApi.On("UuidToTextures", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", true).Once().Return(nil, expectedError)
 
-	suite.Logger.On("IncCounter", "mojang_textures.textures.request", int64(1)).Once()
+	suite.Emitter.On("Emit",
-	suite.Logger.On("RecordTimer", "mojang_textures.textures.request_time", mock.Anything).Once()
+		"mojang_textures:mojang_api_textures_provider:before_request",
+		"aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa",
+	).Once()
+	suite.Emitter.On("Emit",
+		"mojang_textures:mojang_api_textures_provider:after_request",
+		expectedResponse,
+		expectedError,
+	).Once()
 
 	result, err := suite.Provider.GetTextures("aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa")
 

mojangtextures/mojang_textures.go

@@ -2,15 +2,9 @@ package mojangtextures
 
 import (
 	"errors"
-	"net"
-	"net/url"
 	"regexp"
 	"strings"
 	"sync"
-	"syscall"
-	"time"
-
-	"github.com/mono83/slf/wd"
 
 	"github.com/elyby/chrly/api/mojang"
 )
@@ -77,11 +71,15 @@ type TexturesProvider interface {
 	GetTextures(uuid string) (*mojang.SignedTexturesResponse, error)
 }
 
+type Emitter interface {
+	Emit(name string, args ...interface{})
+}
+
 type Provider struct {
+	Emitter
 	UUIDsProvider
 	TexturesProvider
 	Storage
-	Logger wd.Watchdog
 
 	onFirstCall sync.Once
 	*broadcaster
@@ -93,24 +91,20 @@ func (ctx *Provider) GetForUsername(username string) (*mojang.SignedTexturesResp
 	})
 
 	if !allowedUsernamesRegex.MatchString(username) {
-		ctx.Logger.IncCounter("mojang_textures.invalid_username", 1)
 		return nil, errors.New("invalid username")
 	}
 
 	username = strings.ToLower(username)
-	ctx.Logger.IncCounter("mojang_textures.request", 1)
+	ctx.Emit("mojang_textures:call", username)
 
-	uuid, err := ctx.Storage.GetUuid(username)
+	uuid, err := ctx.getUuidFromCache(username)
 	if err == nil && uuid == "" {
-		ctx.Logger.IncCounter("mojang_textures.usernames.cache_hit_nil", 1)
 		return nil, nil
 	}
 
 	if uuid != "" {
-		ctx.Logger.IncCounter("mojang_textures.usernames.cache_hit", 1)
+		textures, err := ctx.getTexturesFromCache(uuid)
-		textures, err := ctx.Storage.GetTextures(uuid)
 		if err == nil {
-			ctx.Logger.IncCounter("mojang_textures.textures.cache_hit", 1)
 			return textures, nil
 		}
 	}
@@ -120,7 +114,7 @@ func (ctx *Provider) GetForUsername(username string) (*mojang.SignedTexturesResp
 	if isFirstListener {
 		go ctx.getResultAndBroadcast(username, uuid)
 	} else {
-		ctx.Logger.IncCounter("mojang_textures.already_scheduled", 1)
+		ctx.Emit("mojang_textures:already_processing", username)
 	}
 
 	result := <-resultChan
@@ -129,19 +123,17 @@ func (ctx *Provider) GetForUsername(username string) (*mojang.SignedTexturesResp
 }
 
 func (ctx *Provider) getResultAndBroadcast(username string, uuid string) {
-	start := time.Now()
+	ctx.Emit("mojang_textures:before_result", username, uuid)
-
 	result := ctx.getResult(username, uuid)
-	ctx.broadcaster.BroadcastAndRemove(username, result)
+	ctx.Emit("mojang_textures:after_result", username, result.textures, result.error)
 
-	ctx.Logger.RecordTimer("mojang_textures.result_time", time.Since(start))
+	ctx.broadcaster.BroadcastAndRemove(username, result)
 }
 
 func (ctx *Provider) getResult(username string, uuid string) *broadcastResult {
 	if uuid == "" {
-		profile, err := ctx.UUIDsProvider.GetUuid(username)
+		profile, err := ctx.getUuid(username)
 		if err != nil {
-			ctx.handleMojangApiResponseError(err, "usernames")
 			return &broadcastResult{nil, err}
 		}
 
@@ -153,16 +145,12 @@ func (ctx *Provider) getResult(username string, uuid string) *broadcastResult {
 		_ = ctx.Storage.StoreUuid(username, uuid)
 
 		if uuid == "" {
-			ctx.Logger.IncCounter("mojang_textures.usernames.uuid_miss", 1)
 			return &broadcastResult{nil, nil}
 		}
-
-		ctx.Logger.IncCounter("mojang_textures.usernames.uuid_hit", 1)
 	}
 
-	textures, err := ctx.TexturesProvider.GetTextures(uuid)
+	textures, err := ctx.getTextures(uuid)
 	if err != nil {
-		ctx.handleMojangApiResponseError(err, "textures")
 		return &broadcastResult{nil, err}
 	}
 
@@ -170,56 +158,37 @@ func (ctx *Provider) getResult(username string, uuid string) *broadcastResult {
 	// therefore store the result even if textures is nil to prevent 429 error
 	ctx.Storage.StoreTextures(uuid, textures)
 
-	if textures != nil {
-		ctx.Logger.IncCounter("mojang_textures.usernames.textures_hit", 1)
-	} else {
-		ctx.Logger.IncCounter("mojang_textures.usernames.textures_miss", 1)
-	}
-
 	return &broadcastResult{textures, nil}
 }
 
-func (ctx *Provider) handleMojangApiResponseError(err error, threadName string) {
+func (ctx *Provider) getUuidFromCache(username string) (string, error) {
-	errParam := wd.ErrParam(err)
+	ctx.Emit("mojang_textures:usernames:before_cache", username)
-	threadParam := wd.NameParam(threadName)
+	uuid, err := ctx.Storage.GetUuid(username)
+	ctx.Emit("mojang_textures:usernames:after_cache", username, uuid, err)
 
-	ctx.Logger.Debug(":name: Got response error :err", threadParam, errParam)
+	return uuid, err
-
+}
-	switch err.(type) {
+
-	case mojang.ResponseError:
+func (ctx *Provider) getTexturesFromCache(uuid string) (*mojang.SignedTexturesResponse, error) {
-		if _, ok := err.(*mojang.BadRequestError); ok {
+	ctx.Emit("mojang_textures:textures:before_cache", uuid)
-			ctx.Logger.Warning(":name: Got 400 Bad Request :err", threadParam, errParam)
+	textures, err := ctx.Storage.GetTextures(uuid)
-			return
+	ctx.Emit("mojang_textures:textures:after_cache", uuid, textures, err)
-		}
+
-
+	return textures, err
-		if _, ok := err.(*mojang.ForbiddenError); ok {
+}
-			ctx.Logger.Warning(":name: Got 403 Forbidden :err", threadParam, errParam)
+
-			return
+func (ctx *Provider) getUuid(username string) (*mojang.ProfileInfo, error) {
-		}
+	ctx.Emit("mojang_textures:usernames:before_call", username)
-
+	profile, err := ctx.UUIDsProvider.GetUuid(username)
-		if _, ok := err.(*mojang.TooManyRequestsError); ok {
+	ctx.Emit("mojang_textures:usernames:after_call", username, profile, err)
-			ctx.Logger.Warning(":name: Got 429 Too Many Requests :err", threadParam, errParam)
+
-			return
+	return profile, err
-		}
+}
-
+
-		return
+func (ctx *Provider) getTextures(uuid string) (*mojang.SignedTexturesResponse, error) {
-	case net.Error:
+	ctx.Emit("mojang_textures:textures:before_call", uuid)
-		if err.(net.Error).Timeout() {
+	textures, err := ctx.TexturesProvider.GetTextures(uuid)
-			return
+	ctx.Emit("mojang_textures:textures:after_call", uuid, textures, err)
-		}
+
-
+	return textures, err
-		if _, ok := err.(*url.Error); ok {
-			return
-		}
-
-		if opErr, ok := err.(*net.OpError); ok && (opErr.Op == "dial" || opErr.Op == "read") {
-			return
-		}
-
-		if err == syscall.ECONNREFUSED {
-			return
-		}
-	}
-
-	ctx.Logger.Emergency(":name: Unknown Mojang response error: :err", threadParam, errParam)
 }

mojangtextures/mojang_textures_test.go

@@ -2,10 +2,7 @@ package mojangtextures
 
 import (
 	"errors"
-	"net"
-	"net/url"
 	"sync"
-	"syscall"
 	"testing"
 	"time"
 
@@ -14,7 +11,6 @@ import (
 	"github.com/stretchr/testify/suite"
 
 	"github.com/elyby/chrly/api/mojang"
-	mocks "github.com/elyby/chrly/tests"
 )
 
 func TestBroadcaster(t *testing.T) {
@@ -86,6 +82,14 @@ func TestBroadcaster(t *testing.T) {
 	})
 }
 
+type mockEmitter struct {
+	mock.Mock
+}
+
+func (e *mockEmitter) Emit(name string, args ...interface{}) {
+	e.Called(append([]interface{}{name}, args...)...)
+}
+
 type mockUuidsProvider struct {
 	mock.Mock
 }
@@ -145,32 +149,31 @@ func (m *mockStorage) StoreTextures(uuid string, textures *mojang.SignedTextures
 type providerTestSuite struct {
 	suite.Suite
 	Provider         *Provider
+	Emitter          *mockEmitter
 	UuidsProvider    *mockUuidsProvider
 	TexturesProvider *mockTexturesProvider
 	Storage          *mockStorage
-	Logger           *mocks.WdMock
 }
 
 func (suite *providerTestSuite) SetupTest() {
+	suite.Emitter = &mockEmitter{}
 	suite.UuidsProvider = &mockUuidsProvider{}
 	suite.TexturesProvider = &mockTexturesProvider{}
 	suite.Storage = &mockStorage{}
-	suite.Logger = &mocks.WdMock{}
 
 	suite.Provider = &Provider{
+		Emitter:          suite.Emitter,
 		UUIDsProvider:    suite.UuidsProvider,
 		TexturesProvider: suite.TexturesProvider,
 		Storage:          suite.Storage,
-		Logger:           suite.Logger,
 	}
 }
 
 func (suite *providerTestSuite) TearDownTest() {
-	// time.Sleep(10 * time.Millisecond) // Add delay to let finish all goroutines before assert mocks calls
+	suite.Emitter.AssertExpectations(suite.T())
 	suite.UuidsProvider.AssertExpectations(suite.T())
 	suite.TexturesProvider.AssertExpectations(suite.T())
 	suite.Storage.AssertExpectations(suite.T())
-	suite.Logger.AssertExpectations(suite.T())
 }
 
 func TestProvider(t *testing.T) {
@@ -178,21 +181,24 @@ func TestProvider(t *testing.T) {
 }
 
 func (suite *providerTestSuite) TestGetForUsernameWithoutAnyCache() {
+	expectedProfile := &mojang.ProfileInfo{Id: "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", Name: "username"}
 	expectedResult := &mojang.SignedTexturesResponse{Id: "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", Name: "username"}
 
-	suite.Logger.On("IncCounter", "mojang_textures.request", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:call", "username").Once()
-	suite.Logger.On("IncCounter", "mojang_textures.usernames.uuid_hit", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:before_cache", "username").Once()
-	suite.Logger.On("IncCounter", "mojang_textures.usernames.textures_hit", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:after_cache", "username", "", &ValueNotFound{}).Once()
-	suite.Logger.On("RecordTimer", "mojang_textures.result_time", mock.Anything).Once()
+	suite.Emitter.On("Emit", "mojang_textures:before_result", "username", "").Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:before_call", "username").Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:after_call", "username", expectedProfile, nil).Once()
+	suite.Emitter.On("Emit", "mojang_textures:textures:before_call", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once()
+	suite.Emitter.On("Emit", "mojang_textures:textures:after_call", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", expectedResult, nil).Once()
+	suite.Emitter.On("Emit", "mojang_textures:after_result", "username", expectedResult, nil).Once()
 
 	suite.Storage.On("GetUuid", "username").Once().Return("", &ValueNotFound{})
 	suite.Storage.On("StoreUuid", "username", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once().Return(nil)
 	suite.Storage.On("StoreTextures", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", expectedResult).Once()
 
-	suite.UuidsProvider.On("GetUuid", "username").Once().Return(&mojang.ProfileInfo{
+	suite.UuidsProvider.On("GetUuid", "username").Once().Return(expectedProfile, nil)
-		Id:   "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa",
-		Name: "username",
-	}, nil)
 	suite.TexturesProvider.On("GetTextures", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once().Return(expectedResult, nil)
 
 	result, err := suite.Provider.GetForUsername("username")
@@ -202,12 +208,18 @@ func (suite *providerTestSuite) TestGetForUsernameWithoutAnyCache() {
 }
 
 func (suite *providerTestSuite) TestGetForUsernameWithCachedUuid() {
+	var expectedCachedTextures *mojang.SignedTexturesResponse
 	expectedResult := &mojang.SignedTexturesResponse{Id: "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", Name: "username"}
 
-	suite.Logger.On("IncCounter", "mojang_textures.request", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:call", "username").Once()
-	suite.Logger.On("IncCounter", "mojang_textures.usernames.cache_hit", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:before_cache", "username").Once()
-	suite.Logger.On("IncCounter", "mojang_textures.usernames.textures_hit", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:after_cache", "username", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", nil).Once()
-	suite.Logger.On("RecordTimer", "mojang_textures.result_time", mock.Anything).Once()
+	suite.Emitter.On("Emit", "mojang_textures:textures:before_cache", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once()
+	suite.Emitter.On("Emit", "mojang_textures:textures:after_cache", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", expectedCachedTextures, &ValueNotFound{}).Once()
+	suite.Emitter.On("Emit", "mojang_textures:before_result", "username", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once()
+	suite.Emitter.On("Emit", "mojang_textures:textures:before_call", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once()
+	suite.Emitter.On("Emit", "mojang_textures:textures:after_call", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", expectedResult, nil).Once()
+	suite.Emitter.On("Emit", "mojang_textures:after_result", "username", expectedResult, nil).Once()
 
 	suite.Storage.On("GetUuid", "username").Once().Return("aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", nil)
 	suite.Storage.On("GetTextures", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once().Return(nil, &ValueNotFound{})
@@ -224,9 +236,11 @@ func (suite *providerTestSuite) TestGetForUsernameWithCachedUuid() {
 func (suite *providerTestSuite) TestGetForUsernameWithFullyCachedResult() {
 	expectedResult := &mojang.SignedTexturesResponse{Id: "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", Name: "username"}
 
-	suite.Logger.On("IncCounter", "mojang_textures.request", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:call", "username").Once()
-	suite.Logger.On("IncCounter", "mojang_textures.usernames.cache_hit", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:before_cache", "username").Once()
-	suite.Logger.On("IncCounter", "mojang_textures.textures.cache_hit", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:after_cache", "username", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", nil).Once()
+	suite.Emitter.On("Emit", "mojang_textures:textures:before_cache", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once()
+	suite.Emitter.On("Emit", "mojang_textures:textures:after_cache", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", expectedResult, nil).Once()
 
 	suite.Storage.On("GetUuid", "username").Once().Return("aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", nil)
 	suite.Storage.On("GetTextures", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once().Return(expectedResult, nil)
@@ -238,8 +252,9 @@ func (suite *providerTestSuite) TestGetForUsernameWithFullyCachedResult() {
 }
 
 func (suite *providerTestSuite) TestGetForUsernameWithCachedUnknownUuid() {
-	suite.Logger.On("IncCounter", "mojang_textures.request", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:call", "username").Once()
-	suite.Logger.On("IncCounter", "mojang_textures.usernames.cache_hit_nil", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:before_cache", "username").Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:after_cache", "username", "", nil).Once()
 
 	suite.Storage.On("GetUuid", "username").Once().Return("", nil)
 
@@ -250,9 +265,16 @@ func (suite *providerTestSuite) TestGetForUsernameWithCachedUnknownUuid() {
 }
 
 func (suite *providerTestSuite) TestGetForUsernameWhichHasNoMojangAccount() {
-	suite.Logger.On("IncCounter", "mojang_textures.request", int64(1)).Once()
+	var expectedProfile *mojang.ProfileInfo
-	suite.Logger.On("IncCounter", "mojang_textures.usernames.uuid_miss", int64(1)).Once()
+	var expectedResult *mojang.SignedTexturesResponse
-	suite.Logger.On("RecordTimer", "mojang_textures.result_time", mock.Anything).Once()
+
+	suite.Emitter.On("Emit", "mojang_textures:call", "username").Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:before_cache", "username").Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:after_cache", "username", "", &ValueNotFound{}).Once()
+	suite.Emitter.On("Emit", "mojang_textures:before_result", "username", "").Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:before_call", "username").Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:after_call", "username", expectedProfile, nil).Once()
+	suite.Emitter.On("Emit", "mojang_textures:after_result", "username", expectedResult, nil).Once()
 
 	suite.Storage.On("GetUuid", "username").Once().Return("", &ValueNotFound{})
 	suite.Storage.On("StoreUuid", "username", "").Once().Return(nil)
@@ -266,21 +288,24 @@ func (suite *providerTestSuite) TestGetForUsernameWhichHasNoMojangAccount() {
 }
 
 func (suite *providerTestSuite) TestGetForUsernameWhichHasMojangAccountButHasNoMojangSkin() {
+	expectedProfile := &mojang.ProfileInfo{Id: "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", Name: "username"}
 	var expectedResult *mojang.SignedTexturesResponse
 
-	suite.Logger.On("IncCounter", "mojang_textures.request", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:call", "username").Once()
-	suite.Logger.On("IncCounter", "mojang_textures.usernames.uuid_hit", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:before_cache", "username").Once()
-	suite.Logger.On("IncCounter", "mojang_textures.usernames.textures_miss", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:after_cache", "username", "", &ValueNotFound{}).Once()
-	suite.Logger.On("RecordTimer", "mojang_textures.result_time", mock.Anything).Once()
+	suite.Emitter.On("Emit", "mojang_textures:before_result", "username", "").Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:before_call", "username").Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:after_call", "username", expectedProfile, nil).Once()
+	suite.Emitter.On("Emit", "mojang_textures:textures:before_call", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once()
+	suite.Emitter.On("Emit", "mojang_textures:textures:after_call", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", expectedResult, nil).Once()
+	suite.Emitter.On("Emit", "mojang_textures:after_result", "username", expectedResult, nil).Once()
 
 	suite.Storage.On("GetUuid", "username").Once().Return("", &ValueNotFound{})
 	suite.Storage.On("StoreUuid", "username", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once().Return(nil)
 	suite.Storage.On("StoreTextures", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", expectedResult).Once()
 
-	suite.UuidsProvider.On("GetUuid", "username").Once().Return(&mojang.ProfileInfo{
+	suite.UuidsProvider.On("GetUuid", "username").Once().Return(expectedProfile, nil)
-		Id:   "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa",
-		Name: "username",
-	}, nil)
 	suite.TexturesProvider.On("GetTextures", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once().Return(expectedResult, nil)
 
 	result, err := suite.Provider.GetForUsername("username")
@@ -290,23 +315,26 @@ func (suite *providerTestSuite) TestGetForUsernameWhichHasMojangAccountButHasNoM
 }
 
 func (suite *providerTestSuite) TestGetForTheSameUsernames() {
+	expectedProfile := &mojang.ProfileInfo{Id: "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", Name: "username"}
 	expectedResult := &mojang.SignedTexturesResponse{Id: "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", Name: "username"}
 
-	suite.Logger.On("IncCounter", "mojang_textures.request", int64(1)).Twice()
+	suite.Emitter.On("Emit", "mojang_textures:call", "username").Twice()
-	suite.Logger.On("IncCounter", "mojang_textures.already_scheduled", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:before_cache", "username").Twice()
-	suite.Logger.On("IncCounter", "mojang_textures.usernames.uuid_hit", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:after_cache", "username", "", &ValueNotFound{}).Twice()
-	suite.Logger.On("IncCounter", "mojang_textures.usernames.textures_hit", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:already_processing", "username").Once()
-	suite.Logger.On("RecordTimer", "mojang_textures.result_time", mock.Anything).Once()
+	suite.Emitter.On("Emit", "mojang_textures:before_result", "username", "").Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:before_call", "username").Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:after_call", "username", expectedProfile, nil).Once()
+	suite.Emitter.On("Emit", "mojang_textures:textures:before_call", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once()
+	suite.Emitter.On("Emit", "mojang_textures:textures:after_call", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", expectedResult, nil).Once()
+	suite.Emitter.On("Emit", "mojang_textures:after_result", "username", expectedResult, nil).Once()
 
 	suite.Storage.On("GetUuid", "username").Twice().Return("", &ValueNotFound{})
 	suite.Storage.On("StoreUuid", "username", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once().Return(nil)
 	suite.Storage.On("StoreTextures", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", expectedResult).Once()
 
 	// If possible, than remove this .After call
-	suite.UuidsProvider.On("GetUuid", "username").Once().After(time.Millisecond).Return(&mojang.ProfileInfo{
+	suite.UuidsProvider.On("GetUuid", "username").Once().After(time.Millisecond).Return(expectedProfile, nil)
-		Id:   "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa",
-		Name: "username",
-	}, nil)
 	suite.TexturesProvider.On("GetTextures", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once().Return(expectedResult, nil)
 
 	results := make([]*mojang.SignedTexturesResponse, 2)
@@ -326,114 +354,53 @@ func (suite *providerTestSuite) TestGetForTheSameUsernames() {
 }
 
 func (suite *providerTestSuite) TestGetForNotAllowedMojangUsername() {
-	suite.Logger.On("IncCounter", "mojang_textures.invalid_username", int64(1)).Once()
-
 	result, err := suite.Provider.GetForUsername("Not allowed")
 	suite.Assert().Error(err, "invalid username")
 	suite.Assert().Nil(result)
 }
 
-type timeoutError struct {
+func (suite *providerTestSuite) TestGetErrorFromUuidsProvider() {
-}
+	var expectedProfile *mojang.ProfileInfo
+	var expectedResult *mojang.SignedTexturesResponse
+	err := errors.New("mock error")
 
-func (*timeoutError) Error() string   { return "timeout error" }
+	suite.Emitter.On("Emit", "mojang_textures:call", "username").Once()
-func (*timeoutError) Timeout() bool   { return true }
+	suite.Emitter.On("Emit", "mojang_textures:usernames:before_cache", "username").Once()
-func (*timeoutError) Temporary() bool { return false }
+	suite.Emitter.On("Emit", "mojang_textures:usernames:after_cache", "username", "", &ValueNotFound{}).Once()
+	suite.Emitter.On("Emit", "mojang_textures:before_result", "username", "").Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:before_call", "username").Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:after_call", "username", expectedProfile, err).Once()
+	suite.Emitter.On("Emit", "mojang_textures:after_result", "username", expectedResult, err).Once()
 
-var expectedErrors = []error{
+	suite.Storage.On("GetUuid", "username").Once().Return("", &ValueNotFound{})
-	&mojang.BadRequestError{},
+	suite.UuidsProvider.On("GetUuid", "username").Once().Return(nil, err)
-	&mojang.ForbiddenError{},
-	&mojang.TooManyRequestsError{},
-	&mojang.ServerError{},
-	&timeoutError{},
-	&url.Error{Op: "GET", URL: "http://localhost"},
-	&net.OpError{Op: "read"},
-	&net.OpError{Op: "dial"},
-	syscall.ECONNREFUSED,
-}
 
-func (suite *providerTestSuite) TestShouldNotLogErrorWhenExpectedErrorReturnedFromUsernameToUuidRequest() {
+	result, resErr := suite.Provider.GetForUsername("username")
-	suite.Logger.On("IncCounter", mock.Anything, mock.Anything)
-	suite.Logger.On("RecordTimer", mock.Anything, mock.Anything)
-	suite.Logger.On("Debug", ":name: Got response error :err", mock.Anything, mock.Anything).Times(len(expectedErrors))
-	suite.Logger.On("Warning", ":name: Got 400 Bad Request :err", mock.Anything, mock.Anything).Once()
-	suite.Logger.On("Warning", ":name: Got 403 Forbidden :err", mock.Anything, mock.Anything).Once()
-	suite.Logger.On("Warning", ":name: Got 429 Too Many Requests :err", mock.Anything, mock.Anything).Once()
-
-	suite.Storage.On("GetUuid", "username").Return("", &ValueNotFound{})
-
-	for _, err := range expectedErrors {
-		suite.UuidsProvider.On("GetUuid", "username").Once().Return(nil, err)
-
-		result, err := suite.Provider.GetForUsername("username")
-		suite.Assert().Nil(result)
-		suite.Assert().NotNil(err)
-		suite.UuidsProvider.AssertExpectations(suite.T())
-		suite.UuidsProvider.ExpectedCalls = nil // https://github.com/stretchr/testify/issues/558#issuecomment-372112364
-	}
-}
-
-func (suite *providerTestSuite) TestShouldLogEmergencyOnUnexpectedErrorReturnedFromUsernameToUuidRequest() {
-	suite.Logger.On("IncCounter", mock.Anything, mock.Anything)
-	suite.Logger.On("RecordTimer", mock.Anything, mock.Anything)
-	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", "username").Return("", &ValueNotFound{})
-
-	suite.UuidsProvider.On("GetUuid", "username").Once().Return(nil, errors.New("unexpected error"))
-
-	result, err := suite.Provider.GetForUsername("username")
 	suite.Assert().Nil(result)
-	suite.Assert().NotNil(err)
+	suite.Assert().Equal(err, resErr)
 }
 
-func (suite *providerTestSuite) TestShouldNotLogErrorWhenExpectedErrorReturnedFromUuidToTexturesRequest() {
+func (suite *providerTestSuite) TestGetErrorFromTexturesProvider() {
-	suite.Logger.On("IncCounter", mock.Anything, mock.Anything)
+	expectedProfile := &mojang.ProfileInfo{Id: "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", Name: "username"}
-	suite.Logger.On("RecordTimer", mock.Anything, mock.Anything)
+	var expectedResult *mojang.SignedTexturesResponse
-	suite.Logger.On("Debug", ":name: Got response error :err", mock.Anything, mock.Anything).Times(len(expectedErrors))
+	err := errors.New("mock error")
-	suite.Logger.On("Warning", ":name: Got 400 Bad Request :err", mock.Anything, mock.Anything).Once()
+
-	suite.Logger.On("Warning", ":name: Got 403 Forbidden :err", mock.Anything, mock.Anything).Once()
+	suite.Emitter.On("Emit", "mojang_textures:call", "username").Once()
-	suite.Logger.On("Warning", ":name: Got 429 Too Many Requests :err", mock.Anything, mock.Anything).Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:before_cache", "username").Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:after_cache", "username", "", &ValueNotFound{}).Once()
+	suite.Emitter.On("Emit", "mojang_textures:before_result", "username", "").Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:before_call", "username").Once()
+	suite.Emitter.On("Emit", "mojang_textures:usernames:after_call", "username", expectedProfile, nil).Once()
+	suite.Emitter.On("Emit", "mojang_textures:textures:before_call", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once()
+	suite.Emitter.On("Emit", "mojang_textures:textures:after_call", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", expectedResult, err).Once()
+	suite.Emitter.On("Emit", "mojang_textures:after_result", "username", expectedResult, err).Once()
 
 	suite.Storage.On("GetUuid", "username").Return("", &ValueNotFound{})
 	suite.Storage.On("StoreUuid", "username", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Return(nil)
-	// suite.Storage.On("GetTextures", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Return(nil, &ValueNotFound{})
+	suite.UuidsProvider.On("GetUuid", "username").Once().Return(expectedProfile, nil)
-	// suite.Storage.On("StoreTextures", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", (*mojang.SignedTexturesResponse)(nil))
+	suite.TexturesProvider.On("GetTextures", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once().Return(nil, err)
 
-	for _, err := range expectedErrors {
+	result, resErr := suite.Provider.GetForUsername("username")
-		suite.UuidsProvider.On("GetUuid", "username").Once().Return(&mojang.ProfileInfo{
-			Id:   "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa",
-			Name: "username",
-		}, nil)
-		suite.TexturesProvider.On("GetTextures", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once().Return(nil, err)
-
-		result, err := suite.Provider.GetForUsername("username")
-		suite.Assert().Nil(result)
-		suite.Assert().NotNil(err)
-		suite.UuidsProvider.AssertExpectations(suite.T())
-		suite.TexturesProvider.AssertExpectations(suite.T())
-		suite.UuidsProvider.ExpectedCalls = nil    // https://github.com/stretchr/testify/issues/558#issuecomment-372112364
-		suite.TexturesProvider.ExpectedCalls = nil // https://github.com/stretchr/testify/issues/558#issuecomment-372112364
-	}
-}
-
-func (suite *providerTestSuite) TestShouldLogEmergencyOnUnexpectedErrorReturnedFromUuidToTexturesRequest() {
-	suite.Logger.On("IncCounter", mock.Anything, mock.Anything)
-	suite.Logger.On("RecordTimer", mock.Anything, mock.Anything)
-	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", "username").Return("", &ValueNotFound{})
-	suite.Storage.On("StoreUuid", "username", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Return(nil)
-
-	suite.UuidsProvider.On("GetUuid", "username").Once().Return(&mojang.ProfileInfo{
-		Id:   "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa",
-		Name: "username",
-	}, nil)
-	suite.TexturesProvider.On("GetTextures", "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa").Once().Return(nil, errors.New("unexpected error"))
-
-	result, err := suite.Provider.GetForUsername("username")
 	suite.Assert().Nil(result)
-	suite.Assert().NotNil(err)
+	suite.Assert().Equal(err, resErr)
 }

mojangtextures/remote_api_uuids_provider.go

@@ -2,16 +2,13 @@ package mojangtextures
 
 import (
 	"encoding/json"
-	"github.com/elyby/chrly/version"
 	"io/ioutil"
 	"net/http"
 	. "net/url"
 	"path"
-	"time"
-
-	"github.com/mono83/slf/wd"
 
 	"github.com/elyby/chrly/api/mojang"
+	"github.com/elyby/chrly/version"
 )
 
 var HttpClient = &http.Client{
@@ -21,24 +18,23 @@ var HttpClient = &http.Client{
 }
 
 type RemoteApiUuidsProvider struct {
+	Emitter
 	Url    URL
-	Logger wd.Watchdog
 }
 
 func (ctx *RemoteApiUuidsProvider) GetUuid(username string) (*mojang.ProfileInfo, error) {
-	ctx.Logger.IncCounter("mojang_textures.usernames.request", 1)
-
 	url := ctx.Url
 	url.Path = path.Join(url.Path, username)
+	urlStr := url.String()
 
-	request, _ := http.NewRequest("GET", url.String(), nil)
+	request, _ := http.NewRequest("GET", urlStr, nil)
 	request.Header.Add("Accept", "application/json")
 	// Change default User-Agent to allow specify "Username -> UUID at time" Mojang's api endpoint
 	request.Header.Add("User-Agent", "Chrly/"+version.Version())
 
-	start := time.Now()
+	ctx.Emit("mojang_textures:remote_api_uuids_provider:before_request", urlStr)
 	response, err := HttpClient.Do(request)
-	ctx.Logger.RecordTimer("mojang_textures.usernames.request_time", time.Since(start))
+	ctx.Emit("mojang_textures:remote_api_uuids_provider:after_request", response, err)
 	if err != nil {
 		return nil, err
 	}

mojangtextures/remote_api_uuids_provider_test.go

@@ -3,21 +3,19 @@ package mojangtextures
 import (
 	"net"
 	"net/http"
-	"net/url"
+	. "net/url"
 	"testing"
 
 	"github.com/h2non/gock"
 	"github.com/stretchr/testify/mock"
 	"github.com/stretchr/testify/suite"
-
-	mocks "github.com/elyby/chrly/tests"
 )
 
 type remoteApiUuidsProviderTestSuite struct {
 	suite.Suite
 
 	Provider *RemoteApiUuidsProvider
-	Logger   *mocks.WdMock
+	Emitter  *mockEmitter
 }
 
 func (suite *remoteApiUuidsProviderTestSuite) SetupSuite() {
@@ -28,14 +26,14 @@ func (suite *remoteApiUuidsProviderTestSuite) SetupSuite() {
 }
 
 func (suite *remoteApiUuidsProviderTestSuite) SetupTest() {
-	suite.Logger = &mocks.WdMock{}
+	suite.Emitter = &mockEmitter{}
 	suite.Provider = &RemoteApiUuidsProvider{
-		Logger: suite.Logger,
+		Emitter: suite.Emitter,
 	}
 }
 
 func (suite *remoteApiUuidsProviderTestSuite) TearDownTest() {
-	suite.Logger.AssertExpectations(suite.T())
+	suite.Emitter.AssertExpectations(suite.T())
 	gock.Off()
 }
 
@@ -44,8 +42,12 @@ func TestRemoteApiUuidsProvider(t *testing.T) {
 }
 
 func (suite *remoteApiUuidsProviderTestSuite) TestGetUuidForValidUsername() {
-	suite.Logger.On("IncCounter", "mojang_textures.usernames.request", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:remote_api_uuids_provider:before_request", "http://example.com/subpath/username").Once()
-	suite.Logger.On("RecordTimer", "mojang_textures.usernames.request_time", mock.Anything).Once()
+	suite.Emitter.On("Emit",
+		"mojang_textures:remote_api_uuids_provider:after_request",
+		mock.AnythingOfType("*http.Response"),
+		nil,
+	).Once()
 
 	gock.New("http://example.com").
 		Get("/subpath/username").
@@ -68,8 +70,12 @@ func (suite *remoteApiUuidsProviderTestSuite) TestGetUuidForValidUsername() {
 }
 
 func (suite *remoteApiUuidsProviderTestSuite) TestGetUuidForNotExistsUsername() {
-	suite.Logger.On("IncCounter", "mojang_textures.usernames.request", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:remote_api_uuids_provider:before_request", "http://example.com/subpath/username").Once()
-	suite.Logger.On("RecordTimer", "mojang_textures.usernames.request_time", mock.Anything).Once()
+	suite.Emitter.On("Emit",
+		"mojang_textures:remote_api_uuids_provider:after_request",
+		mock.AnythingOfType("*http.Response"),
+		nil,
+	).Once()
 
 	gock.New("http://example.com").
 		Get("/subpath/username").
@@ -84,8 +90,12 @@ func (suite *remoteApiUuidsProviderTestSuite) TestGetUuidForNotExistsUsername()
 }
 
 func (suite *remoteApiUuidsProviderTestSuite) TestGetUuidForNon20xResponse() {
-	suite.Logger.On("IncCounter", "mojang_textures.usernames.request", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:remote_api_uuids_provider:before_request", "http://example.com/subpath/username").Once()
-	suite.Logger.On("RecordTimer", "mojang_textures.usernames.request_time", mock.Anything).Once()
+	suite.Emitter.On("Emit",
+		"mojang_textures:remote_api_uuids_provider:after_request",
+		mock.AnythingOfType("*http.Response"),
+		nil,
+	).Once()
 
 	gock.New("http://example.com").
 		Get("/subpath/username").
@@ -101,8 +111,12 @@ func (suite *remoteApiUuidsProviderTestSuite) TestGetUuidForNon20xResponse() {
 }
 
 func (suite *remoteApiUuidsProviderTestSuite) TestGetUuidForNotSuccessRequest() {
-	suite.Logger.On("IncCounter", "mojang_textures.usernames.request", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:remote_api_uuids_provider:before_request", "http://example.com/subpath/username").Once()
-	suite.Logger.On("RecordTimer", "mojang_textures.usernames.request_time", mock.Anything).Once()
+	suite.Emitter.On("Emit",
+		"mojang_textures:remote_api_uuids_provider:after_request",
+		mock.AnythingOfType("*http.Response"),
+		mock.AnythingOfType("*url.Error"),
+	).Once()
 
 	expectedError := &net.OpError{Op: "dial"}
 
@@ -116,15 +130,19 @@ func (suite *remoteApiUuidsProviderTestSuite) TestGetUuidForNotSuccessRequest()
 	assert := suite.Assert()
 	assert.Nil(result)
 	if assert.Error(err) {
-		assert.IsType(&url.Error{}, err)
+		assert.IsType(&Error{}, err)
-		casterErr, _ := err.(*url.Error)
+		casterErr, _ := err.(*Error)
 		assert.Equal(expectedError, casterErr.Err)
 	}
 }
 
 func (suite *remoteApiUuidsProviderTestSuite) TestGetUuidForInvalidSuccessResponse() {
-	suite.Logger.On("IncCounter", "mojang_textures.usernames.request", int64(1)).Once()
+	suite.Emitter.On("Emit", "mojang_textures:remote_api_uuids_provider:before_request", "http://example.com/subpath/username").Once()
-	suite.Logger.On("RecordTimer", "mojang_textures.usernames.request_time", mock.Anything).Once()
+	suite.Emitter.On("Emit",
+		"mojang_textures:remote_api_uuids_provider:after_request",
+		mock.AnythingOfType("*http.Response"),
+		nil,
+	).Once()
 
 	gock.New("http://example.com").
 		Get("/subpath/username").
@@ -139,8 +157,8 @@ func (suite *remoteApiUuidsProviderTestSuite) TestGetUuidForInvalidSuccessRespon
 	assert.Error(err)
 }
 
-func shouldParseUrl(rawUrl string) url.URL {
+func shouldParseUrl(rawUrl string) URL {
-	url, err := url.Parse(rawUrl)
+	url, err := Parse(rawUrl)
 	if err != nil {
 		panic(err)
 	}

script/coverage

@@ -1,46 +0,0 @@
-#!/bin/sh
-# Based on https://github.com/mlafeldt/chef-runner/blob/34269dbb726c243dff9764007e7bd7f0fe9ee331/script/coverage
-# Generate test coverage statistics for Go packages.
-#
-# Works around the fact that `go test -coverprofile` currently does not work
-# with multiple packages, see https://code.google.com/p/go/issues/detail?id=6909
-#
-# Usage: script/coverage [--html]
-#
-#     --html      Additionally create HTML report and open it in browser
-#
-
-set -e
-
-workdir=.cover
-profile="$workdir/cover.out"
-mode=count
-
-generate_cover_data() {
-    rm -rf "$workdir"
-    mkdir "$workdir"
-
-    go test -i "$@" # compile dependencies first before serializing go test invocations
-    for pkg in "$@"; do
-        f="$workdir/$(echo $pkg | tr / -).cover"
-        go test -covermode="$mode" -coverprofile="$f" "$pkg"
-    done
-
-    echo "mode: $mode" >"$profile"
-    grep -h -v "^mode:" "$workdir"/*.cover >>"$profile"
-}
-
-show_cover_report() {
-    go tool cover -${1}="$profile"
-}
-
-generate_cover_data $(go list ./... | grep -v /vendor/)
-show_cover_report func
-case "$1" in
-"")
-    ;;
---html)
-    show_cover_report html ;;
-*)
-    echo >&2 "error: invalid option: $1"; exit 1 ;;
-esac

script/test

@@ -1,27 +0,0 @@
-#!/bin/sh
-# Based on https://github.com/mlafeldt/chef-runner/blob/34269dbb726c243dff9764007e7bd7f0fe9ee331/script/test
-# Run package tests for a file/directory, or all tests if no argument is passed.
-# Useful to e.g. execute package tests for the file currently open in Vim.
-# Usage: script/test [path]
-
-set -e
-
-go_pkg_from_path() {
-    path=$1
-    if test -d "$path"; then
-        dir="$path"
-    else
-        dir=$(dirname "$path")
-    fi
-    (cd "$dir" && go list)
-}
-
-if test $# -gt 0; then
-    pkg=$(go_pkg_from_path "$1")
-    verbose=-v
-else
-    pkg=$(go list ./... | grep -v /vendor/)
-    verbose=
-fi
-
-exec go test ${GOTESTOPTS:-$verbose} $pkg

tests/wd_mock.go

@@ -1,61 +0,0 @@
-package tests
-
-import (
-	"time"
-
-	"github.com/mono83/slf"
-	"github.com/mono83/slf/wd"
-	"github.com/stretchr/testify/mock"
-)
-
-type WdMock struct {
-	mock.Mock
-}
-
-func (m *WdMock) Trace(message string, p ...slf.Param) {
-	m.Called(message)
-}
-
-func (m *WdMock) Debug(message string, p ...slf.Param) {
-	m.Called(message)
-}
-
-func (m *WdMock) Info(message string, p ...slf.Param) {
-	m.Called(message)
-}
-
-func (m *WdMock) Warning(message string, p ...slf.Param) {
-	m.Called(message)
-}
-
-func (m *WdMock) Error(message string, p ...slf.Param) {
-	m.Called(message)
-}
-
-func (m *WdMock) Alert(message string, p ...slf.Param) {
-	m.Called(message)
-}
-
-func (m *WdMock) Emergency(message string, p ...slf.Param) {
-	m.Called(message)
-}
-
-func (m *WdMock) IncCounter(name string, value int64, p ...slf.Param) {
-	m.Called(name, value)
-}
-
-func (m *WdMock) UpdateGauge(name string, value int64, p ...slf.Param) {
-	m.Called(name, value)
-}
-
-func (m *WdMock) RecordTimer(name string, d time.Duration, p ...slf.Param) {
-	m.Called(name, d)
-}
-
-func (m *WdMock) Timer(name string, p ...slf.Param) slf.Timer {
-	return slf.NewTimer(name, p, m)
-}
-
-func (m *WdMock) WithParams(p ...slf.Param) wd.Watchdog {
-	panic("this method shouldn't be used")
-}