Hi, Using freeradius 3.0.25 on centos 7 I have a configuration with a "detail" module writing to a file with locking = yes I have a type = detail listener on that same file. Under some load, apparantly, very sporadically a packet seems to gets lost. Am I correct to say that with locking = yes , there should never be any packet lost due to the reader renaming the file while the writer is writing to it ? How would be a good approach to further troubleshoot this ? -- Regards, Thor
On Nov 19, 2021, at 11:59 AM, Thor Spruyt <thor.spruyt@telenet.be> wrote:
I have a configuration with a "detail" module writing to a file with locking = yes I have a type = detail listener on that same file.
Under some load, apparantly, very sporadically a packet seems to gets lost. Am I correct to say that with locking = yes , there should never be any packet lost due to the reader renaming the file while the writer is writing to it ?
Yes. The writing process is: lock the file write to it unlock The rename process is: try to lock it if not, wait a bit rename it unlock it
How would be a good approach to further troubleshoot this ?
It's pretty hard. If there's a lot of traffic, there would be a lot of debugging logs. And that's hard to deal with. Alan DeKok.
----- Original Message -----
From: "aland" <aland@deployingradius.com>
It's pretty hard. If there's a lot of traffic, there would be a lot of debugging logs. And that's hard to deal with.
I tried to recompile with the readline-devel rpm installed. ./configure --with-systemd --with-openssl --without-snmp --without-vmps --without-dhcp --with-rlm_perl --with-rlm_ldap --with-rlm_sql_mysql --without-rlm_krb5 --without-rlm_pam --without-rlm_python --without-rlm_rest --disable-openssl-version-check However, I now get the following error after running make: src/main/modules.c: In function ?load_byserver?: src/main/modules.c:1387:3: error: ?subcs? undeclared (first use in this function) 1387 | subcs = cf_section_sub_find_name2(cs, "cache", "load"); | ^~~~~ src/main/modules.c:1387:3: note: each undeclared identifier is reported only once for each function it appears in make: *** [scripts/boiler.mk:644: build/objs/src/main/modules.lo] Error 1 -- Thor
On Nov 24, 2021, at 5:21 AM, Thor Spruyt <thor.spruyt@telenet.be> wrote:
However, I now get the following error after running make:
src/main/modules.c: In function ?load_byserver?: src/main/modules.c:1387:3: error: ?subcs? undeclared (first use in this function) 1387 | subcs = cf_section_sub_find_name2(cs, "cache", "load"); | ^~~~~ src/main/modules.c:1387:3: note: each undeclared identifier is reported only once for each function it appears in make: *** [scripts/boiler.mk:644: build/objs/src/main/modules.lo] Error 1
Already fixed in commit b2860aecbb8 Alan DeKok.
----- Original Message -----
From: "aland" <aland@deployingradius.com> It's pretty hard. If there's a lot of traffic, there would be a lot of debugging logs. And that's hard to deal with.
I managed to capture around 1 minute of debug out put with -Xxx Wed Nov 24 16:32:13 2021 : Debug: Server was built with: Wed Nov 24 16:32:13 2021 : Debug: accounting : yes Wed Nov 24 16:32:13 2021 : Debug: authentication : yes Wed Nov 24 16:32:13 2021 : Debug: ascend-binary-attributes : yes Wed Nov 24 16:32:13 2021 : Debug: coa : yes Wed Nov 24 16:32:13 2021 : Debug: recv-coa-from-home-server : no Wed Nov 24 16:32:13 2021 : Debug: control-socket : yes Wed Nov 24 16:32:13 2021 : Debug: detail : yes Wed Nov 24 16:32:13 2021 : Debug: dhcp : yes Wed Nov 24 16:32:13 2021 : Debug: dynamic-clients : yes Wed Nov 24 16:32:13 2021 : Debug: osfc2 : no Wed Nov 24 16:32:13 2021 : Debug: proxy : yes Wed Nov 24 16:32:13 2021 : Debug: regex-pcre : yes Wed Nov 24 16:32:13 2021 : Debug: regex-posix : no Wed Nov 24 16:32:13 2021 : Debug: regex-posix-extended : no Wed Nov 24 16:32:13 2021 : Debug: session-management : yes Wed Nov 24 16:32:13 2021 : Debug: stats : yes Wed Nov 24 16:32:13 2021 : Debug: systemd : yes Wed Nov 24 16:32:13 2021 : Debug: tcp : yes Wed Nov 24 16:32:13 2021 : Debug: threads : yes Wed Nov 24 16:32:13 2021 : Debug: tls : yes Wed Nov 24 16:32:13 2021 : Debug: unlang : yes Wed Nov 24 16:32:13 2021 : Debug: vmps : no Wed Nov 24 16:32:13 2021 : Debug: developer : no Wed Nov 24 16:32:13 2021 : Debug: Server core libs: Wed Nov 24 16:32:13 2021 : Debug: freeradius-server : 3.0.25 Wed Nov 24 16:32:13 2021 : Debug: talloc : 2.1.* Wed Nov 24 16:32:13 2021 : Debug: ssl : 1.0.2k release Wed Nov 24 16:32:13 2021 : Debug: pcre : 8.32 2012-11-30 Wed Nov 24 16:32:13 2021 : Debug: Endianness: Wed Nov 24 16:32:13 2021 : Debug: little Wed Nov 24 16:32:13 2021 : Debug: Compilation flags: Wed Nov 24 16:32:13 2021 : Debug: cppflags : Wed Nov 24 16:32:13 2021 : Debug: cflags : -I. -Isrc -include src/freeradius-devel/autoconf.h -include src/freeradius-devel/build.h -include src/freeradius-devel/features.h -include src/fr eeradius-devel/radpaths.h -fno-strict-aliasing -Wno-date-time -g -O2 -Wall -std=c99 -D_GNU_SOURCE -D_REENTRANT -D_POSIX_PTHREAD_SEMANTICS -DOPENSSL_NO_KRB5 -DNDEBUG -DIS_MODULE=1 Wed Nov 24 16:32:13 2021 : Debug: ldflags : Wed Nov 24 16:32:13 2021 : Debug: libs : -lcrypto -lssl -ltalloc -lpcre -lnsl -lresolv -ldl -lpthread -lreadline Wed Nov 24 16:32:13 2021 : Debug: Wed Nov 24 16:32:13 2021 : Info: FreeRADIUS Version 3.0.25 Wed Nov 24 16:32:13 2021 : Info: Copyright (C) 1999-2021 The FreeRADIUS server project and contributors Wed Nov 24 16:32:13 2021 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Wed Nov 24 16:32:13 2021 : Info: PARTICULAR PURPOSE Wed Nov 24 16:32:13 2021 : Info: You may redistribute copies of FreeRADIUS under the terms of the Wed Nov 24 16:32:13 2021 : Info: GNU General Public License Wed Nov 24 16:32:13 2021 : Info: For more information about these matters, see the file named COPYRIGHT Wed Nov 24 16:32:13 2021 : Info: Starting - reading configuration files ... ... Wed Nov 24 16:32:13 2021 : Debug: Created signal pipe. Read end FD 5, write end FD 6 Wed Nov 24 16:32:13 2021 : Debug: radiusd: #### Opening IP addresses and Ports #### And then: Wed Nov 24 16:32:13 2021 : Debug: Loading proto_detail with path: /opt/radius/lib/proto_detail.so Wed Nov 24 16:32:13 2021 : Debug: Loading proto_detail failed: /opt/radius/lib/proto_detail.so: cannot open shared object file: No such file or directory - No such file or direc tory Wed Nov 24 16:32:13 2021 : Debug: Loading library using linker search path(s) Wed Nov 24 16:32:13 2021 : Debug: Defaults : /lib:/usr/lib Wed Nov 24 16:32:13 2021 : Debug: Failed with error: proto_detail.so: cannot open shared object file: No such file or directory Wed Nov 24 16:32:13 2021 : Debug: listen { Wed Nov 24 16:32:13 2021 : Debug: type = "detail" Wed Nov 24 16:32:13 2021 : Debug: listen { Wed Nov 24 16:32:13 2021 : Debug: filename = "/opt/radius/var/queue/queue_000/detail-*" Wed Nov 24 16:32:13 2021 : Debug: load_factor = 99 Wed Nov 24 16:32:13 2021 : Debug: poll_interval = 1 Wed Nov 24 16:32:13 2021 : Debug: retry_interval = 5 Wed Nov 24 16:32:13 2021 : Debug: one_shot = no Wed Nov 24 16:32:13 2021 : Debug: track = yes Wed Nov 24 16:32:13 2021 : Debug: } Wed Nov 24 16:32:13 2021 : Debug: } The same happens for: Wed Nov 24 16:32:13 2021 : Debug: Failed with error: proto_status.so: cannot open shared object file: No such file or directory Wed Nov 24 16:32:13 2021 : Debug: Failed with error: proto_auth.so: cannot open shared object file: No such file or directory Wed Nov 24 16:32:13 2021 : Debug: Failed with error: proto_acct.so: cannot open shared object file: No such file or directory Everything works as expect however, except for the occasional lost packet in the detail file. So I guess the above library loading errors can be ignored ? -- Thor
On Nov 24, 2021, at 11:20 AM, Thor Spruyt <thor.spruyt@telenet.be> wrote:
I managed to capture around 1 minute of debug out put with -Xxx The same happens for: Wed Nov 24 16:32:13 2021 : Debug: Failed with error: proto_status.so: cannot open shared object file: No such file or directory Wed Nov 24 16:32:13 2021 : Debug: Failed with error: proto_auth.so: cannot open shared object file: No such file or directory Wed Nov 24 16:32:13 2021 : Debug: Failed with error: proto_acct.so: cannot open shared object file: No such file or directory
Everything works as expect however, except for the occasional lost packet in the detail file. So I guess the above library loading errors can be ignored ?
Yes. Alan DeKok.
On Nov 24, 2021, at 5:53 PM, aland aland@deployingradius.com wrote:
Yes.
Ok. With strace I found out the following: Here the .work file is tried but doesn't exist: [pid 14198] open("/opt/radius/var/queue/queue_000/detail.work", O_RDWR <unfinished ...> [pid 14198] <... open resumed>) = -1 ENOENT (No such file or directory) Next a new file was detected, which is opened (not sure if it's locked): [pid 14198] openat(AT_FDCWD, "/opt/radius/var/queue/queue_000/detail-000", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY <unfinished ...> [pid 14198] <... openat resumed>) = 183 [pid 14198] getdents(183 <unfinished ...> [pid 14198] <... getdents resumed>, /* 3 entries */, 32768) = 96 [pid 14198] getdents(183 <unfinished ...> [pid 14198] <... getdents resumed>, /* 0 entries */, 32768) = 0 Here is the file is closed: [pid 14198] close(183 <unfinished ...> [pid 14198] <... close resumed>) = 0 [pid 14198] stat("/opt/radius/var/queue/queue_000/detail-000", <unfinished ...> [pid 14198] <... stat resumed>{st_mode=S_IFREG|0644, st_size=12294, ...}) = 0 And here the rename happens, but isn't the lock gone due to the close ? [pid 14198] rename("/opt/radius/var/queue/queue_000/detail-000", "/opt/radius/var/queue/queue_000/detail.work" <unfinished ...> [pid 14198] <... rename resumed>) = 0 Here it starts prossing the .work file: [pid 14198] open("/opt/radius/var/queue/queue_000/detail.work", O_RDWR <unfinished ...> [pid 14198] <... open resumed>) = 199 -- Thor
On Nov 24, 2021, at 12:40 PM, Thor Spruyt <thor.spruyt@telenet.be> wrote:
With strace I found out the following:
Here the .work file is tried but doesn't exist: [pid 14198] open("/opt/radius/var/queue/queue_000/detail.work", O_RDWR <unfinished ...> [pid 14198] <... open resumed>) = -1 ENOENT (No such file or directory)
That's fine.
Next a new file was detected, which is opened (not sure if it's locked):
You should see calls to fcntl() in order to lock the file. That's if you have "locking = true" in the detail file write.
[pid 14198] openat(AT_FDCWD, "/opt/radius/var/queue/queue_000/detail-000", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY <unfinished ...> [pid 14198] <... openat resumed>) = 183 [pid 14198] getdents(183 <unfinished ...> [pid 14198] <... getdents resumed>, /* 3 entries */, 32768) = 96 [pid 14198] getdents(183 <unfinished ...> [pid 14198] <... getdents resumed>, /* 0 entries */, 32768) = 0
It should be locked.
Here is the file is closed: [pid 14198] close(183 <unfinished ...> [pid 14198] <... close resumed>) = 0 [pid 14198] stat("/opt/radius/var/queue/queue_000/detail-000", <unfinished ...> [pid 14198] <... stat resumed>{st_mode=S_IFREG|0644, st_size=12294, ...}) = 0
And here the rename happens, but isn't the lock gone due to the close ? [pid 14198] rename("/opt/radius/var/queue/queue_000/detail-000", "/opt/radius/var/queue/queue_000/detail.work" <unfinished ...> [pid 14198] <... rename resumed>) = 0
Hmm... locks are gone on close. But the source file exfile.c implements an API which handles all of that. It doesn't call close() until all of the locks have been released. Alan DeKok.
----- On Nov 24, 2021, at 7:27 PM, aland aland@deployingradius.com wrote:
You should see calls to fcntl() in order to lock the file. That's if you have "locking = true" in the detail file write.
I only see calls to fnctl() for the .work file. Also, i have "locking = yes" , instead of "locking = true". Wed Nov 24 16:32:13 2021 : Debug: detail detail-000 { Wed Nov 24 16:32:13 2021 : Debug: filename = "/opt/radius/var/queue/queue_000/detail-000" Wed Nov 24 16:32:13 2021 : Debug: header = "%t" Wed Nov 24 16:32:13 2021 : Debug: permissions = 420 Wed Nov 24 16:32:13 2021 : Debug: locking = yes Wed Nov 24 16:32:13 2021 : Debug: escape_filenames = no Wed Nov 24 16:32:13 2021 : Debug: log_packet_header = no Wed Nov 24 16:32:13 2021 : Debug: } I also notice now, that the permissions doesn't seem to be taken from the config: detail detail-000 { filename = ${localstatedir}/queue/queue_000/detail-000 permissions = 0644 locking = yes } -- Thor
On Nov 24, 2021, at 1:41 PM, Thor Spruyt <thor.spruyt@telenet.be> wrote:
I only see calls to fnctl() for the .work file.
That's fine.
Also, i have "locking = yes" , instead of "locking = true".
That's also fine.
Wed Nov 24 16:32:13 2021 : Debug: detail detail-000 { Wed Nov 24 16:32:13 2021 : Debug: filename = "/opt/radius/var/queue/queue_000/detail-000" Wed Nov 24 16:32:13 2021 : Debug: header = "%t" Wed Nov 24 16:32:13 2021 : Debug: permissions = 420 Wed Nov 24 16:32:13 2021 : Debug: locking = yes Wed Nov 24 16:32:13 2021 : Debug: escape_filenames = no Wed Nov 24 16:32:13 2021 : Debug: log_packet_header = no Wed Nov 24 16:32:13 2021 : Debug: }
I also notice now, that the permissions doesn't seem to be taken from the config: detail detail-000 { filename = ${localstatedir}/queue/queue_000/detail-000 permissions = 0644 locking = yes }
0644 in octal is 420 decimal. So that's fine. $ printf "%d\n" 0644 420 Alan DeKok.
----- On Nov 24, 2021, at 7:45 PM, aland aland@deployingradius.com wrote:
That's fine. That's also fine. 0644 in octal is 420 decimal. So that's fine.
Ok ;-) When the server stop I get the following in radius.log: Wed Nov 24 16:32:10 2021 : Error: detail (/opt/radius/var/queue/queue_000/detail-000): Failed writing exit status to master: Bad file descriptor detail.c: /* * If we're supposed to exit then tell * the master thread we've exited. */ if (data->child_pipe[0] < 0) { packet = NULL; if (write(data->master_pipe[1], &packet, sizeof(packet)) < 0) { ERROR("detail (%s): Failed writing exit status to master: %s", data->name, fr_syserror(errno)); } return NULL; } Could that be a hint that there's an issue with the file descriptor management somewhere ? -- Thor
On Nov 25, 2021, at 5:06 AM, Thor Spruyt <thor.spruyt@telenet.be> wrote:
When the server stop I get the following in radius.log: Wed Nov 24 16:32:10 2021 : Error: detail (/opt/radius/var/queue/queue_000/detail-000): Failed writing exit status to master: Bad file descriptor ... Could that be a hint that there's an issue with the file descriptor management somewhere ?
It just means that the main thread closed the socket before the child thread exited. Alan DeKok.
participants (2)
-
Alan DeKok -
Thor Spruyt