Vector: Support syslog rfc 3164

[fcantournet]

My use case : I want to use vector to parse & ship my json (custom)-formatted nginx logs.

Sadly vector support RFC 5424 and nginx only RFC 3164.
Are there plans to add support for the older RFC 3164 ?

[binarylogic]

Hi @fcantournet, what source type are you using? I assume you're using the syslog source. Have you tried the regex_parser transform? It would allow you to specify custom parsing regex's, including RFC 3164.

[fcantournet]

What source would I use in that case ? tcp ?
I'm don't think nginx supports syslog over tcp :/

I see there is a udp source discussed in issues and also a suggested transform called parser with the different syslog format suggested here :
https://github.com/timberio/vector/issues/334

Is this something you still want to pursue ?

In general I agree with you that syslog 3164 is a very simple protocol and a regexp would do the trick.
I'm just thinking a custom parser is rust will clearly perform better.

EDIT: ok I found the PR for UDP source ! great !

[binarylogic]

Hm. You should be able to connect the regex_parser transform to any source you define:

[sources.my_source_id]
  type = "syslog"
  # ...

[transforms.my_transform_id]
  inputs = ["my_source_id"]
  type = "regex_parser"
  regex = "..."

Would that work for you?

[fcantournet]

Hum but the syslog source is currently actually a source + parser isn't it ?
Like nginx format in rfc3164 so the massages cannot be parsed by the syslog source at the moment.
I think the new udp source from https://github.com/timberio/vector/pull/738 + regexp parser would work on the other hand.

Once this is released I'll switch to that, but for the moment I'm going to use file.
I might be able to work on a moving the parsing of syslog in a transform (and support both rfc) too. Will come back to you on that.

[binarylogic]

Correct, but that does not mean you can't additionally parse the message field. The vector transforms are meant to be chainable. The event leaving the syslog source will be sometihng like:

{
  "host": "...",
  "message": "..."
}

You can see an example here:

https://docs.vector.dev/usage/configuration/sources/syslog#examples

[fcantournet]

Yes I see this, it's actually what I wanted to do :
My Nginx outputs a syslog (rfc3614) log with message containing a json.
I wanted to chain syslog -> json.

The problem is the current syslog source drops all my message because it fails to parse, because rfc5424 is not compatible with rfc3614.
That is why I need a raw UDP + regexp parsing the rfc3614 or better yet a native rfc3614 parser.

[binarylogic]

The problem is the current syslog source drops all my message because it fails to parse, because rfc5424 is not compatible with rfc3614.

Hm, it shouldn't be dropping your message. I'll open a follow up issue to address that.

[kirillt]

@fcantournet As a workaround, if your system uses rsyslog (most probably if you use linux), you can pipe Nginx logs into Vector through it. This way Vector outputs something like this:

{"host":"206.81.29.115:49790","timestamp":"2019-09-01T15:59:34.350512Z","message":"<190>1 2019-09-01T15:59:34.350512+00:00 centos7 journal - - - centos7 nginx: ::1 - - [01/Sep/2019:15:59:34 +0000] \"GET /poweredby.png HTTP/1.1\" 304 0 \"http://localhost/\" \"Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101 Firefox/60.0\""}

The recipe is the following:

1. Put access_log syslog:server=unix:/dev/log,tag=nginx,severity=info combined; into /etc/nginx/nginx.conf.
2. Put action(type="omfwd" Target="0.0.0.0" Port="10514" Protocol="udp" Device="eth0" Template="RSYSLOG_SyslogProtocol23Format") into /etc/rsyslog.conf, this line is version for receiving events via UDP.
3. Configure Vector for receiving events via syslog sink with UDP on port 10514.

Here, piece of the config with Template is very important, it seems that only RSYSLOG_SyslogProtocol23Format corresponds to RFC 5424.

Would be glad if this recipe works for your use-case.
I'm continuing to investigate this issue in the meanwhile.

[binarylogic]

Noting, to close this issue we need to:

• [x] Log when messages are dropped (should be rate limited)
• [x] Explicitly note in the syslog source docs that 3164 is not supported and provide alternative solutions.
• [x] Add warning in docs that 3164 is not supported.

[binarylogic]

Just updating here. Even though the Syslog 3164 RFC is not a specification, we can try to support common formats. Looking at other tools, these regular expressions should solve our usecase:

RFC 3164 (local):

^\<(?<pri>[0-9]+)\>(?<time>[^ ]* {1,2}[^ ]* [^ ]*) (?<ident>[a-zA-Z0-9_\/\.\-]*)(?:\[(?<pid>[0-9]+)\])?(?:[^\:]*\:)? *(?<message>.*)$

And RFC 3164:

/^\<(?<pri>[0-9]+)\>(?<time>[^ ]* {1,2}[^ ]* [^ ]*) (?<host>[^ ]*) (?<ident>[a-zA-Z0-9_\/\.\-]*)(?:\[(?<pid>[0-9]+)\])?(?:[^\:]*\:)? *(?<message>.*)$/

If we can support the above formats I think we can close this.

[nezed]

@kirillt Thanks for interesting workaround! It helped me with collecting logs from clickhouse.
For some reason logs Template="RSYSLOG_SyslogProtocol23Format" are not parsed by vector, but with RSYSLOG_TraditionalForwardFormat it is.

Also i've removed Device="eth0" because my setup uses different interface and this setting leads to following error for me:

create UDP socket bound to device failed: Operation not permitted [v8.32.0]
No UDP socket could successfully be initialized, some functionality may be disabled.  [v8.32.0]

[email protected]
[email protected]

[lukesteensen]

@nezed Do you have an example log line of that format on hand that isn't parsing? We'd love to improve our parser to be able to handle it.

[nezed]

@lukesteensen Sure
For this example i've used following vector.toml config:

data_dir = "/var/lib/vector"

[sources.ch_source]
  type = "syslog"
  address = "0.0.0.0:10514"
  mode = "udp"

[sinks.my_sink_id]
  type = "file"
  inputs = ["ch_source"]
  path = "/var/lib/vector/%Y-%m-%d.log"
  encoding.codec = "ndjson"

Some lines from sink file when sending logs directly to vector:

1. Looks like it was partially parsed but i don't know how to get source message
   json { "facility": "user", "host": "ch-ansible-temp-test-ds.smedc.local.", "message": "2020.05.21 22:36:38.066901 [ 7319 ] {} <Information> Application: Loading metadata from /var/lib/clickhouse/", "msgid": "Application", "procid": 7319, "severity": "info", "source_type": "syslog", "timestamp": "2020-05-21T19:36:38.066Z", "version": 1 }

1. Wasn't parsed
   json { "host": "127.0.0.1:35600", "message": "<11>1 2020-05-21T19:32:12.581Z ch-ansible-temp-test-ds.smedc.local. - 6993 void DB::SystemLog<LogElement>::flushImpl(const std::__1::vector<_Tp>&, uint64_t) [with LogElement = DB::TraceLogElement; uint64_t = long unsigned int] - 2020.05.21 22:32:12.581185 [ 7045 ] {} <Error> void DB::SystemLog<LogElement>::flushImpl(const std::__1::vector<_Tp>&, uint64_t) [with LogElement = DB::TraceLogElement; uint64_t = long unsigned int]: Code: 62, e.displayText() = DB::Exception: Syntax error (Storage to create table for TraceLog): failed at position 229 (line 7, col 13): TTL toStartOfMonth(event_date) + INTERVAL 2 MONTH DELETE\n . Expected one of: number, literal, NULL, Stack trace (when copying this message, always include the lines below):\n\n0. Poco::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int) @ 0x10406ef0 in /usr/bin/clickhouse\n1. DB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int) @ 0x8ff88ad in /usr/bin/clickhouse\n2. ? @ 0xdf5007d in /usr/bin/clickhouse\n3. DB::SystemLog<DB::TraceLogElement>::getCreateTableQuery() @ 0x906e1cb in /usr/bin/clickhouse\n4. DB::SystemLog<DB::TraceLogElement>::prepareTable() @ 0x9071e25 in /usr/bin/clickhouse\n5. DB::SystemLog<DB::TraceLogElement>::flushImpl(std::__1::vector<DB::TraceLogElement, std::__1::allocator<DB::TraceLogElement> > const&, unsigned long) @ 0x9079fa2 in /usr/bin/clickhouse\n6. DB::SystemLog<DB::TraceLogElement>::savingThreadFunction() @ 0x907c5b3 in /usr/bin/clickhouse\n7. ThreadFromGlobalPool::ThreadFromGlobalPool<DB::SystemLog<DB::TraceLogElement>::startup()::'lambda'()>(DB::TraceLogElement&&, DB::SystemLog<DB::TraceLogElement>::startup()::'lambda'()&&...)::'lambda'()::operator()() const @ 0x907c7a6 in /usr/bin/clickhouse\n8. ThreadPoolImpl<std::__1::thread>::worker(std::__1::__list_iterator<std::__1::thread, void*>) @ 0x901e26b in /usr/bin/clickhouse\n9. ? @ 0x901c753 in /usr/bin/clickhouse\n10. start_thread @ 0x76db in /lib/x86_64-linux-gnu/libpthread-2.27.so\n11. clone @ 0x12188f in /lib/x86_64-linux-gnu/libc-2.27.so\n (version 20.4.2.9 (official build))", "source_type": "syslog", "timestamp": "2020-05-21T19:32:12.581329579Z" }

Some lines from sink file when sending logs to vector via rsyslog with following additions in /etc/rsyslog.conf:

# provides UDP syslog reception
module(load="imudp")
input(type="imudp" port="514")

# Redirect syslogs to vector in matching format
action(type="omfwd" Target="0.0.0.0" Port="10514" Protocol="udp" Template="RSYSLOG_TraditionalForwardFormat")
$SpaceLFOnReceive on
$EscapeControlCharactersOnReceive off
$DropTrailingLFOnReception off

1. Partially parsed, same as above
   json { "appname": "-", "facility": "user", "host": "ch-ansible-temp-test-ds.smedc.local.", "message": "2020.05.21 22:43:16.450445 [ 7485 ] {} <Information> Application: Loading metadata from /var/lib/clickhouse/", "procid": 7485, "severity": "info", "source_type": "syslog", "timestamp": "2020-05-21T19:43:16Z" }
2. Partially parsed - better than before
   json { "appname": "-", "facility": "user", "host": "ch-ansible-temp-test-ds.smedc.local.", "message": "DB::SystemLog<LogElement>::flushImpl(const std::__1::vector<_Tp>&, uint64_t) [with LogElement = DB::TraceLogElement; uint64_t = long unsigned int] - 2020.05.21 22:43:46.542823 [ 7532 ] {} <Error> void DB::SystemLog<LogElement>::flushImpl(const std::__1::vector<_Tp>&, uint64_t) [with LogElement = DB::TraceLogElement; uint64_t = long unsigned int]: Code: 62, e.displayText() = DB::Exception: Syntax error (Storage to create table for TraceLog): failed at position 229 (line 7, col 13): TTL toStartOfMonth(event_date) + INTERVAL 2 MONTH DELETE . Expected one of: number, literal, NULL, Stack trace (when copying this message, always include the lines below): 0. Poco::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int) @ 0x10406ef0 in /usr/bin/clickhouse 1. DB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int) @ 0x8ff88ad in /usr/bin/clickhouse 2. ? @ 0xdf5007d in /usr/bin/clickhouse 3. DB::SystemLog<DB::TraceLogElement>::getCreateTableQuery() @ 0x906e1cb in /usr/bin/clickhouse 4. DB::SystemLog<DB::TraceLogElement>::prepareTable() @ 0x9071e25 in /usr/bin/clickhouse 5. DB::SystemLog<DB::TraceLogElement>::flushImpl(std::__1::vector<DB::TraceLogElement, std::__1::allocator<DB::TraceLogElement> > const&, unsigned long) @ 0x9079fa2 in /usr/bin/clickhouse 6. DB::SystemLog<DB::TraceLogElement>::savingThreadFunction() @ 0x907c5b3 in /usr/bin/clickhouse 7. ThreadFromGlobalPool::ThreadFromGlobalPool<DB::SystemLog<DB::TraceLogElement>::startup()::'lambda'()>(DB::TraceLogElement&&, DB::SystemLog<DB::TraceLogElement>::startup()::'lambda'()&&...)::'lambda'()::operator()() const @ 0x907c7a6 in /usr/bin/clickhouse 8. ThreadPoolImpl<std::__1::thread>::worker(std::__1::__list_iterator<std::__1::thread, void*>) @ 0x901e26b in /usr/bin/clickhouse 9. ? @ 0x901c753 in /usr/bin/clickhouse 10. start_thread @ 0x76db in /lib/x86_64-linux-gnu/libpthread-2.27.so 11. clone @ 0x12188f in /lib/x86_64-linux-gnu/libc-2.27.so (version 20.4.2.9 (official build))", "procid": 7485, "severity": "err", "source_type": "syslog", "timestamp": "2020-05-21T19:43:46Z" }

You can reproduce it with default configuration and any clickhouse-server package (docker, deb, etc) by overriding following sections in default /etc/clickhouse-server/config.xml:

<yandex>
    <logger>
        <!-- Override whole section contents -->
        <level>information</level>
        <log>/var/log/clickhouse-server/clickhouse-server.log</log>
        <errorlog>/var/log/clickhouse-server/clickhouse-server.err.log</errorlog>
        <size>100M</size>
        <count>10</count>

        <use_syslog>1</use_syslog>
        <syslog>
            <address>127.0.0.1:10514</address>
            <facility>LOG_DAEMON</facility> <!-- or SYSLOG_USER -->
            <format>syslog</format>
        </syslog>
    </logger>

    <trace_log>
        <!-- Override whole section contents -->
        <database>system</database>
        <table>trace_log</table>

        <!-- The SETTING and TTL are in wrong order -->
        <engine>
            ENGINE = MergeTree
            PARTITION BY toYYYYMM(event_date)
            ORDER BY (event_date, event_time)
            SETTINGS min_bytes_for_wide_part = '10M', index_granularity = 8192
            TTL toStartOfMonth(event_date) + INTERVAL 2 MONTH DELETE
        </engine>
        <flush_interval_milliseconds>7500</flush_interval_milliseconds>
    </trace_log>
</yandex>

(If you don't have error messages immediately after startup then try DROP TABLE system.trace_log)

[email protected]
[email protected]
[email protected] (deb)

[lukesteensen]

Thanks @nezed! That's very helpful.

[FungusHumungus]

So it looks like the message I can see above:

<11>1 2020-05-21T19:32:12.581Z ch-ansible-temp-test-ds.smedc.local. - 6993 void DB::Syst<...>fficial build))

doesn't have a placeholder - to indicate there is no structured data which according to rfc5424 there should be. With that placeholder it seems to parse fine.

I've raised an issue : https://github.com/FungusHumungus/syslog-loose/issues/2 to track this.

@nezed if you could post some example messages from that source so I can make sure it can handle them ok that would be much appreciated.