[Argus] better request tracing logs

[kdembler]

Currently Argus logs all HTTP requests with some basic data associated with them, like request headers, result status code and also responseTime that is populated by logging middleware. However, it's quite unclear what responseTime really represents and it doesn't give us much info. There's many reasons why an Argus node can be slow to respond, for example:

• slow disk lookup
• slow QN query
• slow SP communication
  If we're to be able to deal with those issues, we need more visibility into what is happening during request processing. I think some additional explicit (as in done by logic and not HTTP middleware) logging should be added and include various timing (mostly for points above) so distribution lead can collect that data and see what the issues are

[kdembler]

Also would be good to log response headers, not only request, so things like Content-Size can be aggregated to get idea on throughput

[bedeho]

@zeeshanakram3 would this be feasible ?

[kdembler]

I'm currently using logs from http level that are implicitly logged by a middleware. This is the data that I'm getting:

Details

"fields": { "meta": { "res": { "statusCode": 200 }, "responseTime": 23, "prematurelyClosed": false, "req": { "headers": { "x-b3-parentspanid": "3ebf6731ec618482", "x-b3-spanid": "94c637a094bc18af", "x-b3-traceid": "ccb9c98a684f798a", "x-b3-sampled": "false", "host": "127.0.0.1:3334", "connection": "close", "x-forwarded-for": "199.16.157.181", "accept-encoding": "gzip, deflate", "accept": "*/*", "user-agent": "Twitterbot/1.0", "x-b3-flags": "17155602618" }, "httpVersion": "1.0", "method": "GET", "query": {}, "originalUrl": "/api/v1/assets/2418", "url": "/api/v1/assets/2418" } } }

I would love to have the following data:

• asset ID
• status (missing/proxied/cached/etc)
• storage provider selected, if asset wasn't cached
• total bytes of content transferred
• total request processing time
• QN lookup time
• some details about storage provider performance if possible when proxying, ideally even bandwidth based on time and content size
• user-agent
• IP address
• status code

[zeeshanakram3]

@zeeshanakram3 would this be feasible ?

@bedeho I just created the PR to accomplish this. Now for each request, trace logs would include data points for all the internal spans e.g. QN, StorageNode, Disk read operations etc. The data would be exported to Elasticsearch and can be visualised as end-to-end request trace in Kibana with complete breakdown of time taken by each operation

The exported data also includes the information requested in the above comment.

Here is an example of a trace for GET api/v1/assets/:id request to distributor-node

[mnaamani]

the open-telemetry PR has covered many of the requirements suggested, to add more 'data' we can take advantage of the winston-elasticsearch module we are using and inject "custom" logs:

https://github.com/vanthome/winston-elasticsearch#logs-correlation-with-elastic-apm

We should investigate also if the express middleware loggin configuration can tweaked to add additional data into the fields it is producing.

[mnaamani]

Better yet since we now have instrumentation setup we should be able to add spans to an existing trace to include these additional custom pieces of information. https://opentelemetry.io/docs/instrumentation/js/manual/#traces

And what doesn't fit into a trace, we add a new meter for. https://opentelemetry.io/docs/instrumentation/js/manual/#metrics

[zeeshanakram3]

Addressed in #4779