I'm trying to debug a mod_security2 issue where it at some point appears to stop processing phase:2 rules. I've installed libapache2-mod-security2 and modsecurity-crs from the default apt repositories and have enabled the engine.
SecDebugLogLevel 9 gives following:
...
[/tomc4][4] Recipe: Invoking rule 7f3a5e3c8778; [file "/usr/share/modsecurity-crs/rules/REQUEST-903.9001-DRUPAL-EXCLUSION-RULES.conf"] [line "72"] [id "9001000"].
[/tomc4][5] Rule 7f3a5e3c8778: SecRule "&TX:crs_exclusions_drupal|TX:crs_exclusions_drupal" "@eq 0" "phase:1,auditlog,id:9001000,t:none,nolog,ver:OWASP_CRS/3.3.0,skipAfter:END-DRUPAL-RULE-EXCLUSIONS"
[/tomc4][4] Transformation completed in 0 usec.
[/tomc4][4] Executing operator "eq" with param "0" against &TX:crs_exclusions_drupal.
[/tomc4][9] Target value: "0"
[/tomc4][4] Operator completed in 0 usec.
[/tomc4][4] Warning. Operator EQ matched 0 at TX. [file "/usr/share/modsecurity-crs/rules/REQUEST-903.9001-DRUPAL-EXCLUSION-RULES.conf"] [line "72"] [id "9001000"] [ver "OWASP_CRS/3.3.0"]
[/tomc4][4] Rule returned 1.
[/tomc4][9] Skipping after rule 7f3a5e3c8778 id="END-DRUPAL-RULE-EXCLUSIONS" -> mode SKIP_RULES.
[/tomc4][9] Found rule 7f3a5e387188 id="END-DRUPAL-RULE-EXCLUSIONS".
[/tomc4][4] Continuing execution after rule id="END-DRUPAL-RULE-EXCLUSIONS".
[/tomc4][4] Recipe: Invoking rule 7f3a5e387d68; [file "/usr/share/modsecurity-crs/rules/REQUEST-903.9002-WORDPRESS-EXCLUSION-RULES.conf"] [line "26"] [id "9002000"].
[/tomc4][4] Recipe: Invoking rule 7f3a5e387d68; [file "/usr/share/modsecurity-crs/rules/REQUEST-903.9002-WORDPRESS-EXCLUSION-RULES.conf"] [line "26"] [id "9002000"].
[/tomc4][5] Rule 7f3a5e387d68: SecRule "&TX:crs_exclusions_wordpress|TX:crs_exclusions_wordpress" "@eq 0" "phase:1,auditlog,id:9002000,t:none,nolog,ver:OWASP_CRS/3.3.0,skipAfter:END-WORDPRESS"
[/tomc4][4] Transformation completed in 1 usec.
[/tomc4][4] Executing operator "eq" with param "0" against &TX:crs_exclusions_wordpress.
...
...
[/tomc4][4] Starting phase REQUEST_BODY.
[/tomc4][9] This phase consists of 470 rule(s).
...
[/tomc4][4] Recipe: Invoking rule 7f3a5e3c0190; [file "/usr/share/modsecurity-crs/rules/REQUEST-903.9001-DRUPAL-EXCLUSION-RULES.conf"] [line "81"] [id "9001001"].
[/tomc4][5] Rule 7f3a5e3c0190: SecRule "&TX:crs_exclusions_drupal|TX:crs_exclusions_drupal" "@eq 0" "phase:2,auditlog,id:9001001,t:none,nolog,ver:OWASP_CRS/3.3.0,skipAfter:END-DRUPAL-RULE-EXCLUSIONS"
[/tomc4][4] Transformation completed in 0 usec.
[/tomc4][4] Executing operator "eq" with param "0" against &TX:crs_exclusions_drupal.
[/tomc4][9] Target value: "0"
[/tomc4][4] Operator completed in 0 usec.
[/tomc4][4] Warning. Operator EQ matched 0 at TX. [file "/usr/share/modsecurity-crs/rules/REQUEST-903.9001-DRUPAL-EXCLUSION-RULES.conf"] [line "81"] [id "9001001"] [ver "OWASP_CRS/3.3.0"]
[/tomc4][4] Rule returned 1.
[/tomc4][9] Skipping after rule 7f3a5e3c0190 id="END-DRUPAL-RULE-EXCLUSIONS" -> mode SKIP_RULES.
[/tomc4][9] Current rule is id="9001100" [chained 0] is trying to find the SecMarker="END-DRUPAL-RULE-EXCLUSIONS" [stater 0]
[/tomc4][9] Current rule is id="9001110" [chained 0] is trying to find the SecMarker="END-DRUPAL-RULE-EXCLUSIONS" [stater 0]
[/tomc4][9] Current rule is id="9001112" [chained 0] is trying to find the SecMarker="END-DRUPAL-RULE-EXCLUSIONS" [stater 0]
...
[/tomc4][9] Current rule is id="9006960" [chained 0] is trying to find the SecMarker="END-DRUPAL-RULE-EXCLUSIONS" [stater 0]
[/tomc4][9] Current rule is id="9006970" [chained 0] is trying to find the SecMarker="END-DRUPAL-RULE-EXCLUSIONS" [stater 0]
[/tomc4][9] Current rule is id="910012" [chained 0] is trying to find the SecMarker="END-DRUPAL-RULE-EXCLUSIONS" [stater 0]
[/tomc4][9] Current rule is id="910000" [chained 0] is trying to find the SecMarker="END-DRUPAL-RULE-EXCLUSIONS" [stater 0]
....
[/tomc4][9] Current rule is id="980016" [chained 0] is trying to find the SecMarker="END-DRUPAL-RULE-EXCLUSIONS" [stater 0]
[/tomc4][9] Current rule is id="980018" [chained 0] is trying to find the SecMarker="END-DRUPAL-RULE-EXCLUSIONS" [stater 0]
[/tomc4][4] Hook insert_filter: Adding output filter (r 7f3a5ee6a0a0).
[/tomc4][9] Output filter: Receiving output (f 7f3a5ee3b6d8, r 7f3a5ee6a0a0).
[/tomc4][4] Starting phase RESPONSE_HEADERS.
...
In short, it start processing phase 1, processes rule 9001000 defined in REQUEST-903.9001-DRUPAL-EXCLUSION-RULES.conf. This rule matches and triggers a skip to END-DRUPAL-RULE-EXCLUSIONS, which is defined as a marker at the end of the same file. Mod-security then continues processing the rules defined in other files.
When it moves to phase 2 (REQUEST_BODY), it processes a similar rule in the Drupal file, rule 9001001. This rule again will trigger a skip to END-DRUPAL-RULE-EXCLUSIONS, but this skip will for some reason not find the END-DRUPAL-RULE-EXCLUSIONS SecMarker and will keep skipping all other rules until there are no more rules left to process and it moves on to the next phase.
In the above log, you can see it at some point going from rule id 9006970 which is defined in REQUEST-903.9001-DRUPAL-EXCLUSION-RULES.conf to rule id 910012 which is defined in REQUEST-910-IP-REPUTATION.conf, where it should have stopped at the SecMarker in the Drupal file.
This means that non of the phase 2 rules of the CRS are actually evaluated, and no blocking occurs. Any ideas why this is happening?
