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.28k stars 91 forks source link

Flaky Test: relay::tests::agones_token_router #877

Open markmandel opened 9 months ago

markmandel commented 9 months ago

Tracking bug for flakiness in the Agones integration test.

Test seems to consistently fail here, when it does fail: https://github.com/googleforgames/quilkin/blob/6e0adc902194155ec867a3fadd5bc984331f053b/agones/src/relay.rs#L312

Something about the relay agent not coming up as ready for some reason.

markmandel commented 9 months ago

On a failure, we do see the following:

❯ kubectl get pods -n 1701124569
NAME                                    READY   STATUS    RESTARTS   AGE
quilkin-agones-agent-6fddc959b5-mklss   0/1     Running   0          3m38s
quilkin-relay-agones-5bb9df5765-kp4ks   1/1     Running   0          3m42s

Checking the logs for quilkin-agones-agent-6fddc959b5-mklss we see the following:

❯ kubectl logs -n 1701124569 quilkin-agones-agent-6fddc959b5-mklss
{"timestamp":"2023-11-27T22:36:14.427641Z","level":"INFO","fields":{"message":"Starting Quilkin","version":"0.8.0-dev"},"target":"quilkin::cli","filename":"src/cli.rs"}
{"timestamp":"2023-11-27T22:36:14.427716Z","level":"DEBUG","fields":{"message":"config parameters","cli":"Cli { no_admin: false, config: \"quilkin.yaml\", admin_address: None, quiet: false, command: Agent(Agent { qcmp_port: 7600, relay: [Endpoint], region: None, zone: None, sub_zone: None, provider: Some(Agones { config_namespace: \"1701124569\", gameservers_namespace: \"1701124569\" }), idle_request_interval_secs: 30 }), log_format: Auto }"},"target":"quilkin::cli","filename":"src/cli.rs"}
{"timestamp":"2023-11-27T22:36:14.427807Z","level":"DEBUG","fields":{"message":"provided path not found","path":"quilkin.yaml"},"target":"quilkin::cli","filename":"src/cli.rs"}
{"timestamp":"2023-11-27T22:36:14.427832Z","level":"DEBUG","fields":{"message":"/etc path not found","path":"quilkin.yaml"},"target":"quilkin::cli","filename":"src/cli.rs"}
{"timestamp":"2023-11-27T22:36:14.428180Z","level":"INFO","fields":{"message":"Starting admin endpoint","address":"[::]:8000"},"target":"quilkin::cli::admin","filename":"src/cli/admin.rs"}
{"timestamp":"2023-11-27T22:36:14.428566Z","level":"INFO","fields":{"message":"attempting to connect to `http://quilkin-relay-agones:7900/`"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"client_connect"},"spans":[{"servers":"[Endpoint]","name":"connect"},{"name":"client_connect"}]}
{"timestamp":"2023-11-27T22:36:14.439625Z","level":"DEBUG","fields":{"message":"received restart event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]}
{"timestamp":"2023-11-27T22:36:14.439683Z","level":"TRACE","fields":{"message":"Restarting with endpoints","endpoints":"[]"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]}
{"timestamp":"2023-11-27T22:36:14.439701Z","level":"DEBUG","fields":{"message":"changed detected","watchers":0},"target":"quilkin::config::watch","filename":"src/config/watch.rs","span":{"name":"task"},"spans":[{"name":"task"}]}
{"timestamp":"2023-11-27T22:36:14.443570Z","level":"TRACE","fields":{"message":"new configmap event"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]}
{"timestamp":"2023-11-27T22:36:14.444053Z","level":"TRACE","fields":{"message":"storing new value"},"target":"quilkin::config::slot","filename":"src/config/slot.rs","span":{"name":"task"},"spans":[{"name":"task"}]}
{"timestamp":"2023-11-27T22:36:19.429223Z","level":"INFO","fields":{"message":"Retrying to connect","attempt":1},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"client_connect"},"spans":[{"servers":"[Endpoint]","name":"connect"},{"name":"client_connect"}]}
{"timestamp":"2023-11-27T22:36:19.429304Z","level":"WARN","fields":{"message":"Unable to connect to the XDS server","error":"tonic::transport::Error(Transport, hyper::Error(Connect, Custom { kind: TimedOut, error: Elapsed(()) }))"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"client_connect"},"spans":[{"servers":"[Endpoint]","name":"connect"},{"name":"client_connect"}]}
{"timestamp":"2023-11-27T22:36:21.476827Z","level":"INFO","fields":{"message":"attempting to connect to `http://quilkin-relay-agones:7900/`"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"client_connect"},"spans":[{"servers":"[Endpoint]","name":"connect"},{"name":"client_connect"}]}
{"timestamp":"2023-11-27T22:36:21.479668Z","level":"INFO","fields":{"message":"Connected to management server"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"servers":"[Endpoint]","name":"connect"},"spans":[{"servers":"[Endpoint]","name":"connect"}]}
{"timestamp":"2023-11-27T22:36:21.479730Z","level":"TRACE","fields":{"message":"spawning stream background task"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs"}
{"timestamp":"2023-11-27T22:36:21.479808Z","level":"TRACE","fields":{"message":"starting relay client stream task"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]}
{"timestamp":"2023-11-27T22:36:21.480924Z","level":"TRACE","fields":{"message":"Adding new watcher"},"target":"quilkin::config::slot","filename":"src/config/slot.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]}
{"timestamp":"2023-11-27T22:36:21.480957Z","level":"TRACE","fields":{"message":"starting stream"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]}
{"timestamp":"2023-11-27T22:36:21.480984Z","level":"DEBUG","fields":{"message":"waiting for changes","watcher":"Receiver { shared: Shared { value: RwLock(PhantomData<std::sync::rwlock::RwLock<alloc::sync::Arc<quilkin::net::cluster::ClusterMap>>>, RwLock { data: ClusterMap { map: {None: EndpointSet { endpoints: {}, version: 1 }}, num_endpoints: 0, version: 1 } }), version: Version(2), is_closed: false, ref_count_rx: 1 }, version: Version(2) }"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs"}

Which shows that while it did fail to connect to the relay service, it eventually connected, which means it should have kicked over to being ready 🤔

markmandel commented 9 months ago

Also, just in case I need it again, here's my test rig. Insert your own dev image.

#!/bin/bash

set -eo pipefail

export RUST_BACKTRACE=1
export IMAGE_TAG=us-docker.pkg.dev/quilkin-mark-dev/release/quilkin:0.8.0-dev-2be3696

for i in {1..100}
do
  echo "🔥 Test Run: $i"
  cargo test --color=always --lib relay::tests::agones_token_router -- --nocapture --exact
done
markmandel commented 9 months ago

Put some extra debugging in agent.rs so we could see which readiness health check is failing:

❯ kubectl logs -n 1701128813 quilkin-agones-agent-846b858654-bwvk6
{"timestamp":"2023-11-27T23:46:58.251392Z","level":"INFO","fields":{"message":"Starting Quilkin","version":"0.8.0-dev"},"target":"quilkin::cli","filename":"src/cli.rs"}
{"timestamp":"2023-11-27T23:46:58.251463Z","level":"DEBUG","fields":{"message":"config parameters","cli":"Cli { no_admin: false, config: \"quilkin.yaml\", admin_address: None, quiet: false, command: Agent(Agent { qcmp_port: 7600, relay: [Endpoint], region: None, zone: None, sub_zone: None, provider: Some(Agones { config_namespace: \"1701128813\", gameservers_namespace: \"1701128813\" }), idle_request_interval_secs: 30 }), log_format: Auto }"},"target":"quilkin::cli","filename":"src/cli.rs"}
{"timestamp":"2023-11-27T23:46:58.251548Z","level":"DEBUG","fields":{"message":"provided path not found","path":"quilkin.yaml"},"target":"quilkin::cli","filename":"src/cli.rs"}
{"timestamp":"2023-11-27T23:46:58.251584Z","level":"DEBUG","fields":{"message":"/etc path not found","path":"quilkin.yaml"},"target":"quilkin::cli","filename":"src/cli.rs"}
{"timestamp":"2023-11-27T23:46:58.252020Z","level":"INFO","fields":{"message":"Starting admin endpoint","address":"[::]:8000"},"target":"quilkin::cli::admin","filename":"src/cli/admin.rs"}
{"timestamp":"2023-11-27T23:46:58.252455Z","level":"INFO","fields":{"message":"attempting to connect to `http://quilkin-relay-agones:7900/`"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"client_connect"},"spans":[{"servers":"[Endpoint]","name":"connect"},{"name":"client_connect"}]}
{"timestamp":"2023-11-27T23:46:58.256881Z","level":"INFO","fields":{"message":"Connected to management server"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"servers":"[Endpoint]","name":"connect"},"spans":[{"servers":"[Endpoint]","name":"connect"}]}
{"timestamp":"2023-11-27T23:46:58.256948Z","level":"TRACE","fields":{"message":"spawning stream background task"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs"}
{"timestamp":"2023-11-27T23:46:58.257040Z","level":"TRACE","fields":{"message":"starting relay client stream task"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]}
{"timestamp":"2023-11-27T23:46:58.258228Z","level":"TRACE","fields":{"message":"Adding new watcher"},"target":"quilkin::config::slot","filename":"src/config/slot.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]}
{"timestamp":"2023-11-27T23:46:58.258276Z","level":"TRACE","fields":{"message":"starting stream"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]}
{"timestamp":"2023-11-27T23:46:58.258318Z","level":"DEBUG","fields":{"message":"waiting for changes","watcher":"Receiver { shared: Shared { value: RwLock(PhantomData<std::sync::rwlock::RwLock<alloc::sync::Arc<quilkin::net::cluster::ClusterMap>>>, RwLock { data: ClusterMap { map: {}, num_endpoints: 0, version: 0 } }), version: Version(0), is_closed: false, ref_count_rx: 1 }, version: Version(0) }"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs"}
{"timestamp":"2023-11-27T23:46:58.260993Z","level":"DEBUG","fields":{"message":"received restart event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]}
{"timestamp":"2023-11-27T23:46:58.261049Z","level":"TRACE","fields":{"message":"Restarting with endpoints","endpoints":"[]"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]}
{"timestamp":"2023-11-27T23:46:58.261066Z","level":"DEBUG","fields":{"message":"changed detected","watchers":1},"target":"quilkin::config::watch","filename":"src/config/watch.rs","span":{"name":"task"},"spans":[{"name":"task"}]}
{"timestamp":"2023-11-27T23:46:58.261210Z","level":"DEBUG","fields":{"message":"pushing update","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","watchers":1},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs"}
{"timestamp":"2023-11-27T23:46:58.261232Z","level":"DEBUG","fields":{"message":"waiting for changes","watcher":"Receiver { shared: Shared { value: RwLock(PhantomData<std::sync::rwlock::RwLock<alloc::sync::Arc<quilkin::net::cluster::ClusterMap>>>, RwLock { data: ClusterMap { map: {None: EndpointSet { endpoints: {}, version: 1 }}, num_endpoints: 0, version: 1 } }), version: Version(2), is_closed: false, ref_count_rx: 1 }, version: Version(2) }"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs"}
{"timestamp":"2023-11-27T23:46:58.261856Z","level":"TRACE","fields":{"message":"new configmap event"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]}
{"timestamp":"2023-11-27T23:46:58.262169Z","level":"TRACE","fields":{"message":"storing new value"},"target":"quilkin::config::slot","filename":"src/config/slot.rs","span":{"name":"task"},"spans":[{"name":"task"}]}
{"timestamp":"2023-11-27T23:46:58.262185Z","level":"TRACE","fields":{"message":"calling watcher"},"target":"quilkin::config::slot","filename":"src/config/slot.rs","span":{"name":"task"},"spans":[{"name":"task"}]}
{"timestamp":"2023-11-27T23:46:58.262192Z","level":"DEBUG","fields":{"message":"pushing update","resource_type":"type.googleapis.com/envoy.config.listener.v3.Listener","watchers":1},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"name":"task"},"spans":[{"name":"task"}]}
{"timestamp":"2023-11-27T23:47:01.636281Z","level":"TRACE","fields":{"message":"Agent health check","provider_healthy":"true","relay_healthy":"false"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"}
{"timestamp":"2023-11-27T23:47:02.635294Z","level":"TRACE","fields":{"message":"Agent health check","provider_healthy":"true","relay_healthy":"false"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"}

And it's RuntimeConfig.relay_is_healthy is false!

But interestingly, this failure has no xDS connection issue on this failure, it something else.

Side note: Might be useful for health/readiness endpoints to return a json packet as to why they are unhealthy.

markmandel commented 9 months ago

More debugging logging, current theory is that something is blocking in this block, before the code gets to here:

https://github.com/googleforgames/quilkin/blob/2be3696dde66590d00a07fc02fa22cb8b3c8dd5c/src/net/xds/client.rs#L428-L430

Next step is to narrow down what blocks before we can move to ready.

markmandel commented 9 months ago

End of day, but can confirm, this line here blocks and never returns in some circumstances.

https://github.com/googleforgames/quilkin/blob/2be3696dde66590d00a07fc02fa22cb8b3c8dd5c/src/net/xds/client.rs#L427

Will next dig into why that is, but @XAMPPRocky if you have suggestions also happy to take them.

markmandel commented 9 months ago

May be related:

https://github.com/googleforgames/quilkin/blob/8197bdd23b495d13b1aad816254f096796e91134/src/cli.rs#L262

Apparently is flaky as well.

XAMPPRocky commented 9 months ago

Will next dig into why that is, but @XAMPPRocky if you have suggestions also happy to take them.

I don't unfortunately, I can't replicate in prod, I think it might just be a timing thing with the threads.

markmandel commented 9 months ago

No worries - digging in. At least I can reproduce it pretty reliably now.

markmandel commented 9 months ago

May be related:

https://github.com/googleforgames/quilkin/blob/8197bdd23b495d13b1aad816254f096796e91134/src/cli.rs#L262

Apparently is flaky as well.

Just ran this unit test 300 times off main and it passes... so I think this might be a red herring, and maybe only related to #873's implementation. Redirecting efforts back to quilkin/src/net/xds/client.rs

markmandel commented 9 months ago

Okay, this is tricky.

Here's what a successful log looks like for an agent (with enhanced debugging from my branch): https://github.com/markmandel/quilkin/tree/flaky/agones_token_router

Full Log ``` ❯ kubectl logs -n 1701214854 quilkin-agones-agent-c48c946cc-mxh7d {"timestamp":"2023-11-28T23:41:00.753047Z","level":"INFO","fields":{"message":"starting Quilkin","version":"0.8.0-dev","commit":"15ee1234cbafe661601951647ddd273dfaac15ce"},"target":"quilkin::cli","filename":"src/cli.rs"} {"timestamp":"2023-11-28T23:41:00.753120Z","level":"DEBUG","fields":{"message":"config parameters","cli":"Cli { no_admin: false, config: \"quilkin.yaml\", admin_address: None, quiet: false, command: Agent(Agent { qcmp_port: 7600, relay: [Endpoint], region: None, zone: None, sub_zone: None, provider: Some(Agones { config_namespace: \"1701214854\", gameservers_namespace: \"1701214854\" }), idle_request_interval_secs: 30 }), log_format: Auto }"},"target":"quilkin::cli","filename":"src/cli.rs"} {"timestamp":"2023-11-28T23:41:00.753282Z","level":"DEBUG","fields":{"message":"provided path not found","path":"quilkin.yaml"},"target":"quilkin::cli","filename":"src/cli.rs"} {"timestamp":"2023-11-28T23:41:00.753313Z","level":"DEBUG","fields":{"message":"/etc path not found","path":"quilkin.yaml"},"target":"quilkin::cli","filename":"src/cli.rs"} {"timestamp":"2023-11-28T23:41:00.753700Z","level":"INFO","fields":{"message":"starting admin endpoint","address":"[::]:8000"},"target":"quilkin::cli::admin","filename":"src/cli/admin.rs"} {"timestamp":"2023-11-28T23:41:00.754163Z","level":"INFO","fields":{"message":"attempting to connect to `http://quilkin-relay-agones:7900/`"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"client_connect"},"spans":[{"servers":"[Endpoint]","name":"connect"},{"name":"client_connect"}]} {"timestamp":"2023-11-28T23:41:00.757524Z","level":"INFO","fields":{"message":"retrying to connect","attempt":1},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"client_connect"},"spans":[{"servers":"[Endpoint]","name":"connect"},{"name":"client_connect"}]} {"timestamp":"2023-11-28T23:41:00.757604Z","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::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"client_connect"},"spans":[{"servers":"[Endpoint]","name":"connect"},{"name":"client_connect"}]} {"timestamp":"2023-11-28T23:41:00.761339Z","level":"DEBUG","fields":{"message":"received restart event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:00.761407Z","level":"TRACE","fields":{"message":"restarting with endpoints","endpoints":"[]"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:00.761428Z","level":"DEBUG","fields":{"message":"changed detected","watchers":0},"target":"quilkin::config::watch","filename":"src/config/watch.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:00.764474Z","level":"TRACE","fields":{"message":"new configmap event"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:00.764826Z","level":"TRACE","fields":{"message":"storing new value"},"target":"quilkin::config::slot","filename":"src/config/slot.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:01.630325Z","level":"INFO","fields":{"message":"attempting to connect to `http://quilkin-relay-agones:7900/`"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"client_connect"},"spans":[{"servers":"[Endpoint]","name":"connect"},{"name":"client_connect"}]} {"timestamp":"2023-11-28T23:41:01.633328Z","level":"INFO","fields":{"message":"retrying to connect","attempt":2},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"client_connect"},"spans":[{"servers":"[Endpoint]","name":"connect"},{"name":"client_connect"}]} {"timestamp":"2023-11-28T23:41:01.633371Z","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::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"client_connect"},"spans":[{"servers":"[Endpoint]","name":"connect"},{"name":"client_connect"}]} {"timestamp":"2023-11-28T23:41:03.106148Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"false"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:03.403935Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"false"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:03.850956Z","level":"INFO","fields":{"message":"attempting to connect to `http://quilkin-relay-agones:7900/`"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"client_connect"},"spans":[{"servers":"[Endpoint]","name":"connect"},{"name":"client_connect"}]} {"timestamp":"2023-11-28T23:41:03.852518Z","level":"INFO","fields":{"message":"retrying to connect","attempt":3},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"client_connect"},"spans":[{"servers":"[Endpoint]","name":"connect"},{"name":"client_connect"}]} {"timestamp":"2023-11-28T23:41:03.852582Z","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::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"client_connect"},"spans":[{"servers":"[Endpoint]","name":"connect"},{"name":"client_connect"}]} {"timestamp":"2023-11-28T23:41:04.106347Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"false"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:05.105918Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"false"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:06.105589Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"false"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:06.527499Z","level":"INFO","fields":{"message":"attempting to connect to `http://quilkin-relay-agones:7900/`"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"client_connect"},"spans":[{"servers":"[Endpoint]","name":"connect"},{"name":"client_connect"}]} {"timestamp":"2023-11-28T23:41:06.529348Z","level":"INFO","fields":{"message":"connected to management server"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"servers":"[Endpoint]","name":"connect"},"spans":[{"servers":"[Endpoint]","name":"connect"}]} {"timestamp":"2023-11-28T23:41:06.529395Z","level":"TRACE","fields":{"message":"spawning stream background task"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs"} {"timestamp":"2023-11-28T23:41:06.529428Z","level":"TRACE","fields":{"message":"starting relay client stream task"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]} {"timestamp":"2023-11-28T23:41:06.529462Z","level":"TRACE","fields":{"message":"sending request"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]} {"timestamp":"2023-11-28T23:41:06.529477Z","level":"TRACE","fields":{"message":"streaming requests"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]} {"timestamp":"2023-11-28T23:41:06.530216Z","level":"TRACE","fields":{"message":"control plane: creating from config"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]} {"timestamp":"2023-11-28T23:41:06.530248Z","level":"TRACE","fields":{"message":"adding new watcher"},"target":"quilkin::config::slot","filename":"src/config/slot.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]} {"timestamp":"2023-11-28T23:41:06.530263Z","level":"TRACE","fields":{"message":"control plane: streaming aggregated resources"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]} {"timestamp":"2023-11-28T23:41:06.530292Z","level":"TRACE","fields":{"message":"starting stream"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]} {"timestamp":"2023-11-28T23:41:06.530317Z","level":"DEBUG","fields":{"message":"waiting for changes","watcher":"Receiver { shared: Shared { value: RwLock(PhantomData>>, RwLock { data: ClusterMap { map: {None: EndpointSet { endpoints: {}, version: 1 }}, num_endpoints: 0, version: 1 } }), version: Version(2), is_closed: false, ref_count_rx: 1 }, version: Version(2) }"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs"} {"timestamp":"2023-11-28T23:41:06.530437Z","level":"TRACE","fields":{"message":"message received: checking"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]} {"timestamp":"2023-11-28T23:41:06.530458Z","level":"TRACE","fields":{"message":"message received: success"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]} {"timestamp":"2023-11-28T23:41:06.530482Z","level":"TRACE","fields":{"message":"initial request","id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]} {"timestamp":"2023-11-28T23:41:06.530552Z","level":"TRACE","fields":{"message":"discovery response","id":"0","r#type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","nonce":"49924613-4e62-413b-8d9a-d57d5056a1c6"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]} {"timestamp":"2023-11-28T23:41:06.530597Z","level":"TRACE","fields":{"message":"relay marked as healthy"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]} {"timestamp":"2023-11-28T23:41:06.530649Z","level":"DEBUG","fields":{"message":"received discovery response","config":"{\"clusters\":[{\"endpoints\":[],\"locality\":null}],\"filters\":[{\"name\":\"quilkin.filters.capture.v1alpha1.Capture\",\"label\":null,\"config\":{\"metadataKey\":\"quilkin.dev/capture\",\"suffix\":{\"size\":3,\"remove\":true}}},{\"name\":\"quilkin.filters.token_router.v1alpha1.TokenRouter\",\"label\":null,\"config\":null}],\"id\":\"quilkin-agones-agent-c48c946cc-mxh7d\",\"version\":\"v1alpha1\"}"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]} {"timestamp":"2023-11-28T23:41:06.530695Z","level":"TRACE","fields":{"message":"LOOPING!"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"},"spans":[{"name":"handle_discovery_response"},{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"}]} {"timestamp":"2023-11-28T23:41:06.531271Z","level":"TRACE","fields":{"message":"new message"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"},"spans":[{"name":"handle_discovery_response"},{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"}]} {"timestamp":"2023-11-28T23:41:06.531309Z","level":"DEBUG","fields":{"message":"ACK","nonce":"49924613-4e62-413b-8d9a-d57d5056a1c6"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"},"spans":[{"name":"handle_discovery_response"},{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"}]} {"timestamp":"2023-11-28T23:41:06.531326Z","level":"TRACE","fields":{"message":"LOOPING!"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"},"spans":[{"name":"handle_discovery_response"},{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"}]} {"timestamp":"2023-11-28T23:41:07.106454Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:08.106056Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:09.105713Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:10.106008Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:11.106305Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:11.137381Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.137430Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"","status.state":"PortAllocation"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.137442Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.143515Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.143581Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"","status.state":"PortAllocation"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.143604Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.145881Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.145916Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"","status.state":"PortAllocation"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.145930Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.167001Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.167047Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"","status.state":"Creating"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.167064Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.174654Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.174695Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"","status.state":"Creating"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.174708Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.175278Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.175312Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"","status.state":"Creating"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.175329Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.190038Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.190202Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"","status.state":"Starting"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.190288Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.196720Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.196764Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"","status.state":"Starting"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.196777Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.202324Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.202418Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"34.127.28.163","status.state":"Scheduled"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.202438Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.204065Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.204123Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"","status.state":"Starting"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.204144Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.209084Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.209134Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"34.127.28.163","status.state":"Scheduled"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.209155Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.217795Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.217921Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"34.127.28.163","status.state":"Scheduled"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:11.217939Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:12.106754Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:12.857143Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:12.857201Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"34.127.28.163","status.state":"RequestReady"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:12.857228Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:13.055494Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:13.055563Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"34.127.28.163","status.state":"RequestReady"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:13.056495Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:13.057714Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:13.057755Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"34.127.28.163","status.state":"RequestReady"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:13.057781Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:13.106046Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:13.691502Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:13.691579Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"34.127.28.163","status.state":"Ready"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:13.691606Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:13.695018Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:13.695061Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"34.127.28.163","status.state":"Ready"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:13.695081Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:13.987042Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:13.987176Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"34.127.28.163","status.state":"Ready"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:13.987301Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:14.106297Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:14.404785Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:14.404918Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"34.127.28.163","status.state":"Ready"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:14.404974Z","level":"DEBUG","fields":{"message":"skipping unallocated server"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:14.459807Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:14.459857Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"34.127.28.163","status.state":"Allocated"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:14.459914Z","level":"DEBUG","fields":{"message":"Adding endpoint","endpoint":"{\"address\":\"34.127.28.163:7390\",\"metadata\":{\"quilkin.dev\":{\"tokens\":[\"Nzg5\"]},\"name\":\"fleet-jd5d6-wkvn2-dx4wq\"}}"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:14.459951Z","level":"DEBUG","fields":{"message":"changed detected","watchers":1},"target":"quilkin::config::watch","filename":"src/config/watch.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:14.460061Z","level":"DEBUG","fields":{"message":"pushing update","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","watchers":2},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs"} {"timestamp":"2023-11-28T23:41:14.460078Z","level":"DEBUG","fields":{"message":"waiting for changes","watcher":"Receiver { shared: Shared { value: RwLock(PhantomData>>, RwLock { data: ClusterMap { map: {None: EndpointSet { endpoints: {Endpoint { address: EndpointAddress { host: Ip(34.127.28.163), port: 7390 }, metadata: MetadataView { known: Metadata { tokens: {[55, 56, 57]} }, unknown: {\"name\": String(\"fleet-jd5d6-wkvn2-dx4wq\")} } }}, version: 2 }}, num_endpoints: 1, version: 2 } }), version: Version(4), is_closed: false, ref_count_rx: 1 }, version: Version(4) }"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs"} {"timestamp":"2023-11-28T23:41:14.460142Z","level":"TRACE","fields":{"message":"sending new discovery response"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"},"spans":[{"name":"handle_discovery_response"},{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"}]} {"timestamp":"2023-11-28T23:41:14.460240Z","level":"TRACE","fields":{"message":"discovery response","id":"1","r#type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","nonce":"c8a8411c-bfe0-4ce3-b67a-7aef76e183fd"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"},"spans":[{"name":"handle_discovery_response"},{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"}]} {"timestamp":"2023-11-28T23:41:14.460304Z","level":"DEBUG","fields":{"message":"received discovery response","config":"{\"clusters\":[{\"endpoints\":[{\"address\":\"34.127.28.163:7390\",\"metadata\":{\"quilkin.dev\":{\"tokens\":[\"Nzg5\"]},\"name\":\"fleet-jd5d6-wkvn2-dx4wq\"}}],\"locality\":null}],\"filters\":[{\"name\":\"quilkin.filters.capture.v1alpha1.Capture\",\"label\":null,\"config\":{\"metadataKey\":\"quilkin.dev/capture\",\"suffix\":{\"size\":3,\"remove\":true}}},{\"name\":\"quilkin.filters.token_router.v1alpha1.TokenRouter\",\"label\":null,\"config\":null}],\"id\":\"quilkin-agones-agent-c48c946cc-mxh7d\",\"version\":\"v1alpha1\"}"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]} {"timestamp":"2023-11-28T23:41:14.460564Z","level":"TRACE","fields":{"message":"LOOPING!"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"},"spans":[{"name":"handle_discovery_response"},{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"}]} {"timestamp":"2023-11-28T23:41:14.461410Z","level":"TRACE","fields":{"message":"new message"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"},"spans":[{"name":"handle_discovery_response"},{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"}]} {"timestamp":"2023-11-28T23:41:14.461623Z","level":"DEBUG","fields":{"message":"ACK","nonce":"c8a8411c-bfe0-4ce3-b67a-7aef76e183fd"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"},"spans":[{"name":"handle_discovery_response"},{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"}]} {"timestamp":"2023-11-28T23:41:14.461716Z","level":"TRACE","fields":{"message":"LOOPING!"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"},"spans":[{"name":"handle_discovery_response"},{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"}]} {"timestamp":"2023-11-28T23:41:14.972059Z","level":"DEBUG","fields":{"message":"received applied event from k8s"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:14.972112Z","level":"TRACE","fields":{"message":"checking gameserver","status.address":"34.127.28.163","status.state":"Allocated"},"target":"quilkin::config::providers::k8s::agones","filename":"src/config/providers/k8s/agones.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:14.972155Z","level":"DEBUG","fields":{"message":"Adding endpoint","endpoint":"{\"address\":\"34.127.28.163:7390\",\"metadata\":{\"quilkin.dev\":{\"tokens\":[]},\"name\":\"fleet-jd5d6-wkvn2-dx4wq\"}}"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:14.972183Z","level":"DEBUG","fields":{"message":"changed detected","watchers":1},"target":"quilkin::config::watch","filename":"src/config/watch.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:14.972232Z","level":"DEBUG","fields":{"message":"pushing update","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","watchers":2},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs"} {"timestamp":"2023-11-28T23:41:14.972281Z","level":"DEBUG","fields":{"message":"waiting for changes","watcher":"Receiver { shared: Shared { value: RwLock(PhantomData>>, RwLock { data: ClusterMap { map: {None: EndpointSet { endpoints: {Endpoint { address: EndpointAddress { host: Ip(34.127.28.163), port: 7390 }, metadata: MetadataView { known: Metadata { tokens: {} }, unknown: {\"name\": String(\"fleet-jd5d6-wkvn2-dx4wq\")} } }}, version: 3 }}, num_endpoints: 1, version: 3 } }), version: Version(6), is_closed: false, ref_count_rx: 1 }, version: Version(6) }"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs"} {"timestamp":"2023-11-28T23:41:14.972362Z","level":"TRACE","fields":{"message":"sending new discovery response"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"},"spans":[{"name":"handle_discovery_response"},{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"}]} {"timestamp":"2023-11-28T23:41:14.972416Z","level":"TRACE","fields":{"message":"discovery response","id":"2","r#type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","nonce":"6af0f924-6b97-48b0-892c-167eba5b9644"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"},"spans":[{"name":"handle_discovery_response"},{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"}]} {"timestamp":"2023-11-28T23:41:14.972471Z","level":"DEBUG","fields":{"message":"received discovery response","config":"{\"clusters\":[{\"endpoints\":[{\"address\":\"34.127.28.163:7390\",\"metadata\":{\"quilkin.dev\":{\"tokens\":[]},\"name\":\"fleet-jd5d6-wkvn2-dx4wq\"}}],\"locality\":null}],\"filters\":[{\"name\":\"quilkin.filters.capture.v1alpha1.Capture\",\"label\":null,\"config\":{\"metadataKey\":\"quilkin.dev/capture\",\"suffix\":{\"size\":3,\"remove\":true}}},{\"name\":\"quilkin.filters.token_router.v1alpha1.TokenRouter\",\"label\":null,\"config\":null}],\"id\":\"quilkin-agones-agent-c48c946cc-mxh7d\",\"version\":\"v1alpha1\"}"},"target":"quilkin::net::xds::client","filename":"src/net/xds/client.rs","span":{"name":"handle_discovery_response"},"spans":[{"name":"handle_discovery_response"}]} {"timestamp":"2023-11-28T23:41:14.972522Z","level":"TRACE","fields":{"message":"LOOPING!"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"},"spans":[{"name":"handle_discovery_response"},{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"}]} {"timestamp":"2023-11-28T23:41:14.973320Z","level":"TRACE","fields":{"message":"new message"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"},"spans":[{"name":"handle_discovery_response"},{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"}]} {"timestamp":"2023-11-28T23:41:14.973382Z","level":"DEBUG","fields":{"message":"ACK","nonce":"6af0f924-6b97-48b0-892c-167eba5b9644"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"},"spans":[{"name":"handle_discovery_response"},{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"}]} {"timestamp":"2023-11-28T23:41:14.973402Z","level":"TRACE","fields":{"message":"LOOPING!"},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"},"spans":[{"name":"handle_discovery_response"},{"node.id":"quilkin-agones-agent-c48c946cc-mxh7d","resource_type":"type.googleapis.com/quilkin.config.v1alpha1.Cluster","name":"xds_stream"}]} {"timestamp":"2023-11-28T23:41:15.105735Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:16.037426Z","level":"TRACE","fields":{"message":"new configmap event"},"target":"quilkin::config::providers::k8s","filename":"src/config/providers/k8s.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:16.037474Z","level":"TRACE","fields":{"message":"storing new value"},"target":"quilkin::config::slot","filename":"src/config/slot.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:16.037506Z","level":"TRACE","fields":{"message":"calling watcher"},"target":"quilkin::config::slot","filename":"src/config/slot.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:16.037514Z","level":"DEBUG","fields":{"message":"pushing update","resource_type":"type.googleapis.com/envoy.config.listener.v3.Listener","watchers":1},"target":"quilkin::net::xds::server","filename":"src/net/xds/server.rs","span":{"name":"task"},"spans":[{"name":"task"}]} {"timestamp":"2023-11-28T23:41:16.106333Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:17.105841Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:18.105525Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:19.106317Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:20.106250Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:21.106068Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:22.106381Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:23.105516Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:24.106428Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:25.106045Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:26.105499Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:27.105704Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:28.105907Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:29.106161Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:30.105605Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:31.106312Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:32.106328Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:33.106402Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} {"timestamp":"2023-11-28T23:41:34.106026Z","level":"TRACE","fields":{"message":"agent readiness check","provider_healthy":"true","relay_healthy":"true"},"target":"quilkin::cli::agent","filename":"src/cli/agent.rs"} ```

Seeing if I can identify what should be happening when it's not.

XAMPPRocky commented 9 months ago

What I've seen in the the logs is usually stuff attempting to connect before a service is ready and then getting stuck in that.