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
Hi Klaus,
as you suspected, the problem is the fact the ACK does not match a transaction on proxy 2 and 3. The acc engine is transaction stateful and logs only request belonging to a transaction marked for accounting. Proxy 1 matches the ACK as and end2end ACK for 200 OK (finds the INVITE transaction) and does acc. The following proxies are not able to match the ACK to any INVITE transactions.
So, I guess we should look at the ACK and INVITE (as received) on proxy 2 to find why they do not match anymore...some dumps are welcomed ;)
regards, bogdan
Klaus Darilion wrote:
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
Users mailing list Users@openser.org http://openser.org/cgi-bin/mailman/listinfo/users
-
Bogdan-Andrei Iancu -
Klaus Darilion