#6996 Get backtrace for staging MBS failure
Closed 5 years ago Opened 5 years ago by otaylor.

My build on mbs.stg.fedoraproject.org is mysteriously failing:

https://mbs.stg.fedoraproject.org/module-build-service/1/module-builds/233

(Reproduce by running fedpkg-stage module-build in fedpkg-stage clone modules/minimal-runtime)

The details of the exception are in the log, which to my knowledge is not publicly accessible. I believe they are left in /var/tmp on mbs-backend-stg until /var/tmp is cleaned up.

Being able to build this successfully is necessary to continue the testing process for OSBS builds of Flatpak - this is a blocker for further progress there.


There's nothing in /var/tmp, but there is stuff in logs.

May 29 17:01:30 mbs-backend01 fedmsg-hub: [2018-05-29 17:01:30][module_build_service    INFO] Calling init: MBSModule, 
2018-c556e708-f399-41e4-8e59-acb33ae8d1dd
May 29 17:01:30 mbs-backend01 fedmsg-hub: [2018-05-29 17:01:30][module_build_service WARNING] fatal: remote error: access denied or repository not exported: /rpms/flatpak-runtime-config
May 29 17:01:30 mbs-backend01 fedmsg-hub: [2018-05-29 17:01:30][module_build_service WARNING] Exception UnprocessableEn
tity("Failed on ['git', 'ls-remote', '--exit-code', 'git://pkgs.fedoraproject.org/rpms/flatpak-runtime-config'], retcode 128, out '', err 'fatal: remote error: access denied or repository not exported: /rpms/flatpak-runtime-config\\n'",) 
raised from <function _run at 0x7fea7845e848>.  Retry in 15s
May 29 17:01:30 mbs-backend01 fedmsg-hub: [2018-05-29 17:01:30][module_build_service WARNING] fatal: remote error: access denied or repository not exported: /rpms/flatpak-rpm-macros
May 29 17:01:30 mbs-backend01 fedmsg-hub: [2018-05-29 17:01:30][module_build_service WARNING] Exception UnprocessableEntity("Failed on ['git', 'ls-remote', '--exit-code', 'git://pkgs.fedoraproject.org/rpms/flatpak-rpm-macros'], retcode 128, out '', err 'fatal: remote error: access denied or repository not exported: /rpms/flatpak-rpm-macros\\n'",) raised f
rom <function _run at 0x7fea7845e848>.  Retry in 15s
May 29 17:01:45 mbs-backend01 fedmsg-hub: [2018-05-29 17:01:45][module_build_service WARNING] fatal: remote error: acce
ss denied or repository not exported: /rpms/flatpak-runtime-config
May 29 17:01:45 mbs-backend01 fedmsg-hub: [2018-05-29 17:01:45][module_build_service WARNING] Exception UnprocessableEntity("Failed on ['git', 'ls-remote', '--exit-code', 'git://pkgs.fedoraproject.org/rpms/flatpak-runtime-config'], retcode 128, out '', err 'fatal: remote error: access denied or repository not exported: /rpms/flatpak-runtime-config\\n'",) raised from <function _run at 0x7fea7845e848>.  Retry in 15s
May 29 17:01:45 mbs-backend01 fedmsg-hub: [2018-05-29 17:01:45][module_build_service WARNING] fatal: remote error: access denied or repository not exported: /rpms/flatpak-rpm-macros
May 29 17:01:45 mbs-backend01 fedmsg-hub: [2018-05-29 17:01:45][module_build_service WARNING] Exception UnprocessableEntity("Failed on ['git', 'ls-remote', '--exit-code', 'git://pkgs.fedoraproject.org/rpms/flatpak-rpm-macros'], retcode 128, out '', err 'fatal: remote error: access denied or repository not exported: /rpms/flatpak-rpm-macros\\n'",) raised from <function _run at 0x7fea7845e848>.  Retry in 15s
May 29 17:02:00 mbs-backend01 fedmsg-hub: [2018-05-29 17:02:00][module_build_service WARNING] fatal: remote error: access denied or repository not exported: /rpms/flatpak-runtime-config
May 29 17:02:00 mbs-backend01 fedmsg-hub: [2018-05-29 17:02:00][module_build_service WARNING] Exception UnprocessableEntity("Failed on ['git', 'ls-remote', '--exit-code', 'git://pkgs.fedoraproject.org/rpms/flatpak-runtime-config'], retcode 128, out '', err 'fatal: remote error: access denied or repository not exported: /rpms/flatpak-runtime-config\\n'",) raised from <function _run at 0x7fea7845e848>.  Retry in 15s
May 29 17:02:00 mbs-backend01 fedmsg-hub: [2018-05-29 17:02:00][module_build_service WARNING] fatal: remote error: access denied or repository not exported: /rpms/flatpak-rpm-macros
May 29 17:02:00 mbs-backend01 fedmsg-hub: [2018-05-29 17:02:00][module_build_service WARNING] Exception UnprocessableEntity("Failed on ['git', 'ls-remote', '--exit-code', 'git://pkgs.fedoraproject.org/rpms/flatpak-rpm-macros'], retcode 128, out '', err 'fatal: remote error: access denied or repository not exported: /rpms/flatpak-rpm-macros\\n'",) raised from <function _run at 0x7fea7845e848>.  Retry in 15s
May 29 17:02:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:02:15][module_build_service WARNING] fatal: remote error: access denied or repository not exported: /rpms/flatpak-runtime-config
May 29 17:02:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:02:15][module_build_service WARNING] Exception UnprocessableEntity("Failed on ['git', 'ls-remote', '--exit-code', 'git://pkgs.fedoraproject.org/rpms/flatpak-runtime-config'], retcode 128, out '', err 'fatal: remote error: access denied or repository not exported: /rpms/flatpak-runtime-config\\n'",) raised from <function _run at 0x7fea7845e848>.  Retry in 15s
May 29 17:02:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:02:15][module_build_service WARNING] fatal: remote error: access denied or repository not exported: /rpms/flatpak-rpm-macros
May 29 17:02:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:02:15][module_build_service WARNING] Exception UnprocessableEntity("Failed on ['git', 'ls-remote', '--exit-code', 'git://pkgs.fedoraproject.org/rpms/flatpak-rpm-macros'], retcode 128, out '', err 'fatal: remote error: access denied or repository not exported: /rpms/flatpak-rpm-macros\\n'",) raised from <function _run at 0x7fea7845e848>.  Retry in 15s
May 29 17:02:30 mbs-backend01 fedmsg-hub: [2018-05-29 17:02:30][module_build_service   ERROR] Failed on ['git', 'ls-remote', '--exit-code', 'git://pkgs.fedoraproject.org/rpms/flatpak-runtime-config'], retcode 128, out '', err 'fatal: remote error: access denied or repository not exported: /rpms/flatpak-runtime-config\n'
May 29 17:02:30 mbs-backend01 fedmsg-hub: Traceback (most recent call last):
May 29 17:02:30 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/module_build_service/utils/submit.py", line 48, in _scm_get_latest
May 29 17:02:30 mbs-backend01 fedmsg-hub: pkg.get_repository()).get_latest(pkg.get_ref())
May 29 17:02:30 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/module_build_service/scm.py", line 94, in __init__
May 29 17:02:30 mbs-backend01 fedmsg-hub: self.commit = self.get_latest(self.branch)
May 29 17:02:30 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/module_build_service/scm.py", line 200, in get_latest
May 29 17:02:30 mbs-backend01 fedmsg-hub: output = SCM._run(["git", "ls-remote", "--exit-code", self.repository])[1]
May 29 17:02:30 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/module_build_service/utils/general.py", line 76, in inner
May 29 17:02:30 mbs-backend01 fedmsg-hub: return function(*args, **kwargs)
May 29 17:02:30 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/module_build_service/scm.py", line 145, in _run
May 29 17:02:30 mbs-backend01 fedmsg-hub: cmd, proc.returncode, stdout, stderr))
May 29 17:02:30 mbs-backend01 fedmsg-hub: UnprocessableEntity: Failed on ['git', 'ls-remote', '--exit-code', 'git://pkgs.fedoraproject.org/rpms/flatpak-runtime-config'], retcode 128, out '', err 'fatal: remote error: access denied or repository not exported: /rpms/flatpak-runtime-config\n'
May 29 17:02:30 mbs-backend01 fedmsg-hub: [2018-05-29 17:02:30][module_build_service   ERROR] Failed on ['git', 'ls-remote', '--exit-code', 'git://pkgs.fedoraproject.org/rpms/flatpak-rpm-macros'], retcode 128, out '', err 'fatal: remote error: access denied or repository not exported: /rpms/flatpak-rpm-macros\n'
May 29 17:02:30 mbs-backend01 fedmsg-hub: Traceback (most recent call last):
May 29 17:02:30 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/module_build_service/utils/submit.py", line 48, in _scm_get_latest
May 29 17:02:30 mbs-backend01 fedmsg-hub: pkg.get_repository()).get_latest(pkg.get_ref())
May 29 17:02:30 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/module_build_service/scm.py", line 94, in __init__
May 29 17:02:30 mbs-backend01 fedmsg-hub: self.commit = self.get_latest(self.branch)
May 29 17:02:30 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/module_build_service/scm.py", line 200, in get_latest
May 29 17:02:30 mbs-backend01 fedmsg-hub: output = SCM._run(["git", "ls-remote", "--exit-code", self.repository])[1]
May 29 17:02:30 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/module_build_service/utils/general.py", line 76, in inner
May 29 17:02:30 mbs-backend01 fedmsg-hub: return function(*args, **kwargs)
May 29 17:02:30 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/module_build_service/scm.py", line 145, in _run
May 29 17:02:30 mbs-backend01 fedmsg-hub: cmd, proc.returncode, stdout, stderr))
May 29 17:02:30 mbs-backend01 fedmsg-hub: UnprocessableEntity: Failed on ['git', 'ls-remote', '--exit-code', 'git://pkgs.fedoraproject.org/rpms/flatpak-rpm-macros'], retcode 128, out '', err 'fatal: remote error: access denied or repository not exported: /rpms/flatpak-rpm-macros\n'
May 29 17:02:30 mbs-backend01 fedmsg-hub: [2018-05-29 17:02:30][module_build_service    INFO] <ModuleBuild minimal-runtime, id=233, stream=master, version=20180529165959, state 'failed', batch 0, state_reason 'Failed to get the latest commit for git://pkgs.fedoraproject.org/rpms/flatpak-runtime-config#master\nFailed to get the latest commit for git://pkgs.fedoraproject.org/rpms/flatpak-rpm-macros#master\n'>, state 0->4
May 29 17:02:30 mbs-backend01 fedmsg-hub: [2018-05-29 17:02:30][module_build_service    INFO] Calling failed: MBSModule, 2018-4ef60550-830a-4553-bd87-06f26fa20c6d
May 29 17:05:14 mbs-backend01 fedmsg-hub: [2018-05-29 17:05:14][module_build_service    INFO] Current status:
May 29 17:05:14 mbs-backend01 fedmsg-hub: [2018-05-29 17:05:14][module_build_service    INFO]   * internal queue backlog is 0
May 29 17:05:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:05:15][module_build_service    INFO]   * 72 module builds in the failed state
May 29 17:05:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:05:15][module_build_service    INFO]   * 159 module builds in the ready state
May 29 17:05:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:05:15][module_build_service    INFO] Looking for module builds stuck in the wait state
May 29 17:05:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:05:15][module_build_service    INFO]  0 module builds in the wait state...
May 29 17:05:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:05:15][module_build_service WARNING] process_open_component_builds is not yet implemented...
May 29 17:05:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:05:15][module_build_service    INFO] Connecting to koji 'https://koji.stg.fedoraproject.org/kojihub' with 'kerberos'.
May 29 17:05:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:05:15][module_build_service   ERROR] Error in poller execution:
May 29 17:05:15 mbs-backend01 fedmsg-hub: Traceback (most recent call last):
May 29 17:05:15 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/module_build_service/scheduler/producer.py", line 49, in poll
May 29 17:05:15 mbs-backend01 fedmsg-hub: self.fail_lost_builds(session)
May 29 17:05:15 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/module_build_service/scheduler/producer.py", line 70, in fail_lost_builds
May 29 17:05:15 mbs-backend01 fedmsg-hub: .get_session(conf, None)
May 29 17:05:15 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/module_build_service/utils/general.py", line 76, in inner
May 29 17:05:15 mbs-backend01 fedmsg-hub: return function(*args, **kwargs)
May 29 17:05:15 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/module_build_service/builder/KojiModuleBuilder.py", line 374, in get_session
May 29 17:05:15 mbs-backend01 fedmsg-hub: ccache=ccache
May 29 17:05:15 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/koji/__init__.py", line 2157, in krb_login
May 29 17:05:15 mbs-backend01 fedmsg-hub: ccache.init(cprinc)
May 29 17:05:15 mbs-backend01 fedmsg-hub: Krb5Error: (-1765328189, 'No credentials cache found')
May 29 17:05:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:05:15][module_build_service    INFO] Poller will now sleep for "600" seconds
May 29 17:15:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:15:15][module_build_service    INFO] Current status:
May 29 17:15:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:15:15][module_build_service    INFO]   * internal queue backlog is 0
May 29 17:15:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:15:15][module_build_service    INFO]   * 72 module builds in the failed state
May 29 17:15:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:15:15][module_build_service    INFO]   * 159 module builds in the ready state
May 29 17:15:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:15:15][module_build_service    INFO] Looking for module builds stuck in the wait state
May 29 17:15:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:15:15][module_build_service    INFO]  0 module builds in the wait state...
May 29 17:15:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:15:15][module_build_service WARNING] process_open_component_builds is not yet implemented...
May 29 17:15:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:15:15][module_build_service    INFO] Connecting to koji 'https://koji.stg.fedoraproject.org/kojihub' with 'kerberos'.
May 29 17:15:15 mbs-backend01 fedmsg-hub: [2018-05-29 17:15:15][module_build_service   ERROR] Error in poller execution:
May 29 17:15:15 mbs-backend01 fedmsg-hub: Traceback (most recent call last):
May 29 17:15:15 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/module_build_service/scheduler/producer.py", line 49, in poll
May 29 17:15:15 mbs-backend01 fedmsg-hub: self.fail_lost_builds(session)
May 29 17:15:15 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/module_build_service/scheduler/producer.py", line 70, in fail_lost_builds
May 29 17:15:15 mbs-backend01 fedmsg-hub: .get_session(conf, None)
May 29 17:15:15 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/module_build_service/utils/general.py", line 76, in inner
May 29 17:15:15 mbs-backend01 fedmsg-hub: return function(*args, **kwargs)
May 29 17:15:15 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/module_build_service/builder/KojiModuleBuilder.py", line 374, in get_session
May 29 17:15:15 mbs-backend01 fedmsg-hub: ccache=ccache
May 29 17:15:15 mbs-backend01 fedmsg-hub: File "/usr/lib/python2.7/site-packages/koji/__init__.py", line 2157, in krb_login
May 29 17:15:15 mbs-backend01 fedmsg-hub: ccache.init(cprinc)
May 29 17:15:15 mbs-backend01 fedmsg-hub: Krb5Error: (-1765328189, 'No credentials cache found')

Does that help?

Metadata Update from @kevin:
- Issue assigned to kevin
- Issue priority set to: Waiting on Reporter (was: Needs Review)

5 years ago

This may be related to the Koji prod --> staging sync that happened last week. Bodhi also had trouble using its krb cache after that: https://pagure.io/fedora-infrastructure/issue/6971

Thanks for looking! That's pretty mysterious - since:

git ls-remote --exit-code git://pkgs.fedoraproject.org/rpms/flatpak-runtime-config

works fine on it's own. The error doesn't seem to be a networking problem either. Is it possible that 'pkgs.fedoraproject.org' is DNS resolving to something other than the public IP to pkgs.fedoraproject.org?

Digging around in ansible, I see that for (almost all) of staging infrastructure, pkgs.fedoraproject.org is in fact pointed to pkgs.stg.fedoraproject.org by /etc/hosts. Confusing!

Metadata Update from @otaylor:
- Issue status updated to: Closed (was: Open)

5 years ago

Login to comment on this ticket.

Metadata