Extend HTTP request node to log detailed timing information

[k-toumura]

• Bugfix (non-breaking change which fixes an issue)
• New feature (non-breaking change which adds functionality)

Proposed changes

The current HTTP request node output the time spent on HTTP requests as a metric log(node.http request.duration.mills), but it does not provide a breakdown of the time spent on HTTP request, such as DNS resolution, and TCP connection establishment, which hinders failure analysis.

The got package, used in HTTP request node, can obtain these detailed timing information as a result of HTTP requests. This PR use this feature to add a function to output the detailed timing information as a metric log.

An example of metric log is shown below:

    23 Aug 11:52:27 - [metric] {"level":99,"nodeid":"15576e5393f5cb94","event":"node.http request.duration.millis","msgid":"11c38881d7cf926f","value":"215.305","timestamp":1629687147857}
    23 Aug 11:52:27 - [metric] {"level":99,"nodeid":"15576e5393f5cb94","event":"node.http request.size.bytes","msgid":"11c38881d7cf926f","value":15079,"timestamp":1629687147857}
    23 Aug 11:52:27 - [metric] {"level":99,"nodeid":"15576e5393f5cb94","event":"node.http request.timings.start","msgid":"11c38881d7cf926f","value":1629687147645,"timestamp":1629687147857}
    23 Aug 11:52:27 - [metric] {"level":99,"nodeid":"15576e5393f5cb94","event":"node.http request.timings.socket","msgid":"11c38881d7cf926f","value":1629687147712,"timestamp":1629687147857}
    23 Aug 11:52:27 - [metric] {"level":99,"nodeid":"15576e5393f5cb94","event":"node.http request.timings.lookup","msgid":"11c38881d7cf926f","value":1629687147712,"timestamp":1629687147857}
    23 Aug 11:52:27 - [metric] {"level":99,"nodeid":"15576e5393f5cb94","event":"node.http request.timings.connect","msgid":"11c38881d7cf926f","value":1629687147712,"timestamp":1629687147857}
    23 Aug 11:52:27 - [metric] {"level":99,"nodeid":"15576e5393f5cb94","event":"node.http request.timings.secureConnect","msgid":"11c38881d7cf926f","value":1629687147762,"timestamp":1629687147857}
    23 Aug 11:52:27 - [metric] {"level":99,"nodeid":"15576e5393f5cb94","event":"node.http request.timings.upload","msgid":"11c38881d7cf926f","value":1629687147762,"timestamp":1629687147857}
    23 Aug 11:52:27 - [metric] {"level":99,"nodeid":"15576e5393f5cb94","event":"node.http request.timings.response","msgid":"11c38881d7cf926f","value":1629687147846,"timestamp":1629687147858}
    23 Aug 11:52:27 - [metric] {"level":99,"nodeid":"15576e5393f5cb94","event":"node.http request.timings.end","msgid":"11c38881d7cf926f","value":1629687147856,"timestamp":1629687147858}

Related discussion in PR#2952

Checklist

• I have read the contribution guidelines
• For non-bugfix PRs, I have discussed this change on the forum/slack team.
• I have run grunt to verify the unit tests pass
• I have added suitable unit tests to cover the new/changed functionality

[coveralls]

Coverage decreased (-0.06%) to 67.596% when pulling 490547c on node-red-hitachi:dev-httpreqlog into f1e7ec0 on node-red:dev.

[knolleary]

Thanks for linking to the previous discussion about this. In that discussion I shared a concern about doing this work:

I'm also not keen in exposing things the module gives us directly - because if we ever have to move off the got module, then it's even more work to reproduce the same behaviour.

But there was no further discussion about those concerns - so before we merge this, we need to complete that discussion.

Emitting all of these extra metrics for every single request is going to generate a lot of extra metrics messages. Do we have absolute confidence that these metrics are required? Should they be more 'trace' level messages that can be used when debugging an issue?

Should there be an option setting to either turn on or off this extra level of message?

[k-toumura]

Thanks for linking to the previous discussion about this. In that discussion I shared a concern about doing this work:

I'm also not keen in exposing things the module gives us directly - because if we ever have to move off the got module, then it's even more work to reproduce the same behaviour.

But there was no further discussion about those concerns - so before we merge this, we need to complete that discussion.

got is using http-timer package to measure the timing of HTTP request. To reproduce the same behaviour on another package, we need to choose a package that can use http-timer package (i.e., one that can get an instance of http.ClientRequest class). For example, axios doesn't provide such APIs, unfortunately...

Emitting all of these extra metrics for every single request is going to generate a lot of extra metrics messages. Do we have absolute confidence that these metrics are required? Should they be more 'trace' level messages that can be used when debugging an issue?
Should there be an option setting to either turn on or off this extra level of message?

Detailed timing information is mostly used for debugging purposes.
I'm going to update this PR, what do you think is the best policy?

• Add a configuration item to the each HTTP request node to output timing information to metric log.
• Add a configuration item to settings.js to output timing information to metric log.
• Output timing information to trace log

[k-toumura]

Commit 490547c adds an option setting httpRequestTimingLog in settings.js.

[dceejay]

In order to keep the settings.js file in some sort of structure - would it make sense for this property to be under the existing logging property section ?

[k-toumura]

In this case, I put this property at the top level as one of the Node Settings since it is a setting for a single node type (just like debugUseColors is not in logging property section). However, I'm also not sure whether to put the property in logging property section or node settings section...

[knolleary]

We have no precedent for adding node-specific properties under the logging section.

I'm happy to go with this as proposed. Thanks @k-toumura

[knolleary]

As all commits in this PR were made under the JS CLA and we have the green-tick from that bot, we can merge this as-is.