Nginx日志配置以及如何使其正常工作

Question

我已经为日志记录配置了nginx.conf，如下所示。但是，在运行客户端请求之后，我仍然没有在日志文件中看到任何内容。我刚刚开始学习nginx模块开发。

#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;

在其中一个模块代码中，我调用了日志函数，如下所示。

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

在我重新启动nginx服务器进程(sudo ../nginx-1.12.1-install/sbin/nginx)之后，我使用以下命令执行HTTP GET：

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]

我看到error.log文件包含如下内容，但是我打印的日志没有输出。

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

谁能告诉我我错过了什么？

Answer 1

这很可能是因为您登录到了NGX_LOG_INFO, r->connection->log，但只在http部分启用了error_log ... debug指令。

但根据docs，error_log可以放在以下上下文中：

上下文：main, http, mail, stream, server, location

我认为NGX_LOG_INFO是main，所以尝试在顶层添加error_log logs/error.log debug;，在http之外，如下所示：

...

error_log     logs/error.log debug;

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

这也解释了当您从NGX_LOG_INFO更改为NGX_LOG_DEBUG_HTTP时出现日志消息的原因。

Answer 2

您可以尝试删除日志文件并重新启动nginx，以查看是否会创建新的日志文件。我是在nginx文件夹中启动的，可能路径不正确。nginx可能在当前文件夹中找到，而不是nginx文件夹中。也许它是有用的

Answer 3

我通过修改日志参数使日志消息正常工作，如下所示。

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

我从NGX_LOG_INFO改成了NGX_LOG_DEBUG_HTTP。我不确定这些组件是什么，但我需要努力和理解一些东西。

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

现在，我将继续在我的所有应用程序代码中使用相同的日志消息。