test_clusterip_service_endpoint Failed to connect to clusterIP port 80 after x ms: Connection timed out

Bug #1997589 reported by Bas de Bruijne
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Charmed Kubernetes Testing
New
Undecided
Unassigned

Bug Description

In testrun https://solutions.qa.canonical.com/v2/testruns/a9c727a4-7670-49ee-a617-127787248841 (ck8s 1.25 on jammy, juju3), the test suite fails with:

```
=================================== FAILURES ===================================
_______________________ test_clusterip_service_endpoint ________________________
Traceback (most recent call last):
  File "/home/ubuntu/k8s-validation/jobs/integration/test_service_endpoints.py", line 122, in test_clusterip_service_endpoint
    action = await juju_run(unit, cmd)
  File "/home/ubuntu/k8s-validation/jobs/integration/utils.py", line 623, in juju_run
    raise JujuRunError(unit, cmd, result)
integration.utils.JujuRunError: `curl -vk --noproxy "10.152.183.59" http://10.152.183.59:80` failed on kubernetes-worker/4:

* Trying 10.152.183.59:80...
  % Total % Received % Xferd Average Speed Time Time Time Current
                                 Dload Upload Total Spent Left Speed

  0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:01 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:02 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:03 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:04 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:05 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:06 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:07 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:08 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:09 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:10 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:11 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:12 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:13 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:14 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:15 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:16 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:17 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:18 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:19 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:20 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:21 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:22 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:23 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:24 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:25 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:26 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:27 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:28 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:29 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:30 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:31 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:32 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:33 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:34 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:35 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:36 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:37 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:38 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:39 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:40 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:41 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:42 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:43 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:44 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:45 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:46 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:47 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:48 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:49 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:50 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:51 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:52 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:53 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:54 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:55 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:56 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:57 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:58 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:00:59 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:00 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:01 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:02 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:03 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:04 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:05 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:06 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:07 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:08 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:09 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:10 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:11 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:12 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:13 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:14 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:15 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:16 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:17 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:18 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:19 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:20 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:21 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:22 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:23 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:24 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:25 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:26 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:27 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:28 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:29 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:30 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:31 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:32 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:33 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:34 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:35 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:36 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:37 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:38 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:39 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:40 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:41 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:42 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:43 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:44 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:45 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:46 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:47 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:48 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:49 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:50 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:51 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:52 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:53 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:54 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:55 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:56 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:57 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:58 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:01:59 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:02:00 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:02:01 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:02:02 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:02:03 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:02:04 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:02:05 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:02:06 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:02:07 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:02:08 --:--:-- 0
  0 0 0 0 0 0 0 0 --:--:-- 0:02:09 --:--:-- 0* connect to 10.152.183.59 port 80 failed: Connection timed out
* Failed to connect to 10.152.183.59 port 80 after 129467 ms: Connection timed out

  0 0 0 0 0 0 0 0 --:--:-- 0:02:09 --:--:-- 0
* Closing connection 0
curl: (28) Failed to connect to 10.152.183.59 port 80 after 129467 ms: Connection timed out
------------------------------ Captured log call -------------------------------
INFO sh.command:sh.py:646 <Command '/snap/bin/kubectl create deployment hello-world --image=rocks.canonical.com/cdk/google-samples/hello-app:1.0', pid 80102>: process started
INFO sh.command:sh.py:646 <Command '/snap/bin/kubectl set env deployment/hello-world PORT=50000', pid 80129>: process started
INFO sh.command:sh.py:646 <Command '/snap/bin/kubectl expose deployment hello-world --type=ClusterIP --name=hello-world --protocol=TCP --port=80 --target-port=50000', pid 80157>: process started
INFO sh.command:sh.py:646 <Command '/snap/bin/kubectl get po -o yaml --selector=app=hello-world', pid 80184>: process started
INFO sh.command:sh.py:646 <Command '/snap/bin/kubectl get po -o yaml --selector=app=hello-world', pid 80210>: process started
INFO sh.command:sh.py:646 <Command '/snap/bin/kubectl get po -o yaml --selector=app=hello-world', pid 80236>: process started
INFO sh.command:sh.py:646 <Command '/snap/bin/kubectl get svc -o yaml --selector=app=hello-world', pid 80263>: process started
INFO sh.command:sh.py:646 <Command '/snap/bin/kubectl delete deployment hello-world', pid 80291>: process started
INFO sh.command:sh.py:646 <Command '/snap/bin/kubectl delete service hello-world', pid 80318>: process started
INFO sh.command:sh.py:646 <Command '/snap/bin/kubectl get po -o yaml --selector=app=hello-world', pid 80344>: process started
INFO sh.command:sh.py:646 <Command '/snap/bin/kubectl get po -o yaml --selector=app=hello-world', pid 80370>: process started
=============================== warnings summary ===============================
.tox/py3/lib/python3.10/site-packages/invoke/loader.py:3
  /home/ubuntu/k8s-validation/.tox/py3/lib/python3.10/site-packages/invoke/loader.py:3: DeprecationWarning: the imp module is deprecated in favour of importlib and slated for removal in Python 3.12; see the module's documentation for alternative uses
    import imp

jobs/integration/conftest.py:531
  /home/ubuntu/k8s-validation/jobs/integration/conftest.py:531: PytestDeprecationWarning: The hookimpl pytest_metadata uses old-style configuration options (marks or attributes).
  Please use the pytest.hookimpl(optionalhook=True) decorator instead
   to configure the hooks.
   See https://docs.pytest.org/en/latest/deprecations.html#configuring-hook-specs-impls-using-markers
    @pytest.mark.optionalhook

-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
- generated xml file: /home/ubuntu/project/generated/kubernetes-maas/k8s-suite/test_clusterip_service_endpoint-junit.xml -
----- generated html file: file:///home/ubuntu/k8s-validation/report.html ------
=========================== short test summary info ============================
FAILED jobs/integration/test_service_endpoints.py::test_clusterip_service_endpoint
================== 1 failed, 2 warnings in 152.73s (0:02:32) ===================
Task was destroyed but it is pending!
task: <Task pending name='Task-36' coro=<WebSocketCommonProtocol.keepalive_ping() running at /home/ubuntu/k8s-validation/.tox/py3/lib/python3.10/site-packages/websockets/legacy/protocol.py:1234> wait_for=<Future pending cb=[Task.task_wakeup()]>>
Task was destroyed but it is pending!
task: <Task pending name='Task-43' coro=<Connection._pinger() running at /home/ubuntu/k8s-validation/.tox/py3/lib/python3.10/site-packages/juju/client/connection.py:583> wait_for=<Future pending cb=[Task.task_wakeup()]>>
Fatal error on SSL transport
protocol: <asyncio.sslproto.SSLProtocol object at 0x7f429ad319f0>
transport: <_SelectorSocketTransport closing fd=10>
Traceback (most recent call last):
  File "/usr/lib/python3.10/asyncio/selector_events.py", line 916, in write
    n = self._sock.send(data)
OSError: [Errno 9] Bad file descriptor

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.10/asyncio/sslproto.py", line 690, in _process_write_backlog
    self._transport.write(chunk)
  File "/usr/lib/python3.10/asyncio/selector_events.py", line 922, in write
    self._fatal_error(exc, 'Fatal write error on socket transport')
  File "/usr/lib/python3.10/asyncio/selector_events.py", line 717, in _fatal_error
    self._force_close(exc)
  File "/usr/lib/python3.10/asyncio/selector_events.py", line 729, in _force_close
    self._loop.call_soon(self._call_connection_lost, exc)
  File "/usr/lib/python3.10/asyncio/base_events.py", line 750, in call_soon
    self._check_closed()
  File "/usr/lib/python3.10/asyncio/base_events.py", line 515, 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-35' coro=<WebSocketCommonProtocol.transfer_data() running at /home/ubuntu/k8s-validation/.tox/py3/lib/python3.10/site-packages/websockets/legacy/protocol.py:945> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[Task.task_wakeup(), _wait.<locals>._on_completion() at /usr/lib/python3.10/asyncio/tasks.py:475]>
Task was destroyed but it is pending!
task: <Task pending name='Task-37' coro=<WebSocketCommonProtocol.close_connection() running at /home/ubuntu/k8s-validation/.tox/py3/lib/python3.10/site-packages/websockets/legacy/protocol.py:1289> wait_for=<Task pending name='Task-35' coro=<WebSocketCommonProtocol.transfer_data() running at /home/ubuntu/k8s-validation/.tox/py3/lib/python3.10/site-packages/websockets/legacy/protocol.py:945> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[Task.task_wakeup(), _wait.<locals>._on_completion() at /usr/lib/python3.10/asyncio/tasks.py:475]>>
Task was destroyed but it is pending!
task: <Task pending name='Task-38' coro=<Connection._receiver() running at /home/ubuntu/k8s-validation/.tox/py3/lib/python3.10/site-packages/juju/client/connection.py:535> wait_for=<Future pending cb=[Task.task_wakeup()]>>
Exception ignored in: <coroutine object WebSocketCommonProtocol.close_connection at 0x7f429b0c2c00>
Traceback (most recent call last):
  File "/home/ubuntu/k8s-validation/.tox/py3/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 1329, in close_connection
    await self.close_transport()
  File "/home/ubuntu/k8s-validation/.tox/py3/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 1347, in close_transport
    if await self.wait_for_connection_lost():
  File "/home/ubuntu/k8s-validation/.tox/py3/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 1372, in wait_for_connection_lost
    await asyncio.wait_for(
  File "/usr/lib/python3.10/asyncio/tasks.py", line 405, in wait_for
    loop = events.get_running_loop()
RuntimeError: no running event loop
Task was destroyed but it is pending!
task: <Task pending name='Task-533' coro=<WebSocketCommonProtocol.recv() done, defined at /home/ubuntu/k8s-validation/.tox/py3/lib/python3.10/site-packages/websockets/legacy/protocol.py:486> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[create_task_with_handler.<locals>._task_result_exp_handler(task_name='tmp', logger=<Logger juju....ion (WARNING)>)() at /home/ubuntu/k8s-validation/.tox/py3/lib/python3.10/site-packages/juju/jasyncio.py:64]>
Task was destroyed but it is pending!
task: <Task pending name='Task-534' coro=<Event.wait() done, defined at /usr/lib/python3.10/asyncio/locks.py:201> wait_for=<Future pending cb=[Task.task_wakeup()]>>
ERROR: InvocationError for command /home/ubuntu/k8s-validation/.tox/py3/bin/pytest -v -s --junit-xml=/home/ubuntu/project/generated/kubernetes-maas/k8s-suite/test_clusterip_service_endpoint-junit.xml --controller=foundations-maas --model=kubernetes-maas /home/ubuntu/k8s-validation/jobs/integration/test_service_endpoints.py::test_clusterip_service_endpoint (exited with code 1)
```

It looks similar to LP: #1983990

Crashdumps and configs can be found here:
https://oil-jenkins.canonical.com/artifacts/a9c727a4-7670-49ee-a617-127787248841/index.html

tags: added: cdo-qa foundations-engine
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.