[Users] problem accounting of ACKs
Bogdan-Andrei Iancu
bogdan at voice-system.ro
Mon Jan 9 18:17:52 CET 2006
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 at .....
>
> 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 at 10.10.1.50:8737 SIP/2.0^M To: <sip:+43201 at 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 at 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 at proxy1.ienum.labs.nic.at]
> DEBUG: to body [<sip:+43201 at 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 at 10.10.1.50:8737, o-uri=sip:user201 at 10.10.1.50:8737,
> call_id=9c5e0930eb2b8e5a,
> from="user101"<sip:user101 at 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 at 10.10.1.50:8737 SIP/2.0^M To: <sip:+43201 at proxy1
>
>
>
> proxy 2 (full debug):
> -------------------
> SIP Request:
> method: <ACK>
> uri: <sip:user201 at 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 at proxy1.ienum.labs.nic.at]
> DEBUG: to body [<sip:+43201 at 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 at 10.10.1.50:8737 SIP/2.0^M To: <sip:+43201 at proxy1
>
> _______________________________________________
> Users mailing list
> Users at openser.org
> http://openser.org/cgi-bin/mailman/listinfo/users
>
More information about the Users
mailing list