Musing and digressing around sqlite
Hello, I'm testing FR with the slite backend, with the configs provided by: raddb/mods-config/sql/main/sqlite/schema.sql raddb/mods-config/sql/main/sqlite/queries.conf And I have some questions. So, if I may ask... 1. Almost all tables have an id column, conveniently named "id" and defined as: id int(11) PRIMARY KEY Is there any reason for not having defined those columns as id INTEGER PRIMARY KEY AUTOINCREMENT instead? 2. Incidentally, table "radusergroup" doesn't have such a column. An omission? Or could it prove problematic to define such a column? 3. The post-auth query is defined as: query = "\ INSERT INTO ${..postauth_table} \ (username, pass, reply, authdate) \ VALUES ( \ '%{SQL-User-Name}', \ '%{%{User-Password}:-%{Chap-Password}}', \ '%{reply:Packet-Type}', \ %{%{integer:Event-Timestamp}:-date('now')})" and the log shows it expands as: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'bob', 'hello', 'Access-Accept', ) As a result, no row is inserted into table "radpostauth", since its column "authdate" is defined to be NOT NULL. How is the expression %{%{integer:Event-Timestamp}:-date('now')} supposed to be interpreted? More specifically, why the enclosing %{...}? 4. Replacing above expression by '%S' works beautifully. I mean, the expansion for the query yields a timestamp such as "'2014-07-08 18:09:54'", and a row is now happily inserted into table "radpostauth". :-) What is the rationale for having devised a query based on Event-Timestamp at first hand? 5. BTW, file http://networkradius.com/doc/FreeRADIUS-Implementation-Ch16.pdf describes %S as returning a timestamp with format "YYYY-mmm-ddd HH:MM:SS". Wouldn't something like "YYYY-MM-DD HH:MM:SS" be more accurate? 6. I've left the default setting radius_db = "radius" in raddb/mods-available/sql, even if my db file is named "radiusdb". Everything seems to be working fine. What is the role of variable "radius_db" in an sqlite context? 7. Going back to question 3, this raises the usual question about sqlite in such cases. Would there be a way to get an explicit error message written to syslog? Many thanks in advance, Axel
On 8 Jul 2014, at 14:57, Axel Luttgens <axel.luttgens@skynet.be> wrote:
Hello,
I'm testing FR with the slite backend, with the configs provided by:
raddb/mods-config/sql/main/sqlite/schema.sql raddb/mods-config/sql/main/sqlite/queries.conf
And I have some questions. So, if I may ask...
1. Almost all tables have an id column, conveniently named "id" and defined as:
id int(11) PRIMARY KEY
Is there any reason for not having defined those columns as
id INTEGER PRIMARY KEY AUTOINCREMENT instead?
Nope.
2. Incidentally, table "radusergroup" doesn't have such a column. An omission? Or could it prove problematic to define such a column?
It should probably have one as well.
3. The post-auth query is defined as:
query = "\ INSERT INTO ${..postauth_table} \ (username, pass, reply, authdate) \ VALUES ( \ '%{SQL-User-Name}', \ '%{%{User-Password}:-%{Chap-Password}}', \ '%{reply:Packet-Type}', \ %{%{integer:Event-Timestamp}:-date('now')})"
and the log shows it expands as:
INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'bob', 'hello', 'Access-Accept', )
As a result, no row is inserted into table "radpostauth", since its column "authdate" is defined to be NOT NULL.
Could you provide the debug output please.
How is the expression %{%{integer:Event-Timestamp}:-date('now')} supposed to be interpreted? More specifically, why the enclosing %{...}?
It's interpreted by the xlat parser. As integer:Event-Timestamp expands to a zero length string, data('now') should be inserted into the query string instead... I guess that's a bug.
4. Replacing above expression by '%S' works beautifully. I mean, the expansion for the query yields a timestamp such as "'2014-07-08 18:09:54'", and a row is now happily inserted into table "radpostauth". :-) What is the rationale for having devised a query based on Event-Timestamp at first hand?
It's adjusted for delay, whereas %S isn't. If you're using the detail/reader writer combo using %S will produce invalid results. If you're doing accounting Acct-Delay-Time will be taken into account when producing the value for Event-Timestamp also.
5. BTW, file http://networkradius.com/doc/FreeRADIUS-Implementation-Ch16.pdf describes %S as returning a timestamp with format "YYYY-mmm-ddd HH:MM:SS". Wouldn't something like "YYYY-MM-DD HH:MM:SS" be more accurate?
Probably.
6. I've left the default setting
radius_db = "radius"
in raddb/mods-available/sql, even if my db file is named "radiusdb". Everything seems to be working fine. What is the role of variable "radius_db" in an sqlite context?
None. The database file is set with sql { sqlite { filename = "/path/to/file" } }
7. Going back to question 3, this raises the usual question about sqlite in such cases. Would there be a way to get an explicit error message written to syslog?
Use linelog to log Module-Failure-Message attribute values. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
Le 9 juil. 2014 à 01:18, Arran Cudbard-Bell a écrit :
On 8 Jul 2014, at 14:57, Axel Luttgens wrote:
[...] 3. The post-auth query is defined as:
query = "\ INSERT INTO ${..postauth_table} \ (username, pass, reply, authdate) \ VALUES ( \ '%{SQL-User-Name}', \ '%{%{User-Password}:-%{Chap-Password}}', \ '%{reply:Packet-Type}', \ %{%{integer:Event-Timestamp}:-date('now')})"
and the log shows it expands as:
INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'bob', 'hello', 'Access-Accept', )
As a result, no row is inserted into table "radpostauth", since its column "authdate" is defined to be NOT NULL.
Could you provide the debug output please.
Hello Arran, Thank you for your reply. Here's the output (with -Xx): Wed Jul 9 17:32:02 2014 : Auth: (0) Login OK: [bob] (from client localhost port 0) Wed Jul 9 17:32:02 2014 : Debug: (0) # Executing section post-auth from file /_ROOT/etc/raddb/sites-enabled/default Wed Jul 9 17:32:02 2014 : Debug: (0) post-auth { Wed Jul 9 17:32:02 2014 : Debug: (0) modsingle[post-auth]: calling sql (rlm_sql) for request 0 Wed Jul 9 17:32:02 2014 : Debug: .query Wed Jul 9 17:32:02 2014 : Debug: Parsed xlat tree: Wed Jul 9 17:32:02 2014 : Debug: literal --> .query Wed Jul 9 17:32:02 2014 : Debug: (0) sql : EXPAND .query Wed Jul 9 17:32:02 2014 : Debug: (0) sql : --> .query Wed Jul 9 17:32:02 2014 : Debug: (0) sql : Using query template 'query' Wed Jul 9 17:32:02 2014 : Debug: rlm_sql (sql): Reserved connection (4) Wed Jul 9 17:32:02 2014 : Debug: %{User-Name} Wed Jul 9 17:32:02 2014 : Debug: Parsed xlat tree: Wed Jul 9 17:32:02 2014 : Debug: attribute --> User-Name Wed Jul 9 17:32:02 2014 : Debug: (0) sql : EXPAND %{User-Name} Wed Jul 9 17:32:02 2014 : Debug: (0) sql : --> bob Wed Jul 9 17:32:02 2014 : Debug: (0) sql : SQL-User-Name set to 'bob' Wed Jul 9 17:32:02 2014 : Debug: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', %{%{integer:Event-Timestamp}:-date('now')}) Wed Jul 9 17:32:02 2014 : Debug: Parsed xlat tree: Wed Jul 9 17:32:02 2014 : Debug: literal --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( ' Wed Jul 9 17:32:02 2014 : Debug: attribute --> SQL-User-Name Wed Jul 9 17:32:02 2014 : Debug: literal --> ', ' Wed Jul 9 17:32:02 2014 : Debug: if { Wed Jul 9 17:32:02 2014 : Debug: attribute --> User-Password Wed Jul 9 17:32:02 2014 : Debug: } Wed Jul 9 17:32:02 2014 : Debug: else { Wed Jul 9 17:32:02 2014 : Debug: attribute --> CHAP-Password Wed Jul 9 17:32:02 2014 : Debug: } Wed Jul 9 17:32:02 2014 : Debug: literal --> ', ' Wed Jul 9 17:32:02 2014 : Debug: attribute --> Packet-Type Wed Jul 9 17:32:02 2014 : Debug: literal --> ', Wed Jul 9 17:32:02 2014 : Debug: if { Wed Jul 9 17:32:02 2014 : Debug: xlat --> integer Wed Jul 9 17:32:02 2014 : Debug: { Wed Jul 9 17:32:02 2014 : Debug: literal --> Event-Timestamp Wed Jul 9 17:32:02 2014 : Debug: } Wed Jul 9 17:32:02 2014 : Debug: } Wed Jul 9 17:32:02 2014 : Debug: else { Wed Jul 9 17:32:02 2014 : Debug: literal --> date('now') Wed Jul 9 17:32:02 2014 : Debug: } Wed Jul 9 17:32:02 2014 : Debug: literal --> ) Wed Jul 9 17:32:02 2014 : Debug: (0) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', %{%{integer:Event-Timestamp}:-date('now')}) Wed Jul 9 17:32:02 2014 : Debug: (0) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'bob', 'hello', 'Access-Accept', ) Wed Jul 9 17:32:02 2014 : Debug: rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'bob', 'hello', 'Access-Accept', )' Wed Jul 9 17:32:02 2014 : Debug: (0) sql : No additional queries configured
How is the expression %{%{integer:Event-Timestamp}:-date('now')} supposed to be interpreted? More specifically, why the enclosing %{...}?
It's interpreted by the xlat parser. As integer:Event-Timestamp expands to a zero length string, data('now') should be inserted into the query string instead...
Yes, that's what I thought to have (more or less) understood from the docs. ;-) But...
I guess that's a bug.
... but indeed, perhaps something strange is at work here. For example, when I remove the "integer:" piece before "Event-Timestamp", this is what I get in the debug output: Wed Jul 9 18:13:50 2014 : Auth: (0) Login OK: [bob] (from client localhost port 0) Wed Jul 9 18:13:50 2014 : Debug: (0) # Executing section post-auth from file /_ROOT/etc/raddb/sites-enabled/default Wed Jul 9 18:13:50 2014 : Debug: (0) post-auth { Wed Jul 9 18:13:50 2014 : Debug: (0) modsingle[post-auth]: calling sql (rlm_sql) for request 0 Wed Jul 9 18:13:50 2014 : Debug: .query Wed Jul 9 18:13:50 2014 : Debug: Parsed xlat tree: Wed Jul 9 18:13:50 2014 : Debug: literal --> .query Wed Jul 9 18:13:50 2014 : Debug: (0) sql : EXPAND .query Wed Jul 9 18:13:50 2014 : Debug: (0) sql : --> .query Wed Jul 9 18:13:50 2014 : Debug: (0) sql : Using query template 'query' Wed Jul 9 18:13:50 2014 : Debug: rlm_sql (sql): Reserved connection (4) Wed Jul 9 18:13:50 2014 : Debug: %{User-Name} Wed Jul 9 18:13:50 2014 : Debug: Parsed xlat tree: Wed Jul 9 18:13:50 2014 : Debug: attribute --> User-Name Wed Jul 9 18:13:50 2014 : Debug: (0) sql : EXPAND %{User-Name} Wed Jul 9 18:13:50 2014 : Debug: (0) sql : --> bob Wed Jul 9 18:13:50 2014 : Debug: (0) sql : SQL-User-Name set to 'bob' Wed Jul 9 18:13:50 2014 : Debug: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', %{%{Event-Timestamp}:-date('now')}) Wed Jul 9 18:13:50 2014 : Debug: Parsed xlat tree: Wed Jul 9 18:13:50 2014 : Debug: literal --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( ' Wed Jul 9 18:13:50 2014 : Debug: attribute --> SQL-User-Name Wed Jul 9 18:13:50 2014 : Debug: literal --> ', ' Wed Jul 9 18:13:50 2014 : Debug: if { Wed Jul 9 18:13:50 2014 : Debug: attribute --> User-Password Wed Jul 9 18:13:50 2014 : Debug: } Wed Jul 9 18:13:50 2014 : Debug: else { Wed Jul 9 18:13:50 2014 : Debug: attribute --> CHAP-Password Wed Jul 9 18:13:50 2014 : Debug: } Wed Jul 9 18:13:50 2014 : Debug: literal --> ', ' Wed Jul 9 18:13:50 2014 : Debug: attribute --> Packet-Type Wed Jul 9 18:13:50 2014 : Debug: literal --> ', Wed Jul 9 18:13:50 2014 : Debug: if { Wed Jul 9 18:13:50 2014 : Debug: attribute --> Event-Timestamp Wed Jul 9 18:13:50 2014 : Debug: } Wed Jul 9 18:13:50 2014 : Debug: else { Wed Jul 9 18:13:50 2014 : Debug: literal --> date('now') Wed Jul 9 18:13:50 2014 : Debug: } Wed Jul 9 18:13:50 2014 : Debug: literal --> ) Wed Jul 9 18:13:50 2014 : Debug: (0) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', %{%{Event-Timestamp}:-date('now')}) Wed Jul 9 18:13:50 2014 : Debug: (0) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'bob', 'hello', 'Access-Accept', date=28=27now=27=29) Wed Jul 9 18:13:50 2014 : Debug: rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'bob', 'hello', 'Access-Accept', date=28=27now=27=29)' Wed Jul 9 18:13:50 2014 : Debug: (0) sql : No additional queries configured Of course, that "date=28=27now=27=29" sequence of characters doesn't make any sense for sqlite, and no row gets inserted into the table. Still investigating...
4. Replacing above expression by '%S' works beautifully. I mean, the expansion for the query yields a timestamp such as "'2014-07-08 18:09:54'", and a row is now happily inserted into table "radpostauth". :-) What is the rationale for having devised a query based on Event-Timestamp at first hand?
It's adjusted for delay, whereas %S isn't.
If you're using the detail/reader writer combo using %S will produce invalid results.
If you're doing accounting Acct-Delay-Time will be taken into account when producing the value for Event-Timestamp also.
I don't understand everything yet (I'm just a plain newbie wrt FR...), but am I supposed to have a value for "Event-Timestamp" in the post-auth section (as defined by, basically, the standard configuration coming with FR)? Axel
Le 9 juil. 2014 à 18:54, Axel Luttgens a écrit :
[...] Wed Jul 9 18:13:50 2014 : Debug: (0) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', %{%{Event-Timestamp}:-date('now')}) Wed Jul 9 18:13:50 2014 : Debug: (0) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'bob', 'hello', 'Access-Accept', date=28=27now=27=29) Wed Jul 9 18:13:50 2014 : Debug: rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'bob', 'hello', 'Access-Accept', date=28=27now=27=29)' Wed Jul 9 18:13:50 2014 : Debug: (0) sql : No additional queries configured
Of course, that "date=28=27now=27=29" sequence of characters doesn't make any sense for sqlite, and no row gets inserted into the table.
Still investigating...
I began to fear unlang was completely broken here, and thus tried with linelog, the idea being to check whether a similar expansion fails in that context too. Fortunately, this looks a bit more reassuring: Jul 10 11:11:27 radius.example.com radiusd[2356] <Notice>: (0) Login OK: [bob] (from client localhost port 0) Jul 10 11:11:27 radius.example.com radiusd[2356] <Debug>: (0) # Executing section post-auth from file /_ROOT/etc/raddb/sites-enabled/default Jul 10 11:11:27 radius.example.com radiusd[2356] <Debug>: (0) post-auth { Jul 10 11:11:27 radius.example.com radiusd[2356] <Debug>: (0) syslog_post-auth : EXPAND msgs.%{%{reply:Packet-Type}:-format} Jul 10 11:11:27 radius.example.com radiusd[2356] <Debug>: (0) syslog_post-auth : --> msgs.Access-Accept Jul 10 11:11:27 radius.example.com radiusd[2356] <Debug>: (0) syslog_post-auth : EXPAND %{User-Name}#%{%{User-Password}:-%{Chap-Password}}#%{reply:Packet-Type}#%{%{Event-Timestamp}:-date('now')} Jul 10 11:11:27 radius.example.com radiusd[2356] <Debug>: (0) syslog_post-auth : --> bob#hello#Access-Accept#date('now') Jul 10 11:11:27 radius.example.com radiusd[2356] <Info>: bob#hello#Access-Accept#date('now') So, perhaps could it be inferred that unlang expansions misbehave in an sqlite context only. Are there other things I could try? Axel
On 10-07-14 11:26, Axel Luttgens wrote:
Le 9 juil. 2014 à 18:54, Axel Luttgens a écrit :
[...] Wed Jul 9 18:13:50 2014 : Debug: (0) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', %{%{Event-Timestamp}:-date('now')}) Wed Jul 9 18:13:50 2014 : Debug: (0) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'bob', 'hello', 'Access-Accept', date=28=27now=27=29) Wed Jul 9 18:13:50 2014 : Debug: rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'bob', 'hello', 'Access-Accept', date=28=27now=27=29)' Wed Jul 9 18:13:50 2014 : Debug: (0) sql : No additional queries configured
Of course, that "date=28=27now=27=29" sequence of characters doesn't make any sense for sqlite, and no row gets inserted into the table.
Still investigating...
...
So, perhaps could it be inferred that unlang expansions misbehave in an sqlite context only.
I don't think this is misbehaving, it's more likely the module is trying to prevent SQL injections. I'm not that familiar with SQLite, but possibly something like this would work: COALESCE(%{%{Event-Timestamp}:NULL}, date('now')) -- Herwin Weststrate
Le 10 juil. 2014 à 11:58, Herwin Weststrate a écrit :
On 10-07-14 11:26, Axel Luttgens wrote:
...
So, perhaps could it be inferred that unlang expansions misbehave in an sqlite context only.
I don't think this is misbehaving, it's more likely the module is trying to prevent SQL injections.
I'm not that familiar with SQLite, but possibly something like this would work:
COALESCE(%{%{Event-Timestamp}:NULL}, date('now'))
Hello Herwin, I tend to believe your proposal would just avoid the problematic parts of the expansion, the ones relying on unlang's conditional syntax (i.e. those constructs of the form ${ … -: … }), more specifically when the default value (i.e. the right one) has to be fetched. In that sense, the above would just ask sqlite to provide a default value itself, instead of asking unlang to build the query (to be passed to sqlite) with that default value. Anyway, your suggestion may prove very useful as a workaround. Anecdotally, it is interesting to see that the post-auth queries provided in raddb/mods-config/sql/main for the various db engines but sqlite all feed column "authdate" with simple values such as: '%S' NOW() TO_TIMESTAMP('%S','YYYY-MM-DDHH24:MI:SS') Axel
Le 9 juil. 2014 à 01:18, Arran Cudbard-Bell a écrit :
On 8 Jul 2014, at 14:57, Axel Luttgens wrote:
[...] 5. BTW, file http://networkradius.com/doc/FreeRADIUS-Implementation-Ch16.pdf describes %S as returning a timestamp with format "YYYY-mmm-ddd HH:MM:SS". Wouldn't something like "YYYY-MM-DD HH:MM:SS" be more accurate?
Probably.
On networkradius.com, it is said: We are working on the definitive FreeRADIUS reference and implementation guide. We have provided a few chapters below for feedback. but without obvious instructions as how to provide such a feedback. So, I took the opportunity of my message for writing down that little detail en passant... Axel
Le 9 juil. 2014 à 01:18, Arran Cudbard-Bell a écrit :
On 8 Jul 2014, at 14:57, Axel Luttgens wrote:
[...] 6. I've left the default setting
radius_db = "radius"
in raddb/mods-available/sql, even if my db file is named "radiusdb". Everything seems to be working fine. What is the role of variable "radius_db" in an sqlite context?
None.
The database file is set with
sql {
sqlite { filename = "/path/to/file" } }
Hello Arran, Indeed, this is quite common in the case of an sqlite setup from within an application. May I suggest to anyway slightly adjust that comment appearing in raddb/mods-available/sql: # Database table configuration for everything except Oracle radius_db = "radius" Put that way, it could be understood that the radius_db setting might have some role with sqlite's setup. And such an ambiguity may be re-enforced by the fact that the value of radius_db isn't really a true don't care, even with sqlite; for example, log messages such as <info> rlm_sql (sql): Attempting to connect to database "my great db" are liable be emitted. HTH, Axel
participants (3)
-
Arran Cudbard-Bell -
Axel Luttgens -
Herwin Weststrate