quilkin Flaky Test: relay::tests::agones_token

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.

Nov 27 '23 22:11 markmandel

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 🤔

Nov 27 '23 22:11 markmandel

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

Nov 27 '23 22:11 markmandel

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.

Nov 27 '23 23:11 markmandel

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.

Nov 28 '23 00:11 markmandel

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.

Nov 28 '23 01:11 markmandel

May be related:

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

Apparently is flaky as well.

Nov 28 '23 18:11 markmandel

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.

Nov 28 '23 18:11 XAMPPRocky

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

Nov 28 '23 18:11 markmandel

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

Nov 28 '23 19:11 markmandel

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<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-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<std::sync::rwlock::RwLock<alloc::sync::Arc<quilkin::net::cluster::ClusterMap>>>, 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<std::sync::rwlock::RwLock<alloc::sync::Arc<quilkin::net::cluster::ClusterMap>>>, 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.

Nov 28 '23 23:11 markmandel

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.

Nov 30 '23 10:11 XAMPPRocky

Flaky Test: relay::tests::agones_token_router