szetszwo commented on PR #828: URL: https://github.com/apache/ratis/pull/828#issuecomment-1452874000
Updated the test and added more log messages: https://issues.apache.org/jira/secure/attachment/13055984/828_test2.patch The output looks like below. - Note that `interceptCall`, `start` and `onHeaders` are only invoked once (not per `onNext`). - The timeout mechanism does not work even the total sleep time for all `onNext` is much longer the timeout. ``` 2023-03-02 18:33:11,572 [main] INFO util.LogUtils (Slf4jUtils.java:setLogLevel(38)) - Successfully set org.apache.ratis.conf.ConfUtils log level to WARN 2023-03-02 18:33:11,575 [main] INFO util.LogUtils (Slf4jUtils.java:setLogLevel(38)) - Successfully set org.apache.ratis.util.FileUtils log level to TRACE 2023-03-02 18:33:11,594 [Time-limited test] INFO tests.TestDeadlineClientInterceptor (TestDeadlineClientInterceptor.java:runTestTimeout(77)) - slow = 5, WithInterceptors 2023-03-02 18:33:12,059 [Time-limited test] INFO server.DeadlineClientInterceptor (DeadlineClientInterceptor.java:interceptCall(54)) - callOptions CallOptions{deadline=null, authority=null, callCredentials=null, executor=null, compressorName=null, customOptions=[[internal-stub-type, ASYNC]], waitForReady=false, maxInboundMessageSize=null, maxOutboundMessageSize=null, streamTracerFactories=[]} 2023-03-02 18:33:12,075 [Time-limited test] INFO server.DeadlineClientInterceptor (DeadlineClientInterceptor.java:start(73)) - start Metadata() 2023-03-02 18:33:12,076 [Time-limited test] INFO tests.GrpcTestClient (GrpcTestClient.java:send(107)) - send m0 2023-03-02 18:33:12,085 [Time-limited test] INFO tests.GrpcTestClient (GrpcTestClient.java:send(107)) - send m1 2023-03-02 18:33:12,085 [Time-limited test] INFO tests.GrpcTestClient (GrpcTestClient.java:send(107)) - send m2 2023-03-02 18:33:12,085 [Time-limited test] INFO tests.GrpcTestClient (GrpcTestClient.java:send(107)) - send m3 2023-03-02 18:33:12,085 [Time-limited test] INFO tests.GrpcTestClient (GrpcTestClient.java:send(107)) - send m4 2023-03-02 18:33:12,085 [Time-limited test] INFO tests.GrpcTestClient (GrpcTestClient.java:send(107)) - send m5 2023-03-02 18:33:12,086 [Time-limited test] INFO tests.GrpcTestClient (GrpcTestClient.java:send(107)) - send m6 2023-03-02 18:33:12,086 [Time-limited test] INFO tests.GrpcTestClient (GrpcTestClient.java:send(107)) - send m7 2023-03-02 18:33:12,086 [Time-limited test] INFO tests.GrpcTestClient (GrpcTestClient.java:send(107)) - send m8 2023-03-02 18:33:12,086 [Time-limited test] INFO tests.GrpcTestClient (GrpcTestClient.java:send(107)) - send m9 2023-03-02 18:33:12,315 [grpc-default-executor-1] INFO tests.GreeterImpl (GreeterImpl.java:onNext(53)) - count = 0) Hello m0, slow = 5, sleep 250ms 2023-03-02 18:33:12,578 [grpc-default-executor-1] INFO tests.GreeterImpl (GreeterImpl.java:onNext(53)) - count = 1) Hello m1, slow = 5, sleep 250ms 2023-03-02 18:33:12,580 [grpc-default-executor-0] INFO server.DeadlineClientInterceptor (DeadlineClientInterceptor.java:onHeaders(77)) - onHeaders Metadata(content-type=application/grpc,grpc-encoding=identity,grpc-accept-encoding=gzip) 2023-03-02 18:33:12,581 [Time-limited test] INFO tests.TestDeadlineClientInterceptor (TestDeadlineClientInterceptor.java:runTestTimeout(100)) - 0) passed 2023-03-02 18:33:12,832 [grpc-default-executor-1] INFO tests.GreeterImpl (GreeterImpl.java:onNext(53)) - count = 2) Hello m2, slow = 5, sleep 250ms 2023-03-02 18:33:12,833 [Time-limited test] INFO tests.TestDeadlineClientInterceptor (TestDeadlineClientInterceptor.java:runTestTimeout(100)) - 1) passed 2023-03-02 18:33:13,086 [grpc-default-executor-1] INFO tests.GreeterImpl (GreeterImpl.java:onNext(53)) - count = 3) Hello m3, slow = 5, sleep 250ms 2023-03-02 18:33:13,086 [Time-limited test] INFO tests.TestDeadlineClientInterceptor (TestDeadlineClientInterceptor.java:runTestTimeout(100)) - 2) passed 2023-03-02 18:33:13,341 [grpc-default-executor-1] INFO tests.GreeterImpl (GreeterImpl.java:onNext(53)) - count = 4) Hello m4, slow = 5, sleep 250ms 2023-03-02 18:33:13,341 [Time-limited test] INFO tests.TestDeadlineClientInterceptor (TestDeadlineClientInterceptor.java:runTestTimeout(100)) - 3) passed 2023-03-02 18:33:13,592 [grpc-default-executor-1] INFO tests.GreeterImpl (GreeterImpl.java:onNext(53)) - count = 5) Hello m5, slow = 5, sleep 2s 2023-03-02 18:33:13,592 [Time-limited test] INFO tests.TestDeadlineClientInterceptor (TestDeadlineClientInterceptor.java:runTestTimeout(100)) - 4) passed 2023-03-02 18:33:15,596 [grpc-default-executor-1] INFO tests.GreeterImpl (GreeterImpl.java:onNext(53)) - count = 6) Hello m6, slow = 5, sleep 2s 2023-03-02 18:33:17,602 [grpc-default-executor-1] INFO tests.GreeterImpl (GreeterImpl.java:onNext(53)) - count = 7) Hello m7, slow = 5, sleep 2s 2023-03-02 18:33:19,608 [grpc-default-executor-1] INFO tests.GreeterImpl (GreeterImpl.java:onNext(53)) - count = 8) Hello m8, slow = 5, sleep 2s 2023-03-02 18:33:21,613 [grpc-default-executor-1] INFO tests.GreeterImpl (GreeterImpl.java:onNext(53)) - count = 9) Hello m9, slow = 5, sleep 2s 2023-03-02 18:33:23,624 [grpc-default-executor-1] INFO tests.GrpcTestClient (GrpcTestClient.java:onCompleted(83)) - onCompleted java.lang.AssertionError: 5) reply = 5) Hello m5, COMPLETED at org.junit.Assert.fail(Assert.java:89) at org.apache.ratis.grpc.tests.TestDeadlineClientInterceptor.runTestTimeout(TestDeadlineClientInterceptor.java:107) at org.apache.ratis.grpc.tests.TestDeadlineClientInterceptor.testWithInterceptors(TestDeadlineClientInterceptor.java:57) 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.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27) at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:299) at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:293) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.lang.Thread.run(Thread.java:748) Process finished with exit code 255 ``` -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
