Discussion:
[Sks-devel] SKS logging to syslog using 1.1.6-2~bpo8+1 from debian-packports
Pete Stephenson
2016-12-04 00:47:30 UTC
Permalink
Hi all,

I just setup a fresh sks installation using version 1.1.6-2~bpo8+1
from debian-backports. The server is running Debian Jessie.

By default, all the logs (e.g. what normally would go into db.log and
recon.log) end up in /var/log/syslog, which is not expected or
desired.

My previous installation, running 1.1.5 on Ubuntu 14.04, sent those
logs to /var/log/sks/db.log and /var/log/sks/recon.log.

I've compared my sksconf files and can't find any differences that
would account for those files not being created.

The debian-sks user has write access to the directory /var/log/sks/

Any ideas what might be going on? I'd be happy to provide logs or
other details upon request.
--
Pete Stephenson
John Zaitseff
2016-12-04 02:27:52 UTC
Permalink
Hi, Pete et al.,
Post by Pete Stephenson
I just setup a fresh sks installation using version 1.1.6-2~bpo8+1
from debian-backports. The server is running Debian Jessie.
By default, all the logs (e.g. what normally would go into db.log and
recon.log) end up in /var/log/syslog, which is not expected or
desired.
My previous installation, running 1.1.5 on Ubuntu 14.04, sent those
logs to /var/log/sks/db.log and /var/log/sks/recon.log.
This stumped me for a while as well, until I looked into it rather
more carefully. The issue is that the new Debian package uses
systemd(8) instead of the tradition /etc/init.d scripts, and the
config files for systemd specify all output goes to syslog.

To fix this, create two files, both called override.conf, one in the
/etc/systemd/system/sks.service.d directory, the other in the
/etc/systemd/system/sks-recon.service.d directory.

I'm not sure whether this mailing list allows attachments, so here
are the contents of those files:

====
# /etc/systemd/system/sks-recon.service.d/override.conf
# [JNZ] Modified 19-Nov-2016 for keyserver.zap.org.au

[Service]
ExecStart=
ExecStart=/usr/sbin/sks recon
====

====
# /etc/systemd/system/sks.service.d/override.conf
# [JNZ] Modified 19-Nov-2016 for keyserver.zap.org.au

[Service]
ExecStart=
ExecStart=/usr/sbin/sks db
====

Restart sks ("systemctl restart sks-recon.service && systemctl
restart sks.service", all on one line) and you should be good to go.

You could overwrite files in /lib/systemd/system, but they will be
overwritten on the next package upgrade.

Hope this helps.

Yours truly,

John Zaitseff

--
John Zaitseff ,--_|\ The ZAP Group
Phone: +61 2 9643 7737 / \ Sydney, Australia
E-mail: ***@zap.org.au \_,--._* http://www.zap.org.au/
v
Pete Stephenson
2016-12-05 10:54:49 UTC
Permalink
Post by John Zaitseff
Hi, Pete et al.,
Hi John,
Post by John Zaitseff
This stumped me for a while as well, until I looked into it rather
more carefully. The issue is that the new Debian package uses
systemd(8) instead of the tradition /etc/init.d scripts, and the
config files for systemd specify all output goes to syslog.
Indeed, this is the case!
Post by John Zaitseff
To fix this, create two files, both called override.conf, one in the
/etc/systemd/system/sks.service.d directory, the other in the
/etc/systemd/system/sks-recon.service.d directory.
This got me about 95% of the way there, but it turns out that the
version of systemd used by Debian Jessie (currently stable) doesn't
support "stubs" according to the answer at
<https://askubuntu.com/questions/692732/how-to-reproduce-systemctl-edit-behavior-in-ubuntu-lts>,
so we can't just include the parts that we want to change (the
ExecStart line), but instead need to include the whole file.

Thus, I simply copied the sks.service and sks-recon.service files from
/lib/systemd/system/ to /etc/systemd/system/ (from where systemd
preferentially loads files) and removed "-stdoutlog" from the
ExecStart line, ran "systemctl daemon-reload" to reload the config
files, and ran "systemctl sks restart" and "systemctl sks-recon
restart" and all worked perfectly. The logs are being correctly
written.

Thank you very much for pointing me in the right direction and for
helping me solve this mystery.

Cheers!
-Pete
--
Pete Stephenson
Daniel Kahn Gillmor
2016-12-05 14:01:57 UTC
Permalink
Hi John and Pete--
Post by John Zaitseff
====
# /etc/systemd/system/sks-recon.service.d/override.conf
# [JNZ] Modified 19-Nov-2016 for keyserver.zap.org.au
[Service]
ExecStart=
ExecStart=/usr/sbin/sks recon
====
====
# /etc/systemd/system/sks.service.d/override.conf
# [JNZ] Modified 19-Nov-2016 for keyserver.zap.org.au
[Service]
ExecStart=
ExecStart=/usr/sbin/sks db
====
this does indeed remove the logging of sks to stdout (it drops the
-stdoutlog argument), and causes sks to manually manage its logs, so it
is one way to meets Pete's goals.

But let me explain why i think leaving the logs going to stdout is a
better long-term solution (and indeed, why that will continue to be the
default in debian).

sks has enough to do with managing its network requests (it doesn't even
really do that very well, considering that it needs to be behind an HTTP
reverse proxy to operate safely on the internet). Managing a logfile,
and having to close and re-open the logfile during logfile rotation is
yet another complication that sks really shouldn't need to deal with.

If sks logs to stdout, it just writes to a file descriptor and then
never thinks about it again. This is better for sks, because it gives
it less to "think" about.

so the question is: who handles that file descriptor? under systemd,
that output fd is input to journald, which writes its data to
/var/log/journal, and to any other authorized consumers. the journal
can be queried with, e.g. "journalctl --since yesterday --unit sks", and
the last few entries can be seen with "systemctl status sks" or
"systemctl status sks-recon" as part of an easy service state overview.

if you've got syslog or syslog-ng or rsyslog hooked up into journald,
then they accept new log entries and write them to disk in /var/log.

So the question is: why do you care that the logs are written to
/var/log/sks? if what you want is logs that can be found consistently,
i encourage you to review the output of journalctl. Alternately, if you
really need /var/log/sks/ for whatever reason, and you're running one of
the variants of syslog, i believe you can configure the way that
journald is connected to the syslog daemons so that logs from a given
service get written to a specific logfile. I don't know which syslog
you're using, so i can't provide more details than that, though.

If you take that approach, then "systemctl status sks" will still work
for you, *and* you'll get files in the expected place, *and* you'll get
any future upgrades to the sks{,-recon}.service files provided by the
package manager.

Hope this helps,

--dkg
Pete Stephenson
2016-12-05 14:37:13 UTC
Permalink
On Mon, Dec 5, 2016 at 3:01 PM, Daniel Kahn Gillmor
Post by Daniel Kahn Gillmor
Hi John and Pete--
Hi Daniel,
Post by Daniel Kahn Gillmor
this does indeed remove the logging of sks to stdout (it drops the
-stdoutlog argument), and causes sks to manually manage its logs, so it
is one way to meets Pete's goals.
But let me explain why i think leaving the logs going to stdout is a
better long-term solution (and indeed, why that will continue to be the
default in debian).
sks has enough to do with managing its network requests (it doesn't even
really do that very well, considering that it needs to be behind an HTTP
reverse proxy to operate safely on the internet). Managing a logfile,
and having to close and re-open the logfile during logfile rotation is
yet another complication that sks really shouldn't need to deal with.
While I agree that a program should focus on the one thing it does
well, writing a logfile seems to be a pretty basic thing.

I recall that other tools like logrotate can deal with various
oddities of certain logfiles even if the program writing the logs
doesn't play nice. For example, NTPd can be really chatty with the
Motorola Oncore driver (writing a bunch of data to syslog every
second), so I recompiled it so it can write that to a separate log
defined in the config file. It never closes that file for rotation,
but logrotate can "copytruncate" the file and that has the same
result.

Either way, it seems strange that SKS is ignoring the "logfile: log"
line I explicitly put in the sksconf file in favor of the -stdoutlog
arguement in the .service file.

I don't mind having certain behavior be the default -- and, as you
say, there are good reasons for having that be the default -- but
user-added entries in the config file should take precedence.
Post by Daniel Kahn Gillmor
If sks logs to stdout, it just writes to a file descriptor and then
never thinks about it again. This is better for sks, because it gives
it less to "think" about.
so the question is: who handles that file descriptor? under systemd,
that output fd is input to journald, which writes its data to
/var/log/journal, and to any other authorized consumers. the journal
can be queried with, e.g. "journalctl --since yesterday --unit sks", and
the last few entries can be seen with "systemctl status sks" or
"systemctl status sks-recon" as part of an easy service state overview.
if you've got syslog or syslog-ng or rsyslog hooked up into journald,
then they accept new log entries and write them to disk in /var/log.
So the question is: why do you care that the logs are written to
/var/log/sks? if what you want is logs that can be found consistently,
i encourage you to review the output of journalctl. Alternately, if you
really need /var/log/sks/ for whatever reason, and you're running one of
the variants of syslog, i believe you can configure the way that
journald is connected to the syslog daemons so that logs from a given
service get written to a specific logfile. I don't know which syslog
you're using, so i can't provide more details than that, though.
If you take that approach, then "systemctl status sks" will still work
for you, *and* you'll get files in the expected place, *and* you'll get
any future upgrades to the sks{,-recon}.service files provided by the
package manager.
You're right, if one uses systemd then keeping everything in the
systemd ecosystem makes sense.

Without wanting to reignite the systemd holy war, my use of systemd to
this point has been as an init system, and I have no problem with
that. It does what I need it to reasonably well and I have no
particular complaints.

However, using it as a logging system is strange to me. Years of
habitually using tools like tail to follow log files and having
logrotate rotate them day-by-day and gzip old logs is a bit of an
obstacle to overcome for something that, IMHO, doesn't seem to do
anything particularly better...but I'm willing to learn.

I'm using a bog-standard Debian Jessie installation and it appears to
be using rsyslog. I'm not familiar with how rsyslog and systemd
interact in regards to logging, but if you have any advice to point me
in the right direction I'd be very much obliged.
Post by Daniel Kahn Gillmor
Hope this helps,
It does, indeed. Thank you for the response.

Cheers!
-Pete
--
Pete Stephenson
Daniel Kahn Gillmor
2016-12-06 02:43:30 UTC
Permalink
Post by Pete Stephenson
I don't mind having certain behavior be the default -- and, as you
say, there are good reasons for having that be the default -- but
user-added entries in the config file should take precedence.
hm, i think i agree with you there, but the default should *actually* be
to log to stdout or stderr.

there are a lot more subtleties, corner cases which can break, and
potential permissions problems if the daemon has to open and write to
and close the file, and respond to logrotation events, even if it
doesn't manage the rotation itself (e.g. what happens to a file if it's
copy+truncated while i'm holding it open to write to it?)

writing to a known file descriptor and then forgetting about it is the
simplest possible thing :)
Post by Pete Stephenson
However, using it as a logging system is strange to me. Years of
habitually using tools like tail to follow log files and having
logrotate rotate them day-by-day and gzip old logs is a bit of an
obstacle to overcome for something that, IMHO, doesn't seem to do
anything particularly better...but I'm willing to learn.
the idea is that it's a system service manager -- it knows how to start
and stop services, what to do with their output, how to keep track of
any children they might spawn, how to clean them up, what resources to
give them, etc. This is what an init system *should* do, since it's
well-placed to see all the pieces of the puzzle and to help keep them
isolated where possible and connected where necessary.
Post by Pete Stephenson
I'm using a bog-standard Debian Jessie installation and it appears to
be using rsyslog. I'm not familiar with how rsyslog and systemd
interact in regards to logging, but if you have any advice to point me
in the right direction I'd be very much obliged.
rsyslog receives its input from journald at /run/systemd/journal/syslog,
as standard syslog messages, annotated with identity, facility, and
priority (see syslog(3) for a common library interface used by clients
to write this information)

It then writes them to various files, as determined by the properties
mentioned above, matched as described in rsyslog.conf(5). On debian
jessie, you should be able to drop a file in /etc/rsyslog.d/sks.conf
that contains directives to produce the old /var/log/sks/*.log files,
using the expected permissions, etc. Only now, you don't actually need
to have those files writable (or readable) by the sks-debian user
account at all; the logging is independent of the daemon, and if the
daemon is ever compromised, it can't overwrite its logs.

if you come up with a reasonable /etc/rsyslog.d/sks.conf that you think
would work for other people who happen to run rsyslog in addition to
systemd, i'd be happy to ship it in the debian package to support that
use case. If you decide to do that, you can mail it to the list here,
or you can report it via the debian BTS using "reportbug sks".

Happy hacking,

--dkg
Brian Minton
2016-12-30 16:57:55 UTC
Permalink
It might be useful to submit a bug report against the debian sks package
with that patch.
Post by John Zaitseff
Hi, Pete et al.,
Post by Pete Stephenson
I just setup a fresh sks installation using version 1.1.6-2~bpo8+1
from debian-backports. The server is running Debian Jessie.
By default, all the logs (e.g. what normally would go into db.log and
recon.log) end up in /var/log/syslog, which is not expected or
desired.
My previous installation, running 1.1.5 on Ubuntu 14.04, sent those
logs to /var/log/sks/db.log and /var/log/sks/recon.log.
This stumped me for a while as well, until I looked into it rather
more carefully. The issue is that the new Debian package uses
systemd(8) instead of the tradition /etc/init.d scripts, and the
config files for systemd specify all output goes to syslog.
To fix this, create two files, both called override.conf, one in the
/etc/systemd/system/sks.service.d directory, the other in the
/etc/systemd/system/sks-recon.service.d directory.
I'm not sure whether this mailing list allows attachments, so here
====
# /etc/systemd/system/sks-recon.service.d/override.conf
# [JNZ] Modified 19-Nov-2016 for keyserver.zap.org.au
[Service]
ExecStart=
ExecStart=/usr/sbin/sks recon
====
====
# /etc/systemd/system/sks.service.d/override.conf
# [JNZ] Modified 19-Nov-2016 for keyserver.zap.org.au
[Service]
ExecStart=
ExecStart=/usr/sbin/sks db
====
Restart sks ("systemctl restart sks-recon.service && systemctl
restart sks.service", all on one line) and you should be good to go.
You could overwrite files in /lib/systemd/system, but they will be
overwritten on the next package upgrade.
Hope this helps.
Yours truly,
John Zaitseff
--
John Zaitseff ,--_|\ The ZAP Group
Phone: +61 2 9643 7737 / \ Sydney, Australia
v
_______________________________________________
Sks-devel mailing list
https://lists.nongnu.org/mailman/listinfo/sks-devel
Loading...