Skip to content
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

FlakyTest: ProtocolCompatibilityTest.serviceTalkToGrpcJavaTimeout #1489

Closed
tkountis opened this issue Apr 15, 2021 · 2 comments
Closed

FlakyTest: ProtocolCompatibilityTest.serviceTalkToGrpcJavaTimeout #1489

tkountis opened this issue Apr 15, 2021 · 2 comments
Assignees
Labels
flaky tests Unit tests are flaky

Comments

@tkountis
Copy link
Contributor

org.junit.experimental.theories.internal.ParameterizedAssertionError: serviceTalkToGrpcJavaTimeout("false" <from ssl[0]>, "false" <from streaming[0]>, "gzip" <from compression[0]>)
	at org.junit.experimental.theories.Theories$TheoryAnchor.reportParameterizedError(Theories.java:293)
	at org.junit.experimental.theories.Theories$TheoryAnchor$1$1.evaluate(Theories.java:242)
	at org.junit.experimental.theories.Theories$TheoryAnchor.runWithCompleteAssignment(Theories.java:223)
	at org.junit.experimental.theories.Theories$TheoryAnchor.runWithAssignment(Theories.java:209)
	at org.junit.experimental.theories.Theories$TheoryAnchor.runWithIncompleteAssignment(Theories.java:217)
	at org.junit.experimental.theories.Theories$TheoryAnchor.runWithAssignment(Theories.java:207)
	at org.junit.experimental.theories.Theories$TheoryAnchor.runWithIncompleteAssignment(Theories.java:217)
	at org.junit.experimental.theories.Theories$TheoryAnchor.runWithAssignment(Theories.java:207)
	at org.junit.experimental.theories.Theories$TheoryAnchor.runWithIncompleteAssignment(Theories.java:217)
	at org.junit.experimental.theories.Theories$TheoryAnchor.runWithAssignment(Theories.java:207)
	at org.junit.experimental.theories.Theories$TheoryAnchor.evaluate(Theories.java:192)
	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
	at org.junit.vintage.engine.execution.RunnerExecutor.execute(RunnerExecutor.java:43)
	at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
	at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
	at java.util.Iterator.forEachRemaining(Iterator.java:116)
	at java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1801)
	at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:482)
	at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:472)
	at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
	at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
	at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
	at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:485)
	at org.junit.vintage.engine.VintageTestEngine.executeAllChildren(VintageTestEngine.java:82)
	at org.junit.vintage.engine.VintageTestEngine.execute(VintageTestEngine.java:73)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:108)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:88)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:54)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:67)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:52)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:96)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:75)
	at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor$CollectAllTestClassesExecutor.processAllTestClasses(JUnitPlatformTestClassProcessor.java:99)
	at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor$CollectAllTestClassesExecutor.access$000(JUnitPlatformTestClassProcessor.java:79)
	at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor.stop(JUnitPlatformTestClassProcessor.java:75)
	at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.stop(SuiteTestClassProcessor.java:61)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
	at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:33)
	at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:94)
	at com.sun.proxy.$Proxy2.stop(Unknown Source)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.stop(TestWorker.java:133)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
	at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:182)
	at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:164)
	at org.gradle.internal.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:414)
	at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:64)
	at org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:48)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:56)
	at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.AssertionError: expected:<DEADLINE_EXCEEDED> but was:<UNKNOWN>
	at org.junit.Assert.fail(Assert.java:89)
	at org.junit.Assert.failNotEquals(Assert.java:835)
	at org.junit.Assert.assertEquals(Assert.java:120)
	at org.junit.Assert.assertEquals(Assert.java:146)
	at io.servicetalk.grpc.netty.ProtocolCompatibilityTest.assertGrpcStatusException(ProtocolCompatibilityTest.java:791)
	at io.servicetalk.grpc.netty.ProtocolCompatibilityTest.validateGrpcErrorInResponse(ProtocolCompatibilityTest.java:776)
	at io.servicetalk.grpc.netty.ProtocolCompatibilityTest.testGrpcErrorScalar(ProtocolCompatibilityTest.java:755)
	at io.servicetalk.grpc.netty.ProtocolCompatibilityTest.testGrpcError(ProtocolCompatibilityTest.java:712)
	at io.servicetalk.grpc.netty.ProtocolCompatibilityTest.serviceTalkToGrpcJavaTimeout(ProtocolCompatibilityTest.java:534)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
	at org.junit.experimental.theories.Theories$TheoryAnchor$2.evaluate(Theories.java:279)
	at io.servicetalk.concurrent.internal.ServiceTalkTestTimeout$TimeoutStatement$CallableStatement.call(ServiceTalkTestTimeout.java:161)
	at io.servicetalk.concurrent.internal.ServiceTalkTestTimeout$TimeoutStatement$CallableStatement.call(ServiceTalkTestTimeout.java:153)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	... 1 more
@idelpivnitskiy
Copy link
Member

More detailed log from the CI captured using #1487:
https://github.com/apple/servicetalk/pull/1487/checks?check_run_id=2348839826

2021-04-15T02:22:17.6282469Z ProtocolCompatibilityTest > serviceTalkToGrpcJavaTimeout STANDARD_OUT
2021-04-15T02:22:17.6285360Z     2021-04-15 02:21:58,748              Time-limited test [DEBUG] RoundRobinLoadBalancer         - Load balancer io.servicetalk.loadbalancer.RoundRobinLoadBalancer@26e344f4, received new ServiceDiscoverer event DefaultServiceDiscovererEvent{address=/127.0.0.1:37079, available=true}.
2021-04-15T02:22:17.6288902Z     2021-04-15 02:21:58,748              Time-limited test [DEBUG] RoundRobinLoadBalancer         - Load balancer io.servicetalk.loadbalancer.RoundRobinLoadBalancer@26e344f4 now using 1 addresses: [Host{address=/127.0.0.1:37079, removed=false}]
2021-04-15T02:22:17.6292702Z     2021-04-15 02:21:58,764 servicetalk-global-io-executor-4-1 [DEBUG] HttpDebugUtils                 - [id: 0xd2c2043b, L:/127.0.0.1:43340 - R:127.0.0.1/127.0.0.1:37079] HTTP/2.0 pipeline initialized: Http2FrameCodec#0, Http2MultiplexHandler#0, H2ClientParentConnectionContext$DefaultH2ClientParentConnection#0, DefaultChannelPipeline$TailContext#0
2021-04-15T02:22:17.6296215Z     2021-04-15 02:21:58,765    grpc-default-worker-ELG-2-1 [DEBUG] NettyServerHandler             - [id: 0x41e6e2a6, L:/127.0.0.1:37079 - R:/127.0.0.1:43340] OUTBOUND SETTINGS: ack=false settings={MAX_CONCURRENT_STREAMS=2147483647, INITIAL_WINDOW_SIZE=1048576, MAX_HEADER_LIST_SIZE=8192}
2021-04-15T02:22:17.6298561Z     2021-04-15 02:21:58,765    grpc-default-worker-ELG-2-1 [DEBUG] NettyServerHandler             - [id: 0x41e6e2a6, L:/127.0.0.1:37079 - R:/127.0.0.1:43340] OUTBOUND WINDOW_UPDATE: streamId=0 windowSizeIncrement=983041
2021-04-15T02:22:17.6300839Z     2021-04-15 02:21:58,765    grpc-default-worker-ELG-2-1 [DEBUG] NettyServerHandler             - [id: 0x41e6e2a6, L:/127.0.0.1:37079 - R:/127.0.0.1:43340] INBOUND SETTINGS: ack=false settings={ENABLE_PUSH=0, MAX_CONCURRENT_STREAMS=0, MAX_HEADER_LIST_SIZE=8192}
2021-04-15T02:22:17.6303011Z     2021-04-15 02:21:58,765    grpc-default-worker-ELG-2-1 [DEBUG] NettyServerHandler             - [id: 0x41e6e2a6, L:/127.0.0.1:37079 - R:/127.0.0.1:43340] OUTBOUND SETTINGS: ack=true
2021-04-15T02:22:17.6306600Z     2021-04-15 02:21:58,765    grpc-default-worker-ELG-2-1 [DEBUG] NettyServerHandler             - [id: 0x41e6e2a6, L:/127.0.0.1:37079 - R:/127.0.0.1:43340] INBOUND HEADERS: streamId=3 headers=GrpcHttp2RequestHeaders[:path: /grpc.netty.Compat/ScalarCall, :authority: 127.0.0.1:37079, :method: POST, :scheme: http, te: trailers, grpc-timeout: 1n, user-agent: grpc-service-talk/, grpc-accept-encoding: gzip, content-type: application/grpc+proto, grpc-encoding: gzip, content-length: 33] padding=0 endStream=false
2021-04-15T02:22:17.6310373Z     2021-04-15 02:21:58,766    grpc-default-worker-ELG-2-1 [DEBUG] NettyServerHandler             - [id: 0x41e6e2a6, L:/127.0.0.1:37079 - R:/127.0.0.1:43340] INBOUND DATA: streamId=3 padding=0 endStream=true length=33 bytes=010000001c1f8b0800000000000000e26004000000ffff030061a807fe02000000
2021-04-15T02:22:17.6312581Z     2021-04-15 02:21:58,766    grpc-default-worker-ELG-2-1 [DEBUG] NettyServerHandler             - [id: 0x41e6e2a6, L:/127.0.0.1:37079 - R:/127.0.0.1:43340] OUTBOUND PING: ack=false bytes=1234
2021-04-15T02:22:17.6314775Z     2021-04-15 02:21:58,778    grpc-default-worker-ELG-2-1 [DEBUG] NettyServerHandler             - [id: 0x41e6e2a6, L:/127.0.0.1:37079 - R:/127.0.0.1:43340] OUTBOUND RST_STREAM: streamId=3 errorCode=8
2021-04-15T02:22:17.6315654Z 
2021-04-15T02:22:17.6316489Z ProtocolCompatibilityTest > serviceTalkToGrpcJavaTimeout STANDARD_ERROR
2021-04-15T02:22:17.6319742Z     Unexpected status: GrpcStatus{code=UNKNOWN, cause=io.servicetalk.http.netty.Http2Exception$H2StreamResetException: RST_STREAM received for streamId=3 with error code: 8, description='io.servicetalk.http.netty.Http2Exception$H2StreamResetException: RST_STREAM received for streamId=3 with error code: 8'}, expected: DEADLINE_EXCEEDED
2021-04-15T02:22:17.6323347Z     io.servicetalk.grpc.api.GrpcStatusException: UNKNOWN: io.servicetalk.http.netty.Http2Exception$H2StreamResetException: RST_STREAM received for streamId=3 with error code: 8
2021-04-15T02:22:17.6325706Z     	at io.servicetalk.grpc.api.GrpcUtils.toGrpcException(GrpcUtils.java:284)
2021-04-15T02:22:17.6327737Z     	at io.servicetalk.concurrent.api.OnErrorMapSingle$ErrorMapSubscriber.onError(OnErrorMapSingle.java:72)
2021-04-15T02:22:17.6329578Z     	at io.servicetalk.concurrent.api.MapSingle$1.onError(MapSingle.java:56)
2021-04-15T02:22:17.6332165Z     	at io.servicetalk.concurrent.api.ContextPreservingSingleSubscriber.onError(ContextPreservingSingleSubscriber.java:102)
2021-04-15T02:22:17.6336086Z     	at io.servicetalk.concurrent.api.SingleFlatMapSingle$SubscriberImpl.onError(SingleFlatMapSingle.java:101)
2021-04-15T02:22:17.6339162Z     	at io.servicetalk.concurrent.api.ContextPreservingSingleSubscriber.onError(ContextPreservingSingleSubscriber.java:102)
2021-04-15T02:22:17.6341759Z     	at io.servicetalk.concurrent.api.MapSingle$1.onError(MapSingle.java:56)
2021-04-15T02:22:17.6343492Z     	at io.servicetalk.concurrent.api.TimeoutSingle$TimeoutSubscriber.onError(TimeoutSingle.java:155)
2021-04-15T02:22:17.6346522Z     	at io.servicetalk.concurrent.api.ContextPreservingSingleSubscriber.onError(ContextPreservingSingleSubscriber.java:102)
2021-04-15T02:22:17.6349442Z     	at io.servicetalk.concurrent.api.RetryWhenSingle$RetrySubscriber$1.onError(RetryWhenSingle.java:117)
2021-04-15T02:22:17.6352611Z     	at io.servicetalk.concurrent.api.ContextPreservingCompletableSubscriber.onError(ContextPreservingCompletableSubscriber.java:99)
2021-04-15T02:22:17.6356214Z     	at io.servicetalk.concurrent.internal.SubscriberUtils.safeOnError(SubscriberUtils.java:294)
2021-04-15T02:22:17.6359194Z     	at io.servicetalk.concurrent.internal.SubscriberUtils.deliverErrorFromSource(SubscriberUtils.java:226)
2021-04-15T02:22:17.6362078Z     	at io.servicetalk.concurrent.api.FailedCompletable.doSubscribe(FailedCompletable.java:30)
2021-04-15T02:22:17.6365409Z     	at io.servicetalk.concurrent.api.AbstractSynchronousCompletable.handleSubscribe(AbstractSynchronousCompletable.java:35)
2021-04-15T02:22:17.6368423Z     	at io.servicetalk.concurrent.api.Completable.lambda$subscribeWithContext$3(Completable.java:2197)
2021-04-15T02:22:17.6370901Z     	at io.servicetalk.concurrent.api.ContextPreservingConsumer.accept(ContextPreservingConsumer.java:40)
2021-04-15T02:22:17.6373606Z     	at io.servicetalk.concurrent.api.NoopOffloader.offloadSubscribe(NoopOffloader.java:80)
2021-04-15T02:22:17.6376058Z     	at io.servicetalk.concurrent.api.Completable.subscribeWithContext(Completable.java:2196)
2021-04-15T02:22:17.6378469Z     	at io.servicetalk.concurrent.api.Completable.subscribeInternal(Completable.java:1689)
2021-04-15T02:22:17.6380685Z     	at io.servicetalk.concurrent.api.RetryWhenSingle$RetrySubscriber.onError(RetryWhenSingle.java:99)
2021-04-15T02:22:17.6383610Z     	at io.servicetalk.concurrent.api.ContextPreservingSingleSubscriber.onError(ContextPreservingSingleSubscriber.java:102)
2021-04-15T02:22:17.6386643Z     	at io.servicetalk.concurrent.api.SingleFlatMapSingle$SubscriberImpl$1.onError(SingleFlatMapSingle.java:94)
2021-04-15T02:22:17.6390307Z     	at io.servicetalk.concurrent.api.ContextPreservingCancellableSingleSubscriber.onError(ContextPreservingCancellableSingleSubscriber.java:47)
2021-04-15T02:22:17.6394527Z     	at io.servicetalk.http.utils.BeforeFinallyHttpOperator$ResponseCompletionSubscriber.onError(BeforeFinallyHttpOperator.java:207)
2021-04-15T02:22:17.6397972Z     	at io.servicetalk.concurrent.api.ContextPreservingSingleSubscriber.onError(ContextPreservingSingleSubscriber.java:102)
2021-04-15T02:22:17.6401566Z     	at io.servicetalk.http.netty.H2ClientParentConnectionContext$DefaultH2ClientParentConnection$2.onError(H2ClientParentConnectionContext.java:399)
2021-04-15T02:22:17.6405166Z     	at io.servicetalk.concurrent.api.ContextPreservingSingleSubscriber.onError(ContextPreservingSingleSubscriber.java:102)
2021-04-15T02:22:17.6407767Z     	at io.servicetalk.concurrent.api.MapSingle$1.onError(MapSingle.java:56)
2021-04-15T02:22:17.6409991Z     	at io.servicetalk.http.netty.SpliceFlatStreamToMetaSingle$SplicingSubscriber.onError(SpliceFlatStreamToMetaSingle.java:265)
2021-04-15T02:22:17.6413101Z     	at io.servicetalk.concurrent.api.ContextPreservingSubscriber.onError(ContextPreservingSubscriber.java:99)
2021-04-15T02:22:17.6416886Z     	at io.servicetalk.concurrent.api.ContextPreservingSubscriptionSubscriber.onError(ContextPreservingSubscriptionSubscriber.java:44)
2021-04-15T02:22:17.6420652Z     	at io.servicetalk.concurrent.api.AfterFinallyPublisher$AfterFinallyPublisherSubscriber.onError(AfterFinallyPublisher.java:90)
2021-04-15T02:22:17.6423762Z     	at io.servicetalk.concurrent.api.ContextPreservingSubscriber.onError(ContextPreservingSubscriber.java:99)
2021-04-15T02:22:17.6427158Z     	at io.servicetalk.concurrent.api.CompletableMergeWithPublisher$MergerDelayError.terminateSubscriber(CompletableMergeWithPublisher.java:131)
2021-04-15T02:22:17.6430646Z     	at io.servicetalk.concurrent.api.CompletableMergeWithPublisher$MergerDelayError.onError(CompletableMergeWithPublisher.java:109)
2021-04-15T02:22:17.6435449Z     	at io.servicetalk.concurrent.api.ContextPreservingSubscriptionSubscriber.onError(ContextPreservingSubscriptionSubscriber.java:44)
2021-04-15T02:22:17.6439489Z     	at io.servicetalk.concurrent.api.OnErrorMapPublisher$ErrorMapSubscriber.onError(OnErrorMapPublisher.java:75)
2021-04-15T02:22:17.6442366Z     	at io.servicetalk.concurrent.api.ContextPreservingSubscriber.onError(ContextPreservingSubscriber.java:99)
2021-04-15T02:22:17.6445885Z     	at io.servicetalk.transport.netty.internal.NettyChannelPublisher.sendErrorToTarget(NettyChannelPublisher.java:240)
2021-04-15T02:22:17.6449761Z     	at io.servicetalk.transport.netty.internal.NettyChannelPublisher.exceptionCaught0(NettyChannelPublisher.java:132)
2021-04-15T02:22:17.6453544Z     	at io.servicetalk.transport.netty.internal.NettyChannelPublisher.exceptionCaught(NettyChannelPublisher.java:121)
2021-04-15T02:22:17.6457550Z     	at io.servicetalk.transport.netty.internal.DefaultNettyConnection$NettyToStChannelInboundHandler.exceptionCaught(DefaultNettyConnection.java:608)
2021-04-15T02:22:17.6461271Z     	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302)
2021-04-15T02:22:17.6464694Z     	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281)
2021-04-15T02:22:17.6468036Z     	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273)
2021-04-15T02:22:17.6471272Z     	at io.servicetalk.http.netty.AbstractH2DuplexHandler.userEventTriggered(AbstractH2DuplexHandler.java:62)
2021-04-15T02:22:17.6474840Z     	at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:346)
2021-04-15T02:22:17.6478474Z     	at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:332)
2021-04-15T02:22:17.6482044Z     	at io.netty.channel.AbstractChannelHandlerContext.fireUserEventTriggered(AbstractChannelHandlerContext.java:324)
2021-04-15T02:22:17.6484931Z     	at io.netty.channel.DefaultChannelPipeline$HeadContext.userEventTriggered(DefaultChannelPipeline.java:1428)
2021-04-15T02:22:17.6487883Z     	at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:346)
2021-04-15T02:22:17.6491503Z     	at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:332)
2021-04-15T02:22:17.6494720Z     	at io.netty.channel.DefaultChannelPipeline.fireUserEventTriggered(DefaultChannelPipeline.java:913)
2021-04-15T02:22:17.6497476Z     	at io.netty.handler.codec.http2.Http2MultiplexHandler.channelRead(Http2MultiplexHandler.java:176)
2021-04-15T02:22:17.6500379Z     	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
2021-04-15T02:22:17.6503537Z     	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
2021-04-15T02:22:17.6506632Z     	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
2021-04-15T02:22:17.6509257Z     	at io.netty.handler.codec.http2.Http2FrameCodec.onHttp2Frame(Http2FrameCodec.java:707)
2021-04-15T02:22:17.6511470Z     	at io.netty.handler.codec.http2.Http2FrameCodec$FrameListener.onRstStreamRead(Http2FrameCodec.java:617)
2021-04-15T02:22:17.6514433Z     	at io.netty.handler.codec.http2.Http2FrameListenerDecorator.onRstStreamRead(Http2FrameListenerDecorator.java:59)
2021-04-15T02:22:17.6517890Z     	at io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder$FrameReadListener.onRstStreamRead(DefaultHttp2ConnectionDecoder.java:453)
2021-04-15T02:22:17.6521373Z     	at io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder$PrefaceFrameListener.onRstStreamRead(DefaultHttp2ConnectionDecoder.java:729)
2021-04-15T02:22:17.6524788Z     	at io.netty.handler.codec.http2.DefaultHttp2FrameReader.readRstStreamFrame(DefaultHttp2FrameReader.java:516)
2021-04-15T02:22:17.6528126Z     	at io.netty.handler.codec.http2.DefaultHttp2FrameReader.processPayloadState(DefaultHttp2FrameReader.java:260)
2021-04-15T02:22:17.6531289Z     	at io.netty.handler.codec.http2.DefaultHttp2FrameReader.readFrame(DefaultHttp2FrameReader.java:160)
2021-04-15T02:22:17.6534389Z     	at io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder.decodeFrame(DefaultHttp2ConnectionDecoder.java:181)
2021-04-15T02:22:17.6538662Z     	at io.netty.handler.codec.http2.DecoratingHttp2ConnectionDecoder.decodeFrame(DecoratingHttp2ConnectionDecoder.java:63)
2021-04-15T02:22:17.6541728Z     	at io.netty.handler.codec.http2.Http2ConnectionHandler$FrameDecoder.decode(Http2ConnectionHandler.java:378)
2021-04-15T02:22:17.6544151Z     	at io.netty.handler.codec.http2.Http2ConnectionHandler$PrefaceDecoder.decode(Http2ConnectionHandler.java:242)
2021-04-15T02:22:17.6546799Z     	at io.netty.handler.codec.http2.Http2ConnectionHandler.decode(Http2ConnectionHandler.java:438)
2021-04-15T02:22:17.6549781Z     	at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:508)
2021-04-15T02:22:17.6552704Z     	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:447)
2021-04-15T02:22:17.6555197Z     	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)
2021-04-15T02:22:17.6557950Z     	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
2021-04-15T02:22:17.6561099Z     	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
2021-04-15T02:22:17.6564177Z     	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
2021-04-15T02:22:17.6566727Z     	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
2021-04-15T02:22:17.6569589Z     	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
2021-04-15T02:22:17.6572793Z     	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
2021-04-15T02:22:17.6575575Z     	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
2021-04-15T02:22:17.6578217Z     	at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:795)
2021-04-15T02:22:17.6580591Z     	at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:480)
2021-04-15T02:22:17.6582326Z     	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:378)
2021-04-15T02:22:17.6584208Z     	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
2021-04-15T02:22:17.6586133Z     	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
2021-04-15T02:22:17.6588049Z     	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
2021-04-15T02:22:17.6589516Z     	at java.lang.Thread.run(Thread.java:748)

idelpivnitskiy added a commit to idelpivnitskiy/servicetalk that referenced this issue Apr 15, 2021
Motivation:

Ignore this test until apple#1489 is resolved. Otherwise, it blocks other PRs.
idelpivnitskiy added a commit that referenced this issue Apr 15, 2021
Motivation:

Ignore these tests until #1489 is resolved. Otherwise, it blocks other PRs.
@Scottmitch
Copy link
Member

can we do the following?

  • to test client implements timeout independently of the server -> put an h2 proxy in the middle, strip timeout headers, server never responds
  • to test server implements timeout independently of client -> client disables timeouts

Scottmitch added a commit to Scottmitch/servicetalk-1 that referenced this issue Sep 4, 2021
Motivation:
In the event that gRPC client deadine expires it should send a
RST_STREAM to the peer service. There is a scenario where this may not
happen due to common transport code cleaning up internal state before
propagating the error.

Modifications:
- gRPC utiles to propage the TimeoutException so users can see the
  timeout duration.
- DefaultNettyConnection should still propagate channel close events in
  the event that a write is cancelled.
- WriteStreamSubscriber should still let the close handler know that the
  channel outbound close event occurred even if nothing is pending to
  write when a ChannelOutboundListener#channelClosed event happens. This
  method may not always be the result of a transport error and may be a
  local timeout, in which case we should close the outbound side.

Result:
gRPC will send a RST_STREAM on client timeout. HTTP will close the
channel.
Fixes apple#1489.
Scottmitch added a commit to Scottmitch/servicetalk-1 that referenced this issue Sep 4, 2021
Motivation:
In the event that gRPC client deadine expires it should send a
RST_STREAM to the peer service. There is a scenario where this may not
happen due to common transport code cleaning up internal state before
propagating the error.

Modifications:
- gRPC utiles to propage the TimeoutException so users can see the
  timeout duration.
- DefaultNettyConnection should still propagate channel close events in
  the event that a write is cancelled.
- WriteStreamSubscriber should still let the close handler know that the
  channel outbound close event occurred even if nothing is pending to
  write when a ChannelOutboundListener#channelClosed event happens. This
  method may not always be the result of a transport error and may be a
  local timeout, in which case we should close the outbound side.

Result:
gRPC will send a RST_STREAM on client timeout. HTTP will close the
channel.
Fixes apple#1489.
Scottmitch added a commit that referenced this issue Sep 5, 2021
Motivation:
In the event that gRPC client deadine expires it should send a
RST_STREAM to the peer service. There is a scenario where this may not
happen due to common transport code cleaning up internal state before
propagating the error.

Modifications:
- gRPC utiles to propage the TimeoutException so users can see the
  timeout duration.
- DefaultNettyConnection should still propagate channel close events in
  the event that a write is cancelled.
- WriteStreamSubscriber should still let the close handler know that the
  channel outbound close event occurred even if nothing is pending to
  write when a ChannelOutboundListener#channelClosed event happens. This
  method may not always be the result of a transport error and may be a
  local timeout, in which case we should close the outbound side.

Result:
gRPC will send a RST_STREAM on client timeout. HTTP will close the
channel.
Fixes #1489.
@bondolo bondolo assigned Scottmitch and unassigned bondolo Sep 7, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
flaky tests Unit tests are flaky
Projects
None yet
Development

No branches or pull requests

4 participants