Re: Freeradius-Users post from santoro.ice@gmail.com requires approval
On 10 Jan 2015, at 16:30, Arran Cudbard-Bell <a.cudbardb@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@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2 Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
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@freeradius.org> escreveu:
On 10 Jan 2015, at 16:30, Arran Cudbard-Bell <a.cudbardb@freeradius.org <mailto:a.cudbardb@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@freeradius.org <mailto:a.cudbardb@freeradius.org>> FreeRADIUS development team
FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
Arran Cudbard-Bell <a.cudbardb@freeradius.org <mailto:a.cudbardb@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
On 12-01-15 14:07, Marcelo Santoro wrote:
Hello Arran…
As you say to me… i updated my FreeRadius to 3.0.6 and The SQL Error still there…
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
It looks like the SQL xlat requires the query to return something to run without errors. Postgresql has a possibility to add "RETURNING 0" to the query to make it return something, tha would silence the warnings. I've got no idea if something similar is possible in Mysql. -- Herwin Weststrate
Tks Herwin… I am using the follow Post-Auth Command: update request { Tmp-Integer-0 := "%{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}'}" } Do you know the syntax to call a perl script ? … i can write a perl script to do this update in my MySQL and make the perl script return 0 :) Tks for your help Friend. Best Regards.
Em 12/01/2015, à(s) 11:18, Herwin Weststrate <herwin@quarantainenet.nl> escreveu:
On 12-01-15 14:07, Marcelo Santoro wrote:
Hello Arran…
As you say to me… i updated my FreeRadius to 3.0.6 and The SQL Error still there…
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
It looks like the SQL xlat requires the query to return something to run without errors. Postgresql has a possibility to add "RETURNING 0" to the query to make it return something, tha would silence the warnings. I've got no idea if something similar is possible in Mysql.
-- Herwin Weststrate
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Hi,
I am using the follow Post-Auth Command:
update request { Tmp-Integer-0 := "%{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}'}" }
so the UPDATE returns no value....so Tmp-Integer-0 isnt set to anything...thus fails.... so, a quick guess or 2....you can either wrap up the %sql{} stuff in a %{eval:} statement....or, you can change the thing....are you even using the Tmp-Integer-0 string? why are you updating the request? to be an if(%sql{}) statement instead.... the SQL will be run...you can then look at the result and work on that. running external script is extreme performance hit..running PERL not so..but still big hit alan
Alan… please… can you give me an example how to use:
%sql{} stuff in a %{eval:} statement.
or
if(%sql{}) statement
Tks so much friend. Best Regards Marcelo Santoro
Em 12/01/2015, à(s) 13:27, A.L.M.Buxey@lboro.ac.uk escreveu:
Hi,
I am using the follow Post-Auth Command:
update request { Tmp-Integer-0 := "%{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}'}" }
so the UPDATE returns no value....so Tmp-Integer-0 isnt set to anything...thus fails....
so, a quick guess or 2....you can either wrap up the %sql{} stuff in a %{eval:} statement....or, you can change the thing....are you even using the Tmp-Integer-0 string? why are you updating the request? to be an
if(%sql{}) statement instead.... the SQL will be run...you can then look at the result and work on that.
running external script is extreme performance hit..running PERL not so..but still big hit
alan - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Herwin … o created the Script Perl … and now everything is OK :) This is the config in Freeradius :) post-auth{ # other confs . . . update request { Tmp-Integer-0 := `/scripts/post-auth.pl %{Nas-IP-Address} %{reply:Framed-IP-Address} %{SQL-User-Name}` } } and in my post-auth.pl i execute my SQL update command and return 0 in the end of script: -------------------- # SQL Command... print “0 \n”; -------------------- Tks EveryOne for precious help !!! Best Regards. Marcelo Santoro
Em 12/01/2015, à(s) 11:18, Herwin Weststrate <herwin@quarantainenet.nl> escreveu:
On 12-01-15 14:07, Marcelo Santoro wrote:
Hello Arran…
As you say to me… i updated my FreeRadius to 3.0.6 and The SQL Error still there…
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
It looks like the SQL xlat requires the query to return something to run without errors. Postgresql has a possibility to add "RETURNING 0" to the query to make it return something, tha would silence the warnings. I've got no idea if something similar is possible in Mysql.
-- Herwin Weststrate
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Mon, Jan 12, 2015 at 12:05:46PM -0200, Marcelo Santoro wrote:
post-auth{ # other confs . . . update request { Tmp-Integer-0 := `/scripts/post-auth.pl %{Nas-IP-Address} %{reply:Framed-IP-Address} %{SQL-User-Name}` } }
Just watch out as this won't perform anything like as well as running the query in FreeRADIUS directly. Matthew -- Matthew Newton, Ph.D. <mcn4@le.ac.uk> Systems Specialist, Infrastructure Services, I.T. Services, University of Leicester, Leicester LE1 7RH, United Kingdom For IT help contact helpdesk extn. 2253, <ithelp@le.ac.uk>
participants (5)
-
A.L.M.Buxey＠lboro.ac.uk -
Arran Cudbard-Bell -
Herwin Weststrate -
Marcelo Santoro -
Matthew Newton