Faraday throws Faraday::TimeoutError while simple cURL or Net::HTTP work fine

[dmytro-savochkin]

Basic Info

• Faraday Version: 1.3.0
• Ruby Version: 2.7.2
• Ruby on Rails Version: 6.1

Issue description

I'm trying to make a POST call to a secured host (which is only available from certain machines/IPs). However Faraday throws a Net::ReadTimeout exception while I'm doing it (and before throwing it, it freezes for a substantial amount of time waiting for something).
BUT! The same call via cURL works perfectly fine, it returns the data from the API momentarily (so it's not like Faraday gives too little time before throwing a timeout). It also works if I rewrite the code using Net::HTTP.
This is a persistent issue for me, the behavior above is happening every time I try it.

Please note I will replace the real host name in the examples below because it won't make any difference since it would be impossible for you guys to call it (this a host available from certain IPs only).

Steps to reproduce

My Faraday call which I'm trying to run within rails c console.

begin
  url = 'https://www.somehost.fr/public-api/v1/candidate/account'
  headers = { 'Content-Type' => 'application/json;charset=UTF-8' }
  connection = Faraday.new(url: url, headers: headers)
  response = connection.post do |request|
    request.body = {
      email: 'test-user111@example.com',
      password: 'password',
      loginAfterSuccess: true,
      remember_me: true
    }.to_json
  end
  puts response.body
rescue StandardError => e
  puts e.class
  puts e.message
  puts e.backtrace
end

It gives the following:

Faraday::TimeoutError
Net::ReadTimeout with #<TCPSocket:(closed)>
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/net/protocol.rb:217:in `rbuf_fill'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/net/protocol.rb:191:in `readuntil'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/net/protocol.rb:201:in `readline'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/net/http/response.rb:42:in `read_status_line'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/net/http/response.rb:31:in `read_new'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/net/http.rb:1528:in `block in transport_request'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/net/http.rb:1519:in `catch'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/net/http.rb:1519:in `transport_request'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/net/http.rb:1492:in `request'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/airbrake-11.0.1/lib/airbrake/rails/net_http.rb:11:in `block in request'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/airbrake-11.0.1/lib/airbrake/rack.rb:25:in `capture_timing'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/airbrake-11.0.1/lib/airbrake/rails/net_http.rb:10:in `request'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/faraday-net_http-1.0.0/lib/faraday/adapter/net_http.rb:152:in `block in request_via_request_method'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/net/http.rb:933:in `start'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/faraday-net_http-1.0.0/lib/faraday/adapter/net_http.rb:146:in `request_via_request_method'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/faraday-net_http-1.0.0/lib/faraday/adapter/net_http.rb:131:in `request_with_wrapped_block'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/faraday-net_http-1.0.0/lib/faraday/adapter/net_http.rb:122:in `perform_request'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/faraday-net_http-1.0.0/lib/faraday/adapter/net_http.rb:66:in `block in call'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/faraday-1.3.0/lib/faraday/adapter.rb:60:in `connection'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/faraday-net_http-1.0.0/lib/faraday/adapter/net_http.rb:64:in `call'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/faraday-1.3.0/lib/faraday/request/url_encoded.rb:25:in `call'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/faraday-1.3.0/lib/faraday/rack_builder.rb:154:in `build_response'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/faraday-1.3.0/lib/faraday/connection.rb:492:in `run_request'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/faraday-1.3.0/lib/faraday/connection.rb:279:in `post'
(irb):5:in `irb_binding'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/irb/workspace.rb:114:in `eval'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/irb/workspace.rb:114:in `evaluate'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/irb/context.rb:459:in `evaluate'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/irb.rb:541:in `block (2 levels) in eval_input'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/irb.rb:704:in `signal_status'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/irb.rb:538:in `block in eval_input'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/irb/ruby-lex.rb:166:in `block (2 levels) in each_top_level_statement'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/irb/ruby-lex.rb:151:in `loop'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/irb/ruby-lex.rb:151:in `block in each_top_level_statement'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/irb/ruby-lex.rb:150:in `catch'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/irb/ruby-lex.rb:150:in `each_top_level_statement'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/irb.rb:537:in `eval_input'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/irb.rb:472:in `block in run'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/irb.rb:471:in `catch'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/irb.rb:471:in `run'
/usr/share/rvm/rubies/ruby-2.7.2/lib/ruby/2.7.0/irb.rb:400:in `start'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/railties-6.1.0/lib/rails/commands/console/console_command.rb:70:in `start'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/railties-6.1.0/lib/rails/commands/console/console_command.rb:19:in `start'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/railties-6.1.0/lib/rails/commands/console/console_command.rb:102:in `perform'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/thor-1.0.1/lib/thor/command.rb:27:in `run'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/thor-1.0.1/lib/thor/invocation.rb:127:in `invoke_command'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/thor-1.0.1/lib/thor.rb:392:in `dispatch'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/railties-6.1.0/lib/rails/command/base.rb:69:in `perform'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/railties-6.1.0/lib/rails/command.rb:50:in `invoke'
/opt/applications/app-name/shared/bundle/ruby/2.7.0/gems/railties-6.1.0/lib/rails/commands.rb:18:in `<top (required)>'
./bin/rails:11:in `require'
./bin/rails:11:in `<main>'

This is my cURL request (which I think is almost identical to the Faraday code above?):

curl -v --compressed -H 'Content-Type: application/json;charset=UTF-8' -d '{"email":"test-user111@example.com","password":"password","loginAfterSuccess":true,"remember_me":true}' "https://www.somehost.fr/public-api/v1/candidate/account"

This is what I get in response (once again, I replaced real hosts, IPs, and other sensitive info here):

*   Trying 1.2.3.4...
* Connected to www.somehost.fr (1.2.3.4) port 443 (#0)
* found 129 certificates in /etc/ssl/certs/ca-certificates.crt
* found 520 certificates in /etc/ssl/certs
* ALPN, offering http/1.1
* SSL connection using TLS1.2 / ECDHE_RSA_AES_256_GCM_SHA384
* 	 server certificate verification OK
* 	 server certificate status verification SKIPPED
* 	 common name: somehost.de (matched)
* 	 server certificate expiration date OK
* 	 server certificate activation date OK
* 	 certificate public key: RSA
* 	 certificate version: #3
* 	 subject: C=DE,ST=Berlin,L=Berlin,O=Company Name,CN=somehost.de
* 	 start date: Thu, 12 Mar 2020 00:00:00 GMT
* 	 expire date: Fri, 11 Jun 2021 12:00:00 GMT
* 	 issuer: C=US,O=DigiCert Inc,CN=DigiCert SHA2 Secure Server CA
* 	 compression: NULL
* ALPN, server accepted to use http/1.1
> POST /public-api/v1/candidate/account HTTP/1.1
> Host: www.somehost.fr
> User-Agent: curl/7.47.0
> Accept: */*
> Accept-Encoding: deflate, gzip
> Content-Type: application/json;charset=UTF-8
> Content-Length: 102
> 
* upload completely sent off: 102 out of 102 bytes
< HTTP/1.1 201 Created
< Content-Type: application/json;charset=utf-8
< Expires: Fri, 12 Mar 2021 08:53:49 GMT
< Pragma: no-cache
< Cache-Control: no-cache, no-store, must-revalidate
< x-instance: 5.69/web
< x-xss-protection: 1; mode=block: 10.147.4.207
< x-content-type-options: nosniff: 10.147.4.207
< Content-Encoding: gzip
< Vary: Accept-Encoding
< Content-Length: 808
< Date: Fri, 12 Mar 2021 08:53:49 GMT
< Connection: keep-alive
< Set-Cookie: cfid=00001111-aaaa-bbbb-aa19-aa111c111111;Path=/;Expires=Thu, 01-Apr-2021 10:31:52 UTC;HTTPOnly;HttpOnly;Secure
< Set-Cookie: cftoken=0;Path=/;Expires=Thu, 01-Apr-2021 10:31:52 UTC;HTTPOnly;HttpOnly;Secure
< Set-Cookie: cfid=00001111-aaaa-bbbb-aa19-aa111c111111;path=/;HTTPOnly;HttpOnly;Secure
< Set-Cookie: cftoken=0;path=/;HTTPOnly;HttpOnly;Secure
< Set-Cookie: USER_HASH_ID=00001111-aaaa-bbbb-aa19-aa111c111111;Path=/;Expires=Sat, 12-Mar-2022 08:53:48 UTC
< Set-Cookie: V5=1;Path=/;Expires=Thu, 10-Jun-2021 08:53:48 UTC
< Set-Cookie: UXUSER=%20%3B%20%3B%20%3B;Path=/;Expires=Sun, 11-Apr-2021 08:53:48 UTC
< Set-Cookie: UXUSER=BLACKLIST%3BA%3B%20%3B;Path=/;Expires=Sun, 11-Apr-2021 08:53:48 UTC
< Set-Cookie: COMPANYV5LANG=fr;Path=/;Expires=Sat, 11-Mar-2051 16:45:18 UTC
< Set-Cookie: COMPANYV5LANG=fr;Path=/;Expires=Sat, 12-Mar-2022 08:53:48 UTC
< Set-Cookie: authHash=;Path=/;Expires=Fri, 12-Mar-2021 08:53:48 UTC
< Set-Cookie: CIDFORRETURNINGVISIT=DirectEntry;Path=/;Expires=Sat, 12-Mar-2022 08:53:48 UTC
< Set-Cookie: CIDFORRETURNINGVISITISSET=%22yes%22;Path=/;Expires=Sat, 12-Mar-2022 08:53:48 UTC
< Set-Cookie: SIMID=4361323;Path=/
< Set-Cookie: JSESSIONID=1111EDB222291EE3333BED7C6B4D4444; Path=/; HttpOnly;HttpOnly;Secure
< Set-Cookie: authHash=SomeLongJWT;Path=/;Expires=Fri, 12-Mar-2021 08:55:49 UTC;HTTPOnly
< Set-Cookie: STRGR=1;Path=/;Expires=Sun, 05-Mar-2051 08:53:49 UTC
< Set-Cookie: ONLINE_CF=10.147.5.69; path=/
< Server: API Gateway
< Strict-Transport-Security: max-age=15552000 ; IncludeSubDomains
< Set-Cookie: bm_sz=SomeLongCode; Domain=.somehost.fr; Path=/; Expires=Fri, 12 Mar 2021 12:53:48 GMT; Max-Age=14399; HttpOnly
< Set-Cookie: _abck=SomeLongCode; Domain=.somehost.fr; Path=/; Expires=Sat, 12 Mar 2022 08:53:49 GMT; Max-Age=31536000; Secure
< 
{"authHash":"SomeLongJWT","userLoggedIn":true,"success":true,"candidateId":1122333,"confirmationEmailSent":true}
* Connection #0 to host www.somehost.fr left intact

And this is the call I make using Net::HTTP:

uri = URI('https://www.somehost.fr/public-api/v1/candidate/account')
headers = { 'Content-Type': 'application/json;charset=UTF-8' }
Net::HTTP.start(uri.host, uri.port, :use_ssl => true) do |http|
  request = Net::HTTP::Post.new(uri, headers)
  request.body = {
    email: 'test-user222@example.com',
    password: 'password',
    loginAfterSuccess: true,
    remember_me: true
  }.to_json
  response = http.request(request)
  puts response.body
end

And I get the correct response this way:

{"authHash":"SomeJWT","userLoggedIn":true,"success":true,"candidateId":1112233,"confirmationEmailSent":true}

Am I missing some option or flag I should be passing with Faraday? Or does it look like a bug in Faraday? Any help would be appreciated!

[iMacTia]

Hi @dmytro-savochkin and thanks for the extensive details!
This definitely doesn't sound right, and reading your description of the issue (and the exception), it seems like the request actually reaches the server, but doesn't receive any response back and times out after some time 🤔.

From the ruby doc:

read_timeout: Number of seconds to wait for one block to be read (via one read(2) call). Any number may be used, including Floats for fractional seconds. If the HTTP object cannot read data in this many seconds, it raises a Net::ReadTimeout exception. The default value is 60 seconds.

I personally don't see anything "obviously" wrong with your Faraday code and it seems to me like a good match to the Net::HTTP and cURL requests.

A few question just to rule out some common issues:

1. Do you have access to the server logs by any chance? Is it possible to see if the request actually reaches the server?
2. Do you use a proxy for these requests? (Faraday will automatically pick the http_proxy or https_proxy ENV variables)

[dmytro-savochkin]

Hi @iMacTia!
Thanks for your reply.

1. Do you have access to the server logs by any chance? Is it possible to see if the request actually reaches the server?

No, I don't have access to the server unfortunately. However, since it's a registration endpoint I can implicitly infer that it either doesn't reach the server or reaches it but not successfully because if I first make a call with Faraday and then a call with cURL (using the same email in request body) the latter successfully registers a user. If I make two cURL requests with same email the first registers a user while the second doesn't so it should be a good indicator I think.

2. Do you use a proxy for these requests? (Faraday will automatically pick the http_proxy or https_proxy ENV variables)

I don't think so (checked both printenv and ENV.keys and there is nothing related to proxy).

[iMacTia]

Mmmmh I feel like we're missing something obvious, but it's hard to pinpoint the exact issue from the info we have at hand.
I did a few tests to rule out things like the URL being rewritten or similar, since this is a bit of an unusual way to use Faraday actually 😄, but all the tests I did rendered the same results and requests look identical.

Since there might be some missing pieces in this issue, or may have simplified something that turns up to be important, could you please try adding the logger middleware to your connection and check what it shows?
You can do so changing how you initialise your connection:

connection = Faraday.new(url: url, headers: headers) do |f|
  f.response :logger, nil, { headers: true, bodies: true }
end

Just be careful before copy-pasting here the logs as they will include the bodies and headers of both request and response.

Additional note

In case you're interested, your code can also be simplified taking advantage of faraday_middleware for the json payload and initialising the connection with the base url so you can re-use it for other endpoints as well:

# This is a companion gem with useful middleware
require 'faraday_middleware`

# Note the connection is initialised without the full path, this allows you to reuse it for other endpoints
conn = Faraday.new('https://www.google.com/public-api/v1') do |f|
  f.request :json # this comes from faraday_middleware. It will automatically call to_json on your request body and set the Content-Type header
  f.response :logger, nil, { headers: true, bodies: true }
end

# Now you can use the connection by simply specifying the missing part of the path.
# Please note it should NOT start with `/` or it will remove the `public-api/v1` part provided above
response = conn.post('candidate/account', {
  email: 'test-user111@example.com',
  loginAfterSuccess: true,
  remember_me: true
}) # no need to call to_json!

[dmytro-savochkin]

@iMacTia
Okay, I found the culprit! After checking the request logs as you advised I noticed that Faraday is sending User-Agent: Faraday v1.3.0 header. And, well, this is the only difference between Faraday and other clients. And, as it turned out, the external server for some reason have banned all requests that contain such user agent. Perhaps, they are blocking unknown agents for security reasons... Well, this is to be determined later.
I am closing this ticket as this is not a problem of Faraday. Thank you for your help!

[iMacTia]

Hey @dmytro-savochkin, I'm so glad you managed to find the problem!
And thanks for sharing the unusual resolution with us, it's great to finally know what was going on there 😄