Interceptor for timing multiple, concurrent requests

[guymclean]

Our team feel it would be really helpful if there was a simple way to add a 'request timing' interceptor which logged the total duration it took for requests to be resolved.

@JEuler kindly responded to my previous ticket regarding an interceptor that would log the duration of a network call (#279), however the approach employs an instance variable on the interceptor to hold the request start time, and as the same instance of the interceptor is used for every call, this approach fails to correctly time multiple, concurrent calls.

One way of doing this is to add a custom header to the request (say, send-time) and access the value of this from within the response, however it is bad practice to add headers unnecessarily and some servers may returned a cached value causing issues.

Is there a way to do this, and would this be something the Chopper team would consider adding? We feel it would be very helpful during development and debugging. Thanks!

[JEuler]

Whoops, sorry, will refine it later this week :)

[JEuler]

Whoops, sorry one more time. :)

So, basically, I think you can go with creating kind of "global" map of <string(path of request for example), int> values. And update this map during the network calls. It is not looking like a solution but a hack. :)

[guymclean]

Thanks for looking into this. That's a good idea and my team considered a similar approach, however there are cases where there is no real identifier to use (the requests may have exactly the same path and body) for the map key, and therefore we cannot use this strategy. Is the issue that chopper is built on top of the http package which doesn't expose requests/responses at a low enough level to identify individual requests?

[fryette]

@guymclean
I see 3 options

1. Use Charles with proxy settings enabled. You will see all requests. Most preferable and I believe the most right one.
2. Correct me if I'm wrong, but the request object is absolutely the same in response(yes, the Response has a reference on the Request object).
3. Use your wrapper over the request class then you can determine how much it takes.(combine together with 2)

It's just a theory.

As for me, I'm using 1, because our QA would like to see body/headers and so on as well as timings.

[JEuler]

I'm also using 1 :)

[guymclean]

@fryette thanks for the response.

1. Yes we could use Charles but it adds inconvenient overheads just to get a simple request duration.
2. Yes the request object is exactly the same but there is still no way to identify unique requests, only requests with the same contents (of which their could be multiple)
3. A wrapper may work but it seems a shame to convolute the code to get request duration

[fryette]

@guymclean
4. Add logger to the server)

[guymclean]

Myself and the team have been investigating further as we feel this is a core requirement of this kind of package.

There are 3 types of request object, Request (from the Chopper lib) and Request/BaseRequest from the http lib. The toBaseRequest() method in the Chopper Request object creates and returns a new instance each time. Because BaseRequest doesn't implement hashCode, the base requests that we can access in the onRequest method and onResponse methods don't equate as equal. This is why the idea that @JEuler suggested using a map of requests/hashCodes to date times won't work currently.

One work around we have discovered is to extend the Chopper Request class to cache the BaseRequest object it returns each time it is requested. This way, the exact same instance is used and therefore we can compare equality of BaseRequest in the onRequest and onResponse methods. This allows us to use the map of requests/hashCodes to date times approach.

We hope the Chopper team will include a solution for reliable request timing in a future release. Please let me know if you require any further information.

[guymclean]

Here is the code we are using if you are interested

import 'dart:async';

import 'package:chopper/chopper.dart';
import 'package:flutter/foundation.dart';
import 'package:http/http.dart' as http;

/// A [RequestInterceptor] and [ResponseInterceptor] implementation which logs
/// HTTP request and response data.
///
/// This standard Chopper interceptor has been extended to time calls also
@immutable
class CustomHttpLoggingInterceptor
    implements RequestInterceptor, ResponseInterceptor {
  final Map<int, DateTime> _requestHashCodeToDateTime = {};

  @override
  FutureOr<Request> onRequest(Request request) async {
    final customRequest = CustomRequest(
      request.method,
      request.url,
      request.baseUrl,
      body: request.body,
      parts: request.parts,
      parameters: request.parameters,
      headers: request.headers,
      multipart: request.multipart,
    );

    final base = await customRequest.toBaseRequest();
    chopperLogger.info('--> ${base.method} ${base.url}');
    base.headers.forEach((k, v) => chopperLogger.info('$k: $v'));

    // add hashCode -> requestTime entry to map
    final hashCode = base.hashCode;
    final requestTime = DateTime.now();
    _requestHashCodeToDateTime[hashCode] = requestTime;

    var bytes = '';
    if (base is http.Request) {
      final body = base.body;
      if (body.isNotEmpty) {
        chopperLogger.info(body);
        bytes = ' (${base.bodyBytes.length}-byte body)';
      }
    }

    chopperLogger.info('--> END ${base.method}$bytes');
    return customRequest;
  }

  @override
  FutureOr<Response> onResponse(Response response) {
    final base = response.base.request;
    chopperLogger.info('<-- ${response.statusCode} ${base!.url}');

    response.base.headers.forEach((k, v) => chopperLogger.info('$k: $v'));

    var bytes = '';
    if (response.base is http.Response) {
      final resp = response.base as http.Response;
      if (resp.body.isNotEmpty) {
        chopperLogger.info(resp.body);
        bytes = ' (${response.bodyBytes.length}-byte body)';
      }
    }

    // determine and log the call duration
    final hashCode = base.hashCode;
    final responseTime = DateTime.now();
    if (_requestHashCodeToDateTime.containsKey(hashCode)) {
      final requestTime = _requestHashCodeToDateTime[hashCode];
      final durationInMillis =
          requestTime?.difference(responseTime).inMilliseconds.abs();
      _requestHashCodeToDateTime.remove(base.hashCode);

      chopperLogger.info('Duration: ${durationInMillis}ms');
    }

    chopperLogger.info('--> END ${base.method}$bytes');
    return response;
  }
}

// ignore: must_be_immutable
class CustomRequest extends Request {
  http.BaseRequest? base;

  CustomRequest(
    String method,
    String url,
    String baseUrl, {
    dynamic body,
    List<PartValue>? parts,
    Map<String, dynamic>? parameters,
    Map<String, String>? headers,
    bool? multipart,
  }) : super(
          method,
          url,
          baseUrl,
          body: body,
          parameters: parameters ?? const {},
          headers: headers ?? const {},
          multipart: multipart ?? false,
          parts: parts ?? const [],
        );

  @override
  Future<http.BaseRequest> toBaseRequest() async {
    base ??= await super.toBaseRequest();
    return base!;
  }
}

[techouse]

@JEuler @guymclean has this issue been fully addressed/fixed?

[Guldem]

From the comments I think its partly solved.

When I refactored bits of the logging interceptor I faced the same problems. A possible solution could be to refactor the whole interceptor mechanism to be more of chain instead of separate onRequest/onResponse calls. This is also how OkHttp solves this problem.

It would be a big refactor which also impacts other parts of the code base. Beside being able to time request I could also provide other benefits as better separation of certain processes.