RADIUS authentication failing (timed out) and dumping core

Gertjan

@opoplawski said in RADIUS authentication failing (timed out) and dumping core:

authentication for them. On one of our pfSense boxes, it fails to

You have more boxes with the same setup ?
That a gold mine : you can compare the working one with the failing one.
This is the starting point : the binaries are teh same at a bit level.
Only the local setting differ.

@opoplawski said in RADIUS authentication failing (timed out) and dumping core:

without debug symbol information

Its open source, so you can gave a look at the failing lines and see the test condition where it failed.
So you'll know what variable (example) was not set or out of range or not known but mandatory.
from there you work upwards.

stephenw10

@opoplawski said in RADIUS authentication failing (timed out) and dumping core:

Interestingly, the other offices are able to use the RADIUS server in the
problem office to authenticate. And the problem pfSense box is able to
authenticate using the RADIUS servers in the other offices.

Mmm, that is interesting. Same pfSense versions? Same architectures?

opoplawski

@Gertjan Yeah, I was hoping to spot some differences between the different machines, but I haven't been able to find any that seem relevant yet.

Looking at:
select(10,{ 9 },0x0,0x0,{ 5.000000 }) = 1 (0x1)
recvfrom(9,"^B\M-)\0\M-t\rv\M-]O~\M-$}\M-4~"...,4096,MSG_WAITALL,{ AF_INET
RADIUS:1812 },0x820d022fc) = 244 (0xf4)
recvfrom(9,0x37bbc7deab51,4096,MSG_WAITALL,0x820d02300,0x820d022fc) ERR#35
'Resource temporarily unavailable'
select(10,{ 9 },0x0,0x0,{ 4.708796 }) = 0 (0x0)

This seems to be the recvfrom() call:
https://github.com/LawnGnome/php-radius/blob/1.4.0b1/radlib.c#L503

What I don't understand from reading the code how we could possibly be calling recvfrom() twice in a row without any other system calls in between - or maybe there is something I just don't understand about the truss output.

I'd love to be able to step through the code via gdb, but I can't without debug symbols.

Konstanti

@opoplawski

Hi.
Truss shows only the contents of system calls and nothing else.
As far as I can see, the socket opens in non-blocking mode

fcntl(9,F_SETFL,O_RDWR|O_NONBLOCK) = 0 (0x0)

Therefore, the error for this mode is
35 EAGAIN Resource temporarily unavailable. This is a temporary condition and later calls to the same routine may complete normally.
it is quite real

The main question for me is why the client rejects the "good" first response from the server
For example ,
recvfrom(9,"^B\M-)\0\M-t\rv\M-]O~\M-$}\M-4~"...,4096,MSG_WAITALL,{ AF_INET
RADIUS:1812 },0x820d022fc) = 244 (0xf4)

RADIUS: 1812 - is this the real output of the truss utility ? or has the real ip address been replaced?

recvfrom(9,"^B\M-7\0\M-tL\M-6`\M^T\M^V\M^L"...,4096,MSG_WAITALL, { AF_INET 10.10.11.10:1812 } 0x820d022fc) = 244 (0xf4)

Are there any entries in the client's log?
Is there a way to intercept packet exchange using tcpdump?

if it is possible to run the dtrace utility, then you can see what happens during the connection

dtrace -n 'fbt::rad_send_request:return , fbt::rad_continue_send_request:return , fbt::rad_init_send_request:return , fbt::is_valid_response:return {printf("=>%d",arg1)}'

stephenw10

What pfSense version are you using here?

opoplawski

@stephenw10 pfSense 2.7.2-RELEASE (amd64)

opoplawski

@Konstanti RADIUS:1812 is a redaction of the IP address. dtrace looks like a bridge to far to get working on pfSense.

This is the only thing that ends up in the logs:

openvpn[94373]: /openvpn.auth-user.php: Error during RADIUS authentication : Operation timed out

stephenw10

Are you able to test this in Plus? Where dtrace is available.

opoplawski

@stephenw10 I get:

dtrace: invalid probe specifier fbt::rad_send_request:return , fbt::rad_continue_send_request:return , fbt::rad_init_send_request:return , fbt::is_valid_response:return {printf("=>%d",arg1)}: probe description fbt::rad_send_request:return does not match any probes

stephenw10

That's in 24.11? Looks like it's working but the query you're using in invalid. I won't pretend to be any sort of expert with dtrace though!

opoplawski

@stephenw10 24.03 - looks like I was stuck on previous stable for some reason. I'll try to update soon.

Seems to me like dtrace is for kernel stuff, not just C-library tracing, but I'm completely unfamiliar with dtrace.

stephenw10

Hmm, OK you're seeing the same error in radius from all three versions?

Konstanti

@opoplawski
DTrace is a comprehensive dynamic tracing framework ported from Solaris. DTrace provides a powerful infrastructure that permits administrators, developers, and service personnel to concisely answer arbitrary questions about the behavior of the operating system and user programs.

here is an example of working in user space, maybe you need to know the name of the process that calls the necessary functions

or

opoplawski

@Konstanti As I understand it, I would need probes for the php radius library in order to trace it. When I look at the output of dtrace -l to show the available probes I don't see anything relevant to what I want to trace. There are kernel functions, malloc stuff, syscalls (but I already have that with truss), etc.

It appears that php can be built with dtrace support, but it appears that it hasn't in pfSense Plus. But again what I really want to trace is php-pecl-radius

Konstanti

@opoplawski

Hi
You were right, I was wrong, dtrace does not work with all functions. Therefore, as a result, we see a probe error

P.S.
I think I've found a solution for the userland programs

we find the pid of the php-fpm process
ps -awx | grep php
342 - Ss 8:55.06 php-fpm: master process (/usr/local/lib/php-fpm.conf) (php-fpm)
23960 - I 3:31.30 php-fpm: pool nginx (php-fpm)
27761 - I 2:07.14 php-fpm: pool nginx (php-fpm)
31652 - I 3:16.94 php-fpm: pool nginx (php-fpm)
37038 - I 3:12.25 php-fpm: pool nginx (php-fpm)
46849 - I 0:55.34 php-fpm: pool nginx (php-fpm)
55575 - I 3:18.29 php-fpm: pool nginx (php-fpm)
94877 - I 2:03.82 php-fpm: pool nginx (php-fpm)

2 using dtrace
dtrace -qn 'pid342:radius.so::entry { @[probefunc] = count();}'

dtrace -l | grep pid

70870 pid342 70871 pid342 radius.so 70872 pid342 radius.so 70873 pid342 radius.so 70874 pid342 radius.so 70875 pid342 radius.so 70876 pid342 radius.so 70877 pid342 radius.so 70878 pid342 radius.so 70879 pid342 radius.so 70880 pid342 radius.so 70881 pid342 radius.so 70882 pid342 radius.so 70883 pid342 radius.so 70884 pid342 radius.so 70885 pid342 radius.so 70886 pid342 radius.so 70887 pid342 radius.so 70888 pid342 radius.so 70889 pid342 radius.so 70890 pid342 radius.so 70891 pid342 radius.so 70892 pid342 radius.so 70893 pid342 radius.so 70894 pid342 radius.so 70895 pid342 radius.so 70896 pid342 radius.so 70897 pid342 radius.so 70898 pid342 radius.so 70899 pid342 radius.so 70900 pid342 radius.so 70901 pid342 radius.so 70902 pid342 radius.so 70903 pid342 radius.so 70904 pid342 radius.so 70905 pid342 radius.so 70906 pid342 radius.so 70907 pid342 radius.so 70908 pid342 radius.so 70909 pid342 radius.so 70910 pid342 radius.so 70911 pid342 radius.so 70912 pid342 radius.so 70913 pid342 radius.so 70914 pid342 radius.so 70915 pid342 radius.so 70916 pid342 radius.so 70917 pid342 radius.so 70918 pid342 radius.so 70919 pid342 radius.so 70920 pid342 radius.so 70921 pid342 radius.so 70922 pid342 radius.so 70923 pid342 radius.so 70924 pid342 radius.so 70925 pid342 radius.so 70926 pid342 radius.so 70927 pid342 radius.so 70928 pid342 radius.so 70929 pid342 radius.so 70930 pid342 radius.so 70931 pid342 radius.so radius.so zif_radius_put_vendor_addr entry
rad_close entry
rad_create_request entry
rad_put_vendor_int entry
rad_demangle entry
zif_radius_get_vendor_attr entry
rad_strerror entry
zif_radius_send_request entry
zif_radius_get_tagged_attr_tag entry
zif_radius_demangle entry
zif_radius_request_authenticator entry
zif_radius_put_int entry
rad_salt_value entry
zif_radius_salt_encrypt_attr entry
zif_radius_strerror entry
zif_radius_config entry
zif_radius_cvt_int entry
rad_acct_open entry
zif_radius_cvt_string entry
zif_radius_server_secret entry
zif_radius_get_tagged_attr_data entry
rad_put_vendor_attr entry
rad_send_request entry
rad_put_vendor_addr entry
zif_radius_add_server entry
zif_radius_close entry
rad_get_vendor_attr entry
rad_init_send_request entry
zif_radius_auth_open entry
_radius_close entry
rad_continue_send_request entry
get_module entry
rad_put_int entry
rad_put_attr entry
rad_auth_open entry
rad_get_attr entry
rad_cvt_int entry
zif_radius_acct_open entry
rad_cvt_addr entry
rad_put_addr entry
rad_server_secret entry
zif_radius_put_attr entry
zif_radius_get_attr entry
zif_radius_cvt_addr entry
zif_radius_put_addr entry
zm_startup_radius entry
rad_config entry
zm_info_radius entry
zif_radius_demangle_mppe_key entry
zif_radius_create_request entry
rad_open entry
zif_radius_put_vendor_int entry
zif_radius_put_string entry
rad_cvt_string entry
rad_demangle_mppe_key entry
rad_put_string entry
rad_request_authenticator entry
zif_radius_put_vendor_string entry
zif_radius_put_vendor_attr entry
zm_shutdown_radius entry
rad_put_vendor_string entry
rad_add_server entry

for example ,

dtrace -n 'pid342:radius.so:rad_send_request:return {printf("=>%d",arg1)}'
dtrace: description 'pid342:radius.so:rad_send_request:return ' matched 1 probe