1977 was 136 years ago in radiator bug land

Radius is this thing that allows one system that manages network to tell another system that manages accounts and stuff how much stuff various people are using.  We get radius data from our upstream people about data and stuff moved.  This is cool.

Well, it was cool, but today (as many days previously) they sent us the following radius accounting packet – an interim update – that says that data and stuff happened in 1977 that we should be interested in:

Accounting-Request Id 114       192.168.21.135:54663 -> 192.168.18.2:1813       (3 packets)     +0.001
User-Name = "suepearson@realm"
X-Ascend-PreSession-Time = 2
X-Ascend-Connect-Progress = LAN-Session-Up
Acct-Input-Octets = 2520292297
X-Ascend-Session-Svr-Key = "835AE85C"
X-Ascend-Pre-Input-Octets = 86
Framed-IP-Address = 172.29.184.9
NAS-Port = 1466813801
X-Ascend-Pre-Output-Octets = 69
Service-Type = Framed
Acct-Authentic = RADIUS
Acct-Session-Time = 527348
NAS-Port-Id = "5/1/0/1001.102"
X-Ascend-Data-Rate = 215040000
Calling-Station-Id = "06914625488"
Acct-Status-Type = Interim-Update
Acct-Output-Gigawords = 2
NAS-IP-Address = 10.31.27.72
Event-Timestamp = "Jul 21 1977 10:19:42 SAST"
Acct-Input-Packets = 15266036
NAS-Port-Type = Ethernet
Acct-Delay-Time = 4294967295
X-Ascend-Xmit-Rate = 215040000
X-Ascend-Pre-Output-Packets = 5
Acct-Input-Gigawords = 1
Acct-Output-Octets = 540902857
Acct-Output-Packets = 16361715
Acct-Session-Id = "5/1/0/1002.102_33357671"
Framed-Protocol = PPP
X-Ascend-Pre-Input-Packets = 4

We received that at 2013-08-27 16:55:59 SAST, also known as 1377615359 in unixtime. (I did fudge this packet information to make it semi-anonymous, after radsniff -x printed it with wonderful details.)

According to the packet we received, our friendly upstream server sat on this packet for 136 years before sending it to us, which is interesting, considering that 21 July 1977 was only around 36 years ago. What?!

The first thing I noticed here, after the 1977 was that this attribute is WRONG:

Acct-Delay-Time = 4294967295

What is that? Well, it’s “-1”. It’s what you get when you interpret “-1” as an unsigned 32 bit integer as a 32 bit signed integer. The sign bit is interpreted as 231, and that with all the other bits add up to 232-1. It’s just mathematics, don’t sweat.

So, the system is trying to tell us that something that happened didn’t happen 1 second ago, but will happen one second in the future. This is just your classical non-causal system, nothing to see, please move along, because you don’t want to get caught up in that wormhole back to 1977. So I pondered this and got nowhere, until I wrote the numbers together …

Aha!  36 … 136 … notice something?  100 years!  So, how about this: the Acct-Delay-Time was converted to years, months, days, hours, minutes, and seconds, and the 136 years was truncated to 36 years.  36 years ago, it was 1977.

That’s the largest part of the mystery solved.

So the bug is compound:

  • A clock of something generates timestamps 1 second in the future
  • Acct-Delay-Time is calculated as the difference of timestamps between that clock and another clock, and that is suddenly negative, -1
  • That (signed) number is stored in a 32 bit field as a 32 bit unsigned integer, and becomes 4294967295
  • For the date calculation, the Acct-Delay-Time is converted to YY-MM-DD hh:mm:ss format which might have been okay, but the number is an insane value, so …
  • 100 years is chopped off, changing 136 years to 36 years
  • 2013 – 36 years = 1977. Ta dah!

I suspect this is a bug in radiator, although it might be in a java app that touches the data. If they had just stuck to unixtime, this y2k style bug would not have happened.

I hacked a script to do the more horrible parts of the maths, and it solved the mystery to within 8 minutes, printing out:

Tue Aug 27 17:37:54 ~ $ python x.py
4294967295 seconds in yyyy-mm-dd HH:MM:SS is 136-03-12 06:28:15
Local time less (evil-100years) = 1977-07-21 10:27:44

Here’s the script — rather hacked:

#! /usr/bin/python

import time

localtimestamp = 1377615359
t={}
eviltimestamp = 4294967295
remainder = eviltimestamp
month_days=(31,27,31,30,31,30,31,31,30,31,30,31)

t['yyyy'] = remainder/(365*86400)
remainder = remainder % (365*86400)
t['mm']=1
for days in month_days:
if remainder<86400*days: break
t['mm']+=1
remainder-=86400*days
t['dd']=(remainder/86400)
remainder=remainder % 86400

t['HH']=(remainder/3600)
remainder=remainder % 3600
t['MM']=(remainder/60)
remainder=remainder % 60
t['SS']=remainder

t['yy']=t['yyyy'] % 100
stamp = '%(yyyy)02d-%(mm)02d-%(dd)02d %(HH)02d:%(MM)02d:%(SS)02d' % t
print '%d seconds in yyyy-mm-dd HH:MM:SS is %s' % (eviltimestamp, stamp)
print 'Local time less (evil-100years) = '+\
   time.strftime('%Y-%m-%d %H:%M:%S', \
    time.localtime(localtimestamp- \ 
    (eviltimestamp-(100*365+24)*86400))); # 24 leap years per century ...

I feel like a little boy with a fist full of sand. Yeah!
Keep Calm
ps. Next year this bug will say 1978 …

This entry was posted in Stuff and tagged , , , , , , , , , . Bookmark the permalink.