1410559 - Invalid form causes ISE

Status: RESOLVED DUPLICATE of bug 1269146

(developer.mozilla.org Graveyard :: File attachments, defect, P1)

Description

[Ryan Johnson (:rjohnson)]

What did you do?
================
* User (sheppy) reported connection timeout when doing POST to https://developer.mozilla.org/en-US/docs/Web/HTML/Element/input/tel$files
* I investigated the logs in Papertrail and for that endpoint, at the time that sheppy reported the issues, I found two ISE's and several 408's.

What happened?
==============
The ISE's were due to a KeyError (key 'file' missing from 'cleaned_data' dict) at line 43 in kuma/attachments/forms.py:

self.mime_type = self.mime_type_from_file(cleaned_data['file'])

Here's the raw output from Papertrail:

Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"http_app_kuma: 2017-10-20 14:07:45,011 django.request:ERROR Internal Server Error: /en-US/docs/Web/HTML/Element/input/tel$files: /usr/local/lib/python2.7/dist-packages/django/core/handlers/base.py:256\n","stream":"stderr","time":"2017-10-20T21:07:45.01257369Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"Traceback (most recent call last):\n","stream":"stderr","time":"2017-10-20T21:07:45.012603216Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"  File \"/usr/local/lib/python2.7/dist-packages/django/core/handlers/base.py\", line 132, in get_response\n","stream":"stderr","time":"2017-10-20T21:07:45.01260755Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"    response = wrapped_callback(request, *callback_args, **callback_kwargs)\n","stream":"stderr","time":"2017-10-20T21:07:45.012611377Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"  File \"/usr/local/lib/python2.7/dist-packages/newrelic/hooks/framework_django.py\", line 527, in wrapper\n","stream":"stderr","time":"2017-10-20T21:07:45.012614551Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"    return wrapped(*args, **kwargs)\n","stream":"stderr","time":"2017-10-20T21:07:45.012617736Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"  File \"/usr/local/lib/python2.7/dist-packages/django/views/decorators/clickjacking.py\", line 41, in wrapped_view\n","stream":"stderr","time":"2017-10-20T21:07:45.012621374Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"    resp = view_func(*args, **kwargs)\n","stream":"stderr","time":"2017-10-20T21:07:45.012624346Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"  File \"/app/kuma/core/decorators.py\", line 47, in _wrapped_view\n","stream":"stderr","time":"2017-10-20T21:07:45.012627161Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"    return view_fn(request, *args, **kwargs)\n","stream":"stderr","time":"2017-10-20T21:07:45.012630283Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"  File \"/app/kuma/wiki/decorators.py\", line 107, in process\n","stream":"stderr","time":"2017-10-20T21:07:45.012633551Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"    return func(request, *args, **kwargs)\n","stream":"stderr","time":"2017-10-20T21:07:45.012636683Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"  File \"/app/kuma/attachments/views.py\", line 103, in edit_attachment\n","stream":"stderr","time":"2017-10-20T21:07:45.012639572Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"    if form.is_valid():\n","stream":"stderr","time":"2017-10-20T21:07:45.01264282Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"  File \"/usr/local/lib/python2.7/dist-packages/django/forms/forms.py\", line 184, in is_valid\n","stream":"stderr","time":"2017-10-20T21:07:45.012645786Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"    return self.is_bound and not self.errors\n","stream":"stderr","time":"2017-10-20T21:07:45.012648501Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"  File \"/usr/local/lib/python2.7/dist-packages/django/forms/forms.py\", line 176, in errors\n","stream":"stderr","time":"2017-10-20T21:07:45.012651013Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"    self.full_clean()\n","stream":"stderr","time":"2017-10-20T21:07:45.012653665Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"  File \"/usr/local/lib/python2.7/dist-packages/django/forms/forms.py\", line 393, in full_clean\n","stream":"stderr","time":"2017-10-20T21:07:45.012656236Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"    self._clean_form()\n","stream":"stderr","time":"2017-10-20T21:07:45.0126589Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"  File \"/usr/local/lib/python2.7/dist-packages/django/forms/forms.py\", line 417, in _clean_form\n","stream":"stderr","time":"2017-10-20T21:07:45.01266144Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"    cleaned_data = self.clean()\n","stream":"stderr","time":"2017-10-20T21:07:45.0126641Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"  File \"/app/kuma/attachments/forms.py\", line 43, in clean\n","stream":"stderr","time":"2017-10-20T21:07:45.012666668Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"    self.mime_type = self.mime_type_from_file(cleaned_data['file'])\n","stream":"stderr","time":"2017-10-20T21:07:45.012669333Z"}
Oct 20 14:07:45 ip-172-20-54-65 kubernetes.var.log.containers.web-3188629585-x1rpt_mdn-prod_web-: {"log":"KeyError: 'file'\n","stream":"stderr","time":"2017-10-20T21:07:45.012672142Z"}




What should have happened?
==========================
It should have reported a form validation error.

Is there anything else we should know?
======================================

Comment 2

[[github robot]]

Commits pushed to master at https://github.com/mozilla/kuma

https://github.com/mozilla/kuma/commit/94b318dd6886d6e4c3f98bfeb60b459a038b7c13
bug 1410559: prevent ISE when no file in cleaned data

https://github.com/mozilla/kuma/commit/91ca32953734d32c52dd9438f717774034080b5c
Merge pull request #4475 from escattone/fix-file-attachment-ise-1410559

bug 1410559: prevent ISE when no file in cleaned data