Skip to content

Commit 1630812

Browse files
author
adriancole
committed
log ioexceptions and retries
1 parent d139377 commit 1630812

File tree

4 files changed

+321
-66
lines changed

4 files changed

+321
-66
lines changed

‎CHANGES.md‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,3 +1,6 @@
1+
### Version 3.1
2+
* Log when an http request is retried or a response fails due to an IOException.
3+
14
### Version 3.0
25
* Added support for asynchronous callbacks via `IncrementalCallback<T>` and `IncrementalDecoder.TextStream<T>`.
36
* 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: 26 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -56,10 +56,10 @@ static class Factory {
5656
private final Lazy<Executor> httpExecutor;
5757
private final Provider<Retryer> retryer;
5858
private final Logger logger;
59-
private final Logger.Level logLevel;
59+
private final Provider<Logger.Level> logLevel;
6060

6161
@Inject Factory(Client client, @Named("http") Lazy<Executor> httpExecutor, Provider<Retryer> retryer, Logger logger,
62-
Logger.Level logLevel) {
62+
Provider<Logger.Level> logLevel) {
6363
this.client = checkNotNull(client, "client");
6464
this.httpExecutor = checkNotNull(httpExecutor, "httpExecutor");
6565
this.retryer = checkNotNull(retryer, "retryer");
@@ -86,7 +86,7 @@ static final class IncrementalCallbackMethodHandler extends MethodHandler {
8686
private final IncrementalDecoder.TextStream<?> incDecoder;
8787

8888
private IncrementalCallbackMethodHandler(Target<?> target, Client client, Provider<Retryer> retryer, Logger logger,
89-
Logger.Level logLevel, MethodMetadata metadata,
89+
Provider<Logger.Level> logLevel, MethodMetadata metadata,
9090
BuildTemplateFromArgs buildTemplateFromArgs, Options options,
9191
IncrementalDecoder.TextStream<?> incDecoder, ErrorDecoder errorDecoder,
9292
Lazy<Executor> httpExecutor) {
@@ -150,7 +150,7 @@ static final class SynchronousMethodHandler extends MethodHandler {
150150
private final Decoder.TextStream<?> decoder;
151151

152152
private SynchronousMethodHandler(Target<?> target, Client client, Provider<Retryer> retryer, Logger logger,
153-
Logger.Level logLevel, MethodMetadata metadata,
153+
Provider<Logger.Level> logLevel, MethodMetadata metadata,
154154
BuildTemplateFromArgs buildTemplateFromArgs, Options options,
155155
Decoder.TextStream<?> decoder, ErrorDecoder errorDecoder) {
156156
super(target, client, retryer, logger, logLevel, metadata, buildTemplateFromArgs, options, errorDecoder);
@@ -178,15 +178,16 @@ private SynchronousMethodHandler(Target<?> target, Client client, Provider<Retry
178178
protected final Client client;
179179
protected final Provider<Retryer> retryer;
180180
protected final Logger logger;
181-
protected final Logger.Level logLevel;
181+
protected final Provider<Logger.Level> logLevel;
182182

183183
protected final BuildTemplateFromArgs buildTemplateFromArgs;
184184
protected final Options options;
185185
protected final ErrorDecoder errorDecoder;
186186

187187
private MethodHandler(Target<?> target, Client client, Provider<Retryer> retryer, Logger logger,
188-
Logger.Level logLevel, MethodMetadata metadata, BuildTemplateFromArgs buildTemplateFromArgs,
189-
Options options, ErrorDecoder errorDecoder) {
188+
Provider<Logger.Level> logLevel, MethodMetadata metadata,
189+
BuildTemplateFromArgs buildTemplateFromArgs, Options options,
190+
ErrorDecoder errorDecoder) {
190191
this.target = checkNotNull(target, "target");
191192
this.client = checkNotNull(client, "client for %s", target);
192193
this.retryer = checkNotNull(retryer, "retryer for %s", target);
@@ -206,6 +207,9 @@ public Object invoke(Object[] argv) throws Throwable {
206207
return executeAndDecode(argv, template);
207208
} catch (RetryableException e) {
208209
retryer.continueOrPropagate(e);
210+
if (logLevel.get() != Logger.Level.NONE) {
211+
logger.logRetry(metadata.configKey(), logLevel.get());
212+
}
209213
continue;
210214
}
211215
}
@@ -214,29 +218,36 @@ public Object invoke(Object[] argv) throws Throwable {
214218
public Object executeAndDecode(Object[] argv, RequestTemplate template) throws Throwable {
215219
Request request = targetRequest(template);
216220

217-
if (logLevel.ordinal() > Logger.Level.NONE.ordinal()) {
218-
logger.logRequest(target, logLevel, request);
221+
if (logLevel.get() != Logger.Level.NONE) {
222+
logger.logRequest(metadata.configKey(), logLevel.get(), request);
219223
}
220224

221225
Response response;
222226
long start = System.nanoTime();
223227
try {
224228
response = client.execute(request, options);
225229
} catch (IOException e) {
230+
if (logLevel.get() != Logger.Level.NONE) {
231+
logger.logIOException(metadata.configKey(), logLevel.get(), e, elapsedTime(start));
232+
}
226233
throw errorExecuting(request, e);
227234
}
235+
228236
long elapsedTime = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - start);
229237

230238
try {
231-
if (logLevel.ordinal() > Logger.Level.NONE.ordinal()) {
232-
response = logger.logAndRebufferResponse(target, logLevel, response, elapsedTime);
239+
if (logLevel.get() != Logger.Level.NONE) {
240+
response = logger.logAndRebufferResponse(metadata.configKey(), logLevel.get(), response, elapsedTime);
233241
}
234242
if (response.status() >= 200 && response.status() < 300) {
235243
return decode(argv, response);
236244
} else {
237245
throw errorDecoder.decode(metadata.configKey(), response);
238246
}
239247
} catch (IOException e) {
248+
if (logLevel.get() != Logger.Level.NONE) {
249+
logger.logIOException(metadata.configKey(), logLevel.get(), e, elapsedTime);
250+
}
240251
throw errorReading(request, response, e);
241252
} finally {
242253
ensureClosed(response.body());
@@ -247,5 +258,9 @@ protected Request targetRequest(RequestTemplate template) {
247258
return target.apply(new RequestTemplate(template));
248259
}
249260

261+
protected long elapsedTime(long start) {
262+
return TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - start);
263+
}
264+
250265
protected abstract Object decode(Object[] argv, Response response) throws Throwable;
251266
}

0 commit comments

Comments
 (0)