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

Hadzhiev, Tihomir tihomir.hadzhiev at acision.com
Fri Nov 9 18:30:41 CET 2012


Hi Saul,

Here is a full trace from SYLK:


==> core_trace.txt <==
2012-11-09 18:15:28.202753 [sylk-server 5871] (5) sip_endpoint.c: Processing incoming message: Request msg REGISTER/cseq=10 (rdata0x7fe4d000d3f8)

==> sip_trace.txt <==
2012-11-09 18:15:28.206900 [sylk-server 5871]: RECEIVED: Packet 5, +0:00:37.715565
10.226.20.240:6060 -(SIP over UDP)-> 10.226.20.56:5070
REGISTER sip:10.226.20.56:5070 SIP/2.0
Via: SIP/2.0/UDP 10.226.20.240:6060;branch=z9hG4bKd2c7.79523de.0
To: sip:alice at open-ims.test
From: sip:scscf.open-ims.test:6060;tag=fe1333654d776e39dec8456928d98e62-40d9
CSeq: 10 REGISTER
Call-ID: 3d06c2bd64427876-23096 at 10.226.20.240
Content-Length: 0
User-Agent: Sip EXpress router(2.1.0-dev1 OpenIMSCore (x86_64/linux))
Event: registration
Max-Forwards: 10
Expires: 600120
Contact: <sip:scscf.open-ims.test:6060>
P-Visited-Network-ID: open-ims.test
P-Access-Network-Info: ADSL;utran-cell-id-3gpp=00000000
P-Charging-Vector: icid-value="P-CSCFabcd00000000509d3cbc0000008a";icid-generated-at=10.226.20.240;orig-ioi="open-ims.test"


--

==> core_trace.txt <==
2012-11-09 18:15:28.207665 [sylk-server 5871] (5)       endpoint: Response msg 405/REGISTER/cseq=10 (tdta0x7fe4d001dd80) created
2012-11-09 18:15:28.208198 [sylk-server 5871] (5)  sip_resolve.c: Target '10.226.20.240:6060' type=UDP resolved to '10.226.20.240:6060' type=UDP (UDP transport)

==> sip_trace.txt <==
2012-11-09 18:15:28.208663 [sylk-server 5871]: SENDING: Packet 6, +0:00:37.717328
10.226.20.56:5070 -(SIP over UDP)-> 10.226.20.240:6060
SIP/2.0 405 Method Not Allowed
Via: SIP/2.0/UDP 10.226.20.240:6060;received=10.226.20.240;branch=z9hG4bKd2c7.79523de.0
Call-ID: 3d06c2bd64427876-23096 at 10.226.20.240
From: <sip:scscf.open-ims.test>;tag=fe1333654d776e39dec8456928d98e62-40d9
To: <sip:alice at open-ims.test>
CSeq: 10 REGISTER
Server: SylkServer-2.2.0
Content-Length:  0


--

==> core_trace.txt <==
2012-11-09 18:15:28.209210 [sylk-server 5871] (5) tdta0x7fe4d001: Destroying txdata Response msg 405/REGISTER/cseq=10 (tdta0x7fe4d001dd80)
2012-11-09 18:15:28.297206 [sylk-server 5871] (5) sip_endpoint.c: Processing incoming message: Request msg SUBSCRIBE/cseq=501 (rdata0x7fe4d000d3f8)

==> sip_trace.txt <==
2012-11-09 18:15:28.299752 [sylk-server 5871]: RECEIVED: Packet 7, +0:00:37.808417
10.226.20.240:6060 -(SIP over UDP)-> 10.226.20.56:5070
SUBSCRIBE sip:alice at open-ims.test SIP/2.0
Record-Route: <sip:mo at scscf.open-ims.test:6060;lr>
Route: <sip:10.226.20.56:5070;lr>, <sip:iscmark at scscf.open-ims.test:6060;lr;s=1;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=z9hG4bK37d6.9768f193.0
Via: SIP/2.0/UDP 10.226.20.240:4060;branch=z9hG4bK37d6.702e5fe.0
Via: SIP/2.0/UDP 10.226.55.62:51275;rport=51275;branch=z9hG4bK1352481855266
From: <sip:alice at open-ims.test>;tag=22648
To: <sip:alice at open-ims.test>
Call-ID: M-8a8edb8ba08b552f1978a9dea559cbb5
CSeq: 501 SUBSCRIBE
Max-Forwards: 15
Allow: INVITE, ACK, CANCEL, BYE, MESSAGE, OPTIONS, NOTIFY, PRACK, UPDATE, REFER
Contact: <sip:alice at 10.226.55.62:51275;transport=udp>;+g.oma.sip-im
User-Agent: IM-client/OMA1.0 Mercuro-Gold/v4.0.1631.0
Expires: 600000
Event: message-summary
Accept: application/simple-message-summary
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-CSCFabcd00000000509d3cbc0000008b";icid-generated-at=10.226.20.240;orig-ioi="open-ims.test"


--

==> core_trace.txt <==
2012-11-09 18:15:28.303337 [sylk-server 5871] (5)       endpoint: Response msg 489/SUBSCRIBE/cseq=501 (tdta0x7fe4d001f270) created
2012-11-09 18:15:28.304724 [sylk-server 5871] (5)  sip_resolve.c: Target '10.226.20.240:6060' type=UDP resolved to '10.226.20.240:6060' type=UDP (UDP transport)

==> sip_trace.txt <==
2012-11-09 18:15:28.305283 [sylk-server 5871]: SENDING: Packet 8, +0:00:37.813948
10.226.20.56:5070 -(SIP over UDP)-> 10.226.20.240:6060
SIP/2.0 489 Bad Event
Via: SIP/2.0/UDP 10.226.20.240:6060;received=10.226.20.240;branch=z9hG4bK37d6.9768f193.0
Via: SIP/2.0/UDP 10.226.20.240:4060;branch=z9hG4bK37d6.702e5fe.0
Via: SIP/2.0/UDP 10.226.55.62:51275;rport=51275;branch=z9hG4bK1352481855266
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-8a8edb8ba08b552f1978a9dea559cbb5
From: <sip:alice at open-ims.test>;tag=22648
To: <sip:alice at open-ims.test>
CSeq: 501 SUBSCRIBE
Server: SylkServer-2.2.0
Content-Length:  0


--

==> core_trace.txt <==
2012-11-09 18:15:28.305905 [sylk-server 5871] (5) tdta0x7fe4d001: Destroying txdata Response msg 489/SUBSCRIBE/cseq=501 (tdta0x7fe4d001f270)
2012-11-09 18:15:28.306329 [sylk-server 5871] (5) sip_endpoint.c: Processing incoming message: Request msg SUBSCRIBE/cseq=101 (rdata0x7fe4d000d3f8)

==> sip_trace.txt <==
2012-11-09 18:15:28.306763 [sylk-server 5871]: RECEIVED: Packet 9, +0:00:37.815428
10.226.20.240:6060 -(SIP over UDP)-> 10.226.20.56:5070
SUBSCRIBE sip:alice at open-ims.test SIP/2.0
Record-Route: <sip:mo at scscf.open-ims.test:6060;lr>
Route: <sip:10.226.20.56:5070;lr>, <sip:iscmark at scscf.open-ims.test:6060;lr;s=1;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=z9hG4bK32e9.44b253d.0
Via: SIP/2.0/UDP 10.226.20.240:4060;branch=z9hG4bK32e9.2599433.0
Via: SIP/2.0/UDP 10.226.55.62:51275;rport=51275;branch=z9hG4bK1352481855267
From: <sip:alice at open-ims.test>;tag=15890
To: <sip:alice at open-ims.test>
Call-ID: M-e5f5fa9cdafe8c9abdca315d3c6914fc
CSeq: 101 SUBSCRIBE
Max-Forwards: 15
Allow: INVITE, ACK, CANCEL, BYE, MESSAGE, OPTIONS, NOTIFY, PRACK, UPDATE, REFER
Contact: <sip:alice at 10.226.55.62:51275;transport=udp>;+g.oma.sip-im
User-Agent: IM-client/OMA1.0 Mercuro-Gold/v4.0.1631.0
Expires: 600000
Event: presence.winfo
Accept: application/watcherinfo+xml
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-CSCFabcd00000000509d3cbc0000008d";icid-generated-at=10.226.20.240;orig-ioi="open-ims.test"


--

==> core_trace.txt <==
2012-11-09 18:15:28.307369 [sylk-server 5871] (5)       endpoint: Response msg 489/SUBSCRIBE/cseq=101 (tdta0x7fe4d001f7b0) created
2012-11-09 18:15:28.307783 [sylk-server 5871] (5)  sip_resolve.c: Target '10.226.20.240:6060' type=UDP resolved to '10.226.20.240:6060' type=UDP (UDP transport)

==> sip_trace.txt <==
2012-11-09 18:15:28.308218 [sylk-server 5871]: SENDING: Packet 10, +0:00:37.816883
10.226.20.56:5070 -(SIP over UDP)-> 10.226.20.240:6060
SIP/2.0 489 Bad Event
Via: SIP/2.0/UDP 10.226.20.240:6060;received=10.226.20.240;branch=z9hG4bK32e9.44b253d.0
Via: SIP/2.0/UDP 10.226.20.240:4060;branch=z9hG4bK32e9.2599433.0
Via: SIP/2.0/UDP 10.226.55.62:51275;rport=51275;branch=z9hG4bK1352481855267
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-e5f5fa9cdafe8c9abdca315d3c6914fc
From: <sip:alice at open-ims.test>;tag=15890
To: <sip:alice at open-ims.test>
CSeq: 101 SUBSCRIBE
Server: SylkServer-2.2.0
Content-Length:  0


--

==> core_trace.txt <==
2012-11-09 18:15:28.308720 [sylk-server 5871] (5) tdta0x7fe4d001: Destroying txdata Response msg 489/SUBSCRIBE/cseq=101 (tdta0x7fe4d001f7b0)
2012-11-09 18:15:28.366070 [sylk-server 5871] (5) sip_endpoint.c: Processing incoming message: Request msg SUBSCRIBE/cseq=801 (rdata0x7fe4d000d3f8)

==> sip_trace.txt <==
2012-11-09 18:15:28.366839 [sylk-server 5871]: RECEIVED: Packet 11, +0:00:37.875504
10.226.20.240:6060 -(SIP over UDP)-> 10.226.20.56:5070
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:5070;lr>, <sip:iscmark at scscf.open-ims.test:6060;lr;s=1;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=z9hG4bK28c8.7fcb9d54.0
Via: SIP/2.0/UDP 10.226.20.240:4060;branch=z9hG4bK28c8.5366fa71.0
Via: SIP/2.0/UDP 10.226.55.62:51275;rport=51275;branch=z9hG4bK1352481855268
From: <sip:alice at open-ims.test>;tag=15350
To: <sip:tihoparvi at testing.com>
Call-ID: M-9e9b4a27ede145f23b41f31b10a4975e
CSeq: 801 SUBSCRIBE
Max-Forwards: 15
Allow: INVITE, ACK, CANCEL, BYE, MESSAGE, OPTIONS, NOTIFY, PRACK, UPDATE, REFER
Contact: <sip:alice at 10.226.55.62:51275;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-CSCFabcd00000000509d3cbc0000008e";icid-generated-at=10.226.20.240;orig-ioi="open-ims.test"


--

==> core_trace.txt <==
2012-11-09 18:15:28.367504 [sylk-server 5871] (5) tsx0x7fe4d0021: Transaction created for Request msg SUBSCRIBE/cseq=801 (rdata0x7fe4d000d3f8)
2012-11-09 18:15:28.367962 [sylk-server 5871] (5) tsx0x7fe4d0021: Incoming Request msg SUBSCRIBE/cseq=801 (rdata0x7fe4d000d3f8) in state Null
2012-11-09 18:15:28.368402 [sylk-server 5871] (5) tsx0x7fe4d0021: State changed from Null to Trying, event=RX_MSG
2012-11-09 18:15:28.368831 [sylk-server 5871] (5) dlg0x7fe4d0020: Transaction tsx0x7fe4d0021de8 state changed to Trying
2012-11-09 18:15:28.369261 [sylk-server 5871] (5) dlg0x7fe4d0020: UAS dialog created
2012-11-09 18:15:28.369710 [sylk-server 5871] (5) dlg0x7fe4d0020: Session count inc to 1 by mod-core
2012-11-09 18:15:28.370198 [sylk-server 5871] (5) dlg0x7fe4d0020: Module mod-evsub added as dialog usage, data=0x7fe4d0022b00
2012-11-09 18:15:28.370660 [sylk-server 5871] (5) evsub0x7fe4d00: UAS subscription created, using dialog dlg0x7fe4d0020b88
2012-11-09 18:15:28.371083 [sylk-server 5871] (5) dlg0x7fe4d0020: Session count inc to 3 by mod-evsub
2012-11-09 18:15:28.371497 [sylk-server 5871] (5)       endpoint: Response msg 500/SUBSCRIBE/cseq=801 (tdta0x7fe4d0023000) created

==> notifications_trace.txt <==
2012-11-09 18:15:28.374247 [sylk-server 5871]: Notification name=SIPIncomingSubscriptionGotSubscribe sender=<sipsimple.core._core.IncomingSubscription object at 0x7fe4d8ad6050>
{'body': None,
 'headers': {'Accept': ['multipart/related',
                        'application/rlmi+xml',
                        'application/pidf+xml',
                        'application/rpid+xml',
                        'application/xcap-diff+xml',
                        'message/external-body'],
             'Accept-Contact': FrozenHeader('Accept-Contact', '*;+g.oma.sip-im'),
             'Allow': ['INVITE',
                       'ACK',
                       'CANCEL',
                       'BYE',
                       'MESSAGE',
                       'OPTIONS',
                       'NOTIFY',
                       'PRACK',
                       'UPDATE',
                       'REFER'],
             'Allow-Events': ['refer',
                              'presence',
                              'presence.winfo',
                              'xcap-diff',
                              'conference'],
             'CSeq': (801, 'SUBSCRIBE'),
             'Call-ID': FrozenHeader('Call-ID', 'M-9e9b4a27ede145f23b41f31b10a4975e'),
             'Contact': [FrozenContactHeader(FrozenSIPURI('10.226.55.62', 'alice', None, 51275, False, frozendict({'transport': 'udp'}), frozendict({})), None, frozendict({'q': '0.0', '+g.oma.sip-im': None}))],
             'Content-Length': 0,
             'Event': FrozenEventHeader('presence', frozendict({})),
             'Expires': 600000,
             'From': FrozenFromHeader(FrozenSIPURI('open-ims.test', 'alice', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': '15350'})),
             'Max-Forwards': 15,
             'P-Access-Network-Info': FrozenHeader('P-Access-Network-Info', 'ADSL;utran-cell-id-3gpp=00000000'),
             'P-Asserted-Identity': FrozenHeader('P-Asserted-Identity', '<sip:alice at open-ims.test>'),
             'P-Charging-Vector': FrozenHeader('P-Charging-Vector', 'icid-value="P-CSCFabcd00000000509d3cbc0000008e";icid-generated-at=10.226.20.240;orig-ioi="open-ims.test"'),
             'Privacy': FrozenHeader('Privacy', 'none'),
             'Record-Route': [FrozenRecordRouteHeader(FrozenSIPURI('scscf.open-ims.test', 'mo', None, 6060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({})),
                              FrozenRecordRouteHeader(FrozenSIPURI('pcscf.open-ims.test', 'mo', None, 4060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({}))],
             'Route': [FrozenRouteHeader(FrozenSIPURI('10.226.20.56', None, None, 5070, False, frozendict({'lr': None}), frozendict({})), None, frozendict({})),
                       FrozenRouteHeader(FrozenSIPURI('scscf.open-ims.test', 'iscmark', None, 6060, False, frozendict({'a': '7369703a616c696365406f70656e2d696d732e74657374', 'h': '0', 's': '1', 'lr': None, 'd': '0'}), frozendict({})), None, frozendict({}))],
             'Supported': ['eventlist'],
             'To': FrozenToHeader(FrozenSIPURI('testing.com', 'tihoparvi', None, None, False, frozendict({}), frozendict({})), None, frozendict({})),
             'User-Agent': FrozenHeader('User-Agent', 'IM-client/OMA1.0 Mercuro-Gold/v4.0.1631.0'),
             'Via': [FrozenViaHeader('UDP', '10.226.20.240', 6060, frozendict({'received': '10.226.20.240', 'branch': 'z9hG4bK28c8.7fcb9d54.0'})),
                     FrozenViaHeader('UDP', '10.226.20.240', 4060, frozendict({'branch': 'z9hG4bK28c8.5366fa71.0'})),
                     FrozenViaHeader('UDP', '10.226.55.62', 51275, frozendict({'rport': 51275, 'branch': 'z9hG4bK1352481855268'}))]},
 'method': 'SUBSCRIBE',
 'request_uri': FrozenSIPURI('testing.com', 'tihoparvi', None, None, False, frozendict({}), frozendict({}))}
2012-11-09 18:15:28.382113 [sylk-server 5871]: Notification name=XMPPSubscriptionDidStart sender=<sylk.applications.xmppgateway.xmpp.subscription.XMPPSubscription object at 0x7fe4d85f45d0>
{}
2012-11-09 18:15:28.388362 [sylk-server 5871]: Notification name=XMPPSubscriptionChangedState sender=<sylk.applications.xmppgateway.xmpp.subscription.XMPPSubscription object at 0x7fe4d85f45d0>
{'prev_state': None, 'state': 'subscribe_sent'}
2012-11-09 18:15:28.394574 [sylk-server 5871]: Notification name=S2XPresenceHandlerDidStart sender=<sylk.applications.xmppgateway.presence.S2XPresenceHandler object at 0x7fe4d85f44d0>
{}

==> xmpp_trace.txt <==
2012-11-09T18:15:28.410956+01:00 [sylk-server 5871]: SENDING: Packet 1, +0:00:00
<stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xmlns:db='jabber:server:dialback' to='testing.com' version='1.0' from='open-ims.test'>
--
2012-11-09T18:15:28.412854+01:00 [sylk-server 5871]: RECEIVED: Packet 2, +0:00:00.001898
<?xml version='1.0'?><stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xmlns:db='jabber:server:dialback' id='1312966307' version='1.0'>
--
2012-11-09T18:15:28.414872+01:00 [sylk-server 5871]: RECEIVED: Packet 3, +0:00:00.003916
<stream:features><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://www.process-one.net/en/ejabberd/' ver='TQ2JFyRoSa70h2G1bpgjzuXb2sU='/></stream:features>
--
2012-11-09T18:15:28.416261+01:00 [sylk-server 5871]: SENDING: Packet 4, +0:00:00.005305
<db:result to='testing.com' from='open-ims.test'>6c5593148e4f5491abec4369cc5f70c434f748c13dccb681b261b7ef874c6852</db:result>
--
2012-11-09T18:15:28.419271+01:00 [sylk-server 5871]: RECEIVED: Packet 5, +0:00:00.008315
<?xml version='1.0'?><stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xmlns:db='jabber:server:dialback' from='testing.com' to='open-ims.test' version='1.0'>
--
2012-11-09T18:15:28.420692+01:00 [sylk-server 5871]: SENDING: Packet 6, +0:00:00.009736
<stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xmlns:db='jabber:server:dialback' version='1.0' from='open-ims.test' id='1875b6985888f4ca'>
--
2012-11-09T18:15:28.421286+01:00 [sylk-server 5871]: SENDING: Packet 7, +0:00:00.010330
<stream:features/>
--
2012-11-09T18:15:28.422494+01:00 [sylk-server 5871]: RECEIVED: Packet 8, +0:00:00.011538
<db:result from='testing.com' to='open-ims.test'>3782641204</db:result>
--
2012-11-09T18:15:28.428626+01:00 [sylk-server 5871]: SENDING: Packet 9, +0:00:00.017670
<stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xmlns:db='jabber:server:dialback' to='testing.com' version='1.0' from='open-ims.test'>
--
2012-11-09T18:15:28.430041+01:00 [sylk-server 5871]: RECEIVED: Packet 10, +0:00:00.019085
<?xml version='1.0'?><stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xmlns:db='jabber:server:dialback' id='1648776250' version='1.0'>
--
2012-11-09T18:15:28.430909+01:00 [sylk-server 5871]: RECEIVED: Packet 11, +0:00:00.019953
<stream:features><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://www.process-one.net/en/ejabberd/' ver='TQ2JFyRoSa70h2G1bpgjzuXb2sU='/></stream:features>
--
2012-11-09T18:15:28.431574+01:00 [sylk-server 5871]: SENDING: Packet 12, +0:00:00.020618
<db:verify to='testing.com' from='open-ims.test' id='1875b6985888f4ca'>3782641204</db:verify>
--
2012-11-09T18:15:28.432855+01:00 [sylk-server 5871]: RECEIVED: Packet 13, +0:00:00.021899
<db:verify from='testing.com' to='open-ims.test' id='1875b6985888f4ca' type='valid'/>
--
2012-11-09T18:15:28.433838+01:00 [sylk-server 5871]: SENDING: Packet 14, +0:00:00.022882
<db:result to='testing.com' from='open-ims.test' type='valid'/>
--
2012-11-09T18:15:28.435843+01:00 [sylk-server 5871]: RECEIVED: Packet 15, +0:00:00.024887
<db:verify from='testing.com' to='open-ims.test' id='1312966307'>6c5593148e4f5491abec4369cc5f70c434f748c13dccb681b261b7ef874c6852</db:verify>
--
2012-11-09T18:15:28.437286+01:00 [sylk-server 5871]: SENDING: Packet 16, +0:00:00.026330
<db:verify to='testing.com' from='open-ims.test' id='1312966307' type='valid'/>
--
2012-11-09T18:15:28.438344+01:00 [sylk-server 5871]: RECEIVED: Packet 17, +0:00:00.027388
<db:result from='testing.com' to='open-ims.test' type='valid'/>
--
2012-11-09T18:15:28.439383+01:00 [sylk-server 5871]: SENDING: Packet 18, +0:00:00.028427
<presence to='tihoparvi at testing.com' from='alice at open-ims.test' type='subscribe'/>
--
2012-11-09T18:15:28.439876+01:00 [sylk-server 5871]: SENDING: Packet 19, +0:00:00.028920
<presence to='tihoparvi at testing.com' from='alice at open-ims.test' type='probe'/>
--
2012-11-09T18:15:28.441169+01:00 [sylk-server 5871]: RECEIVED: Packet 20, +0:00:00.030213
<presence from='tihoparvi at testing.com' to='alice at open-ims.test' type='subscribed'/>
--

==> notifications_trace.txt <==
2012-11-09 18:15:28.442794 [sylk-server 5871]: Notification name=XMPPGotPresenceSubscriptionStatus sender=<wokkel.component.InternalComponent object at 0x7fe4d8ab9490>
{'presence_stanza': <sylk.applications.xmppgateway.xmpp.stanzas.SubscriptionPresence object at 0x7fe4d8bc6ed0>}
2012-11-09 18:15:28.443599 [sylk-server 5871]: Notification name=XMPPSubscriptionChangedState sender=<sylk.applications.xmppgateway.xmpp.subscription.XMPPSubscription object at 0x7fe4d85f45d0>
{'prev_state': 'subscribe_sent', 'state': 'active'}

==> core_trace.txt <==
2012-11-09 18:15:28.484529 [sylk-server 5871] (5) dlg0x7fe4d0020: Sending Response msg 202/SUBSCRIBE/cseq=801 (tdta0x7fe4d0023000)
2012-11-09 18:15:28.486277 [sylk-server 5871] (5) tsx0x7fe4d0021: Sending Response msg 202/SUBSCRIBE/cseq=801 (tdta0x7fe4d0023000) in state Trying
2012-11-09 18:15:28.486519 [sylk-server 5871] (5)  sip_resolve.c: Target '10.226.20.240:6060' type=UDP resolved to '10.226.20.240:6060' type=UDP (UDP transport)

==> sip_trace.txt <==
2012-11-09 18:15:28.486742 [sylk-server 5871]: SENDING: Packet 12, +0:00:37.995407
10.226.20.56:5070 -(SIP over UDP)-> 10.226.20.240:6060
SIP/2.0 202 Accepted
Via: SIP/2.0/UDP 10.226.20.240:6060;received=10.226.20.240;branch=z9hG4bK28c8.7fcb9d54.0
Via: SIP/2.0/UDP 10.226.20.240:4060;branch=z9hG4bK28c8.5366fa71.0
Via: SIP/2.0/UDP 10.226.55.62:51275;rport=51275;branch=z9hG4bK1352481855268
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-9e9b4a27ede145f23b41f31b10a4975e
From: <sip:alice at open-ims.test>;tag=15350
To: <sip:tihoparvi at testing.com>;tag=E2LQRGkIOiKzqbmey4L6rQBwgx1C1.3t
CSeq: 801 SUBSCRIBE
Contact: <sip:tihoparvi at 10.226.20.56:5070>
Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER
Supported: 100rel, replaces, norefersub, gruu
Expires: 3600
Server: SylkServer-2.2.0
Content-Length:  0


--

==> core_trace.txt <==
2012-11-09 18:15:28.486896 [sylk-server 5871] (5) tsx0x7fe4d0021: State changed from Trying to Completed, event=TX_MSG
2012-11-09 18:15:28.487101 [sylk-server 5871] (5) dlg0x7fe4d0020: Transaction tsx0x7fe4d0021de8 state changed to Completed



That's the moment when the IMS client logs in and sends the subscription. From the previous e-mail there are also the IMS CORE <-> SYLK <-> XMPP server PDUs.


Here are my two zone files:

1. for the testing.com - XMPP domain



root at testing:/etc/bind# cat testing.com.db
;replace example.com with your domain name. do not forget the . after the domain name!
;Also, replace ns1 with the name of your DNS server
testing.com.      IN      SOA     ns1.testing.com. admin.testing.com. (
;// Do not modify the following lines!
                                                        2006081401
                                                        28800
                                                        3600
                                                        604800
                                                        38400
 )

;Replace the following line as necessary:
;ns1 = DNS Server name
;mta = mail server name
;example.com = domain name
testing.com.      IN      NS              ns1.testing.com.
testing.com.      IN      MX     10       mta.testing.com.

_xmpp-client._tcp.testing.com. 82698 IN SRV     10 0 5222 testing.com.
_xmpp-server._tcp.testing.com. 86400 IN SRV     10 0 5269 testing.com.
_sip._udp                            1D SRV 0 0 5060    testing.com.
_sip._tcp                            1D SRV 0 0 5060    testing.com.

;---------------------------------------;
;            NAPTR RECORDS              ;
;---------------------------------------;
testing.com.          1D IN NAPTR 10 50 "s" "SIP+D2U" ""      _sip._udp
testing.com.          1D IN NAPTR 20 50 "s" "SIP+D2T" ""      _sip._tcp



;Replace the IP address with the right IP addresses.
ns1              IN      A       10.226.20.60
@                IN      A       10.226.20.60
facebook         IN      A       10.226.20.60
conference               IN      A       10.226.20.60


And the other domain -> open-ims.test ( SIP ) domain

root at testing:/etc/bind# cat open-ims.dnszone
$ORIGIN open-ims.test.
$TTL 1W
@                       1D IN SOA                       localhost. root.localhost. (
                                                                2006101001      ; serial
                                                                3H              ; refresh
                                                                15M             ; retry
                                                                1W              ; expiry
                                                                1D )            ; minimum


;---------------------------------------;
;              NS  RECORDS              ;
;---------------------------------------;
                        1D IN NS                                ns

;---------------------------------------;
;              A   RECORDS              ;
;---------------------------------------;
ns                      1D IN A                                 10.226.20.240
pcscf                   1D IN A                                 10.226.20.240
icscf                   1D IN A                                 10.226.20.240
scscf                   1D IN A                                 10.226.20.240
hss                     1D IN A                                 10.226.20.240
open-ims.test.          1D IN A                                 10.226.20.240
;scscf1                 1D IN A                                 10.226.20.31



;---------------------------------------;
;             SRV  RECORDS              ;
;---------------------------------------;
_sip.pcscf              1D SRV 0 0 4060                         pcscf
_sip._udp.pcscf         1D SRV 0 0 4060                         pcscf
_sip._tcp.pcscf         1D SRV 0 0 4060                         pcscf

_sip                    1D SRV 0 0 5060                         icscf
_sip._udp               1D SRV 0 0 5060                         icscf
_sip._tcp               1D SRV 0 0 5060                         icscf

_sip.scscf              1D SRV 0 0 6060                         scscf
_sip._udp.scscf         1D SRV 0 0 6060                         scscf
_sip._tcp.scscf         1D SRV 0 0 6060                         scscf
;_sip._tcp.scscf1        1D SRV 0 0 6060                         scscf1


;---------------------------------------;
;            NAPTR RECORDS              ;
;---------------------------------------;
open-ims.test.          1D IN NAPTR 10 50 "s" "SIP+D2U" ""      _sip._udp
open-ims.test.          1D IN NAPTR 20 50 "s" "SIP+D2T" ""      _sip._tcp

pcrf                                    1D IN A                 127.0.0.1
clf                                     1D IN A                 127.0.0.1

_xmpp-client._tcp.open-ims.test. 82698 IN SRV     10 0 5222 open-ims.test.
_xmpp-server._tcp.open-ims.test. 86400 IN SRV     10 0 5269 open-ims.test.


Thanks and regards.

Tiho




-----Original Message-----
From: Saúl Ibarra Corretgé [mailto:saul at ag-projects.com]
Sent: 09 November 2012 16:53
To: Hadzhiev, Tihomir
Cc: sipbeyondvoip at lists.ag-projects.com
Subject: Re: [SIP Beyond VoIP] Another strange problem whcih I can't overcome for a long time.

Hi,

On Nov 9, 2012, at 4:34 PM, Hadzhiev, Tihomir wrote:

> Hi All,
>
> I hope you will be able to help me with this one.
>
> I have the IMS/SIP client logging in ( have there presence server and so on ) and I'm willing both guys, the IMS guy and the XMPP guy to see their presence together.
>
> Please take a look at the attached tcpdump, which has been taken on the box where Sylk stand ( presence server as well ). I have Open Ims on a different box ( presuming messaging both SIP<->XMPP and MSRP<->XMPP works ). However when I enable the presence at the IMS client, it would start to make SUBSCRIPTIONS and so on, and this is the place where SYLK dies with the following error:
>
> Starting factory
> <sylk.applications.xmppgateway.xmpp.DeferredS2SClientFactory object at
> 0x7f48c8b6ed50> DNSDatagramProtocol starting on 60792 Starting
> protocol <twisted.names.dns.DNSDatagramProtocol object at
> 0x7f48c8b6edd0> [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 "/root/src/sylkserver/sylk/applications/__init__.py", line 139, in handle_notification
>     handler(notification)
>   File "/root/src/sylkserver/sylk/applications/__init__.py", line 167, in _NH_SIPIncomingSubscriptionGotSubscribe
>     app.incoming_subscription(subscribe_request, notification.data)
>   File "/root/src/sylkserver/sylk/applications/xmppgateway/__init__.py", line 133, in incoming_subscription
>     handler.add_sip_subscription(subscribe_request)
>   File "/root/src/sylkserver/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 60792 Closed) Stopping
> protocol <twisted.names.dns.DNSDatagramProtocol object at
> 0x7f48c8b6edd0> 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 0x7f48c8b6e850> 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 "/root/src/sylkserver/sylk/applications/xmppgateway/presence.py", line 138, in handle_notification
>     handler(notification)
>   File "/root/src/sylkserver/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)
>
>
> What I see is that the SUBSCRIBE reaches the XMPP Server, and even the XMPP Server is happy with the subscribe to presence, and what I see in the tcpdump is that once the XMPP server would send backwards SUBSCRIBE towards SYLK- > SYLK dies.
>
> Ok, it might be a problem with the DNS server that I have, but if it was then messaging would have failed as well, but that's not happening.
>
> Currently I have the following hosts:
>
> 10.226.20.240 -> Open-IMS , DNS Server
> 10.226.20.14 -> IMS client, XMPP Client
> 10.226.20.56 -> Sylk + Presence Server
> 10.226.20.60 -> XMPP Server
>
>

Can you send a plaintext capture of the SUBSCRIBE request that you are sending to SylkServer? I'm guessing there is a domain somewhere which needs SRV to be resolved.

--
Saúl Ibarra Corretgé
AG Projects





This e-mail and any attachment is for authorised use by the intended recipient(s) only. It may contain proprietary material, confidential information and/or be subject to legal privilege. It should not be copied, disclosed to, retained or used by, any other party. If you are not an intended recipient then please promptly delete this e-mail and any attachment and all copies and inform the sender. Thank you for understanding.




More information about the SIPBeyondVoIP mailing list