No phase3/4 with rewrite?

Adrian Daminato <[email protected]>
Newsgroups gmane.comp.apache.mod-security.user
Message-ID <CAJ-iWvM96RJ2JukFgm4MoHM_ywEv0XdVrgVGKYpdy8NnNUQktQ@mail.gmail.com> 
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
[email protected]

*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
[email protected]
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/
lmpx.com only provides a reader for public news (NNTP) servers. It is not affiliated with the servers or forums shown here and is not responsible for the content of articles, which is written by their respective authors.