"IllegalStateException: Timer already cancelled" crashes Mobicents

[Raymond Domingo]

It seems "IllegalStateException: Timer already cancelled" is still a
MAJOR problem.
When I run my stress test it is thrown within minutes and after this
ALL calls are lost,
A tomcat server restart is needed to recover...

My revistion
Rev: 7480

Just 10 threads (doing: invite + wait 3sec + bye, repeat)
Within one minute I already recieve the IlegalStateException.
And the bad thing is, tomcat/mobicents doesn't recover (at least not
within a limited amout of time and calls get lost)
I need to restart the tomcat in order to get it working again :(

java.lang.IllegalStateException: Timer already cancelled.
at java.util.Timer.sched(Timer.java:354)
at java.util.Timer.schedule(Timer.java:170)
at org.mobicents.servlet.sip.proxy.ProxyBranchImpl.updateTimer
(ProxyBranchImpl.java:592)
at org.mobicents.servlet.sip.proxy.ProxyBranchImpl.start
(ProxyBranchImpl.java:271)
at org.mobicents.servlet.sip.proxy.ProxyImpl.startNextUntriedBranch
(ProxyImpl.java:555)
at org.mobicents.servlet.sip.proxy.ProxyImpl.startProxy
(ProxyImpl.java:446)
at org.mobicents.servlet.sip.proxy.ProxyImpl.proxyTo(ProxyImpl.java:
308)
at
nl.telecats.kasteel.fastvoip.sipservlets.ForwardSipServlet.setupCall
(ForwardSipServlet.java:830)
at nl.telecats.kasteel.fastvoip.sipservlets.ForwardSipServlet.doInvite
(ForwardSipServlet.java:263)
at javax.servlet.sip.SipServlet.doRequest(SipServlet.java:225)
at
nl.telecats.kasteel.fastvoip.sipservlets.ForwardSipServlet.doRequest
(ForwardSipServlet.java:132)
at javax.servlet.sip.SipServlet.service(SipServlet.java:325)
at
org.mobicents.servlet.sip.core.dispatchers.MessageDispatcher.callServlet
(MessageDispatcher.java:243)
at org.mobicents.servlet.sip.core.dispatchers.InitialRequestDispatcher
$1.dispatch(InitialRequestDispatcher.java:424)
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
(ThreadPoolExecutor.java:651)
at java.util.concurrent.ThreadPoolExecutor$Worker.run
(ThreadPoolExecutor.java:676)
at java.lang.Thread.run(Thread.java:595)

[Vladimir Ralev]

OK. I checked in a simple fix. Can you update again from trunk and
test the new patch.

[Raymond Domingo]

sorry, it didn't help.
after updating to revision 7481 I still got:

On 18 aug, 11:47, Vladimir Ralev <vladimir.ra...@gmail.com> wrote:
> OK. I checked in a simple fix. Can you update again from trunk and
> test the new patch.
>

[Vladimir Ralev]

Can you give more details about the scenario?

[Raymond Domingo]

yes:

My sip test (see 'snapshot sipunittest' below)
-send invite and wait for answer
-send ack
-wait
-send bye

My sipservlet (see 'snapshot sipservlet' below)
- recieves the call doInvite will trigger setupcall method
- proxies (seq) the call
- on ringing changes the timeout (this is a bit out of the ordanary !!)
- done

I hope this is of any help, just let me know when I can be of any help.

[start snapshot sipunittest]
SipCall call1 = ua
.makeCall(
ENDPOINT_AUDIO_TEST,
SipResponse.OK,
WAIT_FOR_RESPONSE_TIMEOUT,
properties
.getProperty(PROP_MOBICENTS_IP)
+ ':'
+ properties

.getProperty(PROP_MOBICENTS_PORT)
+ '/' + testProtocol);

// acknowledge ok
call1.sendInviteOkAck();
call1.waitForAnswer(WAIT_FOR_RESPONSE_TIMEOUT);

wait(3000);

// send bye
call1.disconnect();

call1.waitForAnswer(WAIT_FOR_RESPONSE_TIMEOUT);

// assert X_FAST_VOIP_MAX_DIAL_TIME header is there
ArrayList<SipResponse> allReceivedResponses = call1
.getAllReceivedResponses();
SipResponse sr = allReceivedResponses
.get(allReceivedResponses.size() - 1);
Message message = sr.getMessage();
Header header = message
.getHeader(X_FAST_VOIP_MAX_DIAL_TIME);
assertTrue("Has '" + X_FAST_VOIP_MAX_DIAL_TIME
+ " header", header != null);
callCount++;
[end snapshot sipunittest]

[start snapshot sipservlet]
private void setupCall(SipServletRequest request, String rawDestination,
int maxCallTime, String defaultLanguage)
throws ServletParseException, TooManyHopsException {

ArrayList<URI> proxyToList = new ArrayList<URI>();

// fill the proxy to list code...
proxyToList.add(destURI);

// proxy the call
logger.debug("forward the call / setup the proxy");
Proxy proxy = request.getProxy();
if (routingHostResponseTimeout > 0) {
proxy.setProxyTimeout(routingHostResponseTimeout);
}
proxy.setRecordRoute(true); // set to true to receive bye
proxy.setParallel(false); // proxy sequentially / try one by one
proxy.proxyTo(proxyToList);
}




@Override
protected void doBranchResponse(SipServletResponse resp)
throws ServletException, IOException {
if (INVITE.equalsIgnoreCase(resp.getMethod())) {
if (resp.getStatus() == SipServletResponse.SC_RINGING
|| resp.getStatus() == SipServletResponse.SC_OK) {
if (proxyTimeout > 0) {
resp.getProxy().setProxyTimeout(proxyTimeout);
}
}
}
super.doBranchResponse(resp);
}
[end snapshot sipservlet]


2009/8/18 Vladimir Ralev <vladimi...@gmail.com>:

[Raymond Domingo]

I suspect me calling resp.getProxy().setProxyTimeout(proxyTimeout);
from doBranche (when I recieve the ringing is) has something to do
with causing the exception.

Should it be possibe to change the timeout from doBranchResponse ?

> 2009/8/18 Vladimir Ralev <vladimir.ra...@gmail.com>:

>
>
>
> > Can you give more details about the scenario?
>

[Vladimir Ralev]

I tried these and I couldn't see any hang, but I noticed some other
strange behaviour that might be related. I am wondering now if what
you are seeing is our congestion control kicking in. Thus try to turn
it off by doing something like this in server.xml :
<Connector port="5080" sipMessageQueueSize="160000"
congestionControlCheckingInterval="2000000" .../>

This looks like a good theory to me but I am not certain.

Also I added some more checks in the proxy in the trunk around the
timers that should recover from anything now.

Also, please tell me what kind of load are you trying - calls per
second, how many concurrent calls, what kind of JVM and OS. These can
help further. Thanks.

[Raymond Domingo]

Hi Vladimir,

Thank you for the commit, all seems to work better now, functional all
seems fine.

But after some time in console I start seeing NullPointerExceptions
(increasing in amount over time)
When I stop my test they keep comming for some time, but after a
certain period they stop happening. And all seems ok again. Currently
I just have lots of lines like below (no more details)

2009-08-19 12:48:41,587 [ERROR] - java.lang.NullPointerException
2009-08-19 12:48:41,587 [ERROR] - java.lang.NullPointerException

Is this of any help ?

2009/8/19 Vladimir Ralev <vladimi...@gmail.com>:

[Raymond Domingo]

I just discovered following:

In my test I test usage of 'invalid' hosts. When the 'hostList' passed
to proxyTo(hostList) contains 'invalid' hosts, the NullPointer
appears. When I remove the invalid hosts, there is no exception.

'invalid' hosts in my context are hosts that exist (valid ip's), but
which won't run any services, so hosts which can't be succesfully
used.

Expected behaviour, timeout and next host in 'hostList' should be
used without the NullPointerException

Is this of any help ?

2009/8/19 Raymond Domingo <ray...@domingo.nl>:

[Vladimir Ralev]

There was a problem with logging that limited info as you observed.
Fixed in trunk now and it should show the full stack. I am still
interested to know what kind of load do you test with and what is the
CPU utilization. It is normal to get NPEs at some point under very
high load, we have seen this a few times and it is a natural
congestion control when it happens, but I just dont see the stack
right now and dont know what kind of load you use. It is also possible
something is still not tuned in our locking.

I dont see any reason invalid hosts would generate NPEs right now, but
I have a some ideas on handling load a bit better.

Also if you are using the the code from trunk and UDP, the following
configuration might help - in
server/default/conf/mss-sip-stack.properties add:
gov.nist.javax.sip.RECEIVE_UDP_BUFFER_SIZE=64000
gov.nist.javax.sip.SEND_UDP_BUFFER_SIZE=64000

[R.Domingo]

Monday I am in the office again and I can mail you the details.


-----Oorspronkelijk bericht-----
Van: mobicent...@googlegroups.com
[mailto:mobicent...@googlegroups.com] Namens Vladimir Ralev
Verzonden: woensdag 19 augustus 2009 19:02
Aan: mobicent...@googlegroups.com
Onderwerp: [mobicents-public] Re: "IllegalStateException: Timer already
cancelled" crashes Mobicents