Django-cms: Saving a plugin which include an image performs two identical save requests

[sveetch]

Summary

I developed this Django application than i use into a project:
https://github.com/emencia/cmsplugin-blocks . It's just a set of some basic
plugins to create some kinds of content.

The bug occurs on plugins: Card, Hero and Album but not on Slider.

Expected behaviour

I should be able to create one plugin object which include an image without to reload or have duplicated object.

Actual behaviour

When creating or editing an object of one involved plugin, i got an Error 500
Exception Value: database is locked (full traceback further).

But finally if i just reload the document, the object is well saved in its placeholder with filled data.

From what i find in the development server output the POST request is made twice which may trigger the database lock:

02:37:32   [     200] POST /admin/cms/page/edit-plugin/88/?cms_path=%2Fassociation%2F%3Fedit HTTP/1.1
02:37:32   [     200] GET /admin/jsi18n/ HTTP/1.1
02:37:32   [     500] POST /admin/cms/page/edit-plugin/88/?cms_path=%2Fassociation%2F%3Fedit HTTP/1.1

It is only happening if i fill an image field but if i just fill the text and choices the bug never happen.

This is the bug result on development mode (Debug enabled and SQLite database).

On production environment (Debug disabled and PostgreSQL database), there is rarely an http500 instead the two identical requests succeed but the same object is saved twice.

I tried many changes on my plugins to find something wrong, i searched in every issues related to plugins, searched in mailing list and i didn't find anything that would resolve this bug.

Traceback

Environment:


Request Method: POST
Request URL: http://192.168.0.103:8001/admin/cms/page/add-plugin/?placeholder_id=98&plugin_type=CardPlugin&cms_path=%2Fassociation%2F%3Fedit&plugin_language=fr

Django Version: 1.11.16
Python Version: 3.5.2
Installed Applications:
['filebrowser',
 'ckeditor',
 'ckeditor_uploader',
 'admin_shortcuts',
 'djangocms_admin_style',
 'django.contrib.admin',
 'django.contrib.auth',
 'django.contrib.contenttypes',
 'django.contrib.sessions',
 'django.contrib.sites',
 'django.contrib.messages',
 'django.contrib.staticfiles',
 'django_assets',
 'crispy_forms',
 'crispy_forms_foundation',
 'captcha',
 'project.utils',
 'gtm',
 'logentry_admin',
 'django.contrib.sitemaps',
 'sendfile',
 'sorl.thumbnail',
 'staticpages',
 'django_comments',
 'tagging',
 'zinnia',
 'cmsplugin_zinnia',
 'zinnia_ckeditor',
 'mptt',
 'cms',
 'treebeard',
 'menus',
 'sekizai',
 'djangocms_snippet',
 'djangocms_text_ckeditor',
 'cmsplugin_blocks']
Installed Middleware:
['django.contrib.sessions.middleware.SessionMiddleware',
 'django.middleware.locale.LocaleMiddleware',
 'django.middleware.common.CommonMiddleware',
 'django.middleware.csrf.CsrfViewMiddleware',
 'django.contrib.auth.middleware.AuthenticationMiddleware',
 'django.contrib.auth.middleware.SessionAuthenticationMiddleware',
 'django.contrib.messages.middleware.MessageMiddleware',
 'django.middleware.clickjacking.XFrameOptionsMiddleware',
 'django.middleware.security.SecurityMiddleware',
 'django.contrib.admindocs.middleware.XViewMiddleware',
 'cms.middleware.user.CurrentUserMiddleware',
 'cms.middleware.page.CurrentPageMiddleware',
 'cms.middleware.toolbar.ToolbarMiddleware',
 'cms.middleware.language.LanguageCookieMiddleware']



Traceback:

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/db/backends/utils.py" in execute
  64.                 return self.cursor.execute(sql, params)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/db/backends/sqlite3/base.py" in execute
  328.         return Database.Cursor.execute(self, query, params)

The above exception (database is locked) was the direct cause of the following exception:

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/core/handlers/exception.py" in inner
  41.             response = get_response(request)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/core/handlers/base.py" in _legacy_get_response
  249.             response = self._get_response(request)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/core/handlers/base.py" in _get_response
  187.                 response = self.process_exception_by_middleware(e, request)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/core/handlers/base.py" in _get_response
  185.                 response = wrapped_callback(request, *callback_args, **callback_kwargs)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/utils/decorators.py" in _wrapped_view
  149.                     response = view_func(request, *args, **kwargs)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/views/decorators/cache.py" in _wrapped_view_func
  57.         response = view_func(request, *args, **kwargs)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/contrib/admin/sites.py" in inner
  224.             return view(request, *args, **kwargs)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/views/decorators/clickjacking.py" in wrapped_view
  39.         resp = view_func(*args, **kwargs)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/cms/admin/placeholderadmin.py" in add_plugin
  367.         response = plugin_instance.add_view(request)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/contrib/admin/options.py" in add_view
  1509.         return self.changeform_view(request, None, form_url, extra_context)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/utils/decorators.py" in _wrapper
  67.             return bound_func(*args, **kwargs)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/utils/decorators.py" in _wrapped_view
  149.                     response = view_func(request, *args, **kwargs)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/utils/decorators.py" in bound_func
  63.                 return func.__get__(self, type(self))(*args2, **kwargs2)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/contrib/admin/options.py" in changeform_view
  1409.             return self._changeform_view(request, object_id, form_url, extra_context)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/contrib/admin/options.py" in _changeform_view
  1449.                 self.save_model(request, new_object, form, not add)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/cms/plugin_base.py" in save_model
  303.         return super(CMSPluginBase, self).save_model(request, obj, form, change)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/contrib/admin/options.py" in save_model
  980.         obj.save()

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/cms/models/pluginmodel.py" in save
  341.                 self.add_root(instance=self)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/treebeard/mp_tree.py" in add_root
  625.         return MP_AddRootHandler(cls, **kwargs).process()

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/treebeard/mp_tree.py" in process
  345.         newobj.save()

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/cms/models/pluginmodel.py" in save
  343.         super(CMSPlugin, self).save(*args, **kwargs)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/db/models/base.py" in save
  808.                        force_update=force_update, update_fields=update_fields)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/db/models/base.py" in save_base
  833.                 update_fields=update_fields,

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/dispatch/dispatcher.py" in send
  193.             for receiver in self._live_receivers(sender)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/dispatch/dispatcher.py" in <listcomp>
  193.             for receiver in self._live_receivers(sender)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/cms/signals/plugins.py" in pre_save_plugins
  30.     set_dirty(plugin)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/cms/signals/plugins.py" in set_dirty
  21.         placeholder.mark_as_dirty(language, clear_cache=delete_cache)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/cms/models/placeholdermodel.py" in mark_as_dirty
  529.             ).update(publisher_state=PUBLISHER_STATE_DIRTY)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/db/models/query.py" in update
  650.             rows = query.get_compiler(self.db).execute_sql(CURSOR)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/db/models/sql/compiler.py" in execute_sql
  1204.         cursor = super(SQLUpdateCompiler, self).execute_sql(result_type)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/db/models/sql/compiler.py" in execute_sql
  899.             raise original_exception

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/db/models/sql/compiler.py" in execute_sql
  889.             cursor.execute(sql, params)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/db/backends/utils.py" in execute
  79.             return super(CursorDebugWrapper, self).execute(sql, params)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/db/backends/utils.py" in execute
  64.                 return self.cursor.execute(sql, params)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/db/utils.py" in __exit__
  94.                 six.reraise(dj_exc_type, dj_exc_value, traceback)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/utils/six.py" in reraise
  685.             raise value.with_traceback(tb)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/db/backends/utils.py" in execute
  64.                 return self.cursor.execute(sql, params)

File "/home/emencia/projects/cdn2018/.envs/default/lib/python3.5/site-packages/django/db/backends/sqlite3/base.py" in execute
  328.         return Database.Cursor.execute(self, query, params)

Exception Type: OperationalError at /admin/cms/page/add-plugin/
Exception Value: database is locked

Environment

• Python version: 3.5.2
• Django version: From 1.11.12 to 1.11.16
• django CMS version: From 3.4.6 to 3.5.2
• Database type: SQlite and PostgreSQL

[sveetch]

After many tests i found that bug (which trigger twice the POST request to add-plugin or edit-plugin views) does not occurs on all browser.

It does not happen with:

• Firefox 40.3 on Windows Seven;
• Internet Explorer 11 on Windows Seven;
• Chromium version 69.0.3497.81 on Ubuntu 18.04;

It does happen with:

• Firefox 62 and 63 on Ubuntu 18.04;
• Firefox 62.0.3 on iOS 10.13.4;

[Pankrat]

I have a similar issue in a similar environment. In the browser network tab it looks like this:

The stack trace is slightly different:

IntegrityError: duplicate key value violates unique constraint "cms_cmsplugin_path_7692c19a7d5df9d5_uniq"
DETAIL:  Key (path)=(18MY) already exists.

  File "django/core/handlers/exception.py", line 41, in inner
    response = get_response(request)
  File "django/core/handlers/base.py", line 249, in _legacy_get_response
    response = self._get_response(request)
  File "django/core/handlers/base.py", line 187, in _get_response
    response = self.process_exception_by_middleware(e, request)
  File "django/core/handlers/base.py", line 185, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "python3.5/contextlib.py", line 30, in inner
    return func(*args, **kwds)
  File "django/utils/decorators.py", line 149, in _wrapped_view
    response = view_func(request, *args, **kwargs)
  File "django/views/decorators/cache.py", line 57, in _wrapped_view_func
    response = view_func(request, *args, **kwargs)
  File "django/contrib/admin/sites.py", line 224, in inner
    return view(request, *args, **kwargs)
  File "django/views/decorators/clickjacking.py", line 39, in wrapped_view
    resp = view_func(*args, **kwargs)
  File "cms/admin/placeholderadmin.py", line 367, in add_plugin
    response = plugin_instance.add_view(request)
  File "django/contrib/admin/options.py", line 1509, in add_view
    return self.changeform_view(request, None, form_url, extra_context)
  File "django/utils/decorators.py", line 67, in _wrapper
    return bound_func(*args, **kwargs)
  File "django/utils/decorators.py", line 149, in _wrapped_view
    response = view_func(request, *args, **kwargs)
  File "django/utils/decorators.py", line 63, in bound_func
    return func.__get__(self, type(self))(*args2, **kwargs2)
  File "django/contrib/admin/options.py", line 1409, in changeform_view
    return self._changeform_view(request, object_id, form_url, extra_context)
  File "django/contrib/admin/options.py", line 1449, in _changeform_view
    self.save_model(request, new_object, form, not add)
  File "cms/plugin_base.py", line 303, in save_model
    return super(CMSPluginBase, self).save_model(request, obj, form, change)
  File "django/contrib/admin/options.py", line 980, in save_model
    obj.save()
  File "cms/models/pluginmodel.py", line 341, in save
    self.add_root(instance=self)
  File "treebeard/mp_tree.py", line 625, in add_root
    return MP_AddRootHandler(cls, **kwargs).process()
  File "treebeard/mp_tree.py", line 345, in process
    newobj.save()
  File "cms/models/pluginmodel.py", line 343, in save
    super(CMSPlugin, self).save(*args, **kwargs)
  File "django/db/models/base.py", line 808, in save
    force_update=force_update, update_fields=update_fields)
  File "django/db/models/base.py", line 837, in save_base
    self._save_parents(cls, using, update_fields)
  File "django/db/models/base.py", line 864, in _save_parents
    self._save_table(cls=parent, using=using, update_fields=update_fields)
  File "django/db/models/base.py", line 924, in _save_table
    result = self._do_insert(cls._base_manager, using, fields, update_pk, raw)
  File "django/db/models/base.py", line 963, in _do_insert
    using=using, raw=raw)
  File "django/db/models/manager.py", line 85, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "django/db/models/query.py", line 1076, in _insert
    return query.get_compiler(using=using).execute_sql(return_id)
  File "django/db/models/sql/compiler.py", line 1112, in execute_sql
    cursor.execute(sql, params)
  File "raven/contrib/django/client.py", line 127, in execute
    return real_execute(self, sql, params)
  File "django/db/backends/utils.py", line 64, in execute
    return self.cursor.execute(sql, params)
  File "django/db/utils.py", line 94, in __exit__
    six.reraise(dj_exc_type, dj_exc_value, traceback)
  File "django/utils/six.py", line 685, in reraise
    raise value.with_traceback(tb)
  File "django/db/backends/utils.py", line 64, in execute
    return self.cursor.execute(sql, params)

Environment

• Python 3.5.2 and 2.7
• Django 1.11.16
• Django CMS 3.4.6
• Database PostgreSQL

I could only reproduce this issue with Firefox 62/63. Disabling browser plugins didn't seem to have an effect.

[sveetch]

@Pankrat well you are not ending on "database locked" or duplicate object probably because your plugin have some field with unique clause, like a slug or custom id.

What i am wondering is that does your plugin have some image or file field ? Because i thought this bug of twice requests was related to image/file field that confused some code from cms frontend.

[Pankrat]

Yes, my plugin model derived from CMSPlugin has an ImageField.

[sveetch]

For history, i still reproduce this bug with recent environment.

• Python version: 3.5.2
• Django version: 2.1.8
• django CMS version: 3.6.0
• Firefox 67.0.2