Menu
▾
▴
#461 dialog: tight matching failed for ACK
module [dialog]
Hi ,
i've situation where dlg_onreply executed after dlg_onroute then i see warning 'tight matching failed for ACK'.
first situation, where all ok:
May 19 17:09:51 openser[41625]: 8, INVITE, 192.168.0.1, sip:900001@openser.org onreply_route[2] section
May 19 17:09:51 openser[41625]: 8, INVITE, 192.168.0.1, sip:900001@openser.org status 200 OK
May 19 17:09:51 openser[41625]: INFO:dialog:dlg_onreply: new_state = 3, old_state = 2
May 19 17:09:51 openser[41625]: INFO:dialog:dlg_onreply: ttag = 7D08BF40-1596
May 19 17:09:51 openser[41621]: 5, ACK, 192.168.0.1, sip:900001@openser.org start processing
May 19 17:09:51 openser[41621]: INFO:dialog:dlg_onroute: matching...............
May 19 17:09:51 openser[41621]: 5, ACK, 192.168.0.1, sip:900001@openser.org loose_route section
May 19 17:09:51 openser[41621]: 5, ACK, 192.168.0.1, sip:900001@openser.org route[3] section
May 19 17:09:51 openser[41621]: 5, ACK, 192.168.0.1, sip:900001@openser.org confirmed by a final reply and ACK received
May 19 17:09:51 openser[41621]: 5, ACK, 192.168.0.1, sip:900001@openser.org current active dialogs: 1
and second:
May 19 17:09:55 openser[41624]: 8, INVITE, 192.168.0.1, sip:900001@openser.org onreply_route[2] section
May 19 17:09:55 openser[41624]: 8, INVITE, 192.168.0.1, sip:900001@openser.org status 200 OK
May 19 17:09:55 openser[41627]: 6, ACK, 192.168.0.1, sip:900001@openser.org start processing
May 19 17:09:55 openser[41627]: INFO:dialog:dlg_onroute: matching...............
May 19 17:09:55 openser[41627]: INFO:dialog:dlg_onroute: tight matching failed for ACK with clid 'MWE0NjJhOTFkMWFmOTAxMzUxZTRkNjRiZmM2ZTRmYjU.' and tags '1f7ccf03' '7D08CF54-1A77' and direction 0
May 19 17:09:55 openser[41627]: 6, ACK, 192.168.0.1, sip:900001@openser.org loose_route section
May 19 17:09:55 openser[41627]: 6, ACK, 192.168.0.1, sip:900001@openser.org route[3] section
May 19 17:09:55 openser[41627]: 6, ACK, 192.168.0.1, sip:900001@openser.org dialog not found
May 19 17:09:55 openser[41627]: 6, ACK, 192.168.0.1, sip:900001@openser.org current active dialogs: 0
May 19 17:09:55 openser[41627]: 6, ACK, 192.168.0.1, sip:900001@openser.org route[1] section
May 19 17:09:55 openser[41632]: INFO:dialog:dlg_onreply: new_state = 5, old_state = 5
May 19 17:09:55 openser[41624]: INFO:dialog:dlg_onreply: new_state = 3, old_state = 2
May 19 17:09:55 openser[41624]: INFO:dialog:dlg_onreply: ttag = 7D08CF54-1A77
May 19 17:09:59 openser[41632]: INFO:dialog:dlg_onreply: new_state = 3, old_state = 3
bug?
Logged In: YES
user_id=337916
Originator: NO
Hi,
in the log pasted above the level of the tight matching message is "INFO", not "WARN" as in the trunk and 1.3 branch. Do you modified this statement? Do you've applied any other patches?
Cheers,
Henning
Logged In: YES
user_id=2091720
Originator: YES
yes, for more debug.
---------
--- dlg_handlers.c.orig 2008-05-15 19:24:31.000000000 +0400
+++ dlg_handlers.c 2008-05-18 18:07:14.000000000 +0400
@@ -280,6 +280,10 @@
return;
}
+ /* */
+ LM_INFO("new_state = %i, old_state = %i\n",new_state,old_state);
+ /* */
+
if (new_state==DLG_STATE_CONFIRMED_NA &&
old_state!=DLG_STATE_CONFIRMED_NA && old_state!=DLG_STATE_CONFIRMED ) {
LM_DBG("dialog %p confirmed\n",dlg);
@@ -302,6 +306,10 @@
LM_ERR("could not add further info to the dialog\n");
}
+ /* */
+ LM_INFO("ttag = %.*s\n", dlg->tag[DLG_CALLEE_LEG].len, dlg->tag[DLG_CALLEE_LEG].s);
+ /* */
+
/* set start time */
dlg->start_ts = (unsigned int)(time(0));
@@ -547,8 +555,11 @@
if (pre_match_parse( req, &callid, &ftag, &ttag)<0)
return;
+ /* */
+ LM_INFO("matching...............\n");
+
if (match_dialog( dlg, &callid, &ftag, &ttag, &dir )==0) {
- LM_WARN("tight matching failed for %.*s "
+ LM_INFO("tight matching failed for %.*s "
"with clid '%.*s' and tags '%.*s' '%.*s' "
"and direction %d\n",
req->first_line.u.request.method.len,
-----
Logged In: YES
user_id=1488991
Originator: NO
I can confirm this bug as well. I've seen it on our customer test platform. Through some more analysis and some extra debug output added, i guess i've found at least one reason for this behaviour:
It appears, that the h_id/h_entry parameters are not unique in this certain case. "lookup_dialog" delivers an uncorrect dialog based on the RR-Params which of course has a different callid, fromtag, totag.
I believe, you have the following settings set:
- Database enabled
- Matching is based DID only or with fallback to SIP elements
Do you have dialogs in the dialog table and does this error occur after a restart of the proxy?
I've found a simple point in the dialog module, where the h_entry is adjusted upon loading from the database but "next_id" get's the loaded h_entry value, not the "next" h_entry value.
I will attach patch for this tiny issue.
Carsten
Logged In: YES
user_id=1488991
Originator: NO
Since obviously cannot add a patch to this ticket, here it goes:
This patch is agaist 1.3 SVN.
Index: modules/dialog/dlg_db_handler.c
--- modules/dialog/dlg_db_handler.c (revision 4486)
+++ modules/dialog/dlg_db_handler.c (working copy)
@@ -313,7 +313,7 @@
next_id = d_table->entries[dlg->h_entry].next_id;
d_table->entries[dlg->h_entry].next_id =
- (next_id < dlg->h_id) ? dlg->h_id : next_id;
+ (next_id < dlg->h_id) ? (dlg->h_id+1) : next_id;
GET_STR_VALUE(to_tag, values, 6, 1, 1);
Logged In: NO
I tried with database enabled and without and of course with DID only.
How i see this situation, dlg_onreply and dlg_onroute registred in TM
callback database and right sequence is call dlg_onreply and then
dlg_onroute, but periodically wrong (ratio about 20:1), may be this
is a bug in TM module?
Logged In: YES
user_id=2091720
Originator: YES
opssss.... previous message is my.
Logged In: YES
user_id=1488991
Originator: NO
Well, i would say it is not likely a Bug in the TM module. The TM module processes simply both requests equally; so the problem in your case seems to be that the dlg_onreply for the "200 OK" is processed too slow and at the same time the "ACK" comes in, which triggers the dlg_onroute. I don't know how to fix this.
However, the loading of dialogs from should be fixed like described below; this eased my life a lot ;-) Probably i should report a dedicated Bug for this issue.
Carsten