[OpenSER-Devel] [ openser-Bugs-1967114 ] dialog: tight matching failed for ACK

SourceForge.net noreply at sourceforge.net
Fri Jul 18 15:06:57 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-18 13:06

Message:
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

----------------------------------------------------------------------

Comment By: J0kER (j0ker_)
Date: 2008-07-17 07:22

Message:
Logged In: YES 
user_id=2091720
Originator: YES

opssss.... previous message is my.

----------------------------------------------------------------------

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



More information about the Devel mailing list