High CPU usage when processing certain rules

[anderpups]

When mod_security is in SecRuleEngine DetectionOnly mode certain POSTs cause high CPU usage and a long delay on the return. This does not happen when mod_security is in SecRuleEngine On or mod_security is disabled.

I believe this may be the same bug referenced in #890

Below in the strace, you can see the gap in the times:

``[pid 28139] 12:59:24 write(4, "[03/Mar/2017:12:59:24 --0500] [d"..., 310) = 310
[pid 28139] 12:59:24 write(4, "[03/Mar/2017:12:59:24 --0500] [d"..., 129) = 129
[pid 28139] 12:59:24 write(4, "[03/Mar/2017:12:59:24 --0500] [d"..., 142) = 142
[pid 28139] 12:59:24 write(4, "[03/Mar/2017:12:59:24 --0500] [d"..., 1136) = 1136
[pid 28139] 12:59:24 brk(0) = 0x7fa129701000
[pid 28139] 12:59:24 brk(0x7fa129777000) = 0x7fa129777000
[pid 28139] 12:59:24 write(4, "[03/Mar/2017:12:59:24 --0500] [d"..., 1136) = 1136
[pid 28139] 12:59:24 write(4, "[03/Mar/2017:12:59:24 --0500] [d"..., 151) = 151
[pid 28139] 12:59:24 write(4, "[03/Mar/2017:12:59:24 --0500] [d"..., 306) = 306
[pid 28139] 12:59:24 brk(0) = 0x7fa129777000
[pid 28139] 12:59:24 brk(0x7fa1297ed000) = 0x7fa1297ed000
[pid 28139] 12:59:24 write(4, "[03/Mar/2017:12:59:24 --0500] [d"..., 1136) = 1136
[pid 28139] 13:00:43 write(4, "[03/Mar/2017:13:00:43 --0500] [d"..., 149) = 149
[pid 28139] 13:00:43 write(4, "[03/Mar/2017:13:00:43 --0500] [d"..., 147) = 147
[pid 28139] 13:00:43 write(4, "[03/Mar/2017:13:00:43 --0500] [d"..., 140) = 140
[pid 28139] 13:00:43 write(4, "[03/Mar/2017:13:00:43 --0500] [d"..., 149) = 149
[pid 28139] 13:00:43 write(4, "[03/Mar/2017:13:00:43 --0500] [d"..., 315) = 315
[pid 28139] 13:00:43 write(4, "[03/Mar/2017:13:00:43 --0500] [d"..., 137) = 137
[pid 28139] 13:00:43 write(4, "[03/Mar/2017:13:00:43 --0500] [d"..., 143) = 143
[pid 28139] 13:00:43 write(4, "[03/Mar/2017:13:00:43 --0500] [d"..., 1136) = 1136
[pid 28139] 13:00:43 brk(0) = 0x7fa1297ed000
[pid 28139] 13:00:43 brk(0x7fa12982e000) = 0x7fa12982e000
[pid 28139] 13:00:43 write(4, "[03/Mar/2017:13:00:43 --0500] [d"..., 1136) = 1136
[pid 28139] 13:00:43 write(4, "[03/Mar/2017:13:00:43 --0500] [d"..., 151) = 151
[pid 28139] 13:00:43 write(4, "[03/Mar/2017:13:00:43 --0500] [d"..., 312) = 312
[pid 28139] 13:00:43 brk(0) = 0x7fa12982e000
[pid 28139] 13:00:43 brk(0x7fa12986f000) = 0x7fa12986f000
[pid 28139] 13:00:43 write(4, "[03/Mar/2017:13:00:43 --0500] [d"..., 1136) = 1136
[pid 28139] 13:01:07 write(4, "[03/Mar/2017:13:01:07 --0500] [d"..., 149) = 149
[pid 28139] 13:01:07 write(4, "[03/Mar/2017:13:01:07 --0500] [d"..., 139) = 139
[pid 28139] 13:01:07 write(4, "[03/Mar/2017:13:01:07 --0500] [d"..., 132) = 132
[pid 28139] 13:01:07 write(4, "[03/Mar/2017:13:01:07 --0500] [d"..., 150) = 150

mod_sec_debug log:

[03/Mar/2017:12:59:24 --0500] [dsfstest.dti.state.de.us/sid#7fa12633a730][rid#7fa126414340][/dsfsSTUa0.aspx][4] Executing operator "rx" with param ".+application/x-shockwave-flash|image/svg\\+xml|text/(css|html|ecmascript|javascript|vbscript|x-(javascript|scriptlet|vbscript)).+" against ARGS:__VIEWSTATE.
[03/Mar/2017:12:59:24 --0500] [dsfstest.dti.state.de.us/sid#7fa12633a730][rid#7fa126414340][/dsfsSTUa0.aspx][9] Target value: "/wepdwukltq3mjkwnte4ma9kfgjmd2qwcaibd2qwagibdw8wah4hvmlzawjszwdkfgrmdxychgnzcmmffs9pbwfnzxmvynrutg9nb3v0lmdpzmqcaq8pfgiebfrlehqfeejyywrszxkgqw5kzxjzb25kzaitdxapfgyedkrhdgfwywx1zuzpzwxkbqzjbhrfawqedurhdgfuzxh0rmllbgqfcgnsdf9uyw1lhgtfiurhdgfcb3vuzgdkebxwfxdebybob3qgu2vhcmnoiej5iensawvudbsxc3qgrevgru5trsbgsvjfifbst1rfq1rjt04lmybnienptvbbtlkqmzftvcbdifmgvcbxie0grb4zmvnuienjvklbtcbtvvbqt1juifvosvqglsbxtuqpm1mgsu5dt1jqt1jbveveezqtscbisuditeforevsienmvuinnc1iifdfu1rwsuxmrru0luggv09prfnjreugru1fukfmrfmtnc1ilcbdsevtve5vvcbhuk9wrra0lugsietftlqgq09vtlrzejqtscwguevbq0ggqkxpu1nptqs0mzygq0vtienfwbc0scbbrlrfuibtq0hpt0wgufjpr1jbtqtbicbiie1fvefmuxhbicbtifnquklos0xfuibdty4sieloqy4xqsbeifqgu0vdvvjjvfkgu0vsvkldrvmvqsbeifqgu0vdvvjjvfkgu1ltvevnduegrsbttuluscbjtkmfqsbfifqhqsbfifqgqybbieugvcbdic0gqurwievovklst05nru5uquwgvevdscbbieugvcbdic0gqurwievovklst05nru5uquwgvevdsbhbieygqsbquk9urunusvzfifnzu1rftvmzqsbhigfuzcbhifniruvuie1fvefmieloqxlbiecgribbierjvibpribcqvlfuibdt1jqfuegssagrfvqt05uielou1rjvfvurrhbiekgrfvqt05uie1j
[03/Mar/2017:13:00:43 --0500] [dsfstest.dti.state.de.us/sid#7fa12633a730][rid#7fa126414340][/dsfsSTUa0.aspx][4] Operator completed in 79125155 usec.

[03/Mar/2017:13:00:43 --0500] [dsfstest.dti.state.de.us/sid#7fa12633a730][rid#7fa126414340][/dsfsSTUa0.aspx][4] Executing operator "rx" with param ".+application/x-shockwave-flash|image/svg\\+xml|text/(css|html|ecmascript|javascript|vbscript|x-(javascript|scriptlet|vbscript)).+" against ARGS:__EVENTVALIDATION.
[03/Mar/2017:13:00:43 --0500] [dsfstest.dti.state.de.us/sid#7fa12633a730][rid#7fa126414340][/dsfsSTUa0.aspx][9] Target value: "/wedajgy1np0ac3ikctyaclthbnua8522fmrlxw+4lgs9we/rhs2vrai2b9x7vtf1ejpitzbxv+q7tpwwmxnbxqxfsazoskhxf52af0x9nmxzw/k/811xmg5big/+014k8wgnp5qxr/4ayz8iditnkw+aeo68n5gviltpxaeo32m1hqp7iwpz04oyurghwwhyala0bxpvv8pj7scjbcr7db3vj+mi3xi8y8kry33ovtfv4+mpjtctirr7k1fcy8bdyd+qheqhb5mlckhpfqkbk4gl6zgloufpisq1qxfz+dyftyutxt6qfj1mhp+tgyncia8ts5ynahvh+g6ygne5zdzjobfna/hgijh7v5szwle4qvbqxla/sg3b0ofimqrjfcr0j3r4wvuci3kmirpn84wgurk1t2gnssxkdycu2ptv6xjcgomrwa+0ioam6pvfn88g/+zpq2t0jxr0fbmu6fb6qcjmffvtrkqcyvim4itpxfgqgss7hwhbefl74dgteazbjpdsrfos2zjrpfueid8r7vzz6yocnsahboipdatc5nrcmqpvdvsrc7/eniumustjgurt6slpoc0aq+2qfyt6pl2/r8uvvslqheoltttuen70u8lkb55xu0ztarypzlsrx74iggrvyz/let62bla5o42xzn9a1jexzl3vbridabfk8ngv1yu9pbibij57f/ck8xvhntjfjfssdngsdnw+ppdyr7961vrfh0tnxrnmcprfdnp+7aknafwdz9qjhxen8fx/f9ipttu31c8t+eo2oqg9bw4rzchf9f0x5k0/z8v0emjy9s6lwsaq5lpjcl4er6afj8l9wquyqdk2pt//ywhtkr7gbntmrafxs1ym3tslptq0gilqdqeiwvgdui8kdhxoiux/wst+3sorwb007e6qgcconi+jeul0q0clabh+85xua22dlhx2iultf7xast4njqmzygrgn9maj0rg0igaez9joj45unaregscs3p
[03/Mar/2017:13:01:07 --0500] [dsfstest.dti.state.de.us/sid#7fa12633a730][rid#7fa126414340][/dsfsSTUa0.aspx][4] Operator completed in 24253922 usec.

Apache error_log:

[Fri Mar 03 11:44:53.464260 2017] [core:notice] [pid 13820] SELinux policy enabled; httpd running as context unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023
[Fri Mar 03 11:44:53.485086 2017] [suexec:notice] [pid 13820] AH01232: suEXEC mechanism enabled (wrapper: /usr/sbin/suexec)
[Fri Mar 03 11:44:53.501678 2017] [:notice] [pid 13820] ModSecurity for Apache/2.7.3 (http://www.modsecurity.org/) configured.
[Fri Mar 03 11:44:53.501769 2017] [:notice] [pid 13820] ModSecurity: APR compiled version="1.4.8"; loaded version="1.4.8"
[Fri Mar 03 11:44:53.501828 2017] [:notice] [pid 13820] ModSecurity: PCRE compiled version="8.32 "; loaded version="8.32 2012-11-30"
[Fri Mar 03 11:44:53.501881 2017] [:notice] [pid 13820] ModSecurity: LUA compiled version="Lua 5.1"
[Fri Mar 03 11:44:53.501931 2017] [:notice] [pid 13820] ModSecurity: LIBXML compiled version="2.9.1"
[Fri Mar 03 11:44:53.579149 2017] [auth_digest:notice] [pid 13821] AH01757: generating secret for digest authentication ...
[Fri Mar 03 11:44:53.581706 2017] [lbmethod_heartbeat:notice] [pid 13821] AH02282: No slotmem from mod_heartmonitor
[Fri Mar 03 11:44:53.589947 2017] [mpm_prefork:notice] [pid 13821] AH00163: Apache/2.4.6 () OpenSSL/1.0.1e-fips configured -- resuming normal operations

System version and whatnot:

# cat /etc/oracle-release
Oracle Linux Server release 7.3

# httpd -V
Server version: Apache/2.4.6 ()
Server built:   Sep  5 2016 00:09:36
Server's Module Magic Number: 20120211:24
Server loaded:  APR 1.4.8, APR-UTIL 1.5.2
Compiled using: APR 1.4.8, APR-UTIL 1.5.2
Architecture:   64-bit
Server MPM:     prefork
  threaded:     no
    forked:     yes (variable process count)
Server compiled with....
-D APR_HAS_SENDFILE
-D APR_HAS_MMAP
-D APR_HAVE_IPV6 (IPv4-mapped addresses enabled)
-D APR_USE_SYSVSEM_SERIALIZE
-D APR_USE_PTHREAD_SERIALIZE
-D SINGLE_LISTEN_UNSERIALIZED_ACCEPT
-D APR_HAS_OTHER_CHILD
-D AP_HAVE_RELIABLE_PIPED_LOGS
-D DYNAMIC_MODULE_LIMIT=256
-D HTTPD_ROOT="/etc/httpd"
-D SUEXEC_BIN="/usr/sbin/suexec"
-D DEFAULT_PIDLOG="/run/httpd/httpd.pid"
-D DEFAULT_SCOREBOARD="logs/apache_runtime_status"
-D DEFAULT_ERRORLOG="logs/error_log"
-D AP_TYPES_CONFIG_FILE="conf/mime.types"
-D SERVER_CONFIG_FILE="conf/httpd.conf"

Thanks

[bostrt]

@anderpups what's the complete SecRule/Action associated with that logging you shared?

[03/Mar/2017:12:59:24 --0500] [dsfstest.dti.state.de.us/sid#7fa12633a730][rid#7fa126414340][/dsfsSTUa0.aspx][4] Executing operator "rx" with param ".+application/x-shockwave-flash|image/svg\\+xml|text/(css|html|ecmascript|javascript|vbscript|x-(javascript|scriptlet|vbscript)).+" against ARGS:__VIEWSTATE.
[03/Mar/2017:12:59:24 --0500] [dsfstest.dti.state.de.us/sid#7fa12633a730][rid#7fa126414340][/dsfsSTUa0.aspx][9] Target value: "/wepdwukltq3mjkwnte4..........
[03/Mar/2017:13:00:43 --0500] [dsfstest.dti.state.de.us/sid#7fa12633a730][rid#7fa126414340][/dsfsSTUa0.aspx][4] Operator completed in 79125155 usec.

[anderpups]

@bostrt thanks for the response. After more digging, we have figured out rule 973302 is causing this condition. I also realized that it can also be replicated with "SecRuleEngine On" so please disregard any reference to the different modes. There was some uniqueness to to the requests that I hadn't taken into consideration at first.

I still think this may be a bug since mod_security doesn't actually do any blocking of that rule, but the CPU pegs to 100% while inspecting the traffic when this rule is enabled.

Please let me know if you still need the SecRule/Action config. Thanks

[bostrt]

@anderpups just noticed you ModSecurity version is almost 4 years old (v2.7.3). Can you reproduce on the latest 2.9.1?

[p0pr0ck5]

@anderpups this is a function of the regular expression used in that rule, not the ModSecurity engine itself. That regular expression is really very poorly formed, and will undergo some very significant backtracking when comparing against a target of that size. It looks like you're using the old OWASP CRS v2; consider upgrading to v3 (https://github.com/SpiderLabs/owasp-modsecurity-crs/tree/v3.0/master), which was redesigned to avoid ugly expressions like this.

[anderpups]

Thanks @bostrt and @p0pr0ck5. We were using what was available on the RHEL repo and have the latest version of that installed. I can reach out to them.