logging via udp

[Alexander Zubkov]

Hi,

On Wed, Dec 18, 2019 at 1:01 PM Ondrej Zajicek <santiago at crfreenet.org> wrote:
>
> On Wed, Dec 18, 2019 at 09:14:43AM +0100, Alexander Zubkov wrote:
> > Hello,
> >
> > Made some dirty patch for myself to allow bird to send logs via udp.
> > But it may be useful not only for me, so posting it here. It could be
> > useful when server experiencing high IO-load. As syslog and file
> > operations in bird are blocking, it can be blocked on writing to it
> > for indefinite time, which could lead to various problems like
> > protocol timeouts. So udp logging comes in handy here. The tradeoff is
> > that we can miss some logs if they are not processed in time.
> > You can specify udp log destination like that:
> > log udp [host IP|"hostname"] [port NUMBER|"portname"] ...
>
> Hello
>
> Is this compatible with some standard for UDP logging or with other
> infrastructure (log deamons), or you just collect it using netcat?

Not sure if it is standard now. And message format could be relatively
easily converted into one. That is one of the reasons the patch is
dirty. :)
>From my experience syslog servers are mostly ok with non formatted
plain text udp messages with some issues, which are more or less
severe depending on what you do with these logs later. For example
just tested couple of them:

* syslog-ng with simple source config:

source s_net { network(ip(127.0.0.1) transport(udp) port(514)); };

It most cases it takes the message from packet, prepends it with
timestamp and hostname (ip) from which the packet was received. There
are several options of how to parse messages, though. I get logs like
those with syslog-ng:

Dec 18 21:16:51 127.0.0.1 2019-12-18 21:16:51.773 <INFO> Reconfigured
Dec 18 21:17:09 127.0.0.1 2019-12-18 21:17:09.090 <INFO> Reconfiguring
Dec 18 21:17:09 127.0.0.1 2019-12-18 21:17:09.090 <INFO> Reconfigured

* rsyslog with simple udp config:

module(load="imudp")
input(type="imudp" address="127.0.0.1" port="514")

It is also mostly ok with plaintext messages, it prepends them with
timestamp, but it tries to parse first field of the message as a
hostname. I get logs like those with rsyslog:

Dec 18 21:51:27 2019-12-18 21: 51:27.917 <INFO> Started
Dec 18 21:51:41 2019-12-18 21: 51:41.273 <INFO> Reconfiguring

There can also be issues with message splitting. If message is cut
into two packets or several messages are there in one packet. This
should be also taken into consideration when we look at the resulting
logs.

>
> One issue in the patch is that getaddrinfo() is blocking and could block
> for several seconds if you have unreachable DNS servers. The same issue
> is also in RPKI code, and we plan to add some asynchronous resolver, so
> no need to handle it in this patch.

Yes, you are right. It can block in that place. But on the other hand
it is at reload only, i.e. at controllable points in time. And I also
hope that if I use plain IP address there, it will not use DNS for it.

>
> We already experienced issues related to excsessive logging, another
> neat solution is to log to (length-limited) file on ramfs.
>
> --
> Elen sila lumenn' omentielvo
>
> Ondrej 'Santiago' Zajicek (email: santiago at crfreenet.org)
> OpenPGP encrypted e-mails preferred (KeyID 0x11DEADC3, wwwkeys.pgp.net)
> "To err is human -- to blame it on a computer is even more so."