From 4b1ee7edeb08537a02de6b2bd1fa519b5865b4fd Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Matthias=20D=C3=B6tsch?= Date: Wed, 15 Nov 2023 12:58:22 +0100 Subject: [PATCH] Cleanup Prometheus metrics --- bot/config/config.go | 3 ++- bot/config/metrics.go | 5 +++++ bot/listener.go | 23 ++++++++++++++--------- bot/{ => stats}/metrics.go | 21 ++++++++++++--------- bot/{ => stats}/metrics_test.go | 7 +++---- bot/stats/stats_test.go | 8 +++++--- command/openai/chatgpt.go | 8 ++++++-- command/openai/command.go | 27 +++++++++++++++------------ 8 files changed, 62 insertions(+), 40 deletions(-) rename bot/{ => stats}/metrics.go (76%) rename bot/{ => stats}/metrics_test.go (88%) diff --git a/bot/config/config.go b/bot/config/config.go index 36de1f15..d2a3f2ed 100644 --- a/bot/config/config.go +++ b/bot/config/config.go @@ -46,7 +46,7 @@ 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 @@ -54,6 +54,7 @@ func (c *Config) LoadCustom(key string, value any) error { 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() diff --git a/bot/config/metrics.go b/bot/config/metrics.go index 801caa5c..c18c0258 100644 --- a/bot/config/metrics.go +++ b/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 != "" +} diff --git a/bot/listener.go b/bot/listener.go index 4d12bc4c..2217d137 100644 --- a/bot/listener.go +++ b/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) diff --git a/bot/metrics.go b/bot/stats/metrics.go similarity index 76% rename from bot/metrics.go rename to bot/stats/metrics.go index 20c5a7c1..9a56eb96 100644 --- a/bot/metrics.go +++ b/bot/stats/metrics.go @@ -1,4 +1,4 @@ -package bot +package stats import ( "net/http" @@ -6,7 +6,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/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() diff --git a/bot/metrics_test.go b/bot/stats/metrics_test.go similarity index 88% rename from bot/metrics_test.go rename to bot/stats/metrics_test.go index 56ebb22e..638a01fc 100644 --- a/bot/metrics_test.go +++ b/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") diff --git a/bot/stats/stats_test.go b/bot/stats/stats_test.go index 1282ffc2..14e263cf 100644 --- a/bot/stats/stats_test.go +++ b/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)) } diff --git a/command/openai/chatgpt.go b/command/openai/chatgpt.go index 13fe3cd9..83d9090b 100644 --- a/command/openai/chatgpt.go +++ b/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 } diff --git a/command/openai/command.go b/command/openai/command.go index 0cd1a6c6..d6980dbd 100644 --- a/command/openai/command.go +++ b/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(), - ) - } }() }