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