Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

chore: better logging for config state and transaction sampling #4291

Merged
merged 2 commits into from
Nov 4, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
9 changes: 9 additions & 0 deletions CHANGELOG.asciidoc
Original file line number Diff line number Diff line change
Expand Up @@ -37,6 +37,15 @@ for the latest (4.x) releases. The 3.x branch will be maintained until
2024-03-07 (6 months after the 4.0.0 release).


==== Unreleased

[float]
===== Chores

* Improve trace-level logging to better support debugging central config
and transaction sampling issues.


[[release-notes-3.51.0]]
==== 3.51.0 - 2024/01/12

Expand Down
18 changes: 18 additions & 0 deletions lib/agent.js
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,7 @@ const errors = require('./errors');
const { InflightEventSet } = require('./InflightEventSet');
const Instrumentation = require('./instrumentation');
const { elasticApmAwsLambda } = require('./lambda');
const logging = require('./logging');
const Metrics = require('./metrics');
const parsers = require('./parsers');
const symbols = require('./symbols');
Expand Down Expand Up @@ -324,6 +325,23 @@ Agent.prototype.start = function (opts) {

this.logger.info(preambleData, 'Elastic APM Node.js Agent v%s', version);

if (!logging.isLoggerCustom(this.logger)) {
// Periodically dump the current config (delta from defaults) when logging
// at "trace"-level. This allows getting the effective config from a running
// agent by setting trace-level logging and getting 1 minute of logs.
// (Sometimes getting logs from application *start* is no possible.)
setInterval(() => {
if (this.logger.isLevelEnabled('trace')) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

could the level be changed at runtime? If not I think we could setInterval within this block.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes it can be changed at runtime via central config, and in the use case I needed this for that was the case.
I balked at integrating this change with central config handling.

However, I may do that for the main branch version of this change, because having a setInterval running all the time kinda sucks. On the other hand, having a setInterval (change in behaviour, however slight) that only turns on in "trace" made could mean more subtle bugs. It would be awful if there was a crash that only resulted from code that enabled when in "trace" mode. I'm talking generally.

try {
const currConfig = this._conf.getCurrConfig();
this.logger.trace({ currConfig }, 'currConfig');
} catch (err) {
this.logger.trace({ err }, 'error calculating currConfig');
}
}
}, 60 * 1000).unref();
}

if (isPreviewVersion) {
this.logger.warn(
'Version %s is a pre-release and not intended for use in production environments',
Expand Down
2 changes: 2 additions & 0 deletions lib/apm-client/apm-client.js
Original file line number Diff line number Diff line change
Expand Up @@ -72,6 +72,8 @@ function createApmClient(config, agent) {
!logging.isLoggerCustom(agent.logger)
) {
logging.setLogLevel(agent.logger, value);
// Hackily also set the HttpApmClient._log level.
logging.setLogLevel(client._log, value);
agent.logger.info(
`Central config success: updated logger with new logLevel: ${value}`,
);
Expand Down
22 changes: 22 additions & 0 deletions lib/config/config.js
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,7 @@ const {
DEFAULTS,
CROSS_AGENT_CONFIG_VAR_NAME,
URL_OPTS,
CENTRAL_CONFIG_OPTS,
} = require('./schema');

const {
Expand Down Expand Up @@ -288,6 +289,27 @@ class Config {
}
return loggable;
}

// Returns an object showing the current config, excluding default values.
getCurrConfig() {
const currConfig = {};

// Start with the values from the logging preamble. This selected keys
// that were specified, and handles redaction.
for (let [k, v] of Object.entries(this.loggingPreambleData.config)) {
currConfig[k] = v.value;
}

// Then add the current value of any var possibly set by central config.
currConfig.centralConfig = this.centralConfig;
if (this.centralConfig) {
for (let k of Object.values(CENTRAL_CONFIG_OPTS)) {
currConfig[k] = this[k];
}
}

return currConfig;
}
}

function readEnv() {
Expand Down
4 changes: 4 additions & 0 deletions lib/instrumentation/index.js
Original file line number Diff line number Diff line change
Expand Up @@ -542,6 +542,10 @@ Instrumentation.prototype.addEndedTransaction = function (transaction) {
!transaction.sampled &&
!agent._apmClient.supportsKeepingUnsampledTransaction()
) {
agent.logger.debug(
{ trans: transaction.id, trace: transaction.traceId },
'dropping unsampled transaction',
);
return;
}

Expand Down
1 change: 1 addition & 0 deletions lib/instrumentation/transaction.js
Original file line number Diff line number Diff line change
Expand Up @@ -92,6 +92,7 @@ function Transaction(agent, name, ...args) {
trans: this.id,
parent: this.parentId,
trace: this.traceId,
sampled: this.sampled,
name: this.name,
type: this.type,
subtype: this.subtype,
Expand Down
Loading