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

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

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>