Uploaded image for project: 'Qt'
  1. Qt
  2. QTBUG-138156

tst_QHttpServer::disconnectedInEventLoop leaves a bad state making multipleRequests fail

    XMLWordPrintable

Details

    • Bug
    • Resolution: Unresolved
    • P2: Important
    • None
    • 6.10
    • Network: HTTP
    • None
    • Windows

    Description

       

      This seems like a regression since I didn't observe this behavior before.

       

      It happens only on Windows and for some reason not in CI. To reproduce the failing test you can execute it with

      tst_QHttpServer disconnectedInEventLoop multipleRequests

      With the added logging rules (QT_LOGGING_RULES=qt.network.http2.connection=true) you will get the following output:

       

      ********* Start testing of tst_QHttpServer *********
Config: Using QtTest library 6.10.0, Qt 6.10.0 (x86_64-little_endian-llp64 shared (dynamic) debug build; by MSVC 2022), windows 11
PASS   : tst_QHttpServer::initTestCase()
PASS   : tst_QHttpServer::disconnectedInEventLoop(http/1.1)
PASS   : tst_QHttpServer::disconnectedInEventLoop(https/1.1)
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d36020] Sending SETTINGS frame, 12 bytes
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d36020] Sending WINDOW_UPDATE frame, stream 0, delta 2147418112
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d36020] new stream 1
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d36020] stream 1, state changed from 0 to 2
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d36020] stream 1, sending HEADERS frame with 7 entries
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d36020] stream 1, state changed from 2 to 3
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Peer sent valid client preface
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Sending SETTINGS frame, 6 bytes
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Receiving data, 93 bytes available
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Successfully read a frame, with type: 4
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Received SETTINGS frame
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Received SETTINGS ENABLE_PUSH 0
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Received SETTINGS INITIAL_WINDOW_SIZE 214748364
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Adjusting initial window size for 0 streams by 214682829
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Sending SETTINGS ACK
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Successfully read a frame, with type: 8
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Received WINDOW_UPDATE, stream 0, delta 2147418112
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Successfully read a frame, with type: 1
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Received HEADERS frame on stream 1
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] new stream 1
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Created new incoming stream 1
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] HEADERS frame on stream 1 has PRIORITY flag
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] stream 1, state changed from 0 to 2
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] stream 1, state changed from 2 to 4
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Tried to read frame, got 2
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d36020] Receiving data, 24 bytes available
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d36020] Successfully read a frame, with type: 4
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d36020] Received SETTINGS frame
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d36020] Received SETTINGS ENABLE_PUSH 0
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d36020] Sending SETTINGS ACK
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d36020] Successfully read a frame, with type: 4
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d36020] Received SETTINGS ACK
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d36020] Tried to read frame, got 2
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Receiving data, 9 bytes available
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Successfully read a frame, with type: 4
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Received SETTINGS ACK
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] Tried to read frame, got 2
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] stream 1, sending HEADERS frame with 3 entries
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] starting sendDATA on stream 1, of device: 0x1eb01d9b340
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] starting sendDATA on stream 1, of device: 0x1eb01ed1da0
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] stream 1, about to write to socket, current session window size: 2147483647, stream window size: 214748364, bytes available: 0
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] stream 1, wrote 0 bytes total, if the device is not exhausted, we'll write more later. Remaining window size: 214748364
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] stream 1, exhausted device 0x1eb01ed1da0, sent END_STREAM? 0, sending end stream after DATA
QDEBUG : tst_QHttpServer::disconnectedInEventLoop(http/2) qt.network.http2.connection: [0x1eb01d40a90] stream 1, state changed from 4 to 5
PASS   : tst_QHttpServer::disconnectedInEventLoop(http/2)
QDEBUG : tst_QHttpServer::multipleRequests(http/1.1) qt.network.http2.connection: [0x1eb01d36020] Receiving data, 43 bytes available
QDEBUG : tst_QHttpServer::multipleRequests(http/1.1) qt.network.http2.connection: [0x1eb01d36020] Successfully read a frame, with type: 1
QDEBUG : tst_QHttpServer::multipleRequests(http/1.1) qt.network.http2.connection: [0x1eb01d36020] Received HEADERS frame on stream 1
QDEBUG : tst_QHttpServer::multipleRequests(http/1.1) qt.network.http2.connection: [0x1eb01d36020] Received HEADERS on non-existent stream 1
QCRITICAL: tst_QHttpServer::multipleRequests(http/1.1) qt.network.http2.connection: [0x1eb01d36020] Connection error: HEADERS on invalid stream (1)
QDEBUG : tst_QHttpServer::multipleRequests(http/1.1) qt.network.http2.connection: [0x1eb01d40a90] Receiving data, 17 bytes available
QDEBUG : tst_QHttpServer::multipleRequests(http/1.1) qt.network.http2.connection: [0x1eb01d40a90] Successfully read a frame, with type: 7
PASS   : tst_QHttpServer::multipleRequests(http/1.1)
PASS   : tst_QHttpServer::multipleRequests(https/1.1)
FAIL!  : tst_QHttpServer::multipleRequests(http/2) 'replyPtr->isFinished()' returned FALSE. ()
C:\Users\marauter\qt5\qthttpserver\tests\auto\qhttpserver\tst_qhttpserver.cpp(1282) : failure location
PASS   : tst_QHttpServer::cleanupTestCase()
Totals: 7 passed, 1 failed, 0 skipped, 0 blacklisted, 22640ms
********* Finished testing of tst_QHttpServer *********

      Some interesting events:

      [0x1eb01d36020] = client
      [0x1eb01d40a90] = server

      [0x1eb01d40a90] stream 1, exhausted device 0x1eb01ed1da0, sent END_STREAM? 0, sending end stream after DATA -> Stream 1 goes to half-closed mode

      [0x1eb01d40a90] stream 1, state changed from 4 to 5 -> Stream 1 goes from half-closed to closed. (That would indicate that both sides agree that this stream is closed and the stream Id is not to be reused).

      [0x1eb01d36020] Connection error: HEADERS on invalid stream (1) -> The client gets something on stream 1. My best guess is that this is the response that is delayed by 1000 ms:

      httpserver.route("/event-loop/", this, [] () {
        QEventLoop loop;
        QTimer::singleShot(1000, &loop, &QEventLoop::quit);
        loop.exec();
        return QHttpServerResponse::StatusCode::Ok;
    });

      Calling

      networkAccessManager.clearConnectionCache();

      at the end of tst_QHttpServer::disconnectedInEventLoop makes all tests pass.

       

      Attachments

        No reviews matched the request. Check your Options in the drop-down menu of this sections header.

        Activity

          People

            manordheim Mårten Nordheim
            matthias_rauter Matthias Rauter
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:

              Gerrit Reviews

                There are no open Gerrit changes