diff --git a/docs/development.md b/docs/development.md index 44d7af3..59b8008 100644 --- a/docs/development.md +++ b/docs/development.md @@ -199,24 +199,28 @@ The SDK provides logging level constants that you can use instead of importing t ### Logging Features The SDK includes a comprehensive logging system: -- Custom FATAL level (90) in addition to standard levels -- Convenience functions: `debug()`, `info()`, `warning()`, `error()`, `critical()`, `fatal()`, `exception()` -- File logging with automatic directory creation -- Console output control (stdout/stderr switching) -- httpx/httpcore logging control via `propagate` parameter -- Centralized configuration via `set_level()` and `configure_file_logging()` +- **Function tracing decorator** (`@trace`) with automatic timing and entry/exit logging +- **Custom logging levels**: TRACE (5), FATAL (90), and NONE (100) in addition to standard levels +- **Convenience functions**: `debug()`, `info()`, `warning()`, `error()`, `critical()`, `fatal()`, `exception()`, `trace()` +- **File logging** with automatic directory creation and custom formatting +- **Console output control** (stdout/stderr switching) +- **httpx/httpcore logging control** via `propagate` parameter +- **Centralized configuration** via `set_level()` and `configure_file_logging()` +- **Sensitive data filtering** to automatically redact PII, API keys, passwords, and tokens ### Available Logging Levels The SDK provides the following logging level constants: - `ipsdk.logging.NOTSET` - No logging threshold (0) +- `ipsdk.logging.TRACE` - Function tracing and detailed execution flow (5) - `ipsdk.logging.DEBUG` - Debug messages (10) - `ipsdk.logging.INFO` - Informational messages (20) - `ipsdk.logging.WARNING` - Warning messages (30) - `ipsdk.logging.ERROR` - Error messages (40) - `ipsdk.logging.CRITICAL` - Critical error messages (50) - `ipsdk.logging.FATAL` - Fatal error messages (90) +- `ipsdk.logging.NONE` - Disable all logging (100) ### File Logging @@ -268,6 +272,188 @@ You can specify custom format strings for file handlers: **Note:** File logging automatically creates parent directories if they don't exist. +### Function Tracing with @trace Decorator + +The SDK provides a powerful `@trace` decorator for debugging and performance monitoring. When applied to functions or methods, it automatically logs entry/exit points with execution timing. + +#### Basic Usage + +```python +from ipsdk import logging + +# Enable TRACE level to see trace output +logging.set_level(logging.TRACE) + +@logging.trace +def process_data(data): + # Your implementation + return result + +# When called, logs: +# → module.process_data +# ← module.process_data (0.15ms) +``` + +#### Features + +The `@trace` decorator provides: +- **Automatic entry/exit logging** with `→` and `←` symbols +- **Execution time measurement** in milliseconds (2 decimal precision) +- **Module and class context** extracted automatically from function metadata +- **Exception tracking** with timing when functions exit via exception +- **Sync and async support** - works with both synchronous and asynchronous functions + +#### Decorator vs Manual Logging + +**Old Pattern (deprecated):** +```python +def my_method(self): + logging.trace(self.my_method, modname=__name__, clsname=self.__class__) + # implementation +``` + +**New Pattern (recommended):** +```python +@logging.trace +def my_method(self): + # implementation +``` + +The decorator approach: +- Eliminates repetitive code +- Automatically extracts module and class names +- Provides entry/exit visibility +- Includes execution timing +- Tracks exception exits + +#### Using with Classes + +The decorator works seamlessly with instance methods, class methods, and static methods: + +```python +class DataProcessor: + @logging.trace + def process(self, data): + """Process data - traced automatically""" + return self._transform(data) + + @logging.trace + def _transform(self, data): + """Private method - also traced""" + return data.upper() + + @classmethod + @logging.trace + def from_config(cls, config): + """Class method - traced""" + return cls(config['param']) + + @staticmethod + @logging.trace + def validate(data): + """Static method - traced""" + return len(data) > 0 +``` + +#### Async Functions + +The decorator automatically handles async functions: + +```python +@logging.trace +async def fetch_data(url): + """Async function - timing includes await time""" + async with httpx.AsyncClient() as client: + response = await client.get(url) + return response.json() + +# Logs: +# → module.fetch_data +# ← module.fetch_data (245.67ms) +``` + +#### Exception Tracking + +When functions exit via exception, the decorator logs the exception exit with timing: + +```python +@logging.trace +def risky_operation(): + raise ValueError("Something went wrong") + +# Logs: +# → module.risky_operation +# ← module.risky_operation (exception, 0.03ms) +# (Exception propagates normally) +``` + +#### Output Format + +**Entry log format:** +``` +→ module_name.ClassName.method_name +``` + +**Normal exit format:** +``` +← module_name.ClassName.method_name (1.23ms) +``` + +**Exception exit format:** +``` +← module_name.ClassName.method_name (exception, 1.23ms) +``` + +#### Performance Considerations + +- Uses `time.perf_counter()` for high-precision timing (sub-millisecond accuracy) +- Minimal overhead: ~0.01-0.02ms per traced function call +- Only logs when `TRACE` level is enabled +- Safe to leave decorators in production code (no output when TRACE is disabled) + +#### Example: Debugging Performance Issues + +```python +import time +from ipsdk import logging + +logging.set_level(logging.TRACE) + +@logging.trace +def slow_query(): + time.sleep(0.5) # Simulate slow database query + return "result" + +@logging.trace +def fast_cache_lookup(): + return "cached_result" + +@logging.trace +def main(): + slow_query() + fast_cache_lookup() + return "done" + +main() +# Output: +# → __main__.main +# → __main__.slow_query +# ← __main__.slow_query (500.12ms) +# → __main__.fast_cache_lookup +# ← __main__.fast_cache_lookup (0.01ms) +# ← __main__.main (500.25ms) +``` + +This helps identify performance bottlenecks by showing exactly which functions are taking the most time. + +#### Best Practices + +1. **Use TRACE level in development** - Enable it for debugging, disable in production unless needed +2. **Apply to key functions** - Focus on API calls, database queries, and complex logic +3. **Leave decorators in place** - They're harmless when TRACE is disabled +4. **Review timing data** - Use logs to identify slow operations during development +5. **Combine with other logging** - Mix with `debug()`, `info()`, etc. for comprehensive visibility + ## Documentation Standards All code in the SDK follows strict documentation standards: diff --git a/src/ipsdk/connection.py b/src/ipsdk/connection.py index a7bd017..eeff902 100644 --- a/src/ipsdk/connection.py +++ b/src/ipsdk/connection.py @@ -145,6 +145,7 @@ async def fetch_devices(): class ConnectionBase: client: httpx.Client | httpx.AsyncClient + @logging.trace def __init__( self, host: str, @@ -184,8 +185,6 @@ def __init__( Raises: None """ - logging.trace(self.__init__, modname=__name__, clsname=self.__class__) - self.user = user self.password = password @@ -204,6 +203,7 @@ def __init__( ) self.client.headers["User-Agent"] = f"ipsdk/{metadata.version}" + @logging.trace def _make_base_url( self, host: str, @@ -229,8 +229,6 @@ def _make_base_url( Raises: None """ - logging.trace(self._make_base_url, modname=__name__, clsname=self.__class__) - if port == 0: port = 443 if use_tls is True else 80 @@ -242,6 +240,7 @@ def _make_base_url( return urllib.parse.urlunsplit((proto, host, base_path, None, None)) + @logging.trace def _build_request( self, method: HTTPMethod, @@ -268,8 +267,6 @@ def _build_request( Raises: None """ - logging.trace(self._build_request, modname=__name__, clsname=self.__class__) - self._validate_request_args(method, path, params, json) headers = {} @@ -302,6 +299,7 @@ def _build_request( json=json, ) + @logging.trace def _validate_request_args( self, method: HTTPMethod, @@ -330,9 +328,6 @@ def _validate_request_args( IpsdkError: If method is not HTTPMethod type, params is not dict, json is not dict/list, or path is not string """ - logging.trace( - self._validate_request_args, modname=__name__, clsname=self.__class__ - ) if isinstance(method, HTTPMethod) is False: msg = "method must be of type `HTTPMethod`" raise exceptions.IpsdkError(msg) @@ -378,6 +373,7 @@ def __init__(self, *args: Any, **kwargs: Any) -> None: super().__init__(*args, **kwargs) self._auth_lock = threading.Lock() + @logging.trace def __init_client__( self, base_url: str | None = None, verify: bool = True, timeout: int = 30 ) -> httpx.Client: @@ -397,7 +393,6 @@ def __init_client__( Raises: None """ - logging.trace(self.__init_client__, modname=__name__, clsname=self.__class__) logging.info(f"Creating new client for {base_url}") return httpx.Client( base_url=base_url or "", @@ -411,6 +406,7 @@ def authenticate(self) -> None: Abstract method for implementing authentication """ + @logging.trace def _send_request( self, method: HTTPMethod, @@ -437,8 +433,6 @@ def _send_request( RequestError: Network or connection errors occurred. HTTPStatusError: Server returned an HTTP error status (4xx, 5xx). """ - logging.trace(self._send_request, modname=__name__, clsname=self.__class__) - if self.authenticated is False: assert self._auth_lock is not None with self._auth_lock: @@ -472,6 +466,7 @@ def _send_request( return Response(res) + @logging.trace def get(self, path: str, params: dict[str, Any | None] | None = None) -> Response: """Send an HTTP GET request to the server. @@ -486,9 +481,9 @@ def get(self, path: str, params: dict[str, Any | None] | None = None) -> Respons RequestError: Network or connection errors occurred. HTTPStatusError: Server returned an HTTP error status (4xx, 5xx). """ - logging.trace(self.get, modname=__name__, clsname=self.__class__) return self._send_request(HTTPMethod.GET, path=path, params=params) + @logging.trace def delete( self, path: str, params: dict[str, Any | None] | None = None ) -> Response: @@ -505,9 +500,9 @@ def delete( RequestError: Network or connection errors occurred. HTTPStatusError: Server returned an HTTP error status (4xx, 5xx). """ - logging.trace(self.delete, modname=__name__, clsname=self.__class__) return self._send_request(HTTPMethod.DELETE, path=path, params=params) + @logging.trace def post( self, path: str, @@ -529,9 +524,9 @@ def post( RequestError: Network or connection errors occurred. HTTPStatusError: Server returned an HTTP error status (4xx, 5xx). """ - logging.trace(self.post, modname=__name__, clsname=self.__class__) return self._send_request(HTTPMethod.POST, path=path, params=params, json=json) + @logging.trace def put( self, path: str, @@ -553,9 +548,9 @@ def put( RequestError: Network or connection errors occurred. HTTPStatusError: Server returned an HTTP error status (4xx, 5xx). """ - logging.trace(self.put, modname=__name__, clsname=self.__class__) return self._send_request(HTTPMethod.PUT, path=path, params=params, json=json) + @logging.trace def patch( self, path: str, @@ -577,7 +572,6 @@ def patch( RequestError: Network or connection errors occurred. HTTPStatusError: Server returned an HTTP error status (4xx, 5xx). """ - logging.trace(self.patch, modname=__name__, clsname=self.__class__) return self._send_request(HTTPMethod.PATCH, path=path, params=params, json=json) @@ -588,6 +582,7 @@ def __init__(self, *args: Any, **kwargs: Any) -> None: super().__init__(*args, **kwargs) self._auth_lock = asyncio.Lock() + @logging.trace def __init_client__( self, base_url: str | None = None, verify: bool = True, timeout: int = 30 ) -> httpx.AsyncClient: @@ -610,7 +605,6 @@ def __init_client__( Returns: An instance of `httpx.AsyncClient` """ - logging.trace(self.__init_client__, modname=__name__, clsname=self.__class__) logging.info(f"Creating new async client for {base_url}") return httpx.AsyncClient( base_url=base_url or "", verify=verify, timeout=timeout @@ -622,6 +616,7 @@ async def authenticate(self) -> None: Abstract method for implementing authentication """ + @logging.trace async def _send_request( self, method: HTTPMethod, @@ -648,8 +643,6 @@ async def _send_request( RequestError: Network or connection errors occurred. HTTPStatusError: Server returned an HTTP error status (4xx, 5xx). """ - logging.trace(self._send_request, modname=__name__, clsname=self.__class__) - if self.authenticated is False: assert self._auth_lock is not None async with self._auth_lock: @@ -683,6 +676,7 @@ async def _send_request( return Response(res) + @logging.trace async def get( self, path: str, params: dict[str, Any | None] | None = None ) -> Response: @@ -704,9 +698,9 @@ async def get( Returns: A `Response` object """ - logging.trace(self.get, modname=__name__, clsname=self.__class__) return await self._send_request(HTTPMethod.GET, path=path, params=params) + @logging.trace async def delete( self, path: str, params: dict[str, Any | None] | None = None ) -> Response: @@ -728,9 +722,9 @@ async def delete( Returns: A `Response` object """ - logging.trace(self.delete, modname=__name__, clsname=self.__class__) return await self._send_request(HTTPMethod.DELETE, path=path, params=params) + @logging.trace async def post( self, path: str, @@ -761,11 +755,11 @@ async def post( Returns: A `Response` object """ - logging.trace(self.post, modname=__name__, clsname=self.__class__) return await self._send_request( HTTPMethod.POST, path=path, params=params, json=json ) + @logging.trace async def put( self, path: str, @@ -796,11 +790,11 @@ async def put( Returns: A `Response` object """ - logging.trace(self.put, modname=__name__, clsname=self.__class__) return await self._send_request( HTTPMethod.PUT, path=path, params=params, json=json ) + @logging.trace async def patch( self, path: str, @@ -831,7 +825,6 @@ async def patch( Returns: A `Response` object """ - logging.trace(self.patch, modname=__name__, clsname=self.__class__) return await self._send_request( HTTPMethod.PATCH, path=path, params=params, json=json ) diff --git a/src/ipsdk/exceptions.py b/src/ipsdk/exceptions.py index 4fae85d..6ab0bdd 100644 --- a/src/ipsdk/exceptions.py +++ b/src/ipsdk/exceptions.py @@ -96,6 +96,7 @@ class IpsdkError(Exception): details (dict): Additional error details and context """ + @logging.trace def __init__(self, message: str, exc: httpx.HTTPError | None = None) -> None: """ Initialize the base SDK exception. @@ -103,10 +104,10 @@ def __init__(self, message: str, exc: httpx.HTTPError | None = None) -> None: Args: message (str): Human-readable error message """ - logging.trace(self.__init__, modname=__name__, clsname=self.__class__) super().__init__(message) self._exc = exc + @logging.trace def __str__(self) -> str: """ Return a string representation of the error. @@ -114,7 +115,6 @@ def __str__(self) -> str: Returns: A formatted error message including details if available """ - logging.trace(self.__str__, modname=__name__, clsname=self.__class__) return self.args[0] @property @@ -173,8 +173,8 @@ class RequestError(IpsdkError): ... print(f"Failed request: {e.request.url}") """ + @logging.trace def __init__(self, exc: httpx.HTTPError) -> None: - logging.trace(self.__init__, modname=__name__, clsname=self.__class__) super().__init__(exc.args[0], exc) @@ -224,8 +224,8 @@ class HTTPStatusError(IpsdkError): ... print("Authentication failed") """ + @logging.trace def __init__(self, exc: httpx.HTTPError) -> None: - logging.trace(self.__init__, modname=__name__, clsname=self.__class__) super().__init__(exc.args[0], exc) diff --git a/src/ipsdk/gateway.py b/src/ipsdk/gateway.py index b90cf75..ad025a5 100644 --- a/src/ipsdk/gateway.py +++ b/src/ipsdk/gateway.py @@ -159,6 +159,7 @@ async def get_devices(): from . import logging +@logging.trace def _make_path() -> str: """ Utility function that returns the login url @@ -166,10 +167,10 @@ def _make_path() -> str: Returns: A string that provides the login url """ - logging.trace(_make_path, modname=__name__) return "/login" +@logging.trace def _make_body(user: str, password: str) -> dict[str, str]: """ Utility function to make the authentication body used to authenticate to @@ -183,10 +184,10 @@ def _make_body(user: str, password: str) -> dict[str, str]: A dict object that can be used to send in the body of the authentication request """ - logging.trace(_make_body, modname=__name__) return {"username": user, "password": password} +@logging.trace def _make_headers() -> dict[str, str]: """ Utility function that returns a dict object of headers @@ -194,7 +195,6 @@ def _make_headers() -> dict[str, str]: Returns: A dict object that can be passed to a request to set the headers """ - logging.trace(_make_headers, modname=__name__) return { "Content-Type": "application/json", "Accept": "application/json", @@ -211,11 +211,11 @@ class AuthMixin: password: str | None client: httpx.Client + @logging.trace def authenticate(self) -> None: """ Provides the authentication function for authenticating to the server """ - logging.trace(self.authenticate, modname=__name__, clsname=self.__class__) if self.user is None or self.password is None: msg = "Username and password are required for Gateway authentication" raise exceptions.IpsdkError(msg) @@ -247,11 +247,11 @@ class AsyncAuthMixin: password: str | None client: httpx.AsyncClient + @logging.trace async def authenticate(self) -> None: """ Provides the authentication function for authenticating to the server """ - logging.trace(self.authenticate, modname=__name__, clsname=self.__class__) if self.user is None or self.password is None: msg = "Username and password are required for Gateway authentication" raise exceptions.IpsdkError(msg) @@ -281,6 +281,7 @@ async def authenticate(self) -> None: AsyncGatewayType = AsyncGateway +@logging.trace def gateway_factory( host: str = "localhost", port: int = 0, @@ -328,8 +329,6 @@ def gateway_factory( Returns: An initialized connection instance """ - logging.trace(gateway_factory, modname=__name__) - factory = AsyncGateway if want_async is True else Gateway return factory( host=host, diff --git a/src/ipsdk/http.py b/src/ipsdk/http.py index b0a86d7..429eee7 100644 --- a/src/ipsdk/http.py +++ b/src/ipsdk/http.py @@ -75,6 +75,7 @@ class Request: ValueError: If required parameters are missing or invalid """ + @logging.trace def __init__( self, method: str, @@ -83,7 +84,6 @@ def __init__( headers: dict[str, str | None] | None = None, json: str | bytes | dict | (list | None) = None, ) -> None: - logging.trace(self.__init__, modname=__name__, clsname=self.__class__) self.method = method self.path = path self.params = params or {} @@ -100,6 +100,7 @@ def url(self) -> str: """ return self.path + @logging.trace def __repr__(self) -> str: """ String representation of the request @@ -107,7 +108,6 @@ def __repr__(self) -> str: Returns: str: A string representation of the request """ - logging.trace(self.__repr__, modname=__name__, clsname=self.__class__) return f"Request(method='{self.method}', path='{self.path}')" @@ -128,8 +128,8 @@ class Response: ValueError: If the httpx_response is None or invalid """ + @logging.trace def __init__(self, httpx_response: httpx.Response) -> None: - logging.trace(self.__init__, modname=__name__, clsname=self.__class__) if httpx_response is None: msg = "httpx_response cannot be None" raise ValueError(msg) @@ -196,6 +196,7 @@ def request(self) -> httpx.Request: """ return self._response.request + @logging.trace def json(self) -> dict[str, Any]: """ Parse the response content as JSON @@ -206,13 +207,13 @@ def json(self) -> dict[str, Any]: Raises: ValueError: If the response content is not valid JSON """ - logging.trace(self.json, modname=__name__, clsname=self.__class__) try: return self._response.json() except Exception as exc: msg = f"Failed to parse response as JSON: {exc!s}" raise ValueError(msg) + @logging.trace def raise_for_status(self) -> None: """ Raise an exception if the response status indicates an error @@ -220,9 +221,9 @@ def raise_for_status(self) -> None: Raises: httpx.HTTPStatusError: If the response status code indicates an error """ - logging.trace(self.raise_for_status, modname=__name__, clsname=self.__class__) self._response.raise_for_status() + @logging.trace def is_success(self) -> bool: """ Check if the response indicates success (2xx status code) @@ -230,11 +231,11 @@ def is_success(self) -> bool: Returns: bool: True if the status code is in the 2xx range, False otherwise """ - logging.trace(self.is_success, modname=__name__, clsname=self.__class__) return ( HTTPStatus.OK.value <= self.status_code < HTTPStatus.MULTIPLE_CHOICES.value ) + @logging.trace def is_error(self) -> bool: """ Check if the response indicates an error (4xx or 5xx status code) @@ -242,9 +243,9 @@ def is_error(self) -> bool: Returns: bool: True if the status code indicates an error, False otherwise """ - logging.trace(self.is_error, modname=__name__, clsname=self.__class__) return self.status_code >= HTTPStatus.BAD_REQUEST.value + @logging.trace def __repr__(self) -> str: """ String representation of the response @@ -252,5 +253,4 @@ def __repr__(self) -> str: Returns: str: A string representation of the response """ - logging.trace(self.__repr__, modname=__name__, clsname=self.__class__) return f"Response(status_code={self.status_code}, url='{self.url}')" diff --git a/src/ipsdk/jsonutils.py b/src/ipsdk/jsonutils.py index ee36917..cfd5619 100644 --- a/src/ipsdk/jsonutils.py +++ b/src/ipsdk/jsonutils.py @@ -112,6 +112,7 @@ from . import logging +@logging.trace def loads(s: str) -> Union[dict, list]: """Convert a JSON formatted string to a dict or list object @@ -121,7 +122,6 @@ def loads(s: str) -> Union[dict, list]: Returns: A dict or list object """ - logging.trace(loads, modname=__name__) try: return json.loads(s) except json.JSONDecodeError as exc: @@ -134,6 +134,7 @@ def loads(s: str) -> Union[dict, list]: raise exceptions.SerializationError(msg) +@logging.trace def dumps(o: Union[dict, list]) -> str: """Convert a dict or list to a JSON string @@ -143,7 +144,6 @@ def dumps(o: Union[dict, list]) -> str: Returns: A JSON string representation """ - logging.trace(dumps, modname=__name__) try: return json.dumps(o) except (TypeError, ValueError) as exc: diff --git a/src/ipsdk/logging.py b/src/ipsdk/logging.py index 9f6b474..4c135da 100644 --- a/src/ipsdk/logging.py +++ b/src/ipsdk/logging.py @@ -53,11 +53,15 @@ # Enable TRACE level for detailed function tracing logging.set_level(logging.TRACE) + @logging.trace def process_data(data): - logging.trace(process_data) # Logs "invoking process_data" # ... function implementation return result + # Calling process_data will log: + # "→ module.process_data" on entry + # "← module.process_data (1.23ms)" on exit + Fatal errors that exit the application:: from ipsdk import logging @@ -98,13 +102,18 @@ def process_data(data): logging.set_level(logging.NONE) """ +import inspect import logging import sys +import time import traceback from functools import cache from functools import partial +from functools import wraps +from typing import Any from typing import Callable +from typing import TypeVar from . import heuristics from . import metadata @@ -125,7 +134,7 @@ def process_data(data): # Logging level constants that wrap stdlib logging module constants NOTSET = logging.NOTSET -TRACE = logging.NOTSET +TRACE = logging.TRACE DEBUG = logging.DEBUG INFO = logging.INFO WARNING = logging.WARNING @@ -175,36 +184,73 @@ def log(lvl: int, msg: str) -> None: critical = partial(log, logging.CRITICAL) -def trace( - f: Callable, - modname: str | None = None, - clsname: str | None = None -) -> None: - """Log a trace message for function invocation. +T = TypeVar("T", bound=Callable[..., Any]) + + +def trace(f: T) -> T: + """Decorator to automatically trace function invocations. - This function logs a trace-level message indicating that a function - is being invoked. Useful for detailed debugging and execution flow tracking. + This decorator logs trace-level messages at function entry and exit, + automatically extracting module and qualified name information from + the function object. Useful for detailed debugging and execution flow + tracking. + + The decorator works with both synchronous and asynchronous functions, + logging entry with '→' and exit with '←' symbols. Exit logs include + the execution time in milliseconds. Args: - f (Callable): The function being invoked + f (Callable): The function to wrap with tracing Returns: - None + Callable: The wrapped function with tracing enabled Raises: None - """ - msg = "" - if modname is not None: - msg += f"{modname}." - - if clsname is not None: - msg += f"{clsname.__name__}." - - msg += f.__name__ + Example: + @trace + def process_data(data): + # Function implementation + return result - log(logging.TRACE, msg) + # Logs: "→ module.process_data" on entry + # Logs: "← module.process_data (1.23ms)" on exit + """ + func_name = f"{f.__module__}.{f.__qualname__}" + + if inspect.iscoroutinefunction(f): + @wraps(f) + async def async_wrapper(*args: Any, **kwargs: Any) -> Any: + start_time = time.perf_counter() + log(logging.TRACE, f"→ {func_name}") + try: + result = await f(*args, **kwargs) + except Exception: + elapsed_ms = (time.perf_counter() - start_time) * 1000 + log(logging.TRACE, f"← {func_name} (exception, {elapsed_ms:.2f}ms)") + raise + else: + elapsed_ms = (time.perf_counter() - start_time) * 1000 + log(logging.TRACE, f"← {func_name} ({elapsed_ms:.2f}ms)") + return result + return async_wrapper # type: ignore[return-value] + + @wraps(f) + def sync_wrapper(*args: Any, **kwargs: Any) -> Any: + start_time = time.perf_counter() + log(logging.TRACE, f"→ {func_name}") + try: + result = f(*args, **kwargs) + except Exception: + elapsed_ms = (time.perf_counter() - start_time) * 1000 + log(logging.TRACE, f"← {func_name} (exception, {elapsed_ms:.2f}ms)") + raise + else: + elapsed_ms = (time.perf_counter() - start_time) * 1000 + log(logging.TRACE, f"← {func_name} ({elapsed_ms:.2f}ms)") + return result + return sync_wrapper # type: ignore[return-value] def exception(exc: Exception) -> None: diff --git a/src/ipsdk/platform.py b/src/ipsdk/platform.py index 318f6c6..1af2feb 100644 --- a/src/ipsdk/platform.py +++ b/src/ipsdk/platform.py @@ -230,6 +230,7 @@ async def create_workflow(name): from . import logging +@logging.trace def _make_oauth_headers() -> dict[str, str]: """ Create HTTP headers for OAuth token request. @@ -247,10 +248,10 @@ def _make_oauth_headers() -> dict[str, str]: Raises: None """ - logging.trace(_make_oauth_headers, modname=__name__) return {"Content-Type": "application/x-www-form-urlencoded"} +@logging.trace def _make_oauth_path() -> str: """ Get the URL path for OAuth token endpoint. @@ -267,10 +268,10 @@ def _make_oauth_path() -> str: Raises: None """ - logging.trace(_make_oauth_path, modname=__name__) return "/oauth/token" +@logging.trace def _make_oauth_body(client_id: str, client_secret: str) -> dict[str, str]: """ Create request body for OAuth client credentials authentication. @@ -289,7 +290,6 @@ def _make_oauth_body(client_id: str, client_secret: str) -> dict[str, str]: Raises: None """ - logging.trace(_make_oauth_body, modname=__name__) return { "grant_type": "client_credentials", "client_id": client_id, @@ -297,6 +297,7 @@ def _make_oauth_body(client_id: str, client_secret: str) -> dict[str, str]: } +@logging.trace def _make_basicauth_body(user: str, password: str) -> dict[str, dict[str, str]]: """ Create request body for basic username/password authentication. @@ -315,7 +316,6 @@ def _make_basicauth_body(user: str, password: str) -> dict[str, dict[str, str]]: Raises: None """ - logging.trace(_make_basicauth_body, modname=__name__) return { "user": { "username": user, @@ -324,6 +324,7 @@ def _make_basicauth_body(user: str, password: str) -> dict[str, dict[str, str]]: } +@logging.trace def _make_basicauth_path() -> str: """ Get the URL path for basic authentication endpoint. @@ -340,7 +341,6 @@ def _make_basicauth_path() -> str: Raises: None """ - logging.trace(_make_basicauth_path, modname=__name__) return "/login" @@ -357,11 +357,11 @@ class AuthMixin: client: httpx.Client token: str | None + @logging.trace def authenticate(self) -> None: """ Provides the authentication function for authenticating to the server """ - logging.trace(self.authenticate, modname=__name__, clsname=self.__class__) if self.client_id is not None and self.client_secret is not None: self.authenticate_oauth() elif self.user is not None and self.password is not None: @@ -375,11 +375,11 @@ def authenticate(self) -> None: logging.info("client connection successfully authenticated") + @logging.trace def authenticate_user(self) -> None: """ Performs authentication for basic authorization """ - logging.trace(self.authenticate_user, modname=__name__, clsname=self.__class__) logging.info("Attempting to perform basic authentication") if self.user is None or self.password is None: @@ -401,11 +401,11 @@ def authenticate_user(self) -> None: logging.exception(exc.message, exc) raise exceptions.RequestError(exc.message, exc) + @logging.trace def authenticate_oauth(self) -> None: """ Performs authentication for OAuth client credentials """ - logging.trace(self.authenticate_oauth, modname=__name__, clsname=self.__class__) logging.info("Attempting to perform oauth authentication") if self.client_id is None or self.client_secret is None: @@ -451,11 +451,11 @@ class AsyncAuthMixin: client: httpx.AsyncClient token: str | None + @logging.trace async def authenticate(self) -> None: """ Provides the authentication function for authenticating to the server """ - logging.trace(self.authenticate, modname=__name__, clsname=self.__class__) if self.client_id is not None and self.client_secret is not None: await self.authenticate_oauth() @@ -471,13 +471,11 @@ async def authenticate(self) -> None: logging.info("client connection successfully authenticated") + @logging.trace async def authenticate_basicauth(self) -> None: """ Performs authentication for basic authorization """ - logging.trace( - self.authenticate_basicauth, modname=__name__, clsname=self.__class__ - ) logging.info("Attempting to perform basic authentication") if self.user is None or self.password is None: @@ -499,11 +497,11 @@ async def authenticate_basicauth(self) -> None: logging.exception(exc.message, exc) raise exceptions.RequestError(exc.message, exc) + @logging.trace async def authenticate_oauth(self) -> None: """ Performs authentication for OAuth client credentials """ - logging.trace(self.authenticate_oauth, modname=__name__, clsname=self.__class__) logging.info("Attempting to perform oauth authentication") if self.client_id is None or self.client_secret is None: @@ -536,6 +534,7 @@ async def authenticate_oauth(self) -> None: AsyncPlatformType = AsyncPlatform +@logging.trace def platform_factory( host: str = "localhost", port: int = 0, @@ -595,8 +594,6 @@ def platform_factory( Returns: Platform: An initialized Platform connection instance. """ - logging.trace(platform_factory, modname=__name__) - factory = AsyncPlatform if want_async is True else Platform return factory( host=host, diff --git a/tests/test_logging.py b/tests/test_logging.py index b309e05..60b911c 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -1,6 +1,8 @@ # Copyright (c) 2025 Itential, Inc # GNU General Public License v3.0+ (see LICENSE or https://www.gnu.org/licenses/gpl-3.0.txt) +import asyncio +import contextlib import logging import sys @@ -30,7 +32,7 @@ def test_logging_constants_exist(self): def test_logging_constants_values(self): """Test that logging constants have correct values.""" assert ipsdk_logging.NOTSET == logging.NOTSET - assert ipsdk_logging.TRACE == logging.NOTSET # TRACE is aliased to NOTSET + assert ipsdk_logging.TRACE == 5 # TRACE is a custom level assert ipsdk_logging.DEBUG == logging.DEBUG assert ipsdk_logging.INFO == logging.INFO assert ipsdk_logging.WARNING == logging.WARNING @@ -143,40 +145,72 @@ class TestTraceFunction: """Test the trace logging function.""" def test_trace_function_with_callable(self): - """Test trace function logs function name.""" + """Test trace decorator logs function entry and exit with timing.""" with patch("ipsdk.logging.log") as mock_log: + @ipsdk_logging.trace def test_func(): - pass + return "result" - ipsdk_logging.trace(test_func) - mock_log.assert_called_once_with(logging.TRACE, "test_func") + result = test_func() + + assert result == "result" + assert mock_log.call_count == 2 + # Check that entry and exit were logged with correct symbols + calls = mock_log.call_args_list + assert any("→" in str(call) and "test_func" in str(call) for call in calls) + assert any("←" in str(call) and "test_func" in str(call) for call in calls) + # Check that exit includes timing information in milliseconds + exit_calls = [call for call in calls if "←" in str(call)] + assert len(exit_calls) == 1 + assert "ms)" in str(exit_calls[0]) def test_trace_function_with_different_functions(self): - """Test trace function with different function types.""" + """Test trace decorator with different function types.""" with patch("ipsdk.logging.log") as mock_log: + @ipsdk_logging.trace def regular_func(): - pass + return "regular" class TestClass: + @ipsdk_logging.trace def method(self): - pass + return "method" @staticmethod + @ipsdk_logging.trace def static_method(): - pass - - test_cases = [ - (regular_func, "regular_func"), - (TestClass.method, "method"), - (TestClass.static_method, "static_method"), - ] - - for func, expected_msg in test_cases: - mock_log.reset_mock() - ipsdk_logging.trace(func) - mock_log.assert_called_once_with(logging.TRACE, expected_msg) + return "static" + + # Test regular function + result = regular_func() + assert result == "regular" + assert mock_log.call_count == 2 + calls = mock_log.call_args_list + entry_found = any("→" in str(c) and "regular_func" in str(c) for c in calls) + exit_found = any("←" in str(c) and "regular_func" in str(c) for c in calls) + assert entry_found + assert exit_found + + # Test method + mock_log.reset_mock() + obj = TestClass() + result = obj.method() + assert result == "method" + assert mock_log.call_count == 2 + calls = mock_log.call_args_list + assert any("→" in str(call) and "method" in str(call) for call in calls) + assert any("←" in str(call) and "method" in str(call) for call in calls) + + # Test static method + mock_log.reset_mock() + result = TestClass.static_method() + assert result == "static" + assert mock_log.call_count == 2 + calls = mock_log.call_args_list + assert any("→" in str(c) and "static_method" in str(c) for c in calls) + assert any("←" in str(c) and "static_method" in str(c) for c in calls) class TestExceptionFunction: @@ -645,19 +679,60 @@ def test_actual_logging_output(self, caplog): assert any("critical message" in msg for msg in messages) def test_trace_function_integration(self, caplog): - """Test trace function with actual logging.""" + """Test trace decorator with actual logging.""" logger = ipsdk_logging.get_logger() logger.setLevel(logging.TRACE) logger.propagate = True + @ipsdk_logging.trace def test_function(): """Test function for tracing.""" + return "traced" with caplog.at_level(logging.TRACE, logger=metadata.name): - ipsdk_logging.trace(test_function) + result = test_function() + assert result == "traced" messages = [record.getMessage() for record in caplog.records] - assert any("test_function" in msg for msg in messages) + assert any("→" in msg and "test_function" in msg for msg in messages) + assert any("←" in msg and "test_function" in msg for msg in messages) + + def test_trace_async_function(self): + """Test trace decorator with async functions.""" + with patch("ipsdk.logging.log") as mock_log: + + @ipsdk_logging.trace + async def async_func(): + return "async_result" + + result = asyncio.run(async_func()) + + assert result == "async_result" + assert mock_log.call_count == 2 + calls = mock_log.call_args_list + assert any("→" in str(call) and "async_func" in str(call) for call in calls) + assert any("←" in str(call) and "async_func" in str(call) for call in calls) + + def test_trace_exception_handling(self): + """Test trace decorator logs exception exit with timing.""" + with patch("ipsdk.logging.log") as mock_log: + test_error_msg = "test error" + + @ipsdk_logging.trace + def error_func(): + raise ValueError(test_error_msg) + + with contextlib.suppress(ValueError): + error_func() + + assert mock_log.call_count == 2 + calls = mock_log.call_args_list + assert any("→" in str(call) and "error_func" in str(call) for call in calls) + # Check that exception exit includes both "exception" and timing + exit_calls = [call for call in calls if "←" in str(call)] + assert len(exit_calls) == 1 + assert "exception" in str(exit_calls[0]) + assert "ms)" in str(exit_calls[0]) class TestFormatString: