massakam opened a new pull request, #19778: URL: https://github.com/apache/pulsar/pull/19778
### Motivation There are some cases where an error is returned when trying to expire messages using the pulsar-admin command. For example, when there are no messages in the backlog. ```sh $ ./bin/pulsar-admin topics expire-messages -s sub1 -t 1m persistent://public/default/massakam 2023-03-09T16:07:01,485+0900 [AsyncHttpClient-7-1] WARN org.apache.pulsar.client.admin.internal.BaseResource - [http://localhost:8080/admin/v2/persistent/public/default/massakam/subscription/sub1/expireMessages/60] Failed to perform http post request: javax.ws.rs.ClientErrorException: HTTP 409 {"reason":"Expire message by timestamp not issued on topic persistent://public/default/massakam for subscription sub1 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."} Expire message by timestamp not issued on topic persistent://public/default/massakam for subscription sub1 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. Reason: Expire message by timestamp not issued on topic persistent://public/default/massakam for subscription sub1 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. 2023-03-09T16:07:01,529+0900 [main] WARN org.apache.pulsar.common.util.ShutdownUtil - Triggering immediate shutdown of current process with status 1 java.lang.Exception: Stacktrace for immediate shutdown at org.apache.pulsar.common.util.ShutdownUtil.triggerImmediateForcefulShutdown(ShutdownUtil.java:52) ~[pulsar-common.jar:3.0.0-SNAPSHOT] at org.apache.pulsar.admin.cli.PulsarAdminTool.exit(PulsarAdminTool.java:315) ~[pulsar-client-tools.jar:3.0.0-SNAPSHOT] at org.apache.pulsar.admin.cli.PulsarAdminTool.execute(PulsarAdminTool.java:305) ~[pulsar-client-tools.jar:3.0.0-SNAPSHOT] at org.apache.pulsar.admin.cli.PulsarAdminTool.main(PulsarAdminTool.java:280) ~[pulsar-client-tools.jar:3.0.0-SNAPSHOT] ``` At this time, the broker also prints an error log with a very long stacktrace of the exception that caused it. If we are monitoring error logs, this is very noisy and unnecessarily increases the size of the log files. <details> <summary>click to expand</summary> ``` 2023-03-09T16:07:01,449+0900 [pulsar-web-48-9] ERROR org.apache.pulsar.broker.admin.impl.PersistentTopicsBase - [null] Failed to expire messages up to 60 on persistent://public/default/massakam java.util.concurrent.CompletionException: org.apache.pulsar.broker.web.RestException: Expire message by timestamp not issued on topic persistent://public/default/massakam for subscription sub1 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 java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:332) ~[?:?] at java.util.concurrent.CompletableFuture.uniAcceptNow(CompletableFuture.java:747) ~[?:?] at java.util.concurrent.CompletableFuture.uniAcceptStage(CompletableFuture.java:735) ~[?:?] at java.util.concurrent.CompletableFuture.thenAccept(CompletableFuture.java:2182) ~[?:?] at org.apache.pulsar.broker.admin.impl.PersistentTopicsBase.lambda$internalExpireMessagesByTimestamp$389(PersistentTopicsBase.java:3951) ~[pulsar-broker.jar:3.0.0-SNAPSHOT] at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187) ~[?:?] at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2309) ~[?:?] at org.apache.pulsar.broker.admin.impl.PersistentTopicsBase.lambda$internalExpireMessagesByTimestamp$390(PersistentTopicsBase.java:3899) ~[pulsar-broker.jar:3.0.0-SNAPSHOT] at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187) ~[?:?] at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2309) ~[?:?] at org.apache.pulsar.broker.admin.impl.PersistentTopicsBase.lambda$internalExpireMessagesByTimestamp$391(PersistentTopicsBase.java:3896) ~[pulsar-broker.jar:3.0.0-SNAPSHOT] at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187) ~[?:?] at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2309) ~[?:?] at org.apache.pulsar.broker.admin.impl.PersistentTopicsBase.internalExpireMessagesByTimestamp(PersistentTopicsBase.java:3893) ~[pulsar-broker.jar:3.0.0-SNAPSHOT] at org.apache.pulsar.broker.admin.v2.PersistentTopics.expireTopicMessages(PersistentTopics.java:1485) ~[pulsar-broker.jar:3.0.0-SNAPSHOT] at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?] at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?] at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?] at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?] at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory.lambda$static$0(ResourceMethodInvocationHandlerFactory.java:52) ~[jersey-server-2.34.jar:?] at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:124) ~[jersey-server-2.34.jar:?] at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:167) ~[jersey-server-2.34.jar:?] at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$VoidOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:159) ~[jersey-server-2.34.jar:?] at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:79) ~[jersey-server-2.34.jar:?] at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:475) ~[jersey-server-2.34.jar:?] at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:397) ~[jersey-server-2.34.jar:?] at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:81) ~[jersey-server-2.34.jar:?] at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:255) ~[jersey-server-2.34.jar:?] at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248) ~[jersey-common-2.34.jar:?] at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244) ~[jersey-common-2.34.jar:?] at org.glassfish.jersey.internal.Errors.process(Errors.java:292) ~[jersey-common-2.34.jar:?] at org.glassfish.jersey.internal.Errors.process(Errors.java:274) ~[jersey-common-2.34.jar:?] at org.glassfish.jersey.internal.Errors.process(Errors.java:244) ~[jersey-common-2.34.jar:?] at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:265) ~[jersey-common-2.34.jar:?] at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:234) ~[jersey-server-2.34.jar:?] at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:680) ~[jersey-server-2.34.jar:?] at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:394) ~[jersey-container-servlet-core-2.34.jar:?] at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:346) ~[jersey-container-servlet-core-2.34.jar:?] at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:366) ~[jersey-container-servlet-core-2.34.jar:?] at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:319) ~[jersey-container-servlet-core-2.34.jar:?] at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:205) ~[jersey-container-servlet-core-2.34.jar:?] at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1656) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.servlets.QoSFilter.doFilter(QoSFilter.java:202) ~[jetty-servlets-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1626) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:552) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[jetty-server-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[jetty-server-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[jetty-server-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440) ~[jetty-server-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[jetty-server-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[jetty-server-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[jetty-server-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355) ~[jetty-server-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[jetty-server-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234) ~[jetty-server-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146) ~[jetty-server-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:181) ~[jetty-server-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[jetty-server-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[jetty-server-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487) ~[jetty-server-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732) ~[jetty-server-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479) ~[jetty-server-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) ~[jetty-server-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[jetty-io-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[jetty-io-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[jetty-io-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) ~[jetty-util-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) ~[jetty-util-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) ~[jetty-util-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) ~[jetty-util-9.4.48.v20220622.jar:9.4.48.v20220622] at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) ~[jetty-util-9.4.48.v20220622.jar:9.4.48.v20220622] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.89.Final.jar:4.1.89.Final] at java.lang.Thread.run(Thread.java:833) ~[?:?] Caused by: org.apache.pulsar.broker.web.RestException: Expire message by timestamp not issued on topic persistent://public/default/massakam for subscription sub1 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.broker.admin.impl.PersistentTopicsBase.lambda$internalExpireMessagesByTimestampForSinglePartitionAsync$393(PersistentTopicsBase.java:4021) ~[pulsar-broker.jar:3.0.0-SNAPSHOT] at java.util.concurrent.CompletableFuture.uniAcceptNow(CompletableFuture.java:757) ~[?:?] at java.util.concurrent.CompletableFuture.uniAcceptStage(CompletableFuture.java:735) ~[?:?] at java.util.concurrent.CompletableFuture.thenAccept(CompletableFuture.java:2182) ~[?:?] at org.apache.pulsar.broker.admin.impl.PersistentTopicsBase.internalExpireMessagesByTimestampForSinglePartitionAsync(PersistentTopicsBase.java:3975) ~[pulsar-broker.jar:3.0.0-SNAPSHOT] at org.apache.pulsar.broker.admin.impl.PersistentTopicsBase.lambda$internalExpireMessagesByTimestamp$389(PersistentTopicsBase.java:3950) ~[pulsar-broker.jar:3.0.0-SNAPSHOT] ... 73 more ``` </details> In many cases, it is caused by incorrect requests from users, so I think the log level should be warn instead of error. ### Modifications In the admin APIs to expire messages, if the exception thrown is `RestException`, log a warn, otherwise log an error with the stacktrace of the exception. ### Verifying this change - [ ] Make sure that the change passes the CI checks. ### Documentation <!-- DO NOT REMOVE THIS SECTION. CHECK THE PROPER BOX ONLY. --> - [ ] `doc` <!-- Your PR contains doc changes. --> - [ ] `doc-required` <!-- Your PR changes impact docs and you will update later --> - [ ] `doc-not-needed` <!-- Your PR changes do not impact docs --> - [ ] `doc-complete` <!-- Docs have been already added --> -- 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]
