Trying to log request body, it logs the response instead

[nthx]

Hi.

I'm trying to make 0.9.2 print both request & response bodies.
This is not documented, but discussed over in the #277 PR.
I think, I've made proper setup. I'm using Faraday via Saorin..

  @client = Saorin::Client.new(:url => @endpoint) do |connection|
    connection.response :logger, @logger, :bodies => true
  end

To my eye it looks, debug output doesn't print request body, but prints response body (not expected).
(and it follows printing response body again, as expected).

So I get sth like that in the log: (note value for request. It's duplicate of response actually.

post https://foo.bar.com/api/3.0/json-rpc
request User-Agent: "Faraday v0.9.2"
Content-Type: "application/json"
request {"result":{"accessGranted":false},"id":"foo","jsonrpc":"2.0"}
Status 200
response server: "nginx"
date: "Thu, 14 Jul 2016 21:28:21 GMT"
content-type: "application/json"
transfer-encoding: "chunked"
connection: "close"
response {"result":{"accessGranted":false},"id":"foo","jsonrpc":"2.0"}

Check this code of faraday/response/logger.rb:

    def call(env)
      info "#{env.method} #{env.url.to_s}"
      debug('request') { dump_headers env.request_headers }
      debug('request') { dump_body(env[:body]) } if env[:body] && log_body?(:request)
      super
    end

    def on_complete(env)
      info('Status') { env.status.to_s }
      debug('response') { dump_headers env.response_headers }
      debug('response') { dump_body env[:body] } if env[:body] && log_body?(:response)
    end

If I read it correctly, line: debug('request') { dump_body(env[:body]... prints not the proper var.

And, actually inspecting env[], I can't find request body nowhere :-( Only request_headers, request_options and response data.

Since, I don't believe nobody noticed that before, it's probably I've made some mistake. But where?

[stevenjack]

@nthx I'm seeing this as well..

[nthx]

@stve - does the report makes sense to you?

[nthx]

maybe it needs request configuration too? Haven't tried that though..

@client = Saorin::Client.new(:url => @endpoint) do |connection|
  connection.response :logger, @logger, :bodies => true
  connection.request :logger, @logger, :bodies => true
end

[LouisStAmour]

It's a standard race condition, I think. What's happening here is that env[:body] was once set to the request's body. But by the time the log method or dump_body executes, the response body has replaced the request body inside env[:body] and no further variables/copies are made of the original request body, not that it would necessarily fix things. env is global to the request, we shouldn't assume middleware is executing synchronously and in order before the call is made.

An easy fix would be to use two env values to track bodies, one for request, and one for response.

We don't have this bug with headers because there are two separate values there: request_headers and response_headers. So why not follow their lead...

Alternatively, make a second env value called request_body and store the request body twice in both env.request_body and env.body. That way any code that relies on the existing behaviour keeps it, but updated code such as our logging function here can use request_body if it exists.

If this doesn't get fixed upstream soon, I'm very likely going to patch Faraday and use my own fork. I can't have unreliable logging...

[iMacTia]

@nthx, sorry if I missed it, but which logger are you using?
Code looks fine, the only "issue" I can see is with procs used to evaluate the message. This is usually not an issue, unless their evaluation happens AFTER the request is processed.
I'm not sure this is possible with the standard (synchronous) logger, so I would like to know which one you're using :)

[nthx]

Actually, I've been using my own logger in this case. It has worked for other messages, so I didn't think it might cause an issue.
I will verify with standard logger and re-check my own, and let you know.

[iMacTia]

Hi @nthx, any luck with your tests? Did you discover anything new?
I would like to close this issue and understand if the problem lies on Faraday or the logger

[iMacTia]

I'm going to close this assuming the fault lies on the logger as I tested the standard one and is working fine for me.

@nthx feel free to reopen in case you have any new evidence pointing to Faraday as the possible cause

[LouisStAmour]

I still had this bug, using the Faraday built-in Logger at the time, but I solved it by writing my own logger in middleware, and later by switching from using Faraday to something simpler.

[llxff]

Hi @iMacTia, I stuck with this problem too. I have found that problem reproduced when you define adapter before logger.

This code log request body:

Faraday.new(url: url) do |faraday|
  faraday.response :logger, ::Logger.new(STDOUT), bodies: true
  faraday.adapter Faraday.default_adapter
end

This don't:

Faraday.new(url: url) do |faraday|
  faraday.adapter Faraday.default_adapter
  faraday.response :logger, ::Logger.new(STDOUT), bodies: true
end

[iMacTia]

Hi @llxff,

yes that's expected as the middlewares order is critical and adapter should always be at the bottom.
If you put the adapter BEFORE, than the request will be performed before the logger adapter is reached, causing the response being logged twice.
Also, I'm now reading back @nthx issue with this and I just realised he's missing the adapter in his middlewares stack:

@client = Saorin::Client.new(:url => @endpoint) do |connection|
    connection.response :logger, @logger, :bodies => true
  end

I've also checked the code in Saorin gem and it looks completely wrong for the same exact reason: https://github.com/mashiro/saorin/blob/master/lib/saorin/client/faraday.rb#L16

[nthx]

Makes sense. I can't yet verify it again, but have another thought... I've read my initial report and it says:

This is not documented, but discussed over in the #277 PR.

Is this still the case, that there is no documentation on how actually configure logging of responses?
If the docs were there, then there would be no doubt on how to do it.

May you please create a ticket to update the docs? Or reopen this one maybe?

Also - who should contact Saorin guys?

[iMacTia]

Hi @nthx you're very right our documentation is currently not detailed enough (actually, we're using the Readme as a "documentation").
In your specific case, there's the 3rd example in the https://github.com/lostisland/faraday/blob/master/README.md#basic-use section which shows how to use the logger middleware, but I agree that's not enough.
We're planning to have a revamped Wiki in the near future which should help mitigating this sort of issues.

As per Saorin, I suggest you open an issue on their page providing examples with the failing code and reporting my comment, which should help them to track down the issue.
I prefer you doing this as you're actively using their gem and though will be able to provide any additional information they could need.

Thanks

[benja83]

Hi,

I've just saw this issue and I understand why my request was not well signed.

We created a middleware that add a signature before making the request.
As we define the adapter before using the middleware, the request was sent before adding the authorisation header.

The side effect was that the middleware was using the env.body to build the signature and so it was using the response body to build the signature.

As I was defining the adapter at the top of the connection, my logs were also wrong and I was thinking that my signature script was also wrong.

Best regards!