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

## 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] [browserAuth] loaded
 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] [browserAuth] loaded
 debg [scout-worker-2] Creating new local SAML session for role 'editor'
 debg [scout-worker-2] [scoutPage] loaded
 debg [scout-worker-2] [pageObjects] loaded
```

**Note**: single thread run will log under `[scout-worker]` context

How to verify:

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

---------

Co-authored-by: kibanamachine <42973632+kibanamachine@users.noreply.github.com>
This commit is contained in:
Dzmitry Lemechko 2025-03-06 18:36:11 +01:00 committed by GitHub
parent f4ff56d3d4
commit d958fa97e4
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
6 changed files with 53 additions and 46 deletions

View file

@ -21,7 +21,7 @@ export function createScoutConfig(
}
const configPath = path.join(configDir, `${configName}.json`);
log.info(`[config] Reading test servers confiuration from file: ${configPath}`);
log.serviceMessage('config', `Reading test servers confiuration from file: ${configPath}`);
const config = JSON.parse(fs.readFileSync(configPath, 'utf-8')) as ScoutTestConfig;

View file

@ -10,8 +10,8 @@
import { ToolingLog } from '@kbn/tooling-log';
export class ScoutLogger extends ToolingLog {
constructor() {
super({ level: 'verbose', writeTo: process.stdout }, { context: 'scout' });
constructor(workerContext: string) {
super({ level: 'verbose', writeTo: process.stdout }, { context: workerContext });
this.serviceLoaded('logger');
}
@ -20,20 +20,28 @@ export class ScoutLogger extends ToolingLog {
* @param name unique name of the service
*/
public serviceLoaded(name: string) {
this.debug(`[service] ${name}`);
this.debug(`[${name}] loaded`);
}
/**
* Used to log a message for a service/fixture
*/
public serviceMessage(name: string, message: string) {
this.debug(`[${name}] ${message}`);
}
}
let loggerInstance: ScoutLogger | null = null;
const loggerInstances = new Map<string, ScoutLogger>();
/**
* Singleton logger instance to share across the Scout components
* @returns {ScoutLogger}
* Singleton logger instance for specific worker to share across the Scout components
* @param workerContext logger context, e.g. `scout-worker-1`; default is `scout`
* @returns {ScoutLogger} logger instance
*/
export function getLogger(): ScoutLogger {
if (!loggerInstance) {
loggerInstance = new ScoutLogger();
export function getLogger(workerContext: string = 'scout'): ScoutLogger {
if (!loggerInstances.has(workerContext)) {
loggerInstances.set(workerContext, new ScoutLogger(workerContext));
}
return loggerInstance;
return loggerInstances.get(workerContext)!;
}

View file

@ -25,9 +25,9 @@ export const pageObjectsParallelFixture = scoutPageParallelFixture.extend<
},
{ scoutSpace: ScoutSpaceParallelFixture }
>({
pageObjects: async ({ page, log, scoutSpace }, use) => {
pageObjects: async ({ page, log }, use) => {
const corePageObjects = createCorePageObjects(page);
log.serviceLoaded(`pageObjects:${scoutSpace.id}`);
log.serviceLoaded(`pageObjects`);
await use(corePageObjects);
},
});

View file

@ -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}`);
log.serviceLoaded(`scoutPage`);
await use(extendedPage);
},
});

View file

@ -14,21 +14,21 @@ import {
createKbnUrl,
getEsClient,
getKbnClient,
getLogger,
createSamlSessionManager,
createScoutConfig,
KibanaUrl,
getLogger,
ScoutLogger,
} from '../../../common/services';
import { ScoutTestOptions } from '../../types';
import { ScoutTestConfig } from '.';
import { ScoutLogger } from '../../../common';
import type { ScoutTestOptions } from '../../types';
import type { ScoutTestConfig } from '.';
// re-export to import types from '@kbn-scout'
export type { KbnClient, SamlSessionManager } from '@kbn/test';
export type { ScoutLogger } from '../../../common';
export type { Client as EsClient } from '@elastic/elasticsearch';
export type { KibanaUrl } from '../../../common/services/kibana_url';
export type { ScoutTestConfig } from '../../../types';
export type { ScoutLogger } from '../../../common/services/logger';
/**
* The coreWorkerFixtures setup defines foundational fixtures that are essential
@ -48,24 +48,26 @@ export const coreWorkerFixtures = base.extend<
samlAuth: SamlSessionManager;
}
>({
// Provides a scoped logger instance for each worker. This logger is shared across
// all other fixtures within the worker scope.
// Provides a scoped logger instance for each worker to use in fixtures and tests.
// For parallel workers logger context is matching worker index+1, e.g. '[scout-worker-1]', '[scout-worker-2]', etc.
log: [
({}, use) => {
use(getLogger());
({}, use, workerInfo) => {
const workersCount = workerInfo.config.workers;
const loggerContext =
workersCount === 1 ? 'scout-worker' : `scout-worker-${workerInfo.parallelIndex + 1}`;
use(getLogger(loggerContext));
},
{ scope: 'worker' },
],
/**
* Loads the test server configuration from the source file based on local or cloud
* target, located by default in '.scout/servers' directory. It supplies Playwright
* with all server-related information including hosts, credentials, type of deployment, etc.
*/
config: [
({ log }, use, testInfo) => {
({ log }, use, workerInfo) => {
const configName = 'local';
const projectUse = testInfo.project.use as ScoutTestOptions;
const projectUse = workerInfo.project.use as ScoutTestOptions;
const serversConfigDir = projectUse.serversConfigDir;
const configInstance = createScoutConfig(serversConfigDir, configName, log);

View file

@ -19,13 +19,13 @@ export const scoutSpaceParallelFixture = coreWorkerFixtures.extend<
>({
scoutSpace: [
async ({ log, kbnClient }, use, workerInfo) => {
const spaceId = `test-space-${workerInfo.workerIndex}`;
const spaceId = `test-space-${workerInfo.parallelIndex + 1}`;
const spacePayload = {
id: spaceId,
name: spaceId,
disabledFeatures: [],
};
await measurePerformanceAsync(log, `scoutSpace:${spaceId} 'spaces.create'`, async () => {
await measurePerformanceAsync(log, `spaces.create('${spaceId}')`, async () => {
return kbnClient.spaces.create(spacePayload);
});
@ -35,7 +35,7 @@ export const scoutSpaceParallelFixture = coreWorkerFixtures.extend<
const load = async (path: string) => {
return measurePerformanceAsync(
log,
`scoutSpace:${spaceId} 'savedObjects.load'`,
`savedObjects.load({spaceId:'${spaceId}'})`,
async () => {
const response = await kbnClient.importExport.load(path, {
space: spaceId,
@ -58,7 +58,7 @@ export const scoutSpaceParallelFixture = coreWorkerFixtures.extend<
const cleanStandardList = async () => {
return measurePerformanceAsync(
log,
`scoutSpace:${spaceId} 'savedObjects.cleanStandardList'`,
`savedObjects.cleanStandardList({spaceId:'${spaceId}'})`,
async () => {
savedObjectsCache.clear();
await kbnClient.savedObjects.cleanStandardList({
@ -70,7 +70,7 @@ export const scoutSpaceParallelFixture = coreWorkerFixtures.extend<
const setDefaultIndex = async (dataViewName: string) => {
return measurePerformanceAsync(
log,
`scoutSpace:${spaceId} 'savedObjects.setDefaultIndex'`,
`savedObjects.setDefaultIndex({spaceId:'${spaceId}'})`,
async () => {
if (savedObjectsCache.has(dataViewName)) {
return kbnClient.uiSettings.update(
@ -86,31 +86,27 @@ export const scoutSpaceParallelFixture = coreWorkerFixtures.extend<
);
};
const set = async (values: UiSettingValues) => {
return measurePerformanceAsync(log, `scoutSpace:${spaceId} 'uiSettings.set'`, async () => {
return measurePerformanceAsync(log, `uiSettings.set({spaceId:'${spaceId}'})`, async () => {
return kbnClient.uiSettings.update(values, { space: spaceId });
});
};
const unset = async (...keys: string[]) => {
return measurePerformanceAsync(
log,
`scoutSpace:${spaceId} 'uiSettings.unset'`,
async () => {
return Promise.all(
keys.map((key) => kbnClient.uiSettings.unset(key, { space: spaceId }))
);
}
);
return measurePerformanceAsync(log, `${spaceId}: 'uiSettings.unset'`, async () => {
return Promise.all(
keys.map((key) => kbnClient.uiSettings.unset(key, { space: spaceId }))
);
});
};
const setDefaultTime = async ({ from, to }: { from: string; to: string }) => {
return measurePerformanceAsync(
log,
`scoutSpace:${spaceId} 'uiSettings.setDefaultTime'`,
`uiSettings.setDefaultTime({spaceId:'${spaceId}')`,
async () => {
const utcFrom = isValidUTCDate(from) ? from : formatTime(from);
const untcTo = isValidUTCDate(to) ? to : formatTime(to);
const utcTo = isValidUTCDate(to) ? to : formatTime(to);
return kbnClient.uiSettings.update(
{
'timepicker:timeDefaults': `{ "from": "${utcFrom}", "to": "${untcTo}"}`,
'timepicker:timeDefaults': `{ "from": "${utcFrom}", "to": "${utcTo}"}`,
},
{ space: spaceId }
);
@ -130,11 +126,12 @@ export const scoutSpaceParallelFixture = coreWorkerFixtures.extend<
setDefaultTime,
};
log.serviceLoaded(`scoutSpace:${spaceId}`);
log.serviceMessage('scoutSpace', `New Kibana space '${spaceId}' created`);
await use({ savedObjects, uiSettings, id: spaceId });
// Cleanup space after tests via API call
await measurePerformanceAsync(log, `scoutSpace:${spaceId} 'space.delete'`, async () => {
await measurePerformanceAsync(log, `space.delete(${spaceId})`, async () => {
log.debug(`Deleting space ${spaceId}`);
return kbnClient.spaces.delete(spaceId);
});
},