求记录日志文件的比较好的办法

wd

hi,

我这需要 ngx_lua 处理完请求之后，同时记录一份日志。

想法是通过 log_by_lua_file 做，因为写同一个文件，所以需要写之前加锁？有没有更好的办法？

wd

看了会，貌似通过 socket 发到远端机器比较好。。。我试试看这个吧。

2015-06-29 18:06 GMT+08:00 wd <...@wdicc.com>:

hi,

我这需要 ngx_lua 处理完请求之后，同时记录一份日志。

想法是通过 log_by_lua_file 做，因为写同一个文件，所以需要写之前加锁？有没有更好的办法？

0yuan0

恭喜！

我们是使用春哥公司开源的组件完成的。推荐一下：

https://github.com/cloudflare/lua-resty-logger-socket

On Monday, June 29, 2015 at 6:18:38 PM UTC+8, wd wrote:

看了会，貌似通过 socket 发到远端机器比较好。。。我试试看这个吧。

2015-06-29 18:06 GMT+08:00 wd <w...@wdicc.com>:
hi,

我这需要 ngx_lua 处理完请求之后，同时记录一份日志。

想法是通过 log_by_lua_file 做，因为写同一个文件，所以需要写之前加锁？有没有更好的办法？

wd

2015-06-29 18:46 GMT+08:00 YuanSheng Wang <0y...@gmail.com>:

我们是使用春哥公司开源的组件完成的。推荐一下：
https://github.com/cloudflare/lua-resty-logger-socket

恩，这个我知道。我这主要是改成这种方式得相应改一些程序。

就这么搞吧。多谢了。

agentzh

Hello!

2015-06-29 18:06 GMT+08:00 wd:
> 我这需要 ngx_lua 处理完请求之后，同时记录一份日志。
>
> 想法是通过 log_by_lua_file 做，因为写同一个文件，所以需要写之前加锁？有没有更好的办法？
>

这是一个 FAQ :) 请见

http://openresty.org/faq.html#can-i-use-custom-loggers-in-lua

Regards,
-agentzh

wd

On Mon, Jun 29, 2015 at 8:00 PM, Yichun Zhang (agentzh) <age...@gmail.com> wrote:

Hello!

2015-06-29 18:06 GMT+08:00 wd:
> 我这需要 ngx_lua 处理完请求之后，同时记录一份日志。
>
> 想法是通过 log_by_lua_file 做，因为写同一个文件，所以需要写之前加锁？有没有更好的办法？
>

这是一个 FAQ :) 请见

http://openresty.org/faq.html#can-i-use-custom-loggers-in-lua

看了下，好像省事的办法还是 lua-resty-logger，昨天搞了一下，计划直接发给 flume 然后弄到 hdfs 上面。

Regards,
-agentzh

--

wd

On Mon, Jun 29, 2015 at 8:00 PM, Yichun Zhang (agentzh) <age...@gmail.com> wrote:

Hello!

2015-06-29 18:06 GMT+08:00 wd:
> 我这需要 ngx_lua 处理完请求之后，同时记录一份日志。
>
> 想法是通过 log_by_lua_file 做，因为写同一个文件，所以需要写之前加锁？有没有更好的办法？
>

这是一个 FAQ :) 请见

http://openresty.org/faq.html#can-i-use-custom-loggers-in-lua

我参考这里的例子 https://github.com/cloudflare/lua-resty-logger-socket#synopsis 写了一个最简单的，然后用 http_load 压了一下，发现接收方收到的消息比发送的消息少，这个可能是什么原因？

http_load -f 2000 -p 50

我已经调大了 drop_limit，好像也不行。

Regards,
-agentzh

--

agentzh

Hello!

2015-06-30 15:06 GMT+08:00 wd:
>
> 我参考这里的例子  https://github.com/cloudflare/lua-resty-logger-socket#synopsis
> 写了一个最简单的，然后用 http_load 压了一下，发现接收方收到的消息比发送的消息少，这个可能是什么原因？
>
> http_load -f 2000 -p 50
>
> 我已经调大了 drop_limit，好像也不行。
>

也许是因为 buffer 的原因。这个库出于性能的考虑，会缓冲消息到内存，缓冲区满了或者服务器退出时才会强制刷新缓冲区。你可以配置
periodic_flush 选项，让它周期性地强制刷出缓冲的日志。这对于线上较繁忙的应用倒是无所谓了，但自己测试总会没有流量的。

Regards,
-agentzh

wd

2015-06-30 15:09 GMT+08:00 Yichun Zhang (agentzh) <age...@gmail.com>:

也许是因为 buffer 的原因。这个库出于性能的考虑，会缓冲消息到内存，缓冲区满了或者服务器退出时才会强制刷新缓冲区。你可以配置
periodic_flush 选项，让它周期性地强制刷出缓冲的日志。这对于线上较繁忙的应用倒是无所谓了，但自己测试总会没有流量的。

这个我考虑了，我加了个 location 用来 flush。

另外我本来考虑是 flume 那边有问题，试了一下 ncat 好像也是会丢。

我等下弄一个纯净一点 openresty 环境再看看。

wd

2015-06-30 15:36 GMT+08:00 wd <...@wdicc.com>:

2015-06-30 15:09 GMT+08:00 Yichun Zhang (agentzh) <age...@gmail.com>:
也许是因为 buffer 的原因。这个库出于性能的考虑，会缓冲消息到内存，缓冲区满了或者服务器退出时才会强制刷新缓冲区。你可以配置
periodic_flush 选项，让它周期性地强制刷出缓冲的日志。这对于线上较繁忙的应用倒是无所谓了，但自己测试总会没有流量的。

这个我考虑了，我加了个 location 用来 flush。

另外我本来考虑是 flume 那边有问题，试了一下 ncat 好像也是会丢。

我等下弄一个纯净一点 openresty 环境再看看。

我测试了一会，现象比较诡异，居然还有多的时候，不过只遇到一次。。

有时候压一次 2000 个请求是 ok 的，有时候是会少，我也没找到规律。。

你们那没这个问题么？还是允许少量数据丢失？

wd

我贴一下我的代码吧。

~/http_load-14aug2014/http_load -s 10 -p 30 ~/url 2>/dev/null

284568 fetches, 30 max parallel, 0 bytes, in 10 seconds

0 mean bytes/connection

28456.7 fetches/sec, 0 bytes/sec

msecs/connect: 0.0932643 mean, 7.349 max, 0 min

msecs/first-response: 0.463474 mean, 13.722 max, 0.098 min

HTTP response codes:

code 200 -- 284568

location /test

t.lua

local logger = require "resty.logger.socket"

if not logger.initted() then

local ok, err = logger.init{

host = 'myhost',

port = 41419,

flush_limit = 4096,

drop_limit = 10485760,

}

if not ok then

ngx.log(ngx.ERR, "failed to initialize the logger: ",

err)

return

end

-- construct the custom access log message in

-- the Lua variable "msg"

local msg = os.time() .. "\ttests sdf sdf s df sdf sdf s df sdf s f se wf sd fs df sdf sdf s dfs f we sdf s df sdf sdf s dfs df sdf we f sdf sf sd fs fs f sdf sf \n"

local bytes, err = logger.log(msg)

if err then

ngx.log(ngx.ERR, "failed to log message: ", err)

return

end

location /flush

flush.lua

local logging = require("logging")

local bytes, err = logging.flush_logger()

if err then

ngx.say("flush failed: " .. err)

else

ngx.say('flush ok')

end

远端是用 flume 的 netcat 模式接收数据保存到文件，收到 219597 条数据。

wc -l 1435659586463-1

219597 1435659586463-1

最后差异是大概丢失 23%

2015-06-30 18:16 GMT+08:00 wd <...@wdicc.com>:

2015-06-30 15:36 GMT+08:00 wd <...@wdicc.com>:

2015-06-30 15:09 GMT+08:00 Yichun Zhang (agentzh) <age...@gmail.com>:
也许是因为 buffer 的原因。这个库出于性能的考虑，会缓冲消息到内存，缓冲区满了或者服务器退出时才会强制刷新缓冲区。你可以配置
periodic_flush 选项，让它周期性地强制刷出缓冲的日志。这对于线上较繁忙的应用倒是无所谓了，但自己测试总会没有流量的。

这个我考虑了，我加了个 location 用来 flush。

另外我本来考虑是 flume 那边有问题，试了一下 ncat 好像也是会丢。

我等下弄一个纯净一点 openresty 环境再看看。

我测试了一会，现象比较诡异，居然还有多的时候，不过只遇到一次。。

有时候压一次 2000 个请求是 ok 的，有时候是会少，我也没找到规律。。

你们那没这个问题么？还是允许少量数据丢失？

wd

我多做了几次测试。每次都是重启服务。

304418 208464

302811 206740

丢失大概 30%

我试过用 ncat 测试，ncat 好像容易死掉没有响应，不知道是不是用法有问题。

2015-06-30 18:24 GMT+08:00 wd <...@wdicc.com>:

我贴一下我的代码吧。

~/http_load-14aug2014/http_load -s 10 -p 30 ~/url 2>/dev/null
284568 fetches, 30 max parallel, 0 bytes, in 10 seconds
0 mean bytes/connection
28456.7 fetches/sec, 0 bytes/sec
msecs/connect: 0.0932643 mean, 7.349 max, 0 min
msecs/first-response: 0.463474 mean, 13.722 max, 0.098 min
HTTP response codes:
code 200 -- 284568

location /test
t.lua

local logger = require "resty.logger.socket"

if not logger.initted() then
local ok, err = logger.init{
host = 'myhost',
port = 41419,
flush_limit = 4096,
drop_limit = 10485760,
}
if not ok then
ngx.log(ngx.ERR, "failed to initialize the logger: ",
err)
return
end
end

-- construct the custom access log message in
-- the Lua variable "msg"
local msg = os.time() .. "\ttests sdf sdf s df sdf sdf s df sdf s f se wf sd fs df sdf sdf s dfs f we sdf s df sdf sdf s dfs df sdf we f sdf sf sd fs fs f sdf sf \n"
local bytes, err = logger.log(msg)
if err then
ngx.log(ngx.ERR, "failed to log message: ", err)
return
end

location /flush
flush.lua

sorry 这个代码有点问题用的是我的模块，不过那个模块调用的也是 logger 的 flush。

local logging = require("logging")

local bytes, err = logging.flush_logger()
if err then
ngx.say("flush failed: " .. err)
else
ngx.say('flush ok')
end

远端是用 flume 的 netcat 模式接收数据保存到文件，收到 219597 条数据。

wc -l 1435659586463-1
219597 1435659586463-1

最后差异是大概丢失 23%

2015-06-30 18:16 GMT+08:00 wd <...@wdicc.com>:

2015-06-30 15:36 GMT+08:00 wd <...@wdicc.com>:

2015-06-30 15:09 GMT+08:00 Yichun Zhang (agentzh) <age...@gmail.com>:
也许是因为 buffer 的原因。这个库出于性能的考虑，会缓冲消息到内存，缓冲区满了或者服务器退出时才会强制刷新缓冲区。你可以配置
periodic_flush 选项，让它周期性地强制刷出缓冲的日志。这对于线上较繁忙的应用倒是无所谓了，但自己测试总会没有流量的。

这个我考虑了，我加了个 location 用来 flush。

另外我本来考虑是 flume 那边有问题，试了一下 ncat 好像也是会丢。

我等下弄一个纯净一点 openresty 环境再看看。

我测试了一会，现象比较诡异，居然还有多的时候，不过只遇到一次。。

有时候压一次 2000 个请求是 ok 的，有时候是会少，我也没找到规律。。

你们那没这个问题么？还是允许少量数据丢失？

membphis

确定一下，lua-resty-logger-socket 是用在了 log_by_lua 阶段么？

On Tuesday, June 30, 2015 at 6:31:55 PM UTC+8, wd wrote:

我多做了几次测试。每次都是重启服务。

304418 208464
302811 206740

丢失大概 30%

我试过用 ncat 测试，ncat 好像容易死掉没有响应，不知道是不是用法有问题。

2015-06-30 18:24 GMT+08:00 wd <w...@wdicc.com>:
我贴一下我的代码吧。

~/http_load-14aug2014/http_load -s 10 -p 30 ~/url 2>/dev/null
284568 fetches, 30 max parallel, 0 bytes, in 10 seconds
0 mean bytes/connection
28456.7 fetches/sec, 0 bytes/sec
msecs/connect: 0.0932643 mean, 7.349 max, 0 min
msecs/first-response: 0.463474 mean, 13.722 max, 0.098 min
HTTP response codes:
code 200 -- 284568

location /test
t.lua

local logger = require "resty.logger.socket"

if not logger.initted() then
local ok, err = logger.init{
host = 'myhost',
port = 41419,
flush_limit = 4096,
drop_limit = 10485760,
}
if not ok then
ngx.log(ngx.ERR, "failed to initialize the logger: ",
err)
return
end
end

-- construct the custom access log message in
-- the Lua variable "msg"
local msg = os.time() .. "\ttests sdf sdf s df sdf sdf s df sdf s f se wf sd fs df sdf sdf s dfs f we sdf s df sdf sdf s dfs df sdf we f sdf sf sd fs fs f sdf sf \n"
local bytes, err = logger.log(msg)
if err then
ngx.log(ngx.ERR, "failed to log message: ", err)
return
end

location /flush
flush.lua

sorry 这个代码有点问题用的是我的模块，不过那个模块调用的也是 logger 的 flush。

local logging = require("logging")

local bytes, err = logging.flush_logger()
if err then
ngx.say("flush failed: " .. err)
else
ngx.say('flush ok')
end

远端是用 flume 的 netcat 模式接收数据保存到文件，收到 219597 条数据。

wc -l 1435659586463-1
219597 1435659586463-1

最后差异是大概丢失 23%

2015-06-30 18:16 GMT+08:00 wd <w...@wdicc.com>:

2015-06-30 15:36 GMT+08:00 wd <w...@wdicc.com>:

2015-06-30 15:09 GMT+08:00 Yichun Zhang (agentzh) <age...@gmail.com>:
也许是因为 buffer 的原因。这个库出于性能的考虑，会缓冲消息到内存，缓冲区满了或者服务器退出时才会强制刷新缓冲区。你可以配置
periodic_flush 选项，让它周期性地强制刷出缓冲的日志。这对于线上较繁忙的应用倒是无所谓了，但自己测试总会没有流量的。

这个我考虑了，我加了个 location 用来 flush。

另外我本来考虑是 flume 那边有问题，试了一下 ncat 好像也是会丢。

我等下弄一个纯净一点 openresty 环境再看看。

我测试了一会，现象比较诡异，居然还有多的时候，不过只遇到一次。。

有时候压一次 2000 个请求是 ok 的，有时候是会少，我也没找到规律。。

你们那没这个问题么？还是允许少量数据丢失？

agentzh

Hello!

2015-06-30 18:31 GMT+08:00 wd:
> 我多做了几次测试。每次都是重启服务。
>
> 304418  208464
> 302811  206740
>
> 丢失大概 30%
>

几个建议：

1. 检查 nginx 错误日志文件，看看是否有错误。注意须确保你的 error_log
配置指令本置正确，以免过滤掉直接重要的错误消息。建议使用 error_log logs/error.log warn; 级别。

2. 确保不是你的接收后端的问题。

3. 配置 periodic_flush 选项。

> 我试过用 ncat 测试，ncat 好像容易死掉没有响应，不知道是不是用法有问题。
>

netcat 根本受不了并发，不要用它来测试。你倒可以考虑使用 syslog-ng 进行测试。

Regards,
-agentzh

wd

我重新编译了一个 nginx，然后测试了一下。我的测试环境可能还有些问题。先看看结果把。有问题的地方麻烦指出来我改进下再测试。

nginx.conf 如下

worker_processes  5;
error_log  logs/error.log  info;

events {
    worker_connections  1024;
}

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



    sendfile        on;

    keepalive_timeout  65;

    lua_package_path "/opt/ngx/nginx/lua/?.lua;/opt/vpas-qp/lib/?.lua";


    server {
        listen       8099;
        server_name  localhost;

        location / {
            root   html;
            index  index.html index.htm;
        }

        location /log {
             resolver 127.0.0.1;
             echo "OK";
             log_by_lua_file /opt/ngx/nginx/lua/log.lua;
        }

        error_page   500 502 503 504  /50x.html;
        location = /50x.html {
            root   html;
        }
    }
}


/opt/ngx/nginx/lua/log.lua 如下

local logger = require "resty.logger.socket"
local uuid = require "uuid"  -- 这个是从网上找的，应该就是论坛哥们写的
https://groups.google.com/forum/#!topic/openresty/lOGAkkc3Zk0

if not logger.initted() then
    local ok, err = logger.init{
        host = 'abc.com',
        port = 41419,
        flush_limit = 40960,
        drop_limit = 104857600,
        periodic_flush = 10,
    }
    if not ok then
        ngx.log(ngx.ERR, "failed to initialize the logger: ",
                err)
        return
    end
end

-- construct the custom access log message in
-- the Lua variable "msg"
local uid = uuid.gen_uuid()
local msg = uid .. "\ttests sdf sdf s df sdf sdf s df sdf s f se wf sd
fs df sdf sdf s dfs f we  sdf s df sdf sdf s dfs df sdf we f sdf sf sd
fs fs f sdf sf \n"

ngx.log(ngx.ERR, msg)

local bytes, err = logger.log(msg)
if err then
    ngx.log(ngx.ERR, "failed to log message: ", err)
    return
end

远端收集机器 abc.com 上面跑了个 flume，配置如下，netcat 协议监听端口，然后保存到本地文件。

a1.channels = ch2
a1.sources = avro-source2
a1.sinks = s2

####
a1.channels.ch2.type = file
a1.channels.ch2.checkpointDir =/export/tmp/wd/checkpoint
a1.channels.ch2.dataDirs = /export/tmp/wd/data

a1.sources.avro-source2.channels = ch2
a1.sources.avro-source2.type = netcat
a1.sources.avro-source2.bind = 0.0.0.0
a1.sources.avro-source2.port = 41419
a1.sources.avro-source2.ack-every-event = false
a1.sources.avro-source2.max-line-length = 10240000

a1.sinks.s2.type = file_roll
a1.sinks.s2.channel = ch2
a1.sinks.s2.sink.rollInterval = 0
a1.sinks.s2.sink.directory = /export/tmp/test_log/


使用 http load 压力测试，命令和结果如下, url 里面就一行 http://localhost:8099/log
./http_load -r 100 -p 2 -s 10 ../url
80364 fetches, 2 max parallel, 241092 bytes, in 10 seconds
3 mean bytes/connection
8036.4 fetches/sec, 24109.2 bytes/sec
msecs/connect: 0.0281634 mean, 2.413 max, 0 min
msecs/first-response: 0.205608 mean, 13.234 max, 0.012 min
HTTP response codes:
  code 200 -- 80364

flume 那边收到的数据量

$ wc -l 1435803593030-1
110928 1435803593030-1

我排序 count 了一下，有些数据是重复收到的，最大的是 5 个重复的，还有 4 个 3 个等的情况

      5 7b585137-5e15-4951-9cc9-423800f380f9
      5 7af542a7-d66f-4aab-9c2b-85708b95b747
      5 7a90cf4e-7deb-4279-8869-4c3ef3a0d468
      5 74286718-2266-43a7-9942-a841c6abfdf6
      5 704c9994-2a39-417a-9f13-8a7f8cf0c37f
      5 6f705f0a-1f5b-42d3-bc00-3d0e611752d0
      5 6f273265-64d6-4cf7-a3a0-4b3aebc8a01b
      5 6bd02d75-ac6f-49f8-9639-6d5be1a61021
      5 6740315a-3fa2-4204-b633-5e90097c6777
      5 665a45c4-3ab0-4392-8293-0f215330a3a7
      5 6614c447-3423-4ccd-9b17-290fa3348622
      5 6127458d-6033-4993-8226-3a8383da8f8f
      5 601d377a-7869-435b-a513-58946c0f516b

去重之后算了一下，

$ awk '{print $1}' 1435803593030-1 | sort | uniq -c | sort -nr | wc -l
79102

nginx 的错误日志里面有这些信息

2015/07/02 10:20:21 [error] 28890#0: lua tcp socket write timed out,
context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:8099
2015/07/02 10:20:22 [error] 28890#0: lua tcp socket write timed out,
context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:8099
2015/07/02 10:20:30 [error] 28890#0: lua tcp socket write timed out,
context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:8099
2015/07/02 10:20:31 [error] 28887#0: lua tcp socket write timed out,
context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:8099
2015/07/02 10:20:32 [error] 28887#0: lua tcp socket write timed out,
context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:8099

那个 log.lua 有一行 ngx.log(ngx.ERR, msg) 会把消息记录再 nginx 的错误日志一份，这个数量和
http_load 的发送请求的数量一致。

目前我没有办法排查是 flume 的问题，还是 resty.logger.socket 的问题，有啥好办法么？用 syslog-ng ?


2015-06-30 19:48 GMT+08:00 Yichun Zhang (agentzh) <age...@gmail.com>:
> Hello!
>
> 2015-06-30 18:31 GMT+08:00 wd:
>> 我多做了几次测试。每次都是重启服务。
>>
>> 304418  208464
>> 302811  206740
>>
>> 丢失大概 30%
>>
>
> 几个建议：
>
> 1. 检查 nginx 错误日志文件，看看是否有错误。注意须确保你的 error_log
> 配置指令本置正确，以免过滤掉直接重要的错误消息。建议使用 error_log logs/error.log warn; 级别。
>
> 2. 确保不是你的接收后端的问题。
>
> 3. 配置 periodic_flush 选项。
>
>> 我试过用 ncat 测试，ncat 好像容易死掉没有响应，不知道是不是用法有问题。
>>
>
> netcat 根本受不了并发，不要用它来测试。你倒可以考虑使用 syslog-ng 进行测试。
>
> Regards,
> -agentzh
>
> --
>

doujiang24

写超时，基本就是你的后端接收太慢，跟不上发送的节奏

至于部分数据会重复，原因可能是这样子的：

resty.logger.socket 是批量发的，发送超时是会重试的，重试是全部重试

建议换靠谱的后端服务测试

在 2015年7月2日上午10:46，wd <...@wdicc.com>写道：

我重新编译了一个 nginx，然后测试了一下。我的测试环境可能还有些问题。先看看结果把。有问题的地方麻烦指出来我改进下再测试。

nginx.conf 如下

worker_processes 5;
error_log logs/error.log info;

events {
worker_connections 1024;
}

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

sendfile on;

keepalive_timeout 65;

lua_package_path "/opt/ngx/nginx/lua/?.lua;/opt/vpas-qp/lib/?.lua";

server {
listen 8099;
server_name localhost;

location / {
root html;
index index.html index.htm;
}

location /log {
resolver 127.0.0.1;
echo "OK";
log_by_lua_file /opt/ngx/nginx/lua/log.lua;
}

error_page 500 502 503 504 /50x.html;
location = /50x.html {
root html;
}
}
}

/opt/ngx/nginx/lua/log.lua 如下

local logger = require "resty.logger.socket"
local uuid = require "uuid" -- 这个是从网上找的，应该就是论坛哥们写的
https://groups.google.com/forum/#!topic/openresty/lOGAkkc3Zk0

if not logger.initted() then
local ok, err = logger.init{
host = 'abc.com',
port = 41419,
flush_limit = 40960,
drop_limit = 104857600,
periodic_flush = 10,
}
if not ok then
ngx.log(ngx.ERR, "failed to initialize the logger: ",
err)
return
end
end

-- construct the custom access log message in
-- the Lua variable "msg"
local uid = uuid.gen_uuid()
local msg = uid .. "\ttests sdf sdf s df sdf sdf s df sdf s f se wf sd
fs df sdf sdf s dfs f we sdf s df sdf sdf s dfs df sdf we f sdf sf sd
fs fs f sdf sf \n"

ngx.log(ngx.ERR, msg)

local bytes, err = logger.log(msg)
if err then
ngx.log(ngx.ERR, "failed to log message: ", err)
return
end

远端收集机器 abc.com 上面跑了个 flume，配置如下，netcat 协议监听端口，然后保存到本地文件。

a1.channels = ch2
a1.sources = avro-source2
a1.sinks = s2

####
a1.channels.ch2.type = file
a1.channels.ch2.checkpointDir =/export/tmp/wd/checkpoint
a1.channels.ch2.dataDirs = /export/tmp/wd/data

a1.sources.avro-source2.channels = ch2
a1.sources.avro-source2.type = netcat
a1.sources.avro-source2.bind = 0.0.0.0
a1.sources.avro-source2.port = 41419
a1.sources.avro-source2.ack-every-event = false
a1.sources.avro-source2.max-line-length = 10240000

a1.sinks.s2.type = file_roll
a1.sinks.s2.channel = ch2
a1.sinks.s2.sink.rollInterval = 0
a1.sinks.s2.sink.directory = /export/tmp/test_log/

使用 http load 压力测试，命令和结果如下, url 里面就一行 http://localhost:8099/log
./http_load -r 100 -p 2 -s 10 ../url
80364 fetches, 2 max parallel, 241092 bytes, in 10 seconds
3 mean bytes/connection
8036.4 fetches/sec, 24109.2 bytes/sec
msecs/connect: 0.0281634 mean, 2.413 max, 0 min
msecs/first-response: 0.205608 mean, 13.234 max, 0.012 min
HTTP response codes:
code 200 -- 80364

flume 那边收到的数据量

$ wc -l 1435803593030-1
110928 1435803593030-1

我排序 count 了一下，有些数据是重复收到的，最大的是 5 个重复的，还有 4 个 3 个等的情况

5 7b585137-5e15-4951-9cc9-423800f380f9
5 7af542a7-d66f-4aab-9c2b-85708b95b747
5 7a90cf4e-7deb-4279-8869-4c3ef3a0d468
5 74286718-2266-43a7-9942-a841c6abfdf6
5 704c9994-2a39-417a-9f13-8a7f8cf0c37f
5 6f705f0a-1f5b-42d3-bc00-3d0e611752d0
5 6f273265-64d6-4cf7-a3a0-4b3aebc8a01b
5 6bd02d75-ac6f-49f8-9639-6d5be1a61021
5 6740315a-3fa2-4204-b633-5e90097c6777
5 665a45c4-3ab0-4392-8293-0f215330a3a7
5 6614c447-3423-4ccd-9b17-290fa3348622
5 6127458d-6033-4993-8226-3a8383da8f8f
5 601d377a-7869-435b-a513-58946c0f516b

去重之后算了一下，

$ awk '{print $1}' 1435803593030-1 | sort | uniq -c | sort -nr | wc -l
79102

nginx 的错误日志里面有这些信息

2015/07/02 10:20:21 [error] 28890#0: lua tcp socket write timed out,
context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:8099
2015/07/02 10:20:22 [error] 28890#0: lua tcp socket write timed out,
context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:8099
2015/07/02 10:20:30 [error] 28890#0: lua tcp socket write timed out,
context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:8099
2015/07/02 10:20:31 [error] 28887#0: lua tcp socket write timed out,
context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:8099
2015/07/02 10:20:32 [error] 28887#0: lua tcp socket write timed out,
context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:8099

那个 log.lua 有一行 ngx.log(ngx.ERR, msg) 会把消息记录再 nginx 的错误日志一份，这个数量和
http_load 的发送请求的数量一致。

目前我没有办法排查是 flume 的问题，还是 resty.logger.socket 的问题，有啥好办法么？用 syslog-ng ?

2015-06-30 19:48 GMT+08:00 Yichun Zhang (agentzh) <age...@gmail.com>:
> Hello!
>
> 2015-06-30 18:31 GMT+08:00 wd:
>> 我多做了几次测试。每次都是重启服务。
>>
>> 304418 208464
>> 302811 206740
>>
>> 丢失大概 30%
>>
>
> 几个建议：
>
> 1. 检查 nginx 错误日志文件，看看是否有错误。注意须确保你的 error_log
> 配置指令本置正确，以免过滤掉直接重要的错误消息。建议使用 error_log logs/error.log warn; 级别。
>
> 2. 确保不是你的接收后端的问题。
>
> 3. 配置 periodic_flush 选项。
>
>> 我试过用 ncat 测试，ncat 好像容易死掉没有响应，不知道是不是用法有问题。
>>
>
> netcat 根本受不了并发，不要用它来测试。你倒可以考虑使用 syslog-ng 进行测试。
>
> Regards,
> -agentzh
>
> --
>
--

wd

2015-07-02 21:06 GMT+08:00 DeJiang Zhu <douj...@gmail.com>:
> 写超时，基本就是你的后端接收太慢，跟不上发送的节奏
>
> 至于部分数据会重复，原因可能是这样子的：
>
> resty.logger.socket 是批量发的，发送超时是会重试的，重试是全部重试
>
> 建议换靠谱的后端服务测试

你有什么靠谱的推荐么？flume 做日志收集感觉已经是属于比较成熟的方案了。。
我明天试试看 fluentd 和 syslog-ng 吧。

zoom.quiet

HEKA

在 2015年7月2日 下午11:20，wd <...@wdicc.com> 写道：
> 2015-07-02 21:06 GMT+08:00 DeJiang Zhu <douj...@gmail.com>:
>> 写超时，基本就是你的后端接收太慢，跟不上发送的节奏
>>
>> 至于部分数据会重复，原因可能是这样子的：
>>
>> resty.logger.socket 是批量发的，发送超时是会重试的，重试是全部重试
>>
>> 建议换靠谱的后端服务测试
>
> 你有什么靠谱的推荐么？flume 做日志收集感觉已经是属于比较成熟的方案了。。
> 我明天试试看 fluentd 和 syslog-ng 吧。
>
> --
> -- 
Life's Pathetic, Let's Pythonic! 人生苦短, Python是岸!
俺: http://zoomquiet.io
授: http://creativecommons.org/licenses/by-sa/2.5/cn/
怒: 冗余不做,日子甭过!备份不做,十恶不赦!
KM keep growing environment culture which promoting organization be learnning!

wd

2015-07-02 23:20 GMT+08:00 wd <...@wdicc.com>:
> 2015-07-02 21:06 GMT+08:00 DeJiang Zhu <douj...@gmail.com>:
>> 写超时，基本就是你的后端接收太慢，跟不上发送的节奏
>>
>> 至于部分数据会重复，原因可能是这样子的：
>>
>> resty.logger.socket 是批量发的，发送超时是会重试的，重试是全部重试
>>
>> 建议换靠谱的后端服务测试
>
> 你有什么靠谱的推荐么？flume 做日志收集感觉已经是属于比较成熟的方案了。。
> 我明天试试看 fluentd 和 syslog-ng 吧。

我试了一下 fluentd 的结果，好靠谱的感觉。。。懒得测试其他的了。。。先这样吧。

$ ~/http_load-14aug2014/http_load -f 500000 -p 10 ~/url 2>/dev/null
500000 fetches, 10 max parallel, 1.5e+06 bytes, in 54.7652 seconds
3 mean bytes/connection
9129.89 fetches/sec, 27389.7 bytes/sec
msecs/connect: 0.0369656 mean, 2.548 max, 0 min
msecs/first-response: 1.01564 mean, 13.896 max, 0.031 min
HTTP response codes:
code 200 -- 500000

$ wc -l sk.20150703.b519f03587600ae84.buffer ../logs/.20150703_*
38252 sk.20150703.b519f03587600ae84.buffer
38479 ../logs/.20150703_0.log
38479 ../logs/.20150703_10.log
38479 ../logs/.20150703_11.log
38479 ../logs/.20150703_1.log
38479 ../logs/.20150703_2.log
38479 ../logs/.20150703_3.log
38479 ../logs/.20150703_4.log
38479 ../logs/.20150703_5.log
38479 ../logs/.20150703_6.log
38479 ../logs/.20150703_7.log
38479 ../logs/.20150703_8.log
38479 ../logs/.20150703_9.log
500000 total

agentzh

Hello!

2015-07-02 21:06 GMT+08:00 DeJiang Zhu:
> 写超时，基本就是你的后端接收太慢，跟不上发送的节奏
> 至于部分数据会重复，原因可能是这样子的：
> resty.logger.socket 是批量发的，发送超时是会重试的，重试是全部重试
> 建议换靠谱的后端服务测试
>

我完全同意这个原因分析 :)

值得一提的是，ab 这样的压测工具总是会压到被测服务器（这里即 nginx）的吞吐量极限 [1]，而 nginx
与你的日志服务器之间的数据发送是*异步的*，所以如果日志接收后端（这里是 flume）的极限接收速度低于 nginx 的极限发送速度，则
flume 会被压垮。毕竟在异步情况下，flume 的速度差并不会让 nginx 慢下来（因为 nginx 的发送速度取决于 ab
的发送速度）。

Regards,
-agentzh

[1] 这并不同于真实的流量场景（毕竟在生产上接近吞吐量的极限便离事故不远了）。