Hello, I found the actual reason why this doesn't work any more; but it has nothing to do with rlm_sql_mysql - instead, the problem is that if virtual server proxying is used, the proxied-to virtual server's post-auth does not get executed; the SQL query happened to be in that post-auth. The query I posted earlier is the one which later gets generated by original virtual server; that one gets written just fine, hence the ->1 expansion, but it's a different table and its contents are not evaluated in my situation. (stupid me for not realising this) So, 2.2.0 wrote two INSERTs, one from the "staff" virtual server (the one I need) and a second one by the "AAI" virtual server. 2.x.x now only writes the "AAI" one, completely ignoring virtual server "staff"'s post-auth section. In -X mode this looks like the following *** 2.x.x *** rad_recv: Access-Request packet from host 158.64.1.65 port 41833, id=175, length=62 User-Name = "swinter" User-Password = "********" NAS-Identifier = "AAI-Staff-IdP" server AAI { ... ++- if (NAS-Identifier == "AAI-Staff-IdP" ) returns ok ++ ... skipping else for request 0: Preceding "if" was taken } # server AAI WARNING: Empty pre-proxy section. Using default return values.
Sending proxied request internally to virtual server. server staff { ... Found Auth-Type = PAP # Executing group from file /usr/local/freeradius/config/raddb/sites-enabled/staff +- entering group PAP {...} [pap] login attempt with password "**********" [pap] Using NT encryption. [pap] expand: %{User-Password} -> *********** [pap] NT-Hash of ********* = ############################## [pap] expand: %{mschap:NT-Hash %{User-Password}} -> ########################## [pap] User authenticated successfully ++[pap] returns ok } # server staff Going to the next request <<< Received proxied response code 2 from internal virtual server.
So... nothing after authenticate's "pap" module. *** The same config on a 2.2.0 server yields: *** rad_recv: Access-Request packet from host 158.64.1.65 port 37201, id=177, length=62 User-Name = "swinter" User-Password = "**************" NAS-Identifier = "AAI-Staff-IdP" server AAI { ... ++- if (NAS-Identifier == "AAI-Staff-IdP" ) returns noop ++ ... skipping else for request 0: Preceding "if" was taken } # server AAI WARNING: Empty pre-proxy section. Using default return values.
Sending proxied request internally to virtual server. server staff { ... Found Auth-Type = PAP # Executing group from file /usr/local/freeradius/config/raddb/sites-enabled/staff +- entering group PAP {...} [pap] login attempt with password "************" [pap] Using NT encryption. [pap] expand: %{User-Password} -> ************ [pap] NT-Hash of *********** = ########################## [pap] expand: %{mschap:NT-Hash %{User-Password}} -> ####################### [pap] User authenticated successfully ++[pap] returns ok # Executing section post-auth from file /usr/local/freeradius/config/raddb/sites-enabled/staff +- entering group post-auth {...} ++- entering policy restena_log_policy {...}
(and eventually comes the INSERT) Hope this helps, Stefan
I think I found a regression in the 2.x.x branch. I used to use 2.2.0 until I needed the SSHA1 patch from branch; but with branch code, something totally unrelated now stopped working.
I have a custom SQL query in post-auth, it calls an SQL module instance "sql-webmailsso-users" and does an INSERT. Here is what works with 2.2.0 code:
2.2.0:
expand: INSERT INTO check_webmailsso_users (user,token,timeout) VALUES('%{User-Name}','%{control:RESTENA-Rand-Source}',TIMESTAMPADD(hour, 12, NOW())) ON DUPLICATE KEY UPDATE token='%{control:RESTENA-Rand-Source}', tim eout=TIMESTAMPADD(hour, 12, NOW()) -> INSERT INTO check_webmailsso_users (user,token,timeout) VALUES('swinter','620413e46406a7c05e84253cd75fcb06620413e46406a7c05e84253cd75fcb06620413e46406a7c05e84253cd75fcb06',TIMESTAMPADD(hour, 12, NOW())) ON DUPLICATE KEY UPDATE token='620413e46406a7c05e84253cd75fcb06620413e46406a7c05e84253cd75fcb06620413e46406a7c05e84253cd75fcb06', timeout=TIMESTAMPADD(hour, 12, NOW()) rlm_sql (sql-webmailsso-users): Reserving sql socket id: 1 rlm_sql (sql-webmailsso-users): Released sql socket id: 1 expand: %{sql-webmailsso-users:INSERT INTO check_webmailsso_users (user,token,timeout) VALUES('%{User-Name}','%{control:RESTENA-Rand-Source}',TIMESTAMPADD(hour, 12, NOW())) ON DUPLICATE KEY UPDATE token='%{control:RESTENA-Rand-Source}', timeout=TIMESTAMPADD(hour, 12, NOW())} -> 1 +++[expand] returns noop expand: urn:restena:magicmushroom=%{control:RESTENA-Rand-Source} -> urn:restena:magicmushroom=620413e46406a7c05e84253cd75fcb06620413e46406a7c05e84253cd75fcb06620413e46406a7c05e84253cd75fcb06
I.e. expansion gets done, and the SQL query gets executed. Note that there is a line "+++[expand] returns noop" in the middle.
With 2.x.x branch code, the identical config does not actually perfom the SQL query; even though things still get expanded as they should. Ominously, that "noop" line is NOT showing up in the two 2.x.x branch snapshots I tested with. Here are two examples:
20130610:
expand: INSERT INTO check_webmailsso_users (user,token,timeout) VALUES('%{User-Name}','%{control:RESTENA-Rand-Source}',TIMESTAMPADD(hour, 12, NOW())) ON DUPLICATE KEY UPDATE token='%{control:RESTENA-Rand-Source}', tim eout=TIMESTAMPADD(hour, 12, NOW()) -> INSERT INTO check_webmailsso_users (user,token,timeout) VALUES('swinter','8570ceee00c6d8ed3f1c56e2d47c51318570ceee00c6d8ed3f1c56e2d47c51318570ceee00c6d8ed3f1c56e2d47c5131',TIMESTAMPADD(hour, 12, NOW())) ON DUPLICATE KEY UPDATE token='8570ceee00c6d8ed3f1c56e2d47c51318570ceee00c6d8ed3f1c56e2d47c51318570ceee00c6d8ed3f1c56e2d47c5131', timeout=TIMESTAMPADD(hour, 12, NOW()) rlm_sql (sql-webmailsso-users): Reserving sql socket id: 6 rlm_sql (sql-webmailsso-users): Released sql socket id: 6 expand: %{sql-webmailsso-users:INSERT INTO check_webmailsso_users (user,token,timeout) VALUES('%{User-Name}','%{control:RESTENA-Rand-Source}',TIMESTAMPADD(hour, 12, NOW())) ON DUPLICATE KEY UPDATE token='%{control:RESTENA-Rand-Source}', timeout=TIMESTAMPADD(hour, 12, NOW())} -> 1 expand: urn:restena:magicmushroom=%{control:RESTENA-Rand-Source} -> urn:restena:magicmushroom=8570ceee00c6d8ed3f1c56e2d47c51318570ceee00c6d8ed3f1c56e2d47c51318570ceee00c6d8ed3f1c56e2d47c5131
20310704:
expand: INSERT INTO check_webmailsso_users (user,token,timeout) VALUES('%{User-Name}','%{control:RESTENA-Rand-Source}',TIMESTAMPADD(hour, 12, NOW())) ON DUPLICATE KEY UPDATE token='%{control:RESTENA-Rand-Source}', tim eout=TIMESTAMPADD(hour, 12, NOW()) -> INSERT INTO check_webmailsso_users (user,token,timeout) VALUES('swinter','af571d6c1794a2e491091ac6990d5d6daf571d6c1794a2e491091ac6990d5d6daf571d6c1794a2e491091ac6990d5d6d',TIMESTAMPADD(hour, 12, NOW())) ON DUPLICATE KEY UPDATE token='af571d6c1794a2e491091ac6990d5d6daf571d6c1794a2e491091ac6990d5d6daf571d6c1794a2e491091ac6990d5d6d', timeout=TIMESTAMPADD(hour, 12, NOW()) rlm_sql (sql-webmailsso-users): Reserving sql socket id: 8 rlm_sql (sql-webmailsso-users): Released sql socket id: 8 expand: %{sql-webmailsso-users:INSERT INTO check_webmailsso_users (user,token,timeout) VALUES('%{User-Name}','%{control:RESTENA-Rand-Source}',TIMESTAMPADD(hour, 12, NOW())) ON DUPLICATE KEY UPDATE token='%{control:RESTENA-Rand-Source}', timeout=TIMESTAMPADD(hour, 12, NOW())} -> 1 expand: urn:restena:magicmushroom=%{control:RESTENA-Rand-Source} -> urn:restena:magicmushroom=af571d6c1794a2e491091ac6990d5d6daf571d6c1794a2e491091ac6990d5d6daf571d6c1794a2e491091ac6990d5d6d
Everything looks "pretty much" okay - but my database never gets the INSERT. The only difference I really see in the log is that the "noop" line doesn't show up.
Hope that explains the problem, and helps in finding the problem.
Stefan
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
-- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg Tel: +352 424409 1 Fax: +352 422473