For the 3rd year, Redbrick was a sponsor for BattleSnake, a friendly (and intense!) competition held every year in Victoria, BC. It's a fabulous way to hone your skills and win prizes geared toward your skill level.

The task is to build a program that plays in a multiplayer version of the classic arcade game, Snake. If you choose, you can also have it play in one-on-one Bounty Snake challenges.

This year, I worked on the next generation Redbrick's first bounty snake, Son-of-Robosnake. It's a child of 2017's Robo. I left algorithm improvements to the original creator Scott and tackled a static post-mortem review tool. I wanted a way to inspect any game we played, move-by-move. This blog post is a semi-technical, high-level review of how the logger was approached, developed, and its remaining work.

Existing Review Tools

The official game board allows you to review up to 20 moves of the latest game. There was an update that extended this length but unfortunately wasn't available by tournament start. I wanted something stable and longer.

Further, I wanted to be able to review any game, not just the one still on the screen. We also noticed on tournament day that the replay was not deterministic. In a game we lost due to server timeout, we hit "replay" to see what happened but couldn’t recreate the loss! In the replay, our snake took a non-losing path. I needed something accurate.

Similarly, Cory Binnersley created the Snakedown test server that included full replays and matchmaking against anyone. Part of the code was available on Github, but I couldn't be sure Binnersley wasn’t doing something mischievous behind the scenes, something like mining our snake behavior. I wanted an exclusive tool (and those bragging rights).

Requirements

Robosnake already had some logging. However, they were only turned on during development. Nginx’s built-in logging was used for human-readable messages. Great for experimenting, too harsh to be used in production. Lua was specifically chosen for its performance, and I/O logging was stealing the benefits. This meant for real battles against real enemies, an efficient way to record gameplay was needed.

To avoid expensive I/O, I turned to non-blocking socket logging enabled by Cloudfare's Lua-resty-logger-socket library. The library allows UDP transport, also avoiding any expensive handshaking via standard TCP connections to the socket. Ultimately, logging is a "nice-to-have" feature and dropping a specific turn's data set was an acceptable loss.

In summary, my dream logger needed to satisfy the following requirements:

• Must not significantly impact snake performance
• Able to reproduce any game Easily integrate with snake's behavior Have an informative visual interface
• Display game state info such as who's playing, winner, length
• Display turn metrics like snake health and length

Socket Logging: The first thing the snake’s socket output needed was a recipient socket server. Thus, the first job was setting up Fluent-d and configuring message destinations. I created three tags: DEBUG for human-friendly messages, INFO for easy-to-parse script messages, and REPLAY for game metainformation. DEBUG and INFO messages would both write to generic X.luasnake.log files.

These files would populate quickly, with messages from a single game being written into multiple files. Conversely, REPLAY would write to exclusive X.replays.log files. These files would fill up significantly slower with only one entry per game, the composite game key needed to look up relevant INFO and DEBUG logs.

Creating a Composite Game Id

While socket writing logic was solved pretty quickly, lookup logic took some work. A few issues immediately slithered in:

• Game ids were not unique. They represent the board instance, created once.
• Snake ids were not unique per game. They seem to be attached to a game instance.
• Together, they are not sufficient as a composite key. Son-of-Robosnake could have several challengers at once with the same game and snake ids.

Through the use of nginx’s shared context, a game start timestamp was declared on turn zero of every game. That, combined with the game id and our Robosnake’s snake id, created a sufficiently unique lookup key we could use for the full game.

Logging Useful Information

If you poke around in Son-of-Robosnake’s open-source code, specifically the heuristic function in the algorithm.lua, you can see there’s plenty of ngx.log statements. An issue with those logs, however, is that they’re printed for every node/recursion level Robosnake is evaluating.

Converting those into script-friendly parsing messages would give plenty of insight into how a decision was made, but this logger needs to focus on who did what. Instead, most statements were made from util.lua in util.buildWorldMap. This function effectively recreated the game board into something Robosnake could use.

For each food, snake head, snake body, and snake tail coordinate given by the BattleSnake server, a line was written into the logs with at least who, what, and the coordinates. Meta information about the players including snake name, length, and health was also written at least once per turn.

Replaying a Game

The first phase of replaying a game is figuring out which game a user wants. This step needed to read all composite keys written to the X.replay.log files, and give them to the user as a choice. To keep things simple, the replay tools simply read every file line-by-line and pretty-printed to the console. However, after choosing a game key, the replay needed to search N X.luasnake.log files. In each file, there could be M number of lines with a matching key.

The tools then need to compile the matches into an iterable list of turn-based data sets, including all food, snake positions, snake health, and snake length. Finally, these turns needed to be written in an easy-to-understand visual format. Inspired to have a little fun with multiprocessing, searching N files was parallelized, and data was kept out-of-memory until as late as possible to get the most efficient returns.

Essentially, an active processor received one small chunk of one data file and filters each line. The cumulative output from all processors was a jumbled, out-of-order list of logs needing to be organized into turns. Any sorting issues were sidestepped in step 2 where an empty array was created of the same size as the number of moves taken in a game.

Then, as each log line was processed, it was indexed into the array at its turn number. The most complicated parts of the final step - creating a visual output - was avoiding index errors and finding Unicode characters that clearly distinguished different parts of the game board. With every turn data set, a 2-D empty board array was created, then food and snakes added at their matching (x, y) coordinates. Snake health, length, and turn count were output last, above and below a pretty-string version of the board.

One limitation of the replay tool was that they were developed before the latest /end endpoint was created and integrated. This meant the logger could only get up to N-1 game moves - the move a snake died was the one I couldn’t have. The reviewer is forced to assume how the snake died and who won.

Output and Final Results

On a developer machine, it worked great. Here’s a sample output:

The top of the screen listed the timestamp, game board id, and Robosnake snake id. The user was prompted to choose a game. The instant replay allowed various ways to proceed through the match and showed food as solid dots and various snake parts as different icons for Robosnake and enemy snakes. In classic BattleSnake fashion, however, we couldn’t get fluent-d working in time on production day for the tournament.

What I’d like in the future, three things:

Performance testing

I think it would be a fun experiment to speed test response times between no logging (optimum), NGX logging (original), and socket logging. This entire project has been based on the assumption that we could get replay logging for free, or very cheap. I was planning on doing this in the morning of tournament day while everyone diligently worked, but code freeze on a broken logger meant I was out of luck. I’d also like to do a more in-depth analysis on the total number of calls made.

Request Hooks

I ran into a lot of merge conflicts working on this. Neither rebasing or merging in the master were friends of mine. Being away from it for a few days now, I think it would be cool to capture a copy of the request body at the very start of every turn and punt it to a separately hosted logging service.

All the transformation and log statements would happen there instead of being meshed in with the core Robosnake code and eliminate all human-friendly debug statements. This would reduce the number of calls to 1 for each of the /start, /move, and /end endpoints. It would also give Robosnake full freedom in changing its algorithm without warning the logging developer.

Doing this would effectively allow the logger to be spun off into its project, open-sourced and maintained separately dependent only on changes in the official BattleSnake server.

Better Visual Output

I’m no designer, but I’d like to test and develop the visual output to work with multiple snakes. Rather than unique Unicode characters for every snake head, body, and tail, I’d like to introduce some colors! There’s always the option of developing a client for the browser, but I enjoy the simplicity of just using a terminal.

Summary

Redbrick will be coming back for 2019’s BattleSnake, and with any luck, this logger will be in place. Overall this project was an interesting venture into uniqueness requirements, performance, and multithreading.

FAQs

Help! I can’t find the socket logging code in the Redbrick’s open source repo!

We couldn’t get logging to work in time for the tournament, so we isolated it to its own branch, Socket_logging_module. You’re in the right spot if you can see ./logger.lua and ./replay.py.

Who are you?

I’m Erika, Software E.I.T., and developer at Redbrick. Check out this site to read up on what Redbrick does and our latest projects, or follow me on Twitter for random retweets of tech stuff. If you have any questions, send me a DM there.