Document HttpLoggingInterceptor buffers content #4273

alonaviram · 2018-09-17T13:16:03Z

We should document (further) that the logging interceptor is not general purpose and fully buffers bodies.

Additionally, consider aggregating a single string for a request and a single string for each response to call the logger with to prevent interleaving on the console/logcat/wherever.

old issue below:

Hi,
I'm working on an android app which downloads books.
some of the books are really large and HttpLoggingInterceptor tries to log them and therefore I'm getting OutOfMemoryError which looks like this:

09-17 15:57:02.095 15408-15672/com.some.example E/AndroidRuntime: FATAL EXCEPTION: OkHttp Dispatcher
    Process: com.some.example, PID: 15408
    java.lang.OutOfMemoryError: Failed to allocate a 122708494 byte allocation with 16777216 free bytes and 93MB until OOM
        at java.lang.StringFactory.newStringFromBytes(StringFactory.java:79)
        at java.lang.StringFactory.newStringFromBytes(StringFactory.java:207)
        at okio.Buffer.readString(Buffer.java:631)
        at okio.Buffer.readString(Buffer.java:614)
        at okhttp3.logging.HttpLoggingInterceptor.intercept(HttpLoggingInterceptor.java:273)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
        at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:200)
        at okhttp3.RealCall$AsyncCall.execute(RealCall.java:147)
        at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)
        at java.lang.Thread.run(Thread.java:818)

in production im not logging the body which fixes the error, but in development i want to be able to log it,
how do you suggest me to tackle this issue?
thanks.

The text was updated successfully, but these errors were encountered:

consp1racy · 2018-09-18T11:45:31Z

You want to print a 120 MB string to logcat? Good luck reading that.

The error happens here:

okhttp/okhttp-logging-interceptor/src/main/java/okhttp3/logging/HttpLoggingInterceptor.java

Line 273 in de4acc5

logger.log(buffer.clone().readString(charset));

Currently logger prints the whole body, which in your case is over 100 MB of data.

Perhaps you could copy HttpLoggingInterceptor to your project and modify it so it doesn't even read more than X bytes.

okhttp/okhttp-logging-interceptor/src/main/java/okhttp3/logging/HttpLoggingInterceptor.java

Line 241 in de4acc5

source.request(Long.MAX_VALUE); // Buffer the entire body.

Or print it in chunks, which I leave to you as an excercise (i.e. I don't know how to do that off the top of my head).

bpappin · 2018-10-19T19:51:43Z

I'm seeing this too when I'm downloading very large datasets.

the logging intercepter should never ever ever cause an OOM.

Here's my stack trace:

Fatal Exception: java.lang.OutOfMemoryError: Failed to allocate a 107249352 byte allocation with 25165824 free bytes and 79MB until OOM, max allowed footprint 142756936, growth limit 201326592
       at java.lang.StringFactory.newStringFromBytes(StringFactory.java:81)
       at java.lang.StringFactory.newStringFromBytes(StringFactory.java:209)
       at okio.Buffer.readString(Buffer.java:631)
       at okio.Buffer.readString(Buffer.java:614)
       at okhttp3.logging.HttpLoggingInterceptor.intercept(HttpLoggingInterceptor.java:273)
       at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
       at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
       at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:200)
       at okhttp3.RealCall.execute(RealCall.java:77)
       at com.google.firebase.perf.network.FirebasePerfOkHttpClient.execute(Unknown Source:17)
       at retrofit2.OkHttpCall.execute(OkHttpCall.java:180)
       at retrofit2.ExecutorCallAdapterFactory$ExecutorCallbackCall.execute(ExecutorCallAdapterFactory.java:91)
       at XXXX.tech.network.XXXXClient.bulkAssetsStream(XXXXClient.java:1317)
       atXXXX.tech.sync.handlers.asset.AssetBulkHandler.doSync(AssetBulkHandler.java:52)
       at XXXX.tech.sync.XXXXSyncAdapter.executeGet(XXXXSyncAdapter.java:708)
       at XXXX.tech.sync.XXXXSyncAdapter.onPerformSync(XXXXSyncAdapter.java:276)
       at android.content.AbstractThreadedSyncAdapter$SyncThread.run(AbstractThreadedSyncAdapter.java:321)

bpappin · 2018-10-19T19:52:46Z

No way is the clients issue, this ticket should not be closed until fixed.

JakeWharton · 2018-10-19T19:54:28Z

The logging interceptor will never cause an OOM when you are not logging ridiculously large bodies.

JakeWharton · 2018-10-19T19:57:01Z

Actually that's a lie. If you have 1 byte free in your heap and you ask the logging interceptor to log a 2-byte body it will cause an OOM. But you asked it. So it tried.

bpappin · 2018-10-19T19:57:39Z

Dude, thats a terrible excuse.
It's HTTP, I could be streaming gigs of data. The logging intercepter should never cause an OOM error under any situation.

bpappin · 2018-10-19T20:00:06Z

I appreciate the work done on this library, but since I, and millions of others depend on it, I'm also not willing to just accept that.

JakeWharton · 2018-10-19T20:11:19Z

Why are you logging bodies when streaming gigs of data? Also, as documented, this logger buffers bodies and prevents streaming. It's not a general-purpose logger meant to solve all needs. It's meant to be simple. If you need logging off gigs of streaming bodies you need a custom logger.

bpappin · 2018-10-23T00:47:01Z

Thanks the logger for the library, and sometimes you need to do both at once. A custom logger might be a solution for being able to control the things more closely, but under no situation, is it cool for the logger of a library to generate an OOM error.

…

On Fri., Oct. 19, 2018, 16:12 Jake Wharton, ***@***.***> wrote: Why are you logging bodies when streaming gigs of data? Also, as documented, this logger buffers bodies and prevents streaming. It's not a general-purpose logger meant to solve all needs. It's meant to be simple. If you need logging off gigs of streaming bodies you need a custom logger. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#4273 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ADuRWeXUpey3jGCPJLGadFIpTkW2z3dpks5umjJEgaJpZM4Wr5Yg> .

JakeWharton · 2018-10-23T00:51:20Z

As I've already stated, that is an impossible thing to accomplish. Every call to 'new' everywhere in your application (including inside libraries and the JDK) is always susceptible to OOM no matter what you do. Or, put another way, this logger will never OOM provided you've allocated enough heap for it to log the response body sizes that you've requested. On Mon, Oct 22, 2018 at 8:47 PM Brill Pappin <notifications@github.com> wrote:

…

Thanks the logger for the library, and sometimes you need to do both at once. A custom logger might be a solution for being able to control the things more closely, but under no situation, is it cool for the logger of a library to generate an OOM error. On Fri., Oct. 19, 2018, 16:12 Jake Wharton, ***@***.***> wrote: > Why are you logging bodies when streaming gigs of data? Also, as > documented, this logger buffers bodies and prevents streaming. It's not a > general-purpose logger meant to solve all needs. It's meant to be simple. > If you need logging off gigs of streaming bodies you need a custom logger. > > — > You are receiving this because you commented. > Reply to this email directly, view it on GitHub > <#4273 (comment)>, or mute > the thread > < https://github.com/notifications/unsubscribe-auth/ADuRWeXUpey3jGCPJLGadFIpTkW2z3dpks5umjJEgaJpZM4Wr5Yg > > . > — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#4273 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAEEEcNqg_Vdm2ODp5NB0wMZ9sxlXfnNks5unmcHgaJpZM4Wr5Yg> .

bpappin · 2018-10-23T01:52:40Z

Assume a programmer knows how it works.
Why the resistance to the obvious?

JakeWharton · 2018-10-23T02:05:19Z

I clearly can't assume that from this thread. I'll re-purpose it for better documentation on the logger about the fact that it's not general purpose and that it buffers all content.

In fact, we probably shouldn't be calling the logger multiple times for each request and response but instead create a single string for a request and a string string for a response to prevent interleaving.

bpappin · 2018-10-23T02:34:30Z

It's clearly a low priority for the okhttp team, but logging is one of the fundamental tools that all your developer users need.

If I can't trust it not to toss out a random OOM, when a request turned out to be larger than expected, then I might as well switch to another library.

swankjesse · 2018-10-23T02:39:29Z

I think we’re talking past each other.

Our expectation of BODY logging is that it’s something you’d use during development only, so you can confirm what you’re sending and receiving match your expectations.

If you’re using BODY logging in a situation where you’re logging more than a developer would plausibly read, or if you’re using it in an environment where an OOM would impact an end-user, you’re using it beyond our expected use case.

I don’t think we want to build a BODY logger for the “arbitrarily large” bodies you speak of, not because we don’t value your use case, but because it’s difficult to do in a way that suits everyone. Instead, we provide guidance on the OkHttp wiki on how to write your own interceptors that do whatever you want. If you don’t like our logging interceptor who cares? The whole point of interceptors is that you can write your own.

https://github.com/square/okhttp/wiki/Interceptors

swankjesse · 2018-10-23T02:46:34Z

Also – we don’t buffer the content ’cause we’re lazy and don’t know how to do streaming. We buffer it because we think that when a developer is viewing logs they don’t want the bodies of multiple responses to be interleaved. I know you don’t care about that, but that makes you special! And that’s why we have this interceptors API so you can do what you like.

And finally, it’s annoying to open source contributors when you threaten to take your business elsewhere. We’re not trying to build a library that meets everyone’s needs (because we think that would be big and complicated). Instead we’re trying to build a small but extensible library that meets most people’s needs. Whenever somebody says “add my feature or I’m leaving” it isn’t endearing.

bpappin · 2018-10-23T03:07:07Z

yes used almost exclusivly in debugging, but should still never throw an OOM.
buffering may, or may not be important to the user. Generally the dev just needs to see what is going on, but it is reasonable to truncate, if you must buffer, in order to prevent an OOM.
How hard would it be to simply provide a non-buffering logger, or one that allowed you to specify what endpoints it used? I will contribute it myself, when I have some time, but someone managing the project would have to take ownership.
threatening to take my business elsewhere is not what this has been about, and I think you know that. It is about being able to trust the libraries you depend on for your livelihood, not to surprise you with something like an OOM.
I am flabbergasted that we are even having this discussion.

JakeWharton · 2018-10-23T03:09:58Z

How hard would it be to simply provide a non-buffering logger, or one that allowed you to specify what endpoints it used? I will contribute it myself, when I have some time, but someone managing the project would have to take ownership.

It wouldn't be hard, but we're not interested in providing these features. Sounds like you should write your own interceptor as the documentation recommends.

yschimke · 2020-01-05T11:27:10Z

Closing out as we actively advise forking HttpLoggingInterceptor, and not actively working on this. What is being asked for is completely reasonable, but we are not going to implement as part of the core library. If there is a better open source library providing an improved HttpLoggingInterceptor, we should just link to that.

r9software · 2021-01-26T02:05:35Z

2 years later, same issue, as a developer I understand what everyone is saying... but throwing an error because you are printing something and now you ran of space to print it it is a bug, if you ran out of space add a catch on it, and print the error silently dont kill the app because someone uses the library for doing normal requests and requires to upload a 20 mb image of video that it is parsed on BASE64... I mean it is not a bug on developers code it is a bug on your code. Killing the thread dont kill the bug, I have been using the library for some years now and I know this is a KNOWN BUG...

swankjesse · 2021-01-26T02:25:47Z

@r9software are you doing body logging in development or elsewhere?

yschimke · 2021-01-26T08:29:37Z

@r9software It's an optional module of OkHttp that has limitations with large bodies that has been well known for a long time. The advice has consistently been that if you want something that suits your case better then you should fork the HttpLoggingInterceptor library and adjust it to your needs. If you are disappointed 2 years later you will presumably be twice as disappointed after 4 years.

You had and still have two choices

avoid using HttpLoggingInterceptor when you know you have large bodies
take the source for it and modify it to your needs.

alonaviram changed the title ~~OutOfMemoryError when logging large server call~~ OutOfMemoryError when logging large server response Sep 17, 2018

alonaviram changed the title ~~OutOfMemoryError when logging large server response~~ OkHttpLoggingInterceptor - OutOfMemoryError when logging large server response Sep 17, 2018

JessYanCoding mentioned this issue Sep 28, 2018

java.lang.OutOfMemoryError JessYanCoding/MVPArms#243

Closed

JakeWharton changed the title ~~OkHttpLoggingInterceptor - OutOfMemoryError when logging large server response~~ Document HttpLoggingInterceptor buffers content Oct 23, 2018

swankjesse added the documentation Documentation task label Oct 23, 2018

swankjesse added this to the 3.13 milestone Nov 4, 2018

yschimke closed this as completed Jan 5, 2020

codefromthecrypt mentioned this issue Feb 27, 2024

Synchronous watches kubernetes-client/java#275

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Document HttpLoggingInterceptor buffers content #4273

Document HttpLoggingInterceptor buffers content #4273

alonaviram commented Sep 17, 2018 •

edited by JakeWharton

consp1racy commented Sep 18, 2018

bpappin commented Oct 19, 2018

bpappin commented Oct 19, 2018

JakeWharton commented Oct 19, 2018

JakeWharton commented Oct 19, 2018

bpappin commented Oct 19, 2018

bpappin commented Oct 19, 2018

JakeWharton commented Oct 19, 2018

bpappin commented Oct 23, 2018 via email

JakeWharton commented Oct 23, 2018 via email

bpappin commented Oct 23, 2018

JakeWharton commented Oct 23, 2018

bpappin commented Oct 23, 2018

swankjesse commented Oct 23, 2018

swankjesse commented Oct 23, 2018

bpappin commented Oct 23, 2018

JakeWharton commented Oct 23, 2018

yschimke commented Jan 5, 2020

r9software commented Jan 26, 2021

swankjesse commented Jan 26, 2021

yschimke commented Jan 26, 2021

Document HttpLoggingInterceptor buffers content #4273

Document HttpLoggingInterceptor buffers content #4273

Comments

alonaviram commented Sep 17, 2018 • edited by JakeWharton

consp1racy commented Sep 18, 2018

bpappin commented Oct 19, 2018

bpappin commented Oct 19, 2018

JakeWharton commented Oct 19, 2018

JakeWharton commented Oct 19, 2018

bpappin commented Oct 19, 2018

bpappin commented Oct 19, 2018

JakeWharton commented Oct 19, 2018

bpappin commented Oct 23, 2018 via email

JakeWharton commented Oct 23, 2018 via email

bpappin commented Oct 23, 2018

JakeWharton commented Oct 23, 2018

bpappin commented Oct 23, 2018

swankjesse commented Oct 23, 2018

swankjesse commented Oct 23, 2018

bpappin commented Oct 23, 2018

JakeWharton commented Oct 23, 2018

yschimke commented Jan 5, 2020

r9software commented Jan 26, 2021

swankjesse commented Jan 26, 2021

yschimke commented Jan 26, 2021

alonaviram commented Sep 17, 2018 •

edited by JakeWharton