10-20% message loss when using Stomp Output

[SuperFunks]

Hi there,

We are experiencing 10-20% message drop when sending messages from Logstash 5.2 to a Universal Messaging Queue with the STOMP protocol. (Also verified with Logstash 2.4)

Config to reproduce:

input {
        tcp {
                port => 5001
                type => "umrelay"
        }
}

output {
        file {
            path => "/tmp/stash.out"
        }
        if [type] == "umrelay" {
            stomp {
                 destination => "/test/testqueue"
                 host => "x.x.x.x"
                port => 17092
            }
        }
        stdout{}
}

We are using python to send 100.000 messages to the Logstash TCP input - and outs the messages to a file, stomp and console.

The file contains all 100.000 messages
The console writes all 100.000 messages
The Stomp output produces 83.560 messages

The loss happens at rates above 100 pr. second.

We have verified the STOMP functionality on UM by running 100.000 messages to it directly with Python - and all messages are persisted.
We have also tested multiple input path to logstash but we consistantly get everything written to file-out and console, but 10-20% is lost on the STOMP output.

Operating System:
Source: Debian
Target: OpenSuse

Sample Data:
The message sent from Python in all experiements is "i\n" where i is the current message number in an iteration of 100.000

Steps to reproduce:
Send messages to any logstash input at a message rate above 100 pr. second, and output on Stomp Output.
Count your input and output and assess the message drop. We see about 10-20% drop.

This is a problem - And would like to see a fix to this 😉

Best regards,

SuperFunks

[ph]

@consulthys Do you have any idea what could be causing this?

I am wondering if the library returns something or not at that line when it drops the message.
https://github.com/logstash-plugins/logstash-output-stomp/blob/master/lib/logstash/outputs/stomp.rb#L86

[consulthys]

That's an interesting issue and looks a lot like issue #8 I filed a while ago. Ultimately, the issue was that the plugin was not disconnecting properly, and hence messages would be lost. @SuperFunks can you run logstash with --debug and share your logging output?

[SuperFunks]

Sure thing - the logfile proved to be pretty big though.

I ran a test of 1 million events - and we got 812165 events into the Queue.

Here is the log from the run:
stomp-debug.zip

I have cleared it for sensitive information - but i hope you can still find out what might be wrong.

[ph]

I've looked at the debug log file:

1. I don't see any errors.
2. the plugins receive all the events cat logstash-plain.log | grep stomp | grep events | grep -o '>\d\+' | grep -o '\d\+' | paste -sd+ - | bc => 1000000 (ugly one liner.. )

[ph]

When passed a block, the transaction scope will automatically transmit a BEGIN frame, deliver all transactional frames in the block with a matching transaction header and then send a COMMIT frame to complete the transaction. If an error is raised within the block, an ABORT frame will be sent to the broker to roll-back the transaction and the offending error will be re-raised.

From the documentation if an error is done within the block we should have seen it?

[ph]

Another thing from the log, we connect to stomp once.

[2017-02-13T13:26:15,848][DEBUG][logstash.outputs.stomp ] Connected to stomp server

[ph]

OH OH The #close method seems to never be called, I can't find trace of Disconnecting from stomp broker in the log.

@SuperFunks How are you stopping logstash? Are you waiting for a complete shutdown before doing the asserts on the stomp side?

The last line in the logs you have provided are the following, which indicate that LS was still in the process of shuttting down.

[2017-02-13T13:35:50,917][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline
[2017-02-13T13:35:55,918][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline
[2017-02-13T13:36:00,919][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline
[2017-02-13T13:36:05,919][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline
[2017-02-13T13:36:10,919][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline
[2017-02-13T13:36:15,919][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline
[2017-02-13T13:36:20,919][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline
[2017-02-13T13:36:25,919][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline
[2017-02-13T13:36:30,919][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline

The disconnect line should happen after this, which mean that each worker threads didn't call disconnect on the stomp client and would drop the current inflight messages. Since this plugin uses the concurrency legacy model each worker has is own buffer

[ph]

I am not completely sure about the #disconnect, it's my current working theory. my definition of a transaction would be like a blocking call, either it complete or not. See https://github.com/iande/onstomp/blob/master/extra_doc/UserNarrative.md#transaction

But maybe it's not the case, since the library is async and they use callbacks for some of the error handling.

[SuperFunks]

Hi there,

I never shut down the logstash on this run. But waited 5 minutes before extracting the debuglog.

We have however done tests of this before where some part of the missing events get pushed to the queue but nowhere near the amount lost. Ill make another run with debug where we ask logstash to shutdown, so you can see the disconnects as well.

[ph]

@SuperFunks Thanks, we will figure it out!

The code sending events is pretty thin, https://github.com/logstash-plugins/logstash-output-stomp/blob/master/lib/logstash/outputs/stomp.rb#L77-L88, So I would think its either a problem with our usage of the stomp library or the library itself.

[consulthys]

@SuperFunks Thanks for the logs. In order to remove the noise, would it be possible for you to remove the file and stdout outputs and keep only the stomp one? Moreover, I think that 1000 entries should be sufficient to highlight the issue and keep the log smaller.

We might benefit from using the finer-grained event callbacks in order to gain more insights into what's going on internally.

[SuperFunks]

This is a run for 10000 events - with only Stomp output activated - and the logstash instance is terminated at the end - and disconnects become visible in the log.

Out of 10000 events we got 8316 onto the Queue.

Here is the log: stomp-debug2.zip

I dont understand the "Event callbacks" or if that was meant for me.
Let me know if i can do anything else to help.

[consulthys]

Thanks @SuperFunks I'll have a look.

The mention to "event callbacks" was a note to myself to maybe add in the plugin in order to gain more insights into what's going on internally. Time permitting, I'll get into this.

[SuperFunks]

Looking at the log i see 10000 Filter events and 10000 Output events.
So it must be something happening inside the output events.