Skip to content

SuspiciousOperation, add logging and no longer return 500 from handler #1207

Closed
wants to merge 40 commits into from

4 participants

@ptone
Django member
ptone commented May 23, 2013

For ticket #19866

Will squash/rebase after review

@dstufft

This should probably be logger.exception()

@dstufft
Django member

Not sure that this is the best way to do this. All suspicious operations are going to be sent on the django.security logger with no way to silence a particular one. You should probably handle this logging at each place SuspiciousOperation is being raised at with properly named loggers (e.g. logger.getLogger('django.security.save_files')).

Django member

I don't think I agree with this implementation choice. If the actual exception is passed as extra data with the logged warning, then a trivial two or three line custom filter can silence whichever ones you want, without having to proliferate separate sub-loggers for every new place we raise SuspiciousOperation. More importantly, I think unconditionally logging SuspiciousOperation whenever it is raised is a bad idea. If I catch a SuspiciousOperation (or subclass), that implies that my code expected it and knows how to handle it. If it should be logged, the code catching it can log it appropriately; otherwise, if it's caught it should be assumed that it's being handled properly and doesn't need to be logged. We should just be logging exceptions that get up to the handler without being caught.

Django member

Given the option to silence everything, or figure out how the fuck to write a filter and actually write it most people are going to just silence everything.

Django member

Maybe. There's an example of a filter in Django's own codebase, and it is used in the default logging config, which is where people who don't know how to use logging are most likely to look first for examples. Using a filter isn't any harder than silencing a particular logger.

That said, I don't feel that strongly about it; the sub-loggers are ok. The part I really don't like is SuspiciousOperation automatically logging whenever it is raised; I'll say more about that in a separate comment.

@carljm carljm commented on an outdated diff May 23, 2013
django/contrib/admin/exceptions.py
@@ -0,0 +1,6 @@
+from django.core.exceptions import SuspiciousOperation
+
+
+class DisallowedModeladminLookup(SuspiciousOperation):
@carljm
Django member
carljm added a note May 23, 2013

I think for consistency with the rest of the codebase, it should be ModelAdmin not Modeladmin

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@carljm carljm commented on an outdated diff May 23, 2013
django/contrib/admin/exceptions.py
@@ -0,0 +1,6 @@
+from django.core.exceptions import SuspiciousOperation
+
+
+class DisallowedModeladminLookup(SuspiciousOperation):
+ "Invalid filter was passed to admin view via URL querystring"
@carljm
Django member
carljm added a note May 23, 2013

PEP 257 recommends triple-quoting all docstrings, even if they fit on one line, and AFAIK that's our usual practice.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@carljm carljm and 1 other commented on an outdated diff May 23, 2013
django/core/handlers/base.py
@@ -170,6 +170,22 @@ def get_response(self, request):
response = self.handle_uncaught_exception(request,
resolver, sys.exc_info())
+ except SuspiciousOperation as e:
+ logger.warning(
@carljm
Django member
carljm added a note May 23, 2013

So we double-log any uncaught SuspiciousOperation, once as an error when it is raised and once as a warning when it gets here (but the warning won't actually do anything by default because the default handler is set to level: error). This doesn't seem right; what's the value in double-logging? Either this log should be removed, or we should remove the log-when-raised behavior.

@ptone
Django member
ptone added a note May 24, 2013

Yes, this is double logging, but in this case the logger is 'django.request' not 'django.security', so it is being logged once to each logger. I followed the pattern established for other handled exceptions in the base handler, assuming this represents a category of information that if you are monitoring the 'django.request' logger differently than you are the 'django.security' logger. But I agree that it could be considered redundant, just pointing out the nuance.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@carljm
Django member
carljm commented May 23, 2013

This mostly looks great, thanks for the work on it! Left a couple smaller comments above.

The main issue I have with it is making SuspiciousOperation log itself by default. I think this is an unfortunate loss of flexibility. IIUC it was done because Django itself catches SuspiciousOperation a few places, and those won't make it up to the WSGI handler. But on a closer look, the only place Django does this is in the session backends, and I think that's a good example of why we shouldn't make SuspiciousOperation log itself automatically at a fixed severity. A mismatched session data hash is a less severe problem than an uncaught SuspiciousOperation that results in the user getting a 400 error. Do we want to be upgrading mismatched session hash to something that triggers an admin email on every occurrence? I would say the mismatched session hash should be logged as a warning, not an error, because the session backends are able to recover gracefully and handle it well (just create a new session), whereas unhandled SuspiciousOperation should be logged as an error.

Fortunately, that's how exceptions are supposed to work: if you know how to handle them, you do so, if you don't know how to handle them, you let them bubble up to a layer that does know how. By making SuspiciousOperation log itself, we remove this flexibility from determining how they are logged.

My specific proposal:

  1. Remove the automatic logging in SuspiciousOperation.__init__ (and update the docs on SuspiciousOperation accordingly).
  2. Upgrade the logging in the handler to error instead of warning.
  3. Where the session backends catch SuspiciousSession, have them log it as a warning.
@ptone
Django member
ptone commented May 24, 2013

@carljm thanks for your review!

I only partially agree about the logging when raised comment - namely I do think that SuspiciousOperation should be logged when it is raised, every time. This does not mean it has to be done via the init as is done in the current implementation - the more verbose way would be to add additional explicit 'except SuspOp' clauses to add logging, for example:

https://github.com/django/django/blob/master/django/contrib/sessions/backends/base.py#L100

I'm weakly split between this being worth the extra code and verbosity, and also making it something that has to be remembered to be done any time new handling of SuspOp is added in the future, vs leaving it in the SuspOp init. There are a pretty small number of places to hunt it down currently - so I'd be happy to change the implementation. But I do think that a log message should be generated every time it is raised, one way or the other.

There is no SuspiciousOperation that should lead to mailing the admins really IMO - a single spurious occurrence is not, in and of itself, a clear sign of a security problem, but a high frequency is something to be aware of. A responsible developer would wire the logging config up to something like Sentry or other monitoring software, and set threshold triggers to be notified if some suspicious operation was happening with some frequency. The decision to use mail-admins handler was based on preserving the current behavior of mailing admins for uncaught SuspOps, and the general opinion that security should be loud by default, but something you can turn down, instead of the inverse. In that sense, leaving it as mail-admins by default could be considered the annoying "seat-belt" alarm of your car - not sure where the project should stand on "loud and annoying by default" vs "we are not your mom". Maybe something for @jacobian to weigh in on in terms of security design?

One of the items you bring up is the range of severity when SuspOp is raised. In fact the origin of the ticket was people being annoyed at getting emails about ALLOWED_HOST related SuspOps. Since I think no single occurrence of a SuspOp is a severe situation, I'd be inclined to treat them all as the same severity - and let people come up with ways to monitor their frequency. This is a little like how we currently don't do anything about rate limiting login attempts. And now that I think of it, we have a completely mixed approach here, having recently added user_login_failed signal :(

@ptone
Django member
ptone commented on 277e48a May 24, 2013

@carljm as you can see, we've hardly been consistent on this

@carljm
Django member
carljm commented May 24, 2013

@ptone I don't think we're far apart here, as I agree that it's good for Django to log every SuspiciousOperation, I just think that it should be done explicitly when the exception is caught, allowing for more flexibility in terms of how it is logged in each particular case.

Re logging levels, while it's true that the default mail_admins handler is not very useful and most projects ought to replace it with something better like Sentry, I'm fairly sure the vast majority of Django sites actually run with default logging settings and mail_admins, so we need to make the defaults reasonable (and give some thought to backwards-compatibility), rather than just say "let's make the defaults as noisy as possible and force people to sort it out themselves" - as @dstufft says, that will just result in people silencing everything because they don't want to bother figuring it out. In this particular case, I think that just means that session-hash-mismatches, which historically have been completely silent, should not now suddenly trigger a mail-admins by default (but should be logged; if we log them at "warning" rather than "error" level they won't trigger a mail to admins).

Does that make sense? I'm happy to push a proposed implementation of this so we can compare, would that be useful?

@dstufft
Django member
dstufft commented May 24, 2013

I agree on doing it in the actual code and not in the __init__.

I also agree on being mindful of how noisy the various messages will be and quieting ones that are likely to give a lot of false positives.

@ptone
Django member
ptone commented May 24, 2013

@carljm agree we are very close. I'm happy to push a commit showing the log @ handle rather than init - really the number of places this needs to be done could be counted on 1 hand I believe.

As to "loudness", my personal opinion would be to be quiet by default for SuspOps, since I do think it is all about the pattern. So I won't take any convincing on that point. I do think that all SuspOps should be ranked more or less equal, again, because it is about the pattern, none of them are "oh no, the sky is falling" class errors. If this is the case, the making them quiet will result in silencing some SuspOps that used to mail admins if they reached the WSGI handler. I feel that silencing these in the interest of being right and consistent is worth the change in behavior on this point, and it can be emphasized more strongly in both the docs and release note.

@ptone
Django member
ptone commented May 24, 2013

Branch of branch:
ptone@ticket/19866-susop...susop-log-at-handle

Two final points to reach consensus on:
1. Should all SuspOps be considered equal in severity, or are some considered more prone to false positives, so remain as warnings, while any SuspOp that reaches the WSGI handler be considered an error. I'm for the former, but comments from @dstufft and @carljm imply a belief that not all SuspOps are created equal - and there is the issue of changing current behavior less. If we go with the greater behavior change (but more consistent approach IMO) then the docs should be beefed up to point this out.

  1. Should a SuspOp that reaches the WSGI handler causing a 400-bad-request be logged twice, once for on the django.request logger (as is done for other 4xx/5xx) and once for the security logger, or just the latter?
@ptone
Django member
ptone commented May 24, 2013

another point, is while I handled all the places I'm aware of where SuspOp is handled, and reviewed how it is raised and believe it would otherwise bubble up to the WSGI handler, I'm not %1000 sure that any of the

ack '^ *except.*Exception' 

places may not somehow catch one on the way to the handler

@carljm
Django member
carljm commented May 24, 2013

My thoughts on the raised questions:

1) I'm not concerned about except Exception in random places in the codebase. Or rather, I am, because that's generally smelly, but I don't think we need to worry about every one of those in this patch and try to make a 100% guarantee that none of those could ever possibly catch a SuspiciousOperation.

2) I think it's fine to just log them to django.security and not django.request.

3) I still think that there is a real severity difference between a SuspiciousOperation that can be gracefully recovered from and one that results in the user seeing a 400 Bad Request. And I don't think that an error that results in a 400 Bad Request should be silent by default (especially if in the past it wasn't silent). It's not because a single occurrence of any of them is a "sky is falling" situation (that's also not necessarily true of 500 errors), it's because an "unknown error" type response going out to a user (even if it might be a malicious user) is a situation a site owner should know about by default. I think "it's all about the pattern" is irrelevant, since we have no mechanism in core for tracking error patterns (besides filling people's inboxes with a "pattern" of emails via mail_admins). We know that mail_admins is too noisy for large sites, but that doesn't mean we shouldn't still use it for things that a small-site owner will likely want to know about; and I think 400 responses fall in that category.

@carljm
Django member

This should be a docstring probably, not a comment. Also, "patches a log level" reads oddly; maybe "patches a specific logging method on a logger and yields list of messages it's called with"

@ptone
Django member
ptone commented May 24, 2013

OK - I feel this is very very close, I didn't get a lunch today, so I want to give it one more quick look before merging, when a bit fresher.

I think all the raised points in the discussion are covered.

Only remaining issue in my mind is that there are cases of a SuspiciousOperation subtype being raised that aren't specifically tested - they never were, so this isn't anything going backwards, but I could go a bit more forward here. However the outer handling of this at the WSGI handler is solid, and some of them (like the WizardForm stuff) are pretty edge-casey.

@carljm carljm commented on the diff May 25, 2013
django/contrib/sessions/backends/db.py
@@ -18,7 +20,11 @@ def load(self):
expire_date__gt=timezone.now()
)
return self.decode(s.session_data)
- except (Session.DoesNotExist, SuspiciousOperation):
+ except (Session.DoesNotExist, SuspiciousOperation) as e:
@carljm
Django member
carljm added a note May 25, 2013

Minor quibble, since it's highly unlikely any other SuspiciousOperation could have been raised here, but really this should catch SuspiciousSession

@carljm
Django member
carljm added a note May 25, 2013

Or wait, perhaps I'm wrong; could this also catch InvalidSessionKey?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@carljm carljm commented on the diff May 25, 2013
django/contrib/formtools/exceptions.py
@@ -0,0 +1,6 @@
+from django.core.exceptions import SuspiciousOperation
+
+
+class WizardViewCookieModified(SuspiciousOperation):
+ """Signature of cookie modified"""
+ pass
@carljm
Django member
carljm added a note May 25, 2013

When there is a docstring, the pass isn't actually necessary. Don't particularly care whether we remove it, though.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@carljm carljm commented on the diff May 25, 2013
docs/ref/exceptions.txt
+ The :exc:`SuspiciousOperation` exception is raised when a user has
+ performed an operation that should be considered suspicious from a security
+ perspective, such as tampering with a session cookie. Subclasses of
+ SuspiciousOperation include:
+
+ * DisallowedHost
+ * DisallowedModeladminLookup
+ * DisallowedRedirect
+ * InvalidSessionKey
+ * SuspiciousFileOperation
+ * SuspiciousMultipartForm
+ * SuspiciousSession
+ * WizardViewCookieModified
+
+ Third party apps may create their own subclass of ``SuspiciousOperation``.
+ When a SuspiciousOperation is handled by Django, a warning level message is
@carljm
Django member
carljm added a note May 25, 2013

I think this sentence should now be removed; it's not really true, or not as general as it sounds. There is one specific case (session issues) where Django catches a SuspiciousOperation and logs it as a warning, but that's not necessarily a general policy or something that needs to be documented (if it were, it should be documented in the session docs I think). The following sentence covers the important part.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@carljm carljm commented on the diff May 25, 2013
docs/ref/exceptions.txt
+ SuspiciousOperation include:
+
+ * DisallowedHost
+ * DisallowedModeladminLookup
+ * DisallowedRedirect
+ * InvalidSessionKey
+ * SuspiciousFileOperation
+ * SuspiciousMultipartForm
+ * SuspiciousSession
+ * WizardViewCookieModified
+
+ Third party apps may create their own subclass of ``SuspiciousOperation``.
+ When a SuspiciousOperation is handled by Django, a warning level message is
+ logged with the ``django.security.*`` logger matching the name of the
+ subclass. If a ``SuspiciousOperation`` exception reaches the WSGI handler
+ level it is escalated and logged at an ``Error`` level and results in
@carljm
Django member
carljm added a note May 25, 2013

The phrase "escalated and" here is redundant and could be removed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@carljm carljm commented on the diff May 25, 2013
docs/topics/logging.txt
@@ -434,6 +434,41 @@ For performance reasons, SQL logging is only enabled when
``settings.DEBUG`` is set to ``True``, regardless of the logging
level or handlers that are installed.
+``django.security.*``
+~~~~~~~~~~~~~~~~~~~~~~
+
+The security loggers will receive messages on any occurence of
@carljm
Django member
carljm added a note May 25, 2013

occurrence

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@carljm carljm commented on the diff May 25, 2013
docs/topics/logging.txt
@@ -434,6 +434,41 @@ For performance reasons, SQL logging is only enabled when
``settings.DEBUG`` is set to ``True``, regardless of the logging
level or handlers that are installed.
+``django.security.*``
+~~~~~~~~~~~~~~~~~~~~~~
+
+The security loggers will receive messages on any occurence of
+:exc:`~django.core.exceptions.SuspiciousOperation`. There is a sub-logger for
+each sub-type of SuspiciousOperation. The level of the log event depends on
+where the exception is handled. Most occurences are logged as a warning, while
@carljm
Django member
carljm added a note May 25, 2013

occurrences

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@carljm carljm commented on the diff May 25, 2013
docs/topics/logging.txt
+child loggers will propogate to the parent logger. The ``django.security``
+logger is configured the same as the ``django.request`` logger, and any error
+events will be mailed to admins. Requests resulting in a 400 response due to
+a ``SuspiciousOperation`` will not be logged to the ``django.request`` logger,
+but only to the ``django.security`` logger.
+
+To silence a particular type of SuspiciousOperation, you can override that
+specific logger following this example::
+
+ 'loggers': {
+ 'django.security.DisallowedHost': {
+ 'handlers': ['null'],
+ 'propagate': False,
+ },
+
+A single :exc:`~django.core.exceptions.SuspiciousOperation` event is not likely
@carljm
Django member
carljm added a note May 25, 2013

I'm not sure this para is really helpful to have in the docs. It has to be so vague as to say almost nothing. What is a "cause for concern", what should be monitored, what constitutes "high frequency"; these are all site-specific questions.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@carljm
Django member
carljm commented May 25, 2013

Made a few minor comments; generally looks good to me.

@selwin selwin commented on the diff May 25, 2013
docs/ref/exceptions.txt
@@ -44,9 +44,27 @@ SuspiciousOperation
-------------------
.. exception:: SuspiciousOperation
- The :exc:`SuspiciousOperation` exception is raised when a user has performed
- an operation that should be considered suspicious from a security perspective,
- such as tampering with a session cookie.
+ The :exc:`SuspiciousOperation` exception is raised when a user has
+ performed an operation that should be considered suspicious from a security
+ perspective, such as tampering with a session cookie. Subclasses of
+ SuspiciousOperation include:
+
+ * DisallowedHost
+ * DisallowedModeladminLookup
@selwin
selwin added a note May 25, 2013

Should be "DisallowedModelAdminLookup" :)

@ptone
Django member
ptone added a note May 25, 2013

good catch

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@ptone
Django member
ptone commented May 27, 2013

Merged in d228c11

@ptone ptone closed this May 27, 2013
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.