On Thu, Jul 3, 2014 at 6:30 PM, Alan DeKok <aland@deployingradius.com> wrote:
Chris Knipe wrote:
Ok. So what is the value of the timeout? Is it configurable, and if not, can we get a option to configure the timeout value? I don't see anything in proxy.conf, so my apologies if I missed this.
Then you deleted it. The configuration items are in the default proxy.conf file, with documentation.
Also, the client may time out. You can't control that.
I looked at the -default- proxy.conf, that comes with FR3.0.3 which is what I am using. There isn't anything there in terms of request timeouts, just timeouts which controls when the proxy goes into a dead and/or zombie state - which is not what we are discussing here (again sorry if I missed it - a reference may thus be a good option). The proxy is never marked as dead, nor as a zombie, otherwise the natural thing for me WOULD HAVE been to look at and consider timeouts - that's why zombie / dead server configurations are there, isn't it? The client that sends the request, the FR server that does the proxing, as well as the FR server that receives the proxied request is under my control and neither one of them are timing out. Request: My Application -> FR Proxy -> FR Client, works fine FR Client -> FR Proxy -> My Application, and the FR Proxy then gets this weird behaviour when it decides on it's own when to, and when not to execute post_proxy.
All the requests also generally come back to me at the same time (as posted previously in the logs). Why is post_proxy then executed for one request, but not the other? They arrive back at FR at the same time, baring a few us...
That's what the debug log is for.
Please try and be helpful. I would appreciate it. I *DID* post the debug logs, both of a request that works, as well as a request that does not work. It is clear that for SOME reason, FR executes post_proxy in one request, and not in another. The attributes received in both packets are the same. This is NOT a configuration issue, nor a timeout issue IMHO. If I knew why FR is behaving like this, I would have fixed it. I am here however, to seek assistance to try and find out WHY this is happening.
If you read the two responses posted to the packets, you will also see that both responses gave the proxy hash error, yet the one is still passed through post_proxy, and the other is not..
That shouldn't happen. Please try the v3.0.x branch from git.
But it *IS* happening - that's the whole point of why I am here asking 'experts' as to WHY it is happening. I will however try the latest code and see whether the issue persist. I have since modified my rlm_perl application to use the authorize section to proxy requests to the parent radius server myself. In other words, I am no longer using FR's proxy implementation, but rather do it myself using perl. It's been running like that now for close to 12 hours, and I have not had *one* single Authentication error. There is *something* in FR's proxy code causing this issue, and it's related to high amounts of "concurrent" requests for the same username. I am sending the exact same packet via authorize, instead of the FR proxy modules, and it's working. It is thus NOT a timeout issue, it is NOT related to attributes received / not received, but rather, related to SOMETHING that the proxy modules does / does not do when a response is received. Again, as Phil said, it's more than likely too soon to call a bug, but it sure is leaning towards that and looking like it. Phil in terms of your questions, if I may rather just reply to everything in one email... Let's first get some background. The authentication and accounting is used for user authentication pertaining to NNTP server software - it is NOT NAS orientated. The NNTP Server is written by ourselves, and for local non proxied realms, authentication works without any problem whatsoever. Now, when a user connects, the user is entitled to x amount of concurrent threads to the NNTP server (typically 30). Generally, the client applications used by the customer connects all threads at the same time to the server. Hence, in a VERY short period of time (sub 10uS) 30 odd identical authentication requests are sent off to FR. The only attribute that is different in the authentication request, is the NAS-Port-Id, which we assign the value of the pid of the thread that the client has started on the NNTP servers. A typical authentication request will look like this: Fri Jul 4 00:30:25 2014 Packet-Type = Access-Request Called-Station-Id = 'a.b.8.42' Calling-Station-Id = 'c.d.96.24' NAS-IP-Address = a.b.240.36 NAS-Port-Type = Virtual NAS-Port-Id = '37713' Service-Type = Authenticate-Only User-Name = 'user@local.realm' User-Password = 'password' FR then accepts the packet, and almost exclusively relies on rlm_perl to authenticate the user. rlm_perl also configures various items such as rate limits and does session verification on a custom hardware load balancer. Typically, rlm_perl returns Auth-Type Accept (with reason), and a Configuration-Token attribute that gets sent back to the NNTP server. rlm_perl handles authentication generally under 0.010 seconds (measured from where FR passes the request to rlm_perl, until when rlm_perl executes the return back to FR). A typical response to an access-request looks like this (this is transmitted back to the NNTP software stack): Fri Jul 4 00:34:54 2014 Packet-Type = Access-Accept Configuration-Token = 'OK:37F46FA8-E538-497D-8B05-8D48FF2EC745:user@local.realm:T:1406584800:30:Welcome, user@local.realm (1/30)' This entire authentication process on local non-proxied realms works absolutely flawlessly. There is nothing wrong with this at all, it's fast, the custom code is highly optimized and we're extremely happy with this. When we now get to proxied requests, we have resellers that use our NNTP servers as well. Our NNTP servers sends the same authentication request to our FR server, the FR server sees that the realm needs to go to a proxy server, and then does the following: The packet passes through attr.filter, where we re-write a few attributes, as well as remove various unneeded attributes: my attr_filter.pre-proxy contains: DEFAULT Called-Station-Id == a.b.8.42, Calling-Station-Id =* ANY, NAS-IP-Address := a.b.8.44, NAS-Port-Id =* ANY, NAS-Port-Type == Virtual, Service-Type == Authenticate-Only, User-Name =* ANY, User-Password =* ANY, Proxy-State =* ANY FR then sends the proxy request off directly to the remote FR server (let's leave radsecproxy out of this for now. It was added as I thought the issue may have been caused by packet loss but the issue remains the same, whether the proxied request goes direct to the remote FR server or when it goes via radsecproxy). The auth request proxied generally looks like this: Thu Jul 3 00:02:31 2014 Packet-Type = Access-Request NAS-Port-Type = Virtual Service-Type = Authenticate-Only Calling-Station-Id = 'c.d.8.74' Called-Station-Id = 'a.b.8.42' User-Name = 'user@remote.realm' User-Password = 'aquiaP1eec' Realm = 'remote.realm' NAS-IP-Address = a.b.240.36 Message-Authenticator := 0x00 Proxy-State = 0x3438 All the authentication requests transmitted, DOES make it to the remote FR server, and the remote FR server is a STOCK STANDARD 2.1.12 install that comes with Ubuntu. All usernames & passwords in the users file. There's NOTHING changed, and NOTHING special. A stock standard install with just the parent FR server sending it requests configured in clients.conf. The server obviously responds virtually instantly with an access accept, as such: Thu Jul 3 02:16:50 2014 Packet-Type = Access-Accept Configuration-Token = 'OK:100:15:V:26843545600' Reply-Message = 'Welcome' Service-Type = Authenticate-Only Proxy-State = 0x3339 Now, THIS is where I think the issue is coming in. The accept packet from the remote server, will *always* be identical. The Configuration-Token returned will change over time, but for all initial 30 or 40 "simultaneous" authentication requests, the same Configuration-Token is returned. The main FR server thus sees 30 identical packets, to 30 different requests. What happens now, is that FR will take the 1st response it receives, and will push that through post_proxy. The remaining responses for some reason goes directly to post_auth, instead of what should be, post_proxy. The problem ONLY presents itself in requests sent to proxied servers, and it ONLY presents itself when there is a high amount of "concurrent" requests... Say, more than 10 within a very short period of time. This is essentially what I tried to show by posting the radsecproxy log, together with the log from my perl module. The Configuration-Token returned by the proxied server, and the Configuration-Token expected by our NNTP servers has different formats. The idea thus, is that the FR server *must* execute post_proxy for each and every response it receives from a proxied request, so that the sessions can be configured / confirmed on the load balancers, before the Configuration-Token is then re-written before being transmitted back to the application. Again, for intermediate requests, this works absolutely fine, and FR executes post_proxy as we all expect. This behaviour is *only* seen on a large amount of concurrent requests, and I suspect, is triggered when identical auth accepts are returned from the proxy server. This is somewhat irrelevant though, as my post_proxy rlm_perl module is useless seeing that post_proxy section is not executed in it's *entirety* when FR does this, not even post_proxy_log is called... -- Chris. -- Regards, Chris Knipe