Nomad duplicates logs to stdout when enable_syslog is true

[rodrigol-chan]

Nomad version

Nomad v1.4.3 (f464aca721d222ae9c1f3df643b3c3aaa20e2da7)

Operating system and Environment details

$ lsb_release  -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 22.04.1 LTS
Release:        22.04
Codename:       jammy

Issue

When enable_syslog is true, Nomad logs both to syslog and to stdout.

Reproduction steps

journalctl shows this but log lines aren't always interspersed one by one but rather in blocks. It's easy to check by passing _TRANSPORT.

Expected Result

$ sudo journalctl --lines=5 --unit=nomad.service _TRANSPORT=syslog
Jan 03 16:07:08 nomad-client-camel nomad[11714]:  agent: (runner) starting
Jan 03 16:07:08 nomad-client-camel nomad[11714]:  agent: (clients) disabling vault SSL verification
Jan 03 16:07:08 nomad-client-camel nomad[11714]:  agent: (runner) creating watcher
Jan 03 16:07:08 nomad-client-camel nomad[11714]:  agent: (runner) starting
Jan 03 16:07:08 nomad-client-camel nomad[11714]:  agent: (runner) starting
$ sudo journalctl --lines=5 --unit=nomad.service _TRANSPORT=stdout
$

Actual Result

$ sudo journalctl --lines=5 --unit=nomad.service _TRANSPORT=syslog
Jan 03 16:07:08 nomad-client-camel nomad[11714]:  agent: (runner) starting
Jan 03 16:07:08 nomad-client-camel nomad[11714]:  agent: (clients) disabling vault SSL verification
Jan 03 16:07:08 nomad-client-camel nomad[11714]:  agent: (runner) creating watcher
Jan 03 16:07:08 nomad-client-camel nomad[11714]:  agent: (runner) starting
Jan 03 16:07:08 nomad-client-camel nomad[11714]:  agent: (runner) starting
$ sudo journalctl --lines=5 --unit=nomad.service _TRANSPORT=stdout
Jan 03 16:07:08 nomad-client-camel nomad[11714]:     2023-01-03T16:07:08.567+0100 [INFO]  agent: (runner) starting
Jan 03 16:07:08 nomad-client-camel nomad[11714]:     2023-01-03T16:07:08.567+0100 [WARN]  agent: (clients) disabling vault SSL verification
Jan 03 16:07:08 nomad-client-camel nomad[11714]:     2023-01-03T16:07:08.568+0100 [INFO]  agent: (runner) creating watcher
Jan 03 16:07:08 nomad-client-camel nomad[11714]:     2023-01-03T16:07:08.568+0100 [INFO]  agent: (runner) starting
Jan 03 16:07:08 nomad-client-camel nomad[11714]:     2023-01-03T16:07:08.568+0100 [INFO]  agent: (runner) starting
$

Job file (if appropriate)

Not applicable.

Nomad Server logs (if appropriate)

Not applicable.

Nomad Client logs (if appropriate)

Not applicable.

[tgross]

Hi @rodrigol-chan! Thanks for opening this issue. I've verified the behavior as well -- it looked from your logs that it was specifically consul-template logs, but I see this for any logs. It's particularly easy to see if you run nomad in the foreground, as the logs will go to the journal.

I suspect the problem here is just one of design intent. If you're on a host with journald, we're assuming you're not also sending via syslog (or at least, if you are you're not having journald collect the syslog as well). Maybe we need a way to suppress "normal" stdout/stderr output as well. As a workaround in the meantime, your systemd unit could redirect stdout/stderr to /dev/null.

[rodrigol-chan]

The main advantages about sending logs via syslog even when stdout is captured into the journal is one of log cohesion. Multiline logs sent via syslog are kept multiline, whereas e.g. stack traces are broken on line boundaries and show up as different messages. I'll try the workaround, thanks!

[tgross]

So really what you're looking for here is the ability to turn off stdout logging while leaving syslog logging on? Arguably this problem gets worse with #15625 b/c you could previously turn the log-level to "OFF" and have enable_syslog = true which will emit "INFO"-level only (and can't be configured until #15625 is merged). We'll probably merge that fix anyways and then visit implementing some kind of syslog-only flag.

[rodrigol-chan]

Yes, that's exactly right. Thank you for looking into this!