From 3b5f6fc1841faf2f804aab2b49fc3c916bcdd605 Mon Sep 17 00:00:00 2001 From: Bionic711 Date: Wed, 25 Feb 2026 15:29:59 -0600 Subject: [PATCH 1/5] update wrapper --- .../plugin_invocation_logger.py | 220 +++++++++++------- 1 file changed, 141 insertions(+), 79 deletions(-) diff --git a/application/single_app/semantic_kernel_plugins/plugin_invocation_logger.py b/application/single_app/semantic_kernel_plugins/plugin_invocation_logger.py index e5dfdab9..a7d21a90 100644 --- a/application/single_app/semantic_kernel_plugins/plugin_invocation_logger.py +++ b/application/single_app/semantic_kernel_plugins/plugin_invocation_logger.py @@ -10,6 +10,7 @@ import time import logging import functools +import inspect from typing import Any, Dict, List, Optional, Callable from datetime import datetime from dataclasses import dataclass, asdict @@ -330,93 +331,154 @@ def decorator(func: Callable) -> Callable: extra={"function_name": func.__name__, "plugin_name": plugin_name}, level=logging.DEBUG) - @functools.wraps(func) - def wrapper(*args, **kwargs): - start_time = time.time() - function_name = func.__name__ - - log_event(f"[Plugin Function Logger] Function call started", - extra={"plugin_name": plugin_name, "function_name": function_name}, - level=logging.DEBUG) - - # Prepare parameters (combine args and kwargs) + def _build_parameters(args, kwargs): parameters = {} if args: - # Handle 'self' parameter for methods if hasattr(args[0], '__class__'): parameters.update({f"arg_{i}": arg for i, arg in enumerate(args[1:])}) else: parameters.update({f"arg_{i}": arg for i, arg in enumerate(args)}) parameters.update(kwargs) - - # Enhanced logging: Show parameters + return parameters + + def _log_start(function_name: str): + log_event( + f"[Plugin Function Logger] Function call started", + extra={"plugin_name": plugin_name, "function_name": function_name}, + level=logging.DEBUG + ) + + def _log_parameters(function_name: str, parameters: Dict[str, Any]): param_str = ", ".join([f"{k}={v}" for k, v in parameters.items()]) if parameters else "no parameters" - log_event(f"[Plugin Function Logger] Function parameters", - extra={ - "plugin_name": plugin_name, - "function_name": function_name, - "parameters": parameters, - "param_string": param_str - }, - level=logging.DEBUG) - - try: - result = func(*args, **kwargs) - end_time = time.time() - duration_ms = (end_time - start_time) * 1000 - - # Enhanced logging: Show result and timing - result_preview = str(result)[:200] + "..." if len(str(result)) > 200 else str(result) - log_event(f"[Plugin Function Logger] Function completed successfully", - extra={ - "plugin_name": plugin_name, - "function_name": function_name, - "result_preview": result_preview, - "duration_ms": duration_ms, - "full_function_name": f"{plugin_name}.{function_name}" - }, - level=logging.INFO) - - log_plugin_invocation( - plugin_name=plugin_name, - function_name=function_name, - parameters=parameters, - result=result, - start_time=start_time, - end_time=end_time, - success=True - ) - - return result - - except Exception as e: - end_time = time.time() - duration_ms = (end_time - start_time) * 1000 - - # Enhanced logging: Show error and timing - log_event(f"[Plugin Function Logger] Function failed with error", - extra={ - "plugin_name": plugin_name, - "function_name": function_name, - "duration_ms": duration_ms, - "error_message": str(e), - "full_function_name": f"{plugin_name}.{function_name}" - }, - level=logging.ERROR) - - log_plugin_invocation( - plugin_name=plugin_name, - function_name=function_name, - parameters=parameters, - result=None, - start_time=start_time, - end_time=end_time, - success=False, - error_message=str(e) - ) - - raise # Re-raise the exception - + log_event( + f"[Plugin Function Logger] Function parameters", + extra={ + "plugin_name": plugin_name, + "function_name": function_name, + "parameters": parameters, + "param_string": param_str + }, + level=logging.DEBUG + ) + + def _log_success(function_name: str, result: Any, duration_ms: float): + result_preview = str(result)[:200] + "..." if len(str(result)) > 200 else str(result) + log_event( + f"[Plugin Function Logger] Function completed successfully", + extra={ + "plugin_name": plugin_name, + "function_name": function_name, + "result_preview": result_preview, + "duration_ms": duration_ms, + "full_function_name": f"{plugin_name}.{function_name}" + }, + level=logging.INFO + ) + + def _log_failure(function_name: str, error: Exception, duration_ms: float): + log_event( + f"[Plugin Function Logger] Function failed with error", + extra={ + "plugin_name": plugin_name, + "function_name": function_name, + "duration_ms": duration_ms, + "error_message": str(error), + "full_function_name": f"{plugin_name}.{function_name}" + }, + level=logging.ERROR + ) + + if inspect.iscoroutinefunction(func): + @functools.wraps(func) + async def wrapper(*args, **kwargs): + start_time = time.time() + function_name = func.__name__ + _log_start(function_name) + parameters = _build_parameters(args, kwargs) + _log_parameters(function_name, parameters) + + try: + result = await func(*args, **kwargs) + end_time = time.time() + duration_ms = (end_time - start_time) * 1000 + _log_success(function_name, result, duration_ms) + + log_plugin_invocation( + plugin_name=plugin_name, + function_name=function_name, + parameters=parameters, + result=result, + start_time=start_time, + end_time=end_time, + success=True + ) + + return result + + except Exception as e: + end_time = time.time() + duration_ms = (end_time - start_time) * 1000 + _log_failure(function_name, e, duration_ms) + + log_plugin_invocation( + plugin_name=plugin_name, + function_name=function_name, + parameters=parameters, + result=None, + start_time=start_time, + end_time=end_time, + success=False, + error_message=str(e) + ) + + raise + else: + @functools.wraps(func) + def wrapper(*args, **kwargs): + start_time = time.time() + function_name = func.__name__ + _log_start(function_name) + parameters = _build_parameters(args, kwargs) + _log_parameters(function_name, parameters) + + try: + result = func(*args, **kwargs) + if inspect.iscoroutine(result): + raise RuntimeError("Async coroutine returned from sync function wrapper") + end_time = time.time() + duration_ms = (end_time - start_time) * 1000 + _log_success(function_name, result, duration_ms) + + log_plugin_invocation( + plugin_name=plugin_name, + function_name=function_name, + parameters=parameters, + result=result, + start_time=start_time, + end_time=end_time, + success=True + ) + + return result + + except Exception as e: + end_time = time.time() + duration_ms = (end_time - start_time) * 1000 + _log_failure(function_name, e, duration_ms) + + log_plugin_invocation( + plugin_name=plugin_name, + function_name=function_name, + parameters=parameters, + result=None, + start_time=start_time, + end_time=end_time, + success=False, + error_message=str(e) + ) + + raise + return wrapper return decorator From ba5ae632c511d90863ebdbdfa45fb8f0205b1d79 Mon Sep 17 00:00:00 2001 From: Bionic711 Date: Mon, 2 Mar 2026 16:46:42 -0600 Subject: [PATCH 2/5] fix for json schema validation for plugins --- application/single_app/json_schema_validation.py | 5 ++++- application/single_app/requirements.txt | 6 +++--- 2 files changed, 7 insertions(+), 4 deletions(-) diff --git a/application/single_app/json_schema_validation.py b/application/single_app/json_schema_validation.py index 6e98159b..8bc3ae88 100644 --- a/application/single_app/json_schema_validation.py +++ b/application/single_app/json_schema_validation.py @@ -43,7 +43,10 @@ def validate_plugin(plugin): plugin_copy['endpoint'] = f'sql://{plugin_type}' # First run schema validation - validator = Draft7Validator(schema['definitions']['Plugin']) + if schema.get("$ref") and schema.get("definitions"): + validator = Draft7Validator(schema, resolver=RefResolver.from_schema(schema)) + else: + validator = Draft7Validator(schema) errors = sorted(validator.iter_errors(plugin_copy), key=lambda e: e.path) if errors: return '; '.join([f"{plugin.get('name', '')}: {e.message}" for e in errors]) diff --git a/application/single_app/requirements.txt b/application/single_app/requirements.txt index 6a738388..c8156eab 100644 --- a/application/single_app/requirements.txt +++ b/application/single_app/requirements.txt @@ -3,7 +3,7 @@ pandas==2.2.3 azure-monitor-query==1.4.1 Flask==2.2.5 Flask-WTF==1.2.1 -gunicorn +gunicorn>=23.0.0 Werkzeug==3.1.5 requests==2.32.4 openai>=1.98.0,<2.0.0 @@ -22,7 +22,7 @@ threadpoolctl==3.5.0 azure-search-documents==11.5.3 python-dotenv==0.21.0 azure-ai-formrecognizer==3.3.3 -pyjwt==2.9.0 +pyjwt>=2.9.0 markdown2==2.5.3 azure-mgmt-cognitiveservices==13.6.0 azure-identity==1.23.0 @@ -41,7 +41,7 @@ xlrd==2.0.1 pillow==11.1.0 ffmpeg-binaries-compat==1.0.1 ffmpeg-python==0.2.0 -semantic-kernel>=1.39.2 +semantic-kernel>=1.39.4 redis>=5.0,<6.0 pyodbc>=4.0.0 PyMySQL>=1.0.0 From 4a2f856e27ded87b3278ee1a7d0ed0de1b239c65 Mon Sep 17 00:00:00 2001 From: Bionic711 Date: Mon, 2 Mar 2026 16:54:08 -0600 Subject: [PATCH 3/5] add video indexer fix for custom env --- application/single_app/config.py | 1 + 1 file changed, 1 insertion(+) diff --git a/application/single_app/config.py b/application/single_app/config.py index 989731f4..4f4cfd07 100644 --- a/application/single_app/config.py +++ b/application/single_app/config.py @@ -213,6 +213,7 @@ def get_allowed_extensions(enable_video=False, enable_audio=False): elif AZURE_ENVIRONMENT == "custom": resource_manager = CUSTOM_RESOURCE_MANAGER_URL_VALUE authority = CUSTOM_IDENTITY_URL_VALUE + video_indexer_endpoint = os.getenv("CUSTOM_VIDEO_INDEXER_ENDPOINT", "https://api.videoindexer.ai") credential_scopes=[resource_manager + "/.default"] cognitive_services_scope = CUSTOM_COGNITIVE_SERVICES_URL_VALUE search_resource_manager = CUSTOM_SEARCH_RESOURCE_MANAGER_URL_VALUE From 1bcb8f7593482fd478267e61db684efd2a122261 Mon Sep 17 00:00:00 2001 From: Bionic711 Date: Mon, 2 Mar 2026 17:04:11 -0600 Subject: [PATCH 4/5] fix fragility bug --- application/single_app/config.py | 2 +- .../plugin_invocation_logger.py | 27 ++++++++++++++++--- 2 files changed, 24 insertions(+), 5 deletions(-) diff --git a/application/single_app/config.py b/application/single_app/config.py index 4f4cfd07..292192bb 100644 --- a/application/single_app/config.py +++ b/application/single_app/config.py @@ -88,7 +88,7 @@ EXECUTOR_TYPE = 'thread' EXECUTOR_MAX_WORKERS = 30 SESSION_TYPE = 'filesystem' -VERSION = "0.237.049" +VERSION = "0.237.050" SECRET_KEY = os.getenv('SECRET_KEY', 'dev-secret-key-change-in-production') diff --git a/application/single_app/semantic_kernel_plugins/plugin_invocation_logger.py b/application/single_app/semantic_kernel_plugins/plugin_invocation_logger.py index a7d21a90..40e0ba62 100644 --- a/application/single_app/semantic_kernel_plugins/plugin_invocation_logger.py +++ b/application/single_app/semantic_kernel_plugins/plugin_invocation_logger.py @@ -330,14 +330,33 @@ def decorator(func: Callable) -> Callable: log_event(f"[Plugin Function Logger] Decorating function for plugin", extra={"function_name": func.__name__, "plugin_name": plugin_name}, level=logging.DEBUG) + + # Only skip the first positional argument when the wrapped callable + # explicitly declares a conventional instance/class receiver. + skip_first_positional_arg = False + try: + unwrapped_func = inspect.unwrap(func) + signature = inspect.signature(unwrapped_func) + parameters = list(signature.parameters.values()) + if parameters: + first_parameter = parameters[0] + if ( + first_parameter.kind in ( + inspect.Parameter.POSITIONAL_ONLY, + inspect.Parameter.POSITIONAL_OR_KEYWORD, + ) + and first_parameter.name in {"self", "cls"} + ): + skip_first_positional_arg = True + except (TypeError, ValueError): + # Keep all args if the callable cannot be introspected. + skip_first_positional_arg = False def _build_parameters(args, kwargs): parameters = {} if args: - if hasattr(args[0], '__class__'): - parameters.update({f"arg_{i}": arg for i, arg in enumerate(args[1:])}) - else: - parameters.update({f"arg_{i}": arg for i, arg in enumerate(args)}) + positional_args = args[1:] if skip_first_positional_arg else args + parameters.update({f"arg_{i}": arg for i, arg in enumerate(positional_args)}) parameters.update(kwargs) return parameters From 058c9a29907373cc8e44008b5aae4788131b6a92 Mon Sep 17 00:00:00 2001 From: Bionic711 Date: Mon, 2 Mar 2026 17:13:24 -0600 Subject: [PATCH 5/5] add handling for multi-decorated function --- application/single_app/config.py | 2 +- .../plugin_invocation_logger.py | 57 +++++++++++++++++-- 2 files changed, 54 insertions(+), 5 deletions(-) diff --git a/application/single_app/config.py b/application/single_app/config.py index 292192bb..2f660902 100644 --- a/application/single_app/config.py +++ b/application/single_app/config.py @@ -88,7 +88,7 @@ EXECUTOR_TYPE = 'thread' EXECUTOR_MAX_WORKERS = 30 SESSION_TYPE = 'filesystem' -VERSION = "0.237.050" +VERSION = "0.237.051" SECRET_KEY = os.getenv('SECRET_KEY', 'dev-secret-key-change-in-production') diff --git a/application/single_app/semantic_kernel_plugins/plugin_invocation_logger.py b/application/single_app/semantic_kernel_plugins/plugin_invocation_logger.py index 40e0ba62..f982f0a4 100644 --- a/application/single_app/semantic_kernel_plugins/plugin_invocation_logger.py +++ b/application/single_app/semantic_kernel_plugins/plugin_invocation_logger.py @@ -331,11 +331,15 @@ def decorator(func: Callable) -> Callable: extra={"function_name": func.__name__, "plugin_name": plugin_name}, level=logging.DEBUG) + try: + unwrapped_func = inspect.unwrap(func) + except Exception: + unwrapped_func = func + # Only skip the first positional argument when the wrapped callable # explicitly declares a conventional instance/class receiver. skip_first_positional_arg = False try: - unwrapped_func = inspect.unwrap(func) signature = inspect.signature(unwrapped_func) parameters = list(signature.parameters.values()) if parameters: @@ -351,6 +355,8 @@ def decorator(func: Callable) -> Callable: except (TypeError, ValueError): # Keep all args if the callable cannot be introspected. skip_first_positional_arg = False + + is_async_callable = inspect.iscoroutinefunction(unwrapped_func) def _build_parameters(args, kwargs): parameters = {} @@ -407,7 +413,7 @@ def _log_failure(function_name: str, error: Exception, duration_ms: float): level=logging.ERROR ) - if inspect.iscoroutinefunction(func): + if is_async_callable: @functools.wraps(func) async def wrapper(*args, **kwargs): start_time = time.time() @@ -462,8 +468,51 @@ def wrapper(*args, **kwargs): try: result = func(*args, **kwargs) - if inspect.iscoroutine(result): - raise RuntimeError("Async coroutine returned from sync function wrapper") + if inspect.isawaitable(result): + log_event( + "[Plugin Function Logger] Awaitable returned from sync wrapper; deferring completion logging", + extra={ + "plugin_name": plugin_name, + "function_name": function_name, + "full_function_name": f"{plugin_name}.{function_name}", + }, + level=logging.WARNING, + ) + + async def _await_and_log(awaitable_result): + try: + awaited_value = await awaitable_result + end_time = time.time() + duration_ms = (end_time - start_time) * 1000 + _log_success(function_name, awaited_value, duration_ms) + log_plugin_invocation( + plugin_name=plugin_name, + function_name=function_name, + parameters=parameters, + result=awaited_value, + start_time=start_time, + end_time=end_time, + success=True, + ) + return awaited_value + except Exception as await_error: + end_time = time.time() + duration_ms = (end_time - start_time) * 1000 + _log_failure(function_name, await_error, duration_ms) + log_plugin_invocation( + plugin_name=plugin_name, + function_name=function_name, + parameters=parameters, + result=None, + start_time=start_time, + end_time=end_time, + success=False, + error_message=str(await_error), + ) + raise + + return _await_and_log(result) + end_time = time.time() duration_ms = (end_time - start_time) * 1000 _log_success(function_name, result, duration_ms)