Skip to content

Request thread safety issue #558

@paul

Description

@paul

We're getting weird connection issues in our exception tracker:

HTTP::ConnectionError: error reading from socket: stream closed in another thread
 per_operation.rb  79 wait_readable(...)
[GEM_ROOT]/gems/http-4.1.1/lib/http/timeout/per_operation.rb:79:in `wait_readable'
Caused by:
 IOError: stream closed in another thread
 per_operation.rb  79 wait_readable(...)
[GEM_ROOT]/gems/http-4.1.1/lib/http/timeout/per_operation.rb:79:in `wait_readable'

The logs for that single job don't show anything interesting, but if you look at the logs for all the workers in that process:

[2019-07-12T15:40:15.589244 #4]  INFO -- : [03e56584-c7a1-45ee-9ca4-c86334cd7e75] > POST https://onesignal.com/api/v1/notifications 
[2019-07-12T15:40:15.886281 #4]  INFO -- : [1bf0df80-9dde-4724-a377-5ed9271284de] > POST https://onesignal.com/api/v1/notifications 
[2019-07-12T15:40:15.887557 #4]  INFO -- : [03e56584-c7a1-45ee-9ca4-c86334cd7e75] HTTP::ConnectionError: error reading from socket: stream closed in another thread 
[2019-07-12T15:40:15.889464 #4] ERROR -- : [03e56584-c7a1-45ee-9ca4-c86334cd7e75] Error performing WisperActiveJobBroadcaster::Job (Job ID: 03e56584-c7a1-45ee-9ca4-c86334cd7e75) from Shoryuken(tesseract-production-background) in 691.77ms: HTTP::ConnectionError (error reading from socket: stream closed in another thread): 
[2019-07-12T15:40:16.268402 #4]  INFO -- : [1bf0df80-9dde-4724-a377-5ed9271284de] < 200 OK 

Job 03e5 started posting to the endpoint, and 300ms later another thread (job 1bf0) posted to the same endpoint with a different body. This somehow interrupted the first request in progress, raising the IOError in the first 1.5ms after the 2nd request started. The 2nd request then finished normally.

Here's how we're making that request:

# global default HTTP client
  MyAppHTTP =
    ::HTTP
    .timeout(connect: 2.seconds, read: 10.seconds, write: 10.seconds)
    .use(logging: { logger: Rails.logger })

# class-specific HTTP client

  def http
    @http ||= MyAppHTTP.
              headers(headers).
              timeout(write: 30, connect: 10, read: 40).
              auth("Basic \"#{api_key}\"")
  end

# called like this:

      http.post(url("/notifications"), json: payload.to_json(:web)).status.success?

We're using the shoryuken gem as our job runner, which uses concurrent-ruby for the worker thread pool. I'm not clear how making a request in one worker thread could interfere with another. The wiki says "Thread safety comes into play when you Make an HTTP request", but doesn't offer any details, or instruction how to mitigate it.

This happens more often than I would have expected, too:

image

Metadata

Metadata

Assignees

No one assigned

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions