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-Timeis 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-Timeis converted toYY-MM-DD hh:mm:ssformat 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!
ps. Next year this bug will say 1978 …
