diff --git a/.gitignore b/.gitignore index 7fffda0..b5dfef7 100644 --- a/.gitignore +++ b/.gitignore @@ -167,4 +167,5 @@ logs/ # Documentation build documentation/build/ documentation/.docusaurus/ -documentation/node_modules/ \ No newline at end of file +documentation/node_modules/ +.gitbotrc.json diff --git a/CHANGELOG.md b/CHANGELOG.md index 57c997c..22cc68f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,23 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Added +- Async logging flush semantics documentation and shutdown patterns guide. +- New guides: `testing-patterns.md` (async logger testing), `common-pitfalls.md`. +- `AsyncConfig` validation with helpful error messages. +- Async logger test utilities: `wait_for_async_queue_drain`, `async_logger_with_teardown` fixture. +- Export of `shutdown_async_backend` from main `kakashi` package. + +### Changed +- README license reference corrected to LGPL-2.1. +- Expanded async-backends documentation with flush semantics and shutdown patterns. +- Deprecated legacy `AsyncLogger` (removal planned for v0.4.0); use `kakashi.core.async_interface.get_async_logger`. +- Type hints completed in `logger.py`, `async_interface.py`. +- Deprecations doc now documents dual async systems and migration path. + +### Fixed +- Session test teardown now shuts down both legacy and functional async backends. + ## [0.2.1] - 2026-02-05 ### Changed diff --git a/README.md b/README.md index 56080d6..2570537 100644 --- a/README.md +++ b/README.md @@ -64,7 +64,9 @@ kakashi/ │ ├── structured_logger.py # Structured logging support │ └── sinks.py # Output destination system ├── performance_tests/ # Performance validation -│ └── validate_performance.py +│ ├── test_performance.py +│ ├── test_api_compatibility.py +│ └── test_stability.py └── README.md # This file ``` @@ -72,6 +74,14 @@ kakashi/ ### Basic Usage +**Tip:** For production apps using async logging, register shutdown at startup to prevent message loss: + +```python +import atexit +from kakashi import shutdown_async_logging, shutdown_async_backend +atexit.register(shutdown_async_backend) # For functional async; use shutdown_async_logging for legacy +``` + ```python from kakashi import get_logger, get_async_logger @@ -131,7 +141,8 @@ Run the performance validation to ensure your installation meets production targ ```bash cd performance_tests -python validate_performance.py +pip install -r requirements.txt +python -m pytest test_performance.py -v --benchmark-only ``` This will test: @@ -199,19 +210,35 @@ This will test: ## 🚨 Migration from v0.1.x -The v0.2.0 release maintains backward compatibility while providing significant performance improvements: +The v0.2.x release maintains backward compatibility while providing significant performance improvements: ```python # Old v0.1.x code (still works) -from kakashi import setup, get_logger -setup("production") +from kakashi import setup_logging, get_logger +setup_logging("production") logger = get_logger(__name__) -# New v0.2.0 code (recommended) +# New v0.2.x code (recommended) from kakashi import get_logger logger = get_logger(__name__) # Auto-configuration ``` +### Async Logger Migration + +```python +# Legacy (will be deprecated) +from kakashi import get_async_logger, shutdown_async_logging +logger = get_async_logger(__name__) +# ... use logger ... +shutdown_async_logging() + +# Functional (recommended) +from kakashi.core.async_interface import get_async_logger, shutdown_async_backend +logger = get_async_logger(__name__) # Same name, different implementation +# ... use logger ... +shutdown_async_backend(timeout=5.0) +``` + ## 🧭 Roadmap & Collaboration We are looking for collaborators to help build the next evolution of Kakashi: @@ -235,7 +262,7 @@ We welcome contributions! Please see our [Contributing Guide](CONTRIBUTING.md) f ## 📄 License -This project is licensed under the MIT License - see the [LICENSE](LICENSE) file for details. +This project is licensed under the LGPL-2.1 License - see the [LICENSE](LICENSE) file for details. ## ⚖️ Legal Disclaimers @@ -262,4 +289,4 @@ This project is licensed under the MIT License - see the [LICENSE](LICENSE) file --- -**Kakashi v0.2.0** - Professional High-Performance Logging for Python +**Kakashi v0.2.1** - Professional High-Performance Logging for Python diff --git a/documentation/docs/api/core.md b/documentation/docs/api/core.md index 15812ba..85531ee 100644 --- a/documentation/docs/api/core.md +++ b/documentation/docs/api/core.md @@ -97,7 +97,7 @@ class AsyncLogger: def critical(self, message: str, **fields: Any) -> None def exception(self, message: str, **fields: Any) -> None - def flush(self) -> None + def flush(self) -> None # Best effort only - see below ``` **Key Features:** @@ -106,6 +106,8 @@ class AsyncLogger: - Batch processing for optimal throughput - Graceful shutdown with proper cleanup +**Warning - `flush()` semantics:** `AsyncLogger.flush()` is best-effort only. It sleeps 1ms to yield to the background worker but does NOT guarantee that queued messages have been written. For durability guarantees at shutdown, use `shutdown_async_logging()` or `shutdown_async_backend(timeout=...)` instead. + ## Utility Functions ### `clear_logger_cache()` diff --git a/documentation/docs/guides/async-backends.md b/documentation/docs/guides/async-backends.md index ac7af27..7a93213 100644 --- a/documentation/docs/guides/async-backends.md +++ b/documentation/docs/guides/async-backends.md @@ -167,6 +167,16 @@ def setup_analytics_logging(): return logger ``` +### Flush Semantics (Important) + +**`flush()` on async loggers does NOT guarantee durability.** + +- **Legacy AsyncLogger** (from `kakashi.core.logger`): `flush()` only sleeps 1ms to yield to the background worker. It does **not** wait for queued messages to be written. +- **Functional async loggers** (from `kakashi.core.async_interface`): There is no `flush()` that drains the queue. Messages are processed asynchronously in batches. +- **Only `shutdown_async_backend(timeout=...)` guarantees** that all queued messages are processed before the process exits. This is the ONLY way to ensure no message loss at shutdown. + +**Do not rely on `flush()` for application logic.** Treat async logging as best-effort telemetry. For critical audit trails or state, write to a reliable store (database, message queue) and log secondarily. + ### Error Handling and Recovery ```python @@ -181,27 +191,45 @@ def graceful_shutdown(): print(f"Error during shutdown: {e}") ``` -### Best Practices +### Application Shutdown Patterns -1. **Queue Sizing**: Start with 25,000-50,000 max queue size, adjust based on throughput -2. **Worker Count**: Use 2-4 workers for most applications, 8+ for extreme throughput -3. **Batch Sizing**: Start with 200-500 batch size, increase for higher throughput -4. **Monitoring**: Monitor queue sizes and worker health in production -5. **Error Handling**: Implement graceful shutdown to prevent message loss -6. **Graceful Shutdown**: Ensure all queued messages are processed on shutdown +**You must call `shutdown_async_backend()` at application exit** to prevent message loss. If the process exits without shutdown, queued messages may never be written. + +#### Recommended: Register with atexit ```python import atexit from kakashi.core.async_interface import shutdown_async_backend -# Register shutdown handler +# Register early (e.g. at startup) atexit.register(shutdown_async_backend) -# Or manually at exit: -def cleanup(): - shutdown_async_backend(timeout=10.0) +# Or with custom timeout for high-volume apps: +atexit.register(lambda: shutdown_async_backend(timeout=10.0)) ``` +#### Timeout Considerations + +- **Default (5s)**: Suitable for most applications +- **High-volume**: Use 10-30s if you expect large queues or slow disk/network I/O +- **Tests**: Use shorter timeouts (1-2s) to avoid hanging test suites +- If timeout is exceeded, some messages may be dropped during shutdown + +#### What Happens Without Shutdown + +- Worker threads are daemon threads in some configurations; the process can exit before the queue drains +- Even with non-daemon workers, abrupt exit (SIGKILL, `os._exit`) bypasses atexit +- Result: silent message loss. Always register shutdown for production services. + +### Best Practices + +1. **Queue Sizing**: Start with 25,000-50,000 max queue size, adjust based on throughput +2. **Worker Count**: Use 2-4 workers for most applications, 8+ for extreme throughput +3. **Batch Sizing**: Start with 200-500 batch size, increase for higher throughput +4. **Monitoring**: Monitor queue sizes and worker health in production +5. **Error Handling**: Implement graceful shutdown to prevent message loss +6. **Graceful Shutdown**: Ensure all queued messages are processed on shutdown (see Application Shutdown Patterns above) + --- *Last updated: 2025-08-27* diff --git a/documentation/docs/guides/common-pitfalls.md b/documentation/docs/guides/common-pitfalls.md new file mode 100644 index 0000000..217857c --- /dev/null +++ b/documentation/docs/guides/common-pitfalls.md @@ -0,0 +1,153 @@ +--- +id: common-pitfalls +title: Common Pitfalls with Async Loggers +--- + +## Overview + +This guide documents common mistakes when using Kakashi's async logging and how to avoid them. + +## 1. Relying on `flush()` for Durability + +**Wrong**: Assuming `flush()` waits for all queued messages to be written. + +```python +async_logger.info("Critical audit event") +async_logger.flush() # Does NOT guarantee durability! +# Message may still be in queue - process could exit before it's written +``` + +**Why**: `AsyncLogger.flush()` only sleeps 1ms to yield to the background worker. Functional async loggers have no `flush()` that drains the queue. + +**Right**: Call `shutdown_async_backend(timeout=...)` at application exit. + +```python +import atexit +from kakashi.core.async_interface import shutdown_async_backend +atexit.register(shutdown_async_backend) +``` + +--- + +## 2. Not Shutting Down Async Backends + +**Wrong**: Letting the process exit without calling shutdown. + +```python +# main.py +logger = get_async_logger(__name__) +logger.info("Server stopping") +# Process exits - queued messages are lost +``` + +**Why**: Worker threads may not get CPU time to drain the queue before the process exits. Daemon threads are terminated immediately. + +**Right**: Register shutdown with atexit or call it explicitly before exit. + +```python +atexit.register(lambda: shutdown_async_backend(timeout=10.0)) +``` + +--- + +## 3. Using Async Loggers in Tests Without Cleanup + +**Wrong**: Asserting on log output immediately after async logging. + +```python +def test_login(): + logger = get_async_logger("auth") + logger.info("User logged in", user_id="123") + assert "User logged in" in open("app.log").read() # Flaky - message may not be written yet +``` + +**Why**: Messages are enqueued asynchronously. The assertion runs before the worker processes the queue. + +**Right**: Shut down the backend before asserting, or use a sync logger for this test. + +```python +def test_login(): + logger = get_async_logger("auth") + logger.info("User logged in", user_id="123") + shutdown_async_backend(timeout=2.0) + assert "User logged in" in open("app.log").read() +``` + +See [Testing Patterns](/docs/guides/testing-patterns) for more. + +--- + +## 4. Queue Overflow and Silent Message Drops + +**Wrong**: Assuming every log call results in a written message. + +```python +# High throughput - queue fills up +for i in range(1_000_000): + logger.info("Event", id=i) # Some messages may be dropped +``` + +**Why**: When the queue is full, the configured overflow strategy (e.g. `drop_oldest`) causes silent drops. There is no exception. + +**Right**: Monitor queue size via `get_async_stats()`, size the queue appropriately, and treat async logging as best-effort for non-critical telemetry. + +```python +stats = get_async_stats() +if stats.get("queue_size", 0) > 0.8 * stats.get("max_queue_size", 1): + # Consider backpressure or alerting + pass +``` + +--- + +## 5. Mixing Legacy and Functional Async APIs + +**Wrong**: Calling both shutdown functions and getting confused about which backend is active. + +```python +from kakashi import get_async_logger, shutdown_async_logging +from kakashi.core.async_interface import get_async_logger as get_func_async, shutdown_async_backend + +# Two different systems - easy to mix up +legacy = get_async_logger("a") +func = get_func_async("b") +# Which shutdown drains which queue? +``` + +**Why**: Kakashi has two separate async implementations. Each has its own queue and shutdown. + +**Right**: Stick to one system. For new code, use the functional API throughout. + +```python +from kakashi.core.async_interface import get_async_logger, shutdown_async_backend +logger = get_async_logger(__name__) +# ... +shutdown_async_backend() +``` + +--- + +## 6. Blocking on Full Queue with Default Config + +**Wrong**: Assuming `put` always succeeds; in `block` mode a full queue can block the calling thread. + +```python +# Default overflow_strategy is "block" +for i in range(100_000): + logger.info("x") # Can block indefinitely if workers are slow +``` + +**Right**: For high-throughput or latency-sensitive paths, use `queue_overflow_strategy="drop_oldest"` and accept potential drops, or increase queue size and worker count. + +--- + +## Summary + +| Pitfall | Mitigation | +|---------|------------| +| Relying on `flush()` | Use `shutdown_async_backend()` at exit | +| No shutdown | Register `atexit.register(shutdown_async_backend)` | +| Flaky tests | Shut down before asserting, or use sync logger | +| Queue overflow | Monitor stats, size queue, treat as best-effort | +| Mixing APIs | Use functional async only for new code | +| Blocking on full queue | Use `drop_oldest` or increase capacity | diff --git a/documentation/docs/guides/testing-patterns.md b/documentation/docs/guides/testing-patterns.md new file mode 100644 index 0000000..ce3294a --- /dev/null +++ b/documentation/docs/guides/testing-patterns.md @@ -0,0 +1,179 @@ +--- +id: testing-patterns +title: Testing Patterns for Async Loggers +--- + +## Overview + +Testing applications that use async logging requires care. Async loggers enqueue messages to a background queue; if tests exit before the queue drains, logs may not be written and assertions can fail or become flaky. + +## When to Use Sync vs Async Loggers in Tests + +### Use Sync Loggers When + +- You need to assert on log output immediately +- The test checks that specific log lines were written +- You want deterministic, non-flaky tests +- Testing log format or content + +```python +from kakashi import get_logger + +def test_user_login_logged(): + """Sync logger: output is immediate, assertions work reliably.""" + logger = get_logger("auth") + logger.info("User logged in", user_id="123") + + # Log is already written; safe to assert on file content + assert "User logged in" in open("logs/app.log").read() +``` + +### Use Async Loggers When + +- You are testing async logging behavior itself +- Performance benchmarks +- Integration tests where log content is not asserted +- When you explicitly shut down the backend before asserting + +## Proper Async Backend Shutdown in Tests + +### Functional Async (Pipeline-Based) + +For loggers created via `get_async_logger`, `get_high_performance_logger`, or `get_async_structured_logger` from `kakashi.core.async_interface`, use `shutdown_async_backend` in teardown: + +```python +import pytest +from kakashi.core.async_interface import get_async_logger, shutdown_async_backend + +@pytest.fixture +def async_logger(): + logger = get_async_logger("test.async") + yield logger + # Must shut down before test ends to drain queue + shutdown_async_backend(timeout=2.0) + +def test_async_logging(async_logger): + async_logger.info("Test message", key="value") + shutdown_async_backend(timeout=2.0) # Or in fixture teardown + # Now safe to assert on output +``` + +### Legacy Async (Simple AsyncLogger) + +For `AsyncLogger` from `kakashi.core.logger` (returned by `get_async_logger` from the main package when using the simple API): + +```python +import pytest +from kakashi import get_async_logger, shutdown_async_logging + +@pytest.fixture +def legacy_async_logger(): + logger = get_async_logger("test.legacy") + yield logger + shutdown_async_logging() + +def test_legacy_async(legacy_async_logger): + legacy_async_logger.info("Message") + shutdown_async_logging() # Drain before assert +``` + +## Waiting for Queue Drain + +If you cannot shut down (e.g. shared backend), you can poll `get_async_stats()` until the queue is empty. Use with care and a timeout to avoid hanging tests: + +```python +import time +from kakashi.core.async_interface import get_async_stats + +def wait_for_queue_drain(timeout: float = 5.0, poll_interval: float = 0.05) -> bool: + """Wait until async queue is empty or timeout.""" + start = time.time() + while time.time() - start < timeout: + stats = get_async_stats() + if stats.get("queue_size", 0) == 0: + return True + time.sleep(poll_interval) + return False + +def test_async_with_poll(async_logger): + async_logger.info("Message") + assert wait_for_queue_drain(timeout=2.0), "Queue did not drain" + # Now assert on output +``` + +## Example Test Fixtures + +### Fixture with Proper Cleanup + +```python +# conftest.py +import pytest +from kakashi.core.async_interface import ( + get_async_logger, + shutdown_async_backend, + get_async_stats, +) + +@pytest.fixture +def async_logger_with_teardown(): + """Async logger that shuts down cleanly after each test.""" + logger = get_async_logger("test.async") + yield logger + shutdown_async_backend(timeout=2.0) + +@pytest.fixture(scope="module") +def async_logger_module_scope(): + """Shared async logger for a module; shutdown once at end.""" + logger = get_async_logger("test.module") + yield logger + shutdown_async_backend(timeout=5.0) +``` + +### Testing with Temp Directory + +```python +import tempfile +from pathlib import Path +from kakashi.core.async_interface import get_async_logger, shutdown_async_backend + +def test_async_logs_to_file(): + with tempfile.TemporaryDirectory() as tmp: + log_path = Path(tmp) / "test.log" + logger = get_async_logger("test", log_file=str(log_path)) + logger.info("Written to file") + shutdown_async_backend(timeout=2.0) + + content = log_path.read_text() + assert "Written to file" in content +``` + +## Anti-Patterns to Avoid + +1. **Asserting immediately after logging** without shutdown or drain: + ```python + async_logger.info("x") + assert "x" in file_content # Flaky: message may still be in queue + ``` + +2. **Not shutting down in teardown** when using async loggers: + ```python + @pytest.fixture + def async_logger(): + return get_async_logger("test") # No teardown - messages can be lost + ``` + +3. **Relying on `flush()`** for async loggers: + ```python + async_logger.info("x") + async_logger.flush() # Does NOT wait for queue - still flaky + ``` + +4. **Using async logger when sync suffices** for content assertions: + Prefer sync loggers when you need to assert on log output. + +## Summary + +- Use sync loggers when asserting on log content. +- For async loggers, always call `shutdown_async_backend` (functional) or `shutdown_async_logging` (legacy) in teardown or before asserting. +- Optionally poll `get_async_stats()` for queue drain with a timeout. +- Never rely on `flush()` for durability in tests. diff --git a/documentation/docs/operations/deprecations.md b/documentation/docs/operations/deprecations.md index 54e07cf..2a3a5a6 100644 --- a/documentation/docs/operations/deprecations.md +++ b/documentation/docs/operations/deprecations.md @@ -3,6 +3,53 @@ id: deprecations title: Deprecations & Compatibility --- +## Two Async Logging Systems + +Kakashi provides **two separate async logging implementations**. Choose based on your needs: + +### 1. Legacy Async (Simple) + +- **Location**: `kakashi.core.logger.AsyncLogger` +- **Entry point**: `from kakashi import get_async_logger` (when using the main package logger API) +- **Characteristics**: Single global queue, fixed 10K capacity, writes to stderr, minimal configuration +- **Shutdown**: `shutdown_async_logging()` +- **Use when**: Simple scripts, quick prototypes, or when you need minimal setup +- **Status**: Will be deprecated in v0.3.0; use functional async for new code + +### 2. Functional Async (Pipeline-Based) + +- **Location**: `kakashi.core.async_interface` +- **Entry points**: `get_async_logger`, `get_async_structured_logger`, `get_high_performance_logger`, `get_network_logger` +- **Characteristics**: Configurable queue size, workers, batching, file/network sinks, structured JSON +- **Shutdown**: `shutdown_async_backend(timeout=...)` +- **Use when**: Production applications, high throughput, file/network logging, structured output +- **Status**: **Recommended for new code** + +### Which One Am I Using? + +- If you call `from kakashi import get_async_logger` and get an `AsyncLogger` (no `log_file` or `formatter_type`), you are using the **legacy** system. +- If you call `from kakashi.core.async_interface import get_async_logger` or use `get_structured_logger` with async config, you are using the **functional** system. + +### Migration Path + +```python +# Legacy (will be deprecated) +from kakashi import get_async_logger, shutdown_async_logging +logger = get_async_logger(__name__) +# ... use logger ... +shutdown_async_logging() + +# Functional (recommended) +from kakashi.core.async_interface import get_async_logger, shutdown_async_backend +logger = get_async_logger(__name__) # Same name, different implementation +# ... use logger ... +shutdown_async_backend(timeout=5.0) +``` + +--- + +## Other Deprecations + Legacy singleton-style API is maintained for compatibility but will be deprecated. Prefer the functional API via `kakashi.core` and top-level helpers. Legacy middleware names map to enterprise integrations: @@ -10,3 +57,10 @@ Legacy middleware names map to enterprise integrations: - FastAPI: `kakashi.setup_fastapi(app, ...)` - Flask: `kakashi.setup_flask(app, ...)` - Django: `kakashi.setup_django(...)` + +### Deprecation Timeline + +| Component | Deprecation (v0.3.0) | Removal (v0.4.0) | +|-----------|----------------------|------------------| +| Legacy `AsyncLogger` / `get_async_logger` from `kakashi` | Yes (use `kakashi.core.async_interface`) | Yes | +| Legacy singleton API | Yes | TBD | diff --git a/documentation/sidebars.ts b/documentation/sidebars.ts index ed1cdfc..adf9ac7 100644 --- a/documentation/sidebars.ts +++ b/documentation/sidebars.ts @@ -45,6 +45,8 @@ const sidebars: SidebarsConfig = { 'guides/web-integrations', 'guides/pipeline-composition', 'guides/async-backends', + 'guides/testing-patterns', + 'guides/common-pitfalls', ], }, { diff --git a/kakashi/__init__.py b/kakashi/__init__.py index fc8d643..0c35377 100644 --- a/kakashi/__init__.py +++ b/kakashi/__init__.py @@ -4,6 +4,10 @@ A modern, high-performance logging library designed for production applications that require both high throughput and excellent concurrency scaling. +Note: The legacy AsyncLogger (from get_async_logger in this package) is deprecated +and will be removed in v0.4.0. Use kakashi.core.async_interface.get_async_logger +for new code. See docs/operations/deprecations.md. + FEATURES: - High throughput (56K+ logs/sec) with superior concurrency scaling (1.17x) - Thread-safe operation with lock-free hot paths @@ -37,6 +41,10 @@ # ============================================================================ # MAIN LOGGER API # ============================================================================ +# Note: get_async_logger here is the legacy simple AsyncLogger (kakashi.core.logger). +# For pipeline-based async with configurable sinks, use kakashi.core.async_interface.get_async_logger. +# See documentation/docs/operations/deprecations.md for details. +# ============================================================================ # Main logger classes and entry points from .core.logger import ( @@ -77,6 +85,9 @@ create_custom_logger, clear_logger_cache ) +# Functional async interface (for pipeline-based async loggers) +from .core.async_interface import shutdown_async_backend + # ============================================================================ # VERSION AND METADATA # ============================================================================ @@ -131,7 +142,8 @@ "enable_bright_colors", "disable_colors", "create_custom_logger", - + "shutdown_async_backend", + # ---- VERSION AND METADATA ---- "__version__", "__author__", diff --git a/kakashi/core/async_backend.py b/kakashi/core/async_backend.py index 663f579..bdeac86 100644 --- a/kakashi/core/async_backend.py +++ b/kakashi/core/async_backend.py @@ -40,23 +40,60 @@ class AsyncConfig: # Queue settings max_queue_size: int = 10000 # Maximum messages in queue before blocking/dropping queue_overflow_strategy: str = "block" # "block", "drop_oldest", "drop_newest" - + # Worker thread settings worker_count: int = 1 # Number of worker threads batch_size: int = 100 # Messages to process in one batch batch_timeout: float = 0.1 # Max seconds to wait for batch to fill - + # Shutdown settings shutdown_timeout: float = 5.0 # Max seconds to wait for graceful shutdown - + # Error handling max_error_retries: int = 3 # Max retries for failed writes error_retry_delay: float = 0.1 # Delay between retries - + # Performance tuning enable_batching: bool = True # Enable message batching for efficiency thread_name_prefix: str = "AsyncLogger" # Prefix for worker thread names + def __post_init__(self) -> None: + """Validate configuration parameters.""" + if self.max_queue_size < 1: + raise ValueError( + f"max_queue_size must be >= 1, got {self.max_queue_size}" + ) + if self.max_queue_size > 1_000_000: + raise ValueError( + f"max_queue_size should typically be <= 1000000, got {self.max_queue_size}" + ) + if self.worker_count < 1: + raise ValueError( + f"worker_count must be >= 1, got {self.worker_count}" + ) + if self.worker_count > 64: + raise ValueError( + f"worker_count should typically be <= 64, got {self.worker_count}" + ) + if self.batch_size < 1: + raise ValueError( + f"batch_size must be >= 1, got {self.batch_size}" + ) + if self.batch_timeout <= 0: + raise ValueError( + f"batch_timeout must be > 0, got {self.batch_timeout}" + ) + if self.shutdown_timeout <= 0: + raise ValueError( + f"shutdown_timeout must be > 0, got {self.shutdown_timeout}" + ) + valid_strategies = ("block", "drop_oldest", "drop_newest") + if self.queue_overflow_strategy not in valid_strategies: + raise ValueError( + f"queue_overflow_strategy must be one of {valid_strategies}, " + f"got {self.queue_overflow_strategy!r}" + ) + class QueueMessage: """Message in the async queue.""" diff --git a/kakashi/core/async_interface.py b/kakashi/core/async_interface.py index 5a6a71a..8b05c70 100644 --- a/kakashi/core/async_interface.py +++ b/kakashi/core/async_interface.py @@ -5,7 +5,7 @@ loggers with various performance optimizations. """ -from typing import Optional, Dict, Any, Union +from typing import Optional, Dict, Any, Union, Callable from pathlib import Path from .config import ( @@ -59,6 +59,11 @@ def get_async_logger( # Custom async configuration config = AsyncConfig(max_queue_size=20000, worker_count=3) logger = get_async_logger("high_volume", async_config=config) + + Note: + There is no flush() that guarantees durability. For durability at + application exit, call shutdown_async_backend(timeout=...) (e.g. via + atexit). See shutdown_async_backend for details. """ # Get current environment config and force async env_config = get_environment_config() @@ -142,7 +147,7 @@ def get_high_performance_logger( def get_network_logger( name: str, - network_writer_func: callable, + network_writer_func: Callable[[str], None], max_queue_size: int = 20000, batch_size: int = 100, max_retries: int = 5 @@ -380,17 +385,19 @@ def get_async_stats() -> Dict[str, Any]: def shutdown_async_backend(timeout: float = 5.0) -> None: """ Gracefully shutdown the async logging backend. - - This ensures all queued messages are processed before shutdown. - Call this at application exit to prevent message loss. - + + This is the ONLY way to guarantee all queued messages are processed before + the process exits. Without calling this at shutdown, queued messages may + be lost. + Args: - timeout: Maximum time to wait for shutdown - + timeout: Maximum time to wait for shutdown (seconds). Increase for + high-volume applications or slow I/O. + Example: import atexit atexit.register(shutdown_async_backend) - + # Or manually at exit: shutdown_async_backend(timeout=10.0) """ diff --git a/kakashi/core/logger.py b/kakashi/core/logger.py index 0681927..c0bb883 100644 --- a/kakashi/core/logger.py +++ b/kakashi/core/logger.py @@ -16,7 +16,7 @@ import time import sys import queue -from typing import Optional, Dict, Any +from typing import Optional, Dict, Any, List, Tuple # Pre-computed constants for fast access _LEVEL_NAMES = { @@ -39,7 +39,7 @@ -def _async_worker_thread(): +def _async_worker_thread() -> None: """Background worker for async logging.""" batch = [] batch_size = 50 # Optimal batch size for throughput/latency balance @@ -78,7 +78,7 @@ def _async_worker_thread(): pass # Ignore errors in background thread -def _process_async_batch(batch): +def _process_async_batch(batch: List[Tuple[float, int, str, str, Optional[Dict[str, Any]]]]) -> None: """Process a batch of async log messages.""" try: # Use sys.stderr.write for better async performance @@ -101,7 +101,7 @@ def _process_async_batch(batch): pass # Ignore errors in async processing -def _ensure_async_worker(): +def _ensure_async_worker() -> None: """Ensure async worker thread is running.""" global _async_worker if _async_worker is None or not _async_worker.is_alive(): @@ -119,8 +119,10 @@ class LogFormatter: def __init__(self): pass - def format_message(self, level: int, message: str, logger_name: str, - fields: Optional[Dict[str, Any]] = None) -> str: + def format_message( + self, level: int, message: str, logger_name: str, + fields: Optional[Dict[str, Any]] = None + ) -> str: """Format log message with optimal concurrency performance.""" timestamp = int(time.time()) level_name = _LEVEL_NAMES.get(level, 'UNKNOWN') @@ -151,7 +153,7 @@ def __init__(self, name: str, min_level: int = 20): self.min_level = min_level self.formatter = LogFormatter() - def _get_thread_batch(self): + def _get_thread_batch(self) -> List[str]: """Get thread-local batch for efficient I/O.""" if not hasattr(_thread_local, 'batch'): _thread_local.batch = [] @@ -175,7 +177,7 @@ def _log(self, level: int, message: str, fields: Optional[Dict[str, Any]] = None self._flush_batch(batch) batch.clear() - def _flush_batch(self, batch): + def _flush_batch(self, batch: List[str]) -> None: """Flush batch to stderr efficiently.""" try: # Single write call for entire batch @@ -228,18 +230,30 @@ def flush(self) -> None: class AsyncLogger: """ True asynchronous logger with background processing. - + + .. deprecated:: 0.3.0 + This legacy AsyncLogger will be removed in v0.4.0. Use + :func:`kakashi.core.async_interface.get_async_logger` for new code. + See docs/operations/deprecations.md for migration. + Key features: - Non-blocking enqueue operation - Background worker thread for I/O - Batch processing for efficiency - Superior throughput vs sync logging """ - + def __init__(self, name: str, min_level: int = 20): + import warnings + warnings.warn( + "AsyncLogger from kakashi.core.logger is deprecated and will be removed in v0.4.0. " + "Use kakashi.core.async_interface.get_async_logger for new code.", + DeprecationWarning, + stacklevel=2, + ) self.name = name self.min_level = min_level - + # Ensure async worker is running _ensure_async_worker() @@ -291,9 +305,12 @@ def exception(self, message: str, **fields) -> None: self._log_async(40, message, fields) def flush(self) -> None: - """Flush pending messages (best effort).""" - # For async logger, we can't force immediate flush - # but we can yield to allow background processing + """Flush pending messages (best effort only). + + Does NOT guarantee that queued messages have been written. This method + only sleeps briefly to yield to the background worker. For durability + guarantees at shutdown, use shutdown_async_logging() instead. + """ time.sleep(0.001) diff --git a/performance_tests/conftest.py b/performance_tests/conftest.py index ddd969e..862db6d 100644 --- a/performance_tests/conftest.py +++ b/performance_tests/conftest.py @@ -22,6 +22,11 @@ def cleanup_async_logging(): yield from kakashi import shutdown_async_logging shutdown_async_logging() + try: + from kakashi.core.async_interface import shutdown_async_backend + shutdown_async_backend(timeout=2.0) + except ImportError: + pass @pytest.fixture(scope="session") def temp_test_dir() -> Generator[Path, None, None]: @@ -137,3 +142,53 @@ def kakashi_structured_logger(): """Create a fresh Kakashi structured logger for each test.""" from kakashi.core import create_structured_logger return create_structured_logger("test_structured_logger") + + +# ============================================================================= +# Async logger test utilities +# ============================================================================= + +def wait_for_async_queue_drain( + timeout: float = 5.0, + poll_interval: float = 0.05, +) -> bool: + """ + Wait until the functional async backend queue is empty or timeout. + + Use before asserting on log output when using async loggers. + + Returns: + True if queue drained, False if timeout reached. + """ + import time + try: + from kakashi.core.async_interface import get_async_stats + except ImportError: + return False + start = time.time() + while time.time() - start < timeout: + stats = get_async_stats() + if stats.get("queue_size", 0) == 0: + return True + time.sleep(poll_interval) + return False + + +@pytest.fixture +def async_logger_with_teardown(): + """ + Functional async logger that shuts down cleanly after each test. + + Use for tests that need async logging and must drain the queue + before asserting on output. + """ + try: + from kakashi.core.async_interface import ( + get_async_logger, + shutdown_async_backend, + ) + except ImportError: + pytest.skip("kakashi.core.async_interface not available") + logger = get_async_logger("test.async_teardown") + yield logger + shutdown_async_backend(timeout=2.0)