Freeradius - Client not authenticated

[Federico Olivieri]

Hi All,

That's my first e-mail and freeradius installation. Sorry if I didn't give
you all info required or if my e-mail is wrong.

I just finished to set up freeradius with MySQL and daloRADIUS on my Raspi.
Exciting!!! (I followed this link -
http://www.binaryheartbeat.net/2013/12/raspberry-pi-based-freeradius-server.html
)

I added a user via daloRADIUS, I can see the entry in MySQL but I m not
able to authenticate my wifi device. I enabled the debug mode with
freeradius-XXX command and I got as following:

rad_recv: Access-Request packet from host 192.168.0.5 port 48785, id=0,
length=121
        User-Name = "wiko"
        NAS-IP-Address = 192.168.0.5
        Called-Station-Id = "54a0505814c4"
        Calling-Station-Id = "00738da980df"
        NAS-Identifier = "54a0505814c4"
        NAS-Port = 54
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        EAP-Message = 0x020000090177696b6f
        Message-Authenticator = 0x3fea51568bbe9b1d3e4803bed98db11b
Fri Sep 18 21:57:15 2015 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/default
Fri Sep 18 21:57:15 2015 : Info: +- entering group authorize {...}
Fri Sep 18 21:57:15 2015 : Info: ++[preprocess] returns ok
Fri Sep 18 21:57:15 2015 : Info: ++[chap] returns noop
Fri Sep 18 21:57:15 2015 : Info: ++[mschap] returns noop
Fri Sep 18 21:57:15 2015 : Info: ++[digest] returns noop
Fri Sep 18 21:57:15 2015 : Info: [suffix] No '@' in User-Name = "wiko",
looking up realm NULL
Fri Sep 18 21:57:15 2015 : Info: [suffix] No such realm "NULL"
Fri Sep 18 21:57:15 2015 : Info: ++[suffix] returns noop
Fri Sep 18 21:57:15 2015 : Info: [eap] EAP packet type response id 0 length
9
Fri Sep 18 21:57:15 2015 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Fri Sep 18 21:57:15 2015 : Info: ++[eap] returns updated
Fri Sep 18 21:57:15 2015 : Info: ++[files] returns noop
Fri Sep 18 21:57:15 2015 : Info: [sql]  expand: %{User-Name} -> wiko
Fri Sep 18 21:57:15 2015 : Info: [sql] sql_set_user escaped user --> 'wiko'
Fri Sep 18 21:57:15 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 2
Fri Sep 18 21:57:15 2015 : Info: [sql]  expand: SELECT id, username,
attribute, value, op           FROM radcheck           WHERE username =
'%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, attribute,
value, op           FROM radcheck           WHERE username = 'wiko'
  ORDER BY id
Fri Sep 18 21:57:15 2015 : Info: [sql] User found in radcheck table
Fri Sep 18 21:57:15 2015 : Info: [sql]  expand: SELECT id, username,
attribute, value, op           FROM radreply           WHERE username =
'%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, attribute,
value, op           FROM radreply           WHERE username = 'wiko'
  ORDER BY id
Fri Sep 18 21:57:15 2015 : Info: [sql]  expand: SELECT groupname
FROM radusergroup           WHERE username = '%{SQL-User-Name}'
ORDER BY priority -> SELECT groupname           FROM radusergroup
WHERE username = 'wiko'           ORDER BY priority
Fri Sep 18 21:57:15 2015 : Info: [sql]  expand: SELECT id, groupname,
attribute,           Value, op           FROM radgroupcheck           WHERE
groupname = '%{Sql-Group}'           ORDER BY id -> SELECT id, groupname,
attribute,           Value, op           FROM radgroupcheck           WHERE
groupname = 'WiFi_Users'           ORDER BY id
Fri Sep 18 21:57:15 2015 : Info: [sql] User found in group WiFi_Users
Fri Sep 18 21:57:15 2015 : Info: [sql]  expand: SELECT id, groupname,
attribute,           value, op           FROM radgroupreply           WHERE
groupname = '%{Sql-Group}'           ORDER BY id -> SELECT id, groupname,
attribute,           value, op           FROM radgroupreply           WHERE
groupname = 'WiFi_Users'           ORDER BY id
Fri Sep 18 21:57:15 2015 : Debug: rlm_sql (sql): Released sql socket id: 2
Fri Sep 18 21:57:15 2015 : Info: ++[sql] returns ok
Fri Sep 18 21:57:15 2015 : Info: ++[expiration] returns noop
Fri Sep 18 21:57:15 2015 : Info: ++[logintime] returns noop
Fri Sep 18 21:57:15 2015 : Info: [pap] WARNING: Auth-Type already set.  Not
setting to PAP
Fri Sep 18 21:57:15 2015 : Info: ++[pap] returns noop
Fri Sep 18 21:57:15 2015 : Info: Found Auth-Type = Accept
Fri Sep 18 21:57:15 2015 : Info: Auth-Type = Accept, accepting the user
Fri Sep 18 21:57:15 2015 : Info: # Executing section post-auth from file
/etc/freeradius/sites-enabled/default
Fri Sep 18 21:57:15 2015 : Info: +- entering group post-auth {...}
Fri Sep 18 21:57:15 2015 : Info: [sql]  expand: %{User-Name} -> wiko
Fri Sep 18 21:57:15 2015 : Info: [sql] sql_set_user escaped user --> 'wiko'
Fri Sep 18 21:57:15 2015 : Info: [sql]  expand: %{User-Password} ->
Fri Sep 18 21:57:15 2015 : Info: [sql]  ... expanding second conditional
Fri Sep 18 21:57:15 2015 : Info: [sql]  expand: %{Chap-Password} ->
Fri Sep 18 21:57:15 2015 : Info: [sql]  expand: INSERT INTO radpostauth
                      (username, pass, reply, authdate)
      VALUES (                           '%{User-Name}',
        '%{%{User-Password}:-%{Chap-Password}}',
'%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth
        (username, pass, reply, authdate)                           VALUES
(                           'wiko',                           '',
                'Access-Accept', '2015-09-18 21:57:15')
Fri Sep 18 21:57:15 2015 : Debug: rlm_sql (sql) in sql_postauth: query is
INSERT INTO radpostauth                           (username, pass, reply,
authdate)                           VALUES (
'wiko',                           '',
'Access-Accept', '2015-09-18 21:57:15')
Fri Sep 18 21:57:15 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 1
Fri Sep 18 21:57:15 2015 : Debug: rlm_sql (sql): Released sql socket id: 1
Fri Sep 18 21:57:15 2015 : Info: ++[sql] returns ok
Fri Sep 18 21:57:15 2015 : Info: ++[exec] returns noop
Sending Access-Accept of id 0 to 192.168.0.5 port 48785
Fri Sep 18 21:57:15 2015 : Info: Finished request 1.
Fri Sep 18 21:57:15 2015 : Debug: Going to the next request
Fri Sep 18 21:57:15 2015 : Debug: Waking up in 4.9 seconds.
Fri Sep 18 21:57:20 2015 : Info: Cleaning up request 1 ID 0 with timestamp
+95
Fri Sep 18 21:57:20 2015 : Info: Ready to process requests.

I don't understand the majority of those messages. Can someone help me to
understand where is the error?

Thanks

Federico