Using perl module Log::Syslog::Fast - Unable to catch exception

Question

I am using Log::Syslog::Fast to forward logs to a syslog server. I was testing the script to see how it would react if the syslog server suddenly crashed.

To test I created a file with test messages, started the script & then shutdown the syslog server after 2 messages were received at the syslog server.

The script sent the third message & then dies. The termination is not being caught by eval & 'use warnings 'FATAL' => 'all';' does not help.

Could someone please help me catch the exception & close down the script more gracefully?

What needs to happen here is - After the Command2 is sent, the script should catch the exception & display:

Fail: Command3

Code extract:

$logger = Log::Syslog::Fast->new(LOG_TCP,$server, 514, 13, 6, "test_machine", "Syslog");
$logger->set_pid(0);

foreach $line(<SPOOL>)
{
        ($machine,$time,$message)=(split '\|',$line);
        eval{
                $logger->set_sender($machine);
                $logger->send($message,$time);
        };
        if($@)
        {
                print "\nFail: $message\n";
                exit;
        }
        else
        {
                print "\nSuccess: $message\n";
        }
        sleep 5;
}

Input File:

test_machine1|1461201306|Command1
test_machine1|1461201311|Command2
test_machine1|1461203214|Command3
test_machine1|1461203219|Command4
test_machine2|1461204005|Command5
test_machine2|1461204006|Command6
test_machine2|1461204149|Command7
test_machine3|1461204154|Command8
test_machine3|1461206936|Command9
test_machine3|1461206942|Command10

Output:

Success: Command1

Success: Command2

Success: Command3

Strace Output:

read(4, "test_machine1|1461201306|Command"..., 4096) = 341
read(4, "", 4096)                       = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0
sendto(3, "<110>Apr 20 21:15:06 test_machin"..., 59, 0, NULL, 0) = 59
write(1, "Success Command1\n\n\n", 19Success Command1


)  = 19
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({5, 0}, 0x7ffc707478f0)       = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0
sendto(3, "<110>Apr 20 21:15:11 test_machin"..., 59, 0, NULL, 0) = 59
write(1, "Success Command2\n\n\n", 19Success Command2


)  = 19
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({5, 0}, 0x7ffc707478f0)       = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0
sendto(3, "<110>Apr 20 21:46:54 test_machin"..., 59, 0, NULL, 0) = 59

I want the script to fail here when it tries to send the third message but it does not.

write(1, "Success Command3\n\n\n", 19Success Command3


)  = 19
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({5, 0}, 0x7ffc707478f0)       = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0
sendto(3, "<110>Apr 20 21:46:59 test_machin"..., 59, 0, NULL, 0) = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=26037, si_uid=3179} ---
+++ killed by SIGPIPE +++

The script finally dies while trying to send the fourth message. Unfortunately the eval is not catching the exception.

Answer 1

I want the script to fail here when it tries to send the third message but it does not.

TL;DR You can't do this because of the way the TCP protocol works.

The client and server communicate via a socket. When the client writes to the socket, it's actually writing to a buffer; there's no indication whether the message is actually delivered.

The client can only know that the connection is closed after some data is actually sent to the server, so the first write to the buffer will succeed.

Here's what's happening:

1. When you shut down the server, it sends a TCP FIN packet. A FIN indicates that one side of the connection is done sending data, but can still receive; it doesn't indicate that the connection is closed.

2. The client writes your third log message to the socket buffer successfully, so no exception is thrown.

3. The server sends a TCP RST packet to indicate that it's no longer listening.

4. Because of the RST, the OS now knows that the server's end of the TCP connection is closed. When the client tries to write to the socket buffer, the process is signaled with SIGPIPE and the write returns EPIPE.

---

The script finally dies while trying to send the fourth message. Unfortunately the eval is not catching the exception.

You're not handling SIGPIPE so your program dies when it's signaled. Add the following near the top of your script to ignore SIGPIPE:

$SIG{PIPE} = 'IGNORE';

Now you can handle the exception raised by the send method however you like.

---

Further reading:

• Writing on a TCP socket closed by the peer
• Writing to a closed, local TCP socket not failing
• write on closed socket doesn't generate sigpipe immediatly
• Programming UNIX Sockets in C - Frequently Asked Questions section 2.22, "When will my application receive SIGPIPE?"

Answer 2

Try adding a line

$SIG{PIPE} = sub {
die "SIGPIPE";
};

before anything is being sent.

You might also want to try "print" instead of die.

Answer 3

You might want to trap SIGPIPE like this:

$SIG{PIPE} = "IGNORE";

From the perlipc:

If you're writing to a pipe, you should also trap SIGPIPE. Otherwise, think of what happens when you start up a pipe to a command that doesn't exist: the open() will in all likelihood succeed (it only reflects the fork()'s success), but then your output will fail--spectacularly. Perl can't know whether the command worked, because your command is actually running in a separate process whose exec() might have failed. Therefore, while readers of bogus commands return just a quick EOF, writers to bogus commands will get hit with a signal, which they'd best be prepared to handle.

Also, have a look at this behavior in a C program when writing to a broken socket.