-
Notifications
You must be signed in to change notification settings - Fork 101
feat: add client library debug logging #2659
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: main
Are you sure you want to change the base?
Conversation
|
/gcbrun |
michaelpri10
left a comment
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
A few higher level comments:
- In all places where they are applicable, we should be logging the message ID (seems to be in place already), the ordering key, and whether exactly-once delivery is enabled for subscriptions. Additionally, while it's not explicitly state in the design document, I think we should log ack IDs where applicable as well.
- I don't think we are doing the sub-systems correctly here. I think we want to be creating
java.util.logging.Loggerobjects with names that correspond to the sub-systems. For example, we have ourMessageDispatcher.loggerobject [here](instantiated with the name of thejava-pubsub/google-cloud-pubsub/src/main/java/com/google/cloud/pubsub/v1/MessageDispatcher.java
Line 61 in 1676abc
private static final Logger logger = Logger.getLogger(MessageDispatcher.class.getName()); MessageDispatcherclass. We can create new loggers for each sub-system.
I think that the Python debug logging implementation is good framework for what we want the logging here to look like.
|
/gcbrun |
| @@ -0,0 +1,64 @@ | |||
| /* | |||
| * Copyright 2016 Google LLC | |||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Update year to 2026.
| exactlyOnceDeliveryEnabled.get()); | ||
| } | ||
| if (ackLatency >= ackLatencyDistribution.getPercentile(slowAckPercentile)) { | ||
| slowAckLogger.log(Level.FINE, "pubsub:slow-ack - " + logPrefix); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Since the loggers already have sub-systems attached, we don't need the pubsub:slow-ack prefix on the log. Same for other log calls.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Additionally, we should have messages with more info. Here would be something like {LOG_PREFIX}: Message ack duration of {ack duration} is higher than the p99 ack duration
| int ackLatency = | ||
| Ints.saturatedCast((long) Math.ceil((clock.millisTime() - receivedTimeMillis) / 1000D)); | ||
| String logPrefix = ""; | ||
| if (slowAckLogger.isLoggable(Level.FINE) || ackNackLogger.isLoggable(Level.FINE)) { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Is the use of isLoggable here to avoid allocating and concatenating strings for logging when we don't need them?
| ackLatencyDistribution.record(ackLatency); | ||
| tracer.endSubscribeProcessSpan(this.ackRequestData.getMessageWrapper(), "ack"); | ||
| } | ||
| ackNackLogger.log(Level.FINE, "pubsub:ack-nack - " + logPrefix + " - Action: ACK"); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Use a more descriptive log like Ack called on message. Same below.
| new Object[] { | ||
| ackRequestDataList.size(), | ||
| nackRequestDataList.size(), | ||
| ackRequestDataList.size(), |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Should this be ackRequestDataReceipts?
| final class LoggingUtil { | ||
| private LoggingUtil() {} | ||
|
|
||
| static String getLogPrefix( |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
nit: getSubcriberLogPrefix to differentiate better from getPublisherLogPrefix
| this.getAckRequestData().getAckId(), | ||
| exactlyOnceDeliveryEnabled.get()); | ||
| callbackExceptionsLogger.log( | ||
| Level.WARNING, "pubsub:callback-exceptions - MessageReceiver exception. " + prefix, t); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I think we should have the prefix always be the first part of the logs. Wrapping in in parentheses or square brackets would probably be the best option for formatting.
|
|
||
| import com.google.pubsub.v1.PubsubMessage; | ||
|
|
||
| final class LoggingUtil { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This isn't necessary to do but a potential improvement to help improve readability could be to use this helper class to actually make the log calls. For example, you could create a helper method that takes in the subsystem, the log level, and the arguments needed for the log prefix. This would then get the logger, check isLoggable, create the prefix, and make the actual log call.
Note the getLogger may can either create or return an existing logger with a given name. It is probably worth instantiating each of the loggers within this class and then having an instance of LoggingUtil instantiated within MessageDispatcher and StreamingSubscriberConnection in order to ensure there are strong references to the logger objects.
Thank you for opening a Pull Request! Before submitting your PR, there are a few things you can do to make sure it goes smoothly:
Fixes #<issue_number_goes_here> ☕️
If you write sample code, please follow the samples format.