GNOME Bugzilla – Bug 774141
pipe2 call without O_CLOEXEC flag causes Chromium startup failure
Last modified: 2018-05-24 19:11:55 UTC
Chromium fails to start fully due to a race condition caused by missing O_CLOEXEC flags in glib code. See https://bugs.chromium.org/p/chromium/issues/detail?id=662335 ... futex(0x7fdc770e04c8, FUTEX_WAKE_PRIVATE, 2147483647) = 0 mkdir("/home/markus/.cache", 0700) = -1 EEXIST (File exists) futex(0x7fdc770e04c8, FUTEX_WAKE_PRIVATE, 2147483647) = 0 stat("/home/markus/.cache/bus", 0x7fff94eb0850) = -1 ENOENT (No such file or directory) getresuid([1000], [1000], [1000]) = 0 getresgid([1000], [1000], [1000]) = 0 futex(0x7fdc770e04c8, FUTEX_WAKE_PRIVATE, 2147483647) = 0 open("/var/lib/dbus/machine-id", O_RDONLY) = 77 fstat(77, {st_mode=S_IFREG|0644, st_size=33, ...}) = 0 read(77, "500fac476577f8a0a3d748f800000095"..., 33) = 33 close(77) = 0 pipe2([77, 78], 0) = 0 pipe2([79, 80], 0) = 0 pipe2([81, 82], O_CLOEXEC) = 0 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fdc7031f050) = 19060 close(78) = 0 close(80) = 0 close(82) = 0 read(77, << hangs here >> strace -f shows: 30323 pipe2([77, 78], 0) = 0 30323 pipe2( <unfinished ...> 30376 mprotect(0x7f9f60f35000, 225280, PROT_READ <unfinished ...> 30323 <... pipe2 resumed> [79, 80], 0) = 0 30376 <... mprotect resumed> ) = 0 30323 pipe2([81, 82], O_CLOEXEC) = 0 30323 clone( <unfinished ...> 30376 futex(0x7f9f5e2472c0, FUTEX_WAKE_PRIVATE, 2147483647) = 0 30347 <... fdatasync resumed> ) = 0 30376 munmap(0x7f9f6934a000, 163087) = 0 30376 fcntl(125, F_DUPFD_CLOEXEC, 3) = 126 30376 fstat(126, {st_mode=S_IFCHR|0660, st_rdev=makedev(226, 0), ...}) = 0 30376 readlink("/sys/dev/char/226:0/device/subsystem", "../../../../bus/pci", 4096) = 19 30376 open("/dev/dri", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 127 30376 fstat(127, {st_mode=S_IFDIR|0755, st_size=100, ...}) = 0 30376 getdents(127, /* 5 entries */, 32768) = 144 30376 stat("/dev/dri/card0", {st_mode=S_IFCHR|0660, st_rdev=makedev(226, 0), ...}) = 0 30376 readlink("/sys/dev/char/226:0/device/subsystem", "../../../../bus/pci", 4096) = 19 30376 open("/sys/dev/char/226:0/device/uevent", O_RDONLY <unfinished ...> 30347 ftruncate(75, 0 <unfinished ...> 30390 set_robust_list(0x7f1500b2cbe0, 24) = 0 30347 <... ftruncate resumed> ) = 0 30323 <... clone resumed> child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f1500b2cbd0) = 30390 30347 fdatasync(75 <unfinished ...> 30390 rt_sigaction(SIGCHLD, {SIG_DFL, [CHLD], SA_RESTORER|SA_RESTART, 0x7f1504149350}, {0x5571715363c0, [], SA_RESTORER, 0x7f1507cd8c90}, 8) = 0 30390 rt_sigaction(SIGINT, {SIG_DFL, [INT], SA_RESTORER|SA_RESTART, 0x7f1504149350}, {0x557171536660, [], SA_RESTORER, 0x7f1507cd8c90}, 8) = 0 30390 rt_sigaction(SIGTERM, {SIG_DFL, [TERM], SA_RESTORER|SA_RESTART, 0x7f1504149350}, {0x5571715366a0, [], SA_RESTORER, 0x7f1507cd8c90}, 8) = 0 30390 rt_sigaction(SIGHUP, {SIG_DFL, [HUP], SA_RESTORER|SA_RESTART, 0x7f1504149350}, {0x557171536640, [], SA_RESTORER, 0x7f1507cd8c90}, 8) = 0 30390 rt_sigaction(SIGPIPE, {SIG_DFL, [PIPE], SA_RESTORER|SA_RESTART, 0x7f1504149350}, {SIG_IGN, [], SA_RESTORER, 0x7f1507cd8c90}, 8) = 0 30390 close(77) = 0 30390 close(79) = 0 30390 close(81) = 0 30323 close(78) = 0 30390 open("/proc/self/fd", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC <unfinished ...> 30323 close(80) = 0 30390 <... open resumed> ) = 77 30323 close(82 <unfinished ...> 30390 fstat(77, <unfinished ...> 30323 <... close resumed> ) = 0 30390 <... fstat resumed> {st_mode=S_IFDIR|0500, st_size=0, ...}) = 0 30323 read(77, <unfinished ...> The read(77,...) happens after the child has already closed and reused the descriptor. Adding the O_CLOEXEC flag to the pipe2 calls fixes the issue.
Hmm, O_CLOEXEC isn't enough it still hangs from time to time, but much more rarely. It looks like the bug is in: ./glib/gspawn.c: fork_exec_with_pipes() 6663 clone( <unfinished ...> 6679 <... fdatasync resumed> ) = 0 6718 <... stat resumed> {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0 6663 <... clone resumed> child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f1fa8c0cbd0) = 6730 6708 munmap(0x7f49f16ed000, 162637 <unfinished ...> 6679 close(77 <unfinished ...> 6663 close(79 <unfinished ...> 6730 set_robust_list(0x7f1fa8c0cbe0, 24 <unfinished ...> 6663 <... close resumed> ) = 0 6730 <... set_robust_list resumed> ) = 0 6663 close(81 <unfinished ...> 6708 <... munmap resumed> ) = 0 6663 <... close resumed> ) = 0 6679 <... close resumed> ) = 0 6679 pwrite64(76, "\331\325\5\371 \241c\327\0\0\0\3", 12, 0 <unfinished ...> 6663 close(83 <unfinished ...> 6708 fcntl(125, F_DUPFD_CLOEXEC, 3 <unfinished ...> 6718 stat("/etc/localtime", <unfinished ...> 6663 <... close resumed> ) = 0 6708 <... fcntl resumed> ) = 126 6663 read(78, <unfinished ...> 6718 <... stat resumed> {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0 6663 <... read resumed> 0x7ffd182a6c60, 8) = -1 EAGAIN (Resource temporarily unavailable) 6708 fstat(126, <unfinished ...> 6718 stat("/etc/localtime", <unfinished ...> 6708 <... fstat resumed> {st_mode=S_IFCHR|0660, st_rdev=makedev(226, 0), ...}) = 0 6718 <... stat resumed> {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0 6708 readlink("/sys/dev/char/226:0/device/subsystem", <unfinished ...> 6679 <... pwrite64 resumed> ) = 12 6718 stat("/etc/localtime", <unfinished ...> 6679 fdatasync(76 <unfinished ...> 6718 <... stat resumed> {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0 6663 futex(0x7f1fb00cd4c8, FUTEX_WAKE_PRIVATE, 2147483647 <unfinished ...> 6708 <... readlink resumed> "../../../../bus/pci", 4096) = 19 6663 <... futex resumed> ) = 0 6718 stat("/etc/localtime", <unfinished ...> 6708 open("/dev/dri", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC <unfinished ...> 6718 <... stat resumed> {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0 6663 open("/usr/share/locale/en_US.UTF-8/LC_MESSAGES/glib20.mo", O_RDONLY <unfinished ...> 6730 rt_sigaction(SIGCHLD, {SIG_DFL, [CHLD], SA_RESTORER|SA_RESTART, 0x7f1fac22c350}, <unfinished ...> 6663 <... open resumed> ) = -1 ENOENT (No such file or directory) 6730 <... rt_sigaction resumed> {0x562d3c5635e0, [], SA_RESTORER, 0x7f1fafd83c90}, 8) = 0 6663 open("/usr/share/locale/en_US.utf8/LC_MESSAGES/glib20.mo", O_RDONLY <unfinished ...> 6730 rt_sigaction(SIGINT, {SIG_DFL, [INT], SA_RESTORER|SA_RESTART, 0x7f1fac22c350}, <unfinished ...> 6663 <... open resumed> ) = -1 ENOENT (No such file or directory) 6730 <... rt_sigaction resumed> {0x562d3c563880, [], SA_RESTORER, 0x7f1fafd83c90}, 8) = 0 6663 open("/usr/share/locale/en_US/LC_MESSAGES/glib20.mo", O_RDONLY <unfinished ...> 6730 rt_sigaction(SIGTERM, {SIG_DFL, [TERM], SA_RESTORER|SA_RESTART, 0x7f1fac22c350}, <unfinished ...> 6663 <... open resumed> ) = -1 ENOENT (No such file or directory) 6730 <... rt_sigaction resumed> {0x562d3c5638c0, [], SA_RESTORER, 0x7f1fafd83c90}, 8) = 0 6663 open("/usr/share/locale/en.UTF-8/LC_MESSAGES/glib20.mo", O_RDONLY <unfinished ...> 6730 rt_sigaction(SIGHUP, {SIG_DFL, [HUP], SA_RESTORER|SA_RESTART, 0x7f1fac22c350}, <unfinished ...> 6663 <... open resumed> ) = -1 ENOENT (No such file or directory) 6730 <... rt_sigaction resumed> {0x562d3c563860, [], SA_RESTORER, 0x7f1fafd83c90}, 8) = 0 6663 open("/usr/share/locale/en.utf8/LC_MESSAGES/glib20.mo", O_RDONLY <unfinished ...> 6730 rt_sigaction(SIGPIPE, {SIG_DFL, [PIPE], SA_RESTORER|SA_RESTART, 0x7f1fac22c350}, <unfinished ...> 6663 <... open resumed> ) = -1 ENOENT (No such file or directory) 6730 <... rt_sigaction resumed> {SIG_IGN, [], SA_RESTORER, 0x7f1fafd83c90}, 8) = 0 6663 open("/usr/share/locale/en/LC_MESSAGES/glib20.mo", O_RDONLY <unfinished ...> 6730 close(78 <unfinished ...> 6718 stat("/etc/localtime", <unfinished ...> 6663 <... open resumed> ) = -1 ENOENT (No such file or directory) 6730 <... close resumed> ) = 0 6718 <... stat resumed> {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0 6730 close(80 <unfinished ...> 6708 <... open resumed> ) = 127 6663 wait4(6730, <unfinished ...> 6730 <... close resumed> ) = 0 6718 stat("/etc/localtime", <unfinished ...> 6730 close(82 <unfinished ...> 6718 <... stat resumed> {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0 6730 <... close resumed> ) = 0 6708 fstat(127, <unfinished ...> 6718 stat("/etc/localtime", <unfinished ...> 6708 <... fstat resumed> {st_mode=S_IFDIR|0755, st_size=100, ...}) = 0 6730 open("/proc/self/fd", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC <unfinished ...> 6718 <... stat resumed> {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0 6708 getdents(127, <unfinished ...> 6730 <... open resumed> ) = 78 6718 stat("/etc/localtime", <unfinished ...> 6730 fstat(78, <unfinished ...> 6718 <... stat resumed> {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0 6730 <... fstat resumed> {st_mode=S_IFDIR|0500, st_size=0, ...}) = 0 6718 stat("/etc/localtime", <unfinished ...> 6708 <... getdents resumed> /* 5 entries */, 32768) = 144 6718 <... stat resumed> {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0 6730 futex(0x562d43d5bea0, FUTEX_WAIT_PRIVATE, 2, {0, 86084} <unfinished ...> Here 6663 is the parent and it waits on its child 6730 forever.
-- GitLab Migration Automatic Message -- This bug has been migrated to GNOME's GitLab instance and has been closed from further activity. You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.gnome.org/GNOME/glib/issues/1219.