Bug 1547828 - cups-browsed uses too much CPU
Summary: cups-browsed uses too much CPU
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Fedora
Classification: Fedora
Component: cups-filters
Version: 26
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Zdenek Dohnal
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On: 975241
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-02-22 03:58 UTC by xhe@redhat.com
Modified: 2023-09-14 04:16 UTC (History)
6 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of: 975241
Environment:
Last Closed: 2018-05-03 08:18:56 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description xhe@redhat.com 2018-02-22 03:58:48 UTC
+++ This bug was initially created as a clone of Bug #975241 +++

Description of problem:

Ok this could be seen as a continuation of my previous no fixed bug 959682.
Cups-browsed no longer leaks memory, but still uses pretty big portion of another system resource - CPU - on my 2.2GHz C2D.  While I've not printed any page of paper in past 4 days - here is the 10ten of CPU usage.

$ uptime
 23:10:11 up 4 days, 10:50,  8 users,  load average: 0,35, 1,22, 0,92

   VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 319064  90516  19904 S   3,6  2,3  82:12.22 X
  94928   2240    968 S   0,0  0,1  21:48.83 cups-browsed
 641400  26980   5976 S   1,3  0,7  16:36.64 gnome-terminal-
 193528   2436    620 S   0,0  0,1  11:49.24 cupsd
1317240 454208  51104 S   0,0 11,5   8:57.93 firefox
 784056  78408  21384 S   0,0  2,0   7:01.38 pidgin
 815576  14368   6104 S   1,6  0,4   5:05.48 nm-applet
 445600  35200   1652 S   0,0  0,9   3:31.66 udisksd
 528876   5564    472 S   0,0  0,1   3:05.66 libvirtd
 333264  19156   1272 S   0,0  0,5   2:53.72 gvfs-udisks2-vo
 554068  10900   4888 S   0,0  0,3   2:51.16 xfce4-panel
 208988   8672   2564 S   0,0  0,2   2:25.19 openbox
   4348    392    296 S   0,0  0,0   2:22.80 thinkfan


So while X and gnome-terminal is doing something 'usable' & 'visible'
the amount of CPU time used by cups doing nearly anything usable
at the same time is not in pair.

I may attach some performance analysis later - but probably
experienced cups codes would know better what is going on here.

Version-Release number of selected component (if applicable):
cups-filters-1.0.34-6.fc20.x86_64

How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:
Almost 30 minutes of used CPU time in just 4 days doing unsure what?

Expected results:
At least 10x less used CPU time.

Additional info:

--- Additional comment from Zdenek Kabelac on 2013-06-17 17:31:44 EDT ---

Here is short capture of:

perf record -ag -p pid_of_cups-browsed

Comment 1 xhe@redhat.com 2018-02-22 04:01:54 UTC
Recently, I found my CPU of cups-browsed is always 100%. so that my desktop is dead again and again. 

#  top
top - 11:25:40 up 8 days, 20:43,  2 users,  load average: 3.94, 2.88, 2.73
Tasks: 349 total,   6 running, 282 sleeping,   0 stopped,   0 zombie
%Cpu(s): 43.8 us,  6.5 sy,  0.0 ni, 48.6 id,  0.3 wa,  0.5 hi,  0.2 si,  0.0 st
KiB Mem :  7986540 total,   171632 free,  4380656 used,  3434252 buff/cache
KiB Swap:  8142844 total,  8142844 free,        0 used.  2490052 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                         
 1900 nancy     20   0  604048 338616   9536 R 100.0  4.2  11026:14 cups-browsed                                                    
 3009 nancy     20   0  520192 255084   9932 R  47.1  3.2  11213:28 cups-browsed                                                    
    1 root      20   0  224020  12052   8360 S  35.3  0.2   1603:24 systemd                                                         
  990 root      20   0  339088 115188   7860 S  35.3  1.4   1597:16 cupsd                                                           
  
#  cat /etc/redhat-release 
Fedora release 26 (Twenty Six)

#  uname -r
4.14.18-200.fc26.x86_64

Comment 2 Zdenek Dohnal 2018-02-22 16:12:34 UTC
Hi Xhe,

thank you for reporting this issue? Would you mind sharing:

1) your cups log (set debug level as told in https://fedoraproject.org/wiki/How_to_debug_printing_problems , restart cups and share the output of journal for cups systemd unit)

2) your cups-browsed log (add -d cups-browsed.service in /usr/lib/systemd/system and restart cups-browsed)

What printer models are in your network? Isn't it possible it is connected to bugzilla #1487873?

Comment 3 xhe@redhat.com 2018-02-23 03:34:34 UTC
I did the following operations, but seems no much useful, the CPU is still used more.

1). Enable full debugging information with:
   # su -c 'cupsctl LogLevel=debug2'
2). restart cups service with:
   # su -c 'systemctl restart cups.service'
3). Fetch the log messages.
   # journalctl -u cups -e
4) I checked the CUP% again, CUP is not 100% but it still around 90%.

   # top
  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                   
 1936 nancy     20   0  363924  97980   9156 R  96.7  1.2 372:07.93 cups-browsed              
 2981 nancy     20   0  363584  97860   9296 R  94.7  1.2 377:53.00 cups-browsed              
 2586 nancy     20   0 2547036 330208 147216 S  12.3  4.1   4:35.86 gnome-shell               
17702 root      20   0  226712   9252   7856 S   7.6  0.1   0:18.44 cupsd                     
    1 root      20   0  224020  12160   8448 S   5.6  0.2  34:31.47 systemd  

5) I tried to check the modules of the printer, but didn't find any useful information.
#  su -c "lpinfo -l -v"
Device: uri = https
        class = network
        info = Internet Printing Protocol (https)
        make-and-model = Unknown
        device-id = 
        location = 
Device: uri = http
        class = network
        info = Internet Printing Protocol (http)
        make-and-model = Unknown
        device-id = 
        location = 
Device: uri = socket
        class = network
        info = AppSocket/HP JetDirect
        make-and-model = Unknown
        device-id = 
        location = 
Device: uri = lpd
        class = network
        info = LPD/LPR Host or Printer
        make-and-model = Unknown
        device-id = 
        location = 
Device: uri = ipp
        class = network
        info = Internet Printing Protocol (ipp)
        make-and-model = Unknown
        device-id = 
        location = 
Device: uri = beh
        class = network
        info = Backend Error Handler
        make-and-model = Unknown
        device-id = 
        location = 
Device: uri = hp
        class = direct
        info = HP Printer (HPLIP)
        make-and-model = Unknown
        device-id = 
        location = 
Device: uri = ipps
        class = network
        info = Internet Printing Protocol (ipps)
        make-and-model = Unknown
        device-id = 
        location = 
Device: uri = serial:/dev/ttyS0?baud=115200
        class = serial
        info = Serial Port #1
        make-and-model = Unknown
        device-id = 
        location = 
Device: uri = serial:/dev/ttyS4?baud=115200
        class = serial
        info = Serial Port #5
        make-and-model = Unknown
        device-id = 
        location = 
Device: uri = smb
        class = network
        info = Windows Printer via SAMBA
        make-and-model = Unknown
        device-id = 
        location = 
Device: uri = hpfax
        class = direct
        info = HP Fax (HPLIP)
        make-and-model = Unknown
        device-id = 
        location = 

Here is the logs before and after the cups.service restart.
******************************
#  journalctl -u cups -e
Feb 23 11:05:22 nndesktop1 cupsd[15443]: cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
Feb 23 11:05:22 nndesktop1 cupsd[15443]: [Client 467] 1.1 CUPS-Add-Modify-Printer 195097
Feb 23 11:05:22 nndesktop1 cupsd[15443]: select_timeout: JobHistoryUpdate=0
Feb 23 11:05:22 nndesktop1 cupsd[15443]: [Client 467] cupsdReadClient: error=0, used=0, state=HTTP_STATE_POST_RECV, dat
Feb 23 11:05:22 nndesktop1 cupsd[15443]: [Client 467] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:22 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 120543 CUPS-Add-Modify-P
Feb 23 11:05:22 nndesktop1 cupsd[15443]: [Client 469] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:22 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 281228 CUPS-Add-Modify-P
Feb 23 11:05:23 nndesktop1 cupsd[15443]: Expiring subscriptions...
Feb 23 11:05:23 nndesktop1 cupsd[15443]: [Client 471] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:23 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 49602 CUPS-Add-Modify-Pr
Feb 23 11:05:23 nndesktop1 cupsd[15443]: [Client 473] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:23 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 120564 CUPS-Add-Modify-P
Feb 23 11:05:23 nndesktop1 cupsd[15443]: [Client 475] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:23 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 49620 CUPS-Add-Modify-Pr
Feb 23 11:05:23 nndesktop1 cupsd[15443]: [Client 477] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:23 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 21362 CUPS-Add-Modify-Pr
Feb 23 11:05:24 nndesktop1 cupsd[15443]: Expiring subscriptions...
Feb 23 11:05:24 nndesktop1 cupsd[15443]: [Client 479] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:24 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 120543 CUPS-Add-Modify-P
Feb 23 11:05:25 nndesktop1 cupsd[15443]: Expiring subscriptions...
Feb 23 11:05:25 nndesktop1 cupsd[15443]: [Client 481] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:25 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 92592 CUPS-Add-Modify-Pr
Feb 23 11:05:26 nndesktop1 cupsd[15443]: Expiring subscriptions...
Feb 23 11:05:26 nndesktop1 cupsd[15443]: [Client 483] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:26 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 120564 CUPS-Add-Modify-P
Feb 23 11:05:27 nndesktop1 cupsd[15443]: Expiring subscriptions...
Feb 23 11:05:27 nndesktop1 cupsd[15443]: [Client 485] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:27 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 92592 CUPS-Add-Modify-Pr
Feb 23 11:05:27 nndesktop1 cupsd[15443]: [Client 487] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:27 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 218202 CUPS-Add-Modify-P
Feb 23 11:05:27 nndesktop1 cupsd[15443]: [Client 489] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:27 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 178845 CUPS-Add-Modify-P
...skipping...
Feb 23 11:05:22 nndesktop1 cupsd[15443]: cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
Feb 23 11:05:22 nndesktop1 cupsd[15443]: [Client 467] 1.1 CUPS-Add-Modify-Printer 195097
Feb 23 11:05:22 nndesktop1 cupsd[15443]: select_timeout: JobHistoryUpdate=0
Feb 23 11:05:22 nndesktop1 cupsd[15443]: [Client 467] cupsdReadClient: error=0, used=0, state=HTTP_STATE_POST_RECV, dat
Feb 23 11:05:22 nndesktop1 cupsd[15443]: [Client 467] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:22 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 120543 CUPS-Add-Modify-P
Feb 23 11:05:22 nndesktop1 cupsd[15443]: [Client 469] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:22 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 281228 CUPS-Add-Modify-P
Feb 23 11:05:23 nndesktop1 cupsd[15443]: Expiring subscriptions...
Feb 23 11:05:23 nndesktop1 cupsd[15443]: [Client 471] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:23 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 49602 CUPS-Add-Modify-Pr
Feb 23 11:05:23 nndesktop1 cupsd[15443]: [Client 473] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:23 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 120564 CUPS-Add-Modify-P
Feb 23 11:05:23 nndesktop1 cupsd[15443]: [Client 475] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:23 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 49620 CUPS-Add-Modify-Pr
Feb 23 11:05:23 nndesktop1 cupsd[15443]: [Client 477] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:23 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 21362 CUPS-Add-Modify-Pr
Feb 23 11:05:24 nndesktop1 cupsd[15443]: Expiring subscriptions...
Feb 23 11:05:24 nndesktop1 cupsd[15443]: [Client 479] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:24 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 120543 CUPS-Add-Modify-P
Feb 23 11:05:25 nndesktop1 cupsd[15443]: Expiring subscriptions...
Feb 23 11:05:25 nndesktop1 cupsd[15443]: [Client 481] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:25 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 92592 CUPS-Add-Modify-Pr
Feb 23 11:05:26 nndesktop1 cupsd[15443]: Expiring subscriptions...
Feb 23 11:05:26 nndesktop1 cupsd[15443]: [Client 483] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:26 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 120564 CUPS-Add-Modify-P
Feb 23 11:05:27 nndesktop1 cupsd[15443]: Expiring subscriptions...
Feb 23 11:05:27 nndesktop1 cupsd[15443]: [Client 485] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:27 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 92592 CUPS-Add-Modify-Pr
Feb 23 11:05:27 nndesktop1 cupsd[15443]: [Client 487] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:27 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 218202 CUPS-Add-Modify-P
Feb 23 11:05:27 nndesktop1 cupsd[15443]: [Client 489] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:27 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 178845 CUPS-Add-Modify-P
...skipping...
Feb 23 11:05:22 nndesktop1 cupsd[15443]: cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
Feb 23 11:05:22 nndesktop1 cupsd[15443]: [Client 467] 1.1 CUPS-Add-Modify-Printer 195097
Feb 23 11:05:22 nndesktop1 cupsd[15443]: select_timeout: JobHistoryUpdate=0
Feb 23 11:05:22 nndesktop1 cupsd[15443]: [Client 467] cupsdReadClient: error=0, used=0, state=HTTP_STATE_POST_RECV, dat
Feb 23 11:05:22 nndesktop1 cupsd[15443]: [Client 467] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:22 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 120543 CUPS-Add-Modify-P
Feb 23 11:05:22 nndesktop1 cupsd[15443]: [Client 469] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:22 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 281228 CUPS-Add-Modify-P
Feb 23 11:05:23 nndesktop1 cupsd[15443]: Expiring subscriptions...
Feb 23 11:05:23 nndesktop1 cupsd[15443]: [Client 471] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:23 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 49602 CUPS-Add-Modify-Pr
Feb 23 11:05:23 nndesktop1 cupsd[15443]: [Client 473] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:23 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 120564 CUPS-Add-Modify-P
Feb 23 11:05:23 nndesktop1 cupsd[15443]: [Client 475] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:23 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 49620 CUPS-Add-Modify-Pr
Feb 23 11:05:23 nndesktop1 cupsd[15443]: [Client 477] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:23 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 21362 CUPS-Add-Modify-Pr
Feb 23 11:05:24 nndesktop1 cupsd[15443]: Expiring subscriptions...
Feb 23 11:05:24 nndesktop1 cupsd[15443]: [Client 479] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:24 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 120543 CUPS-Add-Modify-P
Feb 23 11:05:25 nndesktop1 cupsd[15443]: Expiring subscriptions...
Feb 23 11:05:25 nndesktop1 cupsd[15443]: [Client 481] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:25 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 92592 CUPS-Add-Modify-Pr
Feb 23 11:05:26 nndesktop1 cupsd[15443]: Expiring subscriptions...
Feb 23 11:05:26 nndesktop1 cupsd[15443]: [Client 483] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:26 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 120564 CUPS-Add-Modify-P
Feb 23 11:05:27 nndesktop1 cupsd[15443]: Expiring subscriptions...
Feb 23 11:05:27 nndesktop1 cupsd[15443]: [Client 485] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:27 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 92592 CUPS-Add-Modify-Pr
Feb 23 11:05:27 nndesktop1 cupsd[15443]: [Client 487] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:27 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 218202 CUPS-Add-Modify-P
Feb 23 11:05:27 nndesktop1 cupsd[15443]: [Client 489] Returning HTTP Forbidden for CUPS-Add-Modify-Printer (ipp://local
Feb 23 11:05:27 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 178845 CUPS-Add-Modify-P

#  journalctl -u cups -e
Feb 23 11:04:51 nndesktop1 cupsd[15443]: [Client 293] Closing connection.
Feb 23 11:04:51 nndesktop1 cupsd[15443]: cupsdSetBusyState: newbusy="Active clients and dirty file
Feb 23 11:04:51 nndesktop1 cupsd[15443]: cupsdRemoveSelect(fd=28)
Feb 23 11:04:51 nndesktop1 cupsd[15443]: cupsdRemoveSelect(fd=-1)
Feb 23 11:04:51 nndesktop1 cupsd[15443]: select_timeout: JobHistoryUpdate=0
Feb 23 11:04:51 nndesktop1 cupsd[15443]: cupsdAcceptClient(lis=0x55fe6105b3a0(3)) Clients=6
Feb 23 11:04:51 nndesktop1 cupsd[15443]: [Client 298] Server address is "/var/run/cups/cups.sock".
Feb 23 11:04:51 nndesktop1 cupsd[15443]: [Client 298] skipping getpeercon()
Feb 23 11:04:51 nndesktop1 cupsd[15443]: [Client 298] Accepted from localhost (Domain)
Feb 23 11:04:51 nndesktop1 cupsd[15443]: cupsdAddSelect(fd=27, read_cb=0x55fe5fa57b20, write_cb=(n
Feb 23 11:04:51 nndesktop1 cupsd[15443]: [Client 298] Waiting for request.
Feb 23 11:04:51 nndesktop1 cupsd[15443]: select_timeout: JobHistoryUpdate=0
Feb 23 11:04:51 nndesktop1 cupsd[15443]: cupsdAcceptClient(lis=0x55fe6105b3a0(3)) Clients=7
Feb 23 11:04:51 nndesktop1 cupsd[15443]: [Client 299] Server address is "/var/run/cups/cups.sock".
Feb 23 11:04:51 nndesktop1 cupsd[15443]: [Client 299] skipping getpeercon()
Feb 23 11:04:51 nndesktop1 cupsd[15443]: [Client 299] Accepted from localhost (Domain)
Feb 23 11:04:51 nndesktop1 cupsd[15443]: cupsdAddSelect(fd=28, read_cb=0x55fe5fa57b20, write_cb=(n
Feb 23 11:04:51 nndesktop1 cupsd[15443]: [Client 299] Waiting for request.
Feb 23 11:04:51 nndesktop1 cupsd[15443]: [Client 298] cupsdReadClient: error=0, used=0, state=HTTP
Feb 23 11:04:51 nndesktop1 cupsd[15443]: [Client 298] HTTP_STATE_WAITING Closing for error 32 (Bro
Feb 23 11:04:51 nndesktop1 cupsd[15443]: [Client 298] Closing connection.
Feb 23 11:04:51 nndesktop1 cupsd[15443]: [Client 299] Returning HTTP Forbidden for CUPS-Add-Modify
Feb 23 11:04:51 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 925
Feb 23 11:04:51 nndesktop1 cupsd[15443]: [Client 301] Returning HTTP Forbidden for CUPS-Add-Modify
Feb 23 11:04:51 nndesktop1 cupsd[15443]: REQUEST localhost - nancy "POST /admin/ HTTP/1.1" 403 491
lines 977-1001/1001 (END)

Moreover, I found I can not stop the cups.service, is it expected?
#  su -c 'systemctl stop cups.service'
Warning: Stopping cups.service, but it can still be activated by:
  cups.socket
  cups.path

Comment 4 Zdenek Dohnal 2018-02-23 06:30:19 UTC
(In reply to xhe from comment #3)
> I did the following operations, but seems no much useful, the CPU is still
> used more.
I'm sorry I probably confused you - that steps above were only for giving me some debug info.

> 5) I tried to check the modules of the printer, but didn't find any useful
> information.
I'm sorry I probably used wrong word - I was talking about your printer in your network (these printers which cups-browsed probably tries to find) - e.g. is it HP printer, Canon printer etc...

> Moreover, I found I can not stop the cups.service, is it expected?
> #  su -c 'systemctl stop cups.service'
> Warning: Stopping cups.service, but it can still be activated by:
>   cups.socket
>   cups.path
Yes, that's expected - cupsd can be activated even by incoming socket. (If you wanted to turn off cups-browsed, you need to stop cups-browsed.service)

Would you mind attaching cups-browsed logs please?

Comment 5 xhe@redhat.com 2018-02-23 10:05:53 UTC
It's Canon printer (Canon, DADF-AQ1).
I did restart the cups-browsed, and found the CPU is still 97%~100%. The following log is what you wanted? 

#  journalctl -u cups-browsed 
-- Logs begin at Wed 2015-04-01 03:10:02 CST, end at Fri 2018-02-23 17:57:46 CST. --
Feb 22 11:38:33 nndesktop1 systemd[1]: Stopping Make remote CUPS printers available locally...
Feb 22 11:38:36 nndesktop1 systemd[1]: Stopped Make remote CUPS printers available locally.
-- Reboot --
Feb 22 11:39:32 nndesktop1 systemd[1]: Started Make remote CUPS printers available locally.
Feb 22 12:55:24 nndesktop1 systemd[1]: Stopping Make remote CUPS printers available locally...
Feb 22 12:55:27 nndesktop1 systemd[1]: Stopped Make remote CUPS printers available locally.
-- Reboot --
Feb 22 12:56:30 nndesktop1 systemd[1]: Started Make remote CUPS printers available locally.
Feb 22 16:44:55 nndesktop1 systemd[1]: Stopping Make remote CUPS printers available locally...
Feb 22 16:45:01 nndesktop1 systemd[1]: Stopped Make remote CUPS printers available locally.
-- Reboot --
Feb 22 16:46:00 nndesktop1 systemd[1]: Started Make remote CUPS printers available locally.
Feb 22 18:34:33 nndesktop1 systemd[1]: Stopping Make remote CUPS printers available locally...
Feb 22 18:34:36 nndesktop1 systemd[1]: Stopped Make remote CUPS printers available locally.
-- Reboot --
Feb 22 18:35:36 nndesktop1 systemd[1]: Started Make remote CUPS printers available locally.
Feb 23 11:04:31 nndesktop1 systemd[1]: Stopping Make remote CUPS printers available locally...
Feb 23 11:04:31 nndesktop1 systemd[1]: Stopped Make remote CUPS printers available locally.
Feb 23 11:04:32 nndesktop1 systemd[1]: Started Make remote CUPS printers available locally.
Feb 23 11:20:14 nndesktop1 systemd[1]: Stopping Make remote CUPS printers available locally...
Feb 23 11:20:15 nndesktop1 systemd[1]: Stopped Make remote CUPS printers available locally.
Feb 23 11:20:15 nndesktop1 systemd[1]: Started Make remote CUPS printers available locally.
Feb 23 11:20:33 nndesktop1 systemd[1]: Stopping Make remote CUPS printers available locally...
Feb 23 11:20:34 nndesktop1 systemd[1]: Stopped Make remote CUPS printers available locally.
Feb 23 17:54:37 nndesktop1 systemd[1]: Started Make remote CUPS printers available locally.

#top
  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                            
 2981 nancy     20   0  384132 118368   9296 R  97.7  1.5 748:56.05 cups-browsed                                       
 1936 nancy     20   0  386252 120256   9156 R  97.4  1.5 743:05.11 cups-browsed                                       
 2586 nancy     20   0 2630280 331164 116176 S  15.6  4.1  16:23.41 gnome-shell                                        
24044 nancy     20   0  788312  43944  31588 S   5.0  0.6   1:03.27 stardict

Comment 6 Zdenek Dohnal 2018-02-26 09:10:10 UTC
Would you mind following 2) from comment #2? I'll describe it more:

1) open /usr/lib/systemd/system/cups-browsed.service
2) add '-d' to the end of line starting with 'ExecStart'
3) save it and restart cups-browsed - '$ systemctl restart cups-browsed' (notice the time when you restarted it - e.g. 12:00)
4) '$ journalctl -u cups-browsed --since=12:00 > cups-browsed.log' and please attach that log to this bugzilla

Thank you!

Comment 7 xhe@redhat.com 2018-02-27 05:13:50 UTC
Yes, I followed the steps mentioned in #c6, here is the result:

#  date && systemctl restart cups-browsed
Tue Feb 27 13:09:17 CST 2018
Warning: cups-browsed.service changed on disk. Run 'systemctl daemon-reload' to reload units.

#  journalctl -u cups-browsed --since=13:09:16 > cups-browsed.log
#  cat cups-browsed.log 
-- Logs begin at Wed 2015-04-01 03:10:02 CST, end at Tue 2018-02-27 13:10:05 CST. --
Feb 27 13:09:17 nndesktop1 systemd[1]: Stopping Make remote CUPS printers available locally...
Feb 27 13:09:18 nndesktop1 systemd[1]: Stopped Make remote CUPS printers available locally.
Feb 27 13:09:18 nndesktop1 systemd[1]: Started Make remote CUPS printers available locally.

#  journalctl -u cups-browsed --since=13:09 > cups-browsed.log
#  cat cups-browsed.log 
-- Logs begin at Wed 2015-04-01 03:10:02 CST, end at Tue 2018-02-27 13:12:47 CST. --
Feb 27 13:09:17 nndesktop1 systemd[1]: Stopping Make remote CUPS printers available locally...
Feb 27 13:09:18 nndesktop1 systemd[1]: Stopped Make remote CUPS printers available locally.
Feb 27 13:09:18 nndesktop1 systemd[1]: Started Make remote CUPS printers available locally.

Comment 8 Zdenek Dohnal 2018-02-27 10:28:59 UTC
(In reply to xhe from comment #7)
> Warning: cups-browsed.service changed on disk. Run 'systemctl daemon-reload'
> to reload units.

Sorry, I forgot about '# systemctl daemon-reload' needs to be run (warning message seems to be clear though).

In meanwhile, would you mind attaching your config too (/etc/cups/cups-browsed.conf)?

Comment 9 Fedora End Of Life 2018-05-03 07:57:15 UTC
This message is a reminder that Fedora 26 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 26. 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 '26'.

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 26 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 10 Zdenek Kabelac 2018-05-03 08:18:56 UTC
Not observing this issue on my current  Rawhide system - so considering it has been improved.

Comment 11 Red Hat Bugzilla 2023-09-14 04:16:57 UTC
The needinfo request[s] on this closed bug have been removed as they have been unresolved for 1000 days


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