koji

#3236 GenericError: cannot update build , state: COMPLETE
Closed: Dropped by tkopecek. Opened by kevin.

Closed: Dropped
Reopen Issue

We are seeing these in the fedora koji from time to time:

https://koji.fedoraproject.org/koji/taskinfo?taskID=82254466 <- glibc
https://koji.fedoraproject.org/koji/taskinfo?taskID=82243337 <- texlive
https://koji.fedoraproject.org/koji/taskinfo?taskID=82212306 <- workstation live rawhide image

I thought it might be due to the mismatch of builder and hub versions, but the hubs are now also on 1.27.1 (with the patch for the tag issue).

Happy to gather more info. ;(

Metadata Update from @tkopecek:
- Custom field Size adjusted to None
- Issue set to the milestone: 1.29

Just FYI, this is causing rawhide compose failures

Metadata Update from @tkopecek:
- Issue set to the milestone: 1.28 (was: 1.29)

I think that #3220 could be the same issue. Is it happening still after fix @kevin applied?

Yes, it is happening after https://pagure.io/koji/pull-request/3235

Metadata Update from @tkopecek:
- Issue tagged with: bug

I don't believe that this is caused by the same issue as #3220.

The error message here is coming from the failBuild call for a task that looks like it should have completed normally (all subtasks ok). The failBuild call is in an exception handler, and I'd bet that:

  • the completeBuild (or completeImageBuild) call failed
  • said call failed because a network error forced a retry and the call is not reentrant

Can someone look at the kojid logs on the relevant builds and fetch those tracebacks to confirm?

Metadata Update from @mikem:
- Issue untagged with: bug

If I'm right, this is not a new problem. The complete*Build calls have never been reentrant. I'm not sure how feasible it would be to make them so, but it would definitely be at least a bit tricky.

alternately, instead of network retry, a build task being reassigned to another host at just the right (well, wrong) time could also result in the same outcome.

Here's the glibc one: 

Feb  1 21:40:00 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:  File "/usr/sbin/kojid", line 1088, in handler
Feb  1 21:40:00 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:    self.session.host.failBuild(self.id, build_id)
Feb  1 21:40:00 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:  File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2348, in __call__
Feb  1 21:40:00 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:    return self.__func(self.__name, args, opts)
Feb  1 21:40:00 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:  File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2802, in _callMethod
Feb  1 21:40:00 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:    raise err
Feb  1 21:40:00 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]: koji.GenericError: cannot update build 1911186, state: COMPLETE

Feb  1 21:39:35 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]: 2022-02-01 21:39:33,687 [INFO] {15269} koji:2830 Try #1 for call 29 (host.completeBuild) failed: 504 Server Error: Gateway Timeout for
url: https://koji.fedoraproject.org/kojihub?session-id=157784369&session-key=redacted&callnum=28
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]: 2022-02-01 21:39:56,980 [WARNING]
 {15269} koji.TaskManager:1477 TRACEBACK: Traceback (most recent call last):
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:  File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2783, in _callMethod
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:    return self._sendCall(handler, headers, request)
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:  File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2698, in _sendCall
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:    return self._sendOneCall(handler, headers, request)
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:  File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2747, in _sendOneCall
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:    ret = self._read_xmlrpc_response(r)
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:  File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2759, in _read_xmlrpc_response
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:    result = u.close()
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:  File "/usr/lib/python3.10/xmlrpc/client.py", line 668, in close
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:    raise Fault(**self._stack[0])
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]: xmlrpc.client.Fault: <Fault 1009:
 'unable to retry call 28 (method host.completeBuild) for session 157784369'>
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]: During handling of the above exception, another exception occurred:
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]: Traceback (most recent call last):
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:  File "/usr/sbin/kojid", line 1081, in handler
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:    self.session.host.completeBuild(self.id, build_id, srpm, rpms, brmap, logs=logs)
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:  File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2348, in __call__
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:    return self.__func(self.__name, args, opts)
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:  File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2802, in _callMethod
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:    raise err
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]: koji.RetryError: unable to retry call 28 (method host.completeBuild) for session 157784369
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]: During handling of the above exception, another exception occurred:
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]: Traceback (most recent call last):
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:  File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2783, in _callMethod
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:    return self._sendCall(handler, headers, request)
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:  File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2698, in _sendCall
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:    return self._sendOneCall(handler, headers, request)
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:  File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2747, in _sendOneCall
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:    ret = self._read_xmlrpc_response(r)
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:  File "/usr/lib/python3.10/site-packages/koji/__init__.py", line 2759, in _read_xmlrpc_response
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:    result = u.close()
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:  File "/usr/lib/python3.10/xmlrpc/client.py", line 668, in close
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:    raise Fault(**self._stack[0])
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]: xmlrpc.client.Fault: <Fault 1000: 'cannot update build 1911186, state: COMPLETE'>
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]: During handling of the above exception, another exception occurred:
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]: Traceback (most recent call last):
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:  File "/usr/lib/python3.10/site-packages/koji/daemon.py", line 1458, in runTask
Feb  1 21:39:57 buildvm-a32-33.iad2.fedoraproject.org kojid[15269]:    response = (handler.run(),)

So, indeed it looks like a timeout?
But why was it not happening until now? perhaps the wsgi changes I made to try and work around the other issue?

"Gateway timeout". So is there a proxy inbetween your builders and the actual hub?

yep.

I wonder if the proxy logs would show anything more about the 504

I'm not really finding anything. ;(

FWIW "me too" with libreoffice. I've seen this twice now, e.g. https://koji.fedoraproject.org/koji/taskinfo?taskID=82291369 was the latest

I've reverted our wsgi changes back to the way they were before now. Hopefully that gets things stable again...

A successful build for me now: https://koji.fedoraproject.org/koji/taskinfo?taskID=82348440 thanks for that.

Metadata Update from @tkopecek:
- Issue set to the milestone: None (was: 1.28)

Metadata Update from @tkopecek:
- Issue close_status updated to: Dropped
- Issue status updated to: Closed (was: Open)

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

Please continue any further discussion there.
Metadata
None
None
None
None
Low
None
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.