{"id":26145,"date":"2024-02-29T16:21:37","date_gmt":"2024-02-29T15:21:37","guid":{"rendered":"https:\/\/blog.mi.hdm-stuttgart.de\/?p=26145"},"modified":"2024-02-29T17:59:59","modified_gmt":"2024-02-29T16:59:59","slug":"combining-zerolog-loki","status":"publish","type":"post","link":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/2024\/02\/29\/combining-zerolog-loki\/","title":{"rendered":"Combining zerolog & Loki"},"content":{"rendered":"\n


In a recent project, some of my fellow students and I developed a simple hosting provider that enables users to start Docker containers on a remote server using a CLI tool.<\/p>\n\n\n\n

During this project, we developed a Go-based backend service that exposed a REST API to the client and handled the connection to Terraform via RabbitMQ, authentication via Keycloak, and data persistence using DynamoDB. This resulted in the backend being a crucial service that most functionality relied on. Therefore, it was important for us to enable monitoring of the backend. This included the collection of logs containing information about the current events inside the backend as well as the current health of the instance.<\/p>\n\n\n\n

zerolog<\/h3>\n\n\n\n

As we were using zerolog to handle logging within the application, we encountered a simple issue: we needed the logs stored in a place that Grafana could easily query. While there are systems that would have worked for our Docker Compose setup, we found that pushing the logs to Loki from the application itself was the most usable and sustainable solution.<\/p>\n\n\n\n

So we opted to use the hooks feature of zerolog to publish the logs to Loki. First off, what are zerolog hooks?<\/p>\n\n\n\n

Zerolog allows us to pass in a struct with a Run function when creating the logger. This Run function is called whenever a log event is emitted. Therefore, hooks can easily be utilized to extend the functionality of zerolog. A simple example of this would be the following:<\/p>\n\n\n

<\/p>\n

\n\n\n\n
\n
package<\/span> main\n\nimport<\/span> (\n    \"github.com\/rs\/zerolog\"<\/span>\n    \"github.com\/rs\/zerolog\/log\"<\/span>\n)\n\nfunc<\/span> init(){\n    log.Logger = log.Hook(LokiHook{})\n}\n\nfunc<\/span> main() {\n    for<\/span> {\n        log.Info().Msg(\"Sample log message\"<\/span>)\n        time.Sleep(5<\/span>)\n    }\n}\n\ntype<\/span> LokiHook struct<\/span> {\n}\n\nfunc<\/span> (h LokiHook) Run(e *<\/span>zerolog.Event, level zerolog.Level, msg string<\/span>) {\n    e.Str(\"hello\"<\/span>, \"world\"<\/span>)\n}\n<\/pre>\n<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n<\/div>\n\n\n
This will produce the following output:<\/p>\n\n\n
<\/p>\n
\n\n\n\n
\n
{\"level\"<\/span>:\"info\"<\/span>,\"time\"<\/span>:\"2024-02-28T16:18:25+01:00\"<\/span>,\"hello\"<\/span>:\"world\"<\/span>,\"message\"<\/span>:\"Sample log message\"<\/span>}\n<\/pre>\n<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n<\/div>\n\n\n
Great! We have the ability to execute a function on a log event. But where do we go from here?<\/p>\n\n\n\n
Loki<\/h3>\n\n\n\n
Well, first of all, it’s important to have a look at how log messages are published to Loki: Loki exposes an API that uses either JSON or protobuf to allow clients to push logs to the Loki instance. In our case, we will focus on the JSON side of things. The endpoint \/loki\/api\/v1\/push<\/code> expects a JSON payload of the following format:<\/p>\n\n\n
<\/p>\n
\n\n\n\n
\n
{\n  \"streams\"<\/span>: [\n    {\n      \"stream\"<\/span>: {\n        \"label\"<\/span>: \"value\"<\/span>\n      },\n      \"values\"<\/span>: [\n        [\"<unix epoch in nanoseconds>\"<\/span>, \"<log line>\"<\/span>],\n        [\"<unix epoch in nanoseconds>\"<\/span>, \"<log line>\"<\/span>]\n      ]\n    }\n  ]\n}\n<\/pre>\n<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n<\/div>\n\n\n
This means that we simply have to write a zerolog hook that publishes the current log line to Loki this way. That is easy enough, right?<\/p>\n\n\n\n
While yes, this is simple to implement, it is easy to make a possibly fatal mistake. In our current approach, every log event results in an HTTP request. Now imagine a scenario where we wanted to horizontally scale our service. Given enough instances and users, we have essentially just created a tool to DDoS our own Loki instance. So obviously, we cannot proceed with this approach. Additionally, making an HTTP request is a rather slow process. Meaning depending on the frequency of log events, this may lead to a lot of hooks running at the same time. Mind you: All those hooks are goroutines. Given enough load, this could result in a stack overflow.<\/p>\n\n\n\n
Implementation<\/h3>\n\n\n\n
Anyway, enough of the doomsday scenarios, let’s get to fixing:
The most straightforward approach to this problem is the introduction of a buffer. This buffer is filled with the log events that occur and once it reaches a certain size, it sends the entire batch of log statements at once. Using this tactic we can drastically reduce the amount of requests send to our Loki instance. <\/p>\n\n\n\n
However, tying the log event push to the current size of the buffer has one major drawback. If for some reason there are no log events over a long period of time, this could result in logs being published with extreme delay. As a result of this, Loki would be an inconsistent data source and could be more confusing than helpful when investigating incidents. <\/p>\n\n\n\n
This results in the need for a second condition that enables log events to be pushed to Loki. Instead of this second threshold being reliant on the current size of the buffer, it will simply depend on the time since the last time logs were pushed to Loki. To enable this check of the two threshold values, we will employ a simple goroutine that checks the time since the last push as well as the current size of the buffer. Additionally the buffer is split for every log level so the log level for the given events can be passed to Loki.<\/p>\n\n\n\n
This results in a struct with the following properties and the function bgRun<\/code> as the base for the goroutine:<\/p>\n\n\n
<\/p>\n
\n\n\n\n
\n
type<\/span> LokiClient struct<\/span> {\n    PushIntveralSeconds int<\/span>\n    \/\/ This will also trigger the send event<\/span>\n    MaxBatchSize int<\/span>\n    Values       map<\/span>[string<\/span>][][]string<\/span>\n    LokiEndpoint string<\/span>\n    BatchCount   int<\/span>\n}\n\nfunc<\/span> (l *<\/span>LokiClient) bgRun() {\n    lastRunTimestamp :=<\/span> 0<\/span>\n    isWorking :=<\/span> true<\/span>\n    for<\/span> {\n        if<\/span> time.Now().Second()-<\/span>lastRunTimestamp > l.PushIntveralSeconds ||<\/span> l.BatchCount > l.MaxBatchSize {\n            \/\/ Loop over all log levels and send them<\/span>\n            for<\/span> k :=<\/span> range<\/span> l.Values {\n                if<\/span> len<\/span>(l.Values) > 0<\/span> {\n                    prevLogs :=<\/span> l.Values[k]\n                    l.Values[k] = [][]string<\/span>{}\n                    err :=<\/span> pushToLoki(prevLogs, l.LokiEndpoint, k)\n                    if<\/span> err !=<\/span> nil<\/span> &&<\/span> isWorking {\n                        isWorking = false<\/span>\n                        log.Error().Msgf(\"Logs are currently not being forwarded to loki due to an error: %v\"<\/span>, err)\n                    }\n                    if<\/span> err ==<\/span> nil<\/span> &&<\/span> !isWorking {\n                        isWorking = true<\/span>\n                        \/\/ I will not accept PR comments about this log message tyvm<\/span>\n                        log.Info().Msgf(\"Logs are now being published again. The loki instance seems to be reachable once more! May the logeth collecteth'r beest did bless with our logs\"<\/span>)\n                    }\n                }\n            }\n            lastRunTimestamp = time.Now().Second()\n            l.BatchCount = 0<\/span>\n        }\n    }\n}\n<\/pre>\n<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n<\/div>\n\n\n
Based on the afore mentioned spec of the Loki API implementing the HTTP call to Loki is also simple enough:<\/p>\n\n\n
<\/p>\n
\n\n\n\n
\n
type<\/span> lokiStream struct<\/span> {\n    Stream map<\/span>[string<\/span>]string<\/span> `json:\"stream\"`<\/span>\n    Values [][]string<\/span>        `json:\"values\"`<\/span>\n}\n\ntype<\/span> lokiLogEvent struct<\/span> {\n    Streams []lokiStream\n}\n\n\/*<\/span>\nThis function contains *no* error handling\/logging because this:<\/span>\na) should not crash the application<\/span>\nb) would mean that every run of this creates further logs that cannot be published<\/span>\n=> The error will be returned and the problem will be logged ONCE by the handling function<\/span>\n*\/<\/span>\nfunc<\/span> pushToLoki(logs [][]string<\/span>, lokiEndpoint string<\/span>, logLevel string<\/span>) error<\/span> {\n\n    lokiPushPath :=<\/span> \"\/loki\/api\/v1\/push\"<\/span>\n\n    data, err :=<\/span> json.Marshal(lokiLogEvent{\n        Streams: []lokiStream{\n            {\n                Stream: map<\/span>[string<\/span>]string<\/span>{\n                    \"service\"<\/span>: \"demo\"<\/span>,\n                    \"level\"<\/span>:   logLevel,\n                },\n                Values: logs,\n            },\n        },\n    })\n\n    if<\/span> err !=<\/span> nil<\/span> {\n        return<\/span> err\n    }\n\n    req, err :=<\/span> http.NewRequest(http.MethodPost, fmt.Sprintf(\"%v%v\"<\/span>, lokiEndpoint, lokiPushPath), bytes.NewBuffer(data))\n\n    if<\/span> err !=<\/span> nil<\/span> {\n        return<\/span> err\n    }\n\n    ctx, cancel :=<\/span> context.WithTimeout(req.Context(), 100<\/span>*<\/span>time.Millisecond)\n\n    defer<\/span> cancel()\n\n    req = req.WithContext(ctx)\n\n    req.Header.Set(\"Content-Type\"<\/span>, \"application\/json\"<\/span>)\n\n    client :=<\/span> &<\/span>http.Client{}\n\n    resp, err :=<\/span> client.Do(req)\n    if<\/span> err !=<\/span> nil<\/span> {\n        return<\/span> err\n    }\n    defer<\/span> resp.Body.Close()\n\n    return<\/span> nil<\/span>\n}\n<\/pre>\n<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n<\/div>\n\n\n
And thats almost all the work done! Lets just apply that to our little example from earlier:<\/p>\n\n\n
<\/p>\n
\n\n\n\n
\n
package<\/span> main\n\nimport<\/span> (\n    \"strconv\"<\/span>\n    \"time\"<\/span>\n\n    \"github.com\/rs\/zerolog\"<\/span>\n    \"github.com\/rs\/zerolog\/log\"<\/span>\n)\n\nvar<\/span> lokiClient LokiClient\n\nfunc<\/span> init() {\n    lokiClient = LokiClient{\n        PushIntveralSeconds: 10<\/span>,  \/\/ Threshhold of 10s<\/span>\n        MaxBatchSize:        500<\/span>, \/\/Threshold of 500 events<\/span>\n        LokiEndpoint:        \"http:\/\/localhost:3100\"<\/span>,\n        BatchCount:          0<\/span>,\n        Values:              make<\/span>(map<\/span>[string<\/span>][][]string<\/span>),\n    }\n\n    go<\/span> lokiClient.bgRun()\n    log.Logger = log.Hook(LokiHook{})\n}\n\nfunc<\/span> main() {\n\n    for<\/span> {\n        log.Info().Msg(\"Sample log message\"<\/span>)\n        time.Sleep(1<\/span> *<\/span> time.Second)\n    }\n}\n\ntype<\/span> LokiHook struct<\/span> {\n}\n\nfunc<\/span> (h LokiHook) Run(e *<\/span>zerolog.Event, level zerolog.Level, msg string<\/span>) {\n    lokiClient.Values[level.String()] = append<\/span>(lokiClient.Values[level.String()], []string<\/span>{strconv.FormatInt(time.Now().UnixNano(), 10<\/span>), msg})\n    lokiClient.BatchCount++<\/span>\n}\n<\/pre>\n<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n<\/div>\n\n\n
To see the whole example checkout the repository<\/a>.<\/p>\n\n\n\n
\n
When using large batch sizes ensure that your Loki instance is configured to allow batches of the given size.<\/p>\n<\/blockquote>\n","protected":false},"excerpt":{"rendered":"
Publish zerolog events to Loki in just a few lines of code.<\/p>\n","protected":false},"author":1190,"featured_media":0,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_jetpack_memberships_contains_paid_content":false,"footnotes":""},"categories":[1,650,2,657],"tags":[51,332,167],"ppma_author":[1011],"class_list":["post-26145","post","type-post","status-publish","format-standard","hentry","category-allgemein","category-scalable-systems","category-system-engineering","category-teaching-and-learning","tag-design","tag-go","tag-monitoring"],"aioseo_notices":[],"jetpack_featured_media_url":"","jetpack-related-posts":[{"id":26160,"url":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/2024\/02\/29\/why-system-monitoring-is-important-and-how-we-approached-it\/","url_meta":{"origin":26145,"position":0},"title":"Why system monitoring is important and how we approached it","author":"Michelle Becher","date":"29. February 2024","format":false,"excerpt":"Introduction Imagine building a service that aims to generate as much user traffic as possible to be as profitable as possible. The infrastructure of your service usually includes some kind of backend, a server and other frameworks. One day, something is not working as it should and you can't seem\u2026","rel":"","context":"In "Allgemein"","block_context":{"text":"Allgemein","link":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/category\/allgemein\/"},"img":{"alt_text":"","src":"https:\/\/i0.wp.com\/blog.mi.hdm-stuttgart.de\/wp-content\/uploads\/2024\/02\/monitoring.png?resize=350%2C200&ssl=1","width":350,"height":200,"srcset":"https:\/\/i0.wp.com\/blog.mi.hdm-stuttgart.de\/wp-content\/uploads\/2024\/02\/monitoring.png?resize=350%2C200&ssl=1 1x, https:\/\/i0.wp.com\/blog.mi.hdm-stuttgart.de\/wp-content\/uploads\/2024\/02\/monitoring.png?resize=525%2C300&ssl=1 1.5x, https:\/\/i0.wp.com\/blog.mi.hdm-stuttgart.de\/wp-content\/uploads\/2024\/02\/monitoring.png?resize=700%2C400&ssl=1 2x"},"classes":[]},{"id":26197,"url":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/2024\/02\/29\/terraform-x-go-challenges-when-interacting-with-terraform-through-go\/","url_meta":{"origin":26145,"position":1},"title":"Terraform x Go: Challenges when interacting with Terraform through Go","author":"Maximilian Tellmann","date":"29. February 2024","format":false,"excerpt":"Introduction goTerra In a recent project, some of my fellow students and I developed a basic hosting provider that allows a user to spin up Docker containers on a remote server, which is realized by using Terraform locally on the server. During this project, we developed a Go-based backend service\u2026","rel":"","context":"In "Allgemein"","block_context":{"text":"Allgemein","link":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/category\/allgemein\/"},"img":{"alt_text":"","src":"https:\/\/i0.wp.com\/blog.mi.hdm-stuttgart.de\/wp-content\/uploads\/2024\/02\/Untitled-Project-1024x905.png?resize=350%2C200&ssl=1","width":350,"height":200,"srcset":"https:\/\/i0.wp.com\/blog.mi.hdm-stuttgart.de\/wp-content\/uploads\/2024\/02\/Untitled-Project-1024x905.png?resize=350%2C200&ssl=1 1x, https:\/\/i0.wp.com\/blog.mi.hdm-stuttgart.de\/wp-content\/uploads\/2024\/02\/Untitled-Project-1024x905.png?resize=525%2C300&ssl=1 1.5x, https:\/\/i0.wp.com\/blog.mi.hdm-stuttgart.de\/wp-content\/uploads\/2024\/02\/Untitled-Project-1024x905.png?resize=700%2C400&ssl=1 2x"},"classes":[]},{"id":12087,"url":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/2020\/09\/30\/getting-started-with-cloud-computing-a-covid-19-data-map\/","url_meta":{"origin":26145,"position":2},"title":"Getting Started with Cloud Computing – A COVID-19 Data Map","author":"mk306","date":"30. September 2020","format":false,"excerpt":"1. Abstract Are you searching for country-specific, up-to-date numbers and rates for the global pandemic caused by COVID-19? Well, then I got some bad news for you. You won\u2019t find any in this blog post\u2026 not directly anyway. If you are looking for in-depth information about public APIs, location-based data\u2026","rel":"","context":"In "Cloud Technologies"","block_context":{"text":"Cloud Technologies","link":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/category\/scalable-systems\/cloud-technologies\/"},"img":{"alt_text":"","src":"https:\/\/i0.wp.com\/blog.mi.hdm-stuttgart.de\/wp-content\/uploads\/2020\/09\/Response-1.png?resize=350%2C200&ssl=1","width":350,"height":200,"srcset":"https:\/\/i0.wp.com\/blog.mi.hdm-stuttgart.de\/wp-content\/uploads\/2020\/09\/Response-1.png?resize=350%2C200&ssl=1 1x, https:\/\/i0.wp.com\/blog.mi.hdm-stuttgart.de\/wp-content\/uploads\/2020\/09\/Response-1.png?resize=525%2C300&ssl=1 1.5x"},"classes":[]},{"id":26146,"url":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/2024\/02\/29\/using-keycloak-as-iam-for-our-hosting-provider-service\/","url_meta":{"origin":26145,"position":3},"title":"Using Keycloak as IAM for our hosting provider service","author":"Dennis Schmidt","date":"29. February 2024","format":false,"excerpt":"Discover how Keycloak can revolutionize your IAM strategy and propel your projects to new heights of security and efficiency.","rel":"","context":"In "Allgemein"","block_context":{"text":"Allgemein","link":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/category\/allgemein\/"},"img":{"alt_text":"","src":"https:\/\/i0.wp.com\/blog.mi.hdm-stuttgart.de\/wp-content\/uploads\/2024\/02\/stmk_diagrams_en.png?resize=350%2C200&ssl=1","width":350,"height":200},"classes":[]},{"id":11460,"url":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/2020\/09\/29\/get-car-location-using-raspberrypi-and-google-cloud-iot-core\/","url_meta":{"origin":26145,"position":4},"title":"Get car location using Raspberry Pi and Google Cloud IoT Core","author":"Simon L\u00f6bert","date":"29. September 2020","format":false,"excerpt":"Project idea Have you ever been in the situation, that you parked your car somewhere in the city and some hours later, you couldn't remember where you parked it? You may wish to have an application on your smartphone, which is able to locate your car. From this consideration, the\u2026","rel":"","context":"In "Allgemein"","block_context":{"text":"Allgemein","link":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/category\/allgemein\/"},"img":{"alt_text":"","src":"https:\/\/i0.wp.com\/blog.mi.hdm-stuttgart.de\/wp-content\/uploads\/2020\/09\/grafik.png?resize=350%2C200&ssl=1","width":350,"height":200},"classes":[]},{"id":4395,"url":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/2019\/01\/17\/radcup-a-socialmedia-beerpong-app\/","url_meta":{"origin":26145,"position":5},"title":"Radcup – a socialmedia beerpong App","author":"Immanuel Haag","date":"17. January 2019","format":false,"excerpt":"Written by: Immanuel Haag, Christian M\u00fcller, Marc R\u00fcttler Radcup adds a bit of social media to the well-known game Beerpong. With Radcup the user has the possibility to register or login. Afterwards he can display\/localize already existing games and join them if possible or create new games. As soon as\u2026","rel":"","context":"In "System Designs"","block_context":{"text":"System Designs","link":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/category\/system-designs\/"},"img":{"alt_text":"","src":"https:\/\/i0.wp.com\/blog.mi.hdm-stuttgart.de\/wp-content\/uploads\/2019\/01\/Screen-Shot-2019-01-06-at-15.09.35.png?resize=350%2C200&ssl=1","width":350,"height":200,"srcset":"https:\/\/i0.wp.com\/blog.mi.hdm-stuttgart.de\/wp-content\/uploads\/2019\/01\/Screen-Shot-2019-01-06-at-15.09.35.png?resize=350%2C200&ssl=1 1x, https:\/\/i0.wp.com\/blog.mi.hdm-stuttgart.de\/wp-content\/uploads\/2019\/01\/Screen-Shot-2019-01-06-at-15.09.35.png?resize=525%2C300&ssl=1 1.5x"},"classes":[]}],"jetpack_sharing_enabled":true,"authors":[{"term_id":1011,"user_id":1190,"is_guest":0,"slug":"max_herkenhoff","display_name":"Max Herkenhoff","avatar_url":"https:\/\/secure.gravatar.com\/avatar\/234ba1a5f12fa84beff88e72008ebc9b8331d7fe0ca3f1006d5b0c29c34907ee?s=96&d=mm&r=g","0":null,"1":"","2":"","3":"","4":"","5":"","6":"","7":"","8":""}],"_links":{"self":[{"href":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/wp-json\/wp\/v2\/posts\/26145","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/wp-json\/wp\/v2\/users\/1190"}],"replies":[{"embeddable":true,"href":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/wp-json\/wp\/v2\/comments?post=26145"}],"version-history":[{"count":8,"href":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/wp-json\/wp\/v2\/posts\/26145\/revisions"}],"predecessor-version":[{"id":26204,"href":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/wp-json\/wp\/v2\/posts\/26145\/revisions\/26204"}],"wp:attachment":[{"href":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/wp-json\/wp\/v2\/media?parent=26145"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/wp-json\/wp\/v2\/categories?post=26145"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/wp-json\/wp\/v2\/tags?post=26145"},{"taxonomy":"author","embeddable":true,"href":"https:\/\/blog.mi.hdm-stuttgart.de\/index.php\/wp-json\/wp\/v2\/ppma_author?post=26145"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}