NOTICE logs printed when log level set to warn

[shamil]

Hi,

I see that mruby module doesn't respect the error_log setting. In the /etc/nginx/nginx.conf I set log level like so: error_log /var/log/nginx/error.log warn;, but I still see notice logs specifically from mruby module. See examples below. What could be the reason?

For example

/etc/nginx # nginx -t
2017/11/01 22:02:13 [notice] 23#23: ngx_mruby/1.20.1 (mruby/1.3.0) mechanism enabled in /etc/nginx/nginx.conf:34
nginx: the configuration file /etc/nginx/nginx.conf syntax is ok
nginx: configuration file /etc/nginx/nginx.conf test is successful

Or:

/etc/nginx/conf.d # nginx -g 'daemon off;'
2017/11/01 21:25:17 [notice] 42#42: ngx_mruby NOTICE ngx_http_mruby_shared_state_compile:1026: compile info: code->code.string=(
      
      if server_name == "NGINX"
        Server = Nginx
      elsif server_name == "Apache"
        Server = Apache
      end
      
      Server::rputs JSON::stringify({"foo"=>"bar"})
    
    ) code->cache=(1) in /etc/nginx/conf.d/default.conf:24
2017/11/01 21:25:17 [notice] 42#42: ngx_mruby/1.20.1 (mruby/1.3.0) mechanism enabled in /etc/nginx/nginx.conf:34
127.0.0.1 - - [01/Nov/2017:21:25:22 +0000] "GET /test HTTP/1.1" 200 13 "-" "curl/7.56.1" "-"

[matsumotory]

Thank you for your report.
This behavior seems to be a matter of setting nginx itself. The log, "ngx_mruby/1.20.1 (mruby/1.3.0) mechanism enabled " is server context logs. Please check it.

[shamil]

That's what I thought too, but seem like it isn't. [notice] logs only from mruby module are printed, for example perl module doesn't print anything , see config below ...

Here is my nginx.conf

load_module modules/ngx_http_perl_module.so;
load_module modules/ngx_http_mruby_module.so;

user  nginx;
worker_processes  auto;

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

events { worker_connections 1024; }

http {
    include       /etc/nginx/mime.types;
    default_type  application/octet-stream;

    log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for"';

    access_log  /var/log/nginx/access.log main;

    server {
        listen       80;
        server_name  localhost;

        location / {
            mruby_content_handler_code 'Nginx::rputs "Hello world!"';
        }
    }
}

And here is the output from /var/log/nginx/error.log:

2017/11/06 08:28:03 [notice] 52#52: ngx_mruby NOTICE ngx_http_mruby_shared_state_compile:1026: compile info: code->code.string=(Nginx::rputs "Hello world!") code->cache=(1) in /etc/nginx/nginx.conf:27
2017/11/06 08:28:03 [notice] 52#52: ngx_mruby/1.20.1 (mruby/1.3.0) mechanism enabled in /etc/nginx/nginx.conf:30

[matsumotory]

fmm, I can't reproduced this behavior.

git clone [email protected]:matsumotory/ngx_mruby.git
cd ngx_mruby
sh test.sh

• vi build/nginx/conf/nginx.conf

events {
    worker_connections  1024;
}

worker_processes auto;
error_log logs/error_log_test warn;

http {
    include       mime.types;

    mruby_init_code 'p "[#{Process.pid}] init master process"';
    mruby_init_worker_code 'p "[#{Process.pid}] init worker process from inline code";';
    mruby_exit_worker_code 'p "[#{Process.pid}] exit worker process from inline code"';

    server {
        listen       58081;
        server_name  localhost;
        
        location / {
            mruby_content_handler_code "Nginx.rputs 'proxy test ok'";
        }
    }
}   

$ ./build/nginx/sbin/nginx -g 'daemon off;'
"[14561] init master process"
"[14562] init worker process from inline code"
"[14563] init worker process from inline code"

Please check it.

[yyamano]

@matsumotory I can reproduce it.

% sh test.sh
% rm build/nginx/logs/*
% cp build/nginx/conf/nginx.conf build/nginx/conf/nginx.conf.orig
% vi build/nginx/conf/nginx.conf
% diff -u build/nginx/conf/nginx.conf.orig build/nginx/conf/nginx.conf
--- build/nginx/conf/nginx.conf.orig	2017-12-20 01:18:21.501413133 -0500
+++ build/nginx/conf/nginx.conf	2017-12-20 01:18:37.611413133 -0500
@@ -5,7 +5,7 @@
 
 daemon off;
 master_process off;
-error_log logs/error.log debug;
+error_log logs/error.log notice;
 
 http {
     include       mime.types;

% ./build/nginx/sbin/nginx
"[16762] init master process"
"ngx_mruby: STREAM: mruby_stream_init_code"
"[16762] init worker process from inline code"
"ngx_mruby: STREAM: mruby_stream_init_worker_code"
^C"[16762] exit worker process from inline code"
"ngx_mruby: STREAM: mruby_stream_exit_worker_code"

I can see the mechanism enabled message and other notice messages in build/nginx/logs/error.log:

2017/12/20 01:18:58 [notice] 16762#0: ngx_mruby/1.20.1 (mruby/1.3.0) mechanism enabled in /home/vagrant/ngx_mruby/build/nginx/conf/nginx.conf:817
2017/12/20 01:18:58 [notice] 16762#0: ngx_mruby-stream-module NOTICE ngx_stream_mruby_shared_state_compile:405: compile info: code->code.string=(
    p "ngx_mruby: STREAM: mruby_stream_init_code"
    Userdata.new.new_upstream = "127.0.0.1:58081"
  ) in /home/vagrant/ngx_mruby/build/nginx/conf/nginx.conf:834

[yyamano]

Oops, the above configuration was wrong. I can reproduce it with warn level too.

% diff -u build/nginx/conf/nginx.conf.orig build/nginx/conf/nginx.conf
--- build/nginx/conf/nginx.conf.orig	2017-12-20 01:18:21.501413133 -0500
+++ build/nginx/conf/nginx.conf	2017-12-20 03:07:44.188186619 -0500
@@ -5,7 +5,7 @@
 
 daemon off;
 master_process off;
-error_log logs/error.log debug;
+error_log logs/error.log warn;
 
 http {
     include       mime.types;