IP Collection not working properly

[Greentears]

Describe the bug

We have a macro to enable throttling around the IP. Here is the macro:

<Macro MaxRequestNb $host $path $max $timeout>
 <IfDefine !noSecurityRules>
  Use SecRule TX:remote_addr  "~{IpToNotBlock}"       "phase:1,tag:security,t:none,~{skipAfter}:AfterMaxRequestNb"
  Use SecRule REQUEST_HEADERS "!$host"                "phase:1,tag:security,t:none,~{skipAfter}:AfterMaxRequestNb"
  Use SecRule TX:url          "!$path"                "phase:1,tag:security,t:none,~{skipAfter}:AfterMaxRequestNb"
   Use SecAction                                      "phase:1,tag:security,~{nosecaction},setvar:'IP.reqnb_$host$path=+1',expirevar:'IP.reqnb_$host$path=$timeout',deprecatevar:'IP.reqnb_$host$path=$max/$timeout'"
   Use SecRuleDeny "IP:'reqnb_$host$path'" "@gt $max" "phase:1,t:none,~{status}:403,msg:'Too many requests <%{MATCHED_VAR}> (possible application-level DoS Attack)'"
  Use SecMarker AfterMaxRequestNb,tag:security
  # deprecatevar only effective in phase 5; must be set even in case of blocking
  Use SecAction  "phase:5,~{nosecaction},tag:security,deprecatevar:'IP.reqnb_$host$path=$max/$timeout'"
 </IfDefine>
</Macro>

But the macro doesn't work. We checked in debug why it doesn't work and as you can see in the log section, the Recorded original collection variable: IP.reqnb_test = "0" Is still 0 even the second time, after being incremented.
(For this test, i replaced in the macro the reqnb_$host$path to reqnb_test).
I tested more than twice, but still the same result after 10 times

Logs and dumps

audit.debug:[11/Jul/2025:10:13:40.039305 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][5] Rule 55bb209a1e48: SecAction "phase:1,tag:security,nolog,noauditlog,severity:255,pass,msg:'',setvar:IP.reqnb_test=+1,expirevar:IP.reqnb_test=3600,deprecatevar:IP.reqnb_test=1/3600"
audit.debug:[11/Jul/2025:10:13:40.039320 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Setting variable: IP.reqnb_test=+1
audit.debug:[11/Jul/2025:10:13:40.039323 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Recorded original collection variable: IP.reqnb_test = "0"
audit.debug:[11/Jul/2025:10:13:40.039325 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Relative change: reqnb_test=0+1
audit.debug:[11/Jul/2025:10:13:40.039328 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Set variable "IP.reqnb_test" to "1".
audit.debug:[11/Jul/2025:10:13:40.039331 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Expiring variable: IP.reqnb_test=3600
audit.debug:[11/Jul/2025:10:13:40.039334 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Variable "IP.reqnb_test" set to expire in 3600 seconds.
audit.debug:[11/Jul/2025:10:13:40.039336 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Deprecating variable: IP.reqnb_test=1/3600
audit.debug:[11/Jul/2025:10:13:40.039361 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][5] Rule 55bb209ad250: SecRule "IP:'reqnb_test'" "@gt 1" "phase:1,setenv:!noIncreaseBlockCounter,setvar:tx.blocked,setvar:tx.c_=%{IP.blocked},setvar:tx.c_=+%{tx.blocked},setenv:waf-IP-blocked=%{tx.c_},setvar:tx.c_=%{SESSION.blocked},setvar:tx.c_=+%{tx.blocked},setenv:waf-SESSION-blocked=%{tx.c_},setvar:tx.c_=%{IP.BadAuth},setvar:tx.c_=+%{tx.BadAuth},setenv:waf-IP-BadAuth=%{tx.c_},setenv:waf-IP-UPDATE_COUNTER=%{IP.UPDATE_COUNTER},setenv:waf-IP-LAST_UPDATE_TIME=%{IP.LAST_UPDATE_TIME},setenv:waf-IP-UPDATE_RATE=%{IP.UPDATE_RATE},setenv:BlockRuleId=%{ENV.BlockRuleId}|%{rule.id}|,setenv:BlockStatus=%{ENV.BlockStatus}|%{rule.status}|,setenv:LastSecMsg=%{env.LastSecMsg}|%{rule.msg},setenv:LastSecData=%{env.LastSecData}%{MATCHED_VAR_NAME}=%{MATCHED_VAR}|,setvar:GLOBAL.LastMsg=%{rule.msg},severity:ERROR,msg:'Too many requests <%{MATCHED_VAR}> (possible application-level DoS Attack)',capture,tag:security,status:403,setvar:tx.c_=%{IP.blocked},setvar:tx.c_=+%{tx.blocked},setenv:waf-IP-blocked=%{tx.c_},setvar:tx.c_=%{SESSION.
audit.debug:[11/Jul/2025:10:13:40.039369 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Executing operator "gt" with param "1" against IP:reqnb_test.
audit.debug:[11/Jul/2025:10:13:40.323361 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Expanded "IP:/^/" to "IP:__expire_KEY|IP:KEY|IP:TIMEOUT|IP:__key|IP:__name|IP:CREATE_TIME|IP:UPDATE_COUNTER|IP:IS_NEW|IP:reqnb_test|IP:__expire_reqnb_test|IP:blocked".
audit.debug:[11/Jul/2025:10:13:40.323473 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Executing operator "rx" with param "^$" against IP:reqnb_test.
audit.debug:[11/Jul/2025:10:13:40.323484 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Executing operator "rx" with param "^$" against IP:__expire_reqnb_test.
audit.debug:[11/Jul/2025:10:13:40.324402 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Expanded "IP:/^/" to "IP:__expire_KEY|IP:KEY|IP:TIMEOUT|IP:__key|IP:__name|IP:CREATE_TIME|IP:UPDATE_COUNTER|IP:IS_NEW|IP:reqnb_test|IP:__expire_reqnb_test|IP:blocked".
audit.debug:[11/Jul/2025:10:13:40.324508 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Executing operator "unconditionalMatch" with param "" against IP:reqnb_test.
audit.debug:[11/Jul/2025:10:13:40.324524 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Executing operator "unconditionalMatch" with param "" against IP:__expire_reqnb_test.
audit.debug:[11/Jul/2025:10:13:40.324588 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Set variable "IP:reqnb_test" size 13 to collection.
audit.debug:[11/Jul/2025:10:13:40.324591 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Set variable "IP:__expire_reqnb_test" size 22 to collection.
audit.debug:[11/Jul/2025:10:13:40.324599 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Expanded "MATCHED_VARS_NAMES" to "IP:__expire_KEY|IP:KEY|IP:TIMEOUT|IP:__key|IP:__name|IP:CREATE_TIME|IP:UPDATE_COUNTER|IP:IS_NEW|IP:reqnb_test|IP:__expire_reqnb_test|IP:blocked".
audit.debug:[11/Jul/2025:10:13:40.325032 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Executing operator "rx" with param "^IP:(.*)" against IP:reqnb_test.
audit.debug:[11/Jul/2025:10:13:40.325035 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Target value: "IP:reqnb_test"
audit.debug:[11/Jul/2025:10:13:40.325041 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Added regex subexpression to TX.0: IP:reqnb_test
audit.debug:[11/Jul/2025:10:13:40.325044 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Added regex subexpression to TX.1: reqnb_test
audit.debug:[11/Jul/2025:10:13:40.325059 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Resolved macro %{tx.1} to: reqnb_test
audit.debug:[11/Jul/2025:10:13:40.325062 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Set variable "TX.n_" to "__expire_KEYKEYTIMEOUT__key__nameCREATE_TIMEUPDATE_COUNTERIS_NEWreqnb_test".
audit.debug:[11/Jul/2025:10:13:40.325065 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Warning. Pattern match "^IP:(.*)" at IP:reqnb_test. [msg ""]
audit.debug:[11/Jul/2025:10:13:40.325071 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Executing operator "rx" with param "^IP:(.*)" against IP:__expire_reqnb_test.
audit.debug:[11/Jul/2025:10:13:40.325074 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Target value: "IP:__expire_reqnb_test"
audit.debug:[11/Jul/2025:10:13:40.325078 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Added regex subexpression to TX.0: IP:__expire_reqnb_test
audit.debug:[11/Jul/2025:10:13:40.325081 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Added regex subexpression to TX.1: __expire_reqnb_test
audit.debug:[11/Jul/2025:10:13:40.325095 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Resolved macro %{TX.n_} to: __expire_KEYKEYTIMEOUT__key__nameCREATE_TIMEUPDATE_COUNTERIS_NEWreqnb_test
audit.debug:[11/Jul/2025:10:13:40.325102 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Resolved macro %{tx.1} to: __expire_reqnb_test
audit.debug:[11/Jul/2025:10:13:40.325106 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Set variable "TX.n_" to "__expire_KEYKEYTIMEOUT__key__nameCREATE_TIMEUPDATE_COUNTERIS_NEWreqnb_test__expire_reqnb_test".
audit.debug:[11/Jul/2025:10:13:40.325109 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Warning. Pattern match "^IP:(.*)" at IP:__expire_reqnb_test. [msg ""]
audit.debug:[11/Jul/2025:10:13:40.325156 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Resolved macro %{TX.n_} to: __expire_KEYKEYTIMEOUT__key__nameCREATE_TIMEUPDATE_COUNTERIS_NEWreqnb_test__expire_reqnb_test
audit.debug:[11/Jul/2025:10:13:40.325170 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Set variable "TX.n_" to "__expire_KEYKEYTIMEOUT__key__nameCREATE_TIMEUPDATE_COUNTERIS_NEWreqnb_test__expire_reqnb_testblocked".
audit.debug:[11/Jul/2025:10:13:40.325255 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Expanded "IP:/^/" to "IP:__expire_KEY|IP:KEY|IP:TIMEOUT|IP:__key|IP:__name|IP:CREATE_TIME|IP:UPDATE_COUNTER|IP:IS_NEW|IP:reqnb_test|IP:__expire_reqnb_test|IP:blocked".
audit.debug:[11/Jul/2025:10:13:40.325749 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Executing operator "unconditionalMatch" with param "" against IP:reqnb_test.
audit.debug:[11/Jul/2025:10:13:40.325796 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Executing operator "unconditionalMatch" with param "" against IP:__expire_reqnb_test.
audit.debug:[11/Jul/2025:10:13:40.338019 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][5] Rule 55bb164c2180: SecAction "phase:5,nolog,noauditlog,severity:255,pass,msg:'',tag:security,deprecatevar:IP.reqnb_test=1/3600"
audit.debug:[11/Jul/2025:10:13:40.338033 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Deprecating variable: IP.reqnb_test=1/3600
audit.debug:[11/Jul/2025:10:13:40.340495 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] collection_store: Wrote variable: name "reqnb_test", value "1".
audit.debug:[11/Jul/2025:10:13:40.340497 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] collection_store: Wrote variable: name "__expire_reqnb_test", value "1752225220".
audit.debug:[11/Jul/2025:10:13:51.350628 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] collection_unpack: Read variable: name "reqnb_test", value "1".
audit.debug:[11/Jul/2025:10:13:51.350631 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] collection_unpack: Read variable: name "__expire_reqnb_test", value "1752225220".
audit.debug:[11/Jul/2025:10:13:51.362046 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][5] Rule 55bb209a1e48: SecAction "phase:1,tag:security,nolog,noauditlog,severity:255,pass,msg:'',setvar:IP.reqnb_test=+1,expirevar:IP.reqnb_test=3600,deprecatevar:IP.reqnb_test=1/3600"
audit.debug:[11/Jul/2025:10:13:51.362061 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Setting variable: IP.reqnb_test=+1
audit.debug:[11/Jul/2025:10:13:51.362064 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Recorded original collection variable: IP.reqnb_test = "0"
audit.debug:[11/Jul/2025:10:13:51.362067 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Relative change: reqnb_test=0+1
audit.debug:[11/Jul/2025:10:13:51.362070 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Set variable "IP.reqnb_test" to "1".
audit.debug:[11/Jul/2025:10:13:51.362073 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Expiring variable: IP.reqnb_test=3600
audit.debug:[11/Jul/2025:10:13:51.362076 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Variable "IP.reqnb_test" set to expire in 3600 seconds.
audit.debug:[11/Jul/2025:10:13:51.362079 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Deprecating variable: IP.reqnb_test=1/3600
audit.debug:[11/Jul/2025:10:13:51.362121 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][5] Rule 55bb209ad250: SecRule "IP:'reqnb_test'" "@gt 1" "phase:1,setenv:!noIncreaseBlockCounter,setvar:tx.blocked,setvar:tx.c_=%{IP.blocked},setvar:tx.c_=+%{tx.blocked},setenv:waf-IP-blocked=%{tx.c_},setvar:tx.c_=%{SESSION.blocked},setvar:tx.c_=+%{tx.blocked},setenv:waf-SESSION-blocked=%{tx.c_},setvar:tx.c_=%{IP.BadAuth},setvar:tx.c_=+%{tx.BadAuth},setenv:waf-IP-BadAuth=%{tx.c_},setenv:waf-IP-UPDATE_COUNTER=%{IP.UPDATE_COUNTER},setenv:waf-IP-LAST_UPDATE_TIME=%{IP.LAST_UPDATE_TIME},setenv:waf-IP-UPDATE_RATE=%{IP.UPDATE_RATE},setenv:BlockRuleId=%{ENV.BlockRuleId}|%{rule.id}|,setenv:BlockStatus=%{ENV.BlockStatus}|%{rule.status}|,setenv:LastSecMsg=%{env.LastSecMsg}|%{rule.msg},setenv:LastSecData=%{env.LastSecData}%{MATCHED_VAR_NAME}=%{MATCHED_VAR}|,setvar:GLOBAL.LastMsg=%{rule.msg},severity:ERROR,msg:'Too many requests <%{MATCHED_VAR}> (possible application-level DoS Attack)',capture,tag:security,status:403,setvar:tx.c_=%{IP.blocked},setvar:tx.c_=+%{tx.blocked},setenv:waf-IP-blocked=%{tx.c_},setvar:tx.c_=%{SESSION.
audit.debug:[11/Jul/2025:10:13:51.362146 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Executing operator "gt" with param "1" against IP:reqnb_test.
audit.debug:[11/Jul/2025:10:13:51.657033 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Expanded "IP:/^/" to "IP:__expire_KEY|IP:KEY|IP:TIMEOUT|IP:__key|IP:__name|IP:CREATE_TIME|IP:UPDATE_COUNTER|IP:IS_NEW|IP:reqnb_test|IP:__expire_reqnb_test|IP:blocked".
audit.debug:[11/Jul/2025:10:13:51.657124 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Executing operator "rx" with param "^$" against IP:reqnb_test.
audit.debug:[11/Jul/2025:10:13:51.657135 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Executing operator "rx" with param "^$" against IP:__expire_reqnb_test.
audit.debug:[11/Jul/2025:10:13:51.657946 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Expanded "IP:/^/" to "IP:__expire_KEY|IP:KEY|IP:TIMEOUT|IP:__key|IP:__name|IP:CREATE_TIME|IP:UPDATE_COUNTER|IP:IS_NEW|IP:reqnb_test|IP:__expire_reqnb_test|IP:blocked".
audit.debug:[11/Jul/2025:10:13:51.658073 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Executing operator "unconditionalMatch" with param "" against IP:reqnb_test.
audit.debug:[11/Jul/2025:10:13:51.658083 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Executing operator "unconditionalMatch" with param "" against IP:__expire_reqnb_test.
audit.debug:[11/Jul/2025:10:13:51.658138 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Set variable "IP:reqnb_test" size 13 to collection.
audit.debug:[11/Jul/2025:10:13:51.658141 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Set variable "IP:__expire_reqnb_test" size 22 to collection.
audit.debug:[11/Jul/2025:10:13:51.658148 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Expanded "MATCHED_VARS_NAMES" to "IP:__expire_KEY|IP:KEY|IP:TIMEOUT|IP:__key|IP:__name|IP:CREATE_TIME|IP:UPDATE_COUNTER|IP:IS_NEW|IP:reqnb_test|IP:__expire_reqnb_test|IP:blocked".
audit.debug:[11/Jul/2025:10:13:51.658510 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Executing operator "rx" with param "^IP:(.*)" against IP:reqnb_test.
audit.debug:[11/Jul/2025:10:13:51.658513 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Target value: "IP:reqnb_test"
audit.debug:[11/Jul/2025:10:13:51.658517 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Added regex subexpression to TX.0: IP:reqnb_test
audit.debug:[11/Jul/2025:10:13:51.658520 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Added regex subexpression to TX.1: reqnb_test
audit.debug:[11/Jul/2025:10:13:51.658533 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Resolved macro %{tx.1} to: reqnb_test
audit.debug:[11/Jul/2025:10:13:51.658537 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Set variable "TX.n_" to "__expire_KEYKEYTIMEOUT__key__nameCREATE_TIMEUPDATE_COUNTERIS_NEWreqnb_test".
audit.debug:[11/Jul/2025:10:13:51.658540 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Warning. Pattern match "^IP:(.*)" at IP:reqnb_test. [msg ""]
audit.debug:[11/Jul/2025:10:13:51.658545 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Executing operator "rx" with param "^IP:(.*)" against IP:__expire_reqnb_test.
audit.debug:[11/Jul/2025:10:13:51.658548 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Target value: "IP:__expire_reqnb_test"
audit.debug:[11/Jul/2025:10:13:51.658552 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Added regex subexpression to TX.0: IP:__expire_reqnb_test
audit.debug:[11/Jul/2025:10:13:51.658555 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Added regex subexpression to TX.1: __expire_reqnb_test
audit.debug:[11/Jul/2025:10:13:51.658569 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Resolved macro %{TX.n_} to: __expire_KEYKEYTIMEOUT__key__nameCREATE_TIMEUPDATE_COUNTERIS_NEWreqnb_test
audit.debug:[11/Jul/2025:10:13:51.658575 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Resolved macro %{tx.1} to: __expire_reqnb_test
audit.debug:[11/Jul/2025:10:13:51.658579 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Set variable "TX.n_" to "__expire_KEYKEYTIMEOUT__key__nameCREATE_TIMEUPDATE_COUNTERIS_NEWreqnb_test__expire_reqnb_test".
audit.debug:[11/Jul/2025:10:13:51.658582 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Warning. Pattern match "^IP:(.*)" at IP:__expire_reqnb_test. [msg ""]
audit.debug:[11/Jul/2025:10:13:51.658624 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Resolved macro %{TX.n_} to: __expire_KEYKEYTIMEOUT__key__nameCREATE_TIMEUPDATE_COUNTERIS_NEWreqnb_test__expire_reqnb_test
audit.debug:[11/Jul/2025:10:13:51.658631 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Set variable "TX.n_" to "__expire_KEYKEYTIMEOUT__key__nameCREATE_TIMEUPDATE_COUNTERIS_NEWreqnb_test__expire_reqnb_testblocked".
audit.debug:[11/Jul/2025:10:13:51.658710 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Expanded "IP:/^/" to "IP:__expire_KEY|IP:KEY|IP:TIMEOUT|IP:__key|IP:__name|IP:CREATE_TIME|IP:UPDATE_COUNTER|IP:IS_NEW|IP:reqnb_test|IP:__expire_reqnb_test|IP:blocked".
audit.debug:[11/Jul/2025:10:13:51.659138 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Executing operator "unconditionalMatch" with param "" against IP:reqnb_test.
audit.debug:[11/Jul/2025:10:13:51.659186 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][4] Executing operator "unconditionalMatch" with param "" against IP:__expire_reqnb_test.
audit.debug:[11/Jul/2025:10:13:51.670564 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][5] Rule 55bb164c2180: SecAction "phase:5,nolog,noauditlog,severity:255,pass,msg:'',tag:security,deprecatevar:IP.reqnb_test=1/3600"
audit.debug:[11/Jul/2025:10:13:51.670586 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] Deprecating variable: IP.reqnb_test=1/3600
audit.debug:[11/Jul/2025:10:13:51.673139 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] collection_store: Wrote variable: name "reqnb_test", value "1".
audit.debug:[11/Jul/2025:10:13:51.673141 +0200] [mock-server/sid#55bb1f114de0][rid#7fc20801d220][/api2/toto][9] collection_store: Wrote variable: name "__expire_reqnb_test", value "1752225231".

To Reproduce

With mock-server and Postman with the call: https://mock-server/api2/toto with a setup using the macro given above

Expected behavior

The IP Collection increment correctly the variables / remember the correct value

Server (please complete the following information):
Rocky9
Latest version of ModSecurity v2
ModSecurity for Apache/2.9.10.3 (Jun 26 2025) configured.
ModSecurity: APR compiled version="1.7.0"; loaded version="1.7.0"
ModSecurity: PCRE2 compiled version="10.40 2022-04-14"; loaded version="10.40 2022-04-14"
ModSecurity: YAJL compiled version="2.1.0"
ModSecurity: LIBXML compiled version="2.9.13"
ModSecurity: Original server signature: Apache/2.4.62 (Rocky Linux) OpenSSL/3.0.7

[airween]

Hi @Greentears,

thanks for the detailed report - based on given information I try to review and reproduce this issue.

[airween]

@Greentears do you know what is (was) the latest version where this macro worked as you expect?

[Greentears]

@airween I don't exactly know. I started to work with ModSecurity after Marc Stern, so maybe he would know.
As far as I know, it didn't work with the version before June 2024
Did you manage to reproduce the behaviour ?

[Greentears]

Hi @airween,
Were you able to reproduce the issue by any chance ?

[airween]

Hi @airween, Were you able to reproduce the issue by any chance ?

"Unfortunately" yes 😃. But I wasn't able to inspect the cause.