I'm setting up Cloud Elastic APM with a node/express/postgres server. The web requests are coming in as expected, however, only the postgresql START and COMMIT commands from the transactions are being shown but not the queries themselves.
When I set the logs to "trace", I can see the query is being intercepted from pg (see below), but for some reason it's not logged. The only difference between the queries that are logged (START/COMMIT) and the ones that are not, is that the ones logged have IDs and the main query does not. However, I'm not sure if that's important. I also notice that it says "no active transaction found - cannot build new span".
I have enabled the pg_stat_statements extension in postgres as recommended in this post. However, I'm not sure that would do anything since it appears that the APM module intercepts queries directly from pg.
Stack:
- Elastic/APM Cloud: v7.x (not sure where to find the version in the web UI)
- Postgres: v14.1
- Express: v4.17.1
- NodeJS: v14.15.0
- elastic-apm-node: v3.25.0
- TypeScript: v3.9.3
- Knex: v0.21.19
- Objection: v2.2.2
Test Express Route
app.get('/testQueryTrace', testQueryTraceRoute);
export const testQueryTraceRoute = async (req, res, next) => {
try {
// Simple Postgres transaction wrapper
const account = await withTransaction(({ trx }) => {
return AccountModel.query(trx).limit(1);
});
return res.status(200).send({ account });
} catch (err) {
next(err);
}
};
export const withTransaction = async <T>(cb: TransactionCB<T>): Promise<T> => {
const trx = await startTransaction();
const dataStore = new PostgresDataSource(trx);
try {
const result = await cb(dataStore);
await trx.commit();
return result;
} catch (err) {
if (!trx.isCompleted()) {
await trx.rollback();
}
throw err;
}
};
Logs
For a single request to the test route.
{"message":"intercepted request event call to http.Server.prototype.emit for /testQueryTrace"}
{"message":"start trace {\"trans\":\"f2c4fc7a588c6350\",\"trace\":\"acd249e81967cfe7d8e8fcaac71e9a1a\",\"name\":\"unnamed\",\"type\":null,\"subtype\":null,\"action\":null}"}
{"message":"supersedeWithTransRunContext(<Trans f2c4fc7a588c6350>)"}
{"message":"start span {\"span\":\"806b9e53c0c9bf17\",\"parent\":\"f2c4fc7a588c6350\",\"trace\":\"acd249e81967cfe7d8e8fcaac71e9a1a\",\"name\":\"SQL\",\"type\":\"db\",\"subtype\":\"postgresql\",\"action\":\"query\"}"}
{"message":"supersedeWithSpanRunContext(<Span 806b9e53c0c9bf17>)"}
{"message":"intercepted call to pg.Client.prototype.query {\"id\":\"f2c4fc7a588c6350\",\"sql\":\"BEGIN;\"}"}
{"message":"intercepted end of pg.Client.prototype.query {\"id\":\"f2c4fc7a588c6350\"}"}
{"message":"ended span {\"span\":\"806b9e53c0c9bf17\",\"parent\":\"f2c4fc7a588c6350\",\"trace\":\"acd249e81967cfe7d8e8fcaac71e9a1a\",\"name\":\"BEGIN\",\"type\":\"db\",\"subtype\":\"postgresql\",\"action\":\"query\"}"}
{"message":"addEndedSpan(BEGIN)"}
{"message":"encoding span {\"span\":\"806b9e53c0c9bf17\",\"parent\":\"f2c4fc7a588c6350\",\"trace\":\"acd249e81967cfe7d8e8fcaac71e9a1a\",\"name\":\"BEGIN\",\"type\":\"db\"}"}
{"message":"sending span {\"span\":\"806b9e53c0c9bf17\",\"parent\":\"f2c4fc7a588c6350\",\"trace\":\"acd249e81967cfe7d8e8fcaac71e9a1a\",\"name\":\"BEGIN\",\"type\":\"db\"}"}
{"message":"capturing custom stack trace for knex"}
{"message":"shimming knex runner.query"}
{"message":"intercepted call to knex runner.query"}
{"message":"no active transaction found - cannot build new span"}
{"message":"intercepted call to pg.Client.prototype.query {\"id\":null,\"sql\":\"select \\\"account\\\".* from \\\"account\\\" limit $1\"}"}
{"message":"start span {\"span\":\"c44fe6262140bc8e\",\"parent\":\"f2c4fc7a588c6350\",\"trace\":\"acd249e81967cfe7d8e8fcaac71e9a1a\",\"name\":\"SQL\",\"type\":\"db\",\"subtype\":\"postgresql\",\"action\":\"query\"}"}
{"message":"supersedeWithSpanRunContext(<Span c44fe6262140bc8e>)"}
{"message":"intercepted call to pg.Client.prototype.query {\"id\":\"f2c4fc7a588c6350\",\"sql\":\"COMMIT;\"}"}
{"message":"applying custom stack trace to span {\"span\":\"c44fe6262140bc8e\",\"parent\":\"f2c4fc7a588c6350\",\"trace\":\"acd249e81967cfe7d8e8fcaac71e9a1a\"}"}
{"message":"intercepted end of pg.Client.prototype.query {\"id\":\"f2c4fc7a588c6350\"}"}
{"message":"ended span {\"span\":\"c44fe6262140bc8e\",\"parent\":\"f2c4fc7a588c6350\",\"trace\":\"acd249e81967cfe7d8e8fcaac71e9a1a\",\"name\":\"COMMIT\",\"type\":\"db\",\"subtype\":\"postgresql\",\"action\":\"query\"}"}
{"message":"addEndedSpan(COMMIT)"}
{"message":"encoding span {\"span\":\"c44fe6262140bc8e\",\"parent\":\"f2c4fc7a588c6350\",\"trace\":\"acd249e81967cfe7d8e8fcaac71e9a1a\",\"name\":\"COMMIT\",\"type\":\"db\"}"}
{"message":"sending span {\"span\":\"c44fe6262140bc8e\",\"parent\":\"f2c4fc7a588c6350\",\"trace\":\"acd249e81967cfe7d8e8fcaac71e9a1a\",\"name\":\"COMMIT\",\"type\":\"db\"}"}
{"message":"setting transaction result {\"trans\":\"f2c4fc7a588c6350\",\"trace\":\"acd249e81967cfe7d8e8fcaac71e9a1a\",\"result\":\"HTTP 2xx\"}"}
{"message":"setting default transaction name: GET /testQueryTrace {\"trans\":\"f2c4fc7a588c6350\",\"trace\":\"acd249e81967cfe7d8e8fcaac71e9a1a\"}"}
{"message":"addEndedTransaction(GET /testQueryTrace)"}
{"message":"sending transaction {\"trans\":\"f2c4fc7a588c6350\",\"trace\":\"acd249e81967cfe7d8e8fcaac71e9a1a\"}"}
{"message":"ended transaction {\"trans\":\"f2c4fc7a588c6350\",\"trace\":\"acd249e81967cfe7d8e8fcaac71e9a1a\",\"type\":\"request\",\"result\":\"HTTP 2xx\",\"name\":\"GET /testQueryTrace\"}"}
{"message":"intake request start"}
{"message":"_writeBatch"}
{"message":"intakeReq \"socket\": unref it"}