[sr-dev] Dialog module: "CRITICAL bogus event 6 in state 2

Mon Jun 14 15:23:09 CEST 2010

Am 14.06.2010 15:01, schrieb Klaus Feichtinger:
> Hello Ovidiu,
>
> I've been testing reproducablility of the described error and found
> that it is reproducable in "standard" mode onyl. This should mean:
> forked application with child processes. As soon as I start the
> application even as non-forked or with only one child (children=1),
> the error was not reproducable until now. I've fastened reproduction
> with SIPp the call generating tool and in standard mode this error
> messages are visible after about 1-2 minutes (the call rate is one
> call per second with a pause of 1500ms between ACK and the following
> BYE).
>
> Under these test circumstances no subscription for presence or dialog
> state was active; it was tested on a "isolated" server where no other
> UAs were active; only SIPp and one other UA were active.
>
> I found that this problem is UserAgent-independent, too. Do you have
> an idea how to find out any more details about this problem?

This sounds like a race condition where process X received the 200 OK, 
forwards it and then gets suspended before before updating the dialog table.

Then, the ACK is received, forwarded and dialog state updated by process Y.

Maybe it can be solved by updating the dialog state before sending out 
the message.

regards
klaus

>
> regards,
>
> Klaus Feichtinger
>
>> Datum: Thu, 10 Jun 2010 22:24:52 +0200 Von: Klaus
>> Feichtinger<klaus.feichtinger at gmx.net> An: Ovidiu
>> Sas<osas at voipembedded.com> CC: sr-dev at lists.sip-router.org Betreff:
>> Re: [sr-dev] Dialog module: "CRITICAL bogus event 6 in state 2
>
>> Hello,
>>
>> according tcpdump-traces on the linux machine and log entries in
>> syslog (see below) the 200 OK passed the SIP Router (this means -
>> the call was accounted and afterwards the bogus event was noted):
>>
>> Jun 10 18:29:09 debian /usr/sbin/kamailio[20026]: INFO:<script>:
>> ---xlog: a call with sip:116202 at 10.16.10.99 is coming in Jun 10
>> 18:29:12 debian /usr/sbin/kamailio[20027]: NOTICE: acc [acc.c:275]:
>> ACC: transaction answered:
>> timestamp=1276208952;method=INVITE;from_tag=3120233282-36939680-1276187634579;to_tag=3338003860-56654088-1276187447718;call_id=741466613-36939680-1276187634579 at 10.16.10.152;code=200;reason=OK;src_user=116201;src_domain=10.16.10.99;dst_user=116202;dst_domain=10.16.10.90;src_ip=10.16.10.152
>>
>>
Jun 10 18:29:12 debian /usr/sbin/kamailio[20025]: CRITICAL: dialog
>> [dlg_hash.c:591]: bogus event 6 in state 2 for dlg 0xa7eb3ea8
>> [2285:1225504260] with clid
>> '741466613-36939680-1276187634579 at 10.16.10.152' and tags
>> '3120233282-36939680-1276187634579' ''
>>
>>
>> However, this is not the one and only event / state combination I
>> found in syslog. There is also an entry with event 6 in state 1
>> present:
>>
>> Jun 10 19:35:49 debian /usr/sbin/kamailio[20026]: INFO:<script>:
>> ---xlog: a call with sip:116002 at 10.16.10.99 is coming in Jun 10
>> 19:35:50 debian /usr/sbin/kamailio[20027]: NOTICE: acc [acc.c:275]:
>> ACC: transaction answered:
>> timestamp=1276212950;method=INVITE;from_tag=3805046041-37017968-1276191635112;to_tag=befc3f7326747dei0;call_id=789390150-37017968-1276191635112 at 10.16.10.152;code=200;reason=OK;src_user=116201;src_domain=10.16.10.99;dst_user=116002;dst_domain=10.16.10.205;src_ip=10.16.10.152
>>
>>
Jun 10 19:35:50 debian /usr/sbin/kamailio[20026]: CRITICAL: dialog
>> [dlg_hash.c:591]: bogus event 6 in state 1 for dlg 0xa7e979b8
>> [1648:1273002173] with clid
>> '789390150-37017968-1276191635112 at 10.16.10.152' and tags
>> '3805046041-37017968-1276191635112' ''
>>
>> But tomorrow I will test the setting - as recommended by you - to
>> reduce kamailio to a single worker and check if the problem will
>> keep repreduceable.
>>
>> Regards,
>>
>> Klaus Feichtinger
>>
>>> Bogus event 6 in state 2 means ACK received in early state. This
>>> is a little bit bizarre, because it seems that the dialog did
>>> not see the 200ok passing by. Try to use a single worker
>>> (children=1) and see if you can reproduce the problem. Also,
>>> check that the 200ok is really going through the proxy.
>>>
>>> Regards, Ovidiu Sas
>>>
>>> On Thu, Jun 10, 2010 at 6:44 AM, Klaus Feichtinger
>>> <klaus.feichtinger at gmx.net>  wrote:
>>>
>>>> Hello list,
>>>>
>>>> under special circumstances I have a problem with the DIALOG
>>>> module of
>> SIP-Router/Kamailio version 3.0.2. The dialog module is used in
>> combination with presence, presence_xml, pua, pua_usrloc and
>> pua_dialoginfo modules + db_mysql modules. The db_mode is set to
>> "write_through", because of redundancy requirements.
>>>>
>>>> From my point of view this problem has something to do with
>>>> timing in
>> general. E.g. a so called "data call" has a duration of about 50 ms
>> only; INVITE....BYE). That problem occurs on this short calls only.
>> Because of the problems in the dialog state machine, NOTIFY
>> messages are incorrect. Even when the call is already finished, the
>> NOTIFY message includes the state "confirmed" and causes a wrong
>> status indication....
>>>>
>>>> The detailed error message can be seen here: "Jun  9 16:00:39
>>>> debian /usr/sbin/kamailio[14992]: CRITICAL: dialog
>> [dlg_hash.c:591]: bogus event 6 in state 2 for dlg [dialog-ID] with
>> clid [Call-ID] and tags '1299370188-28358304-1276092068837' ''"
>>>>
>>>>
>>>> I found in old mails of the developer list another error that
>>>> looked
>> nearly the same, but it differed in the event and state of the
>> dialog state machine (the thread can be found under the link
>> http://www.mail-archive.com/devel@lists.kamailio.org/msg03234.html).
>> That bug should - according the information that I've found in the
>> list - be solved. Therefore I will ask you: is the error as
>> displayed above another well known error / bug, which (maybe)
>> should already be solved? Is it a new bug?
>>>>
>>>> Thanks for any information.
>>>>
>>>> regards,
>>>>
>>>> Klaus Feichtinger
>>>>
>>>> _______________________________________________ sr-dev mailing
>>>> list sr-dev at lists.sip-router.org
>>>> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
>>>>
>>>>
>>>
>>
>>
>> _______________________________________________ sr-dev mailing
>> list sr-dev at lists.sip-router.org
>> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
>