Welcome to the first in a few blog posts I’ve decided to write about the challenges faced in bringing the MCJukebox 2.0 update out into production. It’s focused mainly around challenges as a developer, and in this post, the main talking point is the difficulty in providing accurate time synchronisation.
The reason behind needing all of this was to provide our new “shows” functionality. Users in the game can setup a show and we’ll send timestamps between clients and the server to ensure music is always in sync. As a result, a time offset of just a few seconds could really show to an end user.
Our main objective with this part of the codebase was to get the current time in Javascript, independent of any time-zones, and within a high level of accuracy. When I started out, although I knew dealing with time can be tricky, I really did think this would be as easy as getting the Unix epoch time.
This did indeed solve our first issue, as by using the number of milliseconds since the 1st January 1970 UTC, no matter where you were located on the globe, we wouldn’t need to worry about geographical location. For sure, clocks occasionally go out of sync, but I was under the impression that computers had advanced enough to synchronise time over the internet and prevent this.
For anyone who hasn’t looked into it, computers use a time protocol called NTP. It’s a complicated mathematical system which pings an array of servers in order to get the most accurate timestamp it can at any given point. The problem is, while some computers do this flawlessly, I found that many of MCJukebox’s users either had this disabled by default or that although the feature was enabled, their computer hadn’t ever run the process.
In order to solve this, we’ve made a very basic and less technical protocol which uses just one server and gets a timestamp accurate to a small fraction of a second. Millisecond level accuracy would have been great, but the development effort and infrastructure required meant this just wasn’t worth it, especially considering the use case.
The way it works is quite simple - the web client sends a request to our servers for the current Unix timestamp, and also logs when this request was sent. Our server responds with a timestamp, which is accurate to the nearest millisecond at the time the packet is sent. The web client then works out how long the response took by working out how long has elapsed between sending a request and receiving the response. Dividing this by two gives a rough approximation of how long the response took. This can then be added onto the Unix time to work out roughly where we are now. This is turned into an offset parameter, and we’re good to go.
The system isn’t perfect, and we’ve already run into our first issue. One user had their time offset by a full hour without realising and this caused issues as we weren’t prepared for such huge numbers.
To summarise, if you have assumptions about the environment of your clients, you’ll be wrong. You can’t rely on them for anything, and wherever possible, you’ll need to do work again which could possibly have already been done but might not have been. Allowing 90% of users the full experience isn’t enough.
Note: This blog post is aimed at developers. You're free to read it, but it does get quite technical.
Most developers would agree that having access to logs on your production server is to great benefit, but it seems like a guide on how a good logging system should work doesn't exist out in the wild. Today I want to take a quick look at how I went from scrolling endlessly on a console in screen, to using Node.JS libraries to provide excellent support as well as the option to expand out in the future.
When I first launched my application, and much like with most projects, I wasn't sure if the idea would take off or if I'd even be working on it in the next few weeks. MCJukebox was running on a shared VPS (from the OVH SSD range) and logs were basic. I tried to avoid them, as it was easier to recreate the issue locally, but if I did need to take a look at the logs I simply scrolled up on the screen until I found the request in question. It worked, but there were some serious downsides. It wouldn't scale, as I was working rather than the server. I also had to assume that something would end up in the console, and if I hadn't logged enough information then my chances of fixing the bug would rapidly decrease. I needed something better and after some research, settled on Bunyan.
To describe it simply, Bunyan allows for logs to be sent with different priorities and you can define different streams which listen out for only logs above a certain level. For example, the setup we use sends everything above the 'info' level, including error and fatal straight to stdout. Here's a look at starting up the application, with Redis intentionally blocked.
This makes finding out what has gone wrong in production really easy - just open up the screen and all you'll see is what matters. We've also configured two additional streams. The debug.log file stores everything which has happened in the last three days, in a very verbose form so that if a customer contacts us with an issue we can take a look at exactly what happened. I'm also personally a fan of Pushover, an app which sends me push notifications using an API, and so another stream will ping my phone if anything enters the 'error' level.
We've got just one more trick up our sleeve, and this is what has really helped us out in diagnosing issues once a customer contacts us. Bunyan has the concept of a child logger, which uses the same stream destinations but has additional properties added automatically each time you send a log. On all of our servers, we use a small Express middleware function to add a random request ID to a new logger assigned to each incoming request.
app.use(function(req, res, next){
req.log = log.child({req_id: uuid.v4()}, true);
req.log.debug({req: req});
next();
});
By doing this, we're able to identify all of the logs associated with a particular request just by searching via. an ID. Bunyan also saves all of it's logs in JSON format, so searching is really easy in pretty much any software. Getting the 'req_id' field back is as simple as doing 'req.log.fields.req_id' - we then show this in the GUI if something has gone wrong, so that the customer can do the work for us and tell us where to look. We log as much as we can about each request: the cookies present, the request URL. What's great is that really important information, like timestamps, are added by Bunyan automatically.
Hopefully from this you understand a bit more about what great logging is - your logs need to be accessible (so you can view them whenever you wish), friendly (so you can actually use them to your benefit), and verbose (not always, but you never know when that bit of additional information may be the key to squashing that nasty bug.
If you have any questions about the setup, or would like to make a suggestion, feel free to tweet me @oliverdunk_ - I'll try and reply as soon as possible.
Chances are, when taking a look at our site you noticed the logo which I just launched. Before I say anymore, I think you'll agree with me that it looks pretty groovy! To make a long story short, it was created by Craftilldawn, a brilliant graphics design team with whom it was a pleasure to work with. Be sure to give their site a visit, but first, here's the story of how our logo came to be.
Like all good logos, I started wanting a brand identity that people could associate with the product. It had to link somewhat to our name, and my friend Lewis put together a quick draft which you can see below. 
It certainly wasn't perfect, and I knew that there was a lot of work to be done, but it served well as the initial prototype and helped me to communicate with others about what I was looking for. My main concerns were that the logo needed to look more modern, have a bit more of a personality and should work better with the rectangular layout we'd be using on the site.
It was at this point that I made contact with Craftilldawn. While they generally only work on much bigger projects, they offered to give us a helping hand and quickly sent over the first draft for what they were thinking of. For an initial sketch, I was quite impressed. 
From here on in, it was a case of letting their team work their magic! I wasn't a fan of how the two letters joined together, so we agreed to take this out of the final product and they got to work. Within a few days, I received the message I had been waiting for and our logo was complete.
Hi there, and welcome to our brand new site! I've always wanted to make sure that MCJukebox is accessible, and the launch of our new site is certainly a step in the right direction. Here, we'll be able to post important information regarding MCJukebox as well as promote new features as and when we launch them.
If you don't know me, I'm Oliver and I'm the creator of Jukebox! I currently work on all of the development myself, so I'll be keeping this blog updated with insights into how I built the service and the challenges we've overcome. If development is your kind of thing, this site is written in pure HTML/CSS and rendered using the Jekyll engine.
Well, if I don't stop writing I'll never be able to launch this site so I should probably go get a move on! Thanks for using Jukebox, and we hope that you enjoy what we've got to offer!