mruby_output_filter after fastcgi_pass causes error. malloc(18446744073709551615) failed (12: Cannot allocate memory)

[sawanoboly]

fastcgi_passと一緒にmruby_output_filterを使おうとすると、次のエラーでリクエストが終了してしまいました。 通常のlocationおよび、proxy_passでは正常にヘッダが追加されます。

[emerg] 8190#0: *1 malloc(18446744073709551615) failed (12: Cannot allocate memory) while sending to client, client: 127.0.0.1, server: localhost, request: "HEAD /info.php HTTP/1.1", upstream: "fastcgi://unix:/var/run/php-fpm.sock", host: "localhost"
[error] 8190#0: *1 failed to read body ngx_http_mruby_body_filter_inline_handler:1763 while sending to client, client: 127.0.0.1, server: localhost, request: "HEAD /info.php HTTP/1.1", upstream: "fastcgi://unix:/var/run/php-fpm.sock", host: "localhost"

Configurations for reproduce

nginx.conf

load_module modules/ngx_http_mruby_module.so;
worker_processes  2;
events {
    worker_connections  1024;
}

http {
    include       mime.types;
    default_type  application/octet-stream;
    sendfile        on;
    tcp_nopush     on;
    keepalive_timeout  5;

    upstream phpfpm {
        server unix:/var/run/php-fpm.sock;
    }

    server {
        listen       8080;
        server_name  localhost;

        location / {
            root   html;
            index  index.html index.htm;
        }
    }

    server {
        listen       80;
        server_name  localhost;

        location / {
            root   html;
            index  index.html index.htm;
            proxy_pass   http://127.0.0.1:8080;
            mruby_output_filter_code '
               r = Nginx::Request.new
               r.headers_out["X-MRUBY"] = "YES"
            ';
        }

        location ~ \.php {
            root   html;
            index  index.html index.htm;
            fastcgi_split_path_info ^(.+\.php)(/.+)$;
            fastcgi_pass   phpfpm;
            fastcgi_index  index.php;
            fastcgi_param  SCRIPT_FILENAME  /usr/share/nginx/html$fastcgi_script_name;
            mruby_output_filter_code '
            r = Nginx::Request.new
            r.headers_out["X-MRUBY"] = "YES"
        ';
        }

    }
}

以下がリクエスト例です。

$ curl -I localhost/
HTTP/1.1 200 OK
Server: nginx/1.11.1
Date: Tue, 07 Jun 2016 05:04:05 GMT
Content-Type: text/html
Content-Length: 612
Connection: keep-alive
Last-Modified: Mon, 06 Jun 2016 09:51:09 GMT
ETag: "5755478d-264"
Accept-Ranges: bytes
X-MRUBY: YES

$ curl -I localhost/info.php
curl: (52) Empty reply from server ## エラーログに Cannot allocate memory

Environments

Nginx: 1.9.11 ngx_mruby: 1.17.2 (DSOビルド)

Nginxのコンフィグオプションは こちら です。

[sawanoboly]

--add-moduleでStaticでも一緒のエラーでリクエスト停止しました。

configure arguments: --prefix=/usr/share/nginx --sbin-path=/usr/sbin/nginx --conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log --http-log-path=/var/log/nginx/access.log --http-client-body-temp-path=/var/lib/nginx/tmp/client_body --http-proxy-temp-path=/var/lib/nginx/tmp/proxy --http-fastcgi-temp-path=/var/lib/nginx/tmp/fastcgi --http-uwsgi-temp-path=/var/lib/nginx/tmp/uwsgi --http-scgi-temp-path=/var/lib/nginx/tmp/scgi --pid-path=/var/run/nginx.pid --lock-path=/var/lock/subsys/nginx --user=nginx --group=nginx --with-file-aio --with-ipv6 --with-http_ssl_module --with-http_realip_module --with-http_addition_module --with-http_xslt_module --with-http_image_filter_module --with-http_geoip_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_degradation_module --with-http_stub_status_module --with-http_perl_module --with-mail --with-mail_ssl_module --with-pcre --with-pcre-jit --with-google_perftools_module --with-debug --with-cc-opt='-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector --param=ssp-buffer-size=4 -m64 -mtune=generic' --with-ld-opt=' -Wl,-E' --with-http_v2_module --with-stream --with-stream_ssl_module --without-stream_access_module --add-dynamic-module=/home/ec2-user/rpmbuild/BUILD/nginx-1.11.1/ngx_cache_purge-2.3.dynamic --add-module=/home/ec2-user/rpmbuild/BUILD/nginx-1.11.1/ngx_mruby/dependence/ngx_devel_kit --add-module=/home/ec2-user/rpmbuild/BUILD/nginx-1.11.1/ngx_mruby

[matsumotory]

もし可能であれば、おかしくなるmallocの場所でのバックトレースやその周辺の変数の値をざっくり頂けるとうれしいです！

[matsumotory]

18446744073709551615っておそらくusgned long longに-1を突っ込んだ値とかだと思うのですよね。

[sawanoboly]

ヒントありがとー。次時間とれるときにやってみます。

[matsumotory]

@sawanoboly Dockerfileなどで再現環境再現することは可能ですか？こちらでもデバッグしようと思います。

[matsumotory]

void *
ngx_alloc(size_t size, ngx_log_t *log)
{   
    void  *p;                       

    p = malloc(size);
    if (p == NULL) {
        ngx_log_error(NGX_LOG_EMERG, log, ngx_errno,
                      "malloc(%uz) failed", size);
    }   

    ngx_log_debug2(NGX_LOG_DEBUG_ALLOC, log, 0, "malloc: %p:%uz", p, size);

    return p;
}   

[sawanoboly]

@matsumoto-r

再現用環境つくりましたー

https://github.com/sawanoboly/reproduce_ngx_mruby_172

[matsumotory]

ありがとうございます！試して調査します〜

[matsumotory]

再現しないですね....これはメモリ次第ですかね

[sawanoboly]

むむ、うちのBoot2Docker環境のVM(VIrtualBox)はこうですね。

Boot2Docker version 1.11.2, build HEAD : a6645c3 - Wed Jun  1 22:59:51 UTC 2016
Docker version 1.11.2, build b9f10c9
docker@default:~$ free -m
              total        used        free      shared  buff/cache   available
Mem:           3007          58         224         164        2724        2600
Swap:          1663           0        1663

初めに見つけたのはAmazon EC2のt2.microなのでメモリ1Gです。

[matsumotory]

どこにどんなログがでますか？

[matsumotory]

あ、再現しました。

$ docker run -p 8080:80 -it reproduce_ngx_mruby
bash-4.3# curl localhost/^C
bash-4.3# free -m
             total       used       free     shared    buffers     cached
Mem:           996        680        315        123         35        514
-/+ buffers/cache:        130        865
Swap:         1154          0       1154
bash-4.3# curl localhost/index.php
curl: (52) Empty reply from server
bash-4.3# less /ngx_mruby/^C
bash-4.3# cat /ngx_mruby/ngx_mruby/build_dynamic/nginx/logs/error.log 
2016/06/10 08:42:00 [notice] 9#0: ngx_mruby NOTICE ngx_http_mruby_shared_state_compile:846: compile info: code->code.string=(
               r = Nginx::Request.new
               r.headers_out["X-MRUBY"] = "YES"
            ) code->cache=(1) in /ngx_mruby/ngx_mruby/build_dynamic/nginx/conf/nginx.conf:40
2016/06/10 08:42:00 [notice] 9#0: ngx_mruby NOTICE ngx_http_mruby_shared_state_compile:846: compile info: code->code.string=(
            r = Nginx::Request.new
            r.headers_out["X-MRUBY"] = "YES"
        ) code->cache=(1) in /ngx_mruby/ngx_mruby/build_dynamic/nginx/conf/nginx.conf:53
2016/06/10 08:42:00 [notice] 9#0: ngx_mruby/1.17.2 (mruby/1.2.0) mechanism enabled in /ngx_mruby/ngx_mruby/build_dynamic/nginx/conf/nginx.conf:57
2016/06/10 08:42:50 [emerg] 15#0: *1 malloc(18446744073709551615) failed (12: Out of memory) while sending to client, client: 127.0.0.1, server: localhost, request: "GET /index.php HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"
2016/06/10 08:42:50 [error] 15#0: *1 failed to read body ngx_http_mruby_body_filter_inline_handler:1763 while sending to client, client: 127.0.0.1, server: localhost, request: "GET /index.php HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "localhost"

[matsumotory]

これ、ひとまずbody_filterでheaderをフィルターすることはできないので、headerのフィルターをやめるとどうなりますかね？

[matsumotory]

@sawanoboly これ、phpを使わないような最小のngx_mrubyだけの再現コードって書けるでしょうか？

[sawanoboly]

とりあえず外してみたところ、これでもコケます。

        location ~ \.php {
            include fastcgi_params;
            root   html;
            index  index.html index.htm;
            fastcgi_split_path_info ^(.+\.php)(/.+)$;
            fastcgi_pass   phpfpm;
            fastcgi_index  index.php;
            fastcgi_param  SCRIPT_FILENAME /ngx_mruby/ngx_mruby/build_dynamic/nginx/html$fastcgi_script_name;
            mruby_output_filter_code '
#            r = Nginx::Request.new
#            r.headers_out["X-MRUBY"] = "YES"
        ';
        }

phpを使わないような最小のngx_mrubyだけの再現コード

これちょっと意味を確認したいんですが、fastcgi_pass相当のことをcontent_codeでやるってことです？

[matsumotory]

いえ、多分fastcgiを使う事が関係しているのではなく、アウトプットfilterをかけたらエラーになっているようなので、ngx_mrubyのtestレベルで再現したいです。

[sawanoboly]

ああ、test/t/ngx_mruby.rb のような記述で、ということかしら。

---

いやちょっと違うか。。

[matsumotory]

そうですね。 #173 で修正を試みてみましたがいかがでしょう。できれば再現コードをtest/t/ngx_mruby.rbに実装した上で、patchが通ることで其のバグが起きない事を確認したいです。

[matsumotory]

Fixed via #173

[wokamoto]

関係あるかわかりませんが fastcgi の結果やリバースプロキシの結果が Content-Length を返さない時に Nginx::Filter#body が落ちるようです。

[emerg] 13633#0: *16 malloc(18446744073709551615) failed (12: Cannot allocate memory), client: xx.xx.xx.xx, server: example.com, request: "HEAD / HTTP/1.1", host: "example.com"
[error] 13633#0: *16 failed to read body ngx_http_mruby_body_filter_handler:1710, client: xx.xx.xx.xx, server: example.com, request: "HEAD / HTTP/1.1", host: "example.com"

こんな感じのスクリプトを書いて、WordPress が吐き出す http を https に置換しようとしたんですが上記のエラーになりました。

v = Nginx::Var.new
host = v.http_host
ctype = v.sent_http_content_type

if ctype =~ /^text\//
  r = Nginx::Request.new
  r.headers_out["X-MRUBY"] = "YES"

  f = Nginx::Filter.new
  content = f.body
  f.body = content.gsub /http:\/\/#{host}\//, "https://#{host}/"
end

WordPress の index.php を書き換えて強引に Content-Length ヘッダを出すようにしたら、上記エラーが出なくなったです。

<?php
/**
 * Front to the WordPress application. This file doesn't do anything, but loads
 * wp-blog-header.php which does and tells WordPress to load the theme.
 *
 * @package WordPress
 */

ob_start();

/**
 * Tells WordPress to load the WordPress theme and output it.
 *
 * @var bool
 */
define('WP_USE_THEMES', true);

/** Loads the WordPress Environment and Template */
require( dirname( __FILE__ ) . '/wp-blog-header.php' );

$out = ob_get_clean();
$length = strlen($out);
header('Content-Length: '.$length);
echo $out;

[matsumotory]

@wokamoto ありがとうございます。はい、おっしゃるとおりでchunkedで送られてくるようなレスポンスはバグにより不正な値がmallocに渡るようでした。

[wokamoto]

chunked だとダメってのは既知の不具合だったんすね... こっち見落としてました https://github.com/matsumoto-r/ngx_mruby/pull/173

[matsumotory]

はい、それで今ディレクティブの分離を行ってそこそこ動くようになったのですが、body_filterでcontent-lengthが変わる場合に、それよりはやいheader_filterで更新するようなヘッダの情報をどうbody_fillterのフックで変更するか、というところで止まっております。時間見つけて直す予定です〜

[matsumotory]

Fixed via #173