Logging issue on "raise httpexceptions.HTTPFound(url)"

[surabujin]

Hi.

If view execute "raise httpexceptions.HTTPFound(url)" the traceback from logging module will appear in console (application started via pserve).

Traceback:

--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.4/logging/__init__.py", line 978, in emit
    msg = self.format(record)
  File "/usr/lib/python3.4/logging/__init__.py", line 828, in format
    return fmt.format(record)
  File "/usr/lib/python3.4/logging/__init__.py", line 573, in format
    record.exc_text = self.formatException(record.exc_info)
  File "/usr/lib/python3.4/logging/__init__.py", line 523, in formatException
    traceback.print_exception(ei[0], ei[1], tb, None, sio)
  File "/usr/lib/python3.4/traceback.py", line 169, in print_exception
    for line in _format_exception_iter(etype, value, tb, limit, chain):
  File "/usr/lib/python3.4/traceback.py", line 146, in _format_exception_iter
    for value, tb in values:
  File "/usr/lib/python3.4/traceback.py", line 125, in _iter_chain
    context = exc.__context__
AttributeError: 'NoneType' object has no attribute '__context__'
Call stack:
  File "/usr/lib/python3.4/threading.py", line 888, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.4/threading.py", line 920, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.4/threading.py", line 868, in run
    self._target(*self._args, **self._kwargs)
  File "/srv/tenpho.com/lib/python3.4/site-packages/waitress-1.0.2-py3.4.egg/waitress/task.py", line 78, in handler_thread
    task.service()
  File "/srv/tenpho.com/lib/python3.4/site-packages/waitress-1.0.2-py3.4.egg/waitress/channel.py", line 338, in service
    task.service()
  File "/srv/tenpho.com/lib/python3.4/site-packages/waitress-1.0.2-py3.4.egg/waitress/task.py", line 169, in service
    self.execute()
  File "/srv/tenpho.com/lib/python3.4/site-packages/waitress-1.0.2-py3.4.egg/waitress/task.py", line 399, in execute
    app_iter = self.channel.server.application(env, start_response)
  File "/srv/tenpho.com/lib/python3.4/site-packages/pyramid-1.9-py3.4.egg/pyramid/router.py", line 270, in __call__
    response = self.execution_policy(environ, self)
  File "/srv/tenpho.com/lib/python3.4/site-packages/pyramid-1.9-py3.4.egg/pyramid/router.py", line 276, in default_execution_policy
    return router.invoke_request(request)
  File "/srv/tenpho.com/lib/python3.4/site-packages/pyramid-1.9-py3.4.egg/pyramid/router.py", line 249, in invoke_request
    response = handle_request(request)
  File "/home/tenpho/tenpho.com/repo/TenPho/tenpho/lib/web.py", line 35, in __call__
    return self.following(request)
  File "/srv/tenpho.com/lib/python3.4/site-packages/pyramid_debugtoolbar-4.2-py3.4.egg/pyramid_debugtoolbar/toolbar.py", line 255, in toolbar_tween
    _logger.exception(exc_msg, exc_info=request.exc_info)
Message: 'Squashed Exception at http://local.dev.tenpho.com:4080/fotografyi/change-pass\ntraceback url: http://local.dev.tenpho.com:4080/_debug_toolbar/313430303634333836393034393736/exception'
Arguments: ()

Looks like issue lies in incorrect(at least for python3.4) call logging.exception. pyramid_debugtoolbar pass exc_info tuple into logging.exception method.

            response = _handler(request)
            toolbar.status_int = response.status_int

            if request.exc_info and intercept_exc:
                toolbar.traceback = process_traceback(request.exc_info)

                msg = 'Squashed Exception at %s\ntraceback url: %s'
                subrequest = make_subrequest(
                    request, root_path, request.pdtb_id + '/exception')
                exc_msg = msg % (request.url, subrequest.url)
                _logger.exception(exc_msg, exc_info=request.exc_info)

But if you take a look on this method:

1215 #---------------------------------------------------------------------------
1216 #   Logger classes and functions
1217 #---------------------------------------------------------------------------
1218
1219 class Logger(Filterer):

# ...

1305     def exception(self, msg, *args, **kwargs):
1306         """
1307         Convenience method for logging an ERROR with exception information.
1308         """
1309         kwargs['exc_info'] = True
1310         self.error(msg, *args, **kwargs)

you will see, that exc_info is replaces with "True".

Environment:
$ python --version
Python 3.4.3
pyramid_debugtoolbar > 4.0.1

PS Despite logging.exception issue - do we really need to catch/report raises of redirect exceptions?

[digitalresistor]

We don't recommend raising HTTPFound unless it truly is an exception, instead the recommendation is to simply return it from your view code. This way if you are using pyramid_tm or anything along those lines everything will get committed as normal.

That being said, this is still a bug in the debugtoolbar and we will look at it.

[mmerickel]

I agree with everything @bertjwregeer said about this issue.

[surabujin]

"We don't recommend raising HTTPFound" who is "we" in this sentence?

According to pyramid documentation HTTPFound can be returned from view or can be raised: https://docs.pylonsproject.org/projects/pyramid/en/latest/narr/views.html#using-a-view-callable-to-do-an-http-redirect

I prefer to raise exception objects, not return them... because they are exceptions (they are located in httpexceptions module). And I don't use pyramid_tm(I have my own transaction manager, capable to distinguish "redirect" exceptions and commit transaction if they are raised).

[mmerickel]

"We don't recommend raising HTTPFound" who is "we" in this sentence?

Well I mean we are both core Pyramid developers and I personally maintain pyramid_tm, pyramid_debugtoolbar, pyramid_retry, and quite a few others - so it's not like it's random advice.

And I don't use pyramid_tm(I have my own transaction manager, capable to distinguish "redirect" exceptions and commit transaction if they are raised).

To be clear pyramid_tm is capable of distinguishing between a raised HTTPException errors and redirects if you define a commit_veto hook. edit: Or rather, it will in its next release. ;-)

No one is saying you can't raise them, and the core docs themselves tend to stay away from opinions on third party libraries like pyramid_tm, but in general we do recommend returning them due to issues with raising in "non error conditions" like the fact that pyramid_tm will, by default, abort your transaction.

[surabujin]

"We don't recommend raising HTTPFound" who is "we" in this sentence?

Well I mean we are both core Pyramid developers and I personally maintain pyramid_tm,
pyramid_debugtoolbar, pyramid_retry, and quite a few others - so it's not like it's random advice.

I have never thought that it was "random advice". I just tried to understand it more detailed. Because pyramid docs told about ability to raise "redirect exceptions" and ... they are exceptions.

Maybe pyramid docs should be updated. Explaining possible drawback from raising "redirects" instead of returning them.

And I don't use pyramid_tm(I have my own transaction manager, capable to distinguish "redirect"
exceptions and commit transaction if they are raised).

To be clear pyramid_tm is capable of distinguishing between a raised HTTPException errors and
redirects if you define a commit_veto hook. edit: Or rather, it will in its next release. ;-)

I am using my own transaction manager, because or requirement to handle more than 1 DB connection at a time. Maybe pyramid_tm is capable to do it now. And maybe I should give it one more chance.

[mmerickel]

Maybe pyramid docs should be updated. Explaining possible drawback from raising "redirects" instead of returning them.

It's certainly possible - I'd be happy to review any pull requests to that effect. It's a classic example of "you can" but "should you?" is always a question of how the rest of your system is setup and it's hard to deal with all of those scenarios.

I am using my own transaction manager, because or requirement to handle more than 1 DB connection at a time. Maybe pyramid_tm is capable to do it now. And maybe I should give it one more chance.

Yes the pyramid_tm tween is a generic wrapper around an in-memory transaction manager.. it does not define any data backends (such as your RDBMS or message queue etc). It allows many / arbitrary data mangers to hook into it and the manager will coordinate talking to them to perform a commit / abort. It can do this is a two-phase manner. See https://zodb.readthedocs.io/en/latest/transactions.html and https://transaction.readthedocs.io/en/latest/ for some information about that.

[mmerickel]

I just pushed a fix in #320... further investigation shows this bug was only on Python < 3.5.

[mmerickel]

@surabujin Just thought I'd let you know that I released pyramid_tm 2.2 and if you set the tm.commit_veto = pyramid_tm.default_commit_veto then things will work as you expect... raising HTTPFound (a 3xx) will not abort and returning (or raising) HTTPBadRequest (a 4xx) will abort the transaction. You can also set response.headers['x-tm'] = 'commit' (or abort) to force a particular error to commit (or abort) from the response object itself in an exception view or elsewhere.