[asterisk-bugs] [JIRA] (ASTERISK-29966) pbx_variables: ast_str_substitute_variables completely ignores substrings
Asterisk Team (JIRA)
noreply at issues.asterisk.org
Sat Mar 12 12:24:07 CST 2022
[ https://issues.asterisk.org/jira/browse/ASTERISK-29966?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=258366#comment-258366 ]
Asterisk Team commented on ASTERISK-29966:
------------------------------------------
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/].
> pbx_variables: ast_str_substitute_variables completely ignores substrings
> -------------------------------------------------------------------------
>
> Key: ASTERISK-29966
> URL: https://issues.asterisk.org/jira/browse/ASTERISK-29966
> Project: Asterisk
> Issue Type: Bug
> Security Level: None
> Components: PBX/General
> Affects Versions: 18.10.1
> Reporter: N A
> Severity: Major
>
> 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);
> pbx_substitute_variables_helper(chan, url, substituted, sizeof(substituted) - 1);
> 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}
--
This message was sent by Atlassian JIRA
(v6.2#6252)
More information about the asterisk-bugs
mailing list