Bug 885541 - Renew-Subscription spam in /var/log/cups/access_log
Summary: Renew-Subscription spam in /var/log/cups/access_log
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Fedora
Classification: Fedora
Component: kde-print-manager
Version: 18
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Rex Dieter
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: AcceptedNTH
Depends On:
Blocks: F18-accepted, F18FinalFreezeExcept
TreeView+ depends on / blocked
 
Reported: 2012-12-10 02:43 UTC by nucleo
Modified: 2012-12-26 04:59 UTC (History)
9 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2012-12-20 05:31:55 UTC
Type: Bug


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
KDE Software Compilation 311528 None None None Never

Description nucleo 2012-12-10 02:43:44 UTC
Description of problem:
There are a lot messages in /var/log/cups/access_log every 3-4 seconds "Renew-Subscription successful-ok" when kde-print-manager installed.

Version-Release number of selected component (if applicable):
kde-print-manager-0.2.0-6.fc18.i686

Actual results:
localhost - - [10/Dec/2012:04:38:02 +0200] "POST / HTTP/1.1" 200 437 Create-Printer-Subscription successful-ok
localhost - - [10/Dec/2012:04:38:05 +0200] "POST / HTTP/1.1" 200 183 Renew-Subscription successful-ok
localhost - - [10/Dec/2012:04:38:09 +0200] "POST / HTTP/1.1" 200 183 Renew-Subscription successful-ok
localhost - - [10/Dec/2012:04:38:12 +0200] "POST / HTTP/1.1" 200 183 Renew-Subscription successful-ok
localhost - - [10/Dec/2012:04:38:16 +0200] "POST / HTTP/1.1" 200 183 Renew-Subscription successful-ok
localhost - - [10/Dec/2012:04:38:19 +0200] "POST / HTTP/1.1" 200 183 Renew-Subscription successful-ok
localhost - - [10/Dec/2012:04:38:23 +0200] "POST / HTTP/1.1" 200 183 Renew-Subscription successful-ok
localhost - - [10/Dec/2012:04:38:26 +0200] "POST / HTTP/1.1" 200 183 Renew-Subscription successful-ok
localhost - - [10/Dec/2012:04:38:30 +0200] "POST / HTTP/1.1" 200 183 Renew-Subscription successful-ok
localhost - - [10/Dec/2012:04:38:33 +0200] "POST / HTTP/1.1" 200 183 Renew-Subscription successful-ok
localhost - - [10/Dec/2012:04:38:37 +0200] "POST / HTTP/1.1" 200 183 Renew-Subscription successful-ok
localhost - - [10/Dec/2012:04:38:40 +0200] "POST / HTTP/1.1" 200 183 Renew-Subscription successful-ok
localhost - - [10/Dec/2012:04:38:44 +0200] "POST / HTTP/1.1" 200 183 Renew-Subscription successful-ok
localhost - - [10/Dec/2012:04:38:47 +0200] "POST / HTTP/1.1" 200 183 Renew-Subscription successful-ok
localhost - - [10/Dec/2012:04:38:51 +0200] "POST / HTTP/1.1" 200 183 Renew-Subscription successful-ok
localhost - - [10/Dec/2012:04:38:54 +0200] "POST / HTTP/1.1" 200 183 Renew-Subscription successful-ok
localhost - - [10/Dec/2012:04:38:58 +0200] "POST / HTTP/1.1" 200 183 Renew-Subscription successful-ok
localhost - - [10/Dec/2012:04:39:01 +0200] "POST / HTTP/1.1" 200 183 Renew-Subscription successful-ok
localhost - - [10/Dec/2012:04:39:05 +0200] "POST / HTTP/1.1" 200 183 Renew-Subscription successful-ok

Expected results:
No spam in /var/log/cups/access_log

Additional info:
No spam if kde-print-manager uninstalled.

Comment 1 Kevin Kofler 2012-12-10 19:08:28 UTC
It's CUPS which spams this logfile with those useless messages, reassigning.

Comment 2 nucleo 2012-12-10 19:16:42 UTC
If I disable and stop cups.service I got the same spam in .xsession-errors which made by kde-print-manager but not CUPS:

plasma-desktop(1659) KCupsConnection::renewDBusSubscription: Request failed 1280 
plasma-desktop(1659) KCupsConnection::renewDBusSubscription: Request failed 1280 
plasma-desktop(1659) KCupsConnection::renewDBusSubscription: Request failed 1280 
plasma-desktop(1659) KCupsConnection::renewDBusSubscription: Request failed 1280 
plasma-desktop(1659) KCupsConnection::renewDBusSubscription: Request failed 1280 
plasma-desktop(1659) KCupsConnection::renewDBusSubscription: Request failed 1280 
plasma-desktop(1659) KCupsConnection::renewDBusSubscription: Request failed 1280 
plasma-desktop(1659) KCupsConnection::renewDBusSubscription: Request failed 1280 
plasma-desktop(1659) KCupsConnection::renewDBusSubscription: Request failed 1280 
plasma-desktop(1659) KCupsConnection::renewDBusSubscription: Request failed 1280

Comment 3 Kevin Kofler 2012-12-10 19:46:55 UTC
Well, of course, if you try to run a CUPS frontend without CUPS running, you'll get error messages…

The real problem is the spam in the non-error case.

Comment 4 nucleo 2012-12-10 19:50:57 UTC
Frontend error message can be shown once but not every 3 seconds.

Comment 5 nucleo 2012-12-10 20:23:06 UTC
There is other problem with CUPS activation.
If kde-print-manager is not installed then cups.service activated after first access to printing. 
But with kde-print-manager installed cups.service activated even if printing never used, so the idea to activate only when it needed don't works.

Comment 6 Tim Waugh 2012-12-14 11:57:46 UTC
Why is it renewing the subscription every 3 seconds?  That's far too often.

You can specify the lease duration you want when you create the lease.  Do that, and remember to renew it before that time is up.  That's what GNOME does.

Alternatively, you get an error code when the lease has expired: simply create a new subscription at that point.  That's how system-config-printer handles it.

Renewing every 3 seconds is a pointless waste of power.

Comment 7 Rex Dieter 2012-12-14 13:48:18 UTC
The code in question seemingly does set/use 
#define RENEW_INTERVAL        3500
#define SUBSCRIPTION_DURATION 3600

except... i think I see the problem,

// Creates the timer that will renew the DBus subscription
m_renewTimer = new QTimer;
m_renewTimer->setInterval(RENEW_INTERVAL);

According to http://qt-project.org/doc/qt-4.8/qtimer.html#interval-prop,
"This property holds the timeout interval in milliseconds."

doh!

Initial tests to patch this to use RENEW_INTERVAL*1000 seems to make it behave.  I'll whip up a test build here shortly...

Comment 8 Rex Dieter 2012-12-14 15:14:21 UTC
We've got a fix in-hand, nominating NTH to avoid spamming /var/log/cups/access_log and users' ~/.xsession-errors

Comment 9 Fedora Update System 2012-12-14 15:21:35 UTC
kde-print-manager-0.2.0-8.fc18 has been submitted as an update for Fedora 18.
https://admin.fedoraproject.org/updates/kde-print-manager-0.2.0-8.fc18

Comment 10 Fedora Update System 2012-12-14 15:31:29 UTC
kde-print-manager-0.2.0-7.fc17 has been submitted as an update for Fedora 17.
https://admin.fedoraproject.org/updates/kde-print-manager-0.2.0-7.fc17

Comment 11 Fedora Update System 2012-12-14 23:21:14 UTC
Package kde-print-manager-0.2.0-8.fc18:
* should fix your issue,
* was pushed to the Fedora 18 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing kde-print-manager-0.2.0-8.fc18'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2012-20386/kde-print-manager-0.2.0-8.fc18
then log in and leave karma (feedback).

Comment 12 nucleo 2012-12-15 21:09:09 UTC
Now enew-Subscription messages appeared once per hour.

localhost - - [15/Dec/2012:15:07:40 -0500] "POST / HTTP/1.1" 200 315 Create-Printer-Subscription successful-ok
localhost - - [15/Dec/2012:15:07:40 -0500] "POST / HTTP/1.1" 200 156 Cancel-Subscription successful-ok
localhost - - [15/Dec/2012:15:07:40 -0500] "POST / HTTP/1.1" 200 441 Create-Printer-Subscription successful-ok
localhost - - [15/Dec/2012:16:06:00 -0500] "POST / HTTP/1.1" 200 187 Renew-Subscription successful-ok

Comment 13 Kevin Kofler 2012-12-15 23:21:13 UTC
That's exactly what the patch is designed to do (renew every 3500 seconds rather than every 3500 milliseconds).

Comment 14 Adam Williamson 2012-12-17 19:28:10 UTC
Discussed at 2012-12-17 NTH review meeting: http://meetbot.fedoraproject.org/fedora-bugzappers/2012-12-17/f18final-blocker-review-5.2012-12-17-16.40.log.txt . Accepted as NTH - this affects KDE lives, it could potentially overflow memory or something icky like that.

Comment 15 Fedora Update System 2012-12-20 05:31:59 UTC
kde-print-manager-0.2.0-8.fc18 has been pushed to the Fedora 18 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 16 Fedora Update System 2012-12-26 04:59:44 UTC
kde-print-manager-0.2.0-7.fc17 has been pushed to the Fedora 17 stable repository.  If problems still persist, please make note of it in this bug report.


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