translate: port to pythonic logging, filename in a message
[odoo/odoo.git] / bin / sql_db.py
index 2cc7140..cdc3d0d 100644 (file)
@@ -1,6 +1,6 @@
 # -*- coding: utf-8 -*-
 ##############################################################################
-#    
+#
 #    OpenERP, Open Source Management Solution
 #    Copyright (C) 2004-2009 Tiny SPRL (<http://tiny.be>).
 #
 #    GNU Affero General Public License for more details.
 #
 #    You should have received a copy of the GNU Affero General Public License
-#    along with this program.  If not, see <http://www.gnu.org/licenses/>.     
+#    along with this program.  If not, see <http://www.gnu.org/licenses/>.
 #
 ##############################################################################
 
 __all__ = ['db_connect', 'close_db']
 
-import netsvc
+from threading import currentThread
+import logging
 from psycopg2.extensions import ISOLATION_LEVEL_AUTOCOMMIT, ISOLATION_LEVEL_READ_COMMITTED, ISOLATION_LEVEL_SERIALIZABLE
 from psycopg2.psycopg1 import cursor as psycopg1cursor
 from psycopg2.pool import PoolError
@@ -50,25 +51,21 @@ psycopg2.extensions.register_type(psycopg2.extensions.new_type((700, 701, 1700,)
 
 
 import tools
-from tools.func import wraps
+from tools.func import wraps, frame_codeinfo
 from datetime import datetime as mdt
 from datetime import timedelta
 import threading
-from inspect import stack
+from inspect import currentframe
 
 import re
 re_from = re.compile('.* from "?([a-zA-Z_0-9]+)"? .*$');
 re_into = re.compile('.* into "?([a-zA-Z_0-9]+)"? .*$');
 
-
-def log(msg, lvl=netsvc.LOG_DEBUG2):
-    logger = netsvc.Logger()
-    logger.notifyChannel('sql', lvl, msg)
-
 sql_counter = 0
 
 class Cursor(object):
-    IN_MAX = 1000
+    IN_MAX = 1000 # decent limit on size of IN queries - guideline = Oracle limit
+    __logger = logging.getLogger('db.cursor')
 
     def check(f):
         @wraps(f)
@@ -81,7 +78,11 @@ class Cursor(object):
     def __init__(self, pool, dbname, serialized=False):
         self.sql_from_log = {}
         self.sql_into_log = {}
-        self.sql_log = False
+
+        # default log level determined at cursor creation, could be
+        # overridden later for debugging purposes
+        self.sql_log = self.__logger.isEnabledFor(logging.DEBUG_SQL)
+
         self.sql_log_count = 0
         self.__closed = True    # avoid the call of close() (by __del__) if an exception
                                 # is raised by any of the following initialisations
@@ -92,7 +93,7 @@ class Cursor(object):
         self._obj = self._cnx.cursor(cursor_factory=psycopg1cursor)
         self.__closed = False   # real initialisation value
         self.autocommit(False)
-        self.__caller = tuple(stack()[2][1:3])
+        self.__caller = frame_codeinfo(currentframe(),2)
 
     def __del__(self):
         if not self.__closed:
@@ -102,17 +103,16 @@ class Cursor(object):
             # pool, preventing some operation on the database like dropping it.
             # This can also lead to a server overload.
             msg = "Cursor not closed explicitly\n"  \
-                  "Cursor was created at %s:%s" % self.__caller
-            log(msg, netsvc.LOG_WARNING)
-            self.close()
+                  "Cursor was created at %s:%s"
+            self.__logger.warn(msg, *self.__caller)
+            self._close(True)
 
     @check
-    def execute(self, query, params=None):
+    def execute(self, query, params=None, log_exceptions=True):
         if '%d' in query or '%f' in query:
-            log(query, netsvc.LOG_WARNING)
-            log("SQL queries cannot contain %d or %f anymore. Use only %s", netsvc.LOG_WARNING)
-            if params:
-                query = query.replace('%d', '%s').replace('%f', '%s')
+            self.__logger.warn(query)
+            self.__logger.warn("SQL queries cannot contain %d or %f anymore. "
+                               "Use only %s")
 
         if self.sql_log:
             now = mdt.now()
@@ -121,19 +121,19 @@ class Cursor(object):
             params = params or None
             res = self._obj.execute(query, params)
         except psycopg2.ProgrammingError, pe:
-            logger= netsvc.Logger()
-            logger.notifyChannel('sql_db', netsvc.LOG_ERROR, "Programming error: %s, in query %s" % (pe, query))
+            if log_exceptions or self.sql_log:
+                self.__logger.error("Programming error: %s, in query %s", pe, query)
             raise
-        except Exception, e:
-            log("bad query: %s" % self._obj.query)
-            log(e)
+        except Exception:
+            if log_exceptions or self.sql_log:
+                self.__logger.exception("bad query: %s", self._obj.query or query)
             raise
 
         if self.sql_log:
             delay = mdt.now() - now
             delay = delay.seconds * 1E6 + delay.microseconds
 
-            log("query: %s" % self._obj.query)
+            self.__logger.log(logging.DEBUG_SQL, "query: %s", self._obj.query)
             self.sql_log_count+=1
             res_from = re_from.match(query.lower())
             if res_from:
@@ -147,6 +147,12 @@ class Cursor(object):
                 self.sql_into_log[res_into.group(1)][1] += delay
         return res
 
+
+    def split_for_in_conditions(self, ids):
+        """Split a list of identifiers into one or more smaller tuples
+           safe for IN conditions, after uniquifying them."""
+        return tools.misc.split_every(self.IN_MAX, set(ids))
+
     def print_log(self):
         global sql_counter
         sql_counter += self.sql_log_count
@@ -158,14 +164,17 @@ class Cursor(object):
             if sqllogs[type]:
                 sqllogitems = sqllogs[type].items()
                 sqllogitems.sort(key=lambda k: k[1][1])
-                log("SQL LOG %s:" % (type,))
+                self.__logger.log(logging.DEBUG_SQL, "SQL LOG %s:", type)
+                sqllogitems.sort(lambda x,y: cmp(x[1][0], y[1][0]))
                 for r in sqllogitems:
                     delay = timedelta(microseconds=r[1][1])
-                    log("table: %s: %s/%s" %(r[0], str(delay), r[1][0]))
+                    self.__logger.log(logging.DEBUG_SQL, "table: %s: %s/%s",
+                                        r[0], delay, r[1][0])
                     sum+= r[1][1]
                 sqllogs[type].clear()
             sum = timedelta(microseconds=sum)
-            log("SUM %s:%s/%d [%d]" % (type, str(sum), self.sql_log_count, sql_counter))
+            self.__logger.log(logging.DEBUG_SQL, "SUM %s:%s/%d [%d]",
+                                type, sum, self.sql_log_count, sql_counter)
             sqllogs[type].clear()
         process('from')
         process('into')
@@ -174,6 +183,9 @@ class Cursor(object):
 
     @check
     def close(self):
+        return self._close(False)
+
+    def _close(self, leak=False):
         if not self._obj:
             return
 
@@ -191,7 +203,12 @@ class Cursor(object):
         # part because browse records keep a reference to the cursor.
         del self._obj
         self.__closed = True
-        self._pool.give_back(self._cnx)
+
+        if leak:
+            self._cnx.leaked = True
+        else:
+            keep_in_pool = self.dbname not in ('template1', 'template0', 'postgres')
+            self._pool.give_back(self._cnx, keep_in_pool=keep_in_pool)
 
     @check
     def autocommit(self, on):
@@ -211,8 +228,13 @@ class Cursor(object):
         return getattr(self._obj, name)
 
 
+class PsycoConnection(psycopg2.extensions.connection):
+    pass
+
 class ConnectionPool(object):
 
+    __logger = logging.getLogger('db.connection_pool')
+
     def locked(fun):
         @wraps(fun)
         def _locked(self, *args, **kwargs):
@@ -228,64 +250,69 @@ class ConnectionPool(object):
         self._connections = []
         self._maxconn = max(maxconn, 1)
         self._lock = threading.Lock()
-        self._logger = netsvc.Logger()
 
     def __repr__(self):
         used = len([1 for c, u in self._connections[:] if u])
         count = len(self._connections)
         return "ConnectionPool(used=%d/count=%d/max=%d)" % (used, count, self._maxconn)
 
-    def _debug(self, msg):
-        self._logger.notifyChannel('ConnectionPool', netsvc.LOG_DEBUG, repr(self))
-        self._logger.notifyChannel('ConnectionPool', netsvc.LOG_DEBUG, msg)
+    def _debug(self, msg, *args):
+        self.__logger.log(logging.DEBUG_SQL, ('%r ' + msg), self, *args)
 
     @locked
     def borrow(self, dsn):
-        self._debug('Borrow connection to %s' % (dsn,))
+        self._debug('Borrow connection to %r', dsn)
+
+        # free leaked connections
+        for i, (cnx, _) in tools.reverse_enumerate(self._connections):
+            if getattr(cnx, 'leaked', False):
+                delattr(cnx, 'leaked')
+                self._connections.pop(i)
+                self._connections.append((cnx, False))
+                self.__logger.warn('%r: Free leaked connection to %r', self, cnx.dsn)
 
-        result = None
         for i, (cnx, used) in enumerate(self._connections):
             if not used and dsn_are_equals(cnx.dsn, dsn):
-                self._debug('Existing connection found at index %d' % i)
-
                 self._connections.pop(i)
                 self._connections.append((cnx, True))
+                self._debug('Existing connection found at index %d', i)
 
-                result = cnx
-                break
-        if result:
-            return result
+                return cnx
 
         if len(self._connections) >= self._maxconn:
             # try to remove the oldest connection not used
             for i, (cnx, used) in enumerate(self._connections):
                 if not used:
-                    self._debug('Removing old connection at index %d: %s' % (i, cnx.dsn))
                     self._connections.pop(i)
+                    self._debug('Removing old connection at index %d: %r', i, cnx.dsn)
                     break
             else:
                 # note: this code is called only if the for loop has completed (no break)
                 raise PoolError('The Connection Pool Is Full')
 
-        self._debug('Create new connection')
-        result = psycopg2.connect(dsn=dsn)
+        result = psycopg2.connect(dsn=dsn, connection_factory=PsycoConnection)
         self._connections.append((result, True))
+        self._debug('Create new connection')
         return result
 
     @locked
-    def give_back(self, connection):
-        self._debug('Give back connection to %s' % (connection.dsn,))
+    def give_back(self, connection, keep_in_pool=True):
+        self._debug('Give back connection to %r', connection.dsn)
         for i, (cnx, used) in enumerate(self._connections):
             if cnx is connection:
                 self._connections.pop(i)
-                self._connections.append((cnx, False))
+                if keep_in_pool:
+                    self._connections.append((cnx, False))
+                    self._debug('Put connection to %r in pool', cnx.dsn)
+                else:
+                    self._debug('Forgot connection to %r', cnx.dsn)
                 break
         else:
             raise PoolError('This connection does not below to the pool')
 
     @locked
     def close_all(self, dsn):
-        self._debug('Close all connections to %s' % (dsn,))
+        self.__logger.info('%r: Close all connections to %r', self, dsn)
         for i, (cnx, used) in tools.reverse_enumerate(self._connections):
             if dsn_are_equals(cnx.dsn, dsn):
                 cnx.close()
@@ -293,17 +320,15 @@ class ConnectionPool(object):
 
 
 class Connection(object):
-    def _debug(self, msg):
-        self._logger.notifyChannel('Connection', netsvc.LOG_DEBUG, msg)
+    __logger = logging.getLogger('db.connection')
 
     def __init__(self, pool, dbname):
         self.dbname = dbname
         self._pool = pool
-        self._logger = netsvc.Logger()
 
     def cursor(self, serialized=False):
         cursor_type = serialized and 'serialized ' or ''
-        self._debug('create %scursor to "%s"' % (cursor_type, self.dbname,))
+        self.__logger.log(logging.DEBUG_SQL, 'create %scursor to %r', cursor_type, self.dbname)
         return Cursor(self._pool, self.dbname, serialized=serialized)
 
     def serialized_cursor(self):
@@ -339,11 +364,15 @@ def dsn_are_equals(first, second):
 _Pool = ConnectionPool(int(tools.config['db_maxconn']))
 
 def db_connect(db_name):
+    currentThread().dbname = db_name
     return Connection(_Pool, db_name)
 
 def close_db(db_name):
     _Pool.close_all(dsn(db_name))
     tools.cache.clean_caches_for_db(db_name)
+    ct = currentThread()
+    if hasattr(ct, 'dbname'):
+        delattr(ct, 'dbname')
 
 
 # vim:expandtab:smartindent:tabstop=4:softtabstop=4:shiftwidth=4: