copr / copr

Clone

#1090 Output missing
Closed: Fixed 4 years ago by praiskup. Opened 4 years ago by iucar.

Closed: Fixed
Reopen Issue

Consider this build, marked as succeeded, but there is no output! No SRPM, no RPMs...

I've found that this is a massive problem in the rawhide chroot. I'm gonna have to rebuild everything for that chroot... :weary:

It's like every RPM has been wiped out except for some noarch packages. How is this possible?
Edited 4 years ago by iucar

Metadata Update from @praiskup:
- Issue assigned to praiskup
4 years ago

For me: cat worker.log-20191021.gz | gunzip | grep backend.worker-7627-PC

[2019-10-15 14:15:31,455][  INFO][backend.worker-7627-PC][worker.py:run:359] Starting worker
[2019-10-15 14:15:31,458][  INFO][backend.worker-7627-PC][msgbus.py:__init__:157] [BUS 'fm'] initializing bus
[2019-10-15 14:15:31,459][  INFO][backend.worker-7627-PC][worker.py:mark_running:91] starting build: {'timeout': 75600, 'memory_reqs': 2048, 'enable_net': False, 'project_owner': 'iucar', 'project_name': 'cran', 'project_dirname': 'cran', 'submitter': 'iucar', 'ended_on': None, 'started_on': 1571148931.1415522, 'submitted_on': None, 'status': 3, 'chroot': 'fedora-rawhide-x86_64', 'arch': 'x86_64', 'buildroot_pkgs': None, 'task_id': '1057405-fedora-rawhide-x86_64', 'build_id': 1057405, 'package_name': 'R-CRAN-RcppArmadillo', 'package_version': '0.9.800.1.0-1.fc30', 'git_repo': 'iucar/cran/R-CRAN-RcppArmadillo', 'git_hash': '6148bb1845934818b2a9950efb1cae73f796e205', 'git_branch': None, 'source_type': 8, 'source_json': '{"clone_url": "https://copr-dist-git.fedorainfracloud.org/git/iucar/cran/R-CRAN-RcppArmadillo.git", "committish": "6148bb1845934818b2a9950efb1cae73f796e205"}', 'pkg_main_version': None, 'pkg_epoch': None, 'pkg_release': None, 'srpm_url': None, 'fetch_sources_only': True, 'repos': '', 'sandbox': 'iucar/cran--iucar', 'destdir': '/var/lib/copr/public_html/results/iucar/cran', 'results_repo_url': 'https://copr-be.cloud.fedoraproject.org/results/iucar/cran', 'result_dir': '01057405-R-CRAN-RcppArmadillo', 'built_packages': '', 'id': 1057405, 'mockchain_macros': {'copr_username': 'iucar', 'copr_projectname': 'cran', 'vendor': 'Fedora Project COPR (iucar/cran)'}}
[2019-10-15 14:15:32,401][  INFO][backend.worker-7627-PC][worker.py:do_job:189] Starting build: id=1057405 builder=172.25.86.15 job: BuildJob<id: 1057405, owner: iucar, project: cran, project_dir: crangit branch: None, git hash: 6148bb1845934818b2a9950efb1cae73f796e205, status: 3 >
[2019-10-15 14:15:32,434][  INFO][backend.worker-7627-PC.builder.mr][__init__.py:__init__:110] Setting up builder: 172.25.86.15
[2019-10-15 14:15:32,443][  INFO][backend.worker-7627-PC.builder.mr][builder.py:_run_ssh_cmd:51] BUILDER CMD: /bin/rpm -q copr-rpmbuild
[2019-10-15 14:15:32,942][  INFO][backend.worker-7627-PC.builder.mr][builder.py:_run_ssh_cmd:51] BUILDER CMD: /usr/bin/test -f /etc/mock/fedora-rawhide-x86_64.cfg
[2019-10-15 14:15:33,219][  INFO][backend.worker-7627-PC.builder.mr][__init__.py:build_pkg:273] Start build: BuildJob<id: 1057405, owner: iucar, project: cran, project_dir: crangit branch: None, git hash: 6148bb1845934818b2a9950efb1cae73f796e205, status: 3 >
[2019-10-15 14:15:33,220][  INFO][backend.worker-7627-PC.builder.mr][__init__.py:mark_dir_with_build_id:334] marking build dir with build_id,
[2019-10-15 14:15:33,221][  INFO][backend.worker-7627-PC.builder.mr][builder.py:_run_ssh_cmd:51] BUILDER CMD: copr-rpmbuild --verbose --drop-resultdir --build-id 1057405 --chroot fedora-rawhide-x86_64 --detached
[2019-10-15 14:15:33,856][  INFO][backend.worker-7627-PC.builder.mr][builder.py:attach_to_build:113] Attaching to live build log: /usr/bin/tail -F -n +0 --pid=17119 /var/lib/copr-rpmbuild/main.log
[2019-10-15 14:21:02,291][  INFO][backend.worker-7627-PC.builder.mr][__init__.py:compress_live_log:297] Compressing /var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64/01057405-R-CRAN-RcppArmadillo/builder-live.log by gzip
[2019-10-15 14:21:02,658][  INFO][backend.worker-7627-PC.builder.mr][builder.py:rsync_call:147] rsyncing of mockbuilder@172.25.86.15:/var/lib/copr-rpmbuild/results/* started for job: BuildJob<id: 1057405, owner: iucar, project: cran, project_dir: crangit branch: None, git hash: 6148bb1845934818b2a9950efb1cae73f796e205, status: 3 >
[2019-10-15 14:21:03,158][  INFO][backend.worker-7627-PC.builder.mr][builder.py:rsync_call:150] rsyncing finished.
[2019-10-15 14:21:03,159][  INFO][backend.worker-7627-PC.builder.mr][__init__.py:on_success_build:236] Success building R-CRAN-RcppArmadillo
[2019-10-15 14:21:03,160][  INFO][backend.worker-7627-PC.builder.mr][__init__.py:sign_built_packages:187] Going to sign pkgs from source: BuildJob<id: 1057405, owner: iucar, project: cran, project_dir: crangit branch: None, git hash: 6148bb1845934818b2a9950efb1cae73f796e205, status: 3 > in chroot: /var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64
[2019-10-15 14:21:04,233][  INFO][backend.worker-7627-PC.builder.mr][sign.py:sign_rpms_in_dir:126] signed rpm: /var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64/01057405-R-CRAN-RcppArmadillo/R-CRAN-RcppArmadillo-debugsource-0.9.800.1.0-1.fc32.x86_64.rpm
[2019-10-15 14:21:05,433][  INFO][backend.worker-7627-PC.builder.mr][sign.py:sign_rpms_in_dir:126] signed rpm: /var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64/01057405-R-CRAN-RcppArmadillo/R-CRAN-RcppArmadillo-0.9.800.1.0-1.fc32.src.rpm
[2019-10-15 14:21:06,575][  INFO][backend.worker-7627-PC.builder.mr][sign.py:sign_rpms_in_dir:126] signed rpm: /var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64/01057405-R-CRAN-RcppArmadillo/R-CRAN-RcppArmadillo-debuginfo-0.9.800.1.0-1.fc32.x86_64.rpm
[2019-10-15 14:21:07,525][  INFO][backend.worker-7627-PC.builder.mr][sign.py:sign_rpms_in_dir:126] signed rpm: /var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64/01057405-R-CRAN-RcppArmadillo/R-CRAN-RcppArmadillo-0.9.800.1.0-1.fc32.x86_64.rpm
[2019-10-15 14:21:07,526][  INFO][backend.worker-7627-PC.builder.mr][__init__.py:sign_built_packages:203] Sign done
[2019-10-15 14:21:07,527][  INFO][backend.worker-7627-PC.builder.mr][__init__.py:do_createrepo:217] Createrepo:: owner:  iucar; project: cran; front url: https://copr.fedorainfracloud.org; path: /var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64; base_url: https://copr-be.cloud.fedoraproject.org/results/iucar/cran/fedora-rawhide-x86_64
[2019-10-15 14:27:16,992][  INFO][backend.worker-7627-PC][worker.py:collect_built_packages:263] Listing built binary packages in /var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64/01057405-R-CRAN-RcppArmadillo
[2019-10-15 14:27:17,086][  INFO][backend.worker-7627-PC][worker.py:collect_built_packages:273] Built packages:
[2019-10-15 14:27:17,087][  INFO][backend.worker-7627-PC][worker.py:get_build_details:298] build details: {'built_packages': 'R-CRAN-RcppArmadillo 0.9.800.1.0\nR-CRAN-RcppArmadillo-debuginfo 0.9.800.1.0\nR-CRAN-RcppArmadillo-debugsource 0.9.800.1.0'}
[2019-10-15 14:27:17,087][  INFO][backend.worker-7627-PC.builder.mr][__init__.py:add_pubkey:154] Retrieving pubkey
[2019-10-15 14:27:17,451][  INFO][backend.worker-7627-PC.builder.mr][__init__.py:add_pubkey:167] Added pubkey for user iucar project cran into: /var/lib/copr/public_html/results/iucar/cran/pubkey.gpg
[2019-10-15 14:27:17,461][  INFO][backend.worker-7627-PC][worker.py:do_job:251] Finished build: id=1057405 builder=172.25.86.15 timeout=75600 destdir=/var/lib/copr/public_html/results/iucar/cran chroot=fedora-rawhide-x86_64
[2019-10-15 14:27:17,490][  INFO][backend.worker-7627-PC][worker.py:return_results:104] Build 1057405 finished with status 1
[2019-10-15 14:27:17,490][  INFO][backend.worker-7627-PC][worker.py:return_results:107] Took 706.3486907482147 seconds.
[2019-10-15 14:27:17,687][  INFO][backend.worker-7627-PC][worker.py:_announce_end:82] worker finished build: 172.25.86.15

This package has several builds:
https://copr.fedorainfracloud.org/coprs/iucar/cran/package/R-CRAN-RcppArmadillo/

But weird thing is that the build artifacts were removed, and later it has been removed entirely, despite the fact that this build should have the highest ENVR...

Ok, first the artifacts were removed by prunerepo:

[2019-10-29 05:12:50,097][  INFO]: Executing: prunerepo --verbose --days 7 --nocreaterepo /var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64
[2019-10-29 07:54:24,988][  INFO]: Removing obsoleted packages...
Executing: dnf repoquery --repofrompath=prunerepo_query,/var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64 --repo=prunerepo_query --refresh --queryformat="%{location}" --quiet --latest-limit=1
Executing: dnf repoquery --repofrompath=prunerepo_query,/var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64 --repo=prunerepo_query --refresh --queryformat="%{location}" --quiet
Removing: /var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64/01045273-R-CRAN-dynamac/R-CRAN-dynamac-0.1.9-1.fc32.src.rpm
Removing: /var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64/01045273-R-CRAN-dynamac/R-CRAN-dynamac-0.1.9-1.fc32.noarch.rpm
...
Removing: /var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64/01057405-R-CRAN-RcppArmadillo/R-CRAN-RcppArmadillo-0.9.800.1.0-1.fc32.src.rpm
...
Removing: /var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64/01057405-R-CRAN-RcppArmadillo/R-CRAN-RcppArmadillo-debuginfo-0.9.800.1.0-1.fc32.x86_64.rpm
...
Removing: /var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64/01057405-R-CRAN-RcppArmadillo/R-CRAN-RcppArmadillo-0.9.800.1.0-1.fc32.x86_64.rpm
...
Removing: /var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64/01057405-R-CRAN-RcppArmadillo/R-CRAN-RcppArmadillo-debugsource-0.9.800.1.0-1.fc32.x86_64.rpm

Hmm, and this actually removed 24394 RPMs :-( sorry for that. Some bug in
prunerepo (or dnf/repoquery, etc.) seems to be the root of the problem.
List of all the removed RPMs is attached.

The final directory removal was expected later (since there were no RPMs,
auto-cleanup did the job):

[2019-11-06 05:27:18,527][  INFO]: Cleaning COPR repository...
...
[2019-11-06 05:34:42,730][  INFO]: Removing: /var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64/01057405-R-CRAN-RcppArmadillo
[2019-11-06 05:34:42,890][  INFO]: Removing: /var/lib/copr/public_html/results/iucar/cran/fedora-rawhide-x86_64/build-01057405.log

log.prune.xz

Metadata Update from @praiskup:
- Issue tagged with: bug
4 years ago

Prunerepo removes to_remove_rpms = set(all_rpms) - set(latest_rpms)

And considering the amount of deleted RPMs, it looks like the latest_rpms variable was (almost?) empty. The latest_rpms variable is given by:

get_all_packages_cmd = [
    'dnf',
    'repoquery',
    '--repofrompath=prunerepo_query,'+os.path.abspath(args.path),
    '--repo=prunerepo_query',
    '--refresh',
    '--queryformat="%{location}"',
    '--quiet',
] + '--latest-limit=1'

... and prunerepo does correct command error checking. So it means either that
the repository was in inconsistent state for a while, or that there's some bug in
dnf (or below). Ideas?

OMG, what a mess. Only this chroot is affected, right?

This could be caused by missing --setopt=skip_if_unavailable=False option in repoquery, see the prunerepo PR.

Only this chroot is affected, right?

We don't track this info; prunerepo is run asynchronously from anything
else, by cron on backend. The process only works with rpm repositories.

But yes, I guess only that chroot is affected because only that is
significantly pruned:

$ for chroot in fedora-30-x86_64 fedora-31-x86_64 fedora-rawhide-x86_64; do echo -n "$chroot: "; dnf repoquery --repofrompath=prunerepo_query,`pwd`/$chroot --repo=prunerepo_query --refresh '--queryformat=%{location}' --quiet --latest-limit=1 --setopt=skip_if_unavailable=False | wc -l ; done
fedora-30-x86_64: 33610
fedora-31-x86_64: 33496
fedora-rawhide-x86_64: 7438
Edited 4 years ago by praiskup

The hotfix is here. I believe we resolved this particular dataloss problem, closing.
https://infrastructure.fedoraproject.org/cgit/ansible.git/commit/?id=460d59e365dfea7e7e27a4879ff05073cd19c16f

Metadata Update from @praiskup:
- Issue close_status updated to: Fixed
- Issue status updated to: Closed (was: Open)
4 years ago

Login to comment on this ticket.

Metadata

bug

None
None
None
None
None
Attachments 1
log.prune.xz
Attached 4 years ago View Comment
Powered by Pagure 5.13.3
Documentation • File an Issue • About • SSH Hostkey/Fingerprint
© Red Hat, Inc. and others.