Actix-webのミドルウェア内のメソッドが二度発火してしまう。

Question

前提・実現したいこと

初質問で、文章がおかしい部分があると思います。申し訳ないです。

Rustを最近学び、自プロジェクトで実際に利用したいと思い立ち、actix-webを使用しWebAPIを作成しています。
その中でヘッダー情報のToken情報を認証サーバーにgrpc(tonicを使用)経由で送信し、バリデーションを行うミドルウェアを現在製作しているのですが、いざ実装して動作確認をしたところ自作したLoggerのメソッドが二度発火してしまうということが起きてしまいました。
このままではLoggerが見づらくなってしまう他、この後実装予定のgrpcの送受信メソッドが二重に発火してしまうのではないかと考え、原因を探ろうとしたのですがFutures等を利用した非同期処理などの勉強が不足しているせいか全く分かりませんでした。

「なぜ二回発火しているのか」
「どう回避すればいいのか」
「現在の実装が完全に間違っている、もしくはバグを生む懸念がある場所があるのか」
この三点を知りたいです。

これは我儘ですが「Rustのデバッグ方法」も教えてくださるとありがたいです…

発生している問題・エラーメッセージ

TestMiddlewareProcess内のcallメソッドにあるLoggerのメソッドにて表示されるメッセージが二度流れている。

    // auth.rs LINE: 43
    fn call(&self, req: ServiceRequest) -> Self::Future {
        let logger = Rc::new(Logger::new(Some("TestMiddleware")));

        // Why is this method firing twice...
        logger.debug("task call from middleware start.");
        // 以下略
    }

該当のソースコード

コードはActix-webに標準で実装されているLoggerを参考に実装しました。
自プロジェクトをGithubにプッシュしようにも原因が分からないバグ（？）を残したまましたくないので、該当部分を切り出したプロジェクトを製作し、テストしました。
actix_middleware_test

ミドルウェアのソースコード

use std::cell::RefCell;
use std::pin::Pin;
use std::rc::Rc;
use std::task::{Context, Poll};
use actix_web::dev::{Service, Transform, ServiceRequest, ServiceResponse};
use futures::Future;
use futures::future::{ok, Ready};
use crate::logger::Logger;

pub struct TestMiddleware;
pub struct TestMiddlewareProcess<S> { service: Rc<RefCell<S>> }

impl<S: 'static, B> Transform<S, ServiceRequest> for TestMiddleware
    where S: Service<ServiceRequest, Response = ServiceResponse<B>, Error = actix_web::Error>,
          S::Future: 'static,
          B: 'static
{
    //type Request = ServiceRequest;
    type Response = ServiceResponse<B>;
    type Error = actix_web::Error;
    type Transform = TestMiddlewareProcess<S>;
    type InitError = ();
    type Future = Ready<Result<Self::Transform, Self::InitError>>;

    fn new_transform(&self, service: S) -> Self::Future {
        ok(TestMiddlewareProcess { service: Rc::new(RefCell::new(service)) })
    }
}

impl<S, B> Service<ServiceRequest> for TestMiddlewareProcess<S>
    where S: Service<ServiceRequest, Response = ServiceResponse<B>, Error = actix_web::Error> + 'static,
          S::Future: 'static,
          B: 'static
{
    type Response = ServiceResponse<B>;
    type Error = actix_web::Error;
    type Future = S::Future;//Pin<Box<dyn Future<Output = Result<Self::Response, Self::Error>>>>;

    fn poll_ready(&self, ctx: &mut Context<'_>) -> Poll<Result<(), Self::Error>> {
        self.service.poll_ready(ctx)
    }

    fn call(&self, req: ServiceRequest) -> Self::Future {
        let logger = Rc::new(Logger::new(Some("TestMiddleware")));

        // Why is this method firing twice...
        logger.debug("task call from middleware start.");

        // Todo: Write Token Validator Task (2021/12/30 23:54)

        self.service.call(req)
        // Box::pin(async move {
        //     let res = serv.call(req).await?;
        //     println!("headers: {:?}", res.headers());
        //     logger.debug("cage task call from middleware response");
        //
        //     Ok(res)
        // })
    }
}

試したこと

・actix-webのバージョンを3.3.2から4.0.0-beta.13にアップデートした。
・LoggerをRc<T>でラップした。（Rcをよく理解できていない）
・env_loggerを利用し、どの様にコードが実行されているのか観測しようとしたがenv_logger自体の発火しているタイミングなどが分からなかった。

補足情報

・CLion 2021.2.3 (Build #CL-212.5457.51, built on October 14, 2021)
・IntellijRust plugin (0.4.160.4261-212)
・cargo 1.58.0-nightly (2e2a16e98 2021-11-08)
・rustup 1.24.3 (ce5817a94 2021-05-31)
・rustc 1.58.0-nightly (82af160c2 2021-11-10)

Cargo.toml

[package]
name = "actix_middleware_test"
version = "0.1.0"
edition = "2021"

# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html

[dependencies]
actix-web = "4.0.0-beta.13"
env_logger = "0.6.2"
futures = "0.3.18"
tokio = { version = "1.12.0", features = ["full"] }
yansi = "0.5.0"
chrono = "0.4.19"
serde = "1.0.130"
serde_json = "1.0.68"
serde_derive = "1.0.130"

追加情報

・rustup override set を使用してrustc 1.56.0 (09c42c458 2021-10-18)に切り替えて実行したところ特に解決するということは起こりませんでした。

・Cargo.toml内のEditionを2021から2018に変更しても同じ事が起きます。

・ブラウザ等の環境問題も疑い、こちらのコードを拝借して実行したところ、二重で発火するということは起こりませんでした。
なお、このコードの依存関係のバージョンを今のプロジェクトに合わせると変更が大きく加わるのでアップデート等の操作は行っていません。

コードの変更箇所

    // main.rs LINE: 82
    fn call(&mut self, mut service_request: Self::Request) -> Self::Future {
    	println!("task start!"); //　デバッグ用に追加

        // if Request path is "/hack_secret", then overwrite truly secret uri.
        if service_request.path() == "/hack_secret" {
            let secret_uri = "/f18b211dd1744570bb643e800308b1e4"
                .parse::<http::Uri>()
                .unwrap();
            service_request
                .match_info_mut()
                .get_mut()
                .update(&secret_uri);
        }
        Box::new(self.service.call(service_request).map(|mut res| {
            // When this middleware is set, it append my custom header to received response.
            let header_name = http::HeaderName::from_lowercase(b"hacker-code").unwrap();
            let header_value =
                http::HeaderValue::from_str("69de96e2-d5b0-41d4-89b8-864222140e24").unwrap();
            res.headers_mut().append(header_name, header_value);
            res
        }))
    }
}

・また、テストに使用しているLoggerをprintln!()に置き換えても該当部分の二重発火は観測できました。

コードの変更箇所

    // auth.rs LINE: 43
    fn call(&self, req: ServiceRequest) -> Self::Future {
        let logger = Rc::new(Logger::new(Some("TestMiddleware")));
        //let serv = self.service.clone();

        // Why is this method firing twice...
        //logger.debug("task call from middleware start.");
        println!("task call from middleware start."); // printlnマクロに変更

        // Todo: Write Token Validator Task (2021/12/30 23:54)

        self.service.call(req)
        // Box::pin(async move {
        //     let res = serv.call(req).await?;
        //     println!("headers: {:?}", res.headers());
        //     // ここにあるメソッドも二度実行された。
        //     logger.debug("cage task call from middleware response");
        //
        //     Ok(res)
        // })
    }

Comments

[equal-l2]

actix_middleware_test を実行してみましたが、middlewareのコードが2度呼ばれる不具合は再現できませんでした
stableで実行しています

Answer 1

二重で発火する原因が分かりました。
今回レスポンスを確認するためのデバッグにGoogleChromeを使用していたのですが、今回はそれが原因でした。
Chromeでリクエストする際に通常のリソースリクエスト一緒にfavicon.icoを入手するためにもう一度リクエストを送信している故に二重で発火しているように見えているということが今回原因でした。
WebAPI開発用のツールで著名なPostmanを使用しデバッグした際、二重で発火するということは起こらず、正しい処理が走りました。

テストする際のツールが原因というのは完全に見逃していました。
今後開発する際の反省点とさせて頂きます。