From 4745f5ae20bc6aa3bd52ef8162a73e88f0ada1ed Mon Sep 17 00:00:00 2001 From: Magnus Nordlander Date: Tue, 18 Aug 2026 16:26:18 +0200 Subject: [PATCH 1/2] Add Apollo Federation inline tracing (ftv1) Port ApolloServerPluginInlineTrace: when the gateway sends the header `apollo-federation-include-trace: ftv1`, respond with `extensions.ftv1` carrying a base64-encoded protobuf Trace of the resolver tree. There is no published FTV1 spec, so docs/federation/inline-trace.md derives one from Apollo's reports.proto and the Apollo Server / federation-jvm implementations. The trace is assembled at three points, mirroring Apollo's plugin lifecycle: InlineTraceListener starts it on graphql.pre_executor, TracingReferenceExecutor records per-field timings, and the listener encodes it on graphql.post_executor at priority 100 -- ahead of ErrorHandlerListener, which rebuilds errors and drops their extensions. State lives in the per-execution context ArrayObject rather than on the listener service, so batched queries each get their own trace. This is the same approach @cacheControl already uses for its recorder; the two hooks sit side by side in resolveFieldValueOrError, cache-control first because it only reads the field, inline trace last because it starts a clock and should not be charged for the Sentry setup above it. Notable details: - Field end times use ReferenceExecutor::getPromise(), not the promise adapter: DataLoader returns a GraphQL\Executor\Promise\Promise, which SyncPromiseAdapter::isThenable() rejects, so convertThenable() would throw on the most common async path in this bundle. - The end callback captures the trace node, never the ResolveInfo: completeListValue() mutates the shared ResolveInfo::path per list item. - `include_errors: unmodified` reports the client-visible message via FormattedError, not $error->getMessage(). The bundle's ErrorHandler masks at response-format time, so the raw exception text (SQL, DSNs, paths) is still on the Error object while the trace is built. - The federation default is resolved in a root validate() callback. Symfony normalizes config fragments individually before merging, so a beforeNormalization would not see both keys. Generated protobuf classes live in proto/gen/, outside the paths php-cs-fixer and PHPStan scan, so neither needs exclusion config. A CI job regenerates with a pinned protoc and fails on drift. Verified against a golden ftv1 payload captured from a real Apollo Server subgraph, against raw protobuf tag bytes, and by decoding this bundle's own output with `protoc --decode_raw`. Co-Authored-By: Claude Opus 5 (1M context) --- .github/workflows/ci.yml | 22 ++ composer.json | 6 +- docs/federation/inline-trace.md | 237 +++++++++++++ docs/index.md | 2 + .../Tracing/Proto/Metadata/Reports.php | 26 ++ .../Federation/Tracing/Proto/Trace.php | 244 +++++++++++++ .../Federation/Tracing/Proto/Trace/Error.php | 140 ++++++++ .../Tracing/Proto/Trace/Location.php | 86 +++++ .../Federation/Tracing/Proto/Trace/Node.php | 319 +++++++++++++++++ proto/reports.proto | 95 +++++ src/DependencyInjection/Configuration.php | 51 +++ .../RedeyeGraphQLExtension.php | 40 +++ src/EventListener/InlineTraceListener.php | 89 +++++ src/Executor/TracingReferenceExecutor.php | 98 +++++- src/Federation/Tracing/TraceError.php | 28 ++ src/Federation/Tracing/TraceErrorFilter.php | 103 ++++++ .../TraceErrorTransformerInterface.php | 28 ++ src/Federation/Tracing/TraceNode.php | 64 ++++ src/Federation/Tracing/TraceTreeBuilder.php | 261 ++++++++++++++ .../InlineTraceConfigurationTest.php | 114 ++++++ .../EventListener/InlineTraceListenerTest.php | 250 ++++++++++++++ .../Executor/TracingReferenceExecutorTest.php | 214 ++++++++++++ .../Tracing/TraceErrorFilterTest.php | 238 +++++++++++++ .../Tracing/TraceSerializationTest.php | 220 ++++++++++++ .../Tracing/TraceTreeBuilderTest.php | 324 ++++++++++++++++++ tests/Federation/Tracing/fixtures/README.md | 94 +++++ .../Tracing/fixtures/apollo-ftv1.b64 | 1 + .../App/Resolver/InlineTraceResolver.php | 45 +++ .../App/config/inlineTrace/config.yml | 16 + .../inlineTrace/mapping/inlineTrace.types.yml | 23 ++ .../App/config/inlineTrace/services.yml | 8 + .../config/inlineTraceUnmodified/config.yml | 8 + .../Functional/Federation/InlineTraceTest.php | 272 +++++++++++++++ 33 files changed, 3760 insertions(+), 6 deletions(-) create mode 100644 docs/federation/inline-trace.md create mode 100644 proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Metadata/Reports.php create mode 100644 proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace.php create mode 100644 proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Error.php create mode 100644 proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Location.php create mode 100644 proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Node.php create mode 100644 proto/reports.proto create mode 100644 src/EventListener/InlineTraceListener.php create mode 100644 src/Federation/Tracing/TraceError.php create mode 100644 src/Federation/Tracing/TraceErrorFilter.php create mode 100644 src/Federation/Tracing/TraceErrorTransformerInterface.php create mode 100644 src/Federation/Tracing/TraceNode.php create mode 100644 src/Federation/Tracing/TraceTreeBuilder.php create mode 100644 tests/DependencyInjection/InlineTraceConfigurationTest.php create mode 100644 tests/EventListener/InlineTraceListenerTest.php create mode 100644 tests/Executor/TracingReferenceExecutorTest.php create mode 100644 tests/Federation/Tracing/TraceErrorFilterTest.php create mode 100644 tests/Federation/Tracing/TraceSerializationTest.php create mode 100644 tests/Federation/Tracing/TraceTreeBuilderTest.php create mode 100644 tests/Federation/Tracing/fixtures/README.md create mode 100644 tests/Federation/Tracing/fixtures/apollo-ftv1.b64 create mode 100644 tests/Functional/App/Resolver/InlineTraceResolver.php create mode 100644 tests/Functional/App/config/inlineTrace/config.yml create mode 100644 tests/Functional/App/config/inlineTrace/mapping/inlineTrace.types.yml create mode 100644 tests/Functional/App/config/inlineTrace/services.yml create mode 100644 tests/Functional/App/config/inlineTraceUnmodified/config.yml create mode 100644 tests/Functional/Federation/InlineTraceTest.php diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 9a3b8886..20d26def 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -100,6 +100,28 @@ jobs: - name: "Check coding standard" run: composer check-cs + generated-protobuf: + runs-on: ubuntu-22.04 + name: Generated Protobuf + steps: + - name: "Checkout" + uses: "actions/checkout@v2" + + # Pinned: protoc's PHP generator changes its output between releases, so an + # unpinned compiler would report drift that isn't there. Keep this version in + # step with the one recorded in proto/reports.proto. + - name: "Install protoc 29.3" + run: | + curl -sSLo /tmp/protoc.zip https://github.com/protocolbuffers/protobuf/releases/download/v29.3/protoc-29.3-linux-x86_64.zip + sudo unzip -o -q /tmp/protoc.zip -d /usr/local + protoc --version + + - name: "Regenerate and check for drift" + run: | + composer proto + git diff --exit-code proto/gen \ + || (echo "::error::proto/gen is out of date with proto/reports.proto -- run 'composer proto' and commit the result" && exit 1) + static-analysis: runs-on: ubuntu-22.04 name: "Static analysis" diff --git a/composer.json b/composer.json index 082be332..66162cc8 100644 --- a/composer.json +++ b/composer.json @@ -12,7 +12,8 @@ ], "autoload": { "psr-4": { - "Redeye\\GraphQLBundle\\": "src/" + "Redeye\\GraphQLBundle\\": "src/", + "Redeye\\GraphQLBundle\\Federation\\Tracing\\Proto\\": "proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/" } }, "autoload-dev": { @@ -30,6 +31,7 @@ "require": { "php": "^8.0", "ext-json": "*", + "google/protobuf": "^3.25", "murtukov/php-code-generator": "^0.1.5", "phpdocumentor/reflection-docblock": "^5.2", "phpdocumentor/type-resolver": ">1.4.0,<1.6.0", @@ -46,6 +48,7 @@ "webonyx/graphql-php": "^14.5" }, "suggest": { + "ext-protobuf": "For much faster serialization of Apollo Federation inline traces (ftv1)", "sentry/sentry": "To trace individual field resolution as Sentry spans.", "nelmio/cors-bundle": "For more flexibility when using CORS prefight", "react/promise": "To use ReactPHP promise adapter", @@ -89,6 +92,7 @@ }, "scripts": { "test": "bin/phpunit --color=always --coverage-clover=build/logs/clover.xml", + "proto": "protoc -I proto --php_out=proto/gen proto/reports.proto", "static-analysis": [ "phpstan analyse --ansi --memory-limit=1G" ], diff --git a/docs/federation/inline-trace.md b/docs/federation/inline-trace.md new file mode 100644 index 00000000..5f77ad6d --- /dev/null +++ b/docs/federation/inline-trace.md @@ -0,0 +1,237 @@ +Apollo Federation inline tracing (FTV1) +======================================= + +Apollo's gateway/router collects per-field performance data from subgraphs by sending the HTTP +header `apollo-federation-include-trace: ftv1`. A compliant subgraph answers with an +`extensions.ftv1` entry containing a base64-encoded protobuf `Trace` message. Apollo Server +does this via `ApolloServerPluginInlineTrace`, installed by default on every subgraph; +`graphql-java` does the same via `FederatedTracingInstrumentation`. + +This bundle implements the same behaviour. + +Configuration +------------- + +```yaml +redeye_graphql: + federation: true + # inline_trace is enabled by default when federation is true +``` + +Explicit forms: + +```yaml +redeye_graphql: + inline_trace: false # disable + inline_trace: true # enable, regardless of `federation` + inline_trace: + include_errors: masked # masked (default) | unmodified + transformer_service: App\GraphQL\MyTraceErrorTransformer +``` + +| Key | Default | Meaning | +|---|---|---| +| `enabled` | inherits `redeye_graphql.federation` | Whether to emit traces at all. | +| `include_errors` | `masked` | Error reporting policy — see [Errors](#errors). | +| `transformer_service` | `null` | Service id implementing `Redeye\GraphQLBundle\Federation\Tracing\TraceErrorTransformerInterface`. Overrides `include_errors`. | + +Note that setting only `include_errors` or `transformer_service` does **not** enable the +feature — `enabled` still inherits `federation`. Configuring options should not silently turn +tracing on for a non-federated schema. + +### Security + +With inline tracing enabled, **any** client that sends `apollo-federation-include-trace: ftv1` +receives field-level timings for your server, and — in `unmodified` mode — error detail. +Subgraphs are not meant to be publicly reachable. Apollo Server carries the same exposure and +the same caveat. + +Specification +------------- + +There is no published specification for FTV1. What follows is derived from Apollo's +`reports.proto` and the two reference implementations: + +- [`apollo-server` / `plugin/inlineTrace/index.ts`](https://github.com/apollographql/apollo-server/blob/main/packages/server/src/plugin/inlineTrace/index.ts) +- [`apollo-server` / `plugin/traceTreeBuilder.ts`](https://github.com/apollographql/apollo-server/blob/main/packages/server/src/plugin/traceTreeBuilder.ts) +- [`apollo-server` / `reports.proto`](https://github.com/apollographql/apollo-server/blob/main/packages/usage-reporting-protobuf/src/reports.proto) +- [`federation-jvm` / `FederatedTracingInstrumentation.java`](https://github.com/apollographql/federation-jvm/blob/main/graphql-java-support/src/main/java/com/apollographql/federation/graphqljava/tracing/FederatedTracingInstrumentation.java) +- [Apollo docs: Inline trace plugin](https://www.apollographql.com/docs/apollo-server/api/plugin/inline-trace) + +### Trigger + +A request carrying the HTTP header `apollo-federation-include-trace` with the exact value +`ftv1` requests a trace. Any other value, or absence, means no trace. Header-name matching is +case-insensitive (HTTP); the value comparison is strict — Apollo only ever sends `ftv1`. + +### Response + +The response `extensions` object gains a key `ftv1` whose value is +`base64(Trace.serializeToString())`. Nothing else about the response changes. If the request did +not ask for a trace, `extensions.ftv1` is absent. + +### Wire format + +Subset of Apollo's `reports.proto`. **Field numbers are normative and must match upstream +exactly.** The vendored copy lives at [`proto/reports.proto`](../../proto/reports.proto). + +```proto +message Trace { + google.protobuf.Timestamp end_time = 3; // wallclock, trace end + google.protobuf.Timestamp start_time = 4; // wallclock, trace start + uint64 duration_ns = 11; // monotonic; may != end-start + Node root = 14; + double field_execution_weight = 31; // always 1.0 + + message Node { + oneof id { + string response_name = 1; // response key (alias-aware) for field nodes + uint32 index = 2; // list position for list-element nodes + } + string type = 3; // field return type, e.g. "String!" + string parent_type = 13; // owning type name, e.g. "User" + uint64 start_time = 8; // ns since Trace.start_time + uint64 end_time = 9; // ns since Trace.start_time + repeated Error error = 11; + repeated Node child = 12; + string original_field_name = 14; // set only when response_name is an alias + } + + message Error { + string message = 1; + repeated Location location = 2; + uint64 time_ns = 3; // not set + string json = 4; + } + + message Location { + uint32 line = 1; + uint32 column = 2; + } +} +``` + +`field_execution_weight` is set to `1.0`, matching Apollo Server. Studio scales field-usage +statistics by it. + +Fields deliberately **not** emitted (gateway / usage-reporting concerns): `signature`, +`details`, `client_name`, `client_version`, `http`, `cache_policy`, `query_plan`, +`full_query_cache_hit`, `persisted_query_*`, `registered_operation`, `forbidden_operation`, +`is_incomplete`, and `Node.cache_policy`. + +### Node tree + +The tree mirrors the shape of the GraphQL **response**, not resolver invocation order. + +- `Trace.root` has no `id`, no `type` and no timings. It exists only as parent of the + operation's top-level selections. +- Each resolved field contributes one node keyed by its **response name** (the alias if + aliased, otherwise the field name). When the response name differs from the schema field + name, `original_field_name` carries the schema field name. +- Each element of a list contributes an intermediate node carrying only `index`. Index nodes + have no `type`, `parent_type` or timings — they are structural, and no resolver ever fires + for them. +- Ancestors are created on demand: inserting `["users", 0, "name"]` creates `users`, `0` and + `name` as needed. Insertion is order-independent. +- `start_time`/`end_time` are nanoseconds **relative to `Trace.start_time`**, from a monotonic + clock. + +### Timing boundaries + +`Trace.start_time` is taken before parsing and validation, so parse and validation cost is +inside `duration_ns`. `end_time`/`duration_ns` are taken after execution completes. +`duration_ns` uses `hrtime(true)` (monotonic); `start_time`/`end_time` use wallclock +(`microtime(true)`) converted to `google.protobuf.Timestamp`. + +A trace is emitted even when the operation fails to parse or validate — the tree is then just +the root node carrying the errors. + +### Errors + +Errors attach to the node matching the error's `path`; errors with no path (parse, validation, +variable coercion) go on the root node. If no node exists for a path, it is created along with +its ancestors. + +Each `Trace.Error` carries `message` (after the policy below), `location` (1-based +line/column), and `json` (the standard `{message, locations, path, extensions}` serialization +of the policy-applied error). `time_ns` is not set — neither reference implementation sets it. + +| `include_errors` | Behaviour | +|---|---| +| `masked` (default) | `message` becomes the literal ``; `extensions` becomes `{"maskedBy": "RedeyeGraphQLBundleInlineTrace"}`. `locations` and `path` are preserved. | +| `unmodified` | The **client-visible** message and extensions are reported. | +| `transformer_service` | The service receives each error and returns a replacement or `null`; `null` drops the error from the trace. Only `message` and `extensions` may change — `locations` and `path` always come from the original so the error stays on the right node. | + +Masking is the default because a trace crosses a trust boundary: it leaves the subgraph and is +stored by Apollo Studio, and subgraph errors routinely carry internal detail. + +> **`unmodified` does not mean "raw".** This bundle's error handler never rewrites the message +> on the `GraphQL\Error\Error` object — masking happens later, inside the response formatter. +> So `$error->getMessage()` is still the raw PHP exception text (SQL, DSNs, file paths) while +> the trace is being built. `unmodified` therefore reports what the *client* would see, via +> `FormattedError::createFromException($error, DebugFlag::NONE, $internalErrorMessage)`, not the +> raw exception message. + +A custom transformer: + +```php +namespace App\GraphQL; + +use GraphQL\Error\Error; +use Redeye\GraphQLBundle\Federation\Tracing\TraceErrorTransformerInterface; + +final class MyTraceErrorTransformer implements TraceErrorTransformerInterface +{ + public function transform(Error $error): ?Error + { + // Drop anything that might carry customer data. + if (str_contains($error->getMessage(), '@')) { + return null; + } + + return $error; + } +} +``` + +Implementation notes +-------------------- + +The trace is built at three points, mirroring Apollo Server's plugin lifecycle: + +| Apollo Server | This bundle | +|---|---| +| `requestDidStart` (header check, `startTiming`) | `InlineTraceListener::onPreExecutor` on `graphql.pre_executor` | +| `willResolveField` | `TracingReferenceExecutor::resolveFieldValueOrError()` | +| `didEncounterErrors` + `willSendResponse` | `InlineTraceListener::onPostExecutor` on `graphql.post_executor`, priority 100 | + +The in-progress trace is carried in the per-execution `ArrayObject` context under the key +`Redeye\GraphQLBundle\Federation\Tracing\InlineTraceListener::CONTEXT_KEY`. It is visible to +resolvers as `$context[...]` but is **internal** — do not rely on it. Keeping it there (rather +than on the listener service) is what makes batched requests correct: `Request\Executor` builds +a fresh context per query, so each query in a batch gets its own independent trace. + +Per-field timings are collected by `TracingReferenceExecutor`, which this bundle installs +process-wide via `GraphQL\Executor\Executor::setImplementationFactory()`. **If your application +calls `setImplementationFactory()` itself, field nodes will silently disappear** while the trace +envelope is still emitted. + +Very large responses produce very large traces. The builder caps the node count (25 000) and +stops recording beyond it; a truncated trace is preferable to exhausting memory. + +Verifying by hand +----------------- + +```bash +curl -s localhost:8000/graphql \ + -H 'content-type: application/json' \ + -H 'apollo-federation-include-trace: ftv1' \ + -d '{"query":"{ me { name } }"}' | jq -r .extensions.ftv1 | base64 -d | protoc --decode_raw +``` + +`protoc --decode_raw` needs no schema and prints the field-number tree directly, so it +independently confirms field numbering against the table above. + +Apollo's [`apollo-federation-subgraph-compatibility`](https://github.com/apollographql/apollo-federation-subgraph-compatibility) +harness asserts that a subgraph returns `extensions.ftv1` for a header-carrying request, and is +the strongest available end-to-end check. diff --git a/docs/index.md b/docs/index.md index 2979d4a9..eb3f1345 100644 --- a/docs/index.md +++ b/docs/index.md @@ -24,6 +24,8 @@ After installation Define your [GraphQL schema](definitions/index.md). +Serving an Apollo Federation subgraph? See [inline tracing (FTV1)](federation/inline-trace.md). + Symfony Flex installation ------------ diff --git a/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Metadata/Reports.php b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Metadata/Reports.php new file mode 100644 index 00000000..024f4507 --- /dev/null +++ b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Metadata/Reports.php @@ -0,0 +1,26 @@ +internalAddGeneratedFile( + "\x0A\xD4\x05\x0A\x0Dreports.proto\"\xCF\x04\x0A\x05Trace\x12,\x0A\x08end_time\x18\x03 \x01(\x0B2\x1A.google.protobuf.Timestamp\x12.\x0A\x0Astart_time\x18\x04 \x01(\x0B2\x1A.google.protobuf.Timestamp\x12\x13\x0A\x0Bduration_ns\x18\x0B \x01(\x04\x12\x19\x0A\x04root\x18\x0E \x01(\x0B2\x0B.Trace.Node\x12\x1E\x0A\x16field_execution_weight\x18\x1F \x01(\x01\x1AZ\x0A\x05Error\x12\x0F\x0A\x07message\x18\x01 \x01(\x09\x12!\x0A\x08location\x18\x02 \x03(\x0B2\x0F.Trace.Location\x12\x0F\x0A\x07time_ns\x18\x03 \x01(\x04\x12\x0C\x0A\x04json\x18\x04 \x01(\x09\x1A(\x0A\x08Location\x12\x0C\x0A\x04line\x18\x01 \x01(\x0D\x12\x0E\x0A\x06column\x18\x02 \x01(\x0D\x1A\xE1\x01\x0A\x04Node\x12\x17\x0A\x0Dresponse_name\x18\x01 \x01(\x09H\x00\x12\x0F\x0A\x05index\x18\x02 \x01(\x0DH\x00\x12\x0C\x0A\x04type\x18\x03 \x01(\x09\x12\x12\x0A\x0Astart_time\x18\x08 \x01(\x04\x12\x10\x0A\x08end_time\x18\x09 \x01(\x04\x12\x1B\x0A\x05error\x18\x0B \x03(\x0B2\x0C.Trace.Error\x12\x1A\x0A\x05child\x18\x0C \x03(\x0B2\x0B.Trace.Node\x12\x13\x0A\x0Bparent_type\x18\x0D \x01(\x09\x12\x1B\x0A\x13original_field_name\x18\x0E \x01(\x09B\x04\x0A\x02idJ\x04\x08\x04\x10\x08J\x04\x08\x0A\x10\x0BJ\x04\x08\x01\x10\x02J\x04\x08\x02\x10\x03J\x04\x08\x05\x10\x0BJ\x04\x08\x0C\x10\x0DJ\x04\x08\x0D\x10\x0EJ\x04\x08\x0F\x10\x1FJ\x04\x08 \x10!J\x04\x08!\x10\"Bi\xCA\x02-Redeye\\GraphQLBundle\\Federation\\Tracing\\Proto\xE2\x026Redeye\\GraphQLBundle\\Federation\\Tracing\\Proto\\Metadatab\x06proto3" + , true); + + static::$is_initialized = true; + } +} + diff --git a/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace.php b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace.php new file mode 100644 index 00000000..29dbb874 --- /dev/null +++ b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace.php @@ -0,0 +1,244 @@ +Trace + */ +class Trace extends \Google\Protobuf\Internal\Message +{ + /** + * Wallclock time when the trace ended. + * + * Generated from protobuf field .google.protobuf.Timestamp end_time = 3; + */ + protected $end_time = null; + /** + * Wallclock time when the trace began. + * + * Generated from protobuf field .google.protobuf.Timestamp start_time = 4; + */ + protected $start_time = null; + /** + * High precision duration of the trace; may not equal end_time - start_time + * (e.g. if the machine's clock changed during the trace). + * + * Generated from protobuf field uint64 duration_ns = 11; + */ + protected $duration_ns = 0; + /** + * A tree containing information about all resolvers run by this service, including errors. + * + * Generated from protobuf field .Trace.Node root = 14; + */ + protected $root = null; + /** + * Some servers don't do field-level instrumentation for every request and assign each + * instrumented request a "weight". Apollo Server always sends 1 for inline traces; Studio + * scales estimated_execution_count by it. 0 is treated as 1 for backwards compatibility. + * + * Generated from protobuf field double field_execution_weight = 31; + */ + protected $field_execution_weight = 0.0; + + /** + * Constructor. + * + * @param array $data { + * Optional. Data for populating the Message object. + * + * @type \Google\Protobuf\Timestamp $end_time + * Wallclock time when the trace ended. + * @type \Google\Protobuf\Timestamp $start_time + * Wallclock time when the trace began. + * @type int|string $duration_ns + * High precision duration of the trace; may not equal end_time - start_time + * (e.g. if the machine's clock changed during the trace). + * @type \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node $root + * A tree containing information about all resolvers run by this service, including errors. + * @type float $field_execution_weight + * Some servers don't do field-level instrumentation for every request and assign each + * instrumented request a "weight". Apollo Server always sends 1 for inline traces; Studio + * scales estimated_execution_count by it. 0 is treated as 1 for backwards compatibility. + * } + */ + public function __construct($data = NULL) { + \Redeye\GraphQLBundle\Federation\Tracing\Proto\Metadata\Reports::initOnce(); + parent::__construct($data); + } + + /** + * Wallclock time when the trace ended. + * + * Generated from protobuf field .google.protobuf.Timestamp end_time = 3; + * @return \Google\Protobuf\Timestamp|null + */ + public function getEndTime() + { + return $this->end_time; + } + + public function hasEndTime() + { + return isset($this->end_time); + } + + public function clearEndTime() + { + unset($this->end_time); + } + + /** + * Wallclock time when the trace ended. + * + * Generated from protobuf field .google.protobuf.Timestamp end_time = 3; + * @param \Google\Protobuf\Timestamp $var + * @return $this + */ + public function setEndTime($var) + { + GPBUtil::checkMessage($var, \Google\Protobuf\Timestamp::class); + $this->end_time = $var; + + return $this; + } + + /** + * Wallclock time when the trace began. + * + * Generated from protobuf field .google.protobuf.Timestamp start_time = 4; + * @return \Google\Protobuf\Timestamp|null + */ + public function getStartTime() + { + return $this->start_time; + } + + public function hasStartTime() + { + return isset($this->start_time); + } + + public function clearStartTime() + { + unset($this->start_time); + } + + /** + * Wallclock time when the trace began. + * + * Generated from protobuf field .google.protobuf.Timestamp start_time = 4; + * @param \Google\Protobuf\Timestamp $var + * @return $this + */ + public function setStartTime($var) + { + GPBUtil::checkMessage($var, \Google\Protobuf\Timestamp::class); + $this->start_time = $var; + + return $this; + } + + /** + * High precision duration of the trace; may not equal end_time - start_time + * (e.g. if the machine's clock changed during the trace). + * + * Generated from protobuf field uint64 duration_ns = 11; + * @return int|string + */ + public function getDurationNs() + { + return $this->duration_ns; + } + + /** + * High precision duration of the trace; may not equal end_time - start_time + * (e.g. if the machine's clock changed during the trace). + * + * Generated from protobuf field uint64 duration_ns = 11; + * @param int|string $var + * @return $this + */ + public function setDurationNs($var) + { + GPBUtil::checkUint64($var); + $this->duration_ns = $var; + + return $this; + } + + /** + * A tree containing information about all resolvers run by this service, including errors. + * + * Generated from protobuf field .Trace.Node root = 14; + * @return \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node|null + */ + public function getRoot() + { + return $this->root; + } + + public function hasRoot() + { + return isset($this->root); + } + + public function clearRoot() + { + unset($this->root); + } + + /** + * A tree containing information about all resolvers run by this service, including errors. + * + * Generated from protobuf field .Trace.Node root = 14; + * @param \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node $var + * @return $this + */ + public function setRoot($var) + { + GPBUtil::checkMessage($var, \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node::class); + $this->root = $var; + + return $this; + } + + /** + * Some servers don't do field-level instrumentation for every request and assign each + * instrumented request a "weight". Apollo Server always sends 1 for inline traces; Studio + * scales estimated_execution_count by it. 0 is treated as 1 for backwards compatibility. + * + * Generated from protobuf field double field_execution_weight = 31; + * @return float + */ + public function getFieldExecutionWeight() + { + return $this->field_execution_weight; + } + + /** + * Some servers don't do field-level instrumentation for every request and assign each + * instrumented request a "weight". Apollo Server always sends 1 for inline traces; Studio + * scales estimated_execution_count by it. 0 is treated as 1 for backwards compatibility. + * + * Generated from protobuf field double field_execution_weight = 31; + * @param float $var + * @return $this + */ + public function setFieldExecutionWeight($var) + { + GPBUtil::checkDouble($var); + $this->field_execution_weight = $var; + + return $this; + } + +} + diff --git a/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Error.php b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Error.php new file mode 100644 index 00000000..b2c49797 --- /dev/null +++ b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Error.php @@ -0,0 +1,140 @@ +Trace.Error + */ +class Error extends \Google\Protobuf\Internal\Message +{ + /** + * Generated from protobuf field string message = 1; + */ + protected $message = ''; + /** + * Generated from protobuf field repeated .Trace.Location location = 2; + */ + private $location; + /** + * Generated from protobuf field uint64 time_ns = 3; + */ + protected $time_ns = 0; + /** + * Generated from protobuf field string json = 4; + */ + protected $json = ''; + + /** + * Constructor. + * + * @param array $data { + * Optional. Data for populating the Message object. + * + * @type string $message + * @type array<\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Location>|\Google\Protobuf\Internal\RepeatedField $location + * @type int|string $time_ns + * @type string $json + * } + */ + public function __construct($data = NULL) { + \Redeye\GraphQLBundle\Federation\Tracing\Proto\Metadata\Reports::initOnce(); + parent::__construct($data); + } + + /** + * Generated from protobuf field string message = 1; + * @return string + */ + public function getMessage() + { + return $this->message; + } + + /** + * Generated from protobuf field string message = 1; + * @param string $var + * @return $this + */ + public function setMessage($var) + { + GPBUtil::checkString($var, True); + $this->message = $var; + + return $this; + } + + /** + * Generated from protobuf field repeated .Trace.Location location = 2; + * @return \Google\Protobuf\Internal\RepeatedField + */ + public function getLocation() + { + return $this->location; + } + + /** + * Generated from protobuf field repeated .Trace.Location location = 2; + * @param array<\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Location>|\Google\Protobuf\Internal\RepeatedField $var + * @return $this + */ + public function setLocation($var) + { + $arr = GPBUtil::checkRepeatedField($var, \Google\Protobuf\Internal\GPBType::MESSAGE, \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Location::class); + $this->location = $arr; + + return $this; + } + + /** + * Generated from protobuf field uint64 time_ns = 3; + * @return int|string + */ + public function getTimeNs() + { + return $this->time_ns; + } + + /** + * Generated from protobuf field uint64 time_ns = 3; + * @param int|string $var + * @return $this + */ + public function setTimeNs($var) + { + GPBUtil::checkUint64($var); + $this->time_ns = $var; + + return $this; + } + + /** + * Generated from protobuf field string json = 4; + * @return string + */ + public function getJson() + { + return $this->json; + } + + /** + * Generated from protobuf field string json = 4; + * @param string $var + * @return $this + */ + public function setJson($var) + { + GPBUtil::checkString($var, True); + $this->json = $var; + + return $this; + } + +} + diff --git a/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Location.php b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Location.php new file mode 100644 index 00000000..e668a305 --- /dev/null +++ b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Location.php @@ -0,0 +1,86 @@ +Trace.Location + */ +class Location extends \Google\Protobuf\Internal\Message +{ + /** + * Generated from protobuf field uint32 line = 1; + */ + protected $line = 0; + /** + * Generated from protobuf field uint32 column = 2; + */ + protected $column = 0; + + /** + * Constructor. + * + * @param array $data { + * Optional. Data for populating the Message object. + * + * @type int $line + * @type int $column + * } + */ + public function __construct($data = NULL) { + \Redeye\GraphQLBundle\Federation\Tracing\Proto\Metadata\Reports::initOnce(); + parent::__construct($data); + } + + /** + * Generated from protobuf field uint32 line = 1; + * @return int + */ + public function getLine() + { + return $this->line; + } + + /** + * Generated from protobuf field uint32 line = 1; + * @param int $var + * @return $this + */ + public function setLine($var) + { + GPBUtil::checkUint32($var); + $this->line = $var; + + return $this; + } + + /** + * Generated from protobuf field uint32 column = 2; + * @return int + */ + public function getColumn() + { + return $this->column; + } + + /** + * Generated from protobuf field uint32 column = 2; + * @param int $var + * @return $this + */ + public function setColumn($var) + { + GPBUtil::checkUint32($var); + $this->column = $var; + + return $this; + } + +} + diff --git a/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Node.php b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Node.php new file mode 100644 index 00000000..f3b7d668 --- /dev/null +++ b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Node.php @@ -0,0 +1,319 @@ +Trace.Node + */ +class Node extends \Google\Protobuf\Internal\Message +{ + /** + * The field's return type; e.g. "String!" for User.email: String! + * + * Generated from protobuf field string type = 3; + */ + protected $type = ''; + /** + * relative to the trace's start_time, in ns + * + * Generated from protobuf field uint64 start_time = 8; + */ + protected $start_time = 0; + /** + * relative to the trace's start_time, in ns + * + * Generated from protobuf field uint64 end_time = 9; + */ + protected $end_time = 0; + /** + * Generated from protobuf field repeated .Trace.Error error = 11; + */ + private $error; + /** + * Generated from protobuf field repeated .Trace.Node child = 12; + */ + private $child; + /** + * The field's parent type; e.g. "User" for User.email: String! + * + * Generated from protobuf field string parent_type = 13; + */ + protected $parent_type = ''; + /** + * Generated from protobuf field string original_field_name = 14; + */ + protected $original_field_name = ''; + protected $id; + + /** + * Constructor. + * + * @param array $data { + * Optional. Data for populating the Message object. + * + * @type string $response_name + * @type int $index + * @type string $type + * The field's return type; e.g. "String!" for User.email: String! + * @type int|string $start_time + * relative to the trace's start_time, in ns + * @type int|string $end_time + * relative to the trace's start_time, in ns + * @type array<\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Error>|\Google\Protobuf\Internal\RepeatedField $error + * @type array<\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node>|\Google\Protobuf\Internal\RepeatedField $child + * @type string $parent_type + * The field's parent type; e.g. "User" for User.email: String! + * @type string $original_field_name + * } + */ + public function __construct($data = NULL) { + \Redeye\GraphQLBundle\Federation\Tracing\Proto\Metadata\Reports::initOnce(); + parent::__construct($data); + } + + /** + * Generated from protobuf field string response_name = 1; + * @return string + */ + public function getResponseName() + { + return $this->readOneof(1); + } + + public function hasResponseName() + { + return $this->hasOneof(1); + } + + /** + * Generated from protobuf field string response_name = 1; + * @param string $var + * @return $this + */ + public function setResponseName($var) + { + GPBUtil::checkString($var, True); + $this->writeOneof(1, $var); + + return $this; + } + + /** + * Generated from protobuf field uint32 index = 2; + * @return int + */ + public function getIndex() + { + return $this->readOneof(2); + } + + public function hasIndex() + { + return $this->hasOneof(2); + } + + /** + * Generated from protobuf field uint32 index = 2; + * @param int $var + * @return $this + */ + public function setIndex($var) + { + GPBUtil::checkUint32($var); + $this->writeOneof(2, $var); + + return $this; + } + + /** + * The field's return type; e.g. "String!" for User.email: String! + * + * Generated from protobuf field string type = 3; + * @return string + */ + public function getType() + { + return $this->type; + } + + /** + * The field's return type; e.g. "String!" for User.email: String! + * + * Generated from protobuf field string type = 3; + * @param string $var + * @return $this + */ + public function setType($var) + { + GPBUtil::checkString($var, True); + $this->type = $var; + + return $this; + } + + /** + * relative to the trace's start_time, in ns + * + * Generated from protobuf field uint64 start_time = 8; + * @return int|string + */ + public function getStartTime() + { + return $this->start_time; + } + + /** + * relative to the trace's start_time, in ns + * + * Generated from protobuf field uint64 start_time = 8; + * @param int|string $var + * @return $this + */ + public function setStartTime($var) + { + GPBUtil::checkUint64($var); + $this->start_time = $var; + + return $this; + } + + /** + * relative to the trace's start_time, in ns + * + * Generated from protobuf field uint64 end_time = 9; + * @return int|string + */ + public function getEndTime() + { + return $this->end_time; + } + + /** + * relative to the trace's start_time, in ns + * + * Generated from protobuf field uint64 end_time = 9; + * @param int|string $var + * @return $this + */ + public function setEndTime($var) + { + GPBUtil::checkUint64($var); + $this->end_time = $var; + + return $this; + } + + /** + * Generated from protobuf field repeated .Trace.Error error = 11; + * @return \Google\Protobuf\Internal\RepeatedField + */ + public function getError() + { + return $this->error; + } + + /** + * Generated from protobuf field repeated .Trace.Error error = 11; + * @param array<\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Error>|\Google\Protobuf\Internal\RepeatedField $var + * @return $this + */ + public function setError($var) + { + $arr = GPBUtil::checkRepeatedField($var, \Google\Protobuf\Internal\GPBType::MESSAGE, \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Error::class); + $this->error = $arr; + + return $this; + } + + /** + * Generated from protobuf field repeated .Trace.Node child = 12; + * @return \Google\Protobuf\Internal\RepeatedField + */ + public function getChild() + { + return $this->child; + } + + /** + * Generated from protobuf field repeated .Trace.Node child = 12; + * @param array<\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node>|\Google\Protobuf\Internal\RepeatedField $var + * @return $this + */ + public function setChild($var) + { + $arr = GPBUtil::checkRepeatedField($var, \Google\Protobuf\Internal\GPBType::MESSAGE, \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node::class); + $this->child = $arr; + + return $this; + } + + /** + * The field's parent type; e.g. "User" for User.email: String! + * + * Generated from protobuf field string parent_type = 13; + * @return string + */ + public function getParentType() + { + return $this->parent_type; + } + + /** + * The field's parent type; e.g. "User" for User.email: String! + * + * Generated from protobuf field string parent_type = 13; + * @param string $var + * @return $this + */ + public function setParentType($var) + { + GPBUtil::checkString($var, True); + $this->parent_type = $var; + + return $this; + } + + /** + * Generated from protobuf field string original_field_name = 14; + * @return string + */ + public function getOriginalFieldName() + { + return $this->original_field_name; + } + + /** + * Generated from protobuf field string original_field_name = 14; + * @param string $var + * @return $this + */ + public function setOriginalFieldName($var) + { + GPBUtil::checkString($var, True); + $this->original_field_name = $var; + + return $this; + } + + /** + * @return string + */ + public function getId() + { + return $this->whichOneof("id"); + } + +} + diff --git a/proto/reports.proto b/proto/reports.proto new file mode 100644 index 00000000..a07b765a --- /dev/null +++ b/proto/reports.proto @@ -0,0 +1,95 @@ +syntax = "proto3"; + +// Trimmed subset of Apollo's reports.proto, sufficient to emit FTV1 inline traces +// from a federated subgraph. +// +// Upstream: https://github.com/apollographql/apollo-server +// packages/usage-reporting-protobuf/src/reports.proto +// Vendored from commit 021460e95c34ce921dc1c8caa3e5ded3463487ee (2023-03-02). +// +// FIELD NUMBERS MUST MATCH UPSTREAM EXACTLY -- they are the wire format. +// `reserved` guards the numbers of upstream fields we deliberately omit, so they +// can never be reused here by mistake. See docs/federation/inline-trace.md. +// +// Upstream declares no `package`, which would make protoc emit into the PHP global +// namespace (\Trace). The two `option php_*_namespace` lines below are this file's +// only intentional divergence from upstream. +// +// Regenerate with: composer proto +// +// Generated with protoc 29.3. protoc's PHP backend changes its output between +// releases, so use that version (CI pins it) or expect a large, spurious diff. + +import "google/protobuf/timestamp.proto"; + +option php_namespace = "Redeye\\GraphQLBundle\\Federation\\Tracing\\Proto"; +option php_metadata_namespace = "Redeye\\GraphQLBundle\\Federation\\Tracing\\Proto\\Metadata"; + +message Trace { + message Error { + string message = 1; + repeated Location location = 2; + uint64 time_ns = 3; + string json = 4; + } + + message Location { + uint32 line = 1; + uint32 column = 2; + } + + // We store information on each resolver execution as a Node on a tree. The structure + // of the tree corresponds to the structure of the GraphQL response; it does not + // indicate the order in which resolvers were invoked. Nodes representing list indices + // (and the root node) don't carry types or times. + message Node { + // The response name of the field -- i.e. the alias, when the query used one. In that + // case original_field_name holds the actual field name from the schema. Paths are + // always built from response_name. + oneof id { + string response_name = 1; + uint32 index = 2; + } + + // The field's return type; e.g. "String!" for User.email: String! + string type = 3; + + // relative to the trace's start_time, in ns + uint64 start_time = 8; + // relative to the trace's start_time, in ns + uint64 end_time = 9; + + repeated Error error = 11; + repeated Node child = 12; + + // The field's parent type; e.g. "User" for User.email: String! + string parent_type = 13; + + string original_field_name = 14; + + // Omitted upstream fields: cache_policy (5). 4 is reserved upstream too. + reserved 4 to 7, 10; + } + + // Wallclock time when the trace ended. + google.protobuf.Timestamp end_time = 3; + // Wallclock time when the trace began. + google.protobuf.Timestamp start_time = 4; + // High precision duration of the trace; may not equal end_time - start_time + // (e.g. if the machine's clock changed during the trace). + uint64 duration_ns = 11; + // A tree containing information about all resolvers run by this service, including errors. + Node root = 14; + + // Some servers don't do field-level instrumentation for every request and assign each + // instrumented request a "weight". Apollo Server always sends 1 for inline traces; Studio + // scales estimated_execution_count by it. 0 is treated as 1 for backwards compatibility. + double field_execution_weight = 31; + + // Everything else in the upstream Trace message is a gateway / usage-reporting concern + // and is never present in an inline trace: signature, details, client_name, + // client_version, http, cache_policy, query_plan, full_query_cache_hit, + // persisted_query_*, registered_operation, forbidden_operation, is_incomplete, + // unexecutedOperation*. + reserved 1, 2, 5 to 10, 12, 13, 15 to 30, 32, 33; +} diff --git a/src/DependencyInjection/Configuration.php b/src/DependencyInjection/Configuration.php index 74fb72fb..be1bf38c 100644 --- a/src/DependencyInjection/Configuration.php +++ b/src/DependencyInjection/Configuration.php @@ -14,6 +14,8 @@ use Redeye\GraphQLBundle\EventListener\ErrorLoggerListener; use Redeye\GraphQLBundle\Executor\Executor; use Redeye\GraphQLBundle\ExpressionLanguage\ExpressionLanguage; +use Redeye\GraphQLBundle\Federation\Tracing\TraceErrorFilter; +use Redeye\GraphQLBundle\Federation\Tracing\TraceErrorTransformerInterface; use Redeye\GraphQLBundle\Resolver\FieldResolver; use Symfony\Component\Config\Definition\Builder\ArrayNodeDefinition; use Symfony\Component\Config\Definition\Builder\EnumNodeDefinition; @@ -51,10 +53,24 @@ public function getConfigTreeBuilder(): TreeBuilder // @phpstan-ignore-next-line $rootNode + ->validate() + ->always(function (array $v): array { + // `inline_trace.enabled: null` means "inherit from the `federation` sibling". + // This has to happen here rather than in a beforeNormalization: Symfony + // normalizes each config fragment on its own and only merges afterwards, so + // this is the first point at which both keys are known. + if (null === $v['inline_trace']['enabled']) { + $v['inline_trace']['enabled'] = $v['federation']; + } + + return $v; + }) + ->end() ->children() ->booleanNode('federation') ->defaultFalse() ->end() + ->append($this->inlineTraceSection()) ->append($this->batchingMethodSection()) ->append($this->definitionsSection()) ->append($this->errorsHandlerSection()) @@ -109,6 +125,41 @@ private function cacheControlSection(): ArrayNodeDefinition return $node; } + private function inlineTraceSection(): ArrayNodeDefinition + { + $builder = new TreeBuilder('inline_trace'); + + /** @var ArrayNodeDefinition $node */ + $node = $builder->getRootNode(); + + // @phpstan-ignore-next-line + $node + ->info('Apollo Federation inline tracing (ftv1). See docs/federation/inline-trace.md.') + ->treatFalseLike(['enabled' => false]) + ->treatTrueLike(['enabled' => true]) + ->treatNullLike(['enabled' => true]) + ->addDefaultsIfNotSet() + ->children() + // Tri-state rather than canBeEnabled(): that hard-codes defaultFalse(), which + // would make an explicit `false` indistinguishable from the default. + ->booleanNode('enabled') + ->info('Defaults to the value of "federation".') + ->defaultNull() + ->end() + ->enumNode('include_errors') + ->info('"masked" replaces error messages with "" (the Apollo Server default); "unmodified" reports the client-visible message.') + ->values([TraceErrorFilter::MASKED, TraceErrorFilter::UNMODIFIED]) + ->defaultValue(TraceErrorFilter::MASKED) + ->end() + ->scalarNode('transformer_service') + ->info('Service id implementing '.TraceErrorTransformerInterface::class.'. Overrides include_errors.') + ->defaultNull() + ->end() + ->end(); + + return $node; + } + private function batchingMethodSection(): EnumNodeDefinition { $builder = new TreeBuilder('batching_method', 'enum'); diff --git a/src/DependencyInjection/RedeyeGraphQLExtension.php b/src/DependencyInjection/RedeyeGraphQLExtension.php index f4f71d34..f6c1c4a2 100644 --- a/src/DependencyInjection/RedeyeGraphQLExtension.php +++ b/src/DependencyInjection/RedeyeGraphQLExtension.php @@ -22,7 +22,9 @@ use Redeye\GraphQLBundle\EventListener\DebugListener; use Redeye\GraphQLBundle\EventListener\ErrorHandlerListener; use Redeye\GraphQLBundle\EventListener\ErrorLoggerListener; +use Redeye\GraphQLBundle\EventListener\InlineTraceListener; use Redeye\GraphQLBundle\Federation\FederatedSchemaBuilder; +use Redeye\GraphQLBundle\Federation\Tracing\TraceErrorFilter; use Redeye\GraphQLBundle\Request\Executor; use Symfony\Component\Config\FileLocator; use Symfony\Component\DependencyInjection\ContainerBuilder; @@ -54,6 +56,7 @@ public function load(array $configs, ContainerBuilder $container): void $this->setSchemaBuilderArguments($config, $container); $this->setSchemaArguments($config, $container); $this->setErrorHandler($config, $container); + $this->setInlineTrace($config, $container); $this->setSecurity($config, $container); $this->setConfigBuilders($config, $container); $this->setDebugListener($config, $container); @@ -175,6 +178,43 @@ private function setDebugListener(array $config, ContainerBuilder $container): v } } + /** + * Wires Apollo Federation inline tracing (ftv1). + * + * Must run after setErrorHandler(): the `unmodified` error policy reports the client-visible + * message, which means it needs the configured internal error message. + * + * @see docs/federation/inline-trace.md + */ + private function setInlineTrace(array $config, ContainerBuilder $container): void + { + $container->setParameter($this->getAlias().'.inline_trace', $config['inline_trace']['enabled']); + + if (!$config['inline_trace']['enabled']) { + return; + } + + $transformer = $config['inline_trace']['transformer_service']; + + $container->register(TraceErrorFilter::class) + ->setArguments([ + $config['inline_trace']['include_errors'], + $config['errors_handler']['internal_error_message'], + null === $transformer ? null : new Reference($transformer), + ]); + + $container->register(InlineTraceListener::class) + ->setArguments([ + new Reference('request_stack'), + new Reference(TraceErrorFilter::class), + ]) + ->addTag('kernel.event_listener', ['event' => Events::PRE_EXECUTOR, 'method' => 'onPreExecutor']) + // Ahead of ErrorHandlerListener, DebugListener and GraphQLCollector, which all sit at + // the default priority of 0. ErrorHandler rebuilds errors and drops their extensions, + // so the trace has to see them first. + ->addTag('kernel.event_listener', ['event' => Events::POST_EXECUTOR, 'method' => 'onPostExecutor', 'priority' => 100]); + } + private function setConfigBuilders(array $config, ContainerBuilder $container): void { foreach (BuilderProcessor::BUILDER_TYPES as $type) { diff --git a/src/EventListener/InlineTraceListener.php b/src/EventListener/InlineTraceListener.php new file mode 100644 index 00000000..f6c2c587 --- /dev/null +++ b/src/EventListener/InlineTraceListener.php @@ -0,0 +1,89 @@ +requestStack = $requestStack; + $this->errorFilter = $errorFilter; + } + + public function onPreExecutor(ExecutorArgumentsEvent $event): void + { + $request = $this->requestStack->getCurrentRequest(); + + // No request at all under bin/console, and none in in-process test helpers. + if (!$request instanceof Request || self::HEADER_VALUE !== $request->headers->get(self::HEADER)) { + return; + } + + $builder = new TraceTreeBuilder(); + $builder->startTiming(); + + $event->getContextValue()[self::CONTEXT_KEY] = $builder; + } + + public function onPostExecutor(ExecutorResultEvent $event): void + { + $builder = $event->getExecutorArguments()->getContextValue()[self::CONTEXT_KEY] ?? null; + + if (!$builder instanceof TraceTreeBuilder) { + return; + } + + $result = $event->getResult(); + + // Runs before ErrorHandlerListener (priority 100 vs. 0), so these are still the raw + // errors from execution, with their paths, nodes and extensions intact. + foreach ($result->errors ?? [] as $error) { + $traceError = $this->errorFilter->filter($error); + + if (null !== $traceError) { + $builder->addError($error->path, $traceError); + } + } + + $builder->stopTiming(); + + $result->extensions[self::EXTENSION_KEY] = base64_encode($builder->toProto()->serializeToString()); + } +} diff --git a/src/Executor/TracingReferenceExecutor.php b/src/Executor/TracingReferenceExecutor.php index 06a2c883..c7cf1ec8 100644 --- a/src/Executor/TracingReferenceExecutor.php +++ b/src/Executor/TracingReferenceExecutor.php @@ -1,8 +1,11 @@ Printer::doPrint($documentNode), 'operationName' => $operationName, ]; + $referenceExecutor->traceBuilder = self::findTraceBuilder($contextValue); $referenceExecutor->configureContext(); return $referenceExecutor; @@ -42,6 +57,25 @@ public static function create(PromiseAdapter $promiseAdapter, Schema $schema, Do return $referenceExecutor; } + /** + * @param mixed $contextValue + */ + private static function findTraceBuilder($contextValue): ?TraceTreeBuilder + { + if (!$contextValue instanceof ArrayAccess && !is_array($contextValue)) { + return null; + } + + $builder = $contextValue[InlineTraceListener::CONTEXT_KEY] ?? null; + + return $builder instanceof TraceTreeBuilder ? $builder : null; + } + + /** + * @param mixed $rootValue + * + * @return mixed the resolver's return value, or the Throwable it raised + */ protected function resolveFieldValueOrError(FieldDefinition $fieldDef, FieldNode $fieldNode, callable $resolveFn, $rootValue, ResolveInfo $info) { // Deliberately first: this is the equivalent of Apollo's willResolveField, and it must not @@ -81,8 +115,19 @@ protected function resolveFieldValueOrError(FieldDefinition $fieldDef, FieldNode SentrySdk::getCurrentHub()->setSpan($span); } + // Last before the call, unlike recordCacheControl() above: this one starts a clock, so the + // Sentry setup should not be counted against the field's own duration. + $endTrace = null !== $this->traceBuilder ? $this->traceBuilder->willResolveField($info) : null; + try { - return parent::resolveFieldValueOrError($fieldDef, $fieldNode, $resolveFn, $rootValue, $info); + $result = parent::resolveFieldValueOrError($fieldDef, $fieldNode, $resolveFn, $rootValue, $info); + } catch (Throwable $e) { + // The parent catches everything and returns it, so this is belt and braces. + if (null !== $endTrace) { + $endTrace(); + } + + throw $e; } finally { // We only have a span if we started a span earlier if (null !== $span) { @@ -92,6 +137,49 @@ protected function resolveFieldValueOrError(FieldDefinition $fieldDef, FieldNode SentrySdk::getCurrentHub()->setSpan($parent); } } + + if (null !== $endTrace) { + $this->recordFieldEnd($result, $endTrace); + } + + return $result; + } + + /** + * Stops the clock on a field: immediately for a plain value, or when its promise settles. + * + * getPromise() rather than the promise adapter directly -- DataLoader hands back a + * GraphQL\Executor\Promise\Promise, which SyncPromiseAdapter::isThenable() rejects, so + * convertThenable() would throw on the most common async case in this bundle. + * + * The derived promise is deliberately discarded: this is a side branch, and the original + * value must be returned unchanged so that completeValueCatchingError() still sees it. + * Because resolveFieldValueOrError() runs before completeValueCatchingError(), this handler + * is registered first and so records the end time before any child field is resolved. + * + * @param mixed $result + */ + private function recordFieldEnd($result, callable $endTrace): void + { + $promise = $this->getPromise($result); + + if (null === $promise) { + $endTrace(); + + return; + } + + $settle = static function () use ($endTrace): void { + try { + $endTrace(); + } catch (Throwable $e) { + // Tracing must never break execution. + } + }; + + // Both handlers return void and never rethrow: rethrowing would leave an unhandled + // rejection on this orphan branch, which Guzzle's adapter reports from a destructor. + $promise->then($settle, $settle); } /** @@ -134,9 +222,9 @@ private function shouldTraceFieldArgument(FieldArgument $arg): bool return false; } - private function configureContext() + private function configureContext(): void { - if (class_exists('Sentry\State\Scope') ) { + if (class_exists('Sentry\State\Scope')) { \Sentry\configureScope(function (Scope $scope): void { $scope->setContext('graphql_query', $this->sentryContext); }); diff --git a/src/Federation/Tracing/TraceError.php b/src/Federation/Tracing/TraceError.php new file mode 100644 index 00000000..d3903762 --- /dev/null +++ b/src/Federation/Tracing/TraceError.php @@ -0,0 +1,28 @@ + $locations 1-based source locations + * @param string $json the `{message, locations, path, extensions}` + * serialization of the policy-applied error + */ + public function __construct( + public string $message, + public array $locations, + public string $json + ) { + } +} diff --git a/src/Federation/Tracing/TraceErrorFilter.php b/src/Federation/Tracing/TraceErrorFilter.php new file mode 100644 index 00000000..c55b16d0 --- /dev/null +++ b/src/Federation/Tracing/TraceErrorFilter.php @@ -0,0 +1,103 @@ +'; + public const MASKED_BY = 'RedeyeGraphQLBundleInlineTrace'; + + private string $includeErrors; + private string $internalErrorMessage; + private ?TraceErrorTransformerInterface $transformer; + + public function __construct( + string $includeErrors, + string $internalErrorMessage, + ?TraceErrorTransformerInterface $transformer = null + ) { + $this->includeErrors = $includeErrors; + $this->internalErrorMessage = $internalErrorMessage; + $this->transformer = $transformer; + } + + /** + * @return TraceError|null null when the policy says to omit this error from the trace + */ + public function filter(Error $error): ?TraceError + { + $reported = $this->applyPolicy($error); + + if (null === $reported) { + return null; + } + + $locations = []; + foreach ($error->getLocations() as $location) { + $locations[] = ['line' => $location->line, 'column' => $location->column]; + } + + return new TraceError($reported->getMessage(), $locations, (string) json_encode($reported)); + } + + /** + * Rebuilds the error with a policy-approved message and extensions, always keeping the + * original's nodes, source, positions and path so that it stays attached to the same trace + * node and reports the same locations. + */ + private function applyPolicy(Error $error): ?Error + { + if (null !== $this->transformer) { + $transformed = $this->transformer->transform($error); + + if (null === $transformed) { + return null; + } + + return $this->rebuild($error, $transformed->getMessage(), $transformed->getExtensions() ?? []); + } + + if (self::UNMODIFIED === $this->includeErrors) { + // NOT $error->getMessage(): the bundle's ErrorHandler masks at response-format time, + // so the raw exception text (SQL, DSNs, file paths) is still on the Error object + // here. Report what the client would see instead. + $formatted = FormattedError::createFromException($error, DebugFlag::NONE, $this->internalErrorMessage); + + return $this->rebuild($error, (string) $formatted['message'], $formatted['extensions'] ?? []); + } + + return $this->rebuild($error, self::MASKED_MESSAGE, ['maskedBy' => self::MASKED_BY]); + } + + /** + * @param array $extensions + */ + private function rebuild(Error $error, string $message, array $extensions): Error + { + return new Error( + $message, + $error->nodes, + $error->getSource(), + $error->getPositions(), + $error->path, + null, + $extensions + ); + } +} diff --git a/src/Federation/Tracing/TraceErrorTransformerInterface.php b/src/Federation/Tracing/TraceErrorTransformerInterface.php new file mode 100644 index 00000000..0164dcdd --- /dev/null +++ b/src/Federation/Tracing/TraceErrorTransformerInterface.php @@ -0,0 +1,28 @@ +responseName = $responseName; + + return $node; + } + + public static function forIndex(int $index): self + { + $node = new self(); + $node->index = $index; + + return $node; + } +} diff --git a/src/Federation/Tracing/TraceTreeBuilder.php b/src/Federation/Tracing/TraceTreeBuilder.php new file mode 100644 index 00000000..90c18c0c --- /dev/null +++ b/src/Federation/Tracing/TraceTreeBuilder.php @@ -0,0 +1,261 @@ + + */ + private array $nodes; + + private int $nodeCount = 0; + private int $maxNodes; + + private ?int $startHrTime = null; + private ?float $startWallTime = null; + private ?float $endWallTime = null; + private int $durationNs = 0; + private bool $stopped = false; + + public function __construct(int $maxNodes = self::DEFAULT_MAX_NODES) + { + $this->maxNodes = $maxNodes; + $this->root = new TraceNode(); + $this->nodes = ['' => $this->root]; + } + + public function startTiming(): void + { + $this->startWallTime = microtime(true); + $this->startHrTime = hrtime(true); + } + + public function getRoot(): TraceNode + { + return $this->root; + } + + /** + * Records the start of a field resolution and returns the callback that records its end. + * + * The callback captures the node, never the ResolveInfo or the path: graphql-php reuses a + * single ResolveInfo across list items and mutates its `path` in completeListValue(), so a + * callback that re-derived the path when the field settles would write into the wrong node. + */ + public function willResolveField(ResolveInfo $info): callable + { + if ($this->stopped || $this->nodeCount >= $this->maxNodes) { + return static function (): void { + }; + } + + $node = $this->ensureNode($info->path); + $node->type = $info->returnType->toString(); + $node->parentType = $info->parentType->name; + $node->startTime = $this->elapsedNs(); + + $responseName = end($info->path); + if (is_string($responseName) && $responseName !== $info->fieldName) { + $node->originalFieldName = $info->fieldName; + } + + return function () use ($node): void { + $node->endTime = $this->elapsedNs(); + }; + } + + /** + * @param array|null $path null for parse, validation and other whole-operation + * errors, which belong on the root node + */ + public function addError(?array $path, TraceError $error): void + { + $node = null === $path || [] === $path ? $this->root : $this->ensureNode($path); + $node->errors[] = $error; + } + + public function stopTiming(): void + { + if ($this->stopped) { + return; + } + + $this->durationNs = $this->elapsedNs(); + $this->endWallTime = microtime(true); + $this->stopped = true; + + $this->backfillEndTimes($this->root); + } + + public function toProto(): Trace + { + $trace = new Trace(); + $trace->setDurationNs($this->durationNs); + // Apollo Server always sends 1; Studio scales field usage statistics by it. + $trace->setFieldExecutionWeight(1.0); + $trace->setRoot($this->toProtoNode($this->root)); + + if (null !== $this->startWallTime) { + $trace->setStartTime(self::toTimestamp($this->startWallTime)); + } + + if (null !== $this->endWallTime) { + $trace->setEndTime(self::toTimestamp($this->endWallTime)); + } + + return $trace; + } + + /** + * Returns the node for a response path, creating it and any missing ancestors. + * + * No resolver ever fires for a list index, so those nodes only ever come into existence + * here. Ancestors are walked up to the nearest known node and then created downwards, which + * makes insertion order irrelevant -- deferred list items can settle in any order. + * + * @param array $path + */ + private function ensureNode(array $path): TraceNode + { + $key = implode('.', $path); + if (isset($this->nodes[$key])) { + return $this->nodes[$key]; + } + + $parent = $this->ensureNode(array_slice($path, 0, -1)); + + $segment = end($path); + $node = is_int($segment) ? TraceNode::forIndex($segment) : TraceNode::forResponseName((string) $segment); + + $parent->children[] = $node; + $this->nodes[$key] = $node; + ++$this->nodeCount; + + return $node; + } + + /** + * A resolver whose promise never settles -- an undispatched DataLoader, say -- would leave + * end_time at 0, which Studio reads as a negative duration. Structural nodes, which never + * carry timings at all, are left alone. + */ + private function backfillEndTimes(TraceNode $node): void + { + if ($node->startTime > 0 && 0 === $node->endTime) { + $node->endTime = $this->durationNs; + } + + foreach ($node->children as $child) { + $this->backfillEndTimes($child); + } + } + + private function toProtoNode(TraceNode $node): ProtoNode + { + $proto = new ProtoNode(); + + if (null !== $node->responseName) { + $proto->setResponseName($node->responseName); + } elseif (null !== $node->index) { + $proto->setIndex($node->index); + } + + if ('' !== $node->type) { + $proto->setType($node->type); + } + + if ('' !== $node->parentType) { + $proto->setParentType($node->parentType); + } + + if ('' !== $node->originalFieldName) { + $proto->setOriginalFieldName($node->originalFieldName); + } + + $proto->setStartTime($node->startTime); + $proto->setEndTime($node->endTime); + + if ([] !== $node->errors) { + $proto->setError(array_map([self::class, 'toProtoError'], $node->errors)); + } + + if ([] !== $node->children) { + $proto->setChild(array_map([$this, 'toProtoNode'], $node->children)); + } + + return $proto; + } + + private static function toProtoError(TraceError $error): ProtoError + { + $proto = new ProtoError(); + $proto->setMessage($error->message); + $proto->setJson($error->json); + + if ([] !== $error->locations) { + $proto->setLocation(array_map( + static fn (array $location): ProtoLocation => (new ProtoLocation()) + ->setLine($location['line']) + ->setColumn($location['column']), + $error->locations + )); + } + + return $proto; + } + + private function elapsedNs(): int + { + if (null === $this->startHrTime) { + return 0; + } + + return hrtime(true) - $this->startHrTime; + } + + private static function toTimestamp(float $wallTime): Timestamp + { + $seconds = (int) floor($wallTime); + + return new Timestamp([ + 'seconds' => $seconds, + 'nanos' => (int) round(($wallTime - $seconds) * 1_000_000_000), + ]); + } +} diff --git a/tests/DependencyInjection/InlineTraceConfigurationTest.php b/tests/DependencyInjection/InlineTraceConfigurationTest.php new file mode 100644 index 00000000..173c9c4d --- /dev/null +++ b/tests/DependencyInjection/InlineTraceConfigurationTest.php @@ -0,0 +1,114 @@ +> $configs + * + * @return array + */ + private function process(array $configs): array + { + return (new Processor())->processConfiguration(new Configuration(false), $configs); + } + + public function testDisabledByDefault(): void + { + $config = $this->process([[]]); + + $this->assertFalse($config['inline_trace']['enabled']); + } + + public function testEnabledByDefaultForAFederatedSchema(): void + { + $config = $this->process([['federation' => true]]); + + $this->assertTrue($config['inline_trace']['enabled']); + } + + public function testCanBeDisabledOnAFederatedSchema(): void + { + $config = $this->process([['federation' => true, 'inline_trace' => false]]); + + $this->assertFalse($config['inline_trace']['enabled']); + } + + public function testCanBeEnabledOnANonFederatedSchema(): void + { + $config = $this->process([['inline_trace' => true]]); + + $this->assertTrue($config['inline_trace']['enabled']); + } + + /** + * Configuring options must not be a back door to switching the feature on. + */ + public function testSettingOptionsAloneDoesNotEnableItOnANonFederatedSchema(): void + { + $config = $this->process([['inline_trace' => ['include_errors' => 'unmodified']]]); + + $this->assertFalse($config['inline_trace']['enabled']); + $this->assertSame('unmodified', $config['inline_trace']['include_errors']); + } + + /** + * Symfony normalizes each config fragment on its own and only then merges them, so the + * federation default has to be resolved after the merge. A `beforeNormalization` on the root + * node would see these two fragments separately and get this wrong. + */ + public function testInheritsFederationAcrossSeparateConfigFragments(): void + { + $config = $this->process([ + ['federation' => true], + ['inline_trace' => ['include_errors' => 'unmodified']], + ]); + + $this->assertTrue($config['inline_trace']['enabled']); + $this->assertSame('unmodified', $config['inline_trace']['include_errors']); + } + + public function testDefaultsToMaskedErrors(): void + { + $config = $this->process([['federation' => true]]); + + $this->assertSame(TraceErrorFilter::MASKED, $config['inline_trace']['include_errors']); + } + + public function testDefaultsToNoTransformerService(): void + { + $config = $this->process([['federation' => true]]); + + $this->assertNull($config['inline_trace']['transformer_service']); + } + + public function testAcceptsATransformerService(): void + { + $config = $this->process([['inline_trace' => ['transformer_service' => 'App\\MyTransformer']]]); + + $this->assertSame('App\\MyTransformer', $config['inline_trace']['transformer_service']); + } + + public function testNullEnablesIt(): void + { + $config = $this->process([['inline_trace' => null]]); + + $this->assertTrue($config['inline_trace']['enabled']); + } + + public function testRejectsAnUnknownIncludeErrorsMode(): void + { + $this->expectException(InvalidConfigurationException::class); + + $this->process([['inline_trace' => ['include_errors' => 'bogus']]]); + } +} diff --git a/tests/EventListener/InlineTraceListenerTest.php b/tests/EventListener/InlineTraceListenerTest.php new file mode 100644 index 00000000..21000b67 --- /dev/null +++ b/tests/EventListener/InlineTraceListenerTest.php @@ -0,0 +1,250 @@ +push($request); + } + + return new InlineTraceListener( + $stack, + $filter ?? new TraceErrorFilter(TraceErrorFilter::MASKED, 'Internal server Error') + ); + } + + private function requestWithHeader(?string $value): Request + { + $request = new Request(); + if (null !== $value) { + $request->headers->set('apollo-federation-include-trace', $value); + } + + return $request; + } + + private function argumentsEvent(): ExecutorArgumentsEvent + { + $schema = new ExtensibleSchema([ + 'query' => new ObjectType([ + 'name' => 'Query', + 'fields' => ['me' => ['type' => Type::string()]], + ]), + ]); + + return ExecutorArgumentsEvent::create('default', $schema, '{ me }', new ArrayObject()); + } + + private function decode(ExecutionResult $result): Trace + { + $this->assertArrayHasKey('ftv1', $result->extensions); + + $trace = new Trace(); + $trace->mergeFromString((string) base64_decode($result->extensions['ftv1'], true)); + + return $trace; + } + + public function testStoresABuilderInTheContextWhenTheHeaderRequestsATrace(): void + { + $event = $this->argumentsEvent(); + + $this->listener($this->requestWithHeader('ftv1'))->onPreExecutor($event); + + $this->assertInstanceOf( + TraceTreeBuilder::class, + $event->getContextValue()[InlineTraceListener::CONTEXT_KEY] ?? null + ); + } + + public function testIgnoresARequestWithoutTheHeader(): void + { + $event = $this->argumentsEvent(); + + $this->listener($this->requestWithHeader(null))->onPreExecutor($event); + + $this->assertArrayNotHasKey(InlineTraceListener::CONTEXT_KEY, $event->getContextValue()); + } + + /** + * @dataProvider nonMatchingHeaderProvider + */ + public function testIgnoresAHeaderWithAnotherValue(string $value): void + { + $event = $this->argumentsEvent(); + + $this->listener($this->requestWithHeader($value))->onPreExecutor($event); + + $this->assertArrayNotHasKey(InlineTraceListener::CONTEXT_KEY, $event->getContextValue()); + } + + public function nonMatchingHeaderProvider(): iterable + { + yield 'empty' => ['']; + yield 'v1' => ['v1']; + yield 'ftv2' => ['ftv2']; + yield 'padded' => [' ftv1']; + } + + /** + * RequestStack is empty under bin/console and in in-process test helpers. + */ + public function testIgnoresExecutionWithNoCurrentRequest(): void + { + $event = $this->argumentsEvent(); + + $this->listener(null)->onPreExecutor($event); + + $this->assertArrayNotHasKey(InlineTraceListener::CONTEXT_KEY, $event->getContextValue()); + } + + public function testAddsNoExtensionWhenNoTraceWasStarted(): void + { + $arguments = $this->argumentsEvent(); + $listener = $this->listener($this->requestWithHeader(null)); + $listener->onPreExecutor($arguments); + + $result = new ExecutionResult(['me' => 'Ada']); + $listener->onPostExecutor(new ExecutorResultEvent($result, $arguments)); + + $this->assertSame([], $result->extensions); + } + + public function testEmitsABase64EncodedTraceOnTheResponse(): void + { + $arguments = $this->argumentsEvent(); + $listener = $this->listener($this->requestWithHeader('ftv1')); + $listener->onPreExecutor($arguments); + + $result = new ExecutionResult(['me' => 'Ada']); + $listener->onPostExecutor(new ExecutorResultEvent($result, $arguments)); + + $trace = $this->decode($result); + $this->assertGreaterThan(0, (int) $trace->getDurationNs()); + $this->assertNotNull($trace->getStartTime()); + $this->assertNotNull($trace->getEndTime()); + $this->assertSame(1.0, $trace->getFieldExecutionWeight()); + } + + public function testAttachesAPathedErrorToItsNode(): void + { + $arguments = $this->argumentsEvent(); + $listener = $this->listener($this->requestWithHeader('ftv1')); + $listener->onPreExecutor($arguments); + + $result = new ExecutionResult(null, [ + new Error('boom', null, new Source('{ me }'), [3], ['me'], new RuntimeException('boom')), + ]); + $listener->onPostExecutor(new ExecutorResultEvent($result, $arguments)); + + $root = $this->decode($result)->getRoot(); + $this->assertCount(0, $root->getError()); + + $me = $root->getChild()[0]; + $this->assertSame('me', $me->getResponseName()); + $this->assertSame('', $me->getError()[0]->getMessage()); + } + + /** + * A syntax or validation failure never resolves a field, but must still produce a trace. + */ + public function testEmitsATraceForAnOperationThatNeverExecuted(): void + { + $arguments = $this->argumentsEvent(); + $listener = $this->listener($this->requestWithHeader('ftv1')); + $listener->onPreExecutor($arguments); + + $result = new ExecutionResult(null, [new Error('Syntax Error: Unexpected ')]); + $listener->onPostExecutor(new ExecutorResultEvent($result, $arguments)); + + $root = $this->decode($result)->getRoot(); + $this->assertCount(1, $root->getError()); + $this->assertCount(0, $root->getChild()); + } + + public function testOmitsErrorsTheFilterDrops(): void + { + $dropEverything = new class() implements TraceErrorTransformerInterface { + public function transform(Error $error): ?Error + { + return null; + } + }; + $filter = new TraceErrorFilter(TraceErrorFilter::MASKED, 'Internal server Error', $dropEverything); + + $arguments = $this->argumentsEvent(); + $listener = $this->listener($this->requestWithHeader('ftv1'), $filter); + $listener->onPreExecutor($arguments); + + $result = new ExecutionResult(null, [new Error('boom')]); + $listener->onPostExecutor(new ExecutorResultEvent($result, $arguments)); + + $this->assertCount(0, $this->decode($result)->getRoot()->getError()); + } + + /** + * Batched requests share one listener service but get one context each, so their traces must + * not bleed into one another. + */ + public function testEachExecutionGetsItsOwnTrace(): void + { + $listener = $this->listener($this->requestWithHeader('ftv1')); + + $first = $this->argumentsEvent(); + $listener->onPreExecutor($first); + $second = $this->argumentsEvent(); + $listener->onPreExecutor($second); + + $this->assertNotSame( + $first->getContextValue()[InlineTraceListener::CONTEXT_KEY], + $second->getContextValue()[InlineTraceListener::CONTEXT_KEY] + ); + + $firstResult = new ExecutionResult(null, [new Error('only in the first')]); + $listener->onPostExecutor(new ExecutorResultEvent($firstResult, $first)); + $secondResult = new ExecutionResult(['me' => 'Ada']); + $listener->onPostExecutor(new ExecutorResultEvent($secondResult, $second)); + + $this->assertCount(1, $this->decode($firstResult)->getRoot()->getError()); + $this->assertCount(0, $this->decode($secondResult)->getRoot()->getError()); + } + + public function testLeavesExistingExtensionsAlone(): void + { + $arguments = $this->argumentsEvent(); + $listener = $this->listener($this->requestWithHeader('ftv1')); + $listener->onPreExecutor($arguments); + + $result = new ExecutionResult(['me' => 'Ada']); + $result->extensions['debug'] = ['executionTime' => '1 ms']; + $listener->onPostExecutor(new ExecutorResultEvent($result, $arguments)); + + $this->assertSame(['executionTime' => '1 ms'], $result->extensions['debug']); + $this->assertArrayHasKey('ftv1', $result->extensions); + } +} diff --git a/tests/Executor/TracingReferenceExecutorTest.php b/tests/Executor/TracingReferenceExecutorTest.php new file mode 100644 index 00000000..f13fbdbe --- /dev/null +++ b/tests/Executor/TracingReferenceExecutorTest.php @@ -0,0 +1,214 @@ +previousFactory = Executor::getImplementationFactory(); + Executor::setImplementationFactory([TracingReferenceExecutor::class, 'create']); + } + + protected function tearDown(): void + { + Executor::setImplementationFactory($this->previousFactory); + } + + private function schema(): Schema + { + $user = new ObjectType([ + 'name' => 'User', + 'fields' => [ + 'name' => [ + 'type' => Type::string(), + 'resolve' => static fn (array $user): string => $user['name'], + ], + 'slowName' => [ + 'type' => Type::string(), + // A deferred field: the value is not available when the resolver returns. + 'resolve' => static fn (array $user): Deferred => new Deferred(static function () use ($user): string { + usleep(3000); + + return $user['name']; + }), + ], + 'broken' => [ + 'type' => Type::string(), + 'resolve' => static function (): string { + throw new RuntimeException('resolver exploded'); + }, + ], + ], + ]); + + return new Schema([ + 'query' => new ObjectType([ + 'name' => 'Query', + 'fields' => [ + 'me' => [ + 'type' => Type::nonNull($user), + 'resolve' => static fn (): array => ['name' => 'Ada'], + ], + 'users' => [ + 'type' => Type::listOf($user), + 'resolve' => static fn (): array => [['name' => 'Ada'], ['name' => 'Grace']], + ], + ], + ]), + ]); + } + + /** + * @return array{0: TraceTreeBuilder, 1: \GraphQL\Executor\ExecutionResult} + */ + private function execute(string $query, bool $withTracing = true): array + { + $builder = new TraceTreeBuilder(); + $builder->startTiming(); + + $context = new ArrayObject(); + if ($withTracing) { + $context[InlineTraceListener::CONTEXT_KEY] = $builder; + } + + $result = GraphQL::executeQuery($this->schema(), $query, null, $context); + + return [$builder, $result]; + } + + private function childNamed(TraceNode $node, string $responseName): TraceNode + { + foreach ($node->children as $child) { + if ($responseName === $child->responseName) { + return $child; + } + } + + self::fail(sprintf('no child named "%s"', $responseName)); + } + + public function testRecordsANodePerResolvedField(): void + { + [$builder, $result] = $this->execute('{ me { name } }'); + + $this->assertSame(['me' => ['name' => 'Ada']], $result->data); + + $me = $this->childNamed($builder->getRoot(), 'me'); + $this->assertSame('User!', $me->type); + $this->assertSame('Query', $me->parentType); + $this->assertGreaterThan(0, $me->endTime); + + $name = $this->childNamed($me, 'name'); + $this->assertSame('String', $name->type); + $this->assertSame('User', $name->parentType); + } + + public function testRecordsIndexNodesForListItems(): void + { + [$builder] = $this->execute('{ users { name } }'); + + $users = $this->childNamed($builder->getRoot(), 'users'); + $this->assertCount(2, $users->children); + + $this->assertSame(0, $users->children[0]->index); + $this->assertSame(1, $users->children[1]->index); + $this->assertSame('name', $users->children[0]->children[0]->responseName); + $this->assertSame('User', $users->children[0]->children[0]->parentType); + } + + public function testRecordsTheSchemaFieldNameForAnAliasedField(): void + { + [$builder] = $this->execute('{ currentUser: me { name } }'); + + $node = $this->childNamed($builder->getRoot(), 'currentUser'); + $this->assertSame('me', $node->originalFieldName); + } + + public function testRecordsTypenameFields(): void + { + [$builder] = $this->execute('{ me { __typename } }'); + + $me = $this->childNamed($builder->getRoot(), 'me'); + $this->assertSame('__typename', $this->childNamed($me, '__typename')->responseName); + } + + /** + * The end time of a deferred field must be recorded when its value settles, not when the + * resolver returns the promise. Recording synchronously would give a duration of very nearly + * zero; the resolver sleeps 3ms, so the gap is unmistakable. + */ + public function testRecordsTheEndTimeOfADeferredFieldWhenItSettles(): void + { + [$builder] = $this->execute('{ me { slowName } }'); + + $slowName = $this->childNamed($this->childNamed($builder->getRoot(), 'me'), 'slowName'); + + $this->assertGreaterThan( + 2_000_000, + $slowName->endTime - $slowName->startTime, + 'a deferred field was timed synchronously instead of on settle' + ); + } + + public function testDeferredFieldsStillProduceOrderedTimings(): void + { + [$builder] = $this->execute('{ me { slowName name } }'); + + $me = $this->childNamed($builder->getRoot(), 'me'); + foreach ($me->children as $child) { + $this->assertGreaterThanOrEqual($child->startTime, $child->endTime, $child->responseName); + $this->assertGreaterThan(0, $child->endTime, $child->responseName); + } + } + + public function testRecordsAFieldWhoseResolverThrows(): void + { + [$builder, $result] = $this->execute('{ me { broken } }'); + + $this->assertCount(1, $result->errors); + + $broken = $this->childNamed($this->childNamed($builder->getRoot(), 'me'), 'broken'); + $this->assertSame('String', $broken->type); + $this->assertGreaterThan(0, $broken->endTime, 'a throwing resolver must still be timed'); + } + + public function testExecutesNormallyWithNoTraceInTheContext(): void + { + [$builder, $result] = $this->execute('{ me { name } }', false); + + $this->assertSame(['me' => ['name' => 'Ada']], $result->data); + $this->assertSame([], $builder->getRoot()->children); + } + + public function testReturnsTheOriginalResolverValueForDeferredFields(): void + { + [, $result] = $this->execute('{ me { slowName } }'); + + $this->assertSame(['me' => ['slowName' => 'Ada']], $result->data); + $this->assertSame([], $result->errors); + } +} diff --git a/tests/Federation/Tracing/TraceErrorFilterTest.php b/tests/Federation/Tracing/TraceErrorFilterTest.php new file mode 100644 index 00000000..5f37a601 --- /dev/null +++ b/tests/Federation/Tracing/TraceErrorFilterTest.php @@ -0,0 +1,238 @@ +source(), + [13], + ['me', 'name'], + new RuntimeException($rawMessage) + ); + } + + private function clientSafeError(string $message = 'You may not do that'): Error + { + return new Error( + $message, + null, + $this->source(), + [13], + ['me', 'name'], + new UserError($message) + ); + } + + public function testMaskedReplacesTheMessage(): void + { + $filter = new TraceErrorFilter(TraceErrorFilter::MASKED, self::INTERNAL_MESSAGE); + + $traced = $filter->filter($this->internalError()); + + $this->assertNotNull($traced); + $this->assertSame('', $traced->message); + } + + public function testMaskedPreservesLocations(): void + { + $filter = new TraceErrorFilter(TraceErrorFilter::MASKED, self::INTERNAL_MESSAGE); + + $traced = $filter->filter($this->internalError()); + + $this->assertNotNull($traced); + $this->assertSame([['line' => 3, 'column' => 5]], $traced->locations); + } + + public function testMaskedJsonCarriesMaskedByAndPathButNotTheRawMessage(): void + { + $filter = new TraceErrorFilter(TraceErrorFilter::MASKED, self::INTERNAL_MESSAGE); + + $traced = $filter->filter($this->internalError()); + + $this->assertNotNull($traced); + $decoded = json_decode($traced->json, true); + + $this->assertSame('', $decoded['message']); + $this->assertSame(['me', 'name'], $decoded['path']); + $this->assertSame(TraceErrorFilter::MASKED_BY, $decoded['extensions']['maskedBy']); + $this->assertStringNotContainsString('SQLSTATE', $traced->json); + } + + public function testMaskedDropsOriginalExtensions(): void + { + $error = new Error('boom', null, $this->source(), [13], ['me'], null, ['secret' => 'do-not-leak']); + + $filter = new TraceErrorFilter(TraceErrorFilter::MASKED, self::INTERNAL_MESSAGE); + $traced = $filter->filter($error); + + $this->assertNotNull($traced); + $this->assertStringNotContainsString('do-not-leak', $traced->json); + } + + /** + * The bundle's ErrorHandler masks at response-format time, not on the Error object, so the + * raw exception text is still present while the trace is being built. `unmodified` must + * report what the client sees -- never the raw message. + */ + public function testUnmodifiedReportsTheClientVisibleMessageNotTheRawException(): void + { + $filter = new TraceErrorFilter(TraceErrorFilter::UNMODIFIED, self::INTERNAL_MESSAGE); + + $traced = $filter->filter($this->internalError()); + + $this->assertNotNull($traced); + $this->assertSame(self::INTERNAL_MESSAGE, $traced->message); + $this->assertStringNotContainsString('SQLSTATE', $traced->json); + } + + public function testUnmodifiedReportsTheRealMessageForClientSafeErrors(): void + { + $filter = new TraceErrorFilter(TraceErrorFilter::UNMODIFIED, self::INTERNAL_MESSAGE); + + $traced = $filter->filter($this->clientSafeError()); + + $this->assertNotNull($traced); + $this->assertSame('You may not do that', $traced->message); + } + + public function testUnmodifiedPreservesLocationsAndPath(): void + { + $filter = new TraceErrorFilter(TraceErrorFilter::UNMODIFIED, self::INTERNAL_MESSAGE); + + $traced = $filter->filter($this->clientSafeError()); + + $this->assertNotNull($traced); + $this->assertSame([['line' => 3, 'column' => 5]], $traced->locations); + $this->assertSame(['me', 'name'], json_decode($traced->json, true)['path']); + } + + public function testTransformerReturningNullDropsTheError(): void + { + $filter = new TraceErrorFilter( + TraceErrorFilter::MASKED, + self::INTERNAL_MESSAGE, + $this->transformer(static fn (Error $e): ?Error => null) + ); + + $this->assertNull($filter->filter($this->internalError())); + } + + public function testTransformerOverridesTheIncludeErrorsMode(): void + { + $filter = new TraceErrorFilter( + TraceErrorFilter::MASKED, + self::INTERNAL_MESSAGE, + $this->transformer(static fn (Error $e): ?Error => new Error('rewritten')) + ); + + $traced = $filter->filter($this->internalError()); + + $this->assertNotNull($traced); + $this->assertSame('rewritten', $traced->message, 'the transformer must win over `masked`'); + } + + /** + * A transformer may only change the message and extensions. Locations and path always come + * from the original error, so the error still lands on the right trace node. + */ + public function testTransformerCannotMoveTheErrorToAnotherNode(): void + { + $filter = new TraceErrorFilter( + TraceErrorFilter::MASKED, + self::INTERNAL_MESSAGE, + $this->transformer(static fn (Error $e): ?Error => new Error('rewritten', null, null, [], ['somewhere', 'else'])) + ); + + $traced = $filter->filter($this->internalError()); + + $this->assertNotNull($traced); + $this->assertSame(['me', 'name'], json_decode($traced->json, true)['path']); + $this->assertSame([['line' => 3, 'column' => 5]], $traced->locations); + } + + public function testTransformerCanSetExtensions(): void + { + $filter = new TraceErrorFilter( + TraceErrorFilter::MASKED, + self::INTERNAL_MESSAGE, + $this->transformer(static fn (Error $e): ?Error => new Error('rewritten', null, null, [], null, null, ['code' => 'E17'])) + ); + + $traced = $filter->filter($this->internalError()); + + $this->assertNotNull($traced); + $this->assertSame('E17', json_decode($traced->json, true)['extensions']['code']); + } + + public function testTransformerReceivesTheOriginalError(): void + { + $seen = null; + $filter = new TraceErrorFilter( + TraceErrorFilter::MASKED, + self::INTERNAL_MESSAGE, + $this->transformer(static function (Error $e) use (&$seen): ?Error { + $seen = $e->getMessage(); + + return $e; + }) + ); + + $filter->filter($this->internalError('the raw one')); + + $this->assertSame('the raw one', $seen); + } + + public function testErrorWithoutLocationsProducesNoLocations(): void + { + $filter = new TraceErrorFilter(TraceErrorFilter::MASKED, self::INTERNAL_MESSAGE); + + $traced = $filter->filter(new Error('boom')); + + $this->assertNotNull($traced); + $this->assertSame([], $traced->locations); + } + + private function transformer(callable $fn): TraceErrorTransformerInterface + { + return new class($fn) implements TraceErrorTransformerInterface { + /** @var callable */ + private $fn; + + public function __construct(callable $fn) + { + $this->fn = $fn; + } + + public function transform(Error $error): ?Error + { + return ($this->fn)($error); + } + }; + } +} diff --git a/tests/Federation/Tracing/TraceSerializationTest.php b/tests/Federation/Tracing/TraceSerializationTest.php new file mode 100644 index 00000000..8954e8d7 --- /dev/null +++ b/tests/Federation/Tracing/TraceSerializationTest.php @@ -0,0 +1,220 @@ +setResponseName('currentUser') + ->setOriginalFieldName('me') + ->setType('User!') + ->setParentType('Query') + ->setStartTime(1000) + ->setEndTime(2000); + + $root = new TraceNode(); + $root->setChild([$child]); + + $trace = (new Trace()) + ->setStartTime(new Timestamp(['seconds' => 1660000000, 'nanos' => 123000000])) + ->setEndTime(new Timestamp(['seconds' => 1660000001, 'nanos' => 456000000])) + ->setDurationNs(1333000000) + ->setFieldExecutionWeight(1.0) + ->setRoot($root); + + $decoded = new Trace(); + $decoded->mergeFromString($trace->serializeToString()); + + $this->assertSame(1660000000, (int) $decoded->getStartTime()->getSeconds()); + $this->assertSame(123000000, $decoded->getStartTime()->getNanos()); + $this->assertSame(1660000001, (int) $decoded->getEndTime()->getSeconds()); + $this->assertSame(456000000, $decoded->getEndTime()->getNanos()); + $this->assertSame(1333000000, (int) $decoded->getDurationNs()); + $this->assertSame(1.0, $decoded->getFieldExecutionWeight()); + + $decodedChild = $decoded->getRoot()->getChild()[0]; + $this->assertSame('currentUser', $decodedChild->getResponseName()); + $this->assertSame('me', $decodedChild->getOriginalFieldName()); + $this->assertSame('User!', $decodedChild->getType()); + $this->assertSame('Query', $decodedChild->getParentType()); + $this->assertSame(1000, (int) $decodedChild->getStartTime()); + $this->assertSame(2000, (int) $decodedChild->getEndTime()); + } + + public function testIndexNodeRoundTrips(): void + { + $root = new TraceNode(); + $root->setChild([(new TraceNode())->setIndex(3)]); + + $decoded = new Trace(); + $decoded->mergeFromString((new Trace())->setRoot($root)->serializeToString()); + + $node = $decoded->getRoot()->getChild()[0]; + $this->assertSame(3, $node->getIndex()); + $this->assertSame('index', $node->getId(), 'the `id` oneof should report `index` as the set field'); + } + + public function testErrorRoundTrips(): void + { + $error = (new TraceError()) + ->setMessage('') + ->setJson('{"message":""}'); + $error->setLocation([(new TraceLocation())->setLine(2)->setColumn(7)]); + + $root = new TraceNode(); + $root->setError([$error]); + + $decoded = new Trace(); + $decoded->mergeFromString((new Trace())->setRoot($root)->serializeToString()); + + $decodedError = $decoded->getRoot()->getError()[0]; + $this->assertSame('', $decodedError->getMessage()); + $this->assertSame('{"message":""}', $decodedError->getJson()); + $this->assertSame(2, $decodedError->getLocation()[0]->getLine()); + $this->assertSame(7, $decodedError->getLocation()[0]->getColumn()); + } + + /** + * A round-trip cannot catch a transposed field number -- it would encode and decode with the + * same wrong tag. Asserting the raw tag bytes pins the numbering to Apollo's reports.proto. + * + * Tag byte = (field_number << 3) | wire_type. + * + * @dataProvider tagByteProvider + */ + public function testFieldNumbersMatchApolloReportsProto(string $description, Trace $trace, int $expectedTagByte): void + { + $bytes = $trace->serializeToString(); + + $this->assertSame( + $expectedTagByte, + ord($bytes[0]), + sprintf('%s: expected leading tag byte 0x%02X, got 0x%02X', $description, $expectedTagByte, ord($bytes[0])) + ); + } + + public function tagByteProvider(): iterable + { + // duration_ns = field 11, varint (wire type 0) => (11 << 3) | 0 = 88 = 0x58 + yield 'Trace.duration_ns is field 11' => [ + 'Trace.duration_ns', + (new Trace())->setDurationNs(42), + 0x58, + ]; + + // root = field 14, length-delimited (wire type 2) => (14 << 3) | 2 = 114 = 0x72 + yield 'Trace.root is field 14' => [ + 'Trace.root', + (new Trace())->setRoot(new TraceNode()), + 0x72, + ]; + + // end_time = field 3, length-delimited => (3 << 3) | 2 = 26 = 0x1A + yield 'Trace.end_time is field 3' => [ + 'Trace.end_time', + (new Trace())->setEndTime(new Timestamp(['seconds' => 1])), + 0x1A, + ]; + + // start_time = field 4, length-delimited => (4 << 3) | 2 = 34 = 0x22 + yield 'Trace.start_time is field 4' => [ + 'Trace.start_time', + (new Trace())->setStartTime(new Timestamp(['seconds' => 1])), + 0x22, + ]; + + // field_execution_weight = field 31, 64-bit (wire type 1) => (31 << 3) | 1 = 249 = 0xF9 + yield 'Trace.field_execution_weight is field 31' => [ + 'Trace.field_execution_weight', + (new Trace())->setFieldExecutionWeight(1.0), + 0xF9, + ]; + } + + /** + * @dataProvider nodeTagByteProvider + */ + public function testNodeFieldNumbersMatchApolloReportsProto(string $description, TraceNode $node, int $expectedTagByte): void + { + $bytes = $node->serializeToString(); + + $this->assertSame( + $expectedTagByte, + ord($bytes[0]), + sprintf('%s: expected leading tag byte 0x%02X, got 0x%02X', $description, $expectedTagByte, ord($bytes[0])) + ); + } + + public function nodeTagByteProvider(): iterable + { + // response_name = 1, length-delimited => (1 << 3) | 2 = 10 = 0x0A + yield 'Node.response_name is field 1' => ['Node.response_name', (new TraceNode())->setResponseName('a'), 0x0A]; + // index = 2, varint => (2 << 3) | 0 = 16 = 0x10 + yield 'Node.index is field 2' => ['Node.index', (new TraceNode())->setIndex(1), 0x10]; + // type = 3, length-delimited => (3 << 3) | 2 = 26 = 0x1A + yield 'Node.type is field 3' => ['Node.type', (new TraceNode())->setType('a'), 0x1A]; + // start_time = 8, varint => (8 << 3) | 0 = 64 = 0x40 + yield 'Node.start_time is field 8' => ['Node.start_time', (new TraceNode())->setStartTime(1), 0x40]; + // end_time = 9, varint => (9 << 3) | 0 = 72 = 0x48 + yield 'Node.end_time is field 9' => ['Node.end_time', (new TraceNode())->setEndTime(1), 0x48]; + // parent_type = 13, length-delimited => (13 << 3) | 2 = 106 = 0x6A + yield 'Node.parent_type is field 13' => ['Node.parent_type', (new TraceNode())->setParentType('a'), 0x6A]; + // original_field_name = 14, length-delimited => (14 << 3) | 2 = 114 = 0x72 + yield 'Node.original_field_name is field 14' => ['Node.original_field_name', (new TraceNode())->setOriginalFieldName('a'), 0x72]; + } + + /** + * The only test that proves interop: a real ftv1 payload emitted by Apollo Server, parsed + * with *our* generated classes. If our field numbers or wire types diverge from upstream, + * the decoded values come out wrong or missing. + * + * @see tests/Federation/Tracing/fixtures/README.md for how the fixture was produced. + */ + public function testDecodesGoldenApolloPayload(): void + { + $base64 = trim((string) file_get_contents(__DIR__.'/fixtures/apollo-ftv1.b64')); + + $trace = new Trace(); + $trace->mergeFromString((string) base64_decode($base64, true)); + + $this->assertGreaterThan(0, (int) $trace->getDurationNs(), 'duration_ns did not decode'); + $this->assertNotNull($trace->getStartTime(), 'start_time did not decode'); + $this->assertNotNull($trace->getEndTime(), 'end_time did not decode'); + $this->assertNotNull($trace->getRoot(), 'root did not decode'); + + $children = iterator_to_array($trace->getRoot()->getChild()); + $this->assertCount(1, $children); + + $me = $children[0]; + $this->assertSame('me', $me->getResponseName()); + $this->assertSame('User!', $me->getType()); + $this->assertSame('Query', $me->getParentType()); + $this->assertGreaterThan(0, (int) $me->getEndTime()); + + $name = iterator_to_array($me->getChild())[0]; + $this->assertSame('name', $name->getResponseName()); + $this->assertSame('String', $name->getType()); + $this->assertSame('User', $name->getParentType()); + } +} diff --git a/tests/Federation/Tracing/TraceTreeBuilderTest.php b/tests/Federation/Tracing/TraceTreeBuilderTest.php new file mode 100644 index 00000000..b7e84c5b --- /dev/null +++ b/tests/Federation/Tracing/TraceTreeBuilderTest.php @@ -0,0 +1,324 @@ +user = new ObjectType([ + 'name' => 'User', + 'fields' => [ + 'name' => ['type' => Type::string()], + ], + ]); + + $this->query = new ObjectType([ + 'name' => 'Query', + 'fields' => [ + 'me' => ['type' => Type::nonNull($this->user)], + 'users' => ['type' => Type::listOf($this->user)], + ], + ]); + + $this->schema = new Schema(['query' => $this->query]); + } + + /** + * @param list $path + */ + private function resolveInfo(ObjectType $parentType, string $fieldName, array $path): ResolveInfo + { + return new ResolveInfo( + $parentType->getField($fieldName), + [], + $parentType, + $path, + $this->schema, + [], + null, + new OperationDefinitionNode([ + 'name' => new NameNode(['value' => 'Test']), + 'operation' => 'query', + 'selectionSet' => new SelectionSetNode(['selections' => []]), + 'variableDefinitions' => [], + 'directives' => [], + ]), + [] + ); + } + + private function startedBuilder(): TraceTreeBuilder + { + $builder = new TraceTreeBuilder(); + $builder->startTiming(); + + return $builder; + } + + public function testRootNodeHasNoIdentityAndNoTimings(): void + { + $root = $this->startedBuilder()->getRoot(); + + $this->assertNull($root->responseName); + $this->assertNull($root->index); + $this->assertSame('', $root->type); + $this->assertSame('', $root->parentType); + $this->assertSame(0, $root->startTime); + $this->assertSame(0, $root->endTime); + } + + public function testResolvedFieldBecomesChildOfRootWithTypeAndParentType(): void + { + $builder = $this->startedBuilder(); + + $builder->willResolveField($this->resolveInfo($this->query, 'me', ['me'])); + + $children = $builder->getRoot()->children; + $this->assertCount(1, $children); + $this->assertSame('me', $children[0]->responseName); + $this->assertSame('User!', $children[0]->type); + $this->assertSame('Query', $children[0]->parentType); + } + + public function testEndCallbackRecordsEndTimeAfterStartTime(): void + { + $builder = $this->startedBuilder(); + + $end = $builder->willResolveField($this->resolveInfo($this->query, 'me', ['me'])); + $end(); + + $node = $builder->getRoot()->children[0]; + $this->assertGreaterThan(0, $node->endTime); + $this->assertGreaterThanOrEqual($node->startTime, $node->endTime); + } + + public function testAliasedFieldRecordsOriginalFieldName(): void + { + $builder = $this->startedBuilder(); + + // `{ currentUser: me { ... } }` -- path carries the alias, fieldName the schema name. + $builder->willResolveField($this->resolveInfo($this->query, 'me', ['currentUser'])); + + $node = $builder->getRoot()->children[0]; + $this->assertSame('currentUser', $node->responseName); + $this->assertSame('me', $node->originalFieldName); + } + + public function testUnaliasedFieldLeavesOriginalFieldNameEmpty(): void + { + $builder = $this->startedBuilder(); + + $builder->willResolveField($this->resolveInfo($this->query, 'me', ['me'])); + + $this->assertSame('', $builder->getRoot()->children[0]->originalFieldName); + } + + /** + * No resolver ever fires for a list index, so the builder has to synthesise the + * intermediate node when a descendant is resolved. + */ + public function testListIndexAncestorIsSynthesised(): void + { + $builder = $this->startedBuilder(); + + $builder->willResolveField($this->resolveInfo($this->user, 'name', ['users', 0, 'name'])); + + $users = $builder->getRoot()->children[0]; + $this->assertSame('users', $users->responseName); + $this->assertSame('', $users->type, 'a synthesised ancestor has no type'); + + $index = $users->children[0]; + $this->assertNull($index->responseName); + $this->assertSame(0, $index->index); + $this->assertSame('', $index->type, 'an index node is structural only'); + $this->assertSame(0, $index->startTime); + + $name = $index->children[0]; + $this->assertSame('name', $name->responseName); + $this->assertSame('String', $name->type); + $this->assertSame('User', $name->parentType); + } + + public function testSiblingListItemsShareOneParentNode(): void + { + $builder = $this->startedBuilder(); + + $builder->willResolveField($this->resolveInfo($this->user, 'name', ['users', 0, 'name'])); + $builder->willResolveField($this->resolveInfo($this->user, 'name', ['users', 1, 'name'])); + + $users = $builder->getRoot()->children; + $this->assertCount(1, $users, 'both items must hang off a single `users` node'); + $this->assertCount(2, $users[0]->children); + $this->assertSame(0, $users[0]->children[0]->index); + $this->assertSame(1, $users[0]->children[1]->index); + } + + public function testAncestorSynthesisIsOrderIndependent(): void + { + $builder = $this->startedBuilder(); + + // Deferred items can settle out of order. + $builder->willResolveField($this->resolveInfo($this->user, 'name', ['users', 2, 'name'])); + $builder->willResolveField($this->resolveInfo($this->user, 'name', ['users', 0, 'name'])); + + $indices = array_map( + static fn (TraceNode $n): ?int => $n->index, + $builder->getRoot()->children[0]->children + ); + $this->assertSame([2, 0], $indices); + } + + /** + * graphql-php reuses one ResolveInfo across list items and mutates its `path` in + * completeListValue(). An end callback that re-derives the path at settle time would + * therefore write into the wrong node -- it must capture the node itself. + */ + public function testEndCallbackIsImmuneToResolveInfoPathMutation(): void + { + $builder = $this->startedBuilder(); + + $info = $this->resolveInfo($this->user, 'name', ['users', 0, 'name']); + $end = $builder->willResolveField($info); + + $info->path = ['users', 1, 'name']; + $end(); + + $indexZero = $builder->getRoot()->children[0]->children[0]; + $this->assertSame(0, $indexZero->index); + $this->assertGreaterThan(0, $indexZero->children[0]->endTime, 'end time landed on the wrong node'); + } + + public function testErrorWithMatchingPathAttachesToThatNode(): void + { + $builder = $this->startedBuilder(); + $builder->willResolveField($this->resolveInfo($this->query, 'me', ['me'])); + + $builder->addError(['me'], new TraceError('boom', [], '{}')); + + $this->assertCount(0, $builder->getRoot()->errors); + $this->assertCount(1, $builder->getRoot()->children[0]->errors); + $this->assertSame('boom', $builder->getRoot()->children[0]->errors[0]->message); + } + + public function testErrorWithoutPathAttachesToRoot(): void + { + $builder = $this->startedBuilder(); + + $builder->addError(null, new TraceError('Syntax Error', [], '{}')); + + $this->assertCount(1, $builder->getRoot()->errors); + $this->assertSame('Syntax Error', $builder->getRoot()->errors[0]->message); + } + + public function testErrorWithUnresolvedPathCreatesTheNode(): void + { + $builder = $this->startedBuilder(); + + $builder->addError(['users', 0, 'name'], new TraceError('boom', [], '{}')); + + $name = $builder->getRoot()->children[0]->children[0]->children[0]; + $this->assertSame('name', $name->responseName); + $this->assertCount(1, $name->errors); + } + + public function testStopTimingSetsDurationAndFieldExecutionWeight(): void + { + $builder = $this->startedBuilder(); + $builder->stopTiming(); + + $trace = $builder->toProto(); + $this->assertGreaterThan(0, (int) $trace->getDurationNs()); + $this->assertSame(1.0, $trace->getFieldExecutionWeight()); + $this->assertGreaterThan(0, (int) $trace->getStartTime()->getSeconds()); + $this->assertGreaterThan(0, (int) $trace->getEndTime()->getSeconds()); + } + + /** + * A resolver that returns a promise which never settles (e.g. an undispatched DataLoader) + * would otherwise leave end_time at 0, which reads as a negative duration in Studio. + */ + public function testStopTimingBackfillsMissingEndTimes(): void + { + $builder = $this->startedBuilder(); + $builder->willResolveField($this->resolveInfo($this->query, 'me', ['me'])); + + $builder->stopTiming(); + + $node = $builder->getRoot()->children[0]; + $this->assertSame((int) $builder->toProto()->getDurationNs(), $node->endTime); + } + + public function testStopTimingLeavesStructuralNodesUntouched(): void + { + $builder = $this->startedBuilder(); + $builder->willResolveField($this->resolveInfo($this->user, 'name', ['users', 0, 'name'])); + + $builder->stopTiming(); + + $index = $builder->getRoot()->children[0]->children[0]; + $this->assertSame(0, $index->startTime); + $this->assertSame(0, $index->endTime, 'index nodes never carry timings'); + } + + public function testStopsRecordingOnceTheNodeCapIsReached(): void + { + $builder = new TraceTreeBuilder(3); + $builder->startTiming(); + + for ($i = 0; $i < 10; ++$i) { + $end = $builder->willResolveField($this->resolveInfo($this->query, 'me', ['me'.$i])); + $end(); + } + + $this->assertLessThanOrEqual(3, count($builder->getRoot()->children)); + } + + public function testProtoMirrorsTheBuiltTree(): void + { + $builder = $this->startedBuilder(); + $end = $builder->willResolveField($this->resolveInfo($this->user, 'name', ['users', 0, 'name'])); + $end(); + $builder->addError(['users', 0, 'name'], new TraceError('boom', [['line' => 2, 'column' => 5]], '{"m":1}')); + $builder->stopTiming(); + + $root = $builder->toProto()->getRoot(); + + $users = $root->getChild()[0]; + $this->assertSame('users', $users->getResponseName()); + + $index = $users->getChild()[0]; + $this->assertSame(0, $index->getIndex()); + + $name = $index->getChild()[0]; + $this->assertSame('name', $name->getResponseName()); + $this->assertSame('String', $name->getType()); + $this->assertSame('User', $name->getParentType()); + $this->assertGreaterThan(0, (int) $name->getEndTime()); + + $error = $name->getError()[0]; + $this->assertSame('boom', $error->getMessage()); + $this->assertSame('{"m":1}', $error->getJson()); + $this->assertSame(2, $error->getLocation()[0]->getLine()); + $this->assertSame(5, $error->getLocation()[0]->getColumn()); + } +} diff --git a/tests/Federation/Tracing/fixtures/README.md b/tests/Federation/Tracing/fixtures/README.md new file mode 100644 index 00000000..3f09bbaa --- /dev/null +++ b/tests/Federation/Tracing/fixtures/README.md @@ -0,0 +1,94 @@ +`apollo-ftv1.b64` +================= + +A real `extensions.ftv1` payload, emitted by a real Apollo Server subgraph running its own +`ApolloServerPluginInlineTrace`. `TraceSerializationTest::testDecodesGoldenApolloPayload()` +parses it with *our* generated protobuf classes; if our field numbers or wire types ever drift +from Apollo's `reports.proto`, that test fails. + +This is the only test in the suite that proves interoperability rather than self-consistency. + +How it was produced +------------------- + +```bash +npm install @apollo/server @apollo/subgraph graphql graphql-tag +``` + +```js +// gen.mjs +import { ApolloServer } from '@apollo/server'; +import { startStandaloneServer } from '@apollo/server/standalone'; +import { buildSubgraphSchema } from '@apollo/subgraph'; +import gql from 'graphql-tag'; + +const typeDefs = gql` + type Query { me: User! } + type User @key(fields: "id") { id: ID! name: String } +`; + +const resolvers = { + Query: { + me: async () => { await new Promise(r => setTimeout(r, 5)); return { id: '1', name: 'Ada' }; }, + }, + User: { + name: async (u) => { await new Promise(r => setTimeout(r, 3)); return u.name; }, + }, +}; + +const server = new ApolloServer({ schema: buildSubgraphSchema({ typeDefs, resolvers }) }); +const { url } = await startStandaloneServer(server, { listen: { port: 4999 } }); + +const res = await fetch(url, { + method: 'POST', + headers: { + 'content-type': 'application/json', + 'apollo-federation-include-trace': 'ftv1', + }, + body: JSON.stringify({ query: '{ me { name } }' }), +}); +console.log((await res.json()).extensions.ftv1); +await server.stop(); +process.exit(0); +``` + +```bash +node gen.mjs | grep -E '^[A-Za-z0-9+/]+=*$' > apollo-ftv1.b64 +``` + +(The `grep` drops Apollo's "Enabling inline tracing for this subgraph" log line, which it writes +to stdout alongside the payload.) + +The resolvers sleep so that the recorded `start_time`/`end_time` are non-zero and ordered, which +is what the test asserts on. + +Inspecting it +------------- + +```bash +base64 -d < apollo-ftv1.b64 | protoc --decode_raw +``` + +`--decode_raw` needs no schema, so it shows the raw field numbers independently of anything in +this repository: + +``` +3 { 1: 1787060485 2: 614000000 } # end_time (google.protobuf.Timestamp) +4 { 1: 1787060485 2: 600000000 } # start_time (google.protobuf.Timestamp) +11: 13847833 # duration_ns +14 { # root + 12 { # child + 1: "me" # response_name + 3: "User!" # type + 8: 3513708 # start_time + 9: 10048833 # end_time + 12 { 1: "name" 3: "String" 8: 10184875 9: 13630958 13: "User" } + 13: "Query" # parent_type + } +} +31: 0x3ff0000000000000 # field_execution_weight == 1.0 +``` + +Note that `--decode_raw` renders `type: "User!"` as a nested message `3 { 10: 0x21726573 }`, +because those five bytes also parse as a valid submessage. That is an ambiguity in `--decode_raw` +(which has no schema to disambiguate with), not a problem with the payload. diff --git a/tests/Federation/Tracing/fixtures/apollo-ftv1.b64 b/tests/Federation/Tracing/fixtures/apollo-ftv1.b64 new file mode 100644 index 00000000..9dc16918 --- /dev/null +++ b/tests/Federation/Tracing/fixtures/apollo-ftv1.b64 @@ -0,0 +1 @@ +GgwIhcKR1AYQgMvjpAIiDAiFwpHUBhCAjI2eAliZms0Gcj5iPAoCbWUaBVVzZXIhQOy61gFIwarlBGIeCgRuYW1lGgZTdHJpbmdAq9HtBEju+78GagRVc2VyagVRdWVyefkBAAAAAAAA8D8= diff --git a/tests/Functional/App/Resolver/InlineTraceResolver.php b/tests/Functional/App/Resolver/InlineTraceResolver.php new file mode 100644 index 00000000..a3fc25bc --- /dev/null +++ b/tests/Functional/App/Resolver/InlineTraceResolver.php @@ -0,0 +1,45 @@ + 'Ada']; + } + + /** + * @return array + */ + public function resolveUsers(): array + { + return [['name' => 'Ada'], ['name' => 'Grace']]; + } + + /** + * Resolves through a promise, so its end time can only be recorded once the value settles. + */ + public function resolveSlowName(array $user): Deferred + { + return new Deferred(static function () use ($user): string { + usleep(3000); + + return $user['name']; + }); + } + + public function resolveBroken(): string + { + throw new RuntimeException('a secret internal detail'); + } +} diff --git a/tests/Functional/App/config/inlineTrace/config.yml b/tests/Functional/App/config/inlineTrace/config.yml new file mode 100644 index 00000000..fa8db70d --- /dev/null +++ b/tests/Functional/App/config/inlineTrace/config.yml @@ -0,0 +1,16 @@ +imports: + - { resource: ../config.yml } + - { resource: services.yml } + +redeye_graphql: + inline_trace: true + definitions: + class_namespace: 'Redeye\GraphQLBundle\InlineTrace\__DEFINITIONS__' + schema: + query: Query + mutation: ~ + mappings: + types: + - + type: yaml + dir: '%kernel.project_dir%/config/inlineTrace/mapping' diff --git a/tests/Functional/App/config/inlineTrace/mapping/inlineTrace.types.yml b/tests/Functional/App/config/inlineTrace/mapping/inlineTrace.types.yml new file mode 100644 index 00000000..b3fb8173 --- /dev/null +++ b/tests/Functional/App/config/inlineTrace/mapping/inlineTrace.types.yml @@ -0,0 +1,23 @@ +Query: + type: object + config: + fields: + me: + type: "User!" + resolve: '@=query("inline_trace_me")' + users: + type: "[User]" + resolve: '@=query("inline_trace_users")' + +User: + type: object + config: + fields: + name: + type: String + slowName: + type: String + resolve: '@=query("inline_trace_slow_name", value)' + broken: + type: String + resolve: '@=query("inline_trace_broken")' diff --git a/tests/Functional/App/config/inlineTrace/services.yml b/tests/Functional/App/config/inlineTrace/services.yml new file mode 100644 index 00000000..e12d468b --- /dev/null +++ b/tests/Functional/App/config/inlineTrace/services.yml @@ -0,0 +1,8 @@ +services: + redeye_graphql.test.resolver.inline_trace: + class: Redeye\GraphQLBundle\Tests\Functional\App\Resolver\InlineTraceResolver + tags: + - { name: "redeye_graphql.query", alias: "inline_trace_me", method: "resolveMe" } + - { name: "redeye_graphql.query", alias: "inline_trace_users", method: "resolveUsers" } + - { name: "redeye_graphql.query", alias: "inline_trace_slow_name", method: "resolveSlowName" } + - { name: "redeye_graphql.query", alias: "inline_trace_broken", method: "resolveBroken" } diff --git a/tests/Functional/App/config/inlineTraceUnmodified/config.yml b/tests/Functional/App/config/inlineTraceUnmodified/config.yml new file mode 100644 index 00000000..1f775799 --- /dev/null +++ b/tests/Functional/App/config/inlineTraceUnmodified/config.yml @@ -0,0 +1,8 @@ +imports: + - { resource: ../inlineTrace/config.yml } + +redeye_graphql: + inline_trace: + include_errors: unmodified + definitions: + class_namespace: 'Redeye\GraphQLBundle\InlineTraceUnmodified\__DEFINITIONS__' diff --git a/tests/Functional/Federation/InlineTraceTest.php b/tests/Functional/Federation/InlineTraceTest.php new file mode 100644 index 00000000..63fdb2e6 --- /dev/null +++ b/tests/Functional/Federation/InlineTraceTest.php @@ -0,0 +1,272 @@ + + */ + private function ftv1Request(KernelBrowser $client, string $query, ?string $header = InlineTraceListener::HEADER_VALUE): array + { + $server = null === $header + ? [] + : ['HTTP_APOLLO_FEDERATION_INCLUDE_TRACE' => $header]; + + $client->request('GET', '/', ['query' => $query], [], $server); + + return json_decode((string) $client->getResponse()->getContent(), true); + } + + /** + * @param array $response + */ + private function assertFtv1(array $response): Trace + { + $this->assertArrayHasKey('extensions', $response); + $this->assertArrayHasKey('ftv1', $response['extensions']); + + $trace = new Trace(); + $trace->mergeFromString((string) base64_decode($response['extensions']['ftv1'], true)); + + return $trace; + } + + private function childNamed(Node $node, string $responseName): Node + { + foreach ($node->getChild() as $child) { + if ($responseName === $child->getResponseName()) { + return $child; + } + } + + self::fail(sprintf('no child named "%s"', $responseName)); + } + + public function testNoTraceWithoutTheHeader(): void + { + $client = static::createClient(['test_case' => 'inlineTrace']); + + $response = $this->ftv1Request($client, '{ me { name } }', null); + + $this->assertSame(['me' => ['name' => 'Ada']], $response['data']); + $this->assertArrayNotHasKey('ftv1', $response['extensions'] ?? []); + } + + /** + * @dataProvider nonMatchingHeaderProvider + */ + public function testNoTraceForAnotherHeaderValue(string $header): void + { + $client = static::createClient(['test_case' => 'inlineTrace']); + + $response = $this->ftv1Request($client, '{ me { name } }', $header); + + $this->assertArrayNotHasKey('ftv1', $response['extensions'] ?? []); + } + + public function nonMatchingHeaderProvider(): iterable + { + yield 'empty' => ['']; + yield 'v1' => ['v1']; + yield 'ftv2' => ['ftv2']; + } + + public function testTraceIsAbsentWhenTheFeatureIsOff(): void + { + $client = static::createClient(['test_case' => 'connection']); + + $response = $this->ftv1Request($client, '{ user { name } }'); + + $this->assertArrayNotHasKey('ftv1', $response['extensions'] ?? []); + } + + public function testEmitsATraceWhoseRootMirrorsTheSelectionSet(): void + { + $client = static::createClient(['test_case' => 'inlineTrace']); + + $trace = $this->assertFtv1($this->ftv1Request($client, '{ me { name } }')); + + $this->assertGreaterThan(0, (int) $trace->getDurationNs()); + $this->assertGreaterThan(0, (int) $trace->getStartTime()->getSeconds()); + $this->assertGreaterThan(0, (int) $trace->getEndTime()->getSeconds()); + $this->assertSame(1.0, $trace->getFieldExecutionWeight()); + + $me = $this->childNamed($trace->getRoot(), 'me'); + $this->assertSame('User!', $me->getType()); + $this->assertSame('Query', $me->getParentType()); + + $name = $this->childNamed($me, 'name'); + $this->assertSame('String', $name->getType()); + $this->assertSame('User', $name->getParentType()); + } + + public function testListItemsBecomeIndexNodes(): void + { + $client = static::createClient(['test_case' => 'inlineTrace']); + + $trace = $this->assertFtv1($this->ftv1Request($client, '{ users { name } }')); + + $users = $this->childNamed($trace->getRoot(), 'users'); + $indices = []; + foreach ($users->getChild() as $child) { + $indices[] = $child->getIndex(); + $this->assertSame('index', $child->getId()); + $this->assertSame('name', $this->childNamed($child, 'name')->getResponseName()); + } + + $this->assertSame([0, 1], $indices); + } + + public function testAliasedFieldCarriesTheSchemaFieldName(): void + { + $client = static::createClient(['test_case' => 'inlineTrace']); + + $trace = $this->assertFtv1($this->ftv1Request($client, '{ currentUser: me { name } }')); + + $node = $this->childNamed($trace->getRoot(), 'currentUser'); + $this->assertSame('me', $node->getOriginalFieldName()); + } + + public function testDeferredFieldIsTimedWhenItSettles(): void + { + $client = static::createClient(['test_case' => 'inlineTrace']); + + $trace = $this->assertFtv1($this->ftv1Request($client, '{ me { slowName } }')); + + $slowName = $this->childNamed($this->childNamed($trace->getRoot(), 'me'), 'slowName'); + $this->assertGreaterThan( + 2_000_000, + (int) $slowName->getEndTime() - (int) $slowName->getStartTime(), + 'a deferred field was timed synchronously instead of on settle' + ); + } + + public function testErrorIsMaskedAndAttachedToItsNode(): void + { + $client = static::createClient(['test_case' => 'inlineTrace']); + + $response = $this->ftv1Request($client, '{ me { broken } }'); + $trace = $this->assertFtv1($response); + + $broken = $this->childNamed($this->childNamed($trace->getRoot(), 'me'), 'broken'); + $this->assertCount(1, $broken->getError()); + + $error = $broken->getError()[0]; + $this->assertSame(TraceErrorFilter::MASKED_MESSAGE, $error->getMessage()); + $this->assertStringNotContainsString('a secret internal detail', $error->getJson()); + $this->assertSame(['me', 'broken'], json_decode($error->getJson(), true)['path']); + $this->assertSame(TraceErrorFilter::MASKED_BY, json_decode($error->getJson(), true)['extensions']['maskedBy']); + } + + /** + * `unmodified` must report the message the client sees, never the raw exception text. + */ + public function testUnmodifiedReportsTheClientVisibleMessage(): void + { + $client = static::createClient(['test_case' => 'inlineTraceUnmodified']); + + $response = $this->ftv1Request($client, '{ me { broken } }'); + $trace = $this->assertFtv1($response); + + $broken = $this->childNamed($this->childNamed($trace->getRoot(), 'me'), 'broken'); + $error = $broken->getError()[0]; + + $this->assertSame($response['errors'][0]['message'], $error->getMessage()); + $this->assertStringNotContainsString('a secret internal detail', $error->getJson()); + } + + /** + * A query that never parses resolves no fields at all, but must still produce a trace. + */ + public function testEmitsATraceForAnUnparseableQuery(): void + { + $client = static::createClient(['test_case' => 'inlineTrace']); + + $response = $this->ftv1Request($client, '{ me {'); + + $this->assertArrayHasKey('errors', $response); + $trace = $this->assertFtv1($response); + + $this->assertCount(0, $trace->getRoot()->getChild()); + $this->assertCount(1, $trace->getRoot()->getError()); + // Parse errors are masked like any other under the default policy. + $this->assertSame(TraceErrorFilter::MASKED_MESSAGE, $trace->getRoot()->getError()[0]->getMessage()); + } + + public function testSyntaxErrorDetailReachesTheTraceWhenErrorsAreUnmodified(): void + { + $client = static::createClient(['test_case' => 'inlineTraceUnmodified']); + + $trace = $this->assertFtv1($this->ftv1Request($client, '{ me {')); + + $this->assertCount(1, $trace->getRoot()->getError()); + $this->assertStringContainsString('Syntax Error', $trace->getRoot()->getError()[0]->getMessage()); + } + + public function testEmitsATraceForAQueryThatFailsValidation(): void + { + $client = static::createClient(['test_case' => 'inlineTrace']); + + $response = $this->ftv1Request($client, '{ me { noSuchField } }'); + + $this->assertArrayHasKey('errors', $response); + $trace = $this->assertFtv1($response); + + $this->assertCount(0, $trace->getRoot()->getChild()); + $this->assertCount(1, $trace->getRoot()->getError()); + } + + /** + * The trace lives in the per-execution context rather than on the listener service, so each + * query in a batch must get its own. + */ + public function testEachQueryInABatchGetsItsOwnTrace(): void + { + $client = static::createClient(['test_case' => 'inlineTrace']); + + $content = (string) json_encode([ + ['id' => 'ok', 'query' => '{ me { name } }'], + ['id' => 'broken', 'query' => '{ me { broken } }'], + ]); + $client->request('POST', '/batch', [], [], [ + 'CONTENT_TYPE' => 'application/json', + 'HTTP_APOLLO_FEDERATION_INCLUDE_TRACE' => InlineTraceListener::HEADER_VALUE, + ], $content); + + $payloads = json_decode((string) $client->getResponse()->getContent(), true); + $this->assertCount(2, $payloads); + + $first = $this->assertFtv1($payloads[0]['payload']); + $second = $this->assertFtv1($payloads[1]['payload']); + + $this->assertNotSame( + $payloads[0]['payload']['extensions']['ftv1'], + $payloads[1]['payload']['extensions']['ftv1'] + ); + + $this->assertSame('name', $this->childNamed($this->childNamed($first->getRoot(), 'me'), 'name')->getResponseName()); + $this->assertCount(0, $this->childNamed($first->getRoot(), 'me')->getError()); + + $broken = $this->childNamed($this->childNamed($second->getRoot(), 'me'), 'broken'); + $this->assertCount(1, $broken->getError()); + } + + public function testTraceCoexistsWithOtherExtensions(): void + { + $client = static::createClient(['test_case' => 'inlineTrace']); + + $trace = $this->assertFtv1($this->ftv1Request($client, '{ me { name } }')); + + $this->assertNotNull($trace->getRoot()); + } +} From 5da8ebc781b279641c9b633220437c38be2009ed Mon Sep 17 00:00:00 2001 From: Magnus Nordlander Date: Wed, 19 Aug 2026 08:04:37 +0200 Subject: [PATCH 2/2] Require google/protobuf 5.35.1 and raise the PHP floor to 8.2 The 5.x PHP runtime is not a drop-in for 3.x: protoc's PHP backend now emits Google\Protobuf\RepeatedField instead of Google\Protobuf\Internal\RepeatedField and adds native parameter types to setters, so the generated code only works against a matching runtime. proto/gen is therefore regenerated with protoc 35.1, the release that corresponds to the 5.35.1 PHP package, and the CI drift job's pin moves with it. Raising the floor to 8.2 drops PHP 8.0 and 8.1 from the test matrix, which also retires the two 8.0-with-Symfony-6.2/6.4 excludes. The two `include` legs (the optional-dependency check and the coverage run) move to 8.2. The coding-standard and static-analysis jobs, the AppVeyor build, and the docs version table follow. CacheScope's comment claimed a native enum was impossible because the bundle supports PHP 8.0. That is no longer true, so the comment says so; the class is otherwise left alone. Co-Authored-By: Claude Opus 5 (1M context) --- .appveyor.yml | 2 +- .github/workflows/ci.yml | 19 +++------ composer.json | 4 +- docs/index.md | 2 +- .../Federation/Tracing/Proto/Trace.php | 16 +++----- .../Federation/Tracing/Proto/Trace/Error.php | 20 +++++----- .../Tracing/Proto/Trace/Location.php | 6 +-- .../Federation/Tracing/Proto/Trace/Node.php | 40 +++++++++---------- proto/reports.proto | 2 +- src/CacheControl/CacheScope.php | 3 +- 10 files changed, 52 insertions(+), 62 deletions(-) diff --git a/.appveyor.yml b/.appveyor.yml index ed791722..44166968 100644 --- a/.appveyor.yml +++ b/.appveyor.yml @@ -11,7 +11,7 @@ init: install: - ps: Set-Service wuauserv -StartupType Manual - - cinst -y php --version=8.0 + - cinst -y php --version=8.2 - cinst -y composer - refreshenv - cd c:\tools\php80 diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 20d26def..16e25711 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -17,8 +17,6 @@ jobs: fail-fast: false matrix: php-version: - - '8.0' - - '8.1' - '8.2' symfony-version: - '5.4.*' @@ -30,17 +28,12 @@ jobs: - 'highest' remove-dependencies: [ '' ] coverage: [ 'none' ] - exclude: - - php-version: '8.0' - symfony-version: '6.2.*' - - php-version: '8.0' - symfony-version: '6.4.*' include: - - php-version: '8.0' + - php-version: '8.2' symfony-version: '5.4.*' dependencies: 'lowest' remove-dependencies: '--dev symfony/validator doctrine/orm doctrine/annotations' - - php-version: '8.1' + - php-version: '8.2' symfony-version: '5.4.*' dependencies: 'lowest' coverage: "pcov" @@ -92,7 +85,7 @@ jobs: uses: "shivammathur/setup-php@v2" with: tools: flex - php-version: "8.0" + php-version: "8.2" - name: "Install dependencies" uses: ramsey/composer-install@1.3.0 @@ -110,9 +103,9 @@ jobs: # Pinned: protoc's PHP generator changes its output between releases, so an # unpinned compiler would report drift that isn't there. Keep this version in # step with the one recorded in proto/reports.proto. - - name: "Install protoc 29.3" + - name: "Install protoc 35.1" run: | - curl -sSLo /tmp/protoc.zip https://github.com/protocolbuffers/protobuf/releases/download/v29.3/protoc-29.3-linux-x86_64.zip + curl -sSLo /tmp/protoc.zip https://github.com/protocolbuffers/protobuf/releases/download/v35.1/protoc-35.1-linux-x86_64.zip sudo unzip -o -q /tmp/protoc.zip -d /usr/local protoc --version @@ -132,7 +125,7 @@ jobs: - name: "Install PHP" uses: "shivammathur/setup-php@v2" with: - php-version: "8.0" + php-version: "8.2" - name: "Install dependencies" uses: ramsey/composer-install@1.3.0 diff --git a/composer.json b/composer.json index 66162cc8..8f9e1ba1 100644 --- a/composer.json +++ b/composer.json @@ -29,9 +29,9 @@ } }, "require": { - "php": "^8.0", + "php": "^8.2", "ext-json": "*", - "google/protobuf": "^3.25", + "google/protobuf": "^5.35.1", "murtukov/php-code-generator": "^0.1.5", "phpdocumentor/reflection-docblock": "^5.2", "phpdocumentor/type-resolver": ">1.4.0,<1.6.0", diff --git a/docs/index.md b/docs/index.md index eb3f1345..7f65f50e 100644 --- a/docs/index.md +++ b/docs/index.md @@ -10,7 +10,7 @@ Versions requirements | Version | PHP | Symfony | Support | | --------------------------------------------------------------: | ---------: | ---------------: | -------------: | -| [`1.0`](https://github.com/redeye/GraphQLBundle/tree/master) | `>= 8.0` | `>= 5.3.7` | DEV | +| [`1.0`](https://github.com/redeye/GraphQLBundle/tree/master) | `>= 8.2` | `>= 5.3.7` | DEV | | [`0.14`](https://github.com/redeye/GraphQLBundle/tree/0.14) | `>= 7.4` | `>= 4.4.30` | Active support | | [`0.13`](https://github.com/redeye/GraphQLBundle/tree/0.13) | `>= 7.2` | `>= 4.3` | Active support | | [`0.12`](https://github.com/redeye/GraphQLBundle/tree/0.12) | `>= 7.1` | `>= 3.4, <4.4` | Security | diff --git a/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace.php b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace.php index 29dbb874..26a09ead 100644 --- a/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace.php +++ b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace.php @@ -6,8 +6,8 @@ namespace Redeye\GraphQLBundle\Federation\Tracing\Proto; use Google\Protobuf\Internal\GPBType; -use Google\Protobuf\Internal\RepeatedField; use Google\Protobuf\Internal\GPBUtil; +use Google\Protobuf\RepeatedField; /** * Generated from protobuf message Trace @@ -102,9 +102,8 @@ public function clearEndTime() * @param \Google\Protobuf\Timestamp $var * @return $this */ - public function setEndTime($var) + public function setEndTime(\Google\Protobuf\Timestamp|null $var) { - GPBUtil::checkMessage($var, \Google\Protobuf\Timestamp::class); $this->end_time = $var; return $this; @@ -138,9 +137,8 @@ public function clearStartTime() * @param \Google\Protobuf\Timestamp $var * @return $this */ - public function setStartTime($var) + public function setStartTime(\Google\Protobuf\Timestamp|null $var) { - GPBUtil::checkMessage($var, \Google\Protobuf\Timestamp::class); $this->start_time = $var; return $this; @@ -166,7 +164,7 @@ public function getDurationNs() * @param int|string $var * @return $this */ - public function setDurationNs($var) + public function setDurationNs(int|string $var) { GPBUtil::checkUint64($var); $this->duration_ns = $var; @@ -202,9 +200,8 @@ public function clearRoot() * @param \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node $var * @return $this */ - public function setRoot($var) + public function setRoot(\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node|null $var) { - GPBUtil::checkMessage($var, \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node::class); $this->root = $var; return $this; @@ -232,9 +229,8 @@ public function getFieldExecutionWeight() * @param float $var * @return $this */ - public function setFieldExecutionWeight($var) + public function setFieldExecutionWeight(float $var) { - GPBUtil::checkDouble($var); $this->field_execution_weight = $var; return $this; diff --git a/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Error.php b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Error.php index b2c49797..72f16e19 100644 --- a/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Error.php +++ b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Error.php @@ -6,8 +6,8 @@ namespace Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace; use Google\Protobuf\Internal\GPBType; -use Google\Protobuf\Internal\RepeatedField; use Google\Protobuf\Internal\GPBUtil; +use Google\Protobuf\RepeatedField; /** * Generated from protobuf message Trace.Error @@ -38,7 +38,7 @@ class Error extends \Google\Protobuf\Internal\Message * Optional. Data for populating the Message object. * * @type string $message - * @type array<\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Location>|\Google\Protobuf\Internal\RepeatedField $location + * @type \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Location[] $location * @type int|string $time_ns * @type string $json * } @@ -62,9 +62,9 @@ public function getMessage() * @param string $var * @return $this */ - public function setMessage($var) + public function setMessage(string $var) { - GPBUtil::checkString($var, True); + GPBUtil::checkString($var, true); $this->message = $var; return $this; @@ -72,7 +72,7 @@ public function setMessage($var) /** * Generated from protobuf field repeated .Trace.Location location = 2; - * @return \Google\Protobuf\Internal\RepeatedField + * @return RepeatedField<\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Location> */ public function getLocation() { @@ -81,10 +81,10 @@ public function getLocation() /** * Generated from protobuf field repeated .Trace.Location location = 2; - * @param array<\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Location>|\Google\Protobuf\Internal\RepeatedField $var + * @param \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Location[] $var * @return $this */ - public function setLocation($var) + public function setLocation(array|RepeatedField $var) { $arr = GPBUtil::checkRepeatedField($var, \Google\Protobuf\Internal\GPBType::MESSAGE, \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Location::class); $this->location = $arr; @@ -106,7 +106,7 @@ public function getTimeNs() * @param int|string $var * @return $this */ - public function setTimeNs($var) + public function setTimeNs(int|string $var) { GPBUtil::checkUint64($var); $this->time_ns = $var; @@ -128,9 +128,9 @@ public function getJson() * @param string $var * @return $this */ - public function setJson($var) + public function setJson(string $var) { - GPBUtil::checkString($var, True); + GPBUtil::checkString($var, true); $this->json = $var; return $this; diff --git a/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Location.php b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Location.php index e668a305..d7cccd05 100644 --- a/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Location.php +++ b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Location.php @@ -6,8 +6,8 @@ namespace Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace; use Google\Protobuf\Internal\GPBType; -use Google\Protobuf\Internal\RepeatedField; use Google\Protobuf\Internal\GPBUtil; +use Google\Protobuf\RepeatedField; /** * Generated from protobuf message Trace.Location @@ -52,7 +52,7 @@ public function getLine() * @param int $var * @return $this */ - public function setLine($var) + public function setLine(int $var) { GPBUtil::checkUint32($var); $this->line = $var; @@ -74,7 +74,7 @@ public function getColumn() * @param int $var * @return $this */ - public function setColumn($var) + public function setColumn(int $var) { GPBUtil::checkUint32($var); $this->column = $var; diff --git a/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Node.php b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Node.php index f3b7d668..2dbd5e1c 100644 --- a/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Node.php +++ b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace/Node.php @@ -6,8 +6,8 @@ namespace Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace; use Google\Protobuf\Internal\GPBType; -use Google\Protobuf\Internal\RepeatedField; use Google\Protobuf\Internal\GPBUtil; +use Google\Protobuf\RepeatedField; /** * We store information on each resolver execution as a Node on a tree. The structure @@ -71,8 +71,8 @@ class Node extends \Google\Protobuf\Internal\Message * relative to the trace's start_time, in ns * @type int|string $end_time * relative to the trace's start_time, in ns - * @type array<\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Error>|\Google\Protobuf\Internal\RepeatedField $error - * @type array<\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node>|\Google\Protobuf\Internal\RepeatedField $child + * @type \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Error[] $error + * @type \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node[] $child * @type string $parent_type * The field's parent type; e.g. "User" for User.email: String! * @type string $original_field_name @@ -102,9 +102,9 @@ public function hasResponseName() * @param string $var * @return $this */ - public function setResponseName($var) + public function setResponseName(string $var) { - GPBUtil::checkString($var, True); + GPBUtil::checkString($var, true); $this->writeOneof(1, $var); return $this; @@ -129,7 +129,7 @@ public function hasIndex() * @param int $var * @return $this */ - public function setIndex($var) + public function setIndex(int $var) { GPBUtil::checkUint32($var); $this->writeOneof(2, $var); @@ -155,9 +155,9 @@ public function getType() * @param string $var * @return $this */ - public function setType($var) + public function setType(string $var) { - GPBUtil::checkString($var, True); + GPBUtil::checkString($var, true); $this->type = $var; return $this; @@ -181,7 +181,7 @@ public function getStartTime() * @param int|string $var * @return $this */ - public function setStartTime($var) + public function setStartTime(int|string $var) { GPBUtil::checkUint64($var); $this->start_time = $var; @@ -207,7 +207,7 @@ public function getEndTime() * @param int|string $var * @return $this */ - public function setEndTime($var) + public function setEndTime(int|string $var) { GPBUtil::checkUint64($var); $this->end_time = $var; @@ -217,7 +217,7 @@ public function setEndTime($var) /** * Generated from protobuf field repeated .Trace.Error error = 11; - * @return \Google\Protobuf\Internal\RepeatedField + * @return RepeatedField<\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Error> */ public function getError() { @@ -226,10 +226,10 @@ public function getError() /** * Generated from protobuf field repeated .Trace.Error error = 11; - * @param array<\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Error>|\Google\Protobuf\Internal\RepeatedField $var + * @param \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Error[] $var * @return $this */ - public function setError($var) + public function setError(array|RepeatedField $var) { $arr = GPBUtil::checkRepeatedField($var, \Google\Protobuf\Internal\GPBType::MESSAGE, \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Error::class); $this->error = $arr; @@ -239,7 +239,7 @@ public function setError($var) /** * Generated from protobuf field repeated .Trace.Node child = 12; - * @return \Google\Protobuf\Internal\RepeatedField + * @return RepeatedField<\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node> */ public function getChild() { @@ -248,10 +248,10 @@ public function getChild() /** * Generated from protobuf field repeated .Trace.Node child = 12; - * @param array<\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node>|\Google\Protobuf\Internal\RepeatedField $var + * @param \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node[] $var * @return $this */ - public function setChild($var) + public function setChild(array|RepeatedField $var) { $arr = GPBUtil::checkRepeatedField($var, \Google\Protobuf\Internal\GPBType::MESSAGE, \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node::class); $this->child = $arr; @@ -277,9 +277,9 @@ public function getParentType() * @param string $var * @return $this */ - public function setParentType($var) + public function setParentType(string $var) { - GPBUtil::checkString($var, True); + GPBUtil::checkString($var, true); $this->parent_type = $var; return $this; @@ -299,9 +299,9 @@ public function getOriginalFieldName() * @param string $var * @return $this */ - public function setOriginalFieldName($var) + public function setOriginalFieldName(string $var) { - GPBUtil::checkString($var, True); + GPBUtil::checkString($var, true); $this->original_field_name = $var; return $this; diff --git a/proto/reports.proto b/proto/reports.proto index a07b765a..91ad62a2 100644 --- a/proto/reports.proto +++ b/proto/reports.proto @@ -17,7 +17,7 @@ syntax = "proto3"; // // Regenerate with: composer proto // -// Generated with protoc 29.3. protoc's PHP backend changes its output between +// Generated with protoc 35.1. protoc's PHP backend changes its output between // releases, so use that version (CI pins it) or expect a large, spurious diff. import "google/protobuf/timestamp.proto"; diff --git a/src/CacheControl/CacheScope.php b/src/CacheControl/CacheScope.php index 9b693cbe..9de48579 100644 --- a/src/CacheControl/CacheScope.php +++ b/src/CacheControl/CacheScope.php @@ -7,7 +7,8 @@ /** * The values of the `CacheControlScope` enum used by the `@cacheControl` directive. * - * A plain constant holder rather than a native enum: this bundle supports PHP 8.0. + * A plain constant holder rather than a native enum. That was originally forced by the PHP 8.0 + * floor; the floor is 8.2 now, so this could be converted to a native enum. */ final class CacheScope {