puzpuzpuz / cls-rtracer Goto Github PK

Hello, I can't make it work with HAPI (version 20).

I'm following the documentation :

const server: Server = hapiServer({
    host,
    (...)
})

await server.register({
  plugin: rTracer.hapiPlugin
})    

 (other plugins, routes, ...)

And in a route :

handler: (request: Request, h: ResponseToolkit) => {
  const requestId = rTracer.id()
  console.log(`requestId: ${requestId}`)

rTracer.id() always returns undefined

By debugging in rtracer.js, I can see that I enter als.enterWith with a generated id, but when the route handler is called als.getStore() alwasy returns undefined

What am I missing ?

When the cls-rtracer middleware is added before a logging middleware based on pino-http >= 7.1.0 the success messages (responses) are logged twice.

The problem happens since the merge of this PR in pino-http: pinojs/pino-http#219
So after this response event listener was added: res.on('close', onResFinished) in addition to the already existing one res.on('finish', onResFinished)

For further reference please check the rejected issue at pino-http: pinojs/pino-http#234
and the sample app to reproduce the issue provided by @Simon-Campbell : https://github.com/Simon-Campbell/pino-http-double-success

Hello,

We did a release two days ago that bumped many packages including a cls-rtracer bump from 2.6.0 to 2.6.1.
We quickly started experiencing memory leaks on all our services as shown below (sample).

We did rollback the release and then released again yesterday. By dumping the memory I did come to the conclusion that [email protected] was leaking. After rollbacking to 2.6.0 and deploying everything again, leaks have disappeared.

Can't share full heapdump but I did saw a pattern of increasing memory usage of cls-rtracer objects.

Then 7 minutes later

Also

Then 7 minutes later

We have a trace id coming from a third party service and would like to use that one, in that request for the logs in our service that calls it. is that possible? here is an example of what we are hoping for

const rTracer = require('cls-rtracer');

const fakeEndpoint = async (req, res) => {
  const traceIdFromThirdParty = req.traceId;
  
  rTracer.setId(traceIdFromThirdParty);
}

Remove redundant if:
https://github.com/puzpuzpuz/cls-rtracer/blob/master/index.js#L71

Hi,

Facing Issues with cls-tracer going out of context and returning id as 'undefined' while using it with redis.
There were some suggestions to use https://github.com/abhiche/cls-redis-patch.
Please let me know if there is any better way to resolve this.

I'm trying to access request id in a form-data request with file upload, I'm using runWithId if the request id is passed in headers otherwise expressMiddleware, but It says undefined. Please find the code below:

const express = require('express');
const app = express();
const RequestTracer = require('cls-rtracer');
const multipart = require('connect-multiparty');
const http = require('http');
const server = http.createServer(app);

app.use((req, res, next) => {
    console.log('app.js->reqId:', req.headers['reqid']); // request-100001

    if (req.headers['reqid']) {
        RequestTracer.runWithId(next, req.headers['reqid']);
    } else {
        RequestTracer.expressMiddleware()(req, res, next);
    }
});

// Form Data request with multipart middleware - Doesn't work
app.post('/upload', multipart(), (req, res, next) => {
    res.json({ reqId: RequestTracer.id() }); // undefined
});

// Form Data request without multipart middleware - Works
app.post('/formdata', (req, res, next) => {
    res.json({ reqId: RequestTracer.id() }); // undefined
});

// Works
app.get('/download', (req, res, next) => {
    res.json({ reqId: RequestTracer.id() }); // request-100001
});

const port = 3000;
server.listen(port);
console.log(`Listening on port: ${port}`);

Here's a repl to run it: https://replit.com/@rohitkhatri/cls-rtracer-code#index.js

It says undefined most of the times when id is passed, but works sometimes, but If the request id is not passed, It always works.

Can anyone please help me here?

In a setup where requestIdFactory is configured to return a map of particular Ids, when we use runWithId without the optional Id parameter, it should use that same requestIdFactory to assign a new map of the required Ids but with the current implementation, it is assigning a uuid id string.

Our app does some periodic polling, which is started by a setInterval and not an external call to our app. This call is missing a trace id. Would it be possible for us to manually set an ID before kicking of the async calls?

Or code is essentially this

export async function setupBroadcastPolling(client: SomeClient) {
  async function loadMessages() {
    try {
      const data = await loadBroadcastMessages(client);

      if (data) {
        broadcastMessages = data.messages;
      }
    } catch (error) {
      logger.error({ error }, 'Unable to poll broadcast messages');
    }
  }

  // reload every minute
  setInterval(loadMessages, 60 * 1000).unref();

  await loadMessages();
}

It would be great if we could have an ID in our logs in this case as well. In this case I'd love to somehow set an ID if it's missing within the loadMessages function. Our client does a bunch of logging as it works, which are all missing the request ID

Discovered this lib yesterday and it works perfectly for my needs, the main thing I have an issue with is that it is using uuid v1.Could you please upgrade, or allow us to initialize it with our own generation function?

See https://medium.com/@apechkurov/hi-gustavo-273b1de1d1f

I am using mongoose like below

require('mongoose').set('debug', function (collectionName, method, query, options) {
  logger.info(`db.${collectionName}.${method}(${JSON.stringify(query)}, ${JSON.stringify(options)});`);
});

I have configured my logger to append rTracer.id() when ever its found, above does never get the ID. even though its a http request.

• Add hapi.js support

This seems to be the only library I can find that will allow me to get a request ID from the request object, which I need for pino-http (pinojs/pino-http#63). So I'd love TypeScript support.

Hi, I had a question on the implementation for the Hapi plugin. I noticed that for the rest of the other framework middleware/plugins you use AsyncLocalStorage.run() but for the Hapi plugin enterWith() is used instead? Why is that and what is it about Hapi specifically that it had to be done this way?

From the Node docs

run() should be preferred over enterWith() unless there are strong reasons to use the latter method.

https://nodejs.org/api/async_context.html#asynclocalstorageenterwithstore

Thank you

Not an issue, but rather request. Fastify already uses Pino under the hood as de facto logger. I am struggling to integrate cls-tracer with Pino in Fastify, so far without success. Would it be possible to provide an example of using cls-traces with Pino in fastify?

See fastify/fastify#1731 (review)

Hi, I'm so impressed by cls-rtracer so I researched about cls and cls-hooked.

I'm creating my module using cls-hooked to learn deeply.

I've following and trying this post: here

However, It's a little bit different implemented code against your code.
https://github.com/puzpuzpuz/cls-rtracer/blob/master/index.js#L61

And my code is :

const traceId = (opts: { test: number } | undefined): Middleware => {
  return async (ctx: Context, next: Function) => {
    // req and res are event emitters. We want to access CLS context inside of their event callbacks
    clsNamespace.bindEmitter(ctx.req);
    clsNamespace.bindEmitter(ctx.res);

    const traceID = uuidv4();

    clsNamespace.run(() => {
      clsNamespace.set('traceID', traceID);
      return next();
    });
  };
};

I'm wondering why you didn't use clsNamespace.run() .
I think I'm not enough to understand at all. Is it same working code?

best wishes.

Steve.

This might be the dumbest question you've seen in your life or might be I'm doing something wrong. In past I've used this package and it worked like charm. But recently I wanted to use it in out existing app but I'm facing problem with same request id being used for multiple request. (Different routes even).

I'm attaching the sample app for reference. Please let me know if I'm doing something wrong or missing something.

"cls-rtracer": "^2.6.3",
"express": "^4.18.3",

const express = require('express');
const rTracer = require('cls-rtracer');

const app = express();

app.use(express.json());
app.use(express.urlencoded({ extended: true }));
app.use(rTracer.expressMiddleware());

// Middleware to set request ID in headers
app.use((req, res, next) => {
  const rTracerId = rTracer.id();
  req.headers['X-POC-Request-ID'] = rTracerId;
  res.header('X-POC-Request-ID', rTracerId);
  next();
});

app.get('/fast-route', (req, res) => {
  const requestId = rTracer.id();
  console.log('Request ID in fast-route:', requestId);

  logMe();

  res.status(200).json({ success: true, requestId });
});

app.get('/slow-route', async (req, res) => {
  const requestId = rTracer.id();
  console.log('Request ID in slow-route:', requestId);

  const response = await new Promise((resolve) => {
    setTimeout(() => {
      return resolve({ message: 'Timed Out....', requestId });
    }, 3000);
  });

  res.status(200).json({
    success: true,
    data: response,
  });
});

function logMe() {
  const requestId = rTracer.id();
  console.log('Request ID in logMe:', requestId);
}

// Start server
app.listen(3000, () => {
  console.log('Server is running on port 3000');
});

I spent about 2 hours and a good deal of coffee tracking this down and thought it might be beneficial to others.

TL;DR. calling app.use(rTracer.expressMiddleware()) before express-session middleware caused erratic logging behavior. Trace Ids were not correct/showing inconsistently.

In the troubleshooting section of the readme it says to open a github issue if we run across any issues around async calls. Even if this isn't that exact issue I thought I should let someone smarter than me know about it.

I was seeing sporadic tracer id logging happening. See the image below. As you can see there is the normal express started message. Then the log statements for the api requests through some custom authentication middleware. I call the endpoint a few times in the next few minutes. Then magically there is a log with the tracer id, then nothing, then tracer id again, but now its showing the same tracer id for four different requests.

I change the following middleware order from:

app.use(rTracer.expressMiddleware());
app.use(session(sessionOptions));
app.use(authenticationMiddleware);

to

app.use(session(sessionOptions));
app.use(rTracer.expressMiddleware());
app.use(authenticationMiddleware);

and no more issues.

So I am trying to include the request-id in my logging, but it doesn't work with koa-morgan.

Here's my code:

import Koa from "koa"
import morgan from "koa-morgan"
import rTracer from "cls-rtracer"

const app = new Koa()
app.use(rTracer.koaMiddleware())
app.use(getMorgan())

app.use(() => {
  console.log("it works here", getReqId())
})

app.listen(8080)

const getReqId = () => {
  return (rTracer.id() ?? "") as string
}

const getMorgan = () => {
  morgan.token("reqId", getReqId)
  return morgan("it doesn't work here  :reqId")
}

then when I run the app

> curl --location --request GET 'localhost:8080/'

it works here fc7170b0-b328-11ed-b4d4-11d1313525c1
it doesn't work here -

I found it used uuid1 as default implementation.

UUID v1 is unique in theory, but still has potential problem. As we know UUID v1 is generated by using a combination the host computers MAC address and the current date and time. I am worried about node.js cluster. Does it safe on node.js cluster on a single machine?

And also, for some systems, they use their own id generator, I think it should have a way to pass user's own generator.

This may be a dumb question, but i just wanted to be sure that if a route gets hit by x number of users at the same time (or you know, possibly very close cause we cant always recreate a real world scenario) that the trace ids will be different per question and its not depended on when u define/initial the library or specific to the folder.

thank you

IMHO peer dependencies are required if you are building plugins for some library. For example lets say you are building webpack plugin then webpack will become your peer dependency.

And some who is using webpack can use use your plugin.

But here I think we only need to use this library cls-rtracer, and I am not using cls-hooked.

By this logic I think we can add cls-hooked under your dependencies section from peerDependencies.

Any thoughts?

I can raise a pull request if you guys agree.

Hi, this question might be wrong but I want to customise the cls-rtracer with additional feature.

Along with requestId, I also want to pass a custom header value and retrieve it later and may be used in my logger to log the info. with requestIdFactory I could set a requestId. is it possible to save additional information in the same context, let's say some sessionId? In our application, both are different. Sometimes sessionId might not exist. storing requestId+sessionId as requestId seems not a solution rather feels like a hack.

Hello,

Thank you for the wonderful library. It's helped a bunch in terms of zeroing in on relevant log messages for a single request.

I have a feature request and was wondering what your thoughts might be around opening up cls-rtracer to have a generic request context object. Rather than simply providing an id that exists throughout the lifetime of the request, there's also a request context object that one can access and put in whatever they want.

Example use case:

Applications that have authorized actions can store the authorized account's id in the request context once authorized. This allows apps to always log an account_id in a single place when relevant, making tracing all of an account's actions very convenient.

2.0.0 (or an experimental version of the library) could start using AsyncLocalStorage instead of cls-hooked:
https://nodejs.org/api/async_hooks.html#async_hooks_class_asynclocalstorage

That should be done once AsyncLocalStorage is backported to Node.js v12.

At the moment TS typings are not validated at all. It would be nice to start doing that in CI builds.

See #14 for the original discussion.

good job !

my question is tha i am using restify （another nodejs framework），just wanna to know which plugin can i use ? thx!

Pretty self-explanatory

I want to pass an additional optional parameter as username to trace the HTTP request and log the entries. Currently, I am using rTracer.id() of cls-rtracer npm module in my express application to trace the http request. I would really appreciate if someone can help me to pass 'username' as an optional parameter using cls-tracer module.

From React Application, I am passing username in headers and making http request to node.js application. I want to capture username in express application and pass to my outbound service request(Node.js Micro service). In the Node.js Microservice, I want to trace the incoming request and log using Username

Hi guys!

I am new to javascript. Was trying to implement this with express and winston...

app.js

const rTracer = require("cls-rtracer");
const requestId = rTracer.id();
const { createLogger } = require("./logger"); //Here i define the transports and logic to add 
                                                                            // namespace of the file name. 
const logger = createLogger(__filename);
logger.debug("Created logger successfully");
const express = require("express");
const bodyParser = require("body-parser");

const app = express();

app.use(bodyParser.json());
app.use(rTracer.expressMiddleware());

app.use(
  "/graphql",
  graphqlHTTP({
    schema: graphQLSchema,
    rootValue: graphQLResolvers,
    graphiql: true
  })
);

app.listen(3001, () => logger.info("Listening on port 3001")); 

logger.js

  const rTracer = require("cls-rtracer");
  const { createLogger, transports, format } = require("winston");
  const packageInfo = require("../../package.json");
  const path = require("path");

function logger(filename, options = []) {
  let prefix = createPrefix(filename);
  ...
  const loggerConfig = {
    transports: []
  };
  const rid = rTracer.id();
  console.log(rid);

  loggerConfig.transports.push(
      new transports.Console({
        level: LOGGING_CLI_LEVEL,
        format: format.combine(
          format.timestamp(),
          format.label({
            label: `[${prefix}]`
          }),
          format.splat(),
          format.prettyPrint(),
          format.simple(),
          format.ms(),
          format.printf((msg) => {
            return colorizer.colorize(
              msg.level,
              `${msg.label} ${
                msg.timestamp
              } [request-id:${rid}] - ${msg.level.toUpperCase()}: ${
                msg.message
              } ${msg.ms}`
            );
          })
        )
      })
    );
  return createLogger({
    ...options,
    ...loggerConfig
  });

I get 2019-07-29T22:04:24.150Z [request-id:undefined] - INFO: Listening on port 3001 +0ms,
which i think i understand as it has not recieved a request yet. So the id reqId is generated by the middleware only right?
Now, the problem it seems to be in the way i use winston. i import and create the logger per module and as it is imported on load, it always get undefined. and then the reqId is never updated, and never .get from the store. Would be nice an example of multiple files where winston logger is imported. Any hints apreciatted :)

Just to add more context.

streams.js

const { createLogger } = require("../logger");
const logger = createLogger(__filename);
logger.debug("Created logger successfully");
const rTracer = require("cls-rtracer");

async function getData() {
  const requestId = rTracer.id();
  ...
  logger.info("Grabbing records from timestamp: " + timestamp); //get Undefined
  console.log(requestId); // Perfect. Same as in the middleware console.log test.
}

When passport.js is used with session:false the async context is lost and rTracer.id() stops returning an ID. I'm pretty sure this a similar issue as described in the README and #20. That said, it seems to be something slightly different, given that #20 is an issue with express-session and I've explicitly disabled sessions here.

Specifically I'm using passport.js configured to accept JWTs with passport-jwt, using code that looks something like this:

const express = require('express');
const jwt = require('express-jwt');
const passport = require('passport');
const passportJwt = require('passport-jwt');
const rTracer = require('cls-rtracer')

passport.use('jwt', new passportJwt.Strategy(/* jwt options */));

const app = express();

app.use(passport.initialize());

app.use(rTracer.expressMiddleware());

app.use((req, res, next) => {
	console.log(rTracer.id()); // prints an id
});

app.get('/foo',
	passport.authenticate('jwt', {session: false}),
	(req, res) => {
		console.log(rTracer.id()); // prints 'undefined' 
	}
);

app.get('/bar', (req, res) => {
	console.log(rTracer.id()); // prints an id 
});

I assume this is fundamentally an issue with either passport or passport-jwt, and so it's not fixable on your end. Your readme said to submit an issue, though, so I hope this is helpful.

It would be really helpful to know that how to use this package with WebSocket communications.
An example would be very useful too.

Related with #5

Running node with --trace-sync-io for an application that uses cls-rtracer outputs warnings such as this one:

(node:31771) WARNING: Detected use of sync API
    at randomBytes (internal/crypto/random.js:54:31)
    at nodeRNG ([...]/node_modules/cls-rtracer/node_modules/uuid/lib/rng.js:7:17)
    at v4 ([...]/node_modules/cls-rtracer/node_modules/uuid/v4.js:13:52)
    at [...]/node_modules/cls-rtracer/index.js:30:30
    at handle ([...]/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix ([...]/node_modules/express/lib/router/index.js:317:13)
    at [...]/node_modules/express/lib/router/index.js:284:7
    at process_params ([...]/node_modules/express/lib/router/index.js:335:12)
    at next ([...]/node_modules/express/lib/router/index.js:275:10)

Using a synchronous API is undesirable even if the randomBytes() function is normally very fast. If for no other reason, just for the fact that it makes --trace-sync-io much less useful when cls-rtracer creates a lot of noise.

I would expect that a UUID V1 should be plenty good enough for cls-rtracer. uuid.v1() is 5 times faster than uuid.v4() and does not trigger the "WARNING: Detected use of sync API" when run with --trace-sync-io as demonstrated by this little experiment:

$ cat experiment.js 
const uuid = require("uuid");
const { performance } = require("perf_hooks");

const iterations = 5000000;

let t_begin = performance.now();
for (let i = 0; i < iterations; ++i) {
    uuid.v1();
}
console.log(`${iterations} uuid.v1(): ${(performance.now() - t_begin).toFixed(0)} ms`);

t_begin = performance.now();
for (let i = 0; i < iterations; ++i) {
    uuid.v4();
}
console.log(`${iterations} uuid.v4(): ${(performance.now() - t_begin).toFixed(0)} ms`);

$ node experiment.js 
5000000 uuid.v1(): 2941 ms
5000000 uuid.v4(): 14589 ms

Is there any way to add new Ids to the existing ones that are already set up with rTracer?

e.g after having set it up with

    app.use(rTracer.koaMiddleware({
        requestIdFactory: (req) => ({
          correlationId: req.get('X-CorrelationId') || randomUUID(),
          otherVars...
        }),
      }));

And then later on, for example after we finish some authentication middleware, and we want to store some extra information only available after that middleware has completed.

So after we can add like Third Party contextual information or where the request came from etc.

Thanks!

Once Fastify v3 is released, it should be added into test suite. There should be at least one change to be done in order to support it: #30 (comment)

I am not able to read the rtracer.id() in the winston logger config file and set the value as separate attribute in the json log. Can someone please help if the similar is implemented with sample piece of code. Thanks

Is it possible to extend library support for versions greater than 10.4.0?

npm WARN notsup (current: {"node":"10.18.0","npm":"6.13.4"})
Unsupported engine for [email protected]: wanted: {"node":">=8.0.0 - <10.0.0 || >=10.4.0"}

It's a very useful toot, and I'd like to add it to my project!