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).

4 files changed, 173 insertions, 97 deletions

diff --git a/cloudinit/cmd/main.py b/cloudinit/cmd/main.py
index c83496c5..65b15edc 100644
--- a/cloudinit/cmd/main.py
+++ b/cloudinit/cmd/main.py
@@ -26,6 +26,7 @@ from cloudinit import signal_handler
 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()
diff --git a/cloudinit/util.py b/cloudinit/util.py
index 5725129e..7196a7ca 100644
--- a/cloudinit/util.py
+++ b/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",
diff --git a/tests/unittests/helpers.py b/tests/unittests/helpers.py
index cf3b46d2..64e56d98 100644
--- a/tests/unittests/helpers.py
+++ b/tests/unittests/helpers.py
@@ -264,16 +264,22 @@ class HttprettyTestCase(TestCase):
 
 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):
diff --git a/tests/unittests/test__init__.py b/tests/unittests/test__init__.py
index 7b6f8c4e..e6f4c318 100644
--- a/tests/unittests/test__init__.py
+++ b/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 @@ class TestHandlerHandlePart(TestCase):
             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