Transaction intializing twice per request for URI '/'

[nagri]

Transaction intializing twice
For the mod security rules that I have wrote, one single request initializes the transaction twice and runs associated lua scripts twice.

Logs and dumps

Output of:

1. DebugLogs (level 9)

[166567211462.029228] [] [4] Initializing transaction
[166567211462.029228] [] [4] Transaction context created.
[166567211462.029228] [] [4] Starting phase CONNECTION. (SecRules 0)
[166567211462.029228] [] [9] This phase consists of 0 rule(s).
[166567211462.029228] [] [4] Starting phase URI. (SecRules 0 + 1/2)
[166567211462.029228] [/] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
[166567211462.029228] [/] [9] This phase consists of 8 rule(s).
[166567211462.029228] [/] [4] (Rule: 200000) Executing operator "Rx" with param "^(?:application(?:/soap\+|/)|text/)xml" against REQUEST_HEADERS:Content-Type.
[166567211462.029228] [/] [4] Rule returned 0.
[166567211462.029228] [/] [9] Matched vars cleaned.
[166567211462.029228] [/] [4] (Rule: 200001) Executing operator "Rx" with param "^application/json" against REQUEST_HEADERS:Content-Type.
[166567211462.029228] [/] [4] Rule returned 0.
[166567211462.029228] [/] [9] Matched vars cleaned.
[166567211462.029228] [/] [4] (Rule: 100001) Executing operator "Eq" with param "0" against USER:EOYVxTvk_twst.
[166567211462.029228] [/] [9] Target value: "0" (Variable: USER:EOYVxTvk_twst)
[166567211462.029228] [/] [9] Matched vars updated.
[166567211462.029228] [/] [4] Running [independent] (non-disruptive) action: setvar
[166567211462.029228] [/] [8] Saving variable: USER:EOYVxTvk_twst with value: 1665672114
[166567211462.029228] [/] [4] Rule returned 1.
[166567211462.029228] [/] [4] Running (disruptive)     action: pass.
[166567211462.029228] [/] [8] Running action pass
[166567211462.029228] [/] [4] (Rule: 100002) Executing operator "Rx" with param "\Qfirefox\E" against REQUEST_HEADERS:User-Agent.
[166567211462.029228] [/] [9] Target value: "firefox" (Variable: REQUEST_HEADERS:User-Agent)
[166567211462.029228] [/] [9] Matched vars updated.
[166567211462.029228] [/] [4] Running [independent] (non-disruptive) action: setvar
[166567211462.029228] [/] [8] Saving variable: USER:dynamic_var with value: user.EOYVxTvk
[166567211462.029228] [/] [4] Rule returned 1.
[166567211462.029228] [/] [9] Running action: log
[166567211462.029228] [/] [9] Saving transaction to logs
[166567211462.029228] [/] [9] Running action: auditlog
[166567211462.029228] [/] [9] Saving transaction to logs
[166567211462.029228] [/] [9] Running action: setuid
[166567211462.029228] [/] [8] User collection initiated with value: ''.
[166567211462.029228] [/] [9] Running action: exec
[166567211462.029228] [/] [8] Running script... /usr/local/openresty/nginx/lua/epoch_time_update.lua
[166567211462.029228] [/] [1]
[166567211462.029228] [/] [1] twst_var_name user.EOYVxTvk_twst
[166567211462.029228] [/] [1] req_rate_var user.EOYVxTvk
[166567211462.029228] [/] [1] throttle_window_start 1665672114
[166567211462.029228] [/] [1] throttle_window_end 1665672174
[166567211462.029228] [/] [1] cant find req_rate_var  user.EOYVxTvk
[166567211462.029228] [/] [1] current_req_rate 0
[166567211462.029228] [/] [1] setting current_req_rate to 1
[166567211462.029228] [/] [9] Returning from lua script:
[166567211462.029228] [/] [4] (Rule: 100004) Executing operator "Gt" with param "30" against USER:EOYVxTvk.
[166567211462.029228] [/] [9] Target value: "1" (Variable: USER:::::EOYVxTvk)
[166567211462.029228] [/] [4] Rule returned 0.
[166567211462.029228] [/] [9] Matched vars cleaned.
[166567211462.029228] [/] [4] (Rule: 100005) Executing operator "Eq" with param "0" against USER:DCrgmTrP_twst.
[166567211462.029228] [/] [9] Target value: "0" (Variable: USER:DCrgmTrP_twst)
[166567211462.029228] [/] [9] Matched vars updated.
[166567211462.029228] [/] [4] Running [independent] (non-disruptive) action: setvar
[166567211462.029228] [/] [8] Saving variable: USER:DCrgmTrP_twst with value: 1665672114
[166567211462.029228] [/] [4] Rule returned 1.
[166567211462.029228] [/] [4] Running (disruptive)     action: pass.
[166567211462.029228] [/] [8] Running action pass
[166567211462.029228] [/] [4] (Rule: 100006) Executing operator "Rx" with param "\Qchrome browser\E" against REQUEST_HEADERS:User-Agent.
[166567211462.029228] [/] [9] Target value: "firefox" (Variable: REQUEST_HEADERS:User-Agent)
[166567211462.029228] [/] [4] Rule returned 0.
[166567211462.029228] [/] [9] Matched vars cleaned.
[166567211462.029228] [/] [4] (Rule: 100008) Executing operator "Gt" with param "45" against USER:DCrgmTrP.
[166567211462.029228] [/] [4] Rule returned 0.
[166567211462.029228] [/] [9] Matched vars cleaned.
[166567211462.029228] [/] [4] Starting phase REQUEST_BODY. (SecRules 2)
[166567211462.029228] [/] [9] This phase consists of 5 rule(s).
[166567211462.029228] [/] [4] (Rule: 200007) Executing operator "Ge" with param "1000" against ARGS.
[166567211462.029228] [/] [9] Target value: "0" (Variable: ARGS)
[166567211462.029228] [/] [4] Rule returned 0.
[166567211462.029228] [/] [9] Matched vars cleaned.
[166567211462.029228] [/] [4] (Rule: 200002) Executing operator "Eq" with param "0" against REQBODY_ERROR.
[166567211462.029228] [/] [9] Target value: "0" (Variable: REQBODY_ERROR)
[166567211462.029228] [/] [4] Rule returned 0.
[166567211462.029228] [/] [9] Matched vars cleaned.
[166567211462.029228] [/] [4] (Rule: 200003) Executing operator "Eq" with param "0" against MULTIPART_STRICT_ERROR.
[166567211462.029228] [/] [9] Target value: "" (Variable: MULTIPART_STRICT_ERROR)
[166567211462.029228] [/] [4] Rule returned 0.
[166567211462.029228] [/] [9] Matched vars cleaned.
[166567211462.029228] [/] [4] (Rule: 200004) Executing operator "Eq" with param "1" against MULTIPART_UNMATCHED_BOUNDARY.
[166567211462.029228] [/] [9] Target value: "" (Variable: MULTIPART_UNMATCHED_BOUNDARY)
[166567211462.029228] [/] [4] Rule returned 0.
[166567211462.029228] [/] [9] Matched vars cleaned.
[166567211462.029228] [/] [4] (Rule: 200005) Executing operator "StrEq" with param "0" against TX:regex(^MSC_).
[166567211462.029228] [/] [4] Rule returned 0.
[166567211462.029228] [/] [9] Matched vars cleaned.
[166567211414.410830] [] [4] Initializing transaction
[166567211414.410830] [] [4] Transaction context created.
[166567211414.410830] [] [4] Starting phase CONNECTION. (SecRules 0)
[166567211414.410830] [] [9] This phase consists of 0 rule(s).
[166567211414.410830] [] [4] Starting phase URI. (SecRules 0 + 1/2)
[166567211414.410830] [/] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
[166567211414.410830] [/] [9] This phase consists of 8 rule(s).
[166567211414.410830] [/] [4] (Rule: 200000) Executing operator "Rx" with param "^(?:application(?:/soap\+|/)|text/)xml" against REQUEST_HEADERS:Content-Type.
[166567211414.410830] [/] [4] Rule returned 0.
[166567211414.410830] [/] [9] Matched vars cleaned.
[166567211414.410830] [/] [4] (Rule: 200001) Executing operator "Rx" with param "^application/json" against REQUEST_HEADERS:Content-Type.
[166567211414.410830] [/] [4] Rule returned 0.
[166567211414.410830] [/] [9] Matched vars cleaned.
[166567211414.410830] [/] [4] (Rule: 100001) Executing operator "Eq" with param "0" against USER:EOYVxTvk_twst.
[166567211414.410830] [/] [9] Target value: "1" (Variable: USER:EOYVxTvk_twst)
[166567211414.410830] [/] [4] Rule returned 0.
[166567211414.410830] [/] [9] Matched vars cleaned.
[166567211414.410830] [/] [4] (Rule: 100002) Executing operator "Rx" with param "\Qfirefox\E" against REQUEST_HEADERS:User-Agent.
[166567211414.410830] [/] [9] Target value: "firefox" (Variable: REQUEST_HEADERS:User-Agent)
[166567211414.410830] [/] [9] Matched vars updated.
[166567211414.410830] [/] [4] Running [independent] (non-disruptive) action: setvar
[166567211414.410830] [/] [8] Saving variable: USER:dynamic_var with value: user.EOYVxTvk
[166567211414.410830] [/] [4] Rule returned 1.
[166567211414.410830] [/] [9] Running action: log
[166567211414.410830] [/] [9] Saving transaction to logs
[166567211414.410830] [/] [9] Running action: auditlog
[166567211414.410830] [/] [9] Saving transaction to logs
[166567211414.410830] [/] [9] Running action: setuid
[166567211414.410830] [/] [8] User collection initiated with value: ''.
[166567211414.410830] [/] [9] Running action: exec
[166567211414.410830] [/] [8] Running script... /usr/local/openresty/nginx/lua/epoch_time_update.lua
[166567211414.410830] [/] [1]
[166567211414.410830] [/] [1] twst_var_name user.EOYVxTvk_twst
[166567211414.410830] [/] [1] req_rate_var user.EOYVxTvk
[166567211414.410830] [/] [1] throttle_window_start 1665672114
[166567211414.410830] [/] [1] throttle_window_end 1665672174
[166567211414.410830] [/] [1] current_req_rate 1
[166567211414.410830] [/] [1] setting current_req_rate to 2
[166567211414.410830] [/] [9] Returning from lua script:
[166567211414.410830] [/] [4] (Rule: 100004) Executing operator "Gt" with param "30" against USER:EOYVxTvk.
[166567211414.410830] [/] [9] Target value: "2" (Variable: USER:::::EOYVxTvk)
[166567211414.410830] [/] [4] Rule returned 0.
[166567211414.410830] [/] [9] Matched vars cleaned.
[166567211414.410830] [/] [4] (Rule: 100005) Executing operator "Eq" with param "0" against USER:DCrgmTrP_twst.
[166567211414.410830] [/] [9] Target value: "1" (Variable: USER:DCrgmTrP_twst)
[166567211414.410830] [/] [4] Rule returned 0.
[166567211414.410830] [/] [9] Matched vars cleaned.
[166567211414.410830] [/] [4] (Rule: 100006) Executing operator "Rx" with param "\Qchrome browser\E" against REQUEST_HEADERS:User-Agent.
[166567211414.410830] [/] [9] Target value: "firefox" (Variable: REQUEST_HEADERS:User-Agent)
[166567211414.410830] [/] [4] Rule returned 0.
[166567211414.410830] [/] [9] Matched vars cleaned.
[166567211414.410830] [/] [4] (Rule: 100008) Executing operator "Gt" with param "45" against USER:DCrgmTrP.
[166567211414.410830] [/] [4] Rule returned 0.
[166567211414.410830] [/] [9] Matched vars cleaned.
[166567211414.410830] [/] [4] Starting phase REQUEST_BODY. (SecRules 2)
[166567211414.410830] [/] [9] This phase consists of 5 rule(s).
[166567211414.410830] [/] [4] (Rule: 200007) Executing operator "Ge" with param "1000" against ARGS.
[166567211414.410830] [/] [9] Target value: "0" (Variable: ARGS)
[166567211414.410830] [/] [4] Rule returned 0.
[166567211414.410830] [/] [9] Matched vars cleaned.
[166567211414.410830] [/] [4] (Rule: 200002) Executing operator "Eq" with param "0" against REQBODY_ERROR.
[166567211414.410830] [/] [9] Target value: "0" (Variable: REQBODY_ERROR)
[166567211414.410830] [/] [4] Rule returned 0.
[166567211414.410830] [/] [9] Matched vars cleaned.
[166567211414.410830] [/] [4] (Rule: 200003) Executing operator "Eq" with param "0" against MULTIPART_STRICT_ERROR.
[166567211414.410830] [/] [9] Target value: "" (Variable: MULTIPART_STRICT_ERROR)
[166567211414.410830] [/] [4] Rule returned 0.
[166567211414.410830] [/] [9] Matched vars cleaned.
[166567211414.410830] [/] [4] (Rule: 200004) Executing operator "Eq" with param "1" against MULTIPART_UNMATCHED_BOUNDARY.
[166567211414.410830] [/] [9] Target value: "" (Variable: MULTIPART_UNMATCHED_BOUNDARY)
[166567211414.410830] [/] [4] Rule returned 0.
[166567211414.410830] [/] [9] Matched vars cleaned.
[166567211414.410830] [/] [4] (Rule: 200005) Executing operator "StrEq" with param "0" against TX:regex(^MSC_).
[166567211414.410830] [/] [4] Rule returned 0.
[166567211414.410830] [/] [9] Matched vars cleaned.
[166567211414.410830] [/] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
[166567211414.410830] [/] [9] This phase consists of 0 rule(s).
[166567211414.410830] [/] [9] Appending response body: 1097 bytes. Limit set to: 524288.000000
[166567211414.410830] [/] [4] Starting phase RESPONSE_BODY. (SecRules 4)
[166567211414.410830] [/] [9] This phase consists of 0 rule(s).
[166567211414.410830] [/] [4] Starting phase LOGGING. (SecRules 5)
[166567211414.410830] [/] [9] This phase consists of 0 rule(s).
[166567211414.410830] [/] [8] Checking if this request is suitable to be saved as an audit log.
[166567211414.410830] [/] [8] Checking if this request is relevant to be part of the audit logs.
[166567211414.410830] [/] [5] Saving this request as part of the audit logs.
[166567211414.410830] [/] [8] Request was relevant to be saved. Parts: 6006

2. AuditLogs

---SJm0ppeU---A--
[13/Oct/2022:14:41:54 +0000] 166567211414.410830 10.0.96.4 64454 10.11.17.192 80
---SJm0ppeU---B--
GET / HTTP/1.1
User-Agent: firefox
Postman-Token: 42c3c623-d140-40d5-9361-2cae719fb36a
Accept: */*
Host: 10.11.17.192
Accept-Encoding: gzip, deflate, br
Connection: keep-alive

---SJm0ppeU---D--

---SJm0ppeU---E--
<!DOCTYPE html>\x0a<html>\x0a<head>\x0a<meta content="text/html;charset=utf-8" http-equiv="Content-Type">\x0a<meta content="utf-8" http-equiv="encoding">\x0a<title>Welcome to OpenResty!</title>\x0a<style>\x0a    body {\x0a        width: 35em;\x0a        margin: 0 auto;\x0a        font-family: Tahoma, Verdana, Arial, sans-serif;\x0a    }\x0a</style>\x0a</head>\x0a<body>\x0a<h1>Welcome to OpenResty!</h1>\x0a<p>If you see this page, the OpenResty web platform is successfully installed and\x0aworking. Further configuration is required.</p>\x0a\x0a<p>For online documentation and support please refer to our\x0a<a href="https://openresty.org/">openresty.org</a> site<br/>\x0aCommercial support is available at\x0a<a href="https://openresty.com/">openresty.com</a>.</p>\x0a<p>We have articles on troubleshooting issues like <a href="https://blog.openresty.com/en/lua-cpu-flame-graph/?src=wb">high CPU usage</a> and\x0a<a href="https://blog.openresty.com/en/how-or-alloc-mem/">large memory usage</a> on <a href="https://blog.openresty.com/">our official blog site</a>.\x0a<p><em>Thank you for flying <a href="https://openresty.org/">OpenResty</a>.</em></p>\x0a</body>\x0a</html>\x0a

---SJm0ppeU---F--
HTTP/1.1 200
Server: openresty/1.21.4.1
Date: Thu, 13 Oct 2022 14:41:54 GMT
Content-Length: 1097
Content-Type: text/html
Last-Modified: Thu, 06 Oct 2022 09:29:18 GMT
Connection: keep-alive
ETag: "633e9fee-449"

---SJm0ppeU---H--
ModSecurity: Warning. Matched "Operator `Rx' with parameter `\Qfirefox\E' against variable `REQUEST_HEADERS:User-Agent' (Value: `firefox' ) [file "/usr/local/openresty/nginx/modsec/main.conf"] [line "8"] [id "100002"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.11.17.192"] [uri "/"] [unique_id "166567211414.410830"] [ref "o0,7v27,7"]

---SJm0ppeU---I--

---SJm0ppeU---J--

---SJm0ppeU---Z--

Notice: Be carefully to not leak any confidential information.

To Reproduce

Steps to reproduce the behavior:
Add the following modsecurity configuration;

SecRule &user.EOYVxTvk_twst "@eq 0" "phase:1,id:100001,pass,setvar:user.EOYVxTvk_twst=%{TIME_EPOCH}"

SecRule REQUEST_HEADERS:User-Agent "\Qfirefox\E" "id:100002,phase:1,log,auditlog,setuid:%{tx.ua_hash},setvar:user.dynamic_var=user.EOYVxTvk,exec:/usr/local/openresty/nginx/lua/epoch_time_update.lua"

SecRule user:EOYVxTvk "@gt 30" "chain,id:100004,phase:1,auditlog,deny,status:429,setenv:RATELIMITED,log,msg:'RATELIMITED User-Agent'"
            SecRule REQUEST_HEADERS:User-Agent "\Qfirefox\E"


SecRule &user.DCrgmTrP_twst "@eq 0" "phase:1,id:100005,pass,setvar:user.DCrgmTrP_twst=%{TIME_EPOCH}"

SecRule REQUEST_HEADERS:User-Agent "\Qchrome browser\E" "id:100006,phase:1,log,auditlog,setuid:%{tx.ua_hash},setvar:user.dynamic_var=user.DCrgmTrP,exec:/usr/local/openresty/nginx/lua/epoch_time_update.lua"

SecRule user:DCrgmTrP "@gt 45" "chain,id:100008,phase:1,auditlog,deny,status:429,setenv:RATELIMITED,log,msg:'RATELIMITED User-Agent'"
            SecRule REQUEST_HEADERS:User-Agent "\Qchrome browser\E"

Curl command to make the request.

curl --location --request GET 'http://10.11.17.192/' --header 'User-Agent: firefox'

Expected behavior

Expectation was Rule: 100002 would run only once per request, but its running twice.

Server (please complete the following information):

• ModSecurity v3.0.1 with nginx-connector v1.0.3
• WebServer: nginx version: openresty/1.21.4.1
• OS (and distro): Ubuntu 22.04.1 LTS

Rule Set (please complete the following information):

• Running any public or commercial rule set? No
• What is the version number? [e.g. 2018-08-11] NA

[martinhsv]

Hello @nagri ,

As far as ModSecurity is concerned it is seeing two transactions.

It is possible for a single HTTP request arriving at an nginx+ModSecurity instance to be processed twice -- depending on how you have set up your nginx configuration. For example error page redirection can result in ModSecurity seeing a request twice (possibly with the request method changed -- owasp-modsecurity/ModSecurity-nginx#152 (comment) )

Even if that particular scenario does not seem to match, my guess is that you are experiencing something comparable.

You could try analyzing and experimenting with which location (etc.) blocks in your nginx configuration that you have modsecurity enabled.

[nagri]

Hey @martinhsv, Thank you for replying.
I saw the link you mentioned and indeed I had some error redirection.
I removed those and now my nginx.conf looks like this;

load_module /usr/local/openresty/nginx/modules/ngx_http_modsecurity_module.so;
worker_processes  1;

events {
    worker_connections  1024;
}

http {
    include       mime.types;
    default_type  application/octet-stream;

    lua_package_path "/usr/local/lib/lua/?.lua;;";

    sendfile        on;

    keepalive_timeout  65;

    server {
        listen       80;
        server_name  localhost;
       
        modsecurity on;
        modsecurity_rules_file /usr/local/openresty/nginx/modsec/main.conf;

        location / {
            root   html;
            index  index.html index.htm;
        }

    }

}

Very basic nginx conf, but the issue still persists.
I checked in nginx access.log, it receives one request only.

furthermore as per the modsecurity audit logs, we can see only one request came and one response was returned. correct me if I am wrong.
What else can I do to debug this further?

[martinhsv]

One thing I'll draw your attention to is that in your posted debug log output, the two transactions (from ModSecurity's point of view) are 166567211462.029228 and 166567211414.410830. The first of those two ends with the phase REQUEST_BODY ("Starting phase REQUEST_BODY.") I.e. there is no execution of either the phase "RESPONSE_HEADERS" or "LOGGING".

This suggests that processing of the original "transaction" is being interrupted at a level above ModSecurity.

Indeed the first .conf file that you posted ( #2816 (comment) ) could be consistent with this possibility -- given the error-redirect specification that is present.

However, unless something not shown is doing something, I would agree that your second .conf file ( #2816 (comment) ) does not suggest this -- especially if the ModSecurity debug log looks the same after the change to the second .conf file.

I would suggest increasing the log level of your nginx error.log file. E.g.:

error_log  /var/log/nginx/error.log debug;

Also, what is/was the content of the response received by the client? With the original .conf was it /50x.html? How about with the second .conf?

[nagri]

Also, what is/was the content of the response received by the client? With the original .conf was it /50x.html? How about with the second .conf?

Response is always OK with HTTP status code 200. Error Never occurred.

One weid thing happening is that if the URI is anything but "/" the flow is proper and modsecurity is processing only one transaction.

here for http://10.11.17.192/index.html

debug.log

[166573028025.877167] [] [4] Initializing transaction
[166573028025.877167] [] [4] Transaction context created.
[166573028025.877167] [] [4] Starting phase CONNECTION. (SecRules 0)
[166573028025.877167] [] [9] This phase consists of 0 rule(s).
[166573028025.877167] [] [4] Starting phase URI. (SecRules 0 + 1/2)
[166573028025.877167] [/index.html] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
[166573028025.877167] [/index.html] [9] This phase consists of 8 rule(s).
[166573028025.877167] [/index.html] [4] (Rule: 200000) Executing operator "Rx" with param "^(?:application(?:/soap\+|/)|text/)xml" against REQUEST_HEADERS:Content-Type.
[166573028025.877167] [/index.html] [4] Rule returned 0.
[166573028025.877167] [/index.html] [9] Matched vars cleaned.
[166573028025.877167] [/index.html] [4] (Rule: 200001) Executing operator "Rx" with param "^application/json" against REQUEST_HEADERS:Content-Type.
[166573028025.877167] [/index.html] [4] Rule returned 0.
[166573028025.877167] [/index.html] [9] Matched vars cleaned.
[166573028025.877167] [/index.html] [4] (Rule: 100001) Executing operator "Eq" with param "0" against USER:EOYVxTvk_twst.
[166573028025.877167] [/index.html] [9] Target value: "0" (Variable: USER:EOYVxTvk_twst)
[166573028025.877167] [/index.html] [9] Matched vars updated.
[166573028025.877167] [/index.html] [4] Running [independent] (non-disruptive) action: setvar
[166573028025.877167] [/index.html] [8] Saving variable: USER:EOYVxTvk_twst with value: 1665730280
[166573028025.877167] [/index.html] [4] Rule returned 1.
[166573028025.877167] [/index.html] [4] Running (disruptive)     action: pass.
[166573028025.877167] [/index.html] [8] Running action pass
[166573028025.877167] [/index.html] [4] (Rule: 100002) Executing operator "Rx" with param "\Qfirefox\E" against REQUEST_HEADERS:User-Agent.
[166573028025.877167] [/index.html] [9] Target value: "firefox" (Variable: REQUEST_HEADERS:User-Agent)
[166573028025.877167] [/index.html] [9] Matched vars updated.
[166573028025.877167] [/index.html] [4] Running [independent] (non-disruptive) action: setvar
[166573028025.877167] [/index.html] [8] Saving variable: USER:dynamic_var with value: user.EOYVxTvk
[166573028025.877167] [/index.html] [4] Rule returned 1.
[166573028025.877167] [/index.html] [9] Running action: log
[166573028025.877167] [/index.html] [9] Saving transaction to logs
[166573028025.877167] [/index.html] [9] Running action: auditlog
[166573028025.877167] [/index.html] [9] Saving transaction to logs
[166573028025.877167] [/index.html] [9] Running action: setuid
[166573028025.877167] [/index.html] [8] User collection initiated with value: ''.
[166573028025.877167] [/index.html] [9] Running action: exec
[166573028025.877167] [/index.html] [8] Running script... /usr/local/openresty/nginx/lua/epoch_time_update.lua
[166573028025.877167] [/index.html] [1]
[166573028025.877167] [/index.html] [1] twst_var_name user.EOYVxTvk_twst
[166573028025.877167] [/index.html] [1] req_rate_var user.EOYVxTvk
[166573028025.877167] [/index.html] [1] throttle_window_start 1665730280
[166573028025.877167] [/index.html] [1] throttle_window_end 1665730340
[166573028025.877167] [/index.html] [1] cant find req_rate_var  user.EOYVxTvk
[166573028025.877167] [/index.html] [1] current_req_rate 0
[166573028025.877167] [/index.html] [1] setting current_req_rate to 1
[166573028025.877167] [/index.html] [9] Returning from lua script:
[166573028025.877167] [/index.html] [4] (Rule: 100004) Executing operator "Gt" with param "30" against USER:EOYVxTvk.
[166573028025.877167] [/index.html] [9] Target value: "1" (Variable: USER:::::EOYVxTvk)
[166573028025.877167] [/index.html] [4] Rule returned 0.
[166573028025.877167] [/index.html] [9] Matched vars cleaned.
[166573028025.877167] [/index.html] [4] (Rule: 100005) Executing operator "Eq" with param "0" against USER:DCrgmTrP_twst.
[166573028025.877167] [/index.html] [9] Target value: "0" (Variable: USER:DCrgmTrP_twst)
[166573028025.877167] [/index.html] [9] Matched vars updated.
[166573028025.877167] [/index.html] [4] Running [independent] (non-disruptive) action: setvar
[166573028025.877167] [/index.html] [8] Saving variable: USER:DCrgmTrP_twst with value: 1665730280
[166573028025.877167] [/index.html] [4] Rule returned 1.
[166573028025.877167] [/index.html] [4] Running (disruptive)     action: pass.
[166573028025.877167] [/index.html] [8] Running action pass
[166573028025.877167] [/index.html] [4] (Rule: 100006) Executing operator "Rx" with param "\Qchrome browser\E" against REQUEST_HEADERS:User-Agent.
[166573028025.877167] [/index.html] [9] Target value: "firefox" (Variable: REQUEST_HEADERS:User-Agent)
[166573028025.877167] [/index.html] [4] Rule returned 0.
[166573028025.877167] [/index.html] [9] Matched vars cleaned.
[166573028025.877167] [/index.html] [4] (Rule: 100008) Executing operator "Gt" with param "45" against USER:DCrgmTrP.
[166573028025.877167] [/index.html] [4] Rule returned 0.
[166573028025.877167] [/index.html] [9] Matched vars cleaned.
[166573028025.877167] [/index.html] [4] Starting phase REQUEST_BODY. (SecRules 2)
[166573028025.877167] [/index.html] [4] Request body processing is disabled
[166573028025.877167] [/index.html] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
[166573028025.877167] [/index.html] [9] This phase consists of 0 rule(s).
[166573028025.877167] [/index.html] [9] Appending response body: 1097 bytes. Limit set to: 524288.000000
[166573028025.877167] [/index.html] [4] Starting phase RESPONSE_BODY. (SecRules 4)
[166573028025.877167] [/index.html] [4] Response body is disabled, returning... 1
[166573028025.877167] [/index.html] [4] Starting phase LOGGING. (SecRules 5)
[166573028025.877167] [/index.html] [9] This phase consists of 0 rule(s).
[166573028025.877167] [/index.html] [8] Checking if this request is suitable to be saved as an audit log.
[166573028025.877167] [/index.html] [8] Checking if this request is relevant to be part of the audit logs.
[166573028025.877167] [/index.html] [5] Saving this request as part of the audit logs.
[166573028025.877167] [/index.html] [8] Request was relevant to be saved. Parts: 6006

audit.log

---GGi7oqGW---A--
[14/Oct/2022:06:51:20 +0000] 166573028025.877167 10.0.96.4 49458 10.11.17.192 80
---GGi7oqGW---B--
GET /index.html HTTP/1.1
User-Agent: firefox
Postman-Token: e85715b5-efef-494e-9ac9-b88e05bc7501
Accept: */*
Host: 10.11.17.192
Accept-Encoding: gzip, deflate, br
Connection: keep-alive

---GGi7oqGW---D--

---GGi7oqGW---E--
<!DOCTYPE html>\x0a<html>\x0a<head>\x0a<meta content="text/html;charset=utf-8" http-equiv="Content-Type">\x0a<meta content="utf-8" http-equiv="encoding">\x0a<title>Welcome to OpenResty!</title>\x0a<style>\x0a    body {\x0a        width: 35em;\x0a        margin: 0 auto;\x0a        font-family: Tahoma, Verdana, Arial, sans-serif;\x0a    }\x0a</style>\x0a</head>\x0a<body>\x0a<h1>Welcome to OpenResty!</h1>\x0a<p>If you see this page, the OpenResty web platform is successfully installed and\x0aworking. Further configuration is required.</p>\x0a\x0a<p>For online documentation and support please refer to our\x0a<a href="https://openresty.org/">openresty.org</a> site<br/>\x0aCommercial support is available at\x0a<a href="https://openresty.com/">openresty.com</a>.</p>\x0a<p>We have articles on troubleshooting issues like <a href="https://blog.openresty.com/en/lua-cpu-flame-graph/?src=wb">high CPU usage</a> and\x0a<a href="https://blog.openresty.com/en/how-or-alloc-mem/">large memory usage</a> on <a href="https://blog.openresty.com/">our official blog site</a>.\x0a<p><em>Thank you for flying <a href="https://openresty.org/">OpenResty</a>.</em></p>\x0a</body>\x0a</html>\x0a

---GGi7oqGW---F--
HTTP/1.1 200
Server: openresty/1.21.4.1
Date: Fri, 14 Oct 2022 06:51:20 GMT
Content-Length: 1097
Content-Type: text/html
Last-Modified: Thu, 06 Oct 2022 09:29:18 GMT
Connection: keep-alive
ETag: "633e9fee-449"

---GGi7oqGW---H--
ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `USER:EOYVxTvk_twst' (Value: `0' ) [file "/usr/local/openresty/nginx/modsec/main.conf"] [line "6"] [id "100001"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.11.17.192"] [uri "/index.html"] [unique_id "166573028025.877167"] [ref ""]
ModSecurity: Warning. Matched "Operator `Rx' with parameter `\Qfirefox\E' against variable `REQUEST_HEADERS:User-Agent' (Value: `firefox' ) [file "/usr/local/openresty/nginx/modsec/main.conf"] [line "8"] [id "100002"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.11.17.192"] [uri "/index.html"] [unique_id "166573028025.877167"] [ref "o0,7v37,7"]
ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `USER:DCrgmTrP_twst' (Value: `0' ) [file "/usr/local/openresty/nginx/modsec/main.conf"] [line "13"] [id "100005"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.11.17.192"] [uri "/index.html"] [unique_id "166573028025.877167"] [ref ""]

---GGi7oqGW---I--

---GGi7oqGW---J--

---GGi7oqGW---Z--

whats so special about "/"?

I also change the nginx error log to debug as you asked for.
Here is what I got for URI /index.html

2022/10/14 06:56:09 [info] 92059#0: *1 ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `USER:EOYVxTvk_twst' (Value: `0' ) [file "/usr/local/openresty/nginx/modsec/main.conf"] [line "6"] [id "100001"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.11.17.192"] [uri "/index.html"] [unique_id "166573056949.050735"] [ref ""], client: 10.0.96.4, server: localhost, request: "GET /index.html HTTP/1.1", host: "10.11.17.192"
2022/10/14 06:56:09 [info] 92059#0: *1 ModSecurity: Warning. Matched "Operator `Rx' with parameter `\Qfirefox\E' against variable `REQUEST_HEADERS:User-Agent' (Value: `firefox' ) [file "/usr/local/openresty/nginx/modsec/main.conf"] [line "8"] [id "100002"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.11.17.192"] [uri "/index.html"] [unique_id "166573056949.050735"] [ref "o0,7v37,7"], client: 10.0.96.4, server: localhost, request: "GET /index.html HTTP/1.1", host: "10.11.17.192"
2022/10/14 06:56:09 [info] 92059#0: *1 ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `USER:DCrgmTrP_twst' (Value: `0' ) [file "/usr/local/openresty/nginx/modsec/main.conf"] [line "13"] [id "100005"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.11.17.192"] [uri "/index.html"] [unique_id "166573056949.050735"] [ref ""], client: 10.0.96.4, server: localhost, request: "GET /index.html HTTP/1.1", host: "10.11.17.192"

Here is what I got for URI / ;

2022/10/14 06:56:30 [info] 92059#0: *1 ModSecurity: Warning. Matched "Operator `Rx' with parameter `\Qfirefox\E' against variable `REQUEST_HEADERS:User-Agent' (Value: `firefox' ) [file "/usr/local/openresty/nginx/modsec/main.conf"] [line "8"] [id "100002"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.11.17.192"] [uri "/"] [unique_id "166573059065.860011"] [ref "o0,7v27,7"], client: 10.0.96.4, server: localhost, request: "GET / HTTP/1.1", host: "10.11.17.192"
2022/10/14 06:56:30 [info] 92059#0: *1 ModSecurity: Warning. Matched "Operator `Rx' with parameter `\Qfirefox\E' against variable `REQUEST_HEADERS:User-Agent' (Value: `firefox' ) [file "/usr/local/openresty/nginx/modsec/main.conf"] [line "8"] [id "100002"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "10.11.17.192"] [uri "/"] [unique_id "166573059065.659690"] [ref "o0,7v27,7"], client: 10.0.96.4, server: localhost, request: "GET / HTTP/1.1", host: "10.11.17.192"

[martinhsv]

Hi @nagri ,

Your discovery that the anomaly only occurs with the URI '/' is a good finding. That narrows down the issue considerably.

It looks like I am able to reproduce that behaviour, so it's not just you.

My speculation is that this use case is at least loosely similar to the error-redirect issue discussed earlier in that:

• an initial URI ('/') is being received by nginx, which is transformed (at least internally) by the nginx configuration into another URI .

It's possible that this is long-time expected behaviour in nginx or it could also be a bug in nginx.

If this is causing a nuisance for you in a production environment, one option that you could consider: if '/' is merely serving safe static content, you could turn off modsecurity in that location block (or only turn it on in other location blocks, rather than in the surrounding server block). Other possibilities include include only turning off (in the '/' location block) those rules that cause misleading results.

[nagri]

If this is causing a nuisance for you in a production environment, one option that you could consider: if '/' is merely serving safe static content, you could turn off modsecurity in that location block (or only turn it on in other location blocks, rather than in the surrounding server block). Other possibilities include include only turning off (in the '/' location block) those rules that cause misleading results.

30% of the traffic comes via '/' and all the rules are needed there as well. I am afraid cant use the workaround you suggested.

What would be the next plan of action? Would you guys try to fix this from your end or would we have to live with this?

[martinhsv]

When I gave that suggestion as a possible mitigation, what I meant was that you should assess what your needs are with respect to your rules.

For example, let's assume you are using blocking mode, and malicious content (such as SQLi) triggers a rule that is intended to result in deny. In that case, I would expect you would not see the request being received by ModSecurity twice. I.e. for these types of rules you probably don't need to do anything special with respect to your URI="/" issue.

For some other rules (e.g. transaction counts used for any anti-DoS purposes), knowing when there is a false doubling of the transaction count should be relatively simple to handle.

It's, of course, up to you what to do. Those are just some things to consider.

In terms of an actual fix, the issue would need more investigation to come to any firm conclusion.

[nagri]

@martinhsv I dont know if this would be the right place to ask this question, but here it goes.

If I create a vaiable say
SecAction "phase:1,id:100001,nolog,pass,setvar:user.ugmJRkZkjvEz=%{TIME_EPOCH}"
This creates a variable user.ugmJRkZkjvEz
would this user.ugmJRkZkjvEz variable be unique to all the worker processes of nginx?

What I am observing is each worker process of nginx has a different copy of user.ugmJRkZkjvEz, or so it seems.
Is there a collection that can be used where values can be consistent across all the nginix workers?

[martinhsv]

Hello @nagri ,

No, this is not the right place for that. Posting questions on an unrelated issue has several negative effects:

• the original '/' issue is a notable one and other members of the ModSecurity community may get value from finding it; separate questions about unrelated matters pollutes the thread and makes it less usable for others
• posting this unrelated shared memory question here makes it less likely that other members of the community will see your question and potentially answer it
• if other members of the community have the same question you do (perhaps months from now) about shared memory, it is more difficult for them to find it (and the answer) because it's embedded in an issue with an unrelated title
  In other words, I would discourage posting unrelated questions to pre-existing issues.

However, to answer your question: if you want memory sharing across nginx worker processes, have a look at ModSecurity's lmdb support (compilation flag: '--with-lmdb').