Pipeline callback calls fastify.log.error even though `err` is undefined

[matteosacchetto]

Prerequisites

• [X] I have written a descriptive issue title
• [X] I have searched existing issues to ensure the bug has not already been reported

Fastify version

4.25.2

Plugin version

2.0.1

Node.js version

18.19.0

Operating system

Linux

Operating system version (i.e. 20.04, 11.3, 10)

22.04

Description

Today I was experimenting with using this module, and I noticed that when this plugin is enabled, on the fastify output log, every request has an additional logged line with "level": "50" (an error log), with an empty message.

Example output

...
{"level":30,"time":1705854780559,"pid":218554,"hostname":"pop-os","reqId":"req-1","req":{"method":"GET","url":"/","hostname":"localhost:3000","remoteAddress":"::ffff:127.0.0.1","remotePort":39902},"msg":"incoming request"}
{"level":50,"time":1705854780586,"pid":218554,"hostname":"pop-os"}
{"level":30,"time":1705854780593,"pid":218554,"hostname":"pop-os","reqId":"req-1","res":{"statusCode":304},"responseTime":33.166690999642015,"msg":"request completed"}
...

While tracking down where it originated from, I found out that this log was added every time a stream was fully done.

I looked through the source code of the plugin, and noticed that multiple times, the pipeline function is used. For example in the following lines: https://github.com/fastify/fastify-throttle/blob/f3c385791486be581f5577e96113e66c2f8bb4e5/index.js#L44-L48

According to the documentation a check on the value of the err variable needs to be performed to asses if the pipeline terminated with an error or it was successful.

Throughout the index.js i noticed that the check is missing in all of the pipelines. That appears to be the cause for the empty error log I noticed. In the current scenario, the value of err for correctly terminated pipelines is undefined, thus the log is without any message.

Adding the check on the err solves the issue

Steps to Reproduce

Here is the link to a repository which reproduces the issue: https://github.com/matteosacchetto/fastify-throttle-additional-error-log

Expected Behavior

The additional error log should not appear when the pipeline terminates correctly

[Uzlopak]

Nice. Thank you for the Feedback. I implemented this plugin without knowing if it would be used soon. So it is great to see some usage ;)

Very good catch.

Basically we need to change it to

err => { err && fastify.log.error(err) }

Can you provide a PR, please?

[matteosacchetto]

Sure! Will open a PR soon.

Though, i do prefer the if w.r.t. the && Something like this

err => { if(err) fastify.log.error(err) }

[matteosacchetto]

Any suggestion on how to test that additional check? I am not sure how to test for that 😅 ...

[Uzlopak]

Sure. When you instantiate the fastify instance you provide a custom logger. That logger has for the error method in the no error case a t.error call and in the error case you check for the Error

[matteosacchetto]

I tried following that strategy, but the issue I am facing is that I am not sure how to consistently get the pipeline to raise an error which will hit the error callback, where we have the check to test I am even questioning if for string and Buffer responses an error could get raised at all or not.

If you know of a way to generate an error which would hit that callback please let me know!

I am currently stuck on this, and I am not able to add test for this change.

[Uzlopak]

If it is only to satisfy the 100% test coverage, you could use t.mockRequire to mock Readable and instead provide a function which instantiates a PassThrough stream, which errors at the first push. https://node-tap.org/plugins/mock/

You could also instead of having to cover all cases extract the callback function.

const pipelineCallback = err => err && fastify.logger error(err)

return pipeline(
          Readable.from(Buffer.from(payload)),
          new ThrottleStream({ bytesPerSecond }),
          pipelineCallback
        )