Adding rid to SubscribeToShard response for debugging. #678

joshua-kim · 2020-01-23T21:41:26Z

Issue #, if available:

Description of changes:

Adding Request ID logging to aid in SubscribeToShard debugging.

Testing:

2020-02-14 12:15:07,732 [KinesisTester-0000] ERROR s.a.k.l.ShardConsumerSubscriber [NONE] - shardId-000000000006: Last request was dispatched at 2020-02-14T20:14:07.616Z, but no response as of 2020-02-14T20:15:07.732Z (PT1M0.116S).  Cancelling subscription, and restarting. Last successful request details: request id - d052b922-6a8a-a098-8693-b8bc4f4decec, timestamp - 2020-02-14T20:13:18.537Z

By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.

ashwing

We need to cache this rid in the FanoutRecordPublisher against the current subscription id and log this in two places 1. along with the infamous "Cancelling subscription and restarting.." logs in shardConsumer 2. in any of exceptionOccured()'s WARN log in FanoutRecordPublisher.

ashwing · 2020-01-30T22:52:50Z

amazon-kinesis-client/src/main/java/software/amazon/kinesis/retrieval/RecordsPublisher.java

@@ -23,7 +25,11 @@
 /**
 * Provides a record publisher that will retrieve records from Kinesis for processing
 */
-public interface RecordsPublisher extends Publisher<RecordsRetrieved> {
+public abstract class RecordsPublisher implements Publisher<RecordsRetrieved> {


Lets avoid using abstract classes - applicable to all places. Keep it as an interface and introduce getLastSuccessfulRequestDetails()

Will update

ashwing · 2020-01-30T22:54:23Z

amazon-kinesis-client/src/main/java/software/amazon/kinesis/retrieval/RecordsPublisher.java

+public abstract class RecordsPublisher implements Publisher<RecordsRetrieved> {
+
+    @Getter @Setter
+    private String lastRequestId;


Along with the requestId, let's have the time it was dispatched and an optional field to capture other meta info. LastRequestDetails getLastSuccessfulRequestDetails()

ashwing · 2020-01-30T22:59:15Z

...is-client/src/main/java/software/amazon/kinesis/retrieval/fanout/FanOutRecordsPublisher.java

@@ -351,7 +351,7 @@ private void resetRecordsDeliveryStateOnSubscriptionOnInit() {
        // Clear any lingering records in the queue.
        if (!recordsDeliveryQueue.isEmpty()) {
            log.warn("{}: Found non-empty queue while starting subscription. This indicates unsuccessful clean up of"
-                    + "previous subscription - {} ", shardId, subscribeToShardId);
+                    + "previous subscription - {}. rid {}", shardId, subscribeToShardId, getLastRequestId());


nit : Make it more readable like. RequestId - { }. Applicable to all places

I agree that's more readable. Will update logs.

ashwing · 2020-01-30T22:59:43Z

...is-client/src/main/java/software/amazon/kinesis/retrieval/fanout/FanOutRecordsPublisher.java

-                    parent.shardId, connectionStartedAt, subscribeToShardId);
+           parent.setLastRequestId(response.responseMetadata().requestId());
+           log.debug("{}: [SubscriptionLifetime]: (RecordFlow#responseReceived) @ {} id: {} -- Response received. rid: {}, erid: {}, sdkfields: {}",
+                    parent.shardId, connectionStartedAt, subscribeToShardId, response.responseMetadata().requestId(), response.responseMetadata().extendedRequestId(), response.sdkFields());


lets remove sdkfields from here

Will update

ashwing · 2020-01-30T23:01:35Z

...-kinesis-client/src/main/java/software/amazon/kinesis/lifecycle/ShardConsumerSubscriber.java

@@ -130,7 +130,7 @@ private void restartIfRequestTimerExpired(long maxTimeBetweenRequests) {
                if (timeSinceLastResponse.toMillis() > maxTimeBetweenRequests) {
                    log.error(
                            "{}: Last request was dispatched at {}, but no response as of {} ({}).  Cancelling subscription, and restarting.",


Is this the only instance of "Last request of dispatched" log in ShardConsumerSubscriber?

ashwing · 2020-01-30T23:04:20Z

...-kinesis-client/src/main/java/software/amazon/kinesis/lifecycle/ShardConsumerSubscriber.java

@@ -130,7 +130,7 @@ private void restartIfRequestTimerExpired(long maxTimeBetweenRequests) {
                if (timeSinceLastResponse.toMillis() > maxTimeBetweenRequests) {
                    log.error(
                            "{}: Last request was dispatched at {}, but no response as of {} ({}).  Cancelling subscription, and restarting.",
-                            shardConsumer.shardInfo().shardId(), lastRequestTime, now, timeSinceLastResponse);
+                            shardConsumer.shardInfo().shardId(), lastRequestTime, now, timeSinceLastResponse, recordsPublisher.getLastRequestId());


Also, PrefetchRecordPublisher while calling this will have null returned. Either let's populate this in PrefetchRecPub or make sure null is handled through optional.

Good catch, will update

yasemin-amzn · 2020-02-11T04:39:19Z

...is-client/src/main/java/software/amazon/kinesis/retrieval/fanout/FanOutRecordsPublisher.java

-            log.warn("{}: Unable to enqueue the payload due to capacity restrictions in delivery queue with remaining capacity {} ",
-                    shardId, recordsDeliveryQueue.remainingCapacity());
+
+            log.warn("{}: Unable to enqueue the payload due to capacity restrictions in delivery queue with remaining capacity {}. Last successful response: RequestId - {}, Timestamp - {}",


Let's log the RequestDetails object directly using its toString() method, so adding/removing attributes in the future won't require updates to all log statements.

+1. Applicable to all places

Using toString now

ashwing

Left some comments

ashwing · 2020-02-12T20:16:22Z

...-kinesis-client/src/main/java/software/amazon/kinesis/lifecycle/ShardConsumerSubscriber.java

-                            "{}: Last request was dispatched at {}, but no response as of {} ({}).  Cancelling subscription, and restarting.",
-                            shardConsumer.shardInfo().shardId(), lastRequestTime, now, timeSinceLastResponse);
+                            "{}: Last request was dispatched at {}, but no response as of {} ({}).  Cancelling subscription, and restarting. Last successful response: RequestId - {}, Timestamp - {}",
+                            shardConsumer.shardInfo().shardId(), lastRequestTime, now, timeSinceLastResponse, recordsPublisher.getLastSuccessfulResponseRequestId(), recordsPublisher.getLastSuccessfulResponseTimestamp());


Let's directly print the requestdetails obj in the logs.

ashwing · 2020-02-12T20:19:52Z

amazon-kinesis-client/src/main/java/software/amazon/kinesis/retrieval/RecordsPublisher.java

+    default String getLastSuccessfulResponseRequestId() {
+        return getLastSuccessfulResponseDetails().map(RequestDetails::requestId).orElse(NONE);
+    }
+
+    /**
+     * Gets last successful response's timestamp.
+     *
+     * @return timestamp associated with last successful response.
+     */
+    default String getLastSuccessfulResponseTimestamp() {
+        return getLastSuccessfulResponseDetails().map(RequestDetails::timestamp).orElse(NONE);


Let's move this to RequestDetails if these methods are required. Ideally we should be requiring only toString() of RequestDetails.

Yeah I think that makes more sense. Updated.

ashwing · 2020-02-12T20:20:14Z

...is-client/src/main/java/software/amazon/kinesis/retrieval/fanout/FanOutRecordsPublisher.java

-            log.warn("{}: Unable to enqueue the payload due to capacity restrictions in delivery queue with remaining capacity {} ",
-                    shardId, recordsDeliveryQueue.remainingCapacity());
+
+            log.warn("{}: Unable to enqueue the payload due to capacity restrictions in delivery queue with remaining capacity {}. Last successful response: RequestId - {}, Timestamp - {}",


+1. Applicable to all places

ashwing · 2020-02-12T20:23:37Z

...is-client/src/main/java/software/amazon/kinesis/retrieval/fanout/FanOutRecordsPublisher.java

-            log.debug("{}: [SubscriptionLifetime]: (RecordFlow#responseReceived) @ {} id: {} -- Response received",
-                    parent.shardId, connectionStartedAt, subscribeToShardId);
+            log.debug("{}: [SubscriptionLifetime]: (RecordFlow#responseReceived) @ {} id: {} -- Response received. Last successful response: RequestId - {}, Timestamp - {}, ExtendedLast successful response: RequestId - {}, Timestamp - {}",
+                    parent.shardId, connectionStartedAt, subscribeToShardId, response.responseMetadata().requestId(), response.responseMetadata().extendedRequestId(), connectionStartedAt);


I think this log is messed up : ). Can you take a look?

Yes it is :) Updated

ashwing · 2020-02-12T20:25:14Z

...is-client/src/main/java/software/amazon/kinesis/retrieval/fanout/FanOutRecordsPublisher.java

-                        subscriptionShutdownEvent.getShutdownEventThrowableOptional());
+                        "{}: Unable to enqueue the {} shutdown event due to capacity restrictions in delivery queue with remaining capacity {}. Ignoring. Last successful response: RequestId - {}, Timestamp - {}",
+                        parent.shardId, subscriptionShutdownEvent.getEventIdentifier(), parent.recordsDeliveryQueue.remainingCapacity(),
+                        subscriptionShutdownEvent.getShutdownEventThrowableOptional(), parent.getLastSuccessfulResponseRequestId(), parent.getLastSuccessfulResponseTimestamp());


The expected and actual arguments doesnt match. Can you check?

Oh good catch. Updated.

yasemin-amzn · 2020-02-14T22:02:23Z

...is-client/src/main/java/software/amazon/kinesis/retrieval/fanout/FanOutRecordsPublisher.java

@@ -681,6 +698,7 @@ public BatchUniqueIdentifier batchUniqueIdentifier() {
        private boolean isDisposed = false;
        private boolean isErrorDispatched = false;
        private boolean isCancelled = false;
+        private RequestDetails recordFlowLastSuccessfuRequestDetails;


why this needs to be a class variable? Let's keep the scope of this object to be within the responceReceived() method.

Yeah this doesn't need to be class level, will move it to be scoped within responseReceived().

yasemin-amzn · 2020-02-14T22:04:01Z

...is-client/src/main/java/software/amazon/kinesis/retrieval/fanout/FanOutRecordsPublisher.java

@@ -718,8 +736,11 @@ public void onEventStream(SdkPublisher<SubscribeToShardEventStream> publisher) {

        @Override
        public void responseReceived(SubscribeToShardResponse response) {
-            log.debug("{}: [SubscriptionLifetime]: (RecordFlow#responseReceived) @ {} id: {} -- Response received",
-                    parent.shardId, connectionStartedAt, subscribeToShardId);
+            log.debug("{}: [SubscriptionLifetime]: (RecordFlow#responseReceived) @ {} id: {} -- Response received. RequestId - {} -- Last successful request details -- {} ",


Doesn't it make sense to log the response that's just received here, instead of the older one? Moving this log statement after the response parsing would address this comment.

Yeah I agree we don't need the stale response metadata, I'll just remove the old response info.

yasemin-amzn · 2020-02-14T22:07:06Z

...client/src/main/java/software/amazon/kinesis/retrieval/polling/BlockingRecordsPublisher.java

@@ -40,6 +42,7 @@
    private final GetRecordsRetrievalStrategy getRecordsRetrievalStrategy;

    private Subscriber<? super RecordsRetrieved> subscriber;
+    private final RequestDetails lastSuccessfulRequestDetails = new RequestDetails();


Current implementation will print none for blocking record publisher implementation. let's update the requestId as part of getNextResults() method to keep this path inline with expectation.

Yeah, I'll add this to BlockingRecordsPublisher.

yasemin-amzn · 2020-02-14T22:11:59Z

...client/src/main/java/software/amazon/kinesis/retrieval/polling/PrefetchRecordsPublisher.java

@@ -98,6 +100,7 @@
    private boolean wasReset = false;

    private Instant lastEventDeliveryTime = Instant.EPOCH;
+    private final RequestDetails lastSuccessfulRequestDetails = new RequestDetails();


Similar to blocking publisher, let's update the requestId in DefaultGetRecordsCacheDeamon, makeRetrievalAttempt() method.

Synced offline, this requires us to either add some unit test specific implementation/upgrade mockito major version since AwsResponseMetadata is a final class which we can't mock with older version of mockito.

ashwing reviewed Jan 24, 2020

View reviewed changes

ashwing suggested changes Jan 30, 2020

View reviewed changes

joshua-kim added 5 commits February 4, 2020 13:36

Adding rid to SubscribeToShard response for debugging.

7dc6f37

Addressing PR comments.

a459ec6

Addressing PR comments.

0d45170

Adding default.

3691237

Removing unused imports.

2f6e5d3

yasemin-amzn reviewed Feb 11, 2020

View reviewed changes

ashwing suggested changes Feb 12, 2020

View reviewed changes

joshua-kim added 3 commits February 14, 2020 10:52

Addressing PR comments.

dd15ea2

Fixing naming.

67bbdfd

Fixing order of logging.

dee8bd5

yasemin-amzn reviewed Feb 14, 2020

View reviewed changes

Addressing PR feedback.

64db125

yasemin-amzn approved these changes Feb 17, 2020

View reviewed changes

Fixing bug in logging.

1a78155

yasemin-amzn approved these changes Feb 17, 2020

View reviewed changes

joshua-kim merged commit 189df4b into awslabs:master Feb 17, 2020

joshua-kim deleted the kimjos-S2S-logs branch February 17, 2020 22:34

joshua-kim added this to the v2.2.9 milestone Feb 18, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Adding rid to SubscribeToShard response for debugging. #678

Adding rid to SubscribeToShard response for debugging. #678

joshua-kim commented Jan 23, 2020 •

edited

ashwing left a comment

ashwing Jan 30, 2020

joshua-kim Jan 31, 2020

ashwing Jan 30, 2020

ashwing Jan 30, 2020

joshua-kim Feb 4, 2020

ashwing Jan 30, 2020

joshua-kim Jan 31, 2020

ashwing Jan 30, 2020

joshua-kim Jan 30, 2020

ashwing Jan 30, 2020 •

edited

joshua-kim Jan 31, 2020

yasemin-amzn Feb 11, 2020

ashwing Feb 12, 2020

joshua-kim Feb 14, 2020

ashwing left a comment

ashwing Feb 12, 2020

joshua-kim Feb 14, 2020

ashwing Feb 12, 2020

joshua-kim Feb 14, 2020

ashwing Feb 12, 2020

ashwing Feb 12, 2020

joshua-kim Feb 14, 2020

ashwing Feb 12, 2020

joshua-kim Feb 14, 2020

yasemin-amzn Feb 14, 2020

joshua-kim Feb 14, 2020

yasemin-amzn Feb 14, 2020

joshua-kim Feb 14, 2020

yasemin-amzn Feb 14, 2020

joshua-kim Feb 14, 2020

yasemin-amzn Feb 14, 2020

joshua-kim Feb 17, 2020

Adding rid to SubscribeToShard response for debugging. #678

Adding rid to SubscribeToShard response for debugging. #678

Conversation

joshua-kim commented Jan 23, 2020 • edited

ashwing left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ashwing Jan 30, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ashwing left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

joshua-kim commented Jan 23, 2020 •

edited

ashwing Jan 30, 2020 •

edited