[OpenSER-Devel] [ openser-Bugs-1967114 ] dialog: tight matching failed for ACK
SourceForge.net
noreply at sourceforge.net
Wed Jul 16 12:26:23 CEST 2008
Bugs item #1967114, was opened at 2008-05-19 14:13
Message generated for change (Comment added) made by carstenbock
You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=743020&aid=1967114&group_id=139143
Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: modules
Group: ver 1.3.x
Status: Open
Resolution: None
Priority: 5
Private: No
Submitted By: J0kER (j0ker_)
Assigned to: Bogdan-Andrei Iancu (bogdan_iancu)
Summary: dialog: tight matching failed for ACK
Initial Comment:
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 at openser.org onreply_route[2] section
May 19 17:09:51 openser[41625]: 8, INVITE, 192.168.0.1, sip:900001 at 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 at 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 at openser.org loose_route section
May 19 17:09:51 openser[41621]: 5, ACK, 192.168.0.1, sip:900001 at openser.org route[3] section
May 19 17:09:51 openser[41621]: 5, ACK, 192.168.0.1, sip:900001 at 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 at openser.org current active dialogs: 1
and second:
May 19 17:09:55 openser[41624]: 8, INVITE, 192.168.0.1, sip:900001 at openser.org onreply_route[2] section
May 19 17:09:55 openser[41624]: 8, INVITE, 192.168.0.1, sip:900001 at openser.org status 200 OK
May 19 17:09:55 openser[41627]: 6, ACK, 192.168.0.1, sip:900001 at 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 at openser.org loose_route section
May 19 17:09:55 openser[41627]: 6, ACK, 192.168.0.1, sip:900001 at openser.org route[3] section
May 19 17:09:55 openser[41627]: 6, ACK, 192.168.0.1, sip:900001 at openser.org dialog not found
May 19 17:09:55 openser[41627]: 6, ACK, 192.168.0.1, sip:900001 at openser.org current active dialogs: 0
May 19 17:09:55 openser[41627]: 6, ACK, 192.168.0.1, sip:900001 at 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?
----------------------------------------------------------------------
Comment By: Carsten Bock (carstenbock)
Date: 2008-07-16 10:26
Message:
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);
----------------------------------------------------------------------
Comment By: Carsten Bock (carstenbock)
Date: 2008-07-16 10:18
Message:
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
----------------------------------------------------------------------
Comment By: J0kER (j0ker_)
Date: 2008-07-09 14:12
Message:
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,
-----
----------------------------------------------------------------------
Comment By: Henning Westerholt (henningw)
Date: 2008-07-02 11:48
Message:
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
----------------------------------------------------------------------
You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=743020&aid=1967114&group_id=139143
More information about the Devel
mailing list