Nginx logging configuration and how to get it working

Question

I have configured the nginx.conf for logging as follows. However, after running the client request, I still do not see anything in my log file. I am just starting to learn nginx module development.

#user  nobody;
worker_processes  1;

pid        logs/nginx.pid;

events {
    worker_connections  1024;
}


http {
    include       mime.types;
    default_type  application/octet-stream;
    error_log     logs/error.log debug;

    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  logs/access.log  combined;

    sendfile        on;
    #tcp_nopush     on;

In one of the module code, I am calling the logging function as below.

ngx_log_debug0(NGX_LOG_INFO, r->connection->log, 0, "Calling ngx_http_hello_world_handler");

After I restart the nginx server process (sudo ../nginx-1.12.1-install/sbin/nginx), I do a HTTP GET using this command:

wget http://localhost/test
--2017-09-05 19:28:30--  http://localhost/test
Resolving localhost... ::1, 127.0.0.1
Connecting to localhost|::1|:80... failed: Connection refused.
Connecting to localhost|127.0.0.1|:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: 12 [text/plain]
Saving to: ‘test’

test                                                       100%[======================================================================================================================================>]      12  --.-KB/s    in 0s      

2017-09-05 19:28:30 (1.91 MB/s) - ‘test’ saved [12/12]

I see the error.log file contains as below, but the log I am printing is not coming out.

2017/09/05 21:53:02 [debug] 94100#0: accept on 0.0.0.0:80, ready: 1
2017/09/05 21:53:02 [debug] 94100#0: posix_memalign: 00007FA982D00EA0:512 @16
2017/09/05 21:53:02 [debug] 94100#0: *4 accept: 127.0.0.1:55276 fd:11
2017/09/05 21:53:02 [debug] 94100#0: *4 event timer add: 11: 60000:1504673642557
2017/09/05 21:53:02 [debug] 94100#0: *4 reusable connection: 1
2017/09/05 21:53:02 [debug] 94100#0: *4 kevent set event: 11: ft:-1 fl:0025
2017/09/05 21:53:02 [debug] 94100#0: *4 http wait request handler
2017/09/05 21:53:02 [debug] 94100#0: *4 malloc: 00007FA983823000:1024
2017/09/05 21:53:02 [debug] 94100#0: *4 recv: eof:0, avail:143, err:0
2017/09/05 21:53:02 [debug] 94100#0: *4 recv: fd:11 143 of 1024
2017/09/05 21:53:02 [debug] 94100#0: *4 reusable connection: 0
2017/09/05 21:53:02 [debug] 94100#0: *4 posix_memalign: 00007FA983819000:4096 @16
2017/09/05 21:53:02 [debug] 94100#0: *4 http process request line
2017/09/05 21:53:02 [debug] 94100#0: *4 http request line: "GET /test HTTP/1.1"
2017/09/05 21:53:02 [debug] 94100#0: *4 http uri: "/test"
2017/09/05 21:53:02 [debug] 94100#0: *4 http args: ""
2017/09/05 21:53:02 [debug] 94100#0: *4 http exten: ""
2017/09/05 21:53:02 [debug] 94100#0: *4 http process request header line
2017/09/05 21:53:02 [debug] 94100#0: *4 http header: "User-Agent: Wget/1.19.1 (darwin15.6.0)"
2017/09/05 21:53:02 [debug] 94100#0: *4 http header: "Accept: */*"
2017/09/05 21:53:02 [debug] 94100#0: *4 http header: "Accept-Encoding: identity"
2017/09/05 21:53:02 [debug] 94100#0: *4 http header: "Host: localhost"
2017/09/05 21:53:02 [debug] 94100#0: *4 http header: "Connection: Keep-Alive"
2017/09/05 21:53:02 [debug] 94100#0: *4 http header done
2017/09/05 21:53:02 [debug] 94100#0: *4 event timer del: 11: 1504673642557
2017/09/05 21:53:02 [debug] 94100#0: *4 rewrite phase: 0
2017/09/05 21:53:02 [debug] 94100#0: *4 test location: "/"
2017/09/05 21:53:02 [debug] 94100#0: *4 test location: "test"
2017/09/05 21:53:02 [debug] 94100#0: *4 using configuration "=/test"
2017/09/05 21:53:02 [debug] 94100#0: *4 http cl:-1 max:1048576
2017/09/05 21:53:02 [debug] 94100#0: *4 rewrite phase: 2
2017/09/05 21:53:02 [debug] 94100#0: *4 post rewrite phase: 3
2017/09/05 21:53:02 [debug] 94100#0: *4 generic phase: 4
2017/09/05 21:53:02 [debug] 94100#0: *4 generic phase: 5
2017/09/05 21:53:02 [debug] 94100#0: *4 access phase: 6
2017/09/05 21:53:02 [debug] 94100#0: *4 access phase: 7
2017/09/05 21:53:02 [debug] 94100#0: *4 post access phase: 8
2017/09/05 21:53:02 [debug] 94100#0: *4 posix_memalign: 00007FA98380D400:4096 @16
2017/09/05 21:53:02 [debug] 94100#0: *4 http cleanup add: 00007FA983819FC8
2017/09/05 21:53:02 [debug] 94100#0: *4 HTTP/1.1 200 OK
Server: nginx/1.12.1
Date: Wed, 06 Sep 2017 04:53:02 GMT
Content-Type: text/plain
Content-Length: 12
Connection: keep-alive

2017/09/05 21:53:02 [debug] 94100#0: *4 write new buf t:1 f:0 00007FA98380D528, pos 00007FA98380D528, size: 148 file: 0, size: 0
2017/09/05 21:53:02 [debug] 94100#0: *4 http write filter: l:0 f:0 s:148
2017/09/05 21:53:02 [debug] 94100#0: *4 http output filter "/test?"
2017/09/05 21:53:02 [debug] 94100#0: *4 http copy filter: "/test?"
2017/09/05 21:53:02 [debug] 94100#0: *4 http postpone filter "/test?" 00007FFF56B2F458
2017/09/05 21:53:02 [debug] 94100#0: *4 write old buf t:1 f:0 00007FA98380D528, pos 00007FA98380D528, size: 148 file: 0, size: 0
2017/09/05 21:53:02 [debug] 94100#0: *4 write new buf t:0 f:0 0000000000000000, pos 0000000109173528, size: 12 file: 0, size: 0
2017/09/05 21:53:02 [debug] 94100#0: *4 http write filter: l:1 f:0 s:160
2017/09/05 21:53:02 [debug] 94100#0: *4 http write filter limit 0
2017/09/05 21:53:02 [debug] 94100#0: *4 writev: 160 of 160
2017/09/05 21:53:02 [debug] 94100#0: *4 http write filter 0000000000000000
2017/09/05 21:53:02 [debug] 94100#0: *4 http copy filter: 0 "/test?"
2017/09/05 21:53:02 [debug] 94100#0: *4 http finalize request: 0, "/test?" a:1, c:2
2017/09/05 21:53:02 [debug] 94100#0: *4 http request count:2 blk:0
2017/09/05 21:53:02 [debug] 94100#0: *4 http run request: "/test?"
2017/09/05 21:53:02 [debug] 94100#0: *4 http reading blocked

Can someone tell me what I am missing?

Answer 1

well, although it's been a long while since this question was posted, I wanna clarify a little bit of what happened and a little bit elaborate on what @AnilJ has done to fix the problem. I first take you to the ngx_log.h header:

#define NGX_LOG_STDERR            0
#define NGX_LOG_EMERG             1
#define NGX_LOG_ALERT             2
#define NGX_LOG_CRIT              3
#define NGX_LOG_ERR               4
#define NGX_LOG_WARN              5
#define NGX_LOG_NOTICE            6
#define NGX_LOG_INFO              7
#define NGX_LOG_DEBUG             8

#define NGX_LOG_DEBUG_CORE        0x010
#define NGX_LOG_DEBUG_ALLOC       0x020
#define NGX_LOG_DEBUG_MUTEX       0x040
#define NGX_LOG_DEBUG_EVENT       0x080
#define NGX_LOG_DEBUG_HTTP        0x100
#define NGX_LOG_DEBUG_MAIL        0x200
#define NGX_LOG_DEBUG_STREAM      0x400

the first 8 macros are major log levels, ordered from the highest priority to the lowest. While, the second stack is the debug log levels. As you can see,

NGX_LOG_DEBUG_CORE = NGX_LOG_DEBUG * 2; // 0x008 * 2 = 0x010
NGX_LOG_DEBUG_ALLOC = NGX_LOG_DEBUG * 4;  // 0x008 * 4 = 0x020

therefore, the following should work:

ngx_log_debug0(16, log, 0, "log this");

to verify that, we can see the logic here:

#define ngx_log_debug(level, log, ...)                                        \
    if ((log)->log_level & level)                                             \
        ngx_log_error_core(NGX_LOG_DEBUG, log, __VA_ARGS__)

if you further investigate in source code, we can see if we set the log level to debug, the following is being set:

    // see ngx_log_set_levels
    if (log->log_level == NGX_LOG_DEBUG) {
        log->log_level = NGX_LOG_DEBUG_ALL;
    }

where NGX_LOG_DEBUG_ALL is equal to 0x7ffffff0

    #define NGX_LOG_DEBUG_ALL         0x7ffffff0

back to the problem in the question, the following code is being called:

    ngx_log_debug0(NGX_LOG_INFO, r->connection->log, 0, "Calling 
    ngx_http_hello_world_handler");

since r->connection->log=NGX_LOG_DEBUG_ALL=0x7ffffff0 and NGX_LOG_INFO=8 then,

     NGX_LOG_INFO & NGX_LOG_DEBUG_ALL = 0x8 & 0x7ffffff0 = false

and you will not see any debug logs. To make it working, one should pick one of NGX_LOG_DEBUG_CORE,NGX_LOG_DEBUG_ALLOC,NGX_LOG_DEBUG_MUTEX,NGX_LOG_DEBUG_EVENT,NGX_LOG_DEBUG_MAIL,NGX_LOG_DEBUG_STREAM or NGX_LOG_DEBUG_ALL itself.

Answer 2

Chances are this is because you log to NGX_LOG_INFO, r->connection->log, but you've enabled the error_log ... debug directive only in the http section.

But as per docs, error_log can be placed in these contexts:

Context: main, http, mail, stream, server, location

I think NGX_LOG_INFO is main, so try adding error_log logs/error.log debug; also at the top level, outside of http, like this:

...

error_log     logs/error.log debug;

http {
    include       mime.types;
    default_type  application/octet-stream;
    error_log     logs/error.log debug;
    ...

This also explains why your log messages appeared when you changed from NGX_LOG_INFO to NGX_LOG_DEBUG_HTTP.

Answer 3

I got my log messages working by modifying the log arguments as below.

ngx_log_debug0(NGX_LOG_DEBUG_HTTP, r->connection->log, 0, "Calling ngx_http_hello_world_handler");

I changed from NGX_LOG_INFO to NGX_LOG_DEBUG_HTTP. I am not sure what are these components are, but something I need work on and understand.

2017/09/05 22:06:03 [debug] 98383#0: *2 post access phase: 8
2017/09/05 22:06:03 [debug] 98383#0: *2 Calling ngx_http_hello_world_handler
2017/09/05 22:06:03 [debug] 98383#0: *2 Calling ngx_http_hello_world_process_request
2017/09/05 22:06:03 [debug] 98383#0: *2 Calling ngx_http_create_cookie_state
2017/09/05 22:06:03 [debug] 98383#0: *2 posix_memalign: 00007FBA4980E400:4096 @16
2017/09/05 22:06:03 [debug] 98383#0: *2 Calling search_headers_in
2017/09/05 22:06:03 [debug] 98383#0: *2 Calling search_headers_in

For now, I will keep using the same log message in all my application code.

Answer 4

You can try to delete the logfile and restart nginx to see whether a new logfile will be created. I start it in nginx folder, maybe the path is not correct. nginx may find in current folder not nginx folder. Maybe it's useful