Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Clean up the pytest output during test/CI failure #129

Open
ca-scribner opened this issue Feb 9, 2024 · 1 comment
Open

Clean up the pytest output during test/CI failure #129

ca-scribner opened this issue Feb 9, 2024 · 1 comment
Labels
enhancement New feature or request

Comments

@ca-scribner
Copy link
Contributor

Context

When we have test failures, the pytest logs are very dense. There's often a lot of stuff like:

Task was destroyed but it is pending!
task: <Task pending name='Task_Receiver' coro=<Connection._receiver() running at /home/runner/work/istio-operators/istio-operators/.tox/cos-integration/lib/python3.8/site-packages/juju/client/connection.py:570> wait_for=<Future finished result=None> cb=[gather.<locals>._done_callback() at /usr/lib/python3.8/asyncio/tasks.py:769, gather.<locals>._done_callback() at /usr/lib/python3.8/asyncio/tasks.py:769]>
Task was destroyed but it is pending!
task: <Task pending name='Task_Pinger' coro=<Connection._pinger() running at /home/runner/work/istio-operators/istio-operators/.tox/cos-integration/lib/python3.8/site-packages/juju/client/connection.py:613> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f79d4a0e310>()]> cb=[gather.<locals>._done_callback() at /usr/lib/python3.8/asyncio/tasks.py:769, gather.<locals>._done_callback() at /usr/lib/python3.8/asyncio/tasks.py:769]>
Exception ignored in: <coroutine object Connection._pinger.<locals>._do_ping at 0x7f79d0292640>
Traceback (most recent call last):
  File "/home/runner/work/istio-operators/istio-operators/.tox/cos-integration/lib/python3.8/site-packages/juju/client/connection.py", line 606, in _do_ping
    await pinger_facade.Ping()
  File "/home/runner/work/istio-operators/istio-operators/.tox/cos-integration/lib/python3.8/site-packages/juju/client/facade.py", line 486, in wrapper
    reply = await f(*args, **kwargs)
  File "/home/runner/work/istio-operators/istio-operators/.tox/cos-integration/lib/python3.8/site-packages/juju/client/_client1.py", line 9012, in Ping
    reply = await self.rpc(msg)
  File "/home/runner/work/istio-operators/istio-operators/.tox/cos-integration/lib/python3.8/site-packages/juju/client/facade.py", line 659, in rpc
    result = await self.connection.rpc(msg, encoder=TypeEncoder)
  File "/home/runner/work/istio-operators/istio-operators/.tox/cos-integration/lib/python3.8/site-packages/juju/client/connection.py", line 667, in rpc
    result = await self._recv(msg['request-id'])
  File "/home/runner/work/istio-operators/istio-operators/.tox/cos-integration/lib/python3.8/site-packages/juju/client/connection.py", line 482, in _recv
    return await self.messages.get(request_id)
  File "/home/runner/work/istio-operators/istio-operators/.tox/cos-integration/lib/python3.8/site-packages/juju/utils.py", line 108, in get
    value = await self._queues[id].get()
  File "/usr/lib/python3.8/asyncio/queues.py", line 165, in get
    getter.cancel()  # Just in case getter is not done yet.
  File "/usr/lib/python3.8/asyncio/base_events.py", line 719, in call_soon
    self._check_closed()
  File "/usr/lib/python3.8/asyncio/base_events.py", line 508, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed
Task was destroyed but it is pending!
task: <Task pending name='Task-4680' coro=<Connection._pinger.<locals>._do_ping() done, defined at /home/runner/work/istio-operators/istio-operators/.tox/cos-integration/lib/python3.8/site-packages/juju/client/connection.py:604> wait_for=<Future cancelled> cb=[create_task_with_handler.<locals>._task_result_exp_handler(task_name='tmp', logger=<Logger juju....ion (WARNING)>)() at /home/runner/work/istio-operators/istio-operators/.tox/cos-integration/lib/python3.8/site-packages/juju/jasyncio.py:39, gather.<locals>._done_callback() at /usr/lib/python3.8/asyncio/tasks.py:769]>
Task was destroyed but it is pending!
task: <Task pending name='Task-4683' coro=<Event.wait() done, defined at /usr/lib/python3.8/asyncio/locks.py:296> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f79d4a0e100>()]> cb=[gather.<locals>._done_callback() at /usr/lib/python3.8/asyncio/tasks.py:769]>
Task was destroyed but it is pending!
task: <Task pending name='Task-4687' coro=<Connection.reconnect() running at /home/runner/work/istio-operators/istio-operators/.tox/cos-integration/lib/python3.8/site-packages/juju/client/connection.py:782>>
sys:1: RuntimeWarning: coroutine 'Connection.reconnect' was never awaited
RuntimeWarning: Enable tracemalloc to get the object allocation traceback
Task was destroyed but it is pending!
task: <Task pending name='Task-4685' coro=<Connection._pinger.<locals>._do_ping() done, defined at /home/runner/work/istio-operators/istio-operators/.tox/cos-integration/lib/python3.8/site-packages/juju/client/connection.py:604> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f79d4a0e1f0>()]> cb=[create_task_with_handler.<locals>._task_result_exp_handler(task_name='tmp', logger=<Logger juju....ion (WARNING)>)() at /home/runner/work/istio-operators/istio-operators/.tox/cos-integration/lib/python3.8/site-packages/juju/jasyncio.py:39]>
Task was destroyed but it is pending!
task: <Task pending name='Task-4686' coro=<Event.wait() done, defined at /usr/lib/python3.8/asyncio/locks.py:296> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f79d4a4f790>()]>>
cos-integration: 1844[572](https://github.com/canonical/istio-operators/actions/runs/7487616195/job/20380350554#step:4:573) C exit 1 (1828.76 seconds) /home/runner/work/istio-operators/istio-operators> pytest --show-capture=no --log-cli-level=INFO -vvs --tb=native --model cos-test tests/test_cos_integration.py pid=17428 [tox/execute/api.py:279]
  cos-integration: FAIL code 1 (1844.31=setup[15.55]+cmd[1828.76] seconds)
  evaluation failed :( (1844.37 seconds)

This makes it really hard to see what the actual error is. It wasn't always this way - has something changed? Have we got the wrong log settings, or are we using something improperly?

What needs to get done

  1. reduce the noise in our CI logs during failures

Definition of Done

see above

@ca-scribner ca-scribner added the enhancement New feature or request label Feb 9, 2024
Copy link

Thank you for reporting us your feedback!

The internal ticket has been created: https://warthogs.atlassian.net/browse/KF-5319.

This message was autogenerated

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement New feature or request
Projects
None yet
Development

No branches or pull requests

1 participant