Retrofit: Logging in Retrofit 2.0

[yangpeiyong]

I am using okhttp Interceptor for logging, the code is:

class LoggingInterceptor implements Interceptor {
    @Override 
    public Response intercept(Chain chain) throws IOException {
    Request request = chain.request();

    long t1 = System.nanoTime();
    Log.d("OkHttp", String.format("Sending request %s on %s%n%s",
        request.url(), chain.connection(), request.headers()));

    Response response = chain.proceed(request);

    long t2 = System.nanoTime();
    Log.d("OkHttp", String.format("Received response for %s in %.1fms%n%s",
        response.request().url(), (t2 - t1) / 1e6d, response.headers()));

    *Log.d("response.body().string()")*
    return response;
  }
}

It causes exception because _response.body().string()_ can only be called once, then how can I log response boy?

[JakeWharton]

Response bodies can only be read once. If you consume the response body then you need to either remove it from the response that you return or you need to replace it with something else. In this instance, you can create a new response body using the string that you read so the normal response-handling code has something to read from.

Something like:

return response.builder()
    .body(ResponseBody.create(response.body().contentType(), bodyString))
    .build();

[ber4444]

Hey, Jake, your code did not work for me with Retrofit 2 (snapshot), because it's incomplete (bodyString undefined) plus builder() is an unresolved method.

[yangpeiyong]

Great! It works!

[arturonaredo]

@ber4444

return response.newBuilder()
                .body(ResponseBody.create(response.body().contentType(), response.body().string()))
                .build();

:)

[ber4444]

@arturonaredo @JakeWharton do you mean:

               Log.d("response: "+response.body().string());
               return response.newBuilder()
                              .body(ResponseBody.create(response.body().contentType(), response.body().string()))
                              .build();

That does not work, gives me:

response:
09-16 16:56:24.167  27174-28054/? E/DiabloTesterApp﹕ ll.u.a.LLUncaughtExceptionHandler.uncaughtException:69 | UNCAUGHT EXCEPTION IN Thread[OkHttp Dispatcher,5,main] @ [s.o.i.h.HttpConnection$FixedLengthSource.read:415]
    java.lang.IllegalStateException: closed
            at com.squareup.okhttp.internal.http.HttpConnection$FixedLengthSource.read(HttpConnection.java:415)
            at okio.Buffer.writeAll(Buffer.java:956)
            at okio.RealBufferedSource.readByteArray(RealBufferedSource.java:92)
            at com.squareup.okhttp.ResponseBody.bytes(ResponseBody.java:57)
            at com.squareup.okhttp.ResponseBody.string(ResponseBody.java:83)
            at com.company.diablo.networking.DiabloService$1.intercept(DiabloService.java:50)
            at com.squareup.okhttp.Call$ApplicationInterceptorChain.proceed(Call.java:221)
            at com.squareup.okhttp.Call.getResponseWithInterceptorChain(Call.java:195)
            at com.squareup.okhttp.Call.access$100(Call.java:34)
            at com.squareup.okhttp.Call$AsyncCall.execute(Call.java:162)
            at com.squareup.okhttp.internal.NamedRunnable.run(NamedRunnable.java:33)
            at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
            at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
            at java.lang.Thread.run(Thread.java:818)
09-16 16:56:24.176  27174-28054/? E/DiabloTesterApp﹕ ll.u.a.LLUncaughtExceptionHandler.uncaughtException:116 | Exception caught while handling uncaught exception
    android.content.ActivityNotFoundException: Unable to find explicit activity class {com.company.diablo.demo/com.company.util.android.Popup}; have you declared this activity in your AndroidManifest.xml?
            at android.app.Instrumentation.checkStartActivityResult(Instrumentation.java:1777)
            at android.app.Instrumentation.execStartActivity(Instrumentation.java:1501)
            at android.app.ContextImpl.startActivity(ContextImpl.java:1243)
            at android.app.ContextImpl.startActivity(ContextImpl.java:1225)
            at android.content.ContextWrapper.startActivity(ContextWrapper.java:323)
            at com.company.util.android.AndroidUtil.startActivityLocal(AndroidUtil.java:26)
            at com.company.util.android.Popup.make(Popup.java:81)
            at com.company.util.android.Popup.make(Popup.java:57)
            at com.company.util.android.LLUncaughtExceptionHandler.uncaughtException(LLUncaughtExceptionHandler.java:77)
            at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:693)
            at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:690)

[JakeWharton]

You cannot read the body twice. Cache the string result to reuse it.

On Wed, Sep 16, 2015, 8:01 PM Gábor Berényi [email protected]
wrote:

@arturonaredo https://github.com/arturonaredo @JakeWharton
https://github.com/JakeWharton do you mean:

           Log.d("response: "+response.body().string());
           return response.newBuilder()
                          .body(ResponseBody.create(response.body().contentType(), response.body().string()))
                          .build();

That does not work, gives me:

response:
09-16 16:56:24.167 27174-28054/? E/DiabloTesterApp﹕ ll.u.a.LLUncaughtExceptionHandler.uncaughtException:69 | UNCAUGHT EXCEPTION IN Thread[OkHttp Dispatcher,5,main] @ [s.o.i.h.HttpConnection$FixedLengthSource.read:415]
java.lang.IllegalStateException: closed
at com.squareup.okhttp.internal.http.HttpConnection$FixedLengthSource.read(HttpConnection.java:415)
at okio.Buffer.writeAll(Buffer.java:956)
at okio.RealBufferedSource.readByteArray(RealBufferedSource.java:92)
at com.squareup.okhttp.ResponseBody.bytes(ResponseBody.java:57)
at com.squareup.okhttp.ResponseBody.string(ResponseBody.java:83)
at com.company.diablo.networking.DiabloService$1.intercept(DiabloService.java:50)
at com.squareup.okhttp.Call$ApplicationInterceptorChain.proceed(Call.java:221)
at com.squareup.okhttp.Call.getResponseWithInterceptorChain(Call.java:195)
at com.squareup.okhttp.Call.access$100(Call.java:34)
at com.squareup.okhttp.Call$AsyncCall.execute(Call.java:162)
at com.squareup.okhttp.internal.NamedRunnable.run(NamedRunnable.java:33)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
at java.lang.Thread.run(Thread.java:818)
09-16 16:56:24.176 27174-28054/? E/DiabloTesterApp﹕ ll.u.a.LLUncaughtExceptionHandler.uncaughtException:116 | Exception caught while handling uncaught exception
android.content.ActivityNotFoundException: Unable to find explicit activity class {com.company.diablo.demo/com.company.util.android.Popup}; have you declared this activity in your AndroidManifest.xml?
at android.app.Instrumentation.checkStartActivityResult(Instrumentation.java:1777)
at android.app.Instrumentation.execStartActivity(Instrumentation.java:1501)
at android.app.ContextImpl.startActivity(ContextImpl.java:1243)
at android.app.ContextImpl.startActivity(ContextImpl.java:1225)
at android.content.ContextWrapper.startActivity(ContextWrapper.java:323)
at com.company.util.android.AndroidUtil.startActivityLocal(AndroidUtil.java:26)
at com.company.util.android.Popup.make(Popup.java:81)
at com.company.util.android.Popup.make(Popup.java:57)
at com.company.util.android.LLUncaughtExceptionHandler.uncaughtException(LLUncaughtExceptionHandler.java:77)
at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:693)
at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:690)

—
Reply to this email directly or view it on GitHub
https://github.com/square/retrofit/issues/1072#issuecomment-140929119.

[yangpeiyong]

Here is my code, it works great.

    public static class LoggingInterceptor implements Interceptor {
        @Override public Response intercept(Chain chain) throws IOException {
            Request request = chain.request();

            long t1 = System.nanoTime();
            String requestLog = String.format("Sending request %s on %s%n%s",
                    request.url(), chain.connection(), request.headers());
            //YLog.d(String.format("Sending request %s on %s%n%s",
            //        request.url(), chain.connection(), request.headers()));
            if(request.method().compareToIgnoreCase("post")==0){
                requestLog ="\n"+requestLog+"\n"+bodyToString(request);
            }
            Log.d("TAG","request"+"\n"+requestLog);

            Response response = chain.proceed(request);
            long t2 = System.nanoTime();

            String responseLog = String.format("Received response for %s in %.1fms%n%s",
                    response.request().url(), (t2 - t1) / 1e6d, response.headers());

            String bodyString = response.body().string();

            Log.d("TAG","response"+"\n"+responseLog+"\n"+bodyString);

            return response.newBuilder()
                    .body(ResponseBody.create(response.body().contentType(), bodyString))
                    .build();
            //return response;
        }
    }

    public static String bodyToString(final Request request) {
        try {
            final Request copy = request.newBuilder().build();
            final Buffer buffer = new Buffer();
            copy.body().writeTo(buffer);
            return buffer.readUtf8();
        } catch (final IOException e) {
            return "did not work";
        }
    }

[ber4444]

Thanks, I got it working too. Note that you make a copy of the request which is not necessary.

[romangromov]

@yangpeiyong working fine, thanks

[Eeram]

@yangpeiyong Thanks, your solution is the first that's working perfectly for me.

[rajuashok]

The IllegalStateException I get when I try to read the body twice is simply:

"IllegalStateException: closed"

Any plan to make that error a bit more detailed? The error is quite vague and makes debugging difficult. Thanks.

[JakeWharton]

That error is neither from Retrofit or OkHttp but Okio, and as succinct as
it is, there's not much more that can be said when you try to read
something that has been closed.

On Wed, Oct 21, 2015, 7:45 PM Ashok Raju [email protected] wrote:

The IllegalStateException I get when I try to read the body twice is
simply:

"IllegalStateException: closed"

Any plan to make that error a bit more detailed? The error is quite vague
and makes debugging difficult. Thanks.

—
Reply to this email directly or view it on GitHub
https://github.com/square/retrofit/issues/1072#issuecomment-150055521.

[rajuashok]

Ah I see.

Yeah I guess I was thinking something like "Response body already closed". The reason this was hard to debug was because the exception was thrown on the api.postToApi() line. Whereas the response body was being read within the OkHttp interceptor (for logging). So I didn't know what was "closed". Oh well, not much you can do though if it's in Okio. Thanks for getting back to me.

[JakeWharton]

Yeah unfortunately the state is completely opaque to OkHttp or it actually could do that. You can't know the thing is closed until you try to interact with it.

[ihajat]

Hi,

Can someone check this please, the body that is returned is always null?? I am using an interceptor and replacing the string with a mock json string.
// dummy mock value
final String ss = "{\"event_id\":\"324\",\"event_action\":\"new\",\"event_type\":\"workorder\"}";
okClient.interceptors().add(new Interceptor() {
@Override
public com.squareup.okhttp.Response intercept(Chain chain) throws IOException {
Request request = chain.request();
com.squareup.okhttp.Response response = chain.proceed(request);
ResponseBody responseBody = response.body();
com.squareup.okhttp.Response newResponse = response.newBuilder().body(ResponseBody.create(responseBody.contentType(), ss.getBytes())).build();

            return newResponse;
        }
    });

//inside the onResponse
@Override
public void onResponse(Response response, Retrofit retrofit) {
if(response.isSuccess()) {
// response.body() = null ALWAYS NULL????

[engmonsh]

@ihajat I have the same problem that res?ponse.body() = null but only in case of http (code < 200 || code >= 300) , did you find any solution for that

[PiaDeveloperBr]

I have an error with @DELETE method in rest Api by using retrofit. Please help me out.
RetroInterface serviceinterface = RetroClient.getApiServices();
Call call = serviceinterface.deleteStory(mStoryId);
call.enqueue(new Callback() {
@Override
public void onResponse(Call call, Response response) {
if(response.isSuccessful()){

                Log.e("delete", "delete"+response.body().getBooks());
               //Not successfull :(
            }
       }

        @Override
        public void onFailure(Call<DeleteStoryResponse> call, Throwable t) {

        }
    });

Error: D/OkHttp: Cannot DELETE /Stories/9

[Setsunalxxl]

@JakeWharton hi,I am using the default log HttpLoggingInterceptor,but when i upload image,totaly 3 images,only log 2 tags of images sometimes.i see the AndroidPlatform code in this method

@Override public void log(int level, String message, Throwable t) {
int logLevel = level == WARN ? Log.WARN : Log.DEBUG;
if (t != null) message = message + '\n' + Log.getStackTraceString(t);

// Split by line, then ensure each line can fit into Log's maximum length.
for (int i = 0, length = message.length(); i < length; i++) {
  int newline = message.indexOf('\n', i);
  newline = newline != -1 ? newline : length;
  do {
    int end = Math.min(newline, i + MAX_LOG_LENGTH);
    Log.println(logLevel, "OkHttp", message.substring(i, end));
    i = end;
  } while (i < newline);
}

}

the parameter message is compelte,but the log message is incomplete.is my log body too long?