owasp-modsecurity / owasp-modsecurity/ModSecurity

Transaction intializing twice per request for URI '/'

Open
#2,816 9 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

3.x
Dominant language
C++
Stars
9.8k
Forks
1.8k
Avg merge
2h 46m
Merged PRs (30d)
1

Description

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
  1. 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

Contributor guide

No contributing guide indexed for this repository

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with the supplied level-9 debug logs for a request to URI '/'; compare the two transaction initialization sequences and the associated Lua script executions. Reproduce the request with the reported ModSecurity rules and determine why one request creates two transactions; done means one transaction and one script execution per request.

Written by the indexing model from the issue text.

Assessment

Tech stack
lua, nginx
Domain
backend, security
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
30/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.