django-debug-toolbar icon indicating copy to clipboard operation
django-debug-toolbar copied to clipboard

Just Enabling Debug Toolbar as Middleware creates Delays of Several Seconds on each request

Open QBH3 opened this issue 1 year ago • 10 comments

in debug_toolbar/middleware.py is following code:

def show_toolbar(request):
    """
    Default function to determine whether to show the toolbar on a given page.
    """
    internal_ips = list(settings.INTERNAL_IPS)

    try:
        # This is a hack for docker installations. It attempts to look
        # up the IP address of the docker host.
        # This is not guaranteed to work.
        docker_ip = (
            # Convert the last segment of the IP address to be .1
            ".".join(socket.gethostbyname("host.docker.internal").rsplit(".")[:-1])
            + ".1"
        )
        internal_ips.append(docker_ip)
    except socket.gaierror:
        # It's fine if the lookup errored since they may not be using docker
        pass
    return settings.DEBUG and request.META.get("REMOTE_ADDR") in internal_ips

on every request it tries to resolve host.docker.internal which might lead to a timeout from the resolver running locally.

I believe at least this behaviour should be described in the documentation and that it might cause problems with certain resolvers.

Also I believe it should be sufficient to do this name resolution only once per server startup and not at every request.

Another way might be to use the documentation to decribe how to add host.docker.internal to INTERNAL_IPS if a user is inclined to do so.

What do you think?

QBH3 avatar May 29 '24 08:05 QBH3

Can you explain these points further? I don't know enough about them.

might lead to a timeout from the resolver running locally.

that it might cause problems with certain resolvers.

Why would a resolver running locally time out? Are there other resolvers you're considering or is it the local case? If there are others can you explain those to me?

I don't use docker often enough to know these answers. Any details you can provide will help.

I'm surprised this is an issue running everything locally.

tim-schilling avatar May 29 '24 10:05 tim-schilling

Hi Tim

Funny thing is, i am not even using Docker to run Django, i rather use a Python virtualenv.

The Effect is, that every request takes at least 5 (and up to 10) Seconds to complete.

time wget http://localhost:8000/django-url/
--2024-05-28 19:27:51--  http://localhost:8000/django-url/
Resolving localhost (localhost)... 127.0.0.1
Connecting to localhost (localhost)|127.0.0.1|:8000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 15666 (15K) [text/html]
Saving to: ‘index.html’

index.html
100%[======================================================================================================>]  15,30K  --.-KB/s    in 0s

2024-05-28 19:28:01 (804 MB/s) - ‘index.html’ saved [15666/15666]

real    0m10,054s
user    0m0,001s
sys     0m0,004s

Regarding Resolvers that might cause such timeouts for non-existing domains, Ubuntu using systemd-resolved and some unfortunate Interaction with mDNS and local Search List for DNS does this to non-existing domains like host.docker.internal from the code above.

QBH3 avatar May 29 '24 10:05 QBH3

Also, if I think about it a bit longer, the code above opens the server far more than intended.

in two ways:

  • If the process is not running in docker in external adversary can try telling you that he is host.docker.internal by poisoning the DNS cache
  • If the process is running in docker all requests coming through a proxy at ".1" will look legitimate and get access to the debug toolbar.

So i really think, that if the user wants such a behaviour they should be able to manually add host.docker.internal to INTERNAL_IPS without negatively effecting users that do not want such an automatic behaviour.

QBH3 avatar May 29 '24 10:05 QBH3

I can't reproduce this problem you're encountering. Can you create a reproducible environment for me?

When I run make example in the toolbar repo and use wget:

λ time wget http://localhost:8000/           
--2024-05-29 06:59:52--  http://localhost:8000/
Resolving localhost (localhost)... 127.0.0.1
Connecting to localhost (localhost)|127.0.0.1|:8000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 14621 (14K) [text/html]
Saving to: ‘index.html’

index.html                                         100%[===============================================================================================================>]  14.28K  --.-KB/s    in 0s      

2024-05-29 06:59:52 (449 MB/s) - ‘index.html’ saved [14621/14621]

wget http://localhost:8000/  0.00s user 0.00s system 2% cpu 0.141 total

tim-schilling avatar May 29 '24 12:05 tim-schilling

I'm good with creating a separate show toolbar callback for docker.

tim-schilling avatar May 29 '24 12:05 tim-schilling

Hi Tim,

what one needs for reproducing this failure is an environment that uses a DNS resolver that times out on resolving host.docker.internal

then you will get the server to hang for as long as the timeout of resolving host.docker.internal is ..

I think basicly it should not try to resolve that domain when not running in a docker.

As a workaround i put host.docker.internal in /etc/hosts and got the server to run without flaws.

QBH3 avatar May 29 '24 12:05 QBH3

We share the same observation on Ubuntu. Upgrading from 4.3.0 to 4.4.0, with no other changes, request time increased by ~1 second for us. A request that took 100ms with version 4.3.0 now takes 1 second. This tracks very well with the time it takes for curl to return an error

time curl host.docker.internal
curl: (6) Could not resolve host: host.docker.internal

real	0m0.942s
user	0m0.009s
sys	0m0.003s

This from is within a docker container on an Ubuntu host btw.

A quick google search reveals that host.docker.internal is only exposed on OSX and Windows, but not on Linux.

MarcoGlauser avatar Jun 04 '24 06:06 MarcoGlauser

A first change has already landed addressing this but isn't yet a part of a release. INTERNAL_IPS is now checked before trying to resolve host.docker.internal and that should hopefully fix many of the local issues people are seeing: https://github.com/jazzband/django-debug-toolbar/commit/cf0cc0dfe86e134ea2a0352a4f0833efbcf9f2c4

matthiask avatar Jun 04 '24 06:06 matthiask

Awesome, https://github.com/jazzband/django-debug-toolbar/commit/cf0cc0dfe86e134ea2a0352a4f0833efbcf9f2c4 will solve our issue, thank you :)

However, there will still be the issue that host.docker.internal cannot be resolved on linux systems, since it's a feature of docker desktop.

MarcoGlauser avatar Jun 05 '24 01:06 MarcoGlauser

I created a very simple project using following command. django-admin startapp test_debug_toolbar

And I added just django-debug-toolbar to make test. After add django-debug-toolbar, admin page loading delays around few seconds.

Here are my settings.

DEBUG_TOOLBAR_CONFIG = {
    "DISABLE_PANELS": [
        # 'debug_toolbar.panels.history.HistoryPanel',
        # 'debug_toolbar.panels.versions.VersionsPanel',
        'debug_toolbar.panels.timer.TimerPanel',
        'debug_toolbar.panels.settings.SettingsPanel',
        'debug_toolbar.panels.headers.HeadersPanel',
        'debug_toolbar.panels.request.RequestPanel',
        'debug_toolbar.panels.sql.SQLPanel',
        'debug_toolbar.panels.staticfiles.StaticFilesPanel',
        'debug_toolbar.panels.templates.TemplatesPanel',
        'debug_toolbar.panels.cache.CachePanel',
        'debug_toolbar.panels.signals.SignalsPanel',
        'debug_toolbar.panels.redirects.RedirectsPanel',
        'debug_toolbar.panels.profiling.ProfilingPanel',
    ],
    "SHOW_TEMPLATE_CONTEXT": True,
}

As you can see, I disabled almost panels, but the same problem. Just adding debug-toolbar middleware is causing few seconds delay.

It seems the problem only happens with django-debug-toolbar 4.4.2, after downgrade to 4.3.0, I can't see the problem.

note I'm not using Docker for the test project.

  • Ubuntu 22.04
  • Django 5.0.6

heindrickdumdum0217 avatar Jun 27 '24 01:06 heindrickdumdum0217

Is this still an issue? The DNS resolving now only happens after checking INTERNAL_IPS, so I'd hope this isn't an issue anymore in 99% of cases.

matthiask avatar Jul 05 '24 14:07 matthiask

I tried on Ubuntu 22.04 directly it worked, but when I try on VM it didn't work.

heindrickdumdum0217 avatar Jul 10 '24 01:07 heindrickdumdum0217

It seems the problem only happens with django-debug-toolbar 4.4.2, after downgrade to 4.3.0, I can't see the problem.

@heindrickdumdum0217 The regression was in

  • #1887

The fix for this was

  • #1929

And was released in 4.4.3

  • https://github.com/jazzband/django-debug-toolbar/releases/tag/4.4.3

So you should try updating to 4.4.3 or later.

I believe this issue can be closed now.

johnthagen avatar Jul 31 '24 11:07 johnthagen

@johnthagen Yes, after upgrade, the error gone.

heindrickdumdum0217 avatar Jul 31 '24 11:07 heindrickdumdum0217

Closing as fixed. Thanks @johnthagen for communicating that.

tim-schilling avatar Aug 20 '24 12:08 tim-schilling