fedora-infrastructure

#12496 koji build that is in a bad signing state
Closed: Fixed with Explanation by kevin. Opened by kevin.

Closed: Fixed with Explanation
Reopen Issue

https://koji.fedoraproject.org/koji/buildinfo?buildID=2699151 / qt-creator-16.0.1-1.fc43 was being signed this morning when koji hubs had a massive DOS and were taken offline for a bit.

After everything was back, sigul became stuck trying to sign this build.

The sgiul vault gets:

2025-04-15 17:54:20,638 INFO: Subrequest: 'id' = b'\x00\x00\x00\x00', 'rpm-arch''
 = b'ppc64le', 'rpm-epoch' = b'', 'rpm-name' = b'qt-creator-debugsource', 'rpm-rr
elease' = b'1.fc43', 'rpm-sigmd5' = b'M\xa5kU\xc6(\x0c\xcf\x056 m[t\xc0\x19', 'rr
pm-version' = b'16.0.1'
2025-04-15 17:54:20,870 DEBUG: sign-rpms:signing: Started handling ('qt-creator--
debugsource', None, '16.0.1', '1.fc43', 'ppc64le', b'54f74eb3b64995fe882b27188033
96cc39a446b57fe91838af8e0100ba9b7912588054213a954f6e19dfa24473378865046e7e044c4bb
3f51d99ccbdf9ebce4ad5')
2025-04-15 17:54:20,870 INFO: Starting signing operation
2025-04-15 17:54:20,870 DEBUG: sign-rpms:signing: Started handling ('qt-creator--
debugsource', None, '16.0.1', '1.fc43', 'ppc64le', b'54f74eb3b64995fe882b27188033
96cc39a446b57fe91838af8e0100ba9b7912588054213a954f6e19dfa24473378865046e7e044c4bb
3f51d99ccbdf9ebce4ad5')
2025-04-15 17:54:20,870 INFO: Starting signing operation
2025-04-15 17:54:20,872 DEBUG: sign-rpms:requests: Started handling 'id' = b'\x00
0\x00\x00\x01', 'rpm-arch' = b's390x', 'rpm-epoch' = b'', 'rpm-name' = b'qt-creaa
tor', 'rpm-release' = b'1.fc43', 'rpm-sigmd5' = b'\xe6$GW}vqbt9.\xe2\xff@uB', 'rr
pm-version' = b'16.0.1'
2025-04-15 17:54:20,872 INFO: Subrequest: 'id' = b'\x00\x00\x00\x01', 'rpm-arch''
 = b's390x', 'rpm-epoch' = b'', 'rpm-name' = b'qt-creator', 'rpm-release' = b'1..
fc43', 'rpm-sigmd5' = b'\xe6$GW}vqbt9.\xe2\xff@uB', 'rpm-version' = b'16.0.1'
2025-04-15 17:54:20,950 INFO: Request error: The RPM file is corrupt
2025-04-15 17:54:20,950 ERROR: Worker sign-rpms:requests (request thread) encounn
tered an error processing
Traceback (most recent call last):
  File "/usr/share/sigul/server.py", line 2471, in __read_one_request
    rpm.verify()
  File "/usr/share/sigul/server.py", line 813, in verify
    raise RPMFileError('Corrupt RPM')
RPMFileError: Corrupt RPM

All the rpms in the build seem fine however. I think this may just be sigul hitting a thing with import signature and erroring in a odd way?

https://kojipkgs.fedoraproject.org//packages/qt-creator/16.0.1/1.fc43/data/sigcache/ppc64le/
shows a sig.HASH.save file, perhaps thats from when it was in the middle of importing it?

I did try and do a 'koji remove-sig qt-creator-16.0.1-1.fc43.ppc64le --all' but it didn't seem to help any.
I started to look at tweaking the db manually, but decided that was a bad idea, and instead just dropped the message bus message for this package so signing would continue on the rest.

We can try again to resign this by just re-tagging into the signing-pending tag.

CC: @mikem

Well this is weird.

The qt-creator-16.0.1-1.fc43.s390x.rpm is definitely corrupted. It's truncated. The file is 5M (exactly), but the header says it should be about 33. Koji's default upload blocksize is 1M, so this looks like it could be a truncated upload. That's the weird part, because Koji has some fairly paranoid upload code that should fail if the uploaded file does not match.

I suppose some other factor could have truncated it, but the timestamp on the file seems to line up with the buildArch task.

At any rate, sigul is not wrong, this build definitely corrupt, and it has nothing to do with any signature headers.

You can't fix this build. I would untag this one and have it rebuilt.

On that s390x builder:

FO] {1104} koji.TaskManager:974 open task: {'id': 131561010, 'waiting': None, 'weight': 3.577866
4264583333}
Apr 15 13:38:15 buildvm-s390x-19.s390.fedoraproject.org kojid[1104]: 2025-04-15 13:38:15,386 [IN
FO] {1104} koji.TaskManager:1304 Task load (3.58) exceeds capacity (3.00)
Apr 15 13:38:15 buildvm-s390x-19.s390.fedoraproject.org kojid[1104]: 2025-04-15 13:38:15,400 [IN
FO] {1104} koji.TaskManager:1047 Not ready for task
Apr 15 13:38:37 buildvm-s390x-19.s390.fedoraproject.org kojid[3003557]: 2025-04-15 13:38:37,497 
[INFO] {3003557} koji:3200 Try #1 for call 3396 (rawUpload) failed: 408 Client Error: Request Ti
meout for url: https://koji.fedoraproject.org/kojihub?filename=qt-creator-debuginfo-16.0.1-1.fc4
3.s390x.rpm&filepath=tasks%2F1010%2F131561010&fileverify=adler32&offset=493879296&overwrite=1
Apr 15 13:38:38 buildvm-s390x-19.s390.fedoraproject.org kojid[1104]: 2025-04-15 13:38:38,719 [IN
FO] {1104} koji.TaskManager:972 pids: {131561010: 3003557}
Apr 15 13:38:58 buildvm-s390x-19.s390.fedoraproject.org kojid[3003557]: 2025-04-15 13:38:58,164 
[INFO] {3003557} koji.TaskManager:1424 RESPONSE: "<?xml version='1.0'?>\n<methodResponse>\n<para
ms>\n<param>\n<value><struct>\n<member>\n<name>rpms</name>\n<value><array><data>\n<value><string
>tasks/1010/131561010/qt-creator-16.0.1-1.fc43.s390x.rpm</string></value>\n<value><string>tasks/
1010/131561010/qt-creator-debuginfo-16.0.1-1.fc43.s390x.rpm</string></value>\n<value><string>tas
ks/1010/131561010/qt-creator-debugsource-16.0.1-1.fc43.s390x.rpm</string></value>\n<value><strin
g>tasks/1010/131561010/qt-creator-translations-16.0.1-1.fc43.noarch.rpm</string></value>\n<value
><string>tasks/1010/131561010/qt-creator-doc-16.0.1-1.fc43.noarch.rpm</string></value>\n<value><
string>tasks/1010/131561010/qt-creator-data-16.0.1-1.fc43.noarch.rpm</string></value>\n</data></
array></value>\n</member>\n<member>\n<name>srpms</name>\n<value><array><data>\n</data></array></
value>\n</member>\n<member>\n<name>logs</name>\n<value><array><data>\n<value><string>tasks/1010/
131561010/mock_output.log</string></value>\n<value><string>tasks/1010/131561010/hw_info.log</str
ing></value>\n<value><string>tasks/1010/131561010/root.log</string></value>\n<value><string>task
s/1010/131561010/build.log</string></value>\n<value><string>tasks/1010/131561010/mock_config.log
</string></value>\n<value><string>tasks/1010/131561010/dnf5.log</string></value>\n<value><string
>tasks/1010/131561010/state.log</string></value>\n<value><string>tasks/1010/131561010/noarch_rpm
diff.json</string></value>\n</data></array></value>\n</member>\n<member>\n<name>brootid</name>\n
<value><int>58825345</int></value>\n</member>\n</struct></value>\n</param>\n</params>\n</methodR
esponse>\n"
Apr 15 13:43:10 buildvm-s390x-19.s390.fedoraproject.org kojid[1104]: 2025-04-15 13:43:10,359 [IN
FO] {1104} koji:3200 Try #1 for call 24624 (host.getHostTasks) failed: 503 Server Error: Service
 Unavailable for url: https://koji.fedoraproject.org/kojihub
Apr 15 13:43:10 buildvm-s390x-19.s390.fedoraproject.org kojid[1104]: 2025-04-15 13:43:10,422 [INFO] {1104} koji.TaskManager:1093 Task 131561010 (pid 3003557) exited with status 0
Apr 15 13:43:10 buildvm-s390x-19.s390.fedoraproject.org kojid[1104]: 2025-04-15 13:43:10,430 [INFO] {1104} koji.TaskManager:1241 Expiring subsession 247085094 (task 131561010)

That's a little later than I need. We see the upload retry notice for qt-creator-debuginfo-16.0.1-1.fc4
3.s390x.rpm (which got through intact).

Could you check around 13:36:36?

ah, this perhaps:

[INFO] {3003557} koji:3200 Try #1 for call 2895 (rawUpload) failed: 408 Client Error: Request Ti
meout for url: https://koji.fedoraproject.org/kojihub?filename=qt-creator-16.0.1-1.fc43.s390x.rp
m&filepath=tasks%2F1010%2F131561010&fileverify=adler32&offset=5242880&overwrite=1
Apr 15 13:36:57 buildvm-s390x-19.s390.fedoraproject.org kojid[1104]: 2025-04-15 13:36:57,625 [IN
FO] {1104} koji:3200 Try #1 for call 24588 (host.getHostTasks) failed: 503 Server Error: Service
 Unavailable for url: https://koji.fedoraproject.org/kojihub

That's the call. Note that offset=5242880 matches the the erroneous length. Are there any further errors after that?

Nope, not until the first part of that first log snippet. ;(

The hub side of this error looks like this:

[Tue Apr 15 13:36:36.168316 2025] [wsgi:error] [pid 1262693:tid 1262693] [client 10.3.163.76:47964] 2025-04-15 13:36:36,168 [ERROR] m=None u=buildvm-s390x-19.s390.fedoraproject.org p=1262693 r=10.3.163.76:47964 koji.upload: Error reading upload. Offset 5242880+0, path /mnt/koji/work/tasks/1010/131561010/qt-creator-16.0.1-1.fc43.s390x.rpm
[Tue Apr 15 13:36:36.171500 2025] [wsgi:error] [pid 1262693:tid 1262693] [client 10.3.163.76:47964] 2025-04-15 13:36:36,168 [ERROR] m=None u=buildvm-s390x-19.s390.fedoraproject.org p=1262693 r=10.3.163.76:47964 koji.upload: Error reading input stream. Content-Length: 1048576
[Tue Apr 15 13:36:36.171517 2025] [wsgi:error] [pid 1262693:tid 1262693] [client 10.3.163.76:47964] Traceback (most recent call last):
[Tue Apr 15 13:36:36.171522 2025] [wsgi:error] [pid 1262693:tid 1262693] [client 10.3.163.76:47964]   File "/usr/lib/python3.13/site-packages/kojihub/kojihub.py", line 16286, in handle_upload
[Tue Apr 15 13:36:36.171526 2025] [wsgi:error] [pid 1262693:tid 1262693] [client 10.3.163.76:47964]     chunk = inf.read(65536)
[Tue Apr 15 13:36:36.171530 2025] [wsgi:error] [pid 1262693:tid 1262693] [client 10.3.163.76:47964] OSError: Apache/mod_wsgi request data read error: Partial results are valid but processing is incomplete.

The bad news is that I see quite a few "Error reading upload" messages between koji01 and koji02

(that doesn't mean all such errors result in corruption, but worth checking)

Yeah, if those were between about 13:30 and 15:00 utc it would have been when things were getting DDoSed... both koji hubs were pegged, stopped responding and I had to reboot one entirely to bring it back up. ;(

From checking the logs, I found one more instance -- qt6-doc-html-6.9.0-1.eln147.noarch.rpm

https://koji.fedoraproject.org/koji/rpminfo?rpmID=42529930

There are 148 such errors in the logs, but most of them are log files. 27 were rpms, 10 of which were actually imported. 2 of those were corrupted.

Metadata Update from @phsmoura:
- Issue priority set to: Waiting on Assignee (was: Needs Review)
- Issue tagged with: medium-gain, medium-trouble, ops

Odd. That one says it finished and was signed ok?
https://koji.fedoraproject.org/koji/buildinfo?buildID=2699213

Will add more logs here when I get a chance.

 
$ koji download-build --rpm qt6-doc-html-6.9.0-1.eln147.noarch.rpm
Downloading [1/1]: qt6-doc-html-6.9.0-1.eln147.noarch.rpm
[====================================] 100% 73.00 MiB / 73.00 MiB
$ rpm -Kv qt6-doc-html-6.9.0-1.eln147.noarch.rpm 
qt6-doc-html-6.9.0-1.eln147.noarch.rpm:
    Header SHA256 digest: OK
    Header SHA1 digest: OK
    Payload SHA256 ALT digest: BAD (Expected ac284ee8436416b2ba7825152a6e5c45c568b4ba9f31d239d0db025ae9957f94 != 7eeef7d1e5cec1de2a1269fff1519da66b078a0945ed586c9ecf66f580d76c2e)
    Payload SHA256 digest: BAD (Expected 94624dcbb6e363f390b20f22acbf220c629e2ead9b4b245a691df93612905656 != 7eeef7d1e5cec1de2a1269fff1519da66b078a0945ed586c9ecf66f580d76c2e)
    MD5 digest: BAD (Expected 4ec17bd703a7d05d2f37656439aab1e6 != 5c7da9951e9e4262111236ff6dfb5790)

CC: @yselkowitz can you rebuild that ^

Odd. That one says it finished and was signed ok?

The only cached signatures in koji are the unsigned ones from the looks of it?
https://kojipkgs.fedoraproject.org//packages/qt6-doc/6.9.0/1.eln147/data/sigcache/

$ koji call queryRPMSigs rpm_id=42529930
[{'rpm_id': 42529930,
  'sighash': 'aaafca5913199891e5f258a7cfdf5cc6',
  'sigkey': ''}]

CC: @yselkowitz can you rebuild that ^

Revbumped and rebuilding for rawhide, ELN build will follow.

I am very puzzled as to how these uploads managed to get truncated without the buildArch task failing. I just don't see a code path where the upload is not verified by the client.

Best guess is that the netapp write cache was lost after the initial 5M of chunks were written. I.e. something like --

  1. client gets the 408 error shown in the logs at the 5M mark
  2. client retries uploading the chunk, possibly getting the other hub instance for the new connection (errors force a new connection, regardless of keepalive)
  3. the client upload continues and succeeds. final checkUpload call returns the correct size and hash
  4. overall network load on the hub breaks nfs and the writes from the remainder of the upload are lost

If I'm right, I'm not sure what Koji could do to prevent the corruption, though perhaps some additional logging could at least help confirm this hypothesis.

Oh wait. I think I see another possibility.

The 408 did not come from koji code. The "Error reading input stream" message indicates a 400 error. It it were 408, the message would have been "Timed out reading input stream". So that means the 408 is coming from the proxy

So here's a theoretical timeline:

  1. client makes the doomed rawUpload call (6th 1M chunk at offset 5242880)
  2. proxy forwards request to koji01
  3. koji01 and/or network is completely bogged down and does not immediately handle the call
  4. proxy times out and returns the 408
  5. client retries call, succeeds, and continues on to complete the upload, including the verify
  6. meanwhile, the original call finally starts executing. Because there is an offset arg, it calls os.ftruncate(fd, offset) before it starts writing. It times out reading the input, because the client and the proxy have moved on, and errors out, but no client ever receives the error.

This is probably more likely, and there's at least an improvement to made here.

Sorry for the delay on logs...

buildvm-s390x-06-logs.txt
buildvm-s390x-19-log.txt

[root@buildvm-s390x-19 ~][PROD-IAD2]# rpm -q koji
koji-1.35.2-1.fc41.1.noarch
[root@buildvm-s390x-19 ~][PROD-IAD2]# rpm -V koji
S.5....T. c /etc/koji.conf

If there's anything further to do here, please feel free to re-open.

Metadata Update from @kevin:
- Issue close_status updated to: Fixed with Explanation
- Issue status updated to: Closed (was: Open)

filed https://pagure.io/koji/pull-request/4370 for koji
Metadata
None

medium-gain medium-trouble ops

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