network-ee-build-container-image* jobs stuck during tag push

[goneri]

Jobs stay stuck at and timeout

LOOP [push-to-intermediate-registry : Push tag to intermediate registry]

e.g: https://8e0e82302d2fae3b5390-711bba4e58c405e4ee9bb7d6b67e10dd.ssl.cf1.rackcdn.com/456/b206a692460d0c462acc95ffbd26a2b92eadd920/check/network-ee-build-container-image/db64cbf/job-output.txt

[pabelanger]

This looks to be some sort of bug in zuul-registry:

Aug 31 13:54:46 zr01 zuul-registry[903]: 2021-08-31 13:54:46,478 INFO cherrypy.access.140434369016048: 38.108.68.109 - - [31/Aug/2021:13:54:46] "GET /v2/quay.io/ansible/network-ee/blobs/sha256:162772c7ef7b68273ab739f462579ddb8a66eb11b5823b0065cf4dff5dc050f3 HTTP/1.1" 200 7735 "" "Go-http-client/1.1"
Aug 31 14:10:59 zr01 zuul-registry[903]: 2021-08-31 14:10:59,455 DEBUG registry.authz: Unauthorized read
Aug 31 14:10:59 zr01 zuul-registry[903]: 2021-08-31 14:10:59,455 INFO cherrypy.access.140434369016048: 64.227.107.188 - - [31/Aug/2021:14:10:59] "GET / HTTP/1.1" 401 735 "" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/34.0.1847.137 Safari/537.36"
Aug 31 14:11:00 zr01 zuul-registry[903]: 2021-08-31 14:11:00,742 ERROR cherrypy.error: [31/Aug/2021:14:11:00] ENGINE Error in HTTPServer.tick
Aug 31 14:11:00 zr01 zuul-registry[903]: Traceback (most recent call last):
Aug 31 14:11:00 zr01 zuul-registry[903]:   File "/opt/venv/zuul-registry-1.0.0/lib/python3.6/site-packages/cheroot/server.py", line 1798, in serve
Aug 31 14:11:00 zr01 zuul-registry[903]:     self.tick()
Aug 31 14:11:00 zr01 zuul-registry[903]:   File "/opt/venv/zuul-registry-1.0.0/lib/python3.6/site-packages/cheroot/server.py", line 2039, in tick
Aug 31 14:11:00 zr01 zuul-registry[903]:     conn = self._connections.get_conn()
Aug 31 14:11:00 zr01 zuul-registry[903]:   File "/opt/venv/zuul-registry-1.0.0/lib/python3.6/site-packages/cheroot/connections.py", line 161, in get_conn
Aug 31 14:11:00 zr01 zuul-registry[903]:     return self._from_server_socket(self.server.socket)
Aug 31 14:11:00 zr01 zuul-registry[903]:   File "/opt/venv/zuul-registry-1.0.0/lib/python3.6/site-packages/cheroot/connections.py", line 188, in _from_server_socket
Aug 31 14:11:00 zr01 zuul-registry[903]:     s, ssl_env = self.server.ssl_adapter.wrap(s)
Aug 31 14:11:00 zr01 zuul-registry[903]:   File "/opt/venv/zuul-registry-1.0.0/lib/python3.6/site-packages/cheroot/ssl/builtin.py", line 278, in wrap
Aug 31 14:11:00 zr01 zuul-registry[903]:     sock, do_handshake_on_connect=True, server_side=True,
Aug 31 14:11:00 zr01 zuul-registry[903]:   File "/usr/lib/python3.6/ssl.py", line 407, in wrap_socket
Aug 31 14:11:00 zr01 zuul-registry[903]:     _context=self, _session=session)
Aug 31 14:11:00 zr01 zuul-registry[903]:   File "/usr/lib/python3.6/ssl.py", line 817, in __init__
Aug 31 14:11:00 zr01 zuul-registry[903]:     self.do_handshake()
Aug 31 14:11:00 zr01 zuul-registry[903]:   File "/usr/lib/python3.6/ssl.py", line 1077, in do_handshake
Aug 31 14:11:00 zr01 zuul-registry[903]:     self._sslobj.do_handshake()
Aug 31 14:11:00 zr01 zuul-registry[903]:   File "/usr/lib/python3.6/ssl.py", line 689, in do_handshake
Aug 31 14:11:00 zr01 zuul-registry[903]:     self._sslobj.do_handshake()
Aug 31 14:11:00 zr01 zuul-registry[903]: ssl.SSLError: [SSL: BAD_DH_G_LENGTH] bad key share (_ssl.c:852)
Aug 31 14:11:22 zr01 zuul-registry[903]: 2021-08-31 14:11:22,410 WARNING cherrypy.error: [31/Aug/2021:14:11:22] ENGINE socket.error 1
Aug 31 14:11:22 zr01 zuul-registry[903]: Traceback (most recent call last):
Aug 31 14:11:22 zr01 zuul-registry[903]:   File "/opt/venv/zuul-registry-1.0.0/lib/python3.6/site-packages/cheroot/server.py", line 1273, in communicate
Aug 31 14:11:22 zr01 zuul-registry[903]:     req.parse_request()
Aug 31 14:11:22 zr01 zuul-registry[903]:   File "/opt/venv/zuul-registry-1.0.0/lib/python3.6/site-packages/cheroot/server.py", line 702, in parse_request
Aug 31 14:11:22 zr01 zuul-registry[903]:     success = self.read_request_line()
Aug 31 14:11:22 zr01 zuul-registry[903]:   File "/opt/venv/zuul-registry-1.0.0/lib/python3.6/site-packages/cheroot/server.py", line 743, in read_request_line
Aug 31 14:11:22 zr01 zuul-registry[903]:     request_line = self.rfile.readline()
Aug 31 14:11:22 zr01 zuul-registry[903]:   File "/opt/venv/zuul-registry-1.0.0/lib/python3.6/site-packages/cheroot/server.py", line 300, in readline
Aug 31 14:11:22 zr01 zuul-registry[903]:     data = self.rfile.readline(256)
Aug 31 14:11:22 zr01 zuul-registry[903]:   File "/usr/lib/python3.6/_pyio.py", line 511, in readline
Aug 31 14:11:22 zr01 zuul-registry[903]:     b = self.read(nreadahead())
Aug 31 14:11:22 zr01 zuul-registry[903]:   File "/usr/lib/python3.6/_pyio.py", line 495, in nreadahead
Aug 31 14:11:22 zr01 zuul-registry[903]:     readahead = self.peek(1)
Aug 31 14:11:22 zr01 zuul-registry[903]:   File "/usr/lib/python3.6/_pyio.py", line 1063, in peek
Aug 31 14:11:22 zr01 zuul-registry[903]:     return self._peek_unlocked(size)
Aug 31 14:11:22 zr01 zuul-registry[903]:   File "/usr/lib/python3.6/_pyio.py", line 1070, in _peek_unlocked
Aug 31 14:11:22 zr01 zuul-registry[903]:     current = self.raw.read(to_read)
Aug 31 14:11:22 zr01 zuul-registry[903]:   File "/usr/lib/python3.6/socket.py", line 586, in readinto
Aug 31 14:11:22 zr01 zuul-registry[903]:     return self._sock.recv_into(b)
Aug 31 14:11:22 zr01 zuul-registry[903]:   File "/usr/lib/python3.6/ssl.py", line 1012, in recv_into
Aug 31 14:11:22 zr01 zuul-registry[903]:     return self.read(nbytes, buffer)
Aug 31 14:11:22 zr01 zuul-registry[903]:   File "/usr/lib/python3.6/ssl.py", line 874, in read
Aug 31 14:11:22 zr01 zuul-registry[903]:     return self._sslobj.read(len, buffer)
Aug 31 14:11:22 zr01 zuul-registry[903]:   File "/usr/lib/python3.6/ssl.py", line 631, in read
Aug 31 14:11:22 zr01 zuul-registry[903]:     v = self._sslobj.read(len, buffer)
Aug 31 14:11:22 zr01 zuul-registry[903]: ssl.SSLError: [SSL: UNEXPECTED_RECORD] unexpected record (_ssl.c:2309)

Which blocks it from accepting new connections. I've restarted the registry and it is processing again.

[goneri]

It works fine now. I let the issue open until we've got a proper long term fix.

[saito-hideki]

Hello @goneri
I'm running into a similar issue with ansible.posix collections, but it was timeout in my case:

• https://github.com/ansible-collections/ansible.posix/pull/278/checks?check_run_id=4074032661
• https://dashboard.zuul.ansible.com/t/ansible/build/1a5ff1a8f43f40e7b3f14f35e1f6cbf5/log/job-output.txt#2396-2397

2021-11-01 23:36:01.898027 | LOOP [push-to-intermediate-registry : Push tag to intermediate registry]
2021-11-02 00:35:48.574443 | POST-RUN END RESULT_TIMED_OUT: [trusted : github.com/ansible/project-config/playbooks/buildset-registry/post.yaml@master]

Sorry if I missed something, but I think CI tests with other collections may have similar issues.

[Shrews]

ansible-runner and ansible-builder container build jobs are also experiencing this timeout (since yesterday) when pushing the tag in post run.

[saito-hideki]

Just FYI.
Currently, there is no issues with CI tests on ansible.posix. It is working without errors.

• network-ee-build-container-image* jobs stuck during tag push #1082 (comment)