diff --git a/doc/source/development_saio.rst b/doc/source/development_saio.rst index ed9472b70c..2eed0ba283 100644 --- a/doc/source/development_saio.rst +++ b/doc/source/development_saio.rst @@ -287,7 +287,7 @@ Sample configuration files are provided with all defaults in line-by-line commen log_facility = LOG_LOCAL1 [pipeline:main] - pipeline = healthcheck cache tempauth proxy-server + pipeline = healthcheck cache tempauth proxy-logging proxy-server [app:proxy-server] use = egg:swift#proxy @@ -307,6 +307,9 @@ Sample configuration files are provided with all defaults in line-by-line commen [filter:cache] use = egg:swift#memcache + [filter:proxy-logging] + use = egg:swift#proxy_logging + #. Create `/etc/swift/swift.conf`: .. code-block:: none diff --git a/doc/source/misc.rst b/doc/source/misc.rst index 1c1c5ed983..6e1d8ca1aa 100644 --- a/doc/source/misc.rst +++ b/doc/source/misc.rst @@ -174,3 +174,10 @@ CNAME Lookup .. automodule:: swift.common.middleware.cname_lookup :members: :show-inheritance: + +Proxy Logging +============= + +.. automodule:: swift.common.middleware.proxy_logging + :members: + :show-inheritance: diff --git a/etc/proxy-server.conf-sample b/etc/proxy-server.conf-sample index 83fc5a44d8..13ee342f33 100644 --- a/etc/proxy-server.conf-sample +++ b/etc/proxy-server.conf-sample @@ -21,7 +21,7 @@ # log_statsd_metric_prefix = [pipeline:main] -pipeline = catch_errors healthcheck cache ratelimit tempauth proxy-server +pipeline = catch_errors healthcheck cache ratelimit tempauth proxy-logging proxy-server [app:proxy-server] use = egg:swift#proxy @@ -247,3 +247,6 @@ use = egg:swift#formpost use = egg:swift#name_check # forbidden_chars = '"`<> # maximum_length = 255 + +[filter:proxy-logging] +use = egg:swift#proxy_logging diff --git a/setup.py b/setup.py index 6e310483b6..7e68734796 100644 --- a/setup.py +++ b/setup.py @@ -93,6 +93,8 @@ setup( 'tempurl=swift.common.middleware.tempurl:filter_factory', 'formpost=swift.common.middleware.formpost:filter_factory', 'name_check=swift.common.middleware.name_check:filter_factory', + 'proxy_logging=swift.common.middleware.proxy_logging:' + 'filter_factory', ], }, ) diff --git a/swift/common/middleware/proxy_logging.py b/swift/common/middleware/proxy_logging.py new file mode 100644 index 0000000000..85c949f4b8 --- /dev/null +++ b/swift/common/middleware/proxy_logging.py @@ -0,0 +1,189 @@ +# Copyright (c) 2010-2011 OpenStack, LLC. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or +# implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +""" +Logging middleware for the Swift proxy. + +This serves as both the default logging implementation and an example of how +to plug in your own logging format/method. + +The logging format implemented below is as follows: + +client_ip remote_addr datetime request_method request_path protocol + status_int referer user_agent auth_token bytes_recvd bytes_sent + client_etag transaction_id headers request_time source + +These values are space-separated, and each is url-encoded, so that they can +be separated with a simple .split() + +* remote_addr is the contents of the REMOTE_ADDR environment variable, while + client_ip is swift's best guess at the end-user IP, extracted variously + from the X-Forwarded-For header, X-Cluster-Ip header, or the REMOTE_ADDR + environment variable. + +* Values that are missing (e.g. due to a header not being present) or zero + are generally represented by a single hyphen ('-'). +""" + +import time +from urllib import quote, unquote + +from webob import Request + +from swift.common.utils import get_logger, get_remote_client, TRUE_VALUES + + +class InputProxy(object): + """ + File-like object that counts bytes read. + To be swapped in for wsgi.input for accounting purposes. + """ + def __init__(self, wsgi_input): + """ + :param wsgi_input: file-like object to wrap the functionality of + """ + self.wsgi_input = wsgi_input + self.bytes_received = 0 + self.client_disconnect = False + + def read(self, *args, **kwargs): + """ + Pass read request to the underlying file-like object and + add bytes read to total. + """ + try: + chunk = self.wsgi_input.read(*args, **kwargs) + except Exception: + self.client_disconnect = True + raise + self.bytes_received += len(chunk) + return chunk + + def readline(self, *args, **kwargs): + """ + Pass readline request to the underlying file-like object and + add bytes read to total. + """ + try: + line = self.wsgi_input.readline(*args, **kwargs) + except Exception: + self.client_disconnect = True + raise + self.bytes_received += len(line) + return line + + +class ProxyLoggingMiddleware(object): + """ + Middleware that logs Swift proxy requests in the swift log format. + """ + + def __init__(self, app, conf): + self.app = app + self.log_hdrs = conf.get('log_headers', 'no').lower() in TRUE_VALUES + access_log_conf = {} + for key in ('log_facility', 'log_name', 'log_level'): + value = conf.get('access_' + key, conf.get(key, None)) + if value: + access_log_conf[key] = value + self.access_logger = get_logger(access_log_conf, + log_route='proxy-access') + + def log_request(self, env, status_int, bytes_received, bytes_sent, + request_time, client_disconnect): + """ + Log a request. + + :param env: WSGI environment + :param status_int: integer code for the response status + :param bytes_received: bytes successfully read from the request body + :param bytes_sent: bytes yielded to the WSGI server + :param request_time: time taken to satisfy the request, in seconds + """ + req = Request(env) + if client_disconnect: # log disconnected clients as '499' status code + status_int = 499 + the_request = quote(unquote(req.path)) + if req.query_string: + the_request = the_request + '?' + req.query_string + logged_headers = None + if self.log_hdrs: + logged_headers = '\n'.join('%s: %s' % (k, v) + for k, v in req.headers.items()) + self.access_logger.info(' '.join(quote(str(x) if x else '-') + for x in ( + get_remote_client(req), + req.remote_addr, + time.strftime('%d/%b/%Y/%H/%M/%S', time.gmtime()), + req.method, + the_request, + req.environ.get('SERVER_PROTOCOL'), + status_int, + req.referer, + req.user_agent, + req.headers.get('x-auth-token'), + bytes_received, + bytes_sent, + req.headers.get('etag', None), + req.environ.get('swift.trans_id'), + logged_headers, + '%.4f' % request_time, + req.environ.get('swift.source'), + ))) + self.access_logger.txn_id = None + + def __call__(self, env, start_response): + status_int = [500] + input_proxy = InputProxy(env['wsgi.input']) + env['wsgi.input'] = input_proxy + start_time = time.time() + + def my_start_response(status, headers, exc_info=None): + status_int[0] = int(status.split()[0]) + return start_response(status, headers, exc_info) + + def iter_response(iterator): + bytes_sent = 0 + client_disconnect = False + try: + for chunk in iterator: + bytes_sent += len(chunk) + yield chunk + except GeneratorExit: # generator was closed before we finished + client_disconnect = True + raise + finally: + self.log_request(env, status_int[0], + input_proxy.bytes_received, bytes_sent, + time.time() - start_time, + client_disconnect or input_proxy.client_disconnect) + + try: + iterator = self.app(env, my_start_response) + except Exception: + self.log_request(env, 500, input_proxy.bytes_received, 0, + time.time() - start_time, input_proxy.client_disconnect) + raise + else: + return iter_response(iterator) + + +def filter_factory(global_conf, **local_conf): + conf = global_conf.copy() + conf.update(local_conf) + + def proxy_logger(app): + return ProxyLoggingMiddleware(app, conf) + return proxy_logger diff --git a/swift/proxy/server.py b/swift/proxy/server.py index 0c105a6db5..527261ec61 100644 --- a/swift/proxy/server.py +++ b/swift/proxy/server.py @@ -65,8 +65,8 @@ from swift.common.http import is_informational, is_success, is_redirection, \ is_client_error, is_server_error, HTTP_CONTINUE, HTTP_OK, HTTP_CREATED, \ HTTP_ACCEPTED, HTTP_PARTIAL_CONTENT, HTTP_MULTIPLE_CHOICES, \ HTTP_BAD_REQUEST, HTTP_NOT_FOUND, HTTP_REQUESTED_RANGE_NOT_SATISFIABLE, \ - HTTP_CLIENT_CLOSED_REQUEST, HTTP_INTERNAL_SERVER_ERROR, \ - HTTP_SERVICE_UNAVAILABLE, HTTP_INSUFFICIENT_STORAGE, HTTPClientDisconnect + HTTP_INTERNAL_SERVER_ERROR, HTTP_SERVICE_UNAVAILABLE, \ + HTTP_INSUFFICIENT_STORAGE, HTTPClientDisconnect def update_headers(response, headers): @@ -129,11 +129,9 @@ class SegmentedIterable(object): """ Iterable that returns the object contents for a segmented object in Swift. - If set, the response's `bytes_transferred` value will be updated (used to - log the size of the request). Also, if there's a failure that cuts the - transfer short, the response's `status_int` will be updated (again, just - for logging since the original status would have already been sent to the - client). + If there's a failure that cuts the transfer short, the response's + `status_int` will be updated (again, just for logging since the original + status would have already been sent to the client). :param controller: The ObjectController instance to work with. :param container: The container the object segments are within. @@ -224,8 +222,6 @@ class SegmentedIterable(object): except StopIteration: self._load_next_segment() self.position += len(chunk) - self.response.bytes_transferred = getattr(self.response, - 'bytes_transferred', 0) + len(chunk) yield chunk except StopIteration: raise @@ -268,9 +264,6 @@ class SegmentedIterable(object): length -= len(chunk) if length < 0: # Chop off the extra: - self.response.bytes_transferred = \ - getattr(self.response, 'bytes_transferred', 0) \ - + length yield chunk[:length] break yield chunk @@ -714,12 +707,8 @@ class Controller(object): def _make_app_iter(self, node, source, response): """ Returns an iterator over the contents of the source (via its read - func). The response.bytes_transferred will be incremented as the - iterator is read so as to measure how much the client is actually sent. - response.client_disconnect will be set to true if the GeneratorExit - occurs before all the source is read. There is also quite a bit of - cleanup to ensure garbage collection works and the underlying socket of - the source is closed. + func). There is also quite a bit of cleanup to ensure garbage + collection works and the underlying socket of the source is closed. :param response: The webob.Response object this iterator should be assigned to via response.app_iter. @@ -740,11 +729,9 @@ class Controller(object): if not chunk: break yield chunk - response.bytes_transferred += len(chunk) except Empty: raise ChunkReadTimeout() except (GeneratorExit, Timeout): - response.client_disconnect = True self.app.logger.warn(_('Client disconnected on read')) except Exception: self.app.logger.exception(_('Trying to send to client')) @@ -831,7 +818,6 @@ class Controller(object): if req.method == 'GET' and \ source.status in (HTTP_OK, HTTP_PARTIAL_CONTENT): res = Response(request=req, conditional_response=True) - res.bytes_transferred = 0 res.app_iter = self._make_app_iter(node, source, res) # See NOTE: swift_conn at top of file about this. res.swift_conn = source.swift_conn @@ -1340,13 +1326,13 @@ class ObjectController(Controller): self.app.logger.increment('errors') return HTTPServiceUnavailable(request=req) chunked = req.headers.get('transfer-encoding') + bytes_transferred = 0 try: with ContextPool(len(nodes)) as pool: for conn in conns: conn.failed = False conn.queue = Queue(self.app.put_queue_depth) pool.spawn(self._send_file, conn, req.path) - req.bytes_transferred = 0 while True: with ChunkReadTimeout(self.app.client_timeout): try: @@ -1355,8 +1341,8 @@ class ObjectController(Controller): if chunked: [conn.queue.put('0\r\n\r\n') for conn in conns] break - req.bytes_transferred += len(chunk) - if req.bytes_transferred > MAX_FILE_SIZE: + bytes_transferred += len(chunk) + if bytes_transferred > MAX_FILE_SIZE: self.app.logger.increment('errors') return HTTPRequestEntityTooLarge(request=req) for conn in list(conns): @@ -1381,14 +1367,13 @@ class ObjectController(Controller): self.app.logger.increment('client_timeouts') return HTTPRequestTimeout(request=req) except (Exception, Timeout): - req.client_disconnect = True self.app.logger.exception( _('ERROR Exception causing client disconnect')) self.app.logger.increment('client_disconnects') self.app.logger.timing_since( '%s.timing' % (stats_type,), start_time) return HTTPClientDisconnect(request=req) - if req.content_length and req.bytes_transferred < req.content_length: + if req.content_length and bytes_transferred < req.content_length: req.client_disconnect = True self.app.logger.warn( _('Client disconnected without sending enough data')) @@ -1438,8 +1423,6 @@ class ObjectController(Controller): for k, v in req.headers.items(): if k.lower().startswith('x-object-meta-'): resp.headers[k] = v - # reset the bytes, since the user didn't actually send anything - req.bytes_transferred = 0 resp.last_modified = float(req.headers['X-Timestamp']) self.app.logger.timing_since('%s.timing' % (stats_type,), start_time) return resp @@ -1985,18 +1968,7 @@ class BaseApplication(object): if self.memcache is None: self.memcache = cache_from_env(env) req = self.update_request(Request(env)) - if 'eventlet.posthooks' in env: - env['eventlet.posthooks'].append( - (self.posthooklogger, (req,), {})) - return self.handle_request(req)(env, start_response) - else: - # Lack of posthook support means that we have to log on the - # start of the response, rather than after all the data has - # been sent. This prevents logging client disconnects - # differently than full transmissions. - response = self.handle_request(req)(env, start_response) - self.posthooklogger(env, req) - return response + return self.handle_request(req)(env, start_response) except (Exception, Timeout): print "EXCEPTION IN __call__: %s: %s" % \ (traceback.format_exc(), env) @@ -2004,12 +1976,7 @@ class BaseApplication(object): [('Content-Type', 'text/plain')]) return ['Internal server error.\n'] - def posthooklogger(self, env, req): - pass - def update_request(self, req): - req.bytes_transferred = '-' - req.client_disconnect = False if 'x-storage-token' in req.headers and \ 'x-auth-token' not in req.headers: req.headers['x-auth-token'] = req.headers['x-storage-token'] @@ -2098,45 +2065,6 @@ class Application(BaseApplication): req.response = super(Application, self).handle_request(req) return req.response - def posthooklogger(self, env, req): - response = getattr(req, 'response', None) - if not response: - return - trans_time = '%.4f' % (time.time() - req.start_time) - the_request = quote(unquote(req.path)) - if req.query_string: - the_request = the_request + '?' + req.query_string - client = get_remote_client(req) - logged_headers = None - if self.log_headers: - logged_headers = '\n'.join('%s: %s' % (k, v) - for k, v in req.headers.items()) - status_int = response.status_int - if getattr(req, 'client_disconnect', False) or \ - getattr(response, 'client_disconnect', False): - status_int = HTTP_CLIENT_CLOSED_REQUEST - self.access_logger.info(' '.join(quote(str(x)) for x in ( - client or '-', - req.remote_addr or '-', - time.strftime('%d/%b/%Y/%H/%M/%S', time.gmtime()), - req.method, - the_request, - req.environ['SERVER_PROTOCOL'], - status_int, - req.referer or '-', - req.user_agent or '-', - req.headers.get('x-auth-token', '-'), - getattr(req, 'bytes_transferred', 0) or '-', - getattr(response, 'bytes_transferred', 0) or '-', - req.headers.get('etag', '-'), - req.environ.get('swift.trans_id', '-'), - logged_headers or '-', - trans_time, - req.environ.get('swift.source', '-'), - ))) - # done with this transaction - self.access_logger.txn_id = None - def app_factory(global_conf, **local_conf): """paste.deploy app factory for creating WSGI proxy apps.""" diff --git a/test/unit/common/middleware/test_proxy_logging.py b/test/unit/common/middleware/test_proxy_logging.py new file mode 100644 index 0000000000..cd5c20661f --- /dev/null +++ b/test/unit/common/middleware/test_proxy_logging.py @@ -0,0 +1,228 @@ +# Copyright (c) 2010-2011 OpenStack, LLC. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or +# implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import unittest +from urllib import quote, unquote +import cStringIO as StringIO + +from webob import Request + +from swift.common.middleware import proxy_logging + + +class FakeApp(object): + def __init__(self, body=['FAKE APP']): + self.body = body + + def __call__(self, env, start_response): + start_response('200 OK', [('Content-Type', 'text/plain')]) + while env['wsgi.input'].read(5): + pass + return self.body + + +class FileLikeExceptor(object): + def __init__(self): + pass + + def read(self, len): + raise IOError('of some sort') + + def readline(self, len=1024): + raise IOError('of some sort') + + +class FakeAppReadline(object): + def __call__(self, env, start_response): + start_response('200 OK', [('Content-Type', 'text/plain')]) + line = env['wsgi.input'].readline() + return ["FAKE APP"] + + +class FakeLogger(object): + def __init__(self, *args, **kwargs): + self.msg = '' + + def info(self, string): + self.msg = string + + +def start_response(*args): + pass + + +class TestProxyLogging(unittest.TestCase): + + 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 = ''.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, 'FAKE APP') + self.assertEquals(log_parts[11], str(len(resp_body))) + + 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_log_headers(self): + app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), + {'log_headers': 'yes'}) + app.access_logger = FakeLogger() + req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'}) + resp = app(req.environ, start_response) + exhaust_generator = [x for x in resp] + log_parts = app.access_logger.msg.split() + headers = unquote(log_parts[14]).split('\n') + self.assert_('Host: localhost:80' in headers) + + 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_upload_line(self): + app = proxy_logging.ProxyLoggingMiddleware(FakeAppReadline(), + {'log_headers': 'yes'}) + app.access_logger = FakeLogger() + req = Request.blank('/', environ={'REQUEST_METHOD': 'GET', + 'wsgi.input': StringIO.StringIO( + 'some stuff\nsome other stuff\n')}) + resp = app(req.environ, start_response) + exhaust_generator = ''.join(resp) + log_parts = app.access_logger.msg.split() + self.assertEquals(log_parts[10], str(len('some stuff\n'))) + + 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 = app.access_logger.msg.split() + self.assertEquals(unquote(log_parts[4]), '/?x=3') + + 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 = app.access_logger.msg.split() + self.assertEquals(log_parts[0], '1.2.3.4') # client ip + self.assertEquals(log_parts[1], '1.2.3.4') # remote addr + + def test_proxy_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', + 'HTTP_X_FORWARDED_FOR': '4.5.6.7,8.9.10.11' + }) + resp = app(req.environ, start_response) + exhaust_generator = [x for x in resp] + log_parts = app.access_logger.msg.split() + self.assertEquals(log_parts[0], '4.5.6.7') # client ip + self.assertEquals(log_parts[1], '1.2.3.4') # remote addr + + app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {}) + app.access_logger = FakeLogger() + req = Request.blank('/', environ={'REQUEST_METHOD': 'GET', + 'REMOTE_ADDR': '1.2.3.4', + 'HTTP_X_CLUSTER_CLIENT_IP': '4.5.6.7' + }) + resp = app(req.environ, start_response) + exhaust_generator = [x for x in resp] + log_parts = app.access_logger.msg.split() + self.assertEquals(log_parts[0], '4.5.6.7') # client ip + self.assertEquals(log_parts[1], '1.2.3.4') # remote addr + + def test_facility(self): + app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), + {'log_headers': 'yes', 'access_log_facility': 'whatever'}) + + def test_filter(self): + factory = proxy_logging.filter_factory({}) + self.assert_(callable(factory)) + self.assert_(callable(factory(FakeApp()))) + + def test_unread_body(self): + app = proxy_logging.ProxyLoggingMiddleware( + FakeApp(['some', 'stuff']), {}) + app.access_logger = FakeLogger() + req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'}) + resp = app(req.environ, start_response) + read_first_chunk = next(resp) + resp.close() # raise a GeneratorExit in middleware app_iter loop + log_parts = app.access_logger.msg.split() + self.assertEquals(log_parts[6], '499') + self.assertEquals(log_parts[11], '4') # write length + + 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 = app.access_logger.msg.split() + self.assertEquals(log_parts[6], '499') + self.assertEquals(log_parts[10], '-') # read length + + def test_disconnect_on_read(self): + app = proxy_logging.ProxyLoggingMiddleware( + FakeApp(['some', 'stuff']), {}) + 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 = app.access_logger.msg.split() + self.assertEquals(log_parts[6], '499') + self.assertEquals(log_parts[10], '-') # read length + +if __name__ == '__main__': + unittest.main() diff --git a/test/unit/proxy/test_server.py b/test/unit/proxy/test_server.py index 10b38ef156..cac43e5130 100644 --- a/test/unit/proxy/test_server.py +++ b/test/unit/proxy/test_server.py @@ -546,131 +546,6 @@ class TestController(unittest.TestCase): class TestProxyServer(unittest.TestCase): - def test_access_log(self): - - class MyApp(proxy_server.Application): - - def handle_request(self, req): - resp = Response(request=req) - req.response = resp - req.start_time = time() - return resp - - def start_response(*args): - pass - - class MockLogger(): - - def __init__(self): - self.buffer = StringIO() - - def info(self, msg, args=None): - if args: - msg = msg % args - self.buffer.write(msg) - - def strip_value(self): - rv = self.buffer.getvalue() - self.buffer.truncate(0) - return rv - - class SnarfStream(object): - # i can't seem to subclass cStringIO - - def __init__(self, *args, **kwargs): - self.sio = StringIO() - - def strip_value(self): - rv = self.getvalue().strip() - self.truncate(0) - return rv - - def __getattr__(self, name): - try: - return object.__getattr__(self, name) - except AttributeError: - try: - return getattr(self.sio, name) - except AttributeError: - return self.__getattribute__(name) - - snarf = SnarfStream() - _orig_get_logger = proxy_server.get_logger - - def mock_get_logger(*args, **kwargs): - if kwargs.get('log_route') != 'proxy-access': - return _orig_get_logger(*args, **kwargs) - kwargs['log_route'] = 'snarf' - logger = _orig_get_logger(*args, **kwargs) - if [h for h in logger.logger.handlers if - isinstance(h, logging.StreamHandler) and h.stream is snarf]: - # snarf handler already setup! - return logger - formatter = logger.logger.handlers[0].formatter - formatter._fmt += ' %(levelname)s' - snarf_handler = logging.StreamHandler(snarf) - snarf_handler.setFormatter(formatter) - logger.logger.addHandler(snarf_handler) - return logger - - def test_conf(conf): - app = MyApp(conf, memcache=FakeMemcache(), account_ring=FakeRing(), - container_ring=FakeRing(), object_ring=FakeRing()) - req = Request.blank('') - app(req.environ, start_response) - - try: - proxy_server.get_logger = mock_get_logger - test_conf({}) - line = snarf.strip_value() - self.assert_(line.startswith('swift')) - self.assert_(line.endswith('INFO')) - test_conf({'log_name': 'snarf-test'}) - line = snarf.strip_value() - self.assert_(line.startswith('snarf-test')) - self.assert_(line.endswith('INFO')) - test_conf({'log_name': 'snarf-test', 'log_level': 'ERROR'}) - line = snarf.strip_value() - self.assertFalse(line) - test_conf({'log_name': 'snarf-test', 'log_level': 'ERROR', - 'access_log_name': 'access-test', - 'access_log_level': 'INFO'}) - line = snarf.strip_value() - self.assert_(line.startswith('access-test')) - self.assert_(line.endswith('INFO')) - - # test facility - def get_facility(logger): - h = [h for h in logger.logger.handlers if - isinstance(h, SysLogHandler)][0] - return h.facility - - conf = {'log_facility': 'LOG_LOCAL0'} - app = MyApp(conf, memcache=FakeMemcache(), account_ring=FakeRing(), - container_ring=FakeRing(), object_ring=FakeRing()) - self.assertEquals(get_facility(app.logger), - SysLogHandler.LOG_LOCAL0) - self.assertEquals(get_facility(app.access_logger), - SysLogHandler.LOG_LOCAL0) - conf = {'log_facility': 'LOG_LOCAL0', - 'access_log_facility': 'LOG_LOCAL1'} - app = MyApp(conf, memcache=FakeMemcache(), account_ring=FakeRing(), - container_ring=FakeRing(), object_ring=FakeRing()) - self.assertEquals(get_facility(app.logger), - SysLogHandler.LOG_LOCAL0) - self.assertEquals(get_facility(app.access_logger), - SysLogHandler.LOG_LOCAL1) - conf = {'access_log_facility': 'LOG_LOCAL1'} - app = MyApp(conf, memcache=FakeMemcache(), account_ring=FakeRing(), - container_ring=FakeRing(), object_ring=FakeRing()) - self.assertEquals(get_facility(app.logger), - SysLogHandler.LOG_LOCAL0) - self.assertEquals(get_facility(app.access_logger), - SysLogHandler.LOG_LOCAL1) - - finally: - proxy_server.get_logger = _orig_get_logger - def test_unhandled_exception(self): class MyApp(proxy_server.Application): @@ -2133,77 +2008,6 @@ class TestObjectController(unittest.TestCase): self.assertEquals(headers[:len(exp)], exp) self.assert_('\r\nContent-Length: 0\r\n' in headers) - def test_client_ip_logging(self): - # test that the client ip field in the log gets populated with the - # ip instead of being blank - (prosrv, acc1srv, acc2srv, con1srv, con2srv, obj1srv, obj2srv) = \ - _test_servers - (prolis, acc1lis, acc2lis, con1lis, con2lis, obj1lis, obj2lis) = \ - _test_sockets - - orig_logger, orig_access_logger = prosrv.logger, prosrv.access_logger - prosrv.logger = prosrv.access_logger = FakeLogger() - sock = connect_tcp(('localhost', prolis.getsockname()[1])) - fd = sock.makefile() - fd.write( - 'GET /v1/a?format=json 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 200' - self.assertEquals(headers[:len(exp)], exp) - exp = '127.0.0.1 127.0.0.1' - self.assertEquals(prosrv.logger.log_dict['exception'], []) - self.assert_(exp in prosrv.logger.log_dict['info'][-1][0][0]) - - def test_chunked_put_logging(self): - # GET account with a query string to test that - # Application.log_request logs the query string. Also, throws - # in a test for logging x-forwarded-for (first entry only). - (prosrv, acc1srv, acc2srv, con1srv, con2srv, obj1srv, obj2srv) = \ - _test_servers - (prolis, acc1lis, acc2lis, con1lis, con2lis, obj1lis, obj2lis) = \ - _test_sockets - - orig_logger, orig_access_logger = prosrv.logger, prosrv.access_logger - prosrv.logger = prosrv.access_logger = FakeLogger() - sock = connect_tcp(('localhost', prolis.getsockname()[1])) - fd = sock.makefile() - fd.write( - 'GET /v1/a?format=json HTTP/1.1\r\nHost: localhost\r\n' - 'Connection: close\r\nX-Auth-Token: t\r\n' - 'Content-Length: 0\r\nX-Forwarded-For: host1, host2\r\n' - '\r\n') - fd.flush() - headers = readuntil2crlfs(fd) - exp = 'HTTP/1.1 200' - self.assertEquals(headers[:len(exp)], exp) - got_log_msg = prosrv.logger.log_dict['info'][-1][0][0] - self.assert_('/v1/a%3Fformat%3Djson' in got_log_msg, - prosrv.logger.log_dict) - exp = 'host1' - self.assertEquals(got_log_msg[:len(exp)], exp) - # Turn on header logging. - - prosrv.logger = prosrv.access_logger = FakeLogger() - prosrv.log_headers = True - sock = connect_tcp(('localhost', prolis.getsockname()[1])) - fd = sock.makefile() - fd.write('GET /v1/a HTTP/1.1\r\nHost: localhost\r\n' - 'Connection: close\r\nX-Auth-Token: t\r\n' - 'Content-Length: 0\r\nGoofy-Header: True\r\n\r\n') - fd.flush() - headers = readuntil2crlfs(fd) - exp = 'HTTP/1.1 200' - self.assertEquals(headers[:len(exp)], exp) - self.assert_('Goofy-Header%3A%20True' in - prosrv.logger.log_dict['info'][-1][0][0], - prosrv.logger.log_dict) - prosrv.log_headers = False - prosrv.logger, prosrv.access_logger = orig_logger, orig_access_logger - def test_chunked_put_utf8_all_the_way_down(self): # Test UTF-8 Unicode all the way through the system ustr = '\xe1\xbc\xb8\xce\xbf\xe1\xbd\xba \xe1\xbc\xb0\xce' \ @@ -2914,87 +2718,6 @@ class TestObjectController(unittest.TestCase): resp = controller.PUT(req) self.assertEquals(resp.status_int // 100, 4) # client error - def test_request_bytes_transferred_attr(self): - with save_globals(): - proxy_server.http_connect = \ - fake_http_connect(200, 200, 201, 201, 201) - controller = proxy_server.ObjectController(self.app, 'account', - 'container', 'object') - req = Request.blank('/a/c/o', environ={'REQUEST_METHOD': 'PUT'}, - headers={'Content-Length': '10'}, - body='1234567890') - self.app.update_request(req) - res = controller.PUT(req) - self.assert_(hasattr(req, 'bytes_transferred')) - self.assertEquals(req.bytes_transferred, 10) - - def test_copy_zero_bytes_transferred_attr(self): - with save_globals(): - proxy_server.http_connect = \ - fake_http_connect(200, 200, 200, 200, 200, 201, 201, 201, - body='1234567890') - controller = proxy_server.ObjectController(self.app, 'account', - 'container', 'object') - req = Request.blank('/a/c/o', environ={'REQUEST_METHOD': 'PUT'}, - headers={'X-Copy-From': 'c/o2', - 'Content-Length': '0'}) - self.app.update_request(req) - res = controller.PUT(req) - self.assert_(hasattr(req, 'bytes_transferred')) - self.assertEquals(req.bytes_transferred, 0) - - def test_response_bytes_transferred_attr(self): - with save_globals(): - proxy_server.http_connect = \ - fake_http_connect(200, 200, 200, body='1234567890') - controller = proxy_server.ObjectController(self.app, 'account', - 'container', 'object') - req = Request.blank('/a/c/o') - self.app.update_request(req) - res = controller.GET(req) - res.body - self.assert_(hasattr(res, 'bytes_transferred')) - self.assertEquals(res.bytes_transferred, 10) - - def test_request_client_disconnect_attr(self): - with save_globals(): - proxy_server.http_connect = \ - fake_http_connect(200, 200, 201, 201, 201) - controller = proxy_server.ObjectController(self.app, 'account', - 'container', 'object') - req = Request.blank('/a/c/o', environ={'REQUEST_METHOD': 'PUT'}, - headers={'Content-Length': '10'}, - body='12345') - self.app.update_request(req) - res = controller.PUT(req) - self.assertEquals(req.bytes_transferred, 5) - self.assert_(hasattr(req, 'client_disconnect')) - self.assert_(req.client_disconnect) - - def test_response_client_disconnect_attr(self): - with save_globals(): - proxy_server.http_connect = \ - fake_http_connect(200, 200, 200, body='1234567890') - controller = proxy_server.ObjectController(self.app, 'account', - 'container', 'object') - req = Request.blank('/a/c/o') - self.app.update_request(req) - orig_object_chunk_size = self.app.object_chunk_size - try: - self.app.object_chunk_size = 5 - res = controller.GET(req) - ix = 0 - for v in res.app_iter: - ix += 1 - if ix > 1: - break - res.app_iter.close() - self.assertEquals(res.bytes_transferred, 5) - self.assert_(hasattr(res, 'client_disconnect')) - self.assert_(res.client_disconnect) - finally: - self.app.object_chunk_size = orig_object_chunk_size - def test_response_get_accept_ranges_header(self): with save_globals(): req = Request.blank('/a/c/o', environ={'REQUEST_METHOD': 'GET'}) @@ -3561,41 +3284,6 @@ class TestContainerController(unittest.TestCase): self.assert_status_map(controller.DELETE, (200, 404, 404, 404), 404) - def test_response_bytes_transferred_attr(self): - with save_globals(): - proxy_server.http_connect = fake_http_connect(200, 200, body='{}') - controller = proxy_server.ContainerController(self.app, 'account', - 'container') - req = Request.blank('/a/c?format=json') - self.app.update_request(req) - res = controller.GET(req) - res.body - self.assert_(hasattr(res, 'bytes_transferred')) - self.assertEquals(res.bytes_transferred, 2) - - def test_response_client_disconnect_attr(self): - with save_globals(): - proxy_server.http_connect = fake_http_connect(200, 200, body='{}') - controller = proxy_server.ContainerController(self.app, 'account', - 'container') - req = Request.blank('/a/c?format=json') - self.app.update_request(req) - orig_object_chunk_size = self.app.object_chunk_size - try: - self.app.object_chunk_size = 1 - res = controller.GET(req) - ix = 0 - for v in res.app_iter: - ix += 1 - if ix > 1: - break - res.app_iter.close() - self.assertEquals(res.bytes_transferred, 1) - self.assert_(hasattr(res, 'client_disconnect')) - self.assert_(res.client_disconnect) - finally: - self.app.object_chunk_size = orig_object_chunk_size - def test_response_get_accept_ranges_header(self): with save_globals(): proxy_server.http_connect = fake_http_connect(200, 200, body='{}') @@ -3950,17 +3638,6 @@ class TestAccountController(unittest.TestCase): resp = controller.HEAD(req) self.assertEquals(resp.status_int, 503) - def test_response_bytes_transferred_attr(self): - with save_globals(): - proxy_server.http_connect = fake_http_connect(200, 200, body='{}') - controller = proxy_server.AccountController(self.app, 'account') - req = Request.blank('/a?format=json') - self.app.update_request(req) - res = controller.GET(req) - res.body - self.assert_(hasattr(res, 'bytes_transferred')) - self.assertEquals(res.bytes_transferred, 2) - def test_response_get_accept_ranges_header(self): with save_globals(): proxy_server.http_connect = fake_http_connect(200, 200, body='{}') @@ -3982,28 +3659,6 @@ class TestAccountController(unittest.TestCase): self.assert_('accept-ranges' in res.headers) self.assertEqual(res.headers['accept-ranges'], 'bytes') - def test_response_client_disconnect_attr(self): - with save_globals(): - proxy_server.http_connect = fake_http_connect(200, 200, body='{}') - controller = proxy_server.AccountController(self.app, 'account') - req = Request.blank('/a?format=json') - self.app.update_request(req) - orig_object_chunk_size = self.app.object_chunk_size - try: - self.app.object_chunk_size = 1 - res = controller.GET(req) - ix = 0 - for v in res.app_iter: - ix += 1 - if ix > 1: - break - res.app_iter.close() - self.assertEquals(res.bytes_transferred, 1) - self.assert_(hasattr(res, 'client_disconnect')) - self.assert_(res.client_disconnect) - finally: - self.app.object_chunk_size = orig_object_chunk_size - def test_PUT(self): with save_globals(): controller = proxy_server.AccountController(self.app, 'account') @@ -4325,14 +3980,12 @@ class TestSegmentedIterable(unittest.TestCase): 'o1'}]) segit.response = Stub() self.assertEquals(''.join(segit), '1') - self.assertEquals(segit.response.bytes_transferred, 1) def test_iter_with_two_segments(self): segit = proxy_server.SegmentedIterable(self.controller, 'lc', [{'name': 'o1'}, {'name': 'o2'}]) segit.response = Stub() self.assertEquals(''.join(segit), '122') - self.assertEquals(segit.response.bytes_transferred, 3) def test_iter_with_get_error(self): @@ -4372,7 +4025,6 @@ class TestSegmentedIterable(unittest.TestCase): segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing) segit.response = Stub() self.assertEquals(''.join(segit.app_iter_range(None, None)), '1') - self.assertEquals(segit.response.bytes_transferred, 1) segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing) self.assertEquals(''.join(segit.app_iter_range(3, None)), '') @@ -4383,7 +4035,6 @@ class TestSegmentedIterable(unittest.TestCase): segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing) segit.response = Stub() self.assertEquals(''.join(segit.app_iter_range(None, 5)), '1') - self.assertEquals(segit.response.bytes_transferred, 1) def test_app_iter_range_with_two_segments(self): listing = [{'name': 'o1', 'bytes': 1}, {'name': 'o2', 'bytes': 2}] @@ -4391,22 +4042,18 @@ class TestSegmentedIterable(unittest.TestCase): segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing) segit.response = Stub() self.assertEquals(''.join(segit.app_iter_range(None, None)), '122') - self.assertEquals(segit.response.bytes_transferred, 3) segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing) segit.response = Stub() self.assertEquals(''.join(segit.app_iter_range(1, None)), '22') - self.assertEquals(segit.response.bytes_transferred, 2) segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing) segit.response = Stub() self.assertEquals(''.join(segit.app_iter_range(1, 5)), '22') - self.assertEquals(segit.response.bytes_transferred, 2) segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing) segit.response = Stub() self.assertEquals(''.join(segit.app_iter_range(None, 2)), '12') - self.assertEquals(segit.response.bytes_transferred, 2) def test_app_iter_range_with_many_segments(self): listing = [{'name': 'o1', 'bytes': 1}, {'name': 'o2', 'bytes': 2}, @@ -4417,38 +4064,31 @@ class TestSegmentedIterable(unittest.TestCase): segit.response = Stub() self.assertEquals(''.join(segit.app_iter_range(None, None)), '122333444455555') - self.assertEquals(segit.response.bytes_transferred, 15) segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing) segit.response = Stub() self.assertEquals(''.join(segit.app_iter_range(3, None)), '333444455555') - self.assertEquals(segit.response.bytes_transferred, 12) segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing) segit.response = Stub() self.assertEquals(''.join(segit.app_iter_range(5, None)), '3444455555') - self.assertEquals(segit.response.bytes_transferred, 10) segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing) segit.response = Stub() self.assertEquals(''.join(segit.app_iter_range(None, 6)), '122333') - self.assertEquals(segit.response.bytes_transferred, 6) segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing) segit.response = Stub() self.assertEquals(''.join(segit.app_iter_range(None, 7)), '1223334') - self.assertEquals(segit.response.bytes_transferred, 7) segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing) segit.response = Stub() self.assertEquals(''.join(segit.app_iter_range(3, 7)), '3334') - self.assertEquals(segit.response.bytes_transferred, 4) segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing) segit.response = Stub() self.assertEquals(''.join(segit.app_iter_range(5, 7)), '34') - self.assertEquals(segit.response.bytes_transferred, 2) if __name__ == '__main__':