Add metrics support to IPA

This utilizes the new metrics support in ironic-lib to allow the agent to
report timing metrics for agent API methods as configured in ironic-lib.

Additionally, this adds developer docs on how to use metrics in IPA,
including some caveats specific to ironic-lib.metrics use in IPA.

Co-Authored-By: Jay Faulkner <jay@jvf.cc>
Co-Authored-By: Alex Weeks <alex.weeks@gmail.com>
Change-Id: Ic08d4ff78b6fb614b474b956a32eac352a14262a
Partial-bug: #1526219

5 files changed, 44 insertions, 26 deletions

diff --git a/ironic_python_agent/agent.py b/ironic_python_agent/agent.py
index 0a1799aa..8c7d3347 100644
--- a/ironic_python_agent/agent.py
+++ b/ironic_python_agent/agent.py
@@ -20,6 +20,7 @@ import threading
 import time
 
 from oslo_concurrency import processutils
+from oslo_config import cfg
 from oslo_log import log
 import pkg_resources
 from six.moves.urllib import parse as urlparse
@@ -35,7 +36,6 @@ from ironic_python_agent import inspector
 from ironic_python_agent import ironic_api_client
 from ironic_python_agent import utils
 
-
 LOG = log.getLogger(__name__)
 
 # Time(in seconds) to wait for any of the interfaces to be up
@@ -45,6 +45,9 @@ NETWORK_WAIT_TIMEOUT = 60
 # Time(in seconds) to wait before reattempt
 NETWORK_WAIT_RETRY = 5
 
+cfg.CONF.import_group('metrics', 'ironic_lib.metrics_utils')
+cfg.CONF.import_group('metrics_statsd', 'ironic_lib.metrics_statsd')
+
 
 def _time():
     """Wraps time.time() for simpler testing."""
@@ -340,6 +343,15 @@ class IronicPythonAgent(base.ExecuteCommandMixin):
             hardware.cache_node(self.node)
             self.heartbeat_timeout = content['heartbeat_timeout']
 
+            # Update config with values from Ironic
+            config = content.get('config', {})
+            if config.get('metrics'):
+                for opt, val in config.items():
+                    setattr(cfg.CONF.metrics, opt, val)
+            if config.get('metrics_statsd'):
+                for opt, val in config.items():
+                    setattr(cfg.CONF.metrics_statsd, opt, val)
+
         wsgi = simple_server.make_server(
             self.listen_address[0],
             self.listen_address[1],
diff --git a/ironic_python_agent/api/controllers/root.py b/ironic_python_agent/api/controllers/root.py
index 46caaad0..c95e2186 100644
--- a/ironic_python_agent/api/controllers/root.py
+++ b/ironic_python_agent/api/controllers/root.py
@@ -12,9 +12,9 @@
 # License for the specific language governing permissions and limitations
 # under the License.
 
+from ironic_lib import metrics_utils
 import pecan
 from pecan import rest
-
 from wsme import types as wtypes
 import wsmeext.pecan as wsme_pecan
 
@@ -81,7 +81,8 @@ class RootController(rest.RestController):
         # NOTE: The reason why convert() it's being called for every
         #       request is because we need to get the host url from
         #       the request object to make the links.
-        return Root.convert()
+        with metrics_utils.get_metrics_logger(__name__).timer('get'):
+            return Root.convert()
 
     @pecan.expose()
     def _route(self, args):
diff --git a/ironic_python_agent/api/controllers/v1/command.py b/ironic_python_agent/api/controllers/v1/command.py
index e4483e29..b6971fa7 100644
--- a/ironic_python_agent/api/controllers/v1/command.py
+++ b/ironic_python_agent/api/controllers/v1/command.py
@@ -13,6 +13,7 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
+from ironic_lib import metrics_utils
 import pecan
 from pecan import rest
 from wsme import types
@@ -78,9 +79,10 @@ class CommandController(rest.RestController):
     @wsme_pecan.wsexpose(CommandResultList)
     def get_all(self):
         """Get all command results."""
-        agent = pecan.request.agent
-        results = agent.list_command_results()
-        return CommandResultList.from_results(results)
+        with metrics_utils.get_metrics_logger(__name__).timer('get_all'):
+            agent = pecan.request.agent
+            results = agent.list_command_results()
+            return CommandResultList.from_results(results)
 
     @wsme_pecan.wsexpose(CommandResult, types.text, types.text)
     def get_one(self, result_id, wait=None):
@@ -91,13 +93,14 @@ class CommandController(rest.RestController):
         :returns: a :class:`ironic_python_agent.api.controller.v1.command.
                   CommandResult` object.
         """
-        agent = pecan.request.agent
-        result = agent.get_command_result(result_id)
+        with metrics_utils.get_metrics_logger(__name__).timer('get_one'):
+            agent = pecan.request.agent
+            result = agent.get_command_result(result_id)
 
-        if wait and wait.lower() == 'true':
-            result.join()
+            if wait and wait.lower() == 'true':
+                result.join()
 
-        return CommandResult.from_result(result)
+            return CommandResult.from_result(result)
 
     @wsme_pecan.wsexpose(CommandResult, types.text, body=Command)
     def post(self, wait=None, command=None):
@@ -109,14 +112,15 @@ class CommandController(rest.RestController):
         :returns: a :class:`ironic_python_agent.api.controller.v1.command.
                   CommandResult` object.
         """
-        # the POST body is always the last arg,
-        # so command must be a kwarg here
-        if command is None:
-            command = Command()
-        agent = pecan.request.agent
-        result = agent.execute_command(command.name, **command.params)
-
-        if wait and wait.lower() == 'true':
-            result.join()
-
-        return result
+        with metrics_utils.get_metrics_logger(__name__).timer('post'):
+            # the POST body is always the last arg,
+            # so command must be a kwarg here
+            if command is None:
+                command = Command()
+            agent = pecan.request.agent
+            result = agent.execute_command(command.name, **command.params)
+
+            if wait and wait.lower() == 'true':
+                result.join()
+
+            return result
diff --git a/ironic_python_agent/api/controllers/v1/status.py b/ironic_python_agent/api/controllers/v1/status.py
index 84efc6a4..b1ed83b8 100644
--- a/ironic_python_agent/api/controllers/v1/status.py
+++ b/ironic_python_agent/api/controllers/v1/status.py
@@ -13,6 +13,7 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
+from ironic_lib import metrics_utils
 import pecan
 from pecan import rest
 from wsme import types
@@ -48,6 +49,7 @@ class StatusController(rest.RestController):
     @wsme_pecan.wsexpose(AgentStatus)
     def get_all(self):
         """Get current status of the running agent."""
-        agent = pecan.request.agent
-        status = agent.get_status()
-        return AgentStatus.from_agent_status(status)
+        with metrics_utils.get_metrics_logger(__name__).timer('get_all'):
+            agent = pecan.request.agent
+            status = agent.get_status()
+            return AgentStatus.from_agent_status(status)
diff --git a/ironic_python_agent/extensions/standby.py b/ironic_python_agent/extensions/standby.py
index 1c77d667..a3d1ccac 100644
--- a/ironic_python_agent/extensions/standby.py
+++ b/ironic_python_agent/extensions/standby.py
@@ -533,7 +533,6 @@ class StandbyExtension(base.BaseAgentExtension):
         stream_raw_images = image_info.get('stream_raw_images', False)
         # don't write image again if already cached
         if self.cached_image_id != image_info['id']:
-
             if self.cached_image_id is not None:
                 LOG.debug('Already had %s cached, overwriting',
                           self.cached_image_id)