Okhttp: Body logging breaks program flow when streams are used.

[snakeru]

The problem is there:
https://github.com/square/okhttp/blob/master/okhttp-logging-interceptor/src/main/java/okhttp3/logging/HttpLoggingInterceptor.java#L240

If I use a streaming connection (say, an SSE), then enabling requests body debugging breaks the program as the logging code waits for the whole body to become available.

ACTIONS:
1) A streaming request is made, a stream is opened, the ResponseBody is saved away for later processing
2) A regular GET request is made, the GET request body should be printed for debug purposes.
EXPECTED OUTPUT:

• the streaming request body is not printed at all as it is being processed outside of OkHTTP
• the regular GET request body is printed out
  ACTUAL OUTPUT:
• program hangs on the first step and never gets to step 2.

[snakeru]

For the record: I do not use the OkHTTP directly, but rather through the Retrofit library (thus the reference to the @Streaming mode). So it might be that I filed the bug report in the wrong place. If that is so - please excuse me and feel free to close it as "won't fix".

[swankjesse]

Don’t use the logging interceptor in such scenarios. Charles Proxy & Chuck are both better tools.

[snakeru]

"- Doctor, when I bend like this - it hurts!"
"- Well, don't bend like this. Next!"

I wouldn't use the logging interceptor in such scenario if I was aware of this bug. In fact, I disabled the body logging yesterday already.

The problem is - when a logging interceptor is enabled on a different day and/or for a different purpose and/or by a different person - it takes time to figure out what went wrong.

If a particular combination of settings produces undesired behaviour - it should be either forbidden or at least a warning should be emitted along the lines of "The things are about to go wrong due to you, user, using A and B at the same time."

[yschimke]

That sounds like a fair point, should probably be more clearly documentated and warn noisily if misapplied. @swankjesse any objection?

[swankjesse]

It’s intended as a debug logger. I think perhaps we should deprecate the BODY mode because it’s so problematic.

[JakeWharton]

Or alias it to BUFFERED or BUFFERED_BODY.

On Tue, Oct 10, 2017 at 12:50 PM Jesse Wilson [e-mail]
wrote:

It’s intended as a debug logger. I think perhaps we should deprecate the
BODY mode because it’s so problematic.

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/square/okhttp/issues/3643#issuecomment-335537291, or mute
the thread
https://github.com/notifications/unsubscribe-auth/AAEEEQejzjJX3TKDOnqupN99nskUfNhOks5sq6A2gaJpZM4PyiJV
.

[guness]

I don't know if it is related but, when I POST a file using multipart(via Retrofit), Body logging breaks the request with the exception:
HTTP FAILED: java.io.IOException: Stream Closed

It works fine when I turn on other levels of logging. It would be great to be able to tune logging level per api call, maybe with annotation, not sure.

[swankjesse]

@guness does your RequestBody support having multiple calls to writeTo() ? That’s required because we call it once to log, and another time to upload.

[swankjesse]

Nothing actionable here.

[guness]

@swankjesse this is my RequestBody:

private fun create(inputStream: InputStream, size: Long, mimeType: String): RequestBody {

    return object : RequestBody() {
        override fun contentType(): MediaType? {
            return MediaType.parse(mimeType)
        }

        override fun contentLength(): Long {
            return size
        }

        @Throws(IOException::class)
        override fun writeTo(sink: BufferedSink) {
            var source: Source? = null
            try {
                source = Okio.source(inputStream)
                sink.writeAll(source!!)
            } catch (e: Exception) {
                Timber.w(e, "Exception while writing all")
                throw e
            } finally {
                Util.closeQuietly(source)
            }
        }
    }
}

not sure if Util closes underlying inputStream.

[swankjesse]

Yeah, this RequestBody is not valid. You need to change it so that it’s possible for OkHttp to call writeTo() multiple times, each time it produces a full copy of the request body.