Django templates intermittently throw failed key lookup exceptions

[vsfeedback]

This issue has been moved from a ticket on Developer Community.

---

When rendering a template in Visual Studio's Django test server, I intermittently observe the following error:

Message=Failed lookup for key [addRowButton] in [...]

The line this issue triggers on looks like this (lightly modified to hide structure):

{% include '.../components/gen_formset_table_form.html' with form=next formset=formset addRowButton=addRowButton addSortable=addSortable %}

It is true that addRowButton is undefined in this template. However, only on some runs is this exception thrown, and having references to undefined keys should not throw exceptions in Django templates.

Once this issue is observed on a given run of the test server, it will consistently reappear every time this template is rendered. And, vice-versa, if the issue does not appear, it never appears. Furthermore, simply pressing the "restart" button on the toolbar is likely to fix the issue.

I also observe on most runs of the test server the following, possibly related issue:

----------------------------------------
Exception happened during processing of request from ('127.0.0.1', 59880)
[20/Feb/2020 20:57:16] "GET /ajax/ing/setup/json/ HTTP/1.1" 200 712
Traceback (most recent call last):
  File "C:\Program Files (x86)\Microsoft Visual Studio\Shared\Python37_64\lib\socketserver.py", line 650, in process_request_thread
    self.finish_request(request, client_address)
  File "C:\Program Files (x86)\Microsoft Visual Studio\Shared\Python37_64\lib\socketserver.py", line 360, in finish_request
    self. RequestHandlerClass(request, client_address, self)
  File "C:\Program Files (x86)\Microsoft Visual Studio\Shared\Python37_64\lib\socketserver.py", line 720, in __init__
    self.handle()
  File "[venvpath]\lib\site-packages\django\core\servers\basehttp.py", line 174, in handle
    self.handle_one_request()
  File "[venvpath]\lib\site-packages\django\core\servers\basehttp.py", line 182, in handle_one_request
    self.raw_requestline = self.rfile.readline(65537)
  File "C:\Program Files (x86)\Microsoft Visual Studio\Shared\Python37_64\lib\socket.py", line 589, in readinto
    return self._sock.recv_into(b)
ConnectionAbortedError: [WinError 10053] An established connection was aborted by the software in your host machine
----------------------------------------

---

Original Comments

Visual Studio Feedback System on 2/20/2020, 11:15 PM:

We have directed your feedback to the appropriate engineering team for further evaluation. The team will review the feedback and notify you about the next steps.

Visual Studio Feedback System on 3/26/2020, 06:52 PM:

I have detected that for the last 35 days, this issue didn't have much product team activity and a very small amount of new votes or comments. Based on this, its severity, and affected area, it’s my experience that this issue is very unlikely to be fixed.

Hugues Valois [MSFT] on 3/27/2020, 10:27 AM:

Thanks for the feedback.

We’ve just released Visual Studio 2019 16.5 and in which we’ve changed the “launch browser” action to wait until the console shows that web url, meaning it is ready to accept connections. What we had noticed in the past was that if it didn’t wait long enough, it could cause weird trouble in the connection leading to page errors.

There’s a small chance that it might help in your scenario, it would be worth trying when you get a chance to update VS.

If it doesn’t help, then I’d try to do those same things from command line rather than in VS and see if the issue still occurs.

thanks

Visual Studio Feedback System on 4/7/2020, 07:18 PM:

We will close this report in 14 days because we don’t have enough information to investigate further. To keep the problem open, please provide the requested details.

sirbayer on 4/12/2020, 00:43 PM:

Unfortunately, I can confirm that this hasn't resolved the issue; I'm still seeing the same exceptions after updating to 16.5.3.

I've never observed these issues when running from the Ubuntu on Windows terminal. In fact, the exceptions generated by VS do not appear in the VS terminal, either - they only seem to exist in the VS debug popups.

Hugues Valois on 4/16/2020, 01:49 PM:

Thanks sirbayer.

I’ve set up a repro for this and I can see that the behavior has changed between VS 2017 and VS 2019.

In VS 2019, even though I have unchecked all Python exceptions in the Exception Settings tool window, it still breaks on that exception. It doesn’t cause any problems with the application, I press F5 to continue and some code must be handling that exception since things work fine, no error in terminal.

However, the debugger should not be breaking when the exception is thrown, if I have all of them disabled in settings, and there is code that handles the exception. In VS 2017, it did not break under the same circumstances.

I was worried this was broken everywhere but fortunately this seem to only be an issue when debugging django templates.

I’ll transfer this over to our bug repo on github. Thank you for filing this.

---

Original Solutions

(no solutions)

[huguesv]

to repro, starting with the VS template for Django project:

in layout.html, add this in the <footer>

            {% include "app/copyright.html" with hello=foo %}

add new item, copyright.html to the app/templates/app folder

<p>Copyright 2020</p>

Just my Code setting doesn't seem to make any difference.
Disable all Python exceptions in the Exception Settings tool window.
Debug the application
Debugger breaks on this exception

If you do the same with VS 2017/ptvsd 4.1.1, it does not break on that exception.
If I install latest ptvsd 4.3.2 in the environment, then it breaks like it does in VS 2019/debugpy.

  Message=Failed lookup for key [foo] in [{'True': True, 'False': False, 'None': None}, {'csrf_token': <SimpleLazyObject: <function csrf.<locals>._get_val at 0x0000023F7CE86CA8>>, 'request': <WSGIRequest: GET '/about/'>, 'user': <SimpleLazyObject: <django.contrib.auth.models.AnonymousUser object at 0x0000023F7D1E7FC8>>, 'perms': <django.contrib.auth.context_processors.PermWrapper object at 0x0000023F7D1D7F48>, 'messages': <django.contrib.messages.storage.fallback.FallbackStorage object at 0x0000023F7CE32348>, 'DEFAULT_MESSAGE_LEVELS': {'DEBUG': 10, 'INFO': 20, 'SUCCESS': 25, 'WARNING': 30, 'ERROR': 40}}, {}, {'title': 'About', 'message': 'Your application description page.', 'year': 2020}]
  Source=C:\Users\huvalo\source\repos\DjangoWebProject4\app\templates\app\layout.html
  StackTrace:
  File "C:\Users\huvalo\source\repos\DjangoWebProject4\app\templates\app\layout.html", line 40, in Django Template
    {% include "app/copyright.html" with hello=foo %}
  File "C:\Users\huvalo\source\repos\DjangoWebProject4\env\Lib\site-packages\django\template\base.py", line 850, in _resolve_lookup
    (bit, current))  # missing attribute
  File "C:\Users\huvalo\source\repos\DjangoWebProject4\env\Lib\site-packages\django\template\base.py", line 796, in resolve
    value = self._resolve_lookup(context)
  File "C:\Users\huvalo\source\repos\DjangoWebProject4\env\Lib\site-packages\django\template\base.py", line 671, in resolve
    obj = self.var.resolve(context)
  File "C:\Users\huvalo\source\repos\DjangoWebProject4\env\Lib\site-packages\django\template\base.py", line 904, in render_annotated
    return self.render(context)
  File "C:\Users\huvalo\source\repos\DjangoWebProject4\env\Lib\site-packages\django\template\base.py", line 937, in render
    bit = node.render_annotated(context)
  File "C:\Users\huvalo\source\repos\DjangoWebProject4\env\Lib\site-packages\django\template\base.py", line 163, in _render
    return self.nodelist.render(context)
  File "C:\Users\huvalo\source\repos\DjangoWebProject4\env\Lib\site-packages\django\template\base.py", line 904, in render_annotated
    return self.render(context)
  File "C:\Users\huvalo\source\repos\DjangoWebProject4\env\Lib\site-packages\django\template\base.py", line 937, in render
    bit = node.render_annotated(context)
  File "C:\Users\huvalo\source\repos\DjangoWebProject4\env\Lib\site-packages\django\template\base.py", line 163, in _render
    return self.nodelist.render(context)
  File "C:\Users\huvalo\source\repos\DjangoWebProject4\env\Lib\site-packages\django\template\base.py", line 171, in render
    return self._render(context)
  File "C:\Users\huvalo\source\repos\DjangoWebProject4\app\views.py", line 43, in about
    'year':datetime.now().year,

[huguesv]

[huguesv]

[huguesv]

This is the code throwing that exception:

And a few frames up the call stack, the code that catches it:

[huguesv]

I tested with more versions, ptvsd 4.2.4 worked fine, ie it detects that it is a handled exception, and ptvsd 4.2.7+ (including debugpy) does not work as expected, it thinks it is unhandled.

[huguesv]

@fabioz almost certainly a pydevd bug regarding detection of handled/unhandled exception.

[int19h]

Likely related to the fix for microsoft/ptvsd#694 and/or microsoft/ptvsd#1181

[fabioz]

I'll investigate.

[fabioz]

Ok, so, showing the error that a variable is not defined happens that way by design...

Now, related to the config, what happens is that in https://github.com/microsoft/debugpy/blob/master/src/debugpy/_vendored/pydevd/_pydevd_bundle/pydevd_process_net_command_json.py#L727, if we are handling either caught/uncaught exceptions, if the django debug option is set, it'll track any django exception and show it (regardless of the user choosing just uncaught or just caught exceptions).

Internally, there's actually a separate configuration for that... this is the 2nd time this comes up so, I think we should create a separate setting for this in the DAP too. We can either pass this option in the launch settings (something as djangoExceptions/jinja2Exceptions) or we can add it to the setExceptionBreakpoints request (as a filter or exception option).

Note that related to the fact that it is shown sometimes and not at others, I don't think there's much that we can do -- I know it should always break or never break, but it seems there is some kind of nondeterminism in django itself there.

p.s.: another option could be to never report VariableDoesNotExist, but I can think of some scenarios where this is actually useful, so, I'm not a big fan of that idea.

[int19h]

If the template is still rendering correctly (sans the debugger), then the exception is effectively handled, isn't it? In which case we shouldn't be reporting it unless "Raised" is checked.

[fabioz]

If the template is still rendering correctly (sans the debugger), then the exception is effectively handled, isn't it? In which case we shouldn't be reporting it unless "Raised" is checked.

Agreed. I'll do that change.