Monitoring Playtime on Your Minecraft Server with Go - Level 1
Tags: go, minecraft, playtime, monitoring
Published: 2021-03-28 21:17:41

---
title: Monitoring Playtime on Your Minecraft Server with Go - Level 1
published: true
description: This article describes the first "naive" approach for collecting daily playtime information for all the players on your Minecraft server. Written in go.
tags: go, minecraft, playtime, monitoring
//cover_image: https://direct_url_to_image.jpg
---

# Why

My kids love Minecraft and are spending a lot of time playing it. Probably a little to much. So much that they aren't really able to keep track of how much it actually is. 

But the basic local game isn't enough, they *need* Mods and they want to play together with their friends. The solution we came up with: run our own servers. I'm currently renting 2 quite cheap virtual machines on [Hetzner Cloud](https://www.hetzner.com/cloud)

For actually running the game I'm using the great Docker Minecraft image from [here](https://hub.docker.com/r/itzg/minecraft-server). The docs are great as well and it has toggles for modding system (e.g. forge) already baked in.

# Idea

To get some idea on how much time my kids (and their friends) are spending on this servers I was looking around for mods, but most were outdated or required some dependencies I wasn't willing to install. That route didn't lead me anywhere promising; but to be honest, I wasn't trying very hard, either.

I like coding and Minecraft is logging extensively ... I thought: 'Why not tailing the log and keeping note of logins and logouts.' Two evenings and some small bug fix / improvement iterations on the following mornings and a basic solution was done. You can find the whole thing here: https://github.com/Crenshinibon/mine-watcher/tree/v1.1

# Tailing

A quick search gave me this nice Go module: [go-tail](https://pkg.go.dev/github.com/hpcloud/tail#section-readme). Seems it's under active development and funded by HewlettPackard. This module might be around for some time.

It mimics the behavior of Unix' *tail* command. And here is the code I'm using:

```go
logTail, err := tail.TailFile(
        [PATH_TO_LOG_FILE], 
        tail.Config{
            //like tail -f keep the log file open and output new log lines
            Follow: true,
            //like tail -F reopens the log file when there log file rotates
            ReOpen: true,
        },
)
if err != nil {
    os.Exit(1)
}

for logLine := range logTail.Lines {
    //do something with line
}
```

That looked promising and easy enough.

# Parsing

The next step was identifying login and logout events in the stream and keeping track of the different players. Both events have a quite similar "anatomy".

> [13:30:42] [Server thread/INFO]: PLAYER_NAME left the game

and

> [13:30:42] [Server thread/INFO]: PLAYER_NAME joined the game

The naive solution: identifying the lines by "left the game" and "joined the game" respectively:

```go
regExpJoined := regexp.MustCompile("joined the game")
//logout
if regExpLeft.Match( LOG_LINE ) {
...
}

regExpLeft := regexp.MustCompile("left the game")
//login
if regExpJoined.Match( LOG_LINE ) {
...
}	
```

> DISCLAIMER: that solution can be easily hacked by your kids. My son just "informed" me about this. Since all in game messages will be logged similarly to system messages, e.g. writing "Ralea2 left the game" into the chat will break my logic. I have to fix that.

Simply splitting the string by whitespace and taking the 4th last element, and voila I have the player's name.

```go
func getPlayerName(line string) string {
        //strings.Fields actually splits the string by whitespace and trims leading/trailing spaces
	words := strings.Fields(line)
	if len(words) < 5 {
		return ""
	}

	return words[len(words)-4]
}
```

# Tracking

For keeping track of different players and their play times I'm using a map. The keys are the player names and the values are structs of the following form:

```go
type playTime struct {
	PlayerName       string        
	DurationOnServer time.Duration 
	LatestStart      time.Time     
	LatestEnd        time.Time     
}
```

When I see a login event of a new player I create a new entry in the map with the player name as key and the struct partially filled with *PlayerName* and *LatestStart*. If it's a known player I will update those fields

```go
current, exists := playTimes[playerName]
if !exists {
    current = &playTime{
        PlayerName: playerName,
    }
}
current.LatestStart = t
playTimes[playerName] = current
```

When I see a logout event I have to be careful. Because, it could be possible that there is no known login event yet (because the "watcher" was started after a player had already joined). A quick and mostly correct solution is to assume that the player logged in right after the start of the day. 

So when I see a logout event I write *LatestEnd* in the struct and calculate the duration: *LatestEnd* - *LatestStart*. And add it to the *DurationOnServer* field. 

```go
current, exists := playTimes[playerName]
if !exists {
    midnight := time.Date(t.Year(), t.Month(), t.Day(), 0, 0, 0, 0, time.UTC)
    current = &playTime{
	PlayerName:  playerName,
	LatestStart: midnight,
    }
}

current.LatestEnd = t
current.DurationOnServer += t.Sub(current.LatestStart)

playTimes[playerName] = current
```

# Persistence

I chose (for now) to simply write json files every day holding individual *readablePlayTime* structs. I added a *playTimeDayLog* struct as a wrapper, as well. You might wonder why I'm not reusing the *playTime* struct for serialization. It's a problem with *time.Duration*, it is an *int64* and stored as nanoseconds. That leads to a big ugly number in the json file, whose actually meaning is hard to grasp.

```go
type playTimeDayLog struct {
        Day       time.Time           `json:"day"`
	Playtimes []*readablePlayTime `json:"playTimes"`
}

type readablePlayTime struct {
	PlayerName         string        `json:"playerName"`
	LatestStart        time.Time     `json:"latestStart"`
	LatestEnd          time.Time     `json:"latestEnd"`
	DurationOnServer   string        `json:"durationOnServer"`
	DurationOnServerNS time.Duration `json:"durationOnServerNS"`
}
```
> I actually spend some time to come up with a more clever way, but haven't without sacrificing the *+ - Operator*; which felt like a bad idea.

In the *main()* function I use a variable to track the current day. If a log event occurs on another day, I loop over all known play time entries, and close still open ones: putting *LatestEnd* date on close before midnight and adding to the total DurationOnServer. 

```go
func main() {
    ... 

    current := time.Now()
    playTimes := make(map[string]*playTime)
    
    for logLine := range logTail.Lines {
        t := time.Now()
        ...

        //comparing based on year in day
	if current.YearDay() != t.YearDay() {	
            fixEnding(playTimes, current)
    
            writeOutDayLog(playTimes, current, *timeLogPath)
	    playTimes = make(map[string]*playTime)
	    current = t
        }
    }
    ...
}


func fixEnding(playTimesMap map[string]*playTime, t time.Time) {
	beforeMidnight := time.Date(t.Year(), t.Month(), t.Day(), 23, 59, 59, 999999999, time.UTC)
	for playerName, playTime := range playTimesMap {
		if playTime.LatestStart.After(playTime.LatestEnd) {
			playTime.LatestEnd = beforeMidnight
			playTime.DurationOnServer += beforeMidnight.Sub(playTime.LatestStart)

			playTimesMap[playerName] = playTime
		}
	}
}
```

Then I write out the json file, update the current day and empty the map.

```go
func writeOutDayLog(
    playTimesMap map[string]*playTime, 
    currentDay time.Time,
    interrupt bool, 
    p string,
) {
        //loop over the collected playTimes and create "readable" ones
	var pt []*readablePlayTime
	for _, v := range playTimesMap {
		rpt := &readablePlayTime{
			PlayerName:         v.PlayerName,
			LatestStart:        v.LatestStart,
			LatestEnd:          v.LatestEnd,
			DurationOnServer:   fmt.Sprintf("%s", v.DurationOnServer),
			DurationOnServerNS: v.DurationOnServer,
		}

		pt = append(pt, rpt)
	}
        
        //create the wrapper struct
	l := playTimeDayLog{
		Day:       currentDay,
		Playtimes: pt,
	}

        //format it a little bit, 2 space indent
	j, _ := json.MarshalIndent(l, "", "  ")

	var filename string
        //if caused by an interrupt include hour:minute:second in the timestamp
	if interrupt {
		filename = fmt.Sprintf(path.Join(p, "playtime_log-%v-interrupt.json"), currentDay.Format("2006-01-02T15:04:05"))
        //otherwise only the day
	} else {
		filename = fmt.Sprintf(path.Join(p, "playtime_log-%v.json"), currentDay.Format("2006-01-02"))
	}

	ioutil.WriteFile(filename, j, 0644)

}

```

# Interrupts

In case of interrupts, e.g. the service is stopped, restarted, failed, whatever ... I would loose the current days data, because it's only in memory yet. To mitigate that issue for now, I hooked into the OS notify system and write out the current data. The secound part of the puzzle was already visible in the *writeOutDayLog* function, which has a toggle indicating it's an unregular (interupt) write out or not.

```go
//write out the current data on sigint/sigterm
c := make(chan os.Signal)
signal.Notify(c, os.Interrupt, syscall.SIGTERM)
signal.Notify(c, os.Interrupt, syscall.SIGINT)
go func() {
	<-c

	fixEnding(playTimes, current)
	writeOutDayLog(playTimes, current, true, *timeLogPath)

	os.Exit(1)
}()

```

# Daemon

To run the program on the server I statically compile everything to a single executable:

`CGO_ENABLED=0 GOOS=linux GOARCH=amd64 go build -ldflags="-w -s -extldflags '-static'" -a`

As well as create and register a simple *systemd* service file.

```
[Unit]
Description=Minecraft Players PlayTime logger

[Service]
ExecStart=/root/mine-watcher --outputLogPath="/root/playtimes/" --minecraftLogPath="/root/data/logs/latest.log"

[Install]
WantedBy=multi-user.target
```

```bash
sudo mv mine-watcher.service /etc/systemd/system/
sudo systemctl enable mine-watcher.service
sudo systemctl start mine-watcher.service
```

That's it for now. In a future version (maybe even article) I I might create a simple web server, summarizing the play times. This might become even useful for the parents of my kids' friends.