search

dakrone / clj-http

An idiomatic clojure http client wrapping the apache client. Officially supported version.
http://clojars.org/clj-http
MIT License
1.78k stars 411 forks source link

logging with logback #504

Closed little-dude closed 5 years ago

little-dude commented 5 years ago

Hi,

I'm using luminus which uses logback by default instead of log4j2 and I can't get the logs from the http client. My project.clj looks like:

(defproject test-logging "0.1.0-SNAPSHOT"
  :description "FIXME: write description"
  :url "http://example.com/FIXME"
  :license {:name "EPL-2.0 OR GPL-2.0-or-later WITH Classpath-exception-2.0"
            :url "https://www.eclipse.org/legal/epl-2.0/"}
  :dependencies [[org.clojure/clojure "1.10.0"]
                 [ch.qos.logback/logback-classic "1.2.3"]
                 [org.clojure/tools.logging "0.4.1"]
                 [clj-http "3.10.0"]]
  :resource-paths ["resources"]
  :main ^:skip-aot test-logging.core
  :repl-options {:init-ns test-logging.core})

And in src/test_logging/core.clj I just have:

(ns test-logging.core
  (:require [clojure.tools.logging :as log]
            [clj-http.client :as http]))

(defn -main []
  (http/post "https://httpbin.org/post" {:body "this is a test"}))

The logback configuration file is under resources/logback.xml:

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true" scan="true" scanPeriod="10 seconds">

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</Pattern>
        </encoder>
    </appender>

    <root level="DEBUG">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

I'm new to the clojure and java world, and I'm a bit lost wrt logging, but as far as I understand, having logback as a dependency should just work out of the box no?

rymndhng commented 5 years ago

disclaimer: not an expert with the logging that is java, however I was able to get logback working by adding this dependency to your project: [org.slf4j/jcl-over-slf4j "2.0.0-alpha0"].

I looked at the logging documentation of Apache HTTPClient link. Then, I looked at this slf4j document to look at what library I needed to add in. See slf4j#legacy for reference.

Example output:

=> (http/post "https://httpbin.org/post" {:body "this is a test" })
23:47:12.173 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.c.protocol.RequestAddCookies - CookieSpec selected: default
23:47:12.174 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.c.protocol.RequestAuthCache - Auth cache not set in the context
23:47:12.175 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.i.c.BasicHttpClientConnectionManager - Get connection for route {s}->https://httpbin.org:443
23:47:12.175 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.i.c.DefaultManagedHttpClientConnection - http-outgoing-1: set socket timeout to 0
23:47:12.175 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.impl.execchain.MainClientExec - Opening connection {s}->https://httpbin.org:443
23:47:12.176 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.i.c.DefaultHttpClientConnectionOperator - Connecting to httpbin.org/34.202.34.10:443
23:47:12.177 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.c.s.SSLConnectionSocketFactory - Connecting socket to httpbin.org/34.202.34.10:443 with timeout 0
23:47:12.250 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.c.s.SSLConnectionSocketFactory - Enabled protocols: [TLSv1.3, TLSv1.2, TLSv1.1, TLSv1]
23:47:12.251 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.c.s.SSLConnectionSocketFactory - Enabled cipher suites:[TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384, TLS_CHACHA20_POLY1305_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256, TLS_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_RSA_WITH_CHACHA20_POLY1305_SHA256, TLS_DHE_DSS_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_DSS_WITH_AES_128_GCM_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384, TLS_RSA_WITH_AES_256_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384, TLS_DHE_RSA_WITH_AES_256_CBC_SHA256, TLS_DHE_DSS_WITH_AES_256_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
23:47:12.254 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.c.s.SSLConnectionSocketFactory - Starting handshake
23:47:12.418 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.c.s.SSLConnectionSocketFactory - Secure session established
23:47:12.419 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.c.s.SSLConnectionSocketFactory -  negotiated protocol: TLSv1.2
23:47:12.420 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.c.s.SSLConnectionSocketFactory -  negotiated cipher suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
23:47:12.421 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.c.s.SSLConnectionSocketFactory -  peer principal: CN=httpbin.org
23:47:12.422 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.c.s.SSLConnectionSocketFactory -  peer alternative names: [httpbin.org, *.httpbin.org]
23:47:12.423 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.c.s.SSLConnectionSocketFactory -  issuer principal: CN=Amazon, OU=Server CA 1B, O=Amazon, C=US
23:47:12.423 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.i.c.DefaultHttpClientConnectionOperator - Connection established 192.168.1.14:57465<->34.202.34.10:443
23:47:12.424 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.impl.execchain.MainClientExec - Executing request POST /post HTTP/1.1
23:47:12.424 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.impl.execchain.MainClientExec - Target auth state: UNCHALLENGED
23:47:12.425 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.impl.execchain.MainClientExec - Proxy auth state: UNCHALLENGED
23:47:12.425 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 >> POST /post HTTP/1.1
23:47:12.426 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 >> Connection: close
23:47:12.426 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 >> accept-encoding: gzip, deflate
23:47:12.427 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 >> Content-Length: 14
23:47:12.427 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 >> Content-Type: text/plain; charset=UTF-8
23:47:12.427 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 >> Host: httpbin.org
23:47:12.427 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 >> User-Agent: Apache-HttpClient/4.5.8 (Java/12)
23:47:12.428 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 >> "POST /post HTTP/1.1[\r][\n]"
23:47:12.428 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 >> "Connection: close[\r][\n]"
23:47:12.428 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 >> "accept-encoding: gzip, deflate[\r][\n]"
23:47:12.429 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 >> "Content-Length: 14[\r][\n]"
23:47:12.429 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 >> "Content-Type: text/plain; charset=UTF-8[\r][\n]"
23:47:12.429 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 >> "Host: httpbin.org[\r][\n]"
23:47:12.430 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 >> "User-Agent: Apache-HttpClient/4.5.8 (Java/12)[\r][\n]"
23:47:12.430 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 >> "[\r][\n]"
23:47:12.430 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 >> "this is a test"
23:47:12.504 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 << "HTTP/1.1 200 OK[\r][\n]"
23:47:12.505 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 << "Access-Control-Allow-Credentials: true[\r][\n]"
23:47:12.506 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 << "Access-Control-Allow-Origin: *[\r][\n]"
23:47:12.506 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 << "Content-Encoding: gzip[\r][\n]"
23:47:12.507 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 << "Content-Type: application/json[\r][\n]"
23:47:12.507 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 << "Date: Sun, 28 Jul 2019 06:47:12 GMT[\r][\n]"
23:47:12.508 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 << "Referrer-Policy: no-referrer-when-downgrade[\r][\n]"
23:47:12.509 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 << "Server: nginx[\r][\n]"
23:47:12.509 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 << "X-Content-Type-Options: nosniff[\r][\n]"
23:47:12.509 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 << "X-Frame-Options: DENY[\r][\n]"
23:47:12.510 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 << "X-XSS-Protection: 1; mode=block[\r][\n]"
23:47:12.510 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 << "Content-Length: 267[\r][\n]"
23:47:12.511 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 << "Connection: Close[\r][\n]"
23:47:12.511 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 << "[\r][\n]"
23:47:12.512 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 << "[0x1f][0x8b][0x8][0x0][0x0][0x0][0x0][0x0][0x0][0x3]e[0x90]_K[0xc3]0[0x14][0xc5][0xdf][0xfb])B[0x9e][0x14][0xfa][0xc7][0x96]n[0x8c][0x89][0xf]e(C|[0xdc]>@lo[0x93]HLBr'[0xea][0xd8]w[0xf7]f[0x9d][0xa3]"[0x4][0xc2]9[0xf7]w[0xf]'9f[0x8c]q[0x11]d[0xe4]kv<[0xe5],[0xc9]A[0xa0] [0xc9]Q[0xe9][0xc8][0xe8][0x8][0x86][0x10][0x91]O[0xc3]Q[0x1b][0x98][0xc3][0xa3][0xb][0xef]3[0xa9]@[0xc][0x10][0xce][0x0]I2[0xba][0xbe][0x7][0x8f][0xc5][0xa3][0xed][0xdd][0xa0][0xad]L[0xb9][0xf2][[0xfb][0x9c][\r]0[0x1a][0x81]0[0xc5][0x12][0xb8]q[0x16][0xc1]b[0xf1][0x2]V[0xa2]J\[0xdd][0xfe][0x1b][0xee][0xbe]<[0x9c][0xab][0xc1]'V[0xde][0x8]m[0xef]Y[0xaf]D[0x88][0x80][0xf][0xfb][0xdd]S[0xb1][0xba]nl[0x1d]U&R![0xfa]WmK[0x17][0xe4]u[0xb6][0x8f][0x10][0x8a]NR`":/z[0x5][0xc5][0x96][0xc0][0x8d][0xd1]dVm[0xb9](W[0xec][0xe6]Y|[0x88][0xaa]nn9m][0x9e][0xf7][0x16][0x9d][0xa5][0x1d]{0f2\[0xd0]R'[0x8b][0xd7][0xcb][0xa6]l[0xda]eY[0xdf][0xd1][0xb5][0xc8][0xd9]_}[0xf9][0xbd]C0[0xbf][0xa5][0xe2][0xba][0xaa]f[0xe5]*[0x9f][\n]"
23:47:12.513 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.wire - http-outgoing-1 << "g[0xa7][0xec][0x7]P![0x1][0x11][0x92][0x1][0x0][0x0]"
23:47:12.514 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 << HTTP/1.1 200 OK
23:47:12.514 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 << Access-Control-Allow-Credentials: true
23:47:12.515 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 << Access-Control-Allow-Origin: *
23:47:12.515 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 << Content-Encoding: gzip
23:47:12.516 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 << Content-Type: application/json
23:47:12.517 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 << Date: Sun, 28 Jul 2019 06:47:12 GMT
23:47:12.517 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 << Referrer-Policy: no-referrer-when-downgrade
23:47:12.518 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 << Server: nginx
23:47:12.519 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 << X-Content-Type-Options: nosniff
23:47:12.519 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 << X-Frame-Options: DENY
23:47:12.520 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 << X-XSS-Protection: 1; mode=block
23:47:12.520 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 << Content-Length: 267
23:47:12.521 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG org.apache.http.headers - http-outgoing-1 << Connection: Close
23:47:12.523 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.i.c.DefaultManagedHttpClientConnection - http-outgoing-1: Close connection
23:47:12.524 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.impl.execchain.MainClientExec - Connection discarded
23:47:12.525 [nRepl-session-26781851-4fb0-42ef-a542-0496f4f231b0] DEBUG o.a.h.i.c.BasicHttpClientConnectionManager - Releasing connection [Not bound]
little-dude commented 5 years ago

Thank you @rymndhng that was it! Logging seems to have quite a complicated history in the Java world.

rymndhng commented 5 years ago

Agreed it's not great. Obligatory XKCD 😆 https://xkcd.com/927/