Latest (svn) release; unable to place a call (solved)

Discussions about using SIP Sorcery on your own computer/server
Post Reply
Nebukadnezar
Posts: 47
Joined: Tue Aug 10, 2010 1:46 pm

Latest (svn) release; unable to place a call (solved)

Post by Nebukadnezar » Thu Aug 12, 2010 6:00 am

I started with installing the v1.2 release and got that to work. The server I use as target for this software is a standard win2003 server behind a (symmetric NAT) router. Next, I downloaded the source for version v1.2(39246) and compiled that with vs2010. The compiled software worked just like the standard v1.2. Next, I created a new project and updated that through svn (51179), compiled, configured and tested that software. Local softphone registered with that server and the configured voip provider registered as well.
However, making a call does not work.

With v1.2 if get the following (console) response when making a call:

Code: Select all

as (13:40:625): AppServerCore INVITE received, uri=sip:6737xxx@metasip.com:5060, cseq=1.
as (13:40:734): Call not authenticated for 707xxxx@metasip.com, responding with Unauthorised.
as (13:40:937): AppServerCore INVITE received, uri=sip:6737xxx@metasip.com:5060, cseq=2.
as (13:41:046 70xxxx): New call from tcp:192.168.1.5:3399 successfully authenticated by digest.
as (13:41:109): Call Manager processing new call on thread sipcallmanager-processcalls-1 for INVITE to sip:6737xxx@metasip.com:5060.

as (13:41:343 70xxxx): Using dialplan out for Out call to sip:6737xxx@metasip.com:5060.
as (13:41:468 70xxxx): Executing script dial plan for call to 6737xxx.
as (13:41:484): Creating DialPlanExecutingScript number 1 for dialplan execution for script owned by 70xxxx.
as (13:42:640): Dial plan execution starting on thread dialplanscript-1 for 70xxxx.
as (13:44:296 70xxxx): Ruby Common
as (13:44:343 70xxxx): Commencing Dial with: voipplanet.
as (13:44:421 70xxxx): Attempting to locate a provider for call leg: sip:6737xxx@voipplanet.
as (13:44:468 70xxxx): ForkCall commencing call leg to sip:6737xxx@sip3.voipplanet.nl.
as (13:44:531 70xxxx): Switching to sip:6737xxx@sip3.voipplanet.nl:5060 via udp:127.0.0.1:5060.
as (13:44:562 70xxxx): SDP on UAC call had RTP socket mangled from 127.0.0.1:4062 to 212.187.xxx.xxx:4062.
Initialising DNS resolver with operating system DNS server entries.
Lookup queueud for NAPTR sip3.voipplanet.nl, queue size=1, in progress=1.
Thread dnslookup-0 looking up NAPTR sip3.voipplanet.nl.
Sending UDP DNS request to 192.168.1.254:53 for NAPTR sip3.voipplanet.nl..
Resolve time for sip3.voipplanet.nl NAPTR 109.375ms.
Complete event fired for DNS lookup on NAPTR sip3.voipplanet.nl.
Lookup queueud for SRV _sip._udp.sip3.voipplanet.nl, queue size=1, in progress=1.
Thread dnslookup-0 looking up SRV _sip._udp.sip3.voipplanet.nl.
Sending UDP DNS request to 192.168.1.254:53 for SRV _sip._udp.sip3.voipplanet.nl..
Resolve time for _sip._udp.sip3.voipplanet.nl SRV 46.875ms.
 no resource records found for _sip._udp.sip3.voipplanet.nl.
Complete event fired for DNS lookup on SRV _sip._udp.sip3.voipplanet.nl.
Lookup queueud for A sip3.voipplanet.nl, queue size=1, in progress=1.
Thread dnslookup-0 looking up A sip3.voipplanet.nl.
Sending UDP DNS request to 192.168.1.254:53 for A sip3.voipplanet.nl..
Resolved A record for sip3.voipplanet.nl to 84.243.247.100 in 78.125ms.
Complete event fired for DNS lookup on A sip3.voipplanet.nl.
as (13:45:921 70xxxx): Response 407 Proxy Authentication Required for sip:6737xxx@sip3.voipplanet.nl.
as (13:46:031 70xxxx): Information response 100 Trying for sip:6737xxx@sip3.voipplanet.nl.
as (13:46:796 70xxxx): Information response 183 Session Progress for sip:6737xxx@sip3.voipplanet.nl.
as (13:46:812 70xxxx): UAS call progressing with SessionProgress.
as (13:47:812 70xxxx): Cancelling call for sip:6737xxx@metasip.com:5060.
SIPServerUserAgent got cancellation request.
as (13:47:890 70xxxx): Client call cancelled halting dial plan.
as (13:47:921 70xxxx): Dialplan call was terminated by client side due to ClientCancelled.
as (13:47:953 70xxxx): Cancelling all call legs for ForkCall app.
as (13:48:000 70xxxx): Cancelling forwarded call leg, sending CANCEL to sip:6737xxx@sip3.voipplanet.nl.
as (13:48:062 70xxxx): Dial command was halted by cancellation of client call after 3.56s.
DialPlanExecutingScript StopExecution on dialplanscript-1.
as (13:48:203 70xxxx): Dial plan execution completed with normal clearing.
as (13:48:390 70xxxx): Response 487 Request Terminated for sip:6737xxx@sip3.voipplanet.nl.
as (13:48:437): Dial plan finished for 707xxxx, gc memory=6031348, physical memory=81350656, running script count=1.
Executing script dialplanscript-1 removed from running scripts list, running script count=0.
STUNClient attempting to determine public IP from stun.voipplanet.nl.
STUNClient Response to initial STUN message received from 84.243.247.177:3478.
STUNClient Public IP=212.187.xxx.xxx.
With the latest svn a call triggers nothing. I tried the different proxy scripts supplied (and edited the local IP numbers), but it won't work.

I placed some debug messages on the proxyscript.py and an invite was received and sent via:

sys.SendInternal(remoteEndPoint, localEndPoint, appServer.ToString(), req, proxyBranch, m_proxySocketInternal)

from there it went to SIPProxyScriptFacade.cs:

m_sipTransport.SendRequest(dstSIPEndPoint, sipRequest);

and then to SIPTransport.cs

and that is where I lost it completely.

This is the console output from the svn version:

Code: Select all

Starting logging initialisation.
Logging initialised.
SIP App Server starting
SIP App Server Console starting...
pid=3056.
os=Microsoft Windows NT 5.2.3790 Service Pack 2.
current directory=D:\SIP-Compiled-SVN\SIP.
base directory=D:\SIP-Compiled-SVN\SIP\.
 SIPDomainManager added domain: metasip.com.
 added domain alias metasip.com.
 added domain alias metasip.com:5060.
 added domain alias localhost.
 added domain alias localhost:5060.
SIP Proxy daemon starting...
 SIP Proxy monitor sender initialised for 127.0.0.1:10001.
Creating SIP Channel for <socket>*:5060</socket>.
 attempting to create SIP UDP channel for 192.168.1.5:5060.
SIPUDPChannel socket on udp:192.168.1.5:5060 listening started.
SIPUDPChannel listener created 192.168.1.5:5060.
 attempting to create SIP UDP channel for 127.0.0.1:5060.
SIPUDPChannel socket on udp:127.0.0.1:5060 listening started.
SIPUDPChannel listener created 127.0.0.1:5060.
Creating SIP Channel for <socket protocol="tcp">*:5060</socket>.
 attempting to create SIP TCP channel for 192.168.1.5:5060.
SIP TCP Channel listener created 192.168.1.5:5060.
 attempting to create SIP TCP channel for 127.0.0.1:5060.
SIP TCP Channel listener created 127.0.0.1:5060.
SIPCallDispatcherFile loading application server endpoints.
 added app server endpoint udp:192.168.1.5:5065 with a relative priority of 100.
 added app server endpoint udp:127.0.0.1:5065 with a relative priority of 100.
Compiling IronPython script file from D:\SIP-Compiled-SVN\SIP\proxyscript.py.
SIPTCPChannel socket on tcp:192.168.1.5:5060 listening started.
IronPython compilation complete.
SIPUDPChannel socket on udp:127.0.0.1:9001 listening started.
SIPUDPChannel listener created 127.0.0.1:9001.
NATKeepAlive Relay instantiated on 127.0.0.1:9001.
SIP Proxy daemon successfully started.
SIPMonitorDaemon starting...
The SIP Monitor Server was successfully started, loopback port 10001.
Internal notifications hosted service successfully started on http://192.168.1.5:8091/notifications.
SIP Registrar daemon starting...
Monitor channel initialised for 127.0.0.1:10001.
Creating SIP Channel for <sipsocket>127.0.0.1:5001</sipsocket>.
 attempting to create SIP UDP channel for 127.0.0.1:5001.
SIPUDPChannel socket on udp:127.0.0.1:5001 listening started.
SIPUDPChannel listener created 127.0.0.1:5001.
Added useragent config, useragent=fring, expiry=3600s, contact lists=True.
Added useragent config, useragent=Nokia, expiry=3600s, contact lists=False.
Added useragent config, useragent=Cisco-CP7960G/8.0, expiry=60s, contact lists=False.
Added useragent config, useragent=.*, expiry=113s, contact lists=True.
SIP Registrar successfully started.
SIP Registration Agent daemon starting...
Monitor channel initialised for 127.0.0.1:10001.
Creating SIP Channel for <sipsocket>127.0.0.1:5002</sipsocket>.
 attempting to create SIP UDP channel for 127.0.0.1:5002.
SIPUDPChannel socket on udp:127.0.0.1:5002 listening started.
SIPUDPChannel listener created 127.0.0.1:5002.
SIPRegistrationAgent thread started with 1 threads.
SIP Registration Agent successfully started.
SIP Notifier Daemon starting...
Monitor channel initialised for 127.0.0.1:10001.
Creating SIP Channel for <sipsocket>127.0.0.1:5003</sipsocket>.
 attempting to create SIP UDP channel for 127.0.0.1:5003.
SIPUDPChannel socket on udp:127.0.0.1:5003 listening started.
SIPUDPChannel listener created 127.0.0.1:5003.
SIP Notifier Daemon successfully started.
SSHServerDaemon starting...
Initiating SIP Application Server Agent.
Creating SIP Channel for <socket>127.0.0.1:5065</socket>.
 attempting to create SIP UDP channel for 127.0.0.1:5065.
SIPUDPChannel socket on udp:127.0.0.1:5065 listening started.
SIPUDPChannel listener created 127.0.0.1:5065.
Ruby common script file changed, reloading ruby common script.
Starting file watch on Ruby Common Script D:\SIP-Compiled-SVN\SIP\dialplan-common.rby.
Provisioning hosted service successfully started on http://192.168.1.5:8080/provisioning.svc.
CrossDomain hosted service successfully started on http://192.168.1.5:8080/.
CallManager hosted service successfully started on http://192.168.1.5:8080/callmanager.svc.
SIPNotificationsService hosted service successfully started on http://192.168.1.5:8080/notificationspull.svc.
SIPTCPChannel socket on tcp:127.0.0.1:5060 listening started.
SIPProxyDaemon STUN client started.
STUNClient attempting to determine public IP from stun.voipplanet.nl.
STUNClient Response to initial STUN message received from 84.243.247.177:3478.
STUNClient Public IP=212.187.xxx.xxx.

[color=#FF0000]Registration softphone (3CXPhone)[/color]

SIP TCP Channel connection accepted from 192.168.1.5:3429.
re: Register queued for sip:70xxxx@metasip.com:5060.
re: Authentication failed stale nonce for realm=metasip.com, username=70xxxx, uri=sip:metasip.com:5060, nonce=20157443331561535963, method=REGISTER.
re: Authentication required for 70xxxx@metasip.com from tcp:192.168.1.5:3429.
re: register result=AuthenticationRequired, time=328.125ms, user=70xxxx.
re: Register queued for sip:70xxxx@metasip.com:5060.
re: Binding expired by client for 70xxxx@metasip.com from tcp:192.168.1.5:3429.
re: Binding update time for 70xxxx@metasip.com took 140.625ms.
re: Registration successful for 70xxxx@metasip.com from tcp:192.168.1.5:3429 (proxy=tcp:192.168.1.5:5060), expiry -1s.
re: register result=Authenticated, time=234.375ms, user=70xxxx.
TCP socket from 192.168.1.5:3429 disconnected.
SIP TCP Channel connection accepted from 192.168.1.5:3433.
re: Register queued for sip:70xxxx@metasip.com:5060.
re: Authentication required for 70xxxx@metasip.com from tcp:192.168.1.5:3433.
re: register result=AuthenticationRequired, time=46.875ms, user=70xxxx.
re: Register queued for sip:70xxxx@metasip.com:5060.
re: New binding request for 70xxxx@metasip.com from tcp:192.168.1.5:3433, expiry requested 120s granted 113s.
re: Binding update time for 70xxxx@metasip.com took 156.25ms.
re: Registration successful for 70xxxx@metasip.com from tcp:192.168.1.5:3433 (proxy=tcp:192.168.1.5:5060), expiry 113s.
re: register result=Authenticated, time=234.375ms, user=70xxxx.
re: Register queued for sip:70xxxx@metasip.com:5060.
re: Binding expired by client for 70xxxx@metasip.com from tcp:192.168.1.5:3433.
re: Binding update time for 70xxxx@metasip.com took 46.875ms.
re: Registration successful for 70xxx@metasip.com from tcp:192.168.1.5:3433 (proxy=tcp:192.168.1.5:5060), expiry -1s.
re: register result=Authenticated, time=125ms, user=70xxxx.
re: Register queued for sip:70xxxx@metasip.com:5060.
re: Authentication required for 70xxxx@metasip.com from tcp:192.168.1.5:3433.
re: register result=AuthenticationRequired, time=46.875ms, user=70xxxx.
re: Register queued for sip:70xxxx@metasip.com:5060.
re: New binding request for 70xxxx@metasip.com from tcp:192.168.1.5:3433, expiry requested 120s granted 113s.
re: Binding update time for 70xxxx@metasip.com took 46.875ms.
re: Registration successful for 70xxxx@metasip.com from tcp:192.168.1.5:3433 (proxy=tcp:192.168.1.5:5060), expiry 113s.
re: register result=Authenticated, time=109.375ms, user=70xxxx.
Removing NAT keep-alive job for binding socket tcp:192.168.1.5:3433.

[color=#FF0000]This is where ia place a call (and nothing happens) [/color]
I figured out that the IP numbers in proxyscript.py all needed to refer to localhost (127.0.0.1). But then i got the next message:

Code: Select all

as (36:56:671 70788): Using dialplan out for Out call to sip:6737931@metasip.internal:5060.
as (36:56:796 70788): Executing script dial plan for call to 6737931.
as (36:56:875 70788): Error executing script dialplan for 6737931. Invalid argument value
Parameter name: ScriptRuntimeSetup must have at least one LanguageSetup
as (36:56:921 70788): UAS call failed with a response status of 500 and Dial plan exception starting script.
Don't know why this is but i fixed it by placing a reference to a app.config file in DialPlanExecutingScript.cs:

Code: Select all

        public string rubyPath = @"d:\\sip-compiled-svn\\sip\\app.config";

        public Action Cleanup;  // A function delegate that will be called when the script is completed to allow any cleanup actions to take place.

        public DialPlanExecutingScript(SIPMonitorLogDelegate logDelegate)
        {
            ScriptNumber = ++ScriptCounter % Int32.MaxValue;
            Id = Guid.NewGuid();

            var setup = ScriptRuntimeSetup.ReadConfiguration(rubyPath);
            var scriptRuntime = Ruby.CreateRuntime(setup);
            DialPlanScriptEngine = Ruby.GetEngine(scriptRuntime);

            //DialPlanScriptEngine = Ruby.CreateEngine();


            DialPlanScriptScope = DialPlanScriptEngine.CreateScope();

            LogDelegate = logDelegate;
        }
and the app.config:

Code: Select all

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="microsoft.scripting" 
             type="Microsoft.Scripting.Hosting.Configuration.Section, Microsoft.Scripting, Version=1.0.0.0, Culture=neutral, publicKeyToken=31bf3856ad364e35"     
             requirePermission="false" />
  </configSections>
  <microsoft.scripting>
    <languages>
      <language names="IronPython,Python,py" 
                extensions=".py" 
                displayName="IronPython 2.0 Beta" 
                type="IronPython.Runtime.PythonContext,IronPython, Version=2.0.0.5000, Culture=neutral, publicKeyToken=31bf3856ad364e35" />
      <language names="IronRuby;Ruby,rb"
                extensions=".rb"
                displayName="IronRuby 1.0 Alpha"
                type="IronRuby.Runtime.RubyContext, IronRuby, Version=1.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"/>
    </languages>
  </microsoft.scripting>
</configuration
also the:
<DialPlanEngineImpersonationUsername value="" />
<DialPlanEngineImpersonationPassword value="" />

need to contain acount credentials of an account with appropriate rights:

Thats it! Now it works!

Post Reply