[Bug] When using TLS to communicate to proxy/brokers, unable to clear namespace backlog. Error does NOT occur when NOT using TLS.

[dameiss-tibco]

Search before asking

• I searched in the issues and found nothing similar.

Read release policy

• I understand that unsupported versions don't get bug fixes. I will attempt to reproduce the issue on a supported version of Pulsar client and Pulsar broker.

Version

Linux c04-pulsar-toolset-0 6.10.0-linuxkit #1 SMP Wed Jul 17 10:51:09 UTC 2024 aarch64 aarch64 aarch64 GNU/Linux
Java 17.0.12
Pulsar 3.0.6
Running in Kubernetes cluster (host platform is MacOS ARM64) using Pulsar helm chartsLinux c04-pulsar-toolset-0 6.10.0-linuxkit #1 SMP Wed Jul 17 10:51:09 UTC 2024 aarch64 aarch64 aarch64 GNU/Linux
Java 17.0.12
Pulsar 3.0.6
Running in Kubernetes cluster (host platform is MacOS ARM64) using Pulsar helm charts

Minimal reproduce step

bin/pulsar-admin namespaces create public/namespace1
bin/pulsar-admin namespaces set-persistence --bookkeeper-ack-quorum 1 --bookkeeper-ensemble 1 --bookkeeper-write-quorum 1 --ml-mark-delete-max-rate 1.0 public/namespace1
bin/pulsar-client produce -m Message public/namespace1/topic1
bin/pulsar-admin topics create-subscription --subscription sub1 persistent://public/namespace1/topic1
bin/pulsar-admin topics bundle-range persistent://public/namespace1/topic1
bin/pulsar-admin namespaces clear-backlog --force public/namespace1
bin/pulsar-admin namespaces clear-backlog --force --sub sub1 public/namespace1
bin/pulsar-admin namespaces clear-backlog --force --bundle 0x80000000_0xc0000000 public/namespace1
bin/pulsar-admin namespaces clear-backlog --force --bundle 0x80000000_0xc0000000 --sub sub1 public/namespace1
bin/pulsar-admin topics unsubscribe --subscription sub1 persistent://public/namespace1/topic1
bin/pulsar-admin topics delete persistent://public/namespace1/topic1
bin/pulsar-admin namespaces delete public/namespace1

What did you expect to see?

Certainly NOT a 500 error. Non-TLS cluster running the same commands yields:

pulsar@c03-pulsar-toolset-0:/pulsar$ bin/pulsar-admin namespaces create public/namespace1
pulsar@c03-pulsar-toolset-0:/pulsar$ bin/pulsar-admin namespaces set-persistence --bookkeeper-ack-quorum 1 --bookkeeper-ensemble 1 --bookkeeper-write-quorum 1 --ml-mark-delete-max-rate 1.0 public/namespace1
pulsar@c03-pulsar-toolset-0:/pulsar$ bin/pulsar-client produce -m Message public/namespace1/topic1
2024-09-19T14:44:13,912+0000 [pulsar-client-io-1-3] INFO  org.apache.pulsar.client.impl.ConnectionPool - [[id: 0x67220b04, L:/10.1.3.234:39716 - R:c03-pulsar-proxy.msgmx.svc.cluster.local/10.111.19.177:6650]] Connected to server
2024-09-19T14:44:14,040+0000 [pulsar-client-io-1-3] INFO  org.apache.pulsar.client.impl.ProducerStatsRecorderImpl - Starting Pulsar producer perf with config: {"topicName":"public/namespace1/topic1","producerName":null,"sendTimeoutMs":30000,"blockIfQueueFull":false,"maxPendingMessages":1000,"maxPendingMessagesAcrossPartitions":50000,"messageRoutingMode":"RoundRobinPartition","hashingScheme":"JavaStringHash","cryptoFailureAction":"FAIL","batchingMaxPublishDelayMicros":1000,"batchingPartitionSwitchFrequencyByPublishDelay":10,"batchingMaxMessages":1000,"batchingMaxBytes":131072,"batchingEnabled":true,"chunkingEnabled":false,"chunkMaxMessageSize":-1,"encryptionKeys":[],"compressionType":"NONE","initialSequenceId":null,"autoUpdatePartitions":true,"autoUpdatePartitionsIntervalSeconds":60,"multiSchema":true,"accessMode":"Shared","lazyStartPartitionedProducers":false,"properties":{},"initialSubscriptionName":null,"nonPartitionedTopicExpected":false}
2024-09-19T14:44:14,050+0000 [pulsar-client-io-1-3] INFO  org.apache.pulsar.client.impl.ProducerStatsRecorderImpl - Pulsar client config: {"serviceUrl":"pulsar://c03-pulsar-proxy:6650/","authPluginClassName":null,"authParams":null,"authParamMap":null,"operationTimeoutMs":30000,"lookupTimeoutMs":30000,"statsIntervalSeconds":60,"numIoThreads":10,"numListenerThreads":10,"connectionsPerBroker":1,"connectionMaxIdleSeconds":180,"useTcpNoDelay":true,"useTls":false,"tlsKeyFilePath":"","tlsCertificateFilePath":"","tlsTrustCertsFilePath":"","tlsAllowInsecureConnection":false,"tlsHostnameVerificationEnable":false,"concurrentLookupRequest":5000,"maxLookupRequest":50000,"maxLookupRedirects":20,"maxNumberOfRejectedRequestPerConnection":50,"keepAliveIntervalSeconds":30,"connectionTimeoutMs":10000,"requestTimeoutMs":60000,"readTimeoutMs":60000,"autoCertRefreshSeconds":300,"initialBackoffIntervalNanos":100000000,"maxBackoffIntervalNanos":60000000000,"enableBusyWait":false,"listenerName":null,"useKeyStoreTls":false,"sslProvider":null,"tlsKeyStoreType":"JKS","tlsKeyStorePath":"","tlsKeyStorePassword":"*****","tlsTrustStoreType":"JKS","tlsTrustStorePath":"","tlsTrustStorePassword":"*****","tlsCiphers":[],"tlsProtocols":[],"memoryLimitBytes":0,"proxyServiceUrl":null,"proxyProtocol":null,"enableTransaction":false,"dnsLookupBindAddress":null,"dnsLookupBindPort":0,"socks5ProxyAddress":null,"socks5ProxyUsername":null,"socks5ProxyPassword":null,"description":null}
2024-09-19T14:44:14,176+0000 [pulsar-client-io-1-5] INFO  org.apache.pulsar.client.impl.ConnectionPool - [[id: 0x50c72f03, L:/10.1.3.234:39730 - R:c03-pulsar-proxy.msgmx.svc.cluster.local/10.111.19.177:6650]] Connected to server
2024-09-19T14:44:14,176+0000 [pulsar-client-io-1-5] INFO  org.apache.pulsar.client.impl.ClientCnx - [id: 0x50c72f03, L:/10.1.3.234:39730 - R:c03-pulsar-proxy.msgmx.svc.cluster.local/10.111.19.177:6650] Connected through proxy to target broker at c03-pulsar-broker-0.c03-pulsar-broker.msgmx.svc.cluster.local:6650
2024-09-19T14:44:14,186+0000 [pulsar-client-io-1-5] INFO  org.apache.pulsar.client.impl.ProducerImpl - [public/namespace1/topic1] [null] Creating producer on cnx [id: 0x50c72f03, L:/10.1.3.234:39730 - R:c03-pulsar-proxy.msgmx.svc.cluster.local/10.111.19.177:6650]
2024-09-19T14:44:14,370+0000 [pulsar-client-io-1-5] INFO  org.apache.pulsar.client.impl.ProducerImpl - [public/namespace1/topic1] [cluster-03-0-3] Created producer on cnx [id: 0x50c72f03, L:/10.1.3.234:39730 - R:c03-pulsar-proxy.msgmx.svc.cluster.local/10.111.19.177:6650]
2024-09-19T14:44:14,407+0000 [main] INFO  org.apache.pulsar.client.impl.ProducerStatsRecorderImpl - [public/namespace1/topic1] [cluster-03-0-3] --- Publish throughput: 2.82 msg/s --- 0.00 Mbit/s --- Latency: med: 28.000 ms - 95pct: 28.000 ms - 99pct: 28.000 ms - 99.9pct: 28.000 ms - max: 28.000 ms --- BatchSize: med: 1.000 - 95pct: 1.000 - 99pct: 1.000 - 99.9pct: 1.000 - max: 1.000 --- MsgSize: med: 7.000 bytes - 95pct: 7.000 bytes - 99pct: 7.000 bytes - 99.9pct: 7.000 bytes - max: 7.000 bytes --- Ack received rate: 2.82 ack/s --- Failed messages: 0 --- Pending messages: 0
2024-09-19T14:44:14,409+0000 [pulsar-client-io-1-5] INFO  org.apache.pulsar.client.impl.ProducerImpl - [public/namespace1/topic1] [cluster-03-0-3] Closed Producer
2024-09-19T14:44:14,410+0000 [main] INFO  org.apache.pulsar.client.impl.PulsarClientImpl - Client closing. URL: pulsar://c03-pulsar-proxy:6650/
2024-09-19T14:44:14,416+0000 [pulsar-client-io-1-5] INFO  org.apache.pulsar.client.impl.ClientCnx - [id: 0x50c72f03, L:/10.1.3.234:39730 ! R:c03-pulsar-proxy.msgmx.svc.cluster.local/10.111.19.177:6650] Disconnected
2024-09-19T14:44:14,416+0000 [pulsar-client-io-1-3] INFO  org.apache.pulsar.client.impl.ClientCnx - [id: 0x67220b04, L:/10.1.3.234:39716 ! R:c03-pulsar-proxy.msgmx.svc.cluster.local/10.111.19.177:6650] Disconnected
2024-09-19T14:44:16,443+0000 [main] INFO  org.apache.pulsar.client.cli.PulsarClientTool - 1 messages successfully produced
pulsar@c03-pulsar-toolset-0:/pulsar$ bin/pulsar-admin topics create-subscription --subscription sub1 persistent://public/namespace1/topic1
pulsar@c03-pulsar-toolset-0:/pulsar$ bin/pulsar-admin topics bundle-range persistent://public/namespace1/topic1
0x80000000_0xc0000000
pulsar@c03-pulsar-toolset-0:/pulsar$ bin/pulsar-admin namespaces clear-backlog --force public/namespace1
pulsar@c03-pulsar-toolset-0:/pulsar$ bin/pulsar-admin namespaces clear-backlog --force --sub sub1 public/namespace1
pulsar@c03-pulsar-toolset-0:/pulsar$ bin/pulsar-admin namespaces clear-backlog --force --bundle 0x80000000_0xc0000000 public/namespace1
pulsar@c03-pulsar-toolset-0:/pulsar$ bin/pulsar-admin namespaces clear-backlog --force --bundle 0x80000000_0xc0000000 --sub sub1 public/namespace1
pulsar@c03-pulsar-toolset-0:/pulsar$ bin/pulsar-admin topics unsubscribe --subscription sub1 persistent://public/namespace1/topic1
pulsar@c03-pulsar-toolset-0:/pulsar$ bin/pulsar-admin topics delete persistent://public/namespace1/topic1
pulsar@c03-pulsar-toolset-0:/pulsar$ bin/pulsar-admin namespaces delete public/namespace1
pulsar@c03-pulsar-toolset-0:/pulsar$ 

What did you see instead?

pulsar@c04-pulsar-toolset-0:/pulsar$ bin/pulsar-admin namespaces create public/namespace1
2024-09-19T14:57:36,924+0000 [main] WARN  org.apache.pulsar.common.util.SecurityUtility - Conscrypt isn't available for Linux aarch64. Using JDK default security provider.
pulsar@c04-pulsar-toolset-0:/pulsar$ bin/pulsar-admin namespaces set-persistence --bookkeeper-ack-quorum 1 --bookkeeper-ensemble 1 --bookkeeper-write-quorum 1 --ml-mark-delete-max-rate 1.0 public/namespace1
2024-09-19T14:57:46,193+0000 [main] WARN  org.apache.pulsar.common.util.SecurityUtility - Conscrypt isn't available for Linux aarch64. Using JDK default security provider.
pulsar@c04-pulsar-toolset-0:/pulsar$ bin/pulsar-client produce -m Message public/namespace1/topic1
2024-09-19T14:57:53,967+0000 [pulsar-client-io-1-3] WARN  org.apache.pulsar.common.util.SecurityUtility - Conscrypt isn't available for Linux aarch64. Using JDK default security provider.
2024-09-19T14:57:54,063+0000 [pulsar-client-io-1-3] INFO  org.apache.pulsar.client.impl.ConnectionPool - [[id: 0xbbd05e8f, L:/10.1.4.48:52230 - R:c04-pulsar-proxy.msgmx.svc.cluster.local/10.106.154.200:6651]] Connected to server
2024-09-19T14:57:54,651+0000 [pulsar-client-io-1-3] INFO  org.apache.pulsar.client.impl.ProducerStatsRecorderImpl - Starting Pulsar producer perf with config: {"topicName":"public/namespace1/topic1","producerName":null,"sendTimeoutMs":30000,"blockIfQueueFull":false,"maxPendingMessages":1000,"maxPendingMessagesAcrossPartitions":50000,"messageRoutingMode":"RoundRobinPartition","hashingScheme":"JavaStringHash","cryptoFailureAction":"FAIL","batchingMaxPublishDelayMicros":1000,"batchingPartitionSwitchFrequencyByPublishDelay":10,"batchingMaxMessages":1000,"batchingMaxBytes":131072,"batchingEnabled":true,"chunkingEnabled":false,"chunkMaxMessageSize":-1,"encryptionKeys":[],"compressionType":"NONE","initialSequenceId":null,"autoUpdatePartitions":true,"autoUpdatePartitionsIntervalSeconds":60,"multiSchema":true,"accessMode":"Shared","lazyStartPartitionedProducers":false,"properties":{},"initialSubscriptionName":null,"nonPartitionedTopicExpected":false}
2024-09-19T14:57:54,661+0000 [pulsar-client-io-1-3] INFO  org.apache.pulsar.client.impl.ProducerStatsRecorderImpl - Pulsar client config: {"serviceUrl":"pulsar+ssl://c04-pulsar-proxy:6651/","authPluginClassName":null,"authParams":null,"authParamMap":null,"operationTimeoutMs":30000,"lookupTimeoutMs":30000,"statsIntervalSeconds":60,"numIoThreads":10,"numListenerThreads":10,"connectionsPerBroker":1,"connectionMaxIdleSeconds":180,"useTcpNoDelay":true,"useTls":true,"tlsKeyFilePath":"","tlsCertificateFilePath":"","tlsTrustCertsFilePath":"/pulsar/certs/proxy-ca/ca.crt","tlsAllowInsecureConnection":false,"tlsHostnameVerificationEnable":false,"concurrentLookupRequest":5000,"maxLookupRequest":50000,"maxLookupRedirects":20,"maxNumberOfRejectedRequestPerConnection":50,"keepAliveIntervalSeconds":30,"connectionTimeoutMs":10000,"requestTimeoutMs":60000,"readTimeoutMs":60000,"autoCertRefreshSeconds":300,"initialBackoffIntervalNanos":100000000,"maxBackoffIntervalNanos":60000000000,"enableBusyWait":false,"listenerName":null,"useKeyStoreTls":false,"sslProvider":null,"tlsKeyStoreType":"JKS","tlsKeyStorePath":"","tlsKeyStorePassword":"*****","tlsTrustStoreType":"JKS","tlsTrustStorePath":"","tlsTrustStorePassword":"*****","tlsCiphers":[],"tlsProtocols":[],"memoryLimitBytes":0,"proxyServiceUrl":null,"proxyProtocol":null,"enableTransaction":false,"dnsLookupBindAddress":null,"dnsLookupBindPort":0,"socks5ProxyAddress":null,"socks5ProxyUsername":null,"socks5ProxyPassword":null,"description":null}
2024-09-19T14:57:55,214+0000 [pulsar-client-io-1-5] INFO  org.apache.pulsar.client.impl.ConnectionPool - [[id: 0xcae86afd, L:/10.1.4.48:52238 - R:c04-pulsar-proxy.msgmx.svc.cluster.local/10.106.154.200:6651]] Connected to server
2024-09-19T14:57:55,215+0000 [pulsar-client-io-1-5] INFO  org.apache.pulsar.client.impl.ClientCnx - [id: 0xcae86afd, L:/10.1.4.48:52238 - R:c04-pulsar-proxy.msgmx.svc.cluster.local/10.106.154.200:6651] Connected through proxy to target broker at c04-pulsar-broker-1.c04-pulsar-broker.msgmx.svc.cluster.local:6651
2024-09-19T14:57:55,247+0000 [pulsar-client-io-1-5] INFO  org.apache.pulsar.client.impl.ProducerImpl - [public/namespace1/topic1] [null] Creating producer on cnx [id: 0xcae86afd, L:/10.1.4.48:52238 - R:c04-pulsar-proxy.msgmx.svc.cluster.local/10.106.154.200:6651]
2024-09-19T14:57:56,678+0000 [pulsar-client-io-1-5] INFO  org.apache.pulsar.client.impl.ProducerImpl - [public/namespace1/topic1] [cluster-04-0-0] Created producer on cnx [id: 0xcae86afd, L:/10.1.4.48:52238 - R:c04-pulsar-proxy.msgmx.svc.cluster.local/10.106.154.200:6651]
2024-09-19T14:57:57,130+0000 [main] INFO  org.apache.pulsar.client.impl.ProducerStatsRecorderImpl - [public/namespace1/topic1] [cluster-04-0-0] --- Publish throughput: 0.41 msg/s --- 0.00 Mbit/s --- Latency: med: 444.000 ms - 95pct: 444.000 ms - 99pct: 444.000 ms - 99.9pct: 444.000 ms - max: 444.000 ms --- BatchSize: med: 1.000 - 95pct: 1.000 - 99pct: 1.000 - 99.9pct: 1.000 - max: 1.000 --- MsgSize: med: 7.000 bytes - 95pct: 7.000 bytes - 99pct: 7.000 bytes - 99.9pct: 7.000 bytes - max: 7.000 bytes --- Ack received rate: 0.41 ack/s --- Failed messages: 0 --- Pending messages: 0
2024-09-19T14:57:57,134+0000 [pulsar-client-io-1-5] INFO  org.apache.pulsar.client.impl.ProducerImpl - [public/namespace1/topic1] [cluster-04-0-0] Closed Producer
2024-09-19T14:57:57,135+0000 [main] INFO  org.apache.pulsar.client.impl.PulsarClientImpl - Client closing. URL: pulsar+ssl://c04-pulsar-proxy:6651/
2024-09-19T14:57:57,141+0000 [pulsar-client-io-1-5] INFO  org.apache.pulsar.client.impl.ClientCnx - [id: 0xcae86afd, L:/10.1.4.48:52238 ! R:c04-pulsar-proxy.msgmx.svc.cluster.local/10.106.154.200:6651] Disconnected
2024-09-19T14:57:57,141+0000 [pulsar-client-io-1-3] INFO  org.apache.pulsar.client.impl.ClientCnx - [id: 0xbbd05e8f, L:/10.1.4.48:52230 ! R:c04-pulsar-proxy.msgmx.svc.cluster.local/10.106.154.200:6651] Disconnected
2024-09-19T14:57:59,165+0000 [main] INFO  org.apache.pulsar.client.cli.PulsarClientTool - 1 messages successfully produced
pulsar@c04-pulsar-toolset-0:/pulsar$ bin/pulsar-admin topics create-subscription --subscription sub1 persistent://public/namespace1/topic1
2024-09-19T14:58:15,895+0000 [main] WARN  org.apache.pulsar.common.util.SecurityUtility - Conscrypt isn't available for Linux aarch64. Using JDK default security provider.
pulsar@c04-pulsar-toolset-0:/pulsar$ bin/pulsar-admin topics bundle-range persistent://public/namespace1/topic1
2024-09-19T14:58:27,812+0000 [main] WARN  org.apache.pulsar.common.util.SecurityUtility - Conscrypt isn't available for Linux aarch64. Using JDK default security provider.
0x80000000_0xc0000000
pulsar@c04-pulsar-toolset-0:/pulsar$ bin/pulsar-admin namespaces clear-backlog --force public/namespace1
2024-09-19T14:58:40,728+0000 [main] WARN  org.apache.pulsar.common.util.SecurityUtility - Conscrypt isn't available for Linux aarch64. Using JDK default security provider.
2024-09-19T14:58:41,547+0000 [AsyncHttpClient-7-1] WARN  org.apache.pulsar.client.admin.internal.BaseResource - [https://c04-pulsar-proxy:443/admin/v2/namespaces/public/namespace1/clearBacklog] Failed to perform http post request: javax.ws.rs.InternalServerErrorException: HTTP 500 {}
HTTP 500 {}

Reason: HTTP 500 {}
pulsar@c04-pulsar-toolset-0:/pulsar$

Anything else?

No response

Are you willing to submit a PR?

• I'm willing to submit a PR!

[lhotari]

@dameiss-tibco Can you reproduce with 3.0.7?

Certainly NOT a 500 error.

Please share the error log from the broker and proxy.

[dameiss-tibco]

Same result with 3.07.

Attached are logs from the proxy, broker-0, broker-1, and the commands/output issued.

broker-0.log
broker-1.log
command.log
proxy.log