ASTERISK-29966: pbx_variables: ast_str

[Home]

Summary: ASTERISK-29966: pbx_variables: ast_str_strlen can be wrong

Reporter: N A (InterLinked) Labels:

Date Opened: 2022-03-12 12:23:09.000-0600 Date Closed: 2022-07-27 07:57:05

Priority: Major Regression?

Status: Closed/Complete Components: PBX/General

Versions: 18.10.1 Frequency of
Occurrence Constant

Related
Issues:

Environment: Attachments:

Description: Bug: ast_str_substitute_variables completely ignores substrings.

Workaround: Use pbx_substitute_variables_helper instead, which works correctly.

It seems the former is simply the ast_str equivalent of the latter, so in this case, they do NOT have feature parity and ast_str_substitute_variables needs to be fixed to have the same behavior as the pbx_ function.

I am marking this as major as even though there is a workaround (do not use the ast_str functions), that requires changing the Asterisk source to do that so there is no easy workaround for users of modules that are using ast_str functions internally.

Complete detail analysis with code examples below:
{noformat}

GOOD:

[AYK]
condition = $[$["${ODBC_FEAT(${dnid},AYK,AYK)}"="1"]&${DB_EXISTS(astrex/tn/${maindnid}/feat/AYK)}&$["${CALLERID(pres)}"="prohib_not_screened"|"${pres}"="prohib_not_screened"]]
gotolocation = rejectAYK,1

[2022-03-12 17:51:03] DEBUG[24089][C-000003b9]: pbx_variables.c:541 ast_str_substitute_variables_full: Function ODBC_FEAT(4002702155,AYK,AYK) result is '1'
[2022-03-12 17:51:03] DEBUG[24089][C-000003b9]: pbx_variables.c:604 ast_str_substitute_variables_full: Expression result is '1'
[2022-03-12 17:51:03] DEBUG[24089][C-000003b9]: pbx_variables.c:541 ast_str_substitute_variables_full: Function DB_EXISTS(astrex/tn/4002702155/feat/AYK) result is '1'
[2022-03-12 17:51:03] DEBUG[24089][C-000003b9]: pbx_variables.c:541 ast_str_substitute_variables_full: Function CALLERID(pres) result is 'prohib_not_screened'
[2022-03-12 17:51:03] DEBUG[24089][C-000003b9]: pbx_variables.c:604 ast_str_substitute_variables_full: Expression result is '1'
[2022-03-12 17:51:03] DEBUG[24089][C-000003b9]: pbx_variables.c:604 ast_str_substitute_variables_full: Expression result is '1'
[2022-03-12 17:51:03] DEBUG[24089][C-000003b9]: app_featureprocess.c:315 feature_process: Condition to check: $[$["${ODBC_FEAT(${dnid},AYK,AYK)}"="1"]&${DB_EXISTS(astrex/tn/${maindnid}/feat/AYK)}&$["${CALLERID(pres)}"="prohib_not_screened"|"${pres}"="prohib_not_screened"]] (evaluates to 1)
[2022-03-12 17:51:03] > Processing feature 'AYK'
[2022-03-12 17:51:03] -- Feature 'AYK' triggered goto (rejectAYK,1)

ALSO GOOD:

[AYK]
condition = $[$["${ODBC_FEAT(${dnid},AYK,AYK)}"="1"]&${DB_EXISTS(astrex/tn/${maindnid}/feat/AYK)}&$["${CALLERID(pres):0:6}"="prohib_not_screened"|"${pres}"="${pres}"]]
gotolocation = rejectAYK,1

[2022-03-12 17:54:13] DEBUG[24433][C-000003ca]: pbx_variables.c:541 ast_str_substitute_variables_full: Function ODBC_FEAT(4002702155,AYK,AYK) result is '1'
[2022-03-12 17:54:13] DEBUG[24433][C-000003ca]: pbx_variables.c:604 ast_str_substitute_variables_full: Expression result is '1'
[2022-03-12 17:54:13] DEBUG[24433][C-000003ca]: pbx_variables.c:541 ast_str_substitute_variables_full: Function DB_EXISTS(astrex/tn/4002702155/feat/AYK) result is '1'
[2022-03-12 17:54:13] DEBUG[24433][C-000003ca]: pbx_variables.c:541 ast_str_substitute_variables_full: Function CALLERID(pres) result is 'allowed_not_screened'
[2022-03-12 17:54:13] DEBUG[24433][C-000003ca]: pbx_variables.c:604 ast_str_substitute_variables_full: Expression result is '1'
[2022-03-12 17:54:13] DEBUG[24433][C-000003ca]: pbx_variables.c:604 ast_str_substitute_variables_full: Expression result is '1'
[2022-03-12 17:54:13] DEBUG[24433][C-000003ca]: app_featureprocess.c:315 feature_process: Condition to check: $[$["${ODBC_FEAT(${dnid},AYK,AYK)}"="1"]&${DB_EXISTS(astrex/tn/${maindnid}/feat/AYK)}&$["${CALLERID(pres):0:6}"="prohib_not_screened"|"${pres}"="${pres}"]] (evaluates to 1)
[2022-03-12 17:54:13] > Processing feature 'AYK'
[2022-03-12 17:54:13] -- Feature 'AYK' triggered goto (rejectAYK,1)

ALSO GOOD:

[AYK] ; Anonymous Call Rejection
condition = $[$["${ODBC_FEAT(${dnid},AYK,AYK)}"="1"]&${DB_EXISTS(astrex/tn/${maindnid}/feat/AYK)}&$["${CALLERID(pres)}"="prohib_not_screened"]]
gotolocation = rejectAYK,1

[2022-03-12 17:58:52] DEBUG[24847][C-000003d8]: pbx_variables.c:541 ast_str_substitute_variables_full: Function SQL_ESC(4002702155) result is '4002702155'
[2022-03-12 17:58:52] DEBUG[24847][C-000003d8]: pbx_variables.c:541 ast_str_substitute_variables_full: Function SQL_ESC(AYK) result is 'AYK'
[2022-03-12 17:58:52] DEBUG[24847][C-000003d8]: pbx_variables.c:541 ast_str_substitute_variables_full: Function SQL_ESC(4002702155) result is '4002702155'
[2022-03-12 17:58:52] DEBUG[24847][C-000003d8]: pbx_variables.c:541 ast_str_substitute_variables_full: Function SQL_ESC(AYK) result is 'AYK'
[2022-03-12 17:58:52] DEBUG[24847][C-000003d8]: res_odbc.c:965 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f591466eb30 from class 'asterisk'
[2022-03-12 17:58:52] DEBUG[24847][C-000003d8]: func_odbc.c:949 acf_odbc_read: Got collength of 5 for column 'value' (offset 0)
[2022-03-12 17:58:52] DEBUG[24847][C-000003d8]: func_odbc.c:998 acf_odbc_read: Got coldata of '1'
[2022-03-12 17:58:52] DEBUG[24847][C-000003d8]: func_odbc.c:1022 acf_odbc_read: buf is now set to '1'
[2022-03-12 17:58:52] DEBUG[24847][C-000003d8]: func_odbc.c:1024 acf_odbc_read: buf is now set to '1'
[2022-03-12 17:58:52] DEBUG[24847][C-000003d8]: res_odbc.c:808 ast_odbc_release_obj: Releasing ODBC handle 0x7f591466eb30 into pool
[2022-03-12 17:58:52] DEBUG[24847][C-000003d8]: pbx_variables.c:541 ast_str_substitute_variables_full: Function ODBC_FEAT(4002702155,AYK,AYK) result is '1'
[2022-03-12 17:58:52] DEBUG[24847][C-000003d8]: pbx_variables.c:604 ast_str_substitute_variables_full: Expression result is '1'
[2022-03-12 17:58:52] DEBUG[24847][C-000003d8]: pbx_variables.c:541 ast_str_substitute_variables_full: Function DB_EXISTS(astrex/tn/4002702155/feat/AYK) result is '1'
[2022-03-12 17:58:52] DEBUG[24847][C-000003d8]: pbx_variables.c:541 ast_str_substitute_variables_full: Function CALLERID(pres) result is 'prohib_not_screened'
[2022-03-12 17:58:52] DEBUG[24847][C-000003d8]: pbx_variables.c:604 ast_str_substitute_variables_full: Expression result is '1'
[2022-03-12 17:58:52] DEBUG[24847][C-000003d8]: pbx_variables.c:604 ast_str_substitute_variables_full: Expression result is '1'
[2022-03-12 17:58:52] DEBUG[24847][C-000003d8]: app_featureprocess.c:315 feature_process: Condition to check: $[$["${ODBC_FEAT(${dnid},AYK,AYK)}"="1"]&${DB_EXISTS(astrex/tn/${maindnid}/feat/AYK)}&$["${CALLERID(pres)}"="prohib_not_screened"]] (evaluates to 1)
[2022-03-12 17:58:52] > Processing feature 'AYK'
[2022-03-12 17:58:52] -- Feature 'AYK' triggered goto (rejectAYK,1)

BAD:

[AYK] ; Anonymous Call Rejection
condition = $[$["${ODBC_FEAT(${dnid},AYK,AYK)}"="1"]&${DB_EXISTS(astrex/tn/${maindnid}/feat/AYK)}&$["${CALLERID(pres)}"="unavailable"|"${CALLERID(pres):0:6}"="prohib_not_screened"]]

[2022-03-12 18:05:56] DEBUG[25281][C-000003e9]: pbx_variables.c:541 ast_str_substitute_variables_full: Function CALLERID(pres) result is 'prohib_not_screened'
[2022-03-12 18:05:56] DEBUG[25281][C-000003e9]: pbx_variables.c:604 ast_str_substitute_variables_full: Expression result is '1' <---------------------------------------------------------------- LIAR! This is *NOT* TRUE!

^----- This confirms that the :0:6 is literally being completely ignored. That is the only way that could be true.

[2022-03-12 18:05:56] DEBUG[25281][C-000003e9]: pbx_variables.c:604 ast_str_substitute_variables_full: Expression result is '1'
[2022-03-12 18:05:56] DEBUG[25281][C-000003e9]: app_featureprocess.c:315 feature_process: Condition to check: $[$["${ODBC_FEAT(${dnid},AYK,AYK)}"="1"]&${DB_EXISTS(astrex/tn/${maindnid}/feat/AYK)}&$["${CALLERID(pres):0:6}"="prohib_not_screened"]] (evaluates to 1)
[2022-03-12 18:05:56] > Processing feature 'AYK'

ANOTHER BAD:

[AYK] ; Anonymous Call Rejection
condition = $[$["${ODBC_FEAT(${dnid},AYK,AYK)}"="1"]&${DB_EXISTS(astrex/tn/${maindnid}/feat/AYK)}&$["${CALLERID(pres)}"="unavailable"|"${CALLERID(pres):0:6}"="prohib"]]
gotolocation = rejectAYK,1

[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: pbx_variables.c:541 ast_str_substitute_variables_full: Function SQL_ESC(4002702155) result is '4002702155'
[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: pbx_variables.c:541 ast_str_substitute_variables_full: Function SQL_ESC(AYK) result is 'AYK'
[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: pbx_variables.c:541 ast_str_substitute_variables_full: Function SQL_ESC(4002702155) result is '4002702155'
[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: pbx_variables.c:541 ast_str_substitute_variables_full: Function SQL_ESC(AYK) result is 'AYK'
[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: res_odbc.c:965 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f591466eb30 from class 'asterisk'
[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: func_odbc.c:949 acf_odbc_read: Got collength of 5 for column 'value' (offset 0)
[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: func_odbc.c:998 acf_odbc_read: Got coldata of '1'
[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: func_odbc.c:1022 acf_odbc_read: buf is now set to '1'
[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: func_odbc.c:1024 acf_odbc_read: buf is now set to '1'
[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: res_odbc.c:808 ast_odbc_release_obj: Releasing ODBC handle 0x7f591466eb30 into pool
[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: pbx_variables.c:541 ast_str_substitute_variables_full: Function ODBC_FEAT(4002702155,AYK,AYK) result is '1'
[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: pbx_variables.c:604 ast_str_substitute_variables_full: Expression result is '1'
[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: pbx_variables.c:541 ast_str_substitute_variables_full: Function DB_EXISTS(astrex/tn/4002702155/feat/AYK) result is '1'
[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: pbx_variables.c:541 ast_str_substitute_variables_full: Function CALLERID(pres) result is 'prohib_not_screened'
[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: pbx_variables.c:541 ast_str_substitute_variables_full: Function CALLERID(pres) result is 'prohib_not_screened'
[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: pbx_variables.c:604 ast_str_substitute_variables_full: Expression result is '0'
[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: pbx_variables.c:604 ast_str_substitute_variables_full: Expression result is '0' <--------------------------------------------------------------------- LIAR!!! This IS TRUE!!!
[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: app_featureprocess.c:315 feature_process: Condition to check: $[$["${ODBC_FEAT(${dnid},AYK,AYK)}"="1"]&${DB_EXISTS(astrex/tn/${maindnid}/feat/AYK)}&$["${CALLERID(pres)}"="unavailable"|"${CALLERID(pres):0:6}"="prohib"]] (evaluates to 0)
[2022-03-12 17:55:53] DEBUG[24661][C-000003d1]: app_featureprocess.c:317 feature_process: Not processing feature 'AYK'

ANOTHER BAD:

[AYK]
condition = $[$["${ODBC_FEAT(${dnid},AYK,AYK)}"="1"]&${DB_EXISTS(astrex/tn/${maindnid}/feat/AYK)}&$["${CALLERID(pres)}"="unavailable"|"${CALLERID(pres):0:6}"="prohib"]]

[2022-03-12 18:09:27] DEBUG[25535][C-000003f1]: pbx_variables.c:541 ast_str_substitute_variables_full: Function ODBC_FEAT(4002702155,AYK,AYK) result is '1'
[2022-03-12 18:09:27] DEBUG[25535][C-000003f1]: pbx_variables.c:604 ast_str_substitute_variables_full: Expression result is '1'
[2022-03-12 18:09:27] DEBUG[25535][C-000003f1]: pbx_variables.c:502 ast_str_substitute_variables_full: Evaluating 'DB_EXISTS(astrex/tn/${maindnid}/feat/AYK)' (from 'DB_EXISTS(astrex/tn/${maindnid}/feat/AYK)}&$["${CALLERID(pres)}"="unavailable"|"${CALLERID(pres):0:6}"="prohib"]' len 41)
[2022-03-12 18:09:27] DEBUG[25535][C-000003f1]: pbx_variables.c:502 ast_str_substitute_variables_full: Evaluating 'maindnid' (from 'maindnid}/feat/AYK)' len 8)
[2022-03-12 18:09:27] DEBUG[25535][C-000003f1]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'maindnid' is '4002702155'
[2022-03-12 18:09:27] DEBUG[25535][C-000003f1]: pbx_variables.c:541 ast_str_substitute_variables_full: Function DB_EXISTS(astrex/tn/4002702155/feat/AYK) result is '1'
[2022-03-12 18:09:27] DEBUG[25535][C-000003f1]: pbx_variables.c:502 ast_str_substitute_variables_full: Evaluating 'CALLERID(pres)' (from 'CALLERID(pres)}"="unavailable"|"${CALLERID(pres):0:6}"="prohib"' len 14)
[2022-03-12 18:09:27] DEBUG[25535][C-000003f1]: pbx_variables.c:541 ast_str_substitute_variables_full: Function CALLERID(pres) result is 'prohib_not_screened'
[2022-03-12 18:09:27] DEBUG[25535][C-000003f1]: pbx_variables.c:502 ast_str_substitute_variables_full: Evaluating 'CALLERID(pres):0:6' (from 'CALLERID(pres):0:6}"="prohib"' len 18)
[2022-03-12 18:09:27] DEBUG[25535][C-000003f1]: pbx_variables.c:541 ast_str_substitute_variables_full: Function CALLERID(pres) result is 'prohib_not_screened'
[2022-03-12 18:09:27] DEBUG[25535][C-000003f1]: pbx_variables.c:604 ast_str_substitute_variables_full: Expression result is '0'
[2022-03-12 18:09:27] DEBUG[25535][C-000003f1]: pbx_variables.c:604 ast_str_substitute_variables_full: Expression result is '0'
[2022-03-12 18:09:27] DEBUG[25535][C-000003f1]: app_featureprocess.c:315 feature_process: Condition to check: $[$["${ODBC_FEAT(${dnid},AYK,AYK)}"="1"]&${DB_EXISTS(astrex/tn/${maindnid}/feat/AYK)}&$["${CALLERID(pres)}"="unavailable"|"${CALLERID(pres):0:6}"="prohib"]] (evaluates to 0)
[2022-03-12 18:09:27] DEBUG[25535][C-000003f1]: app_featureprocess.c:317 feature_process: Not processing feature 'AYK'

Okay, so now what happens if I change from ast_str_retrieve_variables_full to pbx_substitute_variables_helper ??

[2022-03-12 18:16:21] DEBUG[31491][C-000003fb]: pbx_variables.c:765 pbx_substitute_variables_helper_full_location: Function ODBC_FEAT(4002702155,AYK,AYK) result is '1'
[2022-03-12 18:16:21] DEBUG[31491][C-000003fb]: pbx_variables.c:841 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-03-12 18:16:21] DEBUG[31491][C-000003fb]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'maindnid' is '4002702155'
[2022-03-12 18:16:21] DEBUG[31491][C-000003fb]: pbx_variables.c:765 pbx_substitute_variables_helper_full_location: Function DB_EXISTS(astrex/tn/4002702155/feat/AYK) result is '1'
[2022-03-12 18:16:21] DEBUG[31491][C-000003fb]: pbx_variables.c:765 pbx_substitute_variables_helper_full_location: Function CALLERID(pres) result is 'prohib_not_screened'
[2022-03-12 18:16:21] DEBUG[31491][C-000003fb]: pbx_variables.c:765 pbx_substitute_variables_helper_full_location: Function CALLERID(pres) result is 'prohib_not_screened'
[2022-03-12 18:16:21] DEBUG[31491][C-000003fb]: pbx_variables.c:841 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-03-12 18:16:21] DEBUG[31491][C-000003fb]: pbx_variables.c:841 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-03-12 18:16:21] DEBUG[31491][C-000003fb]: app_featureprocess.c:321 feature_process: Condition to check: $[$["${ODBC_FEAT(${dnid},AYK,AYK)}"="1"]&${DB_EXISTS(astrex/tn/${maindnid}/feat/AYK)}&$["${CALLERID(pres)}"="unavailable"|"${CALLERID(pres):0:6}"="prohib"]] (evaluates to 1)
[2022-03-12 18:16:21] > Processing feature 'AYK'
[2022-03-12 18:16:21] -- Feature 'AYK' triggered goto (rejectAYK,1)

With pbx helper, everything just works correctly.
You can confirm above that these two functions are substituting the exact same expression in the exact same circumstances.

{noformat}

Below is some code that takes this bug into account properly, demonstrating the issue in play:

{noformat}
static int feature_process(struct ast_channel *chan, struct feature_proc *f, struct ast_str *strbuf)
{
#define BUGGY_AST_SUB 1

#if BUGGY_AST_SUB
char substituted[1024];
#endif
char name[AST_MAX_CONTEXT], condition[PATH_MAX], gotolocation[AST_MAX_CONTEXT], setvars[PATH_MAX];

ast_mutex_lock(&f->lock);
FEATPROC_STRDUP(name);
FEATPROC_STRDUP(condition);
FEATPROC_STRDUP(gotolocation);
FEATPROC_STRDUP(setvars);
ast_mutex_unlock(&f->lock);

if (!ast_strlen_zero(condition)) {
#if BUGGY_AST_SUB
pbx_substitute_variables_helper(chan, condition, substituted, sizeof(substituted) - 1);
ast_debug(1, "Condition to check: %s (evaluates to %s)\n", condition, substituted);
if (!pbx_checkcondition(substituted)) {
ast_debug(1, "Not processing feature '%s'\n", name);
return 0;
}
#else
ast_str_reset(strbuf);
ast_str_substitute_variables(&strbuf, 0, chan, condition);
ast_debug(1, "Condition to check: %s (evaluates to %s)\n", condition, ast_str_buffer(strbuf));
if (!pbx_checkcondition(ast_str_buffer(strbuf))) {
ast_debug(1, "Not processing feature '%s'\n", name);
return 0;
}
ast_str_reset(strbuf);
#endif
}
ast_verb(4, "Processing feature '%s'\n", name);
{noformat}

Comments: By: Asterisk Team (asteriskteam) 2022-03-12 12:23:10.345-0600

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution. Please note that log messages and other files should not be sent to the Sangoma Asterisk Team unless explicitly asked for. All files should be placed on this issue in a sanitized fashion as needed.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.

Please note that by submitting data, code, or documentation to Sangoma through JIRA, you accept the Terms of Use present at [https://www.asterisk.org/terms-of-use/|https://www.asterisk.org/terms-of-use/].
By: N A (InterLinked) 2022-03-15 17:37:06.201-0500

It appears this is a bug with ast_str_strlen (or some related usage) specifically, and even more bizarrely, only seems to happen with some functions, e.g. CALLERID(num) and CALLERID(pres) but not PASSTHRU.

Notice that if you call ast_str_strlen, it returns 0, but if you call strlen(ast_str_buffer()), it returns 6.

Surely ast_str_strlen and strlen(ast_str_buffer) should always agree?

{noformat}
[Mar 15 18:33:32] DEBUG[427342][C-00000001]: pbx_variables.c:512 ast_str_substitute_variables_full: Evaluating 'CALLERID(num):0:3' (from 'CALLERID(num):0:3}"="123"' len 17)
[Mar 15 18:33:32] DEBUG[427342][C-00000001]: pbx_variables.c:550 ast_str_substitute_variables_full: Function CALLERID(num) result is '123456'
[Mar 15 18:33:32] WARNING[427342][C-00000001]: pbx_variables.c:558 ast_str_substitute_variables_full: Offset: 0, offset2: 3
[Mar 15 18:33:32] DEBUG[427342][C-00000001]: pbx_variables.c:192 ast_str_substring: Length is 0, real length is 6
[Mar 15 18:33:32] DEBUG[427342][C-00000001]: pbx_variables.c:196 ast_str_substring: no need to do anything
{noformat}

{noformat}
static const char *ast_str_substring(struct ast_str *value, int offset, int length)
{
int lr; /* length of the input string after the copy */

lr = ast_str_strlen(value); /* compute length after copy, so we never go out of the workspace */
ast_debug(1, "Length is %d, real length is %lu\n", lr, strlen(ast_str_buffer(value)));

/* Quick check if no need to do anything */
if (offset == 0 && length >= lr) { /* take the whole string */
ast_debug(1, "no need to do anything\n");
return ast_str_buffer(value);
}
{noformat}
By: N A (InterLinked) 2022-03-15 17:53:26.628-0500

Here is a unit test that demonstrates the problem:

As mentioned, pbx_ substitution always works properly. ast_str however is inconsistent due to this bug and fails several tests:

{noformat}
#ifdef TEST_FRAMEWORK
AST_TEST_DEFINE(test_variable_substrings)
{
int i, res = AST_TEST_PASS;
struct ast_channel *chan; /* dummy channel */
struct ast_str *str; /* fancy string for holding comparing value */

const char *test_strings[][5] = {
{"somevaluehere", "CALLERID(num):0:25", "somevaluehere"},
{"somevaluehere", "CALLERID(num):0:5", "somev"},
{"somevaluehere", "CALLERID(num):4:5", "value"},
{"somevaluehere", "CALLERID(num):0:-4", "somevalue"},
{"somevaluehere", "CALLERID(num):-4", "here"},
};

switch (cmd) {
case TEST_INIT:
info->name = "variable_substrings";
info->category = "/main/pbx/";
info->summary = "Test variable substring resolution";
info->description = "Verify that variable substrings are calculated correctly";
return AST_TEST_NOT_RUN;
case TEST_EXECUTE:
break;
}

if (!(chan = ast_dummy_channel_alloc())) {
ast_test_status_update(test, "Unable to allocate dummy channel\n");
return AST_TEST_FAIL;
}

if (!(str = ast_str_create(64))) {
ast_test_status_update(test, "Unable to allocate dynamic string buffer\n");
ast_channel_release(chan);
return AST_TEST_FAIL;
}

for (i = 0; i < ARRAY_LEN(test_strings); i++) {
char substituted[512], tmp[512] = "";

ast_set_callerid(chan, test_strings[i][0], NULL, test_strings[i][0]);

snprintf(tmp, sizeof(tmp), "${%s}", test_strings[i][1]);

/* test ast_str_substitute_variables */
ast_str_substitute_variables(&str, 0, chan, tmp);
ast_debug(1, "Comparing STR %s with %s\n", ast_str_buffer(str), test_strings[i][2]);
if (strcmp(test_strings[i][2], ast_str_buffer(str))) {
ast_test_status_update(test, "Format string '%s' substituted to '%s' using str sub. Expected '%s'.\n", test_strings[i][0], ast_str_buffer(str), test_strings[i][2]);
res = AST_TEST_FAIL;
}

/* test pbx_substitute_variables_helper */
pbx_substitute_variables_helper(chan, tmp, substituted, sizeof(substituted) - 1);
ast_debug(1, "Comparing PBX %s with %s\n", substituted, test_strings[i][2]);
if (strcmp(test_strings[i][2], substituted)) {
ast_test_status_update(test, "Format string '%s' substituted to '%s' using pbx sub. Expected '%s'.\n", test_strings[i][0], substituted, test_strings[i][2]);
res = AST_TEST_FAIL;
}
}

ast_free(str);
ast_channel_release(chan);

return res;
}
#endif
{noformat}

Result:
{noformat}
pbxdev*CLI> test execute category /main/pbx/ name variable_substrings
Running all available tests matching category /main/pbx/ and name variable_substrings

START /main/pbx/ - variable_substrings
[pbx_variables.c:test_variable_substrings:924]: Format string 'somevaluehere' substituted to 'somevaluehere' using str sub. Expected 'somev'.
[pbx_variables.c:test_variable_substrings:924]: Format string 'somevaluehere' substituted to '' using str sub. Expected 'value'.
[pbx_variables.c:test_variable_substrings:924]: Format string 'somevaluehere' substituted to '' using str sub. Expected 'somevalue'.
[pbx_variables.c:test_variable_substrings:924]: Format string 'somevaluehere' substituted to '' using str sub. Expected 'here'.
END /main/pbx/ - variable_substrings Time: <1ms Result: FAIL
{noformat}
By: Friendly Automation (friendly-automation) 2022-07-27 07:57:07.473-0500

Change 18833 merged by Joshua Colp:
pbx_functions.c: Manually update ast_str strlen.

[https://gerrit.asterisk.org/c/asterisk/+/18833|https://gerrit.asterisk.org/c/asterisk/+/18833]
By: Friendly Automation (friendly-automation) 2022-07-27 07:59:12.520-0500

Change 18866 merged by Friendly Automation:
pbx_functions.c: Manually update ast_str strlen.

[https://gerrit.asterisk.org/c/asterisk/+/18866|https://gerrit.asterisk.org/c/asterisk/+/18866]
By: Friendly Automation (friendly-automation) 2022-07-27 07:59:58.442-0500

Change 18865 merged by Friendly Automation:
pbx_functions.c: Manually update ast_str strlen.

[https://gerrit.asterisk.org/c/asterisk/+/18865|https://gerrit.asterisk.org/c/asterisk/+/18865]
By: Friendly Automation (friendly-automation) 2022-07-27 08:07:35.372-0500

Change 18867 merged by Joshua Colp:
pbx_functions.c: Manually update ast_str strlen.

[https://gerrit.asterisk.org/c/asterisk/+/18867|https://gerrit.asterisk.org/c/asterisk/+/18867]
By: Friendly Automation (friendly-automation) 2022-07-27 08:07:46.692-0500

Change 18864 merged by Joshua Colp:
pbx_functions.c: Manually update ast_str strlen.

[https://gerrit.asterisk.org/c/asterisk/+/18864|https://gerrit.asterisk.org/c/asterisk/+/18864]