def format(self, record):
"""Format message with structured tags and any exception/trailer"""
import talisker.sentry # lazy to break import cycle
try:
record.message = self.clean_message(record.getMessage())
# we never want sentry to capture DEBUG logs in its breadcrumbs, as
# they may be sensitive
if record.levelno > logging.DEBUG:
talisker.sentry.record_log_breadcrumb(record)
if len(record.message) > self.MAX_MSG_SIZE:
record.message = (
record.message[:self.MAX_MSG_SIZE] + self.TRUNCATED
)
# this is verbatim from the parent class in stdlib
if self.usesTime():
record.asctime = self.formatTime(record, self.datefmt)
s = self._fmt % record.__dict__
# add our structured tags *before* exception info is added
structured = getattr(record, 'extra', {})
if record.exc_info and 'errno' not in structured:
structured.update(get_errno_fields(record.exc_info[1]))
if structured:
s += " " + self.logfmt(structured)
# add talisker trailers
trailer = getattr(record, '_trailer', None)
if trailer is not None:
s += '\n' + str(trailer)
# this is verbatim from the parent class in stdlib
if record.exc_info:
# Cache the traceback text to avoid converting it multiple
# times (it's constant anyway)
if not record.exc_text:
record.exc_text = self.formatException(record.exc_info)
if record.exc_text:
if s[-1:] != "\n":
s = s + "\n"
try:
s = s + record.exc_text
except UnicodeError: # pragma: no cover
# Sometimes filenames have non-ASCII chars, which can lead
# to errors when s is Unicode and record.exc_text is str
# See issue 8924.
# We also use replace for when there are multiple
# encodings, e.g. UTF-8 for the filesystem and latin-1
# for a script. See issue 13232.
s = s + record.exc_text.decode(
sys.getfilesystemencoding(), 'replace')
return s
except Exception:
# ensure unexpected error doesn't break logging
return super().format(record)
def test_get_errno_fields_permissions():
exc = None
try:
open('/blah', 'w')
except Exception as e:
exc = e
assert util.get_errno_fields(exc) == {
'errno': 'EACCES',
'strerror': 'Permission denied',
'filename': '/blah',
}
def test_get_errno_fields_dns():
exc = None
try:
import socket
s = socket.socket()
s.connect(('some-host-name-that-will-not-resolve.com', 54321))
except Exception as e:
exc = e
assert util.get_errno_fields(exc) == {
'errno': 'EAI_NONAME',
'strerror': 'Name or service not known',
}
def test_get_errno_fields_connection():
exc = None
try:
import socket
s = socket.socket()
s.connect(('localhost', 54321))
except Exception as e:
exc = e
assert util.get_errno_fields(exc) == {
'errno': 'ECONNREFUSED',
'strerror': 'Connection refused',
}
def record_request(request, response=None, exc=None):
metadata = collect_metadata(request, response)
if response:
Context.track('http', metadata['duration_ms'])
if exc:
metadata.update(get_errno_fields(exc))
talisker.sentry.record_breadcrumb(
type='http',
category='requests',
data=metadata,
)
labels = {
'host': metadata['host'],
'view': metadata.get('view', 'unknown'),
}
ctx = Context.current
metric_api_name = getattr(ctx, 'metric_api_name', None)
metric_host_name = getattr(ctx, 'metric_host_name', None)
if metric_api_name is not None:
labels['view'] = metric_api_name
if metric_host_name is not None:
labels['host'] = metric_host_name
labels['host'] = labels['host'].replace('.', '-')
RequestsMetric.count.inc(**labels)
if response is None:
# likely connection errors
logger.exception('http request failure', extra=metadata)
labels['type'] = 'connection'
labels['status'] = metadata.get('errno', 'unknown')
RequestsMetric.errors.inc(**labels)
else:
logger.info('http request', extra=metadata)
labels['status'] = metadata['status_code']
RequestsMetric.latency.observe(metadata['duration_ms'], **labels)
if metadata['status_code'] >= 500:
labels['type'] = 'http'
RequestsMetric.errors.inc(**labels)
def test_get_errno_fields_dns():
exc = None
try:
import socket
import platform
s = socket.socket()
s.connect(('some-host-name-that-will-not-resolve.com', 54321))
except Exception as e:
exc = e
processed_exc = util.get_errno_fields(exc)
if platform.system() == 'Darwin':
assert processed_exc == {
'errno': 'ENOEXEC',
'strerror': 'nodename nor servname provided, or not known'
}
else:
assert processed_exc == {
'errno': 'EAI_NONAME',
'strerror': 'Name or service not known'
}
