Open elchin9610 opened 2 months ago
Mon Apr 22 13:21:21 2024 : Error: Received conflicting packet from client dhcp port 67 - ID: 0 due to unfinished request in module
. Giving up on old request. Mon Apr 22 13:21:53 2024 : Error: Received conflicting packet from client dhcp port 54289 - ID: 0 due to unfinished request in module . Giving up on old request. Mon Apr 22 13:22:31 2024 : Error: Received conflicting packet from client dhcp port 67 - ID: 0 due to unfinished request in module . Giving up on old request.
This isn't a DHCP issue. The back-end is slow, and isn't responding to FreeRADIUS. But the client keeps sending DHCP packets, and eventually the server gets into a bad state, and crashes.
The simple fix is to ensure that the back-end is actually replying to the server.
A longer fix is to read the guidelines in the github issue template, and send over a full gdb back trace. We can then try to see what's going on.
But no amount of bug fixing in FreeRADIUS will make your SQL server faster. The first thing you should do is to find out why the SQL server is slow, and fix that.
Thanks for your reply. To reduce the load on SQL , I use cache memcached. But the result is the same. I'll try to use gdb back trace.
If memcache doesn't help, then the issue is elsewhere.
The default configuration has no issue replying to 10K packets/s. If your local configuration can't handle that, then something in your local configuration is breaking the server.
You will have to go through the configuration to see what has been changed from the defaults, and then find out which piece is taking a long time.
We can take a look at fixing the crash, but it won't have any meaningful change for your system. FreeRADIUS will still be blocked, and will be unable to respond to packets.
i.e. in practice, the difference between "down due to crash" and "down due to something blocking the server" is essentially zero.
Fix the underlying problem. Which is not the crash.
Hello, this problem arose because I used &DHCP-Your-IP-Address= "%{sql:select dhcp.get_available_ip('%{string:DHCP-Relay-Circuit-Id}', '%{DHCP-Client-Hardware-Address}') from dual}"
Tonight I'll change to dhcp_sqlippool
. Many thanks for the help!
Hello, I was able to solve the problem by changing skip_duplicate_checks = yes.
When duplicate packets arrive, the server crashes.
When I use radiusd -X > /tmp/test.log there are no failures. As I understand it, this is because the service operates in a single-threaded mode
Troubleshooting:
radiusd.conf
debug_level = 3
thread pool {
start_servers = 1
max_servers = 1
min_spare_servers = 1
max_spare_servers = 1
}
/mods-enabled/dhcp_sql
pool {
start = ${thread[pool].start_servers}
min = ${thread[pool].min_spare_servers}
max = ${thread[pool].max_servers}
spare = ${thread[pool].max_spare_servers}
uses = 0
retry_delay = 30
lifetime = 0
idle_timeout = 60
}
I connect one test host and block the database using iptablesiptables -A OUTPUT -d 10.132.25.20 -j REJECT
.
I wait 5 minutes and then allow the database connection again iptables -D OUTPUT -d 10.132.25.20 -j REJECT
Having received several duplicate packets, the server crashes.
radius.log
Tue Jun 4 12:04:19 2024 : Debug: (21) Received code 1027 Id 788269544 from 10.10.70.6:67 to 192.168.29.9:67 length 367
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Opcode = Client-Message
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Hardware-Type = Ethernet
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Hardware-Address-Length = 6
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Hop-Count = 1
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Transaction-Id = 788269544
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Number-of-Seconds = 1792
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Flags = Broadcast
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Client-IP-Address = 0.0.0.0
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Your-IP-Address = 0.0.0.0
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Server-IP-Address = 0.0.0.0
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Gateway-IP-Address = 10.10.70.6
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Client-Hardware-Address = 84:2a:fd:6e:20:a0
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Message-Type = DHCP-Request
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Client-Identifier = 0x01842afd6e20a0
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Requested-IP-Address = 1.1.1.1
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Hostname = "DESKTOP-C3J2DH0"
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Client-FQDN = 0x0000004445534b544f502d43334a32444830
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Vendor-Class-Identifier = 0x4d53465420352e30
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Parameter-Request-List = DHCP-Subnet-Mask
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Parameter-Request-List = DHCP-Router-Address
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Parameter-Request-List = DHCP-Domain-Name-Server
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Parameter-Request-List = DHCP-Domain-Name
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Parameter-Request-List = DHCP-Perform-Router-Discovery
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Parameter-Request-List = DHCP-Static-Routes
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Parameter-Request-List = DHCP-Vendor
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Parameter-Request-List = DHCP-NETBIOS-Name-Servers
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Parameter-Request-List = DHCP-NETBIOS-Node-Type
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Parameter-Request-List = DHCP-NETBIOS
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Parameter-Request-List = DHCP-Domain-Search
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Parameter-Request-List = DHCP-Classless-Static-Route
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Parameter-Request-List = 249
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Parameter-Request-List = 252
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Relay-Circuit-Id = 0x323038302d313532
Tue Jun 4 12:04:19 2024 : Debug: (21) Attr-26.54.3154 = 0x0002000000000583010000000000000063343a30393a62373a33373a66633a
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Network-Subnet = 10.10.70.6/32
Tue Jun 4 12:04:19 2024 : Debug: Trying sub-section dhcp DHCP-Request {...}
Tue Jun 4 12:04:19 2024 : Debug: (21) dhcp DHCP-Request {
Tue Jun 4 12:04:19 2024 : Debug: (21) update control {
Tue Jun 4 12:04:19 2024 : Debug: (21) &Pool-Name := "public"
Tue Jun 4 12:04:19 2024 : Debug: (21) } # update control = noop
Tue Jun 4 12:04:19 2024 : Debug: (21) policy dhcp_common {
Tue Jun 4 12:04:19 2024 : Debug: (21) update reply {
Tue Jun 4 12:04:19 2024 : Debug: (21) &DHCP-Domain-Name-Server = 2.2.2.2
Tue Jun 4 12:04:19 2024 : Debug: (21) &DHCP-Domain-Name-Server += 2.2.2.3
Tue Jun 4 12:04:19 2024 : Debug: (21) &DHCP-Subnet-Mask = 255.255.255.0
Tue Jun 4 12:04:19 2024 : Debug: (21) &DHCP-IP-Address-Lease-Time = 1000
Tue Jun 4 12:04:19 2024 : Debug: (21) &DHCP-DHCP-Server-Identifier = 192.168.29.9
Tue Jun 4 12:04:19 2024 : Debug: (21) DHCP-Server-Host-Name = "DHCP"
Tue Jun 4 12:04:19 2024 : Debug: (21) &DHCP-Domain-Name = "DHCP"
Tue Jun 4 12:04:19 2024 : Debug: (21) EXPAND %{DHCP-Gateway-IP-Address}
Tue Jun 4 12:04:19 2024 : Debug: (21) --> 10.10.70.6
Tue Jun 4 12:04:19 2024 : Debug: (21) &NAS-IP-Address = 10.10.70.6
Tue Jun 4 12:04:19 2024 : Debug: (21) } # update reply = noop
Tue Jun 4 12:04:19 2024 : Debug: (21) } # policy dhcp_common = noop
Tue Jun 4 12:04:19 2024 : Debug: (21) policy dhcp_sqlippool_request {
Tue Jun 4 12:04:19 2024 : Debug: (21) if (&DHCP-Requested-IP-Address) {
Tue Jun 4 12:04:19 2024 : Debug: (21) if (&DHCP-Requested-IP-Address) -> TRUE
Tue Jun 4 12:04:19 2024 : Debug: (21) if (&DHCP-Requested-IP-Address) {
Tue Jun 4 12:04:19 2024 : Debug: (21) update request {
Tue Jun 4 12:04:19 2024 : Debug: (21) &Acct-Status-Type := Start
Tue Jun 4 12:04:19 2024 : Debug: (21) } # update request = noop
Tue Jun 4 12:04:19 2024 : Debug: (21) modsingle[accounting]: calling dhcp_sqlippool (rlm_sqlippool)
Tue Jun 4 12:04:19 2024 : Debug: rlm_sql (dhcp_sql): Reserved connection (0)
Tue Jun 4 12:04:19 2024 : Debug: %{control:DHCP-SQL-Option-Identifier}
Tue Jun 4 12:04:19 2024 : Debug: Parsed xlat tree:
Tue Jun 4 12:04:19 2024 : Debug: attribute --> DHCP-SQL-Option-Identifier
Tue Jun 4 12:04:19 2024 : Debug: (21) dhcp_sqlippool: EXPAND %{control:DHCP-SQL-Option-Identifier}
Tue Jun 4 12:04:19 2024 : Debug: (21) dhcp_sqlippool: -->
Tue Jun 4 12:04:19 2024 : Debug: (21) dhcp_sqlippool: SQL-User-Name set to ''
Tue Jun 4 12:04:19 2024 : Debug: commit
Tue Jun 4 12:04:19 2024 : Debug: Parsed xlat tree:
Tue Jun 4 12:04:19 2024 : Debug: literal --> commit
Tue Jun 4 12:04:19 2024 : Debug: (21) dhcp_sqlippool: EXPAND commit
Tue Jun 4 12:04:19 2024 : Debug: (21) dhcp_sqlippool: --> commit
Tue Jun 4 12:04:19 2024 : Debug: (21) dhcp_sqlippool: Executing query: commit
Tue Jun 4 12:04:19 2024 : Debug: Waking up in 0.4 seconds.
Tue Jun 4 12:04:20 2024 : Debug: Waking up in 0.7 seconds.
Tue Jun 4 12:04:20 2024 : Debug: Waking up in 1.1 seconds.
Tue Jun 4 12:04:22 2024 : Debug: Waking up in 1.6 seconds.
Tue Jun 4 12:04:23 2024 : Debug: Waking up in 2.5 seconds.
Tue Jun 4 12:04:25 2024 : Debug: Threads: total/active/spare threads = 1/1/0
Tue Jun 4 12:04:25 2024 : Debug: Waking up in 0.3 seconds.
Tue Jun 4 12:04:25 2024 : Debug: Waking up in 0.4 seconds.
Tue Jun 4 12:04:26 2024 : Debug: Waking up in 0.1 seconds.
Tue Jun 4 12:04:26 2024 : Debug: Waking up in 0.5 seconds.
Tue Jun 4 12:04:26 2024 : Debug: Waking up in 1.1 seconds.
Tue Jun 4 12:04:27 2024 : Error: (22) Ignoring duplicate packet from client dhcp port 67 - ID: 3107335243 due to unfinished request in component
What type of defect/bug is this?
Crash or memory corruption (segv, abort, etc...)
How can the issue be reproduced?
I used the freeradius module DHCP for my clients. My service crashes several times a day.
OS=Debian10 freeradius=3.0.26 database=oracle clients=80k
At first, I received no error logs, so I thought it was either the database or the driver. Changing Oracle to Postgresql didn't the solve the problem.
Then decided to upgrade Debian10 to Debian12, also didn't the solve the problem.
When I use radiusd -X > /tmp/test.log there are no failures. As I understand it, this is because the service operates in a single-threaded mode
Finally, I rebuilt with the option: --with-experimental-modules --enable-developer, and received a log Error: ASSERT FAILED src/main/threads.c[679]: request->magic == REQUEST_MAGIC
My Config
cat radiusd.conf
thread pool { start_servers = 50 max_servers = 200 min_spare_servers = 5 max_spare_servers = 15 }
cat mods-enabled/sql
sql {
}
cat sites-enabled/dhcp
dhcp DHCP-Discover {
} }
dhcp DHCP-Request {
}
Log output from the FreeRADIUS daemon
Relevant log output from client utilities
No response
Backtrace from LLDB or GDB
No response