Merge ~harlowja/cloud-init:just-file-logs into cloud-init:master

[Joshua Harlow]

[Ryan Harper (raharper)]

I'd like to see this merged.

Currently we see mixed timestamp formats in cloud-init.log:

2016-08-29 15:12:15,475 - __init__.py[DEBUG]: handling ssh with freq=None and args=[]
Aug 29 15:12:15 p1 [CLOUDINIT] cloud-init-cfg[INFO]: cloud-init-cfg ['all', 'config']

The point in which the logging format changes depending on whether (and when) the syslog service becomes available and cloud-init updates the logging configuration.

Besides the mixed format, the default rsyslog format (On Ubuntu at least) doesn't include a sub-second timestamp by default, where as the logging module default %(asctime) does at least provide millisecond resolution (note the ,475 in the %(asctime) and the lack of subsecond resolution in the second entry from above).

I'd also like to see a change to the default formatting string to include the same [CLOUDINIT] string, which is injected in the syslog based formatting.

Keeping these strings consistent makes parsing cloud-init.log more reliable.

Please consider adding this to your MP, or conversely, I can propose this separately after
this MP is merged.

root@x1:/etc/cloud/cloud.cfg.d# diff -u 05_logging.cfg.dist 05_logging.cfg
--- 05_logging.cfg.dist 2016-07-14 18:49:20.000000000 +0000
+++ 05_logging.cfg 2016-09-15 21:51:12.592673811 +0000
@@ -35,7 +35,7 @@
    args=(sys.stderr,)

    [formatter_arg0Formatter]
- format=%(asctime)s - %(filename)s[%(levelname)s]: %(message)s
+ format=%(asctime)s [CLOUDINIT] %(filename)s[%(levelname)s]: %(message)s

[Scott Moser (smoser)]

Cloud-init's logging basically employed a "try syslog and fallback to direct log to file".
The proposed "just log to a file" is definitely dramatically simpler and advantageous in some cases.

The way the "try syslog and fallback" works (or worked) on Ubuntu up until systemd was:

a.) cloud-init init --local
    1. read logging config,
    2. attempt to log to syslog ([ *log_base, *log_syslog ])
    3. that fail, so it log to file directly

b.) cloud-init init
   1.) rsyslog would have /dev/log up functional at this point
   2.) cloud-init logging config read and ends up logging to syslog

Systemd changed some things in teh way /dev/log was handled, and the above no longer worked well.

Additionally, cloud-init installs a file /etc/rsyslog.d/21-cloudinit.conf which tells rsyslog to redirect messages generated by cloud-init to /var/log/cloud-init.log

The value of doing this in this way was that we use syslog, so if the user had configured the system to log remotely, cloud-init's logs would go to that remote system as they desired.

If we directly log to a file, then cloud-init's log messages will not without further configuration go to syslog.

One other thing to be aware of is that cloud-init can itself configure rsyslog through cloudinit/config/cc_rsyslog.py . So, the user could provide in user-data some rsyslog configuration, and then the system's syslog (including cloud-init messages) would start goign to that remote server as soon as they realistically could.

[Ryan Harper (raharper)]

I think it's highly useful to have a single logging mechanism for
cloud-init; I do like that cloud-init logs could also be redirected
(copied) to rsyslog for offbox config.
But I'm primarily interested in ensuring the the logs that cloud-init
writes out are formatted the same; and that we don't wait until cloud-init
config stage to configure
logging as that prevents having all events logged in the same format for
each of the four stages.

On Wed, Sep 28, 2016 at 11:19 AM, Scott Moser <email address hidden> wrote:

> Cloud-init's logging basically employed a "try syslog and fallback to
> direct log to file".
> The proposed "just log to a file" is definitely dramatically simpler and
> advantageous in some cases.
>
> The way the "try syslog and fallback" works (or worked) on Ubuntu up until
> systemd was:
>
> a.) cloud-init init --local
> 1. read logging config,
> 2. attempt to log to syslog ([ *log_base, *log_syslog ])
> 3. that fail, so it log to file directly
>
> b.) cloud-init init
> 1.) rsyslog would have /dev/log up functional at this point
> 2.) cloud-init logging config read and ends up logging to syslog
>
> Systemd changed some things in teh way /dev/log was handled, and the above
> no longer worked well.
>
> Additionally, cloud-init installs a file /etc/rsyslog.d/21-cloudinit.conf
> which tells rsyslog to redirect messages generated by cloud-init to
> /var/log/cloud-init.log
>
> The value of doing this in this way was that we use syslog, so if the user
> had configured the system to log remotely, cloud-init's logs would go to
> that remote system as they desired.
>
> If we directly log to a file, then cloud-init's log messages will not
> without further configuration go to syslog.
>
> One other thing to be aware of is that cloud-init can itself configure
> rsyslog through cloudinit/config/cc_rsyslog.py . So, the user could
> provide in user-data some rsyslog configuration, and then the system's
> syslog (including cloud-init messages) would start goign to that remote
> server as soon as they realistically could.
>
> --
> https://code.launchpad.net/~harlowja/cloud-init/+git/
> cloud-init/+merge/301729
> Your team cloud init development team is requested to review the proposed
> merge of ~harlowja/cloud-init:just-file-logs into cloud-init:master.
>
> _______________________________________________
> Mailing list: https://launchpad.net/~cloud-init-dev
> Post to : <email address hidden>
> Unsubscribe : https://launchpad.net/~cloud-init-dev
> More help : https://help.launchpad.net/ListHelp
>

[Scott Moser (smoser)]

On Wed, 28 Sep 2016, Ryan Harper wrote:

> I think it's highly useful to have a single logging mechanism for
> cloud-init; I do like that cloud-init logs could also be redirected
> (copied) to rsyslog for offbox config.
> But I'm primarily interested in ensuring the the logs that cloud-init
> writes out are formatted the same; and that we don't wait until cloud-init
> config stage to configure
> logging as that prevents having all events logged in the same format for
> each of the four stages.

And what I'm primarily interested in is making sure logging to syslog
works, as is it is an extremely popular and common way to log.

I agree that the inconsistent log formats are a pain. I also agree that
your use case is valid. However, that does not all of a sudden mean
others use cases which were originally supported are no longer valid.

[Joshua Harlow (harlowja)]

Ya, so I'm on the fence a little on this. If this change merges people that were using syslog will no longer (by default) see the syslog stuff, that's bad. But the was it working in a systemd world anymore, perhaps not, so that's good. Is there any middle area for this where the old and the new can work (and not be crazy complicated?)

[Scott Moser (smoser)]

I just pulled this, other than the formatter= change.
we'll now log to file.

[Ryan Harper (raharper)]

On Tue, Nov 22, 2016 at 1:34 PM, Scott Moser <email address hidden> wrote:

> I just pulled this, other than the formatter= change.
> we'll now log to file.
>

Great. With the use of journalctl -o short-precise, we can extract
high-res timestamps and events without the change.

>
> --
> https://code.launchpad.net/~harlowja/cloud-init/+git/
> cloud-init/+merge/301729
> Your team cloud init development team is requested to review the proposed
> merge of ~harlowja/cloud-init:just-file-logs into cloud-init:master.
>
> _______________________________________________
> Mailing list: https://launchpad.net/~cloud-init-dev
> Post to : <email address hidden>
> Unsubscribe : https://launchpad.net/~cloud-init-dev
> More help : https://help.launchpad.net/ListHelp
>

diff --git a/config/cloud.cfg.d/05_logging.cfg b/config/cloud.cfg.d/05_logging.cfg
index 2e18073..507b458 100644
--- a/config/cloud.cfg.d/05_logging.cfg
+++ b/config/cloud.cfg.d/05_logging.cfg
@@ -31,7 +31,7 @@ _log:
    [handler_consoleHandler]
    class=StreamHandler
    level=WARNING
-   formatter=arg0Formatter
+   formatter=simpleFormatter
    args=(sys.stderr,)
    
    [formatter_arg0Formatter]
@@ -54,13 +54,21 @@ _log:
 
 log_cfgs:
 # These will be joined into a string that defines the configuration
- - [ *log_base, *log_syslog ]
+#
+# If your desire syslog, just uncomment the following line.
+# - [ *log_base, *log_syslog ]
+#
 # These will be joined into a string that defines the configuration
+#
+# Otherwise by default we just use the most basic (known to work
+# mechanism that does not depend on a system service to operate; which
+# due to cloud-init execution lifecycle we may not always be able to
+# depend on working correctly).
  - [ *log_base, *log_file ]
-# A file path can also be used
+# A file path can also be used.
 # - /etc/log.conf
 
-# this tells cloud-init to redirect its stdout and stderr to
+# This tells cloud-init to redirect its stdout and stderr to
 # 'tee -a /var/log/cloud-init-output.log' so the user can see output
 # there without needing to look on the console.
 output: {all: '| tee -a /var/log/cloud-init-output.log'}