IntenseWebs/freeipa
3
0
Fork 0
mirror of https://salsa.debian.org/freeipa-team/freeipa.git synced 2025-02-25 18:55:28 -06:00
Code Issues Packages Projects Releases Wiki Activity

Extend logging to include execution time

Browse Source 
Adding execution time in logs provides useful information
for identifying API operations that impact IPA performance.

Related: https://pagure.io/freeipa/issue/8759
Signed-off-by: Antonio Torres <antorres@redhat.com>
Reviewed-By: Rob Crittenden <rcritten@redhat.com>
Reviewed-By: Alexander Bokovoy <abokovoy@redhat.com>
This commit is contained in:
Antonio Torres 2021-03-11 17:43:10 +01:00 committed by Rob Crittenden
parent 76dd9a97fd
commit 4d716d3fbc
1 changed files with 16 additions and 0 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

16
ipaserver/rpcserver.py
View File

@ -28,6 +28,7 @@ from __future__ import absolute_import
import logging import logging
from xml.sax.saxutils import escape from xml.sax.saxutils import escape
import os import os
import time
import traceback import traceback
from io import BytesIO from io import BytesIO
from urllib.parse import parse_qs from urllib.parse import parse_qs
@ -374,6 +375,8 @@ class WSGIExecutioner(Executioner):
return self.marshal(result, RefererError(referer='missing'), _id) return self.marshal(result, RefererError(referer='missing'), _id)
if not environ['HTTP_REFERER'].startswith('https://%s/ipa' % self.api.env.host) and not self.env.in_tree: if not environ['HTTP_REFERER'].startswith('https://%s/ipa' % self.api.env.host) and not self.env.in_tree:
return self.marshal(result, RefererError(referer=environ['HTTP_REFERER']), _id) return self.marshal(result, RefererError(referer=environ['HTTP_REFERER']), _id)
if self.api.env.debug:
time_start = time.perf_counter_ns()
try: try:
if ('HTTP_ACCEPT_LANGUAGE' in environ): if ('HTTP_ACCEPT_LANGUAGE' in environ):
lang_reg_w_q = environ['HTTP_ACCEPT_LANGUAGE'].split(',')[0] lang_reg_w_q = environ['HTTP_ACCEPT_LANGUAGE'].split(',')[0]
@ -414,6 +417,8 @@ class WSGIExecutioner(Executioner):
try: try:
params = command.args_options_2_params(*args, **options) params = command.args_options_2_params(*args, **options)
except Exception as e: except Exception as e:
if self.api.env.debug:
time_end = time.perf_counter_ns()
logger.info( logger.info(
'exception %s caught when converting options: %s', 'exception %s caught when converting options: %s',
e.__class__.__name__, str(e) e.__class__.__name__, str(e)
@ -421,6 +426,9 @@ class WSGIExecutioner(Executioner):
# get at least some context of what is going on # get at least some context of what is going on
params = options params = options
error = e error = e
else:
if self.api.env.debug:
time_end = time.perf_counter_ns()
if error: if error:
result_string = type(error).__name__ result_string = type(error).__name__
else: else:
@ -431,6 +439,14 @@ class WSGIExecutioner(Executioner):
name, name,
', '.join(command._repr_iter(**params)), ', '.join(command._repr_iter(**params)),
result_string) result_string)
if self.api.env.debug:
logger.debug('[%s] %s: %s(%s): %s %s',
type(self).__name__,
principal,
name,
', '.join(command._repr_iter(**params)),
result_string,
'etime=' + str(time_end - time_start))
else: else:
logger.info('[%s] %s: %s: %s', logger.info('[%s] %s: %s: %s',
type(self).__name__, type(self).__name__,