[asterisk-bugs] [JIRA] (ASTERISK-29966) pbx_variables: ast_str_strlen can be wrong
Asterisk Team (JIRA)
noreply at issues.asterisk.org
Wed Sep 14 10:10:12 CDT 2022
[ https://issues.asterisk.org/jira/browse/ASTERISK-29966?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Asterisk Team updated ASTERISK-29966:
-------------------------------------
Target Release Version/s: 20.0.0
> pbx_variables: ast_str_strlen can be wrong
> ------------------------------------------
>
> 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
> Target Release: 20.0.0, 19.6.0, 16.28.0, 18.14.0
>
>
> 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}
--
This message was sent by Atlassian JIRA
(v6.2#6252)
More information about the asterisk-bugs
mailing list