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.

Sign up for GitHub

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

Jump to bottom

feat: postgresql responseHook support #528

Merged
merged 7 commits into from
Jun 28, 2021
Merged

feat: postgresql responseHook support #528

Show file tree
Hide file tree
Changes from 3 commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
3f8cdb0
feat: postgresql responseHook support
nata7che Jun 9, 2021
137f925
Merge branch 'main' into main
nata7che Jun 15, 2021
e7914ff
Merge branch 'main' into main
nata7che Jun 20, 2021
022f0f7
Merge branch 'main' into main
nata7che Jun 22, 2021
5f071f3
CR comments
nata7che Jun 23, 2021
0a6952a
Merge branch 'main' into main
nata7che Jun 24, 2021
38b78c6
CR comments
nata7che Jun 24, 2021
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
1 change: 1 addition & 0 deletions plugins/node/opentelemetry-instrumentation-pg/README.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -46,6 +46,7 @@ PostgreSQL instrumentation has few options available to choose from. You can set
| Options | Type | Description |
| ------- | ---- | ----------- |
| [`enhancedDatabaseReporting`](https://github.com/open-telemetry/opentelemetry-js-contrib/blob/main/plugins/node/opentelemetry-instrumentation-pg/src/pg.ts#L48) | `boolean` | If true, additional information about query parameters and results will be attached (as `attributes`) to spans representing database operations |
| `responseHook` | `PgInstrumentationExecutionResponseHook` (function) | Function for adding custom attributes from db response |

## Supported Versions

Expand Down
5 changes: 5 additions & 0 deletions plugins/node/opentelemetry-instrumentation-pg/src/index.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,3 +15,8 @@
*/

export * from './instrumentation';
export {
PgInstrumentationConfig,
PgInstrumentationExecutionResponseHook,
PgResponseHookInformation,
} from './types';
27 changes: 15 additions & 12 deletions plugins/node/opentelemetry-instrumentation-pg/src/instrumentation.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -36,6 +36,7 @@ import {
PostgresCallback,
PgPoolExtended,
PgPoolCallback,
PgInstrumentationConfig,
} from './types';
import * as utils from './utils';
import { AttributeNames } from './enums/AttributeNames';
Expand All @@ -45,17 +46,7 @@ import {
} from '@opentelemetry/semantic-conventions';
import { VERSION } from './version';

export interface PgInstrumentationConfig extends InstrumentationConfig {
/**
* If true, additional information about query parameters and
* results will be attached (as `attributes`) to spans representing
* database operations.
*/
enhancedDatabaseReporting?: boolean;
}

const PG_POOL_COMPONENT = 'pg-pool';

export class PgInstrumentation extends InstrumentationBase {
static readonly COMPONENT = 'pg';

Expand Down Expand Up @@ -134,7 +125,8 @@ export class PgInstrumentation extends InstrumentationBase {
span = utils.handleParameterizedQuery.call(
this,
plugin.tracer,
plugin._config as InstrumentationConfig & PgInstrumentationConfig,
plugin.getConfig() as PgInstrumentationConfig &
dyladan marked this conversation as resolved.
Show resolved Hide resolved
InstrumentationConfig,
query,
params
);
Expand All @@ -146,7 +138,8 @@ export class PgInstrumentation extends InstrumentationBase {
span = utils.handleConfigQuery.call(
this,
plugin.tracer,
plugin._config as InstrumentationConfig & PgInstrumentationConfig,
plugin.getConfig() as PgInstrumentationConfig &
InstrumentationConfig,
queryConfig
);
} else {
Expand All @@ -164,6 +157,8 @@ export class PgInstrumentation extends InstrumentationBase {
if (typeof args[args.length - 1] === 'function') {
// Patch ParameterQuery callback
args[args.length - 1] = utils.patchCallback(
plugin.getConfig() as PgInstrumentationConfig &
InstrumentationConfig,
span,
args[args.length - 1] as PostgresCallback
);
Expand All @@ -179,6 +174,8 @@ export class PgInstrumentation extends InstrumentationBase {
) {
// Patch ConfigQuery callback
let callback = utils.patchCallback(
plugin.getConfig() as PgInstrumentationConfig &
InstrumentationConfig,
span,
(args[0] as NormalizedQueryConfig).callback!
);
Expand All @@ -202,6 +199,12 @@ export class PgInstrumentation extends InstrumentationBase {
.then((result: unknown) => {
// Return a pass-along promise which ends the span and then goes to user's orig resolvers
return new Promise(resolve => {
Copy link
Member

Choose a reason for hiding this comment

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

I understand that nested new Promise was here before but it really is not needed.
You can just do the sync calls inside the then callback function and it behaves exactly the same.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

thanks @rauno56, I agree and also noticed it when writing this PR. However, and if that is alright with you, I'd prefer to leave this change to a different PR?

utils.handleExecutionResult(
plugin.getConfig() as PgInstrumentationConfig &
InstrumentationConfig,
span,
result
);
span.end();
resolve(result);
});
Expand Down
25 changes: 25 additions & 0 deletions plugins/node/opentelemetry-instrumentation-pg/src/types.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,31 @@

import * as pgTypes from 'pg';
import * as pgPoolTypes from 'pg-pool';
import type * as api from '@opentelemetry/api';
import { InstrumentationConfig } from '@opentelemetry/instrumentation';

export interface PgResponseHookInformation {
data: pgTypes.QueryResult | pgTypes.QueryArrayResult;
}

export interface PgInstrumentationExecutionResponseHook {
(span: api.Span, responseInfo: PgResponseHookInformation): void;
}

export interface PgInstrumentationConfig extends InstrumentationConfig {
/**
* If true, additional information about query parameters will be attached (as `attributes`) to spans representing
*/
enhancedDatabaseReporting?: boolean;
vmarchaud marked this conversation as resolved.
Show resolved Hide resolved

/**
* Hook that allows adding custom span attributes based on the data
* returned from "query" Pg actions.
*
* @default undefined
*/
responseHook?: PgInstrumentationExecutionResponseHook;
vmarchaud marked this conversation as resolved.
Show resolved Hide resolved
}

export type PostgresCallback = (err: Error, res: object) => unknown;

Expand Down
38 changes: 36 additions & 2 deletions plugins/node/opentelemetry-instrumentation-pg/src/utils.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -14,7 +14,13 @@
* limitations under the License.
*/

import { Span, SpanStatusCode, Tracer, SpanKind } from '@opentelemetry/api';
import {
Span,
SpanStatusCode,
Tracer,
SpanKind,
diag,
} from '@opentelemetry/api';
import { AttributeNames } from './enums/AttributeNames';
import {
SemanticAttributes,
Expand All @@ -27,9 +33,11 @@ import {
PgClientConnectionParams,
PgPoolCallback,
PgPoolExtended,
PgInstrumentationConfig,
} from './types';
import * as pgTypes from 'pg';
import { PgInstrumentation, PgInstrumentationConfig } from './';
import { PgInstrumentation } from './';
vmarchaud marked this conversation as resolved.
Show resolved Hide resolved
import { safeExecuteInTheMiddle } from '@opentelemetry/instrumentation';

function arrayStringifyHelper(arr: Array<unknown>): string {
return '[' + arr.toString() + ']';
Expand Down Expand Up @@ -161,7 +169,30 @@ export function handleInvalidQuery(
return result;
}

export function handleExecutionResult(
config: PgInstrumentationConfig,
span: Span,
pgResult: pgTypes.QueryResult | pgTypes.QueryArrayResult | unknown
) {
if (config.responseHook !== undefined && pgResult !== undefined) {
Copy link
Contributor

Choose a reason for hiding this comment

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

Same comment from the other "add responseHook", why explicitly only checking against undefined? Why not if (config.responseHook && pg...)

Or event better if (typeof config.responseHook === "function" && pg...)

Copy link
Member

Choose a reason for hiding this comment

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

I think we should just have if (typeof config.responseHook === "function") if user adds hook we should always run it whether the pgResult is undefined or not as this is also some kind of information for someone. Preventing running this hook in such case will confuse user why the hook didn't run soo I would definitely remove it.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

@obecny pushed 👍🏻 good idea!

safeExecuteInTheMiddle(
vmarchaud marked this conversation as resolved.
Show resolved Hide resolved
() => {
config.responseHook!(span, {
data: pgResult as pgTypes.QueryResult | pgTypes.QueryArrayResult,
});
},
err => {
if (err) {
diag.error('Error running response hook', err);
Copy link
Member

@blumamir blumamir Jun 13, 2021 •
edited
Loading

Choose a reason for hiding this comment

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

optional: I like to add a prefix to my logs so if it prints, there is context on where it's coming from. Something like: pg instrumentation: ${...}

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Great idea, I’d suggest implementing this (in a separate PR, of course) at the InstrumentationBase level so that it won't be necessary to manually add the prefix separately for each instrumentation class. WDYT?

Copy link
Member

Choose a reason for hiding this comment

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

I think it's a great idea :)

Copy link
Member

Choose a reason for hiding this comment

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

I now read the v0.21.0 release notes and looks like it was added there:
open-telemetry/opentelemetry-js#2261

Copy link
Member

Choose a reason for hiding this comment

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

It was indeed added on instrumentation but you should use this._diag from the instrumentation class to be able to use it. I think you'll need to give the instance class here to make it work

Copy link
Contributor Author

Choose a reason for hiding this comment

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

@vmarchaud, @blumamir for this PR I recommend not adding this change.
_diag is a protected member, it's accessible only internally within the class or any class that extends it but not externally. Since the pg instrumentation uses the utils module, passing the instrumentation will not be enough and a refactor is needed here.

Copy link
Member

Choose a reason for hiding this comment

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

Yes, I agree. We tried to refactor our instrumentations as well and bumped into the same issue, and decided not to use this component logger after all.
However, we made sure all the log prints are prefixed with ${packageName} instrumentation:, for example.

But I see there is no convention for the contrib instrumentations on that, so it's up to you.

Copy link
Member

@obecny obecny Jun 24, 2021 •
edited
Loading

Choose a reason for hiding this comment

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

why not passing the component logger to the util class directly from class when you call the util method ? @blumamir @nata7che in worst scenario I would change the signature to be public from protected instead of trying to mimic the behaviour of component diag logger. But it should be possible to simply pass the logger from class to util

}
},
true
);
}
}

export function patchCallback(
instrumentationConfig: PgInstrumentationConfig,
span: Span,
cb: PostgresCallback
): PostgresCallback {
Expand All @@ -176,7 +207,10 @@ export function patchCallback(
code: SpanStatusCode.ERROR,
message: err.message,
});
} else {
vmarchaud marked this conversation as resolved.
Show resolved Hide resolved
handleExecutionResult(instrumentationConfig, span, res);
Copy link
Member

Choose a reason for hiding this comment

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

Shouldn't we also call the response hook in the patchCallbackPGPool function below?
Probably not, as I see there are tests for that, but how come it works?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

The PgPool instrumentation added an additional patching to the pgPool.connect method, and uses the same query patching.

Copy link
Member

Choose a reason for hiding this comment

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

I have to admit I'm not very familiar with this instrumentation and its behavior.
So in what cases is "patchCallbackPGPool" being called?

}

span.end();
cb.call(this, err, res);
};
Expand Down
161 changes: 160 additions & 1 deletion plugins/node/opentelemetry-instrumentation-pg/test/pg-pool.test.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -24,7 +24,11 @@ import {
trace,
} from '@opentelemetry/api';
import { BasicTracerProvider } from '@opentelemetry/tracing';
import { PgInstrumentation } from '../src';
import {
PgInstrumentation,
PgInstrumentationConfig,
PgResponseHookInformation,
} from '../src';
import { AsyncHooksContextManager } from '@opentelemetry/context-async-hooks';
import * as testUtils from '@opentelemetry/test-utils';
import {
Expand Down Expand Up @@ -95,6 +99,11 @@ const runCallbackTest = (
};

describe('[email protected]', () => {
function create(config: PgInstrumentationConfig = {}) {
instrumentation.setConfig(config);
instrumentation.enable();
}

let pool: pgPool<pg.Client>;
let contextManager: AsyncHooksContextManager;
let instrumentation: PgInstrumentation;
Expand Down Expand Up @@ -130,6 +139,7 @@ describe('[email protected]', () => {
if (testPostgresLocally) {
testUtils.cleanUpDocker('postgres');
}

pool.end(() => {
done();
});
Expand Down Expand Up @@ -288,5 +298,154 @@ describe('[email protected]', () => {
assert.strictEqual(resNoPromise, undefined, 'No promise is returned');
});
});

describe('when specifying a responseHook configuration', () => {
const dataAttributeName = 'pg_data';
const query = 'SELECT 0::text';
const events: TimedEvent[] = [];

describe('AND valid responseHook', () => {
const pgPoolattributes = {
...DEFAULT_PGPOOL_ATTRIBUTES,
};
const pgAttributes = {
...DEFAULT_PG_ATTRIBUTES,
[SemanticAttributes.DB_STATEMENT]: query,
[dataAttributeName]: '{"rowCount":1}',
};

beforeEach(async () => {
const config: PgInstrumentationConfig = {
enhancedDatabaseReporting: true,
responseHook: (
span: Span,
responseInfo: PgResponseHookInformation
) =>
span.setAttribute(
dataAttributeName,
JSON.stringify({ rowCount: responseInfo?.data.rowCount })
),
};

create(config);
});

it('should attach response hook data to resulting spans for query with callback ', done => {
const parentSpan = provider
.getTracer('test-pg-pool')
.startSpan('test span');
context.with(trace.setSpan(context.active(), parentSpan), () => {
const resNoPromise = pool.query(query, (err, result) => {
if (err) {
vmarchaud marked this conversation as resolved.
Show resolved Hide resolved
return done(err);
}
runCallbackTest(
parentSpan,
pgPoolattributes,
events,
unsetStatus,
2,
0
);
runCallbackTest(
parentSpan,
pgAttributes,
events,
unsetStatus,
2,
1
);
done();
});
assert.strictEqual(
resNoPromise,
undefined,
'No promise is returned'
);
});
});

it('should attach response hook data to resulting spans for query returning a Promise', async () => {
const span = provider
.getTracer('test-pg-pool')
.startSpan('test span');
await context.with(
trace.setSpan(context.active(), span),
async () => {
const result = await pool.query(query);
runCallbackTest(
span,
pgPoolattributes,
events,
unsetStatus,
2,
0
);
runCallbackTest(span, pgAttributes, events, unsetStatus, 2, 1);
assert.ok(result, 'pool.query() returns a promise');
Copy link
Member

Choose a reason for hiding this comment

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

result here was already awaited, right? so it's not a promise, it's the actual response for the invocation. Not sure what this assertion is meant to test... (but I don't mind if it stays here as well).

}
);
});
});

describe('AND invalid responseHook', () => {
const pgPoolattributes = {
...DEFAULT_PGPOOL_ATTRIBUTES,
};
const pgAttributes = {
...DEFAULT_PG_ATTRIBUTES,
[SemanticAttributes.DB_STATEMENT]: query,
};

beforeEach(async () => {
create({
enhancedDatabaseReporting: true,
responseHook: (
span: Span,
responseInfo: PgResponseHookInformation
) => {
throw 'some kind of failure!';
},
});
});

it('should not do any harm when throwing an exception', done => {
const parentSpan = provider
.getTracer('test-pg-pool')
.startSpan('test span');
context.with(trace.setSpan(context.active(), parentSpan), () => {
const resNoPromise = pool.query(query, (err, result) => {
if (err) {
return done(err);
}
assert.ok(result);

runCallbackTest(
parentSpan,
pgPoolattributes,
events,
unsetStatus,
2,
0
);
runCallbackTest(
parentSpan,
pgAttributes,
events,
unsetStatus,
2,
1
);
done();
});
assert.strictEqual(
resNoPromise,
undefined,
'No promise is returned'
);
});
});
});
});
});
});
Loading