Bug 1026949

Summary: Printing notifications are lost due to dbus notifier locking bug
Product: [Fedora] Fedora Reporter: Tim Waugh <twaugh>
Component: cupsAssignee: Marek Kašík <mkasik>
Status: CLOSED EOL QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 20CC: bnocera, fmuellner, jpopelka, mkasik, ofourdan, pnemade, rstrode, tiagomatos, twaugh
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: cups-1.7.0-5.fc20 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
: 1030666 (view as bug list) Environment:
Last Closed: 2015-06-30 01:25:09 UTC Type: Bug
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: 1030666    

Description Tim Waugh 2013-11-05 17:19:53 UTC
Description of problem:
During the Printing Test Day, I lost printing notifications. Printing jobs no longer gave notifications; adjusting things in the control-center failed to update properly. After logging out, then logging back in again, I got notifications back... until they disappeared again shortly afterwards.

The dbus notifier is running -- in fact, it's running twice, which seems odd:

29472 ?        Ss     0:01 /usr/sbin/cupsd -f
 6040 ?        S      0:00  \_ /usr/lib/cups/notifier/dbus dbus:// 
 6041 ?        S      0:00  \_ /usr/lib/cups/notifier/dbus dbus:// 
 6088 ?        S      0:00  \_ Photosmart-5510-series 33 twaugh Test page 1 job-
 6091 ?        S      0:00  |   \_ /usr/bin/gs -dQUIET -dPARANOIDSAFER -dNOPAUSE
 6089 ?        S      0:00  \_ Photosmart-5510-series 33 twaugh Test page 1 job-
 6090 ?        S      0:00  \_ socket://192.168.0.107:9100/ 33 twaugh Test page 

There are two active subscriptions:

>>> pprint.pprint(c.getSubscriptions("/"))
[{'notify-events': [u'printer-state-changed',
                    u'printer-restarted',
                    u'printer-shutdown',
                    u'printer-stopped',
                    u'printer-added',
                    u'printer-deleted',
                    u'job-state-changed',
                    u'job-created',
                    u'job-completed',
                    u'job-stopped'],
  'notify-lease-duration': 3600,
  'notify-recipient-uri': u'dbus://',
  'notify-subscriber-user-name': u'twaugh',
  'notify-subscription-id': 76,
  'notify-time-interval': 0},
 {'notify-events': [u'printer-state-changed',
                    u'printer-restarted',
                    u'printer-shutdown',
                    u'printer-stopped',
                    u'printer-added',
                    u'printer-deleted',
                    u'job-created',
                    u'job-completed'],
  'notify-lease-duration': 600,
  'notify-recipient-uri': u'dbus://',
  'notify-subscriber-user-name': u'twaugh',
  'notify-subscription-id': 87,
  'notify-time-interval': 0}]

gnome-settings-daemon is running:
[twaugh@rubik ~]$ ps axf | grep [g]nome-setti
28157 ?        Sl     0:01              \_ /usr/libexec/gnome-settings-daemon

Version-Release number of selected component (if applicable):
gnome-settings-daemon-3.10.1-2.fc20.x86_64
cups-1.7.0-4.fc20.x86_64

How reproducible:
Often.

Comment 1 Marek Kašík 2013-11-07 12:53:14 UTC
Hi,

the second subscription (the one with 600s duration) is for gnome-control-center's Printers panel.
I can not reproduce the issue with losing of notifications. Could you run the gnome-settings-daemon with debugging mode enabled and attach the log here when the notifications disappear? (
/usr/libexec/gnome-settings-daemon --replace --debug &> ./gsd.log)
Does /var/log/cups/erro_log shows anything suspicious with "LogLevel debug"? (except that g-c-c tries to cancel subscription with id = 0, this should be another bug)

Regards

Marek

Comment 2 Tim Waugh 2013-11-14 16:53:29 UTC
This actually looks to be a CUPS issue. On restart (e.g. cupsctl --debug-logging) the existing dbus notifier is killed and two (!) are started up. One fails, but for some reason leaves a lock file lying around, so the remaining one ends up keeping quiet:

# grep -i notifier /var/log/cups/error_log
D [14/Nov/2013:16:11:42 +0000] PID 31767 (/usr/lib/cups/notifier/dbus) was terminated normally with signal 15.
D [14/Nov/2013:16:13:50 +0000] Notifier dbus started - PID = 32518
D [14/Nov/2013:16:13:50 +0000] [Notifier] state=3
D [14/Nov/2013:16:13:50 +0000] [Notifier] Connected to D-BUS
D [14/Nov/2013:16:14:29 +0000] Notifier dbus started - PID = 32541
[...]
D [14/Nov/2013:16:14:29 +0000] [Notifier] Connected to D-BUS
[...]
D [14/Nov/2013:16:14:35 +0000] [Notifier] state=3
D [14/Nov/2013:16:14:37 +0000] [Notifier] state=-1
D [14/Nov/2013:16:14:37 +0000] [Notifier] ippReadFile() returned IPP_ERROR!
D [14/Nov/2013:16:14:37 +0000] PID 32541 (/usr/lib/cups/notifier/dbus) exited with no errors.
D [14/Nov/2013:16:19:36 +0000] [Notifier] state=3
D [14/Nov/2013:16:49:13 +0000] [Notifier] state=3
D [14/Nov/2013:16:49:18 +0000] [Notifier] state=3
D [14/Nov/2013:16:49:37 +0000] [Notifier] state=3
D [14/Nov/2013:16:49:41 +0000] [Notifier] state=3
D [14/Nov/2013:16:49:43 +0000] [Notifier] state=3

This is the remaining dbus process after reading each event:

write(2, "DEBUG: state=3\n", 15)        = 15
open("/var/spool/cups/tmp/cups-dbus-notifier-lockfile", O_RDWR|O_CREAT|O_EXCL, 0600) = -1 EEXIST (File exists)

Comment 3 Tim Waugh 2013-11-14 17:07:25 UTC
The fix might be as simple as removing the lock file in a SIGTERM handler.

Comment 4 Tim Waugh 2013-11-14 21:25:03 UTC
Fixed in:
  cups-1.5.4-30.fc18
  cups-1.6.4-3.fc19
  cups-1.7.0-5.fc20
  cups-1.7.0-5.fc21

Comment 5 Fedora End Of Life 2015-05-29 09:41:51 UTC
This message is a reminder that Fedora 20 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 20. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '20'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 20 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 6 Fedora End Of Life 2015-06-30 01:25:09 UTC
Fedora 20 changed to end-of-life (EOL) status on 2015-06-23. Fedora 20 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.