[SIP Beyond VoIP] Another strange problem whcih I can't overcome for a long time.

Wed Nov 14 13:58:50 CET 2012

Hi,

On Nov 14, 2012, at 12:24 PM, Hadzhiev, Tihomir wrote:

> Hi All,
> 
> I'm back with the problem I'm still experiencing, e.g. the Sylkserver throwing the exception mentioned below.
> 
> Hope this time you can help me ( I will give you some more information now )
> 
> So here is the sequence that happens:
> 
> 1. I'm logging in with and IMS client -> Open IMS Core
> 2. Open IMS Code does the routing of the SUBSCRIBE towards the XMPP Domain through Sylk
> Here is the PDU that arrives @ Sylk:
> 
> SUBSCRIBE sip:tihoparvi at testing.com SIP/2.0
> Record-Route: <sip:mo at scscf.open-ims.test:6060;lr>
> Route: <sip:10.226.20.56:6060;lr>, <sip:iscmark at scscf.open-ims.test:6060;lr;s=3;h=0;d=0;a=7369703a616c696365406f70656e2d696d732e74657374>
> Record-Route: <sip:mo at pcscf.open-ims.test:4060;lr>
> Via: SIP/2.0/UDP 10.226.20.240:6060;branch=z9hG4bKdfef.f863a616.0
> Via: SIP/2.0/UDP 10.226.20.240:4060;branch=z9hG4bKdfef.cb200bd6.0
> Via: SIP/2.0/UDP 10.226.20.14:50426;rport=50426;branch=z9hG4bK1352889049730
> From: <sip:alice at open-ims.test>;tag=19072
> To: <sip:tihoparvi at testing.com>
> Call-ID: M-d87f70ca9f6c8e2373099a3d08180ac7
> CSeq: 601 SUBSCRIBE
> Max-Forwards: 15
> Allow: INVITE, ACK, CANCEL, BYE, MESSAGE, OPTIONS, NOTIFY, PRACK, UPDATE, REFER
> Contact: <sip:alice at 10.226.20.14:50426;transport=udp>;+g.oma.sip-im
> User-Agent: IM-client/OMA1.0 Mercuro-Gold/v4.0.1631.0
> Expires: 600000
> Event: presence
> Supported: eventlist
> Accept: multipart/related, application/rlmi+xml, application/pidf+xml, application/rpid+xml, application/xcap-diff+xml, message/external-body
> Accept-Contact: *;+g.oma.sip-im
> P-Access-Network-Info: ADSL;utran-cell-id-3gpp=00000000
> Privacy: none
> Supported: timer
> Allow-Events: refer, presence, presence.winfo, xcap-diff, conference
> Content-Length: 0
> P-Asserted-Identity: <sip:alice at open-ims.test>
> P-Charging-Vector: icid-value="P-CSCFabcd0000000050a37995000002af";icid-generated-at=10.226.20.240;orig-ioi="open-ims.test"
> 
> 3. On receiving the PDU above Sylk does a DNS query for the SRV record for "testing.com"
> 
> _xmpp-server_tcptestingcom!
> 
> Queries _xmpp-server._tcp.testing.com: type SRV, class IN
> 
> 4. Response is sent back from the DNS server:
> 
> Service: xmpp-server
> Protocol: tcp
> Name: testing.com
> Type: SRV ( Service location)
> Class: IN ( 0x0001)
> Time to live: 1 day
> ...
> ...
> Port: 5269
> 
> So far so good till here:
> 
> The query above is visible in sylkserver when run with no-fork option.
> 
> 5. Then I see sylk answers with: Status: 202 Accepted
> 
> SIP/2.0 202 Accepted
> Via: SIP/2.0/UDP 10.226.20.240:6060;received=10.226.20.240;branch=z9hG4bKdfef.f863a616.0
> Via: SIP/2.0/UDP 10.226.20.240:4060;branch=z9hG4bKdfef.cb200bd6.0
> Via: SIP/2.0/UDP 10.226.20.14:50426;rport=50426;branch=z9hG4bK1352889049730
> Record-Route: <sip:mo at scscf.open-ims.test:6060;lr>
> Record-Route: <sip:mo at pcscf.open-ims.test:4060;lr>
> Call-ID: M-d87f70ca9f6c8e2373099a3d08180ac7
> From: <sip:alice at open-ims.test>;tag=19072
> To: <sip:tihoparvi at testing.com>;tag=3f9LdrrXJv1s2HRKWfTPcjutRZ-a3GrG
> CSeq: 601 SUBSCRIBE
> Contact: <sip:tihoparvi at 10.226.20.56:6060>
> Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER
> Supported: 100rel, replaces, norefersub, gruu
> Expires: 3600
> Server: SylkServer-2.2.1
> Content-Length:  0
> 
> 6. There is then a DNS query again, I guess from Sylk ( as it is not visible in the console as Source Port ) for A record of testing.com
> 7. Response also comes correctly with the IP address where the XMPP server for "testing.com" is located.
> 8. At this point Sylk initiates the DIALBACK request towards the XMPP server which is a success
> 9. the XMPP server also initiates another tcp session with the DIALBACK which is a success
> 10. At this moment Sylk does another SRV record lookup on "testing.com" which is a success
> 11. Sylk does another A query to testing.com and gets the IP address for testing.com again.
> 12. Sylk initiates another tcp connection towards the XMPP server ->
> 12.1 Sylk sends db:verify - Success
> 12.2 XMPP server sends db:verify - Success
> 13. Sylk sends a presence packet towards XMPP server:
> 
> <presence to='tihoparvi at testing.com' from='alice at open-ims.test' type='subscribe'/><presence to='tihoparvi at testing.com' from='alice at open-ims.test' type='probe'/>
> 
> 14. XMPP server replies with success on the subscription
> 
> <presence from='tihoparvi at testing.com' to='alice at open-ims.test' type='subscribed'/>
> 
> 15. XMPP server sends the following towards SYLK:
> 
> <presence from='tihoparvi at testing.com/13766865661352890530471043' to='alice at open-ims.test' xml:lang='en'>
> <priority>5</priority>
> <c xmlns='http://jabber.org/protocol/caps' node='http://psi-im.org/caps' ver='caps-b75d8d2b25' ext='ca cs ep-notify-2 html'/>
> <delay xmlns='urn:xmpp:delay' from='tihoparvi at testing.com/13766865661352890530471043' stamp='2012-11-14T10:55:30Z'></delay><x xmlns='jabber:x:delay' stamp='20121114T10:55:30'/></presence>
> 
> 16. And this is here where SYLK dies with the below exception
> 
> 
> Starting SylkServer 2.2.1, config=/etc/sylkserver/config.ini
> using set_wakeup_fd
> Logging SIP trace to file "/var/log/sylkserver/sip_trace.txt"
> Logging MSRP trace to file "/var/log/sylkserver/msrp_trace.txt"
> Logging PJSIP trace to file "/var/log/sylkserver/core_trace.txt"
> Logging notifications trace to file "/var/log/sylkserver/notifications_trace.txt"
> SylkServer started, listening on:
> 10.226.20.56:6060 (UDP)
> 10.226.20.56:6060 (TCP)
> 10.226.20.56:5061 (TLS)
> Loaded applications: xmppgateway, irc-conference
> XMPPS2SServerFactory starting on 5269
> Starting factory <sylk.applications.xmppgateway.xmpp.XMPPS2SServerFactory object at 0x7fbac06b3390>
> [xmpp] XMPP listener started on 10.226.20.56:5269
> Starting factory <sylk.applications.xmppgateway.xmpp.DeferredS2SClientFactory object at 0x7fbac0602bd0>
> /etc/resolv.conf changed, reparsing
> Resolver added ('127.0.0.1', 53) to server list
> DNSDatagramProtocol starting on 47468
> Starting protocol <twisted.names.dns.DNSDatagramProtocol object at 0x7fbac0602910>
> [xmppgateway] Presence session established sip:alice at open-ims.test --> xmpp:tihoparvi at testing.com
> Traceback (most recent call last):
>  File "/usr/lib/python2.7/dist-packages/twisted/internet/base.py", line 773, in runUntilCurrent
>    f(*a, **kw)
>  File "/usr/lib/python2.7/dist-packages/sylk/applications/__init__.py", line 139, in handle_notification
>    handler(notification)
>  File "/usr/lib/python2.7/dist-packages/sylk/applications/__init__.py", line 167, in _NH_SIPIncomingSubscriptionGotSubscribe
>    app.incoming_subscription(subscribe_request, notification.data)
>  File "/usr/lib/python2.7/dist-packages/sylk/applications/xmppgateway/__init__.py", line 133, in incoming_subscription
>    handler.add_sip_subscription(subscribe_request)
>  File "/usr/lib/python2.7/dist-packages/sylk/applications/xmppgateway/presence.py", line 87, in add_sip_subscription
>    subscription.accept_pending()
>  File "_core.subscription.pxi", line 507, in sipsimple.core._core.IncomingSubscription.accept_pending (sipsimple/core/_core.c:103161)
>  File "_core.subscription.pxi", line 648, in sipsimple.core._core.IncomingSubscription._send_notify (sipsimple/core/_core.c:105357)
> PJSIPError: Could not send NOTIFY request: No nameserver is in DNS resolver (PJLIB_UTIL_EDNSNONS)
> (UDP Port 47468 Closed)
> Stopping protocol <twisted.names.dns.DNSDatagramProtocol object at 0x7fbac0602910>
> Starting factory <sylk.applications.xmppgateway.xmpp.DeferredS2SClientFactory object at 0x7fbac0719d90>
> DNSDatagramProtocol starting on 40690
> Starting protocol <twisted.names.dns.DNSDatagramProtocol object at 0x7fbac0719f10>
> (UDP Port 40690 Closed)
> Stopping protocol <twisted.names.dns.DNSDatagramProtocol object at 0x7fbac0719f10>
> Incoming connection 0 from u'testing.com' to u'open-ims.test' established
> Stopping factory <sylk.applications.xmppgateway.xmpp.DeferredS2SClientFactory object at 0x7fbac0719d90>
> Outgoing connection 0 from u'open-ims.test' to u'testing.com' established
> error: Exception occured in observer <sylk.applications.xmppgateway.presence.S2XPresenceHandler object at 0x7fbac0602490> while handling notification 'XMPPSubscriptionChangedState'
> Traceback (most recent call last):
>  File "/usr/lib/python2.7/dist-packages/application/notification.py", line 216, in post_notification
>    observer.handle_notification(notification)
>  File "/usr/lib/python2.7/dist-packages/sylk/applications/xmppgateway/presence.py", line 138, in handle_notification
>    handler(notification)
>  File "/usr/lib/python2.7/dist-packages/sylk/applications/xmppgateway/presence.py", line 154, in _NH_XMPPSubscriptionChangedState
>    subscription.accept(content_type, pidf_doc)
>  File "_core.subscription.pxi", line 534, in sipsimple.core._core.IncomingSubscription.accept (sipsimple/core/_core.c:103647)
>  File "_core.subscription.pxi", line 648, in sipsimple.core._core.IncomingSubscription._send_notify (sipsimple/core/_core.c:105357)
> PJSIPError: Could not send NOTIFY request: No nameserver is in DNS resolver (PJLIB_UTIL_EDNSNONS)
> Segmentation fault (core dumped)
> 
> 
> I can't at this moment get the idea about the NOTIFY which should be generated. I would believe that a NOTIFY should be generated by SYLK and sent towards the SIP /IMS domain, but that's not really happening due to the DNS problem. I don't think that there is DNS problem ( otherwise message wouldn't work   and it works )
> 
> Guys please advise, as this is somehow one of the latest steps to have this integration done with IMS Core.
> 

I believe the problem is caused because the Record-Route headers contain domain names, which we don't support very well :-S. Any chance you could try to put IP addresses there and test again? That way we would be certain that this is indeed the problem.

In any case, there shouldn't be a crash, can you attach a backtrace of the generated core file? You can do that as follows:

ulimit -c unlimited
# run sylkserver and wait for it to crash
gdb python core
set logging on
bt full
exit

Then send the generated gdb.txt file over.

Regards,

--
Saúl Ibarra Corretgé
AG Projects