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.

What are you getting for your value of $@ in each case (for the 'if'')? — tale852150, Apr 22 '16 at 15:55
What happens after the third message? Does it continue reporting success indefinitely, or does it eventually throw an exception? I think [this](http://stackoverflow.com/q/11436013/176646) might be related. — ThisSuitIsBlackNot, Apr 22 '16 at 16:16
Perfectly working for me. Did you try strace to get more information about what's happening? — Sebastian, Apr 22 '16 at 19:37
@tale in case of both success & fail $@ is empty when I try to print it. — Gary Vernon Grubb, Apr 24 '16 at 09:36
@This After the third message the script just dies with return code 141. — Gary Vernon Grubb, Apr 24 '16 at 09:40
@Sebas I will update the strace info in the question above. It is getting killed by SIGPIPE. I don't know what that means. Thank you all for your comments, please let me know if you can help further based on the new info I posted. — Gary Vernon Grubb, Apr 24 '16 at 09:40

score 1 · Answer 1 · edited May 23 '17 at 12:07

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.

Thank you. Was able to handle the error more efficiently when I added the above line to my script. However the script still waits for command 4 to notice the broken pipe. How do I make it more sensitive to fail at command 3? — Gary Vernon Grubb, Apr 24 '16 at 10:25

score 1 · Accepted Answer · answered Apr 24 '16 at 10:01

1

Try adding a line

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

before anything is being sent.

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

answered Apr 24 '16 at 10:01

Sebastian

2,472
1
18
31

Thank you. Was able to handle the error more efficiently when I added the above line to my script. However the script still waits for command 4 to notice the broken pipe. How do I make it more sensitive to fail at command 3? – Gary Vernon Grubb Apr 24 '16 at 10:26

score 1 · Answer 3 · edited May 23 '17 at 12:23

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:

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.
The client writes your third log message to the socket buffer successfully, so no exception is thrown.
The server sends a TCP RST packet to indicate that it's no longer listening.
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.

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

3 Answers3