Is this a bug? KeyError: 'is_popup' on mysite/admin, while logging level = DEBUG. Django 1.10.6.

[np]

Hello,

I am a django newbie, just making my first django site. I tried to log the errors of my site, and found out 

KeyError: 'is_popup'  ...

when accessing http://127.0.0.1:8000/admin/. 

I tried this also on fresh install, django 1.10.6, using python 3.5.2. I had nothing else installed in the virtual environment, and the only lines I wrote to reproduce the error was to add

LOGGING = {

'version': 1,

'disable_existing_loggers': False,

'handlers': {

'file': {

'level': 'DEBUG',

'class': 'logging.FileHandler',

'filename': r'C:\Tmp\testproject\log.txt',

},

},

'loggers': {

'django': {

'handlers': ['file'],

'level': 'DEBUG',

'propagate': True,

},

},

}

to the bottom of the settings.py.

Then, on server startup (at http://127.0.0.1:8000) I got

(0.000) 

            SELECT name, type FROM sqlite_master

            WHERE type in ('table', 'view') AND NOT name='sqlite_sequence'

            ORDER BY name; args=None

(0.000) SELECT "django_migrations"."app", "django_migrations"."name" FROM "django_migrations"; args=()

and on first refresh of the page 

"GET / HTTP/1.1" 200 1767

But, when accesing http://127.0.0.1:8000/admin/ I got

(0.001) SELECT "django_session"."session_key", "django_session"."session_data", "django_session"."expire_date" FROM "django_session" WHERE ("django_session"."session_key" = 'ml9pjc4565zd009anzpufwpczy39fmpx' AND "django_session"."expire_date" > '2017-03-10 20:28:51.037208'); args=('ml9pjc4565zd009anzpufwpczy39fmpx', '2017-03-10 20:28:51.037208')

(0.000) SELECT "auth_user"."id", "auth_user"."password", "auth_user"."last_login", "auth_user"."is_superuser", "auth_user"."username", "auth_user"."first_name", "auth_user"."last_name", "auth_user"."email", "auth_user"."is_staff", "auth_user"."is_active", "auth_user"."date_joined" FROM "auth_user" WHERE "auth_user"."id" = 1; args=(1,)

Exception while resolving variable 'is_popup' in template 'admin/index.html'.

Traceback (most recent call last):

  File "C:\Python\Test\lib\site-packages\django\template\base.py", line 885, in _resolve_lookup

    current = current[bit]

  File "C:\Python\Test\lib\site-packages\django\template\context.py", line 75, in __getitem__

    raise KeyError(key)

KeyError: 'is_popup'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):

  File "C:\Python\Test\lib\site-packages\django\template\base.py", line 891, in _resolve_lookup

    if isinstance(current, BaseContext) and getattr(type(current), bit):

AttributeError: type object 'RequestContext' has no attribute 'is_popup'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):

  File "C:\Python\Test\lib\site-packages\django\template\base.py", line 900, in _resolve_lookup

    current = current[int(bit)]

ValueError: invalid literal for int() with base 10: 'is_popup'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):

  File "C:\Python\Test\lib\site-packages\django\template\base.py", line 907, in _resolve_lookup

    (bit, current))  # missing attribute

django.template.base.VariableDoesNotExist: Failed lookup for key [is_popup] in "[{'None': None, 'False': False, 'True': True}, {'perms': <django.contrib.auth.context_processors.PermWrapper object at 0x0000024B1D69BF28>, 'DEFAULT_MESSAGE_LEVELS': {'DEBUG': 10, 'INFO': 20, 'WARNING': 30, 'SUCCESS': 25, 'ERROR': 40}, 'csrf_token': <SimpleLazyObject: <function csrf.<locals>._get_val at 0x0000024B1D6148C8>>, 'request': <WSGIRequest: GET '/admin/'>, 'messages': <django.contrib.messages.storage.fallback.FallbackStorage object at 0x0000024B1D64E160>, 'user': <SimpleLazyObject: <User: admin>>}, {}, {'LANGUAGE_CODE': 'en-us', 'LANGUAGE_BIDI': False, 'title': <django.utils.functional.lazy.<locals>.__proxy__ object at 0x0000024B1CB2F240>, 'has_permission': True, 'app_list': [{'models': [{'perms': {'add': True, 'delete': True, 'change': True}, 'admin_url': '/admin/auth/group/', 'add_url': '/admin/auth/group/add/', 'name': <django.utils.functional.lazy.<locals>.__proxy__ object at 0x0000024B1D66D860>, 'object_name': 'Group'}, {'perms': {'add': True, 'delete': True, 'change': True}, 'admin_url': '/admin/auth/user/', 'add_url': '/admin/auth/user/add/', 'name': <django.utils.functional.lazy.<locals>.__proxy__ object at 0x0000024B1D5AC710>, 'object_name': 'User'}], 'app_url': '/admin/auth/', 'name': <django.utils.functional.lazy.<locals>.__proxy__ object at 0x0000024B1CB2FCF8>, 'has_module_perms': True, 'app_label': 'auth'}], 'site_title': <django.utils.functional.lazy.<locals>.__proxy__ object at 0x0000024B1CB1BF28>, 'available_apps': [{'models': [{'perms': {'add': True, 'delete': True, 'change': True}, 'admin_url': '/admin/auth/group/', 'add_url': '/admin/auth/group/add/', 'name': <django.utils.functional.lazy.<locals>.__proxy__ object at 0x0000024B1D66D470>, 'object_name': 'Group'}, {'perms': {'add': True, 'delete': True, 'change': True}, 'admin_url': '/admin/auth/user/', 'add_url': '/admin/auth/user/add/', 'name': <django.utils.functional.lazy.<locals>.__proxy__ object at 0x0000024B1D66D048>, 'object_name': 'User'}], 'app_url': '/admin/auth/', 'name': <django.utils.functional.lazy.<locals>.__proxy__ object at 0x0000024B1CB2FCF8>, 'has_module_perms': True, 'app_label': 'auth'}], 'site_header': <django.utils.functional.lazy.<locals>.__proxy__ object at 0x0000024B1CB1BFD0>, 'site_url': '/'}]"

Exception while resolving variable 'is_popup' in template 'admin/index.html'.

Traceback (most recent call last):

  File "C:\Python\Test\lib\site-packages\django\template\base.py", line 885, in _resolve_lookup

    current = current[bit]

  File "C:\Python\Test\lib\site-packages\django\template\context.py", line 75, in __getitem__

    raise KeyError(key)

KeyError: 'is_popup'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):

  File "C:\Python\Test\lib\site-packages\django\template\base.py", line 891, in _resolve_lookup

    if isinstance(current, BaseContext) and getattr(type(current), bit):

AttributeError: type object 'RequestContext' has no attribute 'is_popup'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):

  File "C:\Python\Test\lib\site-packages\django\template\base.py", line 900, in _resolve_lookup

    current = current[int(bit)]

ValueError: invalid literal for int() with base 10: 'is_popup'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):

  File "C:\Python\Test\lib\site-packages\django\template\base.py", line 907, in _resolve_lookup

    (bit, current))  # missing attribute

django.template.base.VariableDoesNotExist: Failed lookup for key [is_popup] in "[{'None': None, 'False': False, 'True': True}, {'perms': <django.contrib.auth.context_processors.PermWrapper object at 0x0000024B1D69BF28>, 'DEFAULT_MESSAGE_LEVELS': {'DEBUG': 10, 'INFO': 20, 'WARNING': 30, 'SUCCESS': 25, 'ERROR': 40}, 'csrf_token': <SimpleLazyObject: <function csrf.<locals>._get_val at 0x0000024B1D6148C8>>, 'request': <WSGIRequest: GET '/admin/'>, 'messages': <django.contrib.messages.storage.fallback.FallbackStorage object at 0x0000024B1D64E160>, 'user': <SimpleLazyObject: <User: admin>>}, {}, {'LANGUAGE_CODE': 'en-us', 'LANGUAGE_BIDI': False, 'title': <django.utils.functional.lazy.<locals>.__proxy__ object at 0x0000024B1CB2F240>, 'has_permission': True, 'app_list': [{'models': [{'perms': {'add': True, 'delete': True, 'change': True}, 'admin_url': '/admin/auth/group/', 'add_url': '/admin/auth/group/add/', 'name': <django.utils.functional.lazy.<locals>.__proxy__ object at 0x0000024B1D66D860>, 'object_name': 'Group'}, {'perms': {'add': True, 'delete': True, 'change': True}, 'admin_url': '/admin/auth/user/', 'add_url': '/admin/auth/user/add/', 'name': <django.utils.functional.lazy.<locals>.__proxy__ object at 0x0000024B1D5AC710>, 'object_name': 'User'}], 'app_url': '/admin/auth/', 'name': <django.utils.functional.lazy.<locals>.__proxy__ object at 0x0000024B1CB2FCF8>, 'has_module_perms': True, 'app_label': 'auth'}], 'site_title': <django.utils.functional.lazy.<locals>.__proxy__ object at 0x0000024B1CB1BF28>, 'available_apps': [{'models': [{'perms': {'add': True, 'delete': True, 'change': True}, 'admin_url': '/admin/auth/group/', 'add_url': '/admin/auth/group/add/', 'name': <django.utils.functional.lazy.<locals>.__proxy__ object at 0x0000024B1D66D470>, 'object_name': 'Group'}, {'perms': {'add': True, 'delete': True, 'change': True}, 'admin_url': '/admin/auth/user/', 'add_url': '/admin/auth/user/add/', 'name': <django.utils.functional.lazy.<locals>.__proxy__ object at 0x0000024B1D66D048>, 'object_name': 'User'}], 'app_url': '/admin/auth/', 'name': <django.utils.functional.lazy.<locals>.__proxy__ object at 0x0000024B1CB2FCF8>, 'has_module_perms': True, 'app_label': 'auth'}], 'site_header': <django.utils.functional.lazy.<locals>.__proxy__ object at 0x0000024B1CB1BFD0>, 'site_url': '/'}]"

(0.001) SELECT "django_admin_log"."id", "django_admin_log"."action_time", "django_admin_log"."user_id", "django_admin_log"."content_type_id", "django_admin_log"."object_id", "django_admin_log"."object_repr", "django_admin_log"."action_flag", "django_admin_log"."change_message", "auth_user"."id", "auth_user"."password", "auth_user"."last_login", "auth_user"."is_superuser", "auth_user"."username", "auth_user"."first_name", "auth_user"."last_name", "auth_user"."email", "auth_user"."is_staff", "auth_user"."is_active", "auth_user"."date_joined", "django_content_type"."id", "django_content_type"."app_label", "django_content_type"."model" FROM "django_admin_log" INNER JOIN "auth_user" ON ("django_admin_log"."user_id" = "auth_user"."id") LEFT OUTER JOIN "django_content_type" ON ("django_admin_log"."content_type_id" = "django_content_type"."id") WHERE "django_admin_log"."user_id" = 1 ORDER BY "django_admin_log"."action_time" DESC LIMIT 10; args=(1,)

"GET /admin/ HTTP/1.1" 200 2782

"GET /static/admin/css/base.css HTTP/1.1" 304 0

"GET /static/admin/css/dashboard.css HTTP/1.1" 304 0

"GET /static/admin/css/fonts.css HTTP/1.1" 304 0

"GET /static/admin/fonts/Roboto-Light-webfont.woff HTTP/1.1" 304 0

"GET /static/admin/fonts/Roboto-Bold-webfont.woff HTTP/1.1" 304 0

"GET /static/admin/fonts/Roboto-Regular-webfont.woff HTTP/1.1" 304 0

"GET /static/admin/img/icon-addlink.svg HTTP/1.1" 304 0

"GET /static/admin/img/icon-changelink.svg HTTP/1.1" 304 0

I see similar KeyError: 'is_popup' also i my logfile on my main development site. Is this normal behaviour, or is this a bug? 

[Daniel Hepper]

Yes, this is normal behavior. What you are seeing is the log output for a missing template variable. Django logs these in log level debug. See https://docs.djangoproject.com/en/1.10/topics/logging/#django-template

To get rid of these, you can configure the logger for the template system to only log messages with loglevel INFO and higher.

'loggers': {

'django': {

'handlers': ['file'],

'level': 'DEBUG',

'propagate': True,

},

'django.template': {

'handlers': ['file'],

'level': 'INFO',

'propagate': True,

},

},

Hope that helps,

Daniel

https://consideratecode.com

[np]

Hi Daniel,

Thank you for your anwer. I tested the option for using level: INFO for the django.template -logger. Your solution will suppress the 

Exception while resolving variable 'is_popup' in template 'admin/index.html'. ...

being caught. However, I do not understand why should I just suppress Exceptions/KeyErrors in the templates? I did not understand why this exception is raised. If there is no such variable as 'is_popup', shoudn't I just provide one? Forgive me for asking if the answer is too trivial.

I opened the 'admin/index.html' which extends 'base_site.html', which extends 'base.html', which has following lines (from the beginning of the file):

{% load i18n static %}<!DOCTYPE html>

{% get_current_language as LANGUAGE_CODE %}{% get_current_language_bidi as LANGUAGE_BIDI %}

<html lang="{{ LANGUAGE_CODE|default:"en-us" }}" {% if LANGUAGE_BIDI %}dir="rtl"{% endif %}>

<head>

<title>{% block title %}{% endblock %}</title>

<link rel="stylesheet" type="text/css" href="{% block stylesheet %}{% static "admin/css/base.css" %}{% endblock %}" />

{% block extrastyle %}{% endblock %}

{% if LANGUAGE_BIDI %}<link rel="stylesheet" type="text/css" href="{% block stylesheet_rtl %}{% static "admin/css/rtl.css" %}{% endblock %}" />{% endif %}

{% block extrahead %}{% endblock %}

{% block blockbots %}<meta name="robots" content="NONE,NOARCHIVE" />{% endblock %}

</head>

{% load i18n %}

<body class="{% if is_popup %}popup {% endif %}{% block bodyclass %}{% endblock %}"

  data-admin-utc-offset="{% now "Z" %}">

<!-- Container -->

<div id="container">

    {% if not is_popup %}

    <!-- Header -->

    <div id="header">

        <div id="branding">

        {% block branding %}{% endblock %}

        </div>

as we can see, there are exactly two lines in the (index.html) base.html having 'is_popup'. 

Could you, or someone else please enlighten me a bit more. Is it possible to get rid of this Exception/KeyError, other than filtering out it from the log?

- np

[Melvyn Sopacua]

On Saturday 11 March 2017 07:55:58 np wrote:

 

> being caught. However, I do not understand why should I just *suppress

> *Exceptions/KeyErrors in the templates? I did not understand *why*

> this exception is raised. If there is no such variable as 'is_popup',

> shoudn't I just provide one? Forgive me for asking if the answer is

> too trivial.

 

The admin reuses templates (and forms and views) for a popup window. It does so for the "plus" and "edit" buttons for foreign relations.

 

It is a common pattern to "define something is it applies" and it be undefined if it doesn't. It's kind of a shortcut boolean that saves an extra line in the code.

Django template code tries to keep programming out of the template, so undefined and false are for all intents and purposes identical in comparisons.

 

The exception is logged, so that one is still able to determine why code fails that you think shouldn't fail.

--

Melvyn Sopacua

[np]

Hi

Thanks for your help Melvyn and Daniel.I was not familiar with this pattern. Good to hear that there is nothing actually wrong with the code.

- np