diff --git a/doc/source/admin_guide.rst b/doc/source/admin_guide.rst index 401693c043..9182de2236 100644 --- a/doc/source/admin_guide.rst +++ b/doc/source/admin_guide.rst @@ -477,35 +477,36 @@ Metric Name Description Metrics for `account-server` ("Not Found" is not considered an error and requests which increment `errors` are not included in the timing data): -================================= ==================================================== -Metric Name Description ---------------------------------- ---------------------------------------------------- -`account-server.DELETE.errors` Count of errors handling DELETE requests: bad - request, not mounted, missing timestamp. -`account-server.DELETE.timing` Timing data for each DELETE request not resulting in - an error. -`account-server.PUT.errors` Count of errors handling PUT requests: bad request, - not mounted, conflict. -`account-server.PUT.timing` Timing data for each PUT request not resulting in an - error. -`account-server.HEAD.errors` Count of errors handling HEAD requests: bad request, - not mounted. -`account-server.HEAD.timing` Timing data for each HEAD request not resulting in - an error. -`account-server.GET.errors` Count of errors handling GET requests: bad request, - not mounted, bad delimiter, account listing limit - too high, bad accept header. -`account-server.GET.timing` Timing data for each GET request not resulting in - an error. -`account-server.REPLICATE.errors` Count of errors handling REPLICATE requests: bad - request, not mounted. -`account-server.REPLICATE.timing` Timing data for each REPLICATE request not resulting - in an error. -`account-server.POST.errors` Count of errors handling POST requests: bad request, - bad or missing timestamp, not mounted. -`account-server.POST.timing` Timing data for each POST request not resulting in - an error. -================================= ==================================================== +======================================== ======================================================= +Metric Name Description +---------------------------------------- ------------------------------------------------------- +`account-server.DELETE.errors.timing` Timing data for each DELETE request resulting in an + error: bad request, not mounted, missing timestamp. +`account-server.DELETE.timing` Timing data for each DELETE request not resulting in + an error. +`account-server.PUT.errors.timing` Timing data for each PUT request resulting in an error: + bad request, not mounted, conflict, recently-deleted. +`account-server.PUT.timing` Timing data for each PUT request not resulting in an + error. +`account-server.HEAD.errors.timing` Timing data for each HEAD request resulting in an + error: bad request, not mounted. +`account-server.HEAD.timing` Timing data for each HEAD request not resulting in + an error. +`account-server.GET.errors.timing` Timing data for each GET request resulting in an + error: bad request, not mounted, bad delimiter, + account listing limit too high, bad accept header. +`account-server.GET.timing` Timing data for each GET request not resulting in + an error. +`account-server.REPLICATE.errors.timing` Timing data for each REPLICATE request resulting in an + error: bad request, not mounted. +`account-server.REPLICATE.timing` Timing data for each REPLICATE request not resulting + in an error. +`account-server.POST.errors.timing` Timing data for each POST request resulting in an + error: bad request, bad or missing timestamp, not + mounted. +`account-server.POST.timing` Timing data for each POST request not resulting in + an error. +======================================== ======================================================= Metrics for `account-replicator`: @@ -584,34 +585,34 @@ Metric Name Description Metrics for `container-server` ("Not Found" is not considered an error and requests which increment `errors` are not included in the timing data): -=================================== ==================================================== -Metric Name Description ------------------------------------ ---------------------------------------------------- -`container-server.DELETE.errors` Count of errors handling DELETE requests: bad - request, not mounted, missing timestamp, conflict. -`container-server.DELETE.timing` Timing data for each DELETE request not resulting in - an error. -`container-server.PUT.errors` Count of errors handling PUT requests: bad request, - missing timestamp, not mounted, conflict. -`container-server.PUT.timing` Timing data for each PUT request not resulting in an - error. -`container-server.HEAD.errors` Count of errors handling HEAD requests: bad request, - not mounted. -`container-server.HEAD.timing` Timing data for each HEAD request not resulting in - an error. -`container-server.GET.errors` Count of errors handling GET requests: bad request, - not mounted, parameters not utf8, bad accept header. -`container-server.GET.timing` Timing data for each GET request not resulting in - an error. -`container-server.REPLICATE.errors` Count of errors handling REPLICATE requests: bad - request, not mounted. -`container-server.REPLICATE.timing` Timing data for each REPLICATE request not resulting - in an error. -`container-server.POST.errors` Count of errors handling POST requests: bad request, - bad x-container-sync-to, not mounted. -`container-server.POST.timing` Timing data for each POST request not resulting in - an error. -=================================== ==================================================== +========================================== ==================================================== +Metric Name Description +------------------------------------------ ---------------------------------------------------- +`container-server.DELETE.errors.timing` Timing data for DELETE request errors: bad request, + not mounted, missing timestamp, conflict. +`container-server.DELETE.timing` Timing data for each DELETE request not resulting in + an error. +`container-server.PUT.errors.timing` Timing data for PUT request errors: bad request, + missing timestamp, not mounted, conflict. +`container-server.PUT.timing` Timing data for each PUT request not resulting in an + error. +`container-server.HEAD.errors.timing` Timing data for HEAD request errors: bad request, + not mounted. +`container-server.HEAD.timing` Timing data for each HEAD request not resulting in + an error. +`container-server.GET.errors.timing` Timing data for GET request errors: bad request, + not mounted, parameters not utf8, bad accept header. +`container-server.GET.timing` Timing data for each GET request not resulting in + an error. +`container-server.REPLICATE.errors.timing` Timing data for REPLICATE request errors: bad + request, not mounted. +`container-server.REPLICATE.timing` Timing data for each REPLICATE request not resulting + in an error. +`container-server.POST.errors.timing` Timing data for POST request errors: bad request, + bad x-container-sync-to, not mounted. +`container-server.POST.timing` Timing data for each POST request not resulting in + an error. +========================================== ==================================================== Metrics for `container-sync`: @@ -700,47 +701,49 @@ Metric Name Description Metrics for `object-server`: -================================ ==================================================== -Metric Name Description --------------------------------- ---------------------------------------------------- -`object-server.quarantines` Count of objects (files) found bad and moved to - quarantine. -`object-server.async_pendings` Count of container updates saved as async_pendings - (may result from PUT or DELETE requests). -`object-server.POST.errors` Count of errors handling POST requests: bad request, - missing timestamp, delete-at in past, not mounted. -`object-server.POST.timing` Timing data for each POST request not resulting in - an error. -`object-server.PUT.errors` Count of errors handling PUT requests: bad request, - not mounted, missing timestamp, object creation - constraint violation, delete-at in past. -`object-server.PUT.timeouts` Count of object PUTs which exceeded max_upload_time. -`object-server.PUT.timing` Timing data for each PUT request not resulting in an - error. -`object-server.GET.errors` Count of errors handling GET requests: bad request, - not mounted, header timestamps before the epoch. - File errors resulting in a quarantine are not - counted here. -`object-server.GET.timing` Timing data for each GET request not resulting in an - error. Includes requests which couldn't find the - object (including disk errors resulting in file - quarantine). -`object-server.HEAD.errors` Count of errors handling HEAD requests: bad request, - not mounted. -`object-server.HEAD.timing` Timing data for each HEAD request not resulting in - an error. Includes requests which couldn't find the - object (including disk errors resulting in file - quarantine). -`object-server.DELETE.errors` Count of errors handling DELETE requests: bad - request, missing timestamp, not mounted. Includes - requests which couldn't find or match the object. -`object-server.DELETE.timing` Timing data for each DELETE request not resulting - in an error. -`object-server.REPLICATE.errors` Count of errors handling REPLICATE requests: bad - request, not mounted. -`object-server.REPLICATE.timing` Timing data for each REPLICATE request not resulting - in an error. -================================ ==================================================== +======================================= ==================================================== +Metric Name Description +--------------------------------------- ---------------------------------------------------- +`object-server.quarantines` Count of objects (files) found bad and moved to + quarantine. +`object-server.async_pendings` Count of container updates saved as async_pendings + (may result from PUT or DELETE requests). +`object-server.POST.errors.timing` Timing data for POST request errors: bad request, + missing timestamp, delete-at in past, not mounted. +`object-server.POST.timing` Timing data for each POST request not resulting in + an error. +`object-server.PUT.errors.timing` Timing data for PUT request errors: bad request, + not mounted, missing timestamp, object creation + constraint violation, delete-at in past. +`object-server.PUT.timeouts` Count of object PUTs which exceeded max_upload_time. +`object-server.PUT.timing` Timing data for each PUT request not resulting in an + error. +`object-server.GET.errors.timing` Timing data for GET request errors: bad request, + not mounted, header timestamps before the epoch, + precondition failed. + File errors resulting in a quarantine are not + counted here. +`object-server.GET.timing` Timing data for each GET request not resulting in an + error. Includes requests which couldn't find the + object (including disk errors resulting in file + quarantine). +`object-server.HEAD.errors.timing` Timing data for HEAD request errors: bad request, + not mounted. +`object-server.HEAD.timing` Timing data for each HEAD request not resulting in + an error. Includes requests which couldn't find the + object (including disk errors resulting in file + quarantine). +`object-server.DELETE.errors.timing` Timing data for DELETE request errors: bad request, + missing timestamp, not mounted, precondition + failed. Includes requests which couldn't find or + match the object. +`object-server.DELETE.timing` Timing data for each DELETE request not resulting + in an error. +`object-server.REPLICATE.errors.timing` Timing data for REPLICATE request errors: bad + request, not mounted. +`object-server.REPLICATE.timing` Timing data for each REPLICATE request not resulting + in an error. +======================================= ==================================================== Metrics for `object-updater`: diff --git a/swift/account/server.py b/swift/account/server.py index d8dd442b0d..ad6ecde3ba 100644 --- a/swift/account/server.py +++ b/swift/account/server.py @@ -27,7 +27,7 @@ import swift.common.db from swift.common.db import AccountBroker from swift.common.utils import get_logger, get_param, hash_path, public, \ normalize_timestamp, split_path, storage_directory, config_true_value, \ - validate_device_partition, json + validate_device_partition, json, timing_stats from swift.common.constraints import ACCOUNT_LISTING_LIMIT, \ check_mount, check_float, check_utf8, FORMAT2CONTENT_TYPE from swift.common.db_replicator import ReplicatorRpc @@ -63,46 +63,39 @@ class AccountController(object): return AccountBroker(db_path, account=account, logger=self.logger) @public + @timing_stats def DELETE(self, req): """Handle HTTP DELETE request.""" - start_time = time.time() try: drive, part, account = split_path(unquote(req.path), 3) validate_device_partition(drive, part) except ValueError, err: - self.logger.increment('DELETE.errors') return HTTPBadRequest(body=str(err), content_type='text/plain', request=req) if self.mount_check and not check_mount(self.root, drive): - self.logger.increment('DELETE.errors') return HTTPInsufficientStorage(drive=drive, request=req) if 'x-timestamp' not in req.headers or \ not check_float(req.headers['x-timestamp']): - self.logger.increment('DELETE.errors') return HTTPBadRequest(body='Missing timestamp', request=req, content_type='text/plain') broker = self._get_account_broker(drive, part, account) if broker.is_deleted(): - self.logger.timing_since('DELETE.timing', start_time) return HTTPNotFound(request=req) broker.delete_db(req.headers['x-timestamp']) - self.logger.timing_since('DELETE.timing', start_time) return HTTPNoContent(request=req) @public + @timing_stats def PUT(self, req): """Handle HTTP PUT request.""" - start_time = time.time() try: drive, part, account, container = split_path(unquote(req.path), 3, 4) validate_device_partition(drive, part) except ValueError, err: - self.logger.increment('PUT.errors') return HTTPBadRequest(body=str(err), content_type='text/plain', request=req) if self.mount_check and not check_mount(self.root, drive): - self.logger.increment('PUT.errors') return HTTPInsufficientStorage(drive=drive, request=req) broker = self._get_account_broker(drive, part, account) if container: # put account container @@ -114,13 +107,11 @@ class AccountController(object): req.headers.get('x-timestamp') or time.time())) if req.headers.get('x-account-override-deleted', 'no').lower() != \ 'yes' and broker.is_deleted(): - self.logger.timing_since('PUT.timing', start_time) return HTTPNotFound(request=req) broker.put_container(container, req.headers['x-put-timestamp'], req.headers['x-delete-timestamp'], req.headers['x-object-count'], req.headers['x-bytes-used']) - self.logger.timing_since('PUT.timing', start_time) if req.headers['x-delete-timestamp'] > \ req.headers['x-put-timestamp']: return HTTPNoContent(request=req) @@ -132,13 +123,11 @@ class AccountController(object): broker.initialize(timestamp) created = True elif broker.is_status_deleted(): - self.logger.timing_since('PUT.timing', start_time) return HTTPForbidden(request=req, body='Recently deleted') else: created = broker.is_deleted() broker.update_put_timestamp(timestamp) if broker.is_deleted(): - self.logger.increment('PUT.errors') return HTTPConflict(request=req) metadata = {} metadata.update((key, (value, timestamp)) @@ -146,13 +135,13 @@ class AccountController(object): if key.lower().startswith('x-account-meta-')) if metadata: broker.update_metadata(metadata) - self.logger.timing_since('PUT.timing', start_time) if created: return HTTPCreated(request=req) else: return HTTPAccepted(request=req) @public + @timing_stats def HEAD(self, req): """Handle HTTP HEAD request.""" # TODO(refactor): The account server used to provide a 'account and @@ -161,24 +150,20 @@ class AccountController(object): # container servers directly so this is no longer needed. We should # refactor out the container existence check here and retest # everything. - start_time = time.time() try: drive, part, account, container = split_path(unquote(req.path), 3, 4) validate_device_partition(drive, part) except ValueError, err: - self.logger.increment('HEAD.errors') return HTTPBadRequest(body=str(err), content_type='text/plain', request=req) if self.mount_check and not check_mount(self.root, drive): - self.logger.increment('HEAD.errors') return HTTPInsufficientStorage(drive=drive, request=req) broker = self._get_account_broker(drive, part, account) if not container: broker.pending_timeout = 0.1 broker.stale_reads_ok = True if broker.is_deleted(): - self.logger.timing_since('HEAD.timing', start_time) return HTTPNotFound(request=req) info = broker.get_info() headers = { @@ -203,31 +188,26 @@ class AccountController(object): 'text/xml'], default_match='text/plain') except AssertionError, err: - self.logger.increment('HEAD.errors') return HTTPBadRequest(body='bad accept header: %s' % req.accept, content_type='text/plain', request=req) - self.logger.timing_since('HEAD.timing', start_time) return HTTPNoContent(request=req, headers=headers, charset='utf-8') @public + @timing_stats def GET(self, req): """Handle HTTP GET request.""" - start_time = time.time() try: drive, part, account = split_path(unquote(req.path), 3) validate_device_partition(drive, part) except ValueError, err: - self.logger.increment('GET.errors') return HTTPBadRequest(body=str(err), content_type='text/plain', request=req) if self.mount_check and not check_mount(self.root, drive): - self.logger.increment('GET.errors') return HTTPInsufficientStorage(drive=drive, request=req) broker = self._get_account_broker(drive, part, account) broker.pending_timeout = 0.1 broker.stale_reads_ok = True if broker.is_deleted(): - self.logger.timing_since('GET.timing', start_time) return HTTPNotFound(request=req) info = broker.get_info() resp_headers = { @@ -244,14 +224,12 @@ class AccountController(object): delimiter = get_param(req, 'delimiter') if delimiter and (len(delimiter) > 1 or ord(delimiter) > 254): # delimiters can be made more flexible later - self.logger.increment('GET.errors') return HTTPPreconditionFailed(body='Bad delimiter') limit = ACCOUNT_LISTING_LIMIT given_limit = get_param(req, 'limit') if given_limit and given_limit.isdigit(): limit = int(given_limit) if limit > ACCOUNT_LISTING_LIMIT: - self.logger.increment('GET.errors') return HTTPPreconditionFailed(request=req, body='Maximum limit is %d' % ACCOUNT_LISTING_LIMIT) @@ -259,7 +237,6 @@ class AccountController(object): end_marker = get_param(req, 'end_marker') query_format = get_param(req, 'format') except UnicodeDecodeError, err: - self.logger.increment('GET.errors') return HTTPBadRequest(body='parameters not utf8', content_type='text/plain', request=req) if query_format: @@ -271,7 +248,6 @@ class AccountController(object): 'text/xml'], default_match='text/plain') except AssertionError, err: - self.logger.increment('GET.errors') return HTTPBadRequest(body='bad accept header: %s' % req.accept, content_type='text/plain', request=req) account_list = broker.list_containers_iter(limit, marker, end_marker, @@ -301,66 +277,56 @@ class AccountController(object): account_list = '\n'.join(output_list) else: if not account_list: - self.logger.timing_since('GET.timing', start_time) return HTTPNoContent(request=req, headers=resp_headers) account_list = '\n'.join(r[0] for r in account_list) + '\n' ret = Response(body=account_list, request=req, headers=resp_headers) ret.content_type = out_content_type ret.charset = 'utf-8' - self.logger.timing_since('GET.timing', start_time) return ret @public + @timing_stats def REPLICATE(self, req): """ Handle HTTP REPLICATE request. Handler for RPC calls for account replication. """ - start_time = time.time() try: post_args = split_path(unquote(req.path), 3) drive, partition, hash = post_args validate_device_partition(drive, partition) except ValueError, err: - self.logger.increment('REPLICATE.errors') return HTTPBadRequest(body=str(err), content_type='text/plain', request=req) if self.mount_check and not check_mount(self.root, drive): - self.logger.increment('REPLICATE.errors') return HTTPInsufficientStorage(drive=drive, request=req) try: args = json.load(req.environ['wsgi.input']) except ValueError, err: - self.logger.increment('REPLICATE.errors') return HTTPBadRequest(body=str(err), content_type='text/plain') ret = self.replicator_rpc.dispatch(post_args, args) ret.request = req - self.logger.timing_since('REPLICATE.timing', start_time) return ret @public + @timing_stats def POST(self, req): """Handle HTTP POST request.""" - start_time = time.time() try: drive, part, account = split_path(unquote(req.path), 3) validate_device_partition(drive, part) except ValueError, err: - self.logger.increment('POST.errors') return HTTPBadRequest(body=str(err), content_type='text/plain', request=req) if 'x-timestamp' not in req.headers or \ not check_float(req.headers['x-timestamp']): - self.logger.increment('POST.errors') return HTTPBadRequest(body='Missing or bad timestamp', request=req, content_type='text/plain') if self.mount_check and not check_mount(self.root, drive): - self.logger.increment('POST.errors') return HTTPInsufficientStorage(drive=drive, request=req) broker = self._get_account_broker(drive, part, account) if broker.is_deleted(): - self.logger.timing_since('POST.timing', start_time) return HTTPNotFound(request=req) timestamp = normalize_timestamp(req.headers['x-timestamp']) metadata = {} @@ -369,7 +335,6 @@ class AccountController(object): if key.lower().startswith('x-account-meta-')) if metadata: broker.update_metadata(metadata) - self.logger.timing_since('POST.timing', start_time) return HTTPNoContent(request=req) def __call__(self, env, start_response): diff --git a/swift/common/utils.py b/swift/common/utils.py index 20ef54a279..ec8f302b06 100644 --- a/swift/common/utils.py +++ b/swift/common/utils.py @@ -52,6 +52,7 @@ utf8_decoder = codecs.getdecoder('utf-8') utf8_encoder = codecs.getencoder('utf-8') from swift.common.exceptions import LockTimeout, MessageTimeout +from swift.common.http import is_success, is_redirection, HTTP_NOT_FOUND # logging doesn't import patched as cleanly as one would like from logging.handlers import SysLogHandler @@ -463,6 +464,27 @@ class StatsdClient(object): sample_rate) +def timing_stats(func): + """ + Decorator that logs timing events or errors for public methods in swift's + wsgi server controllers, based on response code. + """ + method = func.func_name + + @functools.wraps(func) + def _timing_stats(ctrl, *args, **kwargs): + start_time = time.time() + resp = func(ctrl, *args, **kwargs) + if is_success(resp.status_int) or is_redirection(resp.status_int) or \ + resp.status_int == HTTP_NOT_FOUND: + ctrl.logger.timing_since(method + '.timing', start_time) + else: + ctrl.logger.timing_since(method + '.errors.timing', start_time) + return resp + + return _timing_stats + + # double inheritance to support property with setter class LogAdapter(logging.LoggerAdapter, object): """ diff --git a/swift/container/server.py b/swift/container/server.py index 984692245f..3e4b520058 100644 --- a/swift/container/server.py +++ b/swift/container/server.py @@ -28,7 +28,7 @@ import swift.common.db from swift.common.db import ContainerBroker from swift.common.utils import get_logger, get_param, hash_path, public, \ normalize_timestamp, storage_directory, split_path, validate_sync_to, \ - config_true_value, validate_device_partition, json + config_true_value, validate_device_partition, json, timing_stats from swift.common.constraints import CONTAINER_LISTING_LIMIT, \ check_mount, check_float, check_utf8, FORMAT2CONTENT_TYPE from swift.common.bufferedhttp import http_connect @@ -141,24 +141,21 @@ class ContainerController(object): return None @public + @timing_stats def DELETE(self, req): """Handle HTTP DELETE request.""" - start_time = time.time() try: drive, part, account, container, obj = split_path( unquote(req.path), 4, 5, True) validate_device_partition(drive, part) except ValueError, err: - self.logger.increment('DELETE.errors') return HTTPBadRequest(body=str(err), content_type='text/plain', request=req) if 'x-timestamp' not in req.headers or \ not check_float(req.headers['x-timestamp']): - self.logger.increment('DELETE.errors') return HTTPBadRequest(body='Missing timestamp', request=req, content_type='text/plain') if self.mount_check and not check_mount(self.root, drive): - self.logger.increment('DELETE.errors') return HTTPInsufficientStorage(drive=drive, request=req) broker = self._get_container_broker(drive, part, account, container) if account.startswith(self.auto_create_account_prefix) and obj and \ @@ -166,25 +163,20 @@ class ContainerController(object): broker.initialize(normalize_timestamp( req.headers.get('x-timestamp') or time.time())) if not os.path.exists(broker.db_file): - self.logger.timing_since('DELETE.timing', start_time) return HTTPNotFound() if obj: # delete object broker.delete_object(obj, req.headers.get('x-timestamp')) - self.logger.timing_since('DELETE.timing', start_time) return HTTPNoContent(request=req) else: # delete container if not broker.empty(): - self.logger.increment('DELETE.errors') return HTTPConflict(request=req) existed = float(broker.get_info()['put_timestamp']) and \ not broker.is_deleted() broker.delete_db(req.headers['X-Timestamp']) if not broker.is_deleted(): - self.logger.increment('DELETE.errors') return HTTPConflict(request=req) resp = self.account_update(req, account, container, broker) - self.logger.timing_since('DELETE.timing', start_time) if resp: return resp if existed: @@ -192,30 +184,26 @@ class ContainerController(object): return HTTPNotFound() @public + @timing_stats def PUT(self, req): """Handle HTTP PUT request.""" - start_time = time.time() try: drive, part, account, container, obj = split_path( unquote(req.path), 4, 5, True) validate_device_partition(drive, part) except ValueError, err: - self.logger.increment('PUT.errors') return HTTPBadRequest(body=str(err), content_type='text/plain', request=req) if 'x-timestamp' not in req.headers or \ not check_float(req.headers['x-timestamp']): - self.logger.increment('PUT.errors') return HTTPBadRequest(body='Missing timestamp', request=req, content_type='text/plain') if 'x-container-sync-to' in req.headers: err = validate_sync_to(req.headers['x-container-sync-to'], self.allowed_sync_hosts) if err: - self.logger.increment('PUT.errors') return HTTPBadRequest(err) if self.mount_check and not check_mount(self.root, drive): - self.logger.increment('PUT.errors') return HTTPInsufficientStorage(drive=drive, request=req) timestamp = normalize_timestamp(req.headers['x-timestamp']) broker = self._get_container_broker(drive, part, account, container) @@ -224,12 +212,10 @@ class ContainerController(object): not os.path.exists(broker.db_file): broker.initialize(timestamp) if not os.path.exists(broker.db_file): - self.logger.timing_since('PUT.timing', start_time) return HTTPNotFound() broker.put_object(obj, timestamp, int(req.headers['x-size']), req.headers['x-content-type'], req.headers['x-etag']) - self.logger.timing_since('PUT.timing', start_time) return HTTPCreated(request=req) else: # put container if not os.path.exists(broker.db_file): @@ -239,7 +225,6 @@ class ContainerController(object): created = broker.is_deleted() broker.update_put_timestamp(timestamp) if broker.is_deleted(): - self.logger.increment('PUT.errors') return HTTPConflict(request=req) metadata = {} metadata.update( @@ -255,7 +240,6 @@ class ContainerController(object): broker.set_x_container_sync_points(-1, -1) broker.update_metadata(metadata) resp = self.account_update(req, account, container, broker) - self.logger.timing_since('PUT.timing', start_time) if resp: return resp if created: @@ -264,25 +248,22 @@ class ContainerController(object): return HTTPAccepted(request=req) @public + @timing_stats def HEAD(self, req): """Handle HTTP HEAD request.""" - start_time = time.time() try: drive, part, account, container, obj = split_path( unquote(req.path), 4, 5, True) validate_device_partition(drive, part) except ValueError, err: - self.logger.increment('HEAD.errors') return HTTPBadRequest(body=str(err), content_type='text/plain', request=req) if self.mount_check and not check_mount(self.root, drive): - self.logger.increment('HEAD.errors') return HTTPInsufficientStorage(drive=drive, request=req) broker = self._get_container_broker(drive, part, account, container) broker.pending_timeout = 0.1 broker.stale_reads_ok = True if broker.is_deleted(): - self.logger.timing_since('HEAD.timing', start_time) return HTTPNotFound(request=req) info = broker.get_info() headers = { @@ -305,32 +286,27 @@ class ContainerController(object): 'text/xml'], default_match='text/plain') except AssertionError, err: - self.logger.increment('HEAD.errors') return HTTPBadRequest(body='bad accept header: %s' % req.accept, content_type='text/plain', request=req) - self.logger.timing_since('HEAD.timing', start_time) return HTTPNoContent(request=req, headers=headers, charset='utf-8') @public + @timing_stats def GET(self, req): """Handle HTTP GET request.""" - start_time = time.time() try: drive, part, account, container, obj = split_path( unquote(req.path), 4, 5, True) validate_device_partition(drive, part) except ValueError, err: - self.logger.increment('GET.errors') return HTTPBadRequest(body=str(err), content_type='text/plain', request=req) if self.mount_check and not check_mount(self.root, drive): - self.logger.increment('GET.errors') return HTTPInsufficientStorage(drive=drive, request=req) broker = self._get_container_broker(drive, part, account, container) broker.pending_timeout = 0.1 broker.stale_reads_ok = True if broker.is_deleted(): - self.logger.timing_since('GET.timing', start_time) return HTTPNotFound(request=req) info = broker.get_info() resp_headers = { @@ -363,7 +339,6 @@ class ContainerController(object): body='Maximum limit is %d' % CONTAINER_LISTING_LIMIT) query_format = get_param(req, 'format') except UnicodeDecodeError, err: - self.logger.increment('GET.errors') return HTTPBadRequest(body='parameters not utf8', content_type='text/plain', request=req) if query_format: @@ -375,7 +350,6 @@ class ContainerController(object): 'text/xml'], default_match='text/plain') except AssertionError, err: - self.logger.increment('GET.errors') return HTTPBadRequest(body='bad accept header: %s' % req.accept, content_type='text/plain', request=req) container_list = broker.list_objects_iter(limit, marker, end_marker, @@ -421,70 +395,59 @@ class ContainerController(object): ''.join(xml_output), '']) else: if not container_list: - self.logger.timing_since('GET.timing', start_time) return HTTPNoContent(request=req, headers=resp_headers) container_list = '\n'.join(r[0] for r in container_list) + '\n' ret = Response(body=container_list, request=req, headers=resp_headers) ret.content_type = out_content_type ret.charset = 'utf-8' - self.logger.timing_since('GET.timing', start_time) return ret @public + @timing_stats def REPLICATE(self, req): """ Handle HTTP REPLICATE request (json-encoded RPC calls for replication.) """ - start_time = time.time() try: post_args = split_path(unquote(req.path), 3) drive, partition, hash = post_args validate_device_partition(drive, partition) except ValueError, err: - self.logger.increment('REPLICATE.errors') return HTTPBadRequest(body=str(err), content_type='text/plain', request=req) if self.mount_check and not check_mount(self.root, drive): - self.logger.increment('REPLICATE.errors') return HTTPInsufficientStorage(drive=drive, request=req) try: args = json.load(req.environ['wsgi.input']) except ValueError, err: - self.logger.increment('REPLICATE.errors') return HTTPBadRequest(body=str(err), content_type='text/plain') ret = self.replicator_rpc.dispatch(post_args, args) ret.request = req - self.logger.timing_since('REPLICATE.timing', start_time) return ret @public + @timing_stats def POST(self, req): """Handle HTTP POST request.""" - start_time = time.time() try: drive, part, account, container = split_path(unquote(req.path), 4) validate_device_partition(drive, part) except ValueError, err: - self.logger.increment('POST.errors') return HTTPBadRequest(body=str(err), content_type='text/plain', request=req) if 'x-timestamp' not in req.headers or \ not check_float(req.headers['x-timestamp']): - self.logger.increment('POST.errors') return HTTPBadRequest(body='Missing or bad timestamp', request=req, content_type='text/plain') if 'x-container-sync-to' in req.headers: err = validate_sync_to(req.headers['x-container-sync-to'], self.allowed_sync_hosts) if err: - self.logger.increment('POST.errors') return HTTPBadRequest(err) if self.mount_check and not check_mount(self.root, drive): - self.logger.increment('POST.errors') return HTTPInsufficientStorage(drive=drive, request=req) broker = self._get_container_broker(drive, part, account, container) if broker.is_deleted(): - self.logger.timing_since('POST.timing', start_time) return HTTPNotFound(request=req) timestamp = normalize_timestamp(req.headers['x-timestamp']) metadata = {} @@ -499,7 +462,6 @@ class ContainerController(object): broker.metadata['X-Container-Sync-To'][0]: broker.set_x_container_sync_points(-1, -1) broker.update_metadata(metadata) - self.logger.timing_since('POST.timing', start_time) return HTTPNoContent(request=req) def __call__(self, env, start_response): diff --git a/swift/obj/server.py b/swift/obj/server.py index 4c5e85b68a..ec84c2da23 100755 --- a/swift/obj/server.py +++ b/swift/obj/server.py @@ -33,7 +33,7 @@ from eventlet import sleep, Timeout, tpool from swift.common.utils import mkdirs, normalize_timestamp, public, \ storage_directory, hash_path, renamer, fallocate, fsync, \ split_path, drop_buffer_cache, get_logger, write_pickle, \ - config_true_value, validate_device_partition + config_true_value, validate_device_partition, timing_stats from swift.common.bufferedhttp import http_connect from swift.common.constraints import check_object_creation, check_mount, \ check_float, check_utf8 @@ -511,36 +511,31 @@ class ObjectController(object): host, partition, contdevice, headers_out, objdevice) @public + @timing_stats def POST(self, request): """Handle HTTP POST requests for the Swift Object Server.""" - start_time = time.time() try: device, partition, account, container, obj = \ split_path(unquote(request.path), 5, 5, True) validate_device_partition(device, partition) except ValueError, err: - self.logger.increment('POST.errors') return HTTPBadRequest(body=str(err), request=request, content_type='text/plain') if 'x-timestamp' not in request.headers or \ not check_float(request.headers['x-timestamp']): - self.logger.increment('POST.errors') return HTTPBadRequest(body='Missing timestamp', request=request, content_type='text/plain') new_delete_at = int(request.headers.get('X-Delete-At') or 0) if new_delete_at and new_delete_at < time.time(): - self.logger.increment('POST.errors') return HTTPBadRequest(body='X-Delete-At in past', request=request, content_type='text/plain') if self.mount_check and not check_mount(self.devices, device): - self.logger.increment('POST.errors') return HTTPInsufficientStorage(drive=device, request=request) file = DiskFile(self.devices, device, partition, account, container, obj, self.logger, disk_chunk_size=self.disk_chunk_size) if 'X-Delete-At' in file.metadata and \ int(file.metadata['X-Delete-At']) <= time.time(): - self.logger.timing_since('POST.timing', start_time) return HTTPNotFound(request=request) if file.is_deleted(): response_class = HTTPNotFound @@ -568,36 +563,30 @@ class ObjectController(object): container, obj, request.headers, device) with file.mkstemp() as (fd, tmppath): file.put(fd, tmppath, metadata, extension='.meta') - self.logger.timing_since('POST.timing', start_time) return response_class(request=request) @public + @timing_stats def PUT(self, request): """Handle HTTP PUT requests for the Swift Object Server.""" - start_time = time.time() try: device, partition, account, container, obj = \ split_path(unquote(request.path), 5, 5, True) validate_device_partition(device, partition) except ValueError, err: - self.logger.increment('PUT.errors') return HTTPBadRequest(body=str(err), request=request, content_type='text/plain') if self.mount_check and not check_mount(self.devices, device): - self.logger.increment('PUT.errors') return HTTPInsufficientStorage(drive=device, request=request) if 'x-timestamp' not in request.headers or \ not check_float(request.headers['x-timestamp']): - self.logger.increment('PUT.errors') return HTTPBadRequest(body='Missing timestamp', request=request, content_type='text/plain') error_response = check_object_creation(request, obj) if error_response: - self.logger.increment('PUT.errors') return error_response new_delete_at = int(request.headers.get('X-Delete-At') or 0) if new_delete_at and new_delete_at < time.time(): - self.logger.increment('PUT.errors') return HTTPBadRequest(body='X-Delete-At in past', request=request, content_type='text/plain') file = DiskFile(self.devices, device, partition, account, container, @@ -674,23 +663,20 @@ class ObjectController(object): 'x-trans-id': request.headers.get('x-trans-id', '-')}, device) resp = HTTPCreated(request=request, etag=etag) - self.logger.timing_since('PUT.timing', start_time) return resp @public + @timing_stats def GET(self, request): """Handle HTTP GET requests for the Swift Object Server.""" - start_time = time.time() try: device, partition, account, container, obj = \ split_path(unquote(request.path), 5, 5, True) validate_device_partition(device, partition) except ValueError, err: - self.logger.increment('GET.errors') return HTTPBadRequest(body=str(err), request=request, content_type='text/plain') if self.mount_check and not check_mount(self.devices, device): - self.logger.increment('GET.errors') return HTTPInsufficientStorage(drive=device, request=request) file = DiskFile(self.devices, device, partition, account, container, obj, self.logger, keep_data_fp=True, @@ -700,54 +686,45 @@ class ObjectController(object): ('X-Delete-At' in file.metadata and int(file.metadata['X-Delete-At']) <= time.time()): if request.headers.get('if-match') == '*': - self.logger.timing_since('GET.timing', start_time) return HTTPPreconditionFailed(request=request) else: - self.logger.timing_since('GET.timing', start_time) return HTTPNotFound(request=request) try: file_size = file.get_data_file_size() except (DiskFileError, DiskFileNotExist): file.quarantine() - self.logger.timing_since('GET.timing', start_time) return HTTPNotFound(request=request) if request.headers.get('if-match') not in (None, '*') and \ file.metadata['ETag'] not in request.if_match: file.close() - self.logger.timing_since('GET.timing', start_time) return HTTPPreconditionFailed(request=request) if request.headers.get('if-none-match') is not None: if file.metadata['ETag'] in request.if_none_match: resp = HTTPNotModified(request=request) resp.etag = file.metadata['ETag'] file.close() - self.logger.timing_since('GET.timing', start_time) return resp try: if_unmodified_since = request.if_unmodified_since except (OverflowError, ValueError): # catches timestamps before the epoch - self.logger.increment('GET.errors') return HTTPPreconditionFailed(request=request) if if_unmodified_since and \ datetime.fromtimestamp( float(file.metadata['X-Timestamp']), UTC) > \ if_unmodified_since: file.close() - self.logger.timing_since('GET.timing', start_time) return HTTPPreconditionFailed(request=request) try: if_modified_since = request.if_modified_since except (OverflowError, ValueError): # catches timestamps before the epoch - self.logger.increment('GET.errors') return HTTPPreconditionFailed(request=request) if if_modified_since and \ datetime.fromtimestamp( float(file.metadata['X-Timestamp']), UTC) < \ if_modified_since: file.close() - self.logger.timing_since('GET.timing', start_time) return HTTPNotModified(request=request) response = Response(app_iter=file, request=request, conditional_response=True) @@ -768,38 +745,33 @@ class ObjectController(object): if 'Content-Encoding' in file.metadata: response.content_encoding = file.metadata['Content-Encoding'] response.headers['X-Timestamp'] = file.metadata['X-Timestamp'] - self.logger.timing_since('GET.timing', start_time) return request.get_response(response) @public + @timing_stats def HEAD(self, request): """Handle HTTP HEAD requests for the Swift Object Server.""" - start_time = time.time() try: device, partition, account, container, obj = \ split_path(unquote(request.path), 5, 5, True) validate_device_partition(device, partition) except ValueError, err: - self.logger.increment('HEAD.errors') resp = HTTPBadRequest(request=request) resp.content_type = 'text/plain' resp.body = str(err) return resp if self.mount_check and not check_mount(self.devices, device): - self.logger.increment('HEAD.errors') return HTTPInsufficientStorage(drive=device, request=request) file = DiskFile(self.devices, device, partition, account, container, obj, self.logger, disk_chunk_size=self.disk_chunk_size) if file.is_deleted() or \ ('X-Delete-At' in file.metadata and int(file.metadata['X-Delete-At']) <= time.time()): - self.logger.timing_since('HEAD.timing', start_time) return HTTPNotFound(request=request) try: file_size = file.get_data_file_size() except (DiskFileError, DiskFileNotExist): file.quarantine() - self.logger.timing_since('HEAD.timing', start_time) return HTTPNotFound(request=request) response = Response(request=request, conditional_response=True) response.headers['Content-Type'] = file.metadata.get( @@ -815,28 +787,24 @@ class ObjectController(object): response.content_length = file_size if 'Content-Encoding' in file.metadata: response.content_encoding = file.metadata['Content-Encoding'] - self.logger.timing_since('HEAD.timing', start_time) return response @public + @timing_stats def DELETE(self, request): """Handle HTTP DELETE requests for the Swift Object Server.""" - start_time = time.time() try: device, partition, account, container, obj = \ split_path(unquote(request.path), 5, 5, True) validate_device_partition(device, partition) except ValueError, e: - self.logger.increment('DELETE.errors') return HTTPBadRequest(body=str(e), request=request, content_type='text/plain') if 'x-timestamp' not in request.headers or \ not check_float(request.headers['x-timestamp']): - self.logger.increment('DELETE.errors') return HTTPBadRequest(body='Missing timestamp', request=request, content_type='text/plain') if self.mount_check and not check_mount(self.devices, device): - self.logger.increment('DELETE.errors') return HTTPInsufficientStorage(drive=device, request=request) response_class = HTTPNoContent file = DiskFile(self.devices, device, partition, account, container, @@ -844,7 +812,6 @@ class ObjectController(object): if 'x-if-delete-at' in request.headers and \ int(request.headers['x-if-delete-at']) != \ int(file.metadata.get('X-Delete-At') or 0): - self.logger.timing_since('DELETE.timing', start_time) return HTTPPreconditionFailed( request=request, body='X-If-Delete-At and X-Delete-At do not match') @@ -869,33 +836,29 @@ class ObjectController(object): 'x-trans-id': request.headers.get('x-trans-id', '-')}, device) resp = response_class(request=request) - self.logger.timing_since('DELETE.timing', start_time) return resp @public + @timing_stats def REPLICATE(self, request): """ Handle REPLICATE requests for the Swift Object Server. This is used by the object replicator to get hashes for directories. """ - start_time = time.time() try: device, partition, suffix = split_path( unquote(request.path), 2, 3, True) validate_device_partition(device, partition) except ValueError, e: - self.logger.increment('REPLICATE.errors') return HTTPBadRequest(body=str(e), request=request, content_type='text/plain') if self.mount_check and not check_mount(self.devices, device): - self.logger.increment('REPLICATE.errors') return HTTPInsufficientStorage(drive=device, request=request) path = os.path.join(self.devices, device, DATADIR, partition) if not os.path.exists(path): mkdirs(path) suffixes = suffix.split('-') if suffix else [] _junk, hashes = tpool_reraise(get_hashes, path, recalculate=suffixes) - self.logger.timing_since('REPLICATE.timing', start_time) return Response(body=pickle.dumps(hashes)) def __call__(self, env, start_response): diff --git a/test/unit/common/test_utils.py b/test/unit/common/test_utils.py index be4bb91d80..db5422f3b4 100644 --- a/test/unit/common/test_utils.py +++ b/test/unit/common/test_utils.py @@ -40,6 +40,7 @@ from eventlet import sleep from swift.common.exceptions import (Timeout, MessageTimeout, ConnectionTimeout) from swift.common import utils +from swift.common.swob import Response class MockOs(): @@ -994,6 +995,43 @@ class TestStatsdLogging(unittest.TestCase): payload = mock_socket.sent[0][0] self.assertTrue(payload.endswith("|@0.5")) + def test_timing_stats(self): + class MockController(object): + def __init__(self, status): + self.status = status + self.logger = self + self.args = () + self.called = 'UNKNOWN' + + def timing_since(self, *args): + self.called = 'timing' + self.args = args + + @utils.timing_stats + def METHOD(controller): + return Response(status=controller.status) + + mock_controller = MockController(200) + METHOD(mock_controller) + self.assertEquals(mock_controller.called, 'timing') + self.assertEquals(len(mock_controller.args), 2) + self.assertEquals(mock_controller.args[0], 'METHOD.timing') + self.assert_(mock_controller.args[1] > 0) + + mock_controller = MockController(404) + METHOD(mock_controller) + self.assertEquals(len(mock_controller.args), 2) + self.assertEquals(mock_controller.called, 'timing') + self.assertEquals(mock_controller.args[0], 'METHOD.timing') + self.assert_(mock_controller.args[1] > 0) + + mock_controller = MockController(401) + METHOD(mock_controller) + self.assertEquals(len(mock_controller.args), 2) + self.assertEquals(mock_controller.called, 'timing') + self.assertEquals(mock_controller.args[0], 'METHOD.errors.timing') + self.assert_(mock_controller.args[1] > 0) + class TestStatsdLoggingDelegation(unittest.TestCase): def setUp(self):