Avoid OpenERP audittrail bug

Question

I'd like to manage OpenERP user's activity by installing the audittrail module.
After creating some rules ( define which user, which object and which activity (create, update..) will be monitored). I update a product to see it works.
When I've tried to update a product i got the system error. Seeing the log, I get
[2010-08-31 12:53:35,042] Cursor not closed explicitly
[2010-08-31 12:53:35,043] Cursor was created at /home/pilgrim/working/sources/addons/audittrail/audittrail.py:204
Here the line that causes error
cr = pooler.get_db(db).cursor()
Looking at sql_db.py, I get the comment

def __del__(self):
    if not self.__closed:
        # Oops. 'self' has not been closed explicitly.
        # The cursor will be deleted by the garbage collector,
        # but the database connection is not put back into the connection
        # 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()

Since I'm new to Python, I don't know how to overcome this issue?
Any hint to get over this?
Thank

Answer 1

t would be important to see the source code to understand whats going on. But from what you have posted it looks like the previous cursor was not closed explicitly.

cr = sqldb.db_connect(dbname).cursor()
.........
cr.close()
cr = None

I would suggest that you hack audittrail.py to find where ever you are creating the cursor and where ever you close them. A typical issue arises in incorrect handling of exceptions, causing code to jump over normal closure.

Try placing a try, except and finally clause around the questionable cursor operation. That should help you to get around the problem.

Answer 2

Can you run OpenERP in a debugger like the PyDev plug in for Eclipse? I find that the most effective way to track down problems. I haven't used the audit trail module, but I took a quick look at the source code, and it appears that the cursor is being opened near the beginning of log_fct(). (I would have expected it to report line 207, which version are you running?) Here's what I think is the relevant code:

def log_fct(self, db, uid, passwd, object, method, fct_src, *args):
    logged_uids = []
    pool = pooler.get_pool(db)
    cr = pooler.get_db(db).cursor() # line 207 in version 5.0.12

    # ...

    if method in ('create'):

        # ...

        cr.close()
        return res_id

    # ...

    cr.close()

It looks like there are several return statements in the method, but each one seems to call cr.close() first, so I don't see any obvious problems. Try running it in the debugger with a break point in this method. If that's not possible, you can try writing to the log with something like this:

    logger = netsvc.Logger()
    logger.notifyChannel('audittrail', netsvc.LOG_INFO, 'something happened')

Update: You commented that this happens under heavy load. Perhaps an exception is being thrown and the cursor is not being closed. You could use a try ... finally statement to make sure that the cursor is always closed. Here's how the sample above would look after converting it:

def log_fct(self, db, uid, passwd, object, method, fct_src, *args):
    logged_uids = []
    pool = pooler.get_pool(db)
    cr = pooler.get_db(db).cursor() # line 207 in version 5.0.12
    try:

        # ...

        if method in ('create'):

            # ...

            return res_id

        # ...

    finally:
        cr.close()

Answer 3

I think I find the answer. See an example

def a():  
  try:
    print 'before return '
    return 1
  finally:
    print 'in finally'

call a()

before return 
in finally
1

It's normal. OK. Try another example ( code extract from audittrail.py)

def do_something_with_db(db):
   // open cusror again
   cr = db.cursor()
   // do somethign
   // close cursor internally
   cr.close()
def execute(db)
   // 1, open connection and open cursor
   cr = db.cursor
   try:
        //2, do something with db, seeing that this method will open cursor again
       return do_something_with_db(db)
   finally:
       cr.close()

Seeing that the implementation of do_something_with_db trying to open the cursor ( can be called connection) but the current one is not explicitly closed. So the solution is simple: Pass the current cr around

Before
**do_something_with_db(db)**
after
**do_something_with_db(cr)**

Now the error's gone.

@Don Kirkby: Yes, we should experiment with try...finally