http://qs321.pair.com?node_id=1129443

MarkusLaker has asked for the wisdom of the Perl Monks concerning the following question:

I'm trying to write a program that logs events on a remote machine. I'm running on Debian Jessie and, for now, logging to my local rsyslogd. The first event always gets lost, but the second is logged normally.

A colleague running the same program against other targets says that Splunk discards the first event and a Windows-based syslog watcher reports the first event as having no usable strings.

I've narrowed it down to this test code:

#!/usr/bin/perl use warnings; use strict; use v5.10; use Sys::Syslog qw/:DEFAULT setlogsock/; setlogsock({ type => 'tcp', host => 'localhost', port => 514 }) or die "Can't set syslog socket\n"; openlog 'wombat', 'ndelay', 'local0' or die "Can't open the event log\n"; syslog 'INFO', 'First wombat event'; syslog 'INFO', 'Second wombat event'; closelog or die $!;

Am I using Sys::Syslog wrongly, or does it have a bug that causes the first event to get lost?

(I know that the man page asks us -- twice -- not to run setlogsock, but there's no other clean way to log events on a remote machine, which is part of the specification of the program I'm writing.)

Many thanks.

Replies are listed 'Best First'.
Re: Sys::Syslog skips the first event
by stevieb (Canon) on Jun 08, 2015 at 15:23 UTC

    Could it be that the first log message initializes the socket and doesn't actually do anything? What if you log a blank line before logging any data? Does that help?

    Also, can you run tcpdump in full packet mode on the remote machine and see if it is actually receiving the first log entry (perhaps it is, but not doing the right thing)?

    -stevieb

      Wireshark suggests that the message is being sent and received. However, RFC3164 suggests that there's no hard, normative standard for sending events over TCP: some applications end events with LF, some with CRLF, and some use byte-counting. Sys::Syslog likes LF+NUL and gives you a way to suppress the null, but the option to suppress the LF doesn't work; I've raised a ticket for that and another for the RFC-violating date format. All in all, with no standards and without the ability to suppress the LF experimentally, it's not surprising that the syslog collectors we've tried don't really like the events that Sys::Syslog emits. :-(

        That sounds like its not gonna be fixed soon. Why not switch to rsyslog?

Re: Sys::Syslog skips the first event
by Anonymous Monk on Jun 08, 2015 at 15:21 UTC
    Am I using Sys::Syslog wrongly ... I know that the man page asks us -- twice -- not to run setlogsock

    It seems you've answered your own question there... although it's too bad that it is not evident from the documentation or version history as to why setlogsock has been discouraged since v0.18 (that was almost 10 years ago). Just a wild guess: maybe a Wireshark trace could give you a hint.

    Have you looked into any of the other Syslog modules?

      The documentation hints that the reason for not using setlogsock is that some people were using it without knowing what it did, and were making their code less reliable, rather than more so, by routinely writing setlogsock('unix').

      Thanks for the pointers to other Syslog modules. I'd rather not resort to them because it would impose more work on the customers who have to run this program, but I'll go there (or just write the subset of syslogging that I actually need) if I can't make the program work acceptably in any other way.