Longest prefix match for contexts sometimes doesn't work

[alshain]

tl;dr; From what I can tell, mod_proxy_cluster tries to select a node based on the longest context match. However, very rarely, this does not work. Maybe a race condition due to missing locks?

Our Problem

We have a mod_proxy_cluster loadbalancer, where two nodes register, each with two contexts:

node1: /
node1: /onlyOnNode1
node2: /
node2: /onlyOnNode2

When I send a request /onlyOnNode1 to Apache, this request is sometimes mistakenly forwarded to node2 by mod_proxy_cluster.

The system will run fine for days or weeks, and only then will the problematic behavior occur.
Once the problematic behavior occurs, it doesn't seem to go away until restarting at least Apache or the Tomcat.
However, because the problematic state is very rare, I haven't been able to investigate it much.

Looking at the code

From what I've been able from the code, this part here searches all longest matches for a URL:

mod_proxy_cluster/native/common/common.c

Lines 426 to 435 in 3cd7ad6

	if (strncmp(uri, context->context, len) == 0) {
	if (uri[len] == '\0' || uri[len] == '/' || len == 1) {
	status[j] = context->status;
	length[j] = len;
	if (len > max) {
	max = len;
	}
	}
	}
	}

So in my case assuming the context_table given above, max should be set to strlen(/onlyOnNode1) == 12, and the length array should look like this: 1, 12, 1, 0 .

Then, we do this:

mod_proxy_cluster/native/common/common.c

Lines 440 to 480 in 3cd7ad6

	/* find the best matching contexts */
	nbest = 1;
	for (j = 0; j < sizecontext; j++) {
	if (length[j] == max) {
	nbest++;
	}
	}
	best = apr_palloc(r->pool, sizeof(node_context) * nbest);
	nbest = 0;
	for (j = 0; j < sizecontext; j++) {
	if (length[j] == max) {
	contextinfo_t *context;
	int ok = 0;
	context = &context_table->context_info[j];
	/* Check status */
	switch (status[j]) {
	case ENABLED:
	ok = 1;
	break;
	case DISABLED:
	/* Only the request with sessionid ok for it */
	if (hassession_byname(r, context->node, route, node_table)) {
	ok = 1;
	}
	break;
	}
	if (ok) {
	best[nbest].node = context->node;
	best[nbest].context = context->id;
	nbest++;
	}
	}
	}
	if (nbest == 0) {
	return NULL;
	}
	best[nbest].node = -1;
	/* Save the result */
	apr_table_setn(r->notes, "proxy-context", (char *)best);
	return best;

Here, we ignore any context whose corresponding length-array-entry isn't == max == 12, so the only one remaining would be node1: /onlyOnNode1.

But this can't have happened, otherwise I wouldn't be here.
If my context dind't pass the status check on lines 456-465, we should end up here instead:

mod_proxy_cluster/native/mod_proxy_cluster/mod_proxy_cluster.c

Line 2709 in 9b2f510

ap_log_rerror(APLOG_MARK, APLOG_TRACE6, 0, r, "proxy_cluster_trans: DECLINED %s uri: %s unparsed_uri: %s",

But this didn't happen either. Instead we get to a request on Tomcat Node2.

Any ideas how this could happen?

Possible race condition?

One idea is, that for some reason, maybe a race condition, the entry node1: /onlyOnNode1 is missing completely from the context table. In that case, it might select node2: / instead depending on the order of the context-table.

I wasn't able to make sense of the locking code, however, and how it influences (calls to) read_context_table or maybe it's actually missing?

MCM Status Servlet

Current dump from the MCM servlet (only enabled after we ran into this issue a few times, haven't seen it since):

Node myapp1 (https://myapp1.mycompany:8443):
Enable Contexts Disable Contexts Stop Contexts
Balancer: myapp,LBGroup: ,Flushpackets: Off,Flushwait: 10000,Ping: 10000000,Smax: -1,Ttl: 60000000,Status: OK,Elected: 34929,Read: 967163,Transferred: 590290274,Connected: 0,Load: 100
Virtual Host 1:
Contexts:
/, Status: ENABLED Request: 0 Disable Stop
/onlyOnNode1, Status: ENABLED Request: 0 Disable Stop
Aliases:
localhost

Node myapp2 (https://myapp2.mycompany:8443):
Enable Contexts Disable Contexts Stop Contexts
Balancer: myapp,LBGroup: ,Flushpackets: Off,Flushwait: 10000,Ping: 10000000,Smax: -1,Ttl: 60000000,Status: OK,Elected: 22738,Read: 679877,Transferred: 371948068,Connected: 0,Load: 100
Virtual Host 1:
Contexts:
/, Status: ENABLED Request: 0 Disable Stop
/onlyOnNode2, Status: ENABLED Request: 0 Disable Stop
Aliases:
localhost

Enabling tracing does not seem to print anything about the context selection. Also it doesn't seem to be possible to restrict tracing to the mod_proxy_cluster module.

[jajik]

Hello,

first of all thank you for the whole report. I think we have noticed similar behavior in the past, but as you know, it's hard to reproduce. I will have a deeper look at this hopefully later this week.

For the debugging, there's a way how to specify LogLevel for individual modules in httpd, you can use following

LogLevel debug proxy_cluster:trace8

which will use trace8 LogLevel for mod_proxy_cluster and debug for everything else.

[rhusar]

@alshain Sorry, which version is this? Is this from main branch?

[alshain]

@rhusar The MCM page says "mod_cluster/2.0.0.Alpha1-SNAPSHOT".
On our engineering server, I can find this info:

$ file mod_proxy_cluster.so
mod_proxy_cluster.so: ELF 64-bit LSB shared object, x86-64, version 1 (SYSV), dynamically linked, BuildID[sha1]=32a475cb1d0d798c47f319a9886a4b4cdc417668, with debug_info, not stripped
$ rpm -qf mod_proxy_cluster.so
COMPANY-base-httpd2.4.57-2.3.el8-1.x86_64
$ sha256sum mod_proxy_cluster.so
edda5a756c3eaab356439be5e7d384ecbd70377457be99d8ddc5b674f372e3f7  mod_proxy_cluster.so

I can ask our infra team for more information.

[alshain]

Thank you both for the quick reply.

Regarding the trace logs: That's one variation I hadn't tried. It doesn't put mod_proxy in trace mode either for me, though. The only thing that's worked so far is enabling trace globally. All other logs seem to have a module name, whereas mod_proxy_cluster doesn't:

Compare:

[Wed Oct 15 17:27:38.151281 2025] [:notice] [pid 2483637:tid 139752502753024] Balancer OURBALANCER changed
[Wed Oct 15 17:43:52.019261 2025] [ssl:trace1] [pid 2516296:tid 139686847348736] ssl_engine_init.c(932): Configuring client authentication
[Wed Oct 15 17:43:52.032666 2025] [:debug] [pid 2516299:tid 139686847348736] mod_proxy_cluster.c(764): update_workers_node starting

[jfclere]

Are you using https://docs.modcluster.io/#cachesharefor?

[jajik]

Thank you both for the quick reply.

Regarding the trace logs: That's one variation I hadn't tried. It doesn't put mod_proxy in trace mode either for me, though.

It should work, alternatively you can use the mod_proxy_cluster.c:trace8 instead. See https://httpd.apache.org/docs/2.4/mod/core.html#loglevel

The only thing that's worked so far is enabling trace globally. All other logs seem to have a module name, whereas > mod_proxy_cluster doesn't:

Compare:

[Wed Oct 15 17:27:38.151281 2025] [:notice] [pid 2483637:tid 139752502753024] Balancer OURBALANCER changed
[Wed Oct 15 17:43:52.019261 2025] [ssl:trace1] [pid 2516296:tid 139686847348736] ssl_engine_init.c(932): Configuring client authentication
[Wed Oct 15 17:43:52.032666 2025] [:debug] [pid 2516299:tid 139686847348736] mod_proxy_cluster.c(764): update_workers_node starting

That looks like you're using quite old version, this was fixed year and a half ago (see #219). I would suggest trying it with the latest revision.

[alshain]

Our infra team is preparing to update to the latest version of mod_proxy_cluster, I'll respond back once we manage to reproduce the issue again.

[rhusar]

@alshain Thanks, please report back once you do.

@jajik This issue goes to show exactly why we should improve our build #243 and start cutting development releases.

[jajik]

@jajik This issue goes to show exactly why we should improve our build #243 and start cutting development releases.

We have the process in place, we're just a bit stuck due to the "alpha" stage we're currently in (and beta being postponed for quite some time).

We can release Alpha2 though, if you want.