Hello All, I noticed that if I call nua_respond() to accept (202 Accepted) an incoming SUBSCRIBE request from my application thread, sofia-sip replies with "500 Responding to a Non-Existing Request" (see trace below with logs of interest surrounded by ****).
If I call nua_respond() from within the callback function (instead of sending a message to application thread), then sofia-sip can transmit the message correctly. Anyone know why this happens? Best Regards, Jerry -----------------------------START OF TRACE LOG OUTPUT------------------------------------------------------------ Type Summary **** CESC ce_ProcCallback: Rcvd event for nua=0x7968c0, pMkData=0x77f194, nh=0x7bbb30, hmagic=0x0, sip=0x7baa14 CESC nua_i_subscribe event: 100 Trying (pMkData->mk=MK1=lineH=0x7968c0) CESC tSubscriberState=nea_embryonic CESC Expires=3700 CESC ce_AllocCeSipData: CESC [EMAIL PROTECTED] CESC contact=sip:[EMAIL PROTECTED] :5096 CESC Reporting Event... **** SOFI nua: nua_event: entering CESC ce_ProcCallback: Rcvd event for nua=0x7968c0, pMkData=0x77f194, nh=0x7b3848, hmagic=0x77f194, sip=0x7bdf6c CESC nua_r_register event: 200 Registration Request Accepted (pMkData->mk=MK1=lineH=0x7968c0) CESC Reporting Event... SOFI nta: timer set next to 160 ms SOFI tport_wakeup_pri(0x7b0498): events IN SOFI tport_recv_event(0x7b0498) SOFI tport_recv_iovec(0x7b0498) msg 0x7bfe98 from (udp/206.80.111.20:50001) has 388 bytes, veclen = 1 SOFI tport_deliver(0x7b0498): msg 0x7bfe98 (388 bytes) from udp/206.229.26.61:50001/sip next=(nil) SOFI nta: received 100 Trying for SUBSCRIBE (101441799) SOFI nta: 100 Trying is going to a transaction SOFI nta_outgoing: RTT is 376.61 ms SOFI tport_release(0x7b0498): 0x7be8e8 by 0x7bf170 with 0x7bfe98 (preliminary) SOFI nua(0x7b3b98): event r_subscribe 100 Trying SOFI tport_wakeup_pri(0x7b0498): events IN SOFI tport_recv_event(0x7b0498) SOFI tport_recv_iovec(0x7b0498) msg 0x7c0428 from (udp/206.80.111.20:50001) has 521 bytes, veclen = 1 SOFI tport_deliver(0x7b0498): msg 0x7c0428 (521 bytes) from udp/206.229.26.61:50001/sip next=(nil) SOFI nta: received 202 Accepted for SUBSCRIBE (101441799) SOFI nta: 202 Accepted is going to a transaction SOFI tport_release(0x7b0498): 0x7be8e8 by 0x7bf170 with 0x7c0428 SOFI nua(): refresh subscribe after 1229 seconds (in [900..2700]) SOFI nua(): refresh subscribe after 1229 seconds SOFI nua(0x7b3b98): event r_subscribe 202 Accepted SOFI tport_wakeup_pri(0x7b0498): events IN SOFI tport_recv_event(0x7b0498) SOFI tport_recv_iovec(0x7b0498) msg 0x7c0eb0 from (udp/206.80.111.20:50001) has 558 bytes, veclen = 1 SOFI tport_deliver(0x7b0498): msg 0x7c0eb0 (558 bytes) from udp/206.229.26.61:50001/sip next=(nil) SOFI nta: received NOTIFY sip:[EMAIL PROTECTED]:50001 SIP/2.0 (CSeq 2) SOFI nta: canonizing sip:[EMAIL PROTECTED]:50001 with contact SOFI nta: NOTIFY (2) going to existing leg SOFI nua(0x7b3b98): nua_notify_server_preprocess: active () SOFI tport_tsend(0x7b0498) tpn = UDP/206.229.26.61:5097 SOFI tport_resolve addrinfo = 206.229.26.61:5097 SOFI tport_by_addrinfo(0x7b0498): not found by name UDP/206.229.26.61:5097 SOFI tport_vsend(0x7b0498): 485 bytes of 485 to UDP/206.229.26.61:5097 SOFI tport_vsend returned 485 SOFI nta: sent 200 OK for NOTIFY (2) SOFI nua(0x7b3b98): event i_notify 200 OK SOFI nua(): refresh subscribe after 1845 seconds (in [900..2700]) SOFI nua(): refresh subscribe after 1845 seconds SOFI tport_wakeup_pri(0x7b0498): events IN SOFI tport_recv_event(0x7b0498) SOFI tport_recv_iovec(0x7b0498) msg 0x7c28a8 from (udp/206.80.111.20:50001) has 558 bytes, veclen = 1 SOFI tport_deliver(0x7b0498): msg 0x7c28a8 (558 bytes) from udp/206.229.26.61:50001/sip next=(nil) SOFI nta: received NOTIFY sip:[EMAIL PROTECTED]:50001 SIP/2.0 (CSeq 2) SOFI nta: NOTIFY (2) going to existing NOTIFY transaction SOFI nta: re-received NOTIFY request, retransmitting 200 reply SOFI tport_tsend(0x7b0498) tpn = UDP/206.229.26.61:5097 SOFI tport_resolve addrinfo = 206.229.26.61:5097 SOFI tport_by_addrinfo(0x7b0498): not found by name UDP/206.229.26.61:5097 SOFI tport_vsend(0x7b0498): 485 bytes of 485 to UDP/206.229.26.61:5097 SOFI tport_vsend returned 485 SOFI tport_wakeup_pri(0x7b0498): events IN SOFI tport_recv_event(0x7b0498) SOFI tport_recv_iovec(0x7b0498) msg 0x7c28a8 from (udp/206.80.111.20:50001) has 468 bytes, veclen = 1 SOFI tport_deliver(0x7b0498): msg 0x7c28a8 (468 bytes) from udp/206.229.26.61:50001/sip next=(nil) SOFI nta: received SUBSCRIBE sip:[EMAIL PROTECTED]:50001 SIP/2.0 (CSeq 2) SOFI nta: SUBSCRIBE (2) going to existing SUBSCRIBE transaction SOFI nua: nua_event: entering CESC ce_ProcCallback: Rcvd event for nua=0x7968c0, pMkData=0x77f194, nh=0x7b3b98, hmagic=0x77f194, sip=0x7bff34 CESC nua_r_subscribe event: 100 Trying (pMkData->mk=MK1=lineH=0x7968c0) CESC Discarding Event... SOFI nua: nua_event: entering CESC ce_ProcCallback: Rcvd event for nua=0x7968c0, pMkData=0x77f194, nh=0x7b3b98, hmagic=0x77f194, sip=0x7c04c4 CESC nua_r_subscribe event: 202 Accepted (pMkData->mk=MK1=lineH=0x7968c0) CESC Reporting Event... SOFI nua: nua_event: entering CESC ce_ProcCallback: Rcvd event for nua=0x7968c0, pMkData=0x77f194, nh=0x7b3b98, hmagic=0x77f194, sip=0x7c0f4c CESC nua_i_notify event: 200 OK (pMkData->mk=MK1=lineH=0x7968c0) CESC ce_ProcCallbackNotify: Rcvd message-summary event CESC ce_ProcCallbackNotifyMsgSummary: CESC MWI OFF for LA1 CESC Handled Event Locally... SOFI nta: timer set next to 1461 ms **** CE2S nua_respond(nh=0x7bbb30, status=202, phrase='Accepted', NUTAG_WITH_THIS(0x7968c0)) **** SOFI nua: nua_respond: entering SOFI nua(0x7bbb30): signal r_respond CE2S nua_notify(nh=0x7bbb30, SIPTAG_FROM(), CE2S NUTAG_SUBSTATE(active), SIPTAG_EVENT(dialog;sla;include-session-description), CE2S SIPTAG_CONTENT_TYPE(application/dialog-info+xml), CE2S SIPTAG_PAYLOAD(...)): CE2S <?xml version="1.0"?> CE2S <dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="0" state="full" entity="sip:[EMAIL PROTECTED]:5060"> CE2S </dialog-info> SOFI nua: nua_notify: entering SOFI nua(0x7bbb30): signal r_notify CE2S [2]nua_handle(nua=0x7968c0, hmagic=0x77f194, url='sip:[EMAIL PROTECTED]:50 96') SOFI nua: nh_create_handle: entering CE2S ...[2]nua_handle() returned nh=0x7c0dc8 CE2S nua_subscribe(nh=0x7c0dc8, CE2S SIPTAG_FROM(sip:[EMAIL PROTECTED]:5060), SIPTAG_EXPIRES(3600), CE2S SIPTAG_CONTACT(sip:[EMAIL PROTECTED]:50001), SIPTAG_EVENT(dialog;sla;include-session-description), CE2S SIPTAG_ACCEPT(application/dialog-info+xml)) SOFI nua: nua_subscribe: entering SOFI nua(0x7c0dc8): signal r_subscribe SOFI nua(0x7bbb30): recv r_respond SOFI nua(0x7bbb30): signal r_respond 202 Accepted **** SOFI nua(0x7bbb30): event i_error 500 Responding to a Non-Existing Request **** SOFI nua(0x7bbb30): recv r_notify SOFI nua(0x7bbb30): signal r_notify SOFI nua: nua_stack_set_params: entering SOFI soa_set_params(static::0x7bbee8, ...) called SOFI nta: selecting scheme sip SOFI tport(0x7b0498): EXPENSIVE unresolved */206.229.26.61:5096 SOFI tport_tsend(0x7b0498) tpn = */206.229.26.61:5096 SOFI tport_resolve addrinfo = 206.229.26.61:5096 SOFI tport_by_addrinfo(0x7b0498): not found by name */206.229.26.61:5096 SOFI tport_vsend(0x7b0498): 889 bytes of 889 to */206.229.26.61:5096 SOFI tport_vsend returned 889 SOFI nta: sent NOTIFY (101441800) to */206.229.26.61:5096 SOFI tport_pend(0x7b0498): pending 0x7c2fc0 for udp/206.80.111.20:50001 (already 0) SOFI nta: timer shortened to 500 ms SOFI nua(0x7c0dc8): recv r_subscribe SOFI nua(0x7c0dc8): signal r_subscribe SOFI nua: nua_stack_set_params: entering SOFI soa_clone(static::0x7aede0, 0x7ae960, 0x7c0dc8) called SOFI soa_set_params(static::0x7c4178, ...) called SOFI nta_leg_tcreate(0x7c4948) SOFI nua(0x7c0dc8): adding subscribe usage with event dialog SOFI nta: selecting scheme sip SOFI tport(0x7b0498): EXPENSIVE unresolved */206.229.26.61:5096 SOFI tport_tsend(0x7b0498) tpn = */206.229.26.61:5096 SOFI tport_resolve addrinfo = 206.229.26.61:5096 SOFI tport_by_addrinfo(0x7b0498): not found by name */206.229.26.61:5096 SOFI tport_vsend(0x7b0498): 714 bytes of 714 to */206.229.26.61:5096 SOFI tport_vsend returned 714 SOFI nta: sent SUBSCRIBE (101441801) to */206.229.26.61:5096 SOFI tport_pend(0x7b0498): pending 0x7c4d68 for udp/206.80.111.20:50001 (already 1) SOFI nua: nua_event: entering **** CESC ce_ProcCallback: Rcvd event for nua=0x7968c0, pMkData=0x77f194, nh=0x7bbb30, hmagic=0x0, sip=0x0 CESC nua_i_error event: 500 Responding to a Non-Existing Request (pMkData->mk=MK1=lineH=0x7968c0) CESC Discarding Event... **** -----------------------------END OF TRACE LOG OUTPUT------------------------------------------------------------ ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/ _______________________________________________ Sofia-sip-devel mailing list Sofia-sip-devel@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/sofia-sip-devel
