Bug 979748 - cupsd uses D-Bus from two different threads
cupsd uses D-Bus from two different threads
Status: CLOSED ERRATA
Product: Fedora
Classification: Fedora
Component: cups (Show other bugs)
19
x86_64 Unspecified
urgent Severity unspecified
: ---
: ---
Assigned To: Tim Waugh
Fedora Extras Quality Assurance
abrt_hash:2c460d75cfcd5d70bdc868cf2b1...
:
: 974506 980294 980310 (view as bug list)
Depends On:
Blocks: 980194
  Show dependency treegraph
 
Reported: 2013-06-30 04:20 EDT by Juan Orti
Modified: 2014-04-14 11:12 EDT (History)
4 users (show)

See Also:
Fixed In Version: cups-1.6.2-15.fc19
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2013-07-10 22:33:34 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
File: backtrace (131.77 KB, text/plain)
2013-06-30 04:20 EDT, Juan Orti
no flags Details
File: cgroup (154 bytes, text/plain)
2013-06-30 04:21 EDT, Juan Orti
no flags Details
File: core_backtrace (1.74 KB, text/plain)
2013-06-30 04:21 EDT, Juan Orti
no flags Details
File: dso_list (3.64 KB, text/plain)
2013-06-30 04:21 EDT, Juan Orti
no flags Details
File: environ (160 bytes, text/plain)
2013-06-30 04:21 EDT, Juan Orti
no flags Details
File: limits (1.29 KB, text/plain)
2013-06-30 04:21 EDT, Juan Orti
no flags Details
File: maps (17.81 KB, text/plain)
2013-06-30 04:21 EDT, Juan Orti
no flags Details
File: open_fds (814 bytes, text/plain)
2013-06-30 04:21 EDT, Juan Orti
no flags Details
File: proc_pid_status (893 bytes, text/plain)
2013-06-30 04:21 EDT, Juan Orti
no flags Details
File: var_log_messages (748 bytes, text/plain)
2013-06-30 04:21 EDT, Juan Orti
no flags Details
GDB output (5.75 KB, text/plain)
2013-07-01 07:08 EDT, Juan Orti
no flags Details
Crash with cups-1.6.2-15.fc19.x86_64 (338.84 KB, application/x-xz)
2013-07-03 12:05 EDT, Juan Orti
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
CUPS Bugs and Features 4347 None None None Never

  None (edit)
Description Juan Orti 2013-06-30 04:20:51 EDT
Version-Release number of selected component:
cups-1.6.2-9.fc19

Additional info:
reporter:       libreport-2.1.5
backtrace_rating: 3
cmdline:        /usr/sbin/cupsd -f
crash_function: __memmove_ssse3_back
executable:     /usr/sbin/cupsd
kernel:         3.9.6-301.fc19.x86_64
runlevel:       unknown
uid:            0

Truncated backtrace:
Thread no. 1 (10 frames)
 #0 __memmove_ssse3_back at ../sysdeps/x86_64/multiarch/memcpy-ssse3-back.S:1664
 #1 memmove at /usr/include/bits/string3.h:57
 #2 delete at dbus-string.c:1175
 #4 _dbus_string_delete at dbus-string.c:1200
 #5 load_message at dbus-message.c:4171
 #6 _dbus_message_loader_queue_messages at dbus-message.c:4245
 #7 _dbus_transport_get_dispatch_status at dbus-transport.c:1101
 #8 _dbus_transport_queue_messages at dbus-transport.c:1128
 #9 _dbus_connection_get_dispatch_status_unlocked at dbus-connection.c:4211
 #11 dispatch_timeout_callback at ../avahi-common/dbus-watch-glue.c:105
Comment 1 Juan Orti 2013-06-30 04:20:56 EDT
Created attachment 767010 [details]
File: backtrace
Comment 2 Juan Orti 2013-06-30 04:21:00 EDT
Created attachment 767011 [details]
File: cgroup
Comment 3 Juan Orti 2013-06-30 04:21:03 EDT
Created attachment 767012 [details]
File: core_backtrace
Comment 4 Juan Orti 2013-06-30 04:21:06 EDT
Created attachment 767013 [details]
File: dso_list
Comment 5 Juan Orti 2013-06-30 04:21:10 EDT
Created attachment 767014 [details]
File: environ
Comment 6 Juan Orti 2013-06-30 04:21:13 EDT
Created attachment 767015 [details]
File: limits
Comment 7 Juan Orti 2013-06-30 04:21:17 EDT
Created attachment 767016 [details]
File: maps
Comment 8 Juan Orti 2013-06-30 04:21:20 EDT
Created attachment 767017 [details]
File: open_fds
Comment 9 Juan Orti 2013-06-30 04:21:23 EDT
Created attachment 767018 [details]
File: proc_pid_status
Comment 10 Juan Orti 2013-06-30 04:21:27 EDT
Created attachment 767019 [details]
File: var_log_messages
Comment 11 Tim Waugh 2013-07-01 06:42:44 EDT
There are quite a few symbols missing so it's hard to see what's happened. :-(

Could you please run these commands?:
1. debuginfo-install cupsd
2. gdb /usr/sbin/cupd /var/tmp/abrt/ccpp-2013-06-30-09:50:42-1513/coredump
3. then at the '(gdb)' prompt: thread apply all bt

What output do you get from step 3?
Comment 12 Juan Orti 2013-07-01 07:08:42 EDT
Created attachment 767328 [details]
GDB output

This is the output of the requested commands with all the needed debuginfo packages installed.
Comment 13 Tim Waugh 2013-07-01 07:30:49 EDT
Thanks.

I think the root cause of this is that cupsd is using avahi_threaded_poll (which makes use of D-Bus) while also using D-Bus in its main thread.  I don't think that's allowed.

The fix will be to alter the avahi polling so that it's done in the main thread (i.e. as it was before it was re-implemented upstream).
Comment 14 Tim Waugh 2013-07-01 10:11:59 EDT
*** Bug 974506 has been marked as a duplicate of this bug. ***
Comment 15 Tim Waugh 2013-07-02 04:06:40 EDT
*** Bug 980294 has been marked as a duplicate of this bug. ***
Comment 16 Tim Waugh 2013-07-02 04:07:22 EDT
*** Bug 980310 has been marked as a duplicate of this bug. ***
Comment 17 Fedora Update System 2013-07-02 04:12:04 EDT
cups-1.6.2-15.fc19 has been submitted as an update for Fedora 19.
https://admin.fedoraproject.org/updates/cups-1.6.2-15.fc19
Comment 18 Fedora Update System 2013-07-02 21:40:10 EDT
Package cups-1.6.2-15.fc19:
* should fix your issue,
* was pushed to the Fedora 19 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing cups-1.6.2-15.fc19'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2013-12162/cups-1.6.2-15.fc19
then log in and leave karma (feedback).
Comment 19 Juan Orti 2013-07-03 12:05:29 EDT
Created attachment 768326 [details]
Crash with cups-1.6.2-15.fc19.x86_64

It happened again with version cups-1.6.2-15.fc19.x86_64
Comment 20 Tim Waugh 2013-07-04 04:47:21 EDT
(In reply to Juan Orti Alcaine from comment #19)
> Created attachment 768326 [details]
> Crash with cups-1.6.2-15.fc19.x86_64
> 
> It happened again with version cups-1.6.2-15.fc19.x86_64

Although abrt claims it was cups-1.6.2-15.fc19.x86_64, it was actually cups-1.6.2-12.fc19.x86_64.  Two things that make me think that:

* /var/log/messages has this:

Jul  3 17:57:16 xenon abrt[14131]: File '/usr/sbin/cupsd' seems to be deleted

i.e. the running binary was actually different than the file on disk.

* the backtrace makes no sense (symbol lookups fail) when running gdb against cups-1.6.2-15.fc19.x86_64, but against cups-1.6.2-12.fc19.x86_64 it makes perfect sense:

Thread 2 (Thread 0x7fceb928c840 (LWP 1580)):
#0  0x00007fceb6ab0ded in __lll_lock_wait () from /lib64/libpthread.so.0
#1  0x00007fceb6aacba1 in _L_lock_790 () from /lib64/libpthread.so.0
#2  0x00007fceb6aacaa7 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x00007fceb7aa012c in avahi_threaded_poll_stop ()
   from /lib64/libavahi-common.so.3
#4  0x00007fceb7aa01f3 in avahi_threaded_poll_free ()
   from /lib64/libavahi-common.so.3
#5  0x00007fceb92f9125 in dnssdStop () at dirsvc.c:1339
#6  cupsdStopBrowsing () at dirsvc.c:324
#7  0x00007fceb9314d65 in cupsdStopServer () at server.c:114
#8  0x00007fceb92e423e in main (argc=<optimized out>, argv=<optimized out>)
    at main.c:1206

Thread 1 (Thread 0x7fcead1f2700 (LWP 2086)):
#0  0x00007fceb5b94a19 in raise () from /lib64/libc.so.6
#1  0x00007fceb5b96128 in abort () from /lib64/libc.so.6
#2  0x00007fceb5b8d986 in __assert_fail_base () from /lib64/libc.so.6
#3  0x00007fceb5b8da32 in __assert_fail () from /lib64/libc.so.6
#4  0x00007fceb789235c in connection_data_ref ()
   from /lib64/libavahi-client.so.3
#5  0x00007fceb7892926 in dispatch_timeout_callback ()
   from /lib64/libavahi-client.so.3
#6  0x00007fceb7a9fbf8 in avahi_simple_poll_dispatch ()
   from /lib64/libavahi-common.so.3
#7  0x00007fceb7a9fedd in avahi_simple_poll_loop ()
   from /lib64/libavahi-common.so.3
#8  0x00007fceb7a9ffa4 in thread () from /lib64/libavahi-common.so.3
#9  0x00007fceb6aaac53 in start_thread () from /lib64/libpthread.so.0
#10 0x00007fceb5c5413d in clone () from /lib64/libc.so.6

and in fact shows the use of avahi_threaded_poll_* functions -- exactly the thing we'd expect to see from that version.

So I think what must have happened was that, on upgrade, the cupsd from the previous version crashed during the restart triggered from the %postun scriptlet.
Comment 21 Juan Orti 2013-07-04 04:55:41 EDT
Humm... maybe I went too quick reporting the crash, I see this opening the coredump. If I understand it right, it seems the running binary was still the 1.6.2-12 version, I got confused when abrt told me it was the newer version, sorry.

[root@xenon tmp]# LANG=C  gdb /usr/sbin/cupd/ /tmp/ccpp-2013-07-03-17\:57\:16-1580/coredump
GNU gdb (GDB) Fedora (7.6-30.fc19)
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
/usr/sbin/cupd/: No such file or directory.
[New LWP 2086]
[New LWP 1580]
Missing separate debuginfo for the main executable file
Try: yum --disablerepo='*' --enablerepo='*debug*' install /usr/lib/debug/.build-id/d4/cd1cdec037a7f9c24cca29bdac7962357eef2a
Core was generated by `/usr/sbin/cupsd -f'.
Program terminated with signal 6, Aborted.
#0  0x00007fceb5b94a19 in ?? ()
(gdb) quit

[root@xenon tmp]# LANG=C yum --disablerepo='*' --enablerepo='*debug*' install /usr/lib/debug/.build-id/d4/cd1cdec037a7f9c24cca29bdac7962357eef2a
Loaded plugins: auto-update-debuginfo, langpacks, refresh-packagekit
Package matching 1:cups-debuginfo-1.6.2-12.fc19.x86_64 already installed. Checking for update.
Nothing to do
Comment 22 Fedora Update System 2013-07-10 22:33:34 EDT
cups-1.6.2-15.fc19 has been pushed to the Fedora 19 stable repository.  If problems still persist, please make note of it in this bug report.

Note You need to log in before you can comment on or make changes to this bug.