Bug 979748

Summary: cupsd uses D-Bus from two different threads
Product: [Fedora] Fedora Reporter: Juan Orti <jorti>
Component: cupsAssignee: Tim Waugh <twaugh>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: urgent    
Version: 19CC: jorti, jpopelka, mdmpsyd, twaugh
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Unspecified   
Whiteboard: abrt_hash:2c460d75cfcd5d70bdc868cf2b1f637d09c7e803
Fixed In Version: cups-1.6.2-15.fc19 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-07-11 02:33:34 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 980194    
Attachments:
Description Flags
File: backtrace
none
File: cgroup
none
File: core_backtrace
none
File: dso_list
none
File: environ
none
File: limits
none
File: maps
none
File: open_fds
none
File: proc_pid_status
none
File: var_log_messages
none
GDB output
none
Crash with cups-1.6.2-15.fc19.x86_64 none

Description Juan Orti 2013-06-30 08:20:51 UTC
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 08:20:56 UTC
Created attachment 767010 [details]
File: backtrace

Comment 2 Juan Orti 2013-06-30 08:21:00 UTC
Created attachment 767011 [details]
File: cgroup

Comment 3 Juan Orti 2013-06-30 08:21:03 UTC
Created attachment 767012 [details]
File: core_backtrace

Comment 4 Juan Orti 2013-06-30 08:21:06 UTC
Created attachment 767013 [details]
File: dso_list

Comment 5 Juan Orti 2013-06-30 08:21:10 UTC
Created attachment 767014 [details]
File: environ

Comment 6 Juan Orti 2013-06-30 08:21:13 UTC
Created attachment 767015 [details]
File: limits

Comment 7 Juan Orti 2013-06-30 08:21:17 UTC
Created attachment 767016 [details]
File: maps

Comment 8 Juan Orti 2013-06-30 08:21:20 UTC
Created attachment 767017 [details]
File: open_fds

Comment 9 Juan Orti 2013-06-30 08:21:23 UTC
Created attachment 767018 [details]
File: proc_pid_status

Comment 10 Juan Orti 2013-06-30 08:21:27 UTC
Created attachment 767019 [details]
File: var_log_messages

Comment 11 Tim Waugh 2013-07-01 10:42:44 UTC
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 11:08:42 UTC
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 11:30:49 UTC
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 14:11:59 UTC
*** Bug 974506 has been marked as a duplicate of this bug. ***

Comment 15 Tim Waugh 2013-07-02 08:06:40 UTC
*** Bug 980294 has been marked as a duplicate of this bug. ***

Comment 16 Tim Waugh 2013-07-02 08:07:22 UTC
*** Bug 980310 has been marked as a duplicate of this bug. ***

Comment 17 Fedora Update System 2013-07-02 08:12:04 UTC
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-03 01:40:10 UTC
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 16:05:29 UTC
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 08:47:21 UTC
(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 08:55:41 UTC
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-11 02:33:34 UTC
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.