Merge ~mgerdts/cloud-init:lp1667735 into cloud-init:master

[Mike Gerdts]

DataSourceSmartOS: fix hang when metadata service is down

If the metadata service in the host is down while a guest that uses
DataSourceSmartOS is booting, the request from the guest falls into the
bit bucket. When the metadata service is eventually started, the guest
has no awareness of this and does not resend the request. This results in
cloud-init hanging forever with a guest reboot as the only recovery
option.

This fix updates the metadata protocol to implement the initialization
phase, just as is implemented by mdata-get and related utilities. The
initialization phase includes draining all pending data from the serial
port, writing an empty command and getting an expected error message in
reply. If the initialization phase times out, it is retried every five
seconds. Each timeout results in a warning message: "Timeout while
initializing metadata client. Is the host metadata service running?" By
default, warning messages are logged to the console, thus the reason for a
hung boot is readily apparent.

LP: #1667735

[Scott Moser (smoser)]

I like it.
Good work.
I've pointed the c-i bot at it, so it will comment soon.

https://jenkins.ubuntu.com/server/job/cloud-init-ci/1005/

there are 2 tiny things inline.

[Server Team CI bot (server-team-bot)]

FAILED: Continuous integration, rev:
https://jenkins.ubuntu.com/server/job/cloud-init-ci/1005/
Executed test runs:
    SUCCESS: Checkout
    FAILED: Unit & Style Tests

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/cloud-init-ci/1005/rebuild

review: Needs Fixing (continuous-integration)

62cafc5... by Mike Gerdts on 2018-04-13

smoser and CI feedback

[Mike Gerdts (mgerdts)]

On Thu, Apr 12, 2018 at 8:34 PM, Scott Moser <email address hidden>
wrote:

> I like it.
> Good work.
> I've pointed the c-i bot at it, so it will comment soon.
>
> https://jenkins.ubuntu.com/server/job/cloud-init-ci/1005/
>
> there are 2 tiny things inline.
>

Thanks for taking a look. I address your comments below and will also
address an issue found by the CI bot.

>
>
> Diff comments:
>
> > diff --git a/cloudinit/sources/DataSourceSmartOS.py b/cloudinit/sources/
> DataSourceSmartOS.py
> > index 86bfa5d..5717dae 100644
> > --- a/cloudinit/sources/DataSourceSmartOS.py
> > +++ b/cloudinit/sources/DataSourceSmartOS.py
> > @@ -360,6 +371,45 @@ class JoyentMetadataClient(object):
> > LOG.debug('Value "%s" found.', value)
> > return value
> >
> > + def _readline(self):
> > + """
> > + Reads a line a byte at a time until \n is encountered.
> Returns an
> > + ascii string with the trailing newline removed.
> > +
> > + If a timeout (per-byte) is set and it expires, a
> > + JoyentMetadataFetchException will be thrown.
> > + """
> > + response = bytearray()
> > + while True:
> > + try:
> > + byte = self.fp.read(1)
> > + if len(byte) == 0:
> > + raise JoyentMetadataTimeoutException(
> > + "Partial response: '%s'" %
> response.decode('ascii'))
> > + if ord(byte) == ord(b'\n'):
>
> is ord needed here?
> we read a byte. can't we just compare it to b'\n' directly?
>

When reading from a serial port, that works fine. I've been unable to
figure out the magic to put bytes of the same kind on response_parts array.

With this:

diff --git a/cloudinit/sources/DataSourceSmartOS.py
b/cloudinit/sources/DataSourceSmartOS.py
index 5717dae..f368e22 100644
--- a/cloudinit/sources/DataSourceSmartOS.py
+++ b/cloudinit/sources/DataSourceSmartOS.py
@@ -383,12 +383,14 @@ class JoyentMetadataClient(object):
         while True:
             try:
                 byte = self.fp.read(1)
+ LOG.debug('read byte %r len %d newline %s', byte,
len(byte),
+ byte == b'\n')
                 if len(byte) == 0:
                     raise JoyentMetadataTimeoutException(
                         "Partial response: '%s'" %
response.decode('ascii'))
- if ord(byte) == ord(b'\n'):
+ if byte == b'\n':
                     return response.decode('ascii')
- response.extend([ord(byte)])
+ response.append(ord(byte))
             except OSError as exc:
                 if exc.errno == errno.EAGAIN:
                     raise JoyentMetadataTimeoutException(

I get:

======================================================================
ERROR: test_negotiate
(tests.unittests.test_datasource.test_smartos.TestJoyentMetadataClient)
----------------------------------------------------------------------
Traceback (most recent call last):
  File
"/home/mgerdts/cloud-init/tests/unittests/test_datasource/test_smartos.py",
line 761, in test_negotiate
    client._negotiate()
  File "/home/mgerdts/cloud-init/cloudinit/sour...

5a78cc5... by Mike Gerdts on 2018-04-16

blist from smoser

2e968f1... by Mike Gerdts on 2018-04-16

smoser fixes #2

[Scott Moser (smoser)]

tiny nit.

[Scott Moser (smoser)]

https://jenkins.ubuntu.com/server/job/cloud-init-ci/1009/console

I approve of this branch, either fix the nit in my last comment or justify it.

review: Approve

[Server Team CI bot (server-team-bot)]

PASSED: Continuous integration, rev:
https://jenkins.ubuntu.com/server/job/cloud-init-ci/1009/
Executed test runs:
    SUCCESS: Checkout
    SUCCESS: Unit & Style Tests
    SUCCESS: Ubuntu LTS: Build
    SUCCESS: Ubuntu LTS: Integration
    SUCCESS: MAAS Compatability Testing
    IN_PROGRESS: Declarative: Post Actions

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/cloud-init-ci/1009/rebuild

review: Approve (continuous-integration)

076968c... by Mike Gerdts on 2018-04-17

smoser final feedback: redundant flush

[Mike Gerdts (mgerdts)]

Yes, that was redundant. Fixed & retested (tox + real system). Fixed in
changeset:

commit 076968c6efc9759d196e604df24aa1bd1701b9be
Author: Mike Gerdts <email address hidden>
Date: Mon Apr 16 22:39:35 2018 -0500

    smoser final feedback: redundant flush

Thanks much for the review, help, and approval.

Mike

On Mon, Apr 16, 2018 at 7:50 PM, Scott Moser <email address hidden>
wrote:

> Review: Approve
>
> https://jenkins.ubuntu.com/server/job/cloud-init-ci/1009/console
>
> I approve of this branch, either fix the nit in my last comment or justify
> it.
>
>
> --
> https://code.launchpad.net/~mgerdts/cloud-init/+git/cloud-
> init/+merge/343118
> You are the owner of ~mgerdts/cloud-init:lp1667735.
>

[Scott Moser (smoser)]

review: Approve

[Server Team CI bot (server-team-bot)]

PASSED: Continuous integration, rev:
https://jenkins.ubuntu.com/server/job/cloud-init-ci/1017/
Executed test runs:
    SUCCESS: Checkout
    SUCCESS: Unit & Style Tests
    SUCCESS: Ubuntu LTS: Build
    SUCCESS: Ubuntu LTS: Integration
    SUCCESS: MAAS Compatability Testing
    IN_PROGRESS: Declarative: Post Actions

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/cloud-init-ci/1017/rebuild

review: Approve (continuous-integration)

[Scott Moser (smoser)]

An upstream commit landed for this bug.

To view that commit see the following URL:
https://git.launchpad.net/cloud-init/commit/?id=4c573d0e

diff --git a/cloudinit/sources/DataSourceSmartOS.py b/cloudinit/sources/DataSourceSmartOS.py
index 86bfa5d..a904808 100644
--- a/cloudinit/sources/DataSourceSmartOS.py
+++ b/cloudinit/sources/DataSourceSmartOS.py
@@ -1,4 +1,5 @@
 # Copyright (C) 2013 Canonical Ltd.
+# Copyright (c) 2018, Joyent, Inc.
 #
 # Author: Ben Howard <[e-mail]>
 #
@@ -21,6 +22,7 @@
 
 import base64
 import binascii
+import errno
 import json
 import os
 import random
@@ -229,6 +231,9 @@ class DataSourceSmartOS(sources.DataSource):
                       self.md_client)
             return False
 
+        # Open once for many requests, rather than once for each request
+        self.md_client.open_transport()
+
         for ci_noun, attribute in SMARTOS_ATTRIB_MAP.items():
             smartos_noun, strip = attribute
             md[ci_noun] = self.md_client.get(smartos_noun, strip=strip)
@@ -236,6 +241,8 @@ class DataSourceSmartOS(sources.DataSource):
         for ci_noun, smartos_noun in SMARTOS_ATTRIB_JSON.items():
             md[ci_noun] = self.md_client.get_json(smartos_noun)
 
+        self.md_client.close_transport()
+
         # @datadictionary: This key may contain a program that is written
         # to a file in the filesystem of the guest on each boot and then
         # executed. It may be of any format that would be considered
@@ -316,6 +323,10 @@ class JoyentMetadataFetchException(Exception):
     pass
 
 
+class JoyentMetadataTimeoutException(JoyentMetadataFetchException):
+    pass
+
+
 class JoyentMetadataClient(object):
     """
     A client implementing v2 of the Joyent Metadata Protocol Specification.
@@ -360,6 +371,47 @@ class JoyentMetadataClient(object):
         LOG.debug('Value "%s" found.', value)
         return value
 
+    def _readline(self):
+        """
+           Reads a line a byte at a time until \n is encountered.  Returns an
+           ascii string with the trailing newline removed.
+
+           If a timeout (per-byte) is set and it expires, a
+           JoyentMetadataFetchException will be thrown.
+        """
+        response = []
+
+        def as_ascii():
+            return b''.join(response).decode('ascii')
+
+        msg = "Partial response: '%s'"
+        while True:
+            try:
+                byte = self.fp.read(1)
+                if len(byte) == 0:
+                    raise JoyentMetadataTimeoutException(msg % as_ascii())
+                if byte == b'\n':
+                    return as_ascii()
+                response.append(byte)
+            except OSError as exc:
+                if exc.errno == errno.EAGAIN:
+                    raise JoyentMetadataTimeoutException(msg % as_ascii())
+                raise
+
+    def _write(self, msg):
+        self.fp.write(msg.encode('ascii'))
+        self.fp.flush()
+
+    def _negotiate(self):
+        LOG.debug('Negotiating protocol V2')
+        self._write('NEGOTIATE V2\n')
+        response = self._readline()
+        LOG.debug('read "%s"', response)
+        if response != 'V2_OK':
+            raise JoyentMetadataFetchException(
+                'Invalid response "%s" to "NEGOTIATE V2"' % response)
+        LOG.debug('Negotiation complete')
+
     def request(self, rtype, param=None):
         request_id = '{0:08x}'.format(random.randint(0, 0xffffffff))
         message_body = ' '.join((request_id, rtype,))
@@ -374,18 +426,11 @@ class JoyentMetadataClient(object):
             self.open_transport()
             need_close = True
 
-        self.fp.write(msg.encode('ascii'))
-        self.fp.flush()
-
-        response = bytearray()
-        response.extend(self.fp.read(1))
-        while response[-1:] != b'\n':
-            response.extend(self.fp.read(1))
-
+        self._write(msg)
+        response = self._readline()
         if need_close:
             self.close_transport()
 
-        response = response.rstrip().decode('ascii')
         LOG.debug('Read "%s" from metadata transport.', response)
 
         if 'SUCCESS' not in response:
@@ -450,6 +495,7 @@ class JoyentMetadataSocketClient(JoyentMetadataClient):
         sock = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM)
         sock.connect(self.socketpath)
         self.fp = sock.makefile('rwb')
+        self._negotiate()
 
     def exists(self):
         return os.path.exists(self.socketpath)
@@ -459,8 +505,9 @@ class JoyentMetadataSocketClient(JoyentMetadataClient):
 
 
 class JoyentMetadataSerialClient(JoyentMetadataClient):
-    def __init__(self, device, timeout=10, smartos_type=SMARTOS_ENV_KVM):
-        super(JoyentMetadataSerialClient, self).__init__(smartos_type)
+    def __init__(self, device, timeout=10, smartos_type=SMARTOS_ENV_KVM,
+                 fp=None):
+        super(JoyentMetadataSerialClient, self).__init__(smartos_type, fp)
         self.device = device
         self.timeout = timeout
 
@@ -468,10 +515,50 @@ class JoyentMetadataSerialClient(JoyentMetadataClient):
         return os.path.exists(self.device)
 
     def open_transport(self):
-        ser = serial.Serial(self.device, timeout=self.timeout)
-        if not ser.isOpen():
-            raise SystemError("Unable to open %s" % self.device)
-        self.fp = ser
+        if self.fp is None:
+            ser = serial.Serial(self.device, timeout=self.timeout)
+            if not ser.isOpen():
+                raise SystemError("Unable to open %s" % self.device)
+            self.fp = ser
+        self._flush()
+        self._negotiate()
+
+    def _flush(self):
+        LOG.debug('Flushing input')
+        # Read any pending data
+        timeout = self.fp.timeout
+        self.fp.timeout = 0.1
+        while True:
+            try:
+                self._readline()
+            except JoyentMetadataTimeoutException:
+                break
+        LOG.debug('Input empty')
+
+        # Send a newline and expect "invalid command".  Keep trying until
+        # successful.  Retry rather frequently so that the "Is the host
+        # metadata service running" appears on the console soon after someone
+        # attaches in an effort to debug.
+        if timeout > 5:
+            self.fp.timeout = 5
+        else:
+            self.fp.timeout = timeout
+        while True:
+            LOG.debug('Writing newline, expecting "invalid command"')
+            self._write('\n')
+            try:
+                response = self._readline()
+                if response == 'invalid command':
+                    break
+                if response == 'FAILURE':
+                    LOG.debug('Got "FAILURE".  Retrying.')
+                    continue
+                LOG.warning('Unexpected response "%s" during flush', response)
+            except JoyentMetadataTimeoutException:
+                LOG.warning('Timeout while initializing metadata client. ' +
+                            'Is the host metadata service running?')
+        LOG.debug('Got "invalid command".  Flush complete.')
+        self.fp.timeout = timeout
 
     def __repr__(self):
         return "%s(device=%s, timeout=%s)" % (
diff --git a/tests/unittests/test_datasource/test_smartos.py b/tests/unittests/test_datasource/test_smartos.py
index 88bae5f..2bea7a1 100644
--- a/tests/unittests/test_datasource/test_smartos.py
+++ b/tests/unittests/test_datasource/test_smartos.py
@@ -1,4 +1,5 @@
 # Copyright (C) 2013 Canonical Ltd.
+# Copyright (c) 2018, Joyent, Inc.
 #
 # Author: Ben Howard <[e-mail]>
 #
@@ -324,6 +325,7 @@ class PsuedoJoyentClient(object):
         if data is None:
             data = MOCK_RETURNS.copy()
         self.data = data
+        self._is_open = False
         return
 
     def get(self, key, default=None, strip=False):
@@ -344,6 +346,14 @@ class PsuedoJoyentClient(object):
     def exists(self):
         return True
 
+    def open_transport(self):
+        assert(not self._is_open)
+        self._is_open = True
+
+    def close_transport(self):
+        assert(self._is_open)
+        self._is_open = False
+
 
 class TestSmartOSDataSource(FilesystemMockingTestCase):
     def setUp(self):
@@ -592,8 +602,46 @@ class TestSmartOSDataSource(FilesystemMockingTestCase):
                          mydscfg['disk_aliases']['FOO'])
 
 
+class ShortReader(object):
+    """Implements a 'read' interface for bytes provided.
+    much like io.BytesIO but the 'endbyte' acts as if EOF.
+    When it is reached a short will be returned."""
+    def __init__(self, initial_bytes, endbyte=b'\0'):
+        self.data = initial_bytes
+        self.index = 0
+        self.len = len(self.data)
+        self.endbyte = endbyte
+
+    @property
+    def emptied(self):
+        return self.index >= self.len
+
+    def read(self, size=-1):
+        """Read size bytes but not past a null."""
+        if size == 0 or self.index >= self.len:
+            return b''
+
+        rsize = size
+        if size < 0 or size + self.index > self.len:
+            rsize = self.len - self.index
+
+        next_null = self.data.find(self.endbyte, self.index, rsize)
+        if next_null >= 0:
+            rsize = next_null - self.index + 1
+        i = self.index
+        self.index += rsize
+        ret = self.data[i:i + rsize]
+        if len(ret) and ret[-1:] == self.endbyte:
+            ret = ret[:-1]
+        return ret
+
+
 class TestJoyentMetadataClient(FilesystemMockingTestCase):
 
+    invalid = b'invalid command\n'
+    failure = b'FAILURE\n'
+    v2_ok = b'V2_OK\n'
+
     def setUp(self):
         super(TestJoyentMetadataClient, self).setUp()
 
@@ -636,6 +684,11 @@ class TestJoyentMetadataClient(FilesystemMockingTestCase):
         return DataSourceSmartOS.JoyentMetadataClient(
             fp=self.serial, smartos_type=DataSourceSmartOS.SMARTOS_ENV_KVM)
 
+    def _get_serial_client(self):
+        self.serial.timeout = 1
+        return DataSourceSmartOS.JoyentMetadataSerialClient(None,
+                                                            fp=self.serial)
+
     def assertEndsWith(self, haystack, prefix):
         self.assertTrue(haystack.endswith(prefix),
                         "{0} does not end with '{1}'".format(
@@ -646,12 +699,14 @@ class TestJoyentMetadataClient(FilesystemMockingTestCase):
                         "{0} does not start with '{1}'".format(
                             repr(haystack), prefix))
 
+    def assertNoMoreSideEffects(self, obj):
+        self.assertRaises(StopIteration, obj)
+
     def test_get_metadata_writes_a_single_line(self):
         client = self._get_client()
         client.get('some_key')
         self.assertEqual(1, self.serial.write.call_count)
         written_line = self.serial.write.call_args[0][0]
-        print(type(written_line))
         self.assertEndsWith(written_line.decode('ascii'),
                             b'\n'.decode('ascii'))
         self.assertEqual(1, written_line.count(b'\n'))
@@ -737,6 +792,52 @@ class TestJoyentMetadataClient(FilesystemMockingTestCase):
         client._checksum = lambda _: self.response_parts['crc']
         self.assertIsNone(client.get('some_key'))
 
+    def test_negotiate(self):
+        client = self._get_client()
+        reader = ShortReader(self.v2_ok)
+        client.fp.read.side_effect = reader.read
+        client._negotiate()
+        self.assertTrue(reader.emptied)
+
+    def test_negotiate_short_response(self):
+        client = self._get_client()
+        # chopped '\n' from v2_ok.
+        reader = ShortReader(self.v2_ok[:-1] + b'\0')
+        client.fp.read.side_effect = reader.read
+        self.assertRaises(DataSourceSmartOS.JoyentMetadataTimeoutException,
+                          client._negotiate)
+        self.assertTrue(reader.emptied)
+
+    def test_negotiate_bad_response(self):
+        client = self._get_client()
+        reader = ShortReader(b'garbage\n' + self.v2_ok)
+        client.fp.read.side_effect = reader.read
+        self.assertRaises(DataSourceSmartOS.JoyentMetadataFetchException,
+                          client._negotiate)
+        self.assertEqual(self.v2_ok, client.fp.read())
+
+    def test_serial_open_transport(self):
+        client = self._get_serial_client()
+        reader = ShortReader(b'garbage\0' + self.invalid + self.v2_ok)
+        client.fp.read.side_effect = reader.read
+        client.open_transport()
+        self.assertTrue(reader.emptied)
+
+    def test_flush_failure(self):
+        client = self._get_serial_client()
+        reader = ShortReader(b'garbage' + b'\0' + self.failure +
+                             self.invalid + self.v2_ok)
+        client.fp.read.side_effect = reader.read
+        client.open_transport()
+        self.assertTrue(reader.emptied)
+
+    def test_flush_many_timeouts(self):
+        client = self._get_serial_client()
+        reader = ShortReader(b'\0' * 100 + self.invalid + self.v2_ok)
+        client.fp.read.side_effect = reader.read
+        client.open_transport()
+        self.assertTrue(reader.emptied)
+
 
 class TestNetworkConversion(TestCase):
     def test_convert_simple(self):