publish doesn't publish in certain cases

[boris-petrov]

CometD version(s)
6.0.12 on the backend, 7.0.12 on the frontend.

Java version & vendor (use: java -version)

java 21.0.2 2024-01-16 LTS
Java(TM) SE Runtime Environment (build 21.0.2+13-LTS-58)
Java HotSpot(TM) 64-Bit Server VM (build 21.0.2+13-LTS-58, mixed mode, sharing)

Description
My code is as follows:

server.getChannel("/second").publish(sender, remoteMap, Promise.from(System.err::println, System.err::println));

This seemingly doesn't publish in certain cases. See below.

How to reproduce?
I've attached a log.
logs.txt

The relevant part starts from ---- handling 660f17c20f2fb30a8fc6fdbd. I've left some of the logging before that as I wasn't sure if it's needed. This handling print is immediately before the publish line I've given above. You can see 10 or so lines below there is a true which is from the System.err::println in the code above. Following this ID 660f17c20f2fb30a8fc6fdbd you can see at 00:12:40.884 there is a Stored at batch 19 concerning it - that's the message that I'm publishing. But then there is nothing until 00:12:52.043 when that message is actually sent. That's around 10 seconds later. The reason that's 10 seconds is that my integration test's timeout is that much - what happens is that my test depends on that message to be received and is waiting on something to change in the frontend because of it. The message doesn't arrive, the test timeouts after 10 seconds which causes the page to be torn down. That disconnects the websocket (that's the lots of unsubscribe messages you see) which for some reason causes the backend to just then send the message.

I'm not sure why that happens but I believe this is not a bug in my code?

One thing to note is that I'm using Tomcat 9.0.87 with virtual threads - I'm not sure if that's relevant or matters at all. And of course this doesn't happen every time but I can reproduce it pretty consistently.

[sbordet]

Sorry for the late reply.

I looked at the logs, and there is a publish to /first that wakes up a suspended /meta/connect -- this is for ack=18.

While sending the message and the /meta/connect reply, there is a publish to /second, which is stored at batch 19.

Then, the client sends another /meta/connect with ack=18, the server receives it, sees the correct acks, the logs shows that the CometD session has 1 message in the queue, but the server decides to suspend the /meta/connect, so the message for /second is not sent back to the client.

The logic to decide to suspend is to check whether the queue has non-lazy messages, so my best guess is that either that particular message is lazy or channel /second is a lazy channel, and the message is not sent.
Is that correct?

There are 2 lines in the logs exactly at that moment that are:

true
deleted

You explained the true, but not deleted -- is it relevant?

[boris-petrov]

Hi, no worries.

Is that correct?

Indeed - /second is a lazy (also persistent and with publishing disabled for the client - which perhaps doesn't matter) channel.

You explained the true, but not deleted -- is it relevant?

No, sorry, I should have removed it. It's part of my code which triggers the other events - you can ignore it.

Is that enough information for you? Can you figure out where the problem is (or even if there is one)? Am I doing something wrong or is this an issue with the suspension logic you mention?

[sbordet]

@boris-petrov there is no problem.

Since the channel is lazy, the message is not sent until some other event that would force the message to be sent, see https://docs.cometd.org/current7/reference/#_java_server_lazy_messages.

Seems to me that everything works as expected.

What's your configuration for the lazy timeout?

[boris-petrov]

I have not configured a lazy timeout (actually I have not configured anything at all - everything is with its default value). From the documentation you linked to it seems that the default one is 5 seconds. But in my case you see that the message is not sent for more than 10 seconds.

[sbordet]

The message should be sent after the lazy timeout expires.

I have written a test case that replicates your logs almost identically, and when the lazy timeout expires, the message is sent to the client.

Can you please double-check that you have not disabled the maxLazyTimeout?

[boris-petrov]

I have not disabled maxLazyTimeout. I didn't even know there was such a setting. I had even forgotten that I'm using lazy channels and that there was such a thing. 😄

There is some race-condition somewhere. As I mentioned in the first post, this doesn't happen every time. The question is where... I'm not sure how to help more. 😞 Here's my configuration for the channel:

private static final Authorizer NO_PUBLISH_AUTHORIZER = (operation, channel, session, message) ->
	operation == Authorizer.Operation.PUBLISH && !session.isLocalSession() ?
		Authorizer.Result.deny("Publishing is not allowed on this channel!") :
		Authorizer.Result.grant();

...

	@Configure({ "/first", "/second", "/third" })
	public void configurePersistentLazyNoPublishChannels(ConfigurableServerChannel channel) {
		channel.setPersistent(true);
		channel.setLazy(true);
		channel.addAuthorizer(NO_PUBLISH_AUTHORIZER);
	}

My CometD servlet:

    <servlet>
        <servlet-name>cometd</servlet-name>
        <servlet-class>org.cometd.annotation.server.AnnotationCometDServlet</servlet-class>
        <init-param>
            <param-name>services</param-name>
            <param-value>com.company.service.StreamingService</param-value>
        </init-param>
        <init-param>
            <param-name>ws.cometdURLMapping</param-name>
            <param-value>/streaming/*</param-value>
        </init-param>
        <init-param>
            <param-name>jsonContext</param-name>
            <param-value>com.company.service.JsonSerializer</param-value>
        </init-param>
        <load-on-startup>1</load-on-startup>
        <async-supported>true</async-supported>
    </servlet>
    <servlet-mapping>
        <servlet-name>cometd</servlet-name>
        <url-pattern>/streaming/*</url-pattern>
    </servlet-mapping>

And I have:

@WebListener
public class BayeuxInitializer implements ServletContextAttributeListener {
	@Override
	public void attributeAdded(ServletContextAttributeEvent event) {
		if (BayeuxServer.ATTRIBUTE.equals(event.getName())) {
			BayeuxServer bayeux = (BayeuxServer) event.getValue();
			bayeux.setSecurityPolicy(new StreamingSecurityPolicy());

			// https://docs.cometd.org/current/reference/#_java_server_configuration
			// "ws.messagesPerFrame" should not be changed from its default value of 1: https://groups.google.com/d/msg/cometd-users/xrGyhhk-8YI/aZD_MZIQBAAJ
			// "ws.maxMessageSize" by default has a good value: https://github.com/cometd/cometd/issues/820#issuecomment-456056108
			// "ws.enableExtension.permessage-deflate" is true by default so compression is enabled for WebSockets

			bayeux.addListener(new StreamingService.SessionListenerImpl());
			bayeux.addListener(new StreamingService.SubscriptionListenerImpl());

			// https://docs.cometd.org/current/reference/#_extensions_acknowledge
			bayeux.addExtension(new AcknowledgedMessagesExtension());
		}
	}
}

That's pretty much all the configuration I have. If you have any other ideas, let me know.