Re: [Serusers] Local ACKs for SER-SEMS

Cesc, I've tried to find some meaning in what you sent, but I don't really know the details of the ACK hack (pun not intended) Jan mentioned. To me it looks like the ACK is absorbed correctly. However, the REGISTER messages confuses me a bit. Also, you don't record_route CANCELs and ACKs, why? g-) ----- Original Message ----- From: "Cesc" &lt;cesc.santa(a)gmail.com&gt; To: "Cesc" &lt;cesc.santa(a)gmail.com&gt;om>; "Greger V. Teigre" &lt;greger(a)teigre.com&gt;om>; "SER-Users" &lt;serusers(a)lists.iptel.org&gt; Sent: Wednesday, November 23, 2005 12:31 PM Subject: Re: [Serusers] Local ACKs for SER-SEMS 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(a)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(a)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(a)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(a)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 &lt;jan(a)iptel.org&gt; wrote: