[BUG] Script execution massively delayed #1812

patschi · 2021-01-02T20:11:38Z

Command line / docker command to reproduce
Running testssl.sh, parameters doesn't matter.

Current issue

Cloned git repo via git clone --depth 1 https://github.com/drwetter/testssl.sh.git (This issue is NOT reproducible on latest 3.0 version)
Running testssl.sh takes 2.5 minutes, also for simply displaying the version or the current banner. Some process is blocking the execution on the latest git commit state.

Example:

~/testssl.sh_git$ time ./testssl.sh -v
+ declare -r ERR_BASH=255
+ declare -r ERR_CMDLINE=254
+ declare -r ERR_FCREATE=253
+ declare -r ERR_FNAMEPARSE=252
+ declare -r ERR_NOSUPPORT=251
+ declare -r ERR_OSSLBIN=250
+ declare -r ERR_DNSBIN=249
+ declare -r ERR_OTHERCLIENT=248
+ declare -r ERR_DNSLOOKUP=247
+ declare -r ERR_CONNECT=246
+ declare -r ERR_CLUELESS=245
+ declare -r ERR_RESOURCE=244
+ declare -r ERR_CHILD=242
+ declare -r ALLOK=0
+ '[' -z 5 ']'
++ kill -l
++ grep -c SIG
+ '[' 13 -eq 0 ']'
+ '[' 5 -lt 3 ']'
+ '[' 5 -le 3 ']'
+ declare -r 'PS4=|${LINENO}> \011${FUNCNAME[0]:+${FUNCNAME[0]}(): }'
|100>   DEBUGTIME=false
|101>   DEBUG_ALLINONE=false
|103>   DEBUG_ALLINONE=false
|104>   [[ braceexpand:hashall:interactive-comments:xtrace =~ xtrace ]]
|105>   false
|110>   false
|111>   exec
|112>   BASH_XTRACEFD=42


###########################################################
    testssl.sh       3.1dev from https://testssl.sh/dev/
    (a9f4bb5 2020-12-29 14:40:58 -- )

      This program is free software. Distribution and
             modification under GPLv2 permitted.
      USAGE w/o ANY WARRANTY. USE IT AT YOUR OWN RISK!

       Please file bugs @ https://testssl.sh/bugs/

###########################################################

 Using "OpenSSL 1.1.1i  8 Dec 2020" [~98 ciphers]
 on XXX:/usr/bin/openssl
 (built: "Dec 23 09:13:14 2020", platform: "debian-amd64")



real    2m30.955s
user    0m0.792s
sys     0m0.242s

To note: For debugging purposes I've only added set -x at the beginning of the bash script.

Expected behavior
Not having such a long delay.

Your system (please complete the following information):

$ awk -F\" '/PRETTY_NAME/ { print $2 }' /etc/os-release
Ubuntu 20.04.1 LTS
$ uname -srm
Linux 4.19.128-microsoft-standard x86_64
$ git log | head -1
commit a9f4bb5fb57ecee7388fdaaa31591a6941a7383a

-> Ran in WSL2

The text was updated successfully, but these errors were encountered:

drwetter · 2021-01-05T18:51:18Z

Hi @patschi ,

testssl.sh testssl.sh takes for me 85-90 seconds, which includes a ROBOT check which alone takes ~20 seconds.

Can't tell right now because my dual boot machines run under Linux but I am afraid that is not unsusal for Windows (IIRC less for WSL, more for Cygwin and the like). The Windows emulation of Linux is bad doing forks, every subprocess / subshell is using that. And there are a lot.

But we can check whether it got stuck somewhere: MEASURE_TIME=true testssl.sh testssl.sh should give you a clue.

Top dogs in a negative sense for me are here:

run_client_simulation: 20
run_robot: 17
run_server_defaults: 9
run_fs: 6
run_cipherlists: 5
run_protocols: 4

So, what do you have?

patschi · 2021-01-05T23:16:39Z

As said I'm simply running time ./testssl.sh -v, which is statically returning the current version of the script - no sort of tests are involved at this point, so it should complete within a second or so and not 2.5 minutes for a static output.

Also I'm using WSL2, so it's a Ubuntu 20.04 VM virtualized via Hyper-V, so there's not the classic WSL version 1 magic involved and it should be way faster.

drwetter · 2021-01-06T08:29:24Z

Sorry, was too much work probably.

Please try SETX=true bash -x ./testssl.sh -v. That should unmask the culprit

drwetter · 2021-01-06T09:21:26Z

Also I'm using WSL2, so it's a Ubuntu 20.04 VM virtualized via Hyper-V, so there's not the classic WSL version 1 magic involved and it should be way faster.

Just curious (and OT): does that (=Hyper-V virtualization layer) happen per default with the October release of W10 when one uses WSL?

patschi · 2021-01-06T12:16:41Z

Sorry, was too much work probably.

Please try SETX=true bash -x ./testssl.sh -v. That should unmask the culprit

That's indeed a very detailed output, helps indeed. The following also repeats and seems to the delay everything the most:

|19102>         find_openssl_binary(): OPENSSL_NR_CIPHERS=98
|19104>         find_openssl_binary(): /usr/bin/openssl s_client -curves sect163k1 -connect invalid.
|19104>         find_openssl_binary(): grep -aiq 'unknown option'
|19110>         find_openssl_binary(): HAS_CURVES=true
|19111>         find_openssl_binary(): for curve in "${curves_ossl[@]}"
|19112>         find_openssl_binary(): /usr/bin/openssl s_client -curves sect163k1 -connect invalid.
|19112>         find_openssl_binary(): grep -Eiaq 'Error with command|unknown option'
|19113>         find_openssl_binary(): [[ 1 -ne 0 ]]
|19113>         find_openssl_binary(): OSSL_SUPPORTED_CURVES+=' sect163k1 '
|19111>         find_openssl_binary(): for curve in "${curves_ossl[@]}"
|19112>         find_openssl_binary(): /usr/bin/openssl s_client -curves sect163r1 -connect invalid.
|19112>         find_openssl_binary(): grep -Eiaq 'Error with command|unknown option'
|19113>         find_openssl_binary(): [[ 1 -ne 0 ]]
|19113>         find_openssl_binary(): OSSL_SUPPORTED_CURVES+=' sect163r1 '
|19111>         find_openssl_binary(): for curve in "${curves_ossl[@]}"
|19112>         find_openssl_binary(): /usr/bin/openssl s_client -curves sect163r2 -connect invalid.
|19112>         find_openssl_binary(): grep -Eiaq 'Error with command|unknown option'
|19113>         find_openssl_binary(): [[ 1 -ne 0 ]]
|19113>         find_openssl_binary(): OSSL_SUPPORTED_CURVES+=' sect163r2 '
|19111>         find_openssl_binary(): for curve in "${curves_ossl[@]}"
|19112>         find_openssl_binary(): /usr/bin/openssl s_client -curves sect193r1 -connect invalid.
|19112>         find_openssl_binary(): grep -Eiaq 'Error with command|unknown option'
|19113>         find_openssl_binary(): [[ 1 -ne 0 ]]
|19113>         find_openssl_binary(): OSSL_SUPPORTED_CURVES+=' sect193r1 '
|19111>         find_openssl_binary(): for curve in "${curves_ossl[@]}"
|19112>         find_openssl_binary(): /usr/bin/openssl s_client -curves sect193r2 -connect invalid.
|19112>         find_openssl_binary(): grep -Eiaq 'Error with command|unknown option'
|19113>         find_openssl_binary(): [[ 1 -ne 0 ]]
|19113>         find_openssl_binary(): OSSL_SUPPORTED_CURVES+=' sect193r2 '
|19111>         find_openssl_binary(): for curve in "${curves_ossl[@]}"
|19112>         find_openssl_binary(): /usr/bin/openssl s_client -curves sect233k1 -connect invalid.
|19112>         find_openssl_binary(): grep -Eiaq 'Error with command|unknown option'
|19113>         find_openssl_binary(): [[ 1 -ne 0 ]]
|19113>         find_openssl_binary(): OSSL_SUPPORTED_CURVES+=' sect233k1 '
|19111>         find_openssl_binary(): for curve in "${curves_ossl[@]}"
|19112>         find_openssl_binary(): /usr/bin/openssl s_client -curves sect233r1 -connect invalid.
|19112>         find_openssl_binary(): grep -Eiaq 'Error with command|unknown option'
|19113>         find_openssl_binary(): [[ 1 -ne 0 ]]
|19113>         find_openssl_binary(): OSSL_SUPPORTED_CURVES+=' sect233r1 '
|19111>         find_openssl_binary(): for curve in "${curves_ossl[@]}"
|19112>         find_openssl_binary(): /usr/bin/openssl s_client -curves sect239k1 -connect invalid.
|19112>         find_openssl_binary(): grep -Eiaq 'Error with command|unknown option'

Does this help in any way?

Just curious (and OT): does that (=Hyper-V virtualization layer) happen per default with the October release of W10 when one uses WSL?

AFAIK: On upgraded Windows installation its default remains at version 1. Newer installations default to version 2. On upgraded installations you can upgrade from WSL1 to WSL2 with a few simple steps - in this upgrade process e.g. the Linux kernel will be installed and moved into a lightweight Hyper-V VM, works just fine.

drwetter · 2021-01-06T14:35:58Z

Does this help in any way?

So each one takes an eternity? What does time /usr/bin/openssl s_client -curves sect239k1 -connect invalid. return?

It smells a bit like a DNS problem which we had that reported back some time, see #1738.

drwetter · 2021-01-06T14:41:32Z

please also try time /usr/bin/openssl s_client -curves prime256v1 -connect invalid.

drwetter · 2021-01-21T16:36:59Z

ping. ;-)

Could you please give it a try.

also it would be great to get the time spent on this:

prompt> for t in  invalid. test. example.  test. ; do
      time /usr/bin/openssl s_client -curves sect239k1 -connect $t
done
prompt>

See #1738, #1489

This commit provides a global variable to the RFC 6761 use of "invalid." which WSL clients doen't seem to handle very well, see #1738, #1812. With this commit it e.g. is possible to use NXCONNECT=localhost:0 ./testssl.sh <TARGET> to save some time. This commit will be amended later.

drwetter · 2021-09-15T08:01:23Z

Can you try the branch windows_dns_fix using NXCONNECT=localhost:0 ./testssl.sh $YOURTARGET and report back pls?

drwetter · 2021-10-02T13:42:35Z

I updated the branchwindows_dns_fix , see commit log. basically this should be a good improvement.

My main concern is that other users encounter longer delays, depending on the windows config, so if it can be found out during testing that this is not happening would be appreciated!

Please comment in #1738.

This commit provides a global variable to the RFC 6761 use of "invalid." which WSL clients don't seem to handle very well, see #1738, #1812. "invalid." is used as a target to find out in a couple of pre-checks what is supported by the openssl version. This PR reduces the number of ``openssl s_client -connect`` by a huge factor. For the remaining invocations the OS used is being determined and if WSL is assumed (the check is probably not 100% accurate) it uses ``127.0.0.1:0`` instead. In (unfortunately only a few) pre-tests the response was immediate. Also it is possible to use another target if needed by NXCONNECT=<mytargethere>:<myport> ./testssl.sh <URL> This is for 3.0. For 3.1dev see #1988 .

drwetter mentioned this issue Jan 21, 2021

testssl.sh 3.0 starts significantly slower than the previous version #1489

Closed

drwetter mentioned this issue Sep 15, 2021

Addressing lame DNS responses on WSL #1988

Merged

drwetter closed this as completed Oct 2, 2021

drwetter added the duplicate label Oct 2, 2021

drwetter mentioned this issue Oct 18, 2021

Addressing lame DNS responses on WSL (3.0) #2012

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[BUG] Script execution massively delayed #1812

[BUG] Script execution massively delayed #1812

patschi commented Jan 2, 2021 •

edited

Loading

drwetter commented Jan 5, 2021

patschi commented Jan 5, 2021

drwetter commented Jan 6, 2021

drwetter commented Jan 6, 2021

patschi commented Jan 6, 2021

drwetter commented Jan 6, 2021

drwetter commented Jan 6, 2021

drwetter commented Jan 21, 2021 •

edited

Loading

drwetter commented Sep 15, 2021

drwetter commented Oct 2, 2021 •

edited

Loading

[BUG] Script execution massively delayed #1812

[BUG] Script execution massively delayed #1812

Comments

patschi commented Jan 2, 2021 • edited Loading

drwetter commented Jan 5, 2021

patschi commented Jan 5, 2021

drwetter commented Jan 6, 2021

drwetter commented Jan 6, 2021

patschi commented Jan 6, 2021

drwetter commented Jan 6, 2021

drwetter commented Jan 6, 2021

drwetter commented Jan 21, 2021 • edited Loading

drwetter commented Sep 15, 2021

drwetter commented Oct 2, 2021 • edited Loading

patschi commented Jan 2, 2021 •

edited

Loading

drwetter commented Jan 21, 2021 •

edited

Loading

drwetter commented Oct 2, 2021 •

edited

Loading