From 55c275527b99fc62acaf68645853df87fbbe1b8b Mon Sep 17 00:00:00 2001 From: David Luna Date: Fri, 24 Nov 2023 10:37:02 +0100 Subject: [PATCH 01/58] feat: add kafkajs consumer instrumentation --- .ci/docker/docker-compose-kafka.yml | 18 +++ .ci/docker/docker-compose.yml | 30 ++++ lib/instrumentation/index.js | 1 + lib/instrumentation/modules/kafkajs.js | 208 +++++++++++++++++++++++++ package-lock.json | 16 ++ package.json | 1 + test/docker-compose.ci.yml | 2 + test/docker-compose.yml | 34 ++++ 8 files changed, 310 insertions(+) create mode 100644 .ci/docker/docker-compose-kafka.yml create mode 100644 lib/instrumentation/modules/kafkajs.js diff --git a/.ci/docker/docker-compose-kafka.yml b/.ci/docker/docker-compose-kafka.yml new file mode 100644 index 0000000000..ac8820f207 --- /dev/null +++ b/.ci/docker/docker-compose-kafka.yml @@ -0,0 +1,18 @@ +version: '2.1' + +services: + kafka: + extends: + file: docker-compose.yml + service: kafka + node_tests: + extends: + file: docker-compose-node-test.yml + service: node_tests + depends_on: + localstack: + condition: service_healthy + +volumes: + nodelafkadata: + driver: local diff --git a/.ci/docker/docker-compose.yml b/.ci/docker/docker-compose.yml index a26340e1c0..00ebb7e60a 100644 --- a/.ci/docker/docker-compose.yml +++ b/.ci/docker/docker-compose.yml @@ -132,6 +132,36 @@ services: volumes: - nodelocalstackdata:/var/lib/localstack + zookeeper: + # https://hub.docker.com/r/bitnami/zookeeper/tags + #restart: always + image: bitnami/zookeeper:3.9.1 + ports: + - "2181:2181" + volumes: + - "zookeeper-volume:/bitnami" + environment: + - ALLOW_ANONYMOUS_LOGIN=yes + + kafka: + # https://hub.docker.com/r/bitnami/kafka/tags + #restart: always + image: bitnami/kafka:3.3.2 + ports: + - "9093:9093" + volumes: + - nodekafkadata:/var/lib/kafka/data + environment: + - KAFKA_BROKER_ID=1 + - KAFKA_CFG_ZOOKEEPER_CONNECT=zookeeper:2181 + - ALLOW_PLAINTEXT_LISTENER=yes + - KAFKA_CFG_LISTENER_SECURITY_PROTOCOL_MAP=CLIENT:PLAINTEXT,EXTERNAL:PLAINTEXT + - KAFKA_CFG_LISTENERS=CLIENT://:9092,EXTERNAL://:9093 + - KAFKA_CFG_ADVERTISED_LISTENERS=CLIENT://kafka:9092,EXTERNAL://localhost:9093 + - KAFKA_CFG_INTER_BROKER_LISTENER_NAME=CLIENT + depends_on: + - zookeeper + volumes: nodepgdata: driver: local diff --git a/lib/instrumentation/index.js b/lib/instrumentation/index.js index d3b1daca38..44bc414ddf 100644 --- a/lib/instrumentation/index.js +++ b/lib/instrumentation/index.js @@ -84,6 +84,7 @@ var MODULE_PATCHERS = [ { modPath: 'http2' }, { modPath: 'ioredis' }, { modPath: 'jade' }, + { modPath: 'kafkajs' }, { modPath: 'knex' }, { modPath: 'koa' }, { modPath: 'koa-router' }, diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js new file mode 100644 index 0000000000..ada5bf8976 --- /dev/null +++ b/lib/instrumentation/modules/kafkajs.js @@ -0,0 +1,208 @@ +/* + * Copyright Elasticsearch B.V. and other contributors where applicable. + * Licensed under the BSD 2-Clause License; you may not use this file except in + * compliance with the BSD 2-Clause License. + */ + +'use strict'; + +const semver = require('semver'); + +const constants = require('../../constants'); +const shimmer = require('../shimmer'); + +const NAME = 'Kafka'; +const TYPE = 'messaging'; +const SUBTYPE = 'kafka'; + + + + +/** + * @typedef {{ Kafka: import('kafkajs').Kafka}} KafkaModule + */ + +/** + * @param {KafkaModule} mod + * @param {any} agent + * @param {Object} options + * @param {string} options.version + * @param {boolean} options.enabled + */ +module.exports = function (mod, agent, { version, enabled }) { + // TODO: discuss this range + if (!enabled || !semver.satisfies(version, '>=2 <3')) { + return mod; + } + + const config = agent._config; + const ins = agent._instrumentation; + + agent.logger.debug('shimming Kafka.prototype.consumer'); + shimmer.wrap(mod.Kafka.prototype, 'consumer', wrapConsumer); + agent.logger.debug('shimming Kafka.prototype.producer'); + shimmer.wrap(mod.Kafka.prototype, 'producer', wrapProducer); + return mod; + + function wrapConsumer(origConsumer) { + const consumer = origConsumer.apply(this.arguments); + + shimmer.wrap(consumer, 'run', wrapConsumerRun); + return consumer; + } + + function wrapConsumerRun(origRun) { + const runConfig = arguments[0]; + + if (typeof runConfig.eachMessage === 'function') { + shimmer.wrap(runConfig, 'eachMessage', wrapEachMessage); + } + + if (typeof runConfig.eachBatch === 'function') { + shimmer.wrap(runConfig, 'eachBatch', wrapEachBatch); + } + } + + /** + * @param {import('kafkajs').EachMessageHandler} origEachMessage + * @returns {import('kafkajs').EachMessageHandler} + */ + function wrapEachMessage(origEachMessage) { + return async function (payload) { + // const { topic, partition, message } = arguments[0]; + const { topic, message } = payload; + + if (shouldIgnoreTopic(topic, config)) { + return origEachMessage.apply(this, arguments); + } + + // XXX: This should be a transaction + // should we use `startTransaction` or `createTransaction` ??? + // https://github.com/elastic/apm/blob/2ad487ebb18ba0a6d47507f2a699fa244841bfa5/specs/agents/tracing-instrumentation-messaging.md?plain=1#L34 + const trans = ins.startTransaction( + `${NAME} RECEIVE from ${topic}`, + TYPE, + {}, // options + ); + + // XXX: if NoopTransaction we could finish right away + if (trans.type === 'noop') { + return origEachMessage.apply(this, arguments); + } + + if (message.headers) { + // TODO: look for a parent context if needed? + trans.propagateTraceContextHeaders( + message.headers, + function (headers, name, value) { + if (name.startsWith('elastic-')) { + return; + } + headers[name] = value; + }, + ); + } + + const messageCtx = { queue: { name: topic } }; + if (config.captureBody) { + // XXX: this is a Buffer. Decode it? + // messageCtx.body = message.value; + } + if (message.headers) { + messageCtx.headers = Object.assign({}, message.headers); + } + + // age: { ms: 0 }, // TODO: check kafkajs docs + // message.timestamp + trans.setMessageContext(messageCtx); + trans._setDestinationContext({ + service: { resource: `${SUBTYPE}/${topic}` }, + }); + + // XXX: is necessary to bind???? + let result; + try { + result = await origEachMessage.apply(this, arguments); + } catch (err) { + trans.setOutcome(constants.OUTCOME_FAILURE); + } finally { + trans.end(); + } + + return result; + }; + } + + /** + * @param {import('kafkajs').EachBatchHandler} origEachMessage + * @returns {import('kafkajs').EachBatchHandler} + */ + function wrapEachBatch(origEachBatch) { + return async function (payload) { + const { batch } = payload; + + // XXX: the callback receives a batch with all mesages (Array) and use code will + // treat them in some sort of loop (I guess) but it's hard to tell + // We could do something simliar to java which is instrument the iterator + // to start/end a transaction for each element iteration + // https://github.com/elastic/apm/blob/2ad487ebb18ba0a6d47507f2a699fa244841bfa5/specs/agents/tracing-instrumentation-messaging.md?plain=1#L62C33-L62C33 + + // for now just a transaction for the whole batch + // XXX: This should be a transaction + // should we use `startTransaction` or `createTransaction` ??? + // https://github.com/elastic/apm/blob/2ad487ebb18ba0a6d47507f2a699fa244841bfa5/specs/agents/tracing-instrumentation-messaging.md?plain=1#L34 + const trans = ins.startTransaction( + `${NAME} RECEIVE from batch`, + TYPE, + {}, // options + ); + + // XXX: if NoopTransaction we could finish right away + if (trans.type === 'noop') { + return origEachBatch.apply(this, arguments); + } + + // XXX: propagate context not possible if messages come from different traces + + trans._setDestinationContext({ + service: { resource: `${SUBTYPE}` }, // no topic because they may be multiple? + }); + + // XXX: is necessary to bind???? + let result; + try { + result = await origEachBatch.apply(this, arguments); + } catch (err) { + trans.setOutcome(constants.OUTCOME_FAILURE); + } finally { + trans.end(); + } + + return result; + }; + } + + function wrapProducer(origProducer) { + const producer = origProducer.apply(this.arguments); + + return producer; + } + + /** + * Returns true if we have to ignore messages on the given topic + * @param {string} topic the topic where client is publishing/subscribing + * @param {any} config the agent's configuration object + * @returns {boolean} + */ + function shouldIgnoreTopic(topic, config) { + if (config.ignoreMessageQueuesRegExp) { + for (const rule of config.ignoreMessageQueuesRegExp) { + if (rule.test(topic)) { + return true; + } + } + } + + return false; + } +}; diff --git a/package-lock.json b/package-lock.json index 6656277e7b..66d30dadda 100644 --- a/package-lock.json +++ b/package-lock.json @@ -97,6 +97,7 @@ "https-pem": "^3.0.0", "ioredis": "^5.1.0", "js-yaml": "^4.1.0", + "kafkajs": "^2.2.4", "knex": "^3.0.1", "koa": "^2.11.0", "koa-bodyparser": "^4.3.0", @@ -12633,6 +12634,15 @@ "safe-buffer": "^5.0.1" } }, + "node_modules/kafkajs": { + "version": "2.2.4", + "resolved": "https://registry.npmjs.org/kafkajs/-/kafkajs-2.2.4.tgz", + "integrity": "sha512-j/YeapB1vfPT2iOIUn/vxdyKEuhuY2PxMBvf5JWux6iSaukAccrMtXEY/Lb7OvavDhOWME589bpLrEdnVHjfjA==", + "dev": true, + "engines": { + "node": ">=14.0.0" + } + }, "node_modules/keygrip": { "version": "1.1.0", "resolved": "https://registry.npmjs.org/keygrip/-/keygrip-1.1.0.tgz", @@ -27909,6 +27919,12 @@ "safe-buffer": "^5.0.1" } }, + "kafkajs": { + "version": "2.2.4", + "resolved": "https://registry.npmjs.org/kafkajs/-/kafkajs-2.2.4.tgz", + "integrity": "sha512-j/YeapB1vfPT2iOIUn/vxdyKEuhuY2PxMBvf5JWux6iSaukAccrMtXEY/Lb7OvavDhOWME589bpLrEdnVHjfjA==", + "dev": true + }, "keygrip": { "version": "1.1.0", "resolved": "https://registry.npmjs.org/keygrip/-/keygrip-1.1.0.tgz", diff --git a/package.json b/package.json index d032d7df1d..02f2d1353c 100644 --- a/package.json +++ b/package.json @@ -174,6 +174,7 @@ "https-pem": "^3.0.0", "ioredis": "^5.1.0", "js-yaml": "^4.1.0", + "kafkajs": "^2.2.4", "knex": "^3.0.1", "koa": "^2.11.0", "koa-bodyparser": "^4.3.0", diff --git a/test/docker-compose.ci.yml b/test/docker-compose.ci.yml index dfe0748a34..fe161d744f 100644 --- a/test/docker-compose.ci.yml +++ b/test/docker-compose.ci.yml @@ -33,3 +33,5 @@ services: condition: service_started localstack: condition: service_started + kafka: + condition: service_started diff --git a/test/docker-compose.yml b/test/docker-compose.yml index 6c8c5903da..bbf0997124 100644 --- a/test/docker-compose.yml +++ b/test/docker-compose.yml @@ -132,6 +132,36 @@ services: volumes: - nodelocalstackdata:/var/lib/localstack + zookeeper: + # https://hub.docker.com/r/bitnami/zookeeper/tags + #restart: always + image: bitnami/zookeeper:3.9.1 + ports: + - "2181:2181" + volumes: + - nodezookeeperdata:/var/lib/zookeeper/data + environment: + - ALLOW_ANONYMOUS_LOGIN=yes + + kafka: + # https://hub.docker.com/r/bitnami/kafka/tags + #restart: always + image: bitnami/kafka:3.3.2 + ports: + - "9093:9093" + volumes: + - nodekafkadata:/var/lib/kafka/data + environment: + - KAFKA_BROKER_ID=1 + - KAFKA_CFG_ZOOKEEPER_CONNECT=zookeeper:2181 + - ALLOW_PLAINTEXT_LISTENER=yes + - KAFKA_CFG_LISTENER_SECURITY_PROTOCOL_MAP=CLIENT:PLAINTEXT,EXTERNAL:PLAINTEXT + - KAFKA_CFG_LISTENERS=CLIENT://:9092,EXTERNAL://:9093 + - KAFKA_CFG_ADVERTISED_LISTENERS=CLIENT://kafka:9092,EXTERNAL://localhost:9093 + - KAFKA_CFG_INTER_BROKER_LISTENER_NAME=CLIENT + depends_on: + - zookeeper + volumes: nodepgdata: driver: local @@ -147,3 +177,7 @@ volumes: driver: local nodelocalstackdata: driver: local + nodekafkadata: + driver: local + nodezookeeperdata: + driver: local From d320cf2f19ab13db12227344fa7dc96836b08cef Mon Sep 17 00:00:00 2001 From: David Luna Date: Fri, 24 Nov 2023 19:46:02 +0100 Subject: [PATCH 02/58] chore: add kafkajs trace sample --- examples/trace-kafka.js | 59 +++++++++++++++++++++++++++++++++++++++++ 1 file changed, 59 insertions(+) create mode 100644 examples/trace-kafka.js diff --git a/examples/trace-kafka.js b/examples/trace-kafka.js new file mode 100644 index 0000000000..94f840107e --- /dev/null +++ b/examples/trace-kafka.js @@ -0,0 +1,59 @@ +#!/usr/bin/env node --unhandled-rejections=strict + +/* + * Copyright Elasticsearch B.V. and other contributors where applicable. + * Licensed under the BSD 2-Clause License; you may not use this file except in + * compliance with the BSD 2-Clause License. + */ + +// A small example showing Elastic APM tracing the 'kadfkajs' package. +// +// This assumes a Kafka server running on localhost. You can use: +// npm run docker:start kafka +// to start a Kafka container. Then `npm run docker:stop` to stop it. + +// eslint-disable-next-line no-unused-vars +const apm = require('../').start({ + serviceName: 'example-trace-kafka', +}); + +const { Kafka } = require('kafkajs'); + +const topic = 'trace-kafka-topic'; +const kafka = new Kafka({ + clientId: 'my-app', + brokers: ['localhost:9092'], +}); +const consumer = kafka.consumer(); +const producer = kafka.producer(); + +async function run() { + await producer.connect(); + await producer.send({ + topic, + messages: [ + { value: 'message 1' }, + { value: 'message 2' }, + { value: 'message 3' }, + ], + }); + + await consumer.connect(); + await consumer.subscribe({ topic, fromBeginning: true }); + await consumer.run({ + eachMessage: async function ({ topic, partition, message }) { + console.log({ + value: message.value.toString(), + }); + }, + }); +} + +run() + .catch((err) => { + console.warn('run err:', err); + }) + .finally(async () => { + await producer.disconnect(); + await consumer.disconnect(); + }); From 1e68b8ec27600ce303a41735943cb0bfe0729a3b Mon Sep 17 00:00:00 2001 From: David Luna Date: Mon, 27 Nov 2023 14:22:25 +0100 Subject: [PATCH 03/58] chore(kafkajs): add trace sample for kafkajs --- examples/trace-kafka.js | 45 ++++++++++++++++++++++++++++++----------- 1 file changed, 33 insertions(+), 12 deletions(-) diff --git a/examples/trace-kafka.js b/examples/trace-kafka.js index 94f840107e..518db09b2f 100644 --- a/examples/trace-kafka.js +++ b/examples/trace-kafka.js @@ -13,21 +13,25 @@ // to start a Kafka container. Then `npm run docker:stop` to stop it. // eslint-disable-next-line no-unused-vars -const apm = require('../').start({ - serviceName: 'example-trace-kafka', -}); +// const apm = require('../').start({ +// serviceName: 'example-trace-kafka', +// }); const { Kafka } = require('kafkajs'); const topic = 'trace-kafka-topic'; -const kafka = new Kafka({ - clientId: 'my-app', - brokers: ['localhost:9092'], -}); -const consumer = kafka.consumer(); -const producer = kafka.producer(); +const kafka = new Kafka({ clientId: 'my-app', brokers: ['localhost:9093'] }); +const admin = kafka.admin(); +let producer, consumer; +let messagesConsumed = 0; async function run() { + await admin.connect(); + await admin.createTopics({ topics: [{ topic }] }); + + consumer = kafka.consumer({ groupId: 'trace-group' }); + producer = kafka.producer(); + await producer.connect(); await producer.send({ topic, @@ -42,11 +46,25 @@ async function run() { await consumer.subscribe({ topic, fromBeginning: true }); await consumer.run({ eachMessage: async function ({ topic, partition, message }) { - console.log({ - value: message.value.toString(), - }); + console.log(`message from topic(${topic}): ${message.value.toString()}`); + messagesConsumed++; }, }); + + await new Promise((resolve, reject) => { + let count = 0; + const id = setInterval(() => { + count++; + if (messagesConsumed === 3) { + clearInterval(id); + resolve(); + } else if (count > 10) { + // set a limit of 10s/retries + clearInterval(id); + reject(new Error('not receiving all messages after 10s')); + } + }, 1000); + }); } run() @@ -54,6 +72,9 @@ run() console.warn('run err:', err); }) .finally(async () => { + console.log('disconnecting Kafkajs client'); await producer.disconnect(); await consumer.disconnect(); + await admin.deleteTopics({ topics: [topic] }); + await admin.disconnect(); }); From 7066b2d20c826c398bd4eb517283478b12644048 Mon Sep 17 00:00:00 2001 From: David Luna Date: Mon, 27 Nov 2023 18:08:46 +0100 Subject: [PATCH 04/58] chore(kafkajs): first try on instrumentation --- examples/trace-kafka.js | 6 ++-- lib/instrumentation/modules/kafkajs.js | 46 ++++++++++++++------------ test/docker-compose.yml | 2 -- 3 files changed, 28 insertions(+), 26 deletions(-) diff --git a/examples/trace-kafka.js b/examples/trace-kafka.js index 518db09b2f..f302959682 100644 --- a/examples/trace-kafka.js +++ b/examples/trace-kafka.js @@ -13,9 +13,9 @@ // to start a Kafka container. Then `npm run docker:stop` to stop it. // eslint-disable-next-line no-unused-vars -// const apm = require('../').start({ -// serviceName: 'example-trace-kafka', -// }); +const apm = require('../').start({ + serviceName: 'example-trace-kafka', +}); const { Kafka } = require('kafkajs'); diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index ada5bf8976..3cd8313ead 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -15,9 +15,6 @@ const NAME = 'Kafka'; const TYPE = 'messaging'; const SUBTYPE = 'kafka'; - - - /** * @typedef {{ Kafka: import('kafkajs').Kafka}} KafkaModule */ @@ -45,22 +42,28 @@ module.exports = function (mod, agent, { version, enabled }) { return mod; function wrapConsumer(origConsumer) { - const consumer = origConsumer.apply(this.arguments); + return function wrappedConsumer() { + const consumer = origConsumer.apply(this, arguments); - shimmer.wrap(consumer, 'run', wrapConsumerRun); - return consumer; + shimmer.wrap(consumer, 'run', wrapConsumerRun); + return consumer; + }; } function wrapConsumerRun(origRun) { - const runConfig = arguments[0]; + return function wrappedConsumerRun() { + const runConfig = arguments[0]; - if (typeof runConfig.eachMessage === 'function') { - shimmer.wrap(runConfig, 'eachMessage', wrapEachMessage); - } + if (typeof runConfig.eachMessage === 'function') { + shimmer.wrap(runConfig, 'eachMessage', wrapEachMessage); + } - if (typeof runConfig.eachBatch === 'function') { - shimmer.wrap(runConfig, 'eachBatch', wrapEachBatch); - } + if (typeof runConfig.eachBatch === 'function') { + shimmer.wrap(runConfig, 'eachBatch', wrapEachBatch); + } + + return origRun.apply(this, arguments); + }; } /** @@ -69,13 +72,14 @@ module.exports = function (mod, agent, { version, enabled }) { */ function wrapEachMessage(origEachMessage) { return async function (payload) { - // const { topic, partition, message } = arguments[0]; const { topic, message } = payload; if (shouldIgnoreTopic(topic, config)) { return origEachMessage.apply(this, arguments); } + console.log('kmessage', message); + // XXX: This should be a transaction // should we use `startTransaction` or `createTransaction` ??? // https://github.com/elastic/apm/blob/2ad487ebb18ba0a6d47507f2a699fa244841bfa5/specs/agents/tracing-instrumentation-messaging.md?plain=1#L34 @@ -105,8 +109,7 @@ module.exports = function (mod, agent, { version, enabled }) { const messageCtx = { queue: { name: topic } }; if (config.captureBody) { - // XXX: this is a Buffer. Decode it? - // messageCtx.body = message.value; + messageCtx.body = message.value.toString(); } if (message.headers) { messageCtx.headers = Object.assign({}, message.headers); @@ -115,14 +118,12 @@ module.exports = function (mod, agent, { version, enabled }) { // age: { ms: 0 }, // TODO: check kafkajs docs // message.timestamp trans.setMessageContext(messageCtx); - trans._setDestinationContext({ - service: { resource: `${SUBTYPE}/${topic}` }, - }); // XXX: is necessary to bind???? let result; try { result = await origEachMessage.apply(this, arguments); + trans.setOutcome(constants.OUTCOME_SUCCESS); } catch (err) { trans.setOutcome(constants.OUTCOME_FAILURE); } finally { @@ -183,9 +184,12 @@ module.exports = function (mod, agent, { version, enabled }) { } function wrapProducer(origProducer) { - const producer = origProducer.apply(this.arguments); + return function wrappedProducer() { + const producer = origProducer.apply(this, arguments); - return producer; + // TODO: instrument producer + return producer; + }; } /** diff --git a/test/docker-compose.yml b/test/docker-compose.yml index bbf0997124..7be8ed0709 100644 --- a/test/docker-compose.yml +++ b/test/docker-compose.yml @@ -134,7 +134,6 @@ services: zookeeper: # https://hub.docker.com/r/bitnami/zookeeper/tags - #restart: always image: bitnami/zookeeper:3.9.1 ports: - "2181:2181" @@ -145,7 +144,6 @@ services: kafka: # https://hub.docker.com/r/bitnami/kafka/tags - #restart: always image: bitnami/kafka:3.3.2 ports: - "9093:9093" From aee63038f7523b692896c7456ffd1df2859ec4a7 Mon Sep 17 00:00:00 2001 From: David Luna Date: Tue, 28 Nov 2023 15:11:49 +0100 Subject: [PATCH 05/58] chore(kafkajs): add typings --- lib/instrumentation/modules/kafkajs.js | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index 3cd8313ead..8501aa761e 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -17,6 +17,8 @@ const SUBTYPE = 'kafka'; /** * @typedef {{ Kafka: import('kafkajs').Kafka}} KafkaModule + * @typedef {(config: any) => import('kafkajs').Producer} ProducerFactory + * @typedef {(config: any) => import('kafkajs').Consumer} ConsumerFactory */ /** @@ -41,6 +43,11 @@ module.exports = function (mod, agent, { version, enabled }) { shimmer.wrap(mod.Kafka.prototype, 'producer', wrapProducer); return mod; + /** + * Returns a function which creates instrumented consumers + * @param {ConsumerFactory} origConsumer + * @returns {ConsumerFactory} + */ function wrapConsumer(origConsumer) { return function wrappedConsumer() { const consumer = origConsumer.apply(this, arguments); From a09186d5768245c1875799b357341bf6ebc39da3 Mon Sep 17 00:00:00 2001 From: David Luna Date: Tue, 28 Nov 2023 19:00:38 +0100 Subject: [PATCH 06/58] chore(kafkajs): add age for message transactions --- lib/instrumentation/modules/kafkajs.js | 39 +++++++++++++++++++------- 1 file changed, 29 insertions(+), 10 deletions(-) diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index 8501aa761e..b274a67f34 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -17,8 +17,11 @@ const SUBTYPE = 'kafka'; /** * @typedef {{ Kafka: import('kafkajs').Kafka}} KafkaModule - * @typedef {(config: any) => import('kafkajs').Producer} ProducerFactory - * @typedef {(config: any) => import('kafkajs').Consumer} ConsumerFactory + * @typedef {import('kafkajs').Producer} Producer + * @typedef {import('kafkajs').Consumer} Consumer + * @typedef {import('kafkajs').ConsumerRunConfig} ConsumerRunConfig + * @typedef {(config: any) => Producer} ProducerFactory + * @typedef {(config: any) => Consumer} ConsumerFactory */ /** @@ -57,6 +60,11 @@ module.exports = function (mod, agent, { version, enabled }) { }; } + /** + * Returns a function which istrument the run callbacks `eachMessage` & `eachBatch` + * @param {Consumer['run']} origRun + * @returns {Consumer['run']} + */ function wrapConsumerRun(origRun) { return function wrappedConsumerRun() { const runConfig = arguments[0]; @@ -74,8 +82,11 @@ module.exports = function (mod, agent, { version, enabled }) { } /** - * @param {import('kafkajs').EachMessageHandler} origEachMessage - * @returns {import('kafkajs').EachMessageHandler} + * Returns the instrumented version of `eachMessage` which + * - creates a transaction each time is called + * - adds the trace context headers for distrubuted tracing + * @param {ConsumerRunConfig['eachMessage']} origEachMessage + * @returns {ConsumerRunConfig['eachMessage']} */ function wrapEachMessage(origEachMessage) { return async function (payload) { @@ -85,8 +96,6 @@ module.exports = function (mod, agent, { version, enabled }) { return origEachMessage.apply(this, arguments); } - console.log('kmessage', message); - // XXX: This should be a transaction // should we use `startTransaction` or `createTransaction` ??? // https://github.com/elastic/apm/blob/2ad487ebb18ba0a6d47507f2a699fa244841bfa5/specs/agents/tracing-instrumentation-messaging.md?plain=1#L34 @@ -103,6 +112,7 @@ module.exports = function (mod, agent, { version, enabled }) { if (message.headers) { // TODO: look for a parent context if needed? + // what if we get this form a context of a transaction? trans.propagateTraceContextHeaders( message.headers, function (headers, name, value) { @@ -118,12 +128,17 @@ module.exports = function (mod, agent, { version, enabled }) { if (config.captureBody) { messageCtx.body = message.value.toString(); } + if (message.headers) { messageCtx.headers = Object.assign({}, message.headers); } - // age: { ms: 0 }, // TODO: check kafkajs docs - // message.timestamp + if (message.timestamp) { + messageCtx.age = { + ms: Date.now() - Number(message.timestamp), + }; + } + trans.setMessageContext(messageCtx); // XXX: is necessary to bind???? @@ -142,8 +157,11 @@ module.exports = function (mod, agent, { version, enabled }) { } /** - * @param {import('kafkajs').EachBatchHandler} origEachMessage - * @returns {import('kafkajs').EachBatchHandler} + * Returns the instrumented version of `eachMessage` which + * - creates a transaction each time is called + * - adds the trace context headers for distrubuted tracing + * @param {ConsumerRunConfig['eachBatch']} origEachBatch + * @returns {ConsumerRunConfig['eachBatch']} */ function wrapEachBatch(origEachBatch) { return async function (payload) { @@ -180,6 +198,7 @@ module.exports = function (mod, agent, { version, enabled }) { let result; try { result = await origEachBatch.apply(this, arguments); + trans.setOutcome(constants.OUTCOME_SUCCESS); } catch (err) { trans.setOutcome(constants.OUTCOME_FAILURE); } finally { From 2fcbb1ab149cffc8a480af9725d4323d31cd0a70 Mon Sep 17 00:00:00 2001 From: David Luna Date: Tue, 28 Nov 2023 21:51:58 +0100 Subject: [PATCH 07/58] chore(kafkajs): remove noop early return --- examples/trace-kafka.js | 3 ++- lib/instrumentation/modules/kafkajs.js | 23 +++++++++-------------- 2 files changed, 11 insertions(+), 15 deletions(-) diff --git a/examples/trace-kafka.js b/examples/trace-kafka.js index f302959682..56225eaeca 100644 --- a/examples/trace-kafka.js +++ b/examples/trace-kafka.js @@ -36,7 +36,7 @@ async function run() { await producer.send({ topic, messages: [ - { value: 'message 1' }, + { value: 'message 1', headers: { foo: 'bar' } }, { value: 'message 2' }, { value: 'message 3' }, ], @@ -47,6 +47,7 @@ async function run() { await consumer.run({ eachMessage: async function ({ topic, partition, message }) { console.log(`message from topic(${topic}): ${message.value.toString()}`); + console.log(`message header ${message.headers}`); messagesConsumed++; }, }); diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index b274a67f34..795f5fcacc 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -96,23 +96,12 @@ module.exports = function (mod, agent, { version, enabled }) { return origEachMessage.apply(this, arguments); } - // XXX: This should be a transaction - // should we use `startTransaction` or `createTransaction` ??? - // https://github.com/elastic/apm/blob/2ad487ebb18ba0a6d47507f2a699fa244841bfa5/specs/agents/tracing-instrumentation-messaging.md?plain=1#L34 - const trans = ins.startTransaction( - `${NAME} RECEIVE from ${topic}`, - TYPE, - {}, // options - ); - - // XXX: if NoopTransaction we could finish right away - if (trans.type === 'noop') { - return origEachMessage.apply(this, arguments); - } - if (message.headers) { + // traceparent is in UTF-8 binary format + // TODO: look for a parent context if needed? // what if we get this form a context of a transaction? + // this below is for producers!!!!!! trans.propagateTraceContextHeaders( message.headers, function (headers, name, value) { @@ -124,6 +113,12 @@ module.exports = function (mod, agent, { version, enabled }) { ); } + const trans = ins.startTransaction( + `${NAME} RECEIVE from ${topic}`, + TYPE, + {}, // options + ); + const messageCtx = { queue: { name: topic } }; if (config.captureBody) { messageCtx.body = message.value.toString(); From 8846ed99137931bbd3a36405d1b6b4571c0f98ae Mon Sep 17 00:00:00 2001 From: David Luna Date: Thu, 30 Nov 2023 11:35:43 +0100 Subject: [PATCH 08/58] chore: add send instrumentation --- examples/trace-kafka.js | 12 +- lib/instrumentation/modules/kafkajs.js | 187 ++++++++++++++++++------- 2 files changed, 143 insertions(+), 56 deletions(-) diff --git a/examples/trace-kafka.js b/examples/trace-kafka.js index 56225eaeca..74d992310d 100644 --- a/examples/trace-kafka.js +++ b/examples/trace-kafka.js @@ -17,11 +17,19 @@ const apm = require('../').start({ serviceName: 'example-trace-kafka', }); +const { Buffer } = require('buffer'); +const { TextEncoder } = require('util'); + const { Kafka } = require('kafkajs'); const topic = 'trace-kafka-topic'; const kafka = new Kafka({ clientId: 'my-app', brokers: ['localhost:9093'] }); const admin = kafka.admin(); + +const headerStr = 'value inside buffer'; +const headerEnc = new TextEncoder().encode(headerStr); +const headerBuf = Buffer.from(headerEnc); + let producer, consumer; let messagesConsumed = 0; @@ -37,7 +45,7 @@ async function run() { topic, messages: [ { value: 'message 1', headers: { foo: 'bar' } }, - { value: 'message 2' }, + { value: 'message 2', headers: { foo: headerBuf } }, { value: 'message 3' }, ], }); @@ -47,7 +55,7 @@ async function run() { await consumer.run({ eachMessage: async function ({ topic, partition, message }) { console.log(`message from topic(${topic}): ${message.value.toString()}`); - console.log(`message header ${message.headers}`); + console.log(`message header ${message.headers.foo}`); messagesConsumed++; }, }); diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index 795f5fcacc..97bf9777e8 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -6,6 +6,8 @@ 'use strict'; +const { Buffer } = require('buffer'); + const semver = require('semver'); const constants = require('../../constants'); @@ -17,11 +19,12 @@ const SUBTYPE = 'kafka'; /** * @typedef {{ Kafka: import('kafkajs').Kafka}} KafkaModule - * @typedef {import('kafkajs').Producer} Producer + * @typedef {(config: any) => Consumer} ConsumerFactory * @typedef {import('kafkajs').Consumer} Consumer * @typedef {import('kafkajs').ConsumerRunConfig} ConsumerRunConfig * @typedef {(config: any) => Producer} ProducerFactory - * @typedef {(config: any) => Consumer} ConsumerFactory + * @typedef {import('kafkajs').Producer} Producer + * @typedef {import('kafkajs').ProducerRecord} ProducerRecord */ /** @@ -96,27 +99,29 @@ module.exports = function (mod, agent, { version, enabled }) { return origEachMessage.apply(this, arguments); } - if (message.headers) { - // traceparent is in UTF-8 binary format - - // TODO: look for a parent context if needed? - // what if we get this form a context of a transaction? - // this below is for producers!!!!!! - trans.propagateTraceContextHeaders( - message.headers, - function (headers, name, value) { - if (name.startsWith('elastic-')) { - return; - } - headers[name] = value; - }, - ); + const traceparent = message.headers && message.headers.traceparent; + const tracestate = message.headers && message.headers.traceparent; + const opts = {}; + + // According to `kafkajs` types a header value might be + // a string or Buffer + // https://github.com/tulios/kafkajs/blob/ff3b1117f316d527ae170b550bc0f772614338e9/types/index.d.ts#L148 + if (typeof traceparent === 'string') { + opts.childOf = traceparent; + } else if (traceparent instanceof Buffer) { + opts.childOf = traceparent.toString('utf-8'); + } + + if (typeof tracestate === 'string') { + opts.tracestate = tracestate; + } else if (tracestate instanceof Buffer) { + opts.tracestate = tracestate.toString('utf-8'); } const trans = ins.startTransaction( `${NAME} RECEIVE from ${topic}`, TYPE, - {}, // options + opts, ); const messageCtx = { queue: { name: topic } }; @@ -136,14 +141,18 @@ module.exports = function (mod, agent, { version, enabled }) { trans.setMessageContext(messageCtx); - // XXX: is necessary to bind???? - let result; + let result, err; try { result = await origEachMessage.apply(this, arguments); - trans.setOutcome(constants.OUTCOME_SUCCESS); - } catch (err) { - trans.setOutcome(constants.OUTCOME_FAILURE); + } catch (ex) { + // Save the error for use in `finally` below, but re-throw it to + // not impact code flow. + err = ex; + throw ex; } finally { + trans.setOutcome( + err ? constants.OUTCOME_FAILURE : constants.OUTCOME_SUCCESS, + ); trans.end(); } @@ -160,43 +169,29 @@ module.exports = function (mod, agent, { version, enabled }) { */ function wrapEachBatch(origEachBatch) { return async function (payload) { - const { batch } = payload; - - // XXX: the callback receives a batch with all mesages (Array) and use code will - // treat them in some sort of loop (I guess) but it's hard to tell - // We could do something simliar to java which is instrument the iterator - // to start/end a transaction for each element iteration - // https://github.com/elastic/apm/blob/2ad487ebb18ba0a6d47507f2a699fa244841bfa5/specs/agents/tracing-instrumentation-messaging.md?plain=1#L62C33-L62C33 - - // for now just a transaction for the whole batch - // XXX: This should be a transaction - // should we use `startTransaction` or `createTransaction` ??? - // https://github.com/elastic/apm/blob/2ad487ebb18ba0a6d47507f2a699fa244841bfa5/specs/agents/tracing-instrumentation-messaging.md?plain=1#L34 - const trans = ins.startTransaction( - `${NAME} RECEIVE from batch`, - TYPE, - {}, // options - ); - - // XXX: if NoopTransaction we could finish right away - if (trans.type === 'noop') { - return origEachBatch.apply(this, arguments); - } - - // XXX: propagate context not possible if messages come from different traces + // Messages could come from different traces so we cannot + // set a traceparent info in the new transaction + // Q: maybe check if all messages have same traceparent? + const trans = ins.startTransaction(`${NAME} RECEIVE from batch`, TYPE); + // We do not use topic in `service.resouce` since messages could + // come from different ones. trans._setDestinationContext({ - service: { resource: `${SUBTYPE}` }, // no topic because they may be multiple? + service: { resource: `${SUBTYPE}` }, }); - // XXX: is necessary to bind???? - let result; + let result, err; try { result = await origEachBatch.apply(this, arguments); - trans.setOutcome(constants.OUTCOME_SUCCESS); - } catch (err) { - trans.setOutcome(constants.OUTCOME_FAILURE); + } catch (ex) { + // Save the error for use in `finally` below, but re-throw it to + // not impact code flow. + err = ex; + throw ex; } finally { + trans.setOutcome( + err ? constants.OUTCOME_FAILURE : constants.OUTCOME_SUCCESS, + ); trans.end(); } @@ -204,15 +199,99 @@ module.exports = function (mod, agent, { version, enabled }) { }; } + /** + * Returns a function which creates instrumented producers + * @param {ProducerFactory} origProducer + * @returns {ProducerFactory} + */ function wrapProducer(origProducer) { return function wrappedProducer() { const producer = origProducer.apply(this, arguments); - // TODO: instrument producer + shimmer.wrap(producer, 'send', wrapProducerSend); return producer; }; } + /** + * TODO: add comment + * @param {Producer['send']} origSend + * @returns {Producer['send']} + */ + function wrapProducerSend(origSend) { + return async function (record) { + const { topic } = record; + + if (shouldIgnoreTopic(topic, config)) { + // TODO: ask trent about `contextPropagationOnly` + return origSend.apply(this, arguments); + } + + const span = ins.createSpan( + `${NAME} send to ${topic}`, + TYPE, + SUBTYPE, + 'send', + { exitSpan: true }, + ); + + // W3C trace-context propagation. + const runContext = ins.currRunContext(); + const parentSpan = + span || runContext.currSpan() || runContext.currTransaction(); + + if (parentSpan) { + record.messages.forEach((msg) => { + const newHeaders = Object.assign({}, msg.headers); + parentSpan.propagateTraceContextHeaders( + newHeaders, + function (carrier, name, value) { + if (name.startsWith('elastic-')) { + return; + } + carrier[name] = value; + }, + ); + msg.headers = newHeaders; + }); + } + + if (!span) { + return origSend.apply(this.arguments); + } + + // We do not add headers or body because: + // - `record.messages` is a list + // - spec says is for transactions (https://github.com/elastic/apm/blob/main/specs/agents/tracing-instrumentation-messaging.md#transaction-context-fields) + span.setMessageContext({ queue: { name: topic } }); + + const service = { + resource: `${SUBTYPE}/${topic}`, + type: SUBTYPE, + name: topic, + }; + + span._setDestinationContext({ service }); + + let result, err; + try { + result = await origSend.apply(this, arguments); + } catch (ex) { + // Save the error for use in `finally` below, but re-throw it to + // not impact code flow. + err = ex; + throw ex; + } finally { + span.setOutcome( + err ? constants.OUTCOME_FAILURE : constants.OUTCOME_SUCCESS, + ); + span.end(); + } + + return result; + }; + } + /** * Returns true if we have to ignore messages on the given topic * @param {string} topic the topic where client is publishing/subscribing From 018b65fe46352fde43ec2f7512f2d48b7f1020dc Mon Sep 17 00:00:00 2001 From: David Luna Date: Mon, 4 Dec 2023 15:35:48 +0100 Subject: [PATCH 09/58] chore: added kafkajs test fixture script --- .../modules/kafkajs/fixtures/use-kafkajs.js | 197 ++++++++++++++++++ .../modules/kafkajs/kafkajs.test.js | 45 ++++ 2 files changed, 242 insertions(+) create mode 100644 test/instrumentation/modules/kafkajs/fixtures/use-kafkajs.js create mode 100644 test/instrumentation/modules/kafkajs/kafkajs.test.js diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs.js new file mode 100644 index 0000000000..b26b6d380f --- /dev/null +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs.js @@ -0,0 +1,197 @@ +/* + * Copyright Elasticsearch B.V. and other contributors where applicable. + * Licensed under the BSD 2-Clause License; you may not use this file except in + * compliance with the BSD 2-Clause License. + */ + +'use strict'; + +const apm = require('../../../../..').start({ + serviceName: 'use-kafkajs', + captureExceptions: false, + centralConfig: false, + metricsInterval: 0, + cloudProvider: 'none', + stackTraceLimit: 4, // get it smaller for reviewing output + logLevel: 'info', +}); + +const { Buffer } = require('buffer'); +const assert = require('assert'); + +const { Kafka } = require('kafkajs'); +/** @type {import('kafkajs').Admin} */ +let admin; +/** @type {import('kafkajs').Consumer} */ +let consumerEach; +/** @type {import('kafkajs').Consumer} */ +let consumerBatch; +/** @type {import('kafkajs').Producer} */ +let producer; + +const TEST_TOPIC_PREFIX = 'elasticapmtest-topic-'; + +/** + * @param {import('kafkajs').Kafka} kafkaClient + * @param {{topic: string; groupId: string}} options + */ +async function useKafkajsClient(kafkaClient, options) { + const { topic, groupId } = options; + const topicEach = topic; + const topicBatch = `${topic}-batch`; + const log = apm.logger.child({ + 'event.module': 'kafkajs', + topic, + }); + + admin = kafkaClient.admin(); + consumerEach = kafkaClient.consumer({ groupId }); + consumerBatch = kafkaClient.consumer({ groupId }); + producer = kafkaClient.producer(); + + let messagesConsumed = 0; + // let data; + + // Create the topics & subscribe + await admin.connect(); + await admin.createTopics({ + topics: [{ topic: topicEach }, { topic: topicBatch }], + }); + log.info('createTopics'); + + await producer.connect(); + await consumerEach.connect(); + await consumerEach.subscribe({ topic: topicEach, fromBeginning: true }); + await consumerBatch.connect(); + await consumerBatch.subscribe({ topic: topicBatch, fromBeginning: true }); + log.info('all connected'); + + // 1st test trasnsactions for each message received + // Ensure an APM transaction so spans can happen. + const eachTx = apm.startTransaction(`manual send to ${topicEach}`); + await producer.send({ + topic: topicEach, + messages: [ + { value: 'each message 1', headers: { foo: 'bar' } }, + { value: 'each message 2', headers: { foo: Buffer.from('bar') } }, // TODO: traceparent + { value: 'each message 3' }, + ], + }); + eachTx.end(); + + const batchTx = apm.startTransaction(`manual send to ${topicBatch}`); + await producer.sendBatch({ + topic: topicBatch, + messages: [ + { value: 'batch message 1', headers: { foo: 'bar' } }, + { value: 'batch message 2', headers: { foo: Buffer.from('bar') } }, // TODO: traceparent + { value: 'batch message 3' }, + ], + }); + batchTx.end(); + + await consumerEach.run({ + eachMessage: async function ({ topic, message }) { + console.log( + `each message from topic(${topic}): ${message.value.toString()}`, + ); + messagesConsumed++; + }, + }); + + await consumerBatch.run({ + eachBatch: async function ({ batch }) { + batch.messages.forEach((message) => { + console.log( + `batch message from topic(${topic}): ${message.value.toString()}`, + ); + messagesConsumed++; + }); + }, + }); + await waitUntil(() => messagesConsumed >= 6, 15000); + + await consumerEach.disconnect(); + await consumerBatch.disconnect(); + await producer.disconnect(); + await admin.deleteTopics({ topics: [topic] }); + await admin.disconnect(); + + consumerEach = null; + consumerBatch = null; + producer = null; + admin = null; +} + +// ---- helper functions + +/** + * Retuns a promise which is resolved when the predicate becomes true or rejected + * if the timeout is reached. + * @param {() => boolean} predicate function which will return true to make ed of wait + * @param {number} [timeout] max time in ms to wait for the predicste to be true (defaults to 5000) + * @returns {Promise} + */ +function waitUntil(predicate, timeout = 5000) { + const startTime = Date.now(); + + return new Promise((resolve, reject) => { + const intervalId = setInterval(() => { + const deltaTime = Date.now() - startTime; + + if (predicate()) { + clearInterval(intervalId); + resolve(); + } else if (deltaTime > timeout) { + clearInterval(intervalId); + reject(new Error(`timeout after ${deltaTime}ms`)); + } + }, 1000); + }); +} + +// ---- mainline + +function main() { + // Config vars. + const clientId = process.env.TEST_CLIENT_ID || 'elastictest-kafka-client'; + const groupId = process.env.TEST_GROUP_ID || 'elastictest-kafka-group'; + const broker = process.env.TEST_KAFKA_URL || 'localhost:9093'; + const topic = + process.env.TEST_TOPIC || + TEST_TOPIC_PREFIX + Math.floor(Math.random() * 1000); + + // Guard against any topic name being used because we will be sending and + // receiveing in it, and potentially *deleting* the topic. + if (!topic.startsWith(TEST_TOPIC_PREFIX)) { + throw new Error( + `cannot use bucket name "${topic}", it must start with ${TEST_TOPIC_PREFIX}`, + ); + } + + const kafkaClient = new Kafka({ clientId, brokers: [broker] }); + + // TODO: this on sending messages + // // Ensure an APM transaction so spans can happen. + // const tx = apm.startTransaction('manual'); + + useKafkajsClient(kafkaClient, { topic, groupId }).then( + function () { + // TODO: make sure disconnect consumer && producer? + process.exitCode = 0; + }, + async function (err) { + apm.logger.error(err, 'useKafkajsClient rejected'); + const clients = [consumerEach, consumerBatch, producer, admin].filter( + (x) => x, + ); + for await (const client of clients) { + await client.disconnect(); + } + + process.exitCode = 1; + }, + ); +} + +main(); diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js new file mode 100644 index 0000000000..a6f8524644 --- /dev/null +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -0,0 +1,45 @@ +/* + * Copyright Elasticsearch B.V. and other contributors where applicable. + * Licensed under the BSD 2-Clause License; you may not use this file except in + * compliance with the BSD 2-Clause License. + */ + +'use strict'; + +// Test instrumentation of the 'kafkajs' module. + +if (process.env.GITHUB_ACTIONS === 'true' && process.platform === 'win32') { + console.log('# SKIP: GH Actions do not support docker services on Windows'); + process.exit(0); +} + +const test = require('tape'); + +const { validateSpan } = require('../../../_validate_schema'); +const { runTestFixtures, sortApmEvents } = require('../../../_utils'); +const { NODE_VER_RANGE_IITM } = require('../../../testconsts'); + +const kafkaUrl = process.env.KAFKA_URL || 'localhost:9093'; + +/** @type {import('../../../_utils').TestFixture[]} */ +const testFixtures = [ + { + name: 'simple Kafkajs usage scenario', + script: 'fixtures/use-kafkajs.js', + cwd: __dirname, + env: { + TEST_CLIENT_ID: 'elastic-kafka-client', + TEST_TOPIC: 'elasticapmtest-topic-1234', + TEST_KAFKA_URL: kafkaUrl, + }, + checkApmServer(t, apmServer) { + t.ok(apmServer.events[0].metadata, 'metadata'); + const events = sortApmEvents(apmServer.events); + }, + }, +]; + +test('kafkajs fixtures', (suite) => { + runTestFixtures(suite, testFixtures); + suite.end(); +}); From 22ff0ea0e1adb5ed36c3b5854c0873dba1247f22 Mon Sep 17 00:00:00 2001 From: David Luna Date: Thu, 7 Dec 2023 12:34:13 +0100 Subject: [PATCH 10/58] chore: fix consumers subscription --- .../modules/kafkajs/fixtures/use-kafkajs.js | 86 +++++++++---------- 1 file changed, 40 insertions(+), 46 deletions(-) diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs.js index b26b6d380f..ed5c6f77d8 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs.js @@ -37,7 +37,7 @@ const TEST_TOPIC_PREFIX = 'elasticapmtest-topic-'; */ async function useKafkajsClient(kafkaClient, options) { const { topic, groupId } = options; - const topicEach = topic; + const topicEach = `${topic}-each`; const topicBatch = `${topic}-batch`; const log = apm.logger.child({ 'event.module': 'kafkajs', @@ -49,9 +49,6 @@ async function useKafkajsClient(kafkaClient, options) { consumerBatch = kafkaClient.consumer({ groupId }); producer = kafkaClient.producer(); - let messagesConsumed = 0; - // let data; - // Create the topics & subscribe await admin.connect(); await admin.createTopics({ @@ -61,11 +58,36 @@ async function useKafkajsClient(kafkaClient, options) { await producer.connect(); await consumerEach.connect(); - await consumerEach.subscribe({ topic: topicEach, fromBeginning: true }); + await consumerEach.subscribe({ topics: [topicEach], fromBeginning: true }); await consumerBatch.connect(); - await consumerBatch.subscribe({ topic: topicBatch, fromBeginning: true }); + await consumerBatch.subscribe({ topics: [topicBatch], fromBeginning: true }); log.info('all connected'); + let eachMessagesConsumed = 0; + let batchMessagesConsumed = 0; + await consumerEach.run({ + eachMessage: async function ({ topic, message }) { + log.info( + { topic }, + `each message from topic(${topic}): ${message.value.toString()}`, + ); + eachMessagesConsumed++; + }, + }); + + await consumerBatch.run({ + eachBatch: async function ({ batch }) { + const { topic } = batch; + batch.messages.forEach((message) => { + log.info( + { topic }, + `batch message from topic(${topic}): ${message.value.toString()}`, + ); + batchMessagesConsumed++; + }); + }, + }); + // 1st test trasnsactions for each message received // Ensure an APM transaction so spans can happen. const eachTx = apm.startTransaction(`manual send to ${topicEach}`); @@ -78,6 +100,7 @@ async function useKafkajsClient(kafkaClient, options) { ], }); eachTx.end(); + log.info({ topic: topicEach }, 'messages sent'); const batchTx = apm.startTransaction(`manual send to ${topicBatch}`); await producer.sendBatch({ @@ -89,38 +112,21 @@ async function useKafkajsClient(kafkaClient, options) { ], }); batchTx.end(); - - await consumerEach.run({ - eachMessage: async function ({ topic, message }) { - console.log( - `each message from topic(${topic}): ${message.value.toString()}`, - ); - messagesConsumed++; - }, - }); - - await consumerBatch.run({ - eachBatch: async function ({ batch }) { - batch.messages.forEach((message) => { - console.log( - `batch message from topic(${topic}): ${message.value.toString()}`, - ); - messagesConsumed++; - }); - }, - }); - await waitUntil(() => messagesConsumed >= 6, 15000); + log.info({ topic: topicBatch }, 'batch sent'); + + try { + await waitUntil(() => { + return eachMessagesConsumed >= 3 && batchMessagesConsumed >= 3; + }, 30000); + } catch (err) { + log.error(err, ' messages could not be consumed after 30s'); + } await consumerEach.disconnect(); await consumerBatch.disconnect(); await producer.disconnect(); - await admin.deleteTopics({ topics: [topic] }); + await admin.deleteTopics({ topics: [topicEach, topicBatch] }); await admin.disconnect(); - - consumerEach = null; - consumerBatch = null; - producer = null; - admin = null; } // ---- helper functions @@ -171,24 +177,12 @@ function main() { const kafkaClient = new Kafka({ clientId, brokers: [broker] }); - // TODO: this on sending messages - // // Ensure an APM transaction so spans can happen. - // const tx = apm.startTransaction('manual'); - useKafkajsClient(kafkaClient, { topic, groupId }).then( function () { - // TODO: make sure disconnect consumer && producer? process.exitCode = 0; }, - async function (err) { + function (err) { apm.logger.error(err, 'useKafkajsClient rejected'); - const clients = [consumerEach, consumerBatch, producer, admin].filter( - (x) => x, - ); - for await (const client of clients) { - await client.disconnect(); - } - process.exitCode = 1; }, ); From 82c1e63491c793dd3b64f2bb8c5c9ec74d1230f2 Mon Sep 17 00:00:00 2001 From: David Luna Date: Thu, 7 Dec 2023 13:10:20 +0100 Subject: [PATCH 11/58] chore: single consumer working --- .../modules/kafkajs/fixtures/use-kafkajs.js | 66 +++++++++---------- 1 file changed, 33 insertions(+), 33 deletions(-) diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs.js index ed5c6f77d8..0edb09a8f9 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs.js @@ -23,9 +23,7 @@ const { Kafka } = require('kafkajs'); /** @type {import('kafkajs').Admin} */ let admin; /** @type {import('kafkajs').Consumer} */ -let consumerEach; -/** @type {import('kafkajs').Consumer} */ -let consumerBatch; +let consumer; /** @type {import('kafkajs').Producer} */ let producer; @@ -41,12 +39,10 @@ async function useKafkajsClient(kafkaClient, options) { const topicBatch = `${topic}-batch`; const log = apm.logger.child({ 'event.module': 'kafkajs', - topic, }); admin = kafkaClient.admin(); - consumerEach = kafkaClient.consumer({ groupId }); - consumerBatch = kafkaClient.consumer({ groupId }); + consumer = kafkaClient.consumer({ groupId }); producer = kafkaClient.producer(); // Create the topics & subscribe @@ -57,31 +53,30 @@ async function useKafkajsClient(kafkaClient, options) { log.info('createTopics'); await producer.connect(); - await consumerEach.connect(); - await consumerEach.subscribe({ topics: [topicEach], fromBeginning: true }); - await consumerBatch.connect(); - await consumerBatch.subscribe({ topics: [topicBatch], fromBeginning: true }); + await consumer.connect(); + await consumer.subscribe({ + topics: [topicEach, topicBatch], + fromBeginning: true, + }); log.info('all connected'); let eachMessagesConsumed = 0; let batchMessagesConsumed = 0; - await consumerEach.run({ - eachMessage: async function ({ topic, message }) { + await consumer.run({ + eachMessage: async function (payload) { + const msgTopic = payload.topic; log.info( - { topic }, - `each message from topic(${topic}): ${message.value.toString()}`, + { topic: msgTopic }, + `each message from topic(${msgTopic}): ${payload.message.value.toString()}`, ); eachMessagesConsumed++; }, - }); - - await consumerBatch.run({ - eachBatch: async function ({ batch }) { - const { topic } = batch; - batch.messages.forEach((message) => { + eachBatch: async function (payload) { + const batchTopic = payload.batch.topic; + payload.batch.messages.forEach((message) => { log.info( - { topic }, - `batch message from topic(${topic}): ${message.value.toString()}`, + { topic: batchTopic }, + `batch message from topic(${batchTopic}): ${message.value.toString()}`, ); batchMessagesConsumed++; }); @@ -90,8 +85,9 @@ async function useKafkajsClient(kafkaClient, options) { // 1st test trasnsactions for each message received // Ensure an APM transaction so spans can happen. + let data; const eachTx = apm.startTransaction(`manual send to ${topicEach}`); - await producer.send({ + data = await producer.send({ topic: topicEach, messages: [ { value: 'each message 1', headers: { foo: 'bar' } }, @@ -100,30 +96,34 @@ async function useKafkajsClient(kafkaClient, options) { ], }); eachTx.end(); - log.info({ topic: topicEach }, 'messages sent'); + log.info({ topic: topicEach, data }, 'messages sent'); const batchTx = apm.startTransaction(`manual send to ${topicBatch}`); - await producer.sendBatch({ - topic: topicBatch, - messages: [ - { value: 'batch message 1', headers: { foo: 'bar' } }, - { value: 'batch message 2', headers: { foo: Buffer.from('bar') } }, // TODO: traceparent - { value: 'batch message 3' }, + data = await producer.sendBatch({ + topicMessages: [ + { + topic: topicBatch, + messages: [ + { value: 'batch message 1', headers: { foo: 'bar' } }, + { value: 'batch message 2', headers: { foo: Buffer.from('bar') } }, // TODO: traceparent + { value: 'batch message 3' }, + ], + }, ], }); batchTx.end(); - log.info({ topic: topicBatch }, 'batch sent'); + log.info({ topic: topicBatch, data }, 'batch sent'); try { await waitUntil(() => { + console.log(eachMessagesConsumed, batchMessagesConsumed); return eachMessagesConsumed >= 3 && batchMessagesConsumed >= 3; }, 30000); } catch (err) { log.error(err, ' messages could not be consumed after 30s'); } - await consumerEach.disconnect(); - await consumerBatch.disconnect(); + await consumer.disconnect(); await producer.disconnect(); await admin.deleteTopics({ topics: [topicEach, topicBatch] }); await admin.disconnect(); From ebcb8db97db335578fc95d3cb25c7165129bceb4 Mon Sep 17 00:00:00 2001 From: David Luna Date: Thu, 7 Dec 2023 15:34:08 +0100 Subject: [PATCH 12/58] chore: separate fixtures for single and batch consumers --- lib/instrumentation/modules/kafkajs.js | 11 +- ...e-kafkajs.js => use-kafkajs-each-batch.js} | 55 ++----- .../fixtures/use-kafkajs-each-message.js | 151 ++++++++++++++++++ 3 files changed, 167 insertions(+), 50 deletions(-) rename test/instrumentation/modules/kafkajs/fixtures/{use-kafkajs.js => use-kafkajs-each-batch.js} (70%) create mode 100644 test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index 97bf9777e8..3b7e8ca6dc 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -100,7 +100,7 @@ module.exports = function (mod, agent, { version, enabled }) { } const traceparent = message.headers && message.headers.traceparent; - const tracestate = message.headers && message.headers.traceparent; + const tracestate = message.headers && message.headers.tracestate; const opts = {}; // According to `kafkajs` types a header value might be @@ -174,11 +174,10 @@ module.exports = function (mod, agent, { version, enabled }) { // Q: maybe check if all messages have same traceparent? const trans = ins.startTransaction(`${NAME} RECEIVE from batch`, TYPE); - // We do not use topic in `service.resouce` since messages could - // come from different ones. - trans._setDestinationContext({ - service: { resource: `${SUBTYPE}` }, - }); + // We should add a span_link for each meesage fo the batch + // https://github.com/elastic/apm/blob/e1564e3addd9f373b6551eab89483d07ed3ff313/specs/agents/tracing-instrumentation-messaging.md?plain=1#L81 + // TODO: + let result, err; try { diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js similarity index 70% rename from test/instrumentation/modules/kafkajs/fixtures/use-kafkajs.js rename to test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js index 0edb09a8f9..76cf1ac1aa 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js @@ -17,7 +17,6 @@ const apm = require('../../../../..').start({ }); const { Buffer } = require('buffer'); -const assert = require('assert'); const { Kafka } = require('kafkajs'); /** @type {import('kafkajs').Admin} */ @@ -35,10 +34,9 @@ const TEST_TOPIC_PREFIX = 'elasticapmtest-topic-'; */ async function useKafkajsClient(kafkaClient, options) { const { topic, groupId } = options; - const topicEach = `${topic}-each`; - const topicBatch = `${topic}-batch`; const log = apm.logger.child({ 'event.module': 'kafkajs', + topic, }); admin = kafkaClient.admin(); @@ -48,36 +46,20 @@ async function useKafkajsClient(kafkaClient, options) { // Create the topics & subscribe await admin.connect(); await admin.createTopics({ - topics: [{ topic: topicEach }, { topic: topicBatch }], + topics: [{ topic }], }); log.info('createTopics'); await producer.connect(); await consumer.connect(); - await consumer.subscribe({ - topics: [topicEach, topicBatch], - fromBeginning: true, - }); + await consumer.subscribe({ topics: [topic], fromBeginning: true }); log.info('all connected'); - let eachMessagesConsumed = 0; let batchMessagesConsumed = 0; await consumer.run({ - eachMessage: async function (payload) { - const msgTopic = payload.topic; - log.info( - { topic: msgTopic }, - `each message from topic(${msgTopic}): ${payload.message.value.toString()}`, - ); - eachMessagesConsumed++; - }, - eachBatch: async function (payload) { - const batchTopic = payload.batch.topic; - payload.batch.messages.forEach((message) => { - log.info( - { topic: batchTopic }, - `batch message from topic(${batchTopic}): ${message.value.toString()}`, - ); + eachBatch: async function ({ batch }) { + batch.messages.forEach((message) => { + log.info(`batch message received: ${message.value.toString()}`); batchMessagesConsumed++; }); }, @@ -86,23 +68,11 @@ async function useKafkajsClient(kafkaClient, options) { // 1st test trasnsactions for each message received // Ensure an APM transaction so spans can happen. let data; - const eachTx = apm.startTransaction(`manual send to ${topicEach}`); - data = await producer.send({ - topic: topicEach, - messages: [ - { value: 'each message 1', headers: { foo: 'bar' } }, - { value: 'each message 2', headers: { foo: Buffer.from('bar') } }, // TODO: traceparent - { value: 'each message 3' }, - ], - }); - eachTx.end(); - log.info({ topic: topicEach, data }, 'messages sent'); - - const batchTx = apm.startTransaction(`manual send to ${topicBatch}`); + const batchTx = apm.startTransaction(`manual send to ${topic}`); data = await producer.sendBatch({ topicMessages: [ { - topic: topicBatch, + topic, messages: [ { value: 'batch message 1', headers: { foo: 'bar' } }, { value: 'batch message 2', headers: { foo: Buffer.from('bar') } }, // TODO: traceparent @@ -112,20 +82,17 @@ async function useKafkajsClient(kafkaClient, options) { ], }); batchTx.end(); - log.info({ topic: topicBatch, data }, 'batch sent'); + log.info({ data }, 'batch sent'); try { - await waitUntil(() => { - console.log(eachMessagesConsumed, batchMessagesConsumed); - return eachMessagesConsumed >= 3 && batchMessagesConsumed >= 3; - }, 30000); + await waitUntil(() => batchMessagesConsumed >= 3, 5000); } catch (err) { log.error(err, ' messages could not be consumed after 30s'); } await consumer.disconnect(); await producer.disconnect(); - await admin.deleteTopics({ topics: [topicEach, topicBatch] }); + await admin.deleteTopics({ topics: [topic] }); await admin.disconnect(); } diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js new file mode 100644 index 0000000000..d2cc9dab02 --- /dev/null +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js @@ -0,0 +1,151 @@ +/* + * Copyright Elasticsearch B.V. and other contributors where applicable. + * Licensed under the BSD 2-Clause License; you may not use this file except in + * compliance with the BSD 2-Clause License. + */ + +'use strict'; + +const apm = require('../../../../..').start({ + serviceName: 'use-kafkajs', + captureExceptions: false, + centralConfig: false, + metricsInterval: 0, + cloudProvider: 'none', + stackTraceLimit: 4, // get it smaller for reviewing output + logLevel: 'info', +}); + +const { Buffer } = require('buffer'); +const assert = require('assert'); + +const { Kafka } = require('kafkajs'); +/** @type {import('kafkajs').Admin} */ +let admin; +/** @type {import('kafkajs').Consumer} */ +let consumer; +/** @type {import('kafkajs').Producer} */ +let producer; + +const TEST_TOPIC_PREFIX = 'elasticapmtest-topic-'; + +/** + * @param {import('kafkajs').Kafka} kafkaClient + * @param {{topic: string; groupId: string}} options + */ +async function useKafkajsClient(kafkaClient, options) { + const { topic, groupId } = options; + const log = apm.logger.child({ + 'event.module': 'kafkajs', + topic, + }); + + admin = kafkaClient.admin(); + consumer = kafkaClient.consumer({ groupId }); + producer = kafkaClient.producer(); + + // Create the topics & subscribe + await admin.connect(); + await admin.createTopics({ topics: [{ topic }] }); + log.info('topic created'); + + await producer.connect(); + await consumer.connect(); + await consumer.subscribe({ topics: [topic], fromBeginning: true }); + log.info('all connected'); + + let eachMessagesConsumed = 0; + await consumer.run({ + eachMessage: async function ({ message }) { + log.info(`message received: ${message.value.toString()}`); + eachMessagesConsumed++; + }, + }); + + // 1st test trasnsactions for each message received + // Ensure an APM transaction so spans can happen. + let data; + const eachTx = apm.startTransaction(`manual send to ${topic}`); + data = await producer.send({ + topic, + messages: [ + { value: 'each message 1', headers: { foo: 'bar' } }, + { value: 'each message 2', headers: { foo: Buffer.from('bar') } }, // TODO: traceparent + { value: 'each message 3' }, + ], + }); + eachTx.end(); + log.info({ data }, 'messages sent'); + + try { + await waitUntil(() => eachMessagesConsumed >= 3, 5000); + } catch (err) { + log.error(err, ' messages could not be consumed after 30s'); + } + + await consumer.disconnect(); + await producer.disconnect(); + await admin.deleteTopics({ topics: [topic] }); + await admin.disconnect(); +} + +// ---- helper functions + +/** + * Retuns a promise which is resolved when the predicate becomes true or rejected + * if the timeout is reached. + * @param {() => boolean} predicate function which will return true to make ed of wait + * @param {number} [timeout] max time in ms to wait for the predicste to be true (defaults to 5000) + * @returns {Promise} + */ +function waitUntil(predicate, timeout = 5000) { + const startTime = Date.now(); + + return new Promise((resolve, reject) => { + const intervalId = setInterval(() => { + const deltaTime = Date.now() - startTime; + + if (predicate()) { + clearInterval(intervalId); + resolve(); + } else if (deltaTime > timeout) { + clearInterval(intervalId); + reject(new Error(`timeout after ${deltaTime}ms`)); + } + }, 1000); + }); +} + +// ---- mainline + +function main() { + // Config vars. + const clientId = process.env.TEST_CLIENT_ID || 'elastictest-kafka-client'; + const groupId = process.env.TEST_GROUP_ID || 'elastictest-kafka-group'; + const broker = process.env.TEST_KAFKA_URL || 'localhost:9093'; + const topic = + process.env.TEST_TOPIC || + TEST_TOPIC_PREFIX + Math.floor(Math.random() * 1000); + + // Guard against any topic name being used because we will be sending and + // receiveing in it, and potentially *deleting* the topic. + if (!topic.startsWith(TEST_TOPIC_PREFIX)) { + throw new Error( + `cannot use bucket name "${topic}", it must start with ${TEST_TOPIC_PREFIX}`, + ); + } + + const kafkaClient = new Kafka({ clientId, brokers: [broker] }); + + useKafkajsClient(kafkaClient, { topic, groupId }).then( + function () { + process.exitCode = 0; + }, + function (err) { + apm.logger.error(err, 'useKafkajsClient rejected'); + process.exitCode = 1; + }, + ); +} + +main(); From ebd0ff9677f1ff8fe6bc77b6d6829dc00884b730 Mon Sep 17 00:00:00 2001 From: David Luna Date: Thu, 7 Dec 2023 18:27:27 +0100 Subject: [PATCH 13/58] chore: add links on batch processing --- lib/instrumentation/modules/kafkajs.js | 35 +++++++++++++++++++++----- 1 file changed, 29 insertions(+), 6 deletions(-) diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index 3b7e8ca6dc..a6ae9e2114 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -12,6 +12,7 @@ const semver = require('semver'); const constants = require('../../constants'); const shimmer = require('../shimmer'); +const { patch } = require('request'); const NAME = 'Kafka'; const TYPE = 'messaging'; @@ -169,15 +170,37 @@ module.exports = function (mod, agent, { version, enabled }) { */ function wrapEachBatch(origEachBatch) { return async function (payload) { - // Messages could come from different traces so we cannot - // set a traceparent info in the new transaction - // Q: maybe check if all messages have same traceparent? const trans = ins.startTransaction(`${NAME} RECEIVE from batch`, TYPE); - // We should add a span_link for each meesage fo the batch - // https://github.com/elastic/apm/blob/e1564e3addd9f373b6551eab89483d07ed3ff313/specs/agents/tracing-instrumentation-messaging.md?plain=1#L81 - // TODO: + const serviceContext = { + framework: { name: 'Kafka' }, + }; + trans.setServiceContext(serviceContext); + + // Extract span links from up to 1000 messages in this batch. + // https://github.com/elastic/apm/blob/main/specs/agents/tracing-instrumentation-messaging.md#receiving-trace-context + // A span link is created from a `traceparent` header in a message. + const messages = payload && payload.batch && payload.batch.messages; + + if (messages) { + const links = []; + const limit = Math.min( + messages.length, + constants.MAX_MESSAGES_PROCESSED_FOR_TRACE_CONTEXT, + ); + + for (let i = 0; i < messages.length; i++) { + const msg = messages[i]; + if (msg.headers && msg.headers.traceparent) { + links.push({ context: msg.headers.traceparent.toString() }); // TODO: check this + if (links.length >= limit) { + break; + } + } + } + trans._addLinks(links); + } let result, err; try { From ba761ed3a9e3751487e625846cefd1e3a4a8df4e Mon Sep 17 00:00:00 2001 From: David Luna Date: Mon, 11 Dec 2023 09:53:49 +0100 Subject: [PATCH 14/58] chore: add tests skeleton --- lib/instrumentation/modules/kafkajs.js | 1 + .../modules/kafkajs/kafkajs.test.js | 42 +++++++++++++++++-- 2 files changed, 40 insertions(+), 3 deletions(-) diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index a6ae9e2114..b0764223e1 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -268,6 +268,7 @@ module.exports = function (mod, agent, { version, enabled }) { parentSpan.propagateTraceContextHeaders( newHeaders, function (carrier, name, value) { + // TODO: why doing it everywhere??? if (name.startsWith('elastic-')) { return; } diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index a6f8524644..b356b61d9d 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -17,15 +17,15 @@ const test = require('tape'); const { validateSpan } = require('../../../_validate_schema'); const { runTestFixtures, sortApmEvents } = require('../../../_utils'); -const { NODE_VER_RANGE_IITM } = require('../../../testconsts'); +// const { NODE_VER_RANGE_IITM } = require('../../../testconsts'); const kafkaUrl = process.env.KAFKA_URL || 'localhost:9093'; /** @type {import('../../../_utils').TestFixture[]} */ const testFixtures = [ { - name: 'simple Kafkajs usage scenario', - script: 'fixtures/use-kafkajs.js', + name: 'simple Kafkajs usage scenario for single message processing', + script: 'fixtures/use-kafkajs-each-message.js', cwd: __dirname, env: { TEST_CLIENT_ID: 'elastic-kafka-client', @@ -35,6 +35,42 @@ const testFixtures = [ checkApmServer(t, apmServer) { t.ok(apmServer.events[0].metadata, 'metadata'); const events = sortApmEvents(apmServer.events); + + console.log(events) + + // Compare some common fields across all spans. + // ignore http/external spans + const spans = events + .filter((e) => e.span && e.span.type !== 'external') + .map((e) => e.span); + spans.forEach((s) => { + const errs = validateSpan(s); + t.equal(errs, null, 'span is valid (per apm-server intake schema)'); + }); + }, + }, + { + name: 'simple Kafkajs usage scenario for batch message processing', + script: 'fixtures/use-kafkajs-each-batch.js', + cwd: __dirname, + env: { + TEST_CLIENT_ID: 'elastic-kafka-client', + TEST_TOPIC: 'elasticapmtest-topic-5678', + TEST_KAFKA_URL: kafkaUrl, + }, + checkApmServer(t, apmServer) { + t.ok(apmServer.events[0].metadata, 'metadata'); + const events = sortApmEvents(apmServer.events); + + // Compare some common fields across all spans. + // ignore http/external spans + const spans = events + .filter((e) => e.span && e.span.type !== 'external') + .map((e) => e.span); + spans.forEach((s) => { + const errs = validateSpan(s); + t.equal(errs, null, 'span is valid (per apm-server intake schema)'); + }); }, }, ]; From 989a44b6cca7b7c22d9f777a52813e761d7854ec Mon Sep 17 00:00:00 2001 From: David Luna Date: Tue, 12 Dec 2023 12:00:05 +0100 Subject: [PATCH 15/58] chore: proper headers capturing --- lib/instrumentation/modules/kafkajs.js | 14 +- .../fixtures/use-kafkajs-each-batch.js | 4 +- .../fixtures/use-kafkajs-each-message.js | 4 +- .../modules/kafkajs/kafkajs.test.js | 201 +++++++++++++++--- 4 files changed, 192 insertions(+), 31 deletions(-) diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index b0764223e1..6e644723b8 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -12,7 +12,6 @@ const semver = require('semver'); const constants = require('../../constants'); const shimmer = require('../shimmer'); -const { patch } = require('request'); const NAME = 'Kafka'; const TYPE = 'messaging'; @@ -131,7 +130,18 @@ module.exports = function (mod, agent, { version, enabled }) { } if (message.headers) { - messageCtx.headers = Object.assign({}, message.headers); + messageCtx.headers = Object.keys(message.headers).reduce( + (acc, name) => { + const value = message.headers[name]; + if (value instanceof Buffer) { + acc[name] = value.toString('utf-8'); + } else { + acc[name] = value; + } + return acc; + }, + {}, + ); } if (message.timestamp) { diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js index 76cf1ac1aa..f9d3b58638 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js @@ -74,8 +74,8 @@ async function useKafkajsClient(kafkaClient, options) { { topic, messages: [ - { value: 'batch message 1', headers: { foo: 'bar' } }, - { value: 'batch message 2', headers: { foo: Buffer.from('bar') } }, // TODO: traceparent + { value: 'batch message 1', headers: { foo: 'string' } }, + { value: 'batch message 2', headers: { foo: Buffer.from('buffer') } }, { value: 'batch message 3' }, ], }, diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js index d2cc9dab02..78f2667ab7 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js @@ -69,8 +69,8 @@ async function useKafkajsClient(kafkaClient, options) { data = await producer.send({ topic, messages: [ - { value: 'each message 1', headers: { foo: 'bar' } }, - { value: 'each message 2', headers: { foo: Buffer.from('bar') } }, // TODO: traceparent + { value: 'each message 1', headers: { foo: 'string' } }, + { value: 'each message 2', headers: { foo: Buffer.from('buffer') } }, { value: 'each message 3' }, ], }); diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index b356b61d9d..8f00fd89b1 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -32,47 +32,198 @@ const testFixtures = [ TEST_TOPIC: 'elasticapmtest-topic-1234', TEST_KAFKA_URL: kafkaUrl, }, + verbose: true, checkApmServer(t, apmServer) { t.ok(apmServer.events[0].metadata, 'metadata'); const events = sortApmEvents(apmServer.events); + const tx = events.shift().transaction; - console.log(events) + // First the transaction. + t.ok(tx, 'got the transaction'); // Compare some common fields across all spans. // ignore http/external spans - const spans = events - .filter((e) => e.span && e.span.type !== 'external') - .map((e) => e.span); + const spans = events.filter((e) => e.span).map((e) => e.span); spans.forEach((s) => { const errs = validateSpan(s); t.equal(errs, null, 'span is valid (per apm-server intake schema)'); }); - }, - }, - { - name: 'simple Kafkajs usage scenario for batch message processing', - script: 'fixtures/use-kafkajs-each-batch.js', - cwd: __dirname, - env: { - TEST_CLIENT_ID: 'elastic-kafka-client', - TEST_TOPIC: 'elasticapmtest-topic-5678', - TEST_KAFKA_URL: kafkaUrl, - }, - checkApmServer(t, apmServer) { - t.ok(apmServer.events[0].metadata, 'metadata'); - const events = sortApmEvents(apmServer.events); + t.equal( + spans.filter((s) => s.trace_id === tx.trace_id).length, + spans.length, + 'all spans have the same trace_id', + ); + t.equal( + spans.filter((s) => s.transaction_id === tx.id).length, + spans.length, + 'all spans have the same transaction_id', + ); + t.equal( + spans.filter((s) => s.sync === false).length, + spans.length, + 'all spans have sync=false', + ); + t.equal( + spans.filter((s) => s.sample_rate === 1).length, + spans.length, + 'all spans have sample_rate=1', + ); - // Compare some common fields across all spans. - // ignore http/external spans - const spans = events - .filter((e) => e.span && e.span.type !== 'external') - .map((e) => e.span); spans.forEach((s) => { - const errs = validateSpan(s); - t.equal(errs, null, 'span is valid (per apm-server intake schema)'); + // Remove variable and common fields to facilitate t.deepEqual below. + delete s.id; + delete s.transaction_id; + delete s.parent_id; + delete s.trace_id; + delete s.timestamp; + delete s.duration; + delete s.sync; + delete s.sample_rate; }); + + t.deepEqual(spans.shift(), { + name: 'Kafka send to elasticapmtest-topic-1234', + type: 'messaging', + subtype: 'kafka', + action: 'send', + context: { + service: { + target: { type: 'kafka', name: 'elasticapmtest-topic-1234' }, + }, + destination: { + service: { + resource: 'kafka/elasticapmtest-topic-1234', + type: '', + name: '', + }, + }, + message: { queue: { name: 'elasticapmtest-topic-1234' } }, + }, + outcome: 'success', + }); + + t.equal(spans.length, 0, 'all spans accounted for'); + + // No check the transactions created for each message received + const transactions = events + .filter((e) => e.transaction) + .map((e) => e.transaction); + const parentId = transactions[0].parent_id; + + t.equal( + transactions.filter((t) => t.trace_id === tx.trace_id).length, + transactions.length, + 'all transactions have the same trace_id', + ); + t.equal( + transactions.filter((t) => t.parent_id === parentId).length, + transactions.length, + 'all transactions have the same parent_id', + ); + t.equal( + transactions + .map((t) => t.context.message.age.ms) + .filter((ms) => typeof ms === 'number' && ms > 0).length, + transactions.length, + 'all transactions have positive age', + ); + // TODO: other checks like sync=false & sample rate? + + transactions.forEach((t) => { + // Remove variable and common fields to facilitate t.deepEqual below. + delete t.id; + delete t.parent_id; + delete t.trace_id; + delete t.timestamp; + delete t.duration; + delete t.sample_rate; + delete t.sampled; + delete t.span_count; + delete t.result; + delete t.context.user; + delete t.context.tags; + delete t.context.custom; + delete t.context.cloud; + delete t.context.message.age; + }); + + // Check message handling transactions + t.deepEqual(transactions.shift(), { + name: 'Kafka RECEIVE from elasticapmtest-topic-1234', + type: 'messaging', + context: { + service: {}, + message: { + queue: { name: 'elasticapmtest-topic-1234' }, + headers: { + foo: 'string', + traceparent: `00-${tx.trace_id}-${parentId}-01`, + tracestate: 'es=s:1', + }, + }, + }, + outcome: 'success', + }); + + t.deepEqual(transactions.shift(), { + name: 'Kafka RECEIVE from elasticapmtest-topic-1234', + type: 'messaging', + context: { + service: {}, + message: { + queue: { name: 'elasticapmtest-topic-1234' }, + headers: { + foo: 'buffer', + traceparent: `00-${tx.trace_id}-${parentId}-01`, + tracestate: 'es=s:1', + }, + }, + }, + outcome: 'success', + }); + + t.deepEqual(transactions.shift(), { + name: 'Kafka RECEIVE from elasticapmtest-topic-1234', + type: 'messaging', + context: { + service: {}, + message: { + queue: { name: 'elasticapmtest-topic-1234' }, + headers: { + traceparent: `00-${tx.trace_id}-${parentId}-01`, + tracestate: 'es=s:1', + }, + }, + }, + outcome: 'success', + }); + t.equal(transactions.length, 0, 'all transactions accounted for'); }, }, + // { + // name: 'simple Kafkajs usage scenario for batch message processing', + // script: 'fixtures/use-kafkajs-each-batch.js', + // cwd: __dirname, + // env: { + // TEST_CLIENT_ID: 'elastic-kafka-client', + // TEST_TOPIC: 'elasticapmtest-topic-5678', + // TEST_KAFKA_URL: kafkaUrl, + // }, + // checkApmServer(t, apmServer) { + // t.ok(apmServer.events[0].metadata, 'metadata'); + // const events = sortApmEvents(apmServer.events); + + // // Compare some common fields across all spans. + // // ignore http/external spans + // const spans = events + // .filter((e) => e.span && e.span.type !== 'external') + // .map((e) => e.span); + // spans.forEach((s) => { + // const errs = validateSpan(s); + // t.equal(errs, null, 'span is valid (per apm-server intake schema)'); + // }); + // }, + // }, ]; test('kafkajs fixtures', (suite) => { From 05f5622734d4a4081bc9a0d056b45fa1f6d15009 Mon Sep 17 00:00:00 2001 From: David Luna Date: Tue, 12 Dec 2023 13:57:13 +0100 Subject: [PATCH 16/58] chore: add batch tests --- lib/instrumentation/modules/kafkajs.js | 90 ++++++++++- .../modules/kafkajs/kafkajs.test.js | 150 +++++++++++++++--- 2 files changed, 207 insertions(+), 33 deletions(-) diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index 6e644723b8..36f350cdb8 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -241,6 +241,7 @@ module.exports = function (mod, agent, { version, enabled }) { const producer = origProducer.apply(this, arguments); shimmer.wrap(producer, 'send', wrapProducerSend); + shimmer.wrap(producer, 'sendBatch', wrapProducerSendBatch); return producer; }; } @@ -253,12 +254,6 @@ module.exports = function (mod, agent, { version, enabled }) { function wrapProducerSend(origSend) { return async function (record) { const { topic } = record; - - if (shouldIgnoreTopic(topic, config)) { - // TODO: ask trent about `contextPropagationOnly` - return origSend.apply(this, arguments); - } - const span = ins.createSpan( `${NAME} send to ${topic}`, TYPE, @@ -289,7 +284,7 @@ module.exports = function (mod, agent, { version, enabled }) { }); } - if (!span) { + if (!span || shouldIgnoreTopic(topic, config)) { return origSend.apply(this.arguments); } @@ -325,6 +320,87 @@ module.exports = function (mod, agent, { version, enabled }) { }; } + /** + * TODO: add comment + * @param {Producer['sendBatch']} origSendBatch + * @returns {Producer['sendBatch']} + */ + function wrapProducerSendBatch(origSendBatch) { + return async function (batch) { + const span = ins.createSpan( + `${NAME} send messages batch`, + TYPE, + SUBTYPE, + 'send', + { exitSpan: true }, + ); + + // W3C trace-context propagation. + const runContext = ins.currRunContext(); + const parentSpan = + span || runContext.currSpan() || runContext.currTransaction(); + + if (parentSpan && batch.topicMessages) { + batch.topicMessages.forEach((topicMessage) => { + topicMessage.messages.forEach((msg) => { + const newHeaders = Object.assign({}, msg.headers); + parentSpan.propagateTraceContextHeaders( + newHeaders, + function (carrier, name, value) { + // TODO: why doing it everywhere??? + if (name.startsWith('elastic-')) { + return; + } + carrier[name] = value; + }, + ); + msg.headers = newHeaders; + }); + }); + } + + // TODO: discuss this + const topics = + batch.topicMessages && batch.topicMessages.map((tm) => tm.topic); + const shouldIgnoreBatch = + topics && topics.every((t) => shouldIgnoreTopic(t, config)); + + if (!span || shouldIgnoreBatch) { + return origSendBatch.apply(this.arguments); + } + + // TODO: mabe set if only one topic or all messages for same topic (which is unlikely? + // span.setMessageContext({ queue: { name: topic } }); + + // TODO: same here about the topic + // const service = { + // resource: `${SUBTYPE}/${topic}`, + // type: SUBTYPE, + // name: topic, + // }; + + const service = { type: SUBTYPE }; + span._setDestinationContext({ service }); + + let result, err; + try { + result = await origSendBatch.apply(this, arguments); + } catch (ex) { + // Save the error for use in `finally` below, but re-throw it to + // not impact code flow. + err = ex; + throw ex; + } finally { + span.setOutcome( + err ? constants.OUTCOME_FAILURE : constants.OUTCOME_SUCCESS, + ); + span.end(); + } + + return result; + }; + } + /** * Returns true if we have to ignore messages on the given topic * @param {string} topic the topic where client is publishing/subscribing diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index 8f00fd89b1..e64b0893b3 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -32,14 +32,13 @@ const testFixtures = [ TEST_TOPIC: 'elasticapmtest-topic-1234', TEST_KAFKA_URL: kafkaUrl, }, - verbose: true, checkApmServer(t, apmServer) { t.ok(apmServer.events[0].metadata, 'metadata'); const events = sortApmEvents(apmServer.events); const tx = events.shift().transaction; // First the transaction. - t.ok(tx, 'got the transaction'); + t.ok(tx, 'got the send transaction'); // Compare some common fields across all spans. // ignore http/external spans @@ -148,6 +147,7 @@ const testFixtures = [ }); // Check message handling transactions + // TODO: messages may come with a different order??? t.deepEqual(transactions.shift(), { name: 'Kafka RECEIVE from elasticapmtest-topic-1234', type: 'messaging', @@ -200,30 +200,128 @@ const testFixtures = [ t.equal(transactions.length, 0, 'all transactions accounted for'); }, }, - // { - // name: 'simple Kafkajs usage scenario for batch message processing', - // script: 'fixtures/use-kafkajs-each-batch.js', - // cwd: __dirname, - // env: { - // TEST_CLIENT_ID: 'elastic-kafka-client', - // TEST_TOPIC: 'elasticapmtest-topic-5678', - // TEST_KAFKA_URL: kafkaUrl, - // }, - // checkApmServer(t, apmServer) { - // t.ok(apmServer.events[0].metadata, 'metadata'); - // const events = sortApmEvents(apmServer.events); - - // // Compare some common fields across all spans. - // // ignore http/external spans - // const spans = events - // .filter((e) => e.span && e.span.type !== 'external') - // .map((e) => e.span); - // spans.forEach((s) => { - // const errs = validateSpan(s); - // t.equal(errs, null, 'span is valid (per apm-server intake schema)'); - // }); - // }, - // }, + { + name: 'simple Kafkajs usage scenario for batch message processing', + script: 'fixtures/use-kafkajs-each-batch.js', + cwd: __dirname, + env: { + TEST_CLIENT_ID: 'elastic-kafka-client', + TEST_TOPIC: 'elasticapmtest-topic-5678', + TEST_KAFKA_URL: kafkaUrl, + }, + checkApmServer(t, apmServer) { + t.ok(apmServer.events[0].metadata, 'metadata'); + const events = sortApmEvents(apmServer.events); + const tx = events.shift().transaction; + + // First the transaction. + t.ok(tx, 'got the send batch transaction'); + + // Compare some common fields across all spans. + // ignore http/external spans + const spans = events.filter((e) => e.span).map((e) => e.span); + const spanId = spans[0].id; + spans.forEach((s) => { + const errs = validateSpan(s); + t.equal(errs, null, 'span is valid (per apm-server intake schema)'); + }); + t.equal( + spans.filter((s) => s.trace_id === tx.trace_id).length, + spans.length, + 'all spans have the same trace_id', + ); + t.equal( + spans.filter((s) => s.transaction_id === tx.id).length, + spans.length, + 'all spans have the same transaction_id', + ); + t.equal( + spans.filter((s) => s.sync === false).length, + spans.length, + 'all spans have sync=false', + ); + t.equal( + spans.filter((s) => s.sample_rate === 1).length, + spans.length, + 'all spans have sample_rate=1', + ); + + spans.forEach((s) => { + // Remove variable and common fields to facilitate t.deepEqual below. + delete s.id; + delete s.transaction_id; + delete s.parent_id; + delete s.trace_id; + delete s.timestamp; + delete s.duration; + delete s.sync; + delete s.sample_rate; + }); + + t.deepEqual(spans.shift(), { + name: 'Kafka send messages batch', + type: 'messaging', + subtype: 'kafka', + action: 'send', + context: { + service: { target: { type: 'kafka' } }, + destination: { service: { type: '', name: '', resource: 'kafka' } }, + }, + outcome: 'success', + }); + + t.equal(spans.length, 0, 'all spans accounted for'); + + // No check the transactions created for each message received + const transactions = events + .filter((e) => e.transaction) + .map((e) => e.transaction); + + // NOTE: no checks like prev test since there is only on span + + transactions.forEach((t) => { + // Remove variable and common fields to facilitate t.deepEqual below. + delete t.id; + delete t.parent_id; + delete t.trace_id; + delete t.timestamp; + delete t.duration; + delete t.sample_rate; + delete t.sampled; + delete t.span_count; + delete t.result; + delete t.context.user; + delete t.context.tags; + delete t.context.custom; + delete t.context.cloud; + }); + + // Check message handling transactions + t.deepEqual(transactions.shift(), { + name: 'Kafka RECEIVE from batch', + type: 'messaging', + context: { service: { framework: { name: 'Kafka' } }, message: {} }, + links: [ + { + trace_id: tx.trace_id, + span_id: spanId, + }, + { + trace_id: tx.trace_id, + span_id: spanId, + }, + { + trace_id: tx.trace_id, + span_id: spanId, + }, + ], + + outcome: 'success', + }); + + t.equal(transactions.length, 0, 'all transactions accounted for'); + }, + }, ]; test('kafkajs fixtures', (suite) => { From 644f2e96a333e66cd580d411d3265312b1b56bb2 Mon Sep 17 00:00:00 2001 From: David Luna Date: Tue, 12 Dec 2023 19:54:44 +0100 Subject: [PATCH 17/58] chore: add ignore message queues --- lib/instrumentation/modules/kafkajs.js | 55 ++-- .../fixtures/use-kafkajs-each-batch.js | 20 +- .../fixtures/use-kafkajs-each-message.js | 23 +- .../modules/kafkajs/kafkajs.test.js | 239 +++++++++--------- 4 files changed, 193 insertions(+), 144 deletions(-) diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index 36f350cdb8..a530d78131 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -40,7 +40,7 @@ module.exports = function (mod, agent, { version, enabled }) { return mod; } - const config = agent._config; + const config = agent._conf; const ins = agent._instrumentation; agent.logger.debug('shimming Kafka.prototype.consumer'); @@ -125,7 +125,10 @@ module.exports = function (mod, agent, { version, enabled }) { ); const messageCtx = { queue: { name: topic } }; - if (config.captureBody) { + if ( + config.captureBody === 'all' || + config.captureBody === 'transactions' + ) { messageCtx.body = message.value.toString(); } @@ -179,9 +182,17 @@ module.exports = function (mod, agent, { version, enabled }) { * @returns {ConsumerRunConfig['eachBatch']} */ function wrapEachBatch(origEachBatch) { - return async function (payload) { + return async function ({ batch }) { + if (shouldIgnoreTopic(batch.topic, config)) { + return origEachBatch.apply(this, arguments); + } + const trans = ins.startTransaction(`${NAME} RECEIVE from batch`, TYPE); + // TODO: not sure if this should be here but we gat batches for only one topic + const messageCtx = { queue: { name: batch.topic } }; + trans.setMessageContext(messageCtx); + const serviceContext = { framework: { name: 'Kafka' }, }; @@ -190,7 +201,7 @@ module.exports = function (mod, agent, { version, enabled }) { // Extract span links from up to 1000 messages in this batch. // https://github.com/elastic/apm/blob/main/specs/agents/tracing-instrumentation-messaging.md#receiving-trace-context // A span link is created from a `traceparent` header in a message. - const messages = payload && payload.batch && payload.batch.messages; + const messages = batch && batch.messages; if (messages) { const links = []; @@ -202,7 +213,7 @@ module.exports = function (mod, agent, { version, enabled }) { for (let i = 0; i < messages.length; i++) { const msg = messages[i]; if (msg.headers && msg.headers.traceparent) { - links.push({ context: msg.headers.traceparent.toString() }); // TODO: check this + links.push({ context: msg.headers.traceparent.toString() }); if (links.length >= limit) { break; @@ -285,7 +296,7 @@ module.exports = function (mod, agent, { version, enabled }) { } if (!span || shouldIgnoreTopic(topic, config)) { - return origSend.apply(this.arguments); + return origSend.apply(this, arguments); } // We do not add headers or body because: @@ -366,7 +377,7 @@ module.exports = function (mod, agent, { version, enabled }) { topics && topics.every((t) => shouldIgnoreTopic(t, config)); if (!span || shouldIgnoreBatch) { - return origSendBatch.apply(this.arguments); + return origSendBatch.apply(this, arguments); } // TODO: mabe set if only one topic or all messages for same topic (which is unlikely? @@ -400,22 +411,22 @@ module.exports = function (mod, agent, { version, enabled }) { return result; }; } +}; - /** - * Returns true if we have to ignore messages on the given topic - * @param {string} topic the topic where client is publishing/subscribing - * @param {any} config the agent's configuration object - * @returns {boolean} - */ - function shouldIgnoreTopic(topic, config) { - if (config.ignoreMessageQueuesRegExp) { - for (const rule of config.ignoreMessageQueuesRegExp) { - if (rule.test(topic)) { - return true; - } +/** + * Returns true if we have to ignore messages on the given topic + * @param {string} topic the topic where client is publishing/subscribing + * @param {{ ignoreMessageQueuesRegExp: RegExp[] }} config the agent's configuration object + * @returns {boolean} + */ +function shouldIgnoreTopic(topic, config) { + if (config.ignoreMessageQueuesRegExp) { + for (const rule of config.ignoreMessageQueuesRegExp) { + if (rule.test(topic)) { + return true; } } - - return false; } -}; + + return false; +} diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js index f9d3b58638..b968a206bc 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js @@ -14,6 +14,7 @@ const apm = require('../../../../..').start({ cloudProvider: 'none', stackTraceLimit: 4, // get it smaller for reviewing output logLevel: 'info', + ignoreMessageQueues: ['*-ignore'], }); const { Buffer } = require('buffer'); @@ -34,6 +35,7 @@ const TEST_TOPIC_PREFIX = 'elasticapmtest-topic-'; */ async function useKafkajsClient(kafkaClient, options) { const { topic, groupId } = options; + const topicToIgnore = `${topic}-ignore`; const log = apm.logger.child({ 'event.module': 'kafkajs', topic, @@ -46,18 +48,22 @@ async function useKafkajsClient(kafkaClient, options) { // Create the topics & subscribe await admin.connect(); await admin.createTopics({ - topics: [{ topic }], + topics: [{ topic }, { topic: topicToIgnore }], }); log.info('createTopics'); await producer.connect(); await consumer.connect(); - await consumer.subscribe({ topics: [topic], fromBeginning: true }); + await consumer.subscribe({ + topics: [topic, topicToIgnore], + fromBeginning: true, + }); log.info('all connected'); let batchMessagesConsumed = 0; await consumer.run({ eachBatch: async function ({ batch }) { + log.info(`batch received for topic: ${batch.topic}`); batch.messages.forEach((message) => { log.info(`batch message received: ${message.value.toString()}`); batchMessagesConsumed++; @@ -79,13 +85,21 @@ async function useKafkajsClient(kafkaClient, options) { { value: 'batch message 3' }, ], }, + { + topic: topicToIgnore, + messages: [ + { value: 'ignore message 1' }, + { value: 'ignore message 2' }, + { value: 'ignore message 3' }, + ], + }, ], }); batchTx.end(); log.info({ data }, 'batch sent'); try { - await waitUntil(() => batchMessagesConsumed >= 3, 5000); + await waitUntil(() => batchMessagesConsumed >= 6, 10000); } catch (err) { log.error(err, ' messages could not be consumed after 30s'); } diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js index 78f2667ab7..70b702c45b 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js @@ -14,10 +14,10 @@ const apm = require('../../../../..').start({ cloudProvider: 'none', stackTraceLimit: 4, // get it smaller for reviewing output logLevel: 'info', + ignoreMessageQueues: ['*-ignore'], }); const { Buffer } = require('buffer'); -const assert = require('assert'); const { Kafka } = require('kafkajs'); /** @type {import('kafkajs').Admin} */ @@ -35,6 +35,7 @@ const TEST_TOPIC_PREFIX = 'elasticapmtest-topic-'; */ async function useKafkajsClient(kafkaClient, options) { const { topic, groupId } = options; + const topicToIgnore = `${topic}-ignore`; const log = apm.logger.child({ 'event.module': 'kafkajs', topic, @@ -51,7 +52,10 @@ async function useKafkajsClient(kafkaClient, options) { await producer.connect(); await consumer.connect(); - await consumer.subscribe({ topics: [topic], fromBeginning: true }); + await consumer.subscribe({ + topics: [topic, topicToIgnore], + fromBeginning: true, + }); log.info('all connected'); let eachMessagesConsumed = 0; @@ -74,13 +78,22 @@ async function useKafkajsClient(kafkaClient, options) { { value: 'each message 3' }, ], }); - eachTx.end(); log.info({ data }, 'messages sent'); + data = await producer.send({ + topic: topicToIgnore, + messages: [ + { value: 'ignore message 1' }, + { value: 'ignore message 2' }, + { value: 'ignore message 3' }, + ], + }); + log.info({ data }, 'messages to ignore sent'); + eachTx.end(); try { - await waitUntil(() => eachMessagesConsumed >= 3, 5000); + await waitUntil(() => eachMessagesConsumed >= 6, 10000); } catch (err) { - log.error(err, ' messages could not be consumed after 30s'); + log.error(err, ' messages could not be consumed after 10s'); } await consumer.disconnect(); diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index e64b0893b3..a6a283e107 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -31,7 +31,9 @@ const testFixtures = [ TEST_CLIENT_ID: 'elastic-kafka-client', TEST_TOPIC: 'elasticapmtest-topic-1234', TEST_KAFKA_URL: kafkaUrl, + KAFKAJS_NO_PARTITIONER_WARNING: '1', }, + verbose: true, checkApmServer(t, apmServer) { t.ok(apmServer.events[0].metadata, 'metadata'); const events = sortApmEvents(apmServer.events); @@ -128,6 +130,13 @@ const testFixtures = [ ); // TODO: other checks like sync=false & sample rate? + // NOTE: messages could arrive in different order so we sort them + // to properly do the assertions + transactions.sort((t1, t2) => { + const header1 = t1.context.message.headers.foo || 'undefined'; + const header2 = t2.context.message.headers.foo || 'undefined'; + return header1 < header2 ? -1 : 1; + }); transactions.forEach((t) => { // Remove variable and common fields to facilitate t.deepEqual below. delete t.id; @@ -147,7 +156,6 @@ const testFixtures = [ }); // Check message handling transactions - // TODO: messages may come with a different order??? t.deepEqual(transactions.shift(), { name: 'Kafka RECEIVE from elasticapmtest-topic-1234', type: 'messaging', @@ -156,7 +164,7 @@ const testFixtures = [ message: { queue: { name: 'elasticapmtest-topic-1234' }, headers: { - foo: 'string', + foo: 'buffer', traceparent: `00-${tx.trace_id}-${parentId}-01`, tracestate: 'es=s:1', }, @@ -173,7 +181,7 @@ const testFixtures = [ message: { queue: { name: 'elasticapmtest-topic-1234' }, headers: { - foo: 'buffer', + foo: 'string', traceparent: `00-${tx.trace_id}-${parentId}-01`, tracestate: 'es=s:1', }, @@ -200,128 +208,131 @@ const testFixtures = [ t.equal(transactions.length, 0, 'all transactions accounted for'); }, }, - { - name: 'simple Kafkajs usage scenario for batch message processing', - script: 'fixtures/use-kafkajs-each-batch.js', - cwd: __dirname, - env: { - TEST_CLIENT_ID: 'elastic-kafka-client', - TEST_TOPIC: 'elasticapmtest-topic-5678', - TEST_KAFKA_URL: kafkaUrl, - }, - checkApmServer(t, apmServer) { - t.ok(apmServer.events[0].metadata, 'metadata'); - const events = sortApmEvents(apmServer.events); - const tx = events.shift().transaction; + // { + // name: 'simple Kafkajs usage scenario for batch message processing', + // script: 'fixtures/use-kafkajs-each-batch.js', + // cwd: __dirname, + // env: { + // TEST_CLIENT_ID: 'elastic-kafka-client', + // TEST_TOPIC: 'elasticapmtest-topic-5678', + // TEST_KAFKA_URL: kafkaUrl, + // KAFKAJS_NO_PARTITIONER_WARNING: '1', + // }, + // verbose: true, + // checkApmServer(t, apmServer) { + // t.ok(apmServer.events[0].metadata, 'metadata'); + // const events = sortApmEvents(apmServer.events); + // console.log(events); + // const tx = events.shift().transaction; - // First the transaction. - t.ok(tx, 'got the send batch transaction'); + // // First the transaction. + // t.ok(tx, 'got the send batch transaction'); - // Compare some common fields across all spans. - // ignore http/external spans - const spans = events.filter((e) => e.span).map((e) => e.span); - const spanId = spans[0].id; - spans.forEach((s) => { - const errs = validateSpan(s); - t.equal(errs, null, 'span is valid (per apm-server intake schema)'); - }); - t.equal( - spans.filter((s) => s.trace_id === tx.trace_id).length, - spans.length, - 'all spans have the same trace_id', - ); - t.equal( - spans.filter((s) => s.transaction_id === tx.id).length, - spans.length, - 'all spans have the same transaction_id', - ); - t.equal( - spans.filter((s) => s.sync === false).length, - spans.length, - 'all spans have sync=false', - ); - t.equal( - spans.filter((s) => s.sample_rate === 1).length, - spans.length, - 'all spans have sample_rate=1', - ); + // // Compare some common fields across all spans. + // // ignore http/external spans + // const spans = events.filter((e) => e.span).map((e) => e.span); + // const spanId = spans[0].id; + // spans.forEach((s) => { + // const errs = validateSpan(s); + // t.equal(errs, null, 'span is valid (per apm-server intake schema)'); + // }); + // t.equal( + // spans.filter((s) => s.trace_id === tx.trace_id).length, + // spans.length, + // 'all spans have the same trace_id', + // ); + // t.equal( + // spans.filter((s) => s.transaction_id === tx.id).length, + // spans.length, + // 'all spans have the same transaction_id', + // ); + // t.equal( + // spans.filter((s) => s.sync === false).length, + // spans.length, + // 'all spans have sync=false', + // ); + // t.equal( + // spans.filter((s) => s.sample_rate === 1).length, + // spans.length, + // 'all spans have sample_rate=1', + // ); - spans.forEach((s) => { - // Remove variable and common fields to facilitate t.deepEqual below. - delete s.id; - delete s.transaction_id; - delete s.parent_id; - delete s.trace_id; - delete s.timestamp; - delete s.duration; - delete s.sync; - delete s.sample_rate; - }); + // spans.forEach((s) => { + // // Remove variable and common fields to facilitate t.deepEqual below. + // delete s.id; + // delete s.transaction_id; + // delete s.parent_id; + // delete s.trace_id; + // delete s.timestamp; + // delete s.duration; + // delete s.sync; + // delete s.sample_rate; + // }); - t.deepEqual(spans.shift(), { - name: 'Kafka send messages batch', - type: 'messaging', - subtype: 'kafka', - action: 'send', - context: { - service: { target: { type: 'kafka' } }, - destination: { service: { type: '', name: '', resource: 'kafka' } }, - }, - outcome: 'success', - }); + // t.deepEqual(spans.shift(), { + // name: 'Kafka send messages batch', + // type: 'messaging', + // subtype: 'kafka', + // action: 'send', + // context: { + // service: { target: { type: 'kafka' } }, + // destination: { service: { type: '', name: '', resource: 'kafka' } }, + // }, + // outcome: 'success', + // }); - t.equal(spans.length, 0, 'all spans accounted for'); + // t.equal(spans.length, 0, 'all spans accounted for'); - // No check the transactions created for each message received - const transactions = events - .filter((e) => e.transaction) - .map((e) => e.transaction); + // // No check the transactions created for each message received + // const transactions = events + // .filter((e) => e.transaction) + // .map((e) => e.transaction); - // NOTE: no checks like prev test since there is only on span + // // NOTE: no checks like prev test since there is only on span - transactions.forEach((t) => { - // Remove variable and common fields to facilitate t.deepEqual below. - delete t.id; - delete t.parent_id; - delete t.trace_id; - delete t.timestamp; - delete t.duration; - delete t.sample_rate; - delete t.sampled; - delete t.span_count; - delete t.result; - delete t.context.user; - delete t.context.tags; - delete t.context.custom; - delete t.context.cloud; - }); + // transactions.forEach((t) => { + // // Remove variable and common fields to facilitate t.deepEqual below. + // delete t.id; + // delete t.parent_id; + // delete t.trace_id; + // delete t.timestamp; + // delete t.duration; + // delete t.sample_rate; + // delete t.sampled; + // delete t.span_count; + // delete t.result; + // delete t.context.user; + // delete t.context.tags; + // delete t.context.custom; + // delete t.context.cloud; + // }); - // Check message handling transactions - t.deepEqual(transactions.shift(), { - name: 'Kafka RECEIVE from batch', - type: 'messaging', - context: { service: { framework: { name: 'Kafka' } }, message: {} }, - links: [ - { - trace_id: tx.trace_id, - span_id: spanId, - }, - { - trace_id: tx.trace_id, - span_id: spanId, - }, - { - trace_id: tx.trace_id, - span_id: spanId, - }, - ], + // // Check message handling transactions + // t.deepEqual(transactions.shift(), { + // name: 'Kafka RECEIVE from batch', + // type: 'messaging', + // context: { service: { framework: { name: 'Kafka' } }, message: {} }, + // links: [ + // { + // trace_id: tx.trace_id, + // span_id: spanId, + // }, + // { + // trace_id: tx.trace_id, + // span_id: spanId, + // }, + // { + // trace_id: tx.trace_id, + // span_id: spanId, + // }, + // ], - outcome: 'success', - }); + // outcome: 'success', + // }); - t.equal(transactions.length, 0, 'all transactions accounted for'); - }, - }, + // t.equal(transactions.length, 0, 'all transactions accounted for'); + // }, + // }, ]; test('kafkajs fixtures', (suite) => { From ed9c6d1f889a89331f86130580a1926d12577955 Mon Sep 17 00:00:00 2001 From: David Luna Date: Tue, 12 Dec 2023 20:11:25 +0100 Subject: [PATCH 18/58] chore: finish batch handling --- .../modules/kafkajs/kafkajs.test.js | 234 +++++++++--------- 1 file changed, 119 insertions(+), 115 deletions(-) diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index a6a283e107..1662836b4b 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -31,9 +31,10 @@ const testFixtures = [ TEST_CLIENT_ID: 'elastic-kafka-client', TEST_TOPIC: 'elasticapmtest-topic-1234', TEST_KAFKA_URL: kafkaUrl, + // Suppres warinings about new default partitioner + // https://kafka.js.org/docs/migration-guide-v2.0.0#producer-new-default-partitioner KAFKAJS_NO_PARTITIONER_WARNING: '1', }, - verbose: true, checkApmServer(t, apmServer) { t.ok(apmServer.events[0].metadata, 'metadata'); const events = sortApmEvents(apmServer.events); @@ -208,131 +209,134 @@ const testFixtures = [ t.equal(transactions.length, 0, 'all transactions accounted for'); }, }, - // { - // name: 'simple Kafkajs usage scenario for batch message processing', - // script: 'fixtures/use-kafkajs-each-batch.js', - // cwd: __dirname, - // env: { - // TEST_CLIENT_ID: 'elastic-kafka-client', - // TEST_TOPIC: 'elasticapmtest-topic-5678', - // TEST_KAFKA_URL: kafkaUrl, - // KAFKAJS_NO_PARTITIONER_WARNING: '1', - // }, - // verbose: true, - // checkApmServer(t, apmServer) { - // t.ok(apmServer.events[0].metadata, 'metadata'); - // const events = sortApmEvents(apmServer.events); - // console.log(events); - // const tx = events.shift().transaction; + { + name: 'simple Kafkajs usage scenario for batch message processing', + script: 'fixtures/use-kafkajs-each-batch.js', + cwd: __dirname, + env: { + TEST_CLIENT_ID: 'elastic-kafka-client', + TEST_TOPIC: 'elasticapmtest-topic-5678', + TEST_KAFKA_URL: kafkaUrl, + // Suppres warinings about new default partitioner + // https://kafka.js.org/docs/migration-guide-v2.0.0#producer-new-default-partitioner + KAFKAJS_NO_PARTITIONER_WARNING: '1', + }, + checkApmServer(t, apmServer) { + t.ok(apmServer.events[0].metadata, 'metadata'); + const events = sortApmEvents(apmServer.events); + const tx = events.shift().transaction; - // // First the transaction. - // t.ok(tx, 'got the send batch transaction'); + // First the transaction. + t.ok(tx, 'got the send batch transaction'); - // // Compare some common fields across all spans. - // // ignore http/external spans - // const spans = events.filter((e) => e.span).map((e) => e.span); - // const spanId = spans[0].id; - // spans.forEach((s) => { - // const errs = validateSpan(s); - // t.equal(errs, null, 'span is valid (per apm-server intake schema)'); - // }); - // t.equal( - // spans.filter((s) => s.trace_id === tx.trace_id).length, - // spans.length, - // 'all spans have the same trace_id', - // ); - // t.equal( - // spans.filter((s) => s.transaction_id === tx.id).length, - // spans.length, - // 'all spans have the same transaction_id', - // ); - // t.equal( - // spans.filter((s) => s.sync === false).length, - // spans.length, - // 'all spans have sync=false', - // ); - // t.equal( - // spans.filter((s) => s.sample_rate === 1).length, - // spans.length, - // 'all spans have sample_rate=1', - // ); + // Compare some common fields across all spans. + // ignore http/external spans + const spans = events.filter((e) => e.span).map((e) => e.span); + const spanId = spans[0].id; + spans.forEach((s) => { + const errs = validateSpan(s); + t.equal(errs, null, 'span is valid (per apm-server intake schema)'); + }); + t.equal( + spans.filter((s) => s.trace_id === tx.trace_id).length, + spans.length, + 'all spans have the same trace_id', + ); + t.equal( + spans.filter((s) => s.transaction_id === tx.id).length, + spans.length, + 'all spans have the same transaction_id', + ); + t.equal( + spans.filter((s) => s.sync === false).length, + spans.length, + 'all spans have sync=false', + ); + t.equal( + spans.filter((s) => s.sample_rate === 1).length, + spans.length, + 'all spans have sample_rate=1', + ); - // spans.forEach((s) => { - // // Remove variable and common fields to facilitate t.deepEqual below. - // delete s.id; - // delete s.transaction_id; - // delete s.parent_id; - // delete s.trace_id; - // delete s.timestamp; - // delete s.duration; - // delete s.sync; - // delete s.sample_rate; - // }); + spans.forEach((s) => { + // Remove variable and common fields to facilitate t.deepEqual below. + delete s.id; + delete s.transaction_id; + delete s.parent_id; + delete s.trace_id; + delete s.timestamp; + delete s.duration; + delete s.sync; + delete s.sample_rate; + }); - // t.deepEqual(spans.shift(), { - // name: 'Kafka send messages batch', - // type: 'messaging', - // subtype: 'kafka', - // action: 'send', - // context: { - // service: { target: { type: 'kafka' } }, - // destination: { service: { type: '', name: '', resource: 'kafka' } }, - // }, - // outcome: 'success', - // }); + t.deepEqual(spans.shift(), { + name: 'Kafka send messages batch', + type: 'messaging', + subtype: 'kafka', + action: 'send', + context: { + service: { target: { type: 'kafka' } }, + destination: { service: { type: '', name: '', resource: 'kafka' } }, + }, + outcome: 'success', + }); - // t.equal(spans.length, 0, 'all spans accounted for'); + t.equal(spans.length, 0, 'all spans accounted for'); - // // No check the transactions created for each message received - // const transactions = events - // .filter((e) => e.transaction) - // .map((e) => e.transaction); + // No check the transactions created for each message received + const transactions = events + .filter((e) => e.transaction) + .map((e) => e.transaction); - // // NOTE: no checks like prev test since there is only on span + // NOTE: no checks like prev test since there is only on span - // transactions.forEach((t) => { - // // Remove variable and common fields to facilitate t.deepEqual below. - // delete t.id; - // delete t.parent_id; - // delete t.trace_id; - // delete t.timestamp; - // delete t.duration; - // delete t.sample_rate; - // delete t.sampled; - // delete t.span_count; - // delete t.result; - // delete t.context.user; - // delete t.context.tags; - // delete t.context.custom; - // delete t.context.cloud; - // }); + transactions.forEach((t) => { + // Remove variable and common fields to facilitate t.deepEqual below. + delete t.id; + delete t.parent_id; + delete t.trace_id; + delete t.timestamp; + delete t.duration; + delete t.sample_rate; + delete t.sampled; + delete t.span_count; + delete t.result; + delete t.context.user; + delete t.context.tags; + delete t.context.custom; + delete t.context.cloud; + }); - // // Check message handling transactions - // t.deepEqual(transactions.shift(), { - // name: 'Kafka RECEIVE from batch', - // type: 'messaging', - // context: { service: { framework: { name: 'Kafka' } }, message: {} }, - // links: [ - // { - // trace_id: tx.trace_id, - // span_id: spanId, - // }, - // { - // trace_id: tx.trace_id, - // span_id: spanId, - // }, - // { - // trace_id: tx.trace_id, - // span_id: spanId, - // }, - // ], + // Check message handling transactions + t.deepEqual(transactions.shift(), { + name: 'Kafka RECEIVE from batch', + type: 'messaging', + context: { + service: { framework: { name: 'Kafka' } }, + message: { queue: { name: 'elasticapmtest-topic-5678' } }, + }, + links: [ + { + trace_id: tx.trace_id, + span_id: spanId, + }, + { + trace_id: tx.trace_id, + span_id: spanId, + }, + { + trace_id: tx.trace_id, + span_id: spanId, + }, + ], - // outcome: 'success', - // }); + outcome: 'success', + }); - // t.equal(transactions.length, 0, 'all transactions accounted for'); - // }, - // }, + t.equal(transactions.length, 0, 'all transactions accounted for'); + }, + }, ]; test('kafkajs fixtures', (suite) => { From 270a8e46165c11c5bbdab86a0cbf265be032aa65 Mon Sep 17 00:00:00 2001 From: David Luna Date: Tue, 12 Dec 2023 21:14:39 +0100 Subject: [PATCH 19/58] chore: update .tav.yml --- .tav.yml | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/.tav.yml b/.tav.yml index 113dc6aa67..7cc1a046a3 100644 --- a/.tav.yml +++ b/.tav.yml @@ -590,3 +590,10 @@ undici: mode: max-5 include: '>=4.7.1 <6' +kafkajs: + name: kafkajs + versions: '2.0.0 || 2.0.2 || 2.1.0 || ^2.2.4' + commands: node test/instrumentation/modules/kafkajs/kafkajs.test.js + update-versions: + mode: latest-minors + include: '>=2 <3' From 2950918a7b701e63988ac5f0a5d2a3ba466e8550 Mon Sep 17 00:00:00 2001 From: David Luna Date: Tue, 12 Dec 2023 21:39:02 +0100 Subject: [PATCH 20/58] chore: update tav.json and test script --- .ci/scripts/test.sh | 3 +++ .ci/tav.json | 3 ++- 2 files changed, 5 insertions(+), 1 deletion(-) diff --git a/.ci/scripts/test.sh b/.ci/scripts/test.sh index 0f50b229b4..f60b1833d5 100755 --- a/.ci/scripts/test.sh +++ b/.ci/scripts/test.sh @@ -216,6 +216,9 @@ elif [[ -n "${TAV_MODULE}" ]]; then aws-sdk|@aws-sdk/client-s3|@aws-sdk/client-dynamodb|@aws-sdk/client-sns|@aws-sdk/client-sqs) DOCKER_COMPOSE_FILE=docker-compose-localstack.yml ;; + kafkajs) + DOCKER_COMPOSE_FILE=docker-compose-kafka.yml + ;; *) # Just the "node_tests" container. No additional services needed for testing. DOCKER_COMPOSE_FILE=docker-compose-node-test.yml diff --git a/.ci/tav.json b/.ci/tav.json index 769e83108a..41f84847d6 100644 --- a/.ci/tav.json +++ b/.ci/tav.json @@ -40,6 +40,7 @@ { "name": "ws", "minMajorVersion": 8 }, { "name": "@koa/router,koa-router", "minMajorVersion": 8 }, { "name": "handlebars,pug", "minMajorVersion": 8 }, - { "name": "bluebird,got", "minMajorVersion": 8 } + { "name": "bluebird,got", "minMajorVersion": 8 }, + { "name": "kafkajs", "minMajorVersion": 14 } ] } From d58f3272a98817694f63db3d24a535f362b2bfeb Mon Sep 17 00:00:00 2001 From: David Luna Date: Tue, 12 Dec 2023 22:00:32 +0100 Subject: [PATCH 21/58] chore: update test action --- .github/workflows/test.yml | 26 ++++++++++++++++++++++++++ 1 file changed, 26 insertions(+) diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 8ac3339afe..89a0dfb100 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -122,6 +122,32 @@ jobs: volumes: - nodelocalstackdata:/var/lib/localstack + zookeeper: + # https://hub.docker.com/r/bitnami/zookeeper/tags + image: bitnami/zookeeper:3.9.1 + env: + ALLOW_ANONYMOUS_LOGIN: 'yes' + ports: + - "2181:2181" + volumes: + - nodezookeeperdata:/var/lib/zookeeper/data + + kafka: + # https://hub.docker.com/r/bitnami/kafka/tags + image: bitnami/kafka:3.3.2 + ports: + - "9093:9093" + volumes: + - nodekafkadata:/var/lib/kafka/data + env: + KAFKA_BROKER_ID: '1' + KAFKA_CFG_ZOOKEEPER_CONNECT: 'zookeeper:2181' + ALLOW_PLAINTEXT_LISTENER: 'yes' + KAFKA_CFG_LISTENER_SECURITY_PROTOCOL_MAP: 'CLIENT:PLAINTEXT,EXTERNAL:PLAINTEXT' + KAFKA_CFG_LISTENERS: 'CLIENT://:9092,EXTERNAL://:9093' + KAFKA_CFG_ADVERTISED_LISTENERS: 'CLIENT://kafka:9092,EXTERNAL://localhost:9093' + KAFKA_CFG_INTER_BROKER_LISTENER_NAME: 'CLIENT' + strategy: fail-fast: false matrix: From 92ba96932c96154812006b30f6dcb788270eed70 Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 09:53:02 +0100 Subject: [PATCH 22/58] chore: log stdout in kafkajs tests --- test/instrumentation/modules/kafkajs/kafkajs.test.js | 2 ++ 1 file changed, 2 insertions(+) diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index 1662836b4b..695d3ee496 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -35,6 +35,7 @@ const testFixtures = [ // https://kafka.js.org/docs/migration-guide-v2.0.0#producer-new-default-partitioner KAFKAJS_NO_PARTITIONER_WARNING: '1', }, + verbose: true, checkApmServer(t, apmServer) { t.ok(apmServer.events[0].metadata, 'metadata'); const events = sortApmEvents(apmServer.events); @@ -221,6 +222,7 @@ const testFixtures = [ // https://kafka.js.org/docs/migration-guide-v2.0.0#producer-new-default-partitioner KAFKAJS_NO_PARTITIONER_WARNING: '1', }, + verbose: true, checkApmServer(t, apmServer) { t.ok(apmServer.events[0].metadata, 'metadata'); const events = sortApmEvents(apmServer.events); From 8b0980286a14511b4fd8a71a17d1dfb3bbb6e187 Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 10:08:37 +0100 Subject: [PATCH 23/58] chore: add node version in topic names --- .../modules/kafkajs/kafkajs.test.js | 30 +++++++++++-------- 1 file changed, 17 insertions(+), 13 deletions(-) diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index 695d3ee496..bf156e13fc 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -21,6 +21,10 @@ const { runTestFixtures, sortApmEvents } = require('../../../_utils'); const kafkaUrl = process.env.KAFKA_URL || 'localhost:9093'; +const version = process.version.replace(/\./g, '-'); +const topicEach = `elasticapmtest-topic-each-${version}`; +const topicBatch = `elasticapmtest-topic-batch-${version}`; + /** @type {import('../../../_utils').TestFixture[]} */ const testFixtures = [ { @@ -29,7 +33,7 @@ const testFixtures = [ cwd: __dirname, env: { TEST_CLIENT_ID: 'elastic-kafka-client', - TEST_TOPIC: 'elasticapmtest-topic-1234', + TEST_TOPIC: topicEach, TEST_KAFKA_URL: kafkaUrl, // Suppres warinings about new default partitioner // https://kafka.js.org/docs/migration-guide-v2.0.0#producer-new-default-partitioner @@ -85,22 +89,22 @@ const testFixtures = [ }); t.deepEqual(spans.shift(), { - name: 'Kafka send to elasticapmtest-topic-1234', + name: `Kafka send to ${topicEach}`, type: 'messaging', subtype: 'kafka', action: 'send', context: { service: { - target: { type: 'kafka', name: 'elasticapmtest-topic-1234' }, + target: { type: 'kafka', name: topicEach }, }, destination: { service: { - resource: 'kafka/elasticapmtest-topic-1234', + resource: `kafka/${topicEach}`, type: '', name: '', }, }, - message: { queue: { name: 'elasticapmtest-topic-1234' } }, + message: { queue: { name: topicEach } }, }, outcome: 'success', }); @@ -159,12 +163,12 @@ const testFixtures = [ // Check message handling transactions t.deepEqual(transactions.shift(), { - name: 'Kafka RECEIVE from elasticapmtest-topic-1234', + name: `Kafka RECEIVE from ${topicEach}`, type: 'messaging', context: { service: {}, message: { - queue: { name: 'elasticapmtest-topic-1234' }, + queue: { name: topicEach }, headers: { foo: 'buffer', traceparent: `00-${tx.trace_id}-${parentId}-01`, @@ -176,12 +180,12 @@ const testFixtures = [ }); t.deepEqual(transactions.shift(), { - name: 'Kafka RECEIVE from elasticapmtest-topic-1234', + name: `Kafka RECEIVE from ${topicEach}`, type: 'messaging', context: { service: {}, message: { - queue: { name: 'elasticapmtest-topic-1234' }, + queue: { name: topicEach }, headers: { foo: 'string', traceparent: `00-${tx.trace_id}-${parentId}-01`, @@ -193,12 +197,12 @@ const testFixtures = [ }); t.deepEqual(transactions.shift(), { - name: 'Kafka RECEIVE from elasticapmtest-topic-1234', + name: `Kafka RECEIVE from ${topicEach}`, type: 'messaging', context: { service: {}, message: { - queue: { name: 'elasticapmtest-topic-1234' }, + queue: { name: topicEach }, headers: { traceparent: `00-${tx.trace_id}-${parentId}-01`, tracestate: 'es=s:1', @@ -216,7 +220,7 @@ const testFixtures = [ cwd: __dirname, env: { TEST_CLIENT_ID: 'elastic-kafka-client', - TEST_TOPIC: 'elasticapmtest-topic-5678', + TEST_TOPIC: topicBatch, TEST_KAFKA_URL: kafkaUrl, // Suppres warinings about new default partitioner // https://kafka.js.org/docs/migration-guide-v2.0.0#producer-new-default-partitioner @@ -316,7 +320,7 @@ const testFixtures = [ type: 'messaging', context: { service: { framework: { name: 'Kafka' } }, - message: { queue: { name: 'elasticapmtest-topic-5678' } }, + message: { queue: { name: topicBatch } }, }, links: [ { From c00cb4a03256b6c0617ef1b4dde239228918eaf5 Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 10:25:44 +0100 Subject: [PATCH 24/58] chore: add node version in group id --- test/instrumentation/modules/kafkajs/kafkajs.test.js | 2 ++ 1 file changed, 2 insertions(+) diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index bf156e13fc..52021477c6 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -33,6 +33,7 @@ const testFixtures = [ cwd: __dirname, env: { TEST_CLIENT_ID: 'elastic-kafka-client', + TEST_GROUP_ID: `elastictest-kafka-group-${version}`, TEST_TOPIC: topicEach, TEST_KAFKA_URL: kafkaUrl, // Suppres warinings about new default partitioner @@ -220,6 +221,7 @@ const testFixtures = [ cwd: __dirname, env: { TEST_CLIENT_ID: 'elastic-kafka-client', + TEST_GROUP_ID: `elastictest-kafka-group-${version}`, TEST_TOPIC: topicBatch, TEST_KAFKA_URL: kafkaUrl, // Suppres warinings about new default partitioner From 1608746dd5f4d560d1637875c87b899685b197c6 Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 10:50:20 +0100 Subject: [PATCH 25/58] chore: add checkScriptResult --- .../modules/kafkajs/fixtures/use-kafkajs-each-batch.js | 2 +- .../modules/kafkajs/fixtures/use-kafkajs-each-message.js | 2 +- test/instrumentation/modules/kafkajs/kafkajs.test.js | 4 ++++ 3 files changed, 6 insertions(+), 2 deletions(-) diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js index b968a206bc..fa201fb15e 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js @@ -106,7 +106,7 @@ async function useKafkajsClient(kafkaClient, options) { await consumer.disconnect(); await producer.disconnect(); - await admin.deleteTopics({ topics: [topic] }); + await admin.deleteTopics({ topics: [topic, topicToIgnore] }); await admin.disconnect(); } diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js index 70b702c45b..cb4c31f948 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js @@ -98,7 +98,7 @@ async function useKafkajsClient(kafkaClient, options) { await consumer.disconnect(); await producer.disconnect(); - await admin.deleteTopics({ topics: [topic] }); + await admin.deleteTopics({ topics: [topic, topicToIgnore] }); await admin.disconnect(); } diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index 52021477c6..8b0f99c8f4 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -41,6 +41,10 @@ const testFixtures = [ KAFKAJS_NO_PARTITIONER_WARNING: '1', }, verbose: true, + checkScriptResult(t, err, stdout, stderr) { + console.log('checkScriptResult err', err); + t.error(err, `script exited successfully: err=${err}`); + }, checkApmServer(t, apmServer) { t.ok(apmServer.events[0].metadata, 'metadata'); const events = sortApmEvents(apmServer.events); From b8bde4efa3781703bf5f7a1c101cfff8fcd1b8f8 Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 10:57:31 +0100 Subject: [PATCH 26/58] chore: add waitForLeaders in topic creation --- .../modules/kafkajs/fixtures/use-kafkajs-each-batch.js | 1 + .../modules/kafkajs/fixtures/use-kafkajs-each-message.js | 5 ++++- 2 files changed, 5 insertions(+), 1 deletion(-) diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js index fa201fb15e..b56d5f8f5e 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js @@ -48,6 +48,7 @@ async function useKafkajsClient(kafkaClient, options) { // Create the topics & subscribe await admin.connect(); await admin.createTopics({ + waitForLeaders: true, topics: [{ topic }, { topic: topicToIgnore }], }); log.info('createTopics'); diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js index cb4c31f948..c2b9f5b507 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js @@ -47,7 +47,10 @@ async function useKafkajsClient(kafkaClient, options) { // Create the topics & subscribe await admin.connect(); - await admin.createTopics({ topics: [{ topic }] }); + await admin.createTopics({ + waitForLeaders: true, + topics: [{ topic, topicToIgnore }], + }); log.info('topic created'); await producer.connect(); From 9443a6c27793017a20848ab4376cc1ea87c8a6f4 Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 13:17:38 +0100 Subject: [PATCH 27/58] chore: add more logs --- test/_utils.js | 3 ++- .../modules/kafkajs/fixtures/use-kafkajs-each-batch.js | 1 + .../modules/kafkajs/fixtures/use-kafkajs-each-message.js | 1 + 3 files changed, 4 insertions(+), 1 deletion(-) diff --git a/test/_utils.js b/test/_utils.js index 1f5699bdfb..8ed7c2f12a 100644 --- a/test/_utils.js +++ b/test/_utils.js @@ -313,7 +313,7 @@ function runTestFixtures(suite, testFixtures) { ); } const start = Date.now(); - execFile( + const proc = execFile( process.execPath, argv, { @@ -332,6 +332,7 @@ function runTestFixtures(suite, testFixtures) { }, async function done(err, stdout, stderr) { if (tf.verbose) { + t.comment(`exitCode: ${proc.exitCode}`); t.comment(`elapsed: ${(Date.now() - start) / 1000}s`); if (err) { t.comment(`err:\n|${formatForTComment(err)}`); diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js index b56d5f8f5e..5301adf95a 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js @@ -161,6 +161,7 @@ function main() { useKafkajsClient(kafkaClient, { topic, groupId }).then( function () { + apm.logger.info('useKafkajsClient resolved'); process.exitCode = 0; }, function (err) { diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js index c2b9f5b507..abf502f472 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js @@ -155,6 +155,7 @@ function main() { useKafkajsClient(kafkaClient, { topic, groupId }).then( function () { + apm.logger.info('useKafkajsClient resolved'); process.exitCode = 0; }, function (err) { From e020d16beb69b151410a22e8961daf4e93039e34 Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 13:42:25 +0100 Subject: [PATCH 28/58] chore: remove custom check --- test/_utils.js | 3 +-- .../fixtures/use-kafkajs-each-batch.js | 20 ++++++++++++++++++- .../fixtures/use-kafkajs-each-message.js | 20 ++++++++++++++++++- .../modules/kafkajs/kafkajs.test.js | 4 ---- 4 files changed, 39 insertions(+), 8 deletions(-) diff --git a/test/_utils.js b/test/_utils.js index 8ed7c2f12a..1f5699bdfb 100644 --- a/test/_utils.js +++ b/test/_utils.js @@ -313,7 +313,7 @@ function runTestFixtures(suite, testFixtures) { ); } const start = Date.now(); - const proc = execFile( + execFile( process.execPath, argv, { @@ -332,7 +332,6 @@ function runTestFixtures(suite, testFixtures) { }, async function done(err, stdout, stderr) { if (tf.verbose) { - t.comment(`exitCode: ${proc.exitCode}`); t.comment(`elapsed: ${(Date.now() - start) / 1000}s`); if (err) { t.comment(`err:\n|${formatForTComment(err)}`); diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js index 5301adf95a..263182da7a 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js @@ -113,6 +113,18 @@ async function useKafkajsClient(kafkaClient, options) { // ---- helper functions +/** + * Creates logger functions for KafkaJS + * @param {string} loglevel + * @returns {(log: any) => void} + */ +function apmKafkaLogger(logLevel) { + const method = logLevel === 'ERROR' ? 'error' : 'info'; + return function (log) { + apm.logger[method](log); + }; +} + /** * Retuns a promise which is resolved when the predicate becomes true or rejected * if the timeout is reached. @@ -157,7 +169,13 @@ function main() { ); } - const kafkaClient = new Kafka({ clientId, brokers: [broker] }); + const kafkaClient = new Kafka({ + clientId, + brokers: [broker], + // To avoid prints directly on stderr + // https://kafka.js.org/docs/custom-logger + logCreator: apmKafkaLogger, + }); useKafkajsClient(kafkaClient, { topic, groupId }).then( function () { diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js index abf502f472..2832dbf9f7 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js @@ -107,6 +107,18 @@ async function useKafkajsClient(kafkaClient, options) { // ---- helper functions +/** + * Creates logger functions for KafkaJS + * @param {string} loglevel + * @returns {(log: any) => void} + */ +function apmKafkaLogger(logLevel) { + const method = logLevel === 'ERROR' ? 'error' : 'info'; + return function (log) { + apm.logger[method](log); + }; +} + /** * Retuns a promise which is resolved when the predicate becomes true or rejected * if the timeout is reached. @@ -151,7 +163,13 @@ function main() { ); } - const kafkaClient = new Kafka({ clientId, brokers: [broker] }); + const kafkaClient = new Kafka({ + clientId, + brokers: [broker], + // To avoid prints directly on stderr + // https://kafka.js.org/docs/custom-logger + logCreator: apmKafkaLogger, + }); useKafkajsClient(kafkaClient, { topic, groupId }).then( function () { diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index 8b0f99c8f4..52021477c6 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -41,10 +41,6 @@ const testFixtures = [ KAFKAJS_NO_PARTITIONER_WARNING: '1', }, verbose: true, - checkScriptResult(t, err, stdout, stderr) { - console.log('checkScriptResult err', err); - t.error(err, `script exited successfully: err=${err}`); - }, checkApmServer(t, apmServer) { t.ok(apmServer.events[0].metadata, 'metadata'); const events = sortApmEvents(apmServer.events); From c369dd307936b70340d9c4cbf7c8b32621c0ccfa Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 13:57:00 +0100 Subject: [PATCH 29/58] chore: add err logs --- test/_utils.js | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/test/_utils.js b/test/_utils.js index 1f5699bdfb..178af4f623 100644 --- a/test/_utils.js +++ b/test/_utils.js @@ -352,6 +352,11 @@ function runTestFixtures(suite, testFixtures) { } else { t.error(err, `${tf.script} exited successfully: err=${err}`); if (err) { + console.log(err.name); + console.log(err.fileName); + console.log(err.lineNumber); + console.log(err.stack); + console.log(err); if (!tf.verbose) { t.comment(`stdout:\n|${formatForTComment(stdout)}`); t.comment(`stderr:\n|${formatForTComment(stderr)}`); From 1e1a31e2d61608d5f9383f419c63cc6e29d07c5d Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 14:13:59 +0100 Subject: [PATCH 30/58] chore: add disconnect logs --- .../modules/kafkajs/fixtures/use-kafkajs-each-batch.js | 5 +++++ .../modules/kafkajs/fixtures/use-kafkajs-each-message.js | 5 +++++ 2 files changed, 10 insertions(+) diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js index 263182da7a..c015d607d0 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js @@ -101,14 +101,19 @@ async function useKafkajsClient(kafkaClient, options) { try { await waitUntil(() => batchMessagesConsumed >= 6, 10000); + log.info('messages consumed'); } catch (err) { log.error(err, ' messages could not be consumed after 30s'); } await consumer.disconnect(); + log.info('consumer disconnect'); await producer.disconnect(); + log.info('producer disconnect'); await admin.deleteTopics({ topics: [topic, topicToIgnore] }); + log.info('topics deleted'); await admin.disconnect(); + log.info('admin disconnect'); } // ---- helper functions diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js index 2832dbf9f7..eb8aea6c32 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js @@ -95,14 +95,19 @@ async function useKafkajsClient(kafkaClient, options) { try { await waitUntil(() => eachMessagesConsumed >= 6, 10000); + log.info('messages consumed'); } catch (err) { log.error(err, ' messages could not be consumed after 10s'); } await consumer.disconnect(); + log.info('consumer disconnect'); await producer.disconnect(); + log.info('producer disconnect'); await admin.deleteTopics({ topics: [topic, topicToIgnore] }); + log.info('topics deleted'); await admin.disconnect(); + log.info('admin disconnect'); } // ---- helper functions From da8e78960fc80f418d94476ba7fa81c336c64e17 Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 14:46:53 +0100 Subject: [PATCH 31/58] chore: enable delete topics --- .ci/docker/docker-compose.yml | 1 + .github/workflows/test.yml | 1 + test/docker-compose.yml | 1 + 3 files changed, 3 insertions(+) diff --git a/.ci/docker/docker-compose.yml b/.ci/docker/docker-compose.yml index db1a2584c3..0f8c3119e5 100644 --- a/.ci/docker/docker-compose.yml +++ b/.ci/docker/docker-compose.yml @@ -167,6 +167,7 @@ services: - KAFKA_CFG_LISTENERS=CLIENT://:9092,EXTERNAL://:9093 - KAFKA_CFG_ADVERTISED_LISTENERS=CLIENT://kafka:9092,EXTERNAL://localhost:9093 - KAFKA_CFG_INTER_BROKER_LISTENER_NAME=CLIENT + - KAFKA_CFG_DELETE_TOPIC_ENABLE=true depends_on: - zookeeper diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 89a0dfb100..ee247c4195 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -147,6 +147,7 @@ jobs: KAFKA_CFG_LISTENERS: 'CLIENT://:9092,EXTERNAL://:9093' KAFKA_CFG_ADVERTISED_LISTENERS: 'CLIENT://kafka:9092,EXTERNAL://localhost:9093' KAFKA_CFG_INTER_BROKER_LISTENER_NAME: 'CLIENT' + KAFKA_CFG_DELETE_TOPIC_ENABLE: 'true' strategy: fail-fast: false diff --git a/test/docker-compose.yml b/test/docker-compose.yml index 1fb4303bdf..91ac67a42f 100644 --- a/test/docker-compose.yml +++ b/test/docker-compose.yml @@ -157,6 +157,7 @@ services: - KAFKA_CFG_LISTENERS=CLIENT://:9092,EXTERNAL://:9093 - KAFKA_CFG_ADVERTISED_LISTENERS=CLIENT://kafka:9092,EXTERNAL://localhost:9093 - KAFKA_CFG_INTER_BROKER_LISTENER_NAME=CLIENT + - KAFKA_CFG_DELETE_TOPIC_ENABLE=true depends_on: - zookeeper From 80cb347ec4b5673f54101fb1edf1bf0cb65c0746 Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 15:49:34 +0100 Subject: [PATCH 32/58] chore: remove comments --- .github/workflows/test.yml | 19 ++++++++++--------- test/_utils.js | 5 ----- 2 files changed, 10 insertions(+), 14 deletions(-) diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index ee247c4195..ab842cd050 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -154,15 +154,16 @@ jobs: matrix: node: - '21' - - '21.0' - - '20' - - '20.0' - - '18.18.2' # Skip >=18.19.0 until IITM double-import issue is resolved. - - '18.0' - - '16' - - '16.0' - - '14' - - '14.17' + # XXX: Omit for now to avoid consuming too many resources + # - '21.0' + # - '20' + # - '20.0' + # - '18.18.2' # Skip >=18.19.0 until IITM double-import issue is resolved. + # - '18.0' + # - '16' + # - '16.0' + # - '14' + # - '14.17' runs-on: ubuntu-latest steps: - uses: actions/checkout@v4 diff --git a/test/_utils.js b/test/_utils.js index 178af4f623..1f5699bdfb 100644 --- a/test/_utils.js +++ b/test/_utils.js @@ -352,11 +352,6 @@ function runTestFixtures(suite, testFixtures) { } else { t.error(err, `${tf.script} exited successfully: err=${err}`); if (err) { - console.log(err.name); - console.log(err.fileName); - console.log(err.lineNumber); - console.log(err.stack); - console.log(err); if (!tf.verbose) { t.comment(`stdout:\n|${formatForTComment(stdout)}`); t.comment(`stderr:\n|${formatForTComment(stderr)}`); From cbd2bc4363dd866a92c14c600175c14dce62f24d Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 16:03:40 +0100 Subject: [PATCH 33/58] chore: add node version to test --- .github/workflows/test.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index ab842cd050..6a4ab780d4 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -154,8 +154,8 @@ jobs: matrix: node: - '21' + - '21.0' # XXX: Omit for now to avoid consuming too many resources - # - '21.0' # - '20' # - '20.0' # - '18.18.2' # Skip >=18.19.0 until IITM double-import issue is resolved. From 8c093ab4dd0f180b658a6eec080f1d86546bc2d3 Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 16:19:35 +0100 Subject: [PATCH 34/58] chore: add logs --- test/test.js | 3 +++ 1 file changed, 3 insertions(+) diff --git a/test/test.js b/test/test.js index ab148e859a..f0f5af816d 100644 --- a/test/test.js +++ b/test/test.js @@ -51,6 +51,9 @@ function runTestFile(test, cb) { stdio: ['inherit', outFile, outFile], }); ps.on('error', cb); + ps.stdout.on('data', (data) => { + console.log(`ps stdout: ${data}`); + }); ps.on('close', function (code) { outFile.close(function onClose(closeErr) { if (closeErr) { From 6f9e03669207a03956c3629c50008612e717bfb8 Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 16:39:19 +0100 Subject: [PATCH 35/58] chore: remove logs --- test/test.js | 3 --- 1 file changed, 3 deletions(-) diff --git a/test/test.js b/test/test.js index f0f5af816d..ab148e859a 100644 --- a/test/test.js +++ b/test/test.js @@ -51,9 +51,6 @@ function runTestFile(test, cb) { stdio: ['inherit', outFile, outFile], }); ps.on('error', cb); - ps.stdout.on('data', (data) => { - console.log(`ps stdout: ${data}`); - }); ps.on('close', function (code) { outFile.close(function onClose(closeErr) { if (closeErr) { From ff93284f97f2253bad30ce96bad06ba69bb955cd Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 16:54:53 +0100 Subject: [PATCH 36/58] chore: remove try/catch --- .../fixtures/use-kafkajs-each-batch.js | 8 +--- .../fixtures/use-kafkajs-each-message.js | 39 +++++++++++-------- 2 files changed, 24 insertions(+), 23 deletions(-) diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js index c015d607d0..939074bed2 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js @@ -99,12 +99,8 @@ async function useKafkajsClient(kafkaClient, options) { batchTx.end(); log.info({ data }, 'batch sent'); - try { - await waitUntil(() => batchMessagesConsumed >= 6, 10000); - log.info('messages consumed'); - } catch (err) { - log.error(err, ' messages could not be consumed after 30s'); - } + await waitUntil(() => batchMessagesConsumed >= 6, 10000); + log.info('messages consumed'); await consumer.disconnect(); log.info('consumer disconnect'); diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js index eb8aea6c32..a7f1a4d1d0 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js @@ -93,12 +93,8 @@ async function useKafkajsClient(kafkaClient, options) { log.info({ data }, 'messages to ignore sent'); eachTx.end(); - try { - await waitUntil(() => eachMessagesConsumed >= 6, 10000); - log.info('messages consumed'); - } catch (err) { - log.error(err, ' messages could not be consumed after 10s'); - } + await waitUntil(() => eachMessagesConsumed >= 6, 10000); + log.info('messages consumed'); await consumer.disconnect(); log.info('consumer disconnect'); @@ -151,7 +147,7 @@ function waitUntil(predicate, timeout = 5000) { // ---- mainline -function main() { +async function main() { // Config vars. const clientId = process.env.TEST_CLIENT_ID || 'elastictest-kafka-client'; const groupId = process.env.TEST_GROUP_ID || 'elastictest-kafka-group'; @@ -176,16 +172,25 @@ function main() { logCreator: apmKafkaLogger, }); - useKafkajsClient(kafkaClient, { topic, groupId }).then( - function () { - apm.logger.info('useKafkajsClient resolved'); - process.exitCode = 0; - }, - function (err) { - apm.logger.error(err, 'useKafkajsClient rejected'); - process.exitCode = 1; - }, - ); + // useKafkajsClient(kafkaClient, { topic, groupId }).then( + // function () { + // apm.logger.info('useKafkajsClient resolved'); + // process.exitCode = 0; + // }, + // function (err) { + // apm.logger.error(err, 'useKafkajsClient rejected'); + // process.exitCode = 1; + // }, + // ); + try { + await useKafkajsClient(kafkaClient, { topic, groupId }); + } catch (ex) { + apm.logger.info('useKafkajsClient rejected', ex); + process.exitCode = 1; + } + + apm.logger.info('useKafkajsClient resolved'); + process.exitCode = 0; } main(); From 455fa1c5deb955df11fed4167a510214e3b3434b Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 17:02:27 +0100 Subject: [PATCH 37/58] chore: increase test timeout --- test/instrumentation/modules/kafkajs/kafkajs.test.js | 2 ++ 1 file changed, 2 insertions(+) diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index 52021477c6..e800cdf471 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -31,6 +31,7 @@ const testFixtures = [ name: 'simple Kafkajs usage scenario for single message processing', script: 'fixtures/use-kafkajs-each-message.js', cwd: __dirname, + timeout: 20000, env: { TEST_CLIENT_ID: 'elastic-kafka-client', TEST_GROUP_ID: `elastictest-kafka-group-${version}`, @@ -219,6 +220,7 @@ const testFixtures = [ name: 'simple Kafkajs usage scenario for batch message processing', script: 'fixtures/use-kafkajs-each-batch.js', cwd: __dirname, + timeout: 20000, env: { TEST_CLIENT_ID: 'elastic-kafka-client', TEST_GROUP_ID: `elastictest-kafka-group-${version}`, From a5ad18811c64aa9eab8ba2158ae35bdc7dd211b4 Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 17:14:09 +0100 Subject: [PATCH 38/58] chore: add test matrix back --- .github/workflows/test.yml | 17 ++++++++--------- 1 file changed, 8 insertions(+), 9 deletions(-) diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 6a4ab780d4..ee247c4195 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -155,15 +155,14 @@ jobs: node: - '21' - '21.0' - # XXX: Omit for now to avoid consuming too many resources - # - '20' - # - '20.0' - # - '18.18.2' # Skip >=18.19.0 until IITM double-import issue is resolved. - # - '18.0' - # - '16' - # - '16.0' - # - '14' - # - '14.17' + - '20' + - '20.0' + - '18.18.2' # Skip >=18.19.0 until IITM double-import issue is resolved. + - '18.0' + - '16' + - '16.0' + - '14' + - '14.17' runs-on: ubuntu-latest steps: - uses: actions/checkout@v4 From 10f28c94275c8b08e5264d250c0385151a9d02b9 Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 17:57:28 +0100 Subject: [PATCH 39/58] chore: add kafka cntainer healthcheck --- .ci/docker/docker-compose.yml | 7 +++++++ test/docker-compose.yml | 7 +++++++ 2 files changed, 14 insertions(+) diff --git a/.ci/docker/docker-compose.yml b/.ci/docker/docker-compose.yml index 0f8c3119e5..b8ebf177ed 100644 --- a/.ci/docker/docker-compose.yml +++ b/.ci/docker/docker-compose.yml @@ -170,6 +170,13 @@ services: - KAFKA_CFG_DELETE_TOPIC_ENABLE=true depends_on: - zookeeper + healthcheck: + # use netcat to check tcp connection available + test: nc -z localhost 9093 || exit -1 + start_period: 15s + interval: 5s + timeout: 10s + retries: 5 volumes: nodepgdata: diff --git a/test/docker-compose.yml b/test/docker-compose.yml index 91ac67a42f..f5cfb1356e 100644 --- a/test/docker-compose.yml +++ b/test/docker-compose.yml @@ -160,6 +160,13 @@ services: - KAFKA_CFG_DELETE_TOPIC_ENABLE=true depends_on: - zookeeper + healthcheck: + # use netcat to check tcp connection available + test: nc -z localhost 9093 || exit -1 + start_period: 15s + interval: 5s + timeout: 10s + retries: 5 volumes: nodepgdata: From 996226a2f4509f95ac14f0735863ab9f4aa17baf Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 18:31:15 +0100 Subject: [PATCH 40/58] chore: remove kafka logger --- .../fixtures/use-kafkajs-each-batch.js | 20 +------- .../fixtures/use-kafkajs-each-message.js | 49 +++++-------------- .../modules/kafkajs/kafkajs.test.js | 2 - 3 files changed, 12 insertions(+), 59 deletions(-) diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js index 939074bed2..97374ba5a5 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js @@ -114,18 +114,6 @@ async function useKafkajsClient(kafkaClient, options) { // ---- helper functions -/** - * Creates logger functions for KafkaJS - * @param {string} loglevel - * @returns {(log: any) => void} - */ -function apmKafkaLogger(logLevel) { - const method = logLevel === 'ERROR' ? 'error' : 'info'; - return function (log) { - apm.logger[method](log); - }; -} - /** * Retuns a promise which is resolved when the predicate becomes true or rejected * if the timeout is reached. @@ -170,13 +158,7 @@ function main() { ); } - const kafkaClient = new Kafka({ - clientId, - brokers: [broker], - // To avoid prints directly on stderr - // https://kafka.js.org/docs/custom-logger - logCreator: apmKafkaLogger, - }); + const kafkaClient = new Kafka({ clientId, brokers: [broker] }); useKafkajsClient(kafkaClient, { topic, groupId }).then( function () { diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js index a7f1a4d1d0..aa8c646523 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js @@ -108,18 +108,6 @@ async function useKafkajsClient(kafkaClient, options) { // ---- helper functions -/** - * Creates logger functions for KafkaJS - * @param {string} loglevel - * @returns {(log: any) => void} - */ -function apmKafkaLogger(logLevel) { - const method = logLevel === 'ERROR' ? 'error' : 'info'; - return function (log) { - apm.logger[method](log); - }; -} - /** * Retuns a promise which is resolved when the predicate becomes true or rejected * if the timeout is reached. @@ -164,33 +152,18 @@ async function main() { ); } - const kafkaClient = new Kafka({ - clientId, - brokers: [broker], - // To avoid prints directly on stderr - // https://kafka.js.org/docs/custom-logger - logCreator: apmKafkaLogger, - }); + const kafkaClient = new Kafka({ clientId, brokers: [broker] }); - // useKafkajsClient(kafkaClient, { topic, groupId }).then( - // function () { - // apm.logger.info('useKafkajsClient resolved'); - // process.exitCode = 0; - // }, - // function (err) { - // apm.logger.error(err, 'useKafkajsClient rejected'); - // process.exitCode = 1; - // }, - // ); - try { - await useKafkajsClient(kafkaClient, { topic, groupId }); - } catch (ex) { - apm.logger.info('useKafkajsClient rejected', ex); - process.exitCode = 1; - } - - apm.logger.info('useKafkajsClient resolved'); - process.exitCode = 0; + useKafkajsClient(kafkaClient, { topic, groupId }).then( + function () { + apm.logger.info('useKafkajsClient resolved'); + process.exitCode = 0; + }, + function (err) { + apm.logger.error(err, 'useKafkajsClient rejected'); + process.exitCode = 1; + }, + ); } main(); diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index e800cdf471..e8f0dd109a 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -7,7 +7,6 @@ 'use strict'; // Test instrumentation of the 'kafkajs' module. - if (process.env.GITHUB_ACTIONS === 'true' && process.platform === 'win32') { console.log('# SKIP: GH Actions do not support docker services on Windows'); process.exit(0); @@ -17,7 +16,6 @@ const test = require('tape'); const { validateSpan } = require('../../../_validate_schema'); const { runTestFixtures, sortApmEvents } = require('../../../_utils'); -// const { NODE_VER_RANGE_IITM } = require('../../../testconsts'); const kafkaUrl = process.env.KAFKA_URL || 'localhost:9093'; From 2c09adbc2da71059f179de377e68304f66408830 Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 18:43:36 +0100 Subject: [PATCH 41/58] chore: fix kafa docker compose --- .ci/docker/docker-compose-kafka.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.ci/docker/docker-compose-kafka.yml b/.ci/docker/docker-compose-kafka.yml index ac8820f207..84e719aeb9 100644 --- a/.ci/docker/docker-compose-kafka.yml +++ b/.ci/docker/docker-compose-kafka.yml @@ -10,7 +10,7 @@ services: file: docker-compose-node-test.yml service: node_tests depends_on: - localstack: + kafka: condition: service_healthy volumes: From 760e2d86bfff728e76d1dc2dc870e71fd38a9378 Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 18:53:49 +0100 Subject: [PATCH 42/58] chore: remove some comments and typos --- .ci/docker/docker-compose-all.yml | 8 ++++++++ .ci/docker/docker-compose-edge.yml | 8 ++++++++ .ci/docker/docker-compose-kafka.yml | 2 +- .ci/docker/docker-compose.yml | 2 -- .github/workflows/test.yml | 2 -- 5 files changed, 17 insertions(+), 5 deletions(-) diff --git a/.ci/docker/docker-compose-all.yml b/.ci/docker/docker-compose-all.yml index 7727d2c7c5..57bbdbf500 100644 --- a/.ci/docker/docker-compose-all.yml +++ b/.ci/docker/docker-compose-all.yml @@ -37,6 +37,10 @@ services: extends: file: docker-compose.yml service: localstack + kafka: + extends: + file: docker-compose.yml + service: kafka node_tests: extends: file: docker-compose-node-test.yml @@ -60,6 +64,8 @@ services: condition: service_healthy localstack: condition: service_healthy + kafka: + condition: service_healthy volumes: nodepgdata: @@ -76,3 +82,5 @@ volumes: driver: local nodelocalstackdata: driver: local + nodekafkadata: + driver: local diff --git a/.ci/docker/docker-compose-edge.yml b/.ci/docker/docker-compose-edge.yml index feb27dd063..c53de517b9 100644 --- a/.ci/docker/docker-compose-edge.yml +++ b/.ci/docker/docker-compose-edge.yml @@ -37,6 +37,10 @@ services: extends: file: docker-compose.yml service: redis + kafka: + extends: + file: docker-compose.yml + service: kafka node_tests: extends: file: docker-compose-node-edge-test.yml @@ -60,6 +64,8 @@ services: condition: service_healthy redis: condition: service_healthy + kafka: + condition: service_healthy volumes: nodepgdata: @@ -76,3 +82,5 @@ volumes: driver: local nodecassandradata: driver: local + nodekafkadata: + driver: local diff --git a/.ci/docker/docker-compose-kafka.yml b/.ci/docker/docker-compose-kafka.yml index 84e719aeb9..178e6eccca 100644 --- a/.ci/docker/docker-compose-kafka.yml +++ b/.ci/docker/docker-compose-kafka.yml @@ -14,5 +14,5 @@ services: condition: service_healthy volumes: - nodelafkadata: + nodekafkadata: driver: local diff --git a/.ci/docker/docker-compose.yml b/.ci/docker/docker-compose.yml index b8ebf177ed..708a2b884f 100644 --- a/.ci/docker/docker-compose.yml +++ b/.ci/docker/docker-compose.yml @@ -142,7 +142,6 @@ services: zookeeper: # https://hub.docker.com/r/bitnami/zookeeper/tags - #restart: always image: bitnami/zookeeper:3.9.1 ports: - "2181:2181" @@ -153,7 +152,6 @@ services: kafka: # https://hub.docker.com/r/bitnami/kafka/tags - #restart: always image: bitnami/kafka:3.3.2 ports: - "9093:9093" diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index ee247c4195..d842f80ec1 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -123,7 +123,6 @@ jobs: - nodelocalstackdata:/var/lib/localstack zookeeper: - # https://hub.docker.com/r/bitnami/zookeeper/tags image: bitnami/zookeeper:3.9.1 env: ALLOW_ANONYMOUS_LOGIN: 'yes' @@ -133,7 +132,6 @@ jobs: - nodezookeeperdata:/var/lib/zookeeper/data kafka: - # https://hub.docker.com/r/bitnami/kafka/tags image: bitnami/kafka:3.3.2 ports: - "9093:9093" From 9f52563d76f914783fbfdf08eb1d7467242f410e Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 13 Dec 2023 19:08:49 +0100 Subject: [PATCH 43/58] chore: update docs --- CHANGELOG.asciidoc | 15 +++++++++++++++ docs/supported-technologies.asciidoc | 1 + 2 files changed, 16 insertions(+) diff --git a/CHANGELOG.asciidoc b/CHANGELOG.asciidoc index d6525474c3..66b55fb65e 100644 --- a/CHANGELOG.asciidoc +++ b/CHANGELOG.asciidoc @@ -33,6 +33,21 @@ Notes: See the <> guide. +==== Unreleased + +[float] +===== Breaking changes + +[float] +===== Features + +* Add support for `kafkajs` version v2. ({issues}2905[#2905]) + +[float] +===== Bug fixes + +[float] +===== Chores [[release-notes-4.3.0]] ==== 4.3.0 - 2023/12/05 diff --git a/docs/supported-technologies.asciidoc b/docs/supported-technologies.asciidoc index b492036be4..d0354afa49 100644 --- a/docs/supported-technologies.asciidoc +++ b/docs/supported-technologies.asciidoc @@ -142,6 +142,7 @@ so those should be supported as well. |https://www.npmjs.com/package/tedious[tedious] |>=1.9 <17.0.0 | (Excluding v4.0.0.) Will instrument all queries |https://www.npmjs.com/package/undici[undici] | >=4.7.1 <6 | Will instrument undici HTTP requests, except HTTP CONNECT. Requires node v14.17.0 or later, or the user to have installed the https://www.npmjs.com/package/diagnostics_channel['diagnostics_channel' polyfill]. |https://www.npmjs.com/package/ws[ws] |>=1.0.0 <8.0.0 |Will instrument outgoing WebSocket messages +|https://www.npmjs.com/package/kafkajs[kafkajs] |>=2.0.0 <3.0.0 |Will instrument all send methods for producers and message and batch processing for consumers. |======================================================================= [float] From e99d189361114e5908d5740607ee8066113eb21c Mon Sep 17 00:00:00 2001 From: David Luna Date: Thu, 14 Dec 2023 09:58:02 +0100 Subject: [PATCH 44/58] chore: update comments --- lib/instrumentation/modules/kafkajs.js | 41 +++++++++++++++++++------- 1 file changed, 30 insertions(+), 11 deletions(-) diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index a530d78131..f532d99ea0 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -50,7 +50,9 @@ module.exports = function (mod, agent, { version, enabled }) { return mod; /** - * Returns a function which creates instrumented consumers + * Returns the patched version of `Kafka.consumer` which creates a new + * consumer with its `run` method patched to instrument message handling + * * @param {ConsumerFactory} origConsumer * @returns {ConsumerFactory} */ @@ -64,7 +66,9 @@ module.exports = function (mod, agent, { version, enabled }) { } /** - * Returns a function which istrument the run callbacks `eachMessage` & `eachBatch` + * Return the patched version of `run` which instruments the + * `eachMessage` & `eachBatch` callbacks. + * * @param {Consumer['run']} origRun * @returns {Consumer['run']} */ @@ -87,7 +91,8 @@ module.exports = function (mod, agent, { version, enabled }) { /** * Returns the instrumented version of `eachMessage` which * - creates a transaction each time is called - * - adds the trace context headers for distrubuted tracing + * - add trace context into the transaction if present in message headers + * * @param {ConsumerRunConfig['eachMessage']} origEachMessage * @returns {ConsumerRunConfig['eachMessage']} */ @@ -175,9 +180,10 @@ module.exports = function (mod, agent, { version, enabled }) { } /** - * Returns the instrumented version of `eachMessage` which + * Returns the instrumented version of `eachBatch` which * - creates a transaction each time is called - * - adds the trace context headers for distrubuted tracing + * - if trace context present in messages inks them to the transaction + * * @param {ConsumerRunConfig['eachBatch']} origEachBatch * @returns {ConsumerRunConfig['eachBatch']} */ @@ -189,7 +195,8 @@ module.exports = function (mod, agent, { version, enabled }) { const trans = ins.startTransaction(`${NAME} RECEIVE from batch`, TYPE); - // TODO: not sure if this should be here but we gat batches for only one topic + // TODO: not sure if this should be here but we got batches for only one topic + // https://github.com/elastic/apm/blob/main/specs/agents/tracing-instrumentation-messaging.md#context-fields const messageCtx = { queue: { name: batch.topic } }; trans.setMessageContext(messageCtx); @@ -243,7 +250,9 @@ module.exports = function (mod, agent, { version, enabled }) { } /** - * Returns a function which creates instrumented producers + * Returns the patched version of `Kafka.producer` which creates a new + * producer with `send` & `sendBatch` methods patched to instrument message sending + * * @param {ProducerFactory} origProducer * @returns {ProducerFactory} */ @@ -258,7 +267,10 @@ module.exports = function (mod, agent, { version, enabled }) { } /** - * TODO: add comment + * Returns the instrumented version of `send` which + * - creates an exit span each time is called + * - propagates trace context through message headers + * * @param {Producer['send']} origSend * @returns {Producer['send']} */ @@ -295,6 +307,8 @@ module.exports = function (mod, agent, { version, enabled }) { }); } + // TODO: discuss this. Should agent propagate trace context + // regardless if the topic is in the ignore list? if (!span || shouldIgnoreTopic(topic, config)) { return origSend.apply(this, arguments); } @@ -332,7 +346,10 @@ module.exports = function (mod, agent, { version, enabled }) { } /** - * TODO: add comment + * Returns the patched version of `Producer.sendBatch` which + * - creates an exit span for the operation + * - propagates trace context via message headers + * * @param {Producer['sendBatch']} origSendBatch * @returns {Producer['sendBatch']} */ @@ -370,7 +387,8 @@ module.exports = function (mod, agent, { version, enabled }) { }); } - // TODO: discuss this + // TODO: discuss this. if all topics are ignored should the agent avoid + // creating a span? const topics = batch.topicMessages && batch.topicMessages.map((tm) => tm.topic); const shouldIgnoreBatch = @@ -380,7 +398,7 @@ module.exports = function (mod, agent, { version, enabled }) { return origSendBatch.apply(this, arguments); } - // TODO: mabe set if only one topic or all messages for same topic (which is unlikely? + // TODO: mabe set if only one topic or all messages for same topic (which is unlikely?) // span.setMessageContext({ queue: { name: topic } }); // TODO: same here about the topic @@ -415,6 +433,7 @@ module.exports = function (mod, agent, { version, enabled }) { /** * Returns true if we have to ignore messages on the given topic + * * @param {string} topic the topic where client is publishing/subscribing * @param {{ ignoreMessageQueuesRegExp: RegExp[] }} config the agent's configuration object * @returns {boolean} From 641a34386d8edd45f423c3ad1c638b3f61971a0b Mon Sep 17 00:00:00 2001 From: David Luna Date: Thu, 14 Dec 2023 11:48:12 +0100 Subject: [PATCH 45/58] chore: config TAV tests --- .ci/docker/docker-compose-kafka.yml | 14 ++++++++++++-- .ci/docker/docker-compose-node-edge-test.yml | 1 + .ci/docker/docker-compose-node-test.yml | 1 + .ci/docker/docker-compose.yml | 19 ++++++++++++------- test/docker-compose.ci.yml | 1 + .../fixtures/use-kafkajs-each-batch.js | 2 +- .../fixtures/use-kafkajs-each-message.js | 2 +- .../modules/kafkajs/kafkajs.test.js | 8 +++----- 8 files changed, 32 insertions(+), 16 deletions(-) diff --git a/.ci/docker/docker-compose-kafka.yml b/.ci/docker/docker-compose-kafka.yml index 178e6eccca..3ae3e159f2 100644 --- a/.ci/docker/docker-compose-kafka.yml +++ b/.ci/docker/docker-compose-kafka.yml @@ -1,18 +1,28 @@ version: '2.1' services: + zookeeper: + extends: + file: docker-compose.yml + service: zookeeper kafka: extends: file: docker-compose.yml service: kafka + depends_on: + - zookeeper node_tests: extends: file: docker-compose-node-test.yml service: node_tests depends_on: - kafka: - condition: service_healthy + - kafka + # TODO: uncomment this if health_check is necessary + # kafka: + # condition: service_healthy volumes: nodekafkadata: driver: local + nodezookeeperdata: + driver: local diff --git a/.ci/docker/docker-compose-node-edge-test.yml b/.ci/docker/docker-compose-node-edge-test.yml index b2129a58bb..e2b135eb73 100644 --- a/.ci/docker/docker-compose-node-edge-test.yml +++ b/.ci/docker/docker-compose-node-edge-test.yml @@ -24,6 +24,7 @@ services: PGUSER: 'postgres' MEMCACHED_HOST: 'memcached' LOCALSTACK_HOST: 'localstack:4566' + KAFKA_HOST: 'kafka:9093' NODE_VERSION: ${NODE_VERSION} NODE_FULL_VERSION: ${NODE_FULL_VERSION} NVM_NODEJS_ORG_MIRROR: ${NVM_NODEJS_ORG_MIRROR} diff --git a/.ci/docker/docker-compose-node-test.yml b/.ci/docker/docker-compose-node-test.yml index 96423bba4a..ede042ddec 100644 --- a/.ci/docker/docker-compose-node-test.yml +++ b/.ci/docker/docker-compose-node-test.yml @@ -21,6 +21,7 @@ services: PGUSER: 'postgres' MEMCACHED_HOST: 'memcached' LOCALSTACK_HOST: 'localstack:4566' + KAFKA_HOST: 'kafka:9093' NODE_VERSION: ${NODE_VERSION} TAV: ${TAV_MODULE} ELASTIC_APM_CONTEXT_MANAGER: ${ELASTIC_APM_CONTEXT_MANAGER} diff --git a/.ci/docker/docker-compose.yml b/.ci/docker/docker-compose.yml index 708a2b884f..e14c125b09 100644 --- a/.ci/docker/docker-compose.yml +++ b/.ci/docker/docker-compose.yml @@ -146,7 +146,7 @@ services: ports: - "2181:2181" volumes: - - "zookeeper-volume:/bitnami" + - nodezookeeperdata:/bitnami environment: - ALLOW_ANONYMOUS_LOGIN=yes @@ -163,18 +163,19 @@ services: - ALLOW_PLAINTEXT_LISTENER=yes - KAFKA_CFG_LISTENER_SECURITY_PROTOCOL_MAP=CLIENT:PLAINTEXT,EXTERNAL:PLAINTEXT - KAFKA_CFG_LISTENERS=CLIENT://:9092,EXTERNAL://:9093 - - KAFKA_CFG_ADVERTISED_LISTENERS=CLIENT://kafka:9092,EXTERNAL://localhost:9093 + - KAFKA_CFG_ADVERTISED_LISTENERS=CLIENT://kafka:9092,EXTERNAL://kafka:9093 - KAFKA_CFG_INTER_BROKER_LISTENER_NAME=CLIENT - KAFKA_CFG_DELETE_TOPIC_ENABLE=true depends_on: - zookeeper + # TODO: maybe not necessary but figure out how to do this healthcheck: # use netcat to check tcp connection available - test: nc -z localhost 9093 || exit -1 - start_period: 15s - interval: 5s - timeout: 10s - retries: 5 + # test: nc -z localhost 9093 || exit -1 + # start_period: 15s + # interval: 5s + # timeout: 10s + # retries: 5 volumes: nodepgdata: @@ -191,3 +192,7 @@ volumes: driver: local nodelocalstackdata: driver: local + nodekafkadata: + driver: local + nodezookeeperdata: + driver: local diff --git a/test/docker-compose.ci.yml b/test/docker-compose.ci.yml index 65d3c41605..d68f46cf9f 100644 --- a/test/docker-compose.ci.yml +++ b/test/docker-compose.ci.yml @@ -12,6 +12,7 @@ services: CASSANDRA_HOST: 'cassandra' MEMCACHED_HOST: 'memcached' LOCALSTACK_HOST: 'localstack:4566' + KAFKA_HOST: 'kafka:9093' PGHOST: 'postgres' PGUSER: 'postgres' depends_on: diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js index 97374ba5a5..cb28cb878e 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js @@ -145,7 +145,7 @@ function main() { // Config vars. const clientId = process.env.TEST_CLIENT_ID || 'elastictest-kafka-client'; const groupId = process.env.TEST_GROUP_ID || 'elastictest-kafka-group'; - const broker = process.env.TEST_KAFKA_URL || 'localhost:9093'; + const broker = process.env.TEST_KAFKA_HOST || 'localhost:9093'; const topic = process.env.TEST_TOPIC || TEST_TOPIC_PREFIX + Math.floor(Math.random() * 1000); diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js index aa8c646523..9732f8cfca 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js @@ -139,7 +139,7 @@ async function main() { // Config vars. const clientId = process.env.TEST_CLIENT_ID || 'elastictest-kafka-client'; const groupId = process.env.TEST_GROUP_ID || 'elastictest-kafka-group'; - const broker = process.env.TEST_KAFKA_URL || 'localhost:9093'; + const broker = process.env.TEST_KAFKA_HOST || 'localhost:9093'; const topic = process.env.TEST_TOPIC || TEST_TOPIC_PREFIX + Math.floor(Math.random() * 1000); diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index e8f0dd109a..6eeba0df4d 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -17,7 +17,7 @@ const test = require('tape'); const { validateSpan } = require('../../../_validate_schema'); const { runTestFixtures, sortApmEvents } = require('../../../_utils'); -const kafkaUrl = process.env.KAFKA_URL || 'localhost:9093'; +const kafkaHost = process.env.KAFKA_HOST || 'localhost:9093'; const version = process.version.replace(/\./g, '-'); const topicEach = `elasticapmtest-topic-each-${version}`; @@ -34,12 +34,11 @@ const testFixtures = [ TEST_CLIENT_ID: 'elastic-kafka-client', TEST_GROUP_ID: `elastictest-kafka-group-${version}`, TEST_TOPIC: topicEach, - TEST_KAFKA_URL: kafkaUrl, + TEST_KAFKA_HOST: kafkaHost, // Suppres warinings about new default partitioner // https://kafka.js.org/docs/migration-guide-v2.0.0#producer-new-default-partitioner KAFKAJS_NO_PARTITIONER_WARNING: '1', }, - verbose: true, checkApmServer(t, apmServer) { t.ok(apmServer.events[0].metadata, 'metadata'); const events = sortApmEvents(apmServer.events); @@ -223,12 +222,11 @@ const testFixtures = [ TEST_CLIENT_ID: 'elastic-kafka-client', TEST_GROUP_ID: `elastictest-kafka-group-${version}`, TEST_TOPIC: topicBatch, - TEST_KAFKA_URL: kafkaUrl, + TEST_KAFKA_HOST: kafkaHost, // Suppres warinings about new default partitioner // https://kafka.js.org/docs/migration-guide-v2.0.0#producer-new-default-partitioner KAFKAJS_NO_PARTITIONER_WARNING: '1', }, - verbose: true, checkApmServer(t, apmServer) { t.ok(apmServer.events[0].metadata, 'metadata'); const events = sortApmEvents(apmServer.events); From f9d9f1915ab42a3d3d6e541c13f8676416789048 Mon Sep 17 00:00:00 2001 From: David Luna Date: Thu, 14 Dec 2023 14:23:21 +0100 Subject: [PATCH 46/58] chore: add cpature body tests --- .../fixtures/use-kafkajs-each-message.js | 2 + .../modules/kafkajs/kafkajs.test.js | 228 ++++++++++++++++-- 2 files changed, 212 insertions(+), 18 deletions(-) diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js index 9732f8cfca..c3a372ad5b 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js @@ -15,6 +15,8 @@ const apm = require('../../../../..').start({ stackTraceLimit: 4, // get it smaller for reviewing output logLevel: 'info', ignoreMessageQueues: ['*-ignore'], + captureBody: process.env.TEST_CAPTURE_BODY || 'off', + captureHeaders: process.env.TEST_CAPTURE_HEADERS || false, }); const { Buffer } = require('buffer'); diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index 6eeba0df4d..a71e6d6c3d 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -19,9 +19,8 @@ const { runTestFixtures, sortApmEvents } = require('../../../_utils'); const kafkaHost = process.env.KAFKA_HOST || 'localhost:9093'; -const version = process.version.replace(/\./g, '-'); -const topicEach = `elasticapmtest-topic-each-${version}`; -const topicBatch = `elasticapmtest-topic-batch-${version}`; +const rand = Math.floor(Math.random() * 1000); +const kafkaTopic = `elasticapmtest-topic-each-${rand}`; /** @type {import('../../../_utils').TestFixture[]} */ const testFixtures = [ @@ -32,8 +31,8 @@ const testFixtures = [ timeout: 20000, env: { TEST_CLIENT_ID: 'elastic-kafka-client', - TEST_GROUP_ID: `elastictest-kafka-group-${version}`, - TEST_TOPIC: topicEach, + TEST_GROUP_ID: `elastictest-kafka-group-${rand}`, + TEST_TOPIC: kafkaTopic, TEST_KAFKA_HOST: kafkaHost, // Suppres warinings about new default partitioner // https://kafka.js.org/docs/migration-guide-v2.0.0#producer-new-default-partitioner @@ -88,22 +87,22 @@ const testFixtures = [ }); t.deepEqual(spans.shift(), { - name: `Kafka send to ${topicEach}`, + name: `Kafka send to ${kafkaTopic}`, type: 'messaging', subtype: 'kafka', action: 'send', context: { service: { - target: { type: 'kafka', name: topicEach }, + target: { type: 'kafka', name: kafkaTopic }, }, destination: { service: { - resource: `kafka/${topicEach}`, + resource: `kafka/${kafkaTopic}`, type: '', name: '', }, }, - message: { queue: { name: topicEach } }, + message: { queue: { name: kafkaTopic } }, }, outcome: 'success', }); @@ -162,12 +161,12 @@ const testFixtures = [ // Check message handling transactions t.deepEqual(transactions.shift(), { - name: `Kafka RECEIVE from ${topicEach}`, + name: `Kafka RECEIVE from ${kafkaTopic}`, type: 'messaging', context: { service: {}, message: { - queue: { name: topicEach }, + queue: { name: kafkaTopic }, headers: { foo: 'buffer', traceparent: `00-${tx.trace_id}-${parentId}-01`, @@ -179,12 +178,12 @@ const testFixtures = [ }); t.deepEqual(transactions.shift(), { - name: `Kafka RECEIVE from ${topicEach}`, + name: `Kafka RECEIVE from ${kafkaTopic}`, type: 'messaging', context: { service: {}, message: { - queue: { name: topicEach }, + queue: { name: kafkaTopic }, headers: { foo: 'string', traceparent: `00-${tx.trace_id}-${parentId}-01`, @@ -196,12 +195,12 @@ const testFixtures = [ }); t.deepEqual(transactions.shift(), { - name: `Kafka RECEIVE from ${topicEach}`, + name: `Kafka RECEIVE from ${kafkaTopic}`, type: 'messaging', context: { service: {}, message: { - queue: { name: topicEach }, + queue: { name: kafkaTopic }, headers: { traceparent: `00-${tx.trace_id}-${parentId}-01`, tracestate: 'es=s:1', @@ -220,8 +219,8 @@ const testFixtures = [ timeout: 20000, env: { TEST_CLIENT_ID: 'elastic-kafka-client', - TEST_GROUP_ID: `elastictest-kafka-group-${version}`, - TEST_TOPIC: topicBatch, + TEST_GROUP_ID: `elastictest-kafka-group-${rand}`, + TEST_TOPIC: kafkaTopic, TEST_KAFKA_HOST: kafkaHost, // Suppres warinings about new default partitioner // https://kafka.js.org/docs/migration-guide-v2.0.0#producer-new-default-partitioner @@ -320,7 +319,7 @@ const testFixtures = [ type: 'messaging', context: { service: { framework: { name: 'Kafka' } }, - message: { queue: { name: topicBatch } }, + message: { queue: { name: kafkaTopic } }, }, links: [ { @@ -343,6 +342,199 @@ const testFixtures = [ t.equal(transactions.length, 0, 'all transactions accounted for'); }, }, + { + name: 'simple Kafkajs usage scenario for headers and body capturing on message reception', + script: 'fixtures/use-kafkajs-each-message.js', + cwd: __dirname, + timeout: 20000, + env: { + TEST_CLIENT_ID: 'elastic-kafka-client', + TEST_GROUP_ID: `elastictest-kafka-group-${rand}`, + TEST_TOPIC: kafkaTopic, + TEST_KAFKA_HOST: kafkaHost, + TEST_CAPTURE_HEADERS: 'true', + TEST_CAPTURE_BODY: 'all', + // Suppres warinings about new default partitioner + // https://kafka.js.org/docs/migration-guide-v2.0.0#producer-new-default-partitioner + KAFKAJS_NO_PARTITIONER_WARNING: '1', + }, + checkApmServer(t, apmServer) { + t.ok(apmServer.events[0].metadata, 'metadata'); + const events = sortApmEvents(apmServer.events); + const tx = events.shift().transaction; + + // First the transaction. + t.ok(tx, 'got the send transaction'); + + // Compare some common fields across all spans. + // ignore http/external spans + const spans = events.filter((e) => e.span).map((e) => e.span); + spans.forEach((s) => { + const errs = validateSpan(s); + t.equal(errs, null, 'span is valid (per apm-server intake schema)'); + }); + t.equal( + spans.filter((s) => s.trace_id === tx.trace_id).length, + spans.length, + 'all spans have the same trace_id', + ); + t.equal( + spans.filter((s) => s.transaction_id === tx.id).length, + spans.length, + 'all spans have the same transaction_id', + ); + t.equal( + spans.filter((s) => s.sync === false).length, + spans.length, + 'all spans have sync=false', + ); + t.equal( + spans.filter((s) => s.sample_rate === 1).length, + spans.length, + 'all spans have sample_rate=1', + ); + + spans.forEach((s) => { + // Remove variable and common fields to facilitate t.deepEqual below. + delete s.id; + delete s.transaction_id; + delete s.parent_id; + delete s.trace_id; + delete s.timestamp; + delete s.duration; + delete s.sync; + delete s.sample_rate; + }); + + t.deepEqual(spans.shift(), { + name: `Kafka send to ${kafkaTopic}`, + type: 'messaging', + subtype: 'kafka', + action: 'send', + context: { + service: { + target: { type: 'kafka', name: kafkaTopic }, + }, + destination: { + service: { + resource: `kafka/${kafkaTopic}`, + type: '', + name: '', + }, + }, + message: { queue: { name: kafkaTopic } }, + }, + outcome: 'success', + }); + + t.equal(spans.length, 0, 'all spans accounted for'); + + // No check the transactions created for each message received + const transactions = events + .filter((e) => e.transaction) + .map((e) => e.transaction); + const parentId = transactions[0].parent_id; + + t.equal( + transactions.filter((t) => t.trace_id === tx.trace_id).length, + transactions.length, + 'all transactions have the same trace_id', + ); + t.equal( + transactions.filter((t) => t.parent_id === parentId).length, + transactions.length, + 'all transactions have the same parent_id', + ); + t.equal( + transactions + .map((t) => t.context.message.age.ms) + .filter((ms) => typeof ms === 'number' && ms > 0).length, + transactions.length, + 'all transactions have positive age', + ); + // TODO: other checks like sync=false & sample rate? + + // NOTE: messages could arrive in different order so we sort them + // to properly do the assertions + transactions.sort((t1, t2) => { + const header1 = t1.context.message.headers.foo || 'undefined'; + const header2 = t2.context.message.headers.foo || 'undefined'; + return header1 < header2 ? -1 : 1; + }); + transactions.forEach((t) => { + // Remove variable and common fields to facilitate t.deepEqual below. + delete t.id; + delete t.parent_id; + delete t.trace_id; + delete t.timestamp; + delete t.duration; + delete t.sample_rate; + delete t.sampled; + delete t.span_count; + delete t.result; + delete t.context.user; + delete t.context.tags; + delete t.context.custom; + delete t.context.cloud; + delete t.context.message.age; + }); + + // Check message handling transactions + t.deepEqual(transactions.shift(), { + name: `Kafka RECEIVE from ${kafkaTopic}`, + type: 'messaging', + context: { + service: {}, + message: { + queue: { name: kafkaTopic }, + headers: { + foo: 'buffer', + traceparent: `00-${tx.trace_id}-${parentId}-01`, + tracestate: 'es=s:1', + }, + body: 'each message 2', + }, + }, + outcome: 'success', + }); + + t.deepEqual(transactions.shift(), { + name: `Kafka RECEIVE from ${kafkaTopic}`, + type: 'messaging', + context: { + service: {}, + message: { + queue: { name: kafkaTopic }, + headers: { + foo: 'string', + traceparent: `00-${tx.trace_id}-${parentId}-01`, + tracestate: 'es=s:1', + }, + body: 'each message 1', + }, + }, + outcome: 'success', + }); + + t.deepEqual(transactions.shift(), { + name: `Kafka RECEIVE from ${kafkaTopic}`, + type: 'messaging', + context: { + service: {}, + message: { + queue: { name: kafkaTopic }, + headers: { + traceparent: `00-${tx.trace_id}-${parentId}-01`, + tracestate: 'es=s:1', + }, + body: 'each message 3', + }, + }, + outcome: 'success', + }); + t.equal(transactions.length, 0, 'all transactions accounted for'); + }, + }, ]; test('kafkajs fixtures', (suite) => { From 27aed57a7d84fc3735894906b1980cebb52f9b8c Mon Sep 17 00:00:00 2001 From: David Luna Date: Mon, 18 Dec 2023 12:28:54 +0100 Subject: [PATCH 47/58] chore: change trace context propagation --- lib/instrumentation/modules/kafkajs.js | 25 +++++++++++++++---------- 1 file changed, 15 insertions(+), 10 deletions(-) diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index f532d99ea0..1aa44057e5 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -277,13 +277,20 @@ module.exports = function (mod, agent, { version, enabled }) { function wrapProducerSend(origSend) { return async function (record) { const { topic } = record; - const span = ins.createSpan( - `${NAME} send to ${topic}`, - TYPE, - SUBTYPE, - 'send', - { exitSpan: true }, - ); + + // TODO: discuss this. Should agent propagate trace context + // regardless if the topic is in the ignore list? + let span; + + if (!shouldIgnoreTopic(topic, config)) { + span = ins.createSpan( + `${NAME} send to ${topic}`, + TYPE, + SUBTYPE, + 'send', + { exitSpan: true }, + ); + } // W3C trace-context propagation. const runContext = ins.currRunContext(); @@ -307,9 +314,7 @@ module.exports = function (mod, agent, { version, enabled }) { }); } - // TODO: discuss this. Should agent propagate trace context - // regardless if the topic is in the ignore list? - if (!span || shouldIgnoreTopic(topic, config)) { + if (!span) { return origSend.apply(this, arguments); } From 3adf8c4d6f111a3e471b8cf963ab93fa82e67764 Mon Sep 17 00:00:00 2001 From: David Luna Date: Mon, 18 Dec 2023 20:44:37 +0100 Subject: [PATCH 48/58] chore: add target to destination context --- lib/instrumentation/modules/kafkajs.js | 55 +++++++++++-------- .../modules/kafkajs/kafkajs.test.js | 5 +- 2 files changed, 35 insertions(+), 25 deletions(-) diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index 1aa44057e5..c94b4c0638 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -360,13 +360,23 @@ module.exports = function (mod, agent, { version, enabled }) { */ function wrapProducerSendBatch(origSendBatch) { return async function (batch) { - const span = ins.createSpan( - `${NAME} send messages batch`, - TYPE, - SUBTYPE, - 'send', - { exitSpan: true }, - ); + // TODO: discuss this. if all topics are ignored should the agent avoid + // creating a span? + let span; + const topics = + batch.topicMessages && batch.topicMessages.map((tm) => tm.topic); + const shouldIgnoreBatch = + topics && topics.every((t) => shouldIgnoreTopic(t, config)); + + if (!shouldIgnoreBatch) { + span = ins.createSpan( + `${NAME} send messages batch`, + TYPE, + SUBTYPE, + 'send', + { exitSpan: true }, + ); + } // W3C trace-context propagation. const runContext = ins.currRunContext(); @@ -392,29 +402,26 @@ module.exports = function (mod, agent, { version, enabled }) { }); } - // TODO: discuss this. if all topics are ignored should the agent avoid - // creating a span? - const topics = - batch.topicMessages && batch.topicMessages.map((tm) => tm.topic); - const shouldIgnoreBatch = - topics && topics.every((t) => shouldIgnoreTopic(t, config)); - - if (!span || shouldIgnoreBatch) { + if (!span) { return origSendBatch.apply(this, arguments); } + const destCtx = { + service: { type: SUBTYPE }, + target: { type: SUBTYPE }, + }; + // TODO: mabe set if only one topic or all messages for same topic (which is unlikely?) - // span.setMessageContext({ queue: { name: topic } }); + // const uniqueTopics = new Set(topics); + // if (uniqueTopics.size === 1) { + // const topic = topics[0]; - // TODO: same here about the topic - // const service = { - // resource: `${SUBTYPE}/${topic}`, - // type: SUBTYPE, - // name: topic, - // }; + // destCtx.service.name = topic; + // destCtx.service.resource = `${SUBTYPE}/${topic}`; + // span.setMessageContext({ queue: { name: topic } }); + // } - const service = { type: SUBTYPE }; - span._setDestinationContext({ service }); + span._setDestinationContext(destCtx); let result, err; try { diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index a71e6d6c3d..7870f5b9a5 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -282,7 +282,10 @@ const testFixtures = [ action: 'send', context: { service: { target: { type: 'kafka' } }, - destination: { service: { type: '', name: '', resource: 'kafka' } }, + destination: { + service: { type: '', name: '', resource: 'kafka' }, + target: { type: 'kafka' }, + }, }, outcome: 'success', }); From 86df3050f0cb7b3b7ac9e4ff7c18fc072825888a Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 27 Dec 2023 10:56:02 +0100 Subject: [PATCH 49/58] chore: remove some comments --- lib/instrumentation/modules/kafkajs.js | 16 ++-------------- 1 file changed, 2 insertions(+), 14 deletions(-) diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index c94b4c0638..4dc552b219 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -35,7 +35,6 @@ const SUBTYPE = 'kafka'; * @param {boolean} options.enabled */ module.exports = function (mod, agent, { version, enabled }) { - // TODO: discuss this range if (!enabled || !semver.satisfies(version, '>=2 <3')) { return mod; } @@ -277,9 +276,6 @@ module.exports = function (mod, agent, { version, enabled }) { function wrapProducerSend(origSend) { return async function (record) { const { topic } = record; - - // TODO: discuss this. Should agent propagate trace context - // regardless if the topic is in the ignore list? let span; if (!shouldIgnoreTopic(topic, config)) { @@ -407,20 +403,12 @@ module.exports = function (mod, agent, { version, enabled }) { } const destCtx = { + // `service.name` and `service.resource` cannot be set since `producer.sendBatch` + // is meant to send to several topics at a time service: { type: SUBTYPE }, target: { type: SUBTYPE }, }; - // TODO: mabe set if only one topic or all messages for same topic (which is unlikely?) - // const uniqueTopics = new Set(topics); - // if (uniqueTopics.size === 1) { - // const topic = topics[0]; - - // destCtx.service.name = topic; - // destCtx.service.resource = `${SUBTYPE}/${topic}`; - // span.setMessageContext({ queue: { name: topic } }); - // } - span._setDestinationContext(destCtx); let result, err; From 0a12b9949f8b46363d4e11968f6ae74d104bdce3 Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 3 Jan 2024 19:39:05 +0100 Subject: [PATCH 50/58] chore: add trace propagation tests --- .../fixtures/use-kafkajs-ctx-propagation.js | 173 ++++++++++++++++++ .../fixtures/use-kafkajs-each-batch.js | 2 +- .../fixtures/use-kafkajs-each-message.js | 2 +- .../modules/kafkajs/kafkajs.test.js | 101 +++++++++- 4 files changed, 271 insertions(+), 7 deletions(-) create mode 100644 test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-ctx-propagation.js diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-ctx-propagation.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-ctx-propagation.js new file mode 100644 index 0000000000..dc6d425e88 --- /dev/null +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-ctx-propagation.js @@ -0,0 +1,173 @@ +/* + * Copyright Elasticsearch B.V. and other contributors where applicable. + * Licensed under the BSD 2-Clause License; you may not use this file except in + * compliance with the BSD 2-Clause License. + */ + +'use strict'; + +const TEST_TOPIC_PREFIX = 'elasticapmtest-topic-'; + +const apm = require('../../../../..').start({ + serviceName: 'use-kafkajs', + captureExceptions: false, + centralConfig: false, + metricsInterval: 0, + cloudProvider: 'none', + stackTraceLimit: 4, // get it smaller for reviewing output + logLevel: 'info', + ignoreMessageQueues: + process.env.TEST_MODE === 'send' ? [`${TEST_TOPIC_PREFIX}*`] : [], +}); + +const { Kafka } = require('kafkajs'); +/** @type {import('kafkajs').Admin} */ +let admin; +/** @type {import('kafkajs').Consumer} */ +let consumer; +/** @type {import('kafkajs').Producer} */ +let producer; + +/** + * @param {import('kafkajs').Kafka} kafkaClient + * @param {{topic: string; groupId: string, mode: string}} options + */ +async function useKafkajsClient(kafkaClient, options) { + const { topic, groupId, mode } = options; + const log = apm.logger.child({ + 'event.module': 'kafkajs', + topic, + }); + + admin = kafkaClient.admin(); + await admin.connect(); + await admin.createTopics({ + waitForLeaders: true, + topics: [{ topic }], + }); + log.info('createTopics'); + + if (mode === 'send') { + // On this mode we send some messages which are ingonerd as per agent config + // this must be executed 1st + producer = kafkaClient.producer(); + await producer.connect(); + log.info('producer connected'); + let data; + const tx = apm.startTransaction(`manual send to ${topic}`); + data = await producer.send({ + topic: topic, + messages: [{ value: 'message 1' }], + }); + log.info({ data }, 'messages sent'); + data = await producer.sendBatch({ + topicMessages: [ + { + topic: topic, + messages: [{ value: 'batch message 1' }], + }, + ], + }); + log.info({ data }, 'batch sent'); + tx.end(); + + await producer.disconnect(); + log.info('messages sent'); + } else if (mode === 'consume') { + // On this mode we consumen the already sent messsages. This time they are + // instrumented (not ignored) and trace context should be added to transactions + // this must be executed 2nd + consumer = kafkaClient.consumer({ groupId }); + await consumer.connect(); + await consumer.subscribe({ + topics: [topic], + fromBeginning: true, + }); + log.info('consumer connected'); + + let messagesConsumed = 0; + await consumer.run({ + eachMessage: async function ({ message }) { + log.info(`message received: ${message.value.toString()}`); + messagesConsumed++; + }, + }); + await waitUntil(() => messagesConsumed >= 2, 10000); + log.info('messages consumed'); + await consumer.disconnect(); + log.info('consumer disconnect'); + await admin.deleteTopics({ topics: [topic] }); + log.info('topics deleted'); + } + await admin.disconnect(); + log.info('admin disconnect'); +} + +// ---- helper functions + +/** + * Retuns a promise which is resolved when the predicate becomes true or rejected + * if the timeout is reached. + * @param {() => boolean} predicate function which will return true to make ed of wait + * @param {number} [timeout] max time in ms to wait for the predicste to be true (defaults to 5000) + * @returns {Promise} + */ +function waitUntil(predicate, timeout = 5000) { + const startTime = Date.now(); + + return new Promise((resolve, reject) => { + const intervalId = setInterval(() => { + const deltaTime = Date.now() - startTime; + + if (predicate()) { + clearInterval(intervalId); + resolve(); + } else if (deltaTime > timeout) { + clearInterval(intervalId); + reject(new Error(`timeout after ${deltaTime}ms`)); + } + }, 1000); + }); +} + +// ---- mainline + +function main() { + // Config vars. + const mode = process.env.TEST_MODE; + const clientId = process.env.TEST_CLIENT_ID || 'elastictest-kafka-client'; + const groupId = process.env.TEST_GROUP_ID || 'elastictest-kafka-group'; + const broker = process.env.TEST_KAFKA_HOST || 'localhost:9093'; + const topic = + process.env.TEST_TOPIC || + TEST_TOPIC_PREFIX + Math.floor(Math.random() * 1000); + + // Guard against any topic name being used because we will be sending and + // receiveing in it, and potentially *deleting* the topic. + if (!topic.startsWith(TEST_TOPIC_PREFIX)) { + throw new Error( + `cannot use topic name "${topic}", it must start with ${TEST_TOPIC_PREFIX}`, + ); + } + + if (!mode) { + throw new Error( + `cannot use ${__filename} wihtout a "TEST_MODE" set to "send|consume" in the env.`, + ); + } + + const kafkaClient = new Kafka({ clientId, brokers: [broker] }); + + useKafkajsClient(kafkaClient, { topic, groupId, mode }).then( + function () { + apm.logger.info(`useKafkajsClient in "${mode}" mode resolved`); + process.exitCode = 0; + }, + function (err) { + apm.logger.error(err, `useKafkajsClient in "${mode}" mode rejected`); + process.exitCode = 1; + }, + ); +} + +main(); diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js index cb28cb878e..eb63c8dc94 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js @@ -154,7 +154,7 @@ function main() { // receiveing in it, and potentially *deleting* the topic. if (!topic.startsWith(TEST_TOPIC_PREFIX)) { throw new Error( - `cannot use bucket name "${topic}", it must start with ${TEST_TOPIC_PREFIX}`, + `cannot use topic name "${topic}", it must start with ${TEST_TOPIC_PREFIX}`, ); } diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js index c3a372ad5b..d1a9b75e13 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js @@ -150,7 +150,7 @@ async function main() { // receiveing in it, and potentially *deleting* the topic. if (!topic.startsWith(TEST_TOPIC_PREFIX)) { throw new Error( - `cannot use bucket name "${topic}", it must start with ${TEST_TOPIC_PREFIX}`, + `cannot use topic name "${topic}", it must start with ${TEST_TOPIC_PREFIX}`, ); } diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index 7870f5b9a5..1e06e68ae8 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -109,7 +109,7 @@ const testFixtures = [ t.equal(spans.length, 0, 'all spans accounted for'); - // No check the transactions created for each message received + // Now check the transactions created for each message received const transactions = events .filter((e) => e.transaction) .map((e) => e.transaction); @@ -292,13 +292,11 @@ const testFixtures = [ t.equal(spans.length, 0, 'all spans accounted for'); - // No check the transactions created for each message received + // Now check the transactions created for each message received const transactions = events .filter((e) => e.transaction) .map((e) => e.transaction); - // NOTE: no checks like prev test since there is only on span - transactions.forEach((t) => { // Remove variable and common fields to facilitate t.deepEqual below. delete t.id; @@ -432,7 +430,7 @@ const testFixtures = [ t.equal(spans.length, 0, 'all spans accounted for'); - // No check the transactions created for each message received + // Now check the transactions created for each message received const transactions = events .filter((e) => e.transaction) .map((e) => e.transaction); @@ -538,6 +536,99 @@ const testFixtures = [ t.equal(transactions.length, 0, 'all transactions accounted for'); }, }, + { + name: 'simple Kafkajs usage scenario of context propagation while sending messages', + script: 'fixtures/use-kafkajs-ctx-propagation.js', + cwd: __dirname, + timeout: 20000, + env: { + TEST_CLIENT_ID: 'elastic-kafka-client', + TEST_GROUP_ID: `elastictest-kafka-group-${rand}`, + TEST_TOPIC: kafkaTopic, + TEST_KAFKA_HOST: kafkaHost, + TEST_CAPTURE_HEADERS: 'true', + TEST_MODE: 'send', + // Suppres warinings about new default partitioner + // https://kafka.js.org/docs/migration-guide-v2.0.0#producer-new-default-partitioner + KAFKAJS_NO_PARTITIONER_WARNING: '1', + }, + checkApmServer(t, apmServer) { + t.ok(apmServer.events[0].metadata, 'metadata'); + const events = sortApmEvents(apmServer.events); + const tx = events.shift().transaction; + + // First the transaction. + t.ok(tx, 'got the send transaction'); + + // Check topic is ignored + const spans = events.filter((e) => e.span).map((e) => e.span); + t.equal(spans.length, 0, 'there are no spans'); + }, + }, + { + name: 'simple Kafkajs usage scenario of context propagation while consuming messages', + script: 'fixtures/use-kafkajs-ctx-propagation.js', + cwd: __dirname, + timeout: 20000, + env: { + TEST_CLIENT_ID: 'elastic-kafka-client', + TEST_GROUP_ID: `elastictest-kafka-group-${rand}`, + TEST_TOPIC: kafkaTopic, + TEST_KAFKA_HOST: kafkaHost, + TEST_CAPTURE_HEADERS: 'true', + TEST_MODE: 'consume', + // Suppres warinings about new default partitioner + // https://kafka.js.org/docs/migration-guide-v2.0.0#producer-new-default-partitioner + KAFKAJS_NO_PARTITIONER_WARNING: '1', + }, + checkApmServer(t, apmServer) { + t.ok(apmServer.events[0].metadata, 'metadata'); + const events = sortApmEvents(apmServer.events); + + // Consuming does not generate spans + const spans = events.filter((e) => e.span).map((e) => e.span); + t.equal(spans.length, 0, 'there are no spans'); + + // Check the transactions fo consuming messages have the proper trace + const transactions = events + .filter((e) => e.transaction) + .map((e) => e.transaction); + + const firstTx = transactions.shift(); + const secondTx = transactions.shift(); + + t.equal( + firstTx.trace_id, + secondTx.trace_id, + 'all transactions have same trace ID', + ); + t.equal( + firstTx.parent_id, + secondTx.parent_id, + 'all transactions have same parent ID', + ); + t.ok( + firstTx.context.message.headers.traceparent, + 'first transactions have traceparent header', + ); + t.ok( + firstTx.context.message.headers.tracestate, + 'first transactions have tracestate header', + ); + t.equal( + firstTx.context.message.headers.traceparent, + secondTx.context.message.headers.traceparent, + 'all transactions have same traceparent', + ); + t.equal( + firstTx.context.message.headers.tracestate, + secondTx.context.message.headers.tracestate, + 'all transactions have same tracestate', + ); + + t.equal(transactions.length, 0, 'all transactions accounted for'); + }, + }, ]; test('kafkajs fixtures', (suite) => { From cb6b08e0109cc8cea01e81b48ec31093f90ee27f Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 14 Feb 2024 13:31:33 +0100 Subject: [PATCH 51/58] chore: fix span links --- .ci/tav.json | 4 +- lib/instrumentation/modules/kafkajs.js | 63 +++++++++++-------- test/docker-compose.yml | 1 + .../fixtures/use-kafkajs-each-message.js | 2 +- .../modules/kafkajs/kafkajs.test.js | 18 ++---- 5 files changed, 47 insertions(+), 41 deletions(-) diff --git a/.ci/tav.json b/.ci/tav.json index 41f84847d6..cf93c2fc6c 100644 --- a/.ci/tav.json +++ b/.ci/tav.json @@ -25,6 +25,7 @@ { "name": "generic-pool", "minMajorVersion": 8 }, { "name": "graphql", "minMajorVersion": 8 }, { "name": "ioredis", "minMajorVersion": 8 }, + { "name": "kafkajs", "minMajorVersion": 14 }, { "name": "knex", "minMajorVersion": 8 }, { "name": "memcached", "minMajorVersion": 8 }, { "name": "mongodb", "minMajorVersion": 8 }, @@ -40,7 +41,6 @@ { "name": "ws", "minMajorVersion": 8 }, { "name": "@koa/router,koa-router", "minMajorVersion": 8 }, { "name": "handlebars,pug", "minMajorVersion": 8 }, - { "name": "bluebird,got", "minMajorVersion": 8 }, - { "name": "kafkajs", "minMajorVersion": 14 } + { "name": "bluebird,got", "minMajorVersion": 8 } ] } diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index 4dc552b219..3be2cd7cd1 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -12,6 +12,7 @@ const semver = require('semver'); const constants = require('../../constants'); const shimmer = require('../shimmer'); +const { redactKeysFromObject } = require('../../filters/sanitize-field-names'); const NAME = 'Kafka'; const TYPE = 'messaging'; @@ -103,6 +104,10 @@ module.exports = function (mod, agent, { version, enabled }) { return origEachMessage.apply(this, arguments); } + // For distributed tracing this instrumentation is going to check + // the headers defined by opentelemetry and ignore the propietary + // `elasticaapmtraceparent` header + // https://github.com/elastic/apm/blob/main/specs/agents/tracing-distributed-tracing.md#binary-fields const traceparent = message.headers && message.headers.traceparent; const tracestate = message.headers && message.headers.tracestate; const opts = {}; @@ -137,18 +142,18 @@ module.exports = function (mod, agent, { version, enabled }) { } if (message.headers) { - messageCtx.headers = Object.keys(message.headers).reduce( - (acc, name) => { - const value = message.headers[name]; - if (value instanceof Buffer) { - acc[name] = value.toString('utf-8'); - } else { - acc[name] = value; - } - return acc; - }, - {}, + // Make sure there is no sensitive data + // and transform non-redacted buffers + messageCtx.headers = redactKeysFromObject( + message.headers, + config.sanitizeFieldNamesRegExp, ); + Object.keys(messageCtx.headers).forEach((key) => { + const value = messageCtx.headers[key]; + if (value instanceof Buffer) { + messageCtx.headers[key] = value.toString('utf-8'); + } + }); } if (message.timestamp) { @@ -192,10 +197,10 @@ module.exports = function (mod, agent, { version, enabled }) { return origEachBatch.apply(this, arguments); } - const trans = ins.startTransaction(`${NAME} RECEIVE from batch`, TYPE); - - // TODO: not sure if this should be here but we got batches for only one topic - // https://github.com/elastic/apm/blob/main/specs/agents/tracing-instrumentation-messaging.md#context-fields + const trans = ins.startTransaction( + `${NAME} RECEIVE from ${batch.topic}`, + TYPE, + ); const messageCtx = { queue: { name: batch.topic } }; trans.setMessageContext(messageCtx); @@ -210,6 +215,7 @@ module.exports = function (mod, agent, { version, enabled }) { const messages = batch && batch.messages; if (messages) { + const traceparentsSeen = new Set(); const links = []; const limit = Math.min( messages.length, @@ -218,8 +224,14 @@ module.exports = function (mod, agent, { version, enabled }) { for (let i = 0; i < messages.length; i++) { const msg = messages[i]; - if (msg.headers && msg.headers.traceparent) { - links.push({ context: msg.headers.traceparent.toString() }); + const traceparent = + msg.headers && + msg.headers.traceparent && + msg.headers.traceparent.toString(); + + if (traceparent && !traceparentsSeen.has(traceparent)) { + links.push({ context: traceparent }); + traceparentsSeen.add(traceparent); if (links.length >= limit) { break; @@ -299,7 +311,6 @@ module.exports = function (mod, agent, { version, enabled }) { parentSpan.propagateTraceContextHeaders( newHeaders, function (carrier, name, value) { - // TODO: why doing it everywhere??? if (name.startsWith('elastic-')) { return; } @@ -356,13 +367,15 @@ module.exports = function (mod, agent, { version, enabled }) { */ function wrapProducerSendBatch(origSendBatch) { return async function (batch) { - // TODO: discuss this. if all topics are ignored should the agent avoid - // creating a span? let span; - const topics = - batch.topicMessages && batch.topicMessages.map((tm) => tm.topic); - const shouldIgnoreBatch = - topics && topics.every((t) => shouldIgnoreTopic(t, config)); + let shouldIgnoreBatch = true; + const messages = batch.topicMessages || []; + for (const msg of messages) { + if (!shouldIgnoreTopic(msg.topic, config)) { + shouldIgnoreBatch = false; + break; + } + } if (!shouldIgnoreBatch) { span = ins.createSpan( @@ -386,7 +399,6 @@ module.exports = function (mod, agent, { version, enabled }) { parentSpan.propagateTraceContextHeaders( newHeaders, function (carrier, name, value) { - // TODO: why doing it everywhere??? if (name.startsWith('elastic-')) { return; } @@ -405,6 +417,7 @@ module.exports = function (mod, agent, { version, enabled }) { const destCtx = { // `service.name` and `service.resource` cannot be set since `producer.sendBatch` // is meant to send to several topics at a time + // TODO: check what the Java agent is doing service: { type: SUBTYPE }, target: { type: SUBTYPE }, }; diff --git a/test/docker-compose.yml b/test/docker-compose.yml index f5cfb1356e..8252071fc1 100644 --- a/test/docker-compose.yml +++ b/test/docker-compose.yml @@ -144,6 +144,7 @@ services: kafka: # https://hub.docker.com/r/bitnami/kafka/tags + # Config ref: https://github.com/bitnami/containers/tree/main/bitnami/kafka#how-to-use-this-image image: bitnami/kafka:3.3.2 ports: - "9093:9093" diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js index d1a9b75e13..4753fe7f0d 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js @@ -80,7 +80,7 @@ async function useKafkajsClient(kafkaClient, options) { messages: [ { value: 'each message 1', headers: { foo: 'string' } }, { value: 'each message 2', headers: { foo: Buffer.from('buffer') } }, - { value: 'each message 3' }, + { value: 'each message 3', headers: { auth: 'secret_token' } }, ], }); log.info({ data }, 'messages sent'); diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index 1e06e68ae8..51923d296c 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -49,6 +49,7 @@ const testFixtures = [ // Compare some common fields across all spans. // ignore http/external spans const spans = events.filter((e) => e.span).map((e) => e.span); + const parentId = spans[0].id; spans.forEach((s) => { const errs = validateSpan(s); t.equal(errs, null, 'span is valid (per apm-server intake schema)'); @@ -113,7 +114,6 @@ const testFixtures = [ const transactions = events .filter((e) => e.transaction) .map((e) => e.transaction); - const parentId = transactions[0].parent_id; t.equal( transactions.filter((t) => t.trace_id === tx.trace_id).length, @@ -132,7 +132,6 @@ const testFixtures = [ transactions.length, 'all transactions have positive age', ); - // TODO: other checks like sync=false & sample rate? // NOTE: messages could arrive in different order so we sort them // to properly do the assertions @@ -202,6 +201,7 @@ const testFixtures = [ message: { queue: { name: kafkaTopic }, headers: { + auth: '[REDACTED]', traceparent: `00-${tx.trace_id}-${parentId}-01`, tracestate: 'es=s:1', }, @@ -292,7 +292,7 @@ const testFixtures = [ t.equal(spans.length, 0, 'all spans accounted for'); - // Now check the transactions created for each message received + // Now check the transactions created const transactions = events .filter((e) => e.transaction) .map((e) => e.transaction); @@ -316,7 +316,7 @@ const testFixtures = [ // Check message handling transactions t.deepEqual(transactions.shift(), { - name: 'Kafka RECEIVE from batch', + name: `Kafka RECEIVE from ${kafkaTopic}`, type: 'messaging', context: { service: { framework: { name: 'Kafka' } }, @@ -327,14 +327,6 @@ const testFixtures = [ trace_id: tx.trace_id, span_id: spanId, }, - { - trace_id: tx.trace_id, - span_id: spanId, - }, - { - trace_id: tx.trace_id, - span_id: spanId, - }, ], outcome: 'success', @@ -453,7 +445,6 @@ const testFixtures = [ transactions.length, 'all transactions have positive age', ); - // TODO: other checks like sync=false & sample rate? // NOTE: messages could arrive in different order so we sort them // to properly do the assertions @@ -525,6 +516,7 @@ const testFixtures = [ message: { queue: { name: kafkaTopic }, headers: { + auth: '[REDACTED]', traceparent: `00-${tx.trace_id}-${parentId}-01`, tracestate: 'es=s:1', }, From 9ffb260f871c39c19b213aa99dd2e3627a5b1c2b Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 14 Feb 2024 16:43:02 +0100 Subject: [PATCH 52/58] chore: honor captureHeaders config option --- lib/instrumentation/modules/kafkajs.js | 2 +- .../fixtures/use-kafkajs-each-message.js | 2 - .../modules/kafkajs/kafkajs.test.js | 37 ++++++------------- 3 files changed, 12 insertions(+), 29 deletions(-) diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index 3be2cd7cd1..410b18eb38 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -141,7 +141,7 @@ module.exports = function (mod, agent, { version, enabled }) { messageCtx.body = message.value.toString(); } - if (message.headers) { + if (message.headers && config.captureHeaders) { // Make sure there is no sensitive data // and transform non-redacted buffers messageCtx.headers = redactKeysFromObject( diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js index 4753fe7f0d..d3ede96c11 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js @@ -15,8 +15,6 @@ const apm = require('../../../../..').start({ stackTraceLimit: 4, // get it smaller for reviewing output logLevel: 'info', ignoreMessageQueues: ['*-ignore'], - captureBody: process.env.TEST_CAPTURE_BODY || 'off', - captureHeaders: process.env.TEST_CAPTURE_HEADERS || false, }); const { Buffer } = require('buffer'); diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index 51923d296c..2ca5a1056f 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -158,7 +158,9 @@ const testFixtures = [ delete t.context.message.age; }); - // Check message handling transactions + // Check message handling transactions. + // Headers should be captured by default and redacted + // according to the default value of `sanitizeFieldNames` t.deepEqual(transactions.shift(), { name: `Kafka RECEIVE from ${kafkaTopic}`, type: 'messaging', @@ -336,7 +338,7 @@ const testFixtures = [ }, }, { - name: 'simple Kafkajs usage scenario for headers and body capturing on message reception', + name: 'simple Kafkajs usage scenario for `captureHeaders=false` and `capturebody=all` on message reception', script: 'fixtures/use-kafkajs-each-message.js', cwd: __dirname, timeout: 20000, @@ -345,8 +347,8 @@ const testFixtures = [ TEST_GROUP_ID: `elastictest-kafka-group-${rand}`, TEST_TOPIC: kafkaTopic, TEST_KAFKA_HOST: kafkaHost, - TEST_CAPTURE_HEADERS: 'true', - TEST_CAPTURE_BODY: 'all', + ELASTIC_APM_CAPTURE_HEADERS: 'false', + ELASTIC_APM_CAPTURE_BODY: 'all', // Suppres warinings about new default partitioner // https://kafka.js.org/docs/migration-guide-v2.0.0#producer-new-default-partitioner KAFKAJS_NO_PARTITIONER_WARNING: '1', @@ -449,9 +451,9 @@ const testFixtures = [ // NOTE: messages could arrive in different order so we sort them // to properly do the assertions transactions.sort((t1, t2) => { - const header1 = t1.context.message.headers.foo || 'undefined'; - const header2 = t2.context.message.headers.foo || 'undefined'; - return header1 < header2 ? -1 : 1; + const body1 = t1.context.message.body || 'undefined'; + const body2 = t2.context.message.body || 'undefined'; + return body1 < body2 ? -1 : 1; }); transactions.forEach((t) => { // Remove variable and common fields to facilitate t.deepEqual below. @@ -479,12 +481,7 @@ const testFixtures = [ service: {}, message: { queue: { name: kafkaTopic }, - headers: { - foo: 'buffer', - traceparent: `00-${tx.trace_id}-${parentId}-01`, - tracestate: 'es=s:1', - }, - body: 'each message 2', + body: 'each message 1', }, }, outcome: 'success', @@ -497,12 +494,7 @@ const testFixtures = [ service: {}, message: { queue: { name: kafkaTopic }, - headers: { - foo: 'string', - traceparent: `00-${tx.trace_id}-${parentId}-01`, - tracestate: 'es=s:1', - }, - body: 'each message 1', + body: 'each message 2', }, }, outcome: 'success', @@ -515,11 +507,6 @@ const testFixtures = [ service: {}, message: { queue: { name: kafkaTopic }, - headers: { - auth: '[REDACTED]', - traceparent: `00-${tx.trace_id}-${parentId}-01`, - tracestate: 'es=s:1', - }, body: 'each message 3', }, }, @@ -538,7 +525,6 @@ const testFixtures = [ TEST_GROUP_ID: `elastictest-kafka-group-${rand}`, TEST_TOPIC: kafkaTopic, TEST_KAFKA_HOST: kafkaHost, - TEST_CAPTURE_HEADERS: 'true', TEST_MODE: 'send', // Suppres warinings about new default partitioner // https://kafka.js.org/docs/migration-guide-v2.0.0#producer-new-default-partitioner @@ -567,7 +553,6 @@ const testFixtures = [ TEST_GROUP_ID: `elastictest-kafka-group-${rand}`, TEST_TOPIC: kafkaTopic, TEST_KAFKA_HOST: kafkaHost, - TEST_CAPTURE_HEADERS: 'true', TEST_MODE: 'consume', // Suppres warinings about new default partitioner // https://kafka.js.org/docs/migration-guide-v2.0.0#producer-new-default-partitioner From 6437bfe44bf0a2ae114b00154eb12afd5d317309 Mon Sep 17 00:00:00 2001 From: David Luna Date: Wed, 14 Feb 2024 17:32:49 +0100 Subject: [PATCH 53/58] chore: tune propagetion context tests --- .../fixtures/use-kafkajs-ctx-propagation.js | 2 +- .../modules/kafkajs/kafkajs.test.js | 57 ++++++++++--------- 2 files changed, 32 insertions(+), 27 deletions(-) diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-ctx-propagation.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-ctx-propagation.js index dc6d425e88..dfe18730e3 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-ctx-propagation.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-ctx-propagation.js @@ -74,7 +74,7 @@ async function useKafkajsClient(kafkaClient, options) { await producer.disconnect(); log.info('messages sent'); } else if (mode === 'consume') { - // On this mode we consumen the already sent messsages. This time they are + // On this mode we consume the already sent messsages. This time they are // instrumented (not ignored) and trace context should be added to transactions // this must be executed 2nd consumer = kafkaClient.consumer({ groupId }); diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index 2ca5a1056f..ad66a2d93d 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -22,6 +22,9 @@ const kafkaHost = process.env.KAFKA_HOST || 'localhost:9093'; const rand = Math.floor(Math.random() * 1000); const kafkaTopic = `elasticapmtest-topic-each-${rand}`; +// this map will be used to stash data to be used among different tests +const store = new Map(); + /** @type {import('../../../_utils').TestFixture[]} */ const testFixtures = [ { @@ -538,6 +541,10 @@ const testFixtures = [ // First the transaction. t.ok(tx, 'got the send transaction'); + // Stash the trace context data to use it on the assertions of the next test + store.set('ctx-propagation-parent-id', tx.id); + store.set('ctx-propagation-trace-id', tx.trace_id); + // Check topic is ignored const spans = events.filter((e) => e.span).map((e) => e.span); t.equal(spans.length, 0, 'there are no spans'); @@ -566,44 +573,42 @@ const testFixtures = [ const spans = events.filter((e) => e.span).map((e) => e.span); t.equal(spans.length, 0, 'there are no spans'); + // Gat stashed data from previous test + const traceId = store.get('ctx-propagation-trace-id'); + const parentId = store.get('ctx-propagation-parent-id'); + // Check the transactions fo consuming messages have the proper trace const transactions = events .filter((e) => e.transaction) .map((e) => e.transaction); - const firstTx = transactions.shift(); - const secondTx = transactions.shift(); - - t.equal( - firstTx.trace_id, - secondTx.trace_id, - 'all transactions have same trace ID', - ); - t.equal( - firstTx.parent_id, - secondTx.parent_id, - 'all transactions have same parent ID', - ); t.ok( - firstTx.context.message.headers.traceparent, - 'first transactions have traceparent header', + transactions.every((t) => t.trace_id === traceId), + 'all transactions have the right trace_id', ); + t.ok( - firstTx.context.message.headers.tracestate, - 'first transactions have tracestate header', + transactions.every((t) => t.parent_id === parentId), + 'all transactions have the right parent_id', ); - t.equal( - firstTx.context.message.headers.traceparent, - secondTx.context.message.headers.traceparent, - 'all transactions have same traceparent', + + t.ok( + transactions.every((t) => { + const traceparent = t.context.message.headers.traceparent; + return traceparent === `00-${t.trace_id}-${parentId}-01`; + }), + 'all transactions have the right traceparent header', ); - t.equal( - firstTx.context.message.headers.tracestate, - secondTx.context.message.headers.tracestate, - 'all transactions have same tracestate', + + t.ok( + transactions.every((t) => { + const tracestate = t.context.message.headers.tracestate; + return tracestate === 'es=s:1'; + }), + 'all transactions have the right tracestate header', ); - t.equal(transactions.length, 0, 'all transactions accounted for'); + t.equal(transactions.length, 2, 'get the right amount of transactions'); }, }, ]; From 69b81b093c5813d8d903da12339556f24284feb0 Mon Sep 17 00:00:00 2001 From: David Luna Date: Thu, 15 Feb 2024 10:50:52 +0100 Subject: [PATCH 54/58] chore: make nits neat --- lib/instrumentation/modules/kafkajs.js | 10 +++++++++- .../kafkajs/fixtures/use-kafkajs-each-message.js | 2 +- test/instrumentation/modules/kafkajs/kafkajs.test.js | 2 +- 3 files changed, 11 insertions(+), 3 deletions(-) diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index 410b18eb38..e82bcdbfa6 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -370,8 +370,16 @@ module.exports = function (mod, agent, { version, enabled }) { let span; let shouldIgnoreBatch = true; const messages = batch.topicMessages || []; + const topics = new Set(); + + // Remove possible topic duplications for (const msg of messages) { - if (!shouldIgnoreTopic(msg.topic, config)) { + topics.add(msg.topic); + } + + // Check if the batch needs to be ignored + for (const t of topics) { + if (!shouldIgnoreTopic(t, config)) { shouldIgnoreBatch = false; break; } diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js index d3ede96c11..1511caae66 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-message.js @@ -78,7 +78,7 @@ async function useKafkajsClient(kafkaClient, options) { messages: [ { value: 'each message 1', headers: { foo: 'string' } }, { value: 'each message 2', headers: { foo: Buffer.from('buffer') } }, - { value: 'each message 3', headers: { auth: 'secret_token' } }, + { value: 'each message 3', headers: { auth: 'this_is_a_secret' } }, ], }); log.info({ data }, 'messages sent'); diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index ad66a2d93d..7fe643971e 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -341,7 +341,7 @@ const testFixtures = [ }, }, { - name: 'simple Kafkajs usage scenario for `captureHeaders=false` and `capturebody=all` on message reception', + name: 'simple Kafkajs usage scenario for `captureHeaders=false` and `captureBody=all` on message reception', script: 'fixtures/use-kafkajs-each-message.js', cwd: __dirname, timeout: 20000, From 2b238e994a3561016d4bf673fa5872bc81b28a73 Mon Sep 17 00:00:00 2001 From: David Luna Date: Fri, 23 Feb 2024 13:48:01 +0100 Subject: [PATCH 55/58] chore: check for single topic in sendBatch instrumentation --- lib/instrumentation/modules/kafkajs.js | 44 ++--- .../fixtures/use-kafkajs-each-batch.js | 4 +- .../modules/kafkajs/kafkajs.test.js | 158 +++++++++++++++++- 3 files changed, 181 insertions(+), 25 deletions(-) diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index e82bcdbfa6..0013c62adc 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -368,6 +368,7 @@ module.exports = function (mod, agent, { version, enabled }) { function wrapProducerSendBatch(origSendBatch) { return async function (batch) { let span; + let topicForContext; let shouldIgnoreBatch = true; const messages = batch.topicMessages || []; const topics = new Set(); @@ -377,22 +378,27 @@ module.exports = function (mod, agent, { version, enabled }) { topics.add(msg.topic); } - // Check if the batch needs to be ignored for (const t of topics) { - if (!shouldIgnoreTopic(t, config)) { - shouldIgnoreBatch = false; - break; + const topicIgnored = shouldIgnoreTopic(t, config); + + shouldIgnoreBatch = shouldIgnoreBatch && topicIgnored; + + // When a topic is not ignored we keep a copy for context unless + // we find a 2nd topic also not ignored. + if (!topicIgnored) { + if (topicForContext) { + topicForContext = undefined; + break; + } + topicForContext = t; } } if (!shouldIgnoreBatch) { - span = ins.createSpan( - `${NAME} send messages batch`, - TYPE, - SUBTYPE, - 'send', - { exitSpan: true }, - ); + const suffix = topicForContext ? ` to ${topicForContext}` : ''; + span = ins.createSpan(`${NAME} send${suffix}`, TYPE, SUBTYPE, 'send', { + exitSpan: true, + }); } // W3C trace-context propagation. @@ -422,15 +428,13 @@ module.exports = function (mod, agent, { version, enabled }) { return origSendBatch.apply(this, arguments); } - const destCtx = { - // `service.name` and `service.resource` cannot be set since `producer.sendBatch` - // is meant to send to several topics at a time - // TODO: check what the Java agent is doing - service: { type: SUBTYPE }, - target: { type: SUBTYPE }, - }; - - span._setDestinationContext(destCtx); + if (topicForContext) { + // We do not add headers or body because: + // - `record.messages` is a list + // - spec says is for transactions (https://github.com/elastic/apm/blob/main/specs/agents/tracing-instrumentation-messaging.md#transaction-context-fields) + span.setMessageContext({ queue: { name: topicForContext } }); + } + span.setServiceTarget(SUBTYPE, topicForContext); let result, err; try { diff --git a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js index eb63c8dc94..28232afcf2 100644 --- a/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js +++ b/test/instrumentation/modules/kafkajs/fixtures/use-kafkajs-each-batch.js @@ -6,6 +6,8 @@ 'use strict'; +const MUST_IGNORE_TOPIC = process.env.TEST_IGNORE_TOPIC === 'true'; + const apm = require('../../../../..').start({ serviceName: 'use-kafkajs', captureExceptions: false, @@ -14,7 +16,7 @@ const apm = require('../../../../..').start({ cloudProvider: 'none', stackTraceLimit: 4, // get it smaller for reviewing output logLevel: 'info', - ignoreMessageQueues: ['*-ignore'], + ignoreMessageQueues: MUST_IGNORE_TOPIC ? ['*-ignore'] : [], }); const { Buffer } = require('buffer'); diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index 7fe643971e..00a5dadf10 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -218,7 +218,7 @@ const testFixtures = [ }, }, { - name: 'simple Kafkajs usage scenario for batch message processing', + name: 'simple Kafkajs usage scenario for batch message processing with a single topic not ignored', script: 'fixtures/use-kafkajs-each-batch.js', cwd: __dirname, timeout: 20000, @@ -227,6 +227,7 @@ const testFixtures = [ TEST_GROUP_ID: `elastictest-kafka-group-${rand}`, TEST_TOPIC: kafkaTopic, TEST_KAFKA_HOST: kafkaHost, + TEST_IGNORE_TOPIC: 'true', // Suppres warinings about new default partitioner // https://kafka.js.org/docs/migration-guide-v2.0.0#producer-new-default-partitioner KAFKAJS_NO_PARTITIONER_WARNING: '1', @@ -280,8 +281,136 @@ const testFixtures = [ delete s.sample_rate; }); + // The 1st batch has only one topic which is not ignored + // so the span has message context and also + // - service.target.name + // - destination.service.resource t.deepEqual(spans.shift(), { - name: 'Kafka send messages batch', + name: `Kafka send to ${kafkaTopic}`, + type: 'messaging', + subtype: 'kafka', + action: 'send', + context: { + service: { target: { type: 'kafka', name: kafkaTopic } }, + destination: { + service: { type: '', name: '', resource: `kafka/${kafkaTopic}` }, + }, + message: { queue: { name: kafkaTopic } }, + }, + outcome: 'success', + }); + + t.equal(spans.length, 0, 'all spans accounted for'); + + // Now check the transactions created + const transactions = events + .filter((e) => e.transaction) + .map((e) => e.transaction); + + transactions.forEach((t) => { + // Remove variable and common fields to facilitate t.deepEqual below. + delete t.id; + delete t.parent_id; + delete t.trace_id; + delete t.timestamp; + delete t.duration; + delete t.sample_rate; + delete t.sampled; + delete t.span_count; + delete t.result; + delete t.context.user; + delete t.context.tags; + delete t.context.custom; + delete t.context.cloud; + }); + + // Check message handling transactions + t.deepEqual(transactions.shift(), { + name: `Kafka RECEIVE from ${kafkaTopic}`, + type: 'messaging', + context: { + service: { framework: { name: 'Kafka' } }, + message: { queue: { name: kafkaTopic } }, + }, + links: [ + { + trace_id: tx.trace_id, + span_id: spanId, + }, + ], + + outcome: 'success', + }); + + t.equal(transactions.length, 0, 'all transactions accounted for'); + }, + }, + { + name: 'simple Kafkajs usage scenario for batch message processing without ignored topics', + script: 'fixtures/use-kafkajs-each-batch.js', + cwd: __dirname, + timeout: 20000, + env: { + TEST_CLIENT_ID: 'elastic-kafka-client', + TEST_GROUP_ID: `elastictest-kafka-group-${rand}`, + TEST_TOPIC: kafkaTopic, + TEST_KAFKA_HOST: kafkaHost, + TEST_IGNORE_TOPIC: 'false', + // Suppres warinings about new default partitioner + // https://kafka.js.org/docs/migration-guide-v2.0.0#producer-new-default-partitioner + KAFKAJS_NO_PARTITIONER_WARNING: '1', + }, + checkApmServer(t, apmServer) { + t.ok(apmServer.events[0].metadata, 'metadata'); + const events = sortApmEvents(apmServer.events); + const tx = events.shift().transaction; + + // First the transaction. + t.ok(tx, 'got the send batch transaction'); + + // Compare some common fields across all spans. + // ignore http/external spans + const spans = events.filter((e) => e.span).map((e) => e.span); + const spanId = spans[0].id; + spans.forEach((s) => { + const errs = validateSpan(s); + t.equal(errs, null, 'span is valid (per apm-server intake schema)'); + }); + t.equal( + spans.filter((s) => s.trace_id === tx.trace_id).length, + spans.length, + 'all spans have the same trace_id', + ); + t.equal( + spans.filter((s) => s.transaction_id === tx.id).length, + spans.length, + 'all spans have the same transaction_id', + ); + t.equal( + spans.filter((s) => s.sync === false).length, + spans.length, + 'all spans have sync=false', + ); + t.equal( + spans.filter((s) => s.sample_rate === 1).length, + spans.length, + 'all spans have sample_rate=1', + ); + + spans.forEach((s) => { + // Remove variable and common fields to facilitate t.deepEqual below. + delete s.id; + delete s.transaction_id; + delete s.parent_id; + delete s.trace_id; + delete s.timestamp; + delete s.duration; + delete s.sync; + delete s.sample_rate; + }); + + t.deepEqual(spans.shift(), { + name: `Kafka send`, type: 'messaging', subtype: 'kafka', action: 'send', @@ -289,7 +418,6 @@ const testFixtures = [ service: { target: { type: 'kafka' } }, destination: { service: { type: '', name: '', resource: 'kafka' }, - target: { type: 'kafka' }, }, }, outcome: 'success', @@ -300,7 +428,12 @@ const testFixtures = [ // Now check the transactions created const transactions = events .filter((e) => e.transaction) - .map((e) => e.transaction); + .map((e) => e.transaction) + // We cannot ensure the order of the received batches so we have to sort + // to do the assertions properly + .sort((ta, tb) => { + return ta.name < tb.name ? -1 : 1; + }); transactions.forEach((t) => { // Remove variable and common fields to facilitate t.deepEqual below. @@ -337,6 +470,23 @@ const testFixtures = [ outcome: 'success', }); + t.deepEqual(transactions.shift(), { + name: `Kafka RECEIVE from ${kafkaTopic}-ignore`, + type: 'messaging', + context: { + service: { framework: { name: 'Kafka' } }, + message: { queue: { name: `${kafkaTopic}-ignore` } }, + }, + links: [ + { + trace_id: tx.trace_id, + span_id: spanId, + }, + ], + + outcome: 'success', + }); + t.equal(transactions.length, 0, 'all transactions accounted for'); }, }, From 0772a66a490167fbf361c33ed50404234b711b21 Mon Sep 17 00:00:00 2001 From: David Luna Date: Thu, 7 Mar 2024 21:02:38 +0100 Subject: [PATCH 56/58] Update test/instrumentation/modules/kafkajs/kafkajs.test.js Co-authored-by: Trent Mick --- test/instrumentation/modules/kafkajs/kafkajs.test.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index 00a5dadf10..f577a8ce7f 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -286,7 +286,7 @@ const testFixtures = [ // - service.target.name // - destination.service.resource t.deepEqual(spans.shift(), { - name: `Kafka send to ${kafkaTopic}`, + name: `Kafka SEND to ${kafkaTopic}`, type: 'messaging', subtype: 'kafka', action: 'send', From c2f1d184a796de0c5b5c11d4dadcb40ffbe2a64a Mon Sep 17 00:00:00 2001 From: David Luna Date: Thu, 7 Mar 2024 21:02:45 +0100 Subject: [PATCH 57/58] Update lib/instrumentation/modules/kafkajs.js Co-authored-by: Trent Mick --- lib/instrumentation/modules/kafkajs.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index 0013c62adc..bc6328f363 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -396,7 +396,7 @@ module.exports = function (mod, agent, { version, enabled }) { if (!shouldIgnoreBatch) { const suffix = topicForContext ? ` to ${topicForContext}` : ''; - span = ins.createSpan(`${NAME} send${suffix}`, TYPE, SUBTYPE, 'send', { + span = ins.createSpan(`${NAME} SEND${suffix}`, TYPE, SUBTYPE, 'send', { exitSpan: true, }); } From eaef6f84e2536cc1c01c3b47229d06dab863313f Mon Sep 17 00:00:00 2001 From: David Luna Date: Fri, 8 Mar 2024 09:52:23 +0100 Subject: [PATCH 58/58] chore: fix naming --- lib/instrumentation/modules/kafkajs.js | 2 +- test/instrumentation/modules/kafkajs/kafkajs.test.js | 6 +++--- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/lib/instrumentation/modules/kafkajs.js b/lib/instrumentation/modules/kafkajs.js index bc6328f363..e0849412e4 100644 --- a/lib/instrumentation/modules/kafkajs.js +++ b/lib/instrumentation/modules/kafkajs.js @@ -292,7 +292,7 @@ module.exports = function (mod, agent, { version, enabled }) { if (!shouldIgnoreTopic(topic, config)) { span = ins.createSpan( - `${NAME} send to ${topic}`, + `${NAME} SEND to ${topic}`, TYPE, SUBTYPE, 'send', diff --git a/test/instrumentation/modules/kafkajs/kafkajs.test.js b/test/instrumentation/modules/kafkajs/kafkajs.test.js index f577a8ce7f..206496efcc 100644 --- a/test/instrumentation/modules/kafkajs/kafkajs.test.js +++ b/test/instrumentation/modules/kafkajs/kafkajs.test.js @@ -91,7 +91,7 @@ const testFixtures = [ }); t.deepEqual(spans.shift(), { - name: `Kafka send to ${kafkaTopic}`, + name: `Kafka SEND to ${kafkaTopic}`, type: 'messaging', subtype: 'kafka', action: 'send', @@ -410,7 +410,7 @@ const testFixtures = [ }); t.deepEqual(spans.shift(), { - name: `Kafka send`, + name: `Kafka SEND`, type: 'messaging', subtype: 'kafka', action: 'send', @@ -555,7 +555,7 @@ const testFixtures = [ }); t.deepEqual(spans.shift(), { - name: `Kafka send to ${kafkaTopic}`, + name: `Kafka SEND to ${kafkaTopic}`, type: 'messaging', subtype: 'kafka', action: 'send',