Merge pull request #497 from innogames/cleanup_metrics

WIP: Cleanup Prometheus metrics

bot/config/config.go

@@ -46,14 +46,15 @@ type Config struct {
 	viper *viper.Viper `mapstructure:"-"`
 }
 
-// LoadCustom does a dynamic config lookup with a given key and unmarshals it into the value
+// LoadCustom does a dynamic config lookup with a given key and unmarshal it into the value
 func (c *Config) LoadCustom(key string, value any) error {
 	if c.viper == nil {
 		return nil
 	}
 	return c.viper.UnmarshalKey(key, value)
 }
 
+// Set a dynamic config value...please only set it in tests!
 func (c *Config) Set(key string, value any) {
 	if c.viper == nil {
 		c.viper = viper.New()

bot/config/metrics.go

@@ -4,3 +4,8 @@ type Metrics struct {
 	// e.g. use ":8082" to expose metrics on all interfaces
 	PrometheusListener string `mapstructure:"prometheus_listener"`
 }
+
+// IsEnabled returns true if the metrics are enabled by config
+func (c *Metrics) IsEnabled() bool {
+	return c.PrometheusListener != ""
+}

bot/listener.go

@@ -5,6 +5,7 @@ import (
 	"os/signal"
 	"syscall"
 
+	"github.com/innogames/slack-bot/v2/bot/stats"
 	"github.com/innogames/slack-bot/v2/bot/util"
 	"github.com/innogames/slack-bot/v2/client"
 	log "github.com/sirupsen/logrus"
@@ -13,18 +14,9 @@ import (
 	"github.com/slack-go/slack/socketmode"
 )
 
-func (b *Bot) startRunnables(ctx *util.ServerContext) {
-	for _, cmd := range b.commands.commands {
-		if runnable, ok := cmd.(Runnable); ok {
-			go runnable.RunAsync(ctx)
-		}
-	}
-}
-
 // Run is blocking method to handle new incoming events...from different sources
 func (b *Bot) Run(ctx *util.ServerContext) {
 	b.startRunnables(ctx)
-	initMetrics(b.config, ctx)
 
 	// initialize Socket Mode:
 	// https://api.slack.com/apis/connections/socket
@@ -54,6 +46,19 @@ func (b *Bot) Run(ctx *util.ServerContext) {
 	}
 }
 
+// startRunnables starts all background tasks and ctx.StopTheWorld() will stop them then properly
+func (b *Bot) startRunnables(ctx *util.ServerContext) {
+	// each command can have a background task which is executed in the background
+	for _, cmd := range b.commands.commands {
+		if runnable, ok := cmd.(Runnable); ok {
+			go runnable.RunAsync(ctx)
+		}
+	}
+
+	// special handler which are executed in the background
+	stats.InitMetrics(b.config, ctx)
+}
+
 func (b *Bot) handleSocketModeEvent(event socketmode.Event) {
 	if event.Request != nil && event.Type != socketmode.EventTypeHello {
 		b.slackClient.Socket.Ack(*event.Request)

bot/metrics.go → bot/stats/metrics.go

@@ -1,12 +1,11 @@
-package bot
+package stats
 
 import (
 	"net/http"
 	"strings"
 	"time"
 
 	"github.com/innogames/slack-bot/v2/bot/config"
-	"github.com/innogames/slack-bot/v2/bot/stats"
 	"github.com/innogames/slack-bot/v2/bot/util"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/collectors"
@@ -23,19 +22,20 @@ func (c *statRegistry) Describe(_ chan<- *prometheus.Desc) {
 
 // Collect returns the current state of all metrics of our slack-bot stats
 func (c *statRegistry) Collect(ch chan<- prometheus.Metric) {
-	for _, key := range stats.GetKeys() {
-		metric := prometheus.NewGauge(prometheus.GaugeOpts{
+	for _, key := range GetKeys() {
+		metric := prometheus.NewCounter(prometheus.CounterOpts{
 			Namespace: "slack_bot",
 			Name:      strings.ReplaceAll(key, "-", "_"),
 		})
-		value, _ := stats.Get(key)
-		metric.Set(float64(value))
+		value, _ := Get(key)
+		metric.Add(float64(value))
 		metric.Collect(ch)
 	}
 }
 
-func initMetrics(cfg config.Config, ctx *util.ServerContext) {
-	if cfg.Metrics.PrometheusListener == "" {
+func InitMetrics(cfg config.Config, ctx *util.ServerContext) {
+	if !cfg.Metrics.IsEnabled() {
+		// prometheus is disabled...skip here
 		return
 	}
 
@@ -64,7 +64,10 @@ func initMetrics(cfg config.Config, ctx *util.ServerContext) {
 		)
 
 		go func() {
-			_ = server.ListenAndServe()
+			err := server.ListenAndServe()
+			if err != nil {
+				log.Warnf("Failed to start prometheus server: %s", err)
+			}
 		}()
 
 		<-ctx.Done()

bot/metrics_test.go → bot/stats/metrics_test.go

@@ -1,4 +1,4 @@
-package bot
+package stats
 
 import (
 	"io"
@@ -8,7 +8,6 @@ import (
 	"time"
 
 	"github.com/innogames/slack-bot/v2/bot/config"
-	"github.com/innogames/slack-bot/v2/bot/stats"
 	"github.com/innogames/slack-bot/v2/bot/util"
 
 	"github.com/stretchr/testify/assert"
@@ -26,9 +25,9 @@ func TestMetrics(t *testing.T) {
 		},
 	}
 
-	stats.Set("test_value", 500)
+	Set("test_value", 500)
 
-	initMetrics(cfg, ctx)
+	InitMetrics(cfg, ctx)
 	time.Sleep(time.Millisecond * 100)
 
 	resp, err := http.Get("http://" + metricsPort + "/metrics")

bot/stats/stats_test.go

@@ -26,13 +26,15 @@ func TestStats(t *testing.T) {
 	assert.Nil(t, err)
 	assert.Equal(t, value, uint(42))
 
-	Increase("test", 2)
+	Increase("test", int64(1))
+	Increase("test", int8(1))
+	Increase("test", 1)
 	value, err = Get("test")
 	assert.Nil(t, err)
-	assert.Equal(t, value, uint(44))
+	assert.Equal(t, value, uint(45))
 
 	IncreaseOne("test")
 	value, err = Get("test")
 	assert.Nil(t, err)
-	assert.Equal(t, value, uint(45))
+	assert.Equal(t, value, uint(46))
 }

command/openai/chatgpt.go

@@ -3,6 +3,7 @@ package openai
 import (
 	"bufio"
 	"encoding/json"
+	"fmt"
 	"io"
 	"net/http"
 	"strings"
@@ -42,12 +43,15 @@ func CallChatGPT(cfg Config, inputMessages []ChatMessage, stream bool) (<-chan s
 			var chatResponse ChatResponse
 			err = json.Unmarshal(body, &chatResponse)
 			if err != nil {
-				messageUpdates <- err.Error()
+				log.Warnf("Openai Error %d: %s", resp.StatusCode, err)
+
+				messageUpdates <- fmt.Sprintf("Error %d: %s", resp.StatusCode, err)
 				return
 			}
 
 			if err = chatResponse.GetError(); err != nil {
-				messageUpdates <- chatResponse.GetError().Error()
+				log.Warn("Openai Error: ", err, chatResponse, body)
+				messageUpdates <- err.Error()
 				return
 			}
 

command/openai/command.go

@@ -241,24 +241,27 @@ func (c *chatGPTCommand) callAndStore(messages []ChatMessage, storageIdentifier
 			log.Warnf("Error while storing openai history: %s", err)
 		}
 
+		// log some stats in the end
+		outputTokens := estimateTokensForMessage(responseText.String())
 		stats.IncreaseOne("openai_calls")
 		stats.Increase("openai_input_tokens", inputTokens)
-		stats.Increase("openai_output_tokens", estimateTokensForMessage(responseText.String()))
+		stats.Increase("openai_output_tokens", outputTokens)
 
-		log.Infof(
-			"Openai %s call took %s with %d sub messages (%d tokens).",
-			c.cfg.Model,
+		logFields := log.Fields{
+			"input_tokens":  inputTokens,
+			"output_tokens": outputTokens,
+			"model":         c.cfg.Model,
+		}
+		if c.cfg.LogTexts {
+			logFields["input_text"] = inputText
+			logFields["output_text"] = responseText.String()
+		}
+
+		log.WithFields(logFields).Infof(
+			"Openai call took %s with %d context messages.",
 			util.FormatDuration(time.Since(startTime)),
 			len(messages),
-			inputTokens,
 		)
-		if c.cfg.LogTexts {
-			log.Infof(
-				"Openai texts. Input: '%s'. Response: '%s'",
-				inputText,
-				responseText.String(),
-			)
-		}
 	}()
 }