Fixing out of sync server times

In My server times are out of sync! I showed a formula to smooth the time differences between multiple servers when working in a collaborative environment, but I started not to believe the results so set out to validate them.

Development environment

I use cloud9 for development and very nice it is too. However, I’m working on push notification for Ephemeral Exchange where multiple servers are involved in writing and monitoring changes, and I’ve discovered that their server times are very poorly synchronized.

For development, my push and api servers are on cloud9 and the redis servers are on Google compute engine in a docker container. For production, the api server is on Google App engine flexible environment docker container, and the push and redis servers are on Google compute engine, also dockerized.

The problem

All of these components have different ideas of what the time is. I use the API server as master of all times – so when an item is created the creation time is that of the api server. The push server gets to know about changes by subscribing to a redis channel which publishes notifications when it detects a change.

A client subscribes to push notification via the API. If the api server is not at the same time as the push server then notifications coming from redis might not be selected because  if the push server’s time is ahead of the api server’s time, it could look like they were made earlier than the subscription actually happened.

On Cloud 9, I found there was a 24 second discrepancy between the push and api server. Here’s the time on two servers checked at more or less the same time (I had to swap between tabs which took a few seconds).

Push server

$ date

Sun May  7 08:52:47 UTC 2017

Api server

$ date

Sun May  7 08:53:05 UTC 2017

A solution

The most accurate way would have been to include a timestamp on each modification in each item, and read it from redis on each change notification. That would have worked, except that

• Because I am monitoring deletes and expirations as well as updates, the items would have been deleted by the time the notification came.
• Some Redis operations used such as ZADD don’t give the opportunity to add a timestamp.
• I would not be able to monitor changes made by means other than the API.

Here’s what I came up with in the end

1. The push server publish periodic requests for a time synch using a redis channel.
2. The api server subscribes to that channel and reacts to messages by writing an item to redis
3. The push server is subscribed to redis changes, and receives a notification when a time sync item is written

This gives me the following information

Using the push server clock

• now  – when it has received a push notification for redis
• requestAt – when the push server asked for a timesynch check
• now – requestAt – elapsed time for the entire process

Using the api clock

• writtenAt – when the api server received the request.

Deducing

• If the clocks were at the same time, then writtenAt would be, requestAt + the network delay (the maximum of which will be approximately (now – requestAt) / 2
• The clock time error should be writtenAt – now – (now – requestAt)/2

Let’s plug in some observed numbers, (which actually came out extremely consistently)

So this tells me the api server is running 24.2 secs ahead of the push server – compare that with my manual observation from earlier, and adjusting for the few seconds it took me to change tabs between them that looks about right.

Push server

$ date

Sun May  7 08:52:47 UTC 2017

Api server

$ date

Sun May  7 08:53:05 UTC 2017

Using that offset

Now I know that each event I log on the push server typically happens (API server time) about 24 seconds from now (Push server time), so I simply log the event with the adjusted time. I’ll keep that timeoffset up to date by applying the formula from My server times are out of sync! to smooth it out and all should be well.

Does it work?

Here are some observations comparing the real creation time stamped in the record, and the estimated creation time using this method – typically less than 20ms out – so that’ll do just fine.

The code

ns.synchTime = function() {

    // I'm using recursive setTimout rather than setInterval
    function sched () {
      pub()
        .then(function() {
          return Useful.handyTimer(ns.settings.redisSyncFrequency);
        })        
        .then(function() {
          sched();
        });
    }
    
    // publish a timesync request    
    function pub() {
      return redisSyncPub_.publish(ns.settings.redisSyncChannel, JSON.stringify({
        requestAt: new Date().getTime(),
        syncId: syncId,
        expire:ns.settings.redisSyncFrequency * 2
      }));
    }
    
    // the first one will generate misleading initialization times, so it'll be ignored
    pub().then(function () { sched() });

  };

else if (db === st.db.ts && method === "set" && message.slice(0, st.syncPrefix.length) === st.syncPrefix) {
            ns.synchTimeUpdate (message);
          }

 ns.synchTimeUpdate = function (message) {
    
    var now = new Date().getTime();
    
    // will look something like this '__keyevent@6__:set sy-.1bfgvorjj.1494145143663'
    var s = message.split (".");
    var sId = s[1];
    
    // check this is for me
    if (sId !== syncId) {
      console.log ("received a synch not for me", sId , syncId);
      return Promise.resolve(null);
    }
    
    // now get the item so the times can be processed
    return redisSync_.get (message)
      .then (function (res) { 
        // convert to an object
        var ob = Useful.obify (res).ob;

        // end to end time
        var latency = (now - ob.requestAt);
        
        // smooth the observations
        
        // ignore completely outlying latency as it could be a network blip
        if (latency < ns.settings.redisSyncNetWorkOutlier && (!timeLatency || latency < timeLatency * 10) ) {
        
          // api server is golden for time,

          // ignore the first one because it'll be misleading since it probably did some initialization
          if (timeNobs) {
            timeLatency = timeNobs > 1 ? latency * smooth + timeLatency * (1 - smooth) : latency;
            var offBy = ob.writtenAt - now - timeLatency/2; 
            timeOffset = timeNobs > 1 ? offBy * smooth + timeOffset * (1 - smooth) : offBy;
          }

          timeNobs++;
        }
        
      });
    
    
  };

ns.synchInit = function () {

  // the push server will ask me to connect 
    return redisSyncSub_.subscribe(ns.settings.redisSyncChannel)
      .then(function(count) {
        if (!count) console.log ('failed to subscribe to ', ns.settings.redisSyncChannel);
        // every time I get one of these, I'll write something
        return redisSyncSub_.on('message', function(channel, message) {
          var ob = Useful.obify (message).ob;
          ob.writtenAt = new Date().getTime();
          return redisSync_.set ([ns.settings.syncPrefix,ob.syncId,ob.writtenAt].join("."), JSON.stringify(ob),"EX", ob.expire)
          .then (function (r) {
            if (!r)console.log ("failed to write sync item",r,ob.syncId);
          });
        });
      });
  };

 ns.logEvent(method, message, "redis", now + timeOffset );