Bug 395115 - print-manager v18.04.1 interacts badly with recent cups v2.2.8, numerous errors leading to high system load
Summary: print-manager v18.04.1 interacts badly with recent cups v2.2.8, numerous erro...
Status: RESOLVED UPSTREAM
Alias: None
Product: print-manager
Classification: Frameworks and Libraries
Component: general (show other bugs)
Version: 18.04
Platform: Gentoo Packages Linux
: NOR normal (vote)
Target Milestone: ---
Assignee: Daniel Nicoletti
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-06-07 17:25 UTC by Tony
Modified: 2018-08-04 13:04 UTC (History)
5 users (show)

See Also:
Latest Commit:
Version Fixed In:


Attachments
cups 2.2.8 compatibility test (930 bytes, patch)
2018-06-08 11:55 UTC, loqs
Details
cups 2.2.8 compatibility test2 (1.89 KB, patch)
2018-06-08 18:17 UTC, loqs
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Tony 2018-06-07 17:25:50 UTC
First bug report to KDE.
If I've missed out any detail, please let me know.

Originally posted downstream on the Gentoo bug-tracker.
https://bugs.gentoo.org/657526
I've been asked to raise the issue upstream.

After a recent update from cups v2.2.7 to cups v2.2.8, I'm seeing lots of errors being thrown by libkcups
The following 3 error messages are being repeated over and over in the journal (several times per second)

Jun 07 12:44:15 tony-workstation plasmashell[679]: libkcups: 3 "LaserJet8150"
Jun 07 12:44:15 tony-workstation plasmashell[679]: libkcups: CUPS-Get-Printers last error: 0 successful-ok
Jun 07 12:44:15 tony-workstation plasmashell[679]: libkcups: "040B localhost \"requesting-user-name\" attribute with bad value."

This is causing system load to rise significantly
top shows libkcups and plasmashell processes at 70-80% CPU usage

Tried reinstalling print-manager, but this made no difference.
Downgrading from cups v2.2.8 to cups v2.2.7 fixes issue.
Comment 1 Tony 2018-06-07 18:09:37 UTC
From CUPS changelog

Changes in CUPS v2.2.8
----------------------

- Additional changes for the scheduler to substitute default values for invalid
  job attributes when running in "relaxed conformance" mode (Issue #5229)
- The `ipptool` program no longer checks for duplicate attributes when running
  in list or CSV mode (Issue #5278)
- Fixed builds without PAM (Issue #5283)
- Fixed `lpoptions` man page (Issue #5286)
- The `cupsCreateJob`, `cupsPrintFile2`, and `cupsPrintFiles2` APIs did not use
  the supplied HTTP connection (Issue #5288)
- Fixed another crash in the scheduler when adding an IPP Everywhere printer
  (Issue #5290)
- Added a workaround for certain web browsers that do not support multiple
  authentication schemes in a single response header (Issue #5289)
- Fixed policy limits containing the `All` operation (Issue #5296)
- The scheduler was always restarted after idle-exit with systemd (Issue #5297)
- Added a USB quirks rule for the HP LaserJet P1102 (Issue #5310)
- The mailto notifier did not wait for the welcome message (Issue #5312)
- Fixed a parsing bug in the pstops filter (Issue #5321)
- Documentation updates (Issue #5299, Issue #5301, Issue #5306)
- Localization updates (Issue #5317)
- The scheduler allowed environment variables to be specified in the
  `cupsd.conf` file (rdar://37836779, rdar://37836995, rdar://37837252,
  rdar://37837581)
- Fax queues did not support pause (p) or wait-for-dialtone (w) characters
  (rdar://39212256)
- The scheduler did not validate notify-recipient-uri values properly
  (rdar://40068936)
- The IPP parser allowed invalid group tags (rdar://40442124)
- Fixed a parsing bug in the new authentication code.
Comment 2 Tony 2018-06-07 19:37:54 UTC
Possible this isn't a print-manager issue,
but rather an issue with CUPS itself

Found bug report on CUPS project page
https://github.com/apple/cups/issues/5325

User here using KDE, but I see no mention of "libkcups" in his output
Difficult to tell due to lack of formatting, and some confusion about version numbers.
Comment 3 Daniel Nicoletti 2018-06-07 21:43:48 UTC
thanks for investigating this, sadly I don't have this version at time to test, but will try to see if I send the things mentioned on that ISSUE.
Comment 4 Tony 2018-06-07 23:58:08 UTC
> will try to see if I send the things mentioned on that ISSUE

Note that upstream CUPS bug report [1] makes references to "my-jobs" and "printer-type".
While my errors in this report make no mention of those, but /do/ make reference to "requesting-user-name".

Pure guess, but this looks like the same bug being hit by 2 different means.
So you may not find any issues in print-manager relating to "my-jobs" and "printer-type" attribs,
but may well do for "requesting-user-name"

Note that changelog for CUPS 2.2.8 mentions
> Additional changes for the scheduler to substitute default values for invalid job attributes when running in "relaxed conformance" mode (Issue #5229)

Upstream commit [2] for this issue certainly makes changes relating to "requesting-user-name"

scheduler/ipp.c
function cupsdProcessIPPRequest()

Again, pure guess,
but it looks like CUPS has tightened up it's API, and is now disallowing previously valid input.

[1] https://github.com/apple/cups/issues/5325
[2] https://github.com/apple/cups/commit/092db1e29ee1ad175dadcf4a027c4b752586b4d4
Comment 5 Bastian Beischer 2018-06-08 09:25:20 UTC
I bisected cups from v2.2.7 to v2.2.8. This is the bisect log:

git bisect start
# bad: [4ebeb20c50145190312c9897efa26ed5b58b3bc5] Update README and INSTALL
git bisect bad 4ebeb20c50145190312c9897efa26ed5b58b3bc5
# good: [84c97c051db7de61342461b6333a6bf31830535e] Update VisualStudio Project
git bisect good 84c97c051db7de61342461b6333a6bf31830535e
# good: [9135aedbb4d91d2e20e7b767c2368eadf6d5a5d4] Update ErrorPolicy in cupsd.conf man page (Issue #5301)
git bisect good 9135aedbb4d91d2e20e7b767c2368eadf6d5a5d4
# bad: [22716a21f7fd8201dd4c5b015defed780c596331] Mirror change from master.
git bisect bad 22716a21f7fd8201dd4c5b015defed780c596331
# good: [66021bfa9043961f0ace0b6a5a82d181d606e755] Mirror mailto changes from master (Issue #5312)
git bisect good 66021bfa9043961f0ace0b6a5a82d181d606e755
# bad: [d66aa76457ccfffb6420cd88bc72f84a5d8d7e37] Mirror documentation updates from master.
git bisect bad d66aa76457ccfffb6420cd88bc72f84a5d8d7e37
# bad: [4c37eb9f77910f6f856fc540fc9a94a5885af17c] Generalize the input validation of some kinds of attributes.
git bisect bad 4c37eb9f77910f6f856fc540fc9a94a5885af17c
# first bad commit: [4c37eb9f77910f6f856fc540fc9a94a5885af17c] Generalize the input validation of some kinds of attributes.

Which identifies this commit as the first bad one:

https://github.com/apple/cups/commit/4c37eb9f77910f6f856fc540fc9a94a5885af17c
Comment 6 loqs 2018-06-08 11:25:00 UTC
From the upstream report at cups
https://cgit.kde.org/print-manager.git/tree/libkcups/KCupsRequest.cpp?h=v18.04.1#n196 is not a valid attribute for that request
https://cgit.kde.org/print-manager.git/tree/libkcups/KCupsRequest.cpp?h=v18.04.1#n200 should be boolean
Comment 7 loqs 2018-06-08 11:55:07 UTC
Created attachment 113150 [details]
cups 2.2.8 compatibility test

previous comment should have linked to printer type not printer
drop printer type tag and change my-jobs to a boolean compile tested only
Comment 8 Bastian Beischer 2018-06-08 12:33:36 UTC
@loqs: Thanks, but unfortunately that doesn't fix it for me.
Comment 9 loqs 2018-06-08 15:29:30 UTC
cupsdProcessIPPRequest: requesting-user-name nameWithoutLanguage 'harvey'
cupsdAddEvent(event=server-audit, dest=(nil)(), job=(nil)(0), text="%04X %s \"requesting-user-name\" attribute with bad value.", ...)

The string cups is complaining about appears to all be valid ascii/UTF-8 and the code in print-manager is using UTF-8 so I fixed the issues where I could see issues in the code.  Unless cups sanitised that string before printing the value to the error log I can not see the problem with it.
Comment 10 loqs 2018-06-08 18:17:41 UTC
Created attachment 113153 [details]
cups 2.2.8 compatibility test2

Updated test fix this additionally removes setting the language parameter to 'utf-8' in ippAddString calls this matches cups internal use of ippAddString.
Comment 11 Daniel Nicoletti 2018-06-08 19:14:47 UTC
(In reply to Bastian Beischer from comment #8)
> @loqs: Thanks, but unfortunately that doesn't fix it for me.

Does the last patch provided fixes the issue for you?
Comment 12 loqs 2018-06-08 20:54:11 UTC
No still same issue with the last patch.  I can only reproduce the issue with LANG=de_DE.utf8
Comment 13 Tony 2018-06-09 09:34:39 UTC
From my POV, this bug can be closed.
Bug (as initially reported) is in CUPS, and /not/ in KDE print-manager.

CUPS maintainers have identified the issue, and there's a possible fix here
https://github.com/heftig/cups/commit/455c52a027ab3548953372a0b7bdb0008420e9ba

I do see there are comments about other potential issues in print-manager, though.
Eg. https://bugs.kde.org/show_bug.cgi?id=395115#c6
I've not been following these and not being a C developer, have no opinion on them.

I am happy for this bug to be closed.
But equally if there's other related issues then leave it open.

Many thanks,
Comment 14 Eric Hameleers 2018-06-10 10:39:16 UTC
Slackware has applied the upstream patch to its cups-2.2.8 package and that solved the issue with print-manager in KDE Plasma5. I agree that there's no need to keep this KDE bug open since it is not an issue in print-manager.
Comment 15 Daniel Nicoletti 2018-06-10 13:59:51 UTC
it might not be an issue with print manager but the last patch seems to be a more correct way to talk to cups, does using it with the patched CUPS has any issue?
Comment 16 Tony 2018-06-12 10:09:40 UTC
> does using it with the patched CUPS has any issue?

No issues so far

Worth noting that my distro has since pushed KDE Applications 18.04.2 out to users
but patch in comment 10 still applies cleanly, and been using this for the last day with no issues
Comment 17 Christoph Feck 2018-06-28 00:01:38 UTC
What is the status of this issue? Does KDE software need changes, or is the issue fixed in upstream (CUPS) code?
Comment 18 Christoph Feck 2018-07-20 02:49:52 UTC
If you can provide the information requested in comment #17, please add it.
Comment 19 Christoph Feck 2018-08-04 13:04:00 UTC
No response, assuming it was fixed upstream. If you have new information, please add a comment.