Fix session timing

Subclass keystoneclient.session.Session to add the timing hooks to
record the elapsed time returned by requests.Response objects, including
the redirection history.  Redirects are included individually and not
rolled into the total time for the original request.

This works for all clients that use OSC's session.

Closes-Bug: #1402577
Change-Id: I9360c90c151579b89a37edb8c11c17feb15b3cb9

5 files changed, 71 insertions, 19 deletions

diff --git a/openstackclient/common/clientmanager.py b/openstackclient/common/clientmanager.py
index 10f38c25..6d2a9d76 100644
--- a/openstackclient/common/clientmanager.py
+++ b/openstackclient/common/clientmanager.py
@@ -19,10 +19,10 @@ import logging
 import pkg_resources
 import sys
 
-from keystoneclient import session
 import requests
 
 from openstackclient.api import auth
+from openstackclient.common import session as osc_session
 from openstackclient.identity import client as identity_client
 
 
@@ -157,7 +157,7 @@ class ClientManager(object):
         self.auth = auth_plugin.load_from_options(**self._auth_params)
         # needed by SAML authentication
         request_session = requests.session()
-        self.session = session.Session(
+        self.session = osc_session.TimingSession(
             auth=self.auth,
             session=request_session,
             verify=self._verify,
diff --git a/openstackclient/common/session.py b/openstackclient/common/session.py
new file mode 100644
index 00000000..dda1c417
--- /dev/null
+++ b/openstackclient/common/session.py
@@ -0,0 +1,50 @@
+#   Licensed under the Apache License, Version 2.0 (the "License"); you may
+#   not use this file except in compliance with the License. You may obtain
+#   a copy of the License at
+#
+#        http://www.apache.org/licenses/LICENSE-2.0
+#
+#   Unless required by applicable law or agreed to in writing, software
+#   distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+#   WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+#   License for the specific language governing permissions and limitations
+#   under the License.
+#
+
+"""Subclass of keystoneclient.session"""
+
+from keystoneclient import session
+
+
+class TimingSession(session.Session):
+    """A Session that supports collection of timing data per Method URL"""
+
+    def __init__(
+            self,
+            **kwargs
+    ):
+        """Pass through all arguments except timing"""
+        super(TimingSession, self).__init__(**kwargs)
+
+        # times is a list of tuples: ("method url", elapsed_time)
+        self.times = []
+
+    def get_timings(self):
+        return self.times
+
+    def reset_timings(self):
+        self.times = []
+
+    def request(self, url, method, **kwargs):
+        """Wrap the usual request() method with the timers"""
+        resp = super(TimingSession, self).request(url, method, **kwargs)
+        for h in resp.history:
+            self.times.append((
+                "%s %s" % (h.request.method, h.request.url),
+                h.elapsed,
+            ))
+        self.times.append((
+            "%s %s" % (resp.request.method, resp.request.url),
+            resp.elapsed,
+        ))
+        return resp
diff --git a/openstackclient/common/timing.py b/openstackclient/common/timing.py
index 1c94682c..d13c86e7 100644
--- a/openstackclient/common/timing.py
+++ b/openstackclient/common/timing.py
@@ -33,10 +33,12 @@ class Timing(lister.Lister):
 
         results = []
         total = 0.0
-        for url, start, end in self.app.timing_data:
-            seconds = end - start
-            total += seconds
-            results.append((url, seconds))
+        for url, td in self.app.timing_data:
+            # NOTE(dtroyer): Take the long way here because total_seconds()
+            #                was added in py27.
+            sec = (td.microseconds + (td.seconds + td.days*86400) * 1e6) / 1e6
+            total += sec
+            results.append((url, sec))
         results.append(('Total', total))
         return (
             column_headers,
diff --git a/openstackclient/shell.py b/openstackclient/shell.py
index 3cfd7312..05882488 100644
--- a/openstackclient/shell.py
+++ b/openstackclient/shell.py
@@ -316,11 +316,10 @@ class OpenStackShell(app.App):
 
         # Process collected timing data
         if self.options.timing:
-            # Loop through extensions
-            for mod in self.ext_modules:
-                client = getattr(self.client_manager, mod.API_NAME)
-                if hasattr(client, 'get_timings'):
-                    self.timing_data.extend(client.get_timings())
+            # Get session data
+            self.timing_data.extend(
+                self.client_manager.session.get_timings(),
+            )
 
             # Use the Timing pseudo-command to generate the output
             tcmd = timing.Timing(self, self.options)
diff --git a/openstackclient/tests/common/test_timing.py b/openstackclient/tests/common/test_timing.py
index aa910b91..a7f93b55 100644
--- a/openstackclient/tests/common/test_timing.py
+++ b/openstackclient/tests/common/test_timing.py
@@ -13,14 +13,15 @@
 
 """Test Timing pseudo-command"""
 
+import datetime
+
 from openstackclient.common import timing
 from openstackclient.tests import fakes
 from openstackclient.tests import utils
 
 
 timing_url = 'GET http://localhost:5000'
-timing_start = 1404802774.872809
-timing_end = 1404802775.724802
+timing_elapsed = 0.872809
 
 
 class FakeGenericClient(object):
@@ -66,9 +67,10 @@ class TestTiming(utils.TestCommand):
         self.assertEqual(datalist, data)
 
     def test_timing_list(self):
-        self.app.timing_data = [
-            (timing_url, timing_start, timing_end),
-        ]
+        self.app.timing_data = [(
+            timing_url,
+            datetime.timedelta(microseconds=timing_elapsed*1000000),
+        )]
 
         arglist = []
         verifylist = []
@@ -79,9 +81,8 @@ class TestTiming(utils.TestCommand):
 
         collist = ('URL', 'Seconds')
         self.assertEqual(collist, columns)
-        timing_sec = timing_end - timing_start
         datalist = [
-            (timing_url, timing_sec),
-            ('Total', timing_sec)
+            (timing_url, timing_elapsed),
+            ('Total', timing_elapsed),
         ]
         self.assertEqual(datalist, data)