Skip to content

Commit 0598afe

Browse files
author
Adrian Cole
committed
Merge pull request OpenFeign#30 from Netflix/log-ioe
log ioexceptions
2 parents 1d0c86d + 75b15a1 commit 0598afe

4 files changed

Lines changed: 322 additions & 69 deletions

File tree

‎CHANGES.md‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,9 @@
44
* `Observer<T>` replaces `IncrementalCallback<T>` and is passed to `Observable.subscribe()`.
55
* On `Subscription.unsubscribe()`, `Observer.onNext()` will stop being called.
66

7+
### Version 3.1
8+
* Log when an http request is retried or a response fails due to an IOException.
9+
710
### Version 3.0
811
* Added support for asynchronous callbacks via `IncrementalCallback<T>` and `IncrementalDecoder.TextStream<T>`.
912
* Wire is now Logger, with configurable Logger.Level.

‎feign-core/src/main/java/feign/Logger.java‎

Lines changed: 48 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -17,7 +17,9 @@
1717

1818
import java.io.BufferedReader;
1919
import java.io.IOException;
20+
import java.io.PrintWriter;
2021
import java.io.Reader;
22+
import java.io.StringWriter;
2123
import java.util.logging.FileHandler;
2224
import java.util.logging.LogRecord;
2325
import java.util.logging.SimpleFormatter;
@@ -59,8 +61,8 @@ public enum Level {
5961
public static class ErrorLogger extends Logger {
6062
final java.util.logging.Logger logger = java.util.logging.Logger.getLogger(Logger.class.getName());
6163

62-
@Override protected void log(Target<?> target, String format, Object... args) {
63-
System.err.printf(format + "%n", args);
64+
@Override protected void log(String configKey, String format, Object... args) {
65+
System.err.printf(methodTag(configKey) + format + "%n", args);
6466
}
6567
}
6668

@@ -70,22 +72,22 @@ public static class ErrorLogger extends Logger {
7072
public static class JavaLogger extends Logger {
7173
final java.util.logging.Logger logger = java.util.logging.Logger.getLogger(Logger.class.getName());
7274

73-
@Override void logRequest(Target<?> target, Level logLevel, Request request) {
75+
@Override void logRequest(String configKey, Level logLevel, Request request) {
7476
if (logger.isLoggable(java.util.logging.Level.FINE)) {
75-
super.logRequest(target, logLevel, request);
77+
super.logRequest(configKey, logLevel, request);
7678
}
7779
}
7880

7981
@Override
80-
Response logAndRebufferResponse(Target<?> target, Level logLevel, Response response, long elapsedTime) throws IOException {
82+
Response logAndRebufferResponse(String configKey, Level logLevel, Response response, long elapsedTime) throws IOException {
8183
if (logger.isLoggable(java.util.logging.Level.FINE)) {
82-
return super.logAndRebufferResponse(target, logLevel, response, elapsedTime);
84+
return super.logAndRebufferResponse(configKey, logLevel, response, elapsedTime);
8385
}
8486
return response;
8587
}
8688

87-
@Override protected void log(Target<?> target, String format, Object... args) {
88-
logger.fine(String.format(format, args));
89+
@Override protected void log(String configKey, String format, Object... args) {
90+
logger.fine(String.format(methodTag(configKey) + format, args));
8991
}
9092

9193
/**
@@ -110,64 +112,68 @@ public String format(LogRecord record) {
110112
}
111113

112114
public static class NoOpLogger extends Logger {
113-
@Override void logRequest(Target<?> target, Level logLevel, Request request) {
115+
@Override void logRequest(String configKey, Level logLevel, Request request) {
114116
}
115117

116118
@Override
117-
Response logAndRebufferResponse(Target<?> target, Level logLevel, Response response, long elapsedTime) throws IOException {
119+
Response logAndRebufferResponse(String configKey, Level logLevel, Response response, long elapsedTime) throws IOException {
118120
return response;
119121
}
120122

121123
@Override
122-
protected void log(Target<?> target, String format, Object... args) {
124+
protected void log(String configKey, String format, Object... args) {
123125
}
124126
}
125127

126128
/**
127129
* Override to log requests and responses using your own implementation.
128130
* Messages will be http request and response text.
129131
*
130-
* @param target useful if using MDC (Mapped Diagnostic Context) loggers
131-
* @param format {@link java.util.Formatter format string}
132-
* @param args arguments applied to {@code format}
132+
* @param configKey value of {@link Feign#configKey(java.lang.reflect.Method)}
133+
* @param format {@link java.util.Formatter format string}
134+
* @param args arguments applied to {@code format}
133135
*/
134-
protected abstract void log(Target<?> target, String format, Object... args);
136+
protected abstract void log(String configKey, String format, Object... args);
135137

136-
void logRequest(Target<?> target, Level logLevel, Request request) {
137-
log(target, "---> %s %s HTTP/1.1", request.method(), request.url());
138+
void logRequest(String configKey, Level logLevel, Request request) {
139+
log(configKey, "---> %s %s HTTP/1.1", request.method(), request.url());
138140
if (logLevel.ordinal() >= Level.HEADERS.ordinal()) {
139141

140142
for (String field : request.headers().keySet()) {
141143
for (String value : valuesOrEmpty(request.headers(), field)) {
142-
log(target, "%s: %s", field, value);
144+
log(configKey, "%s: %s", field, value);
143145
}
144146
}
145147

146148
int bytes = 0;
147149
if (request.body() != null) {
148150
bytes = request.body().getBytes(UTF_8).length;
149151
if (logLevel.ordinal() >= Level.FULL.ordinal()) {
150-
log(target, ""); // CRLF
151-
log(target, "%s", request.body());
152+
log(configKey, ""); // CRLF
153+
log(configKey, "%s", request.body());
152154
}
153155
}
154-
log(target, "---> END HTTP (%s-byte body)", bytes);
156+
log(configKey, "---> END HTTP (%s-byte body)", bytes);
155157
}
156158
}
157159

158-
Response logAndRebufferResponse(Target<?> target, Level logLevel, Response response, long elapsedTime) throws IOException {
159-
log(target, "<--- HTTP/1.1 %s %s (%sms)", response.status(), response.reason(), elapsedTime);
160+
void logRetry(String configKey, Level logLevel) {
161+
log(configKey, "---> RETRYING");
162+
}
163+
164+
Response logAndRebufferResponse(String configKey, Level logLevel, Response response, long elapsedTime) throws IOException {
165+
log(configKey, "<--- HTTP/1.1 %s %s (%sms)", response.status(), response.reason(), elapsedTime);
160166
if (logLevel.ordinal() >= Level.HEADERS.ordinal()) {
161167

162168
for (String field : response.headers().keySet()) {
163169
for (String value : valuesOrEmpty(response.headers(), field)) {
164-
log(target, "%s: %s", field, value);
170+
log(configKey, "%s: %s", field, value);
165171
}
166172
}
167173

168174
if (response.body() != null) {
169175
if (logLevel.ordinal() >= Level.FULL.ordinal()) {
170-
log(target, ""); // CRLF
176+
log(configKey, ""); // CRLF
171177
}
172178

173179
Reader body = response.body().asReader();
@@ -178,11 +184,11 @@ Response logAndRebufferResponse(Target<?> target, Level logLevel, Response respo
178184
while ((line = reader.readLine()) != null) {
179185
buffered.append(line);
180186
if (logLevel.ordinal() >= Level.FULL.ordinal()) {
181-
log(target, "%s", line);
187+
log(configKey, "%s", line);
182188
}
183189
}
184190
String bodyAsString = buffered.toString();
185-
log(target, "<--- END HTTP (%s-byte body)", bodyAsString.getBytes(UTF_8).length);
191+
log(configKey, "<--- END HTTP (%s-byte body)", bodyAsString.getBytes(UTF_8).length);
186192
return Response.create(response.status(), response.reason(), response.headers(), bodyAsString);
187193
} finally {
188194
ensureClosed(response.body());
@@ -191,4 +197,19 @@ Response logAndRebufferResponse(Target<?> target, Level logLevel, Response respo
191197
}
192198
return response;
193199
}
200+
201+
IOException logIOException(String configKey, Level logLevel, IOException ioe, long elapsedTime) {
202+
log(configKey, "<--- ERROR %s: %s (%sms)", ioe.getClass().getSimpleName(), ioe.getMessage(), elapsedTime);
203+
if (logLevel.ordinal() >= Level.FULL.ordinal()) {
204+
StringWriter sw = new StringWriter();
205+
ioe.printStackTrace(new PrintWriter(sw));
206+
log(configKey, sw.toString());
207+
log(configKey, "<--- END ERROR");
208+
}
209+
return ioe;
210+
}
211+
212+
static String methodTag(String configKey) {
213+
return new StringBuilder().append('[').append(configKey.substring(0, configKey.indexOf('('))).append("] ").toString();
214+
}
194215
}

‎feign-core/src/main/java/feign/MethodHandler.java‎

Lines changed: 27 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -45,10 +45,10 @@ static class Factory {
4545
private final Lazy<Executor> httpExecutor;
4646
private final Provider<Retryer> retryer;
4747
private final Logger logger;
48-
private final Logger.Level logLevel;
48+
private final Provider<Logger.Level> logLevel;
4949

5050
@Inject Factory(Client client, @Named("http") Lazy<Executor> httpExecutor, Provider<Retryer> retryer, Logger logger,
51-
Logger.Level logLevel) {
51+
Provider<Logger.Level> logLevel) {
5252
this.client = checkNotNull(client, "client");
5353
this.httpExecutor = checkNotNull(httpExecutor, "httpExecutor");
5454
this.retryer = checkNotNull(retryer, "retryer");
@@ -107,9 +107,10 @@ static class ObserverHandler extends BaseMethodHandler {
107107
private final IncrementalDecoder.TextStream<?> incrementalDecoder;
108108

109109
private ObserverHandler(Target<?> target, Client client, Provider<Retryer> retryer, Logger logger,
110-
Logger.Level logLevel, MethodMetadata metadata, BuildTemplateFromArgs buildTemplateFromArgs,
111-
Options options, IncrementalDecoder.TextStream<?> incrementalDecoder,
112-
ErrorDecoder errorDecoder, Lazy<Executor> httpExecutor) {
110+
Provider<Logger.Level> logLevel, MethodMetadata metadata,
111+
BuildTemplateFromArgs buildTemplateFromArgs, Options options,
112+
IncrementalDecoder.TextStream<?> incrementalDecoder, ErrorDecoder errorDecoder,
113+
Lazy<Executor> httpExecutor) {
113114
super(target, client, retryer, logger, logLevel, metadata, buildTemplateFromArgs, options, errorDecoder);
114115
this.httpExecutor = checkNotNull(httpExecutor, "httpExecutor for %s", target);
115116
this.incrementalDecoder = checkNotNull(incrementalDecoder, "incrementalDecoder for %s", target);
@@ -185,7 +186,7 @@ static class SynchronousMethodHandler extends BaseMethodHandler {
185186
private final Decoder.TextStream<?> decoder;
186187

187188
private SynchronousMethodHandler(Target<?> target, Client client, Provider<Retryer> retryer, Logger logger,
188-
Logger.Level logLevel, MethodMetadata metadata,
189+
Provider<Logger.Level> logLevel, MethodMetadata metadata,
189190
BuildTemplateFromArgs buildTemplateFromArgs, Options options,
190191
Decoder.TextStream<?> decoder, ErrorDecoder errorDecoder) {
191192
super(target, client, retryer, logger, logLevel, metadata, buildTemplateFromArgs, options, errorDecoder);
@@ -215,15 +216,14 @@ static abstract class BaseMethodHandler implements MethodHandler {
215216
protected final Client client;
216217
protected final Provider<Retryer> retryer;
217218
protected final Logger logger;
218-
protected final Logger.Level logLevel;
219-
219+
protected final Provider<Logger.Level> logLevel;
220220
protected final BuildTemplateFromArgs buildTemplateFromArgs;
221221
protected final Options options;
222222
protected final ErrorDecoder errorDecoder;
223223

224224
private BaseMethodHandler(Target<?> target, Client client, Provider<Retryer> retryer, Logger logger,
225-
Logger.Level logLevel, MethodMetadata metadata, BuildTemplateFromArgs buildTemplateFromArgs,
226-
Options options, ErrorDecoder errorDecoder) {
225+
Provider<Logger.Level> logLevel, MethodMetadata metadata,
226+
BuildTemplateFromArgs buildTemplateFromArgs, Options options, ErrorDecoder errorDecoder) {
227227
this.target = checkNotNull(target, "target");
228228
this.client = checkNotNull(client, "client for %s", target);
229229
this.retryer = checkNotNull(retryer, "retryer for %s", target);
@@ -243,6 +243,9 @@ private BaseMethodHandler(Target<?> target, Client client, Provider<Retryer> ret
243243
return executeAndDecode(argv, template);
244244
} catch (RetryableException e) {
245245
retryer.continueOrPropagate(e);
246+
if (logLevel.get() != Logger.Level.NONE) {
247+
logger.logRetry(metadata.configKey(), logLevel.get());
248+
}
246249
continue;
247250
}
248251
}
@@ -251,35 +254,45 @@ private BaseMethodHandler(Target<?> target, Client client, Provider<Retryer> ret
251254
public Object executeAndDecode(Object[] argv, RequestTemplate template) throws Throwable {
252255
Request request = targetRequest(template);
253256

254-
if (logLevel.ordinal() > Logger.Level.NONE.ordinal()) {
255-
logger.logRequest(target, logLevel, request);
257+
if (logLevel.get() != Logger.Level.NONE) {
258+
logger.logRequest(metadata.configKey(), logLevel.get(), request);
256259
}
257260

258261
Response response;
259262
long start = System.nanoTime();
260263
try {
261264
response = client.execute(request, options);
262265
} catch (IOException e) {
266+
if (logLevel.get() != Logger.Level.NONE) {
267+
logger.logIOException(metadata.configKey(), logLevel.get(), e, elapsedTime(start));
268+
}
263269
throw errorExecuting(request, e);
264270
}
265271
long elapsedTime = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - start);
266272

267273
try {
268-
if (logLevel.ordinal() > Logger.Level.NONE.ordinal()) {
269-
response = logger.logAndRebufferResponse(target, logLevel, response, elapsedTime);
274+
if (logLevel.get() != Logger.Level.NONE) {
275+
response = logger.logAndRebufferResponse(metadata.configKey(), logLevel.get(), response, elapsedTime);
270276
}
271277
if (response.status() >= 200 && response.status() < 300) {
272278
return decode(argv, response);
273279
} else {
274280
throw errorDecoder.decode(metadata.configKey(), response);
275281
}
276282
} catch (IOException e) {
283+
if (logLevel.get() != Logger.Level.NONE) {
284+
logger.logIOException(metadata.configKey(), logLevel.get(), e, elapsedTime);
285+
}
277286
throw errorReading(request, response, e);
278287
} finally {
279288
ensureClosed(response.body());
280289
}
281290
}
282291

292+
protected long elapsedTime(long start) {
293+
return TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - start);
294+
}
295+
283296
protected Request targetRequest(RequestTemplate template) {
284297
return target.apply(new RequestTemplate(template));
285298
}

0 commit comments

Comments
 (0)