hi list, there's something wrong with variable expansion; can someone help us with this? regards, duffy (41) Found Auth-Type = EAP (41) # Executing group from file /etc/raddb/sites-enabled/default (41) group authenticate { (41) - entering group authenticate {...} (41) eap : Expiring EAP session with state 0xbdf36a23b8a07fd1 (41) eap : Finished EAP session with state 0xbdf36a23b8a07fd1 (41) eap : Previous EAP request found for state 0xbdf36a23b8a07fd1, released from the list (41) eap : Peer sent TTLS (21) (41) eap : EAP TTLS (21) (41) eap : Calling eap_ttls to process EAP data (41) eap_ttls : Authenticate (41) eap_ttls : processing EAP-TLS (41) eap_ttls : eaptls_verify returned 7 (41) eap_ttls : Done initial handshake (41) eap_ttls : eaptls_process returned 7 (41) eap_ttls : Session established. Proceeding to decode tunneled attributes. (41) eap_ttls : Got tunneled request User-Name = "test@fr3" MS-CHAP-Challenge = 0x84957d49e3ccb7ccbd30bb106b860eb3 MS-CHAP2-Response = 0x210052f234bbc6cc836c72ed546bc0837d250000000000000000b848ba4232812ff9babc1732f8b9b2921892f0e2a55148a1 (41) eap_ttls : Sending tunneled request User-Name = "test@fr3" MS-CHAP-Challenge = 0x84957d49e3ccb7ccbd30bb106b860eb3 MS-CHAP2-Response = 0x210052f234bbc6cc836c72ed546bc0837d250000000000000000b848ba4232812ff9babc1732f8b9b2921892f0e2a55148a1 server inner-tunnel { (41) # Executing section authorize from file /etc/raddb/sites-enabled/inner-tunnel (41) group authorize { (41) - entering group authorize {...} (41) mschap : Found MS-CHAP attributes. Setting 'Auth-Type = mschap' (41) [mschap] = ok (41) suffix : Looking up realm "fr3" for User-Name = "test@fr3" (41) suffix : Found realm "fr3" (41) suffix : Adding Stripped-User-Name = "test" (41) suffix : Adding Realm = "fr3" (41) suffix : Authentication realm is LOCAL. (41) [suffix] = ok (41) update control { (41) Proxy-To-Realm := "LOCAL" (41) } # update control = ok(41) [files] = noop (41) sql : expand: '%{%{Stripped-User-Name}:-%{%{User-Name}:-none}}' -> 'test' (41) sql : SQL-User-Name updated rlm_sql (sql): Reserved connection (41) (41) ERROR: sql : SELECT id, inner_id, attribute, val, op FROM radcheck(COALESCE(NULLIF('%{Event-Timestamp}', ''), '%S')::timestamp with time zone,'%{SQL-User-Name}','%{Realm}','%{Nas-Ip-Address}'::inet,'%{Calling-Station-Id}'::macaddr,parse_bssid(NULLIF('%{WiMAX-BS-Id}', '')),COALESCE(NULLIF('%{WiMAX-PDFID}', ''), '0')::smallint); (41) ERROR: sql : ^ Invalid variable expansion (41) ERROR: sql : Error generating query rlm_sql (sql): Released connection (41) rlm_sql (sql): Opening additional connection (42) rlm_sql (sql): Closing connection (40): Hit idle_timeout, was idle for 90 seconds rlm_sql (sql): You probably need to lower "min" rlm_sql_mysql: Socket destructor called, closing socket (41) [sql] = fail ^C Program received signal SIGINT, Interrupt. 0x00007ffff60084d3 in __select_nocancel () from /lib64/libc.so.6(gdb) bt full#0 0x00007ffff60084d3 in __select_nocancel () from /lib64/libc.so.6 No symbol table info available. #1 0x00007ffff73b8013 in fr_event_loop (el=0xaea650) at src/lib/event.c:390 i = <value optimized out> rcode = <value optimized out> maxfd = 49 when = {tv_sec = 0, tv_usec = 0} wake = <value optimized out> read_fds = {fds_bits = {985162418487296, 0 <repeats 15 times>}} master_fds = {fds_bits = {985162418487296, 0 <repeats 15 times>}} #2 0x000000000041e74c in main (argc=<value optimized out>, argv=<value optimized out>) at src/main/radiusd.c:468 rcode = <value optimized out> argval = <value optimized out> spawn_flag = 0 dont_fork = 1 write_pid = 0 flag = 0 act = {__sigaction_handler = {sa_handler = 0x41eac0 <sig_fatal>, sa_sigaction = 0x41eac0 <sig_fatal>}, sa_mask = {__val = {0 <repeats 16 times>}}, sa_flags = 0, sa_restorer = 0} (gdb)
On Tue, 2013-06-04 at 11:30 +0200, duffy wrote:
hi list, there's something wrong with variable expansion; can someone help us with this? regards, duffy
[...]
(41) sql : expand: '%{%{Stripped-User-Name}:-%{%{User-Name}:-none}}' -> 'test' (41) sql : SQL-User-Name updated rlm_sql (sql): Reserved connection (41) (41) ERROR: sql : SELECT id, inner_id, attribute, val, op FROM radcheck(COALESCE(NULLIF('%{Event-Timestamp}', ''), '%S')::timestamp with time zone,'%{SQL-User-Name}','%{Realm}','%{Nas-Ip-Address}'::inet,'%{Calling-Station-Id}'::macaddr,parse_bssid(NULLIF('%{WiMAX-BS-Id}', '')),COALESCE(NULLIF('%{WiMAX-PDFID}', ''), '0')::smallint); (41) ERROR: sql :
^ Invalid variable expansion
To be clear, the complaint is about %{SQL-User-Name}, which makes little sense since it was just updated. -- Stelian Ionescu a.k.a. fe[nl]ix Quidquid latine dictum sit, altum videtur. http://common-lisp.net/project/iolib
thank you for your reply alan! actually it seems the variable expansion issue is not really solved.. duffy (6) sql : expand: '%{%{Stripped-User-Name}:-%{%{User-Name}:-none}}' -> 'test' (6) sql : SQL-User-Name updated rlm_sql (sql): Reserved connection (39) (6) sql : expand: 'SELECT id, inner_id, attribute, val, op FROM radcheck(COALESCE(NULLIF('%{Event-Timestamp}', ''), '%S')::timestamp with time zone,'%{SQL-User-Name}','%{Realm}','% ddr,parse_bssid(NULLIF('%{WiMAX-BS-Id}', '')),COALESCE(NULLIF('%{WiMAX-PDFID}', ''), '0')::smallint);' -> 'SELECT id, inner_id, attribute, val, op FROM radcheck(COALESCE(NULLIF('0=27=2C with time zone=2C=27test','fr3','=3F.=3F.=3F.=3F'::inet,'_'::macaddr,parse_bssid(NULLIF('0x=3F=3F', '')),COALESCE(NULLIF('0', ''), '0')::smallint);' rlm_sql (sql): Executing query: 'SELECT id, inner_id, attribute, val, op FROM radcheck(COALESCE(NULLIF('0=27=2C =27=27=29=2C =271970-01-01 01:00:00=27=29::timestamp with time zone=2C=27t _bssid(NULLIF('0x=3F=3F', '')),COALESCE(NULLIF('0', ''), '0')::smallint);' rlm_sql_postgresql: Status: PGRES_FATAL_ERROR rlm_sql_postgresql: Error syntax error at or near "," rlm_sql_postgresql: Postgresql Fatal Error: [42601: SYNTAX ERROR] Occurred!! rlm_sql (sql): Database query error 'ERROR: syntax error at or near "," LINE 1: ...0=27=29::timestamp with time zone=2C=27test','fr3','=3F.=3F.... (6) ERROR: sql : SQL query error rlm_sql (sql): Released connection (39) Il 04/06/13 14.52, Alan DeKok ha scritto:
duffy wrote:
hi list, there's something wrong with variable expansion; can someone help us with this?
I've pushed a fix.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
duffy wrote:
thank you for your reply alan! actually it seems the variable expansion issue is not really solved..
Read the debug output. It doesn't complain about variables any more,
_bssid(NULLIF('0x=3F=3F', '')),COALESCE(NULLIF('0', ''), '0')::smallint);' rlm_sql_postgresql: Status: PGRES_FATAL_ERROR rlm_sql_postgresql: Error syntax error at or near "," rlm_sql_postgresql: Postgresql Fatal Error: [42601: SYNTAX ERROR] Occurred!!
See? Fix your query so that it doesn't contain Postgresql syntax errors. Alan DeKok.
On Tue, 2013-06-04 at 09:57 -0400, Alan DeKok wrote:
duffy wrote:
thank you for your reply alan! actually it seems the variable expansion issue is not really solved..
Read the debug output. It doesn't complain about variables any more,
_bssid(NULLIF('0x=3F=3F', '')),COALESCE(NULLIF('0', ''), '0')::smallint);' rlm_sql_postgresql: Status: PGRES_FATAL_ERROR rlm_sql_postgresql: Error syntax error at or near "," rlm_sql_postgresql: Postgresql Fatal Error: [42601: SYNTAX ERROR] Occurred!!
This is from our configuration file: authorize_check_query="\ SELECT id, inner_id, attribute, val, op \ FROM radcheck(\ COALESCE(NULLIF('%{Event-Timestamp}', ''), '%S')::timestamp with time zone,\ '%{SQL-User-Name}',\ '%{Realm}',\ '%{Nas-Ip-Address}'::inet,\ '%{Calling-Station-Id}'::macaddr,\ parse_bssid(NULLIF('%{WiMAX-BS-Id}', '')),\ COALESCE(NULLIF('%{WiMAX-PDFID}', ''), '0')::smallint);" additionally, the debug log shows that Event-Timestamp contains a valid value: rlm_perl: Added pair Event-Timestamp = Jun 4 2013 15:13:09 CEST So I guess that the error is in the xlat function. -- Stelian Ionescu a.k.a. fe[nl]ix Quidquid latine dictum sit, altum videtur. http://common-lisp.net/project/iolib
Stelian Ionescu wrote:
This is from our configuration file:
authorize_check_query="\ SELECT id, inner_id, attribute, val, op \ FROM radcheck(\ COALESCE(NULLIF('%{Event-Timestamp}', ''), '%S')::timestamp with time zone,\ '%{SQL-User-Name}',\ '%{Realm}',\ '%{Nas-Ip-Address}'::inet,\ '%{Calling-Station-Id}'::macaddr,\ parse_bssid(NULLIF('%{WiMAX-BS-Id}', '')),\ COALESCE(NULLIF('%{WiMAX-PDFID}', ''), '0')::smallint);"
additionally, the debug log shows that Event-Timestamp contains a valid value:
rlm_perl: Added pair Event-Timestamp = Jun 4 2013 15:13:09 CEST
So I guess that the error is in the xlat function.
It's hard for me to figure out just what is going on in that expansion. Can you simplify it? Or point out *what* the error is? Alan DeKok.
On Tue, 2013-06-04 at 14:10 -0400, Alan DeKok wrote:
Stelian Ionescu wrote:
This is from our configuration file:
authorize_check_query="\ SELECT id, inner_id, attribute, val, op \ FROM radcheck(\ COALESCE(NULLIF('%{Event-Timestamp}', ''), '%S')::timestamp with time zone,\ '%{SQL-User-Name}',\ '%{Realm}',\ '%{Nas-Ip-Address}'::inet,\ '%{Calling-Station-Id}'::macaddr,\ parse_bssid(NULLIF('%{WiMAX-BS-Id}', '')),\ COALESCE(NULLIF('%{WiMAX-PDFID}', ''), '0')::smallint);"
additionally, the debug log shows that Event-Timestamp contains a valid value:
rlm_perl: Added pair Event-Timestamp = Jun 4 2013 15:13:09 CEST
So I guess that the error is in the xlat function.
It's hard for me to figure out just what is going on in that expansion. Can you simplify it? Or point out *what* the error is?
Take for instance the expansion of '%{Nas-Ip-Address}'::inet from that trace: it's '=3F.=3F.=3F.=3F'::inet which looks like an url-encoding of "?.?.?.?". I can't imagine how this can be since the debug output from rlm_perl, which prints all VPs in the request, shows that the actual value is correct so my only guess is that the xlat function is somehow buggy. -- Stelian Ionescu a.k.a. fe[nl]ix Quidquid latine dictum sit, altum videtur. http://common-lisp.net/project/iolib
Stelian Ionescu wrote:
Take for instance the expansion of '%{Nas-Ip-Address}'::inet from that trace: it's '=3F.=3F.=3F.=3F'::inet which looks like an url-encoding of "?.?.?.?". I can't imagine how this can be since the debug output from rlm_perl, which prints all VPs in the request, shows that the actual value is correct so my only guess is that the xlat function is somehow buggy.
Ah. Let me guess... you're running the query from the inner-tunnel, and you didn't set "copy_request_to_tunnel = yes". The "?.?.?.?" output is produced when the NAS-IP-Address attribute doesn't exist. Since you say it exists, the only place it normally doesn't exist is in the inner-tunnel. Alan DeKok.
On Wed, 2013-06-05 at 09:15 -0400, Alan DeKok wrote:
Stelian Ionescu wrote:
Take for instance the expansion of '%{Nas-Ip-Address}'::inet from that trace: it's '=3F.=3F.=3F.=3F'::inet which looks like an url-encoding of "?.?.?.?". I can't imagine how this can be since the debug output from rlm_perl, which prints all VPs in the request, shows that the actual value is correct so my only guess is that the xlat function is somehow buggy.
Ah. Let me guess... you're running the query from the inner-tunnel, and you didn't set "copy_request_to_tunnel = yes".
The "?.?.?.?" output is produced when the NAS-IP-Address attribute doesn't exist. Since you say it exists, the only place it normally doesn't exist is in the inner-tunnel.
It's true that copy_request_to_tunnel wasn't set to "yes", but the problem still remains in that radius_axlat() didn't output a literal '?' but its hex-encoding, and that's caused by the way sql escaping is currently done. Give these request VPs: Event-Timestamp = 'Jun 7 2013 18:02:09 CEST' SQL-User-Name = 'test' then the SQL fragment «COALESCE(NULLIF('%{Event-Timestamp}', ''), '%S')::timestamp with time zone,'%{SQL-User-Name}'» gets translated into «COALESCE(NULLIF('Jun 7 2013 18:02:09 CEST=27=2C =27=27=29=2C =271970-01-01 01:00:00=27=29::timestamp with time zone=2C=27test'» Notice how the apostrophes and commas are getting hex-encoded, thereby making the resulting query invalid. Another strange thing in that expansion is that %S now gets consistently expanded to «1970-01-01 01:00:00» -- Stelian Ionescu a.k.a. fe[nl]ix Quidquid latine dictum sit, altum videtur. http://common-lisp.net/project/iolib
Stelian Ionescu wrote:
It's true that copy_request_to_tunnel wasn't set to "yes", but the problem still remains in that radius_axlat() didn't output a literal '?' but its hex-encoding, and that's caused by the way sql escaping is currently done.
The escaping is controlled by the "safe-characters" configuration in SQL. If you want to allow '?', edit that configuration item.
Give these request VPs:
Event-Timestamp = 'Jun 7 2013 18:02:09 CEST' SQL-User-Name = 'test'
then the SQL fragment
«COALESCE(NULLIF('%{Event-Timestamp}', ''), '%S')::timestamp with time zone,'%{SQL-User-Name}'»
gets translated into
«COALESCE(NULLIF('Jun 7 2013 18:02:09 CEST=27=2C =27=27=29=2C =271970-01-01 01:00:00=27=29::timestamp with time zone=2C=27test'»
Notice how the apostrophes and commas are getting hex-encoded, thereby making the resulting query invalid.
Because that's how the SQL escaping function works. See? If you run the same xlat in a non-SQL context, you'll see '?' instead of the hex encoded version.
Another strange thing in that expansion is that %S now gets consistently expanded to «1970-01-01 01:00:00»
That shouldn't be happening. It's taken from the packet timestamp, which always gets initialized to the current time. Alan DeKok.
On Tue, 2013-06-11 at 11:10 -0400, Alan DeKok wrote:
Stelian Ionescu wrote:
It's true that copy_request_to_tunnel wasn't set to "yes", but the problem still remains in that radius_axlat() didn't output a literal '?' but its hex-encoding, and that's caused by the way sql escaping is currently done.
The escaping is controlled by the "safe-characters" configuration in SQL. If you want to allow '?', edit that configuration item.
Give these request VPs:
Event-Timestamp = 'Jun 7 2013 18:02:09 CEST' SQL-User-Name = 'test'
then the SQL fragment
«COALESCE(NULLIF('%{Event-Timestamp}', ''), '%S')::timestamp with time zone,'%{SQL-User-Name}'»
gets translated into
«COALESCE(NULLIF('Jun 7 2013 18:02:09 CEST=27=2C =27=27=29=2C =271970-01-01 01:00:00=27=29::timestamp with time zone=2C=27test'»
Notice how the apostrophes and commas are getting hex-encoded, thereby making the resulting query invalid.
Because that's how the SQL escaping function works. See?
No, it's a regression. On 2.* commas and apostrophes part of the literal query as embedded in dialup.conf didn't get escaped, only the various expansions; but now the whole query gets escaped . -- Stelian Ionescu a.k.a. fe[nl]ix Quidquid latine dictum sit, altum videtur. http://common-lisp.net/project/iolib
Stelian Ionescu wrote:
No, it's a regression. On 2.* commas and apostrophes part of the literal query as embedded in dialup.conf didn't get escaped, only the various expansions; but now the whole query gets escaped .
It's a bug fix. In 2.x, the '?' character wasn't listed in "safe-characters". Yet it wasn't escaped. That's wrong. The expansion functionality was re-written for v3. It's now less code, with better error messages, and fewer weird corner cases. As a side effect, the "safe-characters" is now processed correctly. Previously, it wasn't. The "safe-characters" list is editable for a reason. If '.' and '?' should be listed by default, we can go fix that. But the functionality WILL NOT be reverted. The old code was wrong. Alan DeKok.
On Tue, 2013-06-11 at 11:50 -0400, Alan DeKok wrote:
Stelian Ionescu wrote:
No, it's a regression. On 2.* commas and apostrophes part of the literal query as embedded in dialup.conf didn't get escaped, only the various expansions; but now the whole query gets escaped .
It's a bug fix.
In 2.x, the '?' character wasn't listed in "safe-characters". Yet it wasn't escaped. That's wrong.
The expansion functionality was re-written for v3. It's now less code, with better error messages, and fewer weird corner cases. As a side effect, the "safe-characters" is now processed correctly. Previously, it wasn't.
The "safe-characters" list is editable for a reason. If '.' and '?' should be listed by default, we can go fix that. But the functionality WILL NOT be reverted. The old code was wrong.
I'm not referring to '?', but to the fact that parts of the query are being escaped which is wrong because it produces incorrect queries by escaping commas and apostrophes. -- Stelian Ionescu a.k.a. fe[nl]ix Quidquid latine dictum sit, altum videtur. http://common-lisp.net/project/iolib
On Tue, 2013-06-11 at 11:50 -0400, Alan DeKok wrote:
Stelian Ionescu wrote:
No, it's a regression. On 2.* commas and apostrophes part of the literal query as embedded in dialup.conf didn't get escaped, only the various expansions; but now the whole query gets escaped .
It's a bug fix.
In 2.x, the '?' character wasn't listed in "safe-characters". Yet it wasn't escaped. That's wrong.
The expansion functionality was re-written for v3. It's now less code, with better error messages, and fewer weird corner cases. As a side effect, the "safe-characters" is now processed correctly. Previously, it wasn't.
The "safe-characters" list is editable for a reason. If '.' and '?' should be listed by default, we can go fix that. But the functionality WILL NOT be reverted. The old code was wrong.
And here's part of a debugging session of xlat_process on that query: (gdb) print *node $13 = {fmt = 0xb84e90 "SELECT id, inner_id, attribute, val, op FROM radcheck(COALESCE(NULLIF('", len = 71, da = 0x0, num = 0, tag = 0, list = PAIR_LIST_UNKNOWN, ref = REQUEST_UNKNOWN, type = XLAT_LITERAL, next = 0xb850d0, child = 0x0, alternate = 0x0, xlat = 0x0} (gdb) n (gdb) n (gdb) print *node $14 = {fmt = 0xb84ed9 "Event-Timestamp", len = 0, da = 0x65c290, num = 0, tag = -128, list = PAIR_LIST_REQUEST, ref = REQUEST_CURRENT, type = XLAT_ATTRIBUTE, next = 0xb85180, child = 0x0, alternate = 0x0, xlat = 0x0} (gdb) print array[0] $15 = 0xb85b40 "SELECT id, inner_id, attribute, val, op FROM radcheck(COALESCE(NULLIF('" (gdb) n (gdb) print array[1] $16 = 0xb85c80 "Jun 11 2013 17:25:54 CEST" (gdb) n (gdb) print *node $17 = {fmt = 0xb84ee9 "', ''), '%S')::timestamptz,'", len = 28, da = 0x0, num = 0, tag = 0, list = PAIR_LIST_UNKNOWN, ref = REQUEST_UNKNOWN, type = XLAT_PERCENT, next = 0xb85230, child = 0x0, alternate = 0x0, xlat = 0x0} (gdb) n (gdb) print array[2] $18 = 0xb860e0 "=27=2C =27=27=29=2C =271970-01-01 01:00:00=27=29::timestamptz=2C=27" (gdb) n (gdb) print *node $19 = {fmt = 0xb84f07 "SQL-User-Name", len = 0, da = 0x79bf38, num = 0, tag = -128, list = PAIR_LIST_REQUEST, ref = REQUEST_CURRENT, type = XLAT_ATTRIBUTE, next = 0xb852e0, child = 0x0, alternate = 0x0, xlat = 0x0} (gdb) n (gdb) print array[3] $20 = 0xb86540 "test" The third node as returned by the tokenizer is incorrect: «', ''), '%S')::timestamptz,'» should be three nodes not one, first «', ''), '» as XLAT_LITERAL, then «S» as XLAT_PERCENT then «')::timestamptz,'» as XLAT_LITERAL. -- Stelian Ionescu a.k.a. fe[nl]ix Quidquid latine dictum sit, altum videtur. http://common-lisp.net/project/iolib
Stelian Ionescu wrote:
The third node as returned by the tokenizer is incorrect: «', ''), '%S')::timestamptz,'» should be three nodes not one, first «', ''), '» as XLAT_LITERAL, then «S» as XLAT_PERCENT then «')::timestamptz,'» as XLAT_LITERAL.
I've already pushed a fix. Alan DeKok.
On Tue, Jun 11, 2013 at 05:02:33PM +0200, Stelian Ionescu wrote:
then the SQL fragment
«COALESCE(NULLIF('%{Event-Timestamp}', ''), '%S')::timestamp with time zone,'%{SQL-User-Name}'»
gets translated into
«COALESCE(NULLIF('Jun 7 2013 18:02:09 CEST=27=2C =27=27=29=2C =271970-01-01 01:00:00=27=29::timestamp with time zone=2C=27test'»
Notice how the apostrophes and commas are getting hex-encoded, thereby making the resulting query invalid.
Check out 'safe-characters' in sql/*/dialup.conf But be careful in what you permit, as it's there to protect you... 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>
On Tue, 2013-06-11 at 16:22 +0100, Matthew Newton wrote:
On Tue, Jun 11, 2013 at 05:02:33PM +0200, Stelian Ionescu wrote:
then the SQL fragment
«COALESCE(NULLIF('%{Event-Timestamp}', ''), '%S')::timestamp with time zone,'%{SQL-User-Name}'»
gets translated into
«COALESCE(NULLIF('Jun 7 2013 18:02:09 CEST=27=2C =27=27=29=2C =271970-01-01 01:00:00=27=29::timestamp with time zone=2C=27test'»
Notice how the apostrophes and commas are getting hex-encoded, thereby making the resulting query invalid.
Check out 'safe-characters' in sql/*/dialup.conf
I've never had to change safe-characters before, and queries worked(until recently). -- Stelian Ionescu a.k.a. fe[nl]ix Quidquid latine dictum sit, altum videtur. http://common-lisp.net/project/iolib
participants (4)
-
Alan DeKok -
duffy -
Matthew Newton -
Stelian Ionescu