[MDEV-30200] Inconsistent UDF behavior with respect to `max_length` Created: 2022-12-12  Updated: 2023-11-28

Status: Open
Project: MariaDB Server
Component/s: None
Affects Version/s: 10.9, 10.10
Fix Version/s: 10.4, 10.5, 10.6, 10.11

Type: Bug Priority: Minor
Reporter: Trevor Gross Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: UDF
Environment:

`mariadb:10.9` and `mariadb:10.10` docker images


 Description   

There is some inconsistent behavior for the `result`/`length` behavior in string-based user-defined functions.

This isn't exactly documented in MariaDB, but from the MySQL docs:

MySQL passes a buffer to the xxx() function using the result parameter. This buffer is sufficiently long to hold 255 characters, which can be multibyte characters. The xxx() function can store the result in this buffer if it fits, in which case the return value should be a pointer to the buffer. If the function stores the result in a different buffer, it should return a pointer to that buffer.

MariaDB and MySQL have the same behavior: if a `cfg.max_length` is set in `xxx_init()` that is less than 255, then the `result` buffer will have a length of 766 when `xxx()` is called (I am unsure why 766 and not `cfg.max_length`).

However, this behavior differs when `xxx` is called within another function or in some different contexts, e.g. `yyy(xxx())`. For some reason, this pattern makes MariaDB pass a `length` of 0 to `xxx()`, rather than the expected `max_length` or 755.
I have a simple function `lookup6` that returns an ipv6 IP for a host if found. Example correct behavior: logs when running `select lookup6('0.0.0.0')`:

2022-12-11T23:39:13.7807854Z 2022-12-11 23:39:13+00:00 [Debug] UDF: entering process for `udf_examples::lookup::Lookup6`
 
2022-12-11T23:39:13.7808068Z 2022-12-11 23:39:13+00:00 [Debug] UDF: Data receive state at process:
 
2022-12-11T23:39:13.7808209Z [udf/src/wrapper/debug.rs:157] &*initid = UDF_INIT {
 
2022-12-11T23:39:13.7808298Z     maybe_null: true,
 
// NOTE: max_length
 
...
 
2022-12-11T23:39:13.7808810Z }
 
...
 
2022-12-11T23:39:13.7810121Z [udf/src/wrapper/debug.rs:159] result = 0x00007f2538bb36c0
 
// NOTE: got a buffer of length 766
 
2022-12-11T23:39:13.7810254Z [udf/src/wrapper/debug.rs:160] &*length = 766
 
2022-12-11T23:39:13.7810375Z [udf/src/wrapper/debug.rs:161] &*is_null = 0
 
2022-12-11T23:39:13.7810494Z [udf/src/wrapper/debug.rs:162] &*error = 0

Example of the problem: logs when running `set @testval = (select lookup6('0.0.0.0'))`

2022-12-11T23:39:13.7820777Z 2022-12-11 23:39:13+00:00 [Debug] UDF: entering process for `udf_examples::lookup::Lookup6`
 
2022-12-11T23:39:13.7820987Z 2022-12-11 23:39:13+00:00 [Debug] UDF: Data receive state at process:
 
// NOTE: max_length
 
2022-12-11T23:39:13.7821126Z [udf/src/wrapper/debug.rs:157] &*initid = UDF_INIT {
 
2022-12-11T23:39:13.7821216Z     maybe_null: true,
 
2022-12-11T23:39:13.7821380Z     max_length: 39,
 
...
 
2022-12-11T23:39:13.7821731Z }
 
...
 
2022-12-11T23:39:13.7822860Z [udf/src/wrapper/debug.rs:159] result = 0x00007f24f807c618
 
// NOTE: length 0
 
2022-12-11T23:39:13.7822984Z [udf/src/wrapper/debug.rs:160] &*length = 0
 
2022-12-11T23:39:13.7823110Z [udf/src/wrapper/debug.rs:161] &*is_null = 0
 
2022-12-11T23:39:13.7823231Z [udf/src/wrapper/debug.rs:162] &*error = 0
 
2022-12-11T23:39:13.7823570Z 2022-12-11 23:39:13+00:00 [Debug] UDF: 0x1 0 bytes server->udf control transfer (udf_examples::lookup::Lookup6)
 
2022-12-11T23:39:13.7824003Z 2022-12-11 23:39:13+00:00 [Critical] UDF: output overflow, returning NULL. Buffer size: 0, data length: 14 at `udf_examples::lookup::Lookup6::process`
 
2022-12-11T23:39:13.7824259Z 2022-12-11 23:39:13+00:00 [Critical] UDF: contact your UDF vendor as this is a serious bug
 
2022-12-11T23:39:13.7824517Z 2022-12-11 23:39:13+00:00 [Critical] UDF: run with `RUST_LIB_BACKTRACE=1` for a full backtrace
 
2022-12-11T23:39:13.7824601Z Backtrace [
 
2022-12-11T23:39:13.7824754Z     { fn: "udf::wrapper::helpers::buf_result_callback" },
 
2022-12-11T23:39:13.7824844Z     { fn: "lookup6" },
 
2022-12-11T23:39:13.7824987Z     { fn: "_ZN11udf_handler7val_strEP6StringS1_" },
 
2022-12-11T23:39:13.7825173Z     { fn: "_ZN17Item_func_udf_str7val_strEP6String" },
 
2022-12-11T23:39:13.7825309Z     { fn: "_ZN22Item_func_set_user_var5checkEb" },
 
...

Source that catches this error: https://github.com/pluots/sql-udf/tree/4e4ded2f1f24bdb1052fe45262f73e87d5f1e2bb

 Comments   
Comment by Trevor Gross [ 2022-12-12 ]

Minimum reproduction:

code:

bool udf_buf_bug_init(UDF_INIT * initid, UDF_ARGS * args, char * message) {
 
    initid->max_length = 100;
 
    fprintf(stderr, "UDF: set max length to 100\n");
 
    return false;
 
}
 
 
 
char * udf_buf_bug(UDF_INIT * initid, UDF_ARGS * args, char * result,
 
    unsigned long * length, unsigned char * is_null, unsigned char * error)
 
{
 
    fprintf(stderr, "UDF: got result buffer of length %ld\n", *length);
 
    *length = 0;
 
    return 0;
 
}


select udf_buf_bug();
 
select hex(udf_buf_bug());

Output:

UDF: set max length to 100
 
UDF: got result buffer of length 766
 
UDF: set max length to 100
 
UDF: got result buffer of length 0

Repo: https://github.com/tgross35/udf-buf-bug

Comment by Trevor Gross [ 2022-12-12 ]

In testing, if I disregard the initial length and write to the buffer anyway, I still get the correct result. This makes me think the buffer still exists at the proper size (755) but the length just isn't getting passed correctly to the call.

Neither of the `char*` examples (metaphon, is_const) check the `*length` value but they probably should since they're technically overwriting their allowed buffers

Comment by Trevor Gross [ 2022-12-12 ]

xref mysql issue: https://bugs.mysql.com/bug.php?id=109335

Generated at Thu Feb 08 10:14:27 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.