[Broker] Failed to process metadata store notification

[lhotari]

Describe the bug

I came a cross multiple odd log entries "Failed to process metadata store notification
java.lang.IllegalArgumentException: Invalid namespace format. expected / or // but got: public" when investigating #11635 .

I wonder if this has recently changed. This is the log entry:

06:28:50.626 [metadata-store-16-1] INFO  org.apache.pulsar.common.naming.NamespaceBundleFactory - Policy updated for namespace public/dedup-2, refreshing the bundle cache.
06:28:50.626 [metadata-store-16-1] ERROR org.apache.pulsar.metadata.impl.AbstractMetadataStore - Failed to process metadata store notification
java.lang.IllegalArgumentException: Invalid namespace format. expected <tenant>/<namespace> or <tenant>/<cluster>/<namespace> but got: public
	at org.apache.pulsar.common.naming.NamespaceName.<init>(NamespaceName.java:125) ~[org.apache.pulsar-pulsar-common-2.9.0-SNAPSHOT.jar:2.9.0-SNAPSHOT]
	at org.apache.pulsar.common.naming.NamespaceName.<init>(NamespaceName.java:34) ~[org.apache.pulsar-pulsar-common-2.9.0-SNAPSHOT.jar:2.9.0-SNAPSHOT]
	at org.apache.pulsar.common.naming.NamespaceName$1.load(NamespaceName.java:46) ~[org.apache.pulsar-pulsar-common-2.9.0-SNAPSHOT.jar:2.9.0-SNAPSHOT]
	at org.apache.pulsar.common.naming.NamespaceName$1.load(NamespaceName.java:43) ~[org.apache.pulsar-pulsar-common-2.9.0-SNAPSHOT.jar:2.9.0-SNAPSHOT]
	at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3529) ~[com.google.guava-guava-30.1-jre.jar:?]
	at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2278) ~[com.google.guava-guava-30.1-jre.jar:?]
	at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2155) ~[com.google.guava-guava-30.1-jre.jar:?]
	at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2045) ~[com.google.guava-guava-30.1-jre.jar:?]
	at com.google.common.cache.LocalCache.get(LocalCache.java:3951) ~[com.google.guava-guava-30.1-jre.jar:?]
	at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3974) ~[com.google.guava-guava-30.1-jre.jar:?]
	at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4935) ~[com.google.guava-guava-30.1-jre.jar:?]
	at org.apache.pulsar.common.naming.NamespaceName.get(NamespaceName.java:69) ~[org.apache.pulsar-pulsar-common-2.9.0-SNAPSHOT.jar:2.9.0-SNAPSHOT]
	at org.apache.pulsar.common.naming.NamespaceBundleFactory.handleMetadataStoreNotification(NamespaceBundleFactory.java:162) ~[org.apache.pulsar-pulsar-broker-2.9.0-SNAPSHOT.jar:2.9.0-SNAPSHOT]
	at org.apache.pulsar.metadata.impl.AbstractMetadataStore.lambda$receivedNotification$0(AbstractMetadataStore.java:149) ~[org.apache.pulsar-pulsar-metadata-2.9.0-SNAPSHOT.jar:2.9.0-SNAPSHOT]
	at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:895) ~[?:1.8.0_292]
	at org.apache.pulsar.metadata.impl.AbstractMetadataStore.lambda$receivedNotification$1(AbstractMetadataStore.java:147) ~[org.apache.pulsar-pulsar-metadata-2.9.0-SNAPSHOT.jar:2.9.0-SNAPSHOT]
	at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1604) [?:1.8.0_292]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_292]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_292]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-common-4.1.66.Final.jar:4.1.66.Final]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_292]
Caused by: java.lang.IllegalArgumentException: Invalid namespace format. namespace: public
	at org.apache.pulsar.common.naming.NamespaceName.<init>(NamespaceName.java:122) ~[org.apache.pulsar-pulsar-common-2.9.0-SNAPSHOT.jar:2.9.0-SNAPSHOT]
	... 20 more

To Reproduce

The above example is from the logs of running cpp-tests (see #11635). I assume that this happens in the master branch for all namespace policy updates.

Expected behavior

Namespace policy updates shouldn't result in errors.

[lhotari]

@merlimat This problem might be related to recent PIP-45 changes. Please take a look.

[lhotari]

this seems to always fail:

pulsar/pulsar-broker/src/main/java/org/apache/pulsar/common/naming/NamespaceBundleFactory.java

Lines 160 to 172 in 794aa20

	private void handleMetadataStoreNotification(Notification n) {
	if (n.getPath().startsWith(LOCAL_POLICIES_ROOT)) {
	final NamespaceName namespace = NamespaceName.get(getNamespaceFromPoliciesPath(n.getPath()));
	try {
	LOG.info("Policy updated for namespace {}, refreshing the bundle cache.", namespace);
	// Trigger a background refresh to fetch new bundle data from the policies
	bundlesCache.synchronous().invalidate(namespace);
	} catch (Exception e) {
	LOG.error("Failed to update the policy change for ns {}", namespace, e);
	}
	}
	}

this logic looks risky:

pulsar/pulsar-broker/src/main/java/org/apache/pulsar/common/naming/NamespaceBundleFactory.java

Lines 330 to 343 in 794aa20

	public static String getNamespaceFromPoliciesPath(String path) {
	if (path.isEmpty()) {
	return path;
	}
	// String before / is considered empty string by splitter
	Iterable<String> splitter = Splitter.on("/").limit(6).split(path);
	Iterator<String> i = splitter.iterator();
	// skip first three - "","admin", "policies"
	i.next();
	i.next();
	i.next();
	// prop, cluster, namespace
	return Joiner.on("/").join(i);
	}

[eolivelli]

I am pretty sure that CI passed when I merged the #11198 patch

probably there is some case that happens rarely

[lhotari]

I am pretty sure that CI passed when I merged the #11198 patch

probably there is some case that happens rarely

It looks like a problem that just gets logged. The problem seems to be that NotificationType.ChildrenChanged isn't handled in NamespaceBundleFactory.handleMetadataStoreNotification.

[eolivelli]

I see.
let's fix it

[lhotari]

This problem seems to be fixed by #11656 . @Technoboy- can you confirm?

[Technoboy-]

This problem seems to be fixed by #11656 . @Technoboy- can you confirm?

Yes, I think so.

[lhotari]

Closing since this is fixed by #11656