Bugs item #1967114, was opened at 2008-05-19 14:13
Message generated for change (Comment added) made by nobody
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:[EMAIL PROTECTED]
onreply_route[2] section
May 19 17:09:51 openser[41625]: 8, INVITE, 192.168.0.1, sip:[EMAIL PROTECTED]
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:[EMAIL PROTECTED]
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:[EMAIL PROTECTED]
loose_route section
May 19 17:09:51 openser[41621]: 5, ACK, 192.168.0.1, sip:[EMAIL PROTECTED]
route[3] section
May 19 17:09:51 openser[41621]: 5, ACK, 192.168.0.1, sip:[EMAIL PROTECTED]
confirmed by a final reply and ACK received
May 19 17:09:51 openser[41621]: 5, ACK, 192.168.0.1, sip:[EMAIL PROTECTED]
current active dialogs: 1
and second:
May 19 17:09:55 openser[41624]: 8, INVITE, 192.168.0.1, sip:[EMAIL PROTECTED]
onreply_route[2] section
May 19 17:09:55 openser[41624]: 8, INVITE, 192.168.0.1, sip:[EMAIL PROTECTED]
status 200 OK
May 19 17:09:55 openser[41627]: 6, ACK, 192.168.0.1, sip:[EMAIL PROTECTED]
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:[EMAIL PROTECTED]
loose_route section
May 19 17:09:55 openser[41627]: 6, ACK, 192.168.0.1, sip:[EMAIL PROTECTED]
route[3] section
May 19 17:09:55 openser[41627]: 6, ACK, 192.168.0.1, sip:[EMAIL PROTECTED]
dialog not found
May 19 17:09:55 openser[41627]: 6, ACK, 192.168.0.1, sip:[EMAIL PROTECTED]
current active dialogs: 0
May 19 17:09:55 openser[41627]: 6, ACK, 192.168.0.1, sip:[EMAIL PROTECTED]
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: Nobody/Anonymous (nobody)
Date: 2008-07-17 07:18
Message:
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?
----------------------------------------------------------------------
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
_______________________________________________
Devel mailing list
Devel@lists.openser.org
http://lists.openser.org/cgi-bin/mailman/listinfo/devel
