CODEWITHSUNDEEP
pythonsqlalchemypyramid
Peter Tirrell
Peter Tirrell

Reputation: 3003

Pyramid exception logging with SQLAlchemy - commands not committing

I am using the Pyramid web framework with SQLAlchemy, connected to a MySQL backend. The app I've put together works, but I'm trying to add some polish by way of some enhanced logging and exception handling.

I based everything off of the basic SQLAlchemy tutorial on the Pyramid site, using the session like so:

DBSession = scoped_session(sessionmaker(extension=ZopeTransactionExtension()))

Using DBSession to query works great, and if I need to add and commit something to the database I'll do something like 

DBSession.add(myobject)
DBSession.flush()

So I get my new ID.

Then I wanted to add logging to the database, so I followed this tutorial. That seemed to work great. I did initially run into some weirdness with things getting committed and I wasn't sure how SQLAlchemy was working so I had changed "transaction.commit()" to "DBSession.flush()" to force the logs to commit (this is addressed below!).

Next I wanted to add custom exception handling with the intent that I could put a friendly error page for anything that wasn't explicitly caught and still log things. So based on this documentation I created error handlers like so:

from pyramid.view import (
    view_config,
    forbidden_view_config,
    notfound_view_config
    )

from pyramid.httpexceptions import (
    HTTPFound,
    HTTPNotFound,
    HTTPForbidden,
    HTTPBadRequest,
    HTTPInternalServerError
    )

from models import DBSession

import transaction
import logging

log = logging.getLogger(__name__)

#region Custom HTTP Errors and Exceptions
@view_config(context=HTTPNotFound, renderer='HTTPNotFound.mako')
def notfound(request):
    log.exception('404 not found: {0}'.format(str(request.url)))
    request.response.status_int = 404
    return {}

@view_config(context=HTTPInternalServerError, renderer='HTTPInternalServerError.mako')
def internalerror(request):
    log.exception('HTTPInternalServerError: {0}'.format(str(request.url)))
    request.response.status_int = 500
    return {}

@view_config(context=Exception, renderer="HTTPExceptionCaught.mako")
def error_view(exc, request):
    log.exception('HTTPException: {0}'.format(str(request.url)))
    log.exception(exc.message)

    return {}
#endregion

So now my problem is, exceptions are caught and my custom exception view comes up as expected. But the exceptions aren't logged to the database. It appears this is because the DBSession transaction is rolled back on any exception. So I changed the logging handler back to "transaction.commit". This had the effect of actually committing my exception logs to the database, BUT now any DBSession action after any log statement throws an "Instance not bound to a session" error...which makes sense because from what I understand after a transaction.commit() the session is cleared out. The console log always shows exactly what I want logged, including the SQL statements to write the log info to the database. But it's not committing on exception unless I use transaction.commit(), but if I do that then I kill any DBSession statements after the transaction.commit()!.

Sooooo....how might I set things up so that I can log to the database, but also catch and successfully log exceptions to the database, too? I feel like I want the logging handler to use some sort of separate database session/connection/instance/something so that it is self-contained but I'm unclear on how that might work.

Or should I architect what I want to do completely different?

EDIT: I did end up going with a separate, log-specific session dedicated only to adding committing log info to the database. This seemed to work well until I started integrating a Pyramid console script into the mix, in which I ran into problems with sessions and database commits within the script not necessarily working like they do in the actual Pyramid web application.

In hindsight (and what I'm doing now) instead of logging to a database I use the standard logging and FileHandlers (TimedRotatingFileHandlers specifically) and log to the file system.

Upvotes: 3

Views: 1113

Answers (1)

Sergey
Sergey

Reputation: 12407

Using transaction.commit() has an unintended side-effect of the changes to other models being committed too, which is not too cool - the idea behind the "normal" Pyramid session setup with ZopeTransactionExtension is that a single session starts at the beginning of the request, then if everything succeeds the session is committed, if there's an exception then everything is rolled back. It would be better to keep this logic and avoid committing things manually in the middle of request.

(as a side note - DBSession.flush() does not commit the transaction, it emits the SQL statements but the transaction can be rolled back later)

For things like exception logs, I would look at setting up a separate Session which is not bound to Pyramid's request/response cycle (without ZopeTransactionExtension) and then using it to create log records. You'd need to commit the transaction manually after adding a log record:

record = Log("blah")
log_session.add(record)
log_session.commit()

Upvotes: 2

Related Questions