You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@pinot.apache.org by GitBox <gi...@apache.org> on 2022/10/06 21:45:35 UTC
[GitHub] [pinot] dachaostripe opened a new issue, #9545: Tagging unique requestId or eventId to all logs across components
dachaostripe opened a new issue, #9545:
URL: https://github.com/apache/pinot/issues/9545
Currently there's no effective way of searching and gathering all related logs for a particular query or life cycle/control event. As of now, there's only a numeric requestId like `124927` being generated on broker and get sent to online and offline servers to tag a few log messages, but that doesn't include potential exceptions in case of errors. This can cause huge difficulties when troubleshooting errors in production
1. The simple numeric requestId is highly overlapped among hosts in the fleet, searching for such ids are likely to hit many unrelated logs from other hosts; using UUID or similar is a better choice.
2. Not tagging all related logs(especially exceptions) with the appropriate id means that we have no reliable way of finding the exact error for a given request, especially in high traffic environments where it's impossible to search for "nearby logs" to hopefully find related errors
3. There are similar needs for requests received from controller, and life cycle events detected by ZooKeeper, or new online/offline servers notifying it joining the cluster, etc.
Ideally
1. both broker and controller APIs should also accept a special header, like `x-pinot-request-id`, to allow the client to provide an ID that Pinot will use to tag its logs, to allow better correlation with client side logs
2. broker and controller will only generate a unique ID in case `x-pinot-request-id` isn't provided by client; or when this is an internally initiated events, like new hosts joining, unhealthy host detected etc.
3. Broker and controller should also include `x-pinot-request-id` header in the response to client, so client can potentially log it, which is also useful for look up related Pinot logs, in case for some reasons the client doesn't provide this id when making the requests.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org
For additional commands, e-mail: commits-help@pinot.apache.org
[GitHub] [pinot] dachaostripe commented on issue #9545: Tagging unique requestId or eventId to all logs across components
Posted by GitBox <gi...@apache.org>.
dachaostripe commented on issue #9545:
URL: https://github.com/apache/pinot/issues/9545#issuecomment-1271224575
you mean like `queryRequest.getBrokerId()` used at [QueryScheduler](https://github.com/apache/pinot/blob/master/pinot-core/src/main/java/org/apache/pinot/core/query/scheduler/QueryScheduler.java#L257)? which presumably is originated from here at [BaseBrokerRequestHandler](https://github.com/apache/pinot/blob/master/pinot-broker/src/main/java/org/apache/pinot/broker/requesthandler/BaseBrokerRequestHandler.java#L120)? However, the same brokerId doesn't seem being used for logging within the broker, and broken doesn't seem to even make an info/summary log in normal case, assuming this is [the end of request cycle](https://github.com/apache/pinot/blob/master/pinot-broker/src/main/java/org/apache/pinot/broker/requesthandler/BaseBrokerRequestHandler.java#L712-L716).
While it may be possible to make log tradable among components with the (requestId, brokerId) combo, with substantial work it seems, it's still an inefficient and much less convenient approach compared to if we can make them traceable with just a single requestId, if we can just make this requestId globally unique, either as an UUID, or like the [globalQueryId](https://github.com/apache/pinot/blob/0fa93971875fadbca17e5577fc45a9434d395329/pinot-broker/src/main/java/org/apache/pinot/broker/requesthandler/BaseBrokerRequestHandler.java#L1649) you're already making here: `_brokerId + "_" + requestId`
By skimming through the 2 classes I linked above, I found the general pattern of logging is like `LOGGER.error("Some message, requestId={}", requestId)`, which in my opinion is very tedious, inconsistent, and unreliable, that not every log is following the pattern and those untagged logs becomes practically unsearchable in a high traffic production environment.
I'd suggest a more reliable approach of adding a request filter/valve in front of the handler, to put requestId into Log4j's threadContext, like this
```
beforeHandler(Request req) {
val requestId = Optional.of(req.getHeader("x-pinot-requestId")).getOrElse(UUID.newId());
MDC.put("requestId", requestId);
}
afterHandler(Response resp) {
val requestId = MDC.remove("requestId");
resp.setHeader("x-pinot-requestId", requestId);
}
```
Along with proper config in log4j2.xml like
```
<PatternLayout pattern="%d{HH:mm:ss.SSS} {requestId} %p [%c{1}] [%t] %m%n"/>
```
Then all logs made with something like `LOGGER.error("Some message")` will automatically look like this in logs
```
[DateTime] REQUEST_ID processId ... Some message.
```
This will automatically cover all log messages made within a request cycle and make them easily searchable.
In fact, it's already doing something similar [here](https://github.com/apache/pinot/blob/0fa93971875fadbca17e5577fc45a9434d395329/pinot-broker/src/main/java/org/apache/pinot/broker/requesthandler/BaseBrokerRequestHandler.java#L263-L265) with the requestContext, we just need to extend this to log context as well.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org
For additional commands, e-mail: commits-help@pinot.apache.org
[GitHub] [pinot] dachaostripe commented on issue #9545: Tagging unique requestId or eventId to all logs across components
Posted by GitBox <gi...@apache.org>.
dachaostripe commented on issue #9545:
URL: https://github.com/apache/pinot/issues/9545#issuecomment-1270773878
> If pinot broker returns the requestId and the brokerId along with the response/exception, will that help?
This probably would help during testing and development where we can temporarily log the response, assuming broker AND online/offline servers also tag all their related logs with the broker id(in addition to requestId), which is still not as convenient as simply searching for requestId alone.
And that still doesn't solve the problem in production where clients don't usually log the response, and especially in a larger company where the team that owns and maintains Pinot clusters doesn't necessarily also own the clients and cannot force client teams to log the responses(and that also sometimes violates company's security rules). In case of excessive errors from Pinot triggering the alarms, or a client team asking why some of their requests were failing, we don't have an effective way to correlate client and Pinot logs, and to definitively conclude what went wrong for a particular request.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org
For additional commands, e-mail: commits-help@pinot.apache.org
[GitHub] [pinot] mcvsubbu commented on issue #9545: Tagging unique requestId or eventId to all logs across components
Posted by GitBox <gi...@apache.org>.
mcvsubbu commented on issue #9545:
URL: https://github.com/apache/pinot/issues/9545#issuecomment-1270880821
I believe the brokerId is also logged in the server log for a successful query.
We may need to make sure that these are also logged whenever an error/warning pertaining to a query is logged.
In case of clients, the clients only need to log information about queries that don't work as expected, right? They don't need to log anything (unless they want to) if everything goes well with the query
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org
For additional commands, e-mail: commits-help@pinot.apache.org
[GitHub] [pinot] mcvsubbu commented on issue #9545: Tagging unique requestId or eventId to all logs across components
Posted by GitBox <gi...@apache.org>.
mcvsubbu commented on issue #9545:
URL: https://github.com/apache/pinot/issues/9545#issuecomment-1270742796
If pinot broker returns the requestId and the brokerId along with the response/exception, will that help?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org
For additional commands, e-mail: commits-help@pinot.apache.org