Included time inside trans_id

Including the time inside the trans_id can be very useful for knowing
which logs to scan. I made this so the trans_id will still be the
same length (the randomness of the remaining uuid4 should be enough
for this use). I also added a convenience function for retreiving the
time information from a trans_id.

If you're wondering why I just didn't use uuid1 that embeds the time,
it's because it also embeds uuid.getnode() which "The first time this
runs, it may launch a separate program, which could be quite slow."
We could supply our own getnode value, but then we have to guarantee
its uniqueness, yada yada yada.

Change-Id: Ie33caf1e839fd1a21b01a928a8b301126bef7396

swift/common/middleware/catch_errors.py

@@ -14,10 +14,9 @@
 # limitations under the License.
 
 from eventlet import Timeout
-import uuid
 
 from swift.common.swob import Request, HTTPServerError
-from swift.common.utils import get_logger
+from swift.common.utils import get_logger, generate_trans_id
 from swift.common.wsgi import WSGIContext
 
 
@@ -29,7 +28,7 @@ class CatchErrorsContext(WSGIContext):
         self.trans_id_suffix = trans_id_suffix
 
     def handle_request(self, env, start_response):
-        trans_id = 'tx' + uuid.uuid4().hex + self.trans_id_suffix
+        trans_id = generate_trans_id(self.trans_id_suffix)
         env['swift.trans_id'] = trans_id
         self.logger.txn_id = trans_id
         try:

swift/common/utils.py

@@ -21,6 +21,7 @@ import os
 import pwd
 import sys
 import time
+import uuid
 import functools
 from hashlib import md5
 from random import random, shuffle
@@ -178,6 +179,20 @@ def get_param(req, name, default=None):
     return value
 
 
+def generate_trans_id(trans_id_suffix):
+    return 'tx%s-%010x%s' % (
+        uuid.uuid4().hex[:21], time.time(), trans_id_suffix)
+
+
+def get_trans_id_time(trans_id):
+    if len(trans_id) >= 34 and trans_id[:2] == 'tx' and trans_id[23] == '-':
+        try:
+            return int(trans_id[24:34], 16)
+        except ValueError:
+            pass
+    return None
+
+
 class FallocateWrapper(object):
 
     def __init__(self, noop=False):

swift/proxy/server.py

@@ -27,7 +27,6 @@
 import mimetypes
 import os
 from ConfigParser import ConfigParser
-import uuid
 from random import shuffle
 from time import time
 
@@ -35,7 +34,7 @@ from eventlet import Timeout
 
 from swift.common.ring import Ring
 from swift.common.utils import cache_from_env, get_logger, \
-    get_remote_client, split_path, config_true_value
+    get_remote_client, split_path, config_true_value, generate_trans_id
 from swift.common.constraints import check_utf8
 from swift.proxy.controllers import AccountController, ObjectController, \
     ContainerController
@@ -221,7 +220,7 @@ class Application(object):
             controller = controller(self, **path_parts)
             if 'swift.trans_id' not in req.environ:
                 # if this wasn't set by an earlier middleware, set it now
-                trans_id = 'tx' + uuid.uuid4().hex + self.trans_id_suffix
+                trans_id = generate_trans_id(self.trans_id_suffix)
                 req.environ['swift.trans_id'] = trans_id
                 self.logger.txn_id = trans_id
             req.headers['x-trans-id'] = req.environ['swift.trans_id']

test/unit/common/test_utils.py

@@ -1172,6 +1172,43 @@ log_name = %(yarr)s'''
         finally:
             utils._sys_fallocate = orig__sys_fallocate
 
+    def test_generate_trans_id(self):
+        fake_time = 1366428370.5163341
+        with patch.object(utils.time, 'time', return_value=fake_time):
+            trans_id = utils.generate_trans_id('')
+            self.assertEquals(len(trans_id), 34)
+            self.assertEquals(trans_id[:2], 'tx')
+            self.assertEquals(trans_id[23], '-')
+            self.assertEquals(int(trans_id[24:], 16), int(fake_time))
+        with patch.object(utils.time, 'time', return_value=fake_time):
+            trans_id = utils.generate_trans_id('-suffix')
+            self.assertEquals(len(trans_id), 41)
+            self.assertEquals(trans_id[:2], 'tx')
+            self.assertEquals(trans_id[34:], '-suffix')
+            self.assertEquals(trans_id[23], '-')
+            self.assertEquals(int(trans_id[24:34], 16), int(fake_time))
+
+    def test_get_trans_id_time(self):
+        ts = utils.get_trans_id_time('tx8c8bc884cdaf499bb29429aa9c46946e')
+        self.assertEquals(ts, None)
+        ts = utils.get_trans_id_time('tx1df4ff4f55ea45f7b2ec2-0051720c06')
+        self.assertEquals(ts, 1366428678)
+        self.assertEquals(
+            time.asctime(time.gmtime(ts)) + ' UTC',
+            'Sat Apr 20 03:31:18 2013 UTC')
+        ts = utils.get_trans_id_time(
+            'tx1df4ff4f55ea45f7b2ec2-0051720c06-suffix')
+        self.assertEquals(ts, 1366428678)
+        self.assertEquals(
+            time.asctime(time.gmtime(ts)) + ' UTC',
+            'Sat Apr 20 03:31:18 2013 UTC')
+        ts = utils.get_trans_id_time('')
+        self.assertEquals(ts, None)
+        ts = utils.get_trans_id_time('garbage')
+        self.assertEquals(ts, None)
+        ts = utils.get_trans_id_time('tx1df4ff4f55ea45f7b2ec2-almostright')
+        self.assertEquals(ts, None)
+
 
 class TestStatsdLogging(unittest.TestCase):
     def test_get_logger_statsd_client_not_specified(self):