#20 add metrics (#21)

* add metrics option
* add metrics
* update readme
* add examples

README.md

@@ -40,7 +40,8 @@ All parameters can be overwritten by ENV variable.
         "dialect": "postgres",
         "path": "host=myhost port=myport user=gorm dbname=gorm password=mypassword"
     },
-    "loglevel": "trace"
+    "loglevel": "trace",
+    "metrics": false
 }
 ```
 
@@ -69,11 +70,24 @@ services:
         - LOG_LEVEL=info
 ```
 
+## Prometheus Endpoint
+
+The Prometheus endpoint is located under `:8080/metrics` when `enable_metrics` is enabled in the Config.
+
+ONLY for local tests a docker-compose overwrite file is included.
+
+```bash
+docker-compose -f docker-compose.yml -f docker-compose.prometheus.yml up
+```
+
+You can reach Prometheus on port 9090.
+
 ## DSGVO
 
 - Speichert:
     - ChatID + Zug für den Verspätungsalarm. Wird 2 Tage nach Ankunft des Zuges gelöscht (um Verspätungen abzufangen).
     - ChatID + Aktuelle Operation mit Bot (z.B. newalarm, savealarm, ...). Wird 4 Tage nach letzter Interaktion gelöscht.
+    - Metrics erfassen verwendung von Zugnummern ohne Verknüpfungen zu Personen.
 
 ## ToDo
 

cmd/bot.go

@@ -2,9 +2,12 @@ package cmd
 
 import (
 	"context"
+	"net/http"
 	"strconv"
+	"time"
 
 	tgbotapi "github.com/go-telegram-bot-api/telegram-bot-api"
+	"github.com/prometheus/client_golang/prometheus/promhttp"
 	"github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
 
@@ -15,6 +18,7 @@ import (
 	"github.com/pkuebler/bahn-bot/pkg/infrastructure/telegramconversation"
 	"github.com/pkuebler/bahn-bot/pkg/interface/cron"
 	"github.com/pkuebler/bahn-bot/pkg/interface/telegram"
+	"github.com/pkuebler/bahn-bot/pkg/metrics"
 )
 
 // NewBotCmd create a command to start the bot
@@ -51,8 +55,11 @@ func BotCommand(ctx context.Context, cmd *cobra.Command, args []string) {
 		log.Logger.Level = logrus.InfoLevel
 	}
 
+	// metrics
+	metricsRegistry := metrics.NewPrometheusMetric()
+
 	// external interfaces
-	api, err := marudor.NewAPIClient(cfg.APIConfig.APIEndpoint, nil, log)
+	api, err := marudor.NewAPIClient(cfg.APIConfig.APIEndpoint, nil, log, cfg.EnableMetrics)
 	if err != nil {
 		panic(err)
 	}
@@ -68,7 +75,7 @@ func BotCommand(ctx context.Context, cmd *cobra.Command, args []string) {
 
 	// interfaces
 	service := telegram.NewTelegramService(log, repo, app, hafas)
-	cronService := cron.NewCronJob(log, app)
+	cronService := cron.NewCronJob(log, app, cfg.EnableMetrics)
 
 	// conversationengine
 	router := telegramconversation.NewConversationRouter("start")
@@ -113,8 +120,12 @@ func BotCommand(ctx context.Context, cmd *cobra.Command, args []string) {
 		for update := range updates {
 			var tctx telegramconversation.TContext
 
+			startTime := time.Now()
+			metricsRegistry.TelegramInUpdatesTotal.Inc()
+
 			if update.CallbackQuery != nil {
 				log.Tracef("[%d][%s] Callback Query %s", update.CallbackQuery.Message.MessageID, update.CallbackQuery.From.UserName, update.CallbackQuery.Data)
+				metricsRegistry.TelegramInQueriesTotal.Inc()
 
 				chatID := strconv.FormatInt(update.CallbackQuery.Message.Chat.ID, 10)
 
@@ -130,7 +141,10 @@ func BotCommand(ctx context.Context, cmd *cobra.Command, args []string) {
 				command := update.Message.Command()
 				if command != "" {
 					log.Tracef("[%d][%s] Command %s", tctx.MessageID(), update.Message.From.UserName, command)
+					metricsRegistry.TelegramInCommandsTotal.Inc()
 					tctx.SetCommand(command, update.Message.CommandArguments())
+				} else {
+					metricsRegistry.TelegramInMessagesTotal.Inc()
 				}
 
 				tctx.SetMessage(update.Message.Text)
@@ -189,6 +203,7 @@ func BotCommand(ctx context.Context, cmd *cobra.Command, args []string) {
 					reply.ReplyMarkup = keyboard
 				}
 
+				metricsRegistry.TelegramOutMessagesTotal.Inc()
 				bot.Send(reply)
 			}
 
@@ -201,6 +216,9 @@ func BotCommand(ctx context.Context, cmd *cobra.Command, args []string) {
 				msgLog.Tracef("Save State %s with payload `%s` (old: %s / `%s`)", tctx.State(), tctx.StatePayload(), state, payload)
 				return tctx.State(), tctx.StatePayload(), nil
 			})
+
+			duration := time.Now().Sub(startTime).Seconds()
+			metricsRegistry.TelegramRequestDuration.Observe(duration)
 		}
 	}()
 
@@ -209,6 +227,7 @@ func BotCommand(ctx context.Context, cmd *cobra.Command, args []string) {
 		for tctx := range notificationChannel {
 			if tctx.IsReply() {
 				log.Tracef("Reply: %s", tctx.Reply())
+
 				reply := tgbotapi.NewMessage(tctx.ChatID64(), tctx.Reply())
 				reply.ParseMode = tgbotapi.ModeMarkdown
 
@@ -238,5 +257,16 @@ func BotCommand(ctx context.Context, cmd *cobra.Command, args []string) {
 	}()
 
 	cronService.Start(ctx)
+
+	// metric endpoint
+	if cfg.EnableMetrics {
+		log.Info("start metrics endpoint...")
+		http.Handle("/metrics", promhttp.Handler())
+		if err := http.ListenAndServe(":8080", nil); err != nil {
+			log.Error(err)
+			return
+		}
+	}
+
 	<-ctx.Done()
 }

config_example.json

@@ -9,5 +9,6 @@
         "dialect": "postgres",
         "path": "host=postgres port=myport user=bahn-bot dbname=bahn-bot password=supersecretpassword sslmode=disable"
     },
-    "loglevel": "trace"
+    "loglevel": "trace",
+    "enable_metrics": true
 }

docker-compose.prometheus.yml

@@ -0,0 +1,10 @@
+version: '3'
+services:
+  prometheus:
+    image: prom/prometheus:latest
+    ports:
+      - 9090:9090
+    command:
+      - --config.file=/etc/prometheus/prometheus.yml
+    volumes:
+      - ./prometheus.yml:/etc/prometheus/prometheus.yml:ro

go.mod

@@ -7,6 +7,7 @@ require (
 	github.com/go-telegram-bot-api/telegram-bot-api v4.6.4+incompatible
 	github.com/google/uuid v1.1.1
 	github.com/jinzhu/gorm v1.9.15
+	github.com/prometheus/client_golang v0.9.3
 	github.com/sirupsen/logrus v1.6.0
 	github.com/spf13/cobra v1.0.0
 	github.com/stretchr/testify v1.2.2

go.sum

@@ -9,6 +9,7 @@ github.com/alecthomas/units v0.0.0-20151022065526-2efee857e7cf/go.mod h1:ybxpYRF
 github.com/andybalholm/cascadia v1.1.0/go.mod h1:GsXiBklL0woXo1j/WYWtSYYC4ouU9PqHO0sqidkEA4Y=
 github.com/armon/consul-api v0.0.0-20180202201655-eb2c6b5be1b6/go.mod h1:grANhF5doyWs3UAsr3K4I6qtAmlQcZDesFNEHPZAzj8=
 github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973/go.mod h1:Dwedo/Wpr24TaqPxmxbtue+5NUziq4I4S80YR8gNf3Q=
+github.com/beorn7/perks v1.0.0 h1:HWo1m869IqiPhD389kmkxeTalrjNbbJTC8LXupb+sl0=
 github.com/beorn7/perks v1.0.0/go.mod h1:KWe93zE9D1o94FZ5RNwFwVgaQK1VOXiVxmqh+CedLV8=
 github.com/cespare/xxhash v1.1.0/go.mod h1:XrSqR1VqqWfGrhpAt58auRo0WTKS1nRRg3ghfAqPWnc=
 github.com/client9/misspell v0.3.4/go.mod h1:qj6jICC3Q7zFZvVWo7KLAzC3yx5G7kyvSDkc90ppPyw=
@@ -44,6 +45,7 @@ github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b/go.mod h1:SBH7ygxi8pfU
 github.com/golang/groupcache v0.0.0-20190129154638-5b532d6fd5ef/go.mod h1:cIg4eruTrX1D+g88fzRXU5OdNfaM+9IcxsU14FzY7Hc=
 github.com/golang/mock v1.1.1/go.mod h1:oTYuIxOrZwtPieC+H1uAHpcLFnEyAGVDL/k47Jfbm0A=
 github.com/golang/protobuf v1.2.0/go.mod h1:6lQm79b+lXiMfvg/cZm0SGofjICqVBUtrP5yJMmIC1U=
+github.com/golang/protobuf v1.3.1 h1:YF8+flBXS5eO826T4nzqPrxfhQThhXl0YzfuUPu4SBg=
 github.com/golang/protobuf v1.3.1/go.mod h1:6lQm79b+lXiMfvg/cZm0SGofjICqVBUtrP5yJMmIC1U=
 github.com/google/btree v1.0.0/go.mod h1:lNA+9X1NB3Zf8V7Ke586lFgjr2dZNuvo3lPJSGZ5JPQ=
 github.com/google/go-cmp v0.2.0/go.mod h1:oXzfMopK8JAjlY9xF4vHSVASa0yLyX7SntLO5aqRK0M=
@@ -80,6 +82,7 @@ github.com/lib/pq v1.1.1/go.mod h1:5WUZQaWbwv1U+lTReE5YruASi9Al49XbQIvNi/34Woo=
 github.com/magiconair/properties v1.8.0/go.mod h1:PppfXfuXeibc/6YijjN8zIbojt8czPbwD3XqdrwzmxQ=
 github.com/mattn/go-sqlite3 v1.14.0 h1:mLyGNKR8+Vv9CAU7PphKa2hkEqxxhn8i32J6FPj1/QA=
 github.com/mattn/go-sqlite3 v1.14.0/go.mod h1:JIl7NbARA7phWnGvh0LKTyg7S9BA+6gx71ShQilpsus=
+github.com/matttproud/golang_protobuf_extensions v1.0.1 h1:4hp9jkHxhMHkqkrB3Ix0jegS5sx/RkqARlsWZ6pIwiU=
 github.com/matttproud/golang_protobuf_extensions v1.0.1/go.mod h1:D8He9yQNgCq6Z5Ld7szi9bcBfOoFv/3dc6xSMkL2PC0=
 github.com/mitchellh/go-homedir v1.1.0/go.mod h1:SfyaCUpYCn1Vlf4IUYiD9fPX4A5wJrkLzIz1N1q0pr0=
 github.com/mitchellh/mapstructure v1.1.2/go.mod h1:FVVH3fgwuzCH5S8UJGiWEs2h04kUh9fWfEaFds41c1Y=
@@ -90,12 +93,16 @@ github.com/pkg/errors v0.8.0/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINE
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/prometheus/client_golang v0.9.1/go.mod h1:7SWBe2y4D6OKWSNQJUaRYU/AaXPKyh/dDVn+NZz0KFw=
+github.com/prometheus/client_golang v0.9.3 h1:9iH4JKXLzFbOAdtqv/a+j8aewx2Y8lAjAydhbaScPF8=
 github.com/prometheus/client_golang v0.9.3/go.mod h1:/TN21ttK/J9q6uSwhBd54HahCDft0ttaMvbicHlPoso=
 github.com/prometheus/client_model v0.0.0-20180712105110-5c3871d89910/go.mod h1:MbSGuTsp3dbXC40dX6PRTWyKYBIrTGTE9sqQNg2J8bo=
+github.com/prometheus/client_model v0.0.0-20190129233127-fd36f4220a90 h1:S/YWwWx/RA8rT8tKFRuGUZhuA90OyIBpPCXkcbwU8DE=
 github.com/prometheus/client_model v0.0.0-20190129233127-fd36f4220a90/go.mod h1:xMI15A0UPsDsEKsMN9yxemIoYk6Tm2C1GtYGdfGttqA=
 github.com/prometheus/common v0.0.0-20181113130724-41aa239b4cce/go.mod h1:daVV7qP5qjZbuso7PdcryaAu0sAZbrN9i7WWcTMWvro=
+github.com/prometheus/common v0.4.0 h1:7etb9YClo3a6HjLzfl6rIQaU+FDfi0VSX39io3aQ+DM=
 github.com/prometheus/common v0.4.0/go.mod h1:TNfzLD0ON7rHzMJeJkieUDPYmFC7Snx/y86RQel1bk4=
 github.com/prometheus/procfs v0.0.0-20181005140218-185b4288413d/go.mod h1:c3At6R/oaqEKCNdg8wHV1ftS6bRYblBhIjjI8uT2IGk=
+github.com/prometheus/procfs v0.0.0-20190507164030-5867b95ac084 h1:sofwID9zm4tzrgykg80hfFph1mryUeLRsUfoocVVmRY=
 github.com/prometheus/procfs v0.0.0-20190507164030-5867b95ac084/go.mod h1:TjEm7ze935MbeOT/UhFTIMYKhuLP4wbCsTZCD3I8kEA=
 github.com/prometheus/tsdb v0.7.1/go.mod h1:qhTCs0VvXwvX/y3TZrWD7rabWM+ijKTux40TwIPHuXU=
 github.com/rogpeppe/fastuuid v0.0.0-20150106093220-6724a57986af/go.mod h1:XWv6SoW27p1b0cqNHllgS5HIMJraePCO15w5zCzIWYg=

pkg/config/config.go

@@ -26,10 +26,11 @@ type DatabaseConfig struct {
 
 // Config contains the complete service configuration
 type Config struct {
-	APIConfig APIConfig      `json:"api"`
-	Database  DatabaseConfig `json:"database"`
-	Telegram  TelegramConfig `json:"telegram"`
-	LogLevel  string         `env:"LOG_LEVEL" json:"loglevel"`
+	APIConfig     APIConfig      `json:"api"`
+	Database      DatabaseConfig `json:"database"`
+	Telegram      TelegramConfig `json:"telegram"`
+	LogLevel      string         `env:"LOG_LEVEL" json:"loglevel"`
+	EnableMetrics bool           `json:"enable_metrics"`
 }
 
 // NewTestConfig return a config object with test settings

pkg/infrastructure/marudor/api.go

@@ -9,6 +9,8 @@ import (
 	"net/http"
 	"net/http/httputil"
 	"net/url"
+	"strconv"
+	"time"
 
 	"github.com/sirupsen/logrus"
 )
@@ -19,12 +21,13 @@ type APIClient struct {
 	UserAgent   string
 	httpClient  *http.Client
 	log         *logrus.Entry
+	metrics     *APIMetrics
 
 	HafasService *HafasService
 }
 
 // NewAPIClient return a client with all services
-func NewAPIClient(endpoint string, httpClient *http.Client, log *logrus.Entry) (*APIClient, error) {
+func NewAPIClient(endpoint string, httpClient *http.Client, log *logrus.Entry, metrics bool) (*APIClient, error) {
 	if httpClient == nil {
 		httpClient = http.DefaultClient
 	}
@@ -45,6 +48,10 @@ func NewAPIClient(endpoint string, httpClient *http.Client, log *logrus.Entry) (
 		UserAgent:   "pkuebler/marudor-telegram-bot",
 	}
 
+	if metrics {
+		c.metrics = NewAPIMetrics()
+	}
+
 	log.Trace("add services..")
 	c.HafasService = &HafasService{client: c}
 
@@ -85,6 +92,8 @@ func (c *APIClient) newRequest(baseURL *url.URL, method string, path string, que
 }
 
 func (c *APIClient) do(req *http.Request, v interface{}) (*http.Response, error) {
+	startTime := time.Now()
+
 	res, err := c.httpClient.Do(req)
 	if err != nil {
 		c.log.Fatal(err)
@@ -100,6 +109,15 @@ func (c *APIClient) do(req *http.Request, v interface{}) (*http.Response, error)
 	c.log.Trace(req.URL.String())
 	c.log.Trace(string(requestDump))
 
+	if c.metrics != nil {
+		duration := time.Since(startTime)
+		path := req.URL.Path
+		statusCode := strconv.Itoa(res.StatusCode)
+
+		c.metrics.RequestsTotal.WithLabelValues(statusCode, path).Inc()
+		c.metrics.RequestDurationSeconds.WithLabelValues(statusCode, path).Observe(duration.Seconds())
+	}
+
 	if res.StatusCode < 200 || res.StatusCode >= 300 {
 		return res, errors.New(http.StatusText(res.StatusCode))
 	}

pkg/infrastructure/marudor/hafas.go

@@ -5,6 +5,7 @@ import (
 	"fmt"
 	"net/url"
 	"strconv"
+	"strings"
 	"time"
 )
 
@@ -137,7 +138,14 @@ func (h *HafasService) FindTrain(ctx context.Context, trainName string, date tim
 	}
 
 	var results []HafasTrainResult
-	_, err = h.client.do(req, &results)
+	res, err := h.client.do(req, &results)
+
+	if h.client.metrics != nil {
+		statusCode := strconv.Itoa(res.StatusCode)
+		name := strings.ReplaceAll(trainName, " ", "")
+		h.client.metrics.RequestsByTrainNameTotal.WithLabelValues(statusCode, name).Inc()
+	}
+
 	if err != nil {
 		return nil, err
 	}
@@ -159,7 +167,14 @@ func (h *HafasService) GetTrainByStation(ctx context.Context, trainName string,
 	}
 
 	var train HafasTrain
-	_, err = h.client.do(req, &train)
+	res, err := h.client.do(req, &train)
+
+	if h.client.metrics != nil {
+		statusCode := strconv.Itoa(res.StatusCode)
+		name := strings.ReplaceAll(trainName, " ", "")
+		h.client.metrics.RequestsByTrainNameTotal.WithLabelValues(statusCode, name).Inc()
+	}
+
 	if err != nil {
 		return nil, err
 	}

pkg/infrastructure/marudor/metrics.go

@@ -0,0 +1,45 @@
+package marudor
+
+import "github.com/prometheus/client_golang/prometheus"
+
+// APIMetrics Registry
+type APIMetrics struct {
+	RequestsTotal            *prometheus.CounterVec
+	RequestDurationSeconds   *prometheus.HistogramVec
+	RequestsByTrainNameTotal *prometheus.CounterVec
+}
+
+// NewAPIMetrics return a new metric registry
+func NewAPIMetrics() *APIMetrics {
+	marudorPrefix := "marudor_"
+
+	buckets := []float64{.005, .01, .025, .05, .1, .25, .5, 1, 2.5, 5, 10}
+
+	total := prometheus.NewCounterVec(prometheus.CounterOpts{
+		Name: marudorPrefix + "requests_total",
+		Help: "How many HTTP requests processed, partitoned by status code and endpoint",
+	}, []string{"status_code", "endpoint"})
+
+	duration := prometheus.NewHistogramVec(prometheus.HistogramOpts{
+		Name:    marudorPrefix + "duration_seconds",
+		Help:    "request duration",
+		Buckets: buckets,
+	}, []string{"status_code", "endpoint"})
+
+	trainNames := prometheus.NewCounterVec(prometheus.CounterOpts{
+		Name: marudorPrefix + "requests_by_trainname_total",
+		Help: "How many requests processed, partitoned by status code and train name",
+	}, []string{"status_code", "trainname"})
+
+	register := &APIMetrics{
+		RequestsTotal:            total,
+		RequestDurationSeconds:   duration,
+		RequestsByTrainNameTotal: trainNames,
+	}
+
+	prometheus.MustRegister(register.RequestsTotal)
+	prometheus.MustRegister(register.RequestDurationSeconds)
+	prometheus.MustRegister(register.RequestsByTrainNameTotal)
+
+	return register
+}