Crashed WUI due to abbreviate_time in common.py

[rycee]

I've been having a few difficulties with a Tahoe-node I'm running. It produced a long error message whenever I accessed the /storage web path.

With a bit of sleuthing I tracked the problem down to ​common.py:93. The line

return "%dus" % (1000000*s)

seems to assume that s an integer but s actually is a float as can be seen earlier in the function. Changing this line to

return "%dus" % (1000000*int(s))

fixed the issue for me and /storage now shows without problem.

Looking through the other functions in the file it appears as if there are other cases of %d being used together with float values. Perhaps they can also cause problems?

I cannot produce a stack trace at this time since the node is currently in use but I can try again later if there is a need for it.

[zooko]

Let's fix this for v1.7.0.

[rycee]

I have tried to reproduce this problem and have been unsuccesfull. I think what happened is that the computer clock had for some reason gotten very much out of sync prior to the previous pass by the expire crawler. Eventually the time got synchronized over ntp and the reported problem occurred. This should have caused the abbreviate_time function to recieve a very large negative number. This seems to rhyme well with the following python session:

>>> "%d" % (1000000 * -1234567891234.0)
'-1234567891233999872'
>>> "%d" % (1000000 * -12345678912345.0)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
TypeError: int argument required
>>> "%d" % (1000000 * int(-12345678912345.0))
'-12345678912345000000'

That is, python will handle floats as well as can be expected together with %d, as long as the number is small enough.

So, in conclusion, this error should be quite rare indeed and I would not protest if this bug report is closed as WONTFIX or similar. It may possibly be interesting to make the code a bit more robust in these cases, I would have appreciated a "check your clock dummy!" message :-)

[zooko]

Tahoe-LAFS is intended to function correctly in all respects even if the system clock jumps around to arbitrary values [*].

So instead of closing this as wontfix, we'll write a unit test that shows this bug. Thanks for tracking it down! If you want to help out with the next step, report to us what version of Python you have, because my version of Python doesn't behave like yours:

Python 2.6.1 (r261:67515, Feb 11 2010, 00:51:29) 
[GCC 4.2.1 (Apple Inc. build 5646)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> "%d" % (1000000 * -1234567891234.0)
'-1234567891233999872'
>>> "%d" % (1000000 * -12345678912345.0)
'-12345678912344999936'
>>> "%d" % (1000000 * int(-12345678912345.0))
'-12345678912345000000'

[*] Not that it currently does so, but I consider it to be a bug that it exhibits random misbehavior when the gettimeofday(2) gets kicked by ntp or by a sysadmin, due to Tahoe-LAFS relying on the ordering of events in the Twisted reactor and Twisted using the result from gettimeofday(2); see ​http://twistedmatrix.com/trac/ticket/2424

[rycee]

Replying to zooko:

If you want to help out with the next step, report to us what version of Python you have, because my version of Python doesn't behave like yours

The session of comment 2 was taken with the following Python:

Python 2.5.5 (r255:77872, Apr 21 2010, 08:40:04) 
[GCC 4.4.3] on linux2

This is the stock Python of an amd64 Debian Sid installation. The error of the bug report occurred on a 32bit Lenny box and on this box I get the following result:

Python 2.5.2 (r252:60911, Jan 24 2010, 14:53:14) 
[GCC 4.3.2] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> "%d" % (1000000 * -1234.0)
'-1234000000'
>>> "%d" % (1000000 * -12345.0)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
TypeError: int argument required

Thanks for following up on this bug!

[rycee]

Just a note that I cannot reproduce the "int argument required" error with Python 2.6.5 in Debian Sid. So I suppose it is something specific to Python 2.5?

[zooko]

Yeah I suppose it is a bug in Python 2.5. We have Python 2.5 buildslaves, so if you write a unit test that exercises this bug then we can add it to the test suite and know that it is fixed on our supported platforms.

[zooko]

This just needs a simple unit test.

[jacoblyles]

Added unit test to show bug in allmydata.web.common.abbreviate_time in python 2.5

[zooko]

jacoblyles:

Thanks for the patch! Are you sure that your patch will trigger the bug, though? It looks like your patch will cause common.abbreviate_time() to be called with the argument -123000, which is an integer. common.abbreviate_time() will then multiply it by 1,000,000, making it be -123,000,000,000 As far as I understand, the bug shows up only when the argument is float instead of integer, and only when the argument is less than about negative 10 billion, and when the Python version is Python 2.5. If you could change your test to pass a float then we can run the test on our Python 2.5 buildbots.

[jacoblyles]

Yes, this will trigger the bug. common.abbreviate_time() casts its input to a float at ​common.py:82. I have run the test on my own machine with python 2.6 and python 2.5 to confirm that it fails with 2.5.

[davidsarah]

Test looks good to me.

[jacoblyles]

This patch fixes an error with interpolating float values in "%d" format strings in python 2.5

[jacoblyles]

I've attached a patch that should fix the problem. The magic value to break "%d" in Python 2.5 is a float of size 2.0³¹ or larger. I replaced "%d" with "%.0f"

[davidsarah]

Fixed by d3e6e15e23bcc93f. Not sure why this wasn't auto-closed by trac.

[zooko]

jacoblyles: thanks! A couple of things to note for future reference:

1. I re-edited your patch description to be a little more detailed and to have the string "fixes #1055" in it. See also Patches for examples of good patch descriptions.
2. David-Sarah is adding unit tests of the adjacent formatting code in addition to the unit test you added for the one that your patch fixed.
3. It might be good to bundle the tests together into the fix-it patch. At least in this case it would have prevented me from forgetting to apply your tests. :-)

[davidsarah]

Test patch committed in e276050d5ab2a937. It turned out that the instances of %d in abbreviate_rate and abbreviate_size could not have overflowed (and float underflow is not a problem here), so I just committed the original attachment:WHAT.dpatch​.

[zooko]

Oh, and another thing: we need a snippet for NEWS to describe this change.