Bug 94070

Summary: Double close() in logind code (can e.g. cause infinite loops in worker thread)
Product: PackageKit Reporter: Benjamin Berg <benjamin>
Component: coreAssignee: Richard Hughes <richard>
Status: RESOLVED FIXED QA Contact:
Severity: normal    
Priority: medium    
Version: unspecified   
Hardware: Other   
OS: All   
Whiteboard:
i915 platform: i915 features:
Attachments: Patch to fix the double close

Description Benjamin Berg 2016-02-10 00:17:03 UTC
I just had my packagekitd (version 1.0.11-1) go into an infinite loop matching filenames from packages. The funny thing was, it wasn't even matching against a correct file name and the file list was closed.

To be honest, I am totally at a loss about how packagekitd might have gotten into the state that it was in.

It was hanging in this loop (code moved around slightly compared to bt):
https://github.com/hughsie/PackageKit/blob/c0069ed0a41ddf1138f3bb34c9c02e6241a220fd/backends/aptcc/apt-intf.cpp#L1211

The getline() call did not manipulate the "line" in any way, and it was alwas the string "/usr/share/help/eu/aisleriot/thumb_and_pouch.xm" (which is missing the trailing l of the xml extension). .eof() obviously was not true, and there is still a lot of content after the line that it got stuck on.

Open files were:
$ sudo ls -l /proc/1772/fd 
total 0
lr-x------ 1 root root 64 Feb 10 00:11 0 -> /dev/null
lrwx------ 1 root root 64 Feb 10 00:11 1 -> socket:[22473]
lrwx------ 1 root root 64 Feb 10 00:11 18 -> /var/lib/PackageKit/transactions.db
lr-x------ 1 root root 64 Feb 10 00:11 19 -> /var/lib/dpkg/info
lrwx------ 1 root root 64 Feb 10 00:11 2 -> socket:[22473]
lrwx------ 1 root root 64 Feb 10 00:11 3 -> socket:[23066]
lrwx------ 1 root root 64 Feb 10 00:11 4 -> anon_inode:[eventfd]
lrwx------ 1 root root 64 Feb 10 00:11 5 -> socket:[21293]
lrwx------ 1 root root 64 Feb 10 00:11 6 -> anon_inode:[eventfd]
lrwx------ 1 root root 64 Feb 10 00:11 7 -> anon_inode:[eventfd]
lr-x------ 1 root root 64 Feb 10 00:11 8 -> anon_inode:inotify
lrwx------ 1 root root 64 Feb 10 00:11 9 -> /var/lib/PackageKit/transactions.db

So /var/lib/dpkg/info/aisleriot.list was not open. That does seem fishy.

(gdb) bt
#0  0x00007fb67dc6a16d in re_search_internal (p_match_first=0x7fb67b109834, fl_longest_match=0, mctx=0x7fb67b109870) at regexec.c:1174
#1  0x00007fb67dc6a16d in re_search_internal (preg=preg@entry=0x7fb67b109a60, string=string@entry=0x7fb65c0126d0 "/usr/share/help/eu/aisleriot/thumb_and_pouch.xm", length=47, start=<optimized out>, range=0, stop=<optimized out>, nmatch=<optimized out>, pmatch=0x0, eflags=0) at regexec.c:844
#2  0x00007fb67dc6f9e0 in __regexec (preg=preg@entry=0x7fb67b109a60, string=0x7fb65c0126d0 "/usr/share/help/eu/aisleriot/thumb_and_pouch.xm", nmatch=nmatch@entry=0, pmatch=pmatch@entry=0x0, eflags=eflags@entry=0) at regexec.c:252
#3  0x00007fb67a6f784d in AptIntf::searchPackageFiles(char**) (this=this@entry=0x563affd1a8a0, values=<optimized out>) at apt-intf.cpp:1222
#4  0x00007fb67a6fefdc in pk_backend_search_files_thread(PkBackendJob*, GVariant*, gpointer) (job=0x563affd41930 [PkBackendJob], params=<optimized out>, user_data=<optimized out>)
    at pk-backend-aptcc.cpp:665
#5  0x0000563afe55d7ea in pk_backend_job_thread_setup (thread_data=0x563affeffd10) at pk-backend-job.c:814
#6  0x00007fb67e1d19c5 in g_thread_proxy (data=0x563afffce4f0) at /build/glib2.0-2.46.2/./glib/gthread.c:778
#7  0x00007fb67df4b284 in start_thread (arg=0x7fb67b10a700) at pthread_create.c:333
#8  0x00007fb67dc8874d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109



I tried grabbing more info, but then caused a crash:
(gdb) finish
Run till exit from #0  0x00007fb67dc6f9e0 in __regexec (preg=preg@entry=0x7fb67b109a60, string=0x7fb65c0126d0 "/usr/share/help/eu/aisleriot/thumb_and_pouch.xm", 
    nmatch=nmatch@entry=0, pmatch=pmatch@entry=0x0, eflags=eflags@entry=0) at regexec.c:252
0x00007fb67a6f784d in AptIntf::searchPackageFiles (this=this@entry=0x563affd1a8a0, values=<optimized out>) at apt-intf.cpp:1222
1222	apt-intf.cpp: No such file or directory.
Value returned is $5 = 1
(gdb) print in
$6 = {<std::basic_istream<char, std::char_traits<char> >> = {<std::basic_ios<char, std::char_traits<char> >> = {<std::ios_base> = {
        _vptr.ios_base = 0x7fb678fb5460 <vtable for std::basic_ifstream<char, std::char_traits<char> >+64>, static boolalpha = std::_S_boolalpha, static dec = std::_S_dec, 
        static fixed = std::_S_fixed, static hex = std::_S_hex, static internal = std::_S_internal, static left = std::_S_left, static oct = std::_S_oct, 
        static right = std::_S_right, static scientific = std::_S_scientific, static showbase = std::_S_showbase, static showpoint = std::_S_showpoint, 
        static showpos = std::_S_showpos, static skipws = std::_S_skipws, static unitbuf = std::_S_unitbuf, static uppercase = std::_S_uppercase, 
        static adjustfield = std::_S_adjustfield, static basefield = std::_S_basefield, static floatfield = std::_S_floatfield, static badbit = std::_S_badbit, 
        static eofbit = std::_S_eofbit, static failbit = std::_S_failbit, static goodbit = std::_S_goodbit, static app = std::_S_app, static ate = std::_S_ate, 
        static binary = std::_S_bin, static in = std::_S_in, static out = std::_S_out, static trunc = std::_S_trunc, static beg = std::_S_beg, static cur = std::_S_cur, 
        static end = std::_S_end, _M_precision = 6, _M_width = 0, _M_flags = 4098, _M_exception = std::_S_goodbit, _M_streambuf_state = 5, _M_callbacks = 0x0, _M_word_zero = {
          _M_pword = 0x0, _M_iword = 0}, _M_local_word = {{_M_pword = 0x0, _M_iword = 0}, {_M_pword = 0x0, _M_iword = 0}, {_M_pword = 0x0, _M_iword = 0}, {_M_pword = 0x0, 
            _M_iword = 0}, {_M_pword = 0x0, _M_iword = 0}, {_M_pword = 0x0, _M_iword = 0}, {_M_pword = 0x0, _M_iword = 0}, {_M_pword = 0x0, _M_iword = 0}}, _M_word_size = 8, 
        _M_word = 0x7fb67b109c40, _M_ios_locale = {static none = 0, static ctype = 1, static numeric = 2, static collate = 4, static time = 8, static monetary = 16, 
          static messages = 32, static all = 63, _M_impl = 0x7fb678fbd780 <(anonymous namespace)::c_locale_impl>, 
          static _S_classic = 0x7fb678fbd780 <(anonymous namespace)::c_locale_impl>, static _S_global = 0x7fb678fbd780 <(anonymous namespace)::c_locale_impl>, 
          static _S_categories = 0x7fb678fb01e0 <__gnu_cxx::category_names>, static _S_once = 2, static _S_twinned_facets = 0x7fb678fb17c0 <std::locale::_S_twinned_facets>}}, 
      _M_tie = 0x0, _M_fill = 0 '\000', _M_fill_init = false, _M_streambuf = 0x7fb67b109b10, _M_ctype = 0x7fb678fbd1a0 <(anonymous namespace)::ctype_c>, 
      _M_num_put = 0x7fb678fbd130 <(anonymous namespace)::num_put_c>, _M_num_get = 0x7fb678fbd140 <(anonymous namespace)::num_get_c>}, 
    _vptr.basic_istream = 0x7fb678fb5438 <vtable for std::basic_ifstream<char, std::char_traits<char> >+24>, _M_gcount = 0}, 
  _M_filebuf = {<std::basic_streambuf<char, std::char_traits<char> >> = {_vptr.basic_streambuf = 0x7fb678fb5340 <vtable for std::basic_filebuf<char, std::char_traits<char> >+16>, 
      _M_in_beg = 0x7fb65cec7000 "xml\n/usr/share/help/gl/aisleriot/jumbo.xml\n/usr/share/help/gl/aisleriot/jamestown.xml\n/usr/share/help/gl/aisleriot/isabel.xml\n/usr/share/help/gl/aisleriot/hopscotch.xml\n/usr/share/help/gl/aisleriot/he"..., _M_in_cur = 0x7fb65cec8fff "", _M_in_end = 0x7fb65cec8fff "", _M_out_beg = 0x0, _M_out_cur = 0x0, 
      _M_out_end = 0x0, _M_buf_locale = {static none = 0, static ctype = 1, static numeric = 2, static collate = 4, static time = 8, static monetary = 16, static messages = 32, 
        static all = 63, _M_impl = 0x7fb678fbd780 <(anonymous namespace)::c_locale_impl>, static _S_classic = 0x7fb678fbd780 <(anonymous namespace)::c_locale_impl>, 
        static _S_global = 0x7fb678fbd780 <(anonymous namespace)::c_locale_impl>, static _S_categories = 0x7fb678fb01e0 <__gnu_cxx::category_names>, static _S_once = 2, 
        static _S_twinned_facets = 0x7fb678fb17c0 <std::locale::_S_twinned_facets>}}, _M_lock = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, 
        __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>, __align = 0}, _M_file = {_M_cfile = 0x7fb65ce7e3d0, 
      _M_cfile_created = true}, _M_mode = std::_S_in, _M_state_beg = {__count = 0, __value = {__wch = 0, __wchb = "\000\000\000"}}, _M_state_cur = {__count = 0, __value = {
        __wch = 0, __wchb = "\000\000\000"}}, _M_state_last = {__count = 0, __value = {__wch = 0, __wchb = "\000\000\000"}}, 
    _M_buf = 0x7fb65cec7000 "xml\n/usr/share/help/gl/aisleriot/jumbo.xml\n/usr/share/help/gl/aisleriot/jamestown.xml\n/usr/share/help/gl/aisleriot/isabel.xml\n/usr/share/help/gl/aisleriot/hopscotch.xml\n/usr/share/help/gl/aisleriot/he"..., _M_buf_size = 8192, _M_buf_allocated = true, _M_reading = true, _M_writing = false, _M_pback = 0 '\000', 
    _M_pback_cur_save = 0x0, _M_pback_end_save = 0x0, _M_pback_init = false, _M_codecvt = 0x7fb678fbd110 <(anonymous namespace)::codecvt_c>, _M_ext_buf = 0x0, 
    _M_ext_buf_size = 0, _M_ext_next = 0x0, _M_ext_end = 0x0}}
(gdb) print in.eof()
$7 = false
(gdb) print !in

Program received signal SIGSEGV, Segmentation fault.
Comment 1 Benjamin Berg 2016-02-10 00:29:18 UTC
I just checked, if you compare the file with the strings from the input stream cache, then the cut of character is exactly 8kiB after the beginning of the cache. So getline() seems to have returned everything until the buffer was exhausted and nothing more could be read from the (closed) file descriptor.

Now, how could a file descriptor be closed for no apparent reason?
Comment 2 Benjamin Berg 2016-02-10 21:04:42 UTC
I straced the process and saw a spurious close after running an apt-get update (that actually downloaded some new stuff). Haven't been able to pinpoint the source of that close though and I only straced close calls …

strace -p 14204 -e close
strace: Process 14204 attached
close(10)                               = 0
close(11)                               = 0
close(12)                               = 0
close(11)                               = 0
close(11)                               = 0
close(11)                               = 0
close(11)                               = 0
close(11)                               = 0
close(12)                               = 0
close(12)                               = 0
close(13)                               = 0
close(13)                               = 0
close(12)                               = 0
close(13)                               = -1 EBADF (Bad file descriptor)
close(12)                               = 0

Though I guess this might be one of the other threads doing it.
Comment 3 Benjamin Berg 2016-02-10 21:46:01 UTC
open("/dev/urandom", O_RDONLY)          = 10
close(10)                               = 0
open("/var/lib/PackageKit/transactions.db", O_RDWR|O_CREAT|O_CLOEXEC, 0644) = 10
eventfd2(0, EFD_CLOEXEC|EFD_NONBLOCK)   = 11
close(11)                               = 0
open("/var/lib/PackageKit/transactions.db-journal", O_RDWR|O_CREAT|O_CLOEXEC, 0644) = 11
open("/var/lib/PackageKit", O_RDONLY|O_CLOEXEC) = 12
close(12)                               = 0
close(11)                               = 0
eventfd2(0, EFD_CLOEXEC|EFD_NONBLOCK)   = 11
close(11)                               = 0
open("/proc/520/cgroup", O_RDONLY|O_CLOEXEC) = 11
close(11)                               = 0
open("/proc/1/cgroup", O_RDONLY|O_CLOEXEC) = 11
close(11)                               = 0
eventfd2(0, EFD_CLOEXEC|EFD_NONBLOCK)   = 12
close(12)                               = 0
close(13)                               = 0
open("/dev/urandom", O_RDONLY)          = 12
close(12)                               = 0
open("/var/lib/PackageKit/transactions.db", O_RDWR|O_CREAT|O_CLOEXEC, 0644) = 12
eventfd2(0, EFD_CLOEXEC|EFD_NONBLOCK)   = 13
close(13)                               = 0
open("/var/lib/PackageKit/transactions.db-journal", O_RDWR|O_CREAT|O_CLOEXEC, 0644) = 13
open("/var/lib/PackageKit", O_RDONLY|O_CLOEXEC) = 14
close(14)                               = 0
close(13)                               = 0
close(13)                               = -1 EBADF (Bad file descriptor)
eventfd2(0, EFD_CLOEXEC|EFD_NONBLOCK)   = 11
close(11)                               = 0
open("/proc/520/cgroup", O_RDONLY|O_CLOEXEC) = 11
close(11)                               = 0
open("/proc/1/cgroup", O_RDONLY|O_CLOEXEC) = 11
close(11)                               = 0
open("/var/lib/PackageKit/transactions.db-journal", O_RDWR|O_CREAT|O_CLOEXEC, 0644) = 36
close(36)                               = 0
close(35)                               = 0
close(34)                               = 0

Not sure if this proves anything though.
Comment 4 Benjamin Berg 2016-02-10 23:48:01 UTC
Created attachment 121658 [details] [review]
Patch to fix the double close

So, turns out the double close is from the logind interaction. This patch should fix the issue (and the patch seems to work fine here).

Funnily enough, it does mean that the login_fd was always invalid before.
Comment 5 Richard Hughes 2016-02-11 14:29:13 UTC
Pushed to master, thanks!!

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.