Using proxy may break middleware parsers

[graudeejs]

I've setup mitmproxy to listen on port 8080

connection = Faraday.new(url: 'https://aldis.berjoza.lv') do |faraday|
  faraday.response :logger
  faraday.response :json, :content_type => %r[/json$]
  faraday.adapter :patron
  faraday.proxy = 'https://127.0.0.1:8080'
end
connection.get('/bookmarks/bookmarks.json') 

The result isn't parsed. In my opinion that's because when you proxy a request something like this is returned

HTTP/1.1 200 Connection established

HTTP/1.1 200 OK
Date: Thu, 14 Sep 2017 11:39:04 GMT
Content-Type: application/json; charset=utf-8
...

Note the extra HTTP/1.1 200 Connection established

Disabling proxy works as expected and I get parsed body.

Note that I'm using patron, because it's using system ssl certificates.

gem 'faraday', '~> 0.13.1'
gem 'patron', '~> 0.9.1'

[iMacTia]

Hi @graudeejs, I'll need some additional information, can you please provide all the output coming from the logger middleware?

[graudeejs]

I've just noticed, that this happens only for first request. 2nd request will be fine.

And that's logical, because Faraday apparently expects headers right after status 200, but in this case after status 200 (Connection established [to proxy]), there's another status 200.

On next request, connection to proxy is already established, so everything works as expected

@iMacTia here's gist with yaml of first and second response: https://gist.github.com/graudeejs/d9d08f1a5a8f6595d46f44cd1e3ebaa8

P.S.
Sorry about big data :)

[graudeejs]

Oh and logger info:
First request:

I, [2017-09-15T13:30:28.681939 #23018]  INFO -- : get https://aldis.berjoza.lv/bookmarks/bookmarks.json
D, [2017-09-15T13:30:28.682142 #23018] DEBUG -- request: User-Agent: "Faraday v0.13.1"
I, [2017-09-15T13:30:29.116159 #23018]  INFO -- Status: 200
D, [2017-09-15T13:30:29.116367 #23018] DEBUG -- response: 

Second request:

I, [2017-09-15T13:31:03.242617 #23018]  INFO -- : get https://aldis.berjoza.lv/bookmarks/bookmarks.json
D, [2017-09-15T13:31:03.242822 #23018] DEBUG -- request: User-Agent: "Faraday v0.13.1"
I, [2017-09-15T13:31:03.379958 #23018]  INFO -- Status: 200
D, [2017-09-15T13:31:03.380302 #23018] DEBUG -- response: Date: "Fri, 15 Sep 2017 10:31:03 GMT"
Content-Type: "application/json; charset=utf-8"
Transfer-Encoding: "chunked"
Connection: "keep-alive"
Set-Cookie: "__cfduid=da5059891cdd768b5512767d71a3c43de1505471463; expires=Sat, 15-Sep-18 10:31:03 GMT; path=/; domain=.berjoza.lv; HttpOnly"
Last-Modified: "Thu, 14 Sep 2017 08:31:58 GMT"
Access-Control-Allow-Origin: "*"
Expires: "Fri, 15 Sep 2017 10:31:00 GMT"
Cache-Control: "max-age=600"
X-GitHub-Request-Id: "A13E:7A68:CCB4A5:11E2601:59BBA98C"
Via: "1.1 varnish"
Age: "571"
X-Served-By: "cache-bma7024-BMA"
X-Cache: "HIT"
X-Cache-Hits: "6"
X-Timer: "S1505471463.285525,VS0,VE0"
Vary: "Accept-Encoding"
X-Fastly-Request-ID: "60be601a8613edeb9b4e1b4a0d0c51452b3e4092"
Server: "cloudflare-nginx"
CF-RAY: "39eaea057cc28709-ARN"

[graudeejs]

Here's what happens when you make same request with curl throught proxy:

HTTP/1.1 200 Connection established

HTTP/1.1 200 OK
Date: Fri, 15 Sep 2017 10:35:06 GMT
Content-Type: application/json; charset=utf-8
Transfer-Encoding: chunked
Connection: keep-alive
Set-Cookie: __cfduid=d623cb8b87fa32ef4e4e0d35ee76a4a2d1505471706; expires=Sat, 15-Sep-18 10:35:06 GMT; path=/; domain=.berjoza.lv; HttpOnly
Last-Modified: Thu, 14 Sep 2017 08:31:58 GMT
Access-Control-Allow-Origin: *
Expires: Fri, 15 Sep 2017 10:31:00 GMT
Cache-Control: max-age=600
X-GitHub-Request-Id: A13E:7A68:CCB4A5:11E2601:59BBA98C
Via: 1.1 varnish
Age: 0
X-Served-By: cache-bma7024-BMA
X-Cache: MISS
X-Cache-Hits: 0
X-Timer: S1505471706.395001,VS0,VE111
Vary: Accept-Encoding
X-Fastly-Request-ID: 3e00b438a216b2657e2ded59788e398d4cb2cba4
Server: cloudflare-nginx
CF-RAY: 39eaeff4bdf3864f-ARN
...

Notice first HTTP/1.1 200 Connection established - this means that curl/faraday connected to proxy.

[iMacTia]

Thanks @graudeejs, that should allow me to reproduce.
One last thing, can you try using another adapter and see what happens? I would suggest going for the default one (Net::HTTP).

[graudeejs]

@iMacTia Good point. The issue with Net::HTTP is that it uses god know what kind of ssl CA bundle.
Had to prepend this hack:

require 'openssl'
OpenSSL::SSL::VERIFY_PEER = OpenSSL::SSL::VERIFY_NONE

The result is that it works correctly: I had one request via proxy and it was parsed correctly.
So apparently the issue is in patron gem.

[iMacTia]

Mmmmh that helps at least. I believe something is wrong with headers returned by Patron gem.
I know it's not an ideal solution, but may I suggest to remove the JSON middleware restriction on the content type? If you know responses will always be JSON that should work anyway. At least I have some more time to see where the issue is

[graudeejs]

I don't really need to proxy my requests. I wanted to use mitmproxy to have better insight of what's actually going on while developing client for API.
There was one endpoint that returns binary, that's why I needed json restriction.
So after some time spent investigating this issue I decided to report this bug since it might affect other people/projects.

[iMacTia]

Hi @graudeejs,

I've tried replicating this issue locally but unfortunately I wasn't able to do it.
I'm using SquidMan to setup a local proxy on http://127.0.0.1:8080 and I'm using your exact same code to perform a request to your server.
I'm able to receive and parse the response using Patron on Faraday 0.13.0.

I'll now try with mitmproxy and see what happens

[iMacTia]

OK, I was able to reproduce it!
I can see the request works, but the middleware is not behaving as the response headers are missing from the first request. Might be related to #681 and #719

[iMacTia]

Hi @graudeejs, update on this.
It turned out we rely on Patron header parsing.
I had a look into their source code and I think I have identified the issue here: https://github.com/toland/patron/blob/master/lib/patron/response.rb#L124

If you look at the method implementation, here is what happens:

1. They split the response headers string on \r\n (newlines)
2. The remove the first element in the array (which will be "HTTP/1.x XXX")
3. They loop through the remaining lines until a blank line is found

The issue is that in case of a Proxy response, the first line after the HTTP status is a blank line, causing the loop to exit immediately and returning an empty headers hash.

This behaviour is even more complicated by the fact that different versions of CURL behaves differently. In fact, I initially had issues reproducing your issue because it works on one of my computers but not in the other.

I'm really sorry for taking so long to find out, but I believe you want to open this same issue on patron and I'll have to close this as it's not Faraday related.

If you need any additional information, feel free to ask.

[julik]

@iMacTia thanks for the investigation, the fix should be applied once the linked PR is merged to Patron master.

[iMacTia]

@julik thanks for the update!
I’m glad I could help finding the issue.