[Users] problem accounting of ACKs

Hi! I have problems accounting ACK (e2e ACKs after INVITE-200 Ok). I have the following setup: client1 proxy1 proxy2 proxy3 client2 |---INVITE--->| | | | | rewritehostport | | | | t_relay | | | | |--INVITE->| | | | | enum_lookup | | | | t_relay | | | | |-INVITE-->| | | | | lookup() | | | | t_relay | | | | |-----INVITE->| | | | | | | | | |<----200 OK--| | | |<--200 OK-| | | |<--200 OK-| | | | <--200 OK---| | | | | | | | | | ---ACK----> | | | | | loose_route | | | | |----ACK-> | | | | | loose_route | | | | |---ACK--->| | | | | loose_route | | | | |---ACK------>| | | | | | All proxies do accounting. I do see the INVITE and BYE requests accountend by all proxies, but the ACK is only accounted by proxy1. All proxies are configured nearly identical: # accounting parameters modparam("acc", "early_media", 1) modparam("acc", "report_ack", 1) modparam("acc", "report_cancels", 0) modparam("acc", "multi_leg_enabled", 0) modparam("acc", "failed_transaction_flag", 4) # radius, syslog and DB modparam("acc", "log_flag", 1) # syslog modparam("acc", "db_flag", 2) # DB modparam("acc", "db_missed_flag", 3) # DB missed calles table modparam("acc", "swap_direction", 1) and all the flags are set for sure: route{ setflag(1);setflag(2); setflag(3);setflag(4); Does somebody had a similar problem? Are there any known issues how ACKs are handled? Studying the debug log. it looks like proxy 1 identifies the ACK as belonging to a transaction, whereas proxy 2 does not find the transaction (full debug at the end of the mail): proxy 1: ----------- t_lookup_request: start searching: hash=6242, isACK=1 parse_headers: flags=38 DEBUG: t_lookup_request: e2e proxy ACK found parse_headers: flags=8 DEBUG: totag for e2e ACK found: 0 DBG: trans=0x406b1940, callback type 4, id 0 entered parse_headers: flags=258 ACC: request acknowledged: method=ACK, i-uri=sip:user201@..... proxy 2: ----------- t_lookup_request: start searching: hash=6242, isACK=1 DEBUG: proceeding to pre-RFC3261 transaction matching DEBUG: t_lookup_request: no transaction found DEBUG:tm:t_relay: forwarding ACK statelessly DEBUG: mk_proxy: doing DNS lookup... parse_headers: flags=1000 check_via_address(10.10.0.41, 10.10.0.41, 0) Sending: ACK sip:user201@10.10.1.50:8737 SIP/2.0^M To: <sip:+43201@proxy1 Thus, why is there a matching transaction in proxy 1, but not in proxy 2? Why are ACKs not accounting in every case? Thanks Klaus proxy 1 (full debug): ------------------- SIP Request: method: <ACK> uri: <sip:user201@10.10.1.50:8737> version: <SIP/2.0> parse_headers: flags=2 DEBUG: add_param: tag=2b4e3b2d DEBUG:parse_to:end of header reached, state=29 DEBUG: get_hdr_field: <To> [52]; uri=[sip:+43201@proxy1.ienum.labs.nic.at] DEBUG: to body [<sip:+43201@proxy1.ienum.labs.nic.at>] Found param type 232, <branch> = <z9hG4bK-d87543-685643142-1--d87543->; state=6 Found param type 235, <rport> = <n/a>; state=17 end of header reached, state=5 parse_headers: Via found, flags=2 parse_headers: this is the first via After parse_msg... preparing to run routing scripts... DEBUG : sl_filter_ACK: to late to be a local ACK! DEBUG: add_param: tag=f937ab7a DEBUG:parse_to:end of header reached, state=29 xl_printf: final buffer length 186 parse_headers: flags=100 get_hdr_field: cseq <CSeq>: <2> <ACK> DEBUG:maxfwd:is_maxfwd_present: value = 70 parse_headers: flags=200 is_preloaded: No grep_sock_info - checking if host==us: 10==10 && [10.10.1.50] == [10.10.0.41] grep_sock_info - checking if port 5060 matches port 8737 grep_sock_info - checking if host==us: 10==10 && [10.10.1.50] == [10.10.0.41] grep_sock_info - checking if port 5060 matches port 8737 grep_sock_info - checking if host==us: 10==10 && [10.10.1.50] == [10.10.0.41] grep_sock_info - checking if port 5061 matches port 8737 check_self: host != me grep_sock_info - checking if host==us: 10==10 && [10.10.0.41] == [10.10.0.41] grep_sock_info - checking if port 5060 matches port 5060 after_loose: Topmost route URI: 'sip:10.10.0.41;lr;ftag=f937ab7a' is me after_loose: URI to be processed: 'sip:10.10.0.41:5062;r2=on;ftag=f937ab7a;lr=on' after_loose: Next URI is a loose router parse_headers: flags=ffffffffffffffff DEBUG: get_hdr_body : content_length=0 found end of header DEBUG: t_newtran: msg id=2 , global msg id=0 , T on entrance=0xffffffff parse_headers: flags=ffffffffffffffff parse_headers: flags=78 t_lookup_request: start searching: hash=6242, isACK=1 parse_headers: flags=38 DEBUG: t_lookup_request: e2e proxy ACK found parse_headers: flags=8 DEBUG: totag for e2e ACK found: 0 DBG: trans=0x406b1940, callback type 4, id 0 entered parse_headers: flags=258 ACC: request acknowledged: method=ACK, i-uri=sip:user201@10.10.1.50:8737, o-uri=sip:user201@10.10.1.50:8737, call_id=9c5e0930eb2b8e5a, from="user101"<sip:user101@proxy1.ienum.labs.nic.at>;tag=f937ab7a, code=200 parse_headers: flags=258 grep_sock_info - checking if host==us: 10==10 && [10.10.1.50] == [10.10.0.41] grep_sock_info - checking if port 5060 matches port 8737 grep_sock_info - checking if host==us: 10==10 && [10.10.1.50] == [10.10.0.41] grep_sock_info - checking if port 5060 matches port 8737 grep_sock_info - checking if host==us: 10==10 && [10.10.1.50] == [10.10.0.41] grep_sock_info - checking if port 5061 matches port 8737 check_self: host != me Route ftag and From tag are same DEBUG:tm:t_relay: forwarding ACK statelessly DEBUG: mk_proxy: doing DNS lookup... check_via_address(10.10.1.51, 10.10.1.51, 0) Sending: ACK sip:user201@10.10.1.50:8737 SIP/2.0^M To: <sip:+43201@proxy1 proxy 2 (full debug): ------------------- SIP Request: method: <ACK> uri: <sip:user201@10.10.1.50:8737> version: <SIP/2.0> parse_headers: flags=2 DEBUG: add_param: tag=2b4e3b2d DEBUG:parse_to:end of header reached, state=29 DEBUG: get_hdr_field: <To> [52]; uri=[sip:+43201@proxy1.ienum.labs.nic.at] DEBUG: to body [<sip:+43201@proxy1.ienum.labs.nic.at>] Found param type 232, <branch> = <0>; state=16 end of header reached, state=5 parse_headers: Via found, flags=2 parse_headers: this is the first via After parse_msg... preparing to run routing scripts... DEBUG : sl_filter_ACK: to late to be a local ACK! DEBUG: add_param: tag=f937ab7a DEBUG:parse_to:end of header reached, state=29 xl_printf: final buffer length 186 parse_headers: flags=100 Found param type 232, <branch> = <z9hG4bK-d87543-685643142-1--d87543->; state=6 Found param type 235, <rport> = <6477>; state=16 end of header reached, state=5 parse_headers: Via found, flags=100 parse_headers: this is the second via get_hdr_field: cseq <CSeq>: <2> <ACK> DEBUG:maxfwd:is_maxfwd_present: value = 69 parse_headers: flags=200 is_preloaded: No grep_sock_info - checking if host==us: 10==10 && [10.10.1.50] == [10.10.0.41] grep_sock_info - checking if port 5062 matches port 8737 grep_sock_info - checking if host==us: 10==10 && [10.10.1.50] == [10.10.0.41] grep_sock_info - checking if port 5062 matches port 8737 grep_sock_info - checking if host==us: 10==10 && [10.10.1.50] == [10.10.0.41] grep_sock_info - checking if port 5063 matches port 8737 check_self: host != me grep_sock_info - checking if host==us: 10==10 && [10.10.0.41] == [10.10.0.41] grep_sock_info - checking if port 5062 matches port 5062 after_loose: Topmost route URI: 'sip:10.10.0.41:5062;r2=on;ftag=f937ab7a;lr=on' is me grep_sock_info - checking if host==us: 10==10 && [10.10.0.41] == [10.10.0.41] grep_sock_info - checking if port 5063 matches port 5063 after_loose: URI to be processed: 'sip:10.10.0.42:5063;transport=tls;r2=on;ftag=f937ab7a;lr=on' after_loose: Next URI is a loose router DEBUG: has_totag: totag found parse_headers: flags=ffffffffffffffff DEBUG: get_hdr_body : content_length=0 found end of header DEBUG: t_newtran: msg id=1 , global msg id=0 , T on entrance=0xffffffff parse_headers: flags=ffffffffffffffff parse_headers: flags=78 t_lookup_request: start searching: hash=6242, isACK=1 DEBUG: proceeding to pre-RFC3261 transaction matching DEBUG: t_lookup_request: no transaction found DEBUG:tm:t_relay: forwarding ACK statelessly DEBUG: mk_proxy: doing DNS lookup... parse_headers: flags=1000 check_via_address(10.10.0.41, 10.10.0.41, 0) Sending: ACK sip:user201@10.10.1.50:8737 SIP/2.0^M To: <sip:+43201@proxy1