Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix cardinality of opentelemetry span names on client-side navigation #59282

Closed

Conversation

Leonils
Copy link

@Leonils Leonils commented Dec 5, 2023

What?

As noticed in issue #54694, span names for dynamic routes are not consistent and sometimes miss the "next.route" attribute, and have a span name that have the parameters instead of the capturing placeholders.

Fixing a bug or a limitation

  • Fixes High-cardinality HTTP span names #54694 (at least partially)
  • Adds test case for client-side navigation previously leading to wrong span attributes (test added into the test/e2e/opentelemetry test suite)
  • Updated test/e2e/opentelemetry app used to test telemetry (some pages with link between them where created but not quite correct in the links, and were not handling the defined params)

Limits

This PR identify a case where some traces are wrong (see bellow for the detailed identified case). But there might be others that the other of #54694 might think of.

How

Function renderToHTMLOrFlightImpl is the one responsible for rendering of the page. It is also the one that set the next.route attribute, the one that has the interpreted route instead of the full url. However, there is a shortcut to exit the function before next.route is set when the condition isRSCRequest && !isStaticGeneration is met. I think we can set next.route before, so in any case the route has the correct value.

Added test

The added test go to page /app/foo/loading/page1, then click to the <Link/> to /app/[param]/loading/page2. The diff between the expected traces and the ones we get without the fix are:

    {
      ...
      "name": "render route (app) /app/[param]/loading/page1",
      ...
    },
    {
      ...
      "name": "GET /app/[param]/loading/page1",
      ...
    },
    {
      "attributes": {
        "http.method": "GET",
-       "http.route": "/app/[param]/loading/page1",
        "http.status_code": 200,
        "http.target": "/app/foo/loading/page1?_rsc=4t3jn",
-       "next.route": "/app/[param]/loading/page1",
-       "next.span_name": "GET /app/[param]/loading/page1",
+       "next.span_name": "GET /app/foo/loading/page1?_rsc=4t3jn",
        "next.span_type": "BaseServer.handleRequest",
      },
      "kind": 1,
-     "name": "GET /app/[param]/loading/page1",
+     "name": "GET /app/foo/loading/page1?_rsc=4t3jn",
      "parentId": undefined,
      "status": {
        "code": 0,
      },
      "traceId": "[trace-id]",
    },
    {
      "attributes": {
        "http.method": "GET",
-       "http.route": "/app/[param]/loading/page2",
        "http.status_code": 200,
        "http.target": "/app/foo/loading/page2?_rsc=1lrnj",
-       "next.route": "/app/[param]/loading/page2",
-       "next.span_name": "GET /app/[param]/loading/page2",
+       "next.span_name": "GET /app/foo/loading/page2?_rsc=1lrnj",
        "next.span_type": "BaseServer.handleRequest",
      },
      "kind": 1,
-     "name": "GET /app/[param]/loading/page2",
+     "name": "GET /app/foo/loading/page2?_rsc=1lrnj",
      "parentId": undefined,
      "status": {
        "code": 0,
      },
      "traceId": "[trace-id]",
    },
    {
      "attributes": {
        "http.method": "GET",
-       "http.route": "/app/[param]/loading/page2",
        "http.status_code": 200,
        "http.target": "/app/foo/loading/page2?_rsc=1yei0",
-       "next.route": "/app/[param]/loading/page2",
-       "next.span_name": "GET /app/[param]/loading/page2",
+       "next.span_name": "GET /app/foo/loading/page2?_rsc=1yei0",
        "next.span_type": "BaseServer.handleRequest",
      },
      "kind": 1,
-     "name": "GET /app/[param]/loading/page2",
+     "name": "GET /app/foo/loading/page2?_rsc=1yei0",
      "parentId": undefined,
      "status": {
        "code": 0,
      },
      "traceId": "[trace-id]",
    },
    {
      ...
      "name": "generateMetadata /app/[param]/layout",
      ...
    },
    {
      ...
      "name": "generateMetadata /app/[param]/layout",
      ...
    },

We see the first load of page1 that has the correct name, but the next render, fetched from client do not.

@feedthejim feedthejim enabled auto-merge (squash) December 5, 2023 13:41
@ijjk
Copy link
Member

ijjk commented Dec 5, 2023

Allow CI Workflow Run

  • approve CI run for commit: d378499

Note: this should only be enabled once the PR is ready to go and can only be enabled by a maintainer

1 similar comment
@ijjk
Copy link
Member

ijjk commented Dec 5, 2023

Allow CI Workflow Run

  • approve CI run for commit: d378499

Note: this should only be enabled once the PR is ready to go and can only be enabled by a maintainer

@feedthejim feedthejim added the CI approved Approve running CI for fork label Dec 5, 2023
@ijjk
Copy link
Member

ijjk commented Dec 5, 2023

Failing test suites

Commit: 697f99e

pnpm test-dev test/development/app-hmr/hmr.test.ts

  • app-dir-hmr > filesystem changes > should not break when renaming a folder
Expand output

● app-dir-hmr › filesystem changes › should not break when renaming a folder

TIMED OUT: success

undefined

Error: elementHandle.innerText: Element is not attached to the DOM

  626 |
  627 |   if (hardError) {
> 628 |     throw new Error('TIMED OUT: ' + regex + '\n\n' + content + '\n\n' + lastErr)
      |           ^
  629 |   }
  630 |   return false
  631 | }

  at check (lib/next-test-utils.ts:628:11)
  at Object.<anonymous> (development/app-hmr/hmr.test.ts:44:11)

Read more about building and testing Next.js in contributing.md.

pnpm test-start test/e2e/opentelemetry/opentelemetry.test.ts

  • opentelemetry > incoming context propagation > app router > should handle client-side navigation
  • opentelemetry > root context > app router > should handle client-side navigation
Expand output

● opentelemetry › root context › app router › should handle client-side navigation

expect(received).toMatchInlineSnapshot(snapshot)

Snapshot name: `opentelemetry root context app router should handle client-side navigation 1`

- Snapshot  - 11
+ Received  + 93

@@ -13,32 +13,42 @@
      },
      "traceId": "[trace-id]",
    },
    {
      "attributes": {
-       "http.method": "GET",
-       "http.route": "/app/[param]/loading/page1",
-       "http.status_code": 200,
-       "http.target": "/app/foo/loading/page1",
        "next.route": "/app/[param]/loading/page1",
-       "next.span_name": "GET /app/[param]/loading/page1",
-       "next.span_type": "BaseServer.handleRequest",
+       "next.span_name": "render route (app) /app/[param]/loading/page1",
+       "next.span_type": "AppRender.getBodyResult",
      },
-     "kind": 1,
-     "name": "GET /app/[param]/loading/page1",
-     "parentId": undefined,
+     "kind": 0,
+     "name": "render route (app) /app/[param]/loading/page1",
+     "parentId": "[parent-id]",
+     "status": {
+       "code": 0,
+     },
+     "traceId": "[trace-id]",
+   },
+   {
+     "attributes": {
+       "next.route": "/app/[param]/loading/page2",
+       "next.span_name": "render route (app) /app/[param]/loading/page2",
+       "next.span_type": "AppRender.getBodyResult",
+     },
+     "kind": 0,
+     "name": "render route (app) /app/[param]/loading/page2",
+     "parentId": "[parent-id]",
      "status": {
        "code": 0,
      },
      "traceId": "[trace-id]",
    },
    {
      "attributes": {
        "http.method": "GET",
        "http.route": "/app/[param]/loading/page1",
        "http.status_code": 200,
-       "http.target": "/app/foo/loading/page1?_rsc=4t3jn",
+       "http.target": "/app/foo/loading/page1",
        "next.route": "/app/[param]/loading/page1",
        "next.span_name": "GET /app/[param]/loading/page1",
        "next.span_type": "BaseServer.handleRequest",
      },
      "kind": 1,
@@ -70,18 +80,90 @@
    {
      "attributes": {
        "http.method": "GET",
        "http.route": "/app/[param]/loading/page2",
        "http.status_code": 200,
-       "http.target": "/app/foo/loading/page2?_rsc=1yei0",
+       "http.target": "/app/foo/loading/page2?_rsc=1ehoc",
        "next.route": "/app/[param]/loading/page2",
        "next.span_name": "GET /app/[param]/loading/page2",
        "next.span_type": "BaseServer.handleRequest",
      },
      "kind": 1,
      "name": "GET /app/[param]/loading/page2",
      "parentId": undefined,
+     "status": {
+       "code": 0,
+     },
+     "traceId": "[trace-id]",
+   },
+   {
+     "attributes": {
+       "http.method": "GET",
+       "http.status_code": 200,
+       "http.target": "/app/foo/loading/page1?_rsc=4t3jn",
+       "next.span_name": "GET /app/foo/loading/page1?_rsc=4t3jn",
+       "next.span_type": "BaseServer.handleRequest",
+     },
+     "kind": 1,
+     "name": "GET /app/foo/loading/page1?_rsc=4t3jn",
+     "parentId": undefined,
+     "status": {
+       "code": 0,
+     },
+     "traceId": "[trace-id]",
+   },
+   {
+     "attributes": {
+       "next.page": "/app/[param]/layout",
+       "next.span_name": "generateMetadata /app/[param]/layout",
+       "next.span_type": "ResolveMetadata.generateMetadata",
+     },
+     "kind": 0,
+     "name": "generateMetadata /app/[param]/layout",
+     "parentId": "[parent-id]",
+     "status": {
+       "code": 0,
+     },
+     "traceId": "[trace-id]",
+   },
+   {
+     "attributes": {
+       "next.page": "/app/[param]/layout",
+       "next.span_name": "generateMetadata /app/[param]/layout",
+       "next.span_type": "ResolveMetadata.generateMetadata",
+     },
+     "kind": 0,
+     "name": "generateMetadata /app/[param]/layout",
+     "parentId": "[parent-id]",
+     "status": {
+       "code": 0,
+     },
+     "traceId": "[trace-id]",
+   },
+   {
+     "attributes": {
+       "next.page": "/app/[param]/layout",
+       "next.span_name": "generateMetadata /app/[param]/layout",
+       "next.span_type": "ResolveMetadata.generateMetadata",
+     },
+     "kind": 0,
+     "name": "generateMetadata /app/[param]/layout",
+     "parentId": "[parent-id]",
+     "status": {
+       "code": 0,
+     },
+     "traceId": "[trace-id]",
+   },
+   {
+     "attributes": {
+       "next.page": "/app/[param]/layout",
+       "next.span_name": "generateMetadata /app/[param]/layout",
+       "next.span_type": "ResolveMetadata.generateMetadata",
+     },
+     "kind": 0,
+     "name": "generateMetadata /app/[param]/layout",
+     "parentId": "[parent-id]",
      "status": {
        "code": 0,
      },
      "traceId": "[trace-id]",
    },

  277 |                 return `not enough traces, expected 7, but got ${traces.length}`
  278 |               }
> 279 |               expect(traces).toMatchInlineSnapshot(`
      |                              ^
  280 |                 [
  281 |                   {
  282 |                     "attributes": {

  at toMatchInlineSnapshot (e2e/opentelemetry/opentelemetry.test.ts:279:30)
  at check (lib/next-test-utils.ts:610:17)
  at Object.<anonymous> (e2e/opentelemetry/opentelemetry.test.ts:274:13)

● opentelemetry › incoming context propagation › app router › should handle client-side navigation

expect(received).toMatchInlineSnapshot(snapshot)

Snapshot name: `opentelemetry incoming context propagation app router should handle client-side navigation 1`

- Snapshot  - 15
+ Received  + 11

@@ -32,55 +32,51 @@
      "traceId": "[trace-id]",
    },
    {
      "attributes": {
        "http.method": "GET",
-       "http.route": "/app/[param]/loading/page1",
+       "http.route": "/app/[param]/loading/page2",
        "http.status_code": 200,
-       "http.target": "/app/foo/loading/page1?_rsc=4t3jn",
-       "next.route": "/app/[param]/loading/page1",
-       "next.span_name": "GET /app/[param]/loading/page1",
+       "http.target": "/app/foo/loading/page2?_rsc=1ehoc",
+       "next.route": "/app/[param]/loading/page2",
+       "next.span_name": "GET /app/[param]/loading/page2",
        "next.span_type": "BaseServer.handleRequest",
      },
      "kind": 1,
-     "name": "GET /app/[param]/loading/page1",
+     "name": "GET /app/[param]/loading/page2",
      "parentId": undefined,
      "status": {
        "code": 0,
      },
      "traceId": "[trace-id]",
    },
    {
      "attributes": {
        "http.method": "GET",
-       "http.route": "/app/[param]/loading/page2",
        "http.status_code": 200,
-       "http.target": "/app/foo/loading/page2?_rsc=1lrnj",
-       "next.route": "/app/[param]/loading/page2",
-       "next.span_name": "GET /app/[param]/loading/page2",
+       "http.target": "/app/foo/loading/page1?_rsc=4t3jn",
+       "next.span_name": "GET /app/foo/loading/page1?_rsc=4t3jn",
        "next.span_type": "BaseServer.handleRequest",
      },
      "kind": 1,
-     "name": "GET /app/[param]/loading/page2",
+     "name": "GET /app/foo/loading/page1?_rsc=4t3jn",
      "parentId": undefined,
      "status": {
        "code": 0,
      },
      "traceId": "[trace-id]",
    },
    {
      "attributes": {
        "http.method": "GET",
-       "http.route": "/app/[param]/loading/page2",
        "http.status_code": 200,
-       "http.target": "/app/foo/loading/page2?_rsc=1yei0",
-       "next.route": "/app/[param]/loading/page2",
-       "next.span_name": "GET /app/[param]/loading/page2",
+       "http.target": "/app/foo/loading/page2?_rsc=1lrnj",
+       "next.span_name": "GET /app/foo/loading/page2?_rsc=1lrnj",
        "next.span_type": "BaseServer.handleRequest",
      },
      "kind": 1,
-     "name": "GET /app/[param]/loading/page2",
+     "name": "GET /app/foo/loading/page2?_rsc=1lrnj",
      "parentId": undefined,
      "status": {
        "code": 0,
      },
      "traceId": "[trace-id]",

  277 |                 return `not enough traces, expected 7, but got ${traces.length}`
  278 |               }
> 279 |               expect(traces).toMatchInlineSnapshot(`
      |                              ^
  280 |                 [
  281 |                   {
  282 |                     "attributes": {

  at toMatchInlineSnapshot (e2e/opentelemetry/opentelemetry.test.ts:279:30)
  at check (lib/next-test-utils.ts:610:17)
  at Object.<anonymous> (e2e/opentelemetry/opentelemetry.test.ts:274:13)

Read more about building and testing Next.js in contributing.md.

@Leonils
Copy link
Author

Leonils commented Dec 6, 2023

I can't retrieve the logs of why the pipeline failed. Seems there is a timeout. Do you think it comes from my update ?

@ijjk
Copy link
Member

ijjk commented Dec 7, 2023

Stats from current PR

Default Build
General
vercel/next.js canary Leonils/next.js fix/telemetry-client-navigation Change
buildDuration 10.8s 10.8s N/A
buildDurationCached 6.1s 6s N/A
nodeModulesSize 200 MB 200 MB N/A
nextStartRea..uration (ms) 422ms 419ms N/A
Client Bundles (main, webpack)
vercel/next.js canary Leonils/next.js fix/telemetry-client-navigation Change
170-HASH.js gzip 26.7 kB 26.7 kB N/A
199.HASH.js gzip 181 B 185 B N/A
3f784ff6-HASH.js gzip 53.3 kB 53.3 kB
framework-HASH.js gzip 45.2 kB 45.2 kB
main-app-HASH.js gzip 240 B 241 B N/A
main-HASH.js gzip 31.7 kB 31.6 kB N/A
webpack-HASH.js gzip 1.7 kB 1.7 kB N/A
Overall change 98.5 kB 98.5 kB
Legacy Client Bundles (polyfills)
vercel/next.js canary Leonils/next.js fix/telemetry-client-navigation Change
polyfills-HASH.js gzip 31 kB 31 kB
Overall change 31 kB 31 kB
Client Pages
vercel/next.js canary Leonils/next.js fix/telemetry-client-navigation Change
_app-HASH.js gzip 195 B 194 B N/A
_error-HASH.js gzip 183 B 182 B N/A
amp-HASH.js gzip 501 B 501 B
css-HASH.js gzip 321 B 321 B
dynamic-HASH.js gzip 2.5 kB 2.5 kB N/A
edge-ssr-HASH.js gzip 255 B 255 B
head-HASH.js gzip 349 B 350 B N/A
hooks-HASH.js gzip 368 B 369 B N/A
image-HASH.js gzip 4.27 kB 4.27 kB N/A
index-HASH.js gzip 255 B 256 B N/A
link-HASH.js gzip 2.61 kB 2.6 kB N/A
routerDirect..HASH.js gzip 311 B 309 B N/A
script-HASH.js gzip 384 B 384 B
withRouter-HASH.js gzip 307 B 306 B N/A
1afbb74e6ecf..834.css gzip 106 B 106 B
Overall change 1.57 kB 1.57 kB
Client Build Manifests
vercel/next.js canary Leonils/next.js fix/telemetry-client-navigation Change
_buildManifest.js gzip 484 B 482 B N/A
Overall change 0 B 0 B
Rendered Page Sizes
vercel/next.js canary Leonils/next.js fix/telemetry-client-navigation Change
index.html gzip 530 B 527 B N/A
link.html gzip 542 B 540 B N/A
withRouter.html gzip 524 B 524 B
Overall change 524 B 524 B
Edge SSR bundle Size
vercel/next.js canary Leonils/next.js fix/telemetry-client-navigation Change
edge-ssr.js gzip 93.7 kB 93.7 kB N/A
page.js gzip 146 kB 146 kB N/A
Overall change 0 B 0 B
Middleware size
vercel/next.js canary Leonils/next.js fix/telemetry-client-navigation Change
middleware-b..fest.js gzip 626 B 622 B N/A
middleware-r..fest.js gzip 151 B 151 B
middleware.js gzip 37.4 kB 37.4 kB N/A
edge-runtime..pack.js gzip 1.92 kB 1.92 kB
Overall change 2.07 kB 2.07 kB
Next Runtimes
vercel/next.js canary Leonils/next.js fix/telemetry-client-navigation Change
app-page-exp...dev.js gzip 168 kB 168 kB N/A
app-page-exp..prod.js gzip 93.9 kB 93.9 kB N/A
app-page-tur..prod.js gzip 94.7 kB 94.7 kB N/A
app-page-tur..prod.js gzip 89.2 kB 89.2 kB N/A
app-page.run...dev.js gzip 138 kB 138 kB N/A
app-page.run..prod.js gzip 88.5 kB 88.5 kB
app-route-ex...dev.js gzip 23.9 kB 23.9 kB
app-route-ex..prod.js gzip 16.6 kB 16.6 kB
app-route-tu..prod.js gzip 16.6 kB 16.6 kB
app-route-tu..prod.js gzip 16.2 kB 16.2 kB
app-route.ru...dev.js gzip 23.4 kB 23.4 kB
app-route.ru..prod.js gzip 16.2 kB 16.2 kB
pages-api-tu..prod.js gzip 9.37 kB 9.37 kB
pages-api.ru...dev.js gzip 9.64 kB 9.64 kB
pages-api.ru..prod.js gzip 9.37 kB 9.37 kB
pages-turbo...prod.js gzip 21.9 kB 21.9 kB
pages.runtim...dev.js gzip 22.5 kB 22.5 kB
pages.runtim..prod.js gzip 21.9 kB 21.9 kB
server.runti..prod.js gzip 49.4 kB 49.4 kB
Overall change 346 kB 346 kB
Diff details
Diff for page.js

Diff too large to display

Diff for app-page-exp..ntime.dev.js

Diff too large to display

Diff for app-page-exp..time.prod.js

Diff too large to display

Diff for app-page-tur..time.prod.js

Diff too large to display

Diff for app-page-tur..time.prod.js

Diff too large to display

Diff for app-page.runtime.dev.js

Diff too large to display

Diff for app-page.runtime.prod.js

Diff too large to display

Commit: 697f99e

@feedthejim
Copy link
Contributor

@Leonils are you not able to click on the logs from the CI? let me know if I need to copy them. Seems some of the PPR tests are not passing

@Leonils
Copy link
Author

Leonils commented Dec 12, 2023

On this run I do. I'm investigating.

@psimk
Copy link

psimk commented Mar 13, 2024

👋 any update on when this PR will get merged? it's preventing us from adopting OTEL.

@PatNeedham
Copy link

4 failing tests / checks are presumably the reason why this can't be merged yet. However when opening those 4, they all display

The logs for this run have expired and are no longer available.

Can anyone with sufficient permissions rerun / re-trigger those tests? I'd like to help out & see what might be causing them to fail

@samcx
Copy link
Member

samcx commented Apr 23, 2024

@Leonils I will be closing this :pr: in the meantime since it has gotten stale—feel free to ping me here again if you are still interested in getting this :pr: pushed!

@samcx samcx closed this Apr 23, 2024
auto-merge was automatically disabled April 23, 2024 20:58

Pull request was closed

@PatNeedham
Copy link

@samcx there was no path to merging this because nobody was able to view how / why the tests were failing - that's why I asked on March 19th if anyone can re-trigger the tests so we can collectively investigate.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators May 13, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

High-cardinality HTTP span names
6 participants