Re: [mod-security-users] No phase3/4 with rewrite?

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

Hello Adrian,

You are facing a complicated problem on a very old system. Ubuntu 14.04 is
still supported by Ubuntu of course, but I have not touched Apache 2.4.7
and ModSec 2.7.7 for years.

Please try and reproduce the error on a newer system with ModSec 2.9.2 and
a recent Apache > 2.4.30. If it persists, somebody may want to take a closer
look. This way it's likely to take a large amount of time - and time is
scarce, so your question is mostly ignored.

Ahoj,

Christian

On Mon, Oct 29, 2018 at 02:01:55PM -0400, Adrian Daminato wrote:
> I'm running a stock Ubuntu 14.04 setup with Apache 2.4.7 and ModSecurity
> 2.7.7, on a PHP based API that uses rewrites.  With my searches of the
> mailing list archives and git issues, I believe I'm having problem similar
> to the ones described in
> https://github.com/SpiderLabs/ModSecurity/issues/1658
> 
> I'm fairly certain the rewrite is causing this, however other searches have
> led me in circles, or dead-ends, suggesting this problem was resolved (e.g.
> https://github.com/SpiderLabs/ModSecurity/issues/185)
> 
> Even if I'm doing no rules, and having SecAuditEngine set to On, I get
> responses on every request that comes through, except for calls that go via
> /api/ and the rewrite rules, so I'm fairly certain this isn't from a
> ModSecurity misconfiguration that I've done.
> 
> My ModSecurity configuration is as follows:
> 
> SecRuleEngine On
> SecAuditEngine RelevantOnly
> SecAuditLogType Concurrent
> SecAuditLogDirMode 755
> SecAuditLogFileMode 644
> SecAuditLog /var/log/apache2/post_audit.log
> SecAuditLogStorageDir /var/log/apache2/modsecurity
> SecRequestBodyAccess on
> SecResponseBodyAccess On
> SecAuditLogParts ABIEFGHZ
> 
> SecResponseBodyMimeType text/plain text/html text/xml application/json
> application/x-httpd-php
> SecRequestBodyLimitAction ProcessPartial
> SecResponseBodyLimitAction ProcessPartial
> 
> SecDefaultAction "nolog,noauditlog,allow,phase:2"
> 
> SecRule REQUEST_METHOD "POST" "id:1234,allow,phase:2,chain"
> SecRule ARGS:object recording "ctl:auditEngine=On,nolog"
> 
> With debug logging enabled, I can see that requests to the API are hit, and
> the rewrite followed but the response is never hit
> 
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4]
> Initialising transaction (txid W9cU9n8AAQEAAB30p0sAAAAB).
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4]
> Transaction context created (dcfg 7f5560154be8).
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4]
> Starting phase REQUEST_HEADERS.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][9] This
> phase consists of 0 rule(s).
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4]
> Second phase starting (dcfg 7f5560154be8).
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4]
> Input filter: Reading request body.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][9]
> Input filter: Bucket type TRANSIENT contains 53 bytes.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][9]
> Input filter: Bucket type EOS contains 0 bytes.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][5]
> Adding request argument (BODY): name "object", value "recording"
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][5]
> Adding request argument (BODY): name "id", value "20181026131815011691"
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][5]
> Adding request argument (BODY): name "action", value "read"
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4]
> Input filter: Completed receiving request body (length 53).
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4]
> Starting phase REQUEST_BODY.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][9] This
> phase consists of 2 rule(s).
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4]
> Recipe: Invoking rule 7f55600d9148; [file
> "/etc/modsecurity/post_audit.conf"] [line "16"] [id "1234"].
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][5] Rule
> 7f55600d9148: SecRule "REQUEST_METHOD" "@rx POST"
> "nolog,noauditlog,phase:2,id:1234,allow:phase,chain"
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4]
> Transformation completed in 1 usec.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4]
> Executing operator "rx" with param "POST" against REQUEST_METHOD.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][9]
> Target value: "POST"
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4]
> Operator completed in 3 usec.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4] Rule
> returned 1.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][9]
> Match -> mode NEXT_RULE.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4]
> Recipe: Invoking rule 7f55600d9b58; [file
> "/etc/modsecurity/post_audit.conf"] [line "17"].
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][5] Rule
> 7f55600d9b58: SecRule "ARGS:object" "@rx recording" "ctl:auditEngine=On"
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4]
> Transformation completed in 0 usec.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4]
> Executing operator "rx" with param "recording" against ARGS:object.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][9]
> Target value: "recording"
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4]
> Operator completed in 1 usec.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4] Ctl:
> Set auditEngine to 1.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4] Rule
> returned 1.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][9]
> Match, intercepted -> returning.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4]
> Access to phase allowed (phase 2). Pattern match "recording" at
> ARGS:object. [file "/etc/modsecurity/post_audit.conf"] [line "16"] [id
> "1234"]
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4] Hook
> insert_filter: Adding input forwarding filter (r 7f5546c1a0a0).
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4] Hook
> insert_filter: Adding output filter (r 7f5546c1a0a0).
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c0ebf8][/api/webroot/recordings][4]
> Hook insert_filter: Adding input forwarding filter for subrequest (r
> 7f5546c0ebf8).
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c02220][/api/webroot/index.php][4]
> Hook insert_filter: Adding input forwarding filter for subrequest (r
> 7f5546c02220).
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c02220][/api/webroot/index.php][4]
> Input filter: Forwarding input: mode=0, block=0, nbytes=16384 (f
> 7f5546c00b48, r 7f5546c02220).
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c02220][/api/webroot/index.php][4]
> Input filter: Forwarded 53 bytes.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c02220][/api/webroot/index.php][4]
> Input filter: Sent EOS.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c02220][/api/webroot/index.php][4]
> Input filter: Input forwarding complete.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c0ebf8][/api/webroot/recordings][4]
> Input filter: Input forwarding already complete, skipping (f 7f5546c020c8,
> r 7f5546c0ebf8).
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4]
> Input filter: Input forwarding already complete, skipping (f 7f5546c0ea68,
> r 7f5546c1a0a0).
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c1a0a0][/api/recordings][4]
> Initialising logging.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c02220][/api/webroot/index.php][4]
> Starting phase LOGGING.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c02220][/api/webroot/index.php][9]
> This phase consists of 0 rule(s).
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c02220][/api/webroot/index.php][4]
> Recording persistent data took 0 microseconds.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c02220][/api/webroot/index.php][4]
> Audit log: Logging this transaction.
> [29/Oct/2018:10:11:02 --0400]
> [apihost.local/sid#7f55600c6d20][rid#7f5546c02220][/api/webroot/index.php][9]
> Audit Log: Writing 272 bytes to primary concurrent index
> 
> For another endpoint, that's not hitting a rewrite, it processes as expected
> 
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Initialising
> transaction (txid W9cU9n8AAQEAAB31DioAAAAC).
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][5] Adding request
> argument (QUERY_STRING): name "status", value ""
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Transaction
> context created (dcfg 7f5560154be8).
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Starting phase
> REQUEST_HEADERS.
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][9] This phase
> consists of 0 rule(s).
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Second phase
> starting (dcfg 7f5560154be8).
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Input filter:
> This request does not have a body.
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Starting phase
> REQUEST_BODY.
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][9] This phase
> consists of 2 rule(s).
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Recipe:
> Invoking rule 7f55600d9148; [file "/etc/modsecurity/post_audit.conf"] [line
> "16"] [id "1234"].
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][5] Rule
> 7f55600d9148: SecRule "REQUEST_METHOD" "@rx POST"
> "nolog,noauditlog,phase:2,id:1234,allow:phase,chain"
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Transformation
> completed in 1 usec.
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Executing
> operator "rx" with param "POST" against REQUEST_METHOD.
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][9] Target value:
> "GET"
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Operator
> completed in 3 usec.
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Rule returned 0.
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][9] No match,
> chained -> mode NEXT_CHAIN.
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Hook
> insert_filter: Adding output filter (r 7f5546c1a0a0).
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Hook
> insert_error_filter: Adding output filter (r 7f5546c1a0a0).
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][9] Output filter:
> Receiving output (f 7f5546c16140, r 7f5546c1a0a0).
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Starting phase
> RESPONSE_HEADERS.
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][9] This phase
> consists of 0 rule(s).
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][9] Content
> Injection: Not enabled.
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][9] Output filter:
> Bucket type HEAP contains 374 bytes.
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][9] Output filter:
> Bucket type EOS contains 0 bytes.
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Output filter:
> Completed receiving response body (buffered full - 374 bytes).
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Starting phase
> RESPONSE_BODY.
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][9] This phase
> consists of 0 rule(s).
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Output filter:
> Output forwarding complete.
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Initialising
> logging.
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Starting phase
> LOGGING.
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][9] This phase
> consists of 0 rule(s).
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Recording
> persistent data took 0 microseconds.
> [29/Oct/2018:10:11:02 --0400]
> [localhost/sid#7f55600c6d20][rid#7f5546c1a0a0][/rproxy/][4] Audit log:
> Ignoring a non-relevant request.
> 
> The audit log file generated by the API call:
> 
> --a479b55a-B--
> POST /api/ HTTP/1.1
> Authorization: Basic YnVzOmJ1cw==
> Host: apihost.local
> Accept: */*
> Connection: keep-alive
> Content-Type: application/x-www-form-urlencoded
> Content-Length: 53
> 
> --a479b55a-C--
> object=recording&id=20181026131815011691&action=read
> --a479b55a-F--
> HTTP/1.1 200 OK
> Cache-Control: no-store
> Pragma: no-cache
> Vary: Accept-Encoding
> Content-Length: 650
> Keep-Alive: timeout=5, max=100
> Connection: Keep-Alive
> Content-Type: text/xml; charset="utf-8"
> 
> --a479b55a-H--
> Apache-Handler: application/x-httpd-php
> Stopwatch: 1540822262272919 70600 (- - -)
> Stopwatch2: 1540822262272919 70600; combined=112, p1=4, p2=83, p3=0, p4=0,
> p5=24, sr=0, sw=1, l=0, gc=0
> Producer: ModSecurity for Apache/2.7.7 (http://www.modsecurity.org/).
> Server: Apache/2.4.7 (Ubuntu)
> Engine-Mode: "ENABLED"
> 
> --a479b55a-Z--
> 
> And the rewrite rule setup is from an .htaccess in the directory root for
> /api/
> 
> <IfModule mod_rewrite.c>
>     RewriteEngine on
>     RewriteRule    ^$    webroot/    [L]
>     RewriteRule    (.*) webroot/$1    [L]
>  </IfModule>
> 
> Is the rewrite handling still a known issue in 2.7.7, or am I missing a
> simple configuration option to get this working?
> 
> -- 
> Adrian Daminato
> Manager, Core Services, Versature
> 1-877-498-3772 x111
> ada...@ve...
> 
> *The Latest News from Versature:*
> Versature to Scale Operations Through Acquisition by net2phone
> <https://www.versature.com/conversation-blog/net2phone-acquires-versature/>
> Versature Named to Growth 500 Ranking
> <https://www.versature.com/conversation-blog/versature-growth500-2018/>
> Best Questions to Start Your Data Analysis
> <https://www.versature.com/conversation-blog/best-questions-to-start-your-call-data-analysis/>
> 
> [image: Website]
> <https://www.versature.com?utm_source=Signature&utm_medium=Email&utm_campaign=Outreach>
> [image:
> LinkedIn] <https://www.linkedin.com/company/Versature> [image: Twitter]
> <https://www.twitter.com/Versature> [image: Facebook]
> <https://www.facebook.com/Versature> [image: Instagram]
> <https://www.instagram.com/versature_hpbx>

> _______________________________________________
> mod-security-users mailing list
> mod...@li...
> https://lists.sourceforge.net/lists/listinfo/mod-security-users
> Commercial ModSecurity Rules and Support from Trustwave's SpiderLabs:
> http://www.modsecurity.org/projects/commercial/rules/
> http://www.modsecurity.org/projects/commercial/support/