Shellspec can not collect data with the profile option enabled #274
Comments
|
I currently have the same issue
I think it's something related to the timing (see following output from |
Those variables seems to be generated here: shellspec/lib/libexec/reporter.sh Line 20 in f800240 TL;DR;Run 🐞 Bug?As you can see in the screenshot below, in my current situation if i run
However... Look what happens if i first change my locale to the POSIX locale: Now everything works as expected! When does it happen?It seems that this problem happens when i run shellcheck with locales different than the English (which the C/POSIX defaults to)... If i set the locale to one that is not installed on my system, the fallback seems to always be the
As you can see the only language that works all the time is the C locale (this link provides interesting info). We need to check WHAT causes this behaviour to change based on the selected locale. I'll try to look into this problem and see what i can find, but i think only @ko1nksm can give us a real answer... 🖥 System InfoI'm using Cygwin on Windows 10 19044: 🚧 WorkaroundRun |
UPDATEI did a little dive after a ☕ and I think i have found what is the problem... As I suspected before, the bug is indeed in the shellspec/lib/libexec/reporter.sh Lines 17 to 30 in f800240 In the line 25 it is checked if the second space-separated value is a number, and if so, it is skipped: shellspec/lib/libexec/reporter.sh Line 25 in f800240 By adding Basically every line is skipped because in these locales (tested with italian and spanish) the decimal separator is the comma ( This is confirmed by looking at the same output when using the You can see that this time the We can easily reproduce the bug by writing this on the console: ✅ SolutionsSolution n°1A quick solution that can solve this "bug" is adding the other decimal separator to the glob pattern:
shellspec/lib/libexec/reporter.sh Line 25 in f800240 Tests
Solution n°2The most correct solution however would be to start the shellspec/libexec/shellspec-runner.sh Line 69 in f800240 This line would be: LC_ALL=C $SHELLSPEC_TIME $SHELLSPEC_SHELL "$executor" "$@" 3>&2 2>"$SHELLSPEC_TIME_LOG"⚠ Help needed ⚠This would be the best solution, since it would remove the problem from the root. However, it also could introduce new unexpected bugs, because:
To implement this solution we would absolutely need @ko1nksm, since it could break something... Final resultNow the profiler works with all (hopefully) the locales and the time is shown as it should: @ko1nksm I'll make a PR for the 1st solution as soon as I can 😄 |
|
Thanks for all the suggestion/help Luca. I use Shellspec in a MacOS, Linux and AIX environment. Lutz Appendage: |
What do you mean? What shell/locale are you using? |
|
Hello Luca, p.s. In a MacOS environment, the time output does not depend to the used LANG. In the AIX ksh environment (my default shell, but I like the ksh, sorry), the time output honour the used LANG. This is the time command used by Shellspec, I think. And in the Linux and AIX bash environment, also. |
|
Hello Luke, The output (in a AIX environment) evaluated by read_time_log() echoed to the terminal (see lines prefixed by "#### "). And sometimes (in a Linux environment), the output evaluated looks like this (see lines prefixed by "#### "). Therefore, my suggested patch to handle the output use some additional lines of code, to handle Linux and AIX environments and your change. Based on your suggested patch (handle '.' and ',') and some additional lines Shellspec is able to profile the scripts in Linux, AIX (and MacOS) enviroments, in some more/bad weather conditions. Nice, thanks for your investigations, |
Sorry for the late reply, did you test your solution using the integrated tests? Can you provide a PR to my fork updating both the code and tests? This way it will be already in the PR of this repo |
However something that i do not understand is how is this possible... The documentation for AIX @lutzmad Could you provide more context? |
|
@LukeSavefrogs Thanks for your help. And I'm sorry for neglecting you guys for so long. Perhaps #281 can be merged without problems. ShellSpec must work in all locales. I did not pay enough attention to the locale when I wrote that code. Shells and commands have historically respected locales. However, not all. The bash is usually invoked by the shell built-in $ bash -c 'export LC_ALL=de_DE.UTF-8; time -p true'
real 0,00
user 0,00
sys 0,00
$ bash -c 'export LC_ALL=de_DE.UTF-8; env time -p true'
real 0.00
user 0.00
sys 0.00 |
|
Hello, no problem.
I will add additional "time" command output to the issue and I try to find out which "time" command is used. |
|
Hello,
In the man page I find your information also. A POSIX Sample (https://pubs.opengroup.org/onlinepubs/9699919799/functions/times.html) use other terms for "real", "user", "sys" also. Therefore I checked it again based on the suggested "/bin/usr/time" command. And I find a "time.cat" file, but for "en_US" only. And the globalization/localization files are used. Based on the default ("en_US") lang environment. And after a switch to an other ("en_DE") lang environment. But TIME is a KSH shell internal command also, see man snippet. And a BASH shell internal command. My conclusion, the man page is right, but globalization/localization is used for the "en_US" lang environment and the used messages/terms are translated to "en_US" therefore. Shellspec should handle both formats used for "en_US", with and without globalization/localization. Lutz |
|
Hello, Appendage: Linux MacOS |
|
Thanks for the report. It is very interesting. When I wrote these codes, I apparently did not know about the time command. ShellSpec will use Lines 414 to 423 in 166e4f0 In ksh, the (Invoke internal command)
$ time sleep 1
real 0m1.00s
user 0m0.00s
sys 0m0.00s
(Attempts to invoke internal commands but no -p option)
$ time -p sleep 1
ksh: -p: not found
real 0m0.00s
user 0m0.00s
sys 0m0.00s
(Invoke external command)
$ t="time -p"
$ $t sleep 1
real 1.00
user 0.00
sys 0.00The report shows that However, there is another issue. Implementations of the various |
|
Thanks for the report. The bash warnings are fixed here.
This means that the AIX version of the ksh88 is not working at all?
Apparently there is also a problem with ksh93t+. |
What about always forcing the |
|
Hello, The KSH (93) use an internal time command, this is the reason, IBM suggest to use "/usr/bin/time", similar to MacOS. The "." and "," depends to the LANG setting. To add the "," (like ".") to handle the time output will fix the problem. And shellspec will support profiling in non "en_US" environments, on Linux. An unset to NLSPATH will fix the time command output problem on AIX for "en_US" also. On AIX shellspec works well with "-s /bin/bash" only, this is the only way to use shellspec. Lutz |
|
Hello, Running: /bin/ksh93 [ksh Version M 93t+ 2009-05-01] But a test based on mksh works well. Running: /home/j123450/bin/mksh [mksh @(#)MIRBSD KSH R59 2020/10/31] Nice. Have a nivce weekend, |
|
Hello, But a test based on mksh works well. Nice. Have a nice weekend, |
fix: Added support for comma (`,`) as decimal separator - Fix #274
|
I have registered with IBM cloud and modified it to work with ksh93t+ on AIX 7.2 and ksh93u+ on AIX 7.3. The fixes are included in the latest master. Please note that the problems that did not work with ksh93 are not related to locale issues. This is a bug related to the virtual subshell of ksh93. There are no plans to support sh (Version M-11/16/88f). This ksh88 is very old (released around 1995?), and although AIX seems to claim that it is POSIX compliant, it probably has bugs in its errexit-related behaviour. It is quite hard to support this. |
Thank you for taking the time to look into this issue. It's good to see you back in action 😄 |
|
Hello Koichi Nakashima, You are right, the KSH88 is very old and I do not know the reason IBM still use KSH88 as a default shell. I will start testing in a real AIX system next week, based on the github master. Last week I make MKSH ([mksh @(#)MIRBSD KSH R59 2020/10/31]) available on AIX and shellspec works well, I can not find errors based on the shellspec tests, the tests are passed only 47 are skipped. AIX 7.2 shellspec -s /home/j123450/bin/mksh specRunning: /home/j123450/bin/mksh [mksh @(#)MIRBSD KSH R59 2020/10/31] Linux SLES 12/15 and RHEL 9 (I think) shellspec -s /bin/mksh specRunning: /bin/mksh [mksh @(#)MIRBSD KSH R50 2015/04/19 SLES] MacOS shellspec -s /bin/mksh specRunning: /bin/mksh [mksh @(#)MIRBSD KSH R59 2020/10/31] I compare the skipped tests to see the differences, for the MKSH.
Thanks for all your help/support. |
|
Hello (back to MKSH), The BASH will simulate it (on AIX), I think. But MKSH and KSH test the dev filesystem. But the file does not exist. Nice to see, |
Very nice indeed 😳 |
|
Sorry, I am late, Unfortunately I can not find detail information about the new "UseFD" statement used by the test. The old test (based on 0.28.1) looks different (and is passed) The function "warn" was not changed. See snippet from ./lib/libexec/prechecker.sh A new file descriptor is created by shellspec_open_file_descriptor() (in lib/shellspec/lib/core/file_descriptor.sh) Any suggestion, |
|
Thanks for the report. Unfortunately, I cannot reproduce this in my environment. # oslevel
7.2.0.0
# oslevel -s
7200-05-07-2346the
shellspec_open_file_descriptor() {
eval "exec $1>\"\$2\""
}
The test is the same, but rewritten using the new
Since file descriptors are opened only when needed, it does not shown in a simple way. If it works well, you can find fd 3 by Describe "warn()"
UseFD 3
_warn() { /bin/sh -c '/bin/ls -la /proc/$$/fd'> /dev/tty; warn "$@"; }
It 'outputs to fd3'
When call _warn "foo" "bar"
The fd 3 should eq "[warn] foo bar"
End
End# /bin/ksh93 ./shellspec -s /bin/ksh93 ./spec/libexec/prechecker_spec.sh
Running: /usr/bin/ksh93 [ksh Version M 93t+ 2009-05-01]
..total 0
dr-x------ 1 root system 0 May 29 09:21 .
dr-xr-xr-x 1 root system 0 May 29 09:21 ..
c--------- 1 root system 1, 0 May 29 09:21 0
c--------- 1 root system 1, 0 May 29 09:21 1
--w------- 1 root system 0 May 29 09:21 2
lr-xr-xr-x 1 root system 0 May 29 09:21 3 -> /proc/9699828/fd/
...............
Finished in 0.43 seconds (user 0.00 seconds, sys 0.00 seconds)
17 examples, 0 failuresThe version of # ls -al /bin/ksh93
-r-xr-xr-x 2 bin bin 2387068 Aug 03 2023 /bin/ksh93
# shasum /bin/ksh93
6c377b14651f502a9999000eaed7c22b443eb2f1 /bin/ksh93If you have set environment variables that affect the execution environment, please let us know. This is a different issue, your time does not seem to be output.
[edit] See next comment.
[edit] It appears that the reason is that the installation source directory was not specified.
```
COMMAND STATUS
Command: failed stdout: yes stderr: no Before command completion, additional instructions may appear below. installp: The specified device /.cd_98e7ec |
|
I may have been able to reproduce it after setting the locale. But I have no more time today. The reason why the time is not shown is probably due to an error. bash-5.2# LC_ALL=DE_DE /bin/ksh93 ./shellspec -s /bin/ksh93 spec/libexec/prechecker_spec.sh
Running: /bin/ksh93 [ksh Version M 93t+ 2009-05-01]
.F............../shellspec-master/libexec/shellspec-executor.sh[111]: echo: Schreiben in 1 fehlgeschlagen. [Ein Dateideskriptor verweist nicht auf eine offene Datei.]
/shellspec-master/libexec/shellspec-runner.sh[208]: echo: Schreiben in 1 fehlgeschlagen. [Ein Dateideskriptor verweist nicht auf eine offene Datei.]
Examples:
1) libexec/prechecker.sh warn() outputs to fd3
When call warn foo bar
1.1) The fd 3 should eq [warn] foo bar
expected: "[warn] foo bar"
got: ""
# spec/libexec/prechecker_spec.sh:17
Finished in ? seconds (user ? seconds, sys ? seconds)
16 examples, 1 failure
Failure examples / Errors: (Listed here affect your suite's status)
shellspec spec/libexec/prechecker_spec.sh:15 # 1) libexec/prechecker.sh warn() outputs to fd3 FAILED
/shellspec-master/libexec/shellspec-runner.sh[209]: echo: Schreiben in 1 fehlgeschlagen. [Ein Dateideskriptor verweist nicht auf eine offene Datei.]
Aborted with status code [executor: 102] [reporter: ] [error handler: ]
Fatal error occurred, terminated with exit status 102.I don't see why it would affect by the locale. 🤔 |
|
Hello, Based on your sample to gather some more information, my output looks similar, but the test failed. The KSH93 version number is the same, but the files size is not the same. The only ugly environment variables are set/used: And "/opt/freeware/bin" is in the path, to make some Linux/GNU tools available in the AIX environment. The used LANG and NLSPATH variables are the reason for the problem with the "time -p" command output, but this is an other storry. But you can check your NLSPATH to find the translated messages, in your AIX environment. If I check the NLSPATH, I find messages for en_US only. A funny test result, if I do this (based on your last sample). Every think works well. And "LANG=EN_US" work well too, but "LANG=en_US" does not. It is a AIX LANG environment setting/handling problem? |
1. Reasons for not getting the timeSorry. I had overlooked this information.
The AIX bash-5.2# LC_ALL=DE_DE env time -p sleep 0
Real 0,00
Benutzer 0,00
System 0,00To fix this issue, we need to execute 2. echo: write to 1 failedI mistakenly thought that we could not write to file descriptor 3 specified in /home/j123450/lib/shellspec/libexec/shellspec-runner.sh[209]: echo: write to 1 failed [A file descriptor does not refer to an open file.]This is probably a bug in ksh93. In my environment, I was able to reproduce the problem with the following code. $ LC_ALL=DE_DE /bin/ksh93 -c '( ( echo test >&5 | cat ) 5>&1 | cat ) 3>&1 4>&2'
/bin/ksh93[1]: echo: Schreiben in 1 fehlgeschlagen. [Ein Dateideskriptor verweist nicht auf eine offene Datei.]
$ /bin/ksh93 -c '( ( echo test >&5 | cat ) 5>&1 | cat ) 3>&1 4>&2'
testAdding $ LC_ALL=DE_DE /bin/ksh93 -c '( ( echo test >&5 | cat ) 5>&1 | cat ) 3>&1 4>&2 5>/dev/null'
testWe were able to work around this by fixing the following However, it might be better to rewrite the code to use a temporary file so that libexec/shellspec-runner.sh: set +e
( ( ( ( ( set -e; exec 3>&- 4>&- 5>&-; executor "$@" ); echo $? >&5; ) \
| ( set -e; reporter "$@" ) >&3; echo $? >&5 ) 2>&1 \
| ( set -e; error_handler ) >&4; echo $? >&5 ) 5>&1 \
| (
read -r xs1; read -r xs2; read -r xs3
xs='' error='' msg="Aborted with status code"
for i in "$xs1" "$xs2" "$xs3"; do
case $i in
0) continue ;;
"$SHELLSPEC_FAILURE_EXIT_CODE") [ "$xs" ] || xs=$i ;;
"$SHELLSPEC_ERROR_EXIT_CODE") xs=$i error=1 && break ;;
*) [ "${xs#"$SHELLSPEC_FAILURE_EXIT_CODE"}" ] || xs=$i; error=1
esac
done
if [ "$error" ]; then
error "$msg [executor: $xs1] [reporter: $xs2] [error handler: $xs3]"
fi
set_exit_status "${xs:-0}"
)
) 3>&1 4>&2 5>/dev/null
exit_status=$?libexec/shellspec-executor.sh: set +e
( ( ( ( (
( set -e; exec 3>&- 4>&- 5>&-; executor "$@" ) ) 2>&1 >&4; echo $? >&5 ) \
| ( set -e; error_handler ) >&3; echo $? >&5 ) 5>&1) \
| (
read -r xs1 && [ "$xs1" -ne 0 ] && exit "$xs1"
read -r xs2 && [ "$xs2" -ne 0 ] && exit "$xs2"
exit 0
)
) 4>&1 5>/dev/null3. Failure of UseFDThis is the most enigmatic issue. This is probably a bug in ksh93, but the file size being written is very strange. lib/core/dsl.sh: Describe "warn()"
UseFD 3
(
exec 3>/tmp/log.txt
echo >&3
/bin/od -tx1 /tmp/log.txt >/dev/tty
/bin/ls -al "/tmp/log.txt" > /dev/tty
)
It 'outputs to fd3'
When call warn "foo" "bar"
The fd 3 should eq "[warn] foo bar"
End
EndI would have written only newlines ( Running: /bin/ksh93 [ksh Version M 93t+ 2009-05-01]
.0000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
*
0426100 00 00 00 00 00 00 00 00 00 0a
0426112
-rw-r--r-- 1 root system 142410 30 Mai 08:53 /tmp/log.txtFor some reason the first part of the file seems to have What needs to be fixed
|
|
Hello, In general I use "en_US" or "en_US.UTF-8". This fit well (I thought) in the past, but I try do some tests based on "C", tomorrow. From my point of view the "/bin/time -p" problem can not fixed, as long as the NLS messages are used, the messages can not handled properly. The fix from LukeSavefrogs fix the "."/"," problem, but if a NLS package is available, the messages are not properly handled, because values are not properly assigned. But "C" is a good idea. Lutz |
|
Hello, The tests with the KSH93 looks similar to the BASH (version 5.2!) tests now. Based on "LANG=C" no NLSPATH is found in my AIX environment, therefore no messages are translated and the expected message text is found. The runtime time values are available also. Have a nice weekend, p.s. |
This is the following workaround #274 (comment) But the bug where user time and sys time were not being measured correctly has also been fixed.
|
Fixes were added to master.
The time should be measured correctly and the profiler should work correctly. # LC_ALL=DE_DE bash ./shellspec --profile --no-banner spec/semver_spec.sh
Running: /usr/bin/bash [bash 5.2.15(1)-release]
...............................................
Finished in 2.113 seconds (user: 0.457s, sys: 0.031s) [time: bash-builtin]
47 examples, 0 failures
# Top 10 slowest examples of the 47 examples
# 1 0.0441 spec/semver_spec.sh:56-60
# 2 0.0430 spec/semver_spec.sh:88-91
# 3 0.0393 spec/semver_spec.sh:88-91
# 4 0.0382 spec/semver_spec.sh:49-52
# 5 0.0378 spec/semver_spec.sh:49-52
# 6 0.0361 spec/semver_spec.sh:88-91
# 7 0.0321 spec/semver_spec.sh:25-28
# 8 0.0315 spec/semver_spec.sh:88-91
# 9 0.0313 spec/semver_spec.sh:88-91
# 10 0.0313 spec/semver_spec.sh:88-91Bonus: The reimplemented locale-independent # LC_ALL=DE_DE libexec/shellspec-time.sh sleep 1
real:1.10 user:0.00 sys:0.00 type:ksh88-builtin
# LC_ALL=DE_DE ksh93 libexec/shellspec-time.sh sleep 1
real:1.000 user:0.000 sys:0.000 type:ksh93-builtin
# LC_ALL=DE_DE bash libexec/shellspec-time.sh locale
LANG=en_US
LC_COLLATE="DE_DE"
LC_CTYPE="DE_DE"
LC_MONETARY="DE_DE"
LC_NUMERIC="DE_DE"
LC_TIME="DE_DE"
LC_MESSAGES="DE_DE"
LC_ALL=DE_DE
real:0.004 user:0.001 sys:0.001 type:bash-builtin |
Workaround for file descriptor malfunction when specifying locale See below #274
However, it is not clear whether this fix has completely fixed the issue. |
Hello,
I try to use the profile option, but the formatter get no proper data.
This is a problem in shellspec_shift10() because "$2" is empty.
Therefore, I try find the way the function will be called.
But this ended because I can not find the code where "$time_real" filled with proper values.
See /lib/shellspec/lib/libexec/reporter/profiler_formatter.sh in profiler_end() in the line
The time_real is empty, is ''. If I assign "0" to the empty "$time_real" I get no useful report but Shellspec finished without an error.
My question, where the variable "$time_real" came from?
Sorry, I can not find, what is going wrong,
Lutz
p.s.
I use shellspec 0.28.1 dist version.
The text was updated successfully, but these errors were encountered: