def callproc(self, procname, vars=None):
try:
context = analyze_before(self)
except:
perf_logger.exception('analyse_before failed')
context = None
ret = super(PerfCursor, self).callproc(procname, vars)
if context is not None:
try:
analyze_after(*context)
except:
perf_logger.exception('analyse_after failed')
return ret
def callproc(self, procname, vars=None):
try:
context = analyze_before(self)
except:
perf_logger.exception('analyse_before failed')
context = None
ret = super(PerfCursor, self).callproc(procname, vars)
if context is not None:
try:
analyze_after(*context)
except:
perf_logger.exception('analyse_after failed')
return ret
def execute(self, query, vars=None):
try:
context = analyze_before(self)
except:
perf_logger.exception('analyse_before failed')
context = None
ret = super(PerfCursor, self).execute(query, vars)
if context is not None:
try:
analyze_after(*context)
except:
perf_logger.exception('analyse_after failed')
return ret
def execute(self, query, vars=None):
if logger.isEnabledFor(logging.DEBUG):
logger.debug(self.mogrify(query, vars))
try:
context = analyze_before(self)
except:
perf_logger.exception('analyse_before failed')
context = None
ret = super(PerfCursor, self).execute(query, vars)
if context is not None:
try:
analyze_after(*context)
except:
perf_logger.exception('analyse_after failed')
return ret
def execute(self, query, vars=None):
if logger.isEnabledFor(logging.DEBUG):
logger.debug(self.mogrify(query, vars))
try:
context = analyze_before(self)
except Exception:
perf_logger.exception('analyse_before failed')
context = None
# JCA: Log slow queries
if _slow_logging_enabled:
start = time.time()
ret = super(PerfCursor, self).execute(query, vars)
if _slow_logging_enabled:
end = time.time()
if end - start > _slow_threshold:
logger.warning('slow:(%s s):%s' %
(end - start, self.mogrify(query, vars)))
if context is not None:
try:
analyze_after(*context)
except Exception:
perf_logger.exception('analyse_after failed')
return ret
def _dispatch(request, pool, *args, **kwargs):
# AKE: perf analyzer hooks
try:
PerfLog().on_enter()
except Exception:
perf_logger.exception('on_enter failed')
DatabaseOperationalError = backend.get('DatabaseOperationalError')
obj, method = get_object_method(request, pool)
if method in obj.__rpc__:
rpc = obj.__rpc__[method]
else:
raise UserError('Calling method %s on %s is not allowed' %
(method, obj))
log_message = '%s.%s(*%s, **%s) from %s@%s/%s'
username = request.authorization.username
if isinstance(username, bytes):
username = username.decode('utf-8')
log_args = (obj, method, args, kwargs, username, request.remote_addr,
request.path)
logger.info(log_message, *log_args)
# JCA: log slow RPC
if slow_threshold >= 0:
slow_msg = '%s.%s (%s s)'
slow_args = (obj, method)
slow_start = time.time()
user = request.user_id
# AKE: add session to transaction context
if request.authorization.type == 'session':
session = request.authorization.get('session')
party = None
elif request.authorization.type == 'token':
session = request.authorization.get('token')
party = request.authorization.get('party_id')
# AKE: perf analyzer hooks
try:
PerfLog().on_execute(user, session, request.rpc_method, args, kwargs)
except Exception:
perf_logger.exception('on_execute failed')
for count in range(config.getint('database', 'retry'), -1, -1):
# AKE: add session to transaction context
with Transaction().start(pool.database_name,
user,
readonly=rpc.readonly,
context={
'session': session,
'party': party
}) as transaction:
try:
c_args, c_kwargs, transaction.context, transaction.timestamp \
= rpc.convert(obj, *args, **kwargs)
meth = getattr(obj, method)
# AKE: perf analyzer hooks
try:
wrapped_meth = profile(meth)
except Exception:
perf_logger.exception('profile failed')
else:
meth = wrapped_meth
if (rpc.instantiate is None
or not is_instance_method(obj, method)):
result = rpc.result(meth(*c_args, **c_kwargs))
else:
assert rpc.instantiate == 0
inst = c_args.pop(0)
if hasattr(inst, method):
result = rpc.result(meth(inst, *c_args, **c_kwargs))
else:
result = [
rpc.result(meth(i, *c_args, **c_kwargs))
for i in inst
]
except DatabaseOperationalError:
if count and not rpc.readonly:
transaction.rollback()
continue
logger.error(log_message, *log_args, exc_info=True)
# JCA: log slow RPC
if slow_threshold >= 0:
slow_args += (str(time.time() - slow_start), )
log_exception(slow_logger.error, slow_msg, *slow_args)
raise
except (ConcurrencyException, UserError, UserWarning,
LoginException):
logger.debug(log_message, *log_args, exc_info=True)
# JCA: log slow RPC
if slow_threshold >= 0:
slow_args += (str(time.time() - slow_start), )
log_exception(slow_logger.debug, slow_msg, *slow_args)
raise
except Exception:
logger.error(log_message, *log_args, exc_info=True)
# JCA: log slow RPC
if slow_threshold >= 0:
slow_args += (str(time.time() - slow_start), )
log_exception(slow_logger.error, slow_msg, *slow_args)
raise
# Need to commit to unlock SQLite database
transaction.commit()
if request.authorization.type == 'session':
# AKE: moved all session ops to security script
security.reset(pool.database_name, user,
request.authorization.get('session'))
logger.debug('Result: %s', result)
# JCA: log slow RPC
if slow_threshold >= 0:
slow_diff = time.time() - slow_start
slow_args += (str(slow_diff), )
if slow_diff > slow_threshold:
slow_logger.info(slow_msg, *slow_args)
else:
slow_logger.debug(slow_msg, *slow_args)
# AKE: perf analyzer hooks
try:
PerfLog().on_leave(result)
except Exception:
perf_logger.exception('on_leave failed')
return result
def _dispatch(request, pool, *args, **kwargs):
DatabaseOperationalError = backend.get('DatabaseOperationalError')
obj, method = get_object_method(request, pool)
if method in obj.__rpc__:
rpc = obj.__rpc__[method]
else:
raise UserError('Calling method %s on %s is not allowed' %
(method, obj))
# JCA : If log_threshold is != -1, we only log the times for calls that
# exceed the configured value
if log_threshold == -1:
log_message = '%s.%s(*%s, **%s) from %s@%s/%s'
username = request.authorization.username.decode('utf-8')
log_args = (obj, method, args, kwargs, username, request.remote_addr,
request.path)
logger.info(log_message, *log_args)
else:
log_message = '%s.%s (%s s)'
log_args = (obj, method)
log_start = time.time()
user = request.user_id
session = None
if request.authorization.type == 'session':
session = request.authorization.get('session')
for count in range(config.getint('database', 'retry'), -1, -1):
with Transaction().start(pool.database_name,
user,
readonly=rpc.readonly,
context={'session': session}) as transaction:
try:
PerfLog().on_enter(user, session, request.rpc_method, args,
kwargs)
except:
perf_logger.exception('on_enter failed')
try:
c_args, c_kwargs, transaction.context, transaction.timestamp \
= rpc.convert(obj, *args, **kwargs)
meth = getattr(obj, method)
try:
wrapped_meth = profile(meth)
except:
perf_logger.exception('profile failed')
else:
meth = wrapped_meth
if (rpc.instantiate is None
or not is_instance_method(obj, method)):
result = rpc.result(meth(*c_args, **c_kwargs))
else:
assert rpc.instantiate == 0
inst = c_args.pop(0)
if hasattr(inst, method):
result = rpc.result(meth(inst, *c_args, **c_kwargs))
else:
result = [
rpc.result(meth(i, *c_args, **c_kwargs))
for i in inst
]
except DatabaseOperationalError:
if count and not rpc.readonly:
transaction.rollback()
continue
if log_threshold != -1:
log_end = time.time()
log_args += (str(log_end - log_start), )
log_exception(logger.error, log_message, *log_args)
raise
except (ConcurrencyException, UserError, UserWarning,
LoginException):
if log_threshold != -1:
log_end = time.time()
log_args += (str(log_end - log_start), )
log_exception(logger.debug, log_message, *log_args)
raise
except Exception:
if log_threshold != -1:
log_end = time.time()
log_args += (str(log_end - log_start), )
log_exception(logger.error, log_message, *log_args)
raise
# Need to commit to unlock SQLite database
transaction.commit()
if request.authorization.type == 'session':
try:
with Transaction().start(pool.database_name, 0) as transaction:
Session = pool.get('ir.session')
Session.reset(request.authorization.get('session'))
except DatabaseOperationalError:
log_exception(logger.debug, 'Reset session failed')
if log_threshold == -1:
logger.debug('Result: %s', result)
else:
log_end = time.time()
log_args += (str(log_end - log_start), )
if log_end - log_start > log_threshold:
logger.info(log_message, *log_args)
else:
logger.debug(log_message, *log_args)
try:
PerfLog().on_leave(result)
except:
perf_logger.exception('on_leave failed')
return result
def _dispatch(request, pool, *args, **kwargs):
DatabaseOperationalError = backend.get('DatabaseOperationalError')
obj, method = get_object_method(request, pool)
if method in obj.__rpc__:
rpc = obj.__rpc__[method]
else:
raise UserError('Calling method %s on %s is not allowed'
% (method, obj))
log_message = '%s.%s(*%s, **%s) from %s@%s/%s'
log_args = (obj, method, args, kwargs,
request.authorization.username, request.remote_addr, request.path)
logger.info(log_message, *log_args)
user = request.user_id
session = None
if request.authorization.type == 'session':
session = request.authorization.get('session')
for count in range(config.getint('database', 'retry'), -1, -1):
with Transaction().start(pool.database_name, user,
readonly=rpc.readonly,
context={'session': session}) as transaction:
Cache.clean(pool.database_name)
try:
PerfLog().on_enter(user, session,
request.method, args, kwargs)
except:
perf_logger.exception('on_enter failed')
try:
c_args, c_kwargs, transaction.context, transaction.timestamp \
= rpc.convert(obj, *args, **kwargs)
meth = getattr(obj, method)
try:
wrapped_meth = profile(meth)
except:
perf_logger.exception('profile failed')
else:
meth = wrapped_meth
if (rpc.instantiate is None
or not is_instance_method(obj, method)):
result = rpc.result(meth(*c_args, **c_kwargs))
else:
assert rpc.instantiate == 0
inst = c_args.pop(0)
if hasattr(inst, method):
result = rpc.result(meth(inst, *c_args, **c_kwargs))
else:
result = [rpc.result(meth(i, *c_args, **c_kwargs))
for i in inst]
except DatabaseOperationalError:
if count and not rpc.readonly:
transaction.rollback()
continue
logger.error(log_message, *log_args, exc_info=True)
raise
except (ConcurrencyException, UserError, UserWarning):
logger.debug(log_message, *log_args, exc_info=True)
raise
except Exception:
logger.error(log_message, *log_args, exc_info=True)
raise
# Need to commit to unlock SQLite database
transaction.commit()
Cache.resets(pool.database_name)
if request.authorization.type == 'session':
try:
with Transaction().start(pool.database_name, 0) as transaction:
Session = pool.get('ir.session')
Session.reset(request.authorization.get('session'))
except DatabaseOperationalError:
logger.debug('Reset session failed', exc_info=True)
logger.debug('Result: %s', result)
try:
PerfLog().on_leave(result)
except:
perf_logger.exception('on_leave failed')
return result
def _dispatch(request, pool, *args, **kwargs):
# AKE: perf analyzer hooks
try:
PerfLog().on_enter()
except Exception:
perf_logger.exception('on_enter failed')
obj, method = get_object_method(request, pool)
if method in obj.__rpc__:
rpc = obj.__rpc__[method]
else:
abort(HTTPStatus.FORBIDDEN)
user = request.user_id
session = None
if request.authorization.type == 'session':
session = request.authorization.get('session')
if rpc.fresh_session and session:
context = {'_request': request.context}
if not security.check_timeout(
pool.database_name, user, session, context=context):
abort(http.client.UNAUTHORIZED)
log_message = '%s.%s(*%s, **%s) from %s@%s%s'
username = request.authorization.username
if isinstance(username, bytes):
username = username.decode('utf-8')
log_args = (obj, method, args, kwargs, username, request.remote_addr,
request.path)
logger.debug(log_message, *log_args)
# JCA: log slow RPC
if slow_threshold >= 0:
slow_msg = '%s.%s (%s s)'
slow_args = (obj, method)
slow_start = time.time()
# JCA: Format parameters
if format_json_parameters and logger.isEnabledFor(logging.DEBUG):
try:
for line in json.dumps(args,
indent=2,
sort_keys=True,
cls=DEBUGEncoder).split('\n'):
logger.debug('Parameters: %s' % line)
except Exception:
logger.debug('Could not format parameters in log', exc_info=True)
user = request.user_id
# AKE: add session and token to transaction context
token = None
if request.authorization.type == 'token':
token = {
'key': request.authorization.get('token'),
'user': user,
'party': request.authorization.get('party_id'),
}
# AKE: perf analyzer hooks
try:
PerfLog().on_execute(user, session, request.rpc_method, args, kwargs)
except Exception:
perf_logger.exception('on_execute failed')
retry = config.getint('database', 'retry')
for count in range(retry, -1, -1):
if count != retry:
time.sleep(0.02 * (retry - count))
with Transaction().start(pool.database_name,
user,
readonly=rpc.readonly) as transaction:
try:
c_args, c_kwargs, transaction.context, transaction.timestamp \
= rpc.convert(obj, *args, **kwargs)
# AKE: add session to transaction context
transaction.context.update({
'session': session,
'token': token,
})
transaction.context['_request'] = request.context
meth = getattr(obj, method)
# AKE: perf analyzer hooks
try:
wrapped_meth = profile(meth)
except Exception:
perf_logger.exception('profile failed')
else:
meth = wrapped_meth
if (rpc.instantiate is None
or not is_instance_method(obj, method)):
result = rpc.result(meth(*c_args, **c_kwargs))
else:
assert rpc.instantiate == 0
inst = c_args.pop(0)
if hasattr(inst, method):
result = rpc.result(meth(inst, *c_args, **c_kwargs))
else:
result = [
rpc.result(meth(i, *c_args, **c_kwargs))
for i in inst
]
except backend.DatabaseOperationalError:
if count and not rpc.readonly:
transaction.rollback()
continue
logger.error(log_message, *log_args, exc_info=True)
# JCA: log slow RPC
if slow_threshold >= 0:
slow_args += (str(time.time() - slow_start), )
log_exception(slow_logger.error, slow_msg, *slow_args)
raise
except (ConcurrencyException, UserError, UserWarning,
LoginException):
logger.debug(log_message, *log_args, exc_info=True)
# JCA: log slow RPC
if slow_threshold >= 0:
slow_args += (str(time.time() - slow_start), )
log_exception(slow_logger.debug, slow_msg, *slow_args)
raise
except Exception:
logger.error(log_message, *log_args, exc_info=True)
# JCA: log slow RPC
if slow_threshold >= 0:
slow_args += (str(time.time() - slow_start), )
log_exception(slow_logger.error, slow_msg, *slow_args)
raise
# Need to commit to unlock SQLite database
transaction.commit()
while transaction.tasks:
task_id = transaction.tasks.pop()
run_task(pool, task_id)
if session:
context = {'_request': request.context}
security.reset(pool.database_name, session, context=context)
# JCA: Allow to format json result
if format_json_result and logger.isEnabledFor(logging.DEBUG):
try:
for line in json.dumps(result,
indent=2,
sort_keys=True,
cls=DEBUGEncoder).split('\n'):
logger.debug('Result: %s' % line)
except Exception:
logger.debug('Could not format parameters in log',
exc_info=True)
else:
logger.debug('Result: %s', result)
# JCA: log slow RPC
if slow_threshold >= 0:
slow_diff = time.time() - slow_start
slow_args += (str(slow_diff), )
if slow_diff > slow_threshold:
slow_logger.info(slow_msg, *slow_args)
else:
slow_logger.debug(slow_msg, *slow_args)
# AKE: perf analyzer hooks
try:
PerfLog().on_leave(result)
except Exception:
perf_logger.exception('on_leave failed')
response = app.make_response(request, result)
if rpc.readonly and rpc.cache:
response.headers.extend(rpc.cache.headers())
return response
