Analytics API

[swankjesse]

We should add verbose logging for the response cache. Folks occasionally are puzzled when the cache doesn't work. Let's make it easy for them to figure out why.

It would also be handy for debug panels and optimizers to monitor bytes in and out, connections created, etc.

[realdadfish]

It would be great if okhttp would in general get a simple logging facility to see what is actually sent and received over the wire.

[swankjesse]

Also logging connection reuse should be helpful.

[codefromthecrypt]

I'd like to see overall overhead (bytes/ms) per request/response since w/SPDY, HTTP2 compression could dramatically impact things.

[swankjesse]

Strawman:

interface Observer {
  void before(Event event);
  void after(Event event);

  public class Event {
    public Type type;
    public Connection connection;
    public Request request;
    public Response response;
    public int bytesTransmitted;
  }

  public enum Type {
    CONNECT,
    DISCONNECT,
    REQUEST_HEADERS,
    REQUEST_BODY,
    RESPONSE_HEADERS,
    RESPONSE_BODY,
  }
}

We'd call the observer before and after we attempt to do I/O. Fields in Event would be populated as much as convenient: bytesTransmitted wouldn't be populated in BEFORE events, for example.

The application layer could plug into this to do logging or higher-level things.

[JakeWharton]

Connection is mutable so should we expose it?

[swankjesse]

Connection is the easiest way to get access to the Route, the Handshake and eventually the Protocol. We have an awkward time with the seam between public and internal APIs in OkHttp.

[swankjesse]

@tommyd3mdi our new interceptors API can be used to log exactly what went over the wire. See the newly-authored Interceptors doc for a very specific example.

I think that solves about 60% use case of this request. Making me feel justified in punting it to the icebox.

[karthikrg]

@swankjesse We've tried using interceptors but they don't allow us to analyze a connection at the granularity we want to. We are looking for more low level details like DNS lookup time, SSL negotiation time etc. Exposing HttpEngine with hooks for collecting this info would be very valuable to us.

[swankjesse]

With OkHttp 2.6 you'll be able to provide your own instrumented DNS for that, and you can already provide your own instrumented SSL Engine to time that. So what we really need is just a nice API to put it all together.

[swankjesse]

Relevant: https://github.com/raskasa/metrics-okhttp

[swankjesse]

Updated sketch:

package okhttp3;

import java.net.InetAddress;
import java.util.List;

public class EventListener {
  public static final EventListener NULL_EVENT_LISTENER = new EventListener() {
  };

  void dnsStart(String domainName) {
  }

  void dnsEnd(String domainName, List<InetAddress> inetAddressList) {
  }

  void requestHeadersStart(Call call) {
  }

  void requestHeadersEnd(Call call) {
  }
}

[swankjesse]

https://www.w3.org/TR/navigation-timing/#sec-navigation-timing-interface

[bric3]

I was playing around this class to expose some metrics for prometheus, and I noticed that callEnd event was not sent for DELETE calls. In subsequent tests I found out this problem is occurring only when the response has no body e.g. for 204 statuses. I looked at the code and found out some commented tests, like this one

okhttp/okhttp-tests/src/test/java/okhttp3/EventListenerTest.java

Lines 881 to 899 in d041837

	@Ignore("the CallEnd event is omitted")
	@Test public void emptyResponseBody() throws IOException {
	server.enqueue(new MockResponse()
	.setBody("")
	.setBodyDelay(1, TimeUnit.SECONDS)
	.setSocketPolicy(SocketPolicy.DISCONNECT_DURING_RESPONSE_BODY));
	Call call = client.newCall(new Request.Builder()
	.url(server.url("/"))
	.build());
	Response response = call.execute();
	response.body().close();
	List<String> expectedEvents = Arrays.asList("CallStart", "DnsStart", "DnsEnd",
	"ConnectStart", "ConnectEnd", "ConnectionAcquired", "RequestHeadersStart",
	"RequestHeadersEnd", "ResponseHeadersStart", "ResponseHeadersEnd", "ResponseBodyStart",
	"ResponseBodyEnd", "ConnectionReleased", "CallEnd");
	assertEquals(expectedEvents, listener.recordedEventTypes());
	}

I'm sure this is gonna be fixed in the next release(s) of okhttp. As a workaround, I think my only option at this is to place the metrics reporting in the connectionReleased event at this time. I don't think there's anything else, isn't it ?

In my case I know there won't be multiple connections

[swankjesse]

@bric3 sorry about that. Will fix.

[bric3]

@swankjesse Thanks. I was wondering if I mis-understood how event were sent.

I'm sure there's some challenges around that with protocols like websocket or http/2. Thanks again for this work !

[bric3]

@swankjesse I would like to monitor request by their route as defined in Retrofit. However this appear to be difficult to capture this information in Retrofit, see square/retrofit#2732. For bootstrapping the idea I talked about using Request.tag to pass along this contextual route data, but I don't think this is wise regarding the tag usage documentation.

Do you think OkHttp could introduce another concept in that regard ?

[codefromthecrypt]

@swankjesse <https://github.com/swankjesse> I would like to monitor request by their route as defined in Retrofit. However this appear to be difficult to capture this information in Retrofit, see square/retrofit#2732 <square/retrofit#2732>. For bootstrapping the idea I talked about using Request.tag to pass along this contextual route data, but I don't think this is wise regarding the tag usage documentation.

how are you planning to do the monitoring? For example, is it a timer? One thing you could do is add a synthetic request header that your "start" timer removes. There are probably other ways, too.

[bric3]

@adriancole Actually I implemented an eventlistener that feeds prometheus collectors (gauge, summary, counters). Summary are the closest thing to timers if compared to micrometer. (But for reasons outside of this scope I'm using summary instead of histograms).

I considered this approach as well in retrofit, but since I cannot modify the request at the right moment / stage in retrofit I cannot capture the path of the retrofit annotation.

[hamberluo]

@swankjesse EventListener callEnd does not call everytime after callStart

[bric3]

@hamberluo For a workaround look at #270 (comment)

[hamberluo]

@bric3 same workaround with mine. I wonder any other?

[yschimke]

Is it time to move out of experimental? #4068

[bric3]

@yschimke There'is still some bugs in the implementation see the above comments.

e..g this one #270 (comment)

[yschimke]

Can you file a separate issue? Would be really helpful. Specifically my question was prompted by whether the API is finalised. I’m sure we will keep finding some bugs.

[swankjesse]

I’m still happy with the API. I would like to add events for caching + conditional caching, but that isn’t urgent.

[swankjesse]

Final API released! Yay!

[codefromthecrypt]

fantastic!

[bric3]

Regarding the API, what about the above comments, which in short demands some kind of contextual data in the events themselves.

• Analytics API #270 (comment)
• Analytics API #270 (comment)
• Analytics API #270 (comment)

[bric3]

@yschimke Here is it : #4085

[yschimke]

@bric3 Can you file separate issues for the other comments, I am suggesting that feedback like this possibly got missed because of the one big thread.

[bric3]

@yschimke done in #4087

[swankjesse]

FYI: we’re adding new events in OkHttp 3.14.
#4638