BTW, sometimes check->tdata is NULL. There must be a reason why it is NULL. Can you explain this? Many thanks Pedro Gon?alves -------- Original Message -------- Subject: Re: Exceptions when using ICE functionalities Date: Fri, 08 Aug 2008 14:56:24 +0100 From: Pedro Gon?alves <pedro.pandre@xxxxxxxxx> To: pjsip list <pjsip at lists.pjsip.org> References: <48988BCE.30908 at gmail.com> <1879720d0808060210l5004bc90r8cd1ce4fff29eb20 at mail.gmail.com> <48998005.10004 at gmail.com> <1879720d0808060435i618dd5c0p938a810607eb6387 at mail.gmail.com> <4899E830.20706 at gmail.com> <1879720d0808070258m4c87f939raadab2f299c5eb39 at mail.gmail.com> Hi! I updated to the latest version, but the problems remain the same. Now I am experiencing the failing assert in on_stun_request_complete(). Can you explain better why this assert is needed and tell some reasons why it could fail? Anything you tell me will help me to have a better undertanding of this part of PJSIP. Best regards Pedro Gon?alves Benny Prijono wrote: > Pedro, > > this looks similar to http://trac.pjsip.org/repos/ticket/567 > Can you try the latest SVN version? > > Thanks > Benny > > On Wed, Aug 6, 2008 at 7:06 PM, Pedro Gon?alves > <pedro.pandre at gmail.com <mailto:pedro.pandre at gmail.com>> wrote: > > Hi again > > Now I am experiencing very frequently the exception #2, which > happens when, in sess_init_update, one of ice_st's components is NULL. > This even happens in the beggining, in caller before the initial > offer (when ICE procedures are starting). As you can see in the > capture, only a STUN binding request and its answer were captured. > As can be seen in the log, I printed ice_st's components, and they > don't seem to be changed in the call stack (you can see the > complete call stack below). > We can see that ice_st's comp[0] is not NULL, but ice_st's comp[1] > is NULL since on_request_complete > > 18:52:56.245 stun_sock.c pandre-dbg comp=15C7BC0C i=0 on > sess_on_request_complete > 18:52:56.266 stun_sock.c pandre-dbg comp=00000000 i=1 on > sess_on_request_complete > 18:52:56.307 ice_strans.c pandre-dbg comp=15C7BC0C i=0 on > stun_on_status(1) > 18:52:56.337 ice_strans.c pandre-dbg comp=00000000 i=1 on > stun_on_status(1) > 18:52:56.418 ice_strans.c pandre-dbg comp=15C7BC0C i=0 on > stun_on_status > 18:52:56.457 ice_strans.c pandre-dbg comp=00000000 i=1 on > stun_on_status > 18:52:56.488 ice_strans.c pandre-dbg comp=15C7BC0C i=0 on > sess_init_update > 18:52:56.514 ice_strans.c pandre-dbg comp=00000000 i=1 on > sess_init_update > > >From previous runs I know that some components can be NULL, but > then they get some value. > In this case, they keep the NULL value until sess_init_update is > called. > Is there something missing? > I don't know why this happens, nor do I know how to solve this > issue, despite my efforts. > > Best Regards > Pedro Gon?alves > > > Complete call stack: > > PCCommunicator.exe!sess_init_update(pj_ice_strans * > ice_st=0x15b52c5c) Line 547 + 0x18 bytes C > PCCommunicator.exe!stun_on_status(pj_stun_sock * > stun_sock=0x15c7fe0c, pj_stun_sock_op op=PJ_STUN_SOCK_BINDING_OP, > int status=0) Line 1276 + 0x9 bytes C > PCCommunicator.exe!sess_on_request_complete(pj_stun_session * > sess=0x15c8783c, int status=0, void * token=0x00000001, > pj_stun_tx_data * tdata=0x15ca1c5c, const pj_stun_msg * > response=0x15c9fc5c, const void * src_addr=0x15c81e9c, unsigned > int src_addr_len=16) Line 706 + 0x14 bytes C > PCCommunicator.exe!stun_tsx_on_complete(pj_stun_client_tsx * > tsx=0x15ca3f44, int status=0, const pj_stun_msg * > response=0x15c9fc5c, const void * src_addr=0x15c81e9c, unsigned > int src_addr_len=16) Line 424 + 0x29 bytes C > > PCCommunicator.exe!pj_stun_client_tsx_on_rx_msg(pj_stun_client_tsx > * tsx=0x15ca3f44, const pj_stun_msg * msg=0x15c9fc5c, const void * > src_addr=0x15c81e9c, unsigned int src_addr_len=16) Line 395 + > 0x1e bytes C > PCCommunicator.exe!on_incoming_response(pj_stun_session * > sess=0x15c8783c, unsigned int options=5, const unsigned char * > pkt=0x15c8380c, unsigned int pkt_len=88, pj_stun_msg * > msg=0x15c9fc5c, const void * src_addr=0x15c81e9c, unsigned int > src_addr_len=16) Line 1189 + 0x18 bytes C > PCCommunicator.exe!pj_stun_session_on_rx_pkt(pj_stun_session * > sess=0x15c8783c, const void * packet=0x15c8380c, unsigned int > pkt_size=88, unsigned int options=1, void * token=0x00000000, > unsigned int * parsed_len=0x00000000, const void * > src_addr=0x15c81e9c, unsigned int src_addr_len=16) Line 1416 + > 0x21 bytes C > PCCommunicator.exe!on_data_recvfrom(pj_activesock_t * > asock=0x15c7ffb8, void * data=0x15c8380c, unsigned int size=88, > const void * src_addr=0x15c81e9c, int addr_len=16, int status=0) > Line 817 + 0x25 bytes C > PCCommunicator.exe!ioqueue_on_read_complete(pj_ioqueue_key_t * > key=0x08b458d4, pj_ioqueue_op_key_t * op_key=0x15c81e0c, long > bytes_read=88) Line 341 + 0x38 bytes C > PCCommunicator.exe!ioqueue_dispatch_read_event(pj_ioqueue_t * > ioqueue=0x0da80928, pj_ioqueue_key_t * h=0x08b458d4) Line 549 + > 0x16 bytes C > PCCommunicator.exe!pj_ioqueue_poll(pj_ioqueue_t * > ioqueue=0x0da80928, const pj_time_val * timeout=0x0dd3fcac) Line > 763 + 0x17 bytes C > PCCommunicator.exe!pjsip_endpt_handle_events2(pjsip_endpoint * > endpt=0x0b9c705c, const pj_time_val * max_timeout=0x0dd3fe7c, > unsigned int * p_count=0x00000000) Line 694 + 0x10 bytes C > PCCommunicator.exe!pjsip_endpt_handle_events(pjsip_endpoint * > endpt=0x0b9c705c, const pj_time_val * max_timeout=0x0dd3fe7c) > Line 721 + 0xf bytes C > > PCCommunicator.exe!EventHandler(void * __formal=0x00000000) > Line 630 + 0x16 bytes C++ > PCCommunicator.exe!thread_main(void * param=0x08af5e7c) Line > 413 + 0x11 bytes C > > > > > > > > > > Benny Prijono wrote: > > On Wed, Aug 6, 2008 at 11:42 AM, Pedro Gon?alves > <pedro.pandre at gmail.com <mailto:pedro.pandre at gmail.com> > <mailto:pedro.pandre at gmail.com > <mailto:pedro.pandre at gmail.com>>> wrote: > > Benny Prijono wrote: > > On Tue, Aug 5, 2008 at 6:20 PM, Pedro Gon?alves > <pedro.pandre at gmail.com <mailto:pedro.pandre at gmail.com> > <mailto:pedro.pandre at gmail.com <mailto:pedro.pandre at gmail.com>> > <mailto:pedro.pandre at gmail.com > <mailto:pedro.pandre at gmail.com> > <mailto:pedro.pandre at gmail.com > <mailto:pedro.pandre at gmail.com>>>> wrote: > > Hi! > > With the help from PJSIP list useres, I think I am > close to > having my > program to use PJSIP's ICE functionalities 100% > correctly. > > > Not that I'm discouraging you, but I think you've still got > some issues to fix there (as discussed on the other > thread). :) > Regarding the crashes below, do you know in what stage did > these happen? E.g. during ICE creation, in the middle of > conversation, or during ICE destroy sequence? We had > this bug > that looks similar: http://trac.pjsip.org/repos/ticket/567 > > > About the other issues (the ones you told in the other > thread, I > moved the stream destruction to on_media_update(), but these > problems persist (these problems happen in the answerer). > > > Is the problem still with stream not being closed? So what do > you exactly do in on_media_update()? And is on_media_update() > called? And do you close the stream when the call is > disconnected? A snippet will help. > > And lets discuss this on separate/the other thread please. > > > About 1), the failing assert, it happens after initial offer / > answer, but before the subsequent offer, during ICE negotiation > (more specifically, during ICE connectivity checks). > > I've included both the application log and the capture I made > during the exception. > > I can reproduce this behaviour at any time, so if there is > something I can do to help us debug this issue, just ask. > > I've added some debug information in some PJSIP files, in > order to > help me understand the problem. As you can see in the end > of the > log, the assert problem seems to come from somewhere before > pj_stun_session_on_rx_pkt, is it not? > 11:19:15.375 stun_session.c pandre-dbg tdata=339762268 > check->tdata=338037852 on pj_stun_session_on_rx_pkt ckid=0 > 11:19:15.687 stun_session.c pandre-dbg tdata=339762268 > check->tdata=338037852 on on_incoming_response ckid=0 > 11:19:16.292 stun_session.c pandre-dbg tdata=339762268 > check->tdata=338037852 on stun_tsx_on_complete(1) > 11:19:16.335 stun_session.c pandre-dbg tdata=339762268 > check->tdata=338037852 on stun_tsx_on_complete(2) > > > Unfortunately I didn't see the messages (above) in the log, > probably because the file has not completely been written when > the assertion occurs. When the "pj_assert(tdata == > check->tdata)" assertion occurs, does "check->tdata" contain a > value, or is it NULL? > > Cheers > Benny > > > ------------------------------------------------------------------------ > > > > _______________________________________________ > Visit our blog: http://blog.pjsip.org > > pjsip mailing list > pjsip at lists.pjsip.org <mailto:pjsip at lists.pjsip.org> > http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org > > > > > 18:52:05.989 os_core_win32. pjlib 0.9.0-release for win32 initialized > 18:52:05.995 pasound.c PA message: before > paHostApiInitializers[0]. > > 18:52:06.312 pasound.c PA message: after > paHostApiInitializers[0]. > > 18:52:06.317 pasound.c PA message: before > paHostApiInitializers[1]. > > 18:52:06.414 pasound.c PA message: after > paHostApiInitializers[1]. > > 18:52:06.420 pasound.c PA message: before > paHostApiInitializers[2]. > > 18:52:06.425 pasound.c PA message: after > paHostApiInitializers[2]. > > 18:52:06.430 pasound.c PortAudio sound library initialized, > status=0 > 18:52:06.436 pasound.c PortAudio host api count=3 > 18:52:06.441 pasound.c Sound device count=8 > 18:52:06.449 pjlib select() I/O Queue created (0C1C4A0C) > 18:52:06.458 g723decoder Init > 18:52:06.465 g723decoder Init 1 > 18:52:06.470 g723decoder Init done > 18:52:06.476 conference.c Creating conference bridge with 5 ports > 18:52:06.483 conference.c Sound device successfully created for > port 0 > 18:52:06.575 sip_endpoint.c Creating endpoint instance... > 18:52:06.587 pjlib select() I/O Queue created (0DA80928) > 18:52:06.595 sip_endpoint.c Module "mod-msg-print" registered > 18:52:06.619 sip_transport. Transport manager created. > 18:52:06.655 udp08B7BDF8 SIP UDP transport started, published > address is 172.18.0.51:64184 <http://172.18.0.51:64184> > 18:52:06.662 sip_endpoint.c Module "mod-tsx-layer" registered > 18:52:06.670 sip_endpoint.c Module "mod-stateful-util" registered > 18:52:06.677 sip_endpoint.c Module "mod-ua" registered > 18:52:06.685 sip_endpoint.c Module "mod-100rel" registered > 18:52:06.694 sip_endpoint.c Module "mod_expire_session" registered > 18:52:06.700 sip_endpoint.c Module "mod-evsub" registered > 18:52:06.706 sip_endpoint.c Module "mod-presence" registered > 18:52:06.715 evsub.c Event pkg "presence" registered by > mod-presence > 18:52:06.721 sip_endpoint.c Module "mod_options" registered > 18:52:06.730 sip_endpoint.c Module "mod_logging" registered > 18:52:06.737 sip_endpoint.c Module "mod_message" registered > 18:52:06.744 sip_endpoint.c Module "mod_call" registered > 18:52:06.751 sip_endpoint.c Module "mod_opaque" registered > 18:52:06.758 sip_endpoint.c Module "mod-invite" registered > 18:52:06.761 SIPEngine.c Starting Event Handler... > 18:52:06.772 SIPCall.cpp pandre resolve_stun_server > stun_srv=172.18.0.169:3478 <http://172.18.0.169:3478> > 18:52:06.787 SIPCall.cpp pandre resolve_stun_server stun_srv > in SIPEngine=172.18.0.169:3478 <http://172.18.0.169:3478> > 18:52:06.837 endpoint Request msg REGISTER/cseq=18508 > (tdta0DAD5FF8) created. > 18:52:06.845 tsx0DAEF85C Transaction created for Request msg > REGISTER/cseq=18509 (tdta0DAD5FF8) > 18:52:06.853 tsx0DAEF85C Sending Request msg > REGISTER/cseq=18509 (tdta0DAD5FF8) in state Null > 18:52:06.866 sip_resolve.c Target '172.18.0.170:5060 > <http://172.18.0.170:5060>' type=UDP resolved to > '172.18.0.170:5060 <http://172.18.0.170:5060>' type=UDP (UDP > transport) > 18:52:06.901 LOG TX 600 bytes Request msg > REGISTER/cseq=18509 (tdta0DAD5FF8) to UDP 172.18.0.170:5060 > <http://172.18.0.170:5060>: > REGISTER sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com> SIP/2.0Via: > SIP/2.0/UDP > 172.18.0.51:64184;rport;branch=z9hG4bKPj5a52444ef72b4316a8f5c09a68d3e18bRoute: > <sip:172.18.0.170:5060;transport=UDP;lr>Max-Forwards: 70From: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=3cce5f2e578642298a0beb9a06054e99To: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>Call-ID: > 157d9d3aad6d4107ad1a522be677dc1eCSeq: 18509 REGISTERUser-Agent: > WITPCCommunicator/2.0 (English;)Contact: > <sip:172.18.0.51:64184;transport=UDP>;methods="INVITE,NOTIFY,MESSAGE,ACK,BYE,CANCEL";cfwd="False"Expires: > 30Content-Length: 0 > --end msg-- > 18:52:06.910 tsx0DAEF85C State changed from Null to Calling, > event=TX_MSG > 18:52:07.026 sip_endpoint.c Processing incoming message: Response > msg 100/REGISTER/cseq=18509 (rdata08AD205C) > 18:52:07.038 LOG RX 328 bytes Response msg > 100/REGISTER/cseq=18509 (rdata08AD205C) from UDP 172.18.0.170:5060 > <http://172.18.0.170:5060>: > SIP/2.0 100 TryingVia: SIP/2.0/UDP > 172.18.0.51:64184;rport;branch=z9hG4bKPj5a52444ef72b4316a8f5c09a68d3e18bFrom: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=3cce5f2e578642298a0beb9a06054e99To: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>Call-ID: > 157d9d3aad6d4107ad1a522be677dc1eCSeq: 18509 REGISTERContent-Length: 0 > --end msg-- > 18:52:07.051 tsx0DAEF85C Incoming Response msg > 100/REGISTER/cseq=18509 (rdata08AD205C) in state Calling > 18:52:07.063 tsx0DAEF85C State changed from Calling to > Proceeding, event=RX_MSG > 18:52:07.076 sip_endpoint.c Processing incoming message: Response > msg 401/REGISTER/cseq=18509 (rdata08AD205C) > 18:52:07.087 LOG RX 493 bytes Response msg > 401/REGISTER/cseq=18509 (rdata08AD205C) from UDP 172.18.0.170:5060 > <http://172.18.0.170:5060>: > SIP/2.0 401 UnauthorizedVia: SIP/2.0/UDP > 172.18.0.51:64184;rport;branch=z9hG4bKPj5a52444ef72b4316a8f5c09a68d3e18bFrom: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=3cce5f2e578642298a0beb9a06054e99To: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>Call-ID: > 157d9d3aad6d4107ad1a522be677dc1eCSeq: 18509 > REGISTERWWW-Authenticate: Digest > realm="mcg",nonce="MTIxODA0NTEyNjk1MzpXSVQtTUNH",opaque="D03207FDBFBA3D6B2029A4545420C1E05116612932C8B3A7",stale=false,algorithm=MD5Content-Length: > 0 > --end msg-- > 18:52:07.096 tsx0DAEF85C Incoming Response msg > 401/REGISTER/cseq=18509 (rdata08AD205C) in state Proceeding > 18:52:07.108 tsx0DAEF85C State changed from Proceeding to > Completed, event=RX_MSG > 18:52:07.119 tsx0DFB585C Transaction created for Request msg > REGISTER/cseq=18510 (tdta0DAD5FF8) > 18:52:07.129 tsx0DFB585C Sending Request msg > REGISTER/cseq=18510 (tdta0DAD5FF8) in state Null > 18:52:07.145 sip_resolve.c Target '172.18.0.170:5060 > <http://172.18.0.170:5060>' type=UDP resolved to > '172.18.0.170:5060 <http://172.18.0.170:5060>' type=UDP (UDP > transport) > 18:52:07.184 LOG TX 885 bytes Request msg > REGISTER/cseq=18510 (tdta0DAD5FF8) to UDP 172.18.0.170:5060 > <http://172.18.0.170:5060>: > REGISTER sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com> SIP/2.0Via: > SIP/2.0/UDP > 172.18.0.51:64184;rport;branch=z9hG4bKPj6fde5226e9fe4ceaa2f2e2bc56b6236fRoute: > <sip:172.18.0.170:5060;transport=UDP;lr>Max-Forwards: 70From: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=3cce5f2e578642298a0beb9a06054e99To: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>Call-ID: > 157d9d3aad6d4107ad1a522be677dc1eCSeq: 18510 REGISTERUser-Agent: > WITPCCommunicator/2.0 (English;)Contact: > <sip:172.18.0.51:64184;transport=UDP>;methods="INVITE,NOTIFY,MESSAGE,ACK,BYE,CANCEL";cfwd="False"Expires: > 30Authorization: Digest > username="+351914871189 at wcs.wit-software.com > <mailto:351914871189 at wcs.wit-software.com>", realm="mcg", > nonce="MTIxODA0NTEyNjk1MzpXSVQtTUNH", > uri="sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>", > response="e41c4f72c394c78665889c0e29488e33", algorithm=MD5, > opaque="D03207FDBFBA3D6B2029A4545420C1E05116612932C8B3A7"Content-Length: > 0 > --end msg-- > 18:52:07.194 tsx0DFB585C State changed from Null to Calling, > event=TX_MSG > 18:52:07.215 sip_endpoint.c Processing incoming message: Response > msg 100/REGISTER/cseq=18510 (rdata08AD205C) > 18:52:07.232 LOG RX 328 bytes Response msg > 100/REGISTER/cseq=18510 (rdata08AD205C) from UDP 172.18.0.170:5060 > <http://172.18.0.170:5060>: > SIP/2.0 100 TryingVia: SIP/2.0/UDP > 172.18.0.51:64184;rport;branch=z9hG4bKPj6fde5226e9fe4ceaa2f2e2bc56b6236fFrom: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=3cce5f2e578642298a0beb9a06054e99To: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>Call-ID: > 157d9d3aad6d4107ad1a522be677dc1eCSeq: 18510 REGISTERContent-Length: 0 > --end msg-- > 18:52:07.243 tsx0DFB585C Incoming Response msg > 100/REGISTER/cseq=18510 (rdata08AD205C) in state Calling > 18:52:07.261 tsx0DFB585C State changed from Calling to > Proceeding, event=RX_MSG > 18:52:07.278 sip_endpoint.c Processing incoming message: Response > msg 200/REGISTER/cseq=18510 (rdata08AD205C) > 18:52:07.294 LOG RX 488 bytes Response msg > 200/REGISTER/cseq=18510 (rdata08AD205C) from UDP 172.18.0.170:5060 > <http://172.18.0.170:5060>: > SIP/2.0 200 OKVia: SIP/2.0/UDP > 172.18.0.51:64184;rport;branch=z9hG4bKPj6fde5226e9fe4ceaa2f2e2bc56b6236fFrom: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=3cce5f2e578642298a0beb9a06054e99To: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>Call-ID: > 157d9d3aad6d4107ad1a522be677dc1eCSeq: 18510 REGISTERX-Invite-SMS: > trueX-Recommend-EMail: trueContact: > <sip:172.18.0.51:64184;transport=UDP>;methods="INVITE,NOTIFY,MESSAGE,ACK,BYE,CANCEL";cfwd="False";expires=90Content-Length: > 0 > --end msg-- > 18:52:07.306 tsx0DFB585C Incoming Response msg > 200/REGISTER/cseq=18510 (rdata08AD205C) in state Proceeding > 18:52:07.322 tsx0DFB585C State changed from Proceeding to > Completed, event=RX_MSG > 18:52:30.056 dlg0F05085C UAC dialog created > 18:52:30.069 dlg0F05085C Module mod-evsub added as dialog > usage, data=0EF96FAC > 18:52:30.099 evsub0F050E54 UAC subscription created, using > dialog dlg0F05085C > 18:52:30.115 dlg0F05085C Session count inc to 3 by mod-evsub > 18:52:30.132 endpoint Request msg SUBSCRIBE/cseq=18468 > (tdta0ED66FF8) created. > 18:52:30.144 dlg0F05085C Sending Request msg > SUBSCRIBE/cseq=18468 (tdta0ED66FF8) > 18:52:30.155 tsx0F26D85C Transaction created for Request msg > SUBSCRIBE/cseq=18467 (tdta0ED66FF8) > 18:52:30.168 tsx0F26D85C Sending Request msg > SUBSCRIBE/cseq=18467 (tdta0ED66FF8) in state Null > 18:52:30.179 sip_resolve.c Target '172.18.0.170:5060 > <http://172.18.0.170:5060>' type=UDP resolved to > '172.18.0.170:5060 <http://172.18.0.170:5060>' type=UDP (UDP > transport) > 18:52:30.193 LOG TX 574 bytes Request msg > SUBSCRIBE/cseq=18467 (tdta0ED66FF8) to UDP 172.18.0.170:5060 > <http://172.18.0.170:5060>: > SUBSCRIBE sip:172.18.0.170:5060;transport=UDP;lr SIP/2.0Via: > SIP/2.0/UDP > 172.18.0.51:64184;rport;branch=z9hG4bKPj2a88b60293e04037b45d300b58f62805Max-Forwards: > 70From: <sip:+351914871189@xxxxxxxxxxxxxxxxxxxx > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=d103bb6cc0da447e9c7c9c33639de6ffTo: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>Contact: > <sip:172.18.0.51:64184 <http://172.18.0.51:64184>>Call-ID: > 604970b238994208a7d87f72670279d8CSeq: 18467 SUBSCRIBEEvent: > presenceExpires: 600Accept: application/pidf+xml, > application/xpidf+xmlAllow-Events: presenceUser-Agent: > WITPCCommunicator/2.0 (English;)Content-Length: 0 > --end msg-- > 18:52:30.205 tsx0F26D85C State changed from Null to Calling, > event=TX_MSG > 18:52:30.224 dlg0F05085C Transaction tsx0F26D85C state changed > to Calling > 18:52:30.236 evsub0F050E54 Subscription state changed NULL --> SENT > 18:52:30.247 sip_endpoint.c Processing incoming message: Response > msg 200/SUBSCRIBE/cseq=18467 (rdata08AD205C) > 18:52:30.264 LOG RX 325 bytes Response msg > 200/SUBSCRIBE/cseq=18467 (rdata08AD205C) from UDP > 172.18.0.170:5060 <http://172.18.0.170:5060>: > SIP/2.0 200 OKVia: SIP/2.0/UDP > 172.18.0.51:64184;rport;branch=z9hG4bKPj2a88b60293e04037b45d300b58f62805From: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=d103bb6cc0da447e9c7c9c33639de6ffTo: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>Call-ID: > 604970b238994208a7d87f72670279d8CSeq: 18467 SUBSCRIBEContent-Length: 0 > --end msg-- > 18:52:30.290 tsx0F26D85C Incoming Response msg > 200/SUBSCRIBE/cseq=18467 (rdata08AD205C) in state Calling > 18:52:30.300 tsx0F26D85C State changed from Calling to > Completed, event=RX_MSG > 18:52:30.310 dlg0F05085C Received Response msg > 200/SUBSCRIBE/cseq=18467 (rdata08AD205C) > 18:52:30.325 dlg0F05085C Route-set updated > 18:52:30.338 dlg0F05085C Route-set frozen > 18:52:30.350 dlg0F05085C Transaction tsx0F26D85C state changed > to Completed > 18:52:30.361 evsub0F050E54 Will refresh in 595 seconds > 18:52:30.371 evsub0F050E54 Timer UAC_REFRESH scheduled in 595 > seconds > 18:52:30.385 evsub0F050E54 Subscription state changed SENT --> > ACCEPTED > 18:52:30.398 sip_endpoint.c Processing incoming message: Request > msg NOTIFY/cseq=1 (rdata08AD205C) > 18:52:30.408 LOG RX 659 bytes Request msg > NOTIFY/cseq=1 (rdata08AD205C) from UDP 172.18.0.170:5060 > <http://172.18.0.170:5060>: > NOTIFY sip:172.18.0.51:64184;transport=udp SIP/2.0Call-ID: > 604970b238994208a7d87f72670279d8CSeq: 1 NOTIFYFrom: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>To: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=d103bb6cc0da447e9c7c9c33639de6ffVia: > SIP/2.0/UDP > 172.18.0.170:5060;branch=z9hG4bK2dc5f14fb0047ac49899ed225763d3feMax-Forwards: > 70Event: presenceSubscription-State: > active;expires=600Content-Type: > application/pidf+xmlContent-Length: 199<?xml version="1.0" > encoding="UTF-8" standalone="no"?><presence > xmlns:mcg="http://mcg.wit-software.com/presence"; > entity="pres:+351914871189 at wcs.wit-software.com > <mailto:pres%3A%2B351914871189 at wcs.wit-software.com>" > xmlns="urn:ietf:params:xml:ns:pidf"/> > --end msg-- > 18:52:30.423 dlg0F05085C Received Request msg NOTIFY/cseq=1 > (rdata08AD205C) > 18:52:30.438 tsx0ECF885C Transaction created for Request msg > NOTIFY/cseq=1 (rdata08AD205C) > 18:52:30.449 tsx0ECF885C Incoming Request msg NOTIFY/cseq=1 > (rdata08AD205C) in state Null > 18:52:30.461 tsx0ECF885C State changed from Null to Trying, > event=RX_MSG > 18:52:30.474 dlg0F05085C Transaction tsx0ECF885C state changed > to Trying > 18:52:30.490 evsub0F050E54 Will refresh in 595 seconds > 18:52:30.510 evsub0F050E54 Updating UAC_REFRESH timer > 18:52:30.535 evsub0F050E54 Timer UAC_REFRESH scheduled in 595 > seconds > 18:52:30.567 endpoint Response msg 200/NOTIFY/cseq=1 > (tdta0FA52FF8) created > 18:52:30.578 dlg0F05085C Sending Response msg > 200/NOTIFY/cseq=1 (tdta0FA52FF8) > 18:52:30.590 tsx0ECF885C Sending Response msg > 200/NOTIFY/cseq=1 (tdta0FA52FF8) in state Trying > 18:52:30.602 sip_resolve.c Target '172.18.0.170:5060 > <http://172.18.0.170:5060>' type=UDP resolved to > '172.18.0.170:5060 <http://172.18.0.170:5060>' type=UDP (UDP > transport) > 18:52:30.615 LOG TX 462 bytes Response msg > 200/NOTIFY/cseq=1 (tdta0FA52FF8) to UDP 172.18.0.170:5060 > <http://172.18.0.170:5060>: > SIP/2.0 200 OKVia: SIP/2.0/UDP > 172.18.0.170:5060;received=172.18.0.170 > <http://172.18.0.170>;branch=z9hG4bK2dc5f14fb0047ac49899ed225763d3feCall-ID: > 604970b238994208a7d87f72670279d8From: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>To: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=d103bb6cc0da447e9c7c9c33639de6ffCSeq: > 1 NOTIFYContact: <sip:172.18.0.51:64184 > <http://172.18.0.51:64184>>Allow: PRACK, SUBSCRIBE, NOTIFY, > PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATESupported: > 100relContent-Length: 0 > --end msg-- > 18:52:30.626 tsx0ECF885C State changed from Trying to > Completed, event=TX_MSG > 18:52:30.640 dlg0F05085C Transaction tsx0ECF885C state changed > to Completed > 18:52:30.654 evsub0F050E54 Subscription state changed ACCEPTED > --> ACTIVE > 18:52:30.665 tsx0DAEF85C Timeout timer event > 18:52:30.684 tsx0DAEF85C State changed from Completed to > Terminated, event=TIMER > 18:52:30.695 tsx0DFB585C Timeout timer event > 18:52:30.711 tsx0DFB585C State changed from Completed to > Terminated, event=TIMER > 18:52:30.733 tsx0DAEF85C Timeout timer event > 18:52:30.746 tsx0DAEF85C State changed from Terminated to > Destroyed, event=TIMER > 18:52:30.757 tsx0DAEF85C Transaction destroyed! > 18:52:30.773 tsx0DFB585C Timeout timer event > 18:52:30.791 tsx0DFB585C State changed from Terminated to > Destroyed, event=TIMER > 18:52:30.809 tdta0DAD5FF8 Destroying txdata Request msg > REGISTER/cseq=18510 (tdta0DAD5FF8) > 18:52:30.823 tsx0DFB585C Transaction destroyed! > 18:52:35.300 tsx0F26D85C Timeout timer event > 18:52:35.314 tsx0F26D85C State changed from Completed to > Terminated, event=TIMER > 18:52:35.331 dlg0F05085C Transaction tsx0F26D85C state changed > to Terminated > 18:52:35.370 endpoint Request msg PUBLISH/cseq=32834 > (tdta0EF2CFF8) created. > 18:52:35.387 tsx0ED0A85C Transaction created for Request msg > PUBLISH/cseq=32835 (tdta0EF2CFF8) > 18:52:35.400 tsx0ED0A85C Sending Request msg > PUBLISH/cseq=32835 (tdta0EF2CFF8) in state Null > 18:52:35.413 sip_resolve.c Target '172.18.0.170:5060 > <http://172.18.0.170:5060>' type=UDP resolved to > '172.18.0.170:5060 <http://172.18.0.170:5060>' type=UDP (UDP > transport) > 18:52:35.430 LOG TX 672 bytes Request msg > PUBLISH/cseq=32835 (tdta0EF2CFF8) to UDP 172.18.0.170:5060 > <http://172.18.0.170:5060>: > PUBLISH sip:172.18.0.170:5060;transport=UDP;lr SIP/2.0Via: > SIP/2.0/UDP > 172.18.0.51:64184;rport;branch=z9hG4bKPj435ca0600a114dcfa95f2e0042fcc663Max-Forwards: > 70From: <sip:+351914871189@xxxxxxxxxxxxxxxxxxxx > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=2dc057d91f2d43df9100295244573051To: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>Call-ID: > 13cc3b3719394e9d9fc59a546ac81ebcCSeq: 32835 PUBLISHEvent: > presenceContent-Type: application/pidf+xmlContent-Length: > 234<?xml version="1.0" encoding="UTF-8"?><presence > xmlns:mcg="http://mcg.wit-software.com/presence"; > entity="pres:+351914871189 at wcs.wit-software.com > <mailto:pres%3A%2B351914871189 at wcs.wit-software.com>"><tuple > id="0"><mcg:presence><mcg:status>1</mcg:status></mcg:presence></tuple></presence> > --end msg-- > 18:52:35.452 tsx0ED0A85C State changed from Null to Calling, > event=TX_MSG > 18:52:35.477 tsx0F26D85C Timeout timer event > 18:52:35.492 tsx0F26D85C State changed from Terminated to > Destroyed, event=TIMER > 18:52:35.505 tdta0ED66FF8 Destroying txdata Request msg > SUBSCRIBE/cseq=18467 (tdta0ED66FF8) > 18:52:35.526 tsx0F26D85C Transaction destroyed! > 18:52:35.550 sip_endpoint.c Processing incoming message: Response > msg 100/PUBLISH/cseq=32835 (rdata08AD205C) > 18:52:35.576 LOG RX 327 bytes Response msg > 100/PUBLISH/cseq=32835 (rdata08AD205C) from UDP 172.18.0.170:5060 > <http://172.18.0.170:5060>: > SIP/2.0 100 TryingVia: SIP/2.0/UDP > 172.18.0.51:64184;rport;branch=z9hG4bKPj435ca0600a114dcfa95f2e0042fcc663From: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=2dc057d91f2d43df9100295244573051To: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>Call-ID: > 13cc3b3719394e9d9fc59a546ac81ebcCSeq: 32835 PUBLISHContent-Length: 0 > --end msg-- > 18:52:35.589 tsx0ED0A85C Incoming Response msg > 100/PUBLISH/cseq=32835 (rdata08AD205C) in state Calling > 18:52:35.607 tsx0ED0A85C State changed from Calling to > Proceeding, event=RX_MSG > 18:52:35.649 sip_endpoint.c Processing incoming message: Response > msg 200/PUBLISH/cseq=32835 (rdata08AD205C) > 18:52:35.665 LOG RX 323 bytes Response msg > 200/PUBLISH/cseq=32835 (rdata08AD205C) from UDP 172.18.0.170:5060 > <http://172.18.0.170:5060>: > SIP/2.0 200 OKVia: SIP/2.0/UDP > 172.18.0.51:64184;rport;branch=z9hG4bKPj435ca0600a114dcfa95f2e0042fcc663From: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=2dc057d91f2d43df9100295244573051To: > <sip:+351914871189 at wcs.wit-software.com > <mailto:sip%3A%2B351914871189 at wcs.wit-software.com>>Call-ID: > 13cc3b3719394e9d9fc59a546ac81ebcCSeq: 32835 PUBLISHContent-Length: 0 > --end msg-- > 18:52:35.678 tsx0ED0A85C Incoming Response msg > 200/PUBLISH/cseq=32835 (rdata08AD205C) in state Proceeding > 18:52:35.689 tsx0ED0A85C State changed from Proceeding to > Completed, event=RX_MSG > 18:52:40.689 tsx0ED0A85C Timeout timer event > 18:52:40.701 tsx0ED0A85C State changed from Completed to > Terminated, event=TIMER > 18:52:40.723 tsx0ED0A85C Timeout timer event > 18:52:40.734 tsx0ED0A85C State changed from Terminated to > Destroyed, event=TIMER > 18:52:40.747 tdta0EF2CFF8 Destroying txdata Request msg > PUBLISH/cseq=32835 (tdta0EF2CFF8) > 18:52:40.759 tsx0ED0A85C Transaction destroyed! > 18:52:55.957 SIPCall.cpp [TEST] StartCall() > 18:52:55.971 SIPCall.cpp [TEST] StartCall() - MCG Call > 18:52:55.983 SIPCall.cpp [TEST] StartCall() - > pjsip_dlg_create_uac() > 18:52:55.998 dlg15AE285C UAC dialog created > 18:52:56.022 SIPCall.cpp [TEST] StartCall() - > CreateRTPTransports() > 18:52:56.049 SIPCall.cpp [TEST] StartCall() - > pjmedia_endpt_create_sdp() > 18:52:56.061 g723decoder test_Alloc? > 18:52:56.073 g723decoder test_Alloc Ok > 18:52:56.086 SIPCall.cpp pandre create_ice_offer stun_srv in > SIPEngine=172.18.0.169:3478 <http://172.18.0.169:3478> slen=0.000000 > 18:52:56.099 ICEVoiceTransp Creating ICE stream transport with 2 > component(s) > 18:52:56.112 stuntp15C7DEF8 TX 20 bytes STUN message to > 172.18.0.169:3478 <http://172.18.0.169:3478>: > --- begin STUN message --- > STUN Binding request > Hdr: length=0, magic=2112a442, tsx_id=72ae3d6c6df15f90000141bb > Attributes: > --- end of STUN message --- > > 18:52:56.125 stuntsx15CA3F4 STUN client transaction created > 18:52:56.137 stuntsx15CA3F4 STUN sending message (transmit count=1) > 18:52:56.151 stun_msg.c Unrecognized attribute type 0x8020 > 18:52:56.172 sock_common.c pandre-dbg on pj_sockaddr_cp > dst=15C7BC58 src=0012DAAC > 18:52:56.173 stuntp15C7DEF8 RX 88 bytes STUN message from > 172.18.0.169:3478 <http://172.18.0.169:3478>: > --- begin STUN message --- > STUN Binding success response > Hdr: length=68, magic=2112a442, tsx_id=72ae3d6c6df15f90000141bb > Attributes: > MAPPED-ADDRESS: length=8, IPv4 addr=172.18.0.51:64888 > <http://172.18.0.51:64888> > SOURCE-ADDRESS: length=8, IPv4 addr=172.18.0.169:3478 > <http://172.18.0.169:3478> > CHANGED-ADDRESS: length=8, IPv4 addr=172.18.0.170:3479 > <http://172.18.0.170:3479> > ???: length=8 > SERVER: length=16, value="Vovida.org 0.96" > --- end of STUN message --- > > 18:52:56.186 sock_common.c pandre-dbg on pj_sockaddr_cp > dst=15C7BC74 src=15C7BC58 > 18:52:56.210 ICEVoiceTransp Comp 1: srflx candidate starts > Binding discovery > 18:52:56.197 stuntp15C7DEF8 STUN mapped address found/changed: > 172.18.0.51:64888 <http://172.18.0.51:64888> > 18:52:56.211 sock_common.c pandre-dbg on pj_sockaddr_cp > dst=15C7FE78 src=15C9FCBC > 18:52:56.245 stun_sock.c pandre-dbg comp=15C7BC0C i=0 on > sess_on_request_complete > 18:52:56.255 sock_common.c pandre-dbg on pj_sockaddr_cp > dst=15C7BCA8 src=0012D96C > 18:52:56.266 stun_sock.c pandre-dbg comp=00000000 i=1 on > sess_on_request_complete > 18:52:56.292 sock_common.c pandre-dbg on pj_sockaddr_cp > dst=15C7BCC4 src=0012D96C > 18:52:56.307 ice_strans.c pandre-dbg comp=15C7BC0C i=0 on > stun_on_status(1) > 18:52:56.323 ICEVoiceTransp Comp 1: host candidate > 172.18.0.51:64888 <http://172.18.0.51:64888> added > 18:52:56.337 ice_strans.c pandre-dbg comp=00000000 i=1 on > stun_on_status(1) > 18:52:56.351 sock_common.c pandre-dbg on pj_sockaddr_cp > dst=15C7BD14 src=0012D988 > 18:52:56.382 sock_common.c pandre-dbg on pj_sockaddr_cp > dst=15C7BD30 src=0012D988 > 18:52:56.395 ICEVoiceTransp Comp 1: Binding discovery complete, > srflx address is 172.18.0.51:64888 <http://172.18.0.51:64888> > 18:52:56.400 ICEVoiceTransp Comp 1: host candidate > 192.168.102.1:64888 <http://192.168.102.1:64888> added > 18:52:56.418 ice_strans.c pandre-dbg comp=15C7BC0C i=0 on > stun_on_status > 18:52:56.439 sock_common.c pandre-dbg on pj_sockaddr_cp > dst=15C7BD14 src=0012D9A4 > 18:52:56.457 ice_strans.c pandre-dbg comp=00000000 i=1 on > stun_on_status > 18:52:56.471 sock_common.c pandre-dbg on pj_sockaddr_cp > dst=15C7BD30 src=0012D9A4 > 18:52:56.488 ice_strans.c pandre-dbg comp=15C7BC0C i=0 on > sess_init_update > 18:52:56.495 ICEVoiceTransp Comp 1: host candidate > 192.168.1.1:64888 <http://192.168.1.1:64888> added > 18:52:56.512 sock_common.c pandre-dbg on pj_sockaddr_cp > dst=15C7BD80 src=0012D9C0 > 18:52:56.513 sock_common.c pandre-dbg on pj_sockaddr_cp > dst=15C7BD9C src=0012D9C0 > 18:52:56.514 ICEVoiceTransp Comp 1: host candidate > 172.18.0.52:64888 <http://172.18.0.52:64888> added > 18:52:56.514 ice_strans.c pandre-dbg comp=00000000 i=1 on > sess_init_update > 18:52:56.564 stuntp15D2DEF8 TX 20 bytes STUN message to > 172.18.0.169:3478 <http://172.18.0.169:3478>: > --- begin STUN message --- > STUN Binding request > Hdr: length=0, magic=2112a442, tsx_id=153c2ea60099390c0001305e > Attributes: > --- end of STUN message --- > > 18:52:56.578 stuntsx14087F4 STUN client transaction created > 18:52:56.579 stuntsx14087F4 STUN sending message (transmit count=1) > > _______________________________________________ > Visit our blog: http://blog.pjsip.org > > pjsip mailing list > pjsip at lists.pjsip.org <mailto:pjsip at lists.pjsip.org> > http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org > > > ------------------------------------------------------------------------ > > _______________________________________________ > Visit our blog: http://blog.pjsip.org > > pjsip mailing list > pjsip at lists.pjsip.org > http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org >
