core: attach debug information about stream to DEADLINE_EXCEEDED #5892

zhangkun83 · 2019-06-17T23:22:48Z

Works for #4740

Subclasses of AbstractClientStream include remote address in insight if available.
DelayedStream adds buffered time, and the insight of real stream if it's set.
RetriableStream insights outputs of Substreams.
~~ManagedChannelImpl adds channel state. Other information, like last error status, would need API changes to LoadBalancer~~.

Example error message:

deadline exceeded after 8112071ns. [buffered_nanos=24763, remote_addr=foo.test.google.fr/127.0.0.1:44749]

or

deadline exceeded after 8112071ns. [buffered_nanos=22344324763, waiting_for_connection]

This is related to #4776 but taking a more usage-specific approach.

…XCEEDED Most cases the message will include a dump of the transport attributes, which gives important information such as server addresses. Example error message: deadline exceeded after 9699625ns. Channel state: READY. Stream: {delegate=[NettyClientStream attrs={remote-addr=local:in-process-1, io.grpc.internal.GrpcAttributes.securityLevel=NONE, io.grpc.internal.GrpcAttributes.clientEagAttrs={}, local-addr=local:E:c9ab2b05}]

Example output: deadline exceeded after 8112071ns. TimeoutDetails{channel_state=READY, server_addr=foo.test.google.fr/127.0.0.1:44749}

core/src/main/java/io/grpc/internal/ClientCallImpl.java

carl-mastrangelo · 2019-06-18T21:09:46Z

core/src/main/java/io/grpc/inprocess/InProcessTransport.java

@@ -806,6 +807,10 @@ public void setDeadline(Deadline deadline) {
        long effectiveTimeout = max(0, deadline.timeRemaining(TimeUnit.NANOSECONDS));
        headers.put(TIMEOUT_KEY, effectiveTimeout);
      }
+
+      @Override
+      public void appendTimeoutDetails(ToStringHelper toStringHelper) {


TBH, I think StringBuilder is a better fit.

public void appendTimeoutDetails(StringBuilder buffer) { buffer.append(key).append('=').append(value).append(',') }

The code that finally does toString can trim the last character. Alternatively, this could just be a Map<String, Object>.

StringBuilder just makes implementation strictly more complex, as I would have to care for formatting. I would be willing to submit to List<String>, but the generic is a hassle with mockito.

Since nothing is ideal, and most look like abuse to some extent, I just created a custom type InsightBuilder. This would give us more flexibility in terms of formatting, just in case we want to make changes in the future.

ejona86

Overall, looks fair. It's unfortunate it has to be thread-safe, but I understand why, and it doesn't seem to bother the implementations much. Only concern is bookkeeping for retriable stream. I don't care about ToStringHelper vs StringBuilder. I'm fine with either.

core/src/main/java/io/grpc/internal/InternalSubchannel.java

ejona86 · 2019-06-18T22:41:52Z

core/src/main/java/io/grpc/internal/RetriableStream.java

@@ -89,6 +92,10 @@
   */
  private final AtomicBoolean noMoreTransparentRetry = new AtomicBoolean();

+  /** Keeps track of all substreams for informative purposes. */
+  private final ConcurrentLinkedQueue<Substream> allSubstreams =


I'm concerned about how long we'll keep these streams alive. We could potentially be retaining an entire transport for "no reason."

I think we should add a new Collection<Status> or Collection<Status.Code> to State for the completed streams. The stream's Status can be easily passed to State.substreamClosed(Substream), and so when the stream is removed from drainedSubstreams its results will be present in the other list. There's no need for the other stream data for completed streams (like address) since it isn't normally provided.

I have updated this PR according to your suggestion. Now it includes the status codes from all closed substreams. @dapengzhang0, according to javadoc on the drainedSubstreams field, it doesn't seem to always include unfinished substreams. Please advice on how to proceed.

Per offline discussion, I have updated the code and added comments.

core/src/main/java/io/grpc/internal/InsightBuilder.java

carl-mastrangelo · 2019-06-19T16:06:31Z

core/src/main/java/io/grpc/internal/InsightBuilder.java

+ * information.
+ */
+public final class InsightBuilder {
+  private final ArrayList<String> buffer = new ArrayList<String>();


I don't think it matters here... it would add one more import line.

core/src/main/java/io/grpc/internal/RetriableStream.java

zhangkun83 · 2019-06-19T20:00:44Z

PTAL

core/src/main/java/io/grpc/internal/RetriableStream.java

carl-mastrangelo · 2019-06-19T20:21:27Z

core/src/test/java/io/grpc/internal/RetriableStreamTest.java

+        @Override
+        public Void answer(InvocationOnMock in) {
+          InsightBuilder insight = (InsightBuilder) in.getArguments()[0];
+          insight.appendKeyValue("server_addr", "2.2.2.2:443");


existing terminology in our code I think points to this being a "backend_addr", not a server_addr. (or possibly remote_addr)

Changed to remote_addr.

In grpc#5892 getAttributes() is called without any regard of timing. Currently DelayedStream.getAttributes() wil throw if called before passThrough was set. Just to be safe, we are removing that restriction and making it clear on the javadoc. On the other hand, we intend to keep the timing restriction on ClientCall.getAttributes().

ejona86 · 2019-06-19T22:54:46Z

core/src/main/java/io/grpc/internal/RetriableStream.java

+  public void appendTimeoutInsight(InsightBuilder insight) {
+    State currentState;
+    synchronized (lock) {
+      insight.appendKeyValue("closed", closedSubstreamsInsight);


closedSubstreamsInsight.toString()

It is very important that the insight is stringified within the lock. The insight implementation could have chosen to store the Object in the List and serialize at the end.

(Note: this could be considered an argument against passing Objects. Although we deal with this problem with logging already.)

InsightBuilder already does that and that's documented in the javadoc.

ejona86 · 2019-06-19T22:59:14Z

core/src/main/java/io/grpc/internal/RetriableStream.java

+        InsightBuilder substreamInsight = new InsightBuilder();
+        sub.stream.appendTimeoutInsight(substreamInsight);
+        openSubstreamsInsight.append(substreamInsight);
+        insight.appendKeyValue("open", openSubstreamsInsight);


Shouldn't this be outside of the for loop?

Good catch! Fixed.

ejona86 · 2019-06-19T23:01:40Z

core/src/main/java/io/grpc/internal/DelayedStream.java

+        insight.appendKeyValue("buffered_nanos", streamSetTimeNanos - startTimeNanos);
+        realStream.appendTimeoutInsight(insight);
+      } else {
+        insight.append("waiting_for_connection");


Nit: it'd be nice if these cases were more symmetric in the output string, moving this to the next line.

In #5892 getAttributes() is called without any regard of timing. Currently DelayedStream.getAttributes() wil throw if called before passThrough was set. Just to be safe, we are removing that restriction and making it clear on the javadoc. On the other hand, we intend to keep the timing restriction on ClientCall.getAttributes().

carl-mastrangelo

LGTM

zhangkun83 added 4 commits June 16, 2019 16:56

Change to appendTimeoutDetails()

4dc220e

Example output: deadline exceeded after 8112071ns. TimeoutDetails{channel_state=READY, server_addr=foo.test.google.fr/127.0.0.1:44749}

Remove class name from toStringHelper

ee4a104

RetriableStream

5fc808a

zhangkun83 requested review from ejona86, dapengzhang0 and carl-mastrangelo June 17, 2019 23:22

zhangkun83 added 2 commits June 17, 2019 17:53

Revert channel state changes

ab3b8b1

reword DelayedStream message

3a604a1

carl-mastrangelo reviewed Jun 18, 2019

View reviewed changes

ejona86 reviewed Jun 18, 2019

View reviewed changes

zhangkun83 changed the title ~~core: attach debug information about channel and stream to DEADLINE_EXCEEDED~~ core: attach debug information about stream to DEADLINE_EXCEEDED Jun 19, 2019

zhangkun83 added 3 commits June 18, 2019 18:50

Use custom type InsightBuilder instead of ToStringHelper

f8ec8bc

Simply cat

7cbc142

Change RetriableStream according to feedback

f26742d

carl-mastrangelo reviewed Jun 19, 2019

View reviewed changes

dapengzhang0 reviewed Jun 19, 2019

View reviewed changes

core/src/main/java/io/grpc/internal/RetriableStream.java Outdated Show resolved Hide resolved

zhangkun83 added 2 commits June 19, 2019 12:48

Update retriable stream per offline discussion

6c1c02c

Allow passing Object to append()

7b86e64

zhangkun83 requested review from ejona86, carl-mastrangelo and dapengzhang0 June 19, 2019 20:00

carl-mastrangelo reviewed Jun 19, 2019

View reviewed changes

zhangkun83 mentioned this pull request Jun 19, 2019

core: ClientStream.getAttributes() can be called at any time. #5904

Merged

address comments

6f5d347

ejona86 reviewed Jun 19, 2019

View reviewed changes

Fix a bug in RetriableStream

78cb4bb

Reorder

93bdd3f

zhangkun83 requested review from ejona86 and carl-mastrangelo June 19, 2019 23:26

ejona86 approved these changes Jun 19, 2019

View reviewed changes

carl-mastrangelo approved these changes Jun 20, 2019

View reviewed changes

zhangkun83 merged commit ddbaf74 into grpc:master Jun 20, 2019

zhangkun83 deleted the useful_deadline_exceeded branch June 20, 2019 00:30

dapengzhang0 mentioned this pull request Jun 21, 2019

all: fix lint errors #5919

Merged

lock bot locked as resolved and limited conversation to collaborators Sep 18, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

core: attach debug information about stream to DEADLINE_EXCEEDED #5892

core: attach debug information about stream to DEADLINE_EXCEEDED #5892

zhangkun83 commented Jun 17, 2019 •

edited

carl-mastrangelo Jun 18, 2019

zhangkun83 Jun 19, 2019

ejona86 left a comment

ejona86 Jun 18, 2019

zhangkun83 Jun 19, 2019

zhangkun83 Jun 19, 2019

carl-mastrangelo Jun 19, 2019

zhangkun83 Jun 19, 2019

zhangkun83 commented Jun 19, 2019

carl-mastrangelo Jun 19, 2019

zhangkun83 Jun 19, 2019

ejona86 Jun 19, 2019

zhangkun83 Jun 19, 2019

ejona86 Jun 19, 2019

zhangkun83 Jun 19, 2019

ejona86 Jun 19, 2019

zhangkun83 Jun 19, 2019

carl-mastrangelo left a comment

core: attach debug information about stream to DEADLINE_EXCEEDED #5892

core: attach debug information about stream to DEADLINE_EXCEEDED #5892

Conversation

zhangkun83 commented Jun 17, 2019 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ejona86 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

zhangkun83 commented Jun 19, 2019

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

carl-mastrangelo left a comment

Choose a reason for hiding this comment

zhangkun83 commented Jun 17, 2019 •

edited