Get early logging logged, including failures of cmdline url.

Failures to load the kernel command line's url (cloud-config-url=)
would previously get swallowed.  This should make it much more
obvious when that happens.  With logging going to expected places
at sane levels (WARN will go to stderr by default).

cloudinit/cmd/main.py

@@ -26,6 +26,7 @@
 from cloudinit import sources
 from cloudinit import stages
 from cloudinit import templater
+from cloudinit import url_helper
 from cloudinit import util
 from cloudinit import version
 
@@ -129,23 +130,104 @@ def apply_reporting_cfg(cfg):
         reporting.update_configuration(cfg.get('reporting'))
 
 
+def parse_cmdline_url(cmdline, names=('cloud-config-url', 'url')):
+    data = util.keyval_str_to_dict(cmdline)
+    for key in names:
+        if key in data:
+            return key, data[key]
+    raise KeyError("No keys (%s) found in string '%s'" %
+                   (cmdline, names))
+
+
+def attempt_cmdline_url(path, network=True, cmdline=None):
+    """Write data from url referenced in command line to path.
+
+    path: a file to write content to if downloaded.
+    network: should network access be assumed.
+    cmdline: the cmdline to parse for cloud-config-url.
+
+    This is used in MAAS datasource, in "ephemeral" (read-only root)
+    environment where the instance netboots to iscsi ro root.
+    and the entity that controls the pxe config has to configure
+    the maas datasource.
+
+    An attempt is made on network urls even in local datasource
+    for case of network set up in initramfs.
+
+    Return value is a tuple of a logger function (logging.DEBUG)
+    and a message indicating what happened.
+    """
+
+    if cmdline is None:
+        cmdline = util.get_cmdline()
+
+    try:
+        cmdline_name, url = parse_cmdline_url(cmdline)
+    except KeyError:
+        return (logging.DEBUG, "No kernel command line url found.")
+
+    path_is_local = url.startswith("file://") or url.startswith("/")
+
+    if path_is_local and os.path.exists(path):
+        if network:
+            m = ("file '%s' existed, possibly from local stage download"
+                 " of command line url '%s'. Not re-writing." % (path, url))
+            level = logging.INFO
+            if path_is_local:
+                level = logging.DEBUG
+        else:
+            m = ("file '%s' existed, possibly from previous boot download"
+                 " of command line url '%s'. Not re-writing." % (path, url))
+            level = logging.WARN
+
+        return (level, m)
+
+    kwargs = {'url': url, 'timeout': 10, 'retries': 2}
+    if network or path_is_local:
+        level = logging.WARN
+        kwargs['sec_between'] = 1
+    else:
+        level = logging.DEBUG
+        kwargs['sec_between'] = .1
+
+    data = None
+    header = b'#cloud-config'
+    try:
+        resp = util.read_file_or_url(**kwargs)
+        if resp.ok():
+            data = resp.contents
+            if not resp.contents.startswith(header):
+                if cmdline_name == 'cloud-config-url':
+                    level = logging.WARN
+                else:
+                    level = logging.INFO
+                return (
+                    level,
+                    "contents of '%s' did not start with %s" % (url, header))
+        else:
+            return (level,
+                    "url '%s' returned code %s. Ignoring." % (url, resp.code))
+
+    except url_helper.UrlError as e:
+        return (level, "retrieving url '%s' failed: %s" % (url, e))
+
+    util.write_file(path, data, mode=0o600)
+    return (logging.INFO,
+            "wrote cloud-config data from %s='%s' to %s" %
+            (cmdline_name, url, path))
+
+
 def main_init(name, args):
     deps = [sources.DEP_FILESYSTEM, sources.DEP_NETWORK]
     if args.local:
         deps = [sources.DEP_FILESYSTEM]
 
-    if not args.local:
-        # See doc/kernel-cmdline.txt
-        #
-        # This is used in maas datasource, in "ephemeral" (read-only root)
-        # environment where the instance netboots to iscsi ro root.
-        # and the entity that controls the pxe config has to configure
-        # the maas datasource.
-        #
-        # Could be used elsewhere, only works on network based (not local).
-        root_name = "%s.d" % (CLOUD_CONFIG)
-        target_fn = os.path.join(root_name, "91_kernel_cmdline_url.cfg")
-        util.read_write_cmdline_url(target_fn)
+    early_logs = []
+    early_logs.append(
+        attempt_cmdline_url(
+            path=os.path.join("%s.d" % CLOUD_CONFIG,
+                              "91_kernel_cmdline_url.cfg"),
+            network=not args.local))
 
     # Cloud-init 'init' stage is broken up into the following sub-stages
     # 1. Ensure that the init object fetches its config without errors
@@ -171,12 +253,14 @@ def main_init(name, args):
     outfmt = None
     errfmt = None
     try:
-        LOG.debug("Closing stdin")
+        early_logs.append((logging.DEBUG, "Closing stdin."))
         util.close_stdin()
         (outfmt, errfmt) = util.fixup_output(init.cfg, name)
     except Exception:
-        util.logexc(LOG, "Failed to setup output redirection!")
-        print_exc("Failed to setup output redirection!")
+        msg = "Failed to setup output redirection!"
+        util.logexc(LOG, msg)
+        print_exc(msg)
+        early_logs.append((logging.WARN, msg))
     if args.debug:
         # Reset so that all the debug handlers are closed out
         LOG.debug(("Logging being reset, this logger may no"
@@ -190,6 +274,10 @@ def main_init(name, args):
     # been redirected and log now configured.
     welcome(name, msg=w_msg)
 
+    # re-play early log messages before logging was setup
+    for lvl, msg in early_logs:
+        LOG.log(lvl, msg)
+
     # Stage 3
     try:
         init.initialize()

cloudinit/util.py

@@ -1089,31 +1089,6 @@ def get_fqdn_from_hosts(hostname, filename="/etc/hosts"):
     return fqdn
 
 
-def get_cmdline_url(names=('cloud-config-url', 'url'),
-                    starts=b"#cloud-config", cmdline=None):
-    if cmdline is None:
-        cmdline = get_cmdline()
-
-    data = keyval_str_to_dict(cmdline)
-    url = None
-    key = None
-    for key in names:
-        if key in data:
-            url = data[key]
-            break
-
-    if not url:
-        return (None, None, None)
-
-    resp = read_file_or_url(url)
-    # allow callers to pass starts as text when comparing to bytes contents
-    starts = encode_text(starts)
-    if resp.ok() and resp.contents.startswith(starts):
-        return (key, url, resp.contents)
-
-    return (key, url, None)
-
-
 def is_resolvable(name):
     """determine if a url is resolvable, return a boolean
     This also attempts to be resilent against dns redirection.
@@ -1475,25 +1450,6 @@ def ensure_dirs(dirlist, mode=0o755):
         ensure_dir(d, mode)
 
 
-def read_write_cmdline_url(target_fn):
-    if not os.path.exists(target_fn):
-        try:
-            (key, url, content) = get_cmdline_url()
-        except Exception:
-            logexc(LOG, "Failed fetching command line url")
-            return
-        try:
-            if key and content:
-                write_file(target_fn, content, mode=0o600)
-                LOG.debug(("Wrote to %s with contents of command line"
-                          " url %s (len=%s)"), target_fn, url, len(content))
-            elif key and not content:
-                LOG.debug(("Command line key %s with url"
-                          " %s had no contents"), key, url)
-        except Exception:
-            logexc(LOG, "Failed writing url content to %s", target_fn)
-
-
 def yaml_dumps(obj, explicit_start=True, explicit_end=True):
     return yaml.safe_dump(obj,
                           line_break="\n",

tests/unittests/helpers.py

@@ -264,16 +264,22 @@ def tearDown(self):
 
 class TempDirTestCase(TestCase):
     # provide a tempdir per class, not per test.
-    def setUp(self):
-        super(TempDirTestCase, self).setUp()
-        self.tmp = tempfile.mkdtemp()
-        self.addCleanup(shutil.rmtree, self.tmp)
+    @classmethod
+    def setUpClass(cls):
+        cls.tmpd = tempfile.mkdtemp(prefix="ci-%s." % cls.__name__)
+        return TestCase.setUpClass()
+
+    @classmethod
+    def tearDownClass(cls):
+        shutil.rmtree(cls.tmpd)
+        return TestCase.tearDownClass()
 
     def tmp_path(self, path):
+        # if absolute path (starts with /), then make ./path
         if path.startswith(os.path.sep):
             path = "." + path
 
-        return os.path.normpath(os.path.join(self.tmp, path))
+        return os.path.normpath(os.path.join(self.tmpd, path))
 
 
 def populate_dir(path, files):

tests/unittests/test__init__.py

@@ -1,16 +1,18 @@
 # This file is part of cloud-init. See LICENSE file for license information.
 
+import logging
 import os
 import shutil
 import tempfile
 
+from cloudinit.cmd import main
 from cloudinit import handlers
 from cloudinit import helpers
 from cloudinit import settings
 from cloudinit import url_helper
 from cloudinit import util
 
-from .helpers import TestCase, ExitStack, mock
+from .helpers import TestCase, TempDirTestCase, ExitStack, mock
 
 
 class FakeModule(handlers.Handler):
@@ -170,44 +172,68 @@ def test_exception_is_caught(self):
             self.data, self.ctype, self.filename, self.payload)
 
 
-class TestCmdlineUrl(TestCase):
-    def test_invalid_content(self):
-        url = "http://example.com/foo"
-        key = "mykey"
-        payload = b"0"
-        cmdline = "ro %s=%s bar=1" % (key, url)
+class TestCmdlineUrl(TempDirTestCase):
+    def test_parse_cmdline_url_nokey_raises_keyerror(self):
+        self.assertRaises(
+            KeyError, main.parse_cmdline_url, 'root=foo bar single')
 
-        with mock.patch('cloudinit.url_helper.readurl',
-                        return_value=url_helper.StringResponse(payload)):
-            self.assertEqual(
-                util.get_cmdline_url(names=[key], starts="xxxxxx",
-                                     cmdline=cmdline),
-                (key, url, None))
+    def test_parse_cmdline_url_found(self):
+        cmdline = 'root=foo bar single url=http://example.com arg1 -v'
+        self.assertEqual(
+            ('url', 'http://example.com'), main.parse_cmdline_url(cmdline))
 
-    def test_valid_content(self):
-        url = "http://example.com/foo"
-        key = "mykey"
-        payload = b"xcloud-config\nmydata: foo\nbar: wark\n"
+    @mock.patch('cloudinit.cmd.main.util.read_file_or_url')
+    def test_invalid_content(self, m_read):
+        key = "cloud-config-url"
+        url = 'http://example.com/foo'
         cmdline = "ro %s=%s bar=1" % (key, url)
+        m_read.return_value = url_helper.StringResponse(b"unexpected blob")
 
-        with mock.patch('cloudinit.url_helper.readurl',
-                        return_value=url_helper.StringResponse(payload)):
-            self.assertEqual(
-                util.get_cmdline_url(names=[key], starts=b"xcloud-config",
-                                     cmdline=cmdline),
-                (key, url, payload))
+        fpath = self.tmp_path("test_valid")
+        lvl, msg = main.attempt_cmdline_url(
+            fpath, network=True, cmdline=cmdline)
+        self.assertEqual(logging.WARN, lvl)
+        self.assertIn(url, msg)
+        self.assertFalse(os.path.exists(fpath))
 
-    def test_no_key_found(self):
+    @mock.patch('cloudinit.cmd.main.util.read_file_or_url')
+    def test_valid_content(self, m_read):
         url = "http://example.com/foo"
-        key = "mykey"
-        cmdline = "ro %s=%s bar=1" % (key, url)
-
-        with mock.patch('cloudinit.url_helper.readurl',
-                        return_value=url_helper.StringResponse(b'')):
-            self.assertEqual(
-                util.get_cmdline_url(names=["does-not-appear"],
-                                     starts="#cloud-config", cmdline=cmdline),
-                (None, None, None))
+        payload = b"#cloud-config\nmydata: foo\nbar: wark\n"
+        cmdline = "ro %s=%s bar=1" % ('cloud-config-url', url)
+
+        m_read.return_value = url_helper.StringResponse(payload)
+        fpath = self.tmp_path("test_valid")
+        lvl, msg = main.attempt_cmdline_url(
+            fpath, network=True, cmdline=cmdline)
+        self.assertEqual(util.load_file(fpath, decode=False), payload)
+        self.assertEqual(logging.INFO, lvl)
+        self.assertIn(url, msg)
+
+    @mock.patch('cloudinit.cmd.main.util.read_file_or_url')
+    def test_no_key_found(self, m_read):
+        cmdline = "ro mykey=http://example.com/foo root=foo"
+        fpath = self.tmp_path("test_no_key_found")
+        lvl, msg = main.attempt_cmdline_url(
+            fpath, network=True, cmdline=cmdline)
+
+        m_read.assert_not_called()
+        self.assertFalse(os.path.exists(fpath))
+        self.assertEqual(logging.DEBUG, lvl)
+
+    @mock.patch('cloudinit.cmd.main.util.read_file_or_url')
+    def test_exception_warns(self, m_read):
+        url = "http://example.com/foo"
+        cmdline = "ro cloud-config-url=%s root=LABEL=bar" % url
+        fpath = self.tmp_path("test_no_key_found")
+        m_read.side_effect = url_helper.UrlError(
+            cause="Unexpected Error", url="http://example.com/foo")
+
+        lvl, msg = main.attempt_cmdline_url(
+            fpath, network=True, cmdline=cmdline)
+        self.assertEqual(logging.WARN, lvl)
+        self.assertIn(url, msg)
+        self.assertFalse(os.path.exists(fpath))
 
 
 # vi: ts=4 expandtab