pyramid_debugtoolbar icon indicating copy to clipboard operation
pyramid_debugtoolbar copied to clipboard

exception traceback with pyramid-debugtoolbar==2.0.2

Open tisdall opened this issue 11 years ago • 13 comments

on a GET /_debug_toolbar/31343xxxxxxxx38:

Traceback (most recent call last):
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid-1.4.5-py3.3.egg/pyramid/router.py", line 251, in __call__
    response = self.invoke_subrequest(request, use_tweens=True)
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid-1.4.5-py3.3.egg/pyramid/router.py", line 227, in invoke_subrequest
    response = handle_request(request)
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid_debugtoolbar/toolbar.py", line 160, in toolbar_tween
    return handler(request)
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid-1.4.5-py3.3.egg/pyramid/tweens.py", line 21, in excview_tween
    response = handler(request)
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid_tm-0.7-py3.3.egg/pyramid_tm/__init__.py", line 82, in tm_tween
    reraise(*exc_info)
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid_tm-0.7-py3.3.egg/pyramid_tm/compat.py", line 13, in reraise
    raise value
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid_tm-0.7-py3.3.egg/pyramid_tm/__init__.py", line 63, in tm_tween
    response = handler(request)
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid-1.4.5-py3.3.egg/pyramid/router.py", line 161, in handle_request
    response = view_callable(context, request)
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid-1.4.5-py3.3.egg/pyramid/config/views.py", line 237, in _secured_view
    return view(context, request)
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid-1.4.5-py3.3.egg/pyramid/config/views.py", line 377, in viewresult_to_response
    result = view(context, request)
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid-1.4.5-py3.3.egg/pyramid/wsgi.py", line 73, in decorator
    return call_app_with_subpath_as_path_info(request, wrapped)
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid-1.4.5-py3.3.egg/pyramid/request.py", line 461, in call_app_with_subpath_as_path_info
    return new_request.get_response(app)
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/WebOb-1.3.1-py3.3.egg/webob/request.py", line 1320, in send
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/WebOb-1.3.1-py3.3.egg/webob/request.py", line 1284, in call_application
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid-1.4.5-py3.3.egg/pyramid/router.py", line 251, in __call__
    response = self.invoke_subrequest(request, use_tweens=True)
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid-1.4.5-py3.3.egg/pyramid/router.py", line 227, in invoke_subrequest
    response = handle_request(request)
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid-1.4.5-py3.3.egg/pyramid/tweens.py", line 21, in excview_tween
    response = handler(request)
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid-1.4.5-py3.3.egg/pyramid/router.py", line 161, in handle_request
    response = view_callable(context, request)
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid-1.4.5-py3.3.egg/pyramid/config/views.py", line 377, in viewresult_to_response
    result = view(context, request)
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid-1.4.5-py3.3.egg/pyramid/config/views.py", line 493, in _requestonly_view
    response = view(request)
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid_debugtoolbar/views.py", line 264, in sse
    for _id,toolbar in history.last(10)]
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid_debugtoolbar/views.py", line 264, in <listcomp>
    for _id,toolbar in history.last(10)]
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/pyramid_debugtoolbar/toolbar.py", line 62, in json
    'path': self.request.path,
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/WebOb-1.3.1-py3.3.egg/webob/request.py", line 486, in path
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/WebOb-1.3.1-py3.3.egg/webob/descriptors.py", line 68, in fget
  File "/sites/metrics_dev/env/lib/python3.3/site-packages/WebOb-1.3.1-py3.3.egg/webob/request.py", line 159, in encget
KeyError: 'PATH_INFO'

pertinent entries from pip freeze:

pyramid==1.4.5
pyramid-debugtoolbar==2.0.2
pyramid-tm==0.7
WebOb==1.3.1
Mako==0.9.1
Pygments==1.6
repoze.lru==0.6

tisdall avatar Mar 04 '14 20:03 tisdall

@tisdall I'm not clear about what else you may have done to generate this traceback. How did you run your app? It looks like either you are missing an environment variable or something in your stack is not passing it through.

stevepiercy avatar Apr 19 '14 14:04 stevepiercy

I'm running with uwsgi behind nginx. My nginx config seems to be set up correctly to pass PATH_INFO along. I'm only seeing this issue with the debugtoolbar and not my regular program.

I've since upgraded the following packages with no change in the result:

pyramid==1.5
pyramid-debugtoolbar==2.1
WebOb==1.4

and here's the latest log information:

[pid: 8870|app: 0|req: 6/13] 130.63.114.112 () {40 vars in 1257 bytes} [Thu May 22 19:23:07 2014] GET /_debug_toolbar/313430343933393039353837383936 => generated 152 bytes in 2 msecs (HTTP/1.1 404) 2 headers in 87 bytes (1 switches on core 5)
[pid: 8870|app: 0|req: 7/14] 130.63.114.112 () {42 vars in 1288 bytes} [Thu May 22 19:23:10 2014] GET /_debug_toolbar/313430343933393039353837383936 => generated 152 bytes in 2 msecs (HTTP/1.1 404) 2 headers in 87 bytes (1 switches on core 1)
[pid: 8870|app: 0|req: 8/15] 130.63.114.112 () {42 vars in 1288 bytes} [Thu May 22 19:23:11 2014] GET /_debug_toolbar/313430343933393039353837383936 => generated 152 bytes in 1 msecs (HTTP/1.1 404) 2 headers in 87 bytes (1 switches on core 19)
[pid: 8870|app: 0|req: 9/16] 130.63.114.112 () {42 vars in 1288 bytes} [Thu May 22 19:23:12 2014] GET /_debug_toolbar/313430343933393039353837383936 => generated 152 bytes in 1 msecs (HTTP/1.1 404) 2 headers in 87 bytes (1 switches on core 16)
[pid: 8870|app: 0|req: 10/17] 130.63.114.112 () {42 vars in 1288 bytes} [Thu May 22 19:23:13 2014] GET /_debug_toolbar/313430343933393039353837383936 => generated 152 bytes in 2 msecs (HTTP/1.1 404) 2 headers in 87 bytes (1 switches on core 14)
[pid: 8870|app: 0|req: 11/18] 130.63.114.112 () {42 vars in 1288 bytes} [Thu May 22 19:23:14 2014] GET /_debug_toolbar/313430343933393039353837383936 => generated 152 bytes in 1 msecs (HTTP/1.1 404) 2 headers in 87 bytes (1 switches on core 12)
[pid: 8850|app: 0|req: 8/19] 130.63.114.112 () {42 vars in 1288 bytes} [Thu May 22 19:23:14 2014] GET /_debug_toolbar/313430343933393039353837383936 => generated 271097 bytes in 54 msecs (HTTP/1.1 200) 2 headers in 83 bytes (2 switches on core 7)
[pid: 8870|app: 0|req: 12/20] 130.63.114.112 () {42 vars in 1274 bytes} [Thu May 22 19:23:15 2014] GET /_debug_toolbar/sse?request_id=313430343933393039353837383936 => generated 0 bytes in 1 msecs (HTTP/1.1 200) 2 headers in 86 bytes (2 switches on core 10)
Traceback (most recent call last):
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid-1.5-py3.4.egg/pyramid/router.py", line 242, in __call__
    response = self.invoke_subrequest(request, use_tweens=True)
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid-1.5-py3.4.egg/pyramid/router.py", line 217, in invoke_subrequest
    response = handle_request(request)
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid_debugtoolbar/toolbar.py", line 165, in toolbar_tween
    return handler(request)
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid-1.5-py3.4.egg/pyramid/tweens.py", line 21, in excview_tween
    response = handler(request)
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid_tm-0.7-py3.4.egg/pyramid_tm/__init__.py", line 82, in tm_tween
    reraise(*exc_info)
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid_tm-0.7-py3.4.egg/pyramid_tm/compat.py", line 13, in reraise
    raise value
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid_tm-0.7-py3.4.egg/pyramid_tm/__init__.py", line 63, in tm_tween
    response = handler(request)
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid-1.5-py3.4.egg/pyramid/router.py", line 163, in handle_request
    response = view_callable(context, request)
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid-1.5-py3.4.egg/pyramid/config/views.py", line 385, in viewresult_to_response
    result = view(context, request)
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid-1.5-py3.4.egg/pyramid/wsgi.py", line 73, in decorator
    return call_app_with_subpath_as_path_info(request, wrapped)
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid-1.5-py3.4.egg/pyramid/request.py", line 311, in call_app_with_subpath_as_path_info
    return new_request.get_response(app)
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/WebOb-1.4-py3.4.egg/webob/request.py", line 1320, in send
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/WebOb-1.4-py3.4.egg/webob/request.py", line 1284, in call_application
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid-1.5-py3.4.egg/pyramid/router.py", line 242, in __call__
    response = self.invoke_subrequest(request, use_tweens=True)
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid-1.5-py3.4.egg/pyramid/router.py", line 217, in invoke_subrequest
    response = handle_request(request)
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid-1.5-py3.4.egg/pyramid/tweens.py", line 21, in excview_tween
    response = handler(request)
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid-1.5-py3.4.egg/pyramid/router.py", line 163, in handle_request
    response = view_callable(context, request)
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid-1.5-py3.4.egg/pyramid/config/views.py", line 385, in viewresult_to_response
    result = view(context, request)
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid-1.5-py3.4.egg/pyramid/config/views.py", line 501, in _requestonly_view
    response = view(request)
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid_debugtoolbar/views.py", line 264, in sse
    for _id,toolbar in history.last(10)]
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid_debugtoolbar/views.py", line 264, in <listcomp>
    for _id,toolbar in history.last(10)]
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/pyramid_debugtoolbar/toolbar.py", line 62, in json
    'path': self.request.path,
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/WebOb-1.4-py3.4.egg/webob/request.py", line 486, in path
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/WebOb-1.4-py3.4.egg/webob/descriptors.py", line 68, in fget
  File "/sites/metrics_dev/env/lib/python3.4/site-packages/WebOb-1.4-py3.4.egg/webob/request.py", line 159, in encget
KeyError: 'PATH_INFO'
[pid: 8850|app: 0|req: 9/21] 130.63.114.112 () {42 vars in 1273 bytes} [Thu May 22 19:23:18 2014] GET /_debug_toolbar/sse?request_id=313430343933393039353837383936 => generated 0 bytes in 8 msecs (HTTP/1.1 500) 0 headers in 0 bytes (1 switches on core 11)

The interesting thing to note is that the first few loadings of the page give 404, then I get 200 and the page loads, then I get that exception which occurs through a subsequent javascript call to the same page.

tisdall avatar May 22 '14 19:05 tisdall

This stanza looks suspicious:

https://github.com/Pylons/pyramid_debugtoolbar/blob/master/pyramid_debugtoolbar/toolbar.py#L196

mcdonc avatar May 22 '14 19:05 mcdonc

@mcdonc - isn't it returning on line 165 before getting to that section? That's what the traceback seems to be indicating.

tisdall avatar May 22 '14 19:05 tisdall

@mcdonc - nvm.. I think I see what you're getting at. It's possibly removing that environment value on subsequent calls, right?

tisdall avatar May 22 '14 19:05 tisdall

Maybe.

mcdonc avatar May 22 '14 20:05 mcdonc

You could try replacing "del subenviron['PATH_INFO']" with "subenviron['PATH_INFO'] = ''" and see if you see the problem again

mcdonc avatar May 22 '14 20:05 mcdonc

@mcdonc - no luck... I still get the same exception

tisdall avatar May 22 '14 20:05 tisdall

OK, then nobody knows. Could be uwsgi not setting PATH_INFO before handing the request over to webob.

mcdonc avatar May 22 '14 20:05 mcdonc

You could try using Waitress, which always does set PATH_INFO regardless, if only as an isolation step.

mcdonc avatar May 22 '14 20:05 mcdonc

I only ever see the problem on the javascript trying to update the page with a "Accept: text/event-stream" header... It may be some issue with web sockets with nginx and uwsgi. I'll see if I can figure it out.

tisdall avatar May 22 '14 20:05 tisdall

Had same issue with:

pyramid==1.4.5
pyramid-debugtoolbar==2.1

I'm also running on uWSGI. When this issue happens, printing self.environ shows that it is an empty dictionary. Somehow, the environ dictionary of a historical request is not populated, producing an invalid WSGI environ.

Further testing shows that this issue only happens in uWSGI in threaded mode; when switching to single-process, single-thread mode, the issue does not happen. So a workaround would be to switch to single-process, single-thread mode.

lieryan avatar Feb 23 '15 02:02 lieryan

related https://github.com/Pylons/pyramid_debugtoolbar/issues/235

mmerickel avatar Dec 08 '16 02:12 mmerickel