Bug 1366775 - /usr/libexec/gnome-settings-daemon is hammering CPU after login tring to connect to local printing service
Summary: /usr/libexec/gnome-settings-daemon is hammering CPU after login tring to conn...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: cups
Version: 25
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Zdenek Dohnal
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 1368909 1372092 1380260 (view as bug list)
Depends On:
Blocks: F25FinalBlocker
TreeView+ depends on / blocked
 
Reported: 2016-08-12 18:59 UTC by Tomasz Kłoczko
Modified: 2016-10-04 05:56 UTC (History)
18 users (show)

Fixed In Version: cups-2.2.0-2.fc25
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-09-24 15:13:20 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
logging output from gdb attached to gnome-settings-daemon with problem reproduced (24.78 KB, text/plain)
2016-09-15 11:36 UTC, Christian Stadelmann
no flags Details
Proposed patch (1.50 KB, patch)
2016-09-22 14:02 UTC, Zdenek Dohnal
no flags Details | Diff


Links
System ID Private Priority Status Summary Last Updated
GNOME Bugzilla 768174 0 Normal RESOLVED Printers panel and gnome-settings-deamon spinning when cups isn't running (and disabled) 2020-10-07 14:25:53 UTC
Github apple cups issues 4870 0 'None' closed libcups attempted to connect to daemon endlessly if there's no daemon running 2020-10-07 14:25:44 UTC

Description Tomasz Kłoczko 2016-08-12 18:59:26 UTC
Description of problem:
Just found that /usr/libexec/gnome-settings-daemon is hammering CPU after login to Gnome.


Version-Release number of selected component (if applicable):
# rpm -qf /usr/libexec/gnome-settings-daemon
gnome-settings-daemon-3.20.1-3.fc25.x86_64


How reproducible:


Steps to Reproduce:
1. Open GUI Gnome session 
2. check activity of the /usr/libexec/gnome-settings-daemon
3.

Actual results:


Expected results:


Additional info:

I made additional diagnostics observing wht is doing /usr/libexec/gnome-settings-daemon using strace. Seems /usr/libexec/gnome-settings-daemon is trying to connect to ipv6 localhost on port 631.

After attaching to gnome-settings-daemon using strace in putput I see few times a second repeated:

--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=4623, si_uid=1000} ---
close(20)                               = 0
socket(AF_INET6, SOCK_STREAM, IPPROTO_IP) = 20
setsockopt(20, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
setsockopt(20, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0
setsockopt(20, SOL_TCP, TCP_NODELAY, [1], 4) = 0
fcntl(20, F_SETFD, FD_CLOEXEC)          = 0
fcntl(20, F_GETFL)                      = 0x2 (flags O_RDWR)
fcntl(20, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
connect(20, {sa_family=AF_INET6, sin6_port=htons(631), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, 28) = -1 EINPROGRESS (Operation now in progress)
fcntl(20, F_SETFL, O_RDWR)              = 0
poll([{fd=20, events=POLLIN|POLLOUT}], 1, 100) = 1 ([{fd=20, revents=POLLIN|POLLOUT|POLLERR|POLLHUP}])
sendto(20, "POST / HTTP/1.1\r\nContent-Length:"..., 193, 0, NULL, 0) = -1 ECONNREFUSED (Connection refused)
sendto(20, "POST / HTTP/1.1\r\nContent-Length:"..., 193, 0, NULL, 0) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=4623, si_uid=1000} ---
sendto(20, "POST / HTTP/1.1\r\nContent-Length:"..., 193, 0, NULL, 0) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=4623, si_uid=1000} ---
close(20)                               = 0
socket(AF_INET6, SOCK_STREAM, IPPROTO_IP) = 20
setsockopt(20, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
setsockopt(20, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0
setsockopt(20, SOL_TCP, TCP_NODELAY, [1], 4) = 0
fcntl(20, F_SETFD, FD_CLOEXEC)          = 0
fcntl(20, F_GETFL)                      = 0x2 (flags O_RDWR)
fcntl(20, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
connect(20, {sa_family=AF_INET6, sin6_port=htons(631), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, 28) = -1 EINPROGRESS (Operation now in progress)
fcntl(20, F_SETFL, O_RDWR)              = 0
poll([{fd=20, events=POLLIN|POLLOUT}], 1, 100) = 1 ([{fd=20, revents=POLLIN|POLLOUT|POLLERR|POLLHUP}])
sendto(20, "POST / HTTP/1.1\r\nContent-Length:"..., 193, 0, NULL, 0) = -1 ECONNREFUSED (Connection refused)
sendto(20, "POST / HTTP/1.1\r\nContent-Length:"..., 193, 0, NULL, 0) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=4623, si_uid=1000} ---
sendto(20, "POST / HTTP/1.1\r\nContent-Length:"..., 193, 0, NULL, 0) = -1 EPIPE (Broken pipe)

[root@domek ~]# grep -w 631 /etc/services 
ipp             631/tcp                         # Internet Printing Protocol
ipp             631/udp                         # Internet Printing Protocol

Seems like this process doesn't know what to do if there is no locally started printing service.

Killing tjhs proces does no help because new instance is started.
I found that if I'll start o nterminal "/usr/libexec/gnome-settings-daemon -r" and kill original /usr/libexec/gnome-settings-daemon and after this stop /usr/libexec/gnome-settings-daemon started from terminal by pressing ctrl-c new /usr/libexec/gnome-settings-daemon is not started.

Comment 1 Marek Kašík 2016-08-15 09:09:48 UTC
Actually, it should know what to do. We have there connection test which should avoid this situation. Have you disabled the cups service or removed it somehow?

Comment 2 Tomasz Kłoczko 2016-08-15 09:34:01 UTC
I've disabled it because I don't need it.

[root@domek entries]# rpm -q cups
cups-2.2-0.2b2.fc26.x86_64
[root@domek entries]# systemctl status cups
● cups.service - CUPS Scheduler
   Loaded: loaded (/usr/lib/systemd/system/cups.service; disabled; vendor preset: enabled)
   Active: inactive (dead)
     Docs: man:cupsd(8)

Probably I should uninstall package :)

[root@domek entries]# rpm -e cups
error: Failed dependencies:
	cups is needed by (installed) gutenprint-cups-5.2.11-2.fc24.x86_64
	cups is needed by (installed) foomatic-db-ppds-4.0-50.20150819.fc24.noarch
[root@domek entries]# rpm -e cups gutenprint-cups-5.2.11-2.fc24.x86_64 foomatic-db-ppds-4.0-50.20150819.fc24.noarch
error: Failed dependencies:
	foomatic-db-ppds = 4.0-50.20150819.fc24 is needed by (installed) foomatic-db-4.0-50.20150819.fc24.noarch
[root@domek entries]# rpm -e cups gutenprint-cups-5.2.11-2.fc24.x86_64 foomatic-db-ppds-4.0-50.20150819.fc24.noarch foomatic-db-4.0-50.20150819.fc24.noarch
warning: /etc/cups/subscriptions.conf saved as /etc/cups/subscriptions.conf.rpmsave

I'm not sure is gutenprint or foomatic packages where installed by some suggested dependencies or somehow cups has been added by something else.

Comment 3 Marek Kašík 2016-08-16 10:54:19 UTC
Could you try to run it as "/usr/libexec/gnome-settings-daemon -r --debug" and attach here the log?

Comment 4 Tomasz Kłoczko 2016-08-17 20:12:51 UTC
$ /usr/libexec/gnome-settings-daemon -r --debug
** (gnome-settings-daemon:26075): DEBUG: Starting settings manager
** (gnome-settings-daemon:26075): DEBUG: loading PNPIDs
** (gnome-settings-daemon:26075): DEBUG: Loading settings plugins from dir: /usr/lib64/gnome-settings-daemon-3.0/
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/a11y-keyboard.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='Accessibility Keyboard' file='/usr/lib64/gnome-settings-daemon-3.0/a11y-keyboard.gnome-settings-plugin' location='a11y-keyboard'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/a11y-settings.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='Accessibility settings' file='/usr/lib64/gnome-settings-daemon-3.0/a11y-settings.gnome-settings-plugin' location='a11y-settings'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/clipboard.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='Clipboard' file='/usr/lib64/gnome-settings-daemon-3.0/clipboard.gnome-settings-plugin' location='clipboard'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/color.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='Colour' file='/usr/lib64/gnome-settings-daemon-3.0/color.gnome-settings-plugin' location='color'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/datetime.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='Date and Time' file='/usr/lib64/gnome-settings-daemon-3.0/datetime.gnome-settings-plugin' location='datetime'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/housekeeping.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='Housekeeping' file='/usr/lib64/gnome-settings-daemon-3.0/housekeeping.gnome-settings-plugin' location='housekeeping'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/keyboard.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='Keyboard' file='/usr/lib64/gnome-settings-daemon-3.0/keyboard.gnome-settings-plugin' location='keyboard'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/media-keys.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='Media keys' file='/usr/lib64/gnome-settings-daemon-3.0/media-keys.gnome-settings-plugin' location='media-keys'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/mouse.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='Mouse' file='/usr/lib64/gnome-settings-daemon-3.0/mouse.gnome-settings-plugin' location='mouse'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/orientation.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='Orientation' file='/usr/lib64/gnome-settings-daemon-3.0/orientation.gnome-settings-plugin' location='orientation'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/power.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='Power' file='/usr/lib64/gnome-settings-daemon-3.0/power.gnome-settings-plugin' location='power'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/print-notifications.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='Print-notifications' file='/usr/lib64/gnome-settings-daemon-3.0/print-notifications.gnome-settings-plugin' location='print-notifications'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/rfkill.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='Rfkill' file='/usr/lib64/gnome-settings-daemon-3.0/rfkill.gnome-settings-plugin' location='rfkill'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/screensaver-proxy.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='Screensaver Proxy' file='/usr/lib64/gnome-settings-daemon-3.0/screensaver-proxy.gnome-settings-plugin' location='screensaver-proxy'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/sharing.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: Could not find 'Website' in /usr/lib64/gnome-settings-daemon-3.0/sharing.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='Sharing' file='/usr/lib64/gnome-settings-daemon-3.0/sharing.gnome-settings-plugin' location='sharing'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/smartcard.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='Smartcard' file='/usr/lib64/gnome-settings-daemon-3.0/smartcard.gnome-settings-plugin' location='smartcard'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/sound.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='Sound' file='/usr/lib64/gnome-settings-daemon-3.0/sound.gnome-settings-plugin' location='sound'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/wacom.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='Wacom' file='/usr/lib64/gnome-settings-daemon-3.0/wacom.gnome-settings-plugin' location='gsdwacom'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/xrandr.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='XRandR' file='/usr/lib64/gnome-settings-daemon-3.0/xrandr.gnome-settings-plugin' location='xrandr'
** (gnome-settings-daemon:26075): DEBUG: Loading plugin: /usr/lib64/gnome-settings-daemon-3.0/xsettings.gnome-settings-plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsPluginInfo: name='X Settings' file='/usr/lib64/gnome-settings-daemon-3.0/xsettings.gnome-settings-plugin' location='xsettings'
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec24e8a0 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/libpower.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdPowerPlugin
(gnome-settings-daemon:26075): power-plugin-DEBUG: GsdPower initializing
(gnome-settings-daemon:26075): power-plugin-DEBUG: Activating gsd_power plugin
(gnome-settings-daemon:26075): power-plugin-DEBUG: Starting power manager
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated power
** (gnome-settings-daemon:26075): DEBUG: Plugin power: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec25a9e0 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/libhousekeeping.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdHousekeepingPlugin
(gnome-settings-daemon:26075): housekeeping-plugin-DEBUG: GsdHousekeeping initializing
(gnome-settings-daemon:26075): housekeeping-plugin-DEBUG: Activating gsd_housekeeping plugin
(gnome-settings-daemon:26075): housekeeping-plugin-DEBUG: Starting housekeeping manager
(gnome-settings-daemon:26075): housekeeping-plugin-DEBUG: housekeeping: will tidy up in 2 minutes
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated housekeeping
** (gnome-settings-daemon:26075): DEBUG: Plugin housekeeping: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x7efcac004b70 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/libxsettings.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GnomeXSettingsPlugin
** (gnome-settings-daemon:26075): DEBUG: GnomeXSettings initializing
** (gnome-settings-daemon:26075): DEBUG: Activating gnome_xsettings plugin
** (gnome-settings-daemon:26075): DEBUG: Starting xsettings manager
** (gnome-settings-daemon:26075): DEBUG: Starting remote-display manager

** (gnome-settings-daemon:26075): WARNING **: Schemas 'org.gnome.desktop.a11y' has not been setup
** (gnome-settings-daemon:26075): DEBUG: GsdXSettingsGtk initializing
** (gnome-settings-daemon:26075): DEBUG: Setting GTK modules 'pk-gtk-module:canberra-gtk-module'
** (gnome-settings-daemon:26075): DEBUG: xft_settings_set_xresources: orig res 'Xft.dpi:	96
Xft.hinting:	1
Xft.hintstyle:	hintslight
Xft.antialias:	1
Xft.rgba:	none
Xcursor.size:	24
Xcursor.theme:	Adwaita
'
** (gnome-settings-daemon:26075): DEBUG: xft_settings_set_xresources: new res 'Xft.dpi:	96
Xft.hinting:	1
Xft.hintstyle:	hintslight
Xft.antialias:	1
Xft.rgba:	none
Xcursor.size:	24
Xcursor.theme:	Adwaita
'
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated xsettings
** (gnome-settings-daemon:26075): DEBUG: Plugin xsettings: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec2122d0 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/libxrandr.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdXrandrPlugin
(gnome-settings-daemon:26075): xrandr-plugin-DEBUG: GsdXrandr initializing
(gnome-settings-daemon:26075): xrandr-plugin-DEBUG: Activating gsd_xrandr plugin
(gnome-settings-daemon:26075): xrandr-plugin-DEBUG: Starting xrandr manager
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated xrandr
** (gnome-settings-daemon:26075): DEBUG: Plugin xrandr: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec212370 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/libsound.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdSoundPlugin
(gnome-settings-daemon:26075): sound-plugin-DEBUG: GsdSound initializing
(gnome-settings-daemon:26075): sound-plugin-DEBUG: Activating gsd_sound plugin
(gnome-settings-daemon:26075): sound-plugin-DEBUG: Starting sound manager
(gnome-settings-daemon:26075): sound-plugin-DEBUG: Registering directory monitor for /home/tkloczko/.local/share/sounds
(gnome-settings-daemon:26075): sound-plugin-DEBUG: Registering directory monitor for /usr/share/sounds
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated sound
** (gnome-settings-daemon:26075): DEBUG: Plugin sound: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec212140 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/libgsdwacom.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdWacomPlugin
(gnome-settings-daemon:26075): wacom-plugin-DEBUG: GsdWacom initializing
(gnome-settings-daemon:26075): wacom-plugin-DEBUG: Activating gsd_wacom plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated gsdwacom
** (gnome-settings-daemon:26075): DEBUG: Plugin gsdwacom: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec2120a0 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/libkeyboard.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdKeyboardPlugin
(gnome-settings-daemon:26075): keyboard-plugin-DEBUG: GsdKeyboard initializing
(gnome-settings-daemon:26075): keyboard-plugin-DEBUG: Activating gsd_keyboard plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated keyboard
** (gnome-settings-daemon:26075): DEBUG: Plugin keyboard: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec264e80 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/libmouse.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdMousePlugin
(gnome-settings-daemon:26075): mouse-plugin-DEBUG: GsdMouse initializing
(gnome-settings-daemon:26075): mouse-plugin-DEBUG: Activating gsd_mouse plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated mouse
** (gnome-settings-daemon:26075): DEBUG: Plugin mouse: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec212050 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/liba11y-settings.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdA11ySettingsPlugin
(gnome-settings-daemon:26075): a11y-settings-plugin-DEBUG: GsdA11ySettings initializing
(gnome-settings-daemon:26075): a11y-settings-plugin-DEBUG: Activating gsd_a11y_settings plugin
(gnome-settings-daemon:26075): a11y-settings-plugin-DEBUG: Starting a11y_settings manager
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated a11y-settings
** (gnome-settings-daemon:26075): DEBUG: Plugin a11y-settings: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec2ae4a0 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/liba11y-keyboard.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdA11yKeyboardPlugin
** (gnome-settings-daemon:26075): DEBUG: GsdA11yKeyboard initializing
** (gnome-settings-daemon:26075): DEBUG: Activating gsd_a11y_keyboard plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated a11y-keyboard
** (gnome-settings-daemon:26075): DEBUG: Plugin a11y-keyboard: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec2ae4f0 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/libsmartcard.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdSmartcardPlugin
(gnome-settings-daemon:26075): smartcard-plugin-DEBUG: GsdSmartcard initializing
(gnome-settings-daemon:26075): smartcard-plugin-DEBUG: GsdSmartcardManagerError: Registering dbus error org.gnome.SettingsDaemon.Smartcard.Manager.Error.Generic
(gnome-settings-daemon:26075): smartcard-plugin-DEBUG: GsdSmartcardManagerError: Registering dbus error org.gnome.SettingsDaemon.Smartcard.Manager.Error.WithNss
(gnome-settings-daemon:26075): smartcard-plugin-DEBUG: GsdSmartcardManagerError: Registering dbus error org.gnome.SettingsDaemon.Smartcard.Manager.Error.LoadingDriver
(gnome-settings-daemon:26075): smartcard-plugin-DEBUG: GsdSmartcardManagerError: Registering dbus error org.gnome.SettingsDaemon.Smartcard.Manager.Error.WatchingForEvents
(gnome-settings-daemon:26075): smartcard-plugin-DEBUG: GsdSmartcardManagerError: Registering dbus error org.gnome.SettingsDaemon.Smartcard.Manager.Error.ReportingEvents
(gnome-settings-daemon:26075): smartcard-plugin-DEBUG: GsdSmartcardManagerError: Registering dbus error org.gnome.SettingsDaemon.Smartcard.Manager.Error.FindingSmartcard
(gnome-settings-daemon:26075): smartcard-plugin-DEBUG: Activating gsd_smartcard plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated smartcard
** (gnome-settings-daemon:26075): DEBUG: Plugin smartcard: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec2ae540 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/libscreensaver-proxy.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdScreensaverProxyPlugin
(gnome-settings-daemon:26075): screensaver-proxy-plugin-DEBUG: GsdScreensaverProxy initializing
(gnome-settings-daemon:26075): screensaver-proxy-plugin-DEBUG: Activating gsd_screensaver_proxy plugin
(gnome-settings-daemon:26075): screensaver-proxy-plugin-DEBUG: Starting screensaver-proxy manager
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated screensaver-proxy
** (gnome-settings-daemon:26075): DEBUG: Plugin screensaver-proxy: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec2ae590 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/libcolor.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdColorPlugin
(gnome-settings-daemon:26075): color-plugin-DEBUG: GsdColor initializing
(gnome-settings-daemon:26075): color-plugin-DEBUG: Activating gsd_color plugin
(gnome-settings-daemon:26075): color-plugin-DEBUG: Starting color manager
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated color
** (gnome-settings-daemon:26075): DEBUG: Plugin color: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec2ae6d0 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/libsharing.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdSharingPlugin
(gnome-settings-daemon:26075): sharing-plugin-DEBUG: GsdSharing initializing
(gnome-settings-daemon:26075): sharing-plugin-DEBUG: Activating gsd_sharing plugin
(gnome-settings-daemon:26075): sharing-plugin-DEBUG: Starting sharing manager
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated sharing
** (gnome-settings-daemon:26075): DEBUG: Plugin sharing: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec2ae990 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/librfkill.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdRfkillPlugin
(gnome-settings-daemon:26075): rfkill-plugin-DEBUG: GsdRfkill initializing
(gnome-settings-daemon:26075): rfkill-plugin-DEBUG: Activating gsd_rfkill plugin
(gnome-settings-daemon:26075): rfkill-plugin-DEBUG: Read killswitch of type 'WLAN' (idx=0): soft 0 hard 0
(gnome-settings-daemon:26075): rfkill-plugin-DEBUG: Read killswitch of type 'BLUETOOTH' (idx=1): soft 0 hard 0
(gnome-settings-daemon:26075): rfkill-plugin-DEBUG: Read killswitch of type 'WLAN' (idx=2): soft 0 hard 0
(gnome-settings-daemon:26075): rfkill-plugin-DEBUG: Read killswitch of type 'BLUETOOTH' (idx=3): soft 0 hard 0
(gnome-settings-daemon:26075): rfkill-plugin-DEBUG: Added rfkill with ID 0
(gnome-settings-daemon:26075): rfkill-plugin-DEBUG: Added Bluetooth rfkill with ID 1
(gnome-settings-daemon:26075): rfkill-plugin-DEBUG: Added rfkill with ID 2
(gnome-settings-daemon:26075): rfkill-plugin-DEBUG: Added Bluetooth rfkill with ID 3
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated rfkill
** (gnome-settings-daemon:26075): DEBUG: Plugin rfkill: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec2ae400 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/libprint-notifications.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdPrintNotificationsPlugin
(gnome-settings-daemon:26075): print-notifications-plugin-DEBUG: GsdPrintNotifications initializing
(gnome-settings-daemon:26075): print-notifications-plugin-DEBUG: Activating gsd_print_notifications plugin
(gnome-settings-daemon:26075): print-notifications-plugin-DEBUG: Starting print-notifications manager
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated print-notifications
** (gnome-settings-daemon:26075): DEBUG: Plugin print-notifications: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec24e990 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/liborientation.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdOrientationPlugin
(gnome-settings-daemon:26075): orientation-plugin-DEBUG: GsdOrientation initializing
(gnome-settings-daemon:26075): orientation-plugin-DEBUG: Activating gsd_orientation plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated orientation
** (gnome-settings-daemon:26075): DEBUG: Plugin orientation: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec2aeb20 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/libmedia-keys.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdMediaKeysPlugin
(gnome-settings-daemon:26075): media-keys-plugin-DEBUG: GsdMediaKeys initializing
(gnome-settings-daemon:26075): media-keys-plugin-DEBUG: Adding system inhibitors for power keys
(gnome-settings-daemon:26075): media-keys-plugin-DEBUG: Activating gsd_media_keys plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated media-keys
** (gnome-settings-daemon:26075): DEBUG: Plugin media-keys: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec2fa540 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/libdatetime.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdDatetimePlugin
(gnome-settings-daemon:26075): datetime-plugin-DEBUG: GsdDatetime initializing
(gnome-settings-daemon:26075): datetime-plugin-DEBUG: Activating gsd_datetime plugin
(gnome-settings-daemon:26075): datetime-plugin-DEBUG: Starting datetime manager
(gnome-settings-daemon:26075): datetime-plugin-DEBUG: Automatic timezone enabled
(gnome-settings-daemon:26075): datetime-plugin-DEBUG: Starting timezone monitor
(gnome-settings-daemon:26075): datetime-plugin-DEBUG: Incomplete GWeather location entry: (UM) Wake Island, Wake Island Army Airfield Airport
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated datetime
** (gnome-settings-daemon:26075): DEBUG: Plugin datetime: active
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsModule 0x5609ec2aead0 initialising
** (gnome-settings-daemon:26075): DEBUG: Loading /usr/lib64/gnome-settings-daemon-3.0/libclipboard.so
** (gnome-settings-daemon:26075): DEBUG: Creating object of type GsdClipboardPlugin
(gnome-settings-daemon:26075): clipboard-plugin-DEBUG: GsdClipboard initializing
(gnome-settings-daemon:26075): clipboard-plugin-DEBUG: Activating gsd_clipboard plugin
** (gnome-settings-daemon:26075): DEBUG: GnomeSettingsManager: emitting plugin-activated clipboard
** (gnome-settings-daemon:26075): DEBUG: Plugin clipboard: active
** (gnome-settings-daemon:26075): DEBUG: Failed to set the environment: GDBus.Error:org.gnome.SessionManager.NotInInitialization: Setenv interface is only available during the DisplayServer and Initialization phase
** (gnome-settings-daemon:26075): DEBUG: Failed to set the environment: GDBus.Error:org.gnome.SessionManager.NotInInitialization: Setenv interface is only available during the DisplayServer and Initialization phase
** (gnome-settings-daemon:26075): DEBUG: Failed to set the environment: GDBus.Error:org.gnome.SessionManager.NotInInitialization: Setenv interface is only available during the DisplayServer and Initialization phase
** (gnome-settings-daemon:26075): DEBUG: Failed to set the environment: GDBus.Error:org.gnome.SessionManager.NotInInitialization: Setenv interface is only available during the DisplayServer and Initialization phase
** (gnome-settings-daemon:26075): DEBUG: Failed to set the environment: GDBus.Error:org.gnome.SessionManager.NotInInitialization: Setenv interface is only available during the DisplayServer and Initialization phase
** (gnome-settings-daemon:26075): DEBUG: Failed to set the environment: GDBus.Error:org.gnome.SessionManager.NotInInitialization: Setenv interface is only available during the DisplayServer and Initialization phase
** (gnome-settings-daemon:26075): DEBUG: Failed to set the environment: GDBus.Error:org.gnome.SessionManager.NotInInitialization: Setenv interface is only available during the DisplayServer and Initialization phase
(gnome-settings-daemon:26075): media-keys-plugin-DEBUG: System inhibitor fd is 18
** (gnome-settings-daemon:26075): DEBUG: Vino vanished
** (gnome-settings-daemon:26075): DEBUG: Registered client at path /org/gnome/SessionManager/Client8
(gnome-settings-daemon:26075): keyboard-plugin-DEBUG: Starting keyboard manager
(gnome-settings-daemon:26075): keyboard-plugin-DEBUG: Started the keyboard plugin, applying all settings
(gnome-settings-daemon:26075): keyboard-plugin-DEBUG: Applying the bell settings
(gnome-settings-daemon:26075): keyboard-plugin-DEBUG: Applying the num-lock settings
** (gnome-settings-daemon:26075): DEBUG: Starting a11y_keyboard manager
(gnome-settings-daemon:26075): smartcard-plugin-DEBUG: attempting to load NSS database '/etc/pki/nssdb'
(gnome-settings-daemon:26075): smartcard-plugin-DEBUG: NSS database '/etc/pki/nssdb' loaded


Above is last line of the debug output and after this this process starts consuming whole single CPU core. From top output:

top - 21:10:04 up 3 days, 23:45,  2 users,  load average: 2.61, 2.26, 1.87
Tasks: 324 total,   4 running, 319 sleeping,   0 stopped,   1 zombie
%Cpu(s): 40.7 us, 18.6 sy,  0.0 ni, 36.4 id,  0.4 wa,  0.0 hi,  3.9 si,  0.0 st
KiB Mem :  8088772 total,   445000 free,  4461116 used,  3182656 buff/cache
KiB Swap: 10485756 total,  9037972 free,  1447784 used.  3004080 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                              
 5290 tkloczko  20   0 4006896 2.431g 146220 R 103.3 31.5 237:03.34 /usr/lib64/firefox/firefox                                                                           
26075 tkloczko  20   0 1045592  36824  26420 R 100.0  0.5   3:03.62 /usr/libexec/gnome-settings-daemon -r --debug

After tracing pid 26075 using strace I see that it does what I've origially reported and none of additioanl messages are sent on stdout/stderr.

Comment 5 Tomasz Kłoczko 2016-08-17 20:39:32 UTC
Just downloaded and unpacked src.rpm and I see that connections to loacalhosts are only from 3 points in source code:

plugins/print-notifications/gsd-printer.c:        uri = g_strdup_printf ("ipp://localhost/printers/%s",
plugins/print-notifications/gsd-print-notifications-manager.c:            (g_ascii_strncasecmp (server_name, "localhost", 9) == 0 ||
plugins/print-notifications/gsd-print-notifications-manager.c:                        job_uri = g_strdup_printf ("ipp://localhost/jobs/%d", notify_job_id);
po/mk.po:# Maratonec 4 <maraton>, 2002.

Comment 6 Tomasz Kłoczko 2016-08-22 19:56:06 UTC
For the record only.
Link to this external bug report: https://bugzilla.gnome.org/show_bug.cgi?id=768174

Comment 7 Marek Kašík 2016-09-01 10:33:21 UTC
This is probably a bug in CUPS which was introduced between 2.1.4 and 2.2. It seems that it could be this issue: https://github.com/apple/cups/issues/4870.
I've tried the fix which is already in repository (the "http*Connect did not work on Linux when cupsd was not running") but it doesn't fix it for me yet. Downgrading to 2.1.4 fixes the problem for me.

Comment 8 Marek Kašík 2016-09-01 10:38:42 UTC
*** Bug 1368909 has been marked as a duplicate of this bug. ***

Comment 9 Christian Stadelmann 2016-09-01 11:23:11 UTC
*** Bug 1372092 has been marked as a duplicate of this bug. ***

Comment 10 Christian Stadelmann 2016-09-01 11:28:41 UTC
Bugzilla just added the BetaBlocker from my closed duplicate here (interesting, didn't expect that to happen automatically). For the record, here comes the justification I originally put to https://bugzilla.redhat.com/show_bug.cgi?id=1372092#c1 :

Nominating as blocker since
* This bug results in a general system slowdown
* Applications relying on g-s-d break, miss functionality or are rendered useless
* Login takes very long (>10 seconds compared to 2 seconds on F24 on the same machine)
* Logout takes _very_ long (about 30 seconds compared to <1 second on F24 on the same machine)

Citing Beta Release Criteria [1], section "Shutdown, reboot, logout":

Similar to the Alpha criterion for shutting down, shutdown and reboot mechanisms must take storage volumes down cleanly and correctly request a shutdown or reboot from the system firmware. Logging out must return the user to the environment from which they logged in, working as expected. 

logout of 30 seconds is not expected.

I won't mind if it won't make for a Beta blocker, Final blocker or freeze exception would be fine too.

Comment 11 Tomasz Kłoczko 2016-09-03 12:57:47 UTC
Just found that exactly the same effect is when I'm trying to enter Settings -> Printer.
With empty list of available/defined printers gnome-control-center process eats available CPU.

Comment 12 Adam Williamson 2016-09-12 16:37:57 UTC
So in the blocker meeting discussion of this, we had a few questions:

* Under what circumstances does this happen, exactly? Someone sees it in VMs but not on bare metal, someone else doesn't even see it in a VM, I saw it (at least g-s-d eating CPU time) once but don't see it right now on my bare metal system...

* Are we actually sure that all the 'consequences' listed in #c10 actually happen all the time, and are actually caused by this bug? For instance, I *did* get a rather slow login on my current boot, but I *don't* see g-s-d eating lots of CPU time. Even on the boot where I saw g-s-d eating CPU time, I don't recall seeing 'Applications relying on g-s-d break, miss functionality or are rendered useless', and kparal is sceptical of that as well.

If anyone can clarify these points, it'd be great.

Comment 13 Yanko Kaneti 2016-09-12 18:47:49 UTC
(In reply to Adam Williamson from comment #12)
> So in the blocker meeting discussion of this, we had a few questions:
> 
> * Under what circumstances does this happen, exactly? Someone sees it in VMs
> but not on bare metal, someone else doesn't even see it in a VM, I saw it
> (at least g-s-d eating CPU time) once but don't see it right now on my bare
> metal system...

Stop cups service, and disable the cups socket. Then either logout/login or start gnome-control-center->printers.

> 
> * Are we actually sure that all the 'consequences' listed in #c10 actually
> happen all the time, and are actually caused by this bug? For instance, I
> *did* get a rather slow login on my current boot, but I *don't* see g-s-d
> eating lots of CPU time. Even on the boot where I saw g-s-d eating CPU time,
> I don't recall seeing 'Applications relying on g-s-d break, miss
> functionality or are rendered useless', and kparal is sceptical of that as
> well.

Getting gnome-settings-daemon in an loop which prevents it from loading properly all its plugins could break a number of things depenging on the order it happens, from keyboard shortcuts to power management, to tablet handling, to mouse settings....

Comment 14 Christian Stadelmann 2016-09-12 18:58:11 UTC
(In reply to Adam Williamson from comment #12)
> So in the blocker meeting discussion of this, we had a few questions:

I hope to give some answers but that's probably not enough so feel free to add more.

> * Under what circumstances does this happen, exactly? Someone sees it in VMs
> but not on bare metal, someone else doesn't even see it in a VM, I saw it
> (at least g-s-d eating CPU time) once but don't see it right now on my bare
> metal system...

Some conditions to trigger this bug:
* have cups-libs-2.2 installed. 2.1.4 doesn't have this problem.

Some conditions I am not sure about:
* Don't have cups daemon installed
* or don't have cups daemon running
* or don't have a printer installed

> * Are we actually sure that all the 'consequences' listed in #c10 actually
> happen all the time, and are actually caused by this bug? For instance, I
> *did* get a rather slow login on my current boot, but I *don't* see g-s-d
> eating lots of CPU time. Even on the boot where I saw g-s-d eating CPU time,
> I don't recall seeing 'Applications relying on g-s-d break, miss
> functionality or are rendered useless', and kparal is sceptical of that as
> well.

Some consequences:
* gnome-shell indicators for WLAN doesn't work
* display brightness cannot be changed from gnome-shell any more
* changing stuff in gnome-control-center or gnome-tweak-tool sometimes doesn't have any effect at all, sometimes is applied only on next login



Exact steps to reproduce for me:
0. have a Fedora 25 Alpha.2 x86_64 iso
1. install in a VM
2. run `dnf remove cups cups-f*`
3. run `rm -rf /etc/cups`
4. reboot and login

Comment 15 Adam Williamson 2016-09-12 21:40:44 UTC
If you have to actively disable the CUPS service or wipe files in /etc to trigger this, we're not likely to accept it as a blocker. It's only likely to be a blocker if you can encounter it without doing any of that stuff.

Comment 16 Geoffrey Marr 2016-09-13 00:23:28 UTC
Discussed during the 2016-09-12 blocker review meeting: [1]

The decision to delay the classification of this as a bug was made as we generally agree this doesn't violate the criteria sufficiently to be considered a Beta blocker, however we will consider this bug again as a Final blocker as there are several unclear issues with this that we want to consult about before a decision is made.

[1] https://meetbot.fedoraproject.org/fedora-blocker-review/2016-09-12/f25-blocker-review.2016-09-12-16.01.txt

Comment 17 Marek Kašík 2016-09-14 12:15:53 UTC
Just a note, I've just tested the new patch from Michael but gnome-settings-daemon still consumes ~80% of CPU (https://github.com/apple/cups/commit/e8916f41d892d9f24837101c845f32d215bdc04d).

Comment 18 Tim Waugh 2016-09-15 10:45:16 UTC
Is this a CUPS change? Is the component wrong for this bug?

Comment 19 Marek Kašík 2016-09-15 11:06:17 UTC
CUPS 2.1.4 doesn't cause the issue so I think the component is correct.

Comment 20 Christian Stadelmann 2016-09-15 11:36:57 UTC
Created attachment 1201185 [details]
logging output from gdb attached to gnome-settings-daemon with problem reproduced

I've attached a backtrace for this bug. It seems like cups-libs doesn't care that cups.socket is missing but retries again and again, triggering SIGPIPE all the time.

(In reply to Christian Stadelmann from comment #10)
> * Login takes very long (>10 seconds compared to 2 seconds on F24 on the
> same machine)

Actually, this is a separate bug. I don't know where to report it though. Trying to investigate further.

Comment 21 Christian Stadelmann 2016-09-16 20:35:21 UTC
An upgrade to cups 2.2.0-1.fc25 doesn't fix the bug despite github issue #4870 being marked as fixed.

Noe that this bug causes every logout to fail, always resulting in a forced kill of gnome-shell and other GUI applications.

Comment 22 Christian Stadelmann 2016-09-19 11:13:44 UTC
I've added a new (2.2.0-1.fc25) backtrace to upstream, hoping they are able to fix this.

Comment 23 Tomasz Kłoczko 2016-09-19 11:41:48 UTC
Just tested and cups 2.2.0 still has this issue :(

Comment 24 Petr Schindler 2016-09-19 17:45:39 UTC
Discussed at 2016-09-19 blocker review meeting: [1]. 

We decided to delay the decision:  Based on information gathered during the meeting, it seems like there is a possibility of multiple bugs here. Until we can confirm that this is one single bug, we are delaying the classification of this as a blocker.

[1] https://meetbot-raw.fedoraproject.org/fedora-blocker-review/2016-09-19/

Comment 25 Zdenek Dohnal 2016-09-19 19:00:55 UTC
It seems this pull request [1] fixes this issue. I tested it on Fedora 25 by running testcups (as Michael suggested on github) and running 'make check'. When I disabled CUPS and opened Settings -> Printers gnome-control-center doesn't consume large amount of CPU. Printing test page was successful. Scratch build is available at [2]. Would you mind testing it?

[1] https://github.com/xuzhen/cups/commit/aea1878c64f580700bb27b61068dccb1593a3bc3
[2] http://koji.fedoraproject.org/koji/taskinfo?taskID=15708849

Comment 26 Zdenek Dohnal 2016-09-19 19:02:54 UTC
I will wait for Michael opinion on this patch before I will push this to git.

Comment 27 Marek Kašík 2016-09-20 08:19:40 UTC
Thank you for the scratch build, it fixes the problem for me.

Comment 28 Michael Catanzaro 2016-09-20 21:45:09 UTC
(In reply to Zdenek Dohnal from comment #25)
> It seems this pull request [1] fixes this issue.

Andreas Henriksson on IRC reports that [2] (different commit with a different upstream issue number!) fixes the issue for him.

[2] https://github.com/apple/cups/commit/0ca77b3e89dc1f75c91e1a084dba861e378c6c8d

Comment 29 Zdenek Dohnal 2016-09-21 08:14:45 UTC
(In reply to Michael Catanzaro from comment #28)
> Andreas Henriksson on IRC reports that [2] (different commit with a
> different upstream issue number!) fixes the issue for him.
> 
> [2]
> https://github.com/apple/cups/commit/0ca77b3e89dc1f75c91e1a084dba861e378c6c8d

Yes, that is new commit from Michael, he fixed it more sophisticated way. I will test it and I will build it after that.

Comment 30 Tomasz Kłoczko 2016-09-21 12:29:54 UTC
Even if this patch will fix looping in partial failing service IMO bug still is in different place because cups client library should not be trying to initialize any service if there is no any printers defined.
Looks like cups initialisation is trying to establish connectivity to the printer even with empty list of printers.
IMO this should not be like this.

Just found that reported here bug is affecting even lpstat.cups command. This command started without parameters or with -l is looping as well trying to establish connectivity to localhost. However:

[root@domek cups]# rpm -qa \^cups\*
cups-filters-libs-1.11.2-1.fc26.x86_64
cups-devel-2.2.0-1.fc26.x86_64
cups-filesystem-2.2.0-1.fc26.noarch
cups-filters-1.11.2-1.fc26.x86_64
cups-libs-2.2.0-1.fc26.x86_64
cups-client-2.2.0-1.fc26.x86_64
cups-pk-helper-0.2.6-1.fc24.x86_64
cups-debuginfo-2.2.0-1.fc26.x86_64

[root@domek cups]# lpstat.cups -H
localhost:631
[root@domek cups]# rpm -qal cups\* | grep /etc | xargs grep localhost

So looks like localhost:631 print server is hardcoded into library.
IMO we can talk here about at least two bugs.

Comment 31 Zdenek Dohnal 2016-09-22 08:54:10 UTC
For now, scratch build fixing looping in partial failing service:

http://koji.fedoraproject.org/koji/taskinfo?taskID=15732870

Comment 32 Zdenek Dohnal 2016-09-22 13:36:42 UTC
(In reply to Tomasz Kłoczko from comment #30)
> Even if this patch will fix looping in partial failing service IMO bug still
> is in different place because cups client library should not be trying to
> initialize any service if there is no any printers defined.
> Looks like cups initialisation is trying to establish connectivity to the
> printer even with empty list of printers.
> IMO this should not be like this.

This is correct behavior. LibCUPS needs to try to initialize cupsd service, because libcups does not know that there are no printers from start (that information is sent by cupsd on libcups' request). And if cupsd does not run, this try fails.  

> 
> Just found that reported here bug is affecting even lpstat.cups command.
> This command started without parameters or with -l is looping as well trying
> to establish connectivity to localhost. However:
> 

I did not encounter any loop when running lpstat after the newest update. It ends immediately with message 'lpstat: Bad file descriptor'.

> [root@domek cups]# rpm -qa \^cups\*
> cups-filters-libs-1.11.2-1.fc26.x86_64
> cups-devel-2.2.0-1.fc26.x86_64
> cups-filesystem-2.2.0-1.fc26.noarch
> cups-filters-1.11.2-1.fc26.x86_64
> cups-libs-2.2.0-1.fc26.x86_64
> cups-client-2.2.0-1.fc26.x86_64
> cups-pk-helper-0.2.6-1.fc24.x86_64
> cups-debuginfo-2.2.0-1.fc26.x86_64
> 
> [root@domek cups]# lpstat.cups -H
> localhost:631
> [root@domek cups]# rpm -qal cups\* | grep /etc | xargs grep localhost
> 
> So looks like localhost:631 print server is hardcoded into library.
> IMO we can talk here about at least two bugs.

When I ran your commands, I got different results (after stopping and disabling cupsd):

[root@localhost ~]# rpm -qa \^cups\*
cups-client-2.2.0-2.fc25.x86_64
cups-pk-helper-0.2.6-1.fc24.x86_64
cups-lpd-2.2.0-2.fc25.x86_64
cups-debuginfo-2.2.0-2.fc25.x86_64
cups-filters-1.10.0-3.fc25.x86_64
cups-filesystem-2.2.0-2.fc25.noarch
cups-devel-2.2.0-2.fc25.x86_64
cups-filters-libs-1.10.0-3.fc25.x86_64
cups-libs-2.2.0-2.fc25.x86_64
cups-2.2.0-2.fc25.x86_64
cups-ipptool-2.2.0-2.fc25.x86_64

[root@localhost ~]# lpstat.cups -H
localhost:631

[root@localhost ~]# rpm -qal cups\* | grep /etc | xargs grep localhost
grep: /etc/cups: Is a directory
/etc/cups/cupsd.conf:Listen localhost:631
/etc/cups/cupsd.conf.default:Listen localhost:631
grep: /etc/cups/ppd: Is a directory
grep: /etc/cups/ssl: Is a directory

[root@localhost ~]# lpstat -l
lpstat: Bad file descriptor

So after stopping+disabling cupsd, libcups is trying to access address and port, on which cupsd suppose to listen (when cupsd is running and enabled - even its .socket and .path units in systemd - output of command 'lpstat.cups -H' is /var/run/cups/cups.sock). In your case it is localhost:631, because you have it set in your cupsd.conf file.

Comment 33 Zdenek Dohnal 2016-09-22 14:02:06 UTC
Created attachment 1203772 [details]
Proposed patch

Patch was tested and now is in Bodhi.

Comment 34 Fedora Update System 2016-09-23 05:24:57 UTC
cups-2.2.0-2.fc25 has been pushed to the Fedora 25 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-3b495837e7

Comment 35 Tomasz Kłoczko 2016-09-23 13:18:35 UTC
> This is correct behavior. LibCUPS needs to try to initialize cupsd service, because libcups does not know that there are no printers from start (that information is sent by cupsd on libcups' request). And if cupsd does not run, this try fails. 

Connecting to CUPS service by client library should be IMO done only if it is defined on client side at least one defined printer.
In other words cups client library should not been trying to connect to localhost because nothing guarantees that such printer service (without setup) will be available.
I'm not sure am I understand you correctly .. if above means that libcups is used as well on CUPS service side (in cupsd) it may mean that this library contains more than client API/ABI and someone should shift part of the library code to cupsd code.

> When I ran your commands, I got different results (after stopping and disabling cupsd):
[..]
>[root@localhost ~]# rpm -qal cups\* | grep /etc | xargs grep localhost
>grep: /etc/cups: Is a directory
>/etc/cups/cupsd.conf:Listen localhost:631
>/etc/cups/cupsd.conf.default:Listen localhost:631
>grep: /etc/cups/ppd: Is a directory
>grep: /etc/cups/ssl: Is a directory

/etc/cups/cupsd.conf it is cupsd config file and above lone shows that your cupsd will be listening on localhost.

Client conf file is in /etc/cups/client.conf:

$ strace -e trace=file lpstat 2>&1 | grep cups
open("/lib64/libcups.so.2", O_RDONLY|O_CLOEXEC) = 3
open("/etc/cups/client.conf", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/home/tkloczko/.cups/client.conf", O_RDONLY) = -1 ENOENT (No such file or directory)
access("/var/run/cups/cups.sock", R_OK) = -1 ENOENT (No such file or directory)
^C

Seems like this file is not listed in cups-libs package and it should be added by add at least empty file by add to %install section "> %{buildroot}%{sysconfdir}/cups/client.conf" line and in "%files libs" section "%config(noreplace) %{sysconfdir}/cups/client.conf" line should be added as well to guard proper permission of this file by rpm database verification (rpm -Va).

Again: as long as there is no in /etc/cups/client.conf or ~/.cups/client.conf defined any printers libcups should not been trying to connect to anything.
Hardcoded trying to connect /var/run/cups/cups.sock socket should be removed as well.

Comment 36 Geoffrey Marr 2016-09-23 15:19:10 UTC
Tested with scratch build and with package in updates-testing. No longer experience high CPU usage on login. System reports low CPU usage regardless of whether or not the CUPS service is enabled or disabled. Printed test page successfully. As far as the original issue is concerned (high CPU usage), this update (cups-2.2.0-2.fc25) solves the problem.

Comment 37 Zdenek Dohnal 2016-09-23 15:50:11 UTC
(In reply to Tomasz Kłoczko from comment #35)
> Connecting to CUPS service by client library should be IMO done only if it
> is defined on client side at least one defined printer.
> In other words cups client library should not been trying to connect to
> localhost because nothing guarantees that such printer service (without
> setup) will be available.

How else libcups can find out cupsd isn't running? Libcups needs to try to connect to cupsd, which checks, if there is printer or not. Libcups doesn't know by default, if there is any printer. Libcups is just library, which allows application to act as cups client, which need to send request to cupsd for information. If cupsd isn't running or cups.socket or cups.path is disabled, it ends with error. All is correct behavior.

> I'm not sure am I understand you correctly .. if above means that libcups is
> used as well on CUPS service side (in cupsd) it may mean that this library
> contains more than client API/ABI and someone should shift part of the
> library code to cupsd code.
 
No, libcups is just just library, which allows application to act as cups client, which needs to ask cupsd (server, which is running as service) for info. If cupsd is down, libcups returns error and application, which uses libcups, needs to deal with it.

> /etc/cups/cupsd.conf it is cupsd config file and above lone shows that your
> cupsd will be listening on localhost.

I thought your command stuck in infinite loop, so I sent you my output for you to find out there is no issue in the newest version.

> 
> Client conf file is in /etc/cups/client.conf:
> 
> $ strace -e trace=file lpstat 2>&1 | grep cups
> open("/lib64/libcups.so.2", O_RDONLY|O_CLOEXEC) = 3
> open("/etc/cups/client.conf", O_RDONLY) = -1 ENOENT (No such file or
> directory)
> open("/home/tkloczko/.cups/client.conf", O_RDONLY) = -1 ENOENT (No such file
> or directory)
> access("/var/run/cups/cups.sock", R_OK) = -1 ENOENT (No such file or
> directory)
> ^C

My output of that command:

[zdenekdohnal@localhost ~]$ strace -e trace=file lpstat 2>&1 | grep cups
open("/lib64/libcups.so.2", O_RDONLY|O_CLOEXEC) = 3
open("/etc/cups/client.conf", O_RDONLY) = 3
open("/home/zdenekdohnal/.cups/client.conf", O_RDONLY) = -1 ENOENT (No such file or directory)
access("/var/run/cups/cups.sock", R_OK) = -1 ENOENT (No such file or directory)
access("/usr/share/locale/en_US/cups_en_US.po", F_OK) = -1 ENOENT (No such file or directory)
access("/usr/share/locale/en/cups_en.po", F_OK) = -1 ENOENT (No such file or directory)
open("/usr/share/locale/C/cups_C.po", O_RDONLY) = -1 ENOENT (No such file or directory)

It seems you are missing client.conf, which is shipped with main package of cups. Would you mind finding out if you have installed main package (cups-2.2.0-1)? Because as I look on you output of 'rpm -qa', I do not see any main package. I have empty client.conf and printing works.

> Again: as long as there is no in /etc/cups/client.conf or
> ~/.cups/client.conf defined any printers libcups should not been trying to
> connect to anything.

Even if there is no client.conf, libcups can use discovery.

> Hardcoded trying to connect /var/run/cups/cups.sock socket should be removed
> as well.

This is not 'hardcoded' (if you think hardcoded as something that cannot be change - only in source code), it is default setting in cupsd.conf, which you can change. And any case, I thought you are reporting bug in lpstat (which didn't happen).

Comment 38 Tomasz Kłoczko 2016-09-23 17:46:44 UTC
> How else libcups can find out cupsd isn't running?

If there is no any defined in client.conf printers checking should be abandoned and state of the client library ABI should be assuming that there is no cupsd on localhost.
That is all ..
Checking is cupsd running on the same system is not needed to any client functionalities after client library initialization.

Try to think about other client type service like for example DNS.
If resolver does not have any defined in /etc/resolv.conf lines with "nameserver" resolver functions are not trying to connect named on localhost. Isn't it?
You can find exactly the same pattern in many other client libraries.

> My output of that command:

Yes because you have printer service defined in this file.
I haven't even installed cupsd package.


> libcups is just just library, which allows application to act as cups client, which needs to ask cupsd (server, which is running as service) for info.

So when there is no any printers defined in /etc/cups/clien.conf or ~/.cups/client.conf such library on calling any function after check that there is no any printers should just finish with error that there is no printers.

> Even if there is no client.conf, libcups can use discovery.

Of course if API provides function allowing to connect ad check remote service configuration passing in parameters any arbitrary address of printing service.
However by default libcups should nob be trying to connect to anything as same as libc resolver is not trying to discover DNS server if there is no /etc/resolv.conf or this file is empty.

> No, libcups is just just library, which allows application to act as cups client, which needs to ask cupsd (server, which is running as service) for info. 

Seems it is not entirely true. Just build cups package with LDFLAGS="-Wl,--as-needed" and seems like this linking option is not possible to remove from /usr/sbin/cupsd elf NEEDED list. Seems like CUPS server is using for something library which theoretically should be only client library. Strange ..

Here is my list of changes which you can apply to the spec:

-- 
--- cups.spec.orig      2016-09-15 13:56:10.000000000 +0100
+++ cups.spec   2016-09-23 18:11:49.457152603 +0100
@@ -77,15 +77,13 @@
 BuildRequires: openldap-devel
 BuildRequires: pkgconfig(libusb-1.0)
 BuildRequires: krb5-devel
+BuildRequires: libstdc++-devel
 BuildRequires: pkgconfig(avahi-client)
 BuildRequires: systemd
 BuildRequires: pkgconfig(libsystemd)
 BuildRequires: pkgconfig(dbus-1)
 BuildRequires: automake
 
-# Make sure we get postscriptdriver tags.
-BuildRequires: python-cups
-
 %if %{lspp}
 BuildRequires: libselinux-devel
 BuildRequires: audit-libs-devel
@@ -122,9 +120,6 @@
 Summary: CUPS printing system - development environment
 License: LGPLv2
 Requires: %{name}-libs%{?_isa} = %{epoch}:%{version}-%{release}
-Requires: gnutls-devel
-Requires: krb5-devel
-Requires: zlib-devel
 Provides: cupsddk-devel
 
 %package libs
@@ -284,6 +279,7 @@
 export CFLAGS="$RPM_OPT_FLAGS -fstack-protector-all -DLDAP_DEPRECATED=1"
 # --enable-debug to avoid stripping binaries
 %configure --with-docdir=%{_datadir}/%{name}/www --enable-debug \
+       LDFLAGS="-Wl,--as-need" \
 %if %{lspp}
        --enable-lspp \
 %endif
-- 

python-cups does not need to be installed to build cups python support.
Fact that libcups is linked with gnutls, krb5 and zlib does not mean that anyone who will add -lcups to linking options will need to have even installed those devel packages. None of the cups headers files is using header files from these packages as well.
cups source code contains C++ parts so libstdc++-devel needs to be added

Result of -Wl,--as-need on only "objdump -x /usr/sbin/cups":

--- cups-NEEDED.old	2016-09-23 17:40:41.472774323 +0100
+++ cups-NEEDED.new	2016-09-23 17:40:51.627832704 +0100
@@ -20,14 +20,11 @@
 libc.so.6()(64bit)  
 libc.so.6(GLIBC_2.14)(64bit)  
 libc.so.6(GLIBC_2.15)(64bit)  
-libc.so.6(GLIBC_2.16)(64bit)  
 libc.so.6(GLIBC_2.2.5)(64bit)  
 libc.so.6(GLIBC_2.3)(64bit)  
 libc.so.6(GLIBC_2.3.2)(64bit)  
 libc.so.6(GLIBC_2.3.4)(64bit)  
 libc.so.6(GLIBC_2.4)(64bit)  
-libcom_err.so.2()(64bit)  
-libcrypt.so.1()(64bit)  
 libcups.so.2()(64bit)  
 libcupscgi.so.1()(64bit)  
 libcupsimage.so.2()(64bit)  
@@ -35,14 +32,10 @@
 libcupsppdc.so.1()(64bit)  
 libdbus-1.so.3()(64bit)  
 libdbus-1.so.3(LIBDBUS_1_3)(64bit)  
-libdl.so.2()(64bit)  
 libgcc_s.so.1()(64bit)  
 libgcc_s.so.1(GCC_3.0)(64bit)  
-libgnutls.so.30()(64bit)  
 libgssapi_krb5.so.2()(64bit)  
 libgssapi_krb5.so.2(gssapi_krb5_2_MIT)(64bit)  
-libk5crypto.so.3()(64bit)  
-libkrb5.so.3()(64bit)  
 libm.so.6()(64bit)  
 libm.so.6(GLIBC_2.2.5)(64bit)  
 libpam.so.0()(64bit)  
@@ -53,12 +46,10 @@
 libselinux.so.1()(64bit)  
 libstdc++.so.6()(64bit)  
 libstdc++.so.6(CXXABI_1.3)(64bit)  
-libstdc++.so.6(CXXABI_1.3.9)(64bit)  
 libstdc++.so.6(GLIBCXX_3.4)(64bit)  
 libsystemd.so.0()(64bit)  
 libsystemd.so.0(LIBSYSTEMD_209)(64bit)  
 libusb-1.0.so.0()(64bit)  
-libz.so.1()(64bit)  
 rpmlib(CompressedFileNames) <= 3.0.4-1
 rpmlib(FileDigests) <= 4.6.0-1
 rpmlib(PayloadFilesHavePrefix) <= 4.0-1

So as you see cupsd does not uses at all many libraries with which this ony binary is linked.
With -Wl,--as-need binary packages will have shorter list of rpm REQUIRES dependencies.

Back to /etc/cups/client.conf.
This file should be part of cups-libs package because it is client side configuration file.
Despite this that cupsd is linked with libcups cupsd binary is not doing anything with it and can start without reporting any issues without this file.
client.conf is not listed as well in cupsd(8) man page as used configuration file.

Probably it would be good to spend some time investigate why cupsd is using libcups (as theoretically it is only client side library).

Comment 39 Zbigniew Jędrzejewski-Szmek 2016-09-24 11:43:43 UTC
> This file should be part of cups-libs package because it is client side configuration file.

Agreed, is should be. But considering that the file is empty by default, this is mostly a cosmetic change that gives a hint that this file can be used without cups daemon.

> If there is no any defined in client.conf printers checking should be abandoned

No, the list of printers is defined on the server side. An empty client.conf file means "connect to server on localhost".

Comment 40 Tomasz Kłoczko 2016-09-24 12:14:34 UTC
> No, the list of printers is defined on the server side. An empty client.conf file means "connect to server on localhost".

Correction: list of defined print services to test on runtime.
If there is no defined on client side list of those services client library should not try to test any of them.

Comment 41 Zbigniew Jędrzejewski-Szmek 2016-09-24 12:23:47 UTC
(In reply to Tomasz Kłoczko from comment #40)
> > No, the list of printers is defined on the server side. An empty client.conf file means "connect to server on localhost".
> 
> Correction: list of defined print services to test on runtime.
> If there is no defined on client side list of those services client library
> should not try to test any of them.

Even if this were true (I don't think so), this is a separate issue from this one.

Comment 42 Fedora Update System 2016-09-24 15:13:20 UTC
cups-2.2.0-2.fc25 has been pushed to the Fedora 25 stable repository. If problems still persist, please make note of it in this bug report.

Comment 43 Pavel Grunt 2016-10-04 05:56:30 UTC
*** Bug 1380260 has been marked as a duplicate of this bug. ***


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