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.

Sign up for GitHub

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

Jump to bottom

Flaky-test: TopicAuthZTest.testExpireMessage #22422

Closed
1 of 2 tasks
lhotari opened this issue Apr 4, 2024 · 5 comments
Closed
1 of 2 tasks

Flaky-test: TopicAuthZTest.testExpireMessage #22422

lhotari opened this issue Apr 4, 2024 · 5 comments
Labels
type/flaky-tests

Comments

@lhotari
Copy link
Member

lhotari commented Apr 4, 2024

Search before asking

  • I searched in the issues and found nothing similar.

Example failure

https://github.com/apache/pulsar/actions/runs/8549523859/job/23425218067?pr=22421#step:11:1104

Exception stacktrace

Error:  Tests run: 35, Failures: 1, Errors: 0, Skipped: 28, Time elapsed: 13.596 s <<< FAILURE! - in org.apache.pulsar.broker.admin.TopicAuthZTest
  Error:  org.apache.pulsar.broker.admin.TopicAuthZTest.testExpireMessage[true](4)  Time elapsed: 2.106 s  <<< FAILURE!
  org.apache.pulsar.client.admin.PulsarAdminException$ConflictException: Expire message by timestamp not issued on topic persistent://public/default/22c00dad-ae07-483a-befb-163f173ae312-partition-0 for subscription test-sub due to ongoing message expiration not finished or subscription almost catch  up. If it's performed on a partitioned topic operation might succeeded on other partitions, please check stats of individual partition.
  	at org.apache.pulsar.client.admin.PulsarAdminException.wrap(PulsarAdminException.java:252)
  	at org.apache.pulsar.client.admin.internal.BaseResource.sync(BaseResource.java:352)
  	at org.apache.pulsar.client.admin.internal.TopicsImpl.expireMessages(TopicsImpl.java:828)
  	at org.apache.pulsar.broker.admin.TopicAuthZTest.testExpireMessage(TopicAuthZTest.java:1019)
  	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
  	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
  	at org.testng.internal.invokers.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:139)
  	at org.testng.internal.invokers.InvokeMethodRunnable.runOne(InvokeMethodRunnable.java:47)
  	at org.testng.internal.invokers.InvokeMethodRunnable.call(InvokeMethodRunnable.java:76)
  	at org.testng.internal.invokers.InvokeMethodRunnable.call(InvokeMethodRunnable.java:11)
  	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
  	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
  	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
  	at java.base/java.lang.Thread.run(Thread.java:840)
  	Suppressed: org.apache.pulsar.client.admin.PulsarAdminException$ConflictException: Expire message by timestamp not issued on topic persistent://public/default/22c00dad-ae07-483a-befb-163f173ae312-partition-0 for subscription test-sub due to ongoing message expiration not finished or subscription almost catch  up. If it's performed on a partitioned topic operation might succeeded on other partitions, please check stats of individual partition.
  		at org.apache.pulsar.client.admin.internal.BaseResource.getApiException(BaseResource.java:287)
  		at org.apache.pulsar.client.admin.internal.BaseResource$2.failed(BaseResource.java:168)
  		at org.glassfish.jersey.client.JerseyInvocation$1.failed(JerseyInvocation.java:882)
  		at org.glassfish.jersey.client.JerseyInvocation$1.completed(JerseyInvocation.java:863)
  		at org.glassfish.jersey.client.ClientRuntime.processResponse(ClientRuntime.java:232)
  		at org.glassfish.jersey.client.ClientRuntime.access$200(ClientRuntime.java:62)
  		at org.glassfish.jersey.client.ClientRuntime$2.lambda$response$0(ClientRuntime.java:176)
  		at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248)
  		at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244)
  		at org.glassfish.jersey.internal.Errors.process(Errors.java:292)
  		at org.glassfish.jersey.internal.Errors.process(Errors.java:274)
  		at org.glassfish.jersey.internal.Errors.process(Errors.java:244)
  		at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:288)
  		at org.glassfish.jersey.client.ClientRuntime$2.response(ClientRuntime.java:176)
  		at org.apache.pulsar.client.admin.internal.http.AsyncHttpConnector.lambda$apply$1(AsyncHttpConnector.java:254)
  		at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
  		at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
  		at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
  		at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)
  		at org.apache.pulsar.client.admin.internal.http.AsyncHttpConnector.lambda$retryOperation$4(AsyncHttpConnector.java:296)
  		at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
  		at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
  		at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
  		at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)
  		at org.asynchttpclient.netty.NettyResponseFuture.loadContent(NettyResponseFuture.java:222)
  		at org.asynchttpclient.netty.NettyResponseFuture.done(NettyResponseFuture.java:257)
  		at org.asynchttpclient.netty.handler.AsyncHttpClientHandler.finishUpdate(AsyncHttpClientHandler.java:241)
  		at org.asynchttpclient.netty.handler.HttpHandler.handleChunk(HttpHandler.java:114)
  		at org.asynchttpclient.netty.handler.HttpHandler.handleRead(HttpHandler.java:143)
  		at org.asynchttpclient.netty.handler.AsyncHttpClientHandler.channelRead(AsyncHttpClientHandler.java:78)
  		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
  		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
  		at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
  		at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
  		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
  		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
  		at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
  		at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
  		at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)
  		at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318)
  		at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
  		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
  		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
  		at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
  		at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
  		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
  		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
  		at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
  		at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
  		at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
  		at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
  		at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
  		at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
  		at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
  		at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
  		at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
  		... 1 more
  	Caused by: javax.ws.rs.ClientErrorException: HTTP 409 {"reason":"Expire message by timestamp not issued on topic persistent://public/default/22c00dad-ae07-483a-befb-163f173ae312-partition-0 for subscription test-sub due to ongoing message expiration not finished or subscription almost catch  up. If it's performed on a partitioned topic operation might succeeded on other partitions, please check stats of individual partition."}
  		at org.glassfish.jersey.client.JerseyInvocation.createExceptionForFamily(JerseyInvocation.java:985)
  		at org.glassfish.jersey.client.JerseyInvocation.convertToException(JerseyInvocation.java:967)
  		at org.glassfish.jersey.client.JerseyInvocation.access$700(JerseyInvocation.java:82)
  		... 54 more
  Caused by: [CIRCULAR REFERENCE: javax.ws.rs.ClientErrorException: HTTP 409 {"reason":"Expire message by timestamp not issued on topic persistent://public/default/22c00dad-ae07-483a-befb-163f173ae312-partition-0 for subscription test-sub due to ongoing message expiration not finished or subscription almost catch  up. If it's performed on a partitioned topic operation might succeeded on other partitions, please check stats of individual partition."}]

Are you willing to submit a PR?

  • I'm willing to submit a PR!
@lhotari
Copy link
Member Author

lhotari commented Apr 4, 2024

@Technoboy- this is possibly caused by #22342

@lhotari lhotari mentioned this issue Apr 4, 2024
Merged
4 tasks
@lhotari
Copy link
Member Author

lhotari commented Apr 17, 2024

@Technoboy- @coderzc @liangyepianzhou this test is extremely flaky and fails in most builds. Any chance to fix this?

@lhotari
Copy link
Member Author

lhotari commented Apr 17, 2024

most recent exception

  Error:  Tests run: 4, Failures: 2, Errors: 0, Skipped: 2, Time elapsed: 13.614 s <<< FAILURE! - in org.apache.pulsar.broker.admin.TopicAuthZTest
  Error:  org.apache.pulsar.broker.admin.TopicAuthZTest.testExpireMessage[true](4)  Time elapsed: 2.144 s  <<< FAILURE!
  org.mockito.exceptions.misusing.NullInsteadOfMockException: 
  
  Argument passed to when() is null!
  Example of correct stubbing:
      doThrow(new RuntimeException()).when(mock).someMethod();
  Also, if you use @Mock annotation don't miss openMocks()
  	at org.apache.pulsar.broker.admin.TopicAuthZTest.setAuthorizationTopicOperationChecker(TopicAuthZTest.java:149)
  	at org.apache.pulsar.broker.admin.TopicAuthZTest.testExpireMessage(TopicAuthZTest.java:1139)
  	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
  	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
  	at org.testng.internal.invokers.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:139)
  	at org.testng.internal.invokers.InvokeMethodRunnable.runOne(InvokeMethodRunnable.java:47)
  	at org.testng.internal.invokers.InvokeMethodRunnable.call(InvokeMethodRunnable.java:76)
  	at org.testng.internal.invokers.InvokeMethodRunnable.call(InvokeMethodRunnable.java:11)
  	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
  	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
  	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
  	at java.base/java.lang.Thread.run(Thread.java:840)
  
  Error:  org.apache.pulsar.broker.admin.TopicAuthZTest.testExpireMessage[false](8)  Time elapsed: 2.283 s  <<< FAILURE!
  org.mockito.exceptions.misusing.NullInsteadOfMockException: 
  
  Argument passed to when() is null!
  Example of correct stubbing:
      doThrow(new RuntimeException()).when(mock).someMethod();
  Also, if you use @Mock annotation don't miss openMocks()
  	at org.apache.pulsar.broker.admin.TopicAuthZTest.setAuthorizationTopicOperationChecker(TopicAuthZTest.java:149)
  	at org.apache.pulsar.broker.admin.TopicAuthZTest.testExpireMessage(TopicAuthZTest.java:1139)
  	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
  	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
  	at org.testng.internal.invokers.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:139)
  	at org.testng.internal.invokers.InvokeMethodRunnable.runOne(InvokeMethodRunnable.java:47)
  	at org.testng.internal.invokers.InvokeMethodRunnable.call(InvokeMethodRunnable.java:76)
  	at org.testng.internal.invokers.InvokeMethodRunnable.call(InvokeMethodRunnable.java:11)
  	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
  	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
  	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
  	at java.base/java.lang.Thread.run(Thread.java:840)

in https://github.com/apache/pulsar/actions/runs/8714357909/job/23904472982?pr=22521#step:9:1680

@lhotari
Copy link
Member Author

lhotari commented Apr 17, 2024

The stacktraces hint that the test is using Mockito in the wrong way.
Please see Is Mockito thread-safe?.

@lhotari
Copy link
Member Author

lhotari commented Apr 18, 2024

This was addressed in #22507.

@lhotari lhotari closed this as completed Apr 18, 2024
@lhotari lhotari mentioned this issue Apr 18, 2024
Open
2 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
type/flaky-tests
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@lhotari