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
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@tutpro.com:
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@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
Hello,
On 31.08.2009 18:26 Uhr, catalina oancea wrote:
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@tutpro.com:
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@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@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
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
On 31.08.2009 19:46 Uhr, Juha Heinanen wrote:
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.
just to be sure, you said you don't have lookup() at all, right?
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.
I replied to your email on sr-dev with some hints where to add these log messages.
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 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
On 31.08.2009 19:59 Uhr, Juha Heinanen wrote:
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.
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 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
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
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
On 01.09.2009 10:52 Uhr, Juha Heinanen wrote:
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.
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 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
On 01.09.2009 17:15 Uhr, Juha Heinanen wrote:
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.
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 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
On 02.09.2009 8:13 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?
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.
you can put abort() in some if conditions - e.g., based on src ip, some header/uri value.
Cheers, Daniel
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
On 02.09.2009 10:46 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.
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:
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
#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 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
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
On 01.09.2009 12:19 Uhr, Klaus Darilion wrote:
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?
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
-
catalina oancea -
Daniel-Constantin Mierla -
jh＠tutpro.com -
Klaus Darilion