22 Jun
2010
22 Jun
'10
6:27 p.m.
Hello,
I have two issues related to dialog module state keeping/logging that
caught my attention today:
1.) The module considers requests routed in early (but not yet
confirmed) dialogs to be bogus, as can be seen from a few lines of state
machine code in dlg_hash.c:
http://git.sip-router.org/cgi-bin/gitweb.cgi?p=sip-router;a=blob;f=modules_…
In the logs, it shows up something like this:
CRITICAL:dialog:log_next_state_dlg: bogus event 8 in state 2 for dlg
0x7f9f237ffff8 [2901:1286709577] with clid '<Call-ID>' and tags
'<caller
tag>' '<callee tag, always empty>'
I believe that such in-early-dialog requests should not trigger
bogus-event log messages as they look fine from a standard's point of view.
2.) Various race conditions may generate log messages such as following
when DID mode is enabled:
WARNING:dialog:dlg_onroute: unable to find dialog for <REQUEST TYPE>
with route param 'faf.f69e7b4' [4015:79161711]
Observed REQUEST TYPEs at our site were "BYE" when BYE requests were
transmitted by both caller and callee at roughly the same time due to
user behavior; and "PRACK" when a PRACK was received by the UAS after a
486 (Busy Here)/ACK pair of messages was already exchanged between the
UAS and the proxy. In both cases, the associated dialog had already been
destroyed when another request was received.
My suggestion is to lower the log level for this kind of message because
it can simply happen too often but doesn't affect proper dialog handling.
Feedback?
Cheers,
--Timo
22 Jun
22 Jun
6:47 p.m.
New subject: dialog module: in-early-dialog requests / race conditions
2010/6/22 Timo Reimann <timo.reimann(a)1und1.de>de>:
1.) The module considers requests routed in early (but
not yet
confirmed) dialogs to be bogus, as can be seen from a few lines of state
machine code in dlg_hash.c:
http://git.sip-router.org/cgi-bin/gitweb.cgi?p=sip-router;a=blob;f=modules_…
In the logs, it shows up something like this:
CRITICAL:dialog:log_next_state_dlg: bogus event 8 in state 2 for dlg
0x7f9f237ffff8 [2901:1286709577] with clid '<Call-ID>' and tags
'<caller
tag>' '<callee tag, always empty>'
I believe that such in-early-dialog requests should not trigger
bogus-event log messages as they look fine from a standard's point of view.
Do you mean that an in-dialog request (during early dialog state) is
considered a "bug" by dialog module? like a PRACK, INFO, OPTIONS,
MESSAGE or whatever valid in-dialog request in early dialog?
If so, then it's for sure a bug in the code.
--
Iñaki Baz Castillo
<ibc(a)aliax.net>
6:52 p.m.
New subject: dialog module: in-early-dialog requests / race conditions
On Tue, Jun 22, 2010 at 12:27 PM, Timo Reimann <timo.reimann(a)1und1.de> wrote:
Hello,
I have two issues related to dialog module state keeping/logging that
caught my attention today:
1.) The module considers requests routed in early (but not yet
confirmed) dialogs to be bogus, as can be seen from a few lines of state
machine code in dlg_hash.c:
http://git.sip-router.org/cgi-bin/gitweb.cgi?p=sip-router;a=blob;f=modules_…
In the logs, it shows up something like this:
CRITICAL:dialog:log_next_state_dlg: bogus event 8 in state 2 for dlg
0x7f9f237ffff8 [2901:1286709577] with clid '<Call-ID>' and tags
'<caller
tag>' '<callee tag, always empty>'
I believe that such in-early-dialog requests should not trigger
bogus-event log messages as they look fine from a standard's point of view.
If this means adding the DLG_STATE_EARLY to the switch, then it should be fine.
2.) Various race conditions may generate log messages
such as following
when DID mode is enabled:
WARNING:dialog:dlg_onroute: unable to find dialog for <REQUEST TYPE>
with route param 'faf.f69e7b4' [4015:79161711]
Observed REQUEST TYPEs at our site were "BYE" when BYE requests were
transmitted by both caller and callee at roughly the same time due to
user behavior; and "PRACK" when a PRACK was received by the UAS after a
486 (Busy Here)/ACK pair of messages was already exchanged between the
UAS and the proxy. In both cases, the associated dialog had already been
destroyed when another request was received.
My suggestion is to lower the log level for this kind of message because
it can simply happen too often but doesn't affect proper dialog handling.
The proper fix here would be to extend the lifetime of a dialog in
deleted state and absorb any late in-dialog requests.
If we just lower the log level, we don't know if it's a valid warning
log or a bogus one.
Feedback?
Cheers,
--Timo
_______________________________________________
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
sr-users(a)lists.sip-router.org
http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
8:10 p.m.
New subject: dialog module: in-early-dialog requests / race conditions
Hey Iñaki,
Iñaki Baz Castillo wrote:
2010/6/22 Timo Reimann <timo.reimann(a)1und1.de>de>:
Except for PRACK, all types of in-dialog requests received during early
state are considered "bugs" (see the link to dlg_hash.c I posted above).
1.) The module considers requests routed in early
(but not yet
confirmed) dialogs to be bogus, as can be seen from a few lines of state
machine code in dlg_hash.c:
http://git.sip-router.org/cgi-bin/gitweb.cgi?p=sip-router;a=blob;f=modules_…
In the logs, it shows up something like this:
CRITICAL:dialog:log_next_state_dlg: bogus event 8 in state 2 for dlg
0x7f9f237ffff8 [2901:1286709577] with clid '<Call-ID>' and tags
'<caller
tag>' '<callee tag, always empty>'
I believe that such in-early-dialog requests should not trigger
bogus-event log messages as they look fine from a standard's point of view.
Do you mean that an in-dialog request (during early dialog state) is
considered a "bug" by dialog module? like a PRACK, INFO, OPTIONS,
MESSAGE or whatever valid in-dialog request in early dialog? If so, then it's for sure a bug in the code.
Then I will fix it the other day.
Cheers,
--Timo
23 Jun
23 Jun
3:25 p.m.
New subject: dialog module: in-early-dialog requests / race conditions
Hi,
Ovidiu Sas wrote:
On Tue, Jun 22, 2010 at 12:27 PM, Timo Reimann
<timo.reimann(a)1und1.de> wrote:
I've been wondering how to achieve this.
AFAICS, the current implementation removes dialog entries right after
the moment the final request/response pair was seen. In order to prolong
a dying dialog's lifetime, I see two possibilities: Use some
time-triggered function that delays dialog deletion for a short period
of time; or, couple dialog deletion to the deletion of the final
transaction, i.e., the one were dialog state transitions to
DLG_STATE_DELETED. Personally, I prefer the latter approach since it
would quite elegantly re-use the transaction layer's timer.
Cheers,
--Timo
2.) Various race conditions may generate log
messages such as following
when DID mode is enabled:
WARNING:dialog:dlg_onroute: unable to find dialog for <REQUEST TYPE>
with route param 'faf.f69e7b4' [4015:79161711]
Observed REQUEST TYPEs at our site were "BYE" when BYE requests were
transmitted by both caller and callee at roughly the same time due to
user behavior; and "PRACK" when a PRACK was received by the UAS after a
486 (Busy Here)/ACK pair of messages was already exchanged between the
UAS and the proxy. In both cases, the associated dialog had already been
destroyed when another request was received.
My suggestion is to lower the log level for this kind of message because
it can simply happen too often but doesn't affect proper dialog handling.
The proper fix here would be to extend the lifetime of a dialog in
deleted state and absorb any late in-dialog requests.
If we just lower the log level, we don't know if it's a valid warning
log or a bogus one.
3:37 p.m.
New subject: dialog module: in-early-dialog requests / race conditions
On Wed, Jun 23, 2010 at 9:25 AM, Timo Reimann <timo.reimann(a)1und1.de> wrote:
Hi,
Ovidiu Sas wrote:
Yes, the latter approach seems to be the right one.
Regards,
Ovidiu Sas
On Tue, Jun 22, 2010 at 12:27 PM, Timo Reimann
<timo.reimann(a)1und1.de> wrote:
I've been wondering how to achieve this.
AFAICS, the current implementation removes dialog entries right after
the moment the final request/response pair was seen. In order to prolong
a dying dialog's lifetime, I see two possibilities: Use some
time-triggered function that delays dialog deletion for a short period
of time; or, couple dialog deletion to the deletion of the final
transaction, i.e., the one were dialog state transitions to
DLG_STATE_DELETED. Personally, I prefer the latter approach since it
would quite elegantly re-use the transaction layer's timer. 2.) Various race conditions may generate log
messages such as following
when DID mode is enabled:
WARNING:dialog:dlg_onroute: unable to find dialog for <REQUEST TYPE>
with route param 'faf.f69e7b4' [4015:79161711]
Observed REQUEST TYPEs at our site were "BYE" when BYE requests were
transmitted by both caller and callee at roughly the same time due to
user behavior; and "PRACK" when a PRACK was received by the UAS after a
486 (Busy Here)/ACK pair of messages was already exchanged between the
UAS and the proxy. In both cases, the associated dialog had already been
destroyed when another request was received.
My suggestion is to lower the log level for this kind of message because
it can simply happen too often but doesn't affect proper dialog handling.
The proper fix here would be to extend the lifetime of a dialog in
deleted state and absorb any late in-dialog requests.
If we just lower the log level, we don't know if it's a valid warning
log or a bogus one.
4:32 p.m.
New subject: dialog module: in-early-dialog requests / race conditions
2010/6/23 Timo Reimann <timo.reimann(a)1und1.de>de>:
AFAICS, the current implementation removes dialog
entries right after
the moment the final request/response pair was seen. In order to prolong
a dying dialog's lifetime, I see two possibilities: Use some
time-triggered function that delays dialog deletion for a short period
of time; or, couple dialog deletion to the deletion of the final
transaction, i.e., the one were dialog state transitions to
DLG_STATE_DELETED. Personally, I prefer the latter approach since it
would quite elegantly re-use the transaction layer's timer.
Me too. There is no a "timer for dialog" in RFC 3261 so reusing
transaction timers is the best approach IMHO.
--
Iñaki Baz Castillo
<ibc(a)aliax.net>
13 Jul
13 Jul
9:09 p.m.
New subject: dialog module: in-early-dialog requests / race conditions
Hey,
Iñaki Baz Castillo wrote:
2010/6/23 Timo Reimann <timo.reimann(a)1und1.de>de>:
I have tested and committed the proposed re-usage of the transaction
timer to sip-router, Kamailio 3.0 and 1.5.
Cheers,
--Timo
AFAICS, the current implementation removes dialog
entries right after
the moment the final request/response pair was seen. In order to prolong
a dying dialog's lifetime, I see two possibilities: Use some
time-triggered function that delays dialog deletion for a short period
of time; or, couple dialog deletion to the deletion of the final
transaction, i.e., the one were dialog state transitions to
DLG_STATE_DELETED. Personally, I prefer the latter approach since it
would quite elegantly re-use the transaction layer's timer.
Me too. There is no a "timer for dialog" in RFC 3261 so reusing
transaction timers is the best approach IMHO.
14 Jul
14 Jul
1:15 a.m.
New subject: dialog module: in-early-dialog requests / race conditions
2010/7/13 Timo Reimann <timo.reimann(a)1und1.de>de>:
Great, already compiled and will use it in production very soon :)
Thanks a lot.
--
Iñaki Baz Castillo
<ibc(a)aliax.net>
Me too. There
is no a "timer for dialog" in RFC 3261 so reusing
transaction timers is the best approach IMHO.
I have tested and committed the proposed re-usage of the transaction
timer to sip-router, Kamailio 3.0 and 1.5.
5063
days inactive
5084
days old
8 comments
3 participants
participants (3)
-
Iñaki Baz Castillo -
Ovidiu Sas -
Timo Reimann