You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@pulsar.apache.org by "massakam (via GitHub)" <gi...@apache.org> on 2023/03/10 05:55:34 UTC
[GitHub] [pulsar] massakam opened a new pull request, #19778: [refactor][broker] Suppress error logging when message expiration fails
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] github-actions[bot] commented on pull request #19778: [refactor][broker] Suppress error logging when message expiration fails
Posted by "github-actions[bot] (via GitHub)" <gi...@apache.org>.
github-actions[bot] commented on PR #19778:
URL: https://github.com/apache/pulsar/pull/19778#issuecomment-1463313458
@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 -->
```
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] codecov-commenter commented on pull request #19778: [refactor][broker] Suppress error logging when message expiration fails
Posted by "codecov-commenter (via GitHub)" <gi...@apache.org>.
codecov-commenter commented on PR #19778:
URL: https://github.com/apache/pulsar/pull/19778#issuecomment-1493041374
## [Codecov](https://codecov.io/gh/apache/pulsar/pull/19778?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=The+Apache+Software+Foundation) Report
> Merging [#19778](https://codecov.io/gh/apache/pulsar/pull/19778?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=The+Apache+Software+Foundation) (9a1c906) into [master](https://codecov.io/gh/apache/pulsar/commit/68c10eed7604aa3dcc3a6d8b548575e99b94dca2?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=The+Apache+Software+Foundation) (68c10ee) will **decrease** coverage by `0.05%`.
> The diff coverage is `18.18%`.
[](https://codecov.io/gh/apache/pulsar/pull/19778?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=The+Apache+Software+Foundation)
```diff
@@ 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%)` | :arrow_up: |
| systests | `24.98% <0.00%> (-0.06%)` | :arrow_down: |
| unittests | `72.14% <18.18%> (-0.04%)` | :arrow_down: |
Flags with carried forward coverage won't be shown. [Click here](https://docs.codecov.io/docs/carryforward-flags?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=The+Apache+Software+Foundation#carryforward-flags-in-the-pull-request-comment) to find out more.
| [Impacted Files](https://codecov.io/gh/apache/pulsar/pull/19778?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=The+Apache+Software+Foundation) | Coverage Δ | |
|---|---|---|
| [...pulsar/broker/admin/impl/PersistentTopicsBase.java](https://codecov.io/gh/apache/pulsar/pull/19778?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=The+Apache+Software+Foundation#diff-cHVsc2FyLWJyb2tlci9zcmMvbWFpbi9qYXZhL29yZy9hcGFjaGUvcHVsc2FyL2Jyb2tlci9hZG1pbi9pbXBsL1BlcnNpc3RlbnRUb3BpY3NCYXNlLmphdmE=) | `64.24% <18.18%> (-0.36%)` | :arrow_down: |
... and [60 files with indirect coverage changes](https://codecov.io/gh/apache/pulsar/pull/19778/indirect-changes?src=pr&el=tree-more&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=The+Apache+Software+Foundation)
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] nkurihar merged pull request #19778: [refactor][broker] Suppress error logging when message expiration fails
Posted by "nkurihar (via GitHub)" <gi...@apache.org>.
nkurihar merged PR #19778:
URL: https://github.com/apache/pulsar/pull/19778
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org