Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

integrate logs #20300

Merged
merged 8 commits into from
Sep 23, 2021
+346 −245
Merged

integrate logs #20300

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
19aa0c6
integrate logs
xiangyan99 Aug 16, 2021
481c05d
update
xiangyan99 Aug 16, 2021
ead8eda
update
xiangyan99 Aug 17, 2021
4e22d70
update
xiangyan99 Aug 17, 2021
8592e6d
update
xiangyan99 Aug 17, 2021
314ade2
Merge branch 'main' into core_integrate_log
xiangyan99 Aug 27, 2021
a0517ae
Update _universal.py
xiangyan99 Aug 27, 2021
24fef03
update
xiangyan99 Aug 27, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
107 changes: 74 additions & 33 deletions sdk/core/azure-core/azure/core/pipeline/policies/_universal.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -246,6 +246,7 @@ def on_request(self, request):


class NetworkTraceLoggingPolicy(SansIOHTTPPolicy):

"""The logging policy in the pipeline is used to output HTTP network trace to the configured logger.

This accepts both global configuration, and per-request level with "enable_http_logger"
Expand All @@ -264,7 +265,7 @@ class NetworkTraceLoggingPolicy(SansIOHTTPPolicy):
def __init__(self, logging_enable=False, **kwargs): # pylint: disable=unused-argument
self.enable_http_logger = logging_enable

def on_request(self, request):
def on_request(self, request): # pylint: disable=too-many-return-statements
# type: (PipelineRequest) -> None
"""Logs HTTP request to the DEBUG logger.

Expand All @@ -280,27 +281,31 @@ def on_request(self, request):
return

try:
_LOGGER.debug("Request URL: %r", http_request.url)
_LOGGER.debug("Request method: %r", http_request.method)
_LOGGER.debug("Request headers:")
log_string = "Request URL: '{}'".format(http_request.url)
log_string += "/nRequest method: '{}'".format(http_request.method)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Shouldn't \n be used? /n makes the output unreadable:

image

log_string += "/nRequest headers:"
for header, value in http_request.headers.items():
_LOGGER.debug(" %r: %r", header, value)
_LOGGER.debug("Request body:")
log_string += "/n '{}': '{}'".format(header, value)
log_string += "/nRequest body:"

# We don't want to log the binary data of a file upload.
if isinstance(http_request.body, types.GeneratorType):
_LOGGER.debug("File upload")
log_string += "/nFile upload"
_LOGGER.debug(log_string)
return
try:
if isinstance(http_request.body, types.AsyncGeneratorType):
_LOGGER.debug("File upload")
log_string += "/nFile upload"
_LOGGER.debug(log_string)
return
except AttributeError:
pass
if http_request.body:
_LOGGER.debug(str(http_request.body))
log_string += "/n{}".format(str(http_request.body))
_LOGGER.debug(log_string)
return
_LOGGER.debug("This request has no body")
log_string += "/nThis request has no body"
_LOGGER.debug(log_string)
except Exception as err: # pylint: disable=broad-except
_LOGGER.debug("Failed to log request: %r", err)

Expand All @@ -320,28 +325,29 @@ def on_response(self, request, response):
if not _LOGGER.isEnabledFor(logging.DEBUG):
return

_LOGGER.debug("Response status: %r", http_response.status_code)
_LOGGER.debug("Response headers:")
log_string = "Response status: '{}'".format(http_response.status_code)
log_string += "/nResponse headers:"
for res_header, value in http_response.headers.items():
_LOGGER.debug(" %r: %r", res_header, value)
log_string += "/n '{}': '{}'".format(res_header, value)

# We don't want to log binary data if the response is a file.
_LOGGER.debug("Response content:")
log_string += "/nResponse content:"
pattern = re.compile(r'attachment; ?filename=["\w.]+', re.IGNORECASE)
header = http_response.headers.get('content-disposition')

if header and pattern.match(header):
filename = header.partition('=')[2]
_LOGGER.debug("File attachments: %s", filename)
log_string += "/nFile attachments: {}".format(filename)
elif http_response.headers.get("content-type", "").endswith("octet-stream"):
_LOGGER.debug("Body contains binary data.")
log_string += "/nBody contains binary data."
elif http_response.headers.get("content-type", "").startswith("image"):
_LOGGER.debug("Body contains image data.")
log_string += "/nBody contains image data."
else:
if response.context.options.get('stream', False):
_LOGGER.debug("Body is streamable")
log_string += "/nBody is streamable."
else:
_LOGGER.debug(http_response.text())
log_string += "/n{}".format(http_response.text())
_LOGGER.debug(log_string)
except Exception as err: # pylint: disable=broad-except
_LOGGER.debug("Failed to log response: %s", repr(err))

Expand Down Expand Up @@ -376,6 +382,7 @@ class HttpLoggingPolicy(SansIOHTTPPolicy):
"User-Agent",
])
REDACTED_PLACEHOLDER = "REDACTED"
MULTI_RECORD_LOG = "AZURE_SDK_LOGGING_MULTIRECORD"

def __init__(self, logger=None, **kwargs): # pylint: disable=unused-argument
self.logger = logger or logging.getLogger(
Expand All @@ -396,7 +403,7 @@ def _redact_header(self, key, value):
]
return value if key.lower() in lower_case_allowed_header_names else HttpLoggingPolicy.REDACTED_PLACEHOLDER

def on_request(self, request):
def on_request(self, request): # pylint: disable=too-many-return-statements
# type: (PipelineRequest) -> None
"""Logs HTTP method, url and headers.
:param request: The PipelineRequest object.
Expand All @@ -420,26 +427,52 @@ def on_request(self, request):
parsed_url[4] = "&".join(["=".join(part) for part in filtered_qp])
redacted_url = urllib.parse.urlunparse(parsed_url)

logger.info("Request URL: %r", redacted_url)
logger.info("Request method: %r", http_request.method)
logger.info("Request headers:")
multi_record = os.environ.get(HttpLoggingPolicy.MULTI_RECORD_LOG, False)
if multi_record:
logger.info("Request URL: %r", redacted_url)
logger.info("Request method: %r", http_request.method)
logger.info("Request headers:")
for header, value in http_request.headers.items():
value = self._redact_header(header, value)
logger.info(" %r: %r", header, value)
if isinstance(http_request.body, types.GeneratorType):
logger.info("File upload")
return
try:
if isinstance(http_request.body, types.AsyncGeneratorType):
logger.info("File upload")
return
except AttributeError:
pass
if http_request.body:
logger.info("A body is sent with the request")
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just curious why is this at the level info?

This is logged with every request, so I expected this to be at the DEBUG level only

return
logger.info("No body was attached to the request")
return
log_string = "Request URL: '{}'".format(redacted_url)
log_string += "/nRequest method: '{}'".format(http_request.method)
log_string += "/nRequest headers:"
for header, value in http_request.headers.items():
value = self._redact_header(header, value)
logger.info(" %r: %r", header, value)
log_string += "/n '{}': '{}'".format(header, value)
if isinstance(http_request.body, types.GeneratorType):
logger.info("File upload")
log_string += "/nFile upload"
logger.info(log_string)
return
try:
if isinstance(http_request.body, types.AsyncGeneratorType):
logger.info("File upload")
log_string += "/nFile upload"
logger.info(log_string)
return
except AttributeError:
pass
if http_request.body:
logger.info("A body is sent with the request")
log_string += "/nA body is sent with the request"
logger.info(log_string)
return
logger.info("No body was attached to the request")
return
log_string += "/nNo body was attached to the request"
logger.info(log_string)

except Exception as err: # pylint: disable=broad-except
logger.warning("Failed to log request: %s", repr(err))

Expand All @@ -453,15 +486,23 @@ def on_response(self, request, response):
if not logger.isEnabledFor(logging.INFO):
return

logger.info("Response status: %r", http_response.status_code)
logger.info("Response headers:")
multi_record = os.environ.get(HttpLoggingPolicy.MULTI_RECORD_LOG, False)
if multi_record:
logger.info("Response status: %r", http_response.status_code)
logger.info("Response headers:")
for res_header, value in http_response.headers.items():
value = self._redact_header(res_header, value)
logger.info(" %r: %r", res_header, value)
return
log_string = "Response status: {}".format(http_response.status_code)
log_string += "/nResponse headers:"
for res_header, value in http_response.headers.items():
value = self._redact_header(res_header, value)
logger.info(" %r: %r", res_header, value)
log_string += "/n '{}': '{}'".format(res_header, value)
logger.info(log_string)
except Exception as err: # pylint: disable=broad-except
logger.warning("Failed to log response: %s", repr(err))


class ContentDecodePolicy(SansIOHTTPPolicy):
"""Policy for decoding unstreamed response content.

Expand Down
Loading