且构网

分享程序员开发的那些事...
且构网 - 分享程序员编程开发的那些事

Apache HttpClient库的日志级别设置原理

更新时间:2022-09-11 10:13:48

在你的业务类的构造函数里调用下面这个enable方法,以启用日志:

private void enableHeaderWireAndContextLogging(){
        System.setProperty("org.apache.commons.logging.Log", "org.apache.commons.logging.impl.SimpleLog");
        System.setProperty("org.apache.commons.logging.simplelog.showdatetime", "true");
        System.setProperty("org.apache.commons.logging.simplelog.log.httpclient.wire.header", "debug");
        System.setProperty("org.apache.commons.logging.simplelog.log.org.apache.commons.httpclient", "debug");
        System.setProperty("org.apache.commons.logging.simplelog.defaultlog", "debug");
    }

在SimpleLog的实现里,下列代码会从SystemProperty里读取用户用代码进行的设置:

Apache HttpClient库的日志级别设置原理debug级别的日志输出很全:


2019/05/24 16:58:16:397 CST [DEBUG] RequestAddCookies - CookieSpec selected: default

2019/05/24 16:58:16:417 CST [DEBUG] RequestAuthCache - Auth cache not set in the context

2019/05/24 16:58:16:614 CST [DEBUG] PoolingHttpClientConnectionManager - Connection request: [route: {s}->https://hybris.com:443][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 20]

2019/05/24 16:58:21:265 CST [DEBUG] PoolingHttpClientConnectionManager - Connection leased: [id: 0][route: {s}->https://hybris.com:443][total kept alive: 0; route allocated: 1 of 2; total allocated: 1 of 20]

2019/05/24 16:58:21:271 CST [DEBUG] MainClientExec - Opening connection {s}->https://hybris.com:443

2019/05/24 16:58:21:271 CST [DEBUG] DefaultHttpClientConnectionOperator - Connecting to hybris.com/69.145.197.197:443

2019/05/24 16:58:21:271 CST [DEBUG] SSLConnectionSocketFactory - Connecting socket to hybris.com/69.145.197.197:443 with timeout 0

2019/05/24 16:58:21:521 CST [DEBUG] SSLConnectionSocketFactory - Enabled protocols: [TLSv1, TLSv1.1, TLSv1.2]

2019/05/24 16:58:21:521 CST [DEBUG] SSLConnectionSocketFactory - Enabled cipher suites:[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_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, 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_3DES_EDE_CBC_SHA, TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]

2019/05/24 16:58:21:521 CST [DEBUG] SSLConnectionSocketFactory - Starting handshake

2019/05/24 16:58:21:849 CST [DEBUG] SSLConnectionSocketFactory - Secure session established

2019/05/24 16:58:21:849 CST [DEBUG] SSLConnectionSocketFactory - negotiated protocol: TLSv1.2

2019/05/24 16:58:21:849 CST [DEBUG] SSLConnectionSocketFactory - negotiated cipher suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256

2019/05/24 16:58:21:849 CST [DEBUG] SSLConnectionSocketFactory - peer principal: CN=gdm-acdo.apjdemo.hybris.com

2019/05/24 16:58:21:849 CST [DEBUG] SSLConnectionSocketFactory - peer alternative names: []

2019/05/24 16:58:21:849 CST [DEBUG] SSLConnectionSocketFactory - issuer principal: CN=Let’s Encrypt Authority X3, O=Let’s Encrypt, C=US

2019/05/24 16:58:21:849 CST [DEBUG] DefaultHttpClientConnectionOperator - Connection established 10.130.197.181:60875<->169.145.197.197:443

2019/05/24 16:58:21:849 CST [DEBUG] MainClientExec - Executing request GET /sap/opu/odata/sap/CUAN_CONTACT_SRV HTTP/1.1

2019/05/24 16:58:21:849 CST [DEBUG] MainClientExec - Proxy auth state: UNCHALLENGED

2019/05/24 16:58:21:849 CST [DEBUG] headers - http-outgoing-0 >> GET /sap/opu/odata/sap/CUAN_CONTACT_SRV HTTP/1.1

2019/05/24 16:58:21:849 CST [DEBUG] headers - http-outgoing-0 >> Authorization: basic bWt0X2R

2019/05/24 16:58:21:849 CST [DEBUG] headers - http-outgoing-0 >> Cache-Control: no-cache

2019/05/24 16:58:21:849 CST [DEBUG] headers - http-outgoing-0 >> content-type: application/json

2019/05/24 16:58:21:849 CST [DEBUG] headers - http-outgoing-0 >> Accept: application/json

2019/05/24 16:58:21:849 CST [DEBUG] headers - http-outgoing-0 >> x-csrf-token: fetch

2019/05/24 16:58:21:849 CST [DEBUG] headers - http-outgoing-0 >> Host: gdm-hybris.com

2019/05/24 16:58:21:849 CST [DEBUG] headers - http-outgoing-0 >> Connection: Keep-Alive

2019/05/24 16:58:21:849 CST [DEBUG] headers - http-outgoing-0 >> User-Agent: Apache-HttpClient/4.5.1 (Java/1.8.0_60)

2019/05/24 16:58:21:849 CST [DEBUG] headers - http-outgoing-0 >> Accept-Encoding: gzip,deflate

2019/05/24 16:58:21:849 CST [DEBUG] wire - http-outgoing-0 >> “GET /sap/opu/odata/sap/CUAN_CONTACT_SRV HTTP/1.1[\r][\n]”

2019/05/24 16:58:21:849 CST [DEBUG] wire - http-outgoing-0 >> “Authorization: basic bWt0X2[\r][\n]”

2019/05/24 16:58:21:849 CST [DEBUG] wire - http-outgoing-0 >> “Cache-Control: no-cache[\r][\n]”

2019/05/24 16:58:21:849 CST [DEBUG] wire - http-outgoing-0 >> “content-type: application/json[\r][\n]”

2019/05/24 16:58:21:849 CST [DEBUG] wire - http-outgoing-0 >> “Accept: application/json[\r][\n]”

2019/05/24 16:58:21:849 CST [DEBUG] wire - http-outgoing-0 >> “x-csrf-token: fetch[\r][\n]”

2019/05/24 16:58:21:849 CST [DEBUG] wire - http-outgoing-0 >> “Host: gdm-acdo.apjdemo.hybris.com[\r][\n]”

2019/05/24 16:58:21:849 CST [DEBUG] wire - http-outgoing-0 >> “Connection: Keep-Alive[\r][\n]”

2019/05/24 16:58:21:849 CST [DEBUG] wire - http-outgoing-0 >> “User-Agent: Apache-HttpClient/4.5.1 (Java/1.8.0_60)[\r][\n]”

2019/05/24 16:58:21:849 CST [DEBUG] wire - http-outgoing-0 >> “Accept-Encoding: gzip,deflate[\r][\n]”

2019/05/24 16:58:21:849 CST [DEBUG] wire - http-outgoing-0 >> “[\r][\n]”

2019/05/24 16:58:22:061 CST [DEBUG] wire - http-outgoing-0 << “HTTP/1.1 307 Temporary Redirect[\r][\n]”

2019/05/24 16:58:22:061 CST [DEBUG] wire - http-outgoing-0 << “Server: nginx/1.14.2[\r][\n]”

2019/05/24 16:58:22:061 CST [DEBUG] wire - http-outgoing-0 << “Date: Fri, 24 May 2019 08:58:22 GMT[\r][\n]”

2019/05/24 16:58:22:061 CST [DEBUG] wire - http-outgoing-0 << “Content-Length: 0[\r][\n]”

2019/05/24 16:58:22:061 CST [DEBUG] wire - http-outgoing-0 << “Connection: keep-alive[\r][\n]”

2019/05/24 16:58:22:061 CST [DEBUG] wire - http-outgoing-0 << “set-cookie: sap-usercontext=sap-client=100; path=/[\r][\n]”

2019/05/24 16:58:22:061 CST [DEBUG] wire - http-outgoing-0 << “set-cookie: SAP_SEhIHE%3d; path=/; secure; HttpOnly[\r][\n]”

2019/05/24 16:58:22:061 CST [DEBUG] wire - http-outgoing-0 << “x-csrf-token: kVwN39IxT6wSsOnjgeSGww==[\r][\n]”

2019/05/24 16:58:22:061 CST [DEBUG] wire - http-outgoing-0 << “location: https://hybris.com:443/sap/opu/odata/sap/CUAN_CONTACT_SRV/[\r][\n]

2019/05/24 16:58:22:061 CST [DEBUG] wire - http-outgoing-0 << “sap-processing-info: ODataBEP=,crp=,st=,MedCacheHub=,codeployed=X,softstate=[\r][\n]”

2019/05/24 16:58:22:061 CST [DEBUG] wire - http-outgoing-0 << “sap-server: true[\r][\n]”

2019/05/24 16:58:22:061 CST [DEBUG] wire - http-outgoing-0 << “sap-perf-fesrec: 42584.000000[\r][\n]”

2019/05/24 16:58:22:061 CST [DEBUG] wire - http-outgoing-0 << “[\r][\n]”

2019/05/24 16:58:22:061 CST [DEBUG] headers - http-outgoing-0 << HTTP/1.1 307 Temporary Redirect

2019/05/24 16:58:22:061 CST [DEBUG] headers - http-outgoing-0 << Server: nginx/1.14.2

2019/05/24 16:58:22:061 CST [DEBUG] headers - http-outgoing-0 << Date: Fri, 24 May 2019 08:58:22 GMT

2019/05/24 16:58:22:061 CST [DEBUG] headers - http-outgoing-0 << Content-Length: 0

2019/05/24 16:58:22:061 CST [DEBUG] headers - http-outgoing-0 << Connection: keep-alive

2019/05/24 16:58:22:061 CST [DEBUG] headers - http-outgoing-0 << set-cookie: sap-usercontext=sap-client=100; path=/

2019/05/24 16:58:22:061 CST [DEBUG] headers - http-outgoing-0 << set-cookie: SAP_SESSIONID_E4T_100=a-dtZMlUCPrNMQYUQYcL8RULy6l-AhHpqRECAAohIHE%3d; path=/; secure; HttpOnly

2019/05/24 16:58:22:061 CST [DEBUG] headers - http-outgoing-0 << x-csrf-token: kVwSGww==

2019/05/24 16:58:22:061 CST [DEBUG] headers - http-outgoing-0 << location: https://hybris.com:443/sap/opu/odata/sap/CUAN_CONTACT_SRV/

2019/05/24 16:58:22:061 CST [DEBUG] headers - http-outgoing-0 << sap-processing-info: ODataBEP=,crp=,st=,MedCacheHub=,codeployed=X,softstate=

2019/05/24 16:58:22:061 CST [DEBUG] headers - http-outgoing-0 << sap-server: true

2019/05/24 16:58:22:061 CST [DEBUG] headers - http-outgoing-0 << sap-perf-fesrec: 42584.000000

2019/05/24 16:58:22:061 CST [DEBUG] MainClientExec - Connection can be kept alive indefinitely

2019/05/24 16:58:22:061 CST [DEBUG] PoolingHttpClientConnectionManager - Connection [id: 0][route: {s}->https://hybris.com:443] can be kept alive indefinitely

2019/05/24 16:58:22:061 CST [DEBUG] PoolingHttpClientConnectionManager - Connection released: [id: 0][route: {s}->https://hybris.com:443][total kept alive: 1; route allocated: 1 of 2; total allocated: 1 of 20]

2019/05/24 16:58:22:061 CST [DEBUG] ResponseProcessCookies - Cookie accepted [sap-usercontext=“sap-client=100”, version:0, domain:hybris.com, path:/, expiry:null]

2019/05/24 16:58:22:061 CST [DEBUG] ResponseProcessCookies - Cookie accepted [SAP_SESSIONID_E4T_100=“a-dtZMlUCPrNMQYUQYcL8RULy6l-AhHpqRECAAohIHE%3d”, version:0, domain:gdm-acdo.apjdemo.hybris.com, path:/, expiry:null]

2019/05/24 16:58:22:925 CST [DEBUG] DefaultRedirectStrategy - Redirect requested to location ‘https://hybris.com:443/sap/opu/odata/sap/CUAN_CONTACT_SRV/

2019/05/24 16:58:24:219 CST [DEBUG] RedirectExec - Redirecting to ‘https://hybris.com:443/sap/opu/odata/sap/CUAN_CONTACT_SRV/’ via {s}->https://gdm-acdo.apjdemo.hybris.com:443

2019/05/24 16:58:24:230 CST [DEBUG] RequestAddCookies - CookieSpec selected: default

2019/05/24 16:58:24:230 CST [DEBUG] RequestAddCookies - Cookie [version: 0][name: SAP_SESSIONID_E4T_100][value: a-dtZMlUCPrNMQYUQYcL8RULy6l-AhHpqRECAAohIHE%3d][domain: gdm-acdo.apjdemo.hybris.com][path: /][expiry: null] match [(secure)hybris.com:443/sap/opu/odata/sap/CUAN_CONTACT_SRV/]

2019/05/24 16:58:24:230 CST [DEBUG] RequestAddCookies - Cookie [version: 0][name: sap-usercontext][value: sap-client=100][domain: gdm-acdo.apjdemo.hybris.com][path: /][expiry: null] match [(secure)hybris.com:443/sap/opu/odata/sap/CUAN_CONTACT_SRV/]

2019/05/24 16:58:24:231 CST [DEBUG] RequestAuthCache - Auth cache not set in the context

2019/05/24 16:58:24:995 CST [DEBUG] PoolingHttpClientConnectionManager - Connection request: [route: {s}->https://hybris.com:443][total kept alive: 1; route allocated: 1 of 2; total allocated: 1 of 20]

2019/05/24 16:58:24:997 CST [DEBUG] wire - http-outgoing-0 << “[read] I/O error: Read timed out”

2019/05/24 16:58:24:997 CST [DEBUG] PoolingHttpClientConnectionManager - Connection leased: [id: 0][route: {s}->https://hybris.com:443][total kept alive: 0; route allocated: 1 of 2; total allocated: 1 of 20]

2019/05/24 16:58:24:998 CST [DEBUG] MainClientExec - Executing request GET /sap/opu/odata/sap/CUAN_CONTACT_SRV/ HTTP/1.1

2019/05/24 16:58:24:998 CST [DEBUG] MainClientExec - Proxy auth state: UNCHALLENGED

2019/05/24 16:58:24:998 CST [DEBUG] headers - http-outgoing-0 >> GET /sap/opu/odata/sap/CUAN_CONTACT_SRV/ HTTP/1.1

2019/05/24 16:58:24:998 CST [DEBUG] headers - http-outgoing-0 >> Authorization: basic bWt0X2Rl5

2019/05/24 16:58:24:998 CST [DEBUG] headers - http-outgoing-0 >> Cache-Control: no-cache

2019/05/24 16:58:24:998 CST [DEBUG] headers - http-outgoing-0 >> content-type: application/json

2019/05/24 16:58:24:998 CST [DEBUG] headers - http-outgoing-0 >> Accept: application/json

2019/05/24 16:58:24:998 CST [DEBUG] headers - http-outgoing-0 >> x-csrf-token: fetch

2019/05/24 16:58:24:998 CST [DEBUG] headers - http-outgoing-0 >> Host: gdm-acdo.apjdemo.hybris.com:443

2019/05/24 16:58:24:998 CST [DEBUG] headers - http-outgoing-0 >> Connection: Keep-Alive

2019/05/24 16:58:24:998 CST [DEBUG] headers - http-outgoing-0 >> User-Agent: Apache-HttpClient/4.5.1 (Java/1.8.0_60)

2019/05/24 16:58:24:998 CST [DEBUG] headers - http-outgoing-0 >> Cookie: SAP_SESSIONID_E4T_100=a-dtZMlUYcL8RULy6l-AhHpqRECAAohIHE%3d; sap-usercontext=sap-client=100

2019/05/24 16:58:24:998 CST [DEBUG] headers - http-outgoing-0 >> Accept-Encoding: gzip,deflate

2019/05/24 16:58:24:998 CST [DEBUG] wire - http-outgoing-0 >> “GET /sap/opu/odata/sap/CUAN_CONTACT_SRV/ HTTP/1.1[\r][\n]”

2019/05/24 16:58:24:999 CST [DEBUG] wire - http-outgoing-0 >> “Authorization: basic bWt0X2RldjpNWVdlbGNvbWU5[\r][\n]”

2019/05/24 16:58:24:999 CST [DEBUG] wire - http-outgoing-0 >> “Cache-Control: no-cache[\r][\n]”

2019/05/24 16:58:24:999 CST [DEBUG] wire - http-outgoing-0 >> “content-type: application/json[\r][\n]”

2019/05/24 16:58:24:999 CST [DEBUG] wire - http-outgoing-0 >> “Accept: application/json[\r][\n]”

2019/05/24 16:58:24:999 CST [DEBUG] wire - http-outgoing-0 >> “x-csrf-token: fetch[\r][\n]”

2019/05/24 16:58:24:999 CST [DEBUG] wire - http-outgoing-0 >> “Host: hybris.com:443[\r][\n]”

2019/05/24 16:58:24:999 CST [DEBUG] wire - http-outgoing-0 >> “Connection: Keep-Alive[\r][\n]”

2019/05/24 16:58:24:999 CST [DEBUG] wire - http-outgoing-0 >> “User-Agent: Apache-HttpClient/4.5.1 (Java/1.8.0_60)[\r][\n]”

2019/05/24 16:58:24:999 CST [DEBUG] wire - http-outgoing-0 >> “Cookie: SAP_SESSIONID_E4T_100=a-dtZMlUCPrhIHE%3d; sap-usercontext=sap-client=100[\r][\n]”

2019/05/24 16:58:24:999 CST [DEBUG] wire - http-outgoing-0 >> “Accept-Encoding: gzip,deflate[\r][\n]”

2019/05/24 16:58:24:999 CST [DEBUG] wire - http-outgoing-0 >> “[\r][\n]”

2019/05/24 16:58:25:154 CST [DEBUG] wire - http-outgoing-0 << “HTTP/1.1 500 Internal Server Error[\r][\n]”

2019/05/24 16:58:25:154 CST [DEBUG] wire - http-outgoing-0 << “Server: nginx/1.14.2[\r][\n]”

2019/05/24 16:58:25:154 CST [DEBUG] wire - http-outgoing-0 << “Date: Fri, 24 May 2019 08:58:25 GMT[\r][\n]”

2019/05/24 16:58:25:154 CST [DEBUG] wire - http-outgoing-0 << “Content-Type: text/html[\r][\n]”

2019/05/24 16:58:25:154 CST [DEBUG] wire - http-outgoing-0 << “Content-Length: 193[\r][\n]”

2019/05/24 16:58:25:154 CST [DEBUG] wire - http-outgoing-0 << “Connection: close[\r][\n]”

2019/05/24 16:58:25:154 CST [DEBUG] wire - http-outgoing-0 << “[\r][\n]”

2019/05/24 16:58:25:154 CST [DEBUG] wire - http-outgoing-0 << “[\r][\n]”

2019/05/24 16:58:25:155 CST [DEBUG] wire - http-outgoing-0 << “[\r][\n]”

2019/05/24 16:58:25:155 CST [DEBUG] wire - http-outgoing-0 << “[\r][\n]”

2019/05/24 16:58:25:155 CST [DEBUG] wire - http-outgoing-0 << “


500 Internal Server Error

[\r][\n]”

2019/05/24 16:58:25:155 CST [DEBUG] wire - http-outgoing-0 << “

nginx/1.14.2

[\r][\n]”

2019/05/24 16:58:25:155 CST [DEBUG] wire - http-outgoing-0 << “[\r][\n]”

2019/05/24 16:58:25:155 CST [DEBUG] wire - http-outgoing-0 << “[\r][\n]”

2019/05/24 16:58:25:155 CST [DEBUG] headers - http-outgoing-0 << HTTP/1.1 500 Internal Server Error

2019/05/24 16:58:25:155 CST [DEBUG] headers - http-outgoing-0 << Server: nginx/1.14.2

2019/05/24 16:58:25:155 CST [DEBUG] headers - http-outgoing-0 << Date: Fri, 24 May 2019 08:58:25 GMT

2019/05/24 16:58:25:155 CST [DEBUG] headers - http-outgoing-0 << Content-Type: text/html

2019/05/24 16:58:25:155 CST [DEBUG] headers - http-outgoing-0 << Content-Length: 193

2019/05/24 16:58:25:155 CST [DEBUG] headers - http-outgoing-0 << Connection: close

Status code: 500

reason: Internal Server Error