koji

#4417 Task can fail with FileExistsError exception if session expires while uploads are happening
Closed: Fixed by mikem. Opened by adamwill.

Closed: Fixed
Reopen Issue

Many thanks to @mizdebsk for most of the theory here.

A Fedora compose failed due to this task. The error is : [Errno 17] File exists: '/mnt/koji/work/tasks/3296/134603296'. After a bit of digging we found that error is raised on the hub and propagated to the builder. The traceback we see on the builder looks like this, which is important because we can see it occurs during renewal of an expired session:

2025-07-04 20:38:27,568 [WARNING] {1159121} koji.TaskManager:1430 FAULT:
Traceback (most recent call last):
  File "/usr/lib/python3.13/site-packages/koji/daemon.py", line 675, in checkout
    _run(cmd, chdir=update_checkout_dir, fatal=True)
    ~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.13/site-packages/koji/daemon.py", line 535, in _run
    if log_output(session, cmd[0], cmd, logfile, uploadpath,
       ~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
                  cwd=chdir, logerror=1, append=append, env=env):
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.13/site-packages/koji/daemon.py", line 176, in log_output
    incremental_upload(session, remotename, outfd, uploadpath)
    ~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.13/site-packages/koji/daemon.py", line 62, in incremental_upload
    fast_incremental_upload(session, fname, fd, path, retries, logger)
    ~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.13/site-packages/koji/daemon.py", line 102, in fast_incremental_upload
    result = session.rawUpload(contents, offset, path, fname, overwrite=True)
  File "/usr/lib/python3.13/site-packages/koji/__init__.py", line 2539, in __call__
    return self.__func(self.__name, args, opts)
           ~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.13/site-packages/koji/__init__.py", line 3123, in _renew_expired_session
    return func(self, *args, **kwargs)
  File "/usr/lib/python3.13/site-packages/koji/__init__.py", line 3202, in _callMethod
    raise err
  File "/usr/lib/python3.13/site-packages/koji/__init__.py", line 3149, in _callMethod
    return self._sendCall(handler, headers, request)
           ~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.13/site-packages/koji/__init__.py", line 3042, in _sendCall
    raise e
  File "/usr/lib/python3.13/site-packages/koji/__init__.py", line 3038, in _sendCall
    return self._sendOneCall(handler, headers, request)
           ~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.13/site-packages/koji/__init__.py", line 3091, in _sendOneCall
    ret = self._read_xmlrpc_response(r)
  File "/usr/lib/python3.13/site-packages/koji/__init__.py", line 3103, in _read_xmlrpc_response
    result = u.close()
  File "/usr/lib64/python3.13/xmlrpc/client.py", line 642, in close
    raise Fault(**self._stack[0])
xmlrpc.client.Fault: <Fault 1: "<class 'FileExistsError'>: [Errno 17] File exists: '/mnt/koji/work/tasks/3296/134603296'">
During handling of the above exception, another exception occurred:

(there's then a near-duplicate traceback, but it's not important, it's just because there's a recovery attempt which fails in the same way). The traceback on the hub - which shows us where it actually blew up - looks like this:

koji.xmlrpc: Traceback (most recent call last):
File "/usr/lib/python3.13/site-packages/kojihub/kojixmlrpc.py", line 273, in _wrap_handler
  response = handler(environ)
File "/usr/lib/python3.13/site-packages/kojihub/kojixmlrpc.py", line 296, in handle_upload
  return kojihub.handle_upload(environ)
         ~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^
File "/usr/lib/python3.13/site-packages/kojihub/kojihub.py", line 16269, in handle_upload
  fn = get_upload_path(path, name, create=True, volume=volume)
File "/usr/lib/python3.13/site-packages/kojihub/kojihub.py", line 16226, in get_upload_path
  koji.ensuredir(udir)
  ~~~~~~~~~~~~~~^^^^^^
File "/usr/lib/python3.13/site-packages/koji/__init__.py", line 570, in ensuredir
  os.mkdir(directory)
  ~~~~~~~~^^^^^^^^^^^
FileExistsError: [Errno 17] File exists: '/mnt/koji/work/tasks/3296/134603296'

This is very weird, because the relevant bit of ensuredir looks like this:

        try:
            os.mkdir(directory)
        except OSError:
            # do not thrown when dir already exists (could happen in a race)
            if not os.path.isdir(directory):
                # something else must have gone wrong
                raise

that is, we catch OSError exceptions from the os.mkdir call - FileExistsError is an instance of OSError, I checked that - and only raise them if the os.path.isdir(directory) check fails, which it absolutely should not in this case. That path is a directory. When I run this test script on the same host where the failure happened, it prints "ok fine":

#!/usr/bin/python3
import os
directory = "/mnt/koji/work/tasks/3296/134603296"
try:
    os.mkdir(directory)
except OSError:
    if not os.path.isdir(directory):
        raise
    print("ok fine")

so, there must be something weird and race-y going on here. @mizdebsk has a theory, remembering that /mnt/koji here is a symlink to /mnt/fedora_koji/koji, which is on an NFSv4 share, and that there are two Koji hubs (koji01 and koji02) which both mount the same NFSv4 share as /mnt/fedora_koji and symlink /mnt/fedora_koji/koji to /mnt/koji:

"so we have 2 hub servers.
when one creates directory, there is nfs propagation delay before the other sees it.
builder has session with one hub, starts file upload, fist chunk is stored.
but session expires, it establishes a new session, with the other hub.
the other hub tries to make directory for the file, but nfs server refuses - directory exists on netapp
hub checks whether it exists, but doesn't see it yet"

That seems kinda plausible (so far as I follow it), but hard to prove. It'd also have to either be the case that the timing goes wrong in just the same way every time the session expires during uploads and the builder's new session happens to be on the other hub, or we're getting really spectacularly unlucky each time this happens.

Or something else could be going on that we didn't think of.

Anyway, what can we do to fix this? I can think of three angles to attack it from:

  1. Make ensuredirs into a lighter wrapper around os.makedirs, hope that helps
  2. Try and robustify ensuredirs against the problem somehow (sleeps?!)
  3. Attack from the session angle instead, somehow try and avoid sessions expiring - could we 'lock' the session during series of file uploads or something?

I can see in the Koji hub logs that this problem has happened one other time since the datacenter move:

[root@koji01 httpd][PROD-RDU3]# grep FileExistsError * | grep task
error_log:[Fri Jul 04 17:59:31.052260 2025] [wsgi:error] [pid 708276:tid 708276] [client 10.16.163.77:37124] FileExistsError: [Errno 17] File exists: '/mnt/koji/work/tasks/7544/134597544'

There are also some similar-but-probably-a-bit-different cases like this:

error_log:[Fri Jul 04 21:44:34.651556 2025] [wsgi:error] [pid 732096:tid 732096] [client 10.16.163.77:48160] FileExistsError: [Errno 17] File exists: '/mnt/koji/work/cli-build/1751665474.6262825.nTVvVDsN'

@kevin fyi

oh, on @mizdebsk 's theory, we at least don't need the session to expire in the middle of a multi-chunk upload - it can just expire between file uploads. we definitely upload multiple files, reusing the same session instance between them.

There is an evidence in httpd access logs that upload for the file went to two different hubs:

first hub (koji01) has:

10.16.163.76 - - [04/Jul/2025:20:38:24 +0000] "POST /kojihub?filename=checkout.log&filepath=tasks%2F3296%2F134603296&fileverify=adler32&offset=0&overwrite=1 HTTP/1.1" 200 427 "-" "koji/1"

second hub (koji02) has:

10.16.163.76 - - [04/Jul/2025:20:38:26 +0000] "POST /kojihub?filename=checkout.log&filepath=tasks%2F3296%2F134603296&fileverify=adler32&offset=0&overwrite=1 HTTP/1.1" 200 349 "-" "koji/1"

Second hub koji02 is the one that raised the FileExistsError.
It failed to make directory as it was already created by koji01,
but it didn't see the directory in the file system yet either.

because we can see it occurs during renewal of an expired session

The traceback does not indicate this.

The _renew_expired_session function is used as a wrapper on _callMethod. It is part of the code path every call, but it only renews the session when the hub reports an AuthExpired fault.

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

I see two additional instances of this sort of error on the hub today. In neither case did the host show an authentication in access.log matching the time. I'm pretty sure this has nothing to do with expired sessions.

If this is due to a race where two hubs are trying to handle the same call, then it is more likely something similar to this case (where the proxy in front of the hubs made a duplicate call). Do any of these line up with excessive load perhaps?

https://pagure.io/koji/issue/4371

Make ensuredirs into a lighter wrapper around os.makedirs, hope that helps

koji.ensuredir exists because makedirs was insufficient. I suppose now that python's makedirs supports the exists_ok option (since 3.2), we could look into using it. It appears that the code for makedirs is now quite similar to ensuredir.

However, the function is in the main library, where we still support py2, so we'd still need the old version. Given the similarity between ensuredir and makedirs, I'm in no rush. Odds are, we'd see the same failure with makedirs.

I suspect this is more than a race. As you say, this is weird.

IF this error were a race, that would mean that some other thread is removing the directory out from under us. That is almost certainly not the case. No normal process in Koji is going to remove freshly created directories under work/.

My initial guess is nfs caching gone wrong. Have nfs mount options perhaps changed in the move?

Do any of these line up with excessive load perhaps?

No, Koji was under a very light load at that times.

Have nfs mount options perhaps changed in the move?

No, I don't think so.
Hubs were upgraded from Fedora 41 to Fedora 42 and we have a different hardware now.
Edited by mizdebsk

msg sync

msg sync

Some additional debug code in #4422. If this got onto the hub it might help us figure this out.

Is this something that could be fixed/mitigated at the reverse proxy? Usually for this kind of situation, reverse proxies can be configured to keep backends "sticky" for any given client (unless that backend completely fails). That would avoid the NFS racing between hubs.

Yeah, we are using apache mod_proxy_balancer for koji... apparently it can do stickyness on cookie or path/query... https://httpd.apache.org/docs/2.4/mod/mod_proxy_balancer.html
But that could be a option indeed.

I've put in place the debugging patch from #4422

keep backends "sticky"

If a client is using the koji client library, it should be recycling the connection with keepalive.

I do think the proxy is a possible culprit, but there is no smoking gun yet.

That would avoid the NFS racing between hubs.

We don't know the cause of this yet. This behavior is extremely weird. While it could involve a race, I have yet to see theory that would fully account for the behavior.
Edited by mikem

I've put in place the debugging patch from #4422

Thanks! I'll keep an eye on the logs. This seems to happen a few times a day, so hopefully we'll have a little more insight soon

I had a task hit this an hour or so ago: https://koji.fedoraproject.org/koji/taskinfo?taskID=134905757

On koji01 I see this, at the correct time:

2025-07-17 20:55:15,825 [ERROR] m=None u=buildvm-x86-07.rdu3.fedoraproject.org p=148245 r=10.16.163.76:56884 koji: Failed to create directory: /mnt/koji/work/tasks/5757/134905757
2025-07-17 20:55:15,828 [WARNING] m=None u=buildvm-x86-07.rdu3.fedoraproject.org p=148245 r=10.16.163.76:56884 koji.xmlrpc: Traceback (most recent call last):
  File "/usr/lib/python3.13/site-packages/kojihub/kojixmlrpc.py", line 273, in _wrap_handler
    response = handler(environ)
  File "/usr/lib/python3.13/site-packages/kojihub/kojixmlrpc.py", line 296, in handle_upload
    return kojihub.handle_upload(environ)
           ~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^
  File "/usr/lib/python3.13/site-packages/kojihub/kojihub.py", line 16269, in handle_upload
    fn = get_upload_path(path, name, create=True, volume=volume)
  File "/usr/lib/python3.13/site-packages/kojihub/kojihub.py", line 16226, in get_upload_path
    koji.ensuredir(udir)
    ~~~~~~~~~~~~~~^^^^^^
  File "/usr/lib/python3.13/site-packages/koji/__init__.py", line 572, in ensuredir
    os.mkdir(directory)
    ~~~~~~~~^^^^^^^^^^^
FileExistsError: [Errno 17] File exists: '/mnt/koji/work/tasks/5757/134905757'

so we're on the first branch, where _lstat(directory) returns None...
Edited by adamwill

so we're on the first branch, where _lstat(directory) returns None...

Not surprising, but at least we can eliminate some sort of non-dir appearing.

I've added some more debug code in #4422. It might tell us something. It would be interesting to see the time info.

My best guess at this point is that there is a parallel call involved, but the thing is this code is already intended to be race-resistant. That's why we trap the error and check the dir. It's not sane for the kernel to tell us that we can't make a directory because it already exists and then immediately tell us that the directory does not exist. This is more than a race; it looks like an nfs bug.

Ok, I was able to replicate the behavior directly on the hubs by running ensuredir in a loop on both in parallel. I can get the error pretty quickly that way.

I used this to explore the bug a bit and I may have a workaround —

Calling os.listdir on the parent directory appears to force the os to notice there's a new subdirectory there. After making this call, future lstats succeed. This isn't just a timing thing, adding a fairly long wait in the handler does not help the same way.

I'll make a new PR with this workaround.

I have a workaround in #4427

This is the script I used to replicate the issue. It needs to be run in parallel on multiple hosts using the same nfs mount for /mnt/koji
ensuredir-race
Edited by mikem

Metadata Update from @mikem:
- Issue tagged with: testing-basic

There's discussion in the nfs(5) man page under "DATA AND METADATA COHERENCE" that might be useful here until you get an NFS guru's attention.

fwiw, this is definitely linked to the migration.

koji=> select count(id), date_trunc('day', create_time) as day from task where create_time > now() - '14 weeks'::interval and result like '%FileExistsError%' and state=5 group by day order by day;
 count |          day           
-------+------------------------
     3 | 2025-07-04 00:00:00+00
     8 | 2025-07-07 00:00:00+00
     3 | 2025-07-08 00:00:00+00
     1 | 2025-07-09 00:00:00+00
     2 | 2025-07-10 00:00:00+00
     3 | 2025-07-11 00:00:00+00
     1 | 2025-07-12 00:00:00+00
     2 | 2025-07-14 00:00:00+00
     2 | 2025-07-15 00:00:00+00
     4 | 2025-07-16 00:00:00+00
     4 | 2025-07-17 00:00:00+00
     2 | 2025-07-19 00:00:00+00
     4 | 2025-07-21 00:00:00+00
     6 | 2025-07-23 00:00:00+00
(14 rows)

Looking at task failures is imperfect because it the error can happen other ways, but the pattern is still pretty clear.

@kevin can confirm, but AIUI what happened with the migration is basically that we got faster everything. faster CPUs, faster storage.

Metadata Update from @mikem:
- Issue set to the milestone: 1.36

The workaround in #4427 appears to be working well so far. Haven't seen any instances of this error since it was deployed yesterday.

For future reference, it's possible that adding lookupcache=positive might also work around this (but with some performance cost)

@kevin can confirm, but AIUI what happened with the migration is basically that we got faster everything. faster CPUs, faster storage.

yeah.

old dc: virthosts with spinning disks, single 10G network connection, older netapp

new dc: virthosts with nvme, 2 bonded 25G connections, new netapp

So, things likely are a good deal faster at most everything.

So, things likely are a good deal faster at most everything.

One of the things I tried in testing was adding a fairly long sleep before retrying the lstat, so I don't think this is just a change in system speed.

It's possible that this is a kernel bug. Did the kernel change in the migration?

At any rate, the workaround seems to be solving the problem. I don't see any of these errors since July 23. Expecting to include this in 1.36.

Yeaah, the old dc hubs were f41 and new are f42... there was possibly a kernel update in there.

Ah yeah, I have logs...

iad2 koji01 last boot: 6.14.6-200.fc41.x86_64
rdu3 koji01: 6.15.3-200.fc42.x86_64

so, could indeed be a 6.14 -> 6.15 issue.

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

Commit ff1b2b2f fixes this issue

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

Please continue any further discussion there.
Metadata
None

testing-basic testing-done

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.