Bug 41379 - logs debug messages to syslog when using systemd
Summary: logs debug messages to syslog when using systemd
Status: RESOLVED MOVED
Alias: None
Product: PolicyKit
Classification: Unclassified
Component: daemon (show other bugs)
Version: unspecified
Hardware: Other All
: medium normal
Assignee: David Zeuthen (not reading bugmail)
QA Contact: David Zeuthen (not reading bugmail)
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2011-10-01 06:50 UTC by Michael Biebl
Modified: 2018-08-20 21:38 UTC (History)
0 users

See Also:
i915 platform:
i915 features:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Michael Biebl 2011-10-01 06:50:57 UTC
polkitd frequently logs to stderr. Under sysvinit this went to
dbus-daemon's stderr, which is /dev/null, but with init=/bin/systemd
it ends up in syslog, in rather more detail than is useful when not debugging:

Oct  1 14:26:59 reptile dbus-daemon[1511]: ** (polkitd:2034): DEBUG: system-bus-name::1.152 is inquiring whether system-bus-name::1.74 is authorized for org.freedesktop.NetworkManager.settings.modify.own
Oct  1 14:26:59 reptile dbus-daemon[1511]: ** (polkitd:2034): DEBUG:  user of caller is unix-user:root
Oct  1 14:26:59 reptile dbus-daemon[1511]: ** (polkitd:2034): DEBUG:  user of subject is unix-user:smcv
Oct  1 14:26:59 reptile dbus-daemon[1511]: ** (polkitd:2034): DEBUG: checking whether system-bus-name::1.74 is authorized for org.freedesktop.NetworkManager.settings.modify.own
Oct  1 14:26:59 reptile dbus-daemon[1511]: ** (polkitd:2034): DEBUG:   0xc908c0
Oct  1 14:26:59 reptile dbus-daemon[1511]: ** (polkitd:2034): DEBUG:  subject is in session /org/freedesktop/ConsoleKit/Session2 (local=1 active=1)
Oct  1 14:26:59 reptile dbus-daemon[1511]: ** (polkitd:2034): DEBUG:  is authorized (has implicit authorization local=1 active=1)

I think it should suppress g_debug() messages, unless they are requested via
a command-line option or environment variable.


Bug-Debian: http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=643991
Comment 1 David Zeuthen (not reading bugmail) 2011-10-01 07:38:29 UTC
I actually don't like how systemd is doing that by default now ... but that's their problem I guess. I'm betting a lot of passwords and sensitive information etc. will show up :-)

It also think it misses the point that sometimes an app wants to log to /var/log/secure and not /var/log/messages (and polkitd is one of those apps, actually). Yes, I'm aware you can emit some string <N> as the initial part of your debug output but what's the advantage to using printf(3) with this (undocumented? unstable?) API instead of using syslog(3)?

Itching to close this NOTOURBUG but... anyway... can't we just ship a systemd unit file to stop this?
Comment 2 Kay Sievers 2011-10-01 08:51:12 UTC
I'm convinced that no tool should print any debug messages by default. Debug mode should be explicitly requested in the service, with a tool/signal/config file setting.

All debug output is composed with printf and string substitutions, and that can be really expensive. And all that, just to pipe it to /dev/null all the time.

It's not so much about polkit I think, the glib debug stuff seem to be much to simple, and it should be fixed. Debugging needs to be conditional, _before_ the string substitutions are executed.
Comment 3 David Zeuthen (not reading bugmail) 2011-10-01 09:25:32 UTC
Kay: you are right that the glib logging routines leaves much to be desired but that's not the point. The point is that it's frustrating to see bugs like this because the systemd devolopers decide "it's our way, or the highway" by forcing the issue to the apps. And you are lucky, in the polkit case, that we currently don't include sensitive output that you decide to log. You may not be so lucky in other cases. I'm not sure this behavior is helping the perception of your project.

FWIW, I'm not terribly interested in discussing the finer points of logging in this bug but suffice to say I'm not at all convinced that just shoving stdout/stderr to syslog is in any way helpful - as we discussed in CA, I think a more high-level approach is desirable. But this bug is not the right place to discuss this.

To actually make forward progress, it would be helpful to know how to make systemd stop this behavior as I asked for in comment 1.
Comment 4 Simon McVittie 2011-10-01 12:56:08 UTC
(In reply to comment #1)
> I actually don't like how systemd is doing that by default now ... but that's
> their problem I guess.

It's indirect: the dbus systemd unit logs its stdout/stderr, and all D-Bus system services (or when using systemd activation, all system services that don't have a systemd unit) inherit its stdout/stderr. Under sysvinit, dbus-daemon's stdout/stderr would typically be /dev/null so the messages get lost.

> I'm betting a lot of passwords and sensitive information
> etc. will show up :-)

Only if you'd have output them to your stdout/stderr to start with.

(In reply to comment #2)
> I'm convinced that no tool should print any debug messages by default. Debug
> mode should be explicitly requested in the service, with a tool/signal/config
> file setting.

Telepathy has/had some nice macros to help with this: DEBUG ("answer=%d", 42) expands to a conditional call to g_debug ("%s: answer=%d", "the_function", 42), conditional on a debug flag that's usually set via environment variables (and can also be turned off entirely at compile time, but you almost never want that).
Comment 5 David Zeuthen (not reading bugmail) 2011-10-01 14:38:06 UTC
(In reply to comment #4)
> Only if you'd have output them to your stdout/stderr to start with.

Sure. I'm still betting it would show up for some apps.

> (In reply to comment #2)
> > I'm convinced that no tool should print any debug messages by default. Debug
> > mode should be explicitly requested in the service, with a tool/signal/config
> > file setting.
> 
> Telepathy has/had some nice macros to help with this: DEBUG ("answer=%d", 42)
> expands to a conditional call to g_debug ("%s: answer=%d", "the_function", 42),
> conditional on a debug flag that's usually set via environment variables (and
> can also be turned off entirely at compile time, but you almost never want
> that).

Sure. I'm not opposed to making the command-line that the D-Bus activator spawns something like this

 polkitd --mininum-debug-level=notice

assuming a logging API such as

 http://people.freedesktop.org/~david/udisks2-20110929/udisks2-Logging.html

but for working with bug reports, I'd really like

 polkitd --replace

to spew out all debug including level _debug().

For the record, I'm not opposed to stop using syslog() and just rework udisks_log() to append the <Level> stuff and log via stdout/stderr. It's a fine idea.

My main beef is that the systemd developers are forcing my hand like this (who knows, I could have been g_debug()'ing sensitive info so this would be a security bug) - it's not really playing nice at all - and from a practical point of view, I just don't have time to change polkit right here and right now to do this. Sorry but that's just how it is.
Comment 6 Michael Biebl 2011-10-02 07:35:10 UTC
(In reply to comment #3)
> Kay: you are right that the glib logging routines leaves much to be desired but

I can't really comment on that, I just want to say that I prefer applications which are silent by default and only log error messages.
So I'd very much welcome a --debug command line switch.

> To actually make forward progress, it would be helpful to know how to make
> systemd stop this behavior as I asked for in comment 1.

That should be possible by shipping a systemd service file and redirecting stdout/stderr to /dev/null. For that you need to amend the dbus service file and add:
SystemdService=policykit.service

and then install a policykit.service file like:

[Unit]
Description=Framework for managing administrative policies and privileges

[Service]
Type=dbus
BusName=org.freedesktop.PolicyKit1
ExecStart=@libexecdir@/polkitd
StandardOutput=null
StandardError=null

If you want to make the policykit service deactivatable, you can change that the dbus service file to:
SystemdService=dbus-org.freedesktop.PolicyKit1.service

[Unit]
Description=Framework for managing administrative policies and privileges

[Service]
Type=dbus
BusName=org.freedesktop.PolicyKit1
ExecStart=@libexecdir@/polkitd
StandardOutput=null
StandardError=null

[Install]
Alias=dbus-org.freedesktop.PolicyKit1.service


This way the PolicyKit dbus service can be disabled via systemctl enable/disable policykit.service

The Alias directive will create a symlink pointing to policykit.service
Comment 7 David Zeuthen (not reading bugmail) 2011-10-18 09:00:26 UTC
So I tried this.

> If you want to make the policykit service deactivatable, you can change
> that the dbus service file to:
> SystemdService=dbus-org.freedesktop.PolicyKit1.service

Unless I make my service de-activatable, then the StandardOutput and StandardError directives in the systemd unit file are not respected when the service is activated in response to an incoming D-Bus message.

However, if I _do_ make the service activatable then system-admin work is required to enable the service because it's not enabled by default.

Is it supposed to work this way?

You know what, I'm just going to nuke stdout and stderr file descriptors unless an option --debug is given on the command-line. That way I don't have to deal with this at all...
Comment 8 David Zeuthen (not reading bugmail) 2011-10-18 10:17:04 UTC
I've added a --no-debug option that is now used when launching the service

 http://cgit.freedesktop.org/PolicyKit/commit/?id=3811e51b81320a574bb31aa64b6af56340012527

At least this will take care of all the syslog spam for now.

Sure, we should still add a systemd unit file ... I talked to Kay on IM and he said there is a way to do this without requiring the user to run 'systemctl enable polkit.service' (it involves nuking the [Install] section and creating the symlink yourself... that way polkit cannot be enabled nor disabled).
Comment 9 GitLab Migration User 2018-08-20 21:38:58 UTC
-- GitLab Migration Automatic Message --

This bug has been migrated to freedesktop.org's GitLab instance and has been closed from further activity.

You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.freedesktop.org/polkit/polkit/issues/62.


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.