cloud-init should emit all of its logs to the systemd journal

[Dan Watkins]

`journalctl` is a common interface on to a system's logs, and it would be good if I could use journalctl to access cloud-init's logs in the same way I do all(/most) other units running on the system. As things stand, only some of cloud-init's logging ends up in the journal:

$ journalctl -u cloud-init.service -u cloud-final.service -u cloud-init-local.service -u cloud-config.service | wc -l
164
$ wc -l /var/log/cloud-init.log
1000 /var/log/cloud-init.log

(This is particularly desirable when trying to line up cloud-init's logs with logs from another unit; if they were all in the journal then I could just specify -u to journalctl multiple times and get the lines in order all together. Currently, they don't even have the same logging format.)

[Ryan Harper (raharper)]

I think the question is; why don't we log to syslog by default. I think historically cloud-init is run in many OSes which may or maynot have syslog capabilities so it defaults to writing it's own log directly.

At least for local testing, it's easy enough to update /etc/cloud/cloud.d/05_logging.cfg

root@e1:~# diff -u /etc/cloud/cloud.cfg.d/05_logging.cfg.orig /etc/cloud/cloud.cfg.d/05_logging.cfg
--- /etc/cloud/cloud.cfg.d/05_logging.cfg.orig 2019-07-26 14:14:23.950183322 +0000
+++ /etc/cloud/cloud.cfg.d/05_logging.cfg 2019-07-26 14:14:30.110221163 +0000
@@ -57,11 +57,11 @@
 # that defines the configuration.
 #
 # If you want logs to go to syslog, uncomment the following line.
-# - [ *log_base, *log_syslog ]
+ - [ *log_base, *log_syslog ]
 #
 # The default behavior is to just log to a file.
 # This mechanism that does not depend on a system service to operate.
- - [ *log_base, *log_file ]
+# - [ *log_base, *log_file ]
 # A file path can also be used.
 # - /etc/log.conf

[Dan Watkins (oddbloke)]

We just had some internal conversation about this, which I will do my best to summarise here.

Ryan agreed that this would make debugging easier, but worried about removing cloud-init.log as it's a well established path that people rely on. He identified that `cloud-init analyze` was one example of something that would need to be modified to not rely on cloud-init.log.

I noted that I wasn't intending this as a proposal to drop cloud-init.log. I noted that we're going to need to support non-systemd instances using cloud-init.log anyway, so we won't be able to drop those code paths regardless. I noted that `cloud-init collect-logs` may need updating.

I proposed the following plan for Ubuntu: emit to both cloud-init.log and the journal in 20.04 LTS, and discuss dropping cloud-init.log for 22.04 LTS.

[Scott Moser (smoser)]

cloud-init does not write to syslog by default because it wants to
allow the user to configure rsyslog. second difference/tidyness thing
is that /var/log/cloud-init.log contains DEBUG output. I does not
feel proper to me to have debug output written to syslog (or journal)
by default.

cloud-init needs lots of cleanup on logging. it is really verbose in
most cases with output not suitable or useful to the journal.

On Mon, Jul 29, 2019 at 2:10 PM Dan Watkins
<email address hidden> wrote:
>
> We just had some internal conversation about this, which I will do my
> best to summarise here.
>
> Ryan agreed that this would make debugging easier, but worried about
> removing cloud-init.log as it's a well established path that people rely
> on. He identified that `cloud-init analyze` was one example of
> something that would need to be modified to not rely on cloud-init.log.
>
> I noted that I wasn't intending this as a proposal to drop cloud-
> init.log. I noted that we're going to need to support non-systemd
> instances using cloud-init.log anyway, so we won't be able to drop those
> code paths regardless. I noted that `cloud-init collect-logs` may need
> updating.
>
> I proposed the following plan for Ubuntu: emit to both cloud-init.log
> and the journal in 20.04 LTS, and discuss dropping cloud-init.log for
> 22.04 LTS.
>
> --
> You received this bug notification because you are subscribed to cloud-
> init in Ubuntu.
> https://bugs.launchpad.net/bugs/1838032
>
> Title:
> cloud-init should emit all of its logs to the systemd journal
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/ubuntu/+source/cloud-init/+bug/1838032/+subscriptions

[Dan Watkins (oddbloke)]

Yeah, that's a very fair point, Scott. In a freshly launched eoan container:

# journalctl | wc -l
375
# wc -l /var/log/cloud-init.log
679 /var/log/cloud-init.log

so we would be almost tripling the lines in the journal if we put everything from cloud-init over there.

If we exclude DEBUG lines, then we certainly won't make much of an impact on the journal size:

# grep -cv DEBUG /var/log/cloud-init.log
4

But unless those 4 lines are really good, I don't think we're adding much value. ;)

There is a fair amount of low-hanging fruit in the log, though:

Reading/writing files (a third of the lines!):
  # grep -c '\(Read\|Reading\|Writing to\) ' /var/log/cloud-init.log
  227

Running commands:
  # grep -c Running\ command /var/log/cloud-init.log
  28

Loading YAML:
  # grep -c "Attempting to load yaml" /var/log/cloud-init.log
  36

Internal handler logging:
  # grep -c '\(default\|Calling\) handler' /var/log/cloud-init.log
  32

Duplicate logging of config module start:
  # grep -c '\(using lock\|Running module\)' /var/log/cloud-init.log
  103

With all these excluded, we're down to 253 lines, which is within punching distance of reasonable, I think.

(FWIW, I think the right way to go around this would be to promote messages to INFO one-by-one, examining the non-DEBUG log output each time, to find a good balance between information and verbosity. The above exclusions are just to illustrate that we have an easy upper bound of ~250 lines.)

[Dan Watkins (oddbloke)]

OK, so given my investigation in the previous comment, perhaps we can log INFO (and higher) messages to the journal in the short-term, and in the medium-term look at changing some DEBUG lines to INFO to flesh out that journal logging? Does that sounds like a reasonable plan?

[Chad Smith (chad.smith)]

Agreed to start with INFO level, medium-term we can decide whether we want to promote up to INFO level, or add a TRACE level in cloud-init and demote most debug statements to TRACE to reduce the volume of messages at debug level.