Bug#745487: apt python library leak memory and file descriptors

[Michael Vogt <mvo@ubuntu.com>]

On Tue, Apr 22, 2014 at 11:23:24AM +0200, Petter Reinholdtsen wrote:
> Package: python-apt
> Version: 0.8.8.2
> Severity: important

Thanks for your bugreport.
 
> Since I wrote the isenkram package, it have been plagued with a nasty
> resourse leak.  It leak memory and file descriptors every time some
> hardware is inserted.  The amount of leaked memory varies, but seem to
> be 30-40 MiB every time.  The amount of file descriptors depend on the
> number of APT sources listed in /etc/apt/.
> <URL: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=730704 >
> is an example on what happen when the process run out of file
> descriptors, and
> <URL: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=719837 > is the
> initial report about leaking memory.

This is a good test scenario, afaik python-apt is not being used in
daemons so far.

> I've been able to track down the problem to the python-apt library, and
> the following test program demonstrate the leak:
> 
>   #!/usr/bin/python
>   import apt
>   while True:
>     cache = apt.Cache()
>     cache.open(None)
> 
> When left alone running for a while, it crashes like this:
> 
>   % ./apt-leak.py 
>   Traceback (most recent call last):
>     File "./apt-leak.py", line 6, in <module>
>       cache.open(None)
>     File "/usr/lib/python2.7/dist-packages/apt/cache.py", line 147, in open
>       self._records = apt_pkg.PackageRecords(self._cache)

Thanks for this demo, I can reproduce the issue with it. However, if I
change it a little bit and force the python garbage collector there
seems to be no leak (or a small memory leak but no fd leak).
"""
#!/usr/bin/python

import gc
import os
import timeit

import apt

def show_resource_stats():
    mem = open("/proc/self/statm").read().strip().split()[0:2]
    open_fds = len(os.listdir("/proc/self/fd/"))
    print("mem: %s" % mem)
    print("open fds: %s" % open_fds)



if __name__ == "__main__":
    i=0
    while True:
        cache = apt.Cache()
        cache.open()
        i += 1
        if i%10 == 0:
            print("\nAfter %s runs" % i)
            show_resource_stats()
            print(timeit.timeit(gc.collect, number=1))
            print("After collect:")
            show_resource_stats()
"""

I see numbers like:
"""
After 20 runs
mem: ['181774', '165966']
open fds: 653
0.236461877823
After collect:
mem: ['68298', '57910']
open fds: 63

After 30 runs
mem: ['181774', '165980']
open fds: 653
0.229271888733
After collect:
mem: ['68938', '58564']
open fds: 63
"""

Mem is "size" (VmSize) first and "resident" (VmRSS) second.

I suspect that the behavior without running the GC is caused by the
way we handle the pkgCache and pkgDepCache internally. Both are
managed via a CacheFile and it seems that a del of the
pkgCache/pkgDepCache leave the CacheFile (that really has the
resources open) with zero references, but the resources are only
really freed once the GC runs. This needs some investigation in the
python/cache.cc code to see if we can explicitly trigger the free.

> Am I using the library wrong (ie should I do something to release the
> resources when I am done with the cache), or is it a bug in the library
> leaking memory and file descriptors?
> 
> Setting severity to important.  I guess one could argue that it should
> be critical because it causes isenkram to fail, but that severity seemed
> a bit high when I do not know if I am using the library wrong or not.

Even if you would use the library wrong I would argue its a bug
because the library should work well in the simple test case you
provided. 

Cheers,
 Michael

#!/usr/bin/python

import gc
import os
import timeit

import apt

def show_resource_stats():
    mem = open("/proc/self/statm").read().strip().split()[0:2]
    open_fds = len(os.listdir("/proc/self/fd/"))
    print("mem: %s" % mem)
    print("open fds: %s" % open_fds)



if __name__ == "__main__":
    i=0
    while True:
        cache = apt.Cache()
        cache.open()
        i += 1
        if i%10 == 0:
            print("\nAfter %s runs" % i)
            show_resource_stats()
            print(timeit.timeit(gc.collect, number=1))
            print("After collect:")
            show_resource_stats()