Freeradius crashing due to load?
8zero2 operations
8zero2ops at gmail.com
Thu Apr 5 08:21:29 CEST 2018
Maybe there's something which blocks TCP connections.
- Checked all tcp connections, found them to be working well.
Ran it under GDB, not able to find much. maybe not able to find it(dont
know how to read it)
This is the panic command which ran
gdb -silent -x /usr/local/etc/raddb/panic.gdb /usr/local/sbin/radiusd 5678
2>&1 | tee /usr/local/var/log/radius/gdb-radiusd-5678.log
But I see a thread querying a php program from exec. but I think it returns
OK. Is this the problem causing part? Can you help me in finding the
problem? below are the part of GDB logs
Thread 4 (Thread 0x7f559b5fe700 (LWP 967)):
#0 0x00007f5624d71c4d in nanosleep () from /lib64/libc.so.6
No symbol table info available.
#1 0x00007f5624da6e94 in usleep () from /lib64/libc.so.6
No symbol table info available.
#2 0x000000000042bfce in rad_waitpid (pid=1006, status=0x7f559b5fbd2c) at
src/main/threads.c:1354
i = <value optimized out>
mytf = {pid = 1006, status = 0, exited = 0}
tf = 0x7f55f010d6b0
#3 0x00007f56267ebad0 in radius_readfrom_program (fd=55, pid=1006,
timeout=10, answer=0x7f559b5fbda0 "10485760000\nU\177", left=4084) at
src/main/exec.c:446
rcode = <value optimized out>
fds = {fds_bits = {0 <repeats 16 times>}}
when = {tv_sec = 10, tv_usec = 0}
wake = {tv_sec = 0, tv_usec = 0}
elapsed = <value optimized out>
done = <value optimized out>
status = 12
start = {tv_sec = 1522052474, tv_usec = 715900}
nonblock = true
#4 0x00007f56267ec1fb in radius_exec_program (ctx=0xc88330,
out=0x7f55f00414e0 "", outlen=2048, output_pairs=0x0, request=0xc88330,
cmd=0x7f55f010f750 " /var/www/html/internal_api/get_attributes.php
GUEST_DATA_LIMIT", input_pairs=0x7f55f01c9d30, exec_wait=true,
shell_escape=true, timeout=10) at src/main/exec.c:555
pid = 1006
from_child = 55
p = <value optimized out>
child_pid = <value optimized out>
comma = 0
status = <value optimized out>
ret = 0
len = <value optimized out>
answer = "10485760000\nU\177\000\000\306\236t
V\177\000\000\327\217\320$V\177\000\000\306\236t
V\177\000\000\000\000\000\000\000\000\000\000\001", '\000' <repeats 11
times>, "\002", '\000' <repeats 35 times>,
"p\303_\233U\177\000\000\000\000\000\000\000\000\000\000\302\236t
V\177\000\000@'\005%V\177", '\000' <repeats 18 times>"\334,
\303_\233U\177\000\000\370\303_\233U\177\000\000\006\000\000\000\000\000\000\000\030\304_\233U\177\000\000\000\004\000\000\000\000\000\000(A\321$V\177\000\000\030\000\000\000\060\000\000\000@\277_\233U\177\000\000\000\000\000\000U\177",
'\000' <repeats 14 times>,
"F\303_\233`\277_\233U\177\000\000\377\377\377\377\377\377\377\377\320\303_\233U\177\000\000\000\000\000\000\000\000\000\000`\300_\233U\177\000\000\377\003\000\000\000\000\000\000"...
#5 0x00007f56246b7edd in exec_xlat (instance=0xc0cbb0, request=0xc88330,
fmt=<value optimized out>, out=0x7f55f00414e0 "", outlen=2048) at
src/modules/rlm_exec/rlm_exec.c:182
result = <value optimized out>
inst = 0xc0cbb0
input_pairs = <value optimized out>
p = <value optimized out>
#6 0x00007f56267fbfe4 in xlat_aprint (ctx=0xc88330, request=0xc88330,
node=0xf6cd80, escape=0, escape_ctx=0x0, lvl=0) at src/main/xlat.c:2320
rcode = <value optimized out>
str = 0x7f55f00414e0 ""
child = 0x7f55f010f750 "
/var/www/html/internal_api/get_attributes.php GUEST_DATA_LIMIT"
p = <value optimized out>
#7 0x00007f56267fcb41 in xlat_process (out=0x7f559b5fcfa8,
request=0xc88330, head=<value optimized out>, escape=0, escape_ctx=0x0) at
src/main/xlat.c:2410
i = <value optimized out>
list = <value optimized out>
total = <value optimized out>
array = <value optimized out>
answer = <value optimized out>
node = <value optimized out>
#8 0x00007f56267fcba4 in xlat_expand_struct (out=0x7f559b5fd190, outlen=0,
request=<value optimized out>, node=<value optimized out>, escape=<value
optimized out>, escape_ctx=<value optimized out>) at src/main/xlat.c:2482
buff = 0x0
len = <value optimized out>
#9 0x00007f56267f3965 in tmpl_aexpand (ctx=0xc88330, out=0x7f559b5fd190,
request=0xc88330, vpt=0xbb6750, escape=0, escape_ctx=<value optimized out>)
at src/main/tmpl.c:1514
vp = <value optimized out>
slen = -1
#10 0x00007f56267eaf11 in cond_normalise_and_cmp (request=0xc88330,
c=0xbb6130, lhs_type=PW_TYPE_STRING, lhs_enumv=0x0, lhs=0x7f559b5fd210,
lhs_len=8) at src/main/evaluate.c:563
p = <value optimized out>
ret = <value optimized out>
data = {strvalue = 0x7f5626a0b564 "", octets = 0x7f5626a0b564 "",
integer = 648066404, ipaddr = {s_addr = 648066404}, date = 648066404,
filter = {140007991981412, 140007989787096, 34, 11672224}, ifid =
"d\265\240&V\177\000", ipv6addr = {__in6_u = {__u6_addr8 =
"d\265\240&V\177\000\000\330\071\177&V\177\000", __u6_addr16 = {46436,
9888, 32598, 0, 14808, 9855, 32598, 0}, __u6_addr32 = {648066404, 32598,
645872088, 32598}}}, ipv6prefix =
"d\265\240&V\177\000\000\330\071\177&V\177\000\000\"", byte = 100 'd',
ushort = 46436, ether = "d\265\240&V\177", sinteger = 648066404, integer64
= 140007991981412, ipv4prefix = "d\265\240&V\177", ptr = 0x7f5626a0b564}
map = 0xbb61d0
cast = <value optimized out>
cast_type = PW_TYPE_INVALID
rcode = <value optimized out>
rhs_type = PW_TYPE_INVALID
rhs_enumv = 0x0
rhs = 0x0
rhs_len = <value optimized out>
lhs_cast = {strvalue = 0x7f55f01cedd0 "95535243", octets =
0x7f55f01cedd0 "95535243", integer = 4028427728, ipaddr = {s_addr =
4028427728}, date = 4028427728, filter = {140007077375440, 140007989798589,
13139969, 13147840}, ifid = "\320\355\034\360U\177\000", ipv6addr =
{__in6_u = {__u6_addr8 =
"\320\355\034\360U\177\000\000\275f\177&V\177\000", __u6_addr16 = {60880,
61468, 32597, 0, 26301, 9855, 32598, 0}, __u6_addr32 = {4028427728, 32597,
645883581, 32598}}}, ipv6prefix =
"\320\355\034\360U\177\000\000\275f\177&V\177\000\000\001\200", byte = 208
'\320', ushort = 60880, ether = "\320\355\034\360U\177", sinteger =
-266539568, integer64 = 140007077375440, ipv4prefix =
"\320\355\034\360U\177", ptr = 0x7f55f01cedd0}
rhs_cast = {strvalue = 0x7f559b5fd260 "0\203\310", octets =
0x7f559b5fd260 "0\203\310", integer = 2606748256, ipaddr = {s_addr =
2606748256}, date = 2606748256, filter = {140005655695968, 140005655695976,
8391101543934948398, 8751168581018742895}, ifid = "`\322_\233U\177\000",
ipv6addr = {__in6_u = {__u6_addr8 =
"`\322_\233U\177\000\000h\322_\233U\177\000", __u6_addr16 = {53856, 39775,
32597, 0, 53864, 39775, 32597, 0}, __u6_addr32 = {2606748256, 32597,
2606748264, 32597}}}, ipv6prefix =
"`\322_\233U\177\000\000h\322_\233U\177\000\000.t", byte = 96 '`', ushort =
53856, ether = "`\322_\233U\177", sinteger = -1688219040, integer64 =
140005655695968, ipv4prefix = "`\322_\233U\177", ptr = 0x7f559b5fd260}
lhs_cast_buff = 0x0
rhs_cast_buff = 0x0
escape = <value optimized out>
#11 0x00007f56267eb4a5 in radius_evaluate_map (request=0xc88330,
modreturn=<value optimized out>, depth=<value optimized out>, c=0xbb6130)
at src/main/evaluate.c:700
ret = <value optimized out>
data = {strvalue = 0x7f55f01cedd0 "95535243", octets =
0x7f55f01cedd0 "95535243", integer = 4028427728, ipaddr = {s_addr =
4028427728}, date = 4028427728, filter = {140007077375440,
18446744073709551615, 18446744073709551615, 18446744073709551615}, ifid =
"\320\355\034\360U\177\000", ipv6addr = {__in6_u = {__u6_addr8 =
"\320\355\034\360U\177\000\000\377\377\377\377\377\377\377\377",
__u6_addr16 = {60880, 61468, 32597, 0, 65535, 65535, 65535, 65535},
__u6_addr32 = {4028427728, 32597, 4294967295, 4294967295}}}, ipv6prefix =
"\320\355\034\360U\177\000\000\377\377\377\377\377\377\377\377\377\377",
byte = 208 '\320', ushort = 60880, ether = "\320\355\034\360U\177",
sinteger = -266539568, integer64 = 140007077375440, ipv4prefix =
"\320\355\034\360U\177", ptr = 0x7f55f01cedd0}
rcode = 0
map = 0xbb61d0
#12 0x00007f56267eb7a1 in radius_evaluate_cond (request=0xc88330,
modreturn=2, depth=0, c=<value optimized out>) at src/main/evaluate.c:750
rcode = <value optimized out>
#13 0x000000000042514c in modcall_recurse (request=0xc88330,
component=MOD_ACCOUNTING, depth=2, entry=0x7f559b5fdaa0,
do_next_sibling=true) at src/main/modcall.c:479
condition = <value optimized out>
g = 0xf3a4c0
if_taken = <value optimized out>
was_if = <value optimized out>
c = <value optimized out>
priority = <value optimized out>
result = RLM_MODULE_OK
#14 0x00000000004263ea in modcall_child (request=<value optimized out>,
component=<value optimized out>, depth=<value optimized out>,
entry=0x7f559b5fda88, c=<value optimized out>, result=0x7f559b5fd78c,
do_next_sibling=true) at src/main/modcall.c:408
next = 0x7f559b5fdaa0
#15 0x00000000004251d5 in modcall_recurse (request=0xc88330,
component=MOD_ACCOUNTING, depth=1, entry=0x7f559b5fda88,
do_next_sibling=true) at src/main/modcall.c:785
g = 0xf3a300
if_taken = true
was_if = true
c = <value optimized out>
priority = <value optimized out>
result = RLM_MODULE_NOOP
#16 0x00000000004263ea in modcall_child (request=<value optimized out>,
component=<value optimized out>, depth=<value optimized out>,
entry=0x7f559b5fda70, c=<value optimized out>, result=0x7f559b5fda2c,
do_next_sibling=true) at src/main/modcall.c:408
next = 0x7f559b5fda88
#17 0x00000000004251d5 in modcall_recurse (request=0xc88330,
component=MOD_ACCOUNTING, depth=0, entry=0x7f559b5fda70,
do_next_sibling=true) at src/main/modcall.c:785
g = 0xf39a50
if_taken = false
was_if = false
c = <value optimized out>
priority = <value optimized out>
result = RLM_MODULE_UNKNOWN
#18 0x0000000000426383 in modcall (component=<value optimized out>,
c=<value optimized out>, request=<value optimized out>) at
src/main/modcall.c:1130
stack = {{result = RLM_MODULE_NOOP, priority = 0, unwind = 0, c =
0xf39a50}, {result = RLM_MODULE_NOOP, priority = 1, unwind = 0, c =
0xf3a300}, {result = RLM_MODULE_OK, priority = 2, unwind = 0, c =
0xf3a4c0}, {result = RLM_MODULE_NOOP, priority = 1, unwind = 0, c = 0x0},
{result = 13140653, priority = 0, unwind = 0, c = 0xc88e48}, {result = 47,
priority = 0, unwind = -1688216528, c = 0x0}, {result = 100663296, priority
= 0, unwind = 473, c = 0x932a70}, {result = 2606750552, priority = 32597,
unwind = -268168912, c = 0xdc86e0}, {result = 14452496, priority = 0,
unwind = 638003378, c = 0x7f559b5fdb90}, {result = 638009003, priority =
32598, unwind = 0, c = 0x0}, {result = RLM_MODULE_REJECT, priority = 0,
unwind = -1688216080, c = 0x7f559b5fdb90}, {result = 638009424, priority =
32598, unwind = 0, c = 0x0}, {result = RLM_MODULE_REJECT, priority = 0,
unwind = -1688213760, c = 0x0}, {result = RLM_MODULE_REJECT, priority = 0,
unwind = 0, c = 0x0}, {result = RLM_MODULE_REJECT, priority = 0, unwind =
0, c = 0x0}, {result = RLM_MODULE_REJECT, priority = 0, unwind =
-1688216320, c = 0x10}, {result = 2606750752, priority = 32597, unwind = 1,
c = 0x7f559b5fdae0}, {result = 32, priority = 0, unwind = 0, c = 0x0},
{result = 15079056, priority = 0, unwind = 20, c = 0xc88e40}, {result =
4381689, priority = 0, unwind = 27, c = 0x7f559b5fdd00}, {result =
4294967295, priority = 0, unwind = 13140080, c = 0xc882ab}, {result =
RLM_MODULE_REJECT, priority = 0, unwind = 13140080, c = 0x7f559b5fddb0},
{result = 2606751152, priority = 32597, unwind = 643553695, c = 0x1b},
{result = 27, priority = 0, unwind = -1688216144, c = 0x7f559b5fdd10},
{result = 29, priority = 0, unwind = 12588288, c = 0xc88170}, {result =
643536663, priority = 32598, unwind = 28, c = 0xc89b78}, {result =
RLM_MODULE_REJECT, priority = 0, unwind = 13140651, c = 0xc88070}, {result
= 643554284, priority = 32598, unwind = -1688216144, c = 0x48}, {result =
3978007402, priority = 1973628208, unwind = 0, c = 0xc01500}, {result =
2606751160, priority = 32597, unwind = 0, c = 0x0}, {result =
RLM_MODULE_REJECT, priority = 0, unwind = 0, c = 0xc885f0}, {result =
4322832, priority = 0, unwind = -1688216160, c = 0xc88330}}
#19 0x000000000041f9c5 in indexed_modcall (comp=MOD_ACCOUNTING, idx=0,
request=0xc88330) at src/main/modules.c:1028
rcode = <value optimized out>
list = 0xf39a50
server = 0xf2d5c0
#20 0x000000000040ea37 in rad_accounting (request=0xc88330) at
src/main/acct.c:93
vp = <value optimized out>
acct_type = 0
result = <value optimized out>
#21 0x0000000000433dda in request_running (request=0xc88330, action=<value
optimized out>) at src/main/process.c:1527
__FUNCTION__ = "request_running"
#22 0x000000000042cb4a in request_handler_thread (arg=0xdc86e0) at
src/main/threads.c:690
self = 0xdc86e0
#23 0x00007f5625297aa1 in start_thread () from /lib64/libpthread.so.0
No symbol table info available.
#24 0x00007f5624dadbcd in clone () from /lib64/libc.so.6
No symbol table info available.
On Mar 1, 2018, at 2:29 AM, 8zero2 operations <8zero2ops at gmail.com> wrote:
> >
> > I am attaching error logs of freeradius getting crashed randomly during
> day.
>
> ...
> > Thu Mar 1 11:45:24 2018 : Error: (1304488) Ignoring duplicate packet
> from
> > client XXXXXXXX port 44953 - ID: 35 due to unfinished request in
> component
> > authorize module
>
> Something is blocking the server. Fix that.
>
> It's usually the SQL module...
>
> > Thu Mar 1 11:45:34 2018 : ERROR: (1304618) ERROR: Timeout waiting
> > for child
>
> Yes. The child thread is being blocked.
>
> > I have database server modules enabled of sql and ldap. I have monitored
> > them and there is no considerable load on them when this crash happens.
>
> That doesn't matter. What matters is that the client library isn't
> returning to FreeRADIUS.
>
> Maybe there's something which blocks TCP connections.
>
> > How can I debug it and find which module is unresponsive while crash?
> Just
> > point a finger to a direction i will find the way.
>
> Run it under gdb. See doc/bugs for details.
>
> Alan DeKok.
>
>
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/
> list/users.html
More information about the Freeradius-Users
mailing list