square / okhttp

Square’s meticulous HTTP client for the JVM, Android, and GraalVM.
https://square.github.io/okhttp/
Apache License 2.0
45.75k stars 9.15k forks source link

Logging Interceptor Interleaving #2410

Closed eygraber closed 8 years ago

eygraber commented 8 years ago

I'm using HttpLoggingInterceptor from com.squareup.okhttp3:logging-interceptor:3.2.0 and I've noticed that when I make concurrent requests, the logging of the requests and responses are interleaved. I was able to fix this by providing a HttpLoggingInterceptor.Logger that adds synchronized to the log method. Was this left out of the library for performance purposes, or is it a bug?

HttpLoggingInterceptor loggingInterceptor = new HttpLoggingInterceptor(new HttpLoggingInterceptor.Logger() {
      @Override
      public synchronized void log(String message) {
        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 + 4000);
            Log.d("OkHttp", message.substring(i, end));
            i = end;
          } while (i < newline);
        }
      }
    });
    loggingInterceptor.setLevel(HttpLoggingInterceptor.Level.BODY);

OkHttpClient client = new OkHttpClient.Builder()
        .
        .
        .
        .addInterceptor(loggingInterceptor) // this should be the last Interceptor added
        .build();
swankjesse commented 8 years ago

Synchronized here is a little bit dangerous. If your logger is slow for any reason, your network requests could queue up. And even with synchronized, we’re just as likely to interleave with OkHttp as we are with other processes on the device.

eygraber commented 8 years ago

It seemed to work out for when I have concurrent requests in flight, i.e. the logs are no longer interleaved. I know that it doesn't guarantee that it won't interleave with other logs, but it gets rid of the immediate issue of N concurrent requests interleaving their logs.

Because of the above, and the issue with logging potentially causing requests to queue up, is it safe to assume this is working as intended?

swankjesse commented 8 years ago

I think in any situation where the logging interceptor is showing many concurrent requests, our best solution is to recommend Charles Proxy or Stetho, rather than making the logging interceptor more powerful. It's worth the effort to set up these tools.