koji

#3755 koji-gc occasionally gets Directory not empty fault on delete
Closed: Fixed by tkopecek. Opened by kevin.

Closed: Fixed
Reopen Issue

We are seeing sometimes: 

Getting list of builds in trash...
...got 855 builds to check
1st pass: package filter
855 builds remaining
2nd pass: tags
855 builds remaining
3rd pass: signatures
855 builds remaining
4th pass: deletion
Deleted build: Fedora-Astronomy_KDE-Live-38-20230215.n.0
Deleted build: Fedora-Astronomy_KDE-Live-38-20230216.n.0
Deleted build: Fedora-Astronomy_KDE-Live-38-20230216.n.1
Deleted build: Fedora-Astronomy_KDE-Live-38-20230217.n.0
Deleted build: Fedora-Astronomy_KDE-Live-38-20230218.n.0
Deleted build: Fedora-Astronomy_KDE-Live-38-20230219.n.0
Deleted build: Fedora-Astronomy_KDE-Live-38-20230220.n.0
Deleted build: Fedora-Astronomy_KDE-Live-Rawhide-20230215.n.1
Deleted build: Fedora-Astronomy_KDE-Live-Rawhide-20230216.n.2
Deleted build: Fedora-Astronomy_KDE-Live-Rawhide-20230216.n.3
Deleted build: Fedora-Astronomy_KDE-Live-Rawhide-20230217.n.1
Deleted build: Fedora-Astronomy_KDE-Live-Rawhide-20230218.n.0
Deleted build: Fedora-Astronomy_KDE-Live-Rawhide-20230219.n.0
Deleted build: Fedora-Astronomy_KDE-Live-Rawhide-20230220.n.0
Deleted build: Fedora-Budgie-Live-38-20230215.n.0
Deleted build: Fedora-Budgie-Live-38-20230216.n.0
Deleted build: Fedora-Budgie-Live-38-20230216.n.1
Deleted build: Fedora-Budgie-Live-38-20230217.n.0
Deleted build: Fedora-Budgie-Live-38-20230218.n.0
Deleted build: Fedora-Budgie-Live-Rawhide-20230213.n.0
Deleted build: Fedora-Budgie-Live-Rawhide-20230215.n.1
Deleted build: Fedora-Budgie-Live-Rawhide-20230217.n.1
Deleted build: Fedora-Budgie-Live-Rawhide-20230218.n.0
Deleted build: Fedora-Budgie-Live-Rawhide-20230219.n.0
Deleted build: Fedora-Budgie-Live-Rawhide-20230220.n.0
Deleted build: Fedora-Cinnamon-Live-38-20230215.n.0
Deleted build: Fedora-Cinnamon-Live-38-20230216.n.0
Traceback (most recent call last):
  File "/usr/sbin/koji-gc", line 1079, in <module>
    rv = main(args)
         ^^^^^^^^^^
  File "/usr/sbin/koji-gc", line 472, in main
    globals()['handle_' + x]()
  File "/usr/sbin/koji-gc", line 738, in handle_delete
    deletes[nvr].result
  File "/usr/lib/python3.11/site-packages/koji/__init__.py", line 3377, in result
    raise err
xmlrpc.client.Fault: <Fault 1: '39, Directory not empty'>

On the hub:

[Wed Mar 29 08:05:57.594476 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192] 2023-03-29 08:05:57,594 [WARNING] m=deleteBuild u=oscar p=132487 r=10.3.163.77:34192 koji.xmlrpc: Traceback (most recent call last):
[Wed Mar 29 08:05:57.594778 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]   File "/usr/lib/python3.11/site-packages/kojihub/kojixmlrpc.py", line 348, in multiCall
[Wed Mar 29 08:05:57.594785 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]     result = self._dispatch(call['methodName'], call['params'])
[Wed Mar 29 08:05:57.594788 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Wed Mar 29 08:05:57.594791 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]   File "/usr/lib/python3.11/site-packages/kojihub/kojixmlrpc.py", line 329, in _dispatch
[Wed Mar 29 08:05:57.594807 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]     ret = koji.util.call_with_argcheck(func, params, opts)
[Wed Mar 29 08:05:57.594810 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Wed Mar 29 08:05:57.594813 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]   File "/usr/lib/python3.11/site-packages/koji/util.py", line 271, in call_with_argcheck
[Wed Mar 29 08:05:57.594816 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]     return func(*args, **kwargs)
[Wed Mar 29 08:05:57.594819 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]            ^^^^^^^^^^^^^^^^^^^^^
[Wed Mar 29 08:05:57.594822 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]   File "/usr/lib/python3.11/site-packages/kojihub/kojihub.py", line 8613, in delete_build
[Wed Mar 29 08:05:57.594825 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]     _delete_build(binfo)
[Wed Mar 29 08:05:57.594828 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]   File "/usr/lib/python3.11/site-packages/kojihub/kojihub.py", line 8662, in _delete_build
[Wed Mar 29 08:05:57.594831 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]     koji.util.rmtree(builddir)
[Wed Mar 29 08:05:57.594834 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]   File "/usr/lib/python3.11/site-packages/koji/util.py", line 474, in rmtree
[Wed Mar 29 08:05:57.594836 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]     os.rmdir(path)
[Wed Mar 29 08:05:57.594839 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192] OSError: [Errno 39] Directory not empty: '/mnt/koji/packages/Fedora-Cinnamon-Live/38/20230216.n.1'
[Wed Mar 29 08:05:57.594842 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192] 
[Wed Mar 29 08:05:57.594869 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192] 594 [WARNING] m=None u=None p=132487 r=?:? koji.xmlrpc: Traceback (most recent call last):
[Wed Mar 29 08:05:57.594872 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]   File "/usr/lib/python3.11/site-packages/kojihub/kojixmlrpc.py", line 348, in multiCall
[Wed Mar 29 08:05:57.594875 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]     result = self._dispatch(call['methodName'], call['params'])
[Wed Mar 29 08:05:57.594878 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Wed Mar 29 08:05:57.594881 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]   File "/usr/lib/python3.11/site-packages/kojihub/kojixmlrpc.py", line 329, in _dispatch
[Wed Mar 29 08:05:57.594884 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]     ret = koji.util.call_with_argcheck(func, params, opts)
[Wed Mar 29 08:05:57.594887 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Wed Mar 29 08:05:57.594890 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]   File "/usr/lib/python3.11/site-packages/koji/util.py", line 271, in call_with_argcheck
[Wed Mar 29 08:05:57.594893 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]     return func(*args, **kwargs)
[Wed Mar 29 08:05:57.594895 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]            ^^^^^^^^^^^^^^^^^^^^^
[Wed Mar 29 08:05:57.594898 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]   File "/usr/lib/python3.11/site-packages/kojihub/kojihub.py", line 8613, in delete_build
[Wed Mar 29 08:05:57.594901 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]     _delete_build(binfo)
[Wed Mar 29 08:05:57.594904 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]   File "/usr/lib/python3.11/site-packages/kojihub/kojihub.py", line 8662, in _delete_build
[Wed Mar 29 08:05:57.594912 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]     koji.util.rmtree(builddir)
[Wed Mar 29 08:05:57.594915 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]   File "/usr/lib/python3.11/site-packages/koji/util.py", line 474, in rmtree
[Wed Mar 29 08:05:57.594918 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]     os.rmdir(path)
[Wed Mar 29 08:05:57.594921 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192] OSError: [Errno 39] Directory not empty: '/mnt/koji/packages/Fedora-Cinnamon-Live/38/20230216.n.1'
[Wed Mar 29 08:05:57.594924 2023] [wsgi:error] [pid 132487:tid 132517] [client 10.3.163.77:34192]

indeed that dir is not empty: 

# ls -laR /mnt/koji/packages/Fedora-Cinnamon-Live/38/20230216.n.1
/mnt/koji/packages/Fedora-Cinnamon-Live/38/20230216.n.1:
total 16
drwxr-sr-x.  4 apache apache 4096 Feb 16 22:35 .
drwxr-sr-x. 42 apache apache 4096 Mar 29 10:18 ..
drwxr-sr-x.  3 apache apache 4096 Feb 16 22:35 data
drwxr-sr-x.  2 apache apache 4096 Feb 16 22:35 images
/mnt/koji/packages/Fedora-Cinnamon-Live/38/20230216.n.1/data:
total 12
drwxr-sr-x. 3 apache apache 4096 Feb 16 22:35 .
drwxr-sr-x. 4 apache apache 4096 Feb 16 22:35 ..
drwxr-sr-x. 2 apache apache 4096 Mar 29 08:05 logs
/mnt/koji/packages/Fedora-Cinnamon-Live/38/20230216.n.1/data/logs:
total 8
drwxr-sr-x. 2 apache apache 4096 Mar 29 08:05 .
drwxr-sr-x. 3 apache apache 4096 Feb 16 22:35 ..
/mnt/koji/packages/Fedora-Cinnamon-Live/38/20230216.n.1/images:
total 2325804
drwxr-sr-x. 2 apache apache       4096 Feb 16 22:35 .
drwxr-sr-x. 4 apache apache       4096 Feb 16 22:35 ..
-rw-r--r--. 1 apache apache 2372268032 Feb 16 22:35 Fedora-Cinnamon-Live-x86_64-38-20230216.n.1.iso

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

Thanks for the detailed logs!

Well this is a perplexing failure.

This is failing at the final rmdir that our rmtree code runs at the very end after scrubbing the contents. So, somehow the contents were not scrubbed. It would be very surprising if another process were racing here.

There are places deep in the rmtree code where we keep going on certain OSErrors in order to place nice when racing with parallel deletions. My best guess is that there was an error at one of these points (which is unfortunately not logged), and the rmtree kept going until this point (which is basically a failsafe in the design to ensure we do in fact error when we can't manage to delete a tree.

I've got a PR to add more logging to rmtree. You might try pulling that in to see if we get more info about what is happening

https://pagure.io/koji/pull-request/3756

I would be curious if the error repeats if you manually try to delete one of these builds. E.g.

$ koji call deleteBuild Fedora-Cinnamon-Live-38-20230216.n.1

Honestly, my best guess here is that nfs is failing a way that probably shouldn't happen (i.e. an actual error situation in underlying infra), but that the rmtree code is masking the true cause of the error. The logging changes I linked should help determine what is going on.

I can try and fold in that PR tomorrow/this weekend. We do go into freeze tuesday so I'd like to back it out before then. 

➜  ~ koji call deleteBuild Fedora-Cinnamon-Live-38-20230216.n.1
True

# ls -laR /mnt/koji/packages/Fedora-Cinnamon-Live/38/20230216.n.1
ls: cannot access '/mnt/koji/packages/Fedora-Cinnamon-Live/38/20230216.n.1': No such file or directory

So it seems to have worked there. That does point to a race more than anything.

Will try and gather more info. ;)

ok. It's patch in place. Will let you know after the next failed run.

ok. Happened again today. :)

Unfortunately, it happend on the other hub, and I mistakenly didn't update to the patched version there, so I fear this isn't going to be 100% useful. ;(

The koji-gc output: 

Deleted build: gitleaks-8.15.4-1.fc37
Traceback (most recent call last):
  File "/usr/sbin/koji-gc", line 1079, in <module>
    rv = main(args)
         ^^^^^^^^^^
  File "/usr/sbin/koji-gc", line 472, in main
    globals()['handle_' + x]()
  File "/usr/sbin/koji-gc", line 738, in handle_delete
    deletes[nvr].result
  File "/usr/lib/python3.11/site-packages/koji/__init__.py", line 3377, in result
    raise err
xmlrpc.client.Fault: <Fault 1: '39, Directory not empty'>

[Mon Apr 03 08:02:14.727384 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860] 2023-04-03 08:02:14,727 [ERROR] m=None u=None p=998689 r=?:? koji.web: Traceback (most recent call last):
[Mon Apr 03 08:02:14.727404 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]   File "/usr/share/koji-web/scripts/wsgi_publisher.py", line 389, in handle_request
[Mon Apr 03 08:02:14.727409 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]     result = func(environ, **data)
[Mon Apr 03 08:02:14.727412 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]              ^^^^^^^^^^^^^^^^^^^^^
[Mon Apr 03 08:02:14.727415 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]   File "/usr/share/koji-web/scripts/index.py", line 1449, in builds
[Mon Apr 03 08:02:14.727419 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]     return _genHTML(environ, 'builds.chtml')
[Mon Apr 03 08:02:14.727422 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Mon Apr 03 08:02:14.727425 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]   File "/usr/share/koji-web/lib/kojiweb/util.py", line 147, in _genHTML
[Mon Apr 03 08:02:14.727428 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]     return tmpl_inst.respond()
[Mon Apr 03 08:02:14.727430 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]            ^^^^^^^^^^^^^^^^^^^
[Mon Apr 03 08:02:14.727433 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]   File "builds_chtml.py", line 91, in respond
[Mon Apr 03 08:02:14.727436 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]   File "/usr/lib64/python3.11/site-packages/Cheetah/Template.py", line 1685, in _handleCheetahInclude
[Mon Apr 03 08:02:14.727453 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]     nestedTemplateClass = compiler.compile(source=source,
[Mon Apr 03 08:02:14.727456 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Mon Apr 03 08:02:14.727460 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]   File "/usr/lib64/python3.11/site-packages/Cheetah/Template.py", line 738, in compile
[Mon Apr 03 08:02:14.727463 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]     fileHash += str(os.path.getmtime(file))
[Mon Apr 03 08:02:14.727465 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]                     ^^^^^^^^^^^^^^^^^^^^^^
[Mon Apr 03 08:02:14.727468 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]   File "<frozen genericpath>", line 55, in getmtime
[Mon Apr 03 08:02:14.727471 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860] FileNotFoundError: [Errno 2] No such file or directory: '/mnt/fedora_koji/koji/packages/gitleaks/8.15.4/1.fc38/data/sigcache/eb10b464/src/includes/header.chtml'
[Mon Apr 03 08:02:14.727475 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860] 
[Mon Apr 03 08:02:14.727516 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860] 727 [ERROR] m=builds u=None p=998689 r=10.3.163.74:57860 koji.web: Traceback (most recent call last):
[Mon Apr 03 08:02:14.727522 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]   File "/usr/share/koji-web/scripts/wsgi_publisher.py", line 389, in handle_request
[Mon Apr 03 08:02:14.727528 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]     result = func(environ, **data)
[Mon Apr 03 08:02:14.727532 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]              ^^^^^^^^^^^^^^^^^^^^^
[Mon Apr 03 08:02:14.727535 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]   File "/usr/share/koji-web/scripts/index.py", line 1449, in builds
[Mon Apr 03 08:02:14.727538 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]     return _genHTML(environ, 'builds.chtml')
[Mon Apr 03 08:02:14.727541 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Mon Apr 03 08:02:14.727544 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]   File "/usr/share/koji-web/lib/kojiweb/util.py", line 147, in _genHTML
[Mon Apr 03 08:02:14.727547 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]     return tmpl_inst.respond()
[Mon Apr 03 08:02:14.727550 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]            ^^^^^^^^^^^^^^^^^^^
[Mon Apr 03 08:02:14.727552 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]   File "builds_chtml.py", line 91, in respond
[Mon Apr 03 08:02:14.727555 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]   File "/usr/lib64/python3.11/site-packages/Cheetah/Template.py", line 1685, in _handleCheetahInclude
[Mon Apr 03 08:02:14.727558 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]     nestedTemplateClass = compiler.compile(source=source,
[Mon Apr 03 08:02:14.727561 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Mon Apr 03 08:02:14.727564 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]   File "/usr/lib64/python3.11/site-packages/Cheetah/Template.py", line 738, in compile
[Mon Apr 03 08:02:14.727568 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]     fileHash += str(os.path.getmtime(file))
[Mon Apr 03 08:02:14.727570 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]                     ^^^^^^^^^^^^^^^^^^^^^^
[Mon Apr 03 08:02:14.727573 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860]   File "<frozen genericpath>", line 55, in getmtime
[Mon Apr 03 08:02:14.727586 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860] FileNotFoundError: [Errno 2] No such file or directory: '/mnt/fedora_koji/koji/packages/gitleaks/8.15.4/1.fc38/data/sigcache/eb10b464/src/includes/header.chtml'
[Mon Apr 03 08:02:14.727591 2023] [wsgi:error] [pid 998689:tid 998728] [client 10.3.163.74:57860] 
[Mon Apr 03 08:02:14.731450 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016] 2023-04-03 08:02:14,731 [WARNING] m=deleteBuild u=oscar p=998689 r=10.3.163.77:36016 koji.xmlrpc: Traceback (most recent call last):
[Mon Apr 03 08:02:14.731468 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]   File "/usr/lib/python3.11/site-packages/kojihub/kojixmlrpc.py", line 348, in multiCall
[Mon Apr 03 08:02:14.731472 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]     result = self._dispatch(call['methodName'], call['params'])
[Mon Apr 03 08:02:14.731475 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Mon Apr 03 08:02:14.731478 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]   File "/usr/lib/python3.11/site-packages/kojihub/kojixmlrpc.py", line 329, in _dispatch
[Mon Apr 03 08:02:14.731481 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]     ret = koji.util.call_with_argcheck(func, params, opts)
[Mon Apr 03 08:02:14.731484 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Mon Apr 03 08:02:14.731487 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]   File "/usr/lib/python3.11/site-packages/koji/util.py", line 271, in call_with_argcheck
[Mon Apr 03 08:02:14.731506 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]     return func(*args, **kwargs)
[Mon Apr 03 08:02:14.731511 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]            ^^^^^^^^^^^^^^^^^^^^^
[Mon Apr 03 08:02:14.731515 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]   File "/usr/lib/python3.11/site-packages/kojihub/kojihub.py", line 8613, in delete_build
[Mon Apr 03 08:02:14.731519 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]     _delete_build(binfo)
[Mon Apr 03 08:02:14.731522 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]   File "/usr/lib/python3.11/site-packages/kojihub/kojihub.py", line 8662, in _delete_build
[Mon Apr 03 08:02:14.731525 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]     koji.util.rmtree(builddir)
[Mon Apr 03 08:02:14.731528 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]   File "/usr/lib/python3.11/site-packages/koji/util.py", line 474, in rmtree
[Mon Apr 03 08:02:14.731531 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]     os.rmdir(path)
[Mon Apr 03 08:02:14.731533 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016] OSError: [Errno 39] Directory not empty: '/mnt/koji/packages/gitleaks/8.15.4/1.fc38'
[Mon Apr 03 08:02:14.731536 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016] 
[Mon Apr 03 08:02:14.731556 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016] 731 [WARNING] m=None u=None p=998689 r=?:? koji.xmlrpc: Traceback (most recent call last):
[Mon Apr 03 08:02:14.731559 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]   File "/usr/lib/python3.11/site-packages/kojihub/kojixmlrpc.py", line 348, in multiCall
[Mon Apr 03 08:02:14.731562 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]     result = self._dispatch(call['methodName'], call['params'])
[Mon Apr 03 08:02:14.731565 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Mon Apr 03 08:02:14.731568 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]   File "/usr/lib/python3.11/site-packages/kojihub/kojixmlrpc.py", line 329, in _dispatch
[Mon Apr 03 08:02:14.731582 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]     ret = koji.util.call_with_argcheck(func, params, opts)
[Mon Apr 03 08:02:14.731586 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Mon Apr 03 08:02:14.731589 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]   File "/usr/lib/python3.11/site-packages/koji/util.py", line 271, in call_with_argcheck
[Mon Apr 03 08:02:14.731592 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]     return func(*args, **kwargs)
[Mon Apr 03 08:02:14.731595 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]            ^^^^^^^^^^^^^^^^^^^^^
[Mon Apr 03 08:02:14.731597 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]   File "/usr/lib/python3.11/site-packages/kojihub/kojihub.py", line 8613, in delete_build
[Mon Apr 03 08:02:14.731600 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]     _delete_build(binfo)
[Mon Apr 03 08:02:14.731603 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]   File "/usr/lib/python3.11/site-packages/kojihub/kojihub.py", line 8662, in _delete_build
[Mon Apr 03 08:02:14.731606 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]     koji.util.rmtree(builddir)
[Mon Apr 03 08:02:14.731609 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]   File "/usr/lib/python3.11/site-packages/koji/util.py", line 474, in rmtree
[Mon Apr 03 08:02:14.731615 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016] OSError: [Errno 39] Directory not empty: '/mnt/koji/packages/gitleaks/8.15.4/1.fc38'
[Mon Apr 03 08:02:14.731618 2023] [wsgi:error] [pid 998689:tid 998736] [client 10.3.163.77:36016]

I've now updated the other hub too. ;(

ok, here we go: 

Deleted build: Fedora-Container-Base-ELN-0.1677068930
Deleted build: Fedora-Container-Base-ELN-0.1677110401
Traceback (most recent call last):
  File "/usr/sbin/koji-gc", line 1079, in <module>
    rv = main(args)
         ^^^^^^^^^^
  File "/usr/sbin/koji-gc", line 472, in main
    globals()['handle_' + x]()
  File "/usr/sbin/koji-gc", line 738, in handle_delete
    deletes[nvr].result
  File "/usr/lib/python3.11/site-packages/koji/__init__.py", line 3377, in result
    raise err
xmlrpc.client.Fault: <Fault 1: '39, Directory not empty'>

[Wed Apr 05 18:42:39.981181 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052] 2023-04-05 18:42:39,981 [ERROR] m=None u=None p=1391022 r=?:? koji.web: Traceback (most recent call last):
[Wed Apr 05 18:42:39.981222 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]   File "/usr/share/koji-web/scripts/wsgi_publisher.py", line 389, in handle_request
[Wed Apr 05 18:42:39.981227 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]     result = func(environ, **data)
[Wed Apr 05 18:42:39.981230 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]              ^^^^^^^^^^^^^^^^^^^^^
[Wed Apr 05 18:42:39.981234 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]   File "/usr/share/koji-web/scripts/index.py", line 785, in taskinfo
[Wed Apr 05 18:42:39.981246 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]     return _genHTML(environ, 'taskinfo.chtml')
[Wed Apr 05 18:42:39.981272 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Wed Apr 05 18:42:39.981276 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]   File "/usr/share/koji-web/lib/kojiweb/util.py", line 147, in _genHTML
[Wed Apr 05 18:42:39.981279 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]     return tmpl_inst.respond()
[Wed Apr 05 18:42:39.981282 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]            ^^^^^^^^^^^^^^^^^^^
[Wed Apr 05 18:42:39.981285 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]   File "taskinfo_chtml.py", line 412, in respond
[Wed Apr 05 18:42:39.981288 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]   File "/usr/lib64/python3.11/site-packages/Cheetah/Template.py", line 1685, in _handleCheetahInclude
[Wed Apr 05 18:42:39.981306 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]     nestedTemplateClass = compiler.compile(source=source,
[Wed Apr 05 18:42:39.981310 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Wed Apr 05 18:42:39.981313 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]   File "/usr/lib64/python3.11/site-packages/Cheetah/Template.py", line 738, in compile
[Wed Apr 05 18:42:39.981316 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]     fileHash += str(os.path.getmtime(file))
[Wed Apr 05 18:42:39.981319 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]                     ^^^^^^^^^^^^^^^^^^^^^^
[Wed Apr 05 18:42:39.981322 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]   File "<frozen genericpath>", line 55, in getmtime
[Wed Apr 05 18:42:39.981325 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052] FileNotFoundError: [Errno 2] No such file or directory: '/mnt/fedora_koji/koji/packages/Fedora-Container-Base/Rawhide/20230225.n.0/data/logs/image/includes/header.chtml'
[Wed Apr 05 18:42:39.981329 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052] 
[Wed Apr 05 18:42:39.981356 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052] 981 [ERROR] m=None u=None p=1391022 r=?:? koji.web: Traceback (most recent call last):
[Wed Apr 05 18:42:39.981359 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]   File "/usr/share/koji-web/scripts/wsgi_publisher.py", line 389, in handle_request
[Wed Apr 05 18:42:39.981363 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]     result = func(environ, **data)
[Wed Apr 05 18:42:39.981366 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]              ^^^^^^^^^^^^^^^^^^^^^
[Wed Apr 05 18:42:39.981369 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]   File "/usr/share/koji-web/scripts/index.py", line 785, in taskinfo
[Wed Apr 05 18:42:39.981372 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]     return _genHTML(environ, 'taskinfo.chtml')
[Wed Apr 05 18:42:39.981375 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Wed Apr 05 18:42:39.981378 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]   File "/usr/share/koji-web/lib/kojiweb/util.py", line 147, in _genHTML
[Wed Apr 05 18:42:39.981381 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]     return tmpl_inst.respond()
[Wed Apr 05 18:42:39.981384 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]            ^^^^^^^^^^^^^^^^^^^
[Wed Apr 05 18:42:39.981387 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]   File "taskinfo_chtml.py", line 412, in respond
[Wed Apr 05 18:42:39.981390 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]   File "/usr/lib64/python3.11/site-packages/Cheetah/Template.py", line 1685, in _handleCheetahInclude
[Wed Apr 05 18:42:39.981393 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]     nestedTemplateClass = compiler.compile(source=source,
[Wed Apr 05 18:42:39.981396 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Wed Apr 05 18:42:39.981399 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]   File "/usr/lib64/python3.11/site-packages/Cheetah/Template.py", line 738, in compile
[Wed Apr 05 18:42:39.981402 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]     fileHash += str(os.path.getmtime(file))
[Wed Apr 05 18:42:39.981405 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]                     ^^^^^^^^^^^^^^^^^^^^^^
[Wed Apr 05 18:42:39.981414 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052]   File "<frozen genericpath>", line 55, in getmtime
[Wed Apr 05 18:42:39.981417 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052] FileNotFoundError: [Errno 2] No such file or directory: '/mnt/fedora_koji/koji/packages/Fedora-Container-Base/Rawhide/20230225.n.0/data/logs/image/includes/header.chtml'
[Wed Apr 05 18:42:39.981421 2023] [wsgi:error] [pid 1391022:tid 1391069] [client 10.3.163.74:41052] 
[Wed Apr 05 18:42:39.989535 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398] 2023-04-05 18:42:39,989 [WARNING] m=deleteBuild u=oscar p=1391022 r=10.3.163.74:43398 koji: Subdir disappeared during rmtree images: [Errno 2] No such file or directory: 'images'
[Wed Apr 05 18:42:39.989592 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398] 989 [WARNING] m=None u=None p=1391022 r=?:? koji: Subdir disappeared during rmtree images: [Errno 2] No such file or directory: 'images'
[Wed Apr 05 18:42:39.993317 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398] 2023-04-05 18:42:39,993 [WARNING] m=deleteBuild u=oscar p=1391022 r=10.3.163.74:43398 koji.xmlrpc: Traceback (most recent call last):
[Wed Apr 05 18:42:39.993332 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]   File "/usr/lib/python3.11/site-packages/kojihub/kojixmlrpc.py", line 348, in multiCall
[Wed Apr 05 18:42:39.993336 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]     result = self._dispatch(call['methodName'], call['params'])
[Wed Apr 05 18:42:39.993339 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Wed Apr 05 18:42:39.993342 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]   File "/usr/lib/python3.11/site-packages/kojihub/kojixmlrpc.py", line 329, in _dispatch
[Wed Apr 05 18:42:39.993345 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]     ret = koji.util.call_with_argcheck(func, params, opts)
[Wed Apr 05 18:42:39.993348 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Wed Apr 05 18:42:39.993351 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]   File "/usr/lib/python3.11/site-packages/koji/util.py", line 271, in call_with_argcheck
[Wed Apr 05 18:42:39.993354 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]     return func(*args, **kwargs)
[Wed Apr 05 18:42:39.993356 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]            ^^^^^^^^^^^^^^^^^^^^^
[Wed Apr 05 18:42:39.993359 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]   File "/usr/lib/python3.11/site-packages/kojihub/kojihub.py", line 8613, in delete_build
[Wed Apr 05 18:42:39.993362 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]     _delete_build(binfo)
[Wed Apr 05 18:42:39.993365 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]   File "/usr/lib/python3.11/site-packages/kojihub/kojihub.py", line 8662, in _delete_build
[Wed Apr 05 18:42:39.993368 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]     koji.util.rmtree(builddir)
[Wed Apr 05 18:42:39.993371 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]   File "/usr/lib/python3.11/site-packages/koji/util.py", line 476, in rmtree
[Wed Apr 05 18:42:39.993374 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]     os.rmdir(path)
[Wed Apr 05 18:42:39.993377 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398] OSError: [Errno 39] Directory not empty: '/mnt/koji/packages/Fedora-Container-Base/Rawhide/20230225.n.0'
[Wed Apr 05 18:42:39.993380 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398] 
[Wed Apr 05 18:42:39.993401 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398] 993 [WARNING] m=None u=None p=1391022 r=?:? koji.xmlrpc: Traceback (most recent call last):
[Wed Apr 05 18:42:39.993416 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]   File "/usr/lib/python3.11/site-packages/kojihub/kojixmlrpc.py", line 348, in multiCall
[Wed Apr 05 18:42:39.993420 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]     result = self._dispatch(call['methodName'], call['params'])
[Wed Apr 05 18:42:39.993423 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Wed Apr 05 18:42:39.993426 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]   File "/usr/lib/python3.11/site-packages/kojihub/kojixmlrpc.py", line 329, in _dispatch
[Wed Apr 05 18:42:39.993429 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]     ret = koji.util.call_with_argcheck(func, params, opts)
[Wed Apr 05 18:42:39.993431 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Wed Apr 05 18:42:39.993434 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]   File "/usr/lib/python3.11/site-packages/koji/util.py", line 271, in call_with_argcheck
[Wed Apr 05 18:42:39.993437 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]     return func(*args, **kwargs)
[Wed Apr 05 18:42:39.993440 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]            ^^^^^^^^^^^^^^^^^^^^^
[Wed Apr 05 18:42:39.993443 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]   File "/usr/lib/python3.11/site-packages/kojihub/kojihub.py", line 8613, in delete_build
[Wed Apr 05 18:42:39.993446 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]     _delete_build(binfo)
[Wed Apr 05 18:42:39.993448 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]   File "/usr/lib/python3.11/site-packages/kojihub/kojihub.py", line 8662, in _delete_build
[Wed Apr 05 18:42:39.993451 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]     koji.util.rmtree(builddir)
[Wed Apr 05 18:42:39.993454 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]   File "/usr/lib/python3.11/site-packages/koji/util.py", line 476, in rmtree
[Wed Apr 05 18:42:39.993457 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]     os.rmdir(path)
[Wed Apr 05 18:42:39.993460 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398] OSError: [Errno 39] Directory not empty: '/mnt/koji/packages/Fedora-Container-Base/Rawhide/20230225.n.0'
[Wed Apr 05 18:42:39.993463 2023] [wsgi:error] [pid 1391022:tid 1391062] [client 10.3.163.74:43398]

Commit 70c9b3e3 relates to this ticket

ok, circling back here...

still seeing:

Traceback (most recent call last):
  File "/usr/sbin/koji-gc", line 1082, in <module>
    rv = main(args)
         ^^^^^^^^^^
  File "/usr/sbin/koji-gc", line 475, in main
    globals()['handle_' + x]()
  File "/usr/sbin/koji-gc", line 741, in handle_delete
    deletes[nvr].result
  File "/usr/lib/python3.11/site-packages/koji/__init__.py", line 3505, in result
    raise err
xmlrpc.client.Fault: <Fault 1: '39, Directory not empty'>

and on the hub:

[Sun Aug 20 08:00:19.674086 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:391
48] 2023-08-20 08:00:19,674 [ERROR] m=deleteBuild u=oscar p=721140 r=10.3.163.77:39148 koji: U
nable to remove directory ppc64le: [Errno 2] No such file or directory: 'ppc64le'
[Sun Aug 20 08:00:19.674168 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:391
48] 674 [ERROR] m=fileinfo u=None p=721140 r=10.3.163.74:45230 koji: Unable to remove director
y ppc64le: [Errno 2] No such file or directory: 'ppc64le'
[Sun Aug 20 08:00:19.674271 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:391
48] 2023-08-20 08:00:19,674 [WARNING] m=deleteBuild u=oscar p=721140 r=10.3.163.77:39148 koji:
 Subdir disappeared during rmtree aarch64: [Errno 2] No such file or directory: 'aarch64'
[Sun Aug 20 08:00:19.674288 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:391
48] 674 [WARNING] m=fileinfo u=None p=721140 r=10.3.163.74:45230 koji: Subdir disappeared duri
ng rmtree aarch64: [Errno 2] No such file or directory: 'aarch64'
[Sun Aug 20 08:00:19.675105 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:391
48] 2023-08-20 08:00:19,675 [ERROR] m=deleteBuild u=oscar p=721140 r=10.3.163.77:39148 koji: U
nable to remove directory sigcache: [Errno 2] No such file or directory: 'sigcache'
[Sun Aug 20 08:00:19.675136 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:391
48] 675 [ERROR] m=fileinfo u=None p=721140 r=10.3.163.74:45230 koji: Unable to remove director
y sigcache: [Errno 2] No such file or directory: 'sigcache'
[Sun Aug 20 08:00:19.675196 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:391
48] 2023-08-20 08:00:19,675 [ERROR] m=deleteBuild u=oscar p=721140 r=10.3.163.77:39148 koji: U
nable to remove directory data: [Errno 2] No such file or directory: 'data'
[Sun Aug 20 08:00:19.675210 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:391
48] 675 [ERROR] m=fileinfo u=None p=721140 r=10.3.163.74:45230 koji: Unable to remove director
y data: [Errno 2] No such file or directory: 'data'
[Sun Aug 20 08:00:19.676430 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:391
48] 2023-08-20 08:00:19,676 [ERROR] m=deleteBuild u=oscar p=721140 r=10.3.163.77:39148 koji: U
nable to remove directory src: [Errno 13] Permission denied: 'src'
[Sun Aug 20 08:00:19.676485 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:391
48] 676 [ERROR] m=fileinfo u=None p=721140 r=10.3.163.74:45230 koji: Unable to remove director
y src: [Errno 13] Permission denied: 'src'
[Sun Aug 20 08:00:19.678914 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]   File "/usr/lib/python3.11/site-packages/kojihub/kojixmlrpc.py", line 348, in multiCall
[Sun Aug 20 08:00:19.679277 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]     result = self._dispatch(call['methodName'], call['params'])
[Sun Aug 20 08:00:19.679358 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Sun Aug 20 08:00:19.679368 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]   File "/usr/lib/python3.11/site-packages/kojihub/kojixmlrpc.py", line 329, in _dispatch
[Sun Aug 20 08:00:19.679373 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]     ret = koji.util.call_with_argcheck(func, params, opts)
[Sun Aug 20 08:00:19.679585 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Sun Aug 20 08:00:19.679692 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]   File "/usr/lib/python3.11/site-packages/koji/util.py", line 271, in call_with_argcheck
[Sun Aug 20 08:00:19.679696 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]     return func(*args, **kwargs)
[Sun Aug 20 08:00:19.679699 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]            ^^^^^^^^^^^^^^^^^^^^^
[Sun Aug 20 08:00:19.679701 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]   File "/usr/lib/python3.11/site-packages/kojihub/kojihub.py", line 8661, in delete_build
[Sun Aug 20 08:00:19.679704 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]     _delete_build(binfo)
[Sun Aug 20 08:00:19.679707 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]   File "/usr/lib/python3.11/site-packages/kojihub/kojihub.py", line 8710, in _delete_build
[Sun Aug 20 08:00:19.679709 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]     koji.util.rmtree(builddir)
[Sun Aug 20 08:00:19.679712 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]   File "/usr/lib/python3.11/site-packages/koji/util.py", line 476, in rmtree
[Sun Aug 20 08:00:19.679715 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]     os.rmdir(path)
[Sun Aug 20 08:00:19.679717 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148] OSError: [Errno 39] Directory not empty: '/mnt/koji/packages/annobin/12.19/1.fc39'
[Sun Aug 20 08:00:19.679805 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148] 
[Sun Aug 20 08:00:19.679836 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148] 678 [WARNING] m=None u=None p=721140 r=?:? koji.xmlrpc: Traceback (most recent call last):
[Sun Aug 20 08:00:19.679840 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]   File "/usr/lib/python3.11/site-packages/kojihub/kojixmlrpc.py", line 348, in multiCall
[Sun Aug 20 08:00:19.679843 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]     result = self._dispatch(call['methodName'], call['params'])
[Sun Aug 20 08:00:19.680762 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Sun Aug 20 08:00:19.680766 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]   File "/usr/lib/python3.11/site-packages/kojihub/kojixmlrpc.py", line 329, in _dispatch
[Sun Aug 20 08:00:19.680769 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]     ret = koji.util.call_with_argcheck(func, params, opts)
[Sun Aug 20 08:00:19.680772 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Sun Aug 20 08:00:19.680775 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]   File "/usr/lib/python3.11/site-packages/koji/util.py", line 271, in call_with_argcheck
[Sun Aug 20 08:00:19.680778 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]     return func(*args, **kwargs)
[Sun Aug 20 08:00:19.680781 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]            ^^^^^^^^^^^^^^^^^^^^^
[Sun Aug 20 08:00:19.680784 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]   File "/usr/lib/python3.11/site-packages/kojihub/kojihub.py", line 8661, in delete_build
[Sun Aug 20 08:00:19.680787 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]     _delete_build(binfo)
[Sun Aug 20 08:00:19.680790 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]   File "/usr/lib/python3.11/site-packages/kojihub/kojihub.py", line 8710, in _delete_build
[Sun Aug 20 08:00:19.680793 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]     koji.util.rmtree(builddir)
[Sun Aug 20 08:00:19.680795 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]   File "/usr/lib/python3.11/site-packages/koji/util.py", line 476, in rmtree
[Sun Aug 20 08:00:19.680798 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]     os.rmdir(path)
[Sun Aug 20 08:00:19.680801 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148] OSError: [Errno 39] Directory not empty: '/mnt/koji/packages/annobin/12.19/1.fc39'
[Sun Aug 20 08:00:19.680804 2023] [wsgi:error] [pid 721140:tid 721171] [client 10.3.163.77:39148]

I'm not 100% sure that the hub one matches... can koji-gc print out the build it's about to delete?

Also, when it finds this list and goes to delete them and errors on this, will the next run correctly retry and delete those builds? Or are we accumulating a bunch of builds koji should have deleted, but won't? I would think the next run's query would find them fine, but not 100% sure I understand the process.
  • koji-gc can't report it precisely, as it is sending it in batches, so just hub knows which build failed.
  • It looks to me like NFS issue (probably those .nfs* files which still exists for some other process). I don't think we are able to do something about this (except retrying to delete it next time). @mikem other ideas?
  • Yes, builds which failed complete removal are not moved to DELETED state, so they'll be tried again next time.

Is batching worthwhile here? There's not usually that many to delete and doing a lot of them might also impact storage bw?

Yeah, could indeed be a nfs issue. As one thing I was meaning to try, I switched our hubs to use nfsv4 (from v3). Todays run of delete actually did finish normally... so I wonder if the improved locking in v4 "fixed" things. Will have to see if today was just a one time thing or if it's working more reliably now.

Great on the builds.

So, I don't know here... I guess you can just close this? or if you want to adjust the batching or logging anymore?

Batch is worthwile for some loads. E.g. I was deleting 34k builds last month.
Maybe it is an option to add some retry for failed deletions? But not sure if it is worth increasing the complexity when next run will try to do the same anyway.

ok, so it was a fluke that it finished ok that day. I got another failure today. 

Traceback (most recent call last):
  File "/usr/sbin/koji-gc", line 1082, in <module>
    rv = main(args)
         ^^^^^^^^^^
  File "/usr/sbin/koji-gc", line 475, in main
    globals()['handle_' + x]()
  File "/usr/sbin/koji-gc", line 741, in handle_delete
    deletes[nvr].result
  File "/usr/lib/python3.11/site-packages/koji/__init__.py", line 3505, in result
    raise err
xmlrpc.client.Fault: <Fault 1: '39, Directory not empty'>

So, this is the final rmdir for the package and it's expecting that all the files in that dir are deleted, but they aren't. right?

Is that files it sees that should be deleted? Or directories? or both?

I can add further debugging to catch this error and lists what is in the directory in the moment. It could disappear meanwhile, so if there is no result from listdir, it can retry deletion. But we could see in some cases what was there.

Can you try apply #3883 at hub?

Unfortunately we are in freeze for the f39 beta release.

I can do this after though... thanks for the patch.

Beta release is tomorrow, so I can apply after we are out of freeze wed.

One question in the mean time however...

On 2023-09-12 we had:

https://lists.fedoraproject.org/archives/list/releng-cron@lists.fedoraproject.org/message/HW56Q5PJ5WRBLTRATKPGWLMIEHBW467Q

Which said: 

...
264 builds remaining
4th pass: deletion
...
xmlrpc.client.Fault: <Fault 1: '39, Directory not empty'>

The next day:

https://lists.fedoraproject.org/archives/list/releng-cron@lists.fedoraproject.org/message/43A54CPEEGTJ5WQGUFR5PSYPTWCB4WKD

Getting list of builds in trash...
...got 0 builds to check
...

Shouldn't there been some from the failed run the day before? Or did it submit them all in a batch and actually deleted them all, but printed/got the error on one of them?

I know its a bunch more logging, but could we print the proposed list of to be deleted builds at each step so we can check and make sure they were all deleted?

Sorry for the delay. I have rolled that PR out now. Can look at tomorrow's run to see what it shows.

So, The script gave: 

Deleted build: Fedora-Cinnamon-Live-Rawhide-20230820.n.0
Traceback (most recent call last):
  File "/usr/sbin/koji-gc", line 1082, in <module>
    rv = main(args)
         ^^^^^^^^^^
  File "/usr/sbin/koji-gc", line 475, in main
    globals()['handle_' + x]()
  File "/usr/sbin/koji-gc", line 741, in handle_delete
    deletes[nvr].result
  File "/usr/lib/python3.11/site-packages/koji/__init__.py", line 3505, in result
    raise err
xmlrpc.client.Fault: <Fault 1: '39, Directory not empty'>

and I see on the hub: 

[Wed Sep 27 08:00:38.470338 2023] [wsgi:error] [pid 2504922:tid 2504974] [client 10.3.163.77:48354] 470 [ERROR] m=rpminfo u=None p=2504922 r=10.3.163.75:35560 koji: Unable to remove directory aarch64: [Errno 2] No such file or directory: 'aarch64'
[Wed Sep 27 08:00:38.470987 2023] [wsgi:error] [pid 2504922:tid 2504974] [client 10.3.163.77:48354] 2023-09-27 08:00:38,470 [ERROR] m=deleteBuild u=oscar p=2504922 r=10.3.163.77:48354 koji: Unable to remove directory aarch64: [Errno 2] No such file or directory: 'aarch64'
[Wed Sep 27 08:00:38.496242 2023] [wsgi:error] [pid 2504922:tid 2504974] [client 10.3.163.77:48354] 496 [ERROR] m=None u=None p=2504922 r=?:? koji: Unable to remove directory data: [Errno 2] No such file or directory: 'data'
[Wed Sep 27 08:00:38.496294 2023] [wsgi:error] [pid 2504922:tid 2504974] [client 10.3.163.77:48354] 2023-09-27 08:00:38,496 [ERROR] m=deleteBuild u=oscar p=2504922 r=10.3.163.77:48354 koji: Unable to remove directory data: [Errno 2] No such file or directory: 'data'

But its not doing the listdir there that I can find. So, perhaps errno.ENOTEMPTY isn't right here?

It is probably failing in later stage. I've extended PR a bit.

The ENOTEMPTY is the error at the top level when rmtree tries to rmdir the top dir.

The Unable to remove directory errors say "No such file or directory".

 
[Wed Sep 27 08:00:38.470338 2023] [wsgi:error] [pid 2504922:tid 2504974] [client 10.3.163.77:48354] 470 [ERROR] m=rpminfo u=None p=2504922 r=10.3.163.75:35560 koji: Unable to remove directory aarch64: [Errno 2] No such file or directory: 'aarch64'
[Wed Sep 27 08:00:38.470987 2023] [wsgi:error] [pid 2504922:tid 2504974] [client 10.3.163.77:48354] 2023-09-27 08:00:38,470 [ERROR] m=deleteBuild u=oscar p=2504922 r=10.3.163.77:48354 koji: Unable to remove directory aarch64: [Errno 2] No such file or directory: 'aarch64'
[Wed Sep 27 08:00:38.496242 2023] [wsgi:error] [pid 2504922:tid 2504974] [client 10.3.163.77:48354] 496 [ERROR] m=None u=None p=2504922 r=?:? koji: Unable to remove directory data: [Errno 2] No such file or directory: 'data'
[Wed Sep 27 08:00:38.496294 2023] [wsgi:error] [pid 2504922:tid 2504974] [client 10.3.163.77:48354] 2023-09-27 08:00:38,496 [ERROR] m=deleteBuild u=oscar p=2504922 r=10.3.163.77:48354 koji: Unable to remove directory data: [Errno 2] No such file or directory: 'data'

This output is strange. There seem to be duplicate log lines, but the duplicates are odd.

One of them has:

m=rpminfo u=None p=2504922 r=10.3.163.75:35560 koji: Unable to remove directory aarch64: [Errno 2] No such file or directory: 'aarch64'

rpminfo is not an rpc method. It's unclear how this output could happen.

Probably not related, but w e i r d .
Edited by mikem

We could probably extend the retry behavior in rmtree, but I'm not sure that is really the best approach, because if we're seeing these errors then either:

  • the os is doing something very, very wrong underneath is
  • there is some subtle, undiscovered bug in our rmtree code

And working around is only masking what could be a bigger problem

A more complete log of a more recent instance

koji3755-1.log

I guess all the log lines are duplicated? I guess something is wrong with the logging code.

Ah, the "Directory not empty" error is encountered at the top level dir. The logging patch doesn't log the listdir there.

So, we have one "Unable to remove directory" error during traversal, claiming "No such file or directory". The code ignores this since there's no point worrying about deleting something that doesn't exist.

Then we get back to the very top and our last act is to remove the top directory that should now be empty, and fail with a "Directory not empty" error. Either the first error lied and the directory did exist, or something else appeared in the directory in the meantime. Either way, more debug logging would help.

The images directory does in fact remain:

[root@koji01 ~][PROD-IAD2]# find /mnt/koji/packages/flatpak-kde5-runtime/f39/14 -ls
 86874830      4 drwxr-sr-x   3 apache   apache       4096 Nov 27 08:00 /mnt/koji/packages/flatpak-kde5-runtime/f39/14
 86874831      4 drwxr-sr-x   2 apache   apache       4096 Nov 27 08:00 /mnt/koji/packages/flatpak-kde5-runtime/f39/14/images

The logging patch doesn't log the listdir there.

Ah, looks like Tomas already extended the patch (#3883) to log there too, but the hub doesn't have that update

More logging -- https://pagure.io/fork/mikem/koji/commits/pr3883updates

fwiw, the duplicate output is due to #3954

@kevin the duplicate log lines are because your httpd config is out of sync with the code. You'll want to set WSGIDaemonProcess and WSGIProcessGroup. See

https://pagure.io/koji/pull-request/891
https://pagure.io/koji/pull-request/2731

Ah. Will fix. Thanks for the catch!

So, I have not seen this problem at all with koji-gc in the last months.

However, I am seeing a similar thing with koji-change-volumes still. :(

Should I add info on that here? Or file a new koji-tools issue for that?

Thanks for the heads-up. I've grabbed some logs from the hub and am looking through them now. Looks like good data.

This is not a koji-tools issue. The rmtree call is happening via a hub call.

At a glance, there are definitely parallel calls to changeBuildVolume (for the same build)
Edited by mikem

Yeah, I can provide more details. I was trying to move f29 builds to fedora_koji_archive04. I ran a --test run and it showed there were ~800 or so builds to move.

I started the real run and it processed ok for a short time, but then hit at least two errors so I stopped it.

I also try re-running it after cleaning up the errors with one of our hubs disabled. So, all requests were going to the same hub.

It's really sounding like some kind of nfs caching thing where it moves, deletes and then checks and the nfs server gives it back a cached view of the directory? or the rm didn't complete?

Anyhow, please let me know if I can help test or figure this out. We are getting dangerously low on space again, and I really need to archive stuff off the main volume.

Would it be an idea to run it without threads (I know it would be slow, but if it works slow is better than breaking. ;)

I'm digging into this a bit. Maybe hold off on runs for the moment?

I finally have a replicator for this. I'm going to work on a fix.

Hurray! awesome.

The core issue is that our rmtree function is inherently not thread safe, due to its use of chdir to traverse directory trees.

Fixing this without re-breaking #201 is a bit tricky. I've looked at several avenues, and the least invasive seems to be to use fork. That solution is in #4012.

Longer term, we way want to move to a dirfd-based solution, but that ends up being a near complete rewrite of the rmtree function.

For a replicator, see test_rmtree_race_thread in the PR

@tkopecek reasonable to pull into 1.34.1?

@kevin I'm feeling good about the current PR

ok, cool. So far we have been doing fine with prefork setup to avoid the issue, but a fix would be great.

I think we may have switched from prefork due to load issues that were really db issues, but not sure.

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

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

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

Commit d3316540 fixes this issue

Commit 4fddafc5 fixes this issue

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

Please continue any further discussion there.
Metadata
None

testing-done testing-ready

None
None
Low
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.