[scout] improve logs readability by using unique logger context per playwright worker #213218

dmlemeshko · 2025-03-05T11:07:25Z

Summary

Part of #203591

Our current logs are confusing as it is unclear to which worker message is related. E.g.

 proc [playwright]  debg [scout] Creating new local SAML session for role 'admin'
 proc [playwright]  debg [scout] Creating new local SAML session for role 'admin'

it is not clear if the messages are coming from the same worker or 2 different ones.

Before

[chromium] › error_handling.spec.ts:30:12 › Discover app - errors › should render invalid scripted field error @ess
 debg [scout] applying update to kibana config: {"timepicker:timeDefaults":"{ \"from\": \"2015-09-19T06:31:44.000Z\", \"to\": \"2015-09-23T18:31:44.000Z\"}"}
 debg [scout] Requesting url (redacted): [http://localhost:5620/s/test-space-0/internal/kibana/settings]
 debg [scout] scoutSpace:test-space-0 'uiSettings.setDefaultTime' took 116.66ms
...
 debg [scout] [service] browserAuth
 debg [scout] Creating new local SAML session for role 'viewer'
[chromium] › saved_searches.spec.ts:66:14 › Discover app - saved searches › should customize time range on dashboards @ess @svlSearch @svlOblt
 succ [scout] import success
 debg [scout] scoutSpace:test-space-1 'savedObjects.load' took 1028.17ms
 ...
 debg [scout] [service] browserAuth
 debg [scout] Creating new local SAML session for role 'editor'
 debg [scout] [service] scoutPage:test-space-1
 debg [scout] [service] pageObjects:test-space-1

After:

[chromium] › error_handling.spec.ts:30:12 › Discover app - errors › should render invalid scripted field error @ess
 debg [scout-worker-1] applying update to kibana config: {"timepicker:timeDefaults":"{ \"from\": \"2015-09-19T06:31:44.000Z\", \"to\": \"2015-09-23T18:31:44.000Z\"}"}
 debg [scout-worker-1] Requesting url (redacted): [http://localhost:5620/s/test-space-1/internal/kibana/settings]
 debg [scout-worker-1] test-space-1: 'uiSettings.setDefaultTime' took 131.30ms
...
 debg [scout-worker-1] [service] browserAuth
 debg [scout-worker-1] Creating new local SAML session for role 'viewer'
[chromium] › saved_searches.spec.ts:66:14 › Discover app - saved searches › should customize time range on dashboards @ess @svlSearch @svlOblt
 debg [scout-worker-2] test-space-2: 'savedObjects.load' took 1005.91ms
...
 debg [scout-worker-2] [service] browserAuth
 debg [scout-worker-2] Creating new local SAML session for role 'editor'
 debg [scout-worker-2] [service] scoutPage
 debg [scout-worker-2] [service] pageObjects

Note: single thread run will still log under scout context, let me know if it is preferable to have it similar to parallel run, e.g. [scout-worker] [service] scoutPage

How to verify:

start servers - node scripts/scout.js start-server --stateful
run tests - npx playwright test --config x-pack/platform/plugins/private/discover_enhanced/ui_tests/parallel.playwright.config.ts

dmlemeshko · 2025-03-05T11:09:42Z

src/platform/packages/shared/kbn-scout/src/playwright/fixtures/test/page_objects/parallel.ts

    const corePageObjects = createCorePageObjects(page);
-    log.serviceLoaded(`pageObjects:${scoutSpace.id}`);


I believe it is redundant: logger context helps to understand the space we use, there is a 1 to 1 match.

Sounds good about the test space ID being redundant.

A possible improvement for the future (possibly out of scope for this PR): instead of logging just pageObjects (the service name), we could log pageObjects loaded or perhaps pageObjects service loaded to make it clear the service was loaded (successfully). What do you think?

I was thinking about it too, how about having it this way (actually it was in PoC like that):

/** * Used to log when a service/fixture is loaded * @param name unique name of the service */ public serviceLoaded(name: string) { this.debug(`[${name}] loaded`); } /** * Used to log a message for a service/fixture */ public serviceMessage(name: string, message) { this.debug(`[${name}] ${name}`); }

output

debg [scout-worker-2] [scoutPage] loaded debg [scout-worker-2] [pageObjects] loaded debg [scout-worker-2] [scoutPage] just a random message from service

alternatively

debg [scout-worker-2] [service] 'scoutPage' loaded debg [scout-worker-2] [service] 'pageObjects' loaded debg [scout-worker-2] [service] [pageObjects] just a random message from service

but maybe we don't need that [service] context assuming we know that it is coming from playwright worker?

locally run

[chromium] › saved_searches.spec.ts:66:14 › Discover app - saved searches › should customize time range on dashboards @ess @svlSearch @svlOblt debg [scout-worker-2] [logger] loaded info [scout-worker-2] [config] Reading test servers confiuration from file: /Users/dmle/github/kibana/.scout/servers/local.json debg [scout-worker-2] [config] loaded debg [scout-worker-2] [kbnClient] loaded debg [scout-worker-2] Requesting url (redacted): [http://localhost:5620/api/spaces/space] [chromium] › error_handling.spec.ts:30:12 › Discover app - errors › should render invalid scripted field error @ess debg [scout-worker-1] [logger] loaded info [scout-worker-1] [config] Reading test servers confiuration from file: /Users/dmle/github/kibana/.scout/servers/local.json debg [scout-worker-1] [config] loaded debg [scout-worker-1] [kbnClient] loaded debg [scout-worker-1] Requesting url (redacted): [http://localhost:5620/api/spaces/space]

dmlemeshko · 2025-03-05T11:10:47Z

src/platform/packages/shared/kbn-scout/src/playwright/fixtures/test/scout_page/parallel.ts

@@ -33,7 +33,7 @@ export const scoutPageParallelFixture = base.extend<
    extendedPage.gotoApp = (appName: string, pathOptions?: PathOptions) =>
      page.goto(kbnUrl.app(appName, { space: scoutSpace.id, pathOptions }));

-    log.serviceLoaded(`scoutPage:${scoutSpace.id}`);


same here, scout-worker-N logger context is good enough

dmlemeshko · 2025-03-05T11:13:09Z

src/platform/packages/shared/kbn-scout/src/playwright/fixtures/worker/scout_space/parallel.ts

@@ -19,46 +19,42 @@ export const scoutSpaceParallelFixture = coreWorkerFixtures.extend<
 >({
  scoutSpace: [
    async ({ log, kbnClient }, use, workerInfo) => {
-      const spaceId = `test-space-${workerInfo.workerIndex}`;
+      const spaceId = `test-space-${workerInfo.parallelIndex + 1}`;


workerIndex vs parallelIndex:

Playwright created new worker after failure, workerIndex will be increased. Since we delete Kibana space on fixture tear down, we can and should use persistent index - parallelIndex

https://playwright.dev/docs/api/class-workerinfo#worker-info-parallel-index

dmlemeshko · 2025-03-05T11:13:50Z

src/platform/packages/shared/kbn-scout/src/playwright/fixtures/worker/scout_space/parallel.ts

-              // will create new copies of saved objects with unique ids
-              createNewCopies: true,
-            });
+        return measurePerformanceAsync(log, `${spaceId}: 'savedObjects.load'`, async () => {


simplifying message, as we know the worker index now

…na into scout/fix-logger-context

dmlemeshko · 2025-03-05T12:39:37Z

src/platform/packages/shared/kbn-scout/src/playwright/fixtures/worker/log/single_thread.ts

+>({
+  log: [
+    ({}, use) => {
+      use(getLogger('scout'));


when tests are run sequentially we will keep using "scout" context

csr · 2025-03-05T15:41:12Z

src/platform/packages/shared/kbn-scout/src/playwright/fixtures/worker/log/parallel.ts

+>({
+  log: [
+    ({}, use, workerInfo) => {
+      const loggerContext = `scout-worker-${workerInfo.workerIndex + 1}`;


Should we use the parallelIndex instead of the workerIndex here, too? Perhaps (and most likely) it makes no difference, but I wonder what you think.

we should ;) thanks for paying attention, I assumed I did it right.

csr · 2025-03-05T15:43:39Z

src/platform/packages/shared/kbn-scout/src/playwright/fixtures/worker/scout_space/parallel.ts

-        );
+        return measurePerformanceAsync(log, `${spaceId}: 'uiSettings.setDefaultTime'`, async () => {
+          const utcFrom = isValidUTCDate(from) ? from : formatTime(from);
+          const untcTo = isValidUTCDate(to) ? to : formatTime(to);


A typo here, most likely: untcTo should be utcTo.

csr · 2025-03-05T16:06:05Z

It's nice to now see the worker number next to the log, it seems to be working well with 1, 2, and 3 parallel workers:

✅ 1 Worker

Running 9 tests using 1 worker

[chromium] › error_handling.spec.ts:30:12 › Discover app - errors › should render invalid scripted field error @ess
debg [scout-worker-1] [service] logger
info [scout-worker-1] [config] Reading test servers configuration from file: /Users/cesaredecal/dev/kibana/.scout/servers/local.json
debg [scout-worker-1] [service] config
debg [scout-worker-1] [service] kbnClient
debg [scout-worker-1] Requesting url (redacted): [http://localhost:5620/api/spaces/space]
debg [scout-worker-1] Requesting url (redacted): [http://localhost:5620/api/spaces/space]
debg [scout-worker-1] Requesting url (redacted): [http://localhost:5620/api/spaces/space]
...

✅ 2 Workers

Running 9 tests using 2 workers

[chromium] › error_handling.spec.ts:30:12 › Discover app - errors › should render invalid scripted field error @ess
debg [scout-worker-1] [service] logger
[chromium] › saved_searches.spec.ts:66:14 › Discover app - saved searches › should customize time range on dashboards @ess @svlSearch @svlOblt
debg [scout-worker-2] [service] logger
info [scout-worker-1] [config] Reading test servers configuration from file: /Users/cesaredecal/dev/kibana/.scout/servers/local.json
debg [scout-worker-1] [service] config
info [scout-worker-2] [config] Reading test servers configuration from file: /Users/cesaredecal/dev/kibana/.scout/servers/local.json
debg [scout-worker-2] [service] config
debg [scout-worker-1] [service] kbnClient
debg [scout-worker-2] [service] kbnClient
debg [scout-worker-1] Requesting url (redacted): [http://localhost:5620/api/spaces/space]
debg [scout-worker-2] Requesting url (redacted): [http://localhost:5620/api/spaces/space]
debg [scout-worker-1] test-space-1: 'spaces.create' took 816.28ms
debg [scout-worker-1] [service] new Kibana space test-space-1 created
...

✅ 3 Workers

Running 9 tests using 3 workers



[chromium] › saved_searches.spec.ts:66:14 › Discover app - saved searches › should customize time range on dashboards @ess @svlSearch @svlOblt
 debg [scout-worker-2] [service] logger
 info [scout-worker-2] [config] Reading test servers confiuration from file: /Users/cesaredecal/dev/kibana/.scout/servers/local.json
 debg [scout-worker-2] [service] config
 debg [scout-worker-2] [service] kbnClient
[chromium] › error_handling.spec.ts:30:12 › Discover app - errors › should render invalid scripted field error @ess
 debg [scout-worker-1] [service] logger
 info [scout-worker-1] [config] Reading test servers confiuration from file: /Users/cesaredecal/dev/kibana/.scout/servers/local.json
 debg [scout-worker-1] [service] config
 debg [scout-worker-1] [service] kbnClient
[chromium] › saved_searches.spec.ts:66:14 › Discover app - saved searches › should customize time range on dashboards @ess @svlSearch @svlOblt
 debg [scout-worker-2] Requesting url (redacted): [http://localhost:5620/api/spaces/space]
[chromium] › error_handling.spec.ts:30:12 › Discover app - errors › should render invalid scripted field error @ess
 debg [scout-worker-1] Requesting url (redacted): [http://localhost:5620/api/spaces/space]
...

…na into scout/fix-logger-context

csr · 2025-03-05T16:15:13Z

src/platform/packages/shared/kbn-scout/src/playwright/fixtures/worker/scout_space/parallel.ts

@@ -130,11 +118,12 @@ export const scoutSpaceParallelFixture = coreWorkerFixtures.extend<
        setDefaultTime,
      };

-      log.serviceLoaded(`scoutSpace:${spaceId}`);
+      log.serviceLoaded(`new Kibana space ${spaceId} created`);


Now that we updated the serviceLoaded function to print loaded at the end of the string (thanks for making the change), this may not make much sense anymore (the log would end with created loaded). Perhaps we want to use log.debug here instead of log.serviceLoaded?

you got me again :) as it is important to know space name to better understand error logs / screenshot, we can use

serviceMessage('scoutSpace', `new Kibana space '${spaceId}' created`)

to see

debg [scout-worker-1] [scoutSpace] new Kibana space 'test-space-1' created

Neat! Nit, non-blocking at all: perhaps new can be New(uppercase N).

…-fix'

elasticmachine · 2025-03-05T19:20:02Z

💔 Build Failed

Buildkite Build
Commit: 0622113

Failed CI Steps

FTR Configs #113

Metrics [docs]

Public APIs missing comments

Total count of every public API that lacks a comment. Target amount is 0. Run node scripts/build_api_docs --plugin [yourplugin] --stats comments for more detailed information.

id	before	after	diff
`@kbn/scout`	99	102	+3
`@kbn/scout-oblt`	71	74	+3
total			+6

Unknown metric groups

API count

id	before	after	diff
`@kbn/scout`	389	393	+4
`@kbn/scout-oblt`	361	365	+4
total			+8

History

💔 Build #281165 failed 6eeb64d
💚 Build #281089 succeeded cbe40c0
💔 Build #281047 failed 3be1df6

cc @dmlemeshko

use unique logger context per worker

c9505eb

dmlemeshko commented Mar 5, 2025

View reviewed changes

dmlemeshko self-assigned this Mar 5, 2025

dmlemeshko added release_note:skip Skip the PR/issue when compiling release notes v9.0.0 backport:version Backport to applied version labels test:scout v9.1.0 v8.19.0 labels Mar 5, 2025

dmlemeshko marked this pull request as ready for review March 5, 2025 11:14

dmlemeshko requested a review from a team as a code owner March 5, 2025 11:14

dmlemeshko added 3 commits March 5, 2025 12:14

Merge branch 'main' into scout/fix-logger-context

3be1df6

set default context in getLogger

ec657c8

Merge branch 'scout/fix-logger-context' of github.com:dmlemeshko/kiba…

fbc4914

…na into scout/fix-logger-context

dmlemeshko commented Mar 5, 2025

View reviewed changes

Merge branch 'main' into scout/fix-logger-context

cbe40c0

csr reviewed Mar 5, 2025

View reviewed changes

dmlemeshko added 2 commits March 5, 2025 17:10

fix review comments

36cc1f2

Merge branch 'scout/fix-logger-context' of github.com:dmlemeshko/kiba…

6eeb64d

…na into scout/fix-logger-context

dmlemeshko requested a review from csr March 5, 2025 16:11

csr reviewed Mar 5, 2025

View reviewed changes

Update logger call in scoutSpace

dd47d57

dmlemeshko requested a review from csr March 5, 2025 16:30

dmlemeshko added 2 commits March 5, 2025 17:31

Update logger.ts

bbe2beb

Merge branch 'main' into scout/fix-logger-context

29bc0e4

[CI] Auto-commit changed files from 'node scripts/eslint --no-cache -…

0622113

…-fix'

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[scout] improve logs readability by using unique logger context per playwright worker #213218

[scout] improve logs readability by using unique logger context per playwright worker #213218

dmlemeshko commented Mar 5, 2025 •

edited

Loading

dmlemeshko Mar 5, 2025

csr Mar 5, 2025 •

edited

Loading

dmlemeshko Mar 5, 2025 •

edited

Loading

dmlemeshko Mar 5, 2025

dmlemeshko Mar 5, 2025

dmlemeshko Mar 5, 2025 •

edited

Loading

dmlemeshko Mar 5, 2025

dmlemeshko Mar 5, 2025

csr Mar 5, 2025

dmlemeshko Mar 5, 2025

csr Mar 5, 2025

csr commented Mar 5, 2025 •

edited

Loading

csr Mar 5, 2025 •

edited

Loading

dmlemeshko Mar 5, 2025

csr Mar 5, 2025 •

edited

Loading

elasticmachine commented Mar 5, 2025

API count

		const corePageObjects = createCorePageObjects(page);
		log.serviceLoaded(`pageObjects:${scoutSpace.id}`);

[scout] improve logs readability by using unique logger context per playwright worker #213218

Are you sure you want to change the base?

[scout] improve logs readability by using unique logger context per playwright worker #213218

Conversation

dmlemeshko commented Mar 5, 2025 • edited Loading

Summary

Choose a reason for hiding this comment

csr Mar 5, 2025 • edited Loading

Choose a reason for hiding this comment

dmlemeshko Mar 5, 2025 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dmlemeshko Mar 5, 2025 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

csr commented Mar 5, 2025 • edited Loading

csr Mar 5, 2025 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

csr Mar 5, 2025 • edited Loading

Choose a reason for hiding this comment

elasticmachine commented Mar 5, 2025

💔 Build Failed

Failed CI Steps

Metrics [docs]

Public APIs missing comments

API count

History

dmlemeshko commented Mar 5, 2025 •

edited

Loading

csr Mar 5, 2025 •

edited

Loading

dmlemeshko Mar 5, 2025 •

edited

Loading

dmlemeshko Mar 5, 2025 •

edited

Loading

csr commented Mar 5, 2025 •

edited

Loading

csr Mar 5, 2025 •

edited

Loading

csr Mar 5, 2025 •

edited

Loading