koji

#2361 koji-gc delete traceback
Closed: Fixed by tkopecek. Opened by kevin.

Closed: Fixed
Reopen Issue

Seeing: 

Traceback (most recent call last):
  File "/usr/sbin/koji-gc", line 1026, in <module>
    rv = main(args)
  File "/usr/sbin/koji-gc", line 463, in main
    globals()['handle_' + x]()
  File "/usr/sbin/koji-gc", line 730, in handle_delete
    for binfo, result in six.moves.zip(continuing, mcall.call_all()):
  File "/usr/lib/python3.8/site-packages/koji/__init__.py", line 3223, in
call_all
    _results = self._session._callMethod('multiCall', args, {})
  File "/usr/lib/python3.8/site-packages/koji/__init__.py", line 2810, in
_callMethod
    raise err
  File "/usr/lib/python3.8/site-packages/koji/__init__.py", line 2791, in
_callMethod
    return self._sendCall(handler, headers, request)
  File "/usr/lib/python3.8/site-packages/koji/__init__.py", line 2709, in
_sendCall
    return self._sendOneCall(handler, headers, request)
  File "/usr/lib/python3.8/site-packages/koji/__init__.py", line 2755, in
_sendOneCall
    ret = self._read_xmlrpc_response(r)
  File "/usr/lib/python3.8/site-packages/koji/__init__.py", line 2767, in
_read_xmlrpc_response
    result = u.close()
  File "/usr/lib64/python3.8/xmlrpc/client.py", line 655, in close
    raise Fault(**self._stack[0])
xmlrpc.client.Fault: <Fault 1: "<class 'TypeError'>: sequence item
0: expected str instance, int found">

at the end of a delete run.

Full output at:
https://lists.fedoraproject.org/archives/list/releng-cron@lists.fedoraproject.org/message/C2HUKQFTB3RHFCYPLOVSC67T5ZOQEKYE/

It looks like the error happened on the hub. We send a large multi-call operation to the hub, calling the "listTags" RPC many times on many builds. The koji-gc code looks like this:

for nvr, binfo in trash:
    mcall.listTags(build=binfo['id'], perms=False)
for (nvr, binfo), [tags] in six.moves.zip(trash, mcall.call_all()):

Looking at list_tags() in hub/kojihub.py, I don't see anything that jumps out at me. Nothing changed in this method recently, so I suspect the error is further down.

Do you see any stack trace in the Hub logs for this? It may say something like "sequence item 0: expected str instance, int found"

Is this reproducible?

(I tried running this bit of koji-gc code against Fedora's current set of builds in the trashcan tag, and I could not get the multicall to crash.)

So, yeah, there is the following on the hub I think that is related:

19 08:06:36,160 [WARNING] m=deleteBuild u=oscar p=1085666 r=10.3.163.76:42518 koji.xmlrpc: Traceback (most recent call last):
[Sun Jul 19 08:06:36.160823 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/share/koji-hub/kojixmlrpc.py", line 337, in multiCall
[Sun Jul 19 08:06:36.160826 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     result = self._dispatch(call['methodName'], call['params'])
[Sun Jul 19 08:06:36.160828 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/share/koji-hub/kojixmlrpc.py", line 318, in _dispatch
[Sun Jul 19 08:06:36.160830 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     ret = koji.util.call_with_argcheck(func, params, opts)
[Sun Jul 19 08:06:36.160833 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/lib/python3.8/site-packages/koji/util.py", line 258, in call_with_argcheck
[Sun Jul 19 08:06:36.160835 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     return func(*args, **kwargs)
[Sun Jul 19 08:06:36.160837 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/share/koji-hub/kojihub.py", line 8103, in delete_build
[Sun Jul 19 08:06:36.160839 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     _delete_build(binfo)
[Sun Jul 19 08:06:36.160841 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/share/koji-hub/kojihub.py", line 8144, in _delete_build
[Sun Jul 19 08:06:36.160843 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     koji.util.rmtree(builddir)
[Sun Jul 19 08:06:36.160845 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/lib/python3.8/site-packages/koji/util.py", line 429, in rmtree
[Sun Jul 19 08:06:36.160847 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     _rmtree(dev)
[Sun Jul 19 08:06:36.160848 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/lib/python3.8/site-packages/koji/util.py", line 438, in _rmtree
[Sun Jul 19 08:06:36.160851 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     dirs = _stripcwd(dev)
[Sun Jul 19 08:06:36.160853 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/lib/python3.8/site-packages/koji/util.py", line 463, in _stripcwd
[Sun Jul 19 08:06:36.160855 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     st = os.lstat(fn)
[Sun Jul 19 08:06:36.160857 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518] FileNotFoundError: [Errno 2] No such file or directory: 'dummy-test-package-gloster-0-543.fc33.src.rpm.sig'
[Sun Jul 19 08:06:36.160859 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518] 
[Sun Jul 19 08:06:36.160861 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518] During handling of the above exception, another exception occurred:
[Sun Jul 19 08:06:36.160863 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518] 
[Sun Jul 19 08:06:36.160864 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518] Traceback (most recent call last):
[Sun Jul 19 08:06:36.160866 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/share/koji-hub/kojixmlrpc.py", line 238, in _wrap_handler
[Sun Jul 19 08:06:36.160876 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     response = handler(environ)
[Sun Jul 19 08:06:36.160878 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/share/koji-hub/kojixmlrpc.py", line 281, in handle_rpc
[Sun Jul 19 08:06:36.160880 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     return self._dispatch(method, params)
[Sun Jul 19 08:06:36.160882 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/share/koji-hub/kojixmlrpc.py", line 318, in _dispatch
[Sun Jul 19 08:06:36.160895 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     ret = koji.util.call_with_argcheck(func, params, opts)
[Sun Jul 19 08:06:36.160897 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/lib/python3.8/site-packages/koji/util.py", line 258, in call_with_argcheck
[Sun Jul 19 08:06:36.160899 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     return func(*args, **kwargs)
[Sun Jul 19 08:06:36.160901 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/share/koji-hub/kojixmlrpc.py", line 348, in multiCall
[Sun Jul 19 08:06:36.160903 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     faultString = ', '.join(exc_value.args)
[Sun Jul 19 08:06:36.160904 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518] TypeError: sequence item 0: expected str instance, int found
[Sun Jul 19 08:06:36.160906 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518] 
[Sun Jul 19 08:06:36.160932 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518] 160 [WARNING] m=None u=None p=1085666 r=?:? koji.xmlrpc: Traceback (most recent call last):
[Sun Jul 19 08:06:36.160935 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/share/koji-hub/kojixmlrpc.py", line 337, in multiCall
[Sun Jul 19 08:06:36.160937 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     result = self._dispatch(call['methodName'], call['params'])
[Sun Jul 19 08:06:36.160938 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/share/koji-hub/kojixmlrpc.py", line 318, in _dispatch
[Sun Jul 19 08:06:36.160940 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     ret = koji.util.call_with_argcheck(func, params, opts)
[Sun Jul 19 08:06:36.160942 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/lib/python3.8/site-packages/koji/util.py", line 258, in call_with_argcheck
[Sun Jul 19 08:06:36.160944 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     return func(*args, **kwargs)
[Sun Jul 19 08:06:36.160946 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/share/koji-hub/kojihub.py", line 8103, in delete_build
[Sun Jul 19 08:06:36.160948 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     _delete_build(binfo)
[Sun Jul 19 08:06:36.160950 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/share/koji-hub/kojihub.py", line 8144, in _delete_build
[Sun Jul 19 08:06:36.160952 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     koji.util.rmtree(builddir)
[Sun Jul 19 08:06:36.160953 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/lib/python3.8/site-packages/koji/util.py", line 429, in rmtree
[Sun Jul 19 08:06:36.160955 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     _rmtree(dev)
[Sun Jul 19 08:06:36.160957 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/lib/python3.8/site-packages/koji/util.py", line 438, in _rmtree
[Sun Jul 19 08:06:36.160962 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     dirs = _stripcwd(dev)
[Sun Jul 19 08:06:36.160964 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/lib/python3.8/site-packages/koji/util.py", line 463, in _stripcwd
[Sun Jul 19 08:06:36.160966 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     st = os.lstat(fn)
[Sun Jul 19 08:06:36.160968 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518] FileNotFoundError: [Errno 2] No such file or directory: 'dummy-test-package-gloster-0-543.fc33.src.rpm.sig'
[Sun Jul 19 08:06:36.160970 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518] 
[Sun Jul 19 08:06:36.160972 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518] During handling of the above exception, another exception occurred:
[Sun Jul 19 08:06:36.160973 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518] 
[Sun Jul 19 08:06:36.160975 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518] Traceback (most recent call last):
[Sun Jul 19 08:06:36.160977 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/share/koji-hub/kojixmlrpc.py", line 238, in _wrap_handler
[Sun Jul 19 08:06:36.160979 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     response = handler(environ)
[Sun Jul 19 08:06:36.160981 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/share/koji-hub/kojixmlrpc.py", line 281, in handle_rpc
[Sun Jul 19 08:06:36.160983 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     return self._dispatch(method, params)
[Sun Jul 19 08:06:36.160984 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/share/koji-hub/kojixmlrpc.py", line 318, in _dispatch
[Sun Jul 19 08:06:36.160986 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     ret = koji.util.call_with_argcheck(func, params, opts)
[Sun Jul 19 08:06:36.160988 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/lib/python3.8/site-packages/koji/util.py", line 258, in call_with_argcheck
[Sun Jul 19 08:06:36.160990 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     return func(*args, **kwargs)
[Sun Jul 19 08:06:36.160992 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]   File "/usr/share/koji-hub/kojixmlrpc.py", line 348, in multiCall
[Sun Jul 19 08:06:36.160994 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]     faultString = ', '.join(exc_value.args)
[Sun Jul 19 08:06:36.160996 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518] TypeError: sequence item 0: expected str instance, int found
[Sun Jul 19 08:06:36.160997 2020] [wsgi:error] [pid 1085666:tid 139676757255936] [client 10.3.163.76:42518]

So, it looks like it's trying to delete a signature, but that package doesn't have one?

Yes, it seems to happen pretty much on every run.

Metadata Update from @kevin:
- Custom field Size adjusted to None

Filed #2381 for the error handling of multicall

It appears that _stripcwd() suffers from a time-of-check to time-of-use bug, because we call os.listdir(), and then expect to call os.lstat() on each of those results without handling ENOENT if something else deleted the file.

for fn in os.listdir('.'):
    # At this point something else may have deleted "fn" behind our back, so "lstat()" will fail:
    st = os.lstat(fn)

PR #2399 adds a check for ENOENT in _stripcwd()
Edited by ktdreyer

Metadata Update from @tkopecek:
- Issue set to the milestone: 1.23

Metadata Update from @jcupova:
- Issue tagged with: testing-ready

Commit d421faa8 fixes this issue

more race condition problem found in rmtree()

test script:

import os
from multiprocessing import Process
import koji
_DIR = 'brew-testing-dir'
def _mkdirs():
    os.mkdir(_DIR)
    for i in range(0, 100):
        dd = os.path.join(_DIR, 'subdir_' + str(i))
        os.mkdir(dd)
        for j in range(0, 100):
            ddd = os.path.join(dd, 'subdir_' + str(j))
            os.mkdir(ddd)
def test_koji_util_rmtree_parallel():
    _mkdirs()
    tasks = [Process(target=koji.util.rmtree, args=(_DIR,))
             for i in range(0, 10)]
    for task in tasks:
        task.start()
    for task in tasks:
        task.join()
if __name__ == '__main__':
    test_koji_util_rmtree_parallel()

errors:

Traceback (most recent call last):
  File "/usr/lib64/python3.6/multiprocessing/process.py", line 258, in _bootstrap
    self.run()
  File "/usr/lib64/python3.6/multiprocessing/process.py", line 93, in run
    self._target(*self._args, **self._kwargs)
  File "/home/yzhu/git/redhat/fork/koji/koji/util.py", line 442, in rmtree
    _rmtree(dev)
  File "/home/yzhu/git/redhat/fork/koji/koji/util.py", line 451, in _rmtree
    dirs = _stripcwd(dev)
  File "/home/yzhu/git/redhat/fork/koji/koji/util.py", line 475, in _stripcwd
    for fn in os.listdir('.'):
OSError: [Errno 116] Stale file handle: '.'
Traceback (most recent call last):
  File "/usr/lib64/python3.6/multiprocessing/process.py", line 258, in _bootstrap
    self.run()
  File "/usr/lib64/python3.6/multiprocessing/process.py", line 93, in run
    self._target(*self._args, **self._kwargs)
  File "/home/yzhu/git/redhat/fork/koji/koji/util.py", line 442, in rmtree
    _rmtree(dev)
Process Process-1:
  File "/home/yzhu/git/redhat/fork/koji/koji/util.py", line 469, in _rmtree
    os.chdir(subdir)
FileNotFoundError: [Errno 2] No such file or directory: 'subdir_60'

Metadata Update from @jcupova:
- Issue tagged with: testing-done

This issue has been migrated to Fedora Forge:
https://forge.fedoraproject.org/koji/koji/issues/2361

Please continue any further discussion there.
Metadata
None

testing-done testing-ready

None
None
Low
None
Related Pull Requests
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.