Bug 918995 - Latest version of openssl breaks koji client
Summary: Latest version of openssl breaks koji client
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: Fedora
Classification: Fedora
Component: koji
Version: 18
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Dennis Gilmore
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-03-07 11:03 UTC by Lukas Zapletal
Modified: 2014-02-05 19:44 UTC (History)
3 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2014-02-05 19:44:49 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
log from koji client with all debugs on (1.23 MB, application/x-bzip)
2013-03-07 11:04 UTC, Lukas Zapletal
no flags Details
log from koji client with all debugs on (1.23 MB, application/x-bzip)
2013-03-07 11:05 UTC, Lukas Zapletal
no flags Details
log from koji client with all debugs on (5.15 MB, application/x-bzip)
2013-03-07 11:08 UTC, Lukas Zapletal
no flags Details

Description Lukas Zapletal 2013-03-07 11:03:08 UTC
Hello, latest update in Fedora 18 of openssl-1.0.1e-3.fc18.x86_64 breaks koji client. I always get a timeout when I try to submit a build:

CLIENT:

$ koji -d -c ~/.koji/katello-config build --nowait katello-thirdparty-rhel6 /tmp/tito/ruby193-rubygem-alchemy-1.0.1-3.el6.src.rpm
successfully connected to hub
Uploading srpm: /tmp/tito/ruby193-rubygem-alchemy-1.0.1-3.el6.src.rpm
2013-03-07 11:30:29,814 [DEBUG] koji: uploadFile('cli-build/1362652229.783406.xLyyHYoM','ruby193-rubygem-alchemy-1.0.1-3.el6.src.rpm',1048576,'5eb711bdf86be6828ffad6339605f27d',0,...)
2013-03-07 11:30:50,614 [DEBUG] koji: Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/koji/__init__.py", line 1886, in _callMethod
    return self._sendCall(handler, headers, request)
  File "/usr/lib/python2.7/site-packages/koji/__init__.py", line 1797, in _sendCall
    return self._sendOneCall(handler, headers, request)
  File "/usr/lib/python2.7/site-packages/koji/__init__.py", line 1816, in _sendOneCall
    cnx.send(request)
  File "/usr/lib64/python2.7/httplib.py", line 790, in send
    self.sock.sendall(data)
  File "/usr/lib/python2.7/site-packages/koji/ssl/SSLConnection.py", line 105, in sendall
    raise socket.timeout((110, "Operation timed out."))
timeout: (110, 'Operation timed out.')

SERVER:

[Thu Mar 07 05:36:56 2013] [error] [client 78.80.253.33] mod_python (pid=604, interpreter='localhost.localdomain', phase='PythonHandler', handler='kojixmlrpc'): Application error
[Thu Mar 07 05:36:56 2013] [error] [client 78.80.253.33] ServerName: 'localhost.localdomain'
[Thu Mar 07 05:36:56 2013] [error] [client 78.80.253.33] DocumentRoot: '/var/www/html'
[Thu Mar 07 05:36:56 2013] [error] [client 78.80.253.33] URI: '/kojihub'
[Thu Mar 07 05:36:56 2013] [error] [client 78.80.253.33] Location: None
[Thu Mar 07 05:36:56 2013] [error] [client 78.80.253.33] Directory: '/usr/share/koji-hub/'
[Thu Mar 07 05:36:56 2013] [error] [client 78.80.253.33] Filename: '/usr/share/koji-hub/XMLRPC'
[Thu Mar 07 05:36:56 2013] [error] [client 78.80.253.33] PathInfo: ''
[Thu Mar 07 05:36:56 2013] [error] [client 78.80.253.33] Traceback (most recent call last):
[Thu Mar 07 05:36:56 2013] [error] [client 78.80.253.33]   File "/usr/lib64/python2.6/site-packages/mod_python/importer.py", line 1540, in HandlerDispatch\n    default=default_handler, arg=req, silent=hlist.silent)
[Thu Mar 07 05:36:56 2013] [error] [client 78.80.253.33]   File "/usr/lib64/python2.6/site-packages/mod_python/importer.py", line 1232, in _process_target\n    result = _execute_target(config, req, object, arg)
[Thu Mar 07 05:36:56 2013] [error] [client 78.80.253.33]   File "/usr/lib64/python2.6/site-packages/mod_python/importer.py", line 1131, in _execute_target\n    result = object(arg)
[Thu Mar 07 05:36:56 2013] [error] [client 78.80.253.33]   File "/usr/share/koji-hub/kojixmlrpc.py", line 626, in handler\n    h.handle_request(req)
[Thu Mar 07 05:36:56 2013] [error] [client 78.80.253.33]   File "/usr/share/koji-hub/kojixmlrpc.py", line 295, in handle_request\n    response = self._marshaled_dispatch(req.read())
[Thu Mar 07 05:36:56 2013] [error] [client 78.80.253.33] IOError: Client read error (Timeout?)

After downlgrade to openssl-1.0.1c-7.fc18 I saw one timeout, but once koji client retried it, it was success:

$ koji -d -c ~/.koji/katello-config build --nowait katello-thirdparty-rhel6 /tmp/tito/ruby193-rubygem-alchemy-1.0.1-3.el6.src.rpm
successfully connected to hub
Uploading srpm: /tmp/tito/ruby193-rubygem-alchemy-1.0.1-3.el6.src.rpm
2013-03-07 11:38:42,704 [DEBUG] koji: uploadFile('cli-build/1362652722.667673.aOtvSgNJ','ruby193-rubygem-alchemy-1.0.1-3.el6.src.rpm',1048576,'5eb711bdf86be6828ffad6339605f27d',0,...)
2013-03-07 11:39:03,902 [DEBUG] koji: Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/koji/__init__.py", line 1886, in _callMethod
    return self._sendCall(handler, headers, request)
  File "/usr/lib/python2.7/site-packages/koji/__init__.py", line 1797, in _sendCall
    return self._sendOneCall(handler, headers, request)
  File "/usr/lib/python2.7/site-packages/koji/__init__.py", line 1816, in _sendOneCall
    cnx.send(request)
  File "/usr/lib64/python2.7/httplib.py", line 790, in send
    self.sock.sendall(data)
  File "/usr/lib/python2.7/site-packages/koji/ssl/SSLConnection.py", line 105, in sendall
    raise socket.timeout((110, "Operation timed out."))
timeout: (110, 'Operation timed out.')

2013-03-07 11:39:03,902 [INFO] koji: Try #1 for call 4 (uploadFile) failed: (110, 'Operation timed out.')
2013-03-07 11:39:43,579 [DEBUG] koji: Uploaded 1048576 bytes in 60.911812 seconds (16.811189 kbytes/sec)
2013-03-07 11:39:43,580 [DEBUG] koji: Total: 1048576 bytes in 60.911932 seconds (16.811156 kbytes/sec)
2013-03-07 11:39:43,592 [DEBUG] koji: uploadFile('cli-build/1362652722.667673.aOtvSgNJ','ruby193-rubygem-alchemy-1.0.1-3.el6.src.rpm',204911,'39e894aeb8958c769ec5e034349e945e',1048576,...)
2013-03-07 11:39:47,823 [DEBUG] koji: Uploaded 204911 bytes in 4.243348 seconds (47.158141 kbytes/sec)
2013-03-07 11:39:47,823 [DEBUG] koji: Total: 1253487 bytes in 65.155821 seconds (18.787399 kbytes/sec)
2013-03-07 11:39:47,824 [DEBUG] koji: uploadFile('cli-build/1362652722.667673.aOtvSgNJ','ruby193-rubygem-alchemy-1.0.1-3.el6.src.rpm',1253487,'c97a027f678914731ff74ca6e2b95436',-1,...)

I see strange thing, when I try to submit a package, it seems koji client is timeouting too often and trying to re-upload it too soon. In this case it was (I think) uploaded twice:

$ koji -d -c ~/.koji/katello-config build --nowait katello-thirdparty-rhel6 /tmp/tito/ruby193-rubygem-alchemy-1.0.1-3.el6.src.rpm
successfully connected to hub
Uploading srpm: /tmp/tito/ruby193-rubygem-alchemy-1.0.1-3.el6.src.rpm
2013-03-07 11:40:06,833 [DEBUG] koji: uploadFile('cli-build/1362652806.798729.uJQGILFH','ruby193-rubygem-alchemy-1.0.1-3.el6.src.rpm',1048576,'5eb711bdf86be6828ffad6339605f27d',0,...)
2013-03-07 11:40:28,859 [DEBUG] koji: Uploaded 1048576 bytes in 22.060402 seconds (46.418012 kbytes/sec)
2013-03-07 11:40:28,859 [DEBUG] koji: Total: 1048576 bytes in 22.060599 seconds (46.417598 kbytes/sec)
2013-03-07 11:40:28,866 [DEBUG] koji: uploadFile('cli-build/1362652806.798729.uJQGILFH','ruby193-rubygem-alchemy-1.0.1-3.el6.src.rpm',204911,'39e894aeb8958c769ec5e034349e945e',1048576,...)
2013-03-07 11:40:33,763 [DEBUG] koji: Uploaded 204911 bytes in 4.903420 seconds (40.809965 kbytes/sec)
2013-03-07 11:40:33,763 [DEBUG] koji: Total: 1253487 bytes in 26.964630 seconds (45.396818 kbytes/sec)
2013-03-07 11:40:33,764 [DEBUG] koji: uploadFile('cli-build/1362652806.798729.uJQGILFH','ruby193-rubygem-alchemy-1.0.1-3.el6.src.rpm',1253487,'c97a027f678914731ff74ca6e2b95436',-1,...)

By the way there is a patch in latest master that increases default timeout from 20 to 60 seconds, I tried to apply it but without any change: http://git.fedorahosted.org/cgit/koji/commit/?id=582a0679e763fe3aa269c1aab525c6c5e35fa088

Client version: koji-1.7.1-2.fc18.noarch

Server version:

koji-1.6.0-1.el6.1.noarch
koji-utils-1.6.0-1.el6.1.noarch
koji-hub-1.6.0-1.el6.1.noarch
koji-web-1.6.0-1.el6.1.noarch
koji-builder-1.6.0-1.el6.1.noarch

I know I should not mix koji client-server versions, so I tried this also with Koji 1.6.0 client with the same results.

Here are logs with --debug-xmlrpc:

The first two are with downgraded version of openssl (works):
-rw-rw-r-- 1 lzap lzap 1,3M  7. bře 11.51 debug-xmlrpc-kojiclient-1.6-openssl-1.0.1c.log.bz2
-rw-rw-r-- 1 lzap lzap 1,3M  7. bře 11.54 debug-xmlrpc-kojiclient-1.7-openssl-1.0.1c.log.bz2

This one is with the latest stable openssl from F18 (after retryx no 5. I cancelled because it was growing so fast):
-rw-rw-r-- 1 lzap lzap 5,2M  7. bře 12.00 debug-xmlrpc-kojiclient-1.7-openssl-1.0.1e.log.bz2

Comment 1 Lukas Zapletal 2013-03-07 11:04:30 UTC
Created attachment 706529 [details]
log from koji client with all debugs on

Comment 2 Lukas Zapletal 2013-03-07 11:05:51 UTC
Created attachment 706530 [details]
log from koji client with all debugs on

Comment 3 Lukas Zapletal 2013-03-07 11:08:06 UTC
Created attachment 706531 [details]
log from koji client with all debugs on

Comment 4 Lukas Zapletal 2013-03-07 11:13:25 UTC
And one more thing to note - my ADSL upload is poor 500kB/s locally in Europe, 40-50kB/s to Amazon (where we have our koji). I will be happy to assist with more testing.

Comment 5 Eduardo Echeverria 2013-03-28 09:05:49 UTC
I have exactly the same problem, my ADSL is also poor, 112 Kbps, in South America, Venezuela, btw Lukas, the workaround suggested for you (downgrade openssl), don't works for me

Comment 6 Fedora End Of Life 2013-12-21 11:57:20 UTC
This message is a reminder that Fedora 18 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 18. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '18'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 18's end of life.

Thank you for reporting this issue and we are sorry that we may not be 
able to fix it before Fedora 18 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior to Fedora 18's end of life.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 7 Fedora End Of Life 2014-02-05 19:44:49 UTC
Fedora 18 changed to end-of-life (EOL) status on 2014-01-14. Fedora 18 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.


Note You need to log in before you can comment on or make changes to this bug.