Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logging in Retrofit 2.0 #1072

Closed
yangpeiyong opened this issue Sep 10, 2015 · 18 comments

Comments

@yangpeiyong
Copy link

commented Sep 10, 2015

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

This comment has been minimized.

Copy link
Collaborator

commented Sep 10, 2015

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

This comment has been minimized.

Copy link

commented Sep 15, 2015

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

This comment has been minimized.

Copy link
Author

commented Sep 15, 2015

Great! It works!

@arturonaredo

This comment has been minimized.

Copy link

commented Sep 16, 2015

@ber4444

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

:)

@ber4444

This comment has been minimized.

Copy link

commented Sep 17, 2015

@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

This comment has been minimized.

Copy link
Collaborator

commented Sep 17, 2015

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 notifications@github.com
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
#1072 (comment).

@yangpeiyong

This comment has been minimized.

Copy link
Author

commented Sep 18, 2015

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

This comment has been minimized.

Copy link

commented Sep 18, 2015

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

@romangromov

This comment has been minimized.

Copy link

commented Sep 25, 2015

@yangpeiyong working fine, thanks

@Eeram

This comment has been minimized.

Copy link

commented Oct 20, 2015

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

@rajuashok

This comment has been minimized.

Copy link

commented Oct 21, 2015

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

This comment has been minimized.

Copy link
Collaborator

commented Oct 22, 2015

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 notifications@github.com 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
#1072 (comment).

@rajuashok

This comment has been minimized.

Copy link

commented Oct 22, 2015

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

This comment has been minimized.

Copy link
Collaborator

commented Oct 22, 2015

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

This comment has been minimized.

Copy link

commented Jan 24, 2016

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<Events_out> response, Retrofit retrofit) {
if(response.isSuccess()) {
// response.body() = null ALWAYS NULL????

@engmonsh

This comment has been minimized.

Copy link

commented Feb 16, 2016

@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

This comment has been minimized.

Copy link

commented Feb 13, 2017

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

This comment has been minimized.

Copy link

commented Nov 20, 2017

@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?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.