Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
Darkrael opened this issue Mar 1, 2024 · 0 comments
Open

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

Darkrael opened this issue Mar 1, 2024 · 0 comments

Comments

@Darkrael
Copy link

Darkrael commented Mar 1, 2024

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

  • A webbrowser loads /index.html which upon loading sends two fetch requests to load something from my api
  • The server goes through some code and decides that it needs to request that data from another server
  • It sends a request via a "reqwest::async_impl::client::Client" using "send().await"
  • While one thread waits for the answer, the second requests comes in
  • It does not matter what that request does (i've stopped it directly in the get handler function) but the fact that that request comes in now basically freezes the whole server
  • Sometime static content (via actix_files) will still work for a few requests but otherwise the server is completely dead

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<h2::proto::streams::stream::NextAccept> }, 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<h2::proto::streams::stream::NextAccept> }, 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<h2::proto::streams::stream::NextAccept> }, 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
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@Darkrael