Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.
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
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
KDE Software Compilation 311528 0 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.