koji

#3220 tagBuild tasks sometimes fail with "already tagged", when the build was not tagged before the task ran
Closed: Fixed by tkopecek. Opened by adamwill.

Closed: Fixed
Reopen Issue

Since we updated Fedora's Koji deployment to 1.27.1 this weekend, we're seeing quite a lot of failures of tagBuild tasks with "already tagged" errors. This is happening to package builds and image builds. In each case, the build had never been tagged before. Here are some examples:

@kevin looked at the builder logs from the time of that first example (the KDE live image one) and found a long and fairly hard-to-decipher traceback:

 2022-01-20 08:45:00,384 [WARNING] {3348894} koji.TaskManager:1477 TRACEBACK: Traceback (most recent call last):
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2783, in _callMethod
     return self._sendCall(handler, headers, request)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2698, in _sendCall
     return self._sendOneCall(handler, headers, request)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2747, in _sendOneCall
     ret = self._read_xmlrpc_response(r)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2759, in _read_xmlrpc_response
     result = u.close()
   File "/usr/lib64/python3.10/xmlrpc/client.py", line 662, in close
 xmlrpc.client.Fault: <Fault 1004: 'host 394 does not own task 81506954'>
 During handling of the above exception, another exception occurred:
 Traceback (most recent call last):
   File "/usr/lib/python3.10/site-packages/koji/daemon.py", line 1458, in runTask
     response = (handler.run(),)
   File "/usr/lib/python3.10/site-packages/koji/tasks.py", line 335, in run
     return koji.util.call_with_argcheck(self.handler, self.params, self.opts)
   File "/usr/lib/python3.10/site-packages/koji/util.py", line 271, in call_with_argcheck
     return func(*args, **kwargs)
   File "/usr/sbin/kojid", line 1433, in handler
     broot.init()
   File "/usr/sbin/kojid", line 569, in init
     rv = self.mock(['--init'])
   File "/usr/sbin/kojid", line 527, in mock
     incremental_upload(self.session, fname, fd, uploadpath, logger=self.logger)
   File "/usr/lib/python3.10/site-packages/koji/daemon.py", line 62, in incremental_upload
     fast_incremental_upload(session, fname, fd, path, retries, logger)
   File "/usr/lib/python3.10/site-packages/koji/daemon.py", line 102, in fast_incremental_upload
     result = session.rawUpload(contents, offset, path, fname, overwrite=True)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2348, in __call__
     return self.__func(self.__name, args, opts)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2802, in _callMethod
     raise err
 koji.ActionNotAllowed: host 394 does not own task 81506954
 2022-01-20 08:45:00,515 [INFO] {1881719} koji.TaskManager:938 pids: {81506954: 3348894}
 2022-01-20 08:45:00,946 [INFO] {1881719} koji.TaskManager:1136 Task 81506954 (pid 3348894) exited with status 0
 2022-01-20 08:45:00,956 [INFO] {1881719} koji.TaskManager:1284 Expiring subsession 156497585 (task 81506954)
 2022-01-20 08:45:04,827 [INFO] {1881719} koji.TaskManager:1374 Attempting to take task 77578916
 2022-01-20 08:45:05,190 [WARNING] {1881719} koji.TaskManager:1393 Error during host check
 2022-01-20 08:45:05,190 [WARNING] {1881719} koji.TaskManager:1394 Traceback (most recent call last):
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2783, in _callMethod
     return self._sendCall(handler, headers, request)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2698, in _sendCall
     return self._sendOneCall(handler, headers, request)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2747, in _sendOneCall
     ret = self._read_xmlrpc_response(r)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2759, in _read_xmlrpc_response
     result = u.close()
   File "/usr/lib64/python3.10/xmlrpc/client.py", line 662, in close
 xmlrpc.client.Fault: <Fault 1000: 'No such tagInfo: 47029'>
 During handling of the above exception, another exception occurred:
 Traceback (most recent call last):
   File "/usr/lib/python3.10/site-packages/koji/daemon.py", line 1388, in takeTask
     valid_host = handler.checkHost(self.hostdata)
   File "/usr/sbin/kojid", line 1376, in checkHost
     return self.checkHostArch(tag, hostdata)
   File "/usr/sbin/kojid", line 1328, in checkHostArch
     tag = self.session.getBuildConfig(tagref, **opts)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2348, in __call__
     return self.__func(self.__name, args, opts)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2802, in _callMethod
     raise err
 koji.GenericError: No such tagInfo: 47029
 2022-01-20 08:45:05,191 [INFO] {1881719} koji.TaskManager:1396 Skipping task 77578916 (buildArch) due to host check
 2022-01-20 08:45:05,191 [INFO] {1881719} koji.TaskManager:1374 Attempting to take task 77578917
 2022-01-20 08:45:05,553 [WARNING] {1881719} koji.TaskManager:1393 Error during host check
 2022-01-20 08:45:05,553 [WARNING] {1881719} koji.TaskManager:1394 Traceback (most recent call last):
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2783, in _callMethod
     return self._sendCall(handler, headers, request)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2698, in _sendCall
     return self._sendOneCall(handler, headers, request)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2747, in _sendOneCall
     ret = self._read_xmlrpc_response(r)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2759, in _read_xmlrpc_response
     result = u.close()
   File "/usr/lib64/python3.10/xmlrpc/client.py", line 662, in close
 xmlrpc.client.Fault: <Fault 1000: 'No such tagInfo: 47029'>
 During handling of the above exception, another exception occurred:
 Traceback (most recent call last):
   File "/usr/lib/python3.10/site-packages/koji/daemon.py", line 1388, in takeTask
     valid_host = handler.checkHost(self.hostdata)
   File "/usr/sbin/kojid", line 1376, in checkHost
     return self.checkHostArch(tag, hostdata)
   File "/usr/sbin/kojid", line 1328, in checkHostArch
     tag = self.session.getBuildConfig(tagref, **opts)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2348, in __call__
     return self.__func(self.__name, args, opts)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2802, in _callMethod
     raise err
 koji.GenericError: No such tagInfo: 47029
 2022-01-20 08:45:05,553 [INFO] {1881719} koji.TaskManager:1396 Skipping task 77578917 (buildArch) due to host check
 2022-01-20 08:45:05,553 [INFO] {1881719} koji.TaskManager:1374 Attempting to take task 81507055
 2022-01-20 08:45:07,260 [WARNING] {3349225} koji.TaskManager:1477 TRACEBACK: Traceback (most recent call last):
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2783, in _callMethod
     return self._sendCall(handler, headers, request)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2698, in _sendCall
     return self._sendOneCall(handler, headers, request)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2747, in _sendOneCall
     ret = self._read_xmlrpc_response(r)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2759, in _read_xmlrpc_response
     result = u.close()
   File "/usr/lib64/python3.10/xmlrpc/client.py", line 662, in close
 xmlrpc.client.Fault: <Fault 1003: 'build Fedora-KDE-Live-Rawhide-20220120.n.0 already tagged (f36-updates-candidate)'>
 During handling of the above exception, another exception occurred:
 Traceback (most recent call last):
   File "/usr/lib/python3.10/site-packages/koji/daemon.py", line 1458, in runTask
     response = (handler.run(),)
   File "/usr/lib/python3.10/site-packages/koji/tasks.py", line 335, in run
     return koji.util.call_with_argcheck(self.handler, self.params, self.opts)
   File "/usr/lib/python3.10/site-packages/koji/util.py", line 271, in call_with_argcheck
     return func(*args, **kwargs)
   File "/usr/sbin/kojid", line 2476, in handler
     raise e
   File "/usr/sbin/kojid", line 2468, in handler
     self.session.host.tagBuild(self.id, tag_id, build_id, force=force, fromtag=fromtag)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2348, in __call__
     return self.__func(self.__name, args, opts)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2802, in _callMethod
     raise err
 koji.TagError: build Fedora-KDE-Live-Rawhide-20220120.n.0 already tagged (f36-updates-candidate)
 2022-01-20 08:45:11,831 [INFO] {1881719} koji.TaskManager:768 Expiring buildroot: 32515089/f36-build/i386
 2022-01-20 08:45:13,951 [INFO] {1881719} koji.TaskManager:938 pids: {81507055: 3349225}
 2022-01-20 08:45:14,419 [INFO] {1881719} koji.TaskManager:1136 Task 81507055 (pid 3349225) exited with status 0
 2022-01-20 08:45:14,428 [INFO] {1881719} koji.TaskManager:1284 Expiring subsession 156497880 (task 81507055)
 2022-01-20 08:45:17,263 [INFO] {1881719} koji.TaskManager:1374 Attempting to take task 77578916
 2022-01-20 08:45:17,696 [WARNING] {1881719} koji.TaskManager:1393 Error during host check
 2022-01-20 08:45:17,696 [WARNING] {1881719} koji.TaskManager:1394 Traceback (most recent call last):
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2783, in _callMethod
     return self._sendCall(handler, headers, request)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2698, in _sendCall
     return self._sendOneCall(handler, headers, request)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2747, in _sendOneCall
     ret = self._read_xmlrpc_response(r)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2759, in _read_xmlrpc_response
     result = u.close()
   File "/usr/lib64/python3.10/xmlrpc/client.py", line 662, in close
 xmlrpc.client.Fault: <Fault 1000: 'No such tagInfo: 47029'>
 During handling of the above exception, another exception occurred:
 Traceback (most recent call last):
   File "/usr/lib/python3.10/site-packages/koji/daemon.py", line 1388, in takeTask
     valid_host = handler.checkHost(self.hostdata)
   File "/usr/sbin/kojid", line 1376, in checkHost
     return self.checkHostArch(tag, hostdata)
   File "/usr/sbin/kojid", line 1328, in checkHostArch
     tag = self.session.getBuildConfig(tagref, **opts)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2348, in __call__
     return self.__func(self.__name, args, opts)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2802, in _callMethod
     raise err
 koji.GenericError: No such tagInfo: 47029
 2022-01-20 08:45:17,696 [INFO] {1881719} koji.TaskManager:1396 Skipping task 77578916 (buildArch) due to host check
 2022-01-20 08:45:17,696 [INFO] {1881719} koji.TaskManager:1374 Attempting to take task 77578917
 2022-01-20 08:45:18,146 [WARNING] {1881719} koji.TaskManager:1393 Error during host check
 2022-01-20 08:45:18,147 [WARNING] {1881719} koji.TaskManager:1394 Traceback (most recent call last):
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2783, in _callMethod
     return self._sendCall(handler, headers, request)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2698, in _sendCall
     return self._sendOneCall(handler, headers, request)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2747, in _sendOneCall
     ret = self._read_xmlrpc_response(r)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2759, in _read_xmlrpc_response
     result = u.close()
   File "/usr/lib64/python3.10/xmlrpc/client.py", line 662, in close
 xmlrpc.client.Fault: <Fault 1000: 'No such tagInfo: 47029'>
 During handling of the above exception, another exception occurred:
 Traceback (most recent call last):
   File "/usr/lib/python3.10/site-packages/koji/daemon.py", line 1388, in takeTask
     valid_host = handler.checkHost(self.hostdata)
   File "/usr/sbin/kojid", line 1376, in checkHost
     return self.checkHostArch(tag, hostdata)
   File "/usr/sbin/kojid", line 1328, in checkHostArch
     tag = self.session.getBuildConfig(tagref, **opts)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2348, in __call__
     return self.__func(self.__name, args, opts)
   File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2802, in _callMethod
     raise err
 koji.GenericError: No such tagInfo: 47029
 2022-01-20 08:45:18,147 [INFO] {1881719} koji.TaskManager:1396 Skipping task 77578917 (buildArch) due to host check
 2022-01-20 08:45:18,147 [INFO] {1881719} koji.TaskManager:1374 Attempting to take task 81507042
 2022-01-20 08:45:20,284 [INFO] {3349226} koji.build.buildroot:439 /usr/bin/mock -r koji/f36-build-32515160-4400048 --old-chroot --init
 running '/usr/libexec/mock/mock -r koji/f36-build-32515160-4400048 --old-chroot --init' with root privileges on behalf of 'kojibuilder'
 2022-01-20 08:45:24,258 [WARNING] {1881719} koji.TaskManager:803 32515160/f36-build/i386: no retire timestamp
 2022-01-20 08:45:24,260 [INFO] {1881719} koji.TaskManager:938 pids: {81507042: 3349226}
 2022-01-20 08:45:24,674 [INFO] {1881719} koji.TaskManager:940 open task: {'id': 81507042, 'waiting': None, 'weight': 2.6528488775}
 2022-01-20 08:45:49,190 [INFO] {1881719} koji.TaskManager:938 pids: {81507042: 3349226}
 2022-01-20 08:45:49,650 [INFO] {1881719} koji.TaskManager:940 open task: {'id': 81507042, 'waiting': None, 'weight': 2.6528488775}

Clearly something's very wrong, but we're finding it tough sledding to figure out exactly what. We haven't changed anything about how Fedora's Koji is setup, AFAIK; we just updated the hub and builders to the latest version, and upgraded the hubs and builders to Fedora 35.

Some log extracts from the hub side:

 283 [WARNING] m=None u=None p=1041573 r=?:? koji.xmlrpc: Traceback (most recent call last):
   File "/usr/share/koji-hub/kojixmlrpc.py", line 253, in _wrap_handler
     response = handler(environ)
   File "/usr/share/koji-hub/kojixmlrpc.py", line 277, in handle_rpc
     return self._dispatch(method, params)
   File "/usr/share/koji-hub/kojixmlrpc.py", line 314, in _dispatch
     ret = koji.util.call_with_argcheck(func, params, opts)
   File "/usr/lib/python3.10/site-packages/koji/util.py", line 271, in call_with_argcheck
     return func(*args, **kwargs)
   File "/usr/share/koji-hub/kojihub.py", line 12552, in getBuildConfig
     taginfo = get_tag(tag, strict=True, event=event, blocked=True)
   File "/usr/share/koji-hub/kojihub.py", line 3505, in get_tag
     raise koji.GenericError("No such tagInfo: %r" % tagInfo)
 koji.GenericError: No such tagInfo: 46163
 2022-01-20 08:45:00,380 [WARNING] m=None u=buildvm-x86-24.iad2.fedoraproject.org p=1041470 r=10.3.163.74:51708 koji.xmlrpc: Traceback (most recent call last):
 File "/usr/share/koji-hub/kojixmlrpc.py", line 253, in _wrap_handler
   response = handler(environ)
 File "/usr/share/koji-hub/kojixmlrpc.py", line 273, in handle_upload
   return kojihub.handle_upload(environ)
 File "/usr/share/koji-hub/kojihub.py", line 15349, in handle_upload
   fn = get_upload_path(path, name, create=True, volume=volume)
 File "/usr/share/koji-hub/kojihub.py", line 15302, in get_upload_path
   Task(task_id).assertHost(host.id)
 File "/usr/share/koji-hub/kojihub.py", line 147, in assertHost
   raise koji.ActionNotAllowed("host %d does not own task %d" % (host_id, self.id))
 koji.ActionNotAllowed: host 395 does not own task 81506955
 380 [WARNING] m=None u=None p=1041470 r=?:? koji.xmlrpc: Traceback (most recent call last):
 File "/usr/share/koji-hub/kojixmlrpc.py", line 253, in _wrap_handler
   response = handler(environ)
 File "/usr/share/koji-hub/kojixmlrpc.py", line 273, in handle_upload
   return kojihub.handle_upload(environ)
 File "/usr/share/koji-hub/kojihub.py", line 15349, in handle_upload
   fn = get_upload_path(path, name, create=True, volume=volume)
 File "/usr/share/koji-hub/kojihub.py", line 15302, in get_upload_path
   Task(task_id).assertHost(host.id)
 File "/usr/share/koji-hub/kojihub.py", line 147, in assertHost
     raise koji.ActionNotAllowed("host %d does not own task %d" % (host_id, self.id))
 koji.ActionNotAllowed: host 395 does not own task 81506955

It seems to me that https://pagure.io/fork/mikem/koji/c/e50f3135c0c1ccd959a63ee052f6d2941574c38c changed the values dict passed to QueryProcessor() in get_tag from {'tagInfo': tagInfo} to {'tag_id': tagInfo} or {'tag_name': tagInfo} (depending on whether tagInfo is an int or a str). I'm not sure if that's the problem, but it's at least a relevant change in the code in question. That whole PR, in fact, seems like the most likely initial suspect as a whole...

@adamwill Was the image tagged during that task or was it manual tag after that to fix the issue?

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

Metadata Update from @tkopecek:
- Issue priority set to: High (was: Normal)
- Issue set to the milestone: 1.28
- Issue tagged with: bug

It was all koji, no manual intervention at all...

ie, the task just ran, (apparently tagged or thought it tagged at the end) and then tried to tag again and got the error.

Fedora 35 rings a bell a bit. Don't you see other strange errors like unreachable web in some points?

I've had to change WSGIProcessGroup and WSGIDaemonProcess in F34 for dev env I believe. To something like:

WSGIDaemonProcess koji lang=en_US.UTF-8
WSGIProcessGroup koji
Alias /kojihub /usr/share/koji-hub/kojixmlrpc.py
<Directory "/usr/share/koji-hub">
    Options ExecCGI
    SetHandler wsgi-script
    WSGIApplicationGroup %{GLOBAL}
    Require all granted
</Directory>

and

WSGIDaemonProcess koji-web lang=en_US.UTF-8
WSGIProcessGroup koji-web
Alias /koji "/usr/share/koji-web/scripts/wsgi_publisher.py"
<Directory "/usr/share/koji-web/scripts/">
    Options +ExecCGI
    SetHandler wsgi-script
    WSGIApplicationGroup %{GLOBAL}
    Require all granted
</Directory>

when these two were running on the same machine. Still confused - @mikem any idea?
Edited by tkopecek

So, the only thing different from our config in the above is setting WSGIDaemonProcess and WSGIProcessGroup. With WSGIDaemonProcess we should be setting processes and threads right? or it defaults to 1 and 0?

I went ahead and put this in effect in koji.fedoraproject.org... but I had to add 'processes=10 threads=5' or we started swamping the one wsgi process...

That didn't help. Here's logs over all builders for a double tagged build: 

Jan 27 22:31:02 buildvm-s390x-14.s390.fedoraproject.org kojid[3655486]: 2022-01-27 22:31:02,505 [INFO] {3655486} koji.TaskManager:1374 Attempting to take task 82036579
Jan 27 22:31:02 10.16.0.37 kojid[32083]: 2022-01-27 22:31:02,371 [INFO] {32083} koji.TaskManager:1374 Attempting to take task 82036579
Jan 27 22:31:03 buildvm-a64-33.iad2.fedoraproject.org kojid[26509]: 2022-01-27 22:31:02,636 [INFO] {26509} koji.TaskManager:1374 Attempting to take task 82036579
Jan 27 22:31:04 buildhw-x86-14.iad2.fedoraproject.org kojid[2159672]: 2022-01-27 22:31:04,476 [INFO] {2159672} koji.TaskManager:1374 Attempting to take task 82036579
Jan 27 22:31:06 buildvm-a64-33.iad2.fedoraproject.org kojid[26509]: 2022-01-27 22:31:06,282 [INFO] {26509} koji.TaskManager:938 pids: {82036579: 3929610}
Jan 27 22:31:06 buildvm-a64-33.iad2.fedoraproject.org kojid[26509]: 2022-01-27 22:31:06,311 [INFO] {26509} koji.TaskManager:1136 Task 82036579 (pid 3929610) exited with status 0
Jan 27 22:31:06 buildvm-a64-33.iad2.fedoraproject.org kojid[26509]: 2022-01-27 22:31:06,351 [INFO] {26509} koji.TaskManager:1284 Expiring subsession 157435129 (task 82036579)
Jan 27 22:31:07 buildhw-x86-14.iad2.fedoraproject.org kojid[2159672]: 2022-01-27 22:31:07,432 [INFO] {2159672} koji.TaskManager:938 pids: {82036579: 841914}
Jan 27 22:31:07 buildhw-x86-14.iad2.fedoraproject.org kojid[2159672]: 2022-01-27 22:31:07,453 [INFO] {2159672} koji.TaskManager:1136 Task 82036579 (pid 841914) exited with status 0
Jan 27 22:31:07 buildhw-x86-14.iad2.fedoraproject.org kojid[2159672]: 2022-01-27 22:31:07,506 [INFO] {2159672} koji.TaskManager:1284 Expiring subsession 157435139 (task 82036579)

So, it looks like 4 builders all tried to take the task.
One of them ( buildvm-a64-33.iad2.fedoraproject.org ) got it, and finished the task
Then, another one ( buildhw-x86-14.iad2.fedoraproject.org ) got it and tried to do it and got the failure.

So, could something be going on with locking ? or we have so many builders that it's swamping things somehow?

Candidate is here: #3007

PR #3235

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

Thanks. Trying that patch now.

Commit 78d7f3f3 fixes this issue

Commit edad8d44 fixes this issue

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

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

Please continue any further discussion there.
Metadata
None

bug testing-done testing-ready

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