def process_mdc(step, name): log_util.add_update_mdc_key_value_in_task("process_stage_name", name) log_util.add_update_mdc_key_value_in_task("process_stage_step", step) logger.info(step + ": " + name) # Remove the fields now log_util.remove_mdc_key_in_task("process_stage_step") log_util.remove_mdc_key_in_task("process_stage_name")
def process_mdc(step, name): log_util.add_update_mdc_key_value_in_task("process_stage_name", name) log_util.add_update_mdc_key_value_in_task("process_stage_step", step) # set the logger to what we want current_logger_name = getattr(asyncio.current_task(), "loggerName", None) # NCL-7133: use different logger name for process stage update asyncio.current_task( ).loggerName = "org.jboss.pnc._userlog_.process-stage-update" logger.info(step + ": " + name) if current_logger_name: asyncio.current_task().loggerName = current_logger_name # Remove the fields now log_util.remove_mdc_key_in_task("process_stage_step") log_util.remove_mdc_key_in_task("process_stage_name")
async def handler(request): c = await config.get_configuration() log_context = request.headers.get("LOG-CONTEXT", "").strip() if log_context == "": log_context = create_log_context_id() log_user_id = request.headers.get("log-user-id", "").strip() log_request_context = request.headers.get("log-request-context", "").strip() log_process_context = request.headers.get("log-process-context", "").strip() log_expires = request.headers.get("log-expires", "").strip() log_tmp = request.headers.get("log-tmp", "").strip() callback_id = create_callback_id() asyncio.Task.current_task().log_context = log_context log_util.add_update_mdc_key_value_in_task("userId", log_user_id) log_util.add_update_mdc_key_value_in_task("requestContext", log_request_context) log_util.add_update_mdc_key_value_in_task("processContext", log_process_context) log_util.add_update_mdc_key_value_in_task("expires", log_expires) log_util.add_update_mdc_key_value_in_task("tmp", log_tmp) asyncio.Task.current_task().callback_id = callback_id try: spec = await request.json() except ValueError: logger.error( "Rejected {method} {path}: body is not parsable as json". format(method=request.method, path=request.path)) rejected_data = await request.text() ERROR_VALIDATION_JSON_COUNTER.inc() logger.error("Request data: {data}".format(data=rejected_data)) return web.Response( status=400, content_type="application/json", text=json.dumps( obj=[{ "error_message": "expected json", "error_type": "json parsability", "path": [], }], ensure_ascii=False, ), ) try: validator(spec) except voluptuous.MultipleInvalid as x: logger.error( "Rejected {method} {path}: body failed input validation". format(method=request.method, path=request.path)) ERROR_VALIDATION_JSON_COUNTER.inc() logger.error("Request data: {data}".format(data=spec)) return web.Response( status=400, content_type="application/json", text=json.dumps(obj=[e.__dict__ for e in x.errors], ensure_ascii=False), ) logger.info("Accepted {method} {path}: {params}".format( method=request.method, path=request.path, params=spec)) try: validation.callback(spec) except voluptuous.MultipleInvalid as x: callback_mode = False else: callback_mode = True # Set the task_id if provided in the request task_id = spec.get("taskId", None) if task_id: asyncio.Task.current_task().task_id = task_id async def do_call(): try: ret = await coro(spec, **request.app) except cfutures.CancelledError as e: # do nothing else logger.info("Cancellation request received") raise e except exception.DescribedError as e: status = 400 traceback_id, obj = described_error_to_obj(e) ERROR_RESPONSE_400_COUNTER.inc() logger.error( "Failed ({e.__class__.__name__}), traceback hash: {traceback_id}" .format(**locals())) log_traceback_multi_line() except Exception as e: status = 500 traceback_id, obj = exception_to_obj(e) ERROR_RESPONSE_500_COUNTER.inc() logger.error( "Internal failure ({e.__class__.__name__}), traceback hash: {traceback_id}" .format(**locals())) log_traceback_multi_line() else: status = 200 obj = ret logger.info("Completed ok") log_file = file_callback_log.get_callback_log_path(callback_id) logs = "" if os.path.isfile(log_file): with open(log_file, "r") as f: logs = f.read() obj["log"] = logs return status, obj if callback_mode: async def do_callback(callback_spec): status, obj = await do_call() obj["callback"] = {"status": status, "id": callback_id} logger.info("Callback data: {}".format(obj)) @time(REQ_TIME) @time(REQ_HISTOGRAM_TIME) async def send_result(): try: # TODO refactor this into auth.py, we cannot use middleware for callbacks headers = {} current_task = asyncio.Task.current_task() auth_provider = c.get("auth", {}).get("provider", None) if auth_provider == "oauth2_jwt" and request.headers.get( "Authorization", None): auth_header = { "Authorization": request.headers["Authorization"] } context_headers = { "log-user-id": current_task.mdc["userId"], "log-request-context": current_task.mdc["requestContext"], "log-process-context": current_task.mdc["processContext"], "log-expires": current_task.mdc["expires"], "log_tmp": current_task.mdc["tmp"], } logger.debug( "Authorization enabled, adding header to callback: " + str(auth_header)) headers.update(auth_header) headers.update(context_headers) resp = await client_session.request( callback_spec.get("method", "POST"), callback_spec["url"], headers=headers, data=json.dumps( obj=obj, ensure_ascii=False).encode("utf-8"), ) except Exception as e: ERROR_CALLBACK_COUNTER.inc() logger.error( "Unable to send result of callback, exception {ename}, attempt {backoff}/{max_attempts}" .format( ename=e.__class__.__name__, backoff=backoff, max_attempts=max_attempts, )) logger.error(e) resp = None return resp backoff = 1 max_attempts = 9 resp = await send_result() while resp is None or resp.status // 100 != 2: if resp is not None: logger.info( "Unable to send result of callback, status {resp.status}, attempt {backoff}/{max_attempts}" .format(**locals())) sleep_period = 2**backoff logger.debug( "Sleeping for {sleep_period}".format(**locals())) await asyncio.sleep(sleep_period) backoff += 1 if backoff > max_attempts: logger.error( "Giving up on callback after {max_attempts} attempts" .format(**locals())) break resp = await send_result() if backoff <= max_attempts: logger.info("Callback result sent successfully") logger.info( "Creating callback task {callback_id}, returning ID now". format(**locals())) callback_task = request.app.loop.create_task( do_callback(spec["callback"])) callback_task.log_context = log_context callback_task.mdc = asyncio.Task.current_task().mdc callback_task.callback_id = callback_id # Set the task_id if provided in the request task_id = spec.get("taskId", None) if task_id: callback_task.task_id = task_id status = 202 obj = { "callback": { "id": callback_id, "websocket": "ws://" + repour_url + "/callback/" + callback_id, } } else: status, obj = await do_call() response = web.Response( status=status, content_type="application/json", text=json.dumps(obj=obj, ensure_ascii=False), ) return response