IOError: stream closed in another thread

[cabello]

Describe the bug

IOError when closing client after successfully initializing it.

To reproduce

Execute the following script.

require 'bundler/inline'

gemfile do
  source 'https://rubygems.org'
  gem 'launchdarkly-server-sdk'
end

require 'logger'
require 'ldclient-rb'

launch_darkly_sdk_key = 'PUT A REAL SDK KEY HERE'

config = ::LaunchDarkly::Config.new(logger: Logger.new(STDOUT))
client = ::LaunchDarkly::LDClient.new(launch_darkly_sdk_key, config)

client.close if client.initialized?

Expected behavior

Client should close without errors.

Actual behaviour

WARN -- : Unexpected error from event source: #<IOError: stream closed in another thread>

Logs

I, [2019-06-12T18:29:28.669640 #99762]  INFO -- : [LDClient] Initializing stream connection
I, [2019-06-12T18:29:28.670045 #99762]  INFO -- : Connecting to event stream at https://stream.launchdarkly.com/all
D, [2019-06-12T18:29:28.795334 #99762] DEBUG -- : Received event: #<struct SSE::StreamEvent type=:put, ..., id=nil>
D, [2019-06-12T18:29:28.795617 #99762] DEBUG -- : [LDClient] Stream received put message: {"path":"/","data":{"segments":{},"flags":...,"clientSide":false}}}}
I, [2019-06-12T18:29:28.796399 #99762]  INFO -- : [LDClient] Stream initialized
I, [2019-06-12T18:29:28.796635 #99762]  INFO -- : [LDClient] Closing LaunchDarkly client...
W, [2019-06-12T18:29:28.796801 #99762]  WARN -- : Unexpected error from event source: #<IOError: stream closed in another thread>
D, [2019-06-12T18:29:28.796915 #99762] DEBUG -- : Exception trace: ["/Users/john/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/socketry-0.5.1/lib/socketry/tcp/socket.rb:179:in `wait_readable'", "/Users/john/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/socketry-0.5.1/lib/socketry/tcp/socket.rb:179:in `readpartial'", "/Users/john/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/ld-eventsource-1.0.0/lib/ld-eventsource/impl/streaming_http.rb:195:in `read_chunk_into_buffer'", "/Users/john/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/ld-eventsource-1.0.0/lib/ld-eventsource/impl/streaming_http.rb:217:in `block in read_line'", "/Users/john/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/ld-eventsource-1.0.0/lib/ld-eventsource/impl/streaming_http.rb:209:in `loop'", "/Users/john/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/ld-eventsource-1.0.0/lib/ld-eventsource/impl/streaming_http.rb:209:in `read_line'", "/Users/john/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/ld-eventsource-1.0.0/lib/ld-eventsource/impl/streaming_http.rb:174:in `block (2 levels) in read_lines'", "/Users/john/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/ld-eventsource-1.0.0/lib/ld-eventsource/impl/streaming_http.rb:173:in `loop'", "/Users/john/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/ld-eventsource-1.0.0/lib/ld-eventsource/impl/streaming_http.rb:173:in `block in read_lines'", "/Users/john/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/ld-eventsource-1.0.0/lib/ld-eventsource/impl/event_parser.rb:33:in `each'", "/Users/john/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/ld-eventsource-1.0.0/lib/ld-eventsource/impl/event_parser.rb:33:in `each'", "/Users/john/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/ld-eventsource-1.0.0/lib/ld-eventsource/impl/event_parser.rb:33:in `block in items'", "/Users/john/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/ld-eventsource-1.0.0/lib/ld-eventsource/client.rb:256:in `each'", "/Users/john/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/ld-eventsource-1.0.0/lib/ld-eventsource/client.rb:256:in `each'", "/Users/john/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/ld-eventsource-1.0.0/lib/ld-eventsource/client.rb:256:in `read_stream'", "/Users/john/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/ld-eventsource-1.0.0/lib/ld-eventsource/client.rb:188:in `run_stream'", "/Users/john/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/ld-eventsource-1.0.0/lib/ld-eventsource/client.rb:120:in `block in initialize'"]
I, [2019-06-12T18:29:28.797069 #99762]  INFO -- : [LDClient] Stream connection stopped

SDK version

• launchdarkly-server-sdk (5.5.7)
• ld-eventsource (1.0.0)

Language version, developer tools

Ruby 2.6.3

OS/platform

macOS Mojave

Additional context

In production we actually call close as follows:

if client.initialized?
  # We use gems like `parallel` that fork the main process and `at_exit` will be
  # called when these threads exit, we only want to close Launch Darkly connection
  # when the main process is shutting down.
  main_pid = Process.pid
  at_exit do
    client.close if Process.pid == main_pid
  end
end

But the result is the exact same.

We believe the bug is in https://github.com/launchdarkly/ruby-eventsource also maintained by this organization and could be patched like the following but we are not sure if this is the correct solution:

https://github.com/launchdarkly/ruby-eventsource/blob/5e7c613f09f0976b374316a8cd911b59184da572/lib/ld-eventsource/client.rb#L180-L202

def run_stream
  while !@stopped.value
    @cxn = nil
    begin
      @cxn = connect
      # There's a potential race if close was called in the middle of the previous line, i.e. after we
      # connected but before @cxn was set. Checking the variable again is a bit clunky but avoids that.
      return if @stopped.value
      read_stream(@cxn) if !@cxn.nil?
    rescue Errno::EBADF
      # Don't log this as an error - it probably means we closed our own connection deliberately
      @logger.info { "Stream connection closed" }
+    rescue IOError => e
+      return if @stopped.value
+      log_and_dispatch_error(e, "Unexpected error from event source")
    rescue StandardError => e
      # This should not be possible because connect catches all StandardErrors
      log_and_dispatch_error(e, "Unexpected error from event source")
    end
    begin
      @cxn.close if !@cxn.nil?
    rescue StandardError => e
      log_and_dispatch_error(e, "Unexpected error while closing stream")
    end
  end
end

Thanks for taking the time to look into this issue, we appreciate it. 🙏

[eli-darkly]

Thanks for letting us know and sorry about the inconvenience. Your analysis looks correct at first glance - an IO exception under those circumstances isn't really an error and shouldn't be logged. The fix is probably what you suggested, and we should be able to put out a patch shortly.

I'm not sure why we haven't seen this happen all the time. It could be timing-dependent, or it could also be that some versions of the Ruby runtime will throw Errno::EBADF as we expected but others will not.

[eli-darkly]

Sorry we didn't get to this sooner. This has been fixed in v1.0.1 of the launchdarkly-eventsource package, which is in the new 5.5.8 release of the LaunchDarkly Ruby SDK.