Restcomm exception prevents 200 OK response to MESSAGE to be sent to message sender #1023

atsakiridis · 2016-04-27T14:37:05Z

Scenario: iOS olympus sends a message to web olympus but although the message properly sent, seems error gets an exception that prevents it from sending the 200 OK back to the sender. Here are restcomm logs for scenario:

https://gist.github.com/atsakiridis/ac8c8aaa03000b8a274d66107e707db9

Restcomm-Connect version used: Restcomm 7.6.0.879

atsakiridis · 2017-03-14T12:47:33Z

Seems I'm still getting this issue. Here are the android logs

https://gist.github.com/atsakiridis/da6aeaf1c7343c3da3c4095e17c4ae4f

gvagenas · 2017-05-06T18:50:12Z

@atsakiridis I did some tests locally but I couldn't reproduce the problem.

The details for the tests I did are the following:

Latest Restcomm (8.2.0.1225)
Android Olympus 1.0.0-BETA4#1604 using TCP
Web Olympus on Chrome using WSS

Restcomm and both clients were running on the same network.

Messages from Web Olympus to Android Olympus and vice versa were properly sent and 200 OK was sent back with no exceptions.

We need to test again the call flow at cloud to check if this is still a valid issue.
If this is still a valid issue at cloud its most probably related to NAT or LB and we need to have the Restcomm logs and pcap to check.

George

atsakiridis · 2017-05-08T11:55:34Z

Thanks @gvagenas will try to check this latest this week and let you know. I'm sure it was reproducible in cloud, but not sure about locally.

atsakiridis · 2017-05-10T10:41:31Z

@gvagenas just retried and it is reproducible for me locally. Using:

Latest Restcomm (8.2.0.1225) -same as you
Android Olympus 1.0.0-BETA6#1
Web Olympus on Chrome using WSS

Restcomm and both clients were running on the same network. Scenario:

Android Olympus sends message to web Olympus
Web Olympus receives it and sends 200 OK
Restcomm receives 200 OK, but doesn't send 200 OK back to Android Olympus

Problem seems to be that Restcomm breaks with this exception:

13:24:48,378 ERROR [org.restcomm.connect.sms.SmsService] (RestComm-akka.actor.default-dispatcher-63) Can not bind object to session that has been invalidated!!: java.lang.IllegalStateException: Can not bind object to session that has been invalidated!!
	at org.mobicents.servlet.sip.core.session.SipSessionImpl.setAttribute(SipSessionImpl.java:1287)
	at org.mobicents.servlet.sip.message.MobicentsSipSessionFacade.setAttribute(MobicentsSipSessionFacade.java:182)
	at org.restcomm.connect.telephony.api.util.B2BUAHelper.forwardResponse(B2BUAHelper.java:495) [restcomm-connect.telephony.api-8.2.0.1225.jar:8.2.0.1225]
	at org.restcomm.connect.sms.SmsService.response(SmsService.java:387) [restcomm-connect.sms-8.2.0.1225.jar:8.2.0.1225]
	at org.restcomm.connect.sms.SmsService.onReceive(SmsService.java:376) [restcomm-connect.sms-8.2.0.1225.jar:8.2.0.1225]
	at akka.actor.UntypedActor$$anonfun$receive$1.applyOrElse(UntypedActor.scala:159) [akka-actor_2.10-2.1.2.jar:]
	at akka.actor.ActorCell.receiveMessage(ActorCell.scala:425) [akka-actor_2.10-2.1.2.jar:]
	at akka.actor.ActorCell.invoke(ActorCell.scala:386) [akka-actor_2.10-2.1.2.jar:]
	at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:230) [akka-actor_2.10-2.1.2.jar:]
	at akka.dispatch.Mailbox.run(Mailbox.scala:212) [akka-actor_2.10-2.1.2.jar:]
	at akka.dispatch.ForkJoinExecutorConfigurator$MailboxExecutionTask.exec(AbstractDispatcher.scala:506) [akka-actor_2.10-2.1.2.jar:]
	at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:262) [scala-library-2.10.1.jar:]
	at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:975) [scala-library-2.10.1.jar:]
	at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1478) [scala-library-2.10.1.jar:]
	at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:104) [scala-library-2.10.1.jar:]

Attaching Restcomm logs, Android logs, pcap

Archive.zip

gvagenas · 2017-05-31T11:18:07Z

@atsakiridis I couldn't reproduce 100% the issue. From the logs I can see that the session is already invalidated but Restcomm-Connect will never invalidate or set readyToInvalidate a session for a P2P messaging. Maybe @jaimecasero could share some light here

jaimecasero · 2017-08-23T15:11:08Z

these issues use to be caused by Akka actor logic invoking sipservlets API from nonManaged thread (akka thread), and getting "unsync" (combinations here are endless).

in this particular log file, we can see this message, no t sure what it means...
[Message] UserAgentManager Processing Message: "akka.actor.ReceiveTimeout$ sender : class akka.actor.DeadLetterActorRef self is terminated: false
[Emitter] org.restcomm.connect.telephony.ua.UserAgentManager

ill have a deep look later

gvagenas · 2017-08-24T04:23:44Z

@jaimecasero The UserAgentManager messages you see at the logs are not related to the call flow. The akka.actor.ReceiveTimeout is a message that periodically sent to UserAgentManager in order to ping Registrations.

The sip servlets API implementation has not changed and still invoked by a non managed thread (akka thread) and this is still a pending task.

I doubt this is the problem since all other p2p call flows are working properly. Its only the 200 OK for a MESSAGE request that gets the sip session invalidated for a reason.
@jaimecasero can you double check that from sip servlets side there is nothing wrong when handling sip session for MESSAGE requests?

jaimecasero · 2017-08-24T14:44:22Z

@gvagenas MESSAGE is heavily used in SIPServlets testsuite, and im not aware of any issue there (http://ci.telestax.com/view/SipS7/job/TelScale-SIP-Servlets-7-TestSuite/lastCompletedBuild/testReport/org.mobicents.servlet.sip.testsuite.simple/ShootistSipServletTest/testShootistMessageSetContact/). So, if you mean that the container has an issue sending 200OK response to a simple MESSAGE request (if thats the scenario...), i would really doubt such simple scenario has any issue....

Anyway, the attached log file is not showing DEBUG level of sipservlets/jainsip, so there is not much i can check there. @atsakiridis could please attach log fiels with DEBUG level enabled?

@gvagenas MESSAGE requests may be sent in-dialog or not, how is RestcommConnect sending them? Assuming you are sending standalone MESSAGE requests with no previous dialogue context; would it be possible the container is closing the SIPSession related to MESSAGE once the transaction is closed by the final response? If yes, what is the purpose of saving an attribute in the session while processing a response? what are you expecting to get from a standalone MESSAGE in terms of session attributes?

From the code here
https://github.com/RestComm/Restcomm-Connect/blob/master/restcomm/restcomm.telephony.api/src/main/java/org/restcomm/connect/telephony/api/util/B2BUAHelper.java#L495 it seems the B2BUAHelper is saving the last response by default. What is the reason to save a 200OK to a MESSAGE if there is no dialog? -> Maybe the logic here should check whether it makes sense to save the last response or not...

jaimecasero · 2017-10-10T09:28:57Z

from antonis on reproducibiltiy:
and for me it happens sporadically, but still often, maybe 1/2 or 1/3 attempts

jaimecasero · 2017-10-10T10:04:59Z

android:1.0.5-beta7#172
restcom:Restcomm-JBoss-AS7-8.2.1-51
send tenths of messages with no issue...

jaimecasero · 2017-10-10T10:08:47Z

got his 20:03:11,997 ERROR [org.restcomm.connect.telephony.api.util.B2BUAHelper] (RestComm-akka.actor.default-dispatcher-18) Problem while trying to set User part on a clones response for a P2P call, java.lang.NullPointerException
20:03:12,010 INFO [gov.nist.javax.sip.stack.SIPTransactionStack] (RestComm-akka.actor.default-dispatcher-18) <message
from="192.168.1.19:5082"
to="192.168.1.36:59544"
time="1507593792009"
isSender="true"
transactionId="z9hg4bk-343633-9c13a1f20c317f021deedc6be9930238"
callId="1507593791764"
firstLine="SIP/2.0 200 OK"

jaimecasero · 2017-10-10T10:09:04Z

een:gov.nist.javax.sip.stack.SIPDialog@303fc921lastAckReceived is null -- returning false
20:31:23,132 ERROR [org.restcomm.connect.ussd.interpreter.UssdInterpreter] (RestComm-akka.actor.default-dispatcher-57) null: java.lang.NullPointerException
at org.restcomm.connect.ussd.interpreter.UssdInterpreter.onReceive(UssdInterpreter.java:549) [restcomm-connect.ussd-8.2.1-51.jar:8.2.1-51]
at akka.actor.UntypedActor$$anonfun$receive$1.applyOrElse(UntypedActor.scala:159) [akka-actor_2.10-2.1.2.jar:]
at akka.actor.ActorCell.receiveMessage(ActorCell.scala:425) [akka-actor_2.10-2.1.2.jar:]
at akka.actor.ActorCell.invoke(ActorCell.scala:386) [akka-actor_2.10-2.1.2.jar:]
at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:230) [akka-actor_2.10-2.1.2.jar:]
at akka.dispatch.Mailbox.run(Mailbox.scala:212) [akka-actor_2.10-2.1.2.jar:]
at akka.dispatch.ForkJoinExecutorConfigurator$MailboxExecutionTask.exec(AbstractDispatcher.scala:506) [akka-actor_2.10-2.1.2.jar:]
at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:262) [scala-library-2.10.1.jar:]
at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:975) [scala-library-2.10.1.jar:]
at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1478) [scala-library-2.10.1.jar:]
at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:104) [scala-library-2.10.1.jar:]

this is realted to RCML not found, already fixed in another issue

jaimecasero · 2017-10-10T10:40:42Z

6:33:38,674 DEBUG [gov.nist.javax.sip.parser.NioPipelineParser] (pool-AffinityJAIN-thread-8) dispatch task done on SIP/2.0 200 OK^M
Call-ID: [email protected]^M
CSeq: 1 MESSAGE^M
From: sip:[email protected]:37110;registering_acc=192.168.1.19;tag=47501098_ceebeb5f_57a5b08a_45c41d18^M
To: sip:[email protected]:58505;tag=1507631618642^M
Max-Forwards: 70^M
Via: SIP/2.0/WS 192.168.1.19:5082;branch=z9hG4bK45c41d18_57a5b08a_ced077c4-efad-4a30-976f-e2dd3778a572;rport^M
Content-Type: text/plain^M
Contact: sip:[email protected]:58505;transport=ws^M
Content-Length: 0^M
^M

06:33:38,693 ERROR [org.restcomm.connect.sms.SmsService] (RestComm-akka.actor.default-dispatcher-16) null: java.lang.NullPointerException
at org.restcomm.connect.sms.SmsService.response(SmsService.java:434) [restcomm-connect.sms-8.2.1-51.jar:8.2.1-51]
at org.restcomm.connect.sms.SmsService.onReceive(SmsService.java:412) [restcomm-connect.sms-8.2.1-51.jar:8.2.1-51]
at akka.actor.UntypedActor$$anonfun$receive$1.applyOrElse(UntypedActor.scala:159) [akka-actor_2.10-2.1.2.jar:]
at akka.actor.ActorCell.receiveMessage(ActorCell.scala:425) [akka-actor_2.10-2.1.2.jar:]
at akka.actor.ActorCell.invoke(ActorCell.scala:386) [akka-actor_2.10-2.1.2.jar:]
at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:230) [akka-actor_2.10-2.1.2.jar:]
at akka.dispatch.Mailbox.run(Mailbox.scala:212) [akka-actor_2.10-2.1.2.jar:]
at akka.dispatch.ForkJoinExecutorConfigurator$MailboxExecutionTask.exec(AbstractDispatcher.scala:506) [akka-actor_2.10-2.1.2.jar:]
at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:262) [scala-library-2.10.1.jar:]
at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:975) [scala-library-2.10.1.jar:]
at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1478) [scala-library-2.10.1.jar:]
at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:104) [scala-library-2.10.1.jar:]

jaimecasero · 2017-10-10T13:47:18Z

i think latest NPE is the most similar to original one:
06:33:38,693 ERROR [org.restcomm.connect.sms.SmsService] (RestComm-akka.actor.default-dispatcher-16) null: java.lang.NullPointerException
at org.restcomm.connect.sms.SmsService.response(SmsService.java:434) [restcomm-connect.sms-

In this case we are assuming an SMSSession akka actor will be in the sipappsession as attribute. There is no check onthat,and the NPE is triggered. A simple Null checking allows to send the 200OK response back to original client.

Why the P2P message scenario is lacking the correpsonding SMSSession is yet to be asnwered. Apparentl the SMSSession will be created on 3 scenarios:

Explicit creation sending CreateSmsSession to SMSService: this happens in a unmber of situations (Sms and BaseVoice interpreters as part of FSM).
when redirectToHostedSmsApp is enabled. This is if the called has a map in the incomingphonenumbers with sms app associated.
// Since toUser is null, try to route the message outside using the SMS Aggregator

As we can see none of these cover the direct P2P message scenario.

My conclusion is that assumption on existing SMSSession without taking into accoutn P2P scenario was made. The simple Null checking plus a brief comment explaining why should be enough to fix this.

jaimecasero · 2017-10-10T13:49:46Z

09:40:39,081 ERROR [stderr] (RestComm-akka.actor.default-dispatcher-80) java.lang.NullPointerException
09:40:39,081 ERROR [stderr] (RestComm-akka.actor.default-dispatcher-80) at org.restcomm.connect.telephony.api.util.B2BUAHelper.forwardResponse(B2BUAHelper.java:513)
09:40:39,082 ERROR [stderr] (RestComm-akka.actor.default-dispatcher-80) at org.restcomm.connect.sms.SmsService.response(SmsService.java:423)
09:40:39,082 ERROR [stderr] (RestComm-akka.actor.default-dispatcher-80) at org.restcomm.connect.sms.SmsService.onReceive(SmsService.java:412)
09:40:39,082 ERROR [stderr] (RestComm-akka.actor.default-dispatcher-80) at akka.actor.UntypedActor$$anonfun$receive$1.applyOrElse(UntypedActor.scala:159)
09:40:39,082 ERROR [stderr] (RestComm-akka.actor.default-dispatcher-80) at akka.actor.ActorCell.receiveMessage(ActorCell.scala:425)
09:40:39,082 ERROR [stderr] (RestComm-akka.actor.default-dispatcher-80) at akka.actor.ActorCell.invoke(ActorCell.scala:386)
09:40:39,082 ERROR [stderr] (RestComm-akka.actor.default-dispatcher-80) at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:230)
09:40:39,082 ERROR [stderr] (RestComm-akka.actor.default-dispatcher-80) at akka.dispatch.Mailbox.run(Mailbox.scala:212)
09:40:39,082 ERROR [stderr] (RestComm-akka.actor.default-dispatcher-80) at akka.dispatch.ForkJoinExecutorConfigurator$MailboxExecutionTask.exec(AbstractDispatcher.scala:506)
09:40:39,082 ERROR [stderr] (RestComm-akka.actor.default-dispatcher-80) at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:262)
09:40:39,082 ERROR [stderr] (RestComm-akka.actor.default-dispatcher-80) at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:975)
09:40:39,082 ERROR [stderr] (RestComm-akka.actor.default-dispatcher-80) at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1478)
09:40:39,083 ERROR [stderr] (RestComm-akka.actor.default-dispatcher-80) at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:104)

reproduced on olympus by sending message burst

this seems to be related to assumption on clonedresponse to have a Contact Header.Apparently MESSAGE request should not have a Contact header and the sipservletsrequest/jainsip stack prevents the header to be added while creating response:
https://github.com/RestComm/sip-servlets/blob/master/sip-servlets-impl/src/main/java/org/mobicents/servlet/sip/message/SipServletRequestImpl.java#L378

References to an existing issue are made there:constraints from Issue 1687 : Contact Header is present in SIP Message where it shouldn't

Under this finding, Null checking over Contact header should be made before attempting to update user uri.

from https://www.ietf.org/rfc/rfc3428.txt:
A 2xx response to a MESSAGE request MUST NOT contain a body. A UAS
MUST NOT insert a Contact header field into a 2xx response.

atsakiridis assigned gvagenas Apr 27, 2016

atsakiridis added the 1. Bug label Apr 27, 2016

atsakiridis added this to the 7.7.0 milestone Apr 27, 2016

gvagenas modified the milestone: 7.7.0 May 13, 2016

atsakiridis added this to the 8.2.0 milestone Mar 14, 2017

gvagenas modified the milestones: George 8.2.0 Sprint 2, 8.2.0 May 2, 2017

gvagenas modified the milestones: George 8.2.0 Sprint 2, George 8.2.0 Sprint 3 May 18, 2017

jaimecasero closed this as completed in 536a1c7 Oct 10, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Restcomm exception prevents 200 OK response to MESSAGE to be sent to message sender #1023

Restcomm exception prevents 200 OK response to MESSAGE to be sent to message sender #1023

atsakiridis commented Apr 27, 2016

atsakiridis commented Mar 14, 2017

gvagenas commented May 6, 2017

atsakiridis commented May 8, 2017

atsakiridis commented May 10, 2017

gvagenas commented May 31, 2017

jaimecasero commented Aug 23, 2017

gvagenas commented Aug 24, 2017

jaimecasero commented Aug 24, 2017

jaimecasero commented Oct 10, 2017

jaimecasero commented Oct 10, 2017

jaimecasero commented Oct 10, 2017

jaimecasero commented Oct 10, 2017 •

edited

Loading

jaimecasero commented Oct 10, 2017

jaimecasero commented Oct 10, 2017 •

edited

Loading

jaimecasero commented Oct 10, 2017 •

edited

Loading

Restcomm exception prevents 200 OK response to MESSAGE to be sent to message sender #1023

Restcomm exception prevents 200 OK response to MESSAGE to be sent to message sender #1023

Comments

atsakiridis commented Apr 27, 2016

atsakiridis commented Mar 14, 2017

gvagenas commented May 6, 2017

atsakiridis commented May 8, 2017

atsakiridis commented May 10, 2017

gvagenas commented May 31, 2017

jaimecasero commented Aug 23, 2017

gvagenas commented Aug 24, 2017

jaimecasero commented Aug 24, 2017

jaimecasero commented Oct 10, 2017

jaimecasero commented Oct 10, 2017

jaimecasero commented Oct 10, 2017

jaimecasero commented Oct 10, 2017 • edited Loading

jaimecasero commented Oct 10, 2017

jaimecasero commented Oct 10, 2017 • edited Loading

jaimecasero commented Oct 10, 2017 • edited Loading

jaimecasero commented Oct 10, 2017 •

edited

Loading

jaimecasero commented Oct 10, 2017 •

edited

Loading

jaimecasero commented Oct 10, 2017 •

edited

Loading