header already sent while sending response to client

[amq]

nginx -V

nginx version: nginx/1.11.3
built by gcc 4.8.5 20150623 (Red Hat 4.8.5-4) (GCC)
built with OpenSSL 1.0.1e-fips 11 Feb 2013
TLS SNI support enabled
configure arguments: --prefix=/etc/nginx --sbin-path=/usr/sbin/nginx --modules-path=/usr/lib64/nginx/modules --conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log --http-log-path=/var/log/nginx/access.log --pid-path=/var/run/nginx.pid --lock-path=/var/run/nginx.lock --http-client-body-temp-path=/var/cache/nginx/client_temp --http-proxy-temp-path=/var/cache/nginx/proxy_temp --http-fastcgi-temp-path=/var/cache/nginx/fastcgi_temp --http-uwsgi-temp-path=/var/cache/nginx/uwsgi_temp --http-scgi-temp-path=/var/cache/nginx/scgi_temp --user=nginx --group=nginx --with-http_ssl_module --with-http_realip_module --with-http_addition_module --with-http_sub_module --with-http_dav_module --with-http_flv_module --with-http_mp4_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_random_index_module --with-http_secure_link_module --with-http_stub_status_module --with-http_auth_request_module --with-http_xslt_module=dynamic --with-http_image_filter_module=dynamic --with-http_geoip_module=dynamic --with-http_perl_module=dynamic --add-dynamic-module=njs-0.1.0/nginx --with-threads --with-stream --with-stream_ssl_module --with-stream_geoip_module=dynamic --with-http_slice_module --with-mail --with-mail_ssl_module --with-file-aio --with-ipv6 --with-http_v2_module --with-cc-opt='-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector-strong --param=ssp-buffer-size=4 -grecord-gcc-switches -m64 -mtune=generic'

nginx.conf

user nginx;
worker_processes auto;
pid /var/run/nginx.pid;

load_module "modules/ngx_http_modsecurity.so";
load_module "modules/ngx_http_image_filter_module.so";

events {
        worker_connections 4096;
        multi_accept on;
}

http {
...

site.com.conf

server {
        listen 80;

        server_name site.com;
        root /var/www/site.com;

        modsecurity on;

        location / {
                modsecurity_rules '
                SecRuleEngine On
                SecDebugLog /tmp/modsec_debug.log
                SecDebugLogLevel 9
                SecRule ARGS "@contains test" "id:1,phase:2,t:trim,block"
                ';
        }

access.log

ip - - [time] "GET /robots.txt HTTP/1.1" 500 0 "-" "user agent"

error.log

time [alert] num: *num header already sent, client: ip, server: site.com, request: "GET /robots.txt HTTP/1.1", host: "site.com"

nginx.spec

        --add-dynamic-module=%{_topdir}/SOURCES/ModSecurity-nginx \

/opt/ModSecurity git status

# On branch libmodsecurity

git log -n 1

commit 0e5f72977ee1026ae41317881f34c8c290d97b16
Author: Felipe Zimmerle <fcosta@trustwave.com>
Date:   Fri Jul 29 10:40:45 2016 -0700

    Changes MATCHED_VAR behaviour

~/rpmbuild/SOURCES/ModSecurity-nginx git status

# On branch master

git log -n 1

commit ed57c81f005a539a7334ebdeb8cee87c362d6c26
Author: Alexey Zelkin <phantom@nginx.com>
Date:   Tue Jul 12 20:22:28 2016 +0000

    Correct mistake in module name

[zimmerle]

Hi @amq,

Sorry for the delay. Thank you for the report. We are investigating.

[zimmerle]

Hi @amq,

I was testing the issue using the following versions:

libModSecurity: c680ddf2cda4766df081fcf622f68ea9a6c0230f (v3/master)
ModSecurity-nginx: b5ea638dc765989df7023a4277ddf5d0e7e49855 (ModSecurity-nginx/experimental)

The problem seems to be fixed using ModSecurity as static module. Notice that in addition to the rules used in your test, I have also set "block" to deny with 403, as illustrated below:

modsecurity_rules '
    SecRuleEngine On
    SecDebugLog /tmp/modsec_debug.log
    SecDebugLogLevel 9
    SecDefaultAction phase:2,deny,status:403,log,auditlog
    SecRule ARGS "@contains test" "id:1,phase:2,t:trim,block"
    ';

It seems like running the module as dynamic leads nginx to an infinite loop. It may not be a problem with ModSecurity-nginx itself, but with the nginx. Thereat, I am inviting @phantom-az to the discussion.

[defanator]

@phantom-az, any news on this one? Have you had a chance to get something?

[defanator]

I checked the same configuration with nginx/1.11.5, image_filter module from nginx-module-image-filter package, libmodsecurity from https://github.com/SpiderLabs/ModSecurity/commit/1b28776814c0fa4ec9f6b2e0340e5c2c60f54075 and libmodsecurity nginx connector module from https://github.com/SpiderLabs/ModSecurity-nginx/commit/7d2a4eedbb6ecf8f9108e3b2fc14f25c36efb84a, and everything works just fine.

Configuration:

load_module modules/ngx_http_modsecurity_module.so;
load_module modules/ngx_http_image_filter_module.so;

user nginx;
worker_processes 1;

error_log /var/log/nginx/error.log warn;
pid /var/run/nginx.pid;

events {
    worker_connections 4096;
    multi_accept on;
}

http {
    server {
        listen 80;

        server_name site.com;
        root /var/www/site.com;

        modsecurity on;

        location / {
            modsecurity_rules '
            SecRuleEngine On
            SecDebugLog /tmp/modsec_debug.log
            SecDebugLogLevel 9
            SecDefaultAction phase:2,deny,status:403,log,auditlog
            SecRule ARGS "@contains test" "id:1,phase:2,t:trim,block"
            ';
        }
    }
}

Requests:

curl 'http://localhost/robots.txt'
curl 'http://localhost/robots.txt?something=test'

Access log:

127.0.0.1 - - [10/Nov/2016:14:13:40 +0000] "GET /robots.txt HTTP/1.1" 404 169 "-" "curl/7.38.0"
127.0.0.1 - - [10/Nov/2016:14:13:43 +0000] "GET /robots.txt?something=test HTTP/1.1" 403 169 "-" "curl/7.38.0"

Error log:

2016/11/10 14:13:40 [error] 13562#13562: *1 open() "/var/www/site.com/robots.txt" failed (2: No such file or directory), client: 127.0.0.1, server: site.com, request: "GET /robots.txt HTTP/1.1", host: "localhost"

modsec_debug.log:

[4] JSON parser initialization
[9] yajl JSON parsing callback initialization
[4] Initialising transaction
[4] Transaction context created.
[4] Starting phase CONNECTION. (SecRules 0)
[9] This phase consists of 0 rule(s).
[4] Starting phase URI. (SecRules 0 + 1/2)
[4] Starting phase REQUEST_HEADERS.  (SecRules 1)
[9] This phase consists of 0 rule(s).
[4] Starting phase REQUEST_BODY. (SecRules 2)
[4] Request body processing is disabled
[9] This phase consists of 1 rule(s).
[4] (Rule: 1) Executing operator "@contains" with param "test" against ARGS.
[4] Starting phase RESPONSE_HEADERS. (SecRules 3)
[9] This phase consists of 0 rule(s).
[9] Appending response body: 0 bytes. Limit set to: 0.000000
[9] Appending response body: 0 bytes. Limit set to: 0.000000
[4] Starting phase RESPONSE_BODY. (SecRules 4)
[9] This phase consists of 0 rule(s).
[4] Starting phase LOGGING. (SecRules 5)
[9] This phase consists of 0 rule(s).
[8] Checking if this request is suitable to be saved as an audit log.
[8] Checking if this request is relevant to be part of the audit logs.
[5] Return code `404' is not interesting to audit logs, relevant code(s): `'.
[4] JSON: Cleaning up JSON results
[4] JSON parser initialization
[9] yajl JSON parsing callback initialization
[4] Initialising transaction
[4] Transaction context created.
[4] Starting phase CONNECTION. (SecRules 0)
[9] This phase consists of 0 rule(s).
[4] Starting phase URI. (SecRules 0 + 1/2)
[4] Adding request argument (GET): name "something", value "test"
[4] Starting phase REQUEST_HEADERS.  (SecRules 1)
[9] This phase consists of 0 rule(s).
[4] Starting phase REQUEST_BODY. (SecRules 2)
[4] Request body processing is disabled
[9] This phase consists of 1 rule(s).
[4] (Rule: 1) Executing operator "@contains" with param "test" against ARGS.
[9]  T (0) t:trim: "test"
[9] Target value: "test" (Variable: ARGS:something)
[4] Operator completed in 0.000024 seconds
[4] Rule returned 1.
[4] (SecDefaultAction) _ignoring_ action: deny (rule contains a disruptive action)
[4] (SecDefaultAction) Running action: status!!0
[4] (SecDefaultAction) Running action: log!!0
[9] Saving transaction to logs
[4] (SecDefaultAction) Running action: auditlog!!0
[4] Running (disruptive) action: block
[8] Running action block
[4] Saving on the server log: [client 127.0.0.1] ModSecurity: Warning. Matched "Operator `@contains' with parameter `test' against variable `ARGS:something' (Value: `test' ) " at ARGS:something [file "<<reference missing or not informed>>"] [line "5"] [id "1"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/robots.txt?something=test"] [unique_id "147878722393.533733"]
[4] Starting phase RESPONSE_HEADERS. (SecRules 3)
[9] This phase consists of 0 rule(s).
[9] Appending response body: 0 bytes. Limit set to: 0.000000
[9] Appending response body: 0 bytes. Limit set to: 0.000000
[4] Starting phase RESPONSE_BODY. (SecRules 4)
[9] This phase consists of 0 rule(s).
[4] Starting phase LOGGING. (SecRules 5)
[9] This phase consists of 0 rule(s).
[8] Checking if this request is suitable to be saved as an audit log.
[8] This request was marked to be saved via auditlog action.
[8] Checking if this request is relevant to be part of the audit logs.
[5] Saving this request as part of the audit logs.
[8] Request was relevant to be saved. Parts: -1
[4] JSON: Cleaning up JSON results

[zimmerle]

Closing this issue based on @defanator comments.