search

seanmonstar / reqwest

An easy and powerful Rust HTTP Client
https://docs.rs/reqwest
Apache License 2.0
9.93k stars 1.12k forks source link

client.send() hangs in specific case when web request to actix-web comes in #2151

Closed Darkrael closed 4 months ago

Darkrael commented 8 months ago

I've been using reqwest as a web client in an actix-web project as a client to request data from another server. Everything works as expected but one call just does not return and hangs the whole actix-web server if and only if there is another call request directly after.

Example

I've tried troubleshooting the issue but i have no idea why this specific flow of code causes it. I have other endpoints that can be requested 10 times in a seconds and also use the reqwest client concurrently and there is no issue there. For now i have switched to the blocking implementation (reqwest::blocking::Client) which is far from ideal because now debug build will always crash but at least the server won't freeze. I've also tried to put the blocking implementation in a actix_web::rt::Runtime::block_on call which will make the debug work again but has the same issue of freezing the server. It seems that this is an issue with the asynchronous implementation.

I've also used tokio-console which shows 2 tasks are infinitely active:

╭Warnings────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╮
│⚠ 4 tasks have lost their waker                                                                                                                                             │
╰────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╯
╭Tasks (24) ▶ Running (2) ⏸ Idle (20)────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╮
│   Warn  ID  State  Name  Total▿ Busy   Sched  Idle   Polls Target      Location                                             Fields                                         │
│           5 ⏸            13m36s    2µs    0ns 13m36s 1     tokio::task <cargo>/actix-rt-2.9.0/src/arbiter.rs:216:9          kind=local                                     │
│           6 ⏸            13m36s    3µs    2ms 13m36s 2     tokio::task <cargo>/actix-rt-2.9.0/src/system.rs:67:12           kind=local                                     │
│   ⚠ 1     7 ⏸            13m36s    7ms  699ms 13m36s 19    tokio::task src/main.rs:92:1                                     kind=block_on                                  │
│          11 ⏸            13m36s  234µs   74µs 13m36s 11    tokio::task <cargo>/hyper-0.14.28/src/common/exec.rs:49:21       kind=task                                      │
│   ⚠ 1    14 ⏸            13m36s  133ms 13m35s  291ms 1674  tokio::task <cargo>/actix-rt-2.9.0/src/arbiter.rs:143:24         kind=block_on                                  │
│          17 ⏸            13m36s   46ms   24ms 13m36s 1631  tokio::task <cargo>/actix-http-3.6.0/src/date.rs:57:22           kind=local                                     │
│          18 ⏸            13m36s   20ms   57ms 13m36s 1631  tokio::task <cargo>/actix-http-3.6.0/src/date.rs:57:22           kind=local                                     │
│          19 ⏸            13m36s  107µs  215µs 13m36s 2     tokio::task <cargo>/actix-server-2.3.0/src/worker.rs:461:25      kind=local                                     │
│          20 ▶            13m36s  7m04s  6m31s   14µs 840   tokio::task <cargo>/actix-rt-2.9.0/src/arbiter.rs:143:24         kind=block_on                                  │
│          23 ⏸            13m36s   18ms   10ms 13m36s 780   tokio::task <cargo>/actix-http-3.6.0/src/date.rs:57:22           kind=local                                     │
│          24 ⏸            13m36s   10ms   23ms 13m36s 780   tokio::task <cargo>/actix-http-3.6.0/src/date.rs:57:22           kind=local                                     │
│          25 ⏸            13m36s  101µs   46µs 13m36s 2     tokio::task <cargo>/actix-server-2.3.0/src/worker.rs:461:25      kind=local                                     │
│   ⚠ 1    26 ⏸            13m36s   63ms 13m35s  290ms 1620  tokio::task <cargo>/actix-rt-2.9.0/src/arbiter.rs:143:24         kind=block_on                                  │
│          29 ⏸            13m36s   37ms   17ms 13m36s 1629  tokio::task <cargo>/actix-http-3.6.0/src/date.rs:57:22           kind=local                                     │
│          30 ⏸            13m36s   20ms   44ms 13m36s 1629  tokio::task <cargo>/actix-http-3.6.0/src/date.rs:57:22           kind=local                                     │
│          31 ⏸            13m36s    1µs    0ns 13m36s 1     tokio::task <cargo>/actix-server-2.3.0/src/worker.rs:461:25      kind=local                                     │
│   ⚠ 1    32 ⏸            13m36s   62ms 13m35s  290ms 1611  tokio::task <cargo>/actix-rt-2.9.0/src/arbiter.rs:143:24         kind=block_on                                  │
│          35 ⏸            13m36s   35ms   16ms 13m36s 1625  tokio::task <cargo>/actix-http-3.6.0/src/date.rs:57:22           kind=local                                     │
│          36 ⏸            13m36s   22ms   42ms 13m36s 1625  tokio::task <cargo>/actix-http-3.6.0/src/date.rs:57:22           kind=local                                     │
│          37 ⏸            13m36s    3µs    0ns 13m36s 1     tokio::task <cargo>/actix-server-2.3.0/src/worker.rs:461:25      kind=local                                     │
│          45 ⏸             9m37s   11ms    1ms  9m37s 130   tokio::task <cargo>/actix-server-2.3.0/src/service.rs:74:17      kind=local                                     │
│>>        54 ▶             7m04s  7m04s   89µs  179ms 7     tokio::task <cargo>/actix-http-3.6.0/src/h2/dispatcher.rs:136:21 kind=local                                     │
│          56 ⏫            7m04s    1ms  7m04s   59ms 6     tokio::task <cargo>/hyper-0.14.28/src/common/exec.rs:49:21       kind=task                                      │
│          57 ⏫            7m04s  958µs  7m04s   22ms 2     tokio::task <cargo>/actix-http-3.6.0/src/h2/dispatcher.rs:136:21 kind=local

I'm not sure if this indicates that this is a problem with actix instead of reqwest.

Versions

actix-web: 4.4.1 (tested on newest 4.5.1 one as well) reqwest: 0.11.24 (newest)

I've tried to reproduce it with minimal amount of code but it always works there.

Below is some debug output, hope it helps:

Strace ### Single request (no problem) ``` [pid 415421] recvfrom(33, "\27\3\3\0g", 5, 0, NULL, NULL) = 5 <0.000014> [pid 415421] recvfrom(33, "\235\36\213\241\235\371\257\360\335\321\355\313\300$\371\36G1\370t\345: ~\360\36\370K\223\4w\324"..., 103, 0, NULL, NULL) = 103 <0.000030> [pid 415421] recvfrom(33, 0x7f7a342b9213, 5, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000046> strace: Process 415686 attached [pid 415421] socket(AF_INET, SOCK_STREAM|SOCK_CLOEXEC, IPPROTO_TCP) = 34 <0.000033> [pid 415421] connect(34, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("192.168.250.31")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.000074> [pid 415421] getsockopt(34, SOL_SOCKET, SO_ERROR, [0], [4]) = 0 <0.000031> [pid 415421] setsockopt(34, SOL_TCP, TCP_NODELAY, [0], 4) = 0 <0.000027> [pid 415421] sendto(34, "\26\3\1\2\0\1\0\1\374\3\3\205\326*\22\25,M\364\370G\23`p\r\257\276C\324\336\222\334"..., 517, MSG_NOSIGNAL, NULL, 0) = 517 <0.000024> [pid 415421] recvfrom(34, "\26\3\3\0z", 5, 0, NULL, NULL) = 5 <0.000017> [pid 415421] recvfrom(34, "\2\0\0v\3\3k>\216]|:k\221\213\314\263\361)\3759\331o=]j\305\245\21\17L\322"..., 122, 0, NULL, NULL) = 122 <0.000032> [pid 415421] recvfrom(34, "\24\3\3\0\1", 5, 0, NULL, NULL) = 5 <0.000025> [pid 415421] recvfrom(34, "\1", 1, 0, NULL, NULL) = 1 <0.000028> [pid 415421] recvfrom(34, "\27\3\3\0\27", 5, 0, NULL, NULL) = 5 <0.000046> [pid 415421] recvfrom(34, "0\236\300\27T\224\33\251\224\313)\231;d0\275mNsc\317\235\377", 23, 0, NULL, NULL) = 23 <0.000018> [pid 415421] recvfrom(34, "\27\3\3\21\375", 5, 0, NULL, NULL) = 5 <0.000016> [pid 415421] recvfrom(34, "Nc7\245{r{\352uD\264e\t}c\3009\315$\2\220\25\246\321\307+\21\371\21\336\211\t"..., 4605, 0, NULL, NULL) = 2516 <0.000015> [pid 415421] recvfrom(34, "{\206\343\275\247\3663\355@w!\33B*\265:\206gu\222*\353\246Wc\317\35t\230\nY\263"..., 2089, 0, NULL, NULL) = 2089 <0.000023> [pid 415421] recvfrom(34, "\27\3\3\1\31", 5, 0, NULL, NULL) = 5 <0.000013> [pid 415421] recvfrom(34, "A1&\302\241\253\226\254\345'\3\275*XN\275\236b\221\304=\374\247h\331\347\276Hh\214\240f"..., 281, 0, NULL, NULL) = 281 <0.000013> [pid 415421] recvfrom(34, "\27\3\3\0E", 5, 0, NULL, NULL) = 5 <0.000056> [pid 415421] recvfrom(34, "\265\232#K9\303^\321-k\30(\203\230\347\307\226\25\322\220\314(\331\377\5\312\6\"a\2522\20"..., 69, 0, NULL, NULL) = 69 <0.000015> [pid 415421] sendto(34, "\24\3\3\0\1\1\27\3\3\0ER%%{U\231\240\376\207V\24\32\37\362\365Zk\252\347\5\32"..., 80, MSG_NOSIGNAL, NULL, 0) = 80 <0.000057> [pid 415421] getpeername(34, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("192.168.250.31")}, [128 => 16]) = 0 <0.000017> [pid 415421] getsockname(34, {sa_family=AF_INET, sin_port=htons(50508), sin_addr=inet_addr("192.168.252.78")}, [128 => 16]) = 0 <0.000016> (continues further without issue) ``` ### Two requests in a row (will cause the freeze) ``` [pid 415421] recvfrom(33, "\27\3\3\0g", 5, 0, NULL, NULL) = 5 <0.000004> [pid 415421] recvfrom(33, "\251\243\24\334\243\317\271d\242\276\322\321\205\231\276\322\5\214\245x\r\306//\232u\376\332\241k\225\363"..., 103, 0, NULL, NULL) = 103 <0.000003> [pid 415421] recvfrom(33, 0x7f7a341e3593, 5, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000003> strace: Process 415874 attached [pid 415421] socket(AF_INET, SOCK_STREAM|SOCK_CLOEXEC, IPPROTO_TCP) = 34 <0.000012> [pid 415421] connect(34, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("192.168.250.31")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.000035> [pid 415421] getsockopt(34, SOL_SOCKET, SO_ERROR, [0], [4]) = 0 <0.000004> [pid 415421] setsockopt(34, SOL_TCP, TCP_NODELAY, [0], 4) = 0 <0.000004> [pid 415421] sendto(34, "\26\3\1\2\0\1\0\1\374\3\3\352Q\3573\374&\313\342u\216\267v\257\10\v\320\346\345\fh\212"..., 517, MSG_NOSIGNAL, NULL, 0) = 517 <0.000015> [pid 415421] recvfrom(33, "\27\3\3\0g", 5, 0, NULL, NULL) = 5 <0.000091> [pid 415421] recvfrom(33, "\332\307\33I\236_\303\221\243\r\371\256\313\340\353\255 *\1N\6\250\255^)_I4h\224\206\251"..., 103, 0, NULL, NULL) = 103 <0.000031> [pid 415421] recvfrom(33, 0x7f7a341e3593, 5, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000124> ```
Trace output (.output_verbose(true) ### Trace output from the program ``` [2024-03-01T14:48:49.194+00:00] TRACE [hyper::client::pool] take? ("https", example.de): expiration = Some(90s) [2024-03-01T14:48:49.194+00:00] TRACE [hyper::client::pool] removing closed connection for ("https", example.de) [2024-03-01T14:48:49.194+00:00] TRACE [hyper::client::pool] checkout waiting for idle connection: ("https", example.de) [2024-03-01T14:48:49.194+00:00] DEBUG [reqwest::connect] starting new connection: https://example.de/ [2024-03-01T14:48:49.194+00:00] TRACE [hyper::client::connect::http] Http::connect; scheme=Some("https"), host=Some("example.de"), port=None [2024-03-01T14:48:49.194+00:00] DEBUG [hyper::client::connect::dns] resolving host="example.de" [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -> Connection; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] poll; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -> poll; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] connection.state=Open [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -> Connection; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] poll_ready; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -> poll_ready; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] <- poll_ready; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -- poll_ready; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] <- Connection; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] FramedRead::poll_next; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] -> FramedRead::poll_next; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] poll [2024-03-01T14:48:49.482+00:00] TRACE [tokio_util::codec::framed_impl] attempting to decode a frame [2024-03-01T14:48:49.482+00:00] TRACE [tokio_util::codec::framed_impl] frame decoded from buffer [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] read.bytes=80 [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] FramedRead::decode_frame; offset=80 [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] -> FramedRead::decode_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] decoding frame from 80B [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] frame.kind=Headers [2024-03-01T14:48:49.482+00:00] TRACE [h2::frame::headers] loading headers; flags=(0x25: END_HEADERS | END_STREAM | PRIORITY) [2024-03-01T14:48:49.482+00:00] TRACE [h2::hpack::decoder] hpack::decode; [2024-03-01T14:48:49.482+00:00] TRACE [h2::hpack::decoder] -> hpack::decode; [2024-03-01T14:48:49.482+00:00] TRACE [h2::hpack::decoder] decode [2024-03-01T14:48:49.482+00:00] TRACE [h2::hpack::decoder] rem=66 kind=Indexed [2024-03-01T14:48:49.482+00:00] TRACE [h2::hpack::decoder] rem=65 kind=LiteralWithoutIndexing [2024-03-01T14:48:49.482+00:00] TRACE [h2::hpack::decoder] rem=40 kind=Indexed [2024-03-01T14:48:49.482+00:00] TRACE [h2::hpack::decoder] rem=39 kind=Indexed [2024-03-01T14:48:49.482+00:00] TRACE [h2::hpack::decoder] rem=38 kind=Indexed [2024-03-01T14:48:49.482+00:00] TRACE [h2::hpack::decoder] rem=37 kind=Indexed [2024-03-01T14:48:49.482+00:00] TRACE [h2::hpack::decoder] rem=36 kind=Indexed [2024-03-01T14:48:49.482+00:00] TRACE [h2::hpack::decoder] rem=35 kind=Indexed [2024-03-01T14:48:49.482+00:00] TRACE [h2::hpack::decoder] rem=34 kind=Indexed [2024-03-01T14:48:49.482+00:00] TRACE [h2::hpack::decoder] rem=33 kind=LiteralNeverIndexed [2024-03-01T14:48:49.482+00:00] TRACE [h2::hpack::decoder] rem=18 kind=LiteralNeverIndexed [2024-03-01T14:48:49.482+00:00] TRACE [h2::hpack::decoder] rem=2 kind=Indexed [2024-03-01T14:48:49.482+00:00] TRACE [h2::hpack::decoder] rem=1 kind=Indexed [2024-03-01T14:48:49.482+00:00] TRACE [h2::hpack::decoder] <- hpack::decode; [2024-03-01T14:48:49.482+00:00] TRACE [h2::hpack::decoder] -- hpack::decode; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] <- FramedRead::decode_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] -- FramedRead::decode_frame; [2024-03-01T14:48:49.482+00:00] DEBUG [h2::codec::framed_read] received frame=Headers { stream_id: StreamId(17), flags: (0x25: END_HEADERS | END_STREAM | PRIORITY), stream_dep: StreamDependency { dependency_id: StreamId(7), weight: 21, is_exclusive: false } } [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] <- FramedRead::poll_next; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] -- FramedRead::poll_next; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] recv HEADERS frame=Headers { stream_id: StreamId(17), flags: (0x25: END_HEADERS | END_STREAM | PRIORITY), stream_dep: StreamDependency { dependency_id: StreamId(7), weight: 21, is_exclusive: false } } [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::flow_control] inc_window; sz=65535; old=0; new=65535 [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::flow_control] inc_window; sz=131072; old=0; new=131072 [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::streams] recv_headers; stream=StreamId(17); state=State { inner: Idle } [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::recv] opening stream; init_window=65535 [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::store] Queue::push [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::store] -> first entry [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::counts] transition_after; stream=StreamId(17); state=State { inner: HalfClosedRemote(AwaitingHeaders) }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_recv=1; num_send=0 [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -> Connection; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] poll_ready; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -> poll_ready; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] <- poll_ready; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -- poll_ready; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] <- Connection; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] FramedRead::poll_next; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] -> FramedRead::poll_next; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] poll [2024-03-01T14:48:49.482+00:00] TRACE [tokio_util::codec::framed_impl] attempting to decode a frame [2024-03-01T14:48:49.482+00:00] TRACE [tokio_util::codec::framed_impl] frame decoded from buffer [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] read.bytes=13 [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] FramedRead::decode_frame; offset=13 [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] -> FramedRead::decode_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] decoding frame from 13B [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] frame.kind=WindowUpdate [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] <- FramedRead::decode_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] -- FramedRead::decode_frame; [2024-03-01T14:48:49.482+00:00] DEBUG [h2::codec::framed_read] received frame=WindowUpdate { stream_id: StreamId(17), size_increment: 12451840 } [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] <- FramedRead::poll_next; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] -- FramedRead::poll_next; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] recv WINDOW_UPDATE frame=WindowUpdate { stream_id: StreamId(17), size_increment: 12451840 } [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] recv_stream_window_update; stream.id=StreamId(17) stream.state=State { inner: HalfClosedRemote(AwaitingHeaders) } inc=12451840 flow=FlowControl { window_size: Window(131072), available: Window(0) } [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] -> recv_stream_window_update; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::flow_control] inc_window; sz=12451840; old=131072; new=12582912 [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] try_assign_capacity; stream.id=StreamId(17) [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] -> try_assign_capacity; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] requested=0 additional=0 buffered=0 window=12582912 conn=12582912 [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] <- try_assign_capacity; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] -- try_assign_capacity; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] <- recv_stream_window_update; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] -- recv_stream_window_update; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -> Connection; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] poll_ready; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -> poll_ready; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] <- poll_ready; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -- poll_ready; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] <- Connection; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] FramedRead::poll_next; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] -> FramedRead::poll_next; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] poll [2024-03-01T14:48:49.482+00:00] TRACE [tokio_util::codec::framed_impl] attempting to decode a frame [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] <- FramedRead::poll_next; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] -- FramedRead::poll_next; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] try_reclaim_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] -> try_reclaim_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] <- try_reclaim_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] -- try_reclaim_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] poll_complete [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] schedule_pending_open [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] pop_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] -> pop_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] <- pop_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] -- pop_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_write] FramedWrite::flush; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_write] -> FramedWrite::flush; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_write] flushing buffer [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_write] <- FramedWrite::flush; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_write] -- FramedWrite::flush; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] try_reclaim_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] -> try_reclaim_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] <- try_reclaim_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] -- try_reclaim_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] <- poll; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -- poll; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] <- Connection; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -- Connection; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::streams] next_incoming; id=StreamId(17), state=State { inner: HalfClosedRemote(AwaitingHeaders) } [2024-03-01T14:48:49.482+00:00] TRACE [h2::server] received incoming [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -> Connection; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] poll; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -> poll; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] connection.state=Open [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -> Connection; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] poll_ready; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -> poll_ready; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] <- poll_ready; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -- poll_ready; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] <- Connection; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] FramedRead::poll_next; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] -> FramedRead::poll_next; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] poll [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] <- FramedRead::poll_next; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_read] -- FramedRead::poll_next; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] try_reclaim_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] -> try_reclaim_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] <- try_reclaim_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] -- try_reclaim_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] poll_complete [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] schedule_pending_open [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] pop_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] -> pop_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] <- pop_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] -- pop_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_write] FramedWrite::flush; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_write] -> FramedWrite::flush; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_write] flushing buffer [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_write] <- FramedWrite::flush; [2024-03-01T14:48:49.482+00:00] TRACE [h2::codec::framed_write] -- FramedWrite::flush; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] try_reclaim_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] -> try_reclaim_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] <- try_reclaim_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::streams::prioritize] -- try_reclaim_frame; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] <- poll; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -- poll; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] <- Connection; [2024-03-01T14:48:49.482+00:00] TRACE [h2::proto::connection] -- Connection; [2024-03-01T14:48:49.482+00:00] DEBUG [actix_files::service] error handling /static/css/bootstrap.min.css.map: No such file or directory (os error 2) [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::streams] drop_stream_ref; stream=Stream { id: StreamId(17), state: State { inner: HalfClosedRemote(AwaitingHeaders) }, is_counted: true, ref_count: 2, next_pending_send: None, is_pending_send: false, send_flow: FlowControl { window_size: Window(12582912), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: None, pending_send: Deque { indices: None }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: false, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(65535), available: Window(65535) }, in_flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: None }, is_recv: false, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted } [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::counts] transition_after; stream=StreamId(17); state=State { inner: HalfClosedRemote(AwaitingHeaders) }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_recv=1; num_send=0 [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::send] send_headers; frame=Headers { stream_id: StreamId(17), flags: (0x5: END_HEADERS | END_STREAM) }; init_window=131072 [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] Prioritize::queue_frame; stream.id=StreamId(17) [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] -> Prioritize::queue_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] schedule_send stream.id=StreamId(17) [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::store] Queue::push [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::store] -> first entry [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] <- Prioritize::queue_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] -- Prioritize::queue_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::counts] transition_after; stream=StreamId(17); state=State { inner: Closed(EndStream) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=1; num_send=0 [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::streams] drop_stream_ref; stream=Stream { id: StreamId(17), state: State { inner: Closed(EndStream) }, is_counted: true, ref_count: 2, next_pending_send: None, is_pending_send: true, send_flow: FlowControl { window_size: Window(12582912), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: None, pending_send: Deque { indices: Some(Indices { head: 0, tail: 0 }) }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: false, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(65535), available: Window(65535) }, in_flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: None }, is_recv: false, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted } [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::counts] transition_after; stream=StreamId(17); state=State { inner: Closed(EndStream) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=1; num_send=0 [2024-03-01T14:48:49.483+00:00] INFO [actix_web::middleware::logger] 127.0.0.1 "GET /static/css/bootstrap.min.css.map HTTP/2.0" 404 0 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/115.0" 0.000399 [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::streams] drop_stream_ref; stream=Stream { id: StreamId(17), state: State { inner: Closed(EndStream) }, is_counted: true, ref_count: 1, next_pending_send: None, is_pending_send: true, send_flow: FlowControl { window_size: Window(12582912), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: None, pending_send: Deque { indices: Some(Indices { head: 0, tail: 0 }) }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: false, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(65535), available: Window(65535) }, in_flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: None }, is_recv: false, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted } [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::counts] transition_after; stream=StreamId(17); state=State { inner: Closed(EndStream) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=1; num_send=0 [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::connection] -> Connection; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::connection] poll; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::connection] -> poll; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::connection] connection.state=Open [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::connection] -> Connection; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::connection] poll_ready; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::connection] -> poll_ready; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::connection] <- poll_ready; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::connection] -- poll_ready; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::connection] <- Connection; [2024-03-01T14:48:49.483+00:00] TRACE [h2::codec::framed_read] FramedRead::poll_next; [2024-03-01T14:48:49.483+00:00] TRACE [h2::codec::framed_read] -> FramedRead::poll_next; [2024-03-01T14:48:49.483+00:00] TRACE [h2::codec::framed_read] poll [2024-03-01T14:48:49.483+00:00] TRACE [h2::codec::framed_read] <- FramedRead::poll_next; [2024-03-01T14:48:49.483+00:00] TRACE [h2::codec::framed_read] -- FramedRead::poll_next; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] try_reclaim_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] -> try_reclaim_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] <- try_reclaim_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] -- try_reclaim_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] poll_complete [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] schedule_pending_open [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] pop_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] -> pop_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] popped; stream.id=StreamId(17) stream.state=State { inner: Closed(EndStream) } [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] -> popped; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] is_pending_reset=false [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] pop_frame; frame=Headers { stream_id: StreamId(17), flags: (0x5: END_HEADERS | END_STREAM) } [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::counts] transition_after; stream=StreamId(17); state=State { inner: Closed(EndStream) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=1; num_send=0 [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::counts] dec_num_streams; stream=StreamId(17) [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] <- popped; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] -- popped; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] <- pop_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] -- pop_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] writing frame=Headers { stream_id: StreamId(17), flags: (0x5: END_HEADERS | END_STREAM) } [2024-03-01T14:48:49.483+00:00] TRACE [h2::codec::framed_write] FramedWrite::buffer; frame=Headers { stream_id: StreamId(17), flags: (0x5: END_HEADERS | END_STREAM) } [2024-03-01T14:48:49.483+00:00] TRACE [h2::codec::framed_write] -> FramedWrite::buffer; [2024-03-01T14:48:49.483+00:00] DEBUG [h2::codec::framed_write] send frame=Headers { stream_id: StreamId(17), flags: (0x5: END_HEADERS | END_STREAM) } [2024-03-01T14:48:49.483+00:00] TRACE [h2::hpack::encoder] hpack::encode; [2024-03-01T14:48:49.483+00:00] TRACE [h2::hpack::encoder] -> hpack::encode; [2024-03-01T14:48:49.483+00:00] TRACE [h2::hpack::encoder] <- hpack::encode; [2024-03-01T14:48:49.483+00:00] TRACE [h2::hpack::encoder] -- hpack::encode; [2024-03-01T14:48:49.483+00:00] TRACE [h2::codec::framed_write] <- FramedWrite::buffer; [2024-03-01T14:48:49.483+00:00] TRACE [h2::codec::framed_write] -- FramedWrite::buffer; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] try_reclaim_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] -> try_reclaim_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] <- try_reclaim_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] -- try_reclaim_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] schedule_pending_open [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] pop_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] -> pop_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] <- pop_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] -- pop_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::codec::framed_write] FramedWrite::flush; [2024-03-01T14:48:49.483+00:00] TRACE [h2::codec::framed_write] -> FramedWrite::flush; [2024-03-01T14:48:49.483+00:00] TRACE [h2::codec::framed_write] queued_data_frame=false [2024-03-01T14:48:49.483+00:00] TRACE [h2::codec::framed_write] flushing buffer [2024-03-01T14:48:49.483+00:00] TRACE [h2::codec::framed_write] <- FramedWrite::flush; [2024-03-01T14:48:49.483+00:00] TRACE [h2::codec::framed_write] -- FramedWrite::flush; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] try_reclaim_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] -> try_reclaim_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] <- try_reclaim_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::streams::prioritize] -- try_reclaim_frame; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::connection] <- poll; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::connection] -- poll; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::connection] <- Connection; [2024-03-01T14:48:49.483+00:00] TRACE [h2::proto::connection] -- Connection; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] -> Connection; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] poll; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] -> poll; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] connection.state=Open [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] -> Connection; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] poll_ready; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] -> poll_ready; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] <- poll_ready; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] -- poll_ready; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] <- Connection; [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_read] FramedRead::poll_next; [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_read] -> FramedRead::poll_next; [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_read] poll [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_read] <- FramedRead::poll_next; [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_read] -- FramedRead::poll_next; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] try_reclaim_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] -> try_reclaim_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] <- try_reclaim_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] -- try_reclaim_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] poll_complete [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] schedule_pending_open [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] pop_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] -> pop_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] <- pop_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] -- pop_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_write] FramedWrite::flush; [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_write] -> FramedWrite::flush; [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_write] flushing buffer [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_write] <- FramedWrite::flush; [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_write] -- FramedWrite::flush; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] try_reclaim_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] -> try_reclaim_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] <- try_reclaim_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] -- try_reclaim_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] <- poll; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] -- poll; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] <- Connection; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] -- Connection; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] -> Connection; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] poll; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] -> poll; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] connection.state=Open [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] -> Connection; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] poll_ready; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] -> poll_ready; [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_write] FramedWrite::buffer; frame=Ping { ack: false, payload: [59, 124, 219, 122, 11, 135, 22, 180] } [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_write] -> FramedWrite::buffer; [2024-03-01T14:48:53.776+00:00] DEBUG [h2::codec::framed_write] send frame=Ping { ack: false, payload: [59, 124, 219, 122, 11, 135, 22, 180] } [2024-03-01T14:48:53.776+00:00] TRACE [h2::frame::ping] encoding PING; ack=false len=8 [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_write] encoded ping rem=17 [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_write] <- FramedWrite::buffer; [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_write] -- FramedWrite::buffer; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] <- poll_ready; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] -- poll_ready; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] <- Connection; [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_read] FramedRead::poll_next; [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_read] -> FramedRead::poll_next; [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_read] poll [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_read] <- FramedRead::poll_next; [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_read] -- FramedRead::poll_next; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] try_reclaim_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] -> try_reclaim_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] <- try_reclaim_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] -- try_reclaim_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] poll_complete [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] schedule_pending_open [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] pop_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] -> pop_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] <- pop_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] -- pop_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_write] FramedWrite::flush; [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_write] -> FramedWrite::flush; [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_write] queued_data_frame=false [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_write] flushing buffer [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_write] <- FramedWrite::flush; [2024-03-01T14:48:53.776+00:00] TRACE [h2::codec::framed_write] -- FramedWrite::flush; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] try_reclaim_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] -> try_reclaim_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] <- try_reclaim_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::streams::prioritize] -- try_reclaim_frame; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] <- poll; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] -- poll; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] <- Connection; [2024-03-01T14:48:53.776+00:00] TRACE [h2::proto::connection] -- Connection; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] -> Connection; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] poll; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] -> poll; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] connection.state=Open [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] -> Connection; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] poll_ready; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] -> poll_ready; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] <- poll_ready; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] -- poll_ready; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] <- Connection; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] FramedRead::poll_next; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] -> FramedRead::poll_next; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] poll [2024-03-01T14:48:53.777+00:00] TRACE [tokio_util::codec::framed_impl] attempting to decode a frame [2024-03-01T14:48:53.777+00:00] TRACE [tokio_util::codec::framed_impl] frame decoded from buffer [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] read.bytes=17 [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] FramedRead::decode_frame; offset=17 [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] -> FramedRead::decode_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] decoding frame from 17B [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] frame.kind=Ping [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] <- FramedRead::decode_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] -- FramedRead::decode_frame; [2024-03-01T14:48:53.777+00:00] DEBUG [h2::codec::framed_read] received frame=Ping { ack: true, payload: [59, 124, 219, 122, 11, 135, 22, 180] } [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] <- FramedRead::poll_next; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] -- FramedRead::poll_next; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] recv PING frame=Ping { ack: true, payload: [59, 124, 219, 122, 11, 135, 22, 180] } [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::ping_pong] recv PING USER ack [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] -> Connection; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] poll_ready; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] -> poll_ready; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] <- poll_ready; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] -- poll_ready; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] <- Connection; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] FramedRead::poll_next; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] -> FramedRead::poll_next; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] poll [2024-03-01T14:48:53.777+00:00] TRACE [tokio_util::codec::framed_impl] attempting to decode a frame [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] <- FramedRead::poll_next; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] -- FramedRead::poll_next; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] try_reclaim_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] -> try_reclaim_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] <- try_reclaim_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] -- try_reclaim_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] poll_complete [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] schedule_pending_open [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] pop_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] -> pop_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] <- pop_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] -- pop_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_write] FramedWrite::flush; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_write] -> FramedWrite::flush; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_write] flushing buffer [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_write] <- FramedWrite::flush; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_write] -- FramedWrite::flush; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] try_reclaim_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] -> try_reclaim_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] <- try_reclaim_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] -- try_reclaim_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] <- poll; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] -- poll; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] <- Connection; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] -- Connection; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] -> Connection; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] poll; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] -> poll; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] connection.state=Open [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] -> Connection; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] poll_ready; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] -> poll_ready; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] <- poll_ready; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] -- poll_ready; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] <- Connection; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] FramedRead::poll_next; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] -> FramedRead::poll_next; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] poll [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] <- FramedRead::poll_next; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_read] -- FramedRead::poll_next; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] try_reclaim_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] -> try_reclaim_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] <- try_reclaim_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] -- try_reclaim_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] poll_complete [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] schedule_pending_open [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] pop_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] -> pop_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] <- pop_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] -- pop_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_write] FramedWrite::flush; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_write] -> FramedWrite::flush; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_write] flushing buffer [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_write] <- FramedWrite::flush; [2024-03-01T14:48:53.777+00:00] TRACE [h2::codec::framed_write] -- FramedWrite::flush; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] try_reclaim_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] -> try_reclaim_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] <- try_reclaim_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::streams::prioritize] -- try_reclaim_frame; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] <- poll; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] -- poll; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] <- Connection; [2024-03-01T14:48:53.777+00:00] TRACE [h2::proto::connection] -- Connection; [2024-03-01T14:48:58.768+00:00] TRACE [h2::proto::connection] -> Connection; [2024-03-01T14:48:58.768+00:00] TRACE [h2::proto::connection] poll; ...repeats infinitely every 5 seconds ```
hrl1058 commented 4 months ago

seems like i have same problem use reqwest::Client::new() instead reuse the client may fix this problem

seanmonstar commented 4 months ago

seems like i have same problem

Also when using actix?

I cannot tell that this is an issue reqwest. If it doesn't occur with a minimal reproduction, it might be something unrelated. Including what versions of hyper and h2 are in use might be helpful. But I'm inclined to close this unless it can be found to be a bug actually in reqwest.