ngx.socket.tcp cannot send msg to logstash

[anjia0532]

env

host

DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=16.04
DISTRIB_CODENAME=xenial
DISTRIB_DESCRIPTION="Ubuntu 16.04.2 LTS"

logstash version 5.5.2

openresty version 1.11.2.5

openresty configure params

sudo ./configure --prefix=/etc/openresty \
--user=nginx \
--group=nginx \
--with-cc-opt='-O2 -I/usr/local/openresty/zlib/include -I/usr/local/openresty/pcre/include -I/usr/local/openresty/openssl/include' \
--with-ld-opt='-Wl,-rpath,/usr/local/openresty/luajit/lib -L/usr/local/openresty/zlib/lib -L/usr/local/openresty/pcre/lib -L/usr/local/openresty/openssl/lib -Wl,-rpath,/usr/local/openresty/zlib/lib:/usr/local/openresty/pcre/lib:/usr/local/openresty/openssl/lib' \
--with-pcre-jit \
--with-stream \
--with-stream_ssl_module \
--with-http_v2_module \
--with-http_stub_status_module \
--with-http_realip_module \
--with-http_gzip_static_module \
--with-http_sub_module \
--with-http_gunzip_module \
--with-threads \
--with-file-aio \
--with-http_ssl_module \
--with-http_auth_request_module \
--without-mail_pop3_module \
--without-mail_imap_module \
--without-mail_smtp_module \
--without-http_fastcgi_module \
--without-http_uwsgi_module \
--without-http_scgi_module \
--without-http_autoindex_module \
--without-http_memcached_module \
--without-http_empty_gif_module \
--without-http_ssi_module \
--without-http_userid_module \
--without-http_browser_module \
--without-http_rds_json_module \
--without-http_rds_csv_module \
--without-http_memc_module \
--without-http_redis2_module \
--without-lua_resty_memcached \
--without-lua_resty_mysql \
-j4

sudo make -j4 

sudo make install

nginx.conf

error_log  logs/error.log error;
pid        /var/run/nginx.pid;

worker_rlimit_nofile 10240;

events {
    worker_connections  10240; 
}


http {
    include       mime.types;    
    server {
        listen       80;
        location / {
          
                content_by_lua '
                    local sock,err = ngx.socket.tcp()
                    if not sock then
                      ngx.say("init socket has error : ",err)
                    else
                      ngx.say("init socket is ok")
                    end

                    local ok, err = sock:connect("127.0.0.1", 5044)
                    if not ok then 
                      ngx.say("create connect has error : ",err)
                    else
                      ngx.say("create connect is ",ok)
                    end

                    local bytes, err = sock:send("this is test msg")
                    
                    if not bytes then
                        ngx.say("socket send msg has error : ",err)
                    else
                        ngx.say("sended bytes size: " ,bytes)
                    end


                    local ok, err = sock:setkeepalive(0, 100)
                    if not ok then 
                       ngx.say("set keepalive has error : ",err)
                    else
                       ngx.say("set keepalive is ",ok)
                    end

                ';
        }
    }    
}

logstash conf named demo.conf

input {
    tcp {
        port => "5044"
        codec => "plain"
    }
}
output {
  stdout { codec => rubydebug }
}

./bin/logstash -f demo.conf wait for output Successfully started Logstash API endpoint {:port=>9600}

curl localhost

# openresty output
init socket is ok
create connect is 1
sended bytes size: 16
set keepalive is 1

logstash console can't output anything,

sudo tcpdump -i any -vvv -n -A port 5044
tcpdump: listening on any, link-type LINUX_SLL (Linux cooked), capture size 262144 bytes
18:36:40.188829 IP (tos 0x0, ttl 64, id 23893, offset 0, flags [DF], proto TCP (6), length 68)
    127.0.0.1.49714 > 127.0.0.1.5044: Flags [P.], cksum 0xfe38 (incorrect -> 0x8862), seq 2638081705:2638081721, ack 3382832894, win 342, options [nop,nop,TS val 2222059870 ecr 2222058789], length 16
E..D]U@.@..\.........2...=.........V.8.....
.q.^.q.%this is test msg
18:36:40.188838 IP (tos 0x0, ttl 64, id 23861, offset 0, flags [DF], proto TCP (6), length 52)
    127.0.0.1.5044 > 127.0.0.1.49714: Flags [.], cksum 0xfe28 (incorrect -> 0x7145), seq 1, ack 16, win 342, options [nop,nop,TS val 2222059870 ecr 2222059870], length 0
E..4]5@[email protected].....=.....V.(.....
.q.^.q.^
^C
2 packets captured
4 packets received by filter
0 packets dropped by kernel

wireshark has many tcp dup ack and tcp Out-Of-Order info.

curl localhost:5044

logstash console output

{
    "@timestamp" => 2017-09-08T10:33:19.254Z,
          "port" => 49710,
      "@version" => "1",
          "host" => "127.0.0.1",
       "message" => "GET / HTTP/1.1\r"
}
{
    "@timestamp" => 2017-09-08T10:33:19.257Z,
          "port" => 49710,
      "@version" => "1",
          "host" => "127.0.0.1",
       "message" => "Host: localhost:5044\r"
}
{
    "@timestamp" => 2017-09-08T10:33:19.258Z,
          "port" => 49710,
      "@version" => "1",
          "host" => "127.0.0.1",
       "message" => "User-Agent: curl/7.47.0\r"
}
{
    "@timestamp" => 2017-09-08T10:33:19.259Z,
          "port" => 49710,
      "@version" => "1",
          "host" => "127.0.0.1",
       "message" => "Accept: */*\r"
}
{
    "@timestamp" => 2017-09-08T10:33:19.259Z,
          "port" => 49710,
      "@version" => "1",
          "host" => "127.0.0.1",
       "message" => "\r"
}

telnet 127.0.0.1 5044

Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
this is test msg
^]
telnet> Connection closed.

Ctrl+] and Ctrl+D exit telnet

logstash output msg

{
    "@timestamp" => 2017-09-08T10:34:28.588Z,
          "port" => 49712,
      "@version" => "1",
          "host" => "127.0.0.1",
       "message" => "this is test msg\r"
}

[anjia0532]

duplicate cloudflare/lua-resty-logger-socket#29

[agentzh]

@anjia0532 Do you see anything in the nginx error log file? BTW, you can see more details when the nginx debugging logs are enabled.

[anjia0532]

not error log,by the tcpdump log ngx.socket.tcp are sended msg.

tcpdump: listening on any, link-type LINUX_SLL (Linux cooked), capture size 262144 bytes
18:36:40.188829 IP (tos 0x0, ttl 64, id 23893, offset 0, flags [DF], proto TCP (6), length 68)
    127.0.0.1.49714 > 127.0.0.1.5044: Flags [P.], cksum 0xfe38 (incorrect -> 0x8862), seq 2638081705:2638081721, ack 3382832894, win 342, options [nop,nop,TS val 2222059870 ecr 2222058789], length 16
E..D]U@.@..\.........2...=.........V.8.....
.q.^.q.%this is test msg
18:36:40.188838 IP (tos 0x0, ttl 64, id 23861, offset 0, flags [DF], proto TCP (6), length 52)
    127.0.0.1.5044 > 127.0.0.1.49714: Flags [.], cksum 0xfe28 (incorrect -> 0x7145), seq 1, ack 16, win 342, options [nop,nop,TS val 2222059870 ecr 2222059870], length 0
E..4]5@[email protected].....=.....V.(.....
.q.^.q.^
^C
2 packets captured
4 packets received by filter
0 packets dropped by kernel

the chinese IT blog

http://m.blog.csdn.net/chenlycly/article/details/52402945

TCP Dup ACK
TCP Out-of-Order

the ngx.socket.udp is good work, ngx.socket.tcp not (for logstash)

[anjia0532]

ping @agentzh ,

local ok, err = sock:setkeepalive(1000, 100) -- zero cannot send msg to logstash , timeout value must be >0

it worked.

[agentzh]

@anjia0532 The first argument of setkeepalive should never ever to zero. It's the max idle time in the connection pool.

[agentzh]

@anjia0532 Read the documentation.

[agentzh]

Hmm, it seems that zero actually means unlimited. Then there might be other things going on here.

[anjia0532]

yup,i read ngx.socket.tcp doc ,logstash doc and codec plugin source, but not helpful,my english is not good, i posted this issues to chinese email list https://groups.google.com/forum/?nomobile=true#!topic/openresty/icx9jcR6Ja0

[agentzh]

@anjia0532 Maybe you should try using nc on the other side to receive the TCP data? Not sure if it's something specific to your logstash server. Maybe your logstash server may send some data back, which is not expected by your Lua client code code nor the cosocket connection pool.

[agentzh]

@anjia0532 I just tried your code example on my side and everything works as expected:

    location / {
        content_by_lua '
            local sock,err = ngx.socket.tcp()
            if not sock then
              ngx.say("init socket has error : ",err)
            else
              ngx.say("init socket is ok")
            end

            local ok, err = sock:connect("127.0.0.1", 5044)
            if not ok then
              ngx.say("create connect has error : ",err)
            else
              ngx.say("create connect is ",ok)
            end

            local bytes, err = sock:send("this is test msg")

            if not bytes then
                ngx.say("socket send msg has error : ",err)
            else
                ngx.say("sended bytes size: " ,bytes)
            end


            local ok, err = sock:setkeepalive(0, 100)
            if not ok then
               ngx.say("set keepalive has error : ",err)
            else
               ngx.say("set keepalive is ",ok)
            end

        ';
    }

And then I use nc to listen on the local 5044 port with the following shell command:

nc -l -k 5044

Then I do a request to the / location:

$ curl localhost:8080/
init socket is ok
create connect is 1
sended bytes size: 16
set keepalive is 1

And on the terminal running nc, I've got

$ nc -l -k 5044
this is test msg

The test was performed on a Linux box (Fedora 24 x86_64) with the latest OpenResty.

[agentzh]

@anjia0532 Running curl for multiple times also works as expected:

$ nc -l -k 5044
this is test msgthis is test msgthis is test msg

[anjia0532]

Thank you very much for your patience. looks like logstash server's reason

[anjia0532]

@agentzh

$ nc -l -k 5044
$ echo "this is test msg" | telnet 127.0.0.1 5044
#nc output
--
this is test msg
<- there has line break
--

$ curl localhost

#nc output
--
this is test msg <- no line break
--

it will auto append line break to msg when telnet send msg.

i agree with u ,this is logstash server's reason. not ngx.socket.tcp