nats.py icon indicating copy to clipboard operation
nats.py copied to clipboard

nc.flush times out after keyboard interrupt

Open pohlt opened this issue 2 years ago • 1 comments

Setup

  • nats-py: 2.0.0
  • Python 3.10.3
  • OS: Linux 5.16.16

Test Code

import asyncio
from nats.aio.client import Client

async def main():
    nc = Client()
    await nc.connect("nats://localhost:54100", name="test")
    sub = await nc.subscribe("subject")

    try:
        await asyncio.Future()
    except asyncio.CancelledError:
        print("cancelled")

    print("before unsubscribe")
    await sub.unsubscribe()
    print("before flush")
    await nc.flush()
    print("before close")
    await nc.close()
    print("done")


asyncio.run(main(), debug=True)

Behavior

When I run this code, I can successfully connect to the NATS server and subscribe to the topic. The code will then wait for a keyboard interrupt which cancels the Future. During the shutdown, I unsubscribe from the topic, flush, and close the connection.

I experience two unexpected behaviors:

  1. The unsubscribe never actually happens.
  2. The flush times out.

Here is the output from the NATS server started with -D -V:

[1] 2022/03/27 08:32:09.155429 [DBG] [::1]:60536 - cid:49 - Client connection created
[1] 2022/03/27 08:32:09.156595 [TRC] [::1]:60536 - cid:49 - <<- [CONNECT {"echo": true, "headers": true, "lang": "python3", "name": "test", "no_responders": true, "pedantic": false, "protocol": 1, "verbose": false, "version": "2.0.0"}]
[1] 2022/03/27 08:32:09.156632 [TRC] [::1]:60536 - cid:49 - "v2.0.0:python3:test" - <<- [PING]
[1] 2022/03/27 08:32:09.156635 [TRC] [::1]:60536 - cid:49 - "v2.0.0:python3:test" - ->> [PONG]
[1] 2022/03/27 08:32:09.157726 [TRC] [::1]:60536 - cid:49 - "v2.0.0:python3:test" - <<- [SUB subject  1]
[1] 2022/03/27 08:32:11.513880 [DBG] [::1]:60536 - cid:49 - "v2.0.0:python3:test" - Client Ping Timer
[1] 2022/03/27 08:32:11.513941 [TRC] [::1]:60536 - cid:49 - "v2.0.0:python3:test" - ->> [PING]
[1] 2022/03/27 08:32:11.515060 [TRC] [::1]:60536 - cid:49 - "v2.0.0:python3:test" - <<- [PONG]

<Keyboard Interrupt>

[1] 2022/03/27 08:32:15.002813 [TRC] [::1]:60536 - cid:49 - "v2.0.0:python3:test" - <<- [PING]
[1] 2022/03/27 08:32:15.002842 [TRC] [::1]:60536 - cid:49 - "v2.0.0:python3:test" - ->> [PONG]

<10s timeout for flush>

[1] 2022/03/27 08:32:25.024747 [DBG] [::1]:60536 - cid:49 - "v2.0.0:python3:test" - Client connection closed: Client Closed
[1] 2022/03/27 08:32:25.024781 [TRC] [::1]:60536 - cid:49 - "v2.0.0:python3:test" - <-> [DELSUB 1]

<Note the missing UNSUB>

Questions

  1. Shouldn't I use flush during shutdown?
  2. What's The Right Thing(tm) to do during a clean shutdown?

Thanks a lot for your work on nats-py and for looking into this issue.

pohlt avatar Mar 27 '22 06:03 pohlt

Same here.

Note: I use Jetstream with the 2.8.1 server version. Client version 2.1.0 Note2: I personally use drain to cancel all subscriptions.

Hope that helps.

Mokto avatar May 05 '22 05:05 Mokto