Opened 12 years ago

Closed 12 years ago

Last modified 12 years ago

#32 closed defect (fixed)

Exception when calling FTPHost.close after synchronize_times (Windows only)

Reported by: schwa Owned by: schwa
Priority: critical Milestone: 2.4.1
Component: Library Version: 2.4
Keywords: exception, lrucache, Windows Cc:

Description (last modified by schwa)

Running the code

host = ftputil.FTPHost(hostname, user, password)

triggers an exception

Traceback (most recent call last):
  File "g:\test\", line 13, in <module>
  File "g:\test\ftputil\", line 896, in __exit__
  File "g:\test\ftputil\", line 253, in close
  File "g:\test\ftputil\", line 117, in clear
  File "g:\test\ftputil\", line 100, in resize
    self._cache.size = new_size
  File "g:\test\ftputil\", line 186, in __setattr__
    del self.__dict[lru.key]
KeyError: '/htdocs/new/_ftputil_sync_'

with Python 2.6.1. This happens on Windows, but not under Ubuntu Intrepid.

(originally reported by Peter Stirling)

Attachments (3)

heapq.patch (585 bytes) - added by schwa 12 years ago.
Patch against original from Python 2.6.1 on Windows
lrucache.patch (1.0 KB) - added by schwa 12 years ago.
Patch against to use the modified heapq module (676 bytes) - added by schwa 12 years ago.
Show differences of time.time vs. time.clock for Linux vs. Windows.

Download all attachments as: .zip

Change History (18)

comment:1 Changed 12 years ago by schwa

Description: modified (diff)
Status: newassigned

comment:2 Changed 12 years ago by schwa

I can reproduce the bug with Windows XP 3 and both Python 2.5.4 and 2.6.1. I can also confirm that it doesn't happen on Ubuntu 8.10 (Intrepid).

comment:3 Changed 12 years ago by schwa

Peter Stirling wrote:

After further inspection it appears that the windows python2.6 install doesn't include a dll of the compiled heapq module

/usr/lib/python2.5/lib-dynload/, on ubuntu python2.5

However when I tried to test the pure python version it decided to work, so there must be a bad dll somewhere.

To test this I made a copy of the pure python as, and commented out the code that replaces pure-python with the c versions (line 313). I then altered ftputil/ 43) to import from this new module, and when I run the test program I no longer get the exception.

comment:4 Changed 12 years ago by schwa

Running lrucache's tests also seems(*) to reveal the bug.

On Ubuntu:

$ python
<<class '__main__.LRUCache'> (0 elements)>
<<class '__main__.LRUCache'> (25 elements)>
<<class '__main__.LRUCache'> (24 elements)>
<<class '__main__.LRUCache'> (10 elements)>
<<class '__main__.LRUCache'> (10 elements)>
<<class '__main__.LRUCache'> (10 elements)>

On Windows:

<<class '__main__.LRUCache'> (0 elements)>
<<class '__main__.LRUCache'> (25 elements)>
<<class '__main__.LRUCache'> (24 elements)>
Traceback (most recent call last):
  File "", line 219, in <module>
    cache.size = 10
  File "", line 195, in __setattr__
    del self.__dict[lru.key]
KeyError: 46

(*) We don't know for sure if it's the same bug but I think it's highly likely.

Changed 12 years ago by schwa

Attachment: heapq.patch added

Patch against original from Python 2.6.1 on Windows

Changed 12 years ago by schwa

Attachment: lrucache.patch added

Patch against to use the modified heapq module

comment:5 Changed 12 years ago by schwa

Peter, I can't reproduce your workaround with the modified heapq module. When I run the tests in the modified lrucache module (i. e. no ftputil involved), on Windows I still get the traceback for the lrucache tests. Also the traceback for the original ftputil usage, on which this issue is based, remains.

For comparison with your patches I attached mine. (Please ignore the debug code further down in What have we done differently?

comment:6 Changed 12 years ago by schwa

Priority: majorcritical

I set the bug priority to critical because the problem might - in other contexts - apply to a lot of users of ftputil under Windows.

comment:7 Changed 12 years ago by schwa

I made an extra branch, issue32, to investigate the bug. There, I combined the test code into a single module which contains code to reproduce the bug. Just run the script to see if the bug occurs. I also added the outputs of this script when run under Windows XP and Ubuntu Linux.

My results so far:

  • When overriding time.time() in the test code with time.clock() by assigning time.time = time.clock at the start of the script the output on Windows and Linux is the same, i. e. the bug no longer shows.
  • When using time.time() but prepended with time.sleep(2.0) (see function time_)--but without the following print statement--the bug still shows up.
  • When using the normal time.time() without the sleep delay but with just a print statement (not even the print t currently in the code), the bug does not occur.

So there seem to be issues with the way the "time managements" in the two environments work. Maybe this is also related to my Windows investigations happening in a virtual machine (VirtualBox 2.2). This might also explain why the bug hasn't been reported earlier as most Windows users assumedly will run a native Windows and so won't come across the bug (that is, if it really is limited to the virtual environment).

Peter, does the Windows Vista you mentioned in another mail run in a virtual machine? If yes, can you run the test script in a native Windows, i. e. outside any virtual machine, and does the bug happen there?

comment:8 Changed 12 years ago by schwa

By the way, the Windows installation is a Windows XP SP3 (officially patched as of 2009-05-01 but without Windows Explorer 8). The Ubuntu Linux is version 8.10 with a kernel 2.6.27-11. The native OS runs on an AMD64 platform with a single processor/single core and without hardware virtualization support (this processor doesn't have any).

Changed 12 years ago by schwa

Attachment: added

Show differences of time.time vs. time.clock for Linux vs. Windows.

comment:9 Changed 12 years ago by schwa

I think I got to the root cause, described in this and this web page.

As one can check with the attached program, time.time measures more precise under Linux, time.clock under Windows. The output of the program under Linux is:

$ python time
[1241286942.7352209, 1241286942.7352271, 1241286942.73523, 1241286942.7352331,
1241286942.7352359, 1241286942.735239, 1241286942.7352419, 1241286942.735245,
1241286942.7352469, 1241286942.73525]

[6.198883056640625e-06, 2.86102294921875e-06, 3.0994415283203125e-06,
2.86102294921875e-06, 3.0994415283203125e-06, 2.86102294921875e-06,
3.0994415283203125e-06, 1.9073486328125e-06, 3.0994415283203125e-06]


$ python clock
[0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02, 0.02]

[0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0]


while on Windows it's the other way around:

>python time
[1241287016.0969999, 1241287016.0969999, 1241287016.0969999, 1241287016.0969999,
1241287016.0969999, 1241287016.0969999, 1241287016.0969999, 1241287016.0969999,
1241287016.0969999, 1241287016.0969999]

[0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0]


>python clock
[1.0336509249080539e-05, 1.6482541775560862e-05, 2.1511113842681123e-05,
2.6539685909801387e-05, 3.1568257976921645e-05, 3.7434925388561956e-05,
4.2184132340842205e-05, 4.7212704407962462e-05, 5.2241276475082727e-05,

[6.1460325264803225e-06, 5.0285720671202609e-06, 5.0285720671202643e-06,
5.0285720671202575e-06, 5.8666674116403117e-06, 4.7492069522802485e-06,
5.0285720671202575e-06, 5.0285720671202643e-06, 5.3079371819602801e-06]


Because the lrucache module uses time.time irrespective of the platform, on Windows it assigns exactly the same timestamp to multiple cache nodes. This seems to confuse the heapq and/or lrucache module. I'll have to investigate this in more detail to find out what's going on here. :-)

comment:10 Changed 12 years ago by ftputiluser

While I was trying to figure out where the (non-existant) bug was in the heapq module, I learned quite a lot about heaps. A heap is a special kind of binary tree where the keys of each node are greater than that of its parent (this means that you can remove the lowest value in the whole tree by removing the root of the tree, which is a low cost operation).

However for this to work you need a stable sort key, which is where the unix-windows fight causes the problem.

From the python docs:


On Unix, return the current processor time as a floating point number expressed in seconds. The precision, and in fact the very definition of the meaning of “processor time”, depends on that of the C function of the same name, but in any case, this is the function to use for benchmarking Python or timing algorithms.

On Windows, this function returns wall-clock seconds elapsed since the first call to this function, as a floating point number, based on the Win32 function QueryPerformanceCounter(). The resolution is typically better than one microsecond.



Return the time as a floating point number expressed in seconds since the epoch, in UTC. Note that even though the time is always returned as a floating point number, not all systems provide time with a better precision than 1 second. While this function normally returns non-decreasing values, it can return a lower value than a previous call if the system clock has been set back between the two calls.

Windows is one platform where you only get 1s precision from time.time() (there are others).

A patch I made

This uses a synthetic key for all comparisons made within the heapq module, and with it the code runs identically on my windows box and ubuntu.

The patch could be simplified if you didn't want to retain the LRUCache.mtime(key) interface (returns the modification time of the cached item with that key)

Peter Stirling

comment:11 Changed 12 years ago by schwa


thanks for your patch! I've also thought about using just a counter. :-) Thanks to Python having long integers, there won't be any problems with integer overflow or "wrap-around" situations, and we won't have to deal with platform dependencies.

Though this approach should fix the problem, I wonder why lrucache gets so confused. Granted, if the time value provides no stable sort order, I'd expect lrucache to perhaps not delete the actually least recently used item from the cache. However, that doesn't explain the traceback for the cache's size change where it seems the code takes a node from the heap list self.__heap but no longer finds the node's key* in the dictionary self.__dict. I'd like to know why this happens before I declare the bug fixed.

Regarding mtime, I need this for the "maximum age" functionality described in the documentation.

  • Here, I mean the node's key attribute, not the "sort key" (which is supposed to be the last-access time) for the heap.

comment:12 Changed 12 years ago by schwa

It seems the problem is in LRUCache.__delitem__. Running with a time function which assigns the same timestamp on every invocation, I find ...

node = self.__dict[key]

extracts the correct node by its key, in the case of the test program that's 16.

del self.__dict[key]

deletes this node via its key.


deletes a node by searching through the __heap list and comparing the value it finds there with the node. However, since this comparison is done by using Node's __cmp__ method, the remove method removes the very first item in the list, which not happens to be the intended 16 but 15.

So the cache object ends up with a heap list that doesn't match the dictionary.

As far as I can see, the resizing in __setattr__ seems to work correctly.

So increasing the comparison key with every new node, as we both thought of, should reliably fix the bug.

comment:13 Changed 12 years ago by schwa

Resolution: fixed
Status: assignedclosed

Fixed in changeset 855.

comment:14 Changed 12 years ago by schwa

The fixed version I sent to the original author of lrucache consists of these changesets.

comment:15 Changed 12 years ago by schwa

Milestone: 2.4.1
Note: See TracTickets for help on using tickets.