Bug 72275 - PackageKit logs debug information with PRIORITY=0
Summary: PackageKit logs debug information with PRIORITY=0
Status: RESOLVED FIXED
Alias: None
Product: PackageKit
Classification: Unclassified
Component: core (show other bugs)
Version: unspecified
Hardware: Other All
: medium normal
Assignee: Richard Hughes
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2013-12-03 18:45 UTC by Zbigniew Jedrzejewski-Szmek
Modified: 2013-12-07 18:22 UTC (History)
1 user (show)

See Also:
i915 platform:
i915 features:

Attachments

Description Zbigniew Jedrzejewski-Szmek 2013-12-03 18:45:58 UTC 
Various logs from PackageKit show up in red in journalctl output:

Dec 03 13:19:12 bupkis systemd[1]: Starting PackageKit Daemon...
Dec 03 13:19:12 bupkis PackageKit[28350]: daemon start
Dec 03 13:19:12 bupkis dbus-daemon[672]: dbus[672]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Dec 03 13:19:12 bupkis dbus[672]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Dec 03 13:19:12 bupkis systemd[1]: Started PackageKit Daemon.
Dec 03 13:19:17 bupkis sudo[28377]: zbyszek : TTY=pts/10 ; PWD=/ ; USER=root ; COMMAND=/bin/pkcon update
Dec 03 13:19:18 bupkis packagekitd[28350]: Raw timing data was { 0.001, 0.186 }
Dec 03 13:19:18 bupkis packagekitd[28350]: steps were set as [ 5, 95, -1 ] but should have been: [ 1, 99, -1 ] at hif-sack.c:49
Dec 03 13:19:18 bupkis packagekitd[28350]: child is at 0/2 steps and parent done [hif-sack.c:134]
Dec 03 13:19:18 bupkis packagekitd[28350]: 4) pk-backend-hawkey.c:924 (0/4)
Dec 03 13:19:18 bupkis packagekitd[28350]: 3) pk-backend-hawkey.c:676 (1/2)
Dec 03 13:19:18 bupkis packagekitd[28350]: 2) pk-backend-hawkey.c:596 (1/2)
Dec 03 13:19:18 bupkis packagekitd[28350]: 1) hif-sack.c:124 (5/8)
Dec 03 13:19:18 bupkis packagekitd[28350]: 0) hif-sack.c:49 (0/2)
Dec 03 13:19:18 bupkis packagekitd[28350]: Raw timing data was { 0.000, 0.201 }
Dec 03 13:19:18 bupkis packagekitd[28350]: steps were set as [ 2, 98, -1 ] but should have been: [ 0, 100, -1 ] at pk-backend-hawkey.c:596
Dec 03 13:19:18 bupkis packagekitd[28350]: Raw timing data was { 0.676, 0.202 }
Dec 03 13:19:18 bupkis packagekitd[28350]: steps were set as [ 8, 92, -1 ] but should have been: [ 77, 23, -1 ] at pk-backend-hawkey.c:676
Dec 03 13:19:18 bupkis packagekitd[28350]: Raw timing data was { 0.880, 0.565, 0.000, 0.000 }
Dec 03 13:19:18 bupkis packagekitd[28350]: steps were set as [ 39, 50, 1, 10, -1 ] but should have been: [ 61, 39, 0, 0, -1 ] at pk-backend-hawkey.c:924
Dec 03 13:19:18 bupkis PackageKit[28350]: get-updates transaction /10573_aabdbaea from uid 0 finished with success after 1455ms
Dec 03 13:19:18 bupkis polkitd[840]: Unregistered Authentication Agent for unix-process:28378:372360553 (system bus name :1.19064, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)
Dec 03 13:19:25 bupkis sudo[28409]: zbyszek : TTY=pts/10 ; PWD=/ ; USER=root ; COMMAND=/bin/pkcon install subversion
Dec 03 13:19:25 bupkis polkitd[840]: Registered Authentication Agent for unix-process:28410:372361402 (system bus name :1.19066 [/usr/bin/pkttyagent --notify-fd 9 --fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
Dec 03 13:19:25 bupkis PackageKit[28350]: resolve transaction /10574_ecebceae from uid 0 finished with success after 15ms
Dec 03 13:19:35 bupkis PackageKit[28350]: new install-packages transaction /10575_cceebbaa scheduled from uid 0
Dec 03 13:19:35 bupkis PackageKit[28350]: install-packages transaction /10575_cceebbaa from uid 0 finished with failed after 13ms
Dec 03 13:23:09 bupkis PackageKit[28350]: get-updates transaction /10576_ddeabbed from uid 1001 finished with success after 12ms
Dec 03 13:28:12 bupkis PackageKit[28350]: daemon quit

E.g. 'daemon quit':
    SYSLOG_FACILITY=3
    _TRANSPORT=syslog
    PRIORITY=0                    <--------- this means KERN_EMERG    "<0>"  /* system is unusable               */
    SYSLOG_IDENTIFIER=PackageKit
    _COMM=packagekitd
    MESSAGE=daemon quit

I'm also wondering why the same PID uses both packagekitd and PackageKit as the syslog indentifier...

The debug lines ('Raw timing', etc.) are PRIORITY=6, i.e. INFO, but should be DEBUG.
Comment 1 Richard Hughes 2013-12-03 19:35:05 UTC 
PK is doing:

syslog (LOG_DAEMON, "daemon quit");

According to man 3 syslog:

LOG_DAEMON     system daemons without separate facility value

Is this wrong? Using LOG_USER is probably okay too.
Comment 2 Zbigniew Jedrzejewski-Szmek 2013-12-03 20:38:11 UTC 
(In reply to comment #1)
> PK is doing:
> 
> syslog (LOG_DAEMON, "daemon quit");
> 
> According to man 3 syslog:
> 
> LOG_DAEMON     system daemons without separate facility value
> 
> Is this wrong? Using LOG_USER is probably okay too.

"The priority argument is formed by ORing the facility and the level values"

So if you're not doing openlog() before:

syslog(LOG_DAEMON|LOG_DEBUG, ...)

But anyway, outputting this kind of debug information by default is a bit unnecessary. Since every daemon does it in it's own specific format, it soon looks very messy. It's much nicer to (temporarily) increase systemd log level if this kind of information is necessary. So I'd suggest to disable this output from PackageKit unless some option is given.
Comment 3 Richard Hughes 2013-12-04 13:58:48 UTC 
Ahh, that explains a few things, thanks. I think I've sorted it with:

commit 2295b08d4f19b650abc7a14436a486715a913d1c
Author: Richard Hughes <richard@hughsie.com>
Date:   Wed Dec 4 13:57:59 2013 +0000

    Use syslog() correctly
    
    Resolves: https://bugs.freedesktop.org/show_bug.cgi?id=72275

Thanks.

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.