Redundant SQL servers accounting problem, FreeRadius 1.1.4
Hello! I set up redundant SQL PostgeSQL servers configuration: modules{ ... sql sql2 { server = "gw-core.up.ua" num_sql_socks = 3 ... } sql sql1 { server = "sql.up.ua" num_sql_socks = 3 ... } } authorize { ... redundant { sql2 sql1 } } ... accounting { ... redundant { sql2 sql1 } } If sql2 is up when I run FreeRadius, everything works fine. If sql2 is down when I start FreeRadius, everything works fine too and when sql2 comes up, Freeradius starts to use it. But when sql2 was up and then comes down (and FreeRadius is running), FreeRadius exits when it processes accounting query with message in syslog kernel: pid 4516 (radiusd), uid 1002: exited on signal 6 I started it in debug mode: #/usr/local/sbin/radiusd -X ... Processing the authorize section of radiusd.conf modcall: entering group authorize for request 0 ... modcall: entering group redundant for request 0 radius_xlat: 'klepikov_av' rlm_sql (sql2): sql_set_user escaped user --> 'klepikov_av' radius_xlat: 'SELECT id, UserName, Attribute, Value, Op ??FROM radcheck ??WHERE Username = 'klepikov_av' ??ORDER BY id' rlm_sql (sql2): Reserving sql socket id: 2 rlm_sql_postgresql: Status: PGRES_FATAL_ERROR rlm_sql_postgresql: affected rows = rlm_sql_postgresql: Postgresql check_error: PGRES_FATAL_ERROR, returning SQL_DOW N rlm_sql (sql2): Attempting to connect rlm_sql_postgresql #2 rlm_sql_postgresql: Couldn't connect socket to PostgreSQL server radius@gw-core. up.ua:radius_db rlm_sql_postgresql: Postgresql error 'could not connect to server: Connection re fused ?Is the server running on host gw-core.up.ua and accepting ?TCP/IP connect ions on port 5432? ' rlm_sql (sql2): Failed to connect DB handle #2 rlm_sql (sql2): reconnect failed, database down? rlm_sql_getvpdata: database query error rlm_sql (sql2): SQL query error; rejecting user rlm_sql (sql2): Released sql socket id: 2 modcall[authorize]: module "sql2" returns fail for request 0 rlm_sql (sql1): sql_set_user escaped user --> 'klepikov_av' radius_xlat: 'SELECT id, UserName, Attribute, Value, Op ??FROM radcheck ??WHERE Username = 'klepikov_av' ??ORDER BY id' rlm_sql (sql1): Reserving sql socket id: 1 rlm_sql_postgresql: Status: PGRES_TUPLES_OK ... rlm_sql (sql1): Released sql socket id: 1 modcall[authorize]: module "sql1" returns ok for request 0 modcall: leaving group redundant (returns ok) for request 0 modcall: leaving group authorize (returns ok) for request 0 ... Processing the accounting section of radiusd.conf modcall: entering group accounting for request 1 ... modcall: entering group redundant for request 1 radius_xlat: 'klepikov_av' rlm_sql (sql2): sql_set_user escaped user --> 'klepikov_av' radius_xlat: 'INSERT into radacct ??(AcctSessionId, AcctUniqueId, UserName, Rea lm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctAuthentic, ??Connec tInfo_start, CalledStationId, CallingStationId, ServiceType, FramedProtocol, Fra medIPAddress, AcctStartDelay) ??values('45FA990A460300', 'e55d351c2f2bdb96', 'kl epikov_av', 'up.ua', '10.0.0.1', ??'1', 'Async', ('2007-03-16 15:18:02'::timesta mp - '0'::interval), 'RADIUS', '', ??'', '10.1.1.3', 'Framed-User', 'PPP', ??NUL LIF('10.0.1.15', '')::inet, '0')' rlm_sql (sql2): Reserving sql socket id: 0 rlm_sql_postgresql: Status: PGRES_FATAL_ERROR rlm_sql_postgresql: affected rows = rlm_sql_postgresql: Postgresql check_error: PGRES_FATAL_ERROR, returning SQL_DOW N rlm_sql (sql2): Attempting to connect rlm_sql_postgresql #0 rlm_sql_postgresql: Couldn't connect socket to PostgreSQL server radius@gw-core. up.ua:radius_db rlm_sql_postgresql: Postgresql error 'could not connect to server: Connection re fused ?Is the server running on host gw-core.up.ua and accepting ?TCP/IP connect ions on port 5432? ' rlm_sql (sql2): Failed to connect DB handle #0 rlm_sql (sql2): reconnect failed, database down? rlm_sql (sql2): Couldn't insert SQL accounting START record - (null) radius_xlat: 'UPDATE radacct ??SET AcctStartTime = ('2007-03-16 15:18:02'::time stamp - '0'::interval), AcctStartDelay = '0', ??ConnectInfo_start = '' WHERE Acc tSessionId = '45FA990A460300' AND UserName = 'klepikov_av' ??AND NASIPAddress = '10.0.0.1' AND AcctStopTime IS NULL' rlm_sql_postgresql: PostgreSQL Query failed Error: no connection to the server radiusd in free(): error: chunk is already free Abort It looks like accounting module cannot properly make a connection to SQL server, but authorize module can. I found that with num_sql_socks <= 2 FreeRadius works perfect, I made several tests stopping and starting my SQL servers, everything works as it is described in manuals. It seemes to me that problem is somewhere in rlm_sql module, but I am not a programmer, so I can't just find it and write a patch. I use FreeBSD 6.2, FreeRadius 1.1.4, PostgreSQL 7.3.15 (to be exact, PGCluster 1.0.11), the same problem was with PostgreSQL 8.2.3 (to be exact, PGCluster 1.7.0rc5) To reproduce this problem, set up FreeRadius as mentioned above, start databases, start FreeRadius and then stop first database listed in redundant group. With best regards, Alexander V. Klepikov. E-mail: klepikov_a@up.ua PS Sorry for my bad english
Alexander V. Klepikov wrote: ...
rlm_sql_postgresql: PostgreSQL Query failed Error: no connection to the server radiusd in free(): error: chunk is already free
Please run the server under valgrind. I don't use postgresql, so I can't tell what's going wrong. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Hello, Alexander! You wrote to All on Fri, 16 Mar 2007 17:23:19 +0200: AVK> It looks like accounting module cannot properly make a connection AVK> to SQL AVK> server, but authorize module can. I found that with num_sql_socks AVK> <= 2 AVK> FreeRadius works perfect, I made several tests stopping and AVK> starting my SQL Well, I think I found why FreeRadius crashes. Unconnected SQL socket is passed to sql_close function in module rlm_sql in function rlm_sql_query (src/modules/rlm_sql/sql.c line 499). Here is the patch: =========Beginning of the citation============== --- src/modules/rlm_sql/sql.c Fri Aug 26 03:37:47 2005 +++ src/modules/rlm_sql/sql.c Mon Mar 19 16:11:57 2007 @@ -496,6 +496,7 @@ if (ret == SQL_DOWN) { /* close the socket that failed */ + if (sqlsocket->state == sockconnected) (inst->module->sql_close)(sqlsocket, inst->config); /* reconnect the socket */ =========The end of the citation================ My tests shows that problem is gone. I hope I patched right piece of code :) With best regards, Alexander V. Klepikov. E-mail: klepikov_a@up.ua
Alexander V. Klepikov wrote:
Well, I think I found why FreeRadius crashes. Unconnected SQL socket is passed to sql_close function in module rlm_sql in function rlm_sql_query (src/modules/rlm_sql/sql.c line 499). Here is the patch:
Hmm... it looks like similar patches were added in revision 1.72 of that file. I've double-checked the code, and found one more location. Please try the attached patch.
My tests shows that problem is gone. I hope I patched right piece of code :)
If it works... Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog Index: src/modules/rlm_sql/sql.c =================================================================== RCS file: /source/radiusd/src/modules/rlm_sql/sql.c,v retrieving revision 1.79.2.3 diff -u -r1.79.2.3 sql.c --- src/modules/rlm_sql/sql.c 26 Aug 2005 00:37:47 -0000 1.79.2.3 +++ src/modules/rlm_sql/sql.c 19 Mar 2007 16:52:33 -0000 @@ -496,7 +496,9 @@ if (ret == SQL_DOWN) { /* close the socket that failed */ - (inst->module->sql_close)(sqlsocket, inst->config); + if (sqlsocket->conn) { + (inst->module->sql_close)(sqlsocket, inst->config); + } /* reconnect the socket */ if (connect_single_socket(sqlsocket, inst) < 0) { @@ -539,7 +541,9 @@ if (ret == SQL_DOWN) { /* close the socket that failed */ - (inst->module->sql_close)(sqlsocket, inst->config); + if (sqlsocket->conn) { + (inst->module->sql_close)(sqlsocket, inst->config); + } /* reconnect the socket */ if (connect_single_socket(sqlsocket, inst) < 0) {
Hello, Alan! You wrote on Mon, 19 Mar 2007 17:54:52 +0100: AD> Hmm... it looks like similar patches were added in revision 1.72 AD> of AD> that file. I've double-checked the code, and found one more AD> location. AD> Please try the attached patch. I applied the patch and it does not work. It seemes to me, it's becuase SQL socket may be unconnected and sqlsocket->conn != NULL, so I think it's better to check sqlsocket->state . Corrected patch is attached. With best regards, Alexander V. Klepikov. E-mail: klepikov_a@up.ua
Alexander V. Klepikov wrote:
I applied the patch and it does not work. It seemes to me, it's becuase SQL socket may be unconnected and sqlsocket->conn != NULL,
That sounds like a bug to me.
so I think it's better to check sqlsocket->state . Corrected patch is attached.
OK. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Hello, Alan! You wrote on Tue, 20 Mar 2007 12:47:01 +0100: AD> Alexander V. Klepikov wrote:
I applied the patch and it does not work. It seemes to me, it's becuase SQL socket may be unconnected and sqlsocket->conn != NULL,
AD> That sounds like a bug to me. It seemes to me I begin to understand, what is going on in the module rlm_sql_postgresql, but it is very difficult to me to write my conclusions in english. I'm afraid this is not a bug. I looked in the sources, and I found that in module rlm_sql_postgresql in all functions is used construction rlm_sql_postgres_sock *pg_sock = sqlsocket->conn; Then all calls to libpq (the real PostgreSQL driver) deal with pg_sock->conn. Here is one of the best illustrations, function sql_init_socket : =========Beginning of the citation============== static int sql_init_socket(SQLSOCK *sqlsocket, SQL_CONFIG *config) { char connstring[2048]; char *port, *host; rlm_sql_postgres_sock *pg_sock; if (config->sql_server[0] != '\0') { host = " host="; } else { host = ""; } if (config->sql_port[0] != '\0') { port = " port="; } else { port = ""; } if (!sqlsocket->conn) { sqlsocket->conn = (rlm_sql_postgres_sock *)rad_malloc(sizeof(rlm_sql_postgres_sock)); if (!sqlsocket->conn) { return -1; } } pg_sock = sqlsocket->conn; memset(pg_sock, 0, sizeof(*pg_sock)); snprintf(connstring, sizeof(connstring), "dbname=%s%s%s%s%s user=%s password=%s", config->sql_db, host, config->sql_server, port, config->sql_port, config->sql_login, config->sql_password); pg_sock->row=NULL; pg_sock->result=NULL; pg_sock->conn=PQconnectdb(connstring); if (PQstatus(pg_sock->conn) == CONNECTION_BAD) { radlog(L_ERR, "rlm_sql_postgresql: Couldn't connect socket to PostgreSQL server %s@%s:%s", config->sql_login, co radlog(L_ERR, "rlm_sql_postgresql: Postgresql error '%s'", PQerrorMessage(pg_sock->conn)); PQfinish(pg_sock->conn); return SQL_DOWN; } return 0; } =========The end of the citation================ You see, first sqlsocket->conn is inited and all database parameters are set.Then a connection attempt is made: pg_sock->conn=PQconnectdb(connstring) . If connection to DB fails, PQfinish(pg_sock->conn) is called, which frees pg_sock->conn - need to do this is described in libpq docs. So even in case of unsuccessefull connection we have good "database handle" sqlsocket->conn, which should not be NULL. When FreeRadius starts, sql_init_socketpool is called. It inits all SQL sockets and attempts to connect to database(s). I did not find any information about what is going on when database or SQL server suddenly comes down, but it looks like pg_sock->conn is freed when connection to DB became broken. And pg_sock->conn != NULL . That's why libpq crashes when PQfinish(pg_sock->conn) in sql_close function is called. As far I understand, this is expected behavior. According to this, I can make a conclusion that when database handle is checked for connectivity (in rlm_sql module), sqlsocket->state should be used. In theory, sqlsocket->state can equals to sockconnected when actually it is disconnected. It seemes to me, actually this can happen very rarely. May be, state of connection should be checked before running every SQL query to minimize risk of operation on disconnected DB, but I believe it's not necessary yet. Besides, it will require to modify all sql drivers. I think there is few places left in rlm_sql module where sqlsocket->conn should be replaced with sqlsocket->state. I'm sure I can find and patch them. With best regards, Alexander V. Klepikov. E-mail: klepikov_a@up.ua
Alexander V. Klepikov wrote:
I did not find any information about what is going on when database or SQL server suddenly comes down, but it looks like pg_sock->conn is freed when connection to DB became broken. And pg_sock->conn != NULL . That's why libpq crashes when PQfinish(pg_sock->conn) in sql_close function is called.
It seems to me this is the real cause of the problem: pg_sock->conn becomes an invalid pointer. The libpq manpage says the PGconn pointer should not be used after PQfinish has been called. Please try the following patch: Index: src/modules/rlm_sql/drivers/rlm_sql_postgresql/sql_postgresql.c =================================================================== RCS file: /source/radiusd/src/modules/rlm_sql/drivers/rlm_sql_postgresql/sql_postgresql.c,v retrieving revision 1.38.4.1 diff -u -r1.38.4.1 sql_postgresql.c --- src/modules/rlm_sql/drivers/rlm_sql_postgresql/sql_postgresql.c 14 Dec 2005 18:32:03 -0000 1.38.4.1 +++ src/modules/rlm_sql/drivers/rlm_sql_postgresql/sql_postgresql.c 21 Mar 2007 11:28:17 -0000 @@ -61,6 +61,7 @@ /* Prototypes */ static int sql_store_result(SQLSOCK * sqlsocket, SQL_CONFIG *config); static int sql_num_fields(SQLSOCK * sqlsocket, SQL_CONFIG *config); +static int sql_close(SQLSOCK * sqlsocket, SQL_CONFIG *config); /* Internal function. Return true if the postgresql status value * indicates successful completion of the query. Return false otherwise @@ -181,7 +182,7 @@ if (PQstatus(pg_sock->conn) == CONNECTION_BAD) { radlog(L_ERR, "rlm_sql_postgresql: Couldn't connect socket to PostgreSQL server %s@%s:%s", config->sql_login, config->sql_server, config->sql_db); radlog(L_ERR, "rlm_sql_postgresql: Postgresql error '%s'", PQerrorMessage(pg_sock->conn)); - PQfinish(pg_sock->conn); + sql_close(sqlsocket, config); return SQL_DOWN; } -- Nicolas Baradakis
Nicolas Baradakis wrote:
It seems to me this is the real cause of the problem: pg_sock->conn becomes an invalid pointer. The libpq manpage says the PGconn pointer should not be used after PQfinish has been called.
Please try the following patch:
I think it should be applied, independent of anything else. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Hello, Nicolas! You wrote on Wed, 21 Mar 2007 12:37:03 +0100: NB> It seems to me this is the real cause of the problem: pg_sock->conn NB> becomes NB> an invalid pointer. The libpq manpage says the PGconn pointer should NB> not be NB> used after PQfinish has been called. NB> Please try the following patch: [Sorry, skipped] Yes, it solves the problem. Thank you! Very simple solution! But according to Alan it looks like we have discovered a real problem... With best regards, Alexander V. Klepikov. E-mail: klepikov_a@up.ua
Alexander V. Klepikov wrote:
... If connection to DB fails, PQfinish(pg_sock->conn) is called, which frees pg_sock->conn - need to do this is described in libpq docs. So even in case of unsuccessefull connection we have good "database handle" sqlsocket->conn, which should not be NULL.
If pg_sock->conn is freed, that pointer MUST be set to NULL.
According to this, I can make a conclusion that when database handle is checked for connectivity (in rlm_sql module), sqlsocket->state should be used.
No. sqlsocket->state is redundant. If the "conn" handle exists, it MUST be a valid connection handle. If it's not valid, it's NULL, and therefore the socket is disconnected.
In theory, sqlsocket->state can equals to sockconnected when actually it is disconnected.
That's a bug. It's wrong and MUST be fixed.
It seemes to me, actually this can happen very rarely. May be, state of connection should be checked before running every SQL query to minimize risk of operation on disconnected DB, but I believe it's not necessary yet. Besides, it will require to modify all sql drivers.
Then we modify all of the SQL drivers. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Hello, Alan! You wrote on Wed, 21 Mar 2007 12:57:46 +0100: After Nicolas Baradakis's patch some things changed. Now I know that if connection to PostgreSQL DB became broken, libpq does not free pg_sock->conn, so PQfinish(pg_sock->conn) MUST be called. AD> If pg_sock->conn is freed, that pointer MUST be set to NULL. Yes, I understand that. AD> No. sqlsocket->state is redundant. If the "conn" handle exists, AD> it AD> MUST be a valid connection handle. If it's not valid, it's NULL, AD> and AD> therefore the socket is disconnected. Then each time sql_destroy_socket MUST be called after sql_close in database drivers and especially in sql_init_socket when DB connection can't be established. Of course, sqlsocket->state MUST be set then too, maybe in sql_destroy_socket function. It concerns all SQL drivers.
In theory, sqlsocket->state can equals to sockconnected when actually it is disconnected.
I make some additional tests. When DB connection suddenly breakes, sqlsocket->state == sockconnected. AD> That's a bug. It's wrong and MUST be fixed. It seemes to me it would be hard to do. The simplest way I see is to use instead of sqlsocket->state a function that is declared in sql driver module. For PostgreSQL it may look so: static int IsConnected(SQLSOCK *sqlsocket); { rlm_sql_postgres_sock *pg_sock; if (sqlsocket->conn != NULL) { pg_sock = sqlsocket->conn; if ((pg_sock->conn != NULL) && (PQstatus(pg_sock->conn) == CONNECTION_OK)) { return -1; } else { sql_close(sqlsocket,config); sql_destroy(sqlsocket); return 0; } } else return 0; } It seemes to me, it's almost impossible to write code which will allow sqlsocket->conn to provide accurate information about connection state. But again, I'm not a programmer. With best regards, Alexander V. Klepikov. E-mail: klepikov_a@up.ua
Alexander V. Klepikov wrote:
It seemes to me, it's almost impossible to write code which will allow sqlsocket->conn to provide accurate information about connection state. But again, I'm not a programmer.
If that's true, then we still need to audit all of the sql code. Some code does "if (sqlsocket->conn)...", which would then be wrong. It should be "if (sqlsocket->state == sqlconnected) ..." And the "enum" defining "sqlconnected" and "sqlunconnected" should be changed so that 0 means "unconnected". That change avoids other issues, too. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Alexander V. Klepikov wrote:
I make some additional tests. When DB connection suddenly breakes, sqlsocket->state == sockconnected.
I' ve committed a fix to "-r branch_1_1". Please test it, to see if it works. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Hello, Alan! You wrote on Mon, 26 Mar 2007 10:50:17 +0100: AD> I' ve committed a fix to "-r branch_1_1". Please test it, to see AD> if AD> it works. To get it I typed cvs -d :pserver:anoncvs@cvs.freeradius.org:/source checkout -r branch_1_1 radiusd Am I right? I got troubles with running it: =========Beginning of the citation============== Ready to process requests. rad_recv: Access-Request packet from host 10.0.0.1:54081, id=187, length=150 Service-Type = Framed-User Framed-Protocol = PPP User-Name = "klepikov_av" MS-CHAP-Challenge = 0x1d764e6c7150aff0fe12e7b36e4b2820 MS-CHAP2-Response = 0x870014fadc301b947b74c9a4ff099e1b2cbc00000000000000 0023c02712972225b77413cb9a4c00fbac6634cfcacf857aec Calling-Station-Id = "10.1.1.3" NAS-Identifier = "up.ua" NAS-Port = 0 Processing the authorize section of radiusd.conf modcall: entering group authorize for request 0 [Switching to Thread 0x806f000 (LWP 100086)] Breakpoint 1, modcall (component=1, c=0x813b640, request=0x816f900) at modcall.c:236 236 myresult = sp->modinst->entry->module->methods[component]( (gdb) step Program received signal SIGSEGV, Segmentation fault. 0x28349e28 in rad_mangle () from /usr/local/lib/rlm_preprocess-1.1.4.so (gdb) bt #0 0x28349e28 in rad_mangle () from /usr/local/lib/rlm_preprocess-1.1.4.so #1 0x2834a22d in preprocess_authorize () from /usr/local/lib/rlm_preprocess-1.1.4.so #2 0x08054be6 in modcall (component=1, c=0x813b640, request=0x816f900) at modcall.c:236 #3 0x080551f0 in call_one (component=-559038737, p=0x813b640, request=0x816f900, priority=0xbfbfccfc, result=0xbfbfcd00) at modcall.c:269 #4 0x08054e7e in modcall (component=1, c=0x813b680, request=0x816f900) at modcall.c:324 #5 0x0805405c in indexed_modcall (comp=1, idx=135723264, request=0x816f900) at modules.c:469 #6 0x0804d0c8 in rad_authenticate (request=0x816f900) at auth.c:602 #7 0x08056b71 in rad_respond (request=0x816f900, fun=0x804cfd8 <rad_authenticate>) at radiusd.c:1669 #8 0x08058299 in main (argc=2, argv=0xbfbfec94) at radiusd.c:1434 =========The end of the citation================ With best regards, Alexander V. Klepikov. E-mail: klepikov_a@up.ua
Alexander V. Klepikov wrote:
To get it I typed
cvs -d :pserver:anoncvs@cvs.freeradius.org:/source checkout -r branch_1_1 radiusd
Am I right?
Yes.
I got troubles with running it: ... Program received signal SIGSEGV, Segmentation fault. 0x28349e28 in rad_mangle () from /usr/local/lib/rlm_preprocess-1.1.4.so
You are using libraries from an older version of the server. Please ensure that you're running a clean install of "branch_1_1". Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Hello, Alan! You wrote on Mon, 26 Mar 2007 10:50:17 +0100: AD> I' ve committed a fix to "-r branch_1_1". Please test it, to see AD> if AD> it works. Yes, freeradius works without crashes when DB suddenly comes down and then up. With best regards, Alexander V. Klepikov. E-mail: klepikov_a@up.ua
participants (3)
-
Alan DeKok -
Alexander V. Klepikov -
Nicolas Baradakis