← Back to branch summary

~ubuntu-branches/ubuntu/trusty/swift/trusty-updates

« back to all changes in this revision

Viewing changes to test/unit/common/middleware/test_proxy_logging.py

  • Committer: Package Import Robot
  • Author(s): Chuck Short, Soren Hansen, Chuck Short
  • Date: 2012-09-07 19:02:36 UTC
  • mfrom: (1.2.12)
  • Revision ID: package-import@ubuntu.com-20120907190236-fqrmbzm7v6zivs8d
Tags: 1.7.0-0ubuntu1
[ Soren Hansen ]
* Update debian/watch to account for symbolically named tarballs and
  use newer URL.
* Run unit tests at build time.
* Fix Launchpad URLs in debian/watch.

[ Chuck Short ]
* New upstream release
* debian/control: Add pubthon-moc as a build dep
* debian/rules: Dont fail if testsuite fails.

Show diffs side-by-side

added added

removed removed

Lines of Context:
test/unit/common/middleware/test_proxy_logging.py
16
16
import unittest
17
17
from urllib import quote, unquote
18
18
import cStringIO as StringIO
 
19
from logging.handlers import SysLogHandler
19
20
 
20
21
from webob import Request
21
22
 
 
23
from test.unit import FakeLogger
 
24
from swift.common.utils import get_logger
22
25
from swift.common.middleware import proxy_logging
23
26
 
24
27
 
64
67
        return ["FAKE APP"]
65
68
 
66
69
 
67
 
class FakeLogger(object):
68
 
    def __init__(self, *args, **kwargs):
69
 
        self.msg = ''
70
 
 
71
 
    def info(self, string):
72
 
        self.msg = string
73
 
 
74
 
 
75
70
def start_response(*args):
76
71
    pass
77
72
 
78
73
 
79
74
class TestProxyLogging(unittest.TestCase):
80
75
 
 
76
    def _log_parts(self, app):
 
77
        info_calls = app.access_logger.log_dict['info']
 
78
        self.assertEquals(1, len(info_calls))
 
79
        return info_calls[0][0][0].split(' ')
 
80
 
 
81
    def assertTiming(self, exp_metric, app, exp_timing=None):
 
82
        timing_calls = app.access_logger.log_dict['timing']
 
83
        self.assertEquals(1, len(timing_calls))
 
84
        self.assertEquals({}, timing_calls[0][1])
 
85
        self.assertEquals(2, len(timing_calls[0][0]))
 
86
        self.assertEquals(exp_metric, timing_calls[0][0][0])
 
87
        if exp_timing is not None:
 
88
            self.assertEquals(exp_timing, timing_calls[0][0][1])
 
89
 
 
90
    def assertUpdateStats(self, exp_metric, exp_bytes, app):
 
91
        update_stats_calls = app.access_logger.log_dict['update_stats']
 
92
        self.assertEquals(1, len(update_stats_calls))
 
93
        self.assertEquals({}, update_stats_calls[0][1])
 
94
        self.assertEquals((exp_metric, exp_bytes), update_stats_calls[0][0])
 
95
 
 
96
    def test_log_request_statsd_invalid_stats_types(self):
 
97
        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
 
98
        app.access_logger = FakeLogger()
 
99
        for url in ['/', '/foo', '/foo/bar', '/v1']:
 
100
            req = Request.blank(url, environ={'REQUEST_METHOD': 'GET'})
 
101
            resp = app(req.environ, start_response)
 
102
            resp_body = ''.join(resp)
 
103
            self.assertEquals(0, len(app.access_logger.log_dict['timing']))
 
104
            self.assertEquals(0,
 
105
                              len(app.access_logger.log_dict['update_stats']))
 
106
 
 
107
    def test_log_request_stat_type_bad(self):
 
108
        for bad_path in ['', '/', '/bad', '/baddy/mc_badderson', '/v1',
 
109
                         '/v1/']:
 
110
            app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
 
111
            app.access_logger = FakeLogger()
 
112
            req = Request.blank(bad_path, environ={'REQUEST_METHOD': 'GET'})
 
113
            app.log_request(req.environ, 123, 7, 13, 2.71828182846, False)
 
114
            self.assertEqual([], app.access_logger.log_dict['timing'])
 
115
            self.assertEqual([], app.access_logger.log_dict['update_stats'])
 
116
 
 
117
    def test_log_request_stat_type_good(self):
 
118
        path_types = {
 
119
            '/v1/a': 'account',
 
120
            '/v1/a/': 'account',
 
121
            '/v1/a/c': 'container',
 
122
            '/v1/a/c/': 'container',
 
123
            '/v1/a/c/o': 'object',
 
124
            '/v1/a/c/o/': 'object',
 
125
            '/v1/a/c/o/p': 'object',
 
126
            '/v1/a/c/o/p/': 'object',
 
127
            '/v1/a/c/o/p/p2': 'object',
 
128
        }
 
129
        for path, exp_type in path_types.iteritems():
 
130
            app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
 
131
            app.access_logger = FakeLogger()
 
132
            req = Request.blank(path, environ={'REQUEST_METHOD': 'GET'})
 
133
            app.log_request(req.environ, 321, 7, 13, 2.71828182846, False)
 
134
            self.assertTiming('%s.GET.321.timing' % exp_type, app,
 
135
                              exp_timing=2.71828182846 * 1000)
 
136
            self.assertUpdateStats('%s.GET.321.xfer' % exp_type, 7 + 13, app)
 
137
 
 
138
    def test_log_request_stat_method_filtering_default(self):
 
139
        method_map = {
 
140
            'foo': 'BAD_METHOD',
 
141
            '': 'BAD_METHOD',
 
142
            'PUTT': 'BAD_METHOD',
 
143
            'SPECIAL': 'BAD_METHOD',
 
144
            'GET': 'GET',
 
145
            'PUT': 'PUT',
 
146
            'COPY': 'COPY',
 
147
            'HEAD': 'HEAD',
 
148
            'POST': 'POST',
 
149
            'DELETE': 'DELETE',
 
150
        }
 
151
        for method, exp_method in method_map.iteritems():
 
152
            app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
 
153
            app.access_logger = FakeLogger()
 
154
            req = Request.blank('/v1/a/', environ={'REQUEST_METHOD': method})
 
155
            app.log_request(req.environ, 299, 11, 3, 1.17, False)
 
156
            self.assertTiming('account.%s.299.timing' % exp_method, app,
 
157
                              exp_timing=1.17 * 1000)
 
158
            self.assertUpdateStats('account.%s.299.xfer' % exp_method,
 
159
                                   11 + 3, app)
 
160
 
 
161
    def test_log_request_stat_method_filtering_custom(self):
 
162
        method_map = {
 
163
            'foo': 'BAD_METHOD',
 
164
            '': 'BAD_METHOD',
 
165
            'PUTT': 'BAD_METHOD',
 
166
            'SPECIAL': 'SPECIAL',  # will be configured
 
167
            'GET': 'GET',
 
168
            'PUT': 'PUT',
 
169
            'COPY': 'BAD_METHOD',  # prove no one's special
 
170
        }
 
171
        # this conf var supports optional leading access_
 
172
        for conf_key in ['access_log_statsd_valid_http_methods',
 
173
                         'log_statsd_valid_http_methods']:
 
174
            for method, exp_method in method_map.iteritems():
 
175
                app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {
 
176
                    conf_key: 'SPECIAL,  GET,PUT ',  # crazy spaces ok
 
177
                })
 
178
                app.access_logger = FakeLogger()
 
179
                req = Request.blank('/v1/a/c', environ={'REQUEST_METHOD': method})
 
180
                app.log_request(req.environ, 911, 4, 43, 1.01, False)
 
181
                self.assertTiming('container.%s.911.timing' % exp_method, app,
 
182
                                exp_timing=1.01 * 1000)
 
183
                self.assertUpdateStats('container.%s.911.xfer' % exp_method,
 
184
                                    4 + 43, app)
 
185
 
81
186
    def test_basic_req(self):
82
187
        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
83
188
        app.access_logger = FakeLogger()
84
189
        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
85
190
        resp = app(req.environ, start_response)
86
191
        resp_body = ''.join(resp)
87
 
        log_parts = app.access_logger.msg.split()
 
192
        log_parts = self._log_parts(app)
88
193
        self.assertEquals(log_parts[3], 'GET')
89
194
        self.assertEquals(log_parts[4], '/')
90
195
        self.assertEquals(log_parts[5], 'HTTP/1.0')
96
201
        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(
97
202
            ['some', 'chunks', 'of data']), {})
98
203
        app.access_logger = FakeLogger()
99
 
        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
 
204
        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET',
 
205
                                          'swift.source': 'SOS'})
100
206
        resp = app(req.environ, start_response)
101
207
        resp_body = ''.join(resp)
102
 
        log_parts = app.access_logger.msg.split()
 
208
        log_parts = self._log_parts(app)
103
209
        self.assertEquals(log_parts[3], 'GET')
104
210
        self.assertEquals(log_parts[4], '/')
105
211
        self.assertEquals(log_parts[5], 'HTTP/1.0')
106
212
        self.assertEquals(log_parts[6], '200')
107
213
        self.assertEquals(resp_body, 'somechunksof data')
108
214
        self.assertEquals(log_parts[11], str(len(resp_body)))
 
215
        self.assertUpdateStats('SOS.GET.200.xfer', len(resp_body), app)
109
216
 
110
217
    def test_log_headers(self):
111
218
        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(),
114
221
        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
115
222
        resp = app(req.environ, start_response)
116
223
        exhaust_generator = [x for x in resp]
117
 
        log_parts = app.access_logger.msg.split()
 
224
        log_parts = self._log_parts(app)
118
225
        headers = unquote(log_parts[14]).split('\n')
119
226
        self.assert_('Host: localhost:80' in headers)
120
227
 
122
229
        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(),
123
230
                    {'log_headers': 'yes'})
124
231
        app.access_logger = FakeLogger()
125
 
        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET',
 
232
        req = Request.blank('/v1/a/c/o/foo', environ={'REQUEST_METHOD': 'PUT',
126
233
            'wsgi.input': StringIO.StringIO('some stuff')})
127
234
        resp = app(req.environ, start_response)
128
235
        exhaust_generator = [x for x in resp]
129
 
        log_parts = app.access_logger.msg.split()
 
236
        log_parts = self._log_parts(app)
 
237
        self.assertEquals(log_parts[11], str(len('FAKE APP')))
130
238
        self.assertEquals(log_parts[10], str(len('some stuff')))
 
239
        self.assertUpdateStats('object.PUT.200.xfer',
 
240
                               len('some stuff') + len('FAKE APP'),
 
241
                               app)
131
242
 
132
243
    def test_upload_line(self):
133
244
        app = proxy_logging.ProxyLoggingMiddleware(FakeAppReadline(),
134
245
                    {'log_headers': 'yes'})
135
246
        app.access_logger = FakeLogger()
136
 
        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET',
 
247
        req = Request.blank('/v1/a/c', environ={'REQUEST_METHOD': 'POST',
137
248
            'wsgi.input': StringIO.StringIO(
138
249
                            'some stuff\nsome other stuff\n')})
139
250
        resp = app(req.environ, start_response)
140
 
        exhaust_generator = ''.join(resp)
141
 
        log_parts = app.access_logger.msg.split()
 
251
        exhaust_generator = [x for x in resp]
 
252
        log_parts = self._log_parts(app)
 
253
        self.assertEquals(log_parts[11], str(len('FAKE APP')))
142
254
        self.assertEquals(log_parts[10], str(len('some stuff\n')))
 
255
        self.assertUpdateStats('container.POST.200.xfer',
 
256
                               len('some stuff\n') + len('FAKE APP'),
 
257
                               app)
143
258
 
144
259
    def test_log_query_string(self):
145
260
        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
148
263
                'QUERY_STRING': 'x=3'})
149
264
        resp = app(req.environ, start_response)
150
265
        exhaust_generator = [x for x in resp]
151
 
        log_parts = app.access_logger.msg.split()
 
266
        log_parts = self._log_parts(app)
152
267
        self.assertEquals(unquote(log_parts[4]), '/?x=3')
153
268
 
154
269
    def test_client_logging(self):
158
273
                'REMOTE_ADDR': '1.2.3.4'})
159
274
        resp = app(req.environ, start_response)
160
275
        exhaust_generator = [x for x in resp]
161
 
        log_parts = app.access_logger.msg.split()
 
276
        log_parts = self._log_parts(app)
162
277
        self.assertEquals(log_parts[0], '1.2.3.4')  # client ip
163
278
        self.assertEquals(log_parts[1], '1.2.3.4')  # remote addr
164
279
 
165
280
    def test_proxy_client_logging(self):
166
281
        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
167
282
        app.access_logger = FakeLogger()
168
 
        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET',
169
 
                'REMOTE_ADDR': '1.2.3.4',
170
 
                'HTTP_X_FORWARDED_FOR': '4.5.6.7,8.9.10.11'
171
 
                })
 
283
        req = Request.blank('/', environ={
 
284
            'REQUEST_METHOD': 'GET',
 
285
            'REMOTE_ADDR': '1.2.3.4',
 
286
            'HTTP_X_FORWARDED_FOR': '4.5.6.7,8.9.10.11'})
172
287
        resp = app(req.environ, start_response)
173
288
        exhaust_generator = [x for x in resp]
174
 
        log_parts = app.access_logger.msg.split()
 
289
        log_parts = self._log_parts(app)
175
290
        self.assertEquals(log_parts[0], '4.5.6.7')  # client ip
176
291
        self.assertEquals(log_parts[1], '1.2.3.4')  # remote addr
177
292
 
178
293
        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
179
294
        app.access_logger = FakeLogger()
180
 
        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET',
181
 
                'REMOTE_ADDR': '1.2.3.4',
182
 
                'HTTP_X_CLUSTER_CLIENT_IP': '4.5.6.7'
183
 
                })
 
295
        req = Request.blank('/', environ={
 
296
            'REQUEST_METHOD': 'GET',
 
297
            'REMOTE_ADDR': '1.2.3.4',
 
298
            'HTTP_X_CLUSTER_CLIENT_IP': '4.5.6.7'})
184
299
        resp = app(req.environ, start_response)
185
300
        exhaust_generator = [x for x in resp]
186
 
        log_parts = app.access_logger.msg.split()
 
301
        log_parts = self._log_parts(app)
187
302
        self.assertEquals(log_parts[0], '4.5.6.7')  # client ip
188
303
        self.assertEquals(log_parts[1], '1.2.3.4')  # remote addr
189
304
 
190
305
    def test_facility(self):
191
306
        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(),
192
 
                    {'log_headers': 'yes', 'access_log_facility': 'whatever'})
 
307
                    {'log_headers': 'yes',
 
308
                     'access_log_facility': 'LOG_LOCAL7'})
 
309
        handler = get_logger.handler4logger[app.access_logger.logger]
 
310
        self.assertEquals(SysLogHandler.LOG_LOCAL7, handler.facility)
193
311
 
194
312
    def test_filter(self):
195
313
        factory = proxy_logging.filter_factory({})
198
316
 
199
317
    def test_unread_body(self):
200
318
        app = proxy_logging.ProxyLoggingMiddleware(
201
 
                FakeApp(['some', 'stuff']), {})
 
319
            FakeApp(['some', 'stuff']), {})
202
320
        app.access_logger = FakeLogger()
203
321
        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
204
322
        resp = app(req.environ, start_response)
205
323
        read_first_chunk = next(resp)
206
324
        resp.close()  # raise a GeneratorExit in middleware app_iter loop
207
 
        log_parts = app.access_logger.msg.split()
 
325
        log_parts = self._log_parts(app)
208
326
        self.assertEquals(log_parts[6], '499')
209
327
        self.assertEquals(log_parts[11], '4')  # write length
210
328
 
218
336
            body = ''.join(resp)
219
337
        except Exception:
220
338
            pass
221
 
        log_parts = app.access_logger.msg.split()
 
339
        log_parts = self._log_parts(app)
222
340
        self.assertEquals(log_parts[6], '499')
223
341
        self.assertEquals(log_parts[10], '-')  # read length
224
342
 
225
343
    def test_disconnect_on_read(self):
226
344
        app = proxy_logging.ProxyLoggingMiddleware(
227
 
                FakeApp(['some', 'stuff']), {})
 
345
            FakeApp(['some', 'stuff']), {})
228
346
        app.access_logger = FakeLogger()
229
347
        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET',
230
348
            'wsgi.input': FileLikeExceptor()})
233
351
            body = ''.join(resp)
234
352
        except Exception:
235
353
            pass
236
 
        log_parts = app.access_logger.msg.split()
 
354
        log_parts = self._log_parts(app)
237
355
        self.assertEquals(log_parts[6], '499')
238
356
        self.assertEquals(log_parts[10], '-')  # read length
239
357
 
240
 
    def test_no_content_length_no_transfer_encoding(self):
241
 
        app = proxy_logging.ProxyLoggingMiddleware(
242
 
                FakeAppNoContentLengthNoTransferEncoding(), {})
243
 
        app.access_logger = FakeLogger()
244
 
        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
245
 
        resp = app(req.environ, start_response)
246
 
        body = ''.join(resp)
 
358
    def test_no_content_length_no_transfer_encoding_with_list_body(self):
 
359
        app = proxy_logging.ProxyLoggingMiddleware(
 
360
            FakeAppNoContentLengthNoTransferEncoding(
 
361
                # test the "while not chunk: chunk = iterator.next()"
 
362
                body=['', '', 'line1\n', 'line2\n'],
 
363
            ), {})
 
364
        app.access_logger = FakeLogger()
 
365
        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
 
366
        resp = app(req.environ, start_response)
 
367
        resp_body = ''.join(resp)
 
368
        log_parts = self._log_parts(app)
 
369
        self.assertEquals(log_parts[3], 'GET')
 
370
        self.assertEquals(log_parts[4], '/')
 
371
        self.assertEquals(log_parts[5], 'HTTP/1.0')
 
372
        self.assertEquals(log_parts[6], '200')
 
373
        self.assertEquals(resp_body, 'line1\nline2\n')
 
374
        self.assertEquals(log_parts[11], str(len(resp_body)))
 
375
 
 
376
    def test_no_content_length_no_transfer_encoding_with_empty_strings(self):
 
377
        app = proxy_logging.ProxyLoggingMiddleware(
 
378
            FakeAppNoContentLengthNoTransferEncoding(
 
379
                # test the "while not chunk: chunk = iterator.next()"
 
380
                body=['', '', ''],
 
381
            ), {})
 
382
        app.access_logger = FakeLogger()
 
383
        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
 
384
        resp = app(req.environ, start_response)
 
385
        resp_body = ''.join(resp)
 
386
        log_parts = self._log_parts(app)
 
387
        self.assertEquals(log_parts[3], 'GET')
 
388
        self.assertEquals(log_parts[4], '/')
 
389
        self.assertEquals(log_parts[5], 'HTTP/1.0')
 
390
        self.assertEquals(log_parts[6], '200')
 
391
        self.assertEquals(resp_body, '')
 
392
        self.assertEquals(log_parts[11], '-')
 
393
 
 
394
    def test_no_content_length_no_transfer_encoding_with_str_body(self):
 
395
        app = proxy_logging.ProxyLoggingMiddleware(
 
396
            FakeAppNoContentLengthNoTransferEncoding(
 
397
                body='line1\nline2\n',
 
398
            ), {})
 
399
        app.access_logger = FakeLogger()
 
400
        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
 
401
        resp = app(req.environ, start_response)
 
402
        # Python 2.7 can have assertRaises act as a context manager, but python
 
403
        # 2.6 can't.  So there's this.
 
404
        try:
 
405
            resp_body = ''.join(resp)
 
406
        except Exception as e:
 
407
            self.assertEquals(
 
408
                "WSGI [proxy-logging]: No content-length or transfer-encoding "
 
409
                "header sent and there is content! 'l'", str(e))
 
410
        else:
 
411
            self.assert_(False)
247
412
 
248
413
    def test_req_path_info_popping(self):
249
414
        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
253
418
        self.assertEquals(req.environ['PATH_INFO'], '/something')
254
419
        resp = app(req.environ, start_response)
255
420
        resp_body = ''.join(resp)
256
 
        log_parts = app.access_logger.msg.split()
 
421
        log_parts = self._log_parts(app)
257
422
        self.assertEquals(log_parts[3], 'GET')
258
423
        self.assertEquals(log_parts[4], '/v1/something')
259
424
        self.assertEquals(log_parts[5], 'HTTP/1.0')