Skip to content
This repository was archived by the owner on Nov 19, 2020. It is now read-only.

Commit a823c6e

Browse files
peterlynchpeterlynch
committed
Merge pull request #1539 from sonatype/NEXUS-8837-outbound-request-log-response-status
[NEXUS-8837] Add response status line to remote.storage.outbound and make consistent
2 parents b09af7d + c5475b1 commit a823c6e

File tree

3 files changed

+141
-28
lines changed

3 files changed

+141
-28
lines changed

‎components/nexus-core/src/main/java/org/sonatype/nexus/proxy/storage/remote/httpclient/HttpClientRemoteStorage.java‎

Lines changed: 16 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -509,18 +509,30 @@ HttpResponse executeRequest(final ProxyRepository repository, final ResourceStor
509509
final TimerContext timerContext = timer.time();
510510
Stopwatch stopwatch = null;
511511
if (outboundRequestLog.isDebugEnabled()) {
512-
stopwatch = new Stopwatch().start();
512+
outboundRequestLog.debug("[{}] {} {}",
513+
repository.getId(),
514+
httpRequest.getMethod(),
515+
httpRequest.getURI());
516+
stopwatch = Stopwatch.createStarted();
513517
}
518+
519+
HttpResponse response = null;
514520
try {
515-
return doExecuteRequest(repository, request, httpRequest, contentRequest);
521+
response = doExecuteRequest(repository, request, httpRequest, contentRequest);
516522
}
517523
finally {
518524
timerContext.stop();
519525
if (stopwatch != null) {
520-
outboundRequestLog
521-
.debug("[{}] {} {} - {}", repository.getId(), httpRequest.getMethod(), httpRequest.getURI(), stopwatch);
526+
outboundRequestLog.debug("[{}] {} {} -> {}; {}",
527+
repository.getId(),
528+
httpRequest.getMethod(),
529+
httpRequest.getURI(),
530+
response != null ? response.getStatusLine() : "null",
531+
stopwatch);
522532
}
523533
}
534+
535+
return response;
524536
}
525537

526538
private Timer timer(final ProxyRepository repository, final HttpUriRequest httpRequest, final String baseUrl) {

‎plugins/npm/nexus-npm-repository-plugin/src/main/java/com/bolyuba/nexus/plugin/npm/service/internal/proxy/HttpProxyMetadataTransport.java‎

Lines changed: 76 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -34,10 +34,17 @@
3434
import com.bolyuba.nexus.plugin.npm.service.internal.MetadataParser;
3535
import com.bolyuba.nexus.plugin.npm.service.internal.PackageRootIterator;
3636
import com.bolyuba.nexus.plugin.npm.service.internal.ProxyMetadataTransport;
37+
import com.google.common.base.Stopwatch;
38+
import com.yammer.metrics.Metrics;
39+
import com.yammer.metrics.core.MetricsRegistry;
40+
import com.yammer.metrics.core.Timer;
41+
import com.yammer.metrics.core.TimerContext;
3742
import org.apache.http.HttpResponse;
3843
import org.apache.http.HttpStatus;
44+
import org.apache.http.StatusLine;
3945
import org.apache.http.client.HttpClient;
4046
import org.apache.http.client.methods.HttpGet;
47+
import org.apache.http.client.methods.HttpUriRequest;
4148
import org.apache.http.client.protocol.HttpClientContext;
4249
import org.apache.http.util.EntityUtils;
4350
import org.slf4j.Logger;
@@ -61,12 +68,15 @@ public class HttpProxyMetadataTransport
6168

6269
private final HttpClientManager httpClientManager;
6370

71+
private final MetricsRegistry metricsRegistry;
72+
6473
@Inject
6574
public HttpProxyMetadataTransport(final MetadataParser metadataParser,
6675
final HttpClientManager httpClientManager)
6776
{
6877
this.metadataParser = checkNotNull(metadataParser);
6978
this.httpClientManager = checkNotNull(httpClientManager);
79+
this.metricsRegistry = Metrics.defaultRegistry();
7080
}
7181

7282
/**
@@ -82,15 +92,38 @@ public PackageRootIterator fetchRegistryRoot(final NpmProxyRepository npmProxyRe
8292
try {
8393
final HttpGet get = new HttpGet(
8494
buildUri(npmProxyRepository, "-/all")); // TODO: this in NPM specific, might try both root and NPM api
85-
outboundRequestLog.debug("{} - NPM GET {}", npmProxyRepository.getId(), get.getURI());
8695
get.addHeader("accept", NpmRepository.JSON_MIME_TYPE);
8796
final HttpClientContext context = new HttpClientContext();
8897
context.setAttribute(Hc4Provider.HTTP_CTX_KEY_REPOSITORY, npmProxyRepository);
89-
final HttpResponse httpResponse = httpClient.execute(get, context);
98+
99+
final Timer timer = timer(get, npmProxyRepository.getRemoteUrl());
100+
final TimerContext timerContext = timer.time();
101+
Stopwatch stopwatch = null;
102+
103+
if (outboundRequestLog.isDebugEnabled()) {
104+
outboundRequestLog.debug("[{}] {} {}", npmProxyRepository.getId(), get.getMethod(), get.getURI());
105+
stopwatch = Stopwatch.createStarted();
106+
}
107+
108+
final HttpResponse httpResponse;
109+
try {
110+
httpResponse = httpClient.execute(get, context);
111+
}
112+
finally {
113+
timerContext.stop();
114+
if (stopwatch != null) {
115+
stopwatch.stop();
116+
}
117+
}
118+
119+
final StatusLine statusLine = httpResponse.getStatusLine();
120+
if (outboundRequestLog.isDebugEnabled()) {
121+
outboundRequestLog.debug("[{}] {} {} -> {}; {}", npmProxyRepository.getId(), get.getMethod(), get.getURI(),
122+
statusLine, stopwatch);
123+
}
124+
90125
try {
91-
outboundRequestLog.debug("{} - NPM GET {} - {}", npmProxyRepository.getId(), get.getURI(),
92-
httpResponse.getStatusLine());
93-
if (httpResponse.getStatusLine().getStatusCode() == HttpStatus.SC_OK) {
126+
if (statusLine.getStatusCode() == HttpStatus.SC_OK) {
94127
final File tempFile = File
95128
.createTempFile(npmProxyRepository.getId() + "-root", "temp.json",
96129
metadataParser.getTemporaryDirectory());
@@ -102,7 +135,11 @@ public PackageRootIterator fetchRegistryRoot(final NpmProxyRepository npmProxyRe
102135
final FileContentLocator cl = new FileContentLocator(tempFile, NpmRepository.JSON_MIME_TYPE, true);
103136
return metadataParser.parseRegistryRoot(npmProxyRepository.getId(), cl);
104137
}
105-
throw new IOException("Unexpected response from registry root " + httpResponse.getStatusLine());
138+
if (log.isDebugEnabled()) {
139+
log.debug("[{}] {} {} -> unexpected: {}", npmProxyRepository.getId(), get.getMethod(), get.getURI(),
140+
statusLine);
141+
}
142+
throw new IOException("Unexpected response from registry root " + statusLine);
106143
}
107144
finally {
108145
EntityUtils.consumeQuietly(httpResponse.getEntity());
@@ -126,21 +163,44 @@ public PackageRoot fetchPackageRoot(final NpmProxyRepository npmProxyRepository,
126163
npmProxyRepository.getRemoteStorageContext());
127164
try {
128165
final HttpGet get = new HttpGet(buildUri(npmProxyRepository, packageName));
129-
outboundRequestLog.debug("{} - NPM GET {}", npmProxyRepository.getId(), get.getURI());
130166
get.addHeader("accept", NpmRepository.JSON_MIME_TYPE);
131167
if (expired != null && expired.getProperties().containsKey(PROP_ETAG)) {
132168
get.addHeader("if-none-match", expired.getProperties().get(PROP_ETAG));
133169
}
134170
final HttpClientContext context = new HttpClientContext();
135171
context.setAttribute(Hc4Provider.HTTP_CTX_KEY_REPOSITORY, npmProxyRepository);
136-
final HttpResponse httpResponse = httpClient.execute(get, context);
172+
173+
final Timer timer = timer(get, npmProxyRepository.getRemoteUrl());
174+
final TimerContext timerContext = timer.time();
175+
Stopwatch stopwatch = null;
176+
177+
if (outboundRequestLog.isDebugEnabled()) {
178+
outboundRequestLog.debug("[{}] {} {}", npmProxyRepository.getId(), get.getMethod(), get.getURI());
179+
stopwatch = Stopwatch.createStarted();
180+
}
181+
182+
final HttpResponse httpResponse;
183+
try {
184+
httpResponse = httpClient.execute(get, context);
185+
}
186+
finally {
187+
timerContext.stop();
188+
if (stopwatch != null) {
189+
stopwatch.stop();
190+
}
191+
}
192+
193+
final StatusLine statusLine = httpResponse.getStatusLine();
194+
if (outboundRequestLog.isDebugEnabled()) {
195+
outboundRequestLog.debug("[{}] {} {} -> {}; {}", npmProxyRepository.getId(), get.getMethod(), get.getURI(),
196+
statusLine, stopwatch);
197+
}
198+
137199
try {
138-
outboundRequestLog.debug("{} - NPM GET {} - {}", npmProxyRepository.getId(), get.getURI(),
139-
httpResponse.getStatusLine());
140-
if (httpResponse.getStatusLine().getStatusCode() == HttpStatus.SC_NOT_MODIFIED) {
200+
if (statusLine.getStatusCode() == HttpStatus.SC_NOT_MODIFIED) {
141201
return expired;
142202
}
143-
if (httpResponse.getStatusLine().getStatusCode() == HttpStatus.SC_OK) {
203+
if (statusLine.getStatusCode() == HttpStatus.SC_OK) {
144204
final PreparedContentLocator pcl = new PreparedContentLocator(httpResponse.getEntity().getContent(),
145205
NpmRepository.JSON_MIME_TYPE, ContentLocator.UNKNOWN_LENGTH);
146206
final PackageRoot fresh = metadataParser.parsePackageRoot(npmProxyRepository.getId(), pcl);
@@ -172,4 +232,8 @@ private String buildUri(final NpmProxyRepository npmProxyRepository, final Strin
172232
return registryUrl + "/" + pathElem;
173233
}
174234
}
235+
236+
private Timer timer(final HttpUriRequest httpRequest, final String baseUrl) {
237+
return metricsRegistry.newTimer(HttpProxyMetadataTransport.class, baseUrl, httpRequest.getMethod());
238+
}
175239
}

‎plugins/npm/nexus-npm-repository-plugin/src/main/java/com/bolyuba/nexus/plugin/npm/service/tarball/internal/HttpTarballTransport.java‎

Lines changed: 49 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -33,12 +33,19 @@
3333
import com.bolyuba.nexus.plugin.npm.proxy.NpmProxyRepository;
3434
import com.bolyuba.nexus.plugin.npm.service.NpmBlob;
3535
import com.bolyuba.nexus.plugin.npm.service.PackageVersion;
36+
import com.google.common.base.Stopwatch;
3637
import com.google.common.base.Throwables;
3738
import com.google.common.collect.ImmutableSet;
39+
import com.yammer.metrics.Metrics;
40+
import com.yammer.metrics.core.MetricsRegistry;
41+
import com.yammer.metrics.core.Timer;
42+
import com.yammer.metrics.core.TimerContext;
3843
import org.apache.http.HttpResponse;
3944
import org.apache.http.HttpStatus;
45+
import org.apache.http.StatusLine;
4046
import org.apache.http.client.HttpClient;
4147
import org.apache.http.client.methods.HttpGet;
48+
import org.apache.http.client.methods.HttpUriRequest;
4249
import org.apache.http.client.protocol.HttpClientContext;
4350
import org.apache.http.util.EntityUtils;
4451
import org.slf4j.Logger;
@@ -71,9 +78,12 @@ public class HttpTarballTransport
7178

7279
private final Hc4Provider hc4Provider;
7380

81+
private final MetricsRegistry metricsRegistry;
82+
7483
@Inject
7584
public HttpTarballTransport(final Hc4Provider hc4Provider) {
7685
this.hc4Provider = checkNotNull(hc4Provider);
86+
this.metricsRegistry = Metrics.defaultRegistry();
7787
}
7888

7989
public NpmBlob getTarballForVersion(final NpmProxyRepository npmProxyRepository, final File target,
@@ -82,15 +92,38 @@ public NpmBlob getTarballForVersion(final NpmProxyRepository npmProxyRepository,
8292
{
8393
final HttpClient httpClient = hc4Provider.createHttpClient(npmProxyRepository.getRemoteStorageContext());
8494
final HttpGet get = new HttpGet(packageVersion.getDistTarball());
85-
outboundRequestLog.debug("{} - NPMTarball GET {}", npmProxyRepository.getId(), get.getURI());
8695
final HttpClientContext context = new HttpClientContext();
8796
context.setAttribute(Hc4Provider.HTTP_CTX_KEY_REPOSITORY, npmProxyRepository);
8897
get.addHeader("Accept", NpmRepository.TARBALL_MIME_TYPE);
89-
final HttpResponse httpResponse = httpClient.execute(get, context);
98+
99+
final Timer timer = timer(get, npmProxyRepository.getRemoteUrl());
100+
final TimerContext timerContext = timer.time();
101+
Stopwatch stopwatch = null;
102+
103+
if (outboundRequestLog.isDebugEnabled()) {
104+
outboundRequestLog.debug("[{}] {} {}", npmProxyRepository.getId(), get.getMethod(), get.getURI());
105+
stopwatch = Stopwatch.createStarted();
106+
}
107+
108+
final HttpResponse httpResponse;
109+
try {
110+
httpResponse = httpClient.execute(get, context);
111+
}
112+
finally {
113+
timerContext.stop();
114+
if (stopwatch != null) {
115+
stopwatch.stop();
116+
}
117+
}
118+
119+
final StatusLine statusLine = httpResponse.getStatusLine();
120+
if (outboundRequestLog.isDebugEnabled()) {
121+
outboundRequestLog.debug("[{}] {} {} -> {}; {}", npmProxyRepository.getId(), get.getMethod(), get.getURI(),
122+
statusLine, stopwatch);
123+
}
124+
90125
try {
91-
outboundRequestLog.debug("{} - NPMTarball GET {} - {}", npmProxyRepository.getId(), get.getURI(),
92-
httpResponse.getStatusLine());
93-
if (httpResponse.getStatusLine().getStatusCode() == HttpStatus.SC_OK && httpResponse.getEntity() != null) {
126+
if (statusLine.getStatusCode() == HttpStatus.SC_OK && httpResponse.getEntity() != null) {
94127
final MessageDigest md = MessageDigest.getInstance("SHA1");
95128
try (final BufferedOutputStream bos = new BufferedOutputStream(
96129
new DigestOutputStream(new FileOutputStream(target), md))) {
@@ -102,17 +135,17 @@ public NpmBlob getTarballForVersion(final NpmProxyRepository npmProxyRepository,
102135
DigesterUtils.getDigestAsString(md.digest()));
103136
}
104137
else {
105-
if (NO_RETRIES_RESPONSE_CODES.contains(httpResponse.getStatusLine().getStatusCode())) {
106-
log.debug("{} - NPMTarball GET {}: unexpected response: {}", npmProxyRepository.getId(), get.getURI(),
107-
httpResponse.getStatusLine());
138+
if (log.isDebugEnabled()) {
139+
log.debug("[{}] {} {} -> unexpected: {}", npmProxyRepository.getId(), get.getMethod(), get.getURI(),
140+
statusLine);
141+
}
142+
if (NO_RETRIES_RESPONSE_CODES.contains(statusLine.getStatusCode())) {
108143
return null;
109144
}
110145
else {
111-
// in my experience, registry my throw many different errors, from 400, to 500 and then on next try
146+
// in my experience, registry may throw many different errors, from 400, to 500 and then on next try
112147
// will happily serve the same URL! Hence, we do retry almost all of the responses that are not expected.
113-
log.debug("{} - NPMTarball GET {}: unexpected response: {}", npmProxyRepository.getId(), get.getURI(),
114-
httpResponse.getStatusLine());
115-
throw new IOException("Unexpected response for 'GET " + get.getURI() + "': " + httpResponse.getStatusLine());
148+
throw new IOException("Unexpected response for 'GET " + get.getURI() + "': " + statusLine);
116149
}
117150
}
118151
}
@@ -123,4 +156,8 @@ public NpmBlob getTarballForVersion(final NpmProxyRepository npmProxyRepository,
123156
EntityUtils.consumeQuietly(httpResponse.getEntity());
124157
}
125158
}
159+
160+
private Timer timer(final HttpUriRequest httpRequest, final String baseUrl) {
161+
return metricsRegistry.newTimer(HttpTarballTransport.class, baseUrl, httpRequest.getMethod());
162+
}
126163
}

0 commit comments

Comments
 (0)