Make hmac required argument in profiler.Profiler.init

In previous patch we changed behavior or profiler lib. Currently
profiler want create any notification if hmac key is not setted up
and all messages are not properly signed by it.

So to avoid mistakes (e.g. forgot to init profiler with hmac key) this
argument should be required (not optional)

As well a lot of improvments in docs related to profiler module

Change-Id: I74e05234a5638ffd93dbac9180d4497fcb5093ac

osprofiler/profiler.py

@@ -28,14 +28,19 @@ def _clean():
     __local_ctx.profiler = None
 
 
-def init(base_id=None, parent_id=None, hmac_key=None):
+def init(hmac_key, base_id=None, parent_id=None):
-    """Init profiler.
+    """Init profiler instance for current thread.
+
+    You should call profiler.init() before using osprofiler.
+    Otherwise profiler.start() and profiler.stop() methods won't do anything.
+
+    :param hmac_key: secret key to sign trace information.
     :param base_id: Used to bind all related traces.
     :param parent_id: Used to build tree of traces.
     :returns: Profiler instance
     """
-    __local_ctx.profiler = Profiler(base_id=base_id, parent_id=parent_id,
+    __local_ctx.profiler = Profiler(hmac_key, base_id=base_id,
-                                    hmac_key=hmac_key)
+                                    parent_id=parent_id)
     return __local_ctx.profiler
 
 
@@ -48,7 +53,12 @@ def get_profiler():
 
 
 def start(name, info=None):
-    """Send new start notification if profiler instance is presented."""
+    """Send new start notification if profiler instance is presented.
+
+    :param name: The name of action. E.g. wsgi, rpc, db, etc..
+    :param info: Dictionary with extra trace information. For example in wsgi
+                  it can be url, in rpc - message or in db sql - request.
+    """
     profiler = get_profiler()
     if profiler:
         profiler.start(name, info=info)
@@ -64,6 +74,20 @@ def stop(info=None):
 class Trace(object):
 
     def __init__(self, name, info=None):
+        """With statement way to use profiler start()/stop().
+
+
+        >> with profiler.Trace("rpc", info={"any": "values"})
+        >>    some code
+
+        instead of
+
+        >> profiler.start()
+        >> try:
+        >>    your code
+        >> finally:
+              profiler.stop()
+        """
         self._name = name
         self._info = info
 
@@ -76,7 +100,7 @@ class Trace(object):
 
 class Profiler(object):
 
-    def __init__(self, base_id=None, parent_id=None, hmac_key=None):
+    def __init__(self, hmac_key, base_id=None, parent_id=None):
         self.hmac_key = hmac_key
         if not base_id:
             base_id = str(uuid.uuid4())
@@ -84,25 +108,50 @@ class Profiler(object):
         self._name = collections.deque()
 
     def get_base_id(self):
+        """Return base if of trace.
+
+        Base id is the same for all elements in one trace. It's main goal is
+        to be able to retrieve by one request all trace elements from storage.
+        """
         return self._trace_stack[0]
 
     def get_parent_id(self):
+        """Returns parent trace element id."""
         return self._trace_stack[-2]
 
     def get_id(self):
+        """Returns current trace element id."""
         return self._trace_stack[-1]
 
     def start(self, name, info=None):
-        """Currently time measurement itself is delegated to
+        """Start new event.
-        notification.api. Every message is marked with a unix
+
-        timestamp and for now it should be sufficient.
+        Adds new trace_id to trace stack and sends notification
-        Later more precise measurements can be added here.
+        to collector (may be ceilometer). With "info" and 3 ids:
+        base_id - to be able to retrieve all trace elements by one query
+        parent_id - to build tree of events (not just a list)
+        trace_id - current event id.
+
+        As we are writing this code special for OpenStack, and there will be
+        only one implementation of notifier based on ceilometer notifer api.
+        That already contains timestamps, so we don't measure time by hand.
+
+        :param name: name of trace element (db, wsgi, rpc, etc..)
+        :param info: Dictionary with any useful information related to this
+                     trace element. (sql request, rpc message or url...)
         """
+
         self._name.append(name)
         self._trace_stack.append(str(uuid.uuid4()))
         self._notify('%s-start' % name, info)
 
     def stop(self, info=None):
+        """Finish latests event.
+
+        Same as a start, but instead of pushing trace_id to stack it pops it.
+
+        :param info: Dict with useful info. It will be send in notification.
+        """
         self._notify('%s-stop' % self._name.pop(), info)
         self._trace_stack.pop()
 

osprofiler/web.py

@@ -66,9 +66,9 @@ class WsgiMiddleware(object):
         if not self._trace_is_valid(trace_info):
             return request.get_response(self.application)
 
-        profiler.init(trace_info.get("base_id"),
+        profiler.init(self.hmac_key,
-                      trace_info.get("parent_id"),
+                      base_id=trace_info.get("base_id"),
-                      self.hmac_key)
+                      parent_id=trace_info.get("parent_id"))
         info = {
             "request": {
                 "host_url": request.host_url,

tests/test_profiler.py

@@ -28,7 +28,7 @@ class ProfilerGlobMethodsTestCase(test.TestCase):
         self.assertIsNone(profiler.get_profiler())
 
     def test_get_profiler_and_init(self):
-        p = profiler.init(base_id="1", parent_id="2")
+        p = profiler.init("secret", base_id="1", parent_id="2")
         self.assertEqual(profiler.get_profiler(), p)
 
         self.assertEqual(p.get_base_id(), "1")
@@ -40,7 +40,7 @@ class ProfilerGlobMethodsTestCase(test.TestCase):
         profiler.start("name")
 
     def test_start(self):
-        p = profiler.init(base_id="1", parent_id="2")
+        p = profiler.init("secret", base_id="1", parent_id="2")
         p.start = mock.MagicMock()
         profiler.start("name", info="info")
         p.start.assert_called_once_with("name", info="info")
@@ -50,7 +50,7 @@ class ProfilerGlobMethodsTestCase(test.TestCase):
         profiler.stop()
 
     def test_stop(self):
-        p = profiler.init(base_id="1", parent_id="2")
+        p = profiler.init("secret", base_id="1", parent_id="2")
         p.stop = mock.MagicMock()
         profiler.stop(info="info")
         p.stop.assert_called_once_with(info="info")
@@ -59,27 +59,27 @@ class ProfilerGlobMethodsTestCase(test.TestCase):
 class ProfilerTestCase(test.TestCase):
 
     def test_profiler_get_base_id(self):
-        prof = profiler.Profiler(base_id="1", parent_id="2")
+        prof = profiler.Profiler("secret", base_id="1", parent_id="2")
         self.assertEqual(prof.get_base_id(), "1")
 
     @mock.patch("osprofiler.profiler.uuid.uuid4")
     def test_profiler_get_parent_id(self, mock_uuid4):
         mock_uuid4.return_value = "42"
-        prof = profiler.Profiler(base_id="1", parent_id="2")
+        prof = profiler.Profiler("secret", base_id="1", parent_id="2")
         prof.start("test")
         self.assertEqual(prof.get_parent_id(), "2")
 
     @mock.patch("osprofiler.profiler.uuid.uuid4")
     def test_profiler_get_base_id_unset_case(self, mock_uuid4):
         mock_uuid4.return_value = "42"
-        prof = profiler.Profiler()
+        prof = profiler.Profiler("secret")
         self.assertEqual(prof.get_base_id(), "42")
         self.assertEqual(prof.get_parent_id(), "42")
 
     @mock.patch("osprofiler.profiler.uuid.uuid4")
     def test_profiler_get_id(self, mock_uuid4):
         mock_uuid4.return_value = "43"
-        prof = profiler.Profiler()
+        prof = profiler.Profiler("secret")
         prof.start("test")
         self.assertEqual(prof.get_id(), "43")
 
@@ -97,14 +97,14 @@ class ProfilerTestCase(test.TestCase):
             "info": info
         }
 
-        prof = profiler.Profiler(base_id="1", parent_id="2")
+        prof = profiler.Profiler("secret", base_id="1", parent_id="2")
         prof.start("test", info=info)
 
         mock_notify.assert_called_once_with(payload)
 
     @mock.patch("osprofiler.profiler.notifier.notify")
     def test_profiler_stop(self, mock_notify):
-        prof = profiler.Profiler(base_id="1", parent_id="2")
+        prof = profiler.Profiler("secret", base_id="1", parent_id="2")
         prof._trace_stack.append("44")
         prof._name.append("abc")
 
@@ -123,6 +123,11 @@ class ProfilerTestCase(test.TestCase):
         self.assertEqual(len(prof._name), 0)
         self.assertEqual(prof._trace_stack, collections.deque(["1", "2"]))
 
+    def test_profiler_hmac(self):
+        hmac = "secret"
+        prof = profiler.Profiler(hmac, base_id="1", parent_id="2")
+        self.assertEqual(hmac, prof.hmac_key)
+
 
 class TraceTestCase(test.TestCase):
 

tests/test_web.py

@@ -36,13 +36,13 @@ class WebTestCase(test.TestCase):
         self.addCleanup(profiler._clean)
 
     def test_add_trace_id_header_no_hmac(self):
-        profiler.init(base_id="y", parent_id="z")
+        profiler.init(None, base_id="y", parent_id="z")
         headers = {"a": 10, "b": 20}
         web.add_trace_id_header(headers)
         self.assertEqual(sorted(headers.keys()), ["a", "b"])
 
     def test_add_trace_id_header(self):
-        profiler.init(base_id="y", parent_id="z", hmac_key="key")
+        profiler.init("key", base_id="y", parent_id="z")
         headers = {"a": 10, "b": 20}
         web.add_trace_id_header(headers)
         self.assertEqual(sorted(headers.keys()),
@@ -189,7 +189,8 @@ class WebMiddlewareTestCase(test.TestCase):
 
         middleware = web.WsgiMiddleware("app", hmac_key, enabled=True)
         self.assertEqual("yeah!", middleware(request))
-        mock_profiler_init.assert_called_once_with("1", "2", hmac_key)
+        mock_profiler_init.assert_called_once_with(hmac_key, base_id="1",
+                                                   parent_id="2")
         expected_info = {
             "request": {
                 "host_url": request.host_url,