bug: syslog plugin looks doesn’t work

[Sn0rt]

Current Behavior

can't get the log from Syslog server.

Expected Behavior

if the router has been triggered, the syslog plugin with send the log to the syslog server.
now find nothing.

Error Logs

vector is a syslog server. and the error info as below

2023-05-06T07:14:20.986659Z ERROR source{component_kind="source" component_id=log-from-syslog-tcp component_type=syslog component_name=log-from-syslog-tcp}:connection{peer_addr=192.168.80.1:48692}: vector::internal_events::codecs: Internal log [Failed deserializing frame.] has been rate limited 1 times.
2023-05-06T07:14:20.986887Z ERROR source{component_kind="source" component_id=log-from-syslog-tcp component_type=syslog component_name=log-from-syslog-tcp}:connection{peer_addr=192.168.80.1:48692}: vector::internal_events::codecs: Failed deserializing frame. error=unable to parse input as valid syslog message error_type="parser_failed" stage="processing" internal_log_rate_limit=true

rsyslog @ ubuntu (empty log info)

Steps to Reproduce

set a router for test syslog plugin

curl -s http://127.0.0.1:9180/apisix/admin/routes/1 -H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' -X PUT -d @/Users/guohao/workspace/router/syslog.json | jq
{
  "key": "/apisix/routes/1",
  "value": {
    "plugins": {
      "syslog": {
        "timeout": 3000,
        "port": 5050,
        "name": "sys logger",
        "host": "127.0.0.1",
        "pool_size": 5,
        "sock_type": "tcp",
        "retry_delay": 1,
        "buffer_duration": 60,
        "inactive_timeout": 5,
        "include_req_body": false,
        "tls": false,
        "drop_limit": 1048576,
        "batch_max_size": 1000,
        "flush_limit": 1,
        "max_retry_count": 0
      }
    },
    "update_time": 1683357026,
    "upstream": {
      "pass_host": "pass",
      "nodes": {
        "httpbin.org": 1
      },
      "hash_on": "vars",
      "type": "roundrobin",
      "scheme": "http"
    },
    "status": 1,
    "id": "1",
    "uri": "/get",
    "priority": 0,
    "create_time": 1683354859
  }
}

test the logger server. at this phase the vector provide the syslog service.

$ logger -T -n 127.0.0.1 -P 5050 -p local0.info "Hello, World! TCP"

## check the log, the vector successfully.
{"appname":"guohao","facility":"local0","host":"m2","hostname":"m2","message":"Hello, World! TCP","severity":"info","source_ip":"192.168.80.1","source_type":"syslog","timeQuality":{"isSynced":"1","syncAccuracy":"108666","tzKnown":"1"},"timestamp":"2023-05-06T07:10:56.603303Z","version":1}

send a request for trigged the router

curl -X GET "http://127.0.0.1:9080/get?username=test" -H "accept: application/json"
{
  "args": {
    "username": "test"
  },
  "headers": {
    "Accept": "application/json",
    "Host": "127.0.0.1",
    "User-Agent": "curl/8.0.1",
    "X-Amzn-Trace-Id": "Root=1-6455fdbc-6327f1597d06515842891843",
    "X-Forwarded-Host": "127.0.0.1"
  },
  "origin": "127.0.0.1, 125.94.193.83",
  "url": "http://127.0.0.1/get?username=test"
}

check it access log for verify

$ tail -f logs/access.log
...
127.0.0.1 - - [06/May/2023:15:12:27 +0800] 127.0.0.1:9080 "GET /get?username=test HTTP/1.1" 200 351 0.799 "-" "curl/8.0.1" 34.235.32.249:80 200 0.799 "http://127.0.0.1:9080"
127.0.0.1 - - [06/May/2023:15:12:35 +0800] 127.0.0.1:9080 "GET /get?username=test HTTP/1.1" 200 351 0.831 "-" "curl/8.0.1" 3.230.204.70:80 200 0.832 "http://127.0.0.1:9080"

check the vector log and find nothing

{"appname":"guohao","facility":"local0","host":"m2","hostname":"m2","message":"Hello, World! TCP","severity":"info","source_ip":"192.168.80.1","source_type":"syslog","timeQuality":{"isSynced":"1","syncAccuracy":"108666","tzKnown":"1"},"timestamp":"2023-05-06T07:10:56.603303Z","version":1}
2023-05-06T07:14:20.986659Z ERROR source{component_kind="source" component_id=log-from-syslog-tcp component_type=syslog component_name=log-from-syslog-tcp}:connection{peer_addr=192.168.80.1:48692}: vector::internal_events::codecs: Internal log [Failed deserializing frame.] has been rate limited 1 times.
2023-05-06T07:14:20.986887Z ERROR source{component_kind="source" component_id=log-from-syslog-tcp component_type=syslog component_name=log-from-syslog-tcp}:connection{peer_addr=192.168.80.1:48692}: vector::internal_events::codecs: Failed deserializing frame. error=unable to parse input as valid syslog message error_type="parser_failed" stage="processing" internal_log_rate_limit=true

try another syslog server

install rsyslog@ubuntu server

$ logger -T -n 192.168.31.224 -P 514 -p local0.info "Hello, World! TCP"
$ tail -f /var/log/syslog
...
May  6 15:58:26 m2 guohao Hello, World! TCP (for test the rsyslog is working! this log send form develop machine

update the configure of router

curl -s http://127.0.0.1:9180/apisix/admin/routes/1 -H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' -X PUT -d @/Users/guohao/workspace/router/syslog.json | jq
{
  "key": "/apisix/routes/1",
  "value": {
    "create_time": 1683354859,
    "priority": 0,
    "id": "1",
    "update_time": 1683359830,
    "upstream": {
      "type": "roundrobin",
      "pass_host": "pass",
      "nodes": {
        "httpbin.org": 1
      },
      "scheme": "http",
      "hash_on": "vars"
    },
    "status": 1,
    "uri": "/get",
    "plugins": {
      "syslog": {
        "tls": false,
        "timeout": 3000,
        "inactive_timeout": 5,
        "batch_max_size": 1000,
        "sock_type": "tcp",
        "retry_delay": 1,
        "buffer_duration": 60,
        "host": "192.168.31.224",
        "max_retry_count": 0,
        "drop_limit": 1048576,
        "port": 514,
        "flush_limit": 1,
        "pool_size": 5,
        "include_req_body": false,
        "name": "sys logger"
      }
    }
  }
}

$ curl -X GET "http://127.0.0.1:9080/get?username=test" -H "accept: application/json"
{
  "args": {
    "username": "test"
  },
  "headers": {
    "Accept": "application/json",
    "Host": "127.0.0.1",
    "User-Agent": "curl/8.0.1",
    "X-Amzn-Trace-Id": "Root=1-645608e8-54da96a64fbf14fe72e41fa4",
    "X-Forwarded-Host": "127.0.0.1"
  },
  "origin": "127.0.0.1, 125.94.193.83",
  "url": "http://127.0.0.1/get?username=test"
}

find nothing at rsyslog

Environment

• APISIX version (run apisix version): master
• Operating system (run uname -a):
• OpenResty / Nginx version (run openresty -V or nginx -V):
• etcd version, if relevant (run curl http://127.0.0.1:9090/v1/server_info):
• APISIX Dashboard version, if relevant:
• Plugin runner version, for issues related to plugin runners:
• LuaRocks version, for installation issues (run luarocks --version):

[Sn0rt]

it looks encoding error

local function send_syslog_data(conf, log_message, api_ctx)
    local err_msg
    local res = true

    core.log.info("sending a batch logs to ", conf.host, ":", conf.port)

    -- fetch it from lrucache
    local logger, err = core.lrucache.plugin_ctx(
        lrucache, api_ctx, nil, logger_socket.new, logger_socket, {
            host = conf.host,
            port = conf.port,
            flush_limit = conf.flush_limit,
            drop_limit = conf.drop_limit,
            timeout = conf.timeout,
            sock_type = conf.sock_type,
            pool_size = conf.pool_size,
            tls = conf.tls,
        }
    )

    if not logger then
        res = false
        err_msg = "failed when initiating the sys logger processor".. err
    end

    -- reuse the logger object
    local ok, err = logger:log(core.json.encode(log_message)) // <--------- here, no syslog format
    if not ok then
        res = false
        err_msg = "failed to log message" .. err
    end

    return res, err_msg
end

reference doc:

https://stackify.com/syslog-101/