Failure on tip of Django

The tip of Django is failing the test suite like this:

py35-djangotip runtests: commands[1] | python -m unittest discover -b
............ss........................................E
======================================================================
ERROR: test_string_template (tests.test_simple.StringTemplateTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/ned/coverage/django_coverage_plugin/tests/test_simple.py", line 256, in test_string_template
    options={},
  File "/Users/ned/coverage/django_coverage_plugin/tests/plugin_test.py", line 129, in run_django_coverage
    tem = Template(text)
  File "/Users/ned/coverage/django_coverage_plugin/.tox/py35-djangotip/lib/python3.5/site-packages/django/template/base.py", line 184, in __init__
    engine = Engine.get_default()
  File "/Users/ned/coverage/django_coverage_plugin/.tox/py35-djangotip/lib/python3.5/site-packages/django/template/engine.py", line 81, in get_default
    "No DjangoTemplates backend is configured.")
django.core.exceptions.ImproperlyConfigured: No DjangoTemplates backend is configured.

----------------------------------------------------------------------
Ran 55 tests in 0.735s

FAILED (errors=1, skipped=2)

carljm and apollo13 helped in #django to diagnose it:

[13:54:46] <nedbat> apollo13: if you are interested in looking at the django_coverage_plugin failure, I could walk you through it.
[13:54:56] <apollo13> nedbat: sure
[13:56:10] <nedbat> apollo13: you've seen the tox output? https://gist.github.com/nedbat/6713e07bdd3511dbcd1d250f94d1d818
[13:56:32] <apollo13> nedbat: yeah
[13:56:49] <apollo13> sure
[13:57:15] <nedbat> apollo13: so there's one test that fails, the test where I make a template from a string, rather than from a file. and it only fails on tip, not 1.9
[13:57:28] <apollo13> nedbat: all I need to do is clone and run tox?
[13:57:35] <nedbat> apollo13: yup
[13:57:49] <apollo13> nedbat: Ok, will submit a PR once I fiured it out
[13:58:06] <nedbat> apollo13: that would be very cool, thanks! I'm around if things go wrong.
[13:58:28] <apollo13> holy shit, django14 , /me removes a few things from tox.ini^^
[13:59:22] <apollo13> sounds like it
[13:59:46] <apollo13> though you should check it on master
[14:00:03] <nedbat> apollo13: you can just run the environments you want, no need to edit tox.ini
[14:00:21] <apollo13> nedbat: tells you how much I use tox :D
[14:00:48] <nedbat> apollo13: tox -e py27-djangotip
[14:00:51] <apollo13> nedbat: I am getting way more errors though
[14:01:25] <apollo13> https://dpaste.de/3rJY/raw
[14:01:56] <apollo13> which sounds like an ordering problem
[14:02:14] <apollo13> nedbat: can I tell tox to be more verbose, ie show me the test it executes?
[14:02:31] <nedbat> apollo13: the test name is above each stack trace
[14:02:44] <apollo13> nedbat: yes, but I'd also want the ones which are okay
[14:03:08] <apollo13> ie more verbose unittest output
[14:04:15] <apollo13> ah there we go, copied gthe unittest invocation out
[14:04:39] <nedbat> apollo13: i tried tip again, i still only get one failure?
[14:04:55] <apollo13> nedbat: odd, as I said, I just cloned your repo and did tox -e py27-djangotip
[14:05:34] <nedbat> apollo13: btw, this will do what you want with tox:  tox -e py27-djangotip -- discover -b -v
[14:05:45] <nedbat> apollo13: what version of tox?
[14:05:55] <apollo13> nedbat: whatever pip just installed, so latest
[14:06:11] <apollo13> 2.3.1 imported from /home/florian/.local/lib/python2.7/site-packages/tox/__init__.pyc
[14:07:50] <nedbat> apollo13: blah, i still get only one failure.  I wonder if you have environment variables that i don't?
[14:08:25] <apollo13> nedbat: dunno, but that error is test isolation -- I have an idea
[14:08:39] <nedbat> apollo13: comment out "passenv" line in tox.ini ?
[14:09:20] <apollo13> will do later, I can repro the error, shouldn't be that hard to fix
[14:11:01] <nedbat> apollo13: thanks, I appreciate whatever you can give me, even if it's a clue.
[14:16:42] <apollo13> nedbat: are you doing monkey patching somewhere?
[14:17:04] <nedbat> apollo13: no monkeypatching (I think....)
[14:20:52] <apollo13> nedbat: It fails cause <django.template.backends.django.DjangoTemplates object at 0x7f14819d86d0> is not an instance of <class 'django.template.backends.django.DjangoTemplates'>
[14:20:56] <apollo13> which makes literally no sense
[14:21:13] <nedbat> apollo13: buh?
[14:22:35] <apollo13> ok, time for pdb
[14:28:58] <apollo13> nedbat: what does coverage do :D
[14:29:03] <apollo13> I get new ids for classes
[14:29:32] <nedbat> apollo13: sounds like double importing.
[14:29:36] <apollo13> that is I get a new instance of types -- as if sys.modules got nuked and reimported
[14:29:43] <nedbat> apollo13: my tests do that.
[14:29:45] <apollo13> paths are always absolute, but yeah
[14:29:52] <nedbat> apollo13: but it should be consistent within a test.
[14:29:53] <apollo13> well that won't work
[14:29:57] <apollo13> show me
[14:31:05] <apollo13> nedbat: all I can tell you is that django.template.backends.django gets reloaded, but you still have refs to the old module
[14:31:19] <nedbat> apollo13: hmm, i wonder why only that tests minds.
[14:31:22] <nedbat> *test
[14:32:14] <apollo13> nedbat: can you show me where the sys.modules hackers happens, or rather based on what?
[14:32:56] <nedbat> apollo13: every test notes the state of sys.modules, and restores it at the end of the test.
[14:33:09] <nedbat> apollo13: it's in a mixin in unittest-mixins
[14:34:13] <nedbat> apollo13: can you tell me where the class comparison is that breaks if the class is redefined?
[14:34:16] <apollo13> sure
[14:34:43] <apollo13> nedbat: that one fails https://github.com/django/django/blob/master/django/template/engine.py#L74-L75
[14:34:47] <apollo13> it returns zero engines here
[14:34:53] <apollo13> since that method imports  from django.template.backends.django import DjangoTemplates
[14:35:07] <apollo13> if you do sys.modules hackery, this will reimport on every test
[14:35:24] <apollo13> but engines.all() stays constant and already has an instance of that!
[14:36:09] <nedbat> apollo13: is this code new since 1.9?
[14:36:25] <nedbat> oh, the lru_cache....
[14:36:48] <nedbat> ugh, hidden mutable globals
[14:37:06] <apollo13> yeah, the lru_cache might hide that for a while
[14:37:15] <apollo13> that is true, didn't check for that
[14:37:34] <apollo13> so my analysis might not be spot on, but somewhere there is certainly the source of the problems
[14:37:45] <nedbat> apollo13: no, i think you are right. 
[14:38:55] <nedbat> apollo13: hmm, lru_cache is also in 1.9
[14:39:18] <apollo13> nedbat: yes, I do not think it is because of lru_cache, add a print to backends.django print "HI I AM IMPORTED"
[14:40:14] <apollo13> and a print into https://github.com/django/django/blob/2a20ebe6a5b6606f99091530067cca05fb7ce853/django/template/__init__.py and you will see that the init module does not change
[14:40:25] <apollo13> therefore engines will have the "old engines"
[14:40:47] <apollo13> nedbat: I hope that is enough for you to get further
[14:41:01] <apollo13> I am somewhat out of ideas there
[14:41:45] <apollo13> nedbat: I'll tell you the revision in django that caused this in a sec
[14:43:45] <apollo13> nedbat: 9023696613b278bb96a2ab5744da5c2bac023ad7
[14:44:08] <nedbat> apollo13: how did you find that commit?
[14:44:15] <apollo13> nedbat: git bisect
[14:44:40] <nedbat> apollo13: i was afraid of that :)  That means I still need to read the code to understand what part is the problem! :)
[14:45:37] <carljm> nedbat: it's just the imports, I think
[14:45:47] <apollo13> nedbat: nope, I can tell you
[14:45:53] <apollo13> add to django/template/loader.py
[14:45:57] <apollo13> namely: from .backends.django import DjangoTemplates
[14:46:05] <apollo13> this causes the failure to disappear
[14:46:28] <carljm> because that import causes django.template.backends.django to be in sys.modules prior to any test
[14:46:34] <apollo13> jupp
[14:46:35] <nedbat> carljm: hmm, ok.
[14:46:47] <carljm> without that import, you don't ever import it until inside a test
[14:46:50] <nedbat> this sounds hairy.
[14:46:52] <carljm> so each test is getting its own copy
[14:47:20] <apollo13> jupp, but the engine handler still has the old one
[14:47:25] <carljm> but an instance of DjangoTemplates from the first test's copy of that module gets stored in engines.all(), permanently
[14:47:28] <carljm> exactly
[14:47:32] <nedbat> apollo13, carljm: thanks, this is very helpful.
[14:47:46] <carljm> apollo13: great detective work!
[14:48:05] <apollo13> is it okay if I put down my debugger hat and watch a movie with the girls, or can I be of further assistance?
[14:48:16] <carljm> nedbat: sorry I dropped the ball on this yesterday; helping to run the Django sprint basically involves constant interruptions :-)
[14:48:34] <nedbat> carljm: no worries, i was overloaded just managing my small table of coverage.py sprinters.
[14:48:52] <nedbat> apollo13: movie with the girls sounds like a much better use of time 
[14:49:01] <apollo13> that :D
[14:49:19] <apollo13> cyl and keep me updated, sounds like a fun problem to have
[14:49:45] <carljm> apollo13: have fun :-)
[14:50:01] <nedbat> carljm: i guess i'm still a little behind: how does *removing* an import mean that we have something imported earlier than before?
[14:50:15] <carljm> nedbat: no, it's imported later now; that's the problem
[14:50:57] <carljm> in Django 1.9, with the module-level import of backends.django in template.loader, it gets imported before any of your tests run
[14:51:19] <carljm> so it becomes part of the "initial state" of sys.modules, as far as your per-test reset code is concerned
[14:51:29] <carljm> therefore you only ever have the one copy of DjangoTemplates class around
[14:51:33] <nedbat> carljm: it's because there are two imports that either both need to happen before tests run, or both need to happen after, and now they are split across that boundary?
[14:52:21] <carljm> nedbat: i don't know how many imports there are exactly, I wouldn't quite phrase it that way
[14:52:51] <carljm> anything that is imported before your test-wrapping sys.modules-resetting code runs becomes part of the permanent global state of sys.modules
[14:53:13] <nedbat> carljm: yes
[14:53:16] <carljm> which is normally the way sys.modules always works -- it's global and permanent -- stuff gets added to it, but nor removed and then reloaded
[14:53:22] <nedbat> carljm: yup
[14:53:42] <carljm> but now that Django isn't causing an early import of template.backends.django, it never gets imported until inside your first test that runs
[14:54:07] <carljm> and the lazy initialization of the global list of configured Django template engines happens _inside_ your first test
[14:54:31] <nedbat> carljm: the global inside lru_cache?
[14:54:51] * nedbat wishes lru_cache had a classmethod called clear_all_caches()
[14:55:35] <carljm> no, I don't think lru_cache is related
[14:55:46] <carljm> the global instance of EngineHandler
[14:56:07] <carljm> that's where Django maintains a list of all the template engines that you've configured in your settings
[14:56:45] <carljm> the code that's failing inside Engine.get_default() calls engines.all() on line 74
[14:57:03] <carljm> "engines" there is a global singleton instance of EngineHandler
[14:57:21] <nedbat> ah
[14:57:26] <carljm> instantiated at https://github.com/django/django/blob/master/django/template/__init__.py#L47
[14:57:55] <nedbat> yes
[14:58:55] <carljm> you either need this cached property exercised sooner: https://github.com/django/django/blob/master/django/template/utils.py#L26
[14:59:04] <carljm> or you just need to force an earlier import of template.backends.django
[14:59:23] <carljm> so that when that cached property _is_ exercised, it's using a copy of the module that is permanent, not ephemeral to the test
[15:00:48] <nedbat> carljm: yes, thanks for the hand-holding, i'll have to consider how best to get back my isolation.
[15:00:53] <carljm> nedbat: I'd need to look at your tests again to be sure, but I think your best bet to get around all this global state is to instantiate a DjangoTemplates engine explicitly in your tests.
[15:01:22] <carljm> the template engine used to be full of global state spread all over the place, so we extracted out the engine to hold all that state
[15:01:50] <carljm> we still need the global state in order to have things implicitly use the configuration from settings, which are process-global, but that global state is now concentrated in EngineHandler
[15:02:12] <carljm> but the idea is that if you need isolation, you shouldn't rely on the TEMPLATES setting or on Engine.get_default() at all
[15:02:14] <nedbat> carljm: i'd like to have my code have a flavor of, "I don't know what's in Django, but I know how to force it to do everything from scratch each time"
[15:02:31] <nedbat> carljm: well, my tests need to test how TEMPLATES is interacting with my code.
[15:03:01] <carljm> nedbat: how does your code interact with the TEMPLATES setting, specifically?
[15:03:38] <nedbat> carljm: i have tests that the plugin properly detects if debug is on or off, for example.
[15:03:56] <nedbat> carljm: and the latest fix was to ensure that I wasnt reading settings when the real program didn't need to.
[15:04:03] <nedbat> carljm: there's a lot of settings choreography
[15:07:28] <apollo13> carljm: the cached_property afaik is not an issue, since it just builds a list of template engine args, the issue is the caching in https://github.com/django/django/blob/master/django/template/utils.py#L63-L83
[15:08:31] <carljm> apollo13: yes, you're right, it's actually __getitem__ that imports and instantiates the backend class
[15:09:33] <nedbat> carljm, apollo13: right, but if "engines = EngineHandler()" were re-executed for each test, that would fix it.
[15:09:58] <nedbat> apollo13: how's the movie? :)
[15:10:06] <carljm> nedbat: well, debug on/off comes from settings, but eventually it becomes an attribute of the engine instance: https://github.com/django/django/blob/master/django/template/backends/django.py#L27
[15:10:45] <carljm> so even for correctness you should preferably be detecting it there, not looking at settings directly. and if so, you could write that test with an isolated engine instance
[15:10:48] <nedbat> carljm: right. at heart, the problem is that some of Django is imported before tests start, and so persists, and some is imported after, and so is re-imported for each test.
[15:11:34] <carljm> testing that you aren't triggering a settings import is a different thing of course, but still doesn't mean that you couldn't write most of your template-related tests with an isolated engine you create yourself
[15:11:57] <nedbat> carljm: you're saying this function should be written differently: https://github.com/nedbat/django_coverage_plugin/blob/6f8976d9a3faedfb441ee8f53c3bf4bdcc434545/django_coverage_plugin/plugin.py#L39-L46
[15:13:27] <carljm> nedbat: Yes, I am. That function as currently written is (I think) needlessly re-implementing logic that Django already implements. And I'm not sure the interface that function currently promises is even sensible for a multiple-template-engines world
[15:14:14] <nedbat> carljm: this plugin is only concerned with the Django template engine, but i take your point.
[15:14:18] <carljm> nedbat: because "is template debugging on or off" is a per-engine question, not a global question
[15:14:27] <carljm> nedbat: well, you can have multiple DjangoTemplates engines configured
[15:14:35] <carljm> with different settings, source directories, etc
[15:14:53] <nedbat> carljm: true true, and i just moved this check to later, where I could examine the engine directly, so that's a good push in the right direction.
[15:15:28] <carljm> nedbat: though I think it may be difficult for you to fully adapt to the new template-engines world before dropping compatibility with pre-1.8 versions of Django.
[15:15:41] <nedbat> carljm: why is that? What beasts lie in store for me?
[15:16:18] <carljm> nedbat: well, because pre-1.8 there was no such thing as a template engine instance
[15:16:35] <nedbat> carljm: i see
[15:16:51] <carljm> the configuration that is now encapsulated in an engine instance (like an instance of DjangoTemplates) used to be spread implicitly through a bunch of different settings, and ad-hoc cached in various places
[15:17:14] <nedbat> carljm: ok.
[15:17:43] <carljm> i think adapting your approach and your tests to be engine-centric will make your life much easier in terms of isolation

nedbat / django_coverage_plugin

Failure on tip of Django #26