Custom logging with lua-resty-logger-socket

kgorlo · 2017-06-04T17:43:51+00:00

I've used https://github.com/antirez/lua-cmsgpack and thought it worked well. Once they are installed under the openresty luajit/lib directory...

Custom logging with lua-resty-logger-socket

kgorlo

Hi,

I am trying to setup custom logging with https://github.com/cloudflare/lua-resty-logger-socket altogether with https://github.com/detailyang/lua-resty-rfc5424.

Everything works, but what I see in rsyslog (in UDP mode) is that lines are mixed up.

Here is one of lines in rsyslog output file:

Jun 4 11:27:17 localhost nginx[47871]: Hello World!#012<135>Jun 04 11:27:19 localhost nginx[47871]: Hello World!

What I understand is that when lua-resty-logger-socket buffers multiple log lines it simply adds them to buffer and then sends whole buffer as one message to syslog. Syslog treats it as one line (it replaces new line with #012 and facility_severity with <135>).

What can be done to prevent this?

Cheers,

Kamil

kgorlo

Answering my own question:

https://tools.ietf.org/html/rfc5426#section-3.1

3.1.  One Message Per Datagram

   Each syslog UDP datagram MUST contain only one syslog message, which
   MAY be complete or truncated.  The message MUST be formatted and
   truncated according to RFC 5424 [2].  Additional data MUST NOT be
   present in the datagram payload.

So, change to TCP is needed (then it works). TCP is also probably better in terms of big log messages (for sure for > 1KB).

W dniu niedziela, 4 czerwca 2017 11:43:51 UTC+2 użytkownik Kamil Gorlo napisał:

Hi,

I am trying to setup custom logging with https://github.com/cloudflare/lua-resty-logger-socket altogether with https://github.com/detailyang/lua-resty-rfc5424.

Everything works, but what I see in rsyslog (in UDP mode) is that lines are mixed up.

Here is one of lines in rsyslog output file:

>>
Jun 4 11:27:17 localhost nginx[47871]: Hello World!#012<135>Jun 04 11:27:19 localhost nginx[47871]: Hello World!
<<

What I understand is that when lua-resty-logger-socket buffers multiple log lines it simply adds them to buffer and then sends whole buffer as one message to syslog. Syslog treats it as one line (it replaces new line with #012 and facility_severity with <135>).

What can be done to prevent this?

Cheers,
Kamil

detailyang

Hello.

What's your server rsyslog version ? my rsyslog version is
rsyslog-7.4.7-16.el7.x86_64 on Centos7. lua-resty-rfc5424 explicitly
append '\n" to allow rsyslog split the multi message in udp packet.

2017-06-04 17:43 GMT+08:00 Kamil Gorlo <kg...@gmail.com>:
> Hi,
>
> I am trying to setup custom logging with
> https://github.com/cloudflare/lua-resty-logger-socket altogether with
> https://github.com/detailyang/lua-resty-rfc5424.
>
> Everything works, but what I see in rsyslog (in UDP mode) is that lines are
> mixed up.
>
> Here is one of lines in rsyslog output file:
>
>>>
> Jun  4 11:27:17 localhost nginx[47871]: Hello World!#012<135>Jun 04 11:27:19
> localhost nginx[47871]: Hello World!
> <<
>
> What I understand is that when lua-resty-logger-socket buffers multiple log
> lines it simply adds them to buffer and then sends whole buffer as one
> message to syslog. Syslog treats it as one line (it replaces new line with
> #012 and facility_severity with <135>).
>
> What can be done to prevent this?
>
> Cheers,
> Kamil.

kgorlo

I have exact the same version of rsyslog.

I know that lua-resty-rfc5424 explicitly adds '\n'. In fact you can see it in my example (#012). But as stated in RFC, in UDP mode it looks that rsyslog expects only one message per datagram.

When I change mode to TCP then everything works (also thanks to this '\n').

pon., 5 cze 2017 o 05:52 użytkownik Bingwu Yang <deta...@gmail.com> napisał:

Hello.

What's your server rsyslog version ? my rsyslog version is
rsyslog-7.4.7-16.el7.x86_64 on Centos7. lua-resty-rfc5424 explicitly
append '\n" to allow rsyslog split the multi message in udp packet.

2017-06-04 17:43 GMT+08:00 Kamil Gorlo <kg...@gmail.com>:
> Hi,
>
> I am trying to setup custom logging with
> https://github.com/cloudflare/lua-resty-logger-socket altogether with
> https://github.com/detailyang/lua-resty-rfc5424.
>
> Everything works, but what I see in rsyslog (in UDP mode) is that lines are
> mixed up.
>
> Here is one of lines in rsyslog output file:
>
>>>
> Jun 4 11:27:17 localhost nginx[47871]: Hello World!#012<135>Jun 04 11:27:19
> localhost nginx[47871]: Hello World!
> <<
>
> What I understand is that when lua-resty-logger-socket buffers multiple log
> lines it simply adds them to buffer and then sends whole buffer as one
> message to syslog. Syslog treats it as one line (it replaces new line with
> #012 and facility_severity with <135>).
>
> What can be done to prevent this?
>
> Cheers,
> Kamil.

detailyang

Well. RFC-5426 said Each syslog UDP datagram MUST contain only one
syslog message. However, in my production rsyslog allow  UDP datagram
with multiple messags.

Or you can set flush_limit to 0, force lua-resty-logger send message
every time :)



2017-06-05 14:54 GMT+08:00 Kamil Gorlo <kg...@gmail.com>:
> I have exact the same version of rsyslog.
>
> I know that lua-resty-rfc5424 explicitly adds '\n'. In fact you can see it
> in my example (#012). But as stated in RFC, in UDP mode it looks that
> rsyslog expects only one message per datagram.
>
> When I change mode to TCP then everything works (also thanks to this '\n').
>
> pon., 5 cze 2017 o 05:52 użytkownik Bingwu Yang <deta...@gmail.com>
> napisał:
>>
>> Hello.
>>
>> What's your server rsyslog version ? my rsyslog version is
>> rsyslog-7.4.7-16.el7.x86_64 on Centos7. lua-resty-rfc5424 explicitly
>> append '\n" to allow rsyslog split the multi message in udp packet.
>>
>> 2017-06-04 17:43 GMT+08:00 Kamil Gorlo <kg...@gmail.com>:
>> > Hi,
>> >
>> > I am trying to setup custom logging with
>> > https://github.com/cloudflare/lua-resty-logger-socket altogether with
>> > https://github.com/detailyang/lua-resty-rfc5424.
>> >
>> > Everything works, but what I see in rsyslog (in UDP mode) is that lines
>> > are
>> > mixed up.
>> >
>> > Here is one of lines in rsyslog output file:
>> >
>> >>>
>> > Jun  4 11:27:17 localhost nginx[47871]: Hello World!#012<135>Jun 04
>> > 11:27:19
>> > localhost nginx[47871]: Hello World!
>> > <<
>> >
>> > What I understand is that when lua-resty-logger-socket buffers multiple
>> > log
>> > lines it simply adds them to buffer and then sends whole buffer as one
>> > message to syslog. Syslog treats it as one line (it replaces new line
>> > with
>> > #012 and facility_severity with <135>).
>> >
>> > What can be done to prevent this?
>> >
>> > Cheers,
>> > Kamil.

kgorlo

So, how it works in YOUR production? :)

pon., 5 cze 2017 o 09:24 użytkownik Bingwu Yang <deta...@gmail.com> napisał:

Well. RFC-5426 said Each syslog UDP datagram MUST contain only one
syslog message. However, in my production rsyslog allow UDP datagram
with multiple messags.

Or you can set flush_limit to 0, force lua-resty-logger send message
every time :)

2017-06-05 14:54 GMT+08:00 Kamil Gorlo <kg...@gmail.com>:
> I have exact the same version of rsyslog.
>
> I know that lua-resty-rfc5424 explicitly adds '\n'. In fact you can see it
> in my example (#012). But as stated in RFC, in UDP mode it looks that
> rsyslog expects only one message per datagram.
>
> When I change mode to TCP then everything works (also thanks to this '\n').
>
> pon., 5 cze 2017 o 05:52 użytkownik Bingwu Yang <deta...@gmail.com>
> napisał:
>>
>> Hello.
>>
>> What's your server rsyslog version ? my rsyslog version is
>> rsyslog-7.4.7-16.el7.x86_64 on Centos7. lua-resty-rfc5424 explicitly
>> append '\n" to allow rsyslog split the multi message in udp packet.
>>
>> 2017-06-04 17:43 GMT+08:00 Kamil Gorlo <kg...@gmail.com>:
>> > Hi,
>> >
>> > I am trying to setup custom logging with
>> > https://github.com/cloudflare/lua-resty-logger-socket altogether with
>> > https://github.com/detailyang/lua-resty-rfc5424.
>> >
>> > Everything works, but what I see in rsyslog (in UDP mode) is that lines
>> > are
>> > mixed up.
>> >
>> > Here is one of lines in rsyslog output file:
>> >
>> >>>
>> > Jun 4 11:27:17 localhost nginx[47871]: Hello World!#012<135>Jun 04
>> > 11:27:19
>> > localhost nginx[47871]: Hello World!
>> > <<
>> >
>> > What I understand is that when lua-resty-logger-socket buffers multiple
>> > log
>> > lines it simply adds them to buffer and then sends whole buffer as one
>> > message to syslog. Syslog treats it as one line (it replaces new line
>> > with
>> > #012 and facility_severity with <135>).
>> >
>> > What can be done to prevent this?
>> >
>> > Cheers,
>> > Kamil.

detailyang

Well. I check the production again. And make a mistake, the
lua-resty-logger-socket's type is default tcp rather than udp. I'm so
sorry for misleading you.
My production config is as the following:

1. TCP with appropriate flush_limit which depends your env
2. UDP with flush_limit = 0, But  you should notice the UDP datagram
max length is 2 ^ 16

Almost is TCP because people requires do not  lost  message event if
is in LAN. Wish it can help you :)

2017-06-05 15:26 GMT+08:00 Kamil Gorlo <kg...@gmail.com>:
> So, how it works in YOUR production? :)
>
> pon., 5 cze 2017 o 09:24 użytkownik Bingwu Yang <deta...@gmail.com>
> napisał:
>>
>> Well. RFC-5426 said Each syslog UDP datagram MUST contain only one
>> syslog message. However, in my production rsyslog allow  UDP datagram
>> with multiple messags.
>>
>> Or you can set flush_limit to 0, force lua-resty-logger send message
>> every time :)
>>
>>
>>
>> 2017-06-05 14:54 GMT+08:00 Kamil Gorlo <kg...@gmail.com>:
>> > I have exact the same version of rsyslog.
>> >
>> > I know that lua-resty-rfc5424 explicitly adds '\n'. In fact you can see
>> > it
>> > in my example (#012). But as stated in RFC, in UDP mode it looks that
>> > rsyslog expects only one message per datagram.
>> >
>> > When I change mode to TCP then everything works (also thanks to this
>> > '\n').
>> >
>> > pon., 5 cze 2017 o 05:52 użytkownik Bingwu Yang <deta...@gmail.com>
>> > napisał:
>> >>
>> >> Hello.
>> >>
>> >> What's your server rsyslog version ? my rsyslog version is
>> >> rsyslog-7.4.7-16.el7.x86_64 on Centos7. lua-resty-rfc5424 explicitly
>> >> append '\n" to allow rsyslog split the multi message in udp packet.
>> >>
>> >> 2017-06-04 17:43 GMT+08:00 Kamil Gorlo <kg...@gmail.com>:
>> >> > Hi,
>> >> >
>> >> > I am trying to setup custom logging with
>> >> > https://github.com/cloudflare/lua-resty-logger-socket altogether with
>> >> > https://github.com/detailyang/lua-resty-rfc5424.
>> >> >
>> >> > Everything works, but what I see in rsyslog (in UDP mode) is that
>> >> > lines
>> >> > are
>> >> > mixed up.
>> >> >
>> >> > Here is one of lines in rsyslog output file:
>> >> >
>> >> >>>
>> >> > Jun  4 11:27:17 localhost nginx[47871]: Hello World!#012<135>Jun 04
>> >> > 11:27:19
>> >> > localhost nginx[47871]: Hello World!
>> >> > <<
>> >> >
>> >> > What I understand is that when lua-resty-logger-socket buffers
>> >> > multiple
>> >> > log
>> >> > lines it simply adds them to buffer and then sends whole buffer as
>> >> > one
>> >> > message to syslog. Syslog treats it as one line (it replaces new line
>> >> > with
>> >> > #012 and facility_severity with <135>).
>> >> >
>> >> > What can be done to prevent this?
>> >> >
>> >> > Cheers,
>> >> > Kamil.

kgorlo

Ok, makes sense now, thanks!

pon., 5 cze 2017 o 09:41 użytkownik Bingwu Yang <deta...@gmail.com> napisał:

Well. I check the production again. And make a mistake, the
lua-resty-logger-socket's type is default tcp rather than udp. I'm so
sorry for misleading you.
My production config is as the following:

1. TCP with appropriate flush_limit which depends your env
2. UDP with flush_limit = 0, But you should notice the UDP datagram
max length is 2 ^ 16

Almost is TCP because people requires do not lost message event if
is in LAN. Wish it can help you :)

2017-06-05 15:26 GMT+08:00 Kamil Gorlo <kg...@gmail.com>:
> So, how it works in YOUR production? :)
>
> pon., 5 cze 2017 o 09:24 użytkownik Bingwu Yang <deta...@gmail.com>
> napisał:
>>
>> Well. RFC-5426 said Each syslog UDP datagram MUST contain only one
>> syslog message. However, in my production rsyslog allow UDP datagram
>> with multiple messags.
>>
>> Or you can set flush_limit to 0, force lua-resty-logger send message
>> every time :)
>>
>>
>>
>> 2017-06-05 14:54 GMT+08:00 Kamil Gorlo <kg...@gmail.com>:
>> > I have exact the same version of rsyslog.
>> >
>> > I know that lua-resty-rfc5424 explicitly adds '\n'. In fact you can see
>> > it
>> > in my example (#012). But as stated in RFC, in UDP mode it looks that
>> > rsyslog expects only one message per datagram.
>> >
>> > When I change mode to TCP then everything works (also thanks to this
>> > '\n').
>> >
>> > pon., 5 cze 2017 o 05:52 użytkownik Bingwu Yang <deta...@gmail.com>
>> > napisał:
>> >>
>> >> Hello.
>> >>
>> >> What's your server rsyslog version ? my rsyslog version is
>> >> rsyslog-7.4.7-16.el7.x86_64 on Centos7. lua-resty-rfc5424 explicitly
>> >> append '\n" to allow rsyslog split the multi message in udp packet.
>> >>
>> >> 2017-06-04 17:43 GMT+08:00 Kamil Gorlo <kg...@gmail.com>:
>> >> > Hi,
>> >> >
>> >> > I am trying to setup custom logging with
>> >> > https://github.com/cloudflare/lua-resty-logger-socket altogether with
>> >> > https://github.com/detailyang/lua-resty-rfc5424.
>> >> >
>> >> > Everything works, but what I see in rsyslog (in UDP mode) is that
>> >> > lines
>> >> > are
>> >> > mixed up.
>> >> >
>> >> > Here is one of lines in rsyslog output file:
>> >> >
>> >> >>>
>> >> > Jun 4 11:27:17 localhost nginx[47871]: Hello World!#012<135>Jun 04
>> >> > 11:27:19
>> >> > localhost nginx[47871]: Hello World!
>> >> > <<
>> >> >
>> >> > What I understand is that when lua-resty-logger-socket buffers
>> >> > multiple
>> >> > log
>> >> > lines it simply adds them to buffer and then sends whole buffer as
>> >> > one
>> >> > message to syslog. Syslog treats it as one line (it replaces new line
>> >> > with
>> >> > #012 and facility_severity with <135>).
>> >> >
>> >> > What can be done to prevent this?
>> >> >
>> >> > Cheers,
>> >> > Kamil.