Nginx 日志记录配置以及如何使其工作答案

【问题标题】：Nginx logging configuration and how to get it workingNginx 日志记录配置以及如何使其工作
【发布时间】：2018-02-14 09:04:53
【问题描述】：

我已经为日志配置了 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

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

【问题讨论】：

标签： nginx logging

【解决方案1】：

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

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

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

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

...

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 时出现日志消息的原因。

【讨论】：

【解决方案2】：

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

【讨论】：

嗨@J。孙，我厌倦了你的要求，但收效甚微。但是，我添加的日志消息还没有。

【解决方案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

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

【讨论】：