【技术分享】Nginx Lua日志收集

在WAF命中规则后，需要记录拦截的日志，之前使用的方法是ngx.log。运行了一段时间，遇到一个瓶颈，ngx.log 记录每行最长长度为2048字节。

这个限制可以通过修改nginx源码修改，但是让运维修改nginx源码，重新编译nginx，打一个新RPM包，这个方法我自己都不想接受。

所以，我尝试换另外的方法去解决这个问题。

可以看到，基本是用Lua的io.open，但是任何文件操作都会造成nginx请求的阻塞。

这是我完全不能接收的，所以我做了压测对比。使用ab压测一个拦截页面，压测命令如下：

ab -n 100000 -c 100 http://x.x.x.x/payload

第一次 表示 第一次压测每条请求的平均时间，单位是ms。

消耗时间为ngx.log < syslog-ng < io.open，ngx.log 和 io.open 都会阻塞请求，所以我选择 syslog-ng。

那么，有个问题来了：既然 syslog-ng 不阻塞请求，为什么消耗时间不是最慢的？

我也一直在思考这个问题，我的结论是： syslog-ng 方式的时间消耗在了TCP的连接上以及 syslog-ng 写日志的IO操作上，另外两个方法只有IO消耗。所以我也用 syslog-ng 做了远程日志的测试，发现最低的时间0.165，其实已经是最低的消耗时间了，但是由于网路的不稳定性，两次消耗时间差距较大，也放弃了远程日志的方式。

Lua代码:

local logger = require "resty.logger_socket"

-- 使用lua-resty-logger-socket向syslog-ng写入日志
-- 当满足一定的条件，syslog-ng即会进入垃圾收集状态，而暂时不再接受日志信息。这时，会造成非连接的传输协议的日志丢失(例如UDP)
function _M.logger_socket(log_data, blocktype, rulename)
    if not logger.initted() then
        local ok, err = logger.init {
            host = "127.0.0.1",
            port = 514, -- 默认使用tcp方式，使用UDP会造成日志丢失。
            flush_limit = 4096, -- 大小累计到该数值，才进行socket连接。该值可以加快socket速度，不用每条都请求。
            periodic_flush = 10,
        }
        if not ok then
            ngx.log(ngx.ERR, "failed to initialize the logger: ", err)
            return
        end
    end
    local bytes, err = logger.log("datan")

    if err then
        ngx.log(ngx.ERR, "failed to log message: ", err)
        return
    end
end

如果想要近实时的日志，需要将buffer值设置稍微小点，或者使用`periodic_flush`参数（单位是秒）来定时刷新。

logger-socket代码地址：https://github.com/cloudflare/lua-resty-logger-socket

syslog-ng 配置

@version:3.2

# filepath: /etc/syslog-ng/syslog-ng.conf

source s_sys {
    tcp(ip(127.0.0.1) port(514));
};

destination test {
    file("/var/log/syslog-ng.log");
};

log {
    source(s_sys);
    destination(test);
};

当满足一定的条件，syslog-ng 会进入垃圾收集状态，而暂时不再接受日志信息。这时，会造成非连接的传输协议的日志丢失(例如UDP)。所以要使用TCP协议。

为了让日志的文件内容体积不会越来越大，选择使用Logrotate轮询 syslog-ng 的日志。轮询的时候，需要解决一个问题：

当轮询完成后，之前的 /var/log/syslog-ng.log 文件名会被重命名类似 /var/log/syslog-ng.log-20171217 的文件名。此时，syslog-ng 就不能写日志了，因为配置的 /var/log/syslog-ng.log 文件不存在了。

测试发现，reload syslog-ng 服务后，配置的文件又能重新生成。后来，我提了一个issue咨询是否还有其他方式，作者提供了一种更优雅的方式来替代reload操作：对 syslog-ng 发一个reopen信号。

对 syslog-ng 进程发起 reopen 信号的命令为：

/bin/kill -SIGUSR1 `cat /var/run/syslogd.pid 2> /dev/null` 2> /dev/null

Github上提问的ISSUE链接：https://github.com/balabit/syslog-ng/issues/1774

最后，logrotate的配置文件为

/var/log/syslog-ng.log {
    rotate 7
    missingok
    daily
    dateext
    nocompress
    postrotate
        /bin/kill -SIGUSR1 `cat /var/run/syslogd.pid 2> /dev/null` 2> /dev/null
    endscript
}

其中：

• /var/run/syslogd.pid 文件记录着 syslog-ng 运行的 pid

• 可以发现，利用 logrotate 可以执行 shell 命令，所以这也是一种留后门的攻击方式。

  
  

Logrotate每天会自动运行，因为在 cron.daily 定时任务里。

cat /etc/cron.daily/logrotate

#!/bin/sh

/usr/sbin/logrotate /etc/logrotate.conf >/dev/null 2>&1
EXITVALUE=$?
if [ $EXITVALUE != 0 ]; then
    /usr/bin/logger -t logrotate "ALERT exited abnormally with [$EXITVALUE]"
fi
exit 0

那cron.daily 每天什么时候执行？

可以看到 /etc/cron.daily 定义在 /etc/anacrontab 里。

$ cat /etc/anacrontab
# /etc/anacrontab: configuration file for anacron
# See anacron(8) and anacrontab(5) for details.
SHELL=/bin/sh
PATH=/sbin:/bin:/usr/sbin:/usr/bin
MAILTO=root
# the maximal random delay added to the base delay of the jobs
RANDOM_DELAY=45
# the jobs will be started during the following hours only
START_HOURS_RANGE=3-22
#period in days delay in minutes job-identifier command
1    5    cron.daily        nice run-parts /etc/cron.daily
7    25    cron.weekly        nice run-parts /etc/cron.weekly
@monthly 45    cron.monthly        nice run-parts /etc/cron.monthly

start_hours_range=3-22 表示在3点到22点之间运行，cron.daily 会延迟5分钟，并且最大的随机延迟为45分钟。

所以运行时间为，3.05- 3.50。关于这个时间点，网上真的有很多谬论。

看看已经生成的日志文件时间：

-rw-------   1 root root      0 Dec 15 03:25 syslog-ng.log-20171216
-rw-------   1 root root      0 Dec 14 03:17 syslog-ng.log-20171215
-rw-------   1 root root      0 Dec 13 03:41 syslog-ng.log-20171214
-rw-------   1 root root      0 Dec 12 03:17 syslog-ng.log-20171213
-rw-------   1 root root      0 Dec 11 03:18 syslog-ng.log-20171212