pubsub: make Subscriber logs less chatty (#1748)

pongad · web-flow · commit d4be5e5a418b · 2017-03-15T14:08:18.000+11:00
Also use text formatting so we don't unnecessarily allocate Strings when not logging. Fixes #1686.
diff --git a/google-cloud-pubsub/src/main/java/com/google/cloud/pubsub/spi/v1/MessageDispatcher.java b/google-cloud-pubsub/src/main/java/com/google/cloud/pubsub/spi/v1/MessageDispatcher.java
@@ -273,7 +273,8 @@ public void processReceivedMessages(List<com.google.pubsub.v1.ReceivedMessage> r
       ackHandlers.add(new AckHandler(pubsubMessage.getAckId(), messageSize));
     }
     Instant expiration = now.plus(messageDeadlineSeconds * 1000);
-    logger.log(Level.INFO, "Received " + responseMessages.size() + " messages at " + now);
+    logger.log(
+        Level.FINER, "Received {0} messages at {1}", new Object[] {responseMessages.size(), now});
 
     messagesWaiter.incrementPendingMessages(responseMessages.size());
     Iterator<AckHandler> acksIterator = ackHandlers.iterator();
@@ -364,13 +365,9 @@ public void run() {
               ((long) Math.ceil(now.plus(ackExpirationPadding).plus(500).getMillis() / 1000.0))
                   * 1000L);
       logger.log(
-          Level.INFO,
-          "Running alarm sent outstanding acks, at now time: "
-              + now
-              + ", with cutover time: "
-              + cutOverTime
-              + ", padding: "
-              + ackExpirationPadding);
+          Level.FINER,
+          "Running alarm sent outstanding acks, at time: {0}, with cutover time: {1}, padding: {2}",
+          new Object[] {now, cutOverTime, ackExpirationPadding});
       Instant nextScheduleExpiration = null;
       List<PendingModifyAckDeadline> modifyAckDeadlinesToSend = new ArrayList<>();
 
@@ -421,12 +418,9 @@ public void run() {
 
       if (nextScheduleExpiration != null) {
         logger.log(
-            Level.INFO,
-            "Scheduling based on outstanding, now time: "
-                + now
-                + ", "
-                + "next schedule time: "
-                + nextScheduleExpiration);
+            Level.FINER,
+            "Scheduling based on outstanding, at time: {0}, next scheduled time: {1}",
+            new Object[] {now, nextScheduleExpiration});
         setupNextAckDeadlineExtensionAlarm(nextScheduleExpiration);
       }
     }
@@ -438,13 +432,11 @@ private void setupNextAckDeadlineExtensionAlarm(Instant expiration) {
     try {
       if (nextAckDeadlineExtensionAlarmTime.isAfter(possibleNextAlarmTime)) {
         logger.log(
-            Level.INFO,
-            "Scheduling next alarm time: "
-                + possibleNextAlarmTime
-                + ", last alarm set to time: "
-                + nextAckDeadlineExtensionAlarmTime);
+            Level.FINER,
+            "Scheduling next alarm time: {0}, previous alarm time: {1}",
+            new Object[] {possibleNextAlarmTime, nextAckDeadlineExtensionAlarmTime});
         if (ackDeadlineExtensionAlarm != null) {
-          logger.log(Level.INFO, "Canceling previous alarm");
+          logger.log(Level.FINER, "Canceling previous alarm");
           ackDeadlineExtensionAlarm.cancel(false);
         }
 
@@ -475,7 +467,7 @@ private void processOutstandingAckOperations(
       if (!pendingAcks.isEmpty()) {
         try {
           acksToSend = new ArrayList<>(pendingAcks);
-          logger.log(Level.INFO, "Sending {0} acks", acksToSend.size());
+          logger.log(Level.FINER, "Sending {0} acks", acksToSend.size());
         } finally {
           pendingAcks.clear();
         }
@@ -488,7 +480,7 @@ private void processOutstandingAckOperations(
           for (String ackId : pendingNacks) {
             nacksToSend.addAckId(ackId);
           }
-          logger.log(Level.INFO, "Sending {0} nacks", pendingNacks.size());
+          logger.log(Level.FINER, "Sending {0} nacks", pendingNacks.size());
         } finally {
           pendingNacks.clear();
         }
diff --git a/google-cloud-pubsub/src/main/java/com/google/cloud/pubsub/spi/v1/PollingSubscriberConnection.java b/google-cloud-pubsub/src/main/java/com/google/cloud/pubsub/spi/v1/PollingSubscriberConnection.java
@@ -95,7 +95,7 @@ public PollingSubscriberConnection(
 
   @Override
   protected void doStart() {
-    logger.log(Level.INFO, "Starting subscriber.");
+    logger.config("Starting subscriber.");
     initialize();
     notifyStarted();
   }
diff --git a/google-cloud-pubsub/src/main/java/com/google/cloud/pubsub/spi/v1/StreamingSubscriberConnection.java b/google-cloud-pubsub/src/main/java/com/google/cloud/pubsub/spi/v1/StreamingSubscriberConnection.java
@@ -96,7 +96,7 @@ public StreamingSubscriberConnection(
 
   @Override
   protected void doStart() {
-    logger.log(Level.INFO, "Starting subscriber.");
+    logger.config("Starting subscriber.");
     initialize();
     notifyStarted();
   }
@@ -134,13 +134,13 @@ public void onNext(StreamingPullResponse response) {
 
     @Override
     public void onError(Throwable t) {
-      logger.log(Level.INFO, "Terminated streaming with exception", t);
+      logger.log(Level.WARNING, "Terminated streaming with exception", t);
       errorFuture.setException(t);
     }
 
     @Override
     public void onCompleted() {
-      logger.log(Level.INFO, "Streaming pull terminated successfully!");
+      logger.fine("Streaming pull terminated successfully!");
       errorFuture.set(null);
     }
   }
@@ -157,11 +157,9 @@ private void initialize() {
                     CallOptions.DEFAULT.withCallCredentials(MoreCallCredentials.from(credentials))),
                 responseObserver));
     logger.log(
-        Level.INFO,
-        "Initializing stream to subscription "
-            + subscription
-            + " with deadline "
-            + messageDispatcher.getMessageDeadlineSeconds());
+        Level.FINER,
+        "Initializing stream to subscription {0} with deadline {1}",
+        new Object[] {subscription, messageDispatcher.getMessageDeadlineSeconds()});
     requestObserver.onNext(
         StreamingPullRequest.newBuilder()
             .setSubscription(subscription)
diff --git a/google-cloud-pubsub/src/main/java/com/google/cloud/pubsub/spi/v1/Subscriber.java b/google-cloud-pubsub/src/main/java/com/google/cloud/pubsub/spi/v1/Subscriber.java
@@ -321,7 +321,7 @@ public void close() throws IOException {
 
     @Override
     protected void doStart() {
-      logger.log(Level.INFO, "Starting subscriber group.");
+      logger.log(Level.FINE, "Starting subscriber group.");
       // Streaming pull is not enabled on the service yet.
       // startStreamingConnections();
       startPollingConnections();
@@ -395,8 +395,8 @@ public void run() {
                     if (streamAckDeadlineSeconds != possibleStreamAckDeadlineSeconds) {
                       streamAckDeadlineSeconds = possibleStreamAckDeadlineSeconds;
                       logger.log(
-                          Level.INFO,
-                          "Updating stream deadline to {} seconds.",
+                          Level.FINER,
+                          "Updating stream deadline to {0} seconds.",
                           streamAckDeadlineSeconds);
                       for (StreamingSubscriberConnection subscriberConnection :
                           streamingSubscriberConnections) {

Original file line number	Diff line number	Diff line change
`@@ -95,7 +95,7 @@ public PollingSubscriberConnection(`
`95`	`95`
`96`	`96`	`@Override`
`97`	`97`	`protected void doStart() {`
`98`		`- logger.log(Level.INFO, "Starting subscriber.");`
	`98`	`+ logger.config("Starting subscriber.");`
`99`	`99`	`initialize();`
`100`	`100`	`notifyStarted();`
`101`	`101`	`}`