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
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):
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(HTTPStatus.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)
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)
transaction.context['_request'] = request.context
meth = getattr(obj, method)
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)
raise
except (ConcurrencyException, UserError, UserWarning,
LoginException):
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()
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)
logger.debug('Result: %s', result)
response = app.make_response(request, result)
if rpc.readonly and rpc.cache:
response.headers.extend(rpc.cache.headers())
return response