github-mirrors/kibana
1
0
Fork 0
mirror of https://github.com/elastic/kibana.git synced 2025-04-23 17:28:26 -04:00
Code Issues Projects Releases Packages Wiki Activity

Include tracing information in the Kibana logs (#112973)

Browse source 
* change APM nodejs agent default

By default APM agent instruments the code to be a base for log correlation. But it doesn't send transactions to the APM server.

* emit trace IDs into the logs

* use ELASTIC_APM_DISABLE_SEND to keep APM agent active but disable send when necessary

* send data whenver active is set to "true"

* update tests

* keep APM agent active. control disableSend instead

* update snapshot tests

* add debug logging

* REMOVE me. log path to the agent

* init APM agent explicitly in test plugin. it uses another package instance

* REMOVE me. create transaction explicitly

* increase timeout setting for the test

* refactor tests

* remove debug logs

* remove explicit transaction creation

* Revert "remove explicit transaction creation"

This reverts commit cdf2d308e0.

* point to apm nodejs agent commit temporary until a new version is released

* migrate from disableSend to contextPropagationOnly

* TO DISCUSS. what if we enforce contextPropagationOnly to be configured when active is defined

* Revert "TO DISCUSS. what if we enforce contextPropagationOnly to be configured when active is defined"

This reverts commit 62dda4fb27.

* bump to version with fix

* commit using @elastic.co

Co-authored-by: Kibana Machine <42973632+kibanamachine@users.noreply.github.com>
This commit is contained in:
Mikhail Shustov 2021-11-11 12:13:23 +01:00 • committed by GitHub
parent c0cb59b697
commit 7c16e2e57f
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
19 changed files with 360 additions and 24 deletions
Download patch file Download diff file Expand all files Collapse all files

5
.buildkite/scripts/common/env.sh
View file

@ -38,8 +38,10 @@ export ELASTIC_APM_TRANSACTION_SAMPLE_RATE=0.1
if is_pr; then
if [[ "${GITHUB_PR_LABELS:-}" == *"ci:collect-apm"* ]]; then
export ELASTIC_APM_ACTIVE=true
export ELASTIC_APM_CONTEXT_PROPAGATION_ONLY=false
else
export ELASTIC_APM_ACTIVE=false
export ELASTIC_APM_ACTIVE=true
export ELASTIC_APM_CONTEXT_PROPAGATION_ONLY=true
fi
if [[ "${GITHUB_STEP_COMMIT_STATUS_ENABLED:-}" != "true" ]]; then
@ -61,6 +63,7 @@ if is_pr; then
export PR_TARGET_BRANCH="$GITHUB_PR_TARGET_BRANCH"
else
export ELASTIC_APM_ACTIVE=true
export ELASTIC_APM_CONTEXT_PROPAGATION_ONLY=false
export CHECKS_REPORTER_ACTIVE=false
fi

2
package.json
View file

@ -223,7 +223,7 @@
"deep-freeze-strict": "^1.1.1",
"deepmerge": "^4.2.2",
"del": "^5.1.0",
"elastic-apm-node": "^3.23.0",
"elastic-apm-node": "3.24.0",
"execa": "^4.0.2",
"exit-hook": "^2.2.0",
"expiry-js": "0.1.7",

139
packages/kbn-apm-config-loader/src/config.test.ts
View file

@ -21,7 +21,7 @@ describe('ApmConfiguration', () => {
beforeEach(() => {
// start with an empty env to avoid CI from spoiling snapshots, env is unique for each jest file
process.env = {};
devConfigMock.raw = {};
packageMock.raw = {
version: '8.0.0',
build: {
@ -86,10 +86,11 @@ describe('ApmConfiguration', () => {
let config = new ApmConfiguration(mockedRootDir, {}, false);
expect(config.getConfig('serviceName')).toMatchInlineSnapshot(`
Object {
"active": false,
"active": true,
"breakdownMetrics": true,
"captureSpanStackTraces": false,
"centralConfig": false,
"contextPropagationOnly": true,
"environment": "development",
"globalLabels": Object {},
"logUncaughtExceptions": true,
@ -105,12 +106,13 @@ describe('ApmConfiguration', () => {
config = new ApmConfiguration(mockedRootDir, {}, true);
expect(config.getConfig('serviceName')).toMatchInlineSnapshot(`
Object {
"active": false,
"active": true,
"breakdownMetrics": false,
"captureBody": "off",
"captureHeaders": false,
"captureSpanStackTraces": false,
"centralConfig": false,
"contextPropagationOnly": true,
"environment": "development",
"globalLabels": Object {
"git_rev": "sha",
@ -162,13 +164,12 @@ describe('ApmConfiguration', () => {
it('does not load the configuration from the dev config in distributable', () => {
devConfigMock.raw = {
active: true,
serverUrl: 'https://dev-url.co',
active: false,
};
const config = new ApmConfiguration(mockedRootDir, {}, true);
expect(config.getConfig('serviceName')).toEqual(
expect.objectContaining({
active: false,
active: true,
})
);
});
@ -224,4 +225,130 @@ describe('ApmConfiguration', () => {
})
);
});
describe('contextPropagationOnly', () => {
it('sets "active: true" and "contextPropagationOnly: true" by default', () => {
expect(new ApmConfiguration(mockedRootDir, {}, false).getConfig('serviceName')).toEqual(
expect.objectContaining({
active: true,
contextPropagationOnly: true,
})
);
expect(new ApmConfiguration(mockedRootDir, {}, true).getConfig('serviceName')).toEqual(
expect.objectContaining({
active: true,
contextPropagationOnly: true,
})
);
});
it('value from config overrides the default', () => {
const kibanaConfig = {
elastic: {
apm: {
active: false,
contextPropagationOnly: false,
},
},
};
expect(
new ApmConfiguration(mockedRootDir, kibanaConfig, false).getConfig('serviceName')
).toEqual(
expect.objectContaining({
active: false,
contextPropagationOnly: false,
})
);
expect(
new ApmConfiguration(mockedRootDir, kibanaConfig, true).getConfig('serviceName')
).toEqual(
expect.objectContaining({
active: false,
contextPropagationOnly: false,
})
);
});
it('is "false" if "active: true" configured and "contextPropagationOnly" is not specified', () => {
const kibanaConfig = {
elastic: {
apm: {
active: true,
},
},
};
expect(
new ApmConfiguration(mockedRootDir, kibanaConfig, false).getConfig('serviceName')
).toEqual(
expect.objectContaining({
active: true,
contextPropagationOnly: false,
})
);
expect(
new ApmConfiguration(mockedRootDir, kibanaConfig, true).getConfig('serviceName')
).toEqual(
expect.objectContaining({
active: true,
contextPropagationOnly: false,
})
);
});
it('throws if "active: false" set without configuring "contextPropagationOnly: false"', () => {
const kibanaConfig = {
elastic: {
apm: {
active: false,
},
},
};
expect(() =>
new ApmConfiguration(mockedRootDir, kibanaConfig, false).getConfig('serviceName')
).toThrowErrorMatchingInlineSnapshot(
`"APM is disabled, but context propagation is enabled. Please disable context propagation with contextPropagationOnly:false"`
);
expect(() =>
new ApmConfiguration(mockedRootDir, kibanaConfig, true).getConfig('serviceName')
).toThrowErrorMatchingInlineSnapshot(
`"APM is disabled, but context propagation is enabled. Please disable context propagation with contextPropagationOnly:false"`
);
});
it('does not throw if "active: false" and "contextPropagationOnly: false" configured', () => {
const kibanaConfig = {
elastic: {
apm: {
active: false,
contextPropagationOnly: false,
},
},
};
expect(
new ApmConfiguration(mockedRootDir, kibanaConfig, false).getConfig('serviceName')
).toEqual(
expect.objectContaining({
active: false,
contextPropagationOnly: false,
})
);
expect(
new ApmConfiguration(mockedRootDir, kibanaConfig, true).getConfig('serviceName')
).toEqual(
expect.objectContaining({
active: false,
contextPropagationOnly: false,
})
);
});
});
});

39
packages/kbn-apm-config-loader/src/config.ts
View file

@ -16,7 +16,8 @@ import type { AgentConfigOptions } from 'elastic-apm-node';
// https://www.elastic.co/guide/en/apm/agent/nodejs/current/configuration.html
const DEFAULT_CONFIG: AgentConfigOptions = {
active: false,
active: true,
contextPropagationOnly: true,
environment: 'development',
logUncaughtExceptions: true,
globalLabels: {},
@ -71,6 +72,8 @@ export class ApmConfiguration {
private getBaseConfig() {
if (!this.baseConfig) {
const configFromSources = this.getConfigFromAllSources();
this.baseConfig = merge(
{
serviceVersion: this.kibanaVersion,
@ -79,9 +82,7 @@ export class ApmConfiguration {
this.getUuidConfig(),
this.getGitConfig(),
this.getCiConfig(),
this.getConfigFromKibanaConfig(),
this.getDevConfig(),
this.getConfigFromEnv()
configFromSources
);
/**
@ -114,6 +115,12 @@ export class ApmConfiguration {
config.active = true;
}
if (process.env.ELASTIC_APM_CONTEXT_PROPAGATION_ONLY === 'true') {
config.contextPropagationOnly = true;
} else if (process.env.ELASTIC_APM_CONTEXT_PROPAGATION_ONLY === 'false') {
config.contextPropagationOnly = false;
}
if (process.env.ELASTIC_APM_ENVIRONMENT || process.env.NODE_ENV) {
config.environment = process.env.ELASTIC_APM_ENVIRONMENT || process.env.NODE_ENV;
}
@ -249,4 +256,28 @@ export class ApmConfiguration {
return {};
}
}
/**
* Reads APM configuration from different sources and merges them together.
*/
private getConfigFromAllSources(): AgentConfigOptions {
const config = merge(
{},
this.getConfigFromKibanaConfig(),
this.getDevConfig(),
this.getConfigFromEnv()
);
if (config.active === false && config.contextPropagationOnly !== false) {
throw new Error(
'APM is disabled, but context propagation is enabled. Please disable context propagation with contextPropagationOnly:false'
);
}
if (config.active === true) {
config.contextPropagationOnly = config.contextPropagationOnly ?? false;
}
return config;
}
}

3
packages/kbn-logging/src/log_record.ts
View file

@ -20,4 +20,7 @@ export interface LogRecord {
error?: Error;
meta?: { [name: string]: any };
pid: number;
spanId?: string;
traceId?: string;
transactionId?: string;
}

6
src/core/server/logging/__snapshots__/logging_system.test.ts.snap generated
View file

@ -117,7 +117,10 @@ Object {
"message": "trace message",
"meta": undefined,
"pid": Any<Number>,
"spanId": undefined,
"timestamp": 2012-02-01T14:33:22.011Z,
"traceId": undefined,
"transactionId": undefined,
}
`;
@ -133,6 +136,9 @@ Object {
"some": "value",
},
"pid": Any<Number>,
"spanId": undefined,
"timestamp": 2012-02-01T14:33:22.011Z,
"traceId": undefined,
"transactionId": undefined,
}
`;

23
src/core/server/logging/layouts/__snapshots__/json_layout.test.ts.snap generated
View file

@ -88,3 +88,26 @@ Object {
},
}
`;
exports[`\`format()\` correctly formats record and includes correct ECS version. 7`] = `
Object {
"@timestamp": "2012-02-01T09:30:22.011-05:00",
"log": Object {
"level": "TRACE",
"logger": "context-7",
},
"message": "message-6",
"process": Object {
"pid": 5355,
},
"span": Object {
"id": "spanId-1",
},
"trace": Object {
"id": "traceId-1",
},
"transaction": Object {
"id": "transactionId-1",
},
}
`;

47
src/core/server/logging/layouts/json_layout.test.ts
View file

@ -58,6 +58,16 @@ const records: LogRecord[] = [
timestamp,
pid: 5355,
},
{
context: 'context-7',
level: LogLevel.Trace,
message: 'message-6',
timestamp,
pid: 5355,
spanId: 'spanId-1',
traceId: 'traceId-1',
transactionId: 'transactionId-1',
},
];
test('`createConfigSchema()` creates correct schema.', () => {
@ -310,3 +320,40 @@ test('format() meta can not override timestamp', () => {
},
});
});
test('format() meta can not override tracing properties', () => {
const layout = new JsonLayout();
expect(
JSON.parse(
layout.format({
message: 'foo',
timestamp,
level: LogLevel.Debug,
context: 'bar',
pid: 3,
meta: {
span: 'span_override',
trace: 'trace_override',
transaction: 'transaction_override',
},
spanId: 'spanId-1',
traceId: 'traceId-1',
transactionId: 'transactionId-1',
})
)
).toStrictEqual({
ecs: { version: expect.any(String) },
'@timestamp': '2012-02-01T09:30:22.011-05:00',
message: 'foo',
log: {
level: 'DEBUG',
logger: 'bar',
},
process: {
pid: 3,
},
span: { id: 'spanId-1' },
trace: { id: 'traceId-1' },
transaction: { id: 'transactionId-1' },
});
});

3
src/core/server/logging/layouts/json_layout.ts
View file

@ -54,6 +54,9 @@ export class JsonLayout implements Layout {
process: {
pid: record.pid,
},
span: record.spanId ? { id: record.spanId } : undefined,
trace: record.traceId ? { id: record.traceId } : undefined,
transaction: record.transactionId ? { id: record.transactionId } : undefined,
};
const output = record.meta ? merge({ ...record.meta }, log) : log;

12
src/core/server/logging/logger.ts
View file

@ -5,7 +5,7 @@
* in compliance with, at your election, the Elastic License 2.0 or the Server
* Side Public License, v 1.
*/
import apmAgent from 'elastic-apm-node';
import { Appender, LogLevel, LogRecord, LoggerFactory, LogMeta, Logger } from '@kbn/logging';
function isError(x: any): x is Error {
@ -73,6 +73,7 @@ export class BaseLogger implements Logger {
meta,
timestamp: new Date(),
pid: process.pid,
...this.getTraceIds(),
};
}
@ -83,6 +84,15 @@ export class BaseLogger implements Logger {
meta,
timestamp: new Date(),
pid: process.pid,
...this.getTraceIds(),
};
}
private getTraceIds() {
return {
spanId: apmAgent.currentTraceIds['span.id'],
traceId: apmAgent.currentTraceIds['trace.id'],
transactionId: apmAgent.currentTraceIds['transaction.id'],
};
}
}

5
vars/kibanaPipeline.groovy
View file

@ -93,7 +93,7 @@ def withFunctionalTestEnv(List additionalEnvs = [], Closure closure) {
def corsTestServerPort = "64${parallelId}3"
// needed for https://github.com/elastic/kibana/issues/107246
def proxyTestServerPort = "64${parallelId}4"
def apmActive = githubPr.isPr() ? "false" : "true"
def contextPropagationOnly = githubPr.isPr() ? "true" : "false"
withEnv([
"CI_GROUP=${parallelId}",
@ -109,7 +109,8 @@ def withFunctionalTestEnv(List additionalEnvs = [], Closure closure) {
"KBN_NP_PLUGINS_BUILT=true",
"FLEET_PACKAGE_REGISTRY_PORT=${fleetPackageRegistryPort}",
"ALERTING_PROXY_PORT=${alertingProxyPort}",
"ELASTIC_APM_ACTIVE=${apmActive}",
"ELASTIC_APM_ACTIVE=true",
"ELASTIC_APM_CONTEXT_PROPAGATION_ONLY=${contextPropagationOnly}",
"ELASTIC_APM_TRANSACTION_SAMPLE_RATE=0.1",
] + additionalEnvs) {
closure()

1
x-pack/test/functional_execution_context/config.ts
View file

@ -42,6 +42,7 @@ export default async function ({ readConfigFile }: FtrConfigProviderContext) {
`--elasticsearch.hosts=${servers.elasticsearch.protocol}://${servers.elasticsearch.hostname}:${servers.elasticsearch.port}`,
`--elasticsearch.ssl.certificateAuthorities=${CA_CERT_PATH}`,
'--server.requestId.allowFromAnyIp=true',
'--execution_context.enabled=true',
'--logging.appenders.file.type=file',
`--logging.appenders.file.fileName=${logFilePath}`,

13
x-pack/test/functional_execution_context/fixtures/plugins/alerts/server/ensure_apm_started.ts Normal file
View file

@ -0,0 +1,13 @@
/*
* Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
* or more contributor license agreements. Licensed under the Elastic License
* 2.0; you may not use this file except in compliance with the Elastic License
* 2.0.
*/
import apmAgent from 'elastic-apm-node';
import { initApm } from '@kbn/apm-config-loader';
import { REPO_ROOT } from '@kbn/utils';
if (!apmAgent.isStarted()) {
initApm(process.argv, REPO_ROOT, false, 'test-plugin');
}

1
x-pack/test/functional_execution_context/fixtures/plugins/alerts/server/index.ts
View file

@ -5,6 +5,7 @@
* 2.0.
*/
import './ensure_apm_started';
import { FixturePlugin } from './plugin';
export const plugin = () => new FixturePlugin();

27
x-pack/test/functional_execution_context/fixtures/plugins/alerts/server/plugin.ts
View file

@ -4,6 +4,7 @@
* 2.0; you may not use this file except in compliance with the Elastic License
* 2.0.
*/
import apmAgent from 'elastic-apm-node';
import { Plugin, CoreSetup } from 'kibana/server';
import { PluginSetupContract as AlertingPluginSetup } from '../../../../../../plugins/alerting/server/plugin';
@ -81,6 +82,32 @@ export class FixturePlugin implements Plugin<void, void, FixtureSetupDeps, Fixtu
await coreStart.elasticsearch.client.asInternalUser.ping();
},
});
const router = core.http.createRouter();
router.get(
{
path: '/emit_log_with_trace_id',
validate: false,
options: {
authRequired: false,
},
},
async (ctx, req, res) => {
const transaction = apmAgent.startTransaction();
const subscription = req.events.completed$.subscribe(() => {
transaction?.end();
subscription.unsubscribe();
});
await ctx.core.elasticsearch.client.asInternalUser.ping();
return res.ok({
body: {
traceId: apmAgent.currentTraceIds['trace.id'],
},
});
}
);
}
public start() {}

1
x-pack/test/functional_execution_context/tests/index.ts
View file

@ -12,5 +12,6 @@ export default function ({ loadTestFile }: FtrProviderContext) {
this.tags('ciGroup1');
loadTestFile(require.resolve('./browser'));
loadTestFile(require.resolve('./server'));
loadTestFile(require.resolve('./log_correlation'));
});
}

38
x-pack/test/functional_execution_context/tests/log_correlation.ts Normal file
View file

@ -0,0 +1,38 @@
/*
* Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
* or more contributor license agreements. Licensed under the Elastic License
* 2.0; you may not use this file except in compliance with the Elastic License
* 2.0.
*/
import expect from '@kbn/expect';
import type { FtrProviderContext } from '../ftr_provider_context';
import { assertLogContains } from '../test_utils';
export default function ({ getService }: FtrProviderContext) {
const retry = getService('retry');
const supertest = getService('supertest');
describe('Log Correlation', () => {
it('Emits "trace.id" into the logs', async () => {
const response1 = await supertest
.get('/emit_log_with_trace_id')
.set('x-opaque-id', 'myheader1');
expect(response1.body.traceId).to.be.a('string');
const response2 = await supertest.get('/emit_log_with_trace_id');
expect(response1.body.traceId).to.be.a('string');
expect(response2.body.traceId).not.to.be(response1.body.traceId);
await assertLogContains({
description: 'traceId included in the Kibana logs',
predicate: (record) =>
// we don't check trace.id value since trace.id in the test plugin and Kibana are different on CI.
// because different 'elastic-apm-node' instaces are imported
Boolean(record.http?.request?.id?.includes('myheader1') && record.trace?.id),
retry,
});
});
});
}

1
x-pack/test/performance/config.ts
View file

@ -32,6 +32,7 @@ export default async function ({ readConfigFile }: FtrConfigProviderContext) {
...functionalConfig.get('kbnTestServer'),
env: {
ELASTIC_APM_ACTIVE: 'true',
ELASTIC_APM_CONTEXT_PROPAGATION_ONLY: 'false',
ELASTIC_APM_ENVIRONMENT: process.env.CI ? 'ci' : 'development',
ELASTIC_APM_TRANSACTION_SAMPLE_RATE: '1.0',
ELASTIC_APM_SERVER_URL: APM_SERVER_URL,

18
yarn.lock
View file

@ -13225,10 +13225,10 @@ ejs@^3.1.2, ejs@^3.1.6:
dependencies:
jake "^10.6.1"
elastic-apm-http-client@^10.1.0:
version "10.1.0"
resolved "https://registry.yarnpkg.com/elastic-apm-http-client/-/elastic-apm-http-client-10.1.0.tgz#8fbfa3f026f40d82b22b77bf4ed539cc20623edb"
integrity sha512-G+UsOQS8+kTyjbZ9PBXgbN8RGgeTe3FfbVljiwuN+eIf0UwpSR8k5Oh+Z2BELTTVwTcit7NCH4+B4MPayYx1mw==
elastic-apm-http-client@^10.3.0:
version "10.3.0"
resolved "https://registry.yarnpkg.com/elastic-apm-http-client/-/elastic-apm-http-client-10.3.0.tgz#12b95dc190a755cd1a8ce2c296cd28ef50f16aa4"
integrity sha512-BAqB7k5JA/x09L8BVj04WRoknRptmW2rLAoHQVrPvPhUm/IgNz63wPfiBuhWVE//Hl7xEpURO5pMV6az0UArkA==
dependencies:
breadth-filter "^2.0.0"
container-info "^1.0.1"
@ -13239,10 +13239,10 @@ elastic-apm-http-client@^10.1.0:
readable-stream "^3.4.0"
stream-chopper "^3.0.1"
elastic-apm-node@^3.23.0:
version "3.23.0"
resolved "https://registry.yarnpkg.com/elastic-apm-node/-/elastic-apm-node-3.23.0.tgz#e842aa505d576003579803e45fe91f572db74a72"
integrity sha512-yzdO/MwAcjT+TbcBQBKWbDb4beDVmmrIaFCu9VA+z6Ow9GKlQv7QaD9/cQjuN8/KI6ASiJfQI8cPgqy1SgSUuA==
elastic-apm-node@3.24.0:
version "3.24.0"
resolved "https://registry.yarnpkg.com/elastic-apm-node/-/elastic-apm-node-3.24.0.tgz#d7acb3352f928a23c28ebabab2bd30098562814e"
integrity sha512-Fmj/W2chWQa2zb1FfMYK2ypLB4TcnKNX+1klaJFbytRYDLgeSfo0EC7egvI3a+bLPZSRL5053PXOp7slVTPO6Q==
dependencies:
"@elastic/ecs-pino-format" "^1.2.0"
after-all-results "^2.0.0"
@ -13251,7 +13251,7 @@ elastic-apm-node@^3.23.0:
basic-auth "^2.0.1"
cookie "^0.4.0"
core-util-is "^1.0.2"
elastic-apm-http-client "^10.1.0"
elastic-apm-http-client "^10.3.0"
end-of-stream "^1.4.4"
error-callsites "^2.0.4"
error-stack-parser "^2.0.6"