search

googleforgames / quilkin

Quilkin is a non-transparent UDP proxy specifically designed for use with large scale multiplayer dedicated game server deployments, to ensure security, access control, telemetry data, metrics and more.
Apache License 2.0
1.3k stars 94 forks source link

xDS dynamic routing stops working after 4-5 days #660

Closed luckyswede closed 1 year ago

luckyswede commented 1 year ago

Hi, thanks for a great product. I have set up quilkin xds+agones in the same way as described in https://github.com/googleforgames/quilkin/tree/main/examples/agones-xonotic-xds but running my own game server. It all works fine for a few days, but then all of a sudden routing stops working. It has happened 3 times so far, with 4-5 days in between. I have not been able to capture any logs unfortunately from these occasions, I will make sure to do so the next time it happens. The situation was resolved two times by restarting the xds server only if I remember correctly, and last time I also had to restart the proxy. I've been running both single and multiple xds instances, but only a single proxy instance.

Has anyone else encountered this issue?

I have now enabled trace logging both on the proxy and the xds server. I will also make sure to capture the proxy config next time it happens.

markmandel commented 1 year ago

@XAMPPRocky could this be related to https://github.com/googleforgames/quilkin/pull/659 ?

XAMPPRocky commented 1 year ago

@luckyswede Thank you for your issue! Would you also mind trying with the latest version of Quilkin?

@markmandel It might help with the issue, if it's a server side issue. However right now with latest the connection should recover just fine, #659 was downgrading these errors from fatal, but even when that happens the whole management server task retries again and the client reconnects, it shouldn't require a manual restart.

watch stream failed: Error reading events stream: error reading a body from connection: error reading a body from connection: Connection reset by peer (os error 104)
error returned by apiserver during watch: too old resource version: 611227041 (611227330): Expired
luckyswede commented 1 year ago

@XAMPPRocky sure, no problems to try another version, but which one do you mean? Latest from https://console.cloud.google.com/artifacts/docker/quilkin/us/ci/quilkin?

luckyswede commented 1 year ago

@XAMPPRocky It happened again, i'm attaching relevant data. Routing to a new gameserver on port 12827 using token Tm1ic3NNQQ== didnt work, the proxy says "no matching endpoints". The gameserver was added to 07:05:27 xds, but the proxy config was not updated.

I had to restart the xds server to get things to work.

Note that the xds server was also restarted last night at 23:40:11. After that there are no xds related errors in the proxy logs.

trace logs of the xds server xds-logs.txt

trace logs of the proxy server proxy-logs.txt

the k8s yaml for the allocated gameserver gs.yml.txt

output from kubectl get gs gs.txt

output from /config on the proxy instance proxy-config.txt

XAMPPRocky commented 1 year ago

sure, no problems to try another version, but which one do you mean?

Thank you for your response! The latest from that list should be just fine.

Would you be able to run it with RUST_LOG=trace? This will be a lot noisier, but just from the Quilkin logs alone I can't see any indicator, so I need to see traces from the lower level HTTP implementation.

luckyswede commented 1 year ago

Ok, running us-docker.pkg.dev/quilkin/ci/quilkin:0.5.0-dev-717690c now. However, running with trace seems to make the endpoint registration shaky, I had to restart the pods a couple of times to make it work from the get go. Running with info,quilkin=trace seems more robust.

luckyswede commented 1 year ago

Here is an example of when it's not working. I restarted the proxy, then restarted the xds server, and the proxy wasnt able to reconnect to the xds server which caused it to not get info about new gameserver instances.

proxy.log xds.log

markmandel commented 1 year ago

On the proxy side, does seem like the connection with the xDS server drops:

{"timestamp":"2022-12-07T23:42:24.660288Z","level":"WARN","fields":{"message":"Unable to connect to the XDS server","error":"tonic::transport::Error(Transport, hyper::Error(Connect, ConnectError(\"tcp connect error\", Os { code: 110, kind: TimedOut, message: \"Connection timed out\" })))"},"target":"quilkin::xds::client","filename":"src/xds/client.rs","span":{"name":"xds_client_connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"}]}

Seeing this in both proxy-logs.txt and the most recent proxy.log as well.

markmandel commented 1 year ago

Just to rule things out @luckyswede , are you seeing any increase in CPU/Memory/Container restarts with either the xDS admin pods or the proxy pods?

XAMPPRocky commented 1 year ago

To me the interesting part of the proxy log is here, it warns twice that it can't connect to the xDS server, but we don't see anymore attempts to reconnect after the second try.

{"timestamp":"2022-12-11T14:20:58.403633Z","level":"TRACE","fields":{"message":"sending data frame","len":103},"target":"h2::proto::streams::prioritize","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/streams/prioritize.rs","span":{"stream.id":"StreamId(1)","stream.state":"State { inner: Open { local: Streaming, remote: Streaming } }","name":"popped"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"pop_frame"},{"stream.id":"StreamId(1)","stream.state":"State { inner: Open { local: Streaming, remote: Streaming } }","name":"popped"}]}
{"timestamp":"2022-12-11T14:20:58.403649Z","level":"TRACE","fields":{"message":"send_data; sz=103; window=1048107; available=104"},"target":"h2::proto::streams::flow_control","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/streams/flow_control.rs","span":{"name":"updating stream flow"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"pop_frame"},{"stream.id":"StreamId(1)","stream.state":"State { inner: Open { local: Streaming, remote: Streaming } }","name":"popped"},{"name":"updating stream flow"}]}
{"timestamp":"2022-12-11T14:20:58.403667Z","level":"TRACE","fields":{"message":"  notifying task"},"target":"h2::proto::streams::stream","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/streams/stream.rs","span":{"name":"updating stream flow"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"pop_frame"},{"stream.id":"StreamId(1)","stream.state":"State { inner: Open { local: Streaming, remote: Streaming } }","name":"popped"},{"name":"updating stream flow"}]}
{"timestamp":"2022-12-11T14:20:58.403680Z","level":"TRACE","fields":{"message":"send_data; sz=103; window=1048107; available=1048106"},"target":"h2::proto::streams::flow_control","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/streams/flow_control.rs","span":{"name":"updating connection flow"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"pop_frame"},{"stream.id":"StreamId(1)","stream.state":"State { inner: Open { local: Streaming, remote: Streaming } }","name":"popped"},{"name":"updating connection flow"}]}
{"timestamp":"2022-12-11T14:20:58.403695Z","level":"TRACE","fields":{"message":"pop_frame; frame=Data { stream_id: StreamId(1) }"},"target":"h2::proto::streams::prioritize","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/streams/prioritize.rs","span":{"stream.id":"StreamId(1)","stream.state":"State { inner: Open { local: Streaming, remote: Streaming } }","name":"popped"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"pop_frame"},{"stream.id":"StreamId(1)","stream.state":"State { inner: Open { local: Streaming, remote: Streaming } }","name":"popped"}]}
{"timestamp":"2022-12-11T14:20:58.403714Z","level":"TRACE","fields":{"message":"transition_after; stream=StreamId(1); state=State { inner: Open { local: Streaming, remote: Streaming } }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=1"},"target":"h2::proto::streams::counts","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/streams/counts.rs","span":{"stream.id":"StreamId(1)","stream.state":"State { inner: Open { local: Streaming, remote: Streaming } }","name":"popped"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"pop_frame"},{"stream.id":"StreamId(1)","stream.state":"State { inner: Open { local: Streaming, remote: Streaming } }","name":"popped"}]}
{"timestamp":"2022-12-11T14:20:58.403736Z","level":"TRACE","fields":{"message":"writing","frame":"Data { stream_id: StreamId(1) }"},"target":"h2::proto::streams::prioritize","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/streams/prioritize.rs","span":{"name":"poll"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"}]}
{"timestamp":"2022-12-11T14:20:58.403754Z","level":"DEBUG","fields":{"message":"send","frame":"Data { stream_id: StreamId(1) }"},"target":"h2::codec::framed_write","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/codec/framed_write.rs","span":{"frame":"Data { stream_id: StreamId(1) }","name":"FramedWrite::buffer"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"},{"frame":"Data { stream_id: StreamId(1) }","name":"FramedWrite::buffer"}]}
{"timestamp":"2022-12-11T14:20:58.403774Z","level":"TRACE","fields":{"message":"reclaimed","frame":"Data { stream_id: StreamId(1) }","sz":0},"target":"h2::proto::streams::prioritize","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/streams/prioritize.rs","span":{"name":"try_reclaim_frame"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"try_reclaim_frame"}]}
{"timestamp":"2022-12-11T14:20:58.403791Z","level":"TRACE","fields":{"message":"schedule_pending_open"},"target":"h2::proto::streams::prioritize","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/streams/prioritize.rs","span":{"name":"poll"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"}]}
{"timestamp":"2022-12-11T14:20:58.403804Z","level":"TRACE","fields":{"queued_data_frame":false},"target":"h2::codec::framed_write","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/codec/framed_write.rs","span":{"name":"FramedWrite::flush"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedWrite::flush"}]}
{"timestamp":"2022-12-11T14:20:58.403836Z","level":"TRACE","fields":{"message":"flushing buffer"},"target":"h2::codec::framed_write","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/codec/framed_write.rs","span":{"name":"FramedWrite::flush"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedWrite::flush"}]}
{"timestamp":"2022-12-11T14:21:03.095729Z","level":"TRACE","fields":{"message":"registering event source with poller: token=Token(3), interests=READABLE | WRITABLE","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":532},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:21:03.095827Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:03.095852Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:03.095893Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:03.095904Z","level":"TRACE","fields":{"message":"received 107 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:03.095924Z","level":"TRACE","fields":{"message":"Request.parse","bytes":107},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:21:03.095999Z","level":"TRACE","fields":{"message":"Request.parse Complete(107)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:21:03.096028Z","level":"DEBUG","fields":{"message":"parsed 4 headers"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:03.096039Z","level":"DEBUG","fields":{"message":"incoming body is empty"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:03.096045Z","level":"TRACE","fields":{"message":"remote disabling keep-alive"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:03.096133Z","level":"TRACE","fields":{"message":"Server::encode status=200, body=Some(Known(2)), req_method=Some(GET)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"encode_headers"},"spans":[{"name":"encode_headers"}]}
{"timestamp":"2022-12-11T14:21:03.096154Z","level":"TRACE","fields":{"message":"buffer.queue","self.len":75,"buf.len":2},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:03.096208Z","level":"DEBUG","fields":{"message":"flushed 77 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:03.096217Z","level":"TRACE","fields":{"message":"State::close()"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:03.096222Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:03.096239Z","level":"TRACE","fields":{"message":"shut down IO complete"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:03.096252Z","level":"TRACE","fields":{"message":"deregistering event source from poller","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":663},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:21:11.895096Z","level":"TRACE","fields":{"connection.state":"Open"},"target":"h2::proto::connection","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/connection.rs","span":{"name":"poll"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"}]}
{"timestamp":"2022-12-11T14:21:11.895153Z","level":"TRACE","fields":{"message":"poll"},"target":"h2::codec::framed_read","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/codec/framed_read.rs","span":{"name":"FramedRead::poll_next"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedRead::poll_next"}]}
{"timestamp":"2022-12-11T14:21:11.895170Z","level":"TRACE","fields":{"message":"codec closed"},"target":"h2::proto::connection","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/connection.rs","span":{"name":"poll"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"}]}
{"timestamp":"2022-12-11T14:21:11.895179Z","level":"TRACE","fields":{"message":"Streams::recv_eof"},"target":"h2::proto::streams::streams","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/streams/streams.rs","span":{"name":"poll"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"}]}
{"timestamp":"2022-12-11T14:21:11.895188Z","level":"TRACE","fields":{"message":"recv_eof; state=Open { local: Streaming, remote: Streaming }"},"target":"h2::proto::streams::state","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/streams/state.rs","span":{"name":"poll"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"}]}
{"timestamp":"2022-12-11T14:21:11.895217Z","level":"TRACE","fields":{"message":"transition_after; stream=StreamId(1); state=State { inner: Closed(Error(Io(BrokenPipe, None))) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=1"},"target":"h2::proto::streams::counts","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/streams/counts.rs","span":{"name":"poll"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"}]}
{"timestamp":"2022-12-11T14:21:11.895238Z","level":"TRACE","fields":{"message":"dec_num_streams; stream=StreamId(1)"},"target":"h2::proto::streams::counts","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/streams/counts.rs","span":{"name":"poll"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"}]}
{"timestamp":"2022-12-11T14:21:11.895254Z","level":"TRACE","fields":{"connection.state":"Closing(NO_ERROR, Library)"},"target":"h2::proto::connection","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/connection.rs","span":{"name":"poll"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"}]}
{"timestamp":"2022-12-11T14:21:11.895267Z","level":"TRACE","fields":{"message":"connection closing after flush"},"target":"h2::proto::connection","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/connection.rs","span":{"name":"poll"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"}]}
{"timestamp":"2022-12-11T14:21:11.895278Z","level":"TRACE","fields":{"message":"flushing buffer"},"target":"h2::codec::framed_write","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/codec/framed_write.rs","span":{"name":"FramedWrite::flush"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"},{"name":"FramedWrite::flush"}]}
{"timestamp":"2022-12-11T14:21:11.895361Z","level":"TRACE","fields":{"connection.state":"Closed(NO_ERROR, Library)"},"target":"h2::proto::connection","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/connection.rs","span":{"name":"poll"},"spans":[{"servers":"[\"http://quilkin-manage-agones:80\"]","name":"connect"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"},{"peer":"Client","name":"Connection"},{"name":"poll"}]}
{"timestamp":"2022-12-11T14:21:11.895382Z","level":"TRACE","fields":{"message":"Streams::recv_eof"},"target":"h2::proto::streams::streams","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/streams/streams.rs"}
{"timestamp":"2022-12-11T14:21:11.895428Z","level":"TRACE","fields":{"message":"deregistering event source from poller","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":663},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:21:11.895477Z","level":"TRACE","fields":{"message":"signal: Closed","log.target":"want","log.module_path":"want","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/want-0.3.0/src/lib.rs","log.line":330},"target":"want","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/want-0.3.0/src/lib.rs"}
{"timestamp":"2022-12-11T14:21:11.895493Z","level":"DEBUG","fields":{"message":"connection error: hyper::Error(Io, Kind(BrokenPipe))"},"target":"hyper::client::service","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/client/service.rs"}
{"timestamp":"2022-12-11T14:21:11.895525Z","level":"TRACE","fields":{"message":"drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: Closed(Error(Io(BrokenPipe, None))) }, is_counted: false, ref_count: 2, next_pending_send: None, is_pending_send: false, send_flow: FlowControl { window_size: Window(1048004), 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: true, 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(2095985), available: Window(2097152) }, 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 }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted }"},"target":"h2::proto::streams::streams","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/streams/streams.rs"}
{"timestamp":"2022-12-11T14:21:11.895556Z","level":"TRACE","fields":{"message":"transition_after; stream=StreamId(1); state=State { inner: Closed(Error(Io(BrokenPipe, None))) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=0"},"target":"h2::proto::streams::counts","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/streams/counts.rs"}
{"timestamp":"2022-12-11T14:21:11.895569Z","level":"DEBUG","fields":{"message":"client request body error: error writing a body to connection: send stream capacity unexpectedly closed"},"target":"hyper::proto::h2::client","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h2/client.rs"}
{"timestamp":"2022-12-11T14:21:11.895602Z","level":"DEBUG","fields":{"message":"decoder inner stream error: Status { code: Unknown, message: \"error reading a body from connection: broken pipe\", source: Some(hyper::Error(Body, Error { kind: Io(Kind(BrokenPipe)) })) }"},"target":"tonic::codec::decode","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/tonic-0.8.3/src/codec/decode.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"}]}
{"timestamp":"2022-12-11T14:21:11.895627Z","level":"WARN","fields":{"message":"Error from xDS server","error":"status: Unknown, message: \"error reading a body from connection: broken pipe\", details: [], metadata: MetadataMap { headers: {} }"},"target":"quilkin::xds::client","filename":"src/xds/client.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"}]}
{"timestamp":"2022-12-11T14:21:11.895650Z","level":"INFO","fields":{"message":"Lost connection to xDS, retrying"},"target":"quilkin::xds::client","filename":"src/xds/client.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"}]}
{"timestamp":"2022-12-11T14:21:11.895679Z","level":"TRACE","fields":{"message":"poll_ready; idle"},"target":"tonic::transport::service::reconnect","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/tonic-0.8.3/src/transport/service/reconnect.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:11.895708Z","level":"TRACE","fields":{"message":"poll_ready; connecting"},"target":"tonic::transport::service::reconnect","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/tonic-0.8.3/src/transport/service/reconnect.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:11.895724Z","level":"TRACE","fields":{"message":"Http::connect; scheme=Some(\"http\"), host=Some(\"quilkin-manage-agones\"), port=Some(Port(80))"},"target":"hyper::client::connect::http","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/client/connect/http.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:11.895800Z","level":"TRACE","fields":{"message":"poll_ready; not ready"},"target":"tonic::transport::service::reconnect","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/tonic-0.8.3/src/transport/service/reconnect.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:11.895836Z","level":"DEBUG","fields":{"message":"resolving host=\"quilkin-manage-agones\""},"target":"hyper::client::connect::dns","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/client/connect/dns.rs"}
{"timestamp":"2022-12-11T14:21:11.896453Z","level":"TRACE","fields":{"message":"poll_ready; connecting"},"target":"tonic::transport::service::reconnect","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/tonic-0.8.3/src/transport/service/reconnect.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:11.896499Z","level":"DEBUG","fields":{"message":"connecting to 10.4.236.99:80"},"target":"hyper::client::connect::http","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/client/connect/http.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:11.896650Z","level":"TRACE","fields":{"message":"registering event source with poller: token=Token(16777217), interests=READABLE | WRITABLE","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":532},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:11.896683Z","level":"TRACE","fields":{"message":"poll_ready; not ready"},"target":"tonic::transport::service::reconnect","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/tonic-0.8.3/src/transport/service/reconnect.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:11.896828Z","level":"TRACE","fields":{"message":"poll_ready; connecting"},"target":"tonic::transport::service::reconnect","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/tonic-0.8.3/src/transport/service/reconnect.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:11.896851Z","level":"TRACE","fields":{"message":"deregistering event source from poller","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":663},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:11.896876Z","level":"TRACE","fields":{"message":"connect error for 10.4.236.99:80: ConnectError(\"tcp connect error\", Os { code: 111, kind: ConnectionRefused, message: \"Connection refused\" })"},"target":"hyper::client::connect::http","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/client/connect/http.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:11.896975Z","level":"TRACE","fields":{"message":"poll_ready; error"},"target":"tonic::transport::service::reconnect","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/tonic-0.8.3/src/transport/service/reconnect.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:11.896994Z","level":"INFO","fields":{"message":"Retrying to connect","attempt":1},"target":"quilkin::xds::client","filename":"src/xds/client.rs","span":{"name":"xds_client_connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"}]}
{"timestamp":"2022-12-11T14:21:11.897016Z","level":"WARN","fields":{"message":"Unable to connect to the XDS server","error":"tonic::transport::Error(Transport, hyper::Error(Connect, ConnectError(\"tcp connect error\", Os { code: 111, kind: ConnectionRefused, message: \"Connection refused\" })))"},"target":"quilkin::xds::client","filename":"src/xds/client.rs","span":{"name":"xds_client_connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"}]}
{"timestamp":"2022-12-11T14:21:13.075313Z","level":"TRACE","fields":{"message":"poll_ready; idle"},"target":"tonic::transport::service::reconnect","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/tonic-0.8.3/src/transport/service/reconnect.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:13.075380Z","level":"TRACE","fields":{"message":"poll_ready; connecting"},"target":"tonic::transport::service::reconnect","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/tonic-0.8.3/src/transport/service/reconnect.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:13.075389Z","level":"TRACE","fields":{"message":"Http::connect; scheme=Some(\"http\"), host=Some(\"quilkin-manage-agones\"), port=Some(Port(80))"},"target":"hyper::client::connect::http","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/client/connect/http.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:13.075431Z","level":"TRACE","fields":{"message":"poll_ready; not ready"},"target":"tonic::transport::service::reconnect","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/tonic-0.8.3/src/transport/service/reconnect.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:13.075540Z","level":"DEBUG","fields":{"message":"resolving host=\"quilkin-manage-agones\""},"target":"hyper::client::connect::dns","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/client/connect/dns.rs"}
{"timestamp":"2022-12-11T14:21:13.076252Z","level":"TRACE","fields":{"message":"poll_ready; connecting"},"target":"tonic::transport::service::reconnect","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/tonic-0.8.3/src/transport/service/reconnect.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:13.076294Z","level":"DEBUG","fields":{"message":"connecting to 10.4.236.99:80"},"target":"hyper::client::connect::http","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/client/connect/http.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:13.076376Z","level":"TRACE","fields":{"message":"registering event source with poller: token=Token(33554433), interests=READABLE | WRITABLE","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":532},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:13.076412Z","level":"TRACE","fields":{"message":"poll_ready; not ready"},"target":"tonic::transport::service::reconnect","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/tonic-0.8.3/src/transport/service/reconnect.rs","span":{"name":"AggregatedDiscoveryServiceClient::connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"},{"name":"AggregatedDiscoveryServiceClient::connect"}]}
{"timestamp":"2022-12-11T14:21:13.095925Z","level":"TRACE","fields":{"message":"registering event source with poller: token=Token(16777219), interests=READABLE | WRITABLE","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":532},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:21:13.096033Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:13.096046Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:13.096064Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:13.096079Z","level":"TRACE","fields":{"message":"received 107 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:13.096094Z","level":"TRACE","fields":{"message":"Request.parse","bytes":107},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:21:13.096116Z","level":"TRACE","fields":{"message":"Request.parse Complete(107)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:21:13.096138Z","level":"DEBUG","fields":{"message":"parsed 4 headers"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:13.096148Z","level":"DEBUG","fields":{"message":"incoming body is empty"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:13.096153Z","level":"TRACE","fields":{"message":"remote disabling keep-alive"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:13.096172Z","level":"TRACE","fields":{"message":"Server::encode status=200, body=Some(Known(2)), req_method=Some(GET)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"encode_headers"},"spans":[{"name":"encode_headers"}]}
{"timestamp":"2022-12-11T14:21:13.096188Z","level":"TRACE","fields":{"message":"buffer.queue","self.len":75,"buf.len":2},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:13.096243Z","level":"DEBUG","fields":{"message":"flushed 77 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:13.096250Z","level":"TRACE","fields":{"message":"State::close()"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:13.096254Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:13.096270Z","level":"TRACE","fields":{"message":"shut down IO complete"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:13.096279Z","level":"TRACE","fields":{"message":"deregistering event source from poller","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":663},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:21:23.095739Z","level":"TRACE","fields":{"message":"registering event source with poller: token=Token(33554435), interests=READABLE | WRITABLE","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":532},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:21:23.095825Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:23.095838Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:23.095857Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:23.095869Z","level":"TRACE","fields":{"message":"received 107 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:23.095890Z","level":"TRACE","fields":{"message":"Request.parse","bytes":107},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:21:23.095911Z","level":"TRACE","fields":{"message":"Request.parse Complete(107)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:21:23.095955Z","level":"DEBUG","fields":{"message":"parsed 4 headers"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:23.095962Z","level":"DEBUG","fields":{"message":"incoming body is empty"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:23.095967Z","level":"TRACE","fields":{"message":"remote disabling keep-alive"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:23.095983Z","level":"TRACE","fields":{"message":"Server::encode status=200, body=Some(Known(2)), req_method=Some(GET)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"encode_headers"},"spans":[{"name":"encode_headers"}]}
{"timestamp":"2022-12-11T14:21:23.095999Z","level":"TRACE","fields":{"message":"buffer.queue","self.len":75,"buf.len":2},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:23.096063Z","level":"DEBUG","fields":{"message":"flushed 77 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:23.096074Z","level":"TRACE","fields":{"message":"State::close()"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:23.096078Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:23.096095Z","level":"TRACE","fields":{"message":"shut down IO complete"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:23.096107Z","level":"TRACE","fields":{"message":"deregistering event source from poller","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":663},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:21:33.095787Z","level":"TRACE","fields":{"message":"registering event source with poller: token=Token(50331651), interests=READABLE | WRITABLE","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":532},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:21:33.095880Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:33.095899Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:33.095916Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:33.095928Z","level":"TRACE","fields":{"message":"received 107 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:33.095964Z","level":"TRACE","fields":{"message":"Request.parse","bytes":107},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:21:33.095987Z","level":"TRACE","fields":{"message":"Request.parse Complete(107)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:21:33.096009Z","level":"DEBUG","fields":{"message":"parsed 4 headers"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:33.096014Z","level":"DEBUG","fields":{"message":"incoming body is empty"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:33.096020Z","level":"TRACE","fields":{"message":"remote disabling keep-alive"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:33.096041Z","level":"TRACE","fields":{"message":"Server::encode status=200, body=Some(Known(2)), req_method=Some(GET)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"encode_headers"},"spans":[{"name":"encode_headers"}]}
{"timestamp":"2022-12-11T14:21:33.096059Z","level":"TRACE","fields":{"message":"buffer.queue","self.len":75,"buf.len":2},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:33.096118Z","level":"DEBUG","fields":{"message":"flushed 77 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:33.096126Z","level":"TRACE","fields":{"message":"State::close()"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:33.096129Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:33.096143Z","level":"TRACE","fields":{"message":"shut down IO complete"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:33.096150Z","level":"TRACE","fields":{"message":"deregistering event source from poller","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":663},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:21:33.586737Z","level":"TRACE","fields":{"message":"received packet from downstream","id":0,"size":11,"source":"10.4.0.88:7216","contents":"UElOR2NoMUdNRUw="},"target":"quilkin::proxy","filename":"src/proxy.rs"}
{"timestamp":"2022-12-11T14:21:33.586778Z","level":"TRACE","fields":{"message":"read filtering packet","id":"quilkin.filters.capture.v1alpha1.Capture"},"target":"quilkin::filters::chain","filename":"src/filters/chain.rs"}
{"timestamp":"2022-12-11T14:21:33.586811Z","level":"TRACE","fields":{"message":"captured value","key":"quilkin.dev/capture","value":"Y2gxR01FTA=="},"target":"quilkin::filters::capture","filename":"src/filters/capture.rs"}
{"timestamp":"2022-12-11T14:21:33.586820Z","level":"TRACE","fields":{"message":"read passing packet","id":"quilkin.filters.capture.v1alpha1.Capture"},"target":"quilkin::filters::chain","filename":"src/filters/chain.rs"}
{"timestamp":"2022-12-11T14:21:33.586824Z","level":"TRACE","fields":{"message":"read filtering packet","id":"quilkin.filters.token_router.v1alpha1.TokenRouter"},"target":"quilkin::filters::chain","filename":"src/filters/chain.rs"}
{"timestamp":"2022-12-11T14:21:33.586831Z","level":"TRACE","fields":{"message":"Endpoint matched","endpoint.address":"gke-gameservers-eu1-default-657e92a2-bh5z.europe-west1-c.c.goals-gameservers.internal:21376","token":"Y2gxR01FTA=="},"target":"quilkin::filters::token_router","filename":"src/filters/token_router.rs"}
{"timestamp":"2022-12-11T14:21:33.586840Z","level":"TRACE","fields":{"message":"read passing packet","id":"quilkin.filters.token_router.v1alpha1.TokenRouter"},"target":"quilkin::filters::chain","filename":"src/filters/chain.rs"}
{"timestamp":"2022-12-11T14:21:33.586866Z","level":"TRACE","fields":{"message":"Creating new session"},"target":"quilkin::proxy","filename":"src/proxy.rs","span":{"dest":"gke-gameservers-eu1-default-657e92a2-bh5z.europe-west1-c.c.goals-gameservers.internal:21376","source":"10.4.0.88:7216","name":"session_send_packet"},"spans":[{"dest":"gke-gameservers-eu1-default-657e92a2-bh5z.europe-west1-c.c.goals-gameservers.internal:21376","source":"10.4.0.88:7216","name":"session_send_packet"}]}
{"timestamp":"2022-12-11T14:21:33.586929Z","level":"TRACE","fields":{"message":"registering event source with poller: token=Token(67108867), interests=READABLE | WRITABLE","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":532},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","span":{"name":"new"},"spans":[{"dest":"gke-gameservers-eu1-default-657e92a2-bh5z.europe-west1-c.c.goals-gameservers.internal:21376","source":"10.4.0.88:7216","name":"session_send_packet"},{"name":"new"}]}
{"timestamp":"2022-12-11T14:21:33.609044Z","level":"DEBUG","fields":{"message":"skipping mmdb telemetry, no maxmind database available"},"target":"quilkin::maxmind_db","filename":"src/maxmind_db.rs","span":{"name":"new"},"spans":[{"dest":"gke-gameservers-eu1-default-657e92a2-bh5z.europe-west1-c.c.goals-gameservers.internal:21376","source":"10.4.0.88:7216","name":"session_send_packet"},{"name":"new"}]}
{"timestamp":"2022-12-11T14:21:33.609091Z","level":"DEBUG","fields":{"message":"Session created","source":"10.4.0.88:7216","dest":"Endpoint { address: EndpointAddress { host: Name(\"gke-gameservers-eu1-default-657e92a2-bh5z.europe-west1-c.c.goals-gameservers.internal\"), port: Some(21376) }, metadata: MetadataView { known: Metadata { tokens: {[99, 104, 49, 71, 77, 69, 76]} }, unknown: {} } }"},"target":"quilkin::proxy::sessions","filename":"src/proxy/sessions.rs","span":{"name":"new"},"spans":[{"dest":"gke-gameservers-eu1-default-657e92a2-bh5z.europe-west1-c.c.goals-gameservers.internal:21376","source":"10.4.0.88:7216","name":"session_send_packet"},{"name":"new"}]}
{"timestamp":"2022-12-11T14:21:33.609166Z","level":"TRACE","fields":{"message":"sending packet upstream","dest_address":"gke-gameservers-eu1-default-657e92a2-bh5z.europe-west1-c.c.goals-gameservers.internal:21376","contents":"UElORw=="},"target":"quilkin::proxy::sessions","filename":"src/proxy/sessions.rs","span":{"dest":"gke-gameservers-eu1-default-657e92a2-bh5z.europe-west1-c.c.goals-gameservers.internal:21376","source":"10.4.0.88:7216","name":"session_send_packet"},"spans":[{"dest":"gke-gameservers-eu1-default-657e92a2-bh5z.europe-west1-c.c.goals-gameservers.internal:21376","source":"10.4.0.88:7216","name":"session_send_packet"}]}
{"timestamp":"2022-12-11T14:21:33.609240Z","level":"DEBUG","fields":{"message":"Awaiting incoming packet","source":"10.4.0.88:7216","dest":"Endpoint { address: EndpointAddress { host: Name(\"gke-gameservers-eu1-default-657e92a2-bh5z.europe-west1-c.c.goals-gameservers.internal\"), port: Some(21376) }, metadata: MetadataView { known: Metadata { tokens: {[99, 104, 49, 71, 77, 69, 76]} }, unknown: {} } }"},"target":"quilkin::proxy::sessions","filename":"src/proxy/sessions.rs"}
{"timestamp":"2022-12-11T14:21:33.609357Z","level":"DEBUG","fields":{"message":"Awaiting packet","id":0,"addr":"Ok(0.0.0.0:7000)"},"target":"quilkin::proxy","filename":"src/proxy.rs"}
{"timestamp":"2022-12-11T14:21:33.652967Z","level":"TRACE","fields":{"message":"received packet from upstream","from":"10.4.0.88:21376","dest":"gke-gameservers-eu1-default-657e92a2-bh5z.europe-west1-c.c.goals-gameservers.internal:21376","contents":"8IEBAoAd0qphEI57PcREfIEKl9TUa6M="},"target":"quilkin::proxy::sessions","filename":"src/proxy/sessions.rs"}
{"timestamp":"2022-12-11T14:21:33.653012Z","level":"TRACE","fields":{"message":"write filtering packet","id":"quilkin.filters.token_router.v1alpha1.TokenRouter"},"target":"quilkin::filters::chain","filename":"src/filters/chain.rs"}
{"timestamp":"2022-12-11T14:21:33.653020Z","level":"TRACE","fields":{"message":"write passing packet","id":"quilkin.filters.token_router.v1alpha1.TokenRouter"},"target":"quilkin::filters::chain","filename":"src/filters/chain.rs"}
{"timestamp":"2022-12-11T14:21:33.653023Z","level":"TRACE","fields":{"message":"write filtering packet","id":"quilkin.filters.capture.v1alpha1.Capture"},"target":"quilkin::filters::chain","filename":"src/filters/chain.rs"}
{"timestamp":"2022-12-11T14:21:33.653028Z","level":"TRACE","fields":{"message":"write passing packet","id":"quilkin.filters.capture.v1alpha1.Capture"},"target":"quilkin::filters::chain","filename":"src/filters/chain.rs"}
{"timestamp":"2022-12-11T14:21:33.653035Z","level":"TRACE","fields":{"message":"sending packet downstream","from":"10.4.0.88:21376","dest":"10.4.0.88:7216","contents":"8IEBAoAd0qphEI57PcREfIEKl9TUa6M="},"target":"quilkin::proxy::sessions","filename":"src/proxy/sessions.rs"}
{"timestamp":"2022-12-11T14:21:33.653091Z","level":"DEBUG","fields":{"message":"Awaiting incoming packet","source":"10.4.0.88:7216","dest":"Endpoint { address: EndpointAddress { host: Name(\"gke-gameservers-eu1-default-657e92a2-bh5z.europe-west1-c.c.goals-gameservers.internal\"), port: Some(21376) }, metadata: MetadataView { known: Metadata { tokens: {[99, 104, 49, 71, 77, 69, 76]} }, unknown: {} } }"},"target":"quilkin::proxy::sessions","filename":"src/proxy/sessions.rs"}
{"timestamp":"2022-12-11T14:21:43.095243Z","level":"TRACE","fields":{"message":"registering event source with poller: token=Token(4), interests=READABLE | WRITABLE","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":532},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:21:43.095326Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:43.095343Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:43.095380Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:43.095398Z","level":"TRACE","fields":{"message":"received 107 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:43.095415Z","level":"TRACE","fields":{"message":"Request.parse","bytes":107},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:21:43.095433Z","level":"TRACE","fields":{"message":"Request.parse Complete(107)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:21:43.095458Z","level":"DEBUG","fields":{"message":"parsed 4 headers"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:43.095467Z","level":"DEBUG","fields":{"message":"incoming body is empty"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:43.095472Z","level":"TRACE","fields":{"message":"remote disabling keep-alive"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:43.095489Z","level":"TRACE","fields":{"message":"Server::encode status=200, body=Some(Known(2)), req_method=Some(GET)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"encode_headers"},"spans":[{"name":"encode_headers"}]}
{"timestamp":"2022-12-11T14:21:43.095506Z","level":"TRACE","fields":{"message":"buffer.queue","self.len":75,"buf.len":2},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:43.095574Z","level":"DEBUG","fields":{"message":"flushed 77 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:43.095587Z","level":"TRACE","fields":{"message":"State::close()"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:43.095591Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:43.095611Z","level":"TRACE","fields":{"message":"shut down IO complete"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:43.095622Z","level":"TRACE","fields":{"message":"deregistering event source from poller","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":663},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:21:53.095489Z","level":"TRACE","fields":{"message":"registering event source with poller: token=Token(16777220), interests=READABLE | WRITABLE","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":532},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:21:53.095579Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:53.095592Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:53.095611Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:53.095622Z","level":"TRACE","fields":{"message":"received 107 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:53.095642Z","level":"TRACE","fields":{"message":"Request.parse","bytes":107},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:21:53.095666Z","level":"TRACE","fields":{"message":"Request.parse Complete(107)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:21:53.095688Z","level":"DEBUG","fields":{"message":"parsed 4 headers"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:53.095695Z","level":"DEBUG","fields":{"message":"incoming body is empty"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:53.095699Z","level":"TRACE","fields":{"message":"remote disabling keep-alive"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:53.095715Z","level":"TRACE","fields":{"message":"Server::encode status=200, body=Some(Known(2)), req_method=Some(GET)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"encode_headers"},"spans":[{"name":"encode_headers"}]}
{"timestamp":"2022-12-11T14:21:53.095733Z","level":"TRACE","fields":{"message":"buffer.queue","self.len":75,"buf.len":2},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:53.095784Z","level":"DEBUG","fields":{"message":"flushed 77 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:21:53.095793Z","level":"TRACE","fields":{"message":"State::close()"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:53.095797Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:53.095811Z","level":"TRACE","fields":{"message":"shut down IO complete"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:21:53.095819Z","level":"TRACE","fields":{"message":"deregistering event source from poller","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":663},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:22:03.095543Z","level":"TRACE","fields":{"message":"registering event source with poller: token=Token(33554436), interests=READABLE | WRITABLE","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":532},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:22:03.095631Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:03.095646Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:03.095665Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:03.095674Z","level":"TRACE","fields":{"message":"received 107 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:03.095690Z","level":"TRACE","fields":{"message":"Request.parse","bytes":107},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:22:03.095715Z","level":"TRACE","fields":{"message":"Request.parse Complete(107)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:22:03.095736Z","level":"DEBUG","fields":{"message":"parsed 4 headers"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:03.095741Z","level":"DEBUG","fields":{"message":"incoming body is empty"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:03.095746Z","level":"TRACE","fields":{"message":"remote disabling keep-alive"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:03.095765Z","level":"TRACE","fields":{"message":"Server::encode status=200, body=Some(Known(2)), req_method=Some(GET)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"encode_headers"},"spans":[{"name":"encode_headers"}]}
{"timestamp":"2022-12-11T14:22:03.095783Z","level":"TRACE","fields":{"message":"buffer.queue","self.len":75,"buf.len":2},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:03.095833Z","level":"DEBUG","fields":{"message":"flushed 77 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:03.095841Z","level":"TRACE","fields":{"message":"State::close()"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:03.095854Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:03.095871Z","level":"TRACE","fields":{"message":"shut down IO complete"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:03.095878Z","level":"TRACE","fields":{"message":"deregistering event source from poller","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":663},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:22:13.095315Z","level":"TRACE","fields":{"message":"registering event source with poller: token=Token(50331652), interests=READABLE | WRITABLE","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":532},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:22:13.095410Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:13.095426Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:13.095446Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:13.095462Z","level":"TRACE","fields":{"message":"received 107 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:13.095479Z","level":"TRACE","fields":{"message":"Request.parse","bytes":107},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:22:13.095502Z","level":"TRACE","fields":{"message":"Request.parse Complete(107)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:22:13.095523Z","level":"DEBUG","fields":{"message":"parsed 4 headers"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:13.095530Z","level":"DEBUG","fields":{"message":"incoming body is empty"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:13.095535Z","level":"TRACE","fields":{"message":"remote disabling keep-alive"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:13.095552Z","level":"TRACE","fields":{"message":"Server::encode status=200, body=Some(Known(2)), req_method=Some(GET)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"encode_headers"},"spans":[{"name":"encode_headers"}]}
{"timestamp":"2022-12-11T14:22:13.095566Z","level":"TRACE","fields":{"message":"buffer.queue","self.len":75,"buf.len":2},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:13.095635Z","level":"DEBUG","fields":{"message":"flushed 77 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:13.095643Z","level":"TRACE","fields":{"message":"State::close()"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:13.095648Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:13.095665Z","level":"TRACE","fields":{"message":"shut down IO complete"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:13.095674Z","level":"TRACE","fields":{"message":"deregistering event source from poller","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":663},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:22:23.095807Z","level":"TRACE","fields":{"message":"registering event source with poller: token=Token(67108868), interests=READABLE | WRITABLE","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":532},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:22:23.095889Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:23.095902Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:23.095924Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:23.095947Z","level":"TRACE","fields":{"message":"received 107 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:23.095970Z","level":"TRACE","fields":{"message":"Request.parse","bytes":107},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:22:23.096022Z","level":"TRACE","fields":{"message":"Request.parse Complete(107)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:22:23.096047Z","level":"DEBUG","fields":{"message":"parsed 4 headers"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:23.096057Z","level":"DEBUG","fields":{"message":"incoming body is empty"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:23.096063Z","level":"TRACE","fields":{"message":"remote disabling keep-alive"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:23.096085Z","level":"TRACE","fields":{"message":"Server::encode status=200, body=Some(Known(2)), req_method=Some(GET)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"encode_headers"},"spans":[{"name":"encode_headers"}]}
{"timestamp":"2022-12-11T14:22:23.096104Z","level":"TRACE","fields":{"message":"buffer.queue","self.len":75,"buf.len":2},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:23.096156Z","level":"DEBUG","fields":{"message":"flushed 77 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:23.096167Z","level":"TRACE","fields":{"message":"State::close()"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:23.096171Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:23.096188Z","level":"TRACE","fields":{"message":"shut down IO complete"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:23.096202Z","level":"TRACE","fields":{"message":"deregistering event source from poller","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":663},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:22:30.794420Z","level":"TRACE","fields":{"message":"received packet from downstream","id":0,"size":11,"source":"10.4.0.85:4688","contents":"UElOR3kxeW5kdno="},"target":"quilkin::proxy","filename":"src/proxy.rs"}
{"timestamp":"2022-12-11T14:22:30.794466Z","level":"TRACE","fields":{"message":"read filtering packet","id":"quilkin.filters.capture.v1alpha1.Capture"},"target":"quilkin::filters::chain","filename":"src/filters/chain.rs"}
{"timestamp":"2022-12-11T14:22:30.794476Z","level":"TRACE","fields":{"message":"captured value","key":"quilkin.dev/capture","value":"eTF5bmR2eg=="},"target":"quilkin::filters::capture","filename":"src/filters/capture.rs"}
{"timestamp":"2022-12-11T14:22:30.794483Z","level":"TRACE","fields":{"message":"read passing packet","id":"quilkin.filters.capture.v1alpha1.Capture"},"target":"quilkin::filters::chain","filename":"src/filters/chain.rs"}
{"timestamp":"2022-12-11T14:22:30.794486Z","level":"TRACE","fields":{"message":"read filtering packet","id":"quilkin.filters.token_router.v1alpha1.TokenRouter"},"target":"quilkin::filters::chain","filename":"src/filters/chain.rs"}
{"timestamp":"2022-12-11T14:22:30.794527Z","level":"TRACE","fields":{"message":"No endpoint matched token","token":"eTF5bmR2eg=="},"target":"quilkin::filters::token_router","filename":"src/filters/token_router.rs"}
{"timestamp":"2022-12-11T14:22:30.794537Z","level":"TRACE","fields":{"message":"read dropping packet","id":"quilkin.filters.token_router.v1alpha1.TokenRouter"},"target":"quilkin::filters::chain","filename":"src/filters/chain.rs"}
{"timestamp":"2022-12-11T14:22:30.794567Z","level":"DEBUG","fields":{"message":"Awaiting packet","id":0,"addr":"Ok(0.0.0.0:7000)"},"target":"quilkin::proxy","filename":"src/proxy.rs"}
{"timestamp":"2022-12-11T14:22:33.095720Z","level":"TRACE","fields":{"message":"registering event source with poller: token=Token(83886084), interests=READABLE | WRITABLE","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":532},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:22:33.095802Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:33.095814Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:33.095847Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:33.095860Z","level":"TRACE","fields":{"message":"received 107 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:33.095879Z","level":"TRACE","fields":{"message":"Request.parse","bytes":107},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:22:33.095901Z","level":"TRACE","fields":{"message":"Request.parse Complete(107)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:22:33.095922Z","level":"DEBUG","fields":{"message":"parsed 4 headers"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:33.095926Z","level":"DEBUG","fields":{"message":"incoming body is empty"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:33.095930Z","level":"TRACE","fields":{"message":"remote disabling keep-alive"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:33.095972Z","level":"TRACE","fields":{"message":"Server::encode status=200, body=Some(Known(2)), req_method=Some(GET)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"encode_headers"},"spans":[{"name":"encode_headers"}]}
{"timestamp":"2022-12-11T14:22:33.095998Z","level":"TRACE","fields":{"message":"buffer.queue","self.len":75,"buf.len":2},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:33.096054Z","level":"DEBUG","fields":{"message":"flushed 77 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:33.096064Z","level":"TRACE","fields":{"message":"State::close()"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:33.096068Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:33.096084Z","level":"TRACE","fields":{"message":"shut down IO complete"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:33.096092Z","level":"TRACE","fields":{"message":"deregistering event source from poller","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":663},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:22:43.095202Z","level":"TRACE","fields":{"message":"registering event source with poller: token=Token(100663300), interests=READABLE | WRITABLE","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":532},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:22:43.095293Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:43.095307Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:43.095329Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:43.095339Z","level":"TRACE","fields":{"message":"received 107 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:43.095363Z","level":"TRACE","fields":{"message":"Request.parse","bytes":107},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:22:43.095385Z","level":"TRACE","fields":{"message":"Request.parse Complete(107)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:22:43.095411Z","level":"DEBUG","fields":{"message":"parsed 4 headers"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:43.095422Z","level":"DEBUG","fields":{"message":"incoming body is empty"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:43.095428Z","level":"TRACE","fields":{"message":"remote disabling keep-alive"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:43.095445Z","level":"TRACE","fields":{"message":"Server::encode status=200, body=Some(Known(2)), req_method=Some(GET)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"encode_headers"},"spans":[{"name":"encode_headers"}]}
{"timestamp":"2022-12-11T14:22:43.095466Z","level":"TRACE","fields":{"message":"buffer.queue","self.len":75,"buf.len":2},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:43.095542Z","level":"DEBUG","fields":{"message":"flushed 77 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:43.095555Z","level":"TRACE","fields":{"message":"State::close()"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:43.095560Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:43.095586Z","level":"TRACE","fields":{"message":"shut down IO complete"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:43.095597Z","level":"TRACE","fields":{"message":"deregistering event source from poller","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":663},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:22:53.095582Z","level":"TRACE","fields":{"message":"registering event source with poller: token=Token(117440516), interests=READABLE | WRITABLE","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":532},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:22:53.095664Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:53.095675Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:53.095686Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:53.095699Z","level":"TRACE","fields":{"message":"received 107 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:53.095715Z","level":"TRACE","fields":{"message":"Request.parse","bytes":107},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:22:53.095739Z","level":"TRACE","fields":{"message":"Request.parse Complete(107)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:22:53.095763Z","level":"DEBUG","fields":{"message":"parsed 4 headers"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:53.095768Z","level":"DEBUG","fields":{"message":"incoming body is empty"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:53.095773Z","level":"TRACE","fields":{"message":"remote disabling keep-alive"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:53.095789Z","level":"TRACE","fields":{"message":"Server::encode status=200, body=Some(Known(2)), req_method=Some(GET)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"encode_headers"},"spans":[{"name":"encode_headers"}]}
{"timestamp":"2022-12-11T14:22:53.095806Z","level":"TRACE","fields":{"message":"buffer.queue","self.len":75,"buf.len":2},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:53.095869Z","level":"DEBUG","fields":{"message":"flushed 77 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:22:53.095878Z","level":"TRACE","fields":{"message":"State::close()"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:53.095882Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:53.095899Z","level":"TRACE","fields":{"message":"shut down IO complete"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:22:53.095907Z","level":"TRACE","fields":{"message":"deregistering event source from poller","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":663},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:22:58.347396Z","level":"DEBUG","fields":{"message":"pruning expired sessions"},"target":"quilkin::proxy::sessions::manager","filename":"src/proxy/sessions/manager.rs"}
{"timestamp":"2022-12-11T14:22:58.347462Z","level":"DEBUG","fields":{"message":"Session closed","source":"10.4.0.88:7216","dest_address":"gke-gameservers-eu1-default-657e92a2-bh5z.europe-west1-c.c.goals-gameservers.internal:21376"},"target":"quilkin::proxy::sessions","filename":"src/proxy/sessions.rs"}
{"timestamp":"2022-12-11T14:22:58.347484Z","level":"DEBUG","fields":{"message":"Closing Session","source":"10.4.0.88:7216","dest":"Endpoint { address: EndpointAddress { host: Name(\"gke-gameservers-eu1-default-657e92a2-bh5z.europe-west1-c.c.goals-gameservers.internal\"), port: Some(21376) }, metadata: MetadataView { known: Metadata { tokens: {[99, 104, 49, 71, 77, 69, 76]} }, unknown: {} } }"},"target":"quilkin::proxy::sessions","filename":"src/proxy/sessions.rs"}
{"timestamp":"2022-12-11T14:22:58.347519Z","level":"TRACE","fields":{"message":"deregistering event source from poller","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":663},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:23:03.095778Z","level":"TRACE","fields":{"message":"registering event source with poller: token=Token(83886083), interests=READABLE | WRITABLE","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":532},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:23:03.095871Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:23:03.095888Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:23:03.095909Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:23:03.095925Z","level":"TRACE","fields":{"message":"received 107 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:23:03.095970Z","level":"TRACE","fields":{"message":"Request.parse","bytes":107},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:23:03.095992Z","level":"TRACE","fields":{"message":"Request.parse Complete(107)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:23:03.096015Z","level":"DEBUG","fields":{"message":"parsed 4 headers"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:23:03.096020Z","level":"DEBUG","fields":{"message":"incoming body is empty"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:23:03.096024Z","level":"TRACE","fields":{"message":"remote disabling keep-alive"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:23:03.096042Z","level":"TRACE","fields":{"message":"Server::encode status=200, body=Some(Known(2)), req_method=Some(GET)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"encode_headers"},"spans":[{"name":"encode_headers"}]}
{"timestamp":"2022-12-11T14:23:03.096062Z","level":"TRACE","fields":{"message":"buffer.queue","self.len":75,"buf.len":2},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:23:03.096127Z","level":"DEBUG","fields":{"message":"flushed 77 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:23:03.096134Z","level":"TRACE","fields":{"message":"State::close()"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:23:03.096138Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:23:03.096155Z","level":"TRACE","fields":{"message":"shut down IO complete"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:23:03.096162Z","level":"TRACE","fields":{"message":"deregistering event source from poller","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":663},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:23:13.095060Z","level":"TRACE","fields":{"message":"registering event source with poller: token=Token(100663299), interests=READABLE | WRITABLE","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":532},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
{"timestamp":"2022-12-11T14:23:13.095148Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:23:13.095163Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:23:13.095186Z","level":"TRACE","fields":{"message":"Conn::read_head"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:23:13.095200Z","level":"TRACE","fields":{"message":"received 107 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:23:13.095218Z","level":"TRACE","fields":{"message":"Request.parse","bytes":107},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:23:13.095240Z","level":"TRACE","fields":{"message":"Request.parse Complete(107)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"parse_headers"},"spans":[{"name":"parse_headers"}]}
{"timestamp":"2022-12-11T14:23:13.095260Z","level":"DEBUG","fields":{"message":"parsed 4 headers"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:23:13.095266Z","level":"DEBUG","fields":{"message":"incoming body is empty"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:23:13.095270Z","level":"TRACE","fields":{"message":"remote disabling keep-alive"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:23:13.095286Z","level":"TRACE","fields":{"message":"Server::encode status=200, body=Some(Known(2)), req_method=Some(GET)"},"target":"hyper::proto::h1::role","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/role.rs","span":{"name":"encode_headers"},"spans":[{"name":"encode_headers"}]}
{"timestamp":"2022-12-11T14:23:13.095302Z","level":"TRACE","fields":{"message":"buffer.queue","self.len":75,"buf.len":2},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:23:13.095369Z","level":"DEBUG","fields":{"message":"flushed 77 bytes"},"target":"hyper::proto::h1::io","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/io.rs"}
{"timestamp":"2022-12-11T14:23:13.095377Z","level":"TRACE","fields":{"message":"State::close()"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:23:13.095380Z","level":"TRACE","fields":{"message":"flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:23:13.095394Z","level":"TRACE","fields":{"message":"shut down IO complete"},"target":"hyper::proto::h1::conn","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/proto/h1/conn.rs"}
{"timestamp":"2022-12-11T14:23:13.095400Z","level":"TRACE","fields":{"message":"deregistering event source from poller","log.target":"mio::poll","log.module_path":"mio::poll","log.file":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs","log.line":663},"target":"mio::poll","filename":"/usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs"}
markmandel commented 1 year ago

To me the interesting part of the proxy log is here, it warns twice that it can't connect to the xDS server, but we don't see anymore attempts to reconnect after the second try.

So I was going through the code to see if I could find what is going on, so thought I'd document the retry functionality so other people could poke through, and see if they could see something I couldn't see:

Retry on every attempt at connection. We should see multiple retries here when the initial connection drops.

https://github.com/googleforgames/quilkin/blob/a9cf174fc2f260212ac70c75709217d6f90973a6/src/xds/client.rs#L112-L128

But all we see if 1 attempt, which is weird:

{"timestamp":"2022-12-11T14:21:11.896994Z","level":"INFO","fields":{"message":"Retrying to connect","attempt":1},"target":"quilkin::xds::client","filename":"src/xds/client.rs","span":{"name":"xds_client_connect"},"spans":[{"name":"connect"},{"name":"handle_discovery_response"},{"name":"xds_client_connect"}]}

The xds client runs an infinite loop inside a tokio::spawn(...): https://github.com/googleforgames/quilkin/blob/a9cf174fc2f260212ac70c75709217d6f90973a6/src/xds/client.rs#L165

Which, if the connection drops, goes back to to call the connection function above: https://github.com/googleforgames/quilkin/blob/a9cf174fc2f260212ac70c75709217d6f90973a6/src/xds/client.rs#L232-L236

Which leads me to think there is something broken in the retry in the initial connection, but I can't see anything when I look at it 🤔

(The connection dropping is another issue, but one problem at a time)

markmandel commented 1 year ago

Quick thought that just came to mind -- if the retry ends up in a state where it's delaying for a really long time (or indefinitely) - that would explain what we see here I think.

I'm figuring it's not moving into RetryPolicy::Break, because then we would see a lot of log messages of "Lost connection to xDS, retrying", which we don't see.

I can't see where this might be in the retry config, but that's my theory. Might be worth adding some tracing into retry delays?

The only other idea I have, is that the connection hangs on the retry, and doesn't have a timeout value, and this blocks the whole process as well.

markmandel commented 1 year ago

@luckyswede - you may want to trythe image from https://github.com/googleforgames/quilkin/pull/664#issuecomment-1350347831

Not 100% sure it'll solve the problem, but should at least give us a bit more info.

luckyswede commented 1 year ago

@markmandel I've set up the 664 image now, will keep u posted

markmandel commented 1 year ago

Just wanted to check in, since it's been a week.

If it's any consolation - I also found the same thing on an install I had on a 0.4.0 release I had left sit for a few days. So you are not alone.

luckyswede commented 1 year ago

@markmandel Thanks for checking in. I have not experienced this issue any more since running the code from #664 🎉 I left it running for several days, and I also tried to trigger the bug by killing the manage instance - but it still works 👍.

markmandel commented 1 year ago

Awesome! Sounds kind we should cut a 0.5.0 release soon then, and make it official.

XAMPPRocky commented 1 year ago

@markmandel I'm away till the new year, but feel free to cut a new release whenever you want.

markmandel commented 1 year ago

@markmandel I'm away till the new year, but feel free to cut a new release whenever you want.

@XAMPPRocky I'll start a ticket - I'd like to get the xDS Quickstart in the release too - but it can wait until you are back I figure - no reason to rush.

XAMPPRocky commented 1 year ago

Oh I already read through that and it LGTM, just forgot to hit approve.

markmandel commented 1 year ago

In which case, I'm going to close this issue. If it rears it's head again, please file a new ticket, and we'll dig in again.