[ dart:io ] Added timeline events for HttpClient connections and requests

Setting the `enableTimelineLogging` property of `HttpClient` to true results in
timeline events being created for HTTP connections and HTTP requests.
Timeline events contain general connection information, including:
  - Request type
  - Status code
  - Request / response headers
  - Cookies
  - Non-sensitive proxy information
  - Relevent error messages for failed connections

Change-Id: Ibe16a312ab5398c9ae886ea07bea5ca70b63e440
Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/123540
Commit-Queue: Ben Konyi <bkonyi@google.com>
Reviewed-by: Ryan Macnak <rmacnak@google.com>

CHANGELOG.md

@@ -157,6 +157,12 @@ main() { foo(() {}); }
 * Added optional `parent` parameter to `TimelineTask` constructor to allow for
   linking of asynchronous timeline events in the DevTools timeline view.
 
+#### `dart:io`
+
+* Added `enableTimelineLogging` property to `HttpClient` which, when enabled,
+  will post HTTP connection and request information to the developer timeline
+  for all `HttpClient` instances.
+
 ### Dart VM
 
 * Added a new tool for AOT compiling Dart programs to native, self-contained

runtime/observatory/tests/service/verify_http_timeline_test.dart

@@ -0,0 +1,288 @@
+// Copyright (c) 2019, the Dart project authors.  Please see the AUTHORS file
+// for details. All rights reserved. Use of this source code is governed by a
+// BSD-style license that can be found in the LICENSE file.
+// VMOptions=--timeline_streams=Dart
+
+import 'dart:async';
+import 'dart:developer';
+import 'dart:io';
+import 'dart:math';
+import 'package:observatory/service_io.dart';
+import 'package:unittest/unittest.dart';
+
+import 'test_helper.dart';
+
+final rng = Random();
+
+// Enable to test redirects.
+const shouldTestRedirects = false;
+
+const maxRequestDelayMs = 3000;
+const maxResponseDelayMs = 500;
+const serverShutdownDelayMs = 2000;
+
+void randomlyAddCookie(HttpResponse response) {
+  if (rng.nextInt(3) == 0) {
+    response.cookies.add(Cookie('Cookie-Monster', 'Me-want-cookie!'));
+  }
+}
+
+Future<bool> randomlyRedirect(HttpServer server, HttpResponse response) async {
+  if (shouldTestRedirects && rng.nextInt(5) == 0) {
+    final redirectUri = Uri(host: 'www.google.com', port: 80);
+    response.redirect(redirectUri);
+    return true;
+  }
+  return false;
+}
+
+// Execute HTTP requests with random delays so requests have some overlap. This
+// way we can be certain that timeline events are matching up properly even when
+// connections are interrupted or can't be established.
+Future<void> executeWithRandomDelay(Function f) =>
+    Future<void>.delayed(Duration(milliseconds: rng.nextInt(maxRequestDelayMs)))
+        .then((_) async {
+      try {
+        await f();
+      } on HttpException catch (_) {} on SocketException catch (_) {} on StateError catch (_) {}
+    });
+
+Uri randomlyAddRequestParams(Uri uri) {
+  const possiblePathSegments = <String>['foo', 'bar', 'baz', 'foobar'];
+  final segmentSubset =
+      possiblePathSegments.sublist(0, rng.nextInt(possiblePathSegments.length));
+  uri = uri.replace(pathSegments: segmentSubset);
+  if (rng.nextInt(3) == 0) {
+    uri = uri.replace(queryParameters: {
+      'foo': 'bar',
+      'year': '2019',
+    });
+  }
+  return uri;
+}
+
+Future<HttpServer> startServer() async {
+  final server = await HttpServer.bind(InternetAddress.loopbackIPv4, 8011);
+  server.listen((request) async {
+    final response = request.response;
+    randomlyAddCookie(response);
+    if (await randomlyRedirect(server, response)) {
+      // Redirect calls close() on the response.
+      return;
+    }
+    // Randomly delay response.
+    await Future.delayed(
+        Duration(milliseconds: rng.nextInt(maxResponseDelayMs)));
+    response.close();
+  });
+  return server;
+}
+
+Future<void> testMain() async {
+  // Ensure there's a chance some requests will be interrupted.
+  expect(maxRequestDelayMs > serverShutdownDelayMs, isTrue);
+  expect(maxResponseDelayMs < serverShutdownDelayMs, isTrue);
+
+  final server = await startServer();
+  HttpClient.enableTimelineLogging = true;
+  final client = HttpClient();
+  final requests = <Future>[];
+  final address =
+      Uri(scheme: 'http', host: server.address.host, port: server.port);
+
+  // HTTP DELETE
+  for (int i = 0; i < 10; ++i) {
+    final future = executeWithRandomDelay(() async {
+      final r = await client.deleteUrl(randomlyAddRequestParams(address));
+      await r.close();
+    });
+    requests.add(future);
+  }
+
+  // HTTP GET
+  for (int i = 0; i < 10; ++i) {
+    final future = executeWithRandomDelay(() async {
+      final r = await client.getUrl(randomlyAddRequestParams(address));
+      await r.close();
+    });
+    requests.add(future);
+  }
+
+  // HTTP HEAD
+  for (int i = 0; i < 10; ++i) {
+    final future = executeWithRandomDelay(() async {
+      final r = await client.headUrl(randomlyAddRequestParams(address));
+      await r.close();
+    });
+    requests.add(future);
+  }
+
+  // HTTP CONNECT
+  for (int i = 0; i < 10; ++i) {
+    final future = executeWithRandomDelay(() async {
+      final r =
+          await client.openUrl('connect', randomlyAddRequestParams(address));
+      await r.close();
+    });
+    requests.add(future);
+  }
+
+  // HTTP PATCH
+  for (int i = 0; i < 10; ++i) {
+    final future = executeWithRandomDelay(() async {
+      final r = await client.patchUrl(randomlyAddRequestParams(address));
+      await r.close();
+    });
+    requests.add(future);
+  }
+
+  // HTTP POST
+  for (int i = 0; i < 10; ++i) {
+    final future = executeWithRandomDelay(() async {
+      final r = await client.postUrl(randomlyAddRequestParams(address));
+      await r.close();
+    });
+    requests.add(future);
+  }
+
+  // HTTP PUT
+  for (int i = 0; i < 10; ++i) {
+    final future = executeWithRandomDelay(() async {
+      final r = await client.putUrl(randomlyAddRequestParams(address));
+      await r.close();
+    });
+    requests.add(future);
+  }
+
+  // Purposefully close server before some connections can be made to ensure
+  // that refused / interrupted connections correctly create finish timeline
+  // events.
+  await Future.delayed(Duration(milliseconds: serverShutdownDelayMs));
+  await server.close();
+
+  // Ensure all requests complete before finishing.
+  await Future.wait(requests);
+}
+
+bool isStartEvent(Map event) => (event['ph'] == 'b');
+bool isFinishEvent(Map event) => (event['ph'] == 'e');
+
+bool hasCompletedEvents(List traceEvents) {
+  final events = <String, int>{};
+  for (final event in traceEvents) {
+    if (isStartEvent(event)) {
+      final id = event['id'];
+      events.putIfAbsent(id, () => 0);
+      events[id]++;
+    } else if (isFinishEvent(event)) {
+      final id = event['id'];
+      events[id]--;
+    }
+  }
+  bool valid = true;
+  events.forEach((id, count) {
+    if (count != 0) {
+      valid = false;
+    }
+  });
+  return valid;
+}
+
+List filterEventsByName(List traceEvents, String name) =>
+    traceEvents.where((e) => e['name'].contains(name)).toList();
+
+void hasValidHttpConnections(List traceEvents) {
+  final events = filterEventsByName(traceEvents, 'HTTP Connection');
+  expect(hasCompletedEvents(events), isTrue);
+}
+
+void validateHttpStartEvent(Map event, String method) {
+  expect(event.containsKey('args'), isTrue);
+  final args = event['args'];
+  expect(args.containsKey('method'), isTrue);
+  expect(args['method'], method);
+  if (!args.containsKey('error')) {
+    expect(args.containsKey('requestHeaders'), isTrue);
+    expect(args['requestHeaders'] != null, isTrue);
+    expect(args.containsKey('compressionState'), isTrue);
+    expect(args.containsKey('connectionInfo'), isTrue);
+    expect(args.containsKey('contentLength'), isTrue);
+    expect(args.containsKey('cookies'), isTrue);
+    expect(args.containsKey('responseHeaders'), isTrue);
+    expect(args.containsKey('isRedirect'), isTrue);
+    expect(args.containsKey('persistentConnection'), isTrue);
+    expect(args.containsKey('reasonPhrase'), isTrue);
+    expect(args.containsKey('redirects'), isTrue);
+    expect(args.containsKey('statusCode'), isTrue);
+    // If proxyInfo is non-null, uri and port _must_ be non-null.
+    if (args.containsKey('proxyInfo')) {
+      final proxyInfo = args['proxyInfo'];
+      expect(proxyInfo.containsKey('uri'), isTrue);
+      expect(proxyInfo.containsKey('port'), isTrue);
+    }
+  }
+}
+
+void validateHttpFinishEvent(Map event) {
+  expect(event.containsKey('args'), isTrue);
+  final args = event['args'];
+  expect(args.containsKey('compressionState'), isTrue);
+  expect(args.containsKey('connectionInfo'), isTrue);
+  expect(args.containsKey('contentLength'), isTrue);
+  expect(args.containsKey('cookies'), isTrue);
+  expect(args.containsKey('responseHeaders'), isTrue);
+  expect(args.containsKey('isRedirect'), isTrue);
+  expect(args.containsKey('persistentConnection'), isTrue);
+  expect(args.containsKey('reasonPhrase'), isTrue);
+  expect(args.containsKey('redirects'), isTrue);
+  expect(args.containsKey('statusCode'), isTrue);
+}
+
+void hasValidHttpRequests(List traceEvents, String method) {
+  final events = filterEventsByName(traceEvents, 'HTTP $method');
+  expect(hasCompletedEvents(events), isTrue);
+  for (final event in events) {
+    if (isStartEvent(event)) {
+      validateHttpStartEvent(event, method);
+    } else if (isFinishEvent(event)) {
+      validateHttpFinishEvent(event);
+    } else {
+      fail('unexpected event type: ${event["ph"]}');
+    }
+  }
+}
+
+void hasValidHttpCONNECTs(List traceEvents) =>
+    hasValidHttpRequests(traceEvents, 'CONNECT');
+void hasValidHttpDELETEs(List traceEvents) =>
+    hasValidHttpRequests(traceEvents, 'DELETE');
+void hasValidHttpGETs(List traceEvents) =>
+    hasValidHttpRequests(traceEvents, 'GET');
+void hasValidHttpHEADs(List traceEvents) =>
+    hasValidHttpRequests(traceEvents, 'HEAD');
+void hasValidHttpPATCHs(List traceEvents) =>
+    hasValidHttpRequests(traceEvents, 'PATCH');
+void hasValidHttpPOSTs(List traceEvents) =>
+    hasValidHttpRequests(traceEvents, 'POST');
+void hasValidHttpPUTs(List traceEvents) =>
+    hasValidHttpRequests(traceEvents, 'PUT');
+
+var tests = <IsolateTest>[
+  (Isolate isolate) async {
+    final result = await isolate.vm.invokeRpcNoUpgrade('getVMTimeline', {});
+    expect(result['type'], 'Timeline');
+    expect(result.containsKey('traceEvents'), isTrue);
+    final traceEvents = result['traceEvents'];
+    expect(traceEvents.length > 0, isTrue);
+    hasValidHttpConnections(traceEvents);
+    hasValidHttpCONNECTs(traceEvents);
+    hasValidHttpDELETEs(traceEvents);
+    hasValidHttpGETs(traceEvents);
+    hasValidHttpHEADs(traceEvents);
+    hasValidHttpPATCHs(traceEvents);
+    hasValidHttpPOSTs(traceEvents);
+    hasValidHttpPUTs(traceEvents);
+  },
+];
+
+main(args) async => runIsolateTests(args, tests, testeeBefore: testMain);

sdk/lib/_http/http.dart

@@ -1404,6 +1404,12 @@ abstract class HttpClient {
   @Deprecated("Use defaultHttpsPort instead")
   static const int DEFAULT_HTTPS_PORT = defaultHttpsPort;
 
+  /// Enable logging of HTTP requests from all [HttpClient]s to the developer
+  /// timeline.
+  ///
+  /// Default is `false`.
+  static bool enableTimelineLogging;
+
   /// Gets and sets the idle timeout of non-active persistent (keep-alive)
   /// connections.
   ///

sdk/lib/_http/http_impl.dart

@@ -445,7 +445,9 @@ class _HttpClientResponse extends _HttpInboundMessageListInt
   }
 
   Future<HttpClientResponse> _authenticate(bool proxyAuth) {
+    _httpRequest._timeline?.instant('Authentication');
     Future<HttpClientResponse> retry() {
+      _httpRequest._timeline?.instant('Retrying');
       // Drain body and retry.
       return drain().then((_) {
         return _httpClient
@@ -1064,6 +1066,7 @@ class _HttpClientRequest extends _HttpOutboundMessage<HttpClientResponse>
   // The HttpClient this request belongs to.
   final _HttpClient _httpClient;
   final _HttpClientConnection _httpClientConnection;
+  final TimelineTask _timeline;
 
   final Completer<HttpClientResponse> _responseCompleter =
       new Completer<HttpClientResponse>();
@@ -1080,15 +1083,61 @@ class _HttpClientRequest extends _HttpOutboundMessage<HttpClientResponse>
   List<RedirectInfo> _responseRedirects = [];
 
   _HttpClientRequest(_HttpOutgoing outgoing, Uri uri, this.method, this._proxy,
-      this._httpClient, this._httpClientConnection)
+      this._httpClient, this._httpClientConnection, this._timeline)
       : uri = uri,
         super(uri, "1.1", outgoing) {
+    _timeline?.instant('Request initiated');
     // GET and HEAD have 'content-length: 0' by default.
     if (method == "GET" || method == "HEAD") {
       contentLength = 0;
     } else {
       headers.chunkedTransferEncoding = true;
     }
+
+    _responseCompleter.future.then((response) {
+      _timeline?.instant('Response receieved');
+      Map formatConnectionInfo() => {
+            'localPort': response.connectionInfo?.localPort,
+            'remoteAddress': response.connectionInfo?.remoteAddress?.address,
+            'remotePort': response.connectionInfo?.remotePort,
+          };
+
+      Map formatHeaders() {
+        final headers = <String, List<String>>{};
+        response.headers.forEach((name, values) {
+          headers[name] = values;
+        });
+        return headers;
+      }
+
+      List<Map<String, dynamic>> formatRedirectInfo() {
+        final redirects = <Map<String, dynamic>>[];
+        for (final redirect in response.redirects) {
+          redirects.add({
+            'location': redirect.location.toString(),
+            'method': redirect.method,
+            'statusCode': redirect.statusCode,
+          });
+        }
+        return redirects;
+      }
+
+      _timeline?.finish(arguments: {
+        // TODO(bkonyi): consider exposing certificate information?
+        // 'certificate': response.certificate,
+        'requestHeaders': outgoing.outbound.headers._headers,
+        'compressionState': response.compressionState.toString(),
+        'connectionInfo': formatConnectionInfo(),
+        'contentLength': response.contentLength,
+        'cookies': [for (final cookie in response.cookies) cookie.toString()],
+        'responseHeaders': formatHeaders(),
+        'isRedirect': response.isRedirect,
+        'persistentConnection': response.persistentConnection,
+        'reasonPhrase': response.reasonPhrase,
+        'redirects': formatRedirectInfo(),
+        'statusCode': response.statusCode,
+      });
+    }, onError: (e) {});
   }
 
   Future<HttpClientResponse> get done {
@@ -1686,7 +1735,8 @@ class _HttpClientConnection {
     });
   }
 
-  _HttpClientRequest send(Uri uri, int port, String method, _Proxy proxy) {
+  _HttpClientRequest send(
+      Uri uri, int port, String method, _Proxy proxy, TimelineTask timeline) {
     if (closed) {
       throw new HttpException("Socket closed before request was sent",
           uri: uri);
@@ -1698,8 +1748,8 @@ class _HttpClientConnection {
     _SiteCredentials creds; // Credentials used to authorize this request.
     var outgoing = new _HttpOutgoing(_socket);
     // Create new request object, wrapping the outgoing connection.
-    var request =
-        new _HttpClientRequest(outgoing, uri, method, proxy, _httpClient, this);
+    var request = new _HttpClientRequest(
+        outgoing, uri, method, proxy, _httpClient, this, timeline);
     // For the Host header an IPv6 address must be enclosed in []'s.
     var host = uri.host;
     if (host.contains(':')) host = "[$host]";
@@ -1734,6 +1784,7 @@ class _HttpClientConnection {
         creds.authorize(request);
       }
     }
+
     // Start sending the request (lazy, delayed until the user provides
     // data).
     _httpParser.isHead = method == "HEAD";
@@ -1827,10 +1878,31 @@ class _HttpClientConnection {
         .then((_) => _socket.destroy());
   }
 
-  Future<_HttpClientConnection> createProxyTunnel(String host, int port,
-      _Proxy proxy, bool callback(X509Certificate certificate)) {
+  Future<_HttpClientConnection> createProxyTunnel(
+      String host,
+      int port,
+      _Proxy proxy,
+      bool callback(X509Certificate certificate),
+      TimelineTask timeline) {
+    timeline?.instant('Establishing proxy tunnel', arguments: {
+      'proxyInfo': {
+        if (proxy.host != null) 'host': proxy.host,
+        if (proxy.port != null)
+          'port': proxy.port,
+        if (proxy.username != null)
+          'username': proxy.username,
+        // TODO(bkonyi): is this something we would want to surface? Initial
+        // thought is no.
+        // if (proxy.password != null)
+        //   'password': proxy.password,
+        'isDirect': proxy.isDirect,
+      }
+    });
+    final method = "CONNECT";
+    final uri = Uri(host: host, port: port);
+    _HttpClient._startRequestTimelineEvent(timeline, method, uri);
     _HttpClientRequest request =
-        send(new Uri(host: host, port: port), port, "CONNECT", proxy);
+        send(Uri(host: host, port: port), port, method, proxy, timeline);
     if (proxy.isAuthenticated) {
       // If the proxy configuration contains user information use that
       // for proxy basic authorization.
@@ -1840,10 +1912,10 @@ class _HttpClientConnection {
     }
     return request.close().then((response) {
       if (response.statusCode != HttpStatus.ok) {
-        throw new HttpException(
-            "Proxy failed to establish tunnel "
-            "(${response.statusCode} ${response.reasonPhrase})",
-            uri: request.uri);
+        final error = "Proxy failed to establish tunnel "
+            "(${response.statusCode} ${response.reasonPhrase})";
+        timeline?.instant(error);
+        throw new HttpException(error, uri: request.uri);
       }
       var socket = (response as _HttpClientResponse)
           ._httpRequest
@@ -1853,6 +1925,7 @@ class _HttpClientConnection {
           host: host, context: _context, onBadCertificate: callback);
     }).then((secureSocket) {
       String key = _HttpClientConnection.makeKey(true, host, port);
+      timeline?.instant('Proxy tunnel established');
       return new _HttpClientConnection(
           key, secureSocket, request._httpClient, true);
     });
@@ -1966,8 +2039,8 @@ class _ConnectionTarget {
     }
   }
 
-  Future<_ConnectionInfo> connect(
-      String uriHost, int uriPort, _Proxy proxy, _HttpClient client) {
+  Future<_ConnectionInfo> connect(String uriHost, int uriPort, _Proxy proxy,
+      _HttpClient client, TimelineTask timeline) {
     if (hasIdle) {
       var connection = takeIdle();
       client._connectionsChanged();
@@ -1977,7 +2050,7 @@ class _ConnectionTarget {
         _active.length + _connecting >= client.maxConnectionsPerHost) {
       var completer = new Completer<_ConnectionInfo>();
       _pending.add(() {
-        completer.complete(connect(uriHost, uriPort, proxy, client));
+        completer.complete(connect(uriHost, uriPort, proxy, client, timeline));
       });
       return completer.future;
     }
@@ -2023,7 +2096,7 @@ class _ConnectionTarget {
         if (isSecure && !proxy.isDirect) {
           connection._dispose = true;
           return connection
-              .createProxyTunnel(uriHost, uriPort, proxy, callback)
+              .createProxyTunnel(uriHost, uriPort, proxy, callback, timeline)
               .then((tunnel) {
             client
                 ._getConnectionTarget(uriHost, uriPort, true)
@@ -2049,6 +2122,12 @@ class _ConnectionTarget {
 typedef bool BadCertificateCallback(X509Certificate cr, String host, int port);
 
 class _HttpClient implements HttpClient {
+  static bool _enableTimelineLogging = false;
+  static bool get enableTimelineLogging => _enableTimelineLogging;
+  static void set enableTimelineLogging(bool value) {
+    _enableTimelineLogging = value ?? false;
+  }
+
   bool _closing = false;
   bool _closingForcefully = false;
   final Map<String, _ConnectionTarget> _connectionTargets =
@@ -2177,6 +2256,16 @@ class _HttpClient implements HttpClient {
 
   set findProxy(String f(Uri uri)) => _findProxy = f;
 
+  static void _startRequestTimelineEvent(
+      TimelineTask timeline, String method, Uri uri) {
+    timeline?.start('HTTP CLIENT ${method.toUpperCase()}', arguments: {
+      'filterKey':
+          'HTTP/client', // key used to filter network requests from timeline
+      'method': method.toUpperCase(),
+      'uri': uri.toString(),
+    });
+  }
+
   Future<_HttpClientRequest> _openUrl(String method, Uri uri) {
     if (_closing) {
       throw new StateError("Client is closed");
@@ -2214,19 +2303,32 @@ class _HttpClient implements HttpClient {
         return new Future.error(error, stackTrace);
       }
     }
-    return _getConnection(uri.host, port, proxyConf, isSecure)
-        .then((_ConnectionInfo info) {
+    TimelineTask timeline;
+    // TODO(bkonyi): do we want this to be opt-in?
+    if (_enableTimelineLogging) {
+      timeline = TimelineTask();
+      _startRequestTimelineEvent(timeline, method, uri);
+    }
+    return _getConnection(uri.host, port, proxyConf, isSecure, timeline).then(
+        (_ConnectionInfo info) {
       _HttpClientRequest send(_ConnectionInfo info) {
+        timeline?.instant('Connection established');
         return info.connection
-            .send(uri, port, method.toUpperCase(), info.proxy);
+            .send(uri, port, method.toUpperCase(), info.proxy, timeline);
       }
 
       // If the connection was closed before the request was sent, create
       // and use another connection.
       if (info.connection.closed) {
-        return _getConnection(uri.host, port, proxyConf, isSecure).then(send);
+        return _getConnection(uri.host, port, proxyConf, isSecure, timeline)
+            .then(send);
       }
       return send(info);
+    }, onError: (error) {
+      timeline?.finish(arguments: {
+        'error': error.toString(),
+      });
+      throw error;
     });
   }
 
@@ -2293,7 +2395,7 @@ class _HttpClient implements HttpClient {
 
   // Get a new _HttpClientConnection, from the matching _ConnectionTarget.
   Future<_ConnectionInfo> _getConnection(String uriHost, int uriPort,
-      _ProxyConfiguration proxyConf, bool isSecure) {
+      _ProxyConfiguration proxyConf, bool isSecure, TimelineTask timeline) {
     Iterator<_Proxy> proxies = proxyConf.proxies.iterator;
 
     Future<_ConnectionInfo> connect(error) {
@@ -2302,7 +2404,7 @@ class _HttpClient implements HttpClient {
       String host = proxy.isDirect ? uriHost : proxy.host;
       int port = proxy.isDirect ? uriPort : proxy.port;
       return _getConnectionTarget(host, port, isSecure)
-          .connect(uriHost, uriPort, proxy, this)
+          .connect(uriHost, uriPort, proxy, this, timeline)
           // On error, continue with next proxy.
           .catchError(connect);
     }

sdk_nnbd/lib/_http/http.dart

@@ -1404,6 +1404,12 @@ abstract class HttpClient {
   @Deprecated("Use defaultHttpsPort instead")
   static const int DEFAULT_HTTPS_PORT = defaultHttpsPort;
 
+  /// Enable logging of HTTP requests from all [HttpClient]s to the developer
+  /// timeline.
+  ///
+  /// Default is `false`.
+  static bool enableTimelineLogging;
+
   /// Gets and sets the idle timeout of non-active persistent (keep-alive)
   /// connections.
   ///

sdk_nnbd/lib/_http/http_impl.dart

@@ -445,7 +445,9 @@ class _HttpClientResponse extends _HttpInboundMessageListInt
   }
 
   Future<HttpClientResponse> _authenticate(bool proxyAuth) {
+    _httpRequest._timeline?.instant('Authentication');
     Future<HttpClientResponse> retry() {
+      _httpRequest._timeline?.instant('Retrying');
       // Drain body and retry.
       return drain().then((_) {
         return _httpClient
@@ -1064,6 +1066,7 @@ class _HttpClientRequest extends _HttpOutboundMessage<HttpClientResponse>
   // The HttpClient this request belongs to.
   final _HttpClient _httpClient;
   final _HttpClientConnection _httpClientConnection;
+  final TimelineTask _timeline;
 
   final Completer<HttpClientResponse> _responseCompleter =
       new Completer<HttpClientResponse>();
@@ -1080,15 +1083,61 @@ class _HttpClientRequest extends _HttpOutboundMessage<HttpClientResponse>
   List<RedirectInfo> _responseRedirects = [];
 
   _HttpClientRequest(_HttpOutgoing outgoing, Uri uri, this.method, this._proxy,
-      this._httpClient, this._httpClientConnection)
+      this._httpClient, this._httpClientConnection, this._timeline)
       : uri = uri,
         super(uri, "1.1", outgoing) {
+    _timeline?.instant('Request initiated');
     // GET and HEAD have 'content-length: 0' by default.
     if (method == "GET" || method == "HEAD") {
       contentLength = 0;
     } else {
       headers.chunkedTransferEncoding = true;
     }
+
+    _responseCompleter.future.then((response) {
+      _timeline?.instant('Response receieved');
+      Map formatConnectionInfo() => {
+            'localPort': response.connectionInfo?.localPort,
+            'remoteAddress': response.connectionInfo?.remoteAddress?.address,
+            'remotePort': response.connectionInfo?.remotePort,
+          };
+
+      Map formatHeaders() {
+        final headers = <String, List<String>>{};
+        response.headers.forEach((name, values) {
+          headers[name] = values;
+        });
+        return headers;
+      }
+
+      List<Map<String, dynamic>> formatRedirectInfo() {
+        final redirects = <Map<String, dynamic>>[];
+        for (final redirect in response.redirects) {
+          redirects.add({
+            'location': redirect.location.toString(),
+            'method': redirect.method,
+            'statusCode': redirect.statusCode,
+          });
+        }
+        return redirects;
+      }
+
+      _timeline?.finish(arguments: {
+        // TODO(bkonyi): consider exposing certificate information?
+        // 'certificate': response.certificate,
+        'requestHeaders': outgoing.outbound.headers._headers,
+        'compressionState': response.compressionState.toString(),
+        'connectionInfo': formatConnectionInfo(),
+        'contentLength': response.contentLength,
+        'cookies': [for (final cookie in response.cookies) cookie.toString()],
+        'responseHeaders': formatHeaders(),
+        'isRedirect': response.isRedirect,
+        'persistentConnection': response.persistentConnection,
+        'reasonPhrase': response.reasonPhrase,
+        'redirects': formatRedirectInfo(),
+        'statusCode': response.statusCode,
+      });
+    }, onError: (e) {});
   }
 
   Future<HttpClientResponse> get done {
@@ -1686,7 +1735,8 @@ class _HttpClientConnection {
     });
   }
 
-  _HttpClientRequest send(Uri uri, int port, String method, _Proxy proxy) {
+  _HttpClientRequest send(
+      Uri uri, int port, String method, _Proxy proxy, TimelineTask timeline) {
     if (closed) {
       throw new HttpException("Socket closed before request was sent",
           uri: uri);
@@ -1698,8 +1748,8 @@ class _HttpClientConnection {
     _SiteCredentials creds; // Credentials used to authorize this request.
     var outgoing = new _HttpOutgoing(_socket);
     // Create new request object, wrapping the outgoing connection.
-    var request =
-        new _HttpClientRequest(outgoing, uri, method, proxy, _httpClient, this);
+    var request = new _HttpClientRequest(
+        outgoing, uri, method, proxy, _httpClient, this, timeline);
     // For the Host header an IPv6 address must be enclosed in []'s.
     var host = uri.host;
     if (host.contains(':')) host = "[$host]";
@@ -1734,6 +1784,7 @@ class _HttpClientConnection {
         creds.authorize(request);
       }
     }
+
     // Start sending the request (lazy, delayed until the user provides
     // data).
     _httpParser.isHead = method == "HEAD";
@@ -1827,10 +1878,31 @@ class _HttpClientConnection {
         .then((_) => _socket.destroy());
   }
 
-  Future<_HttpClientConnection> createProxyTunnel(String host, int port,
-      _Proxy proxy, bool callback(X509Certificate certificate)) {
+  Future<_HttpClientConnection> createProxyTunnel(
+      String host,
+      int port,
+      _Proxy proxy,
+      bool callback(X509Certificate certificate),
+      TimelineTask timeline) {
+    timeline?.instant('Establishing proxy tunnel', arguments: {
+      'proxyInfo': {
+        if (proxy.host != null) 'host': proxy.host,
+        if (proxy.port != null)
+          'port': proxy.port,
+        if (proxy.username != null)
+          'username': proxy.username,
+        // TODO(bkonyi): is this something we would want to surface? Initial
+        // thought is no.
+        // if (proxy.password != null)
+        //   'password': proxy.password,
+        'isDirect': proxy.isDirect,
+      }
+    });
+    final method = "CONNECT";
+    final uri = Uri(host: host, port: port);
+    _HttpClient._startRequestTimelineEvent(timeline, method, uri);
     _HttpClientRequest request =
-        send(new Uri(host: host, port: port), port, "CONNECT", proxy);
+        send(Uri(host: host, port: port), port, method, proxy, timeline);
     if (proxy.isAuthenticated) {
       // If the proxy configuration contains user information use that
       // for proxy basic authorization.
@@ -1840,10 +1912,10 @@ class _HttpClientConnection {
     }
     return request.close().then((response) {
       if (response.statusCode != HttpStatus.ok) {
-        throw new HttpException(
-            "Proxy failed to establish tunnel "
-            "(${response.statusCode} ${response.reasonPhrase})",
-            uri: request.uri);
+        final error = "Proxy failed to establish tunnel "
+            "(${response.statusCode} ${response.reasonPhrase})";
+        timeline?.instant(error);
+        throw new HttpException(error, uri: request.uri);
       }
       var socket = (response as _HttpClientResponse)
           ._httpRequest
@@ -1853,6 +1925,7 @@ class _HttpClientConnection {
           host: host, context: _context, onBadCertificate: callback);
     }).then((secureSocket) {
       String key = _HttpClientConnection.makeKey(true, host, port);
+      timeline?.instant('Proxy tunnel established');
       return new _HttpClientConnection(
           key, secureSocket, request._httpClient, true);
     });
@@ -1966,8 +2039,8 @@ class _ConnectionTarget {
     }
   }
 
-  Future<_ConnectionInfo> connect(
-      String uriHost, int uriPort, _Proxy proxy, _HttpClient client) {
+  Future<_ConnectionInfo> connect(String uriHost, int uriPort, _Proxy proxy,
+      _HttpClient client, TimelineTask timeline) {
     if (hasIdle) {
       var connection = takeIdle();
       client._connectionsChanged();
@@ -1977,7 +2050,7 @@ class _ConnectionTarget {
         _active.length + _connecting >= client.maxConnectionsPerHost) {
       var completer = new Completer<_ConnectionInfo>();
       _pending.add(() {
-        completer.complete(connect(uriHost, uriPort, proxy, client));
+        completer.complete(connect(uriHost, uriPort, proxy, client, timeline));
       });
       return completer.future;
     }
@@ -2023,7 +2096,7 @@ class _ConnectionTarget {
         if (isSecure && !proxy.isDirect) {
           connection._dispose = true;
           return connection
-              .createProxyTunnel(uriHost, uriPort, proxy, callback)
+              .createProxyTunnel(uriHost, uriPort, proxy, callback, timeline)
               .then((tunnel) {
             client
                 ._getConnectionTarget(uriHost, uriPort, true)
@@ -2049,6 +2122,12 @@ class _ConnectionTarget {
 typedef bool BadCertificateCallback(X509Certificate cr, String host, int port);
 
 class _HttpClient implements HttpClient {
+  static bool _enableTimelineLogging = false;
+  static bool get enableTimelineLogging => _enableTimelineLogging;
+  static void set enableTimelineLogging(bool value) {
+    _enableTimelineLogging = value ?? false;
+  }
+
   bool _closing = false;
   bool _closingForcefully = false;
   final Map<String, _ConnectionTarget> _connectionTargets =
@@ -2177,6 +2256,16 @@ class _HttpClient implements HttpClient {
 
   set findProxy(String f(Uri uri)) => _findProxy = f;
 
+  static void _startRequestTimelineEvent(
+      TimelineTask timeline, String method, Uri uri) {
+    timeline?.start('HTTP CLIENT ${method.toUpperCase()}', arguments: {
+      'filterKey':
+          'HTTP/client', // key used to filter network requests from timeline
+      'method': method.toUpperCase(),
+      'uri': uri.toString(),
+    });
+  }
+
   Future<_HttpClientRequest> _openUrl(String method, Uri uri) {
     if (_closing) {
       throw new StateError("Client is closed");
@@ -2214,19 +2303,32 @@ class _HttpClient implements HttpClient {
         return new Future.error(error, stackTrace);
       }
     }
-    return _getConnection(uri.host, port, proxyConf, isSecure)
-        .then((_ConnectionInfo info) {
+    TimelineTask timeline;
+    // TODO(bkonyi): do we want this to be opt-in?
+    if (_enableTimelineLogging) {
+      timeline = TimelineTask();
+      _startRequestTimelineEvent(timeline, method, uri);
+    }
+    return _getConnection(uri.host, port, proxyConf, isSecure, timeline).then(
+        (_ConnectionInfo info) {
       _HttpClientRequest send(_ConnectionInfo info) {
+        timeline?.instant('Connection established');
         return info.connection
-            .send(uri, port, method.toUpperCase(), info.proxy);
+            .send(uri, port, method.toUpperCase(), info.proxy, timeline);
       }
 
       // If the connection was closed before the request was sent, create
       // and use another connection.
       if (info.connection.closed) {
-        return _getConnection(uri.host, port, proxyConf, isSecure).then(send);
+        return _getConnection(uri.host, port, proxyConf, isSecure, timeline)
+            .then(send);
       }
       return send(info);
+    }, onError: (error) {
+      timeline?.finish(arguments: {
+        'error': error.toString(),
+      });
+      throw error;
     });
   }
 
@@ -2293,7 +2395,7 @@ class _HttpClient implements HttpClient {
 
   // Get a new _HttpClientConnection, from the matching _ConnectionTarget.
   Future<_ConnectionInfo> _getConnection(String uriHost, int uriPort,
-      _ProxyConfiguration proxyConf, bool isSecure) {
+      _ProxyConfiguration proxyConf, bool isSecure, TimelineTask timeline) {
     Iterator<_Proxy> proxies = proxyConf.proxies.iterator;
 
     Future<_ConnectionInfo> connect(error) {
@@ -2302,7 +2404,7 @@ class _HttpClient implements HttpClient {
       String host = proxy.isDirect ? uriHost : proxy.host;
       int port = proxy.isDirect ? uriPort : proxy.port;
       return _getConnectionTarget(host, port, isSecure)
-          .connect(uriHost, uriPort, proxy, this)
+          .connect(uriHost, uriPort, proxy, this, timeline)
           // On error, continue with next proxy.
           .catchError(connect);
     }

tests/standalone_2/io/http_cookie_date_test.dart

@@ -9,6 +9,7 @@ library dart._http;
 import "dart:async";
 import "dart:collection";
 import "dart:convert";
+import "dart:developer";
 import "dart:io";
 import "dart:math";
 import "dart:typed_data";

tests/standalone_2/io/http_override_test.dart

@@ -16,6 +16,7 @@ class MyHttpClient1 implements HttpClient {
   Duration connectionTimeout;
   int maxConnectionsPerHost;
   bool autoUncompress;
+  bool enableTimelineLogging;
 
   Future<HttpClientRequest> open(
           String method, String host, int port, String path) =>
@@ -55,6 +56,7 @@ class MyHttpClient2 implements HttpClient {
   Duration connectionTimeout;
   int maxConnectionsPerHost;
   bool autoUncompress;
+  bool enableTimelineLogging;
 
   Future<HttpClientRequest> open(
           String method, String host, int port, String path) =>