Support to log. #348

prodis · 2016-05-22T02:44:49Z

For some applications is valuable to have the option to log HTTP requests and responses. I have just added support to this.

Example using Rails.logger:

HTTP.log(Rails.logger).get('http://prodis.webstorelw.com.br/version.txt')

It will be logged request method, URL, headers and body, response status code, headers and body:

GET http://prodis.webstorelw.com.br/version.txt
Connection: close
Host: prodis.webstorelw.com.br
User-Agent: http.rb/2.0.1

HTTP/1.1 200 OK
Server: nginx
Date: Sun, 22 May 2016 02:28:55 GMT
Content-Type: text/plain; charset=utf-8
Content-Length: 8
Last-Modified: Thu, 10 Mar 2016 01:04:48 GMT
Connection: close
Etag: "56e0c830-8"
Accept-Ranges: bytes

v4.24.0

If necessary, I can improve it with an optional range of options to log or not headers and body, for example.

What do you think?

tarcieri · 2016-05-23T05:43:22Z

lib/http/options.rb

Why not just nil?

A agree. It should be either nil (I like this idea better), or at least some kind of cached null-logger.

@tarcieri @ixti
HTTP::Logger implicitly works like a null object. We can call HTTP::Logger#log even if its logger attribute is nil.
https://github.com/httprb/http/pull/348/files/9e0569ead67133f171b33582e515bade4185b970#diff-a32552e6c7aef4937f6b3148e3515abdR11

As an alternative we can use nil as default HTTP logger and to deal with this nil when HTTP::Logger#log is called in HTTP::Client class. 😉

Yeah but you will be allocating new instance everytime Options got initialized, which is not pretty awesome ;))

ixti · 2016-05-23T11:16:34Z

IMHO logic of request/response formatting is better to be extracted on Request/Response object:

class Request
  # @param [#<<] io
  def pretty_print(io: STDOUT, skip_headers: true, skip_body: true)
    message = "#{verb} #{uri}"
    headers.each { |k, v| message << "\n#{k}: #{v}" } unless skip_headers
    message << "\n\n#{body}" unless skip_headers || skip_body
    io << message 
  end
end

That way it will make this method possible to be used by #inspect for example:

class Request
  def inspect
    pretty_print(:io => "", :skip_headers => false, :skip_body => true)
  end
end

Also, please, beware that printing out body in response might not be a good idea by couple of reasons:

log will become pretty polluted with pretty useless info
log might become polluted with sensitive information
this might cause unexpected issues when you try to stream body

So, I propose to allow pass :with => [:headers, :body] to #log(logger) API to provide what should be logged. IMHO by default it should log ONLY headlines.

prodis · 2016-05-23T19:47:12Z

@ixti
I agree with you regarding to print body and headers not to be the default behavior. The interface of optional parameters that you proposed sounds good. I really expected to hear some opinions about printing the full log.

About to extract the formatting logic to Request and Response classes, HTTP::Response already has an implementation of inspect method. Can I reimplement it using the new pretty_print method?

ixti · 2016-05-23T20:10:33Z

@prodis Sure.

prodis · 2016-05-23T20:14:50Z

@ixti Great! I do all that things soon.

prodis · 2016-05-30T03:48:56Z

Done.

prodis · 2016-05-30T04:02:00Z

The build of Ruby 2.2.0 was breaking after run all tests green and Rubocop checks were OK. https://travis-ci.org/httprb/http/builds/133830598

I changed the RVM version from 2.2 to 2.2.5 in Travis configuration in order to fix it. If necessary I can checkout the modifications in .travis.yml file.

ixti · 2016-05-30T14:58:18Z

lib/http/headers.rb

+      to_h.map do |name, value|
+        value = value.join("; ") if value.respond_to?(:join)
+        "#{name}: #{value}"
+      end.join(separator)


IMHO its' better to pretty print in the form we will send those headers to server.

@ixti
Sorry, I didn't get it.
Do you mean use "\n" separator or do you are talking about do not join multiples values of header with "; "?

Yeah, something like:

def pretty_print(separator: "\n") map { |k, v| "#{k}: #{v}" }.join(separator) end

So, I was tlking about both :D

Hum, OK.
I used ", " separator to inspect method to return in a single line. Is it OK inspect methods return multiple lines?
Just confirming.

Same approach with inspect method in HTTP::Request and HTTP::Response classes?

Got it.
I am going to do this and the name issues in the other commentaries.

Hey, @ixti.

One point about HTTP::Headers#pretty_print:
I used to_h.map {... instead of self.map {... to avoid duplicated headers with different values.

For example, for these headers:

headers.set :set_cookie, %w(hoo=ray woo=hoo) headers.set :content_type, "application/json"

I believe we expected a printable version like this:
"Set-Cookie: hoo=ray; woo=hoo\nContent-Type: application/json"

And not like this:
"Set-Cookie: hoo=ray\nSet-Cookie: woo=hoo\nContent-Type: application/json"

What do you think?

I'm not strongly against that. Although I thought it's better to print them just as they would be sent to server (we don't join them), but for pretty printing I think it worth to do so. Also, I think in this case it might worth to allow specify truncation length so that long lines would become truncated (have no opinion on this at all though). Anyway, if you think it worth join headers let' do that, but a bit more efficient way will be:

headers.group_by { |x| x[0] }.each do |key, values| io << "\n#{key}: #{values.join '; '}" end

Great tip, @ixti!
I have never used group_by method.
It made my day!

ixti · 2016-05-30T15:22:04Z

lib/http/printer.rb

+  #       "MyHttpRequest headline"
+  #     end
+  #   end
+  module Printer


Proabbly PrettyPrinter will be a bit better name? :D

razum2um · 2016-07-07T13:13:32Z

thanks for great suggestion @prodis, any updates? need help?
@ixti what's left to be done?

prodis · 2016-07-08T13:10:42Z

@razum2um @ixti
Really sorry for delay. Many changes are happening in my life and I didn't give more attention for this PR.

I need to finish the implementation of last comments. I promise to finish next week.

My apologies.

prodis · 2016-07-25T03:36:51Z

@razum2um @ixti
Finally done.

I didn't changed the original behaviour of Request#headline, so it will not log the entire request URI.
Travis is broken because ActiveSupport 5.0.0 requires Ruby version >= 2.2.2.

When possible, please give me a feedback.

ixti · 2016-07-25T15:07:55Z

lib/http/response.rb

+    private
+
+    def headline
+      "HTTP/#{@version} #{code} #{reason}"


It can be simply: "HTTP/#{@version} #{@status}"

ixti · 2016-07-25T16:05:14Z

Thanks for all you hard work. I will try to walk through the PR and merge as soon as possible during this week.

ixti · 2016-08-01T17:07:02Z

After some consideration I think we should do this a bit different.
One of the main concerns I have is that in full format I would like to see request/response as is:

HTTP/1.1 200 OK
Content-Type: text/plain

Hello!

And in one-line format I would expect it to be something like:

HTTP/1.1 200 OK {"Content-Type" => "text/plain"}

It means that HTTP::Logger should receive not an options, but formatter instance.
Also that means we should provide 2 different formatters out of the box:

HTTP::Formatter::Pretty
HTTP::Formatter::Oneline

Both of those should respond to #call with single argument - Request or Response object. That will allow to create logger with formatter proc:

formatter = -> (obj) { "#{obj.class} | #{obj.headline}" }
logger = HTTP::Logger.new(STDOUT, :formatter => formatter)

By default HTTP::Formatter::Oneline for logger should be used, while Pretty with headers only for inspect.

And the last thing I would like to note, I think HTTP::Logger should also be an object that will respond to #call method, so that it will become possible to pass a simple proc for all the logging needs:

HTTP.log { |obj| puts obj }.get("http://example.com")

The above means that we will call logger separately for each req/res. Current PR does not handles logging upon redirects, which most likely should be handled too. I will try to

prodis · 2016-08-05T18:25:20Z

@ixti
I got it and I can do it. If I have some doubt during the development, I get in touch.
Maybe I will take a few weeks to finish it, because I am moving from my current country and I have a lot of things to deal.

Of course, if you want this feature early, feel free to delegate this task for another one. Really I would like to implement it.

Just one question: in the last line of your last comment, it seems you didn't finish the phrase "I will try to...". Am I correct?

ixti · 2016-08-05T19:03:10Z

@prodis heh, same here - lots of thing to handle in my life too. yeah, i haven't finished that phrase, but i forgot what i was going to say already :D

ixti · 2016-08-05T19:04:10Z

Oh. I was going to say that I will try to come up with better described API description later :D

vassilevsky · 2016-12-27T10:47:12Z

Can I help with logging?

vjustov · 2017-10-22T22:18:50Z

I dont want to be that guy but, any updates on this end?

mikegee · 2017-10-23T00:55:36Z

@vassilevsky & @vjustov I think it would be acceptable to take this work, finish implementing @ixti's recommendations, and open another PR. (Retaining @prodis as the author of those commits somehow.)

prodis · 2017-10-23T07:22:23Z

Sorry for long time to have this PR stopped in my side. 🙇
If you might wait for more one week, by the end of the weekend I can finish it.

But @mikegee, @vassilevsky and @vjustov feel free to finish in some way before, just let me know. 😉

tarcieri · 2017-10-23T18:40:42Z

Just wanted to note there’s similar functionality in the Reel web server, and I always liked color coding the log output:

https://github.com/celluloid/reel/wiki/Spy

vassilevsky · 2017-10-23T20:50:11Z

No worries, I added gem 'httplog' and now I have logs. They're pretty good, although a bit verbose.

tarcieri · 2018-09-19T13:42:54Z

I think this was addressed by #499

prodis force-pushed the log branch from 9d46f32 to 9e0569e Compare May 22, 2016 03:05

tarcieri reviewed May 23, 2016
View reviewed changes

prodis force-pushed the log branch 4 times, most recently from 852377a to ff165dd Compare May 30, 2016 03:37

prodis force-pushed the log branch from ff165dd to ba9ecc0 Compare May 30, 2016 03:51

Support to log.

4b3e730

prodis force-pushed the log branch from ba9ecc0 to 4b3e730 Compare May 30, 2016 04:15

ixti reviewed May 30, 2016
View reviewed changes

ixti self-assigned this May 30, 2016

ixti reviewed May 30, 2016
View reviewed changes

prodis added 3 commits July 25, 2016 00:15

Rename Printer to PrettyPrinter and use headline method.

35d512c

Change Headers#inspect to original implementation.

e210ba0

Refactory.

f5a9c1a

ixti reviewed Jul 25, 2016
View reviewed changes

Refactory Response#headline.

a664d16

This was referenced Feb 11, 2017

Request/Response Logging Possible? #238

Closed

net-http-spy support? #394

Closed

tarcieri mentioned this pull request May 28, 2018

Support observers #478

Closed

tarcieri closed this Sep 19, 2018

Support to log. #348

Support to log. #348

Uh oh!

Conversation

prodis commented May 22, 2016

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ixti commented May 23, 2016

Uh oh!

prodis commented May 23, 2016

Uh oh!

ixti commented May 23, 2016

Uh oh!

prodis commented May 23, 2016

Uh oh!

prodis commented May 30, 2016

Uh oh!

prodis commented May 30, 2016

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ixti May 31, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

razum2um commented Jul 7, 2016

Uh oh!

prodis commented Jul 8, 2016

Uh oh!

prodis commented Jul 25, 2016

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ixti commented Jul 25, 2016

Uh oh!

ixti commented Aug 1, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

prodis commented Aug 5, 2016

Uh oh!

ixti commented Aug 5, 2016

Uh oh!

ixti commented Aug 5, 2016

Uh oh!

vassilevsky commented Dec 27, 2016

Uh oh!

vjustov commented Oct 22, 2017

Uh oh!

mikegee commented Oct 23, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

prodis commented Oct 23, 2017

Uh oh!

ixti May 31, 2016 •

edited

Loading

ixti commented Aug 1, 2016 •

edited

Loading

mikegee commented Oct 23, 2017 •

edited

Loading