test_client_routes_change_event - fails with cassandra.protocol.ProtocolException: <Error from server: code=000a [Protocol error] message="Invalid value 'CLIENT_ROUTES_CHANGE' for Event.Type"> #652
Description
Tested on master (as it failed on my branch first):
------------------------------------------------------------------------------------------------------------- Captured log call --------------------------------------------------------------------------------------------------------------
2026-01-23 18:09:47.243 ERROR [__init__:957]: Compression is enabled, but no compression libraries are available. Disabling compression, consider installing one of the Python packages: lz4 and/or python-snappy.
2026-01-23 18:09:47.243 WARNING [__init__:957]: Cluster.__init__ called with contact_points specified, but no load_balancing_policy. In the next major version, this will raise an error; please specify a load-balancing policy. (contact_points = ['127.0.0.1'], lbp = None)
2026-01-23 18:09:47.244 ERROR [__init__:957]: Compression is enabled, but no compression libraries are available. Disabling compression, consider installing one of the Python packages: lz4 and/or python-snappy.
2026-01-23 18:09:47.244 WARNING [__init__:957]: Cluster.__init__ called with contact_points specified, but no load_balancing_policy. In the next major version, this will raise an error; please specify a load-balancing policy. (contact_points = ['127.0.0.1'], lbp = None)
2026-01-23 18:09:47.244 DEBUG [test_control_connection:145]: Connecting to cluster, contact points: ['127.0.0.1']; protocol version: 4
2026-01-23 18:09:47.245 DEBUG [test_control_connection:145]: [control connection] Opening new connection to 127.0.0.1:9042
2026-01-23 18:09:47.245 DEBUG [libevreactor:272]: Connection 140272104419920: '('127.0.0.1', 37206)' -> '('127.0.0.1', 9042)'
2026-01-23 18:09:47.245 DEBUG [libevreactor:279]: Sending initial options message for new connection (140272104419920) to 127.0.0.1:9042
2026-01-23 18:09:47.246 DEBUG [protocol_features:70]: Parsing sharding info from message options {'COMPRESSION': ['lz4', 'snappy'], 'SCYLLA_LWT_ADD_METADATA_MARK': ['LWT_OPTIMIZATION_META_BIT_MASK=2147483648'], 'SCYLLA_NR_SHARDS': ['2'], 'SCYLLA_PARTITIONER': ['org.apache.cassandra.dht.Murmur3Partitioner'], 'SCYLLA_RATE_LIMIT_ERROR': ['ERROR_CODE=61440'], 'SCYLLA_SHARD': ['0'], 'SCYLLA_SHARDING_ALGORITHM': ['biased-token-round-robin'], 'SCYLLA_SHARDING_IGNORE_MSB': ['12'], 'SCYLLA_SHARD_AWARE_PORT': ['19042'], 'SCYLLA_USE_METADATA_ID': [''], 'TABLETS_ROUTING_V1': ['']}
2026-01-23 18:09:47.246 DEBUG [libevreactor:376]: Received options response on new connection (140272104419920) from 127.0.0.1:9042
2026-01-23 18:09:47.246 DEBUG [libevreactor:376]: Sending StartupMessage on <LibevConnection(140272104419920) 127.0.0.1:9042>
2026-01-23 18:09:47.246 DEBUG [libevreactor:376]: Sent StartupMessage on <LibevConnection(140272104419920) 127.0.0.1:9042>
2026-01-23 18:09:47.246 DEBUG [libevreactor:376]: Got ReadyMessage on new connection (140272104419920) from 127.0.0.1:9042
2026-01-23 18:09:47.247 DEBUG [test_control_connection:145]: [control connection] Established new connection <LibevConnection(140272104419920) 127.0.0.1:9042>, registering watchers and refreshing schema and topology
2026-01-23 18:09:47.248 DEBUG [test_control_connection:145]: [control connection] Refreshing node list and token map using preloaded results
2026-01-23 18:09:47.249 DEBUG [test_control_connection:145]: [control connection] Found new host to connect to: 127.0.0.1:9042
2026-01-23 18:09:47.249 INFO [test_control_connection:145]: New Cassandra host <Host: 127.0.0.1:9042 dc1> discovered
2026-01-23 18:09:47.249 DEBUG [test_control_connection:145]: Handling new host <Host: 127.0.0.1:9042 dc1> and notifying listeners
2026-01-23 18:09:47.249 INFO [policies:299]: Using datacenter 'dc1' for DCAwareRoundRobinPolicy (via host '127.0.0.1:9042'); if incorrect, please specify a local_dc to the constructor, or limit contact points to local cluster nodes
2026-01-23 18:09:47.249 DEBUG [test_control_connection:145]: Done preparing queries for new host <Host: 127.0.0.1:9042 dc1>
2026-01-23 18:09:47.249 DEBUG [test_control_connection:145]: Host 127.0.0.1:9042 is now marked up
2026-01-23 18:09:47.249 DEBUG [test_control_connection:145]: [control connection] Found new host to connect to: 127.0.0.3:9042
2026-01-23 18:09:47.249 INFO [test_control_connection:145]: New Cassandra host <Host: 127.0.0.3:9042 dc1> discovered
2026-01-23 18:09:47.249 DEBUG [test_control_connection:145]: Handling new host <Host: 127.0.0.3:9042 dc1> and notifying listeners
2026-01-23 18:09:47.249 DEBUG [test_control_connection:145]: Done preparing queries for new host <Host: 127.0.0.3:9042 dc1>
2026-01-23 18:09:47.249 DEBUG [test_control_connection:145]: Host 127.0.0.3:9042 is now marked up
2026-01-23 18:09:47.249 DEBUG [test_control_connection:145]: [control connection] Found new host to connect to: 127.0.0.2:9042
2026-01-23 18:09:47.249 INFO [test_control_connection:145]: New Cassandra host <Host: 127.0.0.2:9042 dc1> discovered
2026-01-23 18:09:47.249 DEBUG [test_control_connection:145]: Handling new host <Host: 127.0.0.2:9042 dc1> and notifying listeners
2026-01-23 18:09:47.249 DEBUG [test_control_connection:145]: Done preparing queries for new host <Host: 127.0.0.2:9042 dc1>
2026-01-23 18:09:47.249 DEBUG [test_control_connection:145]: Host 127.0.0.2:9042 is now marked up
2026-01-23 18:09:47.250 DEBUG [test_control_connection:145]: [control connection] Finished fetching ring info
2026-01-23 18:09:47.250 DEBUG [test_control_connection:145]: [control connection] Rebuilding token map due to topology changes
2026-01-23 18:09:47.260 DEBUG [test_control_connection:145]: Control connection created
2026-01-23 18:09:47.261 DEBUG [thread:73]: Initializing connection for host 127.0.0.1:9042
2026-01-23 18:09:47.261 DEBUG [thread:73]: Initializing connection for host 127.0.0.3:9042
2026-01-23 18:09:47.262 DEBUG [libevreactor:272]: Connection 140272104421840: '('127.0.0.1', 37214)' -> '('127.0.0.1', 9042)'
2026-01-23 18:09:47.262 DEBUG [libevreactor:279]: Sending initial options message for new connection (140272104421840) to 127.0.0.1:9042
2026-01-23 18:09:47.262 DEBUG [libevreactor:272]: Connection 140272104422480: '('127.0.0.1', 46826)' -> '('127.0.0.3', 9042)'
2026-01-23 18:09:47.263 DEBUG [protocol_features:70]: Parsing sharding info from message options {'COMPRESSION': ['lz4', 'snappy'], 'SCYLLA_LWT_ADD_METADATA_MARK': ['LWT_OPTIMIZATION_META_BIT_MASK=2147483648'], 'SCYLLA_NR_SHARDS': ['2'], 'SCYLLA_PARTITIONER': ['org.apache.cassandra.dht.Murmur3Partitioner'], 'SCYLLA_RATE_LIMIT_ERROR': ['ERROR_CODE=61440'], 'SCYLLA_SHARD': ['1'], 'SCYLLA_SHARDING_ALGORITHM': ['biased-token-round-robin'], 'SCYLLA_SHARDING_IGNORE_MSB': ['12'], 'SCYLLA_SHARD_AWARE_PORT': ['19042'], 'SCYLLA_USE_METADATA_ID': [''], 'TABLETS_ROUTING_V1': ['']}
2026-01-23 18:09:47.263 DEBUG [libevreactor:376]: Received options response on new connection (140272104421840) from 127.0.0.1:9042
2026-01-23 18:09:47.264 DEBUG [libevreactor:376]: Sending StartupMessage on <LibevConnection(140272104421840) 127.0.0.1:9042>
2026-01-23 18:09:47.264 DEBUG [libevreactor:376]: Sent StartupMessage on <LibevConnection(140272104421840) 127.0.0.1:9042>
2026-01-23 18:09:47.264 DEBUG [libevreactor:279]: Sending initial options message for new connection (140272104422480) to 127.0.0.3:9042
2026-01-23 18:09:47.264 DEBUG [libevreactor:376]: Got ReadyMessage on new connection (140272104421840) from 127.0.0.1:9042
2026-01-23 18:09:47.264 DEBUG [thread:73]: First connection created to 127.0.0.1:9042 for shard_id=1
2026-01-23 18:09:47.265 DEBUG [thread:73]: Finished initializing connection for host 127.0.0.1:9042
2026-01-23 18:09:47.265 DEBUG [thread:73]: Added pool for host 127.0.0.1:9042 to session
2026-01-23 18:09:47.265 DEBUG [thread:73]: Initializing connection for host 127.0.0.2:9042
2026-01-23 18:09:47.265 DEBUG [protocol_features:70]: Parsing sharding info from message options {'COMPRESSION': ['lz4', 'snappy'], 'SCYLLA_LWT_ADD_METADATA_MARK': ['LWT_OPTIMIZATION_META_BIT_MASK=2147483648'], 'SCYLLA_NR_SHARDS': ['2'], 'SCYLLA_PARTITIONER': ['org.apache.cassandra.dht.Murmur3Partitioner'], 'SCYLLA_RATE_LIMIT_ERROR': ['ERROR_CODE=61440'], 'SCYLLA_SHARD': ['0'], 'SCYLLA_SHARDING_ALGORITHM': ['biased-token-round-robin'], 'SCYLLA_SHARDING_IGNORE_MSB': ['12'], 'SCYLLA_SHARD_AWARE_PORT': ['19042'], 'SCYLLA_USE_METADATA_ID': [''], 'TABLETS_ROUTING_V1': ['']}
2026-01-23 18:09:47.266 DEBUG [libevreactor:376]: Received options response on new connection (140272104422480) from 127.0.0.3:9042
2026-01-23 18:09:47.266 DEBUG [libevreactor:376]: Sending StartupMessage on <LibevConnection(140272104422480) 127.0.0.3:9042>
2026-01-23 18:09:47.266 DEBUG [libevreactor:376]: Sent StartupMessage on <LibevConnection(140272104422480) 127.0.0.3:9042>
2026-01-23 18:09:47.267 DEBUG [libevreactor:272]: Connection 140272104420560: '('127.0.0.1', 33762)' -> '('127.0.0.2', 9042)'
2026-01-23 18:09:47.267 DEBUG [libevreactor:279]: Sending initial options message for new connection (140272104420560) to 127.0.0.2:9042
2026-01-23 18:09:47.267 DEBUG [libevreactor:376]: Got ReadyMessage on new connection (140272104422480) from 127.0.0.3:9042
2026-01-23 18:09:47.267 DEBUG [thread:73]: First connection created to 127.0.0.3:9042 for shard_id=0
2026-01-23 18:09:47.268 DEBUG [thread:73]: Finished initializing connection for host 127.0.0.3:9042
2026-01-23 18:09:47.268 DEBUG [thread:73]: Added pool for host 127.0.0.3:9042 to session
2026-01-23 18:09:47.268 DEBUG [thread:73]: shard_aware_endpoint=<DefaultEndPoint: 127.0.0.1:19042>
2026-01-23 18:09:47.268 DEBUG [test_control_connection:145]: Not starting MonitorReporter thread for Insights; not supported by server version 3.0.8 on ControlConnection host 127.0.0.1:9042
2026-01-23 18:09:47.268 DEBUG [test_control_connection:145]: Started Session with client_id 3b91714a-8b11-4edd-a5f9-b8f50e8a501f and session_id ca1244b3-76cd-459e-a335-31b450680abb
2026-01-23 18:09:47.269 DEBUG [protocol_features:70]: Parsing sharding info from message options {'COMPRESSION': ['lz4', 'snappy'], 'SCYLLA_LWT_ADD_METADATA_MARK': ['LWT_OPTIMIZATION_META_BIT_MASK=2147483648'], 'SCYLLA_NR_SHARDS': ['2'], 'SCYLLA_PARTITIONER': ['org.apache.cassandra.dht.Murmur3Partitioner'], 'SCYLLA_RATE_LIMIT_ERROR': ['ERROR_CODE=61440'], 'SCYLLA_SHARD': ['0'], 'SCYLLA_SHARDING_ALGORITHM': ['biased-token-round-robin'], 'SCYLLA_SHARDING_IGNORE_MSB': ['12'], 'SCYLLA_SHARD_AWARE_PORT': ['19042'], 'SCYLLA_USE_METADATA_ID': [''], 'TABLETS_ROUTING_V1': ['']}
2026-01-23 18:09:47.269 DEBUG [libevreactor:376]: Received options response on new connection (140272104420560) from 127.0.0.2:9042
2026-01-23 18:09:47.270 DEBUG [libevreactor:376]: Sending StartupMessage on <LibevConnection(140272104420560) 127.0.0.2:9042>
2026-01-23 18:09:47.270 DEBUG [libevreactor:376]: Sent StartupMessage on <LibevConnection(140272104420560) 127.0.0.2:9042>
2026-01-23 18:09:47.271 DEBUG [libevreactor:272]: connection (140272104422160) port=64772 should be shard_id=0
2026-01-23 18:09:47.271 DEBUG [libevreactor:272]: Connection 140272104422160: '('127.0.0.1', 64772)' -> '('127.0.0.1', 19042)'
2026-01-23 18:09:47.271 DEBUG [libevreactor:279]: Sending initial options message for new connection (140272104422160) to 127.0.0.1:19042
2026-01-23 18:09:47.272 ERROR [libevreactor:376]: Closing connection <LibevConnection(140272104419920) 127.0.0.1:9042> due to protocol error: Error from server: code=000a [Protocol error] message="Invalid value 'CLIENT_ROUTES_CHANGE' for Event.Type"
2026-01-23 18:09:47.272 DEBUG [libevreactor:376]: Defuncting connection (140272104419920) to 127.0.0.1:9042: <Error from server: code=000a [Protocol error] message="Invalid value 'CLIENT_ROUTES_CHANGE' for Event.Type">
2026-01-23 18:09:47.272 DEBUG [libevreactor:292]: Closing connection (140272104419920) to 127.0.0.1:9042
2026-01-23 18:09:47.272 DEBUG [libevreactor:296]: Closed socket to 127.0.0.1:9042
2026-01-23 18:09:47.272 DEBUG [libevreactor:376]: Got ReadyMessage on new connection (140272104420560) from 127.0.0.2:9042
2026-01-23 18:09:47.273 DEBUG [thread:73]: First connection created to 127.0.0.2:9042 for shard_id=0
2026-01-23 18:09:47.273 DEBUG [thread:73]: Finished initializing connection for host 127.0.0.2:9042
2026-01-23 18:09:47.273 DEBUG [thread:73]: Added pool for host 127.0.0.2:9042 to session
2026-01-23 18:09:47.273 DEBUG [thread:121]: Shutting down connections to 127.0.0.1:9042
2026-01-23 18:09:47.273 DEBUG [thread:121]: Closing connection (140272104421840) to 127.0.0.1:9042
2026-01-23 18:09:47.274 DEBUG [libevreactor:292]: Closing connection (140272104421840) to 127.0.0.1:9042
2026-01-23 18:09:47.274 DEBUG [protocol_features:70]: Parsing sharding info from message options {'COMPRESSION': ['lz4', 'snappy'], 'SCYLLA_LWT_ADD_METADATA_MARK': ['LWT_OPTIMIZATION_META_BIT_MASK=2147483648'], 'SCYLLA_NR_SHARDS': ['2'], 'SCYLLA_PARTITIONER': ['org.apache.cassandra.dht.Murmur3Partitioner'], 'SCYLLA_RATE_LIMIT_ERROR': ['ERROR_CODE=61440'], 'SCYLLA_SHARD': ['0'], 'SCYLLA_SHARDING_ALGORITHM': ['biased-token-round-robin'], 'SCYLLA_SHARDING_IGNORE_MSB': ['12'], 'SCYLLA_SHARD_AWARE_PORT': ['19042'], 'SCYLLA_USE_METADATA_ID': [''], 'TABLETS_ROUTING_V1': ['']}
2026-01-23 18:09:47.274 DEBUG [libevreactor:376]: Received options response on new connection (140272104422160) from 127.0.0.1:19042
2026-01-23 18:09:47.275 DEBUG [libevreactor:376]: Sending StartupMessage on <LibevConnection(140272104422160) 127.0.0.1:19042>
2026-01-23 18:09:47.275 DEBUG [libevreactor:376]: Sent StartupMessage on <LibevConnection(140272104422160) 127.0.0.1:19042>
2026-01-23 18:09:47.275 DEBUG [libevreactor:296]: Closed socket to 127.0.0.1:9042
2026-01-23 18:09:47.275 DEBUG [thread:121]: Closing pending connection (140272104422160) to 127.0.0.1:9042
2026-01-23 18:09:47.275 DEBUG [libevreactor:292]: Closing connection (140272104422160) to 127.0.0.1:19042
Command line used:
env SCYLLA_VERSION=release/2025.4.2 PROTOCOL_VERSION=4 uv run pytest tests/integration/standard/test_control_connection.py::ControlConnectionTests::test_client_routes_change_event