Rust in Everything
基于 tower 0.5.3

poll_ready must be called first:没就绪就 call

主线位置:就绪主线和请求主线的交接处。poll_ready 在服务实例身上占了一样东西(许可、通道位置、本窗口的次数、一条连接),call 要从同一个实例身上把它取出来。没占就 call,或者占的是 A、call 的是 B,就会走到这一页的 panic。

flowchart TB
  rdy["ready().await"] --> held["self.inner 占到许可"]
  held --> callreq["call(req)"]
  callreq --> c1["clone 一份再 call"]
  callreq --> c2["clone 一份再 oneshot"]
  callreq --> c3["mem::replace 换出来"]
  c1 --> p1["副本没有许可:panic"]
  c2 --> p2["副本等原件的许可:卡死"]
  c3 --> p3["就绪的那个进 future:正常"]

Service trait 里说过:没拿到 Ready(Ok) 就 call,实现方可以 panic(call 的文档)。这一页讲这条规则在实际代码里怎么被踩到,以及 panic 信息长什么样。

四种 panic 信息

每个服务新建出来不 poll_ready,直接 call:

tower = { version = "=0.5.3", features = ["limit", "buffer", "reconnect", "util"] }
tokio = { version = "=1.54.1", features = ["full"] }
use std::panic::{AssertUnwindSafe, catch_unwind};
use std::time::Duration;
use tower::buffer::Buffer;
use tower::limit::{ConcurrencyLimit, RateLimit, rate::Rate};
use tower::reconnect::Reconnect;
use tower::{BoxError, Service, service_fn};

fn echo() -> impl Service<u32, Response = u32, Error = BoxError, Future: Send> + Send + 'static {
  service_fn(|x: u32| async move { Ok::<_, BoxError>(x) })
}

// Call `f` and print the panic message (or "no panic").
fn try_call(name: &str, f: impl FnOnce()) {
  match catch_unwind(AssertUnwindSafe(f)) {
    Ok(()) => println!("{name}: no panic"),
    Err(p) => {
      let msg = p
        .downcast_ref::<&str>()
        .map(|s| s.to_string())
        .or_else(|| p.downcast_ref::<String>().cloned())
        .unwrap();
      println!("{name}: {msg}");
    }
  }
}

#[tokio::main(flavor = "current_thread")]
async fn main() {
  let mut cl = ConcurrencyLimit::new(echo(), 4);
  try_call("ConcurrencyLimit", || drop(cl.call(1)));

  let mut rl = RateLimit::new(echo(), Rate::new(1, Duration::from_secs(1)));
  try_call("RateLimit, 1st call", || drop(rl.call(1)));
  try_call("RateLimit, 2nd call", || drop(rl.call(2)));

  let mk = service_fn(|_: ()| std::future::ready(Ok::<_, BoxError>(echo())));
  let mut rc = Reconnect::new(mk, ());
  try_call("Reconnect", || drop(Service::<u32>::call(&mut rc, 1)));

  let mut bf = Buffer::new(echo(), 4);
  try_call("Buffer", || drop(bf.call(1)));
}

M2 Max、rustc 1.99.0、--release,连跑 3 次,除了线程编号以外输出相同(thread 'main' ... panicked at 那几行是默认 panic hook 打到 stderr 的):

thread 'main' (124641) panicked at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tower-0.5.3/src/limit/concurrency/service.rs:86:14:
max requests in-flight; poll_ready must be called first
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
ConcurrencyLimit: max requests in-flight; poll_ready must be called first
RateLimit, 1st call: no panic

thread 'main' (124641) panicked at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tower-0.5.3/src/limit/rate/service.rs:115:31:
service not ready; poll_ready must be called first
RateLimit, 2nd call: service not ready; poll_ready must be called first

thread 'main' (124641) panicked at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tower-0.5.3/src/reconnect/mod.rs:149:18:
service not ready; poll_ready must be called first
Reconnect: service not ready; poll_ready must be called first

thread 'main' (124641) panicked at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tower-0.5.3/src/buffer/service.rs:122:23:
`send_item` called without first calling `poll_reserve`
Buffer: `send_item` called without first calling `poll_reserve`
中间件什么时候 panic信息出处
ConcurrencyLimit手里没有许可就 call,一定 panicmax requests in-flight; poll_ready must be called firstcall 里对 self.permit.take() 的 expect
RateLimit只在 State::Limited 时;窗口里还有次数,不 poll_ready 也能 callservice not ready; poll_ready must be called firstcall 的 State::Limited 分支
Reconnect状态不是 Connected,而且没有存着的连接错误service not ready; poll_ready must be called firstcall 的兜底分支
Buffer句柄没有预留通道位置`send_item` called without first calling `poll_reserve`call 调 self.tx.send_item,panic 在 tokio-util 的 PollSender::send_item 里

几点:

  • RateLimit 的这个坑测不出来。上面 Rate::new(1, ...) 第一次 call 不 panic,第二次才 panic。窗口次数设得大一点,单元测试里发几个请求永远不会触发,上线后流量一过阈值才 panic。原因见 RateLimit:只有扣掉最后一次的那个 call 会把状态切到 Limited。
  • Buffer 的信息里没有 poll_ready。按 poll_ready must be called first 搜日志,搜不到 Buffer 的这一条。send_item 标了 #[track_caller],所以 panic 的位置报的是 tower 的 buffer/service.rs:122,不是 tokio-util 的文件。
  • Timeout、Filter、LoadShed、SpawnReady(服务还在手里时)不 panic,见 单服务中间件 的对照表。不 panic 不等于用对了:LoadShed 会直接返回 Overloaded。

真实的样子:在 call 里 clone 内层

很少有人真的不调 poll_ready 就 call。常见的是:poll_ready 问的是 self.inner,call 用的却是 self.inner.clone()。手写中间件要把内层服务移进一个 async 块时,最顺手的写法就是这样。

下面的 Log 中间件有三种 call 写法,分别套在 ConcurrencyLimit(1) 和 Buffer(1) 外面,每种发两个请求:

tower = { version = "=0.5.3", features = ["limit", "buffer", "util"] }
tokio = { version = "=1.54.1", features = ["full", "test-util"] }
use std::future::Future;
use std::pin::Pin;
use std::task::{Context, Poll};
use std::time::Duration;
use tower::{BoxError, Service, ServiceBuilder, ServiceExt, service_fn};

#[derive(Clone, Copy, Debug)]
enum Mode {
  CloneThenCall,
  CloneThenOneshot,
  Replace,
}

// A hand-written middleware whose call moves the inner service into a boxed future.
#[derive(Clone)]
struct Log<S> {
  inner: S,
  mode: Mode,
}

impl<S> Service<u32> for Log<S>
where
  S: Service<u32, Response = u32, Error = BoxError> + Clone + Send + 'static,
  S::Future: Send,
{
  type Response = u32;
  type Error = BoxError;
  type Future = Pin<Box<dyn Future<Output = Result<u32, BoxError>> + Send>>;

  fn poll_ready(&mut self, cx: &mut Context<'_>) -> Poll<Result<(), BoxError>> {
    self.inner.poll_ready(cx)
  }

  fn call(&mut self, req: u32) -> Self::Future {
    match self.mode {
      Mode::CloneThenCall => {
        let mut inner = self.inner.clone();
        Box::pin(async move { inner.call(req).await })
      }
      Mode::CloneThenOneshot => {
        let inner = self.inner.clone();
        Box::pin(async move { inner.oneshot(req).await })
      }
      Mode::Replace => {
        let clone = self.inner.clone();
        let mut inner = std::mem::replace(&mut self.inner, clone);
        Box::pin(async move { inner.call(req).await })
      }
    }
  }
}

async fn run<S>(label: &str, inner: S, mode: Mode)
where
  S: Service<u32, Response = u32, Error = BoxError> + Clone + Send + 'static,
  S::Future: Send,
{
  let mut svc = Log { inner, mode };
  let task = tokio::spawn(async move {
    let mut out = Vec::new();
    for i in 1..=2 {
      out.push(svc.ready().await?.call(i).await?);
    }
    Ok::<_, BoxError>(out)
  });
  let result = match tokio::time::timeout(Duration::from_secs(5), task).await {
    Err(_) => "still waiting after 5s".to_string(),
    Ok(Ok(r)) => format!("{:?}", r.map_err(|e| e.to_string())),
    Ok(Err(e)) => {
      let p = e.into_panic();
      let msg = p
        .downcast_ref::<&str>()
        .map(|s| s.to_string())
        .or_else(|| p.downcast_ref::<String>().cloned())
        .unwrap();
      format!("panic: {msg}")
    }
  };
  println!("{label:<10} {:<17} -> {result}", format!("{mode:?}"));
}

fn echo() -> impl Service<u32, Response = u32, Error = BoxError, Future: Send> + Clone + Send + 'static {
  service_fn(|x: u32| async move { Ok::<_, BoxError>(x) })
}

#[tokio::main(flavor = "current_thread", start_paused = true)]
async fn main() {
  std::panic::set_hook(Box::new(|_| {})); // keep the default hook quiet
  for mode in [Mode::CloneThenCall, Mode::CloneThenOneshot, Mode::Replace] {
    run("limit(1)", ServiceBuilder::new().concurrency_limit(1).service(echo()), mode).await;
    run("buffer(1)", ServiceBuilder::new().buffer(1).service(echo()), mode).await;
  }
}

时钟是暂停的(start_paused,需要 tokio 的 test-util),「5 秒」不用真等。连跑 3 次输出相同:

limit(1)   CloneThenCall     -> panic: max requests in-flight; poll_ready must be called first
buffer(1)  CloneThenCall     -> panic: `send_item` called without first calling `poll_reserve`
limit(1)   CloneThenOneshot  -> still waiting after 5s
buffer(1)  CloneThenOneshot  -> still waiting after 5s
limit(1)   Replace           -> Ok([1, 2])
buffer(1)  Replace           -> Ok([1, 2])
  • clone 后 call:panic。 ConcurrencyLimit 和 Buffer 的 Clone 都故意不复制就绪状态:ConcurrencyLimit 的副本 permit: None(Clone),Buffer 的副本是一个新的 PollSender,没有预留位置(Clone)。就绪的是 self.inner,被 call 的是副本。
  • clone 后 oneshot:不 panic,但永远等下去。 这是最容易想到的「修法」:既然副本没就绪,就在 future 里让它自己等就绪。可是唯一的许可(或唯一的通道位置)还在 self.inner 手里。按规则 2,self.inner 在下一次 call 之前会一直拿着它;而下一次 call 要等这个请求完成。上限大于 1 时不会卡死,但每个在途请求背后,self.inner 都额外压着一份许可或位置,直到下一次 call 才用掉:另跑一个上限为 2 的同样写法,只发一个请求,请求进行中信号量剩 0 个许可,请求结束后剩 1 个(连跑 3 次相同)。
  • mem::replace:正常。 把就绪的那个换出来移进 future,把副本留在 self.inner。副本没就绪没关系,下一个请求之前调用方本来就会再 poll_ready。这就是 Service 文档里给的写法。

RateLimit 不会以这种方式出错:它没有 Clone,self.inner.clone() 编译不过。它在需要 Clone 的地方带来的是另一种错误,见 Clone is not satisfied。

📝NOTE
冷知识:这一节的 panic 是从 tonic 用户那里报上来的

issue #547(2021 年 1 月)的标题是「Combining a tower Service with a tonic client panics」。报告者升级到 tower 0.4.4 后,自己写的服务在 call 里 let mut inner = self.0.clone(); 再 inner.call(req),得到 panicked at 'buffer full; poll_ready must be called first',并且强调「Can confirm that poll_ready was in fact called」。这条信息是 0.4 的 Buffer 发出的,也就是说 tonic 的 Channel 背后有一个 Buffer。维护者的回复:「This subtly breaks the contract. The service is driven to ready and then cloned before it is invoked. The original service is ready, but the clone is not necessarily ready.」并给出了 mem::replace 的写法。

随后 PR #548「service: Clarify subtly around cloning and readiness」在 Service 文档里加了「Be careful when cloning inner services」一节,第一个包含它的发布是 tower-service 0.3.2。

那时 Buffer 的 panic 信息还是 tower 自己写的 buffer full; poll_ready must be called first(0.4.13 的 call 里对信号量许可的 expect)。0.5.0 的 #635 把 Buffer 改成直接用有界 mpsc(「This branch changes the buffer to use only a single bounded MPSC, rather than an unbounded MPSC and a semaphore」),许可由 PollSender 保管,信息就变成了上面表里 tokio-util 的那一句。用 0.4.13 跑同样的「不 ready 就 call」,得到的是:

thread 'main' (129379) panicked at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tower-0.4.13/src/buffer/service.rs:146:14:
buffer full; poll_ready must be called first

排查顺序

看到这几条 panic 之一时:

  1. 找到 panic 的那次 call,确认它的接收者和前面 poll_ready 的接收者是同一个实例。clone()、Layer::layer 新造的实例、Arc<Mutex<S>> 里取出来的另一份,都不算同一个。
  2. 自己写的中间件,call 里要把内层移进 future 时用 mem::replace;不需要移进 future 时直接 self.inner.call(req),把返回的 future 包起来。
  3. 不要在 future 里让副本自己 ready():同一个实例上的 poll_ready 占着的资源不会被释放。

小结

  • ConcurrencyLimit 没许可就 call 一定 panic;RateLimit 只在窗口次数用完后 panic,测试里不容易暴露;Reconnect 未连接时 panic;Buffer 的 panic 来自 tokio-util,信息是 `send_item` called without first calling `poll_reserve`。
  • 常见原因是 poll_ready 问的是原件、call 用的是 clone() 出来的副本;这几个中间件的 Clone 都不复制就绪状态。
  • 在 future 里让副本自己 oneshot 不 panic,但原件手里的许可或通道位置不放,上限为 1 时直接卡死。
  • 正确写法是 mem::replace 换出已经就绪的那个。

💬 关联讨论

发起讨论
加载中...