#3377 kojid service run getSessionInfo failed and report SSL handshake interrupted by system
Closed: Duplicate 2 years ago by tkopecek. Opened 2 years ago by weijiangang.

Hi, all

I met a problem about the status of kojibuilder host and ask for some help.
Thanks in advance.

The kojid service kept on Starting up……
● kojid.service - Koji build server
Loaded: loaded (/usr/lib/systemd/system/kojid.service; disabled; vendor preset: disabled)
Active: activating (auto-restart) (Result: exit-code) since Thu 2022-05-26 21:00:44 CST; 29s ago
Docs: https://docs.pagure.org/koji/server_howto/
Process: 3638096 ExecStart=/usr/sbin/kojid --fg --force-lock --verbose (code=exited, status=1/FAILURE)
Main PID: 3638096 (code=exited, status=1/FAILURE)
CPU: 286ms

[kojiadmin@www.kojihost.com wei]$ koji list-hosts
Hostname Enb Rdy Load/Cap Arches Last Update
kojid0 Y N 0.0/2.0 x86_64 Thu, 26 May 2022 20:52:32 CST

The ssl_error_log shows:

[Thu May 26 20:50:29.841137 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] 2022-05-26 20:50:29,841 [INFO] m=host.getID u=kojid0 p=3563479 r=10.20.74.82:55834 koji.xmlrpc: Completed method host.getID for session 466 (#2): 0.000481 seconds, rss 47816, stime 0.446598
[Thu May 26 20:50:29.841269 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] 2022-05-26 20:50:29,841 [DEBUG] m=host.getID u=kojid0 p=3563479 r=10.20.74.82:55834 koji.xmlrpc: Returning 121 bytes after 0.015730 seconds
[Thu May 26 20:50:29.842679 2022] [ssl:debug] [pid 3563479:tid 3563520] ssl_engine_kernel.c(415): [client 10.20.74.82:55834] AH02034: Subsequent (No.5) HTTPS request received for child 199 (server www.kojihost.com:443)
[Thu May 26 20:50:29.842716 2022] [authz_core:debug] [pid 3563479:tid 3563520] mod_authz_core.c(815): [client 10.20.74.82:55834] AH01626: authorization result of Require all granted: granted
[Thu May 26 20:50:29.842722 2022] [authz_core:debug] [pid 3563479:tid 3563520] mod_authz_core.c(815): [client 10.20.74.82:55834] AH01626: authorization result of <RequireAny>: granted
[Thu May 26 20:50:29.842848 2022] [auth_gssapi:debug] [pid 3563479:tid 3563520] mod_auth_gssapi.c(737): [client 10.20.74.82:55834] GSSapiImpersonate not On, skipping impersonation.
[Thu May 26 20:50:29.843222 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] 2022-05-26 20:50:29,843 [DEBUG] m=getSessionInfo u=None p=3563479 r=10.20.74.82:55834 koji.db: b"\n SELECT authtype,callnum,exclusive,expired,master,start_time,EXTRACT(EPOCH FROM start_time),update_time,EXTRACT(EPOCH FROM update_time),user_id FROM sessions\n WHERE id = 466\n AND key = '4-0sC2UCXStEdOWLwABj5'\n AND hostip = '10.20.74.82'\n FOR UPDATE\n "
[Thu May 26 20:50:29.843445 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] 2022-05-26 20:50:29,843 [DEBUG] m=getSessionInfo u=None p=3563479 r=10.20.74.82:55834 koji.db: Execute operation completed in 0.0002 seconds
[Thu May 26 20:50:29.843501 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] 2022-05-26 20:50:29,843 [DEBUG] m=getSessionInfo u=None p=3563479 r=10.20.74.82:55834 koji.db: fetchone operation completed in 0.0000 seconds
[Thu May 26 20:50:29.843560 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] 2022-05-26 20:50:29,843 [DEBUG] m=getSessionInfo u=None p=3563479 r=10.20.74.82:55834 koji.db: b'SELECT name,status,usertype FROM users WHERE id=4'
[Thu May 26 20:50:29.843682 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] 2022-05-26 20:50:29,843 [DEBUG] m=getSessionInfo u=None p=3563479 r=10.20.74.82:55834 koji.db: Execute operation completed in 0.0001 seconds
[Thu May 26 20:50:29.843723 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] 2022-05-26 20:50:29,843 [DEBUG] m=getSessionInfo u=None p=3563479 r=10.20.74.82:55834 koji.db: fetchone operation completed in 0.0000 seconds
[Thu May 26 20:50:29.844802 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] 2022-05-26 20:50:29,843 [DEBUG] m=getSessionInfo u=None p=3563479 r=10.20.74.82:55834 koji.db: b'UPDATE sessions SET update_time=NOW() WHERE id = 466'
[Thu May 26 20:50:29.844970 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] 2022-05-26 20:50:29,844 [DEBUG] m=getSessionInfo u=None p=3563479 r=10.20.74.82:55834 koji.db: Execute operation completed in 0.0001 seconds
[Thu May 26 20:50:29.855117 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] 2022-05-26 20:50:29,855 [DEBUG] m=getSessionInfo u=None p=3563479 r=10.20.74.82:55834 koji.db: b'UPDATE sessions SET callnum=3 WHERE id = 466'
[Thu May 26 20:50:29.855440 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] 2022-05-26 20:50:29,855 [DEBUG] m=getSessionInfo u=None p=3563479 r=10.20.74.82:55834 koji.db: Execute operation completed in 0.0002 seconds
[Thu May 26 20:50:29.855542 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] 2022-05-26 20:50:29,855 [INFO] m=getSessionInfo u=kojid0 p=3563479 r=10.20.74.82:55834 koji.xmlrpc: Handling method getSessionInfo for session 466 (#3)
[Thu May 26 20:50:29.855608 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] 2022-05-26 20:50:29,855 [DEBUG] m=getSessionInfo u=kojid0 p=3563479 r=10.20.74.82:55834 koji.xmlrpc: Params: ()
[Thu May 26 20:50:29.855653 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] 2022-05-26 20:50:29,855 [DEBUG] m=getSessionInfo u=kojid0 p=3563479 r=10.20.74.82:55834 koji.xmlrpc: Opts: {}
[Thu May 26 20:50:29.855716 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] 2022-05-26 20:50:29,855 [INFO] m=getSessionInfo u=kojid0 p=3563479 r=10.20.74.82:55834 koji.xmlrpc: Completed method getSessionInfo for session 466 (#3): 0.000025 seconds, rss 47816, stime 0.446598
[Thu May 26 20:50:29.855913 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] 2022-05-26 20:50:29,855 [WARNING] m=getSessionInfo u=kojid0 p=3563479 r=10.20.74.82:55834 koji.xmlrpc: Traceback (most recent call last):
[Thu May 26 20:50:29.855921 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] File "/usr/lib64/python3.10/xmlrpc/client.py", line 522, in __dump
[Thu May 26 20:50:29.855925 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] f = self.dispatch[type(value)]
[Thu May 26 20:50:29.855929 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] KeyError: <class 'decimal.Decimal'>
[Thu May 26 20:50:29.855931 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834]
[Thu May 26 20:50:29.855949 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] During handling of the above exception, another exception occurred:
[Thu May 26 20:50:29.855953 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834]
[Thu May 26 20:50:29.855956 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] Traceback (most recent call last):
[Thu May 26 20:50:29.855959 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] File "/usr/share/koji-hub/kojixmlrpc.py", line 257, in _wrap_handler
[Thu May 26 20:50:29.855962 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] response = dumps(response, methodresponse=1, marshaller=Marshaller)
[Thu May 26 20:50:29.855965 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] File "/usr/lib/python3.10/site-packages/koji/xmlrpcplus.py", line 83, in dumps
[Thu May 26 20:50:29.855968 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] data = m.dumps(params)
[Thu May 26 20:50:29.855971 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] File "/usr/lib64/python3.10/xmlrpc/client.py", line 514, in dumps
[Thu May 26 20:50:29.855974 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] dump(v, write)
[Thu May 26 20:50:29.855977 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] File "/usr/lib64/python3.10/xmlrpc/client.py", line 536, in __dump
[Thu May 26 20:50:29.855980 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] f(self, value, write)
[Thu May 26 20:50:29.855983 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] File "/usr/lib64/python3.10/xmlrpc/client.py", line 607, in dump_struct
[Thu May 26 20:50:29.855986 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] dump(v, write)
[Thu May 26 20:50:29.855989 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] File "/usr/lib64/python3.10/xmlrpc/client.py", line 526, in __dump
[Thu May 26 20:50:29.855992 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] raise TypeError("cannot marshal %s objects" % type(value))
[Thu May 26 20:50:29.855995 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] TypeError: cannot marshal <class 'decimal.Decimal'> objects
[Thu May 26 20:50:29.855998 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834]
[Thu May 26 20:50:29.856223 2022] [wsgi:error] [pid 3563479:tid 3563520] [client 10.20.74.82:55834] 2022-05-26 20:50:29,856 [DEBUG] m=getSessionInfo u=kojid0 p=3563479 r=10.20.74.82:55834 koji.xmlrpc: Returning 336 bytes after 0.013243 seconds
[Thu May 26 20:50:30.053900 2022] [socache_shmcb:debug] [pid 3563479:tid 3563522] mod_socache_shmcb.c(570): AH00837: socache_shmcb_remove (0xec -> subcache 12)
[Thu May 26 20:50:30.054023 2022] [socache_shmcb:debug] [pid 3563479:tid 3563522] mod_socache_shmcb.c(954): AH00852: possible match at idx=3, data=3923
[Thu May 26 20:50:30.054063 2022] [socache_shmcb:debug] [pid 3563479:tid 3563522] mod_socache_shmcb.c(959): AH00853: shmcb_subcache_remove removing matching entry
[Thu May 26 20:50:30.054098 2022] [socache_shmcb:debug] [pid 3563479:tid 3563522] mod_socache_shmcb.c(585): AH00839: leaving socache_shmcb_remove successfully
[Thu May 26 20:50:30.054175 2022] [ssl:info] [pid 3563479:tid 3563522] (70014)End of file found: [client 10.20.74.82:55834] AH01992: SSL library error 1 reading data
[Thu May 26 20:50:30.054221 2022] [ssl:info] [pid 3563479:tid 3563522] SSL Library Error: error:0A000126:SSL routines::unexpected eof while reading
[Thu May 26 20:50:30.054262 2022] [ssl:debug] [pid 3563479:tid 3563522] ssl_engine_io.c(1473): (70014)End of file found: [client 10.20.74.82:55834] AH02007: SSL handshake interrupted by system [Hint: Stop button pressed in browser?!]
[Thu May 26 20:50:30.054301 2022] [ssl:info] [pid 3563479:tid 3563522] [client 10.20.74.82:55834] AH01998: Connection closed to child 201 with abortive shutdown (server www.kojihost.com:443)

Is it a bug? or i configure something wrong?


It is related to change in recent postgresql. We've https://pagure.io/koji/issue/3366 planned. Workaround is to use older fedora/postgres for now (F35).

Metadata Update from @tkopecek:
- Custom field Size adjusted to None
- Issue close_status updated to: Duplicate
- Issue status updated to: Closed (was: Open)

2 years ago

Login to comment on this ticket.

Metadata