cups-browsed running non-stop on two cores

[Heinrich Schuchardt]

After waking up from standby cups-browsed runs incessantly on two cores:

  18243 cups-br+ 20 0 432256 26348 17848 R 99.7 0.2 66:54.73 cups-br+
  85147 cups-br+ 20 0 432256 26348 17848 R 99.7 0.2 66:52.08 cups-br+

cups-br+ 18243 18.9 0.1 432256 26348 ? Rsl 08:30 135:06 /usr/sbin/cups-browsed

Best regards

Heinrich

ProblemType: Bug
DistroRelease: Ubuntu 24.04
Package: cups-browsed 2.0.0-0ubuntu2
ProcVersionSignature: Ubuntu 6.6.0-14.14-generic 6.6.3
Uname: Linux 6.6.0-14-generic x86_64
ApportVersion: 2.27.0-0ubuntu6
Architecture: amd64
CasperMD5CheckResult: pass
CurrentDesktop: KDE
Date: Sun Jan 14 20:19:22 2024
InstallationDate: Installed on 2021-07-01 (927 days ago)
InstallationMedia: Kubuntu 21.04 "Hirsute Hippo" - Release amd64 (20210420)
MachineType: {report['dmi.sys.vendor']} {report['dmi.product.name']}
Papersize: a4
ProcKernelCmdLine: BOOT_IMAGE=/vmlinuz-6.6.0-14-generic root=/dev/mapper/vgubuntu-root ro
SourcePackage: cups-browsed
UpgradeStatus: No upgrade log present (probably fresh install)
dmi.bios.date: 02/08/2023
dmi.bios.release: 1.63
dmi.bios.vendor: LENOVO
dmi.bios.version: R0UET83W (1.63 )
dmi.board.asset.tag: Not Available
dmi.board.name: 20KV0008GE
dmi.board.vendor: LENOVO
dmi.board.version: SDK0J40697 WIN
dmi.chassis.asset.tag: No Asset Information
dmi.chassis.type: 10
dmi.chassis.vendor: LENOVO
dmi.chassis.version: None
dmi.ec.firmware.release: 1.63
dmi.modalias: dmi:bvnLENOVO:bvrR0UET83W(1.63):bd02/08/2023:br1.63:efr1.63:svnLENOVO:pn20KV0008GE:pvrThinkPadE585:rvnLENOVO:rn20KV0008GE:rvrSDK0J40697WIN:cvnLENOVO:ct10:cvrNone:skuLENOVO_MT_20KV_BU_Think_FM_ThinkPadE585:
dmi.product.family: ThinkPad E585
dmi.product.name: 20KV0008GE
dmi.product.sku: LENOVO_MT_20KV_BU_Think_FM_ThinkPad E585
dmi.product.version: ThinkPad E585
dmi.sys.vendor: LENOVO

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Till Kamppeter (till-kamppeter)]

This bug has been reported by several people. It rarely happens and if one kills and restarts cups-browsed once it happens, everything gets normal again.

What I need to find out what the root cause is is a debug log ofcups-browsed running into the problem. Due to the rare occurence of the bug I did not get one upto now.

So everyone who is suffering the bug, please turn cups-browsed into the debug logging mode. For this, edit /etc/cups/cup-browsed.conf to have a line

DebugLogging file

You most probably only have to uncomment this line and perhaps comment out another one for that.

Then restart cups-browsed:

sudo systemctl stop cups-browsed
sudo systemctl start cups-browsed

Whenever the bug occurs again, please copy the file /var/log/cups-browsed/cups-browsed_log and attach it here.

Note that it can take some days (week?, months?, ...) until you will hit the bug again.

[Till Kamppeter (till-kamppeter)]

Note that this bug is not bug 2018504.

[Heinrich Schuchardt (xypron)]

These are the related syslog messages from yesterdays event. But without debugging enabled. I will report back once I have a log with the debug detail.

[Bryan Beus (bryanbeus)]

@till-kamppeter

I also have experienced this bug. I've activated the debug mode, as indicated above, and will post results when available.

Thanks.

[Heinrich Schuchardt (xypron)]

Hello Till,

The problem has hit me again. Here is the output of 'journalctl -u cups-browsed' since the last boot.

In /etc/cups/cups-browsed.conf I have set: DebugLogging stderr.

I hope there is something helpful for you in the log. While cups-browsed is spinning at 200 % CPU no message has been written in the last 20 minutes.

Attaching gdb gives me the following call chains for the two threads:

Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007e277c62b824 in __errno_location@plt () from /lib/x86_64-linux-gnu/libcups.so.2
(gdb) up
#1 0x00007e277c63dec9 in httpGets () from /lib/x86_64-linux-gnu/libcups.so.2
(gdb) up
#2 0x00007e277c63f283 in _httpUpdate () from /lib/x86_64-linux-gnu/libcups.so.2
(gdb) up
#3 0x00007e277c63f5cb in httpUpdate () from /lib/x86_64-linux-gnu/libcups.so.2
(gdb) up
#4 0x00007e277c656158 in cupsGetResponse () from /lib/x86_64-linux-gnu/libcups.so.2
(gdb) up
#5 0x00007e277c656d5b in cupsDoIORequest () from /lib/x86_64-linux-gnu/libcups.so.2
(gdb) up
#6 0x00007e277c63046a in _cupsGetDests () from /lib/x86_64-linux-gnu/libcups.so.2
(gdb) up
#7 0x00007e277c631d15 in cupsGetNamedDest () from /lib/x86_64-linux-gnu/libcups.so.2
(gdb) up
#8 0x00005865c1ba63d4 in ?? ()
(gdb) up
#9 0x00007e277c097aca in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:444
warning: 444 ./nptl/pthread_create.c: No such file or directory

---

0x00007e277c63df8b in httpGets () from /lib/x86_64-linux-gnu/libcups.so.2
(gdb) up
#1 0x00007e277c63f283 in _httpUpdate () from /lib/x86_64-linux-gnu/libcups.so.2
(gdb)
#2 0x00007e277c63f5cb in httpUpdate () from /lib/x86_64-linux-gnu/libcups.so.2
(gdb)
#3 0x00007e277c656158 in cupsGetResponse () from /lib/x86_64-linux-gnu/libcups.so.2
(gdb)
#4 0x00007e277c656d5b in cupsDoIORequest () from /lib/x86_64-linux-gnu/libcups.so.2
(gdb)
#5 0x00005865c1bb0a40 in ?? ()
(gdb)
#6 0x00005865c1bb2126 in ?? ()
(gdb)
#7 0x00005865c1ba8b71 in ?? ()
(gdb)
#8 0x00005865c1bae2bd in ?? ()
(gdb)
#9 0x00005865c1bafdd5 in ?? ()
(gdb)
#10 0x00007e277c097aca in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:444
warning: 444 ./nptl/pthread_create.c: No such file or directory

We are in function httpGets() which seemingly has been called with parameter line being a NUL terminated string "Content-Security-Policy".

We cycle in the loop 'while (lineptr < lineend)'.
http->used = -47
bufptr > bufend
*lineptr = "Content-Security-Policy"

As bufptr > bufend we never set eol.

The function expects as input a string terminated by a linefeed. But the parameter line = "Content-Security-Policy" has no linefeed. We should not rely on web-servers providing well formed responses.

Best regards

Heinrich

[Heinrich Schuchardt (xypron)]

Upstream bug report created:
Incorrect error handling in httpGets2
https://github.com/OpenPrinting/cups/issues/879

[Till Kamppeter (till-kamppeter)]

Heinrich, thank you very much for your investigations and the upstream bug report with patch.

You made 2 observations possibly leading to the bug in your 2 last comments:

1. String without linefeed
2. httpGets2 error handling

The upstream bug report suggests a solution for (2). Would this be enough? Is (1) independent of (2) and also needs to get fixed?

I hope you have patched your cups-browsed as you suggest and are observing whether the problem occurs again.

Unfortunately, I am only able to look into it and apply any fixes on cups-browsed next week, as I am traveling to FOSDEM this weekend.

Please do not hesitate to post further observations and suggestions for fixes.

[Heinrich Schuchardt (xypron)]

Hello Till,

> 1. String without linefeed
> 2. httpGets2 error handling

I am not sure if 1) isn't just the result of not correctly handling a broken connection due to 2).

Good luck with your two talks at FOSDEM. Enjoy Brussels.

Best regards

Heinrich

[Heinrich Schuchardt (xypron)]

Upstream merge request:
https://github.com/OpenPrinting/cups/pull/880

[Bryan Beus (bryanbeus)]

The problem occurred again.
I did have the debug mode active for cups-browsed, and here is the resulting log file.

[Till Kamppeter (till-kamppeter)]

Thanks everyone for posting logs here.

I would like to have another thing from everyone who runs into the problem.

1. When you observe the problem, DO NOT kill cups-browsed.

2. Save the debug log and attach it to this bug report.

3. Determine the process ID (PID) of cup-browsed:

ps aux | grep cups-browsed | grep -v grep
cups-browsed 846190 0.0 0.0 112932 5760 ? Ssl 00:00 0:00 /usr/sbin/cups-browsed

The first number (second word) in the line is the PID

4. Install the debug symbols package of cups-browsed. Its name is "cups-browsed-dbgsym". Follow the instructions on

https://ubuntu.com/server/docs/debug-symbol-packages

5. Install the debugger gdb if needed:

sudo apt install gdb

6. Attach the debugger gdb to cup-browsed:

sudo gdb attach PID

or

sudo -u cups-browsed attach PID

Replace PID by the PID you determined in (3)

On the prompt of the debugger enter the command

t a a bt

You get some output. If it ends with

--Type <RET> for more, q to quit, c to continue without paging--

press Enter, until you get back to the prompt:

(gdb)

DO NOT press Enter when you are at the prompt.

Now copy the complete output of gdb into an editor, save the file and attach it to this bug report.

[Till Kamppeter (till-kamppeter)]

CUPS 2.4.8 got released and the fix https://github.com/OpenPrinting/cups/issues/879 is included.

Heinrich, thanks again for the investigations and bug report.

Heinrich, best would be to do an SRU of CUPS, applying the patch to Ubuntu's 2.4.7 would be easy, but how does one verify this fix? Do you know how to quickly trigger the bug? I had it only once in more than a year.

[Heinrich Schuchardt (xypron)]

>> Do you know how to quickly trigger the bug?
Till, unfortunately I would not know how to trigger it on purpose.

Concerning SRU of any fix, I think it would be enough to verify that printing still works.

[Heinrich Schuchardt (xypron)]

@Till

There are two processes running:

$ ps aux | grep cups-browsed | grep -v grep
root 2912 0.0 0.0 2892 1708 ? Ss 10:13 0:00 /bin/sh /snap/cups/1047/scripts/run-cups-browsed
root 3407 0.0 0.0 2892 892 ? S 10:13 0:00 /bin/sh /snap/cups/1047/scripts/run-cups-browsed

None of these relates to what top shows as culprit:

2898 root 20 0 195916 16320 11736 R 197.0 0.1 139:30.91 cupsd

$ ps -aux | grep 2898
root 2898 134 0.1 195916 16320 ? Rsl 10:13 141:15 /usr/sbin/cupsd -l

$ sudo gbd -p 2898
(gdb) t a a bt

(gdb) t a a bt

Thread 2 (Thread 0x729b3cc006c0 (LWP 5305) "cupsd"):
#0 0x0000729b3f6a3439 in __pthread_rwlock_wrlock_full64 (abstime=0x0, clockid=0, rwlock=0x64af2f2b0270) at ./nptl/pthread_rwlock_common.c:821
#1 ___pthread_rwlock_wrlock (rwlock=0x64af2f2b0270) at ./nptl/pthread_rwlock_wrlock.c:26
#2 0x000064af2d5231a1 in create_local_bg_thread (con=0x64af2f3a1d70) at /build/cups-0ETlfZ/cups-2.4.7/scheduler/ipp.c:5333
#3 0x0000729b3f69ca94 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:447
#4 0x0000729b3f729c3c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78

Thread 1 (Thread 0x729b3e5b1b40 (LWP 2898) "cupsd"):
#0 0x0000729b3f71c5ad in __GI___libc_write (nbytes=63, buf=0x64af2f1b07c8, fd=6) at ../sysdeps/unix/sysv/linux/write.c:26
#1 __GI___libc_write (fd=6, buf=0x64af2f1b07c8, nbytes=63) at ../sysdeps/unix/sysv/linux/write.c:24
#2 0x0000729b3f95cf66 in ??? () at /lib/x86_64-linux-gnu/libcups.so.2
#3 0x0000729b3f95d3ea in cupsFileFlush () at /lib/x86_64-linux-gnu/libcups.so.2
#4 0x000064af2d5399f5 in cupsdWriteErrorLog (message=0x64af2f1ae7b0 "[Client 26] Closing connection.", level=8) at /build/cups-0ETlfZ/cups-2.4.7/scheduler/log.c:1276
#5 cupsdWriteErrorLog (level=level@entry=8, message=0x64af2f1ae7b0 "[Client 26] Closing connection.") at /build/cups-0ETlfZ/cups-2.4.7/scheduler/log.c:1220
#6 0x000064af2d539b72 in cupsdLogClient (con=<optimized out>, level=8, message=<optimized out>) at /build/cups-0ETlfZ/cups-2.4.7/scheduler/log.c:540
#7 0x000064af2d50d741 in cupsdCloseClient (con=con@entry=0x64af2f3a1d70) at /build/cups-0ETlfZ/cups-2.4.7/scheduler/client.c:405
#8 0x000064af2d50f071 in cupsdReadClient (con=0x64af2f3a1d70) at /build/cups-0ETlfZ/cups-2.4.7/scheduler/client.c:618
#9 0x000064af2d508469 in cupsdDoSelect (timeout=<optimized out>) at /build/cups-0ETlfZ/cups-2.4.7/scheduler/select.c:477
#10 main (argc=<optimized out>, argv=<optimized out>) at /build/cups-0ETlfZ/cups-2.4.7/scheduler/main.c:855

Thread 1 (process 2912 "run-cups-browse"):
#0 0x000075225bf4e7dc in sigsuspend () from target:/lib/x86_64-linux-gnu/libc.so.6
#1 0x00005d1641298ee8 in ?? ()
#2 0x00005d164129911a in ?? ()
#3 0x00005d164129e58a in ?? ()
#4 0x00005d16412a3826 in ?? ()
#5 0x00005d16412a650f in ?? ()
#6 0x00005d164129fc00 in ?? ()
#7 0x00005d16412a4b28 in ?? ()
#8 0x00005d1641297d53 in ?? ()
#9 0x000075225bf35d90 in ?? () from target:/lib/x86_64-linux-gnu/libc.so.6
#10 0x000075225bf35e40 in __libc_start_main () from target:/lib/x86_64-linux-gnu/libc.so.6
#11 0x00005d1641297f15 in ?? ()

Thread 1 (process 3407 "run-cups-browse"...

[Till Kamppeter (till-kamppeter)]

These processes
-----
$ ps aux | grep cups-browsed | grep -v grep
root 2912 0.0 0.0 2892 1708 ? Ss 10:13 0:00 /bin/sh /snap/cups/1047/scripts/run-cups-browsed
root 3407 0.0 0.0 2892 892 ? S 10:13 0:00 /bin/sh /snap/cups/1047/scripts/run-cups-browsed
-----
come from the CUPS Snap. They are from a wrapper script to start cups-browsed, but in your case the CUPS Snap does not start cups-browsed, as you have a classically installed CUPS and the CUPS Snap is only running as proxy for snapped applications. There is no ¨../cups-browsed" process, so cups-browsed is currently not running for you.

You have attached gdb to cupsd.

The instructions I have posted are for applying when cups-browsed is running and stuck, not after killing it. They only make sense if there are actually 1 or 2 cups-browsed processes hanging in a 100%-CPU busy loop.

For your patch on CUPS, which Michael has actually accepted, I am not absolutely sure whether it will solve the problem. If you do not add the "return(NULL);" line, the flow will go into the "return(NULL);" right after the "if () {} else if {}" and so we have no different effect. Or is this not the case?

[Heinrich Schuchardt (xypron)]

>> The instructions are for applying when cups-browsed is running and stuck, not after killing it.

I did not kill any process before attaching gdb.
And top shows 200 % cpu usage by cupsd.

This is what still needs to be solved.

[Till Kamppeter (till-kamppeter)]

So you got the 200% on cupsd now, not on cups-browsed? Seems that cupsd can run into a similar bug.

[theofficialgman (theofficialgman)]

I frequently get 100% cups-browsed
should I open a separate report?

[Tom Chiverton (bugs-launchpad-net-falkensweb)]

> CUPS 2.4.8 got released and the fix https://github.com/OpenPrinting/cups/issues/879 is included.

Is this incorporated into 24.04 yet ?

[Till Kamppeter (till-kamppeter)]

No, the CUPS of 24.04 is 2.4.7.

I am have currently installed 2.4.8 from source and I will see if it actually prevents the problem, but it will need some days to get good evidence whether the bug is really fixed.