Channel Close callback gets called multiple times in version 6.8.2

[jpieger]

This is a regression I found going from version 6.8.1 to 6.8.2. If a callback is registered on a channel object via add_close_callback(), then this callback is triggered once in 6.8.1 and twice in 6.8.2.

Additionally, in 6.8.2 an error log is triggered, even when the channel was closed normally and no error happened. This seems to have the same underlying cause as the double callback.

The following minimal example reproduces the issue:

import aio_pika
connection = await aio_pika.connect_robust("amqp://guest:guest@localhost")
channel = await connection.channel()

channel.add_close_callback(lambda *args: print("Closing", args))

await channel.close()

Using aio-pika 6.8.1 it outputs the following:

 Closing (<RobustChannel "None#Not initialized channel">, None)

And in 6.8.2:

Closing (<RobustChannel "None#Not initialized channel">, <Future finished exception=CancelledError()>)
Robust channel <RobustChannel "None#Not initialized channel"> has been closed.
NoneType: None
Closing (<RobustChannel "None#Not initialized channel">, None)

The line "Robust channel [...] has been closed" is the error log statement that is additionally triggered. I believe this is because the first time the callback is triggered, it carries an CancelledError exception. However this is not a "real" exception, as there are no type/traceback information attached (as seen from the "NoneType: None" output). Grepping over the code makes me believe, that the exception object originates from this default parameter.

[raspe88]

I can verify this issue. Found the same issue.

[mosquito]

@jpieger unfortunately, I am currently spending all my free time on the release of the new major version of aiopika==7.0.0, if you try to reproduce it on the new version, you will help me a lot.

You can install the beta version with this command: pip install --pre 'aio-pika~=7.0.0b6'

[jpieger]

I could not reproduce it on version 7.0.0.

Checking the diff between 6.8.1 and 6.8.2, I think it is this line that introduces the bug.

[mosquito]

Checking the diff between 6.8.1 and 6.8.2, I think it is this line that introduces the bug.

Obviously yes, but the problem is not with this change directly. The problem seems to be that in the new version, the channel state is calculated a little differently and it's probably not reproducing.

[mosquito]

@jpieger I am endlessly interested in how the migration process to version 7 went. Did I have to change something in your code?

Please write as much as possible about this.

[jpieger]

In our codebase we imported pamqp.specification in a few places, this module was no longer available in 7.0.0. I patched the code with a few dirty hacks to avoid the import errors, but that was the only code change necessary. After that our testsuite ran without errors. I did not explore the topic in more depth, but our testsuite did fail with 6.8.2.

[mosquito]

Thank you for your answer, it is very important for me to understand the problems of migration right now.

If there is anything else, please write a comment here.

[DriverX]

+1

After upgrade 6.8.1 -> 6.8.2 we have a lot log messages like that with logging.ERROR level

Robust channel <RobustChannel "None#Not initialized channel"> has been closed.
NoneType: None

I guess NoneType: None is traceback exception, but looks strange.

I hope the hotfix is on the way.

[mosquito]

@jpieger in the version 7, the problem should not manifest itself. Unfortunately, I have no desire to maintain branch 6 apart. Please feel free to reopen this issue when it's actually reproducing.