0-byte body on sdk 6.12 with android when using HttpLoggingInterceptor

[slowcar]

I have the issue that the sdk posts no body (again). Related to https://github.com/microsoftgraph/msgraph-sdk-java/issues/1972 and https://github.com/microsoftgraph/msgraph-sdk-java/issues/1872 that i have posted before.

I can finally reproduce the issue, it occurs when i activate our HttpLoggingInterceptor

sdk is 6.12.0 on android 10, used logging-interceptor is the current version, 4.12.0

Here is our code to create the GraphServiceClient with the logger (simplified): HttpLoggingInterceptor loggingInterceptor = new HttpLoggingInterceptor(System.out::println); loggingInterceptor.level(HttpLoggingInterceptor.Level.BODY); OkHttpClient.Builder builder = GraphClientFactory.create(); builder.addInterceptor(loggingInterceptor); OkHttpClient okHttpClient = builder.build(); GraphServiceClient client = new GraphServiceClient(authProvider, okHttpClient);

If i set the Level to BASIC or NONE, the request works. If i change it to BODY again, it fails.

I am trying to retrieve user availability: `--> POST https://graph.microsoft.com/v1.0/me/calendar/getSchedule Content-Length: 227 content-type: application/json authorization: Bearer prefer: outlook.timezone="UTC" accept: application/json SdkVersion: graph-java, graph-java-core/3.1.12 (featureUsage=1203; android/29) client-request-id: f0b3a2d1-506f-4bbd-9b03-8ba3b71a8085 User-Agent: kiota-java/1.1.12

{"AvailabilityViewInterval":60,"EndTime":{"dateTime":"2024-06-05T13:00:00.000","timeZone":"UTC"},"Schedules":["x@x.x","y@y.y"],"StartTime":{"dateTime":"2024-06-05T12:00:00.000","timeZone":"UTC"}} --> END POST (0-byte body)`

Is there a different way to log headers and body?

[Ndiritu]

Hi @slowcar. Thanks for following up on this issue.

Setting the level to BODY causes the request to fail because the HttpLoggingInterceptor reads the entire stream's contents without resetting it meaning during sending the stream has no further bytes to be read.

To log the body, you can consider using the NativeResponseHandler to get the raw OkHttp Response object from where you can log the response.request. This would however prevent the normal deserialization process.

@baywet @andrueastman thoughts on logging the request body to the OpenTelemetry spans?

[Ndiritu]

A better alternative could be to extend the HttpLoggingInterceptor and reset the ResponseBody contents stream before continuing down the interceptor chain.

[slowcar]

To me it looks like the issue occurs with the request body, not with the response. The request is logged, but can no longer be handled by the graph sdk/kiota? HttpLoggingInterceptor sees to use a Buffer and requestBody.writeTo(buffer) which should be repeatable

I do not understand why the behavior is different compared to the 5.x sdk where we used httplogginginterceptor without any issue.

[mkomko]

I just ran into the same thing and thought that I must be doing something wrong in my own interceptor. But when the same thing happened when using OkHttp's own HttpLoggingInterceptor I got suspicious. Is this a bug in the SDK? What's the solution? Thanks in advance!

[slowcar]

We have removed logging from POST requests as a workaround. Using NativeResponseHandler looks quite complicated and we actually want all the parsing etc. I tried extending HttpLoggingInterceptor but to no avail.

[mkomko]

@baywet @Ndiritu Any update on this? It must be something in the SDK, since OkHttp's own HttpLoggingInterceptor shows that writing to a Buffer should not cause the request body to not be readable again.

It's pretty problematic to not be able to see the request body when reporting issues or analyzing problems.

Thanks in advance!