Skip to main content

How to Debug Outbound HTTP Requests in Repository 3

Peter
Updated

.

Sonatype Nexus Repository 3 requires outbound HTTP access to many external hosts and URLs. Sometimes these outbound requests fail for unknown reasons. Examining the outbound request URLs, the response status codes and HTTP headers of the requests and responses can help debug problems.

An administrator can enable log statements that print the outbound HTTP request and response details into the nexus.log.

Summary Outbound Request Logging

Using the outbound-request.log

New as of version 3.59.0 is a log file named outbound-request.log that records outbound http requests. Use the contents of this log to verify if and where outbound requests were made.

The outbound request log rotates daily, maintains 90 days of compressed log files by default. The log format closely matches the normal inbound request.log, including information such as date/time, authenticated remote user id, method, url, response status code, bytes sent, bytes received, and response time, and thread id.

Samples of the types of log lines you might find in the outbound request log are:

[27/Nov/2023:15:15:05 -0400] - "GET https://repo1.maven.org/maven2/abbot/abbot/0.13.0/abbot-0.13.0.pom HTTP/1.1" 200 166 285 "Nexus/3.63.0-01 (PRO; Mac OS X; 14.1.1; aarch64; 1.8.0_382; pae)" [qtp1085283394-921]
[27/Nov/2023:15:15:22 -0400] - "GET https://repo1.maven.org/maven2/abbot/abbot/10.0.0/abbot-10.0.0.pom HTTP/1.1" 404 554 85 "Nexus/3.63.0-01 (PRO; Mac OS X; 14.1.1; aarch64; 1.8.0_382; pae)" [qtp1085283394-921]

Tip: Comparing the thread id and timings between the inbound request.log, and outbound-request.log can help verify what outbound requests and inbound request has triggered.

Quieting the outbound-request.log

Turning off the outbound request log logger is not recommended. Diagnosing issues resolving repository content will be much more difficult if this logger is quieted.

If you do still have a need to quiet this logger, one can add a new logger named outboundRequests and set its log level to WARN or higher.

Using the nexus.log outbound logger for Remote Repository Requests

As of release 3.59.0, it is now preferred to utilize the outbound-request.log instead for this tracing.

The intent of outbound summary logging is to log a minimum of statements to understand what remote URLs are being accessed in response to any inbound repository request. This logging records:

  • full outbound URL being requested, including HTTP method and protocol used
  • if a response is returned, the HTTP status line and time elapsed between when the request started to the first response of HTTP headers from the remote. The time elapsed does not include the total time to receive the entire response body
  • if a response is not received, you will not see a corresponding response line - however, you may see other log messages describing a problem

Use Cases

This logging is particularly useful to understand what proxy repository members' outbound requests were used to resolve an inbound request to a group repository.

The logging may help isolate unexpected 3xx redirects to servers that need to be whitelisted by an HTTP proxy server or firewall.

By tracking the thread id and the URLs being used, one can relate the log requests together for the same inbound request.

Example

2019-03-11 13:39:43,485-0300 DEBUG [qtp1014084813-360] admin org.sonatype.nexus.httpclient.outbound - https://repo1.maven.org/maven2/org/springframework/boot/spring-boot/1.5.17.RELEASE/spring-boot-1.5.17.RELEASE-javadoc.jar > GET /maven2/org/springframework/boot/spring-boot/1.5.17.RELEASE/spring-boot-1.5.17.RELEASE-javadoc.jar HTTP/1.1
2019-03-11 13:39:43,831-0300 DEBUG [qtp1014084813-360] admin org.sonatype.nexus.httpclient.outbound - https://repo1.maven.org/maven2/org/springframework/boot/spring-boot/1.5.17.RELEASE/spring-boot-1.5.17.RELEASE-javadoc.jar < HTTP/1.1 200 OK @ 351.0 ms
2019-03-11 13:39:44,702-0300 DEBUG [qtp1014084813-360] admin org.sonatype.nexus.httpclient.outbound - http://localhost:8070/rest/integration/repositories/9AA91332-F6541AD7-5C6AC8E7-E0AD5F2D-04F4056A/maven-central-3/evaluate/quarantine > POST /rest/integration/repositories/9AA91332-F6541AD7-5C6AC8E7-E0AD5F2D-04F4056A/maven-central-3/evaluate/quarantine HTTP/1.1
2019-03-11 13:39:44,709-0300 WARN  [qtp1014084813-360] admin com.sonatype.nexus.clm.internal.FirewallContributedHandler - Could not get latest quarantine status for asset maven-central-3:org/springframework/boot/spring-boot/1.5.17.RELEASE/spring-boot-1.5.17.RELEASE-javadoc.jar: Connect to localhost:8070 [localhost/127.0.0.1] failed: Connection refused (Connection refused)
2019-03-11 13:39:44,724-0300 INFO  [qtp1014084813-360] admin com.sonatype.nexus.clm.internal.FirewallContributedHandler - Blocked serving of quarantined asset maven-central-3:org/springframework/boot/spring-boot/1.5.17.RELEASE/spring-boot-1.5.17.RELEASE-javadoc.jar because quarantineStatus=PENDING

Enabling Outbound Repository Request Summary Logging

  1. Open the Logging Configuration to make changes.
  2. In the top right filter field type 'outbound'
  3. Select the logger named org.sonatype.nexus.httpclient.outboundand change the level value to DEBUG.
  4. Click Update. Changes take effect without requiring a server restart.

Disabling Outbound Repository Request Summary Logging

  1. Open the Logging Configuration to make changes.
  2. In the top right filter field type 'outbound'
  3. Select the logger named org.sonatype.nexus.httpclient.outboundand change the level value back to the default INFO level.
  4. Click Update. Changes take effect without requiring a server restart.

Detailed Outbound HTTP Header Logging

All outbound HTTP requests Nexus Repository 3 makes use Apache httpclient libraries.

For every outbound request, including those which have nothing to do with inbound repository content requests, you can enable logging statements that print the full outbound HTTP request and response headers.

CAUTION: This logging is very verbose. Enabling this logging should only be done on a short term to diagnose a specific problem and then immediately be reset back to default levels.

Enabling Outbound HTTP Header Detailed Logging

Caution: This logging is verbose and may print outbound authentication headers in the nexus.log. Enabling this logging should be constrained to the time period required to investigate a problem.

Logger-level changes take effect immediately and do not require a restart of the server.

  1. Open the Logging configuration to make changes.
  2. Click Create logger button
  3. On the Create Logger screen set these values:
    1. Logger name: org.apache.http
    2. Logger level: DEBUG
    Save these changes. If asked to Confirm Update? then click Yes.
  4. Reproduce a scenario that causes Nexus to trigger an outbound request. Examine the nexus.log for activity from the org.apache.http logger.

Disabling Outbound HTTP Header Detailed Logging

When you are done reproducing a problem and examining the HTTP outbound requests in the nexus.log, it is important to reset the log levels to sensible defaults.

Option 1: Reset all Loggers to default levels

  1. Open the Logging configuration to make changes.
  2. Click Reset to default levels button to reset all Loggers to their shipped default values

Option 2: Change a specific Logger level to a previous value

  1. Open the Logging configuration to make changes.
  2. Use the Filter field at top right to find the Logger needing adjustment.

    For example, to find the org.apache.http logger, type that name into the filter field.
  3. Select the found logger in the table and change the Level value to its new value. For example, change the org.apache.http logger back to INFO.
  4. Click Update to save the logger level changes.

Example Outbound HTTP Header Detailed Logging Statements

Here are example log statements similar to what you might see when loading the Welcome page in the Nexus Repository 3 UI:

2017-11-28 15:33:12,518-0400 DEBUG [qtp940770288-59] admin org.apache.http.client.protocol.RequestAddCookies - CookieSpec selected: ignoreCookies
2017-11-28 15:33:12,518-0400 DEBUG [qtp940770288-59] admin org.apache.http.client.protocol.RequestAuthCache - Auth cache not set in the context
2017-11-28 15:33:12,518-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.execchain.MainClientExec - Opening connection {}->http://links.sonatype.com:80
2017-11-28 15:33:12,518-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.conn.DefaultHttpClientConnectionOperator - Connecting to links.sonatype.com/207.223.241.68:80
2017-11-28 15:33:12,573-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.conn.DefaultHttpClientConnectionOperator - Connection established 192.168.2.97:64725<->207.223.241.68:80
2017-11-28 15:33:12,573-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.conn.DefaultManagedHttpClientConnection - http-outgoing-7: set socket timeout to 20000
2017-11-28 15:33:12,573-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.execchain.MainClientExec - Executing request GET /products/nexus/outreach/pro/3.6.1-02/en/admin HTTP/1.1
2017-11-28 15:33:12,573-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.execchain.MainClientExec - Target auth state: UNCHALLENGED
2017-11-28 15:33:12,573-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.execchain.MainClientExec - Proxy auth state: UNCHALLENGED
2017-11-28 15:33:12,573-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-7 >> GET /products/nexus/outreach/pro/3.6.1-02/en/admin HTTP/1.1
2017-11-28 15:33:12,573-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-7 >> Host: links.sonatype.com
2017-11-28 15:33:12,573-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-7 >> Connection: Keep-Alive
2017-11-28 15:33:12,573-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-7 >> User-Agent: Nexus/3.6.1-02 (PRO; Mac OS X; 10.12.6; x86_64; 1.8.0_131)
2017-11-28 15:33:12,573-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-7 >> Accept-Encoding: gzip,deflate
2017-11-28 15:33:12,625-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-7 << HTTP/1.1 302 Found
2017-11-28 15:33:12,625-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-7 << Date: Tue, 28 Nov 2017 19:33:12 GMT
2017-11-28 15:33:12,625-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-7 << Server: Apache
2017-11-28 15:33:12,625-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-7 << Location: http://download.sonatype.com/nexus/outreach/pro-en-all-admin.zip
2017-11-28 15:33:12,625-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-7 << Content-Length: 316
2017-11-28 15:33:12,625-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-7 << Connection: close
2017-11-28 15:33:12,625-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-7 << Content-Type: text/html; charset=iso-8859-1
2017-11-28 15:33:12,625-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.client.DefaultRedirectStrategy - Redirect requested to location 'http://download.sonatype.com/nexus/outreach/pro-en-all-admin.zip'
2017-11-28 15:33:12,625-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.execchain.RedirectExec - Resetting target auth state
2017-11-28 15:33:12,625-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.execchain.RedirectExec - Redirecting to 'http://download.sonatype.com/nexus/outreach/pro-en-all-admin.zip' via {}->http://download.sonatype.com:80
2017-11-28 15:33:12,625-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.conn.DefaultManagedHttpClientConnection - http-outgoing-7: Close connection
2017-11-28 15:33:12,625-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.execchain.MainClientExec - Connection discarded
2017-11-28 15:33:12,625-0400 DEBUG [qtp940770288-59] admin org.apache.http.client.protocol.RequestAddCookies - CookieSpec selected: ignoreCookies
2017-11-28 15:33:12,625-0400 DEBUG [qtp940770288-59] admin org.apache.http.client.protocol.RequestAuthCache - Auth cache not set in the context
2017-11-28 15:33:12,625-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.conn.DefaultManagedHttpClientConnection - http-outgoing-2: set socket timeout to 20000
2017-11-28 15:33:12,625-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.execchain.MainClientExec - Executing request GET /nexus/outreach/pro-en-all-admin.zip HTTP/1.1
2017-11-28 15:33:12,625-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.execchain.MainClientExec - Target auth state: UNCHALLENGED
2017-11-28 15:33:12,626-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.execchain.MainClientExec - Proxy auth state: UNCHALLENGED
2017-11-28 15:33:12,626-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-2 >> GET /nexus/outreach/pro-en-all-admin.zip HTTP/1.1
2017-11-28 15:33:12,626-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-2 >> Host: download.sonatype.com
2017-11-28 15:33:12,626-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-2 >> Connection: Keep-Alive
2017-11-28 15:33:12,626-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-2 >> User-Agent: Nexus/3.6.1-02 (PRO; Mac OS X; 10.12.6; x86_64; 1.8.0_131)
2017-11-28 15:33:12,626-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-2 >> Accept-Encoding: gzip,deflate
2017-11-28 15:33:12,682-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-2 << HTTP/1.1 302 Found
2017-11-28 15:33:12,682-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-2 << Server: nginx
2017-11-28 15:33:12,682-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-2 << Date: Tue, 28 Nov 2017 19:33:12 GMT
2017-11-28 15:33:12,682-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-2 << Content-Type: text/html; charset=iso-8859-1
2017-11-28 15:33:12,682-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-2 << Content-Length: 337
2017-11-28 15:33:12,682-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-2 << Connection: keep-alive
2017-11-28 15:33:12,682-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-2 << Keep-Alive: timeout=5
2017-11-28 15:33:12,682-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-2 << Location: http://sonatype-download.global.ssl.fastly.net/nexus/outreach/pro-en-all-admin.zip
2017-11-28 15:33:12,682-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.execchain.MainClientExec - Connection can be kept alive for 5000 MILLISECONDS
2017-11-28 15:33:12,683-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.client.DefaultRedirectStrategy - Redirect requested to location 'http://sonatype-download.global.ssl.fastly.net/nexus/outreach/pro-en-all-admin.zip'
2017-11-28 15:33:12,683-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.execchain.RedirectExec - Resetting target auth state
2017-11-28 15:33:12,683-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.execchain.RedirectExec - Redirecting to 'http://sonatype-download.global.ssl.fastly.net/nexus/outreach/pro-en-all-admin.zip' via {}->http://sonatype-download.global.ssl.fastly.net:80
2017-11-28 15:33:12,683-0400 DEBUG [qtp940770288-59] admin org.apache.http.client.protocol.RequestAddCookies - CookieSpec selected: ignoreCookies
2017-11-28 15:33:12,683-0400 DEBUG [qtp940770288-59] admin org.apache.http.client.protocol.RequestAuthCache - Auth cache not set in the context
2017-11-28 15:33:12,683-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.conn.DefaultManagedHttpClientConnection - http-outgoing-3: set socket timeout to 20000
2017-11-28 15:33:12,683-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.execchain.MainClientExec - Executing request GET /nexus/outreach/pro-en-all-admin.zip HTTP/1.1
2017-11-28 15:33:12,683-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.execchain.MainClientExec - Target auth state: UNCHALLENGED
2017-11-28 15:33:12,683-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.execchain.MainClientExec - Proxy auth state: UNCHALLENGED
2017-11-28 15:33:12,683-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 >> GET /nexus/outreach/pro-en-all-admin.zip HTTP/1.1
2017-11-28 15:33:12,683-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 >> Host: sonatype-download.global.ssl.fastly.net
2017-11-28 15:33:12,683-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 >> Connection: Keep-Alive
2017-11-28 15:33:12,683-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 >> User-Agent: Nexus/3.6.1-02 (PRO; Mac OS X; 10.12.6; x86_64; 1.8.0_131)
2017-11-28 15:33:12,684-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 >> Accept-Encoding: gzip,deflate
2017-11-28 15:33:12,725-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 << HTTP/1.1 200 OK
2017-11-28 15:33:12,725-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 << Server: Apache
2017-11-28 15:33:12,725-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 << Last-Modified: Mon, 27 Nov 2017 18:49:15 GMT
2017-11-28 15:33:12,725-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 << ETag: "1682d2-a16d-55efb5be3a0c0"
2017-11-28 15:33:12,725-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 << Access-Control-Allow-Origin: *
2017-11-28 15:33:12,725-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 << Content-Type: application/zip
2017-11-28 15:33:12,725-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 << Content-Length: 41325
2017-11-28 15:33:12,725-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 << Accept-Ranges: bytes
2017-11-28 15:33:12,725-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 << Date: Tue, 28 Nov 2017 19:33:12 GMT
2017-11-28 15:33:12,725-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 << Via: 1.1 varnish
2017-11-28 15:33:12,726-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 << Age: 71661
2017-11-28 15:33:12,726-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 << Connection: keep-alive
2017-11-28 15:33:12,726-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 << X-Served-By: cache-jfk8130-JFK
2017-11-28 15:33:12,726-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 << X-Cache: HIT
2017-11-28 15:33:12,726-0400 DEBUG [qtp940770288-59] admin org.apache.http.headers - http-outgoing-3 << X-Cache-Hits: 5
2017-11-28 15:33:12,726-0400 DEBUG [qtp940770288-59] admin org.apache.http.impl.execchain.MainClientExec - Connection can be kept alive for 30000 MILLISECONDS

Related articles