Hold Invite after failover results in 483 Too many hops

[BrownSound777 Brown]

Hi,

 

I modified the distributable click to call servlet to support re-invite and I am trying to test hold after failover.  The scenario is:

 

1) I have two nodes running mobicents  in the same cluster with the c2c servlet deployed.

2) On my "active" server I start mobicents with ./run.sh -c all -b 47.105.84.64

3) On my standby server I start mobicents with ./run.sh -c all -b 0.0.0.0

4) u...@a.com calls u...@a.com  (invite/200/ack)  (call uses the active server 47.105.84.64)

5) I kill the active server

6) The standby server takes over ip 47.105.84.64.  We have our own ip takeover process that works similiar to what is described here: http://tinyurl.com/l3kfe4
7) u...@a.com tries to put the call on hold by sending a re-invite with hold SDP. 

8) The newly active mobicents server sends back a 483:

 

SIP/2.0 483 Too many hops
From: "u1 u1" <sip:u...@a.com>;tag=40-11e0-13d0-ffffffff
To: "u2 u2" <sip:u...@a.com>;tag=41510738_50f32d32_8387008329059927
CSeq: 1 INVITE
Call-ID: 1fc35b5f225da9931b...@47.102.244.232
Via: SIP/2.0/UDP 47.102.244.232:5061;branch=z9hG4bK4a7c5782-0
Content-Length: 0
User-Agent:  Nortel SESM 12.0.3.4
MSS_Initial_Remote_Addr:  47.105.84.64
MSS_Initial_Remote_Addr:  47.105.84.64
MSS_Initial_Remote_Addr:  47.105.84.64
MSS_Initial_Remote_Addr:  47.105.84.64
MSS_Initial_Remote_Addr:  47.105.84.64

MSS_Initial_Remote_Addr:  47.105.84.64
...
MSS_Initial_Remote_Port:  5080
MSS_Initial_Remote_Port:  5080

MSS_Initial_Remote_Port:  5080
...
MSS_Initial_Remote_Transport:  udp
MSS_Initial_Remote_Transport:  udp
...

 

Note: we are not using the load balancer. Also, I was able to get a Bye after failover to work.  I have attached the logs and a call flow diagram.  Let me know if you have any ideas. 

 

Thanks

Anthony

[Vladimir Ralev]

Can you confirm that this works without the failover?

My initial thoughts are that the application router in your backup
server is not configured properly or the application is not deployed
there. Can you check these as well? Note that the application routing
configuration must be done on each server manually.

And we also have a bug that causes these requests to be routed back to
the server in a loop eventually leading the error response.

[BrownSound777 Brown]

I tested hold without failover on both servers individually and it works so the dar configuration and everything seems ok. 

 

I'll look some more at the failover scenario.  I think there is an issue with having the newly active sever pick the correct interface to use.  I want the sip stack to use the ip address that was taken over.  Maybe I need some extra functionality to create a new sip connector with the correct ip after a failover/ip-takeover has occured. 

 

I found that Bye after failover works but I noticed that the Bye sent out from the mobicents server is not sent using the ip address that was taken over. Instead the Bye is sent using one of the other ip configured on the server. 

[Vladimir Ralev]

Yes I was afraid of this, but when you reported BYE is working I
though it is fine. Try to force a static IP address on the backup
machine with this option (use the ip of the primary machine)

<Connector port="5080"
ipAddress = "${jboss.bind.address}"
...
staticServerAddress="122.122.122.122" staticServerPort="44"
useStaticAddress="true"/>

[Vladimir Ralev]

If this doesn't work. The ultimate fix would be run both nodes on the
same ip address, but have the backup node in silent mode (turn arp off
with ip for example http://linux-ip.net/html/tools-ip-link.html). When
the heartbeat fails enable arp together with the other things. You
still need a second IP address on the same interface to keep the
replication going on and probably do the heartbeat. You also need to
put them behind a switch, which will take care of not delivering
anything until the backup node starts responding to arp (or initiates
arp itself). You probably have some Linux admins there, it would be
better to ask them what is required to deploy it like that.

[BrownSound777 Brown]

Hi,

From a Unix point of view the ip takeover is working, and the "floating ip" (aka service address) is acquired by the standby machine when the active one goes down. This is legacy stuff that we have been using for a while. 

 

I added staticServerAddress="47.105.84.64" staticServerPort="5080"   useStaticAddress="true" to the SIP Connector.
However, the hold after failover still doesn't work.  The mss sends back a 404 not found for the hold invite.

 

The non-failover hold works.  In the non-failover hold scenario I see the following logs when the hold invite comes in:

20:29:45,221 DEBUG [Mobicents-SIP-Servlets] 
   gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:235)

   [dialog = gov.nist.javax.sip.stack.SIPDialog@119015b]
...
20:29:45,228 DEBUG [SipApplicationDispatcherImpl]
   Routing State SUBSEQUENT

But in the failover case when the hold invite comes in the dialog is not found:

13:24:28,388 DEBUG [Mobicents-SIP-Servlets]
   gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:235) [dialog = null]
...
13:24:28,416 DEBUG [SipApplicationDispatcherImpl]
   Routing State INITIAL
...
org.mobicents.servlet.sip.core.dispatchers.DispatcherException: the Request-URI does not point to another domain, and there is no Route header,the container should not send the request as it will cause a loop. Instead, the container must reject the request with 404 Not Found final response with no Retry-After header. You may want to check your dar configuration file to see if the request can be handled or make sure you use the correct Application Router jar.

I have attached the full logs.  I will look into dynamically adding the sip connector on the "floating ip" after a failover occurs.  I am hoping that once the listeningpoint and everything is setup on the correct ip then the replicated dialog and application session will be located correctly after the failover when the hold invite comes in.

Thanks
anthony

[Vladimir Ralev]

Yes, my guess was that the container does not recognize itself by IP
address (because it changes), but now I am not so sure. There also
appears to be a problem with replication

From: "u1 u1" <sip:u...@a.com>;tag=29-1750-1a88-ffffffff

To: "u2 u2" <sip:u...@a.com>;tag=10815605_50f32d32_8677217557009562

Call-ID: 734159f34a8358d6...@47.105.84.64

CSeq: 2 ACK

Via: SIP/2.0/UDP
47.102.244.232:5065;rport=5065;branch=z9hG4bK-7107d-1b986af9-3342c778;received=47.102.244.232

Contact: <sip:u...@47.102.244.232:5065;nt_end_pt=YM0+~Kud~Q!.v1SW.uWUqtA0~Ku031~UHdFFm~NAf4imazaS~LXaxTc7devoMa~WbErty5fC6Nj76~Xn7ZQzN~LPcdcU1.qwoTDmp3-15ccr8z8t6Q0E114!BPr~J4S4T.5AJqtT-.f32;nt_server_host=47.102.244.232:5065>

User-Agent: Nortel PCC 7.0.76

Max-Forwards: 20

Content-Length: 0

20:29:45,530 DEBUG [SubsequentRequestDispatcher] Trying to find the
corresponding sip session with key
(sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d6...@47.105.84.64,8677217557009562,TpccSipServlet)
to this subsequent request ACK sip:47.105.84.64:5080;transport=udp
SIP/2.0

From: "u1 u1" <sip:u...@a.com>;tag=29-1750-1a88-ffffffff

To: "u2 u2" <sip:u...@a.com>;tag=10815605_50f32d32_8677217557009562

Call-ID: 734159f34a8358d6...@47.105.84.64

CSeq: 2 ACK

Via: SIP/2.0/UDP
47.102.244.232:5065;rport=5065;branch=z9hG4bK-7107d-1b986af9-3342c778;received=47.102.244.232

Contact: <sip:u...@47.102.244.232:5065;nt_end_pt=YM0+~Kud~Q!.v1SW.uWUqtA0~Ku031~UHdFFm~NAf4imazaS~LXaxTc7devoMa~WbErty5fC6Nj76~Xn7ZQzN~LPcdcU1.qwoTDmp3-15ccr8z8t6Q0E114!BPr~J4S4T.5AJqtT-.f32;nt_server_host=47.102.244.232:5065>

User-Agent: Nortel PCC 7.0.76

Max-Forwards: 20

Content-Length: 0

with the following popped route header null
20:29:45,530 DEBUG [JBossCacheSipManager] sip session
(sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d6...@47.105.84.64,8677217557009562,TpccSipServlet)
found in the local store SessionBasedClusteredSipSession[key:
(sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d6...@47.105.84.64,8677217557009562,TpccSipServlet)
lastAccessedTime: 1249954185230 version: 0 lastOutdated: 0]
20:29:45,530 DEBUG [JBossCacheSipManager] sip session
(sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d6...@47.105.84.64,8677217557009562,TpccSipServlet)
bound and expired ? false
20:29:45,530 DEBUG [SubsequentRequestDispatcher] Inverted try worked.
sip session found :
(sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d6...@47.105.84.64,8677217557009562,TpccSipServlet)
20:29:45,530 DEBUG [Mobicents-SIP-Servlets]
gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:226)
[Done processing Message ACK sip:47.105.84.64:5080;transport=udp
SIP/2.0

]
20:29:45,531 DEBUG [Mobicents-SIP-Servlets]
gov.nist.javax.sip.stack.SIPDialog.requestConsumed(SIPDialog.java:786)
[Request Consumed -- next consumable Request Seqno = 3]
20:29:45,531 DEBUG [Mobicents-SIP-Servlets]
gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246)
[Done processing Message ACK sip:47.105.84.64:5080;transport=udp
SIP/2.0

]
20:29:45,531 DEBUG [Mobicents-SIP-Servlets]
gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1197)
[semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@3287f27a]
20:29:45,531 DEBUG [SipSessionImpl] transaction
gov.nist.javax.sip.stack.SIPServerTransaction@3287f27a has been added
to sip session's ongoingTransactions
20:29:45,532 DEBUG [Mobicents-SIP-Servlets]
[LogWriter.java:111][SIPTransaction.java:1198][SIPTransaction.java:1184][SIPServerTransaction.java:1647][EventScanner.java:254][SipProviderImpl.java:184][DialogFilter.java:944][SIPServerTransaction.java:809][UDPMessageChannel.java:455][UDPMessageChannel.java:414][UDPMessageChannel.java:258][null:-1]
20:29:45,532 INFO [SipStandardContext] We are now after the servlet
invocation, We replicate no matter what
20:29:45,533 DEBUG [Mobicents-SIP-Servlets]
gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:922)
[removePendingTx: z9hg4bk-7107d-1b986af9-3342c778]
20:29:45,533 INFO [SipStandardContext] Snapshot Manager
org.jboss.web.tomcat.service.session.InstantConvergedSnapshotManager@15afd61
20:29:45,535 DEBUG [JBossCacheSipManager] check to see if needs to
store and replicate session with id
(sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d6...@47.105.84.64,8677217557009562,TpccSipServlet)
20:29:45,533 DEBUG [Mobicents-SIP-Servlets]
gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:562)
[Transaction:setState Terminated Transaction
gov.nist.javax.sip.stack.SIPServerTransaction@3287f27a branchID =
z9hG4bK-7107d-1b986af9-3342c778 isClient = false]
20:29:45,535 INFO [JBossCacheSipManager] replicating following sip
session (sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d6...@47.105.84.64,8677217557009562,TpccSipServlet)
20:29:45,535 DEBUG [JBossCacheClusteredSipSession]
processSessionRepl(): session is dirty. Will increment version from: 0
and replicate.
20:29:45,535 DEBUG [Mobicents-SIP-Servlets]
[LogWriter.java:111][SIPTransaction.java:565][SIPServerTransaction.java:1430][EventScanner.java:267][SipProviderImpl.java:184][DialogFilter.java:944][SIPServerTransaction.java:809][UDPMessageChannel.java:455][UDPMessageChannel.java:414][UDPMessageChannel.java:258][null:-1]
20:29:45,535 DEBUG [ClusteredSipSession] writing handlerServlet null
20:29:45,535 DEBUG [Mobicents-SIP-Servlets]
gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1197)
[semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@3287f27a]
20:29:45,536 DEBUG [Mobicents-SIP-Servlets]
[LogWriter.java:111][SIPTransaction.java:1198][SIPTransaction.java:1184][SIPServerTransaction.java:1647][UDPMessageChannel.java:460][UDPMessageChannel.java:414][UDPMessageChannel.java:258][null:-1]
20:29:45,536 ERROR [ConvergedJBossCacheService] externalizeSession():
exception occurred externalizing session
SessionBasedClusteredSipSession[key:
(sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d6...@47.105.84.64,8677217557009562,TpccSipServlet)
lastAccessedTime: 1249954185230 version: 1 lastOutdated: 0]
java.lang.NullPointerException
at java.io.ObjectOutputStream$BlockDataOutputStream.getUTFLength(Unknown Source)
at java.io.ObjectOutputStream$BlockDataOutputStream.writeUTF(Unknown Source)
at java.io.ObjectOutputStream.writeUTF(Unknown Source)
at org.jboss.web.tomcat.service.session.ClusteredSipSession.writeExternal(ClusteredSipSession.java:1168)
at org.jboss.web.tomcat.service.session.SessionBasedClusteredSipSession.writeExternal(SessionBasedClusteredSipSession.java:167)
at org.jboss.web.tomcat.service.session.ConvergedJBossCacheService.externalizeSipSession(ConvergedJBossCacheService.java:1927)
at org.jboss.web.tomcat.service.session.ConvergedJBossCacheService.putSipSession(ConvergedJBossCacheService.java:550)
at org.jboss.web.tomcat.service.session.JBossCacheClusteredSipSession.processSessionRepl(JBossCacheClusteredSipSession.java:158)
at org.jboss.web.tomcat.service.session.JBossCacheSipManager.processSipSessionRepl(JBossCacheSipManager.java:1681)
at org.jboss.web.tomcat.service.session.JBossCacheSipManager.storeSipSession(JBossCacheSipManager.java:750)
at org.jboss.web.tomcat.service.session.InstantConvergedSnapshotManager.snapshot(InstantConvergedSnapshotManager.java:39)
at org.mobicents.servlet.sip.startup.SipStandardContext.exitSipApp(SipStandardContext.java:1086)
at org.mobicents.servlet.sip.core.dispatchers.SubsequentRequestDispatcher$1.dispatch(SubsequentRequestDispatcher.java:319)
at org.mobicents.servlet.sip.core.dispatchers.DispatchTask.dispatchAndHandleExceptions(DispatchTask.java:55)
at org.mobicents.servlet.sip.core.dispatchers.DispatchTask.run(DispatchTask.java:50)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

I think I was able to reproduce this particular problem and I am
looking into it. It is possible that there is another replication
problem that causes your case to fail though.

On Tue, Aug 11, 2009 at 5:30 AM, BrownSound777

[jean.deruelle]

I looked at the logs, and it is strange.
Upon receiving the INVITE on the backup server, there is this log

2009-08-07 11:34:10,277 INFO
[org.mobicents.servlet.sip.core.dispatchers.InitialRequestDispatcher]
Dispatching the request event outside the container

which indicates that the Application Router didn't find any
applications to route the request to. Can you double check the DAR
file ?

There is some rules in the Sip Servlets spec about what to do with the
request if it doesn't find any apps to route to.
And one of those is that if the Request URI points to another domain
it should be sent there.

It seems MSS recognizes 47.105.84.64 as external. It may make sense
since the real IP Addresses of the network interface on this server is
surely not this IP Address. Thus MSS tries to send the request out but
since 47.105.84.64 is it's IP address, there is a loop until the Max-
Forward Header is down to 0 and thus MSS send back the 483 Too Many
Hops

It seems to me that we should add a config option to be able to
specify a set of IP addresses or hosts recognized as being not
external for such cases of IP takeover

Jean

On Aug 7, 11:07 pm, BrownSound777 Brown <brownsound...@gmail.com>
wrote:

> I tested hold without failover on both servers individually and it works so
> the dar configuration and everything seems ok.
>
> I'll look some more at the failover scenario.  I think there is an issue
> with having the newly active sever pick the correct interface to use.  I
> want the sip stack to use the ip address that was taken over.  Maybe I need
> some extra functionality to create a new sip connector with the correct ip
> after a failover/ip-takeover has occured.
>
> I found that Bye after failover works but I noticed that the Bye sent out
> from the mobicents server is not sent using the ip address that was taken
> over. Instead the Bye is sent using one of the other ip configured on the
> server.
>

> > > From: "u1 u1" <sip:u...@a.com <sip%3...@a.com>>;tag=40-11e0-13d0-ffffffff
> > > To: "u2 u2" <sip:u...@a.com <sip%3...@a.com>
> > >;tag=41510738_50f32d32_8387008329059927
> > > CSeq: 1 INVITE
> > > Call-ID: 1fc35b5f225da9931bcc629fc88ac3e4e3...@47.102.244.232

[jean.deruelle]

the staticServerAddress="47.105.84.64" staticServerPort="5080"
useStaticAddress="true" seems to have done the trick wrt to recognize
that the IP Address is not external.

However since there is still no applications to route to , per JSR 289
it sends a 404, please double check your DAR file and make sure INVITE
are routed to the Click to Call application deployed.

Jean

On Aug 11, 5:41 pm, Vladimir Ralev <vladimir.ra...@gmail.com> wrote:
> Yes, my guess was that the container does not recognize itself by IP
> address (because it changes), but now I am not so sure. There also
> appears to be a problem with replication
>
> From: "u1 u1" <sip:u...@a.com>;tag=29-1750-1a88-ffffffff
>
> To: "u2 u2" <sip:u...@a.com>;tag=10815605_50f32d32_8677217557009562
>

> Call-ID: 734159f34a8358d673fda0f1b74b6...@47.105.84.64

>
> CSeq: 2 ACK
>
> Via: SIP/2.0/UDP
> 47.102.244.232:5065;rport=5065;branch=z9hG4bK-7107d-1b986af9-3342c778;recei ved=47.102.244.232
>

> Contact: <sip:u...@47.102.244.232:5065;nt_end_pt=YM0+~Kud~Q!.v1SW.uWUqtA0~Ku031~UHdFFm~NAf4im azaS~LXaxTc7devoMa~WbErty5fC6Nj76~Xn7ZQzN~LPcdcU1.qwoTDmp3-15ccr8z8t6Q0E114 !BPr~J4S4T.5AJqtT-.f32;nt_server_host=47.102.244.232:5065>

>
> User-Agent: Nortel PCC 7.0.76
>
> Max-Forwards: 20
>
> Content-Length: 0
>
> 20:29:45,530 DEBUG [SubsequentRequestDispatcher] Trying to find the
> corresponding sip session with key

> (sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d673fda0f1b74b6...@47.105.84.64,8677217557009562,TpccSipServlet)

> to this subsequent request ACK sip:47.105.84.64:5080;transport=udp
> SIP/2.0
>
> From: "u1 u1" <sip:u...@a.com>;tag=29-1750-1a88-ffffffff
>
> To: "u2 u2" <sip:u...@a.com>;tag=10815605_50f32d32_8677217557009562
>

> Call-ID: 734159f34a8358d673fda0f1b74b6...@47.105.84.64

>
> CSeq: 2 ACK
>
> Via: SIP/2.0/UDP
> 47.102.244.232:5065;rport=5065;branch=z9hG4bK-7107d-1b986af9-3342c778;recei ved=47.102.244.232
>

> Contact: <sip:u...@47.102.244.232:5065;nt_end_pt=YM0+~Kud~Q!.v1SW.uWUqtA0~Ku031~UHdFFm~NAf4im azaS~LXaxTc7devoMa~WbErty5fC6Nj76~Xn7ZQzN~LPcdcU1.qwoTDmp3-15ccr8z8t6Q0E114 !BPr~J4S4T.5AJqtT-.f32;nt_server_host=47.102.244.232:5065>

>
> User-Agent: Nortel PCC 7.0.76
>
> Max-Forwards: 20
>
> Content-Length: 0
>
>  with the following popped route header null
> 20:29:45,530 DEBUG [JBossCacheSipManager] sip session

> (sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d673fda0f1b74b6...@47.105.84.64,8677217557009562,TpccSipServlet)

> found in the local store SessionBasedClusteredSipSession[key:

> (sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d673fda0f1b74b6...@47.105.84.64,8677217557009562,TpccSipServlet)

> lastAccessedTime: 1249954185230 version: 0 lastOutdated: 0]
> 20:29:45,530 DEBUG [JBossCacheSipManager] sip session

> (sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d673fda0f1b74b6...@47.105.84.64,8677217557009562,TpccSipServlet)

> bound and expired ? false
> 20:29:45,530 DEBUG [SubsequentRequestDispatcher] Inverted try worked.
> sip session found :

> (sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d673fda0f1b74b6...@47.105.84.64,8677217557009562,TpccSipServlet)

> 20:29:45,530 DEBUG [Mobicents-SIP-Servlets]
> gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:226)
> [Done processing Message ACK sip:47.105.84.64:5080;transport=udp
> SIP/2.0
>
> ]
> 20:29:45,531 DEBUG [Mobicents-SIP-Servlets]
> gov.nist.javax.sip.stack.SIPDialog.requestConsumed(SIPDialog.java:786)
> [Request Consumed -- next consumable Request Seqno = 3]
> 20:29:45,531 DEBUG [Mobicents-SIP-Servlets]
> gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246)
> [Done processing Message ACK sip:47.105.84.64:5080;transport=udp
> SIP/2.0
>
> ]
> 20:29:45,531 DEBUG [Mobicents-SIP-Servlets]
> gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1197 )
> [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@3287f27a]
> 20:29:45,531 DEBUG [SipSessionImpl] transaction
> gov.nist.javax.sip.stack.SIPServerTransaction@3287f27a has been added
> to sip session's ongoingTransactions
> 20:29:45,532 DEBUG [Mobicents-SIP-Servlets]

> [LogWriter.java:111][SIPTransaction.java:1198][SIPTransaction.java:1184][SI PServerTransaction.java:1647][EventScanner.java:254][SipProviderImpl.java:1 84][DialogFilter.java:944][SIPServerTransaction.java:809][UDPMessageChannel .java:455][UDPMessageChannel.java:414][UDPMessageChannel.java:258][null:-1]

> 20:29:45,532 INFO  [SipStandardContext] We are now after the servlet
> invocation, We replicate no matter what
> 20:29:45,533 DEBUG [Mobicents-SIP-Servlets]

> gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTr ansactionStack.java:922)

> [removePendingTx: z9hg4bk-7107d-1b986af9-3342c778]
> 20:29:45,533 INFO  [SipStandardContext] Snapshot Manager
> org.jboss.web.tomcat.service.session.InstantConvergedSnapshotManager@15afd6 1
> 20:29:45,535 DEBUG [JBossCacheSipManager] check to see if needs to
> store and replicate session with id

> (sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d673fda0f1b74b6...@47.105.84.64,8677217557009562,TpccSipServlet)

> 20:29:45,533 DEBUG [Mobicents-SIP-Servlets]
> gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:562)
> [Transaction:setState Terminated Transaction
> gov.nist.javax.sip.stack.SIPServerTransaction@3287f27a branchID =
> z9hG4bK-7107d-1b986af9-3342c778 isClient = false]
> 20:29:45,535 INFO  [JBossCacheSipManager] replicating following sip

> session (sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d673fda0f1b74b6...@47.105.84.64,8677217557009562,TpccSipServlet)

> 20:29:45,535 DEBUG [JBossCacheClusteredSipSession]
> processSessionRepl(): session is dirty. Will increment version from: 0
> and replicate.
> 20:29:45,535 DEBUG [Mobicents-SIP-Servlets]

> [LogWriter.java:111][SIPTransaction.java:565][SIPServerTransaction.java:143 0][EventScanner.java:267][SipProviderImpl.java:184][DialogFilter.java:944][ SIPServerTransaction.java:809][UDPMessageChannel.java:455][UDPMessageChanne l.java:414][UDPMessageChannel.java:258][null:-1]

> 20:29:45,535 DEBUG [ClusteredSipSession] writing handlerServlet null
> 20:29:45,535 DEBUG [Mobicents-SIP-Servlets]
> gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1197 )
> [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@3287f27a]
> 20:29:45,536 DEBUG [Mobicents-SIP-Servlets]

> [LogWriter.java:111][SIPTransaction.java:1198][SIPTransaction.java:1184][SI PServerTransaction.java:1647][UDPMessageChannel.java:460][UDPMessageChannel .java:414][UDPMessageChannel.java:258][null:-1]

> 20:29:45,536 ERROR [ConvergedJBossCacheService] externalizeSession():
> exception occurred externalizing session
> SessionBasedClusteredSipSession[key:

> (sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d673fda0f1b74b6...@47.105.84.64,8677217557009562,TpccSipServlet)

> lastAccessedTime: 1249954185230 version: 1 lastOutdated: 0]
> java.lang.NullPointerException
> at java.io.ObjectOutputStream$BlockDataOutputStream.getUTFLength(Unknown Source)
> at java.io.ObjectOutputStream$BlockDataOutputStream.writeUTF(Unknown Source)
> at java.io.ObjectOutputStream.writeUTF(Unknown Source)
> at org.jboss.web.tomcat.service.session.ClusteredSipSession.writeExternal(Clus teredSipSession.java:1168)
> at org.jboss.web.tomcat.service.session.SessionBasedClusteredSipSession.writeE xternal(SessionBasedClusteredSipSession.java:167)
> at org.jboss.web.tomcat.service.session.ConvergedJBossCacheService.externalize SipSession(ConvergedJBossCacheService.java:1927)
> at org.jboss.web.tomcat.service.session.ConvergedJBossCacheService.putSipSessi on(ConvergedJBossCacheService.java:550)
> at org.jboss.web.tomcat.service.session.JBossCacheClusteredSipSession.processS essionRepl(JBossCacheClusteredSipSession.java:158)
> at org.jboss.web.tomcat.service.session.JBossCacheSipManager.processSipSession Repl(JBossCacheSipManager.java:1681)
> at org.jboss.web.tomcat.service.session.JBossCacheSipManager.storeSipSession(J BossCacheSipManager.java:750)
> at org.jboss.web.tomcat.service.session.InstantConvergedSnapshotManager.snapsh ot(InstantConvergedSnapshotManager.java:39)
> at org.mobicents.servlet.sip.startup.SipStandardContext.exitSipApp(SipStandard Context.java:1086)
> at org.mobicents.servlet.sip.core.dispatchers.SubsequentRequestDispatcher$1.di spatch(SubsequentRequestDispatcher.java:319)
> at org.mobicents.servlet.sip.core.dispatchers.DispatchTask.dispatchAndHandleEx ceptions(DispatchTask.java:55)

> at org.mobicents.servlet.sip.core.dispatchers.DispatchTask.run(DispatchTask.ja va:50)

> ...
>
> read more »

[jean.deruelle]

I fixed the problem with replication http://code.google.com/p/mobicents/issues/detail?id=873

It should be available starting from build #545 from
http://hudson.jboss.org/hudson/view/Mobicents/job/MobicentsSipServletsRelease/

Thanks

Jean

On Aug 11, 5:41 pm, Vladimir Ralev <vladimir.ra...@gmail.com> wrote:

> Yes, my guess was that the container does not recognize itself by IP
> address (because it changes), but now I am not so sure. There also
> appears to be a problem with replication
>
> From: "u1 u1" <sip:u...@a.com>;tag=29-1750-1a88-ffffffff
>
> To: "u2 u2" <sip:u...@a.com>;tag=10815605_50f32d32_8677217557009562
>

> Call-ID: 734159f34a8358d673fda0f1b74b6...@47.105.84.64

>
> CSeq: 2 ACK
>
> Via: SIP/2.0/UDP

> 47.102.244.232:5065;rport=5065;branch=z9hG4bK-7107d-1b986af9-3342c778;recei ved=47.102.244.232
>

> Contact: <sip:u...@47.102.244.232:5065;nt_end_pt=YM0+~Kud~Q!.v1SW.uWUqtA0~Ku031~UHdFFm~NAf4im azaS~LXaxTc7devoMa~WbErty5fC6Nj76~Xn7ZQzN~LPcdcU1.qwoTDmp3-15ccr8z8t6Q0E114 !BPr~J4S4T.5AJqtT-.f32;nt_server_host=47.102.244.232:5065>

>
> User-Agent: Nortel PCC 7.0.76
>
> Max-Forwards: 20
>
> Content-Length: 0
>
> 20:29:45,530 DEBUG [SubsequentRequestDispatcher] Trying to find the
> corresponding sip session with key

> (sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d673fda0f1b74b6...@47.105.84.64,8677217557009562,TpccSipServlet)

> to this subsequent request ACK sip:47.105.84.64:5080;transport=udp
> SIP/2.0
>
> From: "u1 u1" <sip:u...@a.com>;tag=29-1750-1a88-ffffffff
>
> To: "u2 u2" <sip:u...@a.com>;tag=10815605_50f32d32_8677217557009562
>

> Call-ID: 734159f34a8358d673fda0f1b74b6...@47.105.84.64

>
> CSeq: 2 ACK
>
> Via: SIP/2.0/UDP

> 47.102.244.232:5065;rport=5065;branch=z9hG4bK-7107d-1b986af9-3342c778;recei ved=47.102.244.232
>

> Contact: <sip:u...@47.102.244.232:5065;nt_end_pt=YM0+~Kud~Q!.v1SW.uWUqtA0~Ku031~UHdFFm~NAf4im azaS~LXaxTc7devoMa~WbErty5fC6Nj76~Xn7ZQzN~LPcdcU1.qwoTDmp3-15ccr8z8t6Q0E114 !BPr~J4S4T.5AJqtT-.f32;nt_server_host=47.102.244.232:5065>

>
> User-Agent: Nortel PCC 7.0.76
>
> Max-Forwards: 20
>
> Content-Length: 0
>
>  with the following popped route header null
> 20:29:45,530 DEBUG [JBossCacheSipManager] sip session

> (sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d673fda0f1b74b6...@47.105.84.64,8677217557009562,TpccSipServlet)

> found in the local store SessionBasedClusteredSipSession[key:

> (sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d673fda0f1b74b6...@47.105.84.64,8677217557009562,TpccSipServlet)

> lastAccessedTime: 1249954185230 version: 0 lastOutdated: 0]
> 20:29:45,530 DEBUG [JBossCacheSipManager] sip session

> (sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d673fda0f1b74b6...@47.105.84.64,8677217557009562,TpccSipServlet)

> bound and expired ? false
> 20:29:45,530 DEBUG [SubsequentRequestDispatcher] Inverted try worked.
> sip session found :

> (sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d673fda0f1b74b6...@47.105.84.64,8677217557009562,TpccSipServlet)

> 20:29:45,530 DEBUG [Mobicents-SIP-Servlets]
> gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:226)
> [Done processing Message ACK sip:47.105.84.64:5080;transport=udp
> SIP/2.0
>
> ]
> 20:29:45,531 DEBUG [Mobicents-SIP-Servlets]
> gov.nist.javax.sip.stack.SIPDialog.requestConsumed(SIPDialog.java:786)
> [Request Consumed -- next consumable Request Seqno = 3]
> 20:29:45,531 DEBUG [Mobicents-SIP-Servlets]
> gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246)
> [Done processing Message ACK sip:47.105.84.64:5080;transport=udp
> SIP/2.0
>
> ]
> 20:29:45,531 DEBUG [Mobicents-SIP-Servlets]
> gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1197 )
> [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@3287f27a]
> 20:29:45,531 DEBUG [SipSessionImpl] transaction
> gov.nist.javax.sip.stack.SIPServerTransaction@3287f27a has been added
> to sip session's ongoingTransactions
> 20:29:45,532 DEBUG [Mobicents-SIP-Servlets]

> [LogWriter.java:111][SIPTransaction.java:1198][SIPTransaction.java:1184][SI PServerTransaction.java:1647][EventScanner.java:254][SipProviderImpl.java:1 84][DialogFilter.java:944][SIPServerTransaction.java:809][UDPMessageChannel .java:455][UDPMessageChannel.java:414][UDPMessageChannel.java:258][null:-1]

> 20:29:45,532 INFO  [SipStandardContext] We are now after the servlet
> invocation, We replicate no matter what
> 20:29:45,533 DEBUG [Mobicents-SIP-Servlets]

> gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTr ansactionStack.java:922)

> [removePendingTx: z9hg4bk-7107d-1b986af9-3342c778]
> 20:29:45,533 INFO  [SipStandardContext] Snapshot Manager
> org.jboss.web.tomcat.service.session.InstantConvergedSnapshotManager@15afd6 1
> 20:29:45,535 DEBUG [JBossCacheSipManager] check to see if needs to
> store and replicate session with id

> (sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d673fda0f1b74b6...@47.105.84.64,8677217557009562,TpccSipServlet)

> 20:29:45,533 DEBUG [Mobicents-SIP-Servlets]
> gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:562)
> [Transaction:setState Terminated Transaction
> gov.nist.javax.sip.stack.SIPServerTransaction@3287f27a branchID =
> z9hG4bK-7107d-1b986af9-3342c778 isClient = false]
> 20:29:45,535 INFO  [JBossCacheSipManager] replicating following sip

> session (sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d673fda0f1b74b6...@47.105.84.64,8677217557009562,TpccSipServlet)

> 20:29:45,535 DEBUG [JBossCacheClusteredSipSession]
> processSessionRepl(): session is dirty. Will increment version from: 0
> and replicate.
> 20:29:45,535 DEBUG [Mobicents-SIP-Servlets]

> [LogWriter.java:111][SIPTransaction.java:565][SIPServerTransaction.java:143 0][EventScanner.java:267][SipProviderImpl.java:184][DialogFilter.java:944][ SIPServerTransaction.java:809][UDPMessageChannel.java:455][UDPMessageChanne l.java:414][UDPMessageChannel.java:258][null:-1]

> 20:29:45,535 DEBUG [ClusteredSipSession] writing handlerServlet null
> 20:29:45,535 DEBUG [Mobicents-SIP-Servlets]
> gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1197 )
> [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@3287f27a]
> 20:29:45,536 DEBUG [Mobicents-SIP-Servlets]

> [LogWriter.java:111][SIPTransaction.java:1198][SIPTransaction.java:1184][SI PServerTransaction.java:1647][UDPMessageChannel.java:460][UDPMessageChannel .java:414][UDPMessageChannel.java:258][null:-1]

> 20:29:45,536 ERROR [ConvergedJBossCacheService] externalizeSession():
> exception occurred externalizing session
> SessionBasedClusteredSipSession[key:

> (sip:u...@a.com,29-1750-1a88-ffffffff,sip:u...@a.com,734159f34a8358d673fda0f1b74b6...@47.105.84.64,8677217557009562,TpccSipServlet)

> lastAccessedTime: 1249954185230 version: 1 lastOutdated: 0]
> java.lang.NullPointerException
> at java.io.ObjectOutputStream$BlockDataOutputStream.getUTFLength(Unknown Source)
> at java.io.ObjectOutputStream$BlockDataOutputStream.writeUTF(Unknown Source)
> at java.io.ObjectOutputStream.writeUTF(Unknown Source)

> at org.jboss.web.tomcat.service.session.ClusteredSipSession.writeExternal(Clus teredSipSession.java:1168)
> at org.jboss.web.tomcat.service.session.SessionBasedClusteredSipSession.writeE xternal(SessionBasedClusteredSipSession.java:167)
> at org.jboss.web.tomcat.service.session.ConvergedJBossCacheService.externalize SipSession(ConvergedJBossCacheService.java:1927)
> at org.jboss.web.tomcat.service.session.ConvergedJBossCacheService.putSipSessi on(ConvergedJBossCacheService.java:550)
> at org.jboss.web.tomcat.service.session.JBossCacheClusteredSipSession.processS essionRepl(JBossCacheClusteredSipSession.java:158)
> at org.jboss.web.tomcat.service.session.JBossCacheSipManager.processSipSession Repl(JBossCacheSipManager.java:1681)
> at org.jboss.web.tomcat.service.session.JBossCacheSipManager.storeSipSession(J BossCacheSipManager.java:750)
> at org.jboss.web.tomcat.service.session.InstantConvergedSnapshotManager.snapsh ot(InstantConvergedSnapshotManager.java:39)
> at org.mobicents.servlet.sip.startup.SipStandardContext.exitSipApp(SipStandard Context.java:1086)
> at org.mobicents.servlet.sip.core.dispatchers.SubsequentRequestDispatcher$1.di spatch(SubsequentRequestDispatcher.java:319)
> at org.mobicents.servlet.sip.core.dispatchers.DispatchTask.dispatchAndHandleEx ceptions(DispatchTask.java:55)

> at org.mobicents.servlet.sip.core.dispatchers.DispatchTask.run(DispatchTask.ja va:50)

> ...
>
> read more »

[jean.deruelle]

After an offline chat with vladimir, I made another pass on the logs
and it seems we have another HA bug here.
Details here http://code.google.com/p/mobicents/issues/detail?id=943

We shall rework JAIN SIP to allow pluggable data structures so that we
replicate and fetch at the JSIP level instead

> ...
>
> read more »

[jean.deruelle]

Fixes have been committed, you should be able to try it out from the
next build (#559) from http://hudson.jboss.org/hudson/view/Mobicents/job/MobicentsSipServletsRelease/

Please report back in any case.
Thanks
Jean

On Sep 18, 11:56 am, "jean.deruelle" <jean.derue...@gmail.com> wrote:
> After an offline chat with vladimir, I made another pass on the logs
> and it seems we have another HA bug here.

> Details herehttp://code.google.com/p/mobicents/issues/detail?id=943

> ...
>
> read more »