logging references
This commit is contained in:
John Lancaster
@@ -0,0 +1,277 @@
|
||||
# Network Logging Minimal Example
|
||||
|
||||
Use this reference when an application needs to send Python logs across a network to a receiver process. The example is intentionally small, but it keeps the important production-shaped boundaries: application modules use normal named loggers, startup code configures routing once, network I/O happens away from the caller path, and the receiver owns final formatting and destinations.
|
||||
|
||||
Source docs to keep nearby:
|
||||
|
||||
- [Sending and receiving logging events across a network](https://docs.python.org/3/howto/logging-cookbook.html#sending-and-receiving-logging-events-across-a-network) for the standard socket-listener recipe.
|
||||
- [Dealing with handlers that block](https://docs.python.org/3/howto/logging-cookbook.html#dealing-with-handlers-that-block) for why `QueueHandler` and `QueueListener` belong in front of slow handlers.
|
||||
- [`SocketHandler`](https://docs.python.org/3/library/logging.handlers.html#sockethandler) for the built-in network handler and its pickle-based default wire format.
|
||||
- [`QueueHandler`](https://docs.python.org/3/library/logging.handlers.html#queuehandler) and [`QueueListener`](https://docs.python.org/3/library/logging.handlers.html#queuelistener) for queue-backed logging mechanics.
|
||||
- [`logging.makeLogRecord`](https://docs.python.org/3/library/logging.html#logging.makeLogRecord) for recreating a `LogRecord` from serialized fields.
|
||||
- [`socketserver`](https://docs.python.org/3/library/socketserver.html) for a tiny TCP receiver.
|
||||
- [logging configuration security considerations](https://docs.python.org/3/library/logging.config.html#security-considerations) for treating remote logging configuration and importable config objects as trusted inputs only.
|
||||
|
||||
## Minimal Topology
|
||||
|
||||
Run one receiver process near the final logging destination. Application processes send serialized records to it, and the receiver decides how those records are formatted, filtered, written, rotated, or forwarded.
|
||||
|
||||
```text
|
||||
application code -> named logger -> QueueHandler -> QueueListener -> JSON TCP handler -> receiver -> final handlers
|
||||
```
|
||||
|
||||
This shape is useful because network handlers can block. Even a socket handler can pause on DNS, connection setup, back pressure, or a slow collector. The queue keeps normal request, worker, or CLI code from doing that work directly.
|
||||
|
||||
It also keeps application code boring in the best way:
|
||||
|
||||
```python title="feature.py"
|
||||
import logging
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
def process_order(order_id: str) -> None:
|
||||
logger.info("Processing order %s", order_id)
|
||||
```
|
||||
|
||||
The feature module does not know whether logs go to a terminal, a file, a socket, or a collector. That decision belongs to application startup.
|
||||
|
||||
## Receiver
|
||||
|
||||
The receiver accepts newline-delimited JSON records, recreates `LogRecord` objects, and routes them through local logging configuration.
|
||||
|
||||
```python title="log_receiver.py"
|
||||
import json
|
||||
import logging
|
||||
import logging.config
|
||||
import socketserver
|
||||
|
||||
LOGGING = {
|
||||
"version": 1,
|
||||
"disable_existing_loggers": False,
|
||||
"formatters": {
|
||||
"console": {
|
||||
"format": "%(asctime)s %(levelname)s %(name)s %(message)s",
|
||||
"datefmt": "%Y-%m-%d %H:%M:%S",
|
||||
}
|
||||
},
|
||||
"handlers": {
|
||||
"console": {
|
||||
"class": "logging.StreamHandler",
|
||||
"formatter": "console",
|
||||
"stream": "ext://sys.stdout",
|
||||
}
|
||||
},
|
||||
"root": {"level": "INFO", "handlers": ["console"]},
|
||||
}
|
||||
|
||||
|
||||
class LogRecordHandler(socketserver.StreamRequestHandler):
|
||||
def handle(self) -> None:
|
||||
for line in self.rfile:
|
||||
try:
|
||||
payload = json.loads(line.decode("utf-8"))
|
||||
record = logging.makeLogRecord(payload)
|
||||
except Exception:
|
||||
logging.getLogger(__name__).exception("Dropped malformed log record")
|
||||
continue
|
||||
|
||||
logger = logging.getLogger(record.name)
|
||||
if logger.isEnabledFor(record.levelno):
|
||||
logger.handle(record)
|
||||
|
||||
|
||||
class LogRecordServer(socketserver.ThreadingTCPServer):
|
||||
allow_reuse_address = True
|
||||
|
||||
|
||||
def main() -> None:
|
||||
logging.config.dictConfig(LOGGING)
|
||||
with LogRecordServer(("127.0.0.1", 9020), LogRecordHandler) as server:
|
||||
logging.getLogger(__name__).info("Listening for log records")
|
||||
server.serve_forever()
|
||||
|
||||
|
||||
if __name__ == "__main__":
|
||||
main()
|
||||
```
|
||||
|
||||
### Receiver Mechanics
|
||||
|
||||
- `dictConfig` is local to the receiver. Client processes do not decide the final formatter, file handler, rotation policy, or downstream sink.
|
||||
- `makeLogRecord` rebuilds a logging record from plain fields. This is the same reconstruction step used by the cookbook socket receiver, but this example uses JSON instead of unpickling bytes from the network.
|
||||
- The receiver looks up `logging.getLogger(record.name)` so package-level logger names still route through the normal logging hierarchy.
|
||||
- The `isEnabledFor` check lets receiver-side logger levels suppress records before handlers run. Client-side filtering is still preferred when possible because it avoids wasted network traffic.
|
||||
- Binding to `127.0.0.1` makes the demo local-only. Binding to `0.0.0.0` changes the trust boundary and should be paired with network controls, authentication, or a real collector protocol.
|
||||
|
||||
## Client Configuration
|
||||
|
||||
Configure logging once at application startup. The root logger writes to a queue, and a listener thread sends records over TCP.
|
||||
|
||||
```python title="logging_config.py"
|
||||
import copy
|
||||
import json
|
||||
import logging
|
||||
import logging.handlers
|
||||
import queue
|
||||
import socket
|
||||
|
||||
|
||||
class PreservingQueueHandler(logging.handlers.QueueHandler):
|
||||
def prepare(self, record: logging.LogRecord) -> logging.LogRecord:
|
||||
copied = copy.copy(record)
|
||||
copied.message = copied.getMessage()
|
||||
copied.msg = copied.message
|
||||
copied.args = None
|
||||
|
||||
if copied.exc_info is not None and copied.exc_text is None:
|
||||
copied.exc_text = logging.Formatter().formatException(copied.exc_info)
|
||||
copied.exc_info = None
|
||||
|
||||
return copied
|
||||
|
||||
|
||||
class JsonTcpHandler(logging.Handler):
|
||||
def __init__(self, host: str, port: int, timeout: float = 2.0) -> None:
|
||||
super().__init__()
|
||||
self.host = host
|
||||
self.port = port
|
||||
self.timeout = timeout
|
||||
self._socket: socket.socket | None = None
|
||||
|
||||
def emit(self, record: logging.LogRecord) -> None:
|
||||
try:
|
||||
payload = self._payload_from_record(record)
|
||||
message = json.dumps(payload, separators=(",", ":")).encode("utf-8")
|
||||
self._send(message + b"\n")
|
||||
except Exception:
|
||||
self._close_socket()
|
||||
self.handleError(record)
|
||||
|
||||
def close(self) -> None:
|
||||
self._close_socket()
|
||||
super().close()
|
||||
|
||||
def _close_socket(self) -> None:
|
||||
if self._socket is not None:
|
||||
self._socket.close()
|
||||
self._socket = None
|
||||
|
||||
def _send(self, message: bytes) -> None:
|
||||
if self._socket is None:
|
||||
self._socket = socket.create_connection((self.host, self.port), self.timeout)
|
||||
self._socket.sendall(message)
|
||||
|
||||
def _payload_from_record(self, record: logging.LogRecord) -> dict[str, object]:
|
||||
payload: dict[str, object] = {
|
||||
"name": record.name,
|
||||
"levelno": record.levelno,
|
||||
"levelname": record.levelname,
|
||||
"pathname": record.pathname,
|
||||
"lineno": record.lineno,
|
||||
"funcName": record.funcName,
|
||||
"created": record.created,
|
||||
"process": record.process,
|
||||
"processName": record.processName,
|
||||
"threadName": record.threadName,
|
||||
"msg": record.getMessage(),
|
||||
"args": None,
|
||||
}
|
||||
if record.exc_text is not None:
|
||||
payload["exc_text"] = record.exc_text
|
||||
return payload
|
||||
|
||||
|
||||
def configure_logging(host: str = "127.0.0.1", port: int = 9020) -> logging.handlers.QueueListener:
|
||||
log_queue: queue.Queue[logging.LogRecord] = queue.Queue(maxsize=1000)
|
||||
queue_handler = PreservingQueueHandler(log_queue)
|
||||
network_handler = JsonTcpHandler(host, port)
|
||||
listener = logging.handlers.QueueListener(log_queue, network_handler, respect_handler_level=True)
|
||||
|
||||
root = logging.getLogger()
|
||||
root.setLevel(logging.INFO)
|
||||
root.handlers[:] = [queue_handler]
|
||||
|
||||
listener.start()
|
||||
return listener
|
||||
```
|
||||
|
||||
```python title="app.py"
|
||||
import logging
|
||||
|
||||
from logging_config import configure_logging
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
def main() -> None:
|
||||
listener = configure_logging()
|
||||
try:
|
||||
logger.info("Service started")
|
||||
logger.warning("Example warning from the client")
|
||||
finally:
|
||||
listener.stop()
|
||||
|
||||
|
||||
if __name__ == "__main__":
|
||||
main()
|
||||
```
|
||||
|
||||
Start `log_receiver.py` first, then run `app.py`. The receiver should print the records using its own formatter.
|
||||
|
||||
### Client Mechanics
|
||||
|
||||
- `PreservingQueueHandler` copies the record before mutating it for queue transfer. The standard `QueueHandler.prepare()` intentionally formats and strips unpickleable fields; overriding it is the documented escape hatch when the listener side needs custom serialization or exception text.
|
||||
- `queue.Queue(maxsize=1000)` makes back pressure visible. An unbounded queue is simpler, but a bounded queue forces a production decision about whether to drop, block, buffer elsewhere, or fail when the collector cannot keep up.
|
||||
- `QueueListener` owns the slow handler thread. It should be stopped during application shutdown so queued records are processed before exit.
|
||||
- `JsonTcpHandler` keeps a TCP connection open after the first event. That avoids a connection handshake per log record while keeping the example small enough to inspect.
|
||||
- `handleError()` preserves standard logging error behavior. In production, set an explicit policy for dropped records and collector outages rather than assuming logs always arrive.
|
||||
|
||||
## Rationale Behind The Pattern
|
||||
|
||||
### Use JSON Instead Of The Default Pickle Payload
|
||||
|
||||
The built-in `SocketHandler` sends a pickled record dictionary. That is convenient on a trusted local path, but unpickling network input is a poor default at a trust boundary. JSON is not a complete security boundary by itself, but it is inspectable, language-neutral, and avoids executing pickle payloads.
|
||||
|
||||
If you use `SocketHandler` anyway, override `makePickle()` with a safer encoding, sign payloads with a scheme such as HMAC, or keep the listener strictly inside a trusted local network.
|
||||
|
||||
### Put The Network Handler Behind A Queue
|
||||
|
||||
The cookbook explicitly calls out network handlers as potentially blocking. A queue is the smallest standard-library pattern that separates business code from slow handler work. This matters for web requests, async event loops, worker hot paths, and CLIs where the user should not wait on a collector timeout.
|
||||
|
||||
### Centralize Final Destinations In The Receiver
|
||||
|
||||
Multiple processes writing one file directly is a common source of garbled output, failed rotation, and confusing retention behavior. A receiver process serializes that responsibility: clients emit events, and one process writes or forwards them according to one logging configuration.
|
||||
|
||||
### Keep Logger Names Stable
|
||||
|
||||
Use module loggers such as `logging.getLogger(__name__)`. Do not create a logger per request, user, socket, tenant, or connection. Put those values in structured fields or formatted messages instead. Logger objects are singletons and are not freed during normal execution, so unbounded logger names become an avoidable memory and routing problem.
|
||||
|
||||
### Filter Early When Volume Matters
|
||||
|
||||
The receiver can filter records, but records already crossed the network by then. Set client-side logger or handler levels so routine `DEBUG` records are not serialized and transmitted unless the deployment is intentionally collecting them.
|
||||
|
||||
## Production Checklist
|
||||
|
||||
Before using this beyond a local demo:
|
||||
|
||||
1. Protect the receiver with a trusted network boundary, TLS, a VPN, mutual authentication, or a real log collector. Do not expose an unauthenticated logging port to untrusted clients.
|
||||
2. Decide the outage policy: drop records, block briefly, buffer locally, retry with backoff, or fail startup when the receiver is unavailable.
|
||||
3. Size the queue and choose the overflow behavior deliberately. The default `QueueHandler.enqueue()` uses `put_nowait()`, so a full bounded queue goes through `handleError()`.
|
||||
4. Include service, environment, instance, request, trace, or tenant identifiers when operators need cross-service correlation.
|
||||
5. Redact or avoid secrets before records leave the process.
|
||||
6. Escape or normalize untrusted newline-containing values if the final destination is line-oriented and vulnerable to log injection confusion.
|
||||
7. Load-test the receiver and validate shutdown behavior before relying on the logs during incidents.
|
||||
8. Prefer a managed collector, OpenTelemetry pipeline, syslog, container stdout collection, or platform-native logging when the deployment environment already provides one.
|
||||
|
||||
## Review Questions
|
||||
|
||||
Use these questions when reviewing network logging code:
|
||||
|
||||
- Does normal application code only call named loggers, without attaching handlers in feature modules?
|
||||
- Is network or file I/O behind a queue for web, async, worker, or high-throughput paths?
|
||||
- Is the wire format safe for the trust boundary, or does it rely on unpickling unauthenticated input?
|
||||
- Are logger and handler levels set so noisy records are filtered before crossing the network?
|
||||
- Is collector failure behavior explicit and tested?
|
||||
- Does shutdown stop the listener and flush the queue?
|
||||
- Are secrets, user-controlled newlines, and high-cardinality context handled deliberately?
|
||||
Reference in New Issue
Block a user