31 Aug
2009
31 Aug
'09
11:15 a.m.
when analyzing the weird problem, where request uri gets rewritten with
aor's contact even when there is no command in config file that would do
it, i noticed these lines in syslog:
Aug 31 16:41:50 /usr/sbin/kamailio[23139]: DBG:core:rewrite_uri: rewriting Request-URI
with 'sip:foo.bar@ip-address:5060;transport=UDP'
Aug 31 16:41:50 opensipg /usr/sbin/kamailio[23139]: DBG:registrar:lookup:
'foo.bar@ip-address' Not found in usrloc
Aug 31 16:41:50 opensipg /usr/sbin/kamailio[23139]: DBG:registrar:lookup:
'foo.bar@ip-address' Not found in usrloc
any one has any idea why lookup was called even when it is not in the
script?
this is getting very weird. looks like kamailio is executing statements
on its own.
-- juha
31 Aug
31 Aug
11:26 a.m.
Hi,
This is what the lookup() command does. Are you sure you don't use
this command at all in your cfg? If so, how do you know to which IP
address to send the calls for a certain extension?
Catalina
2009/8/31 Juha Heinanen <jh(a)tutpro.com>om>:
when analyzing the weird problem, where request uri
gets rewritten with
aor's contact even when there is no command in config file that would do
it, i noticed these lines in syslog:
Aug 31 16:41:50 /usr/sbin/kamailio[23139]: DBG:core:rewrite_uri: rewriting Request-URI
with 'sip:foo.bar@ip-address:5060;transport=UDP'
Aug 31 16:41:50 opensipg /usr/sbin/kamailio[23139]: DBG:registrar:lookup:
'foo.bar@ip-address' Not found in usrloc
Aug 31 16:41:50 opensipg /usr/sbin/kamailio[23139]: DBG:registrar:lookup:
'foo.bar@ip-address' Not found in usrloc
any one has any idea why lookup was called even when it is not in the
script?
this is getting very weird. looks like kamailio is executing statements
on its own.
-- juha
_______________________________________________
Kamailio (OpenSER) - Users mailing list
Users(a)lists.kamailio.org
http://lists.kamailio.org/cgi-bin/mailman/listinfo/users
http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
12:35 p.m.
Hello,
On 31.08.2009 18:26 Uhr, catalina oancea wrote:
--
Daniel-Constantin Mierla
* http://www.asipto.com/
Hi,
This is what the lookup() command does. Are you sure you don't use
this command at all in your cfg? If so, how do you know to which IP
address to send the calls for a certain extension?
Catalina
2009/8/31 Juha Heinanen <jh(a)tutpro.com>om>:
> when analyzing the weird problem, where request uri gets rewritten with
> aor's contact even when there is no command in config file that would do
> it, i noticed these lines in syslog:
>
> Aug 31 16:41:50 /usr/sbin/kamailio[23139]: DBG:core:rewrite_uri: rewriting
Request-URI with 'sip:foo.bar@ip-address:5060;transport=UDP'
> Aug 31 16:41:50 opensipg /usr/sbin/kamailio[23139]: DBG:registrar:lookup:
'foo.bar@ip-address' Not found in usrloc
> Aug 31 16:41:50 opensipg /usr/sbin/kamailio[23139]: DBG:registrar:lookup:
'foo.bar@ip-address' Not found in usrloc
>
> any one has any idea why lookup was called even when it is not in the
> script?
>
lookup(location) is called as I can see from log. AFAIK there is no
other module calling it internally. However, there is a rewrite_uri()
done before, since 'Not found in usrloc' message comes afterwards. That
can be from other module: rr, enum, etc.
Also, make sure the proxy uses the config you think it should.
I assume you talk about kamailio 1.5.x ... right?
Cheers,
Daniel
this is
getting very weird. looks like kamailio is executing statements
on its own.
-- juha
_______________________________________________
Kamailio (OpenSER) - Users mailing list
Users(a)lists.kamailio.org
http://lists.kamailio.org/cgi-bin/mailman/listinfo/users
http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
_______________________________________________
Kamailio (OpenSER) - Users mailing list
Users(a)lists.kamailio.org
http://lists.kamailio.org/cgi-bin/mailman/listinfo/users
http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
12:46 p.m.
Daniel-Constantin Mierla writes:
lookup(location) is called as I can see from log.
AFAIK there is no
other module calling it internally. However, there is a rewrite_uri()
done before, since 'Not found in usrloc' message comes afterwards. That
can be from other module: rr, enum, etc.
perhaps rewrite_uri() comes from lookup() itself and then two more
lookups are done that now result in failure.
Also, make sure the proxy uses the config you think it
should.
i'm looking the .cfg file itself.
I assume you talk about kamailio 1.5.x ... right?
yes. i'll add more log statements. unfortunately, i need to wait until
tomorrow for more tests.
anyway, syslog message about entering and leaving script blocks would be
useful.
on the other hand, i don't consider these very useful:
DBG:core:parse_headers: flags=ffffffffffffffff
because it does not even tell, which header it is actually parsing.
-- juha
12:51 p.m.
On 31.08.2009 19:46 Uhr, Juha Heinanen wrote:
I replied to your email on sr-dev with some hints where to add these log
messages.
Daniel-Constantin Mierla writes:
just to be sure, you said you don't have lookup() at all, right?
lookup(location) is called as I can see from log.
AFAIK there is no
other module calling it internally. However, there is a rewrite_uri()
done before, since 'Not found in usrloc' message comes afterwards. That
can be from other module: rr, enum, etc.
perhaps rewrite_uri() comes from lookup() itself and then two more
lookups are done that now result in failure.
Also, make
sure the proxy uses the config you think it should.
i'm looking the .cfg file itself.
I assume you talk about kamailio 1.5.x ... right?
yes. i'll add more log statements. unfortunately, i need to wait until
tomorrow for more tests.
anyway, syslog message about entering and leaving script blocks would be
useful.
on the other hand, i don't consider these very
useful:
DBG:core:parse_headers: flags=ffffffffffffffff
because it does not even tell, which header it is actually parsing.
In this case is "all headers". Most of dbg messages where added by
devs
to help during coding. Some need to be reviewed.
Cheers,
Daniel
--
Daniel-Constantin Mierla
* http://www.asipto.com/
12:59 p.m.
Daniel-Constantin Mierla writes:
just to be sure, you said you don't have lookup()
at all, right?
i have, but much later in processing of the script. the info message
about the r-uri host not being local, comes much before the lookup would
have been executed, it request-uri host would have been local.
somehow the config code is messed up, i.e., it is not executed in the
order as written. exactly the same config on another host does not have
this problem.
-- juha
1:05 p.m.
On 31.08.2009 19:59 Uhr, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
are the hosts with same os? i can't find a reason for such behavior,
unless objects are corrupted. try a make proper; make all; make install
(if you use sources).
Cheers,
Daniel
--
Daniel-Constantin Mierla
* http://www.asipto.com/
just to be sure, you said you don't have
lookup() at all, right?
i have, but much later in processing of the script. the info message
about the r-uri host not being local, comes much before the lookup would
have been executed, it request-uri host would have been local.
somehow the config code is messed up, i.e., it is not executed in the
order as written. exactly the same config on another host does not have
this problem.
1:09 p.m.
Daniel-Constantin Mierla writes:
are the hosts with same os? i can't find a reason
for such behavior,
unless objects are corrupted. try a make proper; make all; make install
(if you use sources).
both run debian, but i don't know if the non-working host is an amd 64 or
something non-intel. i'll find out. both run same code from the same
debian package.
-- juha
1 Sep
1 Sep
2:18 a.m.
i checked the host hw and it is a normal intel dual core processor, so
normal debian i386 package should be fine for it.
i also added more logging to config file like this:
...
xlog("L_INFO", "INFO: : Request URI when leaving Initial_Tasks:
<$ru>\n");
route(2);
and in front of route block 2:
route [2] {
xlog("L_INFO", "INFO: : Request URI when entering Other_Requests:
<$ru>\n");
...
and here is what comes to syslog:
Sep 1 09:01:12 /usr/sbin/kamailio[25325]: INFO: : Request URI when leaving Initial_Tasks:
<sip:foo.bar@movial.com>
Sep 1 09:01:12 /usr/sbin/kamailio[25325]: INFO: : Request URI when entering
Other_Requests: <sip:foo.bar@contact-ip-address:5060;transport=UDP>
thus somehow lookup() was done in between leaving a route block and
entering the next.
there is only one route block where lookup() calls appears and i have
added a xlog call as first thing in it. i have also added another xlog
call just before lookup() call. neither is ever executed.
so how can it be possible that lookup gets executed without calling
lookup() function?
debugging at level 7 does not give any clues. any ideas on how to get
to the bottom of this?
-- juha
3:52 a.m.
Juha Heinanen writes:
...
xlog("L_INFO", "INFO: : Request URI when leaving Initial_Tasks:
<$ru>\n");
route(2);
i changed that to
$avp(REQUEST_URI_AVP) = $ru;
xlog("L_INFO", "INFO: EXTR: Request URI when leaving Initial_Tasks:
<$ru>\n");
route(2);
and in front of route block 2:
route [2] {
xlog("L_INFO", "INFO: EXTR: Request URI when entering Other_Requests:
<$ru>\n");
if (!is_avp_set("$avp(REQUEST_URI_AVP)")) {
$avp(REQUEST_URI_AVP) = $ru;
} else {
$ru = $avp(REQUEST_URI_AVP);
};
and the calls that kept on failing started to work!
something is seriously wrong, however, because there should not be any
need to save/restore request uri from being modified by lookup()
function that is not explicitly called by the script.
-- juha
6:55 a.m.
On 01.09.2009 10:52 Uhr, Juha Heinanen wrote:
Juha Heinanen writes:
this is really strange if you say that the other machine works ok with
same binaries and config. Maybe some objects got corrupted in a way or
another. Would it be possible to get sources and compile/install on
faulty machine?
Cheers,
Daniel
--
Daniel-Constantin Mierla
* http://www.asipto.com/
...
xlog("L_INFO", "INFO: : Request URI when leaving Initial_Tasks:
<$ru>\n");
route(2);
i changed that to
$avp(REQUEST_URI_AVP) = $ru;
xlog("L_INFO", "INFO: EXTR: Request URI when leaving Initial_Tasks:
<$ru>\n");
route(2);
and in front of route block 2:
route [2] {
xlog("L_INFO", "INFO: EXTR: Request URI when entering Other_Requests:
<$ru>\n");
if (!is_avp_set("$avp(REQUEST_URI_AVP)")) {
$avp(REQUEST_URI_AVP) = $ru;
} else {
$ru = $avp(REQUEST_URI_AVP);
};
and the calls that kept on failing started to work!
something is seriously wrong, however, because there should not be any
need to save/restore request uri from being modified by lookup()
function that is not explicitly called by the script.
10:15 a.m.
Daniel-Constantin Mierla writes:
this is really strange if you say that the other
machine works ok with
same binaries and config. Maybe some objects got corrupted in a way or
another. Would it be possible to get sources and compile/install on
faulty machine?
same binaries and config, but not necessarily same sip requests. this
lookup stuff happens only when request is routed by the proxy back to
itself. it has never happened when request comes from outside.
-- juha
3:58 p.m.
On 01.09.2009 17:15 Uhr, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
could you test to the other server with same kind of request to see if
you get some problem?
Maybe better, add an abort() in lookup() function and generate the core.
Then with gdb check the backtrace.
Cheers,
Daniel
--
Daniel-Constantin Mierla
* http://www.asipto.com/
this is really strange if you say that the other
machine works ok with
same binaries and config. Maybe some objects got corrupted in a way or
another. Would it be possible to get sources and compile/install on
faulty machine?
same binaries and config, but not necessarily same sip requests. this
lookup stuff happens only when request is routed by the proxy back to
itself. it has never happened when request comes from outside.
2 Sep
2 Sep
1:13 a.m.
Daniel-Constantin Mierla writes:
could you test to the other server with same kind of
request to see if
you get some problem?
i have tired but no luck.
Maybe better, add an abort() in lookup() function and
generate the core.
Then with gdb check the backtrace.
the problem is that lookup() is called during the first time the request
comes to the proxy and abort() in lookup() would crash the proxy too
early.
i'll try to generate the binary on that host itself in case there is
some differences.
-- juha
2:36 a.m.
On 02.09.2009 8:13 Uhr, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
you can put abort() in some if conditions - e.g., based on src ip, some
header/uri value.
Cheers,
Daniel
--
Daniel-Constantin Mierla
* http://www.asipto.com/
could you test to the other server with same kind
of request to see if
you get some problem?
i have tired but no luck.
Maybe better, add an abort() in lookup() function
and generate the core.
Then with gdb check the backtrace.
the problem is that lookup() is called during the first time the request
comes to the proxy and abort() in lookup() would crash the proxy too
early.
i'll try to generate the binary on that host itself in case there is
some differences.
3:46 a.m.
Daniel-Constantin Mierla writes:
you can put abort() in some if conditions - e.g.,
based on src ip, some
header/uri value.
daniel,
i tried that on my own system and got a core dump from normal lookup()
call. however, when i look at the core, it doesn't tell me much why
this normal lookup() was executed:
#0 0xb7f00424 in __kernel_vsyscall ()
#1 0xb7c07640 in raise () from /lib/i686/cmov/libc.so.6
#2 0xb7c09018 in abort () from /lib/i686/cmov/libc.so.6
#3 0xb78817ae in lookup (_m=0x821c848, _t=0xb3437370 "@sC?", _s=0x0)
at lookup.c:80
#4 0x080564e1 in do_action (a=0x81ce2a0, msg=0x821c848) at action.c:874
#5 0x08055518 in run_action_list (a=0x81c9878, msg=0x821c848) at action.c:145
#6 0x080578a0 in do_action (a=0x81bfda0, msg=0x821c848) at action.c:120
#7 0x08055518 in run_action_list (a=0x81befe8, msg=0x821c848) at action.c:145
#8 0x08057b0d in do_action (a=0x81bfe70, msg=0x821c848) at action.c:746
#9 0x08055518 in run_action_list (a=0x81bd468, msg=0x821c848) at action.c:145
#10 0x080578a0 in do_action (a=0x81abb80, msg=0x821c848) at action.c:120
#11 0x08055518 in run_action_list (a=0x81aa6d8, msg=0x821c848) at action.c:145
#12 0x08057b0d in do_action (a=0x81abc50, msg=0x821c848) at action.c:746
#13 0x08055518 in run_action_list (a=0x81a9ed8, msg=0x821c848) at action.c:145
#14 0x080578a0 in do_action (a=0x818ed40, msg=0x821c848) at action.c:120
#15 0x08055518 in run_action_list (a=0x818b8b0, msg=0x821c848) at action.c:145
#16 0x08057b0d in do_action (a=0x818ee10, msg=0x821c848) at action.c:746
#17 0x08055518 in run_action_list (a=0x81877e0, msg=0x821c848) at action.c:145
#18 0x080578a0 in do_action (a=0x8186b80, msg=0x821c848) at action.c:120
#19 0x08055518 in run_action_list (a=0x8185400, msg=0x821c848) at action.c:145
#20 0x080588d1 in run_top_route (a=0x8185400, msg=0x821c848) at action.c:120
#21 0x08086c0d in receive_msg (
buf=0x8156180 "INVITE sip:test@test.fi SIP/2.0\r\nRecord-Route:
<sip:192.98.101.10;lr;ftag=rxruz>\r\nVia: SIP/2.0/UDP
192.98.101.10;branch=z9hG4bK6c7e.6e29b5d.0\r\nVia: SIP/2.0/UDP
87.95.45.109:5074;received=87.95.45.1"...,
len=1178, rcv_info=0xbfc1a2d0) at receive.c:175
#22 0x080b60bf in udp_rcv_loop () at udp_server.c:449
#23 0x0806c38c in main (argc=15, argv=0xbfc1a454) at main.c:774
does it tell to you, i.e., does it make sense to make this exercise in
production system where the problem occurs?
-- juha
4:08 a.m.
On 02.09.2009 10:46 Uhr, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
from the trace seems that lot of nested IFs are executed on true branch
(action.c:746) and then lookup (action.c:874).
Just got a new idea -- print the line for each executed action -- in
action.c, in function do_action() add at beginning:
LM_ERR("***** executing action at line: %d\n", a->line);
That should give the trace of cfg lines which were executed.
Cheers,
Daniel
you can put abort() in some if conditions - e.g.,
based on src ip, some
header/uri value.
daniel,
i tried that on my own system and got a core dump from normal lookup()
call. however, when i look at the core, it doesn't tell me much why
this normal lookup() was executed:
#0 0xb7f00424 in __kernel_vsyscall ()
#1 0xb7c07640 in raise () from /lib/i686/cmov/libc.so.6
#2 0xb7c09018 in abort () from /lib/i686/cmov/libc.so.6
#3 0xb78817ae in lookup (_m=0x821c848, _t=0xb3437370 "@sC?", _s=0x0)
at lookup.c:80
#4 0x080564e1 in do_action (a=0x81ce2a0, msg=0x821c848) at action.c:874
#5 0x08055518 in run_action_list (a=0x81c9878, msg=0x821c848) at action.c:145
#6 0x080578a0 in do_action (a=0x81bfda0, msg=0x821c848) at action.c:120
#7 0x08055518 in run_action_list (a=0x81befe8, msg=0x821c848) at action.c:145
#8 0x08057b0d in do_action (a=0x81bfe70, msg=0x821c848) at action.c:746
#9 0x08055518 in run_action_list (a=0x81bd468, msg=0x821c848) at action.c:145
#10 0x080578a0 in do_action (a=0x81abb80, msg=0x821c848) at action.c:120
#11 0x08055518 in run_action_list (a=0x81aa6d8, msg=0x821c848) at action.c:145
#12 0x08057b0d in do_action (a=0x81abc50, msg=0x821c848) at action.c:746
#13 0x08055518 in run_action_list (a=0x81a9ed8, msg=0x821c848) at action.c:145
#14 0x080578a0 in do_action (a=0x818ed40, msg=0x821c848) at action.c:120
#15 0x08055518 in run_action_list (a=0x818b8b0, msg=0x821c848) at action.c:145
#16 0x08057b0d in do_action (a=0x818ee10, msg=0x821c848) at action.c:746
#17 0x08055518 in run_action_list (a=0x81877e0, msg=0x821c848) at action.c:145
#18 0x080578a0 in do_action (a=0x8186b80, msg=0x821c848) at action.c:120
#19 0x08055518 in run_action_list (a=0x8185400, msg=0x821c848) at action.c:145
#20 0x080588d1 in run_top_route (a=0x8185400, msg=0x821c848) at action.c:120
#21 0x08086c0d in receive_msg (
buf=0x8156180 "INVITE sip:test@test.fi SIP/2.0\r\nRecord-Route:
<sip:192.98.101.10;lr;ftag=rxruz>\r\nVia: SIP/2.0/UDP
192.98.101.10;branch=z9hG4bK6c7e.6e29b5d.0\r\nVia: SIP/2.0/UDP
87.95.45.109:5074;received=87.95.45.1"...,
len=1178, rcv_info=0xbfc1a2d0) at receive.c:175
#22 0x080b60bf in udp_rcv_loop () at udp_server.c:449
#23 0x0806c38c in main (argc=15, argv=0xbfc1a454) at main.c:774
does it tell to you, i.e., does it make sense to make this exercise in
production system where the problem occurs?
-- juha
--
Daniel-Constantin Mierla
* http://www.asipto.com/
1 Sep
1 Sep
10:18 a.m.
Daniel-Constantin Mierla writes:
Maybe some objects got corrupted in a way or
another. Would it be possible to get sources and compile/install on
faulty machine?
i have build more than one debian package and the lookup thing has
happened on all of them. so i don't think anything that the binaries
would be corrupted.
-- juha
5:19 a.m.
Juha Heinanen schrieb:
i checked the host hw and it is a normal intel dual
core processor, so
normal debian i386 package should be fine for it.
i also added more logging to config file like this:
...
xlog("L_INFO", "INFO: : Request URI when leaving Initial_Tasks:
<$ru>\n");
route(2);
and in front of route block 2:
route [2] {
xlog("L_INFO", "INFO: : Request URI when entering Other_Requests:
<$ru>\n");
...
and here is what comes to syslog:
Sep 1 09:01:12 /usr/sbin/kamailio[25325]: INFO: : Request URI when leaving
Initial_Tasks: <sip:foo.bar@movial.com>
Sep 1 09:01:12 /usr/sbin/kamailio[25325]: INFO: : Request URI when entering
Other_Requests: <sip:foo.bar@contact-ip-address:5060;transport=UDP>
thus somehow lookup() was done in between leaving a route block and
entering the next.
there is only one route block where lookup() calls appears and i have
added a xlog call as first thing in it. i have also added another xlog
call just before lookup() call. neither is ever executed.
so how can it be possible that lookup gets executed without calling
lookup() function?
debugging at level 7 does not give any clues. any ideas on how to get
to the bottom of this?
Maybe there is a problem when the cfg is parsed and the order of
processing is defined. So that lookup is executed at the wrong place.
In Asterisk I would use "dialplan show <context>" to debug this - is
there a similar tool (e.g. FIFO command) in Kamailio to dump the parsed
config?
regards
klaus
6:57 a.m.
On 01.09.2009 12:19 Uhr, Klaus Darilion wrote:
Juha Heinanen schrieb:
the cfg tree is printed at startup, but pretty cryptic.
There is a fifo command that prints the arguments, iirc -- so if the cfg
was given with -f you can see where is located, otherwise, is the
default one.
Cheers,
Daniel
--
Daniel-Constantin Mierla
* http://www.asipto.com/
i checked the host hw and it is a normal intel
dual core processor, so
normal debian i386 package should be fine for it.
i also added more logging to config file like this:
...
xlog("L_INFO", "INFO: : Request URI when leaving Initial_Tasks:
<$ru>\n");
route(2);
and in front of route block 2:
route [2] {
xlog("L_INFO", "INFO: : Request URI when entering Other_Requests:
<$ru>\n");
...
and here is what comes to syslog:
Sep 1 09:01:12 /usr/sbin/kamailio[25325]: INFO: : Request URI when
leaving Initial_Tasks: <sip:foo.bar@movial.com>
Sep 1 09:01:12 /usr/sbin/kamailio[25325]: INFO: : Request URI when
entering Other_Requests:
<sip:foo.bar@contact-ip-address:5060;transport=UDP>
thus somehow lookup() was done in between leaving a route block and
entering the next.
there is only one route block where lookup() calls appears and i have
added a xlog call as first thing in it. i have also added another xlog
call just before lookup() call. neither is ever executed.
so how can it be possible that lookup gets executed without calling
lookup() function?
debugging at level 7 does not give any clues. any ideas on how to get
to the bottom of this?
Maybe there is a problem when the cfg is parsed and the order of
processing is defined. So that lookup is executed at the wrong place.
In Asterisk I would use "dialplan show <context>" to debug this - is
there a similar tool (e.g. FIFO command) in Kamailio to dump the
parsed config?
5646
days inactive
5648
days old
19 comments
4 participants
participants (4)
-
catalina oancea -
Daniel-Constantin Mierla -
jh＠tutpro.com -
Klaus Darilion