rad_recv: Access-Request packet from host 192.168.1.143 port 49154, id=0, length=85
   User-Name = "admin"
   User-Password = "gfhjkm"
   Cisco-AVPair = "shell:priv-lvl=1"
   NAS-IP-Address = 192.168.1.143
   Acct-Session-Id = "0500001A"
Tue Dec  6 00:44:11 2011 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/test
Tue Dec  6 00:44:11 2011 : Info: +- entering group authorize {...}
Tue Dec  6 00:44:11 2011 : Info: ++[preprocess] returns ok
Tue Dec  6 00:44:11 2011 : Info: ++[chap] returns noop
Tue Dec  6 00:44:11 2011 : Info: ++[mschap] returns noop
Tue Dec  6 00:44:11 2011 : Info: [suffix] No '@' in User-Name = "admin", looking up realm NULL
Tue Dec  6 00:44:11 2011 : Info: [suffix] No such realm "NULL"
Tue Dec  6 00:44:11 2011 : Info: ++[suffix] returns noop
Tue Dec  6 00:44:11 2011 : Info: [eap] No EAP-Message, not doing EAP
Tue Dec  6 00:44:11 2011 : Info: ++[eap] returns noop
Tue Dec  6 00:44:11 2011 : Info: ++[files] returns noop
Tue Dec  6 00:44:11 2011 : Info: [sql]    expand: %{User-Name} -> admin
Tue Dec  6 00:44:11 2011 : Info: [sql] sql_set_user escaped user --> 'admin'
Tue Dec  6 00:44:11 2011 : Debug: rlm_sql (sql): Reserving sql socket id: 3
Tue Dec  6 00:44:11 2011 : 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 = 'admin'           ORDER BY id
Tue Dec  6 00:44:11 2011 : Debug: WARNING: Found User-Password == "...".
Tue Dec  6 00:44:11 2011 : Debug: WARNING: Are you sure you don't mean Cleartext-Password?
Tue Dec  6 00:44:11 2011 : Debug: WARNING: See "man rlm_pap" for more information.
Tue Dec  6 00:44:11 2011 : Info: [sql] User found in radcheck table
Tue Dec  6 00:44:11 2011 : 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 = 'admin'           ORDER BY id
Tue Dec  6 00:44:11 2011 : Info: [sql]    expand: SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname           FROM radusergroup           WHERE username = 'admin'           ORDER BY priority
Tue Dec  6 00:44:11 2011 : Debug: rlm_sql (sql): Released sql socket id: 3
Tue Dec  6 00:44:11 2011 : Info: ++[sql] returns ok
Tue Dec  6 00:44:11 2011 : Info: ++[expiration] returns noop
Tue Dec  6 00:44:11 2011 : Info: ++[logintime] returns noop
Tue Dec  6 00:44:11 2011 : Info: ++[pap] returns updated
Tue Dec  6 00:44:11 2011 : Info: Found Auth-Type = PAP
Tue Dec  6 00:44:11 2011 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Dec  6 00:44:11 2011 : Info: !!!    Replacing User-Password in config items with Cleartext-Password.     !!!
Tue Dec  6 00:44:11 2011 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Dec  6 00:44:11 2011 : Info: !!! Please update your configuration so that the "known good"               !!!
Tue Dec  6 00:44:11 2011 : Info: !!! clear text password is in Cleartext-Password, and not in User-Password. !!!
Tue Dec  6 00:44:11 2011 : Info: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Dec  6 00:44:11 2011 : Info: # Executing group from file /etc/freeradius/sites-enabled/test
Tue Dec  6 00:44:11 2011 : Info: +- entering group PAP {...}
Tue Dec  6 00:44:11 2011 : Info: [pap] login attempt with password "gfhjkm"
Tue Dec  6 00:44:11 2011 : Info: [pap] Using clear text password "gfhjkm"
Tue Dec  6 00:44:11 2011 : Info: [pap] User authenticated successfully
Tue Dec  6 00:44:11 2011 : Info: ++[pap] returns ok
Tue Dec  6 00:44:11 2011 : Info: # Executing section post-auth from file /etc/freeradius/sites-enabled/test
Tue Dec  6 00:44:11 2011 : Info: +- entering group post-auth {...}
Tue Dec  6 00:44:11 2011 : Info: [sql]    expand: %{User-Name} -> admin
Tue Dec  6 00:44:11 2011 : Info: [sql] sql_set_user escaped user --> 'admin'
Tue Dec  6 00:44:11 2011 : Info: [sql]    expand: %{User-Password} -> gfhjkm
Tue Dec  6 00:44:11 2011 : 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 (                           'admin',                           'gfhjkm',                           'Access-Accept', '2011-12-06 00:44:11')
Tue Dec  6 00:44:11 2011 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           'admin',                           'gfhjkm',                           'Access-Accept', '2011-12-06 00:44:11')
Tue Dec  6 00:44:11 2011 : Debug: rlm_sql (sql): Reserving sql socket id: 2
Tue Dec  6 00:44:11 2011 : Debug: rlm_sql (sql): Released sql socket id: 2
Tue Dec  6 00:44:11 2011 : Info: ++[sql] returns ok
Tue Dec  6 00:44:11 2011 : Info: ++[exec] returns noop
Sending Access-Accept of id 0 to 192.168.1.143 port 49154
Tue Dec  6 00:44:11 2011 : Info: Finished request 0.
Tue Dec  6 00:44:11 2011 : Debug: Going to the next request
Tue Dec  6 00:44:11 2011 : Debug: Waking up in 4.9 seconds.
rad_recv: Accounting-Request packet from host 192.168.1.143 port 49154, id=0, length=85
   User-Name = "admin"
   NAS-IP-Address = 192.168.1.143
   Called-Station-Id = "192.168.1.143"
   Calling-Station-Id = "192.168.1.137"
   Acct-Status-Type = Start
   Acct-Session-Id = "0500001A"
   Acct-Authentic = RADIUS
Tue Dec  6 00:44:11 2011 : Info: # Executing section preacct from file /etc/freeradius/sites-enabled/test
Tue Dec  6 00:44:11 2011 : Info: +- entering group preacct {...}
Tue Dec  6 00:44:11 2011 : Info: ++[preprocess] returns ok
Tue Dec  6 00:44:11 2011 : Info: [acct_unique] WARNING: Attribute NAS-Port was not found in request, unique ID MAY be inconsistent
Tue Dec  6 00:44:11 2011 : Info: [acct_unique] Hashing ',Client-IP-Address = 192.168.1.143,NAS-IP-Address = 192.168.1.143,Acct-Session-Id = "0500001A",User-Name = "admin"'
Tue Dec  6 00:44:11 2011 : Info: [acct_unique] Acct-Unique-Session-ID = "4c3ff37b5983c355".
Tue Dec  6 00:44:11 2011 : Info: ++[acct_unique] returns ok
Tue Dec  6 00:44:11 2011 : Info: [suffix] No '@' in User-Name = "admin", looking up realm NULL
Tue Dec  6 00:44:11 2011 : Info: [suffix] No such realm "NULL"
Tue Dec  6 00:44:11 2011 : Info: ++[suffix] returns noop
Tue Dec  6 00:44:11 2011 : Info: ++[files] returns noop
Tue Dec  6 00:44:11 2011 : Info: # Executing section accounting from file /etc/freeradius/sites-enabled/test
Tue Dec  6 00:44:11 2011 : Info: +- entering group accounting {...}
Tue Dec  6 00:44:11 2011 : Info: [detail]    expand: /var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d -> /var/log/freeradius/radacct/192.168.1.143/detail-20111206
Tue Dec  6 00:44:11 2011 : Info: [detail] /var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /var/log/freeradius/radacct/192.168.1.143/detail-20111206
Tue Dec  6 00:44:11 2011 : Info: [detail]    expand: %t -> Tue Dec  6 00:44:11 2011
Tue Dec  6 00:44:11 2011 : Info: ++[detail] returns ok
Tue Dec  6 00:44:11 2011 : Info: [radutmp]    expand: /var/log/freeradius/radutmp -> /var/log/freeradius/radutmp
Tue Dec  6 00:44:11 2011 : Info: [radutmp]    expand: %{User-Name} -> admin
Tue Dec  6 00:44:11 2011 : Debug:   rlm_radutmp: No NAS-Port seen.  Cannot do anything.
Tue Dec  6 00:44:11 2011 : Debug:   rlm_radumtp: WARNING: checkrad will probably not work!
Tue Dec  6 00:44:11 2011 : Info: ++[radutmp] returns noop
Tue Dec  6 00:44:11 2011 : Info: [sql]    expand: %{User-Name} -> admin
Tue Dec  6 00:44:11 2011 : Info: [sql] sql_set_user escaped user --> 'admin'
Tue Dec  6 00:44:11 2011 : Info: [sql]    expand: %{Acct-Delay-Time} ->
Tue Dec  6 00:44:11 2011 : Info: [sql]    ... expanding second conditional
Tue Dec  6 00:44:11 2011 : Info: [sql]    expand:            INSERT INTO radacct             (acctsessionid,    acctuniqueid,     username,              realm,            nasipaddress,     nasportid,              nasporttype,      acctstarttime,    acctstoptime,              acctsessiontime,  acctauthentic,    connectinfo_start,              connectinfo_stop, acctinputoctets,  acctoutputoctets,              calledstationid,  callingstationid, acctterminatecause,              servicetype,      framedprotocol,   framedipaddress,              acctstartdelay,   acctstopdelay,    xascendsessionsvrkey)           VALUES             ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',              '%{SQL-User-Name}',              '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}',              '%{NAS-Port-Type}', '%S', NULL,              '0', '%{Acct-Authentic}', '%{Connect-Info}',              '', '0', '0',              '%{Called-Station-Id}', '%{Calling-Station-Id}', '',              '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}',     
Tue Dec  6 00:44:11 2011 : Debug: rlm_sql (sql): Reserving sql socket id: 1
Tue Dec  6 00:44:11 2011 : Debug: rlm_sql (sql): Released sql socket id: 1
Tue Dec  6 00:44:11 2011 : Info: ++[sql] returns ok
Tue Dec  6 00:44:11 2011 : Info: [attr_filter.accounting_response]    expand: %{User-Name} -> admin
Tue Dec  6 00:44:11 2011 : Debug:  attr_filter: Matched entry DEFAULT at line 12
Tue Dec  6 00:44:11 2011 : Info: ++[attr_filter.accounting_response] returns updated
Sending Accounting-Response of id 0 to 192.168.1.143 port 49154
Tue Dec  6 00:44:11 2011 : Info: Finished request 1.
Tue Dec  6 00:44:11 2011 : Info: Cleaning up request 1 ID 0 with timestamp +33
Tue Dec  6 00:44:11 2011 : Debug: Going to the next request
Tue Dec  6 00:44:11 2011 : Debug: Waking up in 4.9 seconds.
Tue Dec  6 00:44:16 2011 : Info: Cleaning up request 0 ID 0 with timestamp +33
Tue Dec  6 00:44:16 2011 : Info: Ready to process requests.

rad_recv: Access-Request packet from host 192.168.1.143 port 49154, id=0, length=89
   User-Name = "$enab15$"
   User-Password = "gfhjkm"
   Cisco-AVPair = "shell:priv-lvl=15"
   NAS-IP-Address = 192.168.1.143
   Acct-Session-Id = "0500001A"
Tue Dec  6 00:48:16 2011 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/test
Tue Dec  6 00:48:16 2011 : Info: +- entering group authorize {...}
Tue Dec  6 00:48:16 2011 : Info: ++[preprocess] returns ok
Tue Dec  6 00:48:16 2011 : Info: ++[chap] returns noop
Tue Dec  6 00:48:16 2011 : Info: ++[mschap] returns noop
Tue Dec  6 00:48:16 2011 : Info: [suffix] No '@' in User-Name = "$enab15$", looking up realm NULL
Tue Dec  6 00:48:16 2011 : Info: [suffix] No such realm "NULL"
Tue Dec  6 00:48:16 2011 : Info: ++[suffix] returns noop
Tue Dec  6 00:48:16 2011 : Info: [eap] No EAP-Message, not doing EAP
Tue Dec  6 00:48:16 2011 : Info: ++[eap] returns noop
Tue Dec  6 00:48:16 2011 : Info: ++[files] returns noop
Tue Dec  6 00:48:16 2011 : Info: [sql]    expand: %{User-Name} -> $enab15$
Tue Dec  6 00:48:16 2011 : Info: [sql] sql_set_user escaped user --> '$enab15$'
Tue Dec  6 00:48:16 2011 : Debug: rlm_sql (sql): Reserving sql socket id: 0
Tue Dec  6 00:48:16 2011 : 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 = '=24enab15=24'           ORDER BY id
Tue Dec  6 00:48:16 2011 : Info: [sql]    expand: SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname           FROM radusergroup           WHERE username = '=24enab15=24'           ORDER BY priority
Tue Dec  6 00:48:16 2011 : Debug: rlm_sql (sql): Released sql socket id: 0
Tue Dec  6 00:48:16 2011 : Info: [sql] User $enab15$ not found
Tue Dec  6 00:48:16 2011 : Info: ++[sql] returns notfound
Tue Dec  6 00:48:16 2011 : Info: ++[expiration] returns noop
Tue Dec  6 00:48:16 2011 : Info: ++[logintime] returns noop
Tue Dec  6 00:48:16 2011 : Info: [pap] WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Tue Dec  6 00:48:16 2011 : Info: ++[pap] returns noop
Tue Dec  6 00:48:16 2011 : Info: ERROR: No authenticate method (Auth-Type) found for the request: Rejecting the user
Tue Dec  6 00:48:16 2011 : Info: Failed to authenticate the user.
Tue Dec  6 00:48:16 2011 : Info: Using Post-Auth-Type Reject
Tue Dec  6 00:48:16 2011 : Info: # Executing group from file /etc/freeradius/sites-enabled/test
Tue Dec  6 00:48:16 2011 : Info: +- entering group REJECT {...}
Tue Dec  6 00:48:16 2011 : Info: [attr_filter.access_reject]    expand: %{User-Name} -> $enab15$
Tue Dec  6 00:48:16 2011 : Debug:  attr_filter: Matched entry DEFAULT at line 11
Tue Dec  6 00:48:16 2011 : Info: ++[attr_filter.access_reject] returns updated
Tue Dec  6 00:48:16 2011 : Info: Delaying reject of request 2 for 1 seconds
Tue Dec  6 00:48:16 2011 : Debug: Going to the next request
Tue Dec  6 00:48:16 2011 : Debug: Waking up in 0.9 seconds.
Tue Dec  6 00:48:17 2011 : Info: Sending delayed reject for request 2
Sending Access-Reject of id 0 to 192.168.1.143 port 49154
Tue Dec  6 00:48:17 2011 : Debug: Waking up in 4.9 seconds.