Tried to handle an error where no error existed

[Avivsalem]

hi. we're using pika 0.13.0.
we get the 'Tried to handle an error where no error existed' error log while consuming messages...
the reason i open this issue, is that we studied it a little bit.
first of all, looking at 0.13.0 code, we see that
this line

pika/pika/adapters/base_connection.py

Line 421 in df10c15

LOGGER.error('Error event %r, %r', events, error)

gets called (with error=None), and then it leads to this line:

pika/pika/adapters/base_connection.py

Line 354 in df10c15

LOGGER.critical("Tried to handle an error where no error existed")

the event we get is 25 (8 bit is on, so it's an error). but the error log is written because 'error' is None.

the culprit, is this line:

pika/pika/adapters/select_connection.py

Line 831 in df10c15

handler(fileno, events)

, that calles the handle_error function, with no 'error' param, making it the default None...

the weird part, is the way we encountered it.
we're using the blocking_connection.consume() generator. for some older reason, we passed inactivity_timeout=0.01, which worked fine...
when we changed it to inactivity_timeout=0.0, the error log started to appear. (and when we changed it back, it disappeared again...)

i thought you might want to look at it. although, i noticed that at the master branch, the lines i mentioned above, are not existent. is there a release coming soon with the new code?

thanks!

[lukebakken]

Thanks for the report @Avivsalem . Calling inactivity_timeout=0.0 is allowed but doesn't really make sense. I'll either disallow it or figure out why this error happens.

i noticed that at the master branch, the lines i mentioned above, are not existent. is there a release coming soon with the new code?

Please give 1.0.0b2 a try in your environment. The 1.0.0 release will happen once I get more feedback about the beta release. I don't expect there to be any more API changes for 1.0.0 so you won't be wasting time by changing your code to accomodate them. All of the code in the examples/ directory has already been updated for master.

NOTE: the 1.0.0 release has API changes that are detailed here,

[lukebakken]

@Avivsalem I also suggest joining the pika-python mailing list if you haven't already. Thanks!

[lukebakken]

I can't reproduce this using Python 3.7.2 or 2.7.15 using 0.13.0b1 and inactivity_timeout=0.0 (code).

If you can think of what might be different in your environment, I'd appreciate it. Thanks! I will re-open this issue if new information allows me to reproduce it.

[Avivsalem]

We're using 0.13.0 release from pypi (don't know the difference between that and 0.13.0b1)
Second, it happens sporadically on our most heavy consumers.

We use prefetch_count=1
and we consume from mirrored queues if that matters...
Also, we have multiple consumer channels on same connection

[Avivsalem]

And by multiple consumers, I mean in a one thread round Robin fashion... I'll try to post a gist later...

[Avivsalem]

@lukebakken
Still didn't manage to pull the code for a gist... But I have some thought about what might be happening...

If you set the heartbeat for a short enough time, and then run the code you wrote on an EMPTY queue, with inactivity_timeout=0.0, eventually, the error will occur (after heartbeat.)
I think it's because when inactivity_timeout=0, the code doesn't process the heartbeats at all... Makes sense?

[Avivsalem]

@lukebakken
followed it more into the code...
the lines in questions are:

pika/pika/adapters/blocking_connection.py

Line 1940 in df10c15

self.connection.process_data_events(time_limit=delta)

is called with time_limit=0
then

pika/pika/adapters/blocking_connection.py

Line 752 in df10c15

self._flush_output(timer.is_ready, common_terminator)

is called, with a _IoloopTimerContext that has 0 as time_limit,
and finally this

pika/pika/adapters/blocking_connection.py

Line 457 in df10c15

while not is_done():

doesn't enter the while loop at all... so

 self._impl.ioloop.poll()
 self._impl.ioloop.process_timeouts()

never gets called...

i believe this is the main difference between 0.0 and 0.01... and the reason for the metioned error... (this, combined with the fact that the heartbeat interval has passed, and was not handled on an empty queue).

i know this is a "voodo" scenario, but we actually encounter this.

[lukebakken]

Wow, thank you for the detailed analysis! I'll check it out today. Have a great weekend!

[Avivsalem]

You too! Thanks for your time.

[lukebakken]

@Avivsalem what heartbeat timeout settings have you tried to reproduce this issue?

@vitaly-krugl - if you have a few minutes to look at this I would appreciate it. It looks as though when inactivity_timeout=0.0 is used, this code won't ever get called, and if a queue is empty heartbeats may not be sent to RabbitMQ because of that.

[Avivsalem]

We use heartbeat=300

[lukebakken]

Well, I still haven't been able to reproduce this yet using the default heartbeat value or 300. Since there is a workaround (don't use 0 for inactivity_timeout) I am going to remove this from the 1.0.0 milestone.

[vitaly-krugl]

Hi Luke, unfortunately I am unable to give it attention at this time. Sorry, Vitaly

…

On Tue, Mar 12, 2019, 4:19 PM Luke Bakken ***@***.***> wrote: @Avivsalem <https://github.com/Avivsalem> what heartbeat timeout settings have you tried to reproduce this issue? @vitaly-krugl <https://github.com/vitaly-krugl> - if you have a few minutes to look at this I would appreciate it. It looks as though when inactivity_timeout=0.0 is used, this code <https://github.com/pika/pika/blob/master/pika/adapters/blocking_connection.py#L514-L515> won't ever get called, and if a queue is empty heartbeats may not be sent to RabbitMQ because there. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#1195 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABX9Kv0NbLpvBxQCFkN4pBH_jedb92prks5vWDXlgaJpZM4bje6T> .