openerp/sql_db.py

   1 # -*- coding: utf-8 -*-
   2 ##############################################################################
   3 #
   4 #    OpenERP, Open Source Management Solution
   5 #    Copyright (C) 2004-2009 Tiny SPRL (<http://tiny.be>).
   6 #    Copyright (C) 2010-2011 OpenERP s.a. (<http://openerp.com>).
   7 #
   8 #    This program is free software: you can redistribute it and/or modify
   9 #    it under the terms of the GNU Affero General Public License as
  10 #    published by the Free Software Foundation, either version 3 of the
  11 #    License, or (at your option) any later version.
  12 #
  13 #    This program is distributed in the hope that it will be useful,
  14 #    but WITHOUT ANY WARRANTY; without even the implied warranty of
  15 #    MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  16 #    GNU Affero General Public License for more details.
  17 #
  18 #    You should have received a copy of the GNU Affero General Public License
  19 #    along with this program.  If not, see <http://www.gnu.org/licenses/>.
  20 #
  21 ##############################################################################
  22
  23 #.apidoc title: PostgreSQL interface
  24
  25 """
  26 The PostgreSQL connector is a connectivity layer between the OpenERP code and
  27 the database, *not* a database abstraction toolkit. Database abstraction is what
  28 the ORM does, in fact.
  29
  30 See also: the `pooler` module
  31 """
  32
  33 #.apidoc add-functions: print_stats
  34 #.apidoc add-classes: Cursor Connection ConnectionPool
  35
  36 __all__ = ['db_connect', 'close_db']
  37
  38 from threading import currentThread
  39 import logging
  40 from psycopg2.extensions import ISOLATION_LEVEL_AUTOCOMMIT, ISOLATION_LEVEL_READ_COMMITTED, ISOLATION_LEVEL_SERIALIZABLE
  41 from psycopg2.psycopg1 import cursor as psycopg1cursor
  42 from psycopg2.pool import PoolError
  43
  44 import psycopg2.extensions
  45 import warnings
  46
  47 psycopg2.extensions.register_type(psycopg2.extensions.UNICODE)
  48
  49 types_mapping = {
  50     'date': (1082,),
  51     'time': (1083,),
  52     'datetime': (1114,),
  53 }
  54
  55 def unbuffer(symb, cr):
  56     if symb is None: return None
  57     return str(symb)
  58
  59 def undecimalize(symb, cr):
  60     if symb is None: return None
  61     return float(symb)
  62
  63 for name, typeoid in types_mapping.items():
  64     psycopg2.extensions.register_type(psycopg2.extensions.new_type(typeoid, name, lambda x, cr: x))
  65 psycopg2.extensions.register_type(psycopg2.extensions.new_type((700, 701, 1700,), 'float', undecimalize))
  66
  67
  68 import tools
  69 from tools.func import wraps, frame_codeinfo
  70 from datetime import datetime as mdt
  71 from datetime import timedelta
  72 import threading
  73 from inspect import currentframe
  74
  75 import re
  76 re_from = re.compile('.* from "?([a-zA-Z_0-9]+)"? .*$');
  77 re_into = re.compile('.* into "?([a-zA-Z_0-9]+)"? .*$');
  78
  79 sql_counter = 0
  80
  81 class Cursor(object):
  82     """ Cursor is an open transaction to Postgres, utilizing a TCP connection
  83
  84         A lightweight wrapper around psycopg2's `psycopg1cursor` objects
  85
  86         This is the object behind the `cr` variable used all over the OpenERP
  87         code.
  88     """
  89     IN_MAX = 1000 # decent limit on size of IN queries - guideline = Oracle limit
  90     __logger = None
  91
  92     def check(f):
  93         @wraps(f)
  94         def wrapper(self, *args, **kwargs):
  95             if self.__closed:
  96                 msg = 'Unable to use a closed cursor.'
  97                 if self.__closer:
  98                     msg += ' It was closed at %s, line %s' % self.__closer
  99                 raise psycopg2.OperationalError(msg)
 100             return f(self, *args, **kwargs)
 101         return wrapper
 102
 103     def __init__(self, pool, dbname, serialized=False):
 104         if self.__class__.__logger is None:
 105             self.__class__.__logger = logging.getLogger('db.cursor')
 106         self.sql_from_log = {}
 107         self.sql_into_log = {}
 108
 109         # default log level determined at cursor creation, could be
 110         # overridden later for debugging purposes
 111         self.sql_log = self.__logger.isEnabledFor(logging.DEBUG_SQL)
 112
 113         self.sql_log_count = 0
 114         self.__closed = True    # avoid the call of close() (by __del__) if an exception
 115                                 # is raised by any of the following initialisations
 116         self._pool = pool
 117         self.dbname = dbname
 118         self._serialized = serialized
 119         self._cnx = pool.borrow(dsn(dbname))
 120         self._obj = self._cnx.cursor(cursor_factory=psycopg1cursor)
 121         self.__closed = False   # real initialisation value
 122         self.autocommit(False)
 123         if self.sql_log:
 124             self.__caller = frame_codeinfo(currentframe(),2)
 125         else:
 126             self.__caller = False
 127         self.__closer = False
 128
 129     def __del__(self):
 130         if not self.__closed:
 131             # Oops. 'self' has not been closed explicitly.
 132             # The cursor will be deleted by the garbage collector,
 133             # but the database connection is not put back into the connection
 134             # pool, preventing some operation on the database like dropping it.
 135             # This can also lead to a server overload.
 136             msg = "Cursor not closed explicitly\n"
 137             if self.__caller:
 138                 msg += "Cursor was created at %s:%s" % self.__caller
 139             else:
 140                 msg += "Please enable sql debugging to trace the caller."
 141             self.__logger.warn(msg)
 142             self._close(True)
 143
 144     @check
 145     def execute(self, query, params=None, log_exceptions=True):
 146         if '%d' in query or '%f' in query:
 147             self.__logger.warn(query)
 148             self.__logger.warn("SQL queries cannot contain %d or %f anymore. "
 149                                "Use only %s")
 150
 151         if self.sql_log:
 152             now = mdt.now()
 153
 154         try:
 155             params = params or None
 156             res = self._obj.execute(query, params)
 157         except psycopg2.ProgrammingError, pe:
 158             if log_exceptions:
 159                 self.__logger.error("Programming error: %s, in query %s", pe, query)
 160             raise
 161         except Exception:
 162             if log_exceptions:
 163                 self.__logger.exception("bad query: %s", self._obj.query or query)
 164             raise
 165
 166         if self.sql_log:
 167             delay = mdt.now() - now
 168             delay = delay.seconds * 1E6 + delay.microseconds
 169
 170             self.__logger.log(logging.DEBUG_SQL, "query: %s", self._obj.query)
 171             self.sql_log_count+=1
 172             res_from = re_from.match(query.lower())
 173             if res_from:
 174                 self.sql_from_log.setdefault(res_from.group(1), [0, 0])
 175                 self.sql_from_log[res_from.group(1)][0] += 1
 176                 self.sql_from_log[res_from.group(1)][1] += delay
 177             res_into = re_into.match(query.lower())
 178             if res_into:
 179                 self.sql_into_log.setdefault(res_into.group(1), [0, 0])
 180                 self.sql_into_log[res_into.group(1)][0] += 1
 181                 self.sql_into_log[res_into.group(1)][1] += delay
 182         return res
 183
 184
 185     def split_for_in_conditions(self, ids):
 186         """Split a list of identifiers into one or more smaller tuples
 187            safe for IN conditions, after uniquifying them."""
 188         return tools.misc.split_every(self.IN_MAX, set(ids))
 189
 190     def print_log(self):
 191         global sql_counter
 192         sql_counter += self.sql_log_count
 193         if not self.sql_log:
 194             return
 195         def process(type):
 196             sqllogs = {'from':self.sql_from_log, 'into':self.sql_into_log}
 197             sum = 0
 198             if sqllogs[type]:
 199                 sqllogitems = sqllogs[type].items()
 200                 sqllogitems.sort(key=lambda k: k[1][1])
 201                 self.__logger.log(logging.DEBUG_SQL, "SQL LOG %s:", type)
 202                 sqllogitems.sort(lambda x,y: cmp(x[1][0], y[1][0]))
 203                 for r in sqllogitems:
 204                     delay = timedelta(microseconds=r[1][1])
 205                     self.__logger.log(logging.DEBUG_SQL, "table: %s: %s/%s",
 206                                         r[0], delay, r[1][0])
 207                     sum+= r[1][1]
 208                 sqllogs[type].clear()
 209             sum = timedelta(microseconds=sum)
 210             self.__logger.log(logging.DEBUG_SQL, "SUM %s:%s/%d [%d]",
 211                                 type, sum, self.sql_log_count, sql_counter)
 212             sqllogs[type].clear()
 213         process('from')
 214         process('into')
 215         self.sql_log_count = 0
 216         self.sql_log = False
 217
 218     @check
 219     def close(self):
 220         return self._close(False)
 221
 222     def _close(self, leak=False):
 223         if not self._obj:
 224             return
 225
 226         if self.sql_log:
 227             self.__closer = frame_codeinfo(currentframe(),3)
 228         self.print_log()
 229
 230         if not self._serialized:
 231             self.rollback() # Ensure we close the current transaction.
 232
 233         self._obj.close()
 234
 235         # This force the cursor to be freed, and thus, available again. It is
 236         # important because otherwise we can overload the server very easily
 237         # because of a cursor shortage (because cursors are not garbage
 238         # collected as fast as they should). The problem is probably due in
 239         # part because browse records keep a reference to the cursor.
 240         del self._obj
 241         self.__closed = True
 242
 243         if leak:
 244             self._cnx.leaked = True
 245         else:
 246             keep_in_pool = self.dbname not in ('template1', 'template0', 'postgres')
 247             self._pool.give_back(self._cnx, keep_in_pool=keep_in_pool)
 248
 249     @check
 250     def autocommit(self, on):
 251         offlevel = [ISOLATION_LEVEL_READ_COMMITTED, ISOLATION_LEVEL_SERIALIZABLE][bool(self._serialized)]
 252         self._cnx.set_isolation_level([offlevel, ISOLATION_LEVEL_AUTOCOMMIT][bool(on)])
 253
 254     @check
 255     def commit(self):
 256         """ Perform an SQL `COMMIT`
 257         """
 258         return self._cnx.commit()
 259
 260     @check
 261     def rollback(self):
 262         """ Perform an SQL `ROLLBACK`
 263         """
 264         return self._cnx.rollback()
 265
 266     @check
 267     def __getattr__(self, name):
 268         return getattr(self._obj, name)
 269
 270         """ Set the mode of postgres operations for all cursors
 271         """
 272         """Obtain the mode of postgres operations for all cursors
 273         """
 274
 275 class PsycoConnection(psycopg2.extensions.connection):
 276     pass
 277
 278 class ConnectionPool(object):
 279     """ The pool of connections to database(s)
 280
 281         Keep a set of connections to pg databases open, and reuse them
 282         to open cursors for all transactions.
 283
 284         The connections are *not* automatically closed. Only a close_db()
 285         can trigger that.
 286     """
 287     __logger = logging.getLogger('db.connection_pool')
 288
 289     def locked(fun):
 290         @wraps(fun)
 291         def _locked(self, *args, **kwargs):
 292             self._lock.acquire()
 293             try:
 294                 return fun(self, *args, **kwargs)
 295             finally:
 296                 self._lock.release()
 297         return _locked
 298
 299
 300     def __init__(self, maxconn=64):
 301         self._connections = []
 302         self._maxconn = max(maxconn, 1)
 303         self._lock = threading.Lock()
 304
 305     def __repr__(self):
 306         used = len([1 for c, u in self._connections[:] if u])
 307         count = len(self._connections)
 308         return "ConnectionPool(used=%d/count=%d/max=%d)" % (used, count, self._maxconn)
 309
 310     def _debug(self, msg, *args):
 311         self.__logger.log(logging.DEBUG_SQL, ('%r ' + msg), self, *args)
 312
 313     @locked
 314     def borrow(self, dsn):
 315         self._debug('Borrow connection to %r', dsn)
 316
 317         # free leaked connections
 318         for i, (cnx, _) in tools.reverse_enumerate(self._connections):
 319             if getattr(cnx, 'leaked', False):
 320                 delattr(cnx, 'leaked')
 321                 self._connections.pop(i)
 322                 self._connections.append((cnx, False))
 323                 self.__logger.warn('%r: Free leaked connection to %r', self, cnx.dsn)
 324
 325         for i, (cnx, used) in enumerate(self._connections):
 326             if not used and dsn_are_equals(cnx.dsn, dsn):
 327                 self._connections.pop(i)
 328                 self._connections.append((cnx, True))
 329                 self._debug('Existing connection found at index %d', i)
 330
 331                 return cnx
 332
 333         if len(self._connections) >= self._maxconn:
 334             # try to remove the oldest connection not used
 335             for i, (cnx, used) in enumerate(self._connections):
 336                 if not used:
 337                     self._connections.pop(i)
 338                     self._debug('Removing old connection at index %d: %r', i, cnx.dsn)
 339                     break
 340             else:
 341                 # note: this code is called only if the for loop has completed (no break)
 342                 raise PoolError('The Connection Pool Is Full')
 343
 344         try:
 345             result = psycopg2.connect(dsn=dsn, connection_factory=PsycoConnection)
 346         except psycopg2.Error, e:
 347             self.__logger.exception('Connection to the database failed')
 348             raise
 349         self._connections.append((result, True))
 350         self._debug('Create new connection')
 351         return result
 352
 353     @locked
 354     def give_back(self, connection, keep_in_pool=True):
 355         self._debug('Give back connection to %r', connection.dsn)
 356         for i, (cnx, used) in enumerate(self._connections):
 357             if cnx is connection:
 358                 self._connections.pop(i)
 359                 if keep_in_pool:
 360                     self._connections.append((cnx, False))
 361                     self._debug('Put connection to %r in pool', cnx.dsn)
 362                 else:
 363                     self._debug('Forgot connection to %r', cnx.dsn)
 364                 break
 365         else:
 366             raise PoolError('This connection does not below to the pool')
 367
 368     @locked
 369     def close_all(self, dsn):
 370         self.__logger.info('%r: Close all connections to %r', self, dsn)
 371         for i, (cnx, used) in tools.reverse_enumerate(self._connections):
 372             if dsn_are_equals(cnx.dsn, dsn):
 373                 cnx.close()
 374                 self._connections.pop(i)
 375
 376
 377 class Connection(object):
 378     """ A lightweight instance of a connection to postgres
 379     """
 380     __logger = logging.getLogger('db.connection')
 381
 382     def __init__(self, pool, dbname):
 383         self.dbname = dbname
 384         self._pool = pool
 385
 386     def cursor(self, serialized=False):
 387         cursor_type = serialized and 'serialized ' or ''
 388         self.__logger.log(logging.DEBUG_SQL, 'create %scursor to %r', cursor_type, self.dbname)
 389         return Cursor(self._pool, self.dbname, serialized=serialized)
 390
 391     def serialized_cursor(self):
 392         return self.cursor(True)
 393
 394     def __nonzero__(self):
 395         """Check if connection is possible"""
 396         try:
 397             warnings.warn("You use an expensive function to test a connection.",
 398                       DeprecationWarning, stacklevel=1)
 399             cr = self.cursor()
 400             cr.close()
 401             return True
 402         except Exception:
 403             return False
 404
 405 def dsn(db_name):
 406     _dsn = ''
 407     for p in ('host', 'port', 'user', 'password'):
 408         cfg = tools.config['db_' + p]
 409         if cfg:
 410             _dsn += '%s=%s ' % (p, cfg)
 411
 412     return '%sdbname=%s' % (_dsn, db_name)
 413
 414 def dsn_are_equals(first, second):
 415     def key(dsn):
 416         k = dict(x.split('=', 1) for x in dsn.strip().split())
 417         k.pop('password', None) # password is not relevant
 418         return k
 419     return key(first) == key(second)
 420
 421
 422 _Pool = None
 423
 424 def db_connect(db_name):
 425     global _Pool
 426     if _Pool is None:
 427         _Pool = ConnectionPool(int(tools.config['db_maxconn']))
 428     currentThread().dbname = db_name
 429     return Connection(_Pool, db_name)
 430
 431 def close_db(db_name):
 432     """ You might want to call openerp.netsvc.Agent.cancel(db_name) along this function."""
 433     _Pool.close_all(dsn(db_name))
 434     tools.cache.clean_caches_for_db(db_name)
 435     ct = currentThread()
 436     if hasattr(ct, 'dbname'):
 437         delattr(ct, 'dbname')
 438
 439
 440 # vim:expandtab:smartindent:tabstop=4:softtabstop=4:shiftwidth=4:
 441