need help. Cannot get registered in local SS

Discussions about using SIP Sorcery on your own computer/server
jamesliu0327
Posts: 23
Joined: Sat Sep 19, 2009 3:12 am

Post by jamesliu0327 » Sun Nov 15, 2009 2:36 am

Here is my sipproviders.xml. Can you look at if something is wrong?

<sipproviders>
<sipprovider>
<id>f39e90ac-24c4-414f-97e6-9adf0c795b41</id>
<owner>username</owner>
<providername>blueface</providername>
<providerusername>test</providerusername>
<providerpassword>password</providerpassword>
<providerserver>sip:sip.blueface.ie</providerserver>
<providerauthusername></providerauthusername>
<provideroutboundproxy></provideroutboundproxy>
<providerfrom></providerfrom>
<providercustomheader></providercustomheader>
<registercontact>sip:username@10.0.0.100</registercontact>
<registerexpiry>3600</registerexpiry>
<registerserver></registerserver>
<registerrealm></registerrealm>
<registerenabled>True</registerenabled>
<registerenabledadmin>True</registerenabledadmin>
<registerdisabledreason></registerdisabledreason>
<inserted>2009-11-13T20:51:39.4843750-07:00</inserted>
<lastupdate>2009-11-13T20:51:39.4843750-07:00</lastupdate>
</sipprovider>
<sipprovider>
<id>b42816c2-6649-4a55-8506-0cbc334ccf08</id>
<owner>jamesliu</owner>
<providername>gizmo5</providername>
<providerusername>17473415263</providerusername>
<providerpassword>xxxx</providerpassword>
<providerserver>sip:proxy01.sipphone.com</providerserver>
<providerauthusername></providerauthusername>
<provideroutboundproxy></provideroutboundproxy>
<providerfrom></providerfrom>
<providercustomheader></providercustomheader>
<registercontact>sip:jamesliu@fireside.getmyip.com</registercontact>
<registerexpiry>110</registerexpiry>
<registerserver></registerserver>
<registerrealm></registerrealm>
<registerenabled>True</registerenabled>
<registerenabledadmin>True</registerenabledadmin>
<registerdisabledreason></registerdisabledreason>
<inserted>2009-11-13T20:55:54.0156250-07:00</inserted>
<lastupdate>2009-11-13T20:55:54.0156250-07:00</lastupdate>
</sipprovider>
<sipprovider>
<id>2bb28e6b-047f-4d01-a7e8-11b81750e555</id>
<owner>jamesliu</owner>
<providername>sipgate</providername>
<providerusername>3006484e2</providerusername>
<providerpassword>xxxx</providerpassword>
<providerserver>sip:sipgate.com</providerserver>
<providerauthusername></providerauthusername>
<provideroutboundproxy></provideroutboundproxy>
<providerfrom></providerfrom>
<providercustomheader></providercustomheader>
<registercontact>sip:jamesliu@fireside.getmyip.com</registercontact>
<registerexpiry>60</registerexpiry>
<registerserver></registerserver>
<registerrealm></registerrealm>
<registerenabled>True</registerenabled>
<registerenabledadmin>True</registerenabledadmin>
<registerdisabledreason></registerdisabledreason>
<inserted>2009-11-14T16:58:08.7187500Z</inserted>
<lastupdate>2009-11-14T16:58:08.7187500Z</lastupdate>
</sipprovider>
</sipproviders>



Yes. I am using a ATA, which a old suncrocket ATA, Innomedia 6328....

Here I copied some line from root.log, which includes at least one BYE signal. Can you look at if it helps...


2009-11-14 19:26:33,234 [3] DEBUG sipsporcery-app [(null)] - pid=3064.
2009-11-14 19:26:33,234 [3] DEBUG sipsporcery-app [(null)] - os=Microsoft Windows NT 5.1.2600 Service Pack 3.
2009-11-14 19:26:33,234 [3] DEBUG sipsporcery-app [(null)] - current directory=C:\temp\sipsorcery-v1.1.
2009-11-14 19:26:33,265 [3] DEBUG sipsorcery [(null)] - 2 SIPSorcery.SIP.App.SIPAccount assets loaded from XML record set.
2009-11-14 19:26:33,265 [3] DEBUG sipsorcery [(null)] - Starting file watch on C:\Temp\sipsorcery-v1.1\xmlconfig and sipaccounts.xml.
2009-11-14 19:26:33,281 [3] DEBUG sipsorcery [(null)] - 2 SIPSorcery.SIP.App.SIPDialPlan assets loaded from XML record set.
2009-11-14 19:26:33,281 [3] DEBUG sipsorcery [(null)] - Starting file watch on C:\Temp\sipsorcery-v1.1\xmlconfig and sipdialplans.xml.
2009-11-14 19:26:33,296 [3] DEBUG sipsorcery [(null)] - 3 SIPSorcery.SIP.App.SIPProvider assets loaded from XML record set.
2009-11-14 19:26:33,296 [3] DEBUG sipsorcery [(null)] - Starting file watch on C:\Temp\sipsorcery-v1.1\xmlconfig and sipproviders.xml.
2009-11-14 19:26:33,312 [3] DEBUG sipsorcery [(null)] - loaded SIPProviderBinding for jamesliu and and binding sip:jamesliu@fireside.getmyip.com;rinstance=137659.
2009-11-14 19:26:33,312 [3] DEBUG sipsorcery [(null)] - loaded SIPProviderBinding for jamesliu and and binding sip:jamesliu@fireside.getmyip.com;rinstance=156022.
2009-11-14 19:26:33,312 [3] DEBUG sipsorcery [(null)] - 2 SIPSorcery.SIP.App.SIPProviderBinding assets loaded from XML record set.
2009-11-14 19:26:33,312 [3] DEBUG sipsorcery [(null)] - Starting file watch on C:\Temp\sipsorcery-v1.1\xmlconfig and sipproviderbindings.xml.
2009-11-14 19:26:33,328 [3] DEBUG sipsorcery [(null)] - Starting file watch on C:\Temp\sipsorcery-v1.1\xmlconfig and sipdomains.xml.
2009-11-14 19:26:33,343 [3] DEBUG sipsorcery [(null)] - SIPDomainManager added domain: fireside.getmyip.com.
2009-11-14 19:26:33,343 [3] DEBUG sipsorcery [(null)] - SIPDomainManager wildcard domain set to fireside.getmyip.com.
2009-11-14 19:26:33,343 [3] DEBUG sipsorcery [(null)] - 1 SIPSorcery.SIP.App.SIPRegistrarBinding assets loaded from XML record set.
2009-11-14 19:26:33,343 [3] DEBUG sipsorcery [(null)] - Starting file watch on C:\Temp\sipsorcery-v1.1\xmlconfig and sipregistrarbindings.xml.
2009-11-14 19:26:33,359 [3] DEBUG sipsorcery [(null)] - 20 SIPSorcery.SIP.App.SIPDialogueAsset assets loaded from XML record set.
2009-11-14 19:26:33,359 [3] DEBUG sipsorcery [(null)] - Starting file watch on C:\Temp\sipsorcery-v1.1\xmlconfig and sipdialogues.xml.
2009-11-14 19:26:33,468 [3] DEBUG sipsorcery [(null)] - 379 SIPSorcery.SIP.App.SIPCDRAsset assets loaded from XML record set.
2009-11-14 19:26:33,468 [3] DEBUG sipsorcery [(null)] - Starting file watch on C:\Temp\sipsorcery-v1.1\xmlconfig and sipcdrs.xml.
2009-11-14 19:26:33,484 [3] DEBUG sipsorcery [(null)] - 2 SIPSorcery.CRM.Customer assets loaded from XML record set.
2009-11-14 19:26:33,484 [3] DEBUG sipsorcery [(null)] - Starting file watch on C:\Temp\sipsorcery-v1.1\xmlconfig and customers.xml.
2009-11-14 19:26:33,484 [3] DEBUG sipsorcery [(null)] - 24 SIPSorcery.CRM.CustomerSession assets loaded from XML record set.
2009-11-14 19:26:33,484 [3] DEBUG sipsorcery [(null)] - Starting file watch on C:\Temp\sipsorcery-v1.1\xmlconfig and customersessions.xml.
2009-11-14 19:26:33,484 [3] DEBUG sipsorcery [(null)] - SIP Proxy daemon starting...
2009-11-14 19:26:33,484 [3] DEBUG sipsorcery [(null)] - SIP Proxy monitor sender initialised for 127.0.0.1:10001.
2009-11-14 19:26:33,656 [3] DEBUG sipsorcery [(null)] - Creating SIP Channel for <socket>*:5060</socket>.
2009-11-14 19:26:33,656 [3] DEBUG sipsorcery [(null)] - attempting to create SIP UDP channel for 192.168.1.105:5060.
2009-11-14 19:26:33,656 [3] DEBUG sipsorcery [(null)] - Attempting to obtain random seed from random.org, timeout is 3s.
2009-11-14 19:26:34,625 [3] DEBUG sipsorcery [(null)] - Random seed retrieved from random.org = 929815757.
2009-11-14 19:26:34,640 [3] DEBUG sipsorcery.sip [(null)] - SIPUDPChannel listener created 192.168.1.105:5060.
2009-11-14 19:26:34,640 [3] DEBUG sipsorcery [(null)] - attempting to create SIP UDP channel for 127.0.0.1:5060.
2009-11-14 19:26:34,640 [sipchanneludp-u7434] DEBUG sipsorcery.sip [(null)] - SIPUDPChannel socket on udp:192.168.1.105:5060 listening started.
2009-11-14 19:26:34,640 [sipchanneludp-u8646] DEBUG sipsorcery.sip [(null)] - SIPUDPChannel socket on udp:127.0.0.1:5060 listening started.
2009-11-14 19:26:34,640 [3] DEBUG sipsorcery.sip [(null)] - SIPUDPChannel listener created 127.0.0.1:5060.
2009-11-14 19:26:34,640 [3] DEBUG sipsorcery [(null)] - Creating SIP Channel for <socket protocol="tcp">*:5060</socket>.
2009-11-14 19:26:34,640 [3] DEBUG sipsorcery [(null)] - attempting to create SIP TCP channel for 192.168.1.105:5060.
2009-11-14 19:26:34,640 [3] DEBUG sipsorcery.sip [(null)] - SIP TCP Channel listener created 192.168.1.105:5060.
2009-11-14 19:26:34,640 [3] DEBUG sipsorcery [(null)] - attempting to create SIP TCP channel for 127.0.0.1:5060.
2009-11-14 19:26:34,656 [sipchanneltcp-t6730] DEBUG sipsorcery.sip [(null)] - SIPTCPChannel socket on tcp:127.0.0.1:5060 listening started.
2009-11-14 19:26:34,656 [3] DEBUG sipsorcery.sip [(null)] - SIP TCP Channel listener created 127.0.0.1:5060.
2009-11-14 19:26:34,656 [sipchanneltcp-t3410] DEBUG sipsorcery.sip [(null)] - SIPTCPChannel socket on tcp:192.168.1.105:5060 listening started.
2009-11-14 19:26:34,671 [3] DEBUG sipsorcery [(null)] - Compiling IronPython script file from C:\Temp\sipsorcery-v1.1\proxyscript.py.
2009-11-14 19:26:35,203 [sipchanneludp-u1906] DEBUG sipsorcery.sip [(null)] - SIPUDPChannel socket on udp:127.0.0.1:9001 listening started.
2009-11-14 19:26:35,203 [3] DEBUG sipsorcery.sip [(null)] - SIPUDPChannel listener created 127.0.0.1:9001.
2009-11-14 19:26:35,218 [3] DEBUG natkeepalive [(null)] - NATKeepAlive Relay instantiated on 127.0.0.1:9001.
2009-11-14 19:26:35,218 [3] DEBUG sipsorcery [(null)] - SIP Proxy daemon successfully started.
2009-11-14 19:26:35,218 [3] DEBUG sipsorcery [(null)] - SIPMonitorDaemon starting...
2009-11-14 19:26:35,218 [sipproxy-stunclient] DEBUG sipsorcery [(null)] - SIPProxyDaemon STUN client started.
2009-11-14 19:26:35,218 [sipproxy-stunclient] DEBUG sipsorcery [(null)] - STUNClient attempting to determine public IP from stun01.sipphone.com.
2009-11-14 19:26:35,218 [3] DEBUG sipsorcery [(null)] - Parsing end point from socket string *:11001.
2009-11-14 19:26:35,218 [3] DEBUG sipsorcery [(null)] - Parsing end point from socket string *:4502.
2009-11-14 19:26:35,234 [3] DEBUG sipsorcery [(null)] - Parsing end point from socket string *:4503.
2009-11-14 19:26:35,234 [3] DEBUG sipsorcery [(null)] - The SIP Monitor Server was successfully started, loopback port 10001.
2009-11-14 19:26:35,234 [3] DEBUG sipsorcery [(null)] - Listenng for client monitor connections on 192.168.1.105:11001.
2009-11-14 19:26:35,234 [3] DEBUG sipsorcery [(null)] - Listenng for client monitor connections on 127.0.0.1:11001.
2009-11-14 19:26:35,234 [3] DEBUG sipsorcery [(null)] - Listenng for client monitor connections on 192.168.1.105:4502.
2009-11-14 19:26:35,234 [3] DEBUG sipsorcery [(null)] - Listenng for client monitor connections on 127.0.0.1:4502.
2009-11-14 19:26:35,234 [3] DEBUG sipsorcery [(null)] - Listenng for machine monitor connections on 192.168.1.105:4503.
2009-11-14 19:26:35,234 [3] DEBUG sipsorcery [(null)] - Listenng for machine monitor connections on 127.0.0.1:4503.
2009-11-14 19:26:35,250 [3] DEBUG sipsorcery [(null)] - SIP Registrar daemon starting...
2009-11-14 19:26:35,250 [3] DEBUG sipsorcery [(null)] - Monitor channel initialised for 127.0.0.1:10001.
2009-11-14 19:26:35,250 [3] DEBUG sipsorcery [(null)] - Creating SIP Channel for <sipsocket>127.0.0.1:5001</sipsocket>.
2009-11-14 19:26:35,250 [3] DEBUG sipsorcery [(null)] - attempting to create SIP UDP channel for 127.0.0.1:5001.
2009-11-14 19:26:35,250 [3] DEBUG sipsorcery.sip [(null)] - SIPUDPChannel listener created 127.0.0.1:5001.
2009-11-14 19:26:35,250 [sipchanneludp-u2980] DEBUG sipsorcery.sip [(null)] - SIPUDPChannel socket on udp:127.0.0.1:5001 listening started.
2009-11-14 19:26:35,250 [3] DEBUG sipsorcery [(null)] - Added useragent config, useragent=fring, expiry=3600s, contact lists=True.
2009-11-14 19:26:35,250 [3] DEBUG sipsorcery [(null)] - Added useragent config, useragent=Nokia, expiry=3600s, contact lists=False.
2009-11-14 19:26:35,250 [3] DEBUG sipsorcery [(null)] - Added useragent config, useragent=Cisco-CP7960G/8.0, expiry=60s, contact lists=False.
2009-11-14 19:26:35,250 [3] DEBUG sipsorcery [(null)] - Added useragent config, useragent=.*, expiry=113s, contact lists=True.
2009-11-14 19:26:35,250 [3] DEBUG sipsorcery [(null)] - SIP Registrar successfully started.
2009-11-14 19:26:35,265 [3] DEBUG sipsorcery [(null)] - SIP Registration Agent daemon starting...
2009-11-14 19:26:35,265 [3] DEBUG sipsorcery [(null)] - Monitor channel initialised for 127.0.0.1:10001.
2009-11-14 19:26:35,265 [3] DEBUG sipsorcery [(null)] - Creating SIP Channel for <sipsocket>127.0.0.1:5002</sipsocket>.
2009-11-14 19:26:35,265 [3] DEBUG sipsorcery [(null)] - attempting to create SIP UDP channel for 127.0.0.1:5002.
2009-11-14 19:26:35,265 [sipchanneludp-u4177] DEBUG sipsorcery.sip [(null)] - SIPUDPChannel socket on udp:127.0.0.1:5002 listening started.
2009-11-14 19:26:35,265 [3] DEBUG sipsorcery.sip [(null)] - SIPUDPChannel listener created 127.0.0.1:5002.
2009-11-14 19:26:35,265 [3] DEBUG sipregagent [(null)] - SIPRegistrationAgent thread started.
2009-11-14 19:26:35,265 [3] DEBUG sipsorcery [(null)] - SIP Registration Agent successfully started.
2009-11-14 19:26:35,265 [3] DEBUG sipsporcery-app [(null)] - Initiating SIP Application Server Agent.
2009-11-14 19:26:35,265 [16] DEBUG sipsorcery [(null)] - ProxyMonitor listening for clients on 192.168.1.105:11001.
2009-11-14 19:26:35,265 [3] DEBUG sipsorcery [(null)] - Creating SIP Channel for <socket>127.0.0.1:5065</socket>.
2009-11-14 19:26:35,265 [3] DEBUG sipsorcery [(null)] - attempting to create SIP UDP channel for 127.0.0.1:5065.
2009-11-14 19:26:35,265 [sipchanneludp-u2985] DEBUG sipsorcery.sip [(null)] - SIPUDPChannel socket on udp:127.0.0.1:5065 listening started.
2009-11-14 19:26:35,265 [3] DEBUG sipsorcery.sip [(null)] - SIPUDPChannel listener created 127.0.0.1:5065.
2009-11-14 19:26:35,281 [4] DEBUG sipsorcery [(null)] - STUNClient Response to initial STUN message received from 198.65.166.165:3478.
2009-11-14 19:26:35,281 [4] DEBUG sipsorcery [(null)] - STUNClient Public IP=67.60.56.110.
2009-11-14 19:26:35,296 [18] DEBUG sipsorcery [(null)] - ra: Checking SIP Provider registration for gizmo5.
2009-11-14 19:26:35,312 [18] DEBUG dnslookup [(null)] - Initialising DNS resolver with operating system DNS server entries.
2009-11-14 19:26:35,328 [18] DEBUG dnslookup [(null)] - Lookup queueud for NAPTR proxy01.sipphone.com, queue size=1, in progress=1.
2009-11-14 19:26:35,328 [dnslookup-4] DEBUG dnslookup [(null)] - Thread dnslookup-4 looking up NAPTR proxy01.sipphone.com.
2009-11-14 19:26:35,343 [dnslookup-4] DEBUG sipsorcery [(null)] - Sending UDP DNS request to 192.168.1.1:53 for NAPTR proxy01.sipphone.com..
2009-11-14 19:26:35,437 [dnslookup-4] DEBUG dnslookup [(null)] - Resolve time for proxy01.sipphone.com NAPTR 109.375ms.
2009-11-14 19:26:35,437 [18] DEBUG dnslookup [(null)] - Complete event fired for DNS lookup on NAPTR proxy01.sipphone.com.
2009-11-14 19:26:35,437 [18] DEBUG dnslookup [(null)] - Lookup queueud for SRV _sip._udp.proxy01.sipphone.com, queue size=1, in progress=1.
2009-11-14 19:26:35,437 [dnslookup-3] DEBUG dnslookup [(null)] - Thread dnslookup-3 looking up SRV _sip._udp.proxy01.sipphone.com.
2009-11-14 19:26:35,437 [dnslookup-3] DEBUG sipsorcery [(null)] - Sending UDP DNS request to 192.168.1.1:53 for SRV _sip._udp.proxy01.sipphone.com..
2009-11-14 19:26:35,453 [3] DEBUG dialplanengine [(null)] - Starting file watch on Ruby Common Script C:\Temp\sipsorcery-v1.1 and dialplan-common.rby.
2009-11-14 19:26:35,515 [dnslookup-3] DEBUG dnslookup [(null)] - Resolve time for _sip._udp.proxy01.sipphone.com SRV 78.125ms.
2009-11-14 19:26:35,515 [dnslookup-3] DEBUG dnslookup [(null)] - result: priority=10, weight=10, port=5060, target=proxy01.sipphone.com..
2009-11-14 19:26:35,515 [18] DEBUG dnslookup [(null)] - Complete event fired for DNS lookup on SRV _sip._udp.proxy01.sipphone.com.
2009-11-14 19:26:35,515 [18] DEBUG dnslookup [(null)] - Lookup queueud for A proxy01.sipphone.com., queue size=1, in progress=1.
2009-11-14 19:26:35,515 [dnslookup-1] DEBUG dnslookup [(null)] - Thread dnslookup-1 looking up A proxy01.sipphone.com..
2009-11-14 19:26:35,515 [dnslookup-1] DEBUG sipsorcery [(null)] - Sending UDP DNS request to 192.168.1.1:53 for A proxy01.sipphone.com..
2009-11-14 19:26:35,531 [dnslookup-1] DEBUG dnslookup [(null)] - Resolved A record for proxy01.sipphone.com. to 198.65.166.131 in 15.625ms.
2009-11-14 19:26:35,531 [18] DEBUG dnslookup [(null)] - Complete event fired for DNS lookup on A proxy01.sipphone.com..
2009-11-14 19:26:35,531 [18] DEBUG sipsorcery [(null)] - ra: Sending initial register for jamesliu and gizmo5 to udp:198.65.166.131:5060.
2009-11-14 19:26:35,531 [18] DEBUG sipsorcery [(null)] - ra: Initiating registration for jamesliu on sip:proxy01.sipphone.com.
2009-11-14 19:26:35,593 [18] DEBUG sipsorcery [(null)] - ra: Checking SIP Provider registration for sipgate.
2009-11-14 19:26:35,593 [18] DEBUG dnslookup [(null)] - Lookup queueud for NAPTR sipgate.com, queue size=1, in progress=1.
2009-11-14 19:26:35,593 [dnslookup-3] DEBUG dnslookup [(null)] - Thread dnslookup-3 looking up NAPTR sipgate.com.
2009-11-14 19:26:35,593 [dnslookup-3] DEBUG sipsorcery [(null)] - Sending UDP DNS request to 192.168.1.1:53 for NAPTR sipgate.com..
2009-11-14 19:26:35,593 [3] DEBUG sipsporcery-app [(null)] - Provisioning hosted service successfully started on http://haitaodell:8080/provisioning.svc.
2009-11-14 19:26:35,609 [3] DEBUG sipsporcery-app [(null)] - CrossDomain hosted service successfully started on http://haitaodell:8080/.
2009-11-14 19:26:35,640 [3] DEBUG sipsporcery-app [(null)] - CallManager hosted service successfully started on http://haitaodell:8080/callmanager.
2009-11-14 19:26:35,671 [dnslookup-3] DEBUG dnslookup [(null)] - Resolve time for sipgate.com NAPTR 78.125ms.
2009-11-14 19:26:35,671 [18] DEBUG dnslookup [(null)] - Complete event fired for DNS lookup on NAPTR sipgate.com.
2009-11-14 19:26:35,671 [18] DEBUG dnslookup [(null)] - Lookup queueud for SRV _sip._udp.sipgate.com, queue size=1, in progress=1.
2009-11-14 19:26:35,671 [dnslookup-1] DEBUG dnslookup [(null)] - Thread dnslookup-1 looking up SRV _sip._udp.sipgate.com.
2009-11-14 19:26:35,671 [dnslookup-1] DEBUG sipsorcery [(null)] - Sending UDP DNS request to 192.168.1.1:53 for SRV _sip._udp.sipgate.com..
2009-11-14 19:26:35,765 [28] DEBUG sipsorcery [(null)] - ProxyMonitor listening for clients on 127.0.0.1:11001.
2009-11-14 19:26:35,937 [dnslookup-1] DEBUG dnslookup [(null)] - Resolve time for _sip._udp.sipgate.com SRV 265.625ms.
2009-11-14 19:26:35,937 [dnslookup-1] DEBUG dnslookup [(null)] - result: priority=0, weight=0, port=5060, target=sipgate.com..
2009-11-14 19:26:35,937 [18] DEBUG dnslookup [(null)] - Complete event fired for DNS lookup on SRV _sip._udp.sipgate.com.
2009-11-14 19:26:35,937 [18] DEBUG dnslookup [(null)] - Lookup queueud for A sipgate.com., queue size=1, in progress=1.
2009-11-14 19:26:35,953 [dnslookup-0] DEBUG dnslookup [(null)] - Thread dnslookup-0 looking up A sipgate.com..
2009-11-14 19:26:35,953 [dnslookup-0] DEBUG sipsorcery [(null)] - Sending UDP DNS request to 192.168.1.1:53 for A sipgate.com..
2009-11-14 19:26:35,953 [dnslookup-0] DEBUG dnslookup [(null)] - Resolved A record for sipgate.com. to 204.155.28.10 in 0ms.
2009-11-14 19:26:35,953 [18] DEBUG dnslookup [(null)] - Complete event fired for DNS lookup on A sipgate.com..
2009-11-14 19:26:35,953 [18] DEBUG sipsorcery [(null)] - ra: Sending initial register for jamesliu and sipgate to udp:204.155.28.10:5060.
2009-11-14 19:26:35,953 [18] DEBUG sipsorcery [(null)] - ra: Initiating registration for jamesliu on sip:sipgate.com.
2009-11-14 19:26:36,265 [29] DEBUG sipsorcery [(null)] - ProxyMonitor listening for clients on 192.168.1.105:4502.
2009-11-14 19:26:36,593 [sipchanneludp-u8646] DEBUG sipproxy [(null)] - GotRequest processing time=1015.63ms, script time=1015.63.
2009-11-14 19:26:36,687 [sipchanneludp-u7434] DEBUG sipproxy [(null)] - GotResponse processing time=46.88ms, script time=46.88.
2009-11-14 19:26:36,750 [sipchanneludp-u4177] DEBUG sipsorcery [(null)] - ra: Contact successfully registered for jamesliu on sip:sipgate.com, expiry 60s.
2009-11-14 19:26:36,765 [30] DEBUG sipsorcery [(null)] - ProxyMonitor listening for clients on 127.0.0.1:4502.
2009-11-14 19:26:36,781 [sipchanneludp-u4177] DEBUG sipsorcery [(null)] - ra: Contact successfully registered for jamesliu on sip:proxy01.sipphone.com, expiry 110s.
2009-11-14 19:26:37,265 [31] DEBUG sipsorcery [(null)] - SIPMonitorMediator listening for machine connections on 192.168.1.105:4503.
2009-11-14 19:26:37,781 [32] DEBUG sipsorcery [(null)] - SIPMonitorMediator listening for machine connections on 127.0.0.1:4503.
2009-11-14 19:26:38,265 [sipregistrar-expirebindings] DEBUG sipsorcery [(null)] - re: Deleting expired binding for jamesliu@fireside.getmyip.com and sip:jamesliu@192.168.1.149:5060, last register 19:26:12.
2009-11-14 19:26:38,265 [sipregistrar-expirebindings] DEBUG sipsorcery [(null)] - SIPAssetsXMLPersistor attempting to delete bcbdfb40-e22b-430a-85f2-b371d822155b type SIPSorcery.SIP.App.SIPRegistrarBinding.
2009-11-14 19:27:14,421 [sipchanneludp-u7434] DEBUG sipproxy [(null)] - GotRequest processing time=31.25ms, script time=31.25.
2009-11-14 19:27:14,453 [siptransport-receive] DEBUG dialplan [(null)] - as (27:14:453 jamesliu): Matching dialogue found for BYE to sip:67.60.56.110:5060 from udp:127.0.0.1:5060.
2009-11-14 19:27:14,500 [siptransport-receive] DEBUG sipsorcery [(null)] - SIPAssetsXMLPersistor attempting to delete 17c28f35-16e8-4bf3-a18e-ec52d2ba2f76 type SIPSorcery.SIP.App.SIPDialogueAsset.
2009-11-14 19:27:14,500 [siptransport-receive] DEBUG sipsorcery [(null)] - SIPAssetsXMLPersistor attempting to delete 1907659b-451f-4375-acdc-8aca4daab6f3 type SIPSorcery.SIP.App.SIPDialogueAsset.
2009-11-14 19:27:14,531 [sipchanneludp-u8646] DEBUG sipproxy [(null)] - GotRequest processing time=31.25ms, script time=31.25.
2009-11-14 19:27:18,406 [sipchanneludp-u2980] DEBUG sipsorcery [(null)] - re: Register queued for sip:jamesliu@192.168.1.105.
2009-11-14 19:27:18,437 [sipregistrar-core2] DEBUG sipsorcery [(null)] - re: Authentication required for sip:jamesliu@fireside.getmyip.com from udp:127.0.0.1:5060.
2009-11-14 19:27:18,437 [sipregistrar-core2] DEBUG sipsorcery [(null)] - re: register result=AuthenticationRequired, time=16ms, user=jamesliu.
2009-11-14 19:27:18,546 [sipchanneludp-u2980] DEBUG sipsorcery [(null)] - re: Register queued for sip:jamesliu@192.168.1.105.
2009-11-14 19:27:18,562 [sipregistrar-core2] DEBUG sipsorcery [(null)] - re: New binding request for jamesliu@fireside.getmyip.com from udp:192.168.1.105:6960, expiry requested 3600s granted 113s.
2009-11-14 19:27:18,578 [sipregistrar-core2] DEBUG sipsorcery [(null)] - re: Binding database add time for jamesliu@fireside.getmyip.com took 0ms.
2009-11-14 19:27:18,578 [sipregistrar-core2] DEBUG sipsorcery [(null)] - re: Binding update time for sip:jamesliu@fireside.getmyip.com took 16ms.
2009-11-14 19:27:18,593 [sipregistrar-core2] DEBUG sipsorcery [(null)] - re: Registration successful for sip:jamesliu@fireside.getmyip.com from udp:192.168.1.105:6960 (proxy=udp:192.168.1.105:5060), expiry 113s.
2009-11-14 19:27:18,593 [sipregistrar-core2] DEBUG sipsorcery [(null)] - re: register result=Authenticated, time=47ms, user=jamesliu.
2009-11-14 19:27:20,156 [sipchanneludp-u2980] DEBUG sipsorcery [(null)] - re: Register queued for sip:jamesliu@192.168.1.105.
2009-11-14 19:27:20,156 [sipregistrar-core1] DEBUG sipsorcery [(null)] - re: Authentication required for sip:jamesliu@fireside.getmyip.com from udp:127.0.0.1:5060.
2009-11-14 19:27:20,171 [sipregistrar-core1] DEBUG sipsorcery [(null)] - re: register result=AuthenticationRequired, time=16ms, user=jamesliu.
2009-11-14 19:27:20,171 [sipchanneludp-u2980] DEBUG sipsorcery [(null)] - re: Register queued for sip:jamesliu@192.168.1.105.
2009-11-14 19:27:20,187 [sipregistrar-core3] DEBUG sipsorcery [(null)] - re: New binding request for jamesliu@fireside.getmyip.com from udp:192.168.1.149:5060, expiry requested 85s granted 85s.
2009-11-14 19:27:20,187 [sipregistrar-core3] DEBUG sipsorcery [(null)] - re: Binding database add time for jamesliu@fireside.getmyip.com took 0ms.
2009-11-14 19:27:20,187 [sipregistrar-core3] DEBUG sipsorcery [(null)] - re: Binding update time for sip:jamesliu@fireside.getmyip.com took 0ms.
2009-11-14 19:27:20,203 [sipregistrar-core3] DEBUG sipsorcery [(null)] - re: Registration successful for sip:jamesliu@fireside.getmyip.com from udp:192.168.1.149:5060 (proxy=udp:192.168.1.105:5060), expiry 85s.
2009-11-14 19:27:20,203 [sipregistrar-core3] DEBUG sipsorcery [(null)] - re: register result=Authenticated, time=31ms, user=jamesliu.
2009-11-14 19:27:20,281 [sipchanneludp-u7434] ERROR sipsorcery.sip [(null)] - Error parsing SIP header f:. The SIP From header was invalid.
2009-11-14 19:27:25,406 [siptransport-receive] DEBUG dialplan [(null)] - as (27:25:406): AppServerCore INVITE received, uri=sip:8003333474@192.168.1.105, cseq=1.
2009-11-14 19:27:25,421 [sipcallmanager-processcalls-2] DEBUG dialplan [(null)] - as (27:25:421): Call not authenticated for jamesliu@fireside.getmyip.com, responding with Unauthorised.
2009-11-14 19:27:25,546 [siptransport-receive] DEBUG dialplan [(null)] - as (27:25:546): AppServerCore INVITE received, uri=sip:8003333474@192.168.1.105, cseq=2.
2009-11-14 19:27:25,562 [sipcallmanager-processcalls-1] DEBUG dialplan [(null)] - as (27:25:562 jamesliu): New call from udp:192.168.1.105:6960 successfully authenticated by digest.
2009-11-14 19:27:25,578 [sipcallmanager-processcalls-1] DEBUG dialplan [(null)] - as (27:25:578): Call Manager processing new call on thread sipcallmanager-processcalls-1 for sip:8003333474@192.168.1.105.
2009-11-14 19:27:25,593 [sipcallmanager-processcalls-1] DEBUG dialplan [(null)] - as (27:25:593 jamesliu): Using dialplan default for Out call to sip:8003333474@192.168.1.105.
2009-11-14 19:27:25,609 [sipcallmanager-processcalls-1] DEBUG dialplan [(null)] - as (27:25:609 jamesliu): Executing script dial plan for call to sip:8003333474@192.168.1.105.
2009-11-14 19:27:25,609 [sipcallmanager-processcalls-1] DEBUG dialplan [(null)] - as (27:25:609): Creating DialPlanExecutingScript number 1 for dialplan execution for script owned by jamesliu.
2009-11-14 19:27:25,625 [sipcallmanager-processcalls-1] DEBUG dialplanengine [(null)] - Incrementing dial plan execution count for default@jamesliu, currently=0.
2009-11-14 19:27:25,625 [sipcallmanager-processcalls-1] DEBUG dialplanengine [(null)] - Incrementing customer execution count for jamesliu, currently=0.
2009-11-14 19:27:25,625 [dialplanscript-1] DEBUG dialplan [(null)] - as (27:25:625): Dial plan execution starting on thread dialplanscript-1 for jamesliu.
2009-11-14 19:27:26,156 [dialplanscript-1] DEBUG dialplan [(null)] - as (27:26:156 jamesliu): Commencing Dial with: 18003333474@gizmo5.
2009-11-14 19:27:26,171 [dialplanscript-1] DEBUG dialplan [(null)] - as (27:26:171 jamesliu): Attempting to locate a provider for call leg: sip:18003333474@gizmo5.
2009-11-14 19:27:26,171 [dialplanscript-1] DEBUG dialplan [(null)] - as (27:26:171 jamesliu): ForkCall commencing call leg to sip:18003333474@proxy01.sipphone.com.
2009-11-14 19:27:26,187 [forkcall-192726-100] DEBUG dialplan [(null)] - as (27:26:187 jamesliu): Switching to sip:18003333474@proxy01.sipphone.com:5060 via udp:127.0.0.1:5060.
2009-11-14 19:27:26,203 [forkcall-192726-100] DEBUG dialplan [(null)] - as (27:26:203 jamesliu): SDP on UAC call had RTP socket mangled from 192.168.1.105:6956 to 67.60.56.110:6956.
2009-11-14 19:27:26,593 [siptransport-receive] DEBUG dialplan [(null)] - as (27:26:593 jamesliu): Information response 100 Giving a try for sip:18003333474@proxy01.sipphone.com.
2009-11-14 19:27:26,609 [siptransport-receive] DEBUG dialplan [(null)] - as (27:26:609 jamesliu): Response 200 OK for sip:18003333474@proxy01.sipphone.com.
2009-11-14 19:27:26,609 [siptransport-receive] DEBUG dialplan [(null)] - as (27:26:609 jamesliu): SDP on UAC response had public IP not mangled, RTP socket 130.94.88.70:13538.
2009-11-14 19:27:26,609 [siptransport-receive] DEBUG dialplan [(null)] - as (27:26:609 jamesliu): Cancelling all call legs for ForkCall app.
2009-11-14 19:27:26,609 [dialplanscript-1] DEBUG dialplan [(null)] - as (27:26:609 jamesliu): Answering client call with a response status of 200.
2009-11-14 19:27:26,703 [dialplanscript-1] DEBUG dialplan [(null)] - as (27:26:703 jamesliu): Dial command was successfully answered in 0.5s.
2009-11-14 19:27:26,703 [dialplanscript-1] DEBUG dialplanengine [(null)] - DialPlanExecutingScript StopExecution on dialplanscript-1.
2009-11-14 19:27:26,781 [dialplanengine-monitor] DEBUG dialplan [(null)] - as (27:26:781 jamesliu): Dial plan execution completed with normal clearing.
2009-11-14 19:27:26,796 [dialplanengine-monitor] DEBUG dialplan [(null)] - as (27:26:796): Dial plan finished for jamesliu, gc memory=6631844, physical memory=98881536, running script count=1.
2009-11-14 19:27:26,796 [dialplanengine-monitor] DEBUG dialplanengine [(null)] - Decrementing dial plan execution count for default@jamesliu, currently=1.
2009-11-14 19:27:26,812 [dialplanengine-monitor] DEBUG dialplanengine [(null)] - Decrementing customer execution count for jamesliu, currently=1.
2009-11-14 19:27:26,812 [dialplanengine-monitor] DEBUG dialplanengine [(null)] - Aborting dialplan script thread.
2009-11-14 19:27:26,812 [dialplanengine-monitor] DEBUG dialplanengine [(null)] - Executing script dialplanscript-1 removed from running scripts list, running script count=0.
2009-11-14 19:27:32,000 [18] DEBUG sipsorcery [(null)] - ra: Checking SIP Provider registration for sipgate.
2009-11-14 19:27:32,000 [18] DEBUG sipsorcery [(null)] - ra: Sending initial register for jamesliu and sipgate to udp:204.155.28.10:5060.
2009-11-14 19:27:32,000 [18] DEBUG sipsorcery [(null)] - ra: Initiating registration for jamesliu on sip:sipgate.com.
2009-11-14 19:27:32,125 [sipchanneludp-u4177] DEBUG sipsorcery [(null)] - ra: Contact successfully registered for jamesliu on sip:sipgate.com, expiry 60s.
2009-11-14 19:27:35,312 [sipproxy-stunclient] DEBUG sipsorcery [(null)] - STUNClient attempting to determine public IP from stun01.sipphone.com.
2009-11-14 19:27:35,375 [4] DEBUG sipsorcery [(null)] - STUNClient Response to initial STUN message received from 198.65.166.165:3478.
2009-11-14 19:27:35,375 [4] DEBUG sipsorcery [(null)] - STUNClient Public IP=67.60.56.110.
2009-11-14 19:27:36,281 [sipchanneludp-u7434] ERROR sipsorcery.sip [(null)] - Error parsing SIP header f:. The SIP From header was invalid.
2009-11-14 19:27:52,281 [sipchanneludp-u7434] ERROR sipsorcery.sip [(null)] - Error parsing SIP header f:. The SIP From header was invalid.
2009-11-14 19:28:08,281 [sipchanneludp-u7434] ERROR sipsorcery.sip [(null)] - Error parsing SIP header f:. The SIP From header was invalid.
2009-11-14 19:28:22,109 [18] DEBUG sipsorcery [(null)] - ra: Checking SIP Provider registration for gizmo5.
2009-11-14 19:28:22,109 [18] DEBUG sipsorcery [(null)] - ra: Sending initial register for jamesliu and gizmo5 to udp:198.65.166.131:5060.
2009-11-14 19:28:22,109 [18] DEBUG sipsorcery [(null)] - ra: Initiating registration for jamesliu on sip:proxy01.sipphone.com.
2009-11-14 19:28:22,234 [sipchanneludp-u4177] DEBUG sipsorcery [(null)] - ra: Contact successfully registered for jamesliu on sip:proxy01.sipphone.com, expiry 110s.
2009-11-14 19:28:24,281 [sipchanneludp-u7434] ERROR sipsorcery.sip [(null)] - Error parsing SIP header f:. The SIP From header was invalid.
2009-11-14 19:28:27,125 [18] DEBUG sipsorcery [(null)] - ra: Checking SIP Provider registration for sipgate.
2009-11-14 19:28:27,125 [18] DEBUG sipsorcery [(null)] - ra: Sending initial register for jamesliu and sipgate to udp:204.155.28.10:5060.
2009-11-14 19:28:27,125 [18] DEBUG sipsorcery [(null)] - ra: Initiating registration for jamesliu on sip:sipgate.com.
2009-11-14 19:28:27,234 [sipchanneludp-u4177] DEBUG sipsorcery [(null)] - ra: Contact successfully registered for jamesliu on sip:sipgate.com, expiry 60s.
2009-11-14 19:28:28,203 [sipchanneludp-u2980] DEBUG sipsorcery [(null)] - re: Register queued for sip:jamesliu@192.168.1.105.
2009-11-14 19:28:28,203 [sipregistrar-core3] DEBUG sipsorcery [(null)] - re: Authentication required for sip:jamesliu@fireside.getmyip.com from udp:127.0.0.1:5060.
2009-11-14 19:28:28,203 [sipregistrar-core3] DEBUG sipsorcery [(null)] - re: register result=AuthenticationRequired, time=0ms, user=jamesliu.
2009-11-14 19:28:28,218 [sipchanneludp-u2980] DEBUG sipsorcery [(null)] - re: Register queued for sip:jamesliu@192.168.1.105.
2009-11-14 19:28:28,234 [sipregistrar-core1] DEBUG sipsorcery [(null)] - re: Binding update request for jamesliu@fireside.getmyip.com from udp:192.168.1.149:5060, expiry requested 85s granted 85s.
2009-11-14 19:28:28,234 [sipregistrar-core1] DEBUG sipsorcery [(null)] - re: Binding database update time for jamesliu@fireside.getmyip.com took 0ms.
2009-11-14 19:28:28,234 [sipregistrar-core1] DEBUG sipsorcery [(null)] - re: Binding update time for sip:jamesliu@fireside.getmyip.com took 0ms.
2009-11-14 19:28:28,234 [sipregistrar-core1] DEBUG sipsorcery [(null)] - re: Registration successful for sip:jamesliu@fireside.getmyip.com from udp:192.168.1.149:5060 (proxy=udp:192.168.1.105:5060), expiry 85s.
2009-11-14 19:28:28,250 [sipregistrar-core1] DEBUG sipsorcery [(null)] - re: register result=Authenticated, time=31ms, user=jamesliu.
2009-11-14 19:28:28,281 [sipchanneludp-u7434] ERROR sipsorcery.sip [(null)] - Error parsing SIP header f:. The SIP From header was invalid.
2009-11-14 19:28:35,375 [sipproxy-stunclient] DEBUG sipsorcery [(null)] - STUNClient attempting to determine public IP from stun01.sipphone.com.
2009-11-14 19:28:35,437 [4] DEBUG sipsorcery [(null)] - STUNClient Response to initial STUN message received from 198.65.166.165:3478.
2009-11-14 19:28:35,437 [4] DEBUG sipsorcery [(null)] - STUNClient Public IP=67.60.56.110.
2009-11-14 19:28:44,906 [sipchanneludp-u7434] ERROR sipsorcery.sip [(null)] - Error parsing SIP header f:. The SIP From header was invalid.
2009-11-14 19:28:56,640 [siptransport-receive] DEBUG dialplan [(null)] - as (28:56:640 jamesliu): Matching dialogue found for BYE to sip:67.60.56.110:5060 from udp:127.0.0.1:5060.
2009-11-14 19:28:56,687 [siptransport-receive] DEBUG sipsorcery [(null)] - SIPAssetsXMLPersistor attempting to delete 6518c5d0-41d0-4c68-b83f-f3323dfd4f5f type SIPSorcery.SIP.App.SIPDialogueAsset.
2009-11-14 19:28:56,687 [siptransport-receive] DEBUG sipsorcery [(null)] - SIPAssetsXMLPersistor attempting to delete 3cb19873-3d87-4bcc-87bb-ea920eef2d88 type SIPSorcery.SIP.App.SIPDialogueAsset.
2009-11-14 19:28:59,656 [sipchanneludp-u2980] DEBUG sipsorcery [(null)] - re: Register queued for sip:jamesliu@192.168.1.105.
2009-11-14 19:28:59,656 [sipregistrar-core2] DEBUG sipsorcery [(null)] - re: Binding update request for jamesliu@fireside.getmyip.com from udp:192.168.1.105:6960, expiry requested 3600s granted 113s.
2009-11-14 19:28:59,656 [sipregistrar-core2] DEBUG sipsorcery [(null)] - re: Binding database update time for jamesliu@fireside.getmyip.com took 0ms.
2009-11-14 19:28:59,656 [sipregistrar-core2] DEBUG sipsorcery [(null)] - re: Binding update time for sip:jamesliu@fireside.getmyip.com took 0ms.
2009-11-14 19:28:59,671 [sipregistrar-core2] DEBUG sipsorcery [(null)] - re: Registration successful for sip:jamesliu@fireside.getmyip.com from udp:192.168.1.105:6960 (proxy=udp:192.168.1.105:5060), expiry 113s.
2009-11-14 19:28:59,671 [sipregistrar-core2] DEBUG sipsorcery [(null)] - re: register result=Authenticated, time=16ms, user=jamesliu.
2009-11-14 19:29:00,281 [sipchanneludp-u7434] ERROR sipsorcery.sip [(null)] - Error parsing SIP header f:. The SIP From header was invalid.
2009-11-14 19:29:16,281 [sipchanneludp-u7434] ERROR sipsorcery.sip [(null)] - Error parsing SIP header f:. The SIP From header was invalid.
2009-11-14 19:29:20,875 [sipchanneludp-u7434] DEBUG sipproxy [(null)] - GotRequest processing time=31.25ms, script time=31.25.
2009-11-14 19:29:20,875 [siptransport-receive] DEBUG dialplan [(null)] - as (29:20:875): AppServerCore INVITE received, uri=sip:8003333474@192.168.1.105, cseq=1.
2009-11-14 19:29:20,875 [sipcallmanager-processcalls-1] DEBUG dialplan [(null)] - as (29:20:875): Call not authenticated for jamesliu@fireside.getmyip.com, responding with Unauthorised.
2009-11-14 19:29:20,953 [siptransport-receive] DEBUG dialplan [(null)] - as (29:20:953): AppServerCore INVITE received, uri=sip:8003333474@192.168.1.105, cseq=2.
2009-11-14 19:29:20,953 [sipcallmanager-processcalls-3] DEBUG dialplan [(null)] - as (29:20:953 jamesliu): New call from udp:192.168.1.105:6960 successfully authenticated by digest.
2009-11-14 19:29:20,953 [sipcallmanager-processcalls-3] DEBUG dialplan [(null)] - as (29:20:953): Call Manager processing new call on thread sipcallmanager-processcalls-3 for sip:8003333474@192.168.1.105.
2009-11-14 19:29:20,968 [sipcallmanager-processcalls-3] DEBUG dialplan [(null)] - as (29:20:968 jamesliu): Using dialplan default for Out call to sip:8003333474@192.168.1.105.
2009-11-14 19:29:20,968 [sipcallmanager-processcalls-3] DEBUG dialplan [(null)] - as (29:20:968 jamesliu): Executing script dial plan for call to sip:8003333474@192.168.1.105.
2009-11-14 19:29:20,968 [sipcallmanager-processcalls-3] DEBUG dialplan [(null)] - as (29:20:968): Creating DialPlanExecutingScript number 2 for dialplan execution for script owned by jamesliu.
2009-11-14 19:29:20,968 [sipcallmanager-processcalls-3] DEBUG dialplanengine [(null)] - Incrementing dial plan execution count for default@jamesliu, currently=0.
2009-11-14 19:29:20,968 [sipcallmanager-processcalls-3] DEBUG dialplanengine [(null)] - Incrementing customer execution count for jamesliu, currently=0.
2009-11-14 19:29:20,984 [dialplanscript-2] DEBUG dialplan [(null)] - as (29:20:984): Dial plan execution starting on thread dialplanscript-2 for jamesliu.
2009-11-14 19:29:21,031 [dialplanscript-2] DEBUG dialplan [(null)] - as (29:21:031 jamesliu): Commencing Dial with: 18003333474@gizmo5.
2009-11-14 19:29:21,031 [dialplanscript-2] DEBUG dialplan [(null)] - as (29:21:031 jamesliu): Attempting to locate a provider for call leg: sip:18003333474@gizmo5.
2009-11-14 19:29:21,031 [dialplanscript-2] DEBUG dialplan [(null)] - as (29:21:031 jamesliu): ForkCall commencing call leg to sip:18003333474@proxy01.sipphone.com.
2009-11-14 19:29:21,031 [forkcall-192921-123] DEBUG dialplan [(null)] - as (29:21:031 jamesliu): Switching to sip:18003333474@proxy01.sipphone.com:5060 via udp:127.0.0.1:5060.
2009-11-14 19:29:21,031 [forkcall-192921-123] DEBUG dialplan [(null)] - as (29:21:031 jamesliu): SDP on UAC call had RTP socket mangled from 192.168.1.105:6956 to 67.60.56.110:6956.
2009-11-14 19:29:21,031 [sipchanneludp-u8646] DEBUG dnslookup [(null)] - Lookup queueud for NAPTR proxy01.sipphone.com, queue size=1, in progress=1.
2009-11-14 19:29:21,031 [dnslookup-0] DEBUG dnslookup [(null)] - Thread dnslookup-0 looking up NAPTR proxy01.sipphone.com.
2009-11-14 19:29:21,031 [dnslookup-0] DEBUG sipsorcery [(null)] - Sending UDP DNS request to 192.168.1.1:53 for NAPTR proxy01.sipphone.com..
2009-11-14 19:29:21,171 [dnslookup-0] DEBUG dnslookup [(null)] - Resolve time for proxy01.sipphone.com NAPTR 140.625ms.
2009-11-14 19:29:21,171 [sipchanneludp-u8646] DEBUG dnslookup [(null)] - Complete event fired for DNS lookup on NAPTR proxy01.sipphone.com.
2009-11-14 19:29:21,171 [sipchanneludp-u8646] DEBUG sipproxy [(null)] - GotRequest processing time=140.63ms, script time=140.63.
2009-11-14 19:29:21,593 [siptransport-receive] DEBUG dialplan [(null)] - as (29:21:593 jamesliu): Information response 100 Giving a try for sip:18003333474@proxy01.sipphone.com.
2009-11-14 19:29:21,593 [siptransport-receive] DEBUG dialplan [(null)] - as (29:21:593 jamesliu): Response 200 OK for sip:18003333474@proxy01.sipphone.com.
2009-11-14 19:29:21,593 [siptransport-receive] DEBUG dialplan [(null)] - as (29:21:593 jamesliu): SDP on UAC response had public IP not mangled, RTP socket 130.94.88.93:18868.
2009-11-14 19:29:21,593 [siptransport-receive] DEBUG dialplan [(null)] - as (29:21:593 jamesliu): Cancelling all call legs for ForkCall app.
2009-11-14 19:29:21,593 [dialplanscript-2] DEBUG dialplan [(null)] - as (29:21:593 jamesliu): Answering client call with a response status of 200.
2009-11-14 19:29:21,640 [dialplanscript-2] DEBUG dialplan [(null)] - as (29:21:640 jamesliu): Dial command was successfully answered in 0.609375s.
2009-11-14 19:29:21,640 [dialplanscript-2] DEBUG dialplanengine [(null)] - DialPlanExecutingScript StopExecution on dialplanscript-2.
2009-11-14 19:29:21,812 [dialplanengine-monitor] DEBUG dialplan [(null)] - as (29:21:812 jamesliu): Dial plan execution completed with normal clearing.
2009-11-14 19:29:21,812 [dialplanengine-monitor] DEBUG dialplan [(null)] - as (29:21:812): Dial plan finished for jamesliu, gc memory=6499620, physical memory=94003200, running script count=1.
2009-11-14 19:29:21,812 [dialplanengine-monitor] DEBUG dialplanengine [(null)] - Decrementing dial plan execution count for default@jamesliu, currently=1.
2009-11-14 19:29:21,812 [dialplanengine-monitor] DEBUG dialplanengine [(null)] - Decrementing customer execution count for jamesliu, currently=1.
2009-11-14 19:29:21,812 [dialplanengine-monitor] DEBUG dialplanengine [(null)] - Executing script dialplanscript-2 removed from running scripts list, running script count=0.
2009-11-14 19:29:22,250 [18] DEBUG sipsorcery [(null)] - ra: Checking SIP Provider registration for sipgate.
2009-11-14 19:29:22,250 [18] DEBUG sipsorcery [(null)] - ra: Sending initial register for jamesliu and sipgate to udp:204.155.28.10:5060.
2009-11-14 19:29:22,250 [18] DEBUG sipsorcery [(null)] - ra: Initiating registration for jamesliu on sip:sipgate.com.
2009-11-14 19:29:22,359 [sipchanneludp-u4177] DEBUG sipsorcery [(null)] - ra: Contact successfully registered for jamesliu on sip:sipgate.com, expiry 60s.

Aaron
Site Admin
Posts: 4652
Joined: Thu Jul 12, 2007 12:13 am

Post by Aaron » Sun Nov 15, 2009 3:08 am

The log message below means the sipsorcery server has received an empty and therefore invalid From header (instead of From: it is also legal to use an abbreviated version of f:).

2009-11-14 19:29:00,281 [sipchanneludp-u7434] ERROR sipsorcery.sip [(null)] - Error parsing SIP header f:. The SIP From header was invalid.

The sipsorcery server will not accept a request with an empty From header as it's both a mandatory field according to the SIP standard and more importantly it is essential for request processing and is heavily used for authentication.

I suspect it could be the issue with the calls not hanging up. If the ATA is not sending valid From header in the BYE request the sipsorcery server will not know to hang the call up.

To test that hypothesis you should download the xlite softphone from counterpath and see if it behaves properly. If it does at least we will then know it's a misbehaving ATA causing the issue and not the sipsorcery config.

Regards,

Aaron

jamesliu0327
Posts: 23
Joined: Sat Sep 19, 2009 3:12 am

Post by jamesliu0327 » Sun Nov 15, 2009 4:07 am

jainpj and Aron, thanks for the great helps.

Yes. With the latest x-lite, the issue of "continue connection after hung up" is gone. And the connection is immediately shut off after I press "hung up" in x-lite.

However, I am not convinced it is due to my old ATA. because, with the same ATA, I do not have the above issue when I use web sipsorcory.com . And the problem only happens in local SS.

jainpj
Posts: 173
Joined: Tue Dec 30, 2008 10:13 am

Post by jainpj » Sun Nov 15, 2009 4:35 pm

Was the x-lite installed on the same server as local ssy? Is the ATA installed behind the same NAT/Router as the ssy server?

If the x-lite is installed on the ssy server, it will be slightly different to the ATA.

I has once issue with the BYE with my local mss and SPA-3102. When I looked at the SIP Traces, I found that the BYE messages were not received by the SPA due to some mangling or some other issues.

I think its some thing to do with the combination of NAT, ATA and local ssy.

Believe me the web ssy works much better as compared to local ssy, because the web ssy is not behind the NAT. I think you will find that its the combination of ATA and the NAT that may be causing the bye to be lost.

jamesliu0327
Posts: 23
Joined: Sat Sep 19, 2009 3:12 am

Post by jamesliu0327 » Sun Nov 15, 2009 5:47 pm

If the x-lite is installed on the ssy server, it will be slightly different to the ATA.

Yes. x-lite is on the ssv server.

I think its some thing to do with the combination of NAT, ATA and local ssy.

aboslutely agree.

I prefer to stick to web SS unless it is down...

Post Reply