exception traceback with pyramid-debugtoolbar==2.0.2

[tisdall]

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

[stevepiercy]

@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.

[tisdall]

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.

[mcdonc]

This stanza looks suspicious:

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

[tisdall]

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

[tisdall]

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

[mcdonc]

Maybe.

[mcdonc]

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

[tisdall]

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

[mcdonc]

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

[mcdonc]

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

[tisdall]

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.

[lieryan]

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.

[mmerickel]

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