DEV Community

Discussion on: Ultimate guide to concurrent logging in Node.js

View post
Collapse
 
cedpoilly profile image
Cedric •

Insightful 🎊

I have a question/suggestion for the longer-term:
Is it possible to refactor & use the Promise API for chaining asynchronous events? - I think it should solve the issue of deeply nested contexts.

@gajus thoughts?

Collapse
 
gajus profile image
Gajus Kuizinas •

The problem that Domains solve is inheritance from any asynchronous context, e.g.

Suppose that your application uses Slonik to run PostgreSQL queries, and you have updatePost function that is run concurrently:

const createPool = require('slonik').createPool;
const sql = require('slonik').sql;

const updatePost = async (pool, postId) => {
  await pool.query(sql`SELECT ${postId}`);
};

(async () => {
  const pool = createPool('postgres://');

  await Promise.all([
    updatePost(pool, 1),
    updatePost(pool, 2),
    updatePost(pool, 3),
  ]);
})();

The above program would produce logs:

[2020-02-01T01:43:31.710Z] DEBUG (20) (@slonik): created a new client connection
poolId:    01DZZ6NN2S2P4TD0CM8YJZKPK3
processId: 77955
stats:
  idleConnectionCount:  0
  totalConnectionCount: 3
  waitingRequestCount:  0

[2020-02-01T01:43:31.710Z] DEBUG (20) (@slonik): client is checked out from the pool
poolId:    01DZZ6NN2S2P4TD0CM8YJZKPK3
processId: 77955
stats:
  idleConnectionCount:  0
  totalConnectionCount: 3
  waitingRequestCount:  0

[2020-02-01T01:43:31.712Z] DEBUG (20) (@slonik): created a new client connection
poolId:    01DZZ6NN2S2P4TD0CM8YJZKPK3
processId: 77953
stats:
  idleConnectionCount:  0
  totalConnectionCount: 3
  waitingRequestCount:  0

[2020-02-01T01:43:31.712Z] DEBUG (20) (@slonik): client is checked out from the pool
poolId:    01DZZ6NN2S2P4TD0CM8YJZKPK3
processId: 77953
stats:
  idleConnectionCount:  0
  totalConnectionCount: 3
  waitingRequestCount:  0

[2020-02-01T01:43:31.712Z] DEBUG (20) (@slonik): created a new client connection
poolId:    01DZZ6NN2S2P4TD0CM8YJZKPK3
processId: 77954
stats:
  idleConnectionCount:  0
  totalConnectionCount: 3
  waitingRequestCount:  0

[2020-02-01T01:43:31.712Z] DEBUG (20) (@slonik): client is checked out from the pool
poolId:    01DZZ6NN2S2P4TD0CM8YJZKPK3
processId: 77954
stats:
  idleConnectionCount:  0
  totalConnectionCount: 3
  waitingRequestCount:  0

[2020-02-01T01:43:36.725Z] DEBUG (20) (@slonik): client connection is closed and removed from the client pool
poolId:    01DZZ6NN2S2P4TD0CM8YJZKPK3
processId: 77955
stats:
  idleConnectionCount:  2
  totalConnectionCount: 2
  waitingRequestCount:  0

[2020-02-01T01:43:36.725Z] DEBUG (20) (@slonik): client connection is closed and removed from the client pool
poolId:    01DZZ6NN2S2P4TD0CM8YJZKPK3
processId: 77954
stats:
  idleConnectionCount:  1
  totalConnectionCount: 1
  waitingRequestCount:  0

[2020-02-01T01:43:36.726Z] DEBUG (20) (@slonik): client connection is closed and removed from the client pool
poolId:    01DZZ6NN2S2P4TD0CM8YJZKPK3
processId: 77953
stats:
  idleConnectionCount:  0
  totalConnectionCount: 0
  waitingRequestCount:  0

If there was an issue with one of the query executions, the above logs would not be particularly useful, and there is no way to pass additional details to the logger.

Let's add Roarr.adopt:

const createPool = require('./src').createPool;
const sql = require('./src').sql;
const Roarr = require('roarr').default;

const updatePost = async (pool, postId) => {
  await Roarr.adopt(
    async () => {
      await pool.query(sql`SELECT ${postId}`);
    },
    {
      postId,
    },
  );
};

(async () => {
  const pool = createPool('postgres://');

  await Promise.all([
    updatePost(pool, 1),
    updatePost(pool, 2),
    updatePost(pool, 3),
  ]);
})();

The only change we did was wrap updatePost body in Roarr.adopt and now the logs contain meaningful context information (the postId):

[2020-02-01T01:49:41.046Z] DEBUG (20) (@slonik): created a new client connection
postId:    2
poolId:    01DZZ70XRJDS3W02FR36JZEJK5
processId: 78010
stats:
  idleConnectionCount:  0
  totalConnectionCount: 3
  waitingRequestCount:  0

[2020-02-01T01:49:41.046Z] DEBUG (20) (@slonik): client is checked out from the pool
postId:    2
poolId:    01DZZ70XRJDS3W02FR36JZEJK5
processId: 78010
stats:
  idleConnectionCount:  0
  totalConnectionCount: 3
  waitingRequestCount:  0

[2020-02-01T01:49:41.048Z] DEBUG (20) (@slonik): created a new client connection
postId:    1
poolId:    01DZZ70XRJDS3W02FR36JZEJK5
processId: 78011
stats:
  idleConnectionCount:  0
  totalConnectionCount: 3
  waitingRequestCount:  0

[2020-02-01T01:49:41.048Z] DEBUG (20) (@slonik): client is checked out from the pool
postId:    1
poolId:    01DZZ70XRJDS3W02FR36JZEJK5
processId: 78011
stats:
  idleConnectionCount:  0
  totalConnectionCount: 3
  waitingRequestCount:  0

[2020-02-01T01:49:41.048Z] DEBUG (20) (@slonik): created a new client connection
postId:    3
poolId:    01DZZ70XRJDS3W02FR36JZEJK5
processId: 78012
stats:
  idleConnectionCount:  0
  totalConnectionCount: 3
  waitingRequestCount:  0

[2020-02-01T01:49:41.049Z] DEBUG (20) (@slonik): client is checked out from the pool
postId:    3
poolId:    01DZZ70XRJDS3W02FR36JZEJK5
processId: 78012
stats:
  idleConnectionCount:  0
  totalConnectionCount: 3
  waitingRequestCount:  0

[2020-02-01T01:49:46.065Z] DEBUG (20) (@slonik): client connection is closed and removed from the client pool
postId:    2
poolId:    01DZZ70XRJDS3W02FR36JZEJK5
processId: 78010
stats:
  idleConnectionCount:  2
  totalConnectionCount: 2
  waitingRequestCount:  0

[2020-02-01T01:49:46.067Z] DEBUG (20) (@slonik): client connection is closed and removed from the client pool
postId:    1
poolId:    01DZZ70XRJDS3W02FR36JZEJK5
processId: 78011
stats:
  idleConnectionCount:  1
  totalConnectionCount: 1
  waitingRequestCount:  0

[2020-02-01T01:49:46.068Z] DEBUG (20) (@slonik): client connection is closed and removed from the client pool
postId:    3
poolId:    01DZZ70XRJDS3W02FR36JZEJK5
processId: 78012
stats:
  idleConnectionCount:  0
  totalConnectionCount: 0
  waitingRequestCount:  0

In a real-world scenario, Roarr.adopt would wrap large parts of your codebase whenever there is additional context information that needs to be added to the logs of descended operations. The added context information will appear with all the logs regardless of however deep in your code those asynchronous calls are made.