From 1de702cd93677d80e5485257a09c63d88a5baf74 Mon Sep 17 00:00:00 2001
From: Anton Maminov <anton.linux@gmail.com>
Date: Thu, 18 Nov 2021 09:47:52 +0200
Subject: [PATCH] add logging

---
 README.md                   |  8 ++++++++
 spec/log_spec.cr            | 18 ++++++++++++++++++
 src/mechanize.cr            |  5 +++++
 src/mechanize/http/agent.cr | 26 ++++++++++++++++++++++++++
 4 files changed, 57 insertions(+)
 create mode 100644 spec/log_spec.cr

diff --git a/README.md b/README.md
index a062c62..28aff22 100644
--- a/README.md
+++ b/README.md
@@ -87,6 +87,14 @@ This method is from [lexbor](https://github.com/kostya/lexbor), so if you want t
 puts page.css("h1").first.inner_text
 ```
 
+### Logging
+
+For activation, simply setup the log to `:debug` level
+
+```crystal
+Log.setup("mechanize", :debug)
+```
+
 ## Contributing
 
 1. Fork it (<https://github.com/Kanezoh/mechanize.cr/fork>)
diff --git a/spec/log_spec.cr b/spec/log_spec.cr
new file mode 100644
index 0000000..184a198
--- /dev/null
+++ b/spec/log_spec.cr
@@ -0,0 +1,18 @@
+require "./spec_helper"
+require "log/spec"
+
+describe "Mechanize logging" do
+  it "emit logs" do
+    Log.capture("mechanize") do |logs|
+      agent = Mechanize.new
+      agent.user_agent = "Firefox"
+      page = agent.get("http://example.com/form")
+
+      logs.check(:debug, "GET: http://example.com/form")
+      logs.check(:debug, "request-header: User-Agent => Firefox")
+      logs.check(:debug, "status: HTTP/1.1 200 OK")
+      logs.check(:debug, "response-header: Content-length => 291")
+      logs.check(:debug, "response-header: Connection => close")
+    end
+  end
+end
diff --git a/src/mechanize.cr b/src/mechanize.cr
index bbec91a..18c54b1 100644
--- a/src/mechanize.cr
+++ b/src/mechanize.cr
@@ -1,3 +1,4 @@
+require "log"
 require "uri"
 require "http/client"
 require "lexbor"
@@ -32,6 +33,7 @@ require "./mechanize/errors/*"
 # ```
 class Mechanize
   VERSION = "0.2.0"
+  Log     = ::Log.for(self)
 
   USER_AGENT = {
     "Mechanize" => "Mechanize/#{VERSION} Crystal/#{Crystal::VERSION} (https://github.com/Kanezoh/mechanize.cr)",
@@ -250,6 +252,9 @@ class Mechanize
     cur_page = form.page || (current_page unless history.empty?)
 
     request_data = form.request_data
+
+    Log.debug { "query: #{request_data.inspect}" }
+
     content_headers = ::HTTP::Headers{
       "Content-Type"   => form.enctype,
       "Content-Length" => request_data.size.to_s,
diff --git a/src/mechanize/http/agent.cr b/src/mechanize/http/agent.cr
index c7fe6f9..c8905a3 100644
--- a/src/mechanize/http/agent.cr
+++ b/src/mechanize/http/agent.cr
@@ -32,6 +32,7 @@ class Mechanize
         response = http_request(uri, method, params)
         body = response.not_nil!.body
         page = response_parse(response, body, uri)
+        response_log(response)
         # save cookies
         save_response_cookies(response, uri, page)
 
@@ -46,6 +47,8 @@ class Mechanize
         redirect_url = response.headers["location"]
         uri = resolve_url(redirect_url, referer)
 
+        Log.debug { "follow redirect to: #{uri.to_s}" }
+
         # Make sure we are not copying over the POST headers from the original request
         headers.delete("Content-MD5")
         headers.delete("Content-Type")
@@ -56,6 +59,8 @@ class Mechanize
 
       # send http request
       private def http_request(uri, method, params) : ::HTTP::Client::Response?
+        request_log(uri, method)
+
         case uri.scheme.not_nil!.downcase
         when "http", "https"
           case method
@@ -206,6 +211,7 @@ class Mechanize
       private def save_cookies(uri, header_cookies)
         host = uri.host
         header_cookies.each do |cookie|
+          Log.debug { "saved cookie: #{cookie.name}=#{cookie.value}" }
           cookie.origin = host
           request_cookies << cookie
         end
@@ -220,6 +226,26 @@ class Mechanize
         end
         valid_cookies
       end
+
+      private def request_log(uri, method)
+        Log.debug { "#{method.to_s.upcase}: #{uri.to_s}" }
+
+        request_headers.each do |key, values|
+          value = values.size == 1 ? values.first : values
+          Log.debug { "request-header: #{key} => #{value}" }
+        end
+      end
+
+      private def response_log(response)
+        return unless response
+
+        Log.debug { "status: #{response.version} #{response.status_code} #{response.status_message}" }
+
+        response.headers.each do |key, values|
+          value = values.size == 1 ? values.first : values
+          Log.debug { "response-header: #{key} => #{value}" }
+        end
+      end
     end
   end
 end