"Module ... became unblocked" after FR30 upgrade
Hi, I'm getting lots of this since upgrading from 2.2.9 to 3.0.11:
Tue Jun 21 15:21:11 2016 : WARNING: (16279306) WARNING: Module rlm_detail became unblocked for request 16279306 Tue Jun 21 15:21:11 2016 : WARNING: (16279309) WARNING: Module rlm_detail became unblocked for request 16279309 Tue Jun 21 15:21:12 2016 : WARNING: (16279322) WARNING: Module rlm_preprocess became unblocked for request 16279322 Tue Jun 21 15:21:13 2016 : WARNING: (16279341) WARNING: Module rlm_preprocess became unblocked for request 16279341 Tue Jun 21 15:21:14 2016 : WARNING: (16279362) WARNING: Module rlm_detail became unblocked for request 16279362 Tue Jun 21 15:21:20 2016 : WARNING: (16279468) WARNING: Module rlm_preprocess became unblocked for request 16279468 Tue Jun 21 15:21:23 2016 : WARNING: (16279506) WARNING: Module rlm_preprocess became unblocked for request 16279506 Tue Jun 21 15:23:38 2016 : WARNING: (16281993) WARNING: Module rlm_preprocess became unblocked for request 16281993
The only reference I found was for rlm_sql, where the OP was told that his SQL server is too slow, which is comprehensible. I don't see how rlm_detail or rlm_preprocess could be too slow, though, especially since there were merely 10 requests/s at this time.
A.L.M.Buxey@lboro.ac.uk wrote on 2016-06-21 16:58:
I'm getting lots of this since upgrading from 2.2.9 to 3.0.11:
Ok, probably found the cause: A radius client (RADIUS proxy from one of the wholesale providers we use) sometimes sends two consecutive accounting requests with the same request id (and from the source ip/port), so FR ignores the second request as a duplicate and won't send an Accounting-Response. The log message then looks like this:
Error: Received conflicting packet from client xxxx_acct3 port 20001 - ID: 143 due to unfinished request. Giving up on old request. WARNING: (3134530) WARNING: Module rlm_preprocess became unblocked for request 3134530
Strangely, I don't get the "Module ... became unblocked" for _all_ of these false duplicates, but _every_ "became unblocked" log entry is preceded by "Error: Received conflicting packet...". Obviously, this is bad and wrong behaviour of the radius client, so I'll try to get them to fix this.
preprocess getting blocked? hmmm, using huntgroups or hints or using some random other thing in preprocess?
preprocess is only used for the huntgroups file, which has only about 45 entries, mostly matching on Client-IP-Address, so this really should not cause trouble. The warnings really looked alarming at first, and I'd really like to know what's happening there, even though they do not seem to do any trouble...
On Jun 22, 2016, at 5:57 AM, Jakob Hirsch <jh@plonk.de> wrote:
Ok, probably found the cause: A radius client (RADIUS proxy from one of the wholesale providers we use) sometimes sends two consecutive accounting requests with the same request id (and from the source ip/port),
Then it's broken.
so FR ignores the second request as a duplicate and won't send an Accounting-Response. The log message then looks like this:
Error: Received conflicting packet from client xxxx_acct3 port 20001 - ID: 143 due to unfinished request. Giving up on old request. WARNING: (3134530) WARNING: Module rlm_preprocess became unblocked for request 3134530
That message really should really describe the underlying problem, but that's not a trivial fix.
Strangely, I don't get the "Module ... became unblocked" for _all_ of these false duplicates, but _every_ "became unblocked" log entry is preceded by "Error: Received conflicting packet...".
That's the problem, thn.
Obviously, this is bad and wrong behaviour of the radius client, so I'll try to get them to fix this.
Yes. If they fix it, the problem will go away. Alan DeKok.
participants (3)
-
A.L.M.Buxey＠lboro.ac.uk -
Alan DeKok -
Jakob Hirsch