GNU bug report logs - #36007
double close() of of=file if receiving SIGINT during fdatasync()

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 36007 in the body.
You can then email your comments to 36007 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Hans Henrik Bergan <divinity76 <at> gmail.com>
To: bug-coreutils <at> gnu.org
Subject: double close() of of=file if receiving SIGINT during fdatasync()
Date: Thu, 30 May 2019 17:38:16 +0200

[Message part 1 (text/plain, inline)]

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:
root <at> 1:/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"]
root <at> 1:/dev# exit pastebinit foo.log
[C [C [C [C [C [C [C [C [C [C [C [C [C [5Pscript foo.log [3Prm foo.log
[2 <at> nano [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
root <at> 1:/dev# exit
exit

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

[Message part 2 (text/html, inline)]

Message #10 received at 36007-done <at> debbugs.gnu.org (full text, mbox):

From: Paul Eggert <eggert <at> cs.ucla.edu>
To: Hans Henrik Bergan <divinity76 <at> gmail.com>, 36007-done <at> debbugs.gnu.org
Subject: Re: bug#36007: double close() of of=file if receiving SIGINT during
 fdatasync()
Date: Thu, 30 May 2019 13:56:04 -0700

[Message part 1 (text/plain, inline)]

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 (text/x-patch, attachment)]

Message #13 received at 36007-done <at> debbugs.gnu.org (full text, mbox):

From: Hans Henrik Bergan <divinity76 <at> gmail.com>
To: Paul Eggert <eggert <at> cs.ucla.edu>
Cc: 36007-done <at> debbugs.gnu.org
Subject: Re: bug#36007: double close() of of=file if receiving SIGINT during
 fdatasync()
Date: Thu, 30 May 2019 23:50:30 +0200

[Message part 1 (text/plain, inline)]

the issue does not reproduce on a current git master build of dd (
commit 00d72e6122d37bbc32ef0e057c1e847fd8129133 )
, good job :)

(dd is an old build, ./dd is a git master build)
root <at> 1:/temp/coreutils/src# dd if=/dev/zero of=/dev/sda4 bs=10M count=100
iflag=fullblock conv=fdatasync
^C100+0 records in
100+0 records out
1048576000 bytes (1.0 GB, 1000 MiB) copied, 17.3542 s, 60.4 MB/s
dd: closing input file '/dev/zero': Bad file descriptor
root <at> 1:/temp/coreutils/src#
root <at> 1:/temp/coreutils/src#
root <at> 1:/temp/coreutils/src# ./dd if=/dev/zero of=/dev/sda4 bs=10M count=100
iflag=fullblock conv=fdatasync
^C100+0 records in
100+0 records out
1048576000 bytes (1.0 GB, 1000 MiB) copied, 19.0614 s, 55.0 MB/s
root <at> 1:/temp/coreutils/src#



On Thu, 30 May 2019 at 22:56, Paul Eggert <eggert <at> cs.ucla.edu> wrote:

> 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.
>

[Message part 2 (text/html, inline)]

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.