def test_disconnect_on_readline(self): app = proxy_logging.ProxyLoggingMiddleware(FakeAppReadline(), {}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET', 'wsgi.input': FileLikeExceptor()}) try: resp = app(req.environ, start_response) body = ''.join(resp) except Exception: pass log_parts = self._log_parts(app) self.assertEquals(log_parts[6], '499') self.assertEquals(log_parts[10], '-') # read length
def test_log_query_string(self): app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {}) app.access_logger = FakeLogger() req = Request.blank('/', environ={ 'REQUEST_METHOD': 'GET', 'QUERY_STRING': 'x=3' }) resp = app(req.environ, start_response) # exhaust generator [x for x in resp] log_parts = self._log_parts(app) self.assertEquals(unquote(log_parts[4]), '/?x=3')
def test_basic_req(self): app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'}) resp = app(req.environ, start_response) resp_body = b''.join(resp) log_parts = self._log_parts(app) self.assertEqual(log_parts[3], 'GET') self.assertEqual(log_parts[4], '/') self.assertEqual(log_parts[5], 'HTTP/1.0') self.assertEqual(log_parts[6], '200') self.assertEqual(resp_body, b'FAKE APP') self.assertEqual(log_parts[11], str(len(resp_body)))
def test_client_logging(self): app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {}) app.access_logger = FakeLogger() req = Request.blank('/', environ={ 'REQUEST_METHOD': 'GET', 'REMOTE_ADDR': '1.2.3.4' }) resp = app(req.environ, start_response) exhaust_generator = [x for x in resp] log_parts = self._log_parts(app) self.assertEquals(log_parts[0], '1.2.3.4') # client ip self.assertEquals(log_parts[1], '1.2.3.4') # remote addr
def test_upload_size(self): # Using default policy app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {'log_headers': 'yes'}) app.access_logger = FakeLogger() req = Request.blank('/v1/a/c/o/foo', environ={ 'REQUEST_METHOD': 'PUT', 'wsgi.input': BytesIO(b'some stuff') }) resp = app(req.environ, start_response) # exhaust generator [x for x in resp] log_parts = self._log_parts(app) self.assertEqual(log_parts[11], str(len('FAKE APP'))) self.assertEqual(log_parts[10], str(len('some stuff'))) self.assertUpdateStats( [('object.PUT.200.xfer', len('some stuff') + len('FAKE APP')), ('object.policy.0.PUT.200.xfer', len('some stuff') + len('FAKE APP'))], app) # Using a non-existent policy app = proxy_logging.ProxyLoggingMiddleware(FakeApp(policy_idx='-1'), {'log_headers': 'yes'}) app.access_logger = FakeLogger() req = Request.blank('/v1/a/c/o/foo', environ={ 'REQUEST_METHOD': 'PUT', 'wsgi.input': BytesIO(b'some stuff') }) resp = app(req.environ, start_response) # exhaust generator [x for x in resp] log_parts = self._log_parts(app) self.assertEqual(log_parts[11], str(len('FAKE APP'))) self.assertEqual(log_parts[10], str(len('some stuff'))) self.assertUpdateStats( [('object.PUT.200.xfer', len('some stuff') + len('FAKE APP'))], app)
def test_upload_size(self): app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {'log_headers': 'yes'}) app.access_logger = FakeLogger() req = Request.blank('/', environ={ 'REQUEST_METHOD': 'GET', 'wsgi.input': StringIO.StringIO('some stuff') }) resp = app(req.environ, start_response) exhaust_generator = [x for x in resp] log_parts = app.access_logger.msg.split() self.assertEquals(log_parts[10], str(len('some stuff')))
def test_multi_segment_resp(self): app = proxy_logging.ProxyLoggingMiddleware( FakeApp(['some', 'chunks', 'of data']), {}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'}) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = app.access_logger.msg.split() self.assertEquals(log_parts[3], 'GET') self.assertEquals(log_parts[4], '/') self.assertEquals(log_parts[5], 'HTTP/1.0') self.assertEquals(log_parts[6], '200') self.assertEquals(resp_body, 'somechunksof data') self.assertEquals(log_parts[11], str(len(resp_body)))
def test_upload_size(self): app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {'log_headers': 'yes'}) app.access_logger = FakeLogger() req = Request.blank('/v1/a/c/o/foo', environ={'REQUEST_METHOD': 'PUT', 'wsgi.input': StringIO.StringIO('some stuff')}) resp = app(req.environ, start_response) exhaust_generator = [x for x in resp] log_parts = self._log_parts(app) self.assertEquals(log_parts[11], str(len('FAKE APP'))) self.assertEquals(log_parts[10], str(len('some stuff'))) self.assertUpdateStats('object.PUT.200.xfer', len('some stuff') + len('FAKE APP'), app)
def test_req_path_info_popping(self): app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {}) app.access_logger = FakeLogger() req = Request.blank('/v1/something', environ={'REQUEST_METHOD': 'GET'}) req.path_info_pop() self.assertEquals(req.environ['PATH_INFO'], '/something') resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[3], 'GET') self.assertEquals(log_parts[4], '/v1/something') self.assertEquals(log_parts[5], 'HTTP/1.0') self.assertEquals(log_parts[6], '200') self.assertEquals(resp_body, 'FAKE APP') self.assertEquals(log_parts[11], str(len(resp_body)))
def test_disconnect_on_read(self): app = proxy_logging.ProxyLoggingMiddleware( FakeApp(['some', 'stuff']), {}) app.access_logger = debug_logger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET', 'wsgi.input': FileLikeExceptor()}) try: resp = app(req.environ, start_response) # read body b''.join(resp) except IOError: pass log_parts = self._log_parts(app) self.assertEqual(log_parts[6], '499') self.assertEqual(log_parts[10], '-') # read length
def test_multi_segment_resp(self): app = proxy_logging.ProxyLoggingMiddleware(FakeApp( ['some', 'chunks', 'of data']), {}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET', 'swift.source': 'SOS'}) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[3], 'GET') self.assertEquals(log_parts[4], '/') self.assertEquals(log_parts[5], 'HTTP/1.0') self.assertEquals(log_parts[6], '200') self.assertEquals(resp_body, 'somechunksof data') self.assertEquals(log_parts[11], str(len(resp_body))) self.assertUpdateStats([('SOS.GET.200.xfer', len(resp_body))], app)
def test_upload_line(self): app = proxy_logging.ProxyLoggingMiddleware(FakeAppReadline(), {'log_headers': 'yes'}) app.access_logger = FakeLogger() req = Request.blank( '/v1/a/c', environ={'REQUEST_METHOD': 'POST', 'wsgi.input': BytesIO(b'some stuff\nsome other stuff\n')}) resp = app(req.environ, start_response) # exhaust generator [x for x in resp] log_parts = self._log_parts(app) self.assertEquals(log_parts[11], str(len('FAKE APP'))) self.assertEquals(log_parts[10], str(len('some stuff\n'))) self.assertUpdateStats([('container.POST.200.xfer', len('some stuff\n') + len('FAKE APP'))], app)
def test_ipv6(self): ipv6addr = '2001:db8:85a3:8d3:1319:8a2e:370:7348' app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'}) req.remote_addr = ipv6addr resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[0], ipv6addr) self.assertEquals(log_parts[1], ipv6addr) self.assertEquals(log_parts[3], 'GET') self.assertEquals(log_parts[4], '/') self.assertEquals(log_parts[5], 'HTTP/1.0') self.assertEquals(log_parts[6], '200') self.assertEquals(resp_body, 'FAKE APP') self.assertEquals(log_parts[11], str(len(resp_body)))
def test_no_content_length_no_transfer_encoding_with_empty_strings(self): app = proxy_logging.ProxyLoggingMiddleware( FakeAppNoContentLengthNoTransferEncoding( # test the "while not chunk: chunk = next(iterator)" body=['', '', ''], ), {}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'}) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[3], 'GET') self.assertEquals(log_parts[4], '/') self.assertEquals(log_parts[5], 'HTTP/1.0') self.assertEquals(log_parts[6], '200') self.assertEquals(resp_body, '') self.assertEquals(log_parts[11], '-')
def test_no_content_length_no_transfer_encoding_with_str_body(self): app = proxy_logging.ProxyLoggingMiddleware( FakeAppNoContentLengthNoTransferEncoding(body='line1\nline2\n', ), {}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'}) resp = app(req.environ, start_response) # Python 2.7 can have assertRaises act as a context manager, but python # 2.6 can't. So there's this. try: resp_body = ''.join(resp) except Exception as e: self.assertEquals( "WSGI [proxy-logging]: No content-length or transfer-encoding " "header sent and there is content! 'l'", str(e)) else: self.assert_(False)
def test_access_log_headers_only(self): app = proxy_logging.ProxyLoggingMiddleware( FakeApp(), {'log_headers': 'yes', 'access_log_headers_only': 'FIRST, seCond'}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'}, headers={'First': '1', 'Second': '2', 'Third': '3'}) resp = app(req.environ, start_response) # exhaust generator [x for x in resp] log_parts = self._log_parts(app) headers = unquote(log_parts[14]).split('\n') self.assertTrue('First: 1' in headers) self.assertTrue('Second: 2' in headers) self.assertTrue('Third: 3' not in headers) self.assertTrue('Host: localhost:80' not in headers)
def test_exploding_body(self): def exploding_body(): yield 'some' yield 'stuff' raise Exception('kaboom!') app = proxy_logging.ProxyLoggingMiddleware( FakeApp(exploding_body()), { 'log_msg_template': '{method} {path} ' '{status_int} {wire_status_int}', }) app.access_logger = debug_logger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'}) resp = req.get_response(app) with self.assertRaises(Exception) as ctx: resp.body self.assertEqual('kaboom!', str(ctx.exception)) log_parts = self._log_parts(app) self.assertEqual(log_parts, ['GET', '/', '500', '200'])
def test_log_request_stat_type_good(self): path_types = { '/v1/a': 'account', '/v1/a/': 'account', '/v1/a/c': 'container', '/v1/a/c/': 'container', '/v1/a/c/o': 'object', '/v1/a/c/o/': 'object', '/v1/a/c/o/p': 'object', '/v1/a/c/o/p/': 'object', '/v1/a/c/o/p/p2': 'object', } for path, exp_type in path_types.iteritems(): app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {}) app.access_logger = FakeLogger() req = Request.blank(path, environ={'REQUEST_METHOD': 'GET'}) app.log_request(req.environ, 321, 7, 13, 2.71828182846, False) self.assertTiming('%s.GET.321.timing' % exp_type, app, exp_timing=2.71828182846 * 1000) self.assertUpdateStats('%s.GET.321.xfer' % exp_type, 7 + 13, app)
def test_iterator_closing(self): class CloseableBody(object): def __init__(self): self.closed = False def close(self): self.closed = True def __iter__(self): return iter(["CloseableBody"]) body = CloseableBody() app = proxy_logging.ProxyLoggingMiddleware(FakeApp(body), {}) req = Request.blank('/', environ={'REQUEST_METHOD': 'GET', 'REMOTE_ADDR': '1.2.3.4'}) resp = app(req.environ, start_response) # exhaust generator [x for x in resp] self.assertTrue(body.closed)
def test_no_content_length_no_transfer_encoding_with_generator(self): class BodyGen(object): def __init__(self, data): self.data = data def __iter__(self): yield self.data app = proxy_logging.ProxyLoggingMiddleware( FakeAppNoContentLengthNoTransferEncoding(body=BodyGen('abc'), ), {}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'}) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[3], 'GET') self.assertEquals(log_parts[4], '/') self.assertEquals(log_parts[5], 'HTTP/1.0') self.assertEquals(log_parts[6], '200') self.assertEquals(resp_body, 'abc') self.assertEquals(log_parts[11], '3')
def test_log_request_stat_method_filtering_default(self): method_map = { 'foo': 'BAD_METHOD', '': 'BAD_METHOD', 'PUTT': 'BAD_METHOD', 'SPECIAL': 'BAD_METHOD', 'GET': 'GET', 'PUT': 'PUT', 'COPY': 'COPY', 'HEAD': 'HEAD', 'POST': 'POST', 'DELETE': 'DELETE', } for method, exp_method in method_map.iteritems(): app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {}) app.access_logger = FakeLogger() req = Request.blank('/v1/a/', environ={'REQUEST_METHOD': method}) app.log_request(req.environ, 299, 11, 3, 1.17, False) self.assertTiming('account.%s.299.timing' % exp_method, app, exp_timing=1.17 * 1000) self.assertUpdateStats('account.%s.299.xfer' % exp_method, 11 + 3, app)
def test_log_request_stat_method_filtering_custom(self): method_map = { 'foo': 'BAD_METHOD', '': 'BAD_METHOD', 'PUTT': 'BAD_METHOD', 'SPECIAL': 'SPECIAL', # will be configured 'GET': 'GET', 'PUT': 'PUT', 'COPY': 'BAD_METHOD', # prove no one's special } # this conf var supports optional leading access_ for conf_key in ['access_log_statsd_valid_http_methods', 'log_statsd_valid_http_methods']: for method, exp_method in method_map.iteritems(): app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), { conf_key: 'SPECIAL, GET,PUT ', # crazy spaces ok }) app.access_logger = FakeLogger() req = Request.blank('/v1/a/c', environ={'REQUEST_METHOD': method}) app.log_request(req.environ, 911, 4, 43, 1.01, False) self.assertTiming('container.%s.911.timing' % exp_method, app, exp_timing=1.01 * 1000) self.assertUpdateStats('container.%s.911.xfer' % exp_method, 4 + 43, app)
def test_facility(self): app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {'log_headers': 'yes', 'access_log_facility': 'LOG_LOCAL7'}) handler = get_logger.handler4logger[app.access_logger.logger] self.assertEquals(SysLogHandler.LOG_LOCAL7, handler.facility)
def test_log_auth_token(self): auth_token = 'b05bf940-0464-4c0e-8c70-87717d2d73e8' # Default - no reveal_sensitive_prefix in config # No x-auth-token header app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'}) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[9], '-') # Has x-auth-token header app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {}) app.access_logger = FakeLogger() req = Request.blank('/', environ={ 'REQUEST_METHOD': 'GET', 'HTTP_X_AUTH_TOKEN': auth_token }) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[9], auth_token) # Truncate to first 8 characters app = proxy_logging.ProxyLoggingMiddleware( FakeApp(), {'reveal_sensitive_prefix': '8'}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'}) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[9], '-') app = proxy_logging.ProxyLoggingMiddleware( FakeApp(), {'reveal_sensitive_prefix': '8'}) app.access_logger = FakeLogger() req = Request.blank('/', environ={ 'REQUEST_METHOD': 'GET', 'HTTP_X_AUTH_TOKEN': auth_token }) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[9], 'b05bf940...') # Token length and reveal_sensitive_prefix are same (no truncate) app = proxy_logging.ProxyLoggingMiddleware( FakeApp(), {'reveal_sensitive_prefix': str(len(auth_token))}) app.access_logger = FakeLogger() req = Request.blank('/', environ={ 'REQUEST_METHOD': 'GET', 'HTTP_X_AUTH_TOKEN': auth_token }) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[9], auth_token) # Don't log x-auth-token app = proxy_logging.ProxyLoggingMiddleware( FakeApp(), {'reveal_sensitive_prefix': '0'}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'}) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[9], '-') app = proxy_logging.ProxyLoggingMiddleware( FakeApp(), {'reveal_sensitive_prefix': '0'}) app.access_logger = FakeLogger() req = Request.blank('/', environ={ 'REQUEST_METHOD': 'GET', 'HTTP_X_AUTH_TOKEN': auth_token }) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[9], '...')
def test_facility(self): app = proxy_logging.ProxyLoggingMiddleware( FakeApp(), { 'log_headers': 'yes', 'access_log_facility': 'whatever' })
def test_log_request_stat_type_good(self): """ log_request() should send timing and byte-count counters for GET requests. Also, __call__()'s iter_response() function should statsd-log time to first byte (calling the passed-in start_response function), but only for GET requests. """ stub_times = [] def stub_time(): return stub_times.pop(0) path_types = { '/v1/a': 'account', '/v1/a/': 'account', '/v1/a/c': 'container', '/v1/a/c/': 'container', '/v1/a/c/o': 'object', '/v1/a/c/o/': 'object', '/v1/a/c/o/p': 'object', '/v1/a/c/o/p/': 'object', '/v1/a/c/o/p/p2': 'object', } with mock.patch("time.time", stub_time): for path, exp_type in path_types.items(): # GET app = proxy_logging.ProxyLoggingMiddleware( FakeApp(body='7654321', response_str='321 Fubar'), {}) app.access_logger = FakeLogger() req = Request.blank(path, environ={ 'REQUEST_METHOD': 'GET', 'wsgi.input': BytesIO(b'4321')}) stub_times = [18.0, 20.71828182846] iter_response = app(req.environ, lambda *_: None) self.assertEqual('7654321', ''.join(iter_response)) self.assertTiming('%s.GET.321.timing' % exp_type, app, exp_timing=2.71828182846 * 1000) self.assertTimingSince( '%s.GET.321.first-byte.timing' % exp_type, app, exp_start=18.0) if exp_type == 'object': # Object operations also return stats by policy # In this case, the value needs to match the timing for GET self.assertTiming('%s.policy.0.GET.321.timing' % exp_type, app, exp_timing=2.71828182846 * 1000) self.assertUpdateStats([('%s.GET.321.xfer' % exp_type, 4 + 7), ('object.policy.0.GET.321.xfer', 4 + 7)], app) else: self.assertUpdateStats([('%s.GET.321.xfer' % exp_type, 4 + 7)], app) # GET Repeat the test above, but with a non-existent policy # Do this only for object types if exp_type == 'object': app = proxy_logging.ProxyLoggingMiddleware( FakeApp(body='7654321', response_str='321 Fubar', policy_idx='-1'), {}) app.access_logger = FakeLogger() req = Request.blank(path, environ={ 'REQUEST_METHOD': 'GET', 'wsgi.input': BytesIO(b'4321')}) stub_times = [18.0, 20.71828182846] iter_response = app(req.environ, lambda *_: None) self.assertEqual('7654321', ''.join(iter_response)) self.assertTiming('%s.GET.321.timing' % exp_type, app, exp_timing=2.71828182846 * 1000) self.assertTimingSince( '%s.GET.321.first-byte.timing' % exp_type, app, exp_start=18.0) # No results returned for the non-existent policy self.assertUpdateStats([('%s.GET.321.xfer' % exp_type, 4 + 7)], app) # GET with swift.proxy_access_log_made already set app = proxy_logging.ProxyLoggingMiddleware( FakeApp(body='7654321', response_str='321 Fubar'), {}) app.access_logger = FakeLogger() req = Request.blank(path, environ={ 'REQUEST_METHOD': 'GET', 'swift.proxy_access_log_made': True, 'wsgi.input': BytesIO(b'4321')}) stub_times = [18.0, 20.71828182846] iter_response = app(req.environ, lambda *_: None) self.assertEqual('7654321', ''.join(iter_response)) self.assertEqual([], app.access_logger.log_dict['timing']) self.assertEqual([], app.access_logger.log_dict['timing_since']) self.assertEqual([], app.access_logger.log_dict['update_stats']) # PUT (no first-byte timing!) app = proxy_logging.ProxyLoggingMiddleware( FakeApp(body='87654321', response_str='314 PiTown'), {}) app.access_logger = FakeLogger() req = Request.blank(path, environ={ 'REQUEST_METHOD': 'PUT', 'wsgi.input': BytesIO(b'654321')}) # (it's not a GET, so time() doesn't have a 2nd call) stub_times = [58.2, 58.2 + 7.3321] iter_response = app(req.environ, lambda *_: None) self.assertEqual('87654321', ''.join(iter_response)) self.assertTiming('%s.PUT.314.timing' % exp_type, app, exp_timing=7.3321 * 1000) self.assertNotTiming( '%s.GET.314.first-byte.timing' % exp_type, app) self.assertNotTiming( '%s.PUT.314.first-byte.timing' % exp_type, app) if exp_type == 'object': # Object operations also return stats by policy In this # case, the value needs to match the timing for PUT. self.assertTiming('%s.policy.0.PUT.314.timing' % exp_type, app, exp_timing=7.3321 * 1000) self.assertUpdateStats( [('object.PUT.314.xfer', 6 + 8), ('object.policy.0.PUT.314.xfer', 6 + 8)], app) else: self.assertUpdateStats( [('%s.PUT.314.xfer' % exp_type, 6 + 8)], app) # PUT Repeat the test above, but with a non-existent policy # Do this only for object types if exp_type == 'object': app = proxy_logging.ProxyLoggingMiddleware( FakeApp(body='87654321', response_str='314 PiTown', policy_idx='-1'), {}) app.access_logger = FakeLogger() req = Request.blank(path, environ={ 'REQUEST_METHOD': 'PUT', 'wsgi.input': BytesIO(b'654321')}) # (it's not a GET, so time() doesn't have a 2nd call) stub_times = [58.2, 58.2 + 7.3321] iter_response = app(req.environ, lambda *_: None) self.assertEqual('87654321', ''.join(iter_response)) self.assertTiming('%s.PUT.314.timing' % exp_type, app, exp_timing=7.3321 * 1000) self.assertNotTiming( '%s.GET.314.first-byte.timing' % exp_type, app) self.assertNotTiming( '%s.PUT.314.first-byte.timing' % exp_type, app) # No results returned for the non-existent policy self.assertUpdateStats([('object.PUT.314.xfer', 6 + 8)], app)
def setup_servers(the_object_server=object_server, extra_conf=None): """ Setup proxy, account, container and object servers using a set of fake rings and policies. :param the_object_server: The object server module to use (optional, defaults to swift.obj.server) :param extra_conf: A dict of config options that will update the basic config passed to all server instances. :returns: A dict containing the following entries: orig_POLICIES: the value of storage_policy.POLICIES prior to it being patched with fake policies orig_SysLogHandler: the value of utils.SysLogHandler prior to it being patched testdir: root directory used for test files test_POLICIES: a StoragePolicyCollection of fake policies test_servers: a tuple of test server instances test_sockets: a tuple of sockets used by test servers test_coros: a tuple of greenthreads in which test servers are running """ context = { "orig_POLICIES": storage_policy._POLICIES, "orig_SysLogHandler": utils.SysLogHandler} utils.HASH_PATH_SUFFIX = b'endcap' utils.SysLogHandler = mock.MagicMock() # Since we're starting up a lot here, we're going to test more than # just chunked puts; we're also going to test parts of # proxy_server.Application we couldn't get to easily otherwise. context["testdir"] = _testdir = \ os.path.join(mkdtemp(), 'tmp_test_proxy_server_chunked') mkdirs(_testdir) rmtree(_testdir) for drive in ('sda1', 'sdb1', 'sdc1', 'sdd1', 'sde1', 'sdf1', 'sdg1', 'sdh1', 'sdi1', 'sdj1', 'sdk1', 'sdl1'): mkdirs(os.path.join(_testdir, drive, 'tmp')) conf = {'devices': _testdir, 'swift_dir': _testdir, 'mount_check': 'false', 'allowed_headers': 'content-encoding, x-object-manifest, content-disposition, foo', 'allow_versions': 't'} if extra_conf: conf.update(extra_conf) prolis = listen_zero() acc1lis = listen_zero() acc2lis = listen_zero() con1lis = listen_zero() con2lis = listen_zero() obj1lis = listen_zero() obj2lis = listen_zero() obj3lis = listen_zero() obj4lis = listen_zero() obj5lis = listen_zero() obj6lis = listen_zero() objsocks = [obj1lis, obj2lis, obj3lis, obj4lis, obj5lis, obj6lis] context["test_sockets"] = \ (prolis, acc1lis, acc2lis, con1lis, con2lis, obj1lis, obj2lis, obj3lis, obj4lis, obj5lis, obj6lis) account_ring_path = os.path.join(_testdir, 'account.ring.gz') account_devs = [ {'port': acc1lis.getsockname()[1]}, {'port': acc2lis.getsockname()[1]}, ] write_fake_ring(account_ring_path, *account_devs) container_ring_path = os.path.join(_testdir, 'container.ring.gz') container_devs = [ {'port': con1lis.getsockname()[1]}, {'port': con2lis.getsockname()[1]}, ] write_fake_ring(container_ring_path, *container_devs) storage_policy._POLICIES = storage_policy.StoragePolicyCollection([ StoragePolicy(0, 'zero', True), StoragePolicy(1, 'one', False), StoragePolicy(2, 'two', False), ECStoragePolicy(3, 'ec', ec_type=DEFAULT_TEST_EC_TYPE, ec_ndata=2, ec_nparity=1, ec_segment_size=4096), ECStoragePolicy(4, 'ec-dup', ec_type=DEFAULT_TEST_EC_TYPE, ec_ndata=2, ec_nparity=1, ec_segment_size=4096, ec_duplication_factor=2)]) obj_rings = { 0: ('sda1', 'sdb1'), 1: ('sdc1', 'sdd1'), 2: ('sde1', 'sdf1'), # sdg1, sdh1, sdi1 taken by policy 3 (see below) } for policy_index, devices in obj_rings.items(): policy = storage_policy.POLICIES[policy_index] obj_ring_path = os.path.join(_testdir, policy.ring_name + '.ring.gz') obj_devs = [ {'port': objsock.getsockname()[1], 'device': dev} for objsock, dev in zip(objsocks, devices)] write_fake_ring(obj_ring_path, *obj_devs) # write_fake_ring can't handle a 3-element ring, and the EC policy needs # at least 6 devs to work with (ec_k=2, ec_m=1, duplication_factor=2), # so we do it manually devs = [{'id': 0, 'zone': 0, 'device': 'sdg1', 'ip': '127.0.0.1', 'port': obj1lis.getsockname()[1]}, {'id': 1, 'zone': 0, 'device': 'sdh1', 'ip': '127.0.0.1', 'port': obj2lis.getsockname()[1]}, {'id': 2, 'zone': 0, 'device': 'sdi1', 'ip': '127.0.0.1', 'port': obj3lis.getsockname()[1]}, {'id': 3, 'zone': 0, 'device': 'sdj1', 'ip': '127.0.0.1', 'port': obj4lis.getsockname()[1]}, {'id': 4, 'zone': 0, 'device': 'sdk1', 'ip': '127.0.0.1', 'port': obj5lis.getsockname()[1]}, {'id': 5, 'zone': 0, 'device': 'sdl1', 'ip': '127.0.0.1', 'port': obj6lis.getsockname()[1]}] pol3_replica2part2dev_id = [[0, 1, 2, 0], [1, 2, 0, 1], [2, 0, 1, 2]] pol4_replica2part2dev_id = [[0, 1, 2, 3], [1, 2, 3, 4], [2, 3, 4, 5], [3, 4, 5, 0], [4, 5, 0, 1], [5, 0, 1, 2]] obj3_ring_path = os.path.join( _testdir, storage_policy.POLICIES[3].ring_name + '.ring.gz') part_shift = 30 with closing(GzipFile(obj3_ring_path, 'wb')) as fh: pickle.dump(RingData(pol3_replica2part2dev_id, devs, part_shift), fh) obj4_ring_path = os.path.join( _testdir, storage_policy.POLICIES[4].ring_name + '.ring.gz') part_shift = 30 with closing(GzipFile(obj4_ring_path, 'wb')) as fh: pickle.dump(RingData(pol4_replica2part2dev_id, devs, part_shift), fh) prosrv = proxy_server.Application(conf, logger=debug_logger('proxy')) for policy in storage_policy.POLICIES: # make sure all the rings are loaded prosrv.get_object_ring(policy.idx) # don't lose this one! context["test_POLICIES"] = storage_policy._POLICIES acc1srv = account_server.AccountController( conf, logger=debug_logger('acct1')) acc2srv = account_server.AccountController( conf, logger=debug_logger('acct2')) con1srv = container_server.ContainerController( conf, logger=debug_logger('cont1')) con2srv = container_server.ContainerController( conf, logger=debug_logger('cont2')) obj1srv = the_object_server.ObjectController( conf, logger=debug_logger('obj1')) obj2srv = the_object_server.ObjectController( conf, logger=debug_logger('obj2')) obj3srv = the_object_server.ObjectController( conf, logger=debug_logger('obj3')) obj4srv = the_object_server.ObjectController( conf, logger=debug_logger('obj4')) obj5srv = the_object_server.ObjectController( conf, logger=debug_logger('obj5')) obj6srv = the_object_server.ObjectController( conf, logger=debug_logger('obj6')) context["test_servers"] = \ (prosrv, acc1srv, acc2srv, con1srv, con2srv, obj1srv, obj2srv, obj3srv, obj4srv, obj5srv, obj6srv) nl = NullLogger() logging_prosv = proxy_logging.ProxyLoggingMiddleware( listing_formats.ListingFilter(prosrv), conf, logger=prosrv.logger) prospa = spawn(wsgi.server, prolis, logging_prosv, nl) acc1spa = spawn(wsgi.server, acc1lis, acc1srv, nl) acc2spa = spawn(wsgi.server, acc2lis, acc2srv, nl) con1spa = spawn(wsgi.server, con1lis, con1srv, nl) con2spa = spawn(wsgi.server, con2lis, con2srv, nl) obj1spa = spawn(wsgi.server, obj1lis, obj1srv, nl) obj2spa = spawn(wsgi.server, obj2lis, obj2srv, nl) obj3spa = spawn(wsgi.server, obj3lis, obj3srv, nl) obj4spa = spawn(wsgi.server, obj4lis, obj4srv, nl) obj5spa = spawn(wsgi.server, obj5lis, obj5srv, nl) obj6spa = spawn(wsgi.server, obj6lis, obj6srv, nl) context["test_coros"] = \ (prospa, acc1spa, acc2spa, con1spa, con2spa, obj1spa, obj2spa, obj3spa, obj4spa, obj5spa, obj6spa) # Create account ts = normalize_timestamp(time.time()) partition, nodes = prosrv.account_ring.get_nodes('a') for node in nodes: conn = swift.proxy.controllers.obj.http_connect(node['ip'], node['port'], node['device'], partition, 'PUT', '/a', {'X-Timestamp': ts, 'x-trans-id': 'test'}) resp = conn.getresponse() assert(resp.status == 201) # Create another account # used for account-to-account tests ts = normalize_timestamp(time.time()) partition, nodes = prosrv.account_ring.get_nodes('a1') for node in nodes: conn = swift.proxy.controllers.obj.http_connect(node['ip'], node['port'], node['device'], partition, 'PUT', '/a1', {'X-Timestamp': ts, 'x-trans-id': 'test'}) resp = conn.getresponse() assert(resp.status == 201) # Create containers, 1 per test policy sock = connect_tcp(('localhost', prolis.getsockname()[1])) fd = sock.makefile() fd.write('PUT /v1/a/c HTTP/1.1\r\nHost: localhost\r\n' 'Connection: close\r\nX-Auth-Token: t\r\n' 'Content-Length: 0\r\n\r\n') fd.flush() headers = readuntil2crlfs(fd) exp = 'HTTP/1.1 201' assert headers[:len(exp)] == exp, "Expected '%s', encountered '%s'" % ( exp, headers[:len(exp)]) # Create container in other account # used for account-to-account tests sock = connect_tcp(('localhost', prolis.getsockname()[1])) fd = sock.makefile() fd.write('PUT /v1/a1/c1 HTTP/1.1\r\nHost: localhost\r\n' 'Connection: close\r\nX-Auth-Token: t\r\n' 'Content-Length: 0\r\n\r\n') fd.flush() headers = readuntil2crlfs(fd) exp = 'HTTP/1.1 201' assert headers[:len(exp)] == exp, "Expected '%s', encountered '%s'" % ( exp, headers[:len(exp)]) sock = connect_tcp(('localhost', prolis.getsockname()[1])) fd = sock.makefile() fd.write( 'PUT /v1/a/c1 HTTP/1.1\r\nHost: localhost\r\n' 'Connection: close\r\nX-Auth-Token: t\r\nX-Storage-Policy: one\r\n' 'Content-Length: 0\r\n\r\n') fd.flush() headers = readuntil2crlfs(fd) exp = 'HTTP/1.1 201' assert headers[:len(exp)] == exp, \ "Expected '%s', encountered '%s'" % (exp, headers[:len(exp)]) sock = connect_tcp(('localhost', prolis.getsockname()[1])) fd = sock.makefile() fd.write( 'PUT /v1/a/c2 HTTP/1.1\r\nHost: localhost\r\n' 'Connection: close\r\nX-Auth-Token: t\r\nX-Storage-Policy: two\r\n' 'Content-Length: 0\r\n\r\n') fd.flush() headers = readuntil2crlfs(fd) exp = 'HTTP/1.1 201' assert headers[:len(exp)] == exp, \ "Expected '%s', encountered '%s'" % (exp, headers[:len(exp)]) return context
def test_log_request_stat_type_good(self): """ log_request() should send timing and byte-count counters for GET requests. Also, __call__()'s iter_response() function should statsd-log time to first byte (calling the passed-in start_response function), but only for GET requests. """ stub_times = [] def stub_time(): return stub_times.pop(0) path_types = { '/v1/a': 'account', '/v1/a/': 'account', '/v1/a/c': 'container', '/v1/a/c/': 'container', '/v1/a/c/o': 'object', '/v1/a/c/o/': 'object', '/v1/a/c/o/p': 'object', '/v1/a/c/o/p/': 'object', '/v1/a/c/o/p/p2': 'object', } for path, exp_type in path_types.iteritems(): orig_time = time.time try: time.time = stub_time # GET app = proxy_logging.ProxyLoggingMiddleware( FakeApp(body='7654321', response_str='321 Fubar'), {}) app.access_logger = FakeLogger() req = Request.blank(path, environ={ 'REQUEST_METHOD': 'GET', 'wsgi.input': StringIO.StringIO('4321') }) stub_times = [18.0, 20.71828182846] iter_response = app(req.environ, lambda *_: None) self.assertEqual('7654321', ''.join(iter_response)) self.assertTiming('%s.GET.321.timing' % exp_type, app, exp_timing=2.71828182846 * 1000) self.assertTimingSince('%s.GET.321.first-byte.timing' % exp_type, app, exp_start=18.0) self.assertUpdateStats('%s.GET.321.xfer' % exp_type, 4 + 7, app) # GET with swift.proxy_access_log_made already set app = proxy_logging.ProxyLoggingMiddleware( FakeApp(body='7654321', response_str='321 Fubar'), {}) app.access_logger = FakeLogger() req = Request.blank(path, environ={ 'REQUEST_METHOD': 'GET', 'swift.proxy_access_log_made': True, 'wsgi.input': StringIO.StringIO('4321') }) stub_times = [18.0, 20.71828182846] iter_response = app(req.environ, lambda *_: None) self.assertEqual('7654321', ''.join(iter_response)) self.assertEqual([], app.access_logger.log_dict['timing']) self.assertEqual([], app.access_logger.log_dict['timing_since']) self.assertEqual([], app.access_logger.log_dict['update_stats']) # PUT (no first-byte timing!) app = proxy_logging.ProxyLoggingMiddleware( FakeApp(body='87654321', response_str='314 PiTown'), {}) app.access_logger = FakeLogger() req = Request.blank(path, environ={ 'REQUEST_METHOD': 'PUT', 'wsgi.input': StringIO.StringIO('654321') }) # (it's not a GET, so time() doesn't have a 2nd call) stub_times = [58.2, 58.2 + 7.3321] iter_response = app(req.environ, lambda *_: None) self.assertEqual('87654321', ''.join(iter_response)) self.assertTiming('%s.PUT.314.timing' % exp_type, app, exp_timing=7.3321 * 1000) self.assertNotTiming('%s.GET.314.first-byte.timing' % exp_type, app) self.assertNotTiming('%s.PUT.314.first-byte.timing' % exp_type, app) self.assertUpdateStats('%s.PUT.314.xfer' % exp_type, 6 + 8, app) finally: time.time = orig_time
def test_log_auth_token(self): auth_token = 'b05bf940-0464-4c0e-8c70-87717d2d73e8' # Default - reveal_sensitive_prefix is 16 # No x-auth-token header app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'}) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[9], '-') # Has x-auth-token header app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET', 'HTTP_X_AUTH_TOKEN': auth_token}) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[9], 'b05bf940-0464-4c...') # Truncate to first 8 characters app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), { 'reveal_sensitive_prefix': '8'}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'}) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[9], '-') app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), { 'reveal_sensitive_prefix': '8'}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET', 'HTTP_X_AUTH_TOKEN': auth_token}) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[9], 'b05bf940...') # Token length and reveal_sensitive_prefix are same (no truncate) app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), { 'reveal_sensitive_prefix': str(len(auth_token))}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET', 'HTTP_X_AUTH_TOKEN': auth_token}) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[9], auth_token) # No effective limit on auth token app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), { 'reveal_sensitive_prefix': constraints.MAX_HEADER_SIZE}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET', 'HTTP_X_AUTH_TOKEN': auth_token}) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[9], auth_token) # Don't log x-auth-token app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), { 'reveal_sensitive_prefix': '0'}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'}) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[9], '-') app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), { 'reveal_sensitive_prefix': '0'}) app.access_logger = FakeLogger() req = Request.blank('/', environ={'REQUEST_METHOD': 'GET', 'HTTP_X_AUTH_TOKEN': auth_token}) resp = app(req.environ, start_response) resp_body = ''.join(resp) log_parts = self._log_parts(app) self.assertEquals(log_parts[9], '...') # Avoids pyflakes error, "local variable 'resp_body' is assigned to # but never used self.assertTrue(resp_body is not None)
def test_chunked_response(self): app = proxy_logging.ProxyLoggingMiddleware(FakeApp(chunked=True), {}) req = Request.blank('/') resp = app(req.environ, start_response) # exhaust generator [x for x in resp]