Game server logs with Grafana Loki and Alloy

Intro

0:00 Hello and welcome back to episode thirty-five, where we're going to keep what our servers write in their logs, and put it next to our metrics, with Grafana's Loki. Let's begin with a quick look at where we're going to be by the end of the episode.

0:14 Our dashboard counts the errors that each server writes, a minute at a time, next to its metrics. Here, MySQL is down, so the saver can't save anyone. Under it are the servers' own lines, as they come, with each error in red, and the saver's errors say why.

0:31 On the website of the series you can find more information about the project. The code for the project is open source on GitHub, tagged at each step of each episode so that you can follow along.

Last time

0:43 Now, before we get to today's work, let's quickly go over what we did last time. First, we fixed why CI had failed since episode twenty-eight, and it passes again. Then our content got a trainer, an NPC that teaches the kick, second wind and the whirlwind, while each player starts with the thrust. The world teaches a skill to a player who stands near the trainer, has reached the skill's level and doesn't know it yet, and tells them why not otherwise, once a test caught us forgetting the level. The client got a window to learn in, and the hotbar greys out what you don't know yet. What a player learns is saved with the rest of them, in Redis after each tick, and in a table of its own in MySQL, from migration V six. And the bots use the skills they know, which is the thrust, for now.

Today

1:28 Each of our servers writes a line for what it does: a player joins or leaves, learns a skill, asks for a story, or something goes wrong. In Compose, those lines go to each container's output, which docker compose logs prints for us, and which is deleted with the container. Our metrics say how much and how fast, and the logs say who and why, so we're going to keep them. Grafana's Alloy is going to read each container's output from Docker, as it comes, and send it to Loki, which keeps the lines and finds them by their labels, such as which service wrote them. Grafana already shows our metrics, and it's going to show the logs on that dashboard too. Then Loki is going to alert us from the logs, for a failure that no metric shows, and CI is going to check both configs. All right, let's get started, with Loki and what it keeps.

2:16 Loki is Grafana's store for logs, and its README calls it like Prometheus, but for logs. It doesn't index what each line says, just a few labels for each stream of lines, like Prometheus's labels on a series. Indexing the labels and nothing more keeps the index small and storing logs cheap, so a query picks the streams by their labels first, and then searches the lines in them. The README lists the stack it's part of, which is what we're going to run: Alloy, Grafana's agent, which gathers the logs and sends them on, then Loki, which stores and queries them, and Grafana, which shows them.

Loki and Alloy

2:51 In compose dot yaml, Loki and Alloy go in next to Mailpit, before Grafana. Loki comes from Grafana's own image, pinned like our other images, and its command points it at a config file of ours, which we mount from the monitoring folder, read-only, like Prometheus's. The logs it keeps go on a volume of their own, so they outlast the container, and its port is three one hundred, which Grafana reaches on Compose's network, and we can reach from the host. Alloy comes from an image of Grafana's too, and its command runs our config, with a folder where it keeps how far it got in each container's output. Alloy reads the containers' output from Docker, so it gets Docker's socket. Read-only doesn't limit what goes over a socket, and the socket lets whoever has it ask Docker anything, so Alloy has as much power as root on the machine, while our config uses it to read logs. Alloy has no port of its own, as nothing needs to reach it. And it starts after Loki, which it sends the lines to. In loki dot yaml, auth enabled is false, as a single game runs on this Loki, so it doesn't need to keep tenants apart. It listens on three one hundred, and logs its own warnings and worse. Common has what each part of Loki shares: Loki is several services, which a big setup runs apart, and we run them all in a single process. So each line is kept once, and the ring that its parts use to find each other is in memory. Its chunks, the compressed lines, go on the file system, on the volume. The schema says how Loki lays out what it stores, from a date on, so that a later layout can start from a later date. Ours is the tsdb index, which Loki's docs recommend, with schema v thirteen, a new index each day. The logs are kept for a week, a hundred and sixty-eight hours, and the compactor is the part that deletes what's older, with retention enabled. Alloy's config is in its own language, a component at a time, each with a name, and each one hands what it produces to the next one by that name. Discovery docker finds the containers through Docker's socket, and looks for new ones each five seconds, like Prometheus looks in Consul. Its default is a minute, and a server that starts after Alloy would wait that long for its lines to arrive. Its filter keeps the ones whose Compose project is nanommo, the name at the top of our compose file, so the other containers on a machine stay out. Discovery relabel takes the containers it found, and gives each one labels. Its rule takes Compose's label on each container, which has the container's service, and writes it into a label of ours, service. So the world server's lines are going to be service server, and the saver's service saver. Loki source docker reads what each container writes, as it comes, from Docker, for the containers in its targets, and hands the lines to loki write, which pushes them to Loki's API, on Compose's network. In Grafana's provisioning, Loki becomes a data source, next to Prometheus, with an id of its own, so that our dashboard can name it. In compose dot prod dot yaml, Loki listens on the server's localhost, like Prometheus, and both start again after a crash or a reboot. And the README gets a section on logs, with what Loki and Alloy do, and the first queries to try.

6:08 Let's start Ember, with Loki and Alloy next to it, and Compose brings up what Ember depends on, MySQL, Redis and Consul. A few seconds later, curl asks Loki's API for the labels it has, and jq prints them. There's a single label, service name, and it isn't ours. Loki adds service name to each stream from the labels it knows, and it found none of them. So its single value is unknown service, and the lines under it come from all of our containers, Ember's next to Alloy's and Loki's, in one stream. Our service label didn't reach Loki, so let's look at the Alloy config again.

6:45 Each Alloy component hands what it makes to the one that names it, and loki source docker names discovery docker's targets here, which skips the relabel in between. So its targets become discovery relabel's output, the containers with their service label. Nothing told us about the gap, as both components are valid on their own, and no component read the relabel's output.

7:08 With the stack started again, Loki has our service label, next to the service name it makes from it. Its values are the containers' services, from alloy to server, in alphabetical order. A query for service server gets Ember's lines alone, oldest first: it listens on port seven seven seven seven, prints its content's hash, serves its metrics, and registers with Consul.

Errors, by stream

7:31 Our servers have always written what goes wrong to standard error, and the rest to standard out, and Docker keeps the two apart, line by line. So the stream a line was written to says whether it's an error. Discovery's relabel sees each container, and the stream is a line's, so the rule goes on loki source docker, as relabel rules that Alloy runs on each line. Loki source docker takes its relabel rules from a component of their own, loki relabel, called streams. Its forward to is empty, as it hands its rules on, and no lines. Its rule copies each line's stream, which Alloy reads from Docker as standard out or standard error, into a stream label of ours. The label has two values, so each container's lines make two streams at most, and Loki's index stays small. The README says which stream our errors go to, and that other images use standard error for everything, such as MySQL's, so the stream says nothing about theirs.

8:31 With twenty bots playing, so that the saver has players to save, let's stop MySQL. The game carries on, as players go into Redis after each tick. A query for the saver's lines with stream standard error gets its errors, one each five seconds, at each attempt to save. And each line says why: the saver couldn't connect to MySQL.

Logs on the dashboard

8:53 Grafana marks each line with its level, from a label called level, and none of our lines has one. Our servers' stream says their level, so two more rules on the stream give them one. The first takes the service and the stream together, which relabel joins with a semicolon, and matches our four servers' standard error. Those lines get the level error, which Grafana shows in red. The second matches their standard out, which gets the level info. Other images' lines match neither, as their standard error isn't necessarily an error, so they get no level from us. On the dashboard, under the metrics, the panels from Loki go at the end of the panels' list. The first is errors a minute, a time series like the others, with the next id, eleven. Its data source is Loki, by the id we gave it, where the others name Prometheus. On the grid, the panel takes the right half of the row with waiting for a story, which has that half empty: twelve of Grafana's twenty-four columns wide, and nine rows tall. The field config and the options are the other time series', so the chart looks like them. That's a plain count as its unit, lines two pixels wide with a light fill under them, the legend at the bottom as a list, and a tooltip that shows each service's value at once. The query is in LogQL, Loki's query language, which picks streams by their labels in braces, like PromQL picks series. Count over time counts the lines of each stream in a minute, for our four servers' standard error, and sum by service adds the streams of each service together. So a burst of errors becomes a line on a chart, which we can read next to the ticks or the players. Each line on the chart is named after its service. The second panel, number twelve, is a logs panel, which lists the lines, and it's called what the servers say. It spans the dashboard's full width, under the others, and it's twelve rows tall, so that a dozen lines or so fit. The panel shows each line's time, wraps the long ones, puts the newest first, and opens a line's labels when we click it. Its query picks our four servers' streams, with a regular expression on the service label. And the README says what the two panels show, and where each line's level comes from.

11:06 With forty bots playing and MySQL stopped again, errors a minute climbs for the saver, as it fails each five seconds. Under it, the lines from the servers come in as they're written: what the bots say, their trips through the gate and the stories they ask for, as info. The saver's errors are in red, each one saying that it couldn't connect to MySQL.

An alert from the logs

11:29 The saver failing is something to be told about, and no metric of ours shows it. The world servers save into Redis after each tick, which works, and the players they saved wait there, unsaved in MySQL, until the saver can reach it. So while MySQL is down, Redis holds the single copy of what players did since. So Loki is going to alert us from the logs, with a rules file in the format of Prometheus's, from episode thirty. Saver failing counts the saver's lines on standard error over a minute, and fires when there are any, for a minute. So a single failed save doesn't email anyone, as it drops out of the minute's count before the alert has waited a minute, while a saver that keeps failing does. The summary says what's wrong, and what it means for players: the saver has been writing errors for a minute, so players stay unsaved in Redis. In loki dot yaml, the ruler is the part of Loki that checks rules, like Prometheus's rule evaluation. It sends its alerts to our Alertmanager, which emails them like it does Prometheus's, and it checks the rules each fifteen seconds. Its rules come from a local folder, and it keeps what it's working on in a folder on its volume. In compose dot yaml, the rules file goes into the local folder the ruler reads, in a folder called fake. Loki keeps each tenant's rules in a folder named after the tenant, and with auth off, Loki calls the tenant fake. And the README's section on logs has the rule, and why its folder is called fake.

13:01 With twenty bots in again, and Alertmanager and Mailpit running, let's stop MySQL. About two minutes later, Mailpit has an email, firing, with one alert, saver failing, for the saver. Its text is our summary: the saver has been writing errors for a minute, so players stay unsaved in Redis. Nothing in Prometheus would have fired, as the saver has no metrics of its own.

Configs, checked

13:27 A typo in Loki's config or Alloy's would leave us without logs, and we'd find out when we needed them. Both tools can check a config without running it, so CI is going to check ours, like it tests our alerts. Loki config is a service that extends Loki's, so it gets its image and its config file, and its command verifies the config and exits, in the test profile, so that docker compose up leaves it out. Alloy config extends Alloy's, and runs Alloy's validate on our config. Both exit with an error on a field they don't know, which a typo makes. In CI, a new step after the alerts' tests runs both. And the README says how to run them, and that neither looks at the rules' LogQL, so it says how a rule that Loki can't parse shows up in Loki's log.

14:14 Compose creates the container, and Loki's check prints nothing of its own, and exits with zero, so the config is good. Alloy's check runs without its dependencies, as it reads the config and nothing else, and it exits with zero too.

Wrap-up

14:29 So, today Loki and Alloy joined our stack, with Alloy reading each container's output from Docker, and Loki keeping it for a week. Our lines reached Loki without their service, until loki source docker read the relabelled containers. Each line has its stream as a label, so our servers' errors stand apart from the rest. The dashboard counts the errors each minute, and lists the servers' lines, with their level. Loki's ruler emails us when the saver fails for a minute, which no metric showed, and CI checks both configs.

Playing it

15:55 Let me know in the comments what you'd like to see next. And if you want to follow along with the series, subscribe to the channel. I hope you find this useful, and thanks for watching.