def iter_response(iterable):
iterator = iter(iterable)
try:
chunk = next(iterator)
while not chunk:
chunk = next(iterator)
except StopIteration:
chunk = b''
for h, v in start_response_args[0][1]:
if h.lower() in ('content-length', 'transfer-encoding'):
break
else:
if not chunk:
start_response_args[0][1].append(('Content-Length', '0'))
elif isinstance(iterable, list):
start_response_args[0][1].append(
('Content-Length', str(sum(len(i) for i in iterable))))
resp_headers = dict(start_response_args[0][1])
start_response(*start_response_args[0])
req = Request(env)
# Log timing information for time-to-first-byte (GET requests only)
method = self.method_from_req(req)
if method == 'GET':
status_int = status_int_for_logging()
policy_index = get_policy_index(req.headers, resp_headers)
metric_name = self.statsd_metric_name(req, status_int, method)
metric_name_policy = self.statsd_metric_name_policy(
req, status_int, method, policy_index)
if metric_name:
self.access_logger.timing_since(
metric_name + '.first-byte.timing', start_time)
if metric_name_policy:
self.access_logger.timing_since(
metric_name_policy + '.first-byte.timing', start_time)
bytes_sent = 0
client_disconnect = False
try:
while chunk:
bytes_sent += len(chunk)
yield chunk
chunk = next(iterator)
except StopIteration: # iterator was depleted
return
except GeneratorExit: # generator was closed before we finished
client_disconnect = True
raise
finally:
status_int = status_int_for_logging(client_disconnect)
self.log_request(req,
status_int,
input_proxy.bytes_received,
bytes_sent,
start_time,
time.time(),
resp_headers=resp_headers)
close_method = getattr(iterable, 'close', None)
if callable(close_method):
close_method()
def iter_response(iterable):
iterator = iter(iterable)
try:
chunk = next(iterator)
while not chunk:
chunk = next(iterator)
except StopIteration:
chunk = ''
for h, v in start_response_args[0][1]:
if h.lower() in ('content-length', 'transfer-encoding'):
break
else:
if not chunk:
start_response_args[0][1].append(('Content-Length', '0'))
elif isinstance(iterable, list):
start_response_args[0][1].append(
('Content-Length', str(sum(len(i) for i in iterable))))
resp_headers = dict(start_response_args[0][1])
start_response(*start_response_args[0])
req = Request(env)
# Log timing information for time-to-first-byte (GET requests only)
method = self.method_from_req(req)
if method == 'GET':
status_int = status_int_for_logging()
policy_index = get_policy_index(req.headers, resp_headers)
metric_name = self.statsd_metric_name(req, status_int, method)
metric_name_policy = self.statsd_metric_name_policy(
req, status_int, method, policy_index)
if metric_name:
self.access_logger.timing_since(
metric_name + '.first-byte.timing', start_time)
if metric_name_policy:
self.access_logger.timing_since(
metric_name_policy + '.first-byte.timing', start_time)
bytes_sent = 0
client_disconnect = False
try:
while chunk:
bytes_sent += len(chunk)
yield chunk
chunk = next(iterator)
except StopIteration: # iterator was depleted
return
except GeneratorExit: # generator was closed before we finished
client_disconnect = True
raise
finally:
status_int = status_int_for_logging(client_disconnect)
self.log_request(
req, status_int, input_proxy.bytes_received, bytes_sent,
start_time, time.time(), resp_headers=resp_headers)
close_method = getattr(iterable, 'close', None)
if callable(close_method):
close_method()
def log_request(self, req, status_int, bytes_received, bytes_sent,
start_time, end_time, resp_headers=None):
"""
Log a request.
:param req: swob.Request object for the request
: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 start_time: timestamp request started
:param end_time: timestamp request completed
:param resp_headers: dict of the response headers
"""
resp_headers = resp_headers or {}
req_path = get_valid_utf8_str(req.path)
the_request = quote(unquote(req_path), QUOTE_SAFE)
if req.query_string:
the_request = the_request + '?' + req.query_string
logged_headers = None
if self.log_hdrs:
if self.log_hdrs_only:
logged_headers = '\n'.join('%s: %s' % (k, v)
for k, v in req.headers.items()
if k in self.log_hdrs_only)
else:
logged_headers = '\n'.join('%s: %s' % (k, v)
for k, v in req.headers.items())
method = self.method_from_req(req)
end_gmtime_str = time.strftime('%d/%b/%Y/%H/%M/%S',
time.gmtime(end_time))
duration_time_str = "%.4f" % (end_time - start_time)
start_time_str = "%.9f" % start_time
end_time_str = "%.9f" % end_time
policy_index = get_policy_index(req.headers, resp_headers)
self.access_logger.info(' '.join(
quote(str(x) if x else '-', QUOTE_SAFE)
for x in (
get_remote_client(req),
req.remote_addr,
end_gmtime_str,
method,
the_request,
req.environ.get('SERVER_PROTOCOL'),
status_int,
req.referer,
req.user_agent,
self.obscure_sensitive(req.headers.get('x-auth-token')),
bytes_received,
bytes_sent,
req.headers.get('etag', None),
req.environ.get('swift.trans_id'),
logged_headers,
duration_time_str,
req.environ.get('swift.source'),
','.join(req.environ.get('swift.log_info') or ''),
start_time_str,
end_time_str,
policy_index
)))
# Log timing and bytes-transferred data to StatsD
metric_name = self.statsd_metric_name(req, status_int, method)
# Only log data for valid controllers (or SOS) to keep the metric count
# down (egregious errors will get logged by the proxy server itself).
if metric_name:
self.access_logger.timing(metric_name + '.timing',
(end_time - start_time) * 1000)
self.access_logger.update_stats(metric_name + '.xfer',
bytes_received + bytes_sent)
def log_request(self,
req,
status_int,
bytes_received,
bytes_sent,
start_time,
end_time,
resp_headers=None):
"""
Log a request.
:param req: swob.Request object for the request
: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 start_time: timestamp request started
:param end_time: timestamp request completed
:param resp_headers: dict of the response headers
"""
resp_headers = resp_headers or {}
logged_headers = None
if self.log_hdrs:
if self.log_hdrs_only:
logged_headers = '\n'.join('%s: %s' % (k, v)
for k, v in req.headers.items()
if k in self.log_hdrs_only)
else:
logged_headers = '\n'.join('%s: %s' % (k, v)
for k, v in req.headers.items())
method = self.method_from_req(req)
end_gmtime_str = time.strftime('%d/%b/%Y/%H/%M/%S',
time.gmtime(end_time))
duration_time_str = "%.4f" % (end_time - start_time)
start_time_str = "%.9f" % start_time
end_time_str = "%.9f" % end_time
policy_index = get_policy_index(req.headers, resp_headers)
self.access_logger.info(' '.join(
quote(str(x) if x else '-', QUOTE_SAFE)
for x in (get_remote_client(req), req.remote_addr, end_gmtime_str,
method, req.path_qs, req.environ.get('SERVER_PROTOCOL'),
status_int, req.referer, req.user_agent,
self.obscure_sensitive(req.headers.get('x-auth-token')),
bytes_received, bytes_sent,
req.headers.get('etag', None),
req.environ.get('swift.trans_id'), logged_headers,
duration_time_str, req.environ.get('swift.source'),
','.join(req.environ.get('swift.log_info') or ''),
start_time_str, end_time_str, policy_index)))
# Log timing and bytes-transferred data to StatsD
metric_name = self.statsd_metric_name(req, status_int, method)
metric_name_policy = self.statsd_metric_name_policy(
req, status_int, method, policy_index)
# Only log data for valid controllers (or SOS) to keep the metric count
# down (egregious errors will get logged by the proxy server itself).
if metric_name:
self.access_logger.timing(metric_name + '.timing',
(end_time - start_time) * 1000)
self.access_logger.update_stats(metric_name + '.xfer',
bytes_received + bytes_sent)
if metric_name_policy:
self.access_logger.timing(metric_name_policy + '.timing',
(end_time - start_time) * 1000)
self.access_logger.update_stats(metric_name_policy + '.xfer',
bytes_received + bytes_sent)
def iter_response(iterable):
iterator = reiterate(iterable)
content_length = None
for h, v in start_response_args[0][1]:
if h.lower() == 'content-length':
content_length = int(v)
break
elif h.lower() == 'transfer-encoding':
break
else:
if isinstance(iterator, list):
content_length = sum(len(i) for i in iterator)
start_response_args[0][1].append(
('Content-Length', str(content_length)))
req = Request(env)
method = self.method_from_req(req)
if method == 'HEAD':
content_length = 0
if content_length is not None:
iterator = enforce_byte_count(iterator, content_length)
wire_status_int = int(start_response_args[0][0].split(' ', 1)[0])
resp_headers = dict(start_response_args[0][1])
start_response(*start_response_args[0])
# Log timing information for time-to-first-byte (GET requests only)
ttfb = 0.0
if method == 'GET':
policy_index = get_policy_index(req.headers, resp_headers)
metric_name = self.statsd_metric_name(req, wire_status_int,
method)
metric_name_policy = self.statsd_metric_name_policy(
req, wire_status_int, method, policy_index)
ttfb = time.time() - start_time
if metric_name:
self.access_logger.timing(
metric_name + '.first-byte.timing', ttfb * 1000)
if metric_name_policy:
self.access_logger.timing(
metric_name_policy + '.first-byte.timing', ttfb * 1000)
bytes_sent = 0
client_disconnect = False
start_status = wire_status_int
try:
for chunk in iterator:
bytes_sent += len(chunk)
yield chunk
except StopIteration: # iterator was depleted
return
except GeneratorExit: # generator was closed before we finished
client_disconnect = True
raise
except Exception:
start_status = 500
raise
finally:
status_int = status_int_for_logging(start_status,
client_disconnect)
self.log_request(req,
status_int,
input_proxy.bytes_received,
bytes_sent,
start_time,
time.time(),
resp_headers=resp_headers,
ttfb=ttfb,
wire_status_int=wire_status_int)
iterator.close()
def log_request(self,
req,
status_int,
bytes_received,
bytes_sent,
start_time,
end_time,
resp_headers=None,
ttfb=0,
wire_status_int=None):
"""
Log a request.
:param req: swob.Request object for the request
: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 start_time: timestamp request started
:param end_time: timestamp request completed
:param resp_headers: dict of the response headers
:param wire_status_int: the on the wire status int
"""
resp_headers = resp_headers or {}
logged_headers = None
if self.log_hdrs:
if self.log_hdrs_only:
logged_headers = '\n'.join('%s: %s' % (k, v)
for k, v in req.headers.items()
if k in self.log_hdrs_only)
else:
logged_headers = '\n'.join('%s: %s' % (k, v)
for k, v in req.headers.items())
method = self.method_from_req(req)
duration_time_str = "%.4f" % (end_time - start_time)
policy_index = get_policy_index(req.headers, resp_headers)
acc, cont, obj = None, None, None
swift_path = req.environ.get('swift.backend_path', req.path)
if swift_path.startswith('/v1/'):
_, acc, cont, obj = split_path(swift_path, 1, 4, True)
replacements = {
# Time information
'end_time':
StrFormatTime(end_time),
'start_time':
StrFormatTime(start_time),
# Information worth to anonymize
'client_ip':
StrAnonymizer(get_remote_client(req), self.anonymization_method,
self.anonymization_salt),
'remote_addr':
StrAnonymizer(req.remote_addr, self.anonymization_method,
self.anonymization_salt),
'path':
StrAnonymizer(req.path_qs, self.anonymization_method,
self.anonymization_salt),
'referer':
StrAnonymizer(req.referer, self.anonymization_method,
self.anonymization_salt),
'user_agent':
StrAnonymizer(req.user_agent, self.anonymization_method,
self.anonymization_salt),
'headers':
StrAnonymizer(logged_headers, self.anonymization_method,
self.anonymization_salt),
'client_etag':
StrAnonymizer(req.headers.get('etag'), self.anonymization_method,
self.anonymization_salt),
'account':
StrAnonymizer(acc, self.anonymization_method,
self.anonymization_salt),
'container':
StrAnonymizer(cont, self.anonymization_method,
self.anonymization_salt),
'object':
StrAnonymizer(obj, self.anonymization_method,
self.anonymization_salt),
# Others information
'method':
method,
'protocol':
req.environ.get('SERVER_PROTOCOL'),
'status_int':
status_int,
'auth_token':
self.obscure_sensitive(req.headers.get('x-auth-token')),
'bytes_recvd':
bytes_received,
'bytes_sent':
bytes_sent,
'transaction_id':
req.environ.get('swift.trans_id'),
'request_time':
duration_time_str,
'source':
req.environ.get('swift.source'),
'log_info':
','.join(req.environ.get('swift.log_info', '')),
'policy_index':
policy_index,
'ttfb':
ttfb,
'pid':
self.pid,
'wire_status_int':
wire_status_int or status_int,
}
self.access_logger.info(
self.log_formatter.format(self.log_msg_template, **replacements))
# Log timing and bytes-transferred data to StatsD
metric_name = self.statsd_metric_name(req, status_int, method)
metric_name_policy = self.statsd_metric_name_policy(
req, status_int, method, policy_index)
# Only log data for valid controllers (or SOS) to keep the metric count
# down (egregious errors will get logged by the proxy server itself).
if metric_name:
self.access_logger.timing(metric_name + '.timing',
(end_time - start_time) * 1000)
self.access_logger.update_stats(metric_name + '.xfer',
bytes_received + bytes_sent)
if metric_name_policy:
self.access_logger.timing(metric_name_policy + '.timing',
(end_time - start_time) * 1000)
self.access_logger.update_stats(metric_name_policy + '.xfer',
bytes_received + bytes_sent)
def log_request(self, req, status_int, bytes_received, bytes_sent,
start_time, end_time, resp_headers=None):
"""
Log a request.
:param req: swob.Request object for the request
: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 start_time: timestamp request started
:param end_time: timestamp request completed
:param resp_headers: dict of the response headers
"""
resp_headers = resp_headers or {}
logged_headers = None
if self.log_hdrs:
if self.log_hdrs_only:
logged_headers = '\n'.join('%s: %s' % (k, v)
for k, v in req.headers.items()
if k in self.log_hdrs_only)
else:
logged_headers = '\n'.join('%s: %s' % (k, v)
for k, v in req.headers.items())
method = self.method_from_req(req)
duration_time_str = "%.4f" % (end_time - start_time)
policy_index = get_policy_index(req.headers, resp_headers)
acc, cont, obj = None, None, None
if req.path.startswith('/v1/'):
_, acc, cont, obj = split_path(req.path, 1, 4, True)
replacements = {
# Time information
'end_time': StrFormatTime(end_time),
'start_time': StrFormatTime(start_time),
# Information worth to anonymize
'client_ip': StrAnonymizer(get_remote_client(req),
self.anonymization_method,
self.anonymization_salt),
'remote_addr': StrAnonymizer(req.remote_addr,
self.anonymization_method,
self.anonymization_salt),
'path': StrAnonymizer(req.path_qs, self.anonymization_method,
self.anonymization_salt),
'referer': StrAnonymizer(req.referer, self.anonymization_method,
self.anonymization_salt),
'user_agent': StrAnonymizer(req.user_agent,
self.anonymization_method,
self.anonymization_salt),
'headers': StrAnonymizer(logged_headers, self.anonymization_method,
self.anonymization_salt),
'client_etag': StrAnonymizer(req.headers.get('etag'),
self.anonymization_method,
self.anonymization_salt),
'account': StrAnonymizer(acc, self.anonymization_method,
self.anonymization_salt),
'container': StrAnonymizer(cont, self.anonymization_method,
self.anonymization_salt),
'object': StrAnonymizer(obj, self.anonymization_method,
self.anonymization_salt),
# Others information
'method': method,
'protocol':
req.environ.get('SERVER_PROTOCOL'),
'status_int': status_int,
'auth_token':
self.obscure_sensitive(
req.headers.get('x-auth-token')),
'bytes_recvd': bytes_received,
'bytes_sent': bytes_sent,
'transaction_id': req.environ.get('swift.trans_id'),
'request_time': duration_time_str,
'source': req.environ.get('swift.source'),
'log_info':
','.join(req.environ.get('swift.log_info', '')),
'policy_index': policy_index,
}
self.access_logger.info(
self.log_formatter.format(self.log_msg_template,
**replacements))
# Log timing and bytes-transferred data to StatsD
metric_name = self.statsd_metric_name(req, status_int, method)
metric_name_policy = self.statsd_metric_name_policy(req, status_int,
method,
policy_index)
# Only log data for valid controllers (or SOS) to keep the metric count
# down (egregious errors will get logged by the proxy server itself).
if metric_name:
self.access_logger.timing(metric_name + '.timing',
(end_time - start_time) * 1000)
self.access_logger.update_stats(metric_name + '.xfer',
bytes_received + bytes_sent)
if metric_name_policy:
self.access_logger.timing(metric_name_policy + '.timing',
(end_time - start_time) * 1000)
self.access_logger.update_stats(metric_name_policy + '.xfer',
bytes_received + bytes_sent)