correct verbosity on CEF logs - bug 627202 - r=telliott
authorTarek Ziade <tarek@ziade.org>
Mon, 31 Jan 2011 22:40:58 +0100
changeset 198 686c14638a85f59bee831cc4a34c1afef13e83f3
parent 197 36ce8dcbaa791cae1bfafa641c14917cccf33199
child 199 02b407388c437e08d232edff9be94f71c9e4576e
push id129
push usertziade@mozilla.com
push dateMon, 31 Jan 2011 21:51:08 +0000
reviewerstelliott
bugs627202
correct verbosity on CEF logs - bug 627202 - r=telliott
keyexchange/filtering/middleware.py
keyexchange/tests/test_keyexchange.py
keyexchange/wsgiapp.py
--- a/keyexchange/filtering/middleware.py
+++ b/keyexchange/filtering/middleware.py
@@ -61,17 +61,18 @@ from keyexchange.filtering.ipqueue impor
 class IPFiltering(object):
     """Filtering IPs
     """
     def __init__(self, app, blacklist_ttl=300, br_blacklist_ttl=86400,
                  queue_size=200, br_queue_size=20, treshold=20,
                  br_treshold=5, cache_servers=['127.0.0.0.1:11211'],
                  admin_page=None, use_memory=False, refresh_frequency=1,
                  observe=False, callback=None, ip_whitelist=None,
-                 async=True, update_blfreq=None, ip_queue_ttl=360):
+                 async=True, update_blfreq=None, ip_queue_ttl=360,
+                 br_callback=None):
 
         """Initializes the middleware.
 
         - app: the wsgi application the middleware wraps
         - blacklist_ttl: defines how long in seconds an IP is blacklisted
         - br_blacklist_ttl: defines how long in seconds an IP that did too many
           bad requests is blacklisted
         - queue_size: Size of the queue used to keep track of the last callers
@@ -81,16 +82,18 @@ class IPFiltering(object):
         - br_treshold: max number of bad request per IP before we blacklist it.
         - observe: if set to True, IPs are still blacklisted but not rejected.
           This mode is useful to observe the behavior of an application without
           rejecting any call, to make sure a configuration works fine. Notice
           that a blacklisted IP will continue to raise its counter in the
           queue.
         - callback: callable that will be called with an IP that is added
           in the blacklist.
+        - br_callback: callable that will be called when a bad request is
+          caught.
         - ip_whitelist: a list of IP that should never be blacklisted.
           Supports all netmask notations.
         - async: if True, uses a thread to sync the blacklist. Otherwise
           updates it every update_blfreq requests.
         - update_blfreq: number of requests before the blacklist is updated.
           async must be False.
         - ip_queue_ttl: Maximum time to live for an IP in the queues.
         """
@@ -115,16 +118,18 @@ class IPFiltering(object):
         self._blacklisted = Blacklist(self._cache_server, refresh_frequency,
                                       self.async)
         if admin_page is not None and not admin_page.startswith('/'):
             admin_page = '/' + admin_page
         self.admin_page = admin_page
         admin_mako = os.path.join(os.path.dirname(__file__), 'admin.mako')
         self._admin_tpl = Template(filename=admin_mako)
         self.callback = callback
+        self.br_callback = br_callback
+
         if ip_whitelist is None:
             self.ip_whitelist = []
         else:
             self.ip_whitelist = [IP(ip) for ip in ip_whitelist]
 
     def _is_whitelisted(self, ip):
         for ip_range in self.ip_whitelist:
             try:
@@ -156,16 +161,22 @@ class IPFiltering(object):
             # blacklisting the IP
             self._blacklisted.add(ip, self.blacklist_ttl)
             if self.callback is not None:
                 self.callback(ip, environ)
 
     def _inc_bad_request(self, ip, environ):
         if self._is_whitelisted(ip):
             return
+
+        if self.br_callback is not None:
+                self.br_callback(ip, environ)
+
+        if self.observe and ip in self._blacklisted:
+            return
         # insert the IP in the br queue
         # if the queue is full, the opposite-end item is discarded
         self._last_br_ips.append(ip)
 
         # counts its occurences in the queue
         if self._last_br_ips.count(ip) >= self.br_treshold:
             # blacklisting the IP
             self._blacklisted.add(ip, self.br_blacklist_ttl)
--- a/keyexchange/tests/test_keyexchange.py
+++ b/keyexchange/tests/test_keyexchange.py
@@ -37,16 +37,17 @@
 """
 import unittest
 import threading
 import json
 import time
 import random
 import hashlib
 import os
+import tempfile
 
 from webtest import TestApp, AppError
 from paste.deploy import loadapp
 
 from keyexchange import wsgiapp
 from keyexchange.tests.client import JPAKE
 from keyexchange.util import MemoryClient
 
@@ -185,16 +186,27 @@ class TestWsgiApp(unittest.TestCase):
     def setUp(self):
         ini_file = os.path.join(HERE, '..', '..', 'etc',
                                 'tests.ini')
         app = loadapp('config:%s' % ini_file)
         # we don't test this here
         app.max_bad_request_calls = 100000
         self.app = TestApp(app)
         self.app.env = self.env = {'REMOTE_ADDR': '127.0.0.1'}
+        self._files = []
+
+    def tearDown(self):
+        for file_ in self._files:
+            if os.path.exists(file_):
+                os.remove(file_)
+
+    def _tmpfile(self):
+        fd, name = tempfile.mkstemp()
+        self._files.append(name)
+        return name
 
     def test_session(self):
         # we want to send data in a secure channel
         data = {'username': 'bob',
                 'password': 'secret'}
 
         # let's create two end-points
         bob = Sender('Bob', 'secret', self.app, data)
@@ -359,17 +371,17 @@ class TestWsgiApp(unittest.TestCase):
         headers = {'X-KeyExchange-Id': 'b' * 256}
         res = self.app.get('/new_channel', headers=headers,
                            extra_environ=self.env)
         cid = str(json.loads(res.body))
         curl = '/%s' % cid
         logs = []
 
         def _counter(log, *args, **kw):
-            logs.append(log)
+            logs.append(kw['msg'])
 
         # the channel is present
         self.app.get(curl, status=200, headers=headers,
                      extra_environ=self.env)
 
         # let's report a log message (and ask for deletion)
         old = wsgiapp.log_cef
         wsgiapp.log_cef = _counter
@@ -417,17 +429,17 @@ class TestWsgiApp(unittest.TestCase):
         # channel should not exist anymore
         self.app.get(curl, status=404, headers=headers,
                      extra_environ=self.env)
 
     def test_report(self):
         logs = []
 
         def _counter(log, *args, **kw):
-            logs.append(log)
+            logs.append(kw['msg'])
 
         headers = {'X-KeyExchange-Log': 'some'}
         old = wsgiapp.log_cef
         wsgiapp.log_cef = _counter
         try:
             self.app.post('/report', params='somelog', extra_environ=self.env)
             self.app.post('/report', params='more', extra_environ=self.env,
                           headers=headers)
@@ -569,8 +581,61 @@ class TestWsgiApp(unittest.TestCase):
     def test_new_channel_header(self):
         headers = {'X-KeyExchange-Id': 'b' * 256}
         res = self.app.get('/new_channel', status=200,
                            headers=headers, extra_environ=self.env)
         cid = str(json.loads(res.body))
 
         # checking that the header is also present
         self.assertEqual(res.headers['X-KeyExchange-Channel'], cid)
+
+    def test_new_channel_observe_mode_cef(self):
+
+        logfile = self._tmpfile()
+
+        # we want to work in observe mode
+        config = {'keyexchange.use_memory': True,
+                  'filtering.use': True,
+                  'filtering.treshold': 1,
+                  'filtering.use_memory': True,
+                  'filtering.observe': True,
+                  'cef.use': True,
+                  'cef.file': logfile,
+                  'cef.version': '1',
+                  'cef.vendor': 'moz',
+                  'cef.device_version': '1',
+                  'cef.product': 'keyex'}
+
+        app = wsgiapp.make_app(config)
+        test_app = TestApp(app)
+        test_app.env = self.env = {'REMOTE_ADDR': '127.0.0.1'}
+
+        key = ("0987507938961303790993045438290584563289655491418028073179828"
+               "34980265161474647d3361865e53d1d7c5a1fa70481fe988c34a29e4acfaf"
+               "b16362dc0b73905a207bfed485d6e52ebefd14c26cb79247f24e5dfaf931e"
+               "574c39acdecba375e81a560b00a311765cc02b5a4d01804955e7256317418"
+               "af1cc1fb84ae123123")
+
+        headers = {'X-KeyExchange-Id': key}
+
+        # let's do one call (id too long)
+        test_app.get('/new_channel', status=400,
+                     headers=headers, extra_environ=self.env)
+
+        # we should be blacklisted now. but in observe mode,
+        # life continues
+        for i in range(10):
+            test_app.get('/new_channel', status=400,
+                         headers=headers, extra_environ=self.env)
+
+        headers = {'X-KeyExchange-Id': 'x' * 256}
+        test_app.get('/new_channel', status=200,
+                     headers=headers, extra_environ=self.env)
+
+        # now let's check the CEF logs, we should have only
+        # one 'blacklisted' event, followed by 11 bad requests events.
+        with open(logfile) as f:
+            logs = [line.split('|')[4]
+                    for line in f.read().split('\n')
+                    if line.strip() != '']
+
+        self.assertEqual(logs.count('BlacklistedIP'), 1)
+        self.assertEqual(logs.count('InvalidClientId'), 11)
--- a/keyexchange/wsgiapp.py
+++ b/keyexchange/wsgiapp.py
@@ -336,17 +336,18 @@ class KeyExchangeApp(object):
         if body_log != '':
             log.append(body_log)
 
         if len(log) == 0:
             # log is empty
             raise HTTPBadRequest()
 
         log = '\n'.join(log)
-        log_cef(log, 5, request.environ, self.config, signature=_REPORT)
+        log_cef('Report', 5, request.environ, self.config, signature=_REPORT,
+                msg=log)
 
         # removing the channel if present
         channel_id = request.headers.get('X-KeyExchange-Cid')
         if client_id is not None and channel_id is not None:
             content = self.cache.get(channel_id)
             if content is not None:
                 # the channel is still existing
                 ttl, ids, data, etag = content