Skip to content
Permalink
Browse files

Add documentation and usage for configuring Apache-compatible logging

This adds documentation, examples, and a working configuration for log4j2
logging. This will allow users to more easily configure their own logging and
debug issues with clj-http through the apache http client logging.

Resolves #196 since the entire request/response can be inspected from the DEBUG
level of logs
  • Loading branch information
dakrone committed Mar 21, 2018
1 parent eca25dd commit 1e530f7679c1497da6b845d4a52ff06c102e9ba0
@@ -38,3 +38,5 @@ http.log
# Intellij Idea
/*.iml
/.idea

log/
@@ -840,7 +840,7 @@ is enabled.

** Debugging
:PROPERTIES:
:CUSTOM_ID: h-d2043bd3-5d97-416a-858d-a7936ff61c50
:CUSTOM_ID: debugging
:END:

There are four debugging methods you can use:
@@ -867,7 +867,7 @@ There are four debugging methods you can use:
(client/get "http://example.org" {:response-interceptor (fn [resp ctx] (println ctx))})
#+END_SRC

Additionally, to debug what data is being sent on the =Socket= when a request is make, clj-http
To debug what data is being sent on the =Socket= when a request is make, clj-http
provides the =:capture-socket= option:

#+BEGIN_SRC clojure
@@ -894,6 +894,73 @@ provides the =:capture-socket= option:
There are currently limitations with =:capture-socket=, a custom connection manager or the
=:insecure= option cannot be used, and async requests are not yet supported.

*** Logging
:PROPERTIES:
:CUSTOM_ID: h-0d505652-d453-48a2-a868-46aef2b8af66
:END:

Finally, if you want to access the logging that the Apache client does internally, you can set up
your dependencies to add the [[https://logging.apache.org/log4j/2.x/][log4j2]] libraries and configure the logging for clj-http. In order to do
this, you'll need to add

#+BEGIN_SRC clojure
[org.apache.logging.log4j/log4j-api "2.11.0"]
[org.apache.logging.log4j/log4j-core "2.11.0"]
[org.apache.logging.log4j/log4j-1.2-api "2.11.0"]
#+END_SRC

To your =project.clj= and have a usable log4j2.properties. I have provided one in
=resources/log4j2.properties=. Make sure to set:

#+BEGIN_SRC fundamental
rootLogger.level = debug
#+END_SRC

If you want to see debug information (or "trace" for trace logging). When you perform a request you
should see something akin to this in the logs:

#+BEGIN_SRC fundamental
[2018-03-20T20:36:34,635][DEBUG][o.a.h.c.p.RequestAddCookies] CookieSpec selected: default
[2018-03-20T20:36:34,635][DEBUG][o.a.h.c.p.RequestAuthCache] Auth cache not set in the context
[2018-03-20T20:36:34,635][DEBUG][o.a.h.i.c.BasicHttpClientConnectionManager] Get connection for route {s}->https://example.com:443
[2018-03-20T20:36:34,636][DEBUG][o.a.h.i.c.DefaultManagedHttpClientConnection] http-outgoing-1: set socket timeout to 0
[2018-03-20T20:36:34,636][DEBUG][o.a.h.i.e.MainClientExec ] Opening connection {s}->https://example.com:443
[2018-03-20T20:36:34,644][DEBUG][o.a.h.i.c.DefaultHttpClientConnectionOperator] Connecting to example.com/10.0.0.1:443
[2018-03-20T20:36:34,644][DEBUG][o.a.h.c.s.SSLConnectionSocketFactory] Connecting socket to example.com/10.0.0.1:443 with timeout 0
[2018-03-20T20:36:34,692][DEBUG][o.a.h.c.s.SSLConnectionSocketFactory] Enabled protocols: [TLSv1, TLSv1.1, TLSv1.2]
[2018-03-20T20:36:34,693][DEBUG][o.a.h.c.s.SSLConnectionSocketFactory] Enabled cipher suites:[TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, ... etc ...]
[2018-03-20T20:36:34,693][DEBUG][o.a.h.c.s.SSLConnectionSocketFactory] Starting handshake
[2018-03-20T20:36:34,841][DEBUG][o.a.h.c.s.SSLConnectionSocketFactory] Secure session established
[2018-03-20T20:36:34,842][DEBUG][o.a.h.c.s.SSLConnectionSocketFactory] negotiated protocol: TLSv1.2
[2018-03-20T20:36:34,842][DEBUG][o.a.h.c.s.SSLConnectionSocketFactory] negotiated cipher suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
[2018-03-20T20:36:34,843][DEBUG][o.a.h.c.s.SSLConnectionSocketFactory] peer principal: CN=example.com
[2018-03-20T20:36:34,843][DEBUG][o.a.h.c.s.SSLConnectionSocketFactory] peer alternative names: [example.com, www.example.com]
[2018-03-20T20:36:34,843][DEBUG][o.a.h.c.s.SSLConnectionSocketFactory] issuer principal: CN=Let's Encrypt Authority X3, O=Let's Encrypt, C=US
[2018-03-20T20:36:34,844][DEBUG][o.a.h.i.c.DefaultHttpClientConnectionOperator] Connection established 192.168.0.29:36792<->10.0.0.1:443
[2018-03-20T20:36:34,844][DEBUG][o.a.h.i.e.MainClientExec ] Executing request POST /post HTTP/1.1
[2018-03-20T20:36:34,844][DEBUG][o.a.h.i.e.MainClientExec ] Target auth state: UNCHALLENGED
[2018-03-20T20:36:34,844][DEBUG][o.a.h.i.e.MainClientExec ] Proxy auth state: UNCHALLENGED
[2018-03-20T20:36:34,845][DEBUG][o.a.h.headers ] http-outgoing-1 >> POST /post HTTP/1.1
[2018-03-20T20:36:34,845][DEBUG][o.a.h.headers ] http-outgoing-1 >> Connection: close
[2018-03-20T20:36:34,845][DEBUG][o.a.h.headers ] http-outgoing-1 >> accept-encoding: gzip, deflate
[2018-03-20T20:36:34,845][DEBUG][o.a.h.headers ] http-outgoing-1 >> Content-Length: 14
[2018-03-20T20:36:34,845][DEBUG][o.a.h.headers ] http-outgoing-1 >> Content-Type: text/plain; charset=UTF-8
[2018-03-20T20:36:34,846][DEBUG][o.a.h.headers ] http-outgoing-1 >> Host: example.com
[2018-03-20T20:36:34,846][DEBUG][o.a.h.headers ] http-outgoing-1 >> User-Agent: Apache-HttpClient/4.5.5 (Java/9.0.1)
[2018-03-20T20:36:34,846][DEBUG][o.a.h.wire ] http-outgoing-1 >> "POST /post HTTP/1.1[\r][\n]"
[2018-03-20T20:36:34,846][DEBUG][o.a.h.wire ] http-outgoing-1 >> "Connection: close[\r][\n]"
[2018-03-20T20:36:34,846][DEBUG][o.a.h.wire ] http-outgoing-1 >> "accept-encoding: gzip, deflate[\r][\n]"
[2018-03-20T20:36:34,847][DEBUG][o.a.h.wire ] http-outgoing-1 >> "Content-Length: 14[\r][\n]"
[2018-03-20T20:36:34,847][DEBUG][o.a.h.wire ] http-outgoing-1 >> "Content-Type: text/plain; charset=UTF-8[\r][\n]"
[2018-03-20T20:36:34,847][DEBUG][o.a.h.wire ] http-outgoing-1 >> "Host: example.com[\r][\n]"
etc etc it will go on forever and be very verbose
#+END_SRC

This provides both the data sent and received on the wire for debugging purposes.

I've also provided an example for changing the log level from clojure in
=examples/logging-apache-requests.clj=.

* Authentication
:PROPERTIES:
:CUSTOM_ID: h-87f38469-36b4-44c6-ae74-0d8f5e80c2ed
@@ -0,0 +1,23 @@
(ns clj-http.examples.logging-apache-requests
"This is an example of configuring Apache's log4j2 logging from Clojure, so
that the http client logging can be seen"
(:require [clj-http.client :as http])
(:import (org.apache.logging.log4j Level
LogManager)))

;; This is a helper function to change the log level for log4j2. If you use a
;; different logging framework (and subsequently a different bridge for log4j
;; then you'll need to substitute your own logging configuration
(defn change-log-level! [logger-name level]
(let [ctx (LogManager/getContext false)
config (.getConfiguration ctx)
logger-config (.getLoggerConfig config logger-name)]
(.setLevel logger-config level)
(.updateLoggers ctx)))

;; Here is an example of using it to change the root logger to "DEBUG" and the
;; back to "INFO" after a request has been completed
(defn post-page-with-debug []
(change-log-level! LogManager/ROOT_LOGGER_NAME Level/DEBUG)
(http/post "https://httpbin.org/post" {:body "this is a test"})
(change-log-level! LogManager/ROOT_LOGGER_NAME Level/INFO))
@@ -14,6 +14,7 @@
[commons-codec "1.11"]
[commons-io "2.6"]
[potemkin "0.4.4"]]
:resource-paths ["resources"]
:profiles {:dev {:dependencies [;; optional deps
[cheshire "5.8.0"]
[crouton "0.1.2"]
@@ -23,11 +24,14 @@
;; other (testing) deps
[org.clojure/clojure "1.9.0"]
[org.clojure/tools.logging "0.4.0"]
[log4j "1.2.17"]
[ring/ring-jetty-adapter "1.6.3"]
[ring/ring-devel "1.6.3"]
;; caching example deps
[org.clojure/core.cache "0.7.1"]]
[org.clojure/core.cache "0.7.1"]
;; logging
[org.apache.logging.log4j/log4j-api "2.11.0"]
[org.apache.logging.log4j/log4j-core "2.11.0"]
[org.apache.logging.log4j/log4j-1.2-api "2.11.0"]]
:plugins [[lein-ancient "0.6.15"]]}
:1.6 {:dependencies [[org.clojure/clojure "1.6.0"]]}
:1.7 {:dependencies [[org.clojure/clojure "1.7.0"]]}
@@ -0,0 +1,38 @@
###
# While no means required, this is an example log4j2.properties that you can use
# for debugging clj-http (mostly the apache http client side). See the readme or
# examples directory for how to use it.

# Change this to "debug" to get debugging information
rootLogger.level = info
rootLogger.appenderRef.console.ref = console
rootLogger.appenderRef.rolling.ref = fileLogger

# Give directory path where log files should get stored
property.basePath = ./log/
status = error

# ConsoleAppender will print logs on console
appender.console.type = Console
appender.console.name = console
appender.console.layout.type = PatternLayout
# Specify the pattern of the logs
appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] %marker%m%n

# RollingFileAppender will print logs in file which can be rotated based on time
# or size
appender.rolling.type = RollingFile
appender.rolling.name = fileLogger
appender.rolling.fileName=${basePath}/clj-http.log
appender.rolling.filePattern=${basePath}clj-http_%d{yyyyMMdd}.log.gz
appender.rolling.layout.type = PatternLayout
appender.rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] %marker%m%n
appender.rolling.policies.type = Policies

# Mention package name here in place of example. Classes in this package or
# subpackages will use ConsoleAppender and RollingFileAppender for logging
logger.example.name = example
logger.example.level = debug
logger.example.additivity = false
logger.example.appenderRef.rolling.ref = fileLogger
logger.example.appenderRef.console.ref = console
@@ -13,7 +13,10 @@
(:import (java.io ByteArrayInputStream)
(java.nio.charset StandardCharsets)
(java.net UnknownHostException)
(org.apache.http HttpEntity)))
(org.apache.http HttpEntity)
(org.apache.logging.log4j LogManager)))

(defonce logger (LogManager/getLogger "clj-http.test.client-test"))

(def base-req
{:scheme :http
@@ -9,6 +9,7 @@
[clojure.test :refer :all]
[ring.adapter.jetty :as ring])
(:import (java.io ByteArrayInputStream)
(java.net SocketTimeoutException)
(java.util.concurrent TimeoutException TimeUnit)
(org.apache.http.params CoreConnectionPNames CoreProtocolPNames)
(org.apache.http.message BasicHeader BasicHeaderIterator)
@@ -21,9 +22,11 @@
(org.apache.http.protocol HttpContext ExecutionContext)
(org.apache.http.impl.client DefaultHttpClient)
(org.apache.http.client.params ClientPNames)
(java.net SocketTimeoutException)
(org.apache.logging.log4j LogManager)
(sun.security.provider.certpath SunCertPathBuilderException)))

(defonce logger (LogManager/getLogger "clj-http.test.core-test"))

(defn handler [req]
(condp = [(:request-method req) (:uri req)]
[:get "/get"]

0 comments on commit 1e530f7

Please sign in to comment.
You can’t perform that action at this time.