Document behavior of message.create

Add docstrings to clarify the behavior of message.create() when both
an exception and detail are passed as arguments.  Updates the
user_messages section of the contributor docs to reflect the changes
introduced in Pike by implementation of the "Explicit user messages"
spec.  Adds tests to prevent regressions.

Closes-bug: #1822000
Change-Id: Ia0425dc9c241d0c101057fbc534e68e7e5fdc317

cinder/message/api.py

@@ -38,12 +38,55 @@ LOG = logging.getLogger(__name__)
 
 
 class API(base.Base):
-    """API for handling user messages."""
+    """API for handling user messages.
+
+    Cinder Messages describe the outcome of a user action using predefined
+    fields that are members of objects defined in the
+    cinder.message.message_field package.  They are intended to be exposed to
+    end users.  Their primary purpose is to provide end users with a means of
+    discovering what went wrong when an asynchronous action in the Volume REST
+    API (for which they've already received a 2xx response) fails.
+
+    Messages contain an 'expires_at' field based on the creation time plus the
+    value of the 'message_ttl' configuration option.  They are periodically
+    reaped by a task of the SchedulerManager class whose periodicity is given
+    by the 'message_reap_interval' configuration option.
+
+    """
 
     def create(self, context, action,
                resource_type=message_field.Resource.VOLUME,
                resource_uuid=None, exception=None, detail=None, level="ERROR"):
-        """Create a message with the specified information."""
+        """Create a message record with the specified information.
+
+        :param context: current context object
+        :param action:
+            a message_field.Action field describing what was taking place
+            when this message was created
+        :param resource_type:
+            a message_field.Resource field describing the resource this
+            message applies to.  Default is message_field.Resource.VOLUME
+        :param resource_uuid:
+            the resource ID if this message applies to an existing resource.
+            Default is None
+        :param exception:
+            if an exception has occurred, you can pass it in and it will be
+            translated into an appropriate message detail ID (possibly
+            message_field.Detail.UNKNOWN_ERROR).  The message
+            in the exception itself is ignored in order not to expose
+            sensitive information to end users.  Default is None
+        :param detail:
+            a message_field.Detail field describing the event the message
+            is about.  Default is None, in which case
+            message_field.Detail.UNKNOWN_ERROR will be used for the message
+            unless an exception in the message_field.EXCEPTION_DETAIL_MAPPINGS
+            is passed; in that case the message_field.Detail field that's
+            mapped to the exception is used.
+        :param level:
+            a string describing the severity of the message.  Suggested
+            values are 'INFO', 'ERROR', 'WARNING'.  Default is 'ERROR'.
+        """
+
         LOG.info("Creating message record for request_id = %s",
                  context.request_id)
         # Updates expiry time for message as per message_ttl config.

cinder/message/message_field.py

@@ -124,6 +124,18 @@ def translate_detail(detail_id):
 
 
 def translate_detail_id(exception, detail):
+    """Get a detail_id to use for a message.
+
+    If exception is in the EXCEPTION_DETAIL_MAPPINGS, returns the detail_id
+    of the mapped Detail field.  If exception is not in the mapping or is None,
+    returns the detail_id of the passed-in Detail field.  Otherwise, returns
+    the detail_id of Detail.UNKNOWN_ERROR.
+
+    :param exception: an Exception (or None)
+    :param detail: a message_field.Detail field (or None)
+    :returns: string
+    :returns: the detail_id of a message_field.Detail field
+    """
     if exception is not None and isinstance(exception, Exception):
         for key, value in Detail.EXCEPTION_DETAIL_MAPPINGS.items():
             if exception.__class__.__name__ in value:

cinder/tests/unit/message/test_api.py

@@ -20,6 +20,7 @@ from cinder.api import microversions as mv
 from cinder.api.openstack import api_version_request as api_version
 from cinder.api.v3 import messages
 from cinder import context
+from cinder import exception
 from cinder.message import api as message_api
 from cinder.message import message_field
 from cinder import test
@@ -54,8 +55,7 @@ class MessageApiTest(test.TestCase):
             'request_id': 'fakerequestid',
             'resource_type': 'fake_resource_type',
             'resource_uuid': None,
-            'action_id':
+            'action_id': message_field.Action.SCHEDULE_ALLOCATE_VOLUME[0],
-                message_field.Action.SCHEDULE_ALLOCATE_VOLUME[0],
             'detail_id': message_field.Detail.UNKNOWN_ERROR[0],
             'message_level': 'ERROR',
             'expires_at': expected_expires_at,
@@ -70,6 +70,205 @@ class MessageApiTest(test.TestCase):
             self.ctxt, expected_message_record)
         mock_utcnow.assert_called_with()
 
+    @mock.patch('oslo_utils.timeutils.utcnow')
+    def test_create_with_minimum_args(self, mock_utcnow):
+        CONF.set_override('message_ttl', 300)
+        mock_utcnow.return_value = datetime.datetime.utcnow()
+        expected_expires_at = timeutils.utcnow() + datetime.timedelta(
+            seconds=300)
+        expected_message_record = {
+            'project_id': 'fakeproject',
+            'request_id': 'fakerequestid',
+            'resource_type': message_field.Resource.VOLUME,
+            'resource_uuid': None,
+            'action_id': message_field.Action.SCHEDULE_ALLOCATE_VOLUME[0],
+            'detail_id': message_field.Detail.UNKNOWN_ERROR[0],
+            'message_level': 'ERROR',
+            'expires_at': expected_expires_at,
+            'event_id': "VOLUME_VOLUME_001_001",
+        }
+        self.message_api.create(
+            self.ctxt,
+            action=message_field.Action.SCHEDULE_ALLOCATE_VOLUME)
+
+        self.message_api.db.message_create.assert_called_once_with(
+            self.ctxt, expected_message_record)
+        mock_utcnow.assert_called_with()
+
+    @mock.patch('oslo_utils.timeutils.utcnow')
+    def test_create_with_no_detail(self, mock_utcnow):
+        # Should get Detail.UNKNOWN_ERROR
+        CONF.set_override('message_ttl', 300)
+        mock_utcnow.return_value = datetime.datetime.utcnow()
+        expected_expires_at = timeutils.utcnow() + datetime.timedelta(
+            seconds=300)
+        expected_message_record = {
+            'project_id': 'fakeproject',
+            'request_id': 'fakerequestid',
+            'resource_type': 'fake_resource_type',
+            'resource_uuid': None,
+            'action_id': message_field.Action.SCHEDULE_ALLOCATE_VOLUME[0],
+            'detail_id': message_field.Detail.UNKNOWN_ERROR[0],
+            'message_level': 'ERROR',
+            'expires_at': expected_expires_at,
+            'event_id': "VOLUME_fake_resource_type_001_001",
+        }
+        self.message_api.create(
+            self.ctxt,
+            action=message_field.Action.SCHEDULE_ALLOCATE_VOLUME,
+            resource_type="fake_resource_type")
+
+        self.message_api.db.message_create.assert_called_once_with(
+            self.ctxt, expected_message_record)
+        mock_utcnow.assert_called_with()
+
+    @mock.patch('oslo_utils.timeutils.utcnow')
+    def test_create_with_detail_only(self, mock_utcnow):
+        CONF.set_override('message_ttl', 300)
+        mock_utcnow.return_value = datetime.datetime.utcnow()
+        expected_expires_at = timeutils.utcnow() + datetime.timedelta(
+            seconds=300)
+        expected_message_record = {
+            'project_id': 'fakeproject',
+            'request_id': 'fakerequestid',
+            'resource_type': 'fake_resource_type',
+            'resource_uuid': None,
+            'action_id': message_field.Action.SCHEDULE_ALLOCATE_VOLUME[0],
+            # this doesn't make sense for this Action, but that's the point
+            'detail_id': message_field.Detail.FAILED_TO_UPLOAD_VOLUME[0],
+            'message_level': 'ERROR',
+            'expires_at': expected_expires_at,
+            'event_id': "VOLUME_fake_resource_type_001_004",
+        }
+        self.message_api.create(
+            self.ctxt,
+            action=message_field.Action.SCHEDULE_ALLOCATE_VOLUME,
+            detail=message_field.Detail.FAILED_TO_UPLOAD_VOLUME,
+            resource_type="fake_resource_type")
+
+        self.message_api.db.message_create.assert_called_once_with(
+            self.ctxt, expected_message_record)
+        mock_utcnow.assert_called_with()
+
+    @mock.patch('oslo_utils.timeutils.utcnow')
+    def test_create_passed_exception_no_detail(self, mock_utcnow):
+        # Detail should be automatically supplied based on the
+        # message_field.Detail.EXCEPTION_DETAIL_MAPPINGS
+        CONF.set_override('message_ttl', 300)
+        mock_utcnow.return_value = datetime.datetime.utcnow()
+        expected_expires_at = timeutils.utcnow() + datetime.timedelta(
+            seconds=300)
+        expected_message_record = {
+            'project_id': 'fakeproject',
+            'request_id': 'fakerequestid',
+            'resource_type': 'fake_resource_type',
+            'resource_uuid': None,
+            'action_id': message_field.Action.SCHEDULE_ALLOCATE_VOLUME[0],
+            # this is determined by the exception we'll be passing
+            'detail_id': message_field.Detail.NOT_ENOUGH_SPACE_FOR_IMAGE[0],
+            'message_level': 'ERROR',
+            'expires_at': expected_expires_at,
+            'event_id': "VOLUME_fake_resource_type_001_007",
+        }
+        exc = exception.ImageTooBig(image_id='fake_image', reason='MYOB')
+        self.message_api.create(
+            self.ctxt,
+            action=message_field.Action.SCHEDULE_ALLOCATE_VOLUME,
+            exception=exc,
+            resource_type="fake_resource_type")
+
+        self.message_api.db.message_create.assert_called_once_with(
+            self.ctxt, expected_message_record)
+        mock_utcnow.assert_called_with()
+
+    @mock.patch('oslo_utils.timeutils.utcnow')
+    def test_create_passed_unmapped_exception_no_detail(self, mock_utcnow):
+        CONF.set_override('message_ttl', 300)
+        mock_utcnow.return_value = datetime.datetime.utcnow()
+        expected_expires_at = timeutils.utcnow() + datetime.timedelta(
+            seconds=300)
+        expected_message_record = {
+            'project_id': 'fakeproject',
+            'request_id': 'fakerequestid',
+            'resource_type': 'fake_resource_type',
+            'resource_uuid': None,
+            'action_id': message_field.Action.COPY_IMAGE_TO_VOLUME[0],
+            'detail_id': message_field.Detail.UNKNOWN_ERROR[0],
+            'message_level': 'ERROR',
+            'expires_at': expected_expires_at,
+            'event_id': "VOLUME_fake_resource_type_005_001",
+        }
+        exc = exception.ImageUnacceptable(image_id='fake_image', reason='MYOB')
+        self.message_api.create(
+            self.ctxt,
+            action=message_field.Action.COPY_IMAGE_TO_VOLUME,
+            exception=exc,
+            resource_type="fake_resource_type")
+
+        self.message_api.db.message_create.assert_called_once_with(
+            self.ctxt, expected_message_record)
+        mock_utcnow.assert_called_with()
+
+    @mock.patch('oslo_utils.timeutils.utcnow')
+    def test_create_passed_mapped_exception_and_detail(self, mock_utcnow):
+        # passed Detail should be ignored because this is a mapped exception
+        CONF.set_override('message_ttl', 300)
+        mock_utcnow.return_value = datetime.datetime.utcnow()
+        expected_expires_at = timeutils.utcnow() + datetime.timedelta(
+            seconds=300)
+        expected_message_record = {
+            'project_id': 'fakeproject',
+            'request_id': 'fakerequestid',
+            'resource_type': 'fake_resource_type',
+            'resource_uuid': None,
+            'action_id': message_field.Action.UPDATE_ATTACHMENT[0],
+            'detail_id': message_field.Detail.NOT_ENOUGH_SPACE_FOR_IMAGE[0],
+            'message_level': 'ERROR',
+            'expires_at': expected_expires_at,
+            'event_id': "VOLUME_fake_resource_type_004_007",
+        }
+        exc = exception.ImageTooBig(image_id='fake_image', reason='MYOB')
+        self.message_api.create(
+            self.ctxt,
+            action=message_field.Action.UPDATE_ATTACHMENT,
+            detail=message_field.Detail.VOLUME_ATTACH_MODE_INVALID,
+            exception=exc,
+            resource_type="fake_resource_type")
+
+        self.message_api.db.message_create.assert_called_once_with(
+            self.ctxt, expected_message_record)
+        mock_utcnow.assert_called_with()
+
+    @mock.patch('oslo_utils.timeutils.utcnow')
+    def test_create_passed_unmapped_exception_and_detail(self, mock_utcnow):
+        # passed Detail should be honored
+        CONF.set_override('message_ttl', 300)
+        mock_utcnow.return_value = datetime.datetime.utcnow()
+        expected_expires_at = timeutils.utcnow() + datetime.timedelta(
+            seconds=300)
+        expected_message_record = {
+            'project_id': 'fakeproject',
+            'request_id': 'fakerequestid',
+            'resource_type': 'fake_resource_type',
+            'resource_uuid': None,
+            'action_id': message_field.Action.UPDATE_ATTACHMENT[0],
+            'detail_id': message_field.Detail.VOLUME_ATTACH_MODE_INVALID[0],
+            'message_level': 'ERROR',
+            'expires_at': expected_expires_at,
+            'event_id': "VOLUME_fake_resource_type_004_005",
+        }
+        exc = ValueError('bogus error')
+        self.message_api.create(
+            self.ctxt,
+            action=message_field.Action.UPDATE_ATTACHMENT,
+            detail=message_field.Detail.VOLUME_ATTACH_MODE_INVALID,
+            exception=exc,
+            resource_type="fake_resource_type")
+
+        self.message_api.db.message_create.assert_called_once_with(
+            self.ctxt, expected_message_record)
+        mock_utcnow.assert_called_with()
+
     def test_create_swallows_exception(self):
         self.mock_object(self.message_api.db, 'create',
                          side_effect=Exception())

doc/source/contributor/user_messages.rst

@@ -1,53 +1,226 @@
 User Messages
 =============
 
+General information
+~~~~~~~~~~~~~~~~~~~
+
 User messages are a way to inform users about the state of asynchronous
 operations. One example would be notifying the user of why a volume
-provisioning request failed. These messages can be requested via the
+provisioning request failed. End users can request these messages via the
-/messages API. All user visible messages must be defined in the permitted
+Volume v3 REST API under the ``/messages`` resource.  The REST API allows
-messages module in order to prevent sharing sensitive information with users.
+only GET and DELETE verbs for this resource.
 
+Internally, you use the ``cinder.message.api`` to work with messages.  In
+order to prevent leakage of sensitive information or breaking the volume
+service abstraction layer, free-form messages are *not* allowed.  Instead, all
+messages must be defined using a combination of pre-defined fields in the
+``cinder.message.message_field`` module.
+
+The message ultimately displayed to end users is combined from an ``Action``
+field and a ``Detail`` field.
+
+* The ``Action`` field describes what was taking place when the message
+  was created, for example, ``Action.COPY_IMAGE_TO_VOLUME``.
+
+* The ``Detail`` field is used to provide more information, for example,
+  ``Detail.NOT_ENOUGH_SPACE_FOR_IMAGE`` or ``Detail.QUOTA_EXCEED``.
+
+Example
+~~~~~~~
 
 Example message generation::
 
  from cinder import context
  from cinder.message import api as message_api
- from cinder.message import defined_messages
+ from cinder.message import message_field
- from cinder.message import resource_types
 
  self.message_api = message_api.API()
 
  context = context.RequestContext()
- project_id = '6c430ede-9476-4128-8838-8d3929ced223'
  volume_id = 'f292cc0c-54a7-4b3b-8174-d2ff82d87008'
 
  self.message_api.create(
      context,
-     defined_messages.EventIds.UNABLE_TO_ALLOCATE,
+     message_field.Action.UNMANAGE_VOLUME,
-     project_id,
+     resource_uuid=volume_id,
-     resource_type=resource_types.VOLUME,
+     detail=message_field.Detail.UNMANAGE_ENC_NOT_SUPPORTED)
-     resource_uuid=volume_id)
 
-Will produce the following::
+Will produce roughly the following::
 
  GET /v3/6c430ede-9476-4128-8838-8d3929ced223/messages
  {
    "messages": [
      {
       "id": "5429fffa-5c76-4d68-a671-37a8e24f37cf",
-      "event_id": "000002",
+      "event_id": "VOLUME_VOLUME_006_008",
-      "user_message": "No storage could be allocated for this volume request.",
+      "user_message": "unmanage volume: Unmanaging encrypted volumes is not supported.",
       "message_level": "ERROR",
       "resource_type": "VOLUME",
       "resource_uuid": "f292cc0c-54a7-4b3b-8174-d2ff82d87008",
-      "created_at": 2015-08-27T09:49:58-05:00,
+      "created_at": 2018-08-27T09:49:58-05:00,
-      "guaranteed_until": 2015-09-27T09:49:58-05:00,
+      "guaranteed_until": 2018-09-27T09:49:58-05:00,
       "request_id": "req-936666d2-4c8f-4e41-9ac9-237b43f8b848",
      }
    ]
  }
 
+Adding user messages
+~~~~~~~~~~~~~~~~~~~~
 
+If you are creating a message in the code but find that the predefined fields
+are insufficient, just add what you need to ``cinder.message.message_field``.
+The key thing to keep in mind is that all defined fields should be appropriate
+for any API user to see and not contain any sensitive information. A good
+rule-of-thumb is to be very general in error messages unless the issue is due
+to a bad user action, then be specific.
+
+As a convenience to developers, the ``Detail`` class contains a
+``EXCEPTION_DETAIL_MAPPINGS`` dict.  This maps ``Detail`` fields to particular
+Cinder exceptions, and allows you to create messages in a context where you've
+caught an Exception that could be any of several possibilities.  Instead of
+having to sort through them where you've caught the exception, you can call
+``message_api.create`` and pass it both the exception and a general detail
+field like ``Detail.SOMETHING_BAD_HAPPENED`` (that's not a real field, but
+you get the idea).  If the passed exception is in the mapping, the resulting
+message will have the mapped ``Detail`` field instead of the generic one.
+
+Usage patterns
+~~~~~~~~~~~~~~
+
+These are taken from the Cinder code.  The exact code may have changed
+by the time you read this, but the general idea should hold.
+
+No exception in context
+-----------------------
+
+From cinder/compute/nova.py::
+
+    def extend_volume(self, context, server_ids, volume_id):
+        api_version = '2.51'
+        events = [self._get_volume_extended_event(server_id, volume_id)
+                  for server_id in server_ids]
+        result = self._send_events(context, events, api_version=api_version)
+        if not result:
+            self.message_api.create(
+                context,
+                message_field.Action.EXTEND_VOLUME,
+                resource_uuid=volume_id,
+                detail=message_field.Detail.NOTIFY_COMPUTE_SERVICE_FAILED)
+        return result
+
+* You must always pass the context object and an action.
+* We're working with an existing volume, so pass its ID as the
+  ``resource_uuid``.
+* You need to fill in some detail, or else the code will supply an
+  ``UNKNOWN_ERROR``, which isn't very helpful.
+
+Cinder exception in context
+---------------------------
+
+From cinder/scheduler/manager.py::
+
+        except exception.NoValidBackend as ex:
+            QUOTAS.rollback(context, reservations,
+                            project_id=volume.project_id)
+            _extend_volume_set_error(self, context, ex, request_spec)
+            self.message_api.create(
+                context,
+                message_field.Action.EXTEND_VOLUME,
+                resource_uuid=volume.id,
+                exception=ex)
+
+* You must always pass the context object and an action.
+* Since we have it available, pass the volume ID as the resource_uuid.
+* It's a Cinder exception.  Check to see if it's in the mapping.
+
+  * If it's there, we can pass it, and the detail will be supplied
+    by the code.
+  * It it's not, consider adding it and mapping it to an existing
+    ``Detail`` field.  If there's no current ``Detail`` field for that
+    exception, go ahead and add that, too.
+  * On the other hand, maybe it's in the mapping, but you have more
+    information in this code context than is available in the mapped
+    ``Detail`` field.  In that case, you may want to use a different
+    ``Detail`` field (creating it if necessary).
+  * Remember, if you pass *both* a mapped exception *and* a detail, the
+    passed detail will be ignored and the mapped ``Detail`` field will be
+    used instead.
+
+General Exception in context
+----------------------------
+
+Not passing the Exception to message_api.create()
++++++++++++++++++++++++++++++++++++++++++++++++++
+
+From cinder/volume/manager.py::
+
+        try:
+            self.driver.extend_volume(volume, new_size)
+        except exception.TargetUpdateFailed:
+            # We just want to log this but continue on with quota commit
+            LOG.warning('Volume extended but failed to update target.')
+        except Exception:
+            LOG.exception("Extend volume failed.",
+                          resource=volume)
+            self.message_api.create(
+                context,
+                message_field.Action.EXTEND_VOLUME,
+                resource_uuid=volume.id,
+                detail=message_field.Detail.DRIVER_FAILED_EXTEND)
+
+* Pass the context object and an action; pass a ``resource_uuid`` since we
+  have it.
+* We're not passing the exception, so the ``detail`` we pass is guaranteed
+  to be used.
+
+Passing the Exception to message_api.create()
++++++++++++++++++++++++++++++++++++++++++++++
+
+From cinder/volume/manager.py::
+
+        try:
+            if volume_metadata.get('readonly') == 'True' and mode != 'ro':
+                raise exception.InvalidVolumeAttachMode(mode=mode,
+                                                        volume_id=volume.id)
+            utils.require_driver_initialized(self.driver)
+
+            LOG.info('Attaching volume %(volume_id)s to instance '
+                     '%(instance)s at mountpoint %(mount)s on host '
+                     '%(host)s.',
+                     {'volume_id': volume_id, 'instance': instance_uuid,
+                      'mount': mountpoint, 'host': host_name_sanitized},
+                     resource=volume)
+            self.driver.attach_volume(context,
+                                      volume,
+                                      instance_uuid,
+                                      host_name_sanitized,
+                                      mountpoint)
+        except Exception as excep:
+            with excutils.save_and_reraise_exception():
+                self.message_api.create(
+                    context,
+                    message_field.Action.ATTACH_VOLUME,
+                    resource_uuid=volume_id,
+                    exception=excep)
+                attachment.attach_status = (
+                    fields.VolumeAttachStatus.ERROR_ATTACHING)
+                attachment.save()
+
+* Pass the context object and an action; pass a resource_uuid since we
+  have it.
+* We're passing an exception, which could be a Cinder
+  ``InvalidVolumeAttachMode``, which is in the mapping.  In that case, the
+  mapped ``Detail`` will be used;
+  otherwise, the code will supply a ``Detail.UNKNOWN_ERROR``.
+
+  This is appropriate if we really have no idea what happened.  If it's
+  possible to provide more information, we can pass a different, generic
+  ``Detail`` field (creating it if necessary).  The passed detail would be
+  used for any exception that's *not* in the mapping.  If it's a mapped
+  exception, then the mapped ``Detail`` field will be used.
+
+Module documentation
+~~~~~~~~~~~~~~~~~~~~
 
 The Message API Module
 ----------------------
@@ -63,8 +236,14 @@ The Message Field Module
 .. automodule:: cinder.message.message_field
     :noindex:
 
-The Permitted Messages Module
+The Defined Messages Module
------------------------------
+---------------------------
+
+This module is DEPRECATED and is currently only used by
+``cinder.api.v3.messages`` to handle pre-Pike message database objects.
+(Editorial comment:: With the default ``message_ttl`` of 2592000 seconds
+(30 days), it's probably safe to remove this module during the Train
+development cycle.)
 
 .. automodule:: cinder.message.defined_messages
     :noindex: