Hi,
I attach a tar'd.gz file with: a snippet of the ser.cfg file, a ser log and the messages (INV and OK) passed from-to ser-sems unix socket. I attach directly to this email a short version of the ser.log file and ser.cfg, for easyness ... hopefully it will go through ...
Hope it helps,
Cesc
============================================= ============================================= ===================================================== == ON THE UNIX SOCK (INVITE FROM SER) ============================================= 0.3 sip_request.intercom INVITE 10033 cafes.org 192.0.1.150 . sip:10033@cafes.org sip:jos@192.0.1.250:6060;transport=UDP sip:jos@cafes.org sip:10033@cafes.org 1832198372@192.0.1.250 1455248939
301 64360:678404969 . . P-MsgFlags: 0 Content-Type: application/sdp . v=0 o=- 3344 3344 IN IP4 192.0.1.250 s=Minisip Session c=IN IP4 192.0.1.250 t=0 0 m=audio 33958 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000/1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15
---ON THE UNIX SOCK (OK FROM SEMS)-------------------------------- 200 OK 64360:678404969 00002EE029403E89 Contact: sip:10033@192.0.1.150:5060 Content-Type: application/sdp Accept-Encoding: application/sdp, text/plain Accept: INVITE, ACK, OPTIONS, BYE, CANCEL, MESSAGE . v=0 o=sems 1515487739 872624585 IN IP4 192.0.1.150 s=- t=0 0 m=audio 7534 RTP/AVP 0 c=IN IP4 192.0.1.150 a=rtpmap:0 PCMU/8000
. ============================================= ============================================= =============================================
# # # SER config file. # #
################################################################################## # ----------- global configuration parameters ------------------------ fork=yes children=2 disable_core_dump=yes
log_stderror=yes debug=2 memlog=1000
listen=IP_LOCAL_SER
/* If not compiled with tls support, this param does not exhist */ disable_tls=0 /* See the first line of main route for another tls very important parameter!*/
tls_certificate="INSTALL_PATH/certs/MU_cert.pem" tls_private_key="INSTALL_PATH/private/MU_prik.pem" tls_ca_list="INSTALL_PATH/certs/ca_list.pem" tls_ciphers_list="NULL-SHA:NULL-MD5:AES256-SHA:AES128-SHA"
#Related to force_tcp_alias (see below) tcp_accept_aliases = yes
#Port to listen to ... this is the standard port where phones also listen .. # Make sure that if any phone running in this same computer, uses another port. port=5060
#hostnames matching an alias that will satisfy the condition uri==myself alias="DOMAIN_NAME" alias="DOMAIN_SUB_PREFIX.DOMAIN_NAME"
check_via=no # (cmd. line: -v) dns=no # (cmd. line: -r) rev_dns=no # (cmd. line: -R)
# ------------------------- request routing logic -------------------
################################################################################## # # main routing logic # route{ #start route[ROUTE.MAIN] ==================================================
# initial sanity checks -- messages with max_forwards==0, or excessively long requests if (!mf_process_maxfwd_header("10")) { sl_send_reply("483","Too Many Hops"); break; }; if (msg:len >= max_len ) { sl_send_reply("513", "Message too big"); break; }; force_tcp_alias(); if (!method=="REGISTER" && !method=="CANCEL" && !method=="ACK" ) { #record_route(); log(2, "LOG: Record route ... IP_LOCAL_SER\n"); record_route(); /*"IP_LOCAL_SER:5060");*/ }; if (loose_route()) { # mark routing logic in request log(2, "LOG: RR-enforced!\n"); append_hf("P-hint: rr-enforced\r\n"); setflag(FL_ROUTE_LOOSE); /* set source routed flag */ /* FIXME: It would be nice to have a way to authenticate loose routed messages ... maybe with TLS ... * but for now, just do nothing ... it only causes havoc */ log(2, "log: fixme!!! routed message ... \n"); route(ROUTE_RELAY); /* route to ROUTE.RELAY */ break; };
#Forward messages not directed to us ... if( ! (uri == myself) and ! is_uri_host_local() ) { log( 2, "LOG: Message not for any of our domains ...\n"); XXXX }; /*ends if ( ! uri == myself ...*/ if (method == "REGISTER" ) { route(ROUTE_REGISTER_MESSAGE); break; }; #end if method is REGISTER #REGISTER messages never go beyond this part
#Route Conference/SEMS related traffic if ( message_needs_to_be_routed_to_sems ){ route( ROUTE_SEMS_TRAFFIC ); break; #CONFERENCE related request should not go beyond this point }; route(ROUTE_RELAY); break; } #ends route[ROUTE MAIN] =====================================================
route[ROUTE_RELAY] /*ROUTE RELAY*/ {
log( 2, "LOG: relaying default case ...\n"); lookup("aliases"); if( ! lookup("location") ) { sl_send_reply("404", "Not Found"); break; } if (!t_relay()) { log(2, "LOG: t_relay error!\n"); sl_reply_error(); break; }; } /* #ends route[ROUTE_RELAY] */
route [ROUTE_REGISTER_MESSAGE] { /*ROUTE REGISTER MESSAGE*/
} /* ends route [ROUTE_REGISTER_MESSAGE]*/
################################################################################### # All SEMS related traffic comes here # Here non-REGISTER messages, such as INV and BYE are treated, and # forwarded to sems. # route [ROUTE_SEMS_TRAFFIC] { /* ROUTE SEMS TRAFFIC*/ log(2, "LOG: request related to a CONFERENCE\n");
#switch to stateful mode if(!t_newtran()){ sl_send_reply("500","colud not create transaction"); break; }; log( 2, "LOG: Transaction created.\n");
if(method=="ACK"){ #absorb ACKs, SER's stateful transaction previously created #will handle the ACK appropriately without passing them to SEMS break; };
t_reply("100", "Trying to contact Conference Server"); log( 2, "LOG: Provisional Response sent.\n");
if (method==INVITE || method==REFER || method==NOTIFY || method==SUBSCRIBE || method==OPTIONS || method==MESSAGE){ #assumes that Sems coinfiguration parameter 'fifo_name=' #has been set to /tmp/sems_fifo if (!t_write_unix("/tmp/sems_sock","semsheaders")){ t_reply("500","error contacting sems"); }; break; }else{ if(method==BYE || method==CANCEL){ #Sems should already know which plug-in is handling that call. #"bye is no plug-in name. It is a reserved name which tells Sems #to terminate the call if (!t_write_unix("/tmp/sems_sock","bye")){ t_reply("500","error contacting sems"); }; break; }; }; break; }
#Terminate with at least one empty line, pliz ============================================= ============================================= ============================================= ============================================= ============================================================ [Wed Nov 23 11:31:49 2005] 2(11986) XLOG: xl_print_log: final buffer length 25 2(11986) [192.0.1.250 ## 11986]
2(11986) XLOG: xl_print_log: final buffer length 561 2(11986) INVITE sip:10033@cafes.org SIP/2.0 From: sip:jos@cafes.org;tag=1455248939 To: sip:10033@cafes.org Call-ID: 1832198372@192.0.1.250 CSeq: 301 INVITE Contact: sip:jos@192.0.1.250:6060;transport=UDP;expires=1000 User-Agent: Minisip-Cafes-Tcnl Content-Type: application/sdp Via: SIP/2.0/UDP 192.0.1.250:6060;branch=z9hG4bK1238405167 Content-Length: 192
v=0 o=- 3344 3344 IN IP4 192.0.1.250 s=Minisip Session c=IN IP4 192.0.1.250 t=0 0 m=audio 33958 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000/1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15
2(11986) parse_headers: flags=128 2(11986) DEBUG: get_hdr_body : content_length=192 2(11986) found end of header 2(11986) DEBUG: is_maxfwd_present: max_forwards header not found! 2(11986) LOG: Record route ... 192.0.1.150 2(11986) DEBUG: add_param: tag=1455248939 2(11986) end of header reached, state=29 2(11986) parse_headers: flags=256 2(11986) find_first_route: No Route headers found 2(11986) loose_route: There is no Route HF 2(11986) grep_sock_info - checking if host==us: 9==11 && [cafes.org] == [192.0.1.150] 2(11986) grep_sock_info - checking if port 5060 matches port 5060 2(11986) grep_sock_info - checking if host==us: 9==10 && [cafes.org] == [230.0.1.75] 2(11986) grep_sock_info - checking if port 5060 matches port 5060 2(11986) grep_sock_info - checking if host==us: 9==9 && [cafes.org] == [127.0.0.1] 2(11986) grep_sock_info - checking if port 5060 matches port 5060 2(11986) grep_sock_info - checking if host==us: 9==11 && [cafes.org] == [192.0.1.150] 2(11986) grep_sock_info - checking if port 5060 matches port 5060 2(11986) grep_sock_info - checking if host==us: 9==9 && [cafes.org] == [127.0.0.1] 2(11986) grep_sock_info - checking if port 5060 matches port 5060 2(11986) grep_sock_info - checking if host==us: 9==11 && [cafes.org] == [192.0.1.150] 2(11986) grep_sock_info - checking if port 5061 matches port 5060 2(11986) LOG: Identifying tags ... local, any, all, grp, conf ... 2(11986) LOG: identifying tag: conf.id@domain 2(11986) LOG: request related to a CONFERENCE 2(11986) sl_send_reply: start 2(11986) parse_headers: flags=-1 2(11986) check_via_address(192.0.1.250, 192.0.1.250, 0) 2(11986) sl_send_reply:(1) sl_timeout=get_ticks()+SL_RPL_WAIT_TIME=602734 2(11986) sl_send_reply:(2) sl_timeout=get_ticks()+SL_RPL_WAIT_TIME=602762 2(11986) DEBUG: t_newtran: msg id=1393 , global msg id=1392 , T on entrance=0xffffffff 2(11986) parse_headers: flags=-1 2(11986) parse_headers: flags=60 2(11986) t_lookup_request: start searching: hash=64360, isACK=0 2(11986) DEBUG: RFC3261 transaction matching failed 2(11986) DEBUG: t_lookup_request: no transaction found 2(11986) LOG: Transaction created. 2(11986) LOG: Provisional Response sent. 2(11986) parse_headers: flags=-1 2(11986) DEBUG: t_check: msg id=1393 global id=1393 T start=0x4042900c 2(11986) DEBUG: t_check: T already found! 2(11986) assemble_msg: calculated route: 2(11986) assemble_msg: next r-uri: sip:jos@192.0.1.250:6060;transport=UDP 2(11986) parse_headers: flags=-1 2(11986) parse_headers: flags=-1 2(11986) DEBUG: add_to_tail_of_timer[0]: 0x40429134 2(11986) DEBUG:destroy_avp_list: destroying list (nil) 2(11986) receive_msg: cleaning up 1(11985) INFO: Deleting entry (location,10033) 1(11985) get_timeout: timeout: '5' 1(11985) get_method: method: 'REGISTER' 1(11985) get_ruri: 'sip:230.0.1.75' 1(11985) get_nexthop: next hop empty 1(11985) get_headers: From: sip:10033@cafes.org;tag=00002EE009A1E851 To: sip:10033@cafes.org CSeq: 1 REGISTER Call-ID: 00002EE07B210D73@192.0.1.150
1(11985) parse_headers: flags=-1 1(11985) end of header reached, state=9 1(11985) DEBUG: get_hdr_field: <To> [23]; uri=[sip:10033@cafes.org] 1(11985) DEBUG: to body [sip:10033@cafes.org ] 1(11985) get_hdr_field: cseq <CSeq>: <1> <REGISTER> 1(11985) get_body_lines: 1(11985) DEBUG: add_param: tag=00002EE009A1E851 1(11985) end of header reached, state=29 1(11985) uac_unixsock: set_loc_timers: transaction avp parameters set to 5 1(11985) DEBUG:tm:t_uac: next_hop=sip:230.0.1.75 1(11985) DEBUG: mk_proxy: doing DNS lookup... 1(11985) DEBUG:destroy_avp_list: destroying list (nil) 1(11985) DEBUG: dlg2hash: 34757 1(11985) DEBUG: add_to_tail_of_timer[4]: 0x40433f6c 1(11985) DEBUG: add_to_tail_of_timer[0]: 0x40433f7c 4(11988) SIP Request: 4(11988) method: <REGISTER> 4(11988) uri: sip:230.0.1.75 4(11988) version: <SIP/2.0> 4(11988) parse_headers: flags=1 4(11988) Found param type 232, <branch> = <z9hG4bK5c78.6c8171b3.0>; state=16 4(11988) end of header reached, state=5 4(11988) parse_headers: Via found, flags=1 4(11988) parse_headers: this is the first via 4(11988) After parse_msg... 4(11988) preparing to run routing scripts... 4(11988) CESC: exec_pre_cb: start calling precallback scripts!!! 4(11988) CESC: exec_pre_cb: pre script callback called!! 4(11988) TIC:tic_response_callback: starting 4(11988) DEBUG : tic_response_callback : only checking replies 4(11988) TIC:tic_response_callback: No operation 4(11988) CESC: exec_pre_cb: pre script callback called!! 4(11988) CESC: exec_pre_cb: pre script callback called!! 4(11988) LOG: ERROR: We got a message looped back from the multicast address, sent by ourselves. 4(11988) LOG: ERROR: Discarding this message 4(11988) parse_headers: flags=8 4(11988) end of header reached, state=9 4(11988) DEBUG: get_hdr_field: <To> [23]; uri=[sip:10033@cafes.org] 4(11988) DEBUG: to body [sip:10033@cafes.org ] 4(11988) DEBUG: add_param: tag=00002EE009A1E851 4(11988) end of header reached, state=29 4(11988) XLOG: xl_print_log: final buffer length 96 4(11988) REGISTER 230.0.1.75 From: sip:10033@cafes.org;00002EE009A1E851 To: sip:10033@cafes.org;<null>
4(11988) DEBUG:destroy_avp_list: destroying list (nil) 4(11988) receive_msg: cleaning up 1(11985) parse_transid: hash_index=64360 label=678404969 1(11985) lineset: Contact: sip:10033@192.0.1.150:5060 Content-Type: application/sdp Accept-Encoding: application/sdp, text/plain Accept: INVITE, ACK, OPTIONS, BYE, CANCEL, MESSAGE
1(11985) body: v=0 o=sems 1515487739 872624585 IN IP4 192.0.1.150 s=- t=0 0 m=audio 7534 RTP/AVP 0 c=IN IP4 192.0.1.150 a=rtpmap:0 PCMU/8000
1(11985) DEBUG: t_lookup_ident: transaction found 1(11985) parse_headers: flags=-1 1(11985) check_via_address(192.0.1.250, 192.0.1.250, 0) 1(11985) DEBUG: cleanup_uac_timers: RETR/FR timers reset 1(11985) DEBUG: add_to_tail_of_timer[4]: 0x404290b8 1(11985) DEBUG: add_to_tail_of_timer[0]: 0x404290c8 1(11985) DEBUG: reply sent out. buf=0x820bd04: SIP/2.0 2..., shmem=0x40431bd4: SIP/2.0 2 1(11985) DEBUG: _reply_light: finished 3(11987) SIP Request: 3(11987) method: <ACK> 3(11987) uri: sip:10033@192.0.1.150:5060 3(11987) version: <SIP/2.0> 3(11987) parse_headers: flags=1 3(11987) DEBUG: add_param: tag=00002EE029403E89 3(11987) end of header reached, state=29 3(11987) DEBUG: get_hdr_field: <To> [44]; uri=[sip:10033@cafes.org] 3(11987) DEBUG: to body [sip:10033@cafes.org] 3(11987) get_hdr_field: cseq <CSeq>: <301> <ACK> 3(11987) Found param type 232, <branch> = <z9hG4bK1238405167>; state=16 3(11987) end of header reached, state=5 3(11987) parse_headers: Via found, flags=1 3(11987) parse_headers: this is the first via 3(11987) After parse_msg... 3(11987) preparing to run routing scripts... 3(11987) CESC: exec_pre_cb: start calling precallback scripts!!! 3(11987) CESC: exec_pre_cb: pre script callback called!! 3(11987) TIC:tic_response_callback: starting 3(11987) DEBUG : tic_response_callback : only checking replies 3(11987) TIC:tic_response_callback: No operation 3(11987) CESC: exec_pre_cb: pre script callback called!! 3(11987) CESC: exec_pre_cb: pre script callback called!! 3(11987) ERROR : SL_FILTER_ACK: *(sl_timeout)=602762, get_ticks()=602760 3(11987) parse_headers: flags=4 3(11987) ERROR : SL_FILTER_ACK: before if(msg->to) 3(11987) ERROR : SL_FILTER_ACK: inside if(msg->to) 3(11987) ERROR : SL_FILTER_ACK: tag_str.len=16, TOTAG_VALUE_LEN=37 3(11987) ERROR : SL_FILTER_ACK: tag_str.s=00002EE029403E89; sl_tag.s=f0ecfd42b179c81ffc953dd05dc8350b.ba0d 3(11987) ERROR : sl_filter_ACK : NO local ACK found 3(11987) XLOG: xl_print_log: final buffer length 91 3(11987)
============================================================ [Wed Nov 23 11:31:49 2005] 3(11987) XLOG: xl_print_log: final buffer length 25 3(11987) [192.0.1.250 ## 11987]
3(11987) XLOG: xl_print_log: final buffer length 280 3(11987) ACK sip:10033@192.0.1.150:5060 SIP/2.0 Max-Forwards: 70 From: sip:jos@cafes.org;tag=1455248939 To: sip:10033@cafes.org;tag=00002EE029403E89 Call-ID: 1832198372@192.0.1.250 CSeq: 301 ACK Via: SIP/2.0/UDP 192.0.1.250:6060;branch=z9hG4bK1238405167 Content-Length: 0
3(11987) DEBUG:maxfwd:is_maxfwd_present: value = 70 3(11987) DBG:maxfwd:process_maxfwd_header: value 70 decreased to 16 3(11987) parse_headers: flags=256 3(11987) DEBUG: get_hdr_body : content_length=0 3(11987) found end of header 3(11987) find_first_route: No Route headers found 3(11987) loose_route: There is no Route HF 3(11987) grep_sock_info - checking if host==us: 11==11 && [192.0.1.150] == [192.0.1.150] 3(11987) grep_sock_info - checking if port 5060 matches port 5060 3(11987) LOG: Identifying tags ... local, any, all, grp, conf ... 3(11987) LOG: identifying tag: conf.id@domain 3(11987) LOG: request related to a CONFERENCE 3(11987) sl_send_reply: start 3(11987) Warning: sl_send_reply: I won't send a reply for ACK!! 3(11987) LOG: ACK intercom received ... 3(11987) DEBUG: t_check: msg id=1674 global id=1673 T start=0xffffffff 3(11987) parse_headers: flags=-1 3(11987) parse_headers: flags=60 3(11987) t_lookup_request: start searching: hash=64360, isACK=1 3(11987) parse_headers: flags=28 3(11987) DEBUG: add_param: tag=1455248939 3(11987) end of header reached, state=29 3(11987) DEBUG: t_lookup_request: e2e proxy ACK found 3(11987) DEBUG: t_check: msg id=1674 global id=1674 T end=(nil) 3(11987) LOG: ACK intercom transaction DOES NOT exhist ... simply absorbing 3(11987) DEBUG:destroy_avp_list: destroying list (nil) 3(11987) receive_msg: cleaning up 8(11992) timer_ticker()!!! 8(11992) DEBUG: timer routine:0,tl=0x40429134 next=(nil) 8(11992) DEBUG: timer routine:4,tl=0x40433f6c next=0x404290b8 8(11992) DEBUG: retransmission_handler : request resending (t=0x40433e54, REGISTER ... ) 8(11992) DEBUG: add_to_tail_of_timer[5]: 0x40433f6c 8(11992) DEBUG: retransmission_handler : done 8(11992) DEBUG: timer routine:4,tl=0x404290b8 next=(nil) 8(11992) DEBUG: retransmission_handler : reply resending (t=0x4042900c, SIP/2.0 2 ... ) 8(11992) DEBUG: reply retransmitted. buf=0x401a4620: SIP/2.0 2..., shmem=0x40431bd4: SIP/2.0 2 8(11992) DEBUG: add_to_tail_of_timer[5]: 0x404290b8 8(11992) DEBUG: retransmission_handler : done
=====================================================
On 11/23/05, Jan Janak jan@iptel.org wrote:
Actually I've seen the mail but did not have yet time to look into it (I have it on my todo list). When communicating with applications like sems over the fifo or unix sockets, SER takes care of ACK processing (that also means generating local e2e ACKs on behalf of sems). This is a hack because tm has to do all the dialog-related logic (such as route processing, loose/strict routing and so on).
Inside tm end-to-end ACKs are matched with the original INVITE transaction. This was needed for accounting purposes, if I recall it correctly.
In any case full tm traces would be helpful, especially for P3.
Jan.
On 23-11-2005 10:38, Cesc wrote:
Hi Greger,
First, the last half of your email ... i cannot run a dedicated instance of SER. We run an embedded system, thus not much space and power to spare. As for the NAT ... we have no NAT in our network (lucky us :D ).
As for the first part ... i had not seen a response either :) Actually, i lost the email in gmail folders, could not find it anywhere ... tks for replying, now i found it again. As for the ACK ... i tried using t_lookup_request ... it turns out that it does find a transaction, but it identifies them as e2e (i guess ... end2end) ... i will investigate further ... and i will provide a trace.
Tks!
Cesc
On 11/23/05, Greger V. Teigre greger@teigre.com wrote:
Hi Cesc, I haven't seen a response to your post?! Are you sure the ACKs are not caught by loose routing? I would suggest setting up a separate ser instance on ex. port 5062 and dedicate it to sems interfacing. Then in your main ser you just correctly forwards the INVITEs to the sems ser instance. Also remember to run fix_nated_sdp("3") for NATed clients (SEMS support active media. Both sems and SER-SEMS should run on a public IP. g-) ----- Original Message ----- From: "Cesc" cesc.santa@gmail.com To: "SER-Users" serusers@lists.iptel.org Sent: Wednesday, November 16, 2005 11:13 AM Subject: [Serusers] Local ACKs for SER-SEMS
Hi,
In my lab we have SER (0.9.4) running, collocated in the same box with SEMS, communicating via the fifo.
An abstraction of the config:
//identify traffic for SEMS //send to route[x]
route[x] { if( !t_newtran() ) { ..... } if( method == "ACK" ) { break;} //drop local acks ... t_reply("100", "msg"); send via fifo to sems ... }
I have stumbled against some problems:
P1) Local ACKs from the phone are not being dropped. P2) to-tag in replies from SER from sl_send_reply and OK message change P3) the t_newtran does not stop sending OKs, even it receives ACKs to them
They all seem to be related ... the ACK from the phone back to SER, which are local(right?), are not dropped for two reasons: the sl_timeout is not updated, as i don't have an sl_send_reply in the route[x] block. I can fix the above by adding an sl_send_reply("183", "sems session in progress") ... but then, the second problem appears. Adding the sl_send_reply(183, ) adds a to-tag to the 183-reply, but then the following OK has a completely different to-tag ... which is the one used by my UA to create the ACK. As the to-tag in the ACK is different to that from the 183-reply ... the sl_filter_ack does not recognize the ACK as local, and does not filter it.
In any case, this would not solve the problem of the t_newtran sending OK replies to the phone, even it receives ACKs to them.
What can i do? should i use t_release somewhere? are these ACKs "local"? if not, where should these ACKs be routed to, to the route[x] block?
Tks in advance,
Cesc
Serusers mailing list serusers@lists.iptel.org http://lists.iptel.org/mailman/listinfo/serusers
Serusers mailing list serusers@lists.iptel.org http://lists.iptel.org/mailman/listinfo/serusers