#8611 bodhi mis-behaving in staging
Closed: Fixed 4 years ago by cverna. Opened 4 years ago by pingou.

So:

But the update is still in "pending" state, no message to trigger CI were sent (for 18 days): https://apps.stg.fedoraproject.org/datagrepper/raw?topic=org.fedoraproject.stg.bodhi.update.status.testing.koji-build-group.build.complete

Is something mis-configured in staging?

In the logs of the consumer, I'm seeing:

2020-02-04 11:47:57,324 INFO  [fedora_messaging.twisted.protocol][MainThread] Consuming message from topic org.fedoraproject.stg.buildsys.tag (message id 41fa4137-d700-4d20-be5a-2d24dabccab6)
2020-02-04 11:47:57,325 INFO  [bodhi][PoolThread-twisted.internet.reactor-0] Received message from fedora-messaging with topic: org.fedoraproject.stg.buildsys.tag
2020-02-04 11:47:57,328 INFO  [bodhi][PoolThread-twisted.internet.reactor-0] fedora-gather-easyfix-0.2.1-96.fc32 tagged into f32-updates-candidate
2020-02-04 11:47:57,350 INFO  [bodhi][PoolThread-twisted.internet.reactor-0] Build was not submitted, skipping
2020-02-04 11:47:57,760 INFO  [bodhi.server][PoolThread-twisted.internet.reactor-0] Sending mail to pingou@...: [Fedora Update] [comment] fedora-gather-easyfix-0.2.1-96.fc32
2020-02-04 11:47:57,760 INFO  [bodhi.server][PoolThread-twisted.internet.reactor-0] Not sending email: No smtp_server defined
2020-02-04 11:47:57,958 INFO  [fedora_messaging.twisted.protocol][MainThread] Successfully consumed message from topic org.fedoraproject.stg.buildsys.tag (message id 41fa4137-d700-4d20-be5a-2d24dabccab6)

2020-02-04 11:47:58,600 INFO  [fedora_messaging.twisted.protocol][MainThread] Consuming message from topic org.fedoraproject.stg.buildsys.tag (message id afda1a71-b90e-4356-ac6a-201b47a2fc76)
2020-02-04 11:47:58,601 INFO  [bodhi][PoolThread-twisted.internet.reactor-0] Received message from fedora-messaging with topic: org.fedoraproject.stg.buildsys.tag
2020-02-04 11:47:58,603 INFO  [bodhi][PoolThread-twisted.internet.reactor-0] fedora-gather-easyfix-0.2.1-96.fc32 tagged into f32-signing-pending
2020-02-04 11:47:58,622 INFO  [bodhi][PoolThread-twisted.internet.reactor-0] Tag is not pending_testing tag, skipping
2020-02-04 11:47:58,725 INFO  [fedora_messaging.twisted.protocol][MainThread] Successfully consumed message from topic org.fedoraproject.stg.buildsys.tag (message id afda1a71-b90e-4356-ac6a-201b47a2fc76)

Hm, so this may be related to robosignatory in fact:

$ koji -p stg buildinfo fedora-gather-easyfix-0.2.1-96.fc32
BUILD: fedora-gather-easyfix-0.2.1-96.fc32 [1431786]
State: COMPLETE
Built by: pingou
Source: git+https://src.stg.fedoraproject.org/rpms/fedora-gather-easyfix.git#99b24150c9c939e3b52d390d0cfd7797137a9d58
Volume: DEFAULT
Task: 90003531 build (rawhide, /rpms/fedora-gather-easyfix.git:99b24150c9c939e3b52d390d0cfd7797137a9d58)
Finished: Tue, 04 Feb 2020 11:47:56 CET
Tags: f32-updates-candidate f32-signing-pending

But according to https://infrastructure.fedoraproject.org/cgit/ansible.git/tree/roles/robosignatory/templates/robosignatory.toml.j2#n221

[[consumer_config.koji_instances.primary.tags]]
from = "f32-signing-pending"
to = "f32-updates-testing-pending"
key = "{{ (env == 'production')|ternary('fedora-32', 'testkey') }}"
keyid = "{{ (env == 'production')|ternary('12c944d0', 'd300e724') }}"

robotsignatory should move the signed builds from f32-signing-pending to f32-updates-testing-pending.

Alright, so robosignatory is failing, I've restarted it but it still fails with:

Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: [robosignatory INFO] Received message from fedora-messaging with topic: org.fedoraproject.stg.buildsys.tag
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: [robosignatory.tagconsumer INFO] Build dummy-test-package-gloster-0-13.fc32 (1431755) tagged into f32-signing-pending on primary
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: [robosignatory.tagconsumer INFO] Going to sign dummy-test-package-gloster-0-13.fc32 with testkey (d300e724) and move to f32-updates-testing-pending
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: [robosignatory.tagconsumer INFO] Signing and writing build dummy-test-package-gloster-0-13.fc32
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: [robosignatory.tagconsumer INFO] RPMs to sign and move: [u'dummy-test-package-gloster-0-13.fc32.src (20120657, signed: True)', u'dummy-test-package-gloster-0-13.fc32.noarch (20120658, signed: True)']
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: [robosignatory.tagconsumer INFO] Build was successfully signed, telling koji to write with key d300e724
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: [robosignatory ERROR] sign permission required: Unable to handle message: Id: 8d95991e-d2e1-496f-8cb3-3ac472ebeeb8
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: Topic: org.fedoraproject.stg.buildsys.tag
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: Headers: {
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: "fedora_messaging_schema": "base.message",
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: "fedora_messaging_severity": 20,
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: "sent-at": "2020-01-24T21:11:08+00:00"
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: }
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: Body: {
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: "build_id": 1431755,
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: "instance": "primary",
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: "name": "dummy-test-package-gloster",
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: "owner": "pingou",
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: "release": "13.fc32",
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: "tag": "f32-signing-pending",
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: "tag_id": 11523,
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: "user": "bodhi",
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: "version": "0"
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: }
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: Traceback (most recent call last):
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: File "/usr/lib/python2.7/site-packages/robosignatory/consumer.py", line 44, in __call__
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: self.tag_handler.consume(msg)
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: File "/usr/lib/python2.7/site-packages/robosignatory/tag.py", line 142, in consume
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: skip_tagging=False)
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: File "/usr/lib/python2.7/site-packages/robosignatory/tag.py", line 217, in dowork
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: self.signwrite_single_build(build_nvr, build_id, tag_info, instance, koji_instance)
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: File "/usr/lib/python2.7/site-packages/robosignatory/tag.py", line 281, in signwrite_single_build
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: instance['client'].writeSignedRPM(rpm['id'], tag_info['keyid'])
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: File "/usr/lib/python2.7/site-packages/koji/__init__.py", line 2135, in __call__
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: return self.__func(self.__name, args, opts)
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: File "/usr/lib/python2.7/site-packages/koji/__init__.py", line 2650, in _callMethod
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: raise err
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: ActionNotAllowed: sign permission required
Feb 04 12:39:40 autosign01.stg.phx2.fedoraproject.org fedora-messaging[9517]: [fedora_messaging.twisted.protocol WARNING] Returning message id 8d95991e-d2e1-496f-8cb3-3ac472ebeeb8 to the queue

So the problem was indeed the prod->stg sync.

It fixed the krb principal, but incomplete:

3638 | autosign/autosign01.phx2.fedoraproject.org@STG.FEDORAPROJECT.ORG

but in the config it's 'stg.phx2' so it doesn't match that and koji just makes a new user. That new user has no perms.

So, for now, I just deleted the other principal and fixed the user_id 3638 one to be correct.

We will need to fix our prod->stg sync to handle this.

So, I think it should be working now.

Metadata Update from @bowlofeggs:
- Issue priority set to: Waiting on Assignee (was: Needs Review)

4 years ago

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

4 years ago

Login to comment on this ticket.

Metadata