Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.
Bug 894623 - OSError: [Errno 12] Cannot allocate memory / mock broken after latest rawhide upgrade
Summary: OSError: [Errno 12] Cannot allocate memory / mock broken after latest rawhide...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: mock
Version: rawhide
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: ---
Assignee: Clark Williams
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-01-12 17:15 UTC by Paulo Andrade
Modified: 2013-05-20 08:07 UTC (History)
14 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2013-03-04 22:43:55 UTC
Type: Bug
Embargoed:

Attachments (Terms of Use)
mock-rawhide-x86_64.txt (1.62 MB, text/plain)
2013-01-24 17:10 UTC, Paulo Andrade 		no flags Details
experiment with unshare() and CLONE_NEWPID (1.36 KB, patch)
2013-02-22 22:11 UTC, Clark Williams 		no flags Details | Diff
View All

Description Paulo Andrade 2013-01-12 17:15:22 UTC 
Noticed after failing to build a simple package, and attempting
to "reset" it shows same "Cannot allocate memory" error.

$ mock --verbose --clean
INFO: mock.py version 1.1.28 starting...
Start: init plugins
DEBUG: ensuring that dir exists: /var/cache/mock/fedora-rawhide-x86_64/yum_cache/
INFO: selinux enabled
Finish: init plugins
Start: run
DEBUG: mock final configuration:
DEBUG:     scm:  False
DEBUG:     resultdir:  %(basedir)s/%(root)s/result
DEBUG:     legal_host_arches:  ('x86_64',)
DEBUG:     dist:  rawhide
DEBUG:     internal_setarch:  True
DEBUG:     scm_opts:  {'git_get': 'git clone SCM_BRN git://localhost/SCM_PKG.git SCM_PKG', 'cvs_get': 'cvs -d /srv/cvs co SCM_BRN SCM_PKG', 'git_timestamps': False, 'ext_src_dir': '/dev/null', 'spec': 'SCM_PKG.spec', 'write_tar': False, 'method': 'git', 'svn_get': 'svn co file:///srv/svn/SCM_PKG/SCM_BRN SCM_PKG'}
DEBUG:     use_host_resolv:  True
DEBUG:     more_buildreqs:  {}
DEBUG:     createrepo_command:  /usr/bin/createrepo -d -q -x *.src.rpm
DEBUG:     yum_builddep_opts:  
DEBUG:     yum.conf:  
[main]
cachedir=/var/cache/yum
debuglevel=1
reposdir=/dev/null
logfile=/var/log/yum.log
retries=20
obsoletes=1
gpgcheck=0
assumeyes=1
syslog_ident=mock
syslog_device=

# repos

[fedora]
name=fedora
mirrorlist=http://mirrors.fedoraproject.org/mirrorlist?repo=rawhide&arch=x86_64
failovermethod=priority

[local]
name=local
baseurl=http://kojipkgs.fedoraproject.org/repos/rawhide/latest/x86_64/
cost=2000
enabled=0

[debug]
name=Fedora Rawhide - x86_64 - Debug
failovermethod=priority
mirrorlist=http://mirrors.fedoraproject.org/mirrorlist?repo=rawhide-debug&arch=x86_64
enabled=0

DEBUG:     cleanup_on_failure:  False
DEBUG:     plugins:  ['tmpfs', 'root_cache', 'yum_cache', 'bind_mount', 'ccache', 'selinux', 'mount', 'package_state']
DEBUG:     chrootuid:  1000
DEBUG:     no_root_shells:  False
DEBUG:     priorities.conf:  
[main]
enabled=0
DEBUG:     yum_common_opts:  []
DEBUG:     chroothome:  /builddir
DEBUG:     basedir:  /var/lib/mock
DEBUG:     internal_dev_setup:  True
DEBUG:     environment:  {'LANG': 'en_US.UTF-8', 'TERM': 'vt100', 'SHELL': '/bin/bash', 'HOSTNAME': 'mock', 'PROMPT_COMMAND': 'echo -n "<mock-chroot>"', 'HOME': '/builddir', 'PATH': '/usr/bin:/bin:/usr/sbin:/sbin'}
DEBUG:     macros:  {'%_rpmfilename': '%%{NAME}-%%{VERSION}-%%{RELEASE}.%%{ARCH}.rpm', '%_topdir': '/builddir/build'}
DEBUG:     version:  1.1.28
DEBUG:     online:  True
DEBUG:     build_log_fmt_name:  unadorned
DEBUG:     chrootgid:  986
DEBUG:     files:  {}
DEBUG:     rpmbuild_arch:  x86_64
DEBUG:     log_config_file:  logging.ini
DEBUG:     rpmbuild_timeout:  0
DEBUG:     cleanup_on_success:  False
DEBUG:     chroot_setup_cmd:  groupinstall buildsys-build
DEBUG:     useradd:  /usr/sbin/useradd -o -m -u %(uid)s -g %(gid)s -d %(home)s -n %(user)s
DEBUG:     root_log_fmt_name:  detailed
DEBUG:     chroot_name:  default
DEBUG:     plugin_conf:  {'package_state_enable': False, 'yum_cache_opts': {'max_metadata_age_days': 30, 'root': 'fedora-rawhide-x86_64', 'basedir': '/var/lib/mock/fedora-rawhide-x86_64', 'cachedir': '/var/cache/mock/fedora-rawhide-x86_64', 'online': True, 'cache_topdir': '/var/cache/mock', 'max_age_days': 30, 'dir': '%(cache_topdir)s/%(root)s/yum_cache/'}, 'mount_opts': {'basedir': '/var/lib/mock/fedora-rawhide-x86_64', 'root': 'fedora-rawhide-x86_64', 'cachedir': '/var/cache/mock/fedora-rawhide-x86_64', 'cache_topdir': '/var/cache/mock'}, 'bind_mount_opts': {'dirs': [], 'create_dirs': False, 'basedir': '/var/lib/mock/fedora-rawhide-x86_64', 'cachedir': '/var/cache/mock/fedora-rawhide-x86_64', 'cache_topdir': '/var/cache/mock', 'root': 'fedora-rawhide-x86_64'}, 'root_cache_enable': True, 'selinux_opts': {'basedir': '/var/lib/mock/fedora-rawhide-x86_64', 'root': 'fedora-rawhide-x86_64', 'cachedir': '/var/cache/mock/fedora-rawhide-x86_64', 'cache_topdir': '/var/cache/mock'}, 'ccache_opts': {'basedir': '/var/lib/mock/fedora-rawhide-x86_64', 'compress': None, 'max_cache_size': '4G', 'cachedir': '/var/cache/mock/fedora-rawhide-x86_64', 'cache_topdir': '/var/cache/mock', 'root': 'fedora-rawhide-x86_64', 'dir': '%(cache_topdir)s/%(root)s/ccache/'}, 'bind_mount_enable': True, 'root_cache_opts': {'exclude_dirs': ['./proc', './sys', './dev', './tmp/ccache', './var/cache/yum'], 'compress_program': 'pigz', 'extension': '.gz', 'root': 'fedora-rawhide-x86_64', 'basedir': '/var/lib/mock/fedora-rawhide-x86_64', 'cachedir': '/var/cache/mock/fedora-rawhide-x86_64', 'age_check': True, 'cache_topdir': '/var/cache/mock', 'max_age_days': 15, 'dir': '%(cache_topdir)s/%(root)s/root_cache/'}, 'selinux_enable': True, 'yum_cache_enable': True, 'tmpfs_enable': False, 'tmpfs_opts': {'basedir': '/var/lib/mock/fedora-rawhide-x86_64', 'required_ram_mb': 900, 'cache_topdir': '/var/cache/mock', 'cachedir': '/var/cache/mock/fedora-rawhide-x86_64', 'max_fs_size': None, 'root': 'fedora-rawhide-x86_64'}, 'ccache_enable': True, 'package_state_opts': {'basedir': '/var/lib/mock/fedora-rawhide-x86_64', 'root': 'fedora-rawhide-x86_64', 'cachedir': '/var/cache/mock/fedora-rawhide-x86_64', 'cache_topdir': '/var/cache/mock'}, 'mount_enable': False}
DEBUG:     state_log_fmt_str:  %(asctime)s - %(message)s
DEBUG:     config_paths:  ['/etc/mock/site-defaults.cfg', '/etc/mock/default.cfg']
DEBUG:     rhnplugin.conf:  
[main]
enabled=0
DEBUG:     build_log_fmt_str:  %(message)s
DEBUG:     state_log_fmt_name:  state
DEBUG:     plugin_dir:  /usr/lib/python2.7/site-packages/mockbuild/plugins
DEBUG:     root_log_fmt_str:  %(levelname)s %(filename)s:%(lineno)d:  %(message)s
DEBUG:     clean:  True
DEBUG:     createrepo_on_rpms:  False
DEBUG:     cache_topdir:  /var/cache/mock
DEBUG:     root:  fedora-rawhide-x86_64
DEBUG:     target_arch:  x86_64
DEBUG: Unsharing. Flags: 738328576
Start: lock buildroot
Start: clean chroot
DEBUG: kill orphans
DEBUG: remove tree: /var/lib/mock/fedora-rawhide-x86_64.tmp
INFO: chroot (/var/lib/mock/fedora-rawhide-x86_64) unlocked and deleted
Finish: clean chroot
Finish: lock buildroot
Finish: run
DEBUG: kill orphans


$ mock --verbose --init
INFO: mock.py version 1.1.28 starting...
Start: init plugins
DEBUG: ensuring that dir exists: /var/cache/mock/fedora-rawhide-x86_64/yum_cache/
INFO: selinux enabled
Finish: init plugins
Start: run
DEBUG: mock final configuration:
DEBUG:     scm:  False
DEBUG:     resultdir:  %(basedir)s/%(root)s/result
DEBUG:     legal_host_arches:  ('x86_64',)
DEBUG:     dist:  rawhide
DEBUG:     internal_setarch:  True
DEBUG:     scm_opts:  {'git_get': 'git clone SCM_BRN git://localhost/SCM_PKG.git SCM_PKG', 'cvs_get': 'cvs -d /srv/cvs co SCM_BRN SCM_PKG', 'git_timestamps': False, 'ext_src_dir': '/dev/null', 'spec': 'SCM_PKG.spec', 'write_tar': False, 'method': 'git', 'svn_get': 'svn co file:///srv/svn/SCM_PKG/SCM_BRN SCM_PKG'}
DEBUG:     use_host_resolv:  True
DEBUG:     more_buildreqs:  {}
DEBUG:     createrepo_command:  /usr/bin/createrepo -d -q -x *.src.rpm
DEBUG:     yum_builddep_opts:  
DEBUG:     yum.conf:  
[main]
cachedir=/var/cache/yum
debuglevel=1
reposdir=/dev/null
logfile=/var/log/yum.log
retries=20
obsoletes=1
gpgcheck=0
assumeyes=1
syslog_ident=mock
syslog_device=

# repos

[fedora]
name=fedora
mirrorlist=http://mirrors.fedoraproject.org/mirrorlist?repo=rawhide&arch=x86_64
failovermethod=priority

[local]
name=local
baseurl=http://kojipkgs.fedoraproject.org/repos/rawhide/latest/x86_64/
cost=2000
enabled=0

[debug]
name=Fedora Rawhide - x86_64 - Debug
failovermethod=priority
mirrorlist=http://mirrors.fedoraproject.org/mirrorlist?repo=rawhide-debug&arch=x86_64
enabled=0

DEBUG:     cleanup_on_failure:  False
DEBUG:     plugins:  ['tmpfs', 'root_cache', 'yum_cache', 'bind_mount', 'ccache', 'selinux', 'mount', 'package_state']
DEBUG:     chrootuid:  1000
DEBUG:     no_root_shells:  False
DEBUG:     priorities.conf:  
[main]
enabled=0
DEBUG:     yum_common_opts:  []
DEBUG:     chroothome:  /builddir
DEBUG:     basedir:  /var/lib/mock
DEBUG:     internal_dev_setup:  True
DEBUG:     environment:  {'LANG': 'en_US.UTF-8', 'TERM': 'vt100', 'SHELL': '/bin/bash', 'HOSTNAME': 'mock', 'PROMPT_COMMAND': 'echo -n "<mock-chroot>"', 'HOME': '/builddir', 'PATH': '/usr/bin:/bin:/usr/sbin:/sbin'}
DEBUG:     macros:  {'%_rpmfilename': '%%{NAME}-%%{VERSION}-%%{RELEASE}.%%{ARCH}.rpm', '%_topdir': '/builddir/build'}
DEBUG:     version:  1.1.28
DEBUG:     online:  True
DEBUG:     build_log_fmt_name:  unadorned
DEBUG:     chrootgid:  986
DEBUG:     files:  {}
DEBUG:     rpmbuild_arch:  x86_64
DEBUG:     log_config_file:  logging.ini
DEBUG:     rpmbuild_timeout:  0
DEBUG:     cleanup_on_success:  False
DEBUG:     chroot_setup_cmd:  groupinstall buildsys-build
DEBUG:     useradd:  /usr/sbin/useradd -o -m -u %(uid)s -g %(gid)s -d %(home)s -n %(user)s
DEBUG:     root_log_fmt_name:  detailed
DEBUG:     chroot_name:  default
DEBUG:     plugin_conf:  {'package_state_enable': False, 'yum_cache_opts': {'max_metadata_age_days': 30, 'root': 'fedora-rawhide-x86_64', 'basedir': '/var/lib/mock/fedora-rawhide-x86_64', 'cachedir': '/var/cache/mock/fedora-rawhide-x86_64', 'online': True, 'cache_topdir': '/var/cache/mock', 'max_age_days': 30, 'dir': '%(cache_topdir)s/%(root)s/yum_cache/'}, 'mount_opts': {'basedir': '/var/lib/mock/fedora-rawhide-x86_64', 'root': 'fedora-rawhide-x86_64', 'cachedir': '/var/cache/mock/fedora-rawhide-x86_64', 'cache_topdir': '/var/cache/mock'}, 'bind_mount_opts': {'dirs': [], 'create_dirs': False, 'basedir': '/var/lib/mock/fedora-rawhide-x86_64', 'cachedir': '/var/cache/mock/fedora-rawhide-x86_64', 'cache_topdir': '/var/cache/mock', 'root': 'fedora-rawhide-x86_64'}, 'root_cache_enable': True, 'selinux_opts': {'basedir': '/var/lib/mock/fedora-rawhide-x86_64', 'root': 'fedora-rawhide-x86_64', 'cachedir': '/var/cache/mock/fedora-rawhide-x86_64', 'cache_topdir': '/var/cache/mock'}, 'ccache_opts': {'basedir': '/var/lib/mock/fedora-rawhide-x86_64', 'compress': None, 'max_cache_size': '4G', 'cachedir': '/var/cache/mock/fedora-rawhide-x86_64', 'cache_topdir': '/var/cache/mock', 'root': 'fedora-rawhide-x86_64', 'dir': '%(cache_topdir)s/%(root)s/ccache/'}, 'bind_mount_enable': True, 'root_cache_opts': {'exclude_dirs': ['./proc', './sys', './dev', './tmp/ccache', './var/cache/yum'], 'compress_program': 'pigz', 'extension': '.gz', 'root': 'fedora-rawhide-x86_64', 'basedir': '/var/lib/mock/fedora-rawhide-x86_64', 'cachedir': '/var/cache/mock/fedora-rawhide-x86_64', 'age_check': True, 'cache_topdir': '/var/cache/mock', 'max_age_days': 15, 'dir': '%(cache_topdir)s/%(root)s/root_cache/'}, 'selinux_enable': True, 'yum_cache_enable': True, 'tmpfs_enable': False, 'tmpfs_opts': {'basedir': '/var/lib/mock/fedora-rawhide-x86_64', 'required_ram_mb': 900, 'cache_topdir': '/var/cache/mock', 'cachedir': '/var/cache/mock/fedora-rawhide-x86_64', 'max_fs_size': None, 'root': 'fedora-rawhide-x86_64'}, 'ccache_enable': True, 'package_state_opts': {'basedir': '/var/lib/mock/fedora-rawhide-x86_64', 'root': 'fedora-rawhide-x86_64', 'cachedir': '/var/cache/mock/fedora-rawhide-x86_64', 'cache_topdir': '/var/cache/mock'}, 'mount_enable': False}
DEBUG:     state_log_fmt_str:  %(asctime)s - %(message)s
DEBUG:     config_paths:  ['/etc/mock/site-defaults.cfg', '/etc/mock/default.cfg']
DEBUG:     rhnplugin.conf:  
[main]
enabled=0
DEBUG:     build_log_fmt_str:  %(message)s
DEBUG:     state_log_fmt_name:  state
DEBUG:     plugin_dir:  /usr/lib/python2.7/site-packages/mockbuild/plugins
DEBUG:     root_log_fmt_str:  %(levelname)s %(filename)s:%(lineno)d:  %(message)s
DEBUG:     clean:  True
DEBUG:     createrepo_on_rpms:  False
DEBUG:     cache_topdir:  /var/cache/mock
DEBUG:     root:  fedora-rawhide-x86_64
DEBUG:     target_arch:  x86_64
DEBUG: Unsharing. Flags: 738328576
Start: lock buildroot
Start: clean chroot
DEBUG: kill orphans
Finish: clean chroot
Finish: lock buildroot
Start: chroot init
DEBUG: ensuring that dir exists: /var/lib/mock/fedora-rawhide-x86_64
DEBUG: creating dir: /var/lib/mock/fedora-rawhide-x86_64
DEBUG: ensuring that dir exists: /var/lib/mock/fedora-rawhide-x86_64/root/
DEBUG: creating dir: /var/lib/mock/fedora-rawhide-x86_64/root/
DEBUG: ensuring that dir exists: /var/lib/mock/fedora-rawhide-x86_64/result
DEBUG: creating dir: /var/lib/mock/fedora-rawhide-x86_64/result
Start: lock buildroot
Mock Version: 1.1.28
INFO: Mock Version: 1.1.28
INFO: Mock Version: 1.1.28
DEBUG: rootdir = /var/lib/mock/fedora-rawhide-x86_64/root/
DEBUG: resultdir = /var/lib/mock/fedora-rawhide-x86_64/result
INFO: calling preinit hooks
INFO: enabled root cache
DEBUG: ensuring that dir exists: /var/cache/mock/fedora-rawhide-x86_64/root_cache/
Start: unpacking root cache
DEBUG: Executing command: ['tar', '--use-compress-program', 'pigz', '-xf', '/var/cache/mock/fedora-rawhide-x86_64/root_cache/cache.tar.gz', '-C', '/var/lib/mock/fedora-rawhide-x86_64/root/'] with env {'LANG': 'en_US.UTF-8', 'TERM': 'vt100', 'SHELL': '/bin/bash', 'HOSTNAME': 'mock', 'HOME': '/builddir', 'PATH': '/usr/bin:/bin:/usr/sbin:/sbin'}
BDB2053 Freeing read locks for locker 0x17e: 1479/139988000905216
BDB2053 Freeing read locks for locker 0x17f: 1479/139988000905216
BDB2053 Freeing read locks for locker 0x180: 1479/139988000905216
BDB2053 Freeing read locks for locker 0x181: 1479/139988000905216
Traceback (most recent call last):
  File "/usr/sbin/mock", line 539, in <module>
    def do_buildsrpm(config_opts, chroot, options, args):
  File "/usr/sbin/mock", line 782, in main
    chroot.init()
  File "<peak.util.decorators.rewrap wrapping mockbuild.backend.init at 0x00CF6500>", line 3, in init
  File "/usr/lib/python2.7/site-packages/mockbuild/trace_decorator.py", line 70, in trace
    result = func(*args, **kw)
  File "/usr/lib/python2.7/site-packages/mockbuild/backend.py", line 279, in init
    self._init()
  File "<peak.util.decorators.rewrap wrapping mockbuild.backend._init at 0x00CF68C0>", line 3, in _init
  File "/usr/lib/python2.7/site-packages/mockbuild/trace_decorator.py", line 70, in trace
    result = func(*args, **kw)
  File "/usr/lib/python2.7/site-packages/mockbuild/backend.py", line 316, in _init
    self._callHooks('preinit')
  File "<peak.util.decorators.rewrap wrapping mockbuild.backend._callHooks at 0x00CE1500>", line 3, in _callHooks
  File "/usr/lib/python2.7/site-packages/mockbuild/trace_decorator.py", line 70, in trace
    result = func(*args, **kw)
  File "/usr/lib/python2.7/site-packages/mockbuild/backend.py", line 843, in _callHooks
    hook()
  File "<peak.util.decorators.rewrap wrapping root_cache._rootCachePreInitHook at 0x00CF31B8>", line 3, in _rootCachePreInitHook
  File "/usr/lib/python2.7/site-packages/mockbuild/trace_decorator.py", line 70, in trace
    result = func(*args, **kw)
  File "/usr/lib/python2.7/site-packages/mockbuild/plugins/root_cache.py", line 108, in _rootCachePreInitHook
    shell=False
  File "<peak.util.decorators.rewrap wrapping mockbuild.util.do at 0x00CE4320>", line 3, in do
  File "/usr/lib/python2.7/site-packages/mockbuild/trace_decorator.py", line 70, in trace
    result = func(*args, **kw)
  File "/usr/lib/python2.7/site-packages/mockbuild/util.py", line 323, in do
    preexec_fn = preexec,
  File "/usr/lib64/python2.7/subprocess.py", line 679, in __init__
    errread, errwrite)
  File "/usr/lib64/python2.7/subprocess.py", line 1143, in _execute_child
    self.pid = os.fork()
OSError: [Errno 12] Cannot allocate memory
Comment 1 Paulo Andrade 2013-01-24 17:10:09 UTC 
Created attachment 686858 [details]
mock-rawhide-x86_64.txt

strace -f output, running as root, it is basically the same
as in a f18 computer, running the same version of mock
until the chunk:

open("/dev/null", O_RDONLY)             = 5
fstat(5, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 3), ...}) = 0
pipe([6, 7])                            = 0
fcntl(6, F_GETFD)                       = 0
fcntl(6, F_SETFD, FD_CLOEXEC)           = 0
fcntl(7, F_GETFD)                       = 0
fcntl(7, F_SETFD, FD_CLOEXEC)           = 0
pipe([8, 9])                            = 0
fcntl(8, F_GETFD)                       = 0
fcntl(8, F_SETFD, FD_CLOEXEC)           = 0
fcntl(9, F_GETFD)                       = 0
fcntl(9, F_SETFD, FD_CLOEXEC)           = 0
pipe([10, 11])                          = 0
fcntl(10, F_GETFD)                      = 0
fcntl(10, F_SETFD, FD_CLOEXEC)          = 0
fcntl(11, F_GETFD)                      = 0
fcntl(11, F_SETFD, FD_CLOEXEC)          = 0
clone(Process 31207 attached
child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fe0e5498a10) = 31207
[pid 31207] set_robust_list(0x7fe0e5498a20, 24) = 0
[pid 31202] close(11)                   = 0
[pid 31202] close(7)                    = 0
[pid 31202] close(9)                    = 0
[pid 31202] mmap(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fe0d95da000
[pid 31207] close(6 <unfinished ...>
[pid 31202] read(10,  <unfinished ...>
[pid 31207] <... close resumed> )       = 0
[pid 31207] close(8)                    = 0
[pid 31207] close(10)                   = 0
[pid 31207] dup2(5, 0)                  = 0
[pid 31207] dup2(7, 1)                  = 1
[pid 31207] dup2(9, 2)                  = 2
[pid 31207] close(5)                    = 0
[pid 31207] close(7)                    = 0
[pid 31207] close(9)                    = 0
[pid 31207] close(3)                    = 0
[pid 31207] close(4)                    = 0
[pid 31207] close(5)                    = -1 EBADF (Bad file descriptor)

search for EBADF to locate it in the strace dump.
Comment 2 Mathieu Bridon 2013-01-27 06:33:40 UTC 
Same problem here.
Comment 3 Sandro Mani 2013-01-29 16:11:05 UTC 
Kernel issue? Issue only appears with 3.8.0(-rc4), with the exact same rawhide system, but using the latest f18 kernel, mock works fine.
Comment 4 Clark Williams 2013-01-30 16:51:26 UTC 
I'd have to say this is a kernel issue. not much I can do about the SLAB allocator refusing to allocate memory.
Comment 5 Paulo Andrade 2013-01-31 14:31:25 UTC 
Try googling for
"python subprocess oserror errno 12 cannot allocate memory Popen"
there are plently of discussions everywhere, without
anybody coming to a proper solution.

I am using the latest rawhide kernel, the error changed
a bit from the one in the strace I attached, but the
two most visible tests I did last night did not show
anything of interest.

First test was to
    import gc
    gc.collect()
in mock.utils.do, that made it run one more subprocess.Popen
call before failing.

Second test was to
    import time
    time.sleep(1000000)
in subprocess._execute_child just before it returning after
triggering the exception, and then investigate the
sleeping process attaching gdb, checking /proc/$pid, etc,
but did not see anything strange.

I did several other random tests, but nothing special...

My current guesses are:
1. Kernel issue that for some reason is summing all resources
   of every fork python does and quickly thinks it is out
   of memory; I also tried adding extra 8Gb of swap and that
   did not change anything (but did not test adding extra
   "real" memory...)
2. Was python rebuilt with gcc 4.8? What else was rebuilt?
   Rebuild with gcc 4.8 may have caused some regression, well,
   I had a simple one:
   http://gcc.gnu.org/bugzilla/show_bug.cgi?id=56143
3. It is a genuine python bug that got uncovered now.
   Particularly I do not like the:
     gc.disable()
     ...
     fork()
     ...
     gc.enable()
   sequence in subprocess._execute_child, but commenting
   that did not make any difference.
Comment 6 Paulo Andrade 2013-02-01 14:01:11 UTC 
Adding kernel-maint to CC.

Fully updated rawhide.

$ rpm -q kernel
kernel-3.8.0-0.rc3.git1.1.fc19.x86_64
kernel-3.8.0-0.rc4.git5.1.fc19.x86_64
kernel-3.8.0-0.rc5.git1.1.fc19.x86_64

$ uname -a
Linux localhost.localdomain 3.8.0-0.rc5.git1.1.fc19.x86_64 #1 SMP Tue Jan 29 18:34:46 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

Stepping into glibc, when the clone syscall fails I see this:

(gdb) 
117       _IO_list_lock ();
(gdb) 
126       pid_t parentpid = THREAD_GETMEM (THREAD_SELF, pid);
(gdb) 
127       THREAD_SETMEM (THREAD_SELF, pid, -parentpid);
(gdb) 
130       pid = ARCH_FORK ();
(gdb) p pid
$23 = <optimized out>
(gdb) p $rip
$24 = (void (*)()) 0x30338bcf54 <__libc_fork+132>
(gdb) x/20i 0x30338bcf54
=> 0x30338bcf54 <__libc_fork+132>:      mov    %fs:0x10,%r8
   0x30338bcf5d <__libc_fork+141>:      xor    %edx,%edx
   0x30338bcf5f <__libc_fork+143>:      lea    0x2d0(%r8),%r10
   0x30338bcf66 <__libc_fork+150>:      xor    %esi,%esi
   0x30338bcf68 <__libc_fork+152>:      mov    $0x1200011,%edi
   0x30338bcf6d <__libc_fork+157>:      mov    $0x38,%eax
   0x30338bcf72 <__libc_fork+162>:      syscall 
   0x30338bcf74 <__libc_fork+164>:      cmp    $0xfffffffffffff000,%rax
   0x30338bcf7a <__libc_fork+170>:      ja     0x30338bd0ab <__libc_fork+475>
   0x30338bcf80 <__libc_fork+176>:      test   %eax,%eax
   0x30338bcf82 <__libc_fork+178>:      mov    %eax,%r13d
   0x30338bcf85 <__libc_fork+181>:      jne    0x30338bd0c0 <__libc_fork+496>
   0x30338bcf8b <__libc_fork+187>:
    mov    0x2fff2e(%rip),%rax        # 0x3033bbcec0 <__fork_generation_pointer>
   0x30338bcf92 <__libc_fork+194>:      test   %rax,%rax
   0x30338bcf95 <__libc_fork+197>:      je     0x30338bcf9b <__libc_fork+203>
   0x30338bcf97 <__libc_fork+199>:      addq   $0x4,(%rax)
   0x30338bcf9b <__libc_fork+203>:      mov    %fs:0x2d0,%eax
   0x30338bcfa3 <__libc_fork+211>:      mov    %eax,%fs:0x2d4
   0x30338bcfab <__libc_fork+219>:      rdtsc  
   0x30338bcfad <__libc_fork+221>:      shl    $0x20,%rdx
(gdb) si
0x00000030338bcf5d      130       pid = ARCH_FORK ();
(gdb) 
0x00000030338bcf5f      130       pid = ARCH_FORK ();
(gdb) 
0x00000030338bcf66      130       pid = ARCH_FORK ();
(gdb) 
0x00000030338bcf68      130       pid = ARCH_FORK ();
(gdb) 
0x00000030338bcf6d      130       pid = ARCH_FORK ();
(gdb) p $rax
$25 = 4294957376
(gdb) si
0x00000030338bcf72      130       pid = ARCH_FORK ();
(gdb) p $rax
$26 = 56
(gdb) si
0x00000030338bcf74      130       pid = ARCH_FORK ();
(gdb) p $rax
$27 = -12


and from the code in sysdeps/unix/sysv/linux/x86_64/sysdep.h

# define INLINE_SYSCALL(name, nr, args...) \
  ({									      \
    unsigned long int resultvar = INTERNAL_SYSCALL (name, , nr, args);	      \
    if (__builtin_expect (INTERNAL_SYSCALL_ERROR_P (resultvar, ), 0))	      \
      {									      \
	__set_errno (INTERNAL_SYSCALL_ERRNO (resultvar, ));		      \
	resultvar = (unsigned long int) -1;				      \
      }									      \
    (long int) resultvar; })

the -12 is just about to become -1
(gdb) p resultvar
$30 = 18446744073709551604
(gdb) p (long)resultvar
$31 = -12


I am sorry I am not familiar enough with the kernel itself to follow
what happens in the syscall, but this may also help (with gdb still just
a few instructions after returning from the syscall):

$ cat /proc/meminfo 
MemTotal:        3998816 kB
MemFree:          209580 kB
Buffers:          184520 kB
Cached:          2093440 kB
SwapCached:         1248 kB
Active:          1520808 kB
Inactive:        1527480 kB
Active(anon):     375740 kB
Inactive(anon):   402740 kB
Active(file):    1145068 kB
Inactive(file):  1124740 kB
Unevictable:           0 kB
Mlocked:               0 kB
SwapTotal:       4030460 kB
SwapFree:        4017724 kB
Dirty:               264 kB
Writeback:             0 kB
AnonPages:        769312 kB
Mapped:            74340 kB
Shmem:              8152 kB
Slab:             634120 kB
SReclaimable:     559664 kB
SUnreclaim:        74456 kB
KernelStack:        2760 kB
PageTables:        15432 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:     6029868 kB
Committed_AS:    1613344 kB
VmallocTotal:   34359738367 kB
VmallocUsed:      366392 kB
VmallocChunk:   34359368812 kB
HardwareCorrupted:     0 kB
AnonHugePages:    180224 kB
HugePages_Total:       0
HugePages_Free:        0
HugePages_Rsvd:        0
HugePages_Surp:        0
Hugepagesize:       2048 kB
DirectMap4k:       85504 kB
DirectMap2M:     4067328 kB
Comment 7 Paulo Andrade 2013-02-01 17:51:37 UTC 
Just updated to latest fedora kernel, and now I see
something strange in dmesg when stepping in gdb.

$ uname -a
Linux localhost.localdomain 3.8.0-0.rc5.git2.1.fc19.x86_64 #1 SMP Wed Jan 30 17:52:10 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

dmesg strange messages:

[   33.370507] IPv6: ADDRCONF(NETDEV_CHANGE): em1: link becomes ready
[   97.505760] BUG: sleeping function called from invalid context at kernel/nsproxy.c:217
[   97.505767] in_atomic(): 0, irqs_disabled(): 1, pid: 1623, name: mock
[   97.505770] INFO: lockdep is turned off.
[   97.505773] irq event stamp: 0
[   97.505776] hardirqs last  enabled at (0): [<          (null)>]           (null)
[   97.505781] hardirqs last disabled at (0): [<ffffffff81063e38>] copy_process.part.22+0x5d8/0x1640
[   97.505791] softirqs last  enabled at (0): [<ffffffff81063e38>] copy_process.part.22+0x5d8/0x1640
[   97.505797] softirqs last disabled at (0): [<          (null)>]           (null)
[   97.505803] Pid: 1623, comm: mock Not tainted 3.8.0-0.rc5.git2.1.fc19.x86_64 #1
[   97.505805] Call Trace:
[   97.505815]  [<ffffffff8109f899>] __might_sleep+0x179/0x230
[   97.505821]  [<ffffffff81097847>] switch_task_namespaces+0x27/0x60
[   97.505826]  [<ffffffff81097890>] exit_task_namespaces+0x10/0x20
[   97.505832]  [<ffffffff81064692>] copy_process.part.22+0xe32/0x1640
[   97.505837]  [<ffffffff81064f95>] do_fork+0xa5/0x450
[   97.505845]  [<ffffffff816d6f47>] ? _raw_spin_unlock+0x27/0x40
[   97.505850]  [<ffffffff810653c6>] sys_clone+0x16/0x20
[   97.505857]  [<ffffffff816e0cf9>] stub_clone+0x69/0x90
[   97.505862]  [<ffffffff816e0919>] ? system_call_fastpath+0x16/0x1b
[  131.370252] BUG: sleeping function called from invalid context at kernel/nsproxy.c:217
[  131.370255] in_atomic(): 0, irqs_disabled(): 1, pid: 1679, name: mock
[  131.370257] INFO: lockdep is turned off.
[  131.370258] irq event stamp: 0
[  131.370259] hardirqs last  enabled at (0): [<          (null)>]           (null)
[  131.370261] hardirqs last disabled at (0): [<ffffffff81063e38>] copy_process.part.22+0x5d8/0x1640
[  131.370266] softirqs last  enabled at (0): [<ffffffff81063e38>] copy_process.part.22+0x5d8/0x1640
[  131.370268] softirqs last disabled at (0): [<          (null)>]           (null)
[  131.370270] Pid: 1679, comm: mock Not tainted 3.8.0-0.rc5.git2.1.fc19.x86_64 #1
[  131.370271] Call Trace:
[  131.370276]  [<ffffffff8109f899>] __might_sleep+0x179/0x230
[  131.370278]  [<ffffffff81097847>] switch_task_namespaces+0x27/0x60
[  131.370280]  [<ffffffff81097890>] exit_task_namespaces+0x10/0x20
[  131.370282]  [<ffffffff81064692>] copy_process.part.22+0xe32/0x1640
[  131.370284]  [<ffffffff81064f95>] do_fork+0xa5/0x450
[  131.370288]  [<ffffffff816d6f47>] ? _raw_spin_unlock+0x27/0x40
[  131.370290]  [<ffffffff810653c6>] sys_clone+0x16/0x20
[  131.370292]  [<ffffffff816e0cf9>] stub_clone+0x69/0x90
[  131.370295]  [<ffffffff816e0919>] ? system_call_fastpath+0x16/0x1b
[  279.608273] BUG: sleeping function called from invalid context at kernel/nsproxy.c:217
[  279.608280] in_atomic(): 0, irqs_disabled(): 1, pid: 1821, name: python
[  279.608283] INFO: lockdep is turned off.
[  279.608286] irq event stamp: 0
[  279.608288] hardirqs last  enabled at (0): [<          (null)>]           (null)
[  279.608293] hardirqs last disabled at (0): [<ffffffff81063e38>] copy_process.part.22+0x5d8/0x1640
[  279.608303] softirqs last  enabled at (0): [<ffffffff81063e38>] copy_process.part.22+0x5d8/0x1640
[  279.608309] softirqs last disabled at (0): [<          (null)>]           (null)
[  279.608315] Pid: 1821, comm: python Not tainted 3.8.0-0.rc5.git2.1.fc19.x86_64 #1
[  279.608318] Call Trace:
[  279.608328]  [<ffffffff8109f899>] __might_sleep+0x179/0x230
[  279.608333]  [<ffffffff81097847>] switch_task_namespaces+0x27/0x60
[  279.608339]  [<ffffffff81097890>] exit_task_namespaces+0x10/0x20
[  279.608344]  [<ffffffff81064692>] copy_process.part.22+0xe32/0x1640
[  279.608350]  [<ffffffff81064f95>] do_fork+0xa5/0x450
[  279.608357]  [<ffffffff816d538e>] ? __schedule+0x43e/0x9d0
[  279.608363]  [<ffffffff810653c6>] sys_clone+0x16/0x20
[  279.608369]  [<ffffffff816e0cf9>] stub_clone+0x69/0x90
[  279.608374]  [<ffffffff816e0b40>] ? tracesys+0xdd/0xe2
[  326.838629] BUG: sleeping function called from invalid context at kernel/nsproxy.c:217
[  326.838636] in_atomic(): 0, irqs_disabled(): 1, pid: 1821, name: python
[  326.838639] INFO: lockdep is turned off.
[  326.838642] irq event stamp: 0
[  326.838645] hardirqs last  enabled at (0): [<          (null)>]           (null)
[  326.838649] hardirqs last disabled at (0): [<ffffffff81063e38>] copy_process.part.22+0x5d8/0x1640
[  326.838660] softirqs last  enabled at (0): [<ffffffff81063e38>] copy_process.part.22+0x5d8/0x1640
[  326.838665] softirqs last disabled at (0): [<          (null)>]           (null)
[  326.838671] Pid: 1821, comm: python Not tainted 3.8.0-0.rc5.git2.1.fc19.x86_64 #1
[  326.838674] Call Trace:
[  326.838684]  [<ffffffff8109f899>] __might_sleep+0x179/0x230
[  326.838689]  [<ffffffff81097847>] switch_task_namespaces+0x27/0x60
[  326.838695]  [<ffffffff81097890>] exit_task_namespaces+0x10/0x20
[  326.838700]  [<ffffffff81064692>] copy_process.part.22+0xe32/0x1640
[  326.838706]  [<ffffffff81064f95>] do_fork+0xa5/0x450
[  326.838713]  [<ffffffff816d6f47>] ? _raw_spin_unlock+0x27/0x40
[  326.838719]  [<ffffffff810653c6>] sys_clone+0x16/0x20
[  326.838725]  [<ffffffff816e0cf9>] stub_clone+0x69/0x90
[  326.838730]  [<ffffffff816e0b40>] ? tracesys+0xdd/0xe2
Comment 8 Shawn Starr 2013-02-05 20:47:56 UTC 
same for: 3.8.0-0.rc6.git1.1.fc19.x86_64

# mock -v init

....

    preexec_fn = preexec,
  File "/usr/lib64/python2.7/subprocess.py", line 679, in __init__
    errread, errwrite)
  File "/usr/lib64/python2.7/subprocess.py", line 1143, in _execute_child
    self.pid = os.fork()
OSError: [Errno 12] Cannot allocate memory


from dmesg:

[   89.143660] BUG: sleeping function called from invalid context at kernel/nsproxy.c:217
[   89.143729] in_atomic(): 0, irqs_disabled(): 1, pid: 1329, name: mock
[   89.143776] no locks held by mock/1329.
[   89.143778] irq event stamp: 324562
[   89.143781] hardirqs last  enabled at (324561): [<ffffffff81163a8d>] get_page_from_freelist+0x51d/0x990
[   89.143791] hardirqs last disabled at (324562): [<ffffffff816daa9d>] _raw_spin_lock_irq+0x1d/0x60
[   89.143798] softirqs last  enabled at (323936): [<ffffffff81070438>] __do_softirq+0x168/0x3d0
[   89.143804] softirqs last disabled at (323931): [<ffffffff816e587c>] call_softirq+0x1c/0x30
[   89.143811] Pid: 1329, comm: mock Not tainted 3.8.0-0.rc6.git1.1.fc19.x86_64 #1
[   89.143814] Call Trace:
[   89.143823]  [<ffffffff8109f8d9>] __might_sleep+0x179/0x230
[   89.143828]  [<ffffffff81097887>] switch_task_namespaces+0x27/0x60
[   89.143833]  [<ffffffff810978d0>] exit_task_namespaces+0x10/0x20
[   89.143839]  [<ffffffff81064692>] copy_process.part.22+0xe32/0x1640
[   89.143844]  [<ffffffff81064f95>] do_fork+0xa5/0x450
[   89.143849]  [<ffffffff816db718>] ? retint_swapgs+0x13/0x1b
[   89.143854]  [<ffffffff810653c6>] sys_clone+0x16/0x20
[   89.143859]  [<ffffffff816e48b9>] stub_clone+0x69/0x90
[   89.143864]  [<ffffffff816e44d9>] ? system_call_fastpath+0x16/0x1b


boot cmdline: 
BOOT_IMAGE=/vmlinuz-3.8.0-0.rc6.git1.1.fc19.x86_64 root=/dev/mapper/vg_panic-lv_root ro quiet rhgb SYSFONT=latarcyrheb-sun16 LANG=en_US.UTF-8 KEYTABLE=us slub_debug=-

Linux panic.sh0n.net 3.8.0-0.rc6.git1.1.fc19.x86_64 #1 SMP Mon Feb 4 15:11:02 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux
Comment 9 Adam Williamson 2013-02-07 05:59:29 UTC 
Seeing the sam here. This is a somewhat major problem for people working on rawhide.
Comment 10 Josh Boyer 2013-02-07 15:10:39 UTC 
Can someone go through the rawhide kernel builds and tell us which was the last working 3.8.0-0.rcX kernel, and which was the first to show this issue?  Also, is "mock -v init" all that is needed to see the issue?

The nsproxy.c error is irritating, but that is kind of irrelevant to the problem.
Comment 11 Michael Schwendt 2013-02-07 17:29:45 UTC 
The oldest one already:

  File "/usr/lib64/python2.7/subprocess.py", line 1143, in _execute_child 
      self.pid = os.fork()
  OSError: [Errno 12] Cannot allocate memory
  [ms19@faldor ~]$ uname -r
  3.8.0-0.rc2.git1.1.fc19.x86_64

# yum.log
Jan 19 10:41:02 Installed: kernel-3.7.2-204.fc18.x86_64
Jan 22 00:36:12 Updated: kernel-headers-3.8.0-0.rc4.git1.1.fc19.x86_64
Jan 22 00:49:12 Updated: libreport-plugin-kerneloops-2.0.20-1.fc19.x86_64
Jan 22 00:49:13 Updated: abrt-addon-kerneloops-2.0.20-1.fc19.x86_64
Jan 22 00:56:38 Installed: kernel-3.8.0-0.rc4.git1.1.fc19.x86_64
Comment 12 Michael Schwendt 2013-02-07 17:30:50 UTC 
> is "mock -v init" all that is needed to see the issue?

Yes, "mock --init" is sufficient for testing it.
Comment 13 Paulo Andrade 2013-02-07 17:43:03 UTC 
I noticed the problem after updating 12th January,
and rarely will go more than 2 weeks without fully
updating rawhide.

I think it might be a gcc-4.8 issue, so, I suggest
testing the same kernel built with gcc 4.7 and
4.8, as gcc was updated to 4.8 around the time the
issue started happening.
Comment 14 Michael Schwendt 2013-02-07 18:39:06 UTC 
> 12th January

The kernel-3.8.0-0.rc2.git1.1.fc19 I tried in comment 11 was built on Jan 7th.

The first gcc 4.8.0 for Rawhide is listed for 2013-01-22:
http://koji.fedoraproject.org/koji/buildinfo?buildID=379804
gcc-4.8.0-0.4.fc19

My only Rawhide installation is an upgrade from F18 made on Jan 22nd, so I cannot comment on breakage before that.

However, I've curiously installed F18's kernel-3.7.2-201.fc18.x86_64 now, and running it, Mock succeeds.
Comment 15 Josh Boyer 2013-02-07 21:09:03 UTC 
Right, 3.8.0-rc2.git1.1 was built with gcc 4.7.  It also happens to be the first 3.8 kernel we built in koji.  That's going to make it harder to poke at.
Comment 16 Josh Boyer 2013-02-08 18:41:05 UTC 
I've bisected this down to:

commit 50804fe3737ca6a5942fdc2057a18a8141d00141
Author: Eric W. Biederman <ebiederm>
Date:   Tue Mar 2 15:41:50 2010 -0800

    pidns: Support unsharing the pid namespace.
    

I have no idea why it's causing mock issues yet.  Clark, you might want to hop into the upstream thread.
Comment 17 Josh Boyer 2013-02-08 21:59:35 UTC 
After discussion with upstream, this appears to be a case of mock using the CLONE_NEWPID flag in the unshare system call without realizing what that does and upstream now actually supporting that call.  Clark is going to poke at this a bit.

The upstream thread is here for those curious:

http://thread.gmane.org/gmane.linux.kernel/1438006
Comment 18 Clark Williams 2013-02-22 22:11:21 UTC 
Created attachment 701377 [details]
experiment with unshare() and CLONE_NEWPID

Possible logic for actually using CLONE_NEWPID correctly.
Comment 19 Clark Williams 2013-02-22 22:58:34 UTC 
I've removed the CLONE_NEWPID bit from the calls to unshare(2) for the time being. The next release of mock will not try and unshare the PID namespace but I'm not giving up since I talked to Eric Biederman about how it should be used. 

queued for next release
Comment 20 Fedora Update System 2013-02-26 22:17:03 UTC 
mock-1.1.29-1.fc17 has been submitted as an update for Fedora 17.
https://admin.fedoraproject.org/updates/mock-1.1.29-1.fc17
Comment 21 Fedora Update System 2013-02-26 22:17:47 UTC 
mock-1.1.29-1.el6 has been submitted as an update for Fedora EPEL 6.
https://admin.fedoraproject.org/updates/mock-1.1.29-1.el6
Comment 22 Fedora Update System 2013-02-26 22:18:20 UTC 
mock-1.1.29-1.fc18 has been submitted as an update for Fedora 18.
https://admin.fedoraproject.org/updates/mock-1.1.29-1.fc18
Comment 23 Fedora Update System 2013-02-27 18:04:19 UTC 
Package mock-1.1.29-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.29-1.el6'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-EPEL-2013-0476/mock-1.1.29-1.el6
then log in and leave karma (feedback).
Comment 24 Mathieu Bridon 2013-03-03 09:04:09 UTC 
I just tested this on latest Rawhide, and it works perfectly, as it always has. :)

Thanks a lot Clark!
Comment 25 Fedora Update System 2013-03-04 22:43:58 UTC 
mock-1.1.29-1.fc18 has been pushed to the Fedora 18 stable repository.  If problems still persist, please make note of it in this bug report.
Comment 26 Fedora Update System 2013-03-23 23:54:57 UTC 
mock-1.1.29-1.fc17 has been pushed to the Fedora 17 stable repository.  If problems still persist, please make note of it in this bug report.
Comment 27 Johnny Hughes 2013-04-05 13:05:16 UTC 
(In reply to comment #23)
> Package mock-1.1.29-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.29-1.el6'
> as soon as you are able to.
> Please go to the following url:
> https://admin.fedoraproject.org/updates/FEDORA-EPEL-2013-0476/mock-1.1.29-1.
> el6
> then log in and leave karma (feedback).

I was having this issue running mock on EL6 with a 3.8.5 kernel.  Upgraded to the latest testing mock for EPEL (Now 1.1.30) and the issue is gone.
Note You need to log in before you can comment on or make changes to this bug.