Dynatrace registry: Truncate log output #3148
Conversation
arminru
force-pushed
the
dt-log-abbreviate
branch
from
fcfd763 to
7acd632
Compare
| .onError(response -> logger.error("Failed metric ingestion: Error Code={}, Response Body={}", response.code(), response.body())); | ||
| .onError(response -> logger.error("Failed metric ingestion: Error Code={}, Response Body={}", | ||
| response.code(), | ||
| StringUtils.truncate(response.body(), LOG_RESPONSE_BODY_TRUNCATION_LIMIT))); |
There was a problem hiding this comment.
What do you think about signaling that the body was truncated?
E.g.: if the length of response.body() is more than the limit, add "[...]" or (truncated).
There was a problem hiding this comment.
I would've used apache/commons/lang3/StringUtils.html#abbreviate if present but unfortunately we don't have that yet in Micrometer's StringUtils.
I could add it there if you think it would make sense.
There was a problem hiding this comment.
I think it would make sense so that it is reusable across the code base.
There was a problem hiding this comment.
Added StringUtils.truncate + tests for it and changed the exporter to use it.
| } catch (Throwable throwable) { | ||
| logger.error("Failed metric ingestion: " + throwable.getMessage(), throwable); | ||
| logger.error("Failed metric ingestion: " + throwable); | ||
| logger.debug(throwable); |
There was a problem hiding this comment.
Is the idea of this coming from a user?
I usually like seeing the stacktrace if an error happened, it makes it easy where the error is coming from. Logging it out on DEBUG level defeats that purpose, you need to know where the log event is coming from so that you can see (and read the code) that a stacktrace is available on a lower level.
There was a problem hiding this comment.
Also, the DEBUG event will not contain a message so it will look weird: it will not tell you what happened and nothing guarantees that these events will be next to (or close to) each other in the logs.
If we decide that we don't want the stacktrace on ERROR level (I would advise against it), I would state that the user sees this stacktrace because metric ingestion failed and there is another log event about it on ERROR level.
There was a problem hiding this comment.
Yes, this was coming from a user.
With code access, the execution context should already be quite clear since the "Failed metric ingestion: " prefix and throwable.toString() afterwards only appear in one single place.
Good point about the events probably not being next to each other necessarily, I did not consider this.
How about this?
logger.error("Failed metric ingestion: " + throwable);
logger.debug("Stack trace for previous 'Failed metric ingestion' error log: ", throwable);
Ideally we would have a throttled error log for this but there is no throttled logger available in Micrometer already, right?
There was a problem hiding this comment.
There is WarnThenDebugLogger that logs at warn level at first and then logs at debug level for the rest of the events.
There was a problem hiding this comment.
I changed it to always print the message as a warning and use the WarnThenDebugLogger for the stack including a reference to the other warning message. This is under the assumption that it will usually be the same error if it would occur multiple times and that the overall context is clear from the log message prefix.
jonatan-ivanov
added
type: task
jonatan-ivanov
removed
the
waiting for feedback
|
Thank you! :) |
|
This seems to have been lost while merging #3152. |
|
fyi: I backported these to 1.9. |
shakuzen
added
enhancement
Sometimes the response body can be quite large so we should truncate it for logging.
Also logging stack traces from errors during HTTP requests only on debug level should be sufficient.