Bug 739550

Summary: Logging gone awry between mock 1.1.12 and 1.1.14
Product: [Fedora] Fedora Reporter: Paul Howarth <paul>
Component: mockAssignee: Clark Williams <williams>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 15CC: dan, mebrown, williams
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: mock-1.1.15-1.el6 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2011-10-02 23:00:39 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
changes to mock to correct logging issues none

Description Paul Howarth 2011-09-19 13:29:08 UTC
I've just updated my f15 builder from mock 1.1.12 to 1.1.14 and something strange has gone on with logging.

The terminal has additional logging, which appears to to of the debug variety, and has multiple logging of the mock version number:

$ mock -r epel-centos-5-x86_64 perl-Text-CSV_XS-0.72-1.el6.src.rpm
INFO: mock.py version 1.1.14 starting...
INFO: State Changed: init plugins
INFO: selinux enabled
INFO: State Changed: start
INFO: Start(perl-Text-CSV_XS-0.72-1.el6.src.rpm)  Config(epel-centos-5-x86_64)
INFO: State Changed: lock buildroot
INFO: State Changed: clean
INFO: chroot (/var/lib/mock/epel-centos-5-x86_64) unlocked and deleted
INFO: State Changed: unlock buildroot
INFO: State Changed: init
INFO: State Changed: lock buildroot
INFO: Mock Version: 1.1.14
INFO: Mock Version: 1.1.14
INFO: Mock Version: 1.1.14
INFO: mounting tmpfs.
INFO: enabled root cache
INFO: State Changed: unpacking root cache
INFO: enabled yum cache
INFO: State Changed: cleaning yum metadata
INFO: enabled ccache
INFO: State Changed: running yum
INFO: State Changed: unlock buildroot
INFO: State Changed: setup
INFO: ENTER do(['bash', '--login', '-c', 'rpmbuild -bs --target x86_64 --nodeps builddir/build/SPECS/perl-Text-CSV_XS.spec'], False, '/var/lib/mock/epel-centos-5-x86_64/root/', None, 0, True, False, 500, 101, None, logger=<mockbuild.trace_decorator.getLog object at 0x20f8b10>)
INFO: LEAVE do --> 

INFO: State Changed: build
INFO: ENTER do(['bash', '--login', '-c', 'rpmbuild -bb --target x86_64 --nodeps builddir/build/SPECS/perl-Text-CSV_XS.spec'], False, '/var/lib/mock/epel-centos-5-x86_64/root/', None, 0, True, False, 500, 101, None, logger=<mockbuild.trace_decorator.getLog object at 0x20f8b10>)
INFO: LEAVE do --> 

INFO: unmounting tmpfs.
INFO: Done(perl-Text-CSV_XS-0.72-1.el6.src.rpm) Config(epel-centos-5-x86_64) 0 minutes 13 seconds
INFO: Results and/or logs in: /var/lib/mock/epel-centos-5-x86_64/result
INFO: State Changed: end

The "ENTER/LEAVE do" logging seems out of place here.

More seriously, the root.log is longer including the yum output:

$ cat /var/lib/mock/epel-centos-5-x86_64/result/root.log 
INFO backend.py:833:  Mock Version: 1.1.14
DEBUG backend.py:274:  rootdir = /var/lib/mock/epel-centos-5-x86_64/root/
DEBUG backend.py:275:  resultdir = /var/lib/mock/epel-centos-5-x86_64/result
DEBUG backend.py:281:  create skeleton dirs
DEBUG backend.py:299:  touch required files
DEBUG backend.py:311:  configure yum
DEBUG backend.py:326:  configure yum rhnplugin
DEBUG backend.py:715:  mount -n -t proc   mock_chroot_proc   /var/lib/mock/epel-centos-5-x86_64/root/proc
DEBUG backend.py:715:  mount -n -t sysfs  mock_chroot_sysfs  /var/lib/mock/epel-centos-5-x86_64/root/sys
DEBUG backend.py:715:  mount -n --bind /var/cache/mock/epel-centos-5-x86_64/yum_cache/  /var/lib/mock/epel-centos-5-x86_64/root/var/cache/yum
DEBUG backend.py:715:  mount -n --bind /var/cache/mock/epel-centos-5-x86_64/ccache/  /var/lib/mock/epel-centos-5-x86_64/root/tmp/ccache
DEBUG backend.py:715:  mount -n --bind /tmp/mock-selinux-plugin.7jRT5x /var/lib/mock/epel-centos-5-x86_64/root/proc/filesystems
DEBUG backend.py:715:  mount -n -t devpts -o gid=5,mode=0620,ptmxmode=0666,newinstance mock_chroot_devpts /var/lib/mock/epel-centos-5-x86_64/root/dev/pts
DEBUG backend.py:715:  mount -n -t tmpfs mock_chroot_shmfs /var/lib/mock/epel-centos-5-x86_64/root/dev/shm
DEBUG backend.py:765:  ['/usr/bin/yum', '--installroot', '/var/lib/mock/epel-centos-5-x86_64/root/', 'update']
DEBUG backend.py:715:  mount -n -t proc   mock_chroot_proc   /var/lib/mock/epel-centos-5-x86_64/root/proc
DEBUG backend.py:715:  mount -n -t sysfs  mock_chroot_sysfs  /var/lib/mock/epel-centos-5-x86_64/root/sys
DEBUG backend.py:715:  mount -n --bind /var/cache/mock/epel-centos-5-x86_64/yum_cache/  /var/lib/mock/epel-centos-5-x86_64/root/var/cache/yum
DEBUG backend.py:715:  mount -n --bind /var/cache/mock/epel-centos-5-x86_64/ccache/  /var/lib/mock/epel-centos-5-x86_64/root/tmp/ccache
DEBUG backend.py:715:  mount -n --bind /tmp/mock-selinux-plugin.7jRT5x /var/lib/mock/epel-centos-5-x86_64/root/proc/filesystems
DEBUG backend.py:715:  mount -n -t devpts -o gid=5,mode=0620,ptmxmode=0666,newinstance mock_chroot_devpts /var/lib/mock/epel-centos-5-x86_64/root/dev/pts
DEBUG backend.py:715:  mount -n -t tmpfs mock_chroot_shmfs /var/lib/mock/epel-centos-5-x86_64/root/dev/shm
DEBUG backend.py:765:  ['/usr/bin/yum', '--installroot', '/var/lib/mock/epel-centos-5-x86_64/root/', 'resolvedep', 'ccache']
DEBUG backend.py:765:  ['/usr/bin/yum', '--installroot', '/var/lib/mock/epel-centos-5-x86_64/root/', 'install', 'ccache']
DEBUG backend.py:765:  ['/usr/bin/yum-builddep', '--installroot', '/var/lib/mock/epel-centos-5-x86_64/root/', '/var/lib/mock/epel-centos-5-x86_64/root///builddir/build/SRPMS/perl-Text-CSV_XS-0.72-1.rhel5.src.rpm']
DEBUG backend.py:601:  Copying packages to result dir

This will be a big problem for me before long when I need that output to debug something.

Comment 1 Peter Robinson 2011-09-19 14:19:31 UTC
reassign to proper component

Comment 2 Clark Williams 2011-09-21 20:23:02 UTC
I suspect this is fallout of the mock -> mockbuild change for namespace cleanup. Looking...

Comment 3 Clark Williams 2011-09-22 15:23:19 UTC
Created attachment 524433 [details]
changes to mock to correct logging issues

Straighten out confusion between /etc/mock/logging.ini and actual logging usage in mock.py and mockbuild/backend.py

Comment 4 Clark Williams 2011-09-22 15:23:54 UTC
Paul, 

Would you try the above patch and see if that straightens out your logging issues?

Comment 5 Paul Howarth 2011-09-23 08:37:15 UTC
(In reply to comment #4)
> Would you try the above patch and see if that straightens out your logging
> issues?

WORKSFORME.

Thanks.

Comment 6 Clark Williams 2011-09-23 18:51:14 UTC
excellent! Changes queued for 1.1.15

Comment 7 Fedora Update System 2011-09-23 20:55:04 UTC
mock-1.1.15-1.fc15 has been submitted as an update for Fedora 15.
https://admin.fedoraproject.org/updates/mock-1.1.15-1.fc15

Comment 8 Fedora Update System 2011-09-23 20:56:06 UTC
mock-1.1.15-1.el6 has been submitted as an update for Fedora EPEL 6.
https://admin.fedoraproject.org/updates/mock-1.1.15-1.el6

Comment 9 Fedora Update System 2011-09-23 20:56:59 UTC
mock-1.0.22-1.el5 has been submitted as an update for Fedora EPEL 5.
https://admin.fedoraproject.org/updates/mock-1.0.22-1.el5

Comment 10 Fedora Update System 2011-09-23 20:57:52 UTC
mock-1.1.15-1.fc14 has been submitted as an update for Fedora 14.
https://admin.fedoraproject.org/updates/mock-1.1.15-1.fc14

Comment 11 Fedora Update System 2011-09-24 21:59:19 UTC
Package mock-1.1.15-1.el6:
* should fix your issue,
* was pushed to the Fedora EPEL 6 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=epel-testing mock-1.1.15-1.el6'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/mock-1.1.15-1.el6
then log in and leave karma (feedback).

Comment 12 Fedora Update System 2011-10-02 22:59:37 UTC
mock-1.1.15-1.fc15 has been pushed to the Fedora 15 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 13 Fedora Update System 2011-10-02 23:08:01 UTC
mock-1.1.15-1.fc14 has been pushed to the Fedora 14 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 14 Fedora Update System 2011-10-16 18:27:38 UTC
mock-1.0.22-1.el5 has been pushed to the Fedora EPEL 5 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 15 Fedora Update System 2011-10-16 18:29:22 UTC
mock-1.1.15-1.el6 has been pushed to the Fedora EPEL 6 stable repository.  If problems still persist, please make note of it in this bug report.