Sql log
Lucas Diaz
lucasdiaz at eternet.cc
Wed Jan 27 14:02:58 CET 2016
Sorry about that.
I launched the server with "/usr/local/sbin/radiusd -Xxxxxxxxxxxxxx",
and below is the output for a wireless 802.11 authentication.
Thanks.
Wed Jan 27 09:59:25 2016 : Debug: (2) Received Access-Request Id 234
from 10.150.105.215:45083 to 172.31.255.213:1812 length 160
Wed Jan 27 09:59:25 2016 : Debug: (2) Service-Type = Framed-User
Wed Jan 27 09:59:25 2016 : Debug: (2) NAS-Port-Id = "wlan1"
Wed Jan 27 09:59:25 2016 : Debug: (2) NAS-Port-Type = Wireless-802.11
Wed Jan 27 09:59:25 2016 : Debug: (2) User-Name = "D4CA6D804F87"
Wed Jan 27 09:59:25 2016 : Debug: (2) Calling-Station-Id =
"D4-CA-6D-80-4F-87"
Wed Jan 27 09:59:25 2016 : Debug: (2) Called-Station-Id =
"4C-5E-0C-66-CF-33:costaneray15E"
Wed Jan 27 09:59:25 2016 : Debug: (2) User-Password = "D4CA6D804F87"
Wed Jan 27 09:59:25 2016 : Debug: (2) NAS-Identifier = "AP Costanera y
Calle 15 Norte"
Wed Jan 27 09:59:25 2016 : Debug: (2) NAS-IP-Address = 10.150.105.215
Wed Jan 27 09:59:25 2016 : Debug: (2) session-state: No State attribute
Wed Jan 27 09:59:25 2016 : Debug: (2) # Executing section authorize from
file /usr/local/etc/raddb/sites-enabled/default
Wed Jan 27 09:59:25 2016 : Debug: (2) authorize {
Wed Jan 27 09:59:25 2016 : Debug: (2) policy filter_username {
Wed Jan 27 09:59:25 2016 : Debug: (2) if (User-Name !=
"%{toupper:%{User-Name}}") {
Wed Jan 27 09:59:25 2016 : Debug: (2) EXPAND TMPL XLAT STRUCT
Wed Jan 27 09:59:25 2016 : Debug: (2) EXPAND %{toupper:%{User-Name}}
Wed Jan 27 09:59:25 2016 : Debug: (2) --> D4CA6D804F87
Wed Jan 27 09:59:25 2016 : Debug: (2) if (User-Name !=
"%{toupper:%{User-Name}}") -> FALSE
Wed Jan 27 09:59:25 2016 : Debug: (2) if (User-Name =~ / /) {
Wed Jan 27 09:59:25 2016 : Debug: No matches
Wed Jan 27 09:59:25 2016 : Debug: (2) if (User-Name =~ / /) -> FALSE
Wed Jan 27 09:59:25 2016 : Debug: (2) if (User-Name =~ /@.*@/ ) {
Wed Jan 27 09:59:25 2016 : Debug: No matches
Wed Jan 27 09:59:25 2016 : Debug: (2) if (User-Name =~ /@.*@/ )
-> FALSE
Wed Jan 27 09:59:25 2016 : Debug: (2) if (User-Name =~ /\\.\\./ ) {
Wed Jan 27 09:59:25 2016 : Debug: No matches
Wed Jan 27 09:59:25 2016 : Debug: (2) if (User-Name =~ /\\.\\./ )
-> FALSE
Wed Jan 27 09:59:25 2016 : Debug: (2) if ((User-Name =~ /@/) &&
(User-Name !~ /@(.+)\\.(.+)$/)) {
Wed Jan 27 09:59:25 2016 : Debug: No matches
Wed Jan 27 09:59:25 2016 : Debug: (2) if ((User-Name =~ /@/) &&
(User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE
Wed Jan 27 09:59:25 2016 : Debug: (2) if (User-Name =~ /\\.$/) {
Wed Jan 27 09:59:25 2016 : Debug: No matches
Wed Jan 27 09:59:25 2016 : Debug: (2) if (User-Name =~ /\\.$/)
-> FALSE
Wed Jan 27 09:59:25 2016 : Debug: (2) if (User-Name =~ /@\\./) {
Wed Jan 27 09:59:25 2016 : Debug: No matches
Wed Jan 27 09:59:25 2016 : Debug: (2) if (User-Name =~ /@\\./)
-> FALSE
Wed Jan 27 09:59:25 2016 : Debug: (2) } # policy filter_username =
notfound
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: returned
from preprocess (rlm_preprocess) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) [preprocess] = ok
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: calling
chap (rlm_chap) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: returned
from chap (rlm_chap) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) [chap] = noop
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: calling
mschap (rlm_mschap) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: returned
from mschap (rlm_mschap) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) [mschap] = noop
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: calling
digest (rlm_digest) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: returned
from digest (rlm_digest) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) [digest] = noop
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: calling
suffix (rlm_realm) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) suffix: Checking for suffix after "@"
Wed Jan 27 09:59:25 2016 : Debug: (2) suffix: No '@' in User-Name =
"D4CA6D804F87", looking up realm NULL
Wed Jan 27 09:59:25 2016 : Debug: (2) suffix: No such realm "NULL"
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: returned
from suffix (rlm_realm) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) [suffix] = noop
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: calling
eap (rlm_eap) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) eap: No EAP-Message, not doing EAP
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: returned
from eap (rlm_eap) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) [eap] = noop
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: calling
files (rlm_files) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: returned
from files (rlm_files) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) [files] = noop
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: calling
sql (rlm_sql) for request 2
Wed Jan 27 09:59:25 2016 : Debug: %{User-Name}
Wed Jan 27 09:59:25 2016 : Debug: Parsed xlat tree:
Wed Jan 27 09:59:25 2016 : Debug: attribute --> User-Name
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: EXPAND %{User-Name}
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: --> D4CA6D804F87
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: SQL-User-Name set to
'D4CA6D804F87'
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: FROM 1 TO 10 MAX 11
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: Examining SQL-User-Name
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: APPENDING SQL-User-Name
FROM 0 TO 10
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: TO in 10 out 10
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: to[0] = Service-Type
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: to[1] = NAS-Port-Id
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: to[2] = NAS-Port-Type
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: to[3] = User-Name
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: to[4] = Calling-Station-Id
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: to[5] = Called-Station-Id
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: to[6] = User-Password
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: to[7] = NAS-Identifier
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: to[8] = NAS-IP-Address
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: to[9] = Event-Timestamp
Wed Jan 27 09:59:25 2016 : Debug: rlm_sql (sql): Reserved connection (5)
Wed Jan 27 09:59:25 2016 : Debug: SELECT 0 as id, username, attribute,
val, op FROM radius_check('%{Framed-IP-Address}',
'%{SQL-User-Name}', '%{NAS-IP-Address}', '%{NAS-Port-Id}',
'%{Service-Type}', '%{NAS-Port-Type}') ORDER BY id
Wed Jan 27 09:59:25 2016 : Debug: Parsed xlat tree:
Wed Jan 27 09:59:25 2016 : Debug: literal --> SELECT 0 as id, username,
attribute, val, op FROM radius_check('
Wed Jan 27 09:59:25 2016 : Debug: attribute --> Framed-IP-Address
Wed Jan 27 09:59:25 2016 : Debug: literal --> ', '
Wed Jan 27 09:59:25 2016 : Debug: attribute --> SQL-User-Name
Wed Jan 27 09:59:25 2016 : Debug: literal --> ', '
Wed Jan 27 09:59:25 2016 : Debug: attribute --> NAS-IP-Address
Wed Jan 27 09:59:25 2016 : Debug: literal --> ', '
Wed Jan 27 09:59:25 2016 : Debug: attribute --> NAS-Port-Id
Wed Jan 27 09:59:25 2016 : Debug: literal --> ', '
Wed Jan 27 09:59:25 2016 : Debug: attribute --> Service-Type
Wed Jan 27 09:59:25 2016 : Debug: literal --> ', '
Wed Jan 27 09:59:25 2016 : Debug: attribute --> NAS-Port-Type
Wed Jan 27 09:59:25 2016 : Debug: literal --> ') ORDER BY id
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: EXPAND SELECT 0 as id,
username, attribute, val, op FROM
radius_check('%{Framed-IP-Address}', '%{SQL-User-Name}',
'%{NAS-IP-Address}', '%{NAS-Port-Id}', '%{Service-Type}',
'%{NAS-Port-Type}') ORDER BY id
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: --> SELECT 0 as id,
username, attribute, val, op FROM radius_check('',
'D4CA6D804F87', '10.150.105.215', 'wlan1', 'Framed-User',
'Wireless-802.11') ORDER BY id
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: Executing select query:
SELECT 0 as id, username, attribute, val, op FROM
radius_check('', 'D4CA6D804F87', '10.150.105.215', 'wlan1',
'Framed-User', 'Wireless-802.11') ORDER BY id
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: User found in radcheck table
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: Conditional check items
matched, merging assignment check items
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: Cleartext-Password :=
"D4CA6D804F87"
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: FROM 1 TO 0 MAX 1
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: Examining Cleartext-Password
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: APPENDING
Cleartext-Password FROM 0 TO 0
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: TO in 0 out 0
Wed Jan 27 09:59:25 2016 : Debug: SELECT 0 as id, username, attribute,
val, op FROM radius_reply('%{Framed-IP-Address}',
'%{SQL-User-Name}', '%{NAS-IP-Address}', '%{NAS-Port-Id}',
'%{Service-Type}', '%{NAS-Port-Type}') ORDER BY id
Wed Jan 27 09:59:25 2016 : Debug: Parsed xlat tree:
Wed Jan 27 09:59:25 2016 : Debug: literal --> SELECT 0 as id, username,
attribute, val, op FROM radius_reply('
Wed Jan 27 09:59:25 2016 : Debug: attribute --> Framed-IP-Address
Wed Jan 27 09:59:25 2016 : Debug: literal --> ', '
Wed Jan 27 09:59:25 2016 : Debug: attribute --> SQL-User-Name
Wed Jan 27 09:59:25 2016 : Debug: literal --> ', '
Wed Jan 27 09:59:25 2016 : Debug: attribute --> NAS-IP-Address
Wed Jan 27 09:59:25 2016 : Debug: literal --> ', '
Wed Jan 27 09:59:25 2016 : Debug: attribute --> NAS-Port-Id
Wed Jan 27 09:59:25 2016 : Debug: literal --> ', '
Wed Jan 27 09:59:25 2016 : Debug: attribute --> Service-Type
Wed Jan 27 09:59:25 2016 : Debug: literal --> ', '
Wed Jan 27 09:59:25 2016 : Debug: attribute --> NAS-Port-Type
Wed Jan 27 09:59:25 2016 : Debug: literal --> ') ORDER BY id
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: EXPAND SELECT 0 as id,
username, attribute, val, op FROM
radius_reply('%{Framed-IP-Address}', '%{SQL-User-Name}',
'%{NAS-IP-Address}', '%{NAS-Port-Id}', '%{Service-Type}',
'%{NAS-Port-Type}') ORDER BY id
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: --> SELECT 0 as id,
username, attribute, val, op FROM radius_reply('',
'D4CA6D804F87', '10.150.105.215', 'wlan1', 'Framed-User',
'Wireless-802.11') ORDER BY id
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: Executing select query:
SELECT 0 as id, username, attribute, val, op FROM
radius_reply('', 'D4CA6D804F87', '10.150.105.215', 'wlan1',
'Framed-User', 'Wireless-802.11') ORDER BY id
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: User found in radreply table,
merging reply items
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: Session-Timeout = 100000
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: FROM 1 TO 0 MAX 1
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: Examining Session-Timeout
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: APPENDING Session-Timeout
FROM 0 TO 0
Wed Jan 27 09:59:25 2016 : Debug: (2) sql: ::: TO in 0 out 0
Wed Jan 27 09:59:25 2016 : Debug: rlm_sql (sql): Released connection (5)
Wed Jan 27 09:59:25 2016 : Info: rlm_sql (sql): Closing connection (6),
from 12 unused connections
Wed Jan 27 09:59:25 2016 : Debug: rlm_sql_firebird: socket destructor
called, closing socket
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: returned
from sql (rlm_sql) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) [sql] = ok
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: calling
expiration (rlm_expiration) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: returned
from expiration (rlm_expiration) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) [expiration] = noop
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: calling
logintime (rlm_logintime) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: returned
from logintime (rlm_logintime) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) [logintime] = noop
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: calling
pap (rlm_pap) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authorize]: returned
from pap (rlm_pap) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) [pap] = updated
Wed Jan 27 09:59:25 2016 : Debug: (2) } # authorize = updated
Wed Jan 27 09:59:25 2016 : Debug: (2) Found Auth-Type = PAP
Wed Jan 27 09:59:25 2016 : Debug: (2) # Executing group from file
/usr/local/etc/raddb/sites-enabled/default
Wed Jan 27 09:59:25 2016 : Debug: (2) Auth-Type PAP {
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authenticate]:
calling pap (rlm_pap) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) pap: Login attempt with password
"D4CA6D804F87" (12)
Wed Jan 27 09:59:25 2016 : Debug: (2) pap: Comparing with "known good"
Cleartext-Password "D4CA6D804F87" (12)
Wed Jan 27 09:59:25 2016 : Debug: (2) pap: User authenticated successfully
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[authenticate]:
returned from pap (rlm_pap) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) [pap] = ok
Wed Jan 27 09:59:25 2016 : Debug: (2) } # Auth-Type PAP = ok
Wed Jan 27 09:59:25 2016 : Debug: (2) # Executing section post-auth from
file /usr/local/etc/raddb/sites-enabled/default
Wed Jan 27 09:59:25 2016 : Debug: (2) post-auth {
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[post-auth]: calling
exec (rlm_exec) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[post-auth]: returned
from exec (rlm_exec) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) [exec] = noop
Wed Jan 27 09:59:25 2016 : Debug: (2) policy
remove_reply_message_if_eap {
Wed Jan 27 09:59:25 2016 : Debug: (2) if (reply:EAP-Message &&
reply:Reply-Message) {
Wed Jan 27 09:59:25 2016 : Debug: (2) if (reply:EAP-Message &&
reply:Reply-Message) -> FALSE
Wed Jan 27 09:59:25 2016 : Debug: (2) else {
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[post-auth]:
calling noop (rlm_always) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) modsingle[post-auth]:
returned from noop (rlm_always) for request 2
Wed Jan 27 09:59:25 2016 : Debug: (2) [noop] = noop
Wed Jan 27 09:59:25 2016 : Debug: (2) } # else = noop
Wed Jan 27 09:59:25 2016 : Debug: (2) } # policy
remove_reply_message_if_eap = noop
Wed Jan 27 09:59:25 2016 : Debug: (2) } # post-auth = noop
Wed Jan 27 09:59:25 2016 : Auth: (2) Login OK: [D4CA6D804F87] (from
client default port 0 cli D4-CA-6D-80-4F-87)
Wed Jan 27 09:59:25 2016 : Debug: (2) Sent Access-Accept Id 234 from
172.31.255.213:1812 to 10.150.105.215:45083 length 0
Wed Jan 27 09:59:25 2016 : Debug: (2) Session-Timeout = 100000
Wed Jan 27 09:59:25 2016 : Debug: (2) Finished request
Wed Jan 27 09:59:25 2016 : Debug: Waking up in 2.9 seconds.
Wed Jan 27 09:59:28 2016 : Debug: (2) Cleaning up request packet ID 234
with timestamp +139
Wed Jan 27 09:59:28 2016 : Info: Ready to process requests
Wed Jan 27 09:59:31 2016 : Info: Ready to process requests
*LUCAS DIAZ | DPTO. REDES*
_______________________________________________________
Istilart 255 | Tel.: 02983 513040
C.P. B7500EGE | Tres Arroyos | Bs As | Argentina *
*www.eternet.cc <http://www.eternet.cc/> | *ETERNET SISTEMAS *
On 01/27/2016 09:53 AM, A.L.M.Buxey at lboro.ac.uk wrote:
> Hi,
>
> without sharing I cannot share a solution.
>
>
> alan
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
More information about the Freeradius-Users
mailing list