logger will hang programs indefinitely

[macb]

logger = LogStashLogger.new(
  type: :unix,
  path: '/path/to/missing/socket',
  program_name: 'ruby-example',
  formatter: :cee_syslog,
  sync: true
)

logger.info 'hello world'
p "got here"

Given the above logger, we'll never get to got here. Instead you'll likely get:

LogStashLogger::Device::Unix - Errno::ENOENT - No such file or directory - connect(2) for "/path/to/missing/socket"

forever and ever.

I found this when integrating LogStashLogger with a sinatra application where sync was not specified. It would still indefinitely hang the http requests for some reason.

The underlying cause seems due to the retry implementation in stud. It seems like this retry logic should be configurable but in the worst case it wouldn't retry indefinitely.

[dwbutler]

Hi,

I tried this and was able to reproduce the issue from Ruby 1.9.3 through 2.3.0. I created a logger with sync unspecified, and was surprised to find that the same behavior happens. Stud::Buffer shouldn't block because of an exception - it only blocks when the backlog is full.

It turns out that Ruby's UNIXSocket defaults to sync = true. If I create a logger with sync: false, the problem stays in the background as expected. I believe the correct fix is to explicitly default sync to false within LogStashLogger.

IMO, retrying indefinitely is a feature rather than a bug. The real problems that need to be solved are:

• Logging a message should never block the application.
• Retries should back off exponentially.
• When the message backlog is full, the user should have control over what happens. (block? start ejecting messages? log to a fallback logger?)

See #68.

[dwbutler]

Now that I did some more research, setting sync to true seems to be a good default in a situation where multiple threads or processes are writing to the same file. (Such as a web app.) See #44

[dwbutler]

Regardless, even with sync set to true, LogStashLogger still ought to buffer messages and flush them in the background. This should not block.

[dwbutler]

I believe LogStashLogger should provide two different options:

• sync. Sets sync on the underlying IO device.
• autoflush. When set to true, immediately writes each incoming log message to the device. If the device raises an exception, the application blocks and retries until it is successful. Defaults to false.

The current sync option does both things.

[macb]

As you pointed out, explicitly specifying sync: false meant the behavior went away until the buffer filled in which case we ran into #68. Given that, #68 seems like a higher priority as compared to this issue (subset of devices as opposed to all devices that could raise exceptions).

[dwbutler]

#81 fixes the default behavior of connectable devices (including the Unix socket device) so that an exception doesn't block, but simply causes the message to be re-enqueued. This should fix the blocking behavior regardless of the sync setting. This also fixes the issue of the blocking behavior when the buffer fills. Messages will be discarded when the buffer fills.

#83 Also allows for messages to be dropped when there is an "unrecoverable" error. However, IMO Errno::ENOENT is a recoverable error. Once you discover the error, you could in theory create , the file, the error will resolve itself, and the messages can now be sent.

[dwbutler]

The blocking behavior is fixed in 0.16.0.

While fixing this, I discovered that Stud::Buffer does actually autoflush every time you write a message. There is no way to turn off this behavior. See the code here. Given this, it wouldn't make sense to expose an autoflush setting yet. Turning off autoflushing will probably require a fork of Stud::Buffer or a different buffering implementation.