Freeradius-Users post from santoro.ice at gmail.com requires approval

Marcelo Santoro santoro.ice at gmail.com
Mon Jan 12 14:07:17 CET 2015


Hello Arran…

As you say to me… i updated my FreeRadius to 3.0.6 and The SQL Error still there…


rlm_sql (sql): Released connection (20)
(2) sqlippool: EXPAND Allocated IP: %{reply:Framed-IP-Address} from %{control:Pool-Name} (did %{Called-Station-Id} cli %{Calling-Station-Id} port %{NAS-Port} user %{User-Name})
(2) sqlippool:    --> Allocated IP: 131.0.120.0 from db_pool (did pppoe-1 cli 00:09:06:0B:1E:39 port 15728672 user teste1)
(2)     [sqlippool] = ok
(2)     [exec] = noop
(2)     policy remove_reply_message_if_eap {
(2)       if (&reply:EAP-Message && &reply:Reply-Message) {
(2)       if (&reply:EAP-Message && &reply:Reply-Message)  -> FALSE
(2)       else {
(2)         [noop] = noop
(2)       } # else = noop
(2)     } # policy remove_reply_message_if_eap = noop
(2)     update request {
(2)       EXPAND %{User-Name}
(2)          --> teste1
(2)       SQL-User-Name set to 'teste1'
rlm_sql (sql): Reserved connection (20)
(2)       EXPAND /usr/local/freeradius-server-3.0.6/var/log/radius/sqllog.sql
(2)          --> /usr/local/freeradius-server-3.0.6/var/log/radius/sqllog.sql
rlm_sql (sql): Executing query: ' UPDATE acessos_clientes set con_id = (select con_id from concentradores where con_ip = '10.0.0.2'), ace_last_ip = '131.0.120.0' where ace_login = 'teste1''
rlm_sql_mysql: Rows matched: 1  Changed: 1  Warnings: 0
rlm_sql_mysql: MYSQL Error: No Fields
rlm_sql_mysql: MYSQL error: 
ERROR: (2)       SQL query failed
rlm_sql (sql): Released connection (20)
(2)       EXPAND %{sql: UPDATE acessos_clientes set con_id = (select con_id from concentradores where con_ip = '%{Nas-IP-Address}'), ace_last_ip = '%{reply:Framed-IP-Address}' where ace_login = '%{SQL-User-Name}'}
(2)          --> 
(2)       Tmp-Integer-0 := 0
(2)     } # update request = noop
(2)   } # post-auth = ok
(2) Sent Access-Accept Id 41 from 186.227.47.5:1812 to 186.227.47.249:57186 length 87
(2)   Framed-Protocol = PPP
(2)   Framed-Compression = Van-Jacobson-TCP-IP
(2)   Mikrotik-Rate-Limit = '1024k/800k 1024k/1024k 1024k/512k 300/300'
(2)   Framed-IP-Address = 131.0.120.0
(2) Finished request
Waking up in 0.1 seconds.


But the SQL command is being executed successful.

I Realy don`t know what is happening :(

Tks For your precious help.



Best Regards
Marcelo Santoro





> Em 10/01/2015, à(s) 07:31, Arran Cudbard-Bell <a.cudbardb at freeradius.org> escreveu:
> 
>> On 10 Jan 2015, at 16:30, Arran Cudbard-Bell <a.cudbardb at freeradius.org <mailto:a.cudbardb at freeradius.org>> wrote:
>> 
>> 
>>> Arran… this is the output of radiusd -X in the exactly time where authentication occurs.
>>> 
>>> The problem is here:
>>> 
>>> expand:  UPDATE acessos_clientes set con_id = (select con_id from concentradores where con_ip = '%{Nas-IP-Address}'), ace_last_ip = '%{reply:Framed-IP-Address}' where ace_login = '%{SQL-User-Name}' ->  UPDATE acessos_clientes set con_id = (select con_id from concentradores where con_ip = '10.0.0.2'), ace_last_ip = '131.0.120.0' where ace_login = 'teste1'
>>> 
>>> 
>>> but it is Working perfectly… as you can see:
>>> con_id is 3
>>> and
>>> ace_last_ip is 131.0.120.0
>>> 
>>> But the error is there: 
>>> MySQL Error: No Fields
>>> 
>>> 
>>> OutPut: 
>>> 
>>> rad_recv: Access-Request packet from host 186.227.X.X port 33586, id=185, length=140
>>> 	Service-Type = Framed-User
>>> 	Framed-Protocol = PPP
>>> 	NAS-Port = 15728654
>>> 	NAS-Port-Type = Ethernet
>>> 	User-Name = "teste1"
>>> 	Calling-Station-Id = "C4:6E:1F:98:1D:4F"
>>> 	Called-Station-Id = "pppoe-1"
>>> 	NAS-Port-Id = "ether2"
>>> 	CHAP-Challenge = 0x4dacd856aa257c6bef6400aa5374954d
>>> 	CHAP-Password = 0x01be52df4c582bbf354be1b7d395fb9b8e
>>> 	NAS-Identifier = "PPPOE-1"
>>> 	NAS-IP-Address = 10.0.0.2
>>> # Executing section authorize from file /etc/freeradius/sites-enabled/default
>>> +- entering group authorize {...}
>>> ++[preprocess] returns ok
>>> [chap] Setting 'Auth-Type := CHAP'
>>> ++[chap] returns ok
>>> ++[mschap] returns noop
>>> [eap] No EAP-Message, not doing EAP
>>> ++[eap] returns noop
>>> [sql] 	expand: %{User-Name} -> teste1
>>> [sql] sql_set_user escaped user --> 'teste1'
>>> rlm_sql (sql): Reserving sql socket id: 119
>>> [sql] 	expand: SELECT id, UserName, Attribute, Value, op           FROM radcheck           WHERE UserName = '%{SQL-User-Name}' 	  AND status = '1'           ORDER BY id -> SELECT id, UserName, Attribute, Value, op           FROM radcheck           WHERE UserName = 'teste1' 	  AND status = '1'           ORDER BY id
>>> rlm_sql_mysql: MYSQL check_error: 2006, returning SQL_DOWN
>>> rlm_sql (sql): Attempting to connect rlm_sql_mysql #119
>>> rlm_sql_mysql: Starting connect to MySQL server for #119
>>> rlm_sql (sql): Connected new DB handle, #119
>>> WARNING: Found User-Password == "...".
>>> WARNING: Are you sure you don't mean Cleartext-Password?
>>> WARNING: See "man rlm_pap" for more information.
>>> [sql] User found in radcheck table
>>> [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 = 'teste1'           ORDER BY id
>>> [sql] 	expand: SELECT groupname           FROM usergroup           WHERE UserName = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname           FROM usergroup           WHERE UserName = 'teste1'           ORDER BY priority
>>> rlm_sql (sql): Released sql socket id: 119
>>> ++[sql] returns ok
>>> ++[expiration] returns noop
>>> ++[logintime] returns noop
>>> [pap] WARNING: Auth-Type already set.  Not setting to PAP
>>> ++[pap] returns noop
>>> Found Auth-Type = CHAP
>>> !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
>>> !!!    Replacing User-Password in config items with Cleartext-Password.     !!!
>>> !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
>>> !!! Please update your configuration so that the "known good"               !!!
>>> !!! clear text password is in Cleartext-Password, and not in User-Password. !!!
>>> !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
>>> # Executing group from file /etc/freeradius/sites-enabled/default
>>> +- entering group CHAP {...}
>>> [chap] login attempt by "teste1" with CHAP password
>>> [chap] Using clear text password "102030" for user teste1 authentication.
>>> [chap] chap user teste1 authenticated succesfully
>>> ++[chap] returns ok
>>> Login OK: [teste1] (from client Auth_PPPOE_T1 port 15728654 cli C4:6E:1F:98:1D:4F)
>>> # Executing section post-auth from file /etc/freeradius/sites-enabled/default
>>> +- entering group post-auth {...}
>>> rlm_sql (sql): Reserving sql socket id: 118
>>> [sqlippool] 	expand: %{User-Name} -> teste1
>>> [sqlippool] sql_set_user escaped user --> 'teste1'
>>> [sqlippool] 	expand: START TRANSACTION -> START TRANSACTION
>>> rlm_sql_mysql: MYSQL check_error: 2006, returning SQL_DOWN
>>> rlm_sql (sql): Attempting to connect rlm_sql_mysql #118
>>> rlm_sql_mysql: Starting connect to MySQL server for #118
>>> rlm_sql (sql): Connected new DB handle, #118
>>> [sqlippool] 	expand: UPDATE radippool   SET nasipaddress = '', pool_key = 0,   callingstationid = '', username = '',   expiry_time = NULL   WHERE expiry_time <= NOW() - INTERVAL 1 SECOND   AND nasipaddress = '%{Nas-IP-Address}' -> UPDATE radippool   SET nasipaddress = '', pool_key = 0,   callingstationid = '', username = '',   expiry_time = NULL   WHERE expiry_time <= NOW() - INTERVAL 1 SECOND   AND nasipaddress = '10.0.0.2'
>>> [sqlippool] 	expand: SELECT framedipaddress FROM radippool  WHERE pool_name = '%{control:Pool-Name}' AND fixed ='N' AND (expiry_time < NOW() OR expiry_time IS NULL)  ORDER BY (username <> '%{User-Name}'),  (callingstationid <> '%{Calling-Station-Id}'),  expiry_time  LIMIT 1  FOR UPDATE -> SELECT framedipaddress FROM radippool  WHERE pool_name = 'db_pool' AND fixed ='N' AND (expiry_time < NOW() OR expiry_time IS NULL)  ORDER BY (username <> 'teste1'),  (callingstationid <> 'C4:6E:1F:98:1D:4F'),  expiry_time  LIMIT 1  FOR UPDATE
>>> [sqlippool] 	expand: UPDATE radippool  SET nasipaddress = '%{NAS-IP-Address}', pool_key = '%{NAS-IP-Address}-%{NAS-Port}',  callingstationid = '%{Calling-Station-Id}', username = '%{User-Name}',  expiry_time = NOW() + INTERVAL 8400 SECOND  WHERE framedipaddress = '131.0.X.X' AND expiry_time IS NULL -> UPDATE radippool  SET nasipaddress = '10.0.0.2', pool_key = '10.0.0.2-15728654',  callingstationid = 'C4:6E:1F:98:1D:4F', username = 'teste1',  expiry_time = NOW() + INTERVAL 8400 SECOND  WHERE framedipaddress = '131.0.X.X' AND expiry_time IS NULL
>>> [sqlippool] Allocated IP 131.0.X.X [00780083]
>>> [sqlippool] 	expand: COMMIT -> COMMIT
>>> rlm_sql (sql): Released sql socket id: 118
>>> [sqlippool] 	expand: Allocated IP: %{reply:Framed-IP-Address} from %{control:Pool-Name}   (did %{Called-Station-Id} cli %{Calling-Station-Id} port %{NAS-Port} user %{User-Name}) -> Allocated IP: 131.0.X.X from db_pool   (did pppoe-1 cli C4:6E:1F:98:1D:4F port 15728654 user teste1)
>>> Allocated IP: 131.0.X.X from db_pool   (did pppoe-1 cli C4:6E:1F:98:1D:4F port 15728654 user teste1)
>>> ++[sqlippool] returns ok
>>> [sql] 	expand: %{User-Name} -> teste1
>>> [sql] sql_set_user escaped user --> 'teste1'
>>> [sql] 	expand: %{User-Password} -> 
>>> [sql] 	... expanding second conditional
>>> [sql] 	expand: %{Chap-Password} -> 0x01be52df4c582bbf354be1b7d395fb9b8e
>>> [sql] 	expand: INSERT INTO radpostauth                           (User, pass, reply, date)                           VALUES (                           '%{User-Name}',                           '%{%{User-Password}:-%{Chap-Password}}',                           '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth                           (User, pass, reply, date)                           VALUES (                           'teste1',                           '0x01be52df4c582bbf354be1b7d395fb9b8e',                           'Access-Accept', '2015-01-09 11:54:21')
>>> rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth                           (User, pass, reply, date)                           VALUES (                           'teste1',                           '0x01be52df4c582bbf354be1b7d395fb9b8e',                           'Access-Accept', '2015-01-09 11:54:21')
>>> rlm_sql (sql): Reserving sql socket id: 117
>>> rlm_sql_mysql: MYSQL check_error: 2006, returning SQL_DOWN
>>> rlm_sql (sql): Attempting to connect rlm_sql_mysql #117
>>> rlm_sql_mysql: Starting connect to MySQL server for #117
>>> rlm_sql (sql): Connected new DB handle, #117
>>> rlm_sql (sql): Released sql socket id: 117
>>> ++[sql] returns ok
>>> ++[exec] returns noop
>>> sql_xlat
>>> 	expand: %{User-Name} -> teste1
>>> sql_set_user escaped user --> 'teste1'
>>> 	expand:  UPDATE acessos_clientes set con_id = (select con_id from concentradores where con_ip = '%{Nas-IP-Address}'), ace_last_ip = '%{reply:Framed-IP-Address}' where ace_login = '%{SQL-User-Name}' ->  UPDATE acessos_clientes set con_id = (select con_id from concentradores where con_ip = '10.0.0.2'), ace_last_ip = '131.0.X.X' where ace_login = 'teste1'
>>> rlm_sql (sql): Reserving sql socket id: 116
>>> rlm_sql_mysql: MYSQL check_error: 2006, returning SQL_DOWN
>>> rlm_sql (sql): Attempting to connect rlm_sql_mysql #116
>>> rlm_sql_mysql: Starting connect to MySQL server for #116
>>> rlm_sql (sql): Connected new DB handle, #116
>>> rlm_sql_mysql: MYSQL Error: No Fields
>>> rlm_sql_mysql: MYSQL error: 
>>> rlm_sql (sql): Attempting to connect rlm_sql_mysql #116
>>> rlm_sql_mysql: Starting connect to MySQL server for #116
>>> rlm_sql (sql): Connected new DB handle, #116
>>> rlm_sql (sql): failed after re-connect
>>> SQL query did not succeed
>>> rlm_sql (sql): Released sql socket id: 116
>>> 	expand: %{sql: UPDATE acessos_clientes set con_id = (select con_id from concentradores where con_ip = '%{Nas-IP-Address}'), ace_last_ip = '%{reply:Framed-IP-Address}' where ace_login = '%{SQL-User-Name}'} -> 
>>> ++[request] returns noop
>>> Sending Access-Accept of id 185 to 186.227.47.X.X port 33586
>>> 	Mikrotik-Rate-Limit := "1024k/800k 1024k/1024k 1024k/512k 300/300"
>>> 	Framed-IP-Address = 131.0.X.X
>>> Finished request 0.
>>> Going to the next request
>>> Waking up in 1.9 seconds.
>>> rad_recv: Accounting-Request packet from host 186.227.47.X.X port 48371, id=186, length=143
>>> 	Service-Type = Framed-User
>>> 	Framed-Protocol = PPP
>>> 	NAS-Port = 15728654
>>> 	NAS-Port-Type = Ethernet
>>> 	User-Name = "teste1"
>>> 	Calling-Station-Id = "C4:6E:1F:98:1D:4F"
>>> 	Called-Station-Id = "pppoe-1"
>>> 	NAS-Port-Id = "ether2"
>>> 	Acct-Session-Id = "81c0000e"
>>> 	Framed-IP-Address = 131.0.X.X
>>> 	Acct-Authentic = RADIUS
>>> 	Event-Timestamp = "Jan  9 2015 11:54:34 BRST"
>>> 	Acct-Status-Type = Start
>>> 	NAS-Identifier = "PPPOE-1"
>>> 	Acct-Delay-Time = 0
>>> 	NAS-IP-Address = 10.0.0.2
>>> # Executing section preacct from file /etc/freeradius/sites-enabled/default
>>> +- entering group preacct {...}
>>> ++[preprocess] returns ok
>>> [acct_unique] Hashing 'NAS-Port = 15728654,Client-IP-Address = 186.227.47.X.X,NAS-IP-Address = 10.0.0.2,Acct-Session-Id = "81c0000e",User-Name = "teste1"'
>>> [acct_unique] Acct-Unique-Session-ID = "e7a32bf7b37ce3d6".
>>> ++[acct_unique] returns ok
>>> [suffix] No '@' in User-Name = "teste1", looking up realm NULL
>>> [suffix] No such realm "NULL"
>>> ++[suffix] returns noop
>>> ++[files] returns noop
>>> # Executing section accounting from file /etc/freeradius/sites-enabled/default
>>> +- entering group accounting {...}
>>> rlm_sql (sql): Reserving sql socket id: 115
>>> [sqlippool] 	expand: %{User-Name} -> teste1
>>> [sqlippool] sql_set_user escaped user --> 'teste1'
>>> [sqlippool] 	expand: START TRANSACTION -> START TRANSACTION
>>> rlm_sql_mysql: MYSQL check_error: 2006, returning SQL_DOWN
>>> rlm_sql (sql): Attempting to connect rlm_sql_mysql #115
>>> rlm_sql_mysql: Starting connect to MySQL server for #115
>>> rlm_sql (sql): Connected new DB handle, #115
>>> [sqlippool] 	expand: UPDATE radippool  SET expiry_time = NOW() + INTERVAL 8400 SECOND  WHERE nasipaddress = '%{NAS-IP-Address}' AND  pool_key = '%{NAS-IP-Address}-%{NAS-Port}'  AND username = '%{User-Name}'  AND callingstationid = '%{Calling-Station-Id}'  AND framedipaddress = '%{Framed-IP-Address}' -> UPDATE radippool  SET expiry_time = NOW() + INTERVAL 8400 SECOND  WHERE nasipaddress = '10.0.0.2' AND  pool_key = '10.0.0.2-15728654'  AND username = 'teste1'  AND callingstationid = 'C4:6E:1F:98:1D:4F'  AND framedipaddress = '131.0.X.X'
>>> [sqlippool] 	expand: COMMIT -> COMMIT
>>> rlm_sql (sql): Released sql socket id: 115
>>> ++[sqlippool] returns ok
>>> ++[exec] returns noop
>>> [sql] 	expand: %{User-Name} -> teste1
>>> [sql] sql_set_user escaped user --> 'teste1'
>>> [sql] 	expand: %{Acct-Delay-Time} -> 0
>>> [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', '0000-00-00 00:00:00',              '0', '%{Acct-Authentic}', '%{Connect-Info}',              '', '0', '0',              '%{Called-Station-Id}', '%{Calling-Station-Id}', '',              '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP
>>> rlm_sql (sql): Reserving sql socket id: 114
>>> rlm_sql_mysql: MYSQL check_error: 2006, returning SQL_DOWN
>>> rlm_sql (sql): Attempting to connect rlm_sql_mysql #114
>>> rlm_sql_mysql: Starting connect to MySQL server for #114
>>> rlm_sql (sql): Connected new DB handle, #114
>>> rlm_sql (sql): Released sql socket id: 114
>>> ++[sql] returns ok
>>> [attr_filter.accounting_response] 	expand: %{User-Name} -> teste1
>>> attr_filter: Matched entry DEFAULT at line 12
>>> ++[attr_filter.accounting_response] returns updated
>>> Sending Accounting-Response of id 186 to 186.227.47.X.X port 48371
>>> Finished request 1.
>>> Cleaning up request 1 ID 186 with timestamp +121
>>> Going to the next request
>>> Waking up in 1.9 seconds.
>>> Cleaning up request 0 ID 185 with timestamp +121
>>> Ready to process requests.
>> 
> I have no idea. Looks like the connections are timing out MySQL side, so when you 
> come to use them, they're no longer viable.
> 
> Not sure if this is triggering the other error though.
> 
> Might be worth using wireshark to get a capture between FreeRADIUS and MySQL.
> I've found that's sometimes helpful in diagnosing weird issues like this.
> 
> If you want to upgrade to 3.0.6 and post the results, i'll help to try track it 
> down. Otherwise i'm not really interested in debugging v2.2.x issues, or enhancing
> the debug output for the SQL module in v2.2.x such that the problem becomes easier 
> to diagnose.
> 
> 
> -Arran
> 
> Arran Cudbard-Bell <a.cudbardb at freeradius.org <mailto:a.cudbardb at freeradius.org>>
> FreeRADIUS development team
> 
> FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
> 
> Arran Cudbard-Bell <a.cudbardb at freeradius.org <mailto:a.cudbardb at freeradius.org>>
> FreeRADIUS development team
> 
> FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
> 
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html



More information about the Freeradius-Users mailing list