Monitoring Playtime on Your Minecraft Server with Go - Level 1

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

For actually running the game I'm using the great Docker Minecraft image from here. 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. 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:

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:

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.

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:

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

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.

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.

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.

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.

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.

//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

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.