users@shoal.java.net

Duplicate AppMessages / custom Serializable objects in the DSC

From: John Peters <JPeters_at_haesoft.com>
Date: Tue, 9 Dec 2008 14:06:13 -0700

Hello,

I’ve been trying to integrate Shoal into one of my company’s products, which uses Glassfish. I’ve been struggling with a couple of problems; believe they come from the JXTA implementation. Bear in mind that I’m no JXTA expert (nor am I a Glassfish expert), so the problem may be due to my test server being set up wrong. For reference, I’m testing on Glassfish V2, on a cluster with three instances (all on the same machine).

The first problem occurs whenever an instance broadcasts a message to the entire cluster. I’ve turned up the logging level and confirmed that each message is sent only once. However, each instance in the cluster receives each message twice. Below is the log output of the instance sending the message:

--

[#|2008-12-09T13:32:41.341-0700|FINER|sun-appserver9.1|ShoalLogger|_ThreadID=53;_ThreadName=httpSSLWorkerThread-38082-0;ClassName=com.sun.enterprise.jxtamgmt.ClusterManager;MethodName=send;_RequestID=fae8822f-2047-4f78-a8fd-8527c939bf21;|Broadcasting Message|#]

[#|2008-12-09T13:32:41.341-0700|FINEST|sun-appserver9.1|ShoalLogger|_ThreadID=53;_ThreadName=httpSSLWorkerThread-38082-0;ClassName=com.sun.enterprise.jxtamgmt.ClusterManager;MethodName=pipeMsgEvent;_RequestID=fae8822f-2047-4f78-a8fd-8527c939bf21;|ClusterManager:Received a AppMessage |#]

[#|2008-12-09T13:32:41.341-0700|FINEST|sun-appserver9.1|ShoalLogger|_ThreadID=53;_ThreadName=httpSSLWorkerThread-38082-0;ClassName=com.sun.enterprise.jxtamgmt.ClusterManager;MethodName=pipeMsgEvent;_RequestID=fae8822f-2047-4f78-a8fd-8527c939bf21;|CLUSTERMANAGER:Discarding loopback message|#]

[#|2008-12-09T13:32:41.341-0700|FINEST|sun-appserver9.1|ShoalLogger|_ThreadID=53;_ThreadName=httpSSLWorkerThread-38082-0;ClassName=com.sun.enterprise.jxtamgmt.ClusterManager;MethodName=pipeMsgEvent;_RequestID=fae8822f-2047-4f78-a8fd-8527c939bf21;|ClusterManager:Received a AppMessage |#]

[#|2008-12-09T13:32:41.341-0700|FINEST|sun-appserver9.1|ShoalLogger|_ThreadID=53;_ThreadName=httpSSLWorkerThread-38082-0;ClassName=com.sun.enterprise.jxtamgmt.ClusterManager;MethodName=pipeMsgEvent;_RequestID=fae8822f-2047-4f78-a8fd-8527c939bf21;|CLUSTERMANAGER:Discarding loopback message|#]

--

And below is the log output of another instance in the cluster. A few notes:

- jxta.jar is located at C:\cluster\glassfish\lib\
- shoal-gms.jar is located at C:\cluster\glassfish\nodeagents\NodeAgent\theInstanceName\lib\
- application.* refers to application code, and is located at C:\cluster\glassfish\nodeagents\NodeAgent\theInstanceName\lib\
- application.AbstractSignalHandler is an abstract Callback that manages obtaining and releasing a MessageSignal. The exception it throws in the log is not a ‘real’ exception, just one I created and then logged to display the stack trace.

--

[#|2008-12-09T13:32:41.341-0700|FINEST|sun-appserver9.1|ShoalLogger|_ThreadID=16;_ThreadName=Executor - 3;ClassName=com.sun.enterprise.jxtamgmt.ClusterManager;MethodName=pipeMsgEvent;_RequestID=0650cff4-2cf1-49b3-bd84-07b36b54ee96;|ClusterManager:Received a AppMessage |#]

[#|2008-12-09T13:32:41.356-0700|FINEST|sun-appserver9.1|ShoalLogger|_ThreadID=16;_ThreadName=Executor - 3;ClassName=com.sun.enterprise.jxtamgmt.ClusterManager;MethodName=pipeMsgEvent;_RequestID=0650cff4-2cf1-49b3-bd84-07b36b54ee96;|ClusterManager: Notifying APPMessage Listeners|#]

[#|2008-12-09T13:32:41.356-0700|FINER|sun-appserver9.1|ShoalLogger|_ThreadID=16;_ThreadName=Executor - 3;ClassName=com.sun.enterprise.ee.cms.impl.jxta.GroupCommunicationProviderImpl;MethodName=handleClusterMessage;_RequestID=0650cff4-2cf1-49b3-bd84-07b36b54ee96;|Received AppMessage Notification, placing in message queue|#]

[#|2008-12-09T13:32:41.356-0700|FINEST|sun-appserver9.1|ShoalLogger|_ThreadID=16;_ThreadName=Executor - 3;ClassName=com.sun.enterprise.jxtamgmt.ClusterManager;MethodName=pipeMsgEvent;_RequestID=0650cff4-2cf1-49b3-bd84-07b36b54ee96;|ClusterManager:Received a AppMessage |#]

[#|2008-12-09T13:32:41.356-0700|FINEST|sun-appserver9.1|ShoalLogger|_ThreadID=16;_ThreadName=Executor - 3;ClassName=com.sun.enterprise.jxtamgmt.ClusterManager;MethodName=pipeMsgEvent;_RequestID=0650cff4-2cf1-49b3-bd84-07b36b54ee96;|ClusterManager: Notifying APPMessage Listeners|#]

[#|2008-12-09T13:32:41.356-0700|FINER|sun-appserver9.1|ShoalLogger|_ThreadID=16;_ThreadName=Executor - 3;ClassName=com.sun.enterprise.ee.cms.impl.jxta.GroupCommunicationProviderImpl;MethodName=handleClusterMessage;_RequestID=0650cff4-2cf1-49b3-bd84-07b36b54ee96;|Received AppMessage Notification, placing in message queue|#]

[#|2008-12-09T13:32:41.356-0700|FINER|sun-appserver9.1|ShoalLogger|_ThreadID=19;_ThreadName=MessageWindowThread;ClassName=com.sun.enterprise.ee.cms.impl.jxta.MessageWindow;MethodName=run;_RequestID=64963e8b-5198-4dc5-ab57-8d2dad3c70df;|Processing received message .... |#]

[#|2008-12-09T13:32:41.356-0700|FINER|sun-appserver9.1|ShoalLogger|_ThreadID=19;_ThreadName=MessageWindowThread;ClassName=com.sun.enterprise.ee.cms.impl.jxta.MessageWindow;MethodName=writeLog;_RequestID=64963e8b-5198-4dc5-ab57-8d2dad3c70df;|Sender:Instance3, Receiver :Instance1, TargetComponent :application.EnvironmentAccess, Message :¬í�sr�<application.EnvironmentAccess$LoadEnvironmentMessageQAå*ðõò³[1]��xp|#]

[#|2008-12-09T13:32:41.356-0700|FINER|sun-appserver9.1|ShoalLogger|_ThreadID=43;_ThreadName=MessageWindowThread;ClassName=com.sun.enterprise.ee.cms.impl.jxta.MessageWindow;MethodName=run;_RequestID=b16849ed-6969-4575-b361-672a8ed1bd2c;|Processing received message .... |#]

[#|2008-12-09T13:32:41.372-0700|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=18;_ThreadName=com.sun.enterprise.ee.cms.impl.common.Router Thread;|2008-12-09 13:32:41,372 [com.sun.enterprise.ee.cms.impl.common.Router Thread] TRACE (AbstractSignalHandler.java [processNotification]:37) - Handler class application.EnvironmentAccess$1 received signal...
java.lang.Exception
            at application.AbstractSignalHandler.processNotification(AbstractSignalHandler.java:37)
            at com.sun.enterprise.ee.cms.impl.client.MessageActionImpl.processMessage(MessageActionImpl.java:80)
            at com.sun.enterprise.ee.cms.impl.client.MessageActionImpl.consumeSignal(MessageActionImpl.java:67)
            at com.sun.enterprise.ee.cms.impl.common.Router.notifyMessageAction(Router.java:320)
            at com.sun.enterprise.ee.cms.impl.common.SignalHandler.analyzeSignal(SignalHandler.java:114)
            at com.sun.enterprise.ee.cms.impl.common.SignalHandler.handleSignal(SignalHandler.java:98)
            at com.sun.enterprise.ee.cms.impl.common.SignalHandler.run(SignalHandler.java:87)
            at java.lang.Thread.run(Thread.java:619)
|#]

[#|2008-12-09T13:32:41.372-0700|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=18;_ThreadName=com.sun.enterprise.ee.cms.impl.common.Router Thread;|2008-12-09 13:32:41,372 [com.sun.enterprise.ee.cms.impl.common.Router Thread] TRACE (AbstractSignalHandler.java [processNotification]:40) - Signal is of type interface com.sun.enterprise.ee.cms.core.MessageSignal
|#]

[#|2008-12-09T13:32:41.372-0700|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=18;_ThreadName=com.sun.enterprise.ee.cms.impl.common.Router Thread;|2008-12-09 13:32:41,372 [com.sun.enterprise.ee.cms.impl.common.Router Thread] DEBUG (EnvironmentAccess.java [handle]:31) - Received LoadEnvironmentMessage.
|#]

[[ Server performs the result of the message, accessing from database, etc. ]]

[#|2008-12-09T13:32:41.388-0700|FINER|sun-appserver9.1|ShoalLogger|_ThreadID=43;_ThreadName=MessageWindowThread;ClassName=com.sun.enterprise.ee.cms.impl.jxta.MessageWindow;MethodName=writeLog;_RequestID=b16849ed-6969-4575-b361-672a8ed1bd2c;|Sender:Instance3, Receiver :Instance1, TargetComponent :application.EnvironmentAccess, Message :¬í�sr�<application.EnvironmentAccess$LoadEnvironmentMessageQAå*ðõò³[1]��xp|#]

[#|2008-12-09T13:32:41.388-0700|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=18;_ThreadName=com.sun.enterprise.ee.cms.impl.common.Router Thread;|2008-12-09 13:32:41,388 [com.sun.enterprise.ee.cms.impl.common.Router Thread] TRACE (AbstractSignalHandler.java [processNotification]:37) - Handler class application.EnvironmentAccess$1 received signal...
java.lang.Exception
            at application.AbstractSignalHandler.processNotification(AbstractSignalHandler.java:37)
            at com.sun.enterprise.ee.cms.impl.client.MessageActionImpl.processMessage(MessageActionImpl.java:80)
            at com.sun.enterprise.ee.cms.impl.client.MessageActionImpl.consumeSignal(MessageActionImpl.java:67)
            at com.sun.enterprise.ee.cms.impl.common.Router.notifyMessageAction(Router.java:320)
            at com.sun.enterprise.ee.cms.impl.common.SignalHandler.analyzeSignal(SignalHandler.java:114)
            at com.sun.enterprise.ee.cms.impl.common.SignalHandler.handleSignal(SignalHandler.java:98)
            at com.sun.enterprise.ee.cms.impl.common.SignalHandler.run(SignalHandler.java:87)
            at java.lang.Thread.run(Thread.java:619)
|#]

[#|2008-12-09T13:32:41.388-0700|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=18;_ThreadName=com.sun.enterprise.ee.cms.impl.common.Router Thread;|2008-12-09 13:32:41,388 [com.sun.enterprise.ee.cms.impl.common.Router Thread] TRACE (AbstractSignalHandler.java [processNotification]:40) - Signal is of type interface com.sun.enterprise.ee.cms.core.MessageSignal
|#]

[#|2008-12-09T13:32:41.388-0700|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=18;_ThreadName=com.sun.enterprise.ee.cms.impl.common.Router Thread;|2008-12-09 13:32:41,388 [com.sun.enterprise.ee.cms.impl.common.Router Thread] DEBUG (EnvironmentAccess.java [handle]:31) - Received LoadEnvironmentMessage.
|#]

[[ Server performs the result of the message, accessing from database, etc. ]]

--

The other instances receive the same message twice, and thus perform twice as many database accesses, etc. Again, not a JXTA expert, so it may be that I missed something basic.

The second problem is one that’s already been discussed on this mailing list. I save objects to the DSC in application code with the call getCache().addToCache(componentId, instanceId, key, value). Other instances have the following log message:

--

[#|2008-12-09T13:24:38.169-0700|FINEST|sun-appserver9.1|ShoalLogger|_ThreadID=20;_ThreadName=Executor - 5;ClassName=com.sun.enterprise.jxtamgmt.ClusterManager;MethodName=pipeMsgEvent;_RequestID=233b6064-31b9-4314-a07f-85b30332ff79;|ClusterManager:Received a AppMessage |#]

[#|2008-12-09T13:24:38.169-0700|WARNING|sun-appserver9.1|ShoalLogger|_ThreadID=20;_ThreadName=Executor - 5;_RequestID=233b6064-31b9-4314-a07f-85b30332ff79;|java.lang.ClassNotFoundException: application.LoginToken|#]

--

I’ve avoided this error by serializing ‘value’ to a byte array, but was wondering if there was a better way of solving the problem. The class I’m trying to persist in the DSC is in the instance’s lib folder.

Additionally, the first problem also manifests itself with the DSC; each instance gets two AppMessages stating that something has been stored in the DSC.

Thank you very much for reading this e-mail. I look forward to your response.
John Peters