sqlippool on 3.0.18
Hi, Wading in to this one now - not sure if this is a bug or if it’s known/fixed so posting here in the hope someone else has had this and looked in to it. If not, I’m learning a lot, so, that’s good. Will post more when I have it. I’m testing upgrading to 3.0.18, and when I get an Accounting-On with sqlippool (I am running a NAS simulator which sends Accounting-On first, not sure if other messages are impacted), I get: <snip> rlm_sql (sql-radiusippool): Reserved connection (0) (0) sqlippool-ipv4: EXPAND %{%{Chargeable-User-Identity}:-%{%{Stripped-User-Name}:-UNKNOWN}} (0) sqlippool-ipv4: --> UNKNOWN (0) sqlippool-ipv4: SQL-User-Name set to 'UNKNOWN' (0) sqlippool-ipv4: EXPAND START TRANSACTION (0) sqlippool-ipv4: --> START TRANSACTION (0) sqlippool-ipv4: Executing query: START TRANSACTION rlm_sql_postgresql: Status: PGRES_COMMAND_OK rlm_sql_postgresql: query affected rows = 0 src/modules/rlm_sql/rlm_sql.c:381: Type mismatch: name[rlm_sql_t] expected[rlm_sql_handle_t] talloc abort: src/modules/rlm_sql/rlm_sql.c:381: Type mismatch: name[rlm_sql_t] expected[rlm_sql_handle_t] </snip> src/modules/rlm_sqlippool/rlm_sqlippool.c:320 is: if (radius_axlat(&expanded, request, query, data->sql_inst->sql_escape_func, data->sql_inst) < 0) return -1; And I notice in Herwin Weststrate’s commit @ c8736367583 there is a lot of use of the handle as the last param for that function rather than the sql module instance: - if (radius_axlat(&expanded, request, inst->config->simul_verify_query, sql_escape_func, inst) < 0) { + if (radius_axlat(&expanded, request, inst->config->simul_verify_query, inst->sql_escape_func, handle) < 0) { Etc. so I’m thinking that commit didn’t take sqlippool in to account. I notice there’s a new function, sql_escape_for_xlat_func, which gets a connection from the pool then releases it, but I’m not sure that’s right for this situation in sqlippool - we’re doing these xlats in the middle of a transaction, so we should have a handle already? I've tried passing the handle to radius_axlat rather than the instance, i.e. (in rlm_sqlippool.c): - if (radius_axlat(&expanded, request, query, data->sql_inst->sql_escape_func, data->sql_inst) < 0) return -1; + if (radius_axlat(&expanded, request, query, data->sql_inst->sql_escape_func, handle) < 0) return -1; But now I get a talloc error - <snip> (0) sqlippool-ipv4: Executing query: START TRANSACTION rlm_sql_postgresql: Status: PGRES_COMMAND_OK rlm_sql_postgresql: query affected rows = 0 Bad talloc magic value - unknown value talloc abort: Bad talloc magic value - unknown value </snip> Here’s a backtrace for that - note the handle is passed through, so I’m not entirely clear why this is objecting. Is the handle freed somewhere? I’m wondering if this is simply because we’re running several queries in a transaction - the first query (i.e. START TRANSACTION) is always fine, even if I put an xlat in it. The second query always triggers this error. Should this handle even still be useable? The next line after the one I’ve changed above calls sql_query, which needs handle to have a ‘conn’ member, so, I expect so.. #3 0x00007fa228d5e77a in _talloc_get_type_abort () from /lib64/libtalloc.so.2 #4 0x00007fa2210f0f40 in sql_escape_func (request=request@entry=0x55a14277f330, out=out@entry=0x55a1427820d0 "", outlen=outlen@entry=30, in=0x55a1427819b0 "192.0.2.0", arg=arg@entry=0x7ffeb7db2ba0) at src/modules/rlm_sql/rlm_sql.c:381 #5 0x00007fa229aa6afe in xlat_aprint (ctx=ctx@entry=0x55a14277f330, request=0x55a14277f330, node=<optimized out>, escape=escape@entry=0x7fa2210f0f10 <sql_escape_func>, escape_ctx=0x7ffeb7db2ba0, lvl=0) at src/main/xlat.c:2371 #6 0x00007fa229aa7aed in xlat_process (out=0x7ffeb7db1990, request=0x55a14277f330, head=0x55a142781f60, escape=0x7fa2210f0f10 <sql_escape_func>, escape_ctx=0x7ffeb7db2ba0) at src/main/xlat.c:2410 #7 0x00007fa229aa6b51 in xlat_aprint (ctx=ctx@entry=0x55a142781a30, request=request@entry=0x55a14277f330, node=node@entry=0x55a142781df0, escape=escape@entry=0x7fa2210f0f10 <sql_escape_func>, escape_ctx=escape_ctx@entry=0x7ffeb7db2ba0, lvl=0) at src/main/xlat.c:2344 #8 0x00007fa229aa79d1 in xlat_process (out=0x7ffeb7db1a90, request=0x55a14277f330, head=<optimized out>, escape=0x7fa2210f0f10 <sql_escape_func>, escape_ctx=0x7ffeb7db2ba0) at src/main/xlat.c:2428 #9 0x00007fa229aa7b44 in xlat_expand_struct (out=out@entry=0x7ffeb7db1b48, outlen=outlen@entry=0, request=request@entry=0x55a14277f330, node=<optimized out>, escape=escape@entry=0x7fa2210f0f10 <sql_escape_func>, escape_ctx=escape_ctx@entry=0x7ffeb7db2ba0) at src/main/xlat.c:2482 #10 0x00007fa229aa8094 in xlat_expand (out=out@entry=0x7ffeb7db1b48, outlen=outlen@entry=0, request=request@entry=0x55a14277f330, fmt=fmt@entry=0x7ffeb7db1b50 "UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', expiry_time = 'now'::timestamp(0) - '1 second'::interval WHERE nasipaddress = '%{%{Nas-IP-Address}:-%{Nas-IPv6-Address}}'", escape=0x7fa2210f0f10 <sql_escape_func>, escape_ctx=escape_ctx@entry=0x7ffeb7db2ba0) at src/main/xlat.c:2547 #11 0x00007fa229aa95fa in radius_axlat (out=out@entry=0x7ffeb7db1b48, request=request@entry=0x55a14277f330, fmt=fmt@entry=0x7ffeb7db1b50 "UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', expiry_time = 'now'::timestamp(0) - '1 second'::interval WHERE nasipaddress = '%{%{Nas-IP-Address}:-%{Nas-IPv6-Address}}'", escape=<optimized out>, ctx=ctx@entry=0x7ffeb7db2ba0) at src/main/xlat.c:2617 #12 0x00007fa2212fae4f in sqlippool_command (fmt=<optimized out>, handle=handle@entry=0x7ffeb7db2ba0, data=data@entry=0x55a14264d250, request=request@entry=0x55a14277f330, param=param@entry=0x0, param_len=param_len@entry=0) at src/modules/rlm_sqlippool/rlm_sqlippool.c:320 #13 0x00007fa2212fb66e in mod_accounting_on (request=0x55a14277f330, inst=0x55a14264d250, handle=0x7ffeb7db2ba0) at src/modules/rlm_sqlippool/rlm_sqlippool.c:706 #14 mod_accounting (instance=0x55a14264d250, request=0x55a14277f330) at src/modules/rlm_sqlippool/rlm_sqlippool.c:779 -- Nathan Ward
On Feb 27, 2019, at 12:44 AM, Nathan Ward <lists+freeradius@daork.net> wrote:
Wading in to this one now - not sure if this is a bug or if it’s known/fixed so posting here in the hope someone else has had this and looked in to it. If not, I’m learning a lot, so, that’s good. Will post more when I have it.
I've pulled over your fixes from the GitHub pull request.
Etc. so I’m thinking that commit didn’t take sqlippool in to account.
Yes.
I notice there’s a new function, sql_escape_for_xlat_func, which gets a connection from the pool then releases it, but I’m not sure that’s right for this situation in sqlippool - we’re doing these xlats in the middle of a transaction, so we should have a handle already?
Yes. We may need to release 3.0.19 soon. <sigh> The underlying issue is that we simply can't test everything in the server. We rely on the community to supply good patches, and to test those patches before an official release. Alan DeKok.
participants (2)
-
Alan DeKok -
Nathan Ward