apm-agent-nodejs icon indicating copy to clipboard operation
apm-agent-nodejs copied to clipboard

Published 20 hours ago • verified publisher icon elastic

GraphQL transaction type and name not set on an Apollo Gateway service

Open diskra opened this issue 2 years ago • 13 comments

Describe the bug

I have a graphql app setup using Apollo Gateway and apollo server express. The transactions get reported to APM but they get reported as normal http /graphql transaction and not as graphQL transaction type in the dropdown. Screenshot 2023-04-05 at 9 23 36 AM

Environment (please complete the following information)

  • OS: Linux
  • Node.js version: 16.19.1
  • APM Server version: 7.17.4
  • Agent version: 3.44.0

package.json

{
  "name": "graph-gateway",
  "version": "1.0.0",
  "description": "",
  "main": "dist/index.ts",
  "scripts": {
    "test": "echo \"Error: no test specified\" && exit 1"
  },
  "author": "Dejan",
  "license": "ISC",
  "dependencies": {
    "elastic-apm-node": "^3.44.0",
    "@apollo/gateway": "^2.4.1",
    "apollo-server-express": "^3.12.0",
    "express": "^4.18.2",
    "lodash": "^4.17.21"
  },
  "devDependencies": {
    "typescript": "^4.5.5"
  }
}

index.ts

const apmHostName = process.env.APM_HOSTNAME;
const apmSecretToken = process.env.APM_SECRET_TOKEN;

const sampleRate = parseFloat(process.env.APM_SAMPLE_RATE as string);

const apm = require("elastic-apm-node");
apm.start({
    serviceName : process.env.SERVICE_NAME,
    serverUrl: apmHostName,
    environment: process.env.APM_ENV,
    logLevel: "debug",
    transactionSampleRate: (sampleRate >= 0 && sampleRate <= 1) ? sampleRate : 1,
    secretToken: apmSecretToken,
    verifyServerCert: process.env.NODE_ENV !== "local",
    cloudProvider: process.env.NODE_ENV === "local" ? "none" : "auto",
});

import { ApolloGateway, RemoteGraphQLDataSource } from "@apollo/gateway";
import { ApolloServer } from "apollo-server-express";
import fs from "fs";
import express from "express";
import _ from "lodash";

const servicePort: number = Number(process.env.PORT) || 3000;

async function startGateway() {
    let gatewayConfig: any = {
        buildService({ url }: any) {
            return new RemoteGraphQLDataSource({
                url,
                willSendRequest({ request, context }: any) {
                    request.http.headers.set('company-name', context.companyName);
                    request.http.headers.set('roles', context.roles);
                    request.http.headers.set('client-id', context.clientId);
                },
            });
        },
    };

    if (process.env.NODE_ENV === "local") {
        gatewayConfig["supergraphSdl"] = fs.readFileSync('./supergraph.graphql').toString();
    }

    const gateway = new ApolloGateway(gatewayConfig);

    const app = express();

    const server = new ApolloServer({
        gateway,
        introspection: process.env.NODE_ENV === "local",
        plugins: [
            {
                async requestDidStart(requestContext: any) {
                    apm.setCustomContext({
                        operationName: requestContext.request.operationName,
                        query: requestContext.request.query,
                        variables: requestContext.request.variables,
                        context: requestContext.context
                    });

                    return {
                        async didEncounterErrors(requestContext: any) {
                            requestContext.errors?.forEach((error: any) => {
                                apm.captureError(error, {
                                    custom: {
                                        subgraph: error?.extensions?.serviceName
                                    }
                                });
                            });

                            apm.setTransactionOutcome("failure");
                        }
                    };
                }
            }
        ],
        context: async ({ req }) => {
            let rolesValue : string = _.get(req, 'headers.roles');

            return {
                companyName: req.headers["company-name"] ?? null,
                clientId: req.headers["client-id"] ?? null,
                roles: JSON.stringify( rolesValue ? rolesValue.split(',') : [] )
            }
        },
    });

    await server.start();

    app.get("/api/v1/system/health", function(req, res) {
        res.send("OK");
    });

    server.applyMiddleware({ app });

    return app.listen({ port: servicePort });
}

async function startApolloServer() {
    return startGateway();
}

startApolloServer().then((url: any) => {
    console.log(
      `Server started!`,
    );
});

Debug Logs

graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.363Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted request event call to http.Server.prototype.emit for /graphql"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.365Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start trace {\"trans\":\"09b9261f9cf1464d\",\"trace\":\"0ee40ff3ea28bbf8c5ea32f3d7610557\",\"name\":\"unnamed\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.366Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(09b926, 'unnamed')> )","ecs":{"version":"1.6.0"},"message":"supersedeWithTransRunContext(<Trans 09b9261f9cf1464d>)"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.370Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting transaction result {\"trans\":\"09b9261f9cf1464d\",\"trace\":\"0ee40ff3ea28bbf8c5ea32f3d7610557\",\"result\":\"HTTP 2xx\"}"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.372Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting default transaction name: OPTIONS /graphql {\"trans\":\"09b9261f9cf1464d\",\"trace\":\"0ee40ff3ea28bbf8c5ea32f3d7610557\"}"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.373Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<> )","ecs":{"version":"1.6.0"},"message":"addEndedTransaction(OPTIONS /graphql)"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.379Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"transaction ignored by filter {\"trans\":\"09b9261f9cf1464d\",\"trace\":\"0ee40ff3ea28bbf8c5ea32f3d7610557\"}"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.379Z","log":{"logger":"elastic-apm-node"},"trans":"09b9261f9cf1464d","name":"OPTIONS /graphql","trace":"0ee40ff3ea28bbf8c5ea32f3d7610557","type":"request","result":"HTTP 2xx","duration":8.789,"ecs":{"version":"1.6.0"},"message":"ended transaction"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.381Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted request event call to http.Server.prototype.emit for /graphql"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.381Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start trace {\"trans\":\"d4c80769bd782f45\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"unnamed\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.382Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(d4c807, 'unnamed')> )","ecs":{"version":"1.6.0"},"message":"supersedeWithTransRunContext(<Trans d4c80769bd782f45>)"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.492Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start span {\"span\":\"a1687e12f4170eab\",\"parent\":\"d4c80769bd782f45\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"unnamed\",\"type\":\"external\",\"subtype\":\"http\",\"action\":null}"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.493Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to http.request {\"id\":\"d4c80769bd782f45\"}"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.494Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"request details: {\"protocol\":\"http:\",\"host\":\"buyer-subgraph:3000\",\"id\":\"d4c80769bd782f45\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.499Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted request event call to http.Server.prototype.emit for /graphql"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.502Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"continue trace {\"trans\":\"6ea35beabe4c93a5\",\"parent\":\"a1687e12f4170eab\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"unnamed\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.503Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(6ea35b, 'unnamed')> )","ecs":{"version":"1.6.0"},"message":"supersedeWithTransRunContext(<Trans 6ea35beabe4c93a5>)"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.566Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to graphql.execute"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.567Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start span {\"span\":\"b50aae702985af3c\",\"parent\":\"6ea35beabe4c93a5\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"GraphQL: Unknown Query\",\"type\":\"db\",\"subtype\":\"graphql\",\"action\":\"execute\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.568Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting default transaction name: ExampleQuery__buyer_subgraph__0 zipCode (/graphql) {\"trans\":\"6ea35beabe4c93a5\",\"parent\":\"a1687e12f4170eab\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.570Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start span {\"span\":\"933f194dbf23a8cf\",\"parent\":\"b50aae702985af3c\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE Query.zipCode\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.571Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(6ea35b, 'ExampleQuery__buyer_subgraph__0 zipCode (/graphql)'), [Span(b50aae, 'GraphQL: ExampleQuery__buyer_subgraph__0 zipCode'),Span(933f19, 'RESOLVE Query.zipCode')]> )","ecs":{"version":"1.6.0"},"message":"supersedeWithSpanRunContext(<Span 933f194dbf23a8cf>)"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.575Z","log":{"logger":"elastic-apm-node"},"method":"POST","path":"/local-location/_search","ecs":{"version":"1.6.0"},"message":"intercepted call to @elastic/elasticsearch.Transport.prototype.request"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.575Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start span {\"span\":\"9b6b4000273ac106\",\"parent\":\"933f194dbf23a8cf\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"Elasticsearch: POST /local-location/_search\",\"type\":\"db\",\"subtype\":\"elasticsearch\",\"action\":\"request\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.577Z","log":{"logger":"elastic-apm-node"},"method":"GET","path":"/","ecs":{"version":"1.6.0"},"message":"intercepted call to @elastic/elasticsearch.Transport.prototype.request"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.578Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start span {\"span\":\"aa43c5192cec8002\",\"parent\":\"9b6b4000273ac106\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"Elasticsearch: GET /\",\"type\":\"db\",\"subtype\":\"elasticsearch\",\"action\":\"request\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.580Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to https.request {\"id\":null}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.707Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended span {\"span\":\"aa43c5192cec8002\",\"parent\":\"9b6b4000273ac106\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"Elasticsearch: GET /\",\"type\":\"db\",\"subtype\":\"elasticsearch\",\"action\":\"request\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.707Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(6ea35b, 'ExampleQuery__buyer_subgraph__0 zipCode (/graphql)'), [Span(b50aae, 'GraphQL: ExampleQuery__buyer_subgraph__0 zipCode'),Span(933f19, 'RESOLVE Query.zipCode'),Span(9b6b40, 'Elasticsearch: POST /local-location/_search')]> )","ecs":{"version":"1.6.0"},"message":"addEndedSpan(Elasticsearch: GET /)"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.707Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"encoding span {\"span\":\"aa43c5192cec8002\",\"parent\":\"9b6b4000273ac106\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"Elasticsearch: GET /\",\"type\":\"db\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.709Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to https.request {\"id\":null}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.713Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending span {\"span\":\"aa43c5192cec8002\",\"parent\":\"9b6b4000273ac106\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"Elasticsearch: GET /\",\"type\":\"db\"}"}
buyer-subgraph-1       | {"log.level":"info","@timestamp":"2023-04-04T19:59:47.726Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"Sending error to Elastic APM: {\"id\":\"2f6988695546a89e091e46af20665940\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.830Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended span {\"span\":\"9b6b4000273ac106\",\"parent\":\"933f194dbf23a8cf\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"Elasticsearch: POST /local-location/_search\",\"type\":\"db\",\"subtype\":\"elasticsearch\",\"action\":\"request\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.830Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(6ea35b, 'ExampleQuery__buyer_subgraph__0 zipCode (/graphql)'), [Span(b50aae, 'GraphQL: ExampleQuery__buyer_subgraph__0 zipCode'),Span(933f19, 'RESOLVE Query.zipCode')]> )","ecs":{"version":"1.6.0"},"message":"addEndedSpan(Elasticsearch: POST /local-location/_search)"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.831Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"encoding span {\"span\":\"9b6b4000273ac106\",\"parent\":\"933f194dbf23a8cf\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"Elasticsearch: POST /local-location/_search\",\"type\":\"db\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.833Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended span {\"span\":\"933f194dbf23a8cf\",\"parent\":\"b50aae702985af3c\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE Query.zipCode\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.833Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(6ea35b, 'ExampleQuery__buyer_subgraph__0 zipCode (/graphql)'), [Span(b50aae, 'GraphQL: ExampleQuery__buyer_subgraph__0 zipCode')]> )","ecs":{"version":"1.6.0"},"message":"addEndedSpan(RESOLVE Query.zipCode)"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.833Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"encoding span {\"span\":\"933f194dbf23a8cf\",\"parent\":\"b50aae702985af3c\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE Query.zipCode\",\"type\":\"custom\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.834Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start span {\"span\":\"4e7d69dcddff8a6e\",\"parent\":\"933f194dbf23a8cf\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE ZipCode.id\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.835Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(6ea35b, 'ExampleQuery__buyer_subgraph__0 zipCode (/graphql)'), [Span(b50aae, 'GraphQL: ExampleQuery__buyer_subgraph__0 zipCode'),Span(933f19, 'RESOLVE Query.zipCode', ended),Span(4e7d69, 'RESOLVE ZipCode.id')]> )","ecs":{"version":"1.6.0"},"message":"supersedeWithSpanRunContext(<Span 4e7d69dcddff8a6e>)"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.835Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start span {\"span\":\"64302de3e93621b8\",\"parent\":\"4e7d69dcddff8a6e\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE ZipCode.name\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.835Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(6ea35b, 'ExampleQuery__buyer_subgraph__0 zipCode (/graphql)'), [Span(b50aae, 'GraphQL: ExampleQuery__buyer_subgraph__0 zipCode'),Span(933f19, 'RESOLVE Query.zipCode', ended),Span(4e7d69, 'RESOLVE ZipCode.id'),Span(64302d, 'RESOLVE ZipCode.name')]> )","ecs":{"version":"1.6.0"},"message":"supersedeWithSpanRunContext(<Span 64302de3e93621b8>)"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.836Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start span {\"span\":\"fa2c05c40b30238c\",\"parent\":\"64302de3e93621b8\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE ZipCode.webName\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.837Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(6ea35b, 'ExampleQuery__buyer_subgraph__0 zipCode (/graphql)'), [Span(b50aae, 'GraphQL: ExampleQuery__buyer_subgraph__0 zipCode'),Span(933f19, 'RESOLVE Query.zipCode', ended),Span(4e7d69, 'RESOLVE ZipCode.id'),Span(64302d, 'RESOLVE ZipCode.name'),Span(fa2c05, 'RESOLVE ZipCode.webName')]> )","ecs":{"version":"1.6.0"},"message":"supersedeWithSpanRunContext(<Span fa2c05c40b30238c>)"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.838Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start span {\"span\":\"988df1ddbcb2aa67\",\"parent\":\"fa2c05c40b30238c\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE ZipCode.stateCode\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.838Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(6ea35b, 'ExampleQuery__buyer_subgraph__0 zipCode (/graphql)'), [Span(b50aae, 'GraphQL: ExampleQuery__buyer_subgraph__0 zipCode'),Span(933f19, 'RESOLVE Query.zipCode', ended),Span(4e7d69, 'RESOLVE ZipCode.id'),Span(64302d, 'RESOLVE ZipCode.name'),Span(fa2c05, 'RESOLVE ZipCode.webName'),Span(988df1, 'RESOLVE ZipCode.stateCode')]> )","ecs":{"version":"1.6.0"},"message":"supersedeWithSpanRunContext(<Span 988df1ddbcb2aa67>)"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.839Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended span {\"span\":\"4e7d69dcddff8a6e\",\"parent\":\"933f194dbf23a8cf\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE ZipCode.id\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.839Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(6ea35b, 'ExampleQuery__buyer_subgraph__0 zipCode (/graphql)'), [Span(b50aae, 'GraphQL: ExampleQuery__buyer_subgraph__0 zipCode'),Span(933f19, 'RESOLVE Query.zipCode', ended)]> )","ecs":{"version":"1.6.0"},"message":"addEndedSpan(RESOLVE ZipCode.id)"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.839Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"encoding span {\"span\":\"4e7d69dcddff8a6e\",\"parent\":\"933f194dbf23a8cf\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE ZipCode.id\",\"type\":\"custom\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.839Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended span {\"span\":\"64302de3e93621b8\",\"parent\":\"4e7d69dcddff8a6e\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE ZipCode.name\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.839Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(6ea35b, 'ExampleQuery__buyer_subgraph__0 zipCode (/graphql)'), [Span(b50aae, 'GraphQL: ExampleQuery__buyer_subgraph__0 zipCode'),Span(933f19, 'RESOLVE Query.zipCode', ended),Span(4e7d69, 'RESOLVE ZipCode.id', ended)]> )","ecs":{"version":"1.6.0"},"message":"addEndedSpan(RESOLVE ZipCode.name)"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.840Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"encoding span {\"span\":\"64302de3e93621b8\",\"parent\":\"4e7d69dcddff8a6e\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE ZipCode.name\",\"type\":\"custom\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.840Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended span {\"span\":\"fa2c05c40b30238c\",\"parent\":\"64302de3e93621b8\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE ZipCode.webName\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.840Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(6ea35b, 'ExampleQuery__buyer_subgraph__0 zipCode (/graphql)'), [Span(b50aae, 'GraphQL: ExampleQuery__buyer_subgraph__0 zipCode'),Span(933f19, 'RESOLVE Query.zipCode', ended),Span(4e7d69, 'RESOLVE ZipCode.id', ended),Span(64302d, 'RESOLVE ZipCode.name', ended)]> )","ecs":{"version":"1.6.0"},"message":"addEndedSpan(RESOLVE ZipCode.webName)"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.840Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"encoding span {\"span\":\"fa2c05c40b30238c\",\"parent\":\"64302de3e93621b8\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE ZipCode.webName\",\"type\":\"custom\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.840Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended span {\"span\":\"988df1ddbcb2aa67\",\"parent\":\"fa2c05c40b30238c\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE ZipCode.stateCode\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.840Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(6ea35b, 'ExampleQuery__buyer_subgraph__0 zipCode (/graphql)'), [Span(b50aae, 'GraphQL: ExampleQuery__buyer_subgraph__0 zipCode'),Span(933f19, 'RESOLVE Query.zipCode', ended),Span(4e7d69, 'RESOLVE ZipCode.id', ended),Span(64302d, 'RESOLVE ZipCode.name', ended),Span(fa2c05, 'RESOLVE ZipCode.webName', ended)]> )","ecs":{"version":"1.6.0"},"message":"addEndedSpan(RESOLVE ZipCode.stateCode)"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.840Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"encoding span {\"span\":\"988df1ddbcb2aa67\",\"parent\":\"fa2c05c40b30238c\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE ZipCode.stateCode\",\"type\":\"custom\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.841Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended span {\"span\":\"b50aae702985af3c\",\"parent\":\"6ea35beabe4c93a5\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"GraphQL: ExampleQuery__buyer_subgraph__0 zipCode\",\"type\":\"db\",\"subtype\":\"graphql\",\"action\":\"execute\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.841Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(6ea35b, 'ExampleQuery__buyer_subgraph__0 zipCode (/graphql)')> )","ecs":{"version":"1.6.0"},"message":"addEndedSpan(GraphQL: ExampleQuery__buyer_subgraph__0 zipCode)"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.841Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"encoding span {\"span\":\"b50aae702985af3c\",\"parent\":\"6ea35beabe4c93a5\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"GraphQL: ExampleQuery__buyer_subgraph__0 zipCode\",\"type\":\"db\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.844Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting transaction result {\"trans\":\"6ea35beabe4c93a5\",\"parent\":\"a1687e12f4170eab\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"result\":\"HTTP 2xx\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.845Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending span {\"span\":\"9b6b4000273ac106\",\"parent\":\"933f194dbf23a8cf\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"Elasticsearch: POST /local-location/_search\",\"type\":\"db\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.845Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending span {\"span\":\"933f194dbf23a8cf\",\"parent\":\"b50aae702985af3c\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE Query.zipCode\",\"type\":\"custom\"}"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.845Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted http.ClientRequest response event {\"id\":\"d4c80769bd782f45\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.845Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending span {\"span\":\"4e7d69dcddff8a6e\",\"parent\":\"933f194dbf23a8cf\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE ZipCode.id\",\"type\":\"custom\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.845Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending span {\"span\":\"64302de3e93621b8\",\"parent\":\"4e7d69dcddff8a6e\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE ZipCode.name\",\"type\":\"custom\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.846Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending span {\"span\":\"fa2c05c40b30238c\",\"parent\":\"64302de3e93621b8\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE ZipCode.webName\",\"type\":\"custom\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.846Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending span {\"span\":\"988df1ddbcb2aa67\",\"parent\":\"fa2c05c40b30238c\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"RESOLVE ZipCode.stateCode\",\"type\":\"custom\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.847Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending span {\"span\":\"b50aae702985af3c\",\"parent\":\"6ea35beabe4c93a5\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"GraphQL: ExampleQuery__buyer_subgraph__0 zipCode\",\"type\":\"db\"}"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.848Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted http.IncomingMessage end event {\"id\":\"d4c80769bd782f45\"}"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.849Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended span {\"span\":\"a1687e12f4170eab\",\"parent\":\"d4c80769bd782f45\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"POST buyer-subgraph:3000\",\"type\":\"external\",\"subtype\":\"http\",\"action\":\"POST\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.850Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<> )","ecs":{"version":"1.6.0"},"message":"addEndedTransaction(ExampleQuery__buyer_subgraph__0 zipCode (/graphql))"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.850Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(d4c807, 'POST unknown route (unnamed)')> )","ecs":{"version":"1.6.0"},"message":"addEndedSpan(POST buyer-subgraph:3000)"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.851Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"encoding span {\"span\":\"a1687e12f4170eab\",\"parent\":\"d4c80769bd782f45\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"POST buyer-subgraph:3000\",\"type\":\"external\"}"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.852Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending span {\"span\":\"a1687e12f4170eab\",\"parent\":\"d4c80769bd782f45\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"name\":\"POST buyer-subgraph:3000\",\"type\":\"external\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.852Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending transaction {\"trans\":\"6ea35beabe4c93a5\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\"}"}
buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.852Z","log":{"logger":"elastic-apm-node"},"trans":"6ea35beabe4c93a5","name":"ExampleQuery__buyer_subgraph__0 zipCode (/graphql)","parent":"a1687e12f4170eab","trace":"2cd752910a8e56288d67186f1cca8588","type":"graphql","result":"HTTP 2xx","duration":347.311,"ecs":{"version":"1.6.0"},"message":"ended transaction"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.859Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting transaction result {\"trans\":\"d4c80769bd782f45\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\",\"result\":\"HTTP 2xx\"}"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.863Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting default transaction name: POST /graphql {\"trans\":\"d4c80769bd782f45\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\"}"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.864Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<> )","ecs":{"version":"1.6.0"},"message":"addEndedTransaction(POST /graphql)"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.866Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending transaction {\"trans\":\"d4c80769bd782f45\",\"trace\":\"2cd752910a8e56288d67186f1cca8588\"}"}
graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-04-04T19:59:47.866Z","log":{"logger":"elastic-apm-node"},"trans":"d4c80769bd782f45","name":"POST /graphql","trace":"2cd752910a8e56288d67186f1cca8588","type":"request","result":"HTTP 2xx","duration":482.225,"ecs":{"version":"1.6.0"},"message":"ended transaction"}

diskra avatar Apr 05 '23 13:04 diskra

same problem, any progress please ?

farzin-khaleghian avatar Apr 13 '23 17:04 farzin-khaleghian

@diskra Thanks for the issue, and my apologies for the delay looking at this.

Can you (or @farzin-khaleghian) help me reproduce here? When I attempt to run your code:

npx tsc index.ts
node dist/index.js

I get this error:

Error: When a manual configuration is not provided, gateway requires an Apollo configuration. See https://www.apollographql.com/docs/apollo-server/federation/managed-federation/ for more information. Manual configuration options include: `serviceList`, `supergraphSdl`, and `experimental_updateServiceDefinitions`.
    at ApolloGateway.load (/Users/trentm/el/apm-agent-nodejs10/tmp/issue3245/node_modules/@apollo/gateway/dist/index.js:264:23)
    at SchemaManager.start (/Users/trentm/el/apm-agent-nodejs10/tmp/issue3245/node_modules/apollo-server-core/dist/utils/schemaManager.js:42:65)
    at ApolloServer._start (/Users/trentm/el/apm-agent-nodejs10/tmp/issue3245/node_modules/apollo-server-core/dist/ApolloServer.js:195:50)
    at ApolloServer.start (/Users/trentm/el/apm-agent-nodejs10/tmp/issue3245/node_modules/apollo-server-core/dist/ApolloServer.js:180:27)
    at startGateway (/Users/trentm/el/apm-agent-nodejs10/tmp/issue3245/dist/index.js:81:18)
    at startApolloServer (/Users/trentm/el/apm-agent-nodejs10/tmp/issue3245/dist/index.js:89:12)
    at Object.<anonymous> (/Users/trentm/el/apm-agent-nodejs10/tmp/issue3245/dist/index.js:91:1)
    at Module._compile (node:internal/modules/cjs/loader:1196:14)
    at Object.Module._extensions..js (node:internal/modules/cjs/loader:1250:10)
    at Module.load (node:internal/modules/cjs/loader:1074:32)
    at Function.Module._load (node:internal/modules/cjs/loader:909:12)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:81:12)
    at node:internal/main/run_main_module:22:47

Or I could run with NODE_ENV=local if I had a "./supergraph.graphql" file. I stopped in the Apollo supergraph docs quickstart before installing the rover tool or creating an Apollo account.

I'm still looking at your debug log. It looks like the transaction.name was set properly in the GraphQL instrumentation, and then later when the transaction was ended that was overwritten with the POST /graphql express-route-based info. I think this may require a change to the APM agent to deal with prioritization of setting the transaction.name when multiple instrumentations are in play (in this case 'graphql' and 'express').

trentm avatar May 10 '23 22:05 trentm

@trentm My bad for not including the supergraph schema. I will post a sample below, however, not sure if it would actually work without the service linked actually running. With all that said, this PR that you merged in recently is actually the end goal https://github.com/elastic/apm-agent-nodejs/pull/3203 and as soon as it's available on npm, I will immediately give it a shot and see if everything is working as expected and if it is, this issue would be irrelevant for me/us personally. With alll that said, here is the supergraph

schema
  @link(url: "https://specs.apollo.dev/link/v1.0")
  @link(url: "https://specs.apollo.dev/join/v0.3", for: EXECUTION)
{
  query: Query
}

directive @join__enumValue(graph: join__Graph!) repeatable on ENUM_VALUE

directive @join__field(graph: join__Graph, requires: join__FieldSet, provides: join__FieldSet, type: String, external: Boolean, override: String, usedOverridden: Boolean) repeatable on FIELD_DEFINITION | INPUT_FIELD_DEFINITION

directive @join__graph(name: String!, url: String!) on ENUM_VALUE

directive @join__implements(graph: join__Graph!, interface: String!) repeatable on OBJECT | INTERFACE

directive @join__type(graph: join__Graph!, key: join__FieldSet, extension: Boolean! = false, resolvable: Boolean! = true, isInterfaceObject: Boolean! = false) repeatable on OBJECT | INTERFACE | UNION | ENUM | INPUT_OBJECT | SCALAR

directive @join__unionMember(graph: join__Graph!, member: String!) repeatable on UNION

directive @link(url: String, as: String, for: link__Purpose, import: [link__Import]) repeatable on SCHEMA

scalar join__FieldSet

enum join__Graph {
  BACKOFFICE_SUBGRAPH @join__graph(name: "backoffice-subgraph", url: "http://backoffice-subgraph:3000/graphql")
}

scalar link__Import

enum link__Purpose {
  """
  `SECURITY` features provide metadata necessary to securely resolve fields.
  """
  SECURITY

  """
  `EXECUTION` features provide metadata necessary for operation execution.
  """
  EXECUTION
}

type Query
  @join__type(graph: BACKOFFICE_SUBGRAPH)
{
  _backoffice: Boolean
}

diskra avatar May 11 '23 01:05 diskra

Thanks. As you suspected, I can get very far with a local repro because I don't have a http://backoffice-subgraph:3000/graphql running.

Looking again at the debug log you posted, I misinterpreted it earlier. I think I see why the original transaction is not getting a graphql-y name.

First, let's consider a single GraphQL service -- i.e. not one using Apollo Gateway. When you call it via curl -X POST http://localhost:3000/graphql?... what happens is:

  • The Express routing directs it to a handler that will ultimately use graphql.execute(...) to make a GraphQL call. At this step the APM agent's http instrumentation creates a unnamed Transaction for the HTTP request, and its apollo-server-core instrumentation sets a boolean on that transaction say "this request is for graphql-related stuff, but I'll wait for the graphql instrumentation to set a good transaction name from the parsed query.
  • Next, the graphql.execute(...) call is made. The APM agent's graphql instrumentation creates a GraphQL Span named GraphQL: ..., and it uses the parsed query info to set a transaction name.
  • When the transaction ends, the APM agent skips using the Express route info to set a transaction name, because a name has already been set.

Now take the Apollo Gateway case:

  • The entry service (graph-gateway-1 in your log), receives the HTTP request. The APM agent's http instrumentation creates an unnamed Transaction, and its apollo-server-core instrumentation sets the boolean marker.
  • The Apollo Gateway code makes an HTTP client request to buyer-subgraph:3000, which eventually returns.
  • When the transaction ends, the APM agent uses the Express route information to set the transaction name to POST /graphql.

The difference here is that the APM agent in the graph-gateway-1 service has no instrumentation that handles the parsed graphql query. graphql.execute(...) is not used in this service, so currently the APM agent doesn't have anything looking at a parsed GraphQL query to use to set a GraphQL-y transaction.name.

To support this I think we'd need the APM agent to instrument the appropriate part of @apollo/gateway to have parsed query information to use to set a good transaction.name. If you have suggests as to the inner workings of @apollo/gateway that would help. The thing that would most help would be a small repro case (in a small github repository or where ever) that showed a small Apollo Gateway service and a downstream Apollo Server app that it calls out to.

trentm avatar May 11 '23 21:05 trentm

@trentm Thank you for that detailed explanation, I certainly learned a lot from it. Unfortunately, I don't know much about the inner workings of Apollo's core. I just setup a very stripped down dockerized setup for you to play with, if you wish to do so, https://github.com/diskra/trent-dejan

diskra avatar May 11 '23 22:05 diskra

I just setup a very stripped down dockerized setup for you to play with

Thanks!

So far, I get some errors. First in yarn:

error Couldn't find package "@rockethomes/[email protected]" required by "@eapi/[email protected]" on the "npm" registry.

in yarn run tsbuild:

$ tsc --build --clean && tsc --build
libraries/graphql-helper/src/custom-scalar.ts:1:20 - error TS2307: Cannot find module 'moment' or its corresponding type declarations.

1 import moment from "moment";
                     ~~~~~~~~

libraries/graphql-helper/src/graph.ts:9:33 - error TS2307: Cannot find module 'graphql-middleware' or its corresponding type declarations.

9 import { applyMiddleware } from "graphql-middleware";
                                  ~~~~~~~~~~~~~~~~~~~~

libraries/graphql-helper/src/graph.ts:10:37 - error TS2307: Cannot find module '@apollo/subgraph' or its corresponding type declarations.

10 import { buildSubgraphSchema } from "@apollo/subgraph";
                                       ~~~~~~~~~~~~~~~~~~


Found 3 errors.

error Command failed with exit code 1.

and I'll have to install rover.

Full log here: https://gist.github.com/trentm/9824fb78b0278413cda48d77420acf27

Ideas?

trentm avatar May 11 '23 22:05 trentm

@trentm very sorry about that. I just pushed up a few commits that remove the @rockethomes/[email protected] package, as well as remove the need for rover installation. Pull down the latest and let me know if you run into any more issues.

diskra avatar May 11 '23 23:05 diskra

@trentm tested out this just now https://github.com/elastic/apm-agent-nodejs/pull/3336 and apollo server 4 works as expected, without a gateway. With a gateway, the gateway shows is transaction type "request" instead of graphql but when the gateway sends the request down the chain, to the other services (apollo servers), it shows as graphql type.

Does not work Screenshot 2023-05-31 at 1 28 51 PM

const server = new ApolloServer({
    gateway,
    introspection: true,
    plugins: getPlugins(true),
    includeStacktraceInErrorResponses: process.env.NODE_ENV !== "prod",
  });

Works Screenshot 2023-05-31 at 1 32 38 PM

const server = new ApolloServer({
    schema: shieldedSchema,
    plugins: getPlugins(),
    includeStacktraceInErrorResponses: process.env.NODE_ENV !== "prod",
  });

package.json

"@apollo/gateway": "^2.3.3",
"@apollo/subgraph": "^2.3.3",
"@apollo/server": "^4.4.0",
"elastic-apm-node": "^3.46.0"

Here are the debug logs.

eapi-graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.281Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted request event call to http.Server.prototype.emit for /graphql"}
eapi-graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.282Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start trace {\"trans\":\"1d74fa67b3eace88\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"unnamed\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
eapi-graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.282Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(1d74fa, 'unnamed')> )","ecs":{"version":"1.6.0"},"message":"supersedeWithTransRunContext(<Trans 1d74fa67b3eace88>)"}
eapi-graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.286Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start span {\"span\":\"f84a72e128bdc513\",\"parent\":\"1d74fa67b3eace88\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"unnamed\",\"type\":\"external\",\"subtype\":\"http\",\"action\":null}"}
eapi-graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.287Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to http.request {\"id\":\"1d74fa67b3eace88\"}"}
eapi-graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.287Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"request details: {\"protocol\":\"http:\",\"host\":\"buyer-subgraph:3000\",\"id\":\"1d74fa67b3eace88\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.293Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted request event call to http.Server.prototype.emit for /graphql"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.296Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"continue trace {\"trans\":\"e3926bbdc5dc1a61\",\"parent\":\"f84a72e128bdc513\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"unnamed\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.296Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(e3926b, 'unnamed')> )","ecs":{"version":"1.6.0"},"message":"supersedeWithTransRunContext(<Trans e3926bbdc5dc1a61>)"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.301Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to graphql.execute"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.301Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start span {\"span\":\"884f32ce212d09ba\",\"parent\":\"e3926bbdc5dc1a61\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"GraphQL: Unknown Query\",\"type\":\"db\",\"subtype\":\"graphql\",\"action\":\"execute\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.302Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting default transaction name: ZipCode__buyer_subgraph__0 zipCode (/graphql) {\"trans\":\"e3926bbdc5dc1a61\",\"parent\":\"f84a72e128bdc513\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.302Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start span {\"span\":\"824c2d5014385942\",\"parent\":\"884f32ce212d09ba\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE Query.zipCode\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.303Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(e3926b, 'ZipCode__buyer_subgraph__0 zipCode (/graphql)'), [Span(884f32, 'GraphQL: ZipCode__buyer_subgraph__0 zipCode'),Span(824c2d, 'RESOLVE Query.zipCode')]> )","ecs":{"version":"1.6.0"},"message":"supersedeWithSpanRunContext(<Span 824c2d5014385942>)"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.303Z","log":{"logger":"elastic-apm-node"},"method":"POST","path":"/local-location/_search","ecs":{"version":"1.6.0"},"message":"intercepted call to @elastic/elasticsearch.Transport.prototype.request"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.304Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start span {\"span\":\"541b6ad6c16c885b\",\"parent\":\"824c2d5014385942\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"Elasticsearch: POST /local-location/_search\",\"type\":\"db\",\"subtype\":\"elasticsearch\",\"action\":\"request\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.304Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to https.request {\"id\":null}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.425Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended span {\"span\":\"541b6ad6c16c885b\",\"parent\":\"824c2d5014385942\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"Elasticsearch: POST /local-location/_search\",\"type\":\"db\",\"subtype\":\"elasticsearch\",\"action\":\"request\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.425Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(e3926b, 'ZipCode__buyer_subgraph__0 zipCode (/graphql)'), [Span(884f32, 'GraphQL: ZipCode__buyer_subgraph__0 zipCode'),Span(824c2d, 'RESOLVE Query.zipCode')]> )","ecs":{"version":"1.6.0"},"message":"addEndedSpan(Elasticsearch: POST /local-location/_search)"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.425Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"encoding span {\"span\":\"541b6ad6c16c885b\",\"parent\":\"824c2d5014385942\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"Elasticsearch: POST /local-location/_search\",\"type\":\"db\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.426Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended span {\"span\":\"824c2d5014385942\",\"parent\":\"884f32ce212d09ba\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE Query.zipCode\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.426Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(e3926b, 'ZipCode__buyer_subgraph__0 zipCode (/graphql)'), [Span(884f32, 'GraphQL: ZipCode__buyer_subgraph__0 zipCode')]> )","ecs":{"version":"1.6.0"},"message":"addEndedSpan(RESOLVE Query.zipCode)"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.426Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"encoding span {\"span\":\"824c2d5014385942\",\"parent\":\"884f32ce212d09ba\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE Query.zipCode\",\"type\":\"custom\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.427Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start span {\"span\":\"d517817294c9e20a\",\"parent\":\"824c2d5014385942\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE ZipCode.id\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.427Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(e3926b, 'ZipCode__buyer_subgraph__0 zipCode (/graphql)'), [Span(884f32, 'GraphQL: ZipCode__buyer_subgraph__0 zipCode'),Span(824c2d, 'RESOLVE Query.zipCode', ended),Span(d51781, 'RESOLVE ZipCode.id')]> )","ecs":{"version":"1.6.0"},"message":"supersedeWithSpanRunContext(<Span d517817294c9e20a>)"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.427Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start span {\"span\":\"b1653a3148159b2d\",\"parent\":\"d517817294c9e20a\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE ZipCode.name\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.427Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(e3926b, 'ZipCode__buyer_subgraph__0 zipCode (/graphql)'), [Span(884f32, 'GraphQL: ZipCode__buyer_subgraph__0 zipCode'),Span(824c2d, 'RESOLVE Query.zipCode', ended),Span(d51781, 'RESOLVE ZipCode.id'),Span(b1653a, 'RESOLVE ZipCode.name')]> )","ecs":{"version":"1.6.0"},"message":"supersedeWithSpanRunContext(<Span b1653a3148159b2d>)"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.427Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start span {\"span\":\"858495df2341dca9\",\"parent\":\"b1653a3148159b2d\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE ZipCode.webUrl\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.427Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(e3926b, 'ZipCode__buyer_subgraph__0 zipCode (/graphql)'), [Span(884f32, 'GraphQL: ZipCode__buyer_subgraph__0 zipCode'),Span(824c2d, 'RESOLVE Query.zipCode', ended),Span(d51781, 'RESOLVE ZipCode.id'),Span(b1653a, 'RESOLVE ZipCode.name'),Span(858495, 'RESOLVE ZipCode.webUrl')]> )","ecs":{"version":"1.6.0"},"message":"supersedeWithSpanRunContext(<Span 858495df2341dca9>)"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.428Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start span {\"span\":\"7e67142623d5c54f\",\"parent\":\"858495df2341dca9\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE ZipCode.webName\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.428Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(e3926b, 'ZipCode__buyer_subgraph__0 zipCode (/graphql)'), [Span(884f32, 'GraphQL: ZipCode__buyer_subgraph__0 zipCode'),Span(824c2d, 'RESOLVE Query.zipCode', ended),Span(d51781, 'RESOLVE ZipCode.id'),Span(b1653a, 'RESOLVE ZipCode.name'),Span(858495, 'RESOLVE ZipCode.webUrl'),Span(7e6714, 'RESOLVE ZipCode.webName')]> )","ecs":{"version":"1.6.0"},"message":"supersedeWithSpanRunContext(<Span 7e67142623d5c54f>)"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.428Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended span {\"span\":\"d517817294c9e20a\",\"parent\":\"824c2d5014385942\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE ZipCode.id\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.428Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(e3926b, 'ZipCode__buyer_subgraph__0 zipCode (/graphql)'), [Span(884f32, 'GraphQL: ZipCode__buyer_subgraph__0 zipCode'),Span(824c2d, 'RESOLVE Query.zipCode', ended)]> )","ecs":{"version":"1.6.0"},"message":"addEndedSpan(RESOLVE ZipCode.id)"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.428Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"encoding span {\"span\":\"d517817294c9e20a\",\"parent\":\"824c2d5014385942\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE ZipCode.id\",\"type\":\"custom\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.429Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended span {\"span\":\"b1653a3148159b2d\",\"parent\":\"d517817294c9e20a\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE ZipCode.name\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.429Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(e3926b, 'ZipCode__buyer_subgraph__0 zipCode (/graphql)'), [Span(884f32, 'GraphQL: ZipCode__buyer_subgraph__0 zipCode'),Span(824c2d, 'RESOLVE Query.zipCode', ended),Span(d51781, 'RESOLVE ZipCode.id', ended)]> )","ecs":{"version":"1.6.0"},"message":"addEndedSpan(RESOLVE ZipCode.name)"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.429Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"encoding span {\"span\":\"b1653a3148159b2d\",\"parent\":\"d517817294c9e20a\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE ZipCode.name\",\"type\":\"custom\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.429Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended span {\"span\":\"858495df2341dca9\",\"parent\":\"b1653a3148159b2d\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE ZipCode.webUrl\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.429Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(e3926b, 'ZipCode__buyer_subgraph__0 zipCode (/graphql)'), [Span(884f32, 'GraphQL: ZipCode__buyer_subgraph__0 zipCode'),Span(824c2d, 'RESOLVE Query.zipCode', ended),Span(d51781, 'RESOLVE ZipCode.id', ended),Span(b1653a, 'RESOLVE ZipCode.name', ended)]> )","ecs":{"version":"1.6.0"},"message":"addEndedSpan(RESOLVE ZipCode.webUrl)"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.429Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"encoding span {\"span\":\"858495df2341dca9\",\"parent\":\"b1653a3148159b2d\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE ZipCode.webUrl\",\"type\":\"custom\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.430Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended span {\"span\":\"7e67142623d5c54f\",\"parent\":\"858495df2341dca9\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE ZipCode.webName\",\"type\":\"custom\",\"subtype\":null,\"action\":null}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.430Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(e3926b, 'ZipCode__buyer_subgraph__0 zipCode (/graphql)'), [Span(884f32, 'GraphQL: ZipCode__buyer_subgraph__0 zipCode'),Span(824c2d, 'RESOLVE Query.zipCode', ended),Span(d51781, 'RESOLVE ZipCode.id', ended),Span(b1653a, 'RESOLVE ZipCode.name', ended),Span(858495, 'RESOLVE ZipCode.webUrl', ended)]> )","ecs":{"version":"1.6.0"},"message":"addEndedSpan(RESOLVE ZipCode.webName)"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.430Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"encoding span {\"span\":\"7e67142623d5c54f\",\"parent\":\"858495df2341dca9\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE ZipCode.webName\",\"type\":\"custom\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.432Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended span {\"span\":\"884f32ce212d09ba\",\"parent\":\"e3926bbdc5dc1a61\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"GraphQL: ZipCode__buyer_subgraph__0 zipCode\",\"type\":\"db\",\"subtype\":\"graphql\",\"action\":\"execute\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.432Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(e3926b, 'ZipCode__buyer_subgraph__0 zipCode (/graphql)')> )","ecs":{"version":"1.6.0"},"message":"addEndedSpan(GraphQL: ZipCode__buyer_subgraph__0 zipCode)"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.433Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"encoding span {\"span\":\"884f32ce212d09ba\",\"parent\":\"e3926bbdc5dc1a61\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"GraphQL: ZipCode__buyer_subgraph__0 zipCode\",\"type\":\"db\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.434Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting transaction result {\"trans\":\"e3926bbdc5dc1a61\",\"parent\":\"f84a72e128bdc513\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"result\":\"HTTP 2xx\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.434Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending span {\"span\":\"541b6ad6c16c885b\",\"parent\":\"824c2d5014385942\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"Elasticsearch: POST /local-location/_search\",\"type\":\"db\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.435Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending span {\"span\":\"824c2d5014385942\",\"parent\":\"884f32ce212d09ba\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE Query.zipCode\",\"type\":\"custom\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.435Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending span {\"span\":\"d517817294c9e20a\",\"parent\":\"824c2d5014385942\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE ZipCode.id\",\"type\":\"custom\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.435Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending span {\"span\":\"b1653a3148159b2d\",\"parent\":\"d517817294c9e20a\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE ZipCode.name\",\"type\":\"custom\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.435Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending span {\"span\":\"858495df2341dca9\",\"parent\":\"b1653a3148159b2d\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE ZipCode.webUrl\",\"type\":\"custom\"}"}
eapi-graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.435Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted http.ClientRequest response event {\"id\":\"1d74fa67b3eace88\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.435Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending span {\"span\":\"7e67142623d5c54f\",\"parent\":\"858495df2341dca9\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"RESOLVE ZipCode.webName\",\"type\":\"custom\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.435Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending span {\"span\":\"884f32ce212d09ba\",\"parent\":\"e3926bbdc5dc1a61\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"GraphQL: ZipCode__buyer_subgraph__0 zipCode\",\"type\":\"db\"}"}
eapi-graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.436Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted http.IncomingMessage end event {\"id\":\"1d74fa67b3eace88\"}"}
eapi-graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.436Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended span {\"span\":\"f84a72e128bdc513\",\"parent\":\"1d74fa67b3eace88\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"POST buyer-subgraph:3000\",\"type\":\"external\",\"subtype\":\"http\",\"action\":\"POST\"}"}
eapi-graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.436Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(1d74fa, 'POST unknown route (unnamed)')> )","ecs":{"version":"1.6.0"},"message":"addEndedSpan(POST buyer-subgraph:3000)"}
eapi-graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.437Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"encoding span {\"span\":\"f84a72e128bdc513\",\"parent\":\"1d74fa67b3eace88\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"POST buyer-subgraph:3000\",\"type\":\"external\"}"}
eapi-graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.437Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending span {\"span\":\"f84a72e128bdc513\",\"parent\":\"1d74fa67b3eace88\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"name\":\"POST buyer-subgraph:3000\",\"type\":\"external\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.436Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<> )","ecs":{"version":"1.6.0"},"message":"addEndedTransaction(ZipCode__buyer_subgraph__0 zipCode (/graphql))"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.437Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending transaction {\"trans\":\"e3926bbdc5dc1a61\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\"}"}
eapi-buyer-subgraph-1       | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.437Z","log":{"logger":"elastic-apm-node"},"trans":"e3926bbdc5dc1a61","name":"ZipCode__buyer_subgraph__0 zipCode (/graphql)","parent":"f84a72e128bdc513","trace":"d454cb70374972d40ea22f98d767cdca","type":"graphql","result":"HTTP 2xx","duration":140.661,"ecs":{"version":"1.6.0"},"message":"ended transaction"}
eapi-graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.439Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting transaction result {\"trans\":\"1d74fa67b3eace88\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\",\"result\":\"HTTP 2xx\"}"}
eapi-graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.440Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting default transaction name: POST /graphql {\"trans\":\"1d74fa67b3eace88\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\"}"}
eapi-graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.440Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<> )","ecs":{"version":"1.6.0"},"message":"addEndedTransaction(POST /graphql)"}
eapi-graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.441Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending transaction {\"trans\":\"1d74fa67b3eace88\",\"trace\":\"d454cb70374972d40ea22f98d767cdca\"}"}
eapi-graph-gateway-1        | {"log.level":"debug","@timestamp":"2023-05-31T17:25:53.441Z","log":{"logger":"elastic-apm-node"},"trans":"1d74fa67b3eace88","name":"POST /graphql","trace":"d454cb70374972d40ea22f98d767cdca","type":"request","result":"HTTP 2xx","duration":158.37,"ecs":{"version":"1.6.0"},"message":"ended transaction"}

diskra avatar May 31 '23 17:05 diskra

With a gateway, the gateway shows is transaction type "request" instead of graphql but when the gateway sends the request down the chain, to the other services (apollo servers), it shows as graphql type.

@diskra Yes, that fits my understanding. If we want the incoming requests to the Apollo Gateway-using server to be marked as GraphQL requests, then we'll need to add new instrumentation of the @apollo/gateway library.

trentm avatar May 31 '23 20:05 trentm

Sorry that I haven't had a chance to get back to this one yet.

trentm avatar May 31 '23 20:05 trentm

@trentm all good, we are all busy. I get it :)

diskra avatar Jun 01 '23 13:06 diskra

I won't be able to learn @apollo/gateway and dig into this for this milestone.

trentm avatar Jun 28 '23 20:06 trentm

Hello ! Same issue here, any work arround while this is being fixed ?

rchoffar avatar Mar 11 '24 15:03 rchoffar