search

RestComm / Restcomm-Connect

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

Sporadically getting '500 Problem to setup the call' #2225

Open atsakiridis opened 7 years ago

atsakiridis commented 7 years ago

When calling demo Apps like +1234/+1235 from web Olympus

I have been getting this for quite a while and I think I now figured out roughly when this occurs, even though it isn't clear what actually causes it. For me whenever I try to reuse an already setup native restcomm installation in MacOS after some time I get this issue when calling any of the Demo Apps.

The first time I extract the zip, for example Restcomm-JBoss-AS7-8.2.0.1240.zip and setup restcomm.conf and advanced.conf as well as Olympus sources to point to correct signaling secure port everything works fine and I can call +1234 with proper audio.

Now if I leave that installation for a couple of days, during which there are potential ip address changes due to DHCP and laptop has slept, then if I come back and fix the ip address in restcomm.conf and run start-restcomm.sh then I consistently get this issue.

The only workaround I have found is to start fresh by unzipping from scratch Restcomm-JBoss-AS7-8.2.0.1240.zip and copying restcomm.conf and advanced.conf. Then everything works fine, until this install is 'invalidated' again after a couple of days. But it's very tedious to do that.

Here's an excerpt of the logs:

isSender="true"
transactionId="z9hg4bk-323832-9bd0093d55624252ffc85056c12f5223"
callId="1497269797180"
firstLine="SIP/2.0 180 Ringing"
>
<![CDATA[SIP/2.0 180 Ringing^M
To: <sip:+1234@192.168.2.3>;tag=46084145_7d0d1279_57a5b08a_8a033db4^M
Via: SIP/2.0/WSS 192.168.2.3:61392;branch=z9hG4bK-323832-9bd0093d55624252ffc85056c12f5223;rport=61392;received=192.168.2.3^M
CSeq: 2 INVITE^M
Call-ID: 1497269797180^M
From: "alice" <sip:alice@192.168.2.3>;tag=1497269797372^M
Server: Restcomm 8.2.0.1240^M
Contact: <sip:192.168.2.3:5083;transport=wss>^M
X-RestComm-CallSid: ID7c7f05e00f4e4d8b96c7bc429583d925-CA820ceeaa1d8847a4ab3f69c814f42796^M
Content-Length: 0^M
^M
]]>
</message>

15:16:37,552 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-9) ********** Call's akka://RestComm/user/$l Current State: "ringing direction: inbound
15:16:37,553 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-9) ********** Call akka://RestComm/user/$l Processing Message: "org.restcomm.connect.telephony.api.GetCallInfo sender : akka://RestComm/user/$k
15:16:37,553 INFO  [org.restcomm.connect.interpreter.VoiceInterpreter] (RestComm-akka.actor.default-dispatcher-9)  ********** VoiceInterpreter's akka://RestComm/user/$k Current State: acquiring call info
, Processing Message: org.restcomm.connect.telephony.api.CallResponse
15:16:37,553 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-9) ********** Call's akka://RestComm/user/$l Current State: "ringing direction: inbound
15:16:37,553 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-9) ********** Call akka://RestComm/user/$l Processing Message: "org.restcomm.connect.commons.patterns.Observe sender : akka://RestComm/user/$k
15:16:37,554 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-9) ********** Call's akka://RestComm/user/$l Current State: "ringing direction: inbound
15:16:37,554 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-9) ********** Call akka://RestComm/user/$l Processing Message: "org.restcomm.connect.commons.patterns.Observe sender : akka://RestComm/user/$k
15:16:37,554 INFO  [org.restcomm.connect.monitoringservice.MonitoringService] (RestComm-akka.actor.default-dispatcher-9) MonitoringService Processing Message: "org.restcomm.connect.commons.patterns.Observing sender : class akka.actor.RepointableActorRef self is terminated: false
15:16:37,554 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-9) ********** Call's akka://RestComm/user/$l Current State: "ringing direction: inbound
15:16:37,554 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-9) ********** Call akka://RestComm/user/$l Processing Message: "org.restcomm.connect.telephony.api.GetCallInfo sender : akka://RestComm/user/$a
15:16:37,554 INFO  [org.restcomm.connect.monitoringservice.MonitoringService] (RestComm-akka.actor.default-dispatcher-9) MonitoringService Processing Message: "org.restcomm.connect.telephony.api.CallResponse sender : class akka.actor.RepointableActorRef self is terminated: false
15:16:37,558 INFO  [org.restcomm.connect.interpreter.VoiceInterpreter] (RestComm-akka.actor.default-dispatcher-9) status callback is null
15:16:37,573 INFO  [org.restcomm.connect.interpreter.VoiceInterpreter] (RestComm-akka.actor.default-dispatcher-7)  ********** VoiceInterpreter's akka://RestComm/user/$k Current State: downloading rcml
, Processing Message: org.restcomm.connect.commons.patterns.Observing
15:16:37,676 WARN  [org.restcomm.connect.http.client.Downloader] (RestComm-akka.actor.default-dispatcher-10) Problem while trying to download RCML java.lang.NullPointerException
15:16:37,677 INFO  [org.restcomm.connect.interpreter.VoiceInterpreter] (RestComm-akka.actor.default-dispatcher-10)  ********** VoiceInterpreter's akka://RestComm/user/$k Current State: downloading rcml
, Processing Message: org.restcomm.connect.http.client.DownloaderResponse
15:16:37,677 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-10) ********** Call's akka://RestComm/user/$l Current State: "ringing direction: inbound
15:16:37,677 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-10) ********** Call akka://RestComm/user/$l Processing Message: "org.restcomm.connect.telephony.api.CallFail sender : akka://RestComm/user/$k
15:16:37,679 INFO  [gov.nist.javax.sip.stack.SIPTransactionStack] (RestComm-akka.actor.default-dispatcher-9) <message
from="192.168.2.3:5083"
to="192.168.2.3:61392"
time="1497269797678"
isSender="true"
transactionId="z9hg4bk-323832-9bd0093d55624252ffc85056c12f5223"
callId="1497269797180"
firstLine="SIP/2.0 500 Problem to setup the call"
>
<![CDATA[SIP/2.0 500 Problem to setup the call^M
To: <sip:+1234@192.168.2.3>;tag=46084145_7d0d1279_57a5b08a_8a033db4^M
Via: SIP/2.0/WSS 192.168.2.3:61392;branch=z9hG4bK-323832-9bd0093d55624252ffc85056c12f5223;rport=61392;received=192.168.2.3^M
CSeq: 2 INVITE^M
Call-ID: 1497269797180^M
From: "alice" <sip:alice@192.168.2.3>;tag=1497269797372^M
Server: Restcomm 8.2.0.1240^M
Contact: <sip:192.168.2.3:5083;transport=wss>^M
Reason: Problem,while,trying,to,download,RCML^M
X-RestComm-CallSid: ID7c7f05e00f4e4d8b96c7bc429583d925-CA820ceeaa1d8847a4ab3f69c814f42796^M
Content-Length: 0^M

Any ideas what might be wrong?

atsakiridis commented 7 years ago

Here's the DEBUG output in case it helps more:

12:35:22,872 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-11) ********** Call's akka://RestComm/user/$l Current State: "ringing direction: inbound
12:35:22,872 DEBUG [org.mobicents.servlet.sip.address.RFC2396UrlDecoder] (RestComm-akka.actor.default-dispatcher-8) uri to decode +1235
12:35:22,872 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-11) ********** Call akka://RestComm/user/$l Processing Message: "org.restcomm.connect.telephony.api.GetCallInfo sender : akka://RestComm/user/$k
12:35:22,873 INFO  [org.restcomm.connect.interpreter.VoiceInterpreter] (RestComm-akka.actor.default-dispatcher-8)  ********** VoiceInterpreter's akka://RestComm/user/$k Current State: acquiring call info
, Processing Message: org.restcomm.connect.telephony.api.CallResponse
12:35:22,873 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-8) ********** Call's akka://RestComm/user/$l Current State: "ringing direction: inbound
12:35:22,873 DEBUG [org.mobicents.servlet.sip.restcomm.dao.CallDetailRecordsDao.getCallDetailRecord] (RestComm-akka.actor.default-dispatcher-11) ooo Using Connection [org.hsqldb.jdbc.JDBCConnection@555784d2]
12:35:22,873 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-8) ********** Call akka://RestComm/user/$l Processing Message: "org.restcomm.connect.commons.patterns.Observe sender : akka://RestComm/user/$k
12:35:22,873 DEBUG [org.mobicents.servlet.sip.restcomm.dao.CallDetailRecordsDao.getCallDetailRecord] (RestComm-akka.actor.default-dispatcher-11) ==>  Preparing: SELECT * FROM "restcomm_call_detail_records" WHERE "sid"=?; 
12:35:22,873 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-8) ********** Call's akka://RestComm/user/$l Current State: "ringing direction: inbound
12:35:22,873 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-8) ********** Call akka://RestComm/user/$l Processing Message: "org.restcomm.connect.commons.patterns.Observe sender : akka://RestComm/user/$k
12:35:22,873 DEBUG [org.mobicents.servlet.sip.address.RFC2396UrlDecoder] (RestComm-akka.actor.default-dispatcher-10) uri to decode bob
12:35:22,874 DEBUG [org.mobicents.servlet.sip.address.RFC2396UrlDecoder] (RestComm-akka.actor.default-dispatcher-10) uri to decode +1235
12:35:22,874 INFO  [org.restcomm.connect.monitoringservice.MonitoringService] (RestComm-akka.actor.default-dispatcher-8) MonitoringService Processing Message: "org.restcomm.connect.commons.patterns.Observing sender : class akka.actor.RepointableActorRef self is terminated: false
12:35:22,874 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-8) ********** Call's akka://RestComm/user/$l Current State: "ringing direction: inbound
12:35:22,874 DEBUG [org.mobicents.servlet.sip.message.SipServletMessageImpl] (RestComm-akka.actor.default-dispatcher-7) Fetching full header name for [Contact] returning [Contact]
12:35:22,874 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-8) ********** Call akka://RestComm/user/$l Processing Message: "org.restcomm.connect.telephony.api.GetCallInfo sender : akka://RestComm/user/$a
12:35:22,874 DEBUG [org.mobicents.servlet.sip.message.SipServletMessageImpl] (RestComm-akka.actor.default-dispatcher-7) Fetching address header for name [Contact]
12:35:22,874 INFO  [org.restcomm.connect.monitoringservice.MonitoringService] (RestComm-akka.actor.default-dispatcher-8) MonitoringService Processing Message: "org.restcomm.connect.telephony.api.CallResponse sender : class akka.actor.RepointableActorRef self is terminated: false
12:35:22,874 DEBUG [org.mobicents.servlet.sip.message.SipServletMessageImpl] (RestComm-akka.actor.default-dispatcher-7) transaction gov.nist.javax.sip.stack.SIPServerTransactionImpl@a1a5427d transactionId = null transactionType false
12:35:22,874 DEBUG [org.mobicents.servlet.sip.message.SipServletMessageImpl] (RestComm-akka.actor.default-dispatcher-7) transaction gov.nist.javax.sip.stack.SIPServerTransactionImpl@a1a5427d transactionId = null transactionType false
12:35:22,874 DEBUG [org.mobicents.servlet.sip.restcomm.dao.CallDetailRecordsDao.getCallDetailRecord] (RestComm-akka.actor.default-dispatcher-11) ==> Parameters: CA36e936233c094cc5ada7e2b7b7911981(String)
12:35:22,874 DEBUG [org.restcomm.connect.monitoringservice.MonitoringService] (RestComm-akka.actor.default-dispatcher-8) New inbound call from: bob  to: +1235
12:35:22,877 DEBUG [org.mobicents.servlet.sip.restcomm.dao.CallDetailRecordsDao.addCallDetailRecord] (RestComm-akka.actor.default-dispatcher-11) ooo Using Connection [org.hsqldb.jdbc.JDBCConnection@1205874e]
12:35:22,878 DEBUG [org.mobicents.servlet.sip.restcomm.dao.CallDetailRecordsDao.addCallDetailRecord] (RestComm-akka.actor.default-dispatcher-11) ==>  Preparing: INSERT INTO "restcomm_call_detail_records" ("sid", "instanceid", "parent_call_sid", "date_created", "date_updated", "account_sid", "recipient", "sender", "phone_number_sid", "status", "start_time", "end_time", "duration", "price", "direction", "answered_by", "api_version", "forwarded_from", "caller_name", "uri", "call_path", "ring_duration", "conference_sid", "muted", "start_conference_on_enter", "end_conference_on_exit", "on_hold", "ms_id") VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); 
12:35:22,878 DEBUG [org.mobicents.servlet.sip.restcomm.dao.CallDetailRecordsDao.addCallDetailRecord] (RestComm-akka.actor.default-dispatcher-11) ==> Parameters: CA36e936233c094cc5ada7e2b7b7911981(String), IDe2d19a876fa845afbb1dd731257686cf(String), null, 2017-07-03 12:35:22.846(Timestamp), 2017-07-03 12:35:22.877(Timestamp), ACae6e420f425248d6a26948c17a9e2acf(String), +1235(String), bob(String), ACae6e420f425248d6a26948c17a9e2acf(String), ringing(String), 2017-07-03 12:35:22.877(Timestamp), null, null, 0.00(String), inbound(String), null, 2012-04-24(String), null, Unknown(String), /2012-04-24/Accounts/ACae6e420f425248d6a26948c17a9e2acf/Calls/CA36e936233c094cc5ada7e2b7b7911981(String), akka://RestComm/user/$l(String), null, null, false(Boolean), null, null, false(Boolean), null
12:35:22,879 INFO  [org.restcomm.connect.interpreter.VoiceInterpreter] (RestComm-akka.actor.default-dispatcher-8) status callback is null
12:35:22,892 INFO  [org.restcomm.connect.interpreter.VoiceInterpreter] (RestComm-akka.actor.default-dispatcher-7)  ********** VoiceInterpreter's akka://RestComm/user/$k Current State: downloading rcml
, Processing Message: org.restcomm.connect.commons.patterns.Observing
12:35:22,892 DEBUG [org.restcomm.connect.http.client.Downloader] (RestComm-akka.actor.default-dispatcher-7) New HttpRequestDescriptor, method: POST URI: https://192.168.2.3:8443/restcomm/demos/hello-world.xml parameters: CallSid=CA36e936233c094cc5ada7e2b7b7911981&InstanceId=IDe2d19a876fa845afbb1dd731257686cf&AccountSid=ACae6e420f425248d6a26948c17a9e2acf&From=bob&To=%2B1235&CallStatus=ringing&ApiVersion=2012-04-24&Direction=inbound&CallerName=null&ForwardedFrom=null&CallTimestamp=2017-07-03T12%3A35%3A22.846%2B03%3A00
12:35:23,003 DEBUG [org.restcomm.connect.http.client.Downloader] (RestComm-akka.actor.default-dispatcher-11) Issue during HTTP request execution: null
12:35:23,003 WARN  [org.restcomm.connect.http.client.Downloader] (RestComm-akka.actor.default-dispatcher-11) Problem while trying to download RCML java.lang.NullPointerException
12:35:23,003 DEBUG [org.mobicents.servlet.sip.message.SipServletMessageImpl] (RestComm-akka.actor.default-dispatcher-8) transaction gov.nist.javax.sip.stack.SIPServerTransactionImpl@a1a5427d transactionId = null transactionType false
12:35:23,003 INFO  [org.restcomm.connect.interpreter.VoiceInterpreter] (RestComm-akka.actor.default-dispatcher-11)  ********** VoiceInterpreter's akka://RestComm/user/$k Current State: downloading rcml
, Processing Message: org.restcomm.connect.http.client.DownloaderResponse
12:35:23,004 DEBUG [org.restcomm.connect.interpreter.VoiceInterpreter] (RestComm-akka.actor.default-dispatcher-11) Download Rcml response succeeded false
12:35:23,004 DEBUG [org.mobicents.servlet.sip.message.SipServletRequestImpl] (RestComm-akka.actor.default-dispatcher-8) setting dialog LocalTag: 50335785_b6b7e7b2_57a5b08a_bd0a9a52
12:35:23,004 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-11) ********** Call's akka://RestComm/user/$l Current State: "ringing direction: inbound
12:35:23,004 DEBUG [org.mobicents.servlet.sip.JainSipUtils] (RestComm-akka.actor.default-dispatcher-8) AppData Transport TLS
12:35:23,004 INFO  [org.restcomm.connect.telephony.Call] (RestComm-akka.actor.default-dispatcher-11) ********** Call akka://RestComm/user/$l Processing Message: "org.restcomm.connect.telephony.api.CallFail sender : akka://RestComm/user/$k
12:35:23,004 DEBUG [org.mobicents.servlet.sip.JainSipUtils] (RestComm-akka.actor.default-dispatcher-8) AppData Transport TLS
12:35:23,004 DEBUG [org.mobicents.servlet.sip.message.SipServletRequestImpl] (RestComm-akka.actor.default-dispatcher-8) We're adding this contact header to our new response: 'Contact: <sip:192.168.2.3:5081;transport=tls>
, transport=TLS
12:35:23,005 DEBUG [org.mobicents.servlet.sip.message.SipServletMessageImpl] (RestComm-akka.actor.default-dispatcher-8) transaction gov.nist.javax.sip.stack.SIPServerTransactionImpl@a1a5427d transactionId = null transactionType false
12:35:23,005 DEBUG [org.mobicents.servlet.sip.message.SipServletMessageImpl] (RestComm-akka.actor.default-dispatcher-8) transaction gov.nist.javax.sip.stack.SIPServerTransactionImpl@a1a5427d transactionId = null transactionType false
12:35:23,005 DEBUG [org.mobicents.servlet.sip.core.session.SipSessionImpl] (RestComm-akka.actor.default-dispatcher-8) setting session creating dialog for this session to gov.nist.javax.sip.stack.SIPDialog@ad0f7128
12:35:23,005 DEBUG [org.mobicents.servlet.sip.core.session.SipSessionImpl] (RestComm-akka.actor.default-dispatcher-8) session creating dialog dialogId c6fbb0b4-da75-1235-4fb4-5f0c5e6480f1:50335785_b6b7e7b2_57a5b08a_bd0a9a52:mbypr0zbn0p7h
12:35:23,005 DEBUG [org.mobicents.servlet.sip.message.SipServletResponseImpl] (RestComm-akka.actor.default-dispatcher-8) original request set to INVITE sips:+1235@192.168.2.3:5081 SIP/2.0
Via: SIP/2.0/TLS 192.168.2.13:50115;branch=z9hG4bKQy0H0e5H9gX9S;rport=50116
atsakiridis commented 7 years ago

@gvagenas I found the issue here. Seems it has to do with the self-signed certificate in the jks and the ip address that got updated due to DHCP. Seems the jks is not automatically regenerated, and then when RC internally tries to retrieve RCML the call probably fails because the trusted jks has a different ip address than the current.

The proposed solution after discussing with @leftyb is to use RESTCOMM_HOSTNAME in restcomm.conf and set it to the hostname, which triggers the jks/cert to be created in a way that hostname is used as CommonName and the ip address not utilized at all in the generation. As long as that hostname is updated in /etc/hosts to point to the right IP address after DHCP changes (which happens in a Mac Laptop by OS automatically) we should be ok.

By the way @gvagenas would be nice if you guys put some WARN logging in place when there's a trust issue when retrieving RCML, so that it's more evident in the RC logs what actually goes wrong instead of generic Problem while trying to download RCML java.lang.NullPointerException. Do you think this makes sense?