Despite that several people reported that their FreeRadius 1.x installation is working fine with MySQL Stored Procedures, I run into quite some problems. Here my environment: - CentOS 4.4 on Xen Server 3.1 - FreeRadius 1.1.6 - MySQL 5.0.37 Community Edition with INNODB Tables I used a very simple stored procedure to track down the problem: --------------- DELIMITER // DROP PROCEDURE IF EXISTS CheckIt // CREATE PROCEDURE CheckIt () BEGIN SELECT 12345; END// --------------- This routine will always return the value 12345. Anyhow, when I called this procedure from FreeRadius I always go an error: "PROCEDURE myDB.CheckIt can't return a result set in the given context" ----- Sun May 6 07:23:10 2007 : Debug: rlm_sql_mysql: query: CALL CheckIt() Sun May 6 07:23:10 2007 : Debug: rlm_sql_mysql: MYSQL check_error: 1312 received Sun May 6 07:23:10 2007 : Error: rlm_sql (sql): database query error, CALL CheckIt(): PROCEDURE myDB.CheckIt can't return a result set in the given context ----- I then tried to call the same function via a PHP script (w/o FreeRadius involved) and run into the same problem. Then I found the information that it is required for MySQL Stored Procedures to function the client_flag 'CLIENT_MULTI_STATEMENTS' (refer to mysql.h) has to be added to the mysql_real_connect call. After adding it to the call within PHP all worked fine. Then I added the flag to freeradius-1.1.6/src/modules/rlm_sql/drivers/rlm_sql_mysql/sql_mysql.c : ----- if (!(mysql_sock->sock = mysql_real_connect(&(mysql_sock->conn), config->sql_server, config->sql_login, config->sql_password, config->sql_db, atoi(config->sql_port), NULL, CLIENT_FOUND_ROWS|CLIENT_MULTI_STATEMENTS))) { ----- ./configure; make; make install Note: CLIENT_MULTI_STATEMENTS automatically also sets CLIENT_MULTI_RESULTS within MySQL Started FreeRadius and procedure calls were accepted and results were correct. ----- Sun May 6 21:29:08 2007 : Debug: rlm_sql_mysql: query: CALL CheckIt() Sun May 6 21:29:08 2007 : Debug: rlm_sql (sql): - sql_xlat finished Sun May 6 21:29:08 2007 : Debug: rlm_sql (sql): Released sql socket id: 0 Sun May 6 21:29:08 2007 : Debug: radius_xlat: '12345' ----- A user can now login and things seem to work fine. But then consecutive MySQL queries started showing new error results: ----- Sun May 6 21:41:42 2007 : Debug: rlm_sql_mysql: MYSQL check_error: 2014 received Sun May 6 21:41:42 2007 : Error: rlm_sql (sql): database query error, <SELECT ... my sql query> : Commands out of sync; you can't run this command now ----- MySQL seems to track the state of each call and when the order of this state is incorrect, MySQL responds with 'CR_COMMANDS_OUT_OF_SYNC' = 'Commands out of sync; you can't run this command now'.
From what I found on the net ... "When the result of a statement isn't freed MySQL gives an error when trying to process a new query"
Could it be that there is somewhere a 'mysql_free_result' missing? This is what the MySQL documentation is saying: -------------------- B.1.2.13. Commands out of sync If you get Commands out of sync; you can't run this command now in your client code, you are calling client functions in the wrong order. This can happen, for example, if you are using mysql_use_result() and try to execute a new query before you have called mysql_free_result(). It can also happen if you try to execute two queries that return data without calling mysql_use_result() or mysql_store_result() in between. -------------------- 2.4.16. Upgrading MySQL If, after an upgrade, you experience problems with recompiled client programs, such as Commands out of sync or unexpected core dumps, you probably have used old header or library files when compiling your programs. In this case, you should check the date for your mysql.h file and libmysqlclient.a library to verify that they are from the new MySQL distribution. If not, recompile your programs with the new headers and libraries. -------------------- ... Did that ... When I leave some time between a login/logout/login it works ... Looks like the MySQL status information times out after a short while. Any hints on getting this up and running without changing O/S ? Thanks!
Hello Gunther, I've the same problems here. I use also a simple SP (just for testing) and I run into the same problems, like you. I've also patched the "sql_mysql.c" file and added the CLIENT_MULTI_STATEMENTS flag. After that, I get also the error 2014. After that, I added to every function, a radlog(L_DBG,"THOMAS: Init (sql_init_socket)"); (with the functionsnames), to see the order of the calls. This is the result: radius_xlat: 'CALL test2 ('00e0.18e0.c19d')' rlm_sql (sql): Reserving sql socket id: 1 THOMAS: Select_Query (sql_select_query) THOMAS: Query (sql_query) rlm_sql_mysql: query: CALL test2 ('00e0.18e0.c19d') THOMAS: Check_error (sql_check_error) THOMAS: Store (sql_store_result) THOMAS: Num_fields (sql_num_fields) THOMAS: Fetch (sql_fetch_row) THOMAS: Fetch (sql_fetch_row) THOMAS: Check_error (sql_check_error) THOMAS: Finish_Select (sql_finish_select_query) THOMAS: Free (sql_free_results) radius_xlat: '' radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM ssg_reply WHERE `id` = '1' ORDER BY id' THOMAS: Select_Query (sql_select_query) THOMAS: Query (sql_query) rlm_sql_mysql: query: SELECT id,UserName,Attribute,Value,op FROM ssg_reply WHERE `id` = '1' ORDER BY id THOMAS: Check_error (sql_check_error) rlm_sql_mysql: MYSQL check_error: 2014 received rlm_sql_getvpdata: database query error I think, the problem is the double call of "sql_fetch_row", but I'm not sure. If I replace the SP with a normal SELECT-query, everything works fine (and the sql_fetch_row function is also called twice). The problem is, I need the SP, so I need a solution,fix,workaround, whatever:) My system: debian etch freeradius 1.1.3 (from deb), and also freeradius 1.1.6 from source mysql 5.0.32 Best regards, Thomas -- View this message in context: http://www.nabble.com/FR-with-MySQL---Stored-Procedures-tf3701829.html#a1037... Sent from the FreeRadius - User mailing list archive at Nabble.com.
++[eap] returns updated radius_xlat: '([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:]?([0-9a-f]{2,})[-:]?([0-9a-f]{2})[-:]?([0-9a-f]{2})' radius_xlat: '001438fb943e' rlm_attr_rewrite: Changed value for attribute Called-Station-Id from '00-14-38-fb-94-3e' to '001438fb943' rlm_attr_rewrite: Could not find value pair for attribute Called-Station-Id ++[uniform_called_id] returns ok radius_xlat: '([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:]?([0-9a-f]{2,})[-:]?([0-9a-f]{2})[-:]?([0-9a-f]{2})' radius_xlat: '0017f231b481' rlm_attr_rewrite: Changed value for attribute Calling-Station-Id from '00-17-f2-31-b4-81' to '0017f231b48' Seems to be missing last char of value... -- Arran Cudbard-Bell (A.Cudbard-Bell@sussex.ac.uk) Authentication, Authorisation and Accounting Officer Infrastructure Services | ENG1 E1-1-08 University Of Sussex, Brighton EXT:01273 873900 | INT: 3900
Arran Cudbard-Bell wrote: ...
rlm_attr_rewrite: Changed value for attribute Calling-Station-Id from '00-17-f2-31-b4-81' to '0017f231b48'
Seems to be missing last char of value...
Try the attached patch. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog Index: src/modules/rlm_attr_rewrite/rlm_attr_rewrite.c =================================================================== RCS file: /source/radiusd/src/modules/rlm_attr_rewrite/rlm_attr_rewrite.c,v retrieving revision 1.43 diff -u -r1.43 rlm_attr_rewrite.c --- src/modules/rlm_attr_rewrite/rlm_attr_rewrite.c 17 Apr 2007 13:14:50 -0000 1.43 +++ src/modules/rlm_attr_rewrite/rlm_attr_rewrite.c 8 May 2007 13:26:26 -0000 @@ -285,9 +285,9 @@ if ((attr_vp->type == PW_TYPE_IPADDR) && (attr_vp->vp_strvalue[0] == '\0')) { - inet_ntop(AF_INET, &(attr_vp->vp_ipaddr), - attr_vp->vp_strvalue, - sizeof(attr_vp->vp_strvalue)); + inet_ntop(AF_INET, &(attr_vp->vp_ipaddr), + attr_vp->vp_strvalue, + sizeof(attr_vp->vp_strvalue)); } ptr = new_str; @@ -325,8 +325,9 @@ return ret; } - strlcpy(ptr, ptr2,len); + memcpy(ptr, ptr2,len); ptr += len; + *ptr = '\0'; ptr2 += pmatch[0].rm_eo; if (i == 0){ @@ -380,8 +381,9 @@ return ret; } if (replace_len){ - strlcpy(ptr, replace_STR, replace_len); + memcpy(ptr, replace_STR, replace_len); ptr += replace_len; + *ptr = '\0'; } } regfree(&preg); @@ -392,7 +394,8 @@ data->attribute, attr_vp->vp_strvalue); return ret; } - strlcpy(ptr, ptr2, len); + memcpy(ptr, ptr2, len); + ptr[len] = '\0'; DEBUG2("rlm_attr_rewrite: Changed value for attribute %s from '%s' to '%s'", data->attribute, attr_vp->vp_strvalue, new_str);
Alan DeKok wrote:
Arran Cudbard-Bell wrote: ...
rlm_attr_rewrite: Changed value for attribute Calling-Station-Id from '00-17-f2-31-b4-81' to '0017f231b48'
Seems to be missing last char of value...
Try the attached patch.
Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
------------------------------------------------------------------------
Index: src/modules/rlm_attr_rewrite/rlm_attr_rewrite.c =================================================================== RCS file: /source/radiusd/src/modules/rlm_attr_rewrite/rlm_attr_rewrite.c,v retrieving revision 1.43 diff -u -r1.43 rlm_attr_rewrite.c --- src/modules/rlm_attr_rewrite/rlm_attr_rewrite.c 17 Apr 2007 13:14:50 -0000 1.43 +++ src/modules/rlm_attr_rewrite/rlm_attr_rewrite.c 8 May 2007 13:26:26 -0000 @@ -285,9 +285,9 @@
if ((attr_vp->type == PW_TYPE_IPADDR) && (attr_vp->vp_strvalue[0] == '\0')) { - inet_ntop(AF_INET, &(attr_vp->vp_ipaddr), - attr_vp->vp_strvalue, - sizeof(attr_vp->vp_strvalue)); + inet_ntop(AF_INET, &(attr_vp->vp_ipaddr), + attr_vp->vp_strvalue, + sizeof(attr_vp->vp_strvalue)); }
ptr = new_str; @@ -325,8 +325,9 @@ return ret; }
- strlcpy(ptr, ptr2,len); + memcpy(ptr, ptr2,len); ptr += len; + *ptr = '\0'; ptr2 += pmatch[0].rm_eo;
if (i == 0){ @@ -380,8 +381,9 @@ return ret; } if (replace_len){ - strlcpy(ptr, replace_STR, replace_len); + memcpy(ptr, replace_STR, replace_len); ptr += replace_len; + *ptr = '\0'; } } regfree(&preg); @@ -392,7 +394,8 @@ data->attribute, attr_vp->vp_strvalue); return ret; } - strlcpy(ptr, ptr2, len); + memcpy(ptr, ptr2, len); + ptr[len] = '\0';
DEBUG2("rlm_attr_rewrite: Changed value for attribute %s from '%s' to '%s'", data->attribute, attr_vp->vp_strvalue, new_str);
------------------------------------------------------------------------
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
radius_xlat: '([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:]?([0-9a-f]{2,})[-:]?([0-9a-f]{2})[-:]?([0-9a-f]{2})' radius_xlat: '0019e30ccd58' rlm_attr_rewrite: Changed value for attribute Calling-Station-Id from '00-19-e3-0c-cd-58' to '0019e30ccd58' Works ! Thanks, -- Arran Cudbard-Bell (A.Cudbard-Bell@sussex.ac.uk) Authentication, Authorisation and Accounting Officer Infrastructure Services | ENG1 E1-1-08 University Of Sussex, Brighton EXT:01273 873900 | INT: 3900
And another... PEAP: Sending tunneled request EAP-Message = 0x020800061a03 FreeRADIUS-Proxied-To = 127.0.0.1 User-Name = "ac221@sussex.ac.uk" State = 0x0b97599351abde4fc473bdaa8ad158b3 Framed-MTU = 1466 NAS-IP-Address = 139.184.135.33 NAS-Identifier = "Fred 802.1x Test" Service-Type = Framed-User NAS-Port = 254 NAS-Port-Type = Ethernet NAS-Port-Id = "wl0" Called-Station-Id = "00-03-93-e8-b7-a1" Calling-Station-Id = "00-19-e3-0c-cd-58" Connect-Info = "CONNECT Ethernet 54Mbps Half duplex" Processing the authorize section of radiusd.conf +- entering group authorize radius_xlat: 'ac221@sussex.ac.uk' hints: Matched DEFAULT at 36 radius_xlat: 'ac221' radius_xlat: 'sussex.ac.uk' radius_xlat: '139.184.135.33' radius_xlat: '139.184.135.33' radius_xlat: '139.184.135.33' radius_xlat: '139.184.135.33' radius_xlat: '139.184.135.33' radius_xlat: '139.184.135.33' ++[preprocess] returns ok radius_xlat: '/usr/local/freeradius/var/log/19700101/auth-detail-01:00' rlm_detail: /usr/local/freeradius/var/log/%Y%m%d/auth-detail-%H:00 expands to /usr/local/freeradius/var/log/19700101/auth-detail-01:00 radius_xlat: 'Thu Jan 1 01:00:00 1970' ... well it doesn't strictly fail. -- Arran Cudbard-Bell (A.Cudbard-Bell@sussex.ac.uk) Authentication, Authorisation and Accounting Officer Infrastructure Services | ENG1 E1-1-08 University Of Sussex, Brighton EXT:01273 873900 | INT: 3900
Arran Cudbard-Bell wrote:
And another... ... expands to /usr/local/freeradius/var/log/19700101/auth-detail-01:00 radius_xlat: 'Thu Jan 1 01:00:00 1970'
... well it doesn't strictly fail.
I've committed a fix. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Alan DeKok wrote:
Arran Cudbard-Bell wrote:
And another... ... expands to /usr/local/freeradius/var/log/19700101/auth-detail-01:00 radius_xlat: 'Thu Jan 1 01:00:00 1970'
... well it doesn't strictly fail.
I've committed a fix.
Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Is that a fix for the attr_rewrite stuff too ? and thanks :) -- Arran Cudbard-Bell (A.Cudbard-Bell@sussex.ac.uk) Authentication, Authorisation and Accounting Officer Infrastructure Services | ENG1 E1-1-08 University Of Sussex, Brighton EXT:01273 873900 | INT: 3900
Arran Cudbard-Bell wrote:
Is that a fix for the attr_rewrite stuff too ?
That was committed, too. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Alan DeKok wrote:
Arran Cudbard-Bell wrote:
Is that a fix for the attr_rewrite stuff too ?
That was committed, too.
Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Hmm still seems to be broken. radius_xlat: '/usr/local/freeradius/var/log/19700101/reply-detail-01:00' rlm_detail: /usr/local/freeradius/var/log/%Y%m%d/reply-detail-%H:00 expands to /usr/local/freeradius/var/log/19700101/reply-detail-01:00 radius_xlat: 'Thu Jan 1 01:00:00 1970' Compiled from scratch , from current CVS head as of 20 minutes ago.. Did it go in properly ? AttrRewrite problem is now fixed though. -- Arran Cudbard-Bell (A.Cudbard-Bell@sussex.ac.uk) Authentication, Authorisation and Accounting Officer Infrastructure Services | ENG1 E1-1-08 University Of Sussex, Brighton EXT:01273 873900 | INT: 3900
Arran Cudbard-Bell wrote:
Compiled from scratch , from current CVS head as of 20 minutes ago..
Did it go in properly ?
Yes. What OS are you running? Is it a 64-bit CPU? Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Alan DeKok wrote:
Arran Cudbard-Bell wrote:
Compiled from scratch , from current CVS head as of 20 minutes ago..
Did it go in properly ?
Yes. What OS are you running? Is it a 64-bit CPU?
Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Darwin (OS 10.4.9) Yes dual core Power PC G5 64bit CPU. Though apparently the "Command line space is 64bit" though there are "fluffy" parts that are still 32bit. -- Arran Cudbard-Bell (A.Cudbard-Bell@sussex.ac.uk) Authentication, Authorisation and Accounting Officer Infrastructure Services | ENG1 E1-1-08 University Of Sussex, Brighton EXT:01273 873900 | INT: 3900
Arran Cudbard-Bell wrote:
Yes dual core Power PC G5 64bit CPU.
That's what I thought. Posix says that "struct timeval" has member "time_t tv_sec". So it *should* be safe to pass a pointer to tv_sec to a function that takes a "time_t *", right? Apparently not on the Mac. <sigh> Please try the attached patch. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog Index: src/main/event.c =================================================================== RCS file: /source/radiusd/src/main/event.c,v retrieving revision 1.33 diff -u -r1.33 event.c --- src/main/event.c 24 Apr 2007 09:18:58 -0000 1.33 +++ src/main/event.c 9 May 2007 09:35:41 -0000 @@ -685,6 +685,8 @@ PW_POST_PROXY_TYPE, PW_TYPE_INTEGER); vp->vp_integer = dval->value; + rad_assert(request->proxy_reply = NULL); + return 1; } @@ -1729,6 +1731,7 @@ request->next_callback = NULL; gettimeofday(&request->received, NULL); + request->timestamp = request->received.tv_sec; request->when = request->received; request->delay = USEC / 10; Index: src/main/xlat.c =================================================================== RCS file: /source/radiusd/src/main/xlat.c,v retrieving revision 1.119 diff -u -r1.119 xlat.c --- src/main/xlat.c 23 Apr 2007 08:10:28 -0000 1.119 +++ src/main/xlat.c 9 May 2007 09:35:41 -0000 @@ -375,6 +375,7 @@ } #endif /* HAVE_REGEX_H */ + /* * Compare two xlat_t structs, based ONLY on the module name. */ @@ -917,7 +918,7 @@ p++; break; case 'd': /* request day */ - TM = localtime_r(&request->received.tv_sec, &s_TM); + TM = localtime_r(&request->timestamp, &s_TM); len = strftime(tmpdt, sizeof(tmpdt), "%d", TM); if (len > 0) { strlcpy(q, tmpdt, freespace); @@ -941,7 +942,7 @@ p++; break; case 'm': /* request month */ - TM = localtime_r(&request->received.tv_sec, &s_TM); + TM = localtime_r(&request->timestamp, &s_TM); len = strftime(tmpdt, sizeof(tmpdt), "%m", TM); if (len > 0) { strlcpy(q, tmpdt, freespace); @@ -962,7 +963,7 @@ p++; break; case 't': /* request timestamp */ - CTIME_R(&request->received.tv_sec, tmpdt, sizeof(tmpdt)); + CTIME_R(&request->timestamp, tmpdt, sizeof(tmpdt)); nl = strchr(tmpdt, '\n'); if (nl) *nl = '\0'; strlcpy(q, tmpdt, freespace); @@ -984,7 +985,7 @@ p++; break; case 'D': /* request date */ - TM = localtime_r(&request->received.tv_sec, &s_TM); + TM = localtime_r(&request->timestamp, &s_TM); len = strftime(tmpdt, sizeof(tmpdt), "%Y%m%d", TM); if (len > 0) { strlcpy(q, tmpdt, freespace); @@ -993,7 +994,7 @@ p++; break; case 'H': /* request hour */ - TM = localtime_r(&request->received.tv_sec, &s_TM); + TM = localtime_r(&request->timestamp, &s_TM); len = strftime(tmpdt, sizeof(tmpdt), "%H", TM); if (len > 0) { strlcpy(q, tmpdt, freespace); @@ -1016,7 +1017,7 @@ p++; break; case 'S': /* request timestamp in SQL format*/ - TM = localtime_r(&request->received.tv_sec, &s_TM); + TM = localtime_r(&request->timestamp, &s_TM); len = strftime(tmpdt, sizeof(tmpdt), "%Y-%m-%d %H:%M:%S", TM); if (len > 0) { strlcpy(q, tmpdt, freespace); @@ -1025,7 +1026,7 @@ p++; break; case 'T': /* request timestamp */ - TM = localtime_r(&request->received.tv_sec, &s_TM); + TM = localtime_r(&request->timestamp, &s_TM); len = strftime(tmpdt, sizeof(tmpdt), "%Y-%m-%d-%H.%M.%S.000000", TM); if (len > 0) { strlcpy(q, tmpdt, freespace); @@ -1043,7 +1044,7 @@ p++; break; case 'Y': /* request year */ - TM = localtime_r(&request->received.tv_sec, &s_TM); + TM = localtime_r(&request->timestamp, &s_TM); len = strftime(tmpdt, sizeof(tmpdt), "%Y", TM); if (len > 0) { strlcpy(q, tmpdt, freespace);
Alan DeKok wrote:
Arran Cudbard-Bell wrote:
Yes dual core Power PC G5 64bit CPU.
That's what I thought.
Posix says that "struct timeval" has member "time_t tv_sec". So it *should* be safe to pass a pointer to tv_sec to a function that takes a "time_t *", right?
Apparently not on the Mac. <sigh> Please try the attached patch.
Yep thats fixed it :) But now get Sending Access-Request of id 41 to 194.82.174.185 port 1812 Service-Type := Authenticate-Only User-Name = "ac221@imperial.ac.uk" NAS-IP-Address = 0x Proxy-State = 0x323134 Proxying request 1 to realm jrs, home server 194.82.174.185 port 1812 Sending Access-Request of id 41 to 194.82.174.185 port 1812 Service-Type := Authenticate-Only User-Name = "ac221@imperial.ac.uk" NAS-IP-Address = 0x Proxy-State = 0x323134 Going to the next request Waking up in 4 seconds... rad_recv: Access-Request packet from host 139.184.134.191 port 32807, id=214, length=62 Sending duplicate proxied request to home server 194.82.174.185 port 1812 - ID: 41 Sending Access-Request of id 41 to 194.82.174.185 port 1812 Service-Type := Authenticate-Only User-Name = "ac221@imperial.ac.uk" NAS-IP-Address = 0x Proxy-State = 0x323134 Waking up in 2 seconds... Rejecting request 1 due to lack of any response from home server 194.82.174.185 port 1812 Assertion failed in event.c, line 688 Abort When proxying, on the second failed attempt.... -- Arran Cudbard-Bell (A.Cudbard-Bell@sussex.ac.uk) Authentication, Authorisation and Accounting Officer Infrastructure Services | ENG1 E1-1-08 University Of Sussex, Brighton EXT:01273 873900 | INT: 3900
Arran Cudbard-Bell wrote: ...
But now get ... Rejecting request 1 due to lack of any response from home server 194.82.174.185 port 1812 Assertion failed in event.c, line 688 Abort
When proxying, on the second failed attempt....
That's a typo in the assertion. Just delete line 688, and it will work. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
That's a typo in the assertion. Just delete line 688, and it will work Yep, thanks. :)
Couple of things, Firstly is is possible to specify return codes for users files depending on matched sections ? Or will the files module always return ok ? Secondly, whats considered decent throughput in terms of (serial) requests per second... With none of the SQL or LDAP checking i'm getting around 300ish requests per second ; With basic LDAP authorisation i'm getting around 130 rps; with group checking (10 groups checks in users file) 65rps; with LDAP and SQL based authorisation 60 rps; with LDAP,SQL based authorisation and MAC blacklist checking 30rps. We have a user base of around 10,000 users with a absolute maximum of 4,000 logged in at any one time, and two Dual Core 2.13ghz 64bit Apple Xserves with basic load balancing. It's obvious that the SQL server is lagging behind, and the LDAP cluster is on some ageing Xserves so probably isn't performing at it's peak... If you have any recommended figures that I could aim for, would be very useful. Thanks, Arran
Arran Cudbard-Bell wrote:
Firstly is is possible to specify return codes for users files depending on matched sections ? Or will the files module always return ok ?
You can't specify return codes from the "users" file.
Secondly, whats considered decent throughput in terms of (serial) requests per second... With none of the SQL or LDAP checking i'm getting around 300ish requests per second ;
That's a little low, to be honest. My tests on a dual core 1.8GHz intel show 25k PAP requests per second from localhost to localhost. That's rather different from what you're seeing. Unless you mean 300 full EAP-TLS/TTLS/PEAP authentications per second. That's pretty fast, considering that almost all of the CPU time is spent doing RSA key operations. And with 5-10 RADIUS packets per EAP authentication, that's 3k requests/s, not 300.
We have a user base of around 10,000 users with a absolute maximum of 4,000 logged in at any one time, and two Dual Core 2.13ghz 64bit Apple Xserves with basic load balancing.
It's obvious that the SQL server is lagging behind, and the LDAP cluster is on some ageing Xserves so probably isn't performing at it's peak...
If you have any recommended figures that I could aim for, would be very useful.
For plain PAP: 10k+ requests/s would be expected. For EAP, substantially less than that. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
It was PAP... Running with debugging mode *off* yields much better results ! Still with completely vanilla install , only getting [req] => 5000 [parallel] => 10 [total] => 50000 [start] => 1178820825.99 [stop] => 1178820836.79 [period] => 10.791821003 [req_s] => 4633 [req_m] => 277988 [req_h] => 16679298 localhost to localhost using #!/usr/local/php/bin/php <?php $stats['req'] = 5000; $stats['parallel'] = 10; $stats['total'] = $stats['req'] * $stats['parallel']; $stats['start'] = microtime(true); echo(exec("/usr/local/freeradius-cvsfast/bin/radclient -q -p {$stats['parallel']} -c {$stats['req']} -f users 127.0.0.1 auth testing123")); $stats['stop'] = microtime(true); $stats['period'] = $stats['stop'] - $stats['start']; $stats['req_s'] = round($stats['total'] / $stats['period']); $stats['req_m'] = round(($stats['total'] / $stats['period'])*60); $stats['req_h'] = round((($stats['total'] / $stats['period'])*60)*60); print_r($stats); ?> and with make CC="gcc -O3 -mcpu=970 -mtune=970 -mpowerpc64 -mpowerpc-gpopt" Setting CC / CFLAGS at configure time doesn't seem to work ... -- Arran Cudbard-Bell (A.Cudbard-Bell@sussex.ac.uk) Authentication, Authorisation and Accounting Officer Infrastructure Services | ENG1 E1-1-08 University Of Sussex, Brighton EXT:01273 873900 | INT: 3900
A.L.M.Buxey@lboro.ac.uk wrote:
Hi,
Running with debugging mode *off* yields much better results !
Still with completely vanilla install , only getting
what are your results when running the performance testing method as prescribed in the docs ?
alan - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Well it's basically the same as what im doing, Wrapper PHP script will record the time more accurately thats all... What are your stats like ? Did you say something like 3600 a second or was that a minute ? -- Arran Cudbard-Bell (A.Cudbard-Bell@sussex.ac.uk) Authentication, Authorisation and Accounting Officer Infrastructure Services | ENG1 E1-1-08 University Of Sussex, Brighton EXT:01273 873900 | INT: 3900
Arran Cudbard-Bell wrote:
It was PAP...
Running with debugging mode *off* yields much better results !
Well, yes.
Still with completely vanilla install , only getting
[req] => 5000 [parallel] => 10 [total] => 50000 [start] => 1178820825.99 [stop] => 1178820836.79 [period] => 10.791821003 [req_s] => 4633
That's pretty low. I'm a little surprised, in fact. I was getting that performance almost 6 years ago on machines available then.
localhost to localhost
Try from one machine to another. Maybe the client & server are competing for resources on the same machine. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Alan DeKok wrote:
Arran Cudbard-Bell wrote:
It was PAP...
Running with debugging mode *off* yields much better results !
Well, yes.
I liked the pretty text ?!
Still with completely vanilla install , only getting
[req] => 5000 [parallel] => 10 [total] => 50000 [start] => 1178820825.99 [stop] => 1178820836.79 [period] => 10.791821003 [req_s] => 4633
That's pretty low. I'm a little surprised, in fact. I was getting that performance almost 6 years ago on machines available then.
Yes it's worryingly low, This is with the G5 optimisation compiler flags passed to GCC... Though i'm not sure it's taking them ... should just be env CFLAGS=-O3 -mcpu=970 -mtune=970 -mpowerpc64 ./configure --prefix=/usr/local/freeradius-cvsfast make make install ... But the configure script doesn't seem to take notice of the CFLAGS env variable , so does not pass the flags to the compiler at build time. Have you had anyone else running FreeRADIUS on a G5 feed back about performance ?
localhost to localhost
Try from one machine to another. Maybe the client & server are competing for resources on the same machine.
Will try machine to machine on monday, or later today if I have time, though I suspect the performance will probably be worse. top reveals that radclient is running at about 70% utilization and radiusd at 104%. These boxes are not under any kind of load and have a pretty vanilla install of Mac OSX Server 10.4.9. Can't figure out why it's so slow.
Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
so...after a while I found a workaround for the SP problem..well, is quick and dirty and probably not the best solution. I've added to the function "sql_fetch_row" in sql_mysql.c a simple "sql_free_result(sqlsocket, config);"...see the diff below. Now my Stored Procedure works correct and as expected (my SP is at the end of this message). Perhaps someone can verify this, and perhaps this can added to the freeradius sourcecode from a developer (well, perhaps not so dirty ;) ) --- sql_mysql.c_org 2007-05-08 15:55:47.000000000 +0200 +++ sql_mysql.c 2007-05-08 15:57:35.000000000 +0200 @@ -50,6 +50,8 @@ SQL_ROW row; } rlm_sql_mysql_sock; +static int sql_free_result(SQLSOCK*, SQL_CONFIG*); + /************************************************************************* * * Function: sql_create_socket @@ -82,7 +84,7 @@ config->sql_db, atoi(config->sql_port), NULL, - CLIENT_FOUND_ROWS))) { + CLIENT_FOUND_ROWS|CLIENT_MULTI_STATEMENTS))) { radlog(L_ERR, "rlm_sql_mysql: Couldn't connect socket to MySQL server %s@%s:%s", config->sql_login, config->sql_server, config->sql_db); radlog(L_ERR, "rlm_sql_mysql: Mysql error '%s'", mysql_error(&mysql_sock->conn)); mysql_sock->sock = NULL; @@ -289,6 +291,9 @@ if (sqlsocket->row == NULL) { return sql_check_error(mysql_errno(mysql_sock->sock)); } + + sql_free_result(sqlsocket, config); + return 0; } My SP: CREATE PROCEDURE ssg_auth (IN `CallingStationID` VARCHAR(14),IN `ClientIP` VARCHAR(15)) SQL SECURITY INVOKER BEGIN DECLARE rows INT (1); DECLARE v_id BIGINT (20); DECLARE v_UserName VARCHAR(10); DECLARE v_Attribute,v_Value VARCHAR (30); DECLARE v_op VARCHAR (4); DECLARE v_IP VARCHAR (15); DECLARE user CURSOR FOR SELECT `id`,`UserName`,`Attribute`,`Value`,`op`,`IP` FROM `ssg_check` WHERE `Calling-Station-Id` = `CallingStationID`; SELECT COUNT(*) INTO rows FROM `ssg_check` WHERE `Calling-Station-Id` = `CallingStationID`; IF rows = 0 THEN INSERT INTO `ssg_check` (`Calling-Station-Id`,`IP`) VALUES (`CallingStationID`,`ClientIP`); SELECT '0','Guest','Auth-Type','REJECT',':='; END IF; IF rows = 1 THEN OPEN user; FETCH user INTO v_id,v_UserName,v_Attribute,v_Value,v_op,v_IP; CLOSE user; IF v_Value = 'REJECT' and v_ip != `ClientIP` THEN UPDATE `ssg_check` SET `IP` = `ClientIP` WHERE `Calling-Station-Id` = `CallingStationID`; END IF; SELECT v_id,v_UserName,v_Attribute,v_Value,v_op; END IF; END; // Thomas -- View this message in context: http://www.nabble.com/FR-with-MySQL---Stored-Procedures-tf3701829.html#a1037... Sent from the FreeRadius - User mailing list archive at Nabble.com.
I added this patch to sql_mysql.c and started testing. 1. When I do not call any SPs, it works fine 2. When I call a SP for the first time, it works fine 3. When I call a SP for the second and more time, the 2014 error shows again It seems that these errors happen whenever any SP is called a second time, and there are still some results not freed. Gunther -----Original Message----- From: freeradius-users-bounces+freeradius=caribsms.com@lists.freeradius.org [mailto:freeradius-users-bounces+freeradius=caribsms.com@lists.freeradius.or g] On Behalf Of cky Sent: Tuesday, 08 May 2007 10:18 AM To: freeradius-users@lists.freeradius.org Subject: Re: FR with MySQL - Stored Procedures so...after a while I found a workaround for the SP problem..well, is quick and dirty and probably not the best solution. I've added to the function "sql_fetch_row" in sql_mysql.c a simple "sql_free_result(sqlsocket, config);"...see the diff below. Now my Stored Procedure works correct and as expected (my SP is at the end of this message). Perhaps someone can verify this, and perhaps this can added to the freeradius sourcecode from a developer (well, perhaps not so dirty ;) ) --- sql_mysql.c_org 2007-05-08 15:55:47.000000000 +0200 +++ sql_mysql.c 2007-05-08 15:57:35.000000000 +0200 @@ -50,6 +50,8 @@ SQL_ROW row; } rlm_sql_mysql_sock; +static int sql_free_result(SQLSOCK*, SQL_CONFIG*); + /************************************************************************* * * Function: sql_create_socket @@ -82,7 +84,7 @@ config->sql_db, atoi(config->sql_port), NULL, - CLIENT_FOUND_ROWS))) { + CLIENT_FOUND_ROWS|CLIENT_MULTI_STATEMENTS))) { radlog(L_ERR, "rlm_sql_mysql: Couldn't connect socket to MySQL server %s@%s:%s", config->sql_login, config->sql_server, config->sql_db); radlog(L_ERR, "rlm_sql_mysql: Mysql error '%s'", mysql_error(&mysql_sock->conn)); mysql_sock->sock = NULL; @@ -289,6 +291,9 @@ if (sqlsocket->row == NULL) { return sql_check_error(mysql_errno(mysql_sock->sock)); } + + sql_free_result(sqlsocket, config); + return 0; } My SP: CREATE PROCEDURE ssg_auth (IN `CallingStationID` VARCHAR(14),IN `ClientIP` VARCHAR(15)) SQL SECURITY INVOKER BEGIN DECLARE rows INT (1); DECLARE v_id BIGINT (20); DECLARE v_UserName VARCHAR(10); DECLARE v_Attribute,v_Value VARCHAR (30); DECLARE v_op VARCHAR (4); DECLARE v_IP VARCHAR (15); DECLARE user CURSOR FOR SELECT `id`,`UserName`,`Attribute`,`Value`,`op`,`IP` FROM `ssg_check` WHERE `Calling-Station-Id` = `CallingStationID`; SELECT COUNT(*) INTO rows FROM `ssg_check` WHERE `Calling-Station-Id` = `CallingStationID`; IF rows = 0 THEN INSERT INTO `ssg_check` (`Calling-Station-Id`,`IP`) VALUES (`CallingStationID`,`ClientIP`); SELECT '0','Guest','Auth-Type','REJECT',':='; END IF; IF rows = 1 THEN OPEN user; FETCH user INTO v_id,v_UserName,v_Attribute,v_Value,v_op,v_IP; CLOSE user; IF v_Value = 'REJECT' and v_ip != `ClientIP` THEN UPDATE `ssg_check` SET `IP` = `ClientIP` WHERE `Calling-Station-Id` = `CallingStationID`; END IF; SELECT v_id,v_UserName,v_Attribute,v_Value,v_op; END IF; END; // Thomas -- View this message in context: http://www.nabble.com/FR-with-MySQL---Stored-Procedures-tf3701829.html#a1037 6727 Sent from the FreeRadius - User mailing list archive at Nabble.com. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Did some further research on the MySQL - FR Stored Procedure (SP) problem. When calling the SP, MySQL always returns two results. One is the actual result and the other is the number of affected rows, which is different to a normal e.g. SELECT query. SP: mysql> call CheckIt('myString'); +--------+ | result | +--------+ | 10 | (result is correct) +--------+ 1 row in set (0.00 sec) Query OK, 0 rows affected (0.00 sec) <-- Result plus the number of affected rows! Normal Query: mysql> select 25 AS result; +--------+ | result | +--------+ | 25 | +--------+ 1 row in set (0.00 sec) <--- Normal query with one result -------- MYSQL 5.0 Ref manual ---- If you write C programs that use the CALL SQL statement to execute stored procedures that produce result sets, you must set the CLIENT_MULTI_RESULTS flag, either explicitly, or implicitly by setting CLIENT_MULTI_STATEMENTS when you call mysql_real_connect(). This is because each such stored procedure produces multiple results: the result sets returned by statements executed within the procedure, as well as a result to indicate the call status. To process the result of a CALL statement, use a loop that calls mysql_next_result() to determine whether there are more results. The following procedure outlines a suggested strategy for handling multiple statements: 1. Pass CLIENT_MULTI_STATEMENTS to mysql_real_connect(), to fully enable multiple-statement execution and multiple-result processing. 2. After calling mysql_query() or mysql_real_query() and verifying that it succeeds, enter a loop within which you process statement results. 3. For each iteration of the loop, handle the current statement result, retrieving either a result set or an affected-rows count. If an error occurs, exit the loop. 4. At the end of the loop, call mysql_next_result() to check whether another result exists and initiate retrieval for it if so. If no more results are available, exit the loop. ---------------------------------- Just for a test, I added a very quick and dirty 'mysql_next_result' into the sql_free_result function of "sql_mysql.c" in row 292 of FR 1.1.6, the same location Thomas used the ..... if (sqlsocket->row == NULL) { return sql_check_error(mysql_errno(mysql_sock->sock)); } mysql_next_result(mysql_sock->sock); /* eat the number of affected rows result */ return 0; } ..... As a result I do not get the 2014 error anymore and everything seems to be working fine. Since I do not really know the implications of just adding this command, maybe one of the experts could help out here. In an ealier posting 3 days ago I said that the problem is not really stored procedure related ... but it is! Once the SP is called at least once other queries will have errors too. Gunther FR 1.1.6 - MySQL 5.0.41 - CentOS 4.4
I added your hack to my version too.
I also don't get any errors till now. It seems to work with SP, and also
normal SQL-querys.
I've modified your patch with some comments and also added a
mysql_version check, so that the patch will only apply to MySQL version
> 5.
Here is the diff...so please, a FR developer take a look at it;)
Thanks, Thomas
--- sql_mysql.c 2007-05-08 15:55:47.000000000 +0200
+++ sql_mysql.c 2007-05-10 10:56:33.000000000 +0200
@@ -75,6 +75,7 @@
mysql_init(&(mysql_sock->conn));
mysql_options(&(mysql_sock->conn), MYSQL_READ_DEFAULT_GROUP,
"freeradius");
+
if (!(mysql_sock->sock = mysql_real_connect(&(mysql_sock->conn),
config->sql_server,
config->sql_login,
@@ -82,7 +83,16 @@
config->sql_db,
atoi(config->sql_port),
NULL,
- CLIENT_FOUND_ROWS)))
{
+ CLIENT_FOUND_ROWS
+ #if MYSQL_VERSION_ID
>= 50000
+ /*
+ * the
CLIENT_MULTI_STATEMENTS flag also include the
+ *
CLIENT_MULTI_RESULT flag, these are necessary for
+ * Stored
Procedures (MySQL 5.x)
+ */
+ |
CLIENT_MULTI_STATEMENTS
+ #endif
+ ))) {
radlog(L_ERR, "rlm_sql_mysql: Couldn't connect socket to
MySQL server %s@%s:%s", config->sql_login, config->sql_server,
config->sql_db);
radlog(L_ERR, "rlm_sql_mysql: Mysql error '%s'",
mysql_error(&mysql_sock->conn));
mysql_sock->sock = NULL;
@@ -289,6 +299,18 @@
if (sqlsocket->row == NULL) {
return sql_check_error(mysql_errno(mysql_sock->sock));
}
+
+ #if MYSQL_VERSION_ID >= 50000
+ /*
+ * Stored Procedures return two results (the result and
affected rows),
+ * so FR fails with a mysql errorcode 2014
(CR_COMMANDS_OUT_OF_SYNC),
+ * when a second mysql-query is executed
+ *
+ * so we drop the second result (assume FR expect just
one result)
+ */
+ mysql_next_result(mysql_sock->sock);
+ #endif
+
return 0;
}
Thomas Martens wrote:
I added your hack to my version too. I also don't get any errors till now. It seems to work with SP, and also normal SQL-querys.
Sounds good to me.
Here is the diff...so please, a FR developer take a look at it;)
Nicolas is looking into it. It should be in 1.1.7 && in 2.0. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
That is great news! Alan DeKok wrote:
Thomas Martens wrote:
I added your hack to my version too. I also don't get any errors till now. It seems to work with SP, and also normal SQL-querys.
Sounds good to me.
Here is the diff...so please, a FR developer take a look at it;)
Nicolas is looking into it. It should be in 1.1.7 && in 2.0.
participants (6)
-
A.L.M.Buxey＠lboro.ac.uk -
Alan DeKok -
Arran Cudbard-Bell -
cky -
Gunther -
Thomas Martens