Improve logging in SQLAlchemy

[Former user]

Here is a small patch for SQLAlchemy which improves the logging capabilities, including the connection id, a timestamp, and the engine passing the logger to the Pool class in order to get all logging into the same file, if using SQLAlchemy on a daemon process.

Index: sqlalchemy/pool.py

--- sqlalchemy/pool.py (revisión: 1041) +++ sqlalchemy/pool.py (copia de trabajo) @@ -10,13 +10,16 @@ be managed automatically, based on module type and connect arguments, simply by calling regular DBAPI connect() methods."""

-import Queue, weakref, string, cPickle +import sys, Queue, weakref, string, cPickle

try: import thread except: import dummythread as thread

+import util + + proxies = {}

def manage(module, **params): @@ -69,10 +72,11 @@

class Pool(object): - def init(self, echo = False, use_threadlocal = True): + def init(self, echo = False, use_threadlocal = True, logger = None): self._threadconns = weakref.WeakValueDictionary() self._use_threadlocal = use_threadlocal self._echo = echo + self._logger = logger or sys.stdout

 def connect(self):
     if not self._use_threadlocal:

@@ -115,7 +119,7 @@ raise NotImplementedError()

 def log(self, msg):

• print msg
• util.log(self._logger, msg, 'Pool')

class ConnectionFairy(object): def init(self, pool): Index: sqlalchemy/util.py =================================================================== --- sqlalchemy/util.py (revisión: 1041) +++ sqlalchemy/util.py (copia de trabajo) @@ -5,7 +5,7 @@ # the MIT License: http://www.opensource.org/licenses/mit-license.php

all = 'OrderedDict', 'generic_repr', 'HashSet', 'AttrProp' -import thread, weakref, UserList,string, inspect +import thread, threading, weakref, UserList, time, string, inspect from exceptions import *

def to_list(x): @@ -23,7 +23,7 @@ return HashSet(to_list(x)) else: return x - +
class AttrProp(object): """a quick way to stick a property accessor on an object""" def init(self, key): @@ -447,4 +447,23 @@ raise AssertionError("instance has no attribute '%s'" % arg)

 return newparams

• \ Sin fin-de-l¡nea al final del archivo + + +def log(logger, message, origin, timestamp=True):
• "Writes a log message into the logger"
• try:
• logwrite = logger.write
• except AttributeError:
• return +
• if timestamp:
• t = time.time()
• ms = (t - long(t)) * 1000
• timestamp = time.strftime("%Y-%m-%d %H:%M:%S", time.localtime(t))
• timestamp = "%s,%03d" % (timestamp, ms)
• else:
• timestamp = ""
• threadname = threading.currentThread().getName()
• threadname = threadname + ' '*(8-len(threadname))
• logwrite('%(timestamp)s %(origin)-8s/%(threadname)s: %(message)s\n' % locals()) + Index: sqlalchemy/engine.py =================================================================== --- sqlalchemy/engine.py (revisión: 1041) +++ sqlalchemy/engine.py (copia de trabajo) @@ -174,6 +174,7 @@ (cargs, cparams) = self.connect_args() if pool is None: params'echo' = echo_pool
• params'logger' = logger self._pool = sqlalchemy.pool.manage(self.dbapi(), params).get_pool(*cargs, cparams) else: self._pool = pool @@ -184,10 +185,7 @@ self.tables = {} self._ischema = None self._figure_paramstyle()
• if logger is None:
• self.logger = sys.stdout
• else:
• self.logger = logger

• self.logger = logger or sys.stdout

  def _get_ischema(self): # We use a property for ischema so that the accessor @@ -523,7 +521,7 @@ else: parameters = parameters.values()

• self.execute(statement, parameters, connection=connection, cursor=cursor, return_raw=True)

• self.execute(statement, parameters, connection=connection, cursor=cursor, return_raw=True) return cursor

   self.pre_exec(proxy, compiled, parameters, **kwargs)
  

  @@ -572,15 +570,19 @@

   try:
       if echo is True or self.echo is not False:
  

  • self.log(statement)
  • self.log(repr(parameters))
  • self.log(connection, statement)
  • self.log(connection, repr(parameters)) if parameters is not None and isinstance(parameters, list) and len(parameters) > 0 and (isinstance(parameters0, list) or isinstance(parameters0, dict)):
  • self.log(connection, 'ExecuteMany') self._executemany(cursor, statement, parameters) else:
  • self.log(connection, 'Execute') self._execute(cursor, statement, parameters) if self.context.transaction is None:
  • self.log(connection, 'COMMIT') self.do_commit(connection) except:
  • self.log(connection, 'ROLLBACK') self.do_rollback(connection) raise if return_raw: @@ -598,9 +600,9 @@ c.executemany(statement, parameters) self.context.rowcount = c.rowcount

• def log(self, msg):

• def log(self, connection, msg): """logs a message using this SQLEngine's logger stream."""
• self.logger.write(msg + "\n")
• return util.log(self.logger, msg, '0x%x' % id(connection))

class ResultProxy:

[Former user]

Patch against revision 1041

[Mike Bayer]

1084 commits a degree of this functionality via a util.Logger object which can be configured or replaced upon sending a new one to engine/pool. that way you can tailor if you want the timestamps, threadnames (which I usually dont). not sure what you gain by the id of the connection entry and it takes up too much room on my console...would rather keep it simple.

[Mike Bayer]

though this solution is hardly better than just the print statments we already had; a real logging solution here would require a lot more thought than this, including registration/filtering of areas for logging (i.e. engine, unit of work, pool), log levels, probably usage of the python logging module to wrap it all together.

[Mike Bayer]

really should use a stock logging package like logging

[Mike Bayer]

logging implemented via python logging module in changeset:1895