search

litespeedtech / lsquic

LiteSpeed QUIC and HTTP/3 Library
MIT License
1.49k stars 324 forks source link

Issue with streams throughput fairness #467

Open mickael-cerisier opened 1 year ago

mickael-cerisier commented 1 year ago

Hi,

I work on a new network layer for our products based on lsquic and libuv. In our product each thread use its own quic stream, so there is one connection with N quic stream. I only use the quic layer, I don't use HTTP3. My problem is pretty simple, if I write lot of data on multiple streams, only one stream has access to the throughput, the others wait that it finished. All streams have the same priority.

I analyse the source code of lsquic but I don't know how to fix.

lsquic_stream.c:2442 there is a code that puts the stream at the end of the list, this part works.

if (stream->sm_qflags & SMQF_WRITE_Q_FLAGS)
{
    if (progress)
    {   /* Move the stream to the end of the list to ensure fairness. */
        TAILQ_REMOVE(&stream->conn_pub->write_streams, stream,
                                                        next_write_stream);
        TAILQ_INSERT_TAIL(&stream->conn_pub->write_streams, stream,
                                                        next_write_stream);
    }
}

lsquic_hpi.c:313 inside calc_next_prio_and_incr my hpi_set[0] is always equal to [4,0] with stream priority set to 255 Values are always same, prio=2 and incr=0 so I go inside next_nonincr.

struct lsquic_stream *
lsquic_hpi_next (void *iter_p)
{
    struct http_prio_iter *const iter = iter_p;
    struct lsquic_stream *stream;
    unsigned prio, incr;

    calc_next_prio_and_incr(iter, prio, incr);

    if (prio >= N_HPI_PRIORITIES)
        return NULL;

    if (incr)
        stream = next_incr(iter, prio);
    else
        stream = next_nonincr(iter, prio);

    if (LSQ_LOG_ENABLED(LSQ_LOG_DEBUG))
        HPI_DEBUG("%s: return stream %"PRIu64", incr: %u, priority %u",
                                            __func__, stream->id, incr, prio);
    return stream;
}

lsquic_hpi.c:275 Inside next_nonincr, I go

  1. else if (iter->hpi_counts[prio] > 1) line 289
  2. if (0 == heap_nonincr_bucket(iter, prio))
  3. goto pop_stream
  4. stream = lsquic_mh_pop(&iter->hpi_min_heap);

At the end, lsquic use the method heapify_min_heap that ignore the list order, but search for the smallest stream id.

my call stack:

heapify_min_heap(min_heap * heap, unsigned int i) at lsquic_min_heap.c(15)
lsquic_mh_pop(min_heap * heap) at lsquic_min_heap.c(86)
next_nonincr(http_prio_iter * iter, unsigned int prio) at lsquic_hpi.c(282)
lsquic_hpi_next(void * iter_p) at lsquic_hpi.c(327)
lsquic_hpi_first(void * iter_p) at lsquic_hpi.c(184)
process_streams_write_events(ietf_full_conn * conn, int high_prio) at lsquic_full_conn_ietf.c(4461)
ietf_full_conn_ci_tick(lsquic_conn * lconn, unsigned __int64 now) at lsquic_full_conn_ietf.c(8529)
process_connections(lsquic_engine * engine, lsquic_conn *(*)(lsquic_engine *) next_conn, unsigned __int64 now) at lsquic_engine.c(3055)
lsquic_engine_process_conns(lsquic_engine * engine) at lsquic_engine.c(2242)

I tested changing the priority of the stream to 4, 5 before realizing that the order is reversed when it's not an HTTP connection, so I tried with 254 and 255, but it didn't change anything.

I don't know if I use wrong the library or if it's a bug. Of course i'm available for more precision.

Otherwise it's a great library, thanks to you. Thanks in advance for the help.

dtikhonov commented 1 year ago

If all the streams are the same priority, they should be sending in round-robin fashion: each "tick," the next stream is picked.

If that does not happen, it's likely a bug.

mickael-cerisier commented 1 year ago

I agree with you, that why I think it's a bug.

mickael-cerisier commented 1 year ago 
6608 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] engine: decref conn 48E9E66CABAF7428, 'HTA' -> 'HA' (task=29772)
6609 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] engine: decref conn 48E9E66CABAF7428, 'HA' -> 'H' (task=29772)
6610 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] conn: Processing ACK (task=29772)
6611 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] sendctl: Got ACK frame, largest acked: 3499; delta: 24 (task=29772)
6612 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] sendctl: ACK comes after a period of quiescence (task=29772)
6613 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] bbr: was quiet (task=29772)
6614 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] sendctl: Smallest unacked: 3496 (task=29772)
6615 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] stream: ACKed; n_unacked: 3 (task=29772)
6616 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] sendctl: acking via regular record #3496 (task=29772)
6617 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] bw-sampler: send rate: 18446744073709551615; ack rate: 27514018 (task=29772)
6618 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] bw-sampler: packet 3496 acked, bandwidth: 27514018 bps (task=29772)
6619 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] stream: ACKed; n_unacked: 2 (task=29772)
6620 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] sendctl: acking via regular record #3497 (task=29772)
6621 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] bw-sampler: send rate: 18446744073709551615; ack rate: 55028037 (task=29772)
6622 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] bw-sampler: packet 3497 acked, bandwidth: 55028037 bps (task=29772)
6623 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] stream: ACKed; n_unacked: 1 (task=29772)
6624 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: acking via regular record #3498 (task=29772)
6625 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bw-sampler: send rate: 18446744073709551615; ack rate: 82542056 (task=29772)
6626 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bw-sampler: packet 3498 acked, bandwidth: 82542056 bps (task=29772)
6627 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] stream: ACKed; n_unacked: 0 (task=29772)
6628 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: acking via regular record #3499 (task=29772)
6629 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bw-sampler: send rate: 18446744073709551615; ack rate: 110056074 (task=29772)
6630 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bw-sampler: packet 3499 acked, bandwidth: 110056074 bps (task=29772)
6631 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: packno 3499; rtt: 428; delta: 24; new srtt: 394 (task=29772)
6632 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: clear sc_n_consec_rtos, sc_n_hsk, sc_ntlp (task=29772)
6633 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: No retransmittable packets: clear alarm (task=29772)
6634 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bbr: end_ack; mode: PROBE_BW; in_flight: 0 (task=29772)
6635 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bbr: up round count to 842; new rt end: 3499 (task=29772)
6636 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bbr: advanced gain cycle, pacing gain set to 1.00 (task=29772)
6637 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bbr: BW estimate: 112959232 (task=29772)
6638 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 0 (task=29772)
6639 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 4 (task=29772)
6640 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 12 (task=29772)
6641 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 16 (task=29772)
6642 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 20 (task=29772)
6643 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 24 (task=29772)
6644 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 28 (task=29772)
6645 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 32 (task=29772)
6646 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 36 (task=29772)
6647 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 40 (task=29772)
6648 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 44 (task=29772)
6649 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 48 (task=29772)
6650 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 52 (task=29772)
6651 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 56 (task=29772)
6652 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 60 (task=29772)
6653 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 64 (task=29772)
6654 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 68 (task=29772)
6655 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 72 (task=29772)
6656 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 76 (task=29772)
6657 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: initialized; # elems: 19; sets: [ 00000100, 00000000 ] (task=29772)
6658 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 0, incr: 0, priority 8 (task=29772)
6659 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 4, incr: 0, priority 8 (task=29772)
6660 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 12, incr: 0, priority 8 (task=29772)
6661 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 16, incr: 0, priority 8 (task=29772)
6662 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 20, incr: 0, priority 8 (task=29772)
6663 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 24, incr: 0, priority 8 (task=29772)
6664 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 28, incr: 0, priority 8 (task=29772)
6665 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 32, incr: 0, priority 8 (task=29772)
6666 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 36, incr: 0, priority 8 (task=29772)
6667 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 40, incr: 0, priority 8 (task=29772)
6668 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 44, incr: 0, priority 8 (task=29772)
6669 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 48, incr: 0, priority 8 (task=29772)
6670 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 52, incr: 0, priority 8 (task=29772)
6671 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 56, incr: 0, priority 8 (task=29772)
6672 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 60, incr: 0, priority 8 (task=29772)
6673 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 64, incr: 0, priority 8 (task=29772)
6674 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 68, incr: 0, priority 8 (task=29772)
6675 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 72, incr: 0, priority 8 (task=29772)
6676 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 76, incr: 0, priority 8 (task=29772)
6677 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 0 (unacked_all: 0); cwnd: 5840; ccfc: 3936747/4726971 (task=29772)
6678 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: APP pns ACK queued opportunistically (task=29772)
6679 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: created packet #3500 (task=29772)
6680 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: created packet #3500 SHORT; flags: version=0, nonce=0, conn_id=1 (task=29772)
6681 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: ACK bytes: 028000853F050000 (task=29772)
6682 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: generated ACK frame: [34111-34111] (task=29772)
6683 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: Put 8 bytes of ACK frame into packet 3500 on outgoing queue (task=29772)
6684 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: APP pns ACK state reset (task=29772)
6685 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 48 (task=29772)
6686 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 32 (task=29772)
6687 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 28 (task=29772)
6688 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 68 (task=29772)
6689 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 36 (task=29772)
6690 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 44 (task=29772)
6691 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 40 (task=29772)
6692 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 52 (task=29772)
6693 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 56 (task=29772)
6694 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 72 (task=29772)
6695 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 64 (task=29772)
6696 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 60 (task=29772)
6697 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 76 (task=29772)
6698 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 24 (task=29772)
6699 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: initialized; # elems: 14; sets: [ 00000100, 00000000 ] (task=29772)
6700 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: lsquic_hpi_next: return stream 24, incr: 0, priority 8 (task=29772)
6701 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] stream: dispatch_write_events (task=29772)
6702 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] stream: increase cc_sent by 1431 to 3938178 (task=29772)
6703 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: generated STREAM frame: stream 24, offset: 3929395, size: 1431, fin: 0 (task=29772)
6704 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 1472 (unacked_all: 0); cwnd: 5840; ccfc: 3938178/4726971 (task=29772)
6705 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: created packet #3501 (task=29772)
6706 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: created packet #3501 SHORT; flags: version=0, nonce=0, conn_id=1 (task=29772)
6707 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] stream: increase cc_sent by 1440 to 3939618 (task=29772)
6708 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: generated STREAM frame: stream 24, offset: 3930826, size: 1440, fin: 0 (task=29772)
6709 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 2944 (unacked_all: 0); cwnd: 5840; ccfc: 3939618/4726971 (task=29772)
6710 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: created packet #3502 (task=29772)
6711 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: created packet #3502 SHORT; flags: version=0, nonce=0, conn_id=1 (task=29772)
6712 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] stream: increase cc_sent by 1440 to 3941058 (task=29772)
6713 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: generated STREAM frame: stream 24, offset: 3932266, size: 1440, fin: 0 (task=29772)
6714 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 4416 (unacked_all: 0); cwnd: 5840; ccfc: 3941058/4726971 (task=29772)
6715 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: created packet #3503 (task=29772)
6716 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: created packet #3503 SHORT; flags: version=0, nonce=0, conn_id=1 (task=29772)
6717 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] stream: increase cc_sent by 1440 to 3942498 (task=29772)
6718 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: generated STREAM frame: stream 24, offset: 3933706, size: 1440, fin: 0 (task=29772)
6719 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 5888 (unacked_all: 0); cwnd: 5840; ccfc: 3942498/4726971 (task=29772)
6720 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] LSQuicStream partial onwrite: 5751 (stream_id=48E9E66CABAF7428-24, peerAddr=192.168.56.1, peerPort=19813, task=29772)
6721 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: lsquic_hpi_next: return stream 28, incr: 0, priority 8 (task=29772)
6722 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 5888 (unacked_all: 0); cwnd: 5840; ccfc: 3942498/4726971 (task=29772)
6723 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 5888 (unacked_all: 0); cwnd: 5840; ccfc: 3942498/4726971 (task=29772)
6724 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: incref conn 48E9E66CABAF7428, 'H' -> 'HO' (task=29772)
6725 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: incref conn 48E9E66CABAF7428, 'HO' -> 'HOK' (task=29772)
6726 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: batched packet #3500 for connection 48E9E66CABAF7428 (task=29772)
6727 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: batched packet #3501 for connection 48E9E66CABAF7428 (task=29772)
6728 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: batched packet #3502 for connection 48E9E66CABAF7428 (task=29772)
6729 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: batched packet #3503 for connection 48E9E66CABAF7428 (task=29772)
6730 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: no more scheduled packets (task=29772)
6731 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: batched all outgoing packets for full conn 48E9E66CABAF7428 (task=29772)
6732 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] handshake: flush header protection application, count: 4 (task=29772)
6733 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] handshake: apply header protection using mask 669690FA03 (task=29772)
6734 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] handshake: apply header protection using mask 97F29D0C20 (task=29772)
6735 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] handshake: apply header protection using mask 3DF2A1F592 (task=29772)
6736 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] handshake: apply header protection using mask 4ECAD4F0CD (task=29772)
6737 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] LSQuicClient send_packets_one_by_one count=4 (task=29772)
6738 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: packets out returned 4 (out of 4) (task=29772)
6739 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: TX packet #3500 SHORT (STREAM ACK), size 1472, ecn: 0, spin: 1; kp: 0, path: 0, flags: 1082171960; Q: 0; L: 0 (task=29772)
6740 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: sent packet #3500 (STREAM ACK) (task=29772)
6741 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bw-sampler: add info for packet 3500 (task=29772)
6742 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: set RETX_APP pns alarm to 255625490446 (25591), mode RETX_MODE_TLP (task=29772)
6743 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: TX packet #3501 SHORT (STREAM), size 1472, ecn: 0, spin: 1; kp: 0, path: 0, flags: 1082171912; Q: 0; L: 0 (task=29772)
6744 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: sent packet #3501 (STREAM) (task=29772)
6745 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bw-sampler: add info for packet 3501 (task=29772)
6746 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: TX packet #3502 SHORT (STREAM), size 1472, ecn: 0, spin: 1; kp: 0, path: 0, flags: 1082171912; Q: 0; L: 0 (task=29772)
6747 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: sent packet #3502 (STREAM) (task=29772)
6748 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bw-sampler: add info for packet 3502 (task=29772)
6749 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: TX packet #3503 SHORT (STREAM), size 1472, ecn: 0, spin: 1; kp: 0, path: 0, flags: 1082171912; Q: 0; L: 0 (task=29772)
6750 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: sent packet #3503 (STREAM) (task=29772)
6751 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bw-sampler: add info for packet 3503 (task=29772)
6752 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: decref conn 48E9E66CABAF7428, 'HOK' -> 'HK' (task=29772)
6753 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: send_packets_out: sent 4 packets (task=29772)
6754 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: decref conn 48E9E66CABAF7428, 'HK' -> 'H' (task=29772)
6755 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: tickable: stream 48 can be written to (task=29772)
6756 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 5888 (unacked_all: 5888); cwnd: 5840; ccfc: 3942498/4726971 (task=29772)
6757 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: not tickable (task=29772)
6758 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: incref conn 48E9E66CABAF7428, 'H' -> 'HA' (task=29772)
6759 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: incref conn 48E9E66CABAF7428, 'HA' -> 'HTA' (task=29772)
6760 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] handshake: strip header protection using mask DE7DDEC09B (task=29772)
6761 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] handshake: pre-decode packno: 34112 (task=29772)
6762 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: RX packet #34112 SHORT, size: 39; ecn: 0, spin: 1; path: 0; Q: 0; L: 0 (task=29772)
6763 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: about to process QUIC_FRAME_ACK frame (task=29772)
6764 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: RX ACK frame: [3503-3500] (task=29772)
6765 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: Saved ACK (task=29772)
6766 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: about to process QUIC_FRAME_MAX_DATA frame (task=29772)
6767 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: RX MAX_DATA frame; offset: 5515362 (task=29772)
6768 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: max data goes from 4726971 to 5515362 (task=29772)
6769 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] conn: about to process QUIC_FRAME_PING frame (task=29772)
6770 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: RX PING frame (task=29772)
6771 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] conn: received PING frame, update last progress to 0 (task=29772)
6772 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] conn: APP pns ACK alarm set to 255625466277 (task=29772)
6773 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] qlog: [255625465277,"TRANSPORT","PACKET_RX","LINE",{"raw":"6748e9e66cabaf7428f89ece24a841954b8b40ae68f2c7d8dfc3f3a2118456","header":{"type":"SHORT","payload_length":"23","packet_number":"34112"},"frames":[{"frame_type":"ACK"},{"frame_type":"PING"},{"frame_type":"MAX_DATA"}]}] (task=29772)
6774 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] LSQuicEngine OnUvRead size:39 flags:0 (peerAddr=192.168.56.1, peerPort=19813, task=29772)
6775 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: decref conn 48E9E66CABAF7428, 'HTA' -> 'HA' (task=29772)
6776 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: decref conn 48E9E66CABAF7428, 'HA' -> 'H' (task=29772)
6777 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] conn: Processing ACK (task=29772)
6778 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: Got ACK frame, largest acked: 3503; delta: 24 (task=29772)
6779 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: ACK comes after a period of quiescence (task=29772)
6780 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bbr: was quiet (task=29772)
6781 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: Smallest unacked: 3500 (task=29772)
6782 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] stream: ACKed; n_unacked: 3 (task=29772)
6783 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: acking via regular record #3500 (task=29772)
6784 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: send rate: 18446744073709551615; ack rate: 27905213 (task=29772)
6785 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: packet 3500 acked, bandwidth: 27905213 bps (task=29772)
6786 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] stream: ACKed; n_unacked: 2 (task=29772)
6787 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: acking via regular record #3501 (task=29772)
6788 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: send rate: 18446744073709551615; ack rate: 55810426 (task=29772)
6789 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: packet 3501 acked, bandwidth: 55810426 bps (task=29772)
6790 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] stream: ACKed; n_unacked: 1 (task=29772)
6791 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: acking via regular record #3502 (task=29772)
6792 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: send rate: 18446744073709551615; ack rate: 83715639 (task=29772)
6793 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: packet 3502 acked, bandwidth: 83715639 bps (task=29772)
6794 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] stream: ACKed; n_unacked: 0 (task=29772)
6795 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: acking via regular record #3503 (task=29772)
6796 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: send rate: 18446744073709551615; ack rate: 111620853 (task=29772)
6797 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: packet 3503 acked, bandwidth: 111620853 bps (task=29772)
6798 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: packno 3503; rtt: 422; delta: 24; new srtt: 394 (task=29772)
6799 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: clear sc_n_consec_rtos, sc_n_hsk, sc_ntlp (task=29772)
6800 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: No retransmittable packets: clear alarm (task=29772)
6801 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bbr: end_ack; mode: PROBE_BW; in_flight: 0 (task=29772)
6802 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bbr: up round count to 843; new rt end: 3503 (task=29772)
6803 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bbr: advanced gain cycle, pacing gain set to 1.00 (task=29772)
6804 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bbr: BW estimate: 112959232 (task=29772)
6805 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 0 (task=29772)
6806 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 4 (task=29772)
6807 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 12 (task=29772)
6808 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 16 (task=29772)
6809 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 20 (task=29772)
6810 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 24 (task=29772)
6811 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 28 (task=29772)
6812 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 32 (task=29772)
6813 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 36 (task=29772)
6814 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 40 (task=29772)
6815 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 44 (task=29772)
6816 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 48 (task=29772)
6817 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 52 (task=29772)
6818 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 56 (task=29772)
6819 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 60 (task=29772)
6820 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 64 (task=29772)
6821 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 68 (task=29772)
6822 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 72 (task=29772)
6823 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 76 (task=29772)
6824 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: initialized; # elems: 19; sets: [ 00000100, 00000000 ] (task=29772)
6825 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 0, incr: 0, priority 8 (task=29772)
6826 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 4, incr: 0, priority 8 (task=29772)
6827 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 12, incr: 0, priority 8 (task=29772)
6828 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 16, incr: 0, priority 8 (task=29772)
6829 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 20, incr: 0, priority 8 (task=29772)
6830 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 24, incr: 0, priority 8 (task=29772)
6831 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 28, incr: 0, priority 8 (task=29772)
6832 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 32, incr: 0, priority 8 (task=29772)
6833 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 36, incr: 0, priority 8 (task=29772)
6834 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 40, incr: 0, priority 8 (task=29772)
6835 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 44, incr: 0, priority 8 (task=29772)
6836 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 48, incr: 0, priority 8 (task=29772)
6837 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 52, incr: 0, priority 8 (task=29772)
6838 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 56, incr: 0, priority 8 (task=29772)
6839 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 60, incr: 0, priority 8 (task=29772)
6840 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 64, incr: 0, priority 8 (task=29772)
6841 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 68, incr: 0, priority 8 (task=29772)
6842 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 72, incr: 0, priority 8 (task=29772)
6843 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 76, incr: 0, priority 8 (task=29772)
6844 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 0 (unacked_all: 0); cwnd: 5840; ccfc: 3942498/5515362 (task=29772)
6845 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] conn: APP pns ACK queued opportunistically (task=29772)
6846 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: created packet #3504 (task=29772)
6847 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: created packet #3504 SHORT; flags: version=0, nonce=0, conn_id=1 (task=29772)
6848 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] conn: ACK bytes: 0280008540060000 (task=29772)
6849 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: generated ACK frame: [34112-34112] (task=29772)
6850 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] conn: Put 8 bytes of ACK frame into packet 3504 on outgoing queue (task=29772)
6851 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] conn: APP pns ACK state reset (task=29772)
6852 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 48 (task=29772)
6853 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 32 (task=29772)
6854 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 28 (task=29772)
6855 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 68 (task=29772)
6856 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 36 (task=29772)
6857 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 44 (task=29772)
6858 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 40 (task=29772)
6859 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 52 (task=29772)
6860 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 56 (task=29772)
6861 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 72 (task=29772)
6862 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 64 (task=29772)
6863 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 60 (task=29772)
6864 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 76 (task=29772)
6865 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 24 (task=29772)
6866 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: initialized; # elems: 14; sets: [ 00000100, 00000000 ] (task=29772)
6867 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: lsquic_hpi_next: return stream 24, incr: 0, priority 8 (task=29772)
6868 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] stream: dispatch_write_events (task=29772)
6869 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] stream: increase cc_sent by 1431 to 3943929 (task=29772)
6870 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: generated STREAM frame: stream 24, offset: 3935146, size: 1431, fin: 0 (task=29772)
6871 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 1472 (unacked_all: 0); cwnd: 5840; ccfc: 3943929/5515362 (task=29772)
6872 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: created packet #3505 (task=29772)
6873 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: created packet #3505 SHORT; flags: version=0, nonce=0, conn_id=1 (task=29772)
6874 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] stream: increase cc_sent by 1440 to 3945369 (task=29772)
6875 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: generated STREAM frame: stream 24, offset: 3936577, size: 1440, fin: 0 (task=29772)
6876 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 2944 (unacked_all: 0); cwnd: 5840; ccfc: 3945369/5515362 (task=29772)
6877 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: created packet #3506 (task=29772)
6878 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: created packet #3506 SHORT; flags: version=0, nonce=0, conn_id=1 (task=29772)
6879 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] stream: increase cc_sent by 1440 to 3946809 (task=29772)
6880 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: generated STREAM frame: stream 24, offset: 3938017, size: 1440, fin: 0 (task=29772)
6881 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 4416 (unacked_all: 0); cwnd: 5840; ccfc: 3946809/5515362 (task=29772)
6882 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: created packet #3507 (task=29772)
6883 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: created packet #3507 SHORT; flags: version=0, nonce=0, conn_id=1 (task=29772)
6884 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] stream: increase cc_sent by 1440 to 3948249 (task=29772)
6885 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: generated STREAM frame: stream 24, offset: 3939457, size: 1440, fin: 0 (task=29772)
6886 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 5888 (unacked_all: 0); cwnd: 5840; ccfc: 3948249/5515362 (task=29772)
6887 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] LSQuicStream partial onwrite: 5751 (stream_id=48E9E66CABAF7428-24, peerAddr=192.168.56.1, peerPort=19813, task=29772)
6888 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: lsquic_hpi_next: return stream 28, incr: 0, priority 8 (task=29772)
6889 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 5888 (unacked_all: 0); cwnd: 5840; ccfc: 3948249/5515362 (task=29772)
6890 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 5888 (unacked_all: 0); cwnd: 5840; ccfc: 3948249/5515362 (task=29772)
6891 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: incref conn 48E9E66CABAF7428, 'H' -> 'HO' (task=29772)
6892 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: incref conn 48E9E66CABAF7428, 'HO' -> 'HOK' (task=29772)
6893 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: batched packet #3504 for connection 48E9E66CABAF7428 (task=29772)
6894 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: batched packet #3505 for connection 48E9E66CABAF7428 (task=29772)
6895 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: batched packet #3506 for connection 48E9E66CABAF7428 (task=29772)
6896 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: batched packet #3507 for connection 48E9E66CABAF7428 (task=29772)
6897 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: no more scheduled packets (task=29772)
6898 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: batched all outgoing packets for full conn 48E9E66CABAF7428 (task=29772)
6899 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] handshake: flush header protection application, count: 4 (task=29772)
6900 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] handshake: apply header protection using mask FA5262CBFF (task=29772)
6901 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] handshake: apply header protection using mask D585B9EA39 (task=29772)
6902 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] handshake: apply header protection using mask A7E20999DD (task=29772)
6903 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] handshake: apply header protection using mask 5F1F111347 (task=29772)
6904 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] LSQuicClient send_packets_one_by_one count=4 (task=29772)
6905 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: packets out returned 4 (out of 4) (task=29772)
6906 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: TX packet #3504 SHORT (STREAM ACK), size 1472, ecn: 0, spin: 0; kp: 0, path: 0, flags: 8430136; Q: 0; L: 0 (task=29772)
6907 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: sent packet #3504 (STREAM ACK) (task=29772)
6908 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: add info for packet 3504 (task=29772)
6909 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: set RETX_APP pns alarm to 255625491188 (25591), mode RETX_MODE_TLP (task=29772)
6910 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: TX packet #3505 SHORT (STREAM), size 1472, ecn: 0, spin: 0; kp: 0, path: 0, flags: 8430088; Q: 0; L: 0 (task=29772)
6911 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: sent packet #3505 (STREAM) (task=29772)
6912 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: add info for packet 3505 (task=29772)
6913 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: TX packet #3506 SHORT (STREAM), size 1472, ecn: 0, spin: 0; kp: 0, path: 0, flags: 8430088; Q: 0; L: 0 (task=29772)
6914 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: sent packet #3506 (STREAM) (task=29772)
6915 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: add info for packet 3506 (task=29772)
6916 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: TX packet #3507 SHORT (STREAM), size 1472, ecn: 0, spin: 0; kp: 0, path: 0, flags: 8430088; Q: 0; L: 0 (task=29772)
6917 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] sendctl: sent packet #3507 (STREAM) (task=29772)
6918 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] bw-sampler: add info for packet 3507 (task=29772)
6919 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] engine: decref conn 48E9E66CABAF7428, 'HOK' -> 'HK' (task=29772)
6920 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] engine: send_packets_out: sent 4 packets (task=29772)
6921 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] engine: decref conn 48E9E66CABAF7428, 'HK' -> 'H' (task=29772)
6922 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] conn: tickable: stream 48 can be written to (task=29772)
6923 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 5888 (unacked_all: 5888); cwnd: 5840; ccfc: 3948249/5515362 (task=29772)
6924 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] conn: not tickable (task=29772)
6925 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] engine: incref conn 48E9E66CABAF7428, 'H' -> 'HA' (task=29772)
6926 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] engine: incref conn 48E9E66CABAF7428, 'HA' -> 'HTA' (task=29772)
6927 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] handshake: strip header protection using mask 5E8663F041 (task=29772)
6928 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] handshake: pre-decode packno: 34113 (task=29772)
6929 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] event: RX packet #34113 SHORT, size: 33; ecn: 0, spin: 0; path: 0; Q: 0; L: 0 (task=29772)
6930 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] conn: about to process QUIC_FRAME_ACK frame (task=29772)
6931 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] event: RX ACK frame: [3507-3504] (task=29772)
6932 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] conn: Saved ACK (task=29772)
6933 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] qlog: [255625466021,"TRANSPORT","PACKET_RX","LINE",{"raw":"4748e9e66cabaf74280322b68fe81d593325144d18a2f4932d78e48fe133d0","header":{"type":"SHORT","payload_length":"17","packet_number":"34113"},"frames":[{"frame_type":"ACK"}]}] (task=29772)

This is a typical log of my problem, there are many streams that need to write, but only stream 24 writes successfully.

Koukan commented 11 months ago

Nobody can help me ?