klaubert / waf-fle

WAF-FLE, ModSecurity Console
http://waf-fle.org
GNU General Public License v2.0
140 stars 74 forks source link

Waf-fle controller returns http response code 500 #50

Open stpic opened 8 years ago

stpic commented 8 years ago

Hi, thanks a lot to anyone would read and even more to anyone would answer. I am facing issues with waf-fle controller sending http response code 500 but i don't understand why. Most of the entries my logc is sending to waf-fle (thanks to a crontab entry and thanks to mlogc-batch-load.pl) are correctly processed.

But for some entries it fails. Here is what i can see in the mlogc-error.log file for such failing entry:

[Wed Nov 18 15:52:52 2015] [3] [27488/0] Configuring ModSecurity Audit Log Collector 2.7.2. [Wed Nov 18 15:52:52 2015] [3] [27488/0] Delaying execution for 5000ms. [Wed Nov 18 15:52:57 2015] [3] [27488/0] No more data to read, emptying buffer: End of file found [Wed Nov 18 15:52:57 2015] [3] [27488/0] Waiting for queue to empty (1 active). [Wed Nov 18 15:52:57 2015] [2] [27488/7f61bae39100] Flagging server as errored after failure to submit entry VknMSwoVAlIAAJQPqggAAAMf with HTTP response code 500: Internal Server Error [Wed Nov 18 15:52:58 2015] [3] [27488/7f61bae67118] Running final transaction checkpoint. [Wed Nov 18 15:52:58 2015] [3] [27488/0] ModSecurity Audit Log Collector 2.7.2 terminating normally.

Then i went on the apache/waf-fle side, set the apache LogLevel to maximum level i know (trace 8) then re-processed the failing entry and here is what i have in the apache log;

[Wed Nov 18 15:32:30.910135 2015] [http:trace4] [pid 12541] http_request.c(301): [client 10.21.2.82:37882] Headers received from client: [Wed Nov 18 15:32:30.910136 2015] [http:trace4] [pid 12543] http_request.c(301): [client 10.21.2.82:37883] Headers received from client: [Wed Nov 18 15:32:30.910227 2015] [http:trace4] [pid 12541] http_request.c(305): [client 10.21.2.82:37882] Authorization: Basic d2ViMDY6d2FmZmxl [Wed Nov 18 15:32:30.910244 2015] [http:trace4] [pid 12543] http_request.c(305): [client 10.21.2.82:37883] Authorization: Basic d2ViMDY6d2FmZmxl [Wed Nov 18 15:32:30.910246 2015] [http:trace4] [pid 12541] http_request.c(305): [client 10.21.2.82:37882] Host: 10.21.0.87 [Wed Nov 18 15:32:30.910255 2015] [http:trace4] [pid 12543] http_request.c(305): [client 10.21.2.82:37883] Host: 10.21.0.87 [Wed Nov 18 15:32:30.910259 2015] [http:trace4] [pid 12541] httprequest.c(305): [client 10.21.2.82:37882] Accept: /_ [Wed Nov 18 15:32:30.910264 2015] [http:trace4] [pid 12543] httprequest.c(305): [client 10.21.2.82:37883] Accept: /_ [Wed Nov 18 15:32:30.910267 2015] [http:trace4] [pid 12541] http_request.c(305): [client 10.21.2.82:37882] X-Content-Hash: md5:a114d59967993c29317814d5592a818a [Wed Nov 18 15:32:30.910271 2015] [http:trace4] [pid 12543] http_request.c(305): [client 10.21.2.82:37883] X-Content-Hash: md5:a114d59967993c29317814d5592a818a [Wed Nov 18 15:32:30.910276 2015] [http:trace4] [pid 12541] http_request.c(305): [client 10.21.2.82:37882] X-ForensicLog-Summary: chgva-srv-web06 10.21.26.42 - - [16/Nov/2015:13:30:47 +0100] \"GET /images/aqua_send_btn_off.gif HTTP/1.1\" 200 208 \"http://members/css/mscnet3_aqua.css\" \"-\" VknMSwoVAlIAAJQPqggAAAMf \"-\" /20151116/20151116-1330/20151116-133033-VknMSwoVAlIAAJQPqggAAAMf 0 4078 md5:a114d59967993c29317814d5592a818a [Wed Nov 18 15:32:30.910281 2015] [http:trace4] [pid 12543] http_request.c(305): [client 10.21.2.82:37883] X-ForensicLog-Summary: chgva-srv-web06 10.21.26.42 - - [16/Nov/2015:13:30:47 +0100] \"GET /images/aqua_send_btn_off.gif HTTP/1.1\" 200 208 \"http://members/css/mscnet3_aqua.css\" \"-\" VknMSwoVAlIAAJQPqggAAAMf \"-\" /20151116/20151116-1330/20151116-133033-VknMSwoVAlIAAJQPqggAAAMf 0 4078 md5:a114d59967993c29317814d5592a818a [Wed Nov 18 15:32:30.910286 2015] [http:trace4] [pid 12541] http_request.c(305): [client 10.21.2.82:37882] Content-Length: 4078 [Wed Nov 18 15:32:30.910290 2015] [http:trace4] [pid 12543] http_request.c(305): [client 10.21.2.82:37883] Content-Length: 4078 [Wed Nov 18 15:32:30.910507 2015] [authz_core:debug] [pid 12541] mod_authz_core.c(802): [client 10.21.2.82:37882] AH01626: authorization result of Require all granted: granted [Wed Nov 18 15:32:30.910520 2015] [authz_core:debug] [pid 12541] mod_authz_core.c(802): [client 10.21.2.82:37882] AH01626: authorization result of : granted [Wed Nov 18 15:32:30.910519 2015] [authz_core:debug] [pid 12543] mod_authz_core.c(802): [client 10.21.2.82:37883] AH01626: authorization result of Require all granted: granted [Wed Nov 18 15:32:30.910529 2015] [core:trace3] [pid 12541] request.c(293): [client 10.21.2.82:37882] request authorized without authentication by access_checker_ex hook: /waf-fle/controller/ [Wed Nov 18 15:32:30.910535 2015] [authz_core:debug] [pid 12543] mod_authz_core.c(802): [client 10.21.2.82:37883] AH01626: authorization result of : granted [Wed Nov 18 15:32:30.910544 2015] [core:trace3] [pid 12543] request.c(293): [client 10.21.2.82:37883] request authorized without authentication by access_checker_ex hook: /waf-fle/controller/ [Wed Nov 18 15:32:30.910618 2015] [authz_core:debug] [pid 12541] mod_authz_core.c(802): [client 10.21.2.82:37882] AH01626: authorization result of Require all granted: granted [Wed Nov 18 15:32:30.910642 2015] [authz_core:debug] [pid 12543] mod_authz_core.c(802): [client 10.21.2.82:37883] AH01626: authorization result of Require all granted: granted [Wed Nov 18 15:32:30.910665 2015] [authz_core:debug] [pid 12541] mod_authz_core.c(802): [client 10.21.2.82:37882] AH01626: authorization result of : granted [Wed Nov 18 15:32:30.910670 2015] [authz_core:debug] [pid 12543] mod_authz_core.c(802): [client 10.21.2.82:37883] AH01626: authorization result of : granted [Wed Nov 18 15:32:30.910673 2015] [core:trace3] [pid 12541] request.c(293): [client 10.21.2.82:37882] request authorized without authentication by access_checker_ex hook: /waf-fle/controller/index.php [Wed Nov 18 15:32:30.910678 2015] [core:trace3] [pid 12543] request.c(293): [client 10.21.2.82:37883] request authorized without authentication by access_checker_ex hook: /waf-fle/controller/index.php [Wed Nov 18 15:32:30.926040 2015] [http:trace3] [pid 12541] http_filters.c(979): [client 10.21.2.82:37882] Response sent with status 500, headers: [Wed Nov 18 15:32:30.926124 2015] [http:trace5] [pid 12541] http_filters.c(986): [client 10.21.2.82:37882] Date: Wed, 18 Nov 2015 14:32:30 GMT [Wed Nov 18 15:32:30.926134 2015] [http:trace5] [pid 12541] http_filters.c(989): [client 10.21.2.82:37882] Server: Apache/2.4.7 (Ubuntu) [Wed Nov 18 15:32:30.926147 2015] [http:trace4] [pid 12541] http_filters.c(808): [client 10.21.2.82:37882] X-Powered-By: PHP/5.5.9-1ubuntu4.14 [Wed Nov 18 15:32:30.926156 2015] [http:trace4] [pid 12541] http_filters.c(808): [client 10.21.2.82:37882] Status: 500 [Wed Nov 18 15:32:30.926165 2015] [http:trace4] [pid 12541] http_filters.c(808): [client 10.21.2.82:37882] Content-Length: 37 [Wed Nov 18 15:32:30.926180 2015] [http:trace4] [pid 12541] http_filters.c(808): [client 10.21.2.82:37882] Connection: close [Wed Nov 18 15:32:30.926199 2015] [http:trace4] [pid 12541] http_filters.c(808): [client 10.21.2.82:37882] Content-Type: text/html [Wed Nov 18 15:32:30.928665 2015] [http:trace3] [pid 12543] http_filters.c(979): [client 10.21.2.82:37883] Response sent with status 500, headers: [Wed Nov 18 15:32:30.928785 2015] [http:trace5] [pid 12543] http_filters.c(986): [client 10.21.2.82:37883] Date: Wed, 18 Nov 2015 14:32:30 GMT [Wed Nov 18 15:32:30.928801 2015] [http:trace5] [pid 12543] http_filters.c(989): [client 10.21.2.82:37883] Server: Apache/2.4.7 (Ubuntu) [Wed Nov 18 15:32:30.928821 2015] [http:trace4] [pid 12543] http_filters.c(808): [client 10.21.2.82:37883] X-Powered-By: PHP/5.5.9-1ubuntu4.14 [Wed Nov 18 15:32:30.928861 2015] [http:trace4] [pid 12543] http_filters.c(808): [client 10.21.2.82:37883] Status: 500 [Wed Nov 18 15:32:30.928872 2015] [http:trace4] [pid 12543] http_filters.c(808): [client 10.21.2.82:37883] Content-Length: 37 [Wed Nov 18 15:32:30.928880 2015] [http:trace4] [pid 12543] http_filters.c(808): [client 10.21.2.82:37883] Connection: close [Wed Nov 18 15:32:30.928888 2015] [http:trace4] [pid 12543] http_filters.c(808): [client 10.21.2.82:37883] Content-Type: text/html

We effectively the status code=500 but no clue about why...

In case it would help here is the failing entry:

root webxx modsec_audit2 # more /tmp/modsec_audit2/20151116/20151116-1330/20151116-133033-VknMSwoVAlIAAJQPqggAAAMf --b5e5e93b-A-- [16/Nov/2015:13:30:47 +0100] VknMSwoVAlIAAJQPqggAAAMf 10.21.26.42 65343 10.21.2.82 80 --b5e5e93b-B-- GET /images/aqua_send_btnoff.gif HTTP/1.1 Host: myhostfake Connection: keep-alive Accept: image/webp,/_;q=0.8 User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.23 57.134 Safari/537.36 Referer: http://myhostfake/css/mscnet3_aqua.css Accept-Encoding: gzip, deflate, sdch Accept-Language: en-US,en;q=0.8 Cookie: style=mscnet3_aqua; fontsize=100 X-Forwarded-For: 10.21.26.42

--b5e5e93b-F-- HTTP/1.1 200 OK X-Frame-Options: SAMEORIGIN Last-Modified: Mon, 03 Aug 2015 20:22:26 GMT Accept-Ranges: bytes Content-Length: 208 Cache-Control: no-cache, no-store Vary: Accept-Encoding,Cookie,Keep-Alive Keep-Alive: timeout=10, max=63 Connection: Keep-Alive Content-Type: image/gif

--b5e5e93b-H-- Message: Failed deleting collection (name "ip", key "10.21.26.245_f89688380f162addd43fa6ff3e64dda3e89 224c5"): Internal error Stopwatch: 1447677003975698 43899029 (- - -) Stopwatch2: 1447677003975698 43899029; combined=806633, p1=1177, p2=0, p3=0, p4=0, p5=402730, sr=109, sw=1, l=0, gc=402725 Producer: ModSecurity for Apache/2.7.2 (http://www.modsecurity.org/); OWASP_CRS/2.2.7. Server: Apache/2.2.22 (Ubuntu) PHP/5.4.21 mod_ssl/2.2.22 OpenSSL/1.0.1

--b5e5e93b-K-- SecAction "phase:1,auditlog,id:691,t:none,setvar:tx.critical_anomaly_score=5,setvar:tx.erroranomaly score=4,setvar:tx.warning_anomaly_score=3,setvar:tx.notice_anomaly_score=2,nolog,pass"

SecAction "phase:1,auditlog,id:9002,t:none,setvar:tx.inbound_anomaly_score_level=10,nolog,pass"

SecAction "phase:1,auditlog,id:9003,t:none,setvar:tx.outbound_anomaly_score_level=4,nolog,pass"

SecAction "phase:1,auditlog,id:9004,t:none,setvar:tx.anomaly_score_blocking=on,nolog,pass"

SecAction "phase:1,auditlog,id:9006,t:none,setvar:tx.max_num_args=255,nolog,pass"

SecAction "phase:1,auditlog,id:9007,t:none,setvar:tx.arg_name_length=100,nolog,pass"

SecAction "phase:1,auditlog,id:9008,t:none,setvar:tx.arg_length=400,nolog,pass"

SecAction "phase:1,auditlog,id:9009,t:none,setvar:tx.total_arg_length=64000,nolog,pass"

SecAction "phase:1,auditlog,id:900012,t:none,setvar:'tx.allowed_methods=GET POST',setvar:tx.allowed_r equest_content_type=application/x-www-form-urlencoded|multipart/form-data|text/xml|application/xml|ap plication/x-amf|application/json,setvar:'tx.allowed_http_versions=HTTP/0.9 HTTP/1.0 HTTP/1.1',setvar: 'tx.restricted_extensions=.asa/ .asax/ .ascx/ .axd/ .backup/ .bak/ .bat/ .cdx/ .cer/ .cfg/ .cmd/ .com / .config/ .conf/ .cs/ .csproj/ .csr/ .dat/ .db/ .dbf/ .dll/ .dos/ .htr/ .htw/ .ida/ .idc/ .idq/ .inc / .ini/ .key/ .licx/ .lnk/ .log/ .mdb/ .old/ .pass/ .pdb/ .pol/ .printer/ .pwd/ .resources/ .resx/ .s ql/ .sys/ .vb/ .vbs/ .vbproj/ .vsdisco/ .webinfo/ .xsd/ .xsx/',setvar:'tx.restricted_headers=/Proxy-C onnection/ /Lock-Token/ /Content-Range/ /Translate/ /via/ /if/',nolog,pass"

SecAction "phase:1,auditlog,id:900014,t:none,setvar:'tx.brute_force_protected_urls=/login.jsp /partne r_login.php',setvar:tx.brute_force_burst_time_slice=60,setvar:tx.brute_force_counter_threshold=10,set var:tx.brute_force_block_timeout=300,nolog,pass"

SecAction "phase:1,auditlog,id:900015,t:none,setvar:tx.dos_burst_time_slice=60,setvar:tx.doscounter threshold=300,setvar:tx.dos_block_timeout=600,nolog,pass"

SecRule "REQUEST_HEADERS:User-Agent" "@rx ^(.*)$" "phase:1,auditlog,id:900018,t:none,t:sha1,t:hexEnco de,setvar:tx.ua_hash=%{matched_var},nolog,pass"

SecRule "REQUEST_HEADERS:x-forwarded-for" "@rx ^\b(\d{1,3}.\d{1,3}.\d{1,3}.\d{1,3})\b" "p hase:1,auditlog,id:900019,t:none,capture,setvar:tx.real_ip=%{tx.1},nolog,pass"

SecRule "&TX:REAL_IP" "!@eq 0" "phase:1,auditlog,id:900020,t:none,initcol:global=global,initcol:ip=%{ tx.realip}%{tx.ua_hash},nolog,pass"

SecRule "REQUEST_METHOD" "@rx ^(?:GET|HEAD)$" "phase:1,log,auditlog,msg:'GET or HEAD Request with Bod y Content.',severity:2,id:960011,ver:OWASP_CRS/2.2.7,rev:1,maturity:9,accuracy:9,block,logdata:%{matc hed_var},t:none,tag:OWASP_CRS/PROTOCOL_VIOLATION/INVALID_HREQ,tag:CAPEC-272,chain"

I noticed in the H section the following: Message: Failed deleting collection (name "ip", key "10.21.26.245_f89688380f162addd43fa6ff3e64dda3e89 224c5"): Internal error

but not clear to me what it means nor whether it could be the reason why waf-fle then sends a 500 as well.

Any help would be much appreciated. With regards