2.x.x regression: custom SQL queries
Hi, 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 -- 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
Hi again, uh, more things seem not to be in order in 2.x.x at the moment. With yesterday's checkout, I notice that %md5 doesn't exist?
grep md5 konsoleXxx.txt
Fri Jul 5 08:41:31 2013 : Info: WARNING: Unknown module "md5" in string expansion "%" Fri Jul 5 08:41:32 2013 : Info: WARNING: Unknown module "md5" in string expansion "%%{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S}" Fri Jul 5 08:41:35 2013 : Info: WARNING: Unknown module "md5" in string expansion "%" Fri Jul 5 08:41:40 2013 : Info: WARNING: Unknown module "md5" in string expansion "%%{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S}" Fri Jul 5 08:41:41 2013 : Info: WARNING: Unknown module "md5" in string expansion "%" Fri Jul 5 08:41:43 2013 : Info: WARNING: Unknown module "md5" in string expansion "%" Fri Jul 5 08:41:43 2013 : Info: WARNING: Unknown module "md5" in string expansion "%" Note that I neither use a double %% nor an expression which only consists of a single % with nothing else in my config. It looks to me like the xlat parser is seriously confused. Starting 2.2.0 instead, with the identical config shows proper expansions:
grep md5 konsoleXxx.txt
Fri Jul 5 08:42:33 2013 : Info: expand: %{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S} -> c8fa166695715ca21e5de23b718f13a5c8fa166695715ca21e5de23b718f13a5c8fa166695715ca21e5de23b718f13a5 Fri Jul 5 08:42:33 2013 : Info: expand: %{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S} -> c8fa166695715ca21e5de23b718f13a5c8fa166695715ca21e5de23b718f13a5c8fa166695715ca21e5de23b718f13a5 Fri Jul 5 08:42:34 2013 : Info: expand: %{md5:%{config:cui_hash_key}%{request:User-Name}%{outer.request:Operator-Name}} -> 3ebe422cd006d883f0d1677e0b1a8fda Fri Jul 5 08:42:34 2013 : Info: expand: %{md5:%{config:cui_hash_key}%{request:User-Name}%{Operator-Name}} -> 3ebe422cd006d883f0d1677e0b1a8fda Fri Jul 5 08:42:35 2013 : Info: expand: %{md5:%{config:cui_hash_key}%{request:User-Name}%{outer.request:Operator-Name}} -> 2d0b24b6a2f1c3407671f60d87281a6d Fri Jul 5 08:42:35 2013 : Info: expand: %{md5:%{config:cui_hash_key}%{request:User-Name}%{Operator-Name}} -> 2d0b24b6a2f1c3407671f60d87281a6d Fri Jul 5 08:42:35 2013 : Info: expand: %{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S} -> 406b166c2c2b1ce9b5ee781ef919b58d406b166c2c2b1ce9b5ee781ef919b58d406b166c2c2b1ce9b5ee781ef919b58d Fri Jul 5 08:42:36 2013 : Info: expand: %{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S} -> 3480a4b72a897793df2e166e10d6dc163480a4b72a897793df2e166e10d6dc163480a4b72a897793df2e166e10d6dc16 Fri Jul 5 08:42:37 2013 : Info: expand: %{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S} -> 76afb853382432f4bbb77330433b866876afb853382432f4bbb77330433b866876afb853382432f4bbb77330433b8668 Fri Jul 5 08:42:38 2013 : Info: expand: %{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S} -> fa3c4b0643df91b8a499bafee0e535d0fa3c4b0643df91b8a499bafee0e535d0fa3c4b0643df91b8a499bafee0e535d0 Fri Jul 5 08:42:38 2013 : Info: expand: %{md5:%{config:cui_hash_key}%{request:User-Name}%{outer.request:Operator-Name}} -> f73e0c6824ee2803594b8fc776d58791 Fri Jul 5 08:42:39 2013 : Info: expand: %{md5:%{config:cui_hash_key}%{request:User-Name}%{Operator-Name}} -> f73e0c6824ee2803594b8fc776d58791 Fri Jul 5 08:42:39 2013 : Info: expand: %{md5:%{config:cui_hash_key}%{request:User-Name}%{outer.request:Operator-Name}} -> d809d816a751c6e65d5447453e3b861e Fri Jul 5 08:42:39 2013 : Info: expand: %{md5:%{config:cui_hash_key}%{request:User-Name}%{Operator-Name}} -> b984fa271511afdf66149ff0de23f338 Fri Jul 5 08:42:40 2013 : Info: expand: %{md5:%{config:cui_hash_key}%{request:User-Name}%{outer.request:Operator-Name}} -> d809d816a751c6e65d5447453e3b861e Fri Jul 5 08:42:40 2013 : Info: expand: %{md5:%{config:cui_hash_key}%{request:User-Name}%{Operator-Name}} -> b984fa271511afdf66149ff0de23f338 I'm abandoning 2.x.x GIT for now, cherry-picking only the SSHA1 hash patch into 2.2.0. Greetings, Stefan On 04.07.2013 09:02, Stefan Winter wrote:
Hi,
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
Stefan Winter wrote:
Hi again,
uh, more things seem not to be in order in 2.x.x at the moment. With yesterday's checkout, I notice that %md5 doesn't exist?
It works for me: ++[eap] returns noop [files] users: Matched entry bob at line 1 [files] expand: %{User-Name} -> bob [files] expand: %{md5:%{User-Name}} -> 9f9d51bc70ef21ca5c14f307980a29d8 ++[files] returns ok Are you sure everything's OK with your system? Alan DeKok.
On 5 Jul 2013, at 08:00, Stefan Winter <stefan.winter@restena.lu> wrote:
Hi again,
uh, more things seem not to be in order in 2.x.x at the moment. With yesterday's checkout, I notice that %md5 doesn't exist?
grep md5 konsoleXxx.txt
Fri Jul 5 08:41:31 2013 : Info: WARNING: Unknown module "md5" in string expansion "%" Fri Jul 5 08:41:32 2013 : Info: WARNING: Unknown module "md5" in string expansion "%%{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S}" Fri Jul 5 08:41:35 2013 : Info: WARNING: Unknown module "md5" in string expansion "%" Fri Jul 5 08:41:40 2013 : Info: WARNING: Unknown module "md5" in string expansion "%%{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S}" Fri Jul 5 08:41:41 2013 : Info: WARNING: Unknown module "md5" in string expansion "%" Fri Jul 5 08:41:43 2013 : Info: WARNING: Unknown module "md5" in string expansion "%" Fri Jul 5 08:41:43 2013 : Info: WARNING: Unknown module "md5" in string expansion "%"
Is rlm_expr listed in instantiate? Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team
On 5 Jul 2013, at 13:42, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 5 Jul 2013, at 08:00, Stefan Winter <stefan.winter@restena.lu> wrote:
Hi again,
uh, more things seem not to be in order in 2.x.x at the moment. With yesterday's checkout, I notice that %md5 doesn't exist?
grep md5 konsoleXxx.txt
Fri Jul 5 08:41:31 2013 : Info: WARNING: Unknown module "md5" in string expansion "%" Fri Jul 5 08:41:32 2013 : Info: WARNING: Unknown module "md5" in string expansion "%%{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S}" Fri Jul 5 08:41:35 2013 : Info: WARNING: Unknown module "md5" in string expansion "%" Fri Jul 5 08:41:40 2013 : Info: WARNING: Unknown module "md5" in string expansion "%%{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S}" Fri Jul 5 08:41:41 2013 : Info: WARNING: Unknown module "md5" in string expansion "%" Fri Jul 5 08:41:43 2013 : Info: WARNING: Unknown module "md5" in string expansion "%" Fri Jul 5 08:41:43 2013 : Info: WARNING: Unknown module "md5" in string expansion "%"
Is rlm_expr listed in instantiate?
Also: %{md5:%rand:1000000%Y%m%d%h%M%S}%{md5:%rand:1000000%Y%m%d%h%M%S} Is wrong. It should be: %{md5:%{rand:1000000}%Y%m%d%h%M%S}%{md5:%{rand:1000000}%Y%m%d%h%M%S} Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team
Hi,
And %rand is wrong. It should be %{rand:...}
Yes, found that in the debug output meanwhile (that, and 5h -> %H). I fixed it, but it didn't help with the md5 situation. About the system being sane... it's an older distro, but has been running all my 2.x.x versions since 2.0.0 or so. I always compile with the same configure switches etc. The sole difference between my 2.2.0 and 2.x.x GIT build is that I also switched OpenSSL from 1.0.1c to 1.0.1e (yes, ld.so.conf / ldconfig point to the version matching the headers). Greetings, Stefan
Alan DeKok. - 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
On 5 Jul 2013, at 14:04, Stefan Winter <stefan.winter@restena.lu> wrote:
Hi,
And %rand is wrong. It should be %{rand:...}
Yes, found that in the debug output meanwhile (that, and 5h -> %H). I fixed it, but it didn't help with the md5 situation.
About the system being sane... it's an older distro, but has been running all my 2.x.x versions since 2.0.0 or so. I always compile with the same configure switches etc. The sole difference between my 2.2.0 and 2.x.x GIT build is that I also switched OpenSSL from 1.0.1c to 1.0.1e (yes, ld.so.conf / ldconfig point to the version matching the headers).
Could be linking to an older version of rlm_expr. The registration for the md5 xlat was moved out of main/xlat.c into rlm_expr, and IIRC 2.x.x doesn't have strict version checking between radiusd and the modules. If this is the case expr will probably be available, but hex/sha1/base64/tobase64/ base64tohex won't be. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team
Hi,
Could be linking to an older version of rlm_expr. The registration for the md5 xlat was moved out of main/xlat.c into rlm_expr, and IIRC 2.x.x doesn't have strict version checking between radiusd and the modules.
If this is the case expr will probably be available, but hex/sha1/base64/tobase64/ base64tohex won't be.
Ah... this rings a bell. I had only seen those md5 errors this morning, while I had 2.x.x running for some longer time. Thought I had only overlooked it... but: Indeed: radiusd.conf links to libs in a symlink directory which always points to the "latest" I've installed. Except that this morning, I didn't adapt the symlink as I hopped between versions. So, sorry about that. The sql INSERT not actually working is still an issue though; just forget about the MD5 please. Sorry for the noise, Stefan -- 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
On 5 Jul 2013, at 14:22, Stefan Winter <stefan.winter@restena.lu> wrote:
Hi,
Could be linking to an older version of rlm_expr. The registration for the md5 xlat was moved out of main/xlat.c into rlm_expr, and IIRC 2.x.x doesn't have strict version checking between radiusd and the modules.
If this is the case expr will probably be available, but hex/sha1/base64/tobase64/ base64tohex won't be.
Ah... this rings a bell. I had only seen those md5 errors this morning, while I had 2.x.x running for some longer time. Thought I had only overlooked it... but:
Indeed: radiusd.conf links to libs in a symlink directory which always points to the "latest" I've installed. Except that this morning, I didn't adapt the symlink as I hopped between versions.
So, sorry about that. The sql INSERT not actually working is still an issue though; just forget about the MD5 please.
Ok. Good that that's fixed. Regarding the SQL inserts, hardly anything has changed in the SQL module since 2.2.0. There have been three commits, and no changes since January 2012 to any of the drivers. That fact that the expansion returns '1', indicates a single row was updated just like you would expect. The missing noop is likely from fixing section priority overrides which is unrelated. I'll run a database instance up to day to double check, which driver are you using? Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team
Hi,
That fact that the expansion returns '1', indicates a single row was updated just like you would expect.
The missing noop is likely from fixing section priority overrides which is unrelated.
I'll run a database instance up to day to double check, which driver are you using?
That's MySQL. The client lib is 5.0.x (which I guess I should update), while the server is a MariaDB 5.5. It's funny... that "1" makes it look like all is fine - but I never see the row in the DB end. I'll make my own investigation early next week, moving the auths for that particular service to a dedicated FR server, and tcpdumping all traffic to the MariaDB server. Just to see if there's really nothing on the wire; or if so, what's happening on the DB Server side. Stefan -- 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
Hi,
Is rlm_expr listed in instantiate?
Yes: instantiate { expr exec eap } The errors only show up on 2.x.x with *NO* config changes. The exact same config works on 2.2.0. Stefan -- 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
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
On 10/07/13 14:47, Stefan Winter wrote:
Hope this helps,
This is almost certainly this: https://github.com/FreeRADIUS/freeradius-server/commit/a00c44328013f0e166636... ...which is necessary for the EAP virtual server post-auth/reject stuff that was backported. Probably needs this code converting to use rad_virtual_server: https://github.com/FreeRADIUS/freeradius-server/blob/v2.x.x/src/main/event.c...
On Wed, Jul 10, 2013 at 04:25:56PM +0100, Phil Mayers wrote:
This is almost certainly this:
https://github.com/FreeRADIUS/freeradius-server/commit/a00c44328013f0e166636...
My code, but as usual I blame Arran for pulling it into v2 ;-P
...which is necessary for the EAP virtual server post-auth/reject stuff that was backported.
Probably needs this code converting to use rad_virtual_server:
https://github.com/FreeRADIUS/freeradius-server/blob/v2.x.x/src/main/event.c...
Untested, but at a quick glance it's probably just changing line 1984 in event.c from fun = rad_authenticate to fun = rad_virtual_server rad_authenticate used to call rad_postauth internally on a success, but not failure (IIRC it was that way around), and the failure case was called from event.c - this meant that inner tunnel fake requests only saw it for one and not both. The new rad_virtual_server just makes sure it's called for both, and the "if accept {postauth}" code got pulled from rad_authenticate. There's probably no reason why rad_virtual_server can't be substituted wherever rad_authenticate appears, and then rad_postauth pulled out from anywhere else it's hiding (essentially just removing event.c:2453 and event.c:2478-2480). That should tidy it up a bit, and make things more consistent. I think this was all tidied and fixed in 3.0, but I can't remember off the top of my head. Matthew -- Matthew Newton, Ph.D. <mcn4@le.ac.uk> Systems Specialist, Infrastructure Services, I.T. Services, University of Leicester, Leicester LE1 7RH, United Kingdom For IT help contact helpdesk extn. 2253, <ithelp@le.ac.uk>
participants (5)
-
Alan DeKok -
Arran Cudbard-Bell -
Matthew Newton -
Phil Mayers -
Stefan Winter