Hello, please help me with SQL integration

27 Feb 2014

      Good day! I installed freeradius 3.0.x on a server with FreeBSD. Simple Authorization Users through a "files" works without problems. I started to connect SQL, as described in the documentation "HOW-SQL". Users added to the table radcheck, and when prompted radtest user user_pass localhost 0 testing123 - user can not login. Comes the following error
root@gateway:~ # radtest fredf wilma 127.0.0.1 0 testing123
Sending Access-Request of id 9 from 0.0.0.0 port 52606 to 127.0.0.1 port 1812
        User-Name = 'fredf'
        User-Password = 'wilma'
        NAS-IP-Address = 127.0.0.1
        NAS-Port = 0
        Message-Authenticator = 0x00
rad_recv: Access-Reject packet from host 127.0.0.1 port 1812, id=9, length=20
root@gateway:~ #

debug message
rad_recv: Access-Request packet from host 127.0.0.1 port 52606, id=9, length=75
        User-Name = 'fredf'
        User-Password = 'wilma'
        NAS-IP-Address = 127.0.0.1
        NAS-Port = 0
        Message-Authenticator = 0x921e720cf0599ea4cae31cf81ee1da87
Thu Feb 27 20:06:01 2014 : Debug: (0) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Thu Feb 27 20:06:01 2014 : Debug: (0)   authorize {
Thu Feb 27 20:06:01 2014 : Debug: (0)   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0
Thu Feb 27 20:06:01 2014 : Debug: (0)   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0
Thu Feb 27 20:06:01 2014 : Debug: (0)   [preprocess] = ok
Thu Feb 27 20:06:01 2014 : Debug: (0)   ? if ("%{sql:SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{User-Name}' ORDER BY id" >= 1)
Thu Feb 27 20:06:01 2014 : Debug: %{sql:SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{User-Name}' ORDER BY id
Thu Feb 27 20:06:01 2014 : Debug: Parsed xlat tree:
Thu Feb 27 20:06:01 2014 : Debug: xlat: sql
Thu Feb 27 20:06:01 2014 : Debug: {
Thu Feb 27 20:06:01 2014 : Debug:       literal: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = ''
Thu Feb 27 20:06:01 2014 : Debug:       attribute: User-Name
Thu Feb 27 20:06:01 2014 : Debug:       {
Thu Feb 27 20:06:01 2014 : Debug:               ref  2
Thu Feb 27 20:06:01 2014 : Debug:               list 1
Thu Feb 27 20:06:01 2014 : Debug:               tag -128
Thu Feb 27 20:06:01 2014 : Debug:       }
Thu Feb 27 20:06:01 2014 : Debug:       literal: '' ORDER BY id'
Thu Feb 27 20:06:01 2014 : Debug: }
Thu Feb 27 20:06:01 2014 : Debug: %{User-Name}
Thu Feb 27 20:06:01 2014 : Debug: Parsed xlat tree:
Thu Feb 27 20:06:01 2014 : Debug: attribute: User-Name
Thu Feb 27 20:06:01 2014 : Debug: {
Thu Feb 27 20:06:01 2014 : Debug:       ref  2
Thu Feb 27 20:06:01 2014 : Debug:       list 1
Thu Feb 27 20:06:01 2014 : Debug:       tag -128
Thu Feb 27 20:06:01 2014 : Debug: }
Thu Feb 27 20:06:01 2014 : Debug: (0)   expand: "%{User-Name}" -> 'fredf'
Thu Feb 27 20:06:01 2014 : Debug: (0) SQL-User-Name set to 'fredf'
Thu Feb 27 20:06:01 2014 : Debug: rlm_sql (sql): Reserved connection (4)
Thu Feb 27 20:06:01 2014 : Debug: /var/log/sqllog.sql
Thu Feb 27 20:06:01 2014 : Debug: Parsed xlat tree:
Thu Feb 27 20:06:01 2014 : Debug: literal: '/var/log/sqllog.sql'
Thu Feb 27 20:06:01 2014 : Debug: (0)   expand: "/var/log/sqllog.sql" -> '/var/log/sqllog.sql'
Thu Feb 27 20:06:01 2014 : Debug: rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'fredf' ORDER BY id'
Thu Feb 27 20:06:01 2014 : Debug: (0) SQL query returned no results ------> why ? If you do this query inside mysql - i got result :(
Thu Feb 27 20:06:01 2014 : Debug: rlm_sql (sql): Released connection (4)
Thu Feb 27 20:06:01 2014 : Info: rlm_sql (sql): Closing connection (0): Too many free connections (5 > 3)
Thu Feb 27 20:06:01 2014 : Debug: (0)   expand: "%{sql:SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{User-Name}' ORDER BY id" -> ''
Thu Feb 27 20:06:01 2014 : Debug: (0)   ? if ("%{sql:SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{User-Name}' ORDER BY id" >= 1) -> FALSE
Thu Feb 27 20:06:01 2014 : Debug: (0)   else else {
Thu Feb 27 20:06:01 2014 : Debug: (0)   modsingle[authorize]: calling reject (rlm_always) for request 0
Thu Feb 27 20:06:01 2014 : Debug: (0)   modsingle[authorize]: returned from reject (rlm_always) for request 0
Thu Feb 27 20:06:01 2014 : Debug: (0)    [reject] = reject
Thu Feb 27 20:06:01 2014 : Debug: (0)   } # else else = reject
Thu Feb 27 20:06:01 2014 : Debug: (0)  } #  authorize = reject
Thu Feb 27 20:06:01 2014 : Debug: (0) Using Post-Auth-Type Reject
Thu Feb 27 20:06:01 2014 : Debug: (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Thu Feb 27 20:06:01 2014 : Debug: (0)  Post-Auth-Type REJECT {
Thu Feb 27 20:06:01 2014 : Debug: (0)   modsingle[post-auth]: calling sql (rlm_sql) for request 0
Thu Feb 27 20:06:01 2014 : Debug: .query
Thu Feb 27 20:06:01 2014 : Debug: Parsed xlat tree:
Thu Feb 27 20:06:01 2014 : Debug: literal: '.query'
Thu Feb 27 20:06:01 2014 : Debug: (0) sql :     expand: ".query" -> '.query'
Thu Feb 27 20:06:01 2014 : Debug: (0) sql : Using query template 'query'
Thu Feb 27 20:06:01 2014 : Debug: rlm_sql (sql): Reserved connection (4)
Thu Feb 27 20:06:01 2014 : Debug: %{User-Name}
Thu Feb 27 20:06:01 2014 : Debug: Parsed xlat tree:
Thu Feb 27 20:06:01 2014 : Debug: attribute: User-Name
Thu Feb 27 20:06:01 2014 : Debug: {
Thu Feb 27 20:06:01 2014 : Debug:       ref  2
Thu Feb 27 20:06:01 2014 : Debug:       list 1
Thu Feb 27 20:06:01 2014 : Debug:       tag -128
Thu Feb 27 20:06:01 2014 : Debug: }
Thu Feb 27 20:06:01 2014 : Debug: (0) sql :     expand: "%{User-Name}" -> 'fredf'
Thu Feb 27 20:06:01 2014 : Debug: (0) sql : SQL-User-Name set to 'fredf'
Thu Feb 27 20:06:01 2014 : Debug: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
Thu Feb 27 20:06:01 2014 : Debug: Parsed xlat tree:
Thu Feb 27 20:06:01 2014 : Debug: literal: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( ''
Thu Feb 27 20:06:01 2014 : Debug: attribute: SQL-User-Name
Thu Feb 27 20:06:01 2014 : Debug: {
Thu Feb 27 20:06:01 2014 : Debug:       ref  2
Thu Feb 27 20:06:01 2014 : Debug:       list 1
Thu Feb 27 20:06:01 2014 : Debug:       tag -128
Thu Feb 27 20:06:01 2014 : Debug: }
Thu Feb 27 20:06:01 2014 : Debug: literal: '', ''
Thu Feb 27 20:06:01 2014 : Debug: if {
Thu Feb 27 20:06:01 2014 : Debug:       attribute: User-Password
Thu Feb 27 20:06:01 2014 : Debug:       {
Thu Feb 27 20:06:01 2014 : Debug:               ref  2
Thu Feb 27 20:06:01 2014 : Debug:               list 1
Thu Feb 27 20:06:01 2014 : Debug:               tag -128
Thu Feb 27 20:06:01 2014 : Debug:       }
Thu Feb 27 20:06:01 2014 : Debug: }
Thu Feb 27 20:06:01 2014 : Debug: else {
Thu Feb 27 20:06:01 2014 : Debug:       attribute: CHAP-Password
Thu Feb 27 20:06:01 2014 : Debug:       {
Thu Feb 27 20:06:01 2014 : Debug:               ref  2
Thu Feb 27 20:06:01 2014 : Debug:               list 1
Thu Feb 27 20:06:01 2014 : Debug:               tag -128
Thu Feb 27 20:06:01 2014 : Debug:       }
Thu Feb 27 20:06:01 2014 : Debug: }
Thu Feb 27 20:06:01 2014 : Debug: literal: '', ''
Thu Feb 27 20:06:01 2014 : Debug: attribute: Packet-Type
Thu Feb 27 20:06:01 2014 : Debug: {
Thu Feb 27 20:06:01 2014 : Debug:       ref  2
Thu Feb 27 20:06:01 2014 : Debug:       list 2
Thu Feb 27 20:06:01 2014 : Debug:       tag -128
Thu Feb 27 20:06:01 2014 : Debug: }
Thu Feb 27 20:06:01 2014 : Debug: literal: '', ''
Thu Feb 27 20:06:01 2014 : Debug: literal (with %): 'S'
Thu Feb 27 20:06:01 2014 : Debug: literal: '')'
Thu Feb 27 20:06:01 2014 : Debug: (0) sql :     expand: "INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')" -> 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'fredf', 'wilma', 'Access-Reject', '2014-02-27 20:06:01')'
Thu Feb 27 20:06:01 2014 : Debug: rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'fredf', 'wilma', 'Access-Reject', '2014-02-27 20:06:01')'
Thu Feb 27 20:06:01 2014 : Debug: rlm_sql (sql): Released connection (4)
Thu Feb 27 20:06:01 2014 : Debug: (0)   modsingle[post-auth]: returned from sql (rlm_sql) for request 0
Thu Feb 27 20:06:01 2014 : Debug: (0)   [-sql] = ok
Thu Feb 27 20:06:01 2014 : Debug: (0)   modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 0
Thu Feb 27 20:06:01 2014 : Debug: %{User-Name}
Thu Feb 27 20:06:01 2014 : Debug: Parsed xlat tree:
Thu Feb 27 20:06:01 2014 : Debug: attribute: User-Name
Thu Feb 27 20:06:01 2014 : Debug: {
Thu Feb 27 20:06:01 2014 : Debug:       ref  2
Thu Feb 27 20:06:01 2014 : Debug:       list 1
Thu Feb 27 20:06:01 2014 : Debug:       tag -128
Thu Feb 27 20:06:01 2014 : Debug: }
Thu Feb 27 20:06:01 2014 : Debug: (0) attr_filter.access_reject :       expand: "%{User-Name}" -> 'fredf'
Thu Feb 27 20:06:01 2014 : Debug: (0) attr_filter.access_reject : Matched entry DEFAULT at line 11
Thu Feb 27 20:06:01 2014 : Debug: (0)   modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 0
Thu Feb 27 20:06:01 2014 : Debug: (0)   [attr_filter.access_reject] = updated
Thu Feb 27 20:06:01 2014 : Debug: (0)   modsingle[post-auth]: calling eap (rlm_eap) for request 0
Thu Feb 27 20:06:01 2014 : Debug: (0) eap : Request didn't contain an EAP-Message, not inserting EAP-Failure
Thu Feb 27 20:06:01 2014 : Debug: (0)   modsingle[post-auth]: returned from eap (rlm_eap) for request 0
Thu Feb 27 20:06:01 2014 : Debug: (0)   [eap] = noop
Thu Feb 27 20:06:01 2014 : Debug: (0)   remove_reply_message_if_eap remove_reply_message_if_eap {
Thu Feb 27 20:06:01 2014 : Debug: (0)    ? if (reply:EAP-Message && reply:Reply-Message)
Thu Feb 27 20:06:01 2014 : Debug: (0)    ? if (reply:EAP-Message && reply:Reply-Message)  -> FALSE
Thu Feb 27 20:06:01 2014 : Debug: (0)    else else {
Thu Feb 27 20:06:01 2014 : Debug: (0)   modsingle[post-auth]: calling noop (rlm_always) for request 0
Thu Feb 27 20:06:01 2014 : Debug: (0)   modsingle[post-auth]: returned from noop (rlm_always) for request 0
Thu Feb 27 20:06:01 2014 : Debug: (0)     [noop] = noop
Thu Feb 27 20:06:01 2014 : Debug: (0)    } # else else = noop
Thu Feb 27 20:06:01 2014 : Debug: (0)   } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
Thu Feb 27 20:06:01 2014 : Debug: (0)  } # Post-Auth-Type REJECT = updated
Thu Feb 27 20:06:01 2014 : Debug: (0) Finished request 0.
Thu Feb 27 20:06:01 2014 : Debug: Waking up in 0.3 seconds.
Thu Feb 27 20:06:01 2014 : Debug: Waking up in 0.5 seconds.
Thu Feb 27 20:06:02 2014 : Debug: (0) Sending delayed reject
Sending Access-Reject of id 9 from 127.0.0.1 port 1812 to 127.0.0.1 port 52606
Thu Feb 27 20:06:02 2014 : Debug: Waking up in 4.9 seconds.
Thu Feb 27 20:06:07 2014 : Debug: (0) Cleaning up request packet ID 9 with timestamp +53
Thu Feb 27 20:06:07 2014 : Info: Ready to process requests.

sqllog.sql
SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'fredf' ORDER BY id;

Please help me ... Thank you

Hello, please help me with SQL integration

For Sinton