Refactor session db logging and key generation for sessions/otks

While I was working on the redis sessiondb stuff, I noticed that
log_wanrning, get_logger ... was duplicated. Also there was code to
generate a unique key for otks that was duplicated.

Changes:

  creating new sessions_common.py and SessionsCommon class to provide
  methods:

        log_warning, log_info, log_debug, get_logger, getUniqueKey

      getUniqueKey method is closer to the method used to make
      session keys in client.py.

      sessions_common.py now report when random_.py chooses a weak
        random number generator. Removed same from rest.py.

      get_logger reconciles all logging under

          roundup.hyperdb.backends.<name of BasicDatabase class>

      some backends used to log to root logger.


  have BasicDatabase in other sessions_*.py modules inherit from
  SessionCommon.

  change logging to use log_* methods.


In addition:

  remove unused imports reported by flake8 and other formatting
  changes

  modify actions.py, rest.py, templating.py to use getUniqueKey
  method.

  add tests for new methods

test_redis_session.py
  swap out ModuleNotFoundError for ImportError to prevent crash in
      python2 when redis is not present.

  allow injection of username:password or just password into redis
  connection URL. set pytest_redis_pw envirnment variable to password
  or user:password when running test.

Author: rouilj

roundup/backends/sessions_common.py

@@ -0,0 +1,50 @@
+import base64, logging
+
+import roundup.anypy.random_ as random_
+from roundup.anypy.strings import b2s
+
+logger = logging.getLogger('roundup.hyperdb.backend.sessions')
+if not random_.is_weak:
+    logger.debug("Importing good random generator")
+else:
+    logger.warning("**SystemRandom not available. Using poor random generator")
+
+
+class SessionCommon:
+
+    def log_debug(self, msg, *args, **kwargs):
+        """Log a message with level DEBUG."""
+
+        logger = self.get_logger()
+        logger.debug(msg, *args, **kwargs)
+
+    def log_info(self, msg, *args, **kwargs):
+        """Log a message with level INFO."""
+
+        logger = self.get_logger()
+        logger.info(msg, *args, **kwargs)
+
+    def log_warning(self, msg, *args, **kwargs):
+        """Log a message with level INFO."""
+        logger = self.get_logger()
+        logger.warning(msg, *args, **kwargs)
+
+    def get_logger(self):
+        """Return the logger for this database."""
+
+        # Because getting a logger requires acquiring a lock, we want
+        # to do it only once.
+        if not hasattr(self, '__logger'):
+            self.__logger = logging.getLogger('roundup.hyperdb.backends.%s' %
+                                              self.name or "basicdb" )
+
+        return self.__logger
+
+    def getUniqueKey(self, length=40):
+        otk = b2s(base64.b64encode(
+            random_.token_bytes(length))).rstrip('=')
+        while self.exists(otk):
+            otk = b2s(base64.b64encode(
+                random_.token_bytes(length))).rstrip('=')
+
+        return otk

roundup/backends/sessions_dbm.py

@@ -6,16 +6,17 @@
 """
 __docformat__ = 'restructuredtext'
 
-import os, marshal, time, logging, random
+import marshal, os, random, time
 
 from roundup.anypy.html import html_escape as escape
 
 from roundup import hyperdb
 from roundup.i18n import _
 from roundup.anypy.dbm_ import anydbm, whichdb
+from roundup.backends.sessions_common import SessionCommon
 
 
-class BasicDatabase:
+class BasicDatabase(SessionCommon):
     ''' Provide a nice encapsulation of an anydbm store.
 
         Keys are id strings, values are automatically marshalled data.
@@ -88,7 +89,7 @@ def getall(self, infoid):
 
     def set(self, infoid, **newvalues):
         db = self.opendb('c')
-        timestamp=None
+        timestamp = None
         try:
             if infoid in db:
                 values = marshal.loads(db[infoid])
@@ -147,7 +148,6 @@ def opendb(self, mode):
         dbm = __import__(db_type)
 
         retries_left = 15
-        logger = logging.getLogger('roundup.hyperdb.backend.sessions')
         while True:
             try:
                 handle = dbm.open(path, mode)
@@ -157,14 +157,16 @@ def opendb(self, mode):
                 #   [Errno 11] Resource temporarily unavailable retry
                 # FIXME: make this more specific
                 if retries_left < 10:
-                    logger.warning('dbm.open failed on ...%s, retry %s left: %s, %s'%(path[-15:],15-retries_left,retries_left,e))
+                    self.log_warning(
+                        'dbm.open failed on ...%s, retry %s left: %s, %s' %
+                        (path[-15:], 15-retries_left, retries_left, e))
                 if retries_left < 0:
                     # We have used up the retries. Reraise the exception
                     # that got us here.
                     raise
                 else:
                     # stagger retry to try to get around thundering herd issue.
-                    time.sleep(random.randint(0,25)*.005)
+                    time.sleep(random.randint(0, 25)*.005)
                     retries_left = retries_left - 1
                     continue  # the while loop
         return handle

roundup/backends/sessions_rdbms.py

@@ -5,67 +5,70 @@
 class. It's now also used for One Time Key handling too.
 """
 __docformat__ = 'restructuredtext'
-import os, time, logging
+import time
 
 from roundup.anypy.html import html_escape as escape
+from roundup.backends.sessions_common import SessionCommon
 
-class BasicDatabase:
+
+class BasicDatabase(SessionCommon):
     ''' Provide a nice encapsulation of an RDBMS table.
 
         Keys are id strings, values are automatically marshalled data.
     '''
     name = None
+
     def __init__(self, db):
         self.db = db
         self.conn, self.cursor = self.db.sql_open_connection()
 
     def clear(self):
-        self.cursor.execute('delete from %ss'%self.name)
+        self.cursor.execute('delete from %ss' % self.name)
 
     def exists(self, infoid):
         n = self.name
-        self.cursor.execute('select count(*) from %ss where %s_key=%s'%(n,
-            n, self.db.arg), (infoid,))
+        self.cursor.execute('select count(*) from %ss where %s_key=%s' %
+                            (n, n, self.db.arg), (infoid,))
         return int(self.cursor.fetchone()[0])
 
     _marker = []
+
     def get(self, infoid, value, default=_marker):
         n = self.name
-        self.cursor.execute('select %s_value from %ss where %s_key=%s'%(n,
-            n, n, self.db.arg), (infoid,))
+        self.cursor.execute('select %s_value from %ss where %s_key=%s' %
+                            (n, n, n, self.db.arg), (infoid,))
         res = self.cursor.fetchone()
         if not res:
             if default != self._marker:
                 return default
-            raise KeyError('No such %s "%s"'%(self.name, escape(infoid)))
+            raise KeyError('No such %s "%s"' % (self.name, escape(infoid)))
         values = eval(res[0])
         return values.get(value, None)
 
     def getall(self, infoid):
         n = self.name
-        self.cursor.execute('select %s_value from %ss where %s_key=%s'%(n,
-            n, n, self.db.arg), (infoid,))
+        self.cursor.execute('select %s_value from %ss where %s_key=%s' %
+                            (n, n, n, self.db.arg), (infoid,))
         res = self.cursor.fetchone()
         if not res:
-            raise KeyError('No such %s "%s"'%(self.name, escape (infoid)))
+            raise KeyError('No such %s "%s"' % (self.name, escape(infoid)))
         return eval(res[0])
 
     def set(self, infoid, **newvalues):
         """ Store all newvalues under key infoid with a timestamp in database.
 
-            If newvalues['__timestamp'] exists and is representable as a floating point number
-            (i.e. could be generated by time.time()), that value is used for the <name>_time
-            column in the database.
+            If newvalues['__timestamp'] exists and is representable as
+            a floating point number (i.e. could be generated by time.time()),
+            that value is used for the <name>_time column in the database.
         """
         c = self.cursor
         n = self.name
         a = self.db.arg
-        c.execute('select %s_value from %ss where %s_key=%s'% \
-                  (n, n, n, a),
-            (infoid,))
+        c.execute('select %s_value from %ss where %s_key=%s' %
+                  (n, n, n, a), (infoid,))
         res = c.fetchone()
 
-        timestamp=time.time()
+        timestamp = time.time()
         if res:
             values = eval(res[0])
         else:
@@ -85,43 +88,43 @@ def set(self, infoid, **newvalues):
         values.update(newvalues)
         if res:
             sql = ('update %ss set %s_value=%s, %s_time=%s '
-                       'where %s_key=%s'%(n, n, a, n, a, n, a))
+                   'where %s_key=%s' % (n, n, a, n, a, n, a))
             args = (repr(values), timestamp, infoid)
         else:
             sql = 'insert into %ss (%s_key, %s_time, %s_value) '\
-                'values (%s, %s, %s)'%(n, n, n, n, a, a, a)
+                'values (%s, %s, %s)' % (n, n, n, n, a, a, a)
             args = (infoid, timestamp, repr(values))
         c.execute(sql, args)
 
     def list(self):
         c = self.cursor
         n = self.name
-        c.execute('select %s_key from %ss'%(n, n))
+        c.execute('select %s_key from %ss' % (n, n))
         return [res[0] for res in c.fetchall()]
 
     def destroy(self, infoid):
-        self.cursor.execute('delete from %ss where %s_key=%s'%(self.name,
-            self.name, self.db.arg), (infoid,))
+        self.cursor.execute('delete from %ss where %s_key=%s' %
+                            (self.name, self.name, self.db.arg), (infoid,))
 
     def updateTimestamp(self, infoid):
         """ don't update every hit - once a minute should be OK """
         now = time.time()
-        self.cursor.execute('''update %ss set %s_time=%s where %s_key=%s
-            and %s_time < %s'''%(self.name, self.name, self.db.arg,
-            self.name, self.db.arg, self.name, self.db.arg),
-            (now, infoid, now-60))
+        self.cursor.execute('''update %ss set %s_time=%s where %s_key=%s '''
+            '''and %s_time < %s''' %
+                            (self.name, self.name, self.db.arg, self.name,
+                             self.db.arg, self.name, self.db.arg),
+                            (now, infoid, now-60))
 
     def clean(self):
         ''' Remove session records that haven't been used for a week. '''
         now = time.time()
         week = 60*60*24*7
         old = now - week
-        self.cursor.execute('delete from %ss where %s_time < %s'%(self.name,
-            self.name, self.db.arg), (old, ))
+        self.cursor.execute('delete from %ss where %s_time < %s' %
+                            (self.name, self.name, self.db.arg), (old, ))
 
     def commit(self):
-        logger = logging.getLogger('roundup.hyperdb.backend')
-        logger.info('commit %s' % self.name)
+        self.log_info('commit %s' % self.name)
         self.conn.commit()
         self.cursor = self.conn.cursor()
 
@@ -136,9 +139,11 @@ def lifetime(self, item_lifetime=0):
     def close(self):
         self.conn.close()
 
+
 class Sessions(BasicDatabase):
     name = 'session'
 
+
 class OneTimeKeys(BasicDatabase):
     name = 'otk'
 

roundup/backends/sessions_redis.py

@@ -18,14 +18,16 @@
 """
 __docformat__ = 'restructuredtext'
 
-import logging, marshal, redis, time
+import marshal, redis, time
 
 from roundup.anypy.html import html_escape as escape
 
 from roundup.i18n import _
 
+from roundup.backends.sessions_common import SessionCommon
 
-class BasicDatabase:
+
+class BasicDatabase(SessionCommon):
     ''' Provide a nice encapsulation of a redis store.
 
         Keys are id strings, values are automatically marshalled data.
@@ -185,9 +187,9 @@ def set(self, infoid, **newvalues):
                     transaction.execute()
                     break
                 except redis.Exceptions.WatchError:
-                    logging.getLogger('roundup.redis').info(
+                    self.log_info(
                         _('Key %(key)s changed in %(name)s db' %
-                        {"key": escape(infoid), "name": self.name})
+                          {"key": escape(infoid), "name": self.name})
                     )
             else:
                 raise Exception(_("Redis set failed afer 3 retries"))

roundup/backends/sessions_sqlite.py

@@ -11,53 +11,33 @@
 provide a performance speedup.
 """
 __docformat__ = 'restructuredtext'
-import os, time, logging
 
-from roundup.anypy.html import html_escape as escape
-import roundup.backends.sessions_rdbms as rdbms_session
+from roundup.backends import sessions_rdbms
 
-class BasicDatabase(rdbms_session.BasicDatabase):
+
+class BasicDatabase(sessions_rdbms.BasicDatabase):
     ''' Provide a nice encapsulation of an RDBMS table.
 
         Keys are id strings, values are automatically marshalled data.
     '''
     name = None
+
     def __init__(self, db):
         self.db = db
         self.conn, self.cursor = self.db.sql_open_connection(dbname=self.name)
 
-        self.sql('''SELECT name FROM sqlite_master WHERE type='table' AND name='%ss';'''%self.name)
+        self.sql('''SELECT name FROM sqlite_master WHERE type='table' AND '''
+                 '''name='%ss';''' % self.name)
         table_exists = self.cursor.fetchone()
 
         if not table_exists:
             # create table/rows etc.
             self.sql('''CREATE TABLE %(name)ss (%(name)s_key VARCHAR(255),
-            %(name)s_value TEXT, %(name)s_time REAL)'''%{"name":self.name})
-            self.sql('CREATE INDEX %(name)s_key_idx ON %(name)ss(%(name)s_key)'%{"name":self.name})
+            %(name)s_value TEXT, %(name)s_time REAL)''' % {"name": self.name})
+            self.sql('CREATE INDEX %(name)s_key_idx ON '
+                     '%(name)ss(%(name)s_key)' % {"name": self.name})
             self.commit()
 
-    def log_debug(self, msg, *args, **kwargs):
-        """Log a message with level DEBUG."""
-
-        logger = self.get_logger()
-        logger.debug(msg, *args, **kwargs)
-
-    def log_info(self, msg, *args, **kwargs):
-        """Log a message with level INFO."""
-
-        logger = self.get_logger()
-        logger.info(msg, *args, **kwargs)
-
-    def get_logger(self):
-        """Return the logger for this database."""
-
-        # Because getting a logger requires acquiring a lock, we want
-        # to do it only once.
-        if not hasattr(self, '__logger'):
-            self.__logger = logging.getLogger('roundup')
-
-        return self.__logger
-
     def sql(self, sql, args=None, cursor=None):
         """ Execute the sql with the optional args.
         """
@@ -69,9 +49,11 @@ def sql(self, sql, args=None, cursor=None):
         else:
             cursor.execute(sql)
 
+
 class Sessions(BasicDatabase):
     name = 'session'
 
+
 class OneTimeKeys(BasicDatabase):
     name = 'otk'