netdev - sk_lookup + test_bprm = huge delay

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [thread-next>] [day] [month] [year] [list]

Date:   Fri, 26 Feb 2021 17:59:50 -0800
From:   Alexei Starovoitov <alexei.starovoitov@...il.com>
To:     KP Singh <kpsingh@...gle.com>, Lorenz Bauer <lmb@...udflare.com>,
        bpf <bpf@...r.kernel.org>,
        Daniel Borkmann <daniel@...earbox.net>,
        Andrii Nakryiko <andrii@...nel.org>,
        Network Development <netdev@...r.kernel.org>
Subject: sk_lookup + test_bprm = huge delay

Hi KP, Lorenz,

I need your help to debug a huge delay I'm seeing while running the test_progs.

To debug it I've added the following printf-s:

diff --git a/tools/testing/selftests/bpf/prog_tests/test_bprm_opts.c
b/tools/testing/selftests/bpf/prog_tests/test_bprm_opts.c
index 2559bb775762..cdd2182c83a2 100644
--- a/tools/testing/selftests/bpf/prog_tests/test_bprm_opts.c
+++ b/tools/testing/selftests/bpf/prog_tests/test_bprm_opts.c
@@ -66,8 +66,10 @@ static int run_set_secureexec(int map_fd, int secureexec)
                 * If the value of TMPDIR is set, the bash command returns 10
                 * and if the value is unset, it returns 20.
                 */
+               null_fd = open("/dev/console", O_WRONLY);
+               dprintf(null_fd, "before_bash\n");
                execle("/bin/bash", "bash", "-c",
-                      "[[ -z \"${TMPDIR}\" ]] || exit 10 && exit 20", NULL,
+                      "echo running_bash > /dev/console;[[ -z
\"${TMPDIR}\" ]] || exit 10 && exit 20", NULL,
                       bash_envp);
                exit(errno);
        } else if (child_pid > 0) {

Then I do:
./test_progs -n 127
before_bash
running_bash
before_bash
running_bash
#127 test_bprm_opts:OK
Summary: 1/0 PASSED, 0 SKIPPED, 0 FAILED

and it takes a split second to execute. There is no visible delay.

But when I run it as:
./test_progs -n 98,127
#98 sk_lookup:OK
before_bash
// huge delay here
running_bash
before_bash
running_bash
#127 test_bprm_opts:OK
Summary: 2/46 PASSED, 0 SKIPPED, 0 FAILED

real    0m51.414s
user    0m0.808s
sys    0m35.731s

All 50 seconds are spent waiting after "before_bash" line is printed.
Something is drastically delaying execle("/bin/bash").

But replacing arg0 of "bash" with "sh" makes it fast !
execle("/bin/bash", "sh"
                               ^^ instead of "bash".
I cannot explain all this at all.

sk_lookup test doing some netns and forking "ip",
but why would that slow down "bash" startup time?
And why would bash start quickly if it thinks that it's name is "sh" ?

For giggles I've tried:
execle("/bin/bash", "foobar"
and it's also slow.

Crazy ideas are welcome :)