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
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.
Same problem here.
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.
I'd have to say this is a kernel issue. not much I can do about the SLAB allocator refusing to allocate memory.
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.
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
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
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
Seeing the sam here. This is a somewhat major problem for people working on rawhide.
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.
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
> is "mock -v init" all that is needed to see the issue? Yes, "mock --init" is sufficient for testing it.
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.
> 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.
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.
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.
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
Created attachment 701377 [details] experiment with unshare() and CLONE_NEWPID Possible logic for actually using CLONE_NEWPID correctly.
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
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
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
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
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 just tested this on latest Rawhide, and it works perfectly, as it always has. :) Thanks a lot Clark!
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.
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.
(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.