Caddy: RFE: specific stdout/stderr format when running as systemd service

[eliasp]

Request For Enhancement

specific stdout/stderr format when running as systemd service

I'd like to see a slightly adapted format for stdout/stderr messages to be used when Caddy detects it is running as systemd service.
Currently, the output in systemctl status [email protected] looks like this:

Apr 18 15:43:10 moria systemd[1]: Starting Caddy HTTP/2 web server for app_backend...
Apr 18 15:43:10 moria systemd[1]: Started Caddy HTTP/2 web server for app_backend.
Apr 18 15:43:10 moria caddy[19203]: Activating privacy features...2016/04/18 15:43:10 [api.company.tld] failed to get certificate: [api.company.tld] error presenting token: Could not start HTTP server for challenge -> listen tcp :80: bind: permission denied
Apr 18 15:43:10 moria systemd[1]: caddy@app_backend.service: main process exited, code=exited, status=1/FAILURE
Apr 18 15:43:10 moria systemd[1]: Unit caddy@app_backend.service entered failed state.

The problems here:

• all messages are crammed into a single line before they're flushed to stdout/stderr (see line#3 of the paste above)
• each line contains a timestamp which is already provided in a better/generic way by systemd's journal

coreos/go-systemd provides the util.RunningFromSystemService() method which takes care of the detection.

This is not about implementing full systemd journal support, which would also be nice, but only about making sure the status output of the caddy service looks sane.

[wmark]

This illustrates the need for a central logging facility in _Caddy_. (Not volunteering here.)

[mholt]

Caddy has a "central logging facilitiy" -- the process log, which is what you're seeing here.

But you're logging more than just stderr, you're also logging stdout, which is not entirely useful. The "crammed into a single line" is a result of logging more than just stderr.

I'd rather have the timestamp logged twice than not at all, and I'd rather not make Caddy bend over too much just for one system manager; this seems mainly to be an aesthetic request?

[eliasp]

@mholt it's a bit beyond being simply aesthetic - systemd's journal is a structured log which means the various information in a single line of log output can be actually interpreted in a meaningful way to be filtered (based on date, context, log level, debug information, line of code generating the output, …) , aggregated etc. See also the default fields used for systemd journal logging and the implementation in coreos/go-systemd.
While journal logging is IMHO not (yet) ready for high-volume logging of thousands of "access logs" per minute or so, it's a massively useful feature for ops and dev people to test, debug, analyze application/process issues etc., so it should be primarily be used for informational process output.

Regarding the timestamps:
a timestamp as it is written currently by Caddy is the readable representation of the timestamp of the Caddy process at the moment it was written, but interpreting it properly becomes harder with different time zones, DST changes etc.
Absolute timestamps as they're used in a structured log allow to show the time depending on the viewer (adapted to the user's locale/timeformat, timezone, etc.) as the display value of the timestamp is generated at the time of inspecting it, not at the time of writing it.

Regarding the single non-wrapped line/late flush:
this means the output can't be followed "live" similar to "tail -f" using journalctl -f -u caddy@foo.

IMHO (but that's my personal opinion) structured log output should be the norm, user-readable rendering at the time of log writing an exception.

[mholt]

Okay, I can understand that.

You can fix the "non-wrapped line" issue by not logging stdout. Just log stderr. The stdout isn't used as a log anyway.

So basically, you want the timestamp to be absolute, meaning, unix timestamp format? Or something with timezone.

[eliasp]

In general, I'm fine with the timestamp as it is…
I just wanted to get rid of it when Caddy runs under the control of systemd, as in this case it:

• provides redundant (and possibly confusing because of different formats) information
• makes it harder to read the actual messages

After reading the discussion again, I feel like this RFE should be simply changed to "Implement systemd journal logging support" which would solve this issues in a generic and proper way.

Please note, that this is an absolutely low-prio issue and is only meant to provide more convenience and aims to "do things right".

[mholt]

Gotcha. I'll leave this issue here until we or someone gets around to it :smile: - thanks for the feedback!

[weingart]

Having Caddy be correct in every single environment is going to be
tantamount to going crazy. Having said that, there may be an "easy" way to
this, in a somewhat generic method:

Modify/enhance the logging parts to take an optional configuration
parameter that specifies the constants that should be used (from
https://golang.org/pkg/log/#pkg-constants) to create a new logging
instance. In this way, the default could be as it is now, but for people
with other needs (more precision, nothing, etc), they could configure the
logging facility to do the "right thing".

This should be a fairly easy diff for someone to do (beginner project).

-Toby.

On Tue, Apr 19, 2016 at 9:19 AM, Matt Holt [email protected] wrote:

Gotcha. I'll leave this issue here until we or someone gets around to it [image:
:smile:] - thanks for the feedback!

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub
https://github.com/mholt/caddy/issues/769#issuecomment-212002510

[mholt]

Excellent -- that's what I had in mind, too. :smile: Rather than make Caddy try to fit in everywhere it goes, make it possible for power users to configure it when they want to. Just not at the expense of Caddy's simplicity.

This could probably be a command line flag or an env variable.

[klingtnet]

I would also vote for _leaving the default log as it is_ but provide an option to configure the output format. The default format makes it easy for users to run some analyzer like goaccess on the logs.

[wmark]

Regarding systemd:

util.RunningFromSystemService() nor _IsRunningSystemd_, nor running in _system.slice_ are reliable indicators that Caddy can talk to systemd:

• Caddy could be wrapped in a shell, or a broker.
• I for one have Caddy in _clustering.slice_ and _user.slice_. _system.slice_ is reserved for services that are exempt from OOM killer.
• In secure environments processes are jailed (and /var/run is stripped); and can only see its own child processes, no siblings or parents.

[eliasp]

@wmark I'd start with the basic assumption that a non-exotic setup is used and try to softly degrade from there…
My 2¢: when the heuristics in util.RunningFromSystemService() fail a rather special (user-defined) setup is used (why the hell would one wrap Caddy in a shell?) and it's up to the user to either follow certain best practices or deal with the fallout on its own.

[klingtnet]

why the hell would one wrap Caddy in a shell?

If wrapped in a shell means something like ExecStart = /bin/sh -c "something --foo bar" then this is not totally uncommon.

[eliasp]

@klingtnet Sure, I know about those cases, but I've never seen a sane scenario where this wouldn't just serve as hack instead of looking for the proper solution to the problem - so IMHO still something we shouldn't put too much thought into supporting it.

[mholt]

So what about either a -logprefix option or CADDY_LOG_PREFIX env var to customize the prefix (date, time, filename/line number, etc.)?

As for systemd journal logging, we could make the logger used to be pluggable. Right now, it can be set to stdout, stderr, syslog, or a file, but we could make these all plugins so that journal is a valid log destination. Would that work?