[pjsip] [Fwd: Re: Exceptions when using ICE functionalities]
Pedro Gonçalves
pedro.pandre at gmail.com
Fri Aug 8 10:07:59 EDT 2008
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: [pjsip] Exceptions when using ICE functionalities
Date: Fri, 08 Aug 2008 14:56:24 +0100
From: Pedro Gonçalves <pedro.pandre at gmail.com>
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 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>>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 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 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
>
More information about the pjsip
mailing list