RealtimeMessaging not working after SmartGWT Upgrade

[MQDeveloper]

SmartClient Version: v13.0p_2024-04-03/PowerEdition Deployment (built 2024-04-03)

I have a SmartGWT project using the RealtimeMessaging Module with ActiveMQ 5.18.3 as the broker. After upgrading from SmartGWT 12.0 to 13.0 the following exception is thrown when running the application.

=== 2024-04-11 13:14:42,975 [1446] ERROR JMSMessageDispatcher - Failed to connect to JMS server
javax.jms.InvalidClientIDException: Broker: localhost - Client: 91A859EE-6B61-448C-9881-D8FBD79EA820 already connected from tcp://127.0.0.1:50244
at org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:265)
at org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:230)
at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:99)
at org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:119)
at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:99)
at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:99)
at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:99)
at org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:852)
at org.apache.activemq.broker.jmx.ManagedTransportConnection.processAddConnection(ManagedTransportConnection.java:77)
at org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:335)
at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:200)
at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:125)
at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:301)
at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:233)
at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:215)
at java.lang.Thread.run(Thread.java:833)

The application can connect to ActiveMQ and send messages, but it can’t establish a websocket connection.

Error:

ISC_RealtimeMessagin…0p_2024-04-03.js:49 WebSocket connection to 'ws://127.0.0.1:8888/gwtModuleName/sc/websocket?ts=1712834943455&isc_noLog=1&type=connect&clientID=91A859EE-6B61-448C-9881-D8FBD79EA820&connectionID=conn_1&subscribedChannels=%7B%0A%20%20%20%20notifications%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%2C%20%0A%20%20%20%20chat%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%0A%7D' failed:

server.properties:

messaging.jms.context: mySettings
messaging.jms.jndiPrefix:
messaging.jms.topicConnectionFactory: jms/ConnectionFactory
jndi.mySettings.java.naming.factory.initial: org.apache.activemq.jndi.ActiveMQInitialContextFactory
jndi.mySettings.java.naming.provider.url: tcp://localhost:61616
messaging.dispatcherImplementer: com.isomorphic.messaging.JMSMessageDispatcher
messaging.websocket.enabled: true
messaging.websocket.URI:/$gwtModuleName/sc/websocket

context.xml:

<Resource auth="Container"
          name="jms/ConnectionFactory"
          type="org.apache.activemq.ActiveMQConnectionFactory"
          description="JMS Connection Factory"
          factory="org.apache.activemq.jndi.JNDIReferenceFactory"
          brokerURL="tcp://localhost:61616"
          brokerName="localhost"/>

<Resource auth="Container"
          name="chatChannel"
          type="org.apache.activemq.command.ActiveMQTopic"
          description="JMS Topic"
          factory="org.apache.activemq.jndi.JNDIReferenceFactory"
          physicalName="chatChannel"/>

ActiveMQ has the default configuration.

Any help would be appreciated.

[Isomorphic]

Note that trimming off error messages and providing partial logs makes it much more difficult to help you.

Need some clarifications:

1) is this server error happening every time or just sometimes? Is it something that happens only on a second attempt, perhaps (would indicate JMS connection cleanup issues)

2) look in your browser's Developer Tools to see what happens when the websocket connection is attempted. There's a difference between total failure (the websocket just isn't there) versus an error occurred (such as your server-side error above). These two scenarios can be discerned also by watching the connection attempt and seeing whether the server error occurs right then. The former (total failure) means looking at your server log to see what happens when we try to register a websocket connection. The latter would be another problem entirely.

3) you mentioned that sending and receiving is working, so can you confirm that COMET seems to be in use (use your browser's developer tools)?

Overall, with the partial logs and lack of information, we can't answer yet.

[MQDeveloper]

After starting the application in the browser, first it attempts to establish the websocket connection, but doesn't find the websocket. (I've also checked if the websocket is opened at /isomorphic/websocket, but it isn't)

[WARN] 404 - GET /gwtModuleName/sc/websocket (127.0.0.1)
   Request headers
      Host: 127.0.0.1:8888
      Connection: Upgrade
      Pragma: no-cache
      Cache-Control: no-cache
      User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36
      Upgrade: websocket
      Origin: http://127.0.0.1:8888
      Sec-WebSocket-Version: 13
      Accept-Encoding: gzip, deflate, br, zstd
      Accept-Language: de,de-DE;q=0.9,en-US;q=0.8,en;q=0.7
      Cookie: isc_cState=ready; JSESSIONID=node0hen7vino4m0q15cyvi1dzo9f61.node0; GLog=~%7B%0A%20%20%20%20trackRPC%3Atrue%2C%20%0A%20%20%20%20isc_pageURL%3A%22http%3A%2F%2F127.0.0.1%3A8888%2Findex.jsp%23home%22%2C%20%0A%20%20%20%20isc_pageGUID%3A%22E650A2F2-0275-45EA-85FB-C1C5BEFF3D4E%22%2C%20%0A%20%20%20%20priorityDefaults%3A%7B%0A%20%20%20%20%20%20%20%20sgwtInternal%3A1%2C%20%0A%20%20%20%20%20%20%20%20RpcTabTiming%3A4%2C%20%0A%20%20%20%20%20%20%20%20Messaging%3A5%2C%20%0A%20%20%20%20%20%20%20%20%22New%20Category%22%3A3%0A%20%20%20%20%7D%2C%20%0A%20%20%20%20defaultPriority%3A3%2C%20%0A%20%20%20%20left%3A-25600%2C%20%0A%20%20%20%20top%3A-25600%2C%20%0A%20%20%20%20width%3A1522%2C%20%0A%20%20%20%20height%3A752%0A%7D
      Sec-WebSocket-Key: ooEpPnVHIWuvqZalfBLTnA==
      Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits
   Response headers
      Cache-Control: must-revalidate,no-cache,no-store
      Content-Type: text/html;charset=iso-8859-1

Then the InvalidIDException happens every few seconds after that.

Looking at the SmartGWT Console, the protocol is downgraded to COMET.

Here is the log:

15:34:43.859:XRP8:DEBUG:Messaging:$zw: subscribe (notifications)
15:34:44.098:XRP8:DEBUG:Messaging:$zw: subscribe (chat)
15:34:45.008:TMR2:DEBUG:Messaging:proceeding to connect
15:34:45.009:TMR2:DEBUG:Messaging:Using WebSocket for comm
15:34:45.661:DEBUG:Messaging:websocket error connecting to: ws://127.0.0.1:8888/gwtModuleName/sc/websocket?ts=1712928885008&type=connect&clientID=8C94C0A2-4DA7-4679-BFE6-3B6003C24829&connectionID=conn_1&subscribedChannels=%7B%0A%20%20%20%20notifications%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%2C%20%0A%20%20%20%20chat%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%0A%7D: {
    "isTrusted":true,
    "type":"error",
    "target":{
        "url":"ws://127.0.0.1:8888/gwtModuleName/sc/websocket?ts=1712928885008&type=connect&clientID=8C94C0A2-4DA7-4679-BFE6-3B6003C24829&connectionID=conn_1&subscribedChannels=%7B%0A%20%20%20%20notifications%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%2C%20%0A%20%20%20%20chat%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%0A%7D",
        "readyState":3,
        "bufferedAmount":0,
        "extensions":"",
        "protocol":"",
        "binaryType":"blob",
        "CONNECTING":0,
        "OPEN":1,
        "CLOSING":2,
        "CLOSED":3
    },
    "currentTarget":{
        "url":"ws://127.0.0.1:8888/gwtModuleName/sc/websocket?ts=1712928885008&type=connect&clientID=8C94C0A2-4DA7-4679-BFE6-3B6003C24829&connectionID=conn_1&subscribedChannels=%7B%0A%20%20%20%20notifications%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%2C%20%0A%20%20%20%20chat%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%0A%7D",
        "readyState":3,
        "bufferedAmount":0,
        "extensions":"",
        "protocol":"",
        "binaryType":"blob",
        "CONNECTING":0,
        "OPEN":1,
        "CLOSING":2,
        "CLOSED":3
    },
    "eventPhase":2,
    "bubbles":false,
    "cancelable":false,
    "defaultPrevented":false,
    "composed":false,
    "timeStamp":6166,
    "srcElement":{
        "url":"ws://127.0.0.1:8888/gwtModuleName/sc/websocket?ts=1712928885008&type=connect&clientID=8C94C0A2-4DA7-4679-BFE6-3B6003C24829&connectionID=conn_1&subscribedChannels=%7B%0A%20%20%20%20notifications%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%2C%20%0A%20%20%20%20chat%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%0A%7D",
        "readyState":3,
        "bufferedAmount":0,
        "extensions":"",
        "protocol":"",
        "binaryType":"blob",
        "CONNECTING":0,
        "OPEN":1,
        "CLOSING":2,
        "CLOSED":3
    },
    "returnValue":true,
    "cancelBubble":false,
    "NONE":0,
    "CAPTURING_PHASE":1,
    "AT_TARGET":2,
    "BUBBLING_PHASE":3
}
15:34:45.662:DEBUG:Messaging:marking websocket protocol unavailable - downgrading to next available protocol
15:34:45.664:DEBUG:Messaging:$zw: downgrade from websocket - onerror handler
15:34:45.665:DEBUG:Messaging:Connection closed - code: 1006, reason:
15:34:45.691:TMR2:DEBUG:Messaging:proceeding to connect
15:34:45.692:TMR2:DEBUG:Messaging:Using EventSource for comm
15:34:45.759:DEBUG:Messaging:connection conn_2 established
15:34:45.760:DEBUG:Messaging:persistent server connection open - ttl: 120000ms, keepaliveDelay: 4000ms, connectTimeout: 10000ms.
15:34:48.758:DEBUG:Messaging:keepalive on conn: conn_2
15:34:49.013:TMR5:DEBUG:Messaging:connect within specified connectTimeout: 10000ms failed, retrying
15:34:49.014:TMR5:DEBUG:Messaging:$zw: connect retry
15:34:49.017:TMR7:DEBUG:Messaging:Destroying connection: conn_2
15:34:49.020:TMR7:DEBUG:Messaging:proceeding to connect
15:34:49.021:TMR7:DEBUG:Messaging:Using EventSource for comm
15:34:49.072:DEBUG:Messaging:EventSource error connecting to: http://127.0.0.1:8888/gwtModuleName/sc/messaging?ts=1712928889020&type=connect&clientID=8C94C0A2-4DA7-4679-BFE6-3B6003C24829&connectionID=conn_3&subscribedChannels=%7B%0A%20%20%20%20notifications%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%2C%20%0A%20%20%20%20chat%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%0A%7D&eventStream=true: {
    "isTrusted":true,
    "type":"error",
    "target":{
        "url":"http://127.0.0.1:8888/gwtModuleName/sc/messaging?ts=1712928889020&type=connect&clientID=8C94C0A2-4DA7-4679-BFE6-3B6003C24829&connectionID=conn_3&subscribedChannels=%7B%0A%20%20%20%20notifications%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%2C%20%0A%20%20%20%20chat%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%0A%7D&eventStream=true",
        "withCredentials":false,
        "readyState":2,
        "onopen":null,
        "onmessage":null,
        "CONNECTING":0,
        "OPEN":1,
        "CLOSED":2
    },
    "currentTarget":{
        "url":"http://127.0.0.1:8888/gwtModuleName/sc/messaging?ts=1712928889020&type=connect&clientID=8C94C0A2-4DA7-4679-BFE6-3B6003C24829&connectionID=conn_3&subscribedChannels=%7B%0A%20%20%20%20notifications%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%2C%20%0A%20%20%20%20chat%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%0A%7D&eventStream=true",
        "withCredentials":false,
        "readyState":2,
        "onopen":null,
        "onmessage":null,
        "CONNECTING":0,
        "OPEN":1,
        "CLOSED":2
    },
    "eventPhase":2,
    "bubbles":false,
    "cancelable":false,
    "defaultPrevented":false,
    "composed":false,
    "timeStamp":9578.799999952316,
    "srcElement":{
        "url":"http://127.0.0.1:8888/gwtModuleName/sc/messaging?ts=1712928889020&type=connect&clientID=8C94C0A2-4DA7-4679-BFE6-3B6003C24829&connectionID=conn_3&subscribedChannels=%7B%0A%20%20%20%20notifications%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%2C%20%0A%20%20%20%20chat%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%0A%7D&eventStream=true",
        "withCredentials":false,
        "readyState":2,
        "onopen":null,
        "onmessage":null,
        "CONNECTING":0,
        "OPEN":1,
        "CLOSED":2
    },
    "returnValue":true,
    "cancelBubble":false,
    "NONE":0,
    "CAPTURING_PHASE":1,
    "AT_TARGET":2,
    "BUBBLING_PHASE":3
}
15:34:49.073:DEBUG:Messaging:EventSource protocol known working - continuing to retry

[Isomorphic]

As far as websockets not working, this is the next step:

The former (total failure) means looking at your server log to see what happens when we try to register a websocket connection.

As far as the COMET fallback (which may not be worth troubleshooting if you can get websockets working), you said messages are being delivered? It looks as if a connecting is established and we immediately receive an error from JMS, so, you would need to troubleshoot why your JMS setup produces this error. You should be able to get the same error if you just try directly (without even a browser).