Musing and digressing around sqlite
Axel Luttgens
axel.luttgens at skynet.be
Wed Jul 9 18:54:01 CEST 2014
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
More information about the Freeradius-Users
mailing list