bugGNU Screen - Bugs: bug #55618, Closing half a million file...

 
 

bug #55618: Closing half a million file descriptors on startup

Submitter:  Lukas Waymann <meribold>
Submitted:  Thu 31 Jan 2019 03:30:40 PM UTC
   
 
Category:  None Severity:  3 - Normal
Priority:  * 5 - Normal Status:  None
Privacy:  Public Assigned to:  None
Open/Closed:  Open Release:  None
Fixed Release:  4.7.0 Planned Release:  None
Work Required:  None
* Mandatory Fields

Add a New Comment Rich Markup
   

Jump to the original submission

Sun 03 Nov 2019 06:57:52 PM UTC, comment #8: 

It is much better, thanks a lot!


root@likhachev:~# time screen --version
Screen version 4.07.00 (GNU) 02-Oct-19

real    0m0,001s
user    0m0,001s
sys     0m0,000s
root@likhachev:~# ulimit -n 1024000
root@likhachev:~# time screen --version
Screen version 4.07.00 (GNU) 02-Oct-19

real    0m0,021s
user    0m0,004s
sys     0m0,017s
root@likhachev:~#


P.S. '02-Oct-19' looks being added in patchlevel.h, leaved it as is. screen is built 5 minutes ago.

Likhachev Vasiliy <lilalkor>
Sat 02 Nov 2019 10:34:41 PM UTC, comment #7: 

Original bug report was about screen using hard limit instead of soft limit, but oh well...
Can you try with following patch:
https://lists.gnu.org/archive/html/screen-devel/2019-11/msg00002.html

Amadeusz Sławiński <amade>
Group administrator
Tue 15 Oct 2019 11:39:10 AM UTC, comment #6: 

Hello!

Have the same issue on Arch Linux with latest version.

root@likhachev:~# ulimit -n 1024
root@likhachev:~# time screen --version
Screen version 4.07.00 (GNU) 02-Oct-19

real    0m0,005s
user    0m0,000s
sys     0m0,005s
root@likhachev:~# ulimit -n 1024000
root@likhachev:~# time screen --version
Screen version 4.07.00 (GNU) 02-Oct-19

real    0m0,401s
user    0m0,270s
sys     0m0,130s


And strace shows the same behavior:

62445 10:49:42 munmap(0x7f0a7308a000, 290848) = 0 <0.000013>
62445 10:49:42 prlimit64(0, RLIMIT_NOFILE, NULL, {rlim_cur=200*1024, rlim_max=200*1024}) = 0 <0.000005>
62445 10:49:42 close(204799)            = -1 EBADF (Неправильный дескриптор файла) <0.000005>
62445 10:49:42 close(204798)            = -1 EBADF (Неправильный дескриптор файла) <0.000005>
62445 10:49:42 close(204797)            = -1 EBADF (Неправильный дескриптор файла) <0.000005>
62445 10:49:42 close(204796)            = -1 EBADF (Неправильный дескриптор файла) <0.000004>
62445 10:49:42 close(204795)            = -1 EBADF (Неправильный дескриптор файла) <0.000004>
<...>
62445 10:49:46 close(5)                 = -1 EBADF (Неправильный дескриптор файла) <0.000005>
62445 10:49:46 close(4)                 = -1 EBADF (Неправильный дескриптор файла) <0.000006>
62445 10:49:46 close(3)                 = -1 EBADF (Неправильный дескриптор файла) <0.000005>
62445 10:49:46 brk(NULL)                = 0x557bcb40b000 <0.000005>
62445 10:49:46 brk(0x557bcb42c000)      = 0x557bcb42c000 <0.000008>
62445 10:49:46 getuid()                 = 0 <0.000008>
62445 10:49:46 getgid()                 = 0 <0.000006>


Likhachev Vasiliy <lilalkor>
Tue 01 Oct 2019 10:52:43 PM UTC, comment #5: 

Should be fixed in v.4.7.0 release

Amadeusz Sławiński <amade>
Group administrator
Mon 20 May 2019 04:56:04 PM UTC, comment #4: 

I tried to apply this patch and rebuild on our freebsd build server, and despite checking (and double-checking) that the new build is indeed installed, screen startup (or creating a new screen) takes ages.

It is trying to close file descriptors starting with the highest-permitted number, truss logging the following until it reaches 3, after which the initial screen is created and the whole process starts again:


32919: getrlimit(RLIMIT_NOFILE,{ cur=7545213,max=7545213 }) = 0 (0x0)
32919: close(7545212)                            ERR#9 'Bad file descriptor'
32919: close(7545211)                            ERR#9 'Bad file descriptor'
32919: close(7545210)                            ERR#9 'Bad file descriptor'
.....
32919: close(5)                                  ERR#9 'Bad file descriptor'
32919: close(4)                                  ERR#9 'Bad file descriptor'
32919: close(3)                                  ERR#9 'Bad file descriptor'


Suggestions welcome..

/Eirik

Eirik Øverby <ltning>
Sat 09 Mar 2019 05:41:44 AM UTC, comment #3: 

Thank you for looking into this Amadeusz. Can you make any estimate for when a new release with this fix might be available yet?

Lukas Waymann <meribold>
Sat 02 Feb 2019 02:37:04 PM UTC, comment #2: 

So this is caused by screen v.4.6.2 misidentifying linux systems as svr4 and hitting wrong codepath.

This is already fixed in git by:
https://git.savannah.gnu.org/cgit/screen.git/commit/?h=screen-v4&id=ec90292592dd2c9d5c108390841e3df24e377ed5

Checked on archlinux and git (screen-v4 branch) and it behaves fine.

Amadeusz Sławiński <amade>
Group administrator
Fri 01 Feb 2019 03:59:42 AM UTC, comment #1: 

I didn't mention that this causes the screen executable to take much longer to start.  (I think the command-line arguments don't matter.)

Before:


$ time screen --version
Screen version 4.06.02 (GNU) 23-Oct-17

real    0m0.008s
user    0m0.000s
sys     0m0.009s


After:


$ time screen --version
Screen version 4.06.02 (GNU) 23-Oct-17

real 0m0.170s
user 0m0.057s
sys 0m0.112s


By the way, is the exit status of screen --version intended to be 1?

Lukas Waymann <meribold>
Thu 31 Jan 2019 03:30:40 PM UTC, original submission:  

systemd recently increased the default hard limit of how many simultaneous file descriptors unprivileged user space processes can have (HIGH_RLIMIT_NOFILE?).  First to 262144 [1] and later to 524288 [2].  Apparently from 4096 (Linux default?).

It seems that this causes screen to try to close half a million file descriptors on startup.  Here's the strace of `screen --version` (abridged; the whole thing is 37 MiB):


execve("/usr/bin/screen", ["screen", "--version"], 0x7ffe6fae1658 /* 43 vars */) = 0
access("/etc/suid-debug", F_OK) = -1 ENOENT (No such file or directory)
brk(NULL) = 0x5570a6a60000
arch_prctl(0x3001 /* ARCH_??? */, 0x7ffc8551a8c0) = -1 EINVAL (Invalid argument)
fcntl(0, F_GETFD) = 0
fcntl(1, F_GETFD) = 0
fcntl(2, F_GETFD) = 0
access("/etc/suid-debug", F_OK) = -1 ENOENT (No such file or directory)
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=232430, ...}) = 0
mmap(NULL, 232430, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fa20bd14000
close(3) = 0
openat(AT_FDCWD, "/usr/lib/tls/x86_64/x86_64/libtinfo.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/tls/x86_64/x86_64", 0x7ffc85519b00) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/tls/x86_64/libtinfo.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/tls/x86_64", 0x7ffc85519b00) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/tls/x86_64/libtinfo.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/tls/x86_64", 0x7ffc85519b00) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/tls/libtinfo.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/tls", 0x7ffc85519b00) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/x86_64/x86_64/libtinfo.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/x86_64/x86_64", 0x7ffc85519b00) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/x86_64/libtinfo.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/x86_64", 0x7ffc85519b00) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/x86_64/libtinfo.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/x86_64", 0x7ffc85519b00) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/libtinfo.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 p\1\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=449040, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa20bd12000
mmap(NULL, 453880, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa20bca3000
mmap(0x7fa20bcba000, 241664, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x17000) = 0x7fa20bcba000
mmap(0x7fa20bcf5000, 94208, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x52000) = 0x7fa20bcf5000
mmap(0x7fa20bd0c000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x68000) = 0x7fa20bd0c000
close(3) = 0
openat(AT_FDCWD, "/usr/lib/libcrypt.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 \20\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=42912, ...}) = 0
mmap(NULL, 233824, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa20bc69000
mprotect(0x7fa20bc6a000, 36864, PROT_NONE) = 0
mmap(0x7fa20bc6a000, 24576, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1000) = 0x7fa20bc6a000
mmap(0x7fa20bc70000, 8192, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x7000) = 0x7fa20bc70000
mmap(0x7fa20bc73000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x9000) = 0x7fa20bc73000
mmap(0x7fa20bc75000, 184672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fa20bc75000
close(3) = 0
openat(AT_FDCWD, "/usr/lib/libpam.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0`\"\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=55048, ...}) = 0
mmap(NULL, 2150416, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa20ba5b000
mprotect(0x7fa20ba68000, 2093056, PROT_NONE) = 0
mmap(0x7fa20bc67000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xc000) = 0x7fa20bc67000
close(3) = 0
openat(AT_FDCWD, "/usr/lib/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\0000C\2\0\0\0\0\0"..., 832) = 832
lseek(3, 792, SEEK_SET) = 792
read(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\201\336\t\36\251c\324\233E\371SoK\5H\334"..., 68) = 68
fstat(3, {st_mode=S_IFREG|0755, st_size=2136840, ...}) = 0
lseek(3, 792, SEEK_SET) = 792
read(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\201\336\t\36\251c\324\233E\371SoK\5H\334"..., 68) = 68
lseek(3, 864, SEEK_SET) = 864
read(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32) = 32
mmap(NULL, 1848896, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa20b897000
mprotect(0x7fa20b8b9000, 1671168, PROT_NONE) = 0
mmap(0x7fa20b8b9000, 1355776, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x22000) = 0x7fa20b8b9000
mmap(0x7fa20ba04000, 311296, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16d000) = 0x7fa20ba04000
mmap(0x7fa20ba51000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b9000) = 0x7fa20ba51000
mmap(0x7fa20ba57000, 13888, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fa20ba57000
close(3) = 0
openat(AT_FDCWD, "/usr/lib/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 \20\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=14240, ...}) = 0
mmap(NULL, 16528, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa20b892000
mmap(0x7fa20b893000, 4096, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1000) = 0x7fa20b893000
mmap(0x7fa20b894000, 4096, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7fa20b894000
mmap(0x7fa20b895000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7fa20b895000
close(3) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa20b890000
arch_prctl(ARCH_SET_FS, 0x7fa20b891000) = 0
mprotect(0x7fa20ba51000, 16384, PROT_READ) = 0
mprotect(0x7fa20b895000, 4096, PROT_READ) = 0
mprotect(0x7fa20bc67000, 4096, PROT_READ) = 0
mprotect(0x7fa20bc73000, 4096, PROT_READ) = 0
mprotect(0x7fa20bd0c000, 20480, PROT_READ) = 0
mprotect(0x5570a5ede000, 4096, PROT_READ) = 0
mprotect(0x7fa20bd76000, 4096, PROT_READ) = 0
munmap(0x7fa20bd14000, 232430) = 0
prlimit64(0, RLIMIT_NOFILE, NULL, {rlim_cur=1024, rlim_max=512*1024}) = 0
close(524287) = -1 EBADF (Bad file descriptor)
close(524286) = -1 EBADF (Bad file descriptor)
close(524285) = -1 EBADF (Bad file descriptor)
...
...
(This goes on.)
...
...
close(5) = -1 EBADF (Bad file descriptor)
close(4) = -1 EBADF (Bad file descriptor)
close(3) = -1 EBADF (Bad file descriptor)
brk(NULL) = 0x5570a6a60000
brk(0x5570a6a81000) = 0x5570a6a81000
getuid() = 1000
getgid() = 100
geteuid() = 1000
getegid() = 100
fstat(1, {st_mode=S_IFREG|0644, st_size=38279899, ...}) = 0
write(1, "Screen version 4.06.02 (GNU) 23-"..., 40Screen version 4.06.02 (GNU) 23-Oct-17
) = 40
exit_group(1) = ?
+++ exited with 1 +++


Also see <https://bugs.archlinux.org/task/61463>.

[1]: https://github.com/systemd/systemd/commit/8aeb1d3176bf90f42c469deb40c3cfdda913acf2
[2]: https://github.com/systemd/systemd/commit/09dad04c49cae3ad2b319c9b4e7773fedd34309a

Lukas Waymann <meribold>

 

(Note: upload size limit is set to 16384 kB, after insertion of the required escape characters.)

Attach Files:
   
   
Comment:
   

No files currently attached

 

Depends on the following items: None found

Items that depend on this one: None found

 

Carbon-Copy List
  • -email is unavailable- added by lilalkor (Posted a comment)
  • -email is unavailable- added by ltning (Posted a comment)
  • -email is unavailable- added by amade (Posted a comment)
  • -email is unavailable- added by meribold (Submitted the item)
  •  

    There are 0 votes so far. Votes easily highlight which items people would like to see resolved in priority, independently of the priority of the item set by tracker managers.

    Only logged-in users can vote.

     

    Follow 5 latest changes.

    Date Changed by Updated Field Previous Value => Replaced by
    2019-11-02 amade StatusFixed None
        Open/ClosedClosed Open
    2019-10-01 amade Open/ClosedOpen Closed
    2019-10-01 amade Fixed ReleaseNone 4.7.0
    2019-02-02 amade StatusNone Fixed

    Back to the top

    Powered by Savane 3.13-f8d8.
    Corresponding source code