[SIP Beyond VoIP] Another case where Sylk would reject Notifications

Hadzhiev, Tihomir tihomir.hadzhiev at acision.com
Fri Nov 16 15:33:42 CET 2012


OK, there you go ( please disregard any logs for user admin at testing.com<mailto:admin at testing.com> as this one is simply the IMS user's address book, but not used in this test ).


1.       Sylk restarted and XMPP client logs in:


2012-11-16T14:53:40.519539+01:00 [sylk-server 30934]: RECEIVED: Packet 1, +0:00:00
<?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'>
--
2012-11-16T14:53:40.524549+01:00 [sylk-server 30934]: SENDING: Packet 2, +0:00:00.005010
<stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xmlns:db='jabber:server:dialback' from='open-ims.test' id='9ebfb40de3b2bc2c'>
--
2012-11-16T14:53:40.526326+01:00 [sylk-server 30934]: RECEIVED: Packet 3, +0:00:00.006787
<db:result from='testing.com' to='open-ims.test'>560148917</db:result>
--
2012-11-16T14:53:40.546940+01:00 [sylk-server 30934]: SENDING: Packet 4, +0:00:00.027401
<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-16T14:53:40.548633+01:00 [sylk-server 30934]: RECEIVED: Packet 5, +0:00:00.029094
<?xml version='1.0'?><stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xmlns:db='jabber:server:dialback' id='322458693'>
--
2012-11-16T14:53:40.549697+01:00 [sylk-server 30934]: SENDING: Packet 6, +0:00:00.030158
<db:verify to='testing.com' from='open-ims.test' id='9ebfb40de3b2bc2c'>560148917</db:verify>
--
2012-11-16T14:53:40.550715+01:00 [sylk-server 30934]: RECEIVED: Packet 7, +0:00:00.031176
<db:verify from='testing.com' to='open-ims.test' id='9ebfb40de3b2bc2c' type='valid'/>
--
2012-11-16T14:53:40.551472+01:00 [sylk-server 30934]: SENDING: Packet 8, +0:00:00.031933
<db:result to='testing.com' from='open-ims.test' type='valid'/>
--
2012-11-16T14:53:40.553323+01:00 [sylk-server 30934]: RECEIVED: Packet 9, +0:00:00.033784
<presence from='tihoparvi at testing.com/CZ-R8LGKEG' to='alice at open-ims.test' type='probe'/>
--

==> notifications_trace.txt <==
2012-11-16 14:53:40.556482 [sylk-server 30934]: Notification name=XMPPGotPresenceProbe sender=<wokkel.component.InternalComponent object at 0x7ffbf8ab2310>
{'presence_stanza': <sylk.applications.xmppgateway.xmpp.stanzas.ProbePresence object at 0x7ffbf8b50f50>}
2012-11-16 14:53:40.558514 [sylk-server 30934]: Notification name=XMPPGotPresenceSubscriptionRequest sender=<sylk.applications.xmppgateway.xmpp.XMPPManager object at 0x7ffbf8aa8490>
{'stanza': <sylk.applications.xmppgateway.xmpp.stanzas.ProbePresence object at 0x7ffbf8b50f50>}
2012-11-16 14:53:40.558905 [sylk-server 30934]: Notification name=XMPPIncomingSubscriptionDidStart sender=<sylk.applications.xmppgateway.xmpp.subscription.XMPPIncomingSubscription object at 0x7ffbf8b592d0>
{}
2012-11-16 14:53:40.559798 [sylk-server 30934]: Notification name=X2SPresenceHandlerDidStart sender=<sylk.applications.xmppgateway.presence.X2SPresenceHandler object at 0x7ffbf8b59090>
{}
2012-11-16 14:53:40.562003 [sylk-server 30934]: Notification name=DNSResolverDidInitialize sender=<sipsimple.lookup.DNSManager object at 0x7ffbf8b50e10>
{'nameservers': ['127.0.0.1']}

==> sip_trace.txt <==
2012-11-16 14:53:40.566693 [sylk-server 30934]: DNS lookup NAPTR open-ims.test succeeded, ttl=86400: 20 50 "s" "SIP+D2T" "" _sip._tcp.open-ims.test., 10 50 "s" "SIP+D2U" "" _sip._udp.open-ims.test.

==> notifications_trace.txt <==
2012-11-16 14:53:40.567829 [sylk-server 30934]: Notification name=DNSLookupTrace sender=<sipsimple.lookup.DNSLookup object at 0x7ffbf8b50710>
{'answer': <dns.resolver.Answer object at 0x7ffbf8b50d90>,
'context': 'lookup_sip_proxy',
'error': None,
'nameservers': ['127.0.0.1'],
'query_name': 'open-ims.test',
'query_type': 'NAPTR',
'uri': SIPURI('open-ims.test', None, None, None, False, {}, {})}
2012-11-16 14:53:40.568932 [sylk-server 30934]: Notification name=DNSLookupDidSucceed sender=<sipsimple.lookup.DNSLookup object at 0x7ffbf8b50710>
{'result': [Route('10.226.20.240', 5060, 'udp'),
            Route('10.226.20.240', 5060, 'tcp')]}

==> xmpp_trace.txt <==
2012-11-16T14:53:40.603690+01:00 [sylk-server 30934]: RECEIVED: Packet 10, +0:00:00.084151
<presence from='tihoparvi at testing.com/CZ-R8LGKEG' 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'/>
</presence>
--

==> core_trace.txt <==
2012-11-16 14:53:40.605167 [sylk-server 30934] (5) dlg0x7ffbf8bd4: UAC dialog created
2012-11-16 14:53:40.605447 [sylk-server 30934] (5) dlg0x7ffbf8bd4: Session count inc to 1 by mod-core
2012-11-16 14:53:40.605964 [sylk-server 30934] (5) dlg0x7ffbf8bd4: Module mod-evsub added as dialog usage, data=0x7ffbf8bd5e80
2012-11-16 14:53:40.606526 [sylk-server 30934] (5) evsub0x7ffbf8b: UAC subscription created, using dialog dlg0x7ffbf8bd4b78
2012-11-16 14:53:40.606596 [sylk-server 30934] (5) dlg0x7ffbf8bd4: Session count inc to 3 by mod-evsub

==> notifications_trace.txt <==
2012-11-16 14:53:40.609239 [sylk-server 30934]: Notification name=XMPPGotPresenceAvailability sender=<wokkel.component.InternalComponent object at 0x7ffbf8ab2310>
{'presence_stanza': <sylk.applications.xmppgateway.xmpp.stanzas.AvailabilityPresence object at 0x7ffbf8b64b10>}

==> core_trace.txt <==
2012-11-16 14:53:40.607060 [sylk-server 30934] (5)       endpoint: Request msg SUBSCRIBE/cseq=21970 (tdta0x7ffbf8bd6390) created.
2012-11-16 14:53:40.611133 [sylk-server 30934] (5) dlg0x7ffbf8bd4: Sending Request msg SUBSCRIBE/cseq=21970 (tdta0x7ffbf8bd6390)
2012-11-16 14:53:40.611230 [sylk-server 30934] (5) tsx0x7ffbf8bd8: Transaction created for Request msg SUBSCRIBE/cseq=21969 (tdta0x7ffbf8bd6390)
2012-11-16 14:53:40.611287 [sylk-server 30934] (5) tsx0x7ffbf8bd8: Sending Request msg SUBSCRIBE/cseq=21969 (tdta0x7ffbf8bd6390) in state Null
2012-11-16 14:53:40.611334 [sylk-server 30934] (5)  sip_resolve.c: Target '10.226.20.240:0' type=Unspecified resolved to '10.226.20.240:5060' type=UDP (UDP transport)

==> sip_trace.txt <==
2012-11-16 14:53:40.611456 [sylk-server 30934]: SENDING: Packet 1, +0:00:00
10.226.20.56:6060 -(SIP over UDP)-> 10.226.20.240:5060
SUBSCRIBE sip:alice at open-ims.test SIP/2.0
Via: SIP/2.0/UDP 10.226.20.56:6060;rport;branch=z9hG4bKPjAJwSi5xicEf5AurgbBADneVBfgqOAkTL
Max-Forwards: 70
From: <sip:tihoparvi at testing.com>;tag=BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f
To: <sip:alice at open-ims.test>
Contact: <sip:clnheraz at 10.226.20.56:6060>
Call-ID: JA7JhBheIYEBluQMcw2-RQ2.lh35CntV
CSeq: 21969 SUBSCRIBE
Event: presence
Expires: 3600
Accept: application/pidf+xml
Allow-Events: conference, refer, presence
User-Agent: SylkServer-2.2.1
Content-Length:  0


--

==> core_trace.txt <==
2012-11-16 14:53:40.611527 [sylk-server 30934] (5) tsx0x7ffbf8bd8: State changed from Null to Calling, event=TX_MSG
2012-11-16 14:53:40.611654 [sylk-server 30934] (5) dlg0x7ffbf8bd4: Transaction tsx0x7ffbf8bd83f8 state changed to Calling
2012-11-16 14:53:40.611702 [sylk-server 30934] (4) evsub0x7ffbf8b: Subscription state changed NULL --> SENT

==> notifications_trace.txt <==
2012-11-16 14:53:40.615585 [sylk-server 30934]: Notification name=SIPSubscriptionChangedState sender=<sipsimple.core._core.Subscription object at 0x7ffbf8bd3b90>
{'prev_state': 'NULL', 'state': 'SENT'}
2012-11-16 14:53:40.615848 [sylk-server 30934]: Notification name=SIPSubscriptionWillStart sender=<sipsimple.core._core.Subscription object at 0x7ffbf8bd3b90>
{}

==> core_trace.txt <==
2012-11-16 14:53:40.611959 [sylk-server 30934] (5) sip_endpoint.c: Processing incoming message: Response msg 202/SUBSCRIBE/cseq=21969 (rdata0x7ffbf8163618)

==> sip_trace.txt <==
2012-11-16 14:53:40.612043 [sylk-server 30934]: RECEIVED: Packet 2, +0:00:00.000587
10.226.20.240:5060 -(SIP over UDP)-> 10.226.20.56:6060
SIP/2.0 202 OK
Record-Route: <sip:mt at 10.226.20.240:6060;lr>
Via: SIP/2.0/UDP 10.226.20.56:6060;rport=6060;branch=z9hG4bKPjAJwSi5xicEf5AurgbBADneVBfgqOAkTL
From: <sip:tihoparvi at testing.com>;tag=BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f
To: <sip:alice at open-ims.test>;tag=48b5b8952e8d0bca6256941910840e90-c9f7
Call-ID: JA7JhBheIYEBluQMcw2-RQ2.lh35CntV
CSeq: 21969 SUBSCRIBE
Expires: 3600
Contact: <sip:10.226.20.56:5080;transport=udp>
Server: kamailio (3.3.2 (x86_64/linux))
Content-Length: 0


--

==> core_trace.txt <==
2012-11-16 14:53:40.612093 [sylk-server 30934] (5) tsx0x7ffbf8bd8: Incoming Response msg 202/SUBSCRIBE/cseq=21969 (rdata0x7ffbf8163618) in state Calling
2012-11-16 14:53:40.612138 [sylk-server 30934] (5) tsx0x7ffbf8bd8: State changed from Calling to Completed, event=RX_MSG
2012-11-16 14:53:40.612266 [sylk-server 30934] (5) dlg0x7ffbf8bd4: Received Response msg 202/SUBSCRIBE/cseq=21969 (rdata0x7ffbf8163618)
2012-11-16 14:53:40.612314 [sylk-server 30934] (5) dlg0x7ffbf8bd4: Route-set updated
2012-11-16 14:53:40.612410 [sylk-server 30934] (5) dlg0x7ffbf8bd4: Route-set frozen
2012-11-16 14:53:40.612459 [sylk-server 30934] (5) dlg0x7ffbf8bd4: Transaction tsx0x7ffbf8bd83f8 state changed to Completed
2012-11-16 14:53:40.612465 [sylk-server 30934] (5) evsub0x7ffbf8b: Will refresh in 3595 seconds
2012-11-16 14:53:40.612560 [sylk-server 30934] (5) evsub0x7ffbf8b: Timer UAC_REFRESH scheduled in 3595 seconds
2012-11-16 14:53:40.618377 [sylk-server 30934] (4) evsub0x7ffbf8b: Subscription state changed SENT --> ACCEPTED

==> notifications_trace.txt <==
2012-11-16 14:53:40.624514 [sylk-server 30934]: Notification name=SIPSubscriptionDidStart sender=<sipsimple.core._core.Subscription object at 0x7ffbf8bd3b90>
{}
2012-11-16 14:53:40.624979 [sylk-server 30934]: Notification name=SIPSubscriptionChangedState sender=<sipsimple.core._core.Subscription object at 0x7ffbf8bd3b90>
{'prev_state': 'SENT', 'state': 'ACCEPTED'}

==> core_trace.txt <==
2012-11-16 14:53:40.618517 [sylk-server 30934] (5) sip_endpoint.c: Processing incoming message: Request msg NOTIFY/cseq=2 (rdata0x7ffbec00f8d8)

==> sip_trace.txt <==
2012-11-16 14:53:40.618576 [sylk-server 30934]: RECEIVED: Packet 3, +0:00:00.007120
10.226.20.240:6060 -(SIP over UDP)-> 10.226.20.56:6060
NOTIFY sip:clnheraz at 10.226.20.56:6060 SIP/2.0
Via: SIP/2.0/UDP 10.226.20.240:6060;branch=z9hG4bK7fd4.6b0eed17.0
Via: SIP/2.0/UDP 10.226.20.56:5080;branch=z9hG4bK7fd4.f88ed8c7.0
To: sip:tihoparvi at testing.com;tag=BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f
From: sip:alice at open-ims.test;tag=48b5b8952e8d0bca6256941910840e90-c9f7
CSeq: 2 NOTIFY
Call-ID: JA7JhBheIYEBluQMcw2-RQ2.lh35CntV
Content-Length: 0
User-Agent: kamailio (3.3.2 (x86_64/linux))
Max-Forwards: 16
Event: presence
Contact: <sip:10.226.20.56:5080;transport=udp>
Subscription-State: active;expires=3600


--

==> core_trace.txt <==
2012-11-16 14:53:40.618638 [sylk-server 30934] (5) dlg0x7ffbf8bd4: Received Request msg NOTIFY/cseq=2 (rdata0x7ffbec00f8d8)
2012-11-16 14:53:40.618683 [sylk-server 30934] (5) tsx0x7ffbec020: Transaction created for Request msg NOTIFY/cseq=2 (rdata0x7ffbec00f8d8)
2012-11-16 14:53:40.618734 [sylk-server 30934] (5) tsx0x7ffbec020: Incoming Request msg NOTIFY/cseq=2 (rdata0x7ffbec00f8d8) in state Null
2012-11-16 14:53:40.618780 [sylk-server 30934] (5) tsx0x7ffbec020: State changed from Null to Trying, event=RX_MSG
2012-11-16 14:53:40.618824 [sylk-server 30934] (5) dlg0x7ffbf8bd4: Transaction tsx0x7ffbec020618 state changed to Trying

==> notifications_trace.txt <==
2012-11-16 14:53:40.628050 [sylk-server 30934]: Notification name=SIPSubscriptionGotNotify sender=<sipsimple.core._core.Subscription object at 0x7ffbf8bd3b90>
{'body': None,
'content_type': None,
'event': 'presence',
'from_header': FrozenFromHeader(FrozenSIPURI('open-ims.test', 'alice', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': '48b5b8952e8d0bca6256941910840e90-c9f7'})),
'headers': {'CSeq': (2, 'NOTIFY'),
             'Call-ID': FrozenHeader('Call-ID', 'JA7JhBheIYEBluQMcw2-RQ2.lh35CntV'),
             'Contact': [FrozenContactHeader(FrozenSIPURI('10.226.20.56', None, None, 5080, False, frozendict({'transport': 'udp'}), frozendict({})), None, frozendict({'q': '0.0'}))],
             'Content-Length': 0,
             'Event': FrozenEventHeader('presence', frozendict({})),
             'From': FrozenFromHeader(FrozenSIPURI('open-ims.test', 'alice', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': '48b5b8952e8d0bca6256941910840e90-c9f7'})),
             'Max-Forwards': 16,
             'Subscription-State': FrozenSubscriptionStateHeader('active', frozendict({'expires': '3600'})),
             'To': FrozenToHeader(FrozenSIPURI('testing.com', 'tihoparvi', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': 'BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f'})),
             'User-Agent': FrozenHeader('User-Agent', 'kamailio (3.3.2 (x86_64/linux))'),
             'Via': [FrozenViaHeader('UDP', '10.226.20.240', 6060, frozendict({'received': '10.226.20.240', 'branch': 'z9hG4bK7fd4.6b0eed17.0'})),
                     FrozenViaHeader('UDP', '10.226.20.56', 5080, frozendict({'branch': 'z9hG4bK7fd4.f88ed8c7.0'}))]},
'request_uri': FrozenSIPURI('10.226.20.56', 'clnheraz', None, 6060, False, frozendict({}), frozendict({})),
'to_header': FrozenToHeader(FrozenSIPURI('testing.com', 'tihoparvi', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': 'BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f'}))}

==> core_trace.txt <==
2012-11-16 14:53:40.618917 [sylk-server 30934] (5) evsub0x7ffbf8b: Will refresh in 3595 seconds
2012-11-16 14:53:40.618964 [sylk-server 30934] (5) evsub0x7ffbf8b: Updating UAC_REFRESH timer
2012-11-16 14:53:40.619010 [sylk-server 30934] (5) evsub0x7ffbf8b: Timer UAC_REFRESH scheduled in 3595 seconds
2012-11-16 14:53:40.619055 [sylk-server 30934] (5)       endpoint: Response msg 200/NOTIFY/cseq=2 (tdta0x7ffbec022480) created
2012-11-16 14:53:40.619101 [sylk-server 30934] (5) dlg0x7ffbf8bd4: Sending Response msg 200/NOTIFY/cseq=2 (tdta0x7ffbec022480)
2012-11-16 14:53:40.619148 [sylk-server 30934] (5) tsx0x7ffbec020: Sending Response msg 200/NOTIFY/cseq=2 (tdta0x7ffbec022480) in state Trying
2012-11-16 14:53:40.619195 [sylk-server 30934] (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-16 14:53:40.619245 [sylk-server 30934]: SENDING: Packet 4, +0:00:00.007789
10.226.20.56:6060 -(SIP over UDP)-> 10.226.20.240:6060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.226.20.240:6060;received=10.226.20.240;branch=z9hG4bK7fd4.6b0eed17.0
Via: SIP/2.0/UDP 10.226.20.56:5080;branch=z9hG4bK7fd4.f88ed8c7.0
Call-ID: JA7JhBheIYEBluQMcw2-RQ2.lh35CntV
From: <sip:alice at open-ims.test>;tag=48b5b8952e8d0bca6256941910840e90-c9f7
To: <sip:tihoparvi at testing.com>;tag=BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f
CSeq: 2 NOTIFY
Contact: <sip:clnheraz at 10.226.20.56:6060>
Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER
Supported: 100rel, replaces, norefersub, gruu
Server: SylkServer-2.2.1
Content-Length:  0


--

==> core_trace.txt <==
2012-11-16 14:53:40.619293 [sylk-server 30934] (5) tsx0x7ffbec020: State changed from Trying to Completed, event=TX_MSG
2012-11-16 14:53:40.619358 [sylk-server 30934] (5) dlg0x7ffbf8bd4: Transaction tsx0x7ffbec020618 state changed to Completed
2012-11-16 14:53:40.619403 [sylk-server 30934] (4) evsub0x7ffbf8b: Subscription state changed ACCEPTED --> ACTIVE

==> notifications_trace.txt <==
2012-11-16 14:53:40.639660 [sylk-server 30934]: Notification name=SIPSubscriptionChangedState sender=<sipsimple.core._core.Subscription object at 0x7ffbf8bd3b90>
{'prev_state': 'ACCEPTED', 'state': 'ACTIVE'}
2012-11-16 14:53:40.639983 [sylk-server 30934]: Notification name=XMPPIncomingSubscriptionChangedState sender=<sylk.applications.xmppgateway.xmpp.subscription.XMPPIncomingSubscription object at 0x7ffbf8b592d0>
{'prev_state': None, 'state': 'active'}

==> xmpp_trace.txt <==
2012-11-16T14:53:40.639095+01:00 [sylk-server 30934]: SENDING: Packet 11, +0:00:00.119556
<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-16T14:53:40.642048+01:00 [sylk-server 30934]: RECEIVED: Packet 12, +0:00:00.122509
<?xml version='1.0'?><stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xmlns:db='jabber:server:dialback' id='1521214135'>
--
2012-11-16T14:53:40.643097+01:00 [sylk-server 30934]: SENDING: Packet 13, +0:00:00.123558
<db:result to='testing.com' from='open-ims.test'>b1f4661ea3c031743a8be3b785b9b559ac9114c073072929190b0294cd8436db</db:result>
--
2012-11-16T14:53:40.648881+01:00 [sylk-server 30934]: RECEIVED: Packet 14, +0:00:00.129342
<?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'>
--
2012-11-16T14:53:40.649603+01:00 [sylk-server 30934]: SENDING: Packet 15, +0:00:00.130064
<stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xmlns:db='jabber:server:dialback' from='open-ims.test' id='a70d7b55195f5ae0'>
--
2012-11-16T14:53:40.651252+01:00 [sylk-server 30934]: RECEIVED: Packet 16, +0:00:00.131713
<db:verify from='testing.com' to='open-ims.test' id='1521214135'>b1f4661ea3c031743a8be3b785b9b559ac9114c073072929190b0294cd8436db</db:verify>
--
2012-11-16T14:53:40.652271+01:00 [sylk-server 30934]: SENDING: Packet 17, +0:00:00.132732
<db:verify to='testing.com' from='open-ims.test' id='1521214135' type='valid'/>
--
2012-11-16T14:53:40.653381+01:00 [sylk-server 30934]: RECEIVED: Packet 18, +0:00:00.133842
<db:result from='testing.com' to='open-ims.test' type='valid'/>
--
2012-11-16T14:53:40.654315+01:00 [sylk-server 30934]: SENDING: Packet 19, +0:00:00.134776
<presence to='tihoparvi at testing.com' from='alice at open-ims.test' type='subscribed'/>
--

==> core_trace.txt <==
2012-11-16 14:53:45.602946 [sylk-server 30934] (5) tsx0x7ffbf8bd8: Timeout timer event
2012-11-16 14:53:45.615057 [sylk-server 30934] (5) tsx0x7ffbf8bd8: State changed from Completed to Terminated, event=TIMER
2012-11-16 14:53:45.615080 [sylk-server 30934] (5) dlg0x7ffbf8bd4: Transaction tsx0x7ffbf8bd83f8 state changed to Terminated
2012-11-16 14:53:45.715959 [sylk-server 30934] (5) tsx0x7ffbf8bd8: Timeout timer event
2012-11-16 14:53:45.716631 [sylk-server 30934] (5) tsx0x7ffbf8bd8: State changed from Terminated to Destroyed, event=TIMER
2012-11-16 14:53:45.718693 [sylk-server 30934] (5) tdta0x7ffbf8bd: Destroying txdata Request msg SUBSCRIBE/cseq=21969 (tdta0x7ffbf8bd6390)
2012-11-16 14:53:45.720721 [sylk-server 30934] (5) tsx0x7ffbf8bd8: Transaction destroyed!


2.       Now IMS User logs in:

==> core_trace.txt <==
2012-11-16 14:54:37.224271 [sylk-server 30934] (5) sip_endpoint.c: Processing incoming message: Request msg SUBSCRIBE/cseq=401 (rdata0x7ffbec00f8d8)

==> sip_trace.txt <==
2012-11-16 14:54:37.227310 [sylk-server 30934]: RECEIVED: Packet 5, +0:00:56.615854
10.226.20.240:6060 -(SIP over UDP)-> 10.226.20.56:6060
SUBSCRIBE sip:tihoparvi at testing.com SIP/2.0
Record-Route: <sip:mo at 10.226.20.240: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 10.226.20.240:4060;lr>
Via: SIP/2.0/UDP 10.226.20.240:6060;branch=z9hG4bK458a.61437682.0
Via: SIP/2.0/UDP 10.226.20.240:4060;branch=z9hG4bK458a.92a1cb12.0
Via: SIP/2.0/UDP 10.226.20.14:55305;rport=55305;branch=z9hG4bK1353054401574
From: <sip:alice at open-ims.test>;tag=2589
To: <sip:tihoparvi at testing.com>
Call-ID: M-d540f97bacf53a0cc3e6b33bde672a4b
CSeq: 401 SUBSCRIBE
Max-Forwards: 15
Allow: INVITE, ACK, CANCEL, BYE, MESSAGE, OPTIONS, NOTIFY, PRACK, UPDATE, REFER
Contact: <sip:alice at 10.226.20.14:55305;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-CSCFabcd0000000050a64dd8000000f5";icid-generated-at=10.226.20.240;orig-ioi="open-ims.test"


--

==> core_trace.txt <==
2012-11-16 14:54:37.230810 [sylk-server 30934] (5) tsx0x7ffbec023: Transaction created for Request msg SUBSCRIBE/cseq=401 (rdata0x7ffbec00f8d8)
2012-11-16 14:54:37.231601 [sylk-server 30934] (5) tsx0x7ffbec023: Incoming Request msg SUBSCRIBE/cseq=401 (rdata0x7ffbec00f8d8) in state Null
2012-11-16 14:54:37.232341 [sylk-server 30934] (5) tsx0x7ffbec023: State changed from Null to Trying, event=RX_MSG
2012-11-16 14:54:37.233043 [sylk-server 30934] (5) dlg0x7ffbec020: Transaction tsx0x7ffbec0234d8 state changed to Trying
2012-11-16 14:54:37.233313 [sylk-server 30934] (5) dlg0x7ffbec020: UAS dialog created
2012-11-16 14:54:37.233714 [sylk-server 30934] (5) dlg0x7ffbec020: Session count inc to 1 by mod-core
2012-11-16 14:54:37.234492 [sylk-server 30934] (5) dlg0x7ffbec020: Module mod-evsub added as dialog usage, data=0x7ffbec036950
2012-11-16 14:54:37.234926 [sylk-server 30934] (5) evsub0x7ffbec0: UAS subscription created, using dialog dlg0x7ffbec020308
2012-11-16 14:54:37.235118 [sylk-server 30934] (5) dlg0x7ffbec020: Session count inc to 3 by mod-evsub
2012-11-16 14:54:37.235534 [sylk-server 30934] (5)       endpoint: Response msg 500/SUBSCRIBE/cseq=401 (tdta0x7ffbec023c40) created

==> notifications_trace.txt <==
2012-11-16 14:54:37.241760 [sylk-server 30934]: Notification name=XMPPSubscriptionDidStart sender=<sylk.applications.xmppgateway.xmpp.subscription.XMPPSubscription object at 0x7ffbf8b685d0>
{}
2012-11-16 14:54:37.242474 [sylk-server 30934]: Notification name=XMPPSubscriptionChangedState sender=<sylk.applications.xmppgateway.xmpp.subscription.XMPPSubscription object at 0x7ffbf8b685d0>
{'prev_state': None, 'state': 'subscribe_sent'}

==> xmpp_trace.txt <==
2012-11-16T14:54:37.238806+01:00 [sylk-server 30934]: SENDING: Packet 20, +0:00:56.719267
<presence to='tihoparvi at testing.com' from='alice at open-ims.test' type='subscribe'/>
--
2012-11-16T14:54:37.239893+01:00 [sylk-server 30934]: SENDING: Packet 21, +0:00:56.720354
<presence to='tihoparvi at testing.com' from='alice at open-ims.test' type='probe'/>
--

==> notifications_trace.txt <==
2012-11-16 14:54:37.246609 [sylk-server 30934]: Notification name=SIPIncomingSubscriptionGotSubscribe sender=<sipsimple.core._core.IncomingSubscription object at 0x7ffbf8b465f0>
{'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': (401, 'SUBSCRIBE'),
             'Call-ID': FrozenHeader('Call-ID', 'M-d540f97bacf53a0cc3e6b33bde672a4b'),
             'Contact': [FrozenContactHeader(FrozenSIPURI('10.226.20.14', 'alice', None, 55305, 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': '2589'})),
             '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-CSCFabcd0000000050a64dd8000000f5";icid-generated-at=10.226.20.240;orig-ioi="open-ims.test"'),
             'Privacy': FrozenHeader('Privacy', 'none'),
             'Record-Route': [FrozenRecordRouteHeader(FrozenSIPURI('10.226.20.240', 'mo', None, 6060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({})),
                              FrozenRecordRouteHeader(FrozenSIPURI('10.226.20.240', 'mo', None, 4060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({}))],
             'Route': [FrozenRouteHeader(FrozenSIPURI('10.226.20.56', None, None, 6060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({})),
                       FrozenRouteHeader(FrozenSIPURI('scscf.open-ims.test', 'iscmark', None, 6060, False, frozendict({'a': '7369703a616c696365406f70656e2d696d732e74657374', 'h': '0', 's': '3', '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': 'z9hG4bK458a.61437682.0'})),
                     FrozenViaHeader('UDP', '10.226.20.240', 4060, frozendict({'branch': 'z9hG4bK458a.92a1cb12.0'})),
                     FrozenViaHeader('UDP', '10.226.20.14', 55305, frozendict({'rport': 55305, 'branch': 'z9hG4bK1353054401574'}))]},
'method': 'SUBSCRIBE',
'request_uri': FrozenSIPURI('testing.com', 'tihoparvi', None, None, False, frozendict({}), frozendict({}))}

==> core_trace.txt <==
2012-11-16 14:54:37.247140 [sylk-server 30934] (5) sip_endpoint.c: Processing incoming message: Request msg SUBSCRIBE/cseq=801 (rdata0x7ffbec00f8d8)

==> sip_trace.txt <==
2012-11-16 14:54:37.247234 [sylk-server 30934]: RECEIVED: Packet 6, +0:00:56.635778
10.226.20.240:6060 -(SIP over UDP)-> 10.226.20.56:6060
SUBSCRIBE sip:admin at testing.com SIP/2.0
Record-Route: <sip:mo at 10.226.20.240: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 10.226.20.240:4060;lr>
Via: SIP/2.0/UDP 10.226.20.240:6060;branch=z9hG4bK3ca5.9c0c9b12.0
Via: SIP/2.0/UDP 10.226.20.240:4060;branch=z9hG4bK3ca5.d753df07.0
Via: SIP/2.0/UDP 10.226.20.14:55305;rport=55305;branch=z9hG4bK1353054401575
From: <sip:alice at open-ims.test>;tag=19353
To: <sip:admin at testing.com>
Call-ID: M-a559aab28821c9c967f5686beeb68568
CSeq: 801 SUBSCRIBE
Max-Forwards: 15
Allow: INVITE, ACK, CANCEL, BYE, MESSAGE, OPTIONS, NOTIFY, PRACK, UPDATE, REFER
Contact: <sip:alice at 10.226.20.14:55305;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-CSCFabcd0000000050a64dd8000000f6";icid-generated-at=10.226.20.240;orig-ioi="open-ims.test"


--

==> core_trace.txt <==
2012-11-16 14:54:37.247293 [sylk-server 30934] (5) tsx0x7ffbec028: Transaction created for Request msg SUBSCRIBE/cseq=801 (rdata0x7ffbec00f8d8)
2012-11-16 14:54:37.247349 [sylk-server 30934] (5) tsx0x7ffbec028: Incoming Request msg SUBSCRIBE/cseq=801 (rdata0x7ffbec00f8d8) in state Null
2012-11-16 14:54:37.247405 [sylk-server 30934] (5) tsx0x7ffbec028: State changed from Null to Trying, event=RX_MSG
2012-11-16 14:54:37.247460 [sylk-server 30934] (5) dlg0x7ffbec027: Transaction tsx0x7ffbec028dc8 state changed to Trying
2012-11-16 14:54:37.247514 [sylk-server 30934] (5) dlg0x7ffbec027: UAS dialog created
2012-11-16 14:54:37.247750 [sylk-server 30934] (5) dlg0x7ffbec027: Session count inc to 1 by mod-core
2012-11-16 14:54:37.247816 [sylk-server 30934] (5) dlg0x7ffbec027: Module mod-evsub added as dialog usage, data=0x7ffbec029b10
2012-11-16 14:54:37.247956 [sylk-server 30934] (5) evsub0x7ffbec0: UAS subscription created, using dialog dlg0x7ffbec027b68
2012-11-16 14:54:37.248007 [sylk-server 30934] (5) dlg0x7ffbec027: Session count inc to 3 by mod-evsub
2012-11-16 14:54:37.248065 [sylk-server 30934] (5)       endpoint: Response msg 500/SUBSCRIBE/cseq=801 (tdta0x7ffbec02a1b0) created

==> notifications_trace.txt <==
2012-11-16 14:54:37.270049 [sylk-server 30934]: Notification name=SIPIncomingSubscriptionGotSubscribe sender=<sipsimple.core._core.IncomingSubscription object at 0x7ffbf8b46680>
{'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-a559aab28821c9c967f5686beeb68568'),
             'Contact': [FrozenContactHeader(FrozenSIPURI('10.226.20.14', 'alice', None, 55305, 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': '19353'})),
             '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-CSCFabcd0000000050a64dd8000000f6";icid-generated-at=10.226.20.240;orig-ioi="open-ims.test"'),
             'Privacy': FrozenHeader('Privacy', 'none'),
             'Record-Route': [FrozenRecordRouteHeader(FrozenSIPURI('10.226.20.240', 'mo', None, 6060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({})),
                              FrozenRecordRouteHeader(FrozenSIPURI('10.226.20.240', 'mo', None, 4060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({}))],
             'Route': [FrozenRouteHeader(FrozenSIPURI('10.226.20.56', None, None, 6060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({})),
                       FrozenRouteHeader(FrozenSIPURI('scscf.open-ims.test', 'iscmark', None, 6060, False, frozendict({'a': '7369703a616c696365406f70656e2d696d732e74657374', 'h': '0', 's': '3', 'lr': None, 'd': '0'}), frozendict({})), None, frozendict({}))],
             'Supported': ['eventlist'],
             'To': FrozenToHeader(FrozenSIPURI('testing.com', 'admin', 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': 'z9hG4bK3ca5.9c0c9b12.0'})),
                     FrozenViaHeader('UDP', '10.226.20.240', 4060, frozendict({'branch': 'z9hG4bK3ca5.d753df07.0'})),
                     FrozenViaHeader('UDP', '10.226.20.14', 55305, frozendict({'rport': 55305, 'branch': 'z9hG4bK1353054401575'}))]},
'method': 'SUBSCRIBE',
'request_uri': FrozenSIPURI('testing.com', 'admin', None, None, False, frozendict({}), frozendict({}))}
2012-11-16 14:54:37.273934 [sylk-server 30934]: Notification name=S2XPresenceHandlerDidStart sender=<sylk.applications.xmppgateway.presence.S2XPresenceHandler object at 0x7ffbf8b68590>
{}

==> core_trace.txt <==
2012-11-16 14:54:37.257842 [sylk-server 30934] (5) sip_endpoint.c: Processing incoming message: Request msg NOTIFY/cseq=4 (rdata0x7ffbec00f8d8)

==> sip_trace.txt <==
2012-11-16 14:54:37.258218 [sylk-server 30934]: RECEIVED: Packet 7, +0:00:56.646762
10.226.20.240:6060 -(SIP over UDP)-> 10.226.20.56:6060
NOTIFY sip:wbfhcopd at 10.226.20.56:6060 SIP/2.0
Via: SIP/2.0/UDP 10.226.20.240:6060;branch=z9hG4bKd0b2.89150127.0
Via: SIP/2.0/UDP 10.226.20.56:5080;branch=z9hG4bKd0b2.62b4a8f4.0
To: sip:admin at testing.com;tag=MdlzJqoJndrpldssDBZ-77gVVv87J0fI
From: sip:alice at open-ims.test;tag=48b5b8952e8d0bca6256941910840e90-ce98
CSeq: 4 NOTIFY
Call-ID: cwL-bWBXrIVO2VDXdhneNgOluVudateT
Content-Length: 1210
User-Agent: kamailio (3.3.2 (x86_64/linux))
Max-Forwards: 16
Event: presence
Contact: <sip:10.226.20.56:5080;transport=udp>
Subscription-State: active;expires=2379
Content-Type: application/pidf+xml

<?xml version="1.0" encoding="utf-8"?>
<presence xmlns:cp="urn:ietf:params:xml:ns:pidf:cipid" xmlns:caps="urn:ietf:params:xml:ns:pidf:caps" xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid" xmlns:pdm="urn:ietf:params:xml:ns:pidf:data-model" xmlns:p="urn:ietf:params:xml:ns:pidf-diff" xmlns:op="urn:oma:xml:prs:pidf:oma-pres" xmlns="urn:ietf:params:xml:ns:pidf" entity="sip:alice at open-ims.test">
  <pdm:person id="JXEEVCMM">
    <op:overriding-willingness>
      <op:basic>open</op:basic>
    </op:overriding-willingness>
    <rpid:activities>
      <rpid:unknown/>
    </rpid:activities>
    <rpid:mood>
      <rpid:neutral/>
    </rpid:mood>
    <cp:homepage>http://dir.bg</cp:homepage>
    <pdm:note>TEST TEXT</pdm:note>
  </pdm:person>
  <pdm:device id="d0001">
    <status>
      <basic>open</basic>
    </status>
    <caps:devcaps>
      <caps:mobility>
        <caps:supported>
          <caps:fixed/>
        </caps:supported>
      </caps:mobility>
    </caps:devcaps>
    <op:network-availability>
      <op:network id="IMS">
        <op:active/>
      </op:network>
    </op:network-availability>
    <pdm:deviceID>urn:uuid:3ca50bcb-7a67-44f1-afd0-994a55f930f4</pdm:deviceID>
  </pdm:device>
</presence>

--

==> core_trace.txt <==
2012-11-16 14:54:37.258372 [sylk-server 30934] (5) sip_ua_layer.c: Unable to find dialogset for Request msg NOTIFY/cseq=4 (rdata0x7ffbec00f8d8), answering with 481
2012-11-16 14:54:37.258439 [sylk-server 30934] (5)       endpoint: Response msg 481/NOTIFY/cseq=4 (tdta0x7ffbec02efb0) created
2012-11-16 14:54:37.258496 [sylk-server 30934] (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-16 14:54:37.258624 [sylk-server 30934]: SENDING: Packet 8, +0:00:56.647168
10.226.20.56:6060 -(SIP over UDP)-> 10.226.20.240:6060
SIP/2.0 481 Call/Transaction Does Not Exist
Via: SIP/2.0/UDP 10.226.20.240:6060;received=10.226.20.240;branch=z9hG4bKd0b2.89150127.0
Via: SIP/2.0/UDP 10.226.20.56:5080;branch=z9hG4bKd0b2.62b4a8f4.0
Call-ID: cwL-bWBXrIVO2VDXdhneNgOluVudateT
From: <sip:alice at open-ims.test>;tag=48b5b8952e8d0bca6256941910840e90-ce98
To: <sip:admin at testing.com>;tag=MdlzJqoJndrpldssDBZ-77gVVv87J0fI
CSeq: 4 NOTIFY
Server: SylkServer-2.2.1
Content-Length:  0


--

==> core_trace.txt <==
2012-11-16 14:54:37.258682 [sylk-server 30934] (5) tdta0x7ffbec02: Destroying txdata Response msg 481/NOTIFY/cseq=4 (tdta0x7ffbec02efb0)
2012-11-16 14:54:37.258771 [sylk-server 30934] (5) sip_endpoint.c: Processing incoming message: Request msg NOTIFY/cseq=3 (rdata0x7ffbec00f8d8)

==> sip_trace.txt <==
2012-11-16 14:54:37.258825 [sylk-server 30934]: RECEIVED: Packet 9, +0:00:56.647369
10.226.20.240:6060 -(SIP over UDP)-> 10.226.20.56:6060
NOTIFY sip:wbfhcopd at 10.226.20.56:6060 SIP/2.0
Via: SIP/2.0/UDP 10.226.20.240:6060;branch=z9hG4bKc4e2.a6072fd6.0
Via: SIP/2.0/UDP 10.226.20.56:5080;branch=z9hG4bKc4e2.1e465923.0
To: sip:tihoparvi at testing.com;tag=vmY3-JM85cI1KBs.znJa1BkJzQQQnrwj
From: sip:alice at open-ims.test;tag=48b5b8952e8d0bca6256941910840e90-5b2d
CSeq: 3 NOTIFY
Call-ID: zBKRmUNQR-JyU8Map19R9yZTNKTzTflm
Content-Length: 1210
User-Agent: kamailio (3.3.2 (x86_64/linux))
Max-Forwards: 16
Event: presence
Contact: <sip:10.226.20.56:5080;transport=udp>
Subscription-State: active;expires=2587
Content-Type: application/pidf+xml

<?xml version="1.0" encoding="utf-8"?>
<presence xmlns:cp="urn:ietf:params:xml:ns:pidf:cipid" xmlns:caps="urn:ietf:params:xml:ns:pidf:caps" xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid" xmlns:pdm="urn:ietf:params:xml:ns:pidf:data-model" xmlns:p="urn:ietf:params:xml:ns:pidf-diff" xmlns:op="urn:oma:xml:prs:pidf:oma-pres" xmlns="urn:ietf:params:xml:ns:pidf" entity="sip:alice at open-ims.test">
  <pdm:person id="JXEEVCMM">
    <op:overriding-willingness>
      <op:basic>open</op:basic>
    </op:overriding-willingness>
    <rpid:activities>
      <rpid:unknown/>
    </rpid:activities>
    <rpid:mood>
      <rpid:neutral/>
    </rpid:mood>
    <cp:homepage>http://dir.bg</cp:homepage>
    <pdm:note>TEST TEXT</pdm:note>
  </pdm:person>
  <pdm:device id="d0001">
    <status>
      <basic>open</basic>
    </status>
    <caps:devcaps>
      <caps:mobility>
        <caps:supported>
          <caps:fixed/>
        </caps:supported>
      </caps:mobility>
    </caps:devcaps>
    <op:network-availability>
      <op:network id="IMS">
        <op:active/>
      </op:network>
    </op:network-availability>
    <pdm:deviceID>urn:uuid:3ca50bcb-7a67-44f1-afd0-994a55f930f4</pdm:deviceID>
  </pdm:device>
</presence>

--

==> core_trace.txt <==
2012-11-16 14:54:37.258915 [sylk-server 30934] (5) sip_ua_layer.c: Unable to find dialogset for Request msg NOTIFY/cseq=3 (rdata0x7ffbec00f8d8), answering with 481
2012-11-16 14:54:37.258974 [sylk-server 30934] (5)       endpoint: Response msg 481/NOTIFY/cseq=3 (tdta0x7ffbec02f700) created
2012-11-16 14:54:37.259037 [sylk-server 30934] (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-16 14:54:37.259095 [sylk-server 30934]: SENDING: Packet 10, +0:00:56.647639
10.226.20.56:6060 -(SIP over UDP)-> 10.226.20.240:6060
SIP/2.0 481 Call/Transaction Does Not Exist
Via: SIP/2.0/UDP 10.226.20.240:6060;received=10.226.20.240;branch=z9hG4bKc4e2.a6072fd6.0
Via: SIP/2.0/UDP 10.226.20.56:5080;branch=z9hG4bKc4e2.1e465923.0
Call-ID: zBKRmUNQR-JyU8Map19R9yZTNKTzTflm
From: <sip:alice at open-ims.test>;tag=48b5b8952e8d0bca6256941910840e90-5b2d
To: <sip:tihoparvi at testing.com>;tag=vmY3-JM85cI1KBs.znJa1BkJzQQQnrwj
CSeq: 3 NOTIFY
Server: SylkServer-2.2.1
Content-Length:  0


--

==> core_trace.txt <==
2012-11-16 14:54:37.259151 [sylk-server 30934] (5) tdta0x7ffbec02: Destroying txdata Response msg 481/NOTIFY/cseq=3 (tdta0x7ffbec02f700)
2012-11-16 14:54:37.259217 [sylk-server 30934] (5) sip_endpoint.c: Processing incoming message: Request msg NOTIFY/cseq=3 (rdata0x7ffbec00f8d8)

==> sip_trace.txt <==
2012-11-16 14:54:37.259335 [sylk-server 30934]: RECEIVED: Packet 11, +0:00:56.647879
10.226.20.240:6060 -(SIP over UDP)-> 10.226.20.56:6060
NOTIFY sip:clnheraz at 10.226.20.56:6060 SIP/2.0
Via: SIP/2.0/UDP 10.226.20.240:6060;branch=z9hG4bK8fd4.56a9cd43.0
Via: SIP/2.0/UDP 10.226.20.56:5080;branch=z9hG4bK8fd4.58e325e6.0
To: sip:tihoparvi at testing.com;tag=BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f
From: sip:alice at open-ims.test;tag=48b5b8952e8d0bca6256941910840e90-c9f7
CSeq: 3 NOTIFY
Call-ID: JA7JhBheIYEBluQMcw2-RQ2.lh35CntV
Content-Length: 1210
User-Agent: kamailio (3.3.2 (x86_64/linux))
Max-Forwards: 16
Event: presence
Contact: <sip:10.226.20.56:5080;transport=udp>
Subscription-State: active;expires=3543
Content-Type: application/pidf+xml

<?xml version="1.0" encoding="utf-8"?>
<presence xmlns:cp="urn:ietf:params:xml:ns:pidf:cipid" xmlns:caps="urn:ietf:params:xml:ns:pidf:caps" xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid" xmlns:pdm="urn:ietf:params:xml:ns:pidf:data-model" xmlns:p="urn:ietf:params:xml:ns:pidf-diff" xmlns:op="urn:oma:xml:prs:pidf:oma-pres" xmlns="urn:ietf:params:xml:ns:pidf" entity="sip:alice at open-ims.test">
  <pdm:person id="JXEEVCMM">
    <op:overriding-willingness>
      <op:basic>open</op:basic>
    </op:overriding-willingness>
    <rpid:activities>
      <rpid:unknown/>
    </rpid:activities>
    <rpid:mood>
      <rpid:neutral/>
    </rpid:mood>
    <cp:homepage>http://dir.bg</cp:homepage>
    <pdm:note>TEST TEXT</pdm:note>
  </pdm:person>
  <pdm:device id="d0001">
    <status>
      <basic>open</basic>
    </status>
    <caps:devcaps>
      <caps:mobility>
        <caps:supported>
          <caps:fixed/>
        </caps:supported>
      </caps:mobility>
    </caps:devcaps>
    <op:network-availability>
      <op:network id="IMS">
        <op:active/>
      </op:network>
    </op:network-availability>
    <pdm:deviceID>urn:uuid:3ca50bcb-7a67-44f1-afd0-994a55f930f4</pdm:deviceID>
  </pdm:device>
</presence>

--

==> core_trace.txt <==
2012-11-16 14:54:37.259392 [sylk-server 30934] (5) sip_ua_layer.c: Unable to find dialog for Request msg NOTIFY/cseq=3 (rdata0x7ffbec00f8d8), answering with 481
2012-11-16 14:54:37.259464 [sylk-server 30934] (5)       endpoint: Response msg 481/NOTIFY/cseq=3 (tdta0x7ffbec030b00) created
2012-11-16 14:54:37.259565 [sylk-server 30934] (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-16 14:54:37.259652 [sylk-server 30934]: SENDING: Packet 12, +0:00:56.648196
10.226.20.56:6060 -(SIP over UDP)-> 10.226.20.240:6060
SIP/2.0 481 Call/Transaction Does Not Exist
Via: SIP/2.0/UDP 10.226.20.240:6060;received=10.226.20.240;branch=z9hG4bK8fd4.56a9cd43.0
Via: SIP/2.0/UDP 10.226.20.56:5080;branch=z9hG4bK8fd4.58e325e6.0
Call-ID: JA7JhBheIYEBluQMcw2-RQ2.lh35CntV
From: <sip:alice at open-ims.test>;tag=48b5b8952e8d0bca6256941910840e90-c9f7
To: <sip:tihoparvi at testing.com>;tag=BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f
CSeq: 3 NOTIFY
Server: SylkServer-2.2.1
Content-Length:  0


--

==> core_trace.txt <==
2012-11-16 14:54:37.259709 [sylk-server 30934] (5) tdta0x7ffbec03: Destroying txdata Response msg 481/NOTIFY/cseq=3 (tdta0x7ffbec030b00)

==> notifications_trace.txt <==
2012-11-16 14:54:37.285918 [sylk-server 30934]: Notification name=XMPPSubscriptionDidStart sender=<sylk.applications.xmppgateway.xmpp.subscription.XMPPSubscription object at 0x7ffbf8b64cd0>
{}
2012-11-16 14:54:37.286214 [sylk-server 30934]: Notification name=XMPPSubscriptionChangedState sender=<sylk.applications.xmppgateway.xmpp.subscription.XMPPSubscription object at 0x7ffbf8b64cd0>
{'prev_state': None, 'state': 'subscribe_sent'}

==> xmpp_trace.txt <==
2012-11-16T14:54:37.271906+01:00 [sylk-server 30934]: SENDING: Packet 22, +0:00:56.752367
<presence to='admin at testing.com' from='alice at open-ims.test' type='subscribe'/>
--
2012-11-16T14:54:37.273267+01:00 [sylk-server 30934]: SENDING: Packet 23, +0:00:56.753728
<presence to='admin at testing.com' from='alice at open-ims.test' type='probe'/>
--

==> notifications_trace.txt <==
2012-11-16 14:54:37.286695 [sylk-server 30934]: Notification name=S2XPresenceHandlerDidStart sender=<sylk.applications.xmppgateway.presence.S2XPresenceHandler object at 0x7ffbf8b64910>
{}

==> xmpp_trace.txt <==
2012-11-16T14:54:37.280117+01:00 [sylk-server 30934]: RECEIVED: Packet 24, +0:00:56.760578
<presence from='tihoparvi at testing.com' to='alice at open-ims.test' type='subscribed'/><presence from='tihoparvi at testing.com/CZ-R8LGKEG' 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/CZ-R8LGKEG' stamp='2012-11-16T14:28:44Z'></delay><x xmlns='jabber:x:delay' stamp='20121116T14:28:44'/></presence><message from='tihoparvi at testing.com' to='alice at open-ims.test'><event xmlns='http://jabber.org/protocol/pubsub#event'><items node='http://jabber.org/protocol/mood'><item id='0'><mood xmlns='http://jabber.org/protocol/mood'/></item></items></event><delay xmlns='urn:xmpp:delay' from='tihoparvi at testing.com/Gajim' stamp='2012-11-15T12:38:18Z'></delay></message><message from='tihoparvi at testing.com' to='alice at open-ims.test'><event xmlns='http://jabber.org/protocol/pubsub#event'><items node='http://jabber.org/protocol/activity'><item id='0'><activity xmlns='http://jabber.org/protocol/activity'/></item></items></event><delay xmlns='urn:xmpp:delay' from='tihoparvi at testing.com/Gajim' stamp='2012-11-15T12:38:18Z'></delay></message>
--

==> core_trace.txt <==
2012-11-16 14:54:37.282283 [sylk-server 30934] (5) dlg0x7ffbec020: Sending Response msg 202/SUBSCRIBE/cseq=401 (tdta0x7ffbec023c40)
2012-11-16 14:54:37.282395 [sylk-server 30934] (5) tsx0x7ffbec023: Sending Response msg 202/SUBSCRIBE/cseq=401 (tdta0x7ffbec023c40) in state Trying
2012-11-16 14:54:37.282456 [sylk-server 30934] (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-16 14:54:37.282519 [sylk-server 30934]: SENDING: Packet 13, +0:00:56.671063
10.226.20.56:6060 -(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=z9hG4bK458a.61437682.0
Via: SIP/2.0/UDP 10.226.20.240:4060;branch=z9hG4bK458a.92a1cb12.0
Via: SIP/2.0/UDP 10.226.20.14:55305;rport=55305;branch=z9hG4bK1353054401574
Record-Route: <sip:mo at 10.226.20.240:6060;lr>
Record-Route: <sip:mo at 10.226.20.240:4060;lr>
Call-ID: M-d540f97bacf53a0cc3e6b33bde672a4b
From: <sip:alice at open-ims.test>;tag=2589
To: <sip:tihoparvi at testing.com>;tag=BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f
CSeq: 401 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


--
2012-11-16 14:54:37.283111 [sylk-server 30934]: SENDING: Packet 14, +0:00:56.671655
10.226.20.56:6060 -(SIP over UDP)-> 10.226.20.240:6060
NOTIFY sip:alice at 10.226.20.14:55305;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.226.20.56:6060;rport;branch=z9hG4bKPjwSi5xicEf5AurgbBADneVBfgqOAkTLT4
Max-Forwards: 70
From: <sip:tihoparvi at testing.com>;tag=BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f
To: <sip:alice at open-ims.test>;tag=2589
Contact: <sip:tihoparvi at 10.226.20.56:6060>
Call-ID: M-d540f97bacf53a0cc3e6b33bde672a4b
CSeq: 21969 NOTIFY
Route: <sip:mo at 10.226.20.240:6060;lr>
Route: <sip:mo at 10.226.20.240:4060;lr>
Event: presence
Subscription-State: pending;expires=599999
Allow-Events: conference, refer, presence
User-Agent: SylkServer-2.2.1
Content-Length:  0


--

==> core_trace.txt <==
2012-11-16 14:54:37.282577 [sylk-server 30934] (5) tsx0x7ffbec023: State changed from Trying to Completed, event=TX_MSG
2012-11-16 14:54:37.282671 [sylk-server 30934] (5) dlg0x7ffbec020: Transaction tsx0x7ffbec0234d8 state changed to Completed
2012-11-16 14:54:37.282826 [sylk-server 30934] (5)       endpoint: Request msg NOTIFY/cseq=21970 (tdta0x7ffbf8bdce30) created.
2012-11-16 14:54:37.282883 [sylk-server 30934] (5) dlg0x7ffbec020: Sending Request msg NOTIFY/cseq=21970 (tdta0x7ffbf8bdce30)
2012-11-16 14:54:37.282940 [sylk-server 30934] (5) tsx0x7ffbf8bde: Transaction created for Request msg NOTIFY/cseq=21969 (tdta0x7ffbf8bdce30)
2012-11-16 14:54:37.282996 [sylk-server 30934] (5) tsx0x7ffbf8bde: Sending Request msg NOTIFY/cseq=21969 (tdta0x7ffbf8bdce30) in state Null
2012-11-16 14:54:37.283053 [sylk-server 30934] (5)  sip_resolve.c: Target '10.226.20.240:6060' type=Unspecified resolved to '10.226.20.240:6060' type=UDP (UDP transport)
2012-11-16 14:54:37.283170 [sylk-server 30934] (5) tsx0x7ffbf8bde: State changed from Null to Calling, event=TX_MSG
2012-11-16 14:54:37.283237 [sylk-server 30934] (5) dlg0x7ffbec020: Transaction tsx0x7ffbf8bdee98 state changed to Calling
2012-11-16 14:54:37.283297 [sylk-server 30934] (4) evsub0x7ffbec0: Subscription state changed NULL --> PENDING

==> notifications_trace.txt <==
2012-11-16 14:54:37.289324 [sylk-server 30934]: Notification name=SIPIncomingSubscriptionAnsweredSubscribe sender=<sipsimple.core._core.IncomingSubscription object at 0x7ffbf8b465f0>
{'body': None,
'code': 202,
'headers': {'Allow': ['SUBSCRIBE',
                       'NOTIFY',
                       'PRACK',
                       'INVITE',
                       'ACK',
                       'BYE',
                       'CANCEL',
                       'UPDATE',
                       'MESSAGE',
                       'REFER'],
             'CSeq': (401, 'SUBSCRIBE'),
             'Call-ID': FrozenHeader('Call-ID', 'M-d540f97bacf53a0cc3e6b33bde672a4b'),
             'Contact': [FrozenContactHeader(FrozenSIPURI('10.226.20.56', 'tihoparvi', None, 6060, False, frozendict({}), frozendict({})), None, frozendict({'q': '0.0'}))],
             'Expires': 3600,
             'From': FrozenFromHeader(FrozenSIPURI('open-ims.test', 'alice', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': '2589'})),
             'Record-Route': [FrozenRecordRouteHeader(FrozenSIPURI('10.226.20.240', 'mo', None, 6060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({})),
                              FrozenRecordRouteHeader(FrozenSIPURI('10.226.20.240', 'mo', None, 4060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({}))],
             'Server': FrozenHeader('Server', 'SylkServer-2.2.1'),
             'Supported': ['100rel', 'replaces', 'norefersub', 'gruu'],
             'To': FrozenToHeader(FrozenSIPURI('testing.com', 'tihoparvi', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': 'BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f'})),
             'Via': [FrozenViaHeader('UDP', '10.226.20.240', 6060, frozendict({'received': '10.226.20.240', 'branch': 'z9hG4bK458a.61437682.0'})),
                     FrozenViaHeader('UDP', '10.226.20.240', 4060, frozendict({'branch': 'z9hG4bK458a.92a1cb12.0'})),
                     FrozenViaHeader('UDP', '10.226.20.14', 55305, frozendict({'rport': 55305, 'branch': 'z9hG4bK1353054401574'}))]},
'reason': 'Accepted'}
2012-11-16 14:54:37.289540 [sylk-server 30934]: Notification name=SIPIncomingSubscriptionChangedState sender=<sipsimple.core._core.IncomingSubscription object at 0x7ffbf8b465f0>
{'prev_state': 'incoming', 'state': 'pending'}

==> core_trace.txt <==

==> sip_trace.txt <==

==> core_trace.txt <==

==> notifications_trace.txt <==
2012-11-16 14:54:37.301952 [sylk-server 30934]: Notification name=SIPIncomingSubscriptionSentNotify sender=<sipsimple.core._core.IncomingSubscription object at 0x7ffbf8b465f0>
{'body': None,
'headers': {'Allow-Events': ['conference', 'refer', 'presence'],
             'CSeq': (21969, 'NOTIFY'),
             'Call-ID': FrozenHeader('Call-ID', 'M-d540f97bacf53a0cc3e6b33bde672a4b'),
             'Contact': [FrozenContactHeader(FrozenSIPURI('10.226.20.56', 'tihoparvi', None, 6060, False, frozendict({}), frozendict({})), None, frozendict({'q': '0.0'}))],
             'Event': FrozenEventHeader('presence', frozendict({})),
             'From': FrozenFromHeader(FrozenSIPURI('testing.com', 'tihoparvi', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': 'BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f'})),
             'Max-Forwards': 70,
             'Route': [FrozenRouteHeader(FrozenSIPURI('10.226.20.240', 'mo', None, 6060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({})),
                       FrozenRouteHeader(FrozenSIPURI('10.226.20.240', 'mo', None, 4060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({}))],
             'Subscription-State': FrozenSubscriptionStateHeader('pending', frozendict({'expires': '599999'})),
             'To': FrozenToHeader(FrozenSIPURI('open-ims.test', 'alice', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': '2589'})),
             'User-Agent': FrozenHeader('User-Agent', 'SylkServer-2.2.1'),
             'Via': [FrozenViaHeader('UDP', '10.226.20.56', 6060, frozendict({'rport': 0, 'branch': 'z9hG4bKPjwSi5xicEf5AurgbBADneVBfgqOAkTLT4'}))]},
'method': 'NOTIFY',
'request_uri': FrozenSIPURI('10.226.20.14', 'alice', None, 55305, False, frozendict({'transport': 'udp'}), frozendict({}))}

==> core_trace.txt <==
2012-11-16 14:54:37.283413 [sylk-server 30934] (5) dlg0x7ffbec027: Sending Response msg 202/SUBSCRIBE/cseq=801 (tdta0x7ffbec02a1b0)
2012-11-16 14:54:37.283469 [sylk-server 30934] (5) tsx0x7ffbec028: Sending Response msg 202/SUBSCRIBE/cseq=801 (tdta0x7ffbec02a1b0) in state Trying
2012-11-16 14:54:37.283526 [sylk-server 30934] (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-16 14:54:37.283586 [sylk-server 30934]: SENDING: Packet 15, +0:00:56.672130
10.226.20.56:6060 -(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=z9hG4bK3ca5.9c0c9b12.0
Via: SIP/2.0/UDP 10.226.20.240:4060;branch=z9hG4bK3ca5.d753df07.0
Via: SIP/2.0/UDP 10.226.20.14:55305;rport=55305;branch=z9hG4bK1353054401575
Record-Route: <sip:mo at 10.226.20.240:6060;lr>
Record-Route: <sip:mo at 10.226.20.240:4060;lr>
Call-ID: M-a559aab28821c9c967f5686beeb68568
From: <sip:alice at open-ims.test>;tag=19353
To: <sip:admin at testing.com>;tag=JA7JhBheIYEBluQMcw2-RQ2.lh35CntV
CSeq: 801 SUBSCRIBE
Contact: <sip:admin 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


--
2012-11-16 14:54:37.284270 [sylk-server 30934]: SENDING: Packet 16, +0:00:56.672814
10.226.20.56:6060 -(SIP over UDP)-> 10.226.20.240:6060
NOTIFY sip:alice at 10.226.20.14:55305;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.226.20.56:6060;rport;branch=z9hG4bKPjMr9UB.WXqoxm6tRnoc8SczPEhE.TvtC2
Max-Forwards: 70
From: <sip:admin at testing.com>;tag=JA7JhBheIYEBluQMcw2-RQ2.lh35CntV
To: <sip:alice at open-ims.test>;tag=19353
Contact: <sip:admin at 10.226.20.56:6060>
Call-ID: M-a559aab28821c9c967f5686beeb68568
CSeq: 19229 NOTIFY
Route: <sip:mo at 10.226.20.240:6060;lr>
Route: <sip:mo at 10.226.20.240:4060;lr>
Event: presence
Subscription-State: pending;expires=599999
Allow-Events: conference, refer, presence
User-Agent: SylkServer-2.2.1
Content-Length:  0


--

==> core_trace.txt <==
2012-11-16 14:54:37.283662 [sylk-server 30934] (5) tsx0x7ffbec028: State changed from Trying to Completed, event=TX_MSG
2012-11-16 14:54:37.283722 [sylk-server 30934] (5) dlg0x7ffbec027: Transaction tsx0x7ffbec028dc8 state changed to Completed
2012-11-16 14:54:37.283900 [sylk-server 30934] (5)       endpoint: Request msg NOTIFY/cseq=19230 (tdta0x7ffbf8be69c0) created.
2012-11-16 14:54:37.283975 [sylk-server 30934] (5) dlg0x7ffbec027: Sending Request msg NOTIFY/cseq=19230 (tdta0x7ffbf8be69c0)
2012-11-16 14:54:37.284037 [sylk-server 30934] (5) tsx0x7ffbf8be8: Transaction created for Request msg NOTIFY/cseq=19229 (tdta0x7ffbf8be69c0)
2012-11-16 14:54:37.284098 [sylk-server 30934] (5) tsx0x7ffbf8be8: Sending Request msg NOTIFY/cseq=19229 (tdta0x7ffbf8be69c0) in state Null
2012-11-16 14:54:37.284153 [sylk-server 30934] (5)  sip_resolve.c: Target '10.226.20.240:6060' type=Unspecified resolved to '10.226.20.240:6060' type=UDP (UDP transport)
2012-11-16 14:54:37.284370 [sylk-server 30934] (5) tsx0x7ffbf8be8: State changed from Null to Calling, event=TX_MSG
2012-11-16 14:54:37.284434 [sylk-server 30934] (5) dlg0x7ffbec027: Transaction tsx0x7ffbf8be8a28 state changed to Calling
2012-11-16 14:54:37.284552 [sylk-server 30934] (4) evsub0x7ffbec0: Subscription state changed NULL --> PENDING

==> notifications_trace.txt <==
2012-11-16 14:54:37.304954 [sylk-server 30934]: Notification name=SIPIncomingSubscriptionAnsweredSubscribe sender=<sipsimple.core._core.IncomingSubscription object at 0x7ffbf8b46680>
{'body': None,
'code': 202,
'headers': {'Allow': ['SUBSCRIBE',
                       'NOTIFY',
                       'PRACK',
                       'INVITE',
                       'ACK',
                       'BYE',
                       'CANCEL',
                       'UPDATE',
                       'MESSAGE',
                       'REFER'],
             'CSeq': (801, 'SUBSCRIBE'),
             'Call-ID': FrozenHeader('Call-ID', 'M-a559aab28821c9c967f5686beeb68568'),
             'Contact': [FrozenContactHeader(FrozenSIPURI('10.226.20.56', 'admin', None, 6060, False, frozendict({}), frozendict({})), None, frozendict({'q': '0.0'}))],
             'Expires': 3600,
             'From': FrozenFromHeader(FrozenSIPURI('open-ims.test', 'alice', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': '19353'})),
             'Record-Route': [FrozenRecordRouteHeader(FrozenSIPURI('10.226.20.240', 'mo', None, 6060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({})),
                              FrozenRecordRouteHeader(FrozenSIPURI('10.226.20.240', 'mo', None, 4060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({}))],
             'Server': FrozenHeader('Server', 'SylkServer-2.2.1'),
             'Supported': ['100rel', 'replaces', 'norefersub', 'gruu'],
             'To': FrozenToHeader(FrozenSIPURI('testing.com', 'admin', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': 'JA7JhBheIYEBluQMcw2-RQ2.lh35CntV'})),
             'Via': [FrozenViaHeader('UDP', '10.226.20.240', 6060, frozendict({'received': '10.226.20.240', 'branch': 'z9hG4bK3ca5.9c0c9b12.0'})),
                     FrozenViaHeader('UDP', '10.226.20.240', 4060, frozendict({'branch': 'z9hG4bK3ca5.d753df07.0'})),
                     FrozenViaHeader('UDP', '10.226.20.14', 55305, frozendict({'rport': 55305, 'branch': 'z9hG4bK1353054401575'}))]},
'reason': 'Accepted'}
2012-11-16 14:54:37.305169 [sylk-server 30934]: Notification name=SIPIncomingSubscriptionChangedState sender=<sipsimple.core._core.IncomingSubscription object at 0x7ffbf8b46680>
{'prev_state': 'incoming', 'state': 'pending'}

==> core_trace.txt <==

==> sip_trace.txt <==

==> core_trace.txt <==

==> notifications_trace.txt <==
2012-11-16 14:54:37.312919 [sylk-server 30934]: Notification name=SIPIncomingSubscriptionSentNotify sender=<sipsimple.core._core.IncomingSubscription object at 0x7ffbf8b46680>
{'body': None,
'headers': {'Allow-Events': ['conference', 'refer', 'presence'],
             'CSeq': (19229, 'NOTIFY'),
             'Call-ID': FrozenHeader('Call-ID', 'M-a559aab28821c9c967f5686beeb68568'),
             'Contact': [FrozenContactHeader(FrozenSIPURI('10.226.20.56', 'admin', None, 6060, False, frozendict({}), frozendict({})), None, frozendict({'q': '0.0'}))],
             'Event': FrozenEventHeader('presence', frozendict({})),
             'From': FrozenFromHeader(FrozenSIPURI('testing.com', 'admin', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': 'JA7JhBheIYEBluQMcw2-RQ2.lh35CntV'})),
             'Max-Forwards': 70,
             'Route': [FrozenRouteHeader(FrozenSIPURI('10.226.20.240', 'mo', None, 6060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({})),
                       FrozenRouteHeader(FrozenSIPURI('10.226.20.240', 'mo', None, 4060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({}))],
             'Subscription-State': FrozenSubscriptionStateHeader('pending', frozendict({'expires': '599999'})),
             'To': FrozenToHeader(FrozenSIPURI('open-ims.test', 'alice', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': '19353'})),
             'User-Agent': FrozenHeader('User-Agent', 'SylkServer-2.2.1'),
             'Via': [FrozenViaHeader('UDP', '10.226.20.56', 6060, frozendict({'rport': 0, 'branch': 'z9hG4bKPjMr9UB.WXqoxm6tRnoc8SczPEhE.TvtC2'}))]},
'method': 'NOTIFY',
'request_uri': FrozenSIPURI('10.226.20.14', 'alice', None, 55305, False, frozendict({'transport': 'udp'}), frozendict({}))}

==> core_trace.txt <==
2012-11-16 14:54:37.292463 [sylk-server 30934] (5) sip_endpoint.c: Processing incoming message: Response msg 200/NOTIFY/cseq=21969 (rdata0x7ffbec00f8d8)

==> sip_trace.txt <==
2012-11-16 14:54:37.292568 [sylk-server 30934]: RECEIVED: Packet 17, +0:00:56.681112
10.226.20.240:6060 -(SIP over UDP)-> 10.226.20.56:6060
SIP/2.0 200 OK
Max-Forwards: 70
User-Agent: IM-client/OMA1.0 Mercuro-Gold/v4.0.1631.0
Via: SIP/2.0/UDP 10.226.20.56:6060;rport=6060;branch=z9hG4bKPjwSi5xicEf5AurgbBADneVBfgqOAkTLT4
From: <sip:tihoparvi at testing.com>;tag=BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f
To: <sip:alice at open-ims.test>;tag=2589
Call-ID: M-d540f97bacf53a0cc3e6b33bde672a4b
CSeq: 21969 NOTIFY
Privacy: none
Content-Length: 0


--

==> core_trace.txt <==
2012-11-16 14:54:37.292636 [sylk-server 30934] (5) tsx0x7ffbf8bde: Incoming Response msg 200/NOTIFY/cseq=21969 (rdata0x7ffbec00f8d8) in state Calling
2012-11-16 14:54:37.292693 [sylk-server 30934] (5) tsx0x7ffbf8bde: State changed from Calling to Completed, event=RX_MSG
2012-11-16 14:54:37.292750 [sylk-server 30934] (5) dlg0x7ffbec020: Received Response msg 200/NOTIFY/cseq=21969 (rdata0x7ffbec00f8d8)
2012-11-16 14:54:37.292806 [sylk-server 30934] (5) dlg0x7ffbec020: Transaction tsx0x7ffbf8bdee98 state changed to Completed

==> notifications_trace.txt <==
2012-11-16 14:54:37.323279 [sylk-server 30934]: Notification name=SIPIncomingSubscriptionNotifyDidSucceed sender=<sipsimple.core._core.IncomingSubscription object at 0x7ffbf8b465f0>
{'body': None,
'code': 200,
'headers': {'CSeq': (21969, 'NOTIFY'),
             'Call-ID': FrozenHeader('Call-ID', 'M-d540f97bacf53a0cc3e6b33bde672a4b'),
             'Content-Length': 0,
             'From': FrozenFromHeader(FrozenSIPURI('testing.com', 'tihoparvi', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': 'BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f'})),
             'Max-Forwards': 70,
             'Privacy': FrozenHeader('Privacy', 'none'),
             'To': FrozenToHeader(FrozenSIPURI('open-ims.test', 'alice', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': '2589'})),
             'User-Agent': FrozenHeader('User-Agent', 'IM-client/OMA1.0 Mercuro-Gold/v4.0.1631.0'),
             'Via': [FrozenViaHeader('UDP', '10.226.20.56', 6060, frozendict({'rport': 6060, 'branch': 'z9hG4bKPjwSi5xicEf5AurgbBADneVBfgqOAkTLT4'}))]},
'reason': 'OK'}

==> core_trace.txt <==
2012-11-16 14:54:37.293120 [sylk-server 30934] (5) sip_endpoint.c: Processing incoming message: Response msg 200/NOTIFY/cseq=19229 (rdata0x7ffbec00f8d8)

==> sip_trace.txt <==
2012-11-16 14:54:37.293191 [sylk-server 30934]: RECEIVED: Packet 18, +0:00:56.681735
10.226.20.240:6060 -(SIP over UDP)-> 10.226.20.56:6060
SIP/2.0 200 OK
Max-Forwards: 70
User-Agent: IM-client/OMA1.0 Mercuro-Gold/v4.0.1631.0
Via: SIP/2.0/UDP 10.226.20.56:6060;rport=6060;branch=z9hG4bKPjMr9UB.WXqoxm6tRnoc8SczPEhE.TvtC2
From: <sip:admin at testing.com>;tag=JA7JhBheIYEBluQMcw2-RQ2.lh35CntV
To: <sip:alice at open-ims.test>;tag=19353
Call-ID: M-a559aab28821c9c967f5686beeb68568
CSeq: 19229 NOTIFY
Privacy: none
Content-Length: 0


--

==> core_trace.txt <==
2012-11-16 14:54:37.293249 [sylk-server 30934] (5) tsx0x7ffbf8be8: Incoming Response msg 200/NOTIFY/cseq=19229 (rdata0x7ffbec00f8d8) in state Calling
2012-11-16 14:54:37.293305 [sylk-server 30934] (5) tsx0x7ffbf8be8: State changed from Calling to Completed, event=RX_MSG
2012-11-16 14:54:37.293361 [sylk-server 30934] (5) dlg0x7ffbec027: Received Response msg 200/NOTIFY/cseq=19229 (rdata0x7ffbec00f8d8)
2012-11-16 14:54:37.293417 [sylk-server 30934] (5) dlg0x7ffbec027: Transaction tsx0x7ffbf8be8a28 state changed to Completed

==> notifications_trace.txt <==
2012-11-16 14:54:37.328009 [sylk-server 30934]: Notification name=SIPIncomingSubscriptionNotifyDidSucceed sender=<sipsimple.core._core.IncomingSubscription object at 0x7ffbf8b46680>
{'body': None,
'code': 200,
'headers': {'CSeq': (19229, 'NOTIFY'),
             'Call-ID': FrozenHeader('Call-ID', 'M-a559aab28821c9c967f5686beeb68568'),
             'Content-Length': 0,
             'From': FrozenFromHeader(FrozenSIPURI('testing.com', 'admin', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': 'JA7JhBheIYEBluQMcw2-RQ2.lh35CntV'})),
             'Max-Forwards': 70,
             'Privacy': FrozenHeader('Privacy', 'none'),
             'To': FrozenToHeader(FrozenSIPURI('open-ims.test', 'alice', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': '19353'})),
             'User-Agent': FrozenHeader('User-Agent', 'IM-client/OMA1.0 Mercuro-Gold/v4.0.1631.0'),
             'Via': [FrozenViaHeader('UDP', '10.226.20.56', 6060, frozendict({'rport': 6060, 'branch': 'z9hG4bKPjMr9UB.WXqoxm6tRnoc8SczPEhE.TvtC2'}))]},
'reason': 'OK'}
2012-11-16 14:54:37.328468 [sylk-server 30934]: Notification name=XMPPGotPresenceSubscriptionStatus sender=<wokkel.component.InternalComponent object at 0x7ffbf8ab2310>
{'presence_stanza': <sylk.applications.xmppgateway.xmpp.stanzas.SubscriptionPresence object at 0x7ffbf8b72d90>}
2012-11-16 14:54:37.328966 [sylk-server 30934]: Notification name=XMPPGotPresenceAvailability sender=<wokkel.component.InternalComponent object at 0x7ffbf8ab2310>
{'presence_stanza': <sylk.applications.xmppgateway.xmpp.stanzas.AvailabilityPresence object at 0x7ffbf8b79610>}
2012-11-16 14:54:37.329370 [sylk-server 30934]: Notification name=SIPIncomingSubscriptionChangedState sender=<sipsimple.core._core.IncomingSubscription object at 0x7ffbf8b465f0>
{'prev_state': 'pending', 'state': 'active'}

==> core_trace.txt <==
2012-11-16 14:54:37.306864 [sylk-server 30934] (5)       endpoint: Request msg NOTIFY/cseq=21971 (tdta0x7ffbf8c37c30) created.
2012-11-16 14:54:37.306979 [sylk-server 30934] (5) dlg0x7ffbec020: Sending Request msg NOTIFY/cseq=21971 (tdta0x7ffbf8c37c30)
2012-11-16 14:54:37.308289 [sylk-server 30934] (5) tsx0x7ffbf8be1: Transaction created for Request msg NOTIFY/cseq=21970 (tdta0x7ffbf8c37c30)
2012-11-16 14:54:37.308354 [sylk-server 30934] (5) tsx0x7ffbf8be1: Sending Request msg NOTIFY/cseq=21970 (tdta0x7ffbf8c37c30) in state Null
2012-11-16 14:54:37.308420 [sylk-server 30934] (5)  sip_resolve.c: Target '10.226.20.240:6060' type=Unspecified resolved to '10.226.20.240:6060' type=UDP (UDP transport)

==> sip_trace.txt <==
2012-11-16 14:54:37.308481 [sylk-server 30934]: SENDING: Packet 19, +0:00:56.697025
10.226.20.56:6060 -(SIP over UDP)-> 10.226.20.240:6060
NOTIFY sip:alice at 10.226.20.14:55305;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.226.20.56:6060;rport;branch=z9hG4bKPjHWRaJFRzxz9ry94cs-tGhnHNYVa5aqKL
Max-Forwards: 70
From: <sip:tihoparvi at testing.com>;tag=BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f
To: <sip:alice at open-ims.test>;tag=2589
Contact: <sip:tihoparvi at 10.226.20.56:6060>
Call-ID: M-d540f97bacf53a0cc3e6b33bde672a4b
CSeq: 21970 NOTIFY
Route: <sip:mo at 10.226.20.240:6060;lr>
Route: <sip:mo at 10.226.20.240:4060;lr>
Event: presence
Subscription-State: active;expires=599999
Allow-Events: conference, refer, presence
User-Agent: SylkServer-2.2.1
Content-Length:  0


--

==> core_trace.txt <==
2012-11-16 14:54:37.308548 [sylk-server 30934] (5) sip_endpoint.c: Processing incoming message: Response msg 200/NOTIFY/cseq=21970 (rdata0x7ffbec00f8d8)
2012-11-16 14:54:37.308630 [sylk-server 30934] (5) tsx0x7ffbf8be1: State changed from Null to Calling, event=TX_MSG
2012-11-16 14:54:37.308687 [sylk-server 30934] (5) dlg0x7ffbec020: Transaction tsx0x7ffbf8be1f08 state changed to Calling

==> sip_trace.txt <==
2012-11-16 14:54:37.308753 [sylk-server 30934]: RECEIVED: Packet 20, +0:00:56.697297
10.226.20.240:6060 -(SIP over UDP)-> 10.226.20.56:6060
SIP/2.0 200 OK
Max-Forwards: 70
User-Agent: IM-client/OMA1.0 Mercuro-Gold/v4.0.1631.0
Via: SIP/2.0/UDP 10.226.20.56:6060;rport=6060;branch=z9hG4bKPjHWRaJFRzxz9ry94cs-tGhnHNYVa5aqKL
From: <sip:tihoparvi at testing.com>;tag=BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f
To: <sip:alice at open-ims.test>;tag=2589
Call-ID: M-d540f97bacf53a0cc3e6b33bde672a4b
CSeq: 21970 NOTIFY
Privacy: none
Content-Length: 0


--

==> core_trace.txt <==
2012-11-16 14:54:37.308808 [sylk-server 30934] (5) tsx0x7ffbf8be1: Incoming Response msg 200/NOTIFY/cseq=21970 (rdata0x7ffbec00f8d8) in state Calling
2012-11-16 14:54:37.308864 [sylk-server 30934] (5) tsx0x7ffbf8be1: State changed from Calling to Completed, event=RX_MSG
2012-11-16 14:54:37.308917 [sylk-server 30934] (4) evsub0x7ffbec0: Subscription state changed PENDING --> ACTIVE

==> notifications_trace.txt <==
2012-11-16 14:54:37.335017 [sylk-server 30934]: Notification name=SIPIncomingSubscriptionSentNotify sender=<sipsimple.core._core.IncomingSubscription object at 0x7ffbf8b465f0>
{'body': None,
'headers': {'Allow-Events': ['conference', 'refer', 'presence'],
             'CSeq': (21970, 'NOTIFY'),
             'Call-ID': FrozenHeader('Call-ID', 'M-d540f97bacf53a0cc3e6b33bde672a4b'),
             'Contact': [FrozenContactHeader(FrozenSIPURI('10.226.20.56', 'tihoparvi', None, 6060, False, frozendict({}), frozendict({})), None, frozendict({'q': '0.0'}))],
             'Event': FrozenEventHeader('presence', frozendict({})),
             'From': FrozenFromHeader(FrozenSIPURI('testing.com', 'tihoparvi', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': 'BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f'})),
             'Max-Forwards': 70,
             'Route': [FrozenRouteHeader(FrozenSIPURI('10.226.20.240', 'mo', None, 6060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({})),
                       FrozenRouteHeader(FrozenSIPURI('10.226.20.240', 'mo', None, 4060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({}))],
             'Subscription-State': FrozenSubscriptionStateHeader('active', frozendict({'expires': '599999'})),
             'To': FrozenToHeader(FrozenSIPURI('open-ims.test', 'alice', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': '2589'})),
             'User-Agent': FrozenHeader('User-Agent', 'SylkServer-2.2.1'),
             'Via': [FrozenViaHeader('UDP', '10.226.20.56', 6060, frozendict({'rport': 0, 'branch': 'z9hG4bKPjHWRaJFRzxz9ry94cs-tGhnHNYVa5aqKL'}))]},
'method': 'NOTIFY',
'request_uri': FrozenSIPURI('10.226.20.14', 'alice', None, 55305, False, frozendict({'transport': 'udp'}), frozendict({}))}

==> core_trace.txt <==
2012-11-16 14:54:37.309008 [sylk-server 30934] (5) dlg0x7ffbec020: Received Response msg 200/NOTIFY/cseq=21970 (rdata0x7ffbec00f8d8)
2012-11-16 14:54:37.309160 [sylk-server 30934] (5) dlg0x7ffbec020: Transaction tsx0x7ffbf8be1f08 state changed to Completed

==> notifications_trace.txt <==
2012-11-16 14:54:37.337119 [sylk-server 30934]: Notification name=SIPIncomingSubscriptionNotifyDidSucceed sender=<sipsimple.core._core.IncomingSubscription object at 0x7ffbf8b465f0>
{'body': None,
'code': 200,
'headers': {'CSeq': (21970, 'NOTIFY'),
             'Call-ID': FrozenHeader('Call-ID', 'M-d540f97bacf53a0cc3e6b33bde672a4b'),
             'Content-Length': 0,
             'From': FrozenFromHeader(FrozenSIPURI('testing.com', 'tihoparvi', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': 'BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f'})),
             'Max-Forwards': 70,
             'Privacy': FrozenHeader('Privacy', 'none'),
             'To': FrozenToHeader(FrozenSIPURI('open-ims.test', 'alice', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': '2589'})),
             'User-Agent': FrozenHeader('User-Agent', 'IM-client/OMA1.0 Mercuro-Gold/v4.0.1631.0'),
             'Via': [FrozenViaHeader('UDP', '10.226.20.56', 6060, frozendict({'rport': 6060, 'branch': 'z9hG4bKPjHWRaJFRzxz9ry94cs-tGhnHNYVa5aqKL'}))]},
'reason': 'OK'}
2012-11-16 14:54:37.337561 [sylk-server 30934]: Notification name=XMPPSubscriptionChangedState sender=<sylk.applications.xmppgateway.xmpp.subscription.XMPPSubscription object at 0x7ffbf8b685d0>
{'prev_state': 'subscribe_sent', 'state': 'active'}
2012-11-16 14:54:37.337904 [sylk-server 30934]: Notification name=XMPPSubscriptionGotNotify sender=<sylk.applications.xmppgateway.xmpp.subscription.XMPPSubscription object at 0x7ffbf8b685d0>
{'presence': <sylk.applications.xmppgateway.xmpp.stanzas.AvailabilityPresence object at 0x7ffbf8b79610>}

==> core_trace.txt <==
2012-11-16 14:54:37.324877 [sylk-server 30934] (5)       endpoint: Request msg NOTIFY/cseq=21972 (tdta0x7ffbf8c57a80) created.
2012-11-16 14:54:37.325082 [sylk-server 30934] (5) dlg0x7ffbec020: Sending Request msg NOTIFY/cseq=21972 (tdta0x7ffbf8c57a80)
2012-11-16 14:54:37.325141 [sylk-server 30934] (5) tsx0x7ffbf8c59: Transaction created for Request msg NOTIFY/cseq=21971 (tdta0x7ffbf8c57a80)
2012-11-16 14:54:37.325198 [sylk-server 30934] (5) tsx0x7ffbf8c59: Sending Request msg NOTIFY/cseq=21971 (tdta0x7ffbf8c57a80) in state Null
2012-11-16 14:54:37.325253 [sylk-server 30934] (5)  sip_resolve.c: Target '10.226.20.240:6060' type=Unspecified resolved to '10.226.20.240:6060' type=UDP (UDP transport)

==> sip_trace.txt <==
2012-11-16 14:54:37.325324 [sylk-server 30934]: SENDING: Packet 21, +0:00:56.713868
10.226.20.56:6060 -(SIP over UDP)-> 10.226.20.240:6060
NOTIFY sip:alice at 10.226.20.14:55305;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.226.20.56:6060;rport;branch=z9hG4bKPj.KdbjAR3winyY.lRZBYtFJbCFO2OPN3M
Max-Forwards: 70
From: <sip:tihoparvi at testing.com>;tag=BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f
To: <sip:alice at open-ims.test>;tag=2589
Contact: <sip:tihoparvi at 10.226.20.56:6060>
Call-ID: M-d540f97bacf53a0cc3e6b33bde672a4b
CSeq: 21971 NOTIFY
Route: <sip:mo at 10.226.20.240:6060;lr>
Route: <sip:mo at 10.226.20.240:4060;lr>
Event: presence
Subscription-State: active;expires=599999
Allow-Events: conference, refer, presence
User-Agent: SylkServer-2.2.1
Content-Type: application/pidf+xml
Content-Length:   873

<?xml version='1.0' encoding='UTF-8'?>
<presence xmlns:dm="urn:ietf:params:xml:ns:pidf:data-model" xmlns:agp-pidf="urn:ag-projects:xml:ns:pidf" xmlns:caps="urn:ietf:params:xml:ns:pidf:caps" xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid" xmlns="urn:ietf:params:xml:ns:pidf" entity="tihoparvi%40testing.com"><tuple id="ID-435a2d52384c474b4547"><status><basic>open</basic><agp-pidf:extended>available</agp-pidf:extended></status><dm:deviceID>435a2d52384c474b4547</dm:deviceID><agp-pidf:device-info id="435a2d52384c474b4547"><agp-pidf:description>CZ-R8LGKEG</agp-pidf:description></agp-pidf:device-info><caps:servcaps><caps:message>true</caps:message><caps:text>true</caps:text></caps:servcaps><contact>sip%3Atihoparvi%40testing.com%3Bxmpp%3Bgr%3D435a2d52384c474b4547</contact></tuple><dm:person id="ID-ed8975ecb63f91ca1146ca625b6fca2d"><rpid:activities/></dm:person></presence>
--

==> core_trace.txt <==
2012-11-16 14:54:37.325382 [sylk-server 30934] (5) tsx0x7ffbf8c59: State changed from Null to Calling, event=TX_MSG
2012-11-16 14:54:37.325438 [sylk-server 30934] (5) dlg0x7ffbec020: Transaction tsx0x7ffbf8c59ae8 state changed to Calling
2012-11-16 14:54:37.325497 [sylk-server 30934] (4) evsub0x7ffbec0: Subscription state changed ACTIVE --> ACTIVE

==> notifications_trace.txt <==
2012-11-16 14:54:37.343392 [sylk-server 30934]: Notification name=SIPIncomingSubscriptionSentNotify sender=<sipsimple.core._core.IncomingSubscription object at 0x7ffbf8b465f0>
{'body': '<?xml version=\'1.0\' encoding=\'UTF-8\'?>\n<presence xmlns:dm="urn:ietf:params:xml:ns:pidf:data-model" xmlns:agp-pidf="urn:ag-projects:xml:ns:pidf" xmlns:caps="urn:ietf:params:xml:ns:pidf:caps" xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid" xmlns="urn:ietf:params:xml:ns:pidf" entity="tihoparvi%40testing.com"><tuple id="ID-435a2d52384c474b4547"><status><basic>open</basic><agp-pidf:extended>available</agp-pidf:extended></status><dm:deviceID>435a2d52384c474b4547</dm:deviceID><agp-pidf:device-info id="435a2d52384c474b4547"><agp-pidf:description>CZ-R8LGKEG</agp-pidf:description></agp-pidf:device-info><caps:servcaps><caps:message>true</caps:message><caps:text>true</caps:text></caps:servcaps><contact>sip%3Atihoparvi%40testing.com%3Bxmpp%3Bgr%3D435a2d52384c474b4547</contact></tuple><dm:person id="ID-ed8975ecb63f91ca1146ca625b6fca2d"><rpid:activities/></dm:person></presence>',
'headers': {'Allow-Events': ['conference', 'refer', 'presence'],
             'CSeq': (21971, 'NOTIFY'),
             'Call-ID': FrozenHeader('Call-ID', 'M-d540f97bacf53a0cc3e6b33bde672a4b'),
             'Contact': [FrozenContactHeader(FrozenSIPURI('10.226.20.56', 'tihoparvi', None, 6060, False, frozendict({}), frozendict({})), None, frozendict({'q': '0.0'}))],
             'Event': FrozenEventHeader('presence', frozendict({})),
             'From': FrozenFromHeader(FrozenSIPURI('testing.com', 'tihoparvi', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': 'BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f'})),
             'Max-Forwards': 70,
             'Route': [FrozenRouteHeader(FrozenSIPURI('10.226.20.240', 'mo', None, 6060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({})),
                       FrozenRouteHeader(FrozenSIPURI('10.226.20.240', 'mo', None, 4060, False, frozendict({'lr': None}), frozendict({})), None, frozendict({}))],
             'Subscription-State': FrozenSubscriptionStateHeader('active', frozendict({'expires': '599999'})),
             'To': FrozenToHeader(FrozenSIPURI('open-ims.test', 'alice', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': '2589'})),
             'User-Agent': FrozenHeader('User-Agent', 'SylkServer-2.2.1'),
             'Via': [FrozenViaHeader('UDP', '10.226.20.56', 6060, frozendict({'rport': 0, 'branch': 'z9hG4bKPj.KdbjAR3winyY.lRZBYtFJbCFO2OPN3M'}))]},
'method': 'NOTIFY',
'request_uri': FrozenSIPURI('10.226.20.14', 'alice', None, 55305, False, frozendict({'transport': 'udp'}), frozendict({}))}

==> core_trace.txt <==
2012-11-16 14:54:37.325599 [sylk-server 30934] (5) sip_endpoint.c: Processing incoming message: Response msg 200/NOTIFY/cseq=21971 (rdata0x7ffbec00f8d8)

==> sip_trace.txt <==
2012-11-16 14:54:37.325656 [sylk-server 30934]: RECEIVED: Packet 22, +0:00:56.714200
10.226.20.240:6060 -(SIP over UDP)-> 10.226.20.56:6060
SIP/2.0 200 OK
Max-Forwards: 70
User-Agent: IM-client/OMA1.0 Mercuro-Gold/v4.0.1631.0
Via: SIP/2.0/UDP 10.226.20.56:6060;rport=6060;branch=z9hG4bKPj.KdbjAR3winyY.lRZBYtFJbCFO2OPN3M
From: <sip:tihoparvi at testing.com>;tag=BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f
To: <sip:alice at open-ims.test>;tag=2589
Call-ID: M-d540f97bacf53a0cc3e6b33bde672a4b
CSeq: 21971 NOTIFY
Privacy: none
Content-Length: 0


--

==> core_trace.txt <==
2012-11-16 14:54:37.325712 [sylk-server 30934] (5) tsx0x7ffbf8c59: Incoming Response msg 200/NOTIFY/cseq=21971 (rdata0x7ffbec00f8d8) in state Calling
2012-11-16 14:54:37.325767 [sylk-server 30934] (5) tsx0x7ffbf8c59: State changed from Calling to Completed, event=RX_MSG
2012-11-16 14:54:37.325821 [sylk-server 30934] (5) dlg0x7ffbec020: Received Response msg 200/NOTIFY/cseq=21971 (rdata0x7ffbec00f8d8)
2012-11-16 14:54:37.325885 [sylk-server 30934] (5) dlg0x7ffbec020: Transaction tsx0x7ffbf8c59ae8 state changed to Completed

==> notifications_trace.txt <==
2012-11-16 14:54:37.346179 [sylk-server 30934]: Notification name=SIPIncomingSubscriptionNotifyDidSucceed sender=<sipsimple.core._core.IncomingSubscription object at 0x7ffbf8b465f0>
{'body': None,
'code': 200,
'headers': {'CSeq': (21971, 'NOTIFY'),
             'Call-ID': FrozenHeader('Call-ID', 'M-d540f97bacf53a0cc3e6b33bde672a4b'),
             'Content-Length': 0,
             'From': FrozenFromHeader(FrozenSIPURI('testing.com', 'tihoparvi', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': 'BNdJ7hoAPdRZGMX.ehk3x80KWzp0946f'})),
             'Max-Forwards': 70,
             'Privacy': FrozenHeader('Privacy', 'none'),
             'To': FrozenToHeader(FrozenSIPURI('open-ims.test', 'alice', None, None, False, frozendict({}), frozendict({})), None, frozendict({'tag': '2589'})),
             'User-Agent': FrozenHeader('User-Agent', 'IM-client/OMA1.0 Mercuro-Gold/v4.0.1631.0'),
             'Via': [FrozenViaHeader('UDP', '10.226.20.56', 6060, frozendict({'rport': 6060, 'branch': 'z9hG4bKPj.KdbjAR3winyY.lRZBYtFJbCFO2OPN3M'}))]},
'reason': 'OK'}

==> core_trace.txt <==
2012-11-16 14:54:42.287742 [sylk-server 30934] (5) tsx0x7ffbf8bde: Timeout timer event
2012-11-16 14:54:42.296362 [sylk-server 30934] (5) tsx0x7ffbf8bde: State changed from Completed to Terminated, event=TIMER
2012-11-16 14:54:42.296512 [sylk-server 30934] (5) dlg0x7ffbec020: Transaction tsx0x7ffbf8bdee98 state changed to Terminated
2012-11-16 14:54:42.306318 [sylk-server 30934] (5) tsx0x7ffbf8bde: Timeout timer event
2012-11-16 14:54:42.306736 [sylk-server 30934] (5) tsx0x7ffbf8bde: State changed from Terminated to Destroyed, event=TIMER
2012-11-16 14:54:42.306850 [sylk-server 30934] (5) tdta0x7ffbf8bd: Destroying txdata Request msg NOTIFY/cseq=21969 (tdta0x7ffbf8bdce30)
2012-11-16 14:54:42.307542 [sylk-server 30934] (5) tsx0x7ffbf8bde: Transaction destroyed!
2012-11-16 14:54:42.307939 [sylk-server 30934] (5) tsx0x7ffbf8be8: Timeout timer event
2012-11-16 14:54:42.308654 [sylk-server 30934] (5) tsx0x7ffbf8be8: State changed from Completed to Terminated, event=TIMER
2012-11-16 14:54:42.308785 [sylk-server 30934] (5) dlg0x7ffbec027: Transaction tsx0x7ffbf8be8a28 state changed to Terminated
2012-11-16 14:54:42.309228 [sylk-server 30934] (5) tsx0x7ffbf8be8: Timeout timer event
2012-11-16 14:54:42.309901 [sylk-server 30934] (5) tsx0x7ffbf8be8: State changed from Terminated to Destroyed, event=TIMER
2012-11-16 14:54:42.310371 [sylk-server 30934] (5) tdta0x7ffbf8be: Destroying txdata Request msg NOTIFY/cseq=19229 (tdta0x7ffbf8be69c0)
2012-11-16 14:54:42.310568 [sylk-server 30934] (5) tsx0x7ffbf8be8: Transaction destroyed!
2012-11-16 14:54:42.327071 [sylk-server 30934] (5) tsx0x7ffbf8be1: Timeout timer event
2012-11-16 14:54:42.329385 [sylk-server 30934] (5) tsx0x7ffbf8be1: State changed from Completed to Terminated, event=TIMER
2012-11-16 14:54:42.329928 [sylk-server 30934] (5) dlg0x7ffbec020: Transaction tsx0x7ffbf8be1f08 state changed to Terminated
2012-11-16 14:54:42.330602 [sylk-server 30934] (5) tsx0x7ffbf8be1: Timeout timer event
2012-11-16 14:54:42.331215 [sylk-server 30934] (5) tsx0x7ffbf8be1: State changed from Terminated to Destroyed, event=TIMER
2012-11-16 14:54:42.333243 [sylk-server 30934] (5) tdta0x7ffbf8c3: Destroying txdata Request msg NOTIFY/cseq=21970 (tdta0x7ffbf8c37c30)
2012-11-16 14:54:42.333670 [sylk-server 30934] (5) tsx0x7ffbf8be1: Transaction destroyed!
2012-11-16 14:54:42.337480 [sylk-server 30934] (5) tsx0x7ffbf8c59: Timeout timer event
2012-11-16 14:54:42.337862 [sylk-server 30934] (5) tsx0x7ffbf8c59: State changed from Completed to Terminated, event=TIMER
2012-11-16 14:54:42.339839 [sylk-server 30934] (5) dlg0x7ffbec020: Transaction tsx0x7ffbf8c59ae8 state changed to Terminated
2012-11-16 14:54:42.441960 [sylk-server 30934] (5) tsx0x7ffbf8c59: Timeout timer event
2012-11-16 14:54:42.442921 [sylk-server 30934] (5) tsx0x7ffbf8c59: State changed from Terminated to Destroyed, event=TIMER
2012-11-16 14:54:42.446698 [sylk-server 30934] (5) tdta0x7ffbf8c5: Destroying txdata Request msg NOTIFY/cseq=21971 (tdta0x7ffbf8c57a80)
2012-11-16 14:54:42.448397 [sylk-server 30934] (5) tsx0x7ffbf8c59: Transaction destroyed!


Tiho

From: Adrian Georgescu [mailto:ag at ag-projects.com]
Sent: 16 November 2012 15:13
To: Hadzhiev, Tihomir
Cc: sipbeyondvoip at lists.ag-projects.com
Subject: Re: [SIP Beyond VoIP] Another case where Sylk would reject Notifications

Can you paste all the logs from SylkServer instead of yours when Notify comes from SIP to XMPP

Adrian

On Nov 16, 2012, at 3:09 PM, Hadzhiev, Tihomir wrote:


Well, the IMS client is acknowledging the NOTIFY, als in the IMS client I can see the XMPP user as Active Subscribe, another screenshot from the IMS client this time.

<image001.png>

Again the problem is that the XMPP Guy doesn't see online the IMS guy






________________________________
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.


________________________________
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.

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ag-projects.com/pipermail/sipbeyondvoip/attachments/20121116/d736edf8/attachment-0001.html>


More information about the SIPBeyondVoIP mailing list