21 Nov
2013
21 Nov
'13
4:49 p.m.
Hello Everyone, Daniel,
This is directly related to the previous emails on this subject, sent by Guillaume. I am
adresing here the exact same issue, we work together.
The following piece of code is supposed to disconnect the previous call placed by a user:
We save call-id,totag (if we have 180,183),fromtag,cseq of the INVITE of the previous
dialog in memcache and we retrieve them for each call the user is placing.
if ($avp(saved_totag_of_previous_call)!=$null){
# the above check should be
equivalent with hastotag() on the other call .
if(dlg_get("$avp(saved_previous_call_callid)",
"$avp(saved_totag_of_previous_call)",
"$avp(saved_fromtag_of_previous_call)"))
{
# sending BYEs to
the previous dialog originated by this user
if
(dlg_bye("all"))
{
xlog("L_INFO","BYE sent to caller&callee");
} else {
xlog("L_INFO","could not send locally generated BYEs\n");
}
dlg_get("$ci","$tt","$ft");
# this BYE will be
caught in event_route[tm:local-request] where we do some accounting
} else {
# # dialog should be in early
state - eg: 183 or 180 has been received
xlog("dlg_get()
failed - because the dialog was not confirmed\n");
if
(t_cancel_callid("$avp(saved_previous_call_callid)",
"$avp(saved_previous_call_invite_cseq)", "22")) {
xlog("maxcall:transaction cancelled - i am in call with call-id: $ci \n");
# do stuff
here
} else {
xlog("maxcall:cannot send forced cancel - the previous dialog had a totag - early
state \n");
xlog("maxcall:i am in call with call-id: $ci \n");
}
# do stuff here
} else {
# dialog should be in
preceeding state - `100 Trying` was received (`100 Trying` does not have a totag)
if
(t_cancel_callid("$avp(saved_previous_call_callid)",
"$avp(saved_previous_call_invite_cseq)", "22")) {
xlog("maxcall:transaction cancelled . i am in call with call-id: $ci \n");
# do stuff here
} else {
xlog("maxcall:cannot send forced cancel - the previous dialog did not have a totag -
preceeding state\n");
xlog("maxcall:I am in call with call-id: $ci \n");
}
}
We see this in the logs, for two quick successive calls from the same UA (same user) so
we could reach the condition
when t_cancel_callid() is called , with $avp(saved_totag_of_previous_call) being null :
So this is when the the user makes the second call:
0(21429) INFO: <script>: cancelling call 3e20b1db528ce041 (entry= 2776, id= 2165 )
0(21429) DEBUG: tm [t_lookup.c:1742]: t_lookup_callid(): created comparable call_id header
field: >Call-ID: 3e20b1db528ce0$
<
0(21429) DEBUG: tm [t_lookup.c:1746]: t_lookup_callid(): created comparable cseq header
field: >CSeq: 20 INVITE<
0(21429) DEBUG: tm [t_lookup.c:1749]: t_lookup_callid(): just locked hash index 57175,
looking for transactions there:
0(21429) DEBUG: tm [t_lookup.c:1762]: t_lookup_callid(): we have a match:
callid=>>Call-ID: 3e20b1db528ce041
<< cseq=>>CSeq: 20<<
0(21429) DEBUG: tm [t_lookup.c:1767]: t_lookup_callid(): DEBUG: t_lookup_callid:
transaction found.
0(21429) DEBUG: tmx [tmx_mod.c:364]: t_cancel_callid(): Now calling cancel_uacs
0(21429) DEBUG: tm [t_cancel.c:329]: cancel_branch(): DEBUG: cancel_branch: sending
cancel...
0(21429) ERROR: <script>: maxcall:transaction cancelled . i am in call with
call-id: 2bf9efb7528ce04d # <- this is our custom logging
0(21429) ERROR: <script>: the other call (previous) had call-id:
3e20b1db528ce041
[...]
then:
0(21429) DEBUG: dialog [dlg_hash.c:600]: dlg_lookup(): ref dlg 0x7f4179801d08 with 1
-> 2
0(21429) DEBUG: dialog [dlg_hash.c:602]: dlg_lookup(): dialog id=9721 found on entry
2505
0(21429) DEBUG: dialog [dlg_var.c:49]: dlg_cfg_cb(): new dialog with no trasaction after
config execution
0(21429) DEBUG: dialog [dlg_hash.c:765]: dlg_unref(): unref dlg 0x7f4179801d08 with 1
-> 1
0(21429) DEBUG: dialog [dlg_hash.c:765]: dlg_unref(): unref dlg 0x7f4179801d08 with 1
-> 0
0(21429) DEBUG: dialog [dlg_hash.c:765]: dlg_unref(): ref <=0 for dialog
0x7f4179801d08
0(21429) DEBUG: dialog [dlg_hash.c:316]: destroy_dlg(): destroying dialog 0x7f4179801d08
(ref 0)
0(21429) DEBUG: dialog [dlg_hash.c:332]: destroy_dlg(): removed timer for dlg
0x7f4179801d08 [2505:9721] with clid '2bf9efb7528ce04d' and tags
'76bc4edf528ce04d' ''
What happens is that kamailio seems that it destroys the second dialog , instead of the
first one. This leads to other inconsitency :
DEBUG: dialog [dlg_hash.c:664]: internal_get_dlg(): no dialog
callid='2bf9efb7528ce04d' found # <- it cannot match the ACK for the second
call.
[...]
0(21429) WARNING: dialog [dlg_handlers.c:1127]: dlg_onroute(): unable to find dialog for
BYE with route param '9c9.9f52' [2505:9721] # <- it cannot match the BYE for
the second call
0(21429) DEBUG: dialog [dlg_hash.c:664]: internal_get_dlg(): no dialog
callid='2bf9efb7528ce04d' found
0(21429) DEBUG: dialog [dlg_hash.c:695]: get_dlg(): no dialog
callid='2bf9efb7528ce04d' found
0(21429) DEBUG: dialog [dlg_handlers.c:1173]: dlg_onroute(): Callid
'2bf9efb7528ce04d' not found
[...]
1(21430) INFO: <script>: event_route[local-request]: call-id=3e20b1db528ce041
from=15909901 to=+33630815276 : local_route (method= BYE) :: dlg flag: 1 1(21430) DEBUG:
pv [pv_trans.c:315]: tr_eval_string(): i=0 j=1
0(21429) WARNING: dialog [dlg_req_within.c:177]: bye_reply_cb(): inconsitent dlg timer
data on dlg 0x7f41797e7048 [2776:2165] with clid '3e20b1db528ce041' and tags
'522612bb528ce041' 'as1b2c7ace'
0(21429) DEBUG: dialog [dlg_hash.c:332]: destroy_dlg(): removed timer for dlg
0x7f41797e7048 [2776:2165] with clid '3e20b1db528ce041' and tags
'522612bb528ce041' 'as1b2c7ace'
It it also mixing the timeout of the first dialog with the one of the second. If we put a
default timeout of 15 seconds for all calls
and we cancel the first call,kamailio will generate a BYEs in
event_route[tm:local-request] after 15 seconds after the call other call was answered,
but with the call-id of the first call - it is mixing dialogs as we can see with kamctl.
We suspect that t_cancel_callid() is not destroying the proper dialog at the right time.
We use dlg_manage() on every INVITE.
It is the same behaviour with kamailio 4.0.2 and kamailio 4.0.3 .
Any hints / ideas about this problem ? Is the problem in the dialog module, or
t_cancel_callid() is doing something wrong ?
Thank you.
Regards,
Dragos
On Wednesday, November 20, 2013 10:57 PM, Daniel-Constantin Mierla
<miconda(a)gmail.com> wrote:
Hello,
are you dropping replies? I don't see the 'SIP/2.0 487 Request
Terminated' being sent to caller, it looks ok and has two Via
headers.
Cheers,
Daniel
On 11/20/13 4:06 PM, Guillaume Bour wrote:
On 20/11/2013 12:01, Daniel-Constantin Mierla wrote:
Hello,
On 11/20/13 11:50 AM, Guillaume Bour wrote:
Hi All
We wan't to prevent our users to make more than one call at
time, so we choose to disconnect the previous call.
When the previous call is established, we use dlg_bye(), and
its ok.
But when it is in early state, we use t_cancel_callid() to
cancel its INVITE transaction.
We face 2 issues:
1) we use local-request event route to account calls on
timeout. Sometimes this route is called for the cancelled call
(after default timeout of 1 hour)
what is in the local-request in this case? Is it a BYE?
2) t_cancel_callid() cancel previous call, but also make current dialog disappear:
call is still ongoing and we can answer and talk to each other, but the dialog does not
appear in 'kamctl stats dialog' and 'kamctl mi dlg_list' commands
Can you send the log with debug=3 in
kamailio.cfg? It will help to see what happens. Otherwise, if the call id is different for
current dialog, it should not happen. The ngrep output in this situation (for both first
and second invite) will help.
Cheers,
Daniel
Hi Daniel,
local-request is triggered by a BYE
I have attached sample log and trace
There is some kind of dialogs mixing. Here is the 1st call dialog
as reported by "kamctl mi dlg_list" before and after the 2d call is
answered:
# kamctl mi dlg_list
dialog:: hash=2790:3231
state:: 2
ref_count:: 1
timestart:: 0
timeout:: 0
callid:: GoXhk8GfkIEEqFyFNcySEjSOOpVKg4Uq
from_uri:: sip:15909901@staging.voip
from_tag:: swYh88AkicGbSHpK.D1z7uo3EX9Q-.AZ
caller_contact:: sip:37984520-gch2kindtioq8@10.0.1.10:5060;transport=udp
caller_cseq:: 24899
caller_route_set::
caller_bind_addr:: udp:10.0.1.10:5060
callee_bind_addr::
to_uri:: sip:+3360000011@staging.voip
to_tag::
callee_contact::
callee_cseq::
callee_route_set::
# kamctl mi dlg_list
dialog:: hash=2790:3231
state:: 3
ref_count:: 2
timestart:: 1384952191
timeout:: 20242152
callid:: GoXhk8GfkIEEqFyFNcySEjSOOpVKg4Uq
from_uri:: sip:15909901@staging.voip
from_tag:: swYh88AkicGbSHpK.D1z7uo3EX9Q-.AZ
caller_contact:: sip:37984520-gch2kindtioq8@10.0.1.20:5060;transport=udp
caller_cseq:: 24899
caller_route_set::
caller_bind_addr:: udp:10.0.1.10:5060
callee_bind_addr:: udp:10.0.1.10:5060
to_uri:: sip:+3360000011@staging.voip
to_tag:: as6c8b935a
callee_contact:: sip:+3360000022@10.0.1.11:5060
callee_cseq::
callee_route_set::
_______________________________________________
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
--
Daniel-Constantin Mierla - http://www.asipto.com http://twitter.com/#!/miconda -
http://www.linkedin.com/in/miconda Kamailio Advanced Trainings - Berlin, Nov 25-28 - more
details about Kamailio trainings at http://www.asipto.com
-
_______________________________________________
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
Is there a known limitation, or do we misuse t_cancel_callid()
?