Waf-fle controller returns http response code 500

[stpic]

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] http_request.c(305): [client 10.21.2.82:37882] Accept: /
[Wed Nov 18 15:32:30.910264 2015] [http:trace4] [pid 12543] http_request.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_btn_off.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.error_anomaly_
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.dos_counter_
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.real_ip}_%{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