Resource Manager: Token Stream RPC Error Leads to Premature TSO Client Cancellation During Startup
- Dominant language
- Go
- Stars
- 40.5k
- Forks
- 6.2k
- PR merge metrics
- PR metrics pending
Description
## Bug Report
Please answer these questions before submitting your issue. Thanks!
### 1. Minimal reproduce step (Required)
1. Cluster Deployment:
Deploy a TiDB cluster with the following configuration:
PD node: One PD instance running at http://166.18.0.11:2379.
TiKV nodes: Four TiKV nodes with these store details:
Store ID 1: 166.18.0.21:20160
Store ID 130: 166.18.0.22:20160
Store ID 195: 166.18.0.23:20160
Store ID 260: 166.18.0.24:20160
2. Start-up Sequence:
Start the PD node (node0) and observe its logs. Notice the watch requests on the resource_group keys between 00:19:35 and 00:21:42 (see PD logs below).
Start the TiDB instance (node1) and monitor its startup logs. Around 2025/02/19 00:20:38, the logs show resource group configuration being loaded.
3. Error Observation:
In the TiDB logs, at approximately 00:20:38, the following warning appears:
```css
[2025/02/19 00:20:38.419 +08:00] [WARN] [resource_manager_client.go:305] ["[resource_manager] get token stream error"] [error="rpc error: code = Canceled desc = context canceled"]
```
Shortly after, the TSO client is closed:
```css
[2025/02/19 00:20:38.419 +08:00] [INFO] [client.go:163] ["[tso] tso client is closed"]
```
4. Additional Logs:
TiKV nodes (node1 and node2) show regular PD connection attempts and some batch command RPC errors on node2, but no issues directly correlate to these errors.
5. Reproducibility:
The issue appears to be reproducible during cluster startup when TiDB loads its resource group configuration, causing the resource manager’s token stream to be unexpectedly canceled.
### 2. What did you expect to see? (Required)
TiDB should successfully establish a stable connection with PD and consistently acquire the token stream from the resource manager.
The TSO client should remain active throughout the startup process, ensuring proper global timestamp generation without any premature cancellation.
### 3. What did you see instead (Required)
Instead, during startup, TiDB logs a warning indicating failure to obtain the token stream due to a "context canceled" error:
```css
[2025/02/19 00:20:38.419 +08:00] [WARN] [resource_manager_client.go:305] ["[resource_manager] get token stream error"] [error="rpc error: code = Canceled desc = context canceled"]
```
This error results in the TSO client’s dispatcher being stopped and the TSO client ultimately closing:
```css
[2025/02/19 00:20:38.419 +08:00] [INFO] [client.go:163] ["[tso] tso client is closed"]
```
The PD and TiKV logs show normal behavior (watch requests and PD connection attempts), suggesting that the issue is isolated to TiDB’s handling of resource group configuration and token stream acquisition.
### 4. What is your TiDB version? (Required)
Release Version: v9.0.0-alpha-100-g91706ec8df-dirty
Edition: Community
Git Commit Hash: 91706ec8dfbf3fd07fe1643cf0d0b6eb2d67eb83
Git Branch: master
UTC Build Time: 2025-02-08 13:04:09
GoVersion: go1.23.4
### logs
PD Node (node0) Logs:
```css
[2025/02/19 00:19:35.346 +08:00] [INFO] [grpc_service.go:96] ["watch request"] [key=resource_group/controller] [range-end=resource_group/controlles] [start-revision=2901927]
[2025/02/19 00:20:38.249 +08:00] [INFO] [grpc_service.go:96] ["watch request"] [key=resource_group/settings] [range-end=resource_group/settingt] [start-revision=2901994]
[2025/02/19 00:20:38.249 +08:00] [INFO] [grpc_service.go:96] ["watch request"] [key=resource_group/controller] [range-end=resource_group/controlles] [start-revision=2901994]
[2025/02/19 00:21:42.019 +08:00] [INFO] [grpc_service.go:96] ["watch request"] [key=resource_group/settings] [range-end=resource_group/settingt] [start-revision=2902061]
```
TiDB Node (node1) Logs:
```css
[2025/02/19 00:19:36.998 +08:00] [INFO] [pd.go:431] ["adaptive update ts interval state transition"] [configuredInterval=2s] [prevAdaptiveUpdateInterval=2s] [newAdaptiveUpdateInterval=2s] [requiredStaleness=0s] [prevState=unknown(0)] [newState=normal]
...
[2025/02/19 00:20:38.419 +08:00] [WARN] [resource_manager_client.go:305] ["[resource_manager] get token stream error"] [error="rpc error: code = Canceled desc = context canceled"]
...
[2025/02/19 00:20:38.419 +08:00] [INFO] [client.go:163] ["[tso] tso client is closed"]
...
```
TiKV Node (node1) Logs:
```css
[2025/02/19 00:00:09.966 +08:00] [INFO] [util.rs:639] ["connecting to PD endpoint"] [endpoints=http://166.18.0.11:2379] [thread_id=12]
[2025/02/19 00:10:09.968 +08:00] [INFO] [util.rs:639] ["connecting to PD endpoint"] [endpoints=http://166.18.0.11:2379] [thread_id=12]
[2025/02/19 00:20:09.970 +08:00] [INFO] [util.rs:639] ["connecting to PD endpoint"] [endpoints=http://166.18.0.11:2379] [thread_id=12]
[2025/02/19 00:30:09.972 +08:00] [INFO] [util.rs:639] ["connecting to PD endpoint"] [endpoints=http://166.18.0.11:2379] [thread_id=12]
[2025/02/19 00:40:09.974 +08:00] [INFO] [util.rs:639] ["connecting to PD endpoint"] [endpoints=http://166.18.0.11:2379] [thread_id=12]
```
TiKV Node (node2) Logs:
```css
[2025/02/18 23:59:33.541 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=11]
[2025/02/19 00:00:36.731 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=8]
[2025/02/19 00:00:36.731 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=7]
[2025/02/19 00:00:36.731 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=11]
[2025/02/19 00:00:36.731 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=10]
[2025/02/19 00:00:55.301 +08:00] [INFO] [util.rs:639] ["connecting to PD endpoint"] [endpoints=http://166.18.0.11:2379] [thread_id=12]
[2025/02/19 00:01:39.921 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=7]
```
Cluster Configuration:
```cpp
pd-ctl -u http://166.18.0.11:2379 store
{
"count": 4,
"stores": [
{
"store": {
"id": 1,
"address": "166.18.0.21:20160",
"version": "8.5.0-alpha",
"peer_address": "166.18.0.21:20160",
"status_address": "127.0.0.1:20180",
"git_hash": "Unknown git hash",
"start_timestamp": 1738456813,
"deploy_path": "/usr/local/bin",
"last_heartbeat": 1740397833572457060,
"state_name": "Up"
},
"status": { ... }
},
{
"store": {
"id": 130,
"address": "166.18.0.22:20160",
"version": "8.5.0-alpha",
"peer_address": "166.18.0.22:20160",
"status_address": "127.0.0.1:20180",
"git_hash": "Unknown git hash",
"start_timestamp": 1738456858,
"deploy_path": "/usr/local/bin",
"last_heartbeat": 1740397828780808752,
"state_name": "Up"
},
"status": { ... }
},
{
"store": {
"id": 195,
"address": "166.18.0.23:20160",
"version": "8.5.0-alpha",
"peer_address": "166.18.0.23:20160",
"status_address": "127.0.0.1:20180",
"git_hash": "Unknown git hash",
"start_timestamp": 1736939894,
"deploy_path": "/usr/local/bin",
"last_heartbeat": 1740397833821703738,
"state_name": "Up"
},
"status": { ... }
},
{
"store": {
"id": 260,
"address": "166.18.0.24:20160",
"version": "8.5.0-alpha",
"peer_address": "166.18.0.24:20160",
"status_address": "127.0.0.1:20180",
"git_hash": "Unknown git hash",
"start_timestamp": 1736939933,
"deploy_path": "/usr/local/bin",
"last_heartbeat": 1740397833182651508,
"state_name": "Up"
},
"status": { ... }
}
]
}
```
Please let me know if further information is needed.
Contributor guide
Assessment
This issue has not been assessed yet.