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>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>> 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>>> 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 >> 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 > 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 > 18:52:06.787 SIPCall.cpp pandre resolve_stun_server stun_srv in > SIPEngine=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' type=UDP resolved > to '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: > REGISTER sip:+351914871189 at wcs.wit-software.com<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<sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=3cce5f2e578642298a0beb9a06054e99To: > <sip:+351914871189 at wcs.wit-software.com<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: > SIP/2.0 100 TryingVia: SIP/2.0/UDP 172.18.0.51:64184;rport;branch=z9hG4bKPj5a52444ef72b4316a8f5c09a68d3e18bFrom: > <sip:+351914871189 at wcs.wit-software.com<sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=3cce5f2e578642298a0beb9a06054e99To: > <sip:+351914871189 at wcs.wit-software.com<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: > SIP/2.0 401 UnauthorizedVia: SIP/2.0/UDP 172.18.0.51:64184;rport;branch=z9hG4bKPj5a52444ef72b4316a8f5c09a68d3e18bFrom: > <sip:+351914871189 at wcs.wit-software.com<sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=3cce5f2e578642298a0beb9a06054e99To: > <sip:+351914871189 at wcs.wit-software.com<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' type=UDP resolved > to '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: > REGISTER sip:+351914871189 at wcs.wit-software.com<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<sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=3cce5f2e578642298a0beb9a06054e99To: > <sip:+351914871189 at wcs.wit-software.com<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", > realm="mcg", nonce="MTIxODA0NTEyNjk1MzpXSVQtTUNH", uri=" > sip:+351914871189 at wcs.wit-software.com<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: > SIP/2.0 100 TryingVia: SIP/2.0/UDP 172.18.0.51:64184;rport;branch=z9hG4bKPj6fde5226e9fe4ceaa2f2e2bc56b6236fFrom: > <sip:+351914871189 at wcs.wit-software.com<sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=3cce5f2e578642298a0beb9a06054e99To: > <sip:+351914871189 at wcs.wit-software.com<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: > SIP/2.0 200 OKVia: SIP/2.0/UDP 172.18.0.51:64184;rport;branch=z9hG4bKPj6fde5226e9fe4ceaa2f2e2bc56b6236fFrom: > <sip:+351914871189 at wcs.wit-software.com<sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=3cce5f2e578642298a0beb9a06054e99To: > <sip:+351914871189 at wcs.wit-software.com<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' type=UDP resolved > to '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: > 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<sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=d103bb6cc0da447e9c7c9c33639de6ffTo: > <sip:+351914871189 at wcs.wit-software.com<sip%3A%2B351914871189 at wcs.wit-software.com>>Contact: > <sip: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: > SIP/2.0 200 OKVia: SIP/2.0/UDP 172.18.0.51:64184;rport;branch=z9hG4bKPj2a88b60293e04037b45d300b58f62805From: > <sip:+351914871189 at wcs.wit-software.com<sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=d103bb6cc0da447e9c7c9c33639de6ffTo: > <sip:+351914871189 at wcs.wit-software.com<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: > NOTIFY sip:172.18.0.51:64184;transport=udp SIP/2.0Call-ID: > 604970b238994208a7d87f72670279d8CSeq: 1 NOTIFYFrom: < > sip:+351914871189 at wcs.wit-software.com<sip%3A%2B351914871189 at wcs.wit-software.com>>To: > <sip:+351914871189 at wcs.wit-software.com<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<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' type=UDP resolved > to '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: > SIP/2.0 200 OKVia: SIP/2.0/UDP 172.18.0.170:5060;received=172.18.0.170;branch=z9hG4bK2dc5f14fb0047ac49899ed225763d3feCall-ID: > 604970b238994208a7d87f72670279d8From: < > sip:+351914871189 at wcs.wit-software.com<sip%3A%2B351914871189 at wcs.wit-software.com>>To: > <sip:+351914871189 at wcs.wit-software.com<sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=d103bb6cc0da447e9c7c9c33639de6ffCSeq: > 1 NOTIFYContact: <sip: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' type=UDP resolved > to '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: > 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<sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=2dc057d91f2d43df9100295244573051To: > <sip:+351914871189 at wcs.wit-software.com<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<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: > SIP/2.0 100 TryingVia: SIP/2.0/UDP 172.18.0.51:64184;rport;branch=z9hG4bKPj435ca0600a114dcfa95f2e0042fcc663From: > <sip:+351914871189 at wcs.wit-software.com<sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=2dc057d91f2d43df9100295244573051To: > <sip:+351914871189 at wcs.wit-software.com<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: > SIP/2.0 200 OKVia: SIP/2.0/UDP 172.18.0.51:64184;rport;branch=z9hG4bKPj435ca0600a114dcfa95f2e0042fcc663From: > <sip:+351914871189 at wcs.wit-software.com<sip%3A%2B351914871189 at wcs.wit-software.com>>;tag=2dc057d91f2d43df9100295244573051To: > <sip:+351914871189 at wcs.wit-software.com<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 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 > : > --- 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: > --- 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 > SOURCE-ADDRESS: length=8, IPv4 addr=172.18.0.169:3478 > CHANGED-ADDRESS: length=8, IPv4 addr=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 > 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:64888added > 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 > 18:52:56.400 ICEVoiceTransp Comp 1: host candidate 192.168.102.1:64888added > 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:64888added > 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:64888added > 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 > : > --- 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 > http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org > > -------------- next part -------------- An HTML attachment was scrubbed... URL: http://lists.pjsip.org/pipermail/pjsip_lists.pjsip.org/attachments/20080807/89237e00/attachment-0001.html
