Bug 1026949 - Printing notifications are lost due to dbus notifier locking bug
Printing notifications are lost due to dbus notifier locking bug
Status: CLOSED EOL
Product: Fedora
Classification: Fedora
Component: cups (Show other bugs)
20
Unspecified Unspecified
unspecified Severity unspecified
: ---
: ---
Assigned To: Marek Kašík
Fedora Extras Quality Assurance
:
Depends On:
Blocks: 1030666
  Show dependency treegraph
 
Reported: 2013-11-05 12:19 EST by Tim Waugh
Modified: 2015-06-29 21:25 EDT (History)
9 users (show)

See Also:
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-29 21:25:09 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)


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

  None (edit)
Description Tim Waugh 2013-11-05 12:19:53 EST
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 07:53:14 EST
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 11:53:29 EST
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 12:07:25 EST
The fix might be as simple as removing the lock file in a SIGTERM handler.
Comment 4 Tim Waugh 2013-11-14 16:25:03 EST
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 05:41:51 EDT
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-29 21:25:09 EDT
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.

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