Skip to content

[refactor][broker] Suppress error logging when message expiration fails#19778

Merged
nkurihar merged 1 commit into
apache:masterfrom
massakam:suppress-msg-exp-error
Apr 5, 2023
Merged

[refactor][broker] Suppress error logging when message expiration fails#19778
nkurihar merged 1 commit into
apache:masterfrom
massakam:suppress-msg-exp-error

Conversation

@massakam

@massakam massakam commented Mar 10, 2023

Copy link
Copy Markdown
Contributor

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.

$ ./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.

click to expand
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

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

  • doc
  • doc-required
  • doc-not-needed
  • doc-complete

@massakam massakam added area/broker doc-not-needed Your PR changes do not impact docs type/refactor Code or documentation refactors. e.g. refactor code structure or methods to improve code readability ready-to-test labels Mar 10, 2023
@massakam massakam self-assigned this Mar 10, 2023
@massakam massakam added this to the 3.0.0 milestone Mar 10, 2023
@github-actions github-actions Bot added doc-label-missing and removed doc-not-needed Your PR changes do not impact docs labels Mar 10, 2023
@github-actions

Copy link
Copy Markdown

@massakam Please add the following content to your PR description and select a checkbox:

- [ ] `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 -->

@github-actions github-actions Bot added doc-not-needed Your PR changes do not impact docs and removed doc-label-missing labels Mar 10, 2023
@massakam massakam force-pushed the suppress-msg-exp-error branch 3 times, most recently from efbec10 to 7b37028 Compare March 14, 2023 01:08
@massakam massakam force-pushed the suppress-msg-exp-error branch from 7b37028 to 22b4b8d Compare March 24, 2023 01:44
@massakam massakam force-pushed the suppress-msg-exp-error branch from 22b4b8d to 9a1c906 Compare March 31, 2023 12:13
@codecov-commenter

codecov-commenter commented Apr 1, 2023

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 18.18182% with 36 lines in your changes missing coverage. Please review.
✅ Project coverage is 72.85%. Comparing base (68c10ee) to head (9a1c906).
⚠️ Report is 2683 commits behind head on master.

Files with missing lines Patch % Lines
...pulsar/broker/admin/impl/PersistentTopicsBase.java 18.18% 33 Missing and 3 partials ⚠️
Additional details and impacted files

Impacted file tree graph

@@             Coverage Diff              @@
##             master   #19778      +/-   ##
============================================
- Coverage     72.89%   72.85%   -0.05%     
+ Complexity    31619    31600      -19     
============================================
  Files          1861     1861              
  Lines        137356   137376      +20     
  Branches      15117    15124       +7     
============================================
- Hits         100131   100080      -51     
- Misses        29271    29349      +78     
+ Partials       7954     7947       -7     
Flag Coverage Δ
inttests 24.49% <0.00%> (+0.06%) ⬆️
systests 24.98% <0.00%> (-0.06%) ⬇️
unittests 72.14% <18.18%> (-0.04%) ⬇️

Flags with carried forward coverage won't be shown. Click here to find out more.

Files with missing lines Coverage Δ
...pulsar/broker/admin/impl/PersistentTopicsBase.java 64.24% <18.18%> (-0.36%) ⬇️

... and 60 files with indirect coverage changes

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.
  • 📦 JS Bundle Analysis: Save yourself from yourself by tracking and limiting bundle sizes in JS merges.

@nkurihar nkurihar left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@nkurihar nkurihar merged commit 0d1fe18 into apache:master Apr 5, 2023
@massakam massakam deleted the suppress-msg-exp-error branch April 6, 2023 06:34
lhotari pushed a commit that referenced this pull request Mar 6, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

area/broker cherry-picked/branch-2.11 doc-not-needed Your PR changes do not impact docs ready-to-test release/2.10.6 release/2.11.4 type/refactor Code or documentation refactors. e.g. refactor code structure or methods to improve code readability

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants