Error when Errno::ECONNREFUSED - Connection refused

[jbatalle]

Hello,
I'm trying to use the last update 0.16.0 (or 0.17.0) and I'm having problems when logstash is down and the process (a Sinatra App) can't access to it. So, in general I see the following log:
E, [2016-07-25T11:37:56.750065 #4282] ERROR -- : [LogStashLogger::Device::UDP] Errno::ECONNREFUSED - Connection refused
But sometimes, when some logs messages are defined, the process stops with the following message:

/home/ubuntu/.rvm/gems/ruby-2.2.5/gems/stud-0.0.22/lib/stud/buffer.rb:248:in `unlock': Attempt to unlock a mutex which is not locked (ThreadError)
        from /home/ubuntu/.rvm/gems/ruby-2.2.5/gems/stud-0.0.22/lib/stud/buffer.rb:248:in `ensure in buffer_flush'
        from /home/ubuntu/.rvm/gems/ruby-2.2.5/gems/stud-0.0.22/lib/stud/buffer.rb:248:in `buffer_flush'
        from /home/ubuntu/.rvm/gems/ruby-2.2.5/gems/stud-0.0.22/lib/stud/buffer.rb:112:in `block (2 levels) in buffer_initialize'
        from /home/ubuntu/.rvm/gems/ruby-2.2.5/gems/stud-0.0.22/lib/stud/buffer.rb:110:in `loop'
        from /home/ubuntu/.rvm/gems/ruby-2.2.5/gems/stud-0.0.22/lib/stud/buffer.rb:110:in `block in buffer_initialize'

I'm trying to generate the same behaviour with a small sinatra app, but for the moment I can't.

[dwbutler]

Hi,

I'm familiar with this error message. It's ultimately caused by breaking out of buffer_flush in a non-deterministic way using exceptions, and losing track of whether the mutex is locked or not. It should normally resolve itself and not bubble up. Are you sure that this exception is the one causing your process to stop? And what do you mean by "stop" - did the process crash? Or is it blocked? Can you provide a full stack trace that includes LogStashLogger?

Thanks!

[dwbutler]

(On a side note, I will probably end up vendoring in Stud::Buffer and modifying it to implement this behavior in a cleaner way that doesn't involve mutexes or exceptions at all.)

[jbatalle]

Hi,
thank you for the response!

When I said stop, I mean the process crash and I need to restart again. Adding the "drop_messages_on_flush_error: true" option, for the moment works properly.

Also comment that I'm not working with only one Sinatra App, I have several (each one listening in different port...) and probably the error happens when multiple process are trying to push data to Logstash at the same time...

Thanks

[dwbutler]

Okay, thanks, that's helpful to know.

Are all your Sinatra apps running in a single process, writing to the same instance of LogStashLogger? That could definitely make thread-safety issues worse.

[jbatalle]

No, all the Sinatra apps runs in different processes. In some cases, when the error appears, more than one of these process crashes.

[dwbutler]

The odd thing about the backtrace you attached is that it is raised from within a thread set up by Stud::Buffer. Normally LogStashLogger will replace it with a thread of its own, but it seems to still be running before that happens.

Normally, an exception raised in a thread will not cause the entire program to abort. Rather, the thread will simply die. Unless you set Thread.abort_on_exception = true. Are you setting this anywhere?

It's looking more and more like I'll need to use a custom buffer implementation. Most likely I will vendor in Stud::Buffer and modify it.

[dwbutler]

This should now be fixed in 0.18.0.