[debbugs-tracker] bug#36007: closed (double close() of of=file if receiving SIGINT during fdatasync())

[GNU bug Tracking System]

Your message dated Thu, 30 May 2019 13:56:04 -0700
with message-id <address@hidden>
and subject line Re: bug#36007: double close() of of=file if receiving SIGINT 
during fdatasync()
has caused the debbugs.gnu.org bug report #36007,
regarding double close() of of=file if receiving SIGINT during fdatasync()
to be marked as done.

(If you believe you have received this mail in error, please contact
address@hidden)


-- 
36007: http://debbugs.gnu.org/cgi/bugreport.cgi?bug=36007
GNU Bug Tracking System
Contact address@hidden with problems

--- Begin Message --- Subject: double close() of of=file if receiving SIGINT during fdatasync() Date: Thu, 30 May 2019 17:38:16 +0200

i think there is a double-close() bug that causes dd to try to close input file twice if it receives a SIGINT during fdatasync(), 

it seems easy to reproduce on a slow block device (the issue was noticed on a 5400RPM harddrive), but i have not been able to reproduce it on a SSD (likely because fdatasync() finishes too fast, i didn't try very hard. like, i suppose i could have hooked fdatasync and made it slow on purpose, but i didn't spend that much time/energy on trying),

anyway, the bug seems to boil down to somehow cleanup() is being called twice

command issued:

time strace dd if=/dev/zero of=/dev/sda4 bs=10M count=10 iflag=fullblock conv=fdatasync >stdout 2>stderr  

dd version: 

address@hidden:/dev# dd --version
dd (coreutils) 8.30
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <https://gnu.org/licenses/gpl.html>.
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.

Written by Paul Rubin, David MacKenzie, and Stuart Kemp.


script log (corrupted when pasted, strictly speaking, but i don't think anything of value was lost. if you want an actual 100% intact log, i can send you a base64 copy if you want, but again i don't think anything of value was lost)

Script started on 2019-05-30 09:39:45-04:00 [TERM="xterm" TTY="/dev/pts/1" COLUMNS="194" LINES="41"]
address@hidden:/dev# exit pastebinit foo.log
[C [C [C [C [C [C [C [C [C [C [C [C [C [5Pscript foo.log [3Prm foo.log address@hidden [C [C [C [C [C [C [C [C [C [1Pcat [C [C [C [C [C [C [C [C [C script foo.log ls [K cat stderr out time strace dd if=/dev/zero of=/dev/sda4 bs=10M count=10 iflag=fullblock conv=fdatasync >stdout 2>stderr
execve("/usr/bin/dd", ["dd", "if=/dev/zero", "of=/dev/sda4", "bs=10M", "count=10", "iflag=fullblock", "conv=fdatasync"], 0x7fffffffe690 /* 18 vars */) = 0
brk(NULL)                               = 0x555555568000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=20223, ...}) = 0
mmap(NULL, 20223, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7ffff7fcb000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260A\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1824496, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ffff7fc9000
mmap(NULL, 1837056, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ffff7e08000
mprotect(0x7ffff7e2a000, 1658880, PROT_NONE) = 0
mmap(0x7ffff7e2a000, 1343488, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x22000) = 0x7ffff7e2a000
mmap(0x7ffff7f72000, 311296, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16a000) = 0x7ffff7f72000
mmap(0x7ffff7fbf000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b6000) = 0x7ffff7fbf000
mmap(0x7ffff7fc5000, 14336, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7ffff7fc5000
close(3)                                = 0
arch_prctl(ARCH_SET_FS, 0x7ffff7fca580) = 0
mprotect(0x7ffff7fbf000, 16384, PROT_READ) = 0
mprotect(0x555555566000, 4096, PROT_READ) = 0
mprotect(0x7ffff7ffc000, 4096, PROT_READ) = 0
munmap(0x7ffff7fcb000, 20223)           = 0
rt_sigaction(SIGINT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGUSR1, {sa_handler=0x555555558430, sa_mask=[INT USR1], sa_flags=SA_RESTORER, sa_restorer=0x7ffff7e3f840}, NULL, 8) = 0
rt_sigaction(SIGINT, {sa_handler=0x555555558420, sa_mask=[INT USR1], sa_flags=SA_RESTORER|SA_NODEFER|SA_RESETHAND, sa_restorer=0x7ffff7e3f840}, NULL, 8) = 0
brk(NULL)                               = 0x555555568000
brk(0x555555589000)                     = 0x555555589000
openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=3031616, ...}) = 0
mmap(NULL, 3031616, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7ffff7b23000
close(3)                                = 0
openat(AT_FDCWD, "/dev/zero", O_RDONLY) = 3
dup2(3, 0)                              = 0
close(3)                                = 0
lseek(0, 0, SEEK_CUR)                   = 0
openat(AT_FDCWD, "/dev/sda4", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
dup2(3, 1)                              = 1
close(3)                                = 0
mmap(NULL, 10498048, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ffff7120000
read(0, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
write(1, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
read(0, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
write(1, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
read(0, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
write(1, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
read(0, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
write(1, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
read(0, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
write(1, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
read(0, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
write(1, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
read(0, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
write(1, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
read(0, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
write(1, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
read(0, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
write(1, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
read(0, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
write(1, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10485760) = 10485760
fdatasync(1)                            = 0
--- SIGINT {si_signo=SIGINT, si_code=SI_USER, si_pid=1399, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
close(0)                                = 0
close(1)                                = 0
openat(AT_FDCWD, "/usr/share/locale/locale.alias", O_RDONLY|O_CLOEXEC) = 0
fstat(0, {st_mode=S_IFREG|0644, st_size=2995, ...}) = 0
read(0, "# Locale name alias data base.\n#"..., 4096) = 2995
read(0, "", 4096)                       = 0
close(0)                                = 0
openat(AT_FDCWD, "/usr/share/locale/en_CA/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
write(2, "10+0 records in\n10+0 records out"..., 3310+0 records in
10+0 records out
) = 33
write(2, "104857600 bytes (105 MB, 100 MiB"..., 62104857600 bytes (105 MB, 100 MiB) copied, 1.94798 s, 53.8 MB/s) = 62
write(2, "\n", 1
)                       = 1
rt_sigprocmask(SIG_BLOCK, [INT USR1], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
close(0)                                = -1 EBADF (Bad file descriptor)
write(2, "dd: ", 4dd: )                     = 4
write(2, "closing input file '/dev/zero'", 30closing input file '/dev/zero') = 30
openat(AT_FDCWD, "/usr/share/locale/en_CA/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
write(2, ": Bad file descriptor", 21: Bad file descriptor)   = 21
write(2, "\n", 1
)                       = 1
close(2)                                = 0
exit_group(1)                           = ?
+++ exited with 1 +++

real 0m1.955s
user 0m0.001s
sys 0m0.201s
address@hidden:/dev# exit
exit

Script done on 2019-05-30 09:40:05-04:00 [COMMAND_EXIT_CODE="1"]

--- End Message ---

--- Begin Message --- Subject: Re: bug#36007: double close() of of=file if receiving SIGINT during fdatasync() Date: Thu, 30 May 2019 13:56:04 -0700 User-agent: Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101 Thunderbird/60.7.0 Thanks for reporting the bug. I installed the attached patch into the development version on Savannah, to fix the bug you reported along with a closely related bug that I found when looking into your problem. Please give this patch a try at your convenience.

0001-dd-be-more-careful-about-signal-handling.patch
Description: Text Data

--- End Message ---