18 Nov
2011
18 Nov
'11
5:28 a.m.
I have a 1.5.3 installation functioning as a registrar that is
exhibiting a very curious, if only infrequent set of behaviours.
The host is CentOS 5.x, with PostgreSQL 9.0 backing usrloc, and
db_mode = 1 (immediate write-through).
I have a registration handler in my initial request route that begins
with a log message:
...
else if(is_method("REGISTER")) {
xlog("L_INFO", "... Processing REGISTER from $si:$sp for
AOR $tu\n");
route(2);
exit;
}
I've got a registrant who consistently re-registers with an expiration
time of 120, so in theory they ought to be re-registering every two
minutes or so. Most of the time they do. But, occasionally, I'll see
a gap of 5-8 minutes go by, in which the above log message does not
appear, and their registration expires so that they can't receive calls.
That's not what's interesting. What's interesting is that I did a
packet capture on the proxy and caught one of these scenarios. Within
that ~8 minute window when the registration expired and calls were
failing, the UAC actually re-registered several times, on normal ~2
minute boundaries, AND the proxy successfully challenged the request
and sent a 200 OK indicating that the binding was stored!
I double-checked all the parameters to ensure that the 401s and 200
OKs corresponded to the right REGISTER flow, etc. - yes, it's all correct.
Is there any imaginable set of circumstances or a known bug that would
cause Kamailio to successfully authenticate and affirm a registration
request, while neither logging its receipt, nor, evidently, storing it
to the database? I can envision a number of database failure modes
that would account for the binding not actually being in the
'location' table, but that doesn't explain why the request wouldn't
even be logged. That's what has me baffled.
Thanks!
-- Alex
--
Alex Balashov - Principal
Evariste Systems LLC
260 Peachtree Street NW
Suite 2200
Atlanta, GA 30303
Tel: +1-678-954-0670
Fax: +1-404-961-1892
Web: http://www.evaristesys.com/
18 Nov
18 Nov
6:02 a.m.
Alex Balashov writes:
else if(is_method("REGISTER")) {
xlog("L_INFO", "... Processing REGISTER from $si:$sp for
AOR $tu\n");
route(2);
exit;
}
no matter what db you use, the above would print the syslog message IF
the piece of code is executed for register requests. check again the
logic in your config script. perhaps there is a way around the above
piece of code.
-- juha
6:07 a.m.
On 11/17/2011 11:02 PM, Juha Heinanen wrote:
That was my thought, as well. However, I don't see it. There's only
one path to route #2, and only route #2 contains any registration
processing. There is only the bare minimum boilerplate above that log
statement, e.g. message length, loop detection, in-dialog request
handling, etc. All authentication and higher-level processing takes
place afterward.
It's not logically possible. I checked, believe me.
--
Alex Balashov - Principal
Evariste Systems LLC
260 Peachtree Street NW
Suite 2200
Atlanta, GA 30303
Tel: +1-678-954-0670
Fax: +1-404-961-1892
Web: http://www.evaristesys.com/
else
if(is_method("REGISTER")) {
xlog("L_INFO", "... Processing REGISTER from $si:$sp for
AOR $tu\n");
route(2);
exit;
}
no matter what db you use, the above would print the syslog message IF
the piece of code is executed for register requests. check again the
logic in your config script. perhaps there is a way around the above
piece of code.
6:52 a.m.
On 11/17/2011 11:15 PM, Juha Heinanen wrote:
Alex Balashov writes:
That would imply a deterministic state of affairs. But this happens
very infrequently, no more than once a day for a few minutes, and only
to a very small percentage of the users.
There is nothing structurally different about the REGISTER requests
that take place within the problem interval vs. outside of it; I
scrutinised that in great detail.
--
Alex Balashov - Principal
Evariste Systems LLC
260 Peachtree Street NW
Suite 2200
Atlanta, GA 30303
Tel: +1-678-954-0670
Fax: +1-404-961-1892
Web: http://www.evaristesys.com/
It's not logically possible. I checked,
believe me.
ok, then start adding more xlog statements in order to figure out what
happens. 
12:47 p.m.
On 18.11.2011 05:07, Alex Balashov wrote:
On 11/17/2011 11:02 PM, Juha Heinanen wrote:
That was my thought, as well. However, I don't see it. There's only one
path to route #2, and only route #2 contains any registration
processing. There is only the bare minimum boilerplate above that log
statement, e.g. message length, loop detection, in-dialog request
handling, etc. All authentication and higher-level processing takes
place afterward.
It's not logically possible. I checked, believe me.
Then, the problem may be the logging:
- sychronous vs asynchronous syslogging?
- local or via UDP to a remote syslog server?
klaus
else
if(is_method("REGISTER")) {
xlog("L_INFO", "... Processing REGISTER from $si:$sp for
AOR $tu\n");
route(2);
exit;
}
no matter what db you use, the above would print the syslog message IF
the piece of code is executed for register requests. check again the
logic in your config script. perhaps there is a way around the above
piece of code.
12:53 p.m.
On 11/18/2011 05:47 AM, Klaus Darilion wrote:
Then, the problem may be the logging:
- sychronous vs asynchronous syslogging?
It's asynchronous.
- local or via UDP to a remote syslog server?
It's local.
--
Alex Balashov - Principal
Evariste Systems LLC
260 Peachtree Street NW
Suite 2200
Atlanta, GA 30303
Tel: +1-678-954-0670
Fax: +1-404-961-1892
Web: http://www.evaristesys.com/
1:24 p.m.
On Nov 18, 2011, at 5:47 AM, Klaus Darilion wrote:
On 18.11.2011 05:07, Alex Balashov wrote:
> On 11/17/2011 11:02 PM, Juha Heinanen wrote:
>
>>> else if(is_method("REGISTER")) {
>>> xlog("L_INFO", "... Processing REGISTER from $si:$sp for
>>> AOR $tu\n");
>>> route(2);
>>> exit;
>>> }
>>
What happens if you move the Register to the beginning of the if statement?
With best regards,
Fred
http://qxork.com
1:32 p.m.
On 11/18/2011 06:24 AM, Fred Posner wrote:
What happens if you move the Register to the beginning
of the if
statement?
While I have not empirically investigated this, the structure
literally looks like this:
if(is_method("OPTIONS")) {
# respond to OPTIONS pings
exit;
}
else if(is_method("INVITE")) {
# route the INVITE
exit;
}
else if(is_method("REGISTER")) {
xlog(...);
route(2);
}
else {
# 403 Forbidden
}
Also, if this were a logic problem, wouldn't it happen all the time?
This registrar has many thousands of users, out of which about half a
dozen have reported this problem, and for them, it only occurs for at
most a few minutes out of each day.
--
Alex Balashov - Principal
Evariste Systems LLC
260 Peachtree Street NW
Suite 2200
Atlanta, GA 30303
Tel: +1-678-954-0670
Fax: +1-404-961-1892
Web: http://www.evaristesys.com/
9:04 p.m.
It can look stupidity, but, I dislike this 'else if' structure.... so,
suppressing the 'else' from the 'else if' wouldn't change in nothing
the
logic, so have you tested this suppression?
Edson.
Em 18/11/2011 09:32, Alex Balashov escreveu:
On 11/18/2011 06:24 AM, Fred Posner wrote:
What happens if you move the Register to the
beginning of the if
statement?
While I have not empirically investigated this, the structure literally
looks like this:
if(is_method("OPTIONS")) {
# respond to OPTIONS pings
exit;
}
else if(is_method("INVITE")) {
# route the INVITE
exit;
}
else if(is_method("REGISTER")) {
xlog(...);
route(2);
}
else {
# 403 Forbidden
}
Also, if this were a logic problem, wouldn't it happen all the time?
This registrar has many thousands of users, out of which about half a
dozen have reported this problem, and for them, it only occurs for at
most a few minutes out of each day.
9:07 p.m.
On 11/18/2011 02:04 PM, Edson - Lists wrote:
It can look stupidity, but, I dislike this 'else
if' structure.... so,
suppressing the 'else' from the 'else if' wouldn't change in nothing
the logic, so have you tested this suppression?
It logically protects from situations in which, hypothetically,
is_method() could malfunction.
No, I haven't tested it. But again, this is obviously not a logic
problem. 99.99% of the registrations work fine, 99% of the time.
--
Alex Balashov - Principal
Evariste Systems LLC
260 Peachtree Street NW
Suite 2200
Atlanta, GA 30303
Tel: +1-678-954-0670
Fax: +1-404-961-1892
Web: http://www.evaristesys.com/
10:16 p.m.
On 11/17/2011 10:28 PM, Alex Balashov wrote:
Cheers.
--
Technical Support
http://www.telesip.net
I have a 1.5.3 installation functioning as a registrar
that is
exhibiting a very curious, if only infrequent set of behaviours.
The host is CentOS 5.x, with PostgreSQL 9.0 backing usrloc, and
db_mode = 1 (immediate write-through).
I have a registration handler in my initial request route that begins
with a log message:
...
else if(is_method("REGISTER")) {
xlog("L_INFO", "... Processing REGISTER from $si:$sp for
AOR $tu\n");
route(2);
exit;
}
I've got a registrant who consistently re-registers with an expiration
time of 120, so in theory they ought to be re-registering every two
minutes or so. Most of the time they do. But, occasionally, I'll see
a gap of 5-8 minutes go by, in which the above log message does not
appear, and their registration expires so that they can't receive calls.
That's not what's interesting. What's interesting is that I did a
packet capture on the proxy and caught one of these scenarios. Within
that ~8 minute window when the registration expired and calls were
failing, the UAC actually re-registered several times, on normal ~2
minute boundaries, AND the proxy successfully challenged the request
and sent a 200 OK indicating that the binding was stored!
I double-checked all the parameters to ensure that the 401s and 200
OKs corresponded to the right REGISTER flow, etc. - yes, it's all
correct.
Is there any imaginable set of circumstances or a known bug that would
cause Kamailio to successfully authenticate and affirm a registration
request, while neither logging its receipt, nor, evidently, storing it
to the database? I can envision a number of database failure modes
that would account for the binding not actually being in the
'location' table, but that doesn't explain why the request wouldn't
even be logged. That's what has me baffled.
My logic tells me:
1) If its not hitting your xlog in your register section then its not
registering to this server
2) If your packet capture is showing a successful registration and you
cannot see it registered in this server then its registering somewhere else.
3) Is it possible that your server is simply re-routing the packet to
another server before it hits your xlog statement and thus the client is
registering there? A full packet capture in and out of the server might
give you a hint, but if you have thousands of customers that might be
tough. On the other hand, if you have thousands of customers, I would
venture to guess that you have more than one server where users can
register and that might explain why the trace shows a successful
registration.
10:27 p.m.
On 11/18/2011 03:16 PM, Andres wrote:
My logic tells me:
1) If its not hitting your xlog in your register section then its not
registering to this server
The registrar is running inside an OpenVZ container, so the first
possibility I investigated was that someone had inadvertently cloned
the container on the same hardware node and that there was an IP
address conflict. However, this turned out not to be the case. I
also double-checked the MAC addresses on the registrations within the
successful interval vs. outside of it.
2) If your packet capture is showing a successful
registration and
you cannot see it registered in this server then its registering
somewhere else.
That stands to reason, but I cannot find any evidence apart to support
that viewpoint, nor anything about the packet capture (e.g. different
hardware or instance signatures) that would seem to corroborate that.
3) Is it possible that your server is simply
re-routing the packet
to another server before it hits your xlog statement and thus the
client is registering there?
I entertained that possibility, but can't find any indication of how
this would be possible, particularly in an arbitrary, small number of
cases for very brief periods.
A full packet capture in and out of the server might
give you a
hint, but if you have thousands of customers that might be tough.
I took a packet capture at the edge router of the network as well as
on the hardware node itself, in addition to the container. All of
them tell the same story.
On the other hand, if you have thousands of customers,
I would
venture to guess that you have more than one server where users can
register and that might explain why the trace shows a successful
registration.
There is just one registrar -- the one under discussion. It's the
main reason Kamailio is used here; it is the only OSS registrar I
know of that has enough throughput capacity to sustain thousands of
devices banging on it with relatively short re-registration intervals.
--
Alex Balashov - Principal
Evariste Systems LLC
260 Peachtree Street NW
Suite 2200
Atlanta, GA 30303
Tel: +1-678-954-0670
Fax: +1-404-961-1892
Web: http://www.evaristesys.com/
11:23 p.m.
There is just one registrar -- the one under
discussion. It's the
main reason Kamailio is used here; it is the only OSS registrar I
know of that has enough throughput capacity to sustain thousands of
devices banging on it with relatively short re-registration intervals.
Hi Alex,
At this point I would consider customizing your script to append an
extra header to your onreply_route logic using something like
append_hf("P-hint: bla...bla...bla\r\n"). My guess is that a packet
capture will show the header inserted under normal circumstances, but
will be absent during the mystery registration in the 8 minute
window. If that happens, it means your mystery registration is not
hitting this server or its not following your expected logic in the
config script.
Hope it helps.
--
Technical Support
http://www.telesip.net
11:24 p.m.
On 11/18/2011 04:23 PM, Andres wrote:
Yeah, I've already "tagged" the registration request in similar
manner. But this is a very good idea, thank you!
--
Alex Balashov - Principal
Evariste Systems LLC
260 Peachtree Street NW
Suite 2200
Atlanta, GA 30303
Tel: +1-678-954-0670
Fax: +1-404-961-1892
Web: http://www.evaristesys.com/
There is just one registrar -- the one under
discussion. It's the
main reason Kamailio is used here; it is the only OSS registrar I
know of that has enough throughput capacity to sustain thousands of
devices banging on it with relatively short re-registration intervals.
Hi Alex,
At this point I would consider customizing your script to append an
extra header to your onreply_route logic using something like
append_hf("P-hint: bla...bla...bla\r\n"). My guess is that a packet
capture will show the header inserted under normal circumstances, but
will be absent during the mystery registration in the 8 minute window.
If that happens, it means your mystery registration is not hitting
this server or its not following your expected logic in the config
script.
19 Nov
19 Nov
3:58 a.m.
I think I've figured out what's going on. Unsurprisingly, it isn't a
Kamailio problem--my proposed thesis seemed as improbable to me as to
all of you.
I had been going off the assumption that the absolute timestamps in
the packet captures off the edge router, from which I was basing my
analysis, were correct, or reasonably close to correct. It's an edge
router, after all. However, the person who took them (I do not have
direct access to it) just informed me that the router actually had
substantial system clock drift - about 20 minutes - at the time they
were taken. This invalidates the correlations I had made about the
proxy log <-> capture.
As you suggested, there is most likely, in fact, a reachability or
UA-related issue.
--
Alex Balashov - Principal
Evariste Systems LLC
260 Peachtree Street NW
Suite 2200
Atlanta, GA 30303
Tel: +1-678-954-0670
Fax: +1-404-961-1892
Web: http://www.evaristesys.com/
4755
days inactive
4756
days old
15 comments
6 participants
participants (6)
-
Alex Balashov -
Andres -
Edson - Lists -
Fred Posner -
Juha Heinanen -
Klaus Darilion