Freeradius-Users post from santoro.ice at gmail.com requires approval
Arran Cudbard-Bell
a.cudbardb at freeradius.org
Sat Jan 10 10:31:41 CET 2015
> On 10 Jan 2015, at 16:30, Arran Cudbard-Bell <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>
FreeRADIUS development team
FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
Arran Cudbard-Bell <a.cudbardb at freeradius.org>
FreeRADIUS development team
FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20150110/502edce2/attachment-0001.html>
More information about the Freeradius-Users
mailing list