diff --git a/README.md b/README.md index b071ba8..301001e 100644 --- a/README.md +++ b/README.md @@ -140,6 +140,35 @@ Three constraints are worth knowing before holding a transaction open: calls on it say so, and `rollback()` raises instead of promising a discard. Verify the data rather than blindly retrying, which can duplicate the writes. +## Finding the Slow Query's Author + +The server's query advisor groups what it measures by the shape of the query, +which is why its report can name a statement but not the place that wrote it: +one line of Cypher usually has a dozen call sites. Turn on source tracking and +each query carries the file, line and function it was written at, so the report +names the line instead. + +```python +client = CoordinodeClient( + "localhost:7080", + debug_source_tracking=True, + app_name="feed-service", # optional, for when services share a database + app_version="2.1.0", +) +``` + +It is off by default and free while off: no frame is read and the request goes +out exactly as it would have. Turn it on where you are looking rather than +everywhere, because what it sends is the paths of your source files. + +The location is read when you call the method, not when the query runs, so +concurrency does not lose it: `create_task`, `gather`, `wait_for`, `shield` and +`TaskGroup` all start the coroutine long after the calling frame has returned, +and all of them still report the line you wrote. Anything outside printable +ASCII is escaped rather than sent raw — a non-ASCII path, but a newline or a +tab just as much, since gRPC refuses those in a header too and would fail the +query rather than the attribution. + ## LangChain — GraphRAG Pipeline ```python diff --git a/coordinode/coordinode/_source.py b/coordinode/coordinode/_source.py new file mode 100644 index 0000000..bf7b780 --- /dev/null +++ b/coordinode/coordinode/_source.py @@ -0,0 +1,199 @@ +"""Call-site attribution for queries. + +When a client is built with ``debug_source_tracking=True``, every query it +sends carries the source location it was written at. The server's query +advisor groups statistics by query shape, and this is what lets it name the +line that wrote the slow one rather than only the query text, which is +usually identical across a dozen call sites. + +Off by default, and off means untouched: no frame is read, no metadata is +built, nothing is sent. The cost of the feature is paid only where somebody +asked for it. + +The metadata keys are the wire contract shared with the Rust driver: + +===================== ========================================== +``x-source-file`` path of the file the call was written in +``x-source-line`` line number, as a string +``x-source-function`` qualified name of the enclosing function +``x-source-app`` application name, when one was configured +``x-source-version`` application version, when one was configured +===================== ========================================== + +``x-source-function`` is the one key the Rust driver leaves empty: it reads +the caller through ``#[track_caller]``, and a ``Location`` there carries no +function name. A Python frame does, so this driver fills it in. +""" + +from __future__ import annotations + +import asyncio +import os +import sys +from types import FrameType +from typing import NamedTuple + +# Directories whose frames are never a call site. This package is the obvious +# one; asyncio is here because a query started with create_task runs its body +# after the frame that started it has gone, leaving an event-loop frame in its +# place. See is_call_site. +# The separator is part of each prefix so that a directory merely NAMED like +# one of these ("coordinode-extra" beside "coordinode") is not swallowed too. +_NOT_CALL_SITES = ( + os.path.dirname(os.path.abspath(__file__)) + os.sep, + os.path.dirname(os.path.abspath(asyncio.__file__)) + os.sep, +) + + +class SourceLocation(NamedTuple): + """Where a query was written: the file, line and enclosing function.""" + + file: str + line: int + function: str + + +def is_call_site(location: SourceLocation) -> bool: + """Whether *location* is somewhere a person could have written the query. + + A location inside this package or inside asyncio is not: it is what is + left on the stack when the frame that wrote the query is already gone, + which happens to a query handed to ``create_task`` and awaited later. + Reporting it would not merely be useless. The advisor groups its + statistics by call site, so one event-loop line would collect the queries + of every unrelated task that took that path and present them as one place + in the code, which is worse than the feature being quiet. + """ + # A frame's filename is normally already absolute, and making one absolute + # is not free: for a relative path it asks the OS for the working + # directory, which would be a syscall on every query. + path = location.file if os.path.isabs(location.file) else os.path.abspath(location.file) + return not path.startswith(_NOT_CALL_SITES) + + +def capture(levels_up: int) -> SourceLocation | None: + """Read the frame *levels_up* above this function's caller. + + Reading one frame directly is what keeps this cheap. The alternative, + ``inspect.stack()``, walks the whole stack and opens each frame's source + file to quote the lines around it: a file system round trip per frame, to + answer a question about one of them. + + ``None`` comes back when the frame cannot be had — an interpreter with no + Python-level frame support, a stack shorter than the walk, or a hardened + application whose audit hook refuses the ``sys._getframe`` event, or the + ``object.__getattr__`` one that reading the frame's own attributes + raises, and answers with whatever exception it likes. Every one of those + is the same thing to a caller: no location. None of them is worth failing + a query over, which is why the whole read is caught broadly rather than + by the ValueError a short stack happens to give. + """ + getframe = getattr(sys, "_getframe", None) + if getframe is None: + return None + try: + # +1 for this frame, which the caller counts from rather than into. + frame: FrameType = getframe(levels_up + 1) + # Reading the frame's attributes is guarded with the read of the frame + # itself, because it is a second thing an audit hook can refuse: + # CPython raises `object.__getattr__` when `f_code` is read, separately + # from the `sys._getframe` event, and a hook may object to either. Both + # leave the same nothing behind, and neither is worth a failed query. + code = frame.f_code + return SourceLocation( + file=code.co_filename, + line=frame.f_lineno, + # Qualified, so a method reads as "Class.method" rather than a bare + # name that says nothing about which class it belongs to. + function=code.co_qualname, + ) + except Exception: + return None + + +def _header_safe(value: str) -> str: + """*value* with everything gRPC would refuse escaped out. + + A metadata key without the ``-bin`` suffix carries an HTTP/2 header value, + and gRPC enforces the permitted range on the client: a value outside + printable ASCII fails the call before it is sent, so an unescaped one + would make a debugging aid the reason every query fails. + + The bar is printable ASCII, not ASCII. A newline, a tab, a NUL and 0x7f + are each refused the same way a non-ASCII character is, and the likeliest + source of one is mundane: an application name read from a file arrives + with the newline that ended it. A POSIX path may legally contain one too. + + The encoding is injective, which matters more than it looks: two call + sites arriving as one string would not merely lose detail, they would be + reported as one place in the code, with the queries of one attributed to + the other. Two things buy that. The escape character escapes itself, so a + name holding a real newline differs from one holding the characters that + spell its escape. And each form is padded to a fixed width, so a character + outside the basic plane cannot spell the same thing as one inside it + followed by a digit. + + Escaped rather than dropped, because an escaped path still names the file + and still groups with itself in the advisor, which is the whole job. + """ + # Three single scans in C, and together they say "every character is in + # 0x20..0x7e, and none of them is the escape character": isascii rules out + # the rest of Unicode, isprintable rules out the control characters and + # 0x7f while counting the space as printable, and a value with no + # backslash cannot collide with an escaped one. + if value.isascii() and value.isprintable() and "\\" not in value: + return value + return "".join(_escape(ch) for ch in value) + + +def _escape(ch: str) -> str: + """One character as itself, or as a fixed-width escape. See _header_safe.""" + if ch == "\\": + return "\\\\" + if " " <= ch <= "~": + return ch + point = ord(ch) + if point < 0x100: + return f"\\x{point:02x}" + if point < 0x10000: + return f"\\u{point:04x}" + return f"\\U{point:08x}" + + +def identity(app_name: str, app_version: str) -> tuple[tuple[str, str], ...]: + """The metadata naming the application, built once per client. + + It cannot change after the client is constructed, so building it per query + would be the same work repeated for every statement the client ever sends. + + Either part may be left out, and an empty one gets no header: the server + reads a missing key and an empty value the same way, so the header would + carry nothing. + """ + pairs = [] + if app_name: + pairs.append(("x-source-app", _header_safe(app_name))) + if app_version: + pairs.append(("x-source-version", _header_safe(app_version))) + return tuple(pairs) + + +def to_metadata( + location: SourceLocation | None, + app_identity: tuple[tuple[str, str], ...], +) -> tuple[tuple[str, str], ...]: + """Build the gRPC metadata for *location*, empty when there is none. + + The application identity rides along with the location rather than on its + own: the server reads them as one source context and discards the whole + context when the file is missing, so sending the identity alone would put + it on the wire for nothing. + """ + if location is None: + return () + return ( + ("x-source-file", _header_safe(location.file)), + # The line is an integer, so its decimal form is ASCII already. + ("x-source-line", str(location.line)), + ("x-source-function", _header_safe(location.function)), + ) + app_identity diff --git a/coordinode/coordinode/client.py b/coordinode/coordinode/client.py index 77ad413..3e5bc17 100644 --- a/coordinode/coordinode/client.py +++ b/coordinode/coordinode/client.py @@ -5,6 +5,8 @@ from __future__ import annotations import asyncio +import functools +import inspect import logging import re from collections.abc import AsyncIterator, Iterator, Sequence @@ -14,6 +16,7 @@ import grpc import grpc.aio +from coordinode import _source from coordinode._types import ( PyValue, dict_to_props, @@ -135,6 +138,113 @@ def _make_channel(host: str, port: int, tls: bool) -> grpc.Channel: return grpc.insecure_channel(target) +def _without_self(fn: Any) -> Any: + """*fn* again, advertising the parameters a caller actually passes. + + Only for reaching the method through the CLASS, which is how + `unittest.mock.create_autospec` reads it. A descriptor that is not a plain + function is not recognised as a method there, so `self` is left in and the + first real argument binds to it — an autospecced call then reports the + wrong argument missing. + + It has to be a separate object. Rewriting the original function's own + signature would be read again every time Python binds the method, taking + the first REMAINING parameter off with it: `client.cypher` would advertise + itself as taking no `query`, and anything inspecting a bound callable to + validate arguments, inject dependencies or generate a wrapper would build + that interface. The original therefore keeps its true signature, which is + the one every binding is derived from. + + Calling it is a real, if uncommon, way to run a query — + ``AsyncCoordinodeClient.cypher(client, "…")`` passes the instance itself — + so it reads the call site too. It reads it from inside the coroutine, + which is as early as this form allows and right for the direct ``await`` + that is how it is written; a caller who instead schedules THIS form as a + task lands on an event-loop frame and is left unattributed rather than + misattributed, which is what every unreadable location does here. + """ + + @functools.wraps(fn) + async def unbound(*args: Any, **kwargs: Any) -> Any: + if args and kwargs.get("_source_location") is None and args[0]._source_tracking_enabled(): + kwargs["_source_location"] = _source.capture(1) + return await fn(*args, **kwargs) + + parameters = list(inspect.signature(fn).parameters.values())[1:] + unbound.__signature__ = inspect.Signature(parameters) # type: ignore[attr-defined] + return unbound + + +class _bound_query(functools.partial): # noqa: N801 — an implementation detail, named like one + """A query method bound to its client, reading the call site when CALLED. + + The moment matters, and two nearby ones are wrong. Inside the coroutine's + body is too late: a query handed to ``create_task``, ``gather``, + ``wait_for``, ``shield`` or a ``TaskGroup`` starts its body long after the + frame that wrote it has returned, so the location would name an + event-loop frame for all of them. Attribute lookup is too early: a bound + method kept for later — which dependency injection and callback-style code + do routinely — is looked up once at the wiring and called from everywhere + afterwards, so every one of those queries would be filed under the line + that stored it. The call is the moment they all share: ``client.cypher(…)`` + evaluates in the caller's own frame whatever is then done with the + coroutine. + + Deriving from ``functools.partial`` is what keeps the coroutine contract. + Code that ASKS whether this is a coroutine function still gets yes, since + the predicates unwrap partials to the function underneath, and a double + that came out synchronous would hand back a plain value where the caller + awaits one. + """ + + def __call__(self, /, *args: Any, **kwargs: Any) -> Any: + # One frame up is whoever wrote the call. A location passed in stays: + # the synchronous client and the helper methods read theirs at THEIR + # boundary, which is the caller's frame rather than this package's. + kwargs.setdefault("_source_location", _source.capture(1)) + return super().__call__(*args, **kwargs) + + +class _tracks_its_call_site: # noqa: N801 — reads as a decorator at the use site + """Make a query method report where each of its calls was written. + + With tracking on, a lookup hands back a :class:`_bound_query`, which reads + the caller when it is called. With tracking off there is no wrapper and no + frame read: the lookup returns the ordinary bound method, and the query + makes the call it made before this feature existed. + """ + + def __init__(self, fn: Any) -> None: + self._fn = fn + functools.update_wrapper(self, fn) + self._unbound = _without_self(fn) + + def __get__(self, obj: Any, objtype: Any = None) -> Any: + if obj is None: + return self._unbound + if not obj._source_tracking_enabled(): + return self._fn.__get__(obj, objtype) + return _bound_query(self._fn, obj) + + +async def _execute_cypher( + stub: Any, + req: Any, + timeout: float, + metadata: tuple[tuple[str, str], ...], +) -> Any: + """Send one ExecuteCypher, carrying *metadata* only when there is some. + + The argument is omitted rather than passed empty so that a client with + source tracking off makes exactly the call it made before the feature + existed. An opt-in feature should be invisible until it is opted into, + down to the shape of the call. + """ + if metadata: + return await stub.ExecuteCypher(req, timeout=timeout, metadata=metadata) + return await stub.ExecuteCypher(req, timeout=timeout) + + def _make_async_channel(host: str, port: int, tls: bool) -> grpc.aio.Channel: target = f"{host}:{port}" if tls: @@ -354,6 +464,14 @@ def is_open(self) -> bool: """True while the transaction can still take statements and be committed.""" return self._state == "open" + def _source_tracking_enabled(self) -> bool: + """Whether a statement's lookup should read its call site. + + A transaction has no setting of its own: it is the client's, since the + connection is what carries the tracking. + """ + return self._client._source_tracking + def _require_open(self, action: str) -> None: if self._state == "open": return @@ -500,10 +618,13 @@ async def _cleanup_preserving_outcome(self) -> None: if _caller_is_being_cancelled(): raise + @_tracks_its_call_site async def cypher( self, query: str, params: dict[str, PyValue] | None = None, + *, + _source_location: _source.SourceLocation | None = None, ) -> list[dict[str, Any]]: """Run one statement inside this transaction and return its rows. @@ -521,6 +642,9 @@ async def cypher( writes are discarded and the handle is consumed. The failure propagates as-is, and any later use of this object raises instead of reporting the server's "unknown transaction id". + + The call site is read when the call is made, for the reason given on + :meth:`AsyncCoordinodeClient.cypher`. """ from coordinode._proto.coordinode.v1.query.cypher_pb2 import ( # type: ignore[import] ExecuteCypherRequest, @@ -536,13 +660,19 @@ async def cypher( parameters=dict_to_props(params or {}), transaction_id=self._id, ) + metadata = self._client._source_metadata(_source_location) # Transition BEFORE the await, mirroring commit(): a concurrent # commit slipping in while this statement is in flight could land # without the statement's write, and the statement's late "unknown # transaction" failure would then overwrite the real outcome. self._state = "executing" try: - resp = await self._client._cypher_stub.ExecuteCypher(req, timeout=self._client._timeout) + resp = await _execute_cypher( + self._client._cypher_stub, + req, + self._client._timeout, + metadata, + ) except grpc.RpcError: # Always attempt the cleanup, without classifying the failure. # Whether the server processed the statement decides only whether @@ -808,6 +938,15 @@ class AsyncCoordinodeClient: # Also accepts separate host and port: async with AsyncCoordinodeClient("localhost", port=7080) as client: ... + + Pass ``debug_source_tracking=True`` to send the file, line and function + each query was written at. The server's advisor groups its statistics by + query shape, so this is what lets it point at the line that wrote the slow + one instead of only the text, which a dozen call sites usually share. + ``app_name`` and ``app_version`` ride along with it, naming the service the + query came from when several share a database. It is off by default and + costs nothing while off, so turn it on where you are looking, not + everywhere: what it sends is your source paths. """ def __init__( @@ -817,6 +956,9 @@ def __init__( *, tls: bool = False, timeout: float = 30.0, + debug_source_tracking: bool = False, + app_name: str = "", + app_version: str = "", ) -> None: # Support "host:port" as a single string (common gRPC convention). # _HOST_PORT_RE matches "hostname:port" and "[IPv6]:port" but not bare @@ -838,6 +980,12 @@ def __init__( self._port = port self._tls = tls self._timeout = timeout + # Off by default, and off is free: no frame is read and no metadata is + # built unless somebody asked for the attribution. + self._source_tracking = debug_source_tracking + # Constant for the life of the client, so it is built here rather than + # rebuilt for every query. + self._app_identity = _source.identity(app_name, app_version) self._channel: grpc.aio.Channel | None = None # Detached cleanup tasks spawned by cancellation handlers, referenced # here until done (an unreferenced task can be garbage-collected @@ -860,6 +1008,23 @@ async def __aenter__(self) -> AsyncCoordinodeClient: async def __aexit__(self, *_: Any) -> None: await self.close() + def _source_tracking_enabled(self) -> bool: + """Whether to read the call site when a query method is looked up. + + Read by the lookup itself, so it has to be answerable without + touching anything else: with tracking off, nothing at all happens. + """ + return self._source_tracking + + def _source_metadata( + self, + location: _source.SourceLocation | None, + ) -> tuple[tuple[str, str], ...]: + """gRPC metadata naming *location*, empty when there is nothing to say.""" + if location is None or not _source.is_call_site(location): + return () + return _source.to_metadata(location, self._app_identity) + async def connect(self) -> None: # A reconnect must not race an in-flight shutdown: when it resumes, # the finalizer unconditionally clears the channel and raises the @@ -945,6 +1110,7 @@ async def _finalize_close(self) -> None: # backstop for those. self._closing = True + @_tracks_its_call_site async def cypher( self, query: str, @@ -955,6 +1121,7 @@ async def cypher( read_preference: str | None = None, after_index: int | None = None, at_timestamp: int | None = None, + _source_location: _source.SourceLocation | None = None, ) -> list[dict[str, Any]]: """Execute an OpenCypher query. Returns rows as list of dicts. @@ -981,6 +1148,10 @@ async def cypher( non-zero ``after_index``: waiting for a new write and reading a fixed past are opposite requests, and the pair is rejected. Zero is rejected too: it is how the wire says "no pin", so it cannot also ask for one. + + The call site is read when this method is called rather than when its + body runs, because everything that starts a coroutine as a task runs + the body after the calling frame has returned. """ from coordinode._proto.coordinode.v1.query.cypher_pb2 import ( # type: ignore[import] ExecuteCypherRequest, @@ -1022,7 +1193,12 @@ async def cypher( req.write_concern.CopyFrom(_make_write_concern(write_concern)) if read_preference is not None: req.read_preference = _make_read_preference(read_preference) - resp = await self._cypher_stub.ExecuteCypher(req, timeout=self._timeout) + resp = await _execute_cypher( + self._cypher_stub, + req, + self._timeout, + self._source_metadata(_source_location), + ) return _rows_to_dicts(resp) def _reclaim_cancelled_begin(self, begin: asyncio.Task[Any]) -> None: @@ -1599,6 +1775,7 @@ async def create_edge_type( et = await self._schema_stub.CreateEdgeType(req, timeout=self._timeout) return EdgeTypeInfo(et) + @_tracks_its_call_site async def create_text_index( self, name: str, @@ -1606,6 +1783,7 @@ async def create_text_index( properties: str | list[str] | tuple[str, ...], *, language: str = "", + _source_location: _source.SourceLocation | None = None, ) -> TextIndexInfo: """Create a full-text (BM25) index on one or more node properties. @@ -1649,7 +1827,10 @@ async def create_text_index( props_expr = ", ".join(prop_list) lang_clause = f" DEFAULT LANGUAGE {language}" if language else "" cypher = f"CREATE TEXT INDEX {name} ON :{label}({props_expr}){lang_clause}" - rows = await self.cypher(cypher) + # Passed on rather than left to the statement below to read: that + # lookup happens here, inside the package, which is not a call site + # and would leave this public query path unattributed. + rows = await self.cypher(cypher, _source_location=_source_location) if rows: return TextIndexInfo(rows[0]) effective_language = language or "english" @@ -1657,7 +1838,13 @@ async def create_text_index( {"index": name, "label": label, "properties": ", ".join(prop_list), "default_language": effective_language} ) - async def drop_text_index(self, name: str) -> None: + @_tracks_its_call_site + async def drop_text_index( + self, + name: str, + *, + _source_location: _source.SourceLocation | None = None, + ) -> None: """Drop a full-text index by name. Args: @@ -1671,7 +1858,9 @@ async def drop_text_index(self, name: str) -> None: await client.drop_text_index("article_body") """ _validate_cypher_identifier(name, "name") - await self.cypher(f"DROP TEXT INDEX {name}") + # The caller's location, passed on for the reason given in + # create_text_index. + await self.cypher(f"DROP TEXT INDEX {name}", _source_location=_source_location) async def traverse( self, @@ -1822,7 +2011,12 @@ def cypher( ) -> list[dict[str, Any]]: """Run one statement inside this transaction. See :meth:`AsyncTransaction.cypher`.""" try: - return self._client._run(self._inner.cypher(query, params)) # type: ignore[no-any-return] + # Read before the coroutine is handed to the loop, for the reason + # given on _caller_location. + location = self._client._caller_location() + return self._client._run( # type: ignore[no-any-return] + self._inner.cypher(query, params, _source_location=location) + ) except BaseException as exc: # An interruption raised INSIDE the stepping coroutine (Ctrl-C # delivered mid-call) completes the task before _run() can @@ -1870,6 +2064,9 @@ class CoordinodeClient: with CoordinodeClient("localhost:7080") as client: rows = client.cypher("MATCH (n:Person) RETURN n.name LIMIT 5") print(rows) # [{"n.name": "Alice"}, ...] + + Takes ``debug_source_tracking``, ``app_name`` and ``app_version`` as + :class:`AsyncCoordinodeClient` does; see there. """ def __init__( @@ -1879,8 +2076,19 @@ def __init__( *, tls: bool = False, timeout: float = 30.0, + debug_source_tracking: bool = False, + app_name: str = "", + app_version: str = "", ) -> None: - self._async = AsyncCoordinodeClient(host, port, tls=tls, timeout=timeout) + self._async = AsyncCoordinodeClient( + host, + port, + tls=tls, + timeout=timeout, + debug_source_tracking=debug_source_tracking, + app_name=app_name, + app_version=app_version, + ) self._loop = asyncio.new_event_loop() self._connected = False @@ -1901,6 +2109,19 @@ def close(self) -> None: if not self._loop.is_closed(): self._loop.close() + def _caller_location(self) -> _source.SourceLocation | None: + """The call site of the synchronous method that calls this, or ``None``. + + Call it DIRECTLY from that method: the frame two levels up is this + helper, then the method, then the caller to attribute. It exists + because the synchronous API hands a coroutine to the loop, and the + coroutine's own view of who called it is the loop by then. + """ + if not self._async._source_tracking: + return None + # Two frames up from here: the synchronous method, then its caller. + return _source.capture(2) + def _run(self, coro: Any) -> Any: if self._loop.is_closed(): raise RuntimeError("CoordinodeClient has been closed and cannot be reused") @@ -1949,6 +2170,10 @@ def cypher( read_preference=read_preference, after_index=after_index, at_timestamp=at_timestamp, + # Read here rather than inside the coroutine: the coroutine + # body runs from the event loop, by which time the frame that + # called this method has already returned. + _source_location=self._caller_location(), ) ) @@ -2109,11 +2334,21 @@ def create_text_index( language: str = "", ) -> TextIndexInfo: """Create a full-text (BM25) index on one or more node properties.""" - return self._run(self._async.create_text_index(name, label, properties, language=language)) + return self._run( + self._async.create_text_index( + name, + label, + properties, + language=language, + # Read here rather than deeper in, for the reason given on + # _caller_location. + _source_location=self._caller_location(), + ) + ) def drop_text_index(self, name: str) -> None: """Drop a full-text index by name.""" - return self._run(self._async.drop_text_index(name)) + return self._run(self._async.drop_text_index(name, _source_location=self._caller_location())) def traverse( self, diff --git a/tests/unit/test_source_tracking.py b/tests/unit/test_source_tracking.py new file mode 100644 index 0000000..bf7113e --- /dev/null +++ b/tests/unit/test_source_tracking.py @@ -0,0 +1,715 @@ +"""Unit tests for query source tracking. + +The feature's whole value is that the location it reports is the line a person +wrote the query on, so these tests assert the line rather than the presence of +a header: a test that only checks "some file was sent" passes just as happily +when the file is a frame inside asyncio. + +They also pin the shape of the wire contract, which is shared with the Rust +driver and read by the server's advisor. A renamed key here is silently +ignored on the server, which is exactly the kind of break no runtime error +would report. +""" + +import asyncio +from unittest.mock import AsyncMock + +import grpc +import pytest + +from coordinode._proto.coordinode.v1.query import cypher_pb2 +from coordinode._source import SourceLocation, identity, is_call_site, to_metadata +from coordinode.client import AsyncCoordinodeClient, CoordinodeClient + + +def _execute_response(): + return cypher_pb2.ExecuteCypherResponse(columns=[], rows=[]) + + +def _stub(): + return type( + "FakeCypherStub", + (), + { + "BeginTransaction": AsyncMock(return_value=cypher_pb2.BeginTransactionResponse(transaction_id=42)), + "ExecuteCypher": AsyncMock(return_value=_execute_response()), + "CommitTransaction": AsyncMock(return_value=cypher_pb2.CommitTransactionResponse(applied_index=7)), + "RollbackTransaction": AsyncMock(return_value=cypher_pb2.RollbackTransactionResponse()), + }, + )() + + +def _async_client(**options): + client = AsyncCoordinodeClient("localhost:0", **options) + client._cypher_stub = _stub() + return client + + +def _sync_client(**options): + client = CoordinodeClient("localhost:0", **options) + client._async._cypher_stub = _stub() + client._connected = True + return client + + +def _sent_metadata(stub_method): + """The metadata of the one call made, as a dict. + + An absent argument reads as no metadata, which is what the client sends + when there is none: the keyword is omitted rather than passed empty, so a + query with tracking off makes the same call it made before the feature + existed. + """ + assert stub_method.await_count == 1, f"expected one call, got {stub_method.await_count}" + return dict(stub_method.await_args.kwargs.get("metadata", ())) + + +# ── Off by default ─────────────────────────────────────────────────────────── + + +class TestOffByDefault: + """Tracking sends nothing until it is asked for, and asks the interpreter + for nothing either: the frame is never read, so the cost of the feature + stays with the people who turned it on.""" + + def test_no_metadata_without_the_flag(self): + async def _inner() -> None: + client = _async_client() + await client.cypher("RETURN 1") + call = client._cypher_stub.ExecuteCypher.await_args + # Not merely empty: the keyword is absent, so the default path + # makes the call it made before this feature existed. Test + # doubles written against that signature keep working. + assert "metadata" not in call.kwargs + + asyncio.run(_inner()) + + def test_no_frame_is_read_without_the_flag(self, monkeypatch): + """The flag gates the frame read itself, not just the sending. + + Reading a frame is cheap but not free, and the contract for the + default path is that it does no work at all. A capture that runs + anyway and is then discarded would still pass the test above. + """ + import coordinode.client as client_module + + def _forbidden(*_args, **_kwargs): + raise AssertionError("the caller's frame was read with tracking off") + + # Patched on the client's reference to the module, not on `sys`: + # replacing `sys._getframe` itself would also replace it for the + # logging module, which calls it to name the line a log record came + # from, and the interpreter would take the rest of the suite down + # with it. + monkeypatch.setattr(client_module._source, "capture", _forbidden) + + async def _inner() -> None: + client = _async_client() + await client.cypher("RETURN 1") + + asyncio.run(_inner()) + + +# ── The reported location ──────────────────────────────────────────────────── + + +class TestReportedLocation: + """The line reported is the caller's own, on every path that reaches + ExecuteCypher.""" + + def test_async_query_reports_the_awaiting_line(self): + async def _inner() -> None: + client = _async_client(debug_source_tracking=True) + await client.cypher("RETURN 1") + expected_line = _inner.__code__.co_firstlineno + 2 + + md = _sent_metadata(client._cypher_stub.ExecuteCypher) + assert md["x-source-file"] == __file__ + assert md["x-source-line"] == str(expected_line) + assert md["x-source-function"].endswith("test_async_query_reports_the_awaiting_line.._inner") + + asyncio.run(_inner()) + + def test_sync_query_reports_the_calling_line(self): + """The synchronous client hands a coroutine to its event loop, so by + the time the query runs, this frame has returned. The location has to + be read on the way in or it is gone.""" + client = _sync_client(debug_source_tracking=True) + client.cypher("RETURN 1") + expected_line = self.test_sync_query_reports_the_calling_line.__code__.co_firstlineno + 5 + + md = _sent_metadata(client._async._cypher_stub.ExecuteCypher) + assert md["x-source-file"] == __file__ + assert md["x-source-line"] == str(expected_line) + assert md["x-source-function"].endswith("test_sync_query_reports_the_calling_line") + + def test_transaction_statement_reports_its_own_line(self): + async def _inner() -> None: + client = _async_client(debug_source_tracking=True) + tx = await client.begin_transaction() + await tx.cypher("CREATE (:A)") + expected_line = _inner.__code__.co_firstlineno + 3 + + md = _sent_metadata(client._cypher_stub.ExecuteCypher) + assert md["x-source-line"] == str(expected_line) + + asyncio.run(_inner()) + + def test_sync_transaction_statement_reports_its_own_line(self): + client = _sync_client(debug_source_tracking=True) + with client.transaction() as tx: + tx.cypher("CREATE (:A)") + expected_line = self.test_sync_transaction_statement_reports_its_own_line.__code__.co_firstlineno + 3 + + md = _sent_metadata(client._async._cypher_stub.ExecuteCypher) + assert md["x-source-line"] == str(expected_line) + + +# ── Application identity ───────────────────────────────────────────────────── + + +class TestApplicationIdentity: + """Name and version are optional, and an empty one is not sent: the server + reads a missing key and an empty value the same way, so a header carrying + nothing is only bytes.""" + + def test_name_and_version_ride_with_the_location(self): + async def _inner() -> None: + client = _async_client( + debug_source_tracking=True, + app_name="feed-service", + app_version="2.1.0", + ) + await client.cypher("RETURN 1") + + md = _sent_metadata(client._cypher_stub.ExecuteCypher) + assert md["x-source-app"] == "feed-service" + assert md["x-source-version"] == "2.1.0" + + asyncio.run(_inner()) + + def test_unset_identity_sends_no_key(self): + async def _inner() -> None: + client = _async_client(debug_source_tracking=True, app_name="feed-service") + await client.cypher("RETURN 1") + + md = _sent_metadata(client._cypher_stub.ExecuteCypher) + assert md["x-source-app"] == "feed-service" + assert "x-source-version" not in md + + asyncio.run(_inner()) + + def test_identity_alone_sends_nothing(self): + """Without the flag there is no location, and the server discards a + source context whose file is missing — so name and version alone would + be headers the server throws away.""" + + async def _inner() -> None: + client = _async_client(app_name="feed-service", app_version="2.1.0") + await client.cypher("RETURN 1") + assert _sent_metadata(client._cypher_stub.ExecuteCypher) == {} + + asyncio.run(_inner()) + + +# ── Frames that are not call sites ─────────────────────────────────────────── + + +class TestNonCallSites: + """A frame belonging to this package or to asyncio is what remains when + the frame that wrote the query is already gone. Reporting it would collect + unrelated queries under one event-loop line in the advisor, so nothing is + sent instead.""" + + def test_asyncio_frame_is_rejected(self): + assert not is_call_site(SourceLocation(file=asyncio.__file__, line=1, function="run")) + + def test_sdk_frame_is_rejected(self): + import coordinode.client as client_module + + assert not is_call_site(SourceLocation(file=client_module.__file__, line=1, function="cypher")) + + def test_user_frame_is_accepted(self): + assert is_call_site(SourceLocation(file=__file__, line=1, function="test")) + + def test_neighbour_of_the_package_is_not_swallowed(self): + """The exclusion is by directory, so a path that merely starts with + the same characters — a sibling named `coordinode-extra` beside + `coordinode` — must stay a call site.""" + import os + + import coordinode.client as client_module + + sdk_dir = os.path.dirname(os.path.abspath(client_module.__file__)) + neighbour = f"{sdk_dir}-extra{os.sep}app.py" + assert is_call_site(SourceLocation(file=neighbour, line=1, function="handler")) + + +class TestIntrospection: + """The query methods stand in for the coroutine functions they used to be, + and everything that asks must still get that answer. The capture had to + move out of the body, but a caller still writes `await client.cypher(...)`, + and code that dispatches on the predicate — `unittest.mock.create_autospec` + most consequentially — must keep building async doubles. This holds with + tracking off, which is the default, so the cost of getting it wrong falls + on people not using the feature at all.""" + + def test_client_cypher_is_a_coroutine_function(self): + import inspect + + assert inspect.iscoroutinefunction(AsyncCoordinodeClient.cypher) + assert asyncio.iscoroutinefunction(AsyncCoordinodeClient.cypher) + + def test_transaction_cypher_is_a_coroutine_function(self): + import inspect + + from coordinode.client import AsyncTransaction + + assert inspect.iscoroutinefunction(AsyncTransaction.cypher) + assert asyncio.iscoroutinefunction(AsyncTransaction.cypher) + + def test_autospec_builds_an_async_double(self): + """The concrete breakage: an autospecced client whose `cypher` came out + synchronous returns a plain value where the caller awaits.""" + from unittest.mock import create_autospec + + async def _inner() -> None: + double = create_autospec(AsyncCoordinodeClient, instance=True) + double.cypher.return_value = [{"n": 1}] + assert await double.cypher("RETURN 1") == [{"n": 1}] + + asyncio.run(_inner()) + + +class TestScheduledQueries: + """Everything that schedules the coroutine as a task runs its body after + the frame that wrote the query has returned. The location is therefore + read when the method is CALLED, which is the only moment every one of + these has in common.""" + + def test_create_task(self): + async def _inner() -> None: + client = _async_client(debug_source_tracking=True) + task = asyncio.create_task(client.cypher("RETURN 1")) + expected_line = _inner.__code__.co_firstlineno + 2 + await task + + md = _sent_metadata(client._cypher_stub.ExecuteCypher) + assert md["x-source-line"] == str(expected_line) + + asyncio.run(_inner()) + + def test_gather(self): + async def _inner() -> None: + client = _async_client(debug_source_tracking=True) + await asyncio.gather(client.cypher("RETURN 1")) + expected_line = _inner.__code__.co_firstlineno + 2 + + md = _sent_metadata(client._cypher_stub.ExecuteCypher) + assert md["x-source-line"] == str(expected_line) + + asyncio.run(_inner()) + + def test_wait_for(self): + async def _inner() -> None: + client = _async_client(debug_source_tracking=True) + await asyncio.wait_for(client.cypher("RETURN 1"), timeout=5) + expected_line = _inner.__code__.co_firstlineno + 2 + + md = _sent_metadata(client._cypher_stub.ExecuteCypher) + assert md["x-source-line"] == str(expected_line) + + asyncio.run(_inner()) + + def test_task_group(self): + async def _inner() -> None: + client = _async_client(debug_source_tracking=True) + async with asyncio.TaskGroup() as tg: + tg.create_task(client.cypher("RETURN 1")) + expected_line = _inner.__code__.co_firstlineno + 3 + + md = _sent_metadata(client._cypher_stub.ExecuteCypher) + assert md["x-source-line"] == str(expected_line) + + asyncio.run(_inner()) + + def test_transaction_statement_as_a_task(self): + async def _inner() -> None: + client = _async_client(debug_source_tracking=True) + tx = await client.begin_transaction() + await asyncio.create_task(tx.cypher("CREATE (:A)")) + expected_line = _inner.__code__.co_firstlineno + 3 + + md = _sent_metadata(client._cypher_stub.ExecuteCypher) + assert md["x-source-line"] == str(expected_line) + + asyncio.run(_inner()) + + +# ── Wire contract ──────────────────────────────────────────────────────────── + + +class TestWireContract: + """The keys are shared with the Rust driver and read by the server. A + rename here is not an error anywhere: the server just stops finding the + context, so the names are pinned in a test.""" + + def test_metadata_keys(self): + md = dict( + to_metadata( + SourceLocation(file="app/feed.py", line=47, function="Feed.render"), + identity("feed-service", "2.1.0"), + ) + ) + assert md == { + "x-source-file": "app/feed.py", + "x-source-line": "47", + "x-source-function": "Feed.render", + "x-source-app": "feed-service", + "x-source-version": "2.1.0", + } + + def test_no_location_means_no_metadata(self): + assert to_metadata(None, identity("feed-service", "2.1.0")) == () + + def test_values_are_ascii(self): + """gRPC rejects a non-ASCII value on a key without the -bin suffix, + and rejects it client-side: the query never reaches the server. A + checkout under a non-ASCII path, or a function named in one — Python + allows both — would otherwise turn tracking from a debugging aid into + the reason every query fails. + """ + md = dict( + to_metadata( + SourceLocation(file="/home/пользователь/app.py", line=47, function="Лента.render"), + identity("сервис", "2.1.0"), + ) + ) + for key, value in md.items(): + value.encode("ascii") # raises if the value would be rejected + # Escaped rather than dropped: the path still identifies the file, so + # the advisor can still group by it and a person can still read it. + assert "app.py" in md["x-source-file"] + assert "render" in md["x-source-function"] + assert md["x-source-line"] == "47" + + def test_escaping_does_not_merge_distinct_files(self): + """Two different files must not arrive as the same metadata. + + The advisor groups by what it receives, so a collision does not lose + information, it invents it: the queries of one call site are reported + under another. A file whose name holds a real newline and a file whose + name holds the four characters that spell the escape are exactly such + a pair, which is why the escape character escapes itself. + """ + with_newline = to_metadata(SourceLocation(file="/app/a\n.py", line=1, function="f"), ()) + with_literal = to_metadata(SourceLocation(file="/app/a\\x0a.py", line=1, function="f"), ()) + assert dict(with_newline)["x-source-file"] != dict(with_literal)["x-source-file"] + + def test_escaping_is_fixed_width_per_form(self): + """The other way two names could arrive as one string. + + An escape whose length varied with the code point would let a + character outside the basic plane spell the same thing as a character + inside it followed by a digit. Each form is therefore padded to its + own fixed width, as Python's own escapes are. + """ + astral = to_metadata(SourceLocation(file="\U0001f600", line=1, function="f"), ()) + bmp_then_digit = to_metadata(SourceLocation(file="ὠ0", line=1, function="f"), ()) + assert dict(astral)["x-source-file"] != dict(bmp_then_digit)["x-source-file"] + + def test_values_are_printable(self): + """ASCII alone is not the bar: gRPC refuses a control character in a + header value just as it refuses a non-ASCII one, and 0x7f with them. + An application name read from a file arrives with the trailing + newline, and a POSIX path may legally contain one, so this is the + likelier of the two ways to break every query.""" + md = dict( + to_metadata( + SourceLocation(file="/app/feed\n.py", line=47, function="render\x00"), + identity("feed-service\n", "2.1.0\t"), + ) + ) + for value in md.values(): + assert all(" " <= ch <= "~" for ch in value), repr(value) + assert "feed" in md["x-source-file"] + assert "render" in md["x-source-function"] + assert "feed-service" in md["x-source-app"] + + def test_identity_omits_what_was_not_given(self): + assert identity("", "") == () + assert identity("feed-service", "") == (("x-source-app", "feed-service"),) + assert identity("", "2.1.0") == (("x-source-version", "2.1.0"),) + + +# ── Failure paths ──────────────────────────────────────────────────────────── + + +class TestFailurePaths: + """Tracking is a debugging aid and must never be the reason a query + fails.""" + + def test_a_failing_query_still_reports_its_error(self): + class _Rejected(grpc.RpcError): + def code(self): + return grpc.StatusCode.INVALID_ARGUMENT + + async def _inner() -> None: + client = _async_client(debug_source_tracking=True) + client._cypher_stub.ExecuteCypher = AsyncMock(side_effect=_Rejected()) + with pytest.raises(grpc.RpcError): + await client.cypher("RETURN 1") + + asyncio.run(_inner()) + + def test_a_refused_frame_read_is_not_an_error(self, monkeypatch): + """A hardened application can install an audit hook that refuses the + `sys._getframe` event, and the hook's exception comes out of the frame + read rather than the ValueError a short stack gives. Either way the + location is unavailable, and an unavailable location must not take the + query down with it.""" + import coordinode._source as source_module + + def _refused(_depth): + raise RuntimeError("audit hook refused sys._getframe") + + # Scoped to the single call: this replaces the attribute on the `sys` + # module itself, which the logging machinery also reads to name the + # line a record came from, so the substitution must not outlive the + # one call under test. + with monkeypatch.context() as patched: + patched.setattr(source_module.sys, "_getframe", _refused, raising=False) + location = source_module.capture(1) + assert location is None + + def test_a_missing_frame_is_not_an_error(self, monkeypatch): + """An interpreter with no Python-level frames, or a stack shorter than + the walk, yields no location. The query goes out unattributed rather + than failing over a debugging aid.""" + import coordinode.client as client_module + + monkeypatch.setattr(client_module._source, "capture", lambda _levels: None) + + async def _inner() -> None: + client = _async_client(debug_source_tracking=True) + await client.cypher("RETURN 1") + assert _sent_metadata(client._cypher_stub.ExecuteCypher) == {} + + asyncio.run(_inner()) + + +class TestBoundSignatures: + """Looking a query method up must not cost it a parameter. + + The descriptor tells `unittest.mock.create_autospec` what the method's + parameters are, and the obvious way to do that — rewriting the underlying + function's signature without `self` — is read again every time Python + binds the method, taking `query` off with it. Frameworks that inspect a + bound callable to validate arguments, inject dependencies or generate a + wrapper would then build the wrong interface, and would do it with + tracking off as well, which is the default. + """ + + def test_bound_query_signature_keeps_query(self): + import inspect + + client = _async_client() + assert "query" in inspect.signature(client.cypher).parameters + + def test_tracked_bound_query_signature_keeps_query(self): + import inspect + + client = _async_client(debug_source_tracking=True) + assert "query" in inspect.signature(client.cypher).parameters + + def test_bound_transaction_signature_keeps_query(self): + import inspect + + async def _inner() -> None: + client = _async_client(debug_source_tracking=True) + tx = await client.begin_transaction() + assert "query" in inspect.signature(tx.cypher).parameters + + asyncio.run(_inner()) + + +class TestSavedBoundMethods: + """A query method kept and called later reports where it was CALLED. + + Dependency injection and callback-style code routinely hold on to a bound + method, so a location read when the method is looked up would file every + later query under the one line that did the wiring — exactly the merging + of unrelated call sites the feature exists to undo. + """ + + def test_saved_bound_method_reports_the_invoking_line(self): + async def _inner() -> None: + client = _async_client(debug_source_tracking=True) + run_query = client.cypher + await run_query("RETURN 1") + expected_line = _inner.__code__.co_firstlineno + 3 + + md = _sent_metadata(client._cypher_stub.ExecuteCypher) + assert md["x-source-line"] == str(expected_line) + + asyncio.run(_inner()) + + def test_two_calls_of_one_saved_method_report_two_lines(self): + """The consequence that matters: distinct call sites stay distinct.""" + + async def _inner() -> None: + client = _async_client(debug_source_tracking=True) + run_query = client.cypher + await run_query("RETURN 1") + await run_query("RETURN 2") + first_line = _inner.__code__.co_firstlineno + 3 + + lines = [ + dict(call.kwargs.get("metadata", ()))["x-source-line"] + for call in client._cypher_stub.ExecuteCypher.await_args_list + ] + assert lines == [str(first_line), str(first_line + 1)] + + asyncio.run(_inner()) + + +class TestHelperQueries: + """The public helpers that reach the server through `cypher` are attributed + to the line that called the HELPER. + + Their internal `self.cypher(...)` sits in this package, so a location read + there is not a call site and is dropped — leaving two public query paths + silently outside the per-query attribution the client advertises. + """ + + def test_create_text_index_reports_the_calling_line(self): + async def _inner() -> None: + client = _async_client(debug_source_tracking=True) + await client.create_text_index("article_body", "Article", "body") + expected_line = _inner.__code__.co_firstlineno + 2 + + md = _sent_metadata(client._cypher_stub.ExecuteCypher) + assert md["x-source-file"] == __file__ + assert md["x-source-line"] == str(expected_line) + + asyncio.run(_inner()) + + def test_drop_text_index_reports_the_calling_line(self): + async def _inner() -> None: + client = _async_client(debug_source_tracking=True) + await client.drop_text_index("article_body") + expected_line = _inner.__code__.co_firstlineno + 2 + + md = _sent_metadata(client._cypher_stub.ExecuteCypher) + assert md["x-source-line"] == str(expected_line) + + asyncio.run(_inner()) + + def test_sync_create_text_index_reports_the_calling_line(self): + client = _sync_client(debug_source_tracking=True) + client.create_text_index("article_body", "Article", "body") + expected_line = self.test_sync_create_text_index_reports_the_calling_line.__code__.co_firstlineno + 2 + + md = _sent_metadata(client._async._cypher_stub.ExecuteCypher) + assert md["x-source-file"] == __file__ + assert md["x-source-line"] == str(expected_line) + + def test_sync_drop_text_index_reports_the_calling_line(self): + client = _sync_client(debug_source_tracking=True) + client.drop_text_index("article_body") + expected_line = self.test_sync_drop_text_index_reports_the_calling_line.__code__.co_firstlineno + 2 + + md = _sent_metadata(client._async._cypher_stub.ExecuteCypher) + assert md["x-source-line"] == str(expected_line) + + def test_helper_query_still_unattributed_without_the_flag(self): + async def _inner() -> None: + client = _async_client() + await client.drop_text_index("article_body") + call = client._cypher_stub.ExecuteCypher.await_args + assert "metadata" not in call.kwargs + + asyncio.run(_inner()) + + +class TestUnboundCallForm: + """Reaching the method through the class, with the instance passed in, is + a valid way to call it, and it must still be attributed. + + That form bypasses the binding entirely, so nothing on the way in reads + the caller. A client with tracking on would send the query with no + location at all — quietly, since an unattributed query is exactly what + the feature's own failure paths produce. + """ + + def test_unbound_call_reports_the_awaiting_line(self): + async def _inner() -> None: + client = _async_client(debug_source_tracking=True) + await AsyncCoordinodeClient.cypher(client, "RETURN 1") + expected_line = _inner.__code__.co_firstlineno + 2 + + md = _sent_metadata(client._cypher_stub.ExecuteCypher) + assert md["x-source-file"] == __file__ + assert md["x-source-line"] == str(expected_line) + + asyncio.run(_inner()) + + def test_unbound_call_sends_nothing_without_the_flag(self): + async def _inner() -> None: + client = _async_client() + await AsyncCoordinodeClient.cypher(client, "RETURN 1") + call = client._cypher_stub.ExecuteCypher.await_args + assert "metadata" not in call.kwargs + + asyncio.run(_inner()) + + +class TestRefusedFrameAttributes: + """An audit hook can refuse the frame's attributes as readily as the frame + itself. + + CPython raises a separate `object.__getattr__` event when `f_code` is + read, so a hook that permits `sys._getframe` and rejects that one would + have the exception come out of the read — and, since the query is already + on its way, fail it. A debugging aid must never be the reason a query + fails, whichever of the two events the hook objects to. + """ + + def _frame_refusing(self, attribute): + class _Frame: + def __getattr__(self, name): + if name == attribute: + raise RuntimeError(f"audit hook refused frame.{name}") + raise AssertionError(f"unexpected attribute {name}") + + return _Frame() + + @pytest.mark.parametrize("attribute", ["f_code", "f_lineno"]) + def test_a_refused_frame_attribute_yields_no_location(self, monkeypatch, attribute): + import coordinode._source as source_module + + with monkeypatch.context() as patched: + patched.setattr( + source_module.sys, + "_getframe", + lambda _depth: self._frame_refusing(attribute), + raising=False, + ) + assert source_module.capture(1) is None + + def test_a_refused_frame_attribute_does_not_fail_the_query(self, monkeypatch): + import coordinode._source as source_module + + async def _inner() -> None: + client = _async_client(debug_source_tracking=True) + with monkeypatch.context() as patched: + patched.setattr( + source_module.sys, + "_getframe", + lambda _depth: self._frame_refusing("f_code"), + raising=False, + ) + await client.cypher("RETURN 1") + assert _sent_metadata(client._cypher_stub.ExecuteCypher) == {} + + asyncio.run(_inner())