CI: test_mutable_errback_called_by_chord_from_group_fail_multiple fails often

[woutdenolf]

I see this test fail often in CI

 =================================== FAILURES ===================================
  _ test_chord.test_mutable_errback_called_by_chord_from_group_fail_multiple[errback_old_style] [Error propagates from body group] _
  
  self = <celery.backends.redis.ResultConsumer object at 0x7f6132ec6710>
  result = <GroupResult: 8d8dfee3-a5fc-4c82-8a89-fc1d10beef7d [aef15b21-9fa3-4862-b37c-3d0c04fb1577, 0d02d76a-82de-4788-944f-fb3e...dc3, 68473988-4cef-4f6e-b556-df28d8b22560, 16ef8f73-7e94-4cb6-8d95-dc38d1b52416, d88e2c60-e2dc-420c-9e57-76e07f27f6aa]>
  timeout = 60, on_interval = None, on_message = None
  kwargs = {'interval': 0.5, 'no_ack': True}, prev_on_m = None, _ = None
  
      def _wait_for_pending(self, result,
                            timeout=None, on_interval=None, on_message=None,
                            **kwargs):
          self.on_wait_for_pending(result, timeout=timeout, **kwargs)
          prev_on_m, self.on_message = self.on_message, on_message
          try:
  >           for _ in self.drain_events_until(
                      result.on_ready, timeout=timeout,
                      on_interval=on_interval):
  
  celery/backends/asynchronous.py:287: 
  _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
  
  self = <celery.backends.asynchronous.Drainer object at 0x7f6132ec6560>
  p = <promise@0x7f6132f0bd90>, timeout = 60, interval = 1, on_interval = None
  wait = <bound method ResultConsumer.drain_events of <celery.backends.redis.ResultConsumer object at 0x7f6132ec6710>>
  
      def drain_events_until(self, p, timeout=None, interval=1, on_interval=None, wait=None):
          wait = wait or self.result_consumer.drain_events
          time_start = time.monotonic()
      
          while 1:
              # Total time spent may exceed a single call to wait()
              if timeout and time.monotonic() - time_start >= timeout:
  >               raise socket.timeout()
  E               TimeoutError
  
              redis_connection.delete(fail_sig_id)
          with subtests.test(msg="Error propagates from body group"):
              res = chord_sig.delay()
              sleep(1)
              with pytest.raises(ExpectedException):
  >               res.get(timeout=TIMEOUT)
  
  t/integration/test_canvas.py:2521: 
  _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
  celery/result.py:675: in get
      return (self.join_native if self.supports_native_join else self.join)(
  celery/result.py:797: in join_native
      for task_id, meta in self.iter_native(timeout, interval, no_ack,
  celery/backends/asynchronous.py:172: in iter_native
      for _ in self._wait_for_pending(result, no_ack=no_ack, **kwargs):
  _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
  
  self = <celery.backends.redis.ResultConsumer object at 0x7f6132ec6710>
  result = <GroupResult: 8d8dfee3-a5fc-4c82-8a89-fc1d10beef7d [aef15b21-9fa3-4862-b37c-3d0c04fb1577, 0d02d76a-82de-4788-944f-fb3e...dc3, 68473988-4cef-4f6e-b556-df28d8b22560, 16ef8f73-7e94-4cb6-8d95-dc38d1b52416, d88e2c60-e2dc-420c-9e57-76e07f27f6aa]>
  timeout = 60, on_interval = None, on_message = None
  kwargs = {'interval': 0.5, 'no_ack': True}, prev_on_m = None, _ = None
  
      def _wait_for_pending(self, result,
                            timeout=None, on_interval=None, on_message=None,
                            **kwargs):
          self.on_wait_for_pending(result, timeout=timeout, **kwargs)
          prev_on_m, self.on_message = self.on_message, on_message
          try:
              for _ in self.drain_events_until(
                      result.on_ready, timeout=timeout,
                      on_interval=on_interval):
                  yield
                  sleep(0)
          except socket.timeout:
  >           raise TimeoutError('The operation timed out.')
  E           celery.exceptions.TimeoutError: The operation timed out.
  
  celery/backends/asynchronous.py:293: TimeoutError

[open-collective-bot]

Hey @woutdenolf 👋,
Thank you for opening an issue. We will get back to you as soon as we can.
Also, check out our Open Collective and consider backing us - every little helps!

We also offer priority support for our sponsors.
If you require immediate assistance please consider sponsoring us.

[woutdenolf]

The test was introduced in #6814. @maybe-sybr Any ideas?

[woutdenolf]

Some recent failures on the master branch

• a failure with errback_new_style and redis:
  https://github.com/celery/celery/actions/runs/3267103097/jobs/5372065653
• a failure with old_new_style and redis:
  https://github.com/celery/celery/actions/runs/3259818925/jobs/5352989449
• a failure with errback_new_style and rabbitmq:
  https://github.com/celery/celery/actions/runs/3279300420/jobs/5398797243
• a failure with errback_new_style and rabbitmq_redis:
  https://github.com/celery/celery/actions/runs/3263710991/jobs/5363372508
• a failure with old_new_style and rabbitmq_redis:
  https://github.com/celery/celery/actions/runs/3262407386/jobs/5359634501

[woutdenolf]

Seems this was known when creating the test (although the comment below was related to test_mutable_errback_called_by_chord_from_group)

    This and the `res.get()` in the subtest below seem to sometimes
    time out and I can't work out why. It seems to only really occur when
    I run the full suite (redis backend) or run `tox -e ... -- -k test_canvas`
    to select the canvas integration tests.

I can't mark them as flaky since subtests don't play nicely with that decorator :(

Originally posted by @maybe-sybr in #6814 (comment)

[Nusnus]

I've seen it as well for some time now. I suspect the problem lies here.
Let me check it out.

[Nusnus]

I have a fix attempt at #7837, you're welcome to check it out @woutdenolf.