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 9a3b8886..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 @@ -100,6 +93,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 35.1" + run: | + 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 + + - 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" @@ -110,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 082be332..8f9e1ba1 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": { @@ -28,8 +29,9 @@ } }, "require": { - "php": "^8.0", + "php": "^8.2", "ext-json": "*", + "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", @@ -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..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 | @@ -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..26a09ead --- /dev/null +++ b/proto/gen/Redeye/GraphQLBundle/Federation/Tracing/Proto/Trace.php @@ -0,0 +1,240 @@ +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(\Google\Protobuf\Timestamp|null $var) + { + $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(\Google\Protobuf\Timestamp|null $var) + { + $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(int|string $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(\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node|null $var) + { + $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(float $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..72f16e19 --- /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 \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Location[] $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(string $var) + { + GPBUtil::checkString($var, true); + $this->message = $var; + + return $this; + } + + /** + * Generated from protobuf field repeated .Trace.Location location = 2; + * @return RepeatedField<\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Location> + */ + public function getLocation() + { + return $this->location; + } + + /** + * Generated from protobuf field repeated .Trace.Location location = 2; + * @param \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Location[] $var + * @return $this + */ + 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; + + 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(int|string $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(string $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..d7cccd05 --- /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(int $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(int $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..2dbd5e1c --- /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 \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 + * } + */ + 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(string $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(int $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(string $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(int|string $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(int|string $var) + { + GPBUtil::checkUint64($var); + $this->end_time = $var; + + return $this; + } + + /** + * Generated from protobuf field repeated .Trace.Error error = 11; + * @return RepeatedField<\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Error> + */ + public function getError() + { + return $this->error; + } + + /** + * Generated from protobuf field repeated .Trace.Error error = 11; + * @param \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Error[] $var + * @return $this + */ + 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; + + return $this; + } + + /** + * Generated from protobuf field repeated .Trace.Node child = 12; + * @return RepeatedField<\Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node> + */ + public function getChild() + { + return $this->child; + } + + /** + * Generated from protobuf field repeated .Trace.Node child = 12; + * @param \Redeye\GraphQLBundle\Federation\Tracing\Proto\Trace\Node[] $var + * @return $this + */ + 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; + + 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(string $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(string $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..91ad62a2 --- /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 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"; + +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/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 { 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()); + } +}