Task mixing

[pronvis]

Copypasted of issue that I create in tokio: tokio-rs/tokio#3500

Version

    │   ├── tokio v1.1.0
    │   │   └── tokio-macros v1.0.0
    │   ├── tokio-util v0.6.2
    │   │   ├── tokio v1.1.0 (*)
    │   │   └── tokio-stream v0.1.2
    │   │       └── tokio v1.1.0 (*)
    │   ├── tokio v1.1.0 (*)
    ├── tokio v1.1.0 (*)
    ├── tokio-stream v0.1.2 (*)
    ├── tokio-util v0.6.2 (*)
    │   ├── tokio v1.1.0 (*)
    │   ├── tokio-stream v0.1.2 (*)
│   └── tokio v1.1.0 (*)
│       │   └── tokio v1.1.0 (*)
│       ├── tokio v1.1.0 (*)
│       ├── tokio-util v0.6.2 (*)
├── tokio v1.1.0 (*)
├── tokio-util v0.6.2 (*)

cargo tree | grep redis:

├── bb8-redis v0.8.0
│   └── redis v0.19.0

cargo tree | grep bb8:

├── bb8 v0.7.0
├── bb8-redis v0.8.0
│   ├── bb8 v0.7.0 (*)

Platform
Linux videotest01.dev.wb.ru 4.19.0-13-cloud-amd64 #1 SMP Debian 4.19.160-2 (2020-11-28) x86_64 GNU/Linux

Description
After moving to Tokio v1.0.1 our "reddis-proxy" service start to fail with "magic" errors:
Response was of incompatible type: "Response type not hashmap compatible" (response was status("PONG"))
This error happens when we call let response: redis::RedisResult<collections::HashMap<String, String>> = conn.hgetall(key).await;
Looks like async tasks mixed somehow and hgetall get response from PING request. Do not know where to dig into, will try with newer version of tokio...

---

We have async fn:

async fn ask_redis(
    redis_pool: Pool<RedisConnectionManager>,
) -> Result<_> {
    let mut conn = redis_pool.get().await?;
    let key = todo!();

    let response: redis::RedisResult<collections::HashMap<String, String>> =
        conn.hgetall(key).await;
    
    ...
}

That called ~10 times per second. And sometimes (in 10-20% cases) this line says: Response was of incompatible type: "Response type not hashmap compatible" (response was status("PONG")).

Redis-pool have logic inside, that sends PING requests to validate connection (I think it do that before each request in my case). So, looks like response on that requests goes in wrong future task... it is the only way (as I think) why hgetall can receive PONG string as a response. We do not have those values in redis.
And all works fine before we moved to tokio 1.x

[djc]

That's pretty surprising! It does indeed seem like there's an issue here with the <RedisConnectionManager as ManageConnection>::is_valid(), but I'm pretty confused that the call to PING and awaiting its result wouldn't take care of the PONG response. Can you produce a minimal reproduction of the issue?

[djc]

I noticed this in the Redis docs:

If the client is subscribed to a channel or a pattern, it will instead return a multi-bulk with a "pong" in the first position and an empty bulk in the second position, unless an argument is provided in which case it returns a copy of the argument.

Is your client subscribed to a channel or pattern?

[djc]

(Note that you don't need to bump the tokio dependency to 1.1 in the bb8 dependencies explicitly, since 1.1 is semver-compatible with 1.0. You can just use tokio 1.1 in your downstream dependency/application, and bb8 should pick it up.)

[HoldMyBeer1111]

Any chance it may be connected with redis-rs/redis-rs#308 ?

[HoldMyBeer1111]

Also we can have a look how it is implemented in mobc: https://github.com/importcjj/mobc/blob/87ae0152a51c0526caee9bd87455acf20cc778cb/mobc-redis/src/lib.rs#L30

[pronvis]

Is your client subscribed to a channel or pattern?

no, we don't

[djc]

@invis87 maybe you can try with the explicit return type as suggested in redis-rs/redis-rs#308?

[pronvis]

@djc I already have it: let response: redis::RedisResult<collections::HashMap<String, String>> = conn.hgetall(key).await;

[djc]

I meant in the ConnectionManager::is_valid() code.

[pronvis]

I don't know how to reproduce that bug. Sometimes service "moved to buggy state" and then there are a lot of Response was of incompatible type: "Response type not hashmap compatible" (response was status("PONG")) until restart, but usually it works fine.
Looks like I need to wait for that state to appear and then trying to catch the problem with gdb.

Buuut, I will try to fix ConnectionManager::is_valid() anyway :)

[pronvis]

Hmmm, interesting!
With those dependencies:

bb8 = "0.7.0"
bb8-redis = "0.8.1"

Service still have response was status("PONG") errors - much less then with version without fix, but still.

On the other hand, with deps:

bb8 = { git = "https://github.com/invis87/bb8.git", branch = "fix_ping_request" }
bb8-redis = { git = "https://github.com/invis87/bb8.git", branch = "fix_ping_request" }

Number if errors is zero.

[djc]

That is surprising. Did you correct for other differences in the Cargo.lock file?