_http: ensure _HttpProfileData.startResponse is called before finishResponse

Fixes flutter/devtools#8509

From my research into the bug:

> I see indeed that `_HttpProfileData.finishResponse()` is called before `_HttpProfileData.startResponse()`. I think this is just a result of microtask scheduling; when the response has no body, `_incoming.dataDone` completes before `_httpRequest._responseCompleter`.

> Since `startResponse` is responsible for setting `responseInProgress` to `true`, the call to `finishResponse` short circuit returns immediately. We therefore don't finish the response timeline, or log the end time, etc.

The fix here does not rely on microtask organization, which I think would be fragile. Instead, we don't listen to the `dataDone` future
until we've logged the start of the response.

Change-Id: Ib735742b297a261e6566ae8caf9eac0d71fc8fdb
Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/415140
Reviewed-by: Ben Konyi <[email protected]>
Commit-Queue: Samuel Rawlins <[email protected]>

Author: srawlins

pkg/vm_service/test/get_http_profile_test.dart

@@ -248,8 +248,8 @@ Future<void> hasValidHttpRequests(HttpProfile profile, String method) async {
           } else {
             // write() was used.
             expect(
-              utf8.decode(fullRequest.requestBody!).startsWith('$method http'),
-              true,
+              utf8.decode(fullRequest.requestBody!),
+              startsWith('$method http'),
             );
           }
         }
@@ -258,9 +258,15 @@ Future<void> hasValidHttpRequests(HttpProfile profile, String method) async {
           final responseData = r.response!;
           expect(responseData.statusCode, greaterThanOrEqualTo(100));
           expect(responseData.endTime, isNotNull);
-          expect(responseData.startTime!.isAfter(r.endTime!), true);
-          expect(responseData.startTime!.isBefore(responseData.endTime!), true);
-          expect(utf8.decode(fullRequest.responseBody!), method);
+          expect(responseData.startTime!, _isAfterOrSameAs(r.endTime!));
+          expect(
+            responseData.startTime!,
+            _isBeforeOrSameAs(responseData.endTime!),
+          );
+          if (method != 'HEAD') {
+            // The HEAD response has no body.
+            expect(utf8.decode(fullRequest.responseBody!), method);
+          }
           responseData.headers;
           responseData.compressionState;
           responseData.connectionInfo;
@@ -279,7 +285,7 @@ Future<void> hasValidHttpRequests(HttpProfile profile, String method) async {
 }
 
 void hasValidHttpProfile(HttpProfile profile, String method) {
-  expect(profile.requests.where((e) => e.method == method).length, 10);
+  expect(profile.requests.where((e) => e.method == method), hasLength(10));
 }
 
 Future<void> hasValidHttpCONNECTs(HttpProfile profile) =>
@@ -329,7 +335,7 @@ final tests = <IsolateTest>[
     final isolateId = isolateRef.id!;
 
     final httpProfile = await service.getHttpProfile(isolateId);
-    expect(httpProfile.requests.length, 70);
+    expect(httpProfile.requests, hasLength(70));
 
     // Verify timeline events.
     await hasValidHttpCONNECTs(httpProfile);
@@ -350,3 +356,56 @@ void main([args = const <String>[]]) => runIsolateTests(
       'get_http_profile_test.dart',
       testeeBefore: testMain,
     );
+
+class _DateTimeMatcher extends Matcher {
+  const _DateTimeMatcher(this._expected, this._condition);
+
+  final DateTime _expected;
+
+  final _DateTimeCondition _condition;
+
+  @override
+  Description describe(Description description) {
+    return description.add('DateTime ${_condition.name} $_expected');
+  }
+
+  @override
+  Description describeMismatch(
+    Object? item,
+    Description mismatchDescription,
+    Map matchState,
+    bool verbose,
+  ) {
+    if (item is! DateTime) return mismatchDescription;
+    final difference = _condition == _DateTimeCondition.before
+        ? item.difference(_expected)
+        : _expected.difference(item);
+    final actualRelation =
+        _condition == _DateTimeCondition.before ? 'after' : 'before';
+    return mismatchDescription
+        .add('is ${difference.inMicroseconds} microseconds $actualRelation');
+  }
+
+  @override
+  bool matches(Object? item, Map matchState) {
+    if (item is! DateTime) {
+      return false;
+    }
+    return switch (_condition) {
+      _DateTimeCondition.before =>
+        item.isBefore(_expected) || item.isAtSameMomentAs(_expected),
+      _DateTimeCondition.after =>
+        item.isAfter(_expected) || item.isAtSameMomentAs(_expected),
+    };
+  }
+}
+
+enum _DateTimeCondition {
+  before,
+  after;
+}
+
+_DateTimeMatcher _isBeforeOrSameAs(DateTime item) =>
+    _DateTimeMatcher(item, _DateTimeCondition.before);
+_DateTimeMatcher _isAfterOrSameAs(DateTime item) =>
+    _DateTimeMatcher(item, _DateTimeCondition.after);

sdk/lib/_http/http_impl.dart

@@ -69,6 +69,7 @@ class _HttpProfileData {
     _updated();
   }
 
+  /// Adds an HTTP request event to the timeline and the list of events.
   void requestEvent(String name, {Map? arguments}) {
     _timeline.instant(name, arguments: arguments);
     requestEvents.add(_HttpProfileEvent(name, arguments));
@@ -131,6 +132,7 @@ class _HttpProfileData {
     _updated();
   }
 
+  /// Marks the response as "started."
   void startResponse({required HttpClientResponse response}) {
     responseDetails = <String, dynamic>{
       'headers': formatHeaders(response.headers),
@@ -175,6 +177,7 @@ class _HttpProfileData {
     _updated();
   }
 
+  /// Marks the response as "finished."
   void finishResponse() {
     // Guard against the response being completed more than once or being
     // completed before the response actually finished starting.
@@ -186,9 +189,10 @@ class _HttpProfileData {
     _updated();
   }
 
+  /// Marks the response as "finished" with an error.
   void finishResponseWithError(String error) {
-    // Return if finishResponseWithError has already been called. Can happen if
-    // the response stream is listened to with `cancelOnError: false`.
+    // Return if `finishResponseWithError` has already been called. Can happen
+    // if the response stream is listened to with `cancelOnError: false`.
     if (!responseInProgress!) return;
     responseInProgress = false;
     responseEndTimestamp = DateTime.now().microsecondsSinceEpoch;
@@ -239,6 +243,13 @@ class _HttpProfileData {
   static final String isolateId = Service.getIsolateId(Isolate.current)!;
 
   bool requestInProgress = true;
+
+  /// Whether the response-processing has started, and has not yet finished.
+  ///
+  /// This field has three meaningful states:
+  /// * `null`: processing the response has not started.
+  /// * `true`: processing the response has started.
+  /// * `false`: processing the response has finished.
   bool? responseInProgress;
 
   late final String id;
@@ -609,9 +620,6 @@ class _HttpClientResponse extends _HttpInboundMessageListInt
       super(_incoming) {
     // Set uri for potential exceptions.
     _incoming.uri = _httpRequest.uri;
-    // Ensure the response profile is completed, even if the response stream is
-    // never actually listened to.
-    _incoming.dataDone.then((_) => _profileData?.finishResponse());
   }
 
   static HttpClientResponseCompressionState _getCompressionState(
@@ -1482,6 +1490,8 @@ class _HttpClientRequest extends _HttpOutboundMessage<HttpClientResponse>
   final _HttpClient _httpClient;
   final _HttpClientConnection _httpClientConnection;
 
+  /// A [Completer] that completes when the response has been fully received,
+  /// including any redirects and authentications.
   final Completer<HttpClientResponse> _responseCompleter =
       Completer<HttpClientResponse>();
 
@@ -1522,6 +1532,11 @@ class _HttpClientRequest extends _HttpOutboundMessage<HttpClientResponse>
         // 'certificate': response.certificate,
         response: response,
       );
+      (response as _HttpClientResponse)._incoming.dataDone.then(
+        // Ensure the response profile is finished, even if the response stream
+        // is never listened to.
+        (_) => _profileData?.finishResponse(),
+      );
     }, onError: (e) {});
   }
 
@@ -1554,7 +1569,10 @@ class _HttpClientRequest extends _HttpOutboundMessage<HttpClientResponse>
   HttpConnectionInfo? get connectionInfo =>
       _httpClientConnection.connectionInfo;
 
-  void _onIncoming(_HttpIncoming incoming) {
+  /// Handles [incoming] by possibly following redirects, possibly
+  /// authenticating, and completing [_responseCompleter] when the response is
+  /// complete.
+  void _handleIncoming(_HttpIncoming incoming) {
     if (_aborted) {
       return;
     }
@@ -2396,7 +2414,7 @@ class _HttpClientConnection {
                 if (nextnonce != null) creds.nonce = nextnonce;
               }
             }
-            request._onIncoming(incoming);
+            request._handleIncoming(incoming);
           })
           // If we see a state error, we failed to get the 'first'
           // element.