search

RestComm / Restcomm-Connect

The Open Source Cloud Communications Platform
http://www.restcomm.com/
GNU Affero General Public License v3.0
244 stars 215 forks source link

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

Closed atsakiridis closed 7 years ago

atsakiridis commented 8 years ago

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 commented 7 years ago

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

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

gvagenas commented 7 years ago

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

The details for the tests I did are the following:

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 commented 7 years ago

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 commented 7 years ago

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

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

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 commented 7 years ago

@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 commented 7 years ago

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 commented 7 years ago

@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 commented 7 years ago

@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 commented 7 years ago

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

jaimecasero commented 7 years ago

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

jaimecasero commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

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: 4f7b92c6f55ce0a6a0023d6a17c82536@192.168.1.19^M CSeq: 1 MESSAGE^M From: sip:bob@192.168.1.38:37110;registering_acc=192.168.1.19;tag=47501098_ceebeb5f_57a5b08a_45c41d18^M To: sip:alice@192.168.1.36: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:alice@192.168.1.36: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 commented 7 years ago

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:

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 commented 7 years ago

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.