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(a)openser.org
http://openser.org/cgi-bin/mailman/listinfo/users