Is get_dirs() in template_loader.py supposed to execute continuously every second?

[maximbelyayev]

I've added LOGGING setting to settings.py with "root" logging setting that has level DEBUG:

LOGGING = {
        "version": 1,
        "disable_existing_loggers": False,
        "handlers": {
            "console": {
                "class": "rich.logging.RichHandler",
                "rich_tracebacks": True,
            },
        },
        "root": {
            "handlers": ["console"],
            "level": "DEBUG",
            "propogate": False
        },
    }

After adding a logger at DEBUG level, I've noticed the following gets printed from logger.debug statements in template_loader.py continuously @ 1x/sec, which pollutes the console. Sidenote: let's say I have apps components, core, and accounts in django-project:

[12/13/24 12:26:47] 
DEBUG    Template loader will search for valid template dirs from template_loader.py:33 following options:                                                            
    - /Users/user/projects/django-project/components                                                                    
    - /Users/user/projects/django-project/core/static                                                                                                                         
    - /Users/user/projects/django-project/accounts/static                                                                                                               
DEBUG    Template loader matched following template dirs:         template_loader.py:92                                       
    - /Users/user/projects/django-project/core/static                                                                   
    - /Users/user/projects/django-project/accounts/static                                                               
    - /Users/user/projects/django-project/components

[12/13/24 12:26:48] 
DEBUG """
DEBUG """

[12/13/24 12:26:49]
DEBUG """
DEBUG """

...                                                           

Is this logging behavior from django-components expected behavior? If so, could it be explained in some fairly simple terms? Thank you!!

[JuroOravec]

Which version of Django-components, Django, and Python are you running?

In the log entries, for the latter two entries, [12/13/24 12:26:48] and [12/13/24 12:26:49], is it just DEBUG """ like you've shown above, or did you modify that to imply that the latter two entries had the same content?

But I don't think is coming from django-components. When I run the demo project in sampleproject directory of this repo, I don't see that behavior.

Assuming you are getting messages that look like Template loader will search for valid template every second:

1. Could you get a trace stack so we can see what is triggering the template_loader?
2. Could you try to make a minimal standalone Django project to reproduce and isolate this?

[maximbelyayev]

I looked into this some more and confirmed the Werkzeug reloading behavior is standard and to be expected when using runserver_plus; see here.

Therefore, it's to be expected that this will get called in the stack trace upon every reload:

File "/Users/user/projects/django-project/.venv/lib/python3.12/site-packages/django/template/loaders/cached.py", line 23, in get_dirs
    yield from loader.get_dirs()

However, now my question becomes this:

Why does any logger.debug() statement in the loaders mentioned below in TEMPLATES get silenced, except for django_components.template_loader.Loader?

TEMPLATES = [{
             ...
            'OPTIONS': {
                ...
                'loaders':[('django.template.loaders.cached.Loader', [
                        'django.template.loaders.filesystem.Loader',
                        'django.template.loaders.app_directories.Loader',
                        'django_components.template_loader.Loader',
                    ]
                )],
                ...
            },
            ...
        }]

For instance if I add the following to each respective loader's get_dirs function, only that of the django_components.template_loader.Loader will output a debug log 'test log' to the console.

import logging
logger = logging.getLogger(__name__)
logger.debug('test log')

This is certainly what's causing the pollution I'm experiencing.

[maximbelyayev]

I guess this has become more of a django logging question; why doesn't "root" logger in LOGGING log from django modules such as django.template? To log django modules, why do you have to specify "loggers" key like so in LOGGING when "root" is already setup at DEBUG level:

"loggers": {
            "django.template.loaders.app_directories": {
                "handlers": ["console"],
                "level": "DEBUG",
                "propagate": False,
            },
        },

Edit: The answer is explained here. You learn something new everyday!

Feel free to close this discussion. No issues with django-components.

[JuroOravec]

Hm, I might be wrong, but I don't think Werkzeug should be reloading every second. E.g. Django watches filesystem changes, and reloads only when a file changes. I would expect Werkzeug to work similarly. Do you possibly run some codegen in your project, and is it possible that this is being triggered on every reload?

[maximbelyayev]

Upon further reading it seems runserver or runserver_plus both use a reloading mechanism that poll the filesystem every second for changes. So it's not reloading every second; rather it's polling (and loading templates) every second. Once the reloader conducts a poll where a change is detected, it reloads the server.

[JuroOravec]

Interesting, didn't know that 👀