jain-sip-ha Dialog replication

[Mic]

Hello,

I need to move an application (using jain-sip) to a JBoss cluster.
I would like to use Mobicents and jain-sip-ha to be able to replicate
the javax.sip.Dialog.

I installed a two nodes Mobicents (mss-1.2-
jboss-5.1.0.GA-1001281339.zip) cluster using POJO cache to share the
data between nodes.

My problem is that the following is not working:

1) Node 1 is doing a SUBSCRIBE:

ClientTransaction clientTransaction =
SipHelper.getInstance().getSipProvider().getNewClientTransaction(request);
Dialog dialog = clientTransaction.getDialog();
clientTransaction.sendRequest();

2) Node 1 puts the dialog into the POJO cache.

3) Node 2 gets the dialog from the POJO cache

4) The dialog retrieved by Node 2 is not valid:

dialog.toString() is "gov.nist.javax.sip.stack.SIPDialog@4c1d89f"
dialog.getState() is null !!!
dialog.getDialogId() is null !!!

and, if I try to send a SUBSCRIBE refresh, I get the following:

2010-03-10 18:06:36,697 ERROR [IPS_PROVIDER] (Thread-25) ERROR: Dialog
not yet established -- no response!
javax.sip.SipException: Dialog not yet established -- no response!
at gov.nist.javax.sip.stack.SIPDialog.createRequest(SIPDialog.java:
1860)
at
it.italtel.ipif.providers.ips.helper.IPSMediator.doSubscribe(IPSMediator.java:
264)

Could someone tell me what is wrong in my procedure?

Thanks and best regards, Michele

----------------------------------------------------------------------------------------------------------------

PS This is how the SIP Stack is initialized on both JBoss Cluster
Nodes :

public class SipHelper {

private SipStackImpl sipStack;
private SipProvider sipProvider;
private MessageFactory messageFactory;
private HeaderFactory headerFactory;
private AddressFactory addressFactory;
private SipListenerImpl sipListener;
private ListeningPoint lp;
private ListeningPoint lp2;

private void initSipStack(SipResultListener sipResultListener,
SipNotifyListener sipNotifyListener) throws Exception
{
Properties properties = new Properties();
properties.setProperty("javax.sip.STACK_NAME",
"italtel.ipif.ips");
properties.setProperty(ManagedMobicentsSipCache.STANDALONE,
"false");
properties.setProperty("javax.sip.OUTBOUND_PROXY",
getServerAddress() + ":" + getServerPort() + "/"+
getTransportProtocol());
// log
properties.setProperty("gov.nist.javax.sip.TRACE_LEVEL",
String.valueOf(ServerLog.TRACE_MESSAGES));
properties.setProperty("gov.nist.javax.sip.SERVER_LOG", LOG_PATH +
"jain_server.log");
properties.setProperty("gov.nist.javax.sip.BAD_MESSAGE_LOG",
LOG_PATH + "jain_unprocessed.log");
properties.setProperty("gov.nist.javax.sip.DEBUG_LOG", LOG_PATH +
"jain_debug.log");
properties.setProperty("gov.nist.javax.sip.LOG_LIFETIME", "3600");
properties.setProperty("gov.nist.javax.sip.LOG_MESSAGE_CONTENT",
"true");

try {
properties.load(new FileInputStream(CONF_PATH + "jain-
sip.properties"));
} catch (FileNotFoundException e) {
if (log.isEnabledFor(Priority.WARN)) {
log.warn(CONF_PATH + "jain-sip.properties" + ":
Configuration file not found for jain-sip!");
}
} catch (IOException e) {
if (log.isEnabledFor(Priority.WARN)) {
log.warn("load " + CONF_PATH + "jain-sip.properties
Error!!");
}
if (log.isDebugEnabled()) {
log.debug("This is the stackTrace: ", e );
}
}

// Create SipStack object
SipFactory sipFactory = SipFactory.getInstance();
sipFactory.setPathName("org.mobicents.ha");
sipStack = sipFactory.createSipStack(properties);
headerFactory = sipFactory.createHeaderFactory();
addressFactory = sipFactory.createAddressFactory();
messageFactory = sipFactory.createMessageFactory();
lp = sipStack.createListeningPoint(getClientAddress(),
getClientPort(), getTransportProtocol());
lp2 = sipStack.createListeningPoint(getClientAddress(),
getClientPort(), getOtherTransportProtocol());
sipProvider = sipStack.createSipProvider(lp);
sipProvider.addListeningPoint(lp2);
sipListener = new SipListenerImpl(log, sipResultListener,
sipNotifyListener);
sipProvider.addSipListener((SipListener)sipListener);
sipStack.start();
}

and this id the jain-sip.properties configuration file:

#Configurazione con proxy
#javax.sip.OUTBOUND_PROXY=<ip_address>:<port>/<transport_protocol>

#Parametri per il LOG
gov.nist.javax.sip.TRACE_LEVEL=32
gov.nist.javax.sip.LOG_MESSAGE_CONTENT=true
gov.nist.javax.sip.LOG_LIFETIME=3600
gov.nist.javax.sip.ACCESS_LOG_VIA_RMI=false
gov.nist.javax.sip.RMI_PORT=8177

#Parametri per ottimizzare le connessioni TCP
gov.nist.javax.sip.CACHE_SERVER_CONNECTIONS=true
gov.nist.javax.sip.CACHE_CLIENT_CONNECTIONS=true
#gov.nist.javax.sip.MAX_CONNECTIONS=numero massimo di socket TCP
contemporanee
gov.nist.javax.sip.MAX_CONNECTIONS=5048576

#Parametri per ottimizzare le transazioni sip
javax.sip.AUTOMATIC_DIALOG_SUPPORT=off
gov.nist.javax.sip.DELIVER_UNSOLICITED_NOTIFY=true
#gov.nist.javax.sip.THREAD_POOL_SIZE=64
gov.nist.javax.sip.REENTRANT_LISTENER=true
# setting up the buffer size to reduce retransmissions and avoid
loosing messages
gov.nist.javax.sip.RECEIVE_UDP_BUFFER_SIZE=65536
gov.nist.javax.sip.SEND_UDP_BUFFER_SIZE=65536
#cache used by jain sip ha to replicate dialogs
#org.mobicents.ha.javax.sip.cache.MobicentsSipCache.cacheName=standard-
session-cache
org.mobicents.ha.javax.sip.cache.MobicentsSipCache.cacheName=ha-
partition

[Jean Deruelle]

If you only use pure JAIN SIP you don't need to install Mobicents at all, just need the jain sip ha libraries, jgroups and jboss cache.

It seems your application is still using the standard dialog dialog.toString() is "gov.nist.javax.sip.stack.SIPDialog@4c1d89f" instead of gov.nist.javax.sip.stack.ConfirmedNoAppDataReplicationSipDialog even though your configuration looks correct

I would recommend checking out http://mobicents.googlecode.com/svn/trunk/servers/jain-sip-ha/ and try this test out http://mobicents.googlecode.com/svn/trunk/servers/jain-sip-ha/jboss-5/src/test/java/org/mobicents/ha/javax/sip/SimpleDialogRecoveryTest.java

Don't forget to modify the IP_ADDRESS in the test.properties or in the code source of the test directly to match your own

If this works, check the code to see what is different in the test and in your application.

I will try to write a blog post about JAIN SIP HA over the week end

Jean

[Michele Mazza]

Hello,

I am testing SimpleDialogRecoveryTest.java as you suggested.

I modified udp.xml in jgroups.jar to have enable_bundling="false" in my mss-1.2-jboss-5.1.0.GA installation.

I run it on my Eclipse (please note that Mobicents is NOT running) and I get the following:

12:40:18,223 DEBUG [StatelessForwarder] BUILD TIMESTAMP = null

12:40:18,239 DEBUG [StatelessForwarder] Config Propeties = {gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.RETRANSMISSION_FILTER=true, javax.sip.AUTOMATIC_DIALOG_SUPPORT=off, javax.sip.STACK_NAME=StatelessForwarder, gov.nist.javax.sip.SERVER_LOG=./logs/statelessforwarderlog.xml, gov.nist.javax.sip.DEBUG_LOG=./logs/statelessforwarderdebug.txt}

12:40:18,239 DEBUG [StatelessForwarder] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:256) [Here are the stack configuration properties 

{gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.RETRANSMISSION_FILTER=true, javax.sip.AUTOMATIC_DIALOG_SUPPORT=off, javax.sip.STACK_NAME=StatelessForwarder, gov.nist.javax.sip.SERVER_LOG=./logs/statelessforwarderlog.xml, gov.nist.javax.sip.DEBUG_LOG=./logs/statelessforwarderdebug.txt}

]

12:40:18,255 DEBUG [StatelessForwarder] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:258) [ ]]>]

12:40:18,255 DEBUG [StatelessForwarder] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:259) [</debug>]

12:40:18,255 DEBUG [StatelessForwarder] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:260) [<description

 logDescription="StatelessForwarder"

 name="null" />

]

12:40:18,255 DEBUG [StatelessForwarder] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:262) [<debug>]

12:40:18,255 DEBUG [StatelessForwarder] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:263) [<![CDATA[ ]

12:40:18,286 DEBUG [StatelessForwarder] gov.nist.javax.sip.SipStackImpl.<init>(SipStackImpl.java:1002) [created Sip stack. Properties = {gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.RETRANSMISSION_FILTER=true, javax.sip.AUTOMATIC_DIALOG_SUPPORT=off, javax.sip.STACK_NAME=StatelessForwarder, gov.nist.javax.sip.SERVER_LOG=./logs/statelessforwarderlog.xml, gov.nist.javax.sip.DEBUG_LOG=./logs/statelessforwarderdebug.txt}]

12:40:18,427 DEBUG [StatelessForwarder] gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:1065) [createListeningPoint : address = 138.132.34.18 port = 5050 transport = UDP]

12:40:19,223 DEBUG [StatelessForwarder] gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:1101) [Created Message Processor: 138.132.34.18 port = 5050 transport = UDP]

12:40:19,223 DEBUG [StatelessForwarder] gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:199) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@11f2ee1 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@3ecfff]

12:40:19,223 DEBUG [StatelessForwarder] gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:1133) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@3ecfff]

12:40:19,255 DEBUG [StatelessForwarder] gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:233) [add SipListener org.mobicents.ha.javax.sip.SimpleDialogRecoveryTest$Balancer@1e0ff2f]

12:40:19,583 DEBUG [shootme] BUILD TIMESTAMP = null

12:40:19,583 DEBUG [shootme] Config Propeties = {org.mobicents.ha.javax.sip.CACHE_CLASS_NAME=org.mobicents.ha.javax.sip.cache.ManagedMobicentsSipCache, gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.STACK_NAME=shootme, gov.nist.javax.sip.SERVER_LOG=logs/shootmelog.xml, org.mobicents.ha.javax.sip.cache.MobicentsSipCache.standalone=true, gov.nist.javax.sip.DEBUG_LOG=logs/shootmedebug.txt}

12:40:19,583 DEBUG [shootme] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:256) [Here are the stack configuration properties 

{org.mobicents.ha.javax.sip.CACHE_CLASS_NAME=org.mobicents.ha.javax.sip.cache.ManagedMobicentsSipCache, gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.STACK_NAME=shootme, gov.nist.javax.sip.SERVER_LOG=logs/shootmelog.xml, org.mobicents.ha.javax.sip.cache.MobicentsSipCache.standalone=true, gov.nist.javax.sip.DEBUG_LOG=logs/shootmedebug.txt}

]

12:40:19,583 DEBUG [shootme] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:258) [ ]]>]

12:40:19,583 DEBUG [shootme] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:259) [</debug>]

12:40:19,583 DEBUG [shootme] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:260) [<description

 logDescription="shootme"

 name="null" />

]

12:40:19,583 DEBUG [shootme] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:262) [<debug>]

12:40:19,583 DEBUG [shootme] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:263) [<![CDATA[ ]

12:40:19,583 DEBUG [shootme] gov.nist.javax.sip.SipStackImpl.<init>(SipStackImpl.java:1002) [created Sip stack. Properties = {org.mobicents.ha.javax.sip.CACHE_CLASS_NAME=org.mobicents.ha.javax.sip.cache.ManagedMobicentsSipCache, gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.STACK_NAME=shootme, gov.nist.javax.sip.SERVER_LOG=logs/shootmelog.xml, org.mobicents.ha.javax.sip.cache.MobicentsSipCache.standalone=true, gov.nist.javax.sip.DEBUG_LOG=logs/shootmedebug.txt}]

12:40:19,677 INFO  [shootme] Mobicents JAIN SIP JBoss Cache Configuration path is : META-INF/cache-configuration.xml

javax.sip.PeerUnavailableException: The Peer SIP Stack: org.mobicents.ha.javax.sip.SipStackImpl could not be instantiated. Ensure the Path Name has been set.

at javax.sip.SipFactory.createStack(SipFactory.java:324)

at javax.sip.SipFactory.createSipStack(SipFactory.java:152)

at org.mobicents.ha.javax.sip.SimpleDialogRecoveryTest$Shootme.init(SimpleDialogRecoveryTest.java:544)

at org.mobicents.ha.javax.sip.SimpleDialogRecoveryTest.testDialogFailover(SimpleDialogRecoveryTest.java:1069)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

at java.lang.reflect.Method.invoke(Unknown Source)

at junit.framework.TestCase.runTest(TestCase.java:154)

at junit.framework.TestCase.runBare(TestCase.java:127)

at junit.framework.TestResult$1.protect(TestResult.java:106)

at junit.framework.TestResult.runProtected(TestResult.java:124)

at junit.framework.TestResult.run(TestResult.java:109)

at junit.framework.TestCase.run(TestCase.java:118)

at junit.framework.TestSuite.runTest(TestSuite.java:208)

at junit.framework.TestSuite.run(TestSuite.java:203)

at org.eclipse.jdt.internal.junit.runner.junit3.JUnit3TestReference.run(JUnit3TestReference.java:130)

at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)

at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:460)

at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:673)

at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:386)

at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:196)

Caused by: java.lang.reflect.InvocationTargetException

at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)

at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)

at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)

at java.lang.reflect.Constructor.newInstance(Unknown Source)

at javax.sip.SipFactory.createStack(SipFactory.java:314)

... 21 more

Caused by: javax.sip.PeerUnavailableException: Unable to initialize the SipCache

at org.mobicents.ha.javax.sip.ClusteredSipStackImpl.<init>(ClusteredSipStackImpl.java:104)

at org.mobicents.ha.javax.sip.SipStackImpl.<init>(SipStackImpl.java:47)

... 26 more

Caused by: org.mobicents.ha.javax.sip.cache.SipCacheException: Couldn't init Mobicents Cache

at org.mobicents.ha.javax.sip.cache.ManagedMobicentsSipCache.init(ManagedMobicentsSipCache.java:93)

at org.mobicents.ha.javax.sip.ClusteredSipStackImpl.<init>(ClusteredSipStackImpl.java:102)

... 27 more

Caused by: org.jboss.cache.CacheException: java.lang.reflect.InvocationTargetException

at org.jboss.cache.util.reflect.ReflectionUtil.invokeAccessibly(ReflectionUtil.java:148)

at org.jboss.cache.factories.ComponentRegistry$PrioritizedMethod.invoke(ComponentRegistry.java:1012)

at org.jboss.cache.factories.ComponentRegistry.internalStart(ComponentRegistry.java:778)

at org.jboss.cache.factories.ComponentRegistry.start(ComponentRegistry.java:632)

at org.jboss.cache.invocation.CacheInvocationDelegate.start(CacheInvocationDelegate.java:345)

at org.mobicents.cache.MobicentsCache.startCache(MobicentsCache.java:66)

at org.mobicents.cache.MobicentsCache.<init>(MobicentsCache.java:38)

at org.mobicents.ha.javax.sip.cache.ManagedMobicentsSipCache.init(ManagedMobicentsSipCache.java:88)

... 28 more

Caused by: java.lang.reflect.InvocationTargetException

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

at java.lang.reflect.Method.invoke(Unknown Source)

at org.jboss.cache.util.reflect.ReflectionUtil.invokeAccessibly(ReflectionUtil.java:144)

... 35 more

Caused by: org.jboss.cache.CacheException: Unable to connect to JGroups channel

at org.jboss.cache.RPCManagerImpl.start(RPCManagerImpl.java:352)

... 40 more

Caused by: org.jgroups.ChannelException: failed to start protocol stack

at org.jgroups.JChannel.startStack(JChannel.java:1625)

at org.jgroups.JChannel.connect(JChannel.java:402)

at org.jboss.cache.RPCManagerImpl.start(RPCManagerImpl.java:347)

... 40 more

Caused by: java.lang.Exception: problem creating sockets (bind_addr=/138.132.34.18, mcast_addr=ffff:0:0:0:0:0:e805:505:45588)

at org.jgroups.protocols.UDP.start(UDP.java:264)

at org.jgroups.stack.ProtocolStack.startStack(ProtocolStack.java:741)

at org.jgroups.JChannel.startStack(JChannel.java:1622)

... 42 more

Caused by: java.net.SocketException: Protocol family unavailable

at java.net.PlainDatagramSocketImpl.join(Native Method)

at java.net.PlainDatagramSocketImpl.join(Unknown Source)

at java.net.MulticastSocket.joinGroup(Unknown Source)

at org.jgroups.protocols.UDP.createSockets(UDP.java:427)

at org.jgroups.protocols.UDP.start(UDP.java:260)

... 44 more

The Peer SIP Stack: org.mobicents.ha.javax.sip.SipStackImpl could not be instantiated. Ensure the Path Name has been set.

java.lang.reflect.InvocationTargetException

at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)

at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)

at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)

at java.lang.reflect.Constructor.newInstance(Unknown Source)

at javax.sip.SipFactory.createStack(SipFactory.java:314)

at javax.sip.SipFactory.createSipStack(SipFactory.java:152)

at org.mobicents.ha.javax.sip.SimpleDialogRecoveryTest$Shootme.init(SimpleDialogRecoveryTest.java:544)

at org.mobicents.ha.javax.sip.SimpleDialogRecoveryTest.testDialogFailover(SimpleDialogRecoveryTest.java:1069)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

at java.lang.reflect.Method.invoke(Unknown Source)

at junit.framework.TestCase.runTest(TestCase.java:154)

at junit.framework.TestCase.runBare(TestCase.java:127)

at junit.framework.TestResult$1.protect(TestResult.java:106)

at junit.framework.TestResult.runProtected(TestResult.java:124)

at junit.framework.TestResult.run(TestResult.java:109)

at junit.framework.TestCase.run(TestCase.java:118)

at junit.framework.TestSuite.runTest(TestSuite.java:208)

at junit.framework.TestSuite.run(TestSuite.java:203)

at org.eclipse.jdt.internal.junit.runner.junit3.JUnit3TestReference.run(JUnit3TestReference.java:130)

at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)

at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:460)

at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:673)

at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:386)

at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:196)

Caused by: javax.sip.PeerUnavailableException: Unable to initialize the SipCache

at org.mobicents.ha.javax.sip.ClusteredSipStackImpl.<init>(ClusteredSipStackImpl.java:104)

at org.mobicents.ha.javax.sip.SipStackImpl.<init>(SipStackImpl.java:47)

... 26 more

Caused by: org.mobicents.ha.javax.sip.cache.SipCacheException: Couldn't init Mobicents Cache

at org.mobicents.ha.javax.sip.cache.ManagedMobicentsSipCache.init(ManagedMobicentsSipCache.java:93)

at org.mobicents.ha.javax.sip.ClusteredSipStackImpl.<init>(ClusteredSipStackImpl.java:102)

... 27 more

Caused by: org.jboss.cache.CacheException: java.lang.reflect.InvocationTargetException

at org.jboss.cache.util.reflect.ReflectionUtil.invokeAccessibly(ReflectionUtil.java:148)

at org.jboss.cache.factories.ComponentRegistry$PrioritizedMethod.invoke(ComponentRegistry.java:1012)

at org.jboss.cache.factories.ComponentRegistry.internalStart(ComponentRegistry.java:778)

at org.jboss.cache.factories.ComponentRegistry.start(ComponentRegistry.java:632)

at org.jboss.cache.invocation.CacheInvocationDelegate.start(CacheInvocationDelegate.java:345)

at org.mobicents.cache.MobicentsCache.startCache(MobicentsCache.java:66)

at org.mobicents.cache.MobicentsCache.<init>(MobicentsCache.java:38)

at org.mobicents.ha.javax.sip.cache.ManagedMobicentsSipCache.init(ManagedMobicentsSipCache.java:88)

... 28 more

Caused by: java.lang.reflect.InvocationTargetException

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

at java.lang.reflect.Method.invoke(Unknown Source)

at org.jboss.cache.util.reflect.ReflectionUtil.invokeAccessibly(ReflectionUtil.java:144)

... 35 more

Caused by: org.jboss.cache.CacheException: Unable to connect to JGroups channel

at org.jboss.cache.RPCManagerImpl.start(RPCManagerImpl.java:352)

... 40 more

Caused by: org.jgroups.ChannelException: failed to start protocol stack

at org.jgroups.JChannel.startStack(JChannel.java:1625)

at org.jgroups.JChannel.connect(JChannel.java:402)

at org.jboss.cache.RPCManagerImpl.start(RPCManagerImpl.java:347)

... 40 more

Caused by: java.lang.Exception: problem creating sockets (bind_addr=/138.132.34.18, mcast_addr=ffff:0:0:0:0:0:e805:505:45588)

at org.jgroups.protocols.UDP.start(UDP.java:264)

at org.jgroups.stack.ProtocolStack.startStack(ProtocolStack.java:741)

at org.jgroups.JChannel.startStack(JChannel.java:1622)

... 42 more

Caused by: java.net.SocketException: Protocol family unavailable

at java.net.PlainDatagramSocketImpl.join(Native Method)

at java.net.PlainDatagramSocketImpl.join(Unknown Source)

at java.net.MulticastSocket.joinGroup(Unknown Source)

at org.jgroups.protocols.UDP.createSockets(UDP.java:427)

at org.jgroups.protocols.UDP.start(UDP.java:260)

... 44 more

Thanks a lot.

Mic

2010/3/18 Jean Deruelle <jean.d...@gmail.com>

[Vladimir Ralev]

Looks like https://jira.jboss.org/jira/browse/JGRP-951 . You can
either turn off ipv6 as suggested or update jgroups and/or jboss
cache. Note that jsip a comes with support for jboss cache 2 and 3, i
am not sure which version you have bundled, 3 is preferred.

> To unsubscribe from this group, send email to
> mobicents-public+unsubscribegooglegroups.com or reply to this email with the
> words "REMOVE ME" as the subject.
>

[Michele Mazza]

Hello,

Even setting -Djava.net.preferIPv4Stack=true, I get the same exception.

I verified the correct property setting using:

    public void testDialogFailover() throws Exception {

     System.out.println(System.getProperty("java.net.preferIPv4Stack"));

        balancer = new Balancer(IP_ADDRESS, BALANCER_PORT);

        ...

Please note that I execute the test on my PC Windows using Eclipse and with Mobicents stoppod.

My application, instead, is running on RedHat.

Regarding the original problem of my application, now the Dialog seems an instance of the good class:

    dialog.toString() = gov.nist.javax.sip.stack.ConfirmedReplicationSipDialog@15e58947

this is created using:

SIPClientTransaction clientTransaction = (SIPClientTransaction) SipHelper.getInstance().getSipProvider().getNewClientTransaction(request);

if (dialog == null) {

dialog = ((ClusteredSipStackImpl)SipHelper.getInstance().getSipStack()).createDialog((SIPTransaction)clientTransaction);

}

The problem is that getDialogId() and getState() return null!

So, when I try to refresh the SUBSCRIBE, I get:

2010-03-23 15:22:48,540 ERROR [IPSMediator] ERROR: Dialog not yet established -- no response!

javax.sip.SipException: Dialog not yet established -- no response!

        at gov.nist.javax.sip.stack.SIPDialog.createRequest(SIPDialog.java:1860)

        at it.italtel.ipif.providers.ips.helper.IPSMediator.doSubscribe(IPSMediator.java:308)

        at it.italtel.ipif.providers.ips.helper.sip.SipCommandWatcherThread.sendMessages(SipCommandWatcherThread.java:178)

        at it.italtel.ipif.providers.ips.helper.sip.SipCommandWatcherThread.run(SipCommandWatcherThread.java:98)

        at java.lang.Thread.run(Thread.java:619)

Thanks for your help.

Mic

2010/3/23 Vladimir Ralev <vladimi...@gmail.com>

[Jean Deruelle]

Can you retry that on Red Hat and see if you get the same exception ?

Can you repost the full exception log with -Djava.net.preferIPv4Stack=true set ?

Can you post the full DEBUG logs for your SUBSCRIBE scenario ?

[Vladimir Ralev]

You have a lot of options with jgroups to fix transport problems. May
be you should change your mcast_addr in the configuration
Right now it is using mcast_addr=ffff:0:0:0:0:0:e805:505:45588 from somewhere
Change this:
<UDP
mcast_addr="${jgroups.udp.mcast_addr:232.15.15.15}"
mcast_port="${jgroups.udp.mcast_port:45000}"
tos="8"

About the replication issue that returns null, did you double check
that the HA is really in use like Jean says?

[Michele Mazza]

On my PC, after setting "-Djava.net.preferIPv4Stack=true" and afeter changing udp.xml as suggested by Vladimir, I get the following log.

I seems that it gets the port (45000) but NOT the IPV4 address!

Now I will gather and send you the logs of my application on RedHat.

java.net.preferIPv4Stack=true

17:04:05,864 DEBUG [StatelessForwarder] BUILD TIMESTAMP = null

17:04:05,879 DEBUG [StatelessForwarder] Config Propeties = {gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.RETRANSMISSION_FILTER=true, javax.sip.AUTOMATIC_DIALOG_SUPPORT=off, javax.sip.STACK_NAME=StatelessForwarder, gov.nist.javax.sip.SERVER_LOG=./logs/statelessforwarderlog.xml, gov.nist.javax.sip.DEBUG_LOG=./logs/statelessforwarderdebug.txt}

17:04:05,879 DEBUG [StatelessForwarder] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:256) [Here are the stack configuration properties 

{gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.RETRANSMISSION_FILTER=true, javax.sip.AUTOMATIC_DIALOG_SUPPORT=off, javax.sip.STACK_NAME=StatelessForwarder, gov.nist.javax.sip.SERVER_LOG=./logs/statelessforwarderlog.xml, gov.nist.javax.sip.DEBUG_LOG=./logs/statelessforwarderdebug.txt}

]

17:04:05,879 DEBUG [StatelessForwarder] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:258) [ ]]>]

17:04:05,879 DEBUG [StatelessForwarder] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:259) [</debug>]

17:04:05,879 DEBUG [StatelessForwarder] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:260) [<description

 logDescription="StatelessForwarder"

 name="null" />

]

17:04:05,879 DEBUG [StatelessForwarder] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:262) [<debug>]

17:04:05,879 DEBUG [StatelessForwarder] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:263) [<![CDATA[ ]

17:04:05,910 DEBUG [StatelessForwarder] gov.nist.javax.sip.SipStackImpl.<init>(SipStackImpl.java:1002) [created Sip stack. Properties = {gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.RETRANSMISSION_FILTER=true, javax.sip.AUTOMATIC_DIALOG_SUPPORT=off, javax.sip.STACK_NAME=StatelessForwarder, gov.nist.javax.sip.SERVER_LOG=./logs/statelessforwarderlog.xml, gov.nist.javax.sip.DEBUG_LOG=./logs/statelessforwarderdebug.txt}]

17:04:05,989 DEBUG [StatelessForwarder] gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:1065) [createListeningPoint : address = 138.132.34.18 port = 5050 transport = UDP]

17:04:06,614 DEBUG [StatelessForwarder] gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:1101) [Created Message Processor: 138.132.34.18 port = 5050 transport = UDP]

17:04:06,614 DEBUG [StatelessForwarder] gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:199) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@3ecfff listeningPoint = gov.nist.javax.sip.ListeningPointImpl@1c99159]

17:04:06,614 DEBUG [StatelessForwarder] gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:1133) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@1c99159]

17:04:06,629 DEBUG [StatelessForwarder] gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:233) [add SipListener org.mobicents.ha.javax.sip.SimpleDialogRecoveryTest$Balancer@9173ef]

17:04:06,676 DEBUG [shootme] BUILD TIMESTAMP = null

17:04:06,676 DEBUG [shootme] Config Propeties = {org.mobicents.ha.javax.sip.CACHE_CLASS_NAME=org.mobicents.ha.javax.sip.cache.ManagedMobicentsSipCache, gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.STACK_NAME=shootme, gov.nist.javax.sip.SERVER_LOG=logs/shootmelog.xml, org.mobicents.ha.javax.sip.cache.MobicentsSipCache.standalone=true, gov.nist.javax.sip.DEBUG_LOG=logs/shootmedebug.txt}

17:04:06,676 DEBUG [shootme] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:256) [Here are the stack configuration properties 

{org.mobicents.ha.javax.sip.CACHE_CLASS_NAME=org.mobicents.ha.javax.sip.cache.ManagedMobicentsSipCache, gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.STACK_NAME=shootme, gov.nist.javax.sip.SERVER_LOG=logs/shootmelog.xml, org.mobicents.ha.javax.sip.cache.MobicentsSipCache.standalone=true, gov.nist.javax.sip.DEBUG_LOG=logs/shootmedebug.txt}

]

17:04:06,676 DEBUG [shootme] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:258) [ ]]>]

17:04:06,676 DEBUG [shootme] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:259) [</debug>]

17:04:06,676 DEBUG [shootme] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:260) [<description

 logDescription="shootme"

 name="null" />

]

17:04:06,676 DEBUG [shootme] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:262) [<debug>]

17:04:06,676 DEBUG [shootme] gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:263) [<![CDATA[ ]

17:04:06,676 DEBUG [shootme] gov.nist.javax.sip.SipStackImpl.<init>(SipStackImpl.java:1002) [created Sip stack. Properties = {org.mobicents.ha.javax.sip.CACHE_CLASS_NAME=org.mobicents.ha.javax.sip.cache.ManagedMobicentsSipCache, gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.STACK_NAME=shootme, gov.nist.javax.sip.SERVER_LOG=logs/shootmelog.xml, org.mobicents.ha.javax.sip.cache.MobicentsSipCache.standalone=true, gov.nist.javax.sip.DEBUG_LOG=logs/shootmedebug.txt}]

17:04:06,692 INFO  [shootme] Mobicents JAIN SIP JBoss Cache Configuration path is : META-INF/cache-configuration.xml

javax.sip.PeerUnavailableException: The Peer SIP Stack: org.mobicents.ha.javax.sip.SipStackImpl could not be instantiated. Ensure the Path Name has been set.

at javax.sip.SipFactory.createStack(SipFactory.java:324)

at javax.sip.SipFactory.createSipStack(SipFactory.java:152)

at org.mobicents.ha.javax.sip.SimpleDialogRecoveryTest$Shootme.init(SimpleDialogRecoveryTest.java:544)

at org.mobicents.ha.javax.sip.SimpleDialogRecoveryTest.testDialogFailover(SimpleDialogRecoveryTest.java:1071)

Caused by: java.lang.Exception: problem creating sockets (bind_addr=/138.132.34.18, mcast_addr=ffff:0:0:0:0:0:e805:505:45000)

at org.jgroups.protocols.UDP.start(UDP.java:264)

at org.jgroups.stack.ProtocolStack.startStack(ProtocolStack.java:741)

at org.jgroups.JChannel.startStack(JChannel.java:1622)

... 42 more

Caused by: java.net.SocketException: Protocol family unavailable

at java.net.PlainDatagramSocketImpl.join(Native Method)

at java.net.PlainDatagramSocketImpl.join(Unknown Source)

at java.net.MulticastSocket.joinGroup(Unknown Source)

at org.jgroups.protocols.UDP.createSockets(UDP.java:427)

at org.jgroups.protocols.UDP.start(UDP.java:260)

... 44 more

The Peer SIP Stack: org.mobicents.ha.javax.sip.SipStackImpl could not be instantiated. Ensure the Path Name has been set.

java.lang.reflect.InvocationTargetException

at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)

at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)

at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)

at java.lang.reflect.Constructor.newInstance(Unknown Source)

at javax.sip.SipFactory.createStack(SipFactory.java:314)

at javax.sip.SipFactory.createSipStack(SipFactory.java:152)

at org.mobicents.ha.javax.sip.SimpleDialogRecoveryTest$Shootme.init(SimpleDialogRecoveryTest.java:544)

at org.mobicents.ha.javax.sip.SimpleDialogRecoveryTest.testDialogFailover(SimpleDialogRecoveryTest.java:1071)

Caused by: java.lang.Exception: problem creating sockets (bind_addr=/138.132.34.18, mcast_addr=ffff:0:0:0:0:0:e805:505:45000)

at org.jgroups.protocols.UDP.start(UDP.java:264)

at org.jgroups.stack.ProtocolStack.startStack(ProtocolStack.java:741)

at org.jgroups.JChannel.startStack(JChannel.java:1622)

... 42 more

Caused by: java.net.SocketException: Protocol family unavailable

at java.net.PlainDatagramSocketImpl.join(Native Method)

at java.net.PlainDatagramSocketImpl.join(Unknown Source)

at java.net.MulticastSocket.joinGroup(Unknown Source)

at org.jgroups.protocols.UDP.createSockets(UDP.java:427)

at org.jgroups.protocols.UDP.start(UDP.java:260)

... 44 more

2010/3/23 Jean Deruelle <jean.d...@gmail.com>

[Jean Deruelle]

which JVM do you use ?

[Vladimir Ralev]

Can you paste the config you use
I mean to replace the default like this
<UDP
mcast_addr="232.15.15.15" (or some other multicast address,
this should force ipv4)
mcast_port="43543"
tos="8"

[Michele Mazza]

java 1.6

2010/3/23 Jean Deruelle <jean.d...@gmail.com>

[Michele Mazza]

Please note I modify the udp.xml in mss-1.2-jboss-5.1.0.GA\sip-balancer\sip-balancer-jar-with-dependencies.jar

After testing with:

<config>

    <UDP

         mcast_addr="232.15.15.15"

         mcast_port="43543"

         tos="8"

I get:

Caused by: java.lang.Exception: problem creating sockets (bind_addr=/138.132.34.18, mcast_addr=ffff:0:0:0:0:0:e805:505:43543)

at org.jgroups.protocols.UDP.start(UDP.java:264)

at org.jgroups.stack.ProtocolStack.startStack(ProtocolStack.java:741)

at org.jgroups.JChannel.startStack(JChannel.java:1622)

... 42 more

2010/3/23 Vladimir Ralev <vladimi...@gmail.com>

[Michele Mazza]

Please find attached the full log of my application.

I inserted some comments you can find using the token "MZZ - " (to speed the reading of the log).

I attache also three main classes:

1) SipHelper

// SIP Stack initialization

private void initSipStack(SipResultListener sipResultListener, SipNotifyListener sipNotifyListener) throws Exception

whre jain-sip.properties is:

gov.nist.javax.sip.TRACE_LEVEL=32

gov.nist.javax.sip.LOG_MESSAGE_CONTENT=true

gov.nist.javax.sip.LOG_LIFETIME=3600

gov.nist.javax.sip.ACCESS_LOG_VIA_RMI=false

gov.nist.javax.sip.RMI_PORT=8177

gov.nist.javax.sip.CACHE_SERVER_CONNECTIONS=true

gov.nist.javax.sip.CACHE_CLIENT_CONNECTIONS=true

gov.nist.javax.sip.MAX_CONNECTIONS=5048576

javax.sip.AUTOMATIC_DIALOG_SUPPORT=off

gov.nist.javax.sip.DELIVER_UNSOLICITED_NOTIFY=true

gov.nist.javax.sip.REENTRANT_LISTENER=true

gov.nist.javax.sip.RECEIVE_UDP_BUFFER_SIZE=65536

gov.nist.javax.sip.SEND_UDP_BUFFER_SIZE=65536

org.mobicents.ha.javax.sip.cache.MobicentsSipCache.cacheName=standard-session-cache

2) IPSMediator

// Sending (and then refreshing) the SUBSCRIBE using PresenceHelper.sendSubscribe

public ControlResult doSubscribe(String subscribedName) {

3) PresenceHelper containing the sendSubscribe

THANKS A LOT

Mic

2010/3/23 Jean Deruelle <jean.d...@gmail.com>

[Michele Mazza]

I am new regarding jain-sip-ha and Mobicents.

How can I double check that the HA is really in use?

Please note that I just installed Mobicents without configuring the LoadBalancer...

Thanks, Mic

[Vladimir Ralev]

Maybe then you have this problem https://jira.jboss.org/jira/browse/JGRP-792
WHich jgroups do you use? Also, try to upgrade your jgroups. If you
can remove ipv6 from your system, that is another solution (easy with
both linux and widows)

[Jean Deruelle]

You're not creating the dialog as you should.

Please use Dialog dialog = sipProvider.getNewDialog(request.getTransaction()); by example like you would do with a non HA application

Please note that you should never cast anything from jain sip to org.mobicents.ha.jain.sip

Clustering and Failover should be transparent (API wise) only by having the jar on the classpath and set the correct properties (like you did), this should just work without you having to access jain sip ha code at all.

Jean

[Michele Mazza]

I have removed all casts to org.mobicents.ha.jain.sip and created a dialog as you suggested.

The only question is that my request (of type javax.sip.message.Request) doesn't have a getTransaction() method.

So i did:

ClientTransaction clientTransaction = sipProvider.getNewClientTransaction(request);

dialog = sipProvider.getNewDialog(clientTransaction);

The result is much better: in the Node 2 I am able to retrieve the dialog created in the Node 1 and all fileds seems ok.

But now the error is a NullPointerException when I try to create a request from the dialog:

2010-03-24 10:29:41,982 DEBUG [IPS_PROVIDER] (Thread-24) Refresh SUBSCRIBE for nome.cogn...@ipifserver.com

2010-03-24 10:29:42,038 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** DIALOG FOUND in sipDialogManager!!!

2010-03-24 10:29:42,040 ERROR [IPS_PROVIDER] (Thread-24) MZZ etag ZbyCIP8Y

2010-03-24 10:29:42,040 ERROR [IPS_PROVIDER] (Thread-24) MZZ toString gov.nist.javax.sip.stack.ConfirmedReplicationSipDialog@35c8d5b0

2010-03-24 10:29:42,041 ERROR [IPS_PROVIDER] (Thread-24) MZZ getState Confirmed Dialog

2010-03-24 10:29:42,041 ERROR [IPS_PROVIDER] (Thread-24) MZZ getDialogId cf1bc795b807afe6d24c21a435b0716a@sip:nome.cogn...@ipifserver.com:92f4dae9:efb19755

2010-03-24 10:29:42,041 ERROR [IPS_PROVIDER] (Thread-24) MZZ getLocalSeqNumber 1

2010-03-24 10:29:42,042 ERROR [IPS_PROVIDER] (Thread-24) ERROR: null

java.lang.NullPointerException

        at gov.nist.javax.sip.stack.SIPDialog.createRequest(SIPDialog.java:1916)

        at gov.nist.javax.sip.stack.SIPDialog.createRequest(SIPDialog.java:1858)

        at it.italtel.ipif.providers.ips.helper.IPSMediator.doSubscribe(IPSMediator.java:307)

        at it.italtel.ipif.providers.ips.helper.sip.SipCommandWatcherThread.sendMessages(SipCommandWatcherThread.java:178)

        at it.italtel.ipif.providers.ips.helper.sip.SipCommandWatcherThread.run(SipCommandWatcherThread.java:98)

        at java.lang.Thread.run(Unknown Source)

Thanks a lot for your great support.

Mic

[Jean Deruelle]

can you make sure you use the latest version of the stack 

http://snapshots.jboss.org/maven2/javax/sip/jain-sip-ri/1.2.X-SNAPSHOT/jain-sip-ri-1.2.X-20100324.024355-121.jar ?

and repost the stacktrace ?

Thanks in advance

Best regards

Jean

[Michele Mazza]

When using jain-sip-ri-1.2.X-20100324.024355-121.jar, the stack trace is:

java.lang.NullPointerException

        at gov.nist.javax.sip.stack.SIPDialog.createRequest(SIPDialog.java:1961)

        at gov.nist.javax.sip.stack.SIPDialog.createRequest(SIPDialog.java:1903)

        at it.italtel.ipif.providers.ips.helper.IPSMediator.doSubscribe(IPSMediator.java:321)

        at it.italtel.ipif.providers.ips.helper.sip.SipCommandWatcherThread.sendMessages(SipCommandWatcherThread.j

        at it.italtel.ipif.providers.ips.helper.sip.SipCommandWatcherThread.run(SipCommandWatcherThread.java:98)

        at java.lang.Thread.run(Unknown Source)

2010/3/24 Jean Deruelle <jean.d...@gmail.com>

[Jean Deruelle]

Can you post the full log once again an print the dialog's last response, sipProvider, and the sipProvider listening points (ip address, port, transport) after failover ?

Thanks

Jean

[Michele Mazza]

Hello,

serverPrimaryNode.log is the log of Node0 which is initiating the SUBSCRIBE.

Here also the refresh is OK.

server.log is the log of the Node1 which wants to refresh the SUBSCRIBE starting from the replicated Dialog.

You can search the token "Refresh SUBSCRIBE for" to go to refresh log.

THANKS A LOT.

Mic

2010/3/24 Jean Deruelle <jean.d...@gmail.com>

[Michele Mazza]

I am adding also the logs for Listening Points and I will send in a few minutes.

Please note that I have 2 listening points and I had to add:

properties.setProperty("javax.sip.OUTBOUND_PROXY", getServerAddress() + ":" + getServerPort() + "/"+ getTransportProtocol());

during stack initialization to avoid a SipStack startup error.

Mic

2010/3/24 Jean Deruelle <jean.d...@gmail.com>

[Jean Deruelle]

There is something odd. I still see the dialog not being found like if the  replication didn't occur even though it seems to have occured...

2010-03-24 15:19:34,011 DEBUG [italtel.ipif] (Thread-24) org.mobicents.ha.javax.sip.ClusteredSipStackImpl.getDialog(ClusteredSipStackImpl.java:224) [checking if the dialog 700426b297664132af3200e447be995c@sip:nome.cogn...@ipifserver.com:30f12c94:ddc5095b is present in the local cache]

2010-03-24 15:19:34,011 DEBUG [italtel.ipif] (Thread-24) gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:836) [getDialog(700426b297664132af3200e447be995c@sip:nome.cogn...@ipifserver.com:30f12c94:ddc5095b) : returning null]

2010-03-24 15:19:34,011 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** DIALOG NOT FOUND in SipStack !!! 

2010-03-24 15:19:34,013 ERROR [IPS_PROVIDER] (Thread-24) MZZ etag MdMU2xFS

2010-03-24 15:19:34,013 ERROR [IPS_PROVIDER] (Thread-24) MZZ toString gov.nist.javax.sip.stack.ConfirmedReplicationSipDialog@3a07d450

2010-03-24 15:19:34,013 ERROR [IPS_PROVIDER] (Thread-24) MZZ getState null

2010-03-24 15:19:34,013 ERROR [IPS_PROVIDER] (Thread-24) MZZ getDialogId null

2010-03-24 15:19:34,014 ERROR [IPS_PROVIDER] (Thread-24) MZZ getLocalSeqNumber 1

2010-03-24 15:19:34,015 ERROR [IPS_PROVIDER] (Thread-24) ---> ERROR IN createRequest 

javax.sip.SipException: Dialog not yet established -- no response!

at gov.nist.javax.sip.stack.SIPDialog.createRequest(SIPDialog.java:1905)

at it.italtel.ipif.providers.ips.helper.IPSMediator.doSubscribe(IPSMediator.java:321)

at it.italtel.ipif.providers.ips.helper.sip.SipCommandWatcherThread.sendMessages(SipCommandWatcherThread.java:178)

at it.italtel.ipif.providers.ips.helper.sip.SipCommandWatcherThread.run(SipCommandWatcherThread.java:98)

at java.lang.Thread.run(Unknown Source)

and 

2010-03-24 15:20:04,035 DEBUG [italtel.ipif] (Thread-24) org.mobicents.ha.javax.sip.ClusteredSipStackImpl.getDialog(ClusteredSipStackImpl.java:224) [checking if the dialog 3223fb5ed145081de06a8dd8a1c10f27@sip:nome.cogn...@ipifserver.com:de6c0ced:85fa21a9 is present in the local cache]

2010-03-24 15:20:04,035 DEBUG [italtel.ipif] (Thread-24) gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:836) [getDialog(3223fb5ed145081de06a8dd8a1c10f27@sip:nome.cogn...@ipifserver.com:de6c0ced:85fa21a9) : returning null]

2010-03-24 15:20:04,035 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** DIALOG NOT FOUND in SipStack !!! 

2010-03-24 15:20:04,036 ERROR [IPS_PROVIDER] (Thread-24) MZZ etag oIEr4nvd

2010-03-24 15:20:04,036 ERROR [IPS_PROVIDER] (Thread-24) MZZ toString gov.nist.javax.sip.stack.ConfirmedReplicationSipDialog@470db599

2010-03-24 15:20:04,037 ERROR [IPS_PROVIDER] (Thread-24) MZZ getState Confirmed Dialog

2010-03-24 15:20:04,037 ERROR [IPS_PROVIDER] (Thread-24) MZZ getDialogId 63503701e1cd39bf52e0f7456674767f@sip:nome.cogn...@ipifserver.com:d3d20b99:93c0b3b0

2010-03-24 15:20:04,037 ERROR [IPS_PROVIDER] (Thread-24) MZZ getLocalSeqNumber 1

2010-03-24 15:20:04,060 ERROR [IPS_PROVIDER] (Thread-24) MZZ getLastResponse SIP/2.0 202 Accepted

[Michele Mazza]

Here is the full log for failover.

Search the token "Refresh SUBSCRIBE for".

The new log is:

2010-03-24 16:54:54,266 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** SipProvider gov.nist.javax.sip.SipProviderImpl@5f8948aa

2010-03-24 16:54:54,267 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** SipProvider LP 0 -> 138.132.115.113

2010-03-24 16:54:54,267 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** SipProvider LP 0 -> 5061

2010-03-24 16:54:54,267 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** SipProvider LP 0 -> 138.132.115.113:5061

2010-03-24 16:54:54,268 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** SipProvider LP 0 -> udp

2010-03-24 16:54:54,268 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** SipProvider LP 1 -> 138.132.115.113

2010-03-24 16:54:54,268 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** SipProvider LP 1 -> 5061

2010-03-24 16:54:54,268 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** SipProvider LP 1 -> 138.132.115.113:5061

2010-03-24 16:54:54,269 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** SipProvider LP 1 -> tcp

Please note that 138.132.115.113 is Node 0 where all is OK.

The problem is for Node 1 whose address is 138.132.115.118 !

Mic

2010/3/24 Michele Mazza <mazz...@gmail.com>

[Michele Mazza]

Soory, the previous log is Node 0.

The log of Node 1 (the one with problem) is this one.

[Michele Mazza]

After the SUBSCRIBE I put the dialog in the POJO Cache.

When I need to refresh, I get the dialog using the user name:

Dialog dialog = (SIPDialog) sipDialogManager.getDialogFromUser(subscribedName);

where getDialogFromUser is going to POJO Cache.

Just for test, I put in the POJO cache also the dialogId (when not null) and (just for test) I try to get the Dialog this way:

  if (dialogId != null) {

    Dialog myDialog = ((ClusteredSipStackImpl) SipHelper.getInstance().getSipStack()).getDialog(dialogId);

    if (myDialog != null)

      log.error("*** MZZ *** DIALOG FOUND in SipStack !!! ");

    else

      log.error("*** MZZ *** DIALOG NOT FOUND in SipStack !!! ");

  }

this myDialog (that I don't use) is retrieved just in the Node 0...

2010/3/24 Jean Deruelle <jean.d...@gmail.com>

[Jean Deruelle]

Well the jain sip ha should take care itself of replicating and doing the failover (reinit the dialog correctly from the cache)

You don't need to replicate the dialog yourself or you will wind up doing the same stuff as jain sip ha.

This should work :

Dialog myDialog = ((SipStackImpl) SipHelper.getInstance().getSipStack()).getDialog(dialogId);

By the way you can see the replication is occuring

2010-03-24 16:52:50,430 INFO  [org.jboss.web.tomcat.service.session.distributedcache.impl.jbc.SipCacheListener] (Incoming-2,138.132.115.118:33314) following node created /jain-sip-ha/Dialogs/a77dd95912eb2ad3fc7f703f444afec6@sip:nome.cogn...@ipifserver.com:8e4c32ea:2cf26cad

I think your problem is that you're mixing it badly with using Mobicents at the same time and it gets replicated in a different cache than the one of your application hence the above method for retrieving it returns null where it should return the dialog correctly failed over.

Jean

[Michele Mazza]

Sorry, I don't have fully understood.

My scenario:

1) Node0 is doing SUBSCRIBE for us...@ipifserver.com

   SIPClientTransaction clientTransaction =sipProvider.getNewClientTransaction(request);

   dialog = SipHelper.getInstance().getSipProvider().getNewDialog(clientTransaction);

   This is creating a dialog

2) Node1 wants to refresh the SUBSCRIBE for us...@ipifserver.com

   How can I get the dialog created in point 1?

My solution was:

A) Node0 puts us...@ipifserver.com/dialog in the POJO Cache

B) Node1 gets dialog from POJO Cache using se...@ipifserver.com as key

2010/3/24 Jean Deruelle <jean.d...@gmail.com>

[Jean Deruelle]

See inline

On Wed, Mar 24, 2010 at 5:47 PM, Michele Mazza <mazz...@gmail.com> wrote:

Sorry, I don't have fully understood.

My scenario:

1) Node0 is doing SUBSCRIBE for us...@ipifserver.com

   SIPClientTransaction clientTransaction =sipProvider.getNewClientTransaction(request);

   dialog = SipHelper.getInstance().getSipProvider().getNewDialog(clientTransaction);

   This is creating a dialog

Correct. when the dialog state will reach CONFIRMED it will get replicated automatically to the cache by jain sip ha layer

 

2) Node1 wants to refresh the SUBSCRIBE for us...@ipifserver.com

   How can I get the dialog created in point 1?

With jain sip ha you just need

Dialog myDialog = ((SipStackImpl) SipHelper.getInstance().getSipStack()).getDialog(dialogId);

that's the beauty of it, it will check if dialog with dilaogId is present locally, if not it will check in the cache, if it is present there it will get it from the cache and do some intiialization so that the dialog is usable (we try to minimize the amount of data replicated that goes over the wire so we don't replicate the full dialog but recreate it) and return it to the application

My solution was:

A) Node0 puts us...@ipifserver.com/dialog in the POJO Cache

B) Node1 gets dialog from POJO Cache using se...@ipifserver.com as key

No need jain sip ha takes care of this automatically.

[Michele Mazza]

Hello Jean,

I modified my application according to your explanation.

Now I save in the POJO cache just the dialogId related to a user.

On the replicated Node, I get just the dialogId from my cache and then I get the dialog this way:

  dialog = ((ClusteredSipStackImpl) SipHelper.getInstance().getSipStack()).getDialog(dialogId);

Form the JBoss console (under jboss.cache) I cas see:

------------------------------- Node 0 - 138.132.115.113 -------------------------------

/  {}
  /MSS_FT_SAS_Timers23a3d117  {}
  /MSS_FT_Timers6f97354c  {}
  /MSS_FT_Timers23a3d117  {}
  /MSS_FT_SAS_Timers6f97354c  {}
  /jain-sip-ha  {}
    /Dialogs  {}
      /2ebf20732b306b954a80b934d5ddf562@sip:nome.cogn...@ipifserver.com:2d6595e0:6297377e  {ir=false, stf=false, is=false, lr=SIP/2.0 202 Accepted
To: ;tag=6297377e
Expires: 3600
Via: SIP/2.0/UDP 138.132.115.113:5061;branch=z9hG4bK8f5e676ea02013ead2e11a9aa1ec6acd353834
CSeq: 1 SUBSCRIBE
Call-ID: 2ebf20732b306b954a80b934d5ddf562@sip:nome.cogn...@ipifserver.com
From: ;tag=2d6595e0
Contact: 
Content-Length: 0

, rl=[Ljava.lang.String;@30cd076c, ftid=z9hG4bK8f5e676ea02013ead2e11a9aa1ec6acd353834, ftm=SUBSCRIBE, tob=true, b2b=false, eh=Event: presence
, fts=false, rt=, ch=Contact: 
}

------------------------------- Node 1 - 138.132.115.118 -------------------------------

/  {}
  /MSS_FT_SAS_Timers23a3d117  {}
  /MSS_FT_Timers6f97354c  {}
  /MSS_FT_Timers23a3d117  {}
  /MSS_FT_SAS_Timers6f97354c  {}
  /jain-sip-ha  {}
    /Dialogs  {}
      /2ebf20732b306b954a80b934d5ddf562@sip:nome.cogn...@ipifserver.com:2d6595e0:6297377e  {ir=false, stf=false, is=false, lr=SIP/2.0 202 Accepted
To: ;tag=6297377e
Expires: 3600
Via: SIP/2.0/UDP 138.132.115.113:5061;branch=z9hG4bK8f5e676ea02013ead2e11a9aa1ec6acd353834
CSeq: 1 SUBSCRIBE
Call-ID: 2ebf20732b306b954a80b934d5ddf562@sip:nome.cogn...@ipifserver.com
From: ;tag=2d6595e0
Contact: 
Content-Length: 0

, rl=[Ljava.lang.String;@30cd076c, ftid=z9hG4bK8f5e676ea02013ead2e11a9aa1ec6acd353834, ftm=SUBSCRIBE, tob=true, b2b=false, eh=Event: presence
, fts=false, rt=, ch=Contact: 
}

So it seems the dialog was correctly replicated!

But from my log:

------------------------------- Node 0 - 138.132.115.113 -------------------------------

2010-03-25 17:11:36,834 DEBUG [IPS_PROVIDER] (Thread-24) Refresh SUBSCRIBE for nome.cogn...@ipifserver.com

2010-03-25 17:11:36,835 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** DIALOG ID FOUND in dialogReplicationMap: sip:nome.cogn...@ipifserver.com 2ebf20732b306b954a80b934d5ddf562@sip:nome.cogn...@ipifserver.com:2d6595e0:6297377e

2010-03-25 17:11:36,835 DEBUG [italtel.ipif.ips] (Thread-24) org.mobicents.ha.javax.sip.ClusteredSipStackImpl.getDialog(ClusteredSipStackImpl.java:224) [checking if the dialog 2ebf20732b306b954a80b934d5ddf562@sip:nome.cogn...@ipifserver.com:2d6595e0:6297377e is present in the local cache]

2010-03-25 17:11:36,835 DEBUG [italtel.ipif.ips] (Thread-24) gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:836) [getDialog(2ebf20732b306b954a80b934d5ddf562@sip:nome.cogn...@ipifserver.com:2d6595e0:6297377e) : returning gov.nist.javax.sip.stack.ConfirmedReplicationSipDialog@20359260]

2010-03-25 17:11:36,835 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** DIALOG FOUND in SipStack !!! 0

2010-03-25 17:11:36,836 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** DUMP SipStack dialog.toString() gov.nist.javax.sip.stack.ConfirmedReplicationSipDialog@20359260

2010-03-25 17:11:36,836 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** DUMP SipStack dialog.getDialogId() 2ebf20732b306b954a80b934d5ddf562@sip:nome.cogn...@ipifserver.com:2d6595e0:6297377e

2010-03-25 17:11:36,836 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** DIALOG FINALLY FOUND in SipStack !!!

2010-03-25 17:11:36,845 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** etag HPbyrbIA

2010-03-25 17:11:36,845 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** toString gov.nist.javax.sip.stack.ConfirmedReplicationSipDialog@20359260

2010-03-25 17:11:36,845 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** getState Confirmed Dialog

2010-03-25 17:11:36,845 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** getDialogId 2ebf20732b306b954a80b934d5ddf562@sip:nome.cogn...@ipifserver.com:2d6595e0:6297377e

2010-03-25 17:11:36,846 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** getLocalSeqNumber 1

2010-03-25 17:11:36,846 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** getLastResponse SIP/2.0 202 Accepted^M

To: <sip:nome.cogn...@ipifserver.com>;tag=6297377e^M

Expires: 3600^M

Via: SIP/2.0/UDP 138.132.115.113:5061;branch=z9hG4bK8f5e676ea02013ead2e11a9aa1ec6acd353834^M

CSeq: 1 SUBSCRIBE^M

Call-ID: 2ebf20732b306b954a80b934d5ddf562@sip:nome.cogn...@ipifserver.com^M

From: <sip:nome.cogn...@ipifserver.com>;tag=2d6595e0^M

Contact: <sip:app-jnaq...@138.132.115.139:5060;transport=udp;wlsscid=5974c6;sipappsessionid=app-jnaqe6nobq6e>^M

Content-Length: 0^M

^M

2010-03-25 17:11:36,846 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** SipProvider gov.nist.javax.sip.SipProviderImpl@cd123c6

2010-03-25 17:11:36,846 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** SipProvider LP getIPAddress() 0 -> 138.132.115.113

2010-03-25 17:11:36,847 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** SipProvider LP getPort() 0 -> 5061

2010-03-25 17:11:36,847 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** SipProvider LP getSentBy() 0 -> 138.132.115.113:5061

2010-03-25 17:11:36,847 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** SipProvider LP getTransport() 0 -> udp

2010-03-25 17:11:36,847 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** SipProvider LP getIPAddress() 1 -> 138.132.115.113

2010-03-25 17:11:36,847 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** SipProvider LP getPort() 1 -> 5061

2010-03-25 17:11:36,847 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** SipProvider LP getSentBy() 1 -> 138.132.115.113:5061

2010-03-25 17:11:36,848 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ *** SipProvider LP getTransport() 1 -> tcp

------------------------------- Node 1 - 138.132.115.118 -------------------------------

2010-03-25 17:13:41,916 DEBUG [IPS_PROVIDER] (Thread-25) Refresh SUBSCRIBE for nome.cogn...@ipifserver.com

2010-03-25 17:13:41,921 ERROR [IPS_PROVIDER] (Thread-25) *** MZZ *** DIALOG ID FOUND in dialogReplicationMap: sip:nome.cogn...@ipifserver.com 2ebf20732b306b954a80b934d5ddf562@sip:nome.cogn...@ipifserver.com:2d6595e0:6297377e

2010-03-25 17:13:41,921 DEBUG [italtel.ipif.ips] (Thread-25) org.mobicents.ha.javax.sip.ClusteredSipStackImpl.getDialog(ClusteredSipStackImpl.java:224) [checking if the dialog 2ebf20732b306b954a80b934d5ddf562@sip:nome.cogn...@ipifserver.com:2d6595e0:6297377e is present in the local cache]

2010-03-25 17:13:41,922 DEBUG [italtel.ipif.ips] (Thread-25) gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:836) [getDialog(2ebf20732b306b954a80b934d5ddf562@sip:nome.cogn...@ipifserver.com:2d6595e0:6297377e) : returning null]

2010-03-25 17:13:41,922 ERROR [IPS_PROVIDER] (Thread-25) *** MZZ *** DIALOG NOT FOUND in SipStack !!! 0

2010-03-25 17:13:42,396 DEBUG [italtel.ipif.ips] (Thread-25) gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:1049) [clientTx: looking for key z9hg4bk0ca2bf967bc3df303a698879f4386d67373338]

2010-03-25 17:13:42,396 DEBUG [italtel.ipif.ips] (Thread-25) gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:1076) [findTransaction: returning  : null]

2010-03-25 17:13:42,396 DEBUG [italtel.ipif.ips] (Thread-25) gov.nist.javax.sip.SipProviderImpl.getNewClientTransaction(SipProviderImpl.java:337) [could not find existing transaction for SUBSCRIBE sip:nome.cogn...@ipifserver.com SIP/2.0^M

 creating a new one ]

2010-03-25 17:13:42,397 DEBUG [italtel.ipif.ips] (Thread-25) gov.nist.javax.sip.stack.DefaultRouter.getNextHop(DefaultRouter.java:232) [Using outbound proxy to route the request = 138.132.115.139:5060/UDP]

2010-03-25 17:13:42,397 DEBUG [italtel.ipif.ips] (Thread-25) org.mobicents.ha.javax.sip.ClusteredSipStackImpl.getDialog(ClusteredSipStackImpl.java:224) [checking if the dialog 9c8608c68a9d3aeccd086a785b7fc66e@sip:nome.cogn...@ipifserver.com:3b2464ff is present in the local cache]

2010-03-25 17:13:42,397 DEBUG [italtel.ipif.ips] (Thread-25) gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:836) [getDialog(9c8608c68a9d3aeccd086a785b7fc66e@sip:nome.cogn...@ipifserver.com:3b2464ff) : returning null]

2010-03-25 17:13:42,397 DEBUG [italtel.ipif.ips] (Thread-25) org.mobicents.ha.javax.sip.ClusteredSipStackImpl.getDialog(ClusteredSipStackImpl.java:231) [local dialog 9c8608c68a9d3aeccd086a785b7fc66e@sip:nome.cogn...@ipifserver.com:3b2464ff is null, checking in the distributed cache]

2010-03-25 17:13:42,397 DEBUG [italtel.ipif.ips] (Thread-25) org.mobicents.ha.javax.sip.ClusteredSipStackImpl.getDialogFromDistributedCache(ClusteredSipStackImpl.java:281) [sipStack org.mobicents.ha.javax.sip.SipStackImpl@618ce95d checking if the dialog 9c8608c68a9d3aeccd086a785b7fc66e@sip:nome.cogn...@ipifserver.com:3b2464ff is present in the distributed cache]

2010-03-25 17:13:42,398 DEBUG [italtel.ipif.ips] (Thread-25) org.mobicents.ha.javax.sip.ClusteredSipStackImpl.getDialog(ClusteredSipStackImpl.java:241) [dialog 9c8608c68a9d3aeccd086a785b7fc66e@sip:nome.cogn...@ipifserver.com:3b2464ff not found in the distributed cache]

2010-03-25 17:13:42,398 DEBUG [italtel.ipif.ips] (Thread-25) gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:234) [Creating message channel 138.132.115.139/5060]

2010-03-25 17:13:42,403 DEBUG [italtel.ipif.ips] (Thread-25) gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:303) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff]

2010-03-25 17:13:42,404 DEBUG [italtel.ipif.ips] (Thread-25) [LogWriter.java:92][SIPClientTransaction.java:304][SIPTransactionStack.java:1543][SIPTransactionStack.java:1521][SipProviderImpl.java:397][PresenceHelper.java:318][IPSMediator.java:370][SipCommandWatcherThread.java:178][SipCommandWatcherThread.java:98][null:-1]

2010-03-25 17:13:42,404 DEBUG [italtel.ipif.ips] (Thread-25) gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:419) [Setting Branch id : z9hG4bK0ca2bf967bc3df303a698879f4386d67373338]

2010-03-25 17:13:42,404 DEBUG [italtel.ipif.ips] (Thread-25) gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1729) [ putTransactionHash :  key = z9hg4bk0ca2bf967bc3df303a698879f4386d67373338]

2010-03-25 17:13:42,404 DEBUG [italtel.ipif.ips] (Thread-25) gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:419) [Setting Branch id : z9hG4bK0ca2bf967bc3df303a698879f4386d67373338]

2010-03-25 17:13:42,405 DEBUG [italtel.ipif.ips] (Thread-25) org.mobicents.ha.javax.sip.ClusteredSipStackImpl.getDialog(ClusteredSipStackImpl.java:224) [checking if the dialog 9c8608c68a9d3aeccd086a785b7fc66e@sip:nome.cogn...@ipifserver.com:3b2464ff is present in the local cache]

2010-03-25 17:13:42,405 DEBUG [italtel.ipif.ips] (Thread-25) gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:836) [getDialog(9c8608c68a9d3aeccd086a785b7fc66e@sip:nome.cogn...@ipifserver.com:3b2464ff) : returning null]

2010-03-25 17:13:42,405 DEBUG [italtel.ipif.ips] (Thread-25) org.mobicents.ha.javax.sip.ClusteredSipStackImpl.getDialog(ClusteredSipStackImpl.java:231) [local dialog 9c8608c68a9d3aeccd086a785b7fc66e@sip:nome.cogn...@ipifserver.com:3b2464ff is null, checking in the distributed cache]

2010-03-25 17:13:42,405 DEBUG [italtel.ipif.ips] (Thread-25) org.mobicents.ha.javax.sip.ClusteredSipStackImpl.getDialogFromDistributedCache(ClusteredSipStackImpl.java:281) [sipStack org.mobicents.ha.javax.sip.SipStackImpl@618ce95d checking if the dialog 9c8608c68a9d3aeccd086a785b7fc66e@sip:nome.cogn...@ipifserver.com:3b2464ff is present in the distributed cache]

2010-03-25 17:13:42,406 DEBUG [italtel.ipif.ips] (Thread-25) org.mobicents.ha.javax.sip.ClusteredSipStackImpl.getDialog(ClusteredSipStackImpl.java:241) [dialog 9c8608c68a9d3aeccd086a785b7fc66e@sip:nome.cogn...@ipifserver.com:3b2464ff not found in the distributed cache]

2010-03-25 17:13:42,415 DEBUG [italtel.ipif.ips] (Thread-25) gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1522) [SipDialog.addTransaction() gov.nist.javax.sip.stack.ConfirmedReplicationSipDialog@719c8616 transaction = gov.nist.javax.sip.stack.SIPClientTransaction@5badeddc]

2010-03-25 17:13:42,415 DEBUG [italtel.ipif.ips] (Thread-25) gov.nist.javax.sip.stack.SIPDialog.setRemoteParty(SIPDialog.java:738) [settingRemoteParty <sip:nome.cogn...@ipifserver.com>]

2010-03-25 17:13:42,415 DEBUG [italtel.ipif.ips] (Thread-25) gov.nist.javax.sip.stack.SIPDialog.setLocalSequenceNumber(SIPDialog.java:1672) [setLocalSequenceNumber: original  0 new  = 1]

2010-03-25 17:13:42,416 DEBUG [italtel.ipif.ips] (Thread-25) gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1580) [isBackToBackUserAgent = false]

2010-03-25 17:13:42,416 DEBUG [italtel.ipif.ips] (Thread-25) gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1588) [Transaction Added gov.nist.javax.sip.stack.ConfirmedReplicationSipDialog@719c86163b2464ff/null]

2010-03-25 17:13:42,416 DEBUG [italtel.ipif.ips] (Thread-25) gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1590) [TID = z9hg4bk0ca2bf967bc3df303a698879f4386d67373338/false]

I attach also the source code.

Do you have any suggestions?

Thanks, Mic

[Vladimir Ralev]

I noticed you have both TCP and UDP in separate SipProviders. We had
an issue with this
http://code.google.com/p/mobicents/issues/detail?id=1306 which is
supposed to be fixed. The issue was about loading a assigning UDP
dialog in TCP provider in the remote nodes. This when the requests
arrive at the surviving nodes the dialog was not associated with the
expected transport sip provider. For a quick test, please disable the
TCP SIP provider, this way there is no chance of such confusion and if
that is the problem it can be fixed. I also see that you duplicate
some of this logic in your code and this line here is very suspicious,
because it assumes only one sip provider:

SipProvider sp = SipHelper.getInstance().getSipProvider();

make sure you are taking the sip provider for the transport you are
actually using and the one where the dialog is associated.

2010-03-25 17:11:36,846 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
SipProvider gov.nist.javax.sip.SipProviderImpl@cd123c6
2010-03-25 17:11:36,846 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
SipProvider LP getIPAddress() 0 -> 138.132.115.113
2010-03-25 17:11:36,847 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
SipProvider LP getPort() 0 -> 5061
2010-03-25 17:11:36,847 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
SipProvider LP getSentBy() 0 -> 138.132.115.113:5061
2010-03-25 17:11:36,847 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
SipProvider LP getTransport() 0 -> udp
2010-03-25 17:11:36,847 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
SipProvider LP getIPAddress() 1 -> 138.132.115.113
2010-03-25 17:11:36,847 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
SipProvider LP getPort() 1 -> 5061
2010-03-25 17:11:36,847 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
SipProvider LP getSentBy() 1 -> 138.132.115.113:5061
2010-03-25 17:11:36,848 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
SipProvider LP getTransport() 1 -> tcp

We had this problem with TCP and UDP just few weeks ago. Make sure you
are looking up the dialog in the right SipProvider

[Michele Mazza]

Hello,

I have tested with just the UDP listening point but this didn't fix the problem.

Reading the jain-sip-ha source code, I noticed that the recovery Node (the one that didn't initiated the dialog), was NOT checking in the distributed cache.

Looking at ClusteredSipStackImpl source, there is a check on the number of tokens in dialogId:

  int nbToken = new StringTokenizer(dialogId, Separators.COLON).countTokens();

  // we should only check the cache for dialog Id where the remote tag is set since we support only established dialog failover

  if(sipDialog == null && nbToken == 3) {sipDialog = getDialogFromDistributedCache(dialogId);}

My dialogId is:

  3968c1f4c64570f5493c5830913c1418@sip:nome.cogn...@ipifserver.com:dc3f1cb:c462172c

and the number of tokens is 4 (probably because I have also 'sip:').

So I have looked manually in the distributed cache:

  if (dialog == null) { // dialog NOT found using ((ClusteredSipStackImpl) sipStack).getDialog(dialogId)

    dialog = ((ClusteredSipStackImpl) sipStack).getSipCache().getDialog(dialogId);

  }

and this seems to work.

From the Node1 I am able to refresh the SUBSCRIBE initiated by the Node0.

The only difference is that the refresh conditional SUBSRIBE in the Node1 (replicated) loses the Event header (so I have to re-add it).

Thanks a lot for your great help.

Michele

2010/3/25 Vladimir Ralev <vladimi...@gmail.com>

[Jean Deruelle]

Interesting can you open an issue so that we fix this by looking at token >= 3 ?

Thanks for the debugging !

Jean

[Michele Mazza]

Hello,

Opened an issue:

Issue 1378:

jain-sip-ha Dialog replication

Merci et salut, Mic

2010/3/26 Jean Deruelle <jean.d...@gmail.com>

[Jean Deruelle]

I just fixed in the SVN trunk. Can you retry directly from the sources ?

Thanks

Jean

[Mic]

Verified.
Many thanks!

On Mar 26, 3:41 pm, Jean Deruelle <jean.derue...@gmail.com> wrote:
> I just fixed in the SVN trunk. Can you retry directly from the sources ?
>
> Thanks
> Jean
>
>
>
> On Fri, Mar 26, 2010 at 3:34 PM, Michele Mazza <mazza...@gmail.com> wrote:
> > Hello,
>
> > Opened an issue:
>

> >  Issue 1378 <http://code.google.com/p/mobicents/issues/detail?id=1378>: jain-sip-ha

> > Dialog replication
>
> > Merci et salut, Mic
>

> > 2010/3/26 Jean Deruelle <jean.derue...@gmail.com>

>
> >> Interesting can you open an issue so that we fix this by looking at token
> >> >= 3 ?
>
> >> Thanks for the debugging !
> >> Jean
>

> >> On Fri, Mar 26, 2010 at 3:18 PM, Michele Mazza <mazza...@gmail.com>wrote:
>
> >>> Hello,
>
> >>> I have tested with just the UDP listening point but this didn't fix the
> >>> problem.
>
> >>> Reading the jain-sip-ha source code, I noticed that the recovery Node
> >>> (the one that didn't initiated the dialog), was NOT checking in the
> >>> distributed cache.
>
> >>> Looking at ClusteredSipStackImpl source, there is a check on the number
> >>> of tokens in dialogId:
>
> >>>   int nbToken = new StringTokenizer(dialogId,
> >>> Separators.COLON).countTokens();
> >>>   // we should only check the cache for dialog Id where the remote tag is
> >>> set since we support only established dialog failover

> >>>   if(sipDialog == null && *nbToken == 3*) {sipDialog =

> >>> getDialogFromDistributedCache(dialogId);}
>
> >>> My dialogId is:
>
> >>>   3968c1f4c64570f5493c5830913c1418@sip

> >>> :nome.cognome_000...@ipifserver.com:dc3f1cb:c462172c

>
> >>> and the number of tokens is 4 (probably because I have also 'sip:').
>
> >>> So I have looked manually in the distributed cache:
>
> >>>   if (dialog == null) { // dialog NOT found using
> >>> ((ClusteredSipStackImpl) sipStack).getDialog(dialogId)

> >>>     dialog = ((ClusteredSipStackImpl) sipStack).*getSipCache()*

> >>> .getDialog(dialogId);
> >>>   }
>
> >>> and this seems to work.
>
> >>> From the Node1 I am able to refresh the SUBSCRIBE initiated by the Node0.
> >>> The only difference is that the refresh conditional SUBSRIBE in the Node1
> >>> (replicated) loses the Event header (so I have to re-add it).
>
> >>> Thanks a lot for your great help.
> >>> Michele
>

> >>> 2010/3/25 Vladimir Ralev <vladimir.ra...@gmail.com>

>
> >>>> I noticed you have both TCP and UDP in separate SipProviders. We had
> >>>> an issue with this

> >>>>http://code.google.com/p/mobicents/issues/detail?id=1306which is

> >>>> On Thu, Mar 25, 2010 at 6:32 PM, Michele Mazza <mazza...@gmail.com>

> >>>> wrote:
> >>>> > Hello Jean,
> >>>> > I modified my application according to your explanation.
> >>>> > Now I save in the POJO cache just the dialogId related to a user.
> >>>> > On the replicated Node, I get just the dialogId from my cache and then
> >>>> I get
> >>>> > the dialog this way:
> >>>> >   dialog = ((ClusteredSipStackImpl)
> >>>> > SipHelper.getInstance().getSipStack()).getDialog(dialogId);
> >>>> > Form the JBoss console (under jboss.cache) I cas see:
> >>>> > ------------------------------- Node 0
> >>>> > - 138.132.115.113 -------------------------------
>
> >>>> > /  {}
> >>>> >   /MSS_FT_SAS_Timers23a3d117  {}
> >>>> >   /MSS_FT_Timers6f97354c  {}
> >>>> >   /MSS_FT_Timers23a3d117  {}
> >>>> >   /MSS_FT_SAS_Timers6f97354c  {}
> >>>> >   /jain-sip-ha  {}
> >>>> >     /Dialogs  {}
>
> >>>> > /2ebf20732b306b954a80b934d5ddf562@sip

> >>>> :nome.cognome_000...@ipifserver.com:2d6595e0:6297377e

> >>>> > {ir=false, stf=false, is=false, lr=SIP/2.0 202 Accepted
> >>>> > To: ;tag=6297377e
> >>>> > Expires: 3600
> >>>> > Via: SIP/2.0/UDP
> >>>> > 138.132.115.113:5061
> >>>> ;branch=z9hG4bK8f5e676ea02013ead2e11a9aa1ec6acd353834
> >>>> > CSeq: 1 SUBSCRIBE
> >>>> > Call-ID:
> >>>> > 2ebf20732b306b954a80b934d5ddf562@sip:

> >>>> nome.cognome_000...@ipifserver.com

> >>>> > From: ;tag=2d6595e0
> >>>> > Contact:
> >>>> > Content-Length: 0
>
> >>>> > , rl=[Ljava.lang.String;@30cd076c,
> >>>> > ftid=z9hG4bK8f5e676ea02013ead2e11a9aa1ec6acd353834, ftm=SUBSCRIBE,
> >>>> tob=true,
> >>>> > b2b=false, eh=Event: presence
> >>>> > , fts=false, rt=, ch=Contact:
> >>>> > }
>
> >>>> > ------------------------------- Node 1
> >>>> > - 138.132.115.118 -------------------------------
>
> >>>> > /  {}
> >>>> >   /MSS_FT_SAS_Timers23a3d117  {}
> >>>> >   /MSS_FT_Timers6f97354c  {}
> >>>> >   /MSS_FT_Timers23a3d117  {}
> >>>> >   /MSS_FT_SAS_Timers6f97354c  {}
> >>>> >   /jain-sip-ha  {}
> >>>> >     /Dialogs  {}
>
> >>>> > /2ebf20732b306b954a80b934d5ddf562@sip

> >>>> :nome.cognome_000...@ipifserver.com:2d6595e0:6297377e

> >>>> > {ir=false, stf=false, is=false, lr=SIP/2.0 202 Accepted
> >>>> > To: ;tag=6297377e
> >>>> > Expires: 3600
> >>>> > Via: SIP/2.0/UDP
> >>>> > 138.132.115.113:5061
> >>>> ;branch=z9hG4bK8f5e676ea02013ead2e11a9aa1ec6acd353834
> >>>> > CSeq: 1 SUBSCRIBE
> >>>> > Call-ID:
> >>>> > 2ebf20732b306b954a80b934d5ddf562@sip:

> >>>> nome.cognome_000...@ipifserver.com

> >>>> > From: ;tag=2d6595e0
> >>>> > Contact:
> >>>> > Content-Length: 0
>
> >>>> > , rl=[Ljava.lang.String;@30cd076c,
> >>>> > ftid=z9hG4bK8f5e676ea02013ead2e11a9aa1ec6acd353834, ftm=SUBSCRIBE,
> >>>> tob=true,
> >>>> > b2b=false, eh=Event: presence
> >>>> > , fts=false, rt=, ch=Contact:
> >>>> > }
>
> >>>> > So it seems the dialog was correctly replicated!
>
> >>>> > But from my log:
>
> >>>> > ------------------------------- Node 0
> >>>> > - 138.132.115.113 -------------------------------
> >>>> > 2010-03-25 17:11:36,834 DEBUG [IPS_PROVIDER] (Thread-24) Refresh
> >>>> SUBSCRIBE

> >>>> > for nome.cognome_000...@ipifserver.com

> >>>> > 2010-03-25 17:11:36,835 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
> >>>> DIALOG
> >>>> > ID FOUND in dialogReplicationMap:

> >>>> sip:nome.cognome_000...@ipifserver.com<sip%3Anome.cognome_000...@ipifserver.com>
> >>>> > 2ebf20732b306b954a80b934d5ddf562@sip
> >>>> :nome.cognome_000...@ipifserver.com:2d6595e0:6297377e

> >>>> > 2010-03-25 17:11:36,835 DEBUG [italtel.ipif.ips] (Thread-24)
>

> >>>> org.mobicents.ha.javax.sip.ClusteredSipStackImpl.getDialog(ClusteredSipStac kImpl.java:224)

> >>>> > [checking if the dialog
> >>>> > 2ebf20732b306b954a80b934d5ddf562@sip

> >>>> :nome.cognome_000...@ipifserver.com:2d6595e0:6297377e

> >>>> > is present in the local cache]
> >>>> > 2010-03-25 17:11:36,835 DEBUG [italtel.ipif.ips] (Thread-24)
>
> >>>> gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack. java:836)
> >>>> > [getDialog(2ebf20732b306b954a80b934d5ddf562@sip

> >>>> :nome.cognome_000...@ipifserver.com:2d6595e0:6297377e)

> >>>> > : returning
> >>>> gov.nist.javax.sip.stack.ConfirmedReplicationSipDialog@20359260]
> >>>> > 2010-03-25 17:11:36,835 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
> >>>> DIALOG
> >>>> > FOUND in SipStack !!! 0
> >>>> > 2010-03-25 17:11:36,836 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
> >>>> DUMP
> >>>> > SipStack dialog.toString()
> >>>> > gov.nist.javax.sip.stack.ConfirmedReplicationSipDialog@20359260
> >>>> > 2010-03-25 17:11:36,836 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
> >>>> DUMP
> >>>> > SipStack dialog.getDialogId()
> >>>> > 2ebf20732b306b954a80b934d5ddf562@sip

> >>>> :nome.cognome_000...@ipifserver.com:2d6595e0:6297377e

> >>>> > 2010-03-25 17:11:36,836 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
> >>>> DIALOG
> >>>> > FINALLY FOUND in SipStack !!!
> >>>> > 2010-03-25 17:11:36,845 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
> >>>> etag
> >>>> > HPbyrbIA
> >>>> > 2010-03-25 17:11:36,845 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
> >>>> > toString
> >>>> gov.nist.javax.sip.stack.ConfirmedReplicationSipDialog@20359260
> >>>> > 2010-03-25 17:11:36,845 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
> >>>> > getState Confirmed Dialog
> >>>> > 2010-03-25 17:11:36,845 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
> >>>> > getDialogId
> >>>> > 2ebf20732b306b954a80b934d5ddf562@sip

> >>>> :nome.cognome_000...@ipifserver.com:2d6595e0:6297377e

> >>>> > 2010-03-25 17:11:36,846 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
> >>>> > getLocalSeqNumber 1
> >>>> > 2010-03-25 17:11:36,846 ERROR [IPS_PROVIDER] (Thread-24) *** MZZ ***
> >>>> > getLastResponse SIP/2.0 202 Accepted^M

> >>>> > To: <sip:nome.cognome_000...@ipifserver.com<sip%3Anome.cognome_000...@ipifserver.com>
>
> ...
>
> read more »

[Jean Deruelle]

My pleasure and thanks to you for going the extra mile :-)

[Jean Deruelle]

Another thing on that, you shouldn't even have to replicate the dialog id. 

the stack upon receiving a subsequent request in the dialog will check the local stack for the dialog, if not found it will check the cache and will find it there and process the subsequent request as if no failover ever occured. so you should just be able to grab the dialog from the RequestEvent or on the transaction.

Jean

[Michele Mazza]

Hello,

My application is now working properly using jain-sip-ha in a JBoss Cluster.

Now I woluld like to avoid replicating the dialog id (according to your suggestion).

I have a dialog associated to a user SUBSCRIBE.

When I need to refresh the SUBSCRIBE, I do:

  Strong dialogId = ...; // get dialogId from my cache

  Dialog dialog = ((ClusteredSipStackImpl) sipStack).getDialog(dialogId);

  Request request = dialog.createRequest(Request.SUBSCRIBE);

  // customize my request for SUBSCRIBE refresh

  request.setHeader(...)

  ...

  // send request

  SIPClientTransaction clientTransaction = (SIPClientTransaction) sipProvider.getNewClientTransaction(request);

  clientTransaction.sendRequest();

My question is the following: I can I get the dialog if not through sipStack.getDialog(dialogId) ?

Thanks a lot and Happy Easter!

Michele

2010/3/29 Jean Deruelle <jean.d...@gmail.com>

[Jean Deruelle]

Humm you might need to replicate it actually if what is triggering the refresh is a timer that failed over, or a request from a different dialog or an external event not related to the dialog that triggers the refresh.

[Michele Mazza]

Thanks a lot anyway for your suggestion.

Michele

2010/4/2 Jean Deruelle <jean.d...@gmail.com>